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

LDAP connection errors when using DS7 and rest2ldap test

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 6.5.0, 6.5.2.1, 7.0.0
    • Fix Version/s: None
    • Component/s: CTS
    • Labels:

      Description

      Bug description

      rest2ldap test with latest DS 7.0.0-SNAPSHOT d670452bfbf 2019-10-08 20:02:29 and AM 6.5.0 fails when asked to issue access token. Roughly one of five requests fail with error 500 after 120 seconds of waiting, others are issued all right (HTTP status 200).

      • Issue persists after DS restart
      • Issue disappears after restart of tomcat where AM lives
      • Turning debug level to message on AM side is accepted by XUI, however debug logs are still filled as if debug=error
      • Test works well with previous DS versions.

      Error in debug says:

      OAuth2Provider:10/11/2019 12:57:22:406 odp. CEST: Thread[http-nio-8083-exec-10,5,main]: TransactionId[7993c746-967e-4ed4-a828-fb1c4bf1d612-1877]
      ERROR: StatefulTokenStore::Could not create access token: Could not create token
      
      amSession:10/11/2019 10:12:19:560 AM CEST: Thread[http-nio-8081-exec-9,5,main]: TransactionId[35a7a6ee-919b-45b4-bdd3-d4c79c76434b-1984]
      ERROR: Unable to persist session to data store, check documentation for CTS configuration to ensure reads and writes may occur, and all appropriate virtual attributes are enabled.
      org.forgerock.openam.cts.exceptions.CoreTokenException: 
      CTS: Timed out whilst waiting for result
      	at org.forgerock.openam.cts.impl.queue.AsyncResultHandler.getResults(AsyncResultHandler.java:81)
      	at org.forgerock.openam.cts.monitoring.impl.queue.TokenMonitoringResultHandler.getResults(TokenMonitoringResultHandler.java:42)
      	at org.forgerock.openam.cts.monitoring.impl.queue.TokenMonitoringResultHandler.getResults(TokenMonitoringResultHandler.java:19)
      	at org.forgerock.openam.cts.CTSPersistentStoreImpl.create(CTSPersistentStoreImpl.java:114)
      	at org.forgerock.openam.cts.CTSPersistentStoreImpl.create(CTSPersistentStoreImpl.java:100)
      	at org.forgerock.openam.cts.CtsTokenManagementLayer.create(CtsTokenManagementLayer.java:56)
      	at org.forgerock.openam.session.cts.SessionPersistenceStore.create(SessionPersistenceStore.java:113)
      	at org.forgerock.openam.session.cts.CtsSessionPersistenceStore.store(CtsSessionPersistenceStore.java:54)
      	at org.forgerock.openam.session.cts.CtsSessionStoreChain$ChainIterator.store(CtsSessionStoreChain.java:62)
      	at org.forgerock.openam.session.cts.SessionPersistenceManagerStep.store(SessionPersistenceManagerStep.java:41)
      	at org.forgerock.openam.session.cts.CtsSessionStoreChain$ChainIterator.store(CtsSessionStoreChain.java:60)
      	at org.forgerock.openam.session.cts.DsameSessionInterceptorStep.store(DsameSessionInterceptorStep.java:58)
      	at org.forgerock.openam.session.cts.CtsSessionStoreChain$ChainIterator.store(CtsSessionStoreChain.java:60)
      	at org.forgerock.openam.session.cts.InMemoryCtsSessionCacheStep.store(InMemoryCtsSessionCacheStep.java:133)
      	at org.forgerock.openam.session.cts.CtsSessionStoreChain$ChainIterator.store(CtsSessionStoreChain.java:60)
      	at org.forgerock.openam.session.cts.AbstractCtsSessionStoreStep.store(AbstractCtsSessionStoreStep.java:27)
      	at org.forgerock.openam.session.cts.CtsSessionStoreChain$ChainIterator.store(CtsSessionStoreChain.java:60)
      	at org.forgerock.openam.session.cts.CtsSessionStoreChain.store(CtsSessionStoreChain.java:36)
      	at org.forgerock.openam.session.cts.CtsSessionAccessManager.persistCtsSession(CtsSessionAccessManager.java:152)
      	at org.forgerock.openam.session.cts.CtsSessionBuilder.build(CtsSessionBuilder.java:113)
      	at com.iplanet.dpro.session.monitoring.MonitoredBuilder.build(MonitoredBuilder.java:93)
      	at com.sun.identity.authentication.service.LoginState.produceSessionFromState(LoginState.java:1131)
      	at com.sun.identity.authentication.service.AMLoginContext.runLogin(AMLoginContext.java:576)
      	at com.sun.identity.authentication.server.AuthContextLocal.submitRequirements(AuthContextLocal.java:586)
      	at org.forgerock.openam.core.rest.authn.core.wrappers.AuthContextLocalWrapper.submitRequirements(AuthContextLocalWrapper.java:108)
      	at org.forgerock.openam.core.rest.authn.core.LoginProcess.next(LoginProcess.java:168)
      	at org.forgerock.openam.core.rest.authn.RestAuthenticationHandler.processAuthentication(RestAuthenticationHandler.java:415)
      	at org.forgerock.openam.core.rest.authn.RestAuthenticationHandler.authenticate(RestAuthenticationHandler.java:209)
      	at org.forgerock.openam.core.rest.authn.http.AuthenticationServiceV1.authenticate(AuthenticationServiceV1.java:164)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at org.forgerock.openam.http.annotations.AnnotatedMethod.invoke(AnnotatedMethod.java:76)
      	at org.forgerock.openam.http.annotations.Endpoints$1.handle(Endpoints.java:64)
      	at org.forgerock.http.routing.Router.handle(Router.java:100)
      	at org.forgerock.openam.audit.AbstractHttpAccessAuditFilter.filter(AbstractHttpAccessAuditFilter.java:59)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:53)
      	at org.forgerock.http.routing.Router.handle(Router.java:100)
      	at org.forgerock.openam.rest.RealmContextFilter.filter(RealmContextFilter.java:87)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:53)
      	at org.forgerock.http.routing.Router.handle(Router.java:100)
      	at org.forgerock.http.routing.Router.handle(Router.java:100)
      	at org.forgerock.openam.rest.RealmRoutingFactory$ChfRealmRouter.handle(RealmRoutingFactory.java:140)
      	at org.forgerock.http.handler.Handlers$UndescribedAsDescribableHandler.handle(Handlers.java:179)
      	at org.forgerock.openam.rest.RealmRoutingFactory$HostnameFilter.filter(RealmRoutingFactory.java:117)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:53)
      	at org.forgerock.http.routing.Router.handle(Router.java:100)
      	at org.forgerock.http.routing.Router.handle(Router.java:100)
      	at org.forgerock.openam.rest.CsrfFilter.filter(CsrfFilter.java:94)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:53)
      	at org.forgerock.http.routing.ResourceApiVersionRoutingFilter.filter(ResourceApiVersionRoutingFilter.java:59)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:53)
      	at org.forgerock.caf.authentication.framework.AuthenticationFramework.grantAccess(AuthenticationFramework.java:188)
      	at org.forgerock.caf.authentication.framework.AuthenticationFramework.lambda$onValidateRequestSuccess$1(AuthenticationFramework.java:181)
      	at org.forgerock.util.promise.Promises$CompletedPromise.thenAsync(Promises.java:260)
      	at org.forgerock.util.promise.Promises$CompletedPromise.thenAsync(Promises.java:249)
      	at org.forgerock.caf.authentication.framework.AuthenticationFramework.validateRequest(AuthenticationFramework.java:144)
      	at org.forgerock.caf.authentication.framework.AuthenticationFramework.processMessage(AuthenticationFramework.java:134)
      	at org.forgerock.caf.authentication.framework.AuthenticationFilter.filter(AuthenticationFilter.java:84)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:53)
      	at org.forgerock.openam.http.GuiceHandler.handle(GuiceHandler.java:51)
      	at org.forgerock.openam.http.HttpRoute$6.handle(HttpRoute.java:206)
      	at org.forgerock.http.routing.Router.handle(Router.java:100)
      	at org.forgerock.openam.dpro.session.ProofOfPossessionTokenFilter.filter(ProofOfPossessionTokenFilter.java:87)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:53)
      	at org.forgerock.http.swagger.OpenApiRequestFilter.filter(OpenApiRequestFilter.java:63)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:53)
      	at org.forgerock.openam.http.ApiDescriptorFilter.filter(ApiDescriptorFilter.java:139)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:53)
      	at org.forgerock.openam.http.OpenAMHttpApplication$1.filter(OpenAMHttpApplication.java:74)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:53)
      	at org.forgerock.http.filter.TransactionIdInboundFilter.filter(TransactionIdInboundFilter.java:86)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:53)
      	at org.forgerock.http.servlet.HttpFrameworkServlet.service(HttpFrameworkServlet.java:252)
      	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at org.forgerock.openam.services.datastore.DataStoreConsistencyFilter.lambda$doFilter$0(DataStoreConsistencyFilter.java:46)
      	at org.forgerock.openam.service.datastore.ReentrantVolatileActionConsistencyController.safeExecute(ReentrantVolatileActionConsistencyController.java:37)
      	at org.forgerock.openam.services.datastore.DataStoreConsistencyFilter.doFilter(DataStoreConsistencyFilter.java:46)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at org.forgerock.openam.rest.ProtocolVersionFilter.doFilter(ProtocolVersionFilter.java:65)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at org.forgerock.openam.validation.ResponseValidationFilter.doFilter(ResponseValidationFilter.java:59)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at org.forgerock.openam.headers.SetHeadersFilter.doFilter(SetHeadersFilter.java:80)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at com.sun.identity.setup.AMSetupFilter.doFilter(AMSetupFilter.java:115)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at org.forgerock.openam.audit.context.AuditContextFilter.doFilter(AuditContextFilter.java:46)
      	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
      	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
      	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:200)
      	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
      	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:490)
      	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
      	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
      	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:678)
      	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
      	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
      	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408)
      	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
      	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:834)
      	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1415)
      	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
      	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
      	at java.lang.Thread.run(Thread.java:748)
      
      

      How to reproduce the issue

      1. run pyforge test with -n to not clean environment afterwards. Test will succeed or maybe fail due to this error during test setup (it doesn't matter), however environment will be set for following check in step 2.

      python3 cleanup.py -fa
      python3 run-pybot.py -n --cfg rest2ldap.cfg -v -c stress -s rest2ldap.oauth2.embedded -t OAuth2_CTS_Load OpenDJ

      2.  do 10 requests to get access token

       http -f -a "clientOIDC_0:password" POST "${URL}/oauth2/access_token?realm=/myrealm" grant_type="password" username="user.0" password="password" scope="uid"
      

       Expected behaviour

      Access token is always issued
      

      Current behaviour

      One or two times of five will not work, there is HTTP 500 in tomcat access log after 120 seconds

      Work around

      Restart AM container

        Attachments

        1. am-cts-issue.patch
          2 kB
        2. am-cts-issue-v2.patch
          2 kB
        3. rest2ldap.cfg
          9 kB

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              lubomir.mlich Ľubomír Mlích
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated: