[0.20.10] Unable to connect to Atlas database

[Jean-Julien Alvado]

Hi,

In our Play application, we are using ReactiveMongo version '0.20.10' and we connect to an Azure Atlas instance.

Since today, we obtain the following error when trying to connect the to the mongo instance:

reactivemongo.core.actors.Exceptions$PrimaryUnavailableException: MongoError['No primary node is available! (Supervisor-1/Connection-1)']

at play.modules.reactivemongo.DefaultReactiveMongoApi.database(DefaultReactiveMongoApi.scala:71)

at reactivemongo.api.MongoConnection.database(MongoConnection.scala:108)

Caused by: reactivemongo.core.actors.Exceptions$InternalState: 

at reactivemongo.ScramNonceFailure(SCRAM-SHA-1, 1002)(<time:2503888350493069>)

at reactivemongo.ScramNonceFailure(SCRAM-SHA-1, 1001)(<time:2503888349737975>)

at reactivemongo.ScramNonceFailure(SCRAM-SHA-1, 1000)(<time:2503888347766690>)

at reactivemongo.ConnectAll$IsMaster(2, {{NodeSet Some(x-y-z-shard-0) Node[x-y-z-shard-00-01.eqrr2.azure.mongodb.net:27017: Primary (1/1/1 available connections), latency=553257518ns, authenticated={}] | Node[x-y-z-shard-00-00.eqrr2.azure.mongodb.net:27017: Secondary (1/1/1 available connections), latency=726808574ns, authenticated={}] | Node[x-y-z-shard-00-02.eqrr2.azure.mongodb.net:27017: Secondary (1/1/1 available connections), latency=514109021ns, authenticated={}] }})(<time:2503888303833830>)

at reactivemongo.IsMaster(true, 2, {{NodeSet Some(x-y-z-shard-0) Node[x-y-z-shard-00-01.eqrr2.azure.mongodb.net:27017: Unknown (1/1/1 available connections), latency=2503887735910426ns, authenticated={}] | Node[x-y-z-shard-00-00.eqrr2.azure.mongodb.net:27017: Secondary (1/1/1 available connections), latency=726808574ns, authenticated={}] | Node[x-y-z-shard-00-02.eqrr2.azure.mongodb.net:27017: Secondary (1/1/1 available connections), latency=514109021ns, authenticated={}] }})(<time:2503888303271334>)

at reactivemongo.ConnectAll$IsMaster(1, {{NodeSet Some(x-y-z-shard-0) Node[x-y-z-shard-00-02.eqrr2.azure.mongodb.net:27017: Secondary (1/1/1 available connections), latency=514109021ns, authenticated={}] | Node[x-y-z-shard-00-00.eqrr2.azure.mongodb.net:27017: Secondary (1/1/1 available connections), latency=726808574ns, authenticated={}] | Node[x-y-z-shard-00-01.eqrr2.azure.mongodb.net:27017: Unknown (1/1/1 available connections), latency=2503887735910426ns, authenticated={}] }})(<time:2503888255249506>)

at reactivemongo.IsMaster(false, 1, {{NodeSet Some(x-y-z-shard-0) Node[x-y-z-shard-00-02.eqrr2.azure.mongodb.net:27017: Unknown (1/1/1 available connections), latency=2503887729192778ns, authenticated={}] | Node[x-y-z-shard-00-00.eqrr2.azure.mongodb.net:27017: Secondary (1/1/1 available connections), latency=726808574ns, authenticated={}] | Node[x-y-z-shard-00-01.eqrr2.azure.mongodb.net:27017: Unknown (1/1/1 available connections), latency=2503887735910426ns, authenticated={}] }})(<time:2503888254732510>)

at reactivemongo.ConnectAll$IsMaster(0, {{NodeSet Some(x-y-z-shard-0) Node[x-y-z-shard-00-01.eqrr2.azure.mongodb.net:27017: Unknown (1/1/1 available connections), latency=2503887735910426ns, authenticated={}] | Node[x-y-z-shard-00-00.eqrr2.azure.mongodb.net:27017: Secondary (1/1/1 available connections), latency=726808574ns, authenticated={}] | Node[x-y-z-shard-00-02.eqrr2.azure.mongodb.net:27017: Unknown (1/1/1 available connections), latency=2503887729192778ns, authenticated={}] }})(<time:2503888239027032>)

at reactivemongo.IsMaster(false, 0, {{NodeSet None Node[x-y-z-shard-00-01.eqrr2.azure.mongodb.net:27017: Unknown (1/1/1 available connections), latency=2503887735910426ns, authenticated={}] | Node[x-y-z-shard-00-00.eqrr2.azure.mongodb.net:27017: Unknown (1/1/1 available connections), latency=2503887380965474ns, authenticated={}] | Node[x-y-z-shard-00-02.eqrr2.azure.mongodb.net:27017: Unknown (1/1/1 available connections), latency=2503887729192778ns, authenticated={}] }})(<time:2503888231760388>)

at reactivemongo.ChannelConnected(13f831e0, {{NodeSet None Node[x-y-z-shard-00-01.eqrr2.azure.mongodb.net:27017: Unknown (0/0/1 available connections), latency=2503887735910426ns, authenticated={}] | Node[x-y-z-shard-00-00.eqrr2.azure.mongodb.net:27017: Unknown (1/1/1 available connections), latency=2503887380965474ns, authenticated={}] | Node[x-y-z-shard-00-02.eqrr2.azure.mongodb.net:27017: Unknown (1/1/1 available connections), latency=2503887729192778ns, authenticated={}] }})(<time:2503887766864487>)

It seems that the ReactiveMongo is experiencing a ScramNonceFailure.

We switched the authentication mechanism from scarm-sha1 to scram-sha256 but we experienced the same issue.

Any help would be greatly appreciated.

Jean-Julien

[Cédric Chantepie]

Without more information, I can only confirm that ReactiveMongo is working fine with Cosmos: http://reactivemongo.org/releases/1.0/documentation/tutorial/azure-cosmos.html

[Jean-Julien Alvado]

Hi Cedric,

This is not a problem with cosmosdb but with Atlas mongo Service.

We tested the connection string against the mongo client and we can access the mongo instance without any problem.

When we launch our application with the same connection string, we can see that all the nodes of the mongo clustered are correctly retrieved but authentication failed with a ScramNonceException as if the driver was not able to obtain the nonce from the mongo server to actually authenticate.

I started the process of migrating to 1.0 as we needed to do it anyway.

Kind Regards,

Jean-Julien

On 24 Oct 2020, at 12:58, Cédric Chantepie <chantep...@gmail.com> wrote:

Without more information, I can only confirm that ReactiveMongo is working fine with Cosmos: http://reactivemongo.org/releases/1.0/documentation/tutorial/azure-cosmos.html

--
You received this message because you are subscribed to the Google Groups "ReactiveMongo - http://reactivemongo.org" group.
To unsubscribe from this group and stop receiving emails from it, send an email to reactivemong...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/reactivemongo/985b6b2b-c909-43be-bfe4-015024218bdbn%40googlegroups.com.

[Cédric Chantepie]

There is no much more issue with Atlas: http://reactivemongo.org/releases/0.1x/documentation/tutorial/mongodb-atlas.html

[Jean-Julien Alvado]

Hi Cedric,

I know it is supposed to be working. What could raise a ScramNonceException?

Regards

On 24 Oct 2020, at 13:17, Cédric Chantepie <chantep...@gmail.com> wrote:

There is no much more issue with Atlas: http://reactivemongo.org/releases/0.1x/documentation/tutorial/mongodb-atlas.html

To view this discussion on the web visit https://groups.google.com/d/msgid/reactivemongo/0ff33661-57d4-497a-b917-af7621d9cf98n%40googlegroups.com.

[Cédric Chantepie]

Bad credentials or bad authentication mode

You received this message because you are subscribed to a topic in the Google Groups "ReactiveMongo - http://reactivemongo.org" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/reactivemongo/eKaMx9E3PMc/unsubscribe.
To unsubscribe from this group and all its topics, send an email to reactivemong...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/reactivemongo/EAE929DC-287C-418C-B6E9-79A5F3C61156%40evertrust.fr.

[Alexandre Aufrere]

Hello Cedric,

Just to let you know:

- it's not working as well with latest drivers

- from the same container, it works using mongo client

Of course it's working perfectly well in our test environment...

If you have any further idea, that would be splendid

Regards,

Alexandre

[Jean-Julien Alvado]

Hello Cedric,

We upgraded to ReactiveMongo 1.0.0 and we are still getting the same behaviour (we managed to reproduce the problem we have with one of our client.

When we deploy our application on a VM/server (IaaS) the application can access the Mongo database without any issue (tested with Atlas and local instance).

When we access the database with the same connection string, it works perfectly.

When we deploy our application within a Kubernetes pod, we cannot access the database (test with Atlas and a local mongodb instance running in the same pod) and we obtain the ScramNonceException.

Here are the logs when deploying the application within minikube:

```

 _  __                _        ______

| |/ /               | |       \ \ \ \

| ' / __ _ _ __   ___| | __ _   \ \ \ \

|  < / _` | '_ \ / _ \ |/ _` |   ) ) ) )

| . \ (_| | | | |  __/ | (_| |  / / / /

|_|\_\__,_|_| |_|\___|_|\__,_| /_/_/_/

                              

==============================

[32;1mRunning with Kanela, the Kamon Instrumentation Agent :: (v1.0.6) [0m

WARNING: An illegal reflective access operation has occurred

WARNING: Illegal reflective access by com.google.inject.internal.cglib.core.$ReflectUtils$1 (file:/tap-proxy/lib/com.google.inject.guice-4.2.3.jar) to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain)

WARNING: Please consider reporting this to the maintainers of com.google.inject.internal.cglib.core.$ReflectUtils$1

WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations

WARNING: All illegal access operations will be denied in a future release

[ [36mdebug [0m] p.a.l.c.ActorSystemProvider - undefined - Starting application default Akka system: application

[ [36mdebug [0m] p.m.r.DefaultReactiveMongoApi - undefined - Resolving database 'tap-proxy' ... (URI(List((evtqa-shard-00-01-w3s6s.mongodb.net,27017), (evtqa-shard-00-02-w3s6s.mongodb.net,27017), (evtqa-shard-00-00-w3s6s.mongodb.net,27017)),MongoConnectionOptions { appName: <undefined>, authenticationMechanism: SCRAM-SHA-1, nbChannelsPerNode: 10, maxInFlightRequestsPerChannel: 200, minIdleChannelsPerNode: 1, heartbeatFrequencyMS: 10000ms, connectTimeoutMS: 0ms, maxIdleTimeMS: 0ms, tcpNoDelay: false, keepAlive: false, sslEnabled: true, sslAllowsInvalidCert: false, writeConcern: WriteConcern(WaitForAcknowledgments(1),false,false,None), readPreference: Primary, readConcern: local },List(),tap-proxy))

[ [37minfo [0m] r.api.Driver - undefined - No mongo-async-driver configuration found

[ [37minfo [0m] r.api.Driver - undefined - [Supervisor-1] Creating connection: tap-proxy

[ [36mdebug [0m] r.api.Driver - undefined - [Supervisor-1] Add connection to the supervisor: tap-proxy

[ [36mdebug [0m] r.a.MongoConnection - undefined - [Supervisor-1/tap-proxy] Waiting is available...

[ [37minfo [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] Starting the MongoDBSystem

[ [36mdebug [0m] r.i.n.u.i.l.InternalLoggerFactory - undefined - Using SLF4J as the default logging framework

[ [36mdebug [0m] r.c.netty.Pack - undefined - Cannot use Netty KQueue (shaded: true)

java.lang.ClassNotFoundException: reactivemongo.io.netty.channel.kqueue.KQueueSocketChannel

at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:581)

at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:178)

at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:521)

at java.base/java.lang.Class.forName0(Native Method)

at java.base/java.lang.Class.forName(Class.java:315)

at reactivemongo.core.netty.Pack$.kqueue(Pack.scala:60)

at reactivemongo.core.netty.Pack$.apply(Pack.scala:45)

at reactivemongo.core.netty.ChannelFactory.<init>(ChannelFactory.scala:47)

at reactivemongo.core.actors.StandardDBSystem.newChannelFactory(MongoDBSystem.scala:1766)

at reactivemongo.core.actors.MongoDBSystem.preStart(MongoDBSystem.scala:325)

[ [36mdebug [0m] r.c.netty.Pack - undefined - Cannot use Netty EPoll (shaded: true)

java.lang.ClassNotFoundException: reactivemongo.io.netty.channel.epoll.EpollSocketChannel

at java.base/jdk.internal.loader.BuiltinClassLoader.loadClass(BuiltinClassLoader.java:581)

at java.base/jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(ClassLoaders.java:178)

at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:521)

at java.base/java.lang.Class.forName0(Native Method)

at java.base/java.lang.Class.forName(Class.java:315)

at reactivemongo.core.netty.Pack$.epoll(Pack.scala:86)

at reactivemongo.core.netty.Pack$.$anonfun$apply$1(Pack.scala:45)

at scala.Option.orElse(Option.scala:477)

at reactivemongo.core.netty.Pack$.apply(Pack.scala:45)

at reactivemongo.core.netty.ChannelFactory.<init>(ChannelFactory.scala:47)

[ [37minfo [0m] r.c.netty.Pack - undefined - Instantiated reactivemongo.core.netty.Pack

[ [36mdebug [0m] r.i.n.c.MultithreadEventLoopGroup - undefined - -Dio.netty.eventLoopThreads: 2

[ [36mdebug [0m] r.i.n.u.i.InternalThreadLocalMap - undefined - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024

[ [36mdebug [0m] r.i.n.u.i.InternalThreadLocalMap - undefined - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096

[ [36mdebug [0m] r.i.n.c.n.NioEventLoop - undefined - -Dio.netty.noKeySetOptimization: false

[ [36mdebug [0m] r.i.n.c.n.NioEventLoop - undefined - -Dio.netty.selectorAutoRebuildThreshold: 512

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent0 - undefined - -Dio.netty.noUnsafe: false

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent0 - undefined - Java version: 11

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent0 - undefined - sun.misc.Unsafe.theUnsafe: available

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent0 - undefined - sun.misc.Unsafe.copyMemory: available

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent0 - undefined - java.nio.Buffer.address: available

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent0 - undefined - direct buffer constructor: unavailable

java.lang.UnsupportedOperationException: Reflective setAccessible(true) disabled

at reactivemongo.io.netty.util.internal.ReflectionUtil.trySetAccessible(ReflectionUtil.java:31)

at reactivemongo.io.netty.util.internal.PlatformDependent0$4.run(PlatformDependent0.java:225)

at java.base/java.security.AccessController.doPrivileged(Native Method)

at reactivemongo.io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:219)

at reactivemongo.io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:289)

at reactivemongo.io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:92)

at reactivemongo.io.netty.channel.nio.NioEventLoop.newTaskQueue0(NioEventLoop.java:279)

at reactivemongo.io.netty.channel.nio.NioEventLoop.newTaskQueue(NioEventLoop.java:150)

at reactivemongo.io.netty.channel.nio.NioEventLoop.<init>(NioEventLoop.java:138)

at reactivemongo.io.netty.channel.nio.NioEventLoopGroup.newChild(NioEventLoopGroup.java:146)

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent0 - undefined - java.nio.Bits.unaligned: available, true

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent0 - undefined - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable

java.lang.IllegalAccessException: class reactivemongo.io.netty.util.internal.PlatformDependent0$6 cannot access class jdk.internal.misc.Unsafe (in module java.base) because module java.base does not export jdk.internal.misc to unnamed module @25214797

at java.base/jdk.internal.reflect.Reflection.newIllegalAccessException(Reflection.java:361)

at java.base/java.lang.reflect.AccessibleObject.checkAccess(AccessibleObject.java:591)

at java.base/java.lang.reflect.Method.invoke(Method.java:558)

at reactivemongo.io.netty.util.internal.PlatformDependent0$6.run(PlatformDependent0.java:335)

at java.base/java.security.AccessController.doPrivileged(Native Method)

at reactivemongo.io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:326)

at reactivemongo.io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:289)

at reactivemongo.io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:92)

at reactivemongo.io.netty.channel.nio.NioEventLoop.newTaskQueue0(NioEventLoop.java:279)

at reactivemongo.io.netty.channel.nio.NioEventLoop.newTaskQueue(NioEventLoop.java:150)

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent0 - undefined - java.nio.DirectByteBuffer.<init>(long, int): unavailable

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent - undefined - sun.misc.Unsafe: available

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent - undefined - maxDirectMemory: 1512374272 bytes (maybe)

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent - undefined - -Dio.netty.tmpdir: /tmp (java.io.tmpdir)

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent - undefined - -Dio.netty.bitMode: 64 (sun.arch.data.model)

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent - undefined - -Dio.netty.maxDirectMemory: -1 bytes

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent - undefined - -Dio.netty.uninitializedArrayAllocationThreshold: -1

[ [36mdebug [0m] r.i.n.u.i.CleanerJava9 - undefined - java.nio.ByteBuffer.cleaner(): available

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent - undefined - -Dio.netty.noPreferDirect: false

[ [36mdebug [0m] r.i.n.u.i.PlatformDependent - undefined - org.jctools-core.MpscChunkedArrayQueue: available

[ [36mdebug [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] Initial node set: {{NodeSet None Node[evtqa-shard-00-01-w3s6s.mongodb.net:27017: Unknown (0/0/0 available connections), latency=9223372036854775807ns, authenticated={}] | Node[evtqa-shard-00-02-w3s6s.mongodb.net:27017: Unknown (0/0/0 available connections), latency=9223372036854775807ns, authenticated={}] | Node[evtqa-shard-00-00-w3s6s.mongodb.net:27017: Unknown (0/0/0 available connections), latency=9223372036854775807ns, authenticated={}] }}

[ [36mdebug [0m] r.i.n.c.DefaultChannelId - undefined - -Dio.netty.processId: 1 (auto-detected)

[ [36mdebug [0m] r.i.n.u.NetUtil - undefined - -Djava.net.preferIPv4Stack: false

[ [36mdebug [0m] r.i.n.u.NetUtil - undefined - -Djava.net.preferIPv6Addresses: false

[ [36mdebug [0m] r.i.n.u.NetUtil - undefined - Loopback interface: lo (lo, 127.0.0.1)

[ [36mdebug [0m] r.i.n.u.NetUtil - undefined - /proc/sys/net/core/somaxconn: 128

[ [36mdebug [0m] r.i.n.c.DefaultChannelId - undefined - -Dio.netty.machineId: 02:42:ac:ff:fe:11:00:05 (auto-detected)

[ [36mdebug [0m] r.i.n.u.ResourceLeakDetector - undefined - -Dreactivemongo.io.netty.leakDetection.level: simple

[ [36mdebug [0m] r.i.n.u.ResourceLeakDetector - undefined - -Dreactivemongo.io.netty.leakDetection.targetRecords: 4

[ [36mdebug [0m] r.i.n.b.PooledByteBufAllocator - undefined - -Dio.netty.allocator.numHeapArenas: 2

[ [36mdebug [0m] r.i.n.b.PooledByteBufAllocator - undefined - -Dio.netty.allocator.numDirectArenas: 2

[ [36mdebug [0m] r.i.n.b.PooledByteBufAllocator - undefined - -Dio.netty.allocator.pageSize: 8192

[ [36mdebug [0m] r.i.n.b.PooledByteBufAllocator - undefined - -Dio.netty.allocator.maxOrder: 11

[ [36mdebug [0m] r.i.n.b.PooledByteBufAllocator - undefined - -Dio.netty.allocator.chunkSize: 16777216

[ [36mdebug [0m] r.i.n.b.PooledByteBufAllocator - undefined - -Dio.netty.allocator.tinyCacheSize: 512

[ [36mdebug [0m] r.i.n.b.PooledByteBufAllocator - undefined - -Dio.netty.allocator.smallCacheSize: 256

[ [36mdebug [0m] r.i.n.b.PooledByteBufAllocator - undefined - -Dio.netty.allocator.normalCacheSize: 64

[ [36mdebug [0m] r.i.n.b.PooledByteBufAllocator - undefined - -Dio.netty.allocator.maxCachedBufferCapacity: 32768

[ [36mdebug [0m] r.i.n.b.PooledByteBufAllocator - undefined - -Dio.netty.allocator.cacheTrimInterval: 8192

[ [36mdebug [0m] r.i.n.b.PooledByteBufAllocator - undefined - -Dio.netty.allocator.cacheTrimIntervalMillis: 0

[ [36mdebug [0m] r.i.n.b.PooledByteBufAllocator - undefined - -Dio.netty.allocator.useCacheForAllThreads: true

[ [36mdebug [0m] r.i.n.b.PooledByteBufAllocator - undefined - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023

[ [36mdebug [0m] r.i.n.b.ByteBufUtil - undefined - -Dio.netty.allocator.type: pooled

[ [36mdebug [0m] r.i.n.b.ByteBufUtil - undefined - -Dio.netty.threadLocalDirectBufferSize: 0

[ [36mdebug [0m] r.i.n.b.ByteBufUtil - undefined - -Dio.netty.maxThreadLocalCharBufferSize: 16384

[ [36mdebug [0m] r.c.n.ChannelFactory - undefined - [Supervisor-1/tap-proxy] Initializing channel 701f4404 to evtqa-shard-00-01-w3s6s.mongodb.net:27017 (Actor[akka://reactivemongo/user/tap-proxy#1622109772])

[ [36mdebug [0m] r.c.n.ChannelFactory - undefined - [Supervisor-1/tap-proxy] Created new channel #701f4404 to evtqa-shard-00-01-w3s6s.mongodb.net:27017 (registered = true)

[ [36mdebug [0m] r.c.n.ChannelFactory - undefined - [Supervisor-1/tap-proxy] Created new channel #8b204a61 to evtqa-shard-00-02-w3s6s.mongodb.net:27017 (registered = false)

[ [36mdebug [0m] r.c.n.ChannelFactory - undefined - [Supervisor-1/tap-proxy] Created new channel #b245c428 to evtqa-shard-00-00-w3s6s.mongodb.net:27017 (registered = false)

[ [36mdebug [0m] r.c.n.ChannelFactory - undefined - [Supervisor-1/tap-proxy] Created new channel #7c9330e9 to evtqa-shard-00-01-w3s6s.mongodb.net:27017 (registered = false)

[ [36mdebug [0m] r.c.n.ChannelFactory - undefined - [Supervisor-1/tap-proxy] Created new channel #b1155c42 to evtqa-shard-00-02-w3s6s.mongodb.net:27017 (registered = false)

[ [36mdebug [0m] r.c.n.ChannelFactory - undefined - [Supervisor-1/tap-proxy] Created new channel #6b5d0d2c to evtqa-shard-00-00-w3s6s.mongodb.net:27017 (registered = false)

[ [36mdebug [0m] r.c.n.ChannelFactory - undefined - [Supervisor-1/tap-proxy] Initializing channel 8b204a61 to evtqa-shard-00-02-w3s6s.mongodb.net:27017 (Actor[akka://reactivemongo/user/tap-proxy#1622109772])

[ [36mdebug [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] Register monitor Actor[akka://reactivemongo/user/Monitor-tap-proxy#685956689]

[ [36mdebug [0m] p.m.r.DefaultReactiveMongoApi - undefined - Resolving database 'tap-proxy' ... (URI(List((evtqa-shard-00-01-w3s6s.mongodb.net,27017), (evtqa-shard-00-02-w3s6s.mongodb.net,27017), (evtqa-shard-00-00-w3s6s.mongodb.net,27017)),MongoConnectionOptions { appName: <undefined>, authenticationMechanism: SCRAM-SHA-1, nbChannelsPerNode: 10, maxInFlightRequestsPerChannel: 200, minIdleChannelsPerNode: 1, heartbeatFrequencyMS: 10000ms, connectTimeoutMS: 0ms, maxIdleTimeMS: 0ms, tcpNoDelay: false, keepAlive: false, sslEnabled: true, sslAllowsInvalidCert: false, writeConcern: WriteConcern(WaitForAcknowledgments(1),false,false,None), readPreference: Primary, readConcern: local },List(),tap-proxy))

[ [36mdebug [0m] r.a.MongoConnection - undefined - [Supervisor-1/tap-proxy] Waiting is available...

[ [36mdebug [0m] p.m.r.DefaultReactiveMongoApi - undefined - Resolving database 'tap-proxy' ... (URI(List((evtqa-shard-00-01-w3s6s.mongodb.net,27017), (evtqa-shard-00-02-w3s6s.mongodb.net,27017), (evtqa-shard-00-00-w3s6s.mongodb.net,27017)),MongoConnectionOptions { appName: <undefined>, authenticationMechanism: SCRAM-SHA-1, nbChannelsPerNode: 10, maxInFlightRequestsPerChannel: 200, minIdleChannelsPerNode: 1, heartbeatFrequencyMS: 10000ms, connectTimeoutMS: 0ms, maxIdleTimeMS: 0ms, tcpNoDelay: false, keepAlive: false, sslEnabled: true, sslAllowsInvalidCert: false, writeConcern: WriteConcern(WaitForAcknowledgments(1),false,false,None), readPreference: Primary, readConcern: local },List(),tap-proxy))

[ [36mdebug [0m] r.a.MongoConnection - undefined - [Supervisor-1/tap-proxy] Waiting is available...

[ [36mdebug [0m] p.m.r.DefaultReactiveMongoApi - undefined - Resolving database 'tap-proxy' ... (URI(List((evtqa-shard-00-01-w3s6s.mongodb.net,27017), (evtqa-shard-00-02-w3s6s.mongodb.net,27017), (evtqa-shard-00-00-w3s6s.mongodb.net,27017)),MongoConnectionOptions { appName: <undefined>, authenticationMechanism: SCRAM-SHA-1, nbChannelsPerNode: 10, maxInFlightRequestsPerChannel: 200, minIdleChannelsPerNode: 1, heartbeatFrequencyMS: 10000ms, connectTimeoutMS: 0ms, maxIdleTimeMS: 0ms, tcpNoDelay: false, keepAlive: false, sslEnabled: true, sslAllowsInvalidCert: false, writeConcern: WriteConcern(WaitForAcknowledgments(1),false,false,None), readPreference: Primary, readConcern: local },List(),tap-proxy))

[ [36mdebug [0m] r.a.MongoConnection - undefined - [Supervisor-1/tap-proxy] Waiting is available...

[ [37minfo [0m] m.TAPService - undefined - [TAPService] version: 1.8.3

[ [37minfo [0m] m.TAPService - undefined - [TAPService] cert-factory version: 2.0.5

[ [37minfo [0m] m.TAPService - undefined - [TAPService] pki-connectors version: 1.5.1

[ [37minfo [0m] m.TAPService - undefined - [TAPService] racs-connectors version: 1.3.0

[ [37minfo [0m] m.TAPService - undefined - [TAPService] license expiration: 'Thu Apr 06 00:00:00 GMT 2119'

[ [37minfo [0m] m.TAPService - undefined - [TAPService] entitled pki-connector(s): 'pki-connectors-awsacmpca', 'pki-connectors-digicert', 'pki-connectors-ejbca', 'pki-connectors-fcms', 'pki-connectors-integrated', 'pki-connectors-msadcs', 'pki-connectors-nexuscm', 'pki-connectors-otpki'

[ [37minfo [0m] m.TAPService - undefined - [TAPService] entitled module(s): 'acme-proxy', 'intune-recovery', 'ocspd', 'ocspd-pkcs11', 'racs-aws', 'racs-azure', 'racs-f5client', 'racs-intune', 'racs-jamf', 'scanner', 'scep-proxy', 'wcce-proxy

'

[ [36mdebug [0m] r.c.n.ChannelFactory - undefined - [Supervisor-1/tap-proxy] Initializing channel 7c9330e9 to evtqa-shard-00-01-w3s6s.mongodb.net:27017 (Actor[akka://reactivemongo/user/tap-proxy#1622109772])

[ [36mdebug [0m] r.c.n.ChannelFactory - undefined - [Supervisor-1/tap-proxy] Initializing channel b245c428 to evtqa-shard-00-00-w3s6s.mongodb.net:27017 (Actor[akka://reactivemongo/user/tap-proxy#1622109772])

[ [36mdebug [0m] r.c.n.ChannelFactory - undefined - [Supervisor-1/tap-proxy] Initializing channel 6b5d0d2c to evtqa-shard-00-00-w3s6s.mongodb.net:27017 (Actor[akka://reactivemongo/user/tap-proxy#1622109772])

[ [36mdebug [0m] r.c.n.ChannelFactory - undefined - [Supervisor-1/tap-proxy] Initializing channel b1155c42 to evtqa-shard-00-02-w3s6s.mongodb.net:27017 (Actor[akka://reactivemongo/user/tap-proxy#1622109772])

[ [36mdebug [0m] r.i.n.u.Recycler - undefined - -Dio.netty.recycler.maxCapacityPerThread: 4096

[ [36mdebug [0m] r.i.n.u.Recycler - undefined - -Dio.netty.recycler.maxSharedCapacityFactor: 2

[ [36mdebug [0m] r.i.n.u.Recycler - undefined - -Dio.netty.recycler.linkCapacity: 16

[ [36mdebug [0m] r.i.n.u.Recycler - undefined - -Dio.netty.recycler.ratio: 8

[ [36mdebug [0m] r.i.n.b.AbstractByteBuf - undefined - -Dreactivemongo.io.netty.buffer.checkAccessible: true

[ [36mdebug [0m] r.i.n.b.AbstractByteBuf - undefined - -Dreactivemongo.io.netty.buffer.checkBounds: true

[ [36mdebug [0m] r.i.n.u.ResourceLeakDetectorFactory - undefined - Loaded default ResourceLeakDetector: reactivemongo.io.netty.util.ResourceLeakDetector@7ce55dfd

[ [36mdebug [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] Prepares a fresh IsMaster request to Node[evtqa-shard-00-01-w3s6s.mongodb.net:27017: Unknown (0/0/1 available connections), latency=9223372036854775807ns, authenticated={}] (channel #701f4404@/172.17.0.5:59982)

[ [36mdebug [0m] r.i.n.h.s.SslHandler - undefined - [id: 0x701f4404, L:/172.17.0.5:59982 - R:evtqa-shard-00-01-w3s6s.mongodb.net/52.57.72.11:27017] HANDSHAKEN: TLS_AES_128_GCM_SHA256

[ [36mdebug [0m] r.i.n.h.s.SslHandler - undefined - [id: 0x8b204a61, L:/172.17.0.5:56572 - R:evtqa-shard-00-02-w3s6s.mongodb.net/52.29.145.53:27017] HANDSHAKEN: TLS_AES_128_GCM_SHA256

[ [36mdebug [0m] r.i.n.h.s.SslHandler - undefined - [id: 0x8b204a61, L:/172.17.0.5:56572 - R:evtqa-shard-00-02-w3s6s.mongodb.net/52.29.145.53:27017] HANDSHAKEN: TLS_AES_128_GCM_SHA256

[ [36mdebug [0m] r.i.n.h.s.SslHandler - undefined - [id: 0x701f4404, L:/172.17.0.5:59982 - R:evtqa-shard-00-01-w3s6s.mongodb.net/52.57.72.11:27017] HANDSHAKEN: TLS_AES_128_GCM_SHA256

[ [36mdebug [0m] r.i.n.h.s.SslHandler - undefined - [id: 0x7c9330e9, L:/172.17.0.5:59988 - R:evtqa-shard-00-01-w3s6s.mongodb.net/52.57.72.11:27017] HANDSHAKEN: TLS_AES_128_GCM_SHA256

[ [36mdebug [0m] r.i.n.h.s.SslHandler - undefined - [id: 0x7c9330e9, L:/172.17.0.5:59988 - R:evtqa-shard-00-01-w3s6s.mongodb.net/52.57.72.11:27017] HANDSHAKEN: TLS_AES_128_GCM_SHA256

[ [36mdebug [0m] r.i.n.h.s.SslHandler - undefined - [id: 0xb1155c42, L:/172.17.0.5:56580 - R:evtqa-shard-00-02-w3s6s.mongodb.net/52.29.145.53:27017] HANDSHAKEN: TLS_AES_128_GCM_SHA256

[ [36mdebug [0m] r.i.n.h.s.SslHandler - undefined - [id: 0xb1155c42, L:/172.17.0.5:56580 - R:evtqa-shard-00-02-w3s6s.mongodb.net/52.29.145.53:27017] HANDSHAKEN: TLS_AES_128_GCM_SHA256

[ [36mdebug [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] Prepares a fresh IsMaster request to Node[evtqa-shard-00-02-w3s6s.mongodb.net:27017: Unknown (0/0/1 available connections), latency=9223372036854775807ns, authenticated={}] (channel #8b204a61@/172.17.0.5:56572)

[ [36mdebug [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] Do not prepare a isMaster request to already probed evtqa-shard-00-01-w3s6s.mongodb.net:27017

[ [36mdebug [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] Do not prepare a isMaster request to already probed evtqa-shard-00-02-w3s6s.mongodb.net:27017

[ [36mdebug [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] Prepares a fresh IsMaster request to Node[evtqa-shard-00-00-w3s6s.mongodb.net:27017: Unknown (1/1/1 available connections), latency=9223372036854775807ns, authenticated={}] (channel #b245c428@/172.17.0.5:60584)

[ [36mdebug [0m] r.i.n.h.s.SslHandler - undefined - [id: 0x6b5d0d2c, L:/172.17.0.5:60588 - R:evtqa-shard-00-00-w3s6s.mongodb.net/3.124.232.225:27017] HANDSHAKEN: TLS_AES_128_GCM_SHA256

[ [36mdebug [0m] r.i.n.h.s.SslHandler - undefined - [id: 0x6b5d0d2c, L:/172.17.0.5:60588 - R:evtqa-shard-00-00-w3s6s.mongodb.net/3.124.232.225:27017] HANDSHAKEN: TLS_AES_128_GCM_SHA256

[ [36mdebug [0m] r.i.n.h.s.SslHandler - undefined - [id: 0xb245c428, L:/172.17.0.5:60584 - R:evtqa-shard-00-00-w3s6s.mongodb.net/3.124.232.225:27017] HANDSHAKEN: TLS_AES_128_GCM_SHA256

[ [36mdebug [0m] r.i.n.h.s.SslHandler - undefined - [id: 0xb245c428, L:/172.17.0.5:60584 - R:evtqa-shard-00-00-w3s6s.mongodb.net/3.124.232.225:27017] HANDSHAKEN: TLS_AES_128_GCM_SHA256

[ [36mdebug [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] The node set is available (Set(evtqa-shard-00-01-w3s6s.mongodb.net:27017)); Waiting authentication: Set()

[ [36mdebug [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] The node set is available (Set(evtqa-shard-00-02-w3s6s.mongodb.net:27017)); Waiting authentication: Set()

[ [36mdebug [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] The node set is available (Set(evtqa-shard-00-00-w3s6s.mongodb.net:27017)); Waiting authentication: Set()

[ [33mwarn [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] Fails to process SCRAM-SHA-1 nonce for 1000

reactivemongo.api.commands.FailedAuthentication$$anon$1: CommandException['null']

[ [36mdebug [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] No pending authentication is matching response: Authenticate(tap-proxy, aauapp)

[ [33mwarn [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] Fails to process SCRAM-SHA-1 nonce for 1001

reactivemongo.api.commands.FailedAuthentication$$anon$1: CommandException['null']

[ [36mdebug [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] No pending authentication is matching response: Authenticate(tap-proxy, aauapp)

[ [33mwarn [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] Fails to process SCRAM-SHA-1 nonce for 1002

reactivemongo.api.commands.FailedAuthentication$$anon$1: CommandException['null']

[ [36mdebug [0m] r.c.a.MongoDBSystem - undefined - [Supervisor-1/tap-proxy] No pending authentication is matching response: Authenticate(tap-proxy, aauapp)

```

Any help would be greatly appreciated.

Kind Regards,

[Carlos Saltos]

I think you have an error with your JVM ... which version you are using ?

I test this with OpenJDK 11 on Debian Linux and it can connect to MongoDB 4.0 without problems using ReactiveMongo 1.0.0

By the way, also the version of Netty here is critical, please check any dependencies evictions from other third parties like HTTP clients.

The Akka should also be aligned, please check you are using version 2.6.10 or at least 2.5.25 which is also compatible with ReactiveMongo 1.0.0

Adicionalmente as Cedric mentioned, it's important to have the Future calls running as def calls and not as val declarations (if you use val for accessing the collections then the system will fail on a MongoDB cluster rotation or any other change or upgrade in the system).

Best regards,

Carlos Saltos

To view this discussion on the web visit https://groups.google.com/d/msgid/reactivemongo/2dfc54cb-a93c-48d2-bd27-990e3c4b7934n%40googlegroups.com.

[Cédric Chantepie]

Netty is shaded by default, so there is no need to evict it from elsewhere (except if you use the -noshaded version, but they are for expert only).

[Carlos Saltos]

Great, good to know Cédric, thanks !!

Now I'm able to reproduce the invalid node status error on my environment.

There are tons of logs messages appearing like this ->

WAR 2020-11-13 18:37:49,930 reactivemongo.core.actors.MongoDBSystem - [Supervisor-1/Connection-14] Invali
d node status Primary for mongo01 (expected: Uninitialized); Fallback to Unknown status

There are so many that the client crashes in around 10 minutes.

I will try to narrow down more and more the error and create a minimal reproducible environment for trying to hunt this bug.

So far ->

ReactiveMongo 1.0.0

Scala 2.12.11

Java Oracle JDK 1.8.0_251

Debian Linux 9

MongoDB 4.0.20 with 3 nodes is replica set

Best regards,

Carlos Saltos

To view this discussion on the web visit https://groups.google.com/d/msgid/reactivemongo/b96c3136-a25f-4943-8a36-27cb302071d6n%40googlegroups.com.

[Alexandre Aufrere]

Hi Carlos,

Answering for Jean-Julien.

We're using gcr.io/distroless/java:11 as base image, which AFAIK means Debian 9 and java 11.0.6.

As for Akka, it's 2.6.5. We in fact use Play Framework 2.8.2 for now.

Best Regards,

Alexandre

[Carlos Saltos]

Thanks for the info Alexander. We use Java 8 ... but I will try with Java 11 on my environment to check if it crashes on the same errors ... anyway I think it can be solved with Java 11 instructing the JVM to allow unsafe operations ... let’s see !!

Best regards,

Carlos Saltos

To view this discussion on the web visit https://groups.google.com/d/msgid/reactivemongo/76594f37-e3b0-4936-bac8-feacbd64e0ffn%40googlegroups.com.

[Alexandre Aufrere]

Hi Carlos,

We managed to make it work by changing the declarations from val to def, adding dependencies so that now we have:

  "com.typesafe.akka" %% "akka-cluster-typed" % akkaVersion,

  "com.typesafe.akka" %% "akka-cluster-tools" % akkaVersion,

  "com.typesafe.akka" %% "akka-cluster-sharding" % akkaVersion,

  "com.typesafe.akka" %% "akka-discovery" % akkaVersion,

  "com.typesafe.akka" %% "akka-protobuf" % akkaVersion,

  "com.typesafe.akka" %% "akka-http" % akkaHttpVersion,

  "com.typesafe.akka" %% "akka-http-spray-json" % akkaHttpVersion,

  "com.lightbend.akka.management" %% "akka-management-cluster-http" % akkaManagementVersion,

  "com.lightbend.akka.management" %% "akka-management-cluster-bootstrap" % akkaManagementVersion

this being on top of the play2-reactivemongo dependency. akkaVersion is positioned manually depending on Play's dependency, and we use currently akkaManagementVersion 1.0.9.

It also seems that, under some circumstances, we get the same stack trace when there are DNS-related issues.

Thanks a lot for your help!

Best regards,

Alexandre

[Cédric Chantepie]

On Monday, 16 November 2020 at 16:20:07 UTC+1 Alexandre Aufrere wrote:

Hi Carlos,

We managed to make it work by changing the declarations from val to def, adding dependencies so that now we have:

Note that as indicated,  the linter rule raise warning for such code smell: scalafix ReactiveMongoLinter --check

[Carlos Saltos]

Great, I’m glad dear Alexander !!

Thank you Cedric for tip ... now with the ReactiveMongo scalafix we are able to use MongoDB correctly in cluster mode ... thanks for that ... we even have Netty native active on our Linux servers and the connections are flying !!!!!!!!!!! ... ReactiveMongo is a great tool !! 👍😎

Best regards and thanks for all,

Carlos Saltos

To view this discussion on the web visit https://groups.google.com/d/msgid/reactivemongo/04539aac-c351-4b58-b187-8e0e0c86daben%40googlegroups.com.

[Jean-Julien Alvado]

Hi Cedric,

We will try to run scalafix.

As we are using Scala 2.13, how can we use then tool as the documentation states that it only supports Scala 2.12?

Kind Regards,

Jean-Julien Alvado Co Founder EverTrust m: +33650871234 e: j...@evertrust.fr

To view this discussion on the web visit https://groups.google.com/d/msgid/reactivemongo/CA%2BZgnSYNc1nriVsshaEskwhmqfw4g3ytFM7NCZrt%2BguMbXSY7Q%40mail.gmail.com.

[Cédric Chantepie]

Temporarily enable scalaCrossVersion to enable 2.12 build (or hope Scalafix release 2.13 compact meanwhile).

To view this discussion on the web visit https://groups.google.com/d/msgid/reactivemongo/7AEB1849-8D7E-497D-B01C-26DE4D874B43%40evertrust.fr.

[Alexandre Aufrere]

Hi Cedric,

It seems to me that scalafix itself is compatible with scala 2.13 since July, if i understood correctly.

Alexandre

[Cédric Chantepie]

As https://search.maven.org/artifact/org.reactivemongo/reactivemongo-scalafix_2.13/1.0.0-scalafix0923/jar