You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by Mikael Ståldal <mi...@magine.com> on 2015/07/16 10:49:45 UTC
FATAL Unable to register shutdown hook because JVM is shutting down.
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.staldal@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.
Re: FATAL Unable to register shutdown hook because JVM is shutting down.
Posted by Gary Gregory <ga...@gmail.com>.
Now that we track the life cycle of objects in a couple of places, I wonder
if we could use this to check that we are shutting down during start up and
be more graceful.
Gary
On Mon, Aug 3, 2015 at 5:05 AM, Mikael Ståldal <mi...@magine.com>
wrote:
> This is not a web application.
>
> On Thu, Jul 16, 2015 at 11:10 AM, Adam Retter <ad...@googlemail.com>
> wrote:
>
> > Are you using log4j in a web application? If so if you google around
> > you can find several suggestions for solving this behaviour.
> >
> > On 16 July 2015 at 09:49, Mikael Ståldal <mi...@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.staldal@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.
> >
> >
> >
> > --
> > Adam Retter
> >
> > skype: adam.retter
> > tweet: adamretter
> > http://www.adamretter.org.uk
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> > For additional commands, e-mail: log4j-user-help@logging.apache.org
> >
> >
>
>
> --
> [image: MagineTV]
>
> *Mikael Ståldal*
> Senior backend developer
>
> *Magine TV*
> mikael.staldal@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: garydgregory@gmail.com | ggregory@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
Re: FATAL Unable to register shutdown hook because JVM is shutting down.
Posted by Mikael Ståldal <mi...@magine.com>.
This is not a web application.
On Thu, Jul 16, 2015 at 11:10 AM, Adam Retter <ad...@googlemail.com>
wrote:
> Are you using log4j in a web application? If so if you google around
> you can find several suggestions for solving this behaviour.
>
> On 16 July 2015 at 09:49, Mikael Ståldal <mi...@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.staldal@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.
>
>
>
> --
> Adam Retter
>
> skype: adam.retter
> tweet: adamretter
> http://www.adamretter.org.uk
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
--
[image: MagineTV]
*Mikael Ståldal*
Senior backend developer
*Magine TV*
mikael.staldal@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.
Re: FATAL Unable to register shutdown hook because JVM is shutting down.
Posted by Adam Retter <ad...@googlemail.com>.
Are you using log4j in a web application? If so if you google around
you can find several suggestions for solving this behaviour.
On 16 July 2015 at 09:49, Mikael Ståldal <mi...@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.staldal@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.
--
Adam Retter
skype: adam.retter
tweet: adamretter
http://www.adamretter.org.uk
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: FATAL Unable to register shutdown hook because JVM is shutting down.
Posted by Ralph Goers <ra...@dslextreme.com>.
That is correct, but if you only log to files that may not be so bad. If you use any asynchronous stuff or things that buffer events then that would be a problem.
Ralph
> On Jul 22, 2015, at 2:41 AM, Mikael Ståldal <mi...@magine.com> wrote:
>
> Yes, Spark seems to have its own shutdown hook and it logs stuff from
> within there.
>
> If I put shutdownHook="disable" in my log4j2.xml, the problem goes away.
> But then I guess that Log4j is never shut down properly?
>
> On Wed, Jul 22, 2015 at 8:39 AM, Ralph Goers <ra...@dslextreme.com>
> wrote:
>
>> The currentContext value indicates whether the LoggerContext stored in the
>> ThreadLocal should be used. This is usually the wrong choice which is why
>> the value is usually set to false. Instead, the LoggerContext is located
>> via the ClassLoaderContextSelector which finds the LoggerContext for the
>> ClassLoader of the class that owns the Logger.
>>
>> It looks to me like something is trying to log after logging has already
>> shut down. This is causing it to retrieve the LoggerContext, which has
>> already been stopped, and then it tries to restart it. Because the
>> LoggerContext is normally stopped by the execution of the shutdown hook it
>> is a very bad sign that the shutdown hook is trying to be reestablished.
>> My guess is that Spark has its own shutdown hook and is trying to log from
>> it after our shutdown hook has already run.
>>
>> When Matt wrote this code I believe he allowed for this situation but I’d
>> really have to dig into the code more to figure out. However, I did find
>> http://stackoverflow.com/questions/17400136/how-to-log-within-shutdown-hooks-with-log4j2
>> <
>> http://stackoverflow.com/questions/17400136/how-to-log-within-shutdown-hooks-with-log4j2>
>> which says to implement your own ShutdownCallbackRegistry.
>>
>> It might be a good idea to add the variation of the Shutdown registry
>> mentioned in the article so that it can be configured.
>>
>> Ralph
>>
>>> On Jul 21, 2015, at 8:57 PM, Remko Popma <re...@gmail.com> wrote:
>>>
>>> Looks like the context returned by
>>> AbstractLoggerAdapter.java:102
>>> is the result of LogManager.getContext(someClass, false);
>>>
>>> The boolean "false" indicates that a different LoggerContext may be
>> created (and started). I suspect this is what causes the problem.
>>>
>>> Ralph understands this part better than me. Ralph, should the slf4j
>> Log4jLoggerFactory pass "false" here? The default for LogManager seems to
>> be "true"...
>>>
>>> Remko
>>>
>>> Sent from my iPhone
>>>
>>>> On 2015/07/21, at 22:58, Mikael Ståldal <mi...@magine.com>
>> wrote:
>>>>
>>>> AbstractLoggerAdapter.java:102
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
>>> For additional commands, e-mail: log4j-user-help@logging.apache.org
>>>
>>>
>>
>>
>
>
> --
> [image: MagineTV]
>
> *Mikael Ståldal*
> Senior backend developer
>
> *Magine TV*
> mikael.staldal@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-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: FATAL Unable to register shutdown hook because JVM is shutting down.
Posted by Mikael Ståldal <mi...@magine.com>.
Yes, Spark seems to have its own shutdown hook and it logs stuff from
within there.
If I put shutdownHook="disable" in my log4j2.xml, the problem goes away.
But then I guess that Log4j is never shut down properly?
On Wed, Jul 22, 2015 at 8:39 AM, Ralph Goers <ra...@dslextreme.com>
wrote:
> The currentContext value indicates whether the LoggerContext stored in the
> ThreadLocal should be used. This is usually the wrong choice which is why
> the value is usually set to false. Instead, the LoggerContext is located
> via the ClassLoaderContextSelector which finds the LoggerContext for the
> ClassLoader of the class that owns the Logger.
>
> It looks to me like something is trying to log after logging has already
> shut down. This is causing it to retrieve the LoggerContext, which has
> already been stopped, and then it tries to restart it. Because the
> LoggerContext is normally stopped by the execution of the shutdown hook it
> is a very bad sign that the shutdown hook is trying to be reestablished.
> My guess is that Spark has its own shutdown hook and is trying to log from
> it after our shutdown hook has already run.
>
> When Matt wrote this code I believe he allowed for this situation but I’d
> really have to dig into the code more to figure out. However, I did find
> http://stackoverflow.com/questions/17400136/how-to-log-within-shutdown-hooks-with-log4j2
> <
> http://stackoverflow.com/questions/17400136/how-to-log-within-shutdown-hooks-with-log4j2>
> which says to implement your own ShutdownCallbackRegistry.
>
> It might be a good idea to add the variation of the Shutdown registry
> mentioned in the article so that it can be configured.
>
> Ralph
>
> > On Jul 21, 2015, at 8:57 PM, Remko Popma <re...@gmail.com> wrote:
> >
> > Looks like the context returned by
> > AbstractLoggerAdapter.java:102
> > is the result of LogManager.getContext(someClass, false);
> >
> > The boolean "false" indicates that a different LoggerContext may be
> created (and started). I suspect this is what causes the problem.
> >
> > Ralph understands this part better than me. Ralph, should the slf4j
> Log4jLoggerFactory pass "false" here? The default for LogManager seems to
> be "true"...
> >
> > Remko
> >
> > Sent from my iPhone
> >
> >> On 2015/07/21, at 22:58, Mikael Ståldal <mi...@magine.com>
> wrote:
> >>
> >> AbstractLoggerAdapter.java:102
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> > For additional commands, e-mail: log4j-user-help@logging.apache.org
> >
> >
>
>
--
[image: MagineTV]
*Mikael Ståldal*
Senior backend developer
*Magine TV*
mikael.staldal@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.
Re: FATAL Unable to register shutdown hook because JVM is shutting down.
Posted by Ralph Goers <ra...@dslextreme.com>.
The currentContext value indicates whether the LoggerContext stored in the ThreadLocal should be used. This is usually the wrong choice which is why the value is usually set to false. Instead, the LoggerContext is located via the ClassLoaderContextSelector which finds the LoggerContext for the ClassLoader of the class that owns the Logger.
It looks to me like something is trying to log after logging has already shut down. This is causing it to retrieve the LoggerContext, which has already been stopped, and then it tries to restart it. Because the LoggerContext is normally stopped by the execution of the shutdown hook it is a very bad sign that the shutdown hook is trying to be reestablished. My guess is that Spark has its own shutdown hook and is trying to log from it after our shutdown hook has already run.
When Matt wrote this code I believe he allowed for this situation but I’d really have to dig into the code more to figure out. However, I did find http://stackoverflow.com/questions/17400136/how-to-log-within-shutdown-hooks-with-log4j2 <http://stackoverflow.com/questions/17400136/how-to-log-within-shutdown-hooks-with-log4j2> which says to implement your own ShutdownCallbackRegistry.
It might be a good idea to add the variation of the Shutdown registry mentioned in the article so that it can be configured.
Ralph
> On Jul 21, 2015, at 8:57 PM, Remko Popma <re...@gmail.com> wrote:
>
> Looks like the context returned by
> AbstractLoggerAdapter.java:102
> is the result of LogManager.getContext(someClass, false);
>
> The boolean "false" indicates that a different LoggerContext may be created (and started). I suspect this is what causes the problem.
>
> Ralph understands this part better than me. Ralph, should the slf4j Log4jLoggerFactory pass "false" here? The default for LogManager seems to be "true"...
>
> Remko
>
> Sent from my iPhone
>
>> On 2015/07/21, at 22:58, Mikael Ståldal <mi...@magine.com> wrote:
>>
>> AbstractLoggerAdapter.java:102
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
Re: FATAL Unable to register shutdown hook because JVM is shutting down.
Posted by Remko Popma <re...@gmail.com>.
Looks like the context returned by
AbstractLoggerAdapter.java:102
is the result of LogManager.getContext(someClass, false);
The boolean "false" indicates that a different LoggerContext may be created (and started). I suspect this is what causes the problem.
Ralph understands this part better than me. Ralph, should the slf4j Log4jLoggerFactory pass "false" here? The default for LogManager seems to be "true"...
Remko
Sent from my iPhone
> On 2015/07/21, at 22:58, Mikael Ståldal <mi...@magine.com> wrote:
>
> AbstractLoggerAdapter.java:102
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-user-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: FATAL Unable to register shutdown hook because JVM is shutting down.
Posted by Mikael Ståldal <mi...@magine.com>.
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 <re...@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 <mi...@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 <re...@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.staldal@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 <ga...@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.staldal@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.staldal@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: garydgregory@gmail.com | ggregory@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.staldal@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.staldal@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-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
--
[image: MagineTV]
*Mikael Ståldal*
Senior backend developer
*Magine TV*
mikael.staldal@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.
Re: FATAL Unable to register shutdown hook because JVM is shutting down.
Posted by Remko Popma <re...@gmail.com>.
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 <mi...@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 <re...@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.staldal@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 <ga...@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.staldal@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.staldal@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: garydgregory@gmail.com | ggregory@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.staldal@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.staldal@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-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: FATAL Unable to register shutdown hook because JVM is shutting down.
Posted by Mikael Ståldal <mi...@magine.com>.
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 <re...@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.staldal@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 <ga...@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.staldal@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.staldal@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: garydgregory@gmail.com | ggregory@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.staldal@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.staldal@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.
Re: FATAL Unable to register shutdown hook because JVM is shutting down.
Posted by Remko Popma <re...@gmail.com>.
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 <mi...@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 <ga...@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.staldal@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.staldal@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: garydgregory@gmail.com | ggregory@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.staldal@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.
>
Re: FATAL Unable to register shutdown hook because JVM is shutting down.
Posted by Mikael Ståldal <mi...@magine.com>.
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 <ga...@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.staldal@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.staldal@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: garydgregory@gmail.com | ggregory@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.staldal@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.
Re: FATAL Unable to register shutdown hook because JVM is shutting down.
Posted by Gary Gregory <ga...@gmail.com>.
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 <mi...@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.staldal@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: garydgregory@gmail.com | ggregory@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