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 <[email protected]>

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                                                                                                                                                                                                                                                                                                                     |

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;
+  }
 }
 
 /**

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.

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} &