[keycloak-user] Wildfly adapter: failed to turn code into token: java.net.SocketException
Jesse Chahal
jessec at stytch.com
Tue Nov 29 18:50:28 EST 2016
I've found the cause of the Issue and wanted to report back incase others
also have this issue. The problem was being caused by AWS NAT Gateway
instances terminating long lived Connections after 5mins using a RST packet
instead of a FIN packet (read up on TCP protocol if unfamiliar with the
different packet types). In our case the keycloak server and the app
servers live in different networks, they need to go through the NAT Gateway
to talk to each other. It is considered good (and common) practice in the
AWS world to use NAT Gateways. The apache HTTPClient does connection
pooling with 20 connections by default. It also supposedly does retry once
or twice. The problem here is that all the connections within the pool are
essentially dead because of RST packets sent to all connections within the
pool (HTTPClient doesn't seem to handle this well). So when the Client does
retry with new connections in the pool it continues to fail. What we did
was have a proxy (read this as AWS ELB) terminate connections after
60seconds (this is the default behaviour of AWS ELB's) using FIN packets.
This cleaner connection destruction is handled better by apache HTTPClient.
Another possible (but bad) solution is the change the connection pooling to
1 using keycloak adapter settings as when the retry happens a new
connection will be made instead of using another bad connection in the
pool. I hope this description will save someone weeks of time that it took
for us to discover and resolve the issue.
A good feature request here might have been to allow users to configure a
connection timeout for the keycloak adapter. This feature is supported by
HTTPClient but is not exposed by the adapter. Should be easy to add support
for this.
On Mon, Nov 28, 2016 at 4:50 PM, Jesse Chahal <jessec at stytch.com> wrote:
> We have been able to reproduce this problem using a single user where we
> dedicated 2 wildfly app servers and 1 keycloak server purely to test this
> out. We have also been able to reproduce this when trying to use multiple
> users as well (but I think the single user scenario is more important). I
> believe it may somehow router/network related but I have yet to find a way
> to prove it. I don't believe there are any docker network related
> limitations in regards to connections. Before this switch we have been
> running keycloak in production for awhile as well as the app servers (on
> full VM's instead of docker). It is unlikely that the problem exists in any
> of our app servers configuration since the configuration is 99% the same.
> In the new setup wildfly app servers live in docker (which are based off of
> the official jboss wildfly docker images).
>
>
> Jesse
>
> On Fri, Nov 25, 2016 at 1:01 AM, Marek Posolda <mposolda at redhat.com>
> wrote:
>
>> Does this happen just if more users tries to login concurrently? It seems
>> there is some limit somewhere for the number of maximum connections. Maybe
>> it will help to increase maximum number of threads at the undertow
>> subsystem on Keycloak side, or maybe at the AWS ELB load balancer side? Or
>> maybe there is even some limit at the docker level?
>>
>> AFAIK The Apache HTTP Client (which is used by our adapters under the
>> hood for exchange code to token) has some retry strategy enabled by
>> default. AFAIK we don't allow to tweak this, but it's likely 1 or 2 retries
>> for each HTTP failed request AFAIK. However this should be rather tweaked
>> by increasing the pool of connections for your server. Relying on Apache
>> HTTP client retryies doesn't look like good solution IMO.
>>
>> Marek
>>
>>
>> On 25/11/16 01:48, Jesse Chahal wrote:
>>
>>> We very recently started working on moving our web/app servers to AWS ECS
>>> (docker). We have been using docker locally for a very long time without
>>> issues.
>>> During this transition we started seeing intermittent login failures
>>> through the normal confidential browser redirect flow (not using
>>> implicit).
>>> It inconsistently fails during the process of turning an authorization
>>> code
>>> into a bearer+refresh_token. The exception is always the same as well. I
>>> have done
>>> tcpdumps packet analysis for things such as RST packets but have not seen
>>> anything that would result in this issue. I have confirmed that the
>>> adapter
>>> does
>>> have the authorization code (although I don't know how to validate it). I
>>> have confirmed that the the date+times are synchronized in both the auth
>>> server
>>> and the app server (therefore no weird expiration issues).
>>> I have posted a stacktrace from the adapter incase anyone else has seen
>>> this issue before. I'm hoping at the very least that maybe we could add a
>>> retry
>>> mechanism to the adapter if a Connection reset issues occurs if no other
>>> solutions present themselves.
>>>
>>> Current network setup:
>>> Keycloak.2.1.0.Final on Centos6 EC2/VM --> AWS ELB load balancer -->
>>> internet -->
>>>
>>> ↓
>>> <---------------------------------------------------------------------
>>> -----------
>>> ↓
>>> AWS NAT Gateway --> AWS ELB load balancer --> Amazon Linux ECS EC2/VM -->
>>> Wildfly10 docker container + keycloak 2.1.0-wildfly-adapter
>>>
>>>
>>> ERROR [org.keycloak.adapters.OAuthRequestAuthenticator] (default
>>> task-13) [
>>> ] failed to turn code into token: java.net.SocketException: Connection
>>> reset
>>> at java.net.SocketInputStream.read(SocketInputStream.java:209)
>>> [rt.jar:1.8.0_111]
>>> at java.net.SocketInputStream.read(SocketInputStream.java:141)
>>> [rt.jar:1.8.0_111]
>>> at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
>>> [jsse.jar:1.8.0_111]
>>> at sun.security.ssl.InputRecord.read(InputRecord.java:503)
>>> [jsse.jar:1.8.0_111]
>>> at
>>> sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
>>> [jsse.jar:1.8.0_111]
>>> at
>>> sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930)
>>> [jsse.jar:1.8.0_111]
>>> at sun.security.ssl.AppInputStream.read(AppInputStream.java:105
>>> )
>>> [jsse.jar:1.8.0_111]
>>> at
>>> org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffe
>>> r(AbstractSessionInputBuffer.java:160)
>>> at
>>> org.apache.http.impl.io.SocketInputBuffer.fillBuffer(SocketI
>>> nputBuffer.java:84)
>>> at
>>> org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(
>>> AbstractSessionInputBuffer.java:273)
>>> at
>>> org.apache.http.impl.conn.DefaultHttpResponseParser.parseHea
>>> d(DefaultHttpResponseParser.java:140)
>>> at
>>> org.apache.http.impl.conn.DefaultHttpResponseParser.parseHea
>>> d(DefaultHttpResponseParser.java:57)
>>> at
>>> org.apache.http.impl.io.AbstractMessageParser.parse(Abstract
>>> MessageParser.java:261)
>>> at
>>> org.apache.http.impl.AbstractHttpClientConnection.receiveRes
>>> ponseHeader(AbstractHttpClientConnection.java:283)
>>> at
>>> org.apache.http.impl.conn.DefaultClientConnection.receiveRes
>>> ponseHeader(DefaultClientConnection.java:251)
>>> at
>>> org.apache.http.impl.conn.AbstractClientConnAdapter.receiveR
>>> esponseHeader(AbstractClientConnAdapter.java:223)
>>> at
>>> org.apache.http.protocol.HttpRequestExecutor.doReceiveRespon
>>> se(HttpRequestExecutor.java:272)
>>> at
>>> org.apache.http.protocol.HttpRequestExecutor.execute(HttpReq
>>> uestExecutor.java:124)
>>> at
>>> org.apache.http.impl.client.DefaultRequestDirector.tryExecut
>>> e(DefaultRequestDirector.java:685)
>>> at
>>> org.apache.http.impl.client.DefaultRequestDirector.execute(D
>>> efaultRequestDirector.java:487)
>>> at
>>> org.apache.http.impl.client.AbstractHttpClient.doExecute(Abs
>>> tractHttpClient.java:882)
>>> at
>>> org.apache.http.impl.client.CloseableHttpClient.execute(Clos
>>> eableHttpClient.java:82)
>>> at
>>> org.apache.http.impl.client.CloseableHttpClient.execute(Clos
>>> eableHttpClient.java:107)
>>> at
>>> org.apache.http.impl.client.CloseableHttpClient.execute(Clos
>>> eableHttpClient.java:55)
>>> at
>>> org.keycloak.adapters.ServerRequest.invokeAccessCodeToToken(
>>> ServerRequest.java:107)
>>> at
>>> org.keycloak.adapters.OAuthRequestAuthenticator.resolveCode(
>>> OAuthRequestAuthenticator.java:327)
>>> at
>>> org.keycloak.adapters.OAuthRequestAuthenticator.authenticate
>>> (OAuthRequestAuthenticator.java:273)
>>> at
>>> org.keycloak.adapters.RequestAuthenticator.authenticate(Requ
>>> estAuthenticator.java:130)
>>> at
>>> org.keycloak.adapters.undertow.AbstractUndertowKeycloakAuthM
>>> ech.keycloakAuthenticate(AbstractUndertowKeycloakAuthMech.java:110)
>>> at
>>> org.keycloak.adapters.undertow.ServletKeycloakAuthMech.authe
>>> nticate(ServletKeycloakAuthMech.java:92)
>>> at
>>> io.undertow.security.impl.SecurityContextImpl$AuthAttempter.
>>> transition(SecurityContextImpl.java:233)
>>> at
>>> io.undertow.security.impl.SecurityContextImpl$AuthAttempter.
>>> transition(SecurityContextImpl.java:250)
>>> at
>>> io.undertow.security.impl.SecurityContextImpl$AuthAttempter.
>>> access$100(SecurityContextImpl.java:219)
>>> at
>>> io.undertow.security.impl.SecurityContextImpl.attemptAuthent
>>> ication(SecurityContextImpl.java:121)
>>> at
>>> io.undertow.security.impl.SecurityContextImpl.authTransition
>>> (SecurityContextImpl.java:96)
>>> at
>>> io.undertow.security.impl.SecurityContextImpl.authenticate(S
>>> ecurityContextImpl.java:89)
>>> at
>>> io.undertow.servlet.handlers.security.ServletAuthenticationC
>>> allHandler.handleRequest(ServletAuthenticationCallHandler.java:55)
>>> at
>>> io.undertow.server.handlers.DisableCacheHandler.handleReques
>>> t(DisableCacheHandler.java:33)
>>> at
>>> io.undertow.server.handlers.PredicateHandler.handleRequest(P
>>> redicateHandler.java:43)
>>> at
>>> io.undertow.security.handlers.AuthenticationConstraintHandle
>>> r.handleRequest(AuthenticationConstraintHandler.java:51)
>>> at
>>> io.undertow.security.handlers.AbstractConfidentialityHandler
>>> .handleRequest(AbstractConfidentialityHandler.java:46)
>>> at
>>> io.undertow.servlet.handlers.security.ServletConfidentiality
>>> ConstraintHandler.handleRequest(ServletConfidentialityConstr
>>> aintHandler.java:64)
>>> at
>>> io.undertow.servlet.handlers.security.ServletSecurityConstra
>>> intHandler.handleRequest(ServletSecurityConstraintHandler.java:56)
>>> at
>>> io.undertow.security.handlers.AuthenticationMechanismsHandle
>>> r.handleRequest(AuthenticationMechanismsHandler.java:60)
>>> at
>>> io.undertow.servlet.handlers.security.CachedAuthenticatedSes
>>> sionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
>>> at
>>> io.undertow.security.handlers.NotificationReceiverHandler.ha
>>> ndleRequest(NotificationReceiverHandler.java:50)
>>> at
>>> io.undertow.security.handlers.AbstractSecurityContextAssocia
>>> tionHandler.handleRequest(AbstractSecurityContextAssociation
>>> Handler.java:43)
>>> at
>>> io.undertow.server.handlers.PredicateHandler.handleRequest(P
>>> redicateHandler.java:43)
>>> at
>>> org.wildfly.extension.undertow.security.jacc.JACCContextIdHa
>>> ndler.handleRequest(JACCContextIdHandler.java:61)
>>> at
>>> io.undertow.server.handlers.PredicateHandler.handleRequest(P
>>> redicateHandler.java:43)
>>> at
>>> org.keycloak.adapters.undertow.ServletPreAuthActionsHandler.
>>> handleRequest(ServletPreAuthActionsHandler.java:69)
>>> at
>>> io.undertow.server.handlers.PredicateHandler.handleRequest(P
>>> redicateHandler.java:43)
>>> at
>>> io.undertow.servlet.handlers.ServletInitialHandler.handleFir
>>> stRequest(ServletInitialHandler.java:284)
>>> at
>>> io.undertow.servlet.handlers.ServletInitialHandler.dispatchR
>>> equest(ServletInitialHandler.java:263)
>>> at
>>> io.undertow.servlet.handlers.ServletInitialHandler.access$00
>>> 0(ServletInitialHandler.java:81)
>>> at
>>> io.undertow.servlet.handlers.ServletInitialHandler$1.handleR
>>> equest(ServletInitialHandler.java:174)
>>> at
>>> io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
>>> at
>>> io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
>>> at
>>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPool
>>> Executor.java:1142)
>>> [rt.jar:1.8.0_111]
>>> at
>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoo
>>> lExecutor.java:617)
>>> [rt.jar:1.8.0_111]
>>> at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_111]
>>>
>>> 2016-11-24 22:37:14,255 WARN
>>> [com.indicee.service.authorization.EjbTimerInterceptor] (default
>>> task-13)
>>> [ ] UserIdentityServiceImpl:findByEmail took 484 ms
>>> 2016-11-24 22:37:14,256 WARN
>>> [com.indicee.service.authorization.EjbTimerInterceptor] (default
>>> task-13)
>>> [ ] AccountSrvImpl:isCurrentAccountUnknown took 499 ms
>>> 2016-11-24 22:37:14,257 WARN
>>> [com.indicee.service.authorization.EjbTimerInterceptor] (default
>>> task-13)
>>> [ ] BrandedVariableLookupSrvImpl:cacheKey took 500 ms
>>> 2016-11-24 22:37:14,959 WARN
>>> [com.indicee.service.authorization.EjbTimerInterceptor] (default
>>> task-13)
>>> [ ] UserIdentityServiceImpl:findByEmail took 697 ms
>>> 2016-11-24 22:37:14,960 WARN
>>> [com.indicee.service.authorization.EjbTimerInterceptor] (default
>>> task-13)
>>> [ ] AccountSrvImpl:isCurrentAccountUnknown took 701 ms
>>> 2016-11-24 22:37:14,962 WARN
>>> [com.indicee.service.authorization.EjbTimerInterceptor] (default
>>> task-13)
>>> [ ] BrandedVariableLookupSrvImpl:getVariables took 703 ms
>>> 2016-11-24 22:37:15,095 INFO
>>> [com.indicee.service.servlet.filter.ClientRequestIdFilter] (default
>>> task-14) [ ] Setting clientId [gwt_43cpg2jpm5oklfjkuue204jsmh] for
>>> session
>>> [qAYdgQ6PytsZ8kG5ah6mxEdmGeNPQpgT_2ExqU6A] created [1480026525644]
>>> 2016-11-24 22:37:15,096 INFO
>>> [com.indicee.service.servlet.filter.ClientRequestIdFilter] (default
>>> task-14) [ ] clientRequestId via atomic integer =
>>> [gwt_43cpg2jpm5oklfjkuue204jsmh_0]
>>> 2016-11-24 22:37:15,138 INFO
>>> [com.indicee.service.servlet.filter.ClientRequestIdFilter] (default
>>> task-15) [ ] clientRequestId via atomic integer =
>>> [gwt_43cpg2jpm5oklfjkuue204jsmh_1]
>>> 2016-11-24 22:37:15,224 INFO
>>> [com.indicee.service.servlet.filter.ClientRequestIdFilter] (default
>>> task-12) [ ] clientRequestId via atomic integer =
>>> [gwt_43cpg2jpm5oklfjkuue204jsmh_2]
>>> 2016-11-24 22:37:15,635 WARN
>>> [com.indicee.service.authorization.EjbTimerInterceptor]
>>> (dInitialHandler.java:284)
>>> at
>>> io.undertow.servlet.handlers.ServletInitialHandler.dispatchR
>>> equest(ServletIni
>>> tialHandler.java:263)
>>> at
>>> io.undertow.servlet.handlers.ServletInitialHandler.access$00
>>> 0(ServletInitialH
>>> andler.java:81)
>>> at
>>> io.undertow.servlet.handlers.ServletInitialHandler$1.handleR
>>> equest(ServletIni
>>> tialHandler.java:174)
>>> at
>>> io.undertow.server.Connectors.executeRootHandler(Connectors.java:202)
>>> at
>>> io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:793)
>>> at
>>> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPool
>>> Executor.java:114
>>> 2) [rt.jar:1.8.0_111]
>>> at
>>> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoo
>>> lExecutor.java:61
>>> 7) [rt.jar:1.8.0_111]
>>> at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_111]
>>> _______________________________________________
>>> keycloak-user mailing list
>>> keycloak-user at lists.jboss.org
>>> https://lists.jboss.org/mailman/listinfo/keycloak-user
>>>
>>
>>
>>
>
More information about the keycloak-user
mailing list