Per-log labels

[EatonZ]

I want to create some custom labels and add them just 1 log entry. After looking through the code in this project, I found a way:

public sealed class RequestInfoLogEntryLabelProvider : HttpLogEntryLabelProvider
{
    public RequestInfoLogEntryLabelProvider(IHttpContextAccessor httpContextAccessor) : base(httpContextAccessor) {}

    protected override void InvokeCore(Dictionary<string, string> labels, HttpContext httpContext)
    {
        var headerValue = httpContext.Request.Headers["TLS-Version"];
        if (StringValues.IsNullOrEmpty(headerValue)) headerValue = "(N/A)";
        labels["tls_version"] = headerValue;
    }
}

It works, but it adds the labels to every log. I don't want that - I just want the labels added to 1 specific log.
I think the best approach would be to let users specify labels in the Log/LogInformation/LogWarning etc calls. That base code is here. You can let the user specify labels through a new param, and then tack those on to what comes back from CreateLabels() further down.

[amanda-tarafa]

We can't add a new parameter to the the GoogleLogger.Log method, this is a method that we are implementing from Microsoft.Extensions.Logging.ILogger. And in any case I don't think there's a need for that.

You can implement conditional label providers, they can be based on HttpContext values or on any other dependency you set up via ASP.NET Core standard dependency injection mechanism. You can see examples of those in UserLogEntryLabelProvider which depends on HttpContext and only adds some labels if there's an authenticated user and EnvironmentNameLogEntryLabelProvider which has a dependency on Microsoft.AspNetCore.Hosting.IHostingEnvironment and sets the aspnetcore_environment if it's present.

Basically, your custom label provider is the one that needs to know when to add a label. If for any reason this approach doesn't work for you do provide more details about your use case and why you can't use the existing label providing mechanism.

[EatonZ]

Hi @amanda-tarafa, adding a condition to my label provider was the first thing I tried, but I wasn't able to because HttpContext doesn't provide enough information.

Here is a quick summary of what I am trying to do:

1. At the beginning of requests, log "Request started" under the "RequestStarted" category name.
2. Associate labels to that log, such as tls_version.
3. Only associate labels to that 1 log, and not others that may come later.

HttpContext does not provide any information about the logging information, so I can't seem to determine whether labels should be added or not. If I could simply check for the "RequestStarted" category, that would be fine, but it doesn't seem like that is possible.

[amanda-tarafa]

No, it's not inmediately possible to check on the entry you are creating the labels for. We could do that possibly.

But, to be honest, I'm not entirely convinced that labeling a log entry is the best way to tackle your use case. What I think I would do is create a trace span at the beginning of the request and label that span with all the info I want. The span will contain all the log entries created within so you know all those lables apply to all those log entries, i.e. to the request in it's entirety. You can see how to do that here.

This is very subjective, and there's no right or wrong, just preferences and context, but adding labels like you are describing to just one entry based on it being the "first", seems off to me. What does that say about the tls_version associated to the rest of the log entries? My point is that when looking at log entries you have to know that a decision was made to add the tls_version only to the first one of each request, and that is not intuitive in my view. If I were to add those labels, I would add them to all the log entries affected or to none. Spans on the other hand, are the ones that mark the start/end of an operation, and adding labels to them that describe that operation makes a lot of sense. Again, this is just my view and you may have any number of constraints or a context that I don't know about, so take this with a pinch of salt.

If labeling spans works for you, great, else, let me know and I can take a look at defining label providers that know about the entry being logged. But just to set expectations, I probably wouldn't be able to get to this in a couple of weeks.

[EatonZ]

Hi @amanda-tarafa, 2 things:

1. It appears a similar request has just come in.

2. I am reconsidering my implementation and had an idea. Instead of creating a new span, I thought maybe I could update the existing/current/parent span, like this:
   tracer.AnnotateSpan(new Dictionary<string, string> { { "Test", "test" } });
   Unfortunately, it doesn't work - no additional labels show up. See below for what span I am referring to. Is the library able to update this span?

[amanda-tarafa]

1. The Log4Net implementation is different from the Diagnostics libraries, first it doens't include tracing, which meand there's no alternative to labeling log entries, and second, as far as I know about it, it doesn't have anything like Diagnostic's label providers, so labels are truly static.

2. That's a case of the Diagnostics trace not being there. The span you are showing was created by the LoadBalancer and we don't have access to it on the Diagnostics library. That load balancer span should contain the Diagnostics span, see how mine looks like:
   

And if I click on the inner span, that's where your label should appear, alongside with the /agent and other labels that we set automatically for all request encompasing spans.

Note also that not all traces are started by the LoadBalancer, some are directly started by Diagnostics, and look as follows. It seems to me that this has to do with the Load Balancer doing sample tracing only (as Diagnostics does by default, with qps = 1) but that's just an assumption on my part, I'm not really familiar with how the Load Balancer works or how to configure it if you wanted it to trace everything.

[EatonZ]

The span you are showing was created by the LoadBalancer and we don't have access to it on the Diagnostics library

Yes - so it's impossible to update it? I thought that since it's "in progress" you could at least add an annotation to it.

[amanda-tarafa]

The span you are showing was created by the LoadBalancer and we don't have access to it on the Diagnostics library

Yes - so it's impossible to update it? I thought that since it's "in progress" you could at least add an annotation to it.

Not through the Diagnostics library, we don't modify spans that we don't create and we almost certainly don't want to do so. Also, think that in this particular case, you would be setting application specific information on a Load Balancer span, which might be a little unexpected.
In Diagnostics if we are sampling a trace, we already create a span at the start of the request, in our middleware, and that one you can annotate.

In any case, if you really want to annotate and external span, you could do it using the Google.Cloud.Trace.v1 library directly, you could inspect the header, get the trace ID, and use the library to fetch the load balancer span and patch it.

[EatonZ]

In Diagnostics if we are sampling a trace, we already create a span at the start of the request, in our middleware, and that one you can annotate.

You're right. I just tested, and it worked.
This is a sufficient solution for me, so I will close this now. Thank you for the suggestions and insight.😁

[EatonZ]

Oh, this is unfortunate. Turns out those labels in the span don't show up in the Cloud Console Logs Viewer. Only Trace list.
This solution will not work as I need to be able to filter by TLS Version and several other fields I am adding, which was why I was adding a log entry in the first place - to be able to filter.
I think my original suggestion should still stand, unless you have another suggestion.

[amanda-tarafa]

Traces can be filtered as well based on the span labels, see below, with the added benefit, in my view, that you can see everything, traces and logs, in one screen.

If you still want to be able to add labels to specific log entries, I can look into adding this feature, but, to set expectations, we won't be able to look/work on this for a couple of weeks.

[EatonZ]

@amanda-tarafa Thanks for that. I think that will work for now, but I'd still like this for logs, so I can do all filtering in one place.

I will await your update in a few weeks.🙂