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.
