Hi,
I'm experiencing some deadlock when remapping System.err using Jim Moore's
LoggingOutputStream w/ log4j v1.2.14. The deadlock is shown below. I realized
that there are dangers of remapping System.err, but I'd appreciate any guidance
for seasoned Log4j experts.
I tried to address this by trying doing hierarchical locking so that all
PrintStream methods grab Logger lock before PrintStream lock. i.e., Use a
"hierarchical locking" PrintStream subclass [instead of regular PrintStream]
between System.out/err + LoggingOutputStream. However, this didn't work
because it does not intercept calls from Throwable.printStackTrace() to the
remapped PrintStream.println().
Any comments about the following ideas?
- Change log4j itself so that it releases Category/Logger lock before
writing to appenders. Maybe store two appender lists in Logger ... one used by
Category.callAppenders() loop and for Category methods to add/remove appenders?
- Come up w/ an alternative log4j.properties configuration that avoid
such problems [but still logs Throwable.printStackTrace()/etc to stderr]?
Your help and expertise is greatly appreciated. Thanks!
- Howard
log4j.properties
----------------
log4j.rootLogger = ALL, console, F
# Writes to original System.err
log4j.appender.console = org.apache.log4j.ConsoleAppender
log4j.appender.console.target = System.err
# uses LoggingOutputStream (routes System.err to Log4j)
log4j.logger.stderr = ALL
log4j.appender.F = org.apache.log4j.FileAppender
log4j.appender.F.File = log.txt
Deadlock dump
-------------
i.e.,
"Thread-5" : RootLogger (0x0acf6af0) -> System.err (0x0ad091e8)
[deadlock w/ Thread-1]
"Thread-1" : System.err (0x0ad091e8) -> RootLogger (0x0acf6af0)
[deadlock w/ Thread-5]
"Thread-5":
at java.io.PrintStream.println(PrintStream.java:739)
- waiting to lock <0x0ad091e8> (a java.io.PrintStream)
at org.apache.log4j.helpers.LogLog.error(LogLog.java:142)
at
org.apache.log4j.helpers.OnlyOnceErrorHandler.error(OnlyOnceErrorHandler.java:77)
at
org.apache.log4j.helpers.OnlyOnceErrorHandler.error(OnlyOnceErrorHandler.java:67)
at org.apache.log4j.helpers.QuietWriter.write(QuietWriter.java:49)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:301)
at
org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:358)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:159)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:230)
- locked <0x0acfb678> (a com.v.server.toolkit.bl.log.Log4jFileAppender)
at
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:65)
at org.apache.log4j.Category.callAppenders(Category.java:203)
- locked <0x0acf6af0> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.log(Category.java:823)
at
com.v.server.core.services.log.ServerLogServiceImpl.println(ServerLogServiceImpl.java:304)
at
com.v.server.core.services.log.ServerLogServiceImpl.println(ServerLogServiceImpl.java:244)
at com.v.vmsserver.VRPCMessageHandler.log(VRPCMessageHandler.java:116)
at
com.v.oem.e.job.EVRPCMessageHandler.received(EVRPCMessageHandler.java:187)
at
com.v.common.core.bl.comm.CMSessionReceiveEvent.dispatchInternal(CMSessionReceiveEvent.java:34)
at
com.v.common.core.bl.comm.CMSessionDispatchableEvent.dispatch(CMSessionDispatchableEvent.java:91)
at com.v.server.core.CMMessageTask.runInContext(CMMessageTask.java:58)
at com.v.server.core.JobTask.run(JobTask.java:61)
at com.v.server.core.concurrent.Task.run(Task.java:118)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1061)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:575)
at java.lang.Thread.run(Thread.java:595)
"Thread-1":
at org.apache.log4j.Category.callAppenders(Category.java:201)
- waiting to lock <0x0acf6af0> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.log(Category.java:835)
at
org.apache.log4j.contribs.JimMoore.LoggingOutputStream.flush(LoggingOutputStream.java:204)
at java.io.PrintStream.write(PrintStream.java:414)
- locked <0x0ad091e8> (a java.io.PrintStream)
at sun.nio.cs.StreamEncoder$CharsetSE.writeBytes(StreamEncoder.java:336)
at sun.nio.cs.StreamEncoder$CharsetSE.implWrite(StreamEncoder.java:395)
at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:136)
- locked <0x0ad09728> (a java.io.OutputStreamWriter)
at java.io.OutputStreamWriter.write(OutputStreamWriter.java:191)
at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:111)
- locked <0x0ad09728> (a java.io.OutputStreamWriter)
at java.io.BufferedWriter.write(BufferedWriter.java:212)
- locked <0x0ad09728> (a java.io.OutputStreamWriter)
at java.io.Writer.write(Writer.java:126)
at java.io.PrintStream.write(PrintStream.java:457)
- locked <0x0ad091e8> (a java.io.PrintStream)
at java.io.PrintStream.print(PrintStream.java:602)
at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:985)
at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:978)
at java.lang.Thread.dispatchUncaughtException(Thread.java:1778)
---------------------------------------------------------------------
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
