[BUG] No logs in console with Serilog inside NoopTransaction (disabled ElasticApm scenario)

[reeloadead]

ECS library: Elastic.CommonSchema.Serilog

ECS schema version: 1.5.0

ECS .NET assembly version: 1.5.3 (earlier and current alfa too)

APM .NET Agent: 1.11.0

.NET framework / OS: .net 5

Description of the problem, including expected versus actual behavior:

• Use logging (AddSerilog()) and tracing (UseElasticApm())
• Disable ElasticApm ("ElasticApm": { "Enabled": "false" } })
• Log something inside transaction

Example:

_logger.LogWarning("Before");
var transaction = _tracer.StartTransaction(GetType().Name, ApiConstants.ActionExec);
try
{
	_logger.LogWarning("Inside");
}
finally
{
	transaction?.End();
}
_logger.LogWarning("After");

Actual behavior: Tracing disabled; No logged messages inside transaction in console.

Example output:

{"@timestamp":"2021-08-18T20:19:17.5361091+03:00","log.level":"Warning","message":"Before","metadata":...}
{"@timestamp":"2021-08-18T20:19:17.5381091+03:00","log.level":"Warning","message":"After","metadata":...}

Expected behavior: Tracing disabled, but log messages should be written to output

Desired output:

{"@timestamp":"2021-08-18T20:19:17.5361091+03:00","log.level":"Warning","message":"Before","metadata":...}
{"@timestamp":"2021-08-18T20:19:17.5371091+03:00","log.level":"Warning","message":"Inside","metadata":...}
{"@timestamp":"2021-08-18T20:19:17.5381091+03:00","log.level":"Warning","message":"After","metadata":...}

Steps to reproduce:

1. Disable ElasticApm
2. Enable Serilog.SelfLog to easily catch exception: Serilog.Debugging.SelfLog.Enable(msg => Debug.WriteLine(msg));
3. NullReferenceException is thrown:

caught exception while emitting to sink Serilog.Sinks.SystemConsole.ConsoleSink: System.NullReferenceException: Object reference not set to an instance of an object.
  at Elastic.CommonSchema.Serilog.LogEventConverter.GetTrace(LogEvent logEvent)
  at Elastic.CommonSchema.Serilog.LogEventConverter.ConvertToEcs(LogEvent logEvent, IEcsTextFormatterConfiguration configuration)
  at Elastic.CommonSchema.Serilog.EcsTextFormatter.Format(LogEvent logEvent, TextWriter output)
  at Serilog.Sinks.SystemConsole.ConsoleSink.Emit(LogEvent logEvent)
  at Serilog.Core.Sinks.SafeAggregateSink.Emit(LogEvent logEvent)

Reasons and fix ideas:

1. NoopTransaction is returned for disabled APM: https://github.com/elastic/apm-agent-dotnet/blob/07a448406c78871a59088f87edaf3bcc191c2e67/src/Elastic.Apm/Api/Tracer.cs#L65

2. ElasticApmEnricher for NoopTransaction adds properties ElasticApmTransactionId, ElasticApmTraceId equal null here: https://github.com/elastic/ecs-dotnet/blob/d1d5b770fc15a81e8883175abe05315c8e525213/src/Elastic.Apm.SerilogEnricher/ElasticApmEnricher.cs#L26

option 1 to fix - adjust ElasticApmEnricher: if (Agent.Tracer?.CurrentTransaction is NoopTransaction) return;

3. ExtensionMethods.TryGetScalarPropertyValue sets value = null for ElasticApmTraceId and returns true: https://github.com/elastic/ecs-dotnet/blob/f0033bd47881a926b0d772b1d14f0fa5ebf92e3a/src/Elastic.CommonSchema.Serilog/ExtensionMethods.cs#L25

option 2 to fix - adjust TryGetScalarPropertyValue: return true only if value != null

4. LogEventConverter's GetTrace() and GetTransaction() methods access Value property of actual null traceId (transactionId):

https://github.com/elastic/ecs-dotnet/blob/f0033bd47881a926b0d772b1d14f0fa5ebf92e3a/src/Elastic.CommonSchema.Serilog/LogEventConverter.cs#L87

https://github.com/elastic/ecs-dotnet/blob/f0033bd47881a926b0d772b1d14f0fa5ebf92e3a/src/Elastic.CommonSchema.Serilog/LogEventConverter.cs#L92

option 3 to fix - add check for null here for both methods of LogEventConverter

[chrisvanderpennen]

Hi, we just ran into this today and I was quite disappointed to discover it was a year old known issue.

[Mpdreamz]

Thanks for raising this and apologies for the delay on this issue.

Will look at addressing this ASAP so we are sure the upcoming 8.4.0 release (#197) does not suffer from this bug.

[Mpdreamz]

Luckily in main the more egregious bug of not logging at all was already fixed.

Opened https://github.com/elastic/ecs-dotnet/pull/234 to ensure the enrichers are aware of the Enabled setting that was introduced in the 1.7 version of the agent. We were still on the 1.4 version of the agent.