v3.5.3: Workflow processing fails to complete due to incomplete WorkflowTaskResult from interrupted pod

[jesseanttila-cai]

Pre-requisites

• I have double-checked my configuration
• I have tested with the :latest image tag (i.e. quay.io/argoproj/workflow-controller:latest) and can confirm the issue still exists on :latest. If not, I have explained why, in detail, in my description below.
• I have searched existing issues and could not find a match for this bug
• I'd like to contribute the fix myself (see contributing guide)

What happened/what you expected to happen?

As part of #12402 (included from v3.5.3 onwards), workflow pod wait-container behavior was changed to create a placeholder (incomplete) WorkflowTaskResult before waiting for the main-container to complete.

argo-workflows/cmd/argoexec/commands/wait.go

Lines 38 to 42 in 0fdf745

	// Create a new empty (placeholder) task result with LabelKeyReportOutputsCompleted set to false.
	wfExecutor.InitializeOutput(bgCtx)
	// Wait for main container to complete
	err := wfExecutor.Wait(ctx)

The WorkflowTaskResult is finalized after output artifacts, logs etc. have been handled:

argo-workflows/cmd/argoexec/commands/wait.go

Line 34 in 0fdf745

defer wfExecutor.FinalizeOutput(bgCtx) // Ensures the LabelKeyReportOutputsCompleted is set to true.

If the wait-container is interrupted in a way that prevents FinalizeOutput from being called (e.g. pod deletion without sufficient grace period), an incomplete WorkflowTaskResult remains with the workflows.argoproj.io/report-outputs-completed label set to false. Retries of the same task will produce additional WorkflowTaskResults and will not mark the previous one complete. This leaves the workflow stuck in Processing state until the WorkflowTaskResult is manually edited to mark it complete.

The reproduction example workflow simulates forced pod deletion using a pod that deletes itself, leaving behind an incomplete WorkflowTaskResult. The included workflow controller log snippet shows the resulting processing loop.

This issue may be one of the causes of #12103.

Version

v3.5.3

Paste a small workflow that reproduces the issue. We must be able to run the workflow; don't enter a workflows that uses private images.

apiVersion: argoproj.io/v1alpha1
kind: Workflow
metadata:
  generateName: workflow-hang-example-
spec:
  entrypoint: self-delete
  templates:
    - name: self-delete
      retryStrategy:
        limit: "1"
        retryPolicy: Always
      podSpecPatch: |
        containers:
          - name: main
            env:
            - name: RETRY_COUNT
              value: "{{retries}}"
        terminationGracePeriodSeconds: 0
      container:
        image: bitnami/kubectl:latest
        env:
          - name: POD_NAME
            valueFrom:
              fieldRef:
                fieldPath: metadata.name
        # Simulate interruption via forced pod deletion on first attempt, complete successfully on retry
        command: ["sh", "-c", "sleep 10; [ $RETRY_COUNT -eq 0 ] && kubectl delete pod $POD_NAME; sleep 10"]

Logs from the workflow controller

time="2024-04-29T10:31:58.427Z" level=info msg="Processing workflow" Phase=Running ResourceVersion=26673983 namespace=ext-namespace workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.428Z" level=info msg="Task-result reconciliation" namespace=ext-namespace numObjs=2 workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.429Z" level=debug msg="task result:\n&WorkflowTaskResult{ObjectMeta:{workflow-hang-example-hf6nh-1013521106  ext-namespace  7ad71c97-1148-4c59-aea4-84e8c56d19c4 26673606 1 2024-04-29 10:29:57 +0000 UTC <nil> <nil> map[workflows.argoproj.io/report-outputs-completed:false workflows.argoproj.io/workflow:workflow-hang-example-hf6nh] map[] [{argoproj.io/v1alpha1 Workflow workflow-hang-example-hf6nh af4266ff-e25f-4e4d-b073-dee4b6778da7 <nil> <nil>}] [] [{argoexec Update argoproj.io/v1alpha1 2024-04-29 10:29:57 +0000 UTC FieldsV1 {\"f:metadata\":{\"f:labels\":{\".\":{},\"f:workflows.argoproj.io/report-outputs-completed\":{},\"f:workflows.argoproj.io/workflow\":{}},\"f:ownerReferences\":{\".\":{},\"k:{\\\"uid\\\":\\\"af4266ff-e25f-4e4d-b073-dee4b6778da7\\\"}\":{}}}} }]},NodeResult:NodeResult{Phase:,Message:,Outputs:nil,Progress:,},}" namespace=ext-namespace workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.429Z" level=debug msg="task result name:\nworkflow-hang-example-hf6nh-1013521106" namespace=ext-namespace workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.429Z" level=debug msg="Marking task result incomplete workflow-hang-example-hf6nh-1013521106" namespace=ext-namespace workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.429Z" level=info msg="task-result changed" namespace=ext-namespace nodeID=workflow-hang-example-hf6nh-1013521106 workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.429Z" level=debug msg="task result:\n&WorkflowTaskResult{ObjectMeta:{workflow-hang-example-hf6nh-3630579407  ext-namespace  3fe40d94-0f39-45ee-aff6-902f6086b578 26673958 2 2024-04-29 10:30:36 +0000 UTC <nil> <nil> map[workflows.argoproj.io/report-outputs-completed:true workflows.argoproj.io/workflow:workflow-hang-example-hf6nh] map[] [{argoproj.io/v1alpha1 Workflow workflow-hang-example-hf6nh af4266ff-e25f-4e4d-b073-dee4b6778da7 <nil> <nil>}] [] [{argoexec Update argoproj.io/v1alpha1 2024-04-29 10:30:57 +0000 UTC FieldsV1 {\"f:metadata\":{\"f:labels\":{\".\":{},\"f:workflows.argoproj.io/report-outputs-completed\":{},\"f:workflows.argoproj.io/workflow\":{}},\"f:ownerReferences\":{\".\":{},\"k:{\\\"uid\\\":\\\"af4266ff-e25f-4e4d-b073-dee4b6778da7\\\"}\":{}}},\"f:outputs\":{}} }]},NodeResult:NodeResult{Phase:,Message:,Outputs:&Outputs{Parameters:[]Parameter{},Artifacts:[]Artifact{},Result:nil,ExitCode:nil,},Progress:,},}" namespace=ext-namespace workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.429Z" level=debug msg="task result name:\nworkflow-hang-example-hf6nh-3630579407" namespace=ext-namespace workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.429Z" level=debug msg="Marking task result complete workflow-hang-example-hf6nh-3630579407" namespace=ext-namespace workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.429Z" level=info msg="task-result changed" namespace=ext-namespace nodeID=workflow-hang-example-hf6nh-3630579407 workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.429Z" level=debug msg="Skipping artifact GC" namespace=ext-namespace workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.429Z" level=debug msg="Evaluating node workflow-hang-example-hf6nh: template: *v1alpha1.WorkflowStep (self-delete), boundaryID: " namespace=ext-namespace workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.429Z" level=debug msg="Resolving the template" base="*v1alpha1.Workflow (namespace=ext-namespace,name=workflow-hang-example-hf6nh)" tmpl="*v1alpha1.WorkflowStep (self-delete)"
time="2024-04-29T10:31:58.429Z" level=debug msg="Getting the template" base="*v1alpha1.Workflow (namespace=ext-namespace,name=workflow-hang-example-hf6nh)" tmpl="*v1alpha1.WorkflowStep (self-delete)"
time="2024-04-29T10:31:58.429Z" level=debug msg="Getting the template by name: self-delete" base="*v1alpha1.Workflow (namespace=ext-namespace,name=workflow-hang-example-hf6nh)" tmpl="*v1alpha1.WorkflowStep (self-delete)"
time="2024-04-29T10:31:58.430Z" level=debug msg="Node workflow-hang-example-hf6nh already completed" namespace=ext-namespace workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.430Z" level=info msg="TaskSet Reconciliation" namespace=ext-namespace workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.430Z" level=info msg=reconcileAgentPod namespace=ext-namespace workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.430Z" level=debug msg="Task results completion status: map[workflow-hang-example-hf6nh-1013521106:false workflow-hang-example-hf6nh-3630579407:true]" namespace=ext-namespace workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.430Z" level=debug msg="taskresults of workflow are incomplete or still have daemon nodes, so can't mark workflow completed" fromPhase=Running namespace=ext-namespace toPhase=Succeeded workflow=workflow-hang-example-hf6nh
time="2024-04-29T10:31:58.443Z" level=info msg="Workflow update successful" namespace=ext-namespace phase=Running resourceVersion=26673983 workflow=workflow-hang-example-hf6nh

Logs from in your workflow's wait container

N/A (wait container must be forcibly interrupted for this issue to appear)

[jswxstw]

It seems unreliable to determine whether the task result has been successfully reported through the AnnotationKeyReportOutputsCompleted.

[shuangkun]

After reproducing it, there are indeed some problems and need to think about how to fix it.

[alexlatchford]

Yeah we are just concluding an RCA after we had a cohort of workflows "stuck" in Running state as the upgrade of the workflow-controller was rolled out from v3.4.16 to v3.5.6. We had the same conclusion that likely #11947 was the root cause, but #12402 seems related too! In either case looks like it's isolated to a transient issue on our end due to incompatibility between argoexec:v3.4.16 sidecars inside the active pods of workflows running at the time of the upgrade and the new workflow-controller:v3.5.6 control plane! Thanks for the original report and the maintainers for all the effort here!

[juliev0]

Is the primary case for this one in which the Controller itself issues a SIGKILL to the container because the container isn't responding fast enough to a SIGTERM?

If so, it seems like we need to indicate on the Controller side that if we are doing a SIGKILL not to wait for the WorkflowTaskResult for that task, right?

[jesseanttila-cai]

Is the primary case for this one in which the Controller itself issues a SIGKILL to the container because the container isn't responding fast enough to a SIGTERM?

The root cause for the pod interruption in my case was primarily related to node deprovisioning, as the environment where this issue appeared consistently uses EC2 Spot Instances along with an aggressive deprovisioning strategy for underutilized nodes. I believe that node-pressure eviction could also cause this issue, along with any other external condition that would result in a non-graceful pod termination.

[juliev0]

Got it. That's interesting that node-deprovisioning and node-pressure eviction would result in SIGKILL rather than SIGTERM.

[Joibel]

Got it. That's interesting that node-deprovisioning and node-pressure eviction would result in SIGKILL rather than SIGTERM.

There are projects like NTH which should get you a SIGTERM with some time to do some work. Perhaps they're not being used here. For non-graceful termination though, we still need a solution.

I think we need to consider "Pod gone away" after a reasonable period (to allow for propogation of the WorkflowTaskResult) to be pod failure and mark the outputs as completed (with error) to allow the workflow to fail/retry.

[roelarents]

Good find. We encounter this sometimes in long running workflows.

This leaves the workflow stuck in Processing state until the WorkflowTaskResult is manually edited to mark it complete.

How exactly can I manually edit this? edit: o, WorkflowTaskResult is a separate Custom Resource in k8s that can be updated (change the workflows.argoproj.io/report-outputs-completed label from "false" to "true")

[agilgur5]

For non-graceful termination though, we still need a solution.

I think we need to consider "Pod gone away" after a reasonable period (to allow for propogation of the WorkflowTaskResult) to be pod failure and mark the outputs as completed (with error) to allow the workflow to fail/retry.

Agreed, I said something very similar in #13066 (comment) and proposed a similar approach in #13344 (comment). The proposed PR #13051 would not necessarily resolve this as a finalizer does not necessarily prevent non-graceful termination (e.g. OOMs and the like are kubelet/node level and not control plane/k8s resource level).

I don't have time to take this on, @Joibel would you be able to tackle this when you're back from vacation? Or if someone else wants to tackle it in the meantime, that would work too. See my proposed approach in #13344 (comment) for more details.

[Joibel]

I don't want to block someone else, but yes, otherwise I have it at the top of the list to do.

[ericblackburn]

Is the primary case for this one in which the Controller itself issues a SIGKILL to the container because the container isn't responding fast enough to a SIGTERM?

If so, it seems like we need to indicate on the Controller side that if we are doing a SIGKILL not to wait for the WorkflowTaskResult for that task, right?

I am seeing this issue in 3.5.8 with just a kubectl delete pod. Reproduction case is

1. submit a workflow
2. kubectl delete the pod for the running node
3. workflow becomes stuck in a perpetual Running status

[Joibel]

@isubasinghe and I are working on a fix