search

micronaut-projects / micronaut-security

The official Micronaut security solution
Apache License 2.0
166 stars 122 forks source link

HttpClient with OAuth2 Client Credentials doesn't work #752

Open kamaydeo opened 2 years ago

kamaydeo commented 2 years ago

Expected Behavior

HTTP Call should return successfully

Actual Behaviour

HTTP calls times out. The token is received and you can see that in the trace logs, but the chain of calls hang, and no call to bitbucket is ever made. Application goes in a strange hung state and any subsequent calls fail.

Stacktrace

 __  __ _                                  _   
|  \/  (_) ___ _ __ ___  _ __   __ _ _   _| |_ 
| |\/| | |/ __| '__/ _ \| '_ \ / _` | | | | __|
| |  | | | (__| | | (_) | | | | (_| | |_| | |_ 
|_|  |_|_|\___|_|  \___/|_| |_|\__,_|\__,_|\__|
  Micronaut (v2.5.11)

Aug 06, 2021 7:23:59 PM org.apache.coyote.AbstractProtocol init
INFO: Initializing ProtocolHandler ["http-nio-8080"]
Aug 06, 2021 7:23:59 PM org.apache.catalina.core.StandardService startInternal
INFO: Starting service [Tomcat]
Aug 06, 2021 7:23:59 PM org.apache.catalina.core.StandardEngine startInternal
INFO: Starting Servlet engine: [Apache Tomcat/9.0.38]
Aug 06, 2021 7:24:00 PM org.apache.coyote.AbstractProtocol start
INFO: Starting ProtocolHandler ["http-nio-8080"]
19:24:00.077 [main] INFO  io.micronaut.runtime.Micronaut -  INFO [,,] Startup completed in 1446ms. Server Running: http://0.0.0.0:8080
19:24:04.694 [default-nioEventLoopGroup-1-1] DEBUG i.m.h.client.netty.DefaultHttpClient - DEBUG [3d32a2db4143c880,3d32a2db4143c880,] Sending HTTP POST to https://bitbucket.org/site/oauth2/access_token
19:24:04.695 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Accept: application/json
19:24:04.695 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Authorization: Basic QWtlM3FDTGtmQzViR1lldjJxOnJIMmVhUE5zOUFqUEJtM3I1dEJxNW1SVVdlTWNrVTR1
19:24:04.696 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-B3-TraceId: 3d32a2db4143c880
19:24:04.696 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-B3-SpanId: abbf68a55213dee8
19:24:04.696 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-B3-ParentSpanId: 3d32a2db4143c880
19:24:04.696 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-B3-Sampled: 0
19:24:04.696 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] content-type: application/x-www-form-urlencoded
19:24:04.696 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] host: bitbucket.org
19:24:04.696 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] connection: close
19:24:04.696 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] content-length: 29
19:24:04.696 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Request Body
19:24:04.696 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] ----
19:24:04.696 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] grant_type=client_credentials
19:24:04.696 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] ----
19:24:04.965 [default-nioEventLoopGroup-1-1] DEBUG i.m.h.client.netty.DefaultHttpClient - DEBUG [3d32a2db4143c880,3d32a2db4143c880,] Received response 200 from https://bitbucket.org/site/oauth2/access_token
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Content-Security-Policy-Report-Only: script-src 'unsafe-eval' 'strict-dynamic' 'unsafe-inline' 'self' http: https: https://d301sr5gafysq2.cloudfront.net; style-src 'self' 'unsafe-inline' https://aui-cdn.atlassian.com https://d301sr5gafysq2.cloudfront.net; report-uri https://web-security-reports.services.atlassian.com/csp-report/bb-website; default-src 'self' 'unsafe-inline' 'unsafe-eval' data: blob: *; connect-src bitbucket.org *.bitbucket.org bb-inf.net *.bb-inf.net id.atlassian.com analytics.atlassian.com as.atlassian.com api-private.stg.atlassian.com api-private.atlassian.com cofs.staging.public.atl-paas.net cofs.prod.public.atl-paas.net intake.opbeat.com api.media.atlassian.com api.segment.io xid.statuspage.io xid.atlassian.com xid.sourcetreeapp.com bam.nr-data.net bam-cell.nr-data.net sentry.io bqlf8qjztdtr.statuspage.io https://d301sr5gafysq2.cloudfront.net; object-src about:; base-uri 'self'
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Server: nginx
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Usage-Quota-Remaining: 999185.861
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Vary: Accept-Language, Origin
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Usage-Request-Cost: 829.47
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Cache-Control: no-cache, no-store, must-revalidate, max-age=0
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Content-Type: application/json
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-B3-TraceId: 3d32a2db4143c880
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Usage-Output-Ops: 0
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Dc-Location: Micros
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Date: Fri, 06 Aug 2021 23:24:04 GMT
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Usage-User-Time: 0.024884
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Usage-System-Time: 0.000000
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Served-By: 5bfd97f0ee5a
19:24:04.966 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Expires: Fri, 06 Aug 2021 23:24:04 GMT
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Consumer-Client-Id: Ake3qCLkfC5bGYev2q
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Content-Language: en
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-View-Name: bitbucket.apps.oauth.oauth20.access_token_request
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Static-Version: 3e2aaee80e34
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Render-Time: 0.0532510280609
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Connection: close
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Token-Id: 81536379
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Usage-Input-Ops: 0
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Grant-Type: client_credentials
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Request-Count: 239
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Version: 3e2aaee80e34
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-Frame-Options: SAMEORIGIN
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] X-App-Key: Ake3qCLkfC5bGYev2q
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] content-length: 323
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] Response Body
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] ----
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] {"scopes": "project snippet pullrequest", "access_token": "HQxsrDUEuKNbk2TdTuPDNVPltgg-BPoDiUPqMVQn669YbsIB1VG0G-0NFbBjpRA8rDzymokUQp0mZkfDmjSDunV3RlryvOSNOg827hB6bPUd-_K6W6kL27GJGumkvz5D-nnD9ESzEPDHM2IaoUsg", "expires_in": 7200, "token_type": "bearer", "state": "client_credentials", "refresh_token": "Jru9Egxk7arwdS2GrQ"}
19:24:04.967 [default-nioEventLoopGroup-1-1] TRACE i.m.h.client.netty.DefaultHttpClient - TRACE [3d32a2db4143c880,3d32a2db4143c880,] ----
19:24:15.563 [http-nio-8080-exec-1] ERROR i.m.servlet.http.ServletHttpHandler - ERROR [3d32a2db4143c880,3d32a2db4143c880,] Internal Server Error: Read Timeout
io.micronaut.http.client.exceptions.ReadTimeoutException: Read Timeout
    at io.micronaut.http.client.exceptions.ReadTimeoutException.<clinit>(ReadTimeoutException.java:26)
    at io.micronaut.http.client.netty.DefaultHttpClient.lambda$null$36(DefaultHttpClient.java:1179)
    at io.reactivex.internal.operators.flowable.FlowableOnErrorNext$OnErrorNextSubscriber.onError(FlowableOnErrorNext.java:103)
    at io.micronaut.reactive.rxjava2.RxInstrumentedSubscriber.onError(RxInstrumentedSubscriber.java:66)
    at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutSubscriber.onTimeout(FlowableTimeoutTimed.java:139)
    at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutTask.run(FlowableTimeoutTimed.java:170)
    at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66)
    at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
    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:829)

Steps To Reproduce

Refer to README.md

Environment Information

Example Application

https://github.com/kamaydeo/http-oauth-client-test

Version

2.5.11

kamaydeo commented 2 years ago

opening a new one since https://github.com/micronaut-projects/micronaut-security/issues/750 was closed incorrectly.

kamaydeo commented 2 years ago

It's been 15 days and no concrete response. I am giving up and closing this issue. It seems like micronaut team is not ready yet and it's waste of time for me to give it a try. I am so happy that I didn't fully invest into this. It was just a POC to compare it against Spring and outcome is very clear.

sdelamo commented 2 years ago

@kamaydeo I saw you deleted the sample application. Could you upload it again?

Moreover, note many of the contributors to Micronaut were on vacation during many weeks in august. Plus we were in the middle of Micronaut 3 release.

tchiotludo commented 2 years ago

I have also the issue on my side, with differents oauth2 authority (pingone & google on my side). This error is raised only just after startup of the app, during the first init of an oauth login.

The oauth client fetch the well-know during the first init on the application. This files is static & deliver in micro seconds by providers.
I've tried to raise the timeout to 5 minutes without any changes.

I have the issue with last version but I have issue since 2.x at least.

Here is the stack trace : 

Error instantiating bean of type  [io.micronaut.security.oauth2.client.DefaultOpenIdProviderMetadata]

Message: Read Timeout
Path Taken: DefaultOpenIdProviderMetadata.openIdConfiguration(OauthClientConfiguration oauthClientConfiguration,OpenIdClientConfiguration openIdClientConfiguration,HttpClient issuerClient)
io.micronaut.context.exceptions.BeanInstantiationException: Error instantiating bean of type  [io.micronaut.security.oauth2.client.DefaultOpenIdProviderMetadata]

Message: Read Timeout
Path Taken: DefaultOpenIdProviderMetadata.openIdConfiguration(OauthClientConfiguration oauthClientConfiguration,OpenIdClientConfiguration openIdClientConfiguration,HttpClient issuerClient)
  at io.micronaut.context.DefaultBeanContext.doCreateBean(DefaultBeanContext.java:2363)
  at io.micronaut.context.DefaultBeanContext.createAndRegisterSingletonInternal(DefaultBeanContext.java:3281)
  at io.micronaut.context.DefaultBeanContext.createAndRegisterSingleton(DefaultBeanContext.java:3267)
  at io.micronaut.context.DefaultBeanContext.getBeanForDefinition(DefaultBeanContext.java:2820)
  at io.micronaut.context.DefaultBeanContext.getBeanInternal(DefaultBeanContext.java:2782)
  at io.micronaut.context.DefaultBeanContext.getBean(DefaultBeanContext.java:1638)
  at
graemerocher commented 2 years ago

@tchiotludo can you provide an example that reproduces the issue?

tchiotludo commented 2 years ago

I will try but I can't reproduce the issue on my machine but I've doubt to succeed. I was able to reproduce the issue on local with this command sudo cpulimit --pid 663800 --limit 10 but It don't seems to be relevant.

I've the feeling that the issue is mostly on docker env deployed to the cloud (limited by cpu like 2 cores). I've 95% reproduction on my env (private code), no matter when the container start (even few hours after), the first hit on /oauth/login/google will timeout after micronaut client timeout even if the timeout is raised. Just after the first error, the second hit will work very quickly with response on few ms.

Stacktrace with micronaut 3.2.3 ``` 2022-01-06 20:35:23,711 ERROR default-nioEventLoopGroup-1-13 i.k.w.controllers.ErrorController Error instantiating bean of type [io.micronaut.security.oauth2.client.DefaultOpenIdProviderMetadata] Message: Read Timeout Path Taken: DefaultOpenIdProviderMetadata.openIdConfiguration(OauthClientConfiguration oauthClientConfiguration,OpenIdClientConfiguration openIdClientConfiguration,HttpClient issuerClient) io.micronaut.context.exceptions.BeanInstantiationException: Error instantiating bean of type [io.micronaut.security.oauth2.client.DefaultOpenIdProviderMetadata] Message: Read Timeout Path Taken: DefaultOpenIdProviderMetadata.openIdConfiguration(OauthClientConfiguration oauthClientConfiguration,OpenIdClientConfiguration openIdClientConfiguration,HttpClient issuerClient) at io.micronaut.context.DefaultBeanContext.doCreateBean(DefaultBeanContext.java:2363) Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: Assembly trace from producer [reactor.core.publisher.FluxLift] : reactor.core.publisher.Flux.error(Flux.java:872) io.micronaut.http.server.RouteExecutor.lambda$executeRoute$14(RouteExecutor.java:663) Error has been observed at the following site(s): |_ Flux.error ⇢ at io.micronaut.http.server.RouteExecutor.lambda$executeRoute$14(RouteExecutor.java:663) |_ Flux.deferContextual ⇢ at io.micronaut.http.server.RouteExecutor.executeRoute(RouteExecutor.java:640) |_ Flux.flatMap ⇢ at io.micronaut.http.server.RouteExecutor.buildRouteResponsePublisher(RouteExecutor.java:611) |_ Flux.flatMap ⇢ at io.micronaut.http.server.RouteExecutor.buildResultEmitter(RouteExecutor.java:627) Stack trace: at io.micronaut.context.DefaultBeanContext.doCreateBean(DefaultBeanContext.java:2363) at io.micronaut.context.DefaultBeanContext.createAndRegisterSingletonInternal(DefaultBeanContext.java:3281) at io.micronaut.context.DefaultBeanContext.createAndRegisterSingleton(DefaultBeanContext.java:3267) at io.micronaut.context.DefaultBeanContext.getBeanForDefinition(DefaultBeanContext.java:2820) at io.micronaut.context.DefaultBeanContext.getBeanInternal(DefaultBeanContext.java:2782) at io.micronaut.context.DefaultBeanContext.getBean(DefaultBeanContext.java:1638) at io.micronaut.inject.provider.BeanProviderDefinition$1.get(BeanProviderDefinition.java:68) at io.micronaut.core.util.SupplierUtil$1.initialize(SupplierUtil.java:48) at io.micronaut.core.util.SupplierUtil$1.get(SupplierUtil.java:43) at io.micronaut.security.oauth2.client.DefaultOpenIdClient.authorizationRedirect(DefaultOpenIdClient.java:123) at io.micronaut.security.oauth2.routes.DefaultOauthController.login(DefaultOauthController.java:76) at io.micronaut.security.oauth2.routes.$DefaultOauthController$Definition$Exec.dispatch(Unknown Source) at io.micronaut.context.AbstractExecutableMethodsDefinition$DispatchedExecutableMethod.invoke(AbstractExecutableMethodsDefinition.java:351) at io.micronaut.inject.ExecutionHandle$1.invoke(ExecutionHandle.java:114) at io.micronaut.web.router.AbstractRouteMatch.execute(AbstractRouteMatch.java:303) at io.micronaut.web.router.RouteMatch.execute(RouteMatch.java:111) at io.micronaut.http.context.ServerRequestContext.with(ServerRequestContext.java:103) at io.micronaut.http.server.RouteExecutor.lambda$executeRoute$14(RouteExecutor.java:656) at reactor.core.publisher.FluxDeferContextual.subscribe(FluxDeferContextual.java:49) at reactor.core.publisher.Flux.subscribe(Flux.java:8402) at reactor.core.publisher.FluxFlatMap$FlatMapMain.onNext(FluxFlatMap.java:426) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onNext(ReactorSubscriber.java:57) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onNext(FluxHide.java:137) at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2398) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.request(FluxHide.java:152) at reactor.core.publisher.FluxFlatMap$FlatMapMain.onSubscribe(FluxFlatMap.java:371) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onSubscribe(ReactorSubscriber.java:50) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onSubscribe(FluxHide.java:122) at reactor.core.publisher.FluxJust.subscribe(FluxJust.java:68) at reactor.core.publisher.Flux.subscribe(Flux.java:8402) at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onNext(MonoFlatMapMany.java:195) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onNext(ReactorSubscriber.java:57) at reactor.core.publisher.MonoNext$NextSubscriber.onNext(MonoNext.java:82) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onNext(ReactorSubscriber.java:57) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.innerNext(FluxConcatMap.java:282) at reactor.core.publisher.FluxConcatMap$ConcatMapInner.onNext(FluxConcatMap.java:861) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onNext(ReactorSubscriber.java:57) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onNext(FluxHide.java:137) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onNext(MonoPeekTerminal.java:180) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onNext(ReactorSubscriber.java:57) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onNext(FluxHide.java:137) at reactor.core.publisher.FluxFilterFuseable$FilterFuseableSubscriber.onNext(FluxFilterFuseable.java:118) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onNext(ReactorSubscriber.java:57) at reactor.core.publisher.FluxDefaultIfEmpty$DefaultIfEmptySubscriber.onNext(FluxDefaultIfEmpty.java:101) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onNext(ReactorSubscriber.java:57) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onNext(FluxHide.java:137) at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2398) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.request(FluxHide.java:152) at reactor.core.publisher.FluxDefaultIfEmpty$DefaultIfEmptySubscriber.request(FluxDefaultIfEmpty.java:77) at reactor.core.publisher.FluxFilterFuseable$FilterFuseableSubscriber.request(FluxFilterFuseable.java:191) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.request(FluxHide.java:152) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.request(MonoPeekTerminal.java:139) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.request(FluxHide.java:152) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:2194) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:2068) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onSubscribe(ReactorSubscriber.java:50) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onSubscribe(FluxHide.java:122) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onSubscribe(MonoPeekTerminal.java:152) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onSubscribe(ReactorSubscriber.java:50) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onSubscribe(FluxHide.java:122) at reactor.core.publisher.FluxFilterFuseable$FilterFuseableSubscriber.onSubscribe(FluxFilterFuseable.java:87) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onSubscribe(ReactorSubscriber.java:50) at reactor.core.publisher.FluxDefaultIfEmpty$DefaultIfEmptySubscriber.onSubscribe(FluxDefaultIfEmpty.java:91) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onSubscribe(ReactorSubscriber.java:50) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onSubscribe(FluxHide.java:122) at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:55) at reactor.core.publisher.Mono.subscribe(Mono.java:4338) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:449) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onNext(FluxConcatMap.java:251) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onNext(ReactorSubscriber.java:57) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onNext(FluxHide.java:137) at reactor.core.publisher.FluxIterable$IterableSubscription.slowPath(FluxIterable.java:270) at reactor.core.publisher.FluxIterable$IterableSubscription.request(FluxIterable.java:228) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.request(FluxHide.java:152) at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onSubscribe(FluxConcatMap.java:236) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onSubscribe(ReactorSubscriber.java:50) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onSubscribe(FluxHide.java:122) at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:164) at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:86) at reactor.core.publisher.InternalFluxOperator.subscribe(InternalFluxOperator.java:62) at reactor.core.publisher.FluxDefer.subscribe(FluxDefer.java:54) at reactor.core.publisher.Mono.subscribe(Mono.java:4338) at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onComplete(FluxSwitchIfEmpty.java:82) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onComplete(ReactorSubscriber.java:71) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onComplete(FluxHide.java:147) at reactor.core.publisher.MonoFlatMap$FlatMapMain.onComplete(MonoFlatMap.java:181) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onComplete(ReactorSubscriber.java:71) at reactor.core.publisher.MonoNext$NextSubscriber.onComplete(MonoNext.java:102) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onComplete(ReactorSubscriber.java:71) at reactor.core.publisher.FluxFlatMap$FlatMapMain.checkTerminated(FluxFlatMap.java:846) at reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:608) at reactor.core.publisher.FluxFlatMap$FlatMapMain.drain(FluxFlatMap.java:588) at reactor.core.publisher.FluxFlatMap$FlatMapMain.onComplete(FluxFlatMap.java:465) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onComplete(ReactorSubscriber.java:71) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onComplete(FluxHide.java:147) at reactor.core.publisher.FluxIterable$IterableSubscription.slowPath(FluxIterable.java:292) at reactor.core.publisher.FluxIterable$IterableSubscription.request(FluxIterable.java:228) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.request(FluxHide.java:152) at reactor.core.publisher.FluxFlatMap$FlatMapMain.onSubscribe(FluxFlatMap.java:371) at io.micronaut.reactive.reactor.instrument.ReactorSubscriber.onSubscribe(ReactorSubscriber.java:50) at reactor.core.publisher.FluxHide$SuppressFuseableSubscriber.onSubscribe(FluxHide.java:122) at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:164) at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:86) at reactor.core.publisher.InternalFluxOperator.subscribe(InternalFluxOperator.java:62) at io.micronaut.configuration.metrics.binder.web.WebMetricsPublisher.subscribe(WebMetricsPublisher.java:157) at reactor.core.publisher.Flux.subscribe(Flux.java:8402) at io.micronaut.http.server.netty.RoutingInBoundHandler.handleRouteMatch(RoutingInBoundHandler.java:571) at io.micronaut.http.server.netty.RoutingInBoundHandler.channelRead0(RoutingInBoundHandler.java:434) at io.micronaut.http.server.netty.RoutingInBoundHandler.channelRead0(RoutingInBoundHandler.java:141) at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:102) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.micronaut.http.netty.stream.HttpStreamsHandler.channelRead(HttpStreamsHandler.java:223) at io.micronaut.http.netty.stream.HttpStreamsServerHandler.channelRead(HttpStreamsServerHandler.java:123) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93) at io.netty.handler.codec.http.websocketx.extensions.WebSocketServerExtensionHandler.channelRead(WebSocketServerExtensionHandler.java:99) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103) at io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93) at io.netty.handler.codec.http.HttpServerKeepAliveHandler.channelRead(HttpServerKeepAliveHandler.java:64) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.handler.flow.FlowControlHandler.dequeue(FlowControlHandler.java:200) at io.netty.handler.flow.FlowControlHandler.channelRead(FlowControlHandler.java:162) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93) at io.kestra.webserver.utils.HttpServerAccessLogHandler.channelRead(HttpServerAccessLogHandler.java:103) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.micronaut.http.server.netty.handler.accesslog.HttpAccessLogHandler.channelRead(HttpAccessLogHandler.java:96) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296) at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:829) Caused by: io.micronaut.http.client.exceptions.ReadTimeoutException: Read Timeout ```

In a meantime, I have also this : https://github.com/tchiotludo/akhq/issues/914. Maybe the issue is on http client

graemerocher commented 2 years ago

Does configuring a separate event loop for the server help? https://docs.micronaut.io/latest/guide/#threadPools

tchiotludo commented 2 years ago

I overestimate the 95% reproduction.

I've try few time since your message and I'm not sure about the result: Seems that when I restart the pod and hit the request, No timeout is coming. So I tried with or without the threadPools, don't see any change. But don't have reproduction at this time.

I've the feeling now, that if we start the server, don't hit the oauth login for long time (health check are in parallel and works), and try to logged after some time, the timeout is reached. When the first hit is done, no more error.

Sorry not a real reproduction for now.

Jim-Harrington commented 2 years ago

I think issue #909 may be related. In trying to figure out what was going on with my #909 problem, I switched from running on micronaut-http-server-tomcat to micronaut-http-server-netty. As soon as I did that, the problem went from the auth token being attached twice to outgoing HTTP requests timing out.

tchiotludo commented 2 years ago

Not really sure @Jim-Harrington, I'm on netty since the beginning (2.x, 3.x)

Jim-Harrington commented 2 years ago

...and so was I when my #909 problem turned into the socket timeouts you're reporting here.

My turn out not to be related, but there are certainly several issues in this auto propagation stuff.

vinhnx222 commented 6 months ago

@tchiotludo Did you get any solution on how to fix it?

tchiotludo commented 6 months ago

@vinhnx222 since latest version, I don't see anymore the error, I'm on the micronautVersion=3.10.1