Search code examples
.netlog4net-configurationlog4net-appender

How to capture Log4net Appender errors when Log4net Debugging turned off


I am using Log4net. I recently decided to add a trace listener to a file to my configuration, to capture any errors generated by Log4net itself. (The Log4net FAQ includes an example configuration for this.)

(I'm talking about cases when Log4net generates an error message of its own, due to being unable to do its job. I'm not talking about configuring it to log application errors.)

While testing this, I messed around with my Log4net configuration in a test project so as to force Log4net or ADO.Net Appender errors, to verify they were handled correctly by the Trace Listener setup.

What I have found suggests that intrinsic Log4net errors will be written to the trace listener, even if Log4net debugging is turned off. This is what I want.

Here's an example error I generated by tweaking the type name of a Log4net.Layout in the app.config to refer to a non-existent type. This was the only entry in the Trace Listener file, which is what I wanted.

log4net:ERROR Failed to find type [log4net.Layout.RawTimeStampLayoutXX]
System.TypeLoadException: Could not load type [log4net.Layout.RawTimeStampLayoutXX]. Tried assembly [log4net, Version=2.0.8.0, Culture=neutral, PublicKeyToken=669e0ddf0bb1aa2a] and all loaded assemblies
  at log4net.Util.SystemInfo.GetTypeFromString(Assembly relativeAssembly, String typeName, Boolean throwOnError, Boolean ignoreCase)
  at log4net.Util.SystemInfo.GetTypeFromString(String typeName, Boolean throwOnError, Boolean ignoreCase)
  at log4net.Repository.Hierarchy.XmlHierarchyConfigurator.CreateObjectFromXml(XmlElement element, Type defaultTargetType, Type typeConstraint)
log4net:ERROR Failed to create object to set param: layout

But, I also found that if the error is in an external system (such as, in the example below, a SQL Server error), the error will only appear in the trace listener file if Log4net debugging is turned ON. Which means that it's surrounded by a great deal of internal housekeeping information.

log4net:ERROR [AdoNetAppender] ErrorCode: GenericFailure. Exception while writing to database
System.Data.SqlClient.SqlException (0x80131904): Must declare the scalar variable "@log_date".
  at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
  at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
  at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
  at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
  at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption)
  at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest)
  at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
  at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
  at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
  at log4net.Appender.AdoNetAppender.SendBuffer(IDbTransaction dbTran, LoggingEvent[] events)
  at log4net.Appender.AdoNetAppender.SendBuffer(LoggingEvent[] events)
ClientConnectionId:8ddb2758-4adc-495e-af8b-c16e0acc937a
Error Number:137,State:2,Class:15

I don't want to run with debugging turned on all the time, just to catch this kind of error. This app runs something like 70 times a day and generates 25KB of debug trace listener output per run, just from internal housekeeping. I don't want to have to wade through megabytes of noise to find the one signal.

So, my questions:

  1. Is it possible to capture errors that are fatal to an Appender in the trace listener, without having Log4net debugging turned on?
  2. Is this behavior by design?

Solution

  • I found a solution. A nice, elegant one.

    All Appender classes in Log4net have a public property called ErrorHandler. By default, this is set to an instance of a class called OnlyOnceErrorHandler, that will log an error to the Debug feed (if enabled) and then stop reporting errors.

    But you can override this, through configuration:

      <log4net>
        <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
          <file value="Logs\logfile.txt" />
          <rollingStyle value="Date" />
          <datePattern value="yyyyMMdd" />
          <maxSizeRollBackups value="-1" />
          <maximumFileSize value="50GB" />
          <errorHandler type="MyTraceLoggingErrorHandler, MyAssembly" />
    

    The ErrorHandler implements the very simple interface IErrorHandler, and can do whatever you want it to do.

    In my case, I simply had it write the messages and exceptions it received to the TraceListener:

    Trace.WriteLine(message);
    Trace.WriteLine(errorCode);
    Trace.WriteLine(e.Message);
    Trace.WriteLine(e.StackTrace);
    

    And that solved my problem.