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
