Async Sink and distributed tracing

[andreycha]

Hi,

We are using Serilog file sink together with ecs-dotnet formatter which by default populates trace id and span id using current activity.

As soon as we switched to async sink, we've noticed that most of the log entries (but not all) don't have trace id and span id. Which is, I believe, due to the fact that formatter for a log entry might called when log entry's activity has been already finished.

Just wanted to double-check if this is a known behavior and if there is any way to have correct trace id and span id using async sink? Otherwise I'd suggest to explicitly state in the documentation that this sink is not guaranteed to work correctly in the presence of distributed tracing.

Thank you!

[bartelink]

It's the job of the capturing phase to grab all the information and stash it in the LogEvent. e.g. LogContext (and other ExecutionContext-based stuff) is grabbed in the client context. Enrichers run there in too.

There's no flowing of context after that - the details are all considered complete. During the emission phase, the sinks can e.g. add or remove tags etc, but nothing else interesting happens.

So in general I would say that any issue that only surfaces after you wrap in the Async Sink means that something is grabbing information at the wrong point in the flow, which represents a bug on the capture end.

It's also conceivable that the overall log configuration is doing something it shouldn't be doing in the processing phase, which happens to be incompatible with what the Async Sink needs.

But the bottom line is that the Async Sink is extremely Simple, by design (both the design of what it does, and design of Serilog wrt what it's duties/concerns are as a result of the overall layout). The other main point is that there's absolutely a handoff between stuff entering the Async Sink (which stashes it in the queue), vs the consuming end (which is async, and, as it stands is in another thread). Even if the impl of the Sink changed, there would still be no assumption that the thread context would flow through to it (but this also goes for other sinks - if they want to have a series of operations that don't flow context, that's perfectly normal; things are not expected to be synchronous in any way).

[bartelink]

cc @nblumhardt unless you can think of anything I haven't covered?

[nblumhardt]

I think that covers it @bartelink 👍

The ECS formatter could be updated to fix this: LogEvent carries the TraceId and SpanId properties it needs, avoiding the need for capturing anything additional at formatting time.

[andreycha]

@bartelink thank you for an extensive summary!

@nblumhardt while I was debugging the issue, I did notice that LogEvent hadn't had these properties included (otherwise they would show up in the logs even with async sink). However, I could have checked the events already after they went through ECS formatter Afair, Serilog already populates them by default, without the need for additional enricher. So I'd need to check on Monday once again. Will also address this issue in ecs-dotnet!