0

EDIT: I have a static initializer block in my custom Handler. When I remove this it runs fine. I suspect there is something wrong in the static initializer. It tries to access some System properties and some LogManager properties.

Im running GlassFish from Eclipse Kepler.

I'm adding my own custom logger to GlassFish 4 as described in Chapter 7 of the Administration guide

All I do is to place the new Handler jar into the domain-dir/lib/ext directory and reference it in the logging.properties file as:

handlers=java.util.logging.ConsoleHandler,com.mytools.logging.JMSFileHandler

But when I start GlassFish it hangs at 69% and after a while I get a timeout error:

java.util.concurrent.TimeoutException
    at java.util.concurrent.FutureTask.get(Unknown Source)
    at oracle.eclipse.tools.glassfish.GlassfishGenericServerBehaviour.launchServer(GlassfishGenericServerBehaviour.java:202)
    at oracle.eclipse.tools.glassfish.GlassfishServerLaunchDelegate.startDASAndTarget(GlassfishServerLaunchDelegate.java:206)
    at oracle.eclipse.tools.glassfish.GlassfishServerLaunchDelegate.launch(GlassfishServerLaunchDelegate.java:110)
    at org.eclipse.debug.internal.core.LaunchConfiguration.launch(LaunchConfiguration.java:858)
    at org.eclipse.debug.internal.core.LaunchConfiguration.launch(LaunchConfiguration.java:707)
    at org.eclipse.debug.internal.core.LaunchConfiguration.launch(LaunchConfiguration.java:700)
    at org.eclipse.wst.server.core.internal.Server.startImpl2(Server.java:3537)
    at org.eclipse.wst.server.core.internal.Server.startImpl(Server.java:3473)
    at org.eclipse.wst.server.core.internal.Server$StartJob.run(Server.java:367)
    at org.eclipse.core.internal.jobs.Worker.run(Worker.java:53)

VisualVM Threaddump:

2014-08-19 17:50:19
Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.25-b01 mixed mode):

