Add ActivityEventAttachingLogProcessor to build ActivityEvents from logs #1833

CodeBlanch · 2021-02-16T07:24:11Z

Changes

Exposes scope, message, & parsed state features on LogRecord
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 tags using JSON path style.

Public API

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

public class OpenTelemetryLoggerOptions
{
        // Turns on parsing scopes onto tags. Default: False
        public bool IncludeScopes { get; set; }

        // Turns on calling the formatter. Default: False
        public bool IncludeMessage { get; set; }

        // Turns on parsing state onto tags. Default: False
        public bool ParseStateValues { get; set; }
}

public class LogRecord
{
        // Set to the result of the formatter if IncludeMessage is turned on.
        public string Message { get; }

        // Set to the parsing results if ParseStateValues is turned on.
        public IReadOnlyList<KeyValuePair<string, object>> StateValues { get; }

        // Invoke a callback for each registered scope. Does a no-op if IncludeScopes is turned off.
        public void ForEachScope<TState>(Action<object, TState> callback, TState state)
}

// 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, object> 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,
                new { forecast });

            return forecast;
        }

No state, no scope, no message:

    log [2/20/2021 4:43:17 AM +00:00]
        CategoryName: Examples.AspNetCore.Controllers.WeatherForecastController
        LogLevel: Information

Message, no state, no scope:

    log [2/20/2021 4:44:58 AM +00:00]
        CategoryName: Examples.AspNetCore.Controllers.WeatherForecastController
        LogLevel: Information
        Message: WeatherForecasts generated 5: { forecast = Examples.AspNetCore.Models.WeatherForecast[] }

State, no scopes, no message:

    log [2/16/2021 7:05:58 AM +00:00]
        CategoryName: Examples.AspNetCore.Controllers.WeatherForecastController
        LogLevel: Information
        state.count: 5
        state.forecasts.forecast[0].Date: 2/16/2021 11:05:58 PM
        state.forecasts.forecast[0].TemperatureC: 0
        state.forecasts.forecast[0].TemperatureF: 32
        state.forecasts.forecast[0].Summary: Scorching
        state.forecasts.forecast[1].Date: 2/17/2021 11:05:58 PM
        state.forecasts.forecast[1].TemperatureC: 9
        state.forecasts.forecast[1].TemperatureF: 48
        state.forecasts.forecast[1].Summary: Cool
        state.forecasts.forecast[2].Date: 2/18/2021 11:05:58 PM
        state.forecasts.forecast[2].TemperatureC: 30
        state.forecasts.forecast[2].TemperatureF: 85
        state.forecasts.forecast[2].Summary: Warm
        state.forecasts.forecast[3].Date: 2/19/2021 11:05:58 PM
        state.forecasts.forecast[3].TemperatureC: 22
        state.forecasts.forecast[3].TemperatureF: 71
        state.forecasts.forecast[3].Summary: Scorching
        state.forecasts.forecast[4].Date: 2/20/2021 11:05:58 PM
        state.forecasts.forecast[4].TemperatureC: 20
        state.forecasts.forecast[4].TemperatureF: 67
        state.forecasts.forecast[4].Summary: Warm
        Format: WeatherForecasts generated {count}: {forecasts}

