refactor(NODE-3356): Update command monitoring logging

lib/command_utils.js

@@ -0,0 +1,122 @@
+'use strict';
+const Msg = require('./core/connection/msg').Msg;
+const KillCursor = require('./core/connection/commands').KillCursor;
+const GetMore = require('./core/connection/commands').GetMore;
+
+/** Commands that we want to redact because of the sensitive nature of their contents */
+const SENSITIVE_COMMANDS = new Set([
+ 'authenticate',
+ 'saslStart',
+ 'saslContinue',
+ 'getnonce',
+ 'createUser',
+ 'updateUser',
+ 'copydbgetnonce',
+ 'copydbsaslstart',
+ 'copydb'
+]);
+
+const HELLO_COMMANDS = new Set(['hello', 'ismaster', 'isMaster']);
+
+const LEGACY_FIND_QUERY_MAP = {
+ $query: 'filter',
+ $orderby: 'sort',
+ $hint: 'hint',
+ $comment: 'comment',
+ $maxScan: 'maxScan',
+ $max: 'max',
+ $min: 'min',
+ $returnKey: 'returnKey',
+ $showDiskLoc: 'showRecordId',
+ $maxTimeMS: 'maxTimeMS',
+ $snapshot: 'snapshot'
+};
+
+const LEGACY_FIND_OPTIONS_MAP = {
+ numberToSkip: 'skip',
+ numberToReturn: 'batchSize',
+ returnFieldsSelector: 'projection'
+};
+
+const OP_QUERY_KEYS = [
+ 'tailable',
+ 'oplogReplay',
+ 'noCursorTimeout',
+ 'awaitData',
+ 'partial',
+ 'exhaust'
+];
+
+const collectionName = command => command.ns.split('.')[1];
+
+const shouldRedactCommand = (commandName, cmd) =>
+ SENSITIVE_COMMANDS.has(commandName) ||
+ (HELLO_COMMANDS.has(commandName) && !!cmd.speculativeAuthenticate);
+
+/**
+ * Extract the actual command from the query, possibly upconverting if it's a legacy
+ * format
+ *
+ * @param {Object} command the command
+ */
+const extractCommand = command => {
+ let extractedCommand;
+ if (command instanceof GetMore) {
+ extractedCommand = {
+ getMore: command.cursorId,
+ collection: collectionName(command),
+ batchSize: command.numberToReturn
+ };
+ } else if (command instanceof KillCursor) {
+ extractedCommand = {
+ killCursors: collectionName(command),
+ cursors: command.cursorIds
+ };
+ } else if (command instanceof Msg) {
+ extractedCommand = command.command;
+ } else if (command.query && command.query.$query) {
+ let result;
+ if (command.ns === 'admin.$cmd') {
+ // upconvert legacy command
+ result = Object.assign({}, command.query.$query);
+ } else {
+ // upconvert legacy find command
+ result = { find: collectionName(command) };
+ Object.keys(LEGACY_FIND_QUERY_MAP).forEach(key => {
+ if (typeof command.query[key] !== 'undefined')
+ result[LEGACY_FIND_QUERY_MAP[key]] = command.query[key];
+ });
+ }
+
+ Object.keys(LEGACY_FIND_OPTIONS_MAP).forEach(key => {
+ if (typeof command[key] !== 'undefined') result[LEGACY_FIND_OPTIONS_MAP[key]] = command[key];
+ });
+
+ OP_QUERY_KEYS.forEach(key => {
+ if (command[key]) result[key] = command[key];
+ });
+
+ if (typeof command.pre32Limit !== 'undefined') {
+ result.limit = command.pre32Limit;
+ }
+
+ if (command.query.$explain) {
+ extractedCommand = { explain: result };
+ } else {
+ extractedCommand = result;
+ }
+ } else {
+ extractedCommand = command.query || command;
+ }
+
+ const commandName = Object.keys(extractedCommand)[0];
+ return {
+ cmd: extractedCommand,
+ name: commandName,
+ shouldRedact: shouldRedactCommand(commandName, extractedCommand)
+ };
+};
+
+module.exports = {
+ extractCommand
+};

lib/core/connection/apm.js

@@ -1,129 +1,16 @@
 'use strict';
-const Msg = require('../connection/msg').Msg;
 const KillCursor = require('../connection/commands').KillCursor;
 const GetMore = require('../connection/commands').GetMore;
 const calculateDurationInMs = require('../../utils').calculateDurationInMs;
