-
Type:
Bug
-
Resolution: Won't Fix
-
Priority:
Major - P3
-
None
-
Affects Version/s: 4.2.10
-
Component/s: None
-
None
-
ALL
-
Sharding 2020-12-14, Sharding 2020-12-28
I made the following test program which drops the database, inserts a document and performs countdocuments on the database in question. Eventually this program will see the document count stay at 0 for several seconds after a successful insert, after which the count increases to 1.
To make this situation reproducible, I insert some more data prior to the drop to generate extra load, and I drop on only ~ 10% of the iterations.
require 'mongo' require 'byebug' Mongo::Logger.logger.level = 1 client = Mongo::Client.new(['localhost:14240', 'localhost:14241']).use('xxx') db1 = client[:db1] loop do 15.times do db1.insert_many([{a: rand}]*5) end check = rand >= 0.9 if check db1.database.drop end db1.insert_one(a: 1) if check v = db1.count_documents if v != 1 p v #byebug 1 loop do v = db1.count_documents if v != 1 p v sleep 1 else byebug 1 end end end end print('.') end
Result:
serene% ruby test.rb ........................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................0 0 0 0 0 [30, 39] in /home/w/apps/tests/shard-phantom/test.rb 30: if v != 1 31: p v 32: sleep 1 33: else 34: byebug => 35: 1 36: end 37: end 38: end 39: end (byebug)
This issue originally appeared in the transactions example tests for the Ruby driver, where instead of doing a count a find was issued, and that find returned no results after the document to be found was inserted.
I tried setting read and write concerns to majority, which didn't fix the problem:
client = Mongo::Client.new(['localhost:14240', 'localhost:14241']).use('xxx').with( read_concern: {level: :majority}, write_concern: {w: :majority})
In the Ruby driver test suite this condition persists for much longer than this reproduce case shows (potentially indefinitely). To get out of it I can insert another document into the collection in question. Note in the following example how the count jumps from 0 to 2 even though I only inserted one document:
(byebug) hr[:employees].count
D, [2020-11-21T04:45:16.374462 #427] DEBUG -- : MONGODB | localhost:27018 req:79 conn:1:1 sconn:22 | hr.count | STARTED | {"count"=>"employees", "query"=>{}, "readConcern"=>{"level"=>"majority"}, "$db"=>"hr", "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007fbe5c090200 @seconds=1605933879, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x6960 type=generic dat...
D, [2020-11-21T04:45:16.379245 #427] DEBUG -- : MONGODB | localhost:27018 req:79 | hr.count | SUCCEEDED | 0.004s
0
(byebug) hr[:employees].insert_one(a:1)
D, [2020-11-21T04:45:20.533725 #427] DEBUG -- : MONGODB | localhost:27018 req:80 conn:1:1 sconn:22 | hr.insert | STARTED | {"insert"=>"employees", "ordered"=>true, "writeConcern"=>{"w"=>"majority"}, "documents"=>[{"a"=>1, "_id"=>BSON::ObjectId('5fb89b6094fbce01ab1bea0e')}], "$db"=>"hr", "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007fbe5c0bea88 @seconds=16059339...
D, [2020-11-21T04:45:20.540557 #427] DEBUG -- : MONGODB | localhost:27018 req:80 | hr.insert | SUCCEEDED | 0.007s
#<Mongo::Operation::Insert::Result:0x7120 documents=[{"n"=>1, "ok"=>1.0, "operationTime"=>#<BSON::Timestamp:0x00007fbe5c0c4af0 @seconds=1605933920, @increment=4>, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007fbe5c0c4a00 @seconds=1605933920, @increment=4>, "signature"=>{"hash"=><BSON::Binary:0x7140 type=generic data=0x0000000000000000...>, "keyId"=>0}}}]>
(byebug) hr[:employees].count
D, [2020-11-21T04:45:21.510076 #427] DEBUG -- : MONGODB | localhost:27017 req:81 conn:1:1 sconn:28 | hr.count | STARTED | {"count"=>"employees", "query"=>{}, "readConcern"=>{"level"=>"majority"}, "$db"=>"hr", "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x00007fbe5c0c4a00 @seconds=1605933920, @increment=4>, "signature"=>{"hash"=><BSON::Binary:0x7140 type=generic dat...
D, [2020-11-21T04:45:21.516207 #427] DEBUG -- : MONGODB | localhost:27017 req:81 | hr.count | SUCCEEDED | 0.005s
2
Note that even though in the above output the counts were sent to different mongoses, prior to insert both mongoses returned 0 and after the insert both returned 2.
This issue seems to only affect 4.2 sharded clusters.
- related to
-
RUBY-2447 Fix intermittent transaction examples test failures
-
- Closed
-