From e3c004d38fe196da61ae9aea3ea0185a275ea4e6 Mon Sep 17 00:00:00 2001 From: Henrik Edin Date: Fri, 14 Feb 2020 15:47:35 -0500 Subject: SERVER-46026 Fix kill_sessions.js and logs_include_client_info.js to handle JSON logs --- jstests/auth/logs_include_client_info.js | 34 ++++++++++++++++++++++++++------ jstests/libs/kill_sessions.js | 21 +++++++++++++++----- src/mongo/db/auth/sasl_commands.cpp | 29 +++++++++++++-------------- src/mongo/shell/check_log.js | 24 ++++++++++++++++++++++ 4 files changed, 82 insertions(+), 26 deletions(-) diff --git a/jstests/auth/logs_include_client_info.js b/jstests/auth/logs_include_client_info.js index 31594a60de5..8d5115cc328 100644 --- a/jstests/auth/logs_include_client_info.js +++ b/jstests/auth/logs_include_client_info.js @@ -1,5 +1,6 @@ // This test just checks that the success/failure messages for authentication include the IP // address of the client attempting to authenticate. +load("jstests/libs/logv2_helpers.js"); (function() { const conn = MongoRunner.runMongod({auth: ""}); @@ -18,12 +19,33 @@ failConn.getDB("admin").auth("root", "toot"); const log = assert.commandWorked(admin.runCommand({getLog: "global"})).log; -const successRegex = - /Successfully authenticated as principal root on admin from client (?:\d{1,3}\.){3}\d{1,3}:\d+/; -const failRegex = - /SASL SCRAM-SHA-\d+ authentication failed for root on admin from client (?:\d{1,3}\.){3}\d{1,3}:\d+/; +if (isJsonLog(conn)) { + function checkAuthSuccess(element, index, array) { + const log = JSON.parse(element); + + return log.id === 20250 && log.attr.principalName === "root" && + log.attr.authDB === "admin" && /(?:\d{1,3}\.){3}\d{1,3}:\d+/.test(log.attr.client); + } + + function checkSCRAMfail(element, index, array) { + const log = JSON.parse(element); + + return log.id === 20249 && /SCRAM-SHA-\d+/.test(log.attr.mechanism) && + log.attr.principalName === "root" && log.attr.authDB === "admin" && + /(?:\d{1,3}\.){3}\d{1,3}:\d+/.test(log.attr.client); + } + + assert(log.some(checkAuthSuccess)); + assert(log.some(checkSCRAMfail)); +} else { + const successRegex = + /Successfully authenticated as principal root on admin from client (?:\d{1,3}\.){3}\d{1,3}:\d+/; + const failRegex = + /SASL SCRAM-SHA-\d+ authentication failed for root on admin from client (?:\d{1,3}\.){3}\d{1,3}:\d+/; + + assert(log.some((line) => successRegex.test(line))); + assert(log.some((line) => failRegex.test(line))); +} -assert(log.some((line) => successRegex.test(line))); -assert(log.some((line) => failRegex.test(line))); MongoRunner.stopMongod(conn); })(); diff --git a/jstests/libs/kill_sessions.js b/jstests/libs/kill_sessions.js index b56554d02c4..bf4a2c541b8 100644 --- a/jstests/libs/kill_sessions.js +++ b/jstests/libs/kill_sessions.js @@ -1,4 +1,5 @@ load("jstests/libs/parallelTester.js"); +load("jstests/libs/logv2_helpers.js"); /** * Implements a kill session test helper @@ -248,11 +249,21 @@ var _kill_sessions_api_module = (function() { CursorHandle.prototype.assertCursorKillLogMessages = function(hostsToCheck) { for (let hostToCheck of hostsToCheck) { if (hostToCheck.host in this._cursors) { - assert(checkLog.checkContainsOnce( - hostToCheck, - 'killing cursor: ' + this._cursors[hostToCheck.host].exactValueString + - ' as part of killing session(s)'), - "cursor kill was not logged by " + hostToCheck.host); + if (isJsonLog(hostToCheck)) { + assert(checkLog.checkContainsOnceJson( + hostToCheck, + 20528, + 'id', + this._cursors[hostToCheck.host].exactValueString), + "cursor kill was not logged by " + hostToCheck.host); + } else { + assert( + checkLog.checkContainsOnce( + hostToCheck, + 'killing cursor: ' + this._cursors[hostToCheck.host].exactValueString + + ' as part of killing session(s)'), + "cursor kill was not logged by " + hostToCheck.host); + } } } }; diff --git a/src/mongo/db/auth/sasl_commands.cpp b/src/mongo/db/auth/sasl_commands.cpp index 22403e23303..b91fa86b9a2 100644 --- a/src/mongo/db/auth/sasl_commands.cpp +++ b/src/mongo/db/auth/sasl_commands.cpp @@ -189,14 +189,14 @@ Status doSaslStep(OperationContext* opCtx, if (!swResponse.isOK()) { LOGV2(20249, - "SASL {mechanism_mechanismName} authentication failed for " - "{mechanism_getPrincipalName} on {mechanism_getAuthenticationDatabase} from client " - "{opCtx_getClient_getRemote} ; {swResponse_getStatus}", - "mechanism_mechanismName"_attr = mechanism.mechanismName(), - "mechanism_getPrincipalName"_attr = mechanism.getPrincipalName(), - "mechanism_getAuthenticationDatabase"_attr = mechanism.getAuthenticationDatabase(), - "opCtx_getClient_getRemote"_attr = opCtx->getClient()->getRemote().toString(), - "swResponse_getStatus"_attr = redact(swResponse.getStatus())); + "SASL {mechanism} authentication failed for " + "{principalName} on {authDB} from client " + "{client} ; {result}", + "mechanism"_attr = mechanism.mechanismName(), + "principalName"_attr = mechanism.getPrincipalName(), + "authDB"_attr = mechanism.getAuthenticationDatabase(), + "client"_attr = opCtx->getClient()->getRemote().toString(), + "result"_attr = redact(swResponse.getStatus())); sleepmillis(saslGlobalParams.authFailedDelay.load()); // All the client needs to know is that authentication has failed. @@ -218,13 +218,12 @@ Status doSaslStep(OperationContext* opCtx, if (!serverGlobalParams.quiet.load()) { LOGV2(20250, - "Successfully authenticated as principal {mechanism_getPrincipalName} on " - "{mechanism_getAuthenticationDatabase} from client " - "{opCtx_getClient_session_remote}", - "mechanism_getPrincipalName"_attr = mechanism.getPrincipalName(), - "mechanism_getAuthenticationDatabase"_attr = - mechanism.getAuthenticationDatabase(), - "opCtx_getClient_session_remote"_attr = opCtx->getClient()->session()->remote()); + "Successfully authenticated as principal {principalName} on " + "{authDB} from client " + "{client}", + "principalName"_attr = mechanism.getPrincipalName(), + "authDB"_attr = mechanism.getAuthenticationDatabase(), + "client"_attr = opCtx->getClient()->session()->remote()); } if (session->isSpeculative()) { authCounter.incSpeculativeAuthenticateSuccessful(mechanism.mechanismName().toString()); diff --git a/src/mongo/shell/check_log.js b/src/mongo/shell/check_log.js index e5152becf6e..cf514536f99 100644 --- a/src/mongo/shell/check_log.js +++ b/src/mongo/shell/check_log.js @@ -50,6 +50,29 @@ checkLog = (function() { return false; }; + /* + * Calls the 'getLog' function on the provided connection 'conn' to see if a log with the + * provided id is found in the logs. If the id is found it looks up the specified attrribute by + * attrName and checks if the msg is found in its value. Note: this function does not throw an + * exception, so the return value should not be ignored. + */ + const checkContainsOnceJson = function(conn, id, attrName, msg) { + const logMessages = getGlobalLog(conn); + if (logMessages === null) { + return false; + } + + for (let logMsg of logMessages) { + if (logMsg.search(`\"id\":${id},`) != -1) { + if (logMsg.search(`\"${attrName}\":\"?[^\"|\\\"]*` + msg) != -1) { + return true; + } + } + } + + return false; + }; + /* * Calls the 'getLog' function at regular intervals on the provided connection 'conn' until * the provided 'msg' is found in the logs, or it times out. Throws an exception on timeout. @@ -145,6 +168,7 @@ checkLog = (function() { return { getGlobalLog: getGlobalLog, checkContainsOnce: checkContainsOnce, + checkContainsOnceJson: checkContainsOnceJson, contains: contains, containsWithCount: containsWithCount, containsWithAtLeastCount: containsWithAtLeastCount, -- cgit v1.2.1