• Post Reply Bookmark Topic Watch Topic
  • New Topic
programming forums Java Mobile Certification Databases Caching Books Engineering Micro Controllers OS Languages Paradigms IDEs Build Tools Frameworks Application Servers Open Source This Site Careers Other Pie Elite all forums
this forum made possible by our volunteer staff, including ...
Marshals:
  • Campbell Ritchie
  • Jeanne Boyarsky
  • Ron McLeod
  • Paul Clapham
  • Liutauras Vilda
Sheriffs:
  • paul wheaton
  • Rob Spoor
  • Devaka Cooray
Saloon Keepers:
  • Stephan van Hulst
  • Tim Holloway
  • Carey Brown
  • Frits Walraven
  • Tim Moores
Bartenders:
  • Mikalai Zaikin

Logging in a Shutdown Hook

 
Ranch Hand
Posts: 590
Eclipse IDE Chrome Java
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
I have a problem with logging that I was wondering if anyone encountered something similar or can see a solution.

Background:

I have implemented my Data class to use a cache to store the records. I've added a shut down hook to ensure that the contents of the cache are written out to the file when the JVM is shutting down.

Problem:

I create a log statement both before and after executing the method that writes the cache to the file. My problem is that the log statement from before the method call gets written out but the log statement after does not get written out.

I have created this sample program below which displays my problem. The output that I see is:

04-Sep-2011 14:21:42 TestLogging main
INFO: Starting program.
04-Sep-2011 14:21:42 TestLogging main
INFO: Ending program.
Program is doing some work...
04-Sep-2011 14:21:42 TestLogging$1 run
INFO: Shutdown operation : START
Shutdown operation doing work...


I was expecting the last line to be

INFO: Shutdown operation : END



Investigation:

I have confirmed that the log statement after the method call is indeed executed by stepping over with the debugger. Also my application terminates normally.

I added a flush() method to my Log class which flushes out the contents of the appender. This should in theory ensure that all log statements are displayed.

I have also tried changing my ConsoleHandler to a FileHandler just in case there was something strange going on with the ConsoleHandler. This made no difference. The last line was still missing from the log statements that were outputted to the file.

Sample Code:

 
Sean Keane
Ranch Hand
Posts: 590
Eclipse IDE Chrome Java
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
Ah, Google to the rescue! The problem and a solution are available on this thread here.

So it seems that the LogManager registers it's own shutdown hook which means that I can't rely on the logging working in my own shutdown hook.
 
Sean Keane
Ranch Hand
Posts: 590
Eclipse IDE Chrome Java
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
So taking the advice from the thread I previously referenced. If I change my run method to the version below, then all the log statements get printed. I'm guessing though that this is because the shutdown hook for the LogManager has already run before I call Log.init(). My Log.init() registers the ConsoleHandler with the logger. So I am basically just setting this up again after the shutdown hook for the LogManager has removed it.

Since you can't rely on the order which shutdown hooks are called then I don't think this approach is really a good one. There is nothing stopping the shutdown hook for the LogManager executing after my call to Log.init() - in which case I would be back in the same situation again with the log statements not getting output.

The thread that I referenced also mentions using an anonymous logger. I'm not quite sure how this is supposed to work. I put together this example below:

However, this does not solve the problem. My final log statement does not get output.

Does anyone know if this thread is talking about something different when it mentions anonymous loggers? I'd really like to get a nice solution to this.
 
Sean Keane
Ranch Hand
Posts: 590
Eclipse IDE Chrome Java
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
Has anyone else solved this problem about logging in the shut down hook? Any ideas?
 
Sheriff
Posts: 11604
178
Hibernate jQuery Eclipse IDE Spring MySQL Database AngularJS Tomcat Server Chrome Java
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator

Sean Keane wrote:Any ideas?


Don't use logging in the shutdown hook

To log an exception in the shutdown hook I have something like e.printStackTrace(System.err);. Besides that one I don't have any logging at all in the shutdown hook, but I have a few lines in the method that's called by the shutdown hook. Here the same problem could occur of course; LogManager already removed ConsoleHandler before the shutdown hook is activated. I didn't care about some debug messages not getting printed, but the error could be important and that's why I used standard error output to print its stack trace.

 
Sean Keane
Ranch Hand
Posts: 590
Eclipse IDE Chrome Java
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
It's not that important for this assignment. As you say I can just as easily replace my log statements with System.out statements.

However, for future reference, it would be good to know how people handle logging in a shutdown hook. It would be useful to have a record in your log file that the operations you are carrying out in your shutdown hook executed successfully or not.
 
Roel De Nijs
Sheriff
Posts: 11604
178
Hibernate jQuery Eclipse IDE Spring MySQL Database AngularJS Tomcat Server Chrome Java
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
Maybe you could start a thread in a more visited forum, so you could have more responses and more people reading it
 
Sean Keane
Ranch Hand
Posts: 590
Eclipse IDE Chrome Java
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
Yep, I stuck a thread in "Java in General". But no bites! One to look into at a later point maybe.
 
reply
    Bookmark Topic Watch Topic
  • New Topic