Logback exceptions when shutting down

[valters]

Hi,

I am sometimes seeing strange exceptions while logback is shutting down. This has never happened before (also when I was using j256 logback appender), and somehow it seems to me it might be introduced by this appender... I have no idea how, but here goes:

15:09:35.101| INFO|Starting App 
...
15:09:36.513| INFO|done
Exception in thread "Logback shutdown hook [default]" Exception in thread "Thread-2" java.util.NoSuchElementException
    at java.base/java.util.ArrayList$Itr.next(ArrayList.java:999)
    at ch.qos.logback.classic.LoggerContext.fireOnStop(LoggerContext.java:335)
    at ch.qos.logback.classic.LoggerContext.stop(LoggerContext.java:349)
    at ch.qos.logback.core.hook.ShutdownHookBase.stop(ShutdownHookBase.java:39)
    at ch.qos.logback.core.hook.DelayingShutdownHook.run(DelayingShutdownHook.java:57)
    at java.base/java.lang.Thread.run(Thread.java:834)
java.lang.ArrayIndexOutOfBoundsException: Index -1 out of bounds for length 10
    at java.base/java.util.ArrayList.shiftTailOverGap(ArrayList.java:779)
    at java.base/java.util.ArrayList.batchRemove(ArrayList.java:870)
    at java.base/java.util.ArrayList.retainAll(ArrayList.java:842)
    at ch.qos.logback.classic.LoggerContext.resetListenersExceptResetResistant(LoggerContext.java:305)
    at ch.qos.logback.classic.LoggerContext.reset(LoggerContext.java:227)
    at ch.qos.logback.classic.LoggerContext.stop(LoggerContext.java:348)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem$ShutdownHandler.run(LogbackLoggingSystem.java:327)
    at java.base/java.lang.Thread.run(Thread.java:834)

And

15:08:33.160| INFO|Starting App 
...
15:08:34.648| INFO|done
Exception in thread "Logback shutdown hook [default]" java.util.NoSuchElementException
    at java.base/java.util.ArrayList$Itr.next(ArrayList.java:999)
    at ch.qos.logback.classic.LoggerContext.fireOnReset(LoggerContext.java:323)
    at ch.qos.logback.classic.LoggerContext.reset(LoggerContext.java:226)
    at ch.qos.logback.classic.LoggerContext.stop(LoggerContext.java:348)
    at ch.qos.logback.core.hook.ShutdownHookBase.stop(ShutdownHookBase.java:39)
    at ch.qos.logback.core.hook.DelayingShutdownHook.run(DelayingShutdownHook.java:57)
    at java.base/java.lang.Thread.run(Thread.java:834)

This seems rather rare, and I would not know how to repro this. Maybe you will have some idea how it could happen? Seems to happen when exiting quickly from the app (i.e., when it has nothing to do). My use-case is a command line app for which I need to push the logs into CW.

I am running Amazon Coretto OpenJDK 11 LTS.

$ java -version
openjdk version "11.0.2" 2019-01-15 LTS
OpenJDK Runtime Environment Corretto-11.0.2.9.3 (build 11.0.2+9-LTS)
OpenJDK 64-Bit Server VM Corretto-11.0.2.9.3 (build 11.0.2+9-LTS, mixed mode)

[valters]

I just saw the same exception when testing with j256 CW appender. So I think it's simply issue that Spring logback shutdown hook has/causes. It's not specific to dibog appender.

06:41:09.452| INFO|done
Exception in thread "Thread-1" java.lang.ArrayIndexOutOfBoundsException
    at java.lang.System.arraycopy(Native Method)
    at java.util.ArrayList.batchRemove(ArrayList.java:730)
    at java.util.ArrayList.retainAll(ArrayList.java:715)
    at ch.qos.logback.classic.LoggerContext.resetListenersExceptResetResistant(LoggerContext.java:305)
    at ch.qos.logback.classic.LoggerContext.reset(LoggerContext.java:227)
    at ch.qos.logback.classic.LoggerContext.stop(LoggerContext.java:348)
    at org.springframework.boot.logging.logback.LogbackLoggingSystem$ShutdownHandler.run(LogbackLoggingSystem.java:327)
    at java.lang.Thread.run(Thread.java:748)

[dibog]

Hi @valters,

I nevertheless looked into the source code of LoggerContext and also could not see how my appender could influence this exception.

Thanks for bringing this issue forward.

Best regards, Dieter

PS: Sorry for the late reaction.