Why is the new Java Logger failing to work consistently here?

Question

Note how most of the other calls Logger calls work, and all the System.out.println() works, but please someone explain to me why the Logger.info() calls in stop() and in destroy() never print with the rest of the log, since those functions are clearly running!? With java12, even the destroy() isn't showing. Is this a bug, am I using it weird, or what?

package test;
import java.util.logging.Logger;

public class Test {
    private static Logger LOGGER = Logger.getLogger(Test.class.getCanonicalName());

    public static void main(String[] args) {
        System.out.println("main()");
        LOGGER.info("main()");
        new Test();
    }

    private Test() {
        LOGGER.info("Test()");
        System.out.println("Test()");
        Runtime.getRuntime().addShutdownHook(new ShutdownThread());
    }

    public void shutdown() throws Exception {
        LOGGER.info("shutdown()");
        System.out.println("shutdown()");
        stop();
        destroy();
    }

    public void stop() throws Exception {
        LOGGER.info("stop()");
        System.out.println("stop()");
    }

    public void destroy() {
        LOGGER.info("destroy()");
        System.out.println("destroy()");
    }

    class ShutdownThread extends Thread {
        ShutdownThread() {
            super("app-shutdown-hook");
        }

        @Override
        public void run() {
            try {
                shutdown();
            } catch (Exception e) {
                e.printStackTrace();
            }
            System.out.println("Bye! ‍♂️");
        }
    }
}

OUTPUT with both java 10 and java 11 (OpenJDK):

main()
Mar 14, 2020 1:53:59 PM test.Test main
INFO: main()
Mar 14, 2020 1:53:59 PM test.Test <init>
INFO: Test()
Test()
Mar 14, 2020 1:53:59 PM test.Test shutdown
INFO: shutdown()
shutdown()
stop()
destroy()
Bye! ‍♂️

OUTPUT with java 12 (OpenJDK):

main()
Mar 14, 2020 2:17:13 PM test.Test main
INFO: main()
Mar 14, 2020 2:17:13 PM test.Test <init>
INFO: Test()
Test()
shutdown()
stop()
destroy()
Bye! ‍♂️

Maybe [this](https://stackoverflow.com/questions/13825403/java-how-to-get-logger-to-work-in-shutdown-hook) ? — HomeIsWhereThePcIs, Mar 14 '20 at 21:45

jmehrens · Accepted Answer · 2020-03-16T15:22:45.243

This issue is coverted in: JDK-8161253 - LogManager$Cleaner() can prevent logging in other shutdown hooks.

Per the ticket:

As a workaround to creating a custom shutdown hook you can create a custom handler and install it on the root logger. The first action of the LogManager$Cleaner is to close all the installed handlers on the logger. Once the cleaner calls the close on the custom handler you can then do one of the following:

Have cleaner run your shutdown code inside the handler.
Find your custom shutdown hook using the Thread API and join with it.

Here is solution #1:

import java.util.logging.Handler;
import java.util.logging.LogRecord;
import java.util.logging.Logger;

public class Test {
    private static Logger LOGGER = Logger.getLogger(Test.class.getCanonicalName());

    public static void main(String[] args) {
        System.out.println("main()");
        LOGGER.info("main()");
        new Test();
    }

    private Test() {
        LOGGER.info("Test()");
        System.out.println("Test()");
        addShutdownHandler();
    }

    private void addShutdownHandler() {
        Logger root = Logger.getLogger("");
        Handler[] handlers = root.getHandlers();

        for(Handler h : handlers) {
            if (h.getClass() == ShutdownHandler.class) {
                return;
            }
        }

        for(Handler h : handlers) {
            root.removeHandler(h);
        }

        root.addHandler(new ShutdownHandler());

        for(Handler h : handlers) {
            root.addHandler(h);
        }
    }

    public void shutdown() throws Exception {
        LOGGER.info("shutdown()");
        System.out.println("shutdown()");
        stop();
        destroy();
    }

    public void stop() throws Exception {
        LOGGER.info("stop()");
        System.out.println("stop()");
    }

    public void destroy() {
        LOGGER.info("destroy()");
        System.out.println("destroy()");
    }

    class ShutdownHandler extends Handler {
        ShutdownHandler() {
        }

        @Override
        public void close() {
            final Thread t = Thread.currentThread();
            final String old = t.getName();
            t.setName("app-shutdown-hook");
            try {
                shutdown();
                System.out.println("Bye! ‍♂️");
            } catch (Exception e) {
                e.printStackTrace();
            } finally {
                t.setName(old);
            }
        }

        @Override
        public void flush() {
        }

        @Override
        public void publish(LogRecord r) {
            isLoggable(r);
        }
    }
}

Solution #2 gets tricky as we can't ensure that from a shutdown hook that another shutdown hook was started. This means extra coding if you want to use Thread::join. So to workaround this issue we simply use the Future API:

import java.util.concurrent.Callable;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.FutureTask;
import java.util.logging.ErrorManager;
import java.util.logging.Handler;
import java.util.logging.LogRecord;
import java.util.logging.Logger;

public class Test {
    private static Logger LOGGER = Logger.getLogger(Test.class.getCanonicalName());

    public static void main(String[] args) {
        System.out.println("main()");
        LOGGER.info("main()");
        new Test();
    }

    private Test() {
        LOGGER.info("Test()");
        System.out.println("Test()");
        addShutdownHandler();
    }

    private void addShutdownHandler() {
        Logger root = Logger.getLogger("");
        Handler[] handlers = root.getHandlers();

        for(Handler h : handlers) {
            if (h.getClass() == CleanerJoin.class) {
                return;
            }
        }

        for(Handler h : handlers) {
            root.removeHandler(h);
        }

        root.addHandler(new CleanerJoin());

        for(Handler h : handlers) {
            root.addHandler(h);
        }
    }

    public void shutdown() throws Exception {
        LOGGER.info("shutdown()");
        System.out.println("shutdown()");
        stop();
        destroy();
    }

    public void stop() throws Exception {
        LOGGER.info("stop()");
        System.out.println("stop()");
    }

    public void destroy() {
        LOGGER.info("destroy()");
        System.out.println("destroy()");
    }

    class ShutdownTask implements Callable<Void> {
        ShutdownTask() {
        }

        @Override
        public Void call() throws Exception {
            shutdown();
            System.out.println("Bye! ‍♂️");
            return null;
        }
    }

    class CleanerJoin extends Handler {
        private final FutureTask<Void> sdt = new FutureTask<>(new ShutdownTask());

        CleanerJoin() {
            Runtime.getRuntime().addShutdownHook(new Thread(sdt, "app-shutdown-hook"));
        }


        @Override
        public void close() {
            boolean interrupted = false;
            try {
                for(;;) {
                    try { //Could use LogManager to lookup timeout values and use a timed join.
                        sdt.get();
                        break;
                    } catch (ExecutionException e) {
                        reportError("Shutdown hook failed.", e, ErrorManager.CLOSE_FAILURE);
                        break;
                    } catch (InterruptedException retry) {
                        interrupted = true;
                    }
                }
            } finally {
                if (interrupted) {
                    Thread.currentThread().interrupt();
                }
            }
        }

        @Override
        public void flush() {
        }

        @Override
        public void publish(LogRecord r) {
            isLoggable(r);
        }
    }
}

Why is the new Java Logger failing to work consistently here?

1 Answers1