[OAK-7485] DocumentNodeStore doesn't work with shared Atlas MongoDB replica set

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 1.9.0
• Fix Version/s: 1.10.0, 1.9.9
• Component/s: documentmk, mongomk
• Assignee: Marcel Reutegger
• Reporter: Tomek Rękawek
• Created: 08/May/18 13:16
• Updated: 12/Oct/18 13:30
• Resolved: 27/Sep/18 08:51

Description

After the Oak switched to using mongo-java-driver 3.6.x, it stopped working with the shared Atlas MongoDB cluster (eg. M2). Following exception is logged:

08.05.2018 13:08:13.881 *ERROR* [FelixStartLevel] org.apache.jackrabbit.oak-store-document bundle org.apache.jackrabbit.oak-store-document:1.9.0 (108)[org.apache.jackrabbit.oak.plugins.document.DocumentNo
deStoreService(224)] : The activate method has thrown an exception (com.mongodb.MongoCommandException: Command failed with error -1: '' on server [redacted]. The full response is { "operationTime" : { "$timestamp" : { "t" : 1525784890, "i" : 2 } }, "ok" : 0.0, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1525784890, "i" : 2 } }, "signature" : { "hash"
: { "$binary" : "Ig9HeiO+kyyQKVzRaUGeqMzspbI=", "$type" : "00" }, "keyId" : { "$numberLong" : "6547663121467572225" } } }, "metrics" : { "atlas" : { "connectionPool" : { "totalCreated" : { "$numberLong" : "56" } }, "bytesInWrites" : { "$numberLong" : "0" } } } })
com.mongodb.MongoCommandException: Command failed with error -1: '' on server [redacted]. The full response is { "operationTime" : { "$timestamp" : { "t" : 152578489
0, "i" : 2 } }, "ok" : 0.0, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1525784890, "i" : 2 } }, "signature" : { "hash" : { "$binary" : "Ig9HeiO+kyyQKVzRaUGeqMzspbI=", "$type" : "00" }, "keyId" : { "$numberLong" : "6547663121467572225" } } }, "metrics" : { "atlas" : { "connectionPool" : { "totalCreated" : { "$numberLong" : "56" } }, "bytesInWrites" : { "$numberLong" : "0" } } } }
        at com.mongodb.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:164) [org.mongodb.mongo-java-driver:3.6.3]                                                                          at com.mongodb.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:295) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:255) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:98) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:441) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:80) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:189) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:264) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.connection.DefaultServerConnection.command(DefaultServerConnection.java:126) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.connection.DefaultServerConnection.command(DefaultServerConnection.java:118) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:226) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:197) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:189) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:99) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:92) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.operation.CommandReadOperation.execute(CommandReadOperation.java:55) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.Mongo$3.execute(Mongo.java:826) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.MongoDatabaseImpl.executeCommand(MongoDatabaseImpl.java:166) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.MongoDatabaseImpl.runCommand(MongoDatabaseImpl.java:138) [org.mongodb.mongo-java-driver:3.6.3]
        at com.mongodb.MongoDatabaseImpl.runCommand(MongoDatabaseImpl.java:133) [org.mongodb.mongo-java-driver:3.6.3]
        at org.apache.jackrabbit.oak.plugins.document.mongo.MongoStatus.getServerStatus(MongoStatus.java:177) [org.apache.jackrabbit.oak-store-document:1.9.0]
        at org.apache.jackrabbit.oak.plugins.document.mongo.MongoStatus.isMajorityReadConcernSupported(MongoStatus.java:91) [org.apache.jackrabbit.oak-store-document:1.9.0]
        at org.apache.jackrabbit.oak.plugins.document.mongo.MongoDocumentNodeStoreBuilderBase.setMongoDB(MongoDocumentNodeStoreBuilderBase.java:92) [org.apache.jackrabbit.oak-store-document:1.9.0]
        at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.registerNodeStore(DocumentNodeStoreService.java:297) [org.apache.jackrabbit.oak-store-document:1.9.0]
        at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.registerNodeStoreIfPossible(DocumentNodeStoreService.java:252) [org.apache.jackrabbit.oak-store-document:1.9.0]
        at org.apache.jackrabbit.oak.plugins.document.DocumentNodeStoreService.activate(DocumentNodeStoreService.java:236) [org.apache.jackrabbit.oak-store-document:1.9.0]

So, it seems that the serverStatus() command fails or doesn't return the required data. Similarly, when using mongo-cli:

$ mongo [redacted]
MongoDB shell version v3.6.4
MongoDB server version: 3.6.4
MongoDB Enterprise [redacted]:PRIMARY> db.serverStatus()
{
        "operationTime" : Timestamp(1525784995, 2),
        "ok" : 0,
        "$clusterTime" : {
                "clusterTime" : Timestamp(1525784995, 2),
                "signature" : {
                        "hash" : BinData(0,"UbUJQri5/e/SsB8lBXmWPMaXwuk="),
                        "keyId" : NumberLong("6547663121467572225")
                }
        },
        "metrics" : {
                "atlas" : {
                        "connectionPool" : {
                                "totalCreated" : NumberLong(56)
                        },
                        "bytesInWrites" : NumberLong(0)
                }
        }
}

The ok field is 0, but there's no error message. What's interesting, when using an older Mongo CLI, the command works fine:

docker run -it --rm mongo:3.4 /bin/bash
root@e3fa93e33d32:/# mongo [redacted]
MongoDB shell version v3.4.14
MongoDB server version: 3.6.4
WARNING: shell and server versions do not match
MongoDB Enterprise [redacted]:PRIMARY> db.serverStatus()
{
        "host" : "[redacted]",
        "version" : "3.6.4",
        "process" : "mongod",
        "pid" : NumberLong(3408),
        "uptime" : 1288779,
        "uptimeMillis" : NumberLong(1288779510),
        "uptimeEstimate" : NumberLong(1288779),
        "localTime" : ISODate("2018-05-08T13:15:48.586Z"),
...