fix(root): add hyperdx and better logging

This commit is contained in:
Carl-Gerhard Lindesvärd
2024-09-13 21:49:51 +02:00
committed by Carl-Gerhard Lindesvärd
parent 4bafa16419
commit c819c18962
22 changed files with 2116 additions and 332 deletions

View File

@@ -28,8 +28,6 @@
"fastify-metrics": "^11.0.0",
"ico-to-png": "^0.2.1",
"jsonwebtoken": "^9.0.2",
"pino": "^8.17.2",
"pino-pretty": "^10.3.1",
"ramda": "^0.29.1",
"request-ip": "^3.3.0",
"sharp": "^0.33.2",

View File

@@ -37,8 +37,11 @@ async function getImageBuffer(url: string) {
})
.png()
.toBuffer();
} catch (e) {
logger.error(e, `Failed to get image from url ${url}`);
} catch (error) {
logger.error(`Failed to get image from url`, {
error,
url,
});
}
}
@@ -138,8 +141,10 @@ export async function ping(
count: request.body.count,
domain: request.body.domain,
});
} catch (e) {
logger.error(e, 'Failed to insert ping');
} catch (error) {
request.log.error('Failed to insert ping', {
error,
});
reply.status(500).send({
error: 'Failed to insert ping',
});

View File

@@ -5,10 +5,12 @@ import cookie from '@fastify/cookie';
import cors from '@fastify/cors';
import type { FastifyTRPCPluginOptions } from '@trpc/server/adapters/fastify';
import { fastifyTRPCPlugin } from '@trpc/server/adapters/fastify';
import type { FastifyBaseLogger, FastifyRequest } from 'fastify';
import Fastify from 'fastify';
import metricsPlugin from 'fastify-metrics';
import { path } from 'ramda';
import { round } from '@openpanel/common';
import { generateId, round } from '@openpanel/common';
import { chQuery, db, TABLE_NAMES } from '@openpanel/db';
import type { IServiceClient } from '@openpanel/db';
import { eventsQueue } from '@openpanel/queue';
@@ -24,7 +26,7 @@ import miscRouter from './routes/misc.router';
import profileRouter from './routes/profile.router';
import trackRouter from './routes/track.router';
import webhookRouter from './routes/webhook.router';
import { logger, logInfo } from './utils/logger';
import { logger } from './utils/logger';
declare module 'fastify' {
interface FastifyRequest {
@@ -49,12 +51,70 @@ async function withTimings<T>(promise: Promise<T>) {
const port = parseInt(process.env.API_PORT || '3000', 10);
const startServer = async () => {
logInfo('Starting server');
logger.info('Starting server');
try {
const fastify = Fastify({
maxParamLength: 15_000,
bodyLimit: 1048576 * 500, // 500MB
logger,
logger: logger as unknown as FastifyBaseLogger,
disableRequestLogging: true,
genReqId: (req) =>
req.headers['request-id']
? String(req.headers['request-id'])
: generateId(),
});
const getTrpcInput = (
request: FastifyRequest
): Record<string, unknown> | undefined => {
const input = path(['query', 'input'], request);
try {
return typeof input === 'string' ? JSON.parse(input).json : input;
} catch (e) {
return undefined;
}
};
// add header to request if it does not exist
fastify.addHook('onRequest', (request, reply, done) => {
if (!request.headers['request-id']) {
request.headers['request-id'] = request.id;
}
done();
});
fastify.addHook('onRequest', (request, reply, done) => {
if (request.url.includes('trpc')) {
request.log.info('request incoming', {
url: request.url.split('?')[0],
method: request.method,
input: getTrpcInput(request),
});
} else {
request.log.info('request incoming', {
url: request.url,
method: request.method,
});
}
done();
});
fastify.addHook('onResponse', (request, reply, done) => {
if (request.url.includes('trpc')) {
request.log.info('request done', {
url: request.url.split('?')[0],
method: request.method,
input: getTrpcInput(request),
responseTime: reply.elapsedTime,
});
} else {
request.log.info('request done', {
url: request.url,
method: request.method,
responseTime: reply.elapsedTime,
});
}
done();
});
fastify.register(compress, {
@@ -117,12 +177,13 @@ const startServer = async () => {
trpcOptions: {
router: appRouter,
createContext: createContext,
onError(error: unknown) {
if (error instanceof Error) {
logger.error(error, error.message);
} else if (error && typeof error === 'object' && 'error' in error) {
logger.error(error.error, 'Unknown error trpc error');
}
onError(ctx) {
ctx.req.log.error('trpc error', {
error: ctx.error,
path: ctx.path,
input: ctx.input,
type: ctx.type,
});
},
} satisfies FastifyTRPCPluginOptions<AppRouter>['trpcOptions'],
});
@@ -139,11 +200,7 @@ const startServer = async () => {
fastify.register(importRouter, { prefix: '/import' });
fastify.register(trackRouter, { prefix: '/track' });
fastify.setErrorHandler((error, request, reply) => {
logger.error(error, 'Error in request', {
url: request.url,
method: request.method,
headers: request.headers,
});
request.log.error('request error', { error });
reply.status(500).send('Internal server error');
});
fastify.get('/', (_request, reply) => {
@@ -185,12 +242,26 @@ const startServer = async () => {
: null,
});
});
fastify.get('/healthcheck/queue', async (request, reply) => {
const count = await eventsQueue.getWaitingCount();
if (count > 40) {
reply.status(500).send({
ok: false,
count,
});
} else {
reply.status(200).send({
ok: true,
count,
});
}
});
if (process.env.NODE_ENV === 'production') {
for (const signal of ['SIGINT', 'SIGTERM']) {
process.on(signal, (err) => {
logger.fatal(err, `uncaught exception detected ${signal}`);
fastify.close().then((err) => {
process.exit(err ? 1 : 0);
process.on(signal, (error) => {
logger.error(`uncaught exception detected ${signal}`, error);
fastify.close().then((error) => {
process.exit(error ? 1 : 0);
});
});
}
@@ -203,8 +274,8 @@ const startServer = async () => {
// Notify when keys expires
getRedisPub().config('SET', 'notify-keyspace-events', 'Ex');
} catch (e) {
logger.error(e, 'Failed to start server');
} catch (error) {
logger.error('Failed to start server', error);
}
};

View File

@@ -21,7 +21,7 @@ const eventRouter: FastifyPluginCallback = (fastify, opts, done) => {
if (error instanceof SdkAuthError) {
return reply.status(401).send(error.message);
}
logger.error(error, 'Failed to validate sdk request');
logger.error('Failed to validate sdk request', { error });
return reply.status(401).send('Unknown validation error');
});
@@ -46,8 +46,8 @@ const eventRouter: FastifyPluginCallback = (fastify, opts, done) => {
});
reply.status(202).send('OK');
}
} catch (e) {
logger.error(e, 'Failed to create bot event');
} catch (error) {
logger.error('Failed to create bot event', { error });
reply.status(401).send();
return;
}

View File

@@ -11,7 +11,7 @@ const eventRouter: FastifyPluginCallback = (fastify, opts, done) => {
if (error instanceof SdkAuthError) {
return reply.status(401).send(error.message);
}
logger.error(error, 'Failed to validate sdk request');
logger.error('Failed to validate sdk request', { error });
return reply.status(401).send('Unknown validation error');
});
@@ -28,8 +28,8 @@ const eventRouter: FastifyPluginCallback = (fastify, opts, done) => {
if (bot) {
return reply.status(202).send('OK');
}
} catch (e) {
logger.error(e, 'Failed to create bot event');
} catch (error) {
logger.error('Failed to create bot event', { error });
reply.status(401).send();
return;
}

View File

@@ -21,7 +21,7 @@ const trackRouter: FastifyPluginCallback = (fastify, opts, done) => {
if (error instanceof SdkAuthError) {
return reply.status(401).send(error.message);
}
logger.error(error, 'Failed to validate sdk request');
logger.error('Failed to validate sdk request', { error });
return reply.status(401).send('Unknown validation error');
});
@@ -50,8 +50,8 @@ const trackRouter: FastifyPluginCallback = (fastify, opts, done) => {
reply.status(202).send('OK');
}
} catch (e) {
logger.error(e, 'Failed to create bot event');
} catch (error) {
logger.error('Failed to create bot event', { error });
reply.status(401).send();
return;
}

View File

@@ -1,10 +1,3 @@
import { createLogger } from '@openpanel/logger';
export const logger = createLogger({ dataset: 'api' });
export function logInfo(msg: string, obj?: unknown) {
logger.info(obj, msg);
}
export const noop = (message: string) => (error: unknown) =>
logger.error(error, message);
export const logger = createLogger({ name: 'api' });

View File

@@ -51,8 +51,8 @@ export async function parseIp(ip?: string): Promise<GeoLocation> {
longitude: res.longitude,
latitude: res.latitude,
};
} catch (e) {
logger.error('Failed to fetch geo location for ip', e);
} catch (error) {
logger.error('Failed to fetch geo location for ip', { error });
return geo;
}
}

View File

@@ -16,6 +16,8 @@
"@clerk/nextjs": "^5.0.12",
"@clickhouse/client": "^1.2.0",
"@hookform/resolvers": "^3.3.4",
"@hyperdx/browser": "^0.21.1",
"@hyperdx/node-opentelemetry": "^0.8.1",
"@openpanel/common": "workspace:^",
"@openpanel/constants": "workspace:^",
"@openpanel/db": "workspace:^",

View File

@@ -1,12 +1,13 @@
'use client';
import React, { useRef, useState } from 'react';
import React, { useEffect, useRef, useState } from 'react';
import { TooltipProvider } from '@/components/ui/tooltip';
import { ModalProvider } from '@/modals';
import type { AppStore } from '@/redux';
import makeStore from '@/redux';
import { api } from '@/trpc/client';
import { ClerkProvider, useAuth } from '@clerk/nextjs';
import HyperDX from '@hyperdx/browser';
import { QueryClient, QueryClientProvider } from '@tanstack/react-query';
import { httpLink } from '@trpc/client';
import { ThemeProvider } from 'next-themes';
@@ -17,7 +18,7 @@ import superjson from 'superjson';
import { OpenPanelComponent } from '@openpanel/nextjs';
function AllProviders({ children }: { children: React.ReactNode }) {
const { userId, getToken } = useAuth();
const { getToken } = useAuth();
const [queryClient] = useState(
() =>
new QueryClient({
@@ -56,6 +57,19 @@ function AllProviders({ children }: { children: React.ReactNode }) {
storeRef.current = makeStore();
}
useEffect(() => {
if (process.env.NEXT_PUBLIC_HYPERDX_API_KEY) {
HyperDX.init({
apiKey: process.env.NEXT_PUBLIC_HYPERDX_API_KEY,
service: 'dashboard-browser',
tracePropagationTargets: [/api.openpanel.dev/i], // Set to link traces from frontend to backend requests
advancedNetworkCapture: true,
consoleCapture: true,
captureConsole: true,
});
}
}, []);
return (
<ThemeProvider
attribute="class"

View File

@@ -1,9 +1,10 @@
/* eslint-disable */
export async function register() {
if (
process.env.NODE_ENV === 'production' &&
process.env.NEXT_RUNTIME === 'nodejs'
) {
if (process.env.NEXT_RUNTIME === 'nodejs' && process.env.HYPERDX_API_KEY) {
const { initSDK } = await import('@hyperdx/node-opentelemetry');
initSDK({
consoleCapture: true,
apiKey: process.env.HYPERDX_API_KEY,
service: 'dashboard',
});
}
}

View File

@@ -20,8 +20,6 @@
"@openpanel/redis": "workspace:*",
"bullmq": "^5.8.7",
"express": "^4.18.2",
"pino": "^8.17.2",
"pino-pretty": "^10.3.1",
"prom-client": "^15.1.3",
"ramda": "^0.29.1",
"sqlstring": "^2.3.3",

View File

@@ -13,6 +13,7 @@ import { cronJob } from './jobs/cron';
import { eventsJob } from './jobs/events';
import { sessionsJob } from './jobs/sessions';
import { register } from './metrics';
import { logger } from './utils/logger';
const PORT = parseInt(process.env.WORKER_PORT || '3000', 10);
const serverAdapter = new ExpressAdapter();
@@ -60,25 +61,40 @@ async function start() {
console.log(`For the UI, open http://localhost:${PORT}/`);
});
function workerLogger(worker: string, type: string, err?: Error) {
console.log(`Worker ${worker} -> ${type}`);
if (err) {
console.error(err);
}
}
const workers = [sessionsWorker, eventsWorker, cronWorker];
workers.forEach((worker) => {
worker.on('error', (err) => {
workerLogger(worker.name, 'error', err);
worker.on('error', (error) => {
logger.error('worker error', {
worker: worker.name,
error,
});
});
worker.on('closed', () => {
workerLogger(worker.name, 'closed');
logger.info('worker closed', {
worker: worker.name,
});
});
worker.on('ready', () => {
workerLogger(worker.name, 'ready');
logger.info('worker ready', {
worker: worker.name,
});
});
worker.on('failed', (job) => {
logger.error('job failed', {
worker: worker.name,
data: job?.data,
error: job?.failedReason,
options: job?.opts,
});
});
worker.on('ioredis:close', () => {
logger.error('worker closed due to ioredis:close', {
worker: worker.name,
});
});
});
@@ -88,7 +104,10 @@ async function start() {
await sessionsWorker.close();
await cronWorker.close();
} catch (e) {
console.error('EXIT HANDLER ERROR', e);
logger.error('exit handler error', {
code: evtOrExitCodeOrError,
error: e,
});
}
process.exit(isNaN(+evtOrExitCodeOrError) ? 1 : +evtOrExitCodeOrError);

View File

@@ -1,3 +1,3 @@
import { createLogger } from '@openpanel/logger';
export const logger = createLogger({ dataset: 'worker' });
export const logger = createLogger({ name: 'worker' });

View File

@@ -3,3 +3,7 @@ import { nanoid } from 'nanoid/non-secure';
export function shortId() {
return nanoid(4);
}
export function generateId() {
return nanoid(8);
}

View File

@@ -19,6 +19,7 @@
"@clickhouse/client": "^1.2.0",
"@openpanel/common": "workspace:*",
"@openpanel/constants": "workspace:*",
"@openpanel/logger": "workspace:*",
"@openpanel/redis": "workspace:*",
"@openpanel/validation": "workspace:*",
"@prisma/client": "^5.1.1",

View File

@@ -1,12 +1,6 @@
import { createLogger } from '@openpanel/logger';
import { getRedisCache } from '@openpanel/redis';
const logger = {
debug: (...args: unknown[]) => console.log('[DEBUG]', ...args),
info: (...args: unknown[]) => console.log('[INFO]', ...args),
warn: (...args: unknown[]) => console.log('[WARN]', ...args),
error: (...args: unknown[]) => console.log('[ERROR]', ...args),
};
export const DELETE = '__DELETE__';
export type QueueItem<T> = {
@@ -47,6 +41,7 @@ export abstract class RedisBuffer<T> {
public prefix = 'op:buffer';
public table: string;
public batchSize?: number;
public logger: ReturnType<typeof createLogger>;
// abstract methods
public abstract onInsert?: OnInsert<T>;
@@ -58,6 +53,9 @@ export abstract class RedisBuffer<T> {
constructor(options: { table: string; batchSize?: number }) {
this.table = options.table;
this.batchSize = options.batchSize;
this.logger = createLogger({ name: `buffer` }).child({
table: this.table,
});
}
public getKey(name?: string) {
@@ -73,12 +71,12 @@ export abstract class RedisBuffer<T> {
await getRedisCache().rpush(this.getKey(), JSON.stringify(value));
const length = await getRedisCache().llen(this.getKey());
logger.debug(
this.logger.debug(
`Inserted item into buffer ${this.table}. Current length: ${length}`
);
if (this.batchSize && length >= this.batchSize) {
logger.info(
this.logger.info(
`Buffer ${this.table} reached batch size (${this.batchSize}). Flushing...`
);
this.flush();
@@ -90,11 +88,13 @@ export abstract class RedisBuffer<T> {
const queue = await this.getQueue(this.batchSize || -1);
if (queue.length === 0) {
logger.debug(`Flush called on empty buffer ${this.table}`);
this.logger.debug(`Flush called on empty buffer ${this.table}`);
return { count: 0, data: [] };
}
logger.info(`Flushing ${queue.length} items from buffer ${this.table}`);
this.logger.info(
`Flushing ${queue.length} items from buffer ${this.table}`
);
try {
const indexes = await this.processQueue(queue);
@@ -105,18 +105,18 @@ export abstract class RedisBuffer<T> {
if (this.onCompleted) {
const res = await this.onCompleted(data);
logger.info(
this.logger.info(
`Completed processing ${res.length} items from buffer ${this.table}`
);
return { count: res.length, data: res };
}
logger.info(
this.logger.info(
`Processed ${indexes.length} items from buffer ${this.table}`
);
return { count: indexes.length, data: indexes };
} catch (e) {
logger.error(
this.logger.error(
`Failed to process queue while flushing buffer ${this.table}:`,
e
);
@@ -126,12 +126,12 @@ export abstract class RedisBuffer<T> {
data: JSON.stringify(queue.map((item) => item.event)),
retries: 0,
});
logger.warn(
this.logger.warn(
`Stored ${queue.length} failed items in ${this.getKey(`failed:${timestamp}`)}`
);
}
} catch (e) {
logger.error(
this.logger.error(
`Failed to get queue while flushing buffer ${this.table}:`,
e
);
@@ -145,7 +145,9 @@ export abstract class RedisBuffer<T> {
});
multi.lrem(this.getKey(), 0, DELETE);
await multi.exec();
logger.debug(`Deleted ${indexes.length} items from buffer ${this.table}`);
this.logger.debug(
`Deleted ${indexes.length} items from buffer ${this.table}`
);
}
public async getQueue(limit: number): Promise<QueueItem<T>[]> {
@@ -156,7 +158,9 @@ export abstract class RedisBuffer<T> {
index,
}))
.filter((item): item is QueueItem<T> => item.event !== null);
logger.debug(`Retrieved ${result.length} items from buffer ${this.table}`);
this.logger.debug(
`Retrieved ${result.length} items from buffer ${this.table}`
);
return result;
}
@@ -164,7 +168,7 @@ export abstract class RedisBuffer<T> {
try {
return JSON.parse(item);
} catch (e) {
logger.warn(`Failed to parse item in buffer ${this.table}:`, e);
this.logger.warn(`Failed to parse item in buffer ${this.table}:`, e);
return null;
}
}

View File

@@ -1,4 +1,4 @@
import { groupBy, omit, pick } from 'ramda';
import { groupBy, omit } from 'ramda';
import SuperJSON from 'superjson';
import { deepMergeObjects } from '@openpanel/common';

View File

@@ -2,8 +2,11 @@ import type { ResponseJSON } from '@clickhouse/client';
import { createClient } from '@clickhouse/client';
import { escape } from 'sqlstring';
import { createLogger } from '@openpanel/logger';
import type { IInterval } from '@openpanel/validation';
const logger = createLogger({ name: 'clickhouse' });
export const TABLE_NAMES = {
events: 'events_v2',
profiles: 'profiles',
@@ -33,6 +36,10 @@ export const ch = new Proxy(originalCh, {
get(target, property, receiver) {
if (property === 'insert' || property === 'query') {
return async (...args: any[]) => {
const childLogger = logger.child({
query: args[0].query,
property,
});
try {
// First attempt
if (property in target) {
@@ -46,27 +53,26 @@ export const ch = new Proxy(originalCh, {
error.message.includes('socket hang up') ||
error.message.includes('Timeout error'))
) {
console.info(
`Caught ${error.message} error on ${property.toString()}, retrying once.`
);
childLogger.error(`Captured error`, {
error,
});
await new Promise((resolve) => setTimeout(resolve, 500));
try {
// Retry once
childLogger.info(`Retrying query`);
if (property in target) {
// @ts-expect-error
return await target[property](...args);
}
} catch (retryError) {
console.error(
`Retry failed for ${property.toString()}:`,
retryError
);
logger.error(`Retry failed`, retryError);
throw retryError; // Rethrow or handle as needed
}
} else {
if (args[0].query) {
console.log('FAILED QUERY:', args[0].query);
}
logger.error('query failed', {
...args[0],
error,
});
// Handle other errors or rethrow them
throw error;
@@ -103,10 +109,12 @@ export async function chQueryWithMeta<T extends Record<string, any>>(
}),
};
console.log(
`Query: (${Date.now() - start}ms, ${response.statistics?.elapsed}ms), Rows: ${json.rows}`,
query
);
logger.info('query info', {
query,
rows: json.rows,
stats: response.statistics,
elapsed: Date.now() - start,
});
return response;
}

View File

@@ -1,19 +1,45 @@
import type { TransportTargetOptions } from 'pino';
import pino from 'pino';
import * as HyperDX from '@hyperdx/node-opentelemetry';
import winston from 'winston';
export function createLogger({ dataset }: { dataset: string }) {
const targets: TransportTargetOptions[] =
process.env.NODE_ENV === 'production' && process.env.BASELIME_API_KEY
? []
: [
{
target: 'pino-pretty',
},
];
export { winston };
const transport = pino.transport({
targets,
export type ILogger = winston.Logger & {
noop: (message: string) => (error: unknown) => void;
};
const logLevel = process.env.LOG_LEVEL ?? 'info';
export function createLogger({ name }: { name: string }): ILogger {
const service = `${name}-${process.env.NODE_ENV ?? 'dev'}`;
const format = process.env.HYPERDX_API_KEY
? winston.format.json()
: winston.format.prettyPrint();
const transports: winston.transport[] = [new winston.transports.Console()];
if (process.env.HYPERDX_API_KEY) {
transports.push(
HyperDX.getWinstonTransport(logLevel, {
detectResources: true,
service,
})
);
}
const logger = winston.createLogger({
defaultMeta: { service },
level: logLevel,
format,
transports,
// Add ISO levels of logging from PINO
levels: Object.assign(
{ fatal: 0, warn: 4, trace: 7 },
winston.config.syslog.levels
),
});
return pino(transport);
return Object.assign(logger, {
noop: (message: string) => (error: unknown) =>
logger.error(`noop: ${message}`, error),
});
}

View File

@@ -8,8 +8,8 @@
"typecheck": "tsc --noEmit"
},
"dependencies": {
"pino": "^8.17.2",
"pino-pretty": "^10.3.1"
"@hyperdx/node-opentelemetry": "^0.8.1",
"winston": "^3.14.2"
},
"devDependencies": {
"@openpanel/eslint-config": "workspace:*",
@@ -28,4 +28,4 @@
]
},
"prettier": "@openpanel/prettier-config"
}
}

2064
pnpm-lock.yaml generated

File diff suppressed because it is too large Load Diff