Skip to content

Writing OpenTelemetry traces to Serilog logs #41

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Draft
wants to merge 2 commits into
base: dev
Choose a base branch
from
Draft

Writing OpenTelemetry traces to Serilog logs #41

wants to merge 2 commits into from

Conversation

srogovtsev
Copy link

This is not supposed to be merged, this is just an proof of concept I've mentioned in #34 (comment). Everything before 2bc12c7 is just a set-up.

To reiterate, the premise is the same as in #18:

  • we have an application that uses Serilog for logging and OpenTelemetry for tracing
  • some parts of application want to provide more readable logs for operations, so we used SerilogTimings, and now we want these operations to end up in the OpenTelemetry too, so we want to use SerilogTracing
  • we have a dependencies that are Serilog-independent, but are OpenTelemetry-compliant (and maybe use Microsoft.Extensions.Logging for its logs, but it really doesn't matter), so we want their traces to end up in our logs as well, preferably in the same format as SerilogTracing

So, the idea is simple: because we already use OpenTelemetry, and we happen to prefer its instrumentation for some dependencies we use, why don't we create an OpenTelemetry exporter that would output the traces captured by OpenTelemetry into Serilog logs? This allows us to avoid the configuration issues discussed in #34 and still get the nice logs we love Serilog for.

(there might be issues when combining OLTP logs and traces, but we'll get there when we get there)

Here's the example configuration (notice the lack of TracingConfiguration from SerilogTracing):

using var logger = new LoggerConfiguration()
    .WriteTo.Console(Formatters.CreateConsoleTextFormatter(TemplateTheme.Literate))
    .CreateLogger();

using var tracerProvider = Sdk.CreateTracerProviderBuilder()
    .AddSource(programSourceName)
    .AddSource(Worker.ActivitySourceName)
    .AddSource("Serilog")
    .AddSerilogExporter(logger)
    .Build();

And here's the output:

[10:34:34 INF] │ Started
[10:34:34 INF] │ Worker ba17449e-57c2-4846-88cb-8a74ceee5884 was run
[15:34:34 INF] ├ Worker Run (20.493 ms)                             
[10:34:34 INF] │ Worker 94195d81-2e3a-4e37-8a24-2a271d44ee5d was run
[15:34:34 INF] ├ Worker Run (0.135 ms)                              
[10:34:34 INF] │ Finished                                           
[15:34:34 INF] ├ Serilog root (63.577 ms)                           
[15:34:34 INF] └─ <Main>$ (71.676 ms)

@srogovtsev srogovtsev mentioned this pull request Jan 24, 2024
Closed
@srogovtsev srogovtsev force-pushed the feature/opentelemetry-integration-poc branch from 3f6b24a to 4ca0f31 Compare February 4, 2024 18:30
@srogovtsev
Copy link
Author

srogovtsev commented Feb 4, 2024 •
edited
Loading

@nblumhardt, I've updated this PoC with a few tests and a (very) small refactoring to SerilogTracing to show the minimal changes required to allow this functionality. Basically, we only need to expose a common activity writing method (I've decided to encapsulate it in a class as I expect there to be some configuration if we decide to move on with this), and then we get the OpenTelemetry front working with Serilog backend practically for free. Of course there's a lot of writing to be done on the exporter side to support the functionality expected by OpenTelemetry users, but that's fairly trivial.

(I've decided to move the discussion here to avoid bloating #34)

@nblumhardt
Copy link
Collaborator

Thanks for the update @srogovtsev. We'll need some time to think though this approach, we're currently pushing on the core abstractions/API and will loop back to this once we have a bit more of the picture in view 👍

@srogovtsev
Copy link
Author

I put this out precisely so that you could consider this use case when pushing the core. Thanks!

@nblumhardt
Copy link
Collaborator

Sorry, I should have been more specific - we've run over the scenario in your PR, we're just not sure what the shape of the solution might be :-)

@srogovtsev
Copy link
Author

This is totally fine by me!

@nblumhardt
Copy link
Collaborator

Hi Sergei, hope all's well.

Just checking in, we've reviewed this scenario and don't think we'll provide an API directly for this, but there should still be a fairly straightforward way to do what you're after by relying on SerilogTracing conventions and implementing your own mapping from Activity to LogEvent based on those.

Keen to help unblock anything you hit if you still want to do something along these lines, just let me know.

@srogovtsev
Copy link
Author

Hi, Nicholas, thank you for following up.

While I'm still thinking in this direction, right now my main concern is that if the logging pipeline itself produces some activities (big example would be any sink using HttpClient when HttpClient instrumentation is on) we might end up in a feedback loop.

Would you happen to have some recommendations on this? I know that, for example, Serilog.Sinks.Seq just suppresses the instrumentation (on some frameworks), but we do not control the sinks that we use (user can add their own in the configuration file).

@nblumhardt
Copy link
Collaborator

Thanks for the follow-up, Sergei. Right now, unfortunately, there's no generic way to suppress instrumentation in arbitrary Serilog sinks.

This could almost be achieved using a sink wrapper (set an AsyncLocal to suppress instrumentation when constructing the sink and when writing to it), but the batched Serilog sinks take explicit steps to clear the execution context before starting the background tasks that would be responsible for making HTTP requests... 🤔

The problem is really a Serilog one, in that it applies to sinks that generate logs just as much as those that generate traces - it's just that it's easier to implicitly/unknowingly generate traces. It'd be reasonable to propose an upstream solution in Serilog, but I'll raise a new ticket here until we have some idea of what a solution (if any) would look like.

@nblumhardt nblumhardt mentioned this pull request Jun 13, 2024
Open
@srogovtsev
Copy link
Author

Yes, batching was the first problem I thought of.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@srogovtsev @nblumhardt