From 8fc754bb8268a165bf3245d6cce6f3d56c95fa9b Mon Sep 17 00:00:00 2001 From: Daria Pardue <81593090+dariakp@users.noreply.github.com> Date: Wed, 16 Jun 2021 16:20:51 -0400 Subject: [PATCH 1/6] Mark logs to check --- lib/core/connection/connection.js | 2 ++ lib/core/connection/pool.js | 1 + lib/core/cursor.js | 2 ++ lib/core/sdam/server.js | 1 + lib/core/topologies/server.js | 1 + lib/operations/command.js | 1 + lib/operations/command_v2.js | 1 + lib/operations/db_ops.js | 1 + 8 files changed, 10 insertions(+) diff --git a/lib/core/connection/connection.js b/lib/core/connection/connection.js index 5b22513b2a6..231100ec5a9 100644 --- a/lib/core/connection/connection.js +++ b/lib/core/connection/connection.js @@ -106,6 +106,7 @@ class Connection extends EventEmitter { // Debug information if (this.logger.isDebug()) { + // TODO: might have sensitive data? this.logger.debug( `creating connection ${this.id} with options [${JSON.stringify( debugOptions(DEBUG_FIELDS, options) @@ -253,6 +254,7 @@ class Connection extends EventEmitter { write(buffer) { // Debug Log if (this.logger.isDebug()) { + // TODO: might need to redact? if (!Array.isArray(buffer)) { this.logger.debug(`writing buffer [${buffer.toString('hex')}] to ${this.address}`); } else { diff --git a/lib/core/connection/pool.js b/lib/core/connection/pool.js index f0061ee914e..a270e5b4ee4 100644 --- a/lib/core/connection/pool.js +++ b/lib/core/connection/pool.js @@ -388,6 +388,7 @@ function messageHandler(self) { // Log if debug enabled if (self.logger.isDebug()) { + // TODO: might need to redact? or delete? self.logger.debug( f( 'message [%s] received from %s:%s', diff --git a/lib/core/cursor.js b/lib/core/cursor.js index 48b60d1a95b..5c15934858f 100644 --- a/lib/core/cursor.js +++ b/lib/core/cursor.js @@ -524,6 +524,7 @@ class CoreCursor extends Readable { if (cursor.operation) { if (cursor.logger.isDebug()) { + // TODO: can this contain sensitive data? cursor.logger.debug( `issue initial query [${JSON.stringify(cursor.cmd)}] with flags [${JSON.stringify( cursor.query @@ -591,6 +592,7 @@ class CoreCursor extends Readable { } if (cursor.logger.isDebug()) { + // TODO: can this contain sensitive data? cursor.logger.debug( `issue initial query [${JSON.stringify(cursor.cmd)}] with flags [${JSON.stringify( cursor.query diff --git a/lib/core/sdam/server.js b/lib/core/sdam/server.js index 26aeb5ed234..3b78d205458 100644 --- a/lib/core/sdam/server.js +++ b/lib/core/sdam/server.js @@ -261,6 +261,7 @@ class Server extends EventEmitter { // Debug log if (this.s.logger.isDebug()) { + // TODO: redact or delete this.s.logger.debug( `executing command [${JSON.stringify({ ns, diff --git a/lib/core/topologies/server.js b/lib/core/topologies/server.js index c6a0bfa5db9..075f1c7b119 100644 --- a/lib/core/topologies/server.js +++ b/lib/core/topologies/server.js @@ -609,6 +609,7 @@ Server.prototype.command = function(ns, cmd, options, callback) { // Debug log if (self.s.logger.isDebug()) + // TODO: redact or delete self.s.logger.debug( f( 'executing command [%s] against %s', diff --git a/lib/operations/command.js b/lib/operations/command.js index fd18a543c51..ddcb2d81d40 100644 --- a/lib/operations/command.js +++ b/lib/operations/command.js @@ -95,6 +95,7 @@ class CommandOperation extends OperationBase { // Debug information if (db.s.logger.isDebug()) { + // TODO: redact or delete db.s.logger.debug( `executing command ${JSON.stringify( command diff --git a/lib/operations/command_v2.js b/lib/operations/command_v2.js index 52f982b885f..63a7ea1182a 100644 --- a/lib/operations/command_v2.js +++ b/lib/operations/command_v2.js @@ -89,6 +89,7 @@ class CommandOperationV2 extends OperationBase { } if (this.logger && this.logger.isDebug()) { + // TODO: redact or delete this.logger.debug(`executing command ${JSON.stringify(cmd)} against ${this.ns}`); } diff --git a/lib/operations/db_ops.js b/lib/operations/db_ops.js index 8f9b89046b2..e33156af858 100644 --- a/lib/operations/db_ops.js +++ b/lib/operations/db_ops.js @@ -228,6 +228,7 @@ function executeCommand(db, command, options, callback) { // Debug information if (db.s.logger.isDebug()) + // TODO: redact or delete db.s.logger.debug( `executing command ${JSON.stringify( command From 2e5d79f0ae1cd74df6af65f14d9dc6fdbf9b0316 Mon Sep 17 00:00:00 2001 From: Daria Pardue <81593090+dariakp@users.noreply.github.com> Date: Mon, 21 Jun 2021 16:44:00 -0400 Subject: [PATCH 2/6] Adjust log content for connection debugging --- lib/core/connection/connection.js | 7 ++++--- lib/core/connection/pool.js | 5 ++--- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/lib/core/connection/connection.js b/lib/core/connection/connection.js index 231100ec5a9..9086142a1ce 100644 --- a/lib/core/connection/connection.js +++ b/lib/core/connection/connection.js @@ -106,7 +106,6 @@ class Connection extends EventEmitter { // Debug information if (this.logger.isDebug()) { - // TODO: might have sensitive data? this.logger.debug( `creating connection ${this.id} with options [${JSON.stringify( debugOptions(DEBUG_FIELDS, options) @@ -256,10 +255,12 @@ class Connection extends EventEmitter { if (this.logger.isDebug()) { // TODO: might need to redact? 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}` + ); } } diff --git a/lib/core/connection/pool.js b/lib/core/connection/pool.js index a270e5b4ee4..521be11e76b 100644 --- a/lib/core/connection/pool.js +++ b/lib/core/connection/pool.js @@ -388,11 +388,10 @@ function messageHandler(self) { // Log if debug enabled if (self.logger.isDebug()) { - // TODO: might need to redact? or delete? 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 ) From a16ce4b65df8e8bf61ebe72e026ab67fcb239363 Mon Sep 17 00:00:00 2001 From: Daria Pardue <81593090+dariakp@users.noreply.github.com> Date: Mon, 21 Jun 2021 17:11:55 -0400 Subject: [PATCH 3/6] Combine command extraction logic --- lib/core/connection/apm.js | 57 ++++++++++++++++++-------------------- 1 file changed, 27 insertions(+), 30 deletions(-) diff --git a/lib/core/connection/apm.js b/lib/core/connection/apm.js index f6e293b4293..85f991b12a7 100644 --- a/lib/core/connection/apm.js +++ b/lib/core/connection/apm.js @@ -20,17 +20,14 @@ const SENSITIVE_COMMANDS = new Set([ const HELLO_COMMANDS = new Set(['hello', 'ismaster', 'isMaster']); // 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) => +const shouldRedactCommand = (commandName, cmd) => SENSITIVE_COMMANDS.has(commandName) || - (HELLO_COMMANDS.has(commandName) && cmd.speculativeAuthenticate) - ? {} - : result; + (HELLO_COMMANDS.has(commandName) && !!cmd.speculativeAuthenticate); const isLegacyPool = pool => pool.s && pool.queue; const LEGACY_FIND_QUERY_MAP = { @@ -69,26 +66,21 @@ const OP_QUERY_KEYS = [ * @param {Object} command the command */ const extractCommand = command => { + let extractedCommand; if (command instanceof GetMore) { - return { + extractedCommand = { getMore: command.cursorId, collection: collectionName(command), batchSize: command.numberToReturn }; - } - - if (command instanceof KillCursor) { - return { + } else if (command instanceof KillCursor) { + extractedCommand = { killCursors: collectionName(command), cursors: command.cursorIds }; - } - - if (command instanceof Msg) { - return command.command; - } - - if (command.query && command.query.$query) { + } 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 @@ -115,13 +107,15 @@ const extractCommand = command => { } if (command.query.$explain) { - return { explain: result }; + extractedCommand = { explain: result }; + } else { + extractedCommand = result; } - - return result; + } else { + extractedCommand = command.query || command; } - return command.query ? command.query : command; + return { cmd: extractedCommand, name: Object.keys(extractedCommand)[0] }; }; const extractReply = (command, reply) => { @@ -183,15 +177,16 @@ class CommandStartedEvent { * @param {Object} command the command */ constructor(pool, command) { - const cmd = extractCommand(command); - const commandName = extractCommandName(cmd); + const extractedCommand = extractCommand(command); + const cmd = extractedCommand.cmd; + 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: shouldRedactCommand(commandName, cmd) ? {} : cmd }); } } @@ -207,15 +202,16 @@ 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 cmd = extractedCommand.cmd; + 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: shouldRedactCommand(commandName, cmd) ? {} : extractReply(command, reply) }); } } @@ -231,15 +227,16 @@ 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 cmd = extractedCommand.cmd; + 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: shouldRedactCommand(commandName, cmd) ? {} : error }); } } From cb621baee5819bc24d215a253862a25893d6b88e Mon Sep 17 00:00:00 2001 From: Daria Pardue <81593090+dariakp@users.noreply.github.com> Date: Tue, 22 Jun 2021 10:40:55 -0400 Subject: [PATCH 4/6] Move command extraction logic to utils --- lib/command_utils.js | 122 +++++++++++++++++++++++++++++++++++++ lib/core/connection/apm.js | 118 ++--------------------------------- 2 files changed, 126 insertions(+), 114 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 00000000000..ba8289c326b --- /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 85f991b12a7..875e418262b 100644 --- a/lib/core/connection/apm.js +++ b/lib/core/connection/apm.js @@ -1,123 +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 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 shouldRedactCommand = (commandName, cmd) => - SENSITIVE_COMMANDS.has(commandName) || - (HELLO_COMMANDS.has(commandName) && !!cmd.speculativeAuthenticate); 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 => { - 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; - } - - return { cmd: extractedCommand, name: Object.keys(extractedCommand)[0] }; -}; - const extractReply = (command, reply) => { if (command instanceof GetMore) { return { @@ -178,7 +71,6 @@ class CommandStartedEvent { */ constructor(pool, command) { const extractedCommand = extractCommand(command); - const cmd = extractedCommand.cmd; const commandName = extractedCommand.name; const connectionDetails = extractConnectionDetails(pool); @@ -186,7 +78,7 @@ class CommandStartedEvent { requestId: command.requestId, databaseName: databaseName(command), commandName, - command: shouldRedactCommand(commandName, cmd) ? {} : cmd + command: extractedCommand.shouldRedact ? {} : extractedCommand.cmd }); } } @@ -203,7 +95,6 @@ class CommandSucceededEvent { */ constructor(pool, command, reply, started) { const extractedCommand = extractCommand(command); - const cmd = extractedCommand.cmd; const commandName = extractedCommand.name; const connectionDetails = extractConnectionDetails(pool); @@ -211,7 +102,7 @@ class CommandSucceededEvent { requestId: command.requestId, commandName, duration: calculateDurationInMs(started), - reply: shouldRedactCommand(commandName, cmd) ? {} : extractReply(command, reply) + reply: extractedCommand.shouldRedact ? {} : extractReply(command, reply) }); } } @@ -228,7 +119,6 @@ class CommandFailedEvent { */ constructor(pool, command, error, started) { const extractedCommand = extractCommand(command); - const cmd = extractedCommand.cmd; const commandName = extractedCommand.name; const connectionDetails = extractConnectionDetails(pool); @@ -236,7 +126,7 @@ class CommandFailedEvent { requestId: command.requestId, commandName, duration: calculateDurationInMs(started), - failure: shouldRedactCommand(commandName, cmd) ? {} : error + failure: extractedCommand.shouldRedact ? {} : error }); } } From da74f03042844d409757c77b1b28884ad02df2fc Mon Sep 17 00:00:00 2001 From: Daria Pardue <81593090+dariakp@users.noreply.github.com> Date: Tue, 22 Jun 2021 15:22:47 -0400 Subject: [PATCH 5/6] update command logging --- lib/core/connection/connection.js | 1 - lib/core/cursor.js | 2 -- lib/core/sdam/server.js | 5 +++-- lib/core/topologies/server.js | 8 +++++--- lib/operations/command.js | 5 +++-- lib/operations/command_v2.js | 9 +++++++-- lib/operations/db_ops.js | 8 +++++--- 7 files changed, 23 insertions(+), 15 deletions(-) diff --git a/lib/core/connection/connection.js b/lib/core/connection/connection.js index 9086142a1ce..8e50f24745a 100644 --- a/lib/core/connection/connection.js +++ b/lib/core/connection/connection.js @@ -253,7 +253,6 @@ class Connection extends EventEmitter { write(buffer) { // Debug Log if (this.logger.isDebug()) { - // TODO: might need to redact? if (!Array.isArray(buffer)) { this.logger.debug(`writing buffer [ ${buffer.toString('hex').length} ] to ${this.address}`); } else { diff --git a/lib/core/cursor.js b/lib/core/cursor.js index 5c15934858f..48b60d1a95b 100644 --- a/lib/core/cursor.js +++ b/lib/core/cursor.js @@ -524,7 +524,6 @@ class CoreCursor extends Readable { if (cursor.operation) { if (cursor.logger.isDebug()) { - // TODO: can this contain sensitive data? cursor.logger.debug( `issue initial query [${JSON.stringify(cursor.cmd)}] with flags [${JSON.stringify( cursor.query @@ -592,7 +591,6 @@ class CoreCursor extends Readable { } if (cursor.logger.isDebug()) { - // TODO: can this contain sensitive data? cursor.logger.debug( `issue initial query [${JSON.stringify(cursor.cmd)}] with flags [${JSON.stringify( cursor.query diff --git a/lib/core/sdam/server.js b/lib/core/sdam/server.js index 3b78d205458..5d5e9b87a56 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,11 +262,11 @@ class Server extends EventEmitter { // Debug log if (this.s.logger.isDebug()) { - // TODO: redact or delete + 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}` ); diff --git a/lib/core/topologies/server.js b/lib/core/topologies/server.js index 075f1c7b119..a10a0178265 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,19 +609,20 @@ Server.prototype.command = function(ns, cmd, options, callback) { options = Object.assign({}, options, { wireProtocolCommand: false }); // Debug log - if (self.s.logger.isDebug()) - // TODO: redact or delete + 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; diff --git a/lib/operations/command.js b/lib/operations/command.js index ddcb2d81d40..98da1dabc99 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,10 +96,10 @@ class CommandOperation extends OperationBase { // Debug information if (db.s.logger.isDebug()) { - // TODO: redact or delete + const extractedCommand = extractCommand(command); db.s.logger.debug( `executing command ${JSON.stringify( - command + extractedCommand.shouldRedact ? extractedCommand.name : 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 63a7ea1182a..32f80e3dc8c 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,8 +90,12 @@ class CommandOperationV2 extends OperationBase { } if (this.logger && this.logger.isDebug()) { - // TODO: redact or delete - 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 : 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 e33156af858..ef0e9e535e7 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,15 +228,16 @@ function executeCommand(db, command, options, callback) { options.readPreference = ReadPreference.resolve(db, options); // Debug information - if (db.s.logger.isDebug()) - // TODO: redact or delete + if (db.s.logger.isDebug()) { + const extractedCommand = extractCommand(command); db.s.logger.debug( `executing command ${JSON.stringify( - command + extractedCommand.shouldRedact ? extractedCommand.name : 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) => { From a7a25bea9f6829f928652fc8fc130676d5b4a248 Mon Sep 17 00:00:00 2001 From: Daria Pardue <81593090+dariakp@users.noreply.github.com> Date: Wed, 23 Jun 2021 17:56:45 -0400 Subject: [PATCH 6/6] Update log messages --- lib/core/connection/connection.js | 6 ++---- lib/core/connection/pool.js | 2 +- lib/core/sdam/server.js | 2 +- lib/core/topologies/server.js | 2 +- lib/operations/command.js | 2 +- lib/operations/command_v2.js | 2 +- lib/operations/db_ops.js | 2 +- 7 files changed, 8 insertions(+), 10 deletions(-) diff --git a/lib/core/connection/connection.js b/lib/core/connection/connection.js index 8e50f24745a..c9d34960c8b 100644 --- a/lib/core/connection/connection.js +++ b/lib/core/connection/connection.js @@ -254,12 +254,10 @@ class Connection extends EventEmitter { // Debug Log if (this.logger.isDebug()) { if (!Array.isArray(buffer)) { - this.logger.debug(`writing buffer [ ${buffer.toString('hex').length} ] 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').length} ] 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 521be11e76b..491df52ceb6 100644 --- a/lib/core/connection/pool.js +++ b/lib/core/connection/pool.js @@ -391,7 +391,7 @@ function messageHandler(self) { self.logger.debug( f( 'message [ %s ] received from %s:%s', - message.raw.toString('hex').length, + message.raw.length, self.options.host, self.options.port ) diff --git a/lib/core/sdam/server.js b/lib/core/sdam/server.js index 5d5e9b87a56..7adb0dfb952 100644 --- a/lib/core/sdam/server.js +++ b/lib/core/sdam/server.js @@ -266,7 +266,7 @@ class Server extends EventEmitter { this.s.logger.debug( `executing command [${JSON.stringify({ ns, - cmd: extractedCommand.shouldRedact ? extractedCommand.name : 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 a10a0178265..43bf7582059 100644 --- a/lib/core/topologies/server.js +++ b/lib/core/topologies/server.js @@ -616,7 +616,7 @@ Server.prototype.command = function(ns, cmd, options, callback) { 'executing command [%s] against %s', JSON.stringify({ ns: ns, - cmd: extractedCommand.shouldRedact ? extractedCommand.name : cmd, + cmd: extractedCommand.shouldRedact ? `${extractedCommand.name} details REDACTED` : cmd, options: debugOptions(debugFields, options) }), self.name diff --git a/lib/operations/command.js b/lib/operations/command.js index 98da1dabc99..e65d3bbb493 100644 --- a/lib/operations/command.js +++ b/lib/operations/command.js @@ -99,7 +99,7 @@ class CommandOperation extends OperationBase { const extractedCommand = extractCommand(command); db.s.logger.debug( `executing command ${JSON.stringify( - extractedCommand.shouldRedact ? extractedCommand.name : 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 32f80e3dc8c..475a1c13426 100644 --- a/lib/operations/command_v2.js +++ b/lib/operations/command_v2.js @@ -93,7 +93,7 @@ class CommandOperationV2 extends OperationBase { const extractedCommand = extractCommand(cmd); this.logger.debug( `executing command ${JSON.stringify( - extractedCommand.shouldRedact ? extractedCommand.name : cmd + extractedCommand.shouldRedact ? `${extractedCommand.name} details REDACTED` : cmd )} against ${this.ns}` ); } diff --git a/lib/operations/db_ops.js b/lib/operations/db_ops.js index ef0e9e535e7..fb9c492da8d 100644 --- a/lib/operations/db_ops.js +++ b/lib/operations/db_ops.js @@ -232,7 +232,7 @@ function executeCommand(db, command, options, callback) { const extractedCommand = extractCommand(command); db.s.logger.debug( `executing command ${JSON.stringify( - extractedCommand.shouldRedact ? extractedCommand.name : command + extractedCommand.shouldRedact ? `${extractedCommand.name} details REDACTED` : command )} against ${dbName}.$cmd with options [${JSON.stringify( debugOptions(debugFields, options) )}]`