MongoDB in a replica set prohibits start of spring application while initial sync is in progress
See original GitHub issueTo 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:
- Created a year ago
- Comments:7 (4 by maintainers)
Top Related StackOverflow Question
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.
After some further debugging I found that the line
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!