Invalid callsite information on Windows 2003/2008 x64

[sdreier]

Hello,

i am using NLog for an ASP.NET 2.0 WebService and in the main it works great .
But yesterday our quality assurance discovered a problem with the log files on x64 operating systems.
The callsite information is everytime the same:

2009-03-13 12:28:27.0781   1 INFO   NLog.LoggerImpl.Write    Config (C:\Program Files (x86)\Test\www\ippbxdc\datacollector.config)
2009-03-13 12:28:27.0781   1 INFO   NLog.LoggerImpl.Write    Pictures (C:\Program Files (x86)\Test\www\userpics)
2009-03-13 12:28:27.0937   1 FATAL  NLog.LoggerImpl.Write    Configuration could not be loaded!
2009-03-13 12:28:27.0937   1 FATAL  NLog.LoggerImpl.Write    Please check the datacollector.config for errors and restart the service!

The same log on a x86 operating system looks like this:

2009-03-13 12:28:27.0781   1 INFO   ippbxdc.Common.readConfig    Config (C:\Program Files (x86)\Test\www\ippbxdc\datacollector.config)
2009-03-13 12:28:27.0781   1 INFO   ippbxdc.Common.readConfig    Pictures (C:\Program Files (x86)\Test\www\userpics)
2009-03-13 12:28:27.0937   1 FATAL  ippbxdc.Common.readConfig    Configuration could not be loaded!
2009-03-13 12:28:27.0937   1 FATAL  ippbxdc.Common.readConfig    Please check the datacollector.config for errors and restart the service!

My NLog configuration file (web.nlog in the same folder as web.config) looks like this:

<?xml version="1.0" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
    <targets async="true">
      <target name="file" xsi:type="File"
            header="IpPbxDataCollector starting..."
            footer="Shutdown completed"
            layout="${longdate} ${threadid:fixedLength=true:padding=3} ${level:uppercase=true:fixedLength=true:padding=-6} ${callsite:fixedLength=true:padding=-60}  ${message}"
            fileName="${basedir}/logs/ippbxdatacollector-${shortdate}.log" />
    </targets>
    <rules>
      <logger name="*" minlevel="Debug" writeTo="file"/>
    </rules>
</nlog>

Does anybody have an idea why the callsite could not be resolved by NLog?


Best regards

Sebastian Dreier

[sdreier]

Does nobody have an idea how to fix this problem?

[sdreier]

During the last week I made further tests to fix the problem and I discovered one interesting aspect.
I reproduced the problem on a x64 machine in our laboratory. Once Visual Studio 2008 SP2 (Team Edition) was installed on the system (for debugging) the problem does not occur anymore.

Does anybody have an idea why this happens?
 

[James Gutierrez]

I'm having this same problem.  Callsite always reports "NLog.LoggerImpl.Write".  Did you ever find a solution?

Thanks

[Jaroslaw Kowalski]

I'm trying to set up an x64 machine to see if I can reproduce the problem in my environment.
Is there anything special about the machines you're using? Which .NET Framework is installed? Which NLog version?

Jarek

[James Gutierrez]

Thanks for the reply.  

My development machine:
Vista 64 SP2
Visual Studio 2008 Pro SP1
.NET 3.5 SP1
NLog version 1.0.0.505
Logging from a WCF service hosted in IIS

This morning I confirmed that ${callsite} works as expected once I deploy to our staging server (32-bit Windows Server 2008), so it definitely is limited to the 64-bit machine.  

[James Gutierrez]

Ok, some more info for you:

1. Callsite works as expected when I log from a console app
2. Also works when I log from an aspx page hosted in visual studio's development web server
3. When I change the website to use local IIS server, callsite just returns 'NLog.LoggerImpl.Write'

Hope this helps.  At this point it's no longer really an issue for me since it works from our production servers and I have a workaround for my dev machine.  Thanks again for your quick response.  I'll monitor this thread to see if there's any other info you want to help figure out what's going on.

[Jaroslaw Kowalski]

The issue seems to be related to the fact that x64 JIT often optimizes away stack frames for small methods and NLog uses stack frame information to figure out the user code that invoked the logger. What's worse, even putting [MethodImpl(NoInlining)] does not seem to work for some people.

http://connect.microsoft.com/VisualStudio/feedback/ViewFeedback.aspx?FeedbackID=162364

I'll see if there's a workaround.

[Jaroslaw Kowalski]

I think I found a workaround for this issue and did some preliminary testing on an x64 VM. Can you please apply the attached patch and let me know if it fixes the issue?

LoggerImpl.cs
x64callsite.patch

Instructions:

1. Download NLog 1.0 sources
2. Replace LoggerImpl.cs with the attached file or apply x64callsite.patch
3. Recompile using MSBuild or NAnt

With this change in place the stack frame should never include anything from NLog assembly although there's no guarantee that it will be precisely the point of invocation (because of JIT optimizations).

[manlyboy]

Thanks - the new .cs file fixed the issue.