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

Aperta
#859 0 commenti 0 reazioni 0 assegnatari Vedi su GitHub

I maintainer di solito rispondono entro 1 giorno

Nessuno ha ancora preso questa issue.

Valutazione

Difficoltà
5/5
Tempo stimato
Più di una settimana
Idoneità per principianti
35/100
Tipo di issue
Bug
Chiarezza
Specificata chiaramente
Stato di attività
Attiva
Stack tecnologico
java

Direzione di ricerca

Start with the replay-state flow in DurableContextImpl, BaseDurableOperation, WaitOperation, and DurableLogger; then compare the separate state in ExecutionManager. Add focused regression coverage in the SDK integration tests for completed waits, callbacks, asynchronous boundaries, child contexts, and concurrent branches, checking actual logger emissions. Done means new continuation logs emit while replayed-history logs remain suppressed and the documented behavior matches.

Scritto dal modello di indicizzazione a partire dal testo della issue.

Descrizione

bug needs-triage pkg:sdk
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
  • #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 #383 introduced the requirement for per-context replay status. This report concerns the remaining transition boundary after consuming completed operations.
Lingua principale
Java
Stelle
28
Fork
18
Merge medio
18h 16m
PR unite (30g)
62

Preparare l'ambiente

Come iniziare

  1. Leggi tutta la issue e poi la guida ai contributi del progetto.
  2. Commenta sulla issue per dire che te ne occupi tu — evita che due persone facciano lo stesso lavoro.
  3. Fai un fork del repository e lavora su un branch.
  4. Apri una pull request che faccia riferimento al numero della issue.

Altre issue di aws/aws-durable-execution-sdk-java

Tutte le issue di aws/aws-durable-execution-sdk-java

Issue simili

Altre issue su Java

Ricevi le nuove issue nella tua casella

Un breve riepilogo di issue GitHub adatte ai principianti.