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: