Log4j 2
  1. Log4j 2
  2. LOG4J2-318

On termination Log4j terminates before the application

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-beta8
    • Fix Version/s: 2.0-beta9
    • Component/s: Core
    • Labels:

      Description

      My application is multi-threaded, when Ctrl-C is pressed to terminate it, Log4J ShutdownHooks in LoggerContext are called to close the appenders, so I lost any log that the application does during its termination.
      What I think I need, is a way to disable the automatic close done by LoggerContext and a way to call the close by myself.

      1. test.zip
        732 kB
        Maurizio Sartori

        Activity

        Hide
        Maurizio Sartori added a comment - - edited

        In the test.zip there is a test that shows the problem.

        If you leave the program run till end, the output is:

        OUT: main: start
        INFO main: start
        OUT: run
        INFO run
        OUT: run: HELLO 0
        INFO run: HELLO 0
        OUT: main: ThreadPool 1
        OUT: run: HELLO 1
        INFO main: ThreadPool 1
        INFO run: HELLO 1
        OUT: main: ThreadPool 1
        OUT: run: HELLO 2
        INFO main: ThreadPool 1
        INFO run: HELLO 2
        OUT: main: ThreadPool 1
        OUT: run: HELLO 3
        INFO main: ThreadPool 1
        INFO run: HELLO 3
        OUT: run: HELLO 4
        OUT: main: ThreadPool 1
        INFO run: HELLO 4
        INFO main: ThreadPool 1
        OUT: main: ThreadPool 1
        OUT: run: HELLO 5
        INFO main: ThreadPool 1
        INFO run: HELLO 5
        OUT: main: ThreadPool 1
        OUT: run: HELLO 6
        INFO main: ThreadPool 1
        INFO run: HELLO 6
        OUT: main: ThreadPool 1
        OUT: run: HELLO 7
        INFO main: ThreadPool 1
        INFO run: HELLO 7
        OUT: run: HELLO 8
        OUT: main: ThreadPool 1
        INFO run: HELLO 8
        INFO main: ThreadPool 1
        OUT: run: HELLO 9
        OUT: main: ThreadPool 1
        INFO run: HELLO 9
        INFO main: ThreadPool 1
        OUT: run: done
        OUT: main: ThreadPool 1
        INFO run: done
        OUT: run: exit
        INFO main: ThreadPool 1
        INFO run: exit
        OUT: main: terminated
        INFO main: terminated
        OUT: main: exit
        INFO main: exit
        2013-07-20 14:52:49,609 DEBUG Shutting down OutputStreamManager SYSTEM_OUT

        If you hit CtrlC the output is:

        OUT: main: start
        INFO main: start
        OUT: run
        INFO run
        OUT: run: HELLO 0
        INFO run: HELLO 0
        OUT: run: HELLO 1
        INFO run: HELLO 1
        OUT: main: ThreadPool 1
        INFO main: ThreadPool 1
        OUT: run: HELLO 2
        OUT: main: ThreadPool 1
        INFO run: HELLO 2
        INFO main: ThreadPool 1
        OUT: run: HELLO 3
        INFO run: HELLO 3
        OUT: main: ThreadPool 1
        INFO main: ThreadPool 1
        ^C
        2013-07-20 14:51:35,636 DEBUG Shutting down OutputStreamManager SYSTEM_OUT
        OUT: run: HELLO 4
        OUT: main: ThreadPool 1
        OUT: run: HELLO 5
        OUT: main: ThreadPool 1
        OUT: run: HELLO 6
        OUT: main: ThreadPool 1
        OUT: run: HELLO 7
        OUT: main: ThreadPool 1
        OUT: run: HELLO 8
        OUT: main: ThreadPool 1
        OUT: run: HELLO 9
        OUT: main: ThreadPool 1
        OUT: run: done
        OUT: run: exit
        OUT: main: ThreadPool 1
        OUT: main: killed
        OUT: main: exit

        Note that all the last logs are LOST!

        Show
        Maurizio Sartori added a comment - - edited In the test.zip there is a test that shows the problem. If you leave the program run till end, the output is: OUT: main: start INFO main: start OUT: run INFO run OUT: run: HELLO 0 INFO run: HELLO 0 OUT: main: ThreadPool 1 OUT: run: HELLO 1 INFO main: ThreadPool 1 INFO run: HELLO 1 OUT: main: ThreadPool 1 OUT: run: HELLO 2 INFO main: ThreadPool 1 INFO run: HELLO 2 OUT: main: ThreadPool 1 OUT: run: HELLO 3 INFO main: ThreadPool 1 INFO run: HELLO 3 OUT: run: HELLO 4 OUT: main: ThreadPool 1 INFO run: HELLO 4 INFO main: ThreadPool 1 OUT: main: ThreadPool 1 OUT: run: HELLO 5 INFO main: ThreadPool 1 INFO run: HELLO 5 OUT: main: ThreadPool 1 OUT: run: HELLO 6 INFO main: ThreadPool 1 INFO run: HELLO 6 OUT: main: ThreadPool 1 OUT: run: HELLO 7 INFO main: ThreadPool 1 INFO run: HELLO 7 OUT: run: HELLO 8 OUT: main: ThreadPool 1 INFO run: HELLO 8 INFO main: ThreadPool 1 OUT: run: HELLO 9 OUT: main: ThreadPool 1 INFO run: HELLO 9 INFO main: ThreadPool 1 OUT: run: done OUT: main: ThreadPool 1 INFO run: done OUT: run: exit INFO main: ThreadPool 1 INFO run: exit OUT: main: terminated INFO main: terminated OUT: main: exit INFO main: exit 2013-07-20 14:52:49,609 DEBUG Shutting down OutputStreamManager SYSTEM_OUT If you hit CtrlC the output is: OUT: main: start INFO main: start OUT: run INFO run OUT: run: HELLO 0 INFO run: HELLO 0 OUT: run: HELLO 1 INFO run: HELLO 1 OUT: main: ThreadPool 1 INFO main: ThreadPool 1 OUT: run: HELLO 2 OUT: main: ThreadPool 1 INFO run: HELLO 2 INFO main: ThreadPool 1 OUT: run: HELLO 3 INFO run: HELLO 3 OUT: main: ThreadPool 1 INFO main: ThreadPool 1 ^C 2013-07-20 14:51:35,636 DEBUG Shutting down OutputStreamManager SYSTEM_OUT OUT: run: HELLO 4 OUT: main: ThreadPool 1 OUT: run: HELLO 5 OUT: main: ThreadPool 1 OUT: run: HELLO 6 OUT: main: ThreadPool 1 OUT: run: HELLO 7 OUT: main: ThreadPool 1 OUT: run: HELLO 8 OUT: main: ThreadPool 1 OUT: run: HELLO 9 OUT: main: ThreadPool 1 OUT: run: done OUT: run: exit OUT: main: ThreadPool 1 OUT: main: killed OUT: main: exit Note that all the last logs are LOST!
        Hide
        Gary Gregory added a comment -

        You cannot control the order of JRE shutdown threads, so it seems to me we need to make using a Log4J shutdown thread optional. If you turn it off, you can then shutdown Log4j yourself.

        We could call the option "shutdownHook=true|false".

        Show
        Gary Gregory added a comment - You cannot control the order of JRE shutdown threads, so it seems to me we need to make using a Log4J shutdown thread optional. If you turn it off, you can then shutdown Log4j yourself. We could call the option "shutdownHook=true|false".
        Hide
        Remko Popma added a comment -

        Or log4j2.disable.shutdownHook=true (because it's enabled by default.) I used similar naming for the sys prop that disables JMX instrumentation.

        Show
        Remko Popma added a comment - Or log4j2.disable.shutdownHook=true (because it's enabled by default.) I used similar naming for the sys prop that disables JMX instrumentation.
        Hide
        Gary Gregory added a comment -

        I do not like having to tweak the command line, everything should be done in the config file, even JMX. Sure, you can have command line gadgets if you like but only to override the config file.

        Show
        Gary Gregory added a comment - I do not like having to tweak the command line, everything should be done in the config file, even JMX. Sure, you can have command line gadgets if you like but only to override the config file.
        Hide
        Remko Popma added a comment -

        I don't disagree with you.
        If you want to implement this as a config option, could you add an option for disabling JMX? It'd be good to make that consistent.

        Show
        Remko Popma added a comment - I don't disagree with you. If you want to implement this as a config option, could you add an option for disabling JMX? It'd be good to make that consistent.
        Hide
        Nick Williams added a comment - - edited

        Agreed. I believe we need the following two configuration options. It seems to me that both should be attributes in the <configuration> root element, unless JMX has other configuration options (in which case it should get its own <Jmx> sub-element).

        <enableShutdownHook> <=> <quote> [ true | false ] <quote> (default true)
        <enableJmx> <=> <quote> [ true | false ] <quote> (default true)

        My $0.02.

        Show
        Nick Williams added a comment - - edited Agreed. I believe we need the following two configuration options. It seems to me that both should be attributes in the <configuration> root element, unless JMX has other configuration options (in which case it should get its own <Jmx> sub-element). <enableShutdownHook> <=> <quote> [ true | false ] <quote> (default true) <enableJmx> <=> <quote> [ true | false ] <quote> (default true) My $0.02.
        Hide
        Gary Gregory added a comment -

        I think we should have a JMX subelement anyway. It is a large grain component and it just feels right to me. I'm sure we'll want to configure other features at some point.

        Show
        Gary Gregory added a comment - I think we should have a JMX subelement anyway. It is a large grain component and it just feels right to me. I'm sure we'll want to configure other features at some point.
        Hide
        Nick Williams added a comment -

        I can agree with that.

        Show
        Nick Williams added a comment - I can agree with that.
        Hide
        Ralph Goers added a comment -

        I am adding the configuration to allow disabling the shutdown hook. The JMX configuration should be in a separate Jira issue. I am also adding code to handle an IllegalStateException, which can occur when something tries to create a LoggerContext during JVM shutdown.

        I don't believe code any more code is needed to call shutdown. The user can currently do

        org.apache.logging.log4j.core.LoggerContext context = (org.apache.logging.log4j.core.LoggerContext)LogManager.getContext(false);
        context.stop();
        

        I don't believe shutdown should be part of the Log4j public API but should be part of the implementation, so the above is correct.

        Show
        Ralph Goers added a comment - I am adding the configuration to allow disabling the shutdown hook. The JMX configuration should be in a separate Jira issue. I am also adding code to handle an IllegalStateException, which can occur when something tries to create a LoggerContext during JVM shutdown. I don't believe code any more code is needed to call shutdown. The user can currently do org.apache.logging.log4j.core.LoggerContext context = (org.apache.logging.log4j.core.LoggerContext)LogManager.getContext( false ); context.stop(); I don't believe shutdown should be part of the Log4j public API but should be part of the implementation, so the above is correct.
        Hide
        Ralph Goers added a comment - - edited

        Added "shutdownHook" attribute to the configuration element. If set to "disable" then no shutdown hook will be registered. If this doesn't meet your needs please let us know.

        Show
        Ralph Goers added a comment - - edited Added "shutdownHook" attribute to the configuration element. If set to "disable" then no shutdown hook will be registered. If this doesn't meet your needs please let us know.
        Hide
        Maurizio Sartori added a comment -

        I tested the beta9-SNAPSHOT with the shutdownHook, it works as expected.
        Thanks.

        Show
        Maurizio Sartori added a comment - I tested the beta9-SNAPSHOT with the shutdownHook, it works as expected. Thanks.

          People

          • Assignee:
            Ralph Goers
            Reporter:
            Maurizio Sartori
          • Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development