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

Audit logging outputs errors in debug log under high load

    Details

    • Sprint:
      Sprint 109 - Shakespeare
    • Support Ticket IDs:

      Description

      When OpenAM is under high load with audit logging enabled, there is following message in CoreSystem debug log.

      ERROR: Error  when flushing the writer
      java.io.IOException: Stream closed
      	at java.io.BufferedWriter.ensureOpen(BufferedWriter.java:116)
      	at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:126)
      	at java.io.BufferedWriter.flush(BufferedWriter.java:253)
      	at org.forgerock.audit.events.handlers.writers.RotatableWriter.flush(RotatableWriter.java:341)
      	at org.forgerock.audit.events.handlers.writers.AsynchronousTextWriter.flush(AsynchronousTextWriter.java:170)
      	at org.forgerock.audit.events.handlers.writers.TextWriterAdapter.flush(TextWriterAdapter.java:65)
      	at org.forgerock.audit.handlers.csv.StandardCsvWriter.flush(StandardCsvWriter.java:138)
      	at org.forgerock.audit.handlers.csv.CsvAuditEventHandler.writeEvent(CsvAuditEventHandler.java:317)
      	at org.forgerock.audit.handlers.csv.CsvAuditEventHandler.publishEventWithRetry(CsvAuditEventHandler.java:262)
      	at org.forgerock.audit.handlers.csv.CsvAuditEventHandler.publishEvent(CsvAuditEventHandler.java:240)
      	at org.forgerock.audit.AuditServiceImpl.publishEventToHandlers(AuditServiceImpl.java:275)
      	at org.forgerock.audit.AuditServiceImpl.handleCreate(AuditServiceImpl.java:216)
      	at org.forgerock.audit.AuditServiceProxy.handleCreate(AuditServiceProxy.java:115)
      	at org.forgerock.openam.audit.DefaultAuditServiceProxy.handleCreate(DefaultAuditServiceProxy.java:66)
      	at org.forgerock.json.resource.InternalConnection.createAsync(InternalConnection.java:44)
      	at org.forgerock.json.resource.AbstractAsynchronousConnection.create(AbstractAsynchronousConnection.java:44)
      	at org.forgerock.openam.audit.AuditEventPublisherImpl.publishForRealm(AuditEventPublisherImpl.java:97)
      	at org.forgerock.openam.audit.AuditEventPublisherImpl.tryPublish(AuditEventPublisherImpl.java:66)
      	at org.forgerock.openam.audit.AbstractHttpAccessAuditFilter.auditAccessSuccess(AbstractHttpAccessAuditFilter.java:120)
      	at org.forgerock.openam.audit.AbstractHttpAccessAuditFilter.access$000(AbstractHttpAccessAuditFilter.java:49)
      	at org.forgerock.openam.audit.AbstractHttpAccessAuditFilter$1.apply(AbstractHttpAccessAuditFilter.java:77)
      	at org.forgerock.openam.audit.AbstractHttpAccessAuditFilter$1.apply(AbstractHttpAccessAuditFilter.java:73)
      	at org.forgerock.util.promise.Promises$CompletedPromise.then(Promises.java:190)
      	at org.forgerock.util.promise.Promises$CompletedPromise.then(Promises.java:179)
      	at org.forgerock.util.promise.Promises$CompletedPromise.then(Promises.java:160)
      	at org.forgerock.openam.audit.AbstractHttpAccessAuditFilter.filter(AbstractHttpAccessAuditFilter.java:73)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:56)
      	at org.forgerock.http.routing.Router.handle(Router.java:92)
      	at org.forgerock.openam.rest.RealmContextFilter.filter(RealmContextFilter.java:84)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:56)
      	at org.forgerock.http.routing.Router.handle(Router.java:92)
      	at org.forgerock.http.routing.ResourceApiVersionRoutingFilter.filter(ResourceApiVersionRoutingFilter.java:64)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:56)
      	at org.forgerock.caf.authentication.framework.AuthenticationFramework.grantAccess(AuthenticationFramework.java:220)
      	at org.forgerock.caf.authentication.framework.AuthenticationFramework.access$400(AuthenticationFramework.java:65)
      	at org.forgerock.caf.authentication.framework.AuthenticationFramework$3.apply(AuthenticationFramework.java:212)
      	at org.forgerock.caf.authentication.framework.AuthenticationFramework$3.apply(AuthenticationFramework.java:205)
      	at org.forgerock.util.promise.Promises$CompletedPromise.thenAsync(Promises.java:255)
      	at org.forgerock.util.promise.Promises$CompletedPromise.thenAsync(Promises.java:244)
      	at org.forgerock.caf.authentication.framework.AuthenticationFramework.validateRequest(AuthenticationFramework.java:168)
      	at org.forgerock.caf.authentication.framework.AuthenticationFramework.access$100(AuthenticationFramework.java:65)
      	at org.forgerock.caf.authentication.framework.AuthenticationFramework$1.apply(AuthenticationFramework.java:155)
      	at org.forgerock.caf.authentication.framework.AuthenticationFramework$1.apply(AuthenticationFramework.java:152)
      	at org.forgerock.util.promise.PromiseImpl$7.handleStateChange(PromiseImpl.java:485)
      	at org.forgerock.util.promise.PromiseImpl.handleCompletion(PromiseImpl.java:567)
      	at org.forgerock.util.promise.PromiseImpl.addOrFireListener(PromiseImpl.java:555)
      	at org.forgerock.util.promise.PromiseImpl.thenAsync(PromiseImpl.java:477)
      	at org.forgerock.util.promise.PromiseImpl.thenAsync(PromiseImpl.java:468)
      	at org.forgerock.caf.authentication.framework.AuthenticationFramework.processMessage(AuthenticationFramework.java:146)
      	at org.forgerock.caf.authentication.framework.AuthenticationFilter.filter(AuthenticationFilter.java:96)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:56)
      	at org.forgerock.openam.http.HandlerProvider.handle(HandlerProvider.java:50)
      	at org.forgerock.openam.http.HttpRoute$3.handle(HttpRoute.java:142)
      	at org.forgerock.http.routing.Router.handle(Router.java:92)
      	at org.forgerock.openam.http.OpenAMHttpApplication$1.filter(OpenAMHttpApplication.java:60)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:56)
      	at org.forgerock.http.filter.TransactionIdInboundFilter.filter(TransactionIdInboundFilter.java:60)
      	at org.forgerock.http.handler.Handlers$1.handle(Handlers.java:56)
      	at org.forgerock.http.servlet.HttpFrameworkServlet.service(HttpFrameworkServlet.java:225)
      	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:44)
      	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:51)
      	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:106)
      	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
      	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:616)
      	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
      	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:522)
      	at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1095)
      	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:672)
      	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1502)
      	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1458)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
      	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
      	at java.lang.Thread.run(Thread.java:745)
      

      Load is simple REST login logout with 50 concurrent users. This happens after 4-6 minutes under 100% load.

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                pavel.balcarek Pavel Balcárek
              • Votes:
                0 Vote for this issue
                Watchers:
                9 Start watching this issue

                Dates

                • Created:
                  Updated: