argoproj / argoproj/argo-workflows
delay between step/pod completion and workflow completion
- Dominant language
- Go
- Stars
- 17k
- Forks
- 3.7k
- Avg merge
- 1d 20h
- Merged PRs (30d)
- 138
Description
### Pre-requisites
- [X] 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.
- [X] 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](https://github.com/argoproj/argo-workflows/blob/main/docs/CONTRIBUTING.md))
### What happened? What did you expect to happen?
UI shows the single step/pod completed successfully at 2024-09-27T04:31:36
but then UI shows big gap to when overall workflow completed successfully at 2024-09-27T04:36:09
### Version(s)
3.4.11
### Paste a minimal workflow that reproduces the issue. We must be able to run the workflow; don't enter a workflows that uses private images.
```YAML
n/a
```
### Logs from the workflow controller
```text
kubectl logs -n argo deploy/workflow-controller | grep ${workflow}
time=\"2024-09-27T04:29:15.202Z\" level=info msg=\"Processing workflow\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:29:15.234Z\" level=info msg=\"Updated phase -> Running\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:29:15.236Z\" level=info msg=\"Retry node aredactwf initialized Running\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:29:15.237Z\" level=info msg=\"Pod node aredactwf-3720301757 initialized Pending\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:29:15.324Z\" level=info msg=\"Created pod: aredactwf(0) (aredactwf-mystep-3720301757)\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:29:15.324Z\" level=info msg=\"TaskSet Reconciliation\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:29:15.324Z\" level=info msg=reconcileAgentPod namespace=myns workflow=aredactwf
time=\"2024-09-27T04:29:15.370Z\" level=info msg=\"Workflow update successful\" namespace=myns phase=Running resourceVersion=426512752 workflow=aredactwf
time=\"2024-09-27T04:29:25.202Z\" level=info msg=\"Processing workflow\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:29:25.205Z\" level=info msg=\"Task-result reconciliation\" namespace=myns numObjs=0 workflow=aredactwf
time=\"2024-09-27T04:29:25.205Z\" level=info msg=\"node changed\" namespace=myns new.message= new.phase=Running new.progress=0/1 nodeID=aredactwf-3720301757 old.message= old.phase=Pending old.progress=0/1 workflow=aredactwf
time=\"2024-09-27T04:29:25.207Z\" level=info msg=\"node aredactwf message: retryStrategy.expression evaluated to false\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:29:25.207Z\" level=info msg=\"TaskSet Reconciliation\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:29:25.207Z\" level=info msg=reconcileAgentPod namespace=myns workflow=aredactwf
time=\"2024-09-27T04:29:25.230Z\" level=info msg=\"Workflow update successful\" namespace=myns phase=Running resourceVersion=426512956 workflow=aredactwf
time=\"2024-09-27T04:29:35.230Z\" level=info msg=\"Processing workflow\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:29:35.233Z\" level=info msg=\"Task-result reconciliation\" namespace=myns numObjs=0 workflow=aredactwf
time=\"2024-09-27T04:29:35.233Z\" level=info msg=\"node unchanged\" namespace=myns nodeID=aredactwf-3720301757 workflow=aredactwf
time=\"2024-09-27T04:29:35.235Z\" level=info msg=\"TaskSet Reconciliation\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:29:35.235Z\" level=info msg=reconcileAgentPod namespace=myns workflow=aredactwf
time=\"2024-09-27T04:31:39.661Z\" level=info msg=\"Processing workflow\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:31:39.663Z\" level=info msg=\"Task-result reconciliation\" namespace=myns numObjs=1 workflow=aredactwf
time=\"2024-09-27T04:31:39.663Z\" level=info msg=\"task-result changed\" namespace=myns nodeID=aredactwf-3720301757 workflow=aredactwf
time=\"2024-09-27T04:31:39.663Z\" level=info msg=\"node unchanged\" namespace=myns nodeID=aredactwf-3720301757 workflow=aredactwf
time=\"2024-09-27T04:31:39.665Z\" level=info msg=\"TaskSet Reconciliation\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:31:39.665Z\" level=info msg=reconcileAgentPod namespace=myns workflow=aredactwf
time=\"2024-09-27T04:31:39.682Z\" level=info msg=\"Workflow update successful\" namespace=myns phase=Running resourceVersion=426514616 workflow=aredactwf
time=\"2024-09-27T04:31:49.683Z\" level=info msg=\"Processing workflow\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:31:49.686Z\" level=info msg=\"Task-result reconciliation\" namespace=myns numObjs=1 workflow=aredactwf
time=\"2024-09-27T04:31:49.686Z\" level=info msg=\"task-result changed\" namespace=myns nodeID=aredactwf-3720301757 workflow=aredactwf
time=\"2024-09-27T04:31:49.686Z\" level=info msg=\"node unchanged\" namespace=myns nodeID=aredactwf-3720301757 workflow=aredactwf
time=\"2024-09-27T04:31:49.688Z\" level=info msg=\"TaskSet Reconciliation\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:31:49.688Z\" level=info msg=reconcileAgentPod namespace=myns workflow=aredactwf
time=\"2024-09-27T04:31:49.707Z\" level=info msg=\"Workflow update successful\" namespace=myns phase=Running resourceVersion=426514616 workflow=aredactwf
time=\"2024-09-27T04:36:09.656Z\" level=info msg=\"Processing workflow\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.658Z\" level=info msg=\"Task-result reconciliation\" namespace=myns numObjs=1 workflow=aredactwf
time=\"2024-09-27T04:36:09.658Z\" level=info msg=\"task-result changed\" namespace=myns nodeID=aredactwf-3720301757 workflow=aredactwf
time=\"2024-09-27T04:36:09.658Z\" level=info msg=\"node changed\" namespace=myns new.message= new.phase=Succeeded new.progress=0/1 nodeID=aredactwf-3720301757 old.message= old.phase=Running old.progress=0/1 workflow=aredactwf
time=\"2024-09-27T04:36:09.660Z\" level=info msg=\"node aredactwf phase Running -> Succeeded\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.660Z\" level=info msg=\"node aredactwf finished: 2024-09-27 04:36:09.66063598 +0000 UTC\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.660Z\" level=info msg=\"TaskSet Reconciliation\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.660Z\" level=info msg=reconcileAgentPod namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.660Z\" level=info msg=\"Running OnExit handler: exit-handler\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.661Z\" level=info msg=\"Retry node aredactwf-1656388105 initialized Running\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.661Z\" level=info msg=\"Steps node aredactwf-3191187056 initialized Running\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.661Z\" level=info msg=\"StepGroup node aredactwf-202582218 initialized Running\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.661Z\" level=info msg=\"Skipping aredactwf.onExit(0)[0].notifyError: when 'Succeeded != Succeeded' evaluated false\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.661Z\" level=info msg=\"Skipped node aredactwf-2734285361 initialized Skipped (message: when 'Succeeded != Succeeded' evaluated false)\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.661Z\" level=info msg=\"Step group node aredactwf-202582218 successful\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.661Z\" level=info msg=\"node aredactwf-202582218 phase Running -> Succeeded\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.661Z\" level=info msg=\"node aredactwf-202582218 finished: 2024-09-27 04:36:09.661610081 +0000 UTC\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.661Z\" level=info msg=\"Outbound nodes of aredactwf-2734285361 is [aredactwf-2734285361]\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.661Z\" level=info msg=\"Outbound nodes of aredactwf-3191187056 is [aredactwf-2734285361]\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.661Z\" level=info msg=\"node aredactwf-3191187056 phase Running -> Succeeded\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.661Z\" level=info msg=\"node aredactwf-3191187056 finished: 2024-09-27 04:36:09.661709572 +0000 UTC\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.662Z\" level=info msg=\"node aredactwf-1656388105 phase Running -> Succeeded\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.662Z\" level=info msg=\"node aredactwf-1656388105 message: retryStrategy.expression evaluated to false\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.662Z\" level=info msg=\"node aredactwf-1656388105 finished: 2024-09-27 04:36:09.662286778 +0000 UTC\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.662Z\" level=info msg=\"Updated phase Running -> Succeeded\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.662Z\" level=info msg=\"Marking workflow completed\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.662Z\" level=info msg=\"Marking workflow as pending archiving\" namespace=myns workflow=aredactwf
time=\"2024-09-27T04:36:09.668Z\" level=info msg=\"cleaning up pod\" action=deletePod key=myns/aredactwf-1340600742-agent/deletePod
time=\"2024-09-27T04:36:09.720Z\" level=info msg=\"Workflow update successful\" namespace=myns phase=Succeeded resourceVersion=426517669 workflow=aredactwf
time=\"2024-09-27T04:36:10.372Z\" level=info msg=\"archiving workflow\" namespace=myns uid=d4ea0321-a659-43d7-8ed9-eb839650b452 workflow=aredactwf
time=\"2024-09-27T04:36:10.466Z\" level=info msg=\"Queueing Succeeded workflow myns/aredactwf for delete in 1m4s due to TTL\"
time=\"2024-09-27T04:36:14.745Z\" level=info msg=\"cleaning up pod\" action=deletePod key=myns/aredactwf-mystep-3720301757/deletePod
```
### Logs from in your workflow's wait container
```text
kubectl logs -n argo -c wait -l workflows.argoproj.io/workflow=${workflow},workflow.argoproj.io/phase!=Succeeded
\"2024-09-27T04:29:18.477Z\" level=info msg=\"Starting Workflow Executor\" version=v3.4.11
\"2024-09-27T04:29:18.482Z\" level=info msg=\"Using executor retry strategy\" Duration=1s Factor=1.6 Jitter=0.5 Steps=5
\"2024-09-27T04:29:18.482Z\" level=info msg=\"monitoring progress disabled\" annotationPatchTickDuration=0s readProgressFileTickDuration=0s
\"2024-09-27T04:29:18.483Z\" level=info msg=\"Starting deadline monitor\"
\"2024-09-27T04:31:29.504Z\" level=info msg=\"Main container completed\" error=\"\"
\"2024-09-27T04:31:29.504Z\" level=info msg=\"No Script output reference in workflow. Capturing script output ignored\"
\"2024-09-27T04:31:29.504Z\" level=info msg=\"No output parameters\"
\"2024-09-27T04:31:29.504Z\" level=info msg=\"No output artifacts\"
\"2024-09-27T04:31:29.524Z\" level=info msg=\"S3 Save path: /tmp/argo/outputs/logs/main.log, key: argo_wf_logs/2024/09/27/04/29/aredactwf/aredactwf-mystep-3720301757/main.log\"
\"2024-09-27T04:31:29.525Z\" level=info msg=\"Creating minio client using AWS SDK credentials\"
\"2024-09-27T04:31:29.565Z\" level=info msg=\"Saving file to s3\" bucket=redactbuc endpoint=s3.amazonaws.com key=argo_wf_logs/2024/09/27/04/29/aredactwf/aredactwf-mystep-3720301757/main.log path=/tmp/argo/outputs/logs/main.log
\"2024-09-27T04:31:29.641Z\" level=info msg=\"Save artifact\" artifactName=main-logs duration=116.831623ms error=\"\" key=argo_wf_logs/2024/09/27/04/29/aredactwf/aredactwf-mystep-3720301757/main.log
\"2024-09-27T04:31:29.641Z\" level=info msg=\"not deleting local artifact\" localArtPath=/tmp/argo/outputs/logs/main.log
\"2024-09-27T04:31:29.641Z\" level=info msg=\"Successfully saved file: /tmp/argo/outputs/logs/main.log\"
\"2024-09-27T04:31:29.659Z\" level=info msg=\"Alloc=11298 TotalAlloc=18244 Sys=33917 NumGC=5 Goroutines=11\"
\"2024-09-27T04:31:29.659Z\" level=info msg=\"Deadline monitor stopped\"
```
Contributor guide
Research direction
Start with the workflow-controller Task-result reconciliation entries and the wait-container executor logs, especially the timestamps around Main container completed, artifact saving, and node phase changes. Reproduce with a minimal workflow and trace the missing interval; done means the cause of the delay is identified and the workflow completion timing is corrected or covered by a regression test.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- aws, go, kubernetes
- Domain
- backend, cloud, distributed-systems
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 32/100