search

quarkusio / quarkus

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

oidc-client, ContextNotActiveException in new thread #22477

Closed lthasle closed 2 years ago

lthasle commented 2 years ago

Describe the bug

It seams like Context is lost in the new thread when using Tokens from oidc-client

See also: https://github.com/quarkusio/quarkus/discussions/22273

Expected behavior

Usage of io.quarkus.oidc.client.Tokens should work, ie. have a value

Actual behavior

Usage(@Inject) of io.quarkus.oidc.client.Tokens is causing: ContextNotActiveException

The result from running: MyResourceTest.fail:

javax.ws.rs.ProcessingException: javax.enterprise.context.ContextNotActiveException
    at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.filterRequest(ClientInvocation.java:780)
    at org.jboss.resteasy.microprofile.client.impl.MpClientInvocation.filterRequest(MpClientInvocation.java:75)
    at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke(ClientInvocation.java:491)
    at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invokeSync(ClientInvoker.java:152)
    at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invoke(ClientInvoker.java:115)
    at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientProxy.invoke(ClientProxy.java:76)
    at com.sun.proxy.$Proxy107.updatestate(Unknown Source)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.jboss.resteasy.microprofile.client.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:146)
    at com.sun.proxy.$Proxy108.updatestate(Unknown Source)
    at org.my.StreamService.lambda$0(StreamService.java:26)
    at org.my.AbstractMeglerService.execute(AbstractMeglerService.java:17)
    at org.my.StreamService.updateState(StreamService.java:26)
    at org.my.StreamService_ClientProxy.updateState(Unknown Source)
    at org.my.QConsumer.run(QConsumer.java:35)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: javax.enterprise.context.ContextNotActiveException
    at io.quarkus.arc.impl.ClientProxies.getDelegate(ClientProxies.java:46)
    at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_ClientProxy.arc$delegate(Unknown Source)
    at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_ClientProxy.getAccessToken(Unknown Source)
    at org.my.StreamAuthenticationFilterMidtNorge.filter(StreamAuthenticationFilterMidtNorge.java:21)
    at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.filterRequest(ClientInvocation.java:767)
    ... 22 more

How to Reproduce?

It is based on: https://quarkus.io/guides/rest-client I added my stuff in the package: org.my

The problem can be verified by running the test: MyResourceTest.fail

The other test: MyResourceTest.ok is doing the same, BUT in same thread (that is not via a Q, as the other test), but it requires proper values in: application.properties to succeed.

Output of uname -a or ver

uname -a Linux hty80028.sb1a.sparebank1.no 4.18.0-348.2.1.el8_5.x86_64 #1 SMP Mon Nov 8 13:30:15 EST 2021 x86_64 x86_64 x86_64 GNU/Linux

Output of java -version

openjdk version "11.0.10" 2021-01-19 OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.10+9) OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.10+9, mixed mode)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.5.4.Final

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

No response

Additional information

rest-client-quickstart.zip

quarkus-bot[bot] commented 2 years ago

/cc @pedroigor, @sberyozkin

sberyozkin commented 2 years ago

Hi @mkouba @stuartwdouglas Can you comment please, FYI, the filter which has OidcClient injected is:

@Priority(Priorities.AUTHENTICATION)
public class StreamAuthenticationFilterMidtNorge implements ClientRequestFilter {

    @NamedOidcClient("MidtNorge")
    Tokens tokens;

    @Override
    public void filter(ClientRequestContext clientRequestContext) throws IOException {
        clientRequestContext.getHeaders().add(HttpHeaders.AUTHORIZATION, "Bearer " + tokens.getAccessToken());
    }
}

and it is used in this code:

@ApplicationScoped
public class QConsumer implements Runnable {

    @Inject
    ConnectionFactory connectionFactory;
    @Inject
    StreamService service;

    private final ExecutorService scheduler = Executors.newSingleThreadExecutor();

    @Override
    public void run() {
        try (JMSContext context = connectionFactory.createContext(Session.AUTO_ACKNOWLEDGE);
                JMSConsumer consumer = context.createConsumer(context.createQueue(MyResource.MY_Q))) {
            while (true) {
                Message message = consumer.receive();
                if (message == null) return;
                                // OidcClient is used during this call
                service.updateState();
            }
        }
    }

    void onStart(@Observes StartupEvent ev) {
        scheduler.submit(this);
    }

    void onStop(@Observes ShutdownEvent ev) {
        scheduler.shutdown();
    }

}

quarkus-smallrye-context-propagation is in the pom.

I think the executor should be created differently, using the one provided by Quarkus ? thanks

mkouba commented 2 years ago

I think the executor should be created differently, using the one provided by Quarkus ?

Yes, a manually created executor does not propagate the CDI request context. You'll need to add the io.quarkus:quarkus-smallrye-context-propagation dependency and inject ManagedExecutor instead. Or change the scope of the StreamService bean to @ApplicationScoped.

CC @FroMage @manovotn

lthasle commented 2 years ago

@mkouba Thanks for your suggestions. But I already have quarkus-smallrye-context-propagation dependency & StreamService use @ApplicationScoped

mkouba commented 2 years ago

& StreamService use @ApplicationScoped

I see. But from the stack trace I can see that this bean probably injects a rest client which expects the context to be active. So I'd say that the injected ManagedExecutor is the only way to go.

manovotn commented 2 years ago

+1, Martin is right. The executor needs to come from SR context propagation. It can be either injected or created via the builder pattern. Injection is the recommended and simpler approach.

lthasle commented 2 years ago

I Injected the ManagedExecutor but then I got another fault, see code and stacktrace below, any more suggestions? @mkouba @sberyozkin

` @ApplicationScoped public class QConsumer implements Runnable {

@Inject
ConnectionFactory connectionFactory;
@Inject
StreamService service;
@Inject
ManagedExecutor scheduler;

@Override
public void run() {
    try (JMSContext context = connectionFactory.createContext(Session.AUTO_ACKNOWLEDGE);
            JMSConsumer consumer = context.createConsumer(context.createQueue(MyResource.MY_Q))) {
        while (true) {
            Message message = consumer.receive();
            if (message == null) return;
            service.updateState();
        }
    }
}

void onStart(@Observes StartupEvent ev) {
    scheduler.submit(this);
}

} `

`

javax.ws.rs.ProcessingException: java.util.concurrent.CompletionException: java.lang.InterruptedException at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.filterRequest(ClientInvocation.java:780) at org.jboss.resteasy.microprofile.client.impl.MpClientInvocation.filterRequest(MpClientInvocation.java:75) at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke(ClientInvocation.java:491) at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invokeSync(ClientInvoker.java:152) at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invoke(ClientInvoker.java:115) at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientProxy.invoke(ClientProxy.java:76) at com.sun.proxy.$Proxy106.updatestate(Unknown Source) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.jboss.resteasy.microprofile.client.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:146) at com.sun.proxy.$Proxy107.updatestate(Unknown Source) at org.my.StreamService.lambda$0(StreamService.java:26) at org.my.AbstractMeglerService.execute(AbstractMeglerService.java:17) at org.my.StreamService.updateState(StreamService.java:26) at org.my.StreamService_ClientProxy.updateState(Unknown Source) at org.my.QConsumer.run(QConsumer.java:33) at io.smallrye.context.impl.wrappers.SlowContextualRunnable.run(SlowContextualRunnable.java:19) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:548) at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449) at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478) at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29) at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:834) Caused by: java.util.concurrent.CompletionException: java.lang.InterruptedException at io.smallrye.mutiny.operators.uni.UniBlockingAwait.await(UniBlockingAwait.java:73) at io.smallrye.mutiny.groups.UniAwait.atMost(UniAwait.java:61) at io.smallrye.mutiny.groups.UniAwait.indefinitely(UniAwait.java:42) at io.quarkus.oidc.client.runtime.TokensHelper.initTokens(TokensHelper.java:20) at io.quarkus.oidc.client.runtime.AbstractTokensProducer.initTokens(AbstractTokensProducer.java:38) at io.quarkus.oidc.client.runtime.AbstractTokensProducer.init(AbstractTokensProducer.java:33) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.create(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.create(Unknown Source) at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:96) at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:29) at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:26) at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26) at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69) at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:26) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.get(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.get(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_Bean.create(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_Bean.create(Unknown Source) at io.quarkus.arc.impl.RequestContext.getIfActive(RequestContext.java:68) at io.quarkus.arc.impl.ClientProxies.getDelegate(ClientProxies.java:27) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_ClientProxy.arc$delegate(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_ClientProxy.getAccessToken(Unknown Source) at org.my.StreamAuthenticationFilterMidtNorge.filter(StreamAuthenticationFilterMidtNorge.java:21) at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.filterRequest(ClientInvocation.java:767) ... 27 more Caused by: java.lang.InterruptedException at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1040) at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1345) at java.base/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:232) at io.smallrye.mutiny.operators.uni.UniBlockingAwait.await(UniBlockingAwait.java:61) ... 50 more `

