search

quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.36k stars 2.56k forks source link

Bug when using quarkus-infinispan-client and quarkus-scheduler together #34930

Open vitaly-masterov opened 11 months ago

vitaly-masterov commented 11 months ago

Describe the bug

It looks like there is a bug when using quarkus-infinispan-client and quarkus-scheduler together. This bug only appears if the Infinispan client is running in a docker environment. If the Infinispan client is running outside of docker, then everything works fine. To reproduce the error, I took the infinispan-client-quickstart project as a basis.

Expected behavior

The normal behavior of a quarkus application with "quarkus-infnispan-client" and "quarkus-scheduler" running in a docker environment is expected to be the same as if it were launched without docker.

Actual behavior

This is the stack trace snippet after running docker-compose:

client      | 2023-07-22 04:00:00,324 ERROR [org.inf.HOTROD] (HotRod-client-async-pool-2-12) ISPN004007: Exception encountered. Retry 10 out of 10: io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /172.25.0.4:11222
client      | Caused by: java.net.ConnectException: Connection refused
client      |   at java.base/sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
client      |   at java.base/sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777)
client      |   at io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:337)
client      |   at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:334)
client      |   at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:776)
client      |   at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:689)
client      |   at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:652)
client      |   at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
client      |   at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
client      |   at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
client      |   at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
client      |   at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
client      |   at java.base/java.lang.Thread.run(Thread.java:829)
client      | 
client      | 2023-07-22 04:00:00,326 ERROR [io.qua.sch.com.run.StatusEmitterInvoker] (executor-thread-1) Error occurred while executing task for trigger IntervalTrigger [id=1_org.acme.infinispan.client.Schedulator#run, interval=10000]: java.util.concurrent.CompletionException: java.lang.RuntimeException: Error injecting org.infinispan.client.hotrod.RemoteCache<java.lang.String, org.acme.infinispan.client.Greeting> org.acme.infinispan.client.Schedulator.cache
client      |   at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331)
client      |   at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346)
client      |   at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:870)
client      |   at java.base/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:883)
client      |   at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2251)
client      |   at java.base/java.util.concurrent.CompletableFuture$MinimalStage.whenComplete(CompletableFuture.java:2820)
client      |   at io.quarkus.scheduler.common.runtime.DefaultInvoker.invoke(DefaultInvoker.java:24)
client      |   at io.quarkus.scheduler.common.runtime.StatusEmitterInvoker.invoke(StatusEmitterInvoker.java:35)
client      |   at io.quarkus.scheduler.runtime.SimpleScheduler$ScheduledTask.doInvoke(SimpleScheduler.java:416)
client      |   at io.quarkus.scheduler.runtime.SimpleScheduler$ScheduledTask$1.handle(SimpleScheduler.java:397)
client      |   at io.quarkus.scheduler.runtime.SimpleScheduler$ScheduledTask$1.handle(SimpleScheduler.java:393)
client      |   at io.vertx.core.impl.ContextBase.lambda$null$0(ContextBase.java:137)
client      |   at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
client      |   at io.vertx.core.impl.ContextBase.lambda$executeBlocking$1(ContextBase.java:135)
client      |   at io.quarkus.vertx.core.runtime.VertxCoreRecorder$14.runWith(VertxCoreRecorder.java:581)
client      |   at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
client      |   at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
client      |   at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
client      |   at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
client      |   at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
client      |   at java.base/java.lang.Thread.run(Thread.java:829)
client      | Caused by: java.lang.RuntimeException: Error injecting org.infinispan.client.hotrod.RemoteCache<java.lang.String, org.acme.infinispan.client.Greeting> org.acme.infinispan.client.Schedulator.cache
client      |   at org.acme.infinispan.client.Schedulator_Bean.doCreate(Unknown Source)
client      |   at org.acme.infinispan.client.Schedulator_Bean.create(Unknown Source)
client      |   at org.acme.infinispan.client.Schedulator_Bean.create(Unknown Source)
client      |   at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:113)
client      |   at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:37)
client      |   at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:34)
client      |   at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26)
client      |   at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69)
client      |   at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:34)
client      |   at io.quarkus.arc.impl.ClientProxies.getApplicationScopedDelegate(ClientProxies.java:21)
client      |   at org.acme.infinispan.client.Schedulator_ClientProxy.arc$delegate(Unknown Source)
client      |   at org.acme.infinispan.client.Schedulator_ClientProxy.run(Unknown Source)
client      |   at org.acme.infinispan.client.Schedulator_ScheduledInvoker_run_72e66771a77415a7284d3ae42331659c186071de.invokeBean(Unknown Source)
client      |   ... 15 more
client      | Caused by: jakarta.enterprise.inject.CreationException: Error creating synthetic bean [47af2c2b34baea5f4bf1e7f4e2217e68a09e3aaa]: jakarta.enterprise.inject.CreationException: Error creating synthetic bean [ddee68cd3f60c96290f55bc237588d70e5c96aab]: org.infinispan.client.hotrod.exceptions.TransportException:: io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /172.25.0.4:11222
client      |   at org.infinispan.client.hotrod.RemoteCache_47af2c2b34baea5f4bf1e7f4e2217e68a09e3aaa_Synthetic_Bean.doCreate(Unknown Source)
client      |   at org.infinispan.client.hotrod.RemoteCache_47af2c2b34baea5f4bf1e7f4e2217e68a09e3aaa_Synthetic_Bean.create(Unknown Source)
client      |   at org.infinispan.client.hotrod.RemoteCache_47af2c2b34baea5f4bf1e7f4e2217e68a09e3aaa_Synthetic_Bean.create(Unknown Source)
client      |   at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:113)
client      |   at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:37)
client      |   at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:34)
client      |   at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26)
client      |   at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69)
client      |   at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:34)
client      |   at org.infinispan.client.hotrod.RemoteCache_47af2c2b34baea5f4bf1e7f4e2217e68a09e3aaa_Synthetic_Bean.get(Unknown Source)
client      |   at org.infinispan.client.hotrod.RemoteCache_47af2c2b34baea5f4bf1e7f4e2217e68a09e3aaa_Synthetic_Bean.get(Unknown Source)
client      |   ... 28 more
client      | Caused by: jakarta.enterprise.inject.CreationException: Error creating synthetic bean [ddee68cd3f60c96290f55bc237588d70e5c96aab]: org.infinispan.client.hotrod.exceptions.TransportException:: io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /172.25.0.4:11222
client      |   at org.infinispan.client.hotrod.RemoteCacheManager_ddee68cd3f60c96290f55bc237588d70e5c96aab_Synthetic_Bean.doCreate(Unknown Source)
client      |   at org.infinispan.client.hotrod.RemoteCacheManager_ddee68cd3f60c96290f55bc237588d70e5c96aab_Synthetic_Bean.create(Unknown Source)
client      |   at org.infinispan.client.hotrod.RemoteCacheManager_ddee68cd3f60c96290f55bc237588d70e5c96aab_Synthetic_Bean.create(Unknown Source)
client      |   at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:113)
client      |   at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:37)
client      |   at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:34)
client      |   at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26)
client      |   at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69)
client      |   at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:34)
client      |   at io.quarkus.arc.impl.ClientProxies.getApplicationScopedDelegate(ClientProxies.java:21)
client      |   at org.infinispan.client.hotrod.RemoteCacheManager_ddee68cd3f60c96290f55bc237588d70e5c96aab_Synthetic_ClientProxy.arc$delegate(Unknown Source)
client      |   at org.infinispan.client.hotrod.RemoteCacheManager_ddee68cd3f60c96290f55bc237588d70e5c96aab_Synthetic_ClientProxy.getCache(Unknown Source)
client      |   at io.quarkus.infinispan.client.runtime.InfinispanClientProducer.getRemoteCache(InfinispanClientProducer.java:374)
client      |   at io.quarkus.infinispan.client.runtime.InfinispanRecorder$3.apply(InfinispanRecorder.java:54)
client      |   at io.quarkus.infinispan.client.runtime.InfinispanRecorder$3.apply(InfinispanRecorder.java:51)
client      |   at io.quarkus.infinispan.client.runtime.InfinispanRecorder$InfinispanClientSupplier.get(InfinispanRecorder.java:82)
client      |   at io.quarkus.arc.runtime.ArcRecorder$4.apply(ArcRecorder.java:129)
client      |   at io.quarkus.arc.runtime.ArcRecorder$4.apply(ArcRecorder.java:126)
client      |   at org.infinispan.client.hotrod.RemoteCache_47af2c2b34baea5f4bf1e7f4e2217e68a09e3aaa_Synthetic_Bean.createSynthetic(Unknown Source)
client      |   ... 39 more

How to Reproduce?

  1. Download sources from GitHub 
    git clone git@github.com:vitaly-masterov/infinispan-client-quickstart.git
  2. Change to the project directory 
    cd infinispan-client-quickstart
  3. Build maven project: 
    ./mvnw clean package
  4. Build docker image 
    docker build --file src/main/docker/Dockerfile.jvm --tag quarkus/infinispan-client .
  5. Run docker-compose 
    docker-compose up

Output of uname -a or ver

Linux calculate 6.1.39-calculate #1 SMP PREEMPT_DYNAMIC Wed Jul 19 21:20:18 UTC 2023 x86_64 AMD Ryzen 5 3600 6-Core Processor AuthenticAMD GNU/Linux

Output of java -version

11, 17

GraalVM version (if different from Java)

No response

Quarkus version or git rev

3.2.1.Final

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.8.6

Additional information

If I comment out this piece of code, then docker-compose starts without errors

    @Inject
    @Remote("mycache")
    RemoteCache<String, Greeting> cache;

and

cache.put("hello", greeting);
quarkus-bot[bot] commented 11 months ago

/cc @karesti (infinispan), @mkouba (scheduler), @wburns (infinispan)

vitaly-masterov commented 11 months ago

I'll make a clarification. I did some more experiments. The influence of the scheduler has an indirect effect. Exactly the same effect occurs if the handler in which the cache is injected is launched in response to the arrival of a message from the message broker. Exactly such a bug appears if you make a REST call. You need to look for a problem precisely when using RemoteCache in the docker runtime environment. Everything works fine without docker.

mkouba commented 11 months ago

So the root cause is Error creating synthetic bean [ddee68cd3f60c96290f55bc237588d70e5c96aab]: org.infinispan.client.hotrod.exceptions.TransportException:: io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /172.25.0.4:11222 thrown when the synthetic bean for org.infinispan.client.hotrod.RemoteCacheManager is being created.

I don't think it's related to quarkus-scheduler or any other extension but quarkus-infinispan-client.

gsmet commented 11 months ago

Could it just be a timing issue i.e. Infinispan not being available yet when trying to connect?

vitaly-masterov commented 11 months ago

It looks like it's true. I changed docker-compose. Added to infnispan-server

    healthcheck:
      test: curl --fail http://172.25.0.4:11222/rest/v2/cache-managers/default/health/status || exit 1
      interval: 10s
      start_period: 30s
      timeout: 10s

And in client-app added:

    depends_on:
      infinispan-server:
        condition: service_healthy

And after that the error disappeared. Probably the client-app was unsuccessfully hooked to infinispan if it had not yet been fully launched.

I'm sorry I bothered you for nothing. The issue can be closed. But in any case, the message in the stack trace is not very informative, because of it it is impossible to understand what the problem is.

I tried to experiment and leave empty 

quarkus.infinispan-client.hosts

the error is exactly the same.

It would be nice to check for this case, if the parameter is set incorrectly or not set at all, then issue an appropriate warning.

karesti commented 11 months ago

yes, this is true @vitaly-masterov sometimes error handling and understanding can be tricky with Infinispan. I'll try to work on this after PTO when I'm back in August, as well as other Infinispan retaled Quarkus issues. Let's keep this issue open meanwhile please @gsmet