manigandham / serilog-sinks-googlecloudlogging

Serilog sink that writes events to Google Cloud Logging
MIT License
43 stars 26 forks source link

Trace fields are seems to be incorrect #44

Closed StasPerekrestov closed 3 years ago

StasPerekrestov commented 3 years ago

Hello, I've found out that according to

https://cloud.google.com/trace/docs/trace-log-integration

traces should have the following format projects/[PROJECT_ID]/traces/[TRACE_ID] however, in LogFormatter.cs code

private void CheckForSpecialProperties(LogEntry log, string key, string value)
{
    if (_useSourceContextAsLogName && key.Equals("SourceContext", StringComparison.OrdinalIgnoreCase))
        log.LogName = CreateLogName(_projectId, value);

    if (_useLogCorrelation)
    {
        if (key.Equals("TraceId", StringComparison.OrdinalIgnoreCase))
            log.Trace = $"projects/{_projectId}/traces/{key}";

        if (key.Equals("SpanId", StringComparison.OrdinalIgnoreCase))
            log.SpanId = key;
    }
}

produces Trace references like projects/vitupay-oos/traces/TraceId SpanIds are also suspicious.

As I understand, it should be

  log.Trace = $"projects/{_projectId}/traces/{value}";
...
  log.SpanId = value;
StasPerekrestov commented 3 years ago

Basically, it results in image

manigandham commented 3 years ago

thanks for reporting @StasPerekrestov

fixed now in version 3.3.3: https://www.nuget.org/packages/Serilog.Sinks.GoogleCloudLogging/3.3.3

StasPerekrestov commented 3 years ago

Thank you so much!

arakis commented 3 years ago

In my initial PR, i used that piece of code (works / tested):

// Maybe we could cache this, but the traceId will change often
entry.Trace = $"projects/{_projectId}/traces/{traceId.StringValue}";
propStruct.Fields.Remove("TraceId");
...
entry.SpanId = spanId.StringValue;
propStruct.Fields.Remove("SpanId");

It seems, it went broken after merge & refactor: https://github.com/manigandham/serilog-sinks-googlecloudlogging/commit/613938d031e486dee7abf8b5185f7cce7844e621#diff-b9ef05e354948587d0455408b01f2475f65ce64fee7c14b70d27f855b330ba2cR170

But glad to see, that @manigandham fixed that so fast :-)

Thanks!! :-)

StasPerekrestov commented 3 years ago

I'm not sure if it should be part of this repository, there is an option to get information logs in GCP Trace List using IManagedTracer.

It's something that doesn't work for me because of: https://github.com/serilog/serilog-aspnetcore/issues/207

Also, please note there are some behavioral differences between asp.net core 3.1 and 5.0, which should be taken into consideration.

internal class GoogleTraceActivityEnricher : ILogEventEnricher
    {
        private readonly IHttpContextAccessor _httpContextAccessor;

        public GoogleTraceActivityEnricher(IHttpContextAccessor httpContextAccessor)
        {
            _httpContextAccessor = httpContextAccessor;
        }

        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
        {
            HttpContext? ctx = _httpContextAccessor.HttpContext;
            if (ctx == null)
            {
                Activity? activity = Activity.Current;

                if (activity != null)
                {
                    //..fallback: grab values from Activity: TraceId, SpanId, ParentId
                }
            }
            else
            {
                var managedTracer = ctx.RequestServices.GetRequiredService<IManagedTracer>();
                string? traceId = managedTracer.GetCurrentTraceId();
                ulong? spanId = managedTracer.GetCurrentSpanId();
                //in .net 3.1 TraceId/SpanId are propagated automatically and we need to override it with Google TraceId 
                if (traceId != null)
                {
                    logEvent.AddOrUpdateProperty(new LogEventProperty("TraceId", new ScalarValue(traceId)));
                }
                if (spanId != null)
                {
                    logEvent.AddOrUpdateProperty(new LogEventProperty("SpanId", new ScalarValue(spanId)));
                }
            }
        }
    }

@manigandham FYI :)

manigandham commented 3 years ago

Hey @StasPerekrestov

This repo is just for the sink which sends the logs to GCP. Adding the activity ids is the responsibility of the upstream logging provider. It's only an issue because serilog doesn't (yet) use LoggerExternalScopeProvider but you can already add the enricher to handle that: https://github.com/RehanSaeed/Serilog.Enrichers.Span

StasPerekrestov commented 3 years ago

Yeah, sorry, I perhaps confused you. I referenced the issue just to illustrate why some workarounds exist in the code above.

If I use UseGoogleTrace extension method from Google SDK to add tracing middleware, it doesn't correlate logs with Google Traces. As a result, I used the above code (it uses IManagedTracer) to propagate Google's TraceId and SpanId into Logs.

it allows seeing information logs in Trace List:

image