Adding Serilog stops Sentry from reporting Scope properties

[georgiosd]

Package

Sentry.Serilog

.NET Flavor

.NET Core

.NET Version

8.0.0

OS

Windows

SDK Version

4.10.1

Self-Hosted Sentry Version

No response

Steps to Reproduce

Scaffold new project:

dotnet new webapi -o SentryScopeApi

Edit .csproj:

<Project Sdk="Microsoft.NET.Sdk.Web">

  <PropertyGroup>
    <TargetFramework>net8.0</TargetFramework>
    <Nullable>enable</Nullable>
    <ImplicitUsings>enable</ImplicitUsings>
  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="Sentry.AspNetCore" Version="4.10.1" />
    <PackageReference Include="Sentry.Serilog" Version="4.10.1" />
    <PackageReference Include="Serilog.AspNetCore" Version="8.0.2" />
  </ItemGroup>

</Project>

Edit Program.cs

using Serilog;

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console()
    .CreateLogger();

var builder = WebApplication.CreateBuilder(args);

builder.WebHost.UseSentry(s =>
{
    s.Dsn = "...";
});

builder.Services.AddSerilog(s => s.WriteTo.Sentry()); // if we remove this, it all goes according to plan

var app = builder.Build();

var logger = app.Services.GetRequiredService<ILogger<Program>>();
var sentry = app.Services.GetRequiredService<IHub>();

using (logger.BeginScope(new Dictionary<string, object> { ["Key1"] = "Value" }))
{
    sentry.CaptureException(new InvalidOperationException(DateTime.Now.ToString()));
}

app.Run();

Expected Result

Sentry issue contains "Key1" value.

Actual Result

Sentry issue does not contain "Key1" value.

[georgiosd]

Would be great if the fix (or a workaround) was ported for use with net6.0 projects.

[bruno-garcia]

Thanks for reporting. net6.0 is still supported by the main line so should be ok to add the fix to it too

[jamescrosswell]

I think I can see why this happens. When using MEL, we register SentryLogger which overrides the BeginScope method like so: https://github.com/getsentry/sentry-dotnet/blob/eb73e2e0145edff6d5819884692a5d5cd171ed63/src/Sentry.Extensions.Logging/SentryLogger.cs#L26-L31

Effectively that provides a way to synchronize the scope between MEL and Sentry.

In the case of the SeriLog integration, SeriLog provides the Logger and we merely implement a Sink for SeriLog... so the scope doesn't get synced.

We'll see if we can find an alternate way to sync the scope in Serilog (hopefully it has some hooks or something that we could use).

[georgiosd]

That would be great :)

For now I solved it by creating a scope in both Serilog and Sentry.

[jamescrosswell]

We'll see if we can find an alternate way to sync the scope in Serilog (hopefully it has some hooks or something that we could use).

This doesn't appear to be possible.

The implementation of SerilogLogger.BeginScope simply delegates to the logger provider:

    public IDisposable BeginScope<TState>(TState state) where TState : notnull
    {
        return _provider.BeginScope(state);
    }

And the implementation of SerilogLoggerProvider.BeginScope looks like this:

    /// <inheritdoc cref="IDisposable" />
    public IDisposable BeginScope<T>(T state)
    {
        if (CurrentScope != null)
            return new SerilogLoggerScope(this, state);

        // The outermost scope pushes and pops the Serilog `LogContext` - once
        // this enricher is on the stack, the `CurrentScope` property takes care
        // of the rest of the `BeginScope()` stack.
        var popSerilogContext = LogContext.Push(this);
        return new SerilogLoggerScope(this, state, popSerilogContext);
    }

The only artefact of this method is from the call to LogContext.Push, which results in a stack of IEnumerable<ILogEventEnricher>. It's possible to retrieve an aggregation of this by calling var enricher = Serilog.Context.LogContext.Clone();, which gives you back an ILogEventEnricher. However, ILogEventEnricher is not very useful:

public interface ILogEventEnricher
{
    void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory);
}

So I can't see any extension points for SeriLog that would enable us to synchronise the scope to Sentry.

[georgiosd]

Wouldn't an enricher work? Scope is pushed to LogEvent.Properties afaik so you could read it from there.

[jamescrosswell]

Wouldn't an enricher work? Scope is pushed to LogEvent.Properties afaik so you could read it from there.

Sentry already reads the Serilog properties for any logs that get piped into the SentrySink: https://github.com/getsentry/sentry-dotnet/blob/bd62cf0421cc7a5d7b7804f8461fae00d47d43b8/src/Sentry.Serilog/SentrySink.cs#L114

However, in your example, you've simply thrown an exception and captured it. Serilog won't be involved in capturing that exception at all... nothing is being "logged".

If you log the error instead, what you've stored on the scope will end up as additional properties on the Logging event and from there be stored as additional data on the Sentry event:

using (logger.BeginScope(new Dictionary<string, object> { ["CaptureMethod"] = "LogError" }))
{
    var exception = new InvalidOperationException(DateTime.Now.ToString());
    logger.LogError(exception, "An error occurred");
}

That will only work for errors that you capture via LogError, however. Any state from the logging scope would be ignored for unhandled exceptions that Sentry captures independently of Serilog.

[georgiosd]

You're right... and I don't use the logger because I store the sentry id while processing an item that fails.

Let me open a ticket on the serilog repo and see if they can help.

[nblumhardt]

That will only work for errors that you capture via LogError, however. Any state from the logging scope would be ignored for unhandled exceptions that Sentry captures independently of Serilog.

By the time the catch block runs, Serilog's scopes will have been popped so may not contain anything useful anyway :thinking:

If you're using the exception filter trick to capture the state at the point the exception was thrown, constructing a throwaway LogEvent (perhaps reusing a [ThreadStatic] one to save on allocations) and calling the enricher returned from LogContext.Clone(), so that you can then extract the log event's properties, could work. HTH!

[jamescrosswell]

If you're using the exception filter trick to capture the state at the point the exception was thrown, constructing a throwaway LogEvent (perhaps reusing a [ThreadStatic] one to save on allocations) and calling the enricher returned from LogContext.Clone(), so that you can then extract the log event's properties, could work. HTH!

Thanks @nblumhardt, that might work. I guess it's only a bit more hacky than what we're doing to sync the scope in the MEL integration 😜

@bitsandfoxes what are your thoughts? We'd probably need to build Serilog event/transaction processors to do this (could refactor it into an Enricher)... and then come up with a simple way to register these (perhaps by default) with the Serilog integration.

[jamescrosswell]

@bitsandfoxes what are your thoughts? We'd probably need to build Serilog event/transaction processors to do this (could refactor it into an Enricher)... and then come up with a simple way to register these (perhaps by default) with the Serilog integration.

Needs a decision on this before we implement:

• https://github.com/getsentry/sentry-dotnet/issues/843#issuecomment-2309193929

[bruno-garcia]

We'd probably need to build Serilog event/transaction processors to do this (could refactor it into an Enricher)... and then come up with a simple way to register these (perhaps by default) with the Serilog integration.

Serilog is the most popular logging lib in .NET, imo it's worth the try