microsoft / microsoft/durabletask-java

RetryContext.lastAttemptNumber is inflated when retriable task is awaited via ctx.anyOf(...)

未关闭
#290 2 条评论 0 个 reaction 已指派 0 人 在 GitHub 查看

还没有人认领这个 Issue。

Needs: Triage :mag:
主要语言
Java
星标
29
派生
18
平均合并
1 天 10 小时
30 天内合并 PR
2

描述

Summary

RetryContext.getLastAttemptNumber() violates its documented contract when the underlying retriable task is awaited indirectly via a CompoundTask (e.g. TaskOrchestrationContext.anyOf(...)). The counter increments on every CompoundTask.await() regardless of whether any task has failed, so a custom RetryHandler sees a lastAttemptNumber much higher than the actual number of failed attempts.

Documented contract

From RetryContext.getLastAttemptNumber():

Gets the previous retry attempt number. This number starts at 1 and increments each time the retry handler is invoked for a particular task failure.

Observed behavior

In a bounded sliding-window fan-out pattern that awaits retriable activities via ctx.anyOf(...), tasks that enter the in-flight window after the first batch has burned through its retries observe lastAttemptNumber ≈ window size in their retry handler — on the first real failure, before any retry has happened.

Root cause

The inflated counter originates somewhere in RetriableTask.attemptNumber accounting when a freshly-scheduled RetriableTask joins an anyOf membership that is already being drained. Relevant entry points in TaskOrchestrationExecutor.java (1.9.0):

// line ~2055
void init() {
    this.startTime = this.startTime == null ? this.context.getCurrentInstant() : this.startTime;
    this.attemptNumber++;
}

// line ~2194
private void initSubTasks() {
    for (Task<V> subTask : this.subTasks) {
        if (subTask instanceof RetriableTask) ((RetriableTask<V>)subTask).init();
    }
}

What we can pin down from the observed behaviour:

  • The retry handler is invoked exactly once per real failure (no double-firing).
  • totalRetryTimeMs is consistent with the real number of attempts — it is 0 on the inflated invocations, confirming zero real retries have happened.
  • attemptNumber on a RetriableTask scheduled mid-drain is already much greater than 1 by the time its first failure reaches the handler.
  • RetriableTasks that exist before the drain loop starts retain a correct counter, even though they participate in many CompoundTask.await() cycles while still pending. So init() cannot be incrementing unconditionally on every initSubTasks() pass; there is effectively an "already initialised" guard for them.

The remaining unknown is what causes a newly constructed RetriableTask to begin life with attemptNumber already inflated — or to be subjected to init() calls that skip the guard the existing tasks benefit from — when it is added to an anyOf membership that has already cycled through several CompoundTask.await() calls. That interaction is the failure surface.

Minimal reproduction

The bug surfaces under these conditions:

  1. Bounded sliding window: tasks are added to the in-flight list mid-drain (one new task scheduled each time one completes).
  2. Outer try/catch wrapping ctx.anyOf(inFlight).await(). The CompoundTask returned by anyOf() re-throws the underlying TaskFailedException from its await(), rather than returning the failed task. Without an outer catch the orchestrator dies on the first failure and the bug never gets a chance to manifest on later tasks.
  3. Enough items to fill a second window after the first has completed. With N total items and a window of W, you need N > W. The first window goes through retries normally (1→max); the second window is where the bug shows up.

Kotlin, Azure Functions Java worker:

class LastAttemptReproOrchestratorFunction {
    companion object {
        const val ORCHESTRATOR_NAME = "LastAttemptReproOrchestratorFunction"
        const val ACTIVITY_NAME = "AlwaysFailsActivityFunction"
        private const val NUM_ACTIVITIES = 20
        private const val MAX_IN_FLIGHT = 10
        private const val MAX_ATTEMPTS = 5
        private const val SLOW_TASK_STEP_MILLIS = 200L
    }

    @FunctionName(ORCHESTRATOR_NAME)
    fun run(
        @DurableOrchestrationTrigger(name = "ctx") ctx: TaskOrchestrationContext,
        executionContext: ExecutionContext,
    ) {
        val log = executionContext.logger
        val opts = TaskOptions(
            RetryHandler { retryCtx ->
                if (!retryCtx.orchestrationContext.isReplaying) {
                    log.log(
                        Level.WARNING,
                        "RetryHandler invoked: lastAttemptNumber=${retryCtx.lastAttemptNumber} " +
                            "(max=$MAX_ATTEMPTS), totalRetryTimeMs=${retryCtx.totalRetryTime.toMillis()}",
                    )
                }
                retryCtx.lastAttemptNumber < MAX_ATTEMPTS
            },
        )

        // Bounded sliding-window fan-out: keep at most MAX_IN_FLIGHT in flight at any time,
        // and start a replacement each time one completes.
        val inFlight = mutableListOf<Task<*>>()
        var nextIndex = 0
        while (nextIndex < MAX_IN_FLIGHT && nextIndex < NUM_ACTIVITIES) {
            inFlight += ctx.callActivity(ACTIVITY_NAME, nextIndex, opts, String::class.java)
            nextIndex++
        }
        while (inFlight.isNotEmpty()) {
            try {
                val completedTask: Task<*> = ctx.anyOf(inFlight).await()
                inFlight.remove(completedTask)
                try {
                    completedTask.await()
                } catch (e: TaskFailedException) {
                    // expected — every activity always fails
                }
            } catch (e: TaskFailedException) {
                // anyOf().await() can throw the underlying TaskFailedException directly
                // rather than returning the failed task — identify the done task and continue.
                val done = inFlight.firstOrNull { it.isDone } ?: throw e
                inFlight.remove(done)
            }
            if (nextIndex < NUM_ACTIVITIES) {
                inFlight += ctx.callActivity(ACTIVITY_NAME, nextIndex, opts, String::class.java)
                nextIndex++
            }
        }
    }

    @FunctionName(ACTIVITY_NAME)
    fun alwaysFails(@DurableActivityTrigger(name = "index") index: Int): String {
        Thread.sleep(index * SLOW_TASK_STEP_MILLIS)
        throw RuntimeException("Always fails (for lastAttemptNumber repro)")
    }
}

(Plus a trivial HTTP trigger that calls durableContext.client.scheduleNewOrchestrationInstance(ORCHESTRATOR_NAME) to start it.)

The staggered Thread.sleep(index * 200ms) in the activity makes the first batch of activities fail quickly and the second batch slowly, ensuring many anyOf().await() iterations run with the second batch still pending.

Observed output

With NUM_ACTIVITIES=20, MAX_IN_FLIGHT=10, MAX_ATTEMPTS=5, all RetryHandler invoked log lines from one orchestration run:

"20/05/2026, 12:41:38.178","RetryHandler invoked: lastAttemptNumber=1 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:38.251","RetryHandler invoked: lastAttemptNumber=2 (max=5), totalRetryTimeMs=570"
"20/05/2026, 12:41:38.313","RetryHandler invoked: lastAttemptNumber=1 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:38.313","RetryHandler invoked: lastAttemptNumber=3 (max=5), totalRetryTimeMs=661"
"20/05/2026, 12:41:38.465","RetryHandler invoked: lastAttemptNumber=4 (max=5), totalRetryTimeMs=722"
"20/05/2026, 12:41:38.554","RetryHandler invoked: lastAttemptNumber=1 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:38.554","RetryHandler invoked: lastAttemptNumber=5 (max=5), totalRetryTimeMs=873"
"20/05/2026, 12:41:38.623","RetryHandler invoked: lastAttemptNumber=2 (max=5), totalRetryTimeMs=722"
"20/05/2026, 12:41:38.763","RetryHandler invoked: lastAttemptNumber=1 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:38.891","RetryHandler invoked: lastAttemptNumber=3 (max=5), totalRetryTimeMs=1030"
"20/05/2026, 12:41:38.891","RetryHandler invoked: lastAttemptNumber=1 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:39.072","RetryHandler invoked: lastAttemptNumber=2 (max=5), totalRetryTimeMs=961"
"20/05/2026, 12:41:39.135","RetryHandler invoked: lastAttemptNumber=1 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:39.201","RetryHandler invoked: lastAttemptNumber=4 (max=5), totalRetryTimeMs=1298"
"20/05/2026, 12:41:39.340","RetryHandler invoked: lastAttemptNumber=1 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:39.437","RetryHandler invoked: lastAttemptNumber=2 (max=5), totalRetryTimeMs=1170"
"20/05/2026, 12:41:39.556","RetryHandler invoked: lastAttemptNumber=5 (max=5), totalRetryTimeMs=1608"
"20/05/2026, 12:41:39.556","RetryHandler invoked: lastAttemptNumber=3 (max=5), totalRetryTimeMs=1479"
"20/05/2026, 12:41:39.556","RetryHandler invoked: lastAttemptNumber=1 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:39.748","RetryHandler invoked: lastAttemptNumber=1 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:39.818","RetryHandler invoked: lastAttemptNumber=2 (max=5), totalRetryTimeMs=1298"
"20/05/2026, 12:41:39.952","RetryHandler invoked: lastAttemptNumber=1 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:40.021","RetryHandler invoked: lastAttemptNumber=4 (max=5), totalRetryTimeMs=1964"
"20/05/2026, 12:41:40.109","RetryHandler invoked: lastAttemptNumber=3 (max=5), totalRetryTimeMs=1846"
"20/05/2026, 12:41:40.215","RetryHandler invoked: lastAttemptNumber=2 (max=5), totalRetryTimeMs=1543"
"20/05/2026, 12:41:40.512","RetryHandler invoked: lastAttemptNumber=5 (max=5), totalRetryTimeMs=2430"
"20/05/2026, 12:41:40.620","RetryHandler invoked: lastAttemptNumber=2 (max=5), totalRetryTimeMs=1748"
"20/05/2026, 12:41:40.698","RetryHandler invoked: lastAttemptNumber=3 (max=5), totalRetryTimeMs=2227"
"20/05/2026, 12:41:40.782","RetryHandler invoked: lastAttemptNumber=4 (max=5), totalRetryTimeMs=2518"
"20/05/2026, 12:41:41.043","RetryHandler invoked: lastAttemptNumber=2 (max=5), totalRetryTimeMs=1964"
"20/05/2026, 12:41:41.283","RetryHandler invoked: lastAttemptNumber=3 (max=5), totalRetryTimeMs=2623"
"20/05/2026, 12:41:41.425","RetryHandler invoked: lastAttemptNumber=2 (max=5), totalRetryTimeMs=2154"
"20/05/2026, 12:41:41.503","RetryHandler invoked: lastAttemptNumber=5 (max=5), totalRetryTimeMs=3191"
"20/05/2026, 12:41:41.565","RetryHandler invoked: lastAttemptNumber=4 (max=5), totalRetryTimeMs=3106"
"20/05/2026, 12:41:41.828","RetryHandler invoked: lastAttemptNumber=2 (max=5), totalRetryTimeMs=2361"
"20/05/2026, 12:41:41.899","RetryHandler invoked: lastAttemptNumber=3 (max=5), totalRetryTimeMs=3029"
"20/05/2026, 12:41:42.356","RetryHandler invoked: lastAttemptNumber=4 (max=5), totalRetryTimeMs=3692"
"20/05/2026, 12:41:42.437","RetryHandler invoked: lastAttemptNumber=5 (max=5), totalRetryTimeMs=3974"
"20/05/2026, 12:41:42.557","RetryHandler invoked: lastAttemptNumber=3 (max=5), totalRetryTimeMs=3452"
"20/05/2026, 12:41:43.109","RetryHandler invoked: lastAttemptNumber=3 (max=5), totalRetryTimeMs=3834"
"20/05/2026, 12:41:43.179","RetryHandler invoked: lastAttemptNumber=4 (max=5), totalRetryTimeMs=4308"
"20/05/2026, 12:41:43.436","RetryHandler invoked: lastAttemptNumber=5 (max=5), totalRetryTimeMs=4766"
"20/05/2026, 12:41:43.717","RetryHandler invoked: lastAttemptNumber=3 (max=5), totalRetryTimeMs=4238"
"20/05/2026, 12:41:44.034","RetryHandler invoked: lastAttemptNumber=4 (max=5), totalRetryTimeMs=4965"
"20/05/2026, 12:41:44.486","RetryHandler invoked: lastAttemptNumber=5 (max=5), totalRetryTimeMs=5589"
"20/05/2026, 12:41:44.800","RetryHandler invoked: lastAttemptNumber=4 (max=5), totalRetryTimeMs=5519"
"20/05/2026, 12:41:45.517","RetryHandler invoked: lastAttemptNumber=5 (max=5), totalRetryTimeMs=6444"
"20/05/2026, 12:41:45.596","RetryHandler invoked: lastAttemptNumber=4 (max=5), totalRetryTimeMs=6125"
"20/05/2026, 12:41:46.480","RetryHandler invoked: lastAttemptNumber=5 (max=5), totalRetryTimeMs=7206"
"20/05/2026, 12:41:47.480","RetryHandler invoked: lastAttemptNumber=5 (max=5), totalRetryTimeMs=8005"
"20/05/2026, 12:41:49.563","RetryHandler invoked: lastAttemptNumber=10 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:49.792","RetryHandler invoked: lastAttemptNumber=10 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:50.045","RetryHandler invoked: lastAttemptNumber=10 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:50.203","RetryHandler invoked: lastAttemptNumber=10 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:50.405","RetryHandler invoked: lastAttemptNumber=10 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:50.623","RetryHandler invoked: lastAttemptNumber=10 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:50.837","RetryHandler invoked: lastAttemptNumber=10 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:51.017","RetryHandler invoked: lastAttemptNumber=10 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:51.255","RetryHandler invoked: lastAttemptNumber=10 (max=5), totalRetryTimeMs=0"
"20/05/2026, 12:41:51.463","RetryHandler invoked: lastAttemptNumber=10 (max=5), totalRetryTimeMs=0"

The first batch of 10 activities (indices 0–9) retries normally — lastAttemptNumber progresses 1→5 and totalRetryTimeMs rises monotonically per task. The second batch (indices 10–19) each see lastAttemptNumber=10 with totalRetryTimeMs=0 on their first failure — equal to MAX_IN_FLIGHT, matching the root-cause analysis above. The retry handler returns false (10 < 5 is false), so the second batch gets zero retries and their first failure propagates. The totalRetryTimeMs=0 confirms no real retry has happened, even though lastAttemptNumber already says 10.

Expected: each task's retry handler sees lastAttemptNumber rising from 1 to 5 as it actually retries.
Actual: tasks entering a refilled window see lastAttemptNumber ≈ window size on first failure — exceeding the retry budget before any real retry happens.

Impact

Any custom RetryHandler that gates retries on lastAttemptNumber (the obvious choice given the docs) silently rejects retries that should fire, under common parallel fan-out patterns. We hit this in production when running 10 items in parallel via anyOf with a 5-attempt cap: the last items in the window saw inflated lastAttemptNumber on their first failure, retries were rejected, the activity failure propagated to the orchestrator, and the orchestration failed instead of recovering.

Workaround: gate on RetryContext.getTotalRetryTime() instead — that field is only written inside RetriableTask.tryRetry() after the timer await and is not affected by initSubTasks.

Suggested fix

Without a precise diagnosis it's premature to prescribe a code change, but the goal is clear: RetryContext.getLastAttemptNumber() must reflect only real handler invocations for a given task, matching totalRetryTime. Whatever code path bumps attemptNumber for a freshly-scheduled RetriableTask joining an active CompoundTask needs to be removed or guarded so that the counter starts at 1 on the first real failure for every task, regardless of when in the orchestrator's lifetime the task was scheduled.

A useful invariant to enforce in tests: for every retry-handler invocation, lastAttemptNumber == 1 || totalRetryTime > 0. Any invocation with lastAttemptNumber > 1 and totalRetryTime == 0 is by definition inconsistent with the documented contract.

Environment

  • com.microsoft:durabletask-client:1.9.0

  • Azure Functions Java worker on Flex Consumption plan, region norwayeast, Maximum instance count = 10

  • Relevant host.json:

    {
      "version": "2.0",
      "functionTimeout": "00:10:00",
      "extensions": {
        "durableTask": {
          "hubName": "MyHub",
          "storageProvider": {
            "partitionCount": 16
          },
          "maxConcurrentActivityFunctions": 10,
          "maxConcurrentOrchestratorFunctions": 20
        }
      },
      "extensionBundle": {
        "id": "Microsoft.Azure.Functions.ExtensionBundle",
        "version": "[4.*, 5.0.0)"
      }
    }
    

贡献指南

打开贡献指南

从这里开始

  1. 先读完整个 Issue,再读项目的贡献指南。
  2. 在 Issue 下留言说明你要接手 —— 这能避免两个人做同样的事。
  3. Fork 仓库,在一个分支上完成修改。
  4. 提交 Pull Request,并在描述里引用这个 Issue 编号。

调研方向

从 TaskOrchestrationExecutor.java 中的 RetriableTask.init() 和 CompoundTask.initSubTasks() 开始,然后使用 ctx.anyOf() 运行 Kotlin 有界滑动窗口复现。跟踪新调度的 RetriableTask 实例如何获取其 attemptNumber。当 getLastAttemptNumber() 在第一次真实失败时从 1 开始,并且仅在后续失败后调用重试处理程序时递增,即表示完成。

由索引模型根据 Issue 内容生成。

评估

技术栈
java, kotlin
领域
backend, distributed-systems
Issue 类型
缺陷
难度
4/5
预计耗时
3-5 天
活跃度
冷清
描述清晰度
基本清楚
新手友好度
45/100

把新 issue 发到你的邮箱

精选适合新手参与的 GitHub issue 摘要。