From b98f2061de9e8b0a814e3e7d39a0e914245953d0 Mon Sep 17 00:00:00 2001 From: Daria Pardue <81593090+dariakp@users.noreply.github.com> Date: Thu, 24 Jun 2021 08:51:52 -0400 Subject: [PATCH] refactor(NODE-3356): Update command monitoring logging (#2853) --- lib/command_utils.js | 122 +++++++++++++++++++++++++++ lib/core/connection/apm.js | 133 +++--------------------------- lib/core/connection/connection.js | 4 +- lib/core/connection/pool.js | 4 +- lib/core/sdam/server.js | 4 +- lib/core/topologies/server.js | 7 +- lib/operations/command.js | 4 +- lib/operations/command_v2.js | 8 +- lib/operations/db_ops.js | 7 +- 9 files changed, 159 insertions(+), 134 deletions(-) create mode 100644 lib/command_utils.js diff --git a/lib/command_utils.js b/lib/command_utils.js new file mode 100644 index 0000000000..ba8289c326 --- /dev/null +++ b/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 +}; diff --git a/lib/core/connection/apm.js b/lib/core/connection/apm.js index f6e293b429..875e418262 100644 --- a/lib/core/connection/apm.js +++ b/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 }); } } diff --git a/lib/core/connection/connection.js b/lib/core/connection/connection.js index 5b22513b2a..c9d34960c8 100644 --- a/lib/core/connection/connection.js +++ b/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}`); } } diff --git a/lib/core/connection/pool.js b/lib/core/connection/pool.js index f0061ee914..491df52ceb 100644 --- a/lib/core/connection/pool.js +++ b/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 ) diff --git a/lib/core/sdam/server.js b/lib/core/sdam/server.js index 26aeb5ed23..7adb0dfb95 100644 --- a/lib/core/sdam/server.js +++ b/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}` ); diff --git a/lib/core/topologies/server.js b/lib/core/topologies/server.js index c6a0bfa5db..43bf758205 100644 --- a/lib/core/topologies/server.js +++ b/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; diff --git a/lib/operations/command.js b/lib/operations/command.js index fd18a543c5..e65d3bbb49 100644 --- a/lib/operations/command.js +++ b/lib/operations/command.js @@ -8,6 +8,7 @@ const handleCallback = require('../utils').handleCallback; const MongoError = require('../core').MongoError; const ReadPreference = require('../core').ReadPreference; const MongoDBNamespace = require('../utils').MongoDBNamespace; +const extractCommand = require('../command_utils').extractCommand; const debugFields = [ 'authSource', @@ -95,9 +96,10 @@ class CommandOperation extends OperationBase { // Debug information if (db.s.logger.isDebug()) { + const extractedCommand = extractCommand(command); db.s.logger.debug( `executing command ${JSON.stringify( - command + extractedCommand.shouldRedact ? `${extractedCommand.name} details REDACTED` : command )} against ${dbName}.$cmd with options [${JSON.stringify( debugOptions(debugFields, options) )}]` diff --git a/lib/operations/command_v2.js b/lib/operations/command_v2.js index 52f982b885..475a1c1342 100644 --- a/lib/operations/command_v2.js +++ b/lib/operations/command_v2.js @@ -9,6 +9,7 @@ const maxWireVersion = require('../core/utils').maxWireVersion; const decorateWithExplain = require('../utils').decorateWithExplain; const commandSupportsReadConcern = require('../core/sessions').commandSupportsReadConcern; const MongoError = require('../core/error').MongoError; +const extractCommand = require('../command_utils').extractCommand; const SUPPORTS_WRITE_CONCERN_AND_COLLATION = 5; @@ -89,7 +90,12 @@ class CommandOperationV2 extends OperationBase { } if (this.logger && this.logger.isDebug()) { - this.logger.debug(`executing command ${JSON.stringify(cmd)} against ${this.ns}`); + const extractedCommand = extractCommand(cmd); + this.logger.debug( + `executing command ${JSON.stringify( + extractedCommand.shouldRedact ? `${extractedCommand.name} details REDACTED` : cmd + )} against ${this.ns}` + ); } server.command(this.ns.toString(), cmd, this.options, (err, result) => { diff --git a/lib/operations/db_ops.js b/lib/operations/db_ops.js index 8f9b89046b..fb9c492da8 100644 --- a/lib/operations/db_ops.js +++ b/lib/operations/db_ops.js @@ -8,6 +8,7 @@ const MongoError = require('../core').MongoError; const parseIndexOptions = require('../utils').parseIndexOptions; const ReadPreference = require('../core').ReadPreference; const toError = require('../utils').toError; +const extractCommand = require('../command_utils').extractCommand; const CONSTANTS = require('../constants'); const MongoDBNamespace = require('../utils').MongoDBNamespace; @@ -227,14 +228,16 @@ function executeCommand(db, command, options, callback) { options.readPreference = ReadPreference.resolve(db, options); // Debug information - if (db.s.logger.isDebug()) + if (db.s.logger.isDebug()) { + const extractedCommand = extractCommand(command); db.s.logger.debug( `executing command ${JSON.stringify( - command + extractedCommand.shouldRedact ? `${extractedCommand.name} details REDACTED` : command )} against ${dbName}.$cmd with options [${JSON.stringify( debugOptions(debugFields, options) )}]` ); + } // Execute command db.s.topology.command(db.s.namespace.withCollection('$cmd'), command, options, (err, result) => {