|
In the test case where we send a series of reads to a primary node P with readPreference='primaryPreferred', we expect the server to respond to the driver immediately with a ShutdownInProgress error. All future reads should be directed to the secondary as P continues with quiesce mode and eventually shuts down.
Observations for this test case:
Reads are directed to Primary node d20020 since we set the readPreference to 'primaryPreferred'.
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:26.721-0400 d20020| {"t":{"$date":"2020-05-26T19:51:26.721-04:00"},"s":"D2", "c":"COMMAND", "id":21965, "ctx":"conn14","msg":"About to run the command","attr":{"db":"test","commandArgs":{"find":"state","filter":{},"limit":1,"singleBatch":true,"lsid":{"id":{"$uuid":"3ff22c32-375d-4bbf-b4e1-fd2199e912b4"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590537086,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test","$readPreference":{"mode":"primaryPreferred"}}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:26.722-0400 d20020| {"t":{"$date":"2020-05-26T19:51:26.721-04:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn14","msg":"Slow query","attr":{"type":"command","ns":"test.state","command":{"find":"state","filter":{},"limit":1,"singleBatch":true,"lsid":{"id":{"$uuid":"3ff22c32-375d-4bbf-b4e1-fd2199e912b4"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590537086,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test","$readPreference":{"mode":"primaryPreferred"}},"planSummary":"COLLSCAN","keysExamined":0,"docsExamined":1,"cursorExhausted":true,"numYields":0,"nreturned":1,"reslen":272,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":0}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:26.973-0400 d20020| {"t":{"$date":"2020-05-26T19:51:26.973-04:00"},"s":"D2", "c":"COMMAND", "id":21965, "ctx":"conn14","msg":"About to run the command","attr":{"db":"test","commandArgs":{"find":"state","filter":{},"limit":1,"singleBatch":true,"lsid":{"id":{"$uuid":"3ff22c32-375d-4bbf-b4e1-fd2199e912b4"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590537086,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test","$readPreference":{"mode":"primaryPreferred"}}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:26.974-0400 d20020| {"t":{"$date":"2020-05-26T19:51:26.974-04:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn14","msg":"Slow query","attr":{"type":"command","ns":"test.state","command":{"find":"state","filter":{},"limit":1,"singleBatch":true,"lsid":{"id":{"$uuid":"3ff22c32-375d-4bbf-b4e1-fd2199e912b4"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590537086,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test","$readPreference":{"mode":"primaryPreferred"}},"planSummary":"COLLSCAN","keysExamined":0,"docsExamined":1,"cursorExhausted":true,"numYields":0,"nreturned":1,"reslen":272,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":0}}
|
...
|
Node d20020 receives a shutdown command, and proceeds to stepdown and enter quiesce mode:
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.095-0400 ReplSetTest stop *** Shutting down mongod in port 20020, wait for process termination: true ***
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.095-0400 {"t":{"$date":"2020-05-26T23:51:27.095Z"},"s":"I", "c":"-", "id":22820, "ctx":"js","msg":"shell: stopping mongo program, waitpid={getWaitPid_a}","attr":{"getWaitPid_a":true}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.096-0400 {"t":{"$date":"2020-05-26T23:51:27.095Z"},"s":"I", "c":"-", "id":22819, "ctx":"js","msg":"waiting for process {pid} to terminate.","attr":{"pid":"32048"}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.096-0400 d20020| {"t":{"$date":"2020-05-26T19:51:27.095-04:00"},"s":"I", "c":"CONTROL", "id":23377, "ctx":"SignalHandler","msg":"got signal {sig} ({strsignal_sig})","attr":{"sig":15,"strsignal_sig":"Terminated"}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.096-0400 d20020| {"t":{"$date":"2020-05-26T19:51:27.095-04:00"},"s":"I", "c":"CONTROL", "id":23378, "ctx":"SignalHandler","msg":"kill from pid:{si_si_pid} uid:{si_si_uid}","attr":{"si_si_pid":32041,"si_si_uid":1000}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.096-0400 d20020| {"t":{"$date":"2020-05-26T19:51:27.095-04:00"},"s":"I", "c":"CONTROL", "id":23381, "ctx":"SignalHandler","msg":"will terminate after current cmd ends"}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.096-0400 d20020| {"t":{"$date":"2020-05-26T19:51:27.096-04:00"},"s":"I", "c":"REPL", "id":21343, "ctx":"RstlKillOpThread","msg":"Starting to kill user operations"}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.096-0400 d20020| {"t":{"$date":"2020-05-26T19:51:27.096-04:00"},"s":"I", "c":"REPL", "id":21344, "ctx":"RstlKillOpThread","msg":"Stopped killing user operations"}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.097-0400 d20020| {"t":{"$date":"2020-05-26T19:51:27.096-04:00"},"s":"I", "c":"REPL", "id":21340, "ctx":"RstlKillOpThread","msg":"State transition ops metrics","attr":{"metrics":{"lastStateTransition":"stepDown","userOpsKilled":0,"userOpsRunning":2}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.097-0400 d20020| {"t":{"$date":"2020-05-26T19:51:27.096-04:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"SignalHandler","msg":"Replica set state transition","attr":{"newState":"SECONDARY","oldState":"PRIMARY"},"tags":[]}
|
...
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.099-0400 d20020| {"t":{"$date":"2020-05-26T19:51:27.097-04:00"},"s":"I", "c":"STORAGE", "id":4695102, "ctx":"SignalHandler","msg":"Entering quiesce mode for shutdown","attr":{"quiesceTimeMillis":4998}}
|
Node d20020 responds to the driver with a ShutdownInProgress isMaster response almost immediately:
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.102-0400 d20020| {"t":{"$date":"2020-05-26T19:51:27.101-04:00"},"s":"D2", "c":"COMMAND", "id":21965, "ctx":"conn16","msg":"About to run the command","attr":{"db":"admin","commandArgs":{"ismaster":1,"client":{"driver":{"name":"PyMongo","version":"3.11.0b1.dev0"},"os":{"type":"Linux","name":"Linux","architecture":"x86_64","version":"4.13.0-46-generic"},"platform":"CPython 3.7.0.final.0"},"$db":"admin"}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.102-0400 d20020| {"t":{"$date":"2020-05-26T19:51:27.101-04:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn16","msg":"client metadata","attr":{"remote":"127.0.0.1:53398","client":"conn16","doc":{"driver":{"name":"PyMongo","version":"3.11.0b1.dev0"},"os":{"type":"Linux","name":"Linux","architecture":"x86_64","version":"4.13.0-46-generic"},"platform":"CPython 3.7.0.final.0"}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.102-0400 d20020| {"t":{"$date":"2020-05-26T19:51:27.101-04:00"},"s":"D1", "c":"COMMAND", "id":21962, "ctx":"conn16","msg":"Assertion while executing command","attr":{"command":"ismaster","db":"admin","commandArgs":{"ismaster":1,"client":{"driver":{"name":"PyMongo","version":"3.11.0b1.dev0"},"os":{"type":"Linux","name":"Linux","architecture":"x86_64","version":"4.13.0-46-generic"},"platform":"CPython 3.7.0.final.0"},"$db":"admin"},"error":"ShutdownInProgress: The server is in quiesce mode and will shut down"}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.102-0400 d20020| {"t":{"$date":"2020-05-26T19:51:27.101-04:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn16","msg":"Slow query","attr":{"type":"command","ns":"admin.$cmd","command":{"ismaster":1,"client":{"driver":{"name":"PyMongo","version":"3.11.0b1.dev0"},"os":{"type":"Linux","name":"Linux","architecture":"x86_64","version":"4.13.0-46-generic"},"platform":"CPython 3.7.0.final.0"},"$db":"admin"},"numYields":0,"ok":0,"errMsg":"The server is in quiesce mode and will shut down","errName":91,"errCode":91,"reslen":344,"locks":{},"protocol":"op_query","durationMillis":0}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.103-0400 d20020| {"t":{"$date":"2020-05-26T19:51:27.101-04:00"},"s":"I", "c":"NETWORK", "id":22944, "ctx":"conn16","msg":"connection ended","attr":{"remote":"127.0.0.1:53398","connectionCount":6}}
|
All future reads are sent to the secondary node d20021:
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.477-0400 d20021| {"t":{"$date":"2020-05-26T19:51:27.477-04:00"},"s":"D2", "c":"COMMAND", "id":21965, "ctx":"conn12","msg":"About to run the command","attr":{"db":"test","commandArgs":{"find":"state","filter":{},"limit":1,"singleBatch":true,"lsid":{"id":{"$uuid":"3ff22c32-375d-4bbf-b4e1-fd2199e912b4"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590537086,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test","$readPreference":{"mode":"primaryPreferred"}}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:51:27.478-0400 d20021| {"t":{"$date":"2020-05-26T19:51:27.477-04:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn12","msg":"Slow query","attr":{"type":"command","ns":"test.state","command":{"find":"state","filter":{},"limit":1,"singleBatch":true,"lsid":{"id":{"$uuid":"3ff22c32-375d-4bbf-b4e1-fd2199e912b4"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590537086,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test","$readPreference":{"mode":"primaryPreferred"}},"planSummary":"COLLSCAN","keysExamined":0,"docsExamined":1,"cursorExhausted":true,"numYields":0,"nreturned":1,"reslen":272,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":0}}
|
...
|
The test completes successfully with driver option retryReads set to false, indicating that all reads completed successfully without the driver ever having to retry.
Example logs: primary_quiesce_mode_streamable_ismaster.txt
|
|
In the test case where the primary node P enters quiesce mode while a read is still in-progress, we expect to see that P will return a ShutdownInProgress error as an isMaster response to the driver. The find should proceed to complete and return to the driver without raising an error even if the driver has already marked S as unknown.
Observations for this test case:
Reads are directed to primary node d20020 since we set the readPreference to 'primaryPreferred':
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.170-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.170-04:00"},"s":"D2", "c":"COMMAND", "id":21965, "ctx":"conn16","msg":"About to run the command","attr":{"db":"test","commandArgs":{"find":"state","filter":{},"limit":1,"singleBatch":true,"lsid":{"id":{"$uuid":"abec9041-4652-4958-b1e7-2a1c896bae44"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590535473,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test","$readPreference":{"mode":"primaryPreferred"}}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.170-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.170-04:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn16","msg":"Slow query","attr":{"type":"command","ns":"test.state","command":{"find":"state","filter":{},"limit":1,"singleBatch":true,"lsid":{"id":{"$uuid":"abec9041-4652-4958-b1e7-2a1c896bae44"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590535473,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test","$readPreference":{"mode":"primaryPreferred"}},"planSummary":"COLLSCAN","keysExamined":0,"docsExamined":1,"cursorExhausted":true,"numYields":0,"nreturned":1,"reslen":272,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1}},"Global":{"acquireCount":{"r":1}},"Database":{"acquireCount":{"r":1}},"Collection":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"protocol":"op_msg","durationMillis":0}}
|
Set a failpoint on the primary node d20020 to hang during a find command. Wait for us to hit this failpoint.:
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.209-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.208-04:00"},"s":"D2", "c":"COMMAND", "id":21965, "ctx":"conn1","msg":"About to run the command","attr":{"db":"admin","commandArgs":{"configureFailPoint":"waitAfterCommandFinishesExecution","mode":"alwaysOn","data":{"ns":"test.state","commands":["find"]},"lsid":{"id":{"$uuid":"9bcf415e-eaa0-489f-8e85-5d2f0e393db7"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590535473,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$readPreference":{"mode":"secondaryPreferred"},"$db":"admin"}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.209-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.209-04:00"},"s":"D2", "c":"COMMAND", "id":21961, "ctx":"conn1","msg":"Admin only command","attr":{"command":"configureFailPoint"}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.209-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.209-04:00"},"s":"W", "c":"CONTROL", "id":23829, "ctx":"conn1","msg":"Set failpoint","attr":{"failPointName":"waitAfterCommandFinishesExecution","failPoint":{"mode":1,"data":{"ns":"test.state","commands":["find"]},"timesEntered":0}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.209-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.209-04:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn1","msg":"Slow query","attr":{"type":"command","ns":"admin.$cmd","appName":"MongoDB Shell","command":{"configureFailPoint":"waitAfterCommandFinishesExecution","mode":"alwaysOn","data":{"ns":"test.state","commands":["find"]},"lsid":{"id":{"$uuid":"9bcf415e-eaa0-489f-8e85-5d2f0e393db7"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590535473,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$readPreference":{"mode":"secondaryPreferred"},"$db":"admin"},"numYields":0,"reslen":174,"locks":{},"protocol":"op_msg","durationMillis":0}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.211-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.210-04:00"},"s":"D2", "c":"COMMAND", "id":21965, "ctx":"conn1","msg":"About to run the command","attr":{"db":"admin","commandArgs":{"waitForFailPoint":"waitAfterCommandFinishesExecution","timesEntered":1.0,"maxTimeMS":300000.0,"lsid":{"id":{"$uuid":"9bcf415e-eaa0-489f-8e85-5d2f0e393db7"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590535473,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$readPreference":{"mode":"secondaryPreferred"},"$db":"admin"}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.211-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.210-04:00"},"s":"D2", "c":"COMMAND", "id":21961, "ctx":"conn1","msg":"Admin only command","attr":{"command":"waitForFailPoint"}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.211-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.211-04:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn1","msg":"Slow query","attr":{"type":"command","ns":"admin.$cmd","appName":"MongoDB Shell","command":{"waitForFailPoint":"waitAfterCommandFinishesExecution","timesEntered":1.0,"maxTimeMS":300000.0,"lsid":{"id":{"$uuid":"9bcf415e-eaa0-489f-8e85-5d2f0e393db7"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590535473,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$readPreference":{"mode":"secondaryPreferred"},"$db":"admin"},"numYields":0,"reslen":163,"locks":{},"protocol":"op_msg","durationMillis":0}}
|
Set a failpoint on the primary node d20020 to hang during quiesce mode:
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.212-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.212-04:00"},"s":"D2", "c":"COMMAND", "id":21965, "ctx":"conn1","msg":"About to run the command","attr":{"db":"admin","commandArgs":{"configureFailPoint":"hangDuringQuiesceMode","mode":"alwaysOn","data":{},"lsid":{"id":{"$uuid":"9bcf415e-eaa0-489f-8e85-5d2f0e393db7"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590535473,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$readPreference":{"mode":"secondaryPreferred"},"$db":"admin"}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.213-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.212-04:00"},"s":"D2", "c":"COMMAND", "id":21961, "ctx":"conn1","msg":"Admin only command","attr":{"command":"configureFailPoint"}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.213-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.212-04:00"},"s":"W", "c":"CONTROL", "id":23829, "ctx":"conn1","msg":"Set failpoint","attr":{"failPointName":"hangDuringQuiesceMode","failPoint":{"mode":1,"data":{},"timesEntered":0}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.213-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.212-04:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn1","msg":"Slow query","attr":{"type":"command","ns":"admin.$cmd","appName":"MongoDB Shell","command":{"configureFailPoint":"hangDuringQuiesceMode","mode":"alwaysOn","data":{},"lsid":{"id":{"$uuid":"9bcf415e-eaa0-489f-8e85-5d2f0e393db7"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590535473,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$readPreference":{"mode":"secondaryPreferred"},"$db":"admin"},"numYields":0,"reslen":174,"locks":{},"protocol":"op_msg","durationMillis":0}}
|
Primary node d20020 receives a shutdown command. It proceeds to stepdown and transition to quiesce mode. The node will hang here due to the failpoint:
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.214-0400 {"t":{"$date":"2020-05-26T23:24:33.214Z"},"s":"I", "c":"-", "id":22820, "ctx":"js","msg":"shell: stopping mongo program, waitpid={getWaitPid_a}","attr":{"getWaitPid_a":false}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.214-0400 {"t":{"$date":"2020-05-26T23:24:33.214Z"},"s":"I", "c":"-", "id":22818, "ctx":"js","msg":"skip waiting for pid {pid} to terminate","attr":{"pid":"31075"}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.214-0400 {"t":{"$date":"2020-05-26T23:24:33.214Z"},"s":"I", "c":"-", "id":22821, "ctx":"js","msg":"shell: stopped mongo program on port {port}","attr":{"port":20020}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.215-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.214-04:00"},"s":"I", "c":"CONTROL", "id":23377, "ctx":"SignalHandler","msg":"got signal {sig} ({strsignal_sig})","attr":{"sig":15,"strsignal_sig":"Terminated"}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.215-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.214-04:00"},"s":"I", "c":"CONTROL", "id":23378, "ctx":"SignalHandler","msg":"kill from pid:{si_si_pid} uid:{si_si_uid}","attr":{"si_si_pid":31068,"si_si_uid":1000}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.215-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.214-04:00"},"s":"I", "c":"CONTROL", "id":23381, "ctx":"SignalHandler","msg":"will terminate after current cmd ends"}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.215-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.214-04:00"},"s":"I", "c":"REPL", "id":21343, "ctx":"RstlKillOpThread","msg":"Starting to kill user operations"}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.215-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.214-04:00"},"s":"I", "c":"REPL", "id":21344, "ctx":"RstlKillOpThread","msg":"Stopped killing user operations"}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.215-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.215-04:00"},"s":"I", "c":"REPL", "id":21340, "ctx":"RstlKillOpThread","msg":"State transition ops metrics","attr":{"metrics":{"lastStateTransition":"stepDown","userOpsKilled":0,"userOpsRunning":2}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.216-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.215-04:00"},"s":"I", "c":"REPL", "id":21358, "ctx":"SignalHandler","msg":"Replica set state transition","attr":{"newState":"SECONDARY","oldState":"PRIMARY"},"tags":[]}
|
...
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.217-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.215-04:00"},"s":"D2", "c":"COMMAND", "id":21965, "ctx":"conn14","msg":"About to run the command","attr":{"db":"admin","commandArgs":{"ismaster":1,"topologyVersion":{"processId":{"$oid":"5ecda528327743f125f915b6"},"counter":9},"maxAwaitTimeMS":1000,"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590535466,"i":1}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"admin","$readPreference":{"mode":"primary"}}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.217-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.216-04:00"},"s":"I", "c":"STORAGE", "id":4695101, "ctx":"SignalHandler","msg":"hangDuringQuiesceMode failpoint enabled"}
|
Primary node d20020 responds to the driver with a ShutdownInProgress isMaster response immediately due to the streamable protocol:
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.219-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.217-04:00"},"s":"D2", "c":"COMMAND", "id":21965, "ctx":"conn17","msg":"About to run the command","attr":{"db":"admin","commandArgs":{"ismaster":1,"client":{"driver":{"name":"PyMongo","version":"3.11.0b1.dev0"},"os":{"type":"Linux","name":"Linux","architecture":"x86_64","version":"4.13.0-46-generic"},"platform":"CPython 3.7.0.final.0"},"$db":"admin"}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.220-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.217-04:00"},"s":"I", "c":"NETWORK", "id":51800, "ctx":"conn17","msg":"client metadata","attr":{"remote":"127.0.0.1:53234","client":"conn17","doc":{"driver":{"name":"PyMongo","version":"3.11.0b1.dev0"},"os":{"type":"Linux","name":"Linux","architecture":"x86_64","version":"4.13.0-46-generic"},"platform":"CPython 3.7.0.final.0"}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:33.220-0400 d20020| {"t":{"$date":"2020-05-26T19:24:33.218-04:00"},"s":"D1", "c":"COMMAND", "id":21962, "ctx":"conn17","msg":"Assertion while executing command","attr":{"command":"ismaster","db":"admin","commandArgs":{"ismaster":1,"client":{"driver":{"name":"PyMongo","version":"3.11.0b1.dev0"},"os":{"type":"Linux","name":"Linux","architecture":"x86_64","version":"4.13.0-46-generic"},"platform":"CPython 3.7.0.final.0"},"$db":"admin"},"error":"ShutdownInProgress: The server is in quiesce mode and will shut down"}}
|
We turn off the failpoint for the find command and return to the driver:
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:34.317-0400 d20020| {"t":{"$date":"2020-05-26T19:24:34.317-04:00"},"s":"D2", "c":"COMMAND", "id":21965, "ctx":"conn1","msg":"About to run the command","attr":{"db":"admin","commandArgs":{"configureFailPoint":"waitAfterCommandFinishesExecution","mode":"off","lsid":{"id":{"$uuid":"9bcf415e-eaa0-489f-8e85-5d2f0e393db7"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590535473,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$readPreference":{"mode":"secondaryPreferred"},"$db":"admin"}}}
|
[js_test:quiesce_mode_streamable_ismaster] 2020-05-26T19:24:34.317-0400 d20020| {"t":{"$date":"2020-05-26T19:24:34.317-04:00"},"s":"D2", "c":"COMMAND", "id":21961, "ctx":"conn1","msg":"Admin only command","attr":{"command":"configureFailPoint"}}
|
The driver does not receive an error from the find command that returns to the driver after the ShutdownInProgress isMaster response. All future reads are directed to the secondary node d20021.
Example logs: primary_quiesce_mode_streamable_ismaster_with_hanging_read.txt
|