Log4php
  1. Log4php
  2. LOG4PHP-138

Permission denied while renaming log file when hundred of users are accessing the application

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 2.0.0
    • Fix Version/s: 2.1.0
    • Component/s: Code
    • Labels:
      None
    • Environment:

      Windows operating system

      Description

      Hi,

      We have developed a web application and integrated with log4php, which is used by hundred of users. When the size of log file exceed the maximum file size, it calls rollOver() function to create back up file for log file and truncate the current log file.

      We faced one error while renaming the file from "filename" to "filename.1". This error is generated when hundred of users are accessing the application at the same time. The error is generated as below:

      PHP Warning: rename(C:\PHP\errors/Test_Module.log,C:\PHP\errors/Test_Module.log.1) [<a href='function.rename'>function.rename</a>]: Permission denied in C:\Inetpub\wwwroot\Test_Application\System\System_Logger\log4php\src\main\php\appenders\LoggerAppenderRollingFile.php on line 140

      Also, back up of log files are not created in sequence when above warning is generated. For example, log file "Test_Module.log" is already exists and rollOver() function is called to create new back up file then it creates "Test_Module.log.4" instead of "Test_Module.log.1".

      Moreover, log file has given all the required permissions and it works fine while appending the logs.

      We would appreciate if you can help us by providing a solution or work-around for resolving this issue.

      Please let me know if more details are required.

      Thank you.

      Best regards,

      Bhumir Sheth

        Activity

        Hide
        Bhumir Sheth added a comment -

        Christian,

        Thank you very much for your prompt response.

        Best regards,

        Bhumir Sheth

        Show
        Bhumir Sheth added a comment - Christian, Thank you very much for your prompt response. Best regards, Bhumir Sheth
        Hide
        Christian Grobmeier added a comment -

        Hello Bhumir,

        we are currently voting on the next release (2.1). It will be out in 2-3 days. Once it is out, it is considered stable.

        2.1 is the only stable version which will help on your critical issues.

        if you need it earlier, this is the code we are voting on:
        http://svn.apache.org/repos/asf/logging/log4php/tags/apache-log4php-2.1.0/

        I think it can be considered stable so far

        Cheers
        Christian

        Show
        Christian Grobmeier added a comment - Hello Bhumir, we are currently voting on the next release (2.1). It will be out in 2-3 days. Once it is out, it is considered stable. 2.1 is the only stable version which will help on your critical issues. if you need it earlier, this is the code we are voting on: http://svn.apache.org/repos/asf/logging/log4php/tags/apache-log4php-2.1.0/ I think it can be considered stable so far Cheers Christian
        Hide
        Bhumir Sheth added a comment -

        Hi Ivan,

        We would like to know that whether log4php v2.1 (revision number 1135098) is stable or beta version. This information will be very helpful to us as this new version has resolved few critical issues that we were facing.

        Also, let us know that other log4php versions 2.2 and 2.3 are stable or beta version. If yes then we can utilize them.

        We would appreciate your help.

        Best regards,

        Bhumir Sheth

        Show
        Bhumir Sheth added a comment - Hi Ivan, We would like to know that whether log4php v2.1 (revision number 1135098) is stable or beta version. This information will be very helpful to us as this new version has resolved few critical issues that we were facing. Also, let us know that other log4php versions 2.2 and 2.3 are stable or beta version. If yes then we can utilize them. We would appreciate your help. Best regards, Bhumir Sheth
        Hide
        Ivan Habunek added a comment -

        Thank you and keep reporting issues.

        Regards,
        Ivan

        Show
        Ivan Habunek added a comment - Thank you and keep reporting issues. Regards, Ivan
        Hide
        Bhumir Sheth added a comment -

        Hi Ivan,

        Thanks for your detailed explanation for issue resolution. I have downloaded latest version of log4php (revision number 1135098) from SVN and tested it on our local server. It seems to be working fine now and issue is no longer duplicated.

        Thank you very much for your help. This has resolved our long pending issue.

        Best Regards,
        Bhumir Sheth

        Show
        Bhumir Sheth added a comment - Hi Ivan, Thanks for your detailed explanation for issue resolution. I have downloaded latest version of log4php (revision number 1135098) from SVN and tested it on our local server. It seems to be working fine now and issue is no longer duplicated. Thank you very much for your help. This has resolved our long pending issue. Best Regards, Bhumir Sheth
        Hide
        Ivan Habunek added a comment - - edited

        I think I understand why this error happens. Let me explain.

        Assuming a rollover is needed, the current rolling file appender does the following:
        1. Lock the file
        2. Write to file
        3. Check file size (decide a rollover is needed)
        4. Close the file (this unlocks the file)
        5. Rename the file to file_1
        6. Create a new file
        7. Resume logging

        Now, the problem with concurrent apps is that another process may be waiting to get a file lock. When the appender reaches step 4 it unlocks the file allowing another concurrent appender to get a lock before it can perform the rollover. Therefore, once it tries to rename the file it fails because the file is locked.

        To solve this, the file must not be unlocked during the rollover process. This can be done like this:
        1. Lock the file
        2. Write to file
        3. Check file size (decide a rollover is needed)
        5. Copy the file to file_1 (instead of rename)
        4. Truncate the file using ftruncate()
        5. Rewind the file pointer using rewind()
        6. Unlock the file
        7. Resume logging

        I have done some testing with multiple loggers started from CLI, and it seems to work as expected.

        Another issue I found is that LoggerAppenderRollingFile::append() first calls the parent::append() and then performs checking of filesize for rollover. This means that the file is locked and then unlocked twice. Once by parent append(), once by the local append().

        I have fixed both these issues in revision #1134244.

        Bhumir, we would appreciate your feedback.

        Show
        Ivan Habunek added a comment - - edited I think I understand why this error happens. Let me explain. Assuming a rollover is needed, the current rolling file appender does the following: 1. Lock the file 2. Write to file 3. Check file size (decide a rollover is needed) 4. Close the file (this unlocks the file) 5. Rename the file to file_1 6. Create a new file 7. Resume logging Now, the problem with concurrent apps is that another process may be waiting to get a file lock. When the appender reaches step 4 it unlocks the file allowing another concurrent appender to get a lock before it can perform the rollover. Therefore, once it tries to rename the file it fails because the file is locked. To solve this, the file must not be unlocked during the rollover process. This can be done like this: 1. Lock the file 2. Write to file 3. Check file size (decide a rollover is needed) 5. Copy the file to file_1 (instead of rename) 4. Truncate the file using ftruncate() 5. Rewind the file pointer using rewind() 6. Unlock the file 7. Resume logging I have done some testing with multiple loggers started from CLI, and it seems to work as expected. Another issue I found is that LoggerAppenderRollingFile::append() first calls the parent::append() and then performs checking of filesize for rollover. This means that the file is locked and then unlocked twice. Once by parent append(), once by the local append(). I have fixed both these issues in revision #1134244. Bhumir, we would appreciate your feedback.
        Hide
        Bhumir Sheth added a comment -

        Hello Ivan and Christian,

        Thank you for update and your efforts.

        I will download the latest files/version of log4php and Php.

        I will verify the issue again and provide you an update by early next week.

        Best regards,

        Bhumir Sheth

        Show
        Bhumir Sheth added a comment - Hello Ivan and Christian, Thank you for update and your efforts. I will download the latest files/version of log4php and Php. I will verify the issue again and provide you an update by early next week. Best regards, Bhumir Sheth
        Hide
        Christian Grobmeier added a comment -

        I just added clearstatcache() as suggested by our friends from PHP.net.
        This should clear the ftell cache.

        Show
        Christian Grobmeier added a comment - I just added clearstatcache() as suggested by our friends from PHP.net. This should clear the ftell cache.
        Hide
        Christian Grobmeier added a comment -

        Hello Bhumir,

        I think Ivan is right - can you try to test your case with the complete version of log4php, not only the files I have mentioned.

        Thanks for you patience - this is a nasty issue.

        Cheers
        Christian

        Show
        Christian Grobmeier added a comment - Hello Bhumir, I think Ivan is right - can you try to test your case with the complete version of log4php, not only the files I have mentioned. Thanks for you patience - this is a nasty issue. Cheers Christian
        Hide
        Ivan Habunek added a comment -

        Hi Bhumir,

        I think that you might be using an older version of log4php than you think. The reasons I think this are:
        1. The mkdir() command in LoggerAppenderFile is located on line 74 in the current revision of the file (r1132551). It used to be on line 73 some time ago (r1059292 and earlier).
        2. You should not be getting the "Strict Standards" warning because the signature of the setFile() function is the same in both LoggerAppenderFile and LoggerAppenderRollingFile classes. This used to be an issue in an older revision. It was fixed in r1059522 if I'm not mistaken.

        Can you please double check that you are using the latest revision of log4php (currently r1132659, but this could increment because we are doing a lot of work currently). Please, do not just download the files that were changed in this fix, but update the whole log4php package using "svn update".

        And of course, as Christian said, do it on your test environment first before applying to production.

        Another thing, your version of PHP is very outdated. 5.2.4 was released in August 2007 - that's 4 years old. Did you by any chance mean 5.3.4?

        Best regards,
        Ivan

        Show
        Ivan Habunek added a comment - Hi Bhumir, I think that you might be using an older version of log4php than you think. The reasons I think this are: 1. The mkdir() command in LoggerAppenderFile is located on line 74 in the current revision of the file (r1132551). It used to be on line 73 some time ago (r1059292 and earlier). 2. You should not be getting the "Strict Standards" warning because the signature of the setFile() function is the same in both LoggerAppenderFile and LoggerAppenderRollingFile classes. This used to be an issue in an older revision. It was fixed in r1059522 if I'm not mistaken. Can you please double check that you are using the latest revision of log4php (currently r1132659, but this could increment because we are doing a lot of work currently). Please, do not just download the files that were changed in this fix, but update the whole log4php package using "svn update". And of course, as Christian said, do it on your test environment first before applying to production. Another thing, your version of PHP is very outdated. 5.2.4 was released in August 2007 - that's 4 years old. Did you by any chance mean 5.3.4? Best regards, Ivan
        Hide
        Bhumir Sheth added a comment -

        Hi Christian,

        Thank you for your update. We have downloaded your updated files from below location:
        https://issues.apache.org/jira/browse/LOG4PHP-138?page=com.atlassian.jira.plugin.ext.subversion%3Asubversion-commits-tabpanel#issue-tabs

        However, we have observed below errors after setting up updated files:

        Strict Standards: Declaration of LoggerAppenderRollingFile::setFile() should be compatible with that of LoggerAppenderFile::setFile() in
        <local env path>\log4php\src\main\php\appenders\LoggerAppenderRollingFile.php on line 49

        Warning: mkdir() [function.mkdir]: Permission denied in <local env path>\log4php\src\main\php\appenders\LoggerAppenderFile.php on line 73

        Also we have observed that we are still able to duplicate the issue. We are using PHP version 5.2.4.

        Please let me know if you need any information.

        Thank you.

        Best regards,

        Bhumir Sheth

        Show
        Bhumir Sheth added a comment - Hi Christian, Thank you for your update. We have downloaded your updated files from below location: https://issues.apache.org/jira/browse/LOG4PHP-138?page=com.atlassian.jira.plugin.ext.subversion%3Asubversion-commits-tabpanel#issue-tabs However, we have observed below errors after setting up updated files: Strict Standards: Declaration of LoggerAppenderRollingFile::setFile() should be compatible with that of LoggerAppenderFile::setFile() in <local env path>\log4php\src\main\php\appenders\LoggerAppenderRollingFile.php on line 49 Warning: mkdir() [function.mkdir] : Permission denied in <local env path>\log4php\src\main\php\appenders\LoggerAppenderFile.php on line 73 Also we have observed that we are still able to duplicate the issue. We are using PHP version 5.2.4. Please let me know if you need any information. Thank you. Best regards, Bhumir Sheth
        Hide
        Christian Grobmeier added a comment -

        Hello Bhumir,

        I have updated the issue. Can you test it with the trunkversion of the code? Two classes (+ 1 Testcase, whichi snot so important for you) are update:

        • LoggerAppenderRollingFile
        • Logger

        I have no chance to test this local - your help is highly appreciated. If you have no time, please let me know. I leave this issue open until I hear from you again or after I hear nothing for a while.

        PLEASE don't test in production if possible
        Cheers,
        Christian

        Show
        Christian Grobmeier added a comment - Hello Bhumir, I have updated the issue. Can you test it with the trunkversion of the code? Two classes (+ 1 Testcase, whichi snot so important for you) are update: LoggerAppenderRollingFile Logger I have no chance to test this local - your help is highly appreciated. If you have no time, please let me know. I leave this issue open until I hear from you again or after I hear nothing for a while. PLEASE don't test in production if possible Cheers, Christian
        Hide
        Christian Grobmeier added a comment -

        Hello Bhumir,

        you are right. Of course the lastest improvment cannot work. After a roll over, all waiting appenders need to see if the file reference has changed. Now they check only the old reference.

        I will try to create a fix now

        Show
        Christian Grobmeier added a comment - Hello Bhumir, you are right. Of course the lastest improvment cannot work. After a roll over, all waiting appenders need to see if the file reference has changed. Now they check only the old reference. I will try to create a fix now
        Hide
        Bhumir Sheth added a comment -

        Hi Christian,

        Thanks for the suggestion.

        We tried by checking the maximum file size after locking the file as
        suggested by you. However, we are still able to duplicate the issue. We have
        modified the function rollOver() to check the maximum file size as below:

        private function rollOver() {

        if(flock($this->fp, LOCK_EX)) {

        if(ftell($this->fp) < $this->getMaximumFileSize())

        { flock($this->fp, LOCK_UN); return; }

        // If maxBackups <= 0, then there is no file renaming to be done.
        if($this->maxBackupIndex > 0) {
        .....
        .....

        Best regards,

        Bhumir Sheth

        Show
        Bhumir Sheth added a comment - Hi Christian, Thanks for the suggestion. We tried by checking the maximum file size after locking the file as suggested by you. However, we are still able to duplicate the issue. We have modified the function rollOver() to check the maximum file size as below: private function rollOver() { if(flock($this->fp, LOCK_EX)) { if(ftell($this->fp) < $this->getMaximumFileSize()) { flock($this->fp, LOCK_UN); return; } // If maxBackups <= 0, then there is no file renaming to be done. if($this->maxBackupIndex > 0) { ..... ..... Best regards, Bhumir Sheth
        Hide
        Christian Grobmeier added a comment -

        Ah yes, I actually expected that. Of course, there are several threads waiting to get lock to roll the file over. After they have it, all threads do a rollover. Of course they must check after they have the lock if the current file needs a roll over.

        if(ftell($this->fp) > $this->getMaxFileSize()) {
        if(flock($this->fp, LOCK_EX)) {
        if(ftell($this->fp) > $this->getMaxFileSize())

        { $this->rollOver(); }

        }
        }

        After the lock, a new check should do the trick.

        Can you try this and let me know ifit works?

        Thanks
        Christian

        Show
        Christian Grobmeier added a comment - Ah yes, I actually expected that. Of course, there are several threads waiting to get lock to roll the file over. After they have it, all threads do a rollover. Of course they must check after they have the lock if the current file needs a roll over. if(ftell($this->fp) > $this->getMaxFileSize()) { if(flock($this->fp, LOCK_EX)) { if(ftell($this->fp) > $this->getMaxFileSize()) { $this->rollOver(); } } } After the lock, a new check should do the trick. Can you try this and let me know ifit works? Thanks Christian
        Hide
        Bhumir Sheth added a comment -

        Hi Christian,

        Thank you for your help.

        We had tried the flock() function within rollOver function and modified as below:

        private function rollOver() {

        if (flock($this->fp, LOCK_EX)) {

        // If maxBackups <= 0, then there is no file renaming to be done.
        if($this->maxBackupIndex > 0) {
        $fileName = $this->getExpandedFileName();

        // Delete the oldest file, to keep Windows happy.
        $file = $fileName . '.' . $this->maxBackupIndex;
        if(is_writable($file))
        unlink($file);
        // Map

        {(maxBackupIndex - 1), ..., 2, 1}

        to

        {maxBackupIndex, ..., 3, 2}

        for($i = $this->maxBackupIndex - 1; $i >= 1; $i--) {
        $file = $fileName . "." . $i;
        if(is_readable($file))

        { $target = $fileName . '.' . ($i + 1); rename($file, $target); }

        }

        // $this->close();

        // Rename fileName to fileName.1
        // $target = $fileName . ".1";
        // $file = $fileName;
        // rename($file, $target);

        copy($fileName, $fileName . ".1");
        }

        ftruncate($this->fp, 0);
        fseek($this->fp, 0);

        flock($this->fp, LOCK_UN);
        fclose($this->fp);

        //unset($this->fp);
        $this->activateOptions();
        $this->setFile($fileName, false);
        }
        }

        By implementing flock() within rollOver() function we were able to avoid the error message and issue of sequence of back up files. However, the above implementation creates another issue. Sometimes it creates back up of log files having small size (i.e. 2KB or 6KB) which is smaller than maximum file size defined (1 MB).

        We are using this application on Windows operating system.

        We would appreciate your further help on this.

        Best regards,

        Bhumir Sheth

        Show
        Bhumir Sheth added a comment - Hi Christian, Thank you for your help. We had tried the flock() function within rollOver function and modified as below: private function rollOver() { if (flock($this->fp, LOCK_EX)) { // If maxBackups <= 0, then there is no file renaming to be done. if($this->maxBackupIndex > 0) { $fileName = $this->getExpandedFileName(); // Delete the oldest file, to keep Windows happy. $file = $fileName . '.' . $this->maxBackupIndex; if(is_writable($file)) unlink($file); // Map {(maxBackupIndex - 1), ..., 2, 1} to {maxBackupIndex, ..., 3, 2} for($i = $this->maxBackupIndex - 1; $i >= 1; $i--) { $file = $fileName . "." . $i; if(is_readable($file)) { $target = $fileName . '.' . ($i + 1); rename($file, $target); } } // $this->close(); // Rename fileName to fileName.1 // $target = $fileName . ".1"; // $file = $fileName; // rename($file, $target); copy($fileName, $fileName . ".1"); } ftruncate($this->fp, 0); fseek($this->fp, 0); flock($this->fp, LOCK_UN); fclose($this->fp); //unset($this->fp); $this->activateOptions(); $this->setFile($fileName, false); } } By implementing flock() within rollOver() function we were able to avoid the error message and issue of sequence of back up files. However, the above implementation creates another issue. Sometimes it creates back up of log files having small size (i.e. 2KB or 6KB) which is smaller than maximum file size defined (1 MB). We are using this application on Windows operating system. We would appreciate your further help on this. Best regards, Bhumir Sheth
        Hide
        Christian Grobmeier added a comment -

        The rollOver function needs a lock before doing its stuff.

        Another process writes to the file (and has the lock) while the seconde process tries to rename.

        For a quick fix, can you try to replace the append method of LoggerAppenderRollingFile with:

        /**

        • @param LoggerLoggingEvent $event
          */
          public function append(LoggerLoggingEvent $event) {
          parent::append($event);
          if(ftell($this->fp) > $this->getMaxFileSize())
          Unknown macro: { if(flock($this->fp, LOCK_EX)) { $this->rollOver(); } }

          }

        This code is untested, I have no env setup currently. Please try this and see if it helps.

        We'll include a patch for the next log4php release if it works for you

        For the sake of completnes - what OS is you code running on? I would like to check if flock is having problems on your OS or not.

        Thanks!
        Christian

        Show
        Christian Grobmeier added a comment - The rollOver function needs a lock before doing its stuff. Another process writes to the file (and has the lock) while the seconde process tries to rename. For a quick fix, can you try to replace the append method of LoggerAppenderRollingFile with: /** @param LoggerLoggingEvent $event */ public function append(LoggerLoggingEvent $event) { parent::append($event); if(ftell($this->fp) > $this->getMaxFileSize()) Unknown macro: { if(flock($this->fp, LOCK_EX)) { $this->rollOver(); } } } This code is untested, I have no env setup currently. Please try this and see if it helps. We'll include a patch for the next log4php release if it works for you For the sake of completnes - what OS is you code running on? I would like to check if flock is having problems on your OS or not. Thanks! Christian

          People

          • Assignee:
            Christian Grobmeier
            Reporter:
            Bhumir Sheth
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development