feat(logging): custom log entries MONGOSH-1989

packages/cli-repl/test/fixtures/custom-log-info.js

@@ -0,0 +1 @@
+log.info('Hi there');

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

@@ -578,6 +578,11 @@ describe('e2e', function () {
       shell.assertNoErrors();
     });
 
+    it('runs a custom log command', async function () {
+      await shell.executeLine("log.info('Try me')");
+      shell.assertNoErrors();
+    });
+
     it('runs help command', async function () {
       expect(await shell.executeLine('help')).to.include('Shell Help');
       shell.assertNoErrors();
@@ -1506,6 +1511,45 @@ describe('e2e', function () {
             ).to.have.lengthOf(1);
           });
         });
+
+        it('writes custom log directly', async function () {
+          const connectionString = await testServer.connectionString();
+          await shell.executeLine(
+            `connect(${JSON.stringify(connectionString)})`
+          );
+          await shell.executeLine("log.info('This is a custom entry')");
+          await eventually(async () => {
+            const log = await readLogfile();
+            expect(
+              log.filter((logEntry) =>
+                logEntry.msg.includes('This is a custom entry')
+              )
+            ).to.have.lengthOf(1);
+          });
+        });
+
+        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,
+            '..',
+            '..',
+            'cli-repl',
+            'test',
+            'fixtures',
+            'custom-log-info.js'
+          );
+          await shell.executeLine(`load('${filename}')`);
+          await eventually(async () => {
+            const log = await readLogfile();
+            expect(
+              log.filter((logEntry) => logEntry.msg.includes('Hi there'))
+            ).to.have.lengthOf(1);
+          });
+        });
       });
 
       describe('history file', function () {

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

@@ -822,4 +822,105 @@ 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',
+      level: 1,
+    });
+
+    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');
+
+    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.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/shell-api/src/shell-instance-state.ts

@@ -362,7 +362,48 @@ export default class ShellInstanceState {
       });
     }
 
-    this.messageBus.emit('mongosh:setCtx', { method: 'setCtx', arguments: {} });
+    const bus = this.messageBus;
+    if (contextObject.log === undefined) {
+      contextObject.log = {
+        info(message: string, attr?: unknown) {
+          bus.emit('mongosh:write-custom-log', {
+            method: 'info',
+            message,
+            attr,
+          });
+        },
+        warn(message: string, attr?: unknown) {
+          bus.emit('mongosh:write-custom-log', {
+            method: 'warn',
+            message,
+            attr,
+          });
+        },
+        error(message: string, attr?: unknown) {
+          bus.emit('mongosh:write-custom-log', {
+            method: 'error',
+            message,
+            attr,
+          });
+        },
+        fatal(message: string, attr?: unknown) {
+          bus.emit('mongosh:write-custom-log', {
+            method: 'fatal',
+            message,
+            attr,
+          });
+        },
+        debug(message: string, attr?: unknown, level?: 1 | 2 | 3 | 4 | 5) {
+          bus.emit('mongosh:write-custom-log', {
+            method: 'debug',
+            message,
+            attr,
+            level,
+          });
+        },
+      };
+    }
+    bus.emit('mongosh:setCtx', { method: 'setCtx', arguments: {} });
   }
 
   get currentServiceProvider(): ServiceProvider {

packages/types/src/index.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.