6

This question is more about C# than it is about log4net (I think).

I created a custom appender and let it read a static field that was set previously by the program.

To my astonishment the static field was reinitialized and the set value dit not make it to the appender.

I fired up debugview and saw that the static constructor is called twice (!). This should not be possible in the same appdomain right? Only debugview brought this to light since VS didn't hit a second time on the breakpoint.

Note that this is not a question about avoiding the use of static variable with log4net. I'm interested in what kind of magic log4net uses to accomplish this?

Edit #1

Hello Jon, Big fan.

I isolated it further as requested. First I started blank and worked towards the target situation that exposes the error. Since I almost matched the target character by character and still didn't repro I went the other way round.

Starting from the error situation I stripped out everything that I deemed not essential till it started ... working as expected.

It seems there is some weird thing hoing on when the runtime tries to resolved the log4net assembly (as observed in debug mode)

This is what I see with debugview:

[7756] General: WARN - Failed to parse module's 'log4net' version . Exception: System.NullReferenceException: Object reference not set to an instance of an object. [7756] at DebuggerShared.Services.EventArgs.ModuleLoadedInDebuggerEventArgs..ctor(String modulePath, String moduleLoadMessage, Boolean isUserCode, String name, String version) [7756] General: WARN - Failed to parse module's 'FollowUp.Common' version . Exception: System.NullReferenceException: Object reference not set to an instance of an object. [7756] at DebuggerShared.Services.EventArgs.ModuleLoadedInDebuggerEventArgs..ctor(String modulePath, String moduleLoadMessage, Boolean isUserCode, String name, String version)

And VS shows no value for the path in the debug-module screen. Now how did I managed to come to that situation? Weird that it managed to load an assembly but can't tell anymore from where :)

Here is the isolated situation to the point that if I modify it further it starts working as expected.

https://www.sugarsync.com/pf/D6486369_1701716_00940

I'm still interested in the technical details but after removing the reference to log4net and adding it again it all started to work again. I'm happy that it works but it nags me that I don't have a thorough explanation

Also, the static constructor iscalled twice now which makes sense since the type is initializes again when log4net gets its hands on it.

I think it isn't worthwhile to spent more time on this cause I think the solution was in a weird state and to understand all this has marginal value. Still, if you can think of something to explain this I'd be glad to here.

Edit #2

It turned out that some assemblies were indeed loaded twice including the one with the static constructor. I'll investigate later how this is possible but I have a workaround by disabling and enabling Costura. Costura is a msbuild task that merges all the assemblies into one. I'm not saying that Costura is the root cause. It could easily be that the csproj/sln files were in strange state.

Thinking on how to diagnose this problem faster in the future I fired up sysinternals ProcessExplorer. Now I expected to see the assemblies being loaded only once but I found saw that they were loaded twice. Seems this is a bug in the runtime thats fixed only in .NET 4

http://forum.sysinternals.com/why-some-net-assemblies-are-duplicated-in-memory_topic15279.html https://connect.microsoft.com/VisualStudio/feedback/details/467560/clr-maps-assemblies-into-the-virtual-address-space-twice

Edit #3 Costura made the assemblies load twice. The issue was fixed on the same day by the project owner :) http://code.google.com/p/costura/issues/detail?id=17&thanks=17&ts=1328826304

We need a Costura tag but I don't have the necessary 1500 reputation points. Please create it if you have the rights. Thanks.

Kind Regards, Tom

Palle Due
  • 5,929
  • 4
  • 17
  • 32
buckley
  • 13,690
  • 3
  • 53
  • 61
  • 1
    "Only debugview brought this to light since VS didn't hit a second time on the breakpoint." <--- I vote for a bug in debugview as a more likely cause of this issue. I'm really curious what really happened there :) – Sergey Kalinichenko Feb 08 '12 at 11:36
  • Hello dasblinkenlight. Debugview is a pure observer, I don't see it generate any side effects. If debug picks up the Trace.Writeline twice that means the code was executed twice and debugview had nothing to do with it. – buckley Feb 08 '12 at 12:35
  • 1
    This didn't happen, stone cold hard guarantee. Forgetting the remove the default trace listener is a common mistake. – Hans Passant Feb 08 '12 at 13:23
  • @buckley: If you believe that the debugview has nothing to do with it, then presumably you can write a short but complete program to demonstrate the problem, right? – Jon Skeet Feb 08 '12 at 14:17

2 Answers2

5

It looks like you managed to load two separate instances of log4net into the same AppDomain.

One project references:

<Reference Include="log4net">
  <HintPath>..\packages\log4net.1.2.11\lib\net35-full\log4net.dll</HintPath>
</Reference>

The other:

<Reference Include="log4net, Version=1.2.10.0, Culture=neutral, PublicKeyToken=1b44e1d426115821, processorArchitecture=MSIL">
  <SpecificVersion>False</SpecificVersion>
  <HintPath>..\ExternalReferences\log4net.dll</HintPath>
</Reference>

One of them is strongly named, the other isn't, this resulted in .net giving them different identities. And the hint path differs too. Also one seems to be 1.2.10, the other 1.2.11.

try calling AppDomain.GetAssemblies() and check if log4net occurs twice.

CodesInChaos
  • 106,488
  • 23
  • 218
  • 262
  • Hello CodeInChaos. Thanks for pointing this out and especially the explanation at why this is possible. Do you also know why this triggers that the static constructor (and thus the static field initialization) is called twice? They are in the same appdomain right, so I expect them to share the static. – buckley Feb 08 '12 at 14:58
  • 3
    If two instances of the assembly get loaded, then each of them gets a completely separate classes, which just happen to have the same name. Thus the static constructor gets called once for each of them. If you check their `AssemblyQualifiedName` it'll probably be different. – CodesInChaos Feb 08 '12 at 15:00
  • Thanks for your tip with the GetAssebmlies (AppDomain currentDomain = AppDomain.CurrentDomain;Assembly[] assems = currentDomain.GetAssemblies()). It helped me find what the problem was. I updated the question with some more findings including an interesting not harmful bug in the .NET runtime. – buckley Feb 09 '12 at 08:49
1

Well it could be explcitly invoking the type initializer:

var initializer = typeof(Foo).TypeInitializer;
initializer.Invoke(null);

However, I'd hope that it's not doing that. Can you come up with a short but complete program which demonstrates this happening?

Jon Skeet
  • 1,421,763
  • 867
  • 9,128
  • 9,194
  • Hello John, I would have isolated it earlier if it wasn't part of a big solution. I should have and you can find it at edit #1 in my question – buckley Feb 08 '12 at 14:45
  • So what actually happens if you do that? .NET doesn't care and just acts as if the static constructor was called for the first time ever? – Chris Marisic Nov 06 '14 at 19:46
  • @ChrisMarisic: Yes, as far as I'm aware, that's the case. – Jon Skeet Nov 06 '14 at 19:59