From 76fcfd733e94b70104f521a58164c545d715b177 Mon Sep 17 00:00:00 2001 From: Florent Date: Tue, 27 Aug 2024 12:38:35 +0200 Subject: [PATCH] Small: Log requests body (#913) Add body in log requests. GRIST_LOG_SKIP_HTTP is a badly named environment variable and its expected values are confusing (to log the requests, you actually have to set its value to "", and setting to "false" actually is equivalent to setting to "true"). We deprecate this env variable in favor of GRIST_LOG_HTTP which is more convenient and understandable: - by default, its undefined, so nothing is logged; - to enable the logs, you just have to set GRIST_LOG_HTTP=true Also this commit removes the default value for GRIST_LOG_SKIP_HTTP, because we don't have to set it to "true" to actually disable the requests logging thanks to GRIST_LOG_HTTP. FlexServer now handles the historical behavior for this deprecated variable. --------- Co-authored-by: Jonathan Perret --- README.md | 2 ++ app/server/lib/FlexServer.ts | 42 +++++++++++++++++++++++++++++++++--- stubs/app/server/server.ts | 1 - test/test_under_docker.sh | 5 ++++- 4 files changed, 45 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index 401baf37..d2e0a9e4 100644 --- a/README.md +++ b/README.md @@ -312,6 +312,8 @@ Grist can be configured in many ways. Here are the main environment variables it | GRIST_UI_FEATURES | comma-separated list of UI features to enable. Allowed names of parts: `helpCenter,billing,templates,createSite,multiSite,multiAccounts,sendToDrive,tutorials,supportGrist`. If a part also exists in GRIST_HIDE_UI_ELEMENTS, it won't be enabled. | | GRIST_UNTRUSTED_PORT | if set, plugins will be served from the given port. This is an alternative to setting APP_UNTRUSTED_URL. | | GRIST_WIDGET_LIST_URL | a url pointing to a widget manifest, by default `https://github.com/gristlabs/grist-widget/releases/download/latest/manifest.json` is used | +| GRIST_LOG_HTTP | When set to `true`, log HTTP requests and responses information. Defaults to `false`. | +| GRIST_LOG_HTTP_BODY | When this variable and `GRIST_LOG_HTTP` are set to `true` , log the body along with the HTTP requests. :warning: Be aware it may leak confidential information in the logs.:warning: Defaults to `false`. | | COOKIE_MAX_AGE | session cookie max age, defaults to 90 days; can be set to "none" to make it a session cookie | | HOME_PORT | port number to listen on for REST API server; if set to "share", add API endpoints to regular grist port. | | PORT | port number to listen on for Grist server | diff --git a/app/server/lib/FlexServer.ts b/app/server/lib/FlexServer.ts index 37070d98..5391b5f2 100644 --- a/app/server/lib/FlexServer.ts +++ b/app/server/lib/FlexServer.ts @@ -442,24 +442,33 @@ export class FlexServer implements GristServer { public addLogging() { if (this._check('logging')) { return; } - if (process.env.GRIST_LOG_SKIP_HTTP) { return; } + if (!this._httpLoggingEnabled()) { return; } // Add a timestamp token that matches exactly the formatting of non-morgan logs. morganLogger.token('logTime', (req: Request) => log.timestamp()); // Add an optional gristInfo token that can replace the url, if the url is sensitive. morganLogger.token('gristInfo', (req: RequestWithGristInfo) => req.gristInfo || req.originalUrl || req.url); morganLogger.token('host', (req: express.Request) => req.get('host')); - const msg = ':logTime :host :method :gristInfo :status :response-time ms - :res[content-length]'; + morganLogger.token('body', (req: express.Request) => + req.is('application/json') ? JSON.stringify(req.body) : undefined + ); + + // For debugging, be careful not to enable logging in production (may log sensitive data) + const shouldLogBody = isAffirmative(process.env.GRIST_LOG_HTTP_BODY); + + const msg = `:logTime :host :method :gristInfo ${shouldLogBody ? ':body ' : ''}` + + ":status :response-time ms - :res[content-length]"; // In hosted Grist, render json so logs retain more organization. function outputJson(tokens: any, req: any, res: any) { return JSON.stringify({ timestamp: tokens.logTime(req, res), + host: tokens.host(req, res), method: tokens.method(req, res), path: tokens.gristInfo(req, res), + ...(shouldLogBody ? { body: tokens.body(req, res) } : {}), status: tokens.status(req, res), timeMs: parseFloat(tokens['response-time'](req, res)) || undefined, contentLength: parseInt(tokens.res(req, res, 'content-length'), 10) || undefined, - host: tokens.host(req, res), altSessionId: req.altSessionId, }); } @@ -2489,6 +2498,33 @@ export class FlexServer implements GristServer { []; return [...pluggedMiddleware, sessionClearMiddleware]; } + + /** + * Returns true if GRIST_LOG_HTTP="true" (or any truthy value). + * Returns true if GRIST_LOG_SKIP_HTTP="" (empty string). + * Returns false otherwise. + * + * Also displays a deprecation warning if GRIST_LOG_SKIP_HTTP is set to any value ("", "true", whatever...), + * and throws an exception if GRIST_LOG_SKIP_HTTP and GRIST_LOG_HTTP are both set to make the server crash. + */ + private _httpLoggingEnabled(): boolean { + const deprecatedOptionEnablesLog = process.env.GRIST_LOG_SKIP_HTTP === ''; + const isGristLogHttpEnabled = isAffirmative(process.env.GRIST_LOG_HTTP); + + if (process.env.GRIST_LOG_HTTP !== undefined && process.env.GRIST_LOG_SKIP_HTTP !== undefined) { + throw new Error('Both GRIST_LOG_HTTP and GRIST_LOG_SKIP_HTTP are set. ' + + 'Please remove GRIST_LOG_SKIP_HTTP and set GRIST_LOG_HTTP to the value you actually want.'); + } + + if (process.env.GRIST_LOG_SKIP_HTTP !== undefined) { + const expectedGristLogHttpVal = deprecatedOptionEnablesLog ? "true" : "false"; + + log.warn(`Setting env variable GRIST_LOG_SKIP_HTTP="${process.env.GRIST_LOG_SKIP_HTTP}" ` + + `is deprecated in favor of GRIST_LOG_HTTP="${expectedGristLogHttpVal}"`); + } + + return isGristLogHttpEnabled || deprecatedOptionEnablesLog; + } } /** diff --git a/stubs/app/server/server.ts b/stubs/app/server/server.ts index 6fbffdf5..c7ccc7be 100644 --- a/stubs/app/server/server.ts +++ b/stubs/app/server/server.ts @@ -15,7 +15,6 @@ const debugging = isAffirmative(process.env.DEBUG) || isAffirmative(process.env. if (!debugging) { // Be a lot less noisy by default. setDefaultEnv('GRIST_LOG_LEVEL', 'error'); - setDefaultEnv('GRIST_LOG_SKIP_HTTP', 'true'); } // Use a distinct cookie. Bump version to 2. diff --git a/test/test_under_docker.sh b/test/test_under_docker.sh index fd75fb10..6663691d 100755 --- a/test/test_under_docker.sh +++ b/test/test_under_docker.sh @@ -31,6 +31,8 @@ cleanup() { GRIST_LOG_LEVEL="error" if [[ "${DEBUG:-}" == 1 ]]; then GRIST_LOG_LEVEL="" + GRIST_LOG_HTTP="true" + GRIST_LOG_HTTP_BODY="true" fi docker run --name $DOCKER_CONTAINER --rm \ @@ -39,7 +41,8 @@ docker run --name $DOCKER_CONTAINER --rm \ --env GRIST_SESSION_COOKIE=grist_test_cookie \ --env GRIST_TEST_LOGIN=1 \ --env GRIST_LOG_LEVEL=$GRIST_LOG_LEVEL \ - --env GRIST_LOG_SKIP_HTTP=${DEBUG:-false} \ + --env GRIST_LOG_HTTP=${GRIST_LOG_HTTP:-false} \ + --env GRIST_LOG_HTTP_BODY=${GRIST_LOG_HTTP_BODY:-false} \ --env TEST_SUPPORT_API_KEY=api_key_for_support \ --env GRIST_TEMPLATE_ORG=templates \ ${TEST_IMAGE:-gristlabs/grist} &