Skip to content

Commit

Permalink
feat: Allows per log entry labels.
Browse files Browse the repository at this point in the history 
Closes #5313
Closes #5929
  • Loading branch information
@amanda-tarafa
amanda-tarafa committed Jun 16, 2021
1 parent c8e9a48 commit 32cb606
Show file tree
Hide file tree
Showing 8 changed files with 654 additions and 81 deletions.
30 changes: 30 additions & 0 deletions ...cs.AspNetCore/Google.Cloud.Diagnostics.AspNetCore.IntegrationTests/Logging/LoggingTest.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -220,6 +220,29 @@ public async Task Logging_ScopeFormatParameter()
});
}

[Fact]
public async Task Logging_AugmentedWithLabels()
{
string testId = IdGenerator.FromGuid();

using (var server = GetTestServer<NoBufferWarningLoggerTestApplication>())
using (var client = server.CreateClient())
{
await client.GetAsync($"/Main/AugmentWithLabels/{testId}");
}

_fixture.AddValidator(testId, results =>
{
var message = EntryData.GetMessage(nameof(MainController.AugmentWithLabels), testId);
var entry = results.Single();
var json = entry.JsonPayload.Fields;
Assert.Equal(message, json["message"].StringValue);

Assert.Equal(1, entry.Labels.Count);
Assert.Equal(testId, entry.Labels["test_id"]);
});
}

[Fact]
public async Task Logging_Trace_FromHeader_Implicit()
{
Expand Down Expand Up @@ -1057,6 +1080,13 @@ public string ScopeFormatParameters(string id)
}
}

public string AugmentWithLabels(string id)
{
string message = EntryData.GetMessage(nameof(AugmentWithLabels), id);
_logger.WithLabels(new KeyValuePair<string, string>("test_id", id)).LogCritical(message);
return message;
}

public string Exception(string id)
{
string message = EntryData.GetMessage(nameof(Exception), id);
Expand Down
69 changes: 42 additions & 27 deletions ....Cloud.Diagnostics.AspNetCore/Google.Cloud.Diagnostics.AspNetCore/Logging/GoogleLogger.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,7 +21,6 @@
using System;
using System.Collections.Generic;
using System.IO;
using System.Linq;
using static System.FormattableString;

#if NETCOREAPP3_1
Expand Down Expand Up @@ -65,6 +64,8 @@ public sealed class GoogleLogger : ILogger
/// <summary>The service provider to resolve additional services from.</summary>
private readonly IServiceProvider _serviceProvider;

private readonly AmbientScopeManager _ambientScopeManager;

internal GoogleLogger(IConsumer<LogEntry> consumer, LogTarget logTarget, LoggerOptions loggerOptions,
string logName, IClock clock = null, IServiceProvider serviceProvider = null)
{
Expand All @@ -77,6 +78,7 @@ internal GoogleLogger(IConsumer<LogEntry> consumer, LogTarget logTarget, LoggerO
_fullLogName = logTarget.GetFullLogName(_loggerOptions.LogName);
_serviceProvider = serviceProvider;
_clock = clock ?? SystemClock.Instance;
_ambientScopeManager = new AmbientScopeManager(_loggerOptions, _serviceProvider);
}

/// <inheritdoc />
Expand Down Expand Up @@ -110,41 +112,17 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
Severity = logLevel.ToLogSeverity(),
Timestamp = Timestamp.FromDateTime(_clock.GetCurrentDateTimeUtc()),
JsonPayload = CreateJsonPayload(eventId, state, exception, message),
Labels = { CreateLabels() },
};

GoogleLoggerScope.Current?.ApplyFullScopeStack(entry);
_ambientScopeManager.GetCurrentScope()?.ApplyTo(entry);
GoogleLoggerScope.Current?.ApplyTo(entry);
SetTraceAndSpanIfAny(entry);

_consumer.Receive(new[] { entry });
}
catch (Exception) when (_loggerOptions.RetryOptions.ExceptionHandling == ExceptionHandling.Ignore) { }
}

private Dictionary<string, string> CreateLabels()
{
var labelProviders = _serviceProvider?.GetService<IEnumerable<ILogEntryLabelProvider>>();
if (labelProviders is null)
{
return _loggerOptions.Labels;
}
using (var iterator = labelProviders.GetEnumerator())
{
if (!iterator.MoveNext())
{
return _loggerOptions.Labels;
}
// By now, we know we have at least one label provider. Clone the labels from the options,
// and invoke each provider on the clone in turn.
var labels = _loggerOptions.Labels.ToDictionary(kvp => kvp.Key, kvp => kvp.Value);
do
{
iterator.Current.Invoke(labels);
} while (iterator.MoveNext());
return labels;
}
}

private Struct CreateJsonPayload<TState>(EventId eventId, TState state, Exception exception, string message)
{
var jsonStruct = new Struct();
Expand Down Expand Up @@ -268,5 +246,42 @@ internal void WriteDiagnostics(TextWriter writer)
writer.WriteLine(Invariant($"{DateTime.UtcNow:yyyy-MM-dd'T'HH:mm:ss} - GoogleLogger will write logs to: {GetGcpConsoleLogsUrl()}"));
writer.Flush();
}

/// <summary>
/// Obtains the current ambient scope, which is not set by user code
/// but instead it is calculated based on the Logger configuration.
/// The ambient scope will be applied to all log entries.
/// It will be applied before the user specified scopes so that the
/// user code is able to override ambient scope values on a per
/// log entry basis.
/// </summary>
internal class AmbientScopeManager
{
private readonly GoogleLoggerScope _permanentParent;
private readonly IServiceProvider _serviceProvider;

internal AmbientScopeManager(LoggerOptions options, IServiceProvider serviceProvider)
{
_permanentParent = options?.Labels is null ? null : GoogleLoggerScope.CreateScope(new LabellingScopeState(options.Labels), null);
_serviceProvider = serviceProvider;
}

public GoogleLoggerScope GetCurrentScope()
{
var current = _permanentParent;

if (_serviceProvider?.GetService<IEnumerable<ILogEntryLabelProvider>>() is IEnumerable<ILogEntryLabelProvider> providers)
{
var labels = new Dictionary<string, string>();
foreach (var provider in providers)
{
provider.Invoke(labels);
}
current = GoogleLoggerScope.CreateScope(new LabellingScopeState(labels), current);
}

return current;
}
}
}
}
93 changes: 80 additions & 13 deletions ...Diagnostics.Common/Google.Cloud.Diagnostics.Common.Tests/Logging/GoogleLoggerScopeTest.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -32,19 +32,46 @@ public class GoogleLoggerScopeTest
private void AssertScope(string scopeValue)
{
var logEntry = GetEmptyLogEntry();
GoogleLoggerScope.Current.ApplyFullScopeStack(logEntry);
GoogleLoggerScope.Current.ApplyTo(logEntry);
Assert.Equal(scopeValue, logEntry.JsonPayload.Fields["scope"].StringValue);
}

private void AssertEmptyScope()
{
var logEntry = GetEmptyLogEntry();
GoogleLoggerScope.Current.ApplyTo(logEntry);
Assert.DoesNotContain(logEntry.JsonPayload.Fields.Keys, key => key == "scope");
}

private void AssertParentScopes(params Struct[] values)
{
var logEntry = GetEmptyLogEntry();
GoogleLoggerScope.Current.ApplyFullScopeStack(logEntry);
GoogleLoggerScope.Current.ApplyTo(logEntry);
Assert.Collection(
logEntry.JsonPayload.Fields["parent_scopes"].ListValue.Values.Select(v => v.StructValue),
values.Select<Struct, Action<Struct>>(expected => actual => Assert.Equal(expected, actual)).ToArray());
}

private void AssertEmptyParentScopes()
{
var logEntry = GetEmptyLogEntry();
GoogleLoggerScope.Current.ApplyTo(logEntry);
Assert.DoesNotContain(logEntry.JsonPayload.Fields.Keys, key => key == "parent_scopes");
}

private void AssertLabels(params KeyValuePair<string, string>[] labels)
{
var logEntry = GetEmptyLogEntry();
GoogleLoggerScope.Current.ApplyTo(logEntry);
Assert.Collection(
logEntry.Labels,
labels.Select<KeyValuePair<string, string>, Action<KeyValuePair<string, string>>>(expected => actual =>
{
Assert.Equal(expected.Key, actual.Key);
Assert.Equal(expected.Value, actual.Value);
}).ToArray());
}

[Fact]
public void Current_Unset()
{
Expand Down Expand Up @@ -98,17 +125,13 @@ public void MultipleScopes_Nested()
public void MultipleScopes_Nested_KeyValuePairs()
{
Assert.Null(GoogleLoggerScope.Current);
using (GoogleLoggerScope.BeginScope(new DummyKeyValuePairs(
new KeyValuePair<string, object>("grandfather", "Joey"),
new KeyValuePair<string, object>("grandmother", "Janey"))))
using (GoogleLoggerScope.BeginScope(new DummyKeyValuePairs { { "grandfather", "Joey" }, { "grandmother", "Janey" } }))
{
AssertScope("['grandfather'='Joey']['grandmother'='Janey']");
AssertParentScopes(
new Struct { Fields = { { "grandfather", Value.ForString("Joey") }, { "grandmother", Value.ForString("Janey") } } });

using (GoogleLoggerScope.BeginScope(new DummyKeyValuePairs(
new KeyValuePair<string, object>("father", "Joe"),
new KeyValuePair<string, object>("mother", "Jane"))))
using (GoogleLoggerScope.BeginScope(new DummyKeyValuePairs { { "father", "Joe" }, { "mother", "Jane" } }))
{
AssertScope("['grandfather'='Joey']['grandmother'='Janey'] => ['father'='Joe']['mother'='Jane']");
AssertParentScopes(
Expand All @@ -123,13 +146,48 @@ public void MultipleScopes_Nested_KeyValuePairs()
Assert.Null(GoogleLoggerScope.Current);
}

[Fact]
public void MultipleScopes_Nested_Labels()
{
Assert.Null(GoogleLoggerScope.Current);
using (GoogleLoggerScope.BeginScope(new LabellingScopeState(
new KeyValuePair<string, string>("grandfather", "Joey"),
new KeyValuePair<string, string>("grandmother", "Janey"))))
{
// This is the labelling scope, we add its information on labels only.
AssertEmptyScope();
AssertEmptyParentScopes();
AssertLabels(
new KeyValuePair<string, string>("grandfather", "Joey"),
new KeyValuePair<string, string>("grandmother", "Janey"));

using (GoogleLoggerScope.BeginScope(new LabellingScopeState(
new KeyValuePair<string, string>("father", "Joe"),
new KeyValuePair<string, string>("mother", "Jane"))))
{
AssertEmptyScope();
AssertEmptyParentScopes();
AssertLabels(
new KeyValuePair<string, string>("grandfather", "Joey"),
new KeyValuePair<string, string>("grandmother", "Janey"),
new KeyValuePair<string, string>("father", "Joe"),
new KeyValuePair<string, string>("mother", "Jane"));
}

AssertEmptyScope();
AssertEmptyParentScopes();
AssertLabels(
new KeyValuePair<string, string>("grandfather", "Joey"),
new KeyValuePair<string, string>("grandmother", "Janey"));
}
Assert.Null(GoogleLoggerScope.Current);
}

[Fact]
public void MultipleScopes_Nested_Mixed()
{
Assert.Null(GoogleLoggerScope.Current);
using (GoogleLoggerScope.BeginScope(new DummyKeyValuePairs(
new KeyValuePair<string, object>("father", "Joe"),
new KeyValuePair<string, object>("mother", "Jane"))))
using (GoogleLoggerScope.BeginScope(new DummyKeyValuePairs { { "father", "Joe" }, { "mother", "Jane" } }))
{
AssertScope("['father'='Joe']['mother'='Jane']");
AssertParentScopes(
Expand All @@ -141,6 +199,15 @@ public void MultipleScopes_Nested_Mixed()
// "myself" is not added to parent_scopes because it is not of the form key=>value.
AssertParentScopes(
new Struct { Fields = { { "father", Value.ForString("Joe") }, { "mother", Value.ForString("Jane") } } });
using (GoogleLoggerScope.BeginScope(new LabellingScopeState(
new KeyValuePair<string, string>("job_title", "hairdresser"))))
{
AssertScope("['father'='Joe']['mother'='Jane'] => myself");
// "myself" is not added to parent_scopes because it is not of the form key=>value.
AssertParentScopes(
new Struct { Fields = { { "father", Value.ForString("Joe") }, { "mother", Value.ForString("Jane") } } });
AssertLabels(new KeyValuePair<string, string>("job_title", "hairdresser"));
}
}

AssertScope("['father'='Joe']['mother'='Jane']");
Expand Down Expand Up @@ -281,9 +348,9 @@ public async Task MultipleScopes_Threads_Started_During_Scope()

private class DummyKeyValuePairs : IEnumerable<KeyValuePair<string, object>>
{
private IEnumerable<KeyValuePair<string, object>> _pairs;
public DummyKeyValuePairs(params KeyValuePair<string, object>[] pairs) => _pairs = pairs;
private IList<KeyValuePair<string, object>> _pairs = new List<KeyValuePair<string, object>>();

public void Add(string key, object value) => _pairs.Add(new KeyValuePair<string, object>(key, value));

public IEnumerator<KeyValuePair<string, object>> GetEnumerator() => _pairs.GetEnumerator();

Expand Down
Loading

0 comments on commit 32cb606

Please sign in to comment.