Hi Ceki / all,
Since then I've done abit more investigation and found a few odd things
which support the theory that there is more than 1 thread writing
to the same log file thus causing our log file to get corrupted and have
missing entries.
I noticed that:
* a thread dump via Weblogic 10.3 is showing that when we deploy our app, there
are 12 AsyncAppender
threads that are active in just 1 weblogic server JVM (threads look like the
below):
"Dispatcher-Thread-37" waiting for lock java.util.arrayl...@1f608cc
WAITING
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:485)
org.apache.log4j.AsyncAppender$Dispatcher.run(AsyncAppender.java:540)
java.lang.Thread.run(Thread.java:619)
* there are also 2 unix file descriptors open on each of the log files that are
getting corrupted.
All the file descriptors come from the 1 java process for the Weblogic server
jvm above
(Again supports the 2 threads writing to the same physical file theory).
I'm planning to debug our app locally to see what's creating the extra
AsyncAppender threads.
Is someone able to tell me how many AsyncAppender threads we should expect to
get spawned
given our log4j.xml config file. I've attached this to the email as a text file.
I'm thinking there should be 6 AsyncAppender threads since we define 6
AsyncAppenders.
Is that right?
Thanks,
Lesley
-----Original Message-----
From: Ceki Gulcu [mailto:[email protected]]
Sent: Thursday, 11 June 2009 5:57 PM
To: Log4J Users List
Subject: Re: log4j v1.2.14 compatible with Java 1.6?
Hello Lesley,
Thank you for the test case.
Indeed, multiple FileAppender instances located in the same JVM and writing to
the same file is a source of error. Just use a single FileAppender instance per
file target.
AsyncAppender uses references to appenders. It does not create them on its own.
So, in principle, using AsyncAppender should not be a problem.
Lesley Tay wrote:
> Hi Ceki,
>
> We actually did a bit more investigation into that same possibility
> and found that if you have a test class similar to the one below:
>
> import java.io.File;
> import java.io.FileWriter;
>
>
>
> public class FileTest {
> public static void main(String args[]) throws Exception {
>
> File file1 = new File("test.file");
> FileWriter writer1 = new FileWriter(file1);
> for (int i = 0 ; i < 20 ; i++) {
> writer1.write("Step 1 \n");
> }
> writer1.flush();
> FileWriter writer2 = new FileWriter(file1);
> for (int i = 0 ; i < 10 ; i++) {
> writer2.write("Step 2 \n");
> }
> writer2.flush();
> writer2.close();
> for (int i = 0 ; i < 20 ; i++) {
> writer1.write("Step 3 \n");
> }
> writer1.flush();
> writer1.close();
> }
> }
>
> We see null characters in the log. Seems to suggest perhaps we either
> have 2 threads writing to the file as you suggested, or two logical files
> open on the same physical file. When the second file is open (writer2) the
> phisical file is filled with null characters up to current end of file1. Then
> writer2 starts writing from the beginnig (overwritting some of the nulls with
> new information) and writer1 continues to appending after what it belives is
> the end of the file.
> This is quite odd especially considering that we use AsyncAppenders (which
> open the files).
>
>
> Regards,
> Lesley
>
--
Ceki Gülcü
Logback: The reliable, generic, fast and flexible logging framework for Java.
http://logback.qos.ch
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
NOTICE
This e-mail and any attachments are confidential and may contain copyright
material of Macquarie Group Limited or third parties. If you are not the
intended recipient of this email you should not read, print, re-transmit, store
or act in reliance on this e-mail or any attachments, and should destroy all
copies of them. Macquarie Group Limited does not guarantee the integrity of any
emails or any attached files. The views or opinions expressed are the author's
own and may not reflect the views or opinions of Macquarie Group Limited.
<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j='http://jakarta.apache.org/log4j/'>
<appender name="FILE" class="org.apache.log4j.DailyRollingFileAppender">
<param name="File" value="${name}-${env}__HOSTNAME_.log"/>
<param name="Append" value="true"/>
<!-- Rollover at midnight each day -->
<param name="DatePattern" value="'.'yyyy-MM-dd"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern"
value="%d{ISO8601}\t%-5p\t(%t)\t{%x}\t[%c{1}]\t%m%n" />
</layout>
</appender>
<appender name="AUDIT_FILE"
class="org.apache.log4j.DailyRollingFileAppender">
<param name="File" value="${name}-${env}-audit__HOSTNAME_.log"/>
<param name="Append" value="true"/>
<!-- Rollover each month -->
<param name="DatePattern" value="'.'yyyy-MMM"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern"
value="%d{ISO8601}\t%-5p\t(%t)\t{%x}\t[%c{1}]\t%m%n" />
</layout>
</appender>
<appender name="USER_LOGGING"
class="org.apache.log4j.DailyRollingFileAppender">
<param name="File" value="${name}-${env}-users__HOSTNAME_.log"/>
<param name="Append" value="true"/>
<!-- Rollover at midnight each day -->
<param name="DatePattern" value="'.'yyyy-MM-dd"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ISO8601}\t%m%n" />
</layout>
</appender>
<appender name="USAGE_LOGGING"
class="org.apache.log4j.DailyRollingFileAppender">
<param name="File" value="${name}-${env}-usage__HOSTNAME_.log"/>
<param name="Append" value="true"/>
<!-- Rollover at midnight each day -->
<param name="DatePattern" value="'.'yyyy-MM-dd"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ISO8601}\t%m%n" />
</layout>
</appender>
<appender name="RECOVERY" class="org.apache.log4j.DailyRollingFileAppender">
<param name="File" value="${name}-${env}-recovery__HOSTNAME_.log"/>
<param name="Append" value="true"/>
<!-- Rollover each month -->
<param name="DatePattern" value="'.'yyyy-MMM"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern"
value="%d{ISO8601}\t%-5p\t(%t)\t{%x}\t[%c{1}]\t%m%n" />
</layout>
</appender>
<appender name="BLAH_LOGGING"
class="org.apache.log4j.DailyRollingFileAppender">
<param name="File" value="${name}-${env}-blah__HOSTNAME_.log"/>
<param name="Append" value="true"/>
<!-- Rollover each month -->
<param name="DatePattern" value="'.'yyyy-MMM"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern"
value="%d{ISO8601}\t%-5p\t(%t)\t{%x}\t[%c{1}]\t%m%n" />
</layout>
</appender>
<appender name="MAIL" class="org.apache.log4j.net.SMTPAppender">
<param name="Threshold" value="ERROR"/>
<param name="SMTPHost" value="smtphost"/>
<param name="To" value="[email protected]"/>
<param name="From" value="[email protected]"/>
<param name="Subject" value="Error Message"/>
<param name="BufferSize" value="1"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%p -
%d{ISO8601}%nCategory: %c%nNDC: %x%nThread: %t%n%nMessage:%n%m%n"/>
</layout>
</appender>
<appender name="NULL" class="org.apache.log4j.varia.NullAppender"/>
<appender name="ASYNC" class="org.apache.log4j.AsyncAppender">
<appender-ref ref="MAIL"/>
<appender-ref ref="FILE"/>
</appender>
<appender name="AUDIT_ASYNC" class="org.apache.log4j.AsyncAppender">
<appender-ref ref="AUDIT_FILE"/>
</appender>
<appender name="USER_LOGGING_ASYNC" class="org.apache.log4j.AsyncAppender">
<appender-ref ref="USER_LOGGING"/>
</appender>
<appender name="RECOVERY_ASYNC" class="org.apache.log4j.AsyncAppender">
<appender-ref ref="RECOVERY"/>
</appender>
<appender name="BLAH_ASYNC" class="org.apache.log4j.AsyncAppender">
<appender-ref ref="BLAH_LOGGING"/>
</appender>
<appender name="USAGE_LOGGING_ASYNC" class="org.apache.log4j.AsyncAppender">
<appender-ref ref="USAGE_LOGGING"/>
</appender>
<!-- ================ -->
<!-- Loggers -->
<!-- ================ -->
<logger name="com.SystemEvent.Audit">
<level value="info"/>
<appender-ref ref="AUDIT_ASYNC"/>
</logger>
<logger name="com.SystemEvent.Event1" additivity="false">
<level value="info"/>
<appender-ref ref="BLAH_ASYNC"/>
</logger>
<logger name="com.SystemEvent.Event2" additivity="false">
<level value="info"/>
<appender-ref ref="RECOVERY_ASYNC"/>
</logger>
<logger name="com.SystemEvent.Event3" additivity="false">
<level value="info"/>
<appender-ref ref="RECOVERY_ASYNC"/>
</logger>
<logger name="com.SystemEvent.Event4" additivity="false">
<level value="info"/>
<appender-ref ref="RECOVERY_ASYNC"/>
</logger>
<!-- otherwise we'll drown in messages -->
<logger name="org.apache.commons">
<level value="WARN"/>
</logger>
<!-- Spring logs way too much -->
<logger name="org.springframework">
<level value="error" />
</logger>
<!-- Hibernate logs too much -->
<logger name="org.hibernate">
<level value="error" />
</logger>
<logger name="user.logging.host.logger" additivity="false">
<level value="info" />
<appender-ref ref="USER_LOGGING_ASYNC"/>
</logger>
<logger name="usage.logger" additivity="false">
<level value="info" />
<appender-ref ref="USAGE_LOGGING_ASYNC"/>
</logger>
<!-- ======================= -->
<!-- Setup the Root logger -->
<!-- ======================= -->
<root>
<level value="INFO"/>
<appender-ref ref="ASYNC"/>
</root>
</log4j:configuration>
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
