Better TypeInitializationException (innerException is also null)

Question

Intro

When an user creates a mistake in the configuration of NLog (like invalid XML), We (NLog) throw a NLogConfigurationException. The exception contains the description what is wrong.

But sometimes this NLogConfigurationException is "eaten" by a System.TypeInitializationException if the first call to NLog is from a static field/property.

Example

E.g. if the user has this program:

using System;
using System.Collections.Generic;
using System.Linq;
using NLog;

namespace TypeInitializationExceptionTest
{
    class Program
    {
        //this throws a NLogConfigurationException because of bad config. (like invalid XML)
        private static Logger logger = LogManager.GetCurrentClassLogger();

        static void Main()
        {
            Console.WriteLine("Press any key");
            Console.ReadLine();
        }
    }
}

and there is a mistake in the config, NLog throws:

throw new NLogConfigurationException("Exception occurred when loading configuration from " + fileName, exception);

But the user will see:

"Copy exception details to the clipboard":

System.TypeInitializationException was unhandled Message: An unhandled exception of type 'System.TypeInitializationException' occurred in mscorlib.dll Additional information: The type initializer for 'TypeInitializationExceptionTest.Program' threw an exception.

So the message is gone!

Questions

1. Why is innerException not visible? (tested in Visual Studio 2013).
2. Can I send more info to the TypeInitializationException? Like a message? We already sending an innerException.
3. Can we use another exception or are there properties on Exception so that more info is reported?
4. Is there another way to give (more) feedback to the user?

Notes

• of course we have no influence on the program written by the user.
• I'm one of the maintainers of NLog.
• Do you like to test it by yourself? Checkout https://github.com/NLog/NLog/tree/TypeInitializationException-tester and start NLog/src/NLog.netfx45.sln

Edit:

please note that I'm the library maintainer, not the user of the library. I cannot change the calling code!

Answer 1

The reason I see is because the Type initialization of Entry point class is failed. Since no type was initialized, so the Type loader has nothing to report about the failed type in TypeInitializationException.

But if you change the Static initializer of logger to other class and then refer that class in Entry method. you'll get the InnerException on TypeInitialization exception.

static class TestClass
{
    public static Logger logger = LogManager.GetCurrentClassLogger();  
}

class Program
{            
    static void Main(string[] args)
    {
        var logger = TestClass.logger;
        Console.WriteLine("Press any key");
        Console.ReadLine();
    }
}

Now you'll get the InnerException because the Entry type was loaded to report the TypeInitializationException.

Hope now you get the idea to keep the Entry point clean and Bootstrap the application from Main() instead of static property of Entry point class.

Update 1

You can also utilize the Lazy<> to avoid the execution of configuration initialization at declaration.

class Program
{
    private static Lazy<Logger> logger = new Lazy<Logger>(() => LogManager.GetCurrentClassLogger());

    static void Main(string[] args)
    {
        //this will throw TypeInitialization with InnerException as a NLogConfigurationException because of bad config. (like invalid XML)
        logger.Value.Info("Test");
        Console.WriteLine("Press any key");
        Console.ReadLine();
    }
}

Alternatively, try Lazy<> in the LogManager for logger instantiation so that the configuration initialization happens when actually the first log statement occurs.

Update 2

I analyzed the source code of NLog and seems like it's already implemented and It make sense. According to the comments on property "NLog should not throw exception unless specified by property LogManager.ThrowExceptions in LogManager.cs".

Fix - In the LogFactory class the private method GetLogger() has the initialization statement which is causing the exception to happen. If you introduce a try catch with the check of property ThrowExceptions then you can prevent the initialization exception.

      if (cacheKey.ConcreteType != null)
            {
                try
                {
                    newLogger.Initialize(cacheKey.Name, this.GetConfigurationForLogger(cacheKey.Name, this.Configuration), this);
                }
                catch (Exception ex)
                {
                    if(ThrowExceptions && ex.MustBeRethrown())
                    throw;
                }
            }

Also it would be great to have these exceptions/errors stored somewhere so that It can be traced why Logger initialization failed because the they were ignored due to ThrowException.

Answer 2

Problem is the static initialization happens when the class is first referenced. In your Program it happens even before the Main() method. So as rule of thumb - avoid any code that can fail in static initialization method. As for your particular problem - use lazy approach instead:

private static Lazy<Logger> logger = 
  new Lazy<Logger>(() => LogManager.GetCurrentClassLogger());

static void Main() {
  logger.Value.Log(...);
}

So the initialization of logger will happen (and possibly fail) when you'll first access the logger - not in some crazy static context.

UPDATE

It is ultimately burden of user of your library to stick to the best practices. So if it were me I'd keep it as it is. There are few options though if you really have to solve it on your end:

1) Don't throw exception - ever - this is valid approach in logging engine, and how log4net works - i.e.

static Logger GetCurrentClassLogger() {
    try {
       var logger = ...; // current implementation
    } catch(Exception e) {
        // let the poor guy now something is wrong - provided he is debugging
        Debug.WriteLine(e);
        // null logger - every single method will do nothing 
        return new NullLogger();
    }
}

2) wrap the lazy approach around the implementation of Logger class (I know your Logger class is much more complex, for sake of this problem let's assume it has just one method Log and it takes string className to construct Logger instance.

class LoggerProxy : Logger {
  private Lazy<Logger> m_Logger;
  // add all arguments you need to construct the logger instance
  public LoggerProxy(string className) {
    m_Logger = new Lazy<Logger>(() => return new Logger(className)); 
  }
  public void Log(string message) {
   m_Logger.Value.Log(message);
  }
}

static Logger GetCurrentClassLogger() {
  var className = GetClassName();
  return new LoggerProxy(className);
}

You'll get rid of this problem (the real initialization will happen while first log method is called and it is backward-compatible approach); only problem is you've added another layer (I don't expect any drastic downgrade of performance, but some logging engines are really into micro-optimization).

Answer 3

I'll just point out the underlying problem you are dealing with here. You are fighting a bug in the debugger, it has a very simple workaround. Use Tools > Options > Debugging > General > tick the "Use Managed Compatibility Mode" checkbox. Also untick Just My Code for the most informative debugging report:

If Just My Code is ticked then the exception report is less informative but still can be drilled down easily by clicking the "View Detail" link.

The option name is unnecessarily cryptic. What it really does is tell Visual Studio to use an older version of the debugging engine. Anybody that uses VS2013 or VS2015 will have this trouble with the new engine, possibly VS2012. Also the basic reason that this issue did not have be addressed in NLog before.

While this is a very good workaround, it is not exactly easy to discover. Nor would programmers particularly like to use the old engine, shiny new features like return value debugging and E+C for 64-bit code are not supported by the old engine. Whether this is a truly a bug, an oversight or a technical limitation in the new engine is hard to guess. This is excessively ugly so don't hesitate to label it "bug", I strongly recommend you take this to connect.microsoft.com. Everybody will be ahead when it gets fixed, I scratched my head over this at least once that I remember. Drilled it down by using Debug > Windows > Exceptions > ticked CLR Exceptions at the time.

A workaround for this very unfortunate behavior is sure to be ugly. You do have to delay raising the exception until program execution has progressed far enough. I don't know your codebase well enough, but delaying parsing the config until the first logging command ought to take care of it. Or store the exception object and throw it on the first log command, probably easier.

Answer 4

I said in an earlier comment that I'm unable to reproduce your issue. Then it occurred to me you were only looking for it in the popup exception dialog, which doesn't display a show details link.

So here's how you can get at the InnerException anyway, because it definitely is there, except Visual Studio doesn't report it for some reason (probably because it's in the entry point type as vendettamit figured out).

So, when you run the tester branch, you get the following dialog:

And it doesn't show the View Details link.

The Copy exception detail to the clipboard isn't particularly helpful either:

System.TypeInitializationException was unhandled
Message: An unhandled exception of type 'System.TypeInitializationException' occurred in mscorlib.dll
Additional information: The type initializer for 'TypeInitializationExceptionTest.Program' threw an exception.

Now, dismiss the dialog with the OK button and head towards the Locals debug window. Here's what you'll see:

See? The InnerException definitely is there, and you found a VS quirk :-)

Answer 5

The only solution I see now is:

move the static initializes (fields) to a static constructor with a try catch

Answer 6

System.TypeInitializationException is always or almost always occurred from not correct initialisation the static members of a class.

You have to check LogManager.GetCurrentClassLogger() via debugger. I'm sure the error is occurred inside that part of code.

//go into LogManager.GetCurrentClassLogger() method
private static Logger logger = LogManager.GetCurrentClassLogger();

Also i suggest you double check your app.config and make sure you haven't included anything wrong.

System.TypeInitializationException is thrown whenever a static constructor throws an exception, or whenever you attempt to access a class where the static constructor threw an exception.

When .NET loads the type, it must prepare all it's static fields before the first time that you use the type. Sometimes, initialization requires running code. It is when that code fails that you get a System.TypeInitializationException.

According the docs

When a class initializer fails to initialize a type, a TypeInitializationException is created and passed a reference to the exception thrown by the type's class initializer. The InnerException property of TypeInitializationException holds the underlying exception. TypeInitializationException uses the HRESULT COR_E_TYPEINITIALIZATION, that has the value 0x80131534. For a list of initial property values for an instance of TypeInitializationException, see the TypeInitializationException constructors.

1) The InnerException is not visible it is very typical for this type of Exception. The version of Visual Studio doesn't matter (ensure that the "Enable the exception assistant" option is checked - Tools> Options>Debugging>General)

2) Usually the TypeInitializationException hides the real exception which can be viewed via InnerException. But the test example below shows how you can populate inner exception info:

public class Test {
    static Test() {
        throw new Exception("InnerExc of TypeInitializationExc");
    }
    static void Main(string[] args) {
    }
}

But sometimes this NLogConfigurationException is "eaten" by an System.TypeInitializationException if the first call to NLog is from a static field/property.

Nothing strange. Someone missed the try catch block somewhere.