Skip to content

Instantly share code, notes, and snippets.

@EshaMaharishi
Last active September 9, 2020 20:42
Show Gist options
  • Save EshaMaharishi/f942a8062bed12a240feba29c828398b to your computer and use it in GitHub Desktop.
Save EshaMaharishi/f942a8062bed12a240feba29c828398b to your computer and use it in GitHub Desktop.
Script:
```
const st = new ShardingTest({shards: {rs0: {nodes: 2}}, config: 1, other: { mongosOptions: {verbose: 3}}});
for (let i = 0; i < 1000; i++) {
st.s.getDB("test").foo.insert({_id: i});
}
let cursor = st.s.getDB("test").foo.find().readPref('secondary');
print("xxx: " + tojson(cursor.next()));
print("xxx: " + tojson(cursor.next()));
assert.commandWorked(st.rs0.getSecondary().adminCommand({replSetStepUp: 1}));
while(cursor.hasNext()) {
print("xxx: " + tojson(cursor.next()));
}
st.stop();
```
Output:
```
// d15520 is the original primary
[js_test:repro] 2020-09-09T20:34:44.225+0000 d15520| {"t":{"$date":"2020-09-09T20:34:44.224+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"PRIMARY","oldState":"SECONDARY"}}
// Cursor gets established on d15521
[js_test:repro] 2020-09-09T20:34:49.827+0000 s15523| {"t":{"$date":"2020-09-09T20:34:49.810+00:00"},"s":"D3", "c":"QUERY", "id":4625502, "ctx":"conn6","msg":"Establishing cursors on remotes","attr":{"opId":1030,"numRemotes":1,"opKey":{"uuid":{"$uuid":"f009bcb6-eaf0-4828-a447-69f19ce6febf"}}}}
[js_test:repro] 2020-09-09T20:34:49.827+0000 s15523| {"t":{"$date":"2020-09-09T20:34:49.810+00:00"},"s":"D3", "c":"EXECUTOR", "id":22607, "ctx":"conn6","msg":"Scheduling remote command request","attr":{"request":"RemoteCommand 1042 -- target:[ip-10-122-9-244:15521] db:test cmd:{ find: \"foo\", readConcern: { prove
[js_test:repro] 2020-09-09T20:34:49.827+0000 s15523| {"t":{"$date":"2020-09-09T20:34:49.811+00:00"},"s":"D2", "c":"ASIO", "id":22597, "ctx":"conn6","msg":"Request finished with response","attr":{"requestId":1042,"isOK":true,"response":"{ cursor: { firstBatch: [ { _id: 0.0 }, { _id: 1.0 }, { _id: 2.0 }, { _id: 3.0 }, { _id: 4.0 }, { _id: 5.0 }, { _id: 6.0 }, { _id: 7.0 }, { _id: 8.0 }, { _id: 9.0 }, { _id: 10.0 }, { _id: 11.0 }, { _id: 12.0 }, { _id: 13.0 }, { _id: 14.0 }, { _id: 15.0 }, { _id: 16.0 }, { _id: 17.0 }, { _id: 18.0 }, { _id: 19.0 }, { _id: 20.0 }, { _id: 21.0 }, { _id: 22.0 }, { _id: 23.0 }, { _id: 24.0 }, { _id: 25.0 }, { _id: 26.0 }, { _id: 27.0 }, { _id: 28.0 }, { _id: 29.0 }, { _id: 30.0 }, { _id: 31.0 }, { _id: 32.0 }, { _id: 33.0 }, { _id: 34.0 }, { _id: 35.0 }, { _id: 36.0 }, { _id: 37.0 }, { _id: 38.0 }, { _id: 39.0 }, { _id: 40.0 }, { _id: 41.0 }, { _id: 42.0 }, { _id: 43.0 }, { _id: 44.0 }, { _id: 45.0 }, { _id: 46.0 }, { _id: 47.0 }, { _id: 48.0 }, { _id: 49.0 }, { _id: 50.0 }, { _id: 51.0 }, { _id: 52.0 }, { _id: 53.0 }, { _id: 54.0 }, { _id: 55.0 }, { _id: 56.0 }, { _id: 57.0 }, { _id: 58.0 }, { _id: 59.0 }, { _id: 60.0 }, { _id: 61.0 }, { _id: 62.0 }, { _id: 63.0 }, { _id: 64.0 }, { _id: 65.0 }, { _id: 66.0 }, { _id: 67.0 }, { _id: 68.0 }, { _id: 69.0 }, { _id: 70.0 }, { _id: 71.0 }, { _id: 72.0 }, { _id: 73.0 }, { _id: 74.0 }, { _id: 75.0 }, { _id: 76.0 }, { _id: 77.0 }, { _id: 78.0 }, { _id: 79.0 }, { _id: 80.0 }, { _id: 81.0 }, { _id: 82.0 }, { _id: 83.0 }, { _id: 84.0 }, { _id: 85.0 }, { _id: 86.0 }, { _id: 87.0 }, { _id: 88.0 }, { _id: 89.0 }, { _id: 90.0 }, { _id: 91.0 }, { _id: 92.0 }, { _id: 93.0 }, { _id: 94.0 }, { _id: 95.0 }, { _id: 96.0 }, { _id: 97.0 }, { _id: 98.0 }, { _id: 99.0 }, { _id: 100.0 } ], id: 5107483629912793847, ns: \"test.foo\" }, ok: 1.0, $gleStats: { lastOpTime: Timestamp(0, 0), electionId: ObjectId('000000000000000000000000') }, lastCommittedOpTime: Timestamp(1599683689, 291), $configServerState: { opTime: { ts: Timestamp(1599683687, 8), t: 1 } }, $clusterTime: { clusterTime: Timestamp(1599683689, 327), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $configTime: Timestamp(1599683687, 40), $topologyTime: Timestamp(1599683687, 10), operationTime: Timestamp(1599683689, 326) }"}}
20306:[js_test:repro] 2020-09-09T20:34:49.828+0000 s15523| {"t":{"$date":"2020-09-09T20:34:49.811+00:00"},"s":"D3", "c":"EXECUTOR", "id":22608, "ctx":"conn6","msg":"Received remote response","attr":{"response":"RemoteOnAnyResponse -- cmd: { cursor: { firstBatch: [ { _id: 0.0 }, { _id: 1.0 }, { _id: 2.0 }, { _id: 3.0 }, { _id: 4.0 }, { _id: 5.0 }, { _id: 6.0 }, { _id: 7.0 }, { _id: 8.0 }, { _id: 9.0 }, { _id: 10.0 }, { _id: 11.0 }, { _id: 12.0 }, { _id: 13.0 }, { _id: 14.0 }, { _id: 15.0 }, { _id: 16.0 }, { _id: 17.0 }, { _id: 18.0 }, { _id: 19.0 }, { _id: 20.0 }, { _id: 21.0 }, { _id: 22.0 }, { _id: 23.0 }, { _id: 24.0 }, { _id: 25.0 }, { _id: 26.0 }, { _id: 27.0 }, { _id: 28.0 }, { _id: 29.0 }, { _id: 30.0 }, { _id: 31.0 }, { _id: 32.0 }, { _id: 33.0 }, { _id: 34.0 }, { _id: 35.0 }, { _id: 36.0 }, { _id: 37.0 }, { _id: 38.0 }, { _id: 39.0 }, { _id: 40.0 }, { _id: 41.0 }, { _id: 42.0 }, { _id: 43.0 }, { _id: 44.0 }, { _id: 45.0 }, { _id: 46.0 }, { _id: 47.0 }, { _id: 48.0 }, { _id: 49.0 }, { _id: 50.0 }, { _id: 51.0 }, { _id: 52.0 }, { _id: 53.0 }, { _id: 54.0 }, { _id: 55.0 }, { _id: 56.0 }, { _id: 57.0 }, { _id: 58.0 }, { _id: 59.0 }, { _id: 60.0 }, { _id: 61.0 }, { _id: 62.0 }, { _id: 63.0 }, { _id: 64.0 }, { _id: 65.0 }, { _id: 66.0 }, { _id: 67.0 }, { _id: 68.0 }, { _id: 69.0 }, { _id: 70.0 }, { _id: 71.0 }, { _id: 72.0 }, { _id: 73.0 }, { _id: 74.0 }, { _id: 75.0 }, { _id: 76.0 }, { _id: 77.0 }, { _id: 78.0 }, { _id: 79.0 }, { _id: 80.0 }, { _id: 81.0 }, { _id: 82.0 }, { _id: 83.0 }, { _id: 84.0 }, { _id: 85.0 }, { _id: 86.0 }, { _id: 87.0 }, { _id: 88.0 }, { _id: 89.0 }, { _id: 90.0 }, { _id: 91.0 }, { _id: 92.0 }, { _id: 93.0 }, { _id: 94.0 }, { _id: 95.0 }, { _id: 96.0 }, { _id: 97.0 }, { _id: 98.0 }, { _id: 99.0 }, { _id: 100.0 } ], id: 5107483629912793847, ns: \"test.foo\" }, ok: 1.0, $gleStats: { lastOpTime: Timestamp(0, 0), electionId: ObjectId('000000000000000000000000') }, lastCommittedOpTime: Timestamp(1599683689, 291), $configServerState: { opTime: { ts: Timestamp(1599683687, 8), t: 1 } }, $clusterTime: { clusterTime: Timestamp(1599683689, 327), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $configTime: Timestamp(1599683687, 40), $topologyTime: Timestamp(1599683687, 10), operationTime: Timestamp(1599683689, 326) } target: ip-10-122-9-244:15521 status: OK elapsedMicros: 583 s moreToCome: false"}}
// The shell had attached $readPreference on the find to mongos
[js_test:repro] 2020-09-09T20:34:49.828+0000 s15523| {"t":{"$date":"2020-09-09T20:34:49.811+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn6","msg":"Slow query","attr":{"type":"command","ns":"test.foo","appName":"MongoDB Shell","command":{"find":"foo","filter":{},"lsid":{"id":{"$uuid":"aabc32e4-8836-4ad4-b0e5-3bc95d179c86"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1599683689,"i":327}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$readPreference":{"mode":"secondary"},"$db":"test"},"nShards":1,"cursorid":9118936375406538520,"numYields":0,"nreturned":101,"reslen":2435,"protocol":"op_msg","durationMillis":1}}
// Step d15521 up to primary
[js_test:repro] 2020-09-09T20:34:49.829+0000 d15520| {"t":{"$date":"2020-09-09T20:34:49.820+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"SECONDARY","oldState":"PRIMARY"}}
[js_test:repro] 2020-09-09T20:34:49.831+0000 d15521| {"t":{"$date":"2020-09-09T20:34:49.822+00:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"ReplCoord-0","msg":"Replica set state transition","attr":{"newState":"PRIMARY","oldState":"SECONDARY"}}
// Mongos sends getMore to d15521 without readPref and it succeeds
[js_test:repro] 2020-09-09T20:34:49.849+0000 s15523| {"t":{"$date":"2020-09-09T20:34:49.836+00:00"},"s":"D3", "c":"EXECUTOR", "id":22607, "ctx":"conn6","msg":"Scheduling remote command request","attr":{"request":"RemoteCommand 1044 -- target:[ip-10-122-9-244:15521] db:test cmd:{ getMore: 5107483629912793847, collection: \"foo\", lsid: { id: UUID(\"aabc32e4-8836-4ad4-b0e5-3bc95d179c86\"), uid: BinData(0, E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855) } }"}}
[js_test:repro] 2020-09-09T20:34:49.849+0000 d15521| {"t":{"$date":"2020-09-09T20:34:49.836+00:00"},"s":"I", "c":"COMMAND", "id":21965, "ctx":"conn26","msg":"About to run the command","attr":{"db":"test","commandArgs":{"getMore":5107483629912793847,"collection":"foo","lsid":{"id":{"$uuid":"aabc32e4-8836-4ad4-b0e5-3bc95d179c86"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1599683689,"i":329}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$client":{"application":{"name":"MongoDB Shell"},"driver":{"name":"MongoDB Internal Client","version":"4.5.0-3060-g58fd67f"},"os":{"type":"Linux","name":"Ubuntu","architecture":"x86_64","version":"18.04"},"mongos":{"host":"ip-10-122-9-244:15523","client":"127.0.0.1:34928","version":"4.5.0-3060-g58fd67f"}},"$configServerState":{"opTime":{"ts":{"$timestamp":{"t":1599683687,"i":40}},"t":1}},"$db":"test"}}}
[js_test:repro] 2020-09-09T20:34:49.849+0000 s15523| {"t":{"$date":"2020-09-09T20:34:49.837+00:00"},"s":"D2", "c":"ASIO", "id":4646302, "ctx":"TaskExecutorPool-0","msg":"Finished request","attr":{"requestId":1044,"status":{"code":0,"codeName":"OK"}}}
// The shell had attached $readPreference on the getMore to mongos
[js_test:repro] 2020-09-09T20:34:49.851+0000 s15523| {"t":{"$date":"2020-09-09T20:34:49.840+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn6","msg":"Slow query","attr":{"type":"command","ns":"test.foo","appName":"MongoDB Shell","command":{"getMore":9118936375406538520,"collection":"foo","lsid":{"id":{"$uuid":"aabc32e4-8836-4ad4-b0e5-3bc95d179c86"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1599683689,"i":327}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test"},"originatingCommand":{"find":"foo","filter":{},"lsid":{"id":{"$uuid":"aabc32e4-8836-4ad4-b0e5-3bc95d179c86"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1599683689,"i":327}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$readPreference":{"mode":"secondary"},"$db":"test"},"nShards":1,"cursorid":9118936375406538520,"cursorExhausted":true,"numYields":0,"nreturned":899,"reslen":20788,"protocol":"op_msg","durationMillis":4}}
```
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment