Uploaded image for project: 'OpenAM'
  1. OpenAM
  2. OPENAM-11778

Getting accessToken using authorization_code result in Unhandled exception

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 14.5.0
    • Fix Version/s: 7.0.0
    • Component/s: CTS
    • Labels:
    • Rank:
      1|hzu8gv:
    • Support Ticket IDs:

      Description

      Running stress test BBC.BBC_site OpenAM.
      doing
      > RestLogin (OK=1000000 KO=0 )
      > Authorize (OK=1000000 KO=0 )
      > AccessToken (OK=999970 KO=30 )

      Topology is haproxy fronting 3 AM with 2 CTS servers in failover mode.
      Client is gatling, 100 concurrent clients, 1m users.

      Using stateful oauth2 session, sometimes (30 of 1m in this case) the request to get a access token from authorization code fails with 'Internal Server Error (500)'

      Example:
      =========================
      HTTP request:
      POST http://grana.internal.forgerock.com:8080/openam/oauth2/access_token?realm=myrealm
      headers=
      Content-Type: application/x-www-form-urlencoded
      Accept: /
      Cookie: iPlanetDirectoryPro=3ja7c4bB3t9vP6x39kuTWHjK6zs.AAJTSQACMDQAAlNLABxIRlRyUlhjakczbnFaZDJJL3B4MktDWk1BaXM9AAJTMQACMDE.; iPlanetDirectoryPro=3ja7c4bB3t9vP6x39kuTWHjK6zs.AAJTSQACMDQAAlNLABxIRlRyUlhjakczbnFaZDJJL3B4MktDWk1BaXM9AAJTMQACMDE.; amlbcookie=01
      Content-Length: 106
      Host: grana.internal.forgerock.com:8080
      Authorization: Basic Y2xpZW50T0lEQzpwYXNzd29yZA==
      params=
      grant_type: authorization_code
      code: 9647234c-2184-4a52-9970-1c35070461ef
      redirect_uri: http://fake.com
      realm=Realm

      {principal='clientOIDC', scheme=BASIC, realmName='null', nonce='null', algorithm='null', response='null', qop='null', nc='00000001', cnonce='null', uri='null', methodName='GET', useAbsoluteURI='false', omitQuery='false'}

      =========================
      HTTP response:
      status=
      500 Internal Server Error
      headers=
      X-Frame-Options: SAMEORIGIN
      Pragma: no-cache
      Cache-Control: no-store
      Date: Tue, 19 Sep 2017 12:15:06 GMT
      Accept-Ranges: bytes
      Server: Restlet-Framework/2.3.4
      Vary: Accept-Charset, Accept-Encoding, Accept-Language, Accept
      Content-Type: application/json
      Transfer-Encoding: chunked
      Connection: close

      body=

      {"error_description":"Internal Server Error","error":"server_error"}

      There is an error in OAuth2Provider debug log:
      OAuth2Provider:09/19/2017 02:15:06:319 PM CEST: Thread[http-nio-8080-exec-67,5,main]: TransactionId[0a1e82a9-b55c-4cb2-b532-7005c0456c48-12629149]
      ERROR: Unhandled exception:
      Internal Server Error (500) - The server encountered an unexpected condition which prevented it from fulfilling the request
      at org.restlet.resource.ServerResource.doHandle(ServerResource.java:539)
      at org.restlet.resource.ServerResource.post(ServerResource.java:1377)
      at org.restlet.resource.ServerResource.doHandle(ServerResource.java:620)
      at org.restlet.resource.ServerResource.doNegotiatedHandle(ServerResource.java:678)
      at org.restlet.resource.ServerResource.doConditionalHandle(ServerResource.java:356)
      at org.restlet.resource.ServerResource.handle(ServerResource.java:1043)
      at org.restlet.resource.Finder.handle(Finder.java:236)
      at org.restlet.routing.Filter.doHandle(Filter.java:150)
      at org.restlet.routing.Filter.handle(Filter.java:197)
      at org.restlet.routing.Filter.doHandle(Filter.java:150)
      at org.restlet.routing.Filter.handle(Filter.java:197)
      at org.restlet.routing.Filter.doHandle(Filter.java:150)
      at org.restlet.routing.Filter.handle(Filter.java:197)
      at org.restlet.routing.Router.doHandle(Router.java:422)
      at org.forgerock.openam.rest.service.RestletRealmRouter.doHandle(RestletRealmRouter.java:93)
      at org.restlet.routing.Router.handle(Router.java:639)
      at org.restlet.routing.Filter.doHandle(Filter.java:150)
      at org.restlet.routing.Filter.handle(Filter.java:197)
      at org.restlet.routing.Filter.doHandle(Filter.java:150)
      at org.restlet.routing.Filter.handle(Filter.java:197)
      at org.restlet.routing.Filter.doHandle(Filter.java:150)
      at org.restlet.engine.application.StatusFilter.doHandle(StatusFilter.java:140)
      at org.restlet.routing.Filter.handle(Filter.java:197)
      at org.restlet.routing.Filter.doHandle(Filter.java:150)
      at org.restlet.routing.Filter.handle(Filter.java:197)
      at org.restlet.engine.CompositeHelper.handle(CompositeHelper.java:202)
      at org.restlet.engine.application.ApplicationHelper.handle(ApplicationHelper.java:75)
      at org.restlet.Application.handle(Application.java:385)
      at org.restlet.routing.Filter.doHandle(Filter.java:150)
      at org.restlet.routing.Filter.handle(Filter.java:197)
      at org.restlet.routing.Router.doHandle(Router.java:422)
      at org.restlet.routing.Router.handle(Router.java:639)
      at org.restlet.routing.Filter.doHandle(Filter.java:150)
      at org.restlet.routing.Filter.handle(Filter.java:197)
      at org.restlet.routing.Router.doHandle(Router.java:422)
      at org.restlet.routing.Router.handle(Router.java:639)
      at org.restlet.routing.Filter.doHandle(Filter.java:150)
      at org.restlet.routing.Filter.handle(Filter.java:197)
      at org.restlet.engine.CompositeHelper.handle(CompositeHelper.java:202)
      at org.restlet.Component.handle(Component.java:408)
      at org.restlet.Server.handle(Server.java:507)
      at org.restlet.engine.connector.ServerHelper.handle(ServerHelper.java:63)
      at org.restlet.engine.adapter.HttpServerHelper.handle(HttpServerHelper.java:143)
      at org.restlet.ext.servlet.ServerServlet.service(ServerServlet.java:1117)
      at org.forgerock.openam.rest.RestEndpointServlet.service(RestEndpointServlet.java:122)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:292)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
      at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
      at org.forgerock.openam.validation.ResponseValidationFilter.doFilter(ResponseValidationFilter.java:36)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
      at org.forgerock.openam.headers.SetHeadersFilter.doFilter(SetHeadersFilter.java:80)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
      at com.sun.identity.setup.AMSetupFilter.doFilter(AMSetupFilter.java:111)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
      at org.forgerock.openam.audit.context.AuditContextFilter.doFilter(AuditContextFilter.java:46)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:212)
      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:94)
      at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:504)
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:141)
      at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
      at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:620)
      at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:502)
      at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1132)
      at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:684)
      at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1533)
      at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1489)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
      at java.lang.Thread.run(Thread.java:745)
      Caused by: java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@6a5517a2 rejected from java.util.concurrent.ThreadPoolExecutor@424341a0[Running, pool size = 50, active threads = 2, queued tasks = 10, completed tasks = 450986]
      at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2047)
      at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:823)
      at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1369)
      at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:134)
      at org.forgerock.openam.audit.context.AuditRequestContextPropagatingExecutorService.submit(AuditRequestContextPropagatingExecutorService.java:95)
      at org.forgerock.openam.scripting.ThreadPoolScriptEvaluator.evaluateScript(ThreadPoolScriptEvaluator.java:80)
      at org.forgerock.openam.oauth2.OpenAMScopeValidator.getUserInfo(OpenAMScopeValidator.java:250)
      at org.forgerock.oauth2.core.RealmOAuth2ProviderSettings.getUserInfo(RealmOAuth2ProviderSettings.java:372)
      at org.forgerock.openam.oauth2.StatefulTokenStore.createOpenIDToken(StatefulTokenStore.java:315)
      at org.forgerock.openam.oauth2.OpenAMTokenStore.createOpenIDToken(OpenAMTokenStore.java:81)
      at org.forgerock.openidconnect.OpenIDTokenIssuer.issueToken(OpenIDTokenIssuer.java:74)
      at org.forgerock.openam.oauth2.OpenAMScopeValidator.additionalDataToReturnFromTokenEndpoint(OpenAMScopeValidator.java:531)
      at org.forgerock.oauth2.core.RealmOAuth2ProviderSettings.additionalDataToReturnFromTokenEndpoint(RealmOAuth2ProviderSettings.java:389)
      at org.forgerock.oauth2.core.AuthorizationCodeGrantTypeHandler.handle(AuthorizationCodeGrantTypeHandler.java:161)
      at org.forgerock.oauth2.core.GrantTypeHandler.handle(GrantTypeHandler.java:70)
      at org.forgerock.oauth2.core.AccessTokenService.requestAccessToken(AccessTokenService.java:110)
      at org.forgerock.oauth2.restlet.TokenEndpointResource.token(TokenEndpointResource.java:81)
      at sun.reflect.GeneratedMethodAccessor147.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at java.lang.reflect.Method.invoke(Method.java:498)
      at org.restlet.resource.ServerResource.doHandle(ServerResource.java:520)
      ... 78 more

      This is logged 30 times, so i'm sure it is related.
      grep -c "Internal Server Error" OAuth2Provider
      30

      There are other errors in: Session debug log:
      amCoreTokenService:09/19/2017 02:08:16:986 PM CEST: Thread[http-nio-8080-exec-64,5,main]: TransactionId[0a1e82a9-b55c-4cb2-b532-7005c0456c48-2424326]
      ERROR: The CTS token reaper cache is full. This will result in degraded performance. You should increase the cache size by setting the advanced server property 'org.forgerock.services.cts.reaper.cache.size' to a number higher than 400000.

      So reaper cache need increasing.

      Also in CoreSystem debug log:

      TransactionId[0a1e82a9-b55c-4cb2-b532-7005c0456c48-0]
      ERROR: CTS Async: Task Processor Error: processing task
      org.forgerock.openam.sm.datalayer.api.DataLayerException:
      CTS: Error during partial query
      [.......]

      Caused by: org.forgerock.openam.cts.exceptions.QueryFailedException:
      CTS: Failed to complete query:
      DN: dc=com
      Conn: FailoverLoadBalancerConnection
      Filter: (&(&(coreTokenType=OAUTH_BLACKLIST)(coreTokenDate01>=20170919120558.134Z)(!(coreTokenString01=01)))(objectClass=frCoreToken))
      at org.forgerock.openam.sm.datalayer.impl.ldap.LdapSearchHandler.performSearch(LdapSearchHandler.java:62)
      at org.forgerock.openam.sm.datalayer.impl.ldap.LdapQueryBuilder.getEntries(LdapQueryBuilder.java:147)
      at org.forgerock.openam.sm.datalayer.impl.ldap.LdapQueryBuilder.access$000(LdapQueryBuilder.java:51)
      at org.forgerock.openam.sm.datalayer.impl.ldap.LdapQueryBuilder$EntryIterator.next(LdapQueryBuilder.java:274)
      ... 13 more
      Caused by: org.forgerock.opendj.ldap.AuthorizationException: Insufficient Access Rights: You do not have sufficient privileges to perform an unindexed search

      Full debug logs are attached where Administrator of JIRA will let me.

        Attachments

        1. OAuth2Provider
          248 kB
        2. Session
          7 kB

          Activity

            People

            Assignee:
            jamesphillpotts James Phillpotts
            Reporter:
            gary.williams Gary Williams
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: