race condition in logging code?

[hanwen]

I'm debugging a deadlock in Gerrit, and got the following report for a data race. Since this has only Jetty in the stack-traces, I thought this might interest you.

There are several similar traces, due to debug logging of objects

WARNING: ThreadSanitizer: data race (pid=14201)
Write of size 4 at 0x7f569e58748c by thread T65:
#0 org.eclipse.jetty.io.SelectChannelEndPoint.onSelected()Ljava/lang/Runnable; (SelectChannelEndPoint.java:168)
#1 org.eclipse.jetty.io.ManagedSelector$SelectorProducer.processSelected()Ljava/lang/Runnable; (ManagedSelector.java:283)
#2 org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce()Ljava/lang/Runnable; (ManagedSelector.java:181)
#3 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume()V (ExecuteProduceConsume.java:249)
#4 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume()V (ExecuteProduceConsume.java:148)
#5 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run()V (ExecuteProduceConsume.java:136)
#6 org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(Ljava/lang/Runnable;)V (QueuedThreadPool.java:671)
#7 org.eclipse.jetty.util.thread.QueuedThreadPool$2.run()V (QueuedThreadPool.java:589)
#8 java.lang.Thread.run()V (Thread.java:745)
#9 (Generated Stub)

Previous read of size 4 at 0x7f569e58748c by thread T19 (mutexes: write M666672754807107656, write M666954229783818720, write M667235704760529400):
#0 org.eclipse.jetty.io.SelectChannelEndPoint.toString()Ljava/lang/String; (SelectChannelEndPoint.java:308)
#1 java.util.Formatter$FormatSpecifier.printString(Ljava/lang/Object;Ljava/util/Locale;)V (Formatter.java:2886)
#2 java.util.Formatter$FormatSpecifier.print(Ljava/lang/Object;Ljava/util/Locale;)V (Formatter.java:2763)
#3 java.util.Formatter.format(Ljava/util/Locale;Ljava/lang/String;[Ljava/lang/Object;)Ljava/util/Formatter; (Formatter.java:2520)
#4 java.util.Formatter.format(Ljava/lang/String;[Ljava/lang/Object;)Ljava/util/Formatter; (Formatter.java:2455)
#5 java.lang.String.format(Ljava/lang/String;[Ljava/lang/Object;)Ljava/lang/String; (String.java:2942)
#6 org.eclipse.jetty.io.AbstractConnection.toString()Ljava/lang/String; (AbstractConnection.java:262)
#7 org.eclipse.jetty.server.HttpConnection.toString()Ljava/lang/String; (HttpConnection.java:569)
#8 org.slf4j.helpers.MessageFormatter.safeObjectAppend(Ljava/lang/StringBuilder;Ljava/lang/Object;)V (MessageFormatter.java:305)
#9 org.slf4j.helpers.MessageFormatter.deeplyAppendParameter(Ljava/lang/StringBuilder;Ljava/lang/Object;Ljava/util/Map;)V (MessageFormatter.java:277)
#10 org.slf4j.helpers.MessageFormatter.arrayFormat(Ljava/lang/String;[Ljava/lang/Object;)Lorg/slf4j/helpers/FormattingTuple; (MessageFormatter.java:231)
#11 org.eclipse.jetty.util.log.JettyAwareLogger.log(Lorg/slf4j/Marker;ILjava/lang/String;[Ljava/lang/Object;Ljava/lang/Throwable;)V (JettyAwareLogger.java:619)
#12 org.eclipse.jetty.util.log.JettyAwareLogger.debug(Ljava/lang/String;[Ljava/lang/Object;)V (JettyAwareLogger.java:206)
#13 org.eclipse.jetty.util.log.Slf4jLog.debug(Ljava/lang/String;[Ljava/lang/Object;)V (Slf4jLog.java:89)
#14 org.eclipse.jetty.server.HttpConnection.onFillable()V (HttpConnection.java:274)
#15 org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded()V (AbstractConnection.java:273)
#16 org.eclipse.jetty.io.FillInterest.fillable()V (FillInterest.java:95)
#17 org.eclipse.jetty.io.SelectChannelEndPoint$2.run()V (SelectChannelEndPoint.java:93)
#18 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume()V (ExecuteProduceConsume.java:303)
#19 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume()V (ExecuteProduceConsume.java:148)
#20 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run()V (ExecuteProduceConsume.java:136)
#21 org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(Ljava/lang/Runnable;)V (QueuedThreadPool.java:671)
#22 org.eclipse.jetty.util.thread.QueuedThreadPool$2.run()V (QueuedThreadPool.java:589)
#23 java.lang.Thread.run()V (Thread.java:745)
#24 (Generated Stub)

[hanwen]

different but similar trace:

Write of size 4 at 0x7f569e587ba0 by thread T19 (mutexes: write M666672754807107656, write M666954229783818720, write M667235704760529400, write M666672754851916272, write M666954229828627072, write M667235704805337704):
#0 sun.nio.ch.SelectionKeyImpl.nioReadyOps(I)V (SelectionKeyImpl.java:95)
#1 sun.nio.ch.SocketChannelImpl.translateReadyOps(IILsun/nio/ch/SelectionKeyImpl;)Z (SocketChannelImpl.java:929)
#2 sun.nio.ch.SocketChannelImpl.translateAndSetReadyOps(ILsun/nio/ch/SelectionKeyImpl;)Z (SocketChannelImpl.java:938)
#3 sun.nio.ch.EPollSelectorImpl.updateSelectedKeys()I (EPollSelectorImpl.java:129)
#4 sun.nio.ch.EPollSelectorImpl.doSelect(J)I (EPollSelectorImpl.java:98)
#5 sun.nio.ch.SelectorImpl.lockAndDoSelect(J)I (SelectorImpl.java:86)
#6 sun.nio.ch.SelectorImpl.select(J)I (SelectorImpl.java:97)
#7 sun.nio.ch.SelectorImpl.select()I (SelectorImpl.java:101)
#8 org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select()Z (ManagedSelector.java:243)
#9 org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce()Ljava/lang/Runnable; (ManagedSelector.java:191)
#10 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume()V (ExecuteProduceConsume.java:249)
#11 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume()V (ExecuteProduceConsume.java:148)
#12 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run()V (ExecuteProduceConsume.java:136)
#13 org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(Ljava/lang/Runnable;)V (QueuedThreadPool.java:671)
#14 org.eclipse.jetty.util.thread.QueuedThreadPool$2.run()V (QueuedThreadPool.java:589)
#15 java.lang.Thread.run()V (Thread.java:745)
#16 (Generated Stub)

Previous read of size 4 at 0x7f569e587ba0 by thread T76:
#0 sun.nio.ch.SelectionKeyImpl.readyOps()I (SelectionKeyImpl.java:88)
#1 org.eclipse.jetty.io.SelectChannelEndPoint.toString()Ljava/lang/String; (SelectChannelEndPoint.java:305)
#2 org.eclipse.jetty.io.SelectChannelEndPoint$2.toString()Ljava/lang/String; (SelectChannelEndPoint.java:99)
#3 org.slf4j.helpers.MessageFormatter.safeObjectAppend(Ljava/lang/StringBuilder;Ljava/lang/Object;)V (MessageFormatter.java:305)
#4 org.slf4j.helpers.MessageFormatter.deeplyAppendParameter(Ljava/lang/StringBuilder;Ljava/lang/Object;Ljava/util/Map;)V (MessageFormatter.java:277)
#5 org.slf4j.helpers.MessageFormatter.arrayFormat(Ljava/lang/String;[Ljava/lang/Object;)Lorg/slf4j/helpers/FormattingTuple; (MessageFormatter.java:231)
#6 org.eclipse.jetty.util.log.JettyAwareLogger.log(Lorg/slf4j/Marker;ILjava/lang/String;[Ljava/lang/Object;Ljava/lang/Throwable;)V (JettyAwareLogger.java:619)
#7 org.eclipse.jetty.util.log.JettyAwareLogger.debug(Ljava/lang/String;[Ljava/lang/Object;)V (JettyAwareLogger.java:206)
#8 org.eclipse.jetty.util.log.Slf4jLog.debug(Ljava/lang/String;[Ljava/lang/Object;)V (Slf4jLog.java:89)
#9 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume()V (ExecuteProduceConsume.java:305)
#10 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume()V (ExecuteProduceConsume.java:148)
#11 org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run()V (ExecuteProduceConsume.java:136)
#12 org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(Ljava/lang/Runnable;)V (QueuedThreadPool.java:671)
#13 org.eclipse.jetty.util.thread.QueuedThreadPool$2.run()V (QueuedThreadPool.java:589)
#14 java.lang.Thread.run()V (Thread.java:745)
#15 (Generated Stub)

