Skip to content

feat(NODE-4815): stringify and truncate BSON documents in log messages #3635

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.

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
Apr 18, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
20 changes: 16 additions & 4 deletions src/mongo_logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -53,6 +53,8 @@ export const SeverityLevel = Object.freeze({
OFF: 'off'
} as const);

/** @internal */
export const DEFAULT_MAX_DOCUMENT_LENGTH = 1000;
/** @internal */
export type SeverityLevel = (typeof SeverityLevel)[keyof typeof SeverityLevel];

Expand Down Expand Up @@ -254,6 +256,15 @@ export interface LogConvertible extends Record<string, any> {
toLog(): Record<string, any>;
}

/** @internal */
export function stringifyWithMaxLen(value: any, maxDocumentLength: number): string {
const ejson = EJSON.stringify(value);

return maxDocumentLength !== 0 && ejson.length > maxDocumentLength
? `${ejson.slice(0, maxDocumentLength)}...`
: ejson;
}

/** @internal */
export type Loggable = LoggableEvent | LogConvertible;

Expand Down Expand Up @@ -292,22 +303,23 @@ function attachConnectionFields(
}

function defaultLogTransform(
logObject: LoggableEvent | Record<string, any>
logObject: LoggableEvent | Record<string, any>,
maxDocumentLength: number = DEFAULT_MAX_DOCUMENT_LENGTH
): Omit<Log, 's' | 't' | 'c'> {
let log: Omit<Log, 's' | 't' | 'c'> = Object.create(null);

switch (logObject.name) {
case COMMAND_STARTED:
log = attachCommandFields(log, logObject);
log.message = 'Command started';
log.command = EJSON.stringify(logObject.command);
log.command = stringifyWithMaxLen(logObject.command, maxDocumentLength);
log.databaseName = logObject.databaseName;
return log;
case COMMAND_SUCCEEDED:
log = attachCommandFields(log, logObject);
log.message = 'Command succeeded';
log.durationMS = logObject.duration;
log.reply = EJSON.stringify(logObject.reply);
log.reply = stringifyWithMaxLen(logObject.reply, maxDocumentLength);
return log;
case COMMAND_FAILED:
log = attachCommandFields(log, logObject);
Expand Down Expand Up @@ -452,7 +464,7 @@ export class MongoLogger {
if (isLogConvertible(message)) {
logMessage = { ...logMessage, ...message.toLog() };
} else {
logMessage = { ...logMessage, ...defaultLogTransform(message) };
logMessage = { ...logMessage, ...defaultLogTransform(message, this.maxDocumentLength) };
}
}
this.logDestination.write(logMessage);
Expand Down
52 changes: 51 additions & 1 deletion test/unit/mongo_logger.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -19,12 +19,14 @@ import {
CONNECTION_POOL_CREATED,
CONNECTION_POOL_READY,
CONNECTION_READY,
DEFAULT_MAX_DOCUMENT_LENGTH,
Log,
MongoDBLogWritable,
MongoLogger,
MongoLoggerOptions,
SEVERITY_LEVEL_MAP,
SeverityLevel
SeverityLevel,
stringifyWithMaxLen
} from '../mongodb';

class BufferingStream extends Writable {
Expand Down Expand Up @@ -1239,4 +1241,52 @@ describe('class MongoLogger', function () {
});
}
});

describe('stringifyWithMaxLen', function () {
const largeDoc = {};
const smallDoc = { test: 'Hello' };
before(function () {
for (let i = 0; i < DEFAULT_MAX_DOCUMENT_LENGTH; i++) {
largeDoc[`test${i}`] = `Hello_${i}`;
}
});

context('when maxDocumentLength = 0', function () {
it('does not truncate document', function () {
expect(stringifyWithMaxLen(largeDoc, 0)).to.equal(EJSON.stringify(largeDoc));
});
});

context('when maxDocumentLength is non-zero', function () {
context('when document has length greater than maxDocumentLength', function () {
it('truncates ejson string to length of maxDocumentLength + 3', function () {
expect(stringifyWithMaxLen(largeDoc, DEFAULT_MAX_DOCUMENT_LENGTH)).to.have.lengthOf(
DEFAULT_MAX_DOCUMENT_LENGTH + 3
);
});
it('ends with "..."', function () {
expect(stringifyWithMaxLen(largeDoc, DEFAULT_MAX_DOCUMENT_LENGTH)).to.match(/^.*\.\.\.$/);
});
});

context('when document has length less than or equal to maxDocumentLength', function () {
it('does not truncate document', function () {
expect(stringifyWithMaxLen(smallDoc, DEFAULT_MAX_DOCUMENT_LENGTH)).to.equal(
EJSON.stringify(smallDoc)
);
});
it('does not end with "..."', function () {
expect(stringifyWithMaxLen(smallDoc, DEFAULT_MAX_DOCUMENT_LENGTH)).to.not.match(
/^.*\.\.\./
);
});

it('produces valid relaxed EJSON', function () {
expect(() => {
EJSON.parse(stringifyWithMaxLen(smallDoc, DEFAULT_MAX_DOCUMENT_LENGTH));
}).to.not.throw();
});
});
});
});
});