logging-log4net-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Dominik Psenner <dpsen...@gmail.com>
Subject Re: IIS Deadlocks happening all the sudden after years of running with no issues
Date Mon, 22 May 2017 08:35:35 GMT
Hi Jim,

please don't expect a sensible response within hours, especially with 
such a complex problem. :-) At first sight, if it did run for over two 
years and suddenly keeps crashing on a daily basis it is very unlikely 
that something that was not modified is the actual culprit. Did any 
modifications happen lately that you are aware of?

Please note that IIS has some interesting default behavior, it would for 
instance start a new instance of a site before the old site is 
destroyed. This means that multiple instances of the same site use the 
same configuration and are therefore going to log and roll into the same 
files. This is well known [1] [2] and has been raised as an issue 
several times on this list. The symptoms you see sound very much like 
that, but note that this is just a guess. Please note that it is known 
that an application can also cause log4net to deadlock [3]. Further 
there is also this issue [4].

I hope this gives you enough information to dig deeper. Let us know what 
the actual root cause was and how you solved it. We may be able to 
condense documentation that helps future readers.

Cheers,
Dominik

[1] 
https://www.google.it/search?q=log4net+iis+deadlock&oq=log4net+iis+deadlock
[2] http://hectorcorrea.com/blog/log4net-thread-safe-but-not-process-safe/17
[3] https://issues.apache.org/jira/browse/LOG4NET-298
[4] https://issues.apache.org/jira/browse/LOG4NET-178

On 2017-05-20 21:26, Jim Scott wrote:
> Is this list still active? Would this be better to post to the dev list?
>
> On May 19, 2017, at 3:45 PM, Jim Scott <jscott@infoconex.com 
> <mailto:jscott@infoconex.com>> wrote:
>
>> We have a webservice that has been running on Windows 2008R2 since 
>> Nov 2015 and has not had any issues until just a week or so ago. The 
>> webservice becomes unresponsive and after installing some debug tools 
>> I can see that we have a deadlock issue.
>> Here is some details of the last dump. Note we are running the 
>> project under .NET 4 and have .NET 2 dependencies in the project that 
>> depend on the .NET 2 1.2.11.0 version of log4net. I can see also on 
>> the stack trace that we had a few exceptions happen and I assume the 
>> blocking thread was attempting to roll our Exceptions.log file 
>> because the create time on the file was from yesterday. At the bottom 
>> of the email is a copy of our logging configuration which we wire up 
>> during Application_Start.
>> We thought it might have originally been related to permissions as 
>> someone had deleted the exception.log and recreated it and it was 
>> owned by them but we fixed that last night and we had another crash 
>> this morning. I am stumped since no code has changed on this box and 
>> nothing unusual about the type of activity. Maybe something in a .NET 
>> patch changed behavior?
>> Any assistance would be appreciated.
>> Thanks
>> Jim
>> Thread that appears to be blocking everything
>> Entry point 	*clr!Thread::intermediateThreadProc*
>> Create time 	*5/19/2017 1:05:32 PM*
>> Time spent in user mode 	*0 Days 00:10:06.359*
>> Time spent in kernel mode 	*0 Days 00:02:51.203*
>>
>>
>>
>> This thread is trying to acquire a System.Threading.ReaderWriterLock 
>> for *reading*
>>
>> *The thread has evidence of _.net exceptions_ on the stack. Check the 
>> Previous .NET Exceptions Report (Exceptions in all .NET Thread 
>> Stacks) to view more details of the associated exception *
>>
>> *.NET Call Stack*
>>
>>
>> [[HelperMethodFrame_1OBJ] (System.Array.Copy)] 
>> System.Array.Copy(System.Array, Int32, System.Array, Int32, Int32, 
>> Boolean)
>> mscorlib_ni!System.Array.Copy(System.Array, System.Array, Int32)+3e
>> mscorlib_ni!System.Security.Permissions.FileIOPermission.AddPathList(System.Security.Permissions.FileIOPermissionAccess,

>> System.Security.AccessControl.AccessControlActions, System.String[], 
>> Boolean, Boolean, Boolean)+5a
>> mscorlib_ni!System.Security.Permissions.FileIOPermission..ctor(System.Security.Permissions.FileIOPermissionAccess,

>> System.String[], Boolean, Boolean)+2a
>> mscorlib_ni!System.IO.Path.GetFullPath(System.String)+5c
>> mscorlib_ni!System.IO.Path.GetDirectoryName(System.String)+a2
>> log4net.Appender.RollingFileAppender.CombinePath(System.String, 
>> System.String)+38
>> log4net.Appender.RollingFileAppender.RollOverTime(Boolean)+16c
>> log4net.Appender.RollingFileAppender.AdjustFileBeforeAppend()+d3
>> log4net.Appender.RollingFileAppender.Append(log4net.Core.LoggingEvent)+13 
>>
>> log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)+f0
>> log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent)+a0

>>
>> log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent)+82 
>>
>> log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type, 
>> log4net.Core.Level, System.Object, System.Exception)+4a
>> log4net.Repository.Hierarchy.Logger.Log(System.Type, 
>> log4net.Core.Level, System.Object, System.Exception)+64
>> log4net.Core.LogImpl.ErrorFormat(System.String, System.Object[])+6a
>>
>>
>> Example thread blocked
>>
>>
>>       Thread 36 - System ID 7332
>>
>> Entry point 	*clr!Thread::intermediateThreadProc*
>> Create time 	*5/19/2017 1:07:12 PM*
>> Time spent in user mode 	*0 Days 00:00:00.421*
>> Time spent in kernel mode 	*0 Days 00:00:00.109*
>>
>>
>>
>> This thread is waiting to enter a .NET Lock
>>
>> *The thread has evidence of _.net exceptions_ on the stack. Check the 
>> Previous .NET Exceptions Report (Exceptions in all .NET Thread 
>> Stacks) to view more details of the associated exception *
>>
>> *.NET Call Stack*
>>
>>
>> [[GCFrame]]
>> [[HelperMethodFrame_1OBJ] (System.Threading.Monitor.Enter)] 
>> System.Threading.Monitor.Enter(System.Object)
>> log4net.Appender.AppenderSkeleton.DoAppend(log4net.Core.LoggingEvent)+2b
>> log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(log4net.Core.LoggingEvent)+a0

>>
>> log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent)+82 
>>
>> log4net.Repository.Hierarchy.Logger.ForcedLog(System.Type, 
>> log4net.Core.Level, System.Object, System.Exception)+4a
>> log4net.Repository.Hierarchy.Logger.Log(System.Type, 
>> log4net.Core.Level, System.Object, System.Exception)+64
>> log4net.Core.LogImpl.InfoFormat(System.String, System.Object[])+6a
>> Configuration file
>> <?xml version="1.0" encoding="utf-8" ?>
>> <log4net>
>>     <appender name="WebsiteLogger" 
>> type="log4net.Appender.RollingFileAppender">
>>         <param name="File" value="C:\logs\WebLogging.log" />
>>        <param name="AppendToFile" value="true" />
>>         <param name="RollingStyle" value="Composite" />
>>         <param name="MaximumFileSize" value="10MB" />
>>         <param name="CountDirection" value="0" />
>>         <param name="StaticLogFileName" value="true" />
>>         <param name="PreserveLogFileNameExtension" value="true" />
>>         <param name="DatePattern" value=".yyyy-MM-dd" />
>>         <param name="MaxSizeRollBackups" value="40" />
>>         <layout type="log4net.Layout.PatternLayout">
>>             <param name="Header" value="Date Time    Level    
>> ThreadId Class    RemoteIP    SessionId Message&#13;&#10;" />
>>             <param name="Footer" value="Ending Program&#13;&#10;" />
>>             <param name="ConversionPattern" value="%d %-5p 
>> %-30logger{1} %-17property{ip} %-12property{sid}  %m%n%exception" />
>>         </layout>
>>     </appender>
>>     <appender name="ExceptionLogger" 
>> type="log4net.Appender.RollingFileAppender">
>>         <param name="File" value="C:\logs\Exceptions.log" />
>>         <param name="AppendToFile" value="true" />
>>         <param name="RollingStyle" value="Composite" />
>>         <param name="MaximumFileSize" value="10MB" />
>>         <param name="CountDirection" value="0" />
>>         <param name="StaticLogFileName" value="true" />
>>         <param name="PreserveLogFileNameExtension" value="true" />
>>         <param name="DatePattern" value=".yyyy-MM-dd" />
>>         <param name="MaxSizeRollBackups" value="40" />
>>         <!-- <lockingModel 
>> type="log4net.Appender.FileAppender+MinimalLock" /> -->
>>         <layout type="log4net.Layout.PatternLayout">
>>             <param name="Header" value="Date Time    Level    
>> ThreadId Class    RemoteIP    SessionId Message&#13;&#10;" />
>>             <param name="Footer" value="Ending Program&#13;&#10;" />
>>             <param name="ConversionPattern" value="%d %-5p %-30c 
>> %-17property{ip} %-12property{sid}  %m%n%exception" />
>>         </layout>
>>         <filter type="log4net.Filter.LevelRangeFilter">
>>             <param name="LevelMin" value="Error" />
>>         </filter>
>>     </appender>
>>     <appender name="UsageWriter" 
>> type="log4net.Appender.RollingFileAppender">
>>         <param name="File" value="C:\logs\Usage.csv" />
>>         <param name="AppendToFile" value="true" />
>>         <param name="RollingStyle" value="Composite" />
>>         <param name="MaximumFileSize" value="10MB" />
>>         <param name="CountDirection" value="0" />
>>         <param name="StaticLogFileName" value="true" />
>>         <param name="PreserveLogFileNameExtension" value="true" />
>>         <param name="DatePattern" value=".yyyy-MM-dd" />
>>         <param name="MaxSizeRollBackups" value="40" />
>>         <layout type="log4net.Layout.PatternLayout">
>>             <param name="ConversionPattern" value="%d{yyyy-MM-dd 
>> HH:mm:ss.fff},%property{ip},%property{sid},%m%n" />
>>             <param name="Header" 
>> value="Date,IPAddress,SessionId,Username,MethodName,ExecutionTime,Extra&#13;&#10;"

>> />
>>         </layout>
>>         <filter type="log4net.Filter.LoggerMatchFilter">
>>             <param name="LoggerToMatch" 
>> value="AccountManagementWebservice.UsageWriter" />
>>             <param name="AcceptOnMatch" value="true" />
>>         </filter>
>>         <filter type="log4net.Filter.DenyAllFilter" />
>>     </appender>
>>     <appender name="AdoNetAppender" 
>> type="log4net.Appender.AdoNetAppender">
>>         <bufferSize value="1" />
>>         <useTransactions value="false" />
>>         <connectionType value="System.Data.SqlClient.SqlConnection, 
>> System.Data, Version=1.0.3300.0, Culture=neutral, 
>> PublicKeyToken=b77a5c561934e089" />
>>         <connectionString value="data source=server;initial 
>> catalog=db;Enlist=false;User ID=user;Password=password" />
>>         <commandText value="INSERT INTO Log4Net 
>> ([Date],[Host],[Application],[Thread],[Level],[Logger],[Message]) 
>> VALUES (@log_date, @host, @application, @thread, @log_level, @logger, 
>> @message)" />
>>         <parameter>
>>             <parameterName value="@log_date" />
>>             <dbType value="DateTime" />
>>             <layout type="log4net.Layout.RawTimeStampLayout" />
>>         </parameter>
>>         <parameter>
>>             <parameterName value="@host" />
>>             <dbType value="String" />
>>             <size value="255" />
>>             <layout type="log4net.Layout.PatternLayout">
>> <conversionPattern value="%property{host}" />
>>             </layout>
>>         </parameter>
>>         <parameter>
>>             <parameterName value="@application" />
>>             <dbType value="String" />
>>             <size value="255" />
>>             <layout type="log4net.Layout.PatternLayout">
>> <conversionPattern value="%property{application}" />
>>             </layout>
>>         </parameter>
>>         <parameter>
>>             <parameterName value="@thread" />
>>             <dbType value="String" />
>>             <size value="255" />
>>             <layout type="log4net.Layout.PatternLayout">
>> <conversionPattern value="%thread" />
>>             </layout>
>>         </parameter>
>>         <parameter>
>>             <parameterName value="@log_level" />
>>             <dbType value="String" />
>>             <size value="50" />
>>             <layout type="log4net.Layout.PatternLayout">
>> <conversionPattern value="%level" />
>>             </layout>
>>         </parameter>
>>         <parameter>
>>             <parameterName value="@logger" />
>>             <dbType value="String" />
>>             <size value="255" />
>>             <layout type="log4net.Layout.PatternLayout">
>> <conversionPattern value="%logger" />
>>             </layout>
>>         </parameter>
>>         <parameter>
>>             <parameterName value="@message" />
>>             <dbType value="String" />
>>             <size value="4000" />
>>             <layout type="log4net.Layout.PatternLayout">
>> <conversionPattern value="%message" />
>>             </layout>
>>         </parameter>
>>         <filter type="log4net.Filter.LevelRangeFilter">
>>             <param name="LevelMin" value="Error" />
>>         </filter>
>>     </appender>
>>     <root>
>>         <level value="DEBUG" />
>>         <appender-ref ref="WebsiteLogger" />
>>         <appender-ref ref="ExceptionLogger" />
>>         <appender-ref ref="AdoNetAppender" />
>>         <appender-ref ref="UsageWriter" />
>>     </root>
>> </log4net>
>>


Mime
View raw message