"Server description changed" messages spamming syslog

[Mark Windrim]

I've got a 3 node replica set, which has been in production for some time.  We are running  Mongo v3.4.0 and are utilizing 5.1.6 with Rails 4.2.7.  Lately we've been getting a lot of debug messages posted logs and we're not sure exactly what these messages mean.  I'm only posted a few lines here, but from the timestamp you can see how quickly these are being received.  Our Rails app is running fine.  Anyone have any idea what these messages mean, and why they're happening so frequently?

Thanks.

D, [2016-12-20T19:50:55.330988 #13343] DEBUG -- : MONGODB | Server description for mongo2:27017 changed from 'secondary' to 'secondary'.

D, [2016-12-20T19:50:56.247207 #13343] DEBUG -- : MONGODB | Server description for mongo3:27017 changed from 'secondary' to 'secondary'.

D, [2016-12-20T19:51:05.165716 #13343] DEBUG -- : MONGODB | Server description for mongo1:27017 changed from 'primary' to 'primary'.

D, [2016-12-20T19:51:05.333484 #13343] DEBUG -- : MONGODB | Server description for mongo2:27017 changed from 'secondary' to 'secondary'.

D, [2016-12-20T19:51:06.289857 #13343] DEBUG -- : MONGODB | Server description for mongo3:27017 changed from 'secondary' to 'secondary'.

D, [2016-12-20T19:51:15.168107 #13343] DEBUG -- : MONGODB | Server description for mongo1:27017 changed from 'primary' to 'primary'.

D, [2016-12-20T19:51:15.336534 #13343] DEBUG -- : MONGODB | Server description for mongo2:27017 changed from 'secondary' to 'secondary'.

D, [2016-12-20T19:51:16.332656 #13343] DEBUG -- : MONGODB | Server description for mongo3:27017 changed from 'secondary' to 'secondary'.

D, [2016-12-20T19:51:25.170365 #13343] DEBUG -- : MONGODB | Server description for mongo1:27017 changed from 'primary' to 'primary'.

D, [2016-12-20T19:51:25.338936 #13343] DEBUG -- : MONGODB | Server description for mongo2:27017 changed from 'secondary' to 'secondary'.

D, [2016-12-20T19:51:26.375188 #13343] DEBUG -- : MONGODB | Server description for mongo3:27017 changed from 'secondary' to 'secondary'.

D, [2016-12-20T19:51:35.172453 #13343] DEBUG -- : MONGODB | Server description for mongo1:27017 changed from 'primary' to 'primary'.

D, [2016-12-20T19:51:35.340919 #13343] DEBUG -- : MONGODB | Server description for mongo2:27017 changed from 'secondary' to 'secondary'.

D, [2016-12-20T19:51:36.417557 #13343] DEBUG -- : MONGODB | Server description for mongo3:27017 changed from 'secondary' to 'secondary'.

[Kevin Adistambha]

Hi Mark

Are there any notable event in the MongoDB logs during that period (errors, etc.)? Also, do those messages also appear when using an older version of MongoDB? (3.4.0 was just released on Nov 29, 2016). Those messages don’t appear to be generated by MongoDB.

Otherwise, the DEBUG log level seems to be the most verbose available in Rails (from Log Levels). If you’re certain that they’re erroneous messages generated by Rails, you may be able to change the log level to a higher setting to filter out the DEBUG messages.

Best regards,
Kevin

​

[Mark Windrim]

Hi Kevin,

Thanks for your reply.  There aren't any errors showing up in our logs.  The app appears to be running fine - just get these messages when in dev mode.  I went back through the logs, and don't see any of these messages for the system when we were running a prior version of MongoDB.  

Thanks,

Mark

[Reid Morrison]

We are seeing the same issue after creating a simple replica-set locally. 

My concern after looking into the code is that it is constantly changing the list of nodes that are available, even though nothing has changed.

Running: mongo-ruber-driver master with MongoDB v3.4.2

The following code from the driver shows the behavior that is being called with every log entry:

def handle(previous, updated)
  publish_sdam_event(
    Monitoring::SERVER_DESCRIPTION_CHANGED,
    Monitoring::Event::ServerDescriptionChanged.new(
      updated.address,
      cluster.topology,
      previous,
      updated
    )
  )
  cluster.add_hosts(updated)
  cluster.remove_hosts(updated)
end

Instructions for setting up the test replica-set:

Setup a local MongoDB ReplicaSet

Preparation

Create the directories for the relevant databases

cd ~/Work
mkdir mongotest
mkdir mongotest/rs1
mkdir mongotest/rs2
mkdir mongotest/rs3

In separate terminal windows run all the following commands

Start the replica set servers

mongod --port 7200 --dbpath ~/Work/mongotest/rs1 --replSet local

mongod --port 7201 --dbpath ~/Work/mongotest/rs2 --replSet local

mongod --port 7202 --dbpath ~/Work/mongotest/rs3 --replSet local

Configure the Replica set

We now need to let the master replica set server know about the other servers

Open the mongo shell to administer the routing server (mongos)

mongo localhost:7200/admin

Run the following commands:

c = { "_id" : "local", "members" : [ { "_id" : 1, "host" : "localhost:7200"}, {  "_id" : 2, "host" : "localhost:7201"}, {  "_id" : 3, "host" : "localhost:7202"} ] } 

db.runCommand({'replSetInitiate' : c})

I can submit a PR to ignore the event, or not raise it if the previous and changed are the same?

Thank you,

Reid Morrison

[lychee xing]

Please submit your PR, I've got same issue.

在 2017年2月14日星期二 UTC+8上午12:35:44，Reid Morrison写道：

[Emily S]

Hi all

This is the ticket associated with the issue: https://jira.mongodb.org/browse/RUBY-1223

And Tomoyuki has kindly opened a pull request here: https://github.com/mongodb/mongo-ruby-driver/pull/877

The improvement will go into the next release of the Ruby driver.

Thanks

Emily