You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Dmitry Spikhalskiy (JIRA)" <ji...@apache.org> on 2016/07/14 23:09:20 UTC

[jira] [Updated] (LOG4J2-1463) Disruptor stops after internal exception or error without diagnostic

     [ https://issues.apache.org/jira/browse/LOG4J2-1463?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Dmitry Spikhalskiy updated LOG4J2-1463:
---------------------------------------
    Description: 
Somewhere in my project, I have a creation of incorrect throwable (with cyclic dependency or two much nesting maybe, have no idea about a root cause for now).

In stdout I have an exception, which is logged ny java.util logger:
{noformat}
Exception in thread "Log4j2-AsyncLogger[AsyncContext@13a5fe33]1" java.lang.RuntimeException: java.lang.StackOverflowError
  at com.lmax.disruptor.FatalExceptionHandler.handleEventException(FatalExceptionHandler.java:45)
  at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:148)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
  at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.StackOverflowError
  at java.util.Collections$SetFromMap.contains(Collections.java:5459)
  at java.lang.Throwable.printEnclosedStackTrace(Throwable.java:681)
...
...
...
  at java.lang.Throwable.printEnclosedStackTrace(Throwable.java:709)
  at java.lang.Throwable.printStackTrace(Throwable.java:667)
  at java.lang.Throwable.printStackTrace(Throwable.java:721)
  at org.apache.logging.log4j.core.pattern.ThrowablePatternConverter.formatOption(ThrowablePatternConverter.java:139)
  at org.apache.logging.log4j.core.pattern.ThrowablePatternConverter.format(ThrowablePatternConverter.java:81)
  at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:69)
  at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
  at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:292)
  at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:206)
  at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:56)
  at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:148)
  at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:112)
  at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:98)
  at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:152)
  at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:125)
  at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:116)
  at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
  at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
  at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:378)
  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:362)
  at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
  at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:353)
  at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:103)
  at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:43)
  at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:28)
  at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
  ... 3 more
{noformat}

So, now Slf4j uses standard com.lmax.disruptor.FatalExceptionHandler, which:

1) use java.util.logging.Logger to log exception
2) rethrow exception and stop consumer thread / disruptor at all
So, the whole app stopped after that because it's blocked on #warn() #error() #info()/others invocation because of stopped disruptor inside Slf4J

What should be good to have:
Custom ExceptionHandler in Slf4J2, that
1) Would try to print some information about log parameters/exception that caused the problem. At least we could try to print exception class, try to print an exception message, try to fetch some first frames of the stacktrace. Up to 10 for example. We can do this even if case of Error and even if we decided th rethrow it and completely stop after this.
2) Will try to ignore such exception in terms of future invocations. So, logging framework shouldn't just stop whole application because of internal exception.

  was:
Hello,

In my project, I have an issue with Log4j2 because looks like, somewhere I have producing of incorrect throwables (with cyclic dependency or two much nesting maybe, have no idea for now).

Symptoms:
In stdout I have an exception:
{noformat}
Exception in thread "Log4j2-AsyncLogger[AsyncContext@13a5fe33]1" java.lang.RuntimeException: java.lang.StackOverflowError
  at com.lmax.disruptor.FatalExceptionHandler.handleEventException(FatalExceptionHandler.java:45)
  at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:148)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
  at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.StackOverflowError
  at java.util.Collections$SetFromMap.contains(Collections.java:5459)
  at java.lang.Throwable.printEnclosedStackTrace(Throwable.java:681)
...
...
...
  at java.lang.Throwable.printEnclosedStackTrace(Throwable.java:709)
  at java.lang.Throwable.printStackTrace(Throwable.java:667)
  at java.lang.Throwable.printStackTrace(Throwable.java:721)
  at org.apache.logging.log4j.core.pattern.ThrowablePatternConverter.formatOption(ThrowablePatternConverter.java:139)
  at org.apache.logging.log4j.core.pattern.ThrowablePatternConverter.format(ThrowablePatternConverter.java:81)
  at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:69)
  at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
  at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:292)
  at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:206)
  at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:56)
  at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:148)
  at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:112)
  at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:98)
  at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:152)
  at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:125)
  at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:116)
  at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
  at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
  at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:378)
  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:362)
  at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
  at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:353)
  at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:103)
  at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:43)
  at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:28)
  at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
  ... 3 more
{noformat}

So, now Slf4j uses standard com.lmax.disruptor.FatalExceptionHandler, which:

1) use java.util.logging.Logger to log exception
2) rethrow exception and stop consumer thread / disruptor at all
So, the whole app stopped after that because it's blocked on #warn() #error() #info()/others invocation because of stopped disruptor inside Slf4J

What should be good to have:
Custom ExceptionHandler, that
1) Would try to print some information about log parameters/exception that caused the problem. At least we could try to print exception class, try to print an exception message, try to fetch some first frames of the stacktrace. Up to 10 for example.
2) Will try to ignore such exception in terms of future invocations. So, logging framework shouldn't just stop whole application because of internal exception.


> Disruptor stops after internal exception or error without diagnostic
> --------------------------------------------------------------------
>
>                 Key: LOG4J2-1463
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-1463
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Core
>    Affects Versions: 2.5
>            Reporter: Dmitry Spikhalskiy
>
> Somewhere in my project, I have a creation of incorrect throwable (with cyclic dependency or two much nesting maybe, have no idea about a root cause for now).
> In stdout I have an exception, which is logged ny java.util logger:
> {noformat}
> Exception in thread "Log4j2-AsyncLogger[AsyncContext@13a5fe33]1" java.lang.RuntimeException: java.lang.StackOverflowError
>   at com.lmax.disruptor.FatalExceptionHandler.handleEventException(FatalExceptionHandler.java:45)
>   at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:148)
>   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>   at java.lang.Thread.run(Thread.java:745)
> Caused by: java.lang.StackOverflowError
>   at java.util.Collections$SetFromMap.contains(Collections.java:5459)
>   at java.lang.Throwable.printEnclosedStackTrace(Throwable.java:681)
> ...
> ...
> ...
>   at java.lang.Throwable.printEnclosedStackTrace(Throwable.java:709)
>   at java.lang.Throwable.printStackTrace(Throwable.java:667)
>   at java.lang.Throwable.printStackTrace(Throwable.java:721)
>   at org.apache.logging.log4j.core.pattern.ThrowablePatternConverter.formatOption(ThrowablePatternConverter.java:139)
>   at org.apache.logging.log4j.core.pattern.ThrowablePatternConverter.format(ThrowablePatternConverter.java:81)
>   at org.apache.logging.log4j.core.pattern.ExtendedThrowablePatternConverter.format(ExtendedThrowablePatternConverter.java:69)
>   at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:36)
>   at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:292)
>   at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:206)
>   at org.apache.logging.log4j.core.layout.PatternLayout.toSerializable(PatternLayout.java:56)
>   at org.apache.logging.log4j.core.layout.AbstractStringLayout.toByteArray(AbstractStringLayout.java:148)
>   at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:112)
>   at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:98)
>   at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:152)
>   at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:125)
>   at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:116)
>   at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
>   at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390)
>   at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:378)
>   at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:362)
>   at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:79)
>   at org.apache.logging.log4j.core.async.AsyncLogger.actualAsyncLog(AsyncLogger.java:353)
>   at org.apache.logging.log4j.core.async.RingBufferLogEvent.execute(RingBufferLogEvent.java:103)
>   at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:43)
>   at org.apache.logging.log4j.core.async.RingBufferLogEventHandler.onEvent(RingBufferLogEventHandler.java:28)
>   at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:129)
>   ... 3 more
> {noformat}
> So, now Slf4j uses standard com.lmax.disruptor.FatalExceptionHandler, which:
> 1) use java.util.logging.Logger to log exception
> 2) rethrow exception and stop consumer thread / disruptor at all
> So, the whole app stopped after that because it's blocked on #warn() #error() #info()/others invocation because of stopped disruptor inside Slf4J
> What should be good to have:
> Custom ExceptionHandler in Slf4J2, that
> 1) Would try to print some information about log parameters/exception that caused the problem. At least we could try to print exception class, try to print an exception message, try to fetch some first frames of the stacktrace. Up to 10 for example. We can do this even if case of Error and even if we decided th rethrow it and completely stop after this.
> 2) Will try to ignore such exception in terms of future invocations. So, logging framework shouldn't just stop whole application because of internal exception.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org