fix(cli-repl): json-clone objects before passing them to pino MONGOSH-884 (#1002)

Author: addaleax

packages/cli-repl/src/setup-logger-and-telemetry.spec.ts

@@ -56,6 +56,11 @@ describe('setupLoggerAndTelemetry', () => {
     bus.emit('mongosh:evaluate-input', { input: '1+1' });
     bus.emit('mongosh:driver-initialized', { driver: { name: 'nodejs', version: '3.6.1' } });
 
+    const circular: any = {};
+    circular.circular = circular;
+    bus.emit('mongosh:api-call', { method: 'circulararg', arguments: { options: { circular } } });
+    expect(circular.circular).to.equal(circular); // Make sure the argument is still intact afterwards
+
     bus.emit('mongosh:start-loading-cli-scripts', { usesShellOption: true });
     bus.emit('mongosh:api-load-file', { nested: true, filename: 'foobar.js' });
     bus.emit('mongosh:start-mongosh-repl', { version: '1.0.0' });
@@ -79,7 +84,7 @@ describe('setupLoggerAndTelemetry', () => {
     bus.emit('mongosh-snippets:snippet-command', { args: ['install', 'foo'] });
     bus.emit('mongosh-snippets:transform-error', { error: 'failed', addition: 'oh no', name: 'foo' });
 
-    bus.emit('mongosh-sp:connect-heartbeat-failure', { connectionId: 'localhost', failure: new Error(), isFailFast: true, isKnownServer: true });
+    bus.emit('mongosh-sp:connect-heartbeat-failure', { connectionId: 'localhost', failure: new Error('cause'), isFailFast: true, isKnownServer: true });
     bus.emit('mongosh-sp:connect-heartbeat-succeeded', { connectionId: 'localhost' });
     bus.emit('mongosh-sp:connect-fail-early');
     bus.emit('mongosh-sp:connect-attempt-finished');
@@ -116,6 +121,7 @@ describe('setupLoggerAndTelemetry', () => {
     expect(logOutput[i].msg).to.match(/^mongosh:evaluate-input/);
     expect(logOutput[i++].msg).to.match(/"input":"1\+1"/);
     expect(logOutput[i++].msg).to.match(/"version":"3.6.1"/);
+    expect(logOutput[i++].msg).to.match(/^mongosh:api-call \{"_inspected":"\{.+circular:.+\}/);
     expect(logOutput[i++].msg).to.equal('mongosh:start-loading-cli-scripts');
     expect(logOutput[i].msg).to.match(/^mongosh:api-load-file/);
     expect(logOutput[i].msg).to.match(/"nested":true/);
@@ -143,7 +149,7 @@ describe('setupLoggerAndTelemetry', () => {
     expect(logOutput[i++].msg).to.equal('mongosh-snippets:load-snippet {"source":"load-all","name":"foo"}');
     expect(logOutput[i++].msg).to.equal('mongosh-snippets:snippet-command {"args":["install","foo"]}');
     expect(logOutput[i++].msg).to.equal('mongosh-snippets:transform-error {"error":"failed","addition":"oh no","name":"foo"}');
-    expect(logOutput[i++].msg).to.equal('mongosh-sp:connect-heartbeat-failure {"connectionId":"localhost","failure":{},"isFailFast":true,"isKnownServer":true}');
+    expect(logOutput[i++].msg).to.equal('mongosh-sp:connect-heartbeat-failure {"connectionId":"localhost","failure":"cause","isFailFast":true,"isKnownServer":true}');
     expect(logOutput[i++].msg).to.equal('mongosh-sp:connect-heartbeat-succeeded {"connectionId":"localhost"}');
     expect(logOutput[i++].msg).to.equal('mongosh-sp:connect-fail-early');
     expect(logOutput[i++].msg).to.equal('mongosh-sp:connect-attempt-finished');

packages/cli-repl/src/setup-logger-and-telemetry.ts

@@ -32,6 +32,7 @@ import type {
   SpResolveSrvSucceededEvent,
   SpMissingOptionalDependencyEvent
 } from '@mongosh/types';
+import { inspect } from 'util';
 
 interface MongoshAnalytics {
   identify(message: {
@@ -49,6 +50,22 @@ interface MongoshAnalytics {
   }): void;
 }
 
+// The default serializer for pino replaces circular properties it finds
+// anywhere in the object graph. In extreme cases, e.g. when a mongosh cursor
+// is passed to it, it follows the graph all the way to the network socket and
+// replaces random properties of its internal state with the string
+// '"[Circular"]':
+//   https://github.com/davidmarkclements/fast-safe-stringify/blob/0e011f068962e8f8974133a47afcabfc003f2183/index.js#L36
+// As a workaround, we do a JSON-based clone for any input that can contain
+// arbitrary values.
+function jsonClone<T>(input: T): T | { _inspected: string } {
+  try {
+    return JSON.parse(JSON.stringify(input));
+  } catch (error) {
+    return { _inspected: inspect(input) };
+  }
+}
+
 // set up a noop, in case we are not able to connect to segment.
 class NoopAnalytics implements MongoshAnalytics {
   identify(_info: any): void {} // eslint-disable-line @typescript-eslint/no-unused-vars
@@ -102,7 +119,7 @@ export default function setupLoggerAndTelemetry(
     const connectionUri = redactCredentials(args.uri);
     const { uri: _uri, ...argsWithoutUri } = args; // eslint-disable-line @typescript-eslint/no-unused-vars
     const params = { session_id: logId, userId, connectionUri, ...argsWithoutUri };
-    log.info('mongosh:connect', params);
+    log.info('mongosh:connect', jsonClone(params));
 
     if (telemetry) {
       analytics.track({
@@ -118,7 +135,7 @@ export default function setupLoggerAndTelemetry(
   });
 
   bus.on('mongosh:driver-initialized', function(driverMetadata: any) {
-    log.info('mongosh:driver-initialized', driverMetadata);
+    log.info('mongosh:driver-initialized', jsonClone(driverMetadata));
   });
 
   bus.on('mongosh:new-user', function(id: string, enableTelemetry: boolean) {
@@ -186,11 +203,11 @@ export default function setupLoggerAndTelemetry(
   });
 
   bus.on('mongosh:setCtx', function(args: ApiEvent) {
-    log.info('mongosh:setCtx', args);
+    log.info('mongosh:setCtx', jsonClone(args));
   });
 
   bus.on('mongosh:api-call', function(args: ApiEvent) {
-    log.info('mongosh:api-call', redactInfo(args));
+    log.info('mongosh:api-call', redactInfo(jsonClone(args)));
   });
 
   bus.on('mongosh:api-load-file', function(args: ScriptLoadFileEvent) {
@@ -355,7 +372,10 @@ export default function setupLoggerAndTelemetry(
   });
 
   bus.on('mongosh-sp:connect-heartbeat-failure', function(ev: SpConnectHeartbeatFailureEvent) {
-    log.info('mongosh-sp:connect-heartbeat-failure', ev);
+    log.info('mongosh-sp:connect-heartbeat-failure', {
+      ...ev,
+      failure: ev.failure?.message
+    });
   });
 
   bus.on('mongosh-sp:connect-heartbeat-succeeded', function(ev: SpConnectHeartbeatSucceededEvent) {