no_cursor_found_driver_logs.rb

D, [2018-03-21T15:07:34.711838 #4902] DEBUG -- : MONGODB | localhost:3001 | admin.find | STARTED | {"find"=>"test", "filter"=>{}, "noCursorTimeout"=>true, "batchSize"=>1, "lsid"=>{"id"=><BSON::Binary:0x70210620710180 type=uuid data=0x1e6172db848a4e03...>}, "$readPreference"=>{"mode"=>"secondaryPreferred"}}
D, [2018-03-21T15:07:34.713316 #4902] DEBUG -- : MONGODB | localhost:3001 | admin.find | SUCCEEDED | 0.00137s
sleeping for 10 seconds
D, [2018-03-21T15:07:44.716721 #4902] DEBUG -- : MONGODB | localhost:3001 | admin.getMore | STARTED | {"getMore"=>106113431435, "collection"=>"test", "batchSize"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007fb65e349da8 @seconds=1521659250, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70210620640440 type=generic data=0x0000000000000000...>, "keyId"=>0}}, "lsid"=>{"id"=><BSON::Binary:0x70210620710180 type=uuid data=0x1e6172db848a4e03...>}}
D, [2018-03-21T15:07:44.717658 #4902] DEBUG -- : MONGODB | localhost:3001 | admin.getMore | SUCCEEDED | 0.000831s
sleeping for 700 seconds
D, [2018-03-21T15:19:24.749197 #4902] DEBUG -- : MONGODB | localhost:3001 | admin.getMore | STARTED | {"getMore"=>106113431435, "collection"=>"test", "batchSize"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007fb65f6c1ca0 @seconds=1521659260, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70210630847540 type=generic data=0x0000000000000000...>, "keyId"=>0}}, "lsid"=>{"id"=><BSON::Binary:0x70210620710180 type=uuid data=0x1e6172db848a4e03...>}}
D, [2018-03-21T15:19:24.750109 #4902] DEBUG -- : MONGODB | localhost:3001 | admin.getMore | FAILED | cursor id 106113431435 not found (43) | 0.00087s
Mongo::Error::OperationFailure: cursor id 106113431435 not found (43)
from /Users/emily/Code/driver/mongo-ruby-driver/lib/mongo/operation/result.rb:256:in `validate!'

# TEST READ ON PRIMARY
[1] mongo(main)> client = Mongo::Client.new(["localhost:3000", "localhost:3001", "localhost:3002"], truncate_logs: false)
D, [2018-03-21T17:38:22.168097 #8539] DEBUG -- : MONGODB | Topology type 'unknown' initializing.
D, [2018-03-21T17:38:22.168238 #8539] DEBUG -- : MONGODB | Server localhost:3000 initializing.
D, [2018-03-21T17:38:22.171029 #8539] DEBUG -- : MONGODB | Server description for localhost:3000 changed from 'unknown' to 'secondary'.
D, [2018-03-21T17:38:22.171127 #8539] DEBUG -- : MONGODB | Server localhost:3001 initializing.
D, [2018-03-21T17:38:22.173038 #8539] DEBUG -- : MONGODB | Server description for localhost:3001 changed from 'unknown' to 'secondary'.
D, [2018-03-21T17:38:22.173162 #8539] DEBUG -- : MONGODB | Server localhost:3002 initializing.
D, [2018-03-21T17:38:22.175149 #8539] DEBUG -- : MONGODB | Server description for localhost:3002 changed from 'unknown' to 'primary'.
D, [2018-03-21T17:38:22.175309 #8539] DEBUG -- : MONGODB | Topology type 'unknown' changed to type 'replica set'.
D, [2018-03-21T17:38:22.175622 #8539] DEBUG -- : MONGODB | There was a change in the members of the 'replica set' topology.
=> #<Mongo::Client:0x70317703944720 cluster=localhost:3000, localhost:3001, localhost:3002>
[3] mongo(main)> coll = client[:test]
=> #<Mongo::Collection:0x70317684762020 namespace=admin.test>
[4] mongo(main)> sleep_intervals = [ 10, 700, 1]
=> [10, 700, 1]
[5] mongo(main)> coll.find({}, no_cursor_timeout: true, batch_size: 1).each_with_index do |doc, i|
[5] mongo(main)*   doc  
[5] mongo(main)*   puts "sleeping for #{sleep_intervals[i]} seconds"  
[5] mongo(main)*   sleep(sleep_intervals[i])  
[5] mongo(main)* end  
D, [2018-03-21T17:38:26.548830 #8539] DEBUG -- : MONGODB | localhost:3002 | admin.find | STARTED | {"find"=>"test", "filter"=>{}, "noCursorTimeout"=>true, "batchSize"=>1, "lsid"=>{"id"=><BSON::Binary:0x70317686453080 type=uuid data=0x8d0df8f5543c450e...>}}
D, [2018-03-21T17:38:26.550410 #8539] DEBUG -- : MONGODB | localhost:3002 | admin.find | SUCCEEDED | 0.001454s
sleeping for 10 seconds
D, [2018-03-21T17:38:36.551702 #8539] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | STARTED | {"getMore"=>107065670009, "collection"=>"test", "batchSize"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007fe83b8aaa18 @seconds=1521668298, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70317704041580 type=generic data=0x0000000000000000...>, "keyId"=>0}}, "lsid"=>{"id"=><BSON::Binary:0x70317686453080 type=uuid data=0x8d0df8f5543c450e...>}}
D, [2018-03-21T17:38:36.552633 #8539] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | SUCCEEDED | 0.000824s
sleeping for 700 seconds
D, [2018-03-21T17:50:16.574732 #8539] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | STARTED | {"getMore"=>107065670009, "collection"=>"test", "batchSize"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007fe838682fe0 @seconds=1521668308, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70317677745800 type=generic data=0x0000000000000000...>, "keyId"=>0}}, "lsid"=>{"id"=><BSON::Binary:0x70317686453080 type=uuid data=0x8d0df8f5543c450e...>}}
D, [2018-03-21T17:50:16.576559 #8539] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | SUCCEEDED | 0.001746s
sleeping for 1 seconds
D, [2018-03-21T17:50:17.580486 #8539] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | STARTED | {"getMore"=>107065670009, "collection"=>"test", "batchSize"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007fe839242d80 @seconds=1521669008, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70317683903960 type=generic data=0x0000000000000000...>, "keyId"=>0}}, "lsid"=>{"id"=><BSON::Binary:0x70317686453080 type=uuid data=0x8d0df8f5543c450e...>}}
D, [2018-03-21T17:50:17.581514 #8539] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | SUCCEEDED | 0.000918s
=> #<Mongo::Collection::View:0x70317686455140 namespace='admin.test' @filter={} @options={"no_cursor_timeout"=>true, "batch_size"=>1}>


# PATCH DRIVER TO NOT USE SESSION, READ FROM SECONDARY
[5] mongo(main)> coll = client[:test, read: { mode: :secondary_preferred }]
=> #<Mongo::Collection:0x70123693875280 namespace=admin.test>
[7] mongo(main)> sleep_intervals = [ 10, 700, 1]
=> [10, 700, 1]
[8] mongo(main)> coll.find({}, no_cursor_timeout: true, batch_size: 1).each_with_index do |doc, i|
[8] mongo(main)*   doc  
[8] mongo(main)*   puts "sleeping for #{sleep_intervals[i]} seconds"  
[8] mongo(main)*   sleep(sleep_intervals[i])  
[8] mongo(main)* end  
D, [2018-03-21T22:56:15.572458 #9427] DEBUG -- : MONGODB | localhost:3001 | admin.find | STARTED | {"find"=>"test", "filter"=>{}, "noCursorTimeout"=>true, "batchSize"=>1, "$readPreference"=>{"mode"=>"secondaryPreferred"}}
D, [2018-03-21T22:56:15.574940 #9427] DEBUG -- : MONGODB | localhost:3001 | admin.find | SUCCEEDED | 0.002321s
sleeping for 10 seconds
D, [2018-03-21T22:56:25.580422 #9427] DEBUG -- : MONGODB | localhost:3001 | admin.getMore | STARTED | {"getMore"=>104058669676, "collection"=>"test", "batchSize"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007f8de2438790 @seconds=1521687366, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70123685240760 type=generic data=0x0000000000000000...>, "keyId"=>0}}}
D, [2018-03-21T22:56:25.581595 #9427] DEBUG -- : MONGODB | localhost:3001 | admin.getMore | SUCCEEDED | 0.000959s
sleeping for 700 seconds
D, [2018-03-21T23:08:05.582992 #9427] DEBUG -- : MONGODB | localhost:3001 | admin.getMore | STARTED | {"getMore"=>104058669676, "collection"=>"test", "batchSize"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007f8de242ae60 @seconds=1521687376, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70123681563420 type=generic data=0x0000000000000000...>, "keyId"=>0}}}
D, [2018-03-21T23:08:05.583824 #9427] DEBUG -- : MONGODB | localhost:3001 | admin.getMore | SUCCEEDED | 0.0007070000000000001s
sleeping for 1 seconds
D, [2018-03-21T23:08:06.588222 #9427] DEBUG -- : MONGODB | localhost:3001 | admin.getMore | STARTED | {"getMore"=>104058669676, "collection"=>"test", "batchSize"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007f8de3b461f8 @seconds=1521688076, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70123693682700 type=generic data=0x0000000000000000...>, "keyId"=>0}}}
D, [2018-03-21T23:08:06.589048 #9427] DEBUG -- : MONGODB | localhost:3001 | admin.getMore | SUCCEEDED | 0.0006640000000000001s
=> #<Mongo::Collection::View:0x70123685185240 namespace='admin.test' @filter={} @options={"no_cursor_timeout"=>true, "batch_size"=>1}>
[9] mongo(main)> client.database.command(buildInfo: 1)
D, [2018-03-21T23:10:09.322660 #9427] DEBUG -- : MONGODB | localhost:3000 | admin.buildInfo | STARTED | {"buildInfo"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007f8de3b3d878 @seconds=1521688086, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70123693665100 type=generic data=0x0000000000000000...>, "keyId"=>0}}, "$readPreference"=>{"mode"=>"primary"}}
D, [2018-03-21T23:10:09.326446 #9427] DEBUG -- : MONGODB | localhost:3000 | admin.buildInfo | SUCCEEDED | 0.003606s
=> #<Mongo::Operation::Result:70123683480220 documents=[{"version"=>"3.6.3", "gitVersion"=>"9586e557d54ef70f9ca4b43c26892cd55257e1a5", "modules"=>[], "allocator"=>"system", "javascriptEngine"=>"mozjs", "sysInfo"=>"deprecated", "versionArray"=>[3, 6, 3, 0], "openssl"=>{"running"=>"OpenSSL 0.9.8zh 14 Jan 2016", "compiled"=>"OpenSSL 0.9.8zh 14 Jan 2016"}, "buildEnvironment"=>{"distmod"=>"", "distarch"=>"x86_64", "cc"=>"gcc: Apple LLVM version 8.1.0 (clang-802.0.42)", "ccflags"=>"-mmacosx-version-min=10.10 -fno-omit-frame-pointer -fno-strict-aliasing -ggdb -pthread -Wall -Wsign-compare -Wno-unknown-pragmas -Winvalid-pch -Werror -O2 -Wno-unused-local-typedefs -Wno-unused-function -Wno-unused-private-field -Wno-deprecated-declarations -Wno-tautological-constant-out-of-range-compare -Wno-unused-const-variable -Wno-missing-braces -Wno-inconsistent-missing-override -Wno-potentially-evaluated-expression -Wno-exceptions -fstack-protector-strong -fno-builtin-memcmp", "cxx"=>"g++: Apple LLVM version 8.1.0 (clang-802.0.42)", "cxxflags"=>"-Woverloaded-virtual -Werror=unused-result -Wpessimizing-move -Wredundant-move -Wno-undefined-var-template -stdlib=libc++ -std=c++14", "linkflags"=>"-mmacosx-version-min=10.10 -Wl,-bind_at_load -Wl,-fatal_warnings -fstack-protector-strong -stdlib=libc++", "target_arch"=>"x86_64", "target_os"=>"macOS"}, "bits"=>64, "debug"=>false, "maxBsonObjectSize"=>16777216, "storageEngines"=>["devnull", "ephemeralForTest", "mmapv1", "wiredTiger"], "ok"=>1.0, "operationTime"=>#<BSON::Timestamp:0x00007f8de27d1758 @seconds=1521688206, @increment=1>, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007f8de27d15f0 @seconds=1521688206, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70123683482120 type=generic data=0x0000000000000000...>, "keyId"=>0}}}]>


# TEST SLEEPING FOR 700 SECONDS BEFORE FIRST GETMORE
[1] mongo(main)> client = Mongo::Client.new(["localhost:3000", "localhost:3001", "localhost:3002"], truncate_logs: false)
D, [2018-03-25T20:42:59.954354 #29229] DEBUG -- : MONGODB | Topology type 'unknown' initializing.
D, [2018-03-25T20:42:59.954546 #29229] DEBUG -- : MONGODB | Server localhost:3000 initializing.
D, [2018-03-25T20:42:59.958704 #29229] DEBUG -- : MONGODB | Server description for localhost:3000 changed from 'unknown' to 'secondary'.
D, [2018-03-25T20:42:59.958877 #29229] DEBUG -- : MONGODB | Server localhost:3001 initializing.
D, [2018-03-25T20:42:59.967515 #29229] DEBUG -- : MONGODB | Server description for localhost:3001 changed from 'unknown' to 'primary'.
D, [2018-03-25T20:42:59.967842 #29229] DEBUG -- : MONGODB | Server localhost:3002 initializing.
D, [2018-03-25T20:42:59.979290 #29229] DEBUG -- : MONGODB | Server description for localhost:3002 changed from 'unknown' to 'secondary'.
D, [2018-03-25T20:42:59.979871 #29229] DEBUG -- : MONGODB | There was a change in the members of the 'unknown' topology.
D, [2018-03-25T20:42:59.980422 #29229] DEBUG -- : MONGODB | Topology type 'unknown' changed to type 'replica set'.
D, [2018-03-25T20:42:59.980909 #29229] DEBUG -- : MONGODB | There was a change in the members of the 'replica set' topology.
=> #<Mongo::Client:0x70117095001960 cluster=localhost:3000, localhost:3001, localhost:3002>
[2] mongo(main)> coll = client[:test, read: { mode: :secondary_preferred }]
=> #<Mongo::Collection:0x70117082176660 namespace=admin.test>
[3] mongo(main)> sleep_intervals = [ 700, 10, 1]
=> [700, 10, 1]
[4] mongo(main)> 
[5] mongo(main)> coll.find({}, no_cursor_timeout: true, batch_size: 1).each_with_index do |doc, i|
[5] mongo(main)*   doc
[5] mongo(main)*   puts "sleeping for #{sleep_intervals[i]} seconds"   
[5] mongo(main)*   sleep(sleep_intervals[i])  
[5] mongo(main)* end  
D, [2018-03-25T20:43:30.979843 #29229] DEBUG -- : MONGODB | localhost:3002 | admin.find | STARTED | {"find"=>"test", "filter"=>{}, "noCursorTimeout"=>true, "batchSize"=>1, "lsid"=>{"id"=><BSON::Binary:0x70117111355340 type=uuid data=0x13ec1aba6ecc4553...>}, "$readPreference"=>{"mode"=>"secondaryPreferred"}}
D, [2018-03-25T20:43:30.983049 #29229] DEBUG -- : MONGODB | localhost:3002 | admin.find | SUCCEEDED | 0.003001s
sleeping for 700 seconds
D, [2018-03-25T20:55:11.005763 #29229] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | STARTED | {"getMore"=>55550255956, "collection"=>"test", "batchSize"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007f8ad3081938 @seconds=1522025007, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70117111368700 type=generic data=0x0000000000000000...>, "keyId"=>0}}, "lsid"=>{"id"=><BSON::Binary:0x70117111355340 type=uuid data=0x13ec1aba6ecc4553...>}}
D, [2018-03-25T20:55:11.006381 #29229] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | FAILED | cursor id 55550255956 not found (43) | 0.000556s
Mongo::Error::OperationFailure: cursor id 55550255956 not found (43)
from /Users/emily/Code/driver/mongo-ruby-driver/lib/mongo/operation/result.rb:256:in `validate!'

# TESTING ON 3.7.3
[7] mongo(main)> coll.find({}, no_cursor_timeout: true, batch_size: 1).each_with_index do |doc, i|
[7] mongo(main)*   doc
[7] mongo(main)*   puts "sleeping for #{sleep_intervals[i]} seconds"    
[7] mongo(main)*   sleep(sleep_intervals[i])    
[7] mongo(main)* end  
D, [2018-03-25T21:34:44.360572 #30107] DEBUG -- : MONGODB | localhost:3002 | admin.find | STARTED | {"find"=>"test", "filter"=>{}, "noCursorTimeout"=>true, "batchSize"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007fbca9b27b78 @seconds=1522028068, @increment=4>, "signature"=>{"hash"=><BSON::Binary:0x70224138811460 type=generic data=0x0000000000000000...>, "keyId"=>0}}, "lsid"=>{"id"=><BSON::Binary:0x70224139527360 type=uuid data=0xb1ce8e7ef7b3453c...>}, "$readPreference"=>{"mode"=>"secondaryPreferred"}}
D, [2018-03-25T21:34:44.362459 #30107] DEBUG -- : MONGODB | localhost:3002 | admin.find | SUCCEEDED | 0.001804s
sleeping for 700 seconds
D, [2018-03-25T21:46:24.395557 #30107] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | STARTED | {"getMore"=>66843923411, "collection"=>"test", "batchSize"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007fbcac8d8cc0 @seconds=1522028082, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70224162768320 type=generic data=0x0000000000000000...>, "keyId"=>0}}, "lsid"=>{"id"=><BSON::Binary:0x70224139527360 type=uuid data=0xb1ce8e7ef7b3453c...>}}
D, [2018-03-25T21:46:24.396458 #30107] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | SUCCEEDED | 0.0007080000000000001s
sleeping for 10 seconds
D, [2018-03-25T21:46:34.400862 #30107] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | STARTED | {"getMore"=>66843923411, "collection"=>"test", "batchSize"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007fbcac8106a8 @seconds=1522028782, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70224162357860 type=generic data=0x0000000000000000...>, "keyId"=>0}}, "lsid"=>{"id"=><BSON::Binary:0x70224139527360 type=uuid data=0xb1ce8e7ef7b3453c...>}}
D, [2018-03-25T21:46:34.401788 #30107] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | SUCCEEDED | 0.000655s
sleeping for 1 seconds
D, [2018-03-25T21:46:35.403425 #30107] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | STARTED | {"getMore"=>66843923411, "collection"=>"test", "batchSize"=>1, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007fbca9fec7d0 @seconds=1522028792, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x70224141312760 type=generic data=0x0000000000000000...>, "keyId"=>0}}, "lsid"=>{"id"=><BSON::Binary:0x70224139527360 type=uuid data=0xb1ce8e7ef7b3453c...>}}
D, [2018-03-25T21:46:35.404260 #30107] DEBUG -- : MONGODB | localhost:3002 | admin.getMore | SUCCEEDED | 0.000716s
=> #<Mongo::Collection::View:0x70224162790460 namespace='admin.test' @filter={} @options={"no_cursor_timeout"=>true, "batch_size"=>1}>