MongoDB in a replica set prohibits start of spring application while initial sync is in progress

See original GitHub issue

To migrate some production MongoDBs I opted for using replica sets to minimize downtime. While everything is working when running in standalone mode, things fall apart when switching to a RS with the following config

version: "2.2"
services:
  mongo:
    image: mongo
    volumes:
      - mongo-data:/data/db
      - ./rs-init.sh:/scripts/rs-init.sh:ro
    networks:
      - appNetwork
    ports:
      - ${MONGO_PORT}:27017
    mem_limit: 1500m
    command: --wiredTigerEngineConfigString="cache_size=512M"
    entrypoint: [ "/usr/bin/mongod", "--bind_ip_all", "--replSet", "test" ]
    restart: always

The rs-init.sh script contains the following:

#!/bin/bash

mongo <<EOF
var config = {
    "_id": "test",
    "version": 1,
    "members": [
        {
            "_id": 1,
            "host": "PRIMARY_NODE_IP:PORT",
            "priority": 2
        },
        {
            "_id": 2,
            "host": "HIDDEN_NODE_IP:PORT",
            "priority": 0,
            "hidden": true
        }
    ]
};
rs.initiate(config, { force: true });
EOF

I got it to start syncing. The primary node was in status PRIMARY and the secondary (hidden) node was in STARTUP2. During the initial sync the spring application failed to start with the error:

org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'repositoryMigration' defined in file 
[/app/classes/powerbot/server/m7/repositories/RepositoryMigration.class]: Invocation of init method failed; nested exception is 
org.springframework.data.mongodb.UncategorizedMongoDbException:  Command failed with error 10107 (NotWritablePrimary): 'not 
master' on server mongo:27017. The full response is 
{
    "topologyVersion": {
        "processId": {
            "$oid": "6258476152adc96e0282f334"
        },
        "counter": 7
    },
    "operationTime": {
        "$timestamp": {
            "t": 1649953064,
            "i": 1
        }
    },
    "ok": 0.0,
    "errmsg": "not master",
    "code": 10107,
    "codeName": "NotWritablePrimary",
    "$clusterTime": {
        "clusterTime": {
            "$timestamp": {
                "t": 1649953064,
                "i": 1
            }
        },
        "signature": {
            "hash": {
                "$binary": {
                    "base64": "AAAAAAAAAAAAAAAAAAAAAAAAAAA=",
                    "subType": "00"
                }
            },
            "keyId": 0
        }
    }
}
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1804)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:620)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542)
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:944)
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:918)
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:583)
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:145)
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:754)
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:434)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:338)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1343)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1332)
	at powerbot.server.M7Application.main(M7Application.java:104)
Caused by: org.springframework.data.mongodb.UncategorizedMongoDbException: Command failed with error 10107 (NotWritablePrimary): 'not master' on server mongo:27017. The full response is {"topologyVersion": {"processId": {"$oid": "6258476152adc96e0282f334"}, "counter": 7}, "operationTime": {"$timestamp": {"t": 1649953064, "i": 1}}, "ok": 0.0, "errmsg": "not master", "code": 10107, "codeName": "NotWritablePrimary", "$clusterTime": {"clusterTime": {"$timestamp": {"t": 1649953064, "i": 1}}, "signature": {"hash": {"$binary": {"base64": "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "subType": "00"}}, "keyId": 0}}}; nested exception is com.mongodb.MongoNotPrimaryException: Command failed with error 10107 (NotWritablePrimary): 'not master' on server mongo:27017. The full response is {"topologyVersion": {"processId": {"$oid": "6258476152adc96e0282f334"}, "counter": 7}, "operationTime": {"$timestamp": {"t": 1649953064, "i": 1}}, "ok": 0.0, "errmsg": "not master", "code": 10107, "codeName": "NotWritablePrimary", "$clusterTime": {"clusterTime": {"$timestamp": {"t": 1649953064, "i": 1}}, "signature": {"hash": {"$binary": {"base64": "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "subType": "00"}}, "keyId": 0}}}
	at org.springframework.data.mongodb.core.MongoExceptionTranslator.translateExceptionIfPossible(MongoExceptionTranslator.java:140)
	at org.springframework.data.mongodb.core.MongoTemplate.potentiallyConvertRuntimeException(MongoTemplate.java:2899)
	at org.springframework.data.mongodb.core.MongoTemplate.execute(MongoTemplate.java:555)
	at org.springframework.data.mongodb.core.DefaultIndexOperations.execute(DefaultIndexOperations.java:214)
	at org.springframework.data.mongodb.core.DefaultIndexOperations.ensureIndex(DefaultIndexOperations.java:121)
	at powerbot.server.m7.repositories.RepositoryMigration.migrate(RepositoryMigration.java:31)
	at powerbot.server.core.repositories.migration.MongoRepositoryMigration.afterPropertiesSet(MongoRepositoryMigration.java:30)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1863)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1800)
	... 16 common frames omitted
