search

micronaut-projects / micronaut-security

The official Micronaut security solution
Apache License 2.0
168 stars 124 forks source link

HttpClient OAuth2 Client Credentials times out #750

Closed kamaydeo closed 3 years ago

kamaydeo commented 3 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

  1. Build and run the example application
  2. Invoke Test Endpoint

Environment Information

Example Application

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

Version

2.5.11

sdelamo commented 3 years ago

Read timeout for Micronaut HTTP client defaults to 10 seconds.

You could update it to a more sensible default for your use case: 

micronaut:
    http:
        client:
            read-timeout: 15s

See Configuring HTTP Clients

Please, reopen if this does not fix the issue.

kamaydeo commented 3 years ago

Suggested fix does not resolve above issue. Now it times out after 15s. Anyways, please run the example I have provided. BTW, I can't reopen the issue so opening a new one.

kamaydeo commented 3 years ago

@sdelamo Any updates?

kamaydeo commented 3 years ago

It's been 20 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 invest fully into this. It was just a POC to compare it against Spring and outcome is very clear.

tchiotludo commented 2 years ago

comment move here : https://github.com/micronaut-projects/micronaut-security/issues/752