Uploaded image for project: 'Ruby Driver'
  1. Ruby Driver
  2. RUBY-1935

database#command attempts to retry as retryable read

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 2.11.0.rc0, 2.10.2, 2.9.2
    • Affects Version/s: None
    • Component/s: Spec Comp
    • Labels:
      None
    • Fully Compatible

      I ran

      {shutdown:1}

      admin command on the last functioning node of the RS, and this caused the application to hang. It appears that the driver is trying to retry the command and was waiting in server selection for a working server to materialize:

      irb(main):005:0> c=Mongo::Client.new('mongodb://localhost:14440')
      D, [2019-09-10T18:00:26.569990 #11418] DEBUG -- : MONGODB | EVENT: #<TopologyOpening topology=Unknown[]>
      D, [2019-09-10T18:00:26.570088 #11418] DEBUG -- : MONGODB | Topology type 'unknown' initializing.
      D, [2019-09-10T18:00:26.570307 #11418] DEBUG -- : MONGODB | EVENT: #<TopologyChanged prev=Unknown[] new=Unknown[localhost:14440]>
      D, [2019-09-10T18:00:26.570364 #11418] DEBUG -- : MONGODB | Topology type 'Unknown' changed to type 'Unknown'.
      D, [2019-09-10T18:00:26.570423 #11418] DEBUG -- : MONGODB | EVENT: #<ServerOpening address=localhost:14440 topology=Unknown[localhost:14440]>
      D, [2019-09-10T18:00:26.570461 #11418] DEBUG -- : MONGODB | Server localhost:14440 initializing.
      D, [2019-09-10T18:00:26.570670 #11418] DEBUG -- : MONGODB | Waiting for up to 30.00 seconds for servers to be scanned: #<Cluster topology=Unknown[localhost:14440] servers=[#<Server address=localhost:14440 UNKNOWN>]>
      D, [2019-09-10T18:00:26.572375 #11418] DEBUG -- : MONGODB | EVENT: #<ServerDescriptionChanged address=localhost:14440 topology=Sharded[localhost:14440] prev=#<Mongo::Server:Description:0x47104320952560 config={} average_round_trip_time=> new=#<Mongo::Server:Description:0x47104320983280 config={"ismaster"=>true, "msg"=>"isdbgrid", "maxBsonObjectSize"=>16777216, "maxMessageSizeBytes"=>48000000, "maxWriteBatchSize"=>100000, "localTime"=>2019-09-10 22:00:26 UTC, "logicalSessionTimeoutMinutes"=>30, "connectionId"=>440, "maxWireVersion"=>8, "minWireVersion"=>0, "ok"=>1.0, "operationTime"=>#<BSON::Timestamp:0x000055aea8a3a640 @seconds=1568152819, @increment=1>, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x000055aea8a3a528 @seconds=1568152819, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x47104320983440 type=generic data=0x0000000000000000...>, "keyId"=>0}}} average_round_trip_time=0.0013202>>
      D, [2019-09-10T18:00:26.572467 #11418] DEBUG -- : MONGODB | Server description for localhost:14440 changed from 'unknown' to 'sharded'.
      D, [2019-09-10T18:00:26.572678 #11418] DEBUG -- : MONGODB | EVENT: #<TopologyChanged prev=Unknown[localhost:14440] new=Sharded[localhost:14440]>
      D, [2019-09-10T18:00:26.572734 #11418] DEBUG -- : MONGODB | Topology type 'Unknown' changed to type 'Sharded'.
      => #<Mongo::Client:0x47104320945280 cluster=#<Cluster topology=Sharded[localhost:14440] servers=[#<Server address=localhost:14440 MONGOS pool=#<ConnectionPool size=0 (0-5) used=0 avail=0 pending=0>>]>>
      irb(main):006:0> c.database.command(shutdown:1)
      D, [2019-09-10T18:00:34.837993 #11418] DEBUG -- : MONGODB | EVENT: #<ServerDescriptionChanged address=localhost:14440 topology=Sharded[localhost:14440] prev=#<Mongo::Server:Description:0x47104320983280 config={"ismaster"=>true, "msg"=>"isdbgrid", "maxBsonObjectSize"=>16777216, "maxMessageSizeBytes"=>48000000, "maxWriteBatchSize"=>100000, "localTime"=>2019-09-10 22:00:26 UTC, "logicalSessionTimeoutMinutes"=>30, "connectionId"=>440, "maxWireVersion"=>8, "minWireVersion"=>0, "ok"=>1.0, "operationTime"=>#<BSON::Timestamp:0x000055aea8a3a640 @seconds=1568152819, @increment=1>, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x000055aea8a3a528 @seconds=1568152819, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x47104320983440 type=generic data=0x0000000000000000...>, "keyId"=>0}}} average_round_trip_time=0.0013202> new=#<Mongo::Server:Description:0x47104322779160 config={"ismaster"=>true, "msg"=>"isdbgrid", "maxBsonObjectSize"=>16777216, "maxMessageSizeBytes"=>48000000, "maxWriteBatchSize"=>100000, "localTime"=>2019-09-10 22:00:34 UTC, "logicalSessionTimeoutMinutes"=>30, "connectionId"=>442, "maxWireVersion"=>8, "minWireVersion"=>0, "ok"=>1.0, "operationTime"=>#<BSON::Timestamp:0x000055aea8da7378 @seconds=1568152829, @increment=1>, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x000055aea8da72b0 @seconds=1568152829, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x47104322779340 type=generic data=0x0000000000000000...>, "keyId"=>0}}} average_round_trip_time=0.0011546014000000002>>
      D, [2019-09-10T18:00:34.838094 #11418] DEBUG -- : MONGODB | Server description for localhost:14440 changed from 'sharded' to 'sharded'.
      D, [2019-09-10T18:00:34.838214 #11418] DEBUG -- : MONGODB | EVENT: #<TopologyChanged prev=Sharded[localhost:14440] new=Sharded[localhost:14440]>
      D, [2019-09-10T18:00:34.838270 #11418] DEBUG -- : MONGODB | Topology type 'Sharded' changed to type 'Sharded'.
      D, [2019-09-10T18:00:34.838772 #11418] DEBUG -- : MONGODB | localhost:14440 | admin.shutdown | STARTED | {"shutdown"=>1, "$readPreference"=>{"mode"=>"primary"}, "lsid"=>{"id"=><BSON::Binary:0x47104321170380 type=uuid data=0x6be50d4103ff4678...>}}
      D, [2019-09-10T18:00:34.843124 #11418] DEBUG -- : MONGODB | localhost:14440 | admin.shutdown | FAILED | EOFError: end of file reached (for 127.0.0.1:14440 (no TLS)) | 0.004188575s
      D, [2019-09-10T18:00:34.843558 #11418] DEBUG -- : MONGODB | EVENT: #<ServerDescriptionChanged address=localhost:14440 topology=Sharded[localhost:14440] prev=#<Mongo::Server:Description:0x47104322779160 config={"ismaster"=>true, "msg"=>"isdbgrid", "maxBsonObjectSize"=>16777216, "maxMessageSizeBytes"=>48000000, "maxWriteBatchSize"=>100000, "localTime"=>2019-09-10 22:00:34 UTC, "logicalSessionTimeoutMinutes"=>30, "connectionId"=>442, "maxWireVersion"=>8, "minWireVersion"=>0, "ok"=>1.0, "operationTime"=>#<BSON::Timestamp:0x000055aea8da7378 @seconds=1568152829, @increment=1>, "$clusterTime"=>{"clusterTime"=>#<BSON::Timestamp:0x000055aea8da72b0 @seconds=1568152829, @increment=1>, "signature"=>{"hash"=><BSON::Binary:0x47104322779340 type=generic data=0x0000000000000000...>, "keyId"=>0}}} average_round_trip_time=0.0011546014000000002> new=#<Mongo::Server:Description:0x47104318808220 config={} average_round_trip_time=>>
      D, [2019-09-10T18:00:34.843638 #11418] DEBUG -- : MONGODB | Server description for localhost:14440 changed from 'sharded' to 'unknown'.
      D, [2019-09-10T18:00:34.843731 #11418] DEBUG -- : MONGODB | EVENT: #<TopologyChanged prev=Sharded[localhost:14440] new=Sharded[localhost:14440]>
      D, [2019-09-10T18:00:34.843785 #11418] DEBUG -- : MONGODB | Topology type 'Sharded' changed to type 'Sharded'.
      W, [2019-09-10T18:00:35.343702 #11418]  WARN -- : Retrying ismaster in monitor for localhost:14440 due to: Mongo::Error::SocketError EOFError: end of file reached (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:35.343858 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::EPIPE: Broken pipe (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:35.845788 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:36.846947 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:37.847747 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:38.848913 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:39.850001 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      
      D, [2019-09-10T18:00:40.851157 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      
      D, [2019-09-10T18:00:41.852303 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:42.853460 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:43.853912 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:44.855154 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:45.855833 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:46.856873 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:47.857994 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:48.859111 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:49.859742 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:50.860881 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:51.862043 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:52.863131 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:53.864301 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:54.865402 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:55.866511 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:56.867669 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:57.868802 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:00:58.869896 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      
      D, [2019-09-10T18:00:59.871016 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      
      
      
      
      
      
      
      
      
      
      
      
      
      
      
      
      
      
      
      
      
      
      
      
      D, [2019-09-10T18:01:00.872141 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      
      
      
      
      
      
      D, [2019-09-10T18:01:01.873277 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:01:02.874433 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      D, [2019-09-10T18:01:03.875597 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
      Traceback (most recent call last):
             16: from /home/w/apps/ruby-driver/lib/mongo/operation/shared/response_handling.rb:87:in `add_server_diagnostics'
             15: from /home/w/apps/ruby-driver/lib/mongo/operation/shared/executable.rb:29:in `block (3 levels) in do_execute'
             14: from /home/w/apps/ruby-driver/lib/mongo/operation/shared/executable.rb:50:in `get_result'
             13: from /home/w/apps/ruby-driver/lib/mongo/operation/shared/executable.rb:55:in `dispatch_message'
             12: from /home/w/apps/ruby-driver/lib/mongo/server.rb:416:in `with_connection'
             11: from /home/w/apps/ruby-driver/lib/mongo/server/connection_pool.rb:559:in `with_connection'
             10: from /home/w/apps/ruby-driver/lib/mongo/operation/shared/executable.rb:56:in `block in dispatch_message'
              9: from /home/w/apps/ruby-driver/lib/mongo/server/connection_base.rb:90:in `dispatch'
              8: from /home/w/apps/ruby-driver/lib/mongo/server/connection.rb:383:in `deliver'
              7: from /home/w/apps/ruby-driver/lib/mongo/server/connection_base.rb:97:in `deliver'
              6: from /home/w/apps/ruby-driver/lib/mongo/server/connectable.rb:83:in `ensure_connected'
              5: from /home/w/apps/ruby-driver/lib/mongo/server/connection_base.rb:105:in `block in deliver'
              4: from /home/w/apps/ruby-driver/lib/mongo/protocol/message.rb:139:in `deserialize'
      D, [2019-09-10T18:01:04.846232 #11418] DEBUG -- : MONGODB | Error running ismaster on localhost:14440: Errno::ECONNREFUSED: Connection refused - connect(2) for 127.0.0.1:14440 (for 127.0.0.1:14440 (no TLS))
              3: from /home/w/apps/ruby-driver/lib/mongo/socket.rb:127:in `read'
              2: from /home/w/apps/ruby-driver/lib/mongo/socket.rb:313:in `handle_errors'
              1: from /home/w/apps/ruby-driver/lib/mongo/socket.rb:319:in `rescue in handle_errors'
      Mongo::Error::SocketError (EOFError: end of file reached (for 127.0.0.1:14440 (no TLS)) (on localhost:14440, attempt 1, later retry failed: Mongo::Error::NoServerAvailable: No primary server is available in cluster: #<Cluster topology=Sharded[localhost:14440] servers=[#<Server address=localhost:14440 UNKNOWN pool=#<ConnectionPool size=0 (0-5) used=0 avail=0 pending=0>>]> with timeout=30, LT=0.015))
      irb(main):007:0> 
      irb(main):008:0> 
      irb(main):009:0> 
      irb(main):010:0> 
      irb(main):011:0> 
      irb(main):012:0> 
      irb(main):013:0> 
      irb(main):014:0> 
      irb(main):015:0> 
      

      database#command operations should probably not be retried by the driver.

            Assignee:
            oleg.pudeyev@mongodb.com Oleg Pudeyev (Inactive)
            Reporter:
            oleg.pudeyev@mongodb.com Oleg Pudeyev (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated:
              Resolved: