SERVER-22428 added logging for read-after-optime timeouts

buildscripts/resmokeconfig/suites/sharding_continuous_config_stepdown.yml

@@ -80,6 +80,7 @@ selector:
     # Calls the config server primary directly (not through mongos)
     - jstests/sharding/moveprimary_ignore_sharded.js
     - jstests/sharding/min_optime_recovery.js
+    - jstests/sharding/replset_config/read_after_optime.js
     - jstests/sharding/server_status.js
     # Runs setShardVersion/getShardVersion against the config server and we don't support retries
     # for this command

jstests/replsets/read_after_optime.js

@@ -5,10 +5,8 @@
 
 var replTest = new ReplSetTest({ nodes: 2 });
 replTest.startSet();
-
-var config = replTest.getReplSetConfig();
-replTest.initiate(config);
-config = replTest.getConfigFromPrimary();
+replTest.initiate();
+var config = replTest.getConfigFromPrimary();
 
 var runTest = function(testDB, primaryConn) {
     primaryConn.getDB('test').user.insert({ x: 1 }, { writeConcern: { w: 2 }});
@@ -24,25 +22,69 @@ var runTest = function(testDB, primaryConn) {
     }
 
     // Test timeout with maxTimeMS
-    var res = assert.commandFailed(testDB.runCommand({
-        find: 'user',
-        filter: { x: 1 },
-        readConcern: {
-            afterOpTime: { ts: twoSecTS, t: term }
-        },
-        maxTimeMS: 1000
-    }));
+    var runTimeoutTest = function() {
+        var timeoutResult = assert.commandFailedWithCode(
+            testDB.runCommand({
+                find: 'user',
+                filter: { x: 1 },
+                readConcern: {
+                    afterOpTime: { ts: twoSecTS, t: term }
+                },
+                maxTimeMS: 5000,
+            }),
+            ErrorCodes.ExceededTimeLimit
+        );
+        assert.gt(timeoutResult.waitedMS, 500);
+    };
 
-    assert.eq(50, res.code, tojson(res)); // ErrorCodes::ExceededTimeLimit
-    assert.gt(res.waitedMS, 500);
-    assert.lt(res.waitedMS, 2500);
+    var countLogMessages = function(msg) {
+        var total = 0;
+        var logMessages = assert.commandWorked(testDB.adminCommand({getLog: 'global'})).log;
+        for (var i = 0; i < logMessages.length; i++) {
+            if (logMessages[i].indexOf(msg) != -1) {
+                total++;
+            }
+        }
+        return total;
+    };
+
+    var checkLog = function(msg, expectedCount) {
+        var count;
+        assert.soon(function() {
+            count = countLogMessages(msg);
+            return expectedCount == count;
+            },
+            'Expected ' + expectedCount + ', but instead saw ' + count +
+                ' log entries containing the following message: ' + msg,
+            60000,
+            300);
+    };
+
+    // Run the time out test 3 times with replication debug log level increased to 2
+    // for first and last run. The time out message should be logged twice.
+    testDB.setLogLevel(2, 'command');
+    runTimeoutTest();
+    testDB.setLogLevel(0, 'command');
+
+    var msg = 'Command on database ' + testDB.getName() +
+        ' timed out waiting for read concern to be satisfied. Command:';
+    checkLog(msg, 1);
+
+    // Read concern timed out message should not be logged.
+    runTimeoutTest();
+
+    testDB.setLogLevel(2, 'command');
+    runTimeoutTest();
+    testDB.setLogLevel(0, 'command');
+
+    checkLog(msg, 2);
 
     // Test read on future afterOpTime that will eventually occur.
     var insertFunc = startParallelShell(
         "sleep(2100); db.user.insert({ y: 1 }, { writeConcern: { w: 2 }});",
         primaryConn.port);
 
-    res = assert.commandWorked(testDB.runCommand({
+    var res = assert.commandWorked(testDB.runCommand({
         find: 'user',
         filter: { x: 1 },
         readConcern: {

jstests/sharding/replset_config/lagged_config_secondary.js

@@ -30,6 +30,23 @@ var exception = assert.throws(function() {
 
 assert.eq(ErrorCodes.ExceededTimeLimit, exception.code);
 
+var msg = 'Command on database config timed out waiting for read concern to be satisfied.';
+assert.soon(
+    function() {
+        var logMessages =
+            assert.commandWorked(delayedConfigSecondary.adminCommand({getLog: 'global'})).log;
+        for (var i = 0; i < logMessages.length; i++) {
+            if (logMessages[i].indexOf(msg) != -1) {
+                return true;
+            }
+        }
+        return false;
+    },
+    'Did not see any log entries containing the following message: ' + msg,
+    60000,
+    300
+);
+
 st.stop();
 
 }());

jstests/sharding/replset_config/read_after_optime.js

@@ -0,0 +1,58 @@
+// Test read after opTime functionality with maxTimeMS on config servers (CSRS only)`.
+
+(function() {
+    'use strict';
+
+    var shardingTest = new ShardingTest({shards: 0});
+    assert(shardingTest.configRS, 'this test requires config servers to run in CSRS mode');
+
+    var configReplSetTest = shardingTest.configRS;
+    var primaryConn = configReplSetTest.getPrimary();
+
+    var lastOp = configReplSetTest.awaitLastOpCommitted();
+    assert(lastOp, 'invalid op returned from ReplSetTest.awaitLastOpCommitted()');
+
+    var config = configReplSetTest.getConfigFromPrimary();
+    var term = -1;
+    if (config.protocolVersion === 1) {
+        term = lastOp.t;
+    }
+
+    var runFindCommand = function(ts) {
+        return primaryConn.getDB('local').runCommand({
+            find: 'oplog.rs',
+            readConcern: {
+                afterOpTime: {
+                    ts: ts,
+                    t: term,
+                },
+            },
+            maxTimeMS: 5000,
+        });
+    };
+
+    assert.commandWorked(runFindCommand(lastOp.ts));
+
+    var timeoutResult = assert.commandFailedWithCode(
+        runFindCommand(new Timestamp(lastOp.ts.getTime() + 2, 0)),
+        ErrorCodes.ExceededTimeLimit
+    );
+    assert.gt(timeoutResult.waitedMS, 500);
+
+    var msg = 'Command on database local timed out waiting for read concern to be satisfied.';
+    assert.soon(
+        function() {
+            var logMessages =
+                assert.commandWorked(primaryConn.adminCommand({getLog: 'global'})).log;
+            for (var i = 0; i < logMessages.length; i++) {
+                if (logMessages[i].indexOf(msg) != -1) {
+                    return true;
+                }
+            }
+            return false;
+        },
+        'Did not see any log entries containing the following message: ' + msg,
+        60000,
+        300
+    );
+})();

src/mongo/db/dbcommands.cpp

@@ -1402,6 +1402,13 @@ bool Command::run(OperationContext* txn,
                 auto readConcernResult = replCoord->waitUntilOpTime(txn, readConcernArgs);
                 readConcernResult.appendInfo(&inPlaceReplyBob);
                 if (!readConcernResult.getStatus().isOK()) {
+                    if (ErrorCodes::ExceededTimeLimit == readConcernResult.getStatus()) {
+                        const int debugLevel = serverGlobalParams.configsvr ? 0 : 2;
+                        LOG(debugLevel)
+                            << "Command on database " << request.getDatabase()
+                            << " timed out waiting for read concern to be satisfied. Command: "
+                            << getRedactedCopyForLogging(request.getCommandArgs());
+                    }
                     auto result =
                         appendCommandStatus(inPlaceReplyBob, readConcernResult.getStatus());
                     inPlaceReplyBob.doneFast();

src/mongo/shell/replsettest.js

@@ -588,6 +588,7 @@ var ReplSetTest = function(opts) {
     /**
      * Waits for the last oplog entry on the primary to be visible in the committed snapshop view
      * of the oplog on *all* secondaries.
+     * Returns last oplog entry.
      */
     this.awaitLastOpCommitted = function() {
         var rst = this;
@@ -614,6 +615,8 @@ var ReplSetTest = function(opts) {
 
             return true;
         }, "Op with OpTime " + tojson(masterOpTime) + " failed to be committed on all secondaries");
+
+        return masterOpTime;
     };
 
     this.awaitReplication = function(timeout) {