While working on a new set of services, we noticed that our logging was not occurring as expected. We had just wired in our core logging implementation that uses Log4Net. Worse, our services were starting up and then crashing – in the development environment only.
After a bit of debugging I found that the problem was that the log4net assembly could not be loaded. What?! There it sits as expected in the bin directory.But IISExpress said “no way, I can’t load it.” (I’m sure it said something like that) :-)
What was odd was that I was able to put in some debugging code and could manually load a type from the assembly, so something is seriously amiss here. Fusion Log Viewer confirms that something is not quite right with the loading of the assembly:
*** Assembly Binder Log Entry (6/1/2014 @ 9:03:05 AM) ***
The operation failed.
Bind result: hr = 0x80070002. The system cannot find the file specified.
Assembly manager loaded from: C:\Windows\Microsoft.NET\Framework\v4.0.30319\clr.dll
Running under executable C:\Program Files (x86)\IIS Express\iisexpress.exe
--- A detailed error log follows.
=== Pre-bind state information ===
LOG: DisplayName = log4net, Version=1.2.12.0, Culture=neutral, PublicKeyToken=669e0ddf0bb1aa2a
(Fully-specified)
LOG: Appbase = file:///C:/Program Files (x86)/IIS Express/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = iisexpress.exe
Calling assembly : (Unknown).
===
LOG: This bind starts in default load context.
LOG: No application configuration file found.
LOG: Using host configuration file: D:\SkyDrive\IISExpress\config\aspnet.config
LOG: Using machine configuration file from C:\Windows\Microsoft.NET\Framework\v4.0.30319\config\machine.config.
LOG: Post-policy reference: log4net, Version=1.2.12.0, Culture=neutral, PublicKeyToken=669e0ddf0bb1aa2a
LOG: GAC Lookup was unsuccessful.
LOG: Attempting download of new URL file:///C:/Program Files (x86)/IIS Express/log4net.DLL.
LOG: Attempting download of new URL file:///C:/Program Files (x86)/IIS Express/log4net/log4net.DLL.
LOG: Attempting download of new URL file:///C:/Program Files (x86)/IIS Express/log4net.EXE.
LOG: Attempting download of new URL file:///C:/Program Files (x86)/IIS Express/log4net/log4net.EXE.
LOG: All probing URLs attempted and failed.
We do have a number of other places where background threads run off and do some initialization work, so perhaps the problem lies there? I switched to tracking when the managed exception was thrown and lo and behold here it is…The plot thickens a bit from this point on. The call stack reveals that this is occurring in System.Web.dll.
System.Web.dll!System.Web.Hosting.ApplicationManager.CreateAppDomainWithHostingEnvironment(string appId, System.Web.Hosting.IApplicationHost appHost, System.Web.Hosting.HostingEnvironmentParameters hostingParameters)
Now why would the ApplicationManager be trying to use Log4Net types? Specifically, "Type is not resolved for member 'log4net.Util.PropertiesDictionary,log4net, Version=1.2.12.0, Culture=neutral, PublicKeyToken=669e0ddf0bb1aa2a'."
Alas, after much gnashing of teeth and tearing of cloth, I found this obscure thread (https://www.mail-archive.com/log4net-dev@logging.apache.org/msg04644.html) on mail archive that does explain things. Reading through the comments I found this nugget:
“Sounds like the webhost was creating multiple appdomains and log4net wasn't available in all of them.”
Finally, this quote from the thread seems to be the resolution, though I abhor putting things in the GAC – especially for nonsensical problems such as this.
“As a matter of fact I'm working with VS2012. I just tried this on a virtual and
ran into this issue. Installing log4net.dll into to the GAC solves this issue
for me.”
I have to admit, this kind of thing drives me nuts. To make matters worse, this has been a problem for a LONG time. C’mon Microsoft, I know you can fix this kind of thing…now get cracking!
/smh
