Apm-agent-dotnet: Using Serilog with Elastic APM causes NullReferenceException

[scotm-gxg]

Describe the bug
When using Serilog and Elastic APM together in Asp.Net COre, a NullReferenceException is thrown on start-up.

Versions:
netcoreapp 2.1
Elastic.Apm.NetCoreAll 1.1.1
Serilog.AspnetCore 3.0.0

To Reproduce
Steps to reproduce the behavior:

1. Clone this repo: https://github.com/scotmeiste/elastic-apm-serilog-error
2. in appsettings.json, replace ServerUrls and SecretToken with your instance of Elastic APM
3. Run Web Api project
4. See error in debug output (Debug Console tab in VS Code)

Elastic APM .NET Agent: [CRITICAL] Exception thrown by logging implementation. Log message: `The agent was started without a service name. The automatically discovered service name is {ServiceName}'. args.Length: 1. Current thread: managed ID: 1
Elastic APM .NET Agent: +-> Exception (exception): System.NullReferenceException: Object reference not set to an instance of an object.
Elastic APM .NET Agent:    at Serilog.Extensions.Logging.SerilogLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at Elastic.Apm.AspNetCore.AspNetCoreLogger.Log[TState](LogLevel level, TState state, Exception e, Func`3 formatter)
   at Elastic.Apm.Logging.LoggingExtensions.DoLog(IApmLogger logger, LogLevel level, String message, Exception e, Object[] args)e: <null>

Expected behavior
Either no error, or a more helpful description of what went wrong.

[gregkalapos]

Hi @scotm-gxg,

thanks for the reproducer. Unfortunately it does not reproduce for me. I tried it on 2 machines, in both cases it worked, I don't see the log you pasted, the sample app worked fine (I tried the http://localhost:5000/weatherforecast) and the data is also visible in Kibana. Tested both with release and debug builds. Logs are at the end of this comment.

Now to the error you see: what it says is that the logging library - in this case serilog - throws an exception when the agent tries to log. The Log message: The agent was started... you see is the log that we try to print when the NullReferenceException happens and this is the very first line the agent tries to log.

I suspect something is not ok with the serilog config on your machine and this error would happen regardless of the agent. Could you maybe quickly deactivate the agent (just remove app.UseAllElasticApm(Configuration);) and see if serilog works that way?

Of course I'm not blaming here - it's totally possible that the bug is in our code, but atm I'm unable to see where that is, so I'm trying to narrow this down.

info: Elastic.Apm[0]
      {{Scope}} The agent was started without a service name. The service name will be automatically discovered.
info: Elastic.Apm[0]
      {{Scope}} The agent was started without a service name. The service name will be automatically discovered.
[17:54:15 INF] {{Scope}} The agent was started without a service name. The service name will be automatically discovered.
[info: Elastic.Apm[0]
      {{Scope}} The agent was started without a service version. The service version will be automatically discovered.
info: Elastic.Apm[0]
      {{Scope}} The agent was started without a service version. The service version will be automatically discovered.
17:54:15 INF] {{Scope}} The agent was started without a service version. The service version will be automatically discovered.
Hosting environment: Development
Content root path: /Users/gergelykalapos/Repos/elastic-apm-serilog-error
Now listening on: http://localhost:5000
Application started. Press Ctrl+C to shut down.

[scotm-gxg]

Hey @gregkalapos thanks for the detailed response...

One thing that maybe i didn't call out enough in the description was that it shows up in the debug console in VSCode (not terminal) and you have to scroll up past some of the .net system messages. (see screenshot)

As you suggested, I deactivated the agent, and Serilog works properly. I honestly am not sure if the issue is with Elastic APM or the Serilog library. But Elastic APM was the most recent add and that's when the issue surfaced so i thought I"d start there, but it could be serilog (or how i have serilog configured).

[scotm-gxg]

its also worth noting that serilog seems to function after the app has intialized, so i'm wondering if its just running into some kind of race condition or something like that.

[gregkalapos]

Thank you! Yes, now I see it and I'm able to debug. I'm trying to figure out what's going on. I'll posting results here in case I find something.

[gregkalapos]

As it seems, all our structured logs with serilog throw an exception.

Already something like this ends up with a NullReferenceException:

_logger?.Info()?.Log("Log {param}.", "abc");

[gregkalapos]

@scotm-gxg I think I have it: https://github.com/elastic/apm-agent-dotnet/pull/545

The reproducer was super useful! 👍 Thanks for that.

I see log lines logged twice on my machine, that was already the case with your setup. I'm not sure if it's agent related... I will try to figure out why that happens.

In case you have time, could you maybe pull my PR and see if everything is ok with that on your machine?

[scotm-gxg]

Glad that test project helped!

I tried building your PR locally, but I got the error again. its near the end of my day here, so I will check it again in the morning to see if I got the right branch and built it correctly and all that.

Thanks again for your help!

[iquirino]

Surprisingly i'm using Serilog too..
But i'm not using custom template.
Is it working nice to me.

[scotm-gxg]

Alright, i'm still getting the error. Things I've checked/done:

• pulled branch (LoggerFix - double checked i was on this branch)
• Incremented version number (1.1.2) to make sure there's no nuget caching issues
• ran dotnet pack -c Release to create nupkg file and saved to local folder
• in my test project, pointed nuget to local folder and updated Elastic.Apm.AspNetCore to the new build/version i just created.

still receive the same output in debug console.

Did I miss something?

Elastic APM .NET Agent: [CRITICAL] Exception thrown by logging implementation. Log message: `The agent was started without a service name. The automatically discovered service name is {ServiceName}'. args.Length: 1. Current thread: managed ID: 1
Elastic APM .NET Agent: +-> Exception (exception): System.NullReferenceException: Object reference not set to an instance of an object.
Elastic APM .NET Agent:    at Serilog.Extensions.Logging.SerilogLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at Elastic.Apm.AspNetCore.AspNetCoreLogger.Log[TState](LogLevel level, TState state, Exception e, Func`3 formatter)
   at Elastic.Apm.Logging.LoggingExtensions.DoLog(IApmLogger logger, LogLevel level, String message, Exception e, Object[] args)e: <null>

[gregkalapos]

@scotm-gxg thanks for the update. I'll fork your repo and try myself.

[gregkalapos]

@scotm-gxg It seems working for me. This branch contains the manually built agent: https://github.com/gregkalapos/elastic-apm-serilog-error/tree/WithElasticBranchPR545

I simply built the agent and referenced the agent dlls without NuGet. The error is gone - it was there originally but I don't see it with the updated version. Here is a PR showing the replaced files.

Maybe 1 idea: The fix itself is in the Elastic.Apm project, so you should make sure that the Elastic.Apm project is updated. The way it works is that you referenced Elastic.Apm.NetCoreAll, which references some of our other packages, including Elastic.Apm - that is where the change happened.

[scotm-gxg]

Ah, ok, i only rebuilt Elastic.Apm.AspNetCore. that's probably why i didn't see the fix. i'll pull what you have above and try running that.

[scotm-gxg]

Alright, looks like its working now!

Thanks for posting that fork/PR. it helped a ton. And thanks for the assistance!

Any idea when this will get rolled into a release? No rush or anything, just want to make sure I update the fix on my main project.

[gregkalapos]

Ah, ok, i only rebuilt Elastic.Apm.AspNetCore. that's probably why i didn't see the fix. i'll pull what you have above and try running that.

Oh, yeah, sorry, I should have said that the fix is in Elastic.Apm.

[gregkalapos]

Alright, looks like its working now!

Thanks for posting that fork/PR. it helped a ton. And thanks for the assistance!

Any idea when this will get rolled into a release? No rush or anything, just want to make sure I update the fix on my main project.

Awesome!

Regarding release: we already have 2 fairly important fixes on master. We don't make promises on release dates, but I think having those 2 fixes out there would be important, so I'm thinking about a patch release very soon.

[gregkalapos]

@scotm-gxg: The patch with the fix is out: https://github.com/elastic/apm-agent-dotnet/releases/tag/1.1.2 - so 1.1.2 should be ok with Serilog. The packages are also updated on nuget.org.

[scotmeiste]

@gregkalapos awesome, thank you!

[rkor1984]

I am experinecing same issue, I am using 1.7.1 version