Details
-
Bug
-
Resolution: Fixed
-
Major
-
2.14, 2.14.1, 2.14.2, 2.14.3, 2.14.4
-
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
- causes
-
-
- Closed
-
- fixes
-
-
- Closed
-