SERVER-51457: Improve log line for failed speculative auth attempts

(cherry picked from commit 33afc4e43719177adac01b9f9978dd3477b37649)

8 files changed, 167 insertions, 33 deletions

diff --git a/jstests/auth/sasl-unknown-mech.js b/jstests/auth/sasl-unknown-mech.js
index 43b793fb20f..566272337fd 100644
--- a/jstests/auth/sasl-unknown-mech.js
+++ b/jstests/auth/sasl-unknown-mech.js
@@ -34,14 +34,14 @@ function saslStartSuccess(mechanism) {
 saslStartSuccess('SCRAM-SHA-1');
 saslStartSuccess('SCRAM-SHA-256');
 
-function saslStartFailure(mechanism) {
+function saslStartFailure(mechanism, expectedCode) {
     const response = assert.commandFailed(saslStart(mechanism));
     assert.gt(response.errmsg.length, 0);
-    assert.neq(response.code, 0);
+    assert.eq(response.code, expectedCode);
 }
-saslStartFailure('scram-sha-1');
-saslStartFailure('MONGODB-CR');
-saslStartFailure(undefined);
+saslStartFailure('scram-sha-1', ErrorCodes.MechanismUnavailable);
+saslStartFailure('MONGODB-CR', ErrorCodes.MechanismUnavailable);
+saslStartFailure(undefined, ErrorCodes.NoSuchKey);
 
 MongoRunner.stopMongod(mongod);
 })();
diff --git a/jstests/auth/speculative-sasl-start.js b/jstests/auth/speculative-sasl-start.js
index 8db5d03dcb7..1019d8e0528 100644
--- a/jstests/auth/speculative-sasl-start.js
+++ b/jstests/auth/speculative-sasl-start.js
@@ -41,6 +41,11 @@ function expectN(mechStats, mech, N, M) {
     assert.eq(M, stats.successful);
 }
 
+function assertSpecLog(severity, expectedAttrs, expectedCount) {
+    assert(
+        checkLog.checkContainsWithCountJson(admin, 20249, expectedAttrs, expectedCount, severity));
+}
+
 const baseOKURI = 'mongodb://admin:pwd@localhost:' + mongod.port + '/admin';
 
 // Speculate SCRAM-SHA-1
@@ -59,19 +64,70 @@ assertStats((s) => expectN(s, 'SCRAM-SHA-1', 1, 1));
 assertStats((s) => expectN(s, 'SCRAM-SHA-256', 2, 2));
 
 const baseFAILURI = 'mongodb://admin:haxx@localhost:' + mongod.port + '/admin';
-
+// Client is impossible to match using checklog.
+const speculativeSHA1AuthFailedAttrs = {
+    "mechanism": "SCRAM-SHA-1",
+    "speculative": true,
+    "principalName": "admin",
+    "authenticationDatabase": "admin",
+    "error": "AuthenticationFailed: SCRAM authentication failed, storedKey mismatch"
+};
+const sha1AuthFailedAttrs = {
+    "mechanism": "SCRAM-SHA-1",
+    "speculative": false,
+    "principalName": "admin",
+    "authenticationDatabase": "admin",
+    "error": "AuthenticationFailed: SCRAM authentication failed, storedKey mismatch"
+};
+const speculativeSHA256AuthFailedAttrs = {
+    "mechanism": "SCRAM-SHA-256",
+    "speculative": true,
+    "principalName": "admin",
+    "authenticationDatabase": "admin",
+    "error": "AuthenticationFailed: SCRAM authentication failed, storedKey mismatch"
+};
+const sha256AuthFailedAttrs = {
+    "mechanism": "SCRAM-SHA-256",
+    "speculative": false,
+    "principalName": "admin",
+    "authenticationDatabase": "admin",
+    "error": "AuthenticationFailed: SCRAM authentication failed, storedKey mismatch"
+};
+const speculativeSHA256MechUnavailableAttrs = {
+    "mechanism": "SCRAM-SHA-256",
+    "speculative": true,
+    "principalName": "admin",
+    "authenticationDatabase": "admin",
+    "error":
+        "MechanismUnavailable: Unable to use SCRAM-SHA-256 based authentication for user without any SCRAM-SHA-256 credentials registered"
+};
+const sha256MechUnavailableAttrs = {
+    "mechanism": "SCRAM-SHA-256",
+    "speculative": false,
+    "principalName": "admin",
+    "authenticationDatabase": "admin",
+    "error":
+        "MechanismUnavailable: Unable to use SCRAM-SHA-256 based authentication for user without any SCRAM-SHA-256 credentials registered"
+};
+admin.setLogLevel(5);
 // Invalid password should never connect regardless of speculative auth.
 test(baseFAILURI + '?authMechanism=SCRAM-SHA-1', false);
 assertStats((s) => expectN(s, 'SCRAM-SHA-1', 2, 1));
 assertStats((s) => expectN(s, 'SCRAM-SHA-256', 2, 2));
+assertSpecLog("I", speculativeSHA1AuthFailedAttrs, 1);
+assertSpecLog("I", sha1AuthFailedAttrs, 1);
 
 test(baseFAILURI + '?authMechanism=SCRAM-SHA-256', false);
 assertStats((s) => expectN(s, 'SCRAM-SHA-1', 2, 1));
 assertStats((s) => expectN(s, 'SCRAM-SHA-256', 3, 2));
+assertSpecLog("I", speculativeSHA256AuthFailedAttrs, 1);
+assertSpecLog("I", sha256AuthFailedAttrs, 1);
 
 test(baseFAILURI, false);
 assertStats((s) => expectN(s, 'SCRAM-SHA-1', 2, 1));
 assertStats((s) => expectN(s, 'SCRAM-SHA-256', 4, 2));
+assertSpecLog("I", speculativeSHA256AuthFailedAttrs, 2);
+assertSpecLog("I", sha256AuthFailedAttrs, 2);
 
 // Update admin use to only allow SCRAM-SHA-1
 
@@ -81,6 +137,7 @@ admin.updateUser('admin', {mechanisms: ['SCRAM-SHA-1']});
 test(baseOKURI, true);
 assertStats((s) => expectN(s, 'SCRAM-SHA-1', 2, 1));
 assertStats((s) => expectN(s, 'SCRAM-SHA-256', 5, 2));
+assertSpecLog("D5", speculativeSHA256MechUnavailableAttrs, 1);
 
 // Explicit SCRAM-SHA-1 should successfully speculate.
 test(baseOKURI + '?authMechanism=SCRAM-SHA-1', true);
@@ -91,11 +148,15 @@ assertStats((s) => expectN(s, 'SCRAM-SHA-256', 5, 2));
 test(baseOKURI + '?authMechanism=SCRAM-SHA-256', false);
 assertStats((s) => expectN(s, 'SCRAM-SHA-1', 3, 2));
 assertStats((s) => expectN(s, 'SCRAM-SHA-256', 6, 2));
+assertSpecLog("D5", speculativeSHA256MechUnavailableAttrs, 2);
+assertSpecLog("I", sha256MechUnavailableAttrs, 1);
 
 // Test that a user not in the admin DB can speculate
 mongod.getDB('test').createUser({user: 'alice', pwd: 'secret', roles: []});
 test('mongodb://alice:secret@localhost:' + mongod.port + '/test', true);
 assertStats((s) => expectN(s, 'SCRAM-SHA-256', 7, 3));
 
+admin.setLogLevel(0);
+
 MongoRunner.stopMongod(mongod);
 })();
diff --git a/src/mongo/base/error_codes.yml b/src/mongo/base/error_codes.yml
index 718e634c81c..f0bb4113dc9 100644
--- a/src/mongo/base/error_codes.yml
+++ b/src/mongo/base/error_codes.yml
@@ -370,6 +370,8 @@ error_codes:
 
     - {code: 326, name: OplogQueryMinTsMissing}
 
+    - {code: 334, name: MechanismUnavailable}
+
     # Error codes 4000-8999 are reserved.
 
     # Non-sequential error codes for compatibility only)
