diff --git a/packages/cli-repl/src/log-entry.ts b/packages/cli-repl/src/log-entry.ts new file mode 100644 index 0000000000..275fd08157 --- /dev/null +++ b/packages/cli-repl/src/log-entry.ts @@ -0,0 +1,37 @@ +export type LogEntry = { + timestamp: string; + severity: string; + component: string; + context: string; + message: string; + id: number | undefined; + attr: any; +}; + +// Parse a log line from mongod < 4.4, i.e. before structured logging came into +// existence. You may have seen code like this before. :) +function parseOldLogEntry(line: string): LogEntry { + const re = /^(?\S*) *(?\S*) *(?\S*) *\[(?[^\]]+)\]\s*(?.*)$/; + const match = line.trim().match(re); + if (!match) { + throw new Error(`Could not parse line ${JSON.stringify(line)}`); + } + return match.groups as unknown as LogEntry; +} + +export function parseAnyLogEntry(line: string): LogEntry { + try { + const newFormat = JSON.parse(line); + return { + id: newFormat.id, + timestamp: newFormat.t?.$date, + severity: newFormat.s, + component: newFormat.c, + context: newFormat.ctx, + message: newFormat.msg, + attr: newFormat.attr + }; + } catch { + return parseOldLogEntry(line); + } +} diff --git a/packages/cli-repl/src/mongocryptd-manager.ts b/packages/cli-repl/src/mongocryptd-manager.ts index 6924960487..ef7dfa5da0 100644 --- a/packages/cli-repl/src/mongocryptd-manager.ts +++ b/packages/cli-repl/src/mongocryptd-manager.ts @@ -7,6 +7,7 @@ import { Readable, PassThrough } from 'stream'; import { MongoshInternalError } from '@mongosh/errors'; import { CliServiceProvider } from '@mongosh/service-provider-server'; import type { MongoshBus } from '@mongosh/types'; +import { parseAnyLogEntry, LogEntry } from './log-entry'; import { ShellHomeDirectory } from './config-directory'; export async function getMongocryptdPaths(): Promise { @@ -79,21 +80,15 @@ export class MongocryptdManager { // Create an async iterator over the individual lines in a mongo(crypt)d // process'es stdout, while also forwarding the log events to the bus. - async* createLogEntryIterator(stdout: Readable, pid: number) { - let isStructuredLog : boolean | undefined = undefined; + async* createLogEntryIterator(stdout: Readable, pid: number): AsyncIterable { for await (const line of readline.createInterface({ input: stdout })) { if (!line.trim()) { continue; } - if (isStructuredLog === undefined) { - // 4.4 and above use structured logging, where the first entry always - // starts with '{'. - isStructuredLog = line.startsWith('{'); - } try { - const logEntry = isStructuredLog ? JSON.parse(line) : parseOldLogEntry(line); + const logEntry = parseAnyLogEntry(line); this.bus.emit('mongosh:mongocryptd-log', { pid, logEntry }); - yield { ...logEntry, isStructuredLog }; + yield logEntry; } catch (error) { this.bus.emit('mongosh:mongocryptd-error', { cause: 'parse', error }); break; @@ -233,18 +228,7 @@ export class MongocryptdManager { } } -// Parse a log line from mongod < 4.4, i.e. before structured logging came into -// existence. You may have seen code like this before. :) -function parseOldLogEntry(line: string): any { - const re = /^(?\S*) *(?\S*) *(?\S*) *\[(?[^\]]+)\]\s*(?.*)$/; - const match = line.trim().match(re); - if (!match) { - throw new Error(`Could not parse line ${JSON.stringify(line)}`); - } - return match.groups; -} - -function getSocketFromLogEntry(logEntry: any): string { +function getSocketFromLogEntry(logEntry: LogEntry): string { let match; // Log message id 23015 has the format // { t: , s: 'I', c: 'NETWORK', id: 23016, ctx: 'listener', msg: '...', attr: { address: '/tmp/q/mongocryptd.sock' } } @@ -255,14 +239,15 @@ function getSocketFromLogEntry(logEntry: any): string { } // Or, 4.2-style: I NETWORK [listener] Listening on /tmp/mongocryptd.sock if (logEntry.id === undefined && (match = logEntry.message.match(/^Listening on (?.+)$/i))) { - if (!isIP(match.groups.addr)) { - return match.groups.addr; + const { addr } = match.groups as any; + if (!isIP(addr)) { + return addr; } } return ''; } -function getPortFromLogEntry(logEntry: any): number { +function getPortFromLogEntry(logEntry: LogEntry): number { let match; // Log message id 23016 has the format // { t: , s: 'I', c: 'NETWORK', id: 23016, ctx: 'listener', msg: '...', attr: { port: 27020 } } @@ -271,7 +256,7 @@ function getPortFromLogEntry(logEntry: any): number { } // Or, 4.2-style: I NETWORK [listener] waiting for connections on port 27020 if (logEntry.id === undefined && (match = logEntry.message.match(/^waiting for connections on port (?\d+)$/i))) { - return +match.groups.port; + return +(match.groups?.port ?? '0'); } return -1; } @@ -281,11 +266,10 @@ function getPortFromLogEntry(logEntry: any): number { async function filterLogStreamForSocketAndPort(input: Readable): Promise<{ port: number, socket: string }> { let port = -1; let socket = ''; - const inputDuplicate = input.pipe(new PassThrough({ objectMode: true })); + const inputDuplicate: AsyncIterable = input.pipe(new PassThrough({ objectMode: true })); for await (const logEntry of inputDuplicate) { - if ((logEntry.c ?? logEntry.component) !== 'NETWORK' || - (logEntry.ctx ?? logEntry.thread) !== 'listener') { + if (logEntry.component !== 'NETWORK' || logEntry.context !== 'listener') { continue; // We are only interested in listening network events } socket ||= getSocketFromLogEntry(logEntry); diff --git a/packages/cli-repl/src/mongosh-repl.spec.ts b/packages/cli-repl/src/mongosh-repl.spec.ts index b9f5f8fd90..4aeb3d71da 100644 --- a/packages/cli-repl/src/mongosh-repl.spec.ts +++ b/packages/cli-repl/src/mongosh-repl.spec.ts @@ -10,6 +10,7 @@ import { StubbedInstance, stubInterface } from 'ts-sinon'; import { promisify } from 'util'; import { expect, fakeTTYProps, tick, useTmpdir, waitEval } from '../test/repl-helpers'; import MongoshNodeRepl, { MongoshIOProvider, MongoshNodeReplOptions } from './mongosh-repl'; +import { parseAnyLogEntry } from './log-entry'; import stripAnsi from 'strip-ansi'; const delay = promisify(setTimeout); @@ -662,69 +663,76 @@ describe('MongoshNodeRepl', () => { }); }); - context('when connecting to a db', () => { - const logLines = [ - '{"t":{"$date":"2020-12-07T07:51:30.691+01:00"},"s":"W", "c":"CONTROL", "id":20698, "ctx":"main","msg":"***** SERVER RESTARTED *****","tags":["startupWarnings"]}', - '{"t":{"$date":"2020-12-07T07:51:32.763+01:00"},"s":"W", "c":"CONTROL", "id":22120, "ctx":"initandlisten","msg":"Access control is not enabled for the database. Read and write access to data and configuration is unrestricted","tags":["startupWarnings"]}' - ]; - it('they are shown as returned by database', async() => { - sp.runCommandWithCheck.withArgs(ADMIN_DB, { - getLog: 'startupWarnings' - }, {}).resolves({ ok: 1, log: logLines }); - await mongoshRepl.initialize(serviceProvider); - - expect(output).to.contain('The server generated these startup warnings when booting'); - logLines.forEach(l => { - const { t: { $date: date }, msg: message } = JSON.parse(l); - expect(output).to.contain(`${date}: ${message}`); + for (const variant of ['structured', 'unstructured']) { + // eslint-disable-next-line no-loop-func + context(`when connecting to a db with ${variant} logs`, () => { + const logLines = variant === 'structured' ? [ + '{"t":{"$date":"2020-12-07T07:51:30.691+01:00"},"s":"W", "c":"CONTROL", "id":20698, "ctx":"main","msg":"***** SERVER RESTARTED *****","tags":["startupWarnings"]}', + '{"t":{"$date":"2020-12-07T07:51:32.763+01:00"},"s":"W", "c":"CONTROL", "id":22120, "ctx":"initandlisten","msg":"Access control is not enabled for the database. Read and write access to data and configuration is unrestricted","tags":["startupWarnings"]}' + ] : [ + '2021-05-03T14:50:59.815+0200 I CONTROL [main] ***** SERVER RESTARTED *****', + '2021-05-03T14:50:59.815+0200 I CONTROL [initandlisten] ** WARNING: Access control is not enabled for the database.', + '2021-05-03T14:50:59.815+0200 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted.' + ]; + it('they are shown as returned by database', async() => { + sp.runCommandWithCheck.withArgs(ADMIN_DB, { + getLog: 'startupWarnings' + }, {}).resolves({ ok: 1, log: logLines }); + await mongoshRepl.initialize(serviceProvider); + + expect(output).to.contain('The server generated these startup warnings when booting'); + logLines.forEach(l => { + const { timestamp, message } = parseAnyLogEntry(l); + expect(output).to.contain(`${timestamp}: ${message}`); + }); + }); + it('they are shown even if the log format cannot be parsed', async() => { + sp.runCommandWithCheck.withArgs(ADMIN_DB, { + getLog: 'startupWarnings' + }, {}).resolves({ ok: 1, log: ['Not JSON'] }); + await mongoshRepl.initialize(serviceProvider); + + expect(output).to.contain('The server generated these startup warnings when booting'); + expect(output).to.contain('Unexpected log line format: Not JSON'); + }); + it('does not show anything when there are no warnings', async() => { + let error = null; + bus.on('mongosh:error', err => { error = err; }); + sp.runCommandWithCheck.withArgs(ADMIN_DB, { + getLog: 'startupWarnings' + }, {}).resolves({ ok: 1, log: [] }); + await mongoshRepl.initialize(serviceProvider); + + expect(output).to.not.contain('The server generated these startup warnings when booting'); + expect(error).to.be.null; + }); + it('does not show anything if retrieving the warnings fails with exception', async() => { + const expectedError = new Error('failed'); + let error = null; + bus.on('mongosh:error', err => { error = err; }); + sp.runCommandWithCheck.withArgs(ADMIN_DB, { + getLog: 'startupWarnings' + }, {}).rejects(expectedError); + await mongoshRepl.initialize(serviceProvider); + + expect(output).to.not.contain('The server generated these startup warnings when booting'); + expect(output).to.not.contain('Error'); + expect(error).to.equal(expectedError); + }); + it('does not show anything if retrieving the warnings returns undefined', async() => { + let error = null; + bus.on('mongosh:error', err => { error = err; }); + sp.runCommandWithCheck.withArgs(ADMIN_DB, { + getLog: 'startupWarnings' + }, {}).resolves(undefined); + await mongoshRepl.initialize(serviceProvider); + + expect(output).to.not.contain('The server generated these startup warnings when booting'); + expect(output).to.not.contain('Error'); + expect(error).to.be.instanceof(MongoshCommandFailed); }); }); - it('they are shown even if the log format cannot be parsed', async() => { - sp.runCommandWithCheck.withArgs(ADMIN_DB, { - getLog: 'startupWarnings' - }, {}).resolves({ ok: 1, log: ['Not JSON'] }); - await mongoshRepl.initialize(serviceProvider); - - expect(output).to.contain('The server generated these startup warnings when booting'); - expect(output).to.contain('Unexpected log line format: Not JSON'); - }); - it('does not show anything when there are no warnings', async() => { - let error = null; - bus.on('mongosh:error', err => { error = err; }); - sp.runCommandWithCheck.withArgs(ADMIN_DB, { - getLog: 'startupWarnings' - }, {}).resolves({ ok: 1, log: [] }); - await mongoshRepl.initialize(serviceProvider); - - expect(output).to.not.contain('The server generated these startup warnings when booting'); - expect(error).to.be.null; - }); - it('does not show anything if retrieving the warnings fails with exception', async() => { - const expectedError = new Error('failed'); - let error = null; - bus.on('mongosh:error', err => { error = err; }); - sp.runCommandWithCheck.withArgs(ADMIN_DB, { - getLog: 'startupWarnings' - }, {}).rejects(expectedError); - await mongoshRepl.initialize(serviceProvider); - - expect(output).to.not.contain('The server generated these startup warnings when booting'); - expect(output).to.not.contain('Error'); - expect(error).to.equal(expectedError); - }); - it('does not show anything if retrieving the warnings returns undefined', async() => { - let error = null; - bus.on('mongosh:error', err => { error = err; }); - sp.runCommandWithCheck.withArgs(ADMIN_DB, { - getLog: 'startupWarnings' - }, {}).resolves(undefined); - await mongoshRepl.initialize(serviceProvider); - - expect(output).to.not.contain('The server generated these startup warnings when booting'); - expect(output).to.not.contain('Error'); - expect(error).to.be.instanceof(MongoshCommandFailed); - }); - }); + } }); context('prompt', () => { diff --git a/packages/cli-repl/src/mongosh-repl.ts b/packages/cli-repl/src/mongosh-repl.ts index 21599903cf..94b7f5b26b 100644 --- a/packages/cli-repl/src/mongosh-repl.ts +++ b/packages/cli-repl/src/mongosh-repl.ts @@ -18,6 +18,7 @@ import clr, { StyleDefinition } from './clr'; import { MONGOSH_WIKI, TELEMETRY_GREETING_MESSAGE } from './constants'; import formatOutput, { formatError } from './format-output'; import { LineByLineInput } from './line-by-line-input'; +import { parseAnyLogEntry, LogEntry } from './log-entry'; export type MongoshCliOptions = ShellCliOptions & { redactInfo?: boolean; @@ -312,10 +313,9 @@ class MongoshNodeRepl implements EvaluationListener { text += `${this.clr('------', ['bold', 'yellow'])}\n`; text += ` ${this.clr('The server generated these startup warnings when booting:', ['bold', 'yellow'])}\n`; result.log.forEach(logLine => { - type LogEntry = { t: { $date: string }, msg: string }; try { - const entry: LogEntry = JSON.parse(logLine); - text += ` ${entry.t.$date}: ${entry.msg}\n`; + const entry: LogEntry = parseAnyLogEntry(logLine); + text += ` ${entry.timestamp}: ${entry.message}\n`; } catch (e) { text += ` Unexpected log line format: ${logLine}\n`; }