Skip to content
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
11 changes: 11 additions & 0 deletions .autover/changes/9efcd50c-f1a0-4b57-90e1-20b54c382f2e.json
Original file line number Diff line number Diff line change
@@ -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."
]
}
]
}
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
49 changes: 48 additions & 1 deletion Libraries/src/Amazon.Lambda.RuntimeSupport/Helpers/Utils.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

/// <summary>
/// Determines if the customer configured the Lambda function to use the JSON log format. This mirrors the
/// resolution done by <see cref="LogLevelLoggerWriter"/>: the .NET runtime specific environment variable is
/// checked first, falling back to the Lambda platform environment variable.
/// </summary>
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);
}

/// <summary>
/// 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.
/// </summary>
internal static void EmitWorkerPoolInitializingLog(IConsoleLoggerWriter consoleLogger, IEnvironmentVariables environmentVariables, int workerCount, int maxConcurrency)
{
if (consoleLogger == null)
return;

if (!IsUsingMultiConcurrency(environmentVariables) || !IsJsonLogFormat(environmentVariables))
Comment thread
normj marked this conversation as resolved.
return;

consoleLogger.FormattedWriteLine(
LogLevelLoggerWriter.LogLevel.Debug.ToString(),
WorkerPoolInitializingLogTemplate,
WorkerPoolInitializingEvent,
workerCount,
maxConcurrency);
}

/// <summary>
/// Determines if the Lambda function is running in multi concurrency mode.
/// </summary>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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<string, IEnumerable<string>> CreateDefaultHeaders(string requestId, string traceId)
{
return new Dictionary<string, IEnumerable<string>>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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()
{
Expand Down
Original file line number Diff line number Diff line change
@@ -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
{
/// <summary>
/// Capturing implementation of <see cref="IConsoleLoggerWriter"/> used by tests to assert what was logged
/// without touching the real console writers.
/// </summary>
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));
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -32,7 +32,7 @@ public TestMultiConcurrencyRuntimeApiClient(IEnvironmentVariables environmentVar
ConsoleLogger = new LogLevelLoggerWriter(environmentVariables);
}

public IConsoleLoggerWriter ConsoleLogger { get; }
public IConsoleLoggerWriter ConsoleLogger { get; set; }

public class InvocationEvent
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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)]
Expand Down
Loading