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

Driver spams Server description for address changed from 'standalone' to 'standalone' log messages

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Minor - P4 Minor - P4
    • 2.14.0
    • Affects Version/s: 2.13.0
    • Component/s: None
    • Labels:
      None
    • Fully Compatible

      I've successfully reproduce this behavior with mongo 2.13.0, mongoid 7.1.2 and rails 6.0.3, on a newly created app (no changes other than adding mongoid and enabled logging to STDOUT). The MongoDB server is v4.4.1, running in docker container (image mongo:4.4-bionic).

      I'm having an issue where mongo driver is constantly logging server description changed messages, even though the topology and server are not changing. This results in logs being spammed with identical messages on every heartbeat (by default 10 seconds). Here's an example of rails console session where I do nothing except initialize the client:

      # DISABLE_SPRING=1 bin/rails c
Loading development environment (Rails 6.0.3.3)
irb(main):001:0> Mongoid.default_client
D, [2020-10-01T06:19:54.493216 #2189] DEBUG -- : MONGODB | Topology type 'unknown' initializing.
D, [2020-10-01T06:19:54.493395 #2189] DEBUG -- : MONGODB | There was a change in the members of the 'Unknown' topology.
D, [2020-10-01T06:19:54.493485 #2189] DEBUG -- : MONGODB | Server mongo:27017 initializing.
D, [2020-10-01T06:19:54.493737 #2189] DEBUG -- : MONGODB | Waiting for up to 30.00 seconds for servers to be scanned: #<Cluster topology=Unknown[mongo:27017] servers=[#<Server address=mongo:27017 UNKNOWN>]>
D, [2020-10-01T06:19:54.495431 #2189] DEBUG -- : MONGODB | Server description for mongo:27017 changed from 'unknown' to 'standalone'.
D, [2020-10-01T06:19:54.495598 #2189] DEBUG -- : MONGODB | Topology type 'Unknown' changed to type 'Single'.
=> #<Mongo::Client:0x11180 cluster=#<Cluster topology=Single[mongo:27017] servers=[#<Server address=mongo:27017 STANDALONE pool=#<ConnectionPool size=0 (0-5) used=0 avail=0 pending=0>>]>>
irb(main):002:0> 
D, [2020-10-01T06:20:04.505012 #2189] DEBUG -- : MONGODB | Server description for mongo:27017 changed from 'standalone' to 'standalone' [awaited].
D, [2020-10-01T06:20:04.505108 #2189] DEBUG -- : MONGODB | There was a change in the members of the 'Single' topology.
D, [2020-10-01T06:20:14.498466 #2189] DEBUG -- : MONGODB | Server description for mongo:27017 changed from 'standalone' to 'standalone'.
D, [2020-10-01T06:20:14.498690 #2189] DEBUG -- : MONGODB | There was a change in the members of the 'Single' topology.
D, [2020-10-01T06:20:14.515687 #2189] DEBUG -- : MONGODB | Server description for mongo:27017 changed from 'standalone' to 'standalone' [awaited].
D, [2020-10-01T06:20:14.515829 #2189] DEBUG -- : MONGODB | There was a change in the members of the 'Single' topology.
D, [2020-10-01T06:20:24.499621 #2189] DEBUG -- : MONGODB | Server description for mongo:27017 changed from 'standalone' to 'standalone'.
D, [2020-10-01T06:20:24.499707 #2189] DEBUG -- : MONGODB | There was a change in the members of the 'Single' topology.
D, [2020-10-01T06:20:24.525004 #2189] DEBUG -- : MONGODB | Server description for mongo:27017 changed from 'standalone' to 'standalone' [awaited].
D, [2020-10-01T06:20:24.525078 #2189] DEBUG -- : MONGODB | There was a change in the members of the 'Single' topology.
D, [2020-10-01T06:20:34.500602 #2189] DEBUG -- : MONGODB | Server description for mongo:27017 changed from 'standalone' to 'standalone'.
D, [2020-10-01T06:20:34.500695 #2189] DEBUG -- : MONGODB | There was a change in the members of the 'Single' topology.
D, [2020-10-01T06:20:34.535105 #2189] DEBUG -- : MONGODB | Server description for mongo:27017 changed from 'standalone' to 'standalone' [awaited].
D, [2020-10-01T06:20:34.535193 #2189] DEBUG -- : MONGODB | There was a change in the members of the 'Single' topology.
D, [2020-10-01T06:20:44.501745 #2189] DEBUG -- : MONGODB | Server description for mongo:27017 changed from 'standalone' to 'standalone'.
D, [2020-10-01T06:20:44.501846 #2189] DEBUG -- : MONGODB | There was a change in the members of the 'Single' topology.

      This looks like bug in the driver, although I don't have enough internal knowledge to be sure. Here's what I've been able to figure out so far:

      • tracking back execution from the point where Monitoring::TOPOLOGY_CHANGED SDAM even is being published, I've ended up in Mongo::Cluster::SdamFlow#publish_description_change_event
      • in that function the checks fails:
        • topology_effectively_changed? returns true, which results in @need_topology_changed_event being set to true, which later on triggers the logging
      • as far as I understand the code, topology_effectively_changed? should NOT return true in this case (when server or topology doesn't actually change)
        • digging more into this method reveals that the condition @previous_server_descriptions != server_descriptions returns true because old and new server description objects have two fields different: localTime and connectionId

       I do not have enough internal knowledge, so here are my questions:

      • is it expected that multiple connections should be used for SDAM discovery?
      • should topology_effectively_changed? method ignore localTime and connectionId fields?
      • is this a bug or expected behavior? 

        1. mongo_log_spam_debug.log
          11 kB

            Assignee:
            oleg.pudeyev@mongodb.com Oleg Pudeyev (Inactive)
            Reporter:
            kristijan@glooko.com Kristijan Novoselić
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: