Skip to content

fix(cli-repl): handle pre-4.4 logs for startup warnings MONGOSH-743 #837

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 3 commits into from
May 4, 2021
Merged

fix(cli-repl): handle pre-4.4 logs for startup warnings MONGOSH-743 #837

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
e5e4605
fix(cli-repl): handle pre-4.4 logs for startup warnings MONGOSH-743
addaleax May 3, 2021
b32ae19
fixup! fix(cli-repl): handle pre-4.4 logs for startup warnings MONGOS…
addaleax May 3, 2021
c8a4b2d
fixup
addaleax May 3, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
37 changes: 37 additions & 0 deletions packages/cli-repl/src/log-entry.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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 = /^(?<timestamp>\S*) *(?<severity>\S*) *(?<component>\S*) *\[(?<context>[^\]]+)\]\s*(?<message>.*)$/;
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);
}
}
40 changes: 12 additions & 28 deletions packages/cli-repl/src/mongocryptd-manager.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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<string[][]> {
Expand Down Expand Up @@ -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<LogEntry> {
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;
Expand Down Expand Up @@ -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 = /^(?<timestamp>\S*) *(?<severity>\S*) *(?<component>\S*) *\[(?<thread>[^\]]+)\]\s*(?<message>.*)$/;
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: <timestamp>, s: 'I', c: 'NETWORK', id: 23016, ctx: 'listener', msg: '...', attr: { address: '/tmp/q/mongocryptd.sock' } }
Expand All @@ -255,14 +239,15 @@ function getSocketFromLogEntry(logEntry: any): string {
}
// Or, 4.2-style: <timestamp> I NETWORK [listener] Listening on /tmp/mongocryptd.sock
if (logEntry.id === undefined && (match = logEntry.message.match(/^Listening on (?<addr>.+)$/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: <timestamp>, s: 'I', c: 'NETWORK', id: 23016, ctx: 'listener', msg: '...', attr: { port: 27020 } }
Expand All @@ -271,7 +256,7 @@ function getPortFromLogEntry(logEntry: any): number {
}
// Or, 4.2-style: <timestamp> I NETWORK [listener] waiting for connections on port 27020
if (logEntry.id === undefined && (match = logEntry.message.match(/^waiting for connections on port (?<port>\d+)$/i))) {
return +match.groups.port;
return +(match.groups?.port ?? '0');
}
return -1;
}
Expand All @@ -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<LogEntry> = 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);
Expand Down
130 changes: 69 additions & 61 deletions packages/cli-repl/src/mongosh-repl.spec.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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', () => {
Expand Down
6 changes: 3 additions & 3 deletions packages/cli-repl/src/mongosh-repl.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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`;
}
Expand Down