diff --git a/package-lock.json b/package-lock.json index 1d8bda8c68..3d4bca0a8a 100644 --- a/package-lock.json +++ b/package-lock.json @@ -29398,6 +29398,7 @@ "lodash": "^4.17.21", "moment": "^2.29.1", "mongodb": "^6.12.0", + "mongodb-log-writer": "^2.1.0", "node-fetch": "^3.3.2", "prettier": "^2.8.8", "rimraf": "^3.0.2" @@ -29436,6 +29437,8 @@ }, "packages/e2e-tests/node_modules/data-uri-to-buffer": { "version": "4.0.1", + "resolved": "https://registry.npmjs.org/data-uri-to-buffer/-/data-uri-to-buffer-4.0.1.tgz", + "integrity": "sha512-0R9ikRb668HB7QDxT1vkpuUBtqc53YyAwMwGeUFKRojY/NWKvdZ+9UYtRfGmhqNbRkTSVpMbmyhXipFFv2cb/A==", "dev": true, "license": "MIT", "engines": { @@ -29444,6 +29447,8 @@ }, "packages/e2e-tests/node_modules/node-fetch": { "version": "3.3.2", + "resolved": "https://registry.npmjs.org/node-fetch/-/node-fetch-3.3.2.tgz", + "integrity": "sha512-dRB78srN/l6gqWulah9SrxeYnxeddIG30+GOqK/9OlLVyLg3HPnr6SqOWTWOXKRwC2eGYCkZ59NNuSgvSrpgOA==", "dev": true, "license": "MIT", "dependencies": { diff --git a/packages/cli-repl/src/cli-repl.spec.ts b/packages/cli-repl/src/cli-repl.spec.ts index 3f915bfbd6..43ba0b6c0f 100644 --- a/packages/cli-repl/src/cli-repl.spec.ts +++ b/packages/cli-repl/src/cli-repl.spec.ts @@ -18,7 +18,7 @@ import { import { expect, fakeTTYProps, - readReplLogfile, + readReplLogFile, tick, useTmpdir, waitBus, @@ -31,6 +31,9 @@ import { CliRepl } from './cli-repl'; import { CliReplErrors } from './error-codes'; import type { DevtoolsConnectOptions } from '@mongosh/service-provider-node-driver'; import type { AddressInfo } from 'net'; +import sinon from 'sinon'; +import type { CliUserConfig } from '@mongosh/types'; +import { MongoLogWriter, MongoLogManager } from 'mongodb-log-writer'; const { EJSON } = bson; const delay = promisify(setTimeout); @@ -53,7 +56,7 @@ describe('CliRepl', function () { async function log(): Promise { if (!cliRepl.logWriter?.logFilePath) return []; await cliRepl.logWriter.flush(); // Ensure any pending data is written first - return readReplLogfile(cliRepl.logWriter.logFilePath); + return readReplLogFile(cliRepl.logWriter.logFilePath); } async function startWithExpectedImmediateExit( @@ -235,6 +238,27 @@ describe('CliRepl', function () { }); }); + it('does not write to log syntax errors if logging is disabled', async function () { + expect( + (await log()).filter((entry) => + entry.attr?.stack?.startsWith('SyntaxError:') + ) + ).to.have.lengthOf(0); + input.write('config.set("disableLogging", true)\n'); + await waitEval(cliRepl.bus); + expect(output).includes('Setting "disableLogging" has been changed'); + + input.write('\n'); + await waitBus(cliRepl.bus, 'mongosh:error'); + await eventually(async () => { + expect( + (await log()).filter((entry) => + entry.attr?.stack?.startsWith('SyntaxError:') + ) + ).to.have.lengthOf(0); + }); + }); + it('writes JS errors to the log file', async function () { input.write('throw new Error("plain js error")\n'); await waitBus(cliRepl.bus, 'mongosh:error'); @@ -297,7 +321,8 @@ describe('CliRepl', function () { 'oidcTrustedEndpoints', 'browser', 'updateURL', - ]); + 'disableLogging', + ] satisfies (keyof CliUserConfig)[]); }); it('fails when trying to overwrite mongosh-owned config settings', async function () { @@ -453,12 +478,14 @@ describe('CliRepl', function () { cliRepl = new CliRepl(cliReplOptions); await cliRepl.start('', {}); await fs.stat(newerlogfile); - try { - await fs.stat(oldlogfile); - expect.fail('missed exception'); - } catch (err: any) { - expect(err.code).to.equal('ENOENT'); - } + await eventually(async () => { + try { + await fs.stat(oldlogfile); + expect.fail('missed exception'); + } catch (err: any) { + expect(err.code).to.equal('ENOENT'); + } + }); }); it('verifies the Node.js version', async function () { @@ -1309,7 +1336,6 @@ describe('CliRepl', function () { hasCollectionNames: true, hasDatabaseNames: true, }); - context('analytics integration', function () { context('with network connectivity', function () { let srv: http.Server; @@ -1333,6 +1359,7 @@ describe('CliRepl', function () { .on('data', (chunk) => { body += chunk; }) + // eslint-disable-next-line @typescript-eslint/no-misused-promises .on('end', async () => { requests.push({ req, body }); totalEventsTracked += JSON.parse(body).batch.length; @@ -1343,7 +1370,7 @@ describe('CliRepl', function () { }) .listen(0); await once(srv, 'listening'); - host = `http://localhost:${(srv.address() as any).port}`; + host = `http://localhost:${(srv.address() as AddressInfo).port}`; cliReplOptions.analyticsOptions = { host, apiKey: '🔑', @@ -1357,6 +1384,48 @@ describe('CliRepl', function () { srv.close(); await once(srv, 'close'); setTelemetryDelay(0); + sinon.restore(); + }); + + context('logging configuration', function () { + it('logging is enabled by default and event is called', async function () { + const onLogInitialized = sinon.stub(); + cliRepl.bus.on('mongosh:log-initialized', onLogInitialized); + + await cliRepl.start(await testServer.connectionString(), {}); + + expect(await cliRepl.getConfig('disableLogging')).is.false; + + expect(onLogInitialized).calledOnce; + expect(cliRepl.logWriter).is.instanceOf(MongoLogWriter); + }); + + it('does not initialize logging when it is disabled', async function () { + cliRepl.config.disableLogging = true; + const onLogInitialized = sinon.stub(); + cliRepl.bus.on('mongosh:log-initialized', onLogInitialized); + + await cliRepl.start(await testServer.connectionString(), {}); + + expect(await cliRepl.getConfig('disableLogging')).is.true; + expect(onLogInitialized).not.called; + + expect(cliRepl.logWriter).is.undefined; + }); + + it('logs cleanup errors', async function () { + sinon + .stub(MongoLogManager.prototype, 'cleanupOldLogFiles') + .rejects(new Error('Method not implemented')); + await cliRepl.start(await testServer.connectionString(), {}); + expect( + (await log()).filter( + (entry) => + entry.ctx === 'log' && + entry.msg === 'Error: Method not implemented' + ) + ).to.have.lengthOf(1); + }); }); it('times out fast', async function () { @@ -1507,11 +1576,11 @@ describe('CliRepl', function () { it('includes a statement about flushed telemetry in the log', async function () { await cliRepl.start(await testServer.connectionString(), {}); - const { logFilePath } = cliRepl.logWriter!; + const { logFilePath } = cliRepl.logWriter as MongoLogWriter; input.write('db.hello()\n'); input.write('exit\n'); await waitBus(cliRepl.bus, 'mongosh:closed'); - const flushEntry = (await readReplLogfile(logFilePath)).find( + const flushEntry = (await readReplLogFile(logFilePath)).find( (entry: any) => entry.id === 1_000_000_045 ); expect(flushEntry.attr.flushError).to.equal(null); diff --git a/packages/cli-repl/src/cli-repl.ts b/packages/cli-repl/src/cli-repl.ts index d3dd3d2e5c..11c4076d67 100644 --- a/packages/cli-repl/src/cli-repl.ts +++ b/packages/cli-repl/src/cli-repl.ts @@ -30,8 +30,9 @@ import type { MongoLogWriter } from 'mongodb-log-writer'; import { MongoLogManager, mongoLogId } from 'mongodb-log-writer'; import type { MongoshNodeReplOptions, MongoshIOProvider } from './mongosh-repl'; import MongoshNodeRepl from './mongosh-repl'; +import type { MongoshLoggingAndTelemetry } from '@mongosh/logging'; +import { setupLoggingAndTelemetry } from '@mongosh/logging'; import { - setupLoggerAndTelemetry, ToggleableAnalytics, ThrottledAnalytics, SampledAnalytics, @@ -119,7 +120,7 @@ export class CliRepl implements MongoshIOProvider { config: CliUserConfigOnDisk; globalConfig: Partial | null = null; globalConfigPaths: string[]; - logManager: MongoLogManager; + logManager?: MongoLogManager; logWriter?: MongoLogWriter; input: Readable; output: Writable; @@ -140,6 +141,8 @@ export class CliRepl implements MongoshIOProvider { fetchMongoshUpdateUrlRegardlessOfCiEnvironment = false; // for testing cachedGlibcVersion: null | string | undefined = null; + private loggingAndTelemetry: MongoshLoggingAndTelemetry | undefined; + /** * Instantiate the new CLI Repl. */ @@ -189,16 +192,6 @@ export class CliRepl implements MongoshIOProvider { }); }); - this.logManager = new MongoLogManager({ - directory: this.shellHomeDirectory.localPath('.'), - retentionDays: 30, - maxLogFileCount: +( - process.env.MONGOSH_TEST_ONLY_MAX_LOG_FILE_COUNT || 100 - ), - onerror: (err: Error) => this.bus.emit('mongosh:error', err, 'log'), - onwarn: (err: Error, path: string) => - this.warnAboutInaccessibleFile(err, path), - }); this.agent = useOrCreateAgent(this.proxyOptions); this.updateNotificationManager = new UpdateNotificationManager({ proxyOptions: this.agent, @@ -256,6 +249,60 @@ export class CliRepl implements MongoshIOProvider { ); } + /** Setup log writer and start logging. */ + private async startLogging(): Promise { + if (!this.loggingAndTelemetry) { + throw new Error('Logging and telemetry not setup'); + } + + this.logManager ??= new MongoLogManager({ + directory: this.shellHomeDirectory.localPath('.'), + retentionDays: 30, + maxLogFileCount: +( + process.env.MONGOSH_TEST_ONLY_MAX_LOG_FILE_COUNT || 100 + ), + onerror: (err: Error) => this.bus.emit('mongosh:error', err, 'log'), + onwarn: (err: Error, path: string) => + this.warnAboutInaccessibleFile(err, path), + }); + + // Do not wait for log cleanup and log errors if MongoLogManager throws any. + void this.logManager + .cleanupOldLogFiles() + .catch((err) => { + this.bus.emit('mongosh:error', err, 'log'); + }) + .finally(() => { + markTime(TimingCategories.Logging, 'cleaned up log files'); + }); + + if (!this.logWriter) { + this.logWriter ??= await this.logManager.createLogWriter(); + + const { quiet } = CliRepl.getFileAndEvalInfo(this.cliOptions); + if (!quiet) { + this.output.write(`Current Mongosh Log ID:\t${this.logWriter.logId}\n`); + } + + markTime(TimingCategories.Logging, 'instantiated log writer'); + } + + this.loggingAndTelemetry.attachLogger(this.logWriter); + + this.logWriter.info( + 'MONGOSH', + mongoLogId(1_000_000_000), + 'log', + 'Starting log', + { + execPath: process.execPath, + envInfo: redactSensitiveData(this.getLoggedEnvironmentVariables()), + ...(await buildInfo()), + } + ); + markTime(TimingCategories.Logging, 'logged initial message'); + } + /** * Setup CLI environment: serviceProvider, ShellEvaluator, log connection * information, external editor, and finally start the repl. @@ -267,7 +314,8 @@ export class CliRepl implements MongoshIOProvider { driverUri: string, driverOptions: DevtoolsConnectOptions ): Promise { - const { version } = require('../package.json'); + // eslint-disable-next-line @typescript-eslint/no-var-requires + const { version }: { version: string } = require('../package.json'); await this.verifyNodeVersion(); markTime(TimingCategories.REPLInstantiation, 'verified node version'); @@ -302,67 +350,54 @@ export class CliRepl implements MongoshIOProvider { try { await this.shellHomeDirectory.ensureExists(); - } catch (err: any) { - this.warnAboutInaccessibleFile(err); + } catch (err: unknown) { + this.warnAboutInaccessibleFile(err as Error); } markTime(TimingCategories.REPLInstantiation, 'ensured shell homedir'); - await this.logManager.cleanupOldLogFiles(); - markTime(TimingCategories.Logging, 'cleaned up log files'); - const logger = await this.logManager.createLogWriter(); - const { quiet } = CliRepl.getFileAndEvalInfo(this.cliOptions); - if (!quiet) { - this.output.write(`Current Mongosh Log ID:\t${logger.logId}\n`); - } - this.logWriter = logger; - markTime(TimingCategories.Logging, 'instantiated log writer'); - - logger.info('MONGOSH', mongoLogId(1_000_000_000), 'log', 'Starting log', { - execPath: process.execPath, - envInfo: redactSensitiveData(this.getLoggedEnvironmentVariables()), - ...(await buildInfo()), - }); - markTime(TimingCategories.Logging, 'logged initial message'); - let analyticsSetupError: Error | null = null; try { await this.setupAnalytics(); - } catch (err: any) { + } catch (err: unknown) { // Need to delay emitting the error on the bus so that logging is in place // as well - analyticsSetupError = err; + analyticsSetupError = err as Error; } markTime(TimingCategories.Telemetry, 'created analytics instance'); - setupLoggerAndTelemetry( - this.bus, - logger, - this.toggleableAnalytics, - { + + this.loggingAndTelemetry = setupLoggingAndTelemetry({ + bus: this.bus, + analytics: this.toggleableAnalytics, + userTraits: { platform: process.platform, arch: process.arch, is_containerized: this.isContainerizedEnvironment, ...(await getOsInfo()), }, - version - ); + mongoshVersion: version, + }); + markTime(TimingCategories.Telemetry, 'completed telemetry setup'); if (analyticsSetupError) { this.bus.emit('mongosh:error', analyticsSetupError, 'analytics'); } + // Read local and global configuration try { this.config = await this.configDirectory.generateOrReadConfig( this.config ); - } catch (err: any) { - this.warnAboutInaccessibleFile(err); + } catch (err: unknown) { + this.warnAboutInaccessibleFile(err as Error); } this.globalConfig = await this.loadGlobalConfigFile(); markTime(TimingCategories.UserConfigLoading, 'read global config files'); + await this.setLoggingEnabled(!(await this.getConfig('disableLogging'))); + // Needs to happen after loading the mongosh config file(s) void this.fetchMongoshUpdateUrl(); @@ -520,6 +555,7 @@ export class CliRepl implements MongoshIOProvider { this.bus.emit('mongosh:start-mongosh-repl', { version }); markTime(TimingCategories.REPLInstantiation, 'starting repl'); await this.mongoshRepl.startRepl(initialized); + this.bus.emit('mongosh:start-session', { isInteractive: true, jsContext: this.mongoshRepl.jsContext(), @@ -605,6 +641,14 @@ export class CliRepl implements MongoshIOProvider { ); } + async setLoggingEnabled(enabled: boolean): Promise { + if (enabled) { + await this.startLogging(); + } else { + this.loggingAndTelemetry?.detachLogger(); + } + } + setTelemetryEnabled(enabled: boolean): void { if (this.globalConfig === null) { // This happens when the per-user config file is loaded before we have @@ -624,7 +668,7 @@ export class CliRepl implements MongoshIOProvider { files: string[], evalScripts: string[] ): Promise { - let lastEvalResult: any; + let lastEvalResult: unknown; let exitCode = 0; try { markTime(TimingCategories.Eval, 'start eval scripts'); @@ -891,6 +935,9 @@ export class CliRepl implements MongoshIOProvider { anonymousId: this.config.telemetryAnonymousId, }); } + if (key === 'disableLogging') { + await this.setLoggingEnabled(!value); + } try { await this.configDirectory.writeConfigFile(this.config); } catch (err: any) { @@ -1284,7 +1331,8 @@ export class CliRepl implements MongoshIOProvider { } async getMoreRecentMongoshVersion(): Promise { - const { version } = require('../package.json'); + // eslint-disable-next-line @typescript-eslint/no-var-requires + const { version }: { version: string } = require('../package.json'); return await this.updateNotificationManager.getLatestVersionIfMoreRecent( process.env .MONGOSH_ASSUME_DIFFERENT_VERSION_FOR_UPDATE_NOTIFICATION_TEST || diff --git a/packages/cli-repl/test/repl-helpers.ts b/packages/cli-repl/test/repl-helpers.ts index 332b8a1769..87bedb63ec 100644 --- a/packages/cli-repl/test/repl-helpers.ts +++ b/packages/cli-repl/test/repl-helpers.ts @@ -87,7 +87,7 @@ const fakeTTYProps: Partial = { }, }; -async function readReplLogfile( +async function readReplLogFile( logPath?: string | null | undefined ): Promise { if (!logPath) return []; @@ -107,5 +107,5 @@ export { waitEval, waitCompletion, fakeTTYProps, - readReplLogfile, + readReplLogFile, }; diff --git a/packages/e2e-tests/package.json b/packages/e2e-tests/package.json index 8677e5bf75..35ae98d88c 100644 --- a/packages/e2e-tests/package.json +++ b/packages/e2e-tests/package.json @@ -33,6 +33,7 @@ "strip-ansi": "^6.0.0" }, "devDependencies": { + "mongodb-log-writer": "^2.1.0", "@mongodb-js/eslint-config-mongosh": "^1.0.0", "@mongodb-js/oidc-mock-provider": "^0.10.2", "@mongodb-js/prettier-config-devtools": "^1.0.1", diff --git a/packages/e2e-tests/test/e2e-tls.spec.ts b/packages/e2e-tests/test/e2e-tls.spec.ts index 9d9c53a6e8..da68f80cc0 100644 --- a/packages/e2e-tests/test/e2e-tls.spec.ts +++ b/packages/e2e-tests/test/e2e-tls.spec.ts @@ -5,7 +5,7 @@ import { startTestServer } from '../../../testing/integration-testing-hooks'; import { useTmpdir, setTemporaryHomeDirectory, - readReplLogfile, + readReplLogFile, getCertPath, connectionStringWithLocalhost, } from './repl-helpers'; @@ -241,13 +241,13 @@ describe('e2e TLS', function () { expect(prompt.state).to.equal('prompt'); const logPath = path.join(logBasePath, `${shell.logId}_log`); - const logContents = await readReplLogfile(logPath); + const logContents = await readReplLogFile(logPath); expect( - logContents.find((line) => line.id === 1_000_000_049).attr + logContents.find((line) => line.id === 1_000_000_049)?.attr .asyncFallbackError ).to.equal(null); // Ensure that system CA loading happened asynchronously. expect( - logContents.find((line) => line.id === 1_000_000_049).attr + logContents.find((line) => line.id === 1_000_000_049)?.attr .systemCertsError ).to.equal(null); // Ensure that system CA could be loaded successfully. }); @@ -278,13 +278,13 @@ describe('e2e TLS', function () { expect(prompt.state).to.equal('prompt'); const logPath = path.join(logBasePath, `${shell.logId}_log`); - const logContents = await readReplLogfile(logPath); + const logContents = await readReplLogFile(logPath); expect( - logContents.find((line) => line.id === 1_000_000_049).attr + logContents.find((line) => line.id === 1_000_000_049)?.attr .asyncFallbackError ).to.equal(null); // Ensure that system CA loading happened asynchronously. expect( - logContents.find((line) => line.id === 1_000_000_049).attr + logContents.find((line) => line.id === 1_000_000_049)?.attr .systemCertsError ).to.equal(null); // Ensure that system CA could be loaded successfully. }); @@ -308,7 +308,7 @@ describe('e2e TLS', function () { expect(prompt.state).to.equal('exit'); const logPath = path.join(logBasePath, `${shell.logId}_log`); - const logContents = await readReplLogfile(logPath); + const logContents = await readReplLogFile(logPath); expect(logContents.find((line) => line.id === 1_000_000_049)).to.exist; }); } diff --git a/packages/e2e-tests/test/e2e.spec.ts b/packages/e2e-tests/test/e2e.spec.ts index 4444a08cb1..8fd076cfb8 100644 --- a/packages/e2e-tests/test/e2e.spec.ts +++ b/packages/e2e-tests/test/e2e.spec.ts @@ -14,7 +14,8 @@ import { promises as fs, createReadStream } from 'fs'; import { promisify } from 'util'; import path from 'path'; import os from 'os'; -import { readReplLogfile, setTemporaryHomeDirectory } from './repl-helpers'; +import type { MongoLogEntryFromFile } from './repl-helpers'; +import { readReplLogFile, setTemporaryHomeDirectory } from './repl-helpers'; import { bson } from '@mongosh/service-provider-core'; import type { Server as HTTPServer } from 'http'; import { createServer as createHTTPServer } from 'http'; @@ -1353,10 +1354,9 @@ describe('e2e', function () { let shell: TestShell; let configPath: string; let logBasePath: string; - let logPath: string; let historyPath: string; let readConfig: () => Promise; - let readLogfile: () => Promise; + let readLogFile: () => Promise; let startTestShell: (...extraArgs: string[]) => Promise; beforeEach(function () { @@ -1393,7 +1393,13 @@ describe('e2e', function () { } readConfig = async () => EJSON.parse(await fs.readFile(configPath, 'utf8')); - readLogfile = async () => readReplLogfile(logPath); + readLogFile = async (): Promise => { + if (!shell.logId) { + throw new Error('Shell does not have a logId associated with it'); + } + const logPath = path.join(logBasePath, `${shell.logId}_log`); + return readReplLogFile(logPath); + }; startTestShell = async (...extraArgs: string[]) => { const shell = this.startTestShell({ args: ['--nodb', ...extraArgs], @@ -1424,7 +1430,6 @@ describe('e2e', function () { beforeEach(async function () { await fs.mkdir(homedir, { recursive: true }); shell = await startTestShell(); - logPath = path.join(logBasePath, `${shell.logId}_log`); }); describe('config file', function () { @@ -1503,14 +1508,141 @@ describe('e2e', function () { }); describe('log file', function () { - it('creates a log file that keeps track of session events', async function () { + it('does not get created if global config has disableLogging', async function () { + const globalConfig = path.join(homedir, 'globalconfig.conf'); + await fs.writeFile(globalConfig, 'mongosh:\n disableLogging: true'); + shell = this.startTestShell({ + args: ['--nodb'], + env: { + ...env, + MONGOSH_GLOBAL_CONFIG_FILE_FOR_TESTING: globalConfig, + }, + forceTerminal: true, + }); + await shell.waitForPrompt(); + expect( + await shell.executeLine('config.get("disableLogging")') + ).to.include('true'); + shell.assertNoErrors(); + expect(await shell.executeLine('print(123 + 456)')).to.include('579'); - await eventually(async () => { - const log = await readLogfile(); - expect( - log.filter((logEntry) => /Evaluating input/.test(logEntry.msg)) - ).to.have.lengthOf(1); + expect(shell.logId).equals(null); + }); + + it('gets created if global config has disableLogging set to false', async function () { + const globalConfig = path.join(homedir, 'globalconfig.conf'); + await fs.writeFile(globalConfig, 'mongosh:\n disableLogging: false'); + shell = this.startTestShell({ + args: ['--nodb'], + env: { + ...env, + MONGOSH_GLOBAL_CONFIG_FILE_FOR_TESTING: globalConfig, + }, + forceTerminal: true, }); + await shell.waitForPrompt(); + expect( + await shell.executeLine('config.get("disableLogging")') + ).to.include('false'); + shell.assertNoErrors(); + + expect(await shell.executeLine('print(123 + 456)')).to.include('579'); + expect(shell.logId).not.equal(null); + + const log = await readLogFile(); + expect( + log.filter( + (logEntry) => logEntry.attr?.input === 'print(123 + 456)' + ) + ).to.have.lengthOf(1); + }); + + it('creates a log file that keeps track of session events', async function () { + expect(await shell.executeLine('print(123 + 456)')).to.include('579'); + const log = await readLogFile(); + expect( + log.filter( + (logEntry) => logEntry.attr?.input === 'print(123 + 456)' + ) + ).to.have.lengthOf(1); + }); + + it('does not write to the log after disableLogging is set to true', async function () { + expect(await shell.executeLine('print(123 + 456)')).to.include('579'); + const log = await readLogFile(); + expect( + log.filter( + (logEntry) => logEntry.attr?.input === 'print(123 + 456)' + ) + ).to.have.lengthOf(1); + + await shell.executeLine(`config.set("disableLogging", true)`); + expect(await shell.executeLine('print(579 - 123)')).to.include('456'); + + const logAfterDisabling = await readLogFile(); + expect( + logAfterDisabling.filter( + (logEntry) => logEntry.attr?.input === 'print(579 - 123)' + ) + ).to.have.lengthOf(0); + expect( + logAfterDisabling.filter( + (logEntry) => logEntry.attr?.input === 'print(123 + 456)' + ) + ).to.have.lengthOf(1); + }); + + it('starts writing to the same log from the point where disableLogging is set to false', async function () { + expect(await shell.executeLine('print(111 + 222)')).to.include('333'); + + let log = await readLogFile(); + expect( + log.filter( + (logEntry) => logEntry.attr?.input === 'print(111 + 222)' + ) + ).to.have.lengthOf(1); + + await shell.executeLine(`config.set("disableLogging", true)`); + expect(await shell.executeLine('print(123 + 456)')).to.include('579'); + + log = await readLogFile(); + const oldLogId = shell.logId; + expect(oldLogId).not.null; + + expect( + log.filter( + (logEntry) => logEntry.attr?.input === 'print(123 + 456)' + ) + ).to.have.lengthOf(0); + + await shell.executeLine(`config.set("disableLogging", false)`); + + expect( + await shell.executeLine('config.get("disableLogging")') + ).to.include('false'); + + expect(await shell.executeLine('print(579 - 123)')).to.include('456'); + + const newLogId = shell.logId; + expect(newLogId).not.null; + expect(oldLogId).equals(newLogId); + log = await readLogFile(); + + expect( + log.filter( + (logEntry) => logEntry.attr?.input === 'print(111 + 222)' + ) + ).to.have.lengthOf(1); + expect( + log.filter( + (logEntry) => logEntry.attr?.input === 'print(579 - 123)' + ) + ).to.have.lengthOf(1); + expect( + log.filter( + (logEntry) => logEntry.attr?.input === 'print(123 + 456)' + ) + ).to.have.lengthOf(0); }); it('includes information about the driver version', async function () { @@ -1521,7 +1653,7 @@ describe('e2e', function () { ) ).to.include('test'); await eventually(async () => { - const log = await readLogfile(); + const log = await readLogFile(); expect( log.filter( (logEntry) => typeof logEntry.attr?.driver?.version === 'string' @@ -1534,7 +1666,12 @@ describe('e2e', function () { await shell.executeLine("log.info('This is a custom entry')"); expect(shell.assertNoErrors()); await eventually(async () => { - const log = await readLogfile(); + const log = await readLogFile< + MongoLogEntryFromFile & { + c: string; + ctx: string; + } + >(); const customLogEntry = log.filter((logEntry) => logEntry.msg.includes('This is a custom entry') ); @@ -1558,7 +1695,7 @@ describe('e2e', function () { await shell.executeLine(`load(${JSON.stringify(filename)})`); expect(shell.assertNoErrors()); await eventually(async () => { - const log = await readLogfile(); + const log = await readLogFile(); expect( log.filter((logEntry) => logEntry.msg.includes('Initiating connection attemp') diff --git a/packages/e2e-tests/test/repl-helpers.ts b/packages/e2e-tests/test/repl-helpers.ts index fbcd274c03..46c67371d7 100644 --- a/packages/e2e-tests/test/repl-helpers.ts +++ b/packages/e2e-tests/test/repl-helpers.ts @@ -6,6 +6,7 @@ import chai from 'chai'; import sinonChai from 'sinon-chai'; import chaiAsPromised from 'chai-as-promised'; import type { MongodSetup } from '../../../testing/integration-testing-hooks'; +import type { MongoLogEntry } from 'mongodb-log-writer'; chai.use(sinonChai); chai.use(chaiAsPromised); @@ -47,7 +48,16 @@ function useTmpdir(): { readonly path: string } { }; } -async function readReplLogfile(logPath: string) { +type MongoLogEntryFromFile = { + t?: { + $date: string; + }; + id: number; +} & Omit; + +async function readReplLogFile( + logPath: string +): Promise { return (await fs.readFile(logPath, 'utf8')) .split('\n') .filter((line) => line.trim()) @@ -161,9 +171,10 @@ async function connectionStringWithLocalhost( // eslint-disable-next-line mocha/no-exports export { useTmpdir, - readReplLogfile, + readReplLogFile, fakeExternalEditor, setTemporaryHomeDirectory, getCertPath, connectionStringWithLocalhost, + MongoLogEntryFromFile, }; diff --git a/packages/logging/src/analytics-helpers.ts b/packages/logging/src/analytics-helpers.ts index 4bdecf5a36..b1f9229368 100644 --- a/packages/logging/src/analytics-helpers.ts +++ b/packages/logging/src/analytics-helpers.ts @@ -11,7 +11,7 @@ export type MongoshAnalyticsIdentity = anonymousId: string; }; -type AnalyticsIdentifyMessage = MongoshAnalyticsIdentity & { +export type AnalyticsIdentifyMessage = MongoshAnalyticsIdentity & { traits: { platform: string; session_id: string }; timestamp?: Date; }; diff --git a/packages/logging/src/helpers.spec.ts b/packages/logging/src/helpers.spec.ts new file mode 100644 index 0000000000..cb41c1f9a3 --- /dev/null +++ b/packages/logging/src/helpers.spec.ts @@ -0,0 +1,26 @@ +import { expect } from 'chai'; +import { toSnakeCase } from './helpers'; + +describe('logging helpers', function () { + describe('toSnakeCase', function () { + const useCases = [ + { input: 'MongoDB REPL', output: 'mongo_db_repl' }, + { + input: 'Node.js REPL Instantiation', + output: 'node_js_repl_instantiation', + }, + { input: 'A', output: 'a' }, + { + input: 'OneLongThingInPascalCase', + output: 'one_long_thing_in_pascal_case', + }, + { input: 'Removes .Dots in Node.js', output: 'removes_dots_in_node_js' }, + ]; + + for (const { input, output } of useCases) { + it(`should convert ${input} to ${output}`, function () { + expect(toSnakeCase(input)).to.equal(output); + }); + } + }); +}); diff --git a/packages/logging/src/helpers.ts b/packages/logging/src/helpers.ts new file mode 100644 index 0000000000..86e195f416 --- /dev/null +++ b/packages/logging/src/helpers.ts @@ -0,0 +1,49 @@ +/** + * A helper class for keeping track of how often specific events occurred. + */ +export class MultiSet> { + _entries: Map = new Map(); + + add(entry: T): void { + const key = JSON.stringify(Object.entries(entry).sort()); + this._entries.set(key, (this._entries.get(key) ?? 0) + 1); + } + + clear(): void { + this._entries.clear(); + } + + *[Symbol.iterator](): Iterator<[T, number]> { + for (const [key, count] of this._entries) { + // eslint-disable-next-line @typescript-eslint/no-unsafe-argument + yield [Object.fromEntries(JSON.parse(key)) as T, count]; + } + } +} + +/** + * It transforms a random string into snake case. Snake case is completely + * lowercase and uses '_' to separate words. For example: + * + * This function defines a "word" as a sequence of characters until the next `.` or capital letter. + * + * 'Random String' => 'random_string' + * + * It will also remove any non alphanumeric characters to ensure the string + * is compatible with Segment. For example: + * + * 'Node.js REPL Instantiation' => 'node_js_repl_instantiation' + * + * @param str Any non snake-case formatted string + * @returns The snake-case formatted string + */ +export function toSnakeCase(str: string): string { + const matches = str.match( + /[A-Z]{2,}(?=[A-Z][a-z]+[0-9]*|\b)|[A-Z]?[a-z]+[0-9]*|[A-Z]|[0-9]+/g + ); + if (!matches) { + return str; + } + + return matches.map((x) => x.toLowerCase()).join('_'); +} diff --git a/packages/logging/src/index.ts b/packages/logging/src/index.ts index 263682d08f..1c6ecba793 100644 --- a/packages/logging/src/index.ts +++ b/packages/logging/src/index.ts @@ -1,4 +1,3 @@ -export { setupLoggerAndTelemetry } from './setup-logger-and-telemetry'; export { MongoshAnalytics, ToggleableAnalytics, @@ -6,3 +5,5 @@ export { NoopAnalytics, ThrottledAnalytics, } from './analytics-helpers'; +export { MongoshLoggingAndTelemetry } from './types'; +export { setupLoggingAndTelemetry } from './logging-and-telemetry'; diff --git a/packages/logging/src/setup-logger-and-telemetry.spec.ts b/packages/logging/src/logging-and-telemetry.spec.ts similarity index 82% rename from packages/logging/src/setup-logger-and-telemetry.spec.ts rename to packages/logging/src/logging-and-telemetry.spec.ts index e0d0515766..bfcfd8af78 100644 --- a/packages/logging/src/setup-logger-and-telemetry.spec.ts +++ b/packages/logging/src/logging-and-telemetry.spec.ts @@ -1,35 +1,14 @@ /* eslint-disable mocha/max-top-level-suites */ import { expect } from 'chai'; import { MongoLogWriter } from 'mongodb-log-writer'; -import { setupLoggerAndTelemetry } from './'; import { EventEmitter } from 'events'; import { MongoshInvalidInputError } from '@mongosh/errors'; import type { MongoshBus } from '@mongosh/types'; -import { toSnakeCase } from './setup-logger-and-telemetry'; - -describe('toSnakeCase', function () { - const useCases = [ - { input: 'MongoDB REPL', output: 'mongo_db_repl' }, - { - input: 'Node.js REPL Instantiation', - output: 'node_js_repl_instantiation', - }, - { input: 'A', output: 'a' }, - { - input: 'OneLongThingInPascalCase', - output: 'one_long_thing_in_pascal_case', - }, - { input: 'Removes .Dots in Node.js', output: 'removes_dots_in_node_js' }, - ]; - - for (const { input, output } of useCases) { - it(`should convert ${input} to ${output}`, function () { - expect(toSnakeCase(input)).to.equal(output); - }); - } -}); +import type { Writable } from 'stream'; +import type { MongoshLoggingAndTelemetry } from '.'; +import { setupLoggingAndTelemetry } from '.'; -describe('setupLoggerAndTelemetry', function () { +describe('MongoshLoggingAndTelemetry', function () { let logOutput: any[]; let analyticsOutput: ['identify' | 'track' | 'log', any][]; let bus: MongoshBus; @@ -37,15 +16,8 @@ describe('setupLoggerAndTelemetry', function () { const userId = '53defe995fa47e6c13102d9d'; const logId = '5fb3c20ee1507e894e5340f3'; - const logger = new MongoLogWriter(logId, `/tmp/${logId}_log`, { - write(chunk: string, cb: () => void) { - logOutput.push(JSON.parse(chunk)); - cb(); - }, - end(cb: () => void) { - cb(); - }, - } as any); + let logger: MongoLogWriter; + const analytics = { identify(info: any) { analyticsOutput.push(['identify', info]); @@ -58,26 +30,61 @@ describe('setupLoggerAndTelemetry', function () { }, }; + let loggingAndTelemetry: MongoshLoggingAndTelemetry; + beforeEach(function () { logOutput = []; analyticsOutput = []; bus = new EventEmitter(); - }); - it('tracks new local connection events', function () { - setupLoggerAndTelemetry( + loggingAndTelemetry = setupLoggingAndTelemetry({ bus, - logger, analytics, - { + userTraits: { platform: process.platform, arch: process.arch, }, - '1.0.0' + mongoshVersion: '1.0.0', + }); + + logger = new MongoLogWriter(logId, `/tmp/${logId}_log`, { + write(chunk: string, cb: () => void) { + logOutput.push(JSON.parse(chunk)); + cb(); + }, + end(cb: () => void) { + cb(); + }, + } as Writable); + }); + + afterEach(function () { + loggingAndTelemetry.detachLogger(); + logger.destroy(); + }); + + it('throws when running attachLogger twice without detaching', function () { + loggingAndTelemetry.attachLogger(logger); + expect(() => loggingAndTelemetry.attachLogger(logger)).throws( + 'Previously set logger has not been detached. Run detachLogger() before setting.' ); + }); + + it('does not throw when attaching and detaching loggers', function () { + loggingAndTelemetry.attachLogger(logger); + loggingAndTelemetry.detachLogger(); + expect(() => loggingAndTelemetry.attachLogger(logger)).does.not.throw(); + }); + + it('tracks new local connection events', function () { + loggingAndTelemetry.attachLogger(logger); + expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; + bus.emit('mongosh:new-user', { userId, anonymousId: userId }); + bus.emit('mongosh:log-initialized'); + bus.emit('mongosh:connect', { uri: 'mongodb://localhost/', is_localhost: true, @@ -94,14 +101,25 @@ describe('setupLoggerAndTelemetry', function () { expect(logOutput[0].attr.node_version).to.equal('v12.19.0'); expect(analyticsOutput).to.deep.equal([ + [ + 'identify', + { + anonymousId: userId, + traits: { + arch: process.arch, + platform: process.platform, + session_id: logId, + }, + }, + ], [ 'track', { - anonymousId: undefined, + anonymousId: userId, event: 'New Connection', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, is_localhost: true, is_atlas: false, atlas_hostname: null, @@ -113,19 +131,14 @@ describe('setupLoggerAndTelemetry', function () { }); it('tracks new atlas connection events', function () { - setupLoggerAndTelemetry( - bus, - logger, - analytics, - { - platform: process.platform, - arch: process.arch, - }, - '1.0.0' - ); + loggingAndTelemetry.attachLogger(logger); + expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; + bus.emit('mongosh:new-user', { userId, anonymousId: userId }); + bus.emit('mongosh:log-initialized'); + bus.emit('mongosh:connect', { uri: 'mongodb://test-data-sets-a011bb.mongodb.net/', is_localhost: false, @@ -146,14 +159,25 @@ describe('setupLoggerAndTelemetry', function () { expect(logOutput[0].attr.node_version).to.equal('v12.19.0'); expect(analyticsOutput).to.deep.equal([ + [ + 'identify', + { + anonymousId: userId, + traits: { + arch: process.arch, + platform: process.platform, + session_id: logId, + }, + }, + ], [ 'track', { - anonymousId: undefined, + anonymousId: userId, event: 'New Connection', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, is_localhost: false, is_atlas: true, atlas_hostname: 'test-data-sets-00-02-a011bb.mongodb.net', @@ -164,21 +188,100 @@ describe('setupLoggerAndTelemetry', function () { ]); }); + it('detaching logger leads to no logging but persists analytics', function () { + loggingAndTelemetry.attachLogger(logger); + + expect(logOutput).to.have.lengthOf(0); + expect(analyticsOutput).to.have.lengthOf(0); + + loggingAndTelemetry.detachLogger(); + + // This event has both analytics and logging + bus.emit('mongosh:use', { db: '' }); + + expect(logOutput).to.have.lengthOf(0); + expect(analyticsOutput).to.have.lengthOf(1); + }); + + it('detaching logger applies to devtools-connect events', function () { + loggingAndTelemetry.attachLogger(logger); + + bus.emit('devtools-connect:connect-fail-early'); + bus.emit('devtools-connect:connect-fail-early'); + + expect(logOutput).to.have.lengthOf(2); + // No analytics event attached to this + expect(analyticsOutput).to.have.lengthOf(0); + + loggingAndTelemetry.detachLogger(); + bus.emit('devtools-connect:connect-fail-early'); + + expect(logOutput).to.have.lengthOf(2); + expect(analyticsOutput).to.have.lengthOf(0); + + loggingAndTelemetry.attachLogger(logger); + + bus.emit('devtools-connect:connect-fail-early'); + bus.emit('devtools-connect:connect-fail-early'); + expect(logOutput).to.have.lengthOf(4); + }); + + it('detaching logger mid-way leads to no logging but persists analytics', function () { + loggingAndTelemetry.attachLogger(logger); + + expect(logOutput).to.have.lengthOf(0); + expect(analyticsOutput).to.have.lengthOf(0); + + // This event has both analytics and logging + bus.emit('mongosh:use', { db: '' }); + + expect(logOutput).to.have.lengthOf(1); + expect(analyticsOutput).to.have.lengthOf(1); + + loggingAndTelemetry.detachLogger(); + + bus.emit('mongosh:use', { db: '' }); + + expect(logOutput).to.have.lengthOf(1); + expect(analyticsOutput).to.have.lengthOf(2); + }); + + it('detaching logger is recoverable', function () { + loggingAndTelemetry.attachLogger(logger); + + expect(logOutput).to.have.lengthOf(0); + expect(analyticsOutput).to.have.lengthOf(0); + + // This event has both analytics and logging + bus.emit('mongosh:use', { db: '' }); + + expect(logOutput).to.have.lengthOf(1); + expect(analyticsOutput).to.have.lengthOf(1); + + loggingAndTelemetry.detachLogger(); + + bus.emit('mongosh:use', { db: '' }); + + expect(logOutput).to.have.lengthOf(1); + expect(analyticsOutput).to.have.lengthOf(2); + + loggingAndTelemetry.attachLogger(logger); + + bus.emit('mongosh:use', { db: '' }); + + expect(logOutput).to.have.lengthOf(2); + expect(analyticsOutput).to.have.lengthOf(3); + }); + it('tracks a sequence of events', function () { - setupLoggerAndTelemetry( - bus, - logger, - analytics, - { - platform: process.platform, - arch: process.arch, - }, - '1.0.0' - ); + loggingAndTelemetry.attachLogger(logger); + expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; bus.emit('mongosh:new-user', { userId, anonymousId: userId }); + bus.emit('mongosh:log-initialized'); + bus.emit('mongosh:update-user', { userId, anonymousId: userId }); bus.emit('mongosh:start-session', { isInteractive: true, @@ -476,7 +579,7 @@ describe('setupLoggerAndTelemetry', function () { traits: { platform: process.platform, arch: process.arch, - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, }, ], @@ -487,7 +590,7 @@ describe('setupLoggerAndTelemetry', function () { traits: { platform: process.platform, arch: process.arch, - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, }, ], @@ -502,7 +605,7 @@ describe('setupLoggerAndTelemetry', function () { boxed_node_bindings: 50, node_repl: 100, mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, }, ], @@ -513,7 +616,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Error', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, name: 'MongoshInvalidInputError', code: 'CLIREPL-1005', scope: 'CLIREPL', @@ -528,7 +631,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Error', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, name: 'MongoshInvalidInputError', code: 'CLIREPL-1005', scope: 'CLIREPL', @@ -543,7 +646,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Use', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, }, ], @@ -554,7 +657,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Show', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, method: 'dbs', }, }, @@ -565,7 +668,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Script Loaded CLI', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, nested: true, shell: true, }, @@ -578,7 +681,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Script Loaded', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, nested: false, }, anonymousId: '53defe995fa47e6c13102d9d', @@ -590,7 +693,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Mongoshrc Loaded', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, anonymousId: '53defe995fa47e6c13102d9d', }, @@ -601,7 +704,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Mongorc Warning', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, anonymousId: '53defe995fa47e6c13102d9d', }, @@ -612,7 +715,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Script Evaluated', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, shell: true, }, anonymousId: '53defe995fa47e6c13102d9d', @@ -625,7 +728,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Snippet Install', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, }, ], @@ -633,11 +736,14 @@ describe('setupLoggerAndTelemetry', function () { }); it('buffers deprecated API calls', function () { - setupLoggerAndTelemetry(bus, logger, analytics, {}, '1.0.0'); + loggingAndTelemetry.attachLogger(logger); + expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; bus.emit('mongosh:new-user', { userId, anonymousId: userId }); + bus.emit('mongosh:log-initialized'); + bus.emit('mongosh:evaluate-started'); logOutput = []; @@ -716,7 +822,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Deprecated Method', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, class: 'Database', method: 'cloneDatabase', }, @@ -729,7 +835,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Deprecated Method', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, class: 'Database', method: 'copyDatabase', }, @@ -742,7 +848,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Deprecated Method', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, class: 'Database', method: 'mangleDatabase', }, @@ -755,7 +861,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'API Call', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, class: 'Database', method: 'cloneDatabase', count: 3, @@ -769,7 +875,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'API Call', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, class: 'Database', method: 'copyDatabase', count: 1, @@ -805,7 +911,8 @@ describe('setupLoggerAndTelemetry', function () { }); it('does not track database calls outside of evaluate-{started,finished}', function () { - setupLoggerAndTelemetry(bus, logger, analytics, {}, '1.0.0'); + loggingAndTelemetry.attachLogger(logger); + expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; @@ -828,19 +935,11 @@ describe('setupLoggerAndTelemetry', function () { }); 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; + loggingAndTelemetry.attachLogger(logger); + bus.emit('mongosh:connect', { uri: 'mongodb://localhost/', is_localhost: true, diff --git a/packages/logging/src/logging-and-telemetry.ts b/packages/logging/src/logging-and-telemetry.ts new file mode 100644 index 0000000000..69b77fa50c --- /dev/null +++ b/packages/logging/src/logging-and-telemetry.ts @@ -0,0 +1,871 @@ +import redactInfo from 'mongodb-redact'; +import { redactURICredentials } from '@mongosh/history'; +import type { + MongoshBus, + ApiEventWithArguments, + ApiEvent, + UseEvent, + EvaluateInputEvent, + ShowEvent, + ConnectEvent, + ScriptLoadFileEvent, + StartLoadingCliScriptsEvent, + StartMongoshReplEvent, + GlobalConfigFileLoadEvent, + CryptLibrarySkipEvent, + CryptLibraryFoundEvent, + SnippetsCommandEvent, + SnippetsErrorEvent, + SnippetsFetchIndexErrorEvent, + SnippetsFetchIndexEvent, + SnippetsLoadedEvent, + SnippetsLoadSnippetEvent, + SnippetsNpmDownloadActiveEvent, + SnippetsNpmDownloadFailedEvent, + SnippetsNpmLookupEvent, + SnippetsRunNpmEvent, + SnippetsTransformErrorEvent, + EditorRunEditCommandEvent, + EditorReadVscodeExtensionsDoneEvent, + EditorReadVscodeExtensionsFailedEvent, + FetchingUpdateMetadataEvent, + FetchingUpdateMetadataCompleteEvent, + SessionStartedEvent, + MongoshBusEventsMap, + WriteCustomLogEvent, +} from '@mongosh/types'; +import { inspect } from 'util'; +import { MongoLogWriter } from 'mongodb-log-writer'; +import { mongoLogId } from 'mongodb-log-writer'; +import type { + AnalyticsIdentifyMessage, + MongoshAnalytics, + MongoshAnalyticsIdentity, +} from './analytics-helpers'; +import type { ConnectEventMap } from '@mongodb-js/devtools-connect'; +import { hookLogger } from '@mongodb-js/devtools-connect'; +import { MultiSet, toSnakeCase } from './helpers'; +import { Writable } from 'stream'; +import type { + LoggingAndTelemetryBusEventState, + MongoshLoggingAndTelemetry, + MongoshLoggingAndTelemetryArguments, + MongoshTrackingProperties, +} from './types'; + +export function setupLoggingAndTelemetry( + props: MongoshLoggingAndTelemetryArguments +): MongoshLoggingAndTelemetry { + const loggingAndTelemetry = new LoggingAndTelemetry(props); + + loggingAndTelemetry.setup(); + return loggingAndTelemetry; +} + +class LoggingAndTelemetry implements MongoshLoggingAndTelemetry { + private static dummyLogger = new MongoLogWriter( + '', + null, + new Writable({ + write(chunk, encoding, callback) { + callback(); + }, + }) + ); + + private readonly bus: MongoshBus; + private readonly analytics: MongoshAnalytics; + private readonly userTraits: { + platform: string; + [key: string]: unknown; + }; + private readonly mongoshVersion: string; + + private log: MongoLogWriter; + private pendingLogEvents: CallableFunction[] = []; + private isSetup = false; + private isBufferingEvents = false; + + constructor({ + bus, + analytics, + userTraits, + mongoshVersion, + }: MongoshLoggingAndTelemetryArguments) { + this.bus = bus; + this.analytics = analytics; + this.log = LoggingAndTelemetry.dummyLogger; + this.userTraits = userTraits; + this.mongoshVersion = mongoshVersion; + } + + public setup(): void { + if (this.isSetup) { + throw new Error('Setup can only be called once.'); + } + this.setupBusEventListeners(); + this.isSetup = true; + this.isBufferingEvents = true; + } + + public attachLogger(logger: MongoLogWriter): void { + if (!this.isSetup) { + throw new Error('Run setup() before setting up the log writer.'); + } + /** Setup can only be run when overriding a dummy log or a null log. */ + if (this.log !== LoggingAndTelemetry.dummyLogger) { + throw new Error( + 'Previously set logger has not been detached. Run detachLogger() before setting.' + ); + } + this.log = logger; + this.isBufferingEvents = false; + + this.runAndClearPendingEvents(); + + this.bus.emit('mongosh:log-initialized'); + } + + public detachLogger() { + this.log = LoggingAndTelemetry.dummyLogger; + // Still run any remaining pending events with the dummy log for telemetry purposes. + this.runAndClearPendingEvents(); + } + + private runAndClearPendingEvents() { + let pendingEvent: CallableFunction | undefined; + while ((pendingEvent = this.pendingLogEvents.shift())) { + pendingEvent(); + } + } + + /** Information used and set by different bus events. */ + private busEventState: LoggingAndTelemetryBusEventState = { + /** We emit different analytics events for loading files and evaluating scripts + * depending on whether we're already in the REPL or not yet. We store the + * state here so that the places where the events are emitted don't have to + * be aware of this distinction. */ + hasStartedMongoshRepl: false, + apiCallTracking: { + isEnabled: false, + apiCalls: new MultiSet>(), + deprecatedApiCalls: new MultiSet>(), + }, + usesShellOption: false, + telemetryAnonymousId: undefined, + userId: undefined, + }; + + private setupBusEventListeners(): void { + const onBus = < + EventsMap extends Record< + keyof MongoshBusEventsMap | keyof ConnectEventMap, + // eslint-disable-next-line @typescript-eslint/no-explicit-any + (...args: any[]) => unknown + > = MongoshBusEventsMap, + K extends + | keyof MongoshBusEventsMap + | keyof ConnectEventMap = keyof MongoshBusEventsMap + >( + event: K, + listener: (...args: Parameters) => void + ) => { + this.bus.on(event, ((...args: Parameters) => { + if (this.isBufferingEvents) { + this.pendingLogEvents.push(() => listener(...args)); + return; + } + + listener(...args); + }) as MongoshBusEventsMap[K]); + return this.bus; + }; + + const getUserTraits = (): AnalyticsIdentifyMessage['traits'] => ({ + ...this.userTraits, + session_id: this.log.logId, + }); + + const getTrackingProperties = (): MongoshTrackingProperties => ({ + mongosh_version: this.mongoshVersion, + session_id: this.log.logId, + }); + + const getTelemetryUserIdentity = (): MongoshAnalyticsIdentity => { + return { + anonymousId: + this.busEventState.telemetryAnonymousId ?? + (this.busEventState.userId as string), + }; + }; + + onBus('mongosh:start-mongosh-repl', (ev: StartMongoshReplEvent) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_002), + 'repl', + 'Started REPL', + ev + ); + this.busEventState.hasStartedMongoshRepl = true; + }); + + onBus( + 'mongosh:start-loading-cli-scripts', + (event: StartLoadingCliScriptsEvent) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_003), + 'repl', + 'Start loading CLI scripts' + ); + this.busEventState.usesShellOption = event.usesShellOption; + } + ); + + onBus('mongosh:connect', (args: ConnectEvent) => { + const { uri, resolved_hostname, ...argsWithoutUriAndHostname } = args; + const connectionUri = uri && redactURICredentials(uri); + const atlasHostname = { + atlas_hostname: args.is_atlas ? resolved_hostname : null, + }; + const properties = { + ...getTrackingProperties(), + ...argsWithoutUriAndHostname, + ...atlasHostname, + }; + + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_004), + 'connect', + 'Connecting to server', + { + userId: this.busEventState.userId, + telemetryAnonymousId: this.busEventState.telemetryAnonymousId, + connectionUri, + ...properties, + } + ); + + this.analytics.track({ + ...getTelemetryUserIdentity(), + event: 'New Connection', + properties, + }); + }); + + onBus('mongosh:start-session', (args: SessionStartedEvent) => { + const normalizedTimingsArray = Object.entries(args.timings).map( + ([key, duration]) => { + const snakeCaseKey = toSnakeCase(key); + return [snakeCaseKey, duration]; + } + ); + + const normalizedTimings = Object.fromEntries(normalizedTimingsArray); + this.analytics.track({ + ...getTelemetryUserIdentity(), + event: 'Startup Time', + properties: { + ...getTrackingProperties(), + is_interactive: args.isInteractive, + js_context: args.jsContext, + ...normalizedTimings, + }, + }); + }); + + onBus( + 'mongosh:new-user', + (newTelemetryUserIdentity: { userId: string; anonymousId: string }) => { + if (!newTelemetryUserIdentity.anonymousId) { + this.busEventState.userId = newTelemetryUserIdentity.userId; + } + this.busEventState.telemetryAnonymousId = + newTelemetryUserIdentity.anonymousId; + this.analytics.identify({ + anonymousId: newTelemetryUserIdentity.anonymousId, + traits: getUserTraits(), + }); + } + ); + + onBus( + 'mongosh:update-user', + (updatedTelemetryUserIdentity: { + userId: string; + anonymousId?: string; + }) => { + if (updatedTelemetryUserIdentity.anonymousId) { + this.busEventState.telemetryAnonymousId = + updatedTelemetryUserIdentity.anonymousId; + } else { + this.busEventState.userId = updatedTelemetryUserIdentity.userId; + } + this.analytics.identify({ + ...getTelemetryUserIdentity(), + traits: getUserTraits(), + }); + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_005), + 'config', + 'User updated' + ); + } + ); + + onBus('mongosh:error', (error: Error, context: string) => { + const mongoshError = error as { + name: string; + message: string; + code: unknown; + scope: unknown; + metadata: unknown; + }; + + this.log[context === 'fatal' ? 'fatal' : 'error']( + 'MONGOSH', + mongoLogId(1_000_000_006), + context, + `${mongoshError.name}: ${mongoshError.message}`, + error + ); + + if (error.name.includes('Mongosh')) { + this.analytics.track({ + ...getTelemetryUserIdentity(), + event: 'Error', + properties: { + ...getTrackingProperties(), + name: mongoshError.name, + code: mongoshError.code, + scope: mongoshError.scope, + metadata: mongoshError.metadata, + }, + }); + } + }); + + onBus('mongosh:write-custom-log', (event: WriteCustomLogEvent) => { + this.log[event.method]( + 'MONGOSH-SCRIPTS', + mongoLogId(1_000_000_054), + 'custom-log', + event.message, + event.attr, + event.level + ); + }); + + onBus('mongosh:globalconfig-load', (args: GlobalConfigFileLoadEvent) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_048), + 'config', + 'Loading global configuration file', + args + ); + }); + + onBus('mongosh:evaluate-input', (args: EvaluateInputEvent) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_007), + 'repl', + 'Evaluating input', + args + ); + }); + + onBus('mongosh:use', (args: UseEvent) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_008), + 'shell-api', + 'Used "use" command', + args + ); + + this.analytics.track({ + ...getTelemetryUserIdentity(), + event: 'Use', + properties: { + ...getTrackingProperties(), + }, + }); + }); + + onBus('mongosh:show', (args: ShowEvent) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_009), + 'shell-api', + 'Used "show" command', + args + ); + + this.analytics.track({ + ...getTelemetryUserIdentity(), + event: 'Show', + properties: { + ...getTrackingProperties(), + method: args.method, + }, + }); + }); + + onBus('mongosh:setCtx', (args: ApiEventWithArguments) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_010), + 'shell-api', + 'Initialized context', + args + ); + }); + + onBus('mongosh:api-call-with-arguments', (args: ApiEventWithArguments) => { + // TODO: redactInfo cannot handle circular or otherwise nontrivial input + let arg; + try { + arg = JSON.parse(JSON.stringify(args)); + } catch { + arg = { _inspected: inspect(args) }; + } + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_011), + 'shell-api', + 'Performed API call', + redactInfo(arg) + ); + }); + + onBus('mongosh:api-load-file', (args: ScriptLoadFileEvent) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_012), + 'shell-api', + 'Loading file via load()', + args + ); + + this.analytics.track({ + ...getTelemetryUserIdentity(), + event: this.busEventState.hasStartedMongoshRepl + ? 'Script Loaded' + : 'Script Loaded CLI', + properties: { + ...getTrackingProperties(), + nested: args.nested, + ...(this.busEventState.hasStartedMongoshRepl + ? {} + : { shell: this.busEventState.usesShellOption }), + }, + }); + }); + + onBus('mongosh:eval-cli-script', () => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_013), + 'repl', + 'Evaluating script passed on the command line' + ); + + this.analytics.track({ + ...getTelemetryUserIdentity(), + event: 'Script Evaluated', + properties: { + ...getTrackingProperties(), + shell: this.busEventState.usesShellOption, + }, + }); + }); + + onBus('mongosh:mongoshrc-load', () => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_014), + 'repl', + 'Loading .mongoshrc.js' + ); + + this.analytics.track({ + ...getTelemetryUserIdentity(), + event: 'Mongoshrc Loaded', + properties: { + ...getTrackingProperties(), + }, + }); + }); + + onBus('mongosh:mongoshrc-mongorc-warn', () => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_015), + 'repl', + 'Warning about .mongorc.js/.mongoshrc.js mismatch' + ); + + this.analytics.track({ + ...getTelemetryUserIdentity(), + event: 'Mongorc Warning', + properties: { + ...getTrackingProperties(), + }, + }); + }); + + onBus('mongosh:crypt-library-load-skip', (ev: CryptLibrarySkipEvent) => { + this.log.info( + 'AUTO-ENCRYPTION', + mongoLogId(1_000_000_050), + 'crypt-library', + 'Skipping shared library candidate', + ev + ); + }); + + onBus('mongosh:crypt-library-load-found', (ev: CryptLibraryFoundEvent) => { + this.log.warn( + 'AUTO-ENCRYPTION', + mongoLogId(1_000_000_051), + 'crypt-library', + 'Accepted shared library candidate', + { + cryptSharedLibPath: ev.cryptSharedLibPath, + expectedVersion: ev.expectedVersion.versionStr, + } + ); + }); + + onBus('mongosh-snippets:loaded', (ev: SnippetsLoadedEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_019), + 'snippets', + 'Loaded snippets', + ev + ); + }); + + onBus('mongosh-snippets:npm-lookup', (ev: SnippetsNpmLookupEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_020), + 'snippets', + 'Performing npm lookup', + ev + ); + }); + + onBus('mongosh-snippets:npm-lookup-stopped', () => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_021), + 'snippets', + 'npm lookup stopped' + ); + }); + + onBus( + 'mongosh-snippets:npm-download-failed', + (ev: SnippetsNpmDownloadFailedEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_022), + 'snippets', + 'npm download failed', + ev + ); + } + ); + + onBus( + 'mongosh-snippets:npm-download-active', + (ev: SnippetsNpmDownloadActiveEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_023), + 'snippets', + 'npm download active', + ev + ); + } + ); + + onBus('mongosh-snippets:fetch-index', (ev: SnippetsFetchIndexEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_024), + 'snippets', + 'Fetching snippet index', + ev + ); + }); + + onBus('mongosh-snippets:fetch-cache-invalid', () => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_025), + 'snippets', + 'Snippet cache invalid' + ); + }); + + onBus( + 'mongosh-snippets:fetch-index-error', + (ev: SnippetsFetchIndexErrorEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_026), + 'snippets', + 'Fetching snippet index failed', + ev + ); + } + ); + + onBus('mongosh-snippets:fetch-index-done', () => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_027), + 'snippets', + 'Fetching snippet index done' + ); + }); + onBus( + 'mongosh-snippets:package-json-edit-error', + (ev: SnippetsErrorEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_028), + 'snippets', + 'Modifying snippets package.json failed', + ev + ); + } + ); + + onBus('mongosh-snippets:spawn-child', (ev: SnippetsRunNpmEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_029), + 'snippets', + 'Spawning helper', + ev + ); + }); + + onBus('mongosh-snippets:load-snippet', (ev: SnippetsLoadSnippetEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_030), + 'snippets', + 'Loading snippet', + ev + ); + }); + + onBus('mongosh-snippets:snippet-command', (ev: SnippetsCommandEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_031), + 'snippets', + 'Running snippet command', + ev + ); + + if (ev.args[0] === 'install') { + this.analytics.track({ + ...getTelemetryUserIdentity(), + event: 'Snippet Install', + properties: { + ...getTrackingProperties(), + }, + }); + } + }); + + onBus( + 'mongosh-snippets:transform-error', + (ev: SnippetsTransformErrorEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_032), + 'snippets', + 'Rewrote error message', + ev + ); + } + ); + + onBus('mongosh:api-call', (ev: ApiEvent) => { + // Only track if we have previously seen a mongosh:evaluate-started call + if (!this.busEventState.apiCallTracking.isEnabled) return; + const { apiCalls, deprecatedApiCalls } = + this.busEventState.apiCallTracking; + if (ev.deprecated) { + deprecatedApiCalls.add({ class: ev.class, method: ev.method }); + } + if (ev.callDepth === 0 && ev.isAsync) { + apiCalls.add({ class: ev.class, method: ev.method }); + } + }); + onBus('mongosh:evaluate-started', () => { + const { apiCalls, deprecatedApiCalls } = + this.busEventState.apiCallTracking; + this.busEventState.apiCallTracking.isEnabled = true; + // Clear API calls before evaluation starts. This is important because + // some API calls are also emitted by mongosh CLI repl internals, + // but we only care about those emitted from user code (i.e. during + // evaluation). + deprecatedApiCalls.clear(); + apiCalls.clear(); + }); + onBus('mongosh:evaluate-finished', () => { + const { apiCalls, deprecatedApiCalls } = + this.busEventState.apiCallTracking; + for (const [entry] of deprecatedApiCalls) { + this.log.warn( + 'MONGOSH', + mongoLogId(1_000_000_033), + 'shell-api', + 'Deprecated API call', + entry + ); + + this.analytics.track({ + ...getTelemetryUserIdentity(), + event: 'Deprecated Method', + properties: { + ...getTrackingProperties(), + ...entry, + }, + }); + } + for (const [entry, count] of apiCalls) { + this.analytics.track({ + ...getTelemetryUserIdentity(), + event: 'API Call', + properties: { + ...getTrackingProperties(), + ...entry, + count, + }, + }); + } + deprecatedApiCalls.clear(); + apiCalls.clear(); + this.busEventState.apiCallTracking.isEnabled = false; + }); + + // Log ids 1_000_000_034 through 1_000_000_042 are reserved for the + // devtools-connect package which was split out from mongosh. + // 'mongodb' is not supported in startup snapshots yet. + + onBus('mongosh-sp:reset-connection-options', () => { + this.log.info( + 'MONGOSH-SP', + mongoLogId(1_000_000_040), + 'connect', + 'Reconnect because of changed connection options' + ); + }); + + onBus( + 'mongosh-editor:run-edit-command', + (ev: EditorRunEditCommandEvent) => { + this.log.error( + 'MONGOSH-EDITOR', + mongoLogId(1_000_000_047), + 'editor', + 'Open external editor', + redactInfo(ev) + ); + } + ); + + onBus( + 'mongosh-editor:read-vscode-extensions-done', + (ev: EditorReadVscodeExtensionsDoneEvent) => { + this.log.error( + 'MONGOSH-EDITOR', + mongoLogId(1_000_000_043), + 'editor', + 'Reading vscode extensions from file system succeeded', + ev + ); + } + ); + + onBus( + 'mongosh-editor:read-vscode-extensions-failed', + (ev: EditorReadVscodeExtensionsFailedEvent) => { + this.log.error( + 'MONGOSH-EDITOR', + mongoLogId(1_000_000_044), + 'editor', + 'Reading vscode extensions from file system failed', + { + ...ev, + error: ev.error.message, + } + ); + } + ); + + onBus( + 'mongosh:fetching-update-metadata', + (ev: FetchingUpdateMetadataEvent) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_052), + 'startup', + 'Fetching update metadata', + { + ...ev, + } + ); + } + ); + + onBus( + 'mongosh:fetching-update-metadata-complete', + (ev: FetchingUpdateMetadataCompleteEvent) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_053), + 'startup', + 'Fetching update metadata complete', + { + ...ev, + } + ); + } + ); + + hookLogger( + this.bus, + { + info: (...args: Parameters) => { + return this.log.info(...args); + }, + warn: (...args: Parameters) => { + return this.log.warn(...args); + }, + error: (...args: Parameters) => { + return this.log.error(...args); + }, + mongoLogId: (...args: Parameters) => { + return this.log.mongoLogId(...args); + }, + }, + 'mongosh', + (uri) => redactURICredentials(uri) + ); + } +} diff --git a/packages/logging/src/setup-logger-and-telemetry.ts b/packages/logging/src/setup-logger-and-telemetry.ts deleted file mode 100644 index c659d21b9e..0000000000 --- a/packages/logging/src/setup-logger-and-telemetry.ts +++ /dev/null @@ -1,795 +0,0 @@ -import redactInfo from 'mongodb-redact'; -import { redactURICredentials } from '@mongosh/history'; -import type { - MongoshBus, - ApiEventWithArguments, - ApiEvent, - UseEvent, - EvaluateInputEvent, - ShowEvent, - ConnectEvent, - ScriptLoadFileEvent, - StartLoadingCliScriptsEvent, - StartMongoshReplEvent, - GlobalConfigFileLoadEvent, - CryptLibrarySkipEvent, - CryptLibraryFoundEvent, - SnippetsCommandEvent, - SnippetsErrorEvent, - SnippetsFetchIndexErrorEvent, - SnippetsFetchIndexEvent, - SnippetsLoadedEvent, - SnippetsLoadSnippetEvent, - SnippetsNpmDownloadActiveEvent, - SnippetsNpmDownloadFailedEvent, - SnippetsNpmLookupEvent, - SnippetsRunNpmEvent, - SnippetsTransformErrorEvent, - EditorRunEditCommandEvent, - EditorReadVscodeExtensionsDoneEvent, - EditorReadVscodeExtensionsFailedEvent, - FetchingUpdateMetadataEvent, - FetchingUpdateMetadataCompleteEvent, - SessionStartedEvent, - WriteCustomLogEvent, -} from '@mongosh/types'; -import { inspect } from 'util'; -import type { MongoLogWriter } from 'mongodb-log-writer'; -import { mongoLogId } from 'mongodb-log-writer'; -import type { MongoshAnalytics } from './analytics-helpers'; -import { hookLogger } from '@mongodb-js/devtools-connect'; - -/** - * A helper class for keeping track of how often specific events occurred. - */ -class MultiSet> { - _entries: Map = new Map(); - - add(entry: T): void { - const key = JSON.stringify(Object.entries(entry).sort()); - this._entries.set(key, (this._entries.get(key) ?? 0) + 1); - } - - clear(): void { - this._entries.clear(); - } - - *[Symbol.iterator](): Iterator<[T, number]> { - for (const [key, count] of this._entries) { - yield [Object.fromEntries(JSON.parse(key)) as T, count]; - } - } -} - -/** - * It transforms a random string into snake case. Snake case is completely - * lowercase and uses '_' to separate words. For example: - * - * This function defines a "word" as a sequence of characters until the next `.` or capital letter. - * - * 'Random String' => 'random_string' - * - * It will also remove any non alphanumeric characters to ensure the string - * is compatible with Segment. For example: - * - * 'Node.js REPL Instantiation' => 'node_js_repl_instantiation' - * - * @param str Any non snake-case formatted string - * @returns The snake-case formatted string - */ -export function toSnakeCase(str: string): string { - const matches = str.match( - /[A-Z]{2,}(?=[A-Z][a-z]+[0-9]*|\b)|[A-Z]?[a-z]+[0-9]*|[A-Z]|[0-9]+/g - ); - if (!matches) { - return str; - } - - return matches.map((x) => x.toLowerCase()).join('_'); -} - -/** - * Connect a MongoshBus instance that emits events to logging and analytics providers. - * - * @param bus A MongoshBus instance - * @param log A MongoLogWriter instance - * @param makeAnalytics A function that returns an analytics provider (or throws otherwise) - */ -export function setupLoggerAndTelemetry( - bus: MongoshBus, - log: MongoLogWriter, - analytics: MongoshAnalytics, - userTraits: any, - mongosh_version: string -): void { - const { logId: session_id } = log; - let userId: string; - let telemetryAnonymousId: string; - - userTraits = { ...userTraits, session_id }; - - const trackProperties = { - mongosh_version, - session_id, - }; - - const getTelemetryUserIdentity = () => ({ - anonymousId: telemetryAnonymousId ?? userId, - }); - - // We emit different analytics events for loading files and evaluating scripts - // depending on whether we're already in the REPL or not yet. We store the - // state here so that the places where the events are emitted don't have to - // be aware of this distinction. - let hasStartedMongoshRepl = false; - bus.on('mongosh:start-mongosh-repl', (ev: StartMongoshReplEvent) => { - log.info('MONGOSH', mongoLogId(1_000_000_002), 'repl', 'Started REPL', ev); - hasStartedMongoshRepl = true; - }); - - let usesShellOption = false; - bus.on( - 'mongosh:start-loading-cli-scripts', - (event: StartLoadingCliScriptsEvent) => { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_003), - 'repl', - 'Start loading CLI scripts' - ); - usesShellOption = event.usesShellOption; - } - ); - - 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); - const atlasHostname = { - atlas_hostname: args.is_atlas ? resolved_hostname : null, - }; - const properties = { - ...trackProperties, - ...argsWithoutUriAndHostname, - ...atlasHostname, - }; - - log.info( - 'MONGOSH', - mongoLogId(1_000_000_004), - 'connect', - 'Connecting to server', - { - userId, - telemetryAnonymousId, - connectionUri, - ...properties, - } - ); - - analytics.track({ - ...getTelemetryUserIdentity(), - event: 'New Connection', - properties, - }); - }); - - bus.on('mongosh:start-session', function (args: SessionStartedEvent) { - const normalisedTimingsArray = Object.entries(args.timings).map( - ([key, duration]) => { - const snakeCaseKey = toSnakeCase(key); - return [snakeCaseKey, duration]; - } - ); - - const normalisedTimings = Object.fromEntries(normalisedTimingsArray); - analytics.track({ - ...getTelemetryUserIdentity(), - event: 'Startup Time', - properties: { - ...trackProperties, - is_interactive: args.isInteractive, - js_context: args.jsContext, - ...normalisedTimings, - }, - }); - }); - - bus.on( - 'mongosh:new-user', - function (newTelemetryUserIdentity: { - userId: string; - anonymousId: string; - }) { - if (!newTelemetryUserIdentity.anonymousId) { - userId = newTelemetryUserIdentity.userId; - } - telemetryAnonymousId = newTelemetryUserIdentity.anonymousId; - analytics.identify({ - anonymousId: newTelemetryUserIdentity.anonymousId, - traits: userTraits, - }); - } - ); - - bus.on( - 'mongosh:update-user', - function (updatedTelemetryUserIdentity: { - userId: string; - anonymousId?: string; - }) { - if (updatedTelemetryUserIdentity.anonymousId) { - telemetryAnonymousId = updatedTelemetryUserIdentity.anonymousId; - } else { - userId = updatedTelemetryUserIdentity.userId; - } - analytics.identify({ - ...getTelemetryUserIdentity(), - traits: userTraits, - }); - log.info('MONGOSH', mongoLogId(1_000_000_005), 'config', 'User updated'); - } - ); - - bus.on('mongosh:error', function (error: Error, context: string) { - const mongoshError = error as { - name: string; - message: string; - code: any; - scope: any; - metadata: any; - }; - - if (context === 'fatal') { - log.fatal( - 'MONGOSH', - mongoLogId(1_000_000_006), - context, - `${mongoshError.name}: ${mongoshError.message}`, - error - ); - } else { - log.error( - 'MONGOSH', - mongoLogId(1_000_000_006), - context, - `${mongoshError.name}: ${mongoshError.message}`, - error - ); - } - - if (error.name.includes('Mongosh')) { - analytics.track({ - ...getTelemetryUserIdentity(), - event: 'Error', - properties: { - ...trackProperties, - name: mongoshError.name, - code: mongoshError.code, - scope: mongoshError.scope, - metadata: mongoshError.metadata, - }, - }); - } - }); - - bus.on( - 'mongosh:globalconfig-load', - function (args: GlobalConfigFileLoadEvent) { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_048), - 'config', - 'Loading global configuration file', - args - ); - } - ); - - bus.on('mongosh:evaluate-input', function (args: EvaluateInputEvent) { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_007), - 'repl', - 'Evaluating input', - args - ); - }); - - bus.on('mongosh:use', function (args: UseEvent) { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_008), - 'shell-api', - 'Used "use" command', - args - ); - - analytics.track({ - ...getTelemetryUserIdentity(), - event: 'Use', - properties: { - ...trackProperties, - }, - }); - }); - - bus.on('mongosh:show', function (args: ShowEvent) { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_009), - 'shell-api', - 'Used "show" command', - args - ); - - analytics.track({ - ...getTelemetryUserIdentity(), - event: 'Show', - properties: { - ...trackProperties, - method: args.method, - }, - }); - }); - - bus.on('mongosh:setCtx', function (args: ApiEventWithArguments) { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_010), - 'shell-api', - 'Initialized context', - args - ); - }); - - bus.on( - 'mongosh:api-call-with-arguments', - function (args: ApiEventWithArguments) { - // TODO: redactInfo cannot handle circular or otherwise nontrivial input - let arg; - try { - arg = JSON.parse(JSON.stringify(args)); - } catch { - arg = { _inspected: inspect(args) }; - } - log.info( - 'MONGOSH', - mongoLogId(1_000_000_011), - 'shell-api', - 'Performed API call', - redactInfo(arg) - ); - } - ); - - bus.on('mongosh:api-load-file', function (args: ScriptLoadFileEvent) { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_012), - 'shell-api', - 'Loading file via load()', - args - ); - - analytics.track({ - ...getTelemetryUserIdentity(), - event: hasStartedMongoshRepl ? 'Script Loaded' : 'Script Loaded CLI', - properties: { - ...trackProperties, - nested: args.nested, - ...(hasStartedMongoshRepl ? {} : { shell: usesShellOption }), - }, - }); - }); - - bus.on('mongosh:eval-cli-script', function () { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_013), - 'repl', - 'Evaluating script passed on the command line' - ); - - analytics.track({ - ...getTelemetryUserIdentity(), - event: 'Script Evaluated', - properties: { - ...trackProperties, - shell: usesShellOption, - }, - }); - }); - - bus.on('mongosh:mongoshrc-load', function () { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_014), - 'repl', - 'Loading .mongoshrc.js' - ); - - analytics.track({ - ...getTelemetryUserIdentity(), - event: 'Mongoshrc Loaded', - properties: { - ...trackProperties, - }, - }); - }); - - bus.on('mongosh:mongoshrc-mongorc-warn', function () { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_015), - 'repl', - 'Warning about .mongorc.js/.mongoshrc.js mismatch' - ); - - analytics.track({ - ...getTelemetryUserIdentity(), - event: 'Mongorc Warning', - properties: { - ...trackProperties, - }, - }); - }); - - bus.on( - 'mongosh:crypt-library-load-skip', - function (ev: CryptLibrarySkipEvent) { - log.info( - 'AUTO-ENCRYPTION', - mongoLogId(1_000_000_050), - 'crypt-library', - 'Skipping shared library candidate', - ev - ); - } - ); - - bus.on( - 'mongosh:crypt-library-load-found', - function (ev: CryptLibraryFoundEvent) { - log.warn( - 'AUTO-ENCRYPTION', - mongoLogId(1_000_000_051), - 'crypt-library', - 'Accepted shared library candidate', - { - cryptSharedLibPath: ev.cryptSharedLibPath, - expectedVersion: ev.expectedVersion.versionStr, - } - ); - } - ); - - bus.on('mongosh-snippets:loaded', function (ev: SnippetsLoadedEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_019), - 'snippets', - 'Loaded snippets', - ev - ); - }); - - bus.on('mongosh-snippets:npm-lookup', function (ev: SnippetsNpmLookupEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_020), - 'snippets', - 'Performing npm lookup', - ev - ); - }); - - bus.on('mongosh-snippets:npm-lookup-stopped', function () { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_021), - 'snippets', - 'npm lookup stopped' - ); - }); - - bus.on( - 'mongosh-snippets:npm-download-failed', - function (ev: SnippetsNpmDownloadFailedEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_022), - 'snippets', - 'npm download failed', - ev - ); - } - ); - - bus.on( - 'mongosh-snippets:npm-download-active', - function (ev: SnippetsNpmDownloadActiveEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_023), - 'snippets', - 'npm download active', - ev - ); - } - ); - - bus.on( - 'mongosh-snippets:fetch-index', - function (ev: SnippetsFetchIndexEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_024), - 'snippets', - 'Fetching snippet index', - ev - ); - } - ); - - bus.on('mongosh-snippets:fetch-cache-invalid', function () { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_025), - 'snippets', - 'Snippet cache invalid' - ); - }); - - bus.on( - 'mongosh-snippets:fetch-index-error', - function (ev: SnippetsFetchIndexErrorEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_026), - 'snippets', - 'Fetching snippet index failed', - ev - ); - } - ); - - bus.on('mongosh-snippets:fetch-index-done', function () { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_027), - 'snippets', - 'Fetching snippet index done' - ); - }); - - bus.on( - 'mongosh-snippets:package-json-edit-error', - function (ev: SnippetsErrorEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_028), - 'snippets', - 'Modifying snippets package.json failed', - ev - ); - } - ); - - bus.on('mongosh-snippets:spawn-child', function (ev: SnippetsRunNpmEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_029), - 'snippets', - 'Spawning helper', - ev - ); - }); - - bus.on( - 'mongosh-snippets:load-snippet', - function (ev: SnippetsLoadSnippetEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_030), - 'snippets', - 'Loading snippet', - ev - ); - } - ); - - bus.on( - 'mongosh-snippets:snippet-command', - function (ev: SnippetsCommandEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_031), - 'snippets', - 'Running snippet command', - ev - ); - - if (ev.args[0] === 'install') { - analytics.track({ - ...getTelemetryUserIdentity(), - event: 'Snippet Install', - properties: { - ...trackProperties, - }, - }); - } - } - ); - - bus.on( - 'mongosh-snippets:transform-error', - function (ev: SnippetsTransformErrorEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_032), - 'snippets', - 'Rewrote error message', - ev - ); - } - ); - - const deprecatedApiCalls = new MultiSet>(); - const apiCalls = new MultiSet>(); - let apiCallTrackingEnabled = false; - bus.on('mongosh:api-call', function (ev: ApiEvent) { - // Only track if we have previously seen a mongosh:evaluate-started call - if (!apiCallTrackingEnabled) return; - if (ev.deprecated) { - deprecatedApiCalls.add({ class: ev.class, method: ev.method }); - } - if (ev.callDepth === 0 && ev.isAsync) { - apiCalls.add({ class: ev.class, method: ev.method }); - } - }); - bus.on('mongosh:evaluate-started', function () { - apiCallTrackingEnabled = true; - // Clear API calls before evaluation starts. This is important because - // some API calls are also emitted by mongosh CLI repl internals, - // but we only care about those emitted from user code (i.e. during - // evaluation). - deprecatedApiCalls.clear(); - apiCalls.clear(); - }); - bus.on('mongosh:evaluate-finished', function () { - for (const [entry] of deprecatedApiCalls) { - log.warn( - 'MONGOSH', - mongoLogId(1_000_000_033), - 'shell-api', - 'Deprecated API call', - entry - ); - - analytics.track({ - ...getTelemetryUserIdentity(), - event: 'Deprecated Method', - properties: { - ...trackProperties, - ...entry, - }, - }); - } - for (const [entry, count] of apiCalls) { - analytics.track({ - ...getTelemetryUserIdentity(), - event: 'API Call', - properties: { - ...trackProperties, - ...entry, - count, - }, - }); - } - deprecatedApiCalls.clear(); - apiCalls.clear(); - apiCallTrackingEnabled = false; - }); - - // Log ids 1_000_000_034 through 1_000_000_042 are reserved for the - // devtools-connect package which was split out from mongosh. - // 'mongodb' is not supported in startup snapshots yet. - // eslint-disable-next-line @typescript-eslint/no-var-requires - hookLogger(bus, log, 'mongosh', redactURICredentials); - - bus.on('mongosh-sp:reset-connection-options', function () { - log.info( - 'MONGOSH-SP', - mongoLogId(1_000_000_040), - 'connect', - 'Reconnect because of changed connection options' - ); - }); - - bus.on( - 'mongosh-editor:run-edit-command', - function (ev: EditorRunEditCommandEvent) { - log.error( - 'MONGOSH-EDITOR', - mongoLogId(1_000_000_047), - 'editor', - 'Open external editor', - redactInfo(ev) - ); - } - ); - - bus.on( - 'mongosh-editor:read-vscode-extensions-done', - function (ev: EditorReadVscodeExtensionsDoneEvent) { - log.error( - 'MONGOSH-EDITOR', - mongoLogId(1_000_000_043), - 'editor', - 'Reading vscode extensions from file system succeeded', - ev - ); - } - ); - - bus.on( - 'mongosh-editor:read-vscode-extensions-failed', - function (ev: EditorReadVscodeExtensionsFailedEvent) { - log.error( - 'MONGOSH-EDITOR', - mongoLogId(1_000_000_044), - 'editor', - 'Reading vscode extensions from file system failed', - { - ...ev, - error: ev.error.message, - } - ); - } - ); - - bus.on( - 'mongosh:fetching-update-metadata', - function (ev: FetchingUpdateMetadataEvent) { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_052), - 'startup', - 'Fetching update metadata', - { - ...ev, - } - ); - } - ); - - bus.on( - 'mongosh:fetching-update-metadata-complete', - function (ev: FetchingUpdateMetadataCompleteEvent) { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_053), - 'startup', - 'Fetching update metadata complete', - { - ...ev, - } - ); - } - ); - - // NB: mongoLogId(1_000_000_045) is used in cli-repl itself - // NB: mongoLogId(1_000_000_034) through mongoLogId(1_000_000_042) are used in devtools-connect - // NB: mongoLogId(1_000_000_049) is used in devtools-connect -} diff --git a/packages/logging/src/types.ts b/packages/logging/src/types.ts new file mode 100644 index 0000000000..797fd5990c --- /dev/null +++ b/packages/logging/src/types.ts @@ -0,0 +1,35 @@ +import type { ApiEvent, MongoshBus } from '@mongosh/types'; +import type { MongoLogWriter } from 'mongodb-log-writer'; +import type { MongoshAnalytics } from './analytics-helpers'; +import type { MultiSet } from './helpers'; + +export interface MongoshLoggingAndTelemetry { + attachLogger(logger: MongoLogWriter): void; + detachLogger(): void; +} + +export type MongoshLoggingAndTelemetryArguments = { + bus: MongoshBus; + analytics: MongoshAnalytics; + userTraits: { platform: string } & { + [key: string]: unknown; + }; + mongoshVersion: string; +}; + +export type MongoshTrackingProperties = { + mongosh_version: string; + session_id: string; +}; + +export type LoggingAndTelemetryBusEventState = { + hasStartedMongoshRepl: boolean; + apiCallTracking: { + isEnabled: boolean; + apiCalls: MultiSet>; + deprecatedApiCalls: MultiSet>; + }; + usesShellOption: boolean; + telemetryAnonymousId: string | undefined; + userId: string | undefined; +}; diff --git a/packages/types/src/index.ts b/packages/types/src/index.ts index 9267eddc89..bbe2617794 100644 --- a/packages/types/src/index.ts +++ b/packages/types/src/index.ts @@ -393,6 +393,8 @@ export interface MongoshBusEventsMap extends ConnectEventMap { 'mongosh:fetching-update-metadata-complete': ( ev: FetchingUpdateMetadataCompleteEvent ) => void; + /** Signals that logging has been initialized. */ + 'mongosh:log-initialized': () => void; } export interface MongoshBus { @@ -504,6 +506,7 @@ export class CliUserConfig extends SnippetShellUserConfig { oidcTrustedEndpoints: undefined | string[] = undefined; browser: undefined | false | string = undefined; updateURL = 'https://downloads.mongodb.com/compass/mongosh.json'; + disableLogging = false; } export class CliUserConfigValidator extends SnippetShellUserConfigValidator { @@ -530,6 +533,7 @@ export class CliUserConfigValidator extends SnippetShellUserConfigValidator { return `${key} must be a positive integer`; } return null; + case 'disableLogging': case 'forceDisableTelemetry': case 'showStackTraces': if (typeof value !== 'boolean') {