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.
