Uploaded image for project: 'WildFly Core'
  1. WildFly Core
  2. WFCORE-6596

AsyncHandler must not park worker thread

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Major Major
    • None
    • None
    • Logging
    • None

      MailHandler that ships with AngusMail has thread local deal with reentrant Handler publish calls due to AngusMail using JUL and the MailHandler using AngusMail.  Log4j2 and logback have similar guards in-place to deal with feedback loops.  In the normal case the guard is never triggered unless log levels get low enough that AugusMail starts issuing debug statements.

      Using wildfly-29.0.1.Final, the AsyncHandler with BLOCK overflow policy + MailHandler I'm able to observe that WildFly will never boot because the AsyncHandler has filled its blocking queue and parked the worker thread and all other threads publishing.  Because the worker thread is parked progress is never made.

      Here is jstack output from WildFly showing that main thread and AsyncHandler worker are calling BlockingQueue.put:

       

      2023-09-27 22:08:04
Full thread dump OpenJDK 64-Bit Server VM (17.0.7+7-Ubuntu-0ubuntu118.04 mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x0000564b040111e0, length=14, elements={
0x0000564b033677e0, 0x0000564b03412c20, 0x0000564b03414550, 0x0000564b0341a290,
0x0000564b0341b910, 0x0000564b0341d130, 0x0000564b0341eef0, 0x0000564b03420830,
0x0000564b0347e4a0, 0x0000564b03556f20, 0x0000564b03559700, 0x0000564b035fa640,
0x0000564b04239f10, 0x0000564b05024db0
}

"main" #1 prio=5 os_prio=0 cpu=2134.93ms elapsed=36.55s tid=0x0000564b033677e0 nid=0xade waiting on condition  [0x00007fbe685d3000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@17.0.7/Native Method)
	- parking to wait for  <0x00000000e06307c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@17.0.7/LockSupport.java:341)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@17.0.7/AbstractQueuedSynchronizer.java:506)
	at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@17.0.7/ForkJoinPool.java:3463)
	at java.util.concurrent.ForkJoinPool.managedBlock(java.base@17.0.7/ForkJoinPool.java:3434)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@17.0.7/AbstractQueuedSynchronizer.java:1623)
	at java.util.concurrent.ArrayBlockingQueue.put(java.base@17.0.7/ArrayBlockingQueue.java:370)
	at org.jboss.logmanager.handlers.AsyncHandler.doPublish(AsyncHandler.java:155)
	at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:77)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:333)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
	at org.jboss.logmanager.Logger.logRaw(Logger.java:852)
	at org.jboss.logmanager.Logger.logRaw(Logger.java:862)
	at org.jboss.logmanager.Logger.log(Logger.java:395)
	at org.jboss.modules.log.JDKModuleLogger.doLog(JDKModuleLogger.java:102)
	at org.jboss.modules.log.JDKModuleLogger.moduleDefined(JDKModuleLogger.java:181)
	at org.jboss.modules.ModuleLoader$3.run(ModuleLoader.java:736)
	at org.jboss.modules.ModuleLoader$3.run(ModuleLoader.java:728)
	at java.security.AccessController.executePrivileged(java.base@17.0.7/AccessController.java:807)
	at java.security.AccessController.doPrivileged(java.base@17.0.7/AccessController.java:569)
	at org.jboss.modules.ModuleLoader.defineModule(ModuleLoader.java:728)
	at org.jboss.modules.ModuleLoader.loadModuleLocal(ModuleLoader.java:535)
	at org.jboss.modules.DelegatingModuleLoader.preloadModule(DelegatingModuleLoader.java:57)
	at org.jboss.modules.Module.addPaths(Module.java:1257)
	at org.jboss.modules.Module.link(Module.java:1627)
	at org.jboss.modules.Module.getPaths(Module.java:1588)
	at org.jboss.modules.Module.getPathsUnchecked(Module.java:1611)
	at org.jboss.modules.Module.loadModuleClass(Module.java:760)
	at org.jboss.modules.ModuleClassLoader.findClass(ModuleClassLoader.java:192)
	at org.jboss.modules.ConcurrentClassLoader.performLoadClassUnchecked(ConcurrentClassLoader.java:410)
	at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:398)
	at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:116)
	at java.lang.ClassLoader.defineClass1(java.base@17.0.7/Native Method)
	at java.lang.ClassLoader.defineClass(java.base@17.0.7/ClassLoader.java:1012)
	at org.jboss.modules.ModuleClassLoader.doDefineOrLoadClass(ModuleClassLoader.java:350)
	at org.jboss.modules.ModuleClassLoader.defineClass(ModuleClassLoader.java:482)
	at org.jboss.modules.ModuleClassLoader.loadClassLocal(ModuleClassLoader.java:276)
	at org.jboss.modules.ModuleClassLoader$1.loadClassLocal(ModuleClassLoader.java:79)
	at org.jboss.modules.Module.loadModuleClass(Module.java:765)
	at org.jboss.modules.ModuleClassLoader.findClass(ModuleClassLoader.java:192)
	at org.jboss.modules.ConcurrentClassLoader.performLoadClassUnchecked(ConcurrentClassLoader.java:410)
	at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:398)
	at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:116)
	at java.lang.ClassLoader.defineClass1(java.base@17.0.7/Native Method)
	at java.lang.ClassLoader.defineClass(java.base@17.0.7/ClassLoader.java:1012)
	at org.jboss.modules.ModuleClassLoader.doDefineOrLoadClass(ModuleClassLoader.java:350)
	at org.jboss.modules.ModuleClassLoader.defineClass(ModuleClassLoader.java:482)
	at org.jboss.modules.ModuleClassLoader.loadClassLocal(ModuleClassLoader.java:276)
	at org.jboss.modules.ModuleClassLoader$1.loadClassLocal(ModuleClassLoader.java:79)
	at org.jboss.modules.Module.loadModuleClass(Module.java:765)
	at org.jboss.modules.ModuleClassLoader.findClass(ModuleClassLoader.java:192)
	at org.jboss.modules.ConcurrentClassLoader.performLoadClassUnchecked(ConcurrentClassLoader.java:410)
	at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:398)
	at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:116)
	at org.jboss.as.jmx.PluggableMBeanServerBuilder.newMBeanServer(PluggableMBeanServerBuilder.java:49)
	at javax.management.MBeanServerFactory.newMBeanServer(java.management@17.0.7/MBeanServerFactory.java:329)
	- locked <0x00000000e1e0b580> (a org.jboss.as.jmx.PluggableMBeanServerBuilder)
	at javax.management.MBeanServerFactory.createMBeanServer(java.management@17.0.7/MBeanServerFactory.java:231)
	at javax.management.MBeanServerFactory.createMBeanServer(java.management@17.0.7/MBeanServerFactory.java:192)
	at java.lang.management.ManagementFactory.getPlatformMBeanServer(java.management@17.0.7/ManagementFactory.java:484)
	- locked <0x00000000e06ea1b0> (a java.lang.Class for java.lang.management.ManagementFactory)
	at org.jboss.modules.Main.main(Main.java:545)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=1.73ms elapsed=36.52s tid=0x0000564b03412c20 nid=0xae5 waiting on condition  [0x00007fbe4921b000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.ref.Reference.waitForReferencePendingList(java.base@17.0.7/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base@17.0.7/Reference.java:253)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base@17.0.7/Reference.java:215)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=1.26ms elapsed=36.52s tid=0x0000564b03414550 nid=0xae6 in Object.wait()  [0x00007fbe4911a000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.7/Native Method)
	- waiting on <0x00000000e013bfe8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@17.0.7/ReferenceQueue.java:155)
	- locked <0x00000000e013bfe8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@17.0.7/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base@17.0.7/Finalizer.java:172)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=1.17ms elapsed=36.51s tid=0x0000564b0341a290 nid=0xae7 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #5 daemon prio=9 os_prio=0 cpu=1.18ms elapsed=36.51s tid=0x0000564b0341b910 nid=0xae8 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Monitor Deflation Thread" #6 daemon prio=9 os_prio=0 cpu=3.57ms elapsed=36.51s tid=0x0000564b0341d130 nid=0xae9 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=3316.31ms elapsed=36.51s tid=0x0000564b0341eef0 nid=0xaea waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #10 daemon prio=9 os_prio=0 cpu=1703.23ms elapsed=36.51s tid=0x0000564b03420830 nid=0xaeb waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"Sweeper thread" #11 daemon prio=9 os_prio=0 cpu=0.68ms elapsed=36.51s tid=0x0000564b0347e4a0 nid=0xaec runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #12 daemon prio=8 os_prio=0 cpu=1.25ms elapsed=36.46s tid=0x0000564b03556f20 nid=0xaed in Object.wait()  [0x00007fbe4471a000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.7/Native Method)
	- waiting on <0x00000000e013c1f8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@17.0.7/ReferenceQueue.java:155)
	- locked <0x00000000e013c1f8> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run(java.base@17.0.7/CleanerImpl.java:140)
	at java.lang.Thread.run(java.base@17.0.7/Thread.java:833)
	at jdk.internal.misc.InnocuousThread.run(java.base@17.0.7/InnocuousThread.java:162)

