MongoDB itest fails on Camel 3.1.0-SNAPSHOT

[ppalaga]

Reproducible against the code in #651

The log:

[INFO] Running org.apache.camel.quarkus.component.mongodb.it.MongoDbTest
        ℹ︎ Checking the system...
        ✔ Docker version should be at least 1.6.0
        ✔ Docker environment should have more than 2GB free disk space
2020-01-22 13:07:40,602 INFO  [org.apa.cam.qua.com.mon.it.MongoDbTestResource] (main) TestcontainersConfiguration(properties={docker.client.strategy=org.testcontainers.dockerclient.EnvironmentAndSystemPropertyClientProviderStrategy, pull.pause.timeout=120})
2020-01-22 13:07:40,648 INFO  [org.tes.doc.DockerClientProviderStrategy] (main) Loaded org.testcontainers.dockerclient.EnvironmentAndSystemPropertyClientProviderStrategy from ~/.testcontainers.properties, will try it first
2020-01-22 13:07:40,679 INFO  [org.tes.doc.DockerClientProviderStrategy] (main) Will use 'okhttp' transport
2020-01-22 13:07:41,186 INFO  [org.tes.doc.EnvironmentAndSystemPropertyClientProviderStrategy] (main) Found docker client settings from environment
2020-01-22 13:07:41,200 INFO  [org.tes.doc.DockerClientProviderStrategy] (main) Found Docker environment with Environment variables, system properties and defaults. Resolved: 
    dockerHost=unix:///var/run/docker.sock
    apiVersion='{UNKNOWN_VERSION}'
    registryUrl='https://index.docker.io/v1/'
    registryUsername='ppalaga'
    registryPassword='null'
    registryEmail='null'
    dockerConfig='DefaultDockerClientConfig[dockerHost=unix:///var/run/docker.sock,registryUsername=ppalaga,registryPassword=<null>,registryEmail=<null>,registryUrl=https://index.docker.io/v1/,dockerConfigPath=/home/ppalaga/.docker,sslConfig=<null>,apiVersion={UNKNOWN_VERSION},dockerConfig=<null>]'

2020-01-22 13:07:41,202 INFO  [org.tes.DockerClientFactory] (main) Docker host IP address is localhost
2020-01-22 13:07:41,412 INFO  [org.tes.DockerClientFactory] (main) Connected to docker: 
  Server Version: 19.03.5
  API Version: 1.40
  Operating System: Fedora 31 (KDE Plasma)
  Total Memory: 31492 MB
2020-01-22 13:07:41,443 WARN  [org.tes.uti.RegistryAuthLocator] (main) Failure when attempting to lookup auth config (dockerImageName: quay.io/testcontainers/ryuk:0.2.3, configFile: /home/ppalaga/.docker/config.json. Falling back to docker-java default behaviour. Exception message: /home/ppalaga/.docker/config.json (No such file or directory)
2020-01-22 13:07:42,120 INFO  [org.tes.DockerClientFactory] (main) Ryuk started - will monitor and terminate Testcontainers containers on JVM exit
2020-01-22 13:07:42,423 INFO  [🐳 .0]] (main) Creating container for image: mongo:4.0
2020-01-22 13:07:42,424 WARN  [org.tes.uti.RegistryAuthLocator] (main) Failure when attempting to lookup auth config (dockerImageName: mongo:4.0, configFile: /home/ppalaga/.docker/config.json. Falling back to docker-java default behaviour. Exception message: /home/ppalaga/.docker/config.json (No such file or directory)
2020-01-22 13:07:42,514 INFO  [🐳 .0]] (main) Starting container with ID: 48dd24bf75ec1c20946c5552af868953b4dece707881ed74ead4fd1c0662132c
2020-01-22 13:07:42,994 INFO  [🐳 .0]] (main) Container mongo:4.0 is starting: 48dd24bf75ec1c20946c5552af868953b4dece707881ed74ead4fd1c0662132c
2020-01-22 13:07:43,870 INFO  [🐳 .0]] (main) Container mongo:4.0 started
2020-01-22 13:07:46,011 INFO  [org.mon.dri.cluster] (main) Cluster created with settings {hosts=[127.0.0.1:27017], mode=SINGLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500}
2020-01-22 13:07:46,049 INFO  [org.mon.dri.cluster] (main) Cluster created with settings {hosts=[127.0.0.1:27017], mode=SINGLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500}
2020-01-22 13:07:46,048 INFO  [org.mon.dri.cluster] (cluster-ClusterId{value='5e283b121d7345680bd745bf', description='null'}-127.0.0.1:27017) Exception in monitor thread while connecting to server 127.0.0.1:27017: com.mongodb.MongoSocketOpenException: Exception opening socket
        at com.mongodb.internal.connection.SocketChannelStream.open(SocketChannelStream.java:63)
        at com.mongodb.internal.connection.InternalStreamConnection.open(InternalStreamConnection.java:126)
        at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:117)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.net.ConnectException: Connection refused
        at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
        at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
        at sun.nio.ch.SocketAdaptor.connect(SocketAdaptor.java:111)
        at com.mongodb.internal.connection.SocketStreamHelper.initialize(SocketStreamHelper.java:64)
        at com.mongodb.internal.connection.SocketChannelStream.initializeSocketChannel(SocketChannelStream.java:72)
        at com.mongodb.internal.connection.SocketChannelStream.open(SocketChannelStream.java:60)
        ... 3 more

2020-01-22 13:07:46,066 INFO  [org.mon.dri.cluster] (cluster-ClusterId{value='5e283b121d7345680bd745c0', description='null'}-127.0.0.1:27017) Exception in monitor thread while connecting to server 127.0.0.1:27017: com.mongodb.MongoSocketOpenException: Exception opening socket
        at com.mongodb.internal.connection.AsynchronousSocketChannelStream$OpenCompletionHandler.failed(AsynchronousSocketChannelStream.java:117)
        at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:128)
        at sun.nio.ch.Invoker$2.run(Invoker.java:218)
        at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.net.ConnectException: Connection refused
        at sun.nio.ch.UnixAsynchronousSocketChannelImpl.checkConnect(Native Method)
        at sun.nio.ch.UnixAsynchronousSocketChannelImpl.finishConnect(UnixAsynchronousSocketChannelImpl.java:252)
        at sun.nio.ch.UnixAsynchronousSocketChannelImpl.finish(UnixAsynchronousSocketChannelImpl.java:198)
        at sun.nio.ch.UnixAsynchronousSocketChannelImpl.onEvent(UnixAsynchronousSocketChannelImpl.java:213)
        at sun.nio.ch.EPollPort$EventHandlerTask.run(EPollPort.java:293)
        ... 1 more

2020-01-22 13:07:46,072 INFO  [org.mon.dri.cluster] (main) Cluster created with settings {hosts=[127.0.0.1:27017], mode=SINGLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500}
2020-01-22 13:07:46,079 INFO  [org.mon.dri.cluster] (cluster-ClusterId{value='5e283b121d7345680bd745c1', description='null'}-127.0.0.1:27017) Exception in monitor thread while connecting to server 127.0.0.1:27017: com.mongodb.MongoSocketOpenException: Exception opening socket
        at com.mongodb.internal.connection.SocketStream.open(SocketStream.java:70)
        at com.mongodb.internal.connection.InternalStreamConnection.open(InternalStreamConnection.java:126)
        at com.mongodb.internal.connection.DefaultServerMonitor$ServerMonitorRunnable.run(DefaultServerMonitor.java:117)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.net.ConnectException: Connection refused (Connection refused)
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at java.net.Socket.connect(Socket.java:607)
        at com.mongodb.internal.connection.SocketStreamHelper.initialize(SocketStreamHelper.java:64)
        at com.mongodb.internal.connection.SocketStream.initializeSocket(SocketStream.java:79)
        at com.mongodb.internal.connection.SocketStream.open(SocketStream.java:65)
        ... 3 more

2020-01-22 13:07:46,223 INFO  [org.apa.cam.qua.cor.FastCamelContext] (main) Apache Camel 3.1.0-SNAPSHOT (CamelContext: camel-1) is starting
2020-01-22 13:07:46,224 INFO  [org.apa.cam.imp.eng.DefaultManagementStrategy] (main) JMX is disabled
2020-01-22 13:07:46,227 INFO  [org.apa.cam.qua.cor.FastCamelContext] (main) StreamCaching is not in use. If using streams then its recommended to enable stream caching. See more details at http://camel.apache.org/stream-caching.html
2020-01-22 13:07:46,228 INFO  [org.apa.cam.qua.cor.FastCamelContext] (main) Total 0 routes, of which 0 are started
2020-01-22 13:07:46,229 INFO  [org.apa.cam.qua.cor.FastCamelContext] (main) Apache Camel 3.1.0-SNAPSHOT (CamelContext: camel-1) started in 0.005 seconds
2020-01-22 13:07:46,230 INFO  [io.quarkus] (main) Quarkus 1.2.0.CR1 started in 0.772s. Listening on: http://0.0.0.0:45087
2020-01-22 13:07:46,230 INFO  [io.quarkus] (main) Profile test activated. 
2020-01-22 13:07:46,231 INFO  [io.quarkus] (main) Installed features: [camel-core, camel-mongodb, camel-support-common, cdi, mongodb-client, resteasy, resteasy-jsonb, smallrye-context-propagation, smallrye-reactive-streams-operators, vertx]
2020-01-22 13:07:47,154 INFO  [org.apa.cam.mai.BaseMainSupport] (executor-thread-1) Autowired property: mongoConnection on component: MongoDbComponent as exactly one instance of type: com.mongodb.client.MongoClient found in the registry
2020-01-22 13:07:47,280 INFO  [org.apa.cam.com.mon.MongoDbEndpoint] (executor-thread-1) Initialising MongoDb endpoint: mongodb://camelMongoClient?collection=camelTest&database=test&dynamicity=true&operation=insert
2020-01-22 13:07:47,292 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-1) HTTP Request to /mongodb/collection/camelTest failed, error id: 6cb41ffd-e00c-433e-9579-063f4127d32f-1: org.jboss.resteasy.spi.UnhandledException: org.apache.camel.FailedToCreateProducerException: Failed to create Producer for endpoint: mongodb://camelMongoClient?collection=camelTest&database=test&dynamicity=true&operation=insert. Reason: java.lang.NoSuchMethodError: com.mongodb.client.MongoClient.getClusterDescription()Lcom/mongodb/connection/ClusterDescription;
        at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:106)
        at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:372)
        at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:209)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:496)
        at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:252)
        at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:153)
        at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:363)
        at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:156)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:238)
        at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
        at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:120)
        at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.access$000(VertxRequestHandler.java:36)
        at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:85)
        at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
        at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2011)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1535)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1395)
        at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
        at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
        at java.lang.Thread.run(Thread.java:748)
        at org.jboss.threads.JBossThread.run(JBossThread.java:479)
