Async Sink Flush Issue with Exception Rethrow

[willbush]

Description

Something about how Serilog or one of the sinks handles the rethrow (in the catch block) causes Log.CloseAndFlush() to not flush.

Not sure if I should report this as an issue here or the one of the sinks.

Reproduction

using Serilog;

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

try
{
    Serilog.Debugging.SelfLog.Enable(Console.WriteLine);
    Log.Information("Hello!");
    throw new Exception("hi");
}
catch (Exception ex)
{
    Log.Fatal(ex, "Error");
    throw;
}
finally
{
    Log.CloseAndFlush();
}

test-serilog.csproj:

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

  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFramework>net8.0</TargetFramework>
    <RootNamespace>test_serilog</RootNamespace>
    <ImplicitUsings>enable</ImplicitUsings>
    <Nullable>enable</Nullable>
  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="Serilog" Version="3.1.1" />
    <PackageReference Include="Serilog.Sinks.Async" Version="1.5.0" />
    <PackageReference Include="Serilog.Sinks.Console" Version="5.0.1" />
    <PackageReference Include="Serilog.Sinks.File" Version="5.0.0" />
  </ItemGroup>

</Project>

output:

test-serilog on  main [?] via .NET v8.0.201 🎯 net8.0
❯ dotnet run
Unhandled exception. [System.Exception: hi
   at Program.<Main>$(String[] args) in /home/will/code/test-serilog/Program.cs:line 11

Change the following:

@@ -17,5 +17,5 @@ catch (Exception ex)
 }
 finally
 {
-   Log.CloseAndFlush();
+   await Log.CloseAndFlushAsync();
 }

output becomes:

test-serilog on  main [?] via .NET v8.0.201 🎯 net8.0
❯ dotnet run
[16:44:33 INF] Hello!
[16:44:33 FTL] Error
System.Exception: hi
   at Program.<Main>$(String[] args) in /home/will/code/test-serilog/Program.cs:line 11
Unhandled exception. System.Exception: hi
   at Program.<Main>$(String[] args) in /home/will/code/test-serilog/Program.cs:line 11
   at Program.<Main>$(String[] args) in /home/will/code/test-serilog/Program.cs:line 21
   at Program.<Main>(String[] args)

Change it back to using Log.CloseAndFlush(); and remove the throw;:

@@ -13,7 +13,6 @@ try
 catch (Exception ex)
 {
    Log.Fatal(ex, "Error");
-   throw;
 }
 finally
 {

And it also works.

❯ dotnet run
[16:45:45 INF] Hello!
[16:45:45 FTL] Error
System.Exception: hi
   at Program.<Main>$(String[] args) in /home/will/code/test-serilog/Program.cs:line 11

Only seems to be an issue with Async sink. I've only tested Async Console.

Expected behavior

I expected Log.CloseAndFlush() to flush the log in a finally block despite a rethrown exception.

Relevant package, tooling and runtime versions

Package versions are in the csproj file above.

❯ dotnet --info
.NET SDK:
 Version:           8.0.201
 Commit:            4c2d78f037
 Workload version:  8.0.200-manifests.3097af8b

Runtime Environment:
 OS Name:     nixos
 OS Version:  24.05
 OS Platform: Linux
 RID:         linux-x64
 Base Path:   /nix/store/dh9gg36zckspv5isph8lwfw50fc2bbsc-dotnet-sdk-8.0.201/sdk/8.0.201/

.NET workloads installed:
There are no installed workloads to display.

Host:
  Version:      8.0.2
  Architecture: x64
  Commit:       1381d5ebd2

.NET SDKs installed:
  7.0.406 [/nix/store/rck91567galfwgah5302gz7l6il7gy9v-dotnet-core-combined/sdk]
  8.0.201 [/nix/store/rck91567galfwgah5302gz7l6il7gy9v-dotnet-core-combined/sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.App 7.0.16 [/nix/store/rck91567galfwgah5302gz7l6il7gy9v-dotnet-core-combined/shared/Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 8.0.2 [/nix/store/rck91567galfwgah5302gz7l6il7gy9v-dotnet-core-combined/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 7.0.16 [/nix/store/rck91567galfwgah5302gz7l6il7gy9v-dotnet-core-combined/shared/Microsoft.NETCore.App]
  Microsoft.NETCore.App 8.0.2 [/nix/store/rck91567galfwgah5302gz7l6il7gy9v-dotnet-core-combined/shared/Microsoft.NETCore.App]

Other architectures found:
  None

Environment variables:
  DOTNET_ROOT       [/nix/store/rck91567galfwgah5302gz7l6il7gy9v-dotnet-core-combined]

global.json file:
  Not found

Learn more:
  https://aka.ms/dotnet/info

Download .NET:
  https://aka.ms/dotnet/download

Additional context

[willbush]

Note a workaround, that removes the rethrow, is to return 1; in the exception block and return 0 after the finally. That way in Docker containers and Kubernetes can make use of the error exit code.

for example:

kubectl describe pod <pod_name>

State:      Terminated
  Reason:   Error
  Exit Code: 1
  ...

[nblumhardt]

Interesting! Thanks for the report. At first glance it appears most likely to be a race somewhere in Serilog.Sinks.Async, I'll shift the issue over to that repo.

We've done some work recently to move Serilog.Sinks.PeriodicBatching over to System.Threading.Channels, and freshly explored all of these kinds of scenarios, so it may be a good time for us to consider doing similar work in Async as well... 🤔

[nblumhardt]

My first glance impressions were wrong, this is just a case of Exception.StackTrace being mutable, and being changed by the rethrow while asynchronously read by the target sink.

The general problem of snapshotting exceptions is something I'm keen to explore further, for this sink and for the built-in batching mechanism in Serilog 4. Will leave this open as a reminder.