diff --git a/apis/Google.Cloud.Diagnostics.AspNetCore/Google.Cloud.Diagnostics.AspNetCore.IntegrationTests/Logging/LoggingTest.cs b/apis/Google.Cloud.Diagnostics.AspNetCore/Google.Cloud.Diagnostics.AspNetCore.IntegrationTests/Logging/LoggingTest.cs index d5f2130417f1..8dd346d89cfb 100644 --- a/apis/Google.Cloud.Diagnostics.AspNetCore/Google.Cloud.Diagnostics.AspNetCore.IntegrationTests/Logging/LoggingTest.cs +++ b/apis/Google.Cloud.Diagnostics.AspNetCore/Google.Cloud.Diagnostics.AspNetCore.IntegrationTests/Logging/LoggingTest.cs @@ -220,6 +220,29 @@ public async Task Logging_ScopeFormatParameter() }); } + [Fact] + public async Task Logging_AugmentedWithLabels() + { + string testId = IdGenerator.FromGuid(); + + using (var server = GetTestServer()) + 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() { @@ -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("test_id", id)).LogCritical(message); + return message; + } + public string Exception(string id) { string message = EntryData.GetMessage(nameof(Exception), id); diff --git a/apis/Google.Cloud.Diagnostics.AspNetCore/Google.Cloud.Diagnostics.AspNetCore/Logging/GoogleLogger.cs b/apis/Google.Cloud.Diagnostics.AspNetCore/Google.Cloud.Diagnostics.AspNetCore/Logging/GoogleLogger.cs index b9d978476845..a98ce10e8ea7 100644 --- a/apis/Google.Cloud.Diagnostics.AspNetCore/Google.Cloud.Diagnostics.AspNetCore/Logging/GoogleLogger.cs +++ b/apis/Google.Cloud.Diagnostics.AspNetCore/Google.Cloud.Diagnostics.AspNetCore/Logging/GoogleLogger.cs @@ -21,7 +21,6 @@ using System; using System.Collections.Generic; using System.IO; -using System.Linq; using static System.FormattableString; #if NETCOREAPP3_1 @@ -65,6 +64,8 @@ public sealed class GoogleLogger : ILogger /// The service provider to resolve additional services from. private readonly IServiceProvider _serviceProvider; + private readonly AmbientScopeManager _ambientScopeManager; + internal GoogleLogger(IConsumer consumer, LogTarget logTarget, LoggerOptions loggerOptions, string logName, IClock clock = null, IServiceProvider serviceProvider = null) { @@ -77,6 +78,7 @@ internal GoogleLogger(IConsumer consumer, LogTarget logTarget, LoggerO _fullLogName = logTarget.GetFullLogName(_loggerOptions.LogName); _serviceProvider = serviceProvider; _clock = clock ?? SystemClock.Instance; + _ambientScopeManager = new AmbientScopeManager(_loggerOptions, _serviceProvider); } /// @@ -110,10 +112,10 @@ public void Log(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 }); @@ -121,30 +123,6 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except catch (Exception) when (_loggerOptions.RetryOptions.ExceptionHandling == ExceptionHandling.Ignore) { } } - private Dictionary CreateLabels() - { - var labelProviders = _serviceProvider?.GetService>(); - 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(EventId eventId, TState state, Exception exception, string message) { var jsonStruct = new Struct(); @@ -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(); } + + /// + /// 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. + /// + 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>() is IEnumerable providers) + { + var labels = new Dictionary(); + foreach (var provider in providers) + { + provider.Invoke(labels); + } + current = GoogleLoggerScope.CreateScope(new LabellingScopeState(labels), current); + } + + return current; + } + } } } diff --git a/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common.Tests/Logging/GoogleLoggerScopeTest.cs b/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common.Tests/Logging/GoogleLoggerScopeTest.cs index 121852f29637..58390c7b8a83 100644 --- a/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common.Tests/Logging/GoogleLoggerScopeTest.cs +++ b/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common.Tests/Logging/GoogleLoggerScopeTest.cs @@ -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>(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[] labels) + { + var logEntry = GetEmptyLogEntry(); + GoogleLoggerScope.Current.ApplyTo(logEntry); + Assert.Collection( + logEntry.Labels, + labels.Select, Action>>(expected => actual => + { + Assert.Equal(expected.Key, actual.Key); + Assert.Equal(expected.Value, actual.Value); + }).ToArray()); + } + [Fact] public void Current_Unset() { @@ -98,17 +125,13 @@ public void MultipleScopes_Nested() public void MultipleScopes_Nested_KeyValuePairs() { Assert.Null(GoogleLoggerScope.Current); - using (GoogleLoggerScope.BeginScope(new DummyKeyValuePairs( - new KeyValuePair("grandfather", "Joey"), - new KeyValuePair("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("father", "Joe"), - new KeyValuePair("mother", "Jane")))) + using (GoogleLoggerScope.BeginScope(new DummyKeyValuePairs { { "father", "Joe" }, { "mother", "Jane" } })) { AssertScope("['grandfather'='Joey']['grandmother'='Janey'] => ['father'='Joe']['mother'='Jane']"); AssertParentScopes( @@ -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("grandfather", "Joey"), + new KeyValuePair("grandmother", "Janey")))) + { + // This is the labelling scope, we add its information on labels only. + AssertEmptyScope(); + AssertEmptyParentScopes(); + AssertLabels( + new KeyValuePair("grandfather", "Joey"), + new KeyValuePair("grandmother", "Janey")); + + using (GoogleLoggerScope.BeginScope(new LabellingScopeState( + new KeyValuePair("father", "Joe"), + new KeyValuePair("mother", "Jane")))) + { + AssertEmptyScope(); + AssertEmptyParentScopes(); + AssertLabels( + new KeyValuePair("grandfather", "Joey"), + new KeyValuePair("grandmother", "Janey"), + new KeyValuePair("father", "Joe"), + new KeyValuePair("mother", "Jane")); + } + + AssertEmptyScope(); + AssertEmptyParentScopes(); + AssertLabels( + new KeyValuePair("grandfather", "Joey"), + new KeyValuePair("grandmother", "Janey")); + } + Assert.Null(GoogleLoggerScope.Current); + } + [Fact] public void MultipleScopes_Nested_Mixed() { Assert.Null(GoogleLoggerScope.Current); - using (GoogleLoggerScope.BeginScope(new DummyKeyValuePairs( - new KeyValuePair("father", "Joe"), - new KeyValuePair("mother", "Jane")))) + using (GoogleLoggerScope.BeginScope(new DummyKeyValuePairs { { "father", "Joe" }, { "mother", "Jane" } })) { AssertScope("['father'='Joe']['mother'='Jane']"); AssertParentScopes( @@ -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("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("job_title", "hairdresser")); + } } AssertScope("['father'='Joe']['mother'='Jane']"); @@ -281,9 +348,9 @@ public async Task MultipleScopes_Threads_Started_During_Scope() private class DummyKeyValuePairs : IEnumerable> { - private IEnumerable> _pairs; - public DummyKeyValuePairs(params KeyValuePair[] pairs) => _pairs = pairs; + private IList> _pairs = new List>(); + public void Add(string key, object value) => _pairs.Add(new KeyValuePair(key, value)); public IEnumerator> GetEnumerator() => _pairs.GetEnumerator(); diff --git a/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common.Tests/Logging/ILoggerExtensionsTest.cs b/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common.Tests/Logging/ILoggerExtensionsTest.cs new file mode 100644 index 000000000000..29fe83e01df9 --- /dev/null +++ b/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common.Tests/Logging/ILoggerExtensionsTest.cs @@ -0,0 +1,211 @@ +// Copyright 2021 Google LLC +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// https://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +using Microsoft.Extensions.Logging; +using Moq; +using System; +using System.Collections.Generic; +using System.Linq; +using Xunit; + +namespace Google.Cloud.Diagnostics.Common.Tests.Logging +{ + public class ILoggerExtensionsTest + { + [Fact] + public void WithLabels_NoChangesInOriginalLogger() + { + var loggerMock = new Mock(MockBehavior.Strict) + .SetupLog("Cutting hair"); + + var originalLogger = loggerMock.Object; + var augmentedLogger = originalLogger.WithLabels(new KeyValuePair("job_title", "hairdresser")); + + Assert.NotSame(originalLogger, augmentedLogger); + loggerMock.VerifyNoOtherCalls(); + + originalLogger.LogInformation("Cutting hair"); + + loggerMock + .VerifyLog(Times.Once()) + .VerifyNoOtherCalls(); + } + + [Fact] + public void WithLabels_BeginsScopeAndEndsScope() + { + var scopeMock = GetScopeMock(); + + var loggerMock = new Mock(MockBehavior.Strict) + .SetupLog("Cutting hair") + .SetupBeginScope(scopeMock.Object, new KeyValuePair("job_title", "hairdresser")); + + var originalLogger = loggerMock.Object; + var augmentedLogger = originalLogger.WithLabels(new KeyValuePair("job_title", "hairdresser")); + + augmentedLogger.LogInformation("Cutting hair"); + + scopeMock.Verify(scope => scope.Dispose(), Times.Once()); + loggerMock + .VerifyLog(Times.Once()) + .VerifyBeginScope(Times.Once()) + .VerifyNoOtherCalls(); + } + + [Fact] + public void WithLabels_UseOriginalAfterAugmented() + { + var scopeMock = GetScopeMock(); + + var loggerMock = new Mock(MockBehavior.Strict) + .SetupLog("Cutting hair") + .SetupBeginScope(scopeMock.Object, new KeyValuePair("job_title", "hairdresser")); + + var originalLogger = loggerMock.Object; + var augmentedLogger = originalLogger.WithLabels(new KeyValuePair("job_title", "hairdresser")); + + augmentedLogger.LogInformation("Cutting hair"); + scopeMock.Verify(scope => scope.Dispose(), Times.Once()); + originalLogger.LogInformation("Cutting hair"); + + loggerMock + .VerifyLog(Times.Exactly(2)) + .VerifyBeginScope(Times.Once()) + .VerifyNoOtherCalls(); + } + + [Fact] + public void WithAddedLabels() + { + var scopeMock = GetScopeMock(); + + var loggerMock = new Mock(MockBehavior.Strict) + .SetupLog("Cutting hair") + .SetupBeginScope(scopeMock.Object, + new KeyValuePair("job_title", "hairdresser"), + new KeyValuePair("tool", "scissors")); + + var originalLogger = loggerMock.Object; + var oneLabelLogger = originalLogger.WithLabels(new KeyValuePair("job_title", "hairdresser")); + var twoLabelLogger = oneLabelLogger.WithAddedLabels(new KeyValuePair("tool", "scissors")); + + Assert.NotSame(oneLabelLogger, twoLabelLogger); + + twoLabelLogger.LogInformation("Cutting hair"); + + scopeMock.Verify(scope => scope.Dispose(), Times.Once()); + + loggerMock + .VerifyLog(Times.Once()) + .VerifyBeginScope(Times.Once()) + .VerifyNoOtherCalls(); + } + + [Fact] + public void WithAddedLabels_NoWithLabels() + { + var scopeMock = GetScopeMock(); + + var loggerMock = new Mock(MockBehavior.Strict) + .SetupLog("Cutting hair") + .SetupBeginScope(scopeMock.Object, new KeyValuePair("job_title", "hairdresser")); + + var originalLogger = loggerMock.Object; + var augmentedLogger = originalLogger.WithAddedLabels(new KeyValuePair("job_title", "hairdresser")); + + augmentedLogger.LogInformation("Cutting hair"); + + scopeMock.Verify(scope => scope.Dispose(), Times.Once()); + loggerMock + .VerifyLog(Times.Once()) + .VerifyBeginScope(Times.Once()) + .VerifyNoOtherCalls(); + } + + [Fact] + public void WithAddedLabels_UseInitiallyAugmented() + { + var oneLabelScopeMock = GetScopeMock(); + var twoLabelsScopeMock = GetScopeMock(); + + var loggerMock = new Mock(MockBehavior.Strict) + .SetupLog("Cutting hair") + .SetupBeginScope(oneLabelScopeMock.Object, new KeyValuePair("job_title", "hairdresser")) + .SetupBeginScope(twoLabelsScopeMock.Object, + new KeyValuePair("job_title", "hairdresser"), + new KeyValuePair("tool", "scissors")); + + var originalLogger = loggerMock.Object; + var oneLabelLogger = originalLogger.WithLabels(new KeyValuePair("job_title", "hairdresser")); + var twoLabelLogger = oneLabelLogger.WithAddedLabels(new KeyValuePair("tool", "scissors")); + + twoLabelLogger.LogInformation("Cutting hair"); + + oneLabelScopeMock.Verify(scope => scope.Dispose(), Times.Never()); + twoLabelsScopeMock.Verify(scope => scope.Dispose(), Times.Once()); + + oneLabelLogger.LogInformation("Cutting hair"); + + oneLabelScopeMock.Verify(scope => scope.Dispose(), Times.Once()); + twoLabelsScopeMock.Verify(scope => scope.Dispose(), Times.Once()); + + loggerMock + .VerifyLog(Times.Exactly(2)) + .VerifyBeginScope(Times.Exactly(2)) + .VerifyNoOtherCalls(); + } + + private Mock GetScopeMock() + { + var scopeMock = new Mock(MockBehavior.Strict); + scopeMock.Setup(scope => scope.Dispose()); + return scopeMock; + } + } + + public static class ILoggerMockExtensions + { + public static Mock SetupBeginScope(this Mock loggerMock, IDisposable returnValue, params KeyValuePair[] acceptedLabels) + { + loggerMock + .Setup(logger => logger.BeginScope( + It.Is(state => state.Labels.Count == acceptedLabels.Length && !state.Labels.Except(acceptedLabels).Any()))) + .Returns(returnValue); + + return loggerMock; + } + + public static Mock SetupLog(this Mock loggerMock, string expectedFinalMessage) + { + loggerMock + .Setup(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny>())) + .Callback>((level, eventId, state, exception, formatter) => Assert.Equal(expectedFinalMessage, formatter(state, exception))); + + return loggerMock; + } + + public static Mock VerifyBeginScope(this Mock loggerMock, Times times) + { + loggerMock.Verify(logger => logger.BeginScope(It.IsAny()), times); + + return loggerMock; + } + + public static Mock VerifyLog(this Mock loggerMock, Times times) + { + loggerMock.Verify(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), null, It.IsAny>()), times); + return loggerMock; + } + } +} diff --git a/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/KeyValuePairEnumerableExtensions.cs b/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/KeyValuePairEnumerableExtensions.cs index 3afdd81353a9..c910b0893676 100644 --- a/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/KeyValuePairEnumerableExtensions.cs +++ b/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/KeyValuePairEnumerableExtensions.cs @@ -12,13 +12,16 @@ // See the License for the specific language governing permissions and // limitations under the License. +using Google.Api.Gax; using Google.Protobuf.WellKnownTypes; using System.Collections.Generic; +using System.Text; namespace Google.Cloud.Diagnostics.Common { /// - /// Extension methods for converting several types to Protobub well known types. + /// Extension methods for converting KeyValuePair Enumerables to several types, + /// including Protobuf well known types. /// public static class KeyValuePairEnumerableExtensions { @@ -32,7 +35,7 @@ public static class KeyValuePairEnumerableExtensions /// which case this method will return null. public static Value ToStructValue(this IEnumerable> fields) { - if (fields == null) + if (fields is null) { return null; } @@ -41,12 +44,12 @@ public static Value ToStructValue(this IEnumerable> Struct fieldsStruct = new Struct(); foreach (var pair in fields) { - hasValues = true; string key = pair.Key; if (string.IsNullOrEmpty(key)) { continue; } + hasValues = true; if (char.IsDigit(key[0])) { key = "_" + key; @@ -55,5 +58,20 @@ public static Value ToStructValue(this IEnumerable> } return hasValues ? Value.ForStruct(fieldsStruct) : null; } + + /// + /// Returns a string representing the given fields with the format: + /// ['key1'='value1']['key2'='value2']... + /// + internal static string ToDefaultStringRepresentation(this IEnumerable> fields) + { + GaxPreconditions.CheckNotNull(fields, nameof(fields)); + StringBuilder builder = new StringBuilder(); + foreach (var pair in fields) + { + builder.Append($"['{pair.Key}'='{pair.Value}']"); + } + return builder.ToString(); + } } } diff --git a/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/Logging/GoogleLoggerScope.cs b/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/Logging/GoogleLoggerScope.cs index bdebaca83a50..920938d6a058 100644 --- a/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/Logging/GoogleLoggerScope.cs +++ b/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/Logging/GoogleLoggerScope.cs @@ -33,38 +33,38 @@ public abstract class GoogleLoggerScope : IDisposable /// public static GoogleLoggerScope Current { - get - { - return _current.Value; - } - private set - { - _current.Value = value; - } + get => _current.Value; + private set => _current.Value = value; } /// /// Creates a new scope with the given state and as parent. /// Sets the newly created scope as . /// - /// public static GoogleLoggerScope BeginScope(object state) => - Current = state switch + Current = CreateScope(state, Current); + + /// + /// Creates a new scope with the given state and as parent. + /// Sets the newly created scope as . + /// + public static GoogleLoggerScope CreateScope(object state, GoogleLoggerScope parent) => + state switch { - IEnumerable> keyValues => new KeyValueLoggerScope(keyValues, Current), - _ => new GoogleLoggerScope(state, Current) + LabellingScopeState labels => new LabellingScope(labels, parent), + IEnumerable> keyValues => new KeyValueLoggerScope(keyValues, parent), + _ => new GoogleLoggerScope(state, parent) }; /// /// The parent scope, may be null. /// - protected internal GoogleLoggerScope Parent { get; } + private GoogleLoggerScope Parent { get; } /// /// Creates a new scope. /// - protected internal GoogleLoggerScope(GoogleLoggerScope parent) - => Parent = parent; + protected internal GoogleLoggerScope(GoogleLoggerScope parent) => Parent = parent; /// /// Removes this scope, and all inner scopes, from the scope stack. @@ -77,7 +77,7 @@ public void Dispose() maybeMyself = maybeMyself.Parent; } // Only if we've found this instance in the Scope stack - // we pop it and all it's child scopes. + // we pop it and all its child scopes. if (maybeMyself == this) { Current = Parent; @@ -91,25 +91,25 @@ public void Dispose() /// information added by more recent scopes can overwrite information added /// by less recent ones. /// - public void ApplyFullScopeStack(LogEntry entry) + public void ApplyTo(LogEntry entry) { GaxPreconditions.CheckNotNull(entry, nameof(entry)); GaxPreconditions.CheckNotNull(entry.JsonPayload, nameof(entry.JsonPayload)); - ApplyFullScopeStackImpl(entry); + ApplyToImp(entry); } - private void ApplyFullScopeStackImpl(LogEntry entry) + private void ApplyToImp(LogEntry entry) { - Parent?.ApplyFullScopeStackImpl(entry); - ApplyThisScope(entry); + Parent?.ApplyToImp(entry); + ApplyThisScopeOnlyTo(entry); } /// /// Apply this scope's information only. - /// Implementers should decide whether to overwirte similar information from + /// Implementers should decide whether to overwrite similar information from /// previous scopes or combine it with this one. /// - protected internal abstract void ApplyThisScope(LogEntry entry); + protected internal abstract void ApplyThisScopeOnlyTo(LogEntry entry); } internal class GoogleLoggerScope : GoogleLoggerScope @@ -133,19 +133,16 @@ public GoogleLoggerScope(TState state, GoogleLoggerScope parent) /// This method will combine existing information so that the scope /// field looks like "grandparentScope => parentScope => childScope". /// - protected internal override void ApplyThisScope(LogEntry entry) + protected internal override void ApplyThisScopeOnlyTo(LogEntry entry) { string stateText = State.ToString() ?? ""; - if (entry.JsonPayload.Fields.TryGetValue("scope", out Value value)) - { - value = Value.ForString($"{value.StringValue} => {stateText}"); - } - else - { - value = Value.ForString(stateText); - } - - entry.JsonPayload.Fields["scope"] = value; + string effectiveText = entry.JsonPayload.Fields.TryGetValue("scope", out Value value) + ? value.KindCase == Value.KindOneofCase.StringValue + ? $"{value.StringValue} => {stateText}" + : throw new InvalidOperationException( + $"scope field in {nameof(entry.JsonPayload)} is expected to be a {nameof(Value.KindOneofCase.StringValue)} or unset. Found a {value.KindCase} instead.") + : stateText; + entry.JsonPayload.Fields["scope"] = Value.ForString(effectiveText); } } @@ -159,15 +156,15 @@ public KeyValueLoggerScope(IEnumerable> state, Goog /// Applies the information contained in to the log entry. /// /// - /// This method first calls . + /// This method first calls . /// Then, if contains elements it will create /// a adding each key value pair to . /// This will be added to the on a list field /// named parent_scopes. /// - protected internal override void ApplyThisScope(LogEntry entry) + protected internal override void ApplyThisScopeOnlyTo(LogEntry entry) { - base.ApplyThisScope(entry); + base.ApplyThisScopeOnlyTo(entry); if (!(State.ToStructValue() is Value newValue)) { @@ -176,7 +173,15 @@ protected internal override void ApplyThisScope(LogEntry entry) if (entry.JsonPayload.Fields.TryGetValue("parent_scopes", out Value existingValues)) { - existingValues.ListValue.Values.Insert(0, newValue); + if (existingValues.KindCase == Value.KindOneofCase.ListValue) + { + existingValues.ListValue.Values.Insert(0, newValue); + } + else + { + throw new InvalidOperationException( + $"parent_scopes field in {nameof(entry.JsonPayload)} is expected to be a {nameof(Value.KindOneofCase.ListValue)} or unset. Found a {existingValues.KindCase} instead."); + } } else { diff --git a/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/Logging/ILoggerExtensions.cs b/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/Logging/ILoggerExtensions.cs new file mode 100644 index 000000000000..9aa3bb7d2aa8 --- /dev/null +++ b/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/Logging/ILoggerExtensions.cs @@ -0,0 +1,132 @@ +// Copyright 2021 Google LLC +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// https://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +using Google.Api.Gax; +using Google.Cloud.Logging.V2; +using Microsoft.Extensions.Logging; +using System; +using System.Collections.Generic; +using System.Linq; + +namespace Google.Cloud.Diagnostics.Common +{ + /// + /// Extensions for to allow augmenting the logged information with contextual data. + /// GoogleLogger(TODO: change this to a cref when I've moved it to this package) + /// will add the information to the that is sent to Google Cloud Logging. + /// For the consumption of other loggers, the information will be included in newly created scopes + /// at the moment of logging, in a format that all loggers should understand. + /// + public static class ILoggerExtensions + { + /// + /// + /// Adds labels to the returned logger that may be included with every subsequent log. + /// How this information is included will depend on the actual . + /// GoogleLogger(TODO: change this to a cref when I've moved it to this package) will include this + /// information in . + /// + /// + /// If had already been augmented with labels, the old labels will be replaced + /// by the new ones on the returned . + /// + /// + public static ILogger WithLabels(this ILogger logger, params KeyValuePair[] labels) => + WithLabels(logger, labels.AsEnumerable()); + + /// + /// + /// Adds labels to the returned logger that may be included with every subsequent log. + /// How this information is included will depend on the actual . + /// GoogleLogger(TODO: change this to a cref when I've moved it to this package) will include this + /// information in . + /// + /// + /// If had already been augmented with labels, the old labels will be replaced + /// by the new ones on the returned . + /// + /// + public static ILogger WithLabels(this ILogger logger, IEnumerable> labels) => + GaxPreconditions.CheckNotNull(logger, nameof(logger)) switch + { + AugmentedLogger augmented => augmented.WithLabels(labels), + _ => AugmentedLogger.ForLabels(logger, labels) + }; + + /// + /// + /// Adds labels to the returned logger that may be included with every subsequent log. + /// How this information is included will depend on the actual . + /// GoogleLogger(TODO: change this to a cref when I've moved it to this package) will include this + /// information in . + /// + /// + /// If had already been augmented with labels, + /// will be added to the existing ones on the returned + /// + /// + public static ILogger WithAddedLabels(this ILogger logger, params KeyValuePair[] labels) => + WithAddedLabels(logger, labels.AsEnumerable()); + + /// + /// + /// Adds labels to the returned logger that may be included with every subsequent log. + /// How this information is included will depend on the actual . + /// GoogleLogger(TODO: change this to a cref when I've moved it to this package) will include this + /// information in . + /// + /// + /// If had already been augmented with labels, + /// will be added to the existing ones on the returned + /// + /// + public static ILogger WithAddedLabels(this ILogger logger, IEnumerable> labels) => + GaxPreconditions.CheckNotNull(logger, nameof(logger)) switch + { + AugmentedLogger augmented => augmented.WithAddedLabels(labels), + _ => AugmentedLogger.ForLabels(logger, labels) + }; + + private class AugmentedLogger : ILogger + { + private ILogger _innerLogger; + private IEnumerable> _labels; + + private AugmentedLogger(ILogger logger, IEnumerable> labels) => + (_innerLogger, _labels) = + (GaxPreconditions.CheckNotNull(logger, nameof(logger)), GaxPreconditions.CheckNotNull(labels, nameof(labels))); + + public static AugmentedLogger ForLabels(ILogger logger, IEnumerable> labels) => + new AugmentedLogger(logger, labels); + + public AugmentedLogger WithLabels(IEnumerable> labels) => + new AugmentedLogger(_innerLogger, labels); + + public AugmentedLogger WithAddedLabels(IEnumerable> extraLabels) => + new AugmentedLogger(_innerLogger, _labels.Concat(GaxPreconditions.CheckNotNull(extraLabels, nameof(extraLabels)))); + + public IDisposable BeginScope(TState state) => _innerLogger.BeginScope(state); + + public bool IsEnabled(LogLevel logLevel) => _innerLogger.IsEnabled(logLevel); + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + using (_innerLogger.BeginScope(new LabellingScopeState(_labels))) + { + _innerLogger.Log(logLevel, eventId, state, exception, formatter); + } + } + } + } +} diff --git a/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/Logging/LabellingScope.cs b/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/Logging/LabellingScope.cs new file mode 100644 index 000000000000..27f50e25a1b4 --- /dev/null +++ b/apis/Google.Cloud.Diagnostics.Common/Google.Cloud.Diagnostics.Common/Logging/LabellingScope.cs @@ -0,0 +1,95 @@ +// Copyright 2021 Google LLC +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// https://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +using Google.Cloud.Logging.V2; +using System.Collections; +using System.Collections.Generic; +using System.Collections.ObjectModel; +using System.Linq; + +namespace Google.Cloud.Diagnostics.Common +{ + /// + /// Represents the data for the labelling scope, basically, labels. + /// + // Note: We implement IEnumerable for the benefit of other ILogger implementations, + // so they can represent this information as they see fit. + public class LabellingScopeState : IEnumerable> + { + /// + /// Creates a new for the given labels. + /// + public LabellingScopeState(IEnumerable> labels) + { + var dictionary = new Dictionary(); + if (labels != null) + { + foreach(var pair in labels) + { + // Let's do this to allow overriding + dictionary[pair.Key] = pair.Value; + } + } + Labels = new ReadOnlyDictionary(dictionary); + } + + internal LabellingScopeState(params KeyValuePair[] labels) + : this(labels.AsEnumerable()) + { } + + /// + /// Labels contained by this state. Won't be null but may be empty. + /// + public IReadOnlyDictionary Labels { get; } + + /// + public IEnumerator> GetEnumerator() => + Labels.Select(pair => new KeyValuePair(pair.Key, pair.Value)).GetEnumerator(); + + IEnumerator IEnumerable.GetEnumerator() => GetEnumerator(); + + /// + /// Returns a string representing the given labels with the format: + /// ['key1'='value1']['key2'='value2']... + /// + // Note: we do this for the benefit of other ILogger implementations. + // If they want to represent this information in a different format + // they can use the enumerator to iterate over all the labels and their values. + public override string ToString() => Labels.ToDefaultStringRepresentation(); + } + + /// + /// Scope that adds the given labels to a log entry. + /// + internal class LabellingScope : GoogleLoggerScope + { + public LabellingScope(LabellingScopeState state, GoogleLoggerScope parent) + :base(state, parent) + { } + + protected internal override void ApplyThisScopeOnlyTo(LogEntry entry) + { + // We very explicitly don't call the base implementation of this + // method which adds the state information to the scope field of the + // LogEntry.JsonPayload. We know these to be labels so we add them + // on the LogEntry.Labels collection. + + foreach(var pair in State.Labels) + { + // It's OK to override, these will get executed in the correct order. + entry.Labels[pair.Key] = pair.Value; + } + } + } +}