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 " />
<param name="Footer" value="Ending Program " />
<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 " />
<param name="Footer" value="Ending Program " />
<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 "
/>
</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>
