#179 Logfile _creationDate is wrong

Platform_Specific
closed
nobody
5
2014-07-08
2008-08-20
Dave Nay
No

Due to filename "tunneling" on Windows, the creation date of a rotated logfile is not correct.

http://blogs.msdn.com/oldnewthing/archive/2005/07/15/439261.aspx

LogFile_WIN32.cpp contains this attempt at a work-around:

// There seems to be a strange "optimization" in the Windows NTFS
// filesystem that causes it to reuse directory entries of deleted
// files. Example:
// 1. create a file named "test.dat"
//    note the file's creation date
// 2. delete the file "test.dat"
// 3. wait a few seconds
// 4. create a file named "test.dat"
//    the new file will have the same creation
//    date as the old one.
// We work around this bug by taking the file's
// modification date as a reference when the
// file is empty.
if (sizeImpl() == 0)
    _creationDate = File(path).getLastModified();
else
    _creationDate = File(path).created();

However this fails in the case of an application that is stopped and started multiple times within the log rotation period.

For example..

The application is started on the first of the month, and creates a log file with correct creation and modification dates. The application can be stopped and started up until the log rotation period (let's say one day). At the one day point, the log file will be rotated, and a new file created with the same name. Due to Windows "tunnelling", this file will be created with a creation date the same as the old rotated file, and a modification date that is correct. The above excerpt of code accounts for this, and uses the modification date for empty files.

The problem is now if the application writes to the log file, then exits. When the application starts again, it will see a logfile that is not empty, and will grab the creation date instead of the modification date. The creation date however is greater than the rotation period and the file is immediately rotated again. All subsequent starts of the application will cause the logfile to be rotated due to Windows continuing to use the original creation date on the new files.

Discussion

  • Logged In: YES
    user_id=1148207
    Originator: NO

    Well, it seems that no mainstream operating system (with the exception of *BSD, maybe) seems to get file creation dates right. I mean, putting this tunneling thing into the kernel is one of the stupidest things in OS design I have seen for a long time. But it's Windows, so what would you expect...
    So I guess we have to completely change the way log file rotation works. Instead of relying on file creation dates, we should either use a shadow file storing the creation date for a log file, or write the creation date of the log file into the first line of the file. Any comments?

     
  • Dave Nay
    Dave Nay
    2008-08-20

    Logged In: YES
    user_id=31549
    Originator: YES

    I was thinking that FileImpl::createFileImpl() could be modified to "touch" the created and modified dates using the SetFileTime() system call. This is already implemented in FileImpl::setLastModifiedImpl()

     
  • Fixed in 1.3.3/svn trunk.

    This has been fixed in the following way: since there's no reliable and portable way to find out the creation date of a file (Windows has the tunneling "feature", most Unixes don't provide the creation date), the creation/rotation date of the log file is written into the log file as the first line, using a special format:

    Log file created/rotated Thursday, 18 Sep 08 14:04:32 GMT

    This way, unless someone tampers with the logfile, we can always find out correctly when to rotate the file.

     
  • Alex Fabijanic
    Alex Fabijanic
    2008-09-23

    This fix is causing a problem. I'm not quite certain yet what the cause is but I can reproduce it on Windows (didn't try any other platform). When the existing current log file is reopened on application restart, CreateFile call in FileStreamBuf::open returns invalid handle, which causes exception to be thrown.

     
  • Alex Fabijanic
    Alex Fabijanic
    2008-09-23

    This fix is causing a problem. I'm not quite certain yet what the cause is but I can reproduce it on Windows (didn't try any other platform). When the existing current log file is reopened on application restart, CreateFile call in FileStreamBuf::open returns invalid handle, which causes exception to be thrown.

     
  • Alex Fabijanic
    Alex Fabijanic
    2008-09-23

    The problem is that the file is already opened by LogFile and re-opening it fails with access violation (in spite of file being opened in FILE_SHARE_READ mode and re-open atempt is for read-only mode). Unless there is some other way to work around this, the reading/writing of the timestamp should be handled in the LogFile which already owns the opened file handle, not in the strategy. If that's the way to go, I'll volunteer to do it for Windows.

    Additionally, I have discovered a discrepancy between FileWIN32 and File_WIN32U::handleLastErrorImpl switch/case structure. I'm filing a separate bug report on that.

     
  • <conspiracyTherory>There must be some specific department in Redmond whose sole purpose is to make the implementation of interval-based log rotation as inconvenient as possible on Windows.</conspiracyTheory>

     
  • Alex Fabijanic
    Alex Fabijanic
    2008-09-23

    Fixed in SVN trunk, rev. 856

    As for the conspiracy, given the sad state of POSIX platforms regarding the issue, it appears to be more widespread than initially thought.

     
  • Alex Fabijanic
    Alex Fabijanic
    2008-09-23

    Fixed in SVN trunk, rev. 856

    As for the conspiracy, given the sad state of POSIX platforms regarding the issue, it appears to be more widespread than initially thought.

     
  • Alex Fabijanic
    Alex Fabijanic
    2008-09-23

    Fixed in SVN 1.3.3 branch, rev. 858