Is there a way to get rid of Object Reference exception for ${aspnet-sessionid} in internal logs for .net core 2. In case logger is being called in layer without HttpContext in it

[Defee]

Hi All!

Issue Template Info:

Type (choose one):
- Question
My question is there a way to write when clause or other clause in layout to exclude the exception throwing from internal-logs in case HttpContext is not determined in the layer?

It extremely hardens troubleshooting from internal nlog logs.

NLog version: Resolved as 4.6.3

NLog.Web/NLog.Web.AspNetCore version:
<PackageReference Include="NLog.Web.AspNetCore" Version="4.8.2" />

NLog.Extensions.Logging version:
Resolved as 1.5.0 from NLog.Web.AspNetCore.

Platform: .NET Core 2

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

<configuration>
  <configSection>
    <section name="nlog" type="NLog.NLogConfig.ConfigSectionHandler,NLog"/>
  </configSection>
  <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" autoReload="true" internalLogLevel="info" internalLogFile="internal-nlog.txt">
    <extensions>
      <add assemblyFile="Microsoft.ApplicationInsights.NLogTarget.dll" />
    </extensions>
    <targets async="true">
      
      <target name="dbTarget" xsi:type="Database" 
              connectionString="YourConnectionString" 
              keepConnection="true" 
              commandText="YourSchema.SaveLogEvent 
                @timeStamp,
                @level, 
                @username, 
                @logger, 
                @url, 
                @machineName,
                @threadId,
                @sessionId,
                @referrer,
                @userAgent,
                @code,
                @message">
        <parameter name="@timeStamp" layout="${date}" />
        <parameter name="@level" layout="${level}" />
        <parameter name="@username" layout="${aspnet-user-identity}" />
        <parameter name="@logger" layout="${logger}" />
        <parameter name="@url" layout="${aspnet-request-url:IncludeHost=true:IncludePort=true:IncludeQueryString=true:IncludeScheme=true}" />
        <parameter name="@machineName" layout="${machinename}" />
        <parameter name="@threadId" layout="${threadid}" />
        <parameter name="@sessionId" layout="${aspnet-sessionid}" />
        <parameter name="@referrer" layout="${aspnet-request-referrer}" />
        <parameter name="@userAgent" layout="${aspnet-request-useragent}" />
        <parameter name="@code" layout="${event-context:item=Code}" />
        <parameter name="@message" layout="${message}" />
      </target>
   
      <target xsi:type="ApplicationInsightsTarget" name="aiTarget" instrumentationKey="YourInstrumentationKey">
        <layout xsi:type="JsonLayout" includeAllProperties="true">
          <attribute name="exception" layout="${exception}" />
          <attribute name="threadId" layout="${threadid}" />
          <attribute name="username" layout="${aspnet-user-identity}" />
          <attribute name="url" layout="${aspnet-request-url:IncludeHost=true:IncludePort=true:IncludeQueryString=true:IncludeScheme=true}" />
          <attribute name="severity" layout="${level:lowercase=true}" />
          <attribute name="eventProperties" >
            <layout type='JsonLayout' includeAllProperties="true"  maxRecursionLimit="5"/>
          </attribute>
        </layout>
      </target>
    </targets>

    <rules>
      <logger name="*" minlevel="Trace" writeTo="dbTarget" />
       <logger name="*" minlevel="Trace" writeTo="aiTarget" /> 
    </rules>
  </nlog>
</configuration>

Question:

Please check the section after the questions for more information.

• What is the current result?
  In internal logs i get the exception Object Reference not set for an instance of an object. The transaction to db however comes just with empty session. (which is expected result)
• What is the expected result?
  Some kind of workaround which will check
• Did you checked the Internal log?
  Yes.
• Please post full exception details (message, stacktrace, inner exceptions)
  Message: Object Reference not set for an instance of an object.
  Details: Is failing inside of the internal log file when trying to call with above layout in the layer where HttpContext is not available. Specifically it fails on ${aspnet-sessionid} retrieving.
• Are there any workarounds? yes/no
  It doesn't log the
• Is there a version in which it did work?
  Didn't check.
• Can you help us by writing an unit test?
  I might help.

Additional Information

I use the wrapper class to log the data in the database, obviously for some of the layers aspnet-sessionid will not be available, is there a workaround to check context in layout if it is null to display empty value/or friendly message for logs, else display session Id.
It happens on the Db target I use.

I really appreciate help as want o get rid of the Object reference is not set as an instance of a object exception in internal nlog logs.

The common wrapper class will throw the exception when you have a Data Access Layer and you call logger in it as it doesn't have a clue about HttpContext.

Possibly related question #153

[snakefoot]

Can you show the full stacktrace of the exception?

[Defee]

Here is how it looks.
internal-nlog.txt

[snakefoot]

I guess we could swallow this exception:

2019-06-13 13:00:04.6763 Warn Exception in layout renderer. Exception: System.InvalidOperationException: Session has not been configured for this application or request.
   at Microsoft.AspNetCore.Http.DefaultHttpContext.get_Session()
   at NLog.Web.LayoutRenderers.AspNetSessionIdLayoutRenderer.DoAppend(StringBuilder builder, LogEventInfo logEvent)
   at NLog.LayoutRenderers.LayoutRenderer.RenderAppendBuilder(LogEventInfo logEvent, StringBuilder builder)

But I have a hard time reproducing this issue:

2019-06-13 13:00:04.8760 Error Error has been raised. Exception: System.NullReferenceException: Object reference not set to an instance of an object.
   at NLog.Targets.Target.PrecalculateVolatileLayoutsWithLock(LogEventInfo logEvent)
   at NLog.Targets.Wrappers.AsyncTargetWrapper.Write(AsyncLogEventInfo logEvent)
   at NLog.Targets.Wrappers.AsyncTargetWrapper.WriteAsyncThreadSafe(AsyncLogEventInfo logEvent)

The later issue is the most interesting. Since there should never be a NullReferenceException.

[snakefoot]

Also little confusing that you are running "NetCore2" but at the same time having NLog-config in the web.config. And have misspelled <configSections> (Your example is missing the "s"):

  <configSections>
    <section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog"/>
  </configSections>

[snakefoot]

Would it be possible for you to modify any of the two example-projects, so they generate the NullReferenceException?

• https://github.com/NLog/NLog.Web/tree/dev/examples/ASP.NET%20Core%202/Visual%20Studio%202017/ASP.NET%20Core%202%20-%20VS2017
• https://github.com/NLog/NLog.Web/tree/dev/examples/ASP.NET%204.6.1/Visual%20Studio%202017/ASP.NET%204.6.1%20-%20VS2017

[Defee]

Sure. Will do it over weekend. I think those 2 exceptions are actually correlated. As first the HttpContext fails with the exception then Nlog logs invalid operation cos sessions is was not configured. But that's an educated guess :)

I guess I copy pasted it from the old project and didn't remove it.
I got used to the xml based nlog config. Do you support Json configuration for core I wonder? I didn't find it in docs.
Also I used common logging along with common.logging for the abstraction level and there it monitors the particular nlog.config file for the configuration as I remember.

[snakefoot]

Nlog logs invalid operation cos sessions is was not configured. But that's an educated guess :)

Also what I have tried to reproduce, but without any luck.

It is possible to configure NLog using appsettings.json:

https://github.com/NLog/NLog.Extensions.Logging/wiki/Json-NLog-Config

[Defee]

It is possible to configure NLog using appsettings.json:
https://github.com/NLog/NLog.Extensions.Logging/wiki/Json-NLog-Config

Thanks! Does it support like separate file configuration? like old scool nlog.config something like nlog.{env}.json?

[snakefoot]

Thanks! Does it support like separate file configuration? like old scool nlog.config something like nlog.{env}.json?

You can load from whatever json-file you want. Doesn't have to be appsettings.json.

[snakefoot]

Created #436 to reduce the loglevel to Debug for InvalidOperationException. But still missing a fix for the special NullReferenceException.

[304NotModified]

I've checked PrecalculateVolatileLayoutsWithLock, but don't see what possible could be null and isn't checked already. Maybe inlining stuff which is making the stracktrace useless?

update: also checked v4.6.3 tag
update2: or someone should send null as logevent, but that's unlikely?

[snakefoot]

@Defee Btw. if you want to optimize your NLog-config. Then you should replace the obsolete ${event-context:item=Code} with ${event-properties:item=Code} (Will reduce allocations and improve concurrency)

[304NotModified]

I've checked PrecalculateVolatileLayoutsWithLock, but don't see what possible could be null and isn't checked already. Maybe inlining stuff which is making the stracktrace useless?

update: also checked v4.6.3 tag
update2: or someone should send null as logevent, but that's unlikely?

Found something I think,

AsyncTaskTarget:

  protected override void FlushAsync(AsyncContinuation asyncContinuation)
        {
            if (_previousTask?.IsCompleted == false || !_requestQueue.IsEmpty)
            {
                InternalLogger.Debug("{0} Flushing {1}", Name, _requestQueue.IsEmpty ? "empty queue" : "pending queue items");
                _requestQueue.Enqueue(new AsyncLogEventInfo(null, asyncContinuation));
                _lazyWriterTimer.Change(0, Timeout.Infinite);
            }
            else
            {
                InternalLogger.Debug("{0} Flushing Nothing", Name);
                asyncContinuation(null);
            }
        }

sents null logEventInfo

[snakefoot]

Found something I think,

None of the targets in question uses AsyncTaskTarget and the _requestQueue is internal, and there are validation whether it is flush-event (No LogEventInfo) on dequeue.

[Defee]

Found something I think,

None of the targets in question uses AsyncTaskTarget and the _requestQueue is internal, and there are validation whether it is flush-event (No LogEventInfo) on dequeue.

Doesn't the following <targets async="true"> mean make all child targets async in nlog.config (xml)? Anyway I plan to make an example today based on the above links you provided :)

[Defee]

I've created the solution but wasn't able to repro Null Reference case. Will try to do some real example with db tomorrow which is more related to what I have at work. Interesting fact: If I set throwExceptions to true it hangs completely. It seems it somehow can be related with the EF Core requests to db logging. So I will dive there deeper tomorrow.

[snakefoot]

Curious what output you get in the NLog internal logger, when application hangs completely with throwExceptions=true

[Defee]

It seems it hangs right before NullReference, it gives me 2 InvalidOperation exceptions (I think because 2 targets are configured) and hangs. In simple app log it freezes right after sql command logging

[Defee]

Still no luck to repro NullReference. Tried with Not exactly the same config. Used Postress. (I use MSSQL at work ).
Will try with the MSSQL over the week.

@304NotModified , @snakefoot
Meanwhile I submit the hotfix via PR for the invalid operation exception.
It was caused by the Session not configured state for some log events. It is not because of the context null though
Pr: #440

@304NotModified where/when exactly FlushAsync is being called?

[snakefoot]

@Defee Doesn't the following mean make all child targets async in nlog.config (xml)?

<targets async="true"> makes all targets become wrapped by AsyncWrapper. It is not the same as AsyncTaskTarget that operates using async Tasks.

AsyncTaskTarget is similar to TargetWithLayout or TargetWithContext. It is base-class to inherit from.

[304NotModified]

Anyway, my point was that logevent is assumed nonNull, while there are cases where it passes as null. As there is one case, there could be multiple as the assumption seems to be non valid.

I will try to add some resharper annotations to the relevant code and then we could rule out this assumption. :)

[304NotModified]

where/when exactly FlushAsync is being called?

I have to check that (limited internet/PC now, holiday :)) , but at least: manual, end of appdomain event and maybe async batch

[304NotModified]

@304NotModified where/when exactly FlushAsync is being called?

Among others, calls to FlushAsync (could be indirect via Flush)

• AppDomainUnload
• ProcessExit
• Manual Flush() (LogManager / LogFactory)
• Shutdown() (LogManager / LogFactory)
• Set LogManager.Configuration = null (also on LogFactory)
• RemoveTarget on Config
• AsyncTargetWrapper
• AutoFlushTargetWrapper (really? :P )

[304NotModified]

#436 has been merged so I think this should be closed