Cannot create configuration due to log4net loading failure

[JonasBRasmussen]

I'm trying to upgrade NH from 4.0.0 til 5.1.3. I have installed the proper Nuget packages and have not yet changed any existing code. This is the first (and right now, only) line of NHibernate-related code:

var config = new NHibernate.Cfg.Configuration();

After this, I plan to do different things to complete the configuration. However, the code fails at this line and I am unable to do any configuration.

I cloned the NH repo so I could debug the problem, and I cannot get past the line

properties = Environment.Properties;

in the Reset() method of the NHibernate.Cfg.Configuration class.

All projects in my solution target .NET 4.6.1. A thing to note is that my web projects are SharePoint (2016) projects, and the assemblies are therefore deployed to the GAC. I have confirmed that all the assemblies have been deployed correctly and that there are no versioning issues (only one version of each NHibernate-related assembly is deployed to the GAC). And just to be clear, everything worked without issue on the same setup with NH 4.0.0 (if I uninstall 5.1.3 and go back to 4.0.0, then everything works just fine again).

I have spent the last couple of days on this upgrade and I am getting no closer to a solution. I hope you can help me out.

The complete stack trace for the exception is:

System.TypeInitializationException: The type initializer for 'NHibernate.Cfg.Environment' threw an exception.
---> System.TypeInitializationException: The type initializer for 'NHibernate.NHibernateLogger' threw an exception.
---> NHibernate.InstantiationException: Unable to instantiate: NHibernate.Log4NetLoggerFactoryNHibernate.Log4NetLoggerFactory
---> System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation.
---> System.TypeInitializationException: The type initializer for 'NHibernate.Log4NetLoggerFactory' threw an exception.
---> System.NullReferenceException: Object reference not set to an instance of an object.
   at NHibernate.Log4NetLoggerFactory.GetGetLoggerByNameMethodCall()
   at NHibernate.Log4NetLoggerFactory..cctor()
   --- End of inner exception stack trace ---
   at NHibernate.Log4NetLoggerFactory..ctor()
   --- End of inner exception stack trace ---
   at System.RuntimeTypeHandle.CreateInstance(RuntimeType type, Boolean publicOnly, Boolean noCheck, Boolean& canBeCached, RuntimeMethodHandleInternal& ctor, Boolean& bNeedSecurityCheck)
   at System.RuntimeType.CreateInstanceSlow(Boolean publicOnly, Boolean skipCheckThis, Boolean fillCache, StackCrawlMark& stackMark)
   at System.Activator.CreateInstance(Type type, Boolean nonPublic)
   at System.Activator.CreateInstance(Type type)
   at NHibernate.NHibernateLogger.GetLoggerFactory(String nhibernateLoggerClass)
   --- End of inner exception stack trace ---
   at NHibernate.NHibernateLogger.GetLoggerFactory(String nhibernateLoggerClass)
   at NHibernate.NHibernateLogger..cctor()
   --- End of inner exception stack trace ---
   at NHibernate.NHibernateLogger.For(Type type)
   at NHibernate.Cfg.Environment..cctor()
   --- End of inner exception stack trace ---
   at NHibernate.Cfg.Configuration.Reset()
   at MyCompany.MyProject.CreateNHibernateConfiguration()

[fredericDelaporte]

It seems the application finds a log4net assembly in the application directory and tries to instantiate the logger for it, but then fails as if the assembly was indeed not available (or maybe outdated, classes not having expected methods).

Either remove log4net or ensure it is up-to-date and available in GAC.

[JonasBRasmussen]

Thank you for the fast response!

I do have a log4net assembly in the GAC, version 2.0.8, which I use for my own logging purposes. Does NHibernate expect a different version?

[fredericDelaporte]

That is the version used in NHibernate tests.

Have you check no older version was also in the GAC?
NHibernate loading mechanism for log4net is System.Type.GetType("log4net.LogManager, log4net"), so it may load any log4net version.
This has not changed since 2010, but in 5.0.0 the code searches for LogManager.GetLogger(Assembly, string), while previously it was searching for the overload just taking a string. So maybe this method was not existing in older versions of log4net (but it looks unlikely to me).

Otherwise, NHibernate attempts to load log4net only if it finds it in the app domain base directory or search directory. This has not changed either, but maybe during your test a log4net assembly gets there while in your normal setup it is not there, avoiding having NHibernate attempting to load it.

Corresponding code is:

nhibernate-core/src/NHibernate/Logging.cs

Lines 120 to 129 in f8b1bc4

	// look for log4net.dll
	string baseDir = AppDomain.CurrentDomain.BaseDirectory;
	string relativeSearchPath = AppDomain.CurrentDomain.RelativeSearchPath;
	string binPath = relativeSearchPath == null ? baseDir : Path.Combine(baseDir, relativeSearchPath);
	string log4NetDllPath = binPath == null ? "log4net.dll" : Path.Combine(binPath, "log4net.dll");
	if (File.Exists(log4NetDllPath) || AppDomain.CurrentDomain.GetAssemblies().Any(a => a.GetName().Name == "log4net"))
	{
	nhibernateLoggerClass = typeof(Log4NetLoggerFactory).AssemblyQualifiedName;
	}

If you do not need NHbernate logs, you can also disable them instead: put an empty appSetting named nhibernate-logger in your application .config file.

[JonasBRasmussen]

Yeah, I dug through that code as well. When I attempted to debug I was unable to hit a breakpoint in the code extract from your post. I just can't make it past the call to Environment.Properties.

I only see one log4net folder in the GAC:

I checked both C:\Windows\Microsoft.NET\assembly and C:\Windows\assembly, and this was the only place I found anything with log4net.

Before upgrading, I did use NHibernate logging of SQL statements, and I'd prefer not to lose that. But if I could get async instead, I might be willing to accept it. But I'm not sure it would help me to put the app setting you mentioned in my .config file, since the crash happens on the Reset() call before anything is attempted to be read from a .config file.

[JonasBRasmussen]

I found the problem! Thanks to your work in #1837, which I replicated, built and deployed locally, I was able to get a more reasonable exception message. It was of course something stupid. :)

System.IO.FileNotFoundException: Could not load file or assembly 'Remotion.Linq, Version=2.1.0.0, Culture=neutral, PublicKeyToken=fee00910d6e5f53b' or one of its dependencies. The system cannot find the file specified

My NuGet references to Remotion.Linq and Remotion.Linq.EagerFetching had been updated to 2.2.0, while NHibernate expects 2.1.0. A simple binding redirect fixed the problem.

[fredericDelaporte]

You may have other issues after the binding redirect. Some possible breaking changes in Remotion 2.2.0 are breaking for NHibernate. See #696. If you must use ReLinq 2.2 instead of 2.1, you would have to wait for NHibernate 5.2.

[JonasBRasmussen]

Thanks for the info! What's the planned release date for 5.2?

[JonasBRasmussen]

Just to follow up: I downgraded the Remotion.Linq packages to 2.1 and removed the binding redirects and that seemed to do it. I then switched back to the official NHibernate 5.1.3 release and that gave me the same error as before. So for now I need to use the changes referenced in #1837 to even make it work. Really look forward to an updated official release (could just be 5.1.4).

[fredericDelaporte]

This means the ReLinq reference trouble was another, unrelated trouble.

For checking what is the actual trouble with the logger, may you try again but only with Logging.log4net.cs file changes? The changes in the other file are likely to cause the logger to be indeed disabled in your case.

(Alternatively, you can also fully take #1837 changes but moreover, in your application code, force the logger to use log4net with following instruction: NHibernateLogger.SetLoggersFactory(new Log4NetLoggerFactory());. It will likely fail in your application case to instantiate the factory, due to static constructor failure, but with my changes, with a better error message.)

[JonasBRasmussen]

Indeed, it does not work if I rollback the changes made to Logging.cs. The stack trace this time is a little more telling, since we now get System.IO.FileNotFoundException: Could not load file or assembly 'log4net' or one of its dependencies. The system cannot find the file specified. The full stack trace:

System.TypeInitializationException: The type initializer for 'NHibernate.Cfg.Environment' threw an exception.
---> System.TypeInitializationException: The type initializer for 'NHibernate.NHibernateLogger' threw an exception.
---> NHibernate.InstantiationException: Unable to instantiate: NHibernate.Log4NetLoggerFactoryNHibernate.Log4NetLoggerFactory
---> System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation.
---> System.TypeInitializationException: The type initializer for 'NHibernate.Log4NetLoggerFactory' threw an exception.
---> System.IO.FileNotFoundException: Could not load file or assembly 'log4net' or one of its dependencies. The system cannot find the file specified.
   at System.RuntimeTypeHandle.GetTypeByName(String name, Boolean throwOnError, Boolean ignoreCase, Boolean reflectionOnly, StackCrawlMarkHandle stackMark, IntPtr pPrivHostBinder, Boolean loadTypeFromPartialName, ObjectHandleOnStack type)
   at System.RuntimeTypeHandle.GetTypeByName(String name, Boolean throwOnError, Boolean ignoreCase, Boolean reflectionOnly, StackCrawlMark& stackMark, IntPtr pPrivHostBinder, Boolean loadTypeFromPartialName)
   at System.Type.GetType(String typeName, Boolean throwOnError)
   at NHibernate.Log4NetLoggerFactory..cctor()
   --- End of inner exception stack trace ---
   at NHibernate.Log4NetLoggerFactory..ctor()
   --- End of inner exception stack trace ---
   at System.RuntimeTypeHandle.CreateInstance(RuntimeType type, Boolean publicOnly, Boolean noCheck, Boolean& canBeCached, RuntimeMethodHandleInternal& ctor, Boolean& bNeedSecurityCheck)
   at System.RuntimeType.CreateInstanceSlow(Boolean publicOnly, Boolean skipCheckThis, Boolean fillCache, StackCrawlMark& stackMark)
   at System.Activator.CreateInstance(Type type, Boolean nonPublic)
   at System.Activator.CreateInstance(Type type)
   at NHibernate.NHibernateLogger.GetLoggerFactory(String nhibernateLoggerClass)
   --- End of inner exception stack trace ---
   at NHibernate.NHibernateLogger.GetLoggerFactory(String nhibernateLoggerClass)
   at NHibernate.NHibernateLogger..cctor()
   --- End of inner exception stack trace ---
   at NHibernate.NHibernateLogger.For(Type type)
   at NHibernate.Cfg.Environment..cctor()
   --- End of inner exception stack trace ---
   at NHibernate.Cfg.Configuration.Reset()
   at MyCompany.MyProject.CreateNHibernateConfiguration()

[fredericDelaporte]

I cannot tell more from that. Now you would have to do classical dependency loading failure debugging. (Like using fusion log.)

You can still work around the issue either by using my full changes (which surely cause the logger to be disabled in your case) or by disabling the logger yourself as explained in a previous comment.

But I'm not sure it would help me to put the app setting you mentioned in my .config file, since the crash happens on the Reset() call before anything is attempted to be read from a .config file.

This setting has a special independent handling. It is a .Net appSetting, not a NHibernate setting.

[JonasBRasmussen]

I'll keep looking into it. When I do AppDomain.CurrentDomain.GetAssemblies().Any(a => a.GetName().Name == "log4net") from application code it finds the log4net assembly just fine, so I don't know why it wouldn't work for NH.

I also tried your other suggestion, but I cannot do NHibernateLogger.SetLoggersFactory(new Log4NetLoggerFactory()) since Log4NetLoggerFactory is not assignable to INHibernateLoggerFactory.

[fredericDelaporte]

The failure seems to happen with the code System.Type.GetType("log4net.LogManager, log4net", true). If you put that code in your application, it should fails the same.

The suggestion about setting the logger is not for working around the failure, but for explicitly triggering the failure in case you use my changes. Sorry for the error, it appears the log4net default NHibernate logger still implements the obsolete logging interface, so the code should instead be LoggerProvider.SetLoggersFactory(new Log4NetLoggerFactory());. (That will trigger an obsolete warning.)

[JonasBRasmussen]

System.Type.GetType("log4net.LogManager, log4net", true) line also fails if used in application code. However, it works fine with System.Type.GetType("log4net.LogManager, log4net, Version=2.0.8.0, Culture=neutral, PublicKeyToken=669e0ddf0bb1aa2a", true). I believe a fully qualified assembly name is required because of it being used in the GAC.

[JonasBRasmussen]

How about changing the first statement of the static constructor of Log4NetLoggerFactory to something like

LogManagerType = System.Type.GetType("log4net.LogManager, log4net")
    ?? AppDomain.CurrentDomain.GetAssemblies()
       .FirstOrDefault(x => x.GetName().Name == "log4net")?.GetType("log4net.LogManager", true);

and similarly the first statement of the static constructor of Log4NetLogger to

`var iLogType = System.Type.GetType("log4net.ILog, log4net")
    ?? AppDomain.CurrentDomain.GetAssemblies()
       .FirstOrDefault(x => x.GetName().Name == "log4net")?.GetType("log4net.ILog", true);`

Then also updating GetNhibernateLoggerClass to similarly use

// look for log4net.dll
if (System.Type.GetType("log4net.LogManager, log4net") != null
    || AppDomain.CurrentDomain.GetAssemblies()
       .FirstOrDefault(x => x.GetName().Name == "log4net")?.GetType("log4net.LogManager") != null)
{
    nhibernateLoggerClass = typeof(Log4NetLoggerFactory).AssemblyQualifiedName;
}

This gives me NHibernate logging.

[JonasBRasmussen]

The above does work, but it is also extremely slow. I therefore reverted to the original changes you made in #1837 and now both configuration and logging works without issue for me! I'm not sure why.

[JonasBRasmussen]

It was only slow due to massive amounts of logging being done. I have now adjusted the log level and re-implemented my changes above, and it works without issue.

I'm still not sure why it seemed to work without my changes, but I must just have missed an app pool recycle or something between all be attempts.

[fredericDelaporte]

System.Type.GetType("log4net.LogManager, log4net", true) line also fails if used in application code. However, it works fine with System.Type.GetType("log4net.LogManager, log4net, Version=2.0.8.0, Culture=neutral, PublicKeyToken=669e0ddf0bb1aa2a", true). I believe a fully qualified assembly name is required because of it being used in the GAC.

But looking in the file history, it looks like the same non-full name was used in NHibernate 4. So why that was working with NH4 and no more with NH5?

And also, hard-coding a log4net version into the code would be of course troublesome.

About AppDomain.CurrentDomain.GetAssemblies(), this can work only if the assembly is already loaded into the appdomain. It will not find anything if the assembly is not yet already loaded. In fact that is something like this which would be needed:

nhibernate-core/src/NHibernate/Util/ReflectHelper.cs

Lines 399 to 477 in 97dc207

	public static System.Type TypeFromAssembly(string type, string assembly, bool throwIfError)
	{
	return TypeFromAssembly(new AssemblyQualifiedTypeName(type, assembly), throwIfError);
	}
	/// <summary>
	/// Returns a <see cref="System.Type"/> from an already loaded Assembly or an
	/// Assembly that is loaded with a partial name.
	/// </summary>
	/// <param name="name">An <see cref="AssemblyQualifiedTypeName" />.</param>
	/// <param name="throwOnError"><see langword="true" /> if an exception should be thrown
	/// in case of an error, <see langword="false" /> otherwise.</param>
	/// <returns>
	/// A <see cref="System.Type"/> object that represents the specified type,
	/// or <see langword="null" /> if the type cannot be loaded.
	/// </returns>
	/// <remarks>
	/// Attempts to get a reference to the type from an already loaded assembly. If the
	/// type cannot be found then the assembly is loaded using
	/// <see cref="Assembly.Load(string)" />.
	/// </remarks>
	public static System.Type TypeFromAssembly(AssemblyQualifiedTypeName name, bool throwOnError)
	{
	try
	{
	// Try to get the type from an already loaded assembly
	System.Type type = System.Type.GetType(name.ToString());
	if (type != null)
	{
	return type;
	}
	if (name.Assembly == null)
	{
	// No assembly was specified for the type, so just fail
	const string noAssembly = "Could not load type {0}. Possible cause: no assembly name specified.";
	log.Warn(noAssembly, name);
	if (throwOnError) throw new TypeLoadException(string.Format(noAssembly, name));
	return null;
	}
	//Load type from already loaded assembly
	type = System.Type.GetType(
	name.ToString(),
	an => AppDomain.CurrentDomain.GetAssemblies().FirstOrDefault(a => a.FullName == an.FullName),
	null);
	if (type != null)
	{
	return type;
	}
	Assembly assembly = Assembly.Load(name.Assembly);
	if (assembly == null)
	{
	log.Warn("Could not load type {0}. Possible cause: incorrect assembly name specified.", name);
	return null;
	}
	type = assembly.GetType(name.Type, throwOnError);
	if (type == null)
	{
	log.Warn("Could not load type {0}.", name);
	return null;
	}
	return type;
	}
	catch (Exception e)
	{
	if (log.IsErrorEnabled())
	{
	log.Error(e, "Could not load type {0}.", name);
	}
	if (throwOnError) throw;
	return null;
	}
	}

Unfortunately it cannot be used here, since ReflectHelper depends on the logger. Maybe should we duplicate that code in Log4NetLoggerFactory.

[JonasBRasmussen]

That helper method should indeed do the job. You could refactor it into a new class that both ReflectHelper and Log4NetLoggerFactory can depend on, and then support optional logging. Until a new version is released, I will stick with the version I have working right now.

Thanks for all your help!

[fredericDelaporte]

I have updated the PR.

[fredericDelaporte]

As it now looks like the current handling should not work for a GAC-ed log4net anyway, reopening this.