[LOG4NET-381] IIS worker process hangs while writing to logs

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Invalid
• Affects Version/s: 1.2.9
• Component/s: Appenders
• Environment: Windows 2008 R2, IIS 7
• Assignee: Unassigned
• Reporter: Indra Bhanu
• Created: 06/Jun/13 04:02
• Updated: 06/Jun/13 13:35
• Resolved: 06/Jun/13 13:35

Description

Observed multiple application pools for website and upon analyzing w3wp process dumps of hang worker processors, we found the hang was due to log4net process and below is your detailed observations.

active requests in all the dumps are saying log4net logging

. 0 Id: 478.2c0c Suspend: -1 Teb: 000007ff`fffaa000 Unfrozen
Child-SP RetAddr Call Site
00000000`01f5cd08 000007fe`fd0881cd ntdll!ZwQueryFullAttributesFile+0xa
00000000`01f5cd10 000007fe`f91ae377 KERNELBASE!GetFileAttributesExW+0x9d
00000000`01f5cde0 000007fe`f7d3d038 mscorwks!DoNDirectCall__PatchGetThreadCall+0x7b
00000000`01f5ce80 000007fe`f7d3cd1c mscorlib_ni!DomainNeutralILStubClass.IL_STUB(System.String, Int32, WIN32_FILE_ATTRIBUTE_DATA ByRef)+0x138
00000000`01f5d000 000007fe`f7cc6318 mscorlib_ni!System.IO.File.FillAttributeInfo(System.String, WIN32_FILE_ATTRIBUTE_DATA ByRef, Boolean, Boolean)+0x27c
00000000`01f5d130 000007fe`f7cc9d04 mscorlib_ni!System.IO.File.InternalExists(System.String)+0x48
00000000`01f5d190 000007ff`002c33cc mscorlib_ni!System.IO.File.Exists(System.String)+0xf4
00000000`01f5d210 000007ff`002c31f6 log4net!log4net.Appender.RollingFileAppender.OpenFile(System.String, Boolean)+0x7c
00000000`01f5d290 000007ff`002c30d8 log4net!log4net.Appender.FileAppender.SafeOpenFile(System.String, Boolean)+0x36
00000000`01f5d300 000007ff`002c1b4c log4net!log4net.Appender.FileAppender.ActivateOptions()+0x148
00000000`01f5d370 000007ff`002b946b log4net!log4net.Appender.RollingFileAppender.ActivateOptions()+0x29c
00000000`01f5d400 000007ff`002b8ec2 log4net!log4net.Repository.Hierarchy.XmlHierarchyConfigurator.ParseAppender(System.Xml.XmlElement)+0x4cb
00000000`01f5d4c0 000007ff`002b92df log4net!log4net.Repository.Hierarchy.XmlHierarchyConfigurator.FindAppenderByReference(System.Xml.XmlElement)+0x212
00000000`01f5d540 000007ff`002b8ec2 log4net!log4net.Repository.Hierarchy.XmlHierarchyConfigurator.ParseAppender(System.Xml.XmlElement)+0x33f
00000000`01f5d600 000007ff`002b8345 log4net!log4net.Repository.Hierarchy.XmlHierarchyConfigurator.FindAppenderByReference(System.Xml.XmlElement)+0x212
00000000`01f5d680 000007ff`002c548b log4net!log4net.Repository.Hierarchy.XmlHierarchyConfigurator.ParseChildrenOfLoggerElement(System.Xml.XmlElement, log4net.Repository.Hierarchy.Logger, Boolean)+0x125
00000000`01f5d710 000007ff`002b7d78 log4net!log4net.Repository.Hierarchy.XmlHierarchyConfigurator.ParseLogger(System.Xml.XmlElement)+0x18b
00000000`01f5d790 000007ff`002b78f5 log4net!log4net.Repository.Hierarchy.XmlHierarchyConfigurator.Configure(System.Xml.XmlElement)+0x3b8
00000000`01f5d820 000007ff`002b785a log4net!log4net.Repository.Hierarchy.Hierarchy.XmlRepositoryConfigure(System.Xml.XmlElement)+0x35
00000000`01f5d860 000007ff`002b7668 log4net!log4net.Config.XmlConfigurator.ConfigureFromXml(log4net.Repository.ILoggerRepository, System.Xml.XmlElement)+0x16a
00000000`01f5d8b0 000007ff`002b72ff log4net!log4net.Config.XmlConfigurator.Configure(log4net.Repository.ILoggerRepository, System.IO.Stream)+0x1f8
00000000`01f5d920 000007ff`002b708c log4net!log4net.Config.XmlConfigurator.Configure(log4net.Repository.ILoggerRepository, System.IO.FileInfo)+0x19f
00000000`01f5d9a0 000007ff`002b6c31 log4net!log4net.Config.XmlConfigurator.ConfigureAndWatch(log4net.Repository.ILoggerRepository, System.IO.FileInfo)+0xfc
00000000`01f5da00 000007ff`002b5fb5 Core!Ent.Logging.LogManager.ConfigureAndWatch(System.IO.FileInfo)+0x31
00000000`01f5da60 000007fe`f91aeb52 App_global_asax!ASP.global_asax.Application_Start(System.Object, System.EventArgs)+0xb55

managed callstack says below

0:000> !clrstack
OS Thread Id: 0x2c0c (0)
Child-SP RetAddr Call Site
0000000001f5ce80 000007fef7d3cd1c DomainNeutralILStubClass.IL_STUB(System.String, Int32, WIN32_FILE_ATTRIBUTE_DATA ByRef)
0000000001f5d000 000007fef7cc6318 System.IO.File.FillAttributeInfo(System.String, WIN32_FILE_ATTRIBUTE_DATA ByRef, Boolean, Boolean)
0000000001f5d130 000007fef7cc9d04 System.IO.File.InternalExists(System.String)
0000000001f5d190 000007ff002c33cc System.IO.File.Exists(System.String)
0000000001f5d210 000007ff002c31f6 log4net.Appender.RollingFileAppender.OpenFile(System.String, Boolean)
0000000001f5d290 000007ff002c30d8 log4net.Appender.FileAppender.SafeOpenFile(System.String, Boolean)
0000000001f5d300 000007ff002c1b4c log4net.Appender.FileAppender.ActivateOptions()
0000000001f5d370 000007ff002b946b log4net.Appender.RollingFileAppender.ActivateOptions()
0000000001f5d400 000007ff002b8ec2 log4net.Repository.Hierarchy.XmlHierarchyConfigurator.ParseAppender(System.Xml.XmlElement)
0000000001f5d4c0 000007ff002b92df log4net.Repository.Hierarchy.XmlHierarchyConfigurator.FindAppenderByReference(System.Xml.XmlElement)
0000000001f5d540 000007ff002b8ec2 log4net.Repository.Hierarchy.XmlHierarchyConfigurator.ParseAppender(System.Xml.XmlElement)
0000000001f5d600 000007ff002b8345 log4net.Repository.Hierarchy.XmlHierarchyConfigurator.FindAppenderByReference(System.Xml.XmlElement)
0000000001f5d680 000007ff002c548b log4net.Repository.Hierarchy.XmlHierarchyConfigurator.ParseChildrenOfLoggerElement(System.Xml.XmlElement, log4net.Repository.Hierarchy.Logger, Boolean)
0000000001f5d710 000007ff002b7d78 log4net.Repository.Hierarchy.XmlHierarchyConfigurator.ParseLogger(System.Xml.XmlElement)
0000000001f5d790 000007ff002b78f5 log4net.Repository.Hierarchy.XmlHierarchyConfigurator.Configure(System.Xml.XmlElement)
0000000001f5d820 000007ff002b785a log4net.Repository.Hierarchy.Hierarchy.XmlRepositoryConfigure(System.Xml.XmlElement)
0000000001f5d860 000007ff002b7668 log4net.Config.XmlConfigurator.ConfigureFromXml(log4net.Repository.ILoggerRepository, System.Xml.XmlElement)
0000000001f5d8b0 000007ff002b72ff log4net.Config.XmlConfigurator.Configure(log4net.Repository.ILoggerRepository, System.IO.Stream)
0000000001f5d920 000007ff002b708c log4net.Config.XmlConfigurator.Configure(log4net.Repository.ILoggerRepository, System.IO.FileInfo)
0000000001f5d9a0 000007ff002b6c31 log4net.Config.XmlConfigurator.ConfigureAndWatch(log4net.Repository.ILoggerRepository, System.IO.FileInfo)
0000000001f5da00 000007ff002b5fb5 Ent.Logging.LogManager.ConfigureAndWatch(System.IO.FileInfo)
0000000001f5da60 000007fef91aeb52 ASP.global_asax.Application_Start(System.Object, System.EventArgs)
0000000001f5e3a0 000007fef7d3afa6 System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo, Boolean)
0000000001f5e540 000007fef16d55b3 System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)
0000000001f5e590 000007fef16e432d System.Web.HttpApplication.ProcessSpecialRequest(System.Web.HttpContext, System.Reflection.MethodInfo, Int32, System.Object, System.EventArgs, System.Web.SessionState.HttpSessionState)
0000000001f5e640 000007fef16d4a5d System.Web.HttpApplicationFactory.EnsureAppStartCalledForIntegratedMode(System.Web.HttpContext, System.Web.HttpApplication)
0000000001f5e6f0 000007fef16d5230 System.Web.HttpApplication.RegisterEventSubscriptionsWithIIS(IntPtr, System.Web.HttpContext, System.Reflection.MethodInfo[])
0000000001f5e7a0 000007fef16e47ce System.Web.HttpApplication.InitSpecial(System.Web.HttpApplicationState, System.Reflection.MethodInfo[], IntPtr, System.Web.HttpContext)
0000000001f5e860 000007fef17dd51e System.Web.HttpApplicationFactory.GetSpecialApplicationInstance(IntPtr, System.Web.HttpContext)
0000000001f5e900 000007fef91aeb52 System.Web.Hosting.PipelineRuntime.InitializeApplication(IntPtr)