sberyozkin commented 2 years ago

@lthasle Interesting. I think it might be related to the fact that the Tokens producer you are injecting in the client filter is blocking. But I'm not sure why it makes a difference if you run the client from a thread different to the one which made the original request - as you confirmed at #22273 the client works OK if not run from the executor thread.

My guess ManagedExecutor is tuned around the reactive calls so one just can't block in its threads. You could've injected OidcClient directly instead of Tokens and use its Uni-aware getAccessToken() but then you'd still need to block to get the actual token as you running it in a filter.

Martin @mkouba, Matej @manovotn - is it indeed the case that ManagedExecutor tasks must be non-blocking ?

@lthasle, One option is to use a OidcClientReactiveFilter - either this one or a custom one (I'll doc it as well how to create a custom reactive filter). But you'll need to switch from RestEasy Classic to RestEasy Reactive - it will be the best option if it can work for you - it will be faster as well.

@mkouba @manovotn Can you recommend any other options ? May be we can configure ManagedExecutor to allow running the blocking tasks ?

@lthasle I'll also look at introducing a simple OidcClient builder which will accept OidcClientConfig and will return Uni<OidcClient> if the discovery is required or OidcClient if not so that the injection can be avoided.

manovotn commented 2 years ago

I am not aware of ME not being able to serve blocking tasks. But I cannot really investigate now (on PTO and travelling). @FroMage knows a lot more about the reactive side of things.

sberyozkin commented 2 years ago

@manovotn sure, enjoy it, happy holidays :-)

lthasle commented 2 years ago

@sberyozkin Thanks for your effort and suggestions so far! We hope that we soon will be able to use: RestEasy Reactive, but for the time being we are not able to

lthasle commented 2 years ago

Same problem with the latest quarkus version: 2.6.0.Final

I also had to change quarkus-test-artemis dependency:

io.quarkiverse.artemis quarkus-test-artemis 1.0.3 test
sberyozkin commented 2 years ago

@lthasle Np, with many people on PTO, myself signing off later today as well, it is unlikely we'll have a solution before the end of the year :-). But at least we know how to approach it: 1) investigate how ManagedExecutor can be enhanced or configured to allow the blocking calls 2) Add OidcClientBulder. I think 1) has to be addressed in any case as a similar issue might arise not only for OidcClient thanks

lthasle commented 2 years ago

Same problem with the latest quarkus version: 2.6.1.Final

FroMage commented 2 years ago

My guess ManagedExecutor is tuned around the reactive calls so one just can't block in its threads.

No it's not, this is directly backed by the Quarkus worker thread pool, so you can block.

FroMage commented 2 years ago

The real question is why is the thread interrupted? And perhaps there are some bits which should handle the interruption?

sberyozkin commented 2 years ago

The real question is why is the thread interrupted?

@FroMage @manovotn May be because the injection is happening on the IO thread while injected tokens producer is blocking. It can be delayed though, the token acquisition. @lthasle, can you please add quarkus.oidc-client.MidtNorge.early-tokens-acquisition=false and see if it helps ?

lthasle commented 2 years ago

@sberyozkin thanks for your proposal but adding: quarkus.oidc-client.MidtNorge.early-tokens-acquisition=false did NOT make any change unfortunately

sberyozkin commented 2 years ago

@lthasle Sorry, I forgot that it is a global property, https://github.com/quarkusio/quarkus/blob/main/extensions/oidc-client/runtime/src/main/java/io/quarkus/oidc/client/runtime/AbstractTokensProducer.java#L21, it is not a client tenant specific, can you please try quarkus.oidc-client.early-tokens-acquisition=false

lthasle commented 2 years ago

@sberyozkin adding: quarkus.oidc-client.early-tokens-acquisition=false did NOT make any change unfortunately

sberyozkin commented 2 years ago

Hmm... I'm out of the ideas right now. TokensProducer which you have injected extends AbstractTokensProducer and if this property is indeed injected then the early token acquisition must be skipped, but the stack trace suggests this property is not injected, io.quarkus.oidc.client.runtime.AbstractTokensProducer.initTokens(AbstractTokensProducer.java:38) -> https://github.com/quarkusio/quarkus/blob/main/extensions/oidc-client/runtime/src/main/java/io/quarkus/oidc/client/runtime/AbstractTokensProducer.java#L38

lthasle commented 2 years ago

@sberyozkin Just to be clear, the result is the same when I use: quarkus.oidc-client.early-tokens-acquisition=false

But the stacktrace is different related to the class AbstractTokensProducer which you talk about: Here is the actual stacktrace, but I guess you already have seen this

javax.ws.rs.ProcessingException: java.util.concurrent.CompletionException: java.lang.InterruptedException at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.filterRequest(ClientInvocation.java:780) at org.jboss.resteasy.microprofile.client.impl.MpClientInvocation.filterRequest(MpClientInvocation.java:75) at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke(ClientInvocation.java:491) at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invokeSync(ClientInvoker.java:152) at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invoke(ClientInvoker.java:115) at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientProxy.invoke(ClientProxy.java:76) at com.sun.proxy.$Proxy107.updatestate(Unknown Source) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.jboss.resteasy.microprofile.client.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:146) at com.sun.proxy.$Proxy108.updatestate(Unknown Source) at org.my.StreamService.lambda$0(StreamService.java:26) at org.my.AbstractMeglerService.execute(AbstractMeglerService.java:17) at org.my.StreamService.updateState(StreamService.java:26) at org.my.StreamService_ClientProxy.updateState(Unknown Source) at org.my.QConsumer.run(QConsumer.java:33) at io.smallrye.context.impl.wrappers.SlowContextualRunnable.run(SlowContextualRunnable.java:19) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:548) at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449) at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478) at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29) at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:834) Caused by: java.util.concurrent.CompletionException: java.lang.InterruptedException at io.smallrye.mutiny.operators.uni.UniBlockingAwait.await(UniBlockingAwait.java:73) at io.smallrye.mutiny.groups.UniAwait.atMost(UniAwait.java:62) at io.smallrye.mutiny.groups.UniAwait.indefinitely(UniAwait.java:43) at io.quarkus.oidc.client.runtime.AbstractTokensProducer.awaitTokens(AbstractTokensProducer.java:47) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge.produceTokens(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_Bean.create(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_Bean.create(Unknown Source) at io.quarkus.arc.impl.RequestContext.getIfActive(RequestContext.java:68) at io.quarkus.arc.impl.ClientProxies.getDelegate(ClientProxies.java:27) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_ClientProxy.arc$delegate(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_ClientProxy.getAccessToken(Unknown Source) at org.my.StreamAuthenticationFilterMidtNorge.filter(StreamAuthenticationFilterMidtNorge.java:21) at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.filterRequest(ClientInvocation.java:767) ... 27 more Caused by: java.lang.InterruptedException at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1040) at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1345) at java.base/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:232) at io.smallrye.mutiny.operators.uni.UniBlockingAwait.await(UniBlockingAwait.java:61) ... 39 more

sberyozkin commented 2 years ago

@lthasle Sorry about all of it, I'll try to have a look when I'm back;

So it all works if it is not a new thread - but if it is a new thread provided by ManagedExecutor then the underlying blocking OidcClient request is interrupted.

Hi @mkouba @manovotn @FroMage - if you have any other ideas why it can be the case then please comment - this is the only difference, the client request filter which has a blocking Tokens producer, is run either from the same thread which entered the Quarkus endpoint (all is good) or from a new thread provided by ManagedExecutor (does not work)

lthasle commented 2 years ago

@sberyozkin I get the same behavior if I try to use reactive, see stacktrace below. But we are for the moment not able to use reactive for our project anyway. java.util.concurrent.CompletionException: java.lang.InterruptedException at io.smallrye.mutiny.operators.uni.UniBlockingAwait.await(UniBlockingAwait.java:73) at io.smallrye.mutiny.groups.UniAwait.atMost(UniAwait.java:62) at io.smallrye.mutiny.groups.UniAwait.indefinitely(UniAwait.java:43) at io.quarkus.oidc.client.runtime.TokensHelper.initTokens(TokensHelper.java:20) at io.quarkus.oidc.client.runtime.AbstractTokensProducer.initTokens(AbstractTokensProducer.java:38) at io.quarkus.oidc.client.runtime.AbstractTokensProducer.init(AbstractTokensProducer.java:33) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.create(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.create(Unknown Source) at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:96) at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:29) at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:26) at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26) at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69) at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:26) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.get(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.get(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_Bean.create(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_Bean.create(Unknown Source) at io.quarkus.arc.impl.RequestContext.getIfActive(RequestContext.java:68) at io.quarkus.arc.impl.ClientProxies.getDelegate(ClientProxies.java:27) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_ClientProxy.arc$delegate(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_ClientProxy.getAccessToken(Unknown Source) at org.my.StreamAuthenticationFilterMidtNorge.filter(StreamAuthenticationFilterMidtNorge.java:21) at org.jboss.resteasy.reactive.client.handlers.ClientRequestFilterRestHandler.handle(ClientRequestFilterRestHandler.java:24) at org.jboss.resteasy.reactive.client.handlers.ClientRequestFilterRestHandler.handle(ClientRequestFilterRestHandler.java:9) at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:141) at org.jboss.resteasy.reactive.client.impl.AsyncInvokerImpl.performRequestInternal(AsyncInvokerImpl.java:262) at org.jboss.resteasy.reactive.client.impl.AsyncInvokerImpl.performRequestInternal(AsyncInvokerImpl.java:252) at org.jboss.resteasy.reactive.client.impl.AsyncInvokerImpl.method(AsyncInvokerImpl.java:212) at org.jboss.resteasy.reactive.client.impl.InvocationBuilderImpl.method(InvocationBuilderImpl.java:324) at org.my.StreamClientMidtNorge$$QuarkusRestClientInterface.updatestate(Unknown Source) at org.my.StreamService.lambda$0(StreamService.java:26) at org.my.AbstractMeglerService.execute(AbstractMeglerService.java:17) at org.my.StreamService.updateState(StreamService.java:26) at org.my.StreamService_ClientProxy.updateState(Unknown Source) at org.my.QConsumer.run(QConsumer.java:33) at io.smallrye.context.impl.wrappers.SlowContextualRunnable.run(SlowContextualRunnable.java:19) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:548) at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449) at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478) at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29) at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:834) Caused by: java.lang.InterruptedException at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1040) at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1345) at java.base/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:232) at io.smallrye.mutiny.operators.uni.UniBlockingAwait.await(UniBlockingAwait.java:61) ... 45 more

lthasle commented 2 years ago

@sberyozkin I get the same behavior if I try without a Q, but in another thread See stacktrace below

Required change: ` MyResource @Path("/ok") @GET public void ok() { //service.updateState(); CompletableFuture.runAsync(() -> service.updateState(), managedExecutor); // managedExecutor injected }

java.util.concurrent.CompletionException: java.lang.InterruptedException at io.smallrye.mutiny.operators.uni.UniBlockingAwait.await(UniBlockingAwait.java:73) at io.smallrye.mutiny.groups.UniAwait.atMost(UniAwait.java:62) at io.smallrye.mutiny.groups.UniAwait.indefinitely(UniAwait.java:43) at io.quarkus.oidc.client.runtime.TokensHelper.initTokens(TokensHelper.java:20) at io.quarkus.oidc.client.runtime.AbstractTokensProducer.initTokens(AbstractTokensProducer.java:38) at io.quarkus.oidc.client.runtime.AbstractTokensProducer.init(AbstractTokensProducer.java:33) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.create(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.create(Unknown Source) at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:96) at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:29) at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:26) at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26) at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69) at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:26) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.get(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.get(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_Bean.create(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_Bean.create(Unknown Source) at io.quarkus.arc.impl.RequestContext.getIfActive(RequestContext.java:68) at io.quarkus.arc.impl.ClientProxies.getDelegate(ClientProxies.java:27) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_ClientProxy.arc$delegate(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_ClientProxy.getAccessToken(Unknown Source) at org.my.StreamAuthenticationFilterMidtNorge.filter(StreamAuthenticationFilterMidtNorge.java:21) at org.jboss.resteasy.reactive.client.handlers.ClientRequestFilterRestHandler.handle(ClientRequestFilterRestHandler.java:24) at org.jboss.resteasy.reactive.client.handlers.ClientRequestFilterRestHandler.handle(ClientRequestFilterRestHandler.java:9) at org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:141) at org.jboss.resteasy.reactive.client.impl.AsyncInvokerImpl.performRequestInternal(AsyncInvokerImpl.java:262) at org.jboss.resteasy.reactive.client.impl.AsyncInvokerImpl.performRequestInternal(AsyncInvokerImpl.java:252) at org.jboss.resteasy.reactive.client.impl.AsyncInvokerImpl.method(AsyncInvokerImpl.java:212) at org.jboss.resteasy.reactive.client.impl.InvocationBuilderImpl.method(InvocationBuilderImpl.java:324) at org.my.StreamClientMidtNorge$$QuarkusRestClientInterface.updatestate(Unknown Source) at org.my.StreamService.lambda$0(StreamService.java:26) at org.my.AbstractMeglerService.execute(AbstractMeglerService.java:17) at org.my.StreamService.updateState(StreamService.java:26) at org.my.StreamService_ClientProxy.updateState(Unknown Source) at org.my.MyResource.lambda$0(MyResource.java:30) at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1736) at io.smallrye.context.impl.wrappers.SlowContextualRunnable.run(SlowContextualRunnable.java:19) at io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:543) at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449) at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452) at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29) at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:834) Caused by: java.lang.InterruptedException at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1040) at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1345) at java.base/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:232) at io.smallrye.mutiny.operators.uni.UniBlockingAwait.await(UniBlockingAwait.java:61) ... 44 more `

geoand commented 2 years ago

I might be misreading this, but why would a request made from the scheduler be expected to be able to retrieve OIDC token from the current request (which doesn't exist)?

sberyozkin commented 2 years ago

Hi @geoand the filter which is applied to the rest client retrieves this token from the remote OIDC server and it is failing; I'll need to add a test to reproduce

geoand commented 2 years ago

Ah okay. I misunderstood what it does then.

Thanks

sberyozkin commented 2 years ago

Hi @lthasle I've finally found the time to add a test, please see #22987. It works fine. (I tested the default filter as well separately)

The only significant difference between your code and the test which I see is that you inject the client (and the factory) directly into Runnable while in the test, Runnable uses the client injected into the endpoint (please try something similar as well). If PR is approved then it will resolve this issue. may be it will make it to 2.7.0.CR1 but if not it should make it to 2.7.0.Final. Please try it then and if it still does not work then please re-open.

Something else might be contributing to the failure in your case. Note, @stuartwdouglas has just improved oidc-client not to depend on vertx-http but only on vertx-core - it might be related as well. So yes, try 2.7.0 CR1/Final please

lthasle commented 2 years ago

@sberyozkin Thanks for your effort, but I get the same fault when I use 2.7.0.CR1 Same applies if I replace the classic dependencies with the reactive ones as well. I am not sure how I can re-open the issue.

javax.ws.rs.ProcessingException: java.util.concurrent.CompletionException: java.lang.InterruptedException at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.filterRequest(ClientInvocation.java:780) at org.jboss.resteasy.microprofile.client.impl.MpClientInvocation.filterRequest(MpClientInvocation.java:75) at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.invoke(ClientInvocation.java:491) at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invokeSync(ClientInvoker.java:152) at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientInvoker.invoke(ClientInvoker.java:115) at org.jboss.resteasy.client.jaxrs.internal.proxy.ClientProxy.invoke(ClientProxy.java:76) at com.sun.proxy.$Proxy117.updatestate(Unknown Source) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.jboss.resteasy.microprofile.client.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:146) at com.sun.proxy.$Proxy118.updatestate(Unknown Source) at org.my.StreamService.lambda$0(StreamService.java:26) at org.my.AbstractMeglerService.execute(AbstractMeglerService.java:17) at org.my.StreamService.updateState(StreamService.java:26) at org.my.StreamService_ClientProxy.updateState(Unknown Source) at org.my.QConsumer.run(QConsumer.java:33) at io.smallrye.context.impl.wrappers.SlowContextualRunnable.run(SlowContextualRunnable.java:19) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:548) at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449) at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478) at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29) at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:834) Caused by: java.util.concurrent.CompletionException: java.lang.InterruptedException at io.smallrye.mutiny.operators.uni.UniBlockingAwait.await(UniBlockingAwait.java:79) at io.smallrye.mutiny.groups.UniAwait.atMost(UniAwait.java:65) at io.smallrye.mutiny.groups.UniAwait.indefinitely(UniAwait.java:46) at io.quarkus.oidc.client.runtime.TokensHelper.initTokens(TokensHelper.java:20) at io.quarkus.oidc.client.runtime.AbstractTokensProducer.initTokens(AbstractTokensProducer.java:38) at io.quarkus.oidc.client.runtime.AbstractTokensProducer.init(AbstractTokensProducer.java:33) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.create(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.create(Unknown Source) at io.quarkus.arc.impl.AbstractSharedContext.createInstanceHandle(AbstractSharedContext.java:101) at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:29) at io.quarkus.arc.impl.AbstractSharedContext$1.get(AbstractSharedContext.java:26) at io.quarkus.arc.impl.LazyValue.get(LazyValue.java:26) at io.quarkus.arc.impl.ComputingCache.computeIfAbsent(ComputingCache.java:69) at io.quarkus.arc.impl.AbstractSharedContext.get(AbstractSharedContext.java:26) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.get(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_Bean.get(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_Bean.create(Unknown Source) at io.quarkus.oidc.client.runtime.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_Bean.create(Unknown Source) at io.quarkus.arc.impl.RequestContext.getIfActive(RequestContext.java:68) at io.quarkus.arc.impl.ClientProxies.getDelegate(ClientProxies.java:27) at io.quarkus.oidc.client.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_ClientProxy.arc$delegate(Unknown Source) at io.quarkus.oidc.client.TokensProducer_MidtNorge_ProducerMethod_produceTokens_494654c3bfa2346b017c24e2e2c4fcfc99087d0e_ClientProxy.getAccessToken(Unknown Source) at org.my.StreamAuthenticationFilterMidtNorge.filter(StreamAuthenticationFilterMidtNorge.java:23) at org.jboss.resteasy.client.jaxrs.internal.ClientInvocation.filterRequest(ClientInvocation.java:767) ... 27 more Caused by: java.lang.InterruptedException at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1040) at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1345) at java.base/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:232) at io.smallrye.mutiny.operators.uni.UniBlockingAwait.await(UniBlockingAwait.java:67) ... 50 more

sberyozkin commented 2 years ago

@lthasle Hi, missed your comment, reopened. I don't know what else can be done - can you please create a specific reproducer, with a test similar to the one I added in my PR ? (The client calls the frontend endpoint, this endpoint, in turn, from a Runnable task calls the downstream endpoint). For example, in your reproducer you have

stream.api.midtnorge/mp-rest/url=https://mysite.com
stream.api.midtnorge/mp-rest/scope=javax.enterprise.context.ApplicationScoped

quarkus.oidc-client.MidtNorge.discovery-enabled=false
quarkus.oidc-client.MidtNorge.auth-server-url=${stream.api.midtnorge/mp-rest/url}

But it can't really work - the downstream target and OIDC server URLs are the same.

How about checkout out Quarkus and modifying the test I've added until you reproduce the problem - everything is already set up there except for the broker ?

lthasle commented 2 years ago

@sberyozkin

Is there a guide which shows how I can setup my environment to run your test? I guess I need something in my settings.xml?

` Quarkus - Documentation ............................ SKIPPED [INFO] ------------------------------------------------------------------------ [INFO] BUILD FAILURE [INFO] ------------------------------------------------------------------------ [INFO] Total time: 44.735 s [INFO] Finished at: 2022-01-24T19:19:37+01:00 [INFO] ------------------------------------------------------------------------ [ERROR] Failed to execute goal on project quarkus-bootstrap-gradle-resolver: Could not resolve dependencies for project io.quarkus:quarkus-bootstrap-gradle-resolver:jar:999-SNAPSHOT: Could not find artifact org.gradle:gradle-tooling-api:jar:7.3.3 in nexus.intern (http://XXX.no/repository/public/) -> [Help 1] [ERROR] [ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch. [ERROR] Re-run Maven using the -X switch to enable full debug logging. [ERROR] [ERROR] For more information about the errors and possible solutions, please read the following articles: [ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/DependencyResolutionException [ERROR] [ERROR] After correcting the problems, you can resume the build with the command [ERROR] mvn -rf :quarkus-bootstrap-gradle-resolver ~/temp/tst/quarkus on main $ mvn clean compile -Pquick-build

`

sberyozkin commented 2 years ago

@lthasle Did you checkout the main branch and built it, see https://github.com/quarkusio/quarkus/blob/main/CONTRIBUTING.md ? CC @gsmet

sberyozkin commented 2 years ago

Looks like you did, sorry

stuartwdouglas commented 2 years ago

You just need to add an @ActivateRequestContext to org.my.QConsumer#run.

Note that if you run the test you will still see a different exception as Quarkus will shutdown before the startup task is complete (once the test is run quarkus shuts down, but the run method is async).

I think this can be closed.

lthasle commented 2 years ago

@sberyozkin @stuartwdouglas THANKS! It works with @ActivateRequestContext

sberyozkin commented 2 years ago

@stuartwdouglas Thanks Stuart, I've learned something new :-) @lthasle Glad it works for you now :-)