search

micronaut-projects / micronaut-starter

Generates Micronaut applications
Apache License 2.0
211 stars 96 forks source link

HttpClient OAuth2 Client Credentials times out #867

Closed kamaydeo closed 3 years ago

kamaydeo commented 3 years ago

Description

HttpClient call times out when used in conjunction with OAuth2 Client Credentials Flow. I'm invoking Bitbucket REST API using Micronaut HttpClient.

Task List

Steps to Reproduce

Refer to README.md

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

Expected Behavior

HTTP Call should return successfully

Actual Behavior

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.

Environment Information

Example Application

The application below has BitbucketService which calls Bitbucket APIs using HttpClient. BitbucketController is provided to invoke the BitBucketService over HTTP. This helps with reproducing the buggy behavior.

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)
kamaydeo commented 3 years ago

Moved it under correct project. https://github.com/micronaut-projects/micronaut-security/issues/750 Closing this issue.