diff --git a/src/mongo/db/auth/sasl_commands.cpp b/src/mongo/db/auth/sasl_commands.cpp
index 0c68225a6ee..8661fb4fcfe 100644
--- a/src/mongo/db/auth/sasl_commands.cpp
+++ b/src/mongo/db/auth/sasl_commands.cpp
@@ -204,10 +204,15 @@ Status doSaslStep(OperationContext* opCtx,
     };
 
     if (!swResponse.isOK()) {
+        int64_t dLevel = 0;
+        if (session->isSpeculative() &&
+            (swResponse.getStatus() == ErrorCodes::MechanismUnavailable)) {
+            dLevel = 5;
+        }
         auto attrs = makeLogAttributes();
         auto errorString = redact(swResponse.getStatus());
         attrs.add("error", errorString);
-        LOGV2(20249, "Authentication failed", attrs);
+        LOGV2_DEBUG(20249, dLevel, "Authentication failed", attrs);
 
         sleepmillis(saslGlobalParams.authFailedDelay.load());
         // All the client needs to know is that authentication has failed.
diff --git a/src/mongo/db/auth/sasl_mechanism_registry.cpp b/src/mongo/db/auth/sasl_mechanism_registry.cpp
index 667fa7a811e..1ade498d3cd 100644
--- a/src/mongo/db/auth/sasl_mechanism_registry.cpp
+++ b/src/mongo/db/auth/sasl_mechanism_registry.cpp
@@ -81,7 +81,7 @@ StatusWith<std::unique_ptr<ServerMechanismBase>> SASLServerMechanismRegistry::ge
         return (*it)->create(std::move(authenticationDatabase));
     }
 
