Draft: Add ActivityEventAttachingLogProcessor to build ActivityEvents from logs in OpenTelemetry.Extensions

[CodeBlanch]

[Moved from #1833]

Fixes #1739

Changes

• Adds a new assembly OpenTelemetry.Extensions
• Adds ActivityEventAttachingLogProcessor which will convert LogRecord objects into ActivityEvent objects on the Activity.Current instance.

Considerations + Design

I wanted to allow users to push details from their ILogger structured logging into their traces but parsing state & scope(s) is an expensive operation. There are also many ways to approach it.

• By default, we won't parse anything.
• If you want to parse state and/or scope(s), it can be turned on via overridable converters. A default converter is provided which will flatten everything into a simple key:value format.

Took inspiration from iSeiryu@c132085 & OpenTracing.Contrib.NetCore.

Public API

New assembly OpenTelemetry.Extensions

// Options for the LogProcessor
public class ActivityEventAttachingLogProcessorOptions
{
        // Callback for converting state into tags.
        public Action<ActivityTagsCollection, IReadOnlyList<KeyValuePair<string, object>>> StateConverter { get; set; } = DefaultLogStateConverter.ConvertState;

        // Callback for converting scopes into tags.
        public Action<ActivityTagsCollection, int, LogRecordScope> ScopeConverter { get; set; } = DefaultLogStateConverter.ConvertScope;
}

// Extension method for registering the LogProcessor
public static OpenTelemetryLoggerOptions AddActivityEventAttachingLogProcessor(
   this OpenTelemetryLoggerOptions loggerOptions,
   Action<ActivityEventAttachingLogProcessorOptions> configure = null)

Examples

Example code:

        [HttpGet]
        public IEnumerable<WeatherForecast> Get()
        {
            // Making an http call here to serve as an example of
            // how dependency calls will be captured and treated
            // automatically as child of incoming request.
            var res = HttpClient.GetStringAsync("http://google.com").Result;
            var rng = new Random();
            var forecast = Enumerable.Range(1, 5).Select(index => new WeatherForecast
            {
                Date = DateTime.Now.AddDays(index),
                TemperatureC = rng.Next(-20, 55),
                Summary = Summaries[rng.Next(Summaries.Length)],
            })
            .ToArray();

            this.logger.LogInformation(
                "WeatherForecasts generated {count}: {forecasts}",
                forecast.Length,
                forecast);

            return forecast;
        }

No state, no scope, no message:

    log [5/6/2021 9:26:20 PM +00:00]
        CategoryName: Examples.AspNetCore.Controllers.WeatherForecastController
        LogLevel: Information

Message, no state, no scope:

    log [5/6/2021 9:27:04 PM +00:00]
        CategoryName: Examples.AspNetCore.Controllers.WeatherForecastController
        LogLevel: Information
        FormattedMessage: WeatherForecasts generated 5: WeatherForecast { Date = 5/7/2021 2:27:04 PM, TemperatureC = -8, TemperatureF = 18, Summary = Freezing }, WeatherForecast { Date = 5/8/2021 2:27:04 PM, TemperatureC = 17, TemperatureF = 62, Summary = Balmy }, WeatherForecast { Date = 5/9/2021 2:27:04 PM, TemperatureC = -3, TemperatureF = 27, Summary = Hot }, WeatherForecast { Date = 5/10/2021 2:27:04 PM, TemperatureC = 30, TemperatureF = 85, Summary = Warm }, WeatherForecast { Date = 5/11/2021 2:27:04 PM, TemperatureC = 32, TemperatureF = 89, Summary = Cool }

State, no scopes, no message:

    log [5/6/2021 9:27:52 PM +00:00]
        CategoryName: Examples.AspNetCore.Controllers.WeatherForecastController
        LogLevel: Information
        state.count: 5
        state.forecasts: WeatherForecast { Date = 5/7/2021 2:27:52 PM, TemperatureC = 53, TemperatureF = 127, Summary = Bracing }, WeatherForecast { Date = 5/8/2021 2:27:52 PM, TemperatureC = -15, TemperatureF = 6, Summary = Sweltering }, WeatherForecast { Date = 5/9/2021 2:27:52 PM, TemperatureC = -3, TemperatureF = 27, Summary = Balmy }, WeatherForecast { Date = 5/10/2021 2:27:52 PM, TemperatureC = 24, TemperatureF = 75, Summary = Chilly }, WeatherForecast { Date = 5/11/2021 2:27:52 PM, TemperatureC = -19, TemperatureF = -2, Summary = Warm }
        state.{OriginalFormat}: WeatherForecasts generated {count}: {forecasts}

State + scopes, no message:

    log [5/6/2021 9:28:42 PM +00:00]
        CategoryName: Examples.AspNetCore.Controllers.WeatherForecastController
        LogLevel: Information
        scope[0].RequestId: 0HM8GQNLJ3QC8:00000001
        scope[0].RequestPath: /WeatherForecast
        scope[0].SpanId: b6ded2efecd77e4f
        scope[0].TraceId: 27b7a492a369f240aafcfdc318547ae7
        scope[0].ParentId: 0000000000000000
        scope[1].ActionId: 8c14f179-2b65-4af4-bdf7-56813379b86c
        scope[1].ActionName: Examples.AspNetCore.Controllers.WeatherForecastController.Get (Examples.AspNetCore)
        scope[2].Id: f10bff66c4ed4e89b6112cbc4d883d51
        scope[2].{OriginalFormat}: {Id}
        state.count: 5
        state.forecasts: WeatherForecast { Date = 5/7/2021 2:28:42 PM, TemperatureC = 20, TemperatureF = 67, Summary = Cool }, WeatherForecast { Date = 5/8/2021 2:28:42 PM, TemperatureC = 46, TemperatureF = 114, Summary = Scorching }, WeatherForecast { Date = 5/9/2021 2:28:42 PM, TemperatureC = 49, TemperatureF = 120, Summary = Cool }, WeatherForecast { Date = 5/10/2021 2:28:42 PM, TemperatureC = -9, TemperatureF = 16, Summary = Hot }, WeatherForecast { Date = 5/11/2021 2:28:42 PM, TemperatureC = 9, TemperatureF = 48, Summary = Cool }
        state.{OriginalFormat}: WeatherForecasts generated {count}: {forecasts}

TODOs

• CHANGELOG.md updated for non-trivial changes
• README.md updated about the feature
• Unit tests
• Design discussion issue Feature Request: Attach log messages to Activity.Events #1739
• Changes in public API reviewed

[codecov]

Codecov Report

Merging #1907 (82b65bb) into main (6cdfcea) will increase coverage by 0.27%.
The diff coverage is n/a.

❗ Current head 82b65bb differs from pull request most recent head 3bbace4. Consider uploading reports for the commit 3bbace4 to get more accurate results

@@            Coverage Diff             @@
##             main    #1907      +/-   ##
==========================================
+ Coverage   83.89%   84.17%   +0.27%     
==========================================
  Files         193      188       -5     
  Lines        6247     6092     -155     
==========================================
- Hits         5241     5128     -113     
+ Misses       1006      964      -42     

Impacted Files	Coverage Δ
...try.Exporter.Jaeger/Implementation/BufferWriter.cs	68.42% <0.00%> (-26.32%)	⬇️
...xporter.Jaeger/Implementation/InMemoryTransport.cs	66.66% <0.00%> (-22.23%)	⬇️
...xporter.OpenTelemetryProtocol/OtlpTraceExporter.cs	47.22% <0.00%> (-20.35%)	⬇️
...rc/OpenTelemetry/Trace/TracerProviderBuilderSdk.cs	89.83% <0.00%> (-10.17%)	⬇️
...emetry.Api/Internal/OpenTelemetryApiEventSource.cs	73.52% <0.00%> (-8.83%)	⬇️
src/OpenTelemetry/Trace/SamplingParameters.cs	69.23% <0.00%> (-7.70%)	⬇️
...ient/Implementation/SqlClientDiagnosticListener.cs	77.94% <0.00%> (-5.16%)	⬇️
src/OpenTelemetry/SuppressInstrumentationScope.cs	95.65% <0.00%> (-4.35%)	⬇️
...ent/Implementation/GrpcClientDiagnosticListener.cs	83.92% <0.00%> (-1.79%)	⬇️
src/OpenTelemetry/Logs/LogRecord.cs	92.50% <0.00%> (-1.35%)	⬇️
... and 33 more

[cijothomas]

curious -is there a need to explicitly add net5.0?

[CodeBlanch]

This is a new project so I figured it would be a good chance to use some of the new tooling. You saw CodeAnalysis.props I'm sure. That file is turning on Microsoft.CodeAnalysis.NetAnalyzers (the successor to Microsoft.CodeAnalysis.FxCopAnalyzers) & nullable reference types. The one bummer with nullable enabled is that VS only properly does analysis for netcoreapp3.1, netstandard2.1, and/or net5.0. If you turn it on for anything older, you get a lot of noise. So I added net5.0 to get proper analysis, it isn't used by any of the code directly. I know that sucks. I just moved it behind a Debug condition, that way it won't be part of the release. Let me know what you think about that.

[cijothomas]

Should we use data.Timestamp even for the exception event?

[CodeBlanch]

You don't think so? It's a log event with an exception added. The timestamp of the log still feels valid to me, but I don't feel strongly about it.

[CodeBlanch]

@cijothomas FYI updated for the log scope changes. Also simplified the default state + scope converters. Looking for some feedback before I continue on with this.

[cijothomas]

The approach and the feature LGTM.
Not marking explicit approval, as PR is draft. We could modify the readme.md in the extensions to document this feature (separate from this PR)

Also there are few unrelated changes to public api analyzers which can be done separately.

[CodeBlanch]

Moved to contrib.