Caused by: org.apache.camel.FailedToCreateProducerException: Failed to create Producer for endpoint: mongodb://camelMongoClient?collection=camelTest&database=test&dynamicity=true&operation=insert. Reason: java.lang.NoSuchMethodError: com.mongodb.client.MongoClient.getClusterDescription()Lcom/mongodb/connection/ClusterDescription;
        at org.apache.camel.impl.engine.DefaultProducerCache.acquireProducer(DefaultProducerCache.java:144)
        at org.apache.camel.impl.engine.DefaultProducerCache.send(DefaultProducerCache.java:160)
        at org.apache.camel.impl.engine.DefaultProducerTemplate.send(DefaultProducerTemplate.java:176)
        at org.apache.camel.impl.engine.DefaultProducerTemplate.send(DefaultProducerTemplate.java:172)
        at org.apache.camel.impl.engine.DefaultProducerTemplate.send(DefaultProducerTemplate.java:153)
        at org.apache.camel.impl.engine.DefaultProducerTemplate.sendBody(DefaultProducerTemplate.java:187)
        at org.apache.camel.impl.engine.DefaultProducerTemplate.sendBody(DefaultProducerTemplate.java:195)
        at org.apache.camel.quarkus.component.mongodb.it.MongoDbResource.writeToCollection(MongoDbResource.java:56)
        at org.apache.camel.quarkus.component.mongodb.it.MongoDbResource_ClientProxy.writeToCollection(MongoDbResource_ClientProxy.zig:225)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:151)
        at org.jboss.resteasy.core.MethodInjectorImpl.lambda$invoke$3(MethodInjectorImpl.java:122)
        at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616)
        at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628)
        at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996)
        at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:110)
        at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:122)
        at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:594)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:468)
        at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:421)
        at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:363)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:423)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:391)
        at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invoke$1(ResourceMethodInvoker.java:365)
        at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:995)
        at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2137)
        at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:110)
        at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:365)
        at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:477)
        ... 17 more
Caused by: java.lang.NoSuchMethodError: com.mongodb.client.MongoClient.getClusterDescription()Lcom/mongodb/connection/ClusterDescription;
        at org.apache.camel.component.mongodb.MongoDbEndpoint.initializeConnection(MongoDbEndpoint.java:240)
        at org.apache.camel.component.mongodb.MongoDbEndpoint.createProducer(MongoDbEndpoint.java:132)
        at org.apache.camel.support.DefaultEndpoint.createAsyncProducer(DefaultEndpoint.java:196)
        at org.apache.camel.impl.engine.ServicePool$SinglePool.acquire(ServicePool.java:204)
        at org.apache.camel.impl.engine.ServicePool$SinglePool.acquire(ServicePool.java:187)
        at org.apache.camel.impl.engine.ServicePool.acquire(ServicePool.java:105)
        at org.apache.camel.impl.engine.DefaultProducerCache.acquireProducer(DefaultProducerCache.java:117)
        ... 48 more

[lburgazzoli]

This is probably related to some changes introduced on master @jamesnetherton was looking at, see #544

[jamesnetherton]

Yes, I have some WIP locally that'll fix this up.

[lburgazzoli]

@jamesnetherton I think you already noticed but if not, that the quarkus team has added a mongodb driver legacy to our dependencies which should probably be removed once migrating to 3.1

[jamesnetherton]

@lburgazzoli Actually I think we need to stick with the legacy driver for now.

What we really want is for Camel to stop using the deprecated Mongo driver uber-jar, and do like Quarkus in migrating to the newer mongodb-driver-sync. I can raise a Camel ticket for that. No idea how much work it would involve.

[lburgazzoli]

I think we moved away from the old client and we now use the client interface so it should be "simple", @jamesnetherton do you mind having a look as part of #544 ?

[jamesnetherton]

Yep, that's one part of it - but camel-mongodb still uses other deprecated APIs which require the presence of the legacy driver dependency.

[lburgazzoli]

uff

[lburgazzoli]

wonder if we should remove them, maybe add some deprecation on 3.0.x if needed

[jamesnetherton]

I think its mostly internal usage for the component, so probably no need for deprecation.

It'd be good if the component could move to the newer driver in 3.1.x.

[jamesnetherton]

I raised CAMEL-14423.

It's not a hard dependency for resolving this issue or #544. For now, we can live with including the legacy driver until the component moves to using the updated APIs.

[jamesnetherton]

Turns out we do have a incompatibility issue 😞 .

I thought Quarkus had bumped to the latest version of the Mongo driver, but they are still on 3.10.x, which is not compatible with 3.12.x used in Camel 3.1.0.

It seems fixable with some dependency overrides on our side. Otherwise we need quarkusio/quarkus#6347 merged for Quarkus 1.2.0.Final.

[jamesnetherton]

@ppalaga I sent a PR to your fork ppalaga#2 which should fix this.

[jamesnetherton]

Fixed in d68e8b7.