Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 2 commits into from
Mar 6, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 9 additions & 0 deletions src/OpenTelemetry/.publicApi/net461/PublicAPI.Unshipped.txt
Original file line number Diff line number Diff line change
@@ -1,3 +1,12 @@
OpenTelemetry.Logs.LogRecord.ForEachScope<TState>(System.Action<object, TState> callback, TState state) -> void
OpenTelemetry.Logs.LogRecord.Message.get -> string
OpenTelemetry.Logs.LogRecord.StateValues.get -> System.Collections.Generic.IReadOnlyList<System.Collections.Generic.KeyValuePair<string, object>>
OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeMessage.get -> bool
OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeMessage.set -> void
OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeScopes.get -> bool
OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeScopes.set -> void
OpenTelemetry.Logs.OpenTelemetryLoggerOptions.ParseStateValues.get -> bool
OpenTelemetry.Logs.OpenTelemetryLoggerOptions.ParseStateValues.set -> void
OpenTelemetry.Trace.ParentBasedSampler.ParentBasedSampler(OpenTelemetry.Trace.Sampler rootSampler, OpenTelemetry.Trace.Sampler remoteParentSampled = null, OpenTelemetry.Trace.Sampler remoteParentNotSampled = null, OpenTelemetry.Trace.Sampler localParentSampled = null, OpenTelemetry.Trace.Sampler localParentNotSampled = null) -> void
OpenTelemetry.Trace.TracerProviderOptions
OpenTelemetry.Trace.TracerProviderOptions.SetErrorStatusOnException.get -> bool
Expand Down
Original file line number Diff line number Diff line change
@@ -1,3 +1,12 @@
OpenTelemetry.Logs.LogRecord.ForEachScope<TState>(System.Action<object, TState> callback, TState state) -> void
OpenTelemetry.Logs.LogRecord.Message.get -> string
OpenTelemetry.Logs.LogRecord.StateValues.get -> System.Collections.Generic.IReadOnlyList<System.Collections.Generic.KeyValuePair<string, object>>
OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeMessage.get -> bool
OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeMessage.set -> void
OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeScopes.get -> bool
OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeScopes.set -> void
OpenTelemetry.Logs.OpenTelemetryLoggerOptions.ParseStateValues.get -> bool
OpenTelemetry.Logs.OpenTelemetryLoggerOptions.ParseStateValues.set -> void
OpenTelemetry.Trace.ParentBasedSampler.ParentBasedSampler(OpenTelemetry.Trace.Sampler rootSampler, OpenTelemetry.Trace.Sampler remoteParentSampled = null, OpenTelemetry.Trace.Sampler remoteParentNotSampled = null, OpenTelemetry.Trace.Sampler localParentSampled = null, OpenTelemetry.Trace.Sampler localParentNotSampled = null) -> void
OpenTelemetry.Trace.TracerProviderOptions
OpenTelemetry.Trace.TracerProviderOptions.SetErrorStatusOnException.get -> bool
Expand Down
36 changes: 34 additions & 2 deletions src/OpenTelemetry/Logs/LogRecord.cs
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@

#if NET461 || NETSTANDARD2_0
using System;
using System.Collections.Generic;
using System.Diagnostics;
using Microsoft.Extensions.Logging;

Expand All @@ -26,9 +27,20 @@ namespace OpenTelemetry.Logs
/// </summary>
public sealed class LogRecord
{
internal LogRecord(DateTime timestamp, string categoryName, LogLevel logLevel, EventId eventId, object state, Exception exception)
private readonly IExternalScopeProvider scopeProvider;

internal LogRecord(
IExternalScopeProvider scopeProvider,
DateTime timestamp,
string categoryName,
LogLevel logLevel,
EventId eventId,
string message,
object state,
Exception exception,
IReadOnlyList<KeyValuePair<string, object>> stateValues)
{
this.Timestamp = timestamp;
this.scopeProvider = scopeProvider;

var activity = Activity.Current;
if (activity != null)
Expand All @@ -39,10 +51,13 @@ internal LogRecord(DateTime timestamp, string categoryName, LogLevel logLevel, E
this.TraceFlags = activity.ActivityTraceFlags;
}

this.Timestamp = timestamp;
this.CategoryName = categoryName;
this.LogLevel = logLevel;
this.EventId = eventId;
this.Message = message;
this.State = state;
this.StateValues = stateValues;
this.Exception = exception;
}

Expand All @@ -62,9 +77,26 @@ internal LogRecord(DateTime timestamp, string categoryName, LogLevel logLevel, E

public EventId EventId { get; }

public string Message { get; }

public object State { get; }

public IReadOnlyList<KeyValuePair<string, object>> StateValues { get; }

public Exception Exception { get; }

/// <summary>
/// Executes callback for each currently active scope objects in order
/// of creation. All callbacks are guaranteed to be called inline from
/// this method.
/// </summary>
/// <typeparam name="TState">State.</typeparam>
/// <param name="callback">The callback to be executed for every scope object.</param>
/// <param name="state">The state object to be passed into the callback.</param>
public void ForEachScope<TState>(Action<object, TState> callback, TState state)
{
this.scopeProvider?.ForEachScope(callback, state);
}
}
}
#endif
145 changes: 138 additions & 7 deletions src/OpenTelemetry/Logs/OpenTelemetryLogger.cs
Original file line number Diff line number Diff line change
Expand Up @@ -16,8 +16,9 @@

#if NET461 || NETSTANDARD2_0
using System;
using System.Collections.Generic;
using System.Reflection.Emit;
using System.Runtime.CompilerServices;
using System.Threading;
using Microsoft.Extensions.Logging;

namespace OpenTelemetry.Logs
Expand All @@ -37,19 +38,29 @@ internal OpenTelemetryLogger(string categoryName, OpenTelemetryLoggerProvider pr

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
if (!this.IsEnabled(logLevel))
if (!this.IsEnabled(logLevel) || Sdk.SuppressInstrumentation)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No strong opinion - my personal preference would be splitting this into two "if" statements. In this way it is easier to put breakpoint on the selected return statement instead of putting a condition-breakpoint (which is much slower since it uses debugger expression-evaluation engine).

if (condition1)
{
    return;
}

if (condition2)
{
    return;
}

{
return;
}

if (Sdk.SuppressInstrumentation)
var processor = this.provider.Processor;
if (processor != null)
{
return;
}
var options = this.provider.Options;

var record = new LogRecord(DateTime.UtcNow, this.categoryName, logLevel, eventId, state, exception);
var record = new LogRecord(
options.IncludeScopes ? this.ScopeProvider : null,
DateTime.UtcNow,
this.categoryName,
logLevel,
eventId,
options.IncludeMessage ? formatter(state, exception) : null,
options.ParseStateValues ? null : (object)state,
exception,
options.ParseStateValues ? this.ParseState(state) : null);

this.provider.Processor?.OnEnd(record);
processor.OnEnd(record);
}
}

[MethodImpl(MethodImplOptions.AggressiveInlining)]
Expand All @@ -59,6 +70,126 @@ public bool IsEnabled(LogLevel logLevel)
}

public IDisposable BeginScope<TState>(TState state) => this.ScopeProvider?.Push(state) ?? null;

private IReadOnlyList<KeyValuePair<string, object>> ParseState<TState>(TState state)
{
if (state is IReadOnlyList<KeyValuePair<string, object>>)
{
return StateValueListParser<TState>.ParseStateFunc(state);
}
else if (state is IEnumerable<KeyValuePair<string, object>> stateValues)
{
return new List<KeyValuePair<string, object>>(stateValues);
}
else
{
return new List<KeyValuePair<string, object>>
{
new KeyValuePair<string, object>(string.Empty, state),
};
}
}

private static class StateValueListParser<TState>
{
static StateValueListParser()
{
/* The code below is building a dynamic method to do this...

int count = state.Count;

List<KeyValuePair<string, object>> stateValues = new List<KeyValuePair<string, object>>(count);

for (int i = 0; i < count; i++)
{
stateValues.Add(state[i]);
}

return stateValues;

...so we don't box structs or allocate an enumerator. */

var stateType = typeof(TState);
var listType = typeof(List<KeyValuePair<string, object>>);
var readOnlyListType = typeof(IReadOnlyList<KeyValuePair<string, object>>);

var dynamicMethod = new DynamicMethod(
nameof(StateValueListParser<TState>),
readOnlyListType,
new[] { stateType },
typeof(StateValueListParser<TState>).Module,
skipVisibility: true);

var generator = dynamicMethod.GetILGenerator();

var testLabel = generator.DefineLabel();
var writeItemLabel = generator.DefineLabel();

generator.DeclareLocal(typeof(int)); // count
generator.DeclareLocal(listType); // list
generator.DeclareLocal(typeof(int)); // i

if (stateType.IsValueType)
{
generator.Emit(OpCodes.Ldarga_S, 0); // state
generator.Emit(OpCodes.Call, stateType.GetProperty("Count").GetMethod);
}
else
{
generator.Emit(OpCodes.Ldarg_0); // state
generator.Emit(OpCodes.Callvirt, typeof(IReadOnlyCollection<KeyValuePair<string, object>>).GetProperty("Count").GetMethod);
}

generator.Emit(OpCodes.Stloc_0); // count = state.Count
generator.Emit(OpCodes.Ldloc_0);
generator.Emit(OpCodes.Newobj, listType.GetConstructor(new Type[] { typeof(int) }));
generator.Emit(OpCodes.Stloc_1); // list = new List(count)

generator.Emit(OpCodes.Ldc_I4_0);
generator.Emit(OpCodes.Stloc_2); // i = 0

generator.Emit(OpCodes.Br_S, testLabel);
generator.MarkLabel(writeItemLabel);
generator.Emit(OpCodes.Ldloc_1); // list
if (stateType.IsValueType)
{
generator.Emit(OpCodes.Ldarga_S, 0); // state
}
else
{
generator.Emit(OpCodes.Ldarg_0); // state
}

generator.Emit(OpCodes.Ldloc_2); // i
if (stateType.IsValueType)
{
generator.Emit(OpCodes.Call, stateType.GetProperty("Item").GetMethod);
}
else
{
generator.Emit(OpCodes.Callvirt, readOnlyListType.GetProperty("Item").GetMethod);
}

generator.Emit(OpCodes.Callvirt, listType.GetMethod("Add", new Type[] { typeof(KeyValuePair<string, object>) })); // list.Add(state[i])

generator.Emit(OpCodes.Ldloc_2); // i
generator.Emit(OpCodes.Ldc_I4_1);
generator.Emit(OpCodes.Add); // i++
generator.Emit(OpCodes.Stloc_2);

generator.MarkLabel(testLabel);
generator.Emit(OpCodes.Ldloc_2); // i
generator.Emit(OpCodes.Ldloc_0); // count
generator.Emit(OpCodes.Blt_S, writeItemLabel);

generator.Emit(OpCodes.Ldloc_1); // list
generator.Emit(OpCodes.Ret);

ParseStateFunc = (Func<TState, IReadOnlyList<KeyValuePair<string, object>>>)dynamicMethod.CreateDelegate(typeof(Func<TState, IReadOnlyList<KeyValuePair<string, object>>>));
}

public static Func<TState, IReadOnlyList<KeyValuePair<string, object>>> ParseStateFunc { get; }
}
}
}
#endif
16 changes: 15 additions & 1 deletion src/OpenTelemetry/Logs/OpenTelemetryLoggerOptions.cs
Original file line number Diff line number Diff line change
Expand Up @@ -17,14 +17,28 @@
#if NET461 || NETSTANDARD2_0
using System;
using System.Collections.Generic;
using Microsoft.Extensions.Logging;

namespace OpenTelemetry.Logs
{
public class OpenTelemetryLoggerOptions
{
internal readonly List<BaseProcessor<LogRecord>> Processors = new List<BaseProcessor<LogRecord>>();

/// <summary>
/// Gets or sets a value indicating whether or not log scopes should be included on generated <see cref="LogRecord"/>s. Default value: False.
/// </summary>
public bool IncludeScopes { get; set; }

/// <summary>
/// Gets or sets a value indicating whether or not log message should be included on generated <see cref="LogRecord"/>s. Default value: False.
CodeBlanch marked this conversation as resolved.
Show resolved Hide resolved
/// </summary>
public bool IncludeMessage { get; set; }
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
public bool IncludeMessage { get; set; }
public bool IncludeFormattedMessage { get; set; }

I think IncludeFormattedMessage is a better name.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sounds good. What about LogRecord.Message you want that to be LogRecord.FormattedMessage or leave as LogRecord.Message?


/// <summary>
/// Gets or sets a value indicating whether or not log state should be parsed into <see cref="LogRecord.StateValues"/> on generated <see cref="LogRecord"/>s. Default value: False.
CodeBlanch marked this conversation as resolved.
Show resolved Hide resolved
/// </summary>
public bool ParseStateValues { get; set; }

/// <summary>
/// Adds processor to the options.
/// </summary>
Expand Down
53 changes: 27 additions & 26 deletions src/OpenTelemetry/Logs/OpenTelemetryLoggerProvider.cs
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,7 @@

#if NET461 || NETSTANDARD2_0
using System;
using System.Collections.Generic;
using System.Collections;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Options;

Expand All @@ -25,9 +25,9 @@ namespace OpenTelemetry.Logs
[ProviderAlias("OpenTelemetry")]
public class OpenTelemetryLoggerProvider : ILoggerProvider, ISupportExternalScope
{
internal readonly OpenTelemetryLoggerOptions Options;
internal BaseProcessor<LogRecord> Processor;
private readonly OpenTelemetryLoggerOptions options;
private readonly IDictionary<string, ILogger> loggers;
private readonly Hashtable loggers = new Hashtable();
private bool disposed;
private IExternalScopeProvider scopeProvider;

Expand All @@ -45,49 +45,50 @@ public OpenTelemetryLoggerProvider(IOptionsMonitor<OpenTelemetryLoggerOptions> o

internal OpenTelemetryLoggerProvider(OpenTelemetryLoggerOptions options)
{
this.options = options ?? throw new ArgumentNullException(nameof(options));
this.loggers = new Dictionary<string, ILogger>(StringComparer.Ordinal);
this.Options = options ?? throw new ArgumentNullException(nameof(options));

foreach (var processor in options.Processors)
{
this.AddProcessor(processor);
}
}

internal IExternalScopeProvider ScopeProvider
void ISupportExternalScope.SetScopeProvider(IExternalScopeProvider scopeProvider)
{
get
this.scopeProvider = scopeProvider;

lock (this.loggers)
{
if (this.scopeProvider == null)
foreach (DictionaryEntry entry in this.loggers)
{
this.scopeProvider = new LoggerExternalScopeProvider();
if (entry.Value is OpenTelemetryLogger logger)
{
logger.ScopeProvider = scopeProvider;
}
}

return this.scopeProvider;
}
}

void ISupportExternalScope.SetScopeProvider(IExternalScopeProvider scopeProvider)
{
// TODO: set existing loggers
this.scopeProvider = scopeProvider;
}

public ILogger CreateLogger(string categoryName)
{
lock (this.loggers)
if (!(this.loggers[categoryName] is OpenTelemetryLogger logger))
{
ILogger logger;

if (this.loggers.TryGetValue(categoryName, out logger))
lock (this.loggers)
{
return logger;
logger = this.loggers[categoryName] as OpenTelemetryLogger;
if (logger == null)
{
logger = new OpenTelemetryLogger(categoryName, this)
{
ScopeProvider = this.scopeProvider,
};

this.loggers[categoryName] = logger;
}
}

logger = new OpenTelemetryLogger(categoryName, this);
this.loggers.Add(categoryName, logger);
return logger;
}

return logger;
}

/// <inheritdoc/>
Expand Down