Caused by: com.mongodb.MongoNotPrimaryException: Command failed with error 10107 (NotWritablePrimary): 'not master' on server mongo:27017. The full response is {"topologyVersion": {"processId": {"$oid": "6258476152adc96e0282f334"}, "counter": 7}, "operationTime": {"$timestamp": {"t": 1649953064, "i": 1}}, "ok": 0.0, "errmsg": "not master", "code": 10107, "codeName": "NotWritablePrimary", "$clusterTime": {"clusterTime": {"$timestamp": {"t": 1649953064, "i": 1}}, "signature": {"hash": {"$binary": {"base64": "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "subType": "00"}}, "keyId": 0}}}
	at com.mongodb.internal.connection.ProtocolHelper.createSpecialException(ProtocolHelper.java:244)
	at com.mongodb.internal.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:171)
	at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:358)
	at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:279)
	at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:100)
	at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:490)
	at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:71)
	at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:253)
	at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:202)
	at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:118)
	at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:110)
	at com.mongodb.internal.operation.CommandOperationHelper.executeWriteCommand(CommandOperationHelper.java:371)
	at com.mongodb.internal.operation.CommandOperationHelper.executeWriteCommand(CommandOperationHelper.java:362)
	at com.mongodb.internal.operation.CommandOperationHelper.executeCommand(CommandOperationHelper.java:286)
	at com.mongodb.internal.operation.CommandOperationHelper.executeCommand(CommandOperationHelper.java:279)
	at com.mongodb.internal.operation.CreateIndexesOperation$1.call(CreateIndexesOperation.java:197)
	at com.mongodb.internal.operation.CreateIndexesOperation$1.call(CreateIndexesOperation.java:192)
	at com.mongodb.internal.operation.OperationHelper.withConnectionSource(OperationHelper.java:650)
	at com.mongodb.internal.operation.OperationHelper.withConnection(OperationHelper.java:612)
	at com.mongodb.internal.operation.CreateIndexesOperation.execute(CreateIndexesOperation.java:192)
	at com.mongodb.internal.operation.CreateIndexesOperation.execute(CreateIndexesOperation.java:72)
	at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:187)
	at com.mongodb.client.internal.MongoCollectionImpl.executeCreateIndexes(MongoCollectionImpl.java:847)
	at com.mongodb.client.internal.MongoCollectionImpl.createIndexes(MongoCollectionImpl.java:830)
	at com.mongodb.client.internal.MongoCollectionImpl.createIndexes(MongoCollectionImpl.java:825)
	at com.mongodb.client.internal.MongoCollectionImpl.createIndex(MongoCollectionImpl.java:810)
	at org.springframework.data.mongodb.core.DefaultIndexOperations.lambda$ensureIndex$0(DefaultIndexOperations.java:131)
	at org.springframework.data.mongodb.core.MongoTemplate.execute(MongoTemplate.java:553)
	... 22 common frames omitted

But the primary node indeed was in state PRIMARY and db.isMaster() returned true as well. I noticed three reoccurring log messages that are sent every 10s:

Apr 14, 2022 @ 18:17:39.279 DEBUG Checking status of mongo:27017
Apr 14, 2022 @ 18:17:39.279 DEBUG Updating cluster description to  {type=REPLICA_SET, servers=[{address=mongo:27017, type=REPLICA_SET_PRIMARY, roundTripTime=4.2 ms, state=CONNECTED}]
Apr 14, 2022 @ 18:17:49.082 DEBUG Sending command '{"ismaster": 1, "$db": "admin", "$clusterTime": {"clusterTime": {"$timestamp": {"t": 1649953054, "i": 1}}, "signature": {"hash": {"$binary": {"base64": "AAAAAAAAAAAAAAAAAAAAAAAAAAA=", "subType": "00"}}, "keyId": 0}}}' with request id 112 to database admin on connection [connectionId{localValue:1, serverValue:17}] to server mongo:27017

But right before spring throws the above exception, there are these odd logs:

Apr 14, 2022 @ 18:18:04.180 DEBUG Updating cluster description to  {type=REPLICA_SET, servers=[{address=mongo:27017, type=REPLICA_SET_SECONDARY, roundTripTime=4.0 ms, state=CONNECTED}]
Apr 14, 2022 @ 18:17:54.193 DEBUG Updating cluster description to  {type=UNKNOWN, servers=[{address=mongo:27017, type=UNKNOWN, state=CONNECTING}]
Apr 14, 2022 @ 18:17:54.173 DEBUG Updating cluster description to  {type=REPLICA_SET, servers=[{address=mongo:27017, type=REPLICA_SET_SECONDARY, roundTripTime=4.0 ms, state=CONNECTED}]

Why is spring updating the cluster description? And why does it not continue to initialize beans while the cluster is not done with the initial sync?

Issue Analytics

  • State:closed
  • Created a year ago
  • Comments:7 (4 by maintainers)

github_iconTop GitHub Comments

1reaction
mp911decommented, Apr 21, 2022

That’s nothing really we can help with as you’re using the MongoDB driver directly and Spring isn’t involved when calling directly MongoDB driver API.

0reactions
samox73commented, Apr 21, 2022

After some further debugging I found that the line

MongoDatabase adminDB = mongoTemplate.getMongoDbFactory().getMongoDatabase("admin");
adminDB.runCommand(new Document("setFeatureCompatibilityVersion", "4.4"));

causes the issue. Without it the application starts just fine. We actually don’t need the statement anymore, so this is not a problem for us, but I’d still like to know why this operation is not supported on a replica set that is doing the initial sync. Thank you for your support!

Read more comments on GitHub >

github_iconTop Results From Across the Web

Replica Set Data Synchronization — MongoDB Manual
Initial sync copies all the data from one member of the replica set to another member. ... This parameter can only be specified...
Read more >
Replica set member not syncing - Replication - MongoDB
Hi, We have a 4.2.6 based replica set running with 3 members. Upon trying to add a 4th member (freshly installed) it will...
Read more >
Rollbacks During Replica Set Failover — MongoDB Manual
A rollback does not occur if the write operations replicate to another member of the replica set before the primary steps down and...
Read more >
Troubleshoot Replica Sets — MongoDB Manual
Check Replica Set Status; Check the Replication Lag; Slow Application of Oplog ... Returns the syncedTo value for each member, which shows the...
Read more >
MongoDB Server Parameters
Available for both mongod and mongos . Specifies the list of authentication mechanisms the server accepts. Set this to one or more of...
Read more >

github_iconTop Related Medium Post

No results found

github_iconTop Related StackOverflow Question

No results found

github_iconTroubleshoot Live Code

Lightrun enables developers to add logs, metrics and snapshots to live code - no restarts or redeploys required.
Start Free

github_iconTop Related Reddit Thread

No results found

github_iconTop Related Hackernoon Post

No results found

github_iconTop Related Tweet

No results found

github_iconTop Related Dev.to Post

No results found

github_iconTop Related Hashnode Post

No results found