There is only one JVM process involved as far as I know. I have a script which looks like this:
#!/bin/sh date "+%F %T,%N Before JVM start" java com.magine.maglev.Job -Djava.util.logging.manager=org.apache.logging.log4j.jul.LogManager date "+%F %T,%N After JVM end" I tried to make it run longer by a Thread.sleep(60*1000), but same problem: 2015-07-21 15:51:04,599538113 Before JVM start 2015-07-21 15:51:05,366 INFO com.magine.maglev.Job$: Startup [... more logging ...] 2015-07-21 15:52:10,799 FATAL Unable to register shutdown hook because JVM is shutting down. java.lang.IllegalStateException: Cannot add new shutdown hook as this is not started. Current state: STOPPED at org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry.addShutdownCallback(DefaultShutdownCallbackRegistry.java:113) at org.apache.logging.log4j.core.impl.Log4jContextFactory.addShutdownCallback(Log4jContextFactory.java:244) at org.apache.logging.log4j.core.LoggerContext.setUpShutdownHook(LoggerContext.java:182) at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:143) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:146) at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:41) at org.apache.logging.log4j.LogManager.getContext(LogManager.java:175) at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:102) at org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:43) at org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:42) at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:29) at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:284) at org.apache.spark.Logging$class.log(Logging.scala:52) at org.apache.spark.rpc.akka.AkkaRpcEnv$$anonfun$actorRef$lzycompute$1$1$$anon$1.log(AkkaRpcEnv.scala:93) at org.apache.spark.util.ActorLogReceive$$anon$1.apply(ActorLogReceive.scala:55) at org.apache.spark.util.ActorLogReceive$$anon$1.apply(ActorLogReceive.scala:42) at scala.PartialFunction$class.applyOrElse(PartialFunction.scala:123) at org.apache.spark.util.ActorLogReceive$$anon$1.applyOrElse(ActorLogReceive.scala:42) at akka.actor.Actor$class.aroundReceive(Actor.scala:465) at org.apache.spark.rpc.akka.AkkaRpcEnv$$anonfun$actorRef$lzycompute$1$1$$anon$1.aroundReceive(AkkaRpcEnv.scala:93) at akka.actor.ActorCell.receiveMessage(ActorCell.scala:516) at akka.actor.ActorCell.invoke(ActorCell.scala:487) at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:238) at akka.dispatch.Mailbox.run(Mailbox.scala:220) at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:393) at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) 2015-07-21 15:52:11,145821352 After JVM end On Tue, Jul 21, 2015 at 3:18 PM, Remko Popma <remko.po...@gmail.com> wrote: > That's strange: if you are logging at startup the shutdown hook should be > registered before the call to logger.log() returns... Does the batch start > another JVM process? > > Sent from my iPhone > > > On 2015/07/21, at 17:18, Mikael Ståldal <mikael.stal...@magine.com> > wrote: > > > > The app do some logging at startup as well, and quite some logging in > > between. However, it is a short running batch job, and in this case the > JVM > > only runs for 6 seconds in total. > > > > See below to get some more context about the timing. The first and last > log > > line are not from Log4j, they are from a bash script used to start the > JVM. > > > > I think that this is not only one problem, but two. First that this > occurs > > in the first place. Second that it is logged at FATAL level. > > > > > > 2015-07-21 10:11:24,022 Before JVM start > > > > 2015-07-21 10:11:24,771 INFO com.magine.maglev.Job$: Startup > > [... more logging here ...] > > 2015-07-21 10:11:30,216 FATAL Unable to register shutdown hook because > JVM > > is shutting down. java.lang.IllegalStateException: Cannot add new > shutdown > > hook as this is not started. Current state: STOPPED > > at > > > org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry.addShutdownCallback(DefaultShutdownCallbackRegistry.java:113) > > at > > > org.apache.logging.log4j.core.impl.Log4jContextFactory.addShutdownCallback(Log4jContextFactory.java:244) > > at > > > org.apache.logging.log4j.core.LoggerContext.setUpShutdownHook(LoggerContext.java:182) > > at > > org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:143) > > at > > > org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:146) > > at > > > org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:41) > > at > > org.apache.logging.log4j.LogManager.getContext(LogManager.java:175) > > at > > > org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:102) > > at > > > org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:43) > > at > > > org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:42) > > at > > > org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:29) > > at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:284) > > at org.apache.spark.Logging$class.log(Logging.scala:52) > > at > > > org.apache.spark.rpc.akka.AkkaRpcEnv$$anonfun$actorRef$lzycompute$1$1$$anon$1.log(AkkaRpcEnv.scala:93) > > at > > > org.apache.spark.util.ActorLogReceive$$anon$1.apply(ActorLogReceive.scala:55) > > at > > > org.apache.spark.util.ActorLogReceive$$anon$1.apply(ActorLogReceive.scala:42) > > at > > scala.PartialFunction$class.applyOrElse(PartialFunction.scala:123) > > at > > > org.apache.spark.util.ActorLogReceive$$anon$1.applyOrElse(ActorLogReceive.scala:42) > > at akka.actor.Actor$class.aroundReceive(Actor.scala:465) > > at > > > org.apache.spark.rpc.akka.AkkaRpcEnv$$anonfun$actorRef$lzycompute$1$1$$anon$1.aroundReceive(AkkaRpcEnv.scala:93) > > at akka.actor.ActorCell.receiveMessage(ActorCell.scala:516) > > at akka.actor.ActorCell.invoke(ActorCell.scala:487) > > at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:238) > > at akka.dispatch.Mailbox.run(Mailbox.scala:220) > > at > > > akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:393) > > at > > scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) > > at > > > scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) > > at > > scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) > > at > > > scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) > > > > 2015-07-21 10:11:30,558 After JVM end > > > > > >> On Tue, Jul 21, 2015 at 12:58 AM, Remko Popma <remko.po...@gmail.com> > wrote: > >> > >> Gary, enjoy your holiday! > >> > >> Mikael, > >> At first glance it seems to me that this problem happens because the > >> application does not start logging until it has done all the work and > the > >> JVM is shutting down. > >> > >> However, I'm not sure it really is a problem: Log4j tried to registered > a > >> shutdown hook, but couldn't. It then notified you of the problem and > >> continued to work. (The stack trace was generated from a try/catch > block.) > >> > >> If this error report is annoying, a workaround may be to change to your > app > >> to start logging at startup. > >> > >> Remko > >> > >> On Mon, Jul 20, 2015 at 6:25 PM, Mikael Ståldal < > mikael.stal...@magine.com > >> wrote: > >> > >>> 2015-07-20 11:23:31,741 FATAL Unable to register shutdown hook because > >> JVM > >>> is shutting down. java.lang.IllegalStateException: Cannot add new > >> shutdown > >>> hook as this is not started. Current state: STOPPED > >>> at > >> > org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry.addShutdownCallback(DefaultShutdownCallbackRegistry.java:113) > >>> at > >> > org.apache.logging.log4j.core.impl.Log4jContextFactory.addShutdownCallback(Log4jContextFactory.java:244) > >>> at > >> > org.apache.logging.log4j.core.LoggerContext.setUpShutdownHook(LoggerContext.java:182) > >>> at > >>> > org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:143) > >>> at > >> > org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:146) > >>> at > >> > org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:41) > >>> at > >>> org.apache.logging.log4j.LogManager.getContext(LogManager.java:175) > >>> at > >> > org.apache.logging.log4j.spi.AbstractLoggerAdapter.getContext(AbstractLoggerAdapter.java:102) > >>> at > >> > org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:43) > >>> at > >> > org.apache.logging.log4j.spi.AbstractLoggerAdapter.getLogger(AbstractLoggerAdapter.java:42) > >>> at > >> > org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:29) > >>> at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:284) > >>> at org.apache.spark.Logging$class.log(Logging.scala:52) > >>> at > >> > org.apache.spark.rpc.akka.AkkaRpcEnv$$anonfun$actorRef$lzycompute$1$1$$anon$1.log(AkkaRpcEnv.scala:93) > >>> at > >> > org.apache.spark.util.ActorLogReceive$$anon$1.apply(ActorLogReceive.scala:55) > >>> at > >> > org.apache.spark.util.ActorLogReceive$$anon$1.apply(ActorLogReceive.scala:42) > >>> at > >>> scala.PartialFunction$class.applyOrElse(PartialFunction.scala:123) > >>> at > >> > org.apache.spark.util.ActorLogReceive$$anon$1.applyOrElse(ActorLogReceive.scala:42) > >>> at akka.actor.Actor$class.aroundReceive(Actor.scala:465) > >>> at > >> > org.apache.spark.rpc.akka.AkkaRpcEnv$$anonfun$actorRef$lzycompute$1$1$$anon$1.aroundReceive(AkkaRpcEnv.scala:93) > >>> at akka.actor.ActorCell.receiveMessage(ActorCell.scala:516) > >>> at akka.actor.ActorCell.invoke(ActorCell.scala:487) > >>> at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:238) > >>> at akka.dispatch.Mailbox.run(Mailbox.scala:220) > >>> at > >> > akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:393) > >>> at > >>> scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) > >>> at > >> > scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) > >>> at > >>> > scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) > >>> at > >> > scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) > >>> > >>> > >>> On Sat, Jul 18, 2015 at 1:44 AM, Gary Gregory <garydgreg...@gmail.com> > >>> wrote: > >>> > >>>> Hi Mikael, > >>>> > >>>> I just committed a minor tweak in git master: Include exceptions when > >>>> logging FATAL events in > >>>> org.apache.logging.log4j.core.LoggerContext.setUpShutdownHook() > >>>> > >>>> Can you try git master and see what is the exception that gets logged? > >>>> > >>>> Thank you, > >>>> Gary > >>>> > >>>> On Thu, Jul 16, 2015 at 1:49 AM, Mikael Ståldal < > >>> mikael.stal...@magine.com > >>>> wrote: > >>>> > >>>>> I sometimes get the message: > >>>>> FATAL Unable to register shutdown hook because JVM is shutting down. > >>>>> > >>>>> This happens in a short running batch job. > >>>>> > >>>>> Can it be so that Log4j did not have time to initialize fully before > >>>>> shutting down? What can be done about it? > >>>>> > >>>>> Log4j 2.3. > >>>>> > >>>>> -- > >>>>> [image: MagineTV] > >>>>> > >>>>> *Mikael Ståldal* > >>>>> Senior backend developer > >>>>> > >>>>> *Magine TV* > >>>>> mikael.stal...@magine.com > >>>>> Regeringsgatan 25 | 111 53 Stockholm, Sweden | www.magine.com > >>>>> > >>>>> Privileged and/or Confidential Information may be contained in this > >>>>> message. If you are not the addressee indicated in this message > >>>>> (or responsible for delivery of the message to such a person), you > >> may > >>>> not > >>>>> copy or deliver this message to anyone. In such case, > >>>>> you should destroy this message and kindly notify the sender by reply > >>>>> email. > >>>> > >>>> > >>>> > >>>> -- > >>>> E-Mail: garydgreg...@gmail.com | ggreg...@apache.org > >>>> Java Persistence with Hibernate, Second Edition > >>>> <http://www.manning.com/bauer3/> > >>>> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/> > >>>> Spring Batch in Action <http://www.manning.com/templier/> > >>>> Blog: http://garygregory.wordpress.com > >>>> Home: http://garygregory.com/ > >>>> Tweet! http://twitter.com/GaryGregory > >>> > >>> > >>> > >>> -- > >>> [image: MagineTV] > >>> > >>> *Mikael Ståldal* > >>> Senior backend developer > >>> > >>> *Magine TV* > >>> mikael.stal...@magine.com > >>> Regeringsgatan 25 | 111 53 Stockholm, Sweden | www.magine.com > >>> > >>> Privileged and/or Confidential Information may be contained in this > >>> message. If you are not the addressee indicated in this message > >>> (or responsible for delivery of the message to such a person), you may > >> not > >>> copy or deliver this message to anyone. In such case, > >>> you should destroy this message and kindly notify the sender by reply > >>> email. > > > > > > > > -- > > [image: MagineTV] > > > > *Mikael Ståldal* > > Senior backend developer > > > > *Magine TV* > > mikael.stal...@magine.com > > Regeringsgatan 25 | 111 53 Stockholm, Sweden | www.magine.com > > > > Privileged and/or Confidential Information may be contained in this > > message. If you are not the addressee indicated in this message > > (or responsible for delivery of the message to such a person), you may > not > > copy or deliver this message to anyone. In such case, > > you should destroy this message and kindly notify the sender by reply > > email. > > --------------------------------------------------------------------- > To unsubscribe, e-mail: log4j-user-unsubscr...@logging.apache.org > For additional commands, e-mail: log4j-user-h...@logging.apache.org > > -- [image: MagineTV] *Mikael Ståldal* Senior backend developer *Magine TV* mikael.stal...@magine.com Regeringsgatan 25 | 111 53 Stockholm, Sweden | www.magine.com Privileged and/or Confidential Information may be contained in this message. If you are not the addressee indicated in this message (or responsible for delivery of the message to such a person), you may not copy or deliver this message to anyone. In such case, you should destroy this message and kindly notify the sender by reply email.