Uploaded image for project: 'Mongoid'
  1. Mongoid
  2. MONGOID-4096

Mongoid 5 #with changes bleeding across queries (and slave_ok all the time?)

    • Type: Icon: Task Task
    • Resolution: Done
    • 5.0.0
    • Affects Version/s: None
    • Component/s: None
    • None

      Hey @durran, I'm testing out Mongoid 5. I'm seeing that Model.with is changing the underlying session/client.

      Here's a spec in Mongoid 4:

      it "doesn't change options" do
        Moped.logger = Logger.new(STDOUT)
        puts(Band.collection.database.session.options.inspect)
        Band.with(:read => :secondary_preferred).first
        puts(Band.collection.database.session.options.inspect)
        Band.first
        Band.with(:read => :primary).first
        puts(Band.collection.database.session.options.inspect)
        Band.first
      end
      

      and its output:

      {:instrumenter=>ActiveSupport::Notifications, :database=>:mongoid_test}
      D, [2015-06-18T18:53:12.978035 #26554] DEBUG -- :   MOPED: 127.0.0.1:27017 QUERY        database=mongoid_test collection=bands selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[:slave_ok] limit=-1 skip=0 batch_size=nil fields=nil runtime: 0.4600ms
      {:instrumenter=>ActiveSupport::Notifications, :database=>:mongoid_test}
      D, [2015-06-18T18:53:12.978597 #26554] DEBUG -- :   MOPED: 127.0.0.1:27017 QUERY        database=mongoid_test collection=bands selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 0.3010ms
      D, [2015-06-18T18:53:12.979045 #26554] DEBUG -- :   MOPED: 127.0.0.1:27017 QUERY        database=mongoid_test collection=bands selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 0.2610ms
      {:instrumenter=>ActiveSupport::Notifications, :database=>:mongoid_test}
      D, [2015-06-18T18:53:12.979490 #26554] DEBUG -- :   MOPED: 127.0.0.1:27017 QUERY        database=mongoid_test collection=bands selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 0.2260ms
      

      This looks right. The first Band.first query has a slave_ok, then the remaining 3 do not have slave_ok. Inspecting Band.collection.database.session.options does not change across updates.

      Here it is in Mongoid 5:

      it "doesn't change options" do
        Mongo::Logger.logger = Logger.new(STDOUT)
        puts(Band.collection.database.client.options.inspect)
        Band.with(:read => {:mode => :secondary_preferred}).first
        puts(Band.collection.database.client.options.inspect)
        Band.first
        Band.with(:read => {:mode => :primary}).first
        puts(Band.collection.database.client.options.inspect)
        Band.first
      end
      

      and its output:

      {:database=>:mongoid_test, :server_selection_timeout=>0.5, :max_pool_size=>1, :heartbeat_frequency=>180, :user=>"mongoid-user", :password=>"password", :auth_source=>"admin", :hosts=>["127.0.0.1:27017"], :options=>{"server_selection_timeout"=>0.5, "max_pool_size"=>1, "heartbeat_frequency"=>180, "user"=>"mongoid-user", "password"=>"password", "auth_source"=>"admin"}}
      D, [2015-06-18T18:51:13.296944 #26432] DEBUG -- : MONGODB | QUERY | namespace=mongoid_test.bands selector={} flags=[:slave_ok, :slave_ok] limit=0 skip=0 project=nil | runtime: 0.3798ms
      {:database=>:mongoid_test, :server_selection_timeout=>0.5, :max_pool_size=>1, :heartbeat_frequency=>180, :user=>"mongoid-user", :password=>"password", :auth_source=>"admin", :hosts=>["127.0.0.1:27017"], :options=>{"server_selection_timeout"=>0.5, "max_pool_size"=>1, "heartbeat_frequency"=>180, "user"=>"mongoid-user", "password"=>"password", "auth_source"=>"admin"}, :read=>{:mode=>:secondary_preferred}}
      D, [2015-06-18T18:51:13.297522 #26432] DEBUG -- : MONGODB | QUERY | namespace=mongoid_test.bands selector={} flags=[:slave_ok, :slave_ok] limit=0 skip=0 project=nil | runtime: 0.2320ms
      D, [2015-06-18T18:51:13.297978 #26432] DEBUG -- : MONGODB | QUERY | namespace=mongoid_test.bands selector={} flags=[:slave_ok] limit=0 skip=0 project=nil | runtime: 0.2561ms
      {:database=>:mongoid_test, :server_selection_timeout=>0.5, :max_pool_size=>1, :heartbeat_frequency=>180, :user=>"mongoid-user", :password=>"password", :auth_source=>"admin", :hosts=>["127.0.0.1:27017"], :options=>{"server_selection_timeout"=>0.5, "max_pool_size"=>1, "heartbeat_frequency"=>180, "user"=>"mongoid-user", "password"=>"password", "auth_source"=>"admin"}, :read=>{:mode=>:primary}}
      D, [2015-06-18T18:51:13.298526 #26432] DEBUG -- : MONGODB | QUERY | namespace=mongoid_test.bands selector={} flags=[:slave_ok] limit=0 skip=0 project=nil | runtime: 0.2551ms
      

      In this case, we see slave_ok in each query (in fact, we see it twice when it should be there just once). But if you look at Band.collection.database.client.options, the options do change after a Band.with. This is why the 2nd Band.first still has two {{slave_ok}}s! This seems really bad, as the secondary read is persisting across multiple queries.

      Seems like there is 1, maybe 2 bugs here.

            Assignee:
            Unassigned Unassigned
            Reporter:
            jonhyman Jon Hyman
            Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

              Created:
              Updated:
              Resolved: