NLog exception handling behavior

classic Classic list List threaded Threaded
1 message Options
Reply | Threaded
Open this post in threaded view
|

NLog exception handling behavior

dhall3000
I am at a loss after having spent an entire day trying to track down a production issue we had the other day. Any help would be greatly appreciated! Also, to protect the privacy of the company I work for I've modified some of the data below.

The issue began because a coder put the following line of code in to production:

Log.Debug("MethodName, Param1 : {1} , Param2 : {2}, Param3: {3}", Param1, Param2, Param3);

This is an obvious no-no and will cause an exception of the array index out of bounds variety. (don’t mean to diss those to whom the problem isn’t obvious. The problem is the curly braces should be valued 0,1 & 2, not 1,2&3). This shouldn't have caused the subsequently observed production issue though because our config file omits the 'throwExceptions' key so the default value of 'false' should be in effect. So the exception should have been swallowed by NLog.

Alas, such was not the case. The exception was thrown, caught higher up the call stack by our application and the exception message and stacktrace dumped to output. Here is one (of many) such exception dumps:

2012-05-11 00:02:00.4613: CompanysApplicationName() - CompanysMethodName() threw an exception.  Exception Message: Index (zero based) must be greater than or equal to zero and less than the size of the argument list. StackTrace:    at System.Text.StringBuilder.AppendFormat(IFormatProvider provider, String format, Object[] args)
   at System.String.Format(IFormatProvider provider, String format, Object[] args)
   at NLog.LogEventInfo.CalcFormattedMessage()
   at NLog.LogEventInfo..ctor(LogLevel level, String loggerName, IFormatProvider formatProvider, String message, Object[] parameters, Exception exception)
   at NLog.Logger.WriteToTargets(LogLevel level, String message, Object[] args)
   at CompanysMethodName() in C:\Systems\Sys1.cs:line 12210
   at CompanysApplicationName()

This caused us to lose control of processing that should have happened subsequent to the Log.Debug statement which forced us to shut down production. Very costly consequences, but that’s beside the point.

Anyway, so we went to repro this problem to gain confidence that we wouldn’t hit this issue again but cannot reproduce this issue. We tried writing a test app using the same Log.Debug statement. What we observed is that no matter the existence or value of ‘throwExceptions’, NLog swallows the exception. Two different test apps were written by two different devs, run on two different dev boxes with this same result. One of these test apps was then moved to the offending production box and run there with the same result.

I then downloaded the NLog source and made a sample project in the NLog solution. My sample program used the same offending Log.Debug statement so I could step through the NLog source. I found that the exception was thrown consistent with the stack trace from the production issue; in NLog.LogEventInfo.CalcFormattedMessage(). Drilling in to the source of CalcFormattedMessage() further, the offending block of code is:

                try
                {
                    this.formattedMessage = string.Format(this.FormatProvider ?? CultureInfo.CurrentCulture, this.Message, this.Parameters);
                }
                catch (Exception exception)
                {
                    this.formattedMessage = this.Message;
                    if (exception.MustBeRethrown())
                    {
                        throw;
                    }

                    InternalLogger.Warn("Error when formatting a message: {0}", exception);
                }

As can be seen from the code, LogManager.ThrowExceptions is never referenced. Contrast this with the following try/catch block that comes from LoggingConfiguration.cs..LoggingConfiguration.InitializeAll():

                try
                {
                    initialize.Initialize(this);
                }
                catch (Exception exception)
                {
                    if (exception.MustBeRethrown())
                    {
                        throw;
                    }

                    if (LogManager.ThrowExceptions)
                    {
                        throw new NLogConfigurationException("Error during initialization of " + initialize, exception);
                    }
                }

Notice how when reading the config file, NLog throws exceptions conditional on the ‘throwExceptions’ value. But in CalcFormattedMessage() above, ‘throwExceptions’ isn’t used.

Given the implementation of CalcFormattedMessage(), the observed behavior in the test apps we wrote is exactly what one would expect. The exception is thrown and handled in that one method, such that from the NLog user’s perspective, the exception is gracefully swallowed.

My questions then are:

1) Am I missing something? From reading just the NLog documentation and sample NLog usage code (that is, prior to examining the NLog source), I expected that setting ‘throwExceptions’ to ‘false’ would cause all exceptions to be swallowed and setting ‘throwExceptions’ to ‘true’ would cause all exceptions to be thrown. On examining the NLog source, however, it appears this behavior is only the case when NLog is ingesting/parsing/processing the config file. But for normal actual logging uses, it appears from examining the NLog source that ‘throwExceptions’ was not intended to have effect.
2) Regardless of the answer to question #1 above, the production issue we experienced remains a mystery. ‘throwExceptions’ was omitted entirely from the config value so the default value of ‘false’ should have been in effect. The exception should have been swallowed by NLog the way it was in our test apps. Can anyone explain why the exceptions were thrown in production?

The production machine is Windows Server 2003 standard x64. The NLog version is 1.0.0.505. The production configuration file is:

<?xml version="1.0" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" autoReload="true" >
    <targets async="true">       
                <target
                name="newArchTeamTempLogger"
                xsi:type="File" layout="${longdate}:
                ${message}" fileName="${basedir}/NewArchTeamTempLogs/${shortdate}.txt"
                />
               
        <target
                name="importantEmailLogger"
                xsi:type="Mail"
                smtpServer="xmail.[companyname].com"
                from="[username]@[companyname].com"
                to="[semi colon separated email list]" subject="Architect ${level}"
                />
               
        <target
                name="statusEmailLogger"
                xsi:type="Mail"
                smtpServer="xmail.[companyname].com"
                from="[username]@[companyname].com"
                to="[semi colon separated email list]" subject="${level}"
                />
               
                <target
                                name="Log"
                                xsi:type="File"
                                fileName="${basedir}/logs/A2C_${shortdate}.txt"
                                layout="${longdate}: ${message}"/>

                <target
                        name="XXLog"
                        xsi:type="File"
                        fileName="[longpathfilename]\YY\${shortdate}.txt"
                        layout="${longdate}: ${message}"
                />               

                <target
                        name="YYLog"
                        xsi:type="File"
                        fileName="[longpathfilename]\XX\${shortdate}.txt"
                        layout="${longdate}: ${message}"
                />               
                               
      <target
                                name="NDrive_Log"
                                xsi:type="File"
                                fileName="[long path file name]\ZZ${shortdate}.txt"
                                layout="${longdate}: ${message}"/>
                               
        <target name="fileActivityAdapter" xsi:type="File" fileName="${basedir}\service_adapter_logs\${shortdate}_${logger}_Log.txt" layout="${longdate} - ${level} - ${message} ${exception:format=ToString}" />
                               
    </targets>

       
    <rules>
        <logger name="ImportantEmailLogger" minlevel="Warn" writeTo="importantEmailLogger" final="true" />
        <logger name="StatusEmailLogger" minlevel="Trace" writeTo="statusEmailLogger" final="true" />               
        <logger name="[company name]" minlevel="Trace" writeTo="fileActivityAdapter"/>                       
        <logger name="NewArchTeamTempLogger" minlevel="Trace" writeTo="newArchTeamTempLogger" final="true" />
               
        <logger name="*" minlevel="Debug" writeTo="Log"/>
        <logger name="*" minlevel="Debug" writeTo="NDrive_Log"/>
        <logger name="*" minlevel="Error" writeTo="ImportantEmailLogger"/>
        <logger name="XX" minlevel="Trace" writeTo="XXLog"/>
        <logger name="YY" minlevel="Trace" writeTo="YYLog"/>
       
    </rules>
</nlog>