diff --git a/.autover/changes/9efcd50c-f1a0-4b57-90e1-20b54c382f2e.json b/.autover/changes/9efcd50c-f1a0-4b57-90e1-20b54c382f2e.json new file mode 100644 index 000000000..1703552ac --- /dev/null +++ b/.autover/changes/9efcd50c-f1a0-4b57-90e1-20b54c382f2e.json @@ -0,0 +1,11 @@ +{ + "Projects": [ + { + "Name": "Amazon.Lambda.RuntimeSupport", + "Type": "Patch", + "ChangelogMessages": [ + "In Lambda managed instances (multi-concurrency) mode, emit a structured DEBUG log during init reporting the worker count and execution environment max concurrency when the JSON log format is enabled." + ] + } + ] +} diff --git a/Libraries/src/Amazon.Lambda.RuntimeSupport/Bootstrap/LambdaBootstrap.cs b/Libraries/src/Amazon.Lambda.RuntimeSupport/Bootstrap/LambdaBootstrap.cs index 87445c768..61012ac09 100644 --- a/Libraries/src/Amazon.Lambda.RuntimeSupport/Bootstrap/LambdaBootstrap.cs +++ b/Libraries/src/Amazon.Lambda.RuntimeSupport/Bootstrap/LambdaBootstrap.cs @@ -294,6 +294,15 @@ internal LambdaBootstrap(HttpClient httpClient, LambdaBootstrapHandler handler, var processingTasksCount = Utils.DetermineProcessingTaskCount(_environmentVariables, Environment.ProcessorCount); _logger.LogInformation($"Using {processingTasksCount} tasks for invoke processing loops"); + // In multi concurrency (Lambda managed instances) mode, emit a one time DEBUG log reporting the worker + // count and execution environment max concurrency for observability. This is a no-op unless the function + // is in multi concurrency mode with the JSON log format configured. + Utils.EmitWorkerPoolInitializingLog( + Client.ConsoleLogger, + _environmentVariables, + processingTasksCount, + Utils.GetMaxConcurrency(_environmentVariables)); + if (processingTasksCount == 1) { await ProcessingLoop(runOnce, cancellationToken); diff --git a/Libraries/src/Amazon.Lambda.RuntimeSupport/Helpers/Utils.cs b/Libraries/src/Amazon.Lambda.RuntimeSupport/Helpers/Utils.cs index 1b99448b8..845814dcc 100644 --- a/Libraries/src/Amazon.Lambda.RuntimeSupport/Helpers/Utils.cs +++ b/Libraries/src/Amazon.Lambda.RuntimeSupport/Helpers/Utils.cs @@ -21,12 +21,59 @@ namespace Amazon.Lambda.RuntimeSupport.Helpers { internal static class Utils { + // The event name emitted in the worker pool initialization debug log. This matches the event name used by the + // Java and Python Lambda runtimes so the log is queryable consistently across languages. + internal const string WorkerPoolInitializingEvent = "runtime_worker_pool_initializing"; + + // The message template used for the worker pool initialization debug log. The named properties are emitted as + // top level fields in the structured JSON log (event, workerCount, executionEnvironmentMaxConcurrency). + internal const string WorkerPoolInitializingLogTemplate = "{event} workerCount={workerCount} executionEnvironmentMaxConcurrency={executionEnvironmentMaxConcurrency}"; + public static bool IsRunningNativeAot() { - // If dynamic code is not supported we are most likely running in an AOT environment. + // If dynamic code is not supported we are most likely running in an AOT environment. return !RuntimeFeature.IsDynamicCodeSupported; } + /// + /// Determines if the customer configured the Lambda function to use the JSON log format. This mirrors the + /// resolution done by : the .NET runtime specific environment variable is + /// checked first, falling back to the Lambda platform environment variable. + /// + internal static bool IsJsonLogFormat(IEnvironmentVariables environmentVariables) + { + var logFormat = environmentVariables.GetEnvironmentVariable(Constants.NET_RIC_LOG_FORMAT_ENVIRONMENT_VARIABLE); + if (string.IsNullOrEmpty(logFormat)) + { + logFormat = environmentVariables.GetEnvironmentVariable(Constants.LAMBDA_LOG_FORMAT_ENVIRONMENT_VARIABLE); + } + + return string.Equals(logFormat, Constants.LAMBDA_LOG_FORMAT_JSON, StringComparison.OrdinalIgnoreCase); + } + + /// + /// Emits a one time DEBUG log during init reporting the number of worker (processing) tasks and the execution + /// environment max concurrency. This is only emitted when the function is running in multi concurrency mode + /// (Lambda managed instances) and the JSON log format is configured. The DEBUG level means the log is only + /// surfaced when the function log level is set to Debug or Trace; that filtering is handled by the console + /// logger writer so it is not re-checked here. + /// + internal static void EmitWorkerPoolInitializingLog(IConsoleLoggerWriter consoleLogger, IEnvironmentVariables environmentVariables, int workerCount, int maxConcurrency) + { + if (consoleLogger == null) + return; + + if (!IsUsingMultiConcurrency(environmentVariables) || !IsJsonLogFormat(environmentVariables)) + return; + + consoleLogger.FormattedWriteLine( + LogLevelLoggerWriter.LogLevel.Debug.ToString(), + WorkerPoolInitializingLogTemplate, + WorkerPoolInitializingEvent, + workerCount, + maxConcurrency); + } + /// /// Determines if the Lambda function is running in multi concurrency mode. /// 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 baf8854b3..06e7426cf 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 @@ -3,9 +3,11 @@ using System; using System.Collections.Concurrent; using System.Collections.Generic; +using System.Linq; using System.Threading; using System.Threading.Tasks; using Amazon.Lambda.Core; +using Amazon.Lambda.RuntimeSupport.Helpers; using Amazon.Lambda.RuntimeSupport.UnitTests.TestHelpers; using Amazon.Lambda.Serialization.Json; using Xunit; @@ -197,6 +199,69 @@ public async Task ThreadPoolStarvation_BlockingHandlers_AllInvocationsDequeued() } } + [Theory] + [InlineData(true, 1)] // Multi concurrency + JSON log format => emitted exactly once. + [InlineData(false, 0)] // Multi concurrency without JSON log format => not emitted. + public async Task WorkerPoolInitializingLog_EmissionGatedByJsonLogFormat(bool jsonLogFormat, int expectedEmissions) + { + TestEnvironmentVariables environmentVariables = new TestEnvironmentVariables(); + environmentVariables.SetEnvironmentVariable( + Amazon.Lambda.RuntimeSupport.Bootstrap.Constants.ENVIRONMENT_VARIABLE_AWS_LAMBDA_MAX_CONCURRENCY, "2"); + if (jsonLogFormat) + { + environmentVariables.SetEnvironmentVariable( + Amazon.Lambda.RuntimeSupport.Bootstrap.Constants.NET_RIC_LOG_FORMAT_ENVIRONMENT_VARIABLE, "Json"); + } + + var capturingLogger = new CapturingConsoleLoggerWriter(); + var testRuntimeApiClient = new TestMultiConcurrencyRuntimeApiClient(environmentVariables, + new TestMultiConcurrencyRuntimeApiClient.InvocationEvent + { + Headers = CreateDefaultHeaders("request1", "trace1"), + FunctionInput = CreateFunctionInput(new SleepTimeEvent(0, 0)) + }) + { + ConsoleLogger = capturingLogger + }; + + var handler = HandlerWrapper.GetHandlerWrapper((SleepTimeEvent sleepTime, ILambdaContext context) => { }, _serializer).Handler; + + var lambdaBootstrap = new LambdaBootstrap( + httpClient: null, + handler: handler, + initializer: null, + ownsHttpClient: true, + environmentVariables: environmentVariables); + lambdaBootstrap.Client = testRuntimeApiClient; + + try + { + CancellationTokenSource cts = new CancellationTokenSource(); + cts.CancelAfter(TimeSpan.FromSeconds(3)); + await lambdaBootstrap.RunAsync(cts.Token); + } + catch (OperationCanceledException) + { + // Expected when the cancellation token is triggered. + } + + var workerPoolWrites = capturingLogger.Writes + .Where(w => w.Args != null && w.Args.Length > 0 && Equals(w.Args[0], Helpers.Utils.WorkerPoolInitializingEvent)) + .ToList(); + + Assert.Equal(expectedEmissions, workerPoolWrites.Count); + + if (expectedEmissions > 0) + { + var write = workerPoolWrites[0]; + Assert.Equal(LogLevelLoggerWriter.LogLevel.Debug.ToString(), write.Level); + Assert.Equal(Helpers.Utils.WorkerPoolInitializingLogTemplate, write.Message); + // Worker count defaults to the max concurrency (2) and max concurrency is 2. + Assert.Equal(2, write.Args[1]); + Assert.Equal(2, write.Args[2]); + } + } + private Dictionary> CreateDefaultHeaders(string requestId, string traceId) { return new Dictionary> 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 6bd724de5..936a8cb7c 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 @@ -80,6 +80,32 @@ public void FormatJsonWithNoMessageProperties() Assert.Equal("Simple Log Message", doc.RootElement.GetProperty("message").GetString()); } + [Fact] + public void FormatWorkerPoolInitializingEvent() + { + var timestamp = DateTime.UtcNow; + var formattedTimestamp = timestamp.ToString("yyyy-MM-ddTHH:mm:ss.fffZ"); + + var formatter = new JsonLogMessageFormatter(); + var state = new MessageState() + { + Level = Helpers.LogLevelLoggerWriter.LogLevel.Debug, + MessageTemplate = Utils.WorkerPoolInitializingLogTemplate, + // Use distinct worker count and max concurrency values to confirm they are reported as separate fields. + MessageArguments = new object[] { Utils.WorkerPoolInitializingEvent, 3, 10 }, + TimeStamp = timestamp + }; + + var json = formatter.FormatMessage(state); + var doc = JsonDocument.Parse(json); + + Assert.Equal(formattedTimestamp, doc.RootElement.GetProperty("timestamp").GetString()); + Assert.Equal("Debug", doc.RootElement.GetProperty("level").GetString()); + Assert.Equal("runtime_worker_pool_initializing", doc.RootElement.GetProperty("event").GetString()); + Assert.Equal(3, doc.RootElement.GetProperty("workerCount").GetInt32()); + Assert.Equal(10, doc.RootElement.GetProperty("executionEnvironmentMaxConcurrency").GetInt32()); + } + [Fact] public void FormatTenantId() { diff --git a/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/TestHelpers/CapturingConsoleLoggerWriter.cs b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/TestHelpers/CapturingConsoleLoggerWriter.cs new file mode 100644 index 000000000..dd95320d5 --- /dev/null +++ b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/TestHelpers/CapturingConsoleLoggerWriter.cs @@ -0,0 +1,26 @@ +// Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +using System; +using System.Collections.Generic; +using Amazon.Lambda.RuntimeSupport.Helpers; + +namespace Amazon.Lambda.RuntimeSupport.UnitTests.TestHelpers +{ + /// + /// Capturing implementation of used by tests to assert what was logged + /// without touching the real console writers. + /// + internal class CapturingConsoleLoggerWriter : IConsoleLoggerWriter + { + public List<(string Level, string Message, object[] Args)> Writes { get; } = new(); + + public void SetRuntimeHeaders(IRuntimeApiHeaders runtimeApiHeaders) { } + + public void FormattedWriteLine(string message) => Writes.Add((null, message, null)); + + public void FormattedWriteLine(string level, string message, params object[] args) => Writes.Add((level, message, args)); + + public void FormattedWriteLine(string level, Exception exception, string message, params object[] args) => Writes.Add((level, message, args)); + } +} diff --git a/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/TestHelpers/TestMultiConcurrencyRuntimeApiClient.cs b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/TestHelpers/TestMultiConcurrencyRuntimeApiClient.cs index 4d7f4493c..eb95afaa3 100644 --- a/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/TestHelpers/TestMultiConcurrencyRuntimeApiClient.cs +++ b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/TestHelpers/TestMultiConcurrencyRuntimeApiClient.cs @@ -32,7 +32,7 @@ public TestMultiConcurrencyRuntimeApiClient(IEnvironmentVariables environmentVar ConsoleLogger = new LogLevelLoggerWriter(environmentVariables); } - public IConsoleLoggerWriter ConsoleLogger { get; } + public IConsoleLoggerWriter ConsoleLogger { get; set; } public class InvocationEvent { diff --git a/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/UtilsTest.cs b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/UtilsTest.cs index a41e809ac..627d043ec 100644 --- a/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/UtilsTest.cs +++ b/Libraries/test/Amazon.Lambda.RuntimeSupport.Tests/Amazon.Lambda.RuntimeSupport.UnitTests/UtilsTest.cs @@ -5,12 +5,76 @@ using Amazon.Lambda.RuntimeSupport.Helpers; using Xunit; using Amazon.Lambda.RuntimeSupport.Bootstrap; +using Amazon.Lambda.RuntimeSupport.UnitTests.TestHelpers; namespace Amazon.Lambda.RuntimeSupport.UnitTests; public class UtilsTest { + [Theory] + // .NET runtime specific variable takes precedence. + [InlineData("Json", null, true)] + [InlineData("json", null, true)] + [InlineData("Text", null, false)] + // Falls back to the Lambda platform variable when the .NET one is not set. + [InlineData(null, "Json", true)] + [InlineData(null, "Text", false)] + // The .NET variable wins over the platform variable. + [InlineData("Text", "Json", false)] + [InlineData("Json", "Text", true)] + [InlineData(null, null, false)] + public void IsJsonLogFormat(string ricLogFormat, string lambdaLogFormat, bool expected) + { + var envVars = new TestEnvironmentVariables(); + if (ricLogFormat != null) + envVars.SetEnvironmentVariable(Constants.NET_RIC_LOG_FORMAT_ENVIRONMENT_VARIABLE, ricLogFormat); + if (lambdaLogFormat != null) + envVars.SetEnvironmentVariable(Constants.LAMBDA_LOG_FORMAT_ENVIRONMENT_VARIABLE, lambdaLogFormat); + + Assert.Equal(expected, Utils.IsJsonLogFormat(envVars)); + } + + [Fact] + public void EmitWorkerPoolInitializingLog_WhenMultiConcurrencyAndJson_EmitsOnce() + { + var envVars = new TestEnvironmentVariables(); + envVars.SetEnvironmentVariable(Constants.ENVIRONMENT_VARIABLE_AWS_LAMBDA_MAX_CONCURRENCY, "10"); + envVars.SetEnvironmentVariable(Constants.NET_RIC_LOG_FORMAT_ENVIRONMENT_VARIABLE, "Json"); + var logger = new CapturingConsoleLoggerWriter(); + + // Use a worker count that differs from the max concurrency to confirm the two values are reported distinctly. + Utils.EmitWorkerPoolInitializingLog(logger, envVars, workerCount: 3, maxConcurrency: 10); + + var write = Assert.Single(logger.Writes); + Assert.Equal(LogLevelLoggerWriter.LogLevel.Debug.ToString(), write.Level); + Assert.Equal(Utils.WorkerPoolInitializingLogTemplate, write.Message); + Assert.Equal(new object[] { Utils.WorkerPoolInitializingEvent, 3, 10 }, write.Args); + } + + [Fact] + public void EmitWorkerPoolInitializingLog_WhenMultiConcurrencyButNotJson_DoesNotEmit() + { + var envVars = new TestEnvironmentVariables(); + envVars.SetEnvironmentVariable(Constants.ENVIRONMENT_VARIABLE_AWS_LAMBDA_MAX_CONCURRENCY, "10"); + var logger = new CapturingConsoleLoggerWriter(); + + Utils.EmitWorkerPoolInitializingLog(logger, envVars, workerCount: 10, maxConcurrency: 10); + + Assert.Empty(logger.Writes); + } + + [Fact] + public void EmitWorkerPoolInitializingLog_WhenNotMultiConcurrency_DoesNotEmit() + { + var envVars = new TestEnvironmentVariables(); + envVars.SetEnvironmentVariable(Constants.NET_RIC_LOG_FORMAT_ENVIRONMENT_VARIABLE, "Json"); + var logger = new CapturingConsoleLoggerWriter(); + + Utils.EmitWorkerPoolInitializingLog(logger, envVars, workerCount: 1, maxConcurrency: 0); + + Assert.Empty(logger.Writes); + } [Theory] [InlineData("5", true)] [InlineData("", false)]