"Notification Thread" #13 daemon prio=9 os_prio=0 cpu=0.29ms elapsed=36.45s tid=0x0000564b03559700 nid=0xaee runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Reference Reaper" #14 daemon prio=5 os_prio=0 cpu=0.43ms elapsed=36.19s tid=0x0000564b035fa640 nid=0xaf0 in Object.wait()  [0x00007fbe43de6000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@17.0.7/Native Method)
	- waiting on <0x00000000e013c3b0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@17.0.7/ReferenceQueue.java:155)
	- locked <0x00000000e013c3b0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@17.0.7/ReferenceQueue.java:176)
	at org.jboss.modules.ref.References$ReaperThread.run(References.java:64)

"pool-1-thread-1" #16 daemon prio=5 os_prio=0 cpu=2218.46ms elapsed=32.32s tid=0x0000564b04239f10 nid=0xaf2 waiting on condition  [0x00007fbe43ce4000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@17.0.7/Native Method)
	- parking to wait for  <0x00000000e06307c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@17.0.7/LockSupport.java:341)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@17.0.7/AbstractQueuedSynchronizer.java:506)
	at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@17.0.7/ForkJoinPool.java:3463)
	at java.util.concurrent.ForkJoinPool.managedBlock(java.base@17.0.7/ForkJoinPool.java:3434)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@17.0.7/AbstractQueuedSynchronizer.java:1623)
	at java.util.concurrent.ArrayBlockingQueue.put(java.base@17.0.7/ArrayBlockingQueue.java:370)
	at org.jboss.logmanager.handlers.AsyncHandler.doPublish(AsyncHandler.java:155)
	at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:77)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:333)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
	at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:341)
	at org.jboss.logmanager.Logger.logRaw(Logger.java:852)
	at org.jboss.logmanager.Logger.logp(Logger.java:659)
	at org.eclipse.angus.mail.util.MailLogger.log(MailLogger.java:218)
	at org.eclipse.angus.mail.util.LogOutputStream.log(LogOutputStream.java:105)
	at org.eclipse.angus.mail.util.LogOutputStream.logBuf(LogOutputStream.java:114)
	at org.eclipse.angus.mail.util.LogOutputStream.write(LogOutputStream.java:78)
	at org.eclipse.angus.mail.util.TraceOutputStream.write(TraceOutputStream.java:118)
	at java.io.BufferedOutputStream.flushBuffer(java.base@17.0.7/BufferedOutputStream.java:81)
	at java.io.BufferedOutputStream.write(java.base@17.0.7/BufferedOutputStream.java:95)
	- locked <0x00000000e1e30d90> (a java.io.BufferedOutputStream)
	at org.eclipse.angus.mail.util.CRLFOutputStream.write(CRLFOutputStream.java:47)
	at org.eclipse.angus.mail.smtp.SMTPOutputStream.write(SMTPOutputStream.java:46)
	at org.eclipse.angus.mail.util.QPEncoderStream.output(QPEncoderStream.java:188)
	at org.eclipse.angus.mail.util.QPEncoderStream.write(QPEncoderStream.java:125)
	at java.io.FilterOutputStream.write(java.base@17.0.7/FilterOutputStream.java:87)
	at java.io.FilterOutputStream.write(java.base@17.0.7/FilterOutputStream.java:137)
	at sun.nio.cs.StreamEncoder.writeBytes(java.base@17.0.7/StreamEncoder.java:234)
	at sun.nio.cs.StreamEncoder.implWrite(java.base@17.0.7/StreamEncoder.java:304)
	at sun.nio.cs.StreamEncoder.implWrite(java.base@17.0.7/StreamEncoder.java:282)
	at sun.nio.cs.StreamEncoder.write(java.base@17.0.7/StreamEncoder.java:132)
	- locked <0x00000000e1e32e98> (a java.io.OutputStreamWriter)
	at sun.nio.cs.StreamEncoder.write(java.base@17.0.7/StreamEncoder.java:142)
	at java.io.OutputStreamWriter.write(java.base@17.0.7/OutputStreamWriter.java:223)
	at org.eclipse.angus.mail.handlers.text_plain.writeTo(text_plain.java:139)
	at jakarta.activation.ObjectDataContentHandler.writeTo(DataHandler.java:866)
	at jakarta.activation.DataHandler.writeTo(DataHandler.java:291)
	at jakarta.mail.internet.MimeBodyPart.writeTo(MimeBodyPart.java:1683)
	at jakarta.mail.internet.MimeMessage.writeTo(MimeMessage.java:1911)
	at org.eclipse.angus.mail.smtp.SMTPTransport.sendMessage(SMTPTransport.java:1305)
	- locked <0x00000000e1e330b8> (a org.eclipse.angus.mail.smtp.SMTPTransport)
	at jakarta.mail.Transport.send0(Transport.java:233)
	at jakarta.mail.Transport.send(Transport.java:102)
	at org.eclipse.angus.mail.util.logging.MailHandler.send(MailHandler.java:2965)
	at org.eclipse.angus.mail.util.logging.MailHandler.publish0(MailHandler.java:725)
	at org.eclipse.angus.mail.util.logging.MailHandler.publish(MailHandler.java:678)
	at org.jboss.logmanager.handlers.AsyncHandler$AsyncTask.run(AsyncHandler.java:206)
	at java.lang.Thread.run(java.base@17.0.7/Thread.java:833)

