NLog.Targets.ElasticSearch (7.1.0) asp.net core 3.0 application exited with stack overflow

[another-mi]

I use app in docker container, and when I activate this target, my container crashed with error "Stack overflow."

[another-mi]

With version NLog.Targets.ElasticSearch (6.1.0) forks fine

[snakefoot]

Think you have to create an issue for https://github.com/elastic/elasticsearch-net

Maybe with the callstack from #102 (Or with your own callstack from the StackOverflowException).

[snakefoot]

@another-mi See also this comment about overriding the JsonSerializer in Elasticsearch.Net

[another-mi]

Thanks, I downgrade version to 6.1.0 but I have another error "Method may only be called on a Type for which Type.IsGenericParameter is true." Pfff

[another-mi]

@another-mi See also this comment about overriding the JsonSerializer in Elasticsearch.Net

Do you have custom implementation for ElasticsearchSerializer?

[snakefoot]

Cannot give much help without a full StackTrace for the exception.

[another-mi]

Message: "Method may only be called on a Type for which Type.IsGenericParameter is true." StackTrace: at Elasticsearch.Net.Transport1.Request[TResponse](HttpMethod method, String path, PostData data, IRequestParameters requestParameters) in c:\Projects\elastic\net-6\src\Elasticsearch.Net\Transport\Transport.cs:line 86 at Elasticsearch.Net.ElasticLowLevelClient.DoRequest[TResponse](HttpMethod method, String path, PostData data, IRequestParameters requestParameters) in c:\Projects\elastic\net-6\src\Elasticsearch.Net\ElasticLowLevelClient.cs:line 58 at Elasticsearch.Net.ElasticLowLevelClient.Bulk[TResponse](PostData body, BulkRequestParameters requestParameters) in c:\Projects\elastic\net-6\src\Elasticsearch.Net\ElasticLowLevelClient.Generated.cs:line 26 at NLog.Targets.ElasticSearch.ElasticSearchTarget.SendBatch(ICollection1 logEvents) in C:\projects\NLog.Targets.ElasticSearch\src\NLog.Targets.ElasticSearch\ElasticSearchTarget.cs:line 171

[snakefoot]

Are you referencing ElasticSearch.Net nuget package directly, and using different version than the one used by NLog.Targets.ElasticSearch-nuget?

[another-mi]

Yes, but it was only for tests ) I have some troubles: When I use NLog.Targets.ElasticSearch (7.1.0), i have error "Stack overflow." When I use NLog.Targets.ElasticSearch (6.1.0), i have error "Method may only be called on a Type for which Type.IsGenericParameter is true." What should I do?

[snakefoot]

When I use NLog.Targets.ElasticSearch (7.1.0), i have error "Stack overflow."

That is a bug in ElasticSearch.Net . But I guess they will argue that you should not have cyclic-reference-loops in the objects that you are logging. But you can try and create an issue.

When I use NLog.Targets.ElasticSearch (6.1.0), i have error "Method may only be called on a Type for which Type.IsGenericParameter is true."

That also sounds like a bug in ElasticSearch.Net. But since they have released ver. 7. Then they will not provide you any support for ver. 6. See also https://github.com/elastic/elasticsearch-net/issues/3503

What object are you trying to log, that makes the ElasticSearch.Net-library explode?

[another-mi]

When I use NLog.Targets.ElasticSearch (7.1.0), i have error "Stack overflow."

That is a bug in ElasticSearch.Net . But I guess they will argue that you should not have cyclic-reference-loops in the objects that you are logging. But you can try and create an issue.

When I use NLog.Targets.ElasticSearch (6.1.0), i have error "Method may only be called on a Type for which Type.IsGenericParameter is true."

That also sounds like a bug in ElasticSearch.Net. But since they have released ver. 7. Then they will not provide you any support for ver. 6. See also elastic/elasticsearch-net#3503

What object are you trying to log, that makes the ElasticSearch.Net-library explode?

It is simple string: logger.LogInformation("New message");

[snakefoot]

How does your NLog.config look like? Pretty sure you are doing something special, else everyone would be complaining.

[another-mi]

<?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="Information" internalLogFile="nlog/internal-nlog.txt">-->
  <extensions>
    <add assembly="NLog.Web.AspNetCore"/>
    <add assembly="NLog.Targets.ElasticSearch"/>
  </extensions>
  <targets>
    <target xsi:type="Console" name="console" layout="${longdate}|${level}|${message}|${exception:format=ToString,StackTrace}" />
    <target xsi:type="BufferingWrapper" flushTimeout="5000" name="elastic" bufferSize="10000" overflowAction="Discard"  >
      <target xsi:type="ElasticSearch"
              uri="elastic uri"
              index="SmsParser-Dev-${date:format=yyyy.MM.dd}"
              documentType="Layout"
              includeAllProperties="True">
        <field name="traceId" layout="${aspnet-TraceIdentifier}" />
        <field name="logger" layout="${logger}" />
        <field name="machinename" layout="${machinename}" />
        <field name="hostname" layout="${hostname}" />
        <field name="message" layout="${message}" />
        <field name="exception" layout="${exception:format=ToString,StackTrace}" />
        <field name="user-identity" layout="${aspnet-user-identity}" />
        <field name="client-ip" layout="${aspnet-request-ip:CheckForwardedForHeader=true}" />
        <field name="requestId" layout="${mdlc:requestId}" />
        <field name="phone" layout="${mdlc:phone}" />
      </target>
    </target>
  </targets>
  <rules>
    <logger name="System.*" maxlevel="Debug" final="true"/>
    <logger name="Microsoft.*" maxlevel="Debug" final="true"/>
    <logger name="*" minlevel="Info" writeTo="console,elastic" />
  </rules>
</nlog>

[snakefoot]

How do you know if you that it is just your LogInformation that fails? Can see you include all logevents from AspNetCore engine and have a bufferingwrapper that saves in bulk every 5 sec.

Does it throw exceptions if you use includeAllProperties=false?

[snakefoot]

I know this is not a perfect solution, but just curious if it fixes your issue with ElasticSearch.net:

<?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="Information" internalLogFile="nlog/internal-nlog.txt">-->
  <extensions>
    <add assembly="NLog.Web.AspNetCore"/>
    <add assembly="NLog.Targets.ElasticSearch"/>
  </extensions>
  <targets>
    <target xsi:type="Console" name="console" layout="${longdate}|${level}|${message}|${exception:format=ToString,StackTrace}" />
    <target xsi:type="BufferingWrapper" flushTimeout="5000" name="elastic" bufferSize="10000" overflowAction="Discard"  >
      <target xsi:type="ElasticSearch"
              uri="elastic uri"
              index="SmsParser-Dev-${date:format=yyyy.MM.dd}"
              documentType="Layout">
        <field name="message" layout="${message}" />
        <field name="properties" layoutType="System.Object">
              <layout type="JsonLayout" includeAllProperties="true" maxRecursionLimit="2">
                   <attribute name="traceId" layout="${aspnet-TraceIdentifier}" />
                   <attribute name="logger" layout="${logger}" />
                   <attribute name="machinename" layout="${machinename}" />
                   <attribute name="hostname" layout="${hostname}" />
                   <attribute name="exception" layout="${exception:format=ToString}" />
                   <attribute name="user-identity" layout="${aspnet-user-identity}" />
                   <attribute name="client-ip" layout="${aspnet-request-ip:CheckForwardedForHeader=true}"/>
                   <attribute name="requestId" layout="${mdlc:requestId}" />
                   <attribute name="phone" layout="${mdlc:phone}" />
              </layout>
        </field>
      </target>
    </target>
  </targets>
  <rules>
    <logger name="System.*" maxlevel="Debug" final="true"/>
    <logger name="Microsoft.*" maxlevel="Debug" final="true"/>
    <logger name="*" minlevel="Info" writeTo="console,elastic" />
  </rules>
</nlog>

It serializes using the NLog-JsonSerializer and then parses it again as an ExpandoObject. Not very efficient but curious if you have other issues than logging rogue objects.

[another-mi]

How do you know if you that it is just your LogInformation that fails? Can see you include all logevents from AspNetCore engine and have a bufferingwrapper that saves in bulk every 5 sec. Does it throw exceptions if you use includeAllProperties=false?

Unfortunately I didn't check it

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[yosbeleg89]

I have the same issue in asp.net core 3.1, I can confirm that if I set includeAllProperties=false it does not happen. @snakefoot is there a solution for this? If I also set the LogLevel to something higher like Warning it does not happen either:

  "Logging": {
    "LogLevel": {
      "Default": "Debug",
      "System": "Warning",
      "Microsoft": "Warning"
    }
  },

[snakefoot]

@yosbeleg89 Not the creator of https://github.com/elastic/elasticsearch-net Guess you have to be careful what you log

[yosbeleg89]

@snakefoot It's not what I log, it's what the framework logs, if it brakes with the framework logs (System and Microsoft) I have nothing to do there. I think this is an issue, an a very painful one to detect the cause, since Stack Overflow does not give any Stack Trace, I don't know if it is on https://github.com/elastic/elasticsearch-net or on this repo because the one that is braking is NLog.Targets.ElasticSearch. If the last one depends on ElasticSearch.Net maybe the issue is there, I'm not familiar with the code, sorry. Should I open an issue on ElasticSearch.Net?

[snakefoot]

@yosbeleg89 Think you need the full stacktrace to report an issue. Similar to the one shown here #102 and detected here #114

Maybe also the log-statement in question.

You could try and setup a NLog.config without buffering or asyncwrapper (No async="true"). That writes to two NLog-targets. Elasticsearch-target and a bonus target like file / console. Where the bonus-target has this layout:

layout="${level}|${logger}|${message}|${exception:format=tostring,data}|${all-event-properties}|${message:raw=true}"

Maybe sure to put the bonus-target first in the logging-rules. Then hopefully you will have the log-message giving issues as last log-message in the bonus-target-output, when the stackoverflow occurs in the Elasticsearch-target

[yosbeleg89]

Think you need the full stacktrace to report an issue

That could be a problem, the whole Stack Trace of an Stack Overflow is it: Stack Overflow.

[snakefoot]

Did not say it would be easy. Just said that others have succeeded in providing the stacktrace from a stackoverflow-exception.

Also if you can provide the actual log statement then clever persons with proper psychic debugging skills might guess the issue.

[yosbeleg89]

Just said that others have succeeded in providing the stacktrace from a stackoverflow-exception.

That would be interesting to know how they did, since it's not possible right now, check https://github.com/dotnet/runtime/issues/9195

Also if you can provide the actual log statement then clever persons with proper psychic debugging skills might guess the issue.

It's not possible to know, since there is no Stack Trace, no logs, it happens in production and not on a specific view/area of the application. What I know is that it's related with Microsoft and System logs, because when I set higher levels for those it does not happen anymore.

Thanks for your help.

[snakefoot]

It's not possible to know, since there is no Stack Trace, no logs, it happens in production and not on a specific view/area of the application.

Did you read my suggestion in my previous comment about setting up a bonus-target to capture the log-statement that causes the stackoverflow?

[yosbeleg89]

@snakefoot Yes, I did, most of the times the last two logs are:

Info|Microsoft.AspNetCore.Routing.EndpointMiddleware|Executed endpoint '<controller removed>.Index (App)'||EndpointName=<controller removed>.Index (App), EventId_Id=1, EventId_Name=ExecutedEndpoint, EventId=ExecutedEndpoint|Executed endpoint '{EndpointName}'
Info|Microsoft.AspNetCore.Hosting.Diagnostics|Request finished in 98.4493ms 200 text/html; charset=utf-8||ElapsedMilliseconds=98.4493, StatusCode=200, ContentType=text/html; charset=utf-8, EventId_Id=2, EventId=2|Request finished in 98.4493ms 200 text/html; charset=utf-8

[snakefoot]

I'm guessing EndpointName=<controller removed>.Index (App) is the output after your own obfuscation.

The controller-class in question (now obfuscated away) does it has public properties where the references can lead to cyclic loop?

What happens if you configure your Logging-Filtering to ignore the Info-Level-output from the logger Microsoft.AspNetCore.Routing.EndpointMiddleware ?

[yosbeleg89]

I'm guessing EndpointName=.Index (App) is the output after your own obfuscation.

You are right. I removed not just because of obfuscation, cuz it happens on others controllers, the most simple one is like:

    [Area("Inf")]
    public class DashboardController : Controller
    {
        [Route("")]
        public IActionResult Index()
        {
            return View();
        }
    }

I reproduced it locally and the last logs this time were:

Info|Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker|Executed action method App.Areas.Inf.Controllers.DashboardController.Index (App), returned result Microsoft.AspNetCore.Mvc.ViewResult in 0.0574ms.||ActionName=App.Areas.Inf.Controllers.DashboardController.Index (App), ActionResult=Microsoft.AspNetCore.Mvc.ViewResult, ElapsedMilliseconds=0.0574, EventId_Id=2, EventId_Name=ActionMethodExecuted, EventId=ActionMethodExecuted|Executed action method {ActionName}, returned result {ActionResult} in {ElapsedMilliseconds}ms.
Info|Microsoft.AspNetCore.Hosting.Diagnostics|Request starting HTTP/2 GET https://localhost:5002/  ||Protocol=HTTP/2, Method=GET, Scheme=https, Host=localhost:5002, Path=/, EventId_Id=1, EventId=1|Request starting HTTP/2 GET https://localhost:5002/

[yosbeleg89]

Since the last log and the one repeating on my tests was in Microsoft.AspNetCore.Hosting.Diagnostics I added this:

<logger name="Microsoft.AspNetCore.Hosting.Diagnostics" minlevel="Trace" final="true" />

And I can confirm that it does not happen now.

[snakefoot]

The objects logged looks harmless to me:

https://github.com/dotnet/aspnetcore/blob/master/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs

https://github.com/dotnet/aspnetcore/blob/master/src/Hosting/Hosting/src/Internal/HostingRequestStartingLog.cs

https://github.com/dotnet/aspnetcore/blob/master/src/Hosting/Hosting/src/Internal/HostingRequestFinishedLog.cs

But maybe logging comes from GenericWebHostedService.cs:

            if (Logger.IsEnabled(LogLevel.Debug))
            {
                foreach (var assembly in Options.WebHostOptions.GetFinalHostingStartupAssemblies())
                {
                    Logger.LogDebug("Loaded hosting startup assembly {assemblyName}", assembly);
                }
            }

Does the problem re-appear if you do this (Add maxLevel="Debug"):

<logger name="Microsoft.AspNetCore.Hosting.Diagnostics" minlevel="Trace" maxlevel="Debug" final="true" />

[yosbeleg89]

@snakefoot btw, it happened again in another namespace. I created a test repo to reproduce it.

the last logs this time:

Debug|Microsoft.AspNetCore.Routing.DefaultLinkGenerator|Found the endpoints Route: {controller=Home}/{action=Index}/{id?} for address Microsoft.AspNetCore.Routing.RouteValuesAddress||Endpoints="Route: {controller=Home}/{action=Index}/{id?}", Address=Microsoft.AspNetCore.Routing.RouteValuesAddress, EventId_Id=100, EventId_Name=EndpointsFound, EventId=EndpointsFound|Found the endpoints {Endpoints} for address {Address}
Debug|Microsoft.AspNetCore.Routing.DefaultLinkGenerator|Successfully processed template {controller=Home}/{action=Index}/{id?} for Route: {controller=Home}/{action=Index}/{id?} resulting in /Home/Privacy and ||Template={controller=Home}/{action=Index}/{id?}, Endpoint=Route: {controller=Home}/{action=Index}/{id?}, Path=/Home/Privacy, EventId_Id=102, EventId_Name=TemplateSucceeded, EventId=TemplateSucceeded|Successfully processed template {Template} for {Endpoint} resulting in {Path} and {Query}
Stack overflow.

this was using the test repo

I don't know if it helps, but the last logs from the VS debug console were:

'elastic-target-test.exe' (CoreCLR: clrhost): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\3.1.2\System.Runtime.Serialization.Primitives.dll'. 
'elastic-target-test.exe' (CoreCLR: clrhost): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\3.1.2\System.Runtime.Numerics.dll'. 
'elastic-target-test.exe' (CoreCLR: clrhost): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\3.1.2\System.IO.Compression.dll'. 
'elastic-target-test.exe' (CoreCLR: clrhost): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\3.1.2\System.Reflection.Emit.dll'. 
'elastic-target-test.exe' (CoreCLR: clrhost): Loaded 'Elasticsearch.Net.CustomDynamicObjectResolver'. 
An unhandled exception of type 'System.StackOverflowException' occurred in System.Private.CoreLib.dll

[snakefoot]

Well still curious what object that is logged, that make it explode.

[yosbeleg89]

If you run the sample project, it should take you a few clicks if any to get the exception, asuming you have an elastic instance running on localhost:9200.

If I change the login levels from:

  "Logging": {
    "LogLevel": {
      "Default": "Debug",
      "System": "Trace",
      "Microsoft": "Trace"
    }
  },

to

  "Logging": {
    "LogLevel": {
      "Default": "Debug",
      "System": "Trace",
      "Microsoft": "Warning"
    }
  },

then the exception goes away.

[yosbeleg89]

@snakefoot Hi, I noticed that there is a merged PR that could help with this issue, is there any planned release with the changes? Thanks

[markmcdowell]

Sorry my fault, I've tag a build with 7.2.0 and it's deploying now.

[yosbeleg89]

Sorry my fault, I've tag a build with 7.2.0 and it's deploying now.

Thanks 🎉

[rahulpandare8]

Use MaxrecursionLimit="1" in target type using target.elasticsearch 7..7.0