"FelixFrameworkWiring" daemon prio=6 tid=0x000000000d95a800 nid=0x2a0c in Object.wait() [0x00000000110bf000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000e14d0148> (a java.util.ArrayList)
    at java.lang.Object.wait(Object.java:503)
    at org.apache.felix.framework.FrameworkWiringImpl.run(FrameworkWiringImpl.java:162)
    - locked <0x00000000e14d0148> (a java.util.ArrayList)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"deployment-jar-scanner" daemon prio=6 tid=0x000000000d959800 nid=0x2f00 waiting on condition [0x0000000010f2e000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e1f259e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"deployment-jar-scanner" daemon prio=6 tid=0x000000000d959000 nid=0x27c waiting on condition [0x0000000010d5f000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e1f259e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"deployment-jar-scanner" daemon prio=6 tid=0x000000000d957800 nid=0x1c78 waiting on condition [0x000000001278e000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e1f259e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"deployment-jar-scanner" daemon prio=6 tid=0x000000000d956800 nid=0x3344 waiting on condition [0x00000000115ce000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e1f259e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"deployment-jar-scanner" daemon prio=6 tid=0x000000000d956000 nid=0x2898 waiting on condition [0x0000000010bee000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e1f259e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"transaction-manager" daemon prio=6 tid=0x000000000d953000 nid=0x3320 in Object.wait() [0x00000000107ff000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000e1eb8be8> (a java.util.TaskQueue)
    at java.lang.Object.wait(Object.java:503)
    at java.util.TimerThread.mainLoop(Timer.java:526)
    - locked <0x00000000e1eb8be8> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:505)

   Locked ownable synchronizers:
    - None

"Thread-11" daemon prio=6 tid=0x000000000d952000 nid=0x1f7c waiting on condition [0x000000001013e000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e20a48b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.ArrayBlockingQueue.take(ArrayBlockingQueue.java:374)
    at com.sun.enterprise.server.logging.GFFileHandler.log(GFFileHandler.java:825)
    at com.sun.enterprise.server.logging.GFFileHandler$3.run(GFFileHandler.java:540)

   Locked ownable synchronizers:
    - None

"deployment-jar-scanner" daemon prio=6 tid=0x000000000d951800 nid=0x29c8 waiting on condition [0x00000000106af000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e1f259e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"deployment-jar-scanner" daemon prio=6 tid=0x000000000d950800 nid=0x21e0 waiting on condition [0x00000000104ef000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e1f259e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"deployment-jar-scanner" daemon prio=6 tid=0x000000000d950000 nid=0x1e84 waiting on condition [0x000000000fd9e000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e1f259e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"pool-3-thread-1" prio=6 tid=0x000000000d94e800 nid=0x2a98 waiting on condition [0x000000001036f000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e1f56a88> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"SCR Component Actor" daemon prio=6 tid=0x000000000d82d000 nid=0x234 in Object.wait() [0x000000000ffee000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000e1fa3df0> (a java.util.LinkedList)
    at java.lang.Object.wait(Object.java:503)
    at org.apache.felix.scr.impl.ComponentActorThread.run(ComponentActorThread.java:74)
    - locked <0x00000000e1fa3df0> (a java.util.LinkedList)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"fileinstall-C:\Work\issue\issRepo\tap-server\server\glassfish\domains\domain1/autodeploy/bundles/plugins/" daemon prio=6 tid=0x000000000da94000 nid=0x30cc in Object.wait() [0x000000000b69e000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000e1fb4648> (a org.apache.felix.fileinstall.internal.DirectoryWatcher)
    at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:268)
    - locked <0x00000000e1fb4648> (a org.apache.felix.fileinstall.internal.DirectoryWatcher)

   Locked ownable synchronizers:
    - None

"Configuration Updater" daemon prio=6 tid=0x000000000d3a7800 nid=0x838 in Object.wait() [0x000000000fbef000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000e1fe1078> (a java.util.LinkedList)
    at java.lang.Object.wait(Object.java:503)
    at org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:67)
    - locked <0x00000000e1fe1078> (a java.util.LinkedList)

   Locked ownable synchronizers:
    - None

"DestroyJavaVM" prio=6 tid=0x000000000239c000 nid=0x35ac waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"GlassFish Kernel Main Thread" prio=6 tid=0x000000000cdbb800 nid=0x3498 in Object.wait() [0x000000000fa2f000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000e2094990> (a com.sun.enterprise.v3.server.AppServerStartup$1)
    at java.lang.Object.wait(Object.java:503)
    at com.sun.enterprise.v3.server.AppServerStartup$1.run(AppServerStartup.java:245)
    - locked <0x00000000e2094990> (a com.sun.enterprise.v3.server.AppServerStartup$1)

   Locked ownable synchronizers:
    - None

"pool-1-thread-1" daemon prio=6 tid=0x000000000c9aa800 nid=0x908 waiting on condition [0x000000000f78e000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000e1b99be0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"FelixStartLevel" daemon prio=6 tid=0x000000000c7d5800 nid=0x32e8 in Object.wait() [0x000000000c39f000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000e14cfed8> (a java.util.ArrayList)
    at java.lang.Object.wait(Object.java:503)
    at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:279)
    - locked <0x00000000e14cfed8> (a java.util.ArrayList)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"FelixDispatchQueue" daemon prio=6 tid=0x000000000a74f800 nid=0x3644 in Object.wait() [0x000000000c66e000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000e14f7828> (a java.util.ArrayList)
    at java.lang.Object.wait(Object.java:503)
    at org.apache.felix.framework.util.EventDispatcher.run(EventDispatcher.java:1063)
    - locked <0x00000000e14f7828> (a java.util.ArrayList)
    at org.apache.felix.framework.util.EventDispatcher.access$000(EventDispatcher.java:54)
    at org.apache.felix.framework.util.EventDispatcher$1.run(EventDispatcher.java:101)
    at java.lang.Thread.run(Thread.java:724)

   Locked ownable synchronizers:
    - None

"Service Thread" daemon prio=6 tid=0x000000000a489800 nid=0x3464 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"C2 CompilerThread1" daemon prio=10 tid=0x000000000a489000 nid=0x35a0 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"C2 CompilerThread0" daemon prio=10 tid=0x000000000a484000 nid=0x34ec waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"JDWP Event Helper Thread" daemon prio=6 tid=0x000000000a476000 nid=0x2de4 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"JDWP Transport Listener: dt_socket" daemon prio=6 tid=0x000000000a472800 nid=0x20f0 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Attach Listener" daemon prio=10 tid=0x000000000a3d3000 nid=0x2f78 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Signal Dispatcher" daemon prio=10 tid=0x000000000a3d2000 nid=0x238 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Finalizer" daemon prio=8 tid=0x0000000008341800 nid=0x3584 in Object.wait() [0x000000000a27f000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000e092a1e8> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
    - locked <0x00000000e092a1e8> (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)

   Locked ownable synchronizers:
    - None

"Reference Handler" daemon prio=10 tid=0x0000000008337800 nid=0x2258 in Object.wait() [0x000000000a37f000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000e0929ca8> (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 <0x00000000e0929ca8> (a java.lang.ref.Reference$Lock)

   Locked ownable synchronizers:
    - None

"VM Thread" prio=10 tid=0x0000000008330000 nid=0x1fd0 runnable 

"GC task thread#0 (ParallelGC)" prio=6 tid=0x00000000023ad000 nid=0x37b8 runnable 

"GC task thread#1 (ParallelGC)" prio=6 tid=0x00000000023af000 nid=0x1a98 runnable 

"GC task thread#2 (ParallelGC)" prio=6 tid=0x00000000023b1800 nid=0x34fc runnable 

"GC task thread#3 (ParallelGC)" prio=6 tid=0x00000000023b3000 nid=0x3368 runnable 

"GC task thread#4 (ParallelGC)" prio=6 tid=0x00000000023b6800 nid=0x2844 runnable 

"GC task thread#5 (ParallelGC)" prio=6 tid=0x00000000023b8000 nid=0xde4 runnable 

"GC task thread#6 (ParallelGC)" prio=6 tid=0x00000000023b9000 nid=0x2ba0 runnable 

"GC task thread#7 (ParallelGC)" prio=6 tid=0x00000000023bc800 nid=0x2c98 runnable 

"VM Periodic Task Thread" prio=10 tid=0x000000000a49e800 nid=0x167c waiting on condition 

JNI global references: 3733
Roland
  • 7,525
  • 13
  • 61
  • 124
  • 1
    Can you attach [visualvm](http://docs.oracle.com/javase/8/docs/technotes/guides/visualvm/index.html) to glassfish and post the thread dump? – jmehrens Aug 19 '14 at 15:37
  • @jmehrens done. Thanks for the comment, I didn't even know about VisualVM – Roland Aug 19 '14 at 15:54
  • 1
    At first glance I don't see anything unusual in the GF thread dump. Can you attach the Eclipse thread dump too? – jmehrens Aug 19 '14 at 17:26
  • @jmehrens The Eclipse Debug view doesnt show any Threads in this case. When GF starts up correctly I get the Thread view after a few seconds. – Roland Aug 20 '14 at 07:57
  • @jmehrens What kind of Manifest do I need to add the my custom Handler? Currently the manifest is the one generated by the Ant jar task. – Roland Aug 20 '14 at 08:48
  • @jmehrens Please see edit about static initializer in the custom Handler. – Roland Aug 20 '14 at 11:38
  • This has all the signs of a classloader deadlock but your thread dump is not showing one. Does verbose classloading show anything useful? – jmehrens Aug 20 '14 at 14:22

3 Answers3

1

Try running with verbose class loading output on. If there is an error in the static block that should show up as unable to load the class.

Then try one of the following:

  1. -XX:+AlwaysLockClassLoader
  2. -XX:+UnlockDiagnosticVMOptions -XX:+UnsyncloadClass

If you can, try and get rid of the static block and just fetch the properties on construction. Most of the handlers work that way so subclasses have their own namespace for the logging.properties.

package baz;
import java.io.IOException;
import java.util.logging.FileHandler;

public class FooHandler extends FileHandler {

    FooHandler() throws IOException {
        super();
    }
}

Will inherit all of the FileHandler properties:

baz.FooHandler.pattern=test.log
baz.FooHandler.append=true

You can also try moving that code to a nested class.

public class FooHandler extends Handler {

    @Override
    public void publish(LogRecord record) {
        if ("baz".equals(Helper.logProperties.get("bar"))) {
        }
    }

    @Override
    public void flush() {
    }

    @Override
    public void close() throws SecurityException {
        if ("baz".equals(Helper.logProperties.get("foo"))) {
        }
    }

    /**
     * Private lazy loaded class.
     */
    private static class Helper {

        /**
         * Use default access to avoid synthetic methods.
         */
        static Properties logProperties = new Properties();

        static {
            try (InputStream packageStream = Helper.class.getResourceAsStream("JMSFileHandler.properties")) {
                if (packageStream != null) {
                    logProperties.load(packageStream);
                }
            } catch (IOException e) {
                e.printStackTrace();
            }
        }
    }
}

Keep in mind that the default LogManager has some classloading and deadlock issues:

  1. logging: problems calling LogManager early in initialization
  2. LogManager class loading inconsistent with Java EE best practices
  3. Deadlock on LogManager initialization but via of HttpURLConnection
  4. DEADLOCK: Between Throwable.PrintStackTrace and ConsoleHandler
jmehrens
  • 10,580
  • 1
  • 38
  • 47
  • Please look at the answer that I just posted. – Roland Aug 20 '14 at 14:24
  • Fetching the properties on construction is a problem because I'm calling the super constructor(my class extends FileHandler) and that is the first thing that has to be called in the constructor. So the only way to initialize the properties is in a static way as in: `public JMSFileHandler() throws IOException, SecurityException { super(PATTERN, LIMIT, COUNT, APPEND);` – Roland Aug 20 '14 at 14:30
  • 1
    @Roland You can call the no argument super constructor and use the logging.properties to setup your handler. 'your.package.JMSFileHandler.pattern' – jmehrens Aug 20 '14 at 14:40
  • I had that idea, but in GlassFish you are supposed to set these properties using `asadmin set-log-attributes` which won't allow custom properties. I could still edit the file by hand though, but AFAIK this is discouraged. – Roland Aug 20 '14 at 14:51
1

After lots of trial and error I have figured out that the problem is in the static initializer of my handler class.

There are two parts that will freeze GlassFish and cause a TimeoutException:

1. Accessing the LogManager:

LogManager logManager = LogManager.getLogManager();

2. Trying to read resources from my package.

Remember that the Jar file will be placed into the domain-dir/lib/ext directory:

    Properties logProperties = new Properties();
    try (InputStream packageStream = JMSFileHandler.class.getResourceAsStream("JMSFileHandler.properties")) {
        if (packageStream != null) {
            logProperties.load(packageStream); //this line causes freeze
        }
    } catch (IOException e) {
        e.printStackTrace();
    }

The critical line here is the one marked with //this line causes freeze. So it is only trying to load the properties that causes a problem.

Roland
  • 7,525
  • 13
  • 61
  • 124
  • 1
    For both #1 and #2 I would expect to see one of the threads blocked in either a file read call or in ClassLoader.loadClass in your thread dump. Have you tried catching Throwable instead of IOException? – jmehrens Aug 21 '14 at 14:21
  • @jmehrens I found the problems. One was an unexpected exception when parsing an int in the wrong format. The other was that Properties.setProperty() will throw a NullPointerException when setting a null value. I will add an answer with clarification ASAP. – Roland Aug 21 '14 at 16:33
1

I have found the problems. The first two caused GlassFish to simply not display any log messages and eventually time out. The last will only cause the Handler to die without any hint of why this is happening.

  1. My custom Handler inherits from java.util.logging.FileHandler and was reading int properties like 'limit'. I thought that I could use the Java convention of _ as a digit separator. Alas this will throw an exception in Integer.parseInt() in my Handler.

  2. Also in my Handler Properties.setProperty(key, value) will throw a NullPointerException if the value is null. This is not directly documented in the Propertiesclass, you have to look it up in the documentation of HashTable(which Properties extends).

  3. java.util.logging.FileHandler reads a property called 'pattern' which designates the logfile. If you designate a non existing directory, it will not be created but instead throw an exception, causing the FileHandler to die quietly.

I still this is a problem with GlassFish, when a custom Handler throws an exception GF should be able to recover from this. Maybe that is because its happening in the static initializer.

Roland
  • 7,525
  • 13
  • 61
  • 124