Skip to content

[Bug]: DurableLogger suppresses handler logs after a resumed wait #859

Open

Description

@zhongkechen

Expected Behavior

With default replay-log suppression enabled, a handler's previously unexecuted continuation after a durable wait should emit its logs on the resumed invocation. It must not require another durable operation after the wait to enable logging.

For a normal initial invocation followed by one resumed invocation, a log before the step and a log inside the step should each appear once, and the post-wait log should appear once on the resumed invocation. Logs belonging to replayed history should remain suppressed.

The Java logging documentation explicitly shows Continuing after wait as logged on replay because it is a new code path.

Actual Behavior

The execution successfully transitions from PENDING to SUCCEEDED, and the code immediately after the wait executes once. However, context.isReplaying() is still true, so DurableLogger skips the logger delegate and the post-wait record is lost.

Four local public-API diagnostic tests captured actual SLF4J delegate calls:

Scenario Observed records across initial invocation and resume
Step followed by a suspending wait, then a final handler log before=1, step=1, after=0; post-wait code reached once with isReplaying() == true
Log immediately after wait, then a new step, then another log The immediate post-wait log is absent; the log after the new step appears once
Replay suppression disabled using LoggerConfig.withReplayLogging() before=2, after=1
Completed callback resumed through callback.get(), then a handler log Post-callback code executes with isReplaying() == true; its log is absent

The four tests used no OTel plugin. Two additional local probes with Execution and Invocation OTel views also reproduced the missing terminal post-wait log. The defect is in the shared SDK replay/logging path and does not depend on trace view or JSON layout.

Steps to Reproduce

Place this diagnostic test under sdk-integration-tests/src/test/java/software/amazon/lambda/durable/PostWaitLoggingProbeTest.java. It uses existing test dependencies, the public handler API, and a recording SLF4J delegate. The three-minute wait is advanced by the local runner; no wall-clock wait or AWS call is needed.

The assertions below describe the current faulty behavior: the continuation runs, but its log never reaches the delegate. The fixed behavior should instead report List.of(false) for afterWaitReplay and include "after" in the final emitted-record list.

package software.amazon.lambda.durable;

import static org.junit.jupiter.api.Assertions.assertEquals;

import java.lang.reflect.Proxy;
import java.time.Duration;
import java.util.List;
import java.util.concurrent.CopyOnWriteArrayList;
import org.junit.jupiter.api.Test;
import org.slf4j.Logger;
import software.amazon.lambda.durable.model.ExecutionStatus;
import software.amazon.lambda.durable.testing.LocalDurableTestRunner;

class PostWaitLoggingProbeTest {
    @Test
    void resumedTerminalWaitExecutesNewCodeButSuppressesItsLog() {
        var emitted = new CopyOnWriteArrayList<String>();
        var afterWaitReplay = new CopyOnWriteArrayList<Boolean>();
        var logger = recordingLogger(emitted);
        var runner = LocalDurableTestRunner.create(String.class, (input, ctx) -> {
            ctx.getLogger(logger).info("before");
            ctx.step("work", String.class, step -> {
                step.getLogger(logger).info("step");
                return "ok";
            });
            ctx.wait("pause", Duration.ofMinutes(3));
            afterWaitReplay.add(ctx.isReplaying());
            ctx.getLogger(logger).info("after");
            return "done";
        });

        assertEquals(ExecutionStatus.PENDING, runner.run("input").getStatus());
        assertEquals(List.of("before", "step"), emitted);
        assertEquals(List.of(), afterWaitReplay);
        runner.advanceTime();
        assertEquals(ExecutionStatus.SUCCEEDED, runner.run("input").getStatus());
        assertEquals(List.of(true), afterWaitReplay);
        assertEquals(List.of("before", "step"), emitted);
    }

    private static Logger recordingLogger(List<String> emitted) {
        return (Logger) Proxy.newProxyInstance(
                Logger.class.getClassLoader(), new Class<?>[] {Logger.class}, (proxy, method, args) -> {
                    if (method.getName().equals("info")) emitted.add((String) args[0]);
                    if (method.getReturnType() == boolean.class) return true;
                    if (method.getName().equals("getName")) return "g05-probe";
                    return null;
                });
    }
}
mvn -pl sdk-integration-tests -am test -Dtest=PostWaitLoggingProbeTest \
  -Dsurefire.failIfNoSpecifiedTests=false

Root Cause

ExecutionManager also maintains a separate global replay state. Updating only that state will not fix the flag read by DurableLogger, and a global switch would lose the isolation needed by replaying child contexts.

Acceptance Criteria

  • Through the public API, verify the initial PENDING invocation and resumed SUCCEEDED invocation. The pre-step, step, and post-wait records each appear once; the post-wait record belongs to the resumed invocation.
  • Update the per-context replay state when the handler reaches previously unexecuted continuation code, even if no further durable operation is started. Keep logs from replayed history suppressed.
  • Cover the verified completed-callback resume case as well as the completed-wait case.
  • Cover asynchronous wait/result-consumption boundaries so that creating a future or completing it early does not prematurely enable logs from historical code.
  • Cover child contexts and concurrent branches; one context reaching new code must not enable replay logs in another context.
  • Preserve skipped completed user code, stored outcomes, stable operation identity, and checkpoint serialization. Keep default replay suppression enabled; adding an extra operation or globally enabling replay logs should not be required.
  • Add focused regression tests for actual logger emissions and align replay-state documentation with the corrected behavior.

The requested record counts describe the normal suspend/resume scenario above, not an exactly-once logging guarantee across arbitrary crashes or invocation retries.

SDK Version

Reproduced with SDK source 4b1aa82b0d898fea495cda45760ce3737fbb341e (Maven version 3.0.0), building the SDK and local testing modules together. The implicated replay/logger paths are unchanged at inspected main commit 1a501400d17532a30e4627f06ea516e0bed7b0cd.

Java Version

Java 21 for the four SDK-only diagnostic tests: 4 tests, 0 failures/errors/skips. Java 17 for the two additional OTel-view probes. These are local observations; this report does not claim a new cloud validation.

Is this a regression?

Unknown; no last working version has been established.

Related Issues

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't workingneeds-triageIssue needs triagepkg:sdkModule: sdk

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions