Configuration in UseSerilog causes process to hang in .NET 8

ghost commented 8 months ago

Description While trialing out TraceId and SpanId support on a new Controllers API project I found that the commented out lines of code when enabled are causing the webapi process from running further. It prints a bunch of messages then hangs and Swagger does not show up anymore. However if the code is commented out then everything runs happily and Swagger is shown as per normal and TraceId and SpanId are also printed out as expected.

Reproduction

Create new Controllers API project.

Add the following code and run the project and notice all is good.

builder.Host.UseSerilog((context, services, configuration) => configuration
.ReadFrom.Configuration(context.Configuration)
.ReadFrom.Services(services)
//.Enrich.FromLogContext()
//.WriteTo.Console(new JsonFormatter())
//.WriteTo.Console(new CompactJsonFormatter())
//.WriteTo.Console(new RenderedCompactJsonFormatter())
.WriteTo.Console(outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3} ({TraceId}:{SpanId})] {Message:lj}{NewLine}{Exception}")
.WriteTo.Console(new ExpressionTemplate("[{@t:HH:mm:ss} {@l:u3} ({@tr}:{@sp})] {@m}\n{@x}"))

Now uncomment the above lines and run the project and notice it just hangs after printing a few messages.

Expected behavior Logging should just continue as normal without hanging the process.

Relevant package, tooling and runtime versions

<PackageReference Include="Serilog.AspNetCore" Version="8.0.1" />
<PackageReference Include="Serilog.Expressions" Version="4.0.0" />

Additional context

.NET SDK:
 Version:           8.0.200
 Commit:            438cab6a9d
 Workload version:  8.0.200-manifests.cdf2cc8e

Runtime Environment:
 OS Name:     debian
 OS Version:  
 OS Platform: Linux
 RID:         linux-x64
 Base Path:   /usr/share/dotnet/sdk/8.0.200/

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

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

.NET SDKs installed:
  8.0.200 [/usr/share/dotnet/sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.App 8.0.2 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 8.0.2 [/usr/share/dotnet/shared/Microsoft.NETCore.App]

Other architectures found:
  None

Environment variables:
  Not set

global.json file:
  Not found

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

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

nblumhardt commented 8 months ago

This all works perfectly for me. Is it possible that your IDE is just waiting for some particular terminal output before triggering the opening of a web browser?

If not, running in debug mode and pressing "break" during the hang should reveal what's going on. Keen to hear what you find!

ghost commented 8 months ago

Tested with a brand new minimal api project with only addition of the code below, same problem. This is a debug build and tested both with/without Debugger. However if I add/uncomment WriteTo.Console() then everything starts working as expected. The call stack doesn't reveal anything relevant. Also tried dotnet run through the CLI, same issue.

builder.Host.UseSerilog((context, services, configuration) => configuration
    .ReadFrom.Configuration(context.Configuration)
    .ReadFrom.Services(services)
    .Enrich.FromLogContext()
    //.WriteTo.Console()
    .WriteTo.Console(new JsonFormatter())
    .WriteTo.Console(new CompactJsonFormatter())
    .WriteTo.Console(new RenderedCompactJsonFormatter()));

nblumhardt commented 8 months ago

Interesting! Seems like a process of elimination should start narrowing it down - if you remove one WriteTo block at a time, is one of them in particular a problem?

ghost commented 8 months ago

Yes tested each one of the WriteTo.*JsonFormatter alone and they all exhibit the same behaviour.

nblumhardt commented 8 months ago

How are you assessing whether or not the process hangs? Can you send a web request to the API? If not, what's the behavior?

These are extremely widely-used components with otherwise fairly simple string formatting code in them, so it's unlikely the issue is a simple/direct one. It's more than likely an environmental problem so unfortunately you'll be the only one able to solve this (it's not possible for me without me being able to repro the issue).

Stepping through start-up in the debugger, with "break on all exceptions" enabled, is the way to go I think.

ghost commented 8 months ago

Thanks for the tip, was able to hit Swagger successfully from the browser. Finally made a breakthrough using the info below. Its the way VSCode is matching the url to launch the browser and because we're logging JSON the match is failing hence the reason it works with WriteTo.Console(). Thanks a lot for this awesome library. Will close this as resolved.

serilog / serilog-aspnetcore

Configuration in UseSerilog causes process to hang in .NET 8 #365