Details
-
Bug
-
Resolution: Fixed
-
Major
-
1.0.13
-
None
-
None
-
Ubuntu 13.04, Java7
Description
Logback hinders program to exit, when SocketAppender is used.
Very easy to reproduce.
Take the following Example Program:
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class Hello {
public static void main(String[] args)
{ Logger logger = LoggerFactory.getLogger("blub"); logger.debug("Hello world."); }}
with the following logback.xml:
<configuration scan="true" scanPeriod="60 seconds" debug="true">
<appender name="test" class="ch.qos.logback.classic.net.SocketAppender">
<remoteHost>localhost</remoteHost>
<port>5514</port>
</appender>
</configuration>
Now run it with 1.0.13 and JVM hangs:
java -cp slf4j-api-1.7.5.jar:logback-core-1.0.13.jar:logback-classic-1.0.13.jar:. Hello
21:04:01,307 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
21:04:01,307 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
21:04:01,307 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at file:/home/arnd/java/logback-1.0.13/logback.xml
21:04:01,417 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 1 minutes
21:04:01,418 |-INFO in ReconfigureOnChangeFilter
- Will scan for changes in [[/home/arnd/java/logback-1.0.13/logback.xml]] every 60 seconds.
21:04:01,418 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter
21:04:01,422 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.classic.net.SocketAppender]
21:04:01,427 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [test]
21:04:01,466 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
21:04:01,468 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@47fe5853 - Registering current configuration as safe fallback point
21:04:01,474 |-WARN in Logger[blub] - No appenders present in context [default] for logger [blub].
21:04:01,475 |-INFO in ch.qos.logback.classic.net.SocketAppender[test] - remote peer localhost:5514: connection established
Stacktrace shows, a Thread "hanging" in ch.qos.logback.core.net.AbstractSocketAppender.dispatchEvents:
Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.25-b01 mixed mode):
"DestroyJavaVM" prio=10 tid=0x00007f713c008800 nid=0x33af waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"pool-1-thread-1" prio=10 tid=0x00007f713c297000 nid=0x33bc waiting on condition [0x00007f71299b3000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000d7c3d3d0> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:458)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359)
at java.util.concurrent.SynchronousQueue.take(SynchronousQueue.java:925)
at ch.qos.logback.core.net.AbstractSocketAppender.dispatchEvents(AbstractSocketAppender.java:234)
at ch.qos.logback.core.net.AbstractSocketAppender.run(AbstractSocketAppender.java:191)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:724)
"Service Thread" daemon prio=10 tid=0x00007f713c0f1800 nid=0x33ba runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" daemon prio=10 tid=0x00007f713c0ef000 nid=0x33b9 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" daemon prio=10 tid=0x00007f713c0ec800 nid=0x33b8 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" daemon prio=10 tid=0x00007f713c0ea000 nid=0x33b7 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" daemon prio=10 tid=0x00007f713c09c000 nid=0x33b6 in Object.wait() [0x00007f712a81e000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000d7765798> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135) - locked <0x00000000d7765798> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:189)
"Reference Handler" daemon prio=10 tid=0x00007f713c099800 nid=0x33b5 in Object.wait() [0x00007f712a91f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000d7765320> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:503)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133) - locked <0x00000000d7765320> (a java.lang.ref.Reference$Lock)
"VM Thread" prio=10 tid=0x00007f713c092000 nid=0x33b4 runnable
"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007f713c016800 nid=0x33b0 runnable
"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007f713c018800 nid=0x33b1 runnable
"GC task thread#2 (ParallelGC)" prio=10 tid=0x00007f713c01a000 nid=0x33b2 runnable
"GC task thread#3 (ParallelGC)" prio=10 tid=0x00007f713c01c000 nid=0x33b3 runnable
"VM Periodic Task Thread" prio=10 tid=0x00007f713c0fc800 nid=0x33bb waiting on condition
JNI global references: 199
Heap
PSYoungGen total 36288K, used 7542K [0x00000000d7760000, 0x00000000d9fe0000, 0x0000000100000000)
eden space 31104K, 24% used [0x00000000d7760000,0x00000000d7ebdb40,0x00000000d95c0000)
from space 5184K, 0% used [0x00000000d9ad0000,0x00000000d9ad0000,0x00000000d9fe0000)
to space 5184K, 0% used [0x00000000d95c0000,0x00000000d95c0000,0x00000000d9ad0000)
ParOldGen total 83072K, used 0K [0x0000000086600000, 0x000000008b720000, 0x00000000d7760000)
object space 83072K, 0% used [0x0000000086600000,0x0000000086600000,0x000000008b720000)
PSPermGen total 21248K, used 6849K [0x0000000081400000, 0x00000000828c0000, 0x0000000086600000)
object space 21248K, 32% used [0x0000000081400000,0x0000000081ab05a0,0x00000000828c0000)
Attachments
Issue Links
- is duplicated by
-
LOGBACK-961 SocketAppender queue thread never completes
- Closed
- relates to (in)
-
LOGBACK-929 Some appenders prevent quitting of application if loggerContext.stop() isn't called.
- Resolved