feat(logging): custom log entries MONGOSH-1989 (#2322)

* feat(logging): custom log entries MONGOSH-1989

* refactor: finalise pr

* refactor: extend shell log from shell api

* feat: add todo for the log help

* test: extend expect cases

* fix: disable lint for log

* refactor: move methods to the class itself

* refactor: no default export

Author: alenakhineika

packages/e2e-tests/test/e2e.spec.ts

@@ -1506,6 +1506,46 @@ describe('e2e', function () {
             ).to.have.lengthOf(1);
           });
         });
+
+        it('writes custom log directly', async function () {
+          await shell.executeLine("log.info('This is a custom entry')");
+          expect(shell.assertNoErrors());
+          await eventually(async () => {
+            const log = await readLogfile();
+            const customLogEntry = log.filter((logEntry) =>
+              logEntry.msg.includes('This is a custom entry')
+            );
+            expect(customLogEntry).to.have.lengthOf(1);
+            expect(customLogEntry[0].s).to.be.equal('I');
+            expect(customLogEntry[0].c).to.be.equal('MONGOSH-SCRIPTS');
+            expect(customLogEntry[0].ctx).to.be.equal('custom-log');
+          });
+        });
+
+        it('writes custom log when loads a script', async function () {
+          const connectionString = await testServer.connectionString();
+          await shell.executeLine(
+            `connect(${JSON.stringify(connectionString)})`
+          );
+          const filename = path.resolve(
+            __dirname,
+            'fixtures',
+            'custom-log-info.js'
+          );
+          await shell.executeLine(`load(${JSON.stringify(filename)})`);
+          expect(shell.assertNoErrors());
+          await eventually(async () => {
+            const log = await readLogfile();
+            expect(
+              log.filter((logEntry) =>
+                logEntry.msg.includes('Initiating connection attemp')
+              )
+            ).to.have.lengthOf(1);
+            expect(
+              log.filter((logEntry) => logEntry.msg.includes('Hi there'))
+            ).to.have.lengthOf(1);
+          });
+        });
       });
 
       describe('history file', function () {
@@ -1931,7 +1971,7 @@ describe('e2e', function () {
         __dirname,
         '..',
         '..',
-        'cli-repl',
+        'e2e-tests',
         'test',
         'fixtures',
         'simple-console-log.js'

packages/e2e-tests/test/fixtures/custom-log-info.js

@@ -0,0 +1,2 @@
+// eslint-disable-next-line no-undef
+log.info('Hi there');

packages/cli-repl/test/fixtures/simple-console-log.js renamed to packages/e2e-tests/test/fixtures/simple-console-log.js

@@ -132,6 +132,35 @@ const translations: Catalog = {
   'service-provider-node-driver': {},
   'shell-api': {
     classes: {
+      ShellLog: {
+        help: {
+          description: 'Shell log methods',
+          link: '#',
+          attributes: {
+            // TODO(MONGOSH-1995): Print help for the global log property.
+            info: {
+              description: 'Writes a custom info message to the log file',
+              example: 'log.info("Custom info message")',
+            },
+            warn: {
+              description: 'Writes a custom warning message to the log file',
+              example: 'log.warn("Custom warning message")',
+            },
+            error: {
+              description: 'Writes a custom error message to the log file',
+              example: 'log.error("Custom error message")',
+            },
+            fatal: {
+              description: 'Writes a custom fatal message to the log file',
+              example: 'log.fatal("Custom fatal message")',
+            },
+            debug: {
+              description: 'Writes a custom debug message to the log file',
+              example: 'log.debug("Custom debug message")',
+            },
+          },
+        },
+      },
       ShellApi: {
         help: {
           description: 'Shell Help',

packages/i18n/src/locales/en_US.ts

@@ -822,4 +822,115 @@ describe('setupLoggerAndTelemetry', function () {
     expect(logOutput).to.have.lengthOf(0);
     expect(analyticsOutput).to.be.empty;
   });
+
+  it('tracks custom logging events', function () {
+    setupLoggerAndTelemetry(
+      bus,
+      logger,
+      analytics,
+      {
+        platform: process.platform,
+        arch: process.arch,
+      },
+      '1.0.0'
+    );
+    expect(logOutput).to.have.lengthOf(0);
+    expect(analyticsOutput).to.be.empty;
+
+    bus.emit('mongosh:connect', {
+      uri: 'mongodb://localhost/',
+      is_localhost: true,
+      is_atlas: false,
+      resolved_hostname: 'localhost',
+      node_version: 'v12.19.0',
+    });
+
+    bus.emit('mongosh:write-custom-log', {
+      method: 'info',
+      message: 'This is an info message',
+      attr: { some: 'value' },
+    });
+
+    bus.emit('mongosh:write-custom-log', {
+      method: 'warn',
+      message: 'This is a warn message',
+    });
+
+    bus.emit('mongosh:write-custom-log', {
+      method: 'error',
+      message: 'Error!',
+    });
+
+    bus.emit('mongosh:write-custom-log', {
+      method: 'fatal',
+      message: 'Fatal!',
+    });
+
+    bus.emit('mongosh:write-custom-log', {
+      method: 'debug',
+      message: 'Debug with level',
+      level: 1,
+    });
+
+    bus.emit('mongosh:write-custom-log', {
+      method: 'debug',
+      message: 'Debug without level',
+    });
+
+    expect(logOutput[0].msg).to.equal('Connecting to server');
+    expect(logOutput[0].attr.connectionUri).to.equal('mongodb://localhost/');
+    expect(logOutput[0].attr.is_localhost).to.equal(true);
+    expect(logOutput[0].attr.is_atlas).to.equal(false);
+    expect(logOutput[0].attr.atlas_hostname).to.equal(null);
+    expect(logOutput[0].attr.node_version).to.equal('v12.19.0');
+
+    expect(logOutput[1].s).to.equal('I');
+    expect(logOutput[1].c).to.equal('MONGOSH-SCRIPTS');
+    expect(logOutput[1].ctx).to.equal('custom-log');
+    expect(logOutput[1].msg).to.equal('This is an info message');
+    expect(logOutput[1].attr.some).to.equal('value');
+
+    expect(logOutput[2].s).to.equal('W');
+    expect(logOutput[2].c).to.equal('MONGOSH-SCRIPTS');
+    expect(logOutput[2].ctx).to.equal('custom-log');
+    expect(logOutput[2].msg).to.equal('This is a warn message');
+
+    expect(logOutput[3].s).to.equal('E');
+    expect(logOutput[3].c).to.equal('MONGOSH-SCRIPTS');
+    expect(logOutput[3].ctx).to.equal('custom-log');
+    expect(logOutput[3].msg).to.equal('Error!');
+
+    expect(logOutput[4].s).to.equal('F');
+    expect(logOutput[4].c).to.equal('MONGOSH-SCRIPTS');
+    expect(logOutput[4].ctx).to.equal('custom-log');
+    expect(logOutput[4].msg).to.equal('Fatal!');
+
+    expect(logOutput[5].s).to.equal('D1');
+    expect(logOutput[5].c).to.equal('MONGOSH-SCRIPTS');
+    expect(logOutput[5].ctx).to.equal('custom-log');
+    expect(logOutput[5].msg).to.equal('Debug with level');
+
+    expect(logOutput[6].s).to.equal('D1');
+    expect(logOutput[6].c).to.equal('MONGOSH-SCRIPTS');
+    expect(logOutput[6].ctx).to.equal('custom-log');
+    expect(logOutput[6].msg).to.equal('Debug without level');
+
+    expect(analyticsOutput).to.deep.equal([
+      [
+        'track',
+        {
+          anonymousId: undefined,
+          event: 'New Connection',
+          properties: {
+            mongosh_version: '1.0.0',
+            session_id: '5fb3c20ee1507e894e5340f3',
+            is_localhost: true,
+            is_atlas: false,
+            atlas_hostname: null,
+            node_version: 'v12.19.0',
+          },
+        },
+      ],
+    ]);
+  });
 });

packages/logging/src/setup-logger-and-telemetry.spec.ts

@@ -31,6 +31,7 @@ import type {
   FetchingUpdateMetadataEvent,
   FetchingUpdateMetadataCompleteEvent,
   SessionStartedEvent,
+  WriteCustomLogEvent,
 } from '@mongosh/types';
 import { inspect } from 'util';
 import type { MongoLogWriter } from 'mongodb-log-writer';
@@ -140,6 +141,17 @@ export function setupLoggerAndTelemetry(
     }
   );
 
+  bus.on('mongosh:write-custom-log', (event: WriteCustomLogEvent) => {
+    log[event.method](
+      'MONGOSH-SCRIPTS',
+      mongoLogId(1_000_000_054),
+      'custom-log',
+      event.message,
+      event.attr,
+      event.level
+    );
+  });
+
   bus.on('mongosh:connect', function (args: ConnectEvent) {
     const { uri, resolved_hostname, ...argsWithoutUriAndHostname } = args;
     const connectionUri = uri && redactURICredentials(uri);

packages/logging/src/setup-logger-and-telemetry.ts

@@ -35,6 +35,7 @@ import NoDatabase from './no-db';
 import type { ShellBson } from './shell-bson';
 import constructShellBson from './shell-bson';
 import { Streams } from './streams';
+import { ShellLog } from './shell-log';
 
 /**
  * The subset of CLI options that is relevant for the shell API's behavior itself.
@@ -159,6 +160,7 @@ export default class ShellInstanceState {
   public context: any;
   public mongos: Mongo[];
   public shellApi: ShellApi;
+  public shellLog: ShellLog;
   public shellBson: ShellBson;
   public cliOptions: ShellCliOptions;
   public evaluationListener: EvaluationListener;
@@ -187,6 +189,7 @@ export default class ShellInstanceState {
     this.initialServiceProvider = initialServiceProvider;
     this.messageBus = messageBus;
     this.shellApi = new ShellApi(this);
+    this.shellLog = new ShellLog(this);
     this.shellBson = constructShellBson(
       initialServiceProvider.bsonLibrary,
       (msg: string) => {
@@ -362,6 +365,8 @@ export default class ShellInstanceState {
       });
     }
 
+    contextObject.log = this.shellLog;
+
     this.messageBus.emit('mongosh:setCtx', { method: 'setCtx', arguments: {} });
   }
 

packages/shell-api/src/shell-instance-state.ts

@@ -0,0 +1,60 @@
+import type ShellInstanceState from './shell-instance-state';
+import { shellApiClassDefault, ShellApiClass } from './decorators';
+
+const instanceStateSymbol = Symbol.for('@@mongosh.instanceState');
+
+/**
+ * This class contains the *global log* property that is considered part of the immediate shell API.
+ */
+@shellApiClassDefault
+export class ShellLog extends ShellApiClass {
+  // Use symbols to make sure these are *not* among the things copied over into
+  // the global scope.
+  [instanceStateSymbol]: ShellInstanceState;
+
+  get _instanceState(): ShellInstanceState {
+    return this[instanceStateSymbol];
+  }
+
+  constructor(instanceState: ShellInstanceState) {
+    super();
+    this[instanceStateSymbol] = instanceState;
+  }
+
+  info(message: string, attr?: unknown) {
+    this[instanceStateSymbol].messageBus.emit('mongosh:write-custom-log', {
+      method: 'info',
+      message,
+      attr,
+    });
+  }
+  warn(message: string, attr?: unknown) {
+    this[instanceStateSymbol].messageBus.emit('mongosh:write-custom-log', {
+      method: 'warn',
+      message,
+      attr,
+    });
+  }
+  error(message: string, attr?: unknown) {
+    this[instanceStateSymbol].messageBus.emit('mongosh:write-custom-log', {
+      method: 'error',
+      message,
+      attr,
+    });
+  }
+  fatal(message: string, attr?: unknown) {
+    this[instanceStateSymbol].messageBus.emit('mongosh:write-custom-log', {
+      method: 'fatal',
+      message,
+      attr,
+    });
+  }
+  debug(message: string, attr?: unknown, level?: 1 | 2 | 3 | 4 | 5) {
+    this[instanceStateSymbol].messageBus.emit('mongosh:write-custom-log', {
+      method: 'debug',
+      message,
+      attr,
+      level,
+    });
+  }
+}

packages/shell-api/src/shell-log.ts

@@ -187,6 +187,13 @@ export interface SessionStartedEvent {
   };
 }
 
+export interface WriteCustomLogEvent {
+  method: 'info' | 'error' | 'warn' | 'fatal' | 'debug';
+  message: string;
+  attr?: unknown;
+  level?: 1 | 2 | 3 | 4 | 5;
+}
+
 export interface MongoshBusEventsMap extends ConnectEventMap {
   /**
    * Signals a connection to a MongoDB instance has been established
@@ -267,6 +274,11 @@ export interface MongoshBusEventsMap extends ConnectEventMap {
   'mongosh:start-loading-cli-scripts': (
     event: StartLoadingCliScriptsEvent
   ) => void;
+  /**
+   * Signals to start writing log to the disc after MongoLogManager is initialized.
+   */
+  'mongosh:write-custom-log': (ev: WriteCustomLogEvent) => void;
+
   /**
    * Signals the successful startup of the mongosh REPL after initial files and configuration
    * have been loaded.