Skip to content

feat(NODE-4686): Add log messages to CLAM #3955

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 27 commits into from
Jan 19, 2024
Merged

feat(NODE-4686): Add log messages to CLAM #3955

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
27 commits
Select commit Hold shift + click to select a range
6d32c32
rebased changes
aditi-khare-mongoDB Dec 20, 2023
5f5d77e
All tests passing, need to add in prose tests
aditi-khare-mongoDB Dec 20, 2023
209ba27
Added prose tests
aditi-khare-mongoDB Dec 20, 2023
3bee17a
Added forgotten edge case
aditi-khare-mongoDB Dec 20, 2023
fcfc98b
removed stray only
aditi-khare-mongoDB Dec 21, 2023
422c6a9
workaround for messy messy rebase
aditi-khare-mongoDB Dec 21, 2023
c360ec2
refixed connection.ts, tests passing again
aditi-khare-mongoDB Dec 21, 2023
054094f
PR requested changes
aditi-khare-mongoDB Jan 4, 2024
0d8d051
Error fix
aditi-khare-mongoDB Jan 4, 2024
383f890
use hello not serverConnectionId to ensure support for versions below…
aditi-khare-mongoDB Jan 4, 2024
7033dc8
test versioning fix and package.lock fix
aditi-khare-mongoDB Jan 5, 2024
1d70579
Merge branch 'main' into NODE-4686/CLAM-logging-with-serverConnectionid
durran Jan 8, 2024
0ae8792
test fix
aditi-khare-mongoDB Jan 9, 2024
e92849d
versioning fix
aditi-khare-mongoDB Jan 9, 2024
9776ec9
PR requested changes, all tests passing
aditi-khare-mongoDB Jan 11, 2024
3332f94
extraneous .only removal
aditi-khare-mongoDB Jan 11, 2024
cacaed2
Update src/mongo_logger.ts
aditi-khare-mongoDB Jan 11, 2024
fa223cf
lint fix
aditi-khare-mongoDB Jan 11, 2024
299e8a1
neal's pr requested changes
aditi-khare-mongoDB Jan 16, 2024
1181991
pr again
aditi-khare-mongoDB Jan 16, 2024
8f6c860
pr requested changes again
aditi-khare-mongoDB Jan 16, 2024
dc93151
pr requested changes 4
aditi-khare-mongoDB Jan 16, 2024
cbb5df6
bailey's pr requested changes
aditi-khare-mongoDB Jan 17, 2024
9ace7a0
reauth support for connection.established
aditi-khare-mongoDB Jan 17, 2024
e9d4f8d
lint fix
aditi-khare-mongoDB Jan 17, 2024
7892601
added getter and using authContext?.authenticating directly
aditi-khare-mongoDB Jan 18, 2024
3c18428
Merge branch 'main' into NODE-4686/CLAM-logging-with-serverConnectionid
durran Jan 18, 2024
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
2 changes: 2 additions & 0 deletions src/bson.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,8 @@ export {
deserialize,
Document,
Double,
EJSON,
EJSONOptions,
Int32,
Long,
MaxKey,
Expand Down
4 changes: 4 additions & 0 deletions src/cmap/connect.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -186,6 +186,10 @@ async function performInitialHandshake(
throw error;
}
}

// Connection establishment is socket creation (tcp handshake, tls handshake, MongoDB handshake (saslStart, saslContinue))
// Once connection is established, command logging can log events (if enabled)
conn.established = true;
}

export interface HandshakeDocument extends Document {
Expand Down
53 changes: 46 additions & 7 deletions src/cmap/connection.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@ import {
MongoWriteConcernError
} from '../error';
import type { ServerApi, SupportedNodeConnectionOptions } from '../mongo_client';
import { MongoLoggableComponent, type MongoLogger, SeverityLevel } from '../mongo_logger';
import { type CancellationToken, TypedEventEmitter } from '../mongo_types';
import type { ReadPreferenceLike } from '../read_preference';
import { applySession, type ClientSession, updateSessionFromResponse } from '../sessions';
Expand Down Expand Up @@ -114,6 +115,8 @@ export interface ConnectionOptions
socketTimeoutMS?: number;
cancellationToken?: CancellationToken;
metadata: ClientMetadata;
/** @internal */
mongoLogger?: MongoLogger | undefined;
}

/** @internal */
Expand Down Expand Up @@ -165,6 +168,16 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
public delayedTimeoutId: NodeJS.Timeout | null = null;
public generation: number;
public readonly description: Readonly<StreamDescription>;
/**
* @public
* Represents if the connection has been established:
* - TCP handshake
* - TLS negotiated
* - mongodb handshake (saslStart, saslContinue), includes authentication
*
* Once connection is established, command logging can log events (if enabled)
*/
public established: boolean;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What is the expected behavior with command logging when we re-authenticate?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reauthentication will send commands we don't want to log I think. We may either need to

  • add logic that more specifically determines whether or not a command should be logged
  • set established to false when reauthenticating and then set it back to true after a successful reauthentication

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree, pinged you on slack for more info on reauth

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry I didn't notice this earlier ( I didn't actually check ) but instead of modifying established when we reauthenticate, could we just check the context.reauthenticating field?

one idea is a getter on the connection class (or we could just inline it):

get shouldEmitAndLog(): boolean {
  return this.monitorCommands ||
      (this.established && !this.context.reauthenticating && this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND))
}

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't it more accurate to edit established as well, though? Since during authentication, the connection is not established.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I understood established to mean that the connection had been established, not that it was "ready"/currently established. What I would like to avoid is duplicate data that might get out of sync. If established=false can also represent a connection reauthenticating, then it's possible for us to end up in a scenario context.reauthenticating=true with established=false (or vice versa) - which is a poorly defined state for the driver.

One way to avoid this is to define established as whether or not the connection was initially established and rely on context.reauthenticating (my suggestion).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That sounds good. I've removed the extra auth changes to conn.established and am using this.authContext?.authenticating in the new getter shouldEmitAndLogCommand instead.


private lastUseTime: number;
private socketTimeoutMS: number;
Expand All @@ -174,6 +187,8 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
private messageStream: Readable;
private socketWrite: (buffer: Uint8Array) => Promise<void>;
private clusterTime: Document | null = null;
/** @internal */
override mongoLogger: MongoLogger | undefined;

/** @event */
static readonly COMMAND_STARTED = COMMAND_STARTED;
Expand All @@ -198,6 +213,8 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
this.socketTimeoutMS = options.socketTimeoutMS ?? 0;
this.monitorCommands = options.monitorCommands;
this.serverApi = options.serverApi;
this.mongoLogger = options.mongoLogger;
this.established = false;

this.description = new StreamDescription(this.address, options);
this.generation = options.generation;
Expand Down Expand Up @@ -258,6 +275,16 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
);
}

private get shouldEmitAndLogCommand(): boolean {
return (
(this.monitorCommands ||
(this.established &&
!this.authContext?.reauthenticating &&
this.mongoLogger?.willLog(SeverityLevel.DEBUG, MongoLoggableComponent.COMMAND))) ??
false
);
}

public markAvailable(): void {
this.lastUseTime = now();
}
Expand Down Expand Up @@ -441,10 +468,13 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
const message = this.prepareCommand(ns.db, command, options);

let started = 0;
if (this.monitorCommands) {
if (this.shouldEmitAndLogCommand) {
started = now();
this.emit(
this.emitAndLogCommand(
this.monitorCommands,
Connection.COMMAND_STARTED,
message.databaseName,
this.established,
new CommandStartedEvent(this, message, this.description.serverConnectionId)
);
}
Expand All @@ -464,9 +494,12 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
throw new MongoServerError(document);
}

if (this.monitorCommands) {
this.emit(
if (this.shouldEmitAndLogCommand) {
this.emitAndLogCommand(
this.monitorCommands,
Connection.COMMAND_SUCCEEDED,
message.databaseName,
this.established,
new CommandSucceededEvent(
this,
message,
Expand All @@ -481,10 +514,13 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
this.controller.signal.throwIfAborted();
}
} catch (error) {
if (this.monitorCommands) {
if (this.shouldEmitAndLogCommand) {
if (error.name === 'MongoWriteConcernError') {
this.emit(
this.emitAndLogCommand(
this.monitorCommands,
Connection.COMMAND_SUCCEEDED,
message.databaseName,
this.established,
new CommandSucceededEvent(
this,
message,
Expand All @@ -494,8 +530,11 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
)
);
} else {
this.emit(
this.emitAndLogCommand(
this.monitorCommands,
Connection.COMMAND_FAILED,
message.databaseName,
this.established,
new CommandFailedEvent(
this,
message,
Expand Down
3 changes: 2 additions & 1 deletion src/cmap/connection_pool.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -699,7 +699,8 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
...this.options,
id: this[kConnectionCounter].next().value,
generation: this[kGeneration],
cancellationToken: this[kCancellationToken]
cancellationToken: this[kCancellationToken],
mongoLogger: this.mongoLogger
};

this[kPending]++;
Expand Down
3 changes: 3 additions & 0 deletions src/constants.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -60,8 +60,11 @@ export const CONNECTION_CHECKED_OUT = 'connectionCheckedOut' as const;
/** @internal */
export const CONNECTION_CHECKED_IN = 'connectionCheckedIn' as const;
export const CLUSTER_TIME_RECEIVED = 'clusterTimeReceived' as const;
/** @internal */
export const COMMAND_STARTED = 'commandStarted' as const;
/** @internal */
export const COMMAND_SUCCEEDED = 'commandSucceeded' as const;
/** @internal */
export const COMMAND_FAILED = 'commandFailed' as const;
/** @internal */
export const SERVER_HEARTBEAT_STARTED = 'serverHeartbeatStarted' as const;
Expand Down
5 changes: 5 additions & 0 deletions src/index.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -292,6 +292,9 @@ export type { StreamDescription, StreamDescriptionOptions } from './cmap/stream_
export type { CompressorName } from './cmap/wire_protocol/compression';
export type { CollectionOptions, CollectionPrivate, ModifyResult } from './collection';
export type {
COMMAND_FAILED,
COMMAND_STARTED,
COMMAND_SUCCEEDED,
CONNECTION_CHECK_OUT_FAILED,
CONNECTION_CHECK_OUT_STARTED,
CONNECTION_CHECKED_IN,
Expand Down Expand Up @@ -367,6 +370,8 @@ export type {
LogComponentSeveritiesClientOptions,
LogConvertible,
Loggable,
LoggableCommandFailedEvent,
LoggableCommandSucceededEvent,
LoggableEvent,
LoggableServerHeartbeatFailedEvent,
LoggableServerHeartbeatStartedEvent,
Expand Down
65 changes: 51 additions & 14 deletions src/mongo_logger.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,12 +1,8 @@
import { type Document, EJSON, type EJSONOptions } from 'bson';
import type { Writable } from 'stream';
import { inspect } from 'util';

import type {
CommandFailedEvent,
CommandStartedEvent,
CommandSucceededEvent
} from './cmap/command_monitoring_events';
import { type Document, EJSON, type EJSONOptions, type ObjectId } from './bson';
import type { CommandStartedEvent } from './cmap/command_monitoring_events';
import type {
ConnectionCheckedInEvent,
ConnectionCheckedOutEvent,
Expand Down Expand Up @@ -295,6 +291,40 @@ function compareSeverity(s0: SeverityLevel, s1: SeverityLevel): 1 | 0 | -1 {
return s0Num < s1Num ? -1 : s0Num > s1Num ? 1 : 0;
}

/**
* @internal
* Must be separate from Events API due to differences in spec requirements for logging a command success
*/
export type LoggableCommandSucceededEvent = {
address: string;
connectionId?: string | number;
requestId: number;
duration: number;
commandName: string;
reply: Document | undefined;
serviceId?: ObjectId;
name: typeof COMMAND_SUCCEEDED;
serverConnectionId: bigint | null;
databaseName: string;
};

/**
* @internal
* Must be separate from Events API due to differences in spec requirements for logging a command failure
*/
export type LoggableCommandFailedEvent = {
address: string;
connectionId?: string | number;
requestId: number;
duration: number;
commandName: string;
failure: Error;
serviceId?: ObjectId;
name: typeof COMMAND_FAILED;
serverConnectionId: bigint | null;
databaseName: string;
};

/**
* @internal
* Must be separate from Events API due to differences in spec requirements for logging server heartbeat beginning
Expand Down Expand Up @@ -350,8 +380,8 @@ export type LoggableEvent =
| ServerSelectionSucceededEvent
| WaitingForSuitableServerEvent
| CommandStartedEvent
| CommandSucceededEvent
| CommandFailedEvent
| LoggableCommandSucceededEvent
| LoggableCommandFailedEvent
| ConnectionPoolCreatedEvent
| ConnectionPoolReadyEvent
| ConnectionPoolClosedEvent
Expand Down Expand Up @@ -383,7 +413,8 @@ export function stringifyWithMaxLen(
maxDocumentLength: number,
options: EJSONOptions = {}
): string {
let strToTruncate: string;
let strToTruncate = '';
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Non-blocking and definitely only tangentially related: the .slice() call below can end up truncating strToTruncate in the middle of a character. That won't happen a lot if the string mostly just contains ASCII data, but since this is a very low-level generic utility, it might be worth accounting for that case (e.g. if (strToTruncate.length > maxDocumentLength && strToTruncate.charCodeAt(maxDocumentLength-1) !== strToTruncate.codePointAt(maxDocumentLength-1)) maxDocumentLength--;).

Copy link
Contributor Author

@aditi-khare-mongoDB aditi-khare-mongoDB Jan 17, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is something we will solve / take a further look at in NODE-5839.


if (typeof value === 'function') {
strToTruncate = value.toString();
} else {
Expand Down Expand Up @@ -420,7 +451,7 @@ function attachServerSelectionFields(

function attachCommandFields(
log: Record<string, any>,
commandEvent: CommandStartedEvent | CommandSucceededEvent | CommandFailedEvent
commandEvent: CommandStartedEvent | LoggableCommandSucceededEvent | LoggableCommandFailedEvent
) {
log.commandName = commandEvent.commandName;
log.requestId = commandEvent.requestId;
Expand All @@ -431,6 +462,8 @@ function attachCommandFields(
if (commandEvent?.serviceId) {
log.serviceId = commandEvent.serviceId.toHexString();
}
log.databaseName = commandEvent.databaseName;
log.serverConnectionId = commandEvent?.serverConnectionId;

return log;
}
Expand Down Expand Up @@ -490,20 +523,20 @@ function defaultLogTransform(
case COMMAND_STARTED:
log = attachCommandFields(log, logObject);
log.message = 'Command started';
log.command = stringifyWithMaxLen(logObject.command, maxDocumentLength);
log.command = stringifyWithMaxLen(logObject.command, maxDocumentLength, { relaxed: true });
log.databaseName = logObject.databaseName;
return log;
case COMMAND_SUCCEEDED:
log = attachCommandFields(log, logObject);
log.message = 'Command succeeded';
log.durationMS = logObject.duration;
log.reply = stringifyWithMaxLen(logObject.reply, maxDocumentLength);
log.reply = stringifyWithMaxLen(logObject.reply, maxDocumentLength, { relaxed: true });
return log;
case COMMAND_FAILED:
log = attachCommandFields(log, logObject);
log.message = 'Command failed';
log.durationMS = logObject.duration;
log.failure = logObject.failure;
log.failure = logObject.failure.message ?? '(redacted)';
return log;
case CONNECTION_POOL_CREATED:
log = attachConnectionFields(log, logObject);
Expand Down Expand Up @@ -701,12 +734,16 @@ export class MongoLogger {
this.logDestination = options.logDestination;
}

willLog(severity: SeverityLevel, component: MongoLoggableComponent): boolean {
return compareSeverity(severity, this.componentSeverities[component]) <= 0;
}

private log(
severity: SeverityLevel,
component: MongoLoggableComponent,
message: Loggable | string
): void {
if (compareSeverity(severity, this.componentSeverities[component]) > 0) return;
if (!this.willLog(severity, component)) return;

let logMessage: Log = { t: new Date(), c: component, s: severity };
if (typeof message === 'string') {
Expand Down
35 changes: 30 additions & 5 deletions src/mongo_types.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,12 +12,15 @@ import type {
ObjectId,
Timestamp
} from './bson';
import type {
LoggableServerHeartbeatFailedEvent,
LoggableServerHeartbeatStartedEvent,
LoggableServerHeartbeatSucceededEvent,
import { type CommandStartedEvent } from './cmap/command_monitoring_events';
import {
type LoggableCommandFailedEvent,
type LoggableCommandSucceededEvent,
type LoggableServerHeartbeatFailedEvent,
type LoggableServerHeartbeatStartedEvent,
type LoggableServerHeartbeatSucceededEvent,
MongoLoggableComponent,
MongoLogger
type MongoLogger
} from './mongo_logger';
import type { Sort } from './sort';

Expand Down Expand Up @@ -442,6 +445,28 @@ export class TypedEventEmitter<Events extends EventsDescription> extends EventEm
this.mongoLogger?.debug(this.component, loggableHeartbeatEvent);
}
}
/** @internal */
emitAndLogCommand<EventKey extends keyof Events>(
monitorCommands: boolean,
event: EventKey | symbol,
databaseName: string,
connectionEstablished: boolean,
...args: Parameters<Events[EventKey]>
): void {
if (monitorCommands) {
this.emit(event, ...args);
}
if (connectionEstablished) {
const loggableCommandEvent:
| CommandStartedEvent
| LoggableCommandFailedEvent
| LoggableCommandSucceededEvent = {
databaseName: databaseName,
...args[0]
};
this.mongoLogger?.debug(MongoLoggableComponent.COMMAND, loggableCommandEvent);
}
}
}

/** @public */
Expand Down
Loading