Log are finally useful… for debugging tracing errors

By now, you’re probably aware of my feelings towards logs, or more specifically logs created by your application. That said, I’ve finally found a use for them!

Why do I hate logs?

The short answer is I don’t. The longer version is that I don’t see any use for logs generated from your application when you can have Spans and Traces instead which provide much richer context and are structured by default.

Logs hail from a world where we were using single servers, and we were viewing logs using `tail -f` or at the very least we were reading them as humans and not aggregating them. Times have moved on and we’re in a world where we have multiple servers, most of which we don’t access directly. We’re in a world where aggregation is the default, where we query logs at scale and therefore structuring them is the default. Finally, we’re in a world where a single user request has to traverse a complex tree of microservices living on different servers, with different code bases, and sometimes in different languages. Logs just don’t cut it.

I would also add that the large data volumes required for logs are costing organizations massive sums of money. So why wouldn’t we look for better?

That’s why traces are far superior:

• Built for machines to interpret
• Correlated by default
• Causation information as standard
• Structured data
• Easy to sample at scale
• Has everything that a log has and more

So everything that you used to use a log for you can, and should, use a Span for. You’ll get all the same things you used to have, and much more. Forget having to keep your LogLevel to Warning as there’s too much data and it’s costing too much. Send spans, sample the ones that are interesting and discard the rest, because errors aren’t the only interesting thing to debug in production.

That doesn’t mean that logs don’t have a use though. As I found out the other day, there’s actually something that they’re really use for, debugging when your traces don’t work!

Debugging Trace configuration in .NET

So the other day I was trying to work out why my trace configuration wasn’t working. I’d set it up like I normally do in .NET, something I’ve done hundreds of times (the job of a DevRel means not working on 1 system but doing mostly PoC and demos, so I think I’m currently up to ConsoleApp1Baggilion). However, I wasn’t getting traces in Honeycomb. So what was the problem?

Here’s the startup code I had:

builder.Services.AddOpenTelemetry()
    .WithTracing(builder => builder
        .AddAspNetCoreInstrumentation()
        .AddOtlpExporter(o => {
            o.Endpoint = new Uri("http://api.honeycomb.io/");
            o.Headers = "x-honeycomb-team=mykey";
        })
    );

Now, the astute among you will see the error immediately, for the rest of you, let me take you on my journey!

OpenTelemetry exporters run in the background, meaning that you won’t see the errors happening in your code. So my code ran fine. My next step was to make sure I’d configured things properly, in that I was actually getting traces. To do that, I added the ConsoleExporter in addition to my OTLP exporter.

builder.Services.AddOpenTelemetry()
    .WithTracing(builder => builder
        .AddAspNetCoreInstrumentation()
        .AddConsoleExporter()
        .AddOtlpExporter(o => {
            o.Endpoint = new Uri("http://api.honeycomb.io/");
            o.Headers = "x-honeycomb-team=mykey";
        })
    );

And behold, I was getting traces. Strange? So, How can I see what the OTLP exporter is doing in the background? This is when I discovered that the .NET OpenTelemetry package uses `EventSource` as it’s debug output, and therefore, we can use that to output to the console when there are errors happening.

The first thing we need to do is create a EventListener that listens to the right source and that accepts an ILogger to send the information to.

public class LoggingOpenTelemetryListener : EventListener
{
    private readonly ILogger<LoggingOpenTelemetryListener> _logger;

    public LoggingOpenTelemetryListener(ILogger<LoggingOpenTelemetryListener> logger)
    {
        _logger = logger;
    }
    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        if (eventSource.Name.StartsWith("OpenTelemetry"))
            EnableEvents(eventSource, EventLevel.Error);
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        _logger.LogWarning(eventData.Message, eventData.Payload?.Select(p => p?.ToString())?.ToArray());
    }
}

Then we need to instantiate that class, and make sure that it’s not disposed. In a Minimal API that as easy as adding this in the `Program.cs`

var builder = WebApplication.CreateBuilder(args);

/// other registrations

builder.Services.AddSingleton<LoggingOpenTelemetryListener>();

// other registrations

var app = builder.Build();

var openTelemetryDebugLogger = app.Services.GetRequiredService<LoggingOpenTelemetryListener>();

// application pipeline

app.Run();

What this does is listen whenever a new `EventSource` is created, and if the name is “OpenTelemetry”, it will listen to the Error events. Whenever an error occurs, the `OnEventWritten` method will be fired. Within there, we get a `Message` property which is actually a template, which we then pass in the payload so that the `Console.WriteLine` can format into the template for us.

So now what did I see in the console?

Exporter failed send data to collector to http://api.honeycomb.io/ endpoint. Data will not be sent. Exception: Grpc.Core.RpcException: Status(StatusCode="DeadlineExceeded", Detail="")

   at Grpc.Net.Client.Internal.HttpClientCallInvoker.BlockingUnaryCall[TRequest,TResponse](Method`2 method, String host, CallOptions options, TRequest request)

   at Grpc.Core.Interceptors.InterceptingCallInvoker.<BlockingUnaryCall>b__3_0[TRequest,TResponse](TRequest req, ClientInterceptorContext`2 ctx)

Progress! We work in IT where seeing a new error message is what counts as progress a lot of the time.

So we can see that we’re hitting a timeout of some description, and that it’s definitely using gRPC. The other thing it gives us is the endpoint that it’s using, so we can make sure it’s using the right one. This is when you can notice that it’s using http instead of https.

Conclusion

It’s actually pretty easy to debug the internals of OpenTelemetry in .NET, and you should be able to set it up pretty easily. It’s really useful for those times where there’s a problem with the configuration of the traces which are the thing that’s important for your application observability. You can add this as a main part of your code and have it always outputting to the console in the case you need to debug.

Why don’t I hate these logs? well there’s no context, no correlation, nothing to trace, it’s an exception that happens out of all the other context, and therefore a log is the right thing here.

In short, use the right things for the right purposes, and for visibility into how your web application is being used, use tracing, not logs.