[janbartel]

@hanwen what version of jetty are you using, so we can match the line numbers?

[hanwen]

JETTY_VERS = '9.3.11.v20160721'

maven_jar(
name = 'jetty_servlet',
artifact = 'org.eclipse.jetty:jetty-servlet:' + JETTY_VERS,
sha1 = 'd550147b85c73ea81084a4ac7915ba7f609021c5',
)

maven_jar(
name = 'jetty_security',
artifact = 'org.eclipse.jetty:jetty-security:' + JETTY_VERS,
sha1 = '1cbefc5d1196b9e1ca6f4cc36738998a6ebde8bf',
)

maven_jar(
name = 'jetty_servlets',
artifact = 'org.eclipse.jetty:jetty-servlets:' + JETTY_VERS,
sha1 = 'a9f7a43977151a463aa21a9b0e882aa3d25452ef',
)

maven_jar(
name = 'jetty_server',
artifact = 'org.eclipse.jetty:jetty-server:' + JETTY_VERS,
sha1 = 'd932e0dc1e9bd4839ae446754615163d60271a66',
)

maven_jar(
name = 'jetty_jmx',
artifact = 'org.eclipse.jetty:jetty-jmx:' + JETTY_VERS,
sha1 = '21a658d2f5eb87c23eef4911966625ea95f66d32',
)

maven_jar(
name = 'jetty_continuation',
artifact = 'org.eclipse.jetty:jetty-continuation:' + JETTY_VERS,
sha1 = '92a91c0dcc5f5d779a1c9f94038332be3f46c9df',
)

maven_jar(
name = 'jetty_http',
artifact = 'org.eclipse.jetty:jetty-http:' + JETTY_VERS,
sha1 = 'dcfb95e5b886a981bb76467b911c5b706117f9cf',
)

maven_jar(
name = 'jetty_io',
artifact = 'org.eclipse.jetty:jetty-io:' + JETTY_VERS,
sha1 = 'db5f4f481159894a4b670072a34917b5414d0c98',
)

maven_jar(
name = 'jetty_util',
artifact = 'org.eclipse.jetty:jetty-util:' + JETTY_VERS,
sha1 = '1812ffd5a04698051180d582c146ca807760c808',
)

[joakime]

Link to stacktrace entry for Jetty 9.3.11

org.eclipse.jetty.io.SelectChannelEndPoint.toString()Ljava/lang/String; (SelectChannelEndPoint.java:305)

https://github.com/eclipse/jetty.project/blob/jetty-9.3.11.v20160721/jetty-io/src/main/java/org/eclipse/jetty/io/SelectChannelEndPoint.java#L305

Not sure how this can deadlock. @sbordet / @gregw got any ideas?

[joakime]

This is no longer relevant in Jetty 9.4.x
The SelectChannelEndpoint class has been heavily refactored.

Closing.