diff --git a/.autover/changes/b2f4a6c1-2350-4e8d-9a3c-configstructuredlog.json b/.autover/changes/b2f4a6c1-2350-4e8d-9a3c-configstructuredlog.json new file mode 100644 index 000000000..ee5655bc3 --- /dev/null +++ b/.autover/changes/b2f4a6c1-2350-4e8d-9a3c-configstructuredlog.json @@ -0,0 +1,11 @@ +{ + "Projects": [ + { + "Name": "Amazon.Lambda.RuntimeSupport", + "Type": "Patch", + "ChangelogMessages": [ + "Fix LambdaLogger.ConfigureStructuredLogging custom JsonSerializerOptions being ignored when JSON log format is enabled. The stdout and stderr log writers each created their own JsonLogMessageFormatter, and the second registration overwrote the first's structured logging callback, so the customer's options never reached the formatter used for stdout. Both writers now share a single formatter instance." + ] + } + ] +} diff --git a/Libraries/src/Amazon.Lambda.RuntimeSupport/Helpers/ConsoleLoggerWriter.cs b/Libraries/src/Amazon.Lambda.RuntimeSupport/Helpers/ConsoleLoggerWriter.cs index 63f76584a..35a6a28a7 100644 --- a/Libraries/src/Amazon.Lambda.RuntimeSupport/Helpers/ConsoleLoggerWriter.cs +++ b/Libraries/src/Amazon.Lambda.RuntimeSupport/Helpers/ConsoleLoggerWriter.cs @@ -107,6 +107,11 @@ public enum LogLevel WrapperTextWriter _wrappedStdOutWriter; WrapperTextWriter _wrappedStdErrorWriter; + /// + /// The supported log output formats resolved from the log format environment variables. + /// + enum LogFormatType { Default, Unformatted, Json } + /// /// Constructor used by bootstrap to put in place a wrapper TextWriter around stdout and stderror so all Console.WriteLine calls /// will be formatted. @@ -173,10 +178,69 @@ public LogLevelLoggerWriter(TextWriter stdOutWriter, TextWriter stdErrorWriter) Initialize(stdOutWriter, stdErrorWriter); } + /// + /// Test-only constructor that wraps the provided writers using an injected environment. This lets tests + /// exercise the two-writer setup (and the shared formatter) without mutating process-wide environment + /// variables or replacing Console.Out/Console.Error, both of which leak across parallel tests. + /// + internal LogLevelLoggerWriter(IEnvironmentVariables environmentVariables, TextWriter stdOutWriter, TextWriter stdErrorWriter) + { + _environmentVariables = environmentVariables; + Initialize(stdOutWriter, stdErrorWriter); + } + private void Initialize(TextWriter stdOutWriter, TextWriter stdErrorWriter) { - _wrappedStdOutWriter = new WrapperTextWriter(_environmentVariables, stdOutWriter, LogLevel.Information.ToString()); - _wrappedStdErrorWriter = new WrapperTextWriter(_environmentVariables, stdErrorWriter, LogLevel.Error.ToString()); + // Create a single formatter here and hand the same instance to both the stdout and stderr writers. + // Both writers resolve the same log format from the same environment variables, so one formatter is + // correct for both. A single shared instance is also required for structured logging customization: + // JsonLogMessageFormatter registers the customer's ConfigureStructuredLogging callback through a + // single static setter on Amazon.Lambda.Core.LambdaLogger. If each writer created its own formatter, + // the second registration would overwrite the first, and the customer's JsonSerializerOptions would + // never reach the formatter used for stdout logging. See https://github.com/aws/aws-lambda-dotnet/issues/2350. + var logMessageFormatter = CreateLogMessageFormatter(_environmentVariables); + + _wrappedStdOutWriter = new WrapperTextWriter(_environmentVariables, stdOutWriter, LogLevel.Information.ToString(), logMessageFormatter); + _wrappedStdErrorWriter = new WrapperTextWriter(_environmentVariables, stdErrorWriter, LogLevel.Error.ToString(), logMessageFormatter); + } + + /// + /// Creates the log message formatter based on the log format resolved from the environment variables. + /// The formatter is created here (rather than inside each WrapperTextWriter) so a single instance can be + /// shared by the stdout and stderr writers; see Initialize and issue #2350. + /// + private static ILogMessageFormatter CreateLogMessageFormatter(IEnvironmentVariables environmentVariables) + { + var envLogFormat = GetEnvironmentVariable(environmentVariables, + Constants.NET_RIC_LOG_FORMAT_ENVIRONMENT_VARIABLE, Constants.LAMBDA_LOG_FORMAT_ENVIRONMENT_VARIABLE); + + var logFormatType = LogFormatType.Default; + if (!string.IsNullOrEmpty(envLogFormat) && + Enum.TryParse(envLogFormat, true, out var result)) + { + logFormatType = result; + } + + if (logFormatType == LogFormatType.Json) + { + return new JsonLogMessageFormatter(); + } + + return new DefaultLogMessageFormatter(logFormatType != LogFormatType.Unformatted); + } + + /// + /// Reads an environment variable, falling back to a secondary name when the primary is not set. + /// + private static string GetEnvironmentVariable(IEnvironmentVariables environmentVariables, string envName, string fallbackEnvName) + { + var value = environmentVariables.GetEnvironmentVariable(envName); + if (string.IsNullOrEmpty(value) && fallbackEnvName != null) + { + value = environmentVariables.GetEnvironmentVariable(fallbackEnvName); + } + + return value; } /// @@ -265,10 +329,6 @@ class WrapperTextWriter : TextWriter private readonly LogLevel _minmumLogLevel = LogLevel.Information; - enum LogFormatType { Default, Unformatted, Json } - - private readonly LogFormatType _logFormatType = LogFormatType.Default; - private readonly ILogMessageFormatter _logMessageFormatter; // If running in multi concurrency mode we need to store the current aws request id in Task @@ -314,11 +374,17 @@ public IRuntimeApiHeaders CurrentRuntimeApiHeaders /// /// /// - public WrapperTextWriter(IEnvironmentVariables environmentVariables, TextWriter innerWriter, string defaultLogLevel) + /// + /// The formatter used to format log records. The same instance is shared between the stdout and stderr + /// writers so structured logging configuration applies to both; the formatter is created and owned by + /// LogLevelLoggerWriter.Initialize (see issue #2350). + /// + public WrapperTextWriter(IEnvironmentVariables environmentVariables, TextWriter innerWriter, string defaultLogLevel, ILogMessageFormatter formatter) { _environmentVariables = environmentVariables; _innerWriter = innerWriter; _defaultLogLevel = defaultLogLevel; + _logMessageFormatter = formatter ?? throw new ArgumentNullException(nameof(formatter)); if(Utils.IsUsingMultiConcurrency(environmentVariables)) { @@ -346,26 +412,14 @@ public WrapperTextWriter(IEnvironmentVariables environmentVariables, TextWriter InternalLogger.GetDefaultLogger().LogInformation($"Failed to parse log level enum value: {envLogLevel}"); } } - - var envLogFormat = GetEnvironmentVariable(Constants.NET_RIC_LOG_FORMAT_ENVIRONMENT_VARIABLE, Constants.LAMBDA_LOG_FORMAT_ENVIRONMENT_VARIABLE); - if (!string.IsNullOrEmpty(envLogFormat)) - { - if (Enum.TryParse(envLogFormat, true, out var result)) - { - _logFormatType = result; - } - } - - if(_logFormatType == LogFormatType.Json) - { - _logMessageFormatter = new JsonLogMessageFormatter(); - } - else - { - _logMessageFormatter = new DefaultLogMessageFormatter(_logFormatType != LogFormatType.Unformatted); - } } + /// + /// The log message formatter this writer uses. Exposed so tests can verify the stdout and stderr + /// writers share the same formatter instance (created by LogLevelLoggerWriter.Initialize); see issue #2350. + /// + internal ILogMessageFormatter LogMessageFormatter => _logMessageFormatter; + private string GetEnvironmentVariable(string envName, string fallbackEnvName) { var value = _environmentVariables.GetEnvironmentVariable(envName); diff --git a/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/LambdaBootstrapMultiConcurrencyTests.cs b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/LambdaBootstrapMultiConcurrencyTests.cs index 06e7426cf..8b5d4671c 100644 --- a/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/LambdaBootstrapMultiConcurrencyTests.cs +++ b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/LambdaBootstrapMultiConcurrencyTests.cs @@ -14,6 +14,12 @@ namespace Amazon.Lambda.RuntimeSupport.UnitTests { + // These tests construct real LogLevelLoggerWriter instances (via TestMultiConcurrencyRuntimeApiClient) which, under + // JSON log format, build a JsonLogMessageFormatter that registers itself as the process-wide LambdaLogger + // structured-logging callback target. That is the same static state the StructuredLogging collection guards, so this + // class must run serially with those tests to avoid overwriting each other's callback registration. See + // https://github.com/aws/aws-lambda-dotnet/issues/2350. + [Collection("StructuredLogging")] public class LambdaBootstrapMultiConcurrencyTests { JsonSerializer _serializer = new JsonSerializer(); diff --git a/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/LogMessageFormatterTests.cs b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/LogMessageFormatterTests.cs index 936a8cb7c..92adaeedc 100644 --- a/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/LogMessageFormatterTests.cs +++ b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/LogMessageFormatterTests.cs @@ -12,6 +12,7 @@ namespace Amazon.Lambda.RuntimeSupport.UnitTests { + [Collection("StructuredLogging")] public class LogMessageFormatterTests { [Fact] diff --git a/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/SharedFormatterStructuredLoggingTests.cs b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/SharedFormatterStructuredLoggingTests.cs new file mode 100644 index 000000000..e056e8932 --- /dev/null +++ b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/SharedFormatterStructuredLoggingTests.cs @@ -0,0 +1,92 @@ +using System; +using System.Collections.Generic; +using System.IO; +using System.Text.Json; +using System.Text.Json.Serialization; +using Amazon.Lambda.RuntimeSupport.Helpers; +using Xunit; + +namespace Amazon.Lambda.RuntimeSupport.UnitTests +{ + /// + /// Regression tests for https://github.com/aws/aws-lambda-dotnet/issues/2350. + /// + /// LogLevelLoggerWriter creates two WrapperTextWriter instances (one for stdout, one for stderr). Before the + /// fix each writer constructed its OWN JsonLogMessageFormatter, and each formatter registered the customer's + /// LambdaLogger.ConfigureStructuredLogging callback through a single static setter on + /// Amazon.Lambda.Core.LambdaLogger, so the second construction overwrote the first. A customer calling + /// ConfigureStructuredLogging then only affected one formatter, while log messages written to stdout went + /// through the OTHER formatter that never received the custom JsonSerializerOptions. The fix makes both writers + /// share a single formatter instance. + /// + /// The test injects an IEnvironmentVariables so it never mutates the process-wide AWS_LAMBDA_LOG_FORMAT (which + /// would race with other tests). It is placed in the serial "StructuredLogging" collection because + /// ConfigureStructuredLogging mutates a process-wide static on LambdaLogger. + /// + [Collection("StructuredLogging")] + public class SharedFormatterStructuredLoggingTests + { + /// A value type that serializes to "{}" under default options (mirrors NodaTime.Instant). + private readonly struct Instant + { + private readonly DateTime _utc; + public Instant(DateTime utc) => _utc = utc; + public DateTime ToUtc() => _utc; + } + + /// Only this converter (registered via OverrideSerializerOptions) makes an Instant serialize to a value. + private sealed class InstantConverter : JsonConverter + { + public override Instant Read(ref Utf8JsonReader reader, Type typeToConvert, JsonSerializerOptions options) + => new Instant(reader.GetDateTime()); + + public override void Write(Utf8JsonWriter writer, Instant value, JsonSerializerOptions options) + => writer.WriteStringValue(value.ToUtc().ToString("yyyy-MM-ddTHH:mm:ssZ", System.Globalization.CultureInfo.InvariantCulture)); + } + + [Fact] + public void ConfigureStructuredLogging_CustomOptions_ReachFormatterUsedForStdout() + { + try + { + // JSON log format is supplied through an injected environment, so we do not touch the process-wide + // environment variable that other (parallel) tests read. + var environmentVariables = new TestEnvironmentVariables(new Dictionary + { + { "AWS_LAMBDA_LOG_FORMAT", "JSON" } + }); + + var stdout = new StringWriter(); + var stderr = new StringWriter(); + + // Constructing the writer creates the (now shared) JsonLogMessageFormatter and registers the + // ConfigureStructuredLogging callback. This is the same code path Lambda uses at startup. + var writer = new LogLevelLoggerWriter(environmentVariables, stdout, stderr); + + // Customer configures structured logging with a converter that only lives in the options collection. + var customOptions = new JsonSerializerOptions(); + customOptions.Converters.Add(new InstantConverter()); + Amazon.Lambda.Core.LambdaLogger.ConfigureStructuredLogging(new Amazon.Lambda.Core.StructuredLoggingOptions + { + OverrideSerializerOptions = customOptions + }); + + // Write a structured log with a destructured value type to STDOUT (the path customer logging uses). + var scheduled = new Instant(new DateTime(2026, 9, 1, 15, 40, 0, DateTimeKind.Utc)); + writer.FormattedWriteLine("Information", "scheduled {@scheduledDate}", scheduled); + + var output = stdout.ToString(); + + // With the fix the converter is applied and the ISO string appears. Without the fix the stdout + // formatter never received the options and the value serialized to "{}". + Assert.Contains("2026-09-01T15:40:00Z", output); + Assert.DoesNotContain("\"scheduledDate\":{}", output); + } + finally + { + // Reset the process-wide callback so this test does not affect others. + Amazon.Lambda.Core.LambdaLogger.ConfigureStructuredLogging(null); + } + } + } +} diff --git a/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/StructuredLoggingCollection.cs b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/StructuredLoggingCollection.cs new file mode 100644 index 000000000..2208bc94a --- /dev/null +++ b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/StructuredLoggingCollection.cs @@ -0,0 +1,16 @@ +using Xunit; + +namespace Amazon.Lambda.RuntimeSupport.UnitTests +{ + /// + /// Tests that call Amazon.Lambda.Core.LambdaLogger.ConfigureStructuredLogging mutate a process-wide + /// static callback on LambdaLogger and construct JsonLogMessageFormatter instances that register themselves as + /// that callback's target. If such tests run in parallel across classes they interfere with each other (the + /// last formatter constructed wins the static registration). Placing every such test in this single collection + /// makes xUnit run them serially. See https://github.com/aws/aws-lambda-dotnet/issues/2350. + /// + [CollectionDefinition("StructuredLogging")] + public class StructuredLoggingCollection + { + } +}