Return-Path: Delivered-To: apmail-logging-log4net-user-archive@www.apache.org Received: (qmail 62111 invoked from network); 24 Sep 2008 20:18:09 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.2) by minotaur.apache.org with SMTP; 24 Sep 2008 20:18:09 -0000 Received: (qmail 55029 invoked by uid 500); 24 Sep 2008 20:18:04 -0000 Delivered-To: apmail-logging-log4net-user-archive@logging.apache.org Received: (qmail 54968 invoked by uid 500); 24 Sep 2008 20:18:04 -0000 Mailing-List: contact log4net-user-help@logging.apache.org; run by ezmlm Precedence: bulk list-help: list-unsubscribe: List-Post: Reply-To: "Log4NET User" List-Id: Delivered-To: mailing list log4net-user@logging.apache.org Received: (qmail 54946 invoked by uid 99); 24 Sep 2008 20:18:04 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 24 Sep 2008 13:18:04 -0700 X-ASF-Spam-Status: No, hits=-2.0 required=10.0 tests=HTML_MESSAGE,RCVD_IN_DNSWL_MED,SPF_HELO_PASS,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of devan.iyer@sap.com designates 155.56.68.140 as permitted sender) Received: from [155.56.68.140] (HELO smtpde03.sap-ag.de) (155.56.68.140) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 24 Sep 2008 20:17:05 +0000 Received: from mail.sap.corp by smtpde03.sap-ag.de (26) with ESMTP id m8OKA9VY026785; Wed, 24 Sep 2008 22:10:09 +0200 (MEST) X-MimeOLE: Produced By Microsoft Exchange V6.5 Content-class: urn:content-classes:message MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----_=_NextPart_001_01C91E81.787D1961" Subject: RE: RollingFileAppender generates unexpected filename and/or causes IIS to hang Date: Wed, 24 Sep 2008 16:09:37 -0400 Message-ID: <7B297BEDF7C12E418F6F48DCAC5627EF018DF8A3@usphle17.phl.sap.corp> In-Reply-To: X-MS-Has-Attach: X-MS-TNEF-Correlator: Thread-Topic: RollingFileAppender generates unexpected filename and/or causes IIS to hang Thread-Index: AckYOA2+S9joYBqeSeazEa3Gb1UFEwGQ6euw References: From: "Iyer, Devan" To: , X-OriginalArrivalTime: 24 Sep 2008 20:09:57.0821 (UTC) FILETIME=[846E5ED0:01C91E81] X-Scanner: Virus Scanner virwal05 X-SAP: out X-Virus-Checked: Checked by ClamAV on apache.org This is a multi-part message in MIME format. ------_=_NextPart_001_01C91E81.787D1961 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable 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. =20 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: =20 protected override void OpenFile(string fileName, bool append) { bool oldAppend =3D this.AppendToFile; string oldFileName =3D this.File; =20 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 =3D oldFileName; // easily set by protected property access base.AppendToFile =3D 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. =20 ________________________________ From: Iyer, Devan=20 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: . = 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. =20 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. =20 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). =20 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: =20 - 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. =20 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. ------_=_NextPart_001_01C91E81.787D1961 Content-Type: text/html; charset="us-ascii" Content-Transfer-Encoding: quoted-printable
I solved this one:

This behaviour is = due to=20 RollingFileAppender and it's base class FileAppender not resetting = certain=20 private member variables when an OpenFile call=20 fails.

RollingFileAppender.OpenFile (filename, bAppend) always does a=20 GetNextOutputFileName(fileName) before calling the base class OpenFile.=20 This appends the string value of m_curSizeRollBackups to=20 filename.
 
FileAppender.OpenFile (filename, bAppend) stores in = private=20 member variables the value of the arguments filename and bAppend and = then=20 attempts to create a LockingStream. This fails with a = LockStateException=20 which is not handled. The correct approach would be to roll back the = values of=20 m_fileName, m_appendToFile , m_curSizeRollBackups and=20 m_scheduledFilename when the OpenFile call fails. I = accomplished=20 this in my subclass as follows:
 
    protected override void=20 <MyClass>OpenFile(string fileName, bool = append)
   =20 {
        bool oldAppend =3D=20 this.AppendToFile;
        string=20 oldFileName =3D this.File;
 
       =20 try
       =20 {
           =20 base.OpenFile (fileName, = append);
       =20 }
        catch = (log4net.Core.LogException=20 ex)
       =20 {
           =20 LogLog.Debug ("CERollingFileAppender.OpenFile, base.OpenFile (fileName, = append)=20 threw an exception, " +=20 ex.Message);
         &nb= sp; =20 base.File =3D oldFileName;    // easily set by protected = property=20 access
          &nb= sp;=20 base.AppendToFile =3D oldAppend;    // easily set by = protected=20 property=20 access
          &nb= sp;=20 base.ExistingInit ();    // no access to=20 m_curSizeRollBackups and m_scheduledFilename but this will do=20 it.
        = }
   =20 }
Ideally this fix should be in the&= nbsp;core RollingFileAppender, FileAppender implementation= s with appropriate additional configuration = status=20 checks.
 

From: Iyer, Devan
Sent: = September 16,=20 2008 1:09 PM
To: = log4net-user@logging.apache.org
Subject:=20 RollingFileAppender generates unexpected filename and/or causes IIS to=20 hang

We are = using rolling=20 file appender in an IIS managed C# application. Our log4Net deployment = is=20 configured with the following options specified in basic.xml:=20 <appendToFile value=3D"false" /> <countDirection = value=3D"0" />=20 <maximumFileSize value=3D"512KB" /> <maxSizeRollBackups = value=3D"100" />=20 <rollingStyle value=3D"Once" /> <staticLogFileName = value=3D"false" />.=20 The file pattern for our log file name is=20 "abc_%date{yyyyMMdd_HHmmss}_%processid_.log".
We = have observed in=20 our production environment that occasionally filenames would be created = with=20 patterns like "abc_%date{yyyyMMdd_HHmmss}_%processid_.log.1",=20 "abc_%date{yyyyMMdd_HHmmss}_%processid_.log.1.2",=20 "abc_%date{yyyyMMdd_HHmmss}_%processid_.log.1.2.3", etc. We have = observed=20 filenames with the dot+sequential numbers pattern after the .log to be = anything=20 from ".1" to ".220". This is one of two unexpected behaviours observed.
 
The second=20 unexpected behaviour seems to a special case of the first that = occasionally=20 causes IIS to hang (100% = CPU=20 consumption). An analysis of several crash dumps taken at = the time of=20 the hang indicated that RollingFileAppender had in memory a filename of = the same=20 pattern as above but with the number of characters [base filename=20 pattern]+[recurring extension pattern] exceeding 255 characters. It is = very=20 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=20 never created.
 
To the = best of our=20 knowledge, there were no events to trigger the filename to be = rolled. As=20 indicated in the configuration options, we are using RollingStyle of = "Once".=20 (The log file content is minimal at the time the symptoms occur - total = file=20 size is about 2K - and the times of occurrence are totally non=20 related).
 
We = have been unable=20 to capture the workflow leading up to the symptoms above due to the high = number=20 of users and document types in our production environment. The = permissions on=20 the logging folder are static. However, we have found a simple workflow = in our=20 lab environment, using permissions, that produce similar symptoms. This = workflow=20 is:
 
- Right click on the logging folder and select=20 "Properties"
- Under the "Security" tab = ensure that IIS_WPG=20 group doesn't have write access to the logging = folder.
- Restart IIS
- Launch our=20 application and view a document.  Check the logging folder to make sure=20 that a logfile is not=20 created.
View=20 a few more documents
- Change the permission on the logging folder and ensure=20 IIS_WPG group has write access to the folder.  DO NOT restart = IIS=20 after changing the permission.
- Launch our=20 application and view another document.
- = At this point a=20 logfile with a filename pattern described will be found in the logging=20 folder.
 
As mentioned, it is unlikely that permissions = are the=20 trigger in our event but it is likely that the same code is creating = these=20 unexpected patterns irrespective of the=20 trigger.
------_=_NextPart_001_01C91E81.787D1961--