From 3ef9b1536b7905981ef84713b3c1ab39b9c1aa0b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Szil=C3=A1rd=20D=C3=B3r=C3=B3?= Date: Wed, 26 Apr 2023 12:22:07 +0200 Subject: [PATCH 1/4] chore: improve log verbosity --- src/app.ts | 14 +++---- src/logger.ts | 47 +++++++++++++++++----- src/utils/__generated__/graphql-request.ts | 7 ++++ 3 files changed, 50 insertions(+), 18 deletions(-) diff --git a/src/app.ts b/src/app.ts index 7fe57ece0..af3941254 100644 --- a/src/app.ts +++ b/src/app.ts @@ -1,13 +1,12 @@ -import express from 'express'; -import helmet from 'helmet'; import { json } from 'body-parser'; import cors from 'cors'; - -import router from './routes'; +import express from 'express'; +import helmet from 'helmet'; import { serverErrors } from './errors'; +import { httpLogger, uncaughtErrorLogger } from './logger'; import { authMiddleware } from './middleware/auth'; import { addOpenApiRoute } from './openapi'; -import { uncaughtErrorLogger, httpLogger } from './logger'; +import router from './routes'; const app = express(); @@ -16,12 +15,11 @@ if (process.env.NODE_ENV === 'production') { } addOpenApiRoute(app); -app.use(httpLogger); +app.use(httpLogger); app.use(helmet(), json(), cors()); app.use(authMiddleware); - app.use(router); - app.use(uncaughtErrorLogger, serverErrors); + export { app }; diff --git a/src/logger.ts b/src/logger.ts index a8bb2af90..eeedceb6c 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -1,6 +1,6 @@ -import winston from 'winston'; -import expressWinston, { LoggerOptions } from 'express-winston'; import { Response } from 'express'; +import expressWinston, { LoggerOptions } from 'express-winston'; +import winston from 'winston'; export const LOG_LEVEL = process.env.AUTH_LOG_LEVEL || 'info'; // * Create a common Winston logger that can be used in both middlewares and manually @@ -12,13 +12,39 @@ export const logger = winston.createLogger({ // * Give more importance to Unauthorized and Forbidden status codes to give more visibility to hacking attempts const SUSPICIOUS_REQUEST_CODES = [401, 403]; -const rewriteUrl = (url: string) => { - if (LOG_LEVEL !== 'debug' && (url.includes('?') || url.includes('#'))) { - const pathname = new URL(url, 'http://noop').pathname; - const char = url.includes('?') ? '?' : '#'; - return `${pathname}${char}*****`; +const maskUrl = (url: string) => { + if (LOG_LEVEL === 'debug' || (!url.includes('?') && !url.includes('#'))) { + return url; + } + + const { pathname, searchParams, hash } = new URL(url, 'http://noop'); + const queryParameters = Array.from(searchParams.keys()); + + if (queryParameters.length > 0) { + return `${pathname}?${queryParameters + .map((param) => `${param}=*****`) + .join('&')})}`; } - return url; + + if (hash) { + return `${pathname}#*****`; + } + + return pathname; +}; + +const maskHeaders = (headers: Record) => { + if (LOG_LEVEL === 'DEBUG') { + return headers; + } + + return Object.keys(headers).reduce( + (returnableHeaders, key) => ({ + ...returnableHeaders, + [key]: '*****', + }), + {} + ); }; const loggerOptions: LoggerOptions = { @@ -27,7 +53,7 @@ const loggerOptions: LoggerOptions = { metaField: null, responseField: null, msg: (req, res) => - `${req.method} ${rewriteUrl(req.url)} ${res.statusCode} ${ + `${req.method} ${maskUrl(req.url)} ${res.statusCode} ${ // eslint-disable-next-line @typescript-eslint/no-explicit-any (res as any).responseTime }ms`, @@ -45,7 +71,8 @@ const loggerOptions: LoggerOptions = { meta.url = url; meta.headers = headers; } else { - meta.url = rewriteUrl(url); + meta.url = maskUrl(url); + meta.headers = maskHeaders(headers); } const userId = auth?.userId; if (userId) { diff --git a/src/utils/__generated__/graphql-request.ts b/src/utils/__generated__/graphql-request.ts index 7a026540c..7c91f3da0 100644 --- a/src/utils/__generated__/graphql-request.ts +++ b/src/utils/__generated__/graphql-request.ts @@ -13048,6 +13048,7 @@ export type Query_Root = { /** fetch aggregated fields from the table: "cli_tokens" */ cliTokensAggregate: CliTokens_Aggregate; config?: Maybe; + configRawJSON: Scalars['String']; configs: Array; /** fetch data from the table: "continents" */ continents: Array; @@ -13571,6 +13572,12 @@ export type Query_RootConfigArgs = { }; +export type Query_RootConfigRawJsonArgs = { + appID: Scalars['uuid']; + resolve: Scalars['Boolean']; +}; + + export type Query_RootConfigsArgs = { resolve: Scalars['Boolean']; where?: InputMaybe; From 738c2b47f730026d893dcd4b994066be9e32abef Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Szil=C3=A1rd=20D=C3=B3r=C3=B3?= Date: Wed, 26 Apr 2023 12:26:11 +0200 Subject: [PATCH 2/4] chore: add changeset --- .changeset/long-trainers-pretend.md | 5 +++++ 1 file changed, 5 insertions(+) create mode 100644 .changeset/long-trainers-pretend.md diff --git a/.changeset/long-trainers-pretend.md b/.changeset/long-trainers-pretend.md new file mode 100644 index 000000000..96830ea7d --- /dev/null +++ b/.changeset/long-trainers-pretend.md @@ -0,0 +1,5 @@ +--- +'hasura-auth': patch +--- + +chore(logs): add masked headers and query parameters to logs From 441c7f8d2908d66ec71a5fbd2b619b9fc9a162a9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Szil=C3=A1rd=20D=C3=B3r=C3=B3?= Date: Wed, 26 Apr 2023 13:06:25 +0200 Subject: [PATCH 3/4] fix: log unhandled exceptions and rejections --- src/app.ts | 24 +++++++++++++++++++++++- 1 file changed, 23 insertions(+), 1 deletion(-) diff --git a/src/app.ts b/src/app.ts index af3941254..dce19615f 100644 --- a/src/app.ts +++ b/src/app.ts @@ -3,7 +3,7 @@ import cors from 'cors'; import express from 'express'; import helmet from 'helmet'; import { serverErrors } from './errors'; -import { httpLogger, uncaughtErrorLogger } from './logger'; +import { httpLogger, logger, uncaughtErrorLogger } from './logger'; import { authMiddleware } from './middleware/auth'; import { addOpenApiRoute } from './openapi'; import router from './routes'; @@ -22,4 +22,26 @@ app.use(authMiddleware); app.use(router); app.use(uncaughtErrorLogger, serverErrors); +process.on('unhandledRejection', (reason) => { + if (reason instanceof Error) { + logger.error(`Unhandled Rejection`, { + message: reason.message, + stack: reason.stack, + }); + process.exit(1); + } + + logger.error(`Unhandled Rejection: ${reason}`); + process.exit(1); +}); + +process.on('uncaughtException', (err, origin) => { + logger.error(`Uncaught Exception`, { + message: err.message, + stack: err.stack, + origin, + }); + process.exit(1); +}); + export { app }; From 37a8bdd9e0cb90e9c5e10257f3fcecc1e9b18668 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Szil=C3=A1rd=20D=C3=B3r=C3=B3?= Date: Wed, 26 Apr 2023 15:09:16 +0200 Subject: [PATCH 4/4] feat: increase verbosity for 4xx / 5xx error logs --- src/logger.ts | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/logger.ts b/src/logger.ts index eeedceb6c..fd73fa2a0 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -59,14 +59,21 @@ const loggerOptions: LoggerOptions = { }ms`, // * Always log status, method, url, and userId when it exists dynamicMeta: ({ method, url, auth, headers }, res) => { - const { responseTime, statusCode } = res as Response & { + const { responseTime, statusCode, body } = res as Response & { responseTime: number; + body: unknown; }; + const meta: Record = { statusCode, method, latencyInNs: responseTime * 1e6, }; + + if (statusCode >= 400) { + meta.reason = body; + } + if (LOG_LEVEL === 'debug') { meta.url = url; meta.headers = headers; @@ -92,7 +99,7 @@ const loggerOptions: LoggerOptions = { return 'info'; }, requestWhitelist: [], - responseWhitelist: ['responseTime'], + responseWhitelist: ['responseTime', 'body'], }; /**