You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by bu...@apache.org on 2011/05/05 00:30:06 UTC
DO NOT REPLY [Bug 51152] New: RollingFileAppender of
companion/extras 1.1 contains possible race condition
https://issues.apache.org/bugzilla/show_bug.cgi?id=51152
Bug #: 51152
Summary: RollingFileAppender of companion/extras 1.1 contains
possible race condition
Product: Log4j
Version: 1.2
Platform: PC
Status: NEW
Severity: normal
Priority: P2
Component: Other
AssignedTo: log4j-dev@logging.apache.org
ReportedBy: grave@gmx.de
Classification: Unclassified
Hi.
I'm using log4j 1.2.16 with the companion/extras 1.1 package to allow rolling
files based on time (at midnight) and perform gz compression. I also use an
non-blocking AsyncAppender that delegates to SMTPAppender, and FileAppender.
System:
- Quadcore Xeon 2,33 Ghz
- JDK 1.5.0_15
- about 20 custom parallel working threads
- about 800-1000mb log file per day
I encountered a strange behavior on that system, that compression sometimes
isn't performed. The file is renamed correctly though (from mylog.log to
mylog.log.yyyy-MM-dd).
I looked at the asynchronous GZCompressionAction and its superclass
ActionBase. ActionBase calls execute() on the subclass when run() is invoked.
But I found out, that sometimes execute() isn't called due to this code:
public synchronized void run()
{
if(!interrupted)
{
Interrupted is set by the close() method. So looking for an invocation of
close() I came across RollingFileAppender:
http://grepcode.com/file/repo1.maven.org/maven2/log4j/apache-log4j-extras/1.1/org/apache/log4j/rolling/RollingFileAppender.java/
Here's where the race condition seems to happen. Debugging revealed, that in
that special case close() is invoked BEFORE run() is called - interrupting the
compression before it has even started.
Looking at:
...
313: if (rollover.getAsynchronous() != null) {
314: lastRolloverAsyncAction = rollover.getAsynchronous();
315: new Thread(lastRolloverAsyncAction).start();
316: }
...
which is protected by a synchronized block, starts a new Thread
(GZCompressionAction). But start()ing doesn't neccessarily mean that
run() is invoked immediately! So when the synchronized block is left,
lastRolloverAsyncAction is open to be interrupted by a parallel close() call
done by this code earlier:
224: synchronized (this) {
225: //
226: // if a previous async task is still running
227: //}
228: if (lastRolloverAsyncAction != null) {
229: //
230: // block until complete
231: //
232: lastRolloverAsyncAction.close();
...
So at this point, before run() even gets invoked by the JVM, close() has
"interrupted" the GZCompressAction (more specific the ActionBase).
I hope somebody could follow me and can confirm this.
I tried to create a test case but it seems really hard to reproduce this.
As soon as I have one, I'll let you know.
In the meantime, maybe someone can take a look at this.
Thanks.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
[Bug 51152] RollingFileAppender of companion/extras 1.1 contains
possible race condition
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=51152
grobmeier <gr...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
CC| |krisztian.kocsis@optimaster
| |.eu
--- Comment #4 from grobmeier <gr...@gmail.com> ---
*** Bug 53417 has been marked as a duplicate of this bug. ***
--
You are receiving this mail because:
You are on the CC list for the bug.
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
DO NOT REPLY [Bug 51152] RollingFileAppender of companion/extras 1.1
contains possible race condition
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=51152
--- Comment #2 from godson <go...@gmail.com> 2011-06-21 12:55:22 UTC ---
It is not a issue... if 2 instance at the same time involved to create log file
at 0 sec(while putting the cron schedule) Rolling files failure should happen,
so we need to change cron schedule time 0sec is not at all preferred one(while
putting the cron schedule).
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
DO NOT REPLY [Bug 51152] RollingFileAppender of companion/extras 1.1
contains possible race condition
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=51152
--- Comment #1 from godson <go...@gmail.com> 2011-05-09 12:27:34 UTC ---
Hi,
I'm also using log4j 1.2.16 with the companion/extras 1.1 package to allow
rolling
files based on time (at midnight).
my log4j.properties file
#log4j.rootLogger=debug, stdout, file
log4j.rootLogger=off
# Logging to both stdout and a file
log4j.logger.com.cymfony=debug, stdout, file
# Logging to the file only. This should be production configuration
# to avoid overflowing stdout.log file.
#log4j.logger.com.cymfony=info, file
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{HH:mm:ss} [%p] %c{1}| %m%n
# NOTE: DO NOT change this appender' class, it is referenced in code
# to generate unique log files for retriever by inserting the
# provider and client into the file name.
log4j.appender.file=org.apache.log4j.rolling.RollingFileAppender
log4j.appender.file.File=logs/crs.log
log4j.appender.file.RollingPolicy=org.apache.log4j.rolling.TimeBasedRollingPolicy
log4j.appender.file.RollingPolicy.FileNamePattern=logs/crs.log.%d{yyyy-MM-dd}
log4j.appender.file.layout=org.apache.log4j.TTCCLayout
log4j.appender.file.layout.DateFormat=DATE
Run this through VNC Viewer, Rolling files based on midnight is working fine.
If i schedule through cron, Rolling files some time it's not happening.
kindly help me to find the solution.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
DO NOT REPLY [Bug 51152] RollingFileAppender of companion/extras 1.1
contains possible race condition
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=51152
Veit Guna <gr...@gmx.de> changed:
What |Removed |Added
----------------------------------------------------------------------------
Platform|PC |Other
OS/Version| |Linux
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
[Bug 51152] RollingFileAppender of companion/extras 1.1 contains
possible race condition
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=51152
grobmeier <gr...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
CC| |log4j-dev@logging.apache.or
| |g
Component|Other |Companions
--
You are receiving this mail because:
You are on the CC list for the bug.
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org
DO NOT REPLY [Bug 51152] RollingFileAppender of companion/extras 1.1
contains possible race condition
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=51152
--- Comment #3 from Veit Guna <gr...@gmx.de> 2011-08-11 18:19:46 UTC ---
Any news on this?
My workaround is, to clone the GZCompressAction as a custom GZCompressAction
and overwrite the run() method from ActionBase to _always_ call execute, not
checking "interrupted" variable anymore.
That seems to work - but isn't really nice.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org