-    return Status(ErrorCodes::BadValue,
+    return Status(ErrorCodes::MechanismUnavailable,
                   str::stream() << "Unsupported mechanism '" << mechanismName
                                 << "' on authentication database '" << authenticationDatabase
                                 << "'");
diff --git a/src/mongo/db/auth/sasl_scram_server_conversation.cpp b/src/mongo/db/auth/sasl_scram_server_conversation.cpp
index ece08adec08..d92b4711c01 100644
--- a/src/mongo/db/auth/sasl_scram_server_conversation.cpp
+++ b/src/mongo/db/auth/sasl_scram_server_conversation.cpp
@@ -209,7 +209,7 @@ StatusWith<std::tuple<bool, std::string>> SaslSCRAMServerMechanism<Policy>::_fir
                           "It is not possible to authenticate as the __system user "
                           "on servers started without a --keyFile parameter");
         } else if (scramCredentials.empty()) {
-            return {ErrorCodes::AuthenticationFailed,
+            return {ErrorCodes::MechanismUnavailable,
                     str::stream() << "Unable to use " << Policy::getName()
                                   << " based authentication for user without any "
                                   << Policy::getName() << " credentials registered"};
diff --git a/src/mongo/db/stats/counters.cpp b/src/mongo/db/stats/counters.cpp
index 63a0b6eb66d..9b4e6142328 100644
--- a/src/mongo/db/stats/counters.cpp
+++ b/src/mongo/db/stats/counters.cpp
@@ -208,7 +208,7 @@ Status AuthCounter::incSpeculativeAuthenticateReceived(const std::string& mechan
     _mechanisms.at(mechanism).speculativeAuthenticate.received.fetchAndAddRelaxed(1);
     return Status::OK();
 } catch (const std::out_of_range&) {
-    return {ErrorCodes::BadValue,
+    return {ErrorCodes::MechanismUnavailable,
             str::stream() << "Received " << auth::kSpeculativeAuthenticate << " for mechanism "
                           << mechanism << " which is unknown or not enabled"};
 }
@@ -219,7 +219,7 @@ Status AuthCounter::incSpeculativeAuthenticateSuccessful(const std::string& mech
 } catch (const std::out_of_range&) {
     // Should never actually occur since it'd mean we succeeded at a mechanism
     // we're not configured for.
-    return {ErrorCodes::BadValue,
+    return {ErrorCodes::MechanismUnavailable,
             str::stream() << "Unexpectedly succeeded at " << auth::kSpeculativeAuthenticate
                           << " for " << mechanism << " which is not enabled"};
 }
@@ -228,7 +228,7 @@ Status AuthCounter::incAuthenticateReceived(const std::string& mechanism) try {
     _mechanisms.at(mechanism).authenticate.received.fetchAndAddRelaxed(1);
     return Status::OK();
 } catch (const std::out_of_range&) {
-    return {ErrorCodes::BadValue,
+    return {ErrorCodes::MechanismUnavailable,
             str::stream() << "Received authentication for mechanism " << mechanism
                           << " which is unknown or not enabled"};
 }
@@ -239,7 +239,7 @@ Status AuthCounter::incAuthenticateSuccessful(const std::string& mechanism) try
 } catch (const std::out_of_range&) {
     // Should never actually occur since it'd mean we succeeded at a mechanism
     // we're not configured for.
-    return {ErrorCodes::BadValue,
+    return {ErrorCodes::MechanismUnavailable,
             str::stream() << "Unexpectedly succeeded at authentication for " << mechanism
                           << " which is not enabled"};
 }
diff --git a/src/mongo/shell/check_log.js b/src/mongo/shell/check_log.js
index 76f026af4ba..dcf94931848 100644
--- a/src/mongo/shell/check_log.js
+++ b/src/mongo/shell/check_log.js
@@ -50,7 +50,7 @@ checkLog = (function() {
         return false;
     };
 
-    const checkContainsOnceJson = function(conn, id, attrsDict) {
+    const checkContainsOnceJson = function(conn, id, attrsDict, severity = null) {
         const logMessages = getGlobalLog(conn);
         if (logMessages === null) {
             return false;
@@ -66,31 +66,39 @@ checkLog = (function() {
                 throw ex;
             }
 
-            if (obj.id === id) {
-                let allAttrMatch = true;
-                for (let attrKey in attrsDict) {
-                    const attrValue = attrsDict[attrKey];
-                    if (attrValue instanceof Function) {
-                        if (!attrValue(obj.attr[attrKey])) {
-                            allAttrMatch = false;
-                            break;
-                        }
-                    } else {
-                        if (obj.attr[attrKey] !== attrValue) {
-                            allAttrMatch = false;
-                            break;
-                        }
-                    }
-                }
-                if (allAttrMatch) {
-                    return true;
-                }
+            if (_compareLogs(obj, id, severity, attrsDict)) {
+                return true;
             }
         }
 
         return false;
     };
 
+    const checkContainsWithCountJson = function(
+        conn, id, attrsDict, expectedCount, severity = null) {
+        const logMessages = getGlobalLog(conn);
+        if (logMessages === null) {
+            return false;
+        }
+
+        let count = 0;
+        for (let logMsg of logMessages) {
+            let obj;
+            try {
+                obj = JSON.parse(logMsg);
+            } catch (ex) {
+                print('checkLog.checkContainsOnce: JsonJSON.parse() failed: ' + tojson(ex) + ': ' +
+                      logMsg);
+                throw ex;
+            }
+
+            if (_compareLogs(obj, id, severity, attrsDict)) {
+                count++;
+            }
+        }
+        return count === expectedCount;
+    };
+
     /*
      * 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
@@ -243,10 +251,68 @@ checkLog = (function() {
         return (Array.isArray(value) ? `[${serialized.join(',')}]` : `{${serialized.join(',')}}`);
     };
 
+    // Internal helper to compare objects filed by field.
+    const _deepEqual = function(object1, object2) {
+        if (object1 == null || object2 == null) {
+            return false;
+        }
+        const keys1 = Object.keys(object1);
+        const keys2 = Object.keys(object2);
+
+        if (keys1.length !== keys2.length) {
+            return false;
+        }
+
+        for (const key of keys1) {
+            const val1 = object1[key];
+            const val2 = object2[key];
+            const areObjects = _isObject(val1) && _isObject(val2);
+            if (areObjects && !_deepEqual(val1, val2) || !areObjects && val1 !== val2) {
+                return false;
+            }
+        }
+
+        return true;
+    };
+
+    // Internal helper to check that the argument is a non-null object.
+    const _isObject = function(object) {
+        return object != null && typeof object === 'object';
+    };
+
+    // Internal helper to check if a log's id, severity, and attributes match with what's expected.
+    const _compareLogs = function(obj, id, severity, attrsDict) {
+        if (obj.id !== id) {
+            return false;
+        }
+        if (severity !== null && obj.s !== severity) {
+            return false;
+        }
+
+        for (let attrKey in attrsDict) {
+            const attrValue = attrsDict[attrKey];
+            if (attrValue instanceof Function) {
+                if (!attrValue(obj.attr[attrKey])) {
+                    return false;
+                }
+            } else if (obj.attr[attrKey] !== attrValue && typeof obj.attr[attrKey] == "object") {
+                if (!_deepEqual(obj.attr[attrKey], attrValue)) {
+                    return false;
+                }
+            } else {
+                if (obj.attr[attrKey] !== attrValue) {
+                    return false;
+                }
+            }
+        }
+        return true;
+    };
+
     return {
         getGlobalLog: getGlobalLog,
         checkContainsOnce: checkContainsOnce,
         checkContainsOnceJson: checkContainsOnceJson,
+        checkContainsWithCountJson: checkContainsWithCountJson,
         checkContainsOnceJsonStringMatch: checkContainsOnceJsonStringMatch,
         contains: contains,
         containsJson: containsJson,