Skip to content

Instantly share code, notes, and snippets.

@joeyAghion

joeyAghion/example.out

Forked from dblock/mongoid-collection-snapshot-nil.rb
Last active April 8, 2018 02:14
Show Gist options
  • Save joeyAghion/eff3a7d61510be724f4e6a9c571f0f5c to your computer and use it in GitHub Desktop.
Save joeyAghion/eff3a7d61510be724f4e6a9c571f0f5c to your computer and use it in GitHub Desktop.
Download ZIP
Raw
example.out
# In most cases, script proceeds as expected:
$ ruby script.rb
................................................................................ done.
$ ruby script.rb
................................................................................ done.
# Occasionally, fails with empty results:
$ ruby script.rb
........script.rb:59:in `block (3 levels) in <main>': got a nil widget (RuntimeError)
from /Users/joey/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/mongoid-6.1.0/lib/mongoid/contextual/mongo.rb:696:in `yield_document'
from /Users/joey/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/mongoid-6.1.0/lib/mongoid/contextual/mongo.rb:133:in `block in each'
from /Users/joey/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/mongo-2.4.1/lib/mongo/collection/view/iterable.rb:45:in `block in each'
from /Users/joey/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/mongo-2.4.1/lib/mongo/cursor.rb:110:in `block in each'
from /Users/joey/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/mongo-2.4.1/lib/mongo/cursor.rb:110:in `each'
from /Users/joey/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/mongo-2.4.1/lib/mongo/cursor.rb:110:in `each'
from /Users/joey/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/mongo-2.4.1/lib/mongo/collection/view/iterable.rb:44:in `each'
from /Users/joey/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/mongoid-6.1.0/lib/mongoid/query_cache.rb:222:in `each'
from /Users/joey/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/mongoid-6.1.0/lib/mongoid/contextual/mongo.rb:132:in `each'
from /Users/joey/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/mongoid-6.1.0/lib/mongoid/contextual.rb:20:in `each'
from /Users/joey/.rbenv/versions/2.2.2/lib/ruby/gems/2.2.0/gems/mongoid-6.1.0/lib/mongoid/findable.rb:15:in `each'
from script.rb:58:in `block (2 levels) in <main>'
# Interestingly, when it fails, it's always after printing 8 `.`s, which corresponds with the number of threads
# performing queries. If I configure a higher `max_pool_size`, more dots are printed before failure.
Raw
mongo.log
D, [2017-05-30T15:39:16.884817 #73321] DEBUG -- : MONGODB | Topology type 'unknown' initializing.
D, [2017-05-30T15:39:16.884968 #73321] DEBUG -- : MONGODB | Server localhost:27017 initializing.
D, [2017-05-30T15:39:16.887803 #73321] DEBUG -- : MONGODB | Topology type 'unknown' changed to type 'single'.
D, [2017-05-30T15:39:16.887896 #73321] DEBUG -- : MONGODB | Server description for localhost:27017 changed from 'unknown' to 'standalone'.
D, [2017-05-30T15:39:16.887955 #73321] DEBUG -- : MONGODB | There was a change in the members of the 'single' topology.
D, [2017-05-30T15:39:16.888605 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.delete | STARTED | {"delete"=>"widgets", "deletes"=>[{"q"=>{}, "limit"=>0}], "ordered"=>true}
D, [2017-05-30T15:39:16.889710 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.delete | SUCCEEDED | 0.000981s
D, [2017-05-30T15:39:16.890070 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.delete | STARTED | {"delete"=>"gadgets", "deletes"=>[{"q"=>{}, "limit"=>0}], "ordered"=>true}
D, [2017-05-30T15:39:16.890443 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.delete | SUCCEEDED | 0.000308s
D, [2017-05-30T15:39:16.892407 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"widgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd513')}], "ordered"=>true}
D, [2017-05-30T15:39:16.892723 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000254s
D, [2017-05-30T15:39:16.893199 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"gadgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd514')}], "ordered"=>true}
D, [2017-05-30T15:39:16.893446 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000201s
D, [2017-05-30T15:39:16.893824 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"widgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd515')}], "ordered"=>true}
D, [2017-05-30T15:39:16.894105 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000224s
D, [2017-05-30T15:39:16.894535 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"gadgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd516')}], "ordered"=>true}
D, [2017-05-30T15:39:16.894811 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000222s
D, [2017-05-30T15:39:16.895234 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"widgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd517')}], "ordered"=>true}
D, [2017-05-30T15:39:16.895527 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000238s
D, [2017-05-30T15:39:16.895901 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"gadgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd518')}], "ordered"=>true}
D, [2017-05-30T15:39:16.896171 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000202s
D, [2017-05-30T15:39:16.896570 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"widgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd519')}], "ordered"=>true}
D, [2017-05-30T15:39:16.896856 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000229s
D, [2017-05-30T15:39:16.897205 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"gadgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd51a')}], "ordered"=>true}
D, [2017-05-30T15:39:16.897548 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000251s
D, [2017-05-30T15:39:16.897929 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"widgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd51b')}], "ordered"=>true}
D, [2017-05-30T15:39:16.898221 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.00022600000000000002s
D, [2017-05-30T15:39:16.898593 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"gadgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd51c')}], "ordered"=>true}
D, [2017-05-30T15:39:16.898905 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.00025499999999999996s
D, [2017-05-30T15:39:16.899245 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"widgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd51d')}], "ordered"=>true}
D, [2017-05-30T15:39:16.899527 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.00022s
D, [2017-05-30T15:39:16.899931 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"gadgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd51e')}], "ordered"=>true}
D, [2017-05-30T15:39:16.900216 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000228s
D, [2017-05-30T15:39:16.900661 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"widgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd51f')}], "ordered"=>true}
D, [2017-05-30T15:39:16.900939 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.00021700000000000002s
D, [2017-05-30T15:39:16.901360 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"gadgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd520')}], "ordered"=>true}
D, [2017-05-30T15:39:16.901600 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000194s
D, [2017-05-30T15:39:16.901923 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"widgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd521')}], "ordered"=>true}
D, [2017-05-30T15:39:16.902169 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.00019s
D, [2017-05-30T15:39:16.902600 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"gadgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd522')}], "ordered"=>true}
D, [2017-05-30T15:39:16.902853 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000199s
D, [2017-05-30T15:39:16.903212 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"widgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd523')}], "ordered"=>true}
D, [2017-05-30T15:39:16.903472 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000204s
D, [2017-05-30T15:39:16.903856 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"gadgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd524')}], "ordered"=>true}
D, [2017-05-30T15:39:16.904117 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000202s
D, [2017-05-30T15:39:16.904473 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"widgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd525')}], "ordered"=>true}
D, [2017-05-30T15:39:16.904754 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.000202s
D, [2017-05-30T15:39:16.905072 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"gadgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd526')}], "ordered"=>true}
D, [2017-05-30T15:39:16.905309 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.00019s
D, [2017-05-30T15:39:16.916961 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"widgets_and_gadgets", "filter"=>{"_slugs"=>{"$all"=>[#<BSON::Regexp::Raw:0x007fdf0c322858 @pattern="^snapshot(?:-(\\d+))?$", @options="">]}, "_id"=>{"$ne"=>BSON::ObjectId('592dca64cdebfd1e693fd527')}}}
D, [2017-05-30T15:39:16.917657 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.000598s
D, [2017-05-30T15:39:16.918684 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"widgets", "filter"=>{}}
D, [2017-05-30T15:39:16.919014 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.000268s
D, [2017-05-30T15:39:16.919453 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"gadgets", "filter"=>{}}
D, [2017-05-30T15:39:16.919741 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.000238s
D, [2017-05-30T15:39:16.920066 #73321] DEBUG -- : MONGODB | Topology type 'unknown' initializing.
D, [2017-05-30T15:39:16.920145 #73321] DEBUG -- : MONGODB | Server localhost:27017 initializing.
D, [2017-05-30T15:39:16.922208 #73321] DEBUG -- : MONGODB | Topology type 'unknown' changed to type 'single'.
D, [2017-05-30T15:39:16.922303 #73321] DEBUG -- : MONGODB | Server description for localhost:27017 changed from 'unknown' to 'standalone'.
D, [2017-05-30T15:39:16.922367 #73321] DEBUG -- : MONGODB | There was a change in the members of the 'single' topology.
D, [2017-05-30T15:39:16.922901 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd513'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51a'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd528')}], "ordered"=>true}
D, [2017-05-30T15:39:16.924284 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.0013210000000000001s
D, [2017-05-30T15:39:16.924733 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd513'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51e'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd529')}], "ordered"=>true}
D, [2017-05-30T15:39:16.925088 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000294s
D, [2017-05-30T15:39:16.925463 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd513'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd520'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd52a')}], "ordered"=>true}
D, [2017-05-30T15:39:16.925790 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000261s
D, [2017-05-30T15:39:16.926119 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd513'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd526'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd52b')}], "ordered"=>true}
D, [2017-05-30T15:39:16.926448 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000259s
D, [2017-05-30T15:39:16.926912 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"gadgets", "filter"=>{}}
D, [2017-05-30T15:39:16.927281 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.00031999999999999997s
D, [2017-05-30T15:39:16.927638 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd515'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd514'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd52c')}], "ordered"=>true}
D, [2017-05-30T15:39:16.928001 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00031499999999999996s
D, [2017-05-30T15:39:16.928314 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd515'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd516'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd52d')}], "ordered"=>true}
D, [2017-05-30T15:39:16.928648 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000287s
D, [2017-05-30T15:39:16.928973 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd515'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd518'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd52e')}], "ordered"=>true}
D, [2017-05-30T15:39:16.929323 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000299s
D, [2017-05-30T15:39:16.929602 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd515'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51c'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd52f')}], "ordered"=>true}
D, [2017-05-30T15:39:16.929915 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000239s
D, [2017-05-30T15:39:16.930188 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd515'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51e'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd530')}], "ordered"=>true}
D, [2017-05-30T15:39:16.930505 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000261s
D, [2017-05-30T15:39:16.930803 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd515'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd526'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd531')}], "ordered"=>true}
D, [2017-05-30T15:39:16.931078 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000218s
D, [2017-05-30T15:39:16.931528 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"gadgets", "filter"=>{}}
D, [2017-05-30T15:39:16.931849 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.00026700000000000004s
D, [2017-05-30T15:39:16.932187 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd517'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd516'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd532')}], "ordered"=>true}
D, [2017-05-30T15:39:16.932511 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000272s
D, [2017-05-30T15:39:16.932792 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd517'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51a'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd533')}], "ordered"=>true}
D, [2017-05-30T15:39:16.933057 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00021700000000000002s
D, [2017-05-30T15:39:16.933347 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd517'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51e'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd534')}], "ordered"=>true}
D, [2017-05-30T15:39:16.933593 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000202s
D, [2017-05-30T15:39:16.933851 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd517'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd520'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd535')}], "ordered"=>true}
D, [2017-05-30T15:39:16.934181 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000283s
D, [2017-05-30T15:39:16.934461 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd517'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd524'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd536')}], "ordered"=>true}
D, [2017-05-30T15:39:16.934718 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00021s
D, [2017-05-30T15:39:16.935056 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd517'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd526'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd537')}], "ordered"=>true}
D, [2017-05-30T15:39:16.935337 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00023s
D, [2017-05-30T15:39:16.935759 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"gadgets", "filter"=>{}}
D, [2017-05-30T15:39:16.936060 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.000245s
D, [2017-05-30T15:39:16.936354 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd519'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd514'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd538')}], "ordered"=>true}
D, [2017-05-30T15:39:16.936617 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00021700000000000002s
D, [2017-05-30T15:39:16.936907 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd519'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd516'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd539')}], "ordered"=>true}
D, [2017-05-30T15:39:16.937178 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00021700000000000002s
D, [2017-05-30T15:39:16.937435 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd519'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51a'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd53a')}], "ordered"=>true}
D, [2017-05-30T15:39:16.937703 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000223s
D, [2017-05-30T15:39:16.937948 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd519'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd520'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd53b')}], "ordered"=>true}
D, [2017-05-30T15:39:16.938183 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000193s
D, [2017-05-30T15:39:16.938442 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd519'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd522'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd53c')}], "ordered"=>true}
D, [2017-05-30T15:39:16.938683 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000196s
D, [2017-05-30T15:39:16.939063 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"gadgets", "filter"=>{}}
D, [2017-05-30T15:39:16.939328 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.000215s
D, [2017-05-30T15:39:16.939627 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51b'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd518'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd53d')}], "ordered"=>true}
D, [2017-05-30T15:39:16.939868 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00019800000000000002s
D, [2017-05-30T15:39:16.940180 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51b'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51a'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd53e')}], "ordered"=>true}
D, [2017-05-30T15:39:16.940404 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00018s
D, [2017-05-30T15:39:16.940637 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51b'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51c'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd53f')}], "ordered"=>true}
D, [2017-05-30T15:39:16.940952 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00025499999999999996s
D, [2017-05-30T15:39:16.941251 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51b'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd520'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd540')}], "ordered"=>true}
D, [2017-05-30T15:39:16.941508 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00020800000000000001s
D, [2017-05-30T15:39:16.941787 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51b'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd524'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd541')}], "ordered"=>true}
D, [2017-05-30T15:39:16.942032 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000201s
D, [2017-05-30T15:39:16.942369 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"gadgets", "filter"=>{}}
D, [2017-05-30T15:39:16.942642 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.00022600000000000002s
D, [2017-05-30T15:39:16.942923 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51d'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd514'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd542')}], "ordered"=>true}
D, [2017-05-30T15:39:16.943151 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000185s
D, [2017-05-30T15:39:16.943420 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51d'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd518'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd543')}], "ordered"=>true}
D, [2017-05-30T15:39:16.943664 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000192s
D, [2017-05-30T15:39:16.943921 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51d'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51a'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd544')}], "ordered"=>true}
D, [2017-05-30T15:39:16.944149 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000184s
D, [2017-05-30T15:39:16.944387 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51d'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51c'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd545')}], "ordered"=>true}
D, [2017-05-30T15:39:16.944613 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000181s
D, [2017-05-30T15:39:16.944852 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51d'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd522'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd546')}], "ordered"=>true}
D, [2017-05-30T15:39:16.945129 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000202s
D, [2017-05-30T15:39:16.945410 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51d'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd526'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd547')}], "ordered"=>true}
D, [2017-05-30T15:39:16.945638 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000184s
D, [2017-05-30T15:39:16.945991 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"gadgets", "filter"=>{}}
D, [2017-05-30T15:39:16.946234 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.000193s
D, [2017-05-30T15:39:16.946551 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51f'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd516'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd548')}], "ordered"=>true}
D, [2017-05-30T15:39:16.946840 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000202s
D, [2017-05-30T15:39:16.947130 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51f'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51a'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd549')}], "ordered"=>true}
D, [2017-05-30T15:39:16.947363 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000184s
D, [2017-05-30T15:39:16.947642 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51f'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51c'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd54a')}], "ordered"=>true}
D, [2017-05-30T15:39:16.947860 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000173s
D, [2017-05-30T15:39:16.948124 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51f'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd526'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd54b')}], "ordered"=>true}
D, [2017-05-30T15:39:16.948350 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000182s
D, [2017-05-30T15:39:16.948707 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"gadgets", "filter"=>{}}
D, [2017-05-30T15:39:16.948930 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.000181s
D, [2017-05-30T15:39:16.949204 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd521'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd514'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd54c')}], "ordered"=>true}
D, [2017-05-30T15:39:16.949427 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00017700000000000002s
D, [2017-05-30T15:39:16.949659 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd521'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd516'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd54d')}], "ordered"=>true}
D, [2017-05-30T15:39:16.949887 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00017800000000000002s
D, [2017-05-30T15:39:16.950159 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd521'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd518'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd54e')}], "ordered"=>true}
D, [2017-05-30T15:39:16.950373 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000171s
D, [2017-05-30T15:39:16.950605 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd521'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51a'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd54f')}], "ordered"=>true}
D, [2017-05-30T15:39:16.950839 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00018800000000000002s
D, [2017-05-30T15:39:16.951084 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd521'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51c'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd550')}], "ordered"=>true}
D, [2017-05-30T15:39:16.951303 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00017s
D, [2017-05-30T15:39:16.951540 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd521'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51e'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd551')}], "ordered"=>true}
D, [2017-05-30T15:39:16.951782 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.0002s
D, [2017-05-30T15:39:16.952027 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd521'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd524'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd552')}], "ordered"=>true}
D, [2017-05-30T15:39:16.952333 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000213s
D, [2017-05-30T15:39:16.952718 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"gadgets", "filter"=>{}}
D, [2017-05-30T15:39:16.952981 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.000213s
D, [2017-05-30T15:39:16.953256 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd523'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd514'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd553')}], "ordered"=>true}
D, [2017-05-30T15:39:16.953499 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000192s
D, [2017-05-30T15:39:16.953804 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd523'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd516'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd554')}], "ordered"=>true}
D, [2017-05-30T15:39:16.954072 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.00022s
D, [2017-05-30T15:39:16.954324 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd523'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd518'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd555')}], "ordered"=>true}
D, [2017-05-30T15:39:16.954581 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000204s
D, [2017-05-30T15:39:16.954824 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd523'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51c'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd556')}], "ordered"=>true}
D, [2017-05-30T15:39:16.955056 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000183s
D, [2017-05-30T15:39:16.955340 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd523'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51e'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd557')}], "ordered"=>true}
D, [2017-05-30T15:39:16.955564 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000179s
D, [2017-05-30T15:39:16.955927 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"gadgets", "filter"=>{}}
D, [2017-05-30T15:39:16.956193 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.000223s
D, [2017-05-30T15:39:16.956463 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd525'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd516'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd558')}], "ordered"=>true}
D, [2017-05-30T15:39:16.956699 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000191s
D, [2017-05-30T15:39:16.956963 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd525'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd518'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd559')}], "ordered"=>true}
D, [2017-05-30T15:39:16.957182 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000176s
D, [2017-05-30T15:39:16.957408 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd525'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd51a'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd55a')}], "ordered"=>true}
D, [2017-05-30T15:39:16.957608 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000157s
D, [2017-05-30T15:39:16.957873 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd525'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd520'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd55b')}], "ordered"=>true}
D, [2017-05-30T15:39:16.958056 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000142s
D, [2017-05-30T15:39:16.958319 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd525'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd522'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd55c')}], "ordered"=>true}
D, [2017-05-30T15:39:16.958542 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000177s
D, [2017-05-30T15:39:16.958813 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | STARTED | {"insert"=>"widgets_and_gadgets.snapshot", "documents"=>[{:widget_id=>BSON::ObjectId('592dca64cdebfd1e693fd525'), :gadget_id=>BSON::ObjectId('592dca64cdebfd1e693fd526'), :_id=>BSON::ObjectId('592dca64cdebfd1e693fd55d')}], "ordered"=>true}
D, [2017-05-30T15:39:16.959030 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.insert | SUCCEEDED | 0.000166s
D, [2017-05-30T15:39:16.959271 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | STARTED | {"insert"=>"widgets_and_gadgets", "documents"=>[{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd527'), "workspace_basename"=>"snapshot", "max_collection_snapshot_instances"=>2, "_slugs"=>["snapshot"], "created_at"=>2017-05-30 19:39:16 UTC}], "ordered"=>t...
D, [2017-05-30T15:39:16.959499 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.insert | SUCCEEDED | 0.00018800000000000002s
D, [2017-05-30T15:39:16.959926 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"widgets_and_gadgets", "filter"=>{}, "sort"=>{"created_at"=>-1}}
D, [2017-05-30T15:39:16.960226 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.000256s
D, [2017-05-30T15:39:16.960540 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.listCollections | STARTED | {"listCollections"=>1, "cursor"=>{}, "filter"=>{:name=>{"$not"=>/system\.|\$/}}}
D, [2017-05-30T15:39:16.961042 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.listCollections | SUCCEEDED | 0.000458s
D, [2017-05-30T15:39:16.961439 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.drop | STARTED | {"drop"=>"widgets_and_gadgets.snapshot-25"}
D, [2017-05-30T15:39:16.961811 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.drop | SUCCEEDED | 0.000324s
D, [2017-05-30T15:39:16.962172 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.delete | STARTED | {"delete"=>"widgets_and_gadgets", "deletes"=>[{"q"=>{"_id"=>BSON::ObjectId('592dca49cdebfd1e284fc540')}, "limit"=>1}], "ordered"=>true}
D, [2017-05-30T15:39:16.962441 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.delete | SUCCEEDED | 0.000209s
D, [2017-05-30T15:39:16.963925 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"widgets_and_gadgets", "filter"=>{}, "limit"=>-1, "sort"=>{"created_at"=>-1}}
D, [2017-05-30T15:39:16.964446 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"widgets_and_gadgets", "filter"=>{}, "limit"=>-1, "sort"=>{"created_at"=>-1}}
D, [2017-05-30T15:39:16.965208 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"widgets_and_gadgets", "filter"=>{}, "limit"=>-1, "sort"=>{"created_at"=>-1}}
D, [2017-05-30T15:39:16.965466 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.001463s
D, [2017-05-30T15:39:16.979137 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.find | STARTED | {"find"=>"widgets_and_gadgets.snapshot", "filter"=>{}}
D, [2017-05-30T15:39:16.979902 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"widgets_and_gadgets", "filter"=>{}, "limit"=>-1, "sort"=>{"created_at"=>-1}}
D, [2017-05-30T15:39:16.980285 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.000318s
D, [2017-05-30T15:39:16.980873 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"widgets_and_gadgets.snapshot", "filter"=>{}}
D, [2017-05-30T15:39:16.981570 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets-imports.find | SUCCEEDED | 0.002357s
D, [2017-05-30T15:39:16.982287 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"widgets", "filter"=>{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd513')}, "limit"=>-1, "sort"=>{"_id"=>1}}
D, [2017-05-30T15:39:16.983527 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.002584s
D, [2017-05-30T15:39:16.983788 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.01851s
D, [2017-05-30T15:39:16.984147 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.019268s
D, [2017-05-30T15:39:16.984708 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"widgets", "filter"=>{"_id"=>BSON::ObjectId('592dc15ecdebfd143d8606b6')}, "limit"=>-1, "sort"=>{"_id"=>1}}
D, [2017-05-30T15:39:16.985253 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"widgets_and_gadgets", "filter"=>{}, "limit"=>-1, "sort"=>{"created_at"=>-1}}
D, [2017-05-30T15:39:16.985814 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"widgets_and_gadgets.snapshot", "filter"=>{}}
D, [2017-05-30T15:39:16.986381 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.004019s
D, [2017-05-30T15:39:16.987411 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"widgets_and_gadgets.snapshot", "filter"=>{}}
D, [2017-05-30T15:39:16.988806 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.0006670000000000001s
D, [2017-05-30T15:39:16.989672 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | STARTED | {"find"=>"gadgets", "filter"=>{"_id"=>BSON::ObjectId('592dca64cdebfd1e693fd51a')}, "limit"=>-1, "sort"=>{"_id"=>1}}
D, [2017-05-30T15:39:16.989737 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.0019s
D, [2017-05-30T15:39:16.990379 #73321] DEBUG -- : MONGODB | localhost:27017 | widgets-and-gadgets.find | SUCCEEDED | 0.002399s
Raw
mongoid.yml
production:
clients:
default:
uri: mongodb://localhost:27017/widgets-and-gadgets
imports:
uri: mongodb://localhost:27017/widgets-and-gadgets-imports
Raw
script.rb
require 'mongoid'
require 'mongoid-collection-snapshot'
Mongoid.load!("mongoid.yml", :production)
Mongo::Logger.logger = Mongoid.logger = Logger.new('mongo.log', Logger::DEBUG)
class Widget
include Mongoid::Document
end
class Gadget
include Mongoid::Document
end
class WidgetsAndGadgets
include Mongoid::CollectionSnapshot
document do
belongs_to :widget, inverse_of: nil
belongs_to :gadget, inverse_of: nil
end
def build
Widget.all.each do |widget|
Gadget.all.each do |gadget|
next unless Random.rand(2) == 1
collection_snapshot.insert_one(widget_id: widget.id, gadget_id: gadget.id)
end
end
end
def snapshot_session
Mongoid.client('imports')
end
end
Widget.delete_all
Gadget.delete_all
10.times do
Widget.create!
Gadget.create!
end
WidgetsAndGadgets.create!
require 'thread'
workers = (0...8).map do
Thread.new do
begin
100.times do
STDOUT.write "."
WidgetsAndGadgets.latest.documents.each do |pair|
raise "got a nil widget" unless pair.widget
raise "got a nil gadget" unless pair.gadget
end
end
rescue ThreadError
end
end
end
workers.map(&:join)
puts " done."
@dblock
Copy link

dblock commented May 30, 2017

The number of widgets doesn't matter, the number of items in the pool does, so a faster way to repro this:

require 'mongoid'
require 'mongoid-collection-snapshot'

Mongoid.load!("mongoid.yml", :production)
Mongo::Logger.logger = Mongoid.logger = Logger.new('mongo.log', Logger::DEBUG)

class Widget
  include Mongoid::Document
end

class Gadget
  include Mongoid::Document
end

class WidgetsAndGadgets
  include Mongoid::CollectionSnapshot

  document do
    belongs_to :widget, inverse_of: nil
    belongs_to :gadget, inverse_of: nil
  end

  def build
    Widget.all.each do |widget|
      Gadget.all.each do |gadget|
        next unless Random.rand(2) == 1
        collection_snapshot.insert_one(widget_id: widget.id, gadget_id: gadget.id)
      end
    end
  end

  def snapshot_session
    Mongoid.client('imports')
  end
end

Widget.delete_all
Gadget.delete_all

Widget.create!
Gadget.create!

WidgetsAndGadgets.create!

require 'thread'

workers = (0...32).map do
  Thread.new do
    STDOUT.write "."
    WidgetsAndGadgets.latest.documents.each do |pair|
      raise "got a nil widget" unless pair.widget
      raise "got a nil gadget" unless pair.gadget
    end
  end
end

workers.map(&:join)

puts " done."
for n in {1..5}; do bundle exec ruby t.rb; done

Breaks 1/5 times for me.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment