Details

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:

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.

Christian Grobmeier
added a comment - 20/Apr/11 16:51 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

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).

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.

Christian Grobmeier
added a comment - 23/Apr/11 13:22 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

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) {
.....
.....

Bhumir Sheth
added a comment - 02/May/11 16:18 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

Christian Grobmeier
added a comment - 01/Jun/11 08:50 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

Christian Grobmeier
added a comment - 01/Jun/11 10:07 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

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

Bhumir Sheth
added a comment - 06/Jun/11 15:08 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

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?

Ivan Habunek
added a comment - 06/Jun/11 15:55 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

Christian Grobmeier
added a comment - 08/Jun/11 07:35 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

Bhumir Sheth
added a comment - 10/Jun/11 06:32 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

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().

Ivan Habunek
added a comment - 10/Jun/11 10:11 - 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.

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.

Bhumir Sheth
added a comment - 14/Jun/11 15:06 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

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.

Bhumir Sheth
added a comment - 27/Jun/11 12:08 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

Christian Grobmeier
added a comment - 27/Jun/11 12:13 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