"Attach Listener" #17 daemon prio=9 os_prio=0 cpu=0.73ms elapsed=0.11s tid=0x0000564b05024db0 nid=0xb2e waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"VM Thread" os_prio=0 cpu=18.09ms elapsed=36.53s tid=0x0000564b0340e7b0 nid=0xae4 runnable  

"GC Thread#0" os_prio=0 cpu=58.18ms elapsed=36.55s tid=0x0000564b033955b0 nid=0xadf runnable  

"GC Thread#1" os_prio=0 cpu=108.51ms elapsed=31.18s tid=0x0000564b03e50760 nid=0xaf3 runnable  

"GC Thread#2" os_prio=0 cpu=53.24ms elapsed=31.15s tid=0x0000564b03f0f730 nid=0xaf4 runnable  

"GC Thread#3" os_prio=0 cpu=4.80ms elapsed=31.15s tid=0x0000564b03f10400 nid=0xaf5 runnable  

"G1 Main Marker" os_prio=0 cpu=0.44ms elapsed=36.55s tid=0x0000564b0339ae80 nid=0xae0 runnable  

"G1 Conc#0" os_prio=0 cpu=0.37ms elapsed=36.55s tid=0x0000564b0339c0b0 nid=0xae1 runnable  

"G1 Refine#0" os_prio=0 cpu=0.34ms elapsed=36.54s tid=0x0000564b033ea0d0 nid=0xae2 runnable  

"G1 Service" os_prio=0 cpu=16.73ms elapsed=36.54s tid=0x0000564b033eb290 nid=0xae3 runnable  

"VM Periodic Task Thread" os_prio=0 cpu=46.99ms elapsed=36.45s tid=0x0000564b0355b310 nid=0xaef waiting on condition  

JNI global refs: 17, weak refs: 0

       

       
      I'm testing with the snapshot of MailHandler but these are the general steps:

      1. In the WildFly console Create a MailHandler included in AngusMail module. Enable it and set its level to ALL. and pushLevel to ALL.
      2. Create an AsyncHandler with MailHandler as the subhandler.  Enable it and set its level to ALL, overflow policy to BLOCK, and capacity to 1000.
      3. Attach the AsyncHandler to the root logger.
      4. Set the root logger level to FINEST.
      5. Restart WildFly.  Shouldn't need an SMTP server.
      6. WildFly will stall forever and can be queried with jstack.
         

      I think there are a few things to consider on changing this behavior.

      1. ThreadLocal or simply checking if the current thread is the worker thread could be used to detect reentrance feedback loop.  
      2. It would be nice if sibling AsyncHandlers don't end up blocking each others worker thread in the case of AH1->MH1->reentrant record->AH2 with full queue.
      3. One policy to consider is if AsyncHandler detects reentrance, pass the current record to `publishToNestedHandlers` effectively barging the queue instead of blocking the worker thread.  This would allow the reentrance code to execute in the MailHandler allowing the record to be dealt with.  Other 3rd party handlers should be doing the same type of reentrance checking.
      4. An alternate policy is if AsyncHandler detects reentrance, just drop any record created by reentrance.  In most cases these reentrant records are not of interest.  This might be the safer choice even though it ignores the overflow policy of BLOCK.

              jperkins-rhn James Perkins
              jason.mehrens Jason Mehrens (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated: