Nlog: .NET Core 2 Uncaught exception some layoutrenderers not available/empty

[joszz]

NLog version: 4.6.5

Platform: .NET Core 2

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"
      autoReload="true"
      internalLogLevel="Warn"
      internalLogFile="Logs\internal-nlog.log">

  <!-- enable asp.net core layout renderers -->
  <extensions>
    <add assembly="NLog.Web.AspNetCore"/>
  </extensions>

  <!-- the targets to write to -->
  <targets async="true">

    <target xsi:type="Database"
            name="database"
            dbProvider="sqlserver"
            connectionString="some-connectionstring"
            keepConnection="false"
            commandType="text">
      <commandText>
        INSERT INTO dbo.Log (MachineName, Logged, Level, Message, Logger, Callsite, Exception, Stacktrace, Controller, Action, Url, TraceId, IP, Method, UserAgent, Referrer, UserName)
        VALUES (@MachineName, @Logged, @Level, @Message, @Logger, @Callsite, @Exception, @Stacktrace, @Controller, @Action, @Url, @TraceId, @IP, @Method, @UserAgent, @Referrer, @User);
      </commandText>

      <parameter name="@MachineName" layout="${machinename}" />
      <parameter name="@Logged" layout="${date}" />
      <parameter name="@Level" layout="${level}" />
      <parameter name="@Message" layout="${message}" />
      <parameter name="@Logger" layout="${logger}" />
      <parameter name="@Callsite" layout="${callsite:filename=true:includeSourcePath=false}" />
      <parameter name="@Controller" layout="${aspnet-mvc-controller}" />
      <parameter name="@Action" layout="${aspnet-mvc-action}" />
      <parameter name="@Url" layout="${aspnet-request-url}" />
      <parameter name="@TraceId" layout="${aspnet-traceidentifier}" />
      <parameter name="@Exception" layout="${exception:tostring}" />
      <parameter name="@Stacktrace" layout="${stacktrace}" />
      <parameter name="@IP" layout="${aspnet-request-ip} "/>
      <parameter name="@Method" layout="${aspnet-request-method}" />
      <parameter name="@UserAgent" layout="${aspnet-request-useragent}" />
      <parameter name="@Referrer" layout="${aspnet-request-referrer}" />
      <parameter name="@PostedBody" layout="${aspnet-request-posted-body}" />
      <parameter name="@User" layout="${aspnet-session:variable=userName}"/>
    </target>

    <!--Log to VS output window-->
    <target name="debugger" xsi:type="Debugger" layout="${logger}::${message}"/>
  </targets>

  <!-- rules to map from logger name to target -->
  <rules>
    <!--Log to VS output window-->
    <logger name="*" minlevel="Trace" writeTo="debugger" />

    <!--Skip non-critical Microsoft logs and so log only own logs-->
    <logger name="Microsoft.*" maxlevel="Info" final="true" />

    <logger name="*" minlevel="Warn" writeTo="database" />
  </rules>
</nlog>

• What is the current result?
  ILogger.LogError() calls will fill these LayoutRenderers with the correct values;
  -- ${aspnet-request-posted-body}
  -- ${aspnet-session:variable=userName}

An uncaught exception however does log most LayoutRenderers, but will have the above LayoutRenderers empty. I think this is because HttpContextAccessor is null in this situation.

• What is the expected result?
  That no mather what the LayoutRenderers have values, also for uncaught exceptions.

• Did you checked the Internal log?
  Yes, nothing is mentioned.
  With NLog.Web.AspNetCore version 4.8.3 it would log "Session is not configured", when an uncaught exception occured. This is not the case, and when calling LogError manually it behaves normally. With version 4.8.4 nothing is shown in the internal logs.

• Please post full exception details (message, stacktrace, inner exceptions)
  There's nothing there.

• Are there any workarounds? yes/no
  Not that I'm aware of.

• Is there a version in which it did work?
  Not that I'm aware of.

• Can you help us by writing an unit test?
  I'll get back to this later.

[welcome[bot]]

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

[snakefoot]

So you are surprised that NLog is not able to log information, that not available in the context of logging uncaught-exception.

And you see the following:

• NLog.Web.AspNetCore version 4.8.3 failed to log information not available
• NLog.Web.AspNetCore version 4.8.4 still fails to log information not available

But you also see:

• NLog.Web.AspNetCore version 4.8.3 wrote a warning to the internalLogFile about "Session is not configured"
• NLog.Web.AspNetCore version 4.8.4 is not writing any warnings when session details not available.

The missing warning is probably a result of https://github.com/NLog/NLog.Web/pull/436, that improves the session-available-checking, so it avoids exceptions being thrown when no session-details available.

NLog continues to write a debug-message when doing logging in a context where session-details are not available.

But it is normal that logging outside the context of the request-session will not be able to capture session-details. And I think it is an improvement that NLog no longer triggers an exception for every log-event outside session-context.

What behavior are you looking for, since you created an issue? You are of course welcome to create a pull-request for https://github.com/NLog/NLog.Web that make the logic even better (able to capture session-details when logging uncaught exception).

[joszz]

What I'm surprised by, or might have misleaded me is maybe better, is that everything else gets logged.
For example the IP or the referrer gets logged, but not the postbody or the session variables. If I just throw a new exception in an Action(Result) for example, I expected (maybe wrong assumption) to have all the necessary information right there in HttpContext. Everything is logged except for the 2 mentioned LayoutRenderers.

I have been digging into the source to try and understand things better, but probably have a long way to go still. I'm sorry if I wasted your time, I tried asking on StackOverflow but didn't get much further.

A colleague of mine came up with a (custom, not so much nlog "native" - outside of it's scope but interfacing with it) workable approach, but maybe we have to rethink the structure/setup in it's entirety. Still a bit new to this, so please don't hold that against me.

[304NotModified]

What I'm surprised by, or might have misleaded me is maybe better, is that everything else gets logged.
For example the IP or the referrer gets logged, but not the postbody or the session variables.

In ASP.NET Core, session is split from httpcontext parts. I needs a different setup and calls

[304NotModified]

I have been digging into the source to try and understand things better, but probably have a long way to go still. I'm sorry if I wasted your time, I tried asking on StackOverflow but didn't get much further.

relevant parts are here:

• https://github.com/NLog/NLog.Web/blob/dev/src/Shared/LayoutRenderers/AspNetSessionIdLayoutRenderer.cs
• https://github.com/NLog/NLog.Web/blob/dev/src/Shared/LayoutRenderers/AspNetLayoutRendererBase.cs
• and https://github.com/NLog/NLog.Web/blob/827088fee965e960d5f606613ab791f2529110b2/src/Shared/Internal/HttpContextExtensions.cs#L72-L94

See for example if (context?.Features.Get<ISessionFeature>()?.Session != null) (where context is the HttpContext)

[304NotModified]

I assume your question has been answered, if not, please let us know!