-
-/** Commands that we want to redact because of the sensitive nature of their contents */
-const SENSITIVE_COMMANDS = new Set([
- 'authenticate',
- 'saslStart',
- 'saslContinue',
- 'getnonce',
- 'createUser',
- 'updateUser',
- 'copydbgetnonce',
- 'copydbsaslstart',
- 'copydb'
-]);
-
-const HELLO_COMMANDS = new Set(['hello', 'ismaster', 'isMaster']);
+const extractCommand = require('../../command_utils').extractCommand;
 
 // helper methods
-const extractCommandName = commandDoc => Object.keys(commandDoc)[0];
 const namespace = command => command.ns;
 const databaseName = command => command.ns.split('.')[0];
-const collectionName = command => command.ns.split('.')[1];
 const generateConnectionId = pool =>
  pool.options ? `${pool.options.host}:${pool.options.port}` : pool.address;
-const maybeRedact = (commandName, cmd, result) =>
- SENSITIVE_COMMANDS.has(commandName) ||
- (HELLO_COMMANDS.has(commandName) && cmd.speculativeAuthenticate)
- ? {}
- : result;
 const isLegacyPool = pool => pool.s && pool.queue;
 
-const LEGACY_FIND_QUERY_MAP = {
- $query: 'filter',
- $orderby: 'sort',
- $hint: 'hint',
- $comment: 'comment',
- $maxScan: 'maxScan',
- $max: 'max',
- $min: 'min',
- $returnKey: 'returnKey',
- $showDiskLoc: 'showRecordId',
- $maxTimeMS: 'maxTimeMS',
- $snapshot: 'snapshot'
-};
-
-const LEGACY_FIND_OPTIONS_MAP = {
- numberToSkip: 'skip',
- numberToReturn: 'batchSize',
- returnFieldsSelector: 'projection'
-};
-
-const OP_QUERY_KEYS = [
- 'tailable',
- 'oplogReplay',
- 'noCursorTimeout',
- 'awaitData',
- 'partial',
- 'exhaust'
-];
-
-/**
- * Extract the actual command from the query, possibly upconverting if it's a legacy
- * format
- *
- * @param {Object} command the command
- */
-const extractCommand = command => {
- if (command instanceof GetMore) {
- return {
- getMore: command.cursorId,
- collection: collectionName(command),
- batchSize: command.numberToReturn
- };
- }
-
- if (command instanceof KillCursor) {
- return {
- killCursors: collectionName(command),
- cursors: command.cursorIds
- };
- }
-
- if (command instanceof Msg) {
- return command.command;
- }
-
- if (command.query && command.query.$query) {
- let result;
- if (command.ns === 'admin.$cmd') {
- // upconvert legacy command
- result = Object.assign({}, command.query.$query);
- } else {
- // upconvert legacy find command
- result = { find: collectionName(command) };
- Object.keys(LEGACY_FIND_QUERY_MAP).forEach(key => {
- if (typeof command.query[key] !== 'undefined')
- result[LEGACY_FIND_QUERY_MAP[key]] = command.query[key];
- });
- }
-
- Object.keys(LEGACY_FIND_OPTIONS_MAP).forEach(key => {
- if (typeof command[key] !== 'undefined') result[LEGACY_FIND_OPTIONS_MAP[key]] = command[key];
- });
-
- OP_QUERY_KEYS.forEach(key => {
- if (command[key]) result[key] = command[key];
- });
-
- if (typeof command.pre32Limit !== 'undefined') {
- result.limit = command.pre32Limit;
- }
-
- if (command.query.$explain) {
- return { explain: result };
- }
-
- return result;
- }
-
- return command.query ? command.query : command;
-};
-
 const extractReply = (command, reply) => {
  if (command instanceof GetMore) {
  return {
@@ -183,15 +70,15 @@ class CommandStartedEvent {
  * @param {Object} command the command
  */
  constructor(pool, command) {
- const cmd = extractCommand(command);
- const commandName = extractCommandName(cmd);
+ const extractedCommand = extractCommand(command);
+ const commandName = extractedCommand.name;
  const connectionDetails = extractConnectionDetails(pool);
 
  Object.assign(this, connectionDetails, {
  requestId: command.requestId,
  databaseName: databaseName(command),
  commandName,
- command: maybeRedact(commandName, cmd, cmd)
+ command: extractedCommand.shouldRedact ? {} : extractedCommand.cmd
  });
  }
 }
@@ -207,15 +94,15 @@ class CommandSucceededEvent {
  * @param {Array} started a high resolution tuple timestamp of when the command was first sent, to calculate duration
  */
  constructor(pool, command, reply, started) {
- const cmd = extractCommand(command);
- const commandName = extractCommandName(cmd);
+ const extractedCommand = extractCommand(command);
+ const commandName = extractedCommand.name;
  const connectionDetails = extractConnectionDetails(pool);
 
  Object.assign(this, connectionDetails, {
  requestId: command.requestId,
  commandName,
  duration: calculateDurationInMs(started),
- reply: maybeRedact(commandName, cmd, extractReply(command, reply))
+ reply: extractedCommand.shouldRedact ? {} : extractReply(command, reply)
  });
  }
 }
@@ -231,15 +118,15 @@ class CommandFailedEvent {
  * @param {Array} started a high resolution tuple timestamp of when the command was first sent, to calculate duration
  */
  constructor(pool, command, error, started) {
- const cmd = extractCommand(command);
- const commandName = extractCommandName(cmd);
+ const extractedCommand = extractCommand(command);
+ const commandName = extractedCommand.name;
  const connectionDetails = extractConnectionDetails(pool);
 
  Object.assign(this, connectionDetails, {
  requestId: command.requestId,
  commandName,
  duration: calculateDurationInMs(started),
- failure: maybeRedact(commandName, cmd, error)
+ failure: extractedCommand.shouldRedact ? {} : error
  });
  }
 }

lib/core/connection/connection.js

@@ -254,10 +254,12 @@ class Connection extends EventEmitter {
  // Debug Log
  if (this.logger.isDebug()) {
  if (!Array.isArray(buffer)) {
- this.logger.debug(`writing buffer [${buffer.toString('hex')}] to ${this.address}`);
+ this.logger.debug(`writing buffer [ ${buffer.toString('hex').length} ] to ${this.address}`);
  } else {
  for (let i = 0; i < buffer.length; i++)
- this.logger.debug(`writing buffer [${buffer[i].toString('hex')}] to ${this.address}`);
+ this.logger.debug(
+ `writing buffer [ ${buffer[i].toString('hex').length} ] to ${this.address}`
+ );
  }
  }
 

lib/core/connection/pool.js

@@ -390,8 +390,8 @@ function messageHandler(self) {
  if (self.logger.isDebug()) {
  self.logger.debug(
  f(
- 'message [%s] received from %s:%s',
- message.raw.toString('hex'),
+ 'message [ %s ] received from %s:%s',
+ message.raw.toString('hex').length,
  self.options.host,
  self.options.port
  )

lib/core/sdam/server.js

@@ -20,6 +20,7 @@ const isNodeShuttingDownError = require('../error').isNodeShuttingDownError;
 const isNetworkErrorBeforeHandshake = require('../error').isNetworkErrorBeforeHandshake;
 const maxWireVersion = require('../utils').maxWireVersion;
 const makeStateMachine = require('../utils').makeStateMachine;
+const extractCommand = require('../../command_utils').extractCommand;
 const common = require('./common');
 const ServerType = common.ServerType;
 const isTransactionCommand = require('../transactions').isTransactionCommand;
@@ -261,10 +262,11 @@ class Server extends EventEmitter {
 
  // Debug log
  if (this.s.logger.isDebug()) {
+ const extractedCommand = extractCommand(cmd);
  this.s.logger.debug(
  `executing command [${JSON.stringify({
  ns,
- cmd,
+ cmd: extractedCommand.shouldRedact ? extractedCommand.name : cmd,
  options: debugOptions(DEBUG_FIELDS, options)
  })}] against ${this.name}`
  );

lib/core/topologies/server.js

@@ -16,6 +16,7 @@ var inherits = require('util').inherits,
  createCompressionInfo = require('./shared').createCompressionInfo,
  resolveClusterTime = require('./shared').resolveClusterTime,
  SessionMixins = require('./shared').SessionMixins,
+ extractCommand = require('../../command_utils').extractCommand,
  relayEvents = require('../utils').relayEvents;
 
 const collationNotSupported = require('../utils').collationNotSupported;
@@ -608,18 +609,20 @@ Server.prototype.command = function(ns, cmd, options, callback) {
  options = Object.assign({}, options, { wireProtocolCommand: false });
 
  // Debug log
- if (self.s.logger.isDebug())
+ if (self.s.logger.isDebug()) {
+ const extractedCommand = extractCommand(cmd);
  self.s.logger.debug(
  f(
  'executing command [%s] against %s',
  JSON.stringify({
  ns: ns,
- cmd: cmd,
+ cmd: extractedCommand.shouldRedact ? extractedCommand.name : cmd,
  options: debugOptions(debugFields, options)
  }),
  self.name
  )
  );
+ }
 
  // If we are not connected or have a disconnectHandler specified
  if (disconnectHandler(self, 'command', ns, cmd, options, callback)) return;