Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-35156

secondary reads return cluster time as the operation time

    XMLWordPrintable

Details

    • Bug
    • Status: Closed
    • Major - P3
    • Resolution: Duplicate
    • 4.0.0
    • None
    • Sharding
    • ALL
    • Hide

      python buildscripts/resmoke.py --suites=no_server repro_server35156.js --storageEngine=wiredTiger
      

      repro_server35156.js

      (function() {
          "use strict";
       
          const rst = new ReplSetTest({nodes: 1, nodeOptions: {setParameter: {writePeriodicNoops: 0}}});
          rst.startSet();
          rst.initiate();
       
          const primary = rst.getPrimary();
          const session = new Mongo(rst.getURL()).startSession();
          const db = session.getDatabase("test");
       
          function logClusterTime(prefix, res) {
              jsTest.log(
                  prefix + ": " +
                  tojson({operationTime: res.operationTime, clusterTime: res.$clusterTime.clusterTime}));
          }
       
          let res = assert.commandWorked(db.runCommand({insert: "mycoll", documents: [{_id: 0}]}));
          logClusterTime("After doing insert", res);
          assert.eq(1, res.n, "insert should have succeeded");
       
          res = assert.commandWorked(db.runCommand({insert: "mycoll", documents: [{_id: 0}]}));
          logClusterTime("After triggering duplicate key error", res);
          assert(res.hasOwnProperty("writeErrors"), "insert should have failed");
          assert.eq(1, res.writeErrors.length, "insert should have failed");
          assert.eq(ErrorCodes.DuplicateKey,
                    res.writeErrors[0].code,
                    "insert should have failed due to duplicate key error");
       
          res = db.runCommand({find: "mycoll", $readPreference: {mode: "secondary"}});
          logClusterTime("After running a read command", res);
       
          // This "find" command hangs because the server returned a clusterTime for which there is no
          // corresponding entry in the oplog. This means we must wait until some other client (e.g. the
          // periodic no-op writer) comes in and writes an entry to the oplog.
          assert.commandWorked(db.runCommand({find: "mycoll", maxTimeMS: 10 * 1000}));
       
          session.endSession();
          rst.stopSet();
      })();
      

      Output

      [js_test:repro_server31887] 2017-11-09T01:30:06.643-0500 ----
      [js_test:repro_server31887] 2017-11-09T01:30:06.643-0500 After doing insert: {
      [js_test:repro_server31887] 2017-11-09T01:30:06.643-0500 	"operationTime" : Timestamp(1510209006, 7),
      [js_test:repro_server31887] 2017-11-09T01:30:06.643-0500 	"clusterTime" : Timestamp(1510209006, 7)
      [js_test:repro_server31887] 2017-11-09T01:30:06.644-0500 }
      [js_test:repro_server31887] 2017-11-09T01:30:06.644-0500 ----
      ...
      [js_test:repro_server31887] 2017-11-09T01:30:06.644-0500 ----
      [js_test:repro_server31887] 2017-11-09T01:30:06.645-0500 After triggering duplicate key error: {
      [js_test:repro_server31887] 2017-11-09T01:30:06.645-0500 	"operationTime" : Timestamp(1510209006, 7),
      [js_test:repro_server31887] 2017-11-09T01:30:06.645-0500 	"clusterTime" : Timestamp(1510209006, 8)
      [js_test:repro_server31887] 2017-11-09T01:30:06.645-0500 }
      [js_test:repro_server31887] 2017-11-09T01:30:06.645-0500 ----
      ...
      [js_test:repro_server31887] 2017-11-09T01:30:06.646-0500 ----
      [js_test:repro_server31887] 2017-11-09T01:30:06.646-0500 After running a read command: {
      [js_test:repro_server31887] 2017-11-09T01:30:06.647-0500 	"operationTime" : Timestamp(1510209006, 8),
      [js_test:repro_server31887] 2017-11-09T01:30:06.647-0500 	"clusterTime" : Timestamp(1510209006, 8)
      [js_test:repro_server31887] 2017-11-09T01:30:06.647-0500 }
      [js_test:repro_server31887] 2017-11-09T01:30:06.647-0500 ----
      ...
      [js_test:repro_server31887] 2017-11-09T01:30:16.659-0500 2017-11-09T01:30:16.655-0500 E QUERY    [thread1] Error: command failed: {
      [js_test:repro_server31887] 2017-11-09T01:30:16.659-0500 	"ok" : 0,
      [js_test:repro_server31887] 2017-11-09T01:30:16.659-0500 	"errmsg" : "operation exceeded time limit",
      [js_test:repro_server31887] 2017-11-09T01:30:16.659-0500 	"code" : 50,
      [js_test:repro_server31887] 2017-11-09T01:30:16.659-0500 	"codeName" : "ExceededTimeLimit",
      [js_test:repro_server31887] 2017-11-09T01:30:16.660-0500 	"$clusterTime" : {
      [js_test:repro_server31887] 2017-11-09T01:30:16.660-0500 		"clusterTime" : Timestamp(1510209006, 8),
      [js_test:repro_server31887] 2017-11-09T01:30:16.660-0500 		"signature" : {
      [js_test:repro_server31887] 2017-11-09T01:30:16.660-0500 			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
      [js_test:repro_server31887] 2017-11-09T01:30:16.660-0500 			"keyId" : NumberLong(0)
      [js_test:repro_server31887] 2017-11-09T01:30:16.660-0500 		}
      [js_test:repro_server31887] 2017-11-09T01:30:16.661-0500 	}
      [js_test:repro_server31887] 2017-11-09T01:30:16.661-0500 } : undefined :
      [js_test:repro_server31887] 2017-11-09T01:30:16.661-0500 _getErrorWithCode@src/mongo/shell/utils.js:25:13
      [js_test:repro_server35156] 2017-11-09T01:30:16.661-0500 doassert@src/mongo/shell/assert.js:16:14
      [js_test:repro_server35156] 2017-11-09T01:30:16.661-0500 assert.commandWorked@src/mongo/shell/assert.js:403:5
      [js_test:repro_server35156] 2017-11-09T01:30:16.661-0500 @repro_server31887.js:36:1
      [js_test:repro_server35156] 2017-11-09T01:30:16.662-0500 @repro_server31887.js:1:2
      [js_test:repro_server35156] 2017-11-09T01:30:16.662-0500 failed to load: repro_server31887.js
      

      Show
      python buildscripts/resmoke.py --suites=no_server repro_server35156.js --storageEngine=wiredTiger repro_server35156.js ( function () { "use strict" ;   const rst = new ReplSetTest({nodes: 1, nodeOptions: {setParameter: {writePeriodicNoops: 0}}}); rst.startSet(); rst.initiate();   const primary = rst.getPrimary(); const session = new Mongo(rst.getURL()).startSession(); const db = session.getDatabase( "test" );   function logClusterTime(prefix, res) { jsTest.log( prefix + ": " + tojson({operationTime: res.operationTime, clusterTime: res.$clusterTime.clusterTime})); }   let res = assert.commandWorked(db.runCommand({insert: "mycoll" , documents: [{_id: 0}]})); logClusterTime( "After doing insert" , res); assert.eq(1, res.n, "insert should have succeeded" );   res = assert.commandWorked(db.runCommand({insert: "mycoll" , documents: [{_id: 0}]})); logClusterTime( "After triggering duplicate key error" , res); assert(res.hasOwnProperty( "writeErrors" ), "insert should have failed" ); assert.eq(1, res.writeErrors.length, "insert should have failed" ); assert.eq(ErrorCodes.DuplicateKey, res.writeErrors[0].code, "insert should have failed due to duplicate key error" );   res = db.runCommand({find: "mycoll" , $readPreference: {mode: "secondary" }}); logClusterTime( "After running a read command" , res);   // This "find" command hangs because the server returned a clusterTime for which there is no // corresponding entry in the oplog. This means we must wait until some other client (e.g. the // periodic no-op writer) comes in and writes an entry to the oplog. assert.commandWorked(db.runCommand({find: "mycoll" , maxTimeMS: 10 * 1000}));   session.endSession(); rst.stopSet(); })(); Output [js_test:repro_server31887] 2017-11-09T01:30:06.643-0500 ---- [js_test:repro_server31887] 2017-11-09T01:30:06.643-0500 After doing insert: { [js_test:repro_server31887] 2017-11-09T01:30:06.643-0500 "operationTime" : Timestamp(1510209006, 7), [js_test:repro_server31887] 2017-11-09T01:30:06.643-0500 "clusterTime" : Timestamp(1510209006, 7) [js_test:repro_server31887] 2017-11-09T01:30:06.644-0500 } [js_test:repro_server31887] 2017-11-09T01:30:06.644-0500 ---- ... [js_test:repro_server31887] 2017-11-09T01:30:06.644-0500 ---- [js_test:repro_server31887] 2017-11-09T01:30:06.645-0500 After triggering duplicate key error: { [js_test:repro_server31887] 2017-11-09T01:30:06.645-0500 "operationTime" : Timestamp(1510209006, 7), [js_test:repro_server31887] 2017-11-09T01:30:06.645-0500 "clusterTime" : Timestamp(1510209006, 8) [js_test:repro_server31887] 2017-11-09T01:30:06.645-0500 } [js_test:repro_server31887] 2017-11-09T01:30:06.645-0500 ---- ... [js_test:repro_server31887] 2017-11-09T01:30:06.646-0500 ---- [js_test:repro_server31887] 2017-11-09T01:30:06.646-0500 After running a read command: { [js_test:repro_server31887] 2017-11-09T01:30:06.647-0500 "operationTime" : Timestamp(1510209006, 8), [js_test:repro_server31887] 2017-11-09T01:30:06.647-0500 "clusterTime" : Timestamp(1510209006, 8) [js_test:repro_server31887] 2017-11-09T01:30:06.647-0500 } [js_test:repro_server31887] 2017-11-09T01:30:06.647-0500 ---- ... [js_test:repro_server31887] 2017-11-09T01:30:16.659-0500 2017-11-09T01:30:16.655-0500 E QUERY [thread1] Error: command failed: { [js_test:repro_server31887] 2017-11-09T01:30:16.659-0500 "ok" : 0, [js_test:repro_server31887] 2017-11-09T01:30:16.659-0500 "errmsg" : "operation exceeded time limit", [js_test:repro_server31887] 2017-11-09T01:30:16.659-0500 "code" : 50, [js_test:repro_server31887] 2017-11-09T01:30:16.659-0500 "codeName" : "ExceededTimeLimit", [js_test:repro_server31887] 2017-11-09T01:30:16.660-0500 "$clusterTime" : { [js_test:repro_server31887] 2017-11-09T01:30:16.660-0500 "clusterTime" : Timestamp(1510209006, 8), [js_test:repro_server31887] 2017-11-09T01:30:16.660-0500 "signature" : { [js_test:repro_server31887] 2017-11-09T01:30:16.660-0500 "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="), [js_test:repro_server31887] 2017-11-09T01:30:16.660-0500 "keyId" : NumberLong(0) [js_test:repro_server31887] 2017-11-09T01:30:16.660-0500 } [js_test:repro_server31887] 2017-11-09T01:30:16.661-0500 } [js_test:repro_server31887] 2017-11-09T01:30:16.661-0500 } : undefined : [js_test:repro_server31887] 2017-11-09T01:30:16.661-0500 _getErrorWithCode@src/mongo/shell/utils.js:25:13 [js_test:repro_server35156] 2017-11-09T01:30:16.661-0500 doassert@src/mongo/shell/assert.js:16:14 [js_test:repro_server35156] 2017-11-09T01:30:16.661-0500 assert.commandWorked@src/mongo/shell/assert.js:403:5 [js_test:repro_server35156] 2017-11-09T01:30:16.661-0500 @repro_server31887.js:36:1 [js_test:repro_server35156] 2017-11-09T01:30:16.662-0500 @repro_server31887.js:1:2 [js_test:repro_server35156] 2017-11-09T01:30:16.662-0500 failed to load: repro_server31887.js

    Description

      As SERVER-31887 pointed out, a failed command advances the cluster time but not the operation time. If we perform a secondary read right after the failed command, the operation time being returned is actually the cluster time. It's problematic because there is no oplog entry at the operation time being returned.

      Attachments

        Issue Links

          Activity

            People

              misha.tyulenev@mongodb.com Misha Tyulenev
              xiangyu.yao@mongodb.com Xiangyu Yao (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              9 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: