Uncaught IndexOutOfRangeException in log4net 1.2.9 Beta

[Ian Dykes <ia...@esendex.com>]

Hi,

We're in the process of updating our logging from version 1.2.0 beta 8 (DLL version 1.2.0.30714) to the 1.2.9 beta and are experiencing an uncaught error when our test system is placed under load.

We're running version 1.1 of the MS .Net framework on Windows 2003 Server, and have also seen this on Windows XP Pro SP2.

We have a server process which catches all exceptions and logs them as errors.  The stack trace we are getting is as follows:

ERROR[slf5s.PRIORITY]
(null)[slf5s.NDC]
2132[slf5s.THREAD]
com.esendex.ems.ScheduledSubmissionServer[slf5s.CATEGORY]
com.esendex.common.statusservice.Status.LogError(:0)[slf5s.LOCATION]
Error calling ProcessMessages[slf5s.MESSAGE]

System.IndexOutOfRangeException: Probable I/O race condition detected while copying memory.  The I/O package is not thread safe by default.  In multithreaded applications, a stream must be accessed in a thread-safe way, such as a thread-safe wrapper returned by TextReader's or TextWriter's Synchronized methods.  This also applies to classes like StreamWriter and StreamReader.

Server stack trace: 
   at System.Buffer.InternalBlockCopy(Array src, Int32 srcOffset, Array dst, Int32 dstOffset, Int32 count)
   at System.IO.StreamWriter.Write(Char[] buffer, Int32 index, Int32 count)
   at System.IO.TextWriter.WriteLine(String value)
   at System.IO.SyncTextWriter.WriteLine(String value)
   at log4net.Util.LogLog.Error(String message, Exception exception)
   at log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders(LoggingEvent loggingEvent)
   at log4net.Repository.Hierarchy.Logger.CallAppenders(LoggingEvent loggingEvent)
   at log4net.Repository.Hierarchy.Logger.ForcedLog(Type callerStackBoundaryDeclaringType, Level level, Object message, Exception exception)
   at log4net.Repository.Hierarchy.Logger.Log(Type callerStackBoundaryDeclaringType, Level level, Object message, Exception exception)
   at log4net.Core.LogImpl.Debug(Object message)
   at com.esendex.ems.datamappers.ScheduledSubmissionBatchDM.SelectBatchForDateTime(DateTime date)
   at com.esendex.ems.implementation.facades.ScheduledSubmissionFacadeImpl.GetBatchesToSubmit(DateTime date)
   at com.esendex.ems.facades.ScheduledSubmissionFacade.GetBatchesToSubmit(DateTime date)
   at System.Runtime.Remoting.Messaging.StackBuilderSink.PrivateProcessMessage(MethodBase mb, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs)
   at System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(IMessage msg, Int32 methodPtr, Boolean fExecuteInContext)

Exception rethrown at [0]: 
   at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
   at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
   at com.esendex.ems.facades.ScheduledSubmissionFacade.GetBatchesToSubmit(DateTime date)
   at com.esendex.ems.ScheduledSubmissionServer.ProcessMessages()
   at com.esendex.ems.ScheduledSubmissionServer.Run()

The server process is logging to one file, while the Debug line (the line "at log4net.Core.LogImpl.Debug(Object message)" in the stack trace) is meant to log to a different file (which other threads will be logging to).  The server code is in a DLL that is late loaded from the GAC by a host EXE program.  This is logging correctly as the above trace is from that log.  The server DLL then calls through to a COM+ component.  The COM+ component late loads an implementation assembly from the GAC.  It is the logging within this implementation DLL that is throwing the exception.

I'm logging to a log4net.Appender.RollingFileAppender with the following configuration:

<appender name="EsendexRollingFileAppender" type="log4net.Appender.RollingFileAppender">
	<param name="File" value="${log.dir.unix}/${namespace}.txt" />
	<param name="AppendToFile" value="true" />
	<param name="MaxSizeRollBackups" value="10" />
	<param name="MaximumFileSize" value="5000000" />
	<param name="RollingStyle" value="Size" />
	<param name="StaticLogFileName" value="true" />
	<layout type="log4net.Layout.PatternLayout">
		<param name="Header" value="---Start of session---\r\n" />
		<param name="Footer" value="---End of session---\r\n" />
		<param name="ConversionPattern" value="[slf5s.start]%d{DATE}[slf5s.DATE]%n%p[slf5s.PRIORITY]%n%x[slf5s.NDC]%n%t[slf5s.THREAD]%n%c[slf5s.CATEGORY]%n%l[slf5s.LOCATION]%n%m[slf5s.MESSAGE]%n%n" />
	</layout>
</appender>

(${log.dir.unix} and ${namespace} are other variables within the config file)

I've had a look around the known bugs with this version and haven't found a resolution to this.  We are not experiencing this problem with the older version 1.2.0 either.

Is there anything we can do to stop this exception being thrown?

Apologies if this is a known problem with a simple resolution, but I've been looking for a solution all day and haven't found anything.

Regards
Ian Dykes
 
-
 
Software Developer
Esendex Ltd
49 Stoney Street
Nottingham NG1 1LX
 
http://www.esendex.com
 
Tel: +44 (0) 115 959 7962
Fax: +44 (0) 115 959 7966
 
Esendex voted as one of O2's "50 To Watch In Mobile".  Read the full story at http://www.realbusiness.co.uk/mobile