From b8f16f52684994e8d56482292165c36bb133bf67 Mon Sep 17 00:00:00 2001 From: gagik Date: Fri, 24 Jan 2025 10:09:31 +0100 Subject: [PATCH 01/15] feat(cli-repl): add option to disable logging MONGOSH-1988 Some tests still need to be fixed --- packages/cli-repl/src/cli-repl.spec.ts | 39 ++- packages/cli-repl/src/cli-repl.ts | 83 +++--- packages/logging/src/analytics-helpers.ts | 2 +- packages/logging/src/multi-set.ts | 49 ++++ .../src/setup-logger-and-telemetry.spec.ts | 173 ++++++++++--- .../logging/src/setup-logger-and-telemetry.ts | 236 +++++++++--------- packages/types/src/index.ts | 10 + 7 files changed, 406 insertions(+), 186 deletions(-) create mode 100644 packages/logging/src/multi-set.ts diff --git a/packages/cli-repl/src/cli-repl.spec.ts b/packages/cli-repl/src/cli-repl.spec.ts index 3f915bfbd6..6eac159152 100644 --- a/packages/cli-repl/src/cli-repl.spec.ts +++ b/packages/cli-repl/src/cli-repl.spec.ts @@ -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 } from 'mongodb-log-writer'; const { EJSON } = bson; const delay = promisify(setTimeout); @@ -297,7 +300,8 @@ describe('CliRepl', function () { 'oidcTrustedEndpoints', 'browser', 'updateURL', - ]); + 'disableLogging', + ] satisfies (keyof CliUserConfig)[]); }); it('fails when trying to overwrite mongosh-owned config settings', async function () { @@ -1310,6 +1314,36 @@ describe('CliRepl', function () { hasDatabaseNames: true, }); + context('logging configuration', function () { + afterEach(function () { + sinon.restore(); + }); + + it('start logging when it is not disabled', async function () { + const emitSpy = sinon.spy(cliRepl.bus, 'emit'); + + await cliRepl.start(await testServer.connectionString(), {}); + + expect(cliRepl.getConfig('disableLogging')).is.false; + + expect(emitSpy).calledWith('mongosh:log-initialized'); + expect(cliRepl.logWriter).is.instanceOf(MongoLogWriter); + }); + + it('does not start logging when it is disabled', async function () { + const emitSpy = sinon.spy(cliRepl.bus, 'emit'); + cliRepl.config.disableLogging = true; + + await cliRepl.start(await testServer.connectionString(), {}); + + expect(cliRepl.getConfig('disableLogging')).is.true; + + expect(emitSpy).called; + expect(emitSpy).not.calledWith('mongosh:log-initialized'); + expect(cliRepl.logWriter).is.undefined; + }); + }); + context('analytics integration', function () { context('with network connectivity', function () { let srv: http.Server; @@ -1333,6 +1367,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 +1378,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: '🔑', diff --git a/packages/cli-repl/src/cli-repl.ts b/packages/cli-repl/src/cli-repl.ts index d3dd3d2e5c..c0da744b03 100644 --- a/packages/cli-repl/src/cli-repl.ts +++ b/packages/cli-repl/src/cli-repl.ts @@ -53,6 +53,7 @@ import type { DevtoolsProxyOptions, } from '@mongodb-js/devtools-proxy-support'; import { useOrCreateAgent } from '@mongodb-js/devtools-proxy-support'; +import { setupMongoLogWriter } from '@mongosh/logging/lib/setup-logger-and-telemetry'; /** * Connecting text key. @@ -256,6 +257,32 @@ export class CliRepl implements MongoshIOProvider { ); } + /** Setup log writer and start logging. */ + private async startLogging() { + 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; + this.logWriter = logger; + setupMongoLogWriter(logger); + this.logWriter = logger; + setupMongoLogWriter(logger); + markTime(TimingCategories.Logging, 'instantiated log writer'); + setupMongoLogWriter(logger); + this.bus.emit('mongosh:log-initialized'); + 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'); + } + /** * Setup CLI environment: serviceProvider, ShellEvaluator, log connection * information, external editor, and finally start the repl. @@ -267,7 +294,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,41 +330,24 @@ 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, { platform: process.platform, @@ -352,17 +363,23 @@ export class CliRepl implements MongoshIOProvider { 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'); + const disableLogging = this.getConfig('disableLogging'); + if (disableLogging !== true) { + await this.startLogging(); + } + // Needs to happen after loading the mongosh config file(s) void this.fetchMongoshUpdateUrl(); @@ -483,7 +500,7 @@ export class CliRepl implements MongoshIOProvider { if (!this.cliOptions.shell) { // We flush the telemetry data as part of exiting. Make sure we have // the right config value. - this.setTelemetryEnabled(await this.getConfig('enableTelemetry')); + this.setTelemetryEnabled(this.getConfig('enableTelemetry')); await this.exit(0); return; } @@ -516,10 +533,11 @@ export class CliRepl implements MongoshIOProvider { // We only enable/disable here, since the rc file/command line scripts // can disable the telemetry setting. - this.setTelemetryEnabled(await this.getConfig('enableTelemetry')); + this.setTelemetryEnabled(this.getConfig('enableTelemetry')); 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(), @@ -624,7 +642,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'); @@ -856,9 +874,7 @@ export class CliRepl implements MongoshIOProvider { * Implements getConfig from the {@link ConfigProvider} interface. */ // eslint-disable-next-line @typescript-eslint/require-await - async getConfig( - key: K - ): Promise { + getConfig(key: K): CliUserConfig[K] { return ( (this.config as CliUserConfig)[key] ?? (this.globalConfig as CliUserConfig)?.[key] ?? @@ -1259,7 +1275,7 @@ export class CliRepl implements MongoshIOProvider { } try { - const updateURL = (await this.getConfig('updateURL')).trim(); + const updateURL = this.getConfig('updateURL').trim(); if (!updateURL) return; const localFilePath = this.shellHomeDirectory.localPath( @@ -1284,7 +1300,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/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/multi-set.ts b/packages/logging/src/multi-set.ts new file mode 100644 index 0000000000..86e195f416 --- /dev/null +++ b/packages/logging/src/multi-set.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/setup-logger-and-telemetry.spec.ts b/packages/logging/src/setup-logger-and-telemetry.spec.ts index e0d0515766..90ffe8e47f 100644 --- a/packages/logging/src/setup-logger-and-telemetry.spec.ts +++ b/packages/logging/src/setup-logger-and-telemetry.spec.ts @@ -5,7 +5,8 @@ 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'; +import { setupMongoLogWriter, toSnakeCase } from './setup-logger-and-telemetry'; +import type { Writable } from 'stream'; describe('toSnakeCase', function () { const useCases = [ @@ -37,15 +38,21 @@ 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); + setupMongoLogWriter( + new MongoLogWriter({ + logId, + logFilePath: `/tmp/${logId}_log`, + target: { + write(chunk: string, cb: () => void) { + logOutput.push(JSON.parse(chunk)); + cb(); + }, + end(cb: () => void) { + cb(); + }, + } as Writable, + }) + ); const analytics = { identify(info: any) { analyticsOutput.push(['identify', info]); @@ -64,11 +71,77 @@ describe('setupLoggerAndTelemetry', function () { bus = new EventEmitter(); }); + it('accepts user ID at setup', function () { + setupLoggerAndTelemetry( + bus, + analytics, + { userId }, + { + 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', + }); + + expect(analyticsOutput).to.deep.equal([ + [ + 'track', + { + anonymousId: userId, + event: 'New Connection', + properties: { + mongosh_version: '1.0.0', + session_id: logId, + is_localhost: true, + is_atlas: false, + atlas_hostname: null, + node_version: 'v12.19.0', + }, + }, + ], + ]); + }); + + it('throws if an event occurs before the user is set', function () { + setupLoggerAndTelemetry( + bus, + analytics, + {}, + { + platform: process.platform, + arch: process.arch, + }, + '1.0.0' + ); + expect(logOutput).to.have.lengthOf(0); + expect(analyticsOutput).to.be.empty; + + expect(() => + bus.emit('mongosh:connect', { + uri: 'mongodb://localhost/', + is_localhost: true, + is_atlas: false, + resolved_hostname: 'localhost', + node_version: 'v12.19.0', + }) + ).throws('No telemetry identity found'); + }); + it('tracks new local connection events', function () { setupLoggerAndTelemetry( bus, - logger, analytics, + {}, { platform: process.platform, arch: process.arch, @@ -78,6 +151,8 @@ describe('setupLoggerAndTelemetry', function () { expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; + bus.emit('mongosh:new-user', { userId, anonymousId: userId }); + bus.emit('mongosh:connect', { uri: 'mongodb://localhost/', is_localhost: true, @@ -94,14 +169,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, @@ -115,8 +201,8 @@ describe('setupLoggerAndTelemetry', function () { it('tracks new atlas connection events', function () { setupLoggerAndTelemetry( bus, - logger, analytics, + {}, { platform: process.platform, arch: process.arch, @@ -126,6 +212,8 @@ describe('setupLoggerAndTelemetry', function () { expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; + bus.emit('mongosh:new-user', { userId, anonymousId: userId }); + bus.emit('mongosh:connect', { uri: 'mongodb://test-data-sets-a011bb.mongodb.net/', is_localhost: false, @@ -146,14 +234,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', @@ -167,8 +266,8 @@ describe('setupLoggerAndTelemetry', function () { it('tracks a sequence of events', function () { setupLoggerAndTelemetry( bus, - logger, analytics, + {}, { platform: process.platform, arch: process.arch, @@ -476,7 +575,7 @@ describe('setupLoggerAndTelemetry', function () { traits: { platform: process.platform, arch: process.arch, - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, }, ], @@ -487,7 +586,7 @@ describe('setupLoggerAndTelemetry', function () { traits: { platform: process.platform, arch: process.arch, - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, }, ], @@ -502,7 +601,7 @@ describe('setupLoggerAndTelemetry', function () { boxed_node_bindings: 50, node_repl: 100, mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, }, ], @@ -513,7 +612,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 +627,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 +642,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Use', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, }, ], @@ -554,7 +653,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Show', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, method: 'dbs', }, }, @@ -565,7 +664,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 +677,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 +689,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Mongoshrc Loaded', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, anonymousId: '53defe995fa47e6c13102d9d', }, @@ -601,7 +700,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Mongorc Warning', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, anonymousId: '53defe995fa47e6c13102d9d', }, @@ -612,7 +711,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 +724,7 @@ describe('setupLoggerAndTelemetry', function () { event: 'Snippet Install', properties: { mongosh_version: '1.0.0', - session_id: '5fb3c20ee1507e894e5340f3', + session_id: logId, }, }, ], @@ -633,7 +732,7 @@ describe('setupLoggerAndTelemetry', function () { }); it('buffers deprecated API calls', function () { - setupLoggerAndTelemetry(bus, logger, analytics, {}, '1.0.0'); + setupLoggerAndTelemetry(bus, analytics, {}, {}, '1.0.0'); expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; @@ -716,7 +815,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 +828,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 +841,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 +854,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 +868,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 +904,7 @@ describe('setupLoggerAndTelemetry', function () { }); it('does not track database calls outside of evaluate-{started,finished}', function () { - setupLoggerAndTelemetry(bus, logger, analytics, {}, '1.0.0'); + setupLoggerAndTelemetry(bus, analytics, {}, {}, '1.0.0'); expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; diff --git a/packages/logging/src/setup-logger-and-telemetry.ts b/packages/logging/src/setup-logger-and-telemetry.ts index c659d21b9e..05cd0e67ea 100644 --- a/packages/logging/src/setup-logger-and-telemetry.ts +++ b/packages/logging/src/setup-logger-and-telemetry.ts @@ -31,35 +31,19 @@ import type { FetchingUpdateMetadataEvent, FetchingUpdateMetadataCompleteEvent, SessionStartedEvent, - WriteCustomLogEvent, + MongoshBusEventsMap, } from '@mongosh/types'; import { inspect } from 'util'; -import type { MongoLogWriter } from 'mongodb-log-writer'; +import { MongoLogWriter } from 'mongodb-log-writer'; import { mongoLogId } from 'mongodb-log-writer'; -import type { MongoshAnalytics } from './analytics-helpers'; +import type { + AnalyticsIdentifyMessage, + MongoshAnalytics, + MongoshAnalyticsIdentity, +} 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]; - } - } -} +import { MultiSet } from './multi-set'; +import { Writable } from 'stream'; /** * It transforms a random string into snake case. Snake case is completely @@ -97,38 +81,86 @@ export function toSnakeCase(str: string): string { */ export function setupLoggerAndTelemetry( bus: MongoshBus, - log: MongoLogWriter, analytics: MongoshAnalytics, - userTraits: any, + providedTraits: { platform: string } & { + [key: string]: unknown; + }, mongosh_version: string -): void { +): { + setMongoLogWriter: (logger: MongoLogWriter) => void; +} { + const dummySink = new Writable({ + write(chunk, encoding, callback) { + callback(); + }, + }); + let log = new MongoLogWriter({ + logId: '', + logFilePath: null, + target: dummySink, + }); + + function setMongoLogWriter(logger: MongoLogWriter) { + log = logger; + } + const { logId: session_id } = log; let userId: string; let telemetryAnonymousId: string; + let pendingLogEvents: CallableFunction[] = []; - userTraits = { ...userTraits, session_id }; + const userTraits: AnalyticsIdentifyMessage['traits'] & { + [key: string]: unknown; + } = { + ...providedTraits, + session_id, + }; + + let hasMongoLogWriterInitialized = false; + + bus.on('mongosh:log-initialized', () => { + hasMongoLogWriterInitialized = true; + for (const ev of pendingLogEvents) { + ev(); + } + pendingLogEvents = []; + }); + const getTelemetryUserIdentity = (): MongoshAnalyticsIdentity => ({ + anonymousId: telemetryAnonymousId ?? userId, + }); const trackProperties = { mongosh_version, session_id, }; - const getTelemetryUserIdentity = () => ({ - anonymousId: telemetryAnonymousId ?? userId, - }); + // eslint-disable-next-line @typescript-eslint/no-explicit-any + function onBus( + event: keyof MongoshBusEventsMap, + listener: (...args: T) => void + ) { + bus.on(event, (...args: T) => { + if (hasMongoLogWriterInitialized) { + listener(...args); + } else { + pendingLogEvents.push(() => listener(...args)); + } + }); + } // 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) => { + onBus('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( + + onBus( 'mongosh:start-loading-cli-scripts', (event: StartLoadingCliScriptsEvent) => { log.info( @@ -141,18 +173,7 @@ 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) { + onBus('mongosh:connect', function (args: ConnectEvent) { const { uri, resolved_hostname, ...argsWithoutUriAndHostname } = args; const connectionUri = uri && redactURICredentials(uri); const atlasHostname = { @@ -184,7 +205,7 @@ export function setupLoggerAndTelemetry( }); }); - bus.on('mongosh:start-session', function (args: SessionStartedEvent) { + onBus('mongosh:start-session', function (args: SessionStartedEvent) { const normalisedTimingsArray = Object.entries(args.timings).map( ([key, duration]) => { const snakeCaseKey = toSnakeCase(key); @@ -205,7 +226,7 @@ export function setupLoggerAndTelemetry( }); }); - bus.on( + onBus( 'mongosh:new-user', function (newTelemetryUserIdentity: { userId: string; @@ -222,7 +243,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on( + onBus( 'mongosh:update-user', function (updatedTelemetryUserIdentity: { userId: string; @@ -241,7 +262,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on('mongosh:error', function (error: Error, context: string) { + onBus('mongosh:error', function (error: Error, context: string) { const mongoshError = error as { name: string; message: string; @@ -250,23 +271,13 @@ export function setupLoggerAndTelemetry( 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 - ); - } + log[context === 'fatal' ? 'fatal' : 'error']( + 'MONGOSH', + mongoLogId(1_000_000_006), + context, + `${mongoshError.name}: ${mongoshError.message}`, + error + ); if (error.name.includes('Mongosh')) { analytics.track({ @@ -283,7 +294,7 @@ export function setupLoggerAndTelemetry( } }); - bus.on( + onBus( 'mongosh:globalconfig-load', function (args: GlobalConfigFileLoadEvent) { log.info( @@ -296,7 +307,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on('mongosh:evaluate-input', function (args: EvaluateInputEvent) { + onBus('mongosh:evaluate-input', function (args: EvaluateInputEvent) { log.info( 'MONGOSH', mongoLogId(1_000_000_007), @@ -306,7 +317,7 @@ export function setupLoggerAndTelemetry( ); }); - bus.on('mongosh:use', function (args: UseEvent) { + onBus('mongosh:use', function (args: UseEvent) { log.info( 'MONGOSH', mongoLogId(1_000_000_008), @@ -324,7 +335,7 @@ export function setupLoggerAndTelemetry( }); }); - bus.on('mongosh:show', function (args: ShowEvent) { + onBus('mongosh:show', function (args: ShowEvent) { log.info( 'MONGOSH', mongoLogId(1_000_000_009), @@ -343,7 +354,7 @@ export function setupLoggerAndTelemetry( }); }); - bus.on('mongosh:setCtx', function (args: ApiEventWithArguments) { + onBus('mongosh:setCtx', function (args: ApiEventWithArguments) { log.info( 'MONGOSH', mongoLogId(1_000_000_010), @@ -353,7 +364,7 @@ export function setupLoggerAndTelemetry( ); }); - bus.on( + onBus( 'mongosh:api-call-with-arguments', function (args: ApiEventWithArguments) { // TODO: redactInfo cannot handle circular or otherwise nontrivial input @@ -373,7 +384,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on('mongosh:api-load-file', function (args: ScriptLoadFileEvent) { + onBus('mongosh:api-load-file', function (args: ScriptLoadFileEvent) { log.info( 'MONGOSH', mongoLogId(1_000_000_012), @@ -393,7 +404,7 @@ export function setupLoggerAndTelemetry( }); }); - bus.on('mongosh:eval-cli-script', function () { + onBus('mongosh:eval-cli-script', function () { log.info( 'MONGOSH', mongoLogId(1_000_000_013), @@ -411,7 +422,7 @@ export function setupLoggerAndTelemetry( }); }); - bus.on('mongosh:mongoshrc-load', function () { + onBus('mongosh:mongoshrc-load', function () { log.info( 'MONGOSH', mongoLogId(1_000_000_014), @@ -428,7 +439,7 @@ export function setupLoggerAndTelemetry( }); }); - bus.on('mongosh:mongoshrc-mongorc-warn', function () { + onBus('mongosh:mongoshrc-mongorc-warn', function () { log.info( 'MONGOSH', mongoLogId(1_000_000_015), @@ -445,7 +456,7 @@ export function setupLoggerAndTelemetry( }); }); - bus.on( + onBus( 'mongosh:crypt-library-load-skip', function (ev: CryptLibrarySkipEvent) { log.info( @@ -458,7 +469,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on( + onBus( 'mongosh:crypt-library-load-found', function (ev: CryptLibraryFoundEvent) { log.warn( @@ -474,7 +485,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on('mongosh-snippets:loaded', function (ev: SnippetsLoadedEvent) { + onBus('mongosh-snippets:loaded', function (ev: SnippetsLoadedEvent) { log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_019), @@ -484,7 +495,7 @@ export function setupLoggerAndTelemetry( ); }); - bus.on('mongosh-snippets:npm-lookup', function (ev: SnippetsNpmLookupEvent) { + onBus('mongosh-snippets:npm-lookup', function (ev: SnippetsNpmLookupEvent) { log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_020), @@ -494,7 +505,7 @@ export function setupLoggerAndTelemetry( ); }); - bus.on('mongosh-snippets:npm-lookup-stopped', function () { + onBus('mongosh-snippets:npm-lookup-stopped', function () { log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_021), @@ -503,7 +514,7 @@ export function setupLoggerAndTelemetry( ); }); - bus.on( + onBus( 'mongosh-snippets:npm-download-failed', function (ev: SnippetsNpmDownloadFailedEvent) { log.info( @@ -516,7 +527,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on( + onBus( 'mongosh-snippets:npm-download-active', function (ev: SnippetsNpmDownloadActiveEvent) { log.info( @@ -529,20 +540,17 @@ export function setupLoggerAndTelemetry( } ); - bus.on( - 'mongosh-snippets:fetch-index', - function (ev: SnippetsFetchIndexEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_024), - 'snippets', - 'Fetching snippet index', - ev - ); - } - ); + onBus('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 () { + onBus('mongosh-snippets:fetch-cache-invalid', function () { log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_025), @@ -551,7 +559,7 @@ export function setupLoggerAndTelemetry( ); }); - bus.on( + onBus( 'mongosh-snippets:fetch-index-error', function (ev: SnippetsFetchIndexErrorEvent) { log.info( @@ -564,7 +572,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on('mongosh-snippets:fetch-index-done', function () { + onBus('mongosh-snippets:fetch-index-done', function () { log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_027), @@ -573,7 +581,7 @@ export function setupLoggerAndTelemetry( ); }); - bus.on( + onBus( 'mongosh-snippets:package-json-edit-error', function (ev: SnippetsErrorEvent) { log.info( @@ -586,7 +594,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on('mongosh-snippets:spawn-child', function (ev: SnippetsRunNpmEvent) { + onBus('mongosh-snippets:spawn-child', function (ev: SnippetsRunNpmEvent) { log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_029), @@ -596,7 +604,7 @@ export function setupLoggerAndTelemetry( ); }); - bus.on( + onBus( 'mongosh-snippets:load-snippet', function (ev: SnippetsLoadSnippetEvent) { log.info( @@ -609,7 +617,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on( + onBus( 'mongosh-snippets:snippet-command', function (ev: SnippetsCommandEvent) { log.info( @@ -632,7 +640,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on( + onBus( 'mongosh-snippets:transform-error', function (ev: SnippetsTransformErrorEvent) { log.info( @@ -648,7 +656,7 @@ export function setupLoggerAndTelemetry( const deprecatedApiCalls = new MultiSet>(); const apiCalls = new MultiSet>(); let apiCallTrackingEnabled = false; - bus.on('mongosh:api-call', function (ev: ApiEvent) { + onBus('mongosh:api-call', function (ev: ApiEvent) { // Only track if we have previously seen a mongosh:evaluate-started call if (!apiCallTrackingEnabled) return; if (ev.deprecated) { @@ -658,7 +666,7 @@ export function setupLoggerAndTelemetry( apiCalls.add({ class: ev.class, method: ev.method }); } }); - bus.on('mongosh:evaluate-started', function () { + onBus('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, @@ -667,7 +675,7 @@ export function setupLoggerAndTelemetry( deprecatedApiCalls.clear(); apiCalls.clear(); }); - bus.on('mongosh:evaluate-finished', function () { + onBus('mongosh:evaluate-finished', function () { for (const [entry] of deprecatedApiCalls) { log.warn( 'MONGOSH', @@ -708,7 +716,7 @@ export function setupLoggerAndTelemetry( // eslint-disable-next-line @typescript-eslint/no-var-requires hookLogger(bus, log, 'mongosh', redactURICredentials); - bus.on('mongosh-sp:reset-connection-options', function () { + onBus('mongosh-sp:reset-connection-options', function () { log.info( 'MONGOSH-SP', mongoLogId(1_000_000_040), @@ -717,7 +725,7 @@ export function setupLoggerAndTelemetry( ); }); - bus.on( + onBus( 'mongosh-editor:run-edit-command', function (ev: EditorRunEditCommandEvent) { log.error( @@ -730,7 +738,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on( + onBus( 'mongosh-editor:read-vscode-extensions-done', function (ev: EditorReadVscodeExtensionsDoneEvent) { log.error( @@ -743,7 +751,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on( + onBus( 'mongosh-editor:read-vscode-extensions-failed', function (ev: EditorReadVscodeExtensionsFailedEvent) { log.error( @@ -759,7 +767,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on( + onBus( 'mongosh:fetching-update-metadata', function (ev: FetchingUpdateMetadataEvent) { log.info( @@ -774,7 +782,7 @@ export function setupLoggerAndTelemetry( } ); - bus.on( + onBus( 'mongosh:fetching-update-metadata-complete', function (ev: FetchingUpdateMetadataCompleteEvent) { log.info( @@ -792,4 +800,6 @@ export function setupLoggerAndTelemetry( // 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 + + return { setMongoLogWriter }; } diff --git a/packages/types/src/index.ts b/packages/types/src/index.ts index 9267eddc89..c9ae38c7d5 100644 --- a/packages/types/src/index.ts +++ b/packages/types/src/index.ts @@ -97,6 +97,13 @@ export interface MongocryptdLogEvent { logEntry: any; } +export interface WriteCustomLogEvent { + method: 'info' | 'error' | 'warn' | 'debug'; + message: string; + attr?: unknown; + level?: 1 | 2 | 3 | 4 | 5; +} + export interface StartMongoshReplEvent { version: string; } @@ -393,6 +400,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 +513,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 { From df08a2954139dd7d7bb282703cbad6848559d7ef Mon Sep 17 00:00:00 2001 From: gagik Date: Fri, 24 Jan 2025 17:43:35 +0100 Subject: [PATCH 02/15] refactor(cli-repl): use a object-oriented structure, hook loggers at initialization I think this refactor provides much better readability and provides an easier interface for us to test and debug the functionality of this. This also moves the hookLoggers call to the point of initialization as --- packages/cli-repl/src/cli-repl.spec.ts | 4 +- packages/cli-repl/src/cli-repl.ts | 20 +- packages/logging/src/helpers.spec.ts | 26 + .../logging/src/{multi-set.ts => helpers.ts} | 0 packages/logging/src/index.ts | 2 +- ....spec.ts => logging-and-telemetry.spec.ts} | 165 ++-- packages/logging/src/logging-and-telemetry.ts | 785 +++++++++++++++++ .../logging/src/setup-logger-and-telemetry.ts | 805 ------------------ packages/types/src/index.ts | 2 +- 9 files changed, 887 insertions(+), 922 deletions(-) create mode 100644 packages/logging/src/helpers.spec.ts rename packages/logging/src/{multi-set.ts => helpers.ts} (100%) rename packages/logging/src/{setup-logger-and-telemetry.spec.ts => logging-and-telemetry.spec.ts} (91%) create mode 100644 packages/logging/src/logging-and-telemetry.ts delete mode 100644 packages/logging/src/setup-logger-and-telemetry.ts diff --git a/packages/cli-repl/src/cli-repl.spec.ts b/packages/cli-repl/src/cli-repl.spec.ts index 6eac159152..e986a3f917 100644 --- a/packages/cli-repl/src/cli-repl.spec.ts +++ b/packages/cli-repl/src/cli-repl.spec.ts @@ -1326,7 +1326,7 @@ describe('CliRepl', function () { expect(cliRepl.getConfig('disableLogging')).is.false; - expect(emitSpy).calledWith('mongosh:log-initialized'); + expect(emitSpy).calledWith('mongosh:logger-initialized'); expect(cliRepl.logWriter).is.instanceOf(MongoLogWriter); }); @@ -1339,7 +1339,7 @@ describe('CliRepl', function () { expect(cliRepl.getConfig('disableLogging')).is.true; expect(emitSpy).called; - expect(emitSpy).not.calledWith('mongosh:log-initialized'); + expect(emitSpy).not.calledWith('mongosh:logger-initialized'); expect(cliRepl.logWriter).is.undefined; }); }); diff --git a/packages/cli-repl/src/cli-repl.ts b/packages/cli-repl/src/cli-repl.ts index c0da744b03..ff54cf70fe 100644 --- a/packages/cli-repl/src/cli-repl.ts +++ b/packages/cli-repl/src/cli-repl.ts @@ -31,10 +31,10 @@ import { MongoLogManager, mongoLogId } from 'mongodb-log-writer'; import type { MongoshNodeReplOptions, MongoshIOProvider } from './mongosh-repl'; import MongoshNodeRepl from './mongosh-repl'; import { - setupLoggerAndTelemetry, ToggleableAnalytics, ThrottledAnalytics, SampledAnalytics, + MongoshLoggingAndTelemetry, } from '@mongosh/logging'; import type { MongoshBus } from '@mongosh/types'; import { @@ -53,7 +53,6 @@ import type { DevtoolsProxyOptions, } from '@mongodb-js/devtools-proxy-support'; import { useOrCreateAgent } from '@mongodb-js/devtools-proxy-support'; -import { setupMongoLogWriter } from '@mongosh/logging/lib/setup-logger-and-telemetry'; /** * Connecting text key. @@ -258,7 +257,7 @@ export class CliRepl implements MongoshIOProvider { } /** Setup log writer and start logging. */ - private async startLogging() { + private async startLogging(loggingAndTelemetry: MongoshLoggingAndTelemetry) { await this.logManager.cleanupOldLogFiles(); markTime(TimingCategories.Logging, 'cleaned up log files'); const logger = await this.logManager.createLogWriter(); @@ -268,13 +267,10 @@ export class CliRepl implements MongoshIOProvider { } this.logWriter = logger; - this.logWriter = logger; - setupMongoLogWriter(logger); - this.logWriter = logger; - setupMongoLogWriter(logger); + loggingAndTelemetry.setupLogger(logger); + markTime(TimingCategories.Logging, 'instantiated log writer'); - setupMongoLogWriter(logger); - this.bus.emit('mongosh:log-initialized'); + this.bus.emit('mongosh:logger-initialized'); logger.info('MONGOSH', mongoLogId(1_000_000_000), 'log', 'Starting log', { execPath: process.execPath, envInfo: redactSensitiveData(this.getLoggedEnvironmentVariables()), @@ -346,7 +342,7 @@ export class CliRepl implements MongoshIOProvider { markTime(TimingCategories.Telemetry, 'created analytics instance'); - setupLoggerAndTelemetry( + const loggingAndTelemetry = new MongoshLoggingAndTelemetry( this.bus, this.toggleableAnalytics, { @@ -357,6 +353,8 @@ export class CliRepl implements MongoshIOProvider { }, version ); + loggingAndTelemetry.setup(); + markTime(TimingCategories.Telemetry, 'completed telemetry setup'); if (analyticsSetupError) { @@ -377,7 +375,7 @@ export class CliRepl implements MongoshIOProvider { const disableLogging = this.getConfig('disableLogging'); if (disableLogging !== true) { - await this.startLogging(); + await this.startLogging(loggingAndTelemetry); } // Needs to happen after loading the mongosh config file(s) 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/multi-set.ts b/packages/logging/src/helpers.ts similarity index 100% rename from packages/logging/src/multi-set.ts rename to packages/logging/src/helpers.ts diff --git a/packages/logging/src/index.ts b/packages/logging/src/index.ts index 263682d08f..d14b18af7a 100644 --- a/packages/logging/src/index.ts +++ b/packages/logging/src/index.ts @@ -1,4 +1,4 @@ -export { setupLoggerAndTelemetry } from './setup-logger-and-telemetry'; +export { MongoshLoggingAndTelemetry } from './logging-and-telemetry'; export { MongoshAnalytics, ToggleableAnalytics, diff --git a/packages/logging/src/setup-logger-and-telemetry.spec.ts b/packages/logging/src/logging-and-telemetry.spec.ts similarity index 91% rename from packages/logging/src/setup-logger-and-telemetry.spec.ts rename to packages/logging/src/logging-and-telemetry.spec.ts index 90ffe8e47f..8b27e62465 100644 --- a/packages/logging/src/setup-logger-and-telemetry.spec.ts +++ b/packages/logging/src/logging-and-telemetry.spec.ts @@ -1,36 +1,13 @@ /* 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 { setupMongoLogWriter, toSnakeCase } from './setup-logger-and-telemetry'; import type { Writable } from 'stream'; +import { MongoshLoggingAndTelemetry } from './logging-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); - }); - } -}); - -describe('setupLoggerAndTelemetry', function () { +describe('MongoshLoggingAndTelemetry', function () { let logOutput: any[]; let analyticsOutput: ['identify' | 'track' | 'log', any][]; let bus: MongoshBus; @@ -38,21 +15,16 @@ describe('setupLoggerAndTelemetry', function () { const userId = '53defe995fa47e6c13102d9d'; const logId = '5fb3c20ee1507e894e5340f3'; - setupMongoLogWriter( - new MongoLogWriter({ - logId, - logFilePath: `/tmp/${logId}_log`, - target: { - write(chunk: string, cb: () => void) { - logOutput.push(JSON.parse(chunk)); - cb(); - }, - end(cb: () => void) { - cb(); - }, - } as Writable, - }) - ); + const logger = new MongoLogWriter(logId, `/tmp/${logId}_log`, { + write(chunk: string, cb: () => void) { + logOutput.push(JSON.parse(chunk)); + cb(); + }, + end(cb: () => void) { + cb(); + }, + } as Writable); + const analytics = { identify(info: any) { analyticsOutput.push(['identify', info]); @@ -71,87 +43,41 @@ describe('setupLoggerAndTelemetry', function () { bus = new EventEmitter(); }); - it('accepts user ID at setup', function () { - setupLoggerAndTelemetry( + it('throws when trying to setup writer prematurely', function () { + const loggingAndTelemetry = new MongoshLoggingAndTelemetry( bus, analytics, - { userId }, { 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', - }); - expect(analyticsOutput).to.deep.equal([ - [ - 'track', - { - anonymousId: userId, - event: 'New Connection', - properties: { - mongosh_version: '1.0.0', - session_id: logId, - is_localhost: true, - is_atlas: false, - atlas_hostname: null, - node_version: 'v12.19.0', - }, - }, - ], - ]); - }); - - it('throws if an event occurs before the user is set', function () { - setupLoggerAndTelemetry( - bus, - analytics, - {}, - { - platform: process.platform, - arch: process.arch, - }, - '1.0.0' + expect(() => loggingAndTelemetry.setupLogger(logger)).throws( + 'Run setup() before setting up the log writer.' ); - expect(logOutput).to.have.lengthOf(0); - expect(analyticsOutput).to.be.empty; - - expect(() => - bus.emit('mongosh:connect', { - uri: 'mongodb://localhost/', - is_localhost: true, - is_atlas: false, - resolved_hostname: 'localhost', - node_version: 'v12.19.0', - }) - ).throws('No telemetry identity found'); }); it('tracks new local connection events', function () { - setupLoggerAndTelemetry( + const loggingAndTelemetry = new MongoshLoggingAndTelemetry( bus, analytics, - {}, { platform: process.platform, arch: process.arch, }, '1.0.0' ); + + loggingAndTelemetry.setup(); + loggingAndTelemetry.setupLogger(logger); + expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; bus.emit('mongosh:new-user', { userId, anonymousId: userId }); + bus.emit('mongosh:logger-initialized'); bus.emit('mongosh:connect', { uri: 'mongodb://localhost/', @@ -199,20 +125,24 @@ describe('setupLoggerAndTelemetry', function () { }); it('tracks new atlas connection events', function () { - setupLoggerAndTelemetry( + const loggingAndTelemetry = new MongoshLoggingAndTelemetry( bus, analytics, - {}, { platform: process.platform, arch: process.arch, }, '1.0.0' ); + + loggingAndTelemetry.setup(); + loggingAndTelemetry.setupLogger(logger); + expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; bus.emit('mongosh:new-user', { userId, anonymousId: userId }); + bus.emit('mongosh:logger-initialized'); bus.emit('mongosh:connect', { uri: 'mongodb://test-data-sets-a011bb.mongodb.net/', @@ -264,20 +194,25 @@ describe('setupLoggerAndTelemetry', function () { }); it('tracks a sequence of events', function () { - setupLoggerAndTelemetry( + const loggingAndTelemetry = new MongoshLoggingAndTelemetry( bus, analytics, - {}, { platform: process.platform, arch: process.arch, }, '1.0.0' ); + + loggingAndTelemetry.setup(); + loggingAndTelemetry.setupLogger(logger); + expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; bus.emit('mongosh:new-user', { userId, anonymousId: userId }); + bus.emit('mongosh:logger-initialized'); + bus.emit('mongosh:update-user', { userId, anonymousId: userId }); bus.emit('mongosh:start-session', { isInteractive: true, @@ -732,11 +667,25 @@ describe('setupLoggerAndTelemetry', function () { }); it('buffers deprecated API calls', function () { - setupLoggerAndTelemetry(bus, analytics, {}, {}, '1.0.0'); + const loggingAndTelemetry = new MongoshLoggingAndTelemetry( + bus, + analytics, + { + platform: process.platform, + arch: process.arch, + }, + '1.0.0' + ); + + loggingAndTelemetry.setup(); + loggingAndTelemetry.setupLogger(logger); + expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; bus.emit('mongosh:new-user', { userId, anonymousId: userId }); + bus.emit('mongosh:logger-initialized'); + bus.emit('mongosh:evaluate-started'); logOutput = []; @@ -904,7 +853,19 @@ describe('setupLoggerAndTelemetry', function () { }); it('does not track database calls outside of evaluate-{started,finished}', function () { - setupLoggerAndTelemetry(bus, analytics, {}, {}, '1.0.0'); + const loggingAndTelemetry = new MongoshLoggingAndTelemetry( + bus, + analytics, + { + platform: process.platform, + arch: process.arch, + }, + '1.0.0' + ); + + loggingAndTelemetry.setup(); + loggingAndTelemetry.setupLogger(logger); + expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; diff --git a/packages/logging/src/logging-and-telemetry.ts b/packages/logging/src/logging-and-telemetry.ts new file mode 100644 index 0000000000..8dfd53b134 --- /dev/null +++ b/packages/logging/src/logging-and-telemetry.ts @@ -0,0 +1,785 @@ +/* eslint prefer-arrow-callback: "error" */ +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, +} 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 { hookLogger } from '@mongodb-js/devtools-connect'; +import { MultiSet, toSnakeCase } from './helpers'; +import { Writable } from 'stream'; + +export class MongoshLoggingAndTelemetry { + log: MongoLogWriter; + pendingLogEvents: CallableFunction[] = []; + + telemetryAnonymousId: string | undefined; + userId: string | undefined; + trackingProperties: { + mongosh_version: string; + session_id: string; + }; + userTraits: AnalyticsIdentifyMessage['traits'] & { + [key: string]: unknown; + }; + + isSetup = false; + hasMongoLogWriterInitialized = false; + + constructor( + public bus: MongoshBus, + public analytics: MongoshAnalytics, + public providedTraits: { platform: string } & { + [key: string]: unknown; + }, + mongoshVersion: string + ) { + const dummySink = new Writable({ + write(chunk, encoding, callback) { + callback(); + }, + }); + this.log = new MongoLogWriter('', null, dummySink); + + this.userTraits = { + ...providedTraits, + session_id: this.log.logId, + }; + + this.trackingProperties = { + mongosh_version: mongoshVersion, + session_id: this.log.logId, + }; + } + + public setup() { + this._setupBusEventListeners(); + this.isSetup = true; + } + + public setupLogger(logger: MongoLogWriter) { + if (!this.isSetup) { + throw new Error('Run setup() before setting up the log writer.'); + } + this.log = logger; + + this.userTraits.session_id = this.log.logId; + this.trackingProperties.session_id = this.log.logId; + } + + public getTelemetryUserIdentity = (): MongoshAnalyticsIdentity => ({ + anonymousId: this.telemetryAnonymousId ?? (this.userId as string), + }); + + /** Start processing pending events after mongosh:logger-initialized */ + private onLoggerInitialized() { + this.hasMongoLogWriterInitialized = true; + for (const pendingEvent of this.pendingLogEvents) { + pendingEvent(); + } + this.pendingLogEvents = []; + + hookLogger(this.bus, this.log, 'mongosh', (uri) => + redactURICredentials(uri) + ); + } + + private _setupBusEventListeners() { + this.bus.on( + 'mongosh:logger-initialized', + this.onLoggerInitialized.bind(this) + ); + + // eslint-disable-next-line @typescript-eslint/no-explicit-any + const onBus = ( + event: keyof MongoshBusEventsMap, + listener: (...args: T) => void + ) => { + this.bus.on(event, (...args: T) => { + if (this.hasMongoLogWriterInitialized) { + listener(...args); + } else { + this.pendingLogEvents.push(() => listener(...args)); + } + }); + }; + + // 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; + + /* eslint prefer-arrow-callback: "error" */ + onBus('mongosh:start-mongosh-repl', (ev: StartMongoshReplEvent) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_002), + 'repl', + 'Started REPL', + ev + ); + hasStartedMongoshRepl = true; + }); + + let usesShellOption = false; + + onBus( + 'mongosh:start-loading-cli-scripts', + (event: StartLoadingCliScriptsEvent) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_003), + 'repl', + 'Start loading CLI scripts' + ); + 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 = { + ...this.trackingProperties, + ...argsWithoutUriAndHostname, + ...atlasHostname, + }; + + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_004), + 'connect', + 'Connecting to server', + { + userId: this.userId, + telemetryAnonymousId: this.telemetryAnonymousId, + connectionUri, + ...properties, + } + ); + + this.analytics.track({ + ...this.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({ + ...this.getTelemetryUserIdentity(), + event: 'Startup Time', + properties: { + ...this.trackingProperties, + is_interactive: args.isInteractive, + js_context: args.jsContext, + ...normalizedTimings, + }, + }); + }); + + onBus( + 'mongosh:new-user', + (newTelemetryUserIdentity: { userId: string; anonymousId: string }) => { + if (!newTelemetryUserIdentity.anonymousId) { + this.userId = newTelemetryUserIdentity.userId; + } + this.telemetryAnonymousId = newTelemetryUserIdentity.anonymousId; + this.analytics.identify({ + anonymousId: newTelemetryUserIdentity.anonymousId, + traits: this.userTraits, + }); + } + ); + + onBus( + 'mongosh:update-user', + (updatedTelemetryUserIdentity: { + userId: string; + anonymousId?: string; + }) => { + if (updatedTelemetryUserIdentity.anonymousId) { + this.telemetryAnonymousId = updatedTelemetryUserIdentity.anonymousId; + } else { + this.userId = updatedTelemetryUserIdentity.userId; + } + this.analytics.identify({ + ...this.getTelemetryUserIdentity(), + traits: this.userTraits, + }); + 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({ + ...this.getTelemetryUserIdentity(), + event: 'Error', + properties: { + ...this.trackingProperties, + name: mongoshError.name, + code: mongoshError.code, + scope: mongoshError.scope, + metadata: mongoshError.metadata, + }, + }); + } + }); + + 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({ + ...this.getTelemetryUserIdentity(), + event: 'Use', + properties: { + ...this.trackingProperties, + }, + }); + }); + + onBus('mongosh:show', (args: ShowEvent) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_009), + 'shell-api', + 'Used "show" command', + args + ); + + this.analytics.track({ + ...this.getTelemetryUserIdentity(), + event: 'Show', + properties: { + ...this.trackingProperties, + 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({ + ...this.getTelemetryUserIdentity(), + event: hasStartedMongoshRepl ? 'Script Loaded' : 'Script Loaded CLI', + properties: { + ...this.trackingProperties, + nested: args.nested, + ...(hasStartedMongoshRepl ? {} : { shell: 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({ + ...this.getTelemetryUserIdentity(), + event: 'Script Evaluated', + properties: { + ...this.trackingProperties, + shell: usesShellOption, + }, + }); + }); + + onBus('mongosh:mongoshrc-load', () => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_014), + 'repl', + 'Loading .mongoshrc.js' + ); + + this.analytics.track({ + ...this.getTelemetryUserIdentity(), + event: 'Mongoshrc Loaded', + properties: { + ...this.trackingProperties, + }, + }); + }); + + 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({ + ...this.getTelemetryUserIdentity(), + event: 'Mongorc Warning', + properties: { + ...this.trackingProperties, + }, + }); + }); + + 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({ + ...this.getTelemetryUserIdentity(), + event: 'Snippet Install', + properties: { + ...this.trackingProperties, + }, + }); + } + }); + + onBus( + 'mongosh-snippets:transform-error', + (ev: SnippetsTransformErrorEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_032), + 'snippets', + 'Rewrote error message', + ev + ); + } + ); + + const deprecatedApiCalls = new MultiSet< + Pick + >(); + const apiCalls = new MultiSet>(); + let apiCallTrackingEnabled = false; + onBus('mongosh:api-call', (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 }); + } + }); + onBus('mongosh:evaluate-started', () => { + 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(); + }); + onBus('mongosh:evaluate-finished', () => { + for (const [entry] of deprecatedApiCalls) { + this.log.warn( + 'MONGOSH', + mongoLogId(1_000_000_033), + 'shell-api', + 'Deprecated API call', + entry + ); + + this.analytics.track({ + ...this.getTelemetryUserIdentity(), + event: 'Deprecated Method', + properties: { + ...this.trackingProperties, + ...entry, + }, + }); + } + for (const [entry, count] of apiCalls) { + this.analytics.track({ + ...this.getTelemetryUserIdentity(), + event: 'API Call', + properties: { + ...this.trackingProperties, + ...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 + + 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, + } + ); + } + ); + } +} 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 05cd0e67ea..0000000000 --- a/packages/logging/src/setup-logger-and-telemetry.ts +++ /dev/null @@ -1,805 +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, - MongoshBusEventsMap, -} 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 { hookLogger } from '@mongodb-js/devtools-connect'; -import { MultiSet } from './multi-set'; -import { Writable } from 'stream'; - -/** - * 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, - analytics: MongoshAnalytics, - providedTraits: { platform: string } & { - [key: string]: unknown; - }, - mongosh_version: string -): { - setMongoLogWriter: (logger: MongoLogWriter) => void; -} { - const dummySink = new Writable({ - write(chunk, encoding, callback) { - callback(); - }, - }); - let log = new MongoLogWriter({ - logId: '', - logFilePath: null, - target: dummySink, - }); - - function setMongoLogWriter(logger: MongoLogWriter) { - log = logger; - } - - const { logId: session_id } = log; - let userId: string; - let telemetryAnonymousId: string; - let pendingLogEvents: CallableFunction[] = []; - - const userTraits: AnalyticsIdentifyMessage['traits'] & { - [key: string]: unknown; - } = { - ...providedTraits, - session_id, - }; - - let hasMongoLogWriterInitialized = false; - - bus.on('mongosh:log-initialized', () => { - hasMongoLogWriterInitialized = true; - for (const ev of pendingLogEvents) { - ev(); - } - pendingLogEvents = []; - }); - - const getTelemetryUserIdentity = (): MongoshAnalyticsIdentity => ({ - anonymousId: telemetryAnonymousId ?? userId, - }); - const trackProperties = { - mongosh_version, - session_id, - }; - - // eslint-disable-next-line @typescript-eslint/no-explicit-any - function onBus( - event: keyof MongoshBusEventsMap, - listener: (...args: T) => void - ) { - bus.on(event, (...args: T) => { - if (hasMongoLogWriterInitialized) { - listener(...args); - } else { - pendingLogEvents.push(() => listener(...args)); - } - }); - } - - // 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; - onBus('mongosh:start-mongosh-repl', (ev: StartMongoshReplEvent) => { - log.info('MONGOSH', mongoLogId(1_000_000_002), 'repl', 'Started REPL', ev); - hasStartedMongoshRepl = true; - }); - - let usesShellOption = false; - - onBus( - 'mongosh:start-loading-cli-scripts', - (event: StartLoadingCliScriptsEvent) => { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_003), - 'repl', - 'Start loading CLI scripts' - ); - usesShellOption = event.usesShellOption; - } - ); - - onBus('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, - }); - }); - - onBus('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, - }, - }); - }); - - onBus( - '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, - }); - } - ); - - onBus( - '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'); - } - ); - - onBus('mongosh:error', function (error: Error, context: string) { - const mongoshError = error as { - name: string; - message: string; - code: any; - scope: any; - metadata: any; - }; - - log[context === 'fatal' ? 'fatal' : '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, - }, - }); - } - }); - - onBus( - 'mongosh:globalconfig-load', - function (args: GlobalConfigFileLoadEvent) { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_048), - 'config', - 'Loading global configuration file', - args - ); - } - ); - - onBus('mongosh:evaluate-input', function (args: EvaluateInputEvent) { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_007), - 'repl', - 'Evaluating input', - args - ); - }); - - onBus('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, - }, - }); - }); - - onBus('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, - }, - }); - }); - - onBus('mongosh:setCtx', function (args: ApiEventWithArguments) { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_010), - 'shell-api', - 'Initialized context', - args - ); - }); - - onBus( - '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) - ); - } - ); - - onBus('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 }), - }, - }); - }); - - onBus('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, - }, - }); - }); - - onBus('mongosh:mongoshrc-load', function () { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_014), - 'repl', - 'Loading .mongoshrc.js' - ); - - analytics.track({ - ...getTelemetryUserIdentity(), - event: 'Mongoshrc Loaded', - properties: { - ...trackProperties, - }, - }); - }); - - onBus('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, - }, - }); - }); - - onBus( - 'mongosh:crypt-library-load-skip', - function (ev: CryptLibrarySkipEvent) { - log.info( - 'AUTO-ENCRYPTION', - mongoLogId(1_000_000_050), - 'crypt-library', - 'Skipping shared library candidate', - ev - ); - } - ); - - onBus( - '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, - } - ); - } - ); - - onBus('mongosh-snippets:loaded', function (ev: SnippetsLoadedEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_019), - 'snippets', - 'Loaded snippets', - ev - ); - }); - - onBus('mongosh-snippets:npm-lookup', function (ev: SnippetsNpmLookupEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_020), - 'snippets', - 'Performing npm lookup', - ev - ); - }); - - onBus('mongosh-snippets:npm-lookup-stopped', function () { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_021), - 'snippets', - 'npm lookup stopped' - ); - }); - - onBus( - 'mongosh-snippets:npm-download-failed', - function (ev: SnippetsNpmDownloadFailedEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_022), - 'snippets', - 'npm download failed', - ev - ); - } - ); - - onBus( - 'mongosh-snippets:npm-download-active', - function (ev: SnippetsNpmDownloadActiveEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_023), - 'snippets', - 'npm download active', - ev - ); - } - ); - - onBus('mongosh-snippets:fetch-index', function (ev: SnippetsFetchIndexEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_024), - 'snippets', - 'Fetching snippet index', - ev - ); - }); - - onBus('mongosh-snippets:fetch-cache-invalid', function () { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_025), - 'snippets', - 'Snippet cache invalid' - ); - }); - - onBus( - 'mongosh-snippets:fetch-index-error', - function (ev: SnippetsFetchIndexErrorEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_026), - 'snippets', - 'Fetching snippet index failed', - ev - ); - } - ); - - onBus('mongosh-snippets:fetch-index-done', function () { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_027), - 'snippets', - 'Fetching snippet index done' - ); - }); - - onBus( - '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 - ); - } - ); - - onBus('mongosh-snippets:spawn-child', function (ev: SnippetsRunNpmEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_029), - 'snippets', - 'Spawning helper', - ev - ); - }); - - onBus( - 'mongosh-snippets:load-snippet', - function (ev: SnippetsLoadSnippetEvent) { - log.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_030), - 'snippets', - 'Loading snippet', - ev - ); - } - ); - - onBus( - '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, - }, - }); - } - } - ); - - onBus( - '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; - onBus('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 }); - } - }); - onBus('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(); - }); - onBus('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); - - onBus('mongosh-sp:reset-connection-options', function () { - log.info( - 'MONGOSH-SP', - mongoLogId(1_000_000_040), - 'connect', - 'Reconnect because of changed connection options' - ); - }); - - onBus( - 'mongosh-editor:run-edit-command', - function (ev: EditorRunEditCommandEvent) { - log.error( - 'MONGOSH-EDITOR', - mongoLogId(1_000_000_047), - 'editor', - 'Open external editor', - redactInfo(ev) - ); - } - ); - - onBus( - '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 - ); - } - ); - - onBus( - '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, - } - ); - } - ); - - onBus( - 'mongosh:fetching-update-metadata', - function (ev: FetchingUpdateMetadataEvent) { - log.info( - 'MONGOSH', - mongoLogId(1_000_000_052), - 'startup', - 'Fetching update metadata', - { - ...ev, - } - ); - } - ); - - onBus( - '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 - - return { setMongoLogWriter }; -} diff --git a/packages/types/src/index.ts b/packages/types/src/index.ts index c9ae38c7d5..e761ac234b 100644 --- a/packages/types/src/index.ts +++ b/packages/types/src/index.ts @@ -401,7 +401,7 @@ export interface MongoshBusEventsMap extends ConnectEventMap { ev: FetchingUpdateMetadataCompleteEvent ) => void; /** Signals that logging has been initialized. */ - 'mongosh:log-initialized': () => void; + 'mongosh:logger-initialized': () => void; } export interface MongoshBus { From 71ce8b54cd668aabf7c90164199b9937463915e5 Mon Sep 17 00:00:00 2001 From: gagik Date: Sun, 26 Jan 2025 22:50:29 +0100 Subject: [PATCH 03/15] fix(tests): add validation for CliUserConfig Adds validation for the disableLogging field and fixes the equivalent test. --- packages/types/src/index.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/packages/types/src/index.ts b/packages/types/src/index.ts index e761ac234b..e0b00dc70f 100644 --- a/packages/types/src/index.ts +++ b/packages/types/src/index.ts @@ -540,6 +540,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') { From 23d3f2190fa5e048350ec580a3e4a7af22a65000 Mon Sep 17 00:00:00 2001 From: gagik Date: Mon, 27 Jan 2025 13:43:05 +0100 Subject: [PATCH 04/15] refactor(cli-repl): apply changes from review Use async getConfig, add return types, remove unnecessary eslint comments, move bus variables into class state, use explicit private and public fields. --- packages/cli-repl/src/cli-repl.ts | 16 +- packages/logging/src/logging-and-telemetry.ts | 141 +++++++++--------- 2 files changed, 82 insertions(+), 75 deletions(-) diff --git a/packages/cli-repl/src/cli-repl.ts b/packages/cli-repl/src/cli-repl.ts index ff54cf70fe..81c3b766a3 100644 --- a/packages/cli-repl/src/cli-repl.ts +++ b/packages/cli-repl/src/cli-repl.ts @@ -257,7 +257,9 @@ export class CliRepl implements MongoshIOProvider { } /** Setup log writer and start logging. */ - private async startLogging(loggingAndTelemetry: MongoshLoggingAndTelemetry) { + private async startLogging( + loggingAndTelemetry: MongoshLoggingAndTelemetry + ): Promise { await this.logManager.cleanupOldLogFiles(); markTime(TimingCategories.Logging, 'cleaned up log files'); const logger = await this.logManager.createLogWriter(); @@ -373,7 +375,7 @@ export class CliRepl implements MongoshIOProvider { this.globalConfig = await this.loadGlobalConfigFile(); markTime(TimingCategories.UserConfigLoading, 'read global config files'); - const disableLogging = this.getConfig('disableLogging'); + const disableLogging = await this.getConfig('disableLogging'); if (disableLogging !== true) { await this.startLogging(loggingAndTelemetry); } @@ -498,7 +500,7 @@ export class CliRepl implements MongoshIOProvider { if (!this.cliOptions.shell) { // We flush the telemetry data as part of exiting. Make sure we have // the right config value. - this.setTelemetryEnabled(this.getConfig('enableTelemetry')); + this.setTelemetryEnabled(await this.getConfig('enableTelemetry')); await this.exit(0); return; } @@ -531,7 +533,7 @@ export class CliRepl implements MongoshIOProvider { // We only enable/disable here, since the rc file/command line scripts // can disable the telemetry setting. - this.setTelemetryEnabled(this.getConfig('enableTelemetry')); + this.setTelemetryEnabled(await this.getConfig('enableTelemetry')); this.bus.emit('mongosh:start-mongosh-repl', { version }); markTime(TimingCategories.REPLInstantiation, 'starting repl'); await this.mongoshRepl.startRepl(initialized); @@ -872,7 +874,9 @@ export class CliRepl implements MongoshIOProvider { * Implements getConfig from the {@link ConfigProvider} interface. */ // eslint-disable-next-line @typescript-eslint/require-await - getConfig(key: K): CliUserConfig[K] { + async getConfig( + key: K + ): Promise { return ( (this.config as CliUserConfig)[key] ?? (this.globalConfig as CliUserConfig)?.[key] ?? @@ -1273,7 +1277,7 @@ export class CliRepl implements MongoshIOProvider { } try { - const updateURL = this.getConfig('updateURL').trim(); + const updateURL = (await this.getConfig('updateURL')).trim(); if (!updateURL) return; const localFilePath = this.shellHomeDirectory.localPath( diff --git a/packages/logging/src/logging-and-telemetry.ts b/packages/logging/src/logging-and-telemetry.ts index 8dfd53b134..e0d65e3bf4 100644 --- a/packages/logging/src/logging-and-telemetry.ts +++ b/packages/logging/src/logging-and-telemetry.ts @@ -1,4 +1,3 @@ -/* eslint prefer-arrow-callback: "error" */ import redactInfo from 'mongodb-redact'; import { redactURICredentials } from '@mongosh/history'; import type { @@ -47,26 +46,27 @@ import { MultiSet, toSnakeCase } from './helpers'; import { Writable } from 'stream'; export class MongoshLoggingAndTelemetry { - log: MongoLogWriter; - pendingLogEvents: CallableFunction[] = []; - - telemetryAnonymousId: string | undefined; - userId: string | undefined; - trackingProperties: { + private readonly trackingProperties: { mongosh_version: string; session_id: string; }; - userTraits: AnalyticsIdentifyMessage['traits'] & { + private readonly userTraits: AnalyticsIdentifyMessage['traits'] & { [key: string]: unknown; }; - isSetup = false; - hasMongoLogWriterInitialized = false; + private log: MongoLogWriter; + private pendingLogEvents: CallableFunction[] = []; + + private telemetryAnonymousId: string | undefined; + private userId: string | undefined; + + private isSetup = false; + private hasMongoLogWriterInitialized = false; constructor( - public bus: MongoshBus, - public analytics: MongoshAnalytics, - public providedTraits: { platform: string } & { + public readonly bus: MongoshBus, + public readonly analytics: MongoshAnalytics, + providedTraits: { platform: string } & { [key: string]: unknown; }, mongoshVersion: string @@ -89,27 +89,23 @@ export class MongoshLoggingAndTelemetry { }; } - public setup() { + public setup(): void { this._setupBusEventListeners(); this.isSetup = true; } - public setupLogger(logger: MongoLogWriter) { + public setupLogger(logger: MongoLogWriter): void { if (!this.isSetup) { throw new Error('Run setup() before setting up the log writer.'); } + if (this.hasMongoLogWriterInitialized) { + throw new Error('Logger has already been initialized.'); + } this.log = logger; this.userTraits.session_id = this.log.logId; this.trackingProperties.session_id = this.log.logId; - } - - public getTelemetryUserIdentity = (): MongoshAnalyticsIdentity => ({ - anonymousId: this.telemetryAnonymousId ?? (this.userId as string), - }); - /** Start processing pending events after mongosh:logger-initialized */ - private onLoggerInitialized() { this.hasMongoLogWriterInitialized = true; for (const pendingEvent of this.pendingLogEvents) { pendingEvent(); @@ -119,35 +115,43 @@ export class MongoshLoggingAndTelemetry { hookLogger(this.bus, this.log, 'mongosh', (uri) => redactURICredentials(uri) ); + + this.bus.emit('mongosh:logger-initialized'); } - private _setupBusEventListeners() { - this.bus.on( - 'mongosh:logger-initialized', - this.onLoggerInitialized.bind(this) - ); + private _getTelemetryUserIdentity(): MongoshAnalyticsIdentity { + return { + anonymousId: this.telemetryAnonymousId ?? (this.userId as string), + }; + } + + /** 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. */ + private hasStartedMongoshRepl = false; + + private apiCallTracking = { + isEnabled: false, + apiCalls: new MultiSet>(), + deprecatedApiCalls: new MultiSet>(), + }; + private usesShellOption = false; - // eslint-disable-next-line @typescript-eslint/no-explicit-any - const onBus = ( - event: keyof MongoshBusEventsMap, - listener: (...args: T) => void + private _setupBusEventListeners(): void { + const onBus = ( + event: K, + listener: (...args: Parameters) => void ) => { - this.bus.on(event, (...args: T) => { + this.bus.on(event, ((...args: Parameters) => { if (this.hasMongoLogWriterInitialized) { listener(...args); } else { this.pendingLogEvents.push(() => listener(...args)); } - }); + }) as MongoshBusEventsMap[K]); }; - // 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; - - /* eslint prefer-arrow-callback: "error" */ onBus('mongosh:start-mongosh-repl', (ev: StartMongoshReplEvent) => { this.log.info( 'MONGOSH', @@ -156,11 +160,9 @@ export class MongoshLoggingAndTelemetry { 'Started REPL', ev ); - hasStartedMongoshRepl = true; + this.hasStartedMongoshRepl = true; }); - let usesShellOption = false; - onBus( 'mongosh:start-loading-cli-scripts', (event: StartLoadingCliScriptsEvent) => { @@ -170,7 +172,7 @@ export class MongoshLoggingAndTelemetry { 'repl', 'Start loading CLI scripts' ); - usesShellOption = event.usesShellOption; + this.usesShellOption = event.usesShellOption; } ); @@ -200,7 +202,7 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this.getTelemetryUserIdentity(), + ...this._getTelemetryUserIdentity(), event: 'New Connection', properties, }); @@ -216,7 +218,7 @@ export class MongoshLoggingAndTelemetry { const normalizedTimings = Object.fromEntries(normalizedTimingsArray); this.analytics.track({ - ...this.getTelemetryUserIdentity(), + ...this._getTelemetryUserIdentity(), event: 'Startup Time', properties: { ...this.trackingProperties, @@ -253,7 +255,7 @@ export class MongoshLoggingAndTelemetry { this.userId = updatedTelemetryUserIdentity.userId; } this.analytics.identify({ - ...this.getTelemetryUserIdentity(), + ...this._getTelemetryUserIdentity(), traits: this.userTraits, }); this.log.info( @@ -284,7 +286,7 @@ export class MongoshLoggingAndTelemetry { if (error.name.includes('Mongosh')) { this.analytics.track({ - ...this.getTelemetryUserIdentity(), + ...this._getTelemetryUserIdentity(), event: 'Error', properties: { ...this.trackingProperties, @@ -327,7 +329,7 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this.getTelemetryUserIdentity(), + ...this._getTelemetryUserIdentity(), event: 'Use', properties: { ...this.trackingProperties, @@ -345,7 +347,7 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this.getTelemetryUserIdentity(), + ...this._getTelemetryUserIdentity(), event: 'Show', properties: { ...this.trackingProperties, @@ -391,12 +393,16 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this.getTelemetryUserIdentity(), - event: hasStartedMongoshRepl ? 'Script Loaded' : 'Script Loaded CLI', + ...this._getTelemetryUserIdentity(), + event: this.hasStartedMongoshRepl + ? 'Script Loaded' + : 'Script Loaded CLI', properties: { ...this.trackingProperties, nested: args.nested, - ...(hasStartedMongoshRepl ? {} : { shell: usesShellOption }), + ...(this.hasStartedMongoshRepl + ? {} + : { shell: this.usesShellOption }), }, }); }); @@ -410,11 +416,11 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this.getTelemetryUserIdentity(), + ...this._getTelemetryUserIdentity(), event: 'Script Evaluated', properties: { ...this.trackingProperties, - shell: usesShellOption, + shell: this.usesShellOption, }, }); }); @@ -428,7 +434,7 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this.getTelemetryUserIdentity(), + ...this._getTelemetryUserIdentity(), event: 'Mongoshrc Loaded', properties: { ...this.trackingProperties, @@ -445,7 +451,7 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this.getTelemetryUserIdentity(), + ...this._getTelemetryUserIdentity(), event: 'Mongorc Warning', properties: { ...this.trackingProperties, @@ -615,7 +621,7 @@ export class MongoshLoggingAndTelemetry { if (ev.args[0] === 'install') { this.analytics.track({ - ...this.getTelemetryUserIdentity(), + ...this._getTelemetryUserIdentity(), event: 'Snippet Install', properties: { ...this.trackingProperties, @@ -637,14 +643,10 @@ export class MongoshLoggingAndTelemetry { } ); - const deprecatedApiCalls = new MultiSet< - Pick - >(); - const apiCalls = new MultiSet>(); - let apiCallTrackingEnabled = false; onBus('mongosh:api-call', (ev: ApiEvent) => { // Only track if we have previously seen a mongosh:evaluate-started call - if (!apiCallTrackingEnabled) return; + if (!this.apiCallTracking.isEnabled) return; + const { apiCalls, deprecatedApiCalls } = this.apiCallTracking; if (ev.deprecated) { deprecatedApiCalls.add({ class: ev.class, method: ev.method }); } @@ -653,7 +655,8 @@ export class MongoshLoggingAndTelemetry { } }); onBus('mongosh:evaluate-started', () => { - apiCallTrackingEnabled = true; + const { apiCalls, deprecatedApiCalls } = this.apiCallTracking; + this.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 @@ -662,6 +665,7 @@ export class MongoshLoggingAndTelemetry { apiCalls.clear(); }); onBus('mongosh:evaluate-finished', () => { + const { apiCalls, deprecatedApiCalls } = this.apiCallTracking; for (const [entry] of deprecatedApiCalls) { this.log.warn( 'MONGOSH', @@ -672,7 +676,7 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this.getTelemetryUserIdentity(), + ...this._getTelemetryUserIdentity(), event: 'Deprecated Method', properties: { ...this.trackingProperties, @@ -682,7 +686,7 @@ export class MongoshLoggingAndTelemetry { } for (const [entry, count] of apiCalls) { this.analytics.track({ - ...this.getTelemetryUserIdentity(), + ...this._getTelemetryUserIdentity(), event: 'API Call', properties: { ...this.trackingProperties, @@ -693,13 +697,12 @@ export class MongoshLoggingAndTelemetry { } deprecatedApiCalls.clear(); apiCalls.clear(); - apiCallTrackingEnabled = false; + this.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. - // eslint-disable-next-line @typescript-eslint/no-var-requires onBus('mongosh-sp:reset-connection-options', () => { this.log.info( From e5ae4dd144ac3c231bf58420f5c0a0ae0d0a8587 Mon Sep 17 00:00:00 2001 From: gagik Date: Tue, 28 Jan 2025 12:04:40 +0100 Subject: [PATCH 05/15] tests: add initial set of tests Will follow up with more end to end tests. --- packages/cli-repl/src/cli-repl.spec.ts | 58 ++++++++--------- packages/cli-repl/src/cli-repl.ts | 1 - .../logging/src/logging-and-telemetry.spec.ts | 62 ++++++------------- packages/logging/src/logging-and-telemetry.ts | 9 ++- 4 files changed, 53 insertions(+), 77 deletions(-) diff --git a/packages/cli-repl/src/cli-repl.spec.ts b/packages/cli-repl/src/cli-repl.spec.ts index e986a3f917..23ca5ebbea 100644 --- a/packages/cli-repl/src/cli-repl.spec.ts +++ b/packages/cli-repl/src/cli-repl.spec.ts @@ -1313,37 +1313,6 @@ describe('CliRepl', function () { hasCollectionNames: true, hasDatabaseNames: true, }); - - context('logging configuration', function () { - afterEach(function () { - sinon.restore(); - }); - - it('start logging when it is not disabled', async function () { - const emitSpy = sinon.spy(cliRepl.bus, 'emit'); - - await cliRepl.start(await testServer.connectionString(), {}); - - expect(cliRepl.getConfig('disableLogging')).is.false; - - expect(emitSpy).calledWith('mongosh:logger-initialized'); - expect(cliRepl.logWriter).is.instanceOf(MongoLogWriter); - }); - - it('does not start logging when it is disabled', async function () { - const emitSpy = sinon.spy(cliRepl.bus, 'emit'); - cliRepl.config.disableLogging = true; - - await cliRepl.start(await testServer.connectionString(), {}); - - expect(cliRepl.getConfig('disableLogging')).is.true; - - expect(emitSpy).called; - expect(emitSpy).not.calledWith('mongosh:logger-initialized'); - expect(cliRepl.logWriter).is.undefined; - }); - }); - context('analytics integration', function () { context('with network connectivity', function () { let srv: http.Server; @@ -1394,6 +1363,33 @@ describe('CliRepl', function () { setTelemetryDelay(0); }); + context('logging configuration', function () { + it('logging is enabled by default', async function () { + const onLoggerInitialized = sinon.stub(); + cliRepl.bus.on('mongosh:logger-initialized', onLoggerInitialized); + + await cliRepl.start(await testServer.connectionString(), {}); + + expect(await cliRepl.getConfig('disableLogging')).is.false; + + expect(onLoggerInitialized).calledOnce; + expect(cliRepl.logWriter).is.instanceOf(MongoLogWriter); + }); + + it('does not start logging when it is disabled', async function () { + cliRepl.config.disableLogging = true; + const onLoggerInitialized = sinon.stub(); + cliRepl.bus.on('mongosh:logger-initialized', onLoggerInitialized); + + await cliRepl.start(await testServer.connectionString(), {}); + + expect(await cliRepl.getConfig('disableLogging')).is.true; + expect(onLoggerInitialized).not.called; + + expect(cliRepl.logWriter).is.undefined; + }); + }); + it('times out fast', async function () { const testStartMs = Date.now(); // The `httpRequestTimeout` of our Segment Analytics is set to diff --git a/packages/cli-repl/src/cli-repl.ts b/packages/cli-repl/src/cli-repl.ts index 81c3b766a3..6b2fd05ada 100644 --- a/packages/cli-repl/src/cli-repl.ts +++ b/packages/cli-repl/src/cli-repl.ts @@ -272,7 +272,6 @@ export class CliRepl implements MongoshIOProvider { loggingAndTelemetry.setupLogger(logger); markTime(TimingCategories.Logging, 'instantiated log writer'); - this.bus.emit('mongosh:logger-initialized'); logger.info('MONGOSH', mongoLogId(1_000_000_000), 'log', 'Starting log', { execPath: process.execPath, envInfo: redactSensitiveData(this.getLoggedEnvironmentVariables()), diff --git a/packages/logging/src/logging-and-telemetry.spec.ts b/packages/logging/src/logging-and-telemetry.spec.ts index 8b27e62465..46d66576b4 100644 --- a/packages/logging/src/logging-and-telemetry.spec.ts +++ b/packages/logging/src/logging-and-telemetry.spec.ts @@ -37,14 +37,14 @@ describe('MongoshLoggingAndTelemetry', function () { }, }; + let loggingAndTelemetry: MongoshLoggingAndTelemetry; + beforeEach(function () { logOutput = []; analyticsOutput = []; bus = new EventEmitter(); - }); - it('throws when trying to setup writer prematurely', function () { - const loggingAndTelemetry = new MongoshLoggingAndTelemetry( + loggingAndTelemetry = new MongoshLoggingAndTelemetry( bus, analytics, { @@ -53,23 +53,31 @@ describe('MongoshLoggingAndTelemetry', function () { }, '1.0.0' ); + }); + + it('throws when running setup twice', function () { + loggingAndTelemetry.setup(); + + expect(() => loggingAndTelemetry.setup()).throws( + 'Setup can only be called once.' + ); + }); + it('throws when trying to setup writer prematurely', function () { expect(() => loggingAndTelemetry.setupLogger(logger)).throws( 'Run setup() before setting up the log writer.' ); }); - it('tracks new local connection events', function () { - const loggingAndTelemetry = new MongoshLoggingAndTelemetry( - bus, - analytics, - { - platform: process.platform, - arch: process.arch, - }, - '1.0.0' + it('throws when running setupLogger twice', function () { + loggingAndTelemetry.setup(); + loggingAndTelemetry.setupLogger(logger); + expect(() => loggingAndTelemetry.setupLogger(logger)).throws( + 'Logger has already been initialized.' ); + }); + it('tracks new local connection events', function () { loggingAndTelemetry.setup(); loggingAndTelemetry.setupLogger(logger); @@ -125,16 +133,6 @@ describe('MongoshLoggingAndTelemetry', function () { }); it('tracks new atlas connection events', function () { - const loggingAndTelemetry = new MongoshLoggingAndTelemetry( - bus, - analytics, - { - platform: process.platform, - arch: process.arch, - }, - '1.0.0' - ); - loggingAndTelemetry.setup(); loggingAndTelemetry.setupLogger(logger); @@ -667,16 +665,6 @@ describe('MongoshLoggingAndTelemetry', function () { }); it('buffers deprecated API calls', function () { - const loggingAndTelemetry = new MongoshLoggingAndTelemetry( - bus, - analytics, - { - platform: process.platform, - arch: process.arch, - }, - '1.0.0' - ); - loggingAndTelemetry.setup(); loggingAndTelemetry.setupLogger(logger); @@ -853,16 +841,6 @@ describe('MongoshLoggingAndTelemetry', function () { }); it('does not track database calls outside of evaluate-{started,finished}', function () { - const loggingAndTelemetry = new MongoshLoggingAndTelemetry( - bus, - analytics, - { - platform: process.platform, - arch: process.arch, - }, - '1.0.0' - ); - loggingAndTelemetry.setup(); loggingAndTelemetry.setupLogger(logger); diff --git a/packages/logging/src/logging-and-telemetry.ts b/packages/logging/src/logging-and-telemetry.ts index e0d65e3bf4..12b5c18676 100644 --- a/packages/logging/src/logging-and-telemetry.ts +++ b/packages/logging/src/logging-and-telemetry.ts @@ -46,6 +46,8 @@ import { MultiSet, toSnakeCase } from './helpers'; import { Writable } from 'stream'; export class MongoshLoggingAndTelemetry { + public log: MongoLogWriter; + private readonly trackingProperties: { mongosh_version: string; session_id: string; @@ -54,14 +56,12 @@ export class MongoshLoggingAndTelemetry { [key: string]: unknown; }; - private log: MongoLogWriter; private pendingLogEvents: CallableFunction[] = []; private telemetryAnonymousId: string | undefined; private userId: string | undefined; - - private isSetup = false; private hasMongoLogWriterInitialized = false; + private isSetup = false; constructor( public readonly bus: MongoshBus, @@ -90,6 +90,9 @@ export class MongoshLoggingAndTelemetry { } public setup(): void { + if (this.isSetup) { + throw new Error('Setup can only be called once.'); + } this._setupBusEventListeners(); this.isSetup = true; } From da2b5b3b512673a94dde8995858084c00de2b672 Mon Sep 17 00:00:00 2001 From: gagik Date: Thu, 30 Jan 2025 09:57:38 +0100 Subject: [PATCH 06/15] feat: add ability to detach logger and use only telemetry and more tests Will add some more E2E and unit tests. --- packages/cli-repl/src/cli-repl.spec.ts | 40 +++--- packages/cli-repl/src/cli-repl.ts | 64 ++++++--- packages/e2e-tests/test/e2e.spec.ts | 72 ++++++++-- .../logging/src/logging-and-telemetry.spec.ts | 125 +++++++++++++---- packages/logging/src/logging-and-telemetry.ts | 127 ++++++++++-------- packages/types/src/index.ts | 2 +- 6 files changed, 301 insertions(+), 129 deletions(-) diff --git a/packages/cli-repl/src/cli-repl.spec.ts b/packages/cli-repl/src/cli-repl.spec.ts index 23ca5ebbea..5d30e1ea0b 100644 --- a/packages/cli-repl/src/cli-repl.spec.ts +++ b/packages/cli-repl/src/cli-repl.spec.ts @@ -238,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'); @@ -1365,29 +1386,16 @@ describe('CliRepl', function () { context('logging configuration', function () { it('logging is enabled by default', async function () { - const onLoggerInitialized = sinon.stub(); - cliRepl.bus.on('mongosh:logger-initialized', onLoggerInitialized); + 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(onLoggerInitialized).calledOnce; + expect(onLogInitialized).calledOnce; expect(cliRepl.logWriter).is.instanceOf(MongoLogWriter); }); - - it('does not start logging when it is disabled', async function () { - cliRepl.config.disableLogging = true; - const onLoggerInitialized = sinon.stub(); - cliRepl.bus.on('mongosh:logger-initialized', onLoggerInitialized); - - await cliRepl.start(await testServer.connectionString(), {}); - - expect(await cliRepl.getConfig('disableLogging')).is.true; - expect(onLoggerInitialized).not.called; - - expect(cliRepl.logWriter).is.undefined; - }); }); it('times out fast', async function () { diff --git a/packages/cli-repl/src/cli-repl.ts b/packages/cli-repl/src/cli-repl.ts index 6b2fd05ada..a93c4f6736 100644 --- a/packages/cli-repl/src/cli-repl.ts +++ b/packages/cli-repl/src/cli-repl.ts @@ -30,11 +30,11 @@ 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 { MongoshLoggingAndTelemetry } from '@mongosh/logging'; import { ToggleableAnalytics, ThrottledAnalytics, SampledAnalytics, - MongoshLoggingAndTelemetry, } from '@mongosh/logging'; import type { MongoshBus } from '@mongosh/types'; import { @@ -119,7 +119,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 +140,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 +191,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, @@ -257,9 +249,24 @@ export class CliRepl implements MongoshIOProvider { } /** Setup log writer and start logging. */ - private async startLogging( - loggingAndTelemetry: MongoshLoggingAndTelemetry - ): Promise { + private async startLogging(): Promise { + if (!this.loggingAndTelemetry) { + throw new Error('Logging and telemetry not setup'); + } + + if (!this.logManager) { + 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), + }); + } + await this.logManager.cleanupOldLogFiles(); markTime(TimingCategories.Logging, 'cleaned up log files'); const logger = await this.logManager.createLogWriter(); @@ -269,7 +276,7 @@ export class CliRepl implements MongoshIOProvider { } this.logWriter = logger; - loggingAndTelemetry.setupLogger(logger); + this.loggingAndTelemetry.attachLogger(logger); markTime(TimingCategories.Logging, 'instantiated log writer'); logger.info('MONGOSH', mongoLogId(1_000_000_000), 'log', 'Starting log', { @@ -343,7 +350,7 @@ export class CliRepl implements MongoshIOProvider { markTime(TimingCategories.Telemetry, 'created analytics instance'); - const loggingAndTelemetry = new MongoshLoggingAndTelemetry( + this.loggingAndTelemetry = new MongoshLoggingAndTelemetry( this.bus, this.toggleableAnalytics, { @@ -354,7 +361,7 @@ export class CliRepl implements MongoshIOProvider { }, version ); - loggingAndTelemetry.setup(); + this.loggingAndTelemetry.setup(); markTime(TimingCategories.Telemetry, 'completed telemetry setup'); @@ -374,10 +381,7 @@ export class CliRepl implements MongoshIOProvider { this.globalConfig = await this.loadGlobalConfigFile(); markTime(TimingCategories.UserConfigLoading, 'read global config files'); - const disableLogging = await this.getConfig('disableLogging'); - if (disableLogging !== true) { - await this.startLogging(loggingAndTelemetry); - } + await this.setLoggingEnabled(!(await this.getConfig('disableLogging'))); // Needs to happen after loading the mongosh config file(s) void this.fetchMongoshUpdateUrl(); @@ -622,6 +626,19 @@ export class CliRepl implements MongoshIOProvider { ); } + async setLoggingEnabled(enabled: boolean): Promise { + if (enabled) { + if (!this.logWriter) { + await this.startLogging(); + } + // Do nothing if there is already an active log writer. + } else { + this.loggingAndTelemetry?.detachLogger(); + this.logWriter?.destroy(); + this.logWriter = undefined; + } + } + setTelemetryEnabled(enabled: boolean): void { if (this.globalConfig === null) { // This happens when the per-user config file is loaded before we have @@ -908,6 +925,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) { diff --git a/packages/e2e-tests/test/e2e.spec.ts b/packages/e2e-tests/test/e2e.spec.ts index 4444a08cb1..55422633b7 100644 --- a/packages/e2e-tests/test/e2e.spec.ts +++ b/packages/e2e-tests/test/e2e.spec.ts @@ -22,6 +22,7 @@ import { once } from 'events'; import type { AddressInfo } from 'net'; const { EJSON } = bson; import { sleep } from './util-helpers'; +import type { LogEntry } from '@mongosh/shell-api/src/log-entry'; const jsContextFlagCombinations: `--jsContext=${'plain-vm' | 'repl'}`[][] = [ [], @@ -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 () => { + 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,61 @@ describe('e2e', function () { }); describe('log file', function () { + it('does not create a log 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'); + expect(shell.logId).equals(null); + }); + it('creates a log file that keeps track of session events', async function () { 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); - }); + const log = await readLogfile(); + expect( + // eslint-disable-next-line @typescript-eslint/no-unsafe-argument + log.filter( + (logEntry) => logEntry.attr?.input === 'print(123 + 456)' + ) + ).to.have.lengthOf(1); + }); + + it('does not write to the log file 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('includes information about the driver version', async function () { diff --git a/packages/logging/src/logging-and-telemetry.spec.ts b/packages/logging/src/logging-and-telemetry.spec.ts index 46d66576b4..abee859686 100644 --- a/packages/logging/src/logging-and-telemetry.spec.ts +++ b/packages/logging/src/logging-and-telemetry.spec.ts @@ -15,15 +15,7 @@ describe('MongoshLoggingAndTelemetry', 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 Writable); + let logger: MongoLogWriter; const analytics = { identify(info: any) { @@ -53,6 +45,21 @@ describe('MongoshLoggingAndTelemetry', function () { }, '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 setup twice', function () { @@ -64,28 +71,35 @@ describe('MongoshLoggingAndTelemetry', function () { }); it('throws when trying to setup writer prematurely', function () { - expect(() => loggingAndTelemetry.setupLogger(logger)).throws( + expect(() => loggingAndTelemetry.attachLogger(logger)).throws( 'Run setup() before setting up the log writer.' ); }); - it('throws when running setupLogger twice', function () { + it('throws when running attachLogger twice without detaching', function () { loggingAndTelemetry.setup(); - loggingAndTelemetry.setupLogger(logger); - expect(() => loggingAndTelemetry.setupLogger(logger)).throws( - 'Logger has already been initialized.' + 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.setup(); + loggingAndTelemetry.attachLogger(logger); + loggingAndTelemetry.detachLogger(); + expect(() => loggingAndTelemetry.attachLogger(logger)).does.not.throw(); + }); + it('tracks new local connection events', function () { loggingAndTelemetry.setup(); - loggingAndTelemetry.setupLogger(logger); + 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:logger-initialized'); + bus.emit('mongosh:log-initialized'); bus.emit('mongosh:connect', { uri: 'mongodb://localhost/', @@ -134,13 +148,13 @@ describe('MongoshLoggingAndTelemetry', function () { it('tracks new atlas connection events', function () { loggingAndTelemetry.setup(); - loggingAndTelemetry.setupLogger(logger); + 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:logger-initialized'); + bus.emit('mongosh:log-initialized'); bus.emit('mongosh:connect', { uri: 'mongodb://test-data-sets-a011bb.mongodb.net/', @@ -191,6 +205,71 @@ describe('MongoshLoggingAndTelemetry', function () { ]); }); + it('detaching logger leads to no logging but persists analytics', function () { + loggingAndTelemetry.setup(); + 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 mid-way leads to no logging but persists analytics', function () { + loggingAndTelemetry.setup(); + 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.setup(); + 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 () { const loggingAndTelemetry = new MongoshLoggingAndTelemetry( bus, @@ -203,13 +282,13 @@ describe('MongoshLoggingAndTelemetry', function () { ); loggingAndTelemetry.setup(); - loggingAndTelemetry.setupLogger(logger); + 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:logger-initialized'); + bus.emit('mongosh:log-initialized'); bus.emit('mongosh:update-user', { userId, anonymousId: userId }); bus.emit('mongosh:start-session', { @@ -666,13 +745,13 @@ describe('MongoshLoggingAndTelemetry', function () { it('buffers deprecated API calls', function () { loggingAndTelemetry.setup(); - loggingAndTelemetry.setupLogger(logger); + 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:logger-initialized'); + bus.emit('mongosh:log-initialized'); bus.emit('mongosh:evaluate-started'); @@ -842,7 +921,7 @@ describe('MongoshLoggingAndTelemetry', function () { it('does not track database calls outside of evaluate-{started,finished}', function () { loggingAndTelemetry.setup(); - loggingAndTelemetry.setupLogger(logger); + loggingAndTelemetry.attachLogger(logger); expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; diff --git a/packages/logging/src/logging-and-telemetry.ts b/packages/logging/src/logging-and-telemetry.ts index 12b5c18676..05629a3009 100644 --- a/packages/logging/src/logging-and-telemetry.ts +++ b/packages/logging/src/logging-and-telemetry.ts @@ -46,7 +46,7 @@ import { MultiSet, toSnakeCase } from './helpers'; import { Writable } from 'stream'; export class MongoshLoggingAndTelemetry { - public log: MongoLogWriter; + private log: MongoLogWriter | null; private readonly trackingProperties: { mongosh_version: string; @@ -60,12 +60,12 @@ export class MongoshLoggingAndTelemetry { private telemetryAnonymousId: string | undefined; private userId: string | undefined; - private hasMongoLogWriterInitialized = false; + private isDummyLog = true; private isSetup = false; constructor( - public readonly bus: MongoshBus, - public readonly analytics: MongoshAnalytics, + private readonly bus: MongoshBus, + private readonly analytics: MongoshAnalytics, providedTraits: { platform: string } & { [key: string]: unknown; }, @@ -97,29 +97,38 @@ export class MongoshLoggingAndTelemetry { this.isSetup = true; } - public setupLogger(logger: MongoLogWriter): void { + public attachLogger(logger: MongoLogWriter): void { if (!this.isSetup) { throw new Error('Run setup() before setting up the log writer.'); } - if (this.hasMongoLogWriterInitialized) { - throw new Error('Logger has already been initialized.'); + /** Setup can only be run when overriding a dummy log or a null log. */ + if (this.log && !this.isDummyLog) { + throw new Error( + 'Previously set logger has not been detached. Run detachLogger() before setting.' + ); } this.log = logger; this.userTraits.session_id = this.log.logId; this.trackingProperties.session_id = this.log.logId; - this.hasMongoLogWriterInitialized = true; + this.isDummyLog = false; + + hookLogger(this.bus, this.log, 'mongosh', (uri) => + redactURICredentials(uri) + ); + for (const pendingEvent of this.pendingLogEvents) { pendingEvent(); } this.pendingLogEvents = []; - hookLogger(this.bus, this.log, 'mongosh', (uri) => - redactURICredentials(uri) - ); + this.bus.emit('mongosh:log-initialized'); + } - this.bus.emit('mongosh:logger-initialized'); + public detachLogger() { + this.pendingLogEvents = []; + this.log = null; } private _getTelemetryUserIdentity(): MongoshAnalyticsIdentity { @@ -147,7 +156,9 @@ export class MongoshLoggingAndTelemetry { listener: (...args: Parameters) => void ) => { this.bus.on(event, ((...args: Parameters) => { - if (this.hasMongoLogWriterInitialized) { + const isLoggerAttachedOrNull = + (this.log && !this.isDummyLog) || this.log === null; + if (isLoggerAttachedOrNull) { listener(...args); } else { this.pendingLogEvents.push(() => listener(...args)); @@ -156,7 +167,7 @@ export class MongoshLoggingAndTelemetry { }; onBus('mongosh:start-mongosh-repl', (ev: StartMongoshReplEvent) => { - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_002), 'repl', @@ -169,7 +180,7 @@ export class MongoshLoggingAndTelemetry { onBus( 'mongosh:start-loading-cli-scripts', (event: StartLoadingCliScriptsEvent) => { - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_003), 'repl', @@ -191,7 +202,7 @@ export class MongoshLoggingAndTelemetry { ...atlasHostname, }; - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_004), 'connect', @@ -261,7 +272,7 @@ export class MongoshLoggingAndTelemetry { ...this._getTelemetryUserIdentity(), traits: this.userTraits, }); - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_005), 'config', @@ -279,13 +290,15 @@ export class MongoshLoggingAndTelemetry { metadata: unknown; }; - this.log[context === 'fatal' ? 'fatal' : 'error']( - 'MONGOSH', - mongoLogId(1_000_000_006), - context, - `${mongoshError.name}: ${mongoshError.message}`, - error - ); + if (this.log) { + 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({ @@ -303,7 +316,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh:globalconfig-load', (args: GlobalConfigFileLoadEvent) => { - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_048), 'config', @@ -313,7 +326,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh:evaluate-input', (args: EvaluateInputEvent) => { - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_007), 'repl', @@ -323,7 +336,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh:use', (args: UseEvent) => { - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_008), 'shell-api', @@ -341,7 +354,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh:show', (args: ShowEvent) => { - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_009), 'shell-api', @@ -360,7 +373,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh:setCtx', (args: ApiEventWithArguments) => { - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_010), 'shell-api', @@ -377,7 +390,7 @@ export class MongoshLoggingAndTelemetry { } catch { arg = { _inspected: inspect(args) }; } - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_011), 'shell-api', @@ -387,7 +400,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh:api-load-file', (args: ScriptLoadFileEvent) => { - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_012), 'shell-api', @@ -411,7 +424,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh:eval-cli-script', () => { - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_013), 'repl', @@ -429,7 +442,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh:mongoshrc-load', () => { - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_014), 'repl', @@ -446,7 +459,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh:mongoshrc-mongorc-warn', () => { - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_015), 'repl', @@ -463,7 +476,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh:crypt-library-load-skip', (ev: CryptLibrarySkipEvent) => { - this.log.info( + this.log?.info( 'AUTO-ENCRYPTION', mongoLogId(1_000_000_050), 'crypt-library', @@ -473,7 +486,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh:crypt-library-load-found', (ev: CryptLibraryFoundEvent) => { - this.log.warn( + this.log?.warn( 'AUTO-ENCRYPTION', mongoLogId(1_000_000_051), 'crypt-library', @@ -486,7 +499,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh-snippets:loaded', (ev: SnippetsLoadedEvent) => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_019), 'snippets', @@ -496,7 +509,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh-snippets:npm-lookup', (ev: SnippetsNpmLookupEvent) => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_020), 'snippets', @@ -506,7 +519,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh-snippets:npm-lookup-stopped', () => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_021), 'snippets', @@ -517,7 +530,7 @@ export class MongoshLoggingAndTelemetry { onBus( 'mongosh-snippets:npm-download-failed', (ev: SnippetsNpmDownloadFailedEvent) => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_022), 'snippets', @@ -530,7 +543,7 @@ export class MongoshLoggingAndTelemetry { onBus( 'mongosh-snippets:npm-download-active', (ev: SnippetsNpmDownloadActiveEvent) => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_023), 'snippets', @@ -541,7 +554,7 @@ export class MongoshLoggingAndTelemetry { ); onBus('mongosh-snippets:fetch-index', (ev: SnippetsFetchIndexEvent) => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_024), 'snippets', @@ -551,7 +564,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh-snippets:fetch-cache-invalid', () => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_025), 'snippets', @@ -562,7 +575,7 @@ export class MongoshLoggingAndTelemetry { onBus( 'mongosh-snippets:fetch-index-error', (ev: SnippetsFetchIndexErrorEvent) => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_026), 'snippets', @@ -573,7 +586,7 @@ export class MongoshLoggingAndTelemetry { ); onBus('mongosh-snippets:fetch-index-done', () => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_027), 'snippets', @@ -583,7 +596,7 @@ export class MongoshLoggingAndTelemetry { onBus( 'mongosh-snippets:package-json-edit-error', (ev: SnippetsErrorEvent) => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_028), 'snippets', @@ -594,7 +607,7 @@ export class MongoshLoggingAndTelemetry { ); onBus('mongosh-snippets:spawn-child', (ev: SnippetsRunNpmEvent) => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_029), 'snippets', @@ -604,7 +617,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh-snippets:load-snippet', (ev: SnippetsLoadSnippetEvent) => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_030), 'snippets', @@ -614,7 +627,7 @@ export class MongoshLoggingAndTelemetry { }); onBus('mongosh-snippets:snippet-command', (ev: SnippetsCommandEvent) => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_031), 'snippets', @@ -636,7 +649,7 @@ export class MongoshLoggingAndTelemetry { onBus( 'mongosh-snippets:transform-error', (ev: SnippetsTransformErrorEvent) => { - this.log.info( + this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_032), 'snippets', @@ -670,7 +683,7 @@ export class MongoshLoggingAndTelemetry { onBus('mongosh:evaluate-finished', () => { const { apiCalls, deprecatedApiCalls } = this.apiCallTracking; for (const [entry] of deprecatedApiCalls) { - this.log.warn( + this.log?.warn( 'MONGOSH', mongoLogId(1_000_000_033), 'shell-api', @@ -708,7 +721,7 @@ export class MongoshLoggingAndTelemetry { // 'mongodb' is not supported in startup snapshots yet. onBus('mongosh-sp:reset-connection-options', () => { - this.log.info( + this.log?.info( 'MONGOSH-SP', mongoLogId(1_000_000_040), 'connect', @@ -719,7 +732,7 @@ export class MongoshLoggingAndTelemetry { onBus( 'mongosh-editor:run-edit-command', (ev: EditorRunEditCommandEvent) => { - this.log.error( + this.log?.error( 'MONGOSH-EDITOR', mongoLogId(1_000_000_047), 'editor', @@ -732,7 +745,7 @@ export class MongoshLoggingAndTelemetry { onBus( 'mongosh-editor:read-vscode-extensions-done', (ev: EditorReadVscodeExtensionsDoneEvent) => { - this.log.error( + this.log?.error( 'MONGOSH-EDITOR', mongoLogId(1_000_000_043), 'editor', @@ -745,7 +758,7 @@ export class MongoshLoggingAndTelemetry { onBus( 'mongosh-editor:read-vscode-extensions-failed', (ev: EditorReadVscodeExtensionsFailedEvent) => { - this.log.error( + this.log?.error( 'MONGOSH-EDITOR', mongoLogId(1_000_000_044), 'editor', @@ -761,7 +774,7 @@ export class MongoshLoggingAndTelemetry { onBus( 'mongosh:fetching-update-metadata', (ev: FetchingUpdateMetadataEvent) => { - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_052), 'startup', @@ -776,7 +789,7 @@ export class MongoshLoggingAndTelemetry { onBus( 'mongosh:fetching-update-metadata-complete', (ev: FetchingUpdateMetadataCompleteEvent) => { - this.log.info( + this.log?.info( 'MONGOSH', mongoLogId(1_000_000_053), 'startup', diff --git a/packages/types/src/index.ts b/packages/types/src/index.ts index e0b00dc70f..69d15b1390 100644 --- a/packages/types/src/index.ts +++ b/packages/types/src/index.ts @@ -401,7 +401,7 @@ export interface MongoshBusEventsMap extends ConnectEventMap { ev: FetchingUpdateMetadataCompleteEvent ) => void; /** Signals that logging has been initialized. */ - 'mongosh:logger-initialized': () => void; + 'mongosh:log-initialized': () => void; } export interface MongoshBus { From 0858257451123197851452a09854003cd8365e5c Mon Sep 17 00:00:00 2001 From: gagik Date: Thu, 30 Jan 2025 14:11:02 +0100 Subject: [PATCH 07/15] tests: add e2e tests for global config and midway disabling and enabling of the logs --- packages/cli-repl/src/cli-repl.spec.ts | 15 +++- packages/e2e-tests/test/e2e.spec.ts | 82 +++++++++++++++++-- packages/e2e-tests/test/test-shell.ts | 12 ++- packages/logging/src/logging-and-telemetry.ts | 15 ++-- 4 files changed, 106 insertions(+), 18 deletions(-) diff --git a/packages/cli-repl/src/cli-repl.spec.ts b/packages/cli-repl/src/cli-repl.spec.ts index 5d30e1ea0b..754a201f8e 100644 --- a/packages/cli-repl/src/cli-repl.spec.ts +++ b/packages/cli-repl/src/cli-repl.spec.ts @@ -1385,7 +1385,7 @@ describe('CliRepl', function () { }); context('logging configuration', function () { - it('logging is enabled by default', async function () { + it('logging is enabled by default and event is called', async function () { const onLogInitialized = sinon.stub(); cliRepl.bus.on('mongosh:log-initialized', onLogInitialized); @@ -1396,6 +1396,19 @@ describe('CliRepl', function () { 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('times out fast', async function () { diff --git a/packages/e2e-tests/test/e2e.spec.ts b/packages/e2e-tests/test/e2e.spec.ts index 55422633b7..ed1076e698 100644 --- a/packages/e2e-tests/test/e2e.spec.ts +++ b/packages/e2e-tests/test/e2e.spec.ts @@ -1356,7 +1356,7 @@ describe('e2e', function () { let logBasePath: string; let historyPath: string; let readConfig: () => Promise; - let readLogfile: () => Promise; + let readLogFile: () => Promise; let startTestShell: (...extraArgs: string[]) => Promise; beforeEach(function () { @@ -1393,7 +1393,7 @@ describe('e2e', function () { } readConfig = async () => EJSON.parse(await fs.readFile(configPath, 'utf8')); - readLogfile = async () => { + readLogFile = async () => { if (!shell.logId) { throw new Error('Shell does not have a logId associated with it'); } @@ -1508,7 +1508,7 @@ describe('e2e', function () { }); describe('log file', function () { - it('does not create a log if global config has disableLogging', 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({ @@ -1529,9 +1529,38 @@ describe('e2e', function () { 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( + // eslint-disable-next-line @typescript-eslint/no-unsafe-argument + 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(); + const log = await readLogFile(); expect( // eslint-disable-next-line @typescript-eslint/no-unsafe-argument log.filter( @@ -1540,9 +1569,9 @@ describe('e2e', function () { ).to.have.lengthOf(1); }); - it('does not write to the log file after disableLogging is set to true', async function () { + 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(); + const log = await readLogFile(); expect( log.filter( (logEntry) => logEntry.attr?.input === 'print(123 + 456)' @@ -1552,7 +1581,7 @@ describe('e2e', function () { await shell.executeLine(`config.set("disableLogging", true)`); expect(await shell.executeLine('print(579 - 123)')).to.include('456'); - const logAfterDisabling = await readLogfile(); + const logAfterDisabling = await readLogFile(); expect( logAfterDisabling.filter( (logEntry) => logEntry.attr?.input === 'print(579 - 123)' @@ -1565,6 +1594,43 @@ describe('e2e', function () { ).to.have.lengthOf(1); }); + it('starts writing to a new log from the point where disableLogging is set to false', async function () { + await shell.executeLine(`config.set("disableLogging", true)`); + expect(await shell.executeLine('print(123 + 456)')).to.include('579'); + const 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).not.equal(newLogId); + const logsAfterEnabling = await readLogFile(); + expect( + logsAfterEnabling.filter( + (logEntry) => logEntry.attr?.input === 'print(579 - 123)' + ) + ).to.have.lengthOf(1); + expect( + logsAfterEnabling.filter( + (logEntry) => logEntry.attr?.input === 'print(123 + 456)' + ) + ).to.have.lengthOf(0); + }); + it('includes information about the driver version', async function () { const connectionString = await testServer.connectionString(); expect( @@ -1573,7 +1639,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' diff --git a/packages/e2e-tests/test/test-shell.ts b/packages/e2e-tests/test/test-shell.ts index 3a5d870b82..b7564996cf 100644 --- a/packages/e2e-tests/test/test-shell.ts +++ b/packages/e2e-tests/test/test-shell.ts @@ -362,12 +362,16 @@ export class TestShell { } get logId(): string | null { - const match = /^Current Mongosh Log ID:\s*(?[a-z0-9]{24})$/m.exec( - this._output + const matches = this._output.match( + /^Current Mongosh Log ID:\s*([a-z0-9]{24})$/gm ); - if (!match) { + if (!matches || matches.length === 0) { return null; } - return match.groups!.logId; + const lastMatch = matches[matches.length - 1]; + const logIdMatch = /^Current Mongosh Log ID:\s*([a-z0-9]{24})$/.exec( + lastMatch + ); + return logIdMatch ? logIdMatch[1] : null; } } diff --git a/packages/logging/src/logging-and-telemetry.ts b/packages/logging/src/logging-and-telemetry.ts index 05629a3009..3dea9b3664 100644 --- a/packages/logging/src/logging-and-telemetry.ts +++ b/packages/logging/src/logging-and-telemetry.ts @@ -118,17 +118,22 @@ export class MongoshLoggingAndTelemetry { redactURICredentials(uri) ); - for (const pendingEvent of this.pendingLogEvents) { - pendingEvent(); - } - this.pendingLogEvents = []; + this.runAndCleanPendingEvents(); this.bus.emit('mongosh:log-initialized'); } public detachLogger() { - this.pendingLogEvents = []; this.log = null; + // Still run any remaining pending events for telemetry purposes. + this.runAndCleanPendingEvents(); + } + + private runAndCleanPendingEvents() { + for (const pendingEvent of this.pendingLogEvents) { + pendingEvent(); + } + this.pendingLogEvents = []; } private _getTelemetryUserIdentity(): MongoshAnalyticsIdentity { From 6311256a67a276e9cc0e65a944cf1e03567f3ea3 Mon Sep 17 00:00:00 2001 From: gagik Date: Thu, 30 Jan 2025 14:42:57 +0100 Subject: [PATCH 08/15] refactor: move custom log entries into new structure --- packages/e2e-tests/test/e2e.spec.ts | 11 ++++++--- packages/e2e-tests/test/test-shell.ts | 7 +++--- .../logging/src/logging-and-telemetry.spec.ts | 23 +++---------------- packages/logging/src/logging-and-telemetry.ts | 14 +++++++++++ packages/types/src/index.ts | 7 ------ 5 files changed, 28 insertions(+), 34 deletions(-) diff --git a/packages/e2e-tests/test/e2e.spec.ts b/packages/e2e-tests/test/e2e.spec.ts index ed1076e698..8ed230fd33 100644 --- a/packages/e2e-tests/test/e2e.spec.ts +++ b/packages/e2e-tests/test/e2e.spec.ts @@ -1356,7 +1356,7 @@ describe('e2e', function () { let logBasePath: string; let historyPath: string; let readConfig: () => Promise; - let readLogFile: () => Promise; + let readLogFile: () => Promise; let startTestShell: (...extraArgs: string[]) => Promise; beforeEach(function () { @@ -1652,7 +1652,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<{ + msg: string; + s: string; + c: string; + ctx: string; + }>(); const customLogEntry = log.filter((logEntry) => logEntry.msg.includes('This is a custom entry') ); @@ -1676,7 +1681,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<{ msg: string }>(); expect( log.filter((logEntry) => logEntry.msg.includes('Initiating connection attemp') diff --git a/packages/e2e-tests/test/test-shell.ts b/packages/e2e-tests/test/test-shell.ts index b7564996cf..64b6987acf 100644 --- a/packages/e2e-tests/test/test-shell.ts +++ b/packages/e2e-tests/test/test-shell.ts @@ -368,10 +368,9 @@ export class TestShell { if (!matches || matches.length === 0) { return null; } - const lastMatch = matches[matches.length - 1]; - const logIdMatch = /^Current Mongosh Log ID:\s*([a-z0-9]{24})$/.exec( - lastMatch + const lastMatch = /^Current Mongosh Log ID:\s*([a-z0-9]{24})$/.exec( + matches[matches.length - 1] ); - return logIdMatch ? logIdMatch[1] : null; + return lastMatch ? lastMatch[1] : null; } } diff --git a/packages/logging/src/logging-and-telemetry.spec.ts b/packages/logging/src/logging-and-telemetry.spec.ts index abee859686..002ed08a04 100644 --- a/packages/logging/src/logging-and-telemetry.spec.ts +++ b/packages/logging/src/logging-and-telemetry.spec.ts @@ -271,16 +271,6 @@ describe('MongoshLoggingAndTelemetry', function () { }); it('tracks a sequence of events', function () { - const loggingAndTelemetry = new MongoshLoggingAndTelemetry( - bus, - analytics, - { - platform: process.platform, - arch: process.arch, - }, - '1.0.0' - ); - loggingAndTelemetry.setup(); loggingAndTelemetry.attachLogger(logger); @@ -945,19 +935,12 @@ describe('MongoshLoggingAndTelemetry', 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.setup(); + 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 index 3dea9b3664..45dccce1f6 100644 --- a/packages/logging/src/logging-and-telemetry.ts +++ b/packages/logging/src/logging-and-telemetry.ts @@ -32,6 +32,7 @@ import type { FetchingUpdateMetadataCompleteEvent, SessionStartedEvent, MongoshBusEventsMap, + WriteCustomLogEvent, } from '@mongosh/types'; import { inspect } from 'util'; import { MongoLogWriter } from 'mongodb-log-writer'; @@ -320,6 +321,19 @@ export class MongoshLoggingAndTelemetry { } }); + onBus('mongosh:write-custom-log', (event: WriteCustomLogEvent) => { + if (this.log) { + 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', diff --git a/packages/types/src/index.ts b/packages/types/src/index.ts index 69d15b1390..bbe2617794 100644 --- a/packages/types/src/index.ts +++ b/packages/types/src/index.ts @@ -97,13 +97,6 @@ export interface MongocryptdLogEvent { logEntry: any; } -export interface WriteCustomLogEvent { - method: 'info' | 'error' | 'warn' | 'debug'; - message: string; - attr?: unknown; - level?: 1 | 2 | 3 | 4 | 5; -} - export interface StartMongoshReplEvent { version: string; } From e6c2356a1a31fe08f70d26dce80bf0e7a47dde48 Mon Sep 17 00:00:00 2001 From: gagik Date: Thu, 30 Jan 2025 15:57:21 +0100 Subject: [PATCH 09/15] fix: wrap the bus for hookLogger and tests Wrapping the bus can allow us to inject onBus onto the logger which can help us prevent logs being created from there. That said, we still have the problem of having to either re-register those hooks each time, so we may want to instead update hookLogger to take function for getting the latest log rather than just a variable. --- .../logging/src/logging-and-telemetry.spec.ts | 23 ++ packages/logging/src/logging-and-telemetry.ts | 329 +++++++++++------- 2 files changed, 218 insertions(+), 134 deletions(-) diff --git a/packages/logging/src/logging-and-telemetry.spec.ts b/packages/logging/src/logging-and-telemetry.spec.ts index 002ed08a04..fa9e857397 100644 --- a/packages/logging/src/logging-and-telemetry.spec.ts +++ b/packages/logging/src/logging-and-telemetry.spec.ts @@ -221,6 +221,29 @@ describe('MongoshLoggingAndTelemetry', function () { expect(analyticsOutput).to.have.lengthOf(1); }); + it('detaching logger applies to devtools-connect events', function () { + loggingAndTelemetry.setup(); + 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'); + expect(logOutput).to.have.lengthOf(3); + }); + it('detaching logger mid-way leads to no logging but persists analytics', function () { loggingAndTelemetry.setup(); loggingAndTelemetry.attachLogger(logger); diff --git a/packages/logging/src/logging-and-telemetry.ts b/packages/logging/src/logging-and-telemetry.ts index 45dccce1f6..39dae78ea8 100644 --- a/packages/logging/src/logging-and-telemetry.ts +++ b/packages/logging/src/logging-and-telemetry.ts @@ -42,6 +42,7 @@ import type { 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'; @@ -63,6 +64,7 @@ export class MongoshLoggingAndTelemetry { private userId: string | undefined; private isDummyLog = true; private isSetup = false; + private hookedExternalListenersLogId: string | undefined = undefined; constructor( private readonly bus: MongoshBus, @@ -98,6 +100,45 @@ export class MongoshLoggingAndTelemetry { this.isSetup = true; } + 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 is used to suppress externally defined listeners which + * only emit log events such as those from devtools-connect. + */ + suppressWhenLogIsNullOrDummy = false, + } = {} + ) => { + this.bus.on(event, ((...args: Parameters) => { + if ( + (this.log === null || this.isDummyLog) && + suppressWhenLogIsNullOrDummy + ) { + return; + } + + const isLoggerAttachedOrNull = + (this.log && !this.isDummyLog) || this.log === null; + if (isLoggerAttachedOrNull) { + listener(...args); + } else { + this.pendingLogEvents.push(() => listener(...args)); + } + }) as MongoshBusEventsMap[K]); + return this.bus; + }; + public attachLogger(logger: MongoLogWriter): void { if (!this.isSetup) { throw new Error('Run setup() before setting up the log writer.'); @@ -114,10 +155,24 @@ export class MongoshLoggingAndTelemetry { this.trackingProperties.session_id = this.log.logId; this.isDummyLog = false; + if (this.hookedExternalListenersLogId !== this.log.logId) { + hookLogger( + { + ...this.bus, + on: (event, listener) => + this.onBus( + event, + listener as (...args: unknown[]) => void, + { suppressWhenLogIsNullOrDummy: true } + ), + }, + this.log, + 'mongosh', + (uri) => redactURICredentials(uri) + ); - hookLogger(this.bus, this.log, 'mongosh', (uri) => - redactURICredentials(uri) - ); + this.hookedExternalListenersLogId = this.log.logId; + } this.runAndCleanPendingEvents(); @@ -157,22 +212,7 @@ export class MongoshLoggingAndTelemetry { private usesShellOption = false; private _setupBusEventListeners(): void { - const onBus = ( - event: K, - listener: (...args: Parameters) => void - ) => { - this.bus.on(event, ((...args: Parameters) => { - const isLoggerAttachedOrNull = - (this.log && !this.isDummyLog) || this.log === null; - if (isLoggerAttachedOrNull) { - listener(...args); - } else { - this.pendingLogEvents.push(() => listener(...args)); - } - }) as MongoshBusEventsMap[K]); - }; - - onBus('mongosh:start-mongosh-repl', (ev: StartMongoshReplEvent) => { + this.onBus('mongosh:start-mongosh-repl', (ev: StartMongoshReplEvent) => { this.log?.info( 'MONGOSH', mongoLogId(1_000_000_002), @@ -183,7 +223,7 @@ export class MongoshLoggingAndTelemetry { this.hasStartedMongoshRepl = true; }); - onBus( + this.onBus( 'mongosh:start-loading-cli-scripts', (event: StartLoadingCliScriptsEvent) => { this.log?.info( @@ -196,7 +236,7 @@ export class MongoshLoggingAndTelemetry { } ); - onBus('mongosh:connect', (args: ConnectEvent) => { + this.onBus('mongosh:connect', (args: ConnectEvent) => { const { uri, resolved_hostname, ...argsWithoutUriAndHostname } = args; const connectionUri = uri && redactURICredentials(uri); const atlasHostname = { @@ -228,7 +268,7 @@ export class MongoshLoggingAndTelemetry { }); }); - onBus('mongosh:start-session', (args: SessionStartedEvent) => { + this.onBus('mongosh:start-session', (args: SessionStartedEvent) => { const normalizedTimingsArray = Object.entries(args.timings).map( ([key, duration]) => { const snakeCaseKey = toSnakeCase(key); @@ -249,7 +289,7 @@ export class MongoshLoggingAndTelemetry { }); }); - onBus( + this.onBus( 'mongosh:new-user', (newTelemetryUserIdentity: { userId: string; anonymousId: string }) => { if (!newTelemetryUserIdentity.anonymousId) { @@ -263,7 +303,7 @@ export class MongoshLoggingAndTelemetry { } ); - onBus( + this.onBus( 'mongosh:update-user', (updatedTelemetryUserIdentity: { userId: string; @@ -287,7 +327,7 @@ export class MongoshLoggingAndTelemetry { } ); - onBus('mongosh:error', (error: Error, context: string) => { + this.onBus('mongosh:error', (error: Error, context: string) => { const mongoshError = error as { name: string; message: string; @@ -321,7 +361,7 @@ export class MongoshLoggingAndTelemetry { } }); - onBus('mongosh:write-custom-log', (event: WriteCustomLogEvent) => { + this.onBus('mongosh:write-custom-log', (event: WriteCustomLogEvent) => { if (this.log) { this.log[event.method]( 'MONGOSH-SCRIPTS', @@ -334,17 +374,20 @@ export class MongoshLoggingAndTelemetry { } }); - onBus('mongosh:globalconfig-load', (args: GlobalConfigFileLoadEvent) => { - this.log?.info( - 'MONGOSH', - mongoLogId(1_000_000_048), - 'config', - 'Loading global configuration file', - args - ); - }); + this.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.onBus('mongosh:evaluate-input', (args: EvaluateInputEvent) => { this.log?.info( 'MONGOSH', mongoLogId(1_000_000_007), @@ -354,7 +397,7 @@ export class MongoshLoggingAndTelemetry { ); }); - onBus('mongosh:use', (args: UseEvent) => { + this.onBus('mongosh:use', (args: UseEvent) => { this.log?.info( 'MONGOSH', mongoLogId(1_000_000_008), @@ -372,7 +415,7 @@ export class MongoshLoggingAndTelemetry { }); }); - onBus('mongosh:show', (args: ShowEvent) => { + this.onBus('mongosh:show', (args: ShowEvent) => { this.log?.info( 'MONGOSH', mongoLogId(1_000_000_009), @@ -391,7 +434,7 @@ export class MongoshLoggingAndTelemetry { }); }); - onBus('mongosh:setCtx', (args: ApiEventWithArguments) => { + this.onBus('mongosh:setCtx', (args: ApiEventWithArguments) => { this.log?.info( 'MONGOSH', mongoLogId(1_000_000_010), @@ -401,24 +444,27 @@ export class MongoshLoggingAndTelemetry { ); }); - 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.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) + ); } - this.log?.info( - 'MONGOSH', - mongoLogId(1_000_000_011), - 'shell-api', - 'Performed API call', - redactInfo(arg) - ); - }); + ); - onBus('mongosh:api-load-file', (args: ScriptLoadFileEvent) => { + this.onBus('mongosh:api-load-file', (args: ScriptLoadFileEvent) => { this.log?.info( 'MONGOSH', mongoLogId(1_000_000_012), @@ -442,7 +488,7 @@ export class MongoshLoggingAndTelemetry { }); }); - onBus('mongosh:eval-cli-script', () => { + this.onBus('mongosh:eval-cli-script', () => { this.log?.info( 'MONGOSH', mongoLogId(1_000_000_013), @@ -460,7 +506,7 @@ export class MongoshLoggingAndTelemetry { }); }); - onBus('mongosh:mongoshrc-load', () => { + this.onBus('mongosh:mongoshrc-load', () => { this.log?.info( 'MONGOSH', mongoLogId(1_000_000_014), @@ -477,7 +523,7 @@ export class MongoshLoggingAndTelemetry { }); }); - onBus('mongosh:mongoshrc-mongorc-warn', () => { + this.onBus('mongosh:mongoshrc-mongorc-warn', () => { this.log?.info( 'MONGOSH', mongoLogId(1_000_000_015), @@ -494,30 +540,36 @@ export class MongoshLoggingAndTelemetry { }); }); - 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 - ); - }); + this.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, - } - ); - }); + this.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.onBus('mongosh-snippets:loaded', (ev: SnippetsLoadedEvent) => { this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_019), @@ -527,7 +579,7 @@ export class MongoshLoggingAndTelemetry { ); }); - onBus('mongosh-snippets:npm-lookup', (ev: SnippetsNpmLookupEvent) => { + this.onBus('mongosh-snippets:npm-lookup', (ev: SnippetsNpmLookupEvent) => { this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_020), @@ -537,7 +589,7 @@ export class MongoshLoggingAndTelemetry { ); }); - onBus('mongosh-snippets:npm-lookup-stopped', () => { + this.onBus('mongosh-snippets:npm-lookup-stopped', () => { this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_021), @@ -546,7 +598,7 @@ export class MongoshLoggingAndTelemetry { ); }); - onBus( + this.onBus( 'mongosh-snippets:npm-download-failed', (ev: SnippetsNpmDownloadFailedEvent) => { this.log?.info( @@ -559,7 +611,7 @@ export class MongoshLoggingAndTelemetry { } ); - onBus( + this.onBus( 'mongosh-snippets:npm-download-active', (ev: SnippetsNpmDownloadActiveEvent) => { this.log?.info( @@ -572,17 +624,20 @@ export class MongoshLoggingAndTelemetry { } ); - onBus('mongosh-snippets:fetch-index', (ev: SnippetsFetchIndexEvent) => { - this.log?.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_024), - 'snippets', - 'Fetching snippet index', - ev - ); - }); + this.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.onBus('mongosh-snippets:fetch-cache-invalid', () => { this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_025), @@ -591,7 +646,7 @@ export class MongoshLoggingAndTelemetry { ); }); - onBus( + this.onBus( 'mongosh-snippets:fetch-index-error', (ev: SnippetsFetchIndexErrorEvent) => { this.log?.info( @@ -604,7 +659,7 @@ export class MongoshLoggingAndTelemetry { } ); - onBus('mongosh-snippets:fetch-index-done', () => { + this.onBus('mongosh-snippets:fetch-index-done', () => { this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_027), @@ -612,7 +667,7 @@ export class MongoshLoggingAndTelemetry { 'Fetching snippet index done' ); }); - onBus( + this.onBus( 'mongosh-snippets:package-json-edit-error', (ev: SnippetsErrorEvent) => { this.log?.info( @@ -625,7 +680,7 @@ export class MongoshLoggingAndTelemetry { } ); - onBus('mongosh-snippets:spawn-child', (ev: SnippetsRunNpmEvent) => { + this.onBus('mongosh-snippets:spawn-child', (ev: SnippetsRunNpmEvent) => { this.log?.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_029), @@ -635,37 +690,43 @@ export class MongoshLoggingAndTelemetry { ); }); - onBus('mongosh-snippets:load-snippet', (ev: SnippetsLoadSnippetEvent) => { - this.log?.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_030), - 'snippets', - 'Loading snippet', - ev - ); - }); + this.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 - ); + this.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({ - ...this._getTelemetryUserIdentity(), - event: 'Snippet Install', - properties: { - ...this.trackingProperties, - }, - }); + if (ev.args[0] === 'install') { + this.analytics.track({ + ...this._getTelemetryUserIdentity(), + event: 'Snippet Install', + properties: { + ...this.trackingProperties, + }, + }); + } } - }); + ); - onBus( + this.onBus( 'mongosh-snippets:transform-error', (ev: SnippetsTransformErrorEvent) => { this.log?.info( @@ -678,7 +739,7 @@ export class MongoshLoggingAndTelemetry { } ); - onBus('mongosh:api-call', (ev: ApiEvent) => { + this.onBus('mongosh:api-call', (ev: ApiEvent) => { // Only track if we have previously seen a mongosh:evaluate-started call if (!this.apiCallTracking.isEnabled) return; const { apiCalls, deprecatedApiCalls } = this.apiCallTracking; @@ -689,7 +750,7 @@ export class MongoshLoggingAndTelemetry { apiCalls.add({ class: ev.class, method: ev.method }); } }); - onBus('mongosh:evaluate-started', () => { + this.onBus('mongosh:evaluate-started', () => { const { apiCalls, deprecatedApiCalls } = this.apiCallTracking; this.apiCallTracking.isEnabled = true; // Clear API calls before evaluation starts. This is important because @@ -699,7 +760,7 @@ export class MongoshLoggingAndTelemetry { deprecatedApiCalls.clear(); apiCalls.clear(); }); - onBus('mongosh:evaluate-finished', () => { + this.onBus('mongosh:evaluate-finished', () => { const { apiCalls, deprecatedApiCalls } = this.apiCallTracking; for (const [entry] of deprecatedApiCalls) { this.log?.warn( @@ -739,7 +800,7 @@ export class MongoshLoggingAndTelemetry { // devtools-connect package which was split out from mongosh. // 'mongodb' is not supported in startup snapshots yet. - onBus('mongosh-sp:reset-connection-options', () => { + this.onBus('mongosh-sp:reset-connection-options', () => { this.log?.info( 'MONGOSH-SP', mongoLogId(1_000_000_040), @@ -748,7 +809,7 @@ export class MongoshLoggingAndTelemetry { ); }); - onBus( + this.onBus( 'mongosh-editor:run-edit-command', (ev: EditorRunEditCommandEvent) => { this.log?.error( @@ -761,7 +822,7 @@ export class MongoshLoggingAndTelemetry { } ); - onBus( + this.onBus( 'mongosh-editor:read-vscode-extensions-done', (ev: EditorReadVscodeExtensionsDoneEvent) => { this.log?.error( @@ -774,7 +835,7 @@ export class MongoshLoggingAndTelemetry { } ); - onBus( + this.onBus( 'mongosh-editor:read-vscode-extensions-failed', (ev: EditorReadVscodeExtensionsFailedEvent) => { this.log?.error( @@ -790,7 +851,7 @@ export class MongoshLoggingAndTelemetry { } ); - onBus( + this.onBus( 'mongosh:fetching-update-metadata', (ev: FetchingUpdateMetadataEvent) => { this.log?.info( @@ -805,7 +866,7 @@ export class MongoshLoggingAndTelemetry { } ); - onBus( + this.onBus( 'mongosh:fetching-update-metadata-complete', (ev: FetchingUpdateMetadataCompleteEvent) => { this.log?.info( From f0b46ce49f935f06f85b09d734903764b2889982 Mon Sep 17 00:00:00 2001 From: gagik Date: Fri, 31 Jan 2025 13:40:46 +0100 Subject: [PATCH 10/15] refactor: use a setup function and simplify state Moved public-facing API to a function and interface. Reuse the same log writer in cli-repl. Removed session_id as a stored state and instead provide it dynamically through this.log. --- packages/cli-repl/src/cli-repl.spec.ts | 2 +- packages/cli-repl/src/cli-repl.ts | 79 ++- packages/e2e-tests/test/e2e.spec.ts | 28 +- packages/e2e-tests/test/test-shell.ts | 11 +- packages/logging/src/index.ts | 3 +- .../logging/src/logging-and-telemetry.spec.ts | 40 +- packages/logging/src/logging-and-telemetry.ts | 659 +++++++++--------- packages/logging/src/types.ts | 35 + 8 files changed, 438 insertions(+), 419 deletions(-) create mode 100644 packages/logging/src/types.ts diff --git a/packages/cli-repl/src/cli-repl.spec.ts b/packages/cli-repl/src/cli-repl.spec.ts index 754a201f8e..bf548b221e 100644 --- a/packages/cli-repl/src/cli-repl.spec.ts +++ b/packages/cli-repl/src/cli-repl.spec.ts @@ -1559,7 +1559,7 @@ 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'); diff --git a/packages/cli-repl/src/cli-repl.ts b/packages/cli-repl/src/cli-repl.ts index a93c4f6736..19c47c7e9c 100644 --- a/packages/cli-repl/src/cli-repl.ts +++ b/packages/cli-repl/src/cli-repl.ts @@ -30,7 +30,8 @@ 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 { MongoshLoggingAndTelemetry } from '@mongosh/logging'; +import type { MongoshLoggingAndTelemetry } from '@mongosh/logging'; +import { setupLoggingAndTelemetry } from '@mongosh/logging'; import { ToggleableAnalytics, ThrottledAnalytics, @@ -254,36 +255,44 @@ export class CliRepl implements MongoshIOProvider { throw new Error('Logging and telemetry not setup'); } - if (!this.logManager) { - 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.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), + }); 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`); + + 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.logWriter = logger; - this.loggingAndTelemetry.attachLogger(logger); + this.loggingAndTelemetry.attachLogger(this.logWriter); - 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()), - }); + 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'); } @@ -350,18 +359,17 @@ export class CliRepl implements MongoshIOProvider { markTime(TimingCategories.Telemetry, 'created analytics instance'); - this.loggingAndTelemetry = new MongoshLoggingAndTelemetry( - this.bus, - 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 - ); - this.loggingAndTelemetry.setup(); + mongoshVersion: version, + }); markTime(TimingCategories.Telemetry, 'completed telemetry setup'); @@ -628,14 +636,9 @@ export class CliRepl implements MongoshIOProvider { async setLoggingEnabled(enabled: boolean): Promise { if (enabled) { - if (!this.logWriter) { - await this.startLogging(); - } - // Do nothing if there is already an active log writer. + await this.startLogging(); } else { this.loggingAndTelemetry?.detachLogger(); - this.logWriter?.destroy(); - this.logWriter = undefined; } } diff --git a/packages/e2e-tests/test/e2e.spec.ts b/packages/e2e-tests/test/e2e.spec.ts index 8ed230fd33..df2cb97fc1 100644 --- a/packages/e2e-tests/test/e2e.spec.ts +++ b/packages/e2e-tests/test/e2e.spec.ts @@ -1594,10 +1594,20 @@ describe('e2e', function () { ).to.have.lengthOf(1); }); - it('starts writing to a new log from the point where disableLogging is set to false', async function () { + it('starts writing to the same log from the point where disableLogging is set to false', async function () { + expect(await shell.executeLine('print(222 - 111)')).to.include('111'); + + let log = await readLogFile(); + expect( + log.filter( + (logEntry) => logEntry.attr?.input === 'print(222 - 111)' + ) + ).to.have.lengthOf(1); + await shell.executeLine(`config.set("disableLogging", true)`); expect(await shell.executeLine('print(123 + 456)')).to.include('579'); - const log = await readLogFile(); + + log = await readLogFile(); const oldLogId = shell.logId; expect(oldLogId).not.null; @@ -1617,15 +1627,21 @@ describe('e2e', function () { const newLogId = shell.logId; expect(newLogId).not.null; - expect(oldLogId).not.equal(newLogId); - const logsAfterEnabling = await readLogFile(); + expect(oldLogId).equals(newLogId); + log = await readLogFile(); + expect( - logsAfterEnabling.filter( + log.filter( + (logEntry) => logEntry.attr?.input === 'print(222 - 111)' + ) + ).to.have.lengthOf(1); + expect( + log.filter( (logEntry) => logEntry.attr?.input === 'print(579 - 123)' ) ).to.have.lengthOf(1); expect( - logsAfterEnabling.filter( + log.filter( (logEntry) => logEntry.attr?.input === 'print(123 + 456)' ) ).to.have.lengthOf(0); diff --git a/packages/e2e-tests/test/test-shell.ts b/packages/e2e-tests/test/test-shell.ts index 64b6987acf..3a5d870b82 100644 --- a/packages/e2e-tests/test/test-shell.ts +++ b/packages/e2e-tests/test/test-shell.ts @@ -362,15 +362,12 @@ export class TestShell { } get logId(): string | null { - const matches = this._output.match( - /^Current Mongosh Log ID:\s*([a-z0-9]{24})$/gm + const match = /^Current Mongosh Log ID:\s*(?[a-z0-9]{24})$/m.exec( + this._output ); - if (!matches || matches.length === 0) { + if (!match) { return null; } - const lastMatch = /^Current Mongosh Log ID:\s*([a-z0-9]{24})$/.exec( - matches[matches.length - 1] - ); - return lastMatch ? lastMatch[1] : null; + return match.groups!.logId; } } diff --git a/packages/logging/src/index.ts b/packages/logging/src/index.ts index d14b18af7a..1c6ecba793 100644 --- a/packages/logging/src/index.ts +++ b/packages/logging/src/index.ts @@ -1,4 +1,3 @@ -export { MongoshLoggingAndTelemetry } from './logging-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/logging-and-telemetry.spec.ts b/packages/logging/src/logging-and-telemetry.spec.ts index fa9e857397..bfcfd8af78 100644 --- a/packages/logging/src/logging-and-telemetry.spec.ts +++ b/packages/logging/src/logging-and-telemetry.spec.ts @@ -5,7 +5,8 @@ import { EventEmitter } from 'events'; import { MongoshInvalidInputError } from '@mongosh/errors'; import type { MongoshBus } from '@mongosh/types'; import type { Writable } from 'stream'; -import { MongoshLoggingAndTelemetry } from './logging-and-telemetry'; +import type { MongoshLoggingAndTelemetry } from '.'; +import { setupLoggingAndTelemetry } from '.'; describe('MongoshLoggingAndTelemetry', function () { let logOutput: any[]; @@ -36,15 +37,15 @@ describe('MongoshLoggingAndTelemetry', function () { analyticsOutput = []; bus = new EventEmitter(); - loggingAndTelemetry = new MongoshLoggingAndTelemetry( + loggingAndTelemetry = setupLoggingAndTelemetry({ bus, 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) { @@ -62,22 +63,7 @@ describe('MongoshLoggingAndTelemetry', function () { logger.destroy(); }); - it('throws when running setup twice', function () { - loggingAndTelemetry.setup(); - - expect(() => loggingAndTelemetry.setup()).throws( - 'Setup can only be called once.' - ); - }); - - it('throws when trying to setup writer prematurely', function () { - expect(() => loggingAndTelemetry.attachLogger(logger)).throws( - 'Run setup() before setting up the log writer.' - ); - }); - it('throws when running attachLogger twice without detaching', function () { - loggingAndTelemetry.setup(); loggingAndTelemetry.attachLogger(logger); expect(() => loggingAndTelemetry.attachLogger(logger)).throws( 'Previously set logger has not been detached. Run detachLogger() before setting.' @@ -85,14 +71,12 @@ describe('MongoshLoggingAndTelemetry', function () { }); it('does not throw when attaching and detaching loggers', function () { - loggingAndTelemetry.setup(); loggingAndTelemetry.attachLogger(logger); loggingAndTelemetry.detachLogger(); expect(() => loggingAndTelemetry.attachLogger(logger)).does.not.throw(); }); it('tracks new local connection events', function () { - loggingAndTelemetry.setup(); loggingAndTelemetry.attachLogger(logger); expect(logOutput).to.have.lengthOf(0); @@ -147,7 +131,6 @@ describe('MongoshLoggingAndTelemetry', function () { }); it('tracks new atlas connection events', function () { - loggingAndTelemetry.setup(); loggingAndTelemetry.attachLogger(logger); expect(logOutput).to.have.lengthOf(0); @@ -206,7 +189,6 @@ describe('MongoshLoggingAndTelemetry', function () { }); it('detaching logger leads to no logging but persists analytics', function () { - loggingAndTelemetry.setup(); loggingAndTelemetry.attachLogger(logger); expect(logOutput).to.have.lengthOf(0); @@ -222,7 +204,6 @@ describe('MongoshLoggingAndTelemetry', function () { }); it('detaching logger applies to devtools-connect events', function () { - loggingAndTelemetry.setup(); loggingAndTelemetry.attachLogger(logger); bus.emit('devtools-connect:connect-fail-early'); @@ -241,11 +222,11 @@ describe('MongoshLoggingAndTelemetry', function () { loggingAndTelemetry.attachLogger(logger); bus.emit('devtools-connect:connect-fail-early'); - expect(logOutput).to.have.lengthOf(3); + 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.setup(); loggingAndTelemetry.attachLogger(logger); expect(logOutput).to.have.lengthOf(0); @@ -266,7 +247,6 @@ describe('MongoshLoggingAndTelemetry', function () { }); it('detaching logger is recoverable', function () { - loggingAndTelemetry.setup(); loggingAndTelemetry.attachLogger(logger); expect(logOutput).to.have.lengthOf(0); @@ -294,7 +274,6 @@ describe('MongoshLoggingAndTelemetry', function () { }); it('tracks a sequence of events', function () { - loggingAndTelemetry.setup(); loggingAndTelemetry.attachLogger(logger); expect(logOutput).to.have.lengthOf(0); @@ -757,7 +736,6 @@ describe('MongoshLoggingAndTelemetry', function () { }); it('buffers deprecated API calls', function () { - loggingAndTelemetry.setup(); loggingAndTelemetry.attachLogger(logger); expect(logOutput).to.have.lengthOf(0); @@ -933,7 +911,6 @@ describe('MongoshLoggingAndTelemetry', function () { }); it('does not track database calls outside of evaluate-{started,finished}', function () { - loggingAndTelemetry.setup(); loggingAndTelemetry.attachLogger(logger); expect(logOutput).to.have.lengthOf(0); @@ -961,7 +938,6 @@ describe('MongoshLoggingAndTelemetry', function () { expect(logOutput).to.have.lengthOf(0); expect(analyticsOutput).to.be.empty; - loggingAndTelemetry.setup(); loggingAndTelemetry.attachLogger(logger); bus.emit('mongosh:connect', { diff --git a/packages/logging/src/logging-and-telemetry.ts b/packages/logging/src/logging-and-telemetry.ts index 39dae78ea8..1bf0d2f1ea 100644 --- a/packages/logging/src/logging-and-telemetry.ts +++ b/packages/logging/src/logging-and-telemetry.ts @@ -46,229 +46,216 @@ 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; +} -export class MongoshLoggingAndTelemetry { - private log: MongoLogWriter | null; +class LoggingAndTelemetry implements MongoshLoggingAndTelemetry { + private static dummyLogger = new MongoLogWriter( + '', + null, + new Writable({ + write(chunk, encoding, callback) { + callback(); + }, + }) + ); - private readonly trackingProperties: { - mongosh_version: string; - session_id: string; - }; - private readonly userTraits: AnalyticsIdentifyMessage['traits'] & { + 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 telemetryAnonymousId: string | undefined; - private userId: string | undefined; - private isDummyLog = true; private isSetup = false; - private hookedExternalListenersLogId: string | undefined = undefined; - - constructor( - private readonly bus: MongoshBus, - private readonly analytics: MongoshAnalytics, - providedTraits: { platform: string } & { - [key: string]: unknown; - }, - mongoshVersion: string - ) { - const dummySink = new Writable({ - write(chunk, encoding, callback) { - callback(); - }, - }); - this.log = new MongoLogWriter('', null, dummySink); - - this.userTraits = { - ...providedTraits, - session_id: this.log.logId, - }; - - this.trackingProperties = { - mongosh_version: mongoshVersion, - session_id: this.log.logId, - }; + 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.setupBusEventListeners(); this.isSetup = true; + this.isBufferingEvents = true; } - 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 is used to suppress externally defined listeners which - * only emit log events such as those from devtools-connect. - */ - suppressWhenLogIsNullOrDummy = false, - } = {} - ) => { - this.bus.on(event, ((...args: Parameters) => { - if ( - (this.log === null || this.isDummyLog) && - suppressWhenLogIsNullOrDummy - ) { - return; - } - - const isLoggerAttachedOrNull = - (this.log && !this.isDummyLog) || this.log === null; - if (isLoggerAttachedOrNull) { - listener(...args); - } else { - this.pendingLogEvents.push(() => listener(...args)); - } - }) as MongoshBusEventsMap[K]); - return this.bus; - }; - 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 && !this.isDummyLog) { + 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.userTraits.session_id = this.log.logId; - this.trackingProperties.session_id = this.log.logId; - - this.isDummyLog = false; - if (this.hookedExternalListenersLogId !== this.log.logId) { - hookLogger( - { - ...this.bus, - on: (event, listener) => - this.onBus( - event, - listener as (...args: unknown[]) => void, - { suppressWhenLogIsNullOrDummy: true } - ), - }, - this.log, - 'mongosh', - (uri) => redactURICredentials(uri) - ); - - this.hookedExternalListenersLogId = this.log.logId; - } - - this.runAndCleanPendingEvents(); + this.runAndClearPendingEvents(); this.bus.emit('mongosh:log-initialized'); } public detachLogger() { - this.log = null; - // Still run any remaining pending events for telemetry purposes. - this.runAndCleanPendingEvents(); + this.log = LoggingAndTelemetry.dummyLogger; + // Still run any remaining pending events with the dummy log for telemetry purposes. + this.runAndClearPendingEvents(); } - private runAndCleanPendingEvents() { - for (const pendingEvent of this.pendingLogEvents) { + private runAndClearPendingEvents() { + let pendingEvent: CallableFunction | undefined; + while ((pendingEvent = this.pendingLogEvents.shift())) { pendingEvent(); } - this.pendingLogEvents = []; } - private _getTelemetryUserIdentity(): MongoshAnalyticsIdentity { - return { - anonymousId: this.telemetryAnonymousId ?? (this.userId as string), + /** 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; }; - } - /** 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. */ - private hasStartedMongoshRepl = false; + const getUserTraits = (): AnalyticsIdentifyMessage['traits'] => ({ + ...this.userTraits, + session_id: this.log.logId, + }); + + const getTrackingProperties = (): MongoshTrackingProperties => ({ + mongosh_version: this.mongoshVersion, + session_id: this.log.logId, + }); - private apiCallTracking = { - isEnabled: false, - apiCalls: new MultiSet>(), - deprecatedApiCalls: new MultiSet>(), - }; - private usesShellOption = false; + const getTelemetryUserIdentity = (): MongoshAnalyticsIdentity => { + return { + anonymousId: + this.busEventState.telemetryAnonymousId ?? + (this.busEventState.userId as string), + }; + }; - private _setupBusEventListeners(): void { - this.onBus('mongosh:start-mongosh-repl', (ev: StartMongoshReplEvent) => { - this.log?.info( + onBus('mongosh:start-mongosh-repl', (ev: StartMongoshReplEvent) => { + this.log.info( 'MONGOSH', mongoLogId(1_000_000_002), 'repl', 'Started REPL', ev ); - this.hasStartedMongoshRepl = true; + this.busEventState.hasStartedMongoshRepl = true; }); - this.onBus( + onBus( 'mongosh:start-loading-cli-scripts', (event: StartLoadingCliScriptsEvent) => { - this.log?.info( + this.log.info( 'MONGOSH', mongoLogId(1_000_000_003), 'repl', 'Start loading CLI scripts' ); - this.usesShellOption = event.usesShellOption; + this.busEventState.usesShellOption = event.usesShellOption; } ); - this.onBus('mongosh:connect', (args: ConnectEvent) => { + 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 = { - ...this.trackingProperties, + ...getTrackingProperties(), ...argsWithoutUriAndHostname, ...atlasHostname, }; - this.log?.info( + this.log.info( 'MONGOSH', mongoLogId(1_000_000_004), 'connect', 'Connecting to server', { - userId: this.userId, - telemetryAnonymousId: this.telemetryAnonymousId, + userId: this.busEventState.userId, + telemetryAnonymousId: this.busEventState.telemetryAnonymousId, connectionUri, ...properties, } ); this.analytics.track({ - ...this._getTelemetryUserIdentity(), + ...getTelemetryUserIdentity(), event: 'New Connection', properties, }); }); - this.onBus('mongosh:start-session', (args: SessionStartedEvent) => { + onBus('mongosh:start-session', (args: SessionStartedEvent) => { const normalizedTimingsArray = Object.entries(args.timings).map( ([key, duration]) => { const snakeCaseKey = toSnakeCase(key); @@ -278,10 +265,10 @@ export class MongoshLoggingAndTelemetry { const normalizedTimings = Object.fromEntries(normalizedTimingsArray); this.analytics.track({ - ...this._getTelemetryUserIdentity(), + ...getTelemetryUserIdentity(), event: 'Startup Time', properties: { - ...this.trackingProperties, + ...getTrackingProperties(), is_interactive: args.isInteractive, js_context: args.jsContext, ...normalizedTimings, @@ -289,36 +276,38 @@ export class MongoshLoggingAndTelemetry { }); }); - this.onBus( + onBus( 'mongosh:new-user', (newTelemetryUserIdentity: { userId: string; anonymousId: string }) => { if (!newTelemetryUserIdentity.anonymousId) { - this.userId = newTelemetryUserIdentity.userId; + this.busEventState.userId = newTelemetryUserIdentity.userId; } - this.telemetryAnonymousId = newTelemetryUserIdentity.anonymousId; + this.busEventState.telemetryAnonymousId = + newTelemetryUserIdentity.anonymousId; this.analytics.identify({ anonymousId: newTelemetryUserIdentity.anonymousId, - traits: this.userTraits, + traits: getUserTraits(), }); } ); - this.onBus( + onBus( 'mongosh:update-user', (updatedTelemetryUserIdentity: { userId: string; anonymousId?: string; }) => { if (updatedTelemetryUserIdentity.anonymousId) { - this.telemetryAnonymousId = updatedTelemetryUserIdentity.anonymousId; + this.busEventState.telemetryAnonymousId = + updatedTelemetryUserIdentity.anonymousId; } else { - this.userId = updatedTelemetryUserIdentity.userId; + this.busEventState.userId = updatedTelemetryUserIdentity.userId; } this.analytics.identify({ - ...this._getTelemetryUserIdentity(), - traits: this.userTraits, + ...getTelemetryUserIdentity(), + traits: getUserTraits(), }); - this.log?.info( + this.log.info( 'MONGOSH', mongoLogId(1_000_000_005), 'config', @@ -327,7 +316,7 @@ export class MongoshLoggingAndTelemetry { } ); - this.onBus('mongosh:error', (error: Error, context: string) => { + onBus('mongosh:error', (error: Error, context: string) => { const mongoshError = error as { name: string; message: string; @@ -348,10 +337,10 @@ export class MongoshLoggingAndTelemetry { if (error.name.includes('Mongosh')) { this.analytics.track({ - ...this._getTelemetryUserIdentity(), + ...getTelemetryUserIdentity(), event: 'Error', properties: { - ...this.trackingProperties, + ...getTrackingProperties(), name: mongoshError.name, code: mongoshError.code, scope: mongoshError.scope, @@ -361,7 +350,7 @@ export class MongoshLoggingAndTelemetry { } }); - this.onBus('mongosh:write-custom-log', (event: WriteCustomLogEvent) => { + onBus('mongosh:write-custom-log', (event: WriteCustomLogEvent) => { if (this.log) { this.log[event.method]( 'MONGOSH-SCRIPTS', @@ -374,21 +363,18 @@ export class MongoshLoggingAndTelemetry { } }); - this.onBus( - 'mongosh:globalconfig-load', - (args: GlobalConfigFileLoadEvent) => { - this.log?.info( - 'MONGOSH', - mongoLogId(1_000_000_048), - 'config', - 'Loading global configuration file', - args - ); - } - ); + onBus('mongosh:globalconfig-load', (args: GlobalConfigFileLoadEvent) => { + this.log.info( + 'MONGOSH', + mongoLogId(1_000_000_048), + 'config', + 'Loading global configuration file', + args + ); + }); - this.onBus('mongosh:evaluate-input', (args: EvaluateInputEvent) => { - this.log?.info( + onBus('mongosh:evaluate-input', (args: EvaluateInputEvent) => { + this.log.info( 'MONGOSH', mongoLogId(1_000_000_007), 'repl', @@ -397,8 +383,8 @@ export class MongoshLoggingAndTelemetry { ); }); - this.onBus('mongosh:use', (args: UseEvent) => { - this.log?.info( + onBus('mongosh:use', (args: UseEvent) => { + this.log.info( 'MONGOSH', mongoLogId(1_000_000_008), 'shell-api', @@ -407,16 +393,16 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this._getTelemetryUserIdentity(), + ...getTelemetryUserIdentity(), event: 'Use', properties: { - ...this.trackingProperties, + ...getTrackingProperties(), }, }); }); - this.onBus('mongosh:show', (args: ShowEvent) => { - this.log?.info( + onBus('mongosh:show', (args: ShowEvent) => { + this.log.info( 'MONGOSH', mongoLogId(1_000_000_009), 'shell-api', @@ -425,17 +411,17 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this._getTelemetryUserIdentity(), + ...getTelemetryUserIdentity(), event: 'Show', properties: { - ...this.trackingProperties, + ...getTrackingProperties(), method: args.method, }, }); }); - this.onBus('mongosh:setCtx', (args: ApiEventWithArguments) => { - this.log?.info( + onBus('mongosh:setCtx', (args: ApiEventWithArguments) => { + this.log.info( 'MONGOSH', mongoLogId(1_000_000_010), 'shell-api', @@ -444,28 +430,25 @@ export class MongoshLoggingAndTelemetry { ); }); - this.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-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) + ); + }); - this.onBus('mongosh:api-load-file', (args: ScriptLoadFileEvent) => { - this.log?.info( + onBus('mongosh:api-load-file', (args: ScriptLoadFileEvent) => { + this.log.info( 'MONGOSH', mongoLogId(1_000_000_012), 'shell-api', @@ -474,22 +457,22 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this._getTelemetryUserIdentity(), - event: this.hasStartedMongoshRepl + ...getTelemetryUserIdentity(), + event: this.busEventState.hasStartedMongoshRepl ? 'Script Loaded' : 'Script Loaded CLI', properties: { - ...this.trackingProperties, + ...getTrackingProperties(), nested: args.nested, - ...(this.hasStartedMongoshRepl + ...(this.busEventState.hasStartedMongoshRepl ? {} - : { shell: this.usesShellOption }), + : { shell: this.busEventState.usesShellOption }), }, }); }); - this.onBus('mongosh:eval-cli-script', () => { - this.log?.info( + onBus('mongosh:eval-cli-script', () => { + this.log.info( 'MONGOSH', mongoLogId(1_000_000_013), 'repl', @@ -497,17 +480,17 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this._getTelemetryUserIdentity(), + ...getTelemetryUserIdentity(), event: 'Script Evaluated', properties: { - ...this.trackingProperties, - shell: this.usesShellOption, + ...getTrackingProperties(), + shell: this.busEventState.usesShellOption, }, }); }); - this.onBus('mongosh:mongoshrc-load', () => { - this.log?.info( + onBus('mongosh:mongoshrc-load', () => { + this.log.info( 'MONGOSH', mongoLogId(1_000_000_014), 'repl', @@ -515,16 +498,16 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this._getTelemetryUserIdentity(), + ...getTelemetryUserIdentity(), event: 'Mongoshrc Loaded', properties: { - ...this.trackingProperties, + ...getTrackingProperties(), }, }); }); - this.onBus('mongosh:mongoshrc-mongorc-warn', () => { - this.log?.info( + onBus('mongosh:mongoshrc-mongorc-warn', () => { + this.log.info( 'MONGOSH', mongoLogId(1_000_000_015), 'repl', @@ -532,45 +515,39 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this._getTelemetryUserIdentity(), + ...getTelemetryUserIdentity(), event: 'Mongorc Warning', properties: { - ...this.trackingProperties, + ...getTrackingProperties(), }, }); }); - this.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-skip', (ev: CryptLibrarySkipEvent) => { + this.log.info( + 'AUTO-ENCRYPTION', + mongoLogId(1_000_000_050), + 'crypt-library', + 'Skipping shared library candidate', + ev + ); + }); - this.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: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, + } + ); + }); - this.onBus('mongosh-snippets:loaded', (ev: SnippetsLoadedEvent) => { - this.log?.info( + onBus('mongosh-snippets:loaded', (ev: SnippetsLoadedEvent) => { + this.log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_019), 'snippets', @@ -579,8 +556,8 @@ export class MongoshLoggingAndTelemetry { ); }); - this.onBus('mongosh-snippets:npm-lookup', (ev: SnippetsNpmLookupEvent) => { - this.log?.info( + onBus('mongosh-snippets:npm-lookup', (ev: SnippetsNpmLookupEvent) => { + this.log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_020), 'snippets', @@ -589,8 +566,8 @@ export class MongoshLoggingAndTelemetry { ); }); - this.onBus('mongosh-snippets:npm-lookup-stopped', () => { - this.log?.info( + onBus('mongosh-snippets:npm-lookup-stopped', () => { + this.log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_021), 'snippets', @@ -598,10 +575,10 @@ export class MongoshLoggingAndTelemetry { ); }); - this.onBus( + onBus( 'mongosh-snippets:npm-download-failed', (ev: SnippetsNpmDownloadFailedEvent) => { - this.log?.info( + this.log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_022), 'snippets', @@ -611,10 +588,10 @@ export class MongoshLoggingAndTelemetry { } ); - this.onBus( + onBus( 'mongosh-snippets:npm-download-active', (ev: SnippetsNpmDownloadActiveEvent) => { - this.log?.info( + this.log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_023), 'snippets', @@ -624,21 +601,18 @@ export class MongoshLoggingAndTelemetry { } ); - this.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-index', (ev: SnippetsFetchIndexEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_024), + 'snippets', + 'Fetching snippet index', + ev + ); + }); - this.onBus('mongosh-snippets:fetch-cache-invalid', () => { - this.log?.info( + onBus('mongosh-snippets:fetch-cache-invalid', () => { + this.log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_025), 'snippets', @@ -646,10 +620,10 @@ export class MongoshLoggingAndTelemetry { ); }); - this.onBus( + onBus( 'mongosh-snippets:fetch-index-error', (ev: SnippetsFetchIndexErrorEvent) => { - this.log?.info( + this.log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_026), 'snippets', @@ -659,18 +633,18 @@ export class MongoshLoggingAndTelemetry { } ); - this.onBus('mongosh-snippets:fetch-index-done', () => { - this.log?.info( + onBus('mongosh-snippets:fetch-index-done', () => { + this.log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_027), 'snippets', 'Fetching snippet index done' ); }); - this.onBus( + onBus( 'mongosh-snippets:package-json-edit-error', (ev: SnippetsErrorEvent) => { - this.log?.info( + this.log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_028), 'snippets', @@ -680,8 +654,8 @@ export class MongoshLoggingAndTelemetry { } ); - this.onBus('mongosh-snippets:spawn-child', (ev: SnippetsRunNpmEvent) => { - this.log?.info( + onBus('mongosh-snippets:spawn-child', (ev: SnippetsRunNpmEvent) => { + this.log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_029), 'snippets', @@ -690,46 +664,40 @@ export class MongoshLoggingAndTelemetry { ); }); - this.onBus( - 'mongosh-snippets:load-snippet', - (ev: SnippetsLoadSnippetEvent) => { - this.log?.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_030), - 'snippets', - 'Loading snippet', - ev - ); - } - ); + onBus('mongosh-snippets:load-snippet', (ev: SnippetsLoadSnippetEvent) => { + this.log.info( + 'MONGOSH-SNIPPETS', + mongoLogId(1_000_000_030), + 'snippets', + 'Loading snippet', + ev + ); + }); - this.onBus( - 'mongosh-snippets:snippet-command', - (ev: SnippetsCommandEvent) => { - this.log?.info( - 'MONGOSH-SNIPPETS', - mongoLogId(1_000_000_031), - 'snippets', - 'Running snippet command', - 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({ - ...this._getTelemetryUserIdentity(), - event: 'Snippet Install', - properties: { - ...this.trackingProperties, - }, - }); - } + if (ev.args[0] === 'install') { + this.analytics.track({ + ...getTelemetryUserIdentity(), + event: 'Snippet Install', + properties: { + ...getTrackingProperties(), + }, + }); } - ); + }); - this.onBus( + onBus( 'mongosh-snippets:transform-error', (ev: SnippetsTransformErrorEvent) => { - this.log?.info( + this.log.info( 'MONGOSH-SNIPPETS', mongoLogId(1_000_000_032), 'snippets', @@ -739,10 +707,11 @@ export class MongoshLoggingAndTelemetry { } ); - this.onBus('mongosh:api-call', (ev: ApiEvent) => { + onBus('mongosh:api-call', (ev: ApiEvent) => { // Only track if we have previously seen a mongosh:evaluate-started call - if (!this.apiCallTracking.isEnabled) return; - const { apiCalls, deprecatedApiCalls } = this.apiCallTracking; + if (!this.busEventState.apiCallTracking.isEnabled) return; + const { apiCalls, deprecatedApiCalls } = + this.busEventState.apiCallTracking; if (ev.deprecated) { deprecatedApiCalls.add({ class: ev.class, method: ev.method }); } @@ -750,9 +719,10 @@ export class MongoshLoggingAndTelemetry { apiCalls.add({ class: ev.class, method: ev.method }); } }); - this.onBus('mongosh:evaluate-started', () => { - const { apiCalls, deprecatedApiCalls } = this.apiCallTracking; - this.apiCallTracking.isEnabled = true; + 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 @@ -760,10 +730,11 @@ export class MongoshLoggingAndTelemetry { deprecatedApiCalls.clear(); apiCalls.clear(); }); - this.onBus('mongosh:evaluate-finished', () => { - const { apiCalls, deprecatedApiCalls } = this.apiCallTracking; + onBus('mongosh:evaluate-finished', () => { + const { apiCalls, deprecatedApiCalls } = + this.busEventState.apiCallTracking; for (const [entry] of deprecatedApiCalls) { - this.log?.warn( + this.log.warn( 'MONGOSH', mongoLogId(1_000_000_033), 'shell-api', @@ -772,20 +743,20 @@ export class MongoshLoggingAndTelemetry { ); this.analytics.track({ - ...this._getTelemetryUserIdentity(), + ...getTelemetryUserIdentity(), event: 'Deprecated Method', properties: { - ...this.trackingProperties, + ...getTrackingProperties(), ...entry, }, }); } for (const [entry, count] of apiCalls) { this.analytics.track({ - ...this._getTelemetryUserIdentity(), + ...getTelemetryUserIdentity(), event: 'API Call', properties: { - ...this.trackingProperties, + ...getTrackingProperties(), ...entry, count, }, @@ -793,15 +764,15 @@ export class MongoshLoggingAndTelemetry { } deprecatedApiCalls.clear(); apiCalls.clear(); - this.apiCallTracking.isEnabled = false; + 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. - this.onBus('mongosh-sp:reset-connection-options', () => { - this.log?.info( + onBus('mongosh-sp:reset-connection-options', () => { + this.log.info( 'MONGOSH-SP', mongoLogId(1_000_000_040), 'connect', @@ -809,10 +780,10 @@ export class MongoshLoggingAndTelemetry { ); }); - this.onBus( + onBus( 'mongosh-editor:run-edit-command', (ev: EditorRunEditCommandEvent) => { - this.log?.error( + this.log.error( 'MONGOSH-EDITOR', mongoLogId(1_000_000_047), 'editor', @@ -822,10 +793,10 @@ export class MongoshLoggingAndTelemetry { } ); - this.onBus( + onBus( 'mongosh-editor:read-vscode-extensions-done', (ev: EditorReadVscodeExtensionsDoneEvent) => { - this.log?.error( + this.log.error( 'MONGOSH-EDITOR', mongoLogId(1_000_000_043), 'editor', @@ -835,10 +806,10 @@ export class MongoshLoggingAndTelemetry { } ); - this.onBus( + onBus( 'mongosh-editor:read-vscode-extensions-failed', (ev: EditorReadVscodeExtensionsFailedEvent) => { - this.log?.error( + this.log.error( 'MONGOSH-EDITOR', mongoLogId(1_000_000_044), 'editor', @@ -851,10 +822,10 @@ export class MongoshLoggingAndTelemetry { } ); - this.onBus( + onBus( 'mongosh:fetching-update-metadata', (ev: FetchingUpdateMetadataEvent) => { - this.log?.info( + this.log.info( 'MONGOSH', mongoLogId(1_000_000_052), 'startup', @@ -866,10 +837,10 @@ export class MongoshLoggingAndTelemetry { } ); - this.onBus( + onBus( 'mongosh:fetching-update-metadata-complete', (ev: FetchingUpdateMetadataCompleteEvent) => { - this.log?.info( + this.log.info( 'MONGOSH', mongoLogId(1_000_000_053), 'startup', @@ -880,5 +851,25 @@ export class MongoshLoggingAndTelemetry { ); } ); + + 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/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; +}; From fb3e0a2ff4e7e9ff5090cf70dd735398c232591d Mon Sep 17 00:00:00 2001 From: Alena Khineika Date: Tue, 4 Feb 2025 20:39:21 +0100 Subject: [PATCH 11/15] feat(cli-repl): do not wait for log clean-up MONGOSH-1990 (#2355) * feat(cli-repl): do not wait for log clean-up MONGOSH-1990 * test: add test for log manager throwing error * test: remove only * fix: mark time after log cleanup --- packages/cli-repl/src/cli-repl.spec.ts | 31 ++++++++++++++++++++------ packages/cli-repl/src/cli-repl.ts | 11 +++++++-- 2 files changed, 33 insertions(+), 9 deletions(-) diff --git a/packages/cli-repl/src/cli-repl.spec.ts b/packages/cli-repl/src/cli-repl.spec.ts index bf548b221e..f3c9e294ec 100644 --- a/packages/cli-repl/src/cli-repl.spec.ts +++ b/packages/cli-repl/src/cli-repl.spec.ts @@ -33,7 +33,7 @@ import type { DevtoolsConnectOptions } from '@mongosh/service-provider-node-driv import type { AddressInfo } from 'net'; import sinon from 'sinon'; import type { CliUserConfig } from '@mongosh/types'; -import { MongoLogWriter } from 'mongodb-log-writer'; +import { MongoLogWriter, MongoLogManager } from 'mongodb-log-writer'; const { EJSON } = bson; const delay = promisify(setTimeout); @@ -478,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 () { @@ -1382,6 +1384,7 @@ describe('CliRepl', function () { srv.close(); await once(srv, 'close'); setTelemetryDelay(0); + sinon.restore(); }); context('logging configuration', function () { @@ -1409,6 +1412,20 @@ describe('CliRepl', function () { 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 () { diff --git a/packages/cli-repl/src/cli-repl.ts b/packages/cli-repl/src/cli-repl.ts index 19c47c7e9c..11c4076d67 100644 --- a/packages/cli-repl/src/cli-repl.ts +++ b/packages/cli-repl/src/cli-repl.ts @@ -266,8 +266,15 @@ export class CliRepl implements MongoshIOProvider { this.warnAboutInaccessibleFile(err, path), }); - await this.logManager.cleanupOldLogFiles(); - markTime(TimingCategories.Logging, 'cleaned up log files'); + // 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(); From ebb7e16ac07b76e5b61722a213e1bdc9732b768d Mon Sep 17 00:00:00 2001 From: gagik Date: Wed, 5 Feb 2025 10:51:52 +0100 Subject: [PATCH 12/15] fix: suggestions from code review Change typing of LogEntry and use EJSON.parse, remove unnecessary eslint comment --- packages/e2e-tests/test/e2e-tls.spec.ts | 11 +++---- packages/e2e-tests/test/e2e.spec.ts | 30 +++++++++---------- packages/e2e-tests/test/repl-helpers.ts | 8 +++-- packages/logging/src/logging-and-telemetry.ts | 18 +++++------ 4 files changed, 34 insertions(+), 33 deletions(-) diff --git a/packages/e2e-tests/test/e2e-tls.spec.ts b/packages/e2e-tests/test/e2e-tls.spec.ts index 9d9c53a6e8..d53c246116 100644 --- a/packages/e2e-tests/test/e2e-tls.spec.ts +++ b/packages/e2e-tests/test/e2e-tls.spec.ts @@ -243,11 +243,11 @@ describe('e2e TLS', function () { const logPath = path.join(logBasePath, `${shell.logId}_log`); const logContents = await readReplLogfile(logPath); expect( - logContents.find((line) => line.id === 1_000_000_049).attr + logContents.find((line) => line.id.__value === 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.__value === 1_000_000_049)?.attr .systemCertsError ).to.equal(null); // Ensure that system CA could be loaded successfully. }); @@ -280,11 +280,11 @@ describe('e2e TLS', function () { const logPath = path.join(logBasePath, `${shell.logId}_log`); const logContents = await readReplLogfile(logPath); expect( - logContents.find((line) => line.id === 1_000_000_049).attr + logContents.find((line) => line.id.__value === 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.__value === 1_000_000_049)?.attr .systemCertsError ).to.equal(null); // Ensure that system CA could be loaded successfully. }); @@ -309,7 +309,8 @@ describe('e2e TLS', function () { const logPath = path.join(logBasePath, `${shell.logId}_log`); const logContents = await readReplLogfile(logPath); - expect(logContents.find((line) => line.id === 1_000_000_049)).to.exist; + expect(logContents.find((line) => line.id.__value === 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 df2cb97fc1..a111bd97f5 100644 --- a/packages/e2e-tests/test/e2e.spec.ts +++ b/packages/e2e-tests/test/e2e.spec.ts @@ -22,7 +22,7 @@ import { once } from 'events'; import type { AddressInfo } from 'net'; const { EJSON } = bson; import { sleep } from './util-helpers'; -import type { LogEntry } from '@mongosh/shell-api/src/log-entry'; +import type { MongoLogEntry } from 'mongodb-log-writer'; const jsContextFlagCombinations: `--jsContext=${'plain-vm' | 'repl'}`[][] = [ [], @@ -1356,7 +1356,7 @@ describe('e2e', function () { let logBasePath: string; let historyPath: string; let readConfig: () => Promise; - let readLogFile: () => Promise; + let readLogFile: () => Promise; let startTestShell: (...extraArgs: string[]) => Promise; beforeEach(function () { @@ -1393,12 +1393,12 @@ describe('e2e', function () { } readConfig = async () => EJSON.parse(await fs.readFile(configPath, 'utf8')); - readLogFile = async () => { + 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); + return readReplLogfile(logPath); }; startTestShell = async (...extraArgs: string[]) => { const shell = this.startTestShell({ @@ -1551,7 +1551,6 @@ describe('e2e', function () { const log = await readLogFile(); expect( - // eslint-disable-next-line @typescript-eslint/no-unsafe-argument log.filter( (logEntry) => logEntry.attr?.input === 'print(123 + 456)' ) @@ -1562,7 +1561,6 @@ describe('e2e', function () { expect(await shell.executeLine('print(123 + 456)')).to.include('579'); const log = await readLogFile(); expect( - // eslint-disable-next-line @typescript-eslint/no-unsafe-argument log.filter( (logEntry) => logEntry.attr?.input === 'print(123 + 456)' ) @@ -1595,12 +1593,12 @@ describe('e2e', function () { }); it('starts writing to the same log from the point where disableLogging is set to false', async function () { - expect(await shell.executeLine('print(222 - 111)')).to.include('111'); + expect(await shell.executeLine('print(111 + 222)')).to.include('333'); let log = await readLogFile(); expect( log.filter( - (logEntry) => logEntry.attr?.input === 'print(222 - 111)' + (logEntry) => logEntry.attr?.input === 'print(111 + 222)' ) ).to.have.lengthOf(1); @@ -1632,7 +1630,7 @@ describe('e2e', function () { expect( log.filter( - (logEntry) => logEntry.attr?.input === 'print(222 - 111)' + (logEntry) => logEntry.attr?.input === 'print(111 + 222)' ) ).to.have.lengthOf(1); expect( @@ -1668,12 +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<{ - msg: string; - s: string; - c: string; - ctx: string; - }>(); + const log = await readLogFile< + MongoLogEntry & { + c: string; + ctx: string; + } + >(); const customLogEntry = log.filter((logEntry) => logEntry.msg.includes('This is a custom entry') ); @@ -1697,7 +1695,7 @@ describe('e2e', function () { await shell.executeLine(`load(${JSON.stringify(filename)})`); expect(shell.assertNoErrors()); await eventually(async () => { - const log = await readLogFile<{ msg: string }>(); + 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..99fbdaca8e 100644 --- a/packages/e2e-tests/test/repl-helpers.ts +++ b/packages/e2e-tests/test/repl-helpers.ts @@ -6,6 +6,8 @@ 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'; +import { EJSON } from 'bson'; chai.use(sinonChai); chai.use(chaiAsPromised); @@ -47,11 +49,13 @@ function useTmpdir(): { readonly path: string } { }; } -async function readReplLogfile(logPath: string) { +async function readReplLogfile( + logPath: string +): Promise { return (await fs.readFile(logPath, 'utf8')) .split('\n') .filter((line) => line.trim()) - .map((line) => JSON.parse(line)); + .map((line) => EJSON.parse(line)); } const fakeExternalEditor = async ({ diff --git a/packages/logging/src/logging-and-telemetry.ts b/packages/logging/src/logging-and-telemetry.ts index 1bf0d2f1ea..5b11ab6432 100644 --- a/packages/logging/src/logging-and-telemetry.ts +++ b/packages/logging/src/logging-and-telemetry.ts @@ -351,16 +351,14 @@ class LoggingAndTelemetry implements MongoshLoggingAndTelemetry { }); onBus('mongosh:write-custom-log', (event: WriteCustomLogEvent) => { - if (this.log) { - this.log[event.method]( - 'MONGOSH-SCRIPTS', - mongoLogId(1_000_000_054), - 'custom-log', - event.message, - event.attr, - event.level - ); - } + 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) => { From a9fd752d2437f254328aa7e9bcf1570937395f80 Mon Sep 17 00:00:00 2001 From: gagik Date: Wed, 5 Feb 2025 10:56:24 +0100 Subject: [PATCH 13/15] fix: rename readReplLogfile to readReplLogFile and remove unnecessary log undefined check --- packages/cli-repl/src/cli-repl.spec.ts | 6 +++--- packages/cli-repl/test/repl-helpers.ts | 4 ++-- packages/e2e-tests/test/e2e-tls.spec.ts | 8 ++++---- packages/e2e-tests/test/e2e.spec.ts | 4 ++-- packages/e2e-tests/test/repl-helpers.ts | 4 ++-- packages/logging/src/logging-and-telemetry.ts | 16 +++++++--------- 6 files changed, 20 insertions(+), 22 deletions(-) diff --git a/packages/cli-repl/src/cli-repl.spec.ts b/packages/cli-repl/src/cli-repl.spec.ts index f3c9e294ec..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, @@ -56,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( @@ -1580,7 +1580,7 @@ describe('CliRepl', function () { 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/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/test/e2e-tls.spec.ts b/packages/e2e-tests/test/e2e-tls.spec.ts index d53c246116..181fc61890 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,7 +241,7 @@ 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.__value === 1_000_000_049)?.attr .asyncFallbackError @@ -278,7 +278,7 @@ 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.__value === 1_000_000_049)?.attr .asyncFallbackError @@ -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.__value === 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 a111bd97f5..47623c2658 100644 --- a/packages/e2e-tests/test/e2e.spec.ts +++ b/packages/e2e-tests/test/e2e.spec.ts @@ -14,7 +14,7 @@ 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 { 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'; @@ -1398,7 +1398,7 @@ describe('e2e', function () { throw new Error('Shell does not have a logId associated with it'); } const logPath = path.join(logBasePath, `${shell.logId}_log`); - return readReplLogfile(logPath); + return readReplLogFile(logPath); }; startTestShell = async (...extraArgs: string[]) => { const shell = this.startTestShell({ diff --git a/packages/e2e-tests/test/repl-helpers.ts b/packages/e2e-tests/test/repl-helpers.ts index 99fbdaca8e..312600b842 100644 --- a/packages/e2e-tests/test/repl-helpers.ts +++ b/packages/e2e-tests/test/repl-helpers.ts @@ -49,7 +49,7 @@ function useTmpdir(): { readonly path: string } { }; } -async function readReplLogfile( +async function readReplLogFile( logPath: string ): Promise { return (await fs.readFile(logPath, 'utf8')) @@ -165,7 +165,7 @@ async function connectionStringWithLocalhost( // eslint-disable-next-line mocha/no-exports export { useTmpdir, - readReplLogfile, + readReplLogFile, fakeExternalEditor, setTemporaryHomeDirectory, getCertPath, diff --git a/packages/logging/src/logging-and-telemetry.ts b/packages/logging/src/logging-and-telemetry.ts index 5b11ab6432..69b77fa50c 100644 --- a/packages/logging/src/logging-and-telemetry.ts +++ b/packages/logging/src/logging-and-telemetry.ts @@ -325,15 +325,13 @@ class LoggingAndTelemetry implements MongoshLoggingAndTelemetry { metadata: unknown; }; - if (this.log) { - this.log[context === 'fatal' ? 'fatal' : 'error']( - 'MONGOSH', - mongoLogId(1_000_000_006), - context, - `${mongoshError.name}: ${mongoshError.message}`, - error - ); - } + 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({ From 417c41143a9f7ccba26520d0e2a17830ae547087 Mon Sep 17 00:00:00 2001 From: gagik Date: Wed, 5 Feb 2025 12:45:22 +0100 Subject: [PATCH 14/15] fix(tests): readjust type of readReplLogFile --- packages/e2e-tests/test/e2e-tls.spec.ts | 11 +++++------ packages/e2e-tests/test/e2e.spec.ts | 8 ++++---- packages/e2e-tests/test/repl-helpers.ts | 13 ++++++++++--- 3 files changed, 19 insertions(+), 13 deletions(-) diff --git a/packages/e2e-tests/test/e2e-tls.spec.ts b/packages/e2e-tests/test/e2e-tls.spec.ts index 181fc61890..da68f80cc0 100644 --- a/packages/e2e-tests/test/e2e-tls.spec.ts +++ b/packages/e2e-tests/test/e2e-tls.spec.ts @@ -243,11 +243,11 @@ describe('e2e TLS', function () { const logPath = path.join(logBasePath, `${shell.logId}_log`); const logContents = await readReplLogFile(logPath); expect( - logContents.find((line) => line.id.__value === 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.__value === 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. }); @@ -280,11 +280,11 @@ describe('e2e TLS', function () { const logPath = path.join(logBasePath, `${shell.logId}_log`); const logContents = await readReplLogFile(logPath); expect( - logContents.find((line) => line.id.__value === 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.__value === 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. }); @@ -309,8 +309,7 @@ describe('e2e TLS', function () { const logPath = path.join(logBasePath, `${shell.logId}_log`); const logContents = await readReplLogFile(logPath); - expect(logContents.find((line) => line.id.__value === 1_000_000_049)).to - .exist; + 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 47623c2658..8fd076cfb8 100644 --- a/packages/e2e-tests/test/e2e.spec.ts +++ b/packages/e2e-tests/test/e2e.spec.ts @@ -14,6 +14,7 @@ import { promises as fs, createReadStream } from 'fs'; import { promisify } from 'util'; import path from 'path'; import os from 'os'; +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'; @@ -22,7 +23,6 @@ import { once } from 'events'; import type { AddressInfo } from 'net'; const { EJSON } = bson; import { sleep } from './util-helpers'; -import type { MongoLogEntry } from 'mongodb-log-writer'; const jsContextFlagCombinations: `--jsContext=${'plain-vm' | 'repl'}`[][] = [ [], @@ -1356,7 +1356,7 @@ describe('e2e', function () { let logBasePath: string; let historyPath: string; let readConfig: () => Promise; - let readLogFile: () => Promise; + let readLogFile: () => Promise; let startTestShell: (...extraArgs: string[]) => Promise; beforeEach(function () { @@ -1393,7 +1393,7 @@ describe('e2e', function () { } readConfig = async () => EJSON.parse(await fs.readFile(configPath, 'utf8')); - readLogFile = async (): Promise => { + readLogFile = async (): Promise => { if (!shell.logId) { throw new Error('Shell does not have a logId associated with it'); } @@ -1667,7 +1667,7 @@ describe('e2e', function () { expect(shell.assertNoErrors()); await eventually(async () => { const log = await readLogFile< - MongoLogEntry & { + MongoLogEntryFromFile & { c: string; ctx: string; } diff --git a/packages/e2e-tests/test/repl-helpers.ts b/packages/e2e-tests/test/repl-helpers.ts index 312600b842..46c67371d7 100644 --- a/packages/e2e-tests/test/repl-helpers.ts +++ b/packages/e2e-tests/test/repl-helpers.ts @@ -7,7 +7,6 @@ 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'; -import { EJSON } from 'bson'; chai.use(sinonChai); chai.use(chaiAsPromised); @@ -49,13 +48,20 @@ function useTmpdir(): { readonly path: string } { }; } -async function readReplLogFile( +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()) - .map((line) => EJSON.parse(line)); + .map((line) => JSON.parse(line)); } const fakeExternalEditor = async ({ @@ -170,4 +176,5 @@ export { setTemporaryHomeDirectory, getCertPath, connectionStringWithLocalhost, + MongoLogEntryFromFile, }; From 0ffae4cb4390b5ad9c09c9e9a4b10f6b0c5fc2bc Mon Sep 17 00:00:00 2001 From: gagik Date: Wed, 5 Feb 2025 14:01:40 +0100 Subject: [PATCH 15/15] fix(tests): add log-writer to resolve depcheck error We use a type from the mongodb-log-writer but it was not in the dependencies, so we add it back to fix the check test. --- package-lock.json | 5 +++++ packages/e2e-tests/package.json | 1 + 2 files changed, 6 insertions(+) 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/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",