Uploaded image for project: 'Undertow'
  1. Undertow
  2. UNDERTOW-1763

DefaultAccessLogReceiver may throw "IOException: Stream closed" or NullPointerException due to a concurrency issue

    Details

      Description

      DefaultAccessLogReceiver may throw "IOException: Stream closed" or NullPointerException due to a concurrency issue between DefaultAccessLogReceiver#run() and DefaultAccessLogReceiver#close().

      If DefaultAccessLogReceiver#close() is invoked while another task thread is executing inside the "finally" clause of DefaultAccessLogReceiver#run(), there's a concurrency issue that allows multiple task threads execute run() in parallel.

      This can cause the following "java.io.IOException: Stream closed" or NullPointerException inside run() or writeMessage():

      ERROR [io.undertow] (default task-1) UT005016: Error writing access log: java.io.IOException: Stream closed
      	at java.io.BufferedWriter.ensureOpen(BufferedWriter.java:116)
      	at java.io.BufferedWriter.write(BufferedWriter.java:221)
      	at java.io.Writer.write(Writer.java:157)
      	at io.undertow.server.handlers.accesslog.DefaultAccessLogReceiver.writeMessage(DefaultAccessLogReceiver.java:245)
      	at io.undertow.server.handlers.accesslog.DefaultAccessLogReceiver.run(DefaultAccessLogReceiver.java:188)
      	at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
      	at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
      	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
      	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
      	at java.lang.Thread.run(Thread.java:748)
      
      ERROR [org.jboss.threads.errors] (default task-1) Thread Thread[default task-1,5,main] threw an uncaught exception: java.lang.NullPointerException
      	at io.undertow.server.handlers.accesslog.DefaultAccessLogReceiver.writeMessage(DefaultAccessLogReceiver.java:245)
      	at io.undertow.server.handlers.accesslog.DefaultAccessLogReceiver.run(DefaultAccessLogReceiver.java:188)
      	at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
      	at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
      	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
      	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
      	at java.lang.Thread.run(Thread.java:748)
      
      ERROR [io.undertow] (default task-1) UT005016: Error writing access log: 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 io.undertow.server.handlers.accesslog.DefaultAccessLogReceiver.run(DefaultAccessLogReceiver.java:201)
      	at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
      	at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
      	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
      	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1377)
      	at java.lang.Thread.run(Thread.java:748)
      
      ERROR [org.jboss.threads.errors] (default task-1) Thread Thread[default task-3,5,main] threw an uncaught exception: java.lang.NullPointerException
              at io.undertow.server.handlers.accesslog.DefaultAccessLogReceiver.run(DefaultAccessLogReceiver.java:201)
              at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
              at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
              at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
              at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1348)
              at java.lang.Thread.run(Thread.java:748)
      

      This happens because the "state" is reset to 0 (not running) at the beginning of the "finally" clause of DefaultAccessLogReceiver#run(). So, if another thread (MSC service thread in EAP/WildFly) invokes DefaultAccessLogReceiver#close() at the same time, it has a possibility to trigger "logWriteExecutor.execute(this)" to spawn a new thread that executes run(). (In a normal scenario, "logWriteExecutor.execute(this)" needs to be executed here in order to close a writer. So, I think close() itself is fine.)

      I think the "state" should be set at the end of the finally clause to prevent other threads from entering DefaultAccessLogReceiver#run().

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

                People

                • Assignee:
                  flavia.rainone Flavia Rainone
                  Reporter:
                  mmiura Masafumi Miura
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  2 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: