Nlog: IIS appliction running medium trust outputs ProcessName as Unknown

[thebiffman]

NLog version: 4.7.5

Platform: .Net 4.8

Current NLog config (xml or C#, if relevant)

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
      autoReload="true"
      throwExceptions="true"
      internalLogLevel="Warn" internalLogFile="c:\temp\nlog-internal.log" >

  <!-- 
    This configuration file is generated if it does not exist and will not be updated
    The documentation for the NLog configuration can be found at https://github.com/nlog/NLog/wiki/Configuration-file
  -->

  <!-- optional, add some variabeles
  https://github.com/nlog/NLog/wiki/Configuration-file#variables
  -->
  <variable name="loglocation" value="c:\netadmin\logs\"/>

  <!-- 
  These are the default targets defined by netadmin. Additional targets can be added:
    See https://github.com/nlog/NLog/wiki/Targets for possible targets.
    See https://github.com/nlog/NLog/wiki/Layout-Renderers for the possible layout renderers.
  -->
  <targets>

    <!-- Keeps a log file for each process and day-->
    <target xsi:type="File" 
            name="ProcessLog"
            fileName="${var:loglocation}${processname}.log" 
            layout="${longdate} ${uppercase:${level}} ${message} ${exception:format=tostring}"
            keepFileOpen="true"
            concurrentWrites="true"
            archiveFileName="${var:loglocation}\archive\${processname}-{#}.log"
            archiveEvery="Day"
            archiveNumbering="DateAndSequence"
            archiveDateFormat="yyyyMMddHHmmss"
            maxArchiveFiles="90"


            />

     <!-- Keeps a log file for each class and day and archive for 30 days -->
    <target xsi:type="File"
              name="ClassLog"
              fileName="${var:loglocation}${logger}.log"
              layout="${longdate} - ${callsite}${newline}${level}: ${message}${newline}${exception:format=ToString}"
              keepFileOpen="true"
              concurrentWrites="true"
              archiveFileName="${var:loglocation}\archive\${logger}-{#}.log"
              archiveEvery="Day"
              archiveNumbering="Date"
              archiveDateFormat="yyyyMMddHHmmss"
              maxArchiveFiles="30"
            />

    <!-- Output to debugger-->
    <target xsi:type="Console"
            name="StandardConsole"
            layout="${longdate} ${processname} ${logger} ${message} ${exception:format=tostring}"
            />

    <!-- Output to an attached debugger -->
    <target xsi:type="Debugger"
            name="AttachedDebugger"
            layout="${logger} ${message} ${exception:format=tostring}"
            />

    <target xsi:type="NLogViewer"
            name="viewer"
            includeSourceInfo="true"
            layout="${longdate}|${level:uppercase=true}|${processname}|${logger}|${message}|${exception:format=tostring}"
            address="udp://127.0.0.1:9999"/>

  </targets>

  <!-- These are the rules defined by netadmin, these can be modified and additional rules can be added to customize logging-->
  <rules>

    <!-- Everything needed when developing to class-files -->
    <logger name="*" minlevel="Trace" writeTo="ClassLog" enabled="false" />

    <!-- All fatal, error, warnings and info are logged to the process specific log file -->
    <logger name="*" minlevel="Trace" writeTo="ProcessLog" enabled="true"/>

    <!-- Everything is logged to the processlog, default not enabled -->
    <logger name="*" writeTo="ProcessLog" enabled="false"/>

    <!-- Everything is logged to the console, default not enabled -->
    <logger name="*" writeTo="Console" enabled="false"/>

    <!-- Everything is logged to an attached debugger, default not enabled -->
    <logger name="*" writeTo="AttachedDebugger" enabled="false"/>

    <!-- This enables use of Sentinel to view logs in real-time etc -->
    <logger name="*" minlevel="Trace" writeTo="viewer" enabled="true" />

  </rules>
</nlog>

• What is the current result?
  Most logs are written to a file named after the process, but the logs from IIS process (w3wp) are sometimes written to a file named _unknown_.log sometimes, instead of w3wp.log.

• What is the expected result?
  All logs should be written to files named after the process.

• Did you checked the Internal log?
  Yes

• Please post full exception details (message, stacktrace, inner exceptions)
  N/A

• Are there any workarounds? yes/no
  No

• Is there a version in which it did work?
  Yes, 4.3.7 on .NET Framework 4.5. It started happening when we updated the NuGet package from that version to 4.7.5 and .NET Framework 4.8.

• Can you help us by writing an unit test?
  No, probably not.

[welcome[bot]]

Hi! Thanks for opening your first issue here! Please make sure to follow the issue template - so we could help you better!

[thebiffman]

I can add that I tried to restart the webserver (iisreset) when writing this issue. The wireup in our process was written to w3wp.log but then when I logged in to our application the log switched over to _unknown_.log.

We have several application pools (w3wp.exe processes) running at the same time.

[snakefoot]

@thebiffman Thank you for reporting this. It really sounds like a bug.

First since the issue can be re-produced with iireset and then logging in to your application. Could you configure internalLogLevel="Debug" and attach the output to this issue. From where it is working to suddenly changing to _unknown_.log.

Secondly could you afterwards try and change from NLog 4.7.5 to NLog 4.7.0 and see if the bug also exist in that version. In case the bug was introduced with #3941

[snakefoot]

This is pure guessing since I know nothing about IIS. But lets say IIS starts a new AppDomain, and static variables doesn't transfer to the new AppDomain. And the new AppDomain is restricted somehow and cannot lookup current-process-name using Process.GetCurrentProcess().MainModule.FileName. Then all logging from the new AppDomain will end at _unknown.log_

[thebiffman]

Thanks for the quick responses. I tried to look through some of the recent changes but had missed the PR you linked. I think that the bug was introduced then, yes.

I spent some time during the evening remote debugging our application and managed to figure out that the property containing the filepath (CurrentProcessFilePath in AppEnvironmentWrapper) contains an empty string, which indicates that the GetCurrentProcess call fails or something along those lines. I have not managed to verify if/what exception is thrown since it happens at startup. It seems that the new way of fetching the information about the process failed for 1 out of 2 IIS Worker processes (w3wp.exe) that starts up at the same time in this specific case. One had the proper path, one an empty string. Since it wont be updated unless its null it stays an empty string and results in unkown-named logfile. Our application contains 2+ different application pools (which runs in separate processes) that all uses NLog and starts at the same time. I got some help from a colleague who did some remote debugging magic to trigger the LookupCurrentProcessFilePath again while debuggig, and that time the property was filled with the correct value. This makes me believe that maybe it has something to do with the startup process. I will have to investigate a bit more another day.

I also tested NLog 4.7.0 and that seemed to fix the problem, which also makes sense and are in line with everything else I discovered.

[snakefoot]

Thank you for the confirmation about it is working for NLog 4.7.0. I have been able to reproduce it in an unit-test with a medium-trust-appdomain with no rights at all.

There it actually fails to compile the method that contains the call to Process.GetCurrentProcess() so fails horrible. Will make a pull-request to handle System.Security.SecurityException when it fails.

[snakefoot]

@thebiffman I would be really grateful if you could verify that the pre-release-build from #4182 will resolve the issue:

NLog.4.7.5.12201-PR4182.nupkg

[thebiffman]

That was quick work :) I appreciate it.

Unfortunately that build does not fix our problem, altough I think its close. I did some additional remote debugging with that version installed and managed to find exactly where the exception is thrown. It seems that its when accessing the MainModule property on the Process object in LookupCurrentProcessFilePath method.

Exception:
MainModule 'currentProcess.MainModule' threw an exception of type 'System.ComponentModel.Win32Exception' System.Diagnostics.ProcessModule {System.ComponentModel.Win32Exception}
Message "Access is denied"

So it is not a SecurityException. Just as a test i modified the code to return null regardless of what type exception is thrown when accessing MainModule. This may not be an acceptable solution but I wanted to test it and it seems to work in this case. When doing that it will always use the fallback if it fails, regardless of how it fails and if the fallback also fails then it will return string.empty and result in unknown.log as before...

I find this quite weird since all our pools are run with the same user account that is an administrator. And it only sometims fails.

[snakefoot]

@thebiffman Curious if Process.GetCurrentProcess().ProcessName would work. Then one could skip the Win32 API-call.

Thank you for testsing, and a new build is on its way with fallback logic for all exceptions.

[snakefoot]

@thebiffman Updated nuget-package that should fallback independent of whatever exception:

NLog.4.7.5.12202-PR4182.nupkg

[thebiffman]

@snakefoot I have tried the new build and that works great. No more longs in the _unknown_.log files and no errors as far as I can see. Great!

[snakefoot]

Excellent. Thank you for the help with testing.

[thebiffman]

@thebiffman Curious if Process.GetCurrentProcess().ProcessName would work. Then one could skip the Win32 API-call.

Thank you for testsing, and a new build is on its way with fallback logic for all exceptions.

I did a quick test and using that property worked fine, no exception it looks like. But of course that only results in "w3wp", not the full path to the file like its supposed to be.

[snakefoot]

But of course that only results in "w3wp", not the full path to the file like its supposed to be.

Yes was thinking the same, that if someone used ${processdir} then it would still break. So I guess Win32 API fallback are here to stay until NetFramework and IIS have left planet earth.

[thebiffman]

A couple of follow-up questions

Should I close this issue?

Any idea when next release will be?

Thanks.

[snakefoot]

Should I close this issue?

The issue will be closed when the pull-request is merged.

Any idea when next release will be?

Nope it depends on when @304NotModified has time, and how critical the issue is.

[304NotModified]

Will release the new version this week. :)

[304NotModified]

NLog 4.7.6 is now live!

https://www.nuget.org/packages/NLog/4.7.6/

[snakefoot]

@thebiffman Btw. one should avoid using throwExceptions="true" in NLog.config unless as last resort when troubleshooting why NLog.config will not load. It is intended for unit-tersting only, and will give unexpected behavior in production environment.

[thebiffman]

@thebiffman Btw. one should avoid using throwExceptions="true" in NLog.config unless as last resort when troubleshooting why NLog.config will not load. It is intended for unit-tersting only, and will give unexpected behavior in production environment.

Oh, thanks. We have been using it for quite some time in production unfortunately, but I have updated our default configuration now and will inform my team. I also updated our project with the new release the other day. Thanks for the quick turnaround :)