DO NOT REPLY [Bug 21499] New: - DailyRollingFileAppender not rolled (if necessary) on shutdown

[bu...@apache.org]

DO NOT REPLY TO THIS EMAIL, BUT PLEASE POST YOUR BUG 
RELATED COMMENTS THROUGH THE WEB INTERFACE AVAILABLE AT
<http://nagoya.apache.org/bugzilla/show_bug.cgi?id=21499>.
ANY REPLY MADE TO THIS MESSAGE WILL NOT BE COLLECTED AND 
INSERTED IN THE BUG DATABASE.

http://nagoya.apache.org/bugzilla/show_bug.cgi?id=21499

DailyRollingFileAppender not rolled (if necessary) on shutdown

           Summary: DailyRollingFileAppender not rolled (if necessary) on
                    shutdown
           Product: Log4j
           Version: unspecified
          Platform: PC
        OS/Version: Windows NT/2K
            Status: NEW
          Severity: Normal
          Priority: Other
         Component: Appender
        AssignedTo: log4j-dev@jakarta.apache.org
        ReportedBy: John.Bize@ExceptionalSoftware.com


This is related to Rug Report #18965.

We are using log4j in a J2EE environment, and are having problems with
the DailyRollingFileAppender, especialy (but not exclusively) with the 
HTML Layout.

When we redeploy an application to the running J2EE server (We are using 
BEA WebLogic.), the application reinitializes and with the first message, 
log4j attempts the rollOver().

When the application didn't have a ServletContextListener, the renameTo() in
rollOver() would fail.  I presume this is just a BillWare problem, I don't
think its a problem on Unix.  (I don't know what Posix says, if anything.)

So we implemented a ServletContextListener to call LogManager.shutdown(),
and the errors "Failed to rename ..." went away.  And so did rolling for
our HTML layout appender.

I don't know why our HTML layout was hit the hardest, but the Pattern and
XML layout appenders often rolled when the HTML wouldn't.  Somehow 
activateOptions() received different values from file.lastModified() for
the different appenders.  (For testing, I hung these three appenders onto
the rootLogger.)

I turned on log4j debug logging, but got nothing useful, beyond the 
observation, that it wasn't even trying to roll the appender, so I sprinkled 
a few more LogLogs in there, and this is what I discovered:

When log4j initializes for a DailyRollingFileAppender, activateOptions() 
resets:
  scheduledFilename = fileName+sdf.format(new Date(file.lastModified()));

The file is modified (closed) when the ServletContextListener.contextDestroyed()
calls LogManager.shutdown(), the current time is used to set the 
scheduledFilename (on the restart), and when the scheduled rollOver() occurs, 
it senses that the new file is the same as the previous, and silently returns.

We have a nightly build that runs 5 minutes after midnight, and after all the
tests pass, it deploy's the new EAR to the server.  Since no one is in pressing
buttons that early in the morning, the redeployment causes the first logging to 
occur within the scheduled roll interval.  The rollOver() detects that the 
scheduledFilename has not changed, and so no roll occurs.

My current workaround is to log a fatal message to the root logger in the 
ServletContextListener.contextDestroyed() method before calling 
LogManager.shutdown(), but that probably won't work for folks that are using 
non appending loggers.  I'm also concerned with the fact that I may be 
performing lots of I/O on an application that is trying to shut down.

I believe the LogManager.shutdown() should roll each DailyRollingFileAppender
before it is closed; at least optionally.  I experimented by adding a 
setNow() method to DailyRollingFileAppender, and calling setNow() and 
rollOver() on any DailyRollingFileAppender found in 
Category.closeNestedAppenders().  It seemed to work, but there may be other 
implications. (e.g:  Should an empty file roll?)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@jakarta.apache.org
For additional commands, e-mail: log4j-dev-help@jakarta.apache.org