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

Agent Audit logging spams ERROR level logs

    Details

    • Type: Improvement
    • Status: Open
    • Priority: Minor
    • Resolution: Unresolved
    • Affects Version/s: 5.5.1
    • Fix Version/s: None
    • Component/s: audit logging, web agents
    • Labels:
    • Rank:
      1|hzvvqv:
    • Support Ticket IDs:

      Description

      Bug description

      CoreSystem log in ERROR level debugging is getting lots of the following exceptions:

      amLog:04/30/2018 10:08:11:450 AM BST: Thread[http-nio-28080-exec-2,5,main]: TransactionId[51681112-dc76-441c-b057-d7a910949374-105022]
      ERROR: LogService::process():
      java.lang.NullPointerException: trackingId value cannot be null
       at org.forgerock.util.Reject.checkNotNull(Reject.java:82)
       at org.forgerock.util.Reject.ifNull(Reject.java:240)

      It appears that is occurred by Agent's (remote) auditing. 

      How to reproduce the issue

      1. Install and configure a Web Agent with the following config:

      com.sun.identity.agents.config.audit.accesstype = LOG_BOTH
      com.sun.identity.agents.config.log.disposition = REMOTE
      com.sun.identity.agents.config.remote.log.interval = 1

      2. Authenticate against the protected URL -> session is created

      3. Immediately invalidate the session via the Admin Console

      4. Observe the CoreSystem logs with the default debugging level (ERROR)

       

      You will see the a NPE: trackingId value cannot be null exception log.

      It appears that trackingID refers to contextID which is some kind of session identifier. So as long as the session is gone, there is no contextID.

       

      Now, if you turn on WARNING level debugging, you will see that before this call, there is another exception which says that session has not be found which is followed by the empty trackingId:

      amLog:04/30/2018 10:08:11:445 AM BST: Thread[http-nio-28080-exec-2,5,main]: TransactionId[51681112-dc76-441c-b057-d7a910949374-105022]
      WARNING: LogService::process(): SSOException
      com.iplanet.sso.SSOException: Invalid session ID.Session not found. This likely means it has expired and been removed.
       at com.iplanet.sso.providers.dpro.SSOProviderImpl.createSSOToken(SSOProviderImpl.java:140)
       at com.iplanet.sso.providers.dpro.SSOProviderImpl.createSSOToken(SSOProviderImpl.java:221)
       at com.iplanet.sso.providers.dpro.SSOProviderImpl.createSSOToken(SSOProviderImpl.java:204)
       at com.iplanet.sso.providers.dpro.SSOProviderImpl.createSSOToken(SSOProviderImpl.java:234)
       at com.iplanet.sso.SSOTokenManager.createSSOToken(SSOTokenManager.java:371)
       at com.sun.identity.log.service.LogRecWrite.execute(LogRecWrite.java:137)
       at com.sun.identity.log.service.LogService.process(LogService.java:185)
       at com.iplanet.services.comm.server.PLLRequestServlet.handleRequest(PLLRequestServlet.java:202)
       at com.iplanet.services.comm.server.PLLRequestServlet.doPost(PLLRequestServlet.java:140)
       at javax.servlet.http.HttpServlet.service(HttpServlet.java:648)
       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:1539)
       at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1495)
       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)
      Caused by: org.forgerock.openam.dpro.session.InvalidSessionIdException: Invalid session ID.Session not found. This likely means it has expired and been removed.
       at org.forgerock.openam.session.cts.CtsSessionWrapper.getSession(CtsSessionWrapper.java:162)
       at org.forgerock.openam.session.cts.CtsSessionWrapper.<init>(CtsSessionWrapper.java:49)
       at org.forgerock.openam.session.cts.CtsOperations.resolveSession(CtsOperations.java:317)
       at com.iplanet.dpro.session.monitoring.MonitoredOperations.lambda$resolveSession$2(MonitoredOperations.java:92)
       at com.iplanet.dpro.session.monitoring.MonitoredOperations.time(MonitoredOperations.java:187)
       at com.iplanet.dpro.session.monitoring.MonitoredOperations.resolveSession(MonitoredOperations.java:92)
       at com.iplanet.dpro.session.service.SessionService.getSession(SessionService.java:160)
       at org.forgerock.openam.session.cts.CtsSessionProvider.getSession(CtsSessionProvider.java:44)
       at com.iplanet.sso.providers.dpro.SSOProviderImpl.createSSOToken(SSOProviderImpl.java:128)
       ... 43 more
      amLog:04/30/2018 10:08:11:450 AM BST: Thread[http-nio-28080-exec-2,5,main]: TransactionId[51681112-dc76-441c-b057-d7a910949374-105022]
      ERROR: LogService::process():
      java.lang.NullPointerException: trackingId value cannot be null
       at org.forgerock.util.Reject.checkNotNull(Reject.java:82)
       at org.forgerock.util.Reject.ifNull(Reject.java:240)
       at org.forgerock.audit.events.AuditEventBuilder.trackingId(AuditEventBuilder.java:190)
       at com.sun.identity.log.service.LogRecWrite.auditAccessMessage(LogRecWrite.java:243)
       at com.sun.identity.log.service.LogRecWrite.execute(LogRecWrite.java:198)
       at com.sun.identity.log.service.LogService.process(LogService.java:185)
       at com.iplanet.services.comm.server.PLLRequestServlet.handleRequest(PLLRequestServlet.java:202)
       at com.iplanet.services.comm.server.PLLRequestServlet.doPost(PLLRequestServlet.java:140)
       at javax.servlet.http.HttpServlet.service(HttpServlet.java:648)
       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:1539)
       at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1495)
       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)

       

      Wouldn't it better that an empty trackingId is sent as a warning instead of an error?

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              anastasios.kampas Anastasios Kampas
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated: