RollingFileAppender error when one thread rolls (date) the current log file and another thread tries to append a new log entry at the same time
heed <joakim.heed <at> cogmed.com>
2011-12-29 16:24:14 GMT
Hi!
I've noticed an error (seen it a few times on different servers) that I
think occurs exactly when one thread rolls (date, per day) the current log
file and another thread tries to append a new log entry at the same time.
I've looked really quick at the source code for this particular case and I
can't really see how these two events are protected from each other, but it
could be that I just didn't find the lock or protection mechanism that is
used to secure the roll from simultaneously writes/appends. If possible it
would be interesting to get a short explanation of how this mechanism works.
We're using version 1.2.10 of log4net.
Our setup is to use an Apache web server on Linux together with mod_mono and
mono to run a asp.net/C# based web service. Only one instance of the mono
process should be running so there should only be access from one process
but there will be log access from several threads.
(Apache uses piped logging and also rolls its log files at midnight)
Please let me know if you need any other information.
/Joakim
I'll attach the error from the Apache log that receives the stack trace from
mono:
**
ERROR:../../mono/io-layer/handles-private.h:362:_wapi_handle_share_release:
assertion failed: (info->handle_refs > 0)
Stacktrace:
at (wrapper managed-to-native) System.IO.MonoIO.Close
(intptr,System.IO.MonoIOError&) <0x00050>
at (wrapper managed-to-native) System.IO.MonoIO.Close
(intptr,System.IO.MonoIOError&) <0x00050>
at System.IO.FileStream.Dispose (bool) <0x000b7>
at System.IO.Stream.Close () <0x0001b>
at log4net.Appender.FileAppender/ExclusiveLock.CloseFile () <0x00055>
at log4net.Appender.FileAppender/LockingStream.Close () <0x0001a>
at System.IO.StreamWriter.Dispose (bool) <0x000c8>
at System.IO.StreamWriter.Close () <0x0001b>
at log4net.Util.TextWriterAdapter.Close () <0x0001d>
at log4net.Util.QuietTextWriter.Close () <0x00017>
at log4net.Appender.TextWriterAppender.CloseWriter () <0x00045>
at log4net.Appender.FileAppender.CloseWriter () <0x00047>
at log4net.Appender.TextWriterAppender.WriteFooterAndCloseWriter ()
<0x00025>
at log4net.Appender.FileAppender.CloseFile () <0x00016>
at log4net.Appender.RollingFileAppender.RollOverTime (bool) <0x0020f>
at log4net.Appender.RollingFileAppender.AdjustFileBeforeAppend ()
<0x0013f>
at log4net.Appender.RollingFileAppender.Append (log4net.Core.LoggingEvent)
<0x0001b>
at log4net.Appender.AppenderSkeleton.DoAppend (log4net.Core.LoggingEvent)
<0x0014a>
at log4net.Util.AppenderAttachedImpl.AppendLoopOnAppenders
(log4net.Core.LoggingEvent) <0x0012c>
at log4net.Repository.Hierarchy.Logger.CallAppenders
(log4net.Core.LoggingEvent) <0x000b7>
at log4net.Repository.Hierarchy.Logger.ForcedLog
(System.Type,log4net.Core.Level,object,System.Exception) <0x00086>
at log4net.Repository.Hierarchy.Logger.Log
(System.Type,log4net.Core.Level,object,System.Exception) <0x00074>
at log4net.Core.LogImpl.Debug (object) <0x00040>
at FluorineFx.AmfRequestHandler.ProcessRequest
(System.Web.HttpApplication) <0x00173>
at FluorineFx.FluorineGateway.ProcessRequest (System.Web.HttpApplication)
<0x00048>
at FluorineFx.FluorineGateway.ApplicationPreRequestHandlerExecute
(object,System.EventArgs) <0x0004b>
at System.Web.HttpApplication/<RunHooks>c__Iterator1.MoveNext () <0x0034e>
at System.Web.HttpApplication/<Pipeline>c__Iterator2.MoveNext () <0x03072>
at System.Web.HttpApplication.Tick () <0x00040>
at System.Web.HttpApplication.Start (object) <0x001cb>
at System.Web.HttpApplication.System.Web.IHttpHandler.ProcessRequest
(System.Web.HttpContext) <0x0003b>
at System.Web.HttpRuntime.Process (System.Web.HttpWorkerRequest) <0x0023d>
at System.Web.HttpRuntime.RealProcessRequest (object) <0x0005f>
at System.Web.HttpRuntime.ProcessRequest (System.Web.HttpWorkerRequest)
<0x0004f>
at Mono.WebServer.MonoWorkerRequest.ProcessRequest () <0x000af>
at Mono.WebServer.BaseApplicationHost.ProcessRequest
(Mono.WebServer.MonoWorkerRequest) <0x00083>
at Mono.WebServer.ModMonoApplicationHost.ProcessRequest
(int,string,string,string,string,string,int,string,int,string,string[],string[],object)
<0x0043f>
at (wrapper remoting-invoke-with-check)
Mono.WebServer.ModMonoApplicationHost.ProcessRequest
(int,string,string,string,string,string,int,string,int,string,string[],string[],object)
<0x001ef>
at (wrapper xdomain-dispatch)
Mono.WebServer.ModMonoApplicationHost.ProcessRequest
(object,byte[]&,byte[]&,int,string,string,string,string,string,int,string,int,string,string[],string[])
<0x004e3>
at (wrapper xdomain-invoke)
Mono.WebServer.ModMonoApplicationHost.ProcessRequest
(int,string,string,string,string,string,int,string,int,string,string[],string[],object)
<0x00252>
at (wrapper remoting-invoke-with-check)
Mono.WebServer.ModMonoApplicationHost.ProcessRequest
(int,string,string,string,string,string,int,string,int,string,string[],string[],object)
<0x00127>
at Mono.WebServer.ModMonoWorker.InnerRun (object) <0x0067f>
at Mono.WebServer.ModMonoWorker.Run (object) <0x0002f>
at (wrapper runtime-invoke) object.runtime_invoke_void__this___object
(object,intptr,intptr,intptr) <0x0005c>
Native stacktrace:
/usr/bin/mono() [0x487ad6]
/lib/libpthread.so.0(+0xef60) [0x7f2929b95f60]
/lib/libc.so.6(gsignal+0x35) [0x7f29295d6165]
/lib/libc.so.6(abort+0x180) [0x7f29295d8f70]
/lib/libglib-2.0.so.0(g_assertion_message+0x131) [0x7f292a2125d1]
/lib/libglib-2.0.so.0(g_test_timer_start+0) [0x7f292a212b50]
/usr/bin/mono() [0x59d649]
/usr/bin/mono() [0x597658]
/usr/bin/mono() [0x597774]
/usr/bin/mono() [0x5095fc]
[0x40a0dba0]
Debug info from gdb:
=================================================================
Got a SIGABRT while executing native code. This usually indicates
a fatal error in the mono runtime or one of the native libraries
used by your application.
=================================================================
** (/usr/lib/mono/2.0/mod-mono-server2.exe:26967): WARNING **:
process_set_termination_details: error looking up process handle 0x403
[Tue Dec 20 00:00:13 2011] [error] (70014)End of file found: read_data
failed
[Tue Dec 20 00:00:13 2011] [error] Command stream corrupted, last command
was 1
[Tue Dec 20 00:00:13 2011] [error] (104)Connection reset by peer: read_data
failed
[Tue Dec 20 00:00:13 2011] [error] Command stream corrupted, last command
was 1
And this is the appender from the log4net.config file:
<appender name="RollingLogFileAppender"
type="log4net.Appender.RollingFileAppender">
<file value="Logs/fluorine.log" />
<appendToFile value="true" />
<rollingStyle value="Date" />
<datePattern value="yyyyMMdd" />
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%date [%thread] %-5level %logger -
%message%newline" />
</layout>
</appender>
--
--
View this message in context: http://old.nabble.com/RollingFileAppender-error-when-one-thread-rolls-%28date%29-the-current-log-file-and-another-thread-tries-to-append-a-new-log-entry-at-the-same-time-tp33050908p33050908.html
Sent from the Log4net - Dev mailing list archive at Nabble.com.
RSS Feed