diff --git a/Libraries/src/Amazon.Lambda.DurableExecution/DurableContext.cs b/Libraries/src/Amazon.Lambda.DurableExecution/DurableContext.cs index 87a874c2d..37c07f90d 100644 --- a/Libraries/src/Amazon.Lambda.DurableExecution/DurableContext.cs +++ b/Libraries/src/Amazon.Lambda.DurableExecution/DurableContext.cs @@ -2,7 +2,6 @@ using Amazon.Lambda.Core; using Amazon.Lambda.DurableExecution.Internal; using Microsoft.Extensions.Logging; -using Microsoft.Extensions.Logging.Abstractions; namespace Amazon.Lambda.DurableExecution; @@ -18,6 +17,7 @@ internal sealed class DurableContext : IDurableContext private readonly OperationIdGenerator _idGenerator; private readonly string _durableExecutionArn; private readonly CheckpointBatcher? _batcher; + private ILogger _logger; public DurableContext( ExecutionState state, @@ -33,13 +33,25 @@ public DurableContext( _durableExecutionArn = durableExecutionArn; _batcher = batcher; LambdaContext = lambdaContext; + _logger = new ReplayAwareLogger(new LambdaCoreLogger(), state, modeAware: true); } - // Replay-safe logger ships in a follow-up PR; see IDurableContext.Logger doc. - public ILogger Logger => NullLogger.Instance; + public ILogger Logger => _logger; public IExecutionContext ExecutionContext => new DurableExecutionContext(_durableExecutionArn); public ILambdaContext LambdaContext { get; } + public void ConfigureLogger(LoggerConfig config) + { + if (config == null) throw new ArgumentNullException(nameof(config)); + + // If the user supplies a CustomLogger, wrap it. Otherwise re-wrap the + // existing inner logger (unwrapping if it was already a ReplayAwareLogger) + // so toggling ModeAware works without losing the previous custom logger. + var inner = config.CustomLogger + ?? (_logger is ReplayAwareLogger existing ? existing.Inner : _logger); + _logger = new ReplayAwareLogger(inner, _state, config.ModeAware); + } + [RequiresUnreferencedCode("Reflection-based JSON for T. Use the ICheckpointSerializer overload for AOT/trimmed deployments.")] [RequiresDynamicCode("Reflection-based JSON for T. Use the ICheckpointSerializer overload for AOT/trimmed deployments.")] public Task StepAsync( diff --git a/Libraries/src/Amazon.Lambda.DurableExecution/DurableFunction.cs b/Libraries/src/Amazon.Lambda.DurableExecution/DurableFunction.cs index d629a0b2e..fd8c86f71 100644 --- a/Libraries/src/Amazon.Lambda.DurableExecution/DurableFunction.cs +++ b/Libraries/src/Amazon.Lambda.DurableExecution/DurableFunction.cs @@ -9,6 +9,7 @@ using Amazon.Lambda.DurableExecution.Services; using Amazon.Lambda.Model; using Amazon.Runtime; +using Microsoft.Extensions.Logging; namespace Amazon.Lambda.DurableExecution; @@ -180,9 +181,20 @@ private static async Task WrapAsyncCore result; try { - result = await DurableExecutionHandler.RunAsync( - state, terminationManager, - async () => await workflow(userPayload, context)); + // Push execution-level metadata into a logging scope so structured + // providers (the runtime's JSON formatter, Serilog, Powertools, + // etc.) tag every log line emitted by user code with the + // execution ARN and request id. + using (context.Logger.BeginScope(new Dictionary + { + ["durableExecutionArn"] = invocationInput.DurableExecutionArn, + ["awsRequestId"] = lambdaContext.AwsRequestId ?? string.Empty, + })) + { + result = await DurableExecutionHandler.RunAsync( + state, terminationManager, + async () => await workflow(userPayload, context)); + } await batcher.DrainAsync(); } diff --git a/Libraries/src/Amazon.Lambda.DurableExecution/IDurableContext.cs b/Libraries/src/Amazon.Lambda.DurableExecution/IDurableContext.cs index ff18d1218..a66c29cb2 100644 --- a/Libraries/src/Amazon.Lambda.DurableExecution/IDurableContext.cs +++ b/Libraries/src/Amazon.Lambda.DurableExecution/IDurableContext.cs @@ -13,13 +13,21 @@ namespace Amazon.Lambda.DurableExecution; public interface IDurableContext { /// - /// A logger scoped to the durable execution. Currently returns - /// ; - /// the replay-safe DurableLogger (suppresses messages during replay) - /// ships in a follow-up PR. + /// Replay-safe logger. Messages emitted while the workflow is re-deriving + /// prior operations from checkpointed state are suppressed by default, so + /// a 30-step workflow re-invoked 30 times still emits each line once. + /// Use this instead of Console.WriteLine or other ambient loggers, + /// which will repeat on every replay. Replace the underlying logger or + /// disable replay-aware filtering via . /// ILogger Logger { get; } + /// + /// Swap the underlying logger or toggle replay-aware filtering. Idempotent — + /// later calls overwrite earlier configuration. + /// + void ConfigureLogger(LoggerConfig config); + /// /// Metadata about the current durable execution. /// @@ -81,7 +89,10 @@ Task WaitAsync( public interface IStepContext { /// - /// Logger scoped to this step. + /// Logger scoped to this step. Same instance as + /// ; emits within an + /// that carries the step's + /// operationId, operationName, and attempt. /// ILogger Logger { get; } diff --git a/Libraries/src/Amazon.Lambda.DurableExecution/Internal/LambdaCoreLogger.cs b/Libraries/src/Amazon.Lambda.DurableExecution/Internal/LambdaCoreLogger.cs new file mode 100644 index 000000000..a8ee08fa6 --- /dev/null +++ b/Libraries/src/Amazon.Lambda.DurableExecution/Internal/LambdaCoreLogger.cs @@ -0,0 +1,61 @@ +using Microsoft.Extensions.Logging; +using CoreLambdaLogger = Amazon.Lambda.Core.LambdaLogger; + +namespace Amazon.Lambda.DurableExecution.Internal; + +/// +/// Default for . Routes log +/// records through so they flow into the same +/// pipeline used by the rest of the AWS Lambda for .NET runtime — the runtime +/// host installs a redirector that produces structured JSON when +/// AWS_LAMBDA_LOG_FORMAT=JSON and honors AWS_LAMBDA_LOG_LEVEL. +/// +/// +/// In-package adapter to avoid forcing a dependency on +/// Amazon.Lambda.Logging.AspNetCore; users who want a richer experience +/// (Serilog, Powertools, etc.) can swap their own logger via +/// . +/// +/// Implementation note: we always pass the pre-rendered message to +/// rather than the +/// raw template plus args. The runtime's text-mode formatter feeds args through +/// string.Format, which throws on named placeholders ({OrderId}); +/// rendering up-front via the supplied formatter substitutes them correctly +/// regardless of the runtime log format. +/// +internal sealed class LambdaCoreLogger : ILogger +{ + private static readonly NullScope SharedScope = new(); + + public IDisposable? BeginScope(TState state) where TState : notnull => SharedScope; + + // Level filtering is performed by the runtime layer (AWS_LAMBDA_LOG_LEVEL). + public bool IsEnabled(LogLevel logLevel) => logLevel != LogLevel.None; + + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + if (!IsEnabled(logLevel)) return; + + var message = formatter(state, exception); + var levelName = logLevel.ToString(); + + if (exception != null) + { + CoreLambdaLogger.Log(levelName, exception, message); + } + else + { + CoreLambdaLogger.Log(levelName, message); + } + } + + private sealed class NullScope : IDisposable + { + public void Dispose() { } + } +} diff --git a/Libraries/src/Amazon.Lambda.DurableExecution/Internal/ReplayAwareLogger.cs b/Libraries/src/Amazon.Lambda.DurableExecution/Internal/ReplayAwareLogger.cs new file mode 100644 index 000000000..5e24f53fe --- /dev/null +++ b/Libraries/src/Amazon.Lambda.DurableExecution/Internal/ReplayAwareLogger.cs @@ -0,0 +1,57 @@ +using Microsoft.Extensions.Logging; + +namespace Amazon.Lambda.DurableExecution.Internal; + +/// +/// decorator that suppresses messages while the workflow +/// is replaying prior operations. Reads +/// on every call so it correctly transitions to passthrough the moment the +/// state's per-operation tracker decides we've caught up to fresh execution. +/// +/// +/// Mirrors the suppression behavior of the Python and Java durable execution +/// SDKs: replay calls return without invoking the +/// inner logger. always delegates so scopes +/// stay balanced — suppression only applies at log emission. +/// +internal sealed class ReplayAwareLogger : ILogger +{ + private readonly ILogger _inner; + private readonly ExecutionState _state; + private readonly bool _modeAware; + + public ReplayAwareLogger(ILogger inner, ExecutionState state, bool modeAware) + { + _inner = inner; + _state = state; + _modeAware = modeAware; + } + + /// The wrapped logger; exposed so ConfigureLogger can rewrap without losing it. + public ILogger Inner => _inner; + + /// Whether replay suppression is active. + public bool ModeAware => _modeAware; + + public IDisposable? BeginScope(TState state) where TState : notnull + => _inner.BeginScope(state); + + public bool IsEnabled(LogLevel logLevel) + { + if (ShouldSuppress()) return false; + return _inner.IsEnabled(logLevel); + } + + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + if (ShouldSuppress()) return; + _inner.Log(logLevel, eventId, state, exception, formatter); + } + + private bool ShouldSuppress() => _modeAware && _state.IsReplaying; +} diff --git a/Libraries/src/Amazon.Lambda.DurableExecution/Internal/StepOperation.cs b/Libraries/src/Amazon.Lambda.DurableExecution/Internal/StepOperation.cs index 54e52005d..912ba93f5 100644 --- a/Libraries/src/Amazon.Lambda.DurableExecution/Internal/StepOperation.cs +++ b/Libraries/src/Amazon.Lambda.DurableExecution/Internal/StepOperation.cs @@ -189,7 +189,21 @@ private async Task ExecuteFunc(int attemptNumber, CancellationToken cancellat try { var stepContext = new StepContext(OperationId, attemptNumber, _logger); - var result = await _func(stepContext); + + // Step-scoped metadata so structured log providers tag user code + // lines with the operation id, name, and current attempt. Wrap + // only the user-func call — checkpoint emission shouldn't carry + // step metadata into any side-channel logging. + T result; + using (_logger.BeginScope(new Dictionary + { + ["operationId"] = OperationId, + ["operationName"] = Name ?? string.Empty, + ["attempt"] = attemptNumber, + })) + { + result = await _func(stepContext); + } await EnqueueAsync(new SdkOperationUpdate { diff --git a/Libraries/src/Amazon.Lambda.DurableExecution/LoggerConfig.cs b/Libraries/src/Amazon.Lambda.DurableExecution/LoggerConfig.cs new file mode 100644 index 000000000..801d0a7c9 --- /dev/null +++ b/Libraries/src/Amazon.Lambda.DurableExecution/LoggerConfig.cs @@ -0,0 +1,24 @@ +using Microsoft.Extensions.Logging; + +namespace Amazon.Lambda.DurableExecution; + +/// +/// Configuration for . Lets users +/// swap the underlying (e.g. Serilog, AWS Lambda Powertools) +/// or disable replay-aware filtering for debugging. +/// +public sealed class LoggerConfig +{ + /// + /// Optional to use instead of the SDK default. When + /// null, the durable context keeps its existing inner logger. + /// + public ILogger? CustomLogger { get; init; } + + /// + /// When true (default), messages are suppressed while the workflow is + /// re-deriving prior operations from checkpointed state. Set to false to + /// see every log line on every replay (useful for local debugging). + /// + public bool ModeAware { get; init; } = true; +} diff --git a/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/Amazon.Lambda.DurableExecution.IntegrationTests.csproj b/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/Amazon.Lambda.DurableExecution.IntegrationTests.csproj index 0ef2e561d..8dda2b047 100644 --- a/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/Amazon.Lambda.DurableExecution.IntegrationTests.csproj +++ b/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/Amazon.Lambda.DurableExecution.IntegrationTests.csproj @@ -31,6 +31,7 @@ + diff --git a/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/ReplayAwareLoggerTest.cs b/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/ReplayAwareLoggerTest.cs new file mode 100644 index 000000000..88e7756fb --- /dev/null +++ b/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/ReplayAwareLoggerTest.cs @@ -0,0 +1,148 @@ +using System.Linq; +using System.Text; +using Amazon.CloudWatchLogs; +using Amazon.CloudWatchLogs.Model; +using Amazon.Lambda.Model; +using Xunit; +using Xunit.Abstractions; + +namespace Amazon.Lambda.DurableExecution.IntegrationTests; + +/// +/// End-to-end proof of the replay-aware logger: a workflow with a Wait between +/// two steps re-invokes Lambda once. Lines emitted via +/// context.Logger.LogInformation in the workflow body and after step 1 +/// must appear ONCE in CloudWatch (suppressed on the replay invocation), +/// while parallel Console.WriteLine control lines must appear TWICE +/// (proving the function genuinely replayed). +/// +public class ReplayAwareLoggerTest +{ + private readonly ITestOutputHelper _output; + public ReplayAwareLoggerTest(ITestOutputHelper output) => _output = output; + + [Fact] + public async Task ReplayAwareLogger_SuppressesDuplicateLogsOnReplay() + { + await using var deployment = await DurableFunctionDeployment.CreateAsync( + DurableFunctionDeployment.FindTestFunctionDir("ReplayAwareLoggerFunction"), + "logreplay", _output); + + var (invokeResponse, executionName) = await deployment.InvokeAsync("""{"orderId": "log-replay"}"""); + Assert.Equal(200, invokeResponse.StatusCode); + + var responsePayload = Encoding.UTF8.GetString(invokeResponse.Payload.ToArray()); + _output.WriteLine($"Response: {responsePayload}"); + + var arn = await deployment.FindDurableExecutionArnByNameAsync(executionName, TimeSpan.FromSeconds(60)); + Assert.NotNull(arn); + + var status = await deployment.PollForCompletionAsync(arn!, TimeSpan.FromSeconds(60)); + Assert.Equal("SUCCEEDED", status, ignoreCase: true); + + // Sanity check the durable history: two step events, one wait, one + // re-invocation. Confirms the workflow really did replay. + await deployment.WaitForHistoryAsync( + arn!, + h => (h.Events?.Count(e => e.EventType == EventType.StepStarted) ?? 0) >= 2 + && (h.Events?.Any(e => e.WaitSucceededDetails != null) ?? false), + TimeSpan.FromSeconds(60)); + + // CloudWatch is eventually consistent — wait until ALL log lines we + // expect have been ingested. The stop condition demands the full + // expected count of every marker so the test never short-circuits with + // a still-arriving "after_step1" record (which is emitted at a + // different timestamp than workflow_start and indexes independently). + using var logs = new AmazonCloudWatchLogsClient(RegionEndpoint.USEast1); + var logGroup = $"/aws/lambda/{deployment.FunctionName}"; + + var allEvents = await PollForLogEvents( + logs, logGroup, + stopWhen: events => + // Replay-aware: 1 each (suppressed on the second invocation). + CountMatching(events, "LOG_REPLAY_TEST workflow_start") >= 1 && + CountMatching(events, "LOG_REPLAY_TEST after_step1") >= 1 && + CountMatching(events, "LOG_REPLAY_TEST workflow_end") >= 1 && + // Control: workflow_start and after_step1 emit on both + // invocations (2 each); workflow_end only on the second (1). + CountMatching(events, "LOG_REPLAY_CONTROL workflow_start") >= 2 && + CountMatching(events, "LOG_REPLAY_CONTROL after_step1") >= 2 && + CountMatching(events, "LOG_REPLAY_CONTROL workflow_end") >= 1, + timeout: TimeSpan.FromMinutes(2)); + + var messages = allEvents.Select(e => e.Message ?? string.Empty).ToList(); + _output.WriteLine($"Collected {messages.Count} log events from {logGroup}"); + + // Replay-aware lines: each must appear exactly once across both invocations. + Assert.Equal(1, CountMatching(messages, "LOG_REPLAY_TEST workflow_start")); + Assert.Equal(1, CountMatching(messages, "LOG_REPLAY_TEST after_step1")); + Assert.Equal(1, CountMatching(messages, "LOG_REPLAY_TEST workflow_end")); + + // Control lines (Console.WriteLine, not replay-aware): the + // workflow-start and after_step1 markers run on both invocations and + // must appear twice; workflow_end runs only on the second invocation + // (after the Wait completes) so it appears once. + Assert.Equal(2, CountMatching(messages, "LOG_REPLAY_CONTROL workflow_start")); + Assert.Equal(2, CountMatching(messages, "LOG_REPLAY_CONTROL after_step1")); + Assert.Equal(1, CountMatching(messages, "LOG_REPLAY_CONTROL workflow_end")); + } + + private static int CountMatching(IEnumerable events, string substring) + => events.Count(e => e.Message != null && e.Message.Contains(substring, StringComparison.Ordinal)); + + private static int CountMatching(IEnumerable messages, string substring) + => messages.Count(m => m.Contains(substring, StringComparison.Ordinal)); + + private async Task> PollForLogEvents( + IAmazonCloudWatchLogs logs, + string logGroupName, + Func, bool> stopWhen, + TimeSpan timeout) + { + var deadline = DateTime.UtcNow + timeout; + var attempt = 0; + var lastSeen = new List(); + + // Filter only on our marker prefix to keep payload size small. + const string filterPattern = "\"LOG_REPLAY_\""; + + while (DateTime.UtcNow < deadline) + { + attempt++; + try + { + var events = new List(); + string? nextToken = null; + do + { + var resp = await logs.FilterLogEventsAsync(new FilterLogEventsRequest + { + LogGroupName = logGroupName, + FilterPattern = filterPattern, + NextToken = nextToken, + }); + if (resp.Events != null) events.AddRange(resp.Events); + nextToken = resp.NextToken; + } while (!string.IsNullOrEmpty(nextToken)); + + _output.WriteLine($"[CW poll {attempt}] events={events.Count}"); + lastSeen = events; + if (stopWhen(events)) return events; + } + catch (Amazon.CloudWatchLogs.Model.ResourceNotFoundException) + { + // Log group not yet provisioned — Lambda creates it on first + // invocation, but it can lag behind the function being Active. + _output.WriteLine($"[CW poll {attempt}] log group not yet present: {logGroupName}"); + } + catch (Exception ex) + { + _output.WriteLine($"[CW poll {attempt}] error (will retry): {ex.Message}"); + } + await Task.Delay(TimeSpan.FromSeconds(3)); + } + + _output.WriteLine($"[CW poll] gave up after {attempt} attempts; returning last-seen ({lastSeen.Count} events)"); + return lastSeen; + } +} diff --git a/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/TestFunctions/ReplayAwareLoggerFunction/Dockerfile b/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/TestFunctions/ReplayAwareLoggerFunction/Dockerfile new file mode 100644 index 000000000..c1913d56a --- /dev/null +++ b/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/TestFunctions/ReplayAwareLoggerFunction/Dockerfile @@ -0,0 +1,7 @@ +FROM public.ecr.aws/lambda/provided:al2023 + +RUN dnf install -y libicu + +COPY bin/publish/ ${LAMBDA_TASK_ROOT} + +ENTRYPOINT ["/var/task/bootstrap"] diff --git a/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/TestFunctions/ReplayAwareLoggerFunction/Function.cs b/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/TestFunctions/ReplayAwareLoggerFunction/Function.cs new file mode 100644 index 000000000..6f4774ef1 --- /dev/null +++ b/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/TestFunctions/ReplayAwareLoggerFunction/Function.cs @@ -0,0 +1,71 @@ +using Amazon.Lambda.Core; +using Amazon.Lambda.DurableExecution; +using Amazon.Lambda.RuntimeSupport; +using Amazon.Lambda.Serialization.SystemTextJson; +using Microsoft.Extensions.Logging; + +namespace DurableExecutionTestFunction; + +/// +/// Workflow used by ReplayAwareLoggerTest. Pairs each replay-aware +/// context.Logger.LogInformation line with a control +/// Console.WriteLine so the test can prove the SDK suppresses replay +/// duplicates: the LogInformation lines should appear exactly once across the +/// two invocations a Wait-driven workflow produces, while the Console.WriteLine +/// control lines should appear once per invocation. +/// +public class Function +{ + public static async Task Main(string[] args) + { + var handler = new Function(); + var serializer = new DefaultLambdaJsonSerializer(); + using var handlerWrapper = HandlerWrapper.GetHandlerWrapper(handler.Handler, serializer); + using var bootstrap = new LambdaBootstrap(handlerWrapper); + await bootstrap.RunAsync(); + } + + public Task Handler( + DurableExecutionInvocationInput input, ILambdaContext context) + => DurableFunction.WrapAsync(Workflow, input, context); + + private async Task Workflow(TestEvent input, IDurableContext context) + { + // Workflow-level: emitted on invocation 1, suppressed on invocation 2 (replay). + context.Logger.LogInformation("LOG_REPLAY_TEST workflow_start order={OrderId}", input.OrderId); + Console.WriteLine($"LOG_REPLAY_CONTROL workflow_start order={input.OrderId}"); + + var step1 = await context.StepAsync( + async (_) => + { + await Task.CompletedTask; + return $"validated-{input.OrderId}"; + }, + name: "validate"); + + // Between-step log: invocation 1 emits, invocation 2 is still in Replay + // (Wait-on-SUCCEEDED replay does not flip the mode), so it must be suppressed. + context.Logger.LogInformation("LOG_REPLAY_TEST after_step1 result={Result}", step1); + Console.WriteLine($"LOG_REPLAY_CONTROL after_step1 result={step1}"); + + await context.WaitAsync(TimeSpan.FromSeconds(3), name: "short_wait"); + + // Step 2 runs fresh on invocation 2 — its EnterExecutionMode flips the + // logger from suppress to passthrough. The next LogInformation lands. + var step2 = await context.StepAsync( + async (_) => + { + await Task.CompletedTask; + return $"processed-{step1}"; + }, + name: "process"); + + context.Logger.LogInformation("LOG_REPLAY_TEST workflow_end final={Final}", step2); + Console.WriteLine($"LOG_REPLAY_CONTROL workflow_end final={step2}"); + + return new TestResult { Status = "completed", Data = step2 }; + } +} + +public class TestEvent { public string? OrderId { get; set; } } +public class TestResult { public string? Status { get; set; } public string? Data { get; set; } } diff --git a/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/TestFunctions/ReplayAwareLoggerFunction/ReplayAwareLoggerFunction.csproj b/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/TestFunctions/ReplayAwareLoggerFunction/ReplayAwareLoggerFunction.csproj new file mode 100644 index 000000000..6f5f657e4 --- /dev/null +++ b/Libraries/test/Amazon.Lambda.DurableExecution.IntegrationTests/TestFunctions/ReplayAwareLoggerFunction/ReplayAwareLoggerFunction.csproj @@ -0,0 +1,18 @@ + + + + net8.0 + Exe + true + bootstrap + enable + enable + + + + + + + + + diff --git a/Libraries/test/Amazon.Lambda.DurableExecution.Tests/DurableContextTests.cs b/Libraries/test/Amazon.Lambda.DurableExecution.Tests/DurableContextTests.cs index cc3b9a460..7bd01e39d 100644 --- a/Libraries/test/Amazon.Lambda.DurableExecution.Tests/DurableContextTests.cs +++ b/Libraries/test/Amazon.Lambda.DurableExecution.Tests/DurableContextTests.cs @@ -1,8 +1,11 @@ using Amazon.Lambda.Core; using Amazon.Lambda.DurableExecution; using Amazon.Lambda.DurableExecution.Internal; +using Amazon.Lambda.DurableExecution.Tests.Internal; using Amazon.Lambda.TestUtilities; +using Microsoft.Extensions.Logging; using Xunit; +using LogLevel = Microsoft.Extensions.Logging.LogLevel; namespace Amazon.Lambda.DurableExecution.Tests; @@ -214,10 +217,61 @@ public async Task StepAsync_CustomSerializer_UsedForSerialization() } [Fact] - public void Logger_Defaults_ToNullLogger() + public void Logger_Default_IsReplayAwareLogger() { var context = CreateContext(); Assert.NotNull(context.Logger); + Assert.IsType(context.Logger); + } + + [Fact] + public void ConfigureLogger_NullArg_Throws() + { + var context = CreateContext(); + Assert.Throws(() => context.ConfigureLogger(null!)); + } + + [Fact] + public void ConfigureLogger_WithCustomLogger_ReachesUserLogger() + { + var context = CreateContext(); + var custom = new RecordingLogger(); + context.ConfigureLogger(new LoggerConfig { CustomLogger = custom }); + + // Default state has no checkpoint → starts in Execution mode, so + // logs flow through immediately. + context.Logger.LogInformation("hi"); + + Assert.Single(custom.Records); + Assert.Equal(LogLevel.Information, custom.Records[0].Level); + } + + [Fact] + public void ConfigureLogger_ModeAwareFalse_LogsDuringReplay() + { + // Seed a checkpoint so the context starts in Replay mode. + var custom = new RecordingLogger(); + var context = CreateContext(new InitialExecutionState + { + Operations = new List + { + new() + { + Id = IdAt(99), + Type = OperationTypes.Step, + Status = OperationStatuses.Succeeded + } + } + }); + + context.ConfigureLogger(new LoggerConfig { CustomLogger = custom, ModeAware = true }); + context.Logger.LogInformation("replay-default"); + Assert.Empty(custom.Records); + + context.ConfigureLogger(new LoggerConfig { ModeAware = false }); + context.Logger.LogInformation("replay-disabled"); + Assert.Single(custom.Records); + Assert.Contains("replay-disabled", custom.Records[0].Message); } [Fact] @@ -887,7 +941,7 @@ public async Task StepAsync_ReadyReplay_AdvancesAttemptAndExecutes() Assert.True(executed); Assert.Equal("ok", result); Assert.False(tm.IsTerminated); - Assert.Equal(ExecutionMode.Execution, state.Mode); + Assert.False(state.IsReplaying); } [Fact] diff --git a/Libraries/test/Amazon.Lambda.DurableExecution.Tests/Internal/ReplayAwareLoggerTests.cs b/Libraries/test/Amazon.Lambda.DurableExecution.Tests/Internal/ReplayAwareLoggerTests.cs new file mode 100644 index 000000000..dc92ccf79 --- /dev/null +++ b/Libraries/test/Amazon.Lambda.DurableExecution.Tests/Internal/ReplayAwareLoggerTests.cs @@ -0,0 +1,153 @@ +using Amazon.Lambda.DurableExecution.Internal; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace Amazon.Lambda.DurableExecution.Tests.Internal; + +public class ReplayAwareLoggerTests +{ + private const string SeedOpId = "seed"; + + private static ExecutionState ReplayState() + { + // Seed one completed user-replayable op so IsReplaying starts true. + // The op is NOT yet visited via TrackReplay, so we stay in replay. + var state = new ExecutionState(); + state.LoadFromCheckpoint(new InitialExecutionState + { + Operations = new List + { + new() { Id = SeedOpId, Type = OperationTypes.Step, Status = OperationStatuses.Succeeded } + } + }); + Assert.True(state.IsReplaying); + return state; + } + + [Fact] + public void Log_DuringReplay_Suppressed() + { + var inner = new RecordingLogger(); + var logger = new ReplayAwareLogger(inner, ReplayState(), modeAware: true); + + logger.LogInformation("hello"); + + Assert.Empty(inner.Records); + } + + [Fact] + public void Log_DuringExecution_Passthrough() + { + var state = ReplayState(); + state.TrackReplay(SeedOpId); + var inner = new RecordingLogger(); + var logger = new ReplayAwareLogger(inner, state, modeAware: true); + + logger.LogInformation("hello"); + + Assert.Single(inner.Records); + Assert.Equal(LogLevel.Information, inner.Records[0].Level); + } + + [Fact] + public void Log_ModeAwareFalse_AlwaysLogs() + { + var inner = new RecordingLogger(); + var logger = new ReplayAwareLogger(inner, ReplayState(), modeAware: false); + + logger.LogWarning("still here"); + + Assert.Single(inner.Records); + } + + [Fact] + public void IsEnabled_DuringReplay_ReturnsFalse() + { + var inner = new RecordingLogger { ForcedEnabled = true }; + var logger = new ReplayAwareLogger(inner, ReplayState(), modeAware: true); + + Assert.False(logger.IsEnabled(LogLevel.Information)); + } + + [Fact] + public void IsEnabled_DuringExecution_DelegatesToInner() + { + var state = ReplayState(); + state.TrackReplay(SeedOpId); + var inner = new RecordingLogger { ForcedEnabled = false }; + var logger = new ReplayAwareLogger(inner, state, modeAware: true); + + Assert.False(logger.IsEnabled(LogLevel.Information)); + + inner.ForcedEnabled = true; + Assert.True(logger.IsEnabled(LogLevel.Information)); + } + + [Fact] + public void BeginScope_AlwaysDelegates() + { + var inner = new RecordingLogger(); + var logger = new ReplayAwareLogger(inner, ReplayState(), modeAware: true); + + // Even during replay, scopes must pass through to keep the scope stack + // balanced. + using (logger.BeginScope("scope-during-replay")) + { + Assert.Equal(1, inner.OpenScopes); + } + Assert.Equal(0, inner.OpenScopes); + } + + [Fact] + public void Log_TransitionsFromReplayToExecution() + { + // Mirror Python's test_logger_replay_then_new_logging: while the state + // is replaying the logger drops messages, but the moment TrackReplay + // visits the last checkpointed op IsReplaying flips and the next log + // line lands. + var state = ReplayState(); + var inner = new RecordingLogger(); + var logger = new ReplayAwareLogger(inner, state, modeAware: true); + + logger.LogInformation("during replay"); + Assert.Empty(inner.Records); + + state.TrackReplay(SeedOpId); + logger.LogInformation("after transition"); + + Assert.Single(inner.Records); + Assert.Contains("after transition", inner.Records[0].Message); + } +} + +internal sealed class RecordingLogger : ILogger +{ + public List<(LogLevel Level, string Message)> Records { get; } = new(); + public int OpenScopes { get; private set; } + public bool ForcedEnabled { get; set; } = true; + + public IDisposable BeginScope(TState state) where TState : notnull + { + OpenScopes++; + return new ScopeToken(this); + } + + public bool IsEnabled(LogLevel logLevel) => ForcedEnabled; + + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + Records.Add((logLevel, formatter(state, exception))); + } + + private sealed class ScopeToken : IDisposable + { + private readonly RecordingLogger _owner; + public ScopeToken(RecordingLogger owner) => _owner = owner; + public void Dispose() => _owner.OpenScopes--; + } +}