State + scopes, no message:

    log [2/16/2021 7:06:35 AM +00:00]
        CategoryName: Examples.AspNetCore.Controllers.WeatherForecastController
        LogLevel: Information
        scope[0].RequestId: 0HM6I95IH48G6:00000001
        scope[0].RequestPath: /WeatherForecast
        scope[0].SpanId: 32e6c7f36149bb49
        scope[0].TraceId: aa7f050d5657fd45a1e0d9b1e1e79ae0
        scope[0].ParentId: 0000000000000000
        scope[1].ActionId: 4e593297-71c2-4164-afcf-52b0af85c4d9
        scope[1].ActionName: Examples.AspNetCore.Controllers.WeatherForecastController.Get (Examples.AspNetCore)
        state.count: 5
        state.forecasts.forecast[0].Date: 2/16/2021 11:06:35 PM
        state.forecasts.forecast[0].TemperatureC: -5
        state.forecasts.forecast[0].TemperatureF: 24
        state.forecasts.forecast[0].Summary: Chilly
        state.forecasts.forecast[1].Date: 2/17/2021 11:06:35 PM
        state.forecasts.forecast[1].TemperatureC: -2
        state.forecasts.forecast[1].TemperatureF: 29
        state.forecasts.forecast[1].Summary: Chilly
        state.forecasts.forecast[2].Date: 2/18/2021 11:06:35 PM
        state.forecasts.forecast[2].TemperatureC: 30
        state.forecasts.forecast[2].TemperatureF: 85
        state.forecasts.forecast[2].Summary: Chilly
        state.forecasts.forecast[3].Date: 2/19/2021 11:06:35 PM
        state.forecasts.forecast[3].TemperatureC: 51
        state.forecasts.forecast[3].TemperatureF: 123
        state.forecasts.forecast[3].Summary: Sweltering
        state.forecasts.forecast[4].Date: 2/20/2021 11:06:35 PM
        state.forecasts.forecast[4].TemperatureC: 15
        state.forecasts.forecast[4].TemperatureF: 58
        state.forecasts.forecast[4].Summary: Warm
        Format: WeatherForecasts generated {count}: {forecasts}

TODOs

CHANGELOG.md updated for non-trivial changes
Unit tests
Design discussion issue Feature Request: Attach log messages to Activity.Events #1739 [Performance] Boxing in OpenTelemetryLogger #1834
Changes in public API reviewed

CodeBlanch · 2021-02-16T07:25:44Z

Wanted to get feedback before starting on tests.

examples/AspNetCore/appsettings.json

reyang · 2021-02-16T18:28:46Z

src/OpenTelemetry/Logs/OpenTelemetryLoggerProvider.cs

        }

        public ILogger CreateLogger(string categoryName)
        {
-            lock (this.loggers)
+            if (!this.loggers.TryGetValue(categoryName, out var logger))


Curious - Is this thread safe (e.g. would it be possible to break the internal state of Dictionary if other threads are trying to write to it)? https://stackoverflow.com/questions/6738634/is-this-non-locked-trygetvalue-dictionary-access-thread-safe

Thanks for the tip! Sadly I have this pattern in a bunch of places I now need to go fix up 😭 I updated the code to use a ConcurrentDictionary instead. Check it out, LMK if it looks better now. I think it's worth avoiding the lock here because a lot of threads could all be asking for ILoggers/writing messages at the same time?

reyang · 2021-02-16T18:33:13Z

src/OpenTelemetry/Logs/ActivityEventAttachingLogProcessor.cs

+
+namespace OpenTelemetry.Logs
+{
+    internal class ActivityEventAttachingLogProcessor : BaseProcessor<LogRecord>


I'm struggling with this name, meanwhile I don't have a good proposal...

Ya I know it's a mouthful. Open to suggestions.

open-telemetry/opentelemetry-specification#1461
This PR suggests that span events are conceptually the same as logs.

I guess we could consider something like this?

TracerProvider.LogRecordToActivityEventProcessor() (inherited from LogProcessor): Converts LogRecord to ActivityEvent, and uses Activity.AddEvent to attach it to the current Activity. If there there is no "current activity", this processor will simply ignore the log record.

LoggerProvider.ActivityEventToLogRecordProcessor(logger) (inherited from ActivityProcessor): Converts the ActivityEvents objects to LogRecords.

reyang

LGTM once we've confirmed the thread-safety in the double-lock dictionary code https://github.com/open-telemetry/opentelemetry-dotnet/pull/1833/files#r577044684.

reyang · 2021-02-16T18:37:32Z

One design question that we might need to consider - there might be a scenario where the user wants to convert Activity events to logs (e.g. underlying distributed tracing system does not support Activity event). We might need to avoid the infinite loop if folks misconfigured the SDK to convert logs to activity events AND activity events to logs.

Since there will be requirements to convert logs to traces, traces to logs, logs to metrics and metrics to logs, we might need to plan ahead-of-time:

What would be the ideal namespace and class names (e.g. should the log-to-trace converter belong to logs namespace or trace namespace or neither).
How do we configure them.

src/OpenTelemetry/Logs/OpenTelemetryLoggingExtensions.cs

examples/AspNetCore/Program.cs

codecov · 2021-02-20T04:42:11Z

Codecov Report

Merging #1833 (d411cf6) into main (cb066cb) will decrease coverage by 1.98%.
The diff coverage is 55.22%.

@@            Coverage Diff             @@
##             main    #1833      +/-   ##
==========================================
- Coverage   83.77%   81.79%   -1.99%     
==========================================
  Files         187      190       +3     
  Lines        5967     6213     +246     
==========================================
+ Hits         4999     5082      +83     
- Misses        968     1131     +163

Impacted Files	Coverage Δ
...lemetry/Logs/ActivityEventAttachingLogProcessor.cs	`0.00% <0.00%> (ø)`
.../Logs/ActivityEventAttachingLogProcessorOptions.cs	`0.00% <0.00%> (ø)`
src/OpenTelemetry/Logs/DefaultLogStateConverter.cs	`0.00% <0.00%> (ø)`
...enTelemetry/Logs/OpenTelemetryLoggingExtensions.cs	`50.00% <0.00%> (-35.72%)`	⬇️
src/OpenTelemetry/Logs/OpenTelemetryLogger.cs	`26.82% <20.54%> (-44.60%)`	⬇️
...nTelemetry/Internal/OpenTelemetrySdkEventSource.cs	`70.00% <40.00%> (-1.77%)`	⬇️
src/OpenTelemetry/Logs/LogRecord.cs	`82.50% <77.77%> (-5.00%)`	⬇️
.../OpenTelemetry/Logs/OpenTelemetryLoggerProvider.cs	`77.55% <88.23%> (+7.09%)`	⬆️
src/OpenTelemetry/Trace/TracerProviderSdk.cs	`95.16% <98.64%> (+4.38%)`	⬆️
...metryProtocol/Implementation/ActivityExtensions.cs	`86.89% <100.00%> (+0.05%)`	⬆️
... and 27 more

CodeBlanch · 2021-02-20T04:57:36Z

@reyang

One design question that we might need to consider - there might be a scenario where the user wants to convert Activity events to logs (e.g. underlying distributed tracing system does not support Activity event). We might need to avoid the infinite loop if folks misconfigured the SDK to convert logs to activity events AND activity events to logs.

Since there will be requirements to convert logs to traces, traces to logs, logs to metrics and metrics to logs, we might need to plan ahead-of-time:

What would be the ideal namespace and class names (e.g. should the log-to-trace converter belong to logs namespace or trace namespace or neither).

How do we configure them.

This is all good stuff I have been thinking about and don't have an immediate answer to/for! I am setting the ActivityEvent.Name to "log" so it would be easy to filter them out going the other direction (ActivityEvent->LogRecord). Although I think you were getting at building something more like what we have for suppressing downstream instrumentation?

reyang · 2021-02-22T05:07:59Z

src/OpenTelemetry/Logs/OpenTelemetryLoggerProvider.cs


-                if (this.loggers.TryGetValue(categoryName, out logger))
+                if (this.loggers.TryAdd(categoryName, logger))


Do we know if this.loggers.TryGetValue(categoryName, out var logger) will always succeed when TryAdd failed?
If yes, the code can be simplified by returning this.loggers[categoryName] (and avoid the while-loop).
If no, perhaps store the logger locally to avoid creating multiple instances in the loop?

@reyang I updated it (again) to use Hashtable. @mconnew just pointed out to me that Hashtable has unique thread safety gurantees which make it useful for caching scenarios.

Looks great! 💯

reyang

LGTM.

…h/opentelemetry-dotnet into logs-to-activityevents

CodeBlanch added 2 commits February 15, 2021 11:08

Added ActivityEventAttachingLogProcessor.

69eabf1

Testing and tweaks.

4fde024

CodeBlanch requested a review from a team February 16, 2021 07:24

CodeBlanch added the pr:do-not-merge label Feb 16, 2021

reyang reviewed Feb 16, 2021

View reviewed changes

examples/AspNetCore/appsettings.json Outdated Show resolved Hide resolved

reyang reviewed Feb 16, 2021

View reviewed changes

reyang approved these changes Feb 16, 2021

View reviewed changes

cijothomas reviewed Feb 17, 2021

View reviewed changes

src/OpenTelemetry/Logs/OpenTelemetryLoggingExtensions.cs Outdated Show resolved Hide resolved

cijothomas reviewed Feb 17, 2021

View reviewed changes

examples/AspNetCore/Program.cs Outdated Show resolved Hide resolved

CodeBlanch added 2 commits February 19, 2021 20:30

State parsing and code review.

0725ae6

Code review.

8c505e3

Merge branch 'main' into logs-to-activityevents

c78c50a

CodeBlanch mentioned this pull request Feb 20, 2021

[Performance] Boxing in OpenTelemetryLogger #1834

Closed

reyang self-requested a review February 22, 2021 05:04

reyang reviewed Feb 22, 2021

View reviewed changes

reyang approved these changes Feb 22, 2021

View reviewed changes

cijothomas and others added 6 commits February 22, 2021 10:11

Merge branch 'main' into logs-to-activityevents

7367ea5

Switch to Hashtable for OpenTelemetryLoggerProvider logger cache.

28d77ec

Merge from main.

36e3722

Merge branch 'logs-to-activityevents' of https://github.com/CodeBlanc…

79c6bf8

…h/opentelemetry-dotnet into logs-to-activityevents

Fixed enumerator.

94bf100

Merge branch 'main' into logs-to-activityevents

f940610

CodeBlanch mentioned this pull request Mar 6, 2021

Logs: Support parsing State & Scopes and capture of formatted Message #1869

Merged

4 tasks

reyang mentioned this pull request Mar 7, 2021

Remove options, stick with builder #1875

Merged

3 tasks

CodeBlanch mentioned this pull request Mar 14, 2021

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

Closed

5 tasks

CodeBlanch closed this Mar 14, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add ActivityEventAttachingLogProcessor to build ActivityEvents from logs #1833

Add ActivityEventAttachingLogProcessor to build ActivityEvents from logs #1833

CodeBlanch commented Feb 16, 2021 •

edited

Loading

CodeBlanch commented Feb 16, 2021

reyang Feb 16, 2021

CodeBlanch Feb 20, 2021

reyang Feb 16, 2021

CodeBlanch Feb 20, 2021

reyang Feb 28, 2021

reyang left a comment

reyang commented Feb 16, 2021 •

edited

Loading

codecov bot commented Feb 20, 2021 •

edited

Loading

CodeBlanch commented Feb 20, 2021

reyang Feb 22, 2021 •

edited

Loading

CodeBlanch Feb 28, 2021

reyang Feb 28, 2021

reyang left a comment


		if (this.loggers.TryGetValue(categoryName, out logger))
		if (this.loggers.TryAdd(categoryName, logger))

Add ActivityEventAttachingLogProcessor to build ActivityEvents from logs #1833

Add ActivityEventAttachingLogProcessor to build ActivityEvents from logs #1833

Conversation

CodeBlanch commented Feb 16, 2021 • edited Loading

Changes

Considerations + Design

Public API

Examples

TODOs

CodeBlanch commented Feb 16, 2021

reyang Feb 16, 2021

Choose a reason for hiding this comment

CodeBlanch Feb 20, 2021

Choose a reason for hiding this comment

reyang Feb 16, 2021

Choose a reason for hiding this comment

CodeBlanch Feb 20, 2021

Choose a reason for hiding this comment

reyang Feb 28, 2021

Choose a reason for hiding this comment

reyang left a comment

Choose a reason for hiding this comment

reyang commented Feb 16, 2021 • edited Loading

codecov bot commented Feb 20, 2021 • edited Loading

Codecov Report

CodeBlanch commented Feb 20, 2021

reyang Feb 22, 2021 • edited Loading

Choose a reason for hiding this comment

CodeBlanch Feb 28, 2021

Choose a reason for hiding this comment

reyang Feb 28, 2021

Choose a reason for hiding this comment

reyang left a comment

Choose a reason for hiding this comment

CodeBlanch commented Feb 16, 2021 •

edited

Loading

reyang commented Feb 16, 2021 •

edited

Loading

codecov bot commented Feb 20, 2021 •

edited

Loading

reyang Feb 22, 2021 •

edited

Loading