Uploaded image for project: 'C Driver'
  1. C Driver
  2. CDRIVER-631

Timeout for reconnects is longer than would be expected

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • 1.1.6, 1.1.7
    • Affects Version/s: 1.1.4
    • Component/s: None
    • Labels:
      None

      It can take a surprising amount of time before we report primary not available when connecting to a replica set with two downed members.

      In particular, we have to try:

      (1(initial connect) + 3(tries)) * 2(non-responsive members in seed list) * 2(non-responsive members discovered from live member) * N(connecttimeoutms) = a maximum of 16 * N seconds before returning.

      With a timeout of 3 seconds:

      2015/05/01 14:39:14.0873: [15700]:    DEBUG:      cluster: Client initialized in replica set mode.
      2015/05/01 14:39:14.0873: [15700]:    DEBUG:      cluster: Reconnecting to replica set.
      2015/05/01 14:39:17.0876: [15700]:  WARNING:      cluster: Failed connection to localhost:30001
      2015/05/01 14:39:20.0879: [15700]:  WARNING:      cluster: Failed connection to localhost:30002
      2015/05/01 14:39:20.0883: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30003
      2015/05/01 14:39:20.0883: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30002
      2015/05/01 14:39:20.0883: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30001
      2015/05/01 14:39:23.0889: [15700]:  WARNING:      cluster: Failed connection to localhost:30001
      2015/05/01 14:39:26.0894: [15700]:  WARNING:      cluster: Failed connection to localhost:30002
      2015/05/01 14:39:26.0901: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30003
      2015/05/01 14:39:26.0901: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30002
      2015/05/01 14:39:26.0901: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30001
      2015/05/01 14:39:26.0902: [15700]:    DEBUG:      cluster: Reconnecting to replica set.
      2015/05/01 14:39:29.0904: [15700]:  WARNING:      cluster: Failed connection to localhost:30001
      2015/05/01 14:39:32.0907: [15700]:  WARNING:      cluster: Failed connection to localhost:30002
      2015/05/01 14:39:32.0911: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30003
      2015/05/01 14:39:32.0911: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30002
      2015/05/01 14:39:32.0911: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30001
      2015/05/01 14:39:35.0916: [15700]:  WARNING:      cluster: Failed connection to localhost:30001
      2015/05/01 14:39:38.0922: [15700]:  WARNING:      cluster: Failed connection to localhost:30002
      2015/05/01 14:39:38.0928: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30003
      2015/05/01 14:39:38.0928: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30002
      2015/05/01 14:39:38.0928: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30001
      2015/05/01 14:39:38.0929: [15700]:    DEBUG:      cluster: Reconnecting to replica set.
      2015/05/01 14:39:41.0932: [15700]:  WARNING:      cluster: Failed connection to localhost:30001
      2015/05/01 14:39:44.0935: [15700]:  WARNING:      cluster: Failed connection to localhost:30002
      2015/05/01 14:39:44.0938: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30003
      2015/05/01 14:39:44.0938: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30002
      2015/05/01 14:39:44.0938: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30001
      2015/05/01 14:39:47.0944: [15700]:  WARNING:      cluster: Failed connection to localhost:30001
      2015/05/01 14:39:50.0949: [15700]:  WARNING:      cluster: Failed connection to localhost:30002
      2015/05/01 14:39:50.0956: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30003
      2015/05/01 14:39:50.0956: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30002
      2015/05/01 14:39:50.0956: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30001
      2015/05/01 14:39:50.0956: [15700]:    DEBUG:      cluster: Reconnecting to replica set.
      2015/05/01 14:39:53.0959: [15700]:  WARNING:      cluster: Failed connection to localhost:30001
      2015/05/01 14:39:56.0962: [15700]:  WARNING:      cluster: Failed connection to localhost:30002
      2015/05/01 14:39:56.0966: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30003
      2015/05/01 14:39:56.0966: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30002
      2015/05/01 14:39:56.0966: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30001
      2015/05/01 14:39:59.0971: [15700]:  WARNING:      cluster: Failed connection to localhost:30001
      2015/05/01 14:40:02.0975: [15700]:  WARNING:      cluster: Failed connection to localhost:30002
      2015/05/01 14:40:02.0982: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30003
      2015/05/01 14:40:02.0982: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30002
      2015/05/01 14:40:02.0982: [15700]:    DEBUG:      cluster: Registering potential peer: localhost:30001
      Cursor Failure: Requested PRIMARY node is not available.
      

            Assignee:
            jesse@mongodb.com A. Jesse Jiryu Davis
            Reporter:
            mira.carey@mongodb.com Mira Carey
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: