This week's book giveaway is in the Servlets forum.
We're giving away four copies of Murach's Java Servlets and JSP and have Joel Murach on-line!
See this thread for details.
The moose likes Developer Certification (SCJD/OCMJD) and the fly likes Logging in a Shutdown Hook Big Moose Saloon
  Search | Java FAQ | Recent Topics | Flagged Topics | Hot Topics | Zero Replies
Register / Login


Win a copy of Murach's Java Servlets and JSP this week in the Servlets forum!
JavaRanch » Java Forums » Certification » Developer Certification (SCJD/OCMJD)
Bookmark "Logging in a Shutdown Hook" Watch "Logging in a Shutdown Hook" New topic
Author

Logging in a Shutdown Hook

Sean Keane
Ranch Hand

Joined: Nov 03, 2010
Posts: 581

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:



SCJP (1.4 | 5.0), OCJP (6.0), OCMJD
Sean Keane
Ranch Hand

Joined: Nov 03, 2010
Posts: 581

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

Joined: Nov 03, 2010
Posts: 581

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

Joined: Nov 03, 2010
Posts: 581

Has anyone else solved this problem about logging in the shut down hook? Any ideas?
Roel De Nijs
Bartender

Joined: Jul 19, 2004
Posts: 5122
    
  12

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.


SCJA, SCJP (1.4 | 5.0 | 6.0), SCJD
http://www.javaroe.be/
Sean Keane
Ranch Hand

Joined: Nov 03, 2010
Posts: 581

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
Bartender

Joined: Jul 19, 2004
Posts: 5122
    
  12

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

Joined: Nov 03, 2010
Posts: 581

Yep, I stuck a thread in "Java in General". But no bites! One to look into at a later point maybe.
 
wood burning stoves
 
subject: Logging in a Shutdown Hook
 
Similar Threads
The requested resource (/servletTestApp/) is not available
Logger
Java logging API
Logging (java.util.logging)
Logging - entering method