rebus log4net has wrong date

Question

When I throw an exception in a handler for a message type, then the exception is logged with UTCDate, however this should be the computer date.

The weird thing is that it logs it correctly and then logs in wrong, so multiple log messages are added to the file. This is not needed!

The correct time in the log below is 2014-02-18 14:... and the wrong time is 18-02-2014 13:.... I do not need the log with the wrong time Log:

2014-02-18 14:08:43,616 WARN Rebus 1 worker 1 Rebus.Bus.RebusBus - User exception in Rebus 1 worker 1: System.IO.IOException: Error writing to file ---> System.UnauthorizedAccessException: Access to the path 'X' is denied.
   at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
   at System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShare share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options, String msgPath, Boolean bFromProxy)
   at System.IO.FileStream..ctor(String path, FileMode mode)
   at X.Y(X X, X X, X X) in X:line 538
   --- End of inner exception stack trace ---
   at X.Y(X X, X X, X X) in X:line 546
   at Rebus.Bus.Dispatcher.DispatchToHandler[TMessage](TMessage message, IHandleMessages`1 handler)

18-02-2014 13:08:43:
System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.IO.IOException: Error writing to file ---> System.UnauthorizedAccessException: Access to the path 'X' is denied.
   at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
   at System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShare share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options, String msgPath, Boolean bFromProxy)
   at System.IO.FileStream..ctor(String path, FileMode mode)
   at X.Y(X X, X X, X X) in X:line 538
   --- End of inner exception stack trace ---
   at X.Y(X X, X X, X X) in X:line 546
   at Rebus.Bus.Dispatcher.DispatchToHandler[TMessage](TMessage message, IHandleMessages`1 handler)
   --- End of inner exception stack trace ---
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)
   at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
   at Rebus.Bus.Dispatcher.Dispatch[TMessage](TMessage message)
   --- End of inner exception stack trace ---
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)
   at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
   at System.Reflection.MethodBase.Invoke(Object obj, Object[] parameters)
   at Rebus.Bus.Worker.DoTry()
   at Rebus.Bus.Worker.TryProcessIncomingMessage()
   at Rebus.Bus.Worker.MainLoop()

Log4NetConfiguration:

<log4net>
    <logger name="NHibernate">
      <level value="ERROR" />
    </logger>
    <logger name="NHibernate.SQL">
      <level value="ERROR" />
    </logger>
    <!-- The DebugFileAppender writes all messages to a log file-->
    <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
      <file value="X" />
      <appendToFile value="true" />
      <maximumFileSize value="10000KB" />
      <maxSizeRollBackups value="10" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date %level %thread %logger - %message%newline" />
      </layout>
    </appender>
    <appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
      <mapping>
        <level value="ERROR" />
        <forecolor value="Red" />
      </mapping>
      <mapping>
        <level value="DEBUG" />
        <forecolor value="Yellow" />
      </mapping>
      <mapping>
        <level value="INFO" />
        <forecolor value="White" />
      </mapping>
      <layout type="log4net.Layout.PatternLayout">
        <conversionpattern value="%date [%thread] %logger %-5level - %message%newline" />
      </layout>
    </appender>
    <appender name="EventLogAppender" type="log4net.Appender.EventLogAppender">
      <!--<param name="LogName" value="X" />-->
      <param name="ApplicationName" value="X" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date %newline %type %newline %method %newline %message %newline %exception" />
      </layout>
      <filter type="log4net.Filter.LevelRangeFilter">
        <levelMin value="WARN" />
        <levelMax value="FATAL" />
      </filter>
    </appender>
    <root>
      <!-- add other appenders here and the log messages will be sent to every listed appender -->
      <appender-ref ref="EventLogAppender" />
      <appender-ref ref="RollingFile" />
      <appender-ref ref="ColoredConsoleAppender" />
    </root>
  </log4net>

Rebus logging setup:

var rebusConfigurer = Configure.With(new WindsorContainerAdapter(container))
    .Logging(l => l.Log4Net()).Transport(t => t.UseMsmqAndGetInputQueueNameFromAppConfig())
    .MessageOwnership(o => o.FromRebusConfigurationSection())
    .X(s => s.StoreInSqlServer(() => (SqlConnection)container.Resolve<ISession>().Connection, "X", "X"))
    .SpecifyOrderOfHandlers(s => s.Use(new MyMessageHandlerInspector()));

Exception being caught by Rebus

throw new IOException("Error writing to file", exception);

How do I prevent or configure how rebus logs this? As you can see in the log, some of the rebus logging is ok, and other is not.

Answer 1

The thing is that Rebus keeps track of caught exceptions including their timestamps between retries, which is dnoe by keeping a list of Timed<Exception> instances around - and it used to initialize each with DateTime.UtcNow.

I've changed it in Rebus 0.57.0 though to use DateTime.Now, because I agree with you that it doesn't make sense - or at least it looks pretty weird alongside Log4Net's timestamps :)