[prev in list] [next in list] [prev in thread] [next in thread]
List: log4net-user
Subject: RE: RollingFileAppender generates unexpected filename and/or causes IIS to hang
From: "Iyer, Devan" <devan.iyer () sap ! com>
Date: 2008-09-24 20:09:37
Message-ID: 7B297BEDF7C12E418F6F48DCAC5627EF018DF8A3 () usphle17 ! phl ! sap ! corp
[Download RAW message or body]
I solved this one:
This behaviour is due to RollingFileAppender and it's base class
FileAppender not resetting certain private member variables when an
OpenFile call fails.
RollingFileAppender.OpenFile (filename, bAppend) always does a
GetNextOutputFileName(fileName) before calling the base class OpenFile.
This appends the string value of m_curSizeRollBackups to filename.
FileAppender.OpenFile (filename, bAppend) stores in private member
variables the value of the arguments filename and bAppend and then
attempts to create a LockingStream. This fails with a LockStateException
which is not handled. The correct approach would be to roll back the
values of m_fileName, m_appendToFile , m_curSizeRollBackups and
m_scheduledFilename when the OpenFile call fails. I accomplished this in
my subclass as follows:
protected override void <MyClass>OpenFile(string fileName, bool
append)
{
bool oldAppend = this.AppendToFile;
string oldFileName = this.File;
try
{
base.OpenFile (fileName, append);
}
catch (log4net.Core.LogException ex)
{
LogLog.Debug ("CERollingFileAppender.OpenFile, base.OpenFile
(fileName, append) threw an exception, " + ex.Message);
base.File = oldFileName; // easily set by protected
property access
base.AppendToFile = oldAppend; // easily set by protected
property access
base.ExistingInit (); // no access to
m_curSizeRollBackups and m_scheduledFilename but this will do it.
}
}
Ideally this fix should be in the core RollingFileAppender, FileAppender
implementations with appropriate additional configuration status checks.
________________________________
From: Iyer, Devan
Sent: September 16, 2008 1:09 PM
To: log4net-user@logging.apache.org
Subject: RollingFileAppender generates unexpected filename and/or causes
IIS to hang
We are using rolling file appender in an IIS managed C# application. Our
log4Net deployment is configured with the following options specified in
basic.xml: <appendToFile value="false" /> <countDirection value="0" />
<maximumFileSize value="512KB" /> <maxSizeRollBackups value="100" />
<rollingStyle value="Once" /> <staticLogFileName value="false" />. The
file pattern for our log file name is
"abc_%date{yyyyMMdd_HHmmss}_%processid_.log".
We have observed in our production environment that occasionally
filenames would be created with patterns like
"abc_%date{yyyyMMdd_HHmmss}_%processid_.log.1",
"abc_%date{yyyyMMdd_HHmmss}_%processid_.log.1.2",
"abc_%date{yyyyMMdd_HHmmss}_%processid_.log.1.2.3", etc. We have
observed filenames with the dot+sequential numbers pattern after the
.log to be anything from ".1" to ".220". This is one of two unexpected
behaviours observed.
The second unexpected behaviour seems to a special case of the first
that occasionally causes IIS to hang (100% CPU consumption). An analysis
of several crash dumps taken at the time of the hang indicated that
RollingFileAppender had in memory a filename of the same pattern as
above but with the number of characters [base filename
pattern]+[recurring extension pattern] exceeding 255 characters. It is
very likely that an attempt to create a file by such name on NTFS would
throw exceptions at various levels - managed and native - and hence the
file itself is never created.
To the best of our knowledge, there were no events to trigger the
filename to be rolled. As indicated in the configuration options, we are
using RollingStyle of "Once". (The log file content is minimal at the
time the symptoms occur - total file size is about 2K - and the times of
occurrence are totally non related).
We have been unable to capture the workflow leading up to the symptoms
above due to the high number of users and document types in our
production environment. The permissions on the logging folder are
static. However, we have found a simple workflow in our lab environment,
using permissions, that produce similar symptoms. This workflow is:
- Right click on the logging folder and select "Properties"
- Under the "Security" tab ensure that IIS_WPG group doesn't have write
access to the logging folder.
- Restart IIS
- Launch our application and view a document. Check the logging folder
to make sure that a logfile is not created.
- View a few more documents
- Change the permission on the logging folder and ensure IIS_WPG group
has write access to the folder. DO NOT restart IIS after changing the
permission.
- Launch our application and view another document.
- At this point a logfile with a filename pattern described will be
found in the logging folder.
As mentioned, it is unlikely that permissions are the trigger in our
event but it is likely that the same code is creating these unexpected
patterns irrespective of the trigger.
[Attachment #3 (text/html)]
<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.0 Transitional//EN">
<HTML><HEAD>
<META http-equiv=Content-Type content="text/html; charset=us-ascii">
<META content="MSHTML 6.00.3790.4324" name=GENERATOR></HEAD>
<BODY>
<DIV dir=ltr align=left><FONT face=Arial color=#008000 size=2><SPAN
class=044232819-24092008>I solved this one:<BR><BR>This behaviour is due to
RollingFileAppender and it's base class FileAppender not resetting certain
private member variables when an OpenFile call
fails.</SPAN></FONT></DIV><FONT><SPAN class=044232819-24092008>
<DIV dir=ltr align=left><FONT face=Arial color=#008000 size=2></FONT><BR><FONT
face=Arial color=#008000 size=2>RollingFileAppender.OpenFile <SPAN
class=044232819-24092008>(filename, bAppend) </SPAN>always does a
GetNextOutputFileName(fileName) before calling the base class OpenFile.
This appends the string value of m_curSizeRollBackups to
filename.</FONT></DIV>
<DIV dir=ltr align=left><FONT face=Arial color=#008000
size=2></FONT> </DIV>
<DIV dir=ltr align=left></SPAN></FONT><SPAN class=044232819-24092008><FONT
face=Arial color=#008000 size=2>FileAppender.OpenFile <SPAN
class=044232819-24092008>(filename, bAppend)</SPAN> stores in private
member variables the value of the arguments filename and bAppend and then
attempts to create a LockingStream. This fails with a LockStateException
which is not handled. The correct approach would be to roll back the values of
m_fileName, m_appendToFile , m_curSizeRollBackups and
m_scheduledFilename when the OpenFile call fails. </FONT></SPAN><SPAN
class=044232819-24092008><FONT face=Arial color=#008000 size=2>I accomplished
this in my subclass as follows:</FONT></SPAN></DIV>
<DIV dir=ltr align=left><SPAN class=044232819-24092008><FONT face=Arial
color=#008000 size=2></FONT></SPAN> </DIV>
<DIV dir=ltr align=left><SPAN class=044232819-24092008><FONT face=Arial
color=#008000 size=2> protected override void
<MyClass>OpenFile(string fileName, bool append)<BR>
{<BR></FONT></SPAN><SPAN class=044232819-24092008><FONT face=Arial color=#008000
size=2> bool oldAppend =
this.AppendToFile;<BR> string
oldFileName = this.File;</FONT></SPAN></DIV>
<DIV><FONT face=Arial color=#008000 size=2></FONT> </DIV>
<DIV dir=ltr align=left><SPAN class=044232819-24092008><FONT face=Arial
color=#008000 size=2>
try<BR>
{<BR>
base.OpenFile (fileName, append);<BR>
}<BR> catch (log4net.Core.LogException
ex)<BR>
{<BR>
LogLog.Debug ("CERollingFileAppender.OpenFile, base.OpenFile (fileName, append)
threw an exception, " +
ex.Message);<BR>
base.File = oldFileName; // easily set by protected property
access<BR>
base.AppendToFile = oldAppend; // easily set by protected
property
access<BR>
base.ExistingInit (); // no access to
m_curSizeRollBackups and m_scheduledFilename but this will do
it.<BR> }<BR>
}<BR></FONT></SPAN></DIV>
<DIV><SPAN class=044232819-24092008></SPAN><FONT face=Arial><FONT
color=#008000><FONT
size=2>Ideally this fix should be in the core RollingFileAppender, FileAppender implementation<SPAN \
class=044232819-24092008>s with appropriate additional configuration status
checks.</SPAN></FONT></FONT></FONT></DIV>
<DIV><FONT face=Arial><FONT color=#008000><FONT size=2><SPAN
class=044232819-24092008></SPAN></FONT></FONT></FONT> </DIV>
<DIV class=OutlookMessageHeader lang=en-us dir=ltr align=left>
<HR tabIndex=-1>
<FONT face=Tahoma size=2><B>From:</B> Iyer, Devan <BR><B>Sent:</B> September 16,
2008 1:09 PM<BR><B>To:</B> log4net-user@logging.apache.org<BR><B>Subject:</B>
RollingFileAppender generates unexpected filename and/or causes IIS to
hang<BR></FONT><BR></DIV>
<DIV></DIV>
<DIV>
<DIV><FONT face=Arial size=2><SPAN class=975345217-16092008>We are using rolling
file appender in an IIS managed C# application. Our log4Net deployment is
configured with the following options specified in basic.xml:
</SPAN></FONT><SPAN class=975345217-16092008><FONT face=Arial
size=2><appendToFile value="false" /> <countDirection value="0" />
<maximumFileSize value="512KB" /> <maxSizeRollBackups value="100" />
<rollingStyle value="Once" /> <staticLogFileName value="false" />.
The file pattern for our log file name is
"abc_%date{yyyyMMdd_HHmmss}_%processid_.log".<BR></FONT></DIV></SPAN>
<DIV><FONT face=Arial size=2><SPAN class=975345217-16092008>We have observed in
our production environment that occasionally filenames would be created with
patterns like "abc_%date{yyyyMMdd_HHmmss}_%processid_.log.1",
"abc_%date{yyyyMMdd_HHmmss}_%processid_.log.1.2",
"abc_%date{yyyyMMdd_HHmmss}_%processid_.log.1.2.3", etc. We have observed
filenames with the dot+sequential numbers pattern after the .log to be anything
from ".1" to ".220". This is one of two unexpected behaviour<SPAN
class=067140620-16092008>s</SPAN> observed.</SPAN></FONT></DIV>
<DIV><FONT face=Arial size=2><SPAN
class=975345217-16092008></SPAN></FONT> </DIV>
<DIV><FONT face=Arial><FONT size=2><SPAN class=975345217-16092008>The second
unexpected behaviour seems to a special case of the first that occasionally
causes IIS to hang <SPAN class=067140620-16092008>(</SPAN>100% CPU
consumption<SPAN class=067140620-16092008>)</SPAN>. </SPAN><SPAN
class=975345217-16092008>An analysis of several crash dumps taken at the time of
the hang indicated that RollingFileAppender had in memory a filename of the same
pattern as above but with the number of characters [base filename
pattern]+[recurring extension pattern] exceeding 255 characters. It is very
likely that an attempt to create a file by such name on NTFS would throw
exceptions at various levels - managed and native - and hence the file itself is
never created.</SPAN></FONT></FONT></DIV>
<DIV><FONT face=Arial size=2><SPAN
class=975345217-16092008></SPAN></FONT> </DIV>
<DIV><FONT face=Arial size=2><SPAN class=975345217-16092008>To the best of our
knowledge, there were no events to trigger the filename to be rolled. As
indicated in the configuration options, we are using RollingStyle of "Once".
(The log file content is minimal at the time the symptoms occur - total file
size is about 2K - and the times of occurrence are totally non
related).</SPAN></FONT></DIV>
<DIV><FONT face=Arial size=2><SPAN
class=975345217-16092008></SPAN></FONT> </DIV>
<DIV><FONT face=Arial size=2><SPAN class=975345217-16092008>We have been unable
to capture the workflow leading up to the symptoms above due to the high number
of users and document types in our production environment. The permissions on
the logging folder are static. However, we have found a simple workflow in our
lab environment, using permissions, that produce similar symptoms. This workflow
is:</SPAN></FONT></DIV>
<DIV><FONT face=Arial size=2><SPAN
class=975345217-16092008></SPAN></FONT> </DIV>
<DIV><SPAN class=975345217-16092008>
<DIV dir=ltr align=left><SPAN class=034521823-09092008><FONT face=Arial
color=#0000ff size=2>- Right click on the <SPAN
class=975345217-16092008>l</SPAN>ogging folder and select
"Properties"</FONT></SPAN></DIV>
<DIV dir=ltr align=left><SPAN class=034521823-09092008><FONT face=Arial
color=#0000ff size=2>- Under the "Security" tab ensure that IIS_WPG
group doesn't have write access to the logging folder.</FONT></SPAN></DIV>
<DIV dir=ltr align=left><SPAN class=034521823-09092008><FONT face=Arial
color=#0000ff size=2>- Restart IIS</FONT></SPAN></DIV>
<DIV dir=ltr align=left><SPAN class=034521823-09092008><FONT face=Arial
color=#0000ff size=2>- Launch <SPAN class=975345217-16092008>our
application and view a document</SPAN>. Check the <SPAN
class=975345217-16092008>l</SPAN>ogging folder to make sure
that a <SPAN class=975345217-16092008>logfile </SPAN>is not
created.</FONT></SPAN></DIV>
<DIV dir=ltr align=left><SPAN class=034521823-09092008><FONT color=#0000ff><FONT
face=Arial><FONT size=2>- <SPAN class=975345217-16092008>V</SPAN>iew
a <SPAN class=975345217-16092008>few more </SPAN>document<SPAN
class=975345217-16092008>s</SPAN></FONT></FONT></FONT></SPAN></DIV>
<DIV dir=ltr align=left><SPAN class=034521823-09092008><FONT face=Arial
color=#0000ff size=2>- Change the permission on the <SPAN
class=975345217-16092008>l</SPAN>ogging folder and ensure
IIS_WPG group has write access to the folder. DO NOT restart IIS
after changing the permission.</FONT></SPAN></DIV>
<DIV dir=ltr align=left><SPAN class=034521823-09092008><FONT face=Arial
color=#0000ff size=2>- Launch <SPAN class=975345217-16092008>our
application and view another document</SPAN>.</FONT></SPAN></DIV>
<DIV dir=ltr align=left><SPAN class=034521823-09092008><SPAN
class=975345217-16092008><FONT face=Arial color=#0000ff size=2>- At this point a
logfile with a filename pattern described will be found in the logging
folder.</FONT></SPAN></SPAN></DIV></SPAN></DIV>
<DIV><SPAN class=975345217-16092008><FONT face=Arial size=2></FONT> </DIV>
<DIV><SPAN class=975345217-16092008></SPAN><FONT face=Arial size=2>A<SPAN
class=975345217-16092008>s mentioned, it is unlikely that permissions are the
trigger in our event but it is likely that the same code is creating these
unexpected patterns irrespective of the
trigger.</SPAN><BR></FONT></SPAN></DIV></DIV></BODY></HTML>
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic