Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Simplify RPC logs #1473

Merged
merged 1 commit into from
Dec 20, 2022
Merged

Simplify RPC logs #1473

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
35 changes: 23 additions & 12 deletions packages/toolpad-app/pages/api/rpc.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,8 @@ import {
} from '../../src/server/data';
import { getLatestToolpadRelease } from '../../src/server/getLatestRelease';
import { hasOwnProperty } from '../../src/utils/collections';
import { withRpcReqResLogs } from '../../src/server/logs/withLogs';
import { errorFrom, serializeError } from '../../src/utils/errors';
import logger from '../../src/server/logs/logger';

export interface Method<P extends any[] = any[], R = any> {
(...params: P): Promise<R>;
Expand Down Expand Up @@ -72,6 +73,7 @@ function createRpcHandler(definition: Definition): NextApiHandler<RpcResponse> {
res.status(405).end();
return;
}

const { type, name, params } = req.body as RpcRequest;

if (!hasOwnProperty(definition, type) || !hasOwnProperty(definition[type], name)) {
Expand All @@ -82,20 +84,29 @@ function createRpcHandler(definition: Definition): NextApiHandler<RpcResponse> {
const method: MethodResolver<any> = definition[type][name];

let rawResult;
let error: Error | null = null;
try {
rawResult = await method({ params, req, res });
} catch (error) {
console.error(error);
if (error instanceof Error) {
res.json({ error: { message: error.message, code: error.code, stack: error.stack } });
} else {
res.status(500).end();
}

return;
} catch (rawError) {
error = errorFrom(rawError);
}
const responseData: RpcResponse = { result: superjson.stringify(rawResult) };

const responseData: RpcResponse = error
? { error: serializeError(error) }
: { result: superjson.stringify(rawResult) };

res.json(responseData);

const logLevel = error ? 'warn' : 'trace';
logger[logLevel](
{
key: 'rpc',
type,
name,
error,
},
'Handled RPC request',
);
};
}

Expand Down Expand Up @@ -182,4 +193,4 @@ const rpcServer = {

export type ServerDefinition = MethodsOf<typeof rpcServer>;

export default withRpcReqResLogs(createRpcHandler(rpcServer));
export default createRpcHandler(rpcServer);
2 changes: 0 additions & 2 deletions packages/toolpad-app/src/server/config.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,6 @@ export type ServerConfig = {
encryptionKeys: string[];
basicAuthUser?: string;
basicAuthPassword?: string;
serverLogsEnabled: boolean;
recaptchaV2SecretKey?: string;
recaptchaV3SecretKey?: string;
ecsNodeUrl?: string;
Expand Down Expand Up @@ -55,7 +54,6 @@ function readConfig(): ServerConfig & typeof sharedConfig {
databaseUrl: process.env.TOOLPAD_DATABASE_URL,
googleSheetsClientId: process.env.TOOLPAD_DATASOURCE_GOOGLESHEETS_CLIENT_ID,
googleSheetsClientSecret: process.env.TOOLPAD_DATASOURCE_GOOGLESHEETS_CLIENT_SECRET,
serverLogsEnabled: !!process.env.TOOLPAD_SERVER_LOGS_ENABLED,
recaptchaV2SecretKey: process.env.TOOLPAD_RECAPTCHA_V2_SECRET_KEY,
recaptchaV3SecretKey: process.env.TOOLPAD_RECAPTCHA_V3_SECRET_KEY,
ecsNodeUrl: process.env.TOOLPAD_ECS_NODE_URL,
Expand Down
24 changes: 0 additions & 24 deletions packages/toolpad-app/src/server/logs/logInfo.ts
View file
Open in desktop

This file was deleted.

6 changes: 5 additions & 1 deletion packages/toolpad-app/src/server/logs/logSerializers.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
import { NextApiRequest, NextApiResponse } from 'next';
import { errorFrom } from '../../utils/errors';

function getReqLoggableIPAddress(req: NextApiRequest): string | null {
const forwardedHeader = req.headers['x-forwarded-for'];
Expand Down Expand Up @@ -38,9 +39,12 @@ export function resSerializer(res: NextApiResponse) {
};
}

export function resErrSerializer(error: Error) {
export function errSerializer(rawError: unknown) {
const error = errorFrom(rawError);
return {
message: error.message,
name: error.name,
stack: error.stack,
code: error.code,
};
}
35 changes: 30 additions & 5 deletions packages/toolpad-app/src/server/logs/logger.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,8 +1,8 @@
import pino from 'pino';
import ecsFormat from '@elastic/ecs-pino-format';

import type { NextApiRequest, NextApiResponse } from 'next';
import config from '../config';
import { reqSerializer, resSerializer, resErrSerializer } from './logSerializers';
import { errSerializer, reqSerializer, resSerializer } from './logSerializers';

let transport;
if (config.ecsNodeUrl) {
Expand All @@ -21,17 +21,42 @@ if (config.ecsNodeUrl) {

const logger = pino(
{
enabled: config.serverLogsEnabled,
level: process.env.LOG_LEVEL || 'info',
redact: { paths: [] },
serializers: {
err: errSerializer,
error: errSerializer,
req: reqSerializer,
res: resSerializer,
resErr: resErrSerializer,
},
...(config.ecsNodeUrl ? ecsFormat() : {}),
},
transport,
);

export default logger;
interface ReqResLogPayload {
key: 'apiReqRes';
req: NextApiRequest;
res: NextApiResponse;
}

interface RpcReqResLogPayload {
key: 'rpc';
type: 'query' | 'mutation';
name: string;
error: Error | null;
}

type LogPayload = ReqResLogPayload | RpcReqResLogPayload;

function logMethod(method: 'info' | 'trace' | 'error' | 'warn' | 'fatal') {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nice, this works better than a function just for logInfo

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I'm thinking roughly:

  • fatal: Unrecoverable errors, the node process should crash (or has crashed and this is the report).
  • error: Unexpected, but we can degrade in a safe way. The user experience is impacted, so this must be investigated
  • warn: Unexpected, but we can degrade in a safe way. The user experience isn't really impacted, investigate when lots of these happen.
  • info: informational, we want to see these appear in a log aggregator for metrics

We play with logelevel on different use-cases

  • production: info
  • local: warn, info will most likely lead to too many logs

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sounds great, one of the alerts I set up in Sentry was for frequent warnings too.

return (obj: LogPayload, msg: string) => logger[method](obj, msg);
}

export default {
info: logMethod('info'),
trace: logMethod('trace'),
error: logMethod('error'),
warn: logMethod('warn'),
fatal: logMethod('fatal'),
};
58 changes: 2 additions & 56 deletions packages/toolpad-app/src/server/logs/withLogs.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,44 +1,10 @@
import { NextApiHandler, NextApiRequest, NextApiResponse } from 'next';
import logInfo from './logInfo';
import type { RpcResponse } from '../../../pages/api/rpc';

type RestArgs = [
chunk: any,
encoding: BufferEncoding,
callback?: ((error?: Error | null) => void) | undefined,
];

const logWithResponseBody = (
res: NextApiResponse,
logHandler: (responseBody: Record<string, unknown>) => void,
): void => {
const oldWrite = res.write;
const oldEnd = res.end;

const chunks: Buffer[] = [];
res.write = (...restArgs: any[]) => {
chunks.push(Buffer.from(restArgs[0]));
return oldWrite.apply(res, restArgs as RestArgs);
};

res.end = (...restArgs: any[]) => {
if (restArgs[0]) {
chunks.push(Buffer.from(restArgs[0]));
}

const loggableResponseBody = JSON.parse(Buffer.concat(chunks).toString('utf8'), (key, value) =>
key === 'stack' ? undefined : value,
);
logHandler(loggableResponseBody);

return oldEnd.apply(res, restArgs as RestArgs);
};
};
import logger from './logger';

export const withReqResLogs =
(apiHandler: NextApiHandler) =>
(req: NextApiRequest, res: NextApiResponse): unknown | Promise<unknown> => {
logInfo(
logger.info(
{
key: 'apiReqRes',
req,
Expand All @@ -49,23 +15,3 @@ export const withReqResLogs =

return apiHandler(req, res);
};

export const withRpcReqResLogs =
(apiHandler: NextApiHandler) =>
async (req: NextApiRequest, res: NextApiResponse): Promise<unknown> => {
logWithResponseBody(res, (resBody) => {
const error = (resBody as RpcResponse).error;

logInfo(
{
key: 'rpcReqRes',
req,
res,
...(error ? { resErr: error } : {}),
},
'Handled RPC request',
);
});

return apiHandler(req, res);
};