search

elastic / ecs-dotnet

https://www.elastic.co/guide/en/ecs-logging/dotnet/current/setup.html
Apache License 2.0
119 stars 59 forks source link

Getting a StackOverflowException using WithElasticApmCorrelationInfo #292

Closed ifoutz closed 1 year ago

ifoutz commented 1 year ago

ECS integration/library project(s) (e.g. Elastic.CommonSchema.Serilog):

Elastic.Apm.SerilogEnricher

ECS schema version (e.g. 1.4.0):

8.4.0

ECS .NET assembly version (e.g. 1.4.2):

8.4.0-alpha4

Elasticsearch version (if applicable):

.NET framework / OS:

.Net 6, Windows 10

Description of the problem, including expected versus actual behavior:

I am using Serilog and ECS to log a simple web api application. Here is the logging setup:

hostBuilder.UseSerilog((ctx, lc) =>
            {
                lc.ReadFrom.Configuration(ctx.Configuration)
                .MinimumLevel.ControlledBy(loggingLevelSwitch)
                .Enrich.FromLogContext()
                .Enrich.WithEnvironmentName()
                .Enrich.WithMachineName()
                .Enrich.WithProcessId()
                .Enrich.WithThreadId()
                .Enrich.WithAssemblyName()
                .Enrich.WithAssemblyVersion()
                .Enrich.WithClientAgent()
                .Enrich.WithClientIp()
                .Enrich.WithExceptionDetails()
                //.Enrich.WithElasticApmCorrelationInfo()
                .Enrich.WithProperty("IstationEnvironment", configureOptions.IstationEnvironment)
                .Enrich.WithProperty("IstationTeam", configureOptions.IstationTeam)
                .Enrich.WithProperty("IstationProject", configureOptions.IstationProject)
                // Filter out ASP.NET Core infrastructre logs that are Information and below (they get replaced by the serilog middleware below)
                .MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning)
                // Filter out components that are too chatty at the debug level
                .MinimumLevel.Override("Orleans.Runtime.DeploymentLoadPublisher", LogEventLevel.Information)
                .MinimumLevel.Override("Orleans.Runtime.Management.ManagementGrain", LogEventLevel.Information)
                .MinimumLevel.Override("Orleans.Runtime.SiloControl", LogEventLevel.Information)
                .MinimumLevel.Override("Orleans.Runtime.GrainDirectory.LocalGrainDirectory", LogEventLevel.Information)
                .MinimumLevel.Override("Elastic.Apm", LogEventLevel.Information);

                if (configureOptions.UseEcsJsonFormatting)
                {
                    lc.Enrich.WithEcsHttpContext(ctx.Configuration.Get<HttpContextAccessor>());
                    var config = new EcsTextFormatterConfiguration();
                    lc.WriteTo.Console(new EcsTextFormatter(config));
                }
                else
                {
                    lc.WriteTo.Console();
                }
            });

If I comment out the line: .Enrich.WithElasticApmCorrelationInfo() then it works as expected. But when that line is left in, I get a StackOverflowException before the app finishes initializing. Here is the stack trace I get:

    [Managed to Native Transition]  
    System.Private.CoreLib.dll!Interop.Kernel32.GetEnvironmentVariable(string lpName, ref char lpBuffer, uint nSize)    Unknown
    System.Private.CoreLib.dll!System.Environment.GetEnvironmentVariableCore(string variable)   Unknown
    System.Private.CoreLib.dll!System.Environment.GetEnvironmentVariable(string variable)   Unknown
    Elastic.Apm.Extensions.Hosting.dll!Elastic.Apm.Extensions.Hosting.Config.MicrosoftExtensionsConfig.Read(string key, string fallBackEnvVarName)  Unknown
    Elastic.Apm.dll!Elastic.Apm.Config.AbstractConfigurationWithEnvFallbackReader.ServiceVersion.get()  Unknown
    Elastic.Apm.SerilogEnricher.dll!Elastic.Apm.SerilogEnricher.ElasticApmEnricher.Enrich(Serilog.Events.LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory)  Unknown
    Serilog.dll!Serilog.Core.Enrichers.SafeAggregateEnricher.Enrich(Serilog.Events.LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory)    Unknown
    Serilog.dll!Serilog.Core.Logger.Dispatch(Serilog.Events.LogEvent logEvent)  Unknown
    Serilog.Extensions.Logging.dll!Serilog.Extensions.Logging.SerilogLogger.Write<Elastic.Apm.Logging.LogValuesFormatter.LogValues>(Serilog.Events.LogEventLevel level, Microsoft.Extensions.Logging.EventId eventId, Elastic.Apm.Logging.LogValuesFormatter.LogValues state, System.Exception exception, System.Func<Elastic.Apm.Logging.LogValuesFormatter.LogValues, System.Exception, string> formatter)    Unknown
    Serilog.Extensions.Logging.dll!Serilog.Extensions.Logging.SerilogLogger.Log<Elastic.Apm.Logging.LogValuesFormatter.LogValues>(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId, Elastic.Apm.Logging.LogValuesFormatter.LogValues state, System.Exception exception, System.Func<Elastic.Apm.Logging.LogValuesFormatter.LogValues, System.Exception, string> formatter)  Unknown
    Elastic.Apm.Extensions.Hosting.dll!Elastic.Apm.Extensions.Hosting.NetCoreLogger.Log<Elastic.Apm.Logging.LogValuesFormatter.LogValues>(Elastic.Apm.Logging.LogLevel level, Elastic.Apm.Logging.LogValuesFormatter.LogValues state, System.Exception e, System.Func<Elastic.Apm.Logging.LogValuesFormatter.LogValues, System.Exception, string> formatter)    Unknown
    Elastic.Apm.dll!Elastic.Apm.Logging.LoggingExtensions.DoLog(Elastic.Apm.Logging.IApmLogger logger, Elastic.Apm.Logging.LogLevel level, string message, System.Exception e, object[] args)   Unknown
    Elastic.Apm.dll!Elastic.Apm.Config.AbstractConfigurationReader.ParseServiceVersion(Elastic.Apm.Config.ConfigurationKeyValue kv) Unknown
    [The 8 frame(s) above this were repeated 992 times] 
    Serilog.Extensions.Logging.dll!Serilog.Extensions.Logging.SerilogLogger.Write<Elastic.Apm.Logging.LogValuesFormatter.LogValues>(Serilog.Events.LogEventLevel level, Microsoft.Extensions.Logging.EventId eventId, Elastic.Apm.Logging.LogValuesFormatter.LogValues state, System.Exception exception, System.Func<Elastic.Apm.Logging.LogValuesFormatter.LogValues, System.Exception, string> formatter)    Unknown
    Serilog.Extensions.Logging.dll!Serilog.Extensions.Logging.SerilogLogger.Log<Elastic.Apm.Logging.LogValuesFormatter.LogValues>(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId, Elastic.Apm.Logging.LogValuesFormatter.LogValues state, System.Exception exception, System.Func<Elastic.Apm.Logging.LogValuesFormatter.LogValues, System.Exception, string> formatter)  Unknown
    Elastic.Apm.Extensions.Hosting.dll!Elastic.Apm.Extensions.Hosting.NetCoreLogger.Log<Elastic.Apm.Logging.LogValuesFormatter.LogValues>(Elastic.Apm.Logging.LogLevel level, Elastic.Apm.Logging.LogValuesFormatter.LogValues state, System.Exception e, System.Func<Elastic.Apm.Logging.LogValuesFormatter.LogValues, System.Exception, string> formatter)    Unknown
    Elastic.Apm.dll!Elastic.Apm.Logging.LoggingExtensions.DoLog(Elastic.Apm.Logging.IApmLogger logger, Elastic.Apm.Logging.LogLevel level, string message, System.Exception e, object[] args)   Unknown
    Elastic.Apm.dll!Elastic.Apm.Config.AbstractConfigurationReader.ParseServiceVersion(Elastic.Apm.Config.ConfigurationKeyValue kv) Unknown
    Elastic.Apm.SerilogEnricher.dll!Elastic.Apm.SerilogEnricher.ElasticApmEnricher.Enrich(Serilog.Events.LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory)  Unknown
    Serilog.dll!Serilog.Core.Enrichers.SafeAggregateEnricher.Enrich(Serilog.Events.LogEvent logEvent, Serilog.Core.ILogEventPropertyFactory propertyFactory)    Unknown
    Serilog.dll!Serilog.Core.Logger.Dispatch(Serilog.Events.LogEvent logEvent)  Unknown
    Serilog.Extensions.Logging.dll!Serilog.Extensions.Logging.SerilogLogger.Write<Microsoft.Extensions.Logging.FormattedLogValues>(Serilog.Events.LogEventLevel level, Microsoft.Extensions.Logging.EventId eventId, Microsoft.Extensions.Logging.FormattedLogValues state, System.Exception exception, System.Func<Microsoft.Extensions.Logging.FormattedLogValues, System.Exception, string> formatter)   Unknown
    Serilog.Extensions.Logging.dll!Serilog.Extensions.Logging.SerilogLogger.Log<Microsoft.Extensions.Logging.FormattedLogValues>(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId, Microsoft.Extensions.Logging.FormattedLogValues state, System.Exception exception, System.Func<Microsoft.Extensions.Logging.FormattedLogValues, System.Exception, string> formatter) Unknown
    Microsoft.Extensions.Logging.Abstractions.dll!Microsoft.Extensions.Logging.Logger<System.__Canon>.Log<Microsoft.Extensions.Logging.FormattedLogValues>(Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId, Microsoft.Extensions.Logging.FormattedLogValues state, System.Exception exception, System.Func<Microsoft.Extensions.Logging.FormattedLogValues, System.Exception, string> formatter)   Unknown
    Microsoft.Extensions.Logging.Abstractions.dll!Microsoft.Extensions.Logging.LoggerExtensions.Log(Microsoft.Extensions.Logging.ILogger logger, Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId, System.Exception exception, string message, object[] args)   Unknown
    Microsoft.Extensions.Logging.Abstractions.dll!Microsoft.Extensions.Logging.LoggerExtensions.LogDebug(Microsoft.Extensions.Logging.ILogger logger, Microsoft.Extensions.Logging.EventId eventId, string message, object[] args)  Unknown
    Microsoft.Extensions.Hosting.dll!Microsoft.Extensions.Hosting.Internal.HostingLoggerExtensions.Starting(Microsoft.Extensions.Logging.ILogger logger)    Unknown
    Microsoft.Extensions.Hosting.dll!Microsoft.Extensions.Hosting.Internal.Host.StartAsync(System.Threading.CancellationToken cancellationToken)    Unknown
    Microsoft.AspNetCore.dll!Microsoft.AspNetCore.Builder.WebApplication.StartAsync(System.Threading.CancellationToken cancellationToken)   Unknown
    Microsoft.Extensions.Hosting.Abstractions.dll!Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.RunAsync(Microsoft.Extensions.Hosting.IHost host, System.Threading.CancellationToken token)    Unknown
    Microsoft.Extensions.Hosting.Abstractions.dll!Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.Run(Microsoft.Extensions.Hosting.IHost host)   Unknown
    Microsoft.AspNetCore.dll!Microsoft.AspNetCore.Builder.WebApplication.Run(string url)    Unknown
>   Api.dll!Program.<Main>$(string[] args) Line 340 C#

Steps to reproduce:

  1. Spin up a simple .Net Web App API.
  2. Initialize with WithElasticApmCorrelationInfo
  3. Get StackOverflowException
  4. Initialize without WithElasticApmCorrelationInfo
  5. App works normally
Mpdreamz commented 1 year ago

Thanks for reporting this one @ifoutz ! It's a bit of a catch22 situation so I am still working out how to break out of this self referencing loop.

The cause is that Elastic.Apm itself logs in the property getter for ServiceVersion if that is not configured explicitly:

https://github.com/elastic/apm-agent-dotnet/blob/3a8fc3cc2cd299fe29c2e739cfb912f580e170c0/src/Elastic.Apm/Config/AbstractConfigurationReader.cs#L874

cc @gregkalapos

Mpdreamz commented 1 year ago

Opened a fix for this in the agent: https://github.com/elastic/apm-agent-dotnet/pull/2054

This will mean we need to bump the minimum version in our ECS.NET packages too once the fix is released.