JBoss deadlocks due to log4j serialization

Solution Verified - Updated

Environment

  • JBoss Enterprise Application Platform (EAP)

Issue

  • JBoss becomes unresponsive with threads getting stalled in log4j. Thread dumps show log4j is deadlocked like so:
"ajp-127.0.0.1-8009-1":
	at org.apache.log4j.Category.callAppenders(Category.java:201)
	- waiting to lock <0x00000006eb935130> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:388)
	at org.apache.log4j.Category.fatal(Category.java:379)
	at org.jboss.serial.persister.RegularObjectPersister.writeSlotWithMethod(RegularObjectPersister.java:127)
	at org.jboss.serial.persister.RegularObjectPersister.defaultWrite(RegularObjectPersister.java:86)
	at org.jboss.serial.persister.RegularObjectPersister.writeData(RegularObjectPersister.java:62)
	at org.jboss.serial.objectmetamodel.ObjectDescriptorFactory.describeObject(ObjectDescriptorFactory.java:276)
	at org.jboss.serial.objectmetamodel.DataContainer$DataContainerOutput.writeObject(DataContainer.java:390)
	at org.jboss.serial.persister.RegularObjectPersister.writeSlotWithFields(RegularObjectPersister.java:182)
	at org.jboss.serial.persister.RegularObjectPersister.defaultWrite(RegularObjectPersister.java:90)
	at org.jboss.serial.persister.RegularObjectPersister.writeData(RegularObjectPersister.java:62)
	at org.jboss.serial.objectmetamodel.ObjectDescriptorFactory.describeObject(ObjectDescriptorFactory.java:276)
	at org.jboss.serial.objectmetamodel.DataContainer$DataContainerOutput.writeObject(DataContainer.java:390)
	at org.jboss.serial.persister.RegularObjectPersister.writeSlotWithFields(RegularObjectPersister.java:182)
        ...
        at org.jboss.serial.persister.RegularObjectPersister.writeSlotWithFields(RegularObjectPersister.java:182)
	at org.jboss.serial.persister.RegularObjectPersister.defaultWrite(RegularObjectPersister.java:90)
	at org.jboss.serial.persister.RegularObjectPersister.writeData(RegularObjectPersister.java:62)
	at org.jboss.serial.objectmetamodel.ObjectDescriptorFactory.describeObject(ObjectDescriptorFactory.java:276)
	at org.jboss.serial.objectmetamodel.DataContainer$DataContainerOutput.writeObject(DataContainer.java:390)
	at org.jboss.serial.persister.ArrayPersister.saveObjectArray(ArrayPersister.java:110)
	at org.jboss.serial.persister.ArrayPersister.writeData(ArrayPersister.java:101)
	at org.jboss.serial.objectmetamodel.ObjectDescriptorFactory.describeObject(ObjectDescriptorFactory.java:276)
	at org.jboss.serial.objectmetamodel.DataContainer$DataContainerOutput.writeObject(DataContainer.java:390)
	at org.jboss.serial.persister.RegularObjectPersister.writeSlotWithFields(RegularObjectPersister.java:182)
	at org.jboss.serial.persister.ObjectOutputStreamProxy.writeFields(ObjectOutputStreamProxy.java:79)
	at org.jboss.serial.persister.ObjectOutputStreamProxy.defaultWriteObject(ObjectOutputStreamProxy.java:68)
	at java.util.Vector.writeObject(Vector.java:1012)
	- locked <0x00000006ec86e8b0> (a java.util.Vector)
	at sun.reflect.GeneratedMethodAccessor1794.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.jboss.serial.persister.RegularObjectPersister.writeSlotWithMethod(RegularObjectPersister.java:120)
        ...

"ajp-127.0.0.1-8009-2" prio=10 tid=0x00002aaad54f7800 nid=0x3e84 waiting for monitor entry [0x000000005adfb000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at java.util.Vector.size(Vector.java:268)
	- waiting to lock <0x00000006ec86e8b0> (a java.util.Vector)
	at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:62)
	at org.apache.log4j.Category.callAppenders(Category.java:203)
	- locked <0x00000006eb935130> (a org.apache.log4j.spi.RootLogger)
	at org.apache.log4j.Category.forcedLog(Category.java:388)
	at org.apache.log4j.Category.log(Category.java:853)
        ...

Resolution

  • Do not serialize log4j or objects that have reference chains to log4j
  • If log4j is referenced from other serializable objects, ensure it is a transient or static reference to prevent undesired serialization of log4j
  • Be careful about resteasy exceptions being serialized back to the client. For example, trying to serialize a org.jboss.resteasy.client.ClientResponseFailure can cause this as it has references to objects that reference non-serializable writers, logger streams, and log4j classes. Exceptions such as this should instead be caught with a custom serializable exception given back to the client instead with relevant information pulled into it.

Root Cause

  • JBoss serialization is allowing serialization of non-serialiazable objects
  • Hitting an error during serialization of the log4j appenders Vector grabs locks the RootLogger and appenders Vector in an inverse order that can deadlock with typical log4j threading behavior
  • This occurs when one thread starts serializing the Log4j appenders Vector and so grabs its lock. Meanwhile, a second thread needs to log a message and so locks the RootLogger and then waits on the locked Vector to be able to determine its size. Then the first thread hits an exception in its serialization of the Vector, needs to log, and so tries to grab the RootLogger. The threads are then effectively deadlocked.

Diagnostic Steps

  • Troubleshoot using thread dumps and additional steps mentioned in Java application unresponsive
  • If unsure of what leads to the log4j serialization, enable DEBUG logging for JBoss serialization, ensuring your appender logs thread names (%t option) and then reproduce the issue:
<appender name="FILE" class="org.jboss.logging.appender.DailyRollingFileAppender">
   ...
   <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%d %-5p [%c] (%t) %m%n"/>
   </layout>
</appender>
...
<category name="org.jboss.serial">
   <priority value="DEBUG"/>
</category>
  • With this logging you can follow messages like the following from the deadlocking thread to track what calls lead to improper serialization of log4j:
DEBUG [org.jboss.serial.persister.RegularObjectPersister] writeSlotWithFields slot=sun.nio.cs.StreamEncoder objectField out with object=org.jboss.logging.util.LoggerStream
DEBUG [org.jboss.serial.persister.RegularObjectPersister] writeSlotWithFields slot=org.jboss.logging.util.LoggerStream objectField logger with object=org.apache.log4j.Logger
DEBUG [org.jboss.serial.persister.RegularObjectPersister] writeSlotWithFields slot=org.apache.log4j.Logger objectField aai with object=org.apache.log4j.helpers.AppenderAttachableImpl
SBR
Product(s)
Components
Tags

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.