refactor(NODE-3356): Update command monitoring logging (#2853)

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,10 @@ 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.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].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.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} details REDACTED` : 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} details REDACTED` : 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;