Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-896

SocketAppender causes Deadlock

    XMLWordPrintable

Details

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: Major Major
    • 1.1.3
    • 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

      {invocationCounter=0}

      - 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

        Activity

          People

            tony19 Tony Trinh
            arndh Arnd Hannemann
            Votes:
            2 Vote for this issue
            Watchers:
            7 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: