Uploaded image for project: 'Dev - Nexus Repo'
  1. Dev - Nexus Repo
  2. NEXUS-13228

race condition writing to request.log under high load may cause dead lock, thread pool exhaustion and CPU spike

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 2.14, 2.14.1, 2.14.2, 2.14.3, 2.14.4
    • Fix Version/s: 2.14.5
    • Component/s: Logging
    • Story Points:
      2

      Description

      Nexus 2.x uses version 1.1.2 of logback-access,logback-core,logback-classic. As such it may be affected by a race condition that has been reported and described in https://jira.qos.ch/browse/LOGBACK-1270.

      Nexus uses a custom PatternLayoutEncoder defined inside the logback-access.xml file so that the request log can print the user name for each authenticated request log line.

      Recently the LogBack developers released a backported fix for version 1.1.x line of releases. Nexus 2.14.x uses version 1.1.2 of logback.

      Symptoms

      The main symptom is a single thread was blocking many others from writing to the request.log.

      Example Blocking Thread
      "qtp2074628523-9375" #9375 prio=5 os_prio=0 tid=0x00007f8cb0404800 nid=0x2014 waiting for monitor entry [0x00007f8d4466b000]
         java.lang.Thread.State: BLOCKED (on object monitor)
          at ch.qos.logback.core.pattern.PatternLayoutBase.writeLoopOnConverters(PatternLayoutBase.java:116)
          at ch.qos.logback.access.PatternLayout.doLayout(PatternLayout.java:196)
          at ch.qos.logback.access.PatternLayout.doLayout(PatternLayout.java:65)
          at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:134)
          at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:194)
          at ch.qos.logback.core.FileAppender.writeOut(FileAppender.java:209)
          at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:219)
          at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:182)
          at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
          at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
          at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
          at ch.qos.logback.access.jetty.RequestLogImpl.log(RequestLogImpl.java:142)
          at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:92)
          at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154)
          at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
          at org.eclipse.jetty.server.Server.handle(Server.java:370)
          at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)
          at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:971)
          at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1033)
          at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)
          at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
          at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
          at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:696)
          at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)
          at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
          at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
          at java.lang.Thread.run(Unknown Source)
      
         Locked ownable synchronizers:
          - <0x00000006c8e2e578> (a java.util.concurrent.locks.ReentrantLock$FairSync)
      
      
      Example Blocked Thread
      "qtp2074628523-9368" #9368 prio=5 os_prio=0 tid=0x00007f8d0c00b000 nid=0x200a waiting on condition [0x00007f8d471f0000]
         java.lang.Thread.State: WAITING (parking)
      	at sun.misc.Unsafe.park(Native Method)
      	- parking to wait for  <0x00000006c8e2e578> (a java.util.concurrent.locks.ReentrantLock$FairSync)
      	at java.util.concurrent.locks.LockSupport.park(Unknown Source)
      	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(Unknown Source)
      	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(Unknown Source)
      	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(Unknown Source)
      	at java.util.concurrent.locks.ReentrantLock$FairSync.lock(Unknown Source)
      	at java.util.concurrent.locks.ReentrantLock.lock(Unknown Source)
      	at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:217)
      	at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:182)
      	at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
      	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
      	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
      	at ch.qos.logback.access.jetty.RequestLogImpl.log(RequestLogImpl.java:142)
      	at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:92)
      	at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154)
      	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
      	at org.eclipse.jetty.server.Server.handle(Server.java:370)
      	at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)
      	at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:971)
      	at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1033)
      	at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)
      	at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
      	at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
      	at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:696)
      	at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)
      	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
      	at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
      	at java.lang.Thread.run(Unknown Source)
      
         Locked ownable synchronizers:
      	- None
      

      Workaround

      A restart will be required to escape the dead lock.

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                plynch Peter Lynch
                Last Updated By:
                Rich Seddon
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:
                  Date of First Response: