Last active
September 9, 2020 20:42
-
-
Save EshaMaharishi/f942a8062bed12a240feba29c828398b to your computer and use it in GitHub Desktop.
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
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