Log4j 2
  1. Log4j 2
  2. LOG4J2-137

Build hangs during SMTPAppenderTest

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta3
    • Fix Version/s: 2.0-beta4
    • Component/s: None
    • Labels:
      None
    • Environment:

      Description

      I was trying to build SVN revision r1426064

      This is the stacktrace of the hang:
      Running org.apache.logging.log4j.core.appender.SMTPAppenderTest
      2012-12-28 22:10:56
      Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.6-b04 mixed mode):
      "Thread-0" prio=5 tid=0x00007ffd70a23800 nid=0x5307 runnable [0x0000000171629000]
      java.lang.Thread.State: RUNNABLE
      at java.net.PlainSocketImpl.socketAccept(Native Method)
      at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:398)
      at java.net.ServerSocket.implAccept(ServerSocket.java:522)
      at java.net.ServerSocket.accept(ServerSocket.java:490)
      at com.dumbster.smtp.SimpleSmtpServer.run(Unknown Source)
      at java.lang.Thread.run(Thread.java:722)
      "Service Thread" daemon prio=5 tid=0x00007ffd71855000 nid=0x5103 runnable [0x0000000000000000]
      java.lang.Thread.State: RUNNABLE
      "C2 CompilerThread1" daemon prio=5 tid=0x00007ffd71854000 nid=0x5003 waiting on condition [0x0000000000000000]
      java.lang.Thread.State: RUNNABLE
      "C2 CompilerThread0" daemon prio=5 tid=0x00007ffd70856000 nid=0x4f03 waiting on condition [0x0000000000000000]
      java.lang.Thread.State: RUNNABLE
      "Signal Dispatcher" daemon prio=5 tid=0x00007ffd70855000 nid=0x4e03 waiting on condition [0x0000000000000000]
      java.lang.Thread.State: RUNNABLE
      "Finalizer" daemon prio=5 tid=0x00007ffd7081e000 nid=0x3b03 in Object.wait() [0x0000000170b56000]
      java.lang.Thread.State: WAITING (on object monitor)
      at java.lang.Object.wait(Native Method)

      • waiting on <0x000000014e7a5798> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
      • locked <0x000000014e7a5798> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)
        "Reference Handler" daemon prio=5 tid=0x00007ffd7080f800 nid=0x3a03 in Object.wait() [0x0000000170a53000]
        java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
      • waiting on <0x000000014e7a5320> (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 <0x000000014e7a5320> (a java.lang.ref.Reference$Lock)
        "main" prio=5 tid=0x00007ffd7080e000 nid=0x1703 in Object.wait() [0x000000010bbed000]
        java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
      • waiting on <0x000000014f874068> (a com.dumbster.smtp.SimpleSmtpServer)
        at java.lang.Object.wait(Object.java:503)
        at com.dumbster.smtp.SimpleSmtpServer.start(Unknown Source)
      • locked <0x000000014f874068> (a com.dumbster.smtp.SimpleSmtpServer)
        at org.apache.logging.log4j.core.appender.SMTPAppenderTest.testDelivery(SMTPAppenderTest.java:137)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:601)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
        at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
        at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:252)
        at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:141)
        at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:112)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:601)
        at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189)
        at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165)
        at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85)
        at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:115)
        at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:75)
        "VM Thread" prio=5 tid=0x00007ffd71847800 nid=0x3903 runnable
        "GC task thread#0 (ParallelGC)" prio=5 tid=0x00007ffd71804800 nid=0x3703 runnable
        "GC task thread#1 (ParallelGC)" prio=5 tid=0x00007ffd71805800 nid=0x3803 runnable
        "VM Periodic Task Thread" prio=5 tid=0x00007ffd71852800 nid=0x5203 waiting on condition
        JNI global references: 160
        Heap
        PSYoungGen total 26240K, used 17690K [0x000000014e7a0000, 0x00000001504e0000, 0x000000016bba0000)
        eden space 22528K, 78% used [0x000000014e7a0000,0x000000014f8e6a98,0x000000014fda0000)
        from space 3712K, 0% used [0x0000000150140000,0x0000000150140000,0x00000001504e0000)
        to space 3712K, 0% used [0x000000014fda0000,0x000000014fda0000,0x0000000150140000)
        ParOldGen total 59904K, used 0K [0x0000000113fa0000, 0x0000000117a20000, 0x000000014e7a0000)
        object space 59904K, 0% used [0x0000000113fa0000,0x0000000113fa0000,0x0000000117a20000)
        PSPermGen total 21248K, used 7927K [0x000000010eda0000, 0x0000000110260000, 0x0000000113fa0000)
        object space 21248K, 37% used [0x000000010eda0000,0x000000010f55df20,0x0000000110260000)

        Activity

        Hide
        Scott Severtson added a comment -

        I'm unable to reproduce the hang with the following configuration:

        Apache Maven 2.2.1 (rdebian-8)
        Java version: 1.6.0_33
        Java home: /usr/lib/jvm/java-6-sun-1.6.0.33/jre
        Default locale: en_US, platform encoding: UTF-8
        OS name: "linux" version: "3.2.0-35-generic" arch: "amd64" Family: "unix"

        The test uses TCP port 8199 - is it possible that port is in use by another application? Is the OSX Application Firewall appropriately configured to allow both the inbound and outbound connections?

        I see that Dumbster's SimpleSmtpServer is in an "accept" state, which probably means that it never received the packets sent by the Appender. The SMTPAppender seems to be waiting for a response, which it will never get. I'm 99% sure this is related to a firewall.

        Show
        Scott Severtson added a comment - I'm unable to reproduce the hang with the following configuration: Apache Maven 2.2.1 (rdebian-8) Java version: 1.6.0_33 Java home: /usr/lib/jvm/java-6-sun-1.6.0.33/jre Default locale: en_US, platform encoding: UTF-8 OS name: "linux" version: "3.2.0-35-generic" arch: "amd64" Family: "unix" The test uses TCP port 8199 - is it possible that port is in use by another application? Is the OSX Application Firewall appropriately configured to allow both the inbound and outbound connections? I see that Dumbster's SimpleSmtpServer is in an "accept" state, which probably means that it never received the packets sent by the Appender. The SMTPAppender seems to be waiting for a response, which it will never get. I'm 99% sure this is related to a firewall.
        Hide
        Joern Huxhorn added a comment - - edited

        Aww, crap. Some other program - in this case AirFlick - was occupying port 8199.
        It now builds with Java 6.
        Interestingly, it hangs at the same test with Java 7 (with firewall disabled).
        I updated the original report with new stacktraces and new environment.

        Show
        Joern Huxhorn added a comment - - edited Aww, crap. Some other program - in this case AirFlick - was occupying port 8199. It now builds with Java 6. Interestingly, it hangs at the same test with Java 7 (with firewall disabled). I updated the original report with new stacktraces and new environment.
        Hide
        Ralph Goers added a comment -

        I built with Java 1.7.0_05 and 1.7.0_10 and both Maven 3.0.3 and 3.0.4. I found some problems in some other tests which I fixed but did not experience the hang. I believe the only difference between my system and yours is that you are using OS/X 10.8.2 while I am running OS/X 10.7.5. My machine is a 2.5 GHz Intel Core i7.

        I also tested on a second MacBook Pro and had no errors. That was also running 10.7.5 and has a 2.4 GHz Intel Core I7.

        Can you check out the latest code and see if you still get the hang?

        Show
        Ralph Goers added a comment - I built with Java 1.7.0_05 and 1.7.0_10 and both Maven 3.0.3 and 3.0.4. I found some problems in some other tests which I fixed but did not experience the hang. I believe the only difference between my system and yours is that you are using OS/X 10.8.2 while I am running OS/X 10.7.5. My machine is a 2.5 GHz Intel Core i7. I also tested on a second MacBook Pro and had no errors. That was also running 10.7.5 and has a 2.4 GHz Intel Core I7. Can you check out the latest code and see if you still get the hang?
        Hide
        Joern Huxhorn added a comment -

        Whatever you did, it seems to have fixed the issue. I built three times and everything seems alright. Thanks!

        Show
        Joern Huxhorn added a comment - Whatever you did, it seems to have fixed the issue. I built three times and everything seems alright. Thanks!
        Hide
        Ralph Goers added a comment -

        Nevermind. In looking at the source code for version 1.6 it seems there is a race condition that may cause the server thread to notify the client before the client waits. The latest version of dumbster fixed this but apparently wasn't released. The project appears to be dead as the update was made in 2005 and the source hasn't been updated since. The project seems to have been forked to github but I don't see any releases anywhere. Given that, I really don't have a clue how to fix this.

        Show
        Ralph Goers added a comment - Nevermind. In looking at the source code for version 1.6 it seems there is a race condition that may cause the server thread to notify the client before the client waits. The latest version of dumbster fixed this but apparently wasn't released. The project appears to be dead as the update was made in 2005 and the source hasn't been updated since. The project seems to have been forked to github but I don't see any releases anywhere. Given that, I really don't have a clue how to fix this.
        Hide
        Ralph Goers added a comment -

        Dumbster only consists of 6 classes. They are all under the Apache license v2 so I just added them directly under the test directory and fixed the bug. I then removed the dependency on dumbster.

        Show
        Ralph Goers added a comment - Dumbster only consists of 6 classes. They are all under the Apache license v2 so I just added them directly under the test directory and fixed the bug. I then removed the dependency on dumbster.
        Hide
        Joern Huxhorn added a comment -

        Thanks. Forgot to close this on time.

        Show
        Joern Huxhorn added a comment - Thanks. Forgot to close this on time.

          People

          • Assignee:
            Ralph Goers
            Reporter:
            Joern Huxhorn
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development