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

Suspected startup race when running with FBC

    Details

    • Type: Bug
    • Status: Open
    • Priority: Blocker
    • Resolution: Unresolved
    • Affects Version/s: 7.0.0
    • Fix Version/s: None
    • Component/s: None
    • Labels:

      Description

      Bug description

      We have recently noticed an issue that sometimes occurs when using AM with FBC only (no embedded DS) from the older docker image (although I suspect that it would also occur with the newer image, as it appears to be a problem with the AM binary, not with the config).

      AM gets into a state where every auth request fails (and probably others that use the auth framework too, e.g. OAuth grants), with logs as follows:

      2020-07-14T12:46:59.215492963Z amResourceLookup: resourceURL: null 
      2020-07-14T12:46:59.215753846Z amResourceLookup: resourceURL: null 
      2020-07-14T12:46:59.215922450Z amResourceLookup: resourceName: /config/auth/default/DataStore.xml 
      2020-07-14T12:46:59.216061398Z amResourceLookup: resourceName: /config/auth/default/DataStore.xml 
      2020-07-14T12:46:59.216697162Z AMModuleProperties, parse file :null 
      2020-07-14T12:46:59.217553485Z AMModuleProperties, parser error : 
      2020-07-14T12:46:59.222417004Z Authentication encountered an error: [Status: 401 Unauthorized] 
      2020-07-14T12:46:59.222864760Z Authentication encountered an error: [Status: 401 Unauthorized]
      

      On the "parser error" log entry, there is a stack trace:

      java.lang.NullPointerException: null
      	at com.sun.identity.authentication.spi.AMModuleProperties.<init>(AMModuleProperties.java:94)
      	at com.sun.identity.authentication.spi.AMModuleProperties.getModuleProperties(AMModuleProperties.java:170)
      	at com.sun.identity.authentication.spi.AMLoginModule.forceCallbacksInit(AMLoginModule.java:632)
      	at com.sun.identity.authentication.spi.AMLoginModule.getCallback(AMLoginModule.java:597)
      	at com.sun.identity.authentication.spi.AMLoginModule.getCallback(AMLoginModule.java:568)
      	at com.sun.identity.authentication.spi.AMLoginModule.login(AMLoginModule.java:1177)
      	at jdk.internal.reflect.GeneratedMethodAccessor95.invoke(Unknown Source)
      	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
      	at com.sun.identity.authentication.jaas.LoginContext.invoke(LoginContext.java:220)
      	at com.sun.identity.authentication.jaas.LoginContext.login(LoginContext.java:128)
      	at com.sun.identity.authentication.service.AMLoginContext.runLogin(AMLoginContext.java:531)
      	at com.sun.identity.authentication.service.AMLoginContext.executeLogin(AMLoginContext.java:501)
      	at com.sun.identity.authentication.server.AuthContextLocal.login(AuthContextLocal.java:430)
      	at com.sun.identity.authentication.server.AuthContextLocal.login(AuthContextLocal.java:355)
      	at com.sun.identity.authentication.server.AuthContextLocal.login(AuthContextLocal.java:288)
      	at com.sun.identity.authentication.server.AuthContextLocal.login(AuthContextLocal.java:223)
      	at org.forgerock.openam.core.rest.authn.core.wrappers.AuthContextLocalWrapper.login(AuthContextLocalWrapper.java:59)
      	at org.forgerock.openam.core.rest.authn.core.LoginAuthenticator.startLoginProcess(LoginAuthenticator.java:157)
      	at org.forgerock.openam.core.rest.authn.core.LoginAuthenticator.getLoginProcess(LoginAuthenticator.java:99)
      	at org.forgerock.openam.core.rest.authn.RestAuthenticationHandler.authenticate(RestAuthenticationHandler.java:235)
      	at org.forgerock.openam.core.rest.authn.http.AuthenticationServiceV1.authenticate(AuthenticationServiceV1.java:157)
      	at jdk.internal.reflect.GeneratedMethodAccessor93.invoke(Unknown Source)
      	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
      	at org.forgerock.openam.http.annotations.AnnotatedMethod.invoke(AnnotatedMethod.java:81)
      	at org.forgerock.openam.http.annotations.Endpoints$1.handle(Endpoints.java:77)
      	at org.forgerock.http.routing.Router.handle(Router.java:100)
      	at org.forgerock.openam.rest.DisableCachingFilter.filter(DisableCachingFilter.java:90)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	at org.forgerock.openam.audit.AbstractHttpAccessAuditFilter.filter(AbstractHttpAccessAuditFilter.java:88)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	at org.forgerock.http.routing.Router.handle(Router.java:100)
      	at org.forgerock.openam.cors.CorsFilter.filter(CorsFilter.java:77)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	at org.forgerock.openam.rest.RealmContextFilter.filter(RealmContextFilter.java:85)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	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:123)
      	at org.forgerock.http.handler.Handlers$UndescribedAsDescribableHandler.handle(Handlers.java:180)
      	at org.forgerock.openam.rest.RealmRoutingFactory$HostnameFilter.filter(RealmRoutingFactory.java:100)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	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:91)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	at org.forgerock.http.routing.ResourceApiVersionRoutingFilter.filter(ResourceApiVersionRoutingFilter.java:59)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	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:263)
      	at org.forgerock.util.promise.Promises$CompletedPromise.thenAsync(Promises.java:252)
      	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:85)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	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:88)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	at org.forgerock.http.swagger.OpenApiRequestFilter.filter(OpenApiRequestFilter.java:63)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	at org.forgerock.openam.http.ApiDescriptorFilter.filter(ApiDescriptorFilter.java:119)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	at org.forgerock.openam.http.ResponseContext$ResponseContextFilter.filter(ResponseContext.java:53)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	at org.forgerock.openam.http.OpenAMHttpApplication.lambda$static$1(OpenAMHttpApplication.java:60)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	at org.forgerock.openam.http.OpenAMHttpApplication.lambda$cacheHeaderFilter$3(OpenAMHttpApplication.java:88)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	at org.forgerock.http.filter.TransactionIdInboundFilter.filter(TransactionIdInboundFilter.java:86)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:54)
      	at org.forgerock.http.servlet.HttpFrameworkServlet.service(HttpFrameworkServlet.java:261)
      	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
      	at org.forgerock.openam.http.OpenAMHttpFrameworkServlet.service(OpenAMHttpFrameworkServlet.java:47)
      	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:66)
      	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.SecureCookieFilter.doFilter(SecureCookieFilter.java:62)
      	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.DisableSameSiteCookiesFilter.doFilter(DisableSameSiteCookiesFilter.java:105)
      	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 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 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:47)
      	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:202)
      	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
      	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
      	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:690)
      	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:373)
      	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
      	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
      	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
      	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
      	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
      	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
      	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
      	at java.base/java.lang.Thread.run(Thread.java:834)

      How to reproduce the issue

      Unfortunately the issue doesn't happen consistently, but given the code analysis, I think it can happen any time you run an FBC-only change.

      We have only been noticing this issue since the end of May. In mid-May we updated to AM commit 1ba49f89bf13e3d0543c80fd5fa284e32b5fd9e4 from the previous version we were using, 007878d135fb859c709c1c7c03ddccb582c9b2f5. I don't know if this is related, but the timing is slightly suspicious.

      Expected behaviour

      AM always works

      Current behaviour

      AM sometimes doesn't work

      Work around

      None

      Code analysis

      Looking at the logs and stack trace, it is possible to work out that AMModuleProperties#getModuleProperties(String fileName) is being called with a fileName of null. Tracking back through the stack, we find that the fileName is initialised in AMLoginModule.java:958:

      AMLoginModule.java
      fileName = loginState.getFileName(moduleClass+ ".xml");
      

      Eventually we then find that its value comes from AuthClientUtils.java:1886:

      AuthClientUtils.java
      resourceName = ResourceLookup.getFirstExisting(servletContext,
        fileRoot,localeName,
        orgFilePath,
        filePath,filename,
        templatePath);
      

      Looking at the code in ResourceLookup.java we find that the value ultimately comes from the ResourceLookup#getResourceURL(ServletContext, String):

      ResourceLookup.java
          private static URL getResourceURL(ServletContext context, String resourceName) {
              URL resourceURL = null;
              try {
                  if (context != null) {
                      resourceURL = context.getResource(resourceName);
                  }
                  //Only try to lookup XMLs from the classpath as UI files from JAR files cannot be used by RequestDispatcher
                  if (resourceURL == null && resourceName.endsWith(".xml")) {
                      // remove leading '/' from resourceName
                      resourceURL = Thread.currentThread().getContextClassLoader().getResource(resourceName.substring(1));
                  }
              } catch (MalformedURLException murle) {
                  DEBUG.debug("Error getting resource: " + resourceURL + " cause: " + murle.getMessage());
              }
              return resourceURL;
          }
      

      Now, looking in the docker container in the servlet context, we find:

      forgerock@am-7846f9c4df-lzggx:/usr/local/tomcat/webapps/am$ ls config/auth/default
      account_expired.jsp                Message.jsp
      Adaptive.xml                       module_denied.jsp
      [...snip...]
      Cert.xml                           OpenIdConnect.xml
      DataStore.xml                      org_inactive.jsp
      ...
      

      So, the path /config/auth/default/DataStore.xml does exist in the servlet context, so we must assume from the code above that the ServletContext passed to the getResourceURL method must be null because if it wasn't, we know that context.getResource(resourceName) would definitely return a non-null value.

      So, tracking back through the call heirarchy, we find where the ServletContext has come from in LoginState.java:1857:

      ResourceLookup.java
          public String getFileName(String fileName) {
              return AuthUtils.getFileName(fileName, getLocale(), getOrgDN(),
                      servletRequest, LazyConfig.AUTHD.getServletContext(), indexType, indexName);
          }
      

      Now looking at the AuthD class we find that the ServletContext in there would come from LoginLougoutMapping.java:112:

      ResourceLookup.java
          public boolean initializeAuth(ServletContext servletCtx) {
              AuthD authD = AuthD.getAuth();
              if (authD == null) {
                  return false;
              } else {
                  authD.setServletContext(servletCtx);
              }
              return true;
          }
      

      In order for the servletCtx to be null in the AuthD instance, either this method was never called (it's called from AMSetupServlet, so we can eliminate this), or the authD instance was null.

      If you look at the AuthD#getAuth() method, you can see that it uses the SingletonHolder pattern that is vulnerable to sometimes not returning the value you might otherwise think it would (Google has some good results for explaining deficiencies in the singleton patterns in Java).

      Thoughts:

      • The SingletonHolder in AuthD should be swapped for a in implementation using the more robust enum-based pattern
      • In AMSetupServlet,java:1051 where LoginLogoutMapping#initializeAuth(ServletContext) is called, the return value should be being checked, and if false, maybe it should be retried a couple of times (with a little sleep)?
      • There are a few places in the above referenced code that could benefit from some extra logging to trap this error

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              jamesphillpotts James Phillpotts
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated: