Repository navigation
[Bug]: DurableLogger suppresses handler logs after a resumed wait #859
Description
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=falseRoot Cause
DurableContextImplinitializes its per-context replay flag to true when that context has cached operations.BaseDurableOperation.execute()clears that flag only when it encounters an operation with no cached checkpoint.WaitOperation.replay()marks an alreadySUCCEEDEDwait complete and returns. Consuming its result does not advance the context out of replay.DurableLogger.shouldSuppress()sees the stale flag and skips the log call.
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
PENDINGinvocation and resumedSUCCEEDEDinvocation. 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
- [Bug]: Align Execution log correlation and complete Invocation handler MDC #858 tracks missing or incorrectly mapped log-correlation fields. This issue tracks whether a log record is emitted at all after replay reaches new code.
- Closed [Feature]: Use per-context replay status for logging #383 introduced the requirement for per-context replay status. This report concerns the remaining transition boundary after consuming completed operations.
Activity