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

[aditi-khare-mongoDB]

Description

Add logging to CLAM events, un-skip + add support for CLAM logging spec tests, and add in prose tests.

What is changing?

CLAM logging messages will be enabled when loggingClientOptions for component MongoLoggableComponent.COMMAND >= SeverityLevel.DEBUG.

NOTE:

• Command logging is enabled separate from command monitoring, and the command logging messages contain additional fields than command monitoring, resulting in the need for the additional emitAndLogCommand method.
• More context can be found within the kickoff.
• through inspection of the spec runner, failureIsRedacted is already supported

Is there new documentation needed for these changes?

Not until logging is released (NODE-5762)

What is the motivation for this change?

To allow users to see CLAM events through logging.

Double check the following

• Ran npm run check:lint script
• Self-review completed using the steps outlined here
• PR title follows the correct format: type(NODE-xxxx)[!]: description
  • Example: feat(NODE-1234)!: rewriting everything in coffeescript
• Changes are covered by tests
• New TODOs have a related JIRA ticket

[durran]

Can we rebase this quickly against main first so we have an accurate diff against the new connection class changes?

[aditi-khare-mongoDB]

@durran rebase is done, TIA!

[durran]

Note that the unit tests are failing because the test command failed event has no failure on it.

[aditi-khare-mongoDB]

Added in the failure field to the unit tests

[durran]

Looks like we have the same failures with the extra pings here now on this PR. An extra 2 events are getting sent and the unified tests are failing.

[aditi-khare-mongoDB]

I had a syntax error in emitAndLogCommand that made the output invalid, is fixed now.

[durran]

There are still failures that need to be addressed both in unit tests:

https://spruce.mongodb.com/task/mongo_node_driver_next_lint_run_unit_tests_node_16_patch_efece79d95a2c9892915ffd8c04f229d9e84196d_659726d4a4cf475f0b6a7eb6_24_01_04_21_44_53/logs?execution=0&sortBy=STATUS&sortDir=ASC

And in the integration tests:

https://spruce.mongodb.com/task/mongo_node_driver_next_rhel8_no_auth_tests_test_4.0_server_noauth_patch_efece79d95a2c9892915ffd8c04f229d9e84196d_659726d4a4cf475f0b6a7eb6_24_01_04_21_44_53/logs?execution=0&sortBy=STATUS&sortDir=ASC

[baileympearson]

This is an interesting idea - I see it's used in TypedEventEmitter to know which logging component to use.

Will there ever be a case where emitAndLogCommand will be used to log for a component that is not MongoLoggableComponent.COMMAND?

[aditi-khare-mongoDB]

No, there won't. The extra this.component check should ensure that an emitAndLog or variant function (emitAndLogCommand, emitAndLogHeartbeat) is not called from any class for which the logging component is not defined already.

[aditi-khare-mongoDB]

I can add in an extra check such as: this.component === MongoLoggableComponent.COMMAND, remove the this.component check for emitAndLogCommand, or keep it the same. What do you think?

[baileympearson]

It's strange to me that we have a dedicated method for logging commands, but to use it we also need to set the component on the class. I would expect that either:

• we only have emitAndLogCommand(), and not the component property.
• we have a generic emitAndLog() method that uses the component property and no specialized methods on the TypedEventEmitter

No, there won't. The extra this.component check should ensure that an emitAndLog or variant function (emitAndLogCommand, emitAndLogHeartbeat) is not called from any class for which the logging component is not defined already.

If we want to prevent the emitAndLog functions from being called, maybe we could use inheritance for this? that way we could only define the log methods where they can be used

class TypedEventEmitter {
  private logger: MongoLogger;
}

class CommandEventEmitter extends TypedEventEmitter {
  emitAndLogCommand(..) {}
}


class HeartbeatEventEmitter extends TypedEventEmitter {
  emitAndLogHeartbeat(..) {}
}

class Connection extends CommandEventEmitter { ...} 
class Monitor extends HeartbeatEventEmitter { ...} 

[aditi-khare-mongoDB]

That's true. For the sake of this PR, I'll just hardcode in the component in emitAndLogCommand as MongoLoggableComponent.COMMAND. Since I realize emitAndLogCommand already implies that the command component is being utilized.

[addaleax]

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--;).

[aditi-khare-mongoDB]

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

[baileympearson]

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

[baileympearson]

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

[aditi-khare-mongoDB]

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

[baileympearson]

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))
}

[aditi-khare-mongoDB]

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

[baileympearson]

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).

[aditi-khare-mongoDB]

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.