argoproj / argo-workflows

Workflow Engine for Kubernetes
https://argo-workflows.readthedocs.io/
Apache License 2.0
15.1k stars 3.2k forks source link

retryStrategy does not work correctly when we use hook #11589

Closed toyamagu-2021 closed 1 year ago

toyamagu-2021 commented 1 year ago

Pre-requisites

What happened/what you expected to happen?

Abstract

Root cause

How to fix

Version

latest

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.

spec:
  templates:
    - name: argosay
      inputs: {}
      outputs: {}
      metadata: {}
      container:
        name: ''
        image: argoproj/argosay:v2
        command:
          - /bin/sh
          - '-c'
        args:
          - /bin/sleep 2; exit 1; /argosay
        resources: {}
      retryStrategy:
        limit: 3
    - name: hook
      inputs: {}
      outputs: {}
      metadata: {}
      container:
        name: ''
        image: argoproj/argosay:v2
        command:
          - /bin/sh
          - '-c'
        args:
          - /bin/sleep 2; /argosay
        resources: {}
  entrypoint: argosay
  arguments: {}
  hooks:
    failed:
      template: hook
      arguments: {}
      expression: workflow.status == "Failed"
    running:
      template: hook
      arguments: {}
      expression: workflow.status == "Running"
    succeed:
      template: hook
      arguments: {}
      expression: workflow.status == "Succeeded"

Logs from the workflow controller

time="2023-08-17T00:17:07.438Z" level=info msg="resolved artifact repository" artifactRepositoryRef="argo/#"
time="2023-08-17T00:17:07.438Z" level=info msg="Updated phase  -> Running" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.438Z" level=warning msg="Node was nil, will be initialized as type Skipped" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.438Z" level=info msg="was unable to obtain node for , letting display name to be nodeName" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.438Z" level=info msg="Retry node omniscient-dragon-6gv5q initialized Running" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.438Z" level=info msg="lastChildNode: nil"
time="2023-08-17T00:17:07.438Z" level=info msg="was unable to obtain node for , letting display name to be nodeName" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.438Z" level=info msg="Pod node omniscient-dragon-6gv5q-2532542085 initialized Pending" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.438Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.443Z" level=info msg="Created pod: omniscient-dragon-6gv5q(0) (omniscient-dragon-6gv5q-argosay-2532542085)" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.443Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.443Z" level=warning msg="Node was nil, will be initialized as type Skipped" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.443Z" level=info msg="was unable to obtain node for , letting display name to be nodeName" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.443Z" level=info msg="Pod node omniscient-dragon-6gv5q-794260213 initialized Pending" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.443Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.447Z" level=info msg="Created pod: omniscient-dragon-6gv5q.hooks.running (omniscient-dragon-6gv5q-hook-794260213)" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.447Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.447Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:07.447Z" level=info msg="Workflow to be dehydrated" Workflow Size=2224
time="2023-08-17T00:17:07.450Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1637 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:08.430Z" level=info msg="Processing workflow" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:08.430Z" level=info msg="Task-result reconciliation" namespace=argo numObjs=0 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:08.430Z" level=info msg="node changed" namespace=argo new.message=PodInitializing new.phase=Pending new.progress=0/1 nodeID=omniscient-dragon-6gv5q-794260213 old.message= old.phase=Pending old.progress=0/1 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:08.430Z" level=info msg="node changed" namespace=argo new.message=PodInitializing new.phase=Pending new.progress=0/1 nodeID=omniscient-dragon-6gv5q-2532542085 old.message= old.phase=Pending old.progress=0/1 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:08.431Z" level=info msg="lastChildNode: &NodeStatus{ID:omniscient-dragon-6gv5q-794260213,Name:omniscient-dragon-6gv5q.hooks.running,DisplayName:omniscient-dragon-6gv5q.hooks.running,Type:Pod,TemplateName:hook,TemplateRef:nil,Phase:Pending,BoundaryID:,Message:PodInitializing,StartedAt:2023-08-17 00:17:07 +0900 JST,FinishedAt:0001-01-01 00:00:00 +0000 UTC,PodIP:,Daemoned:nil,Inputs:nil,Outputs:nil,Children:[],OutboundNodes:[],TemplateScope:local/,ResourcesDuration:ResourcesDuration{},HostNodeName:k3d-k3s-default-server-0,MemoizationStatus:nil,EstimatedDuration:6,SynchronizationStatus:nil,Progress:0/1,}"
time="2023-08-17T00:17:08.431Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:08.431Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:08.431Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:08.431Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:08.431Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:08.431Z" level=info msg="Workflow to be dehydrated" Workflow Size=2542
time="2023-08-17T00:17:08.436Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1648 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:09.560Z" level=info msg="Processing workflow" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:09.560Z" level=info msg="Task-result reconciliation" namespace=argo numObjs=0 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:09.560Z" level=info msg="node unchanged" namespace=argo nodeID=omniscient-dragon-6gv5q-794260213 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:09.560Z" level=info msg="node unchanged" namespace=argo nodeID=omniscient-dragon-6gv5q-2532542085 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:09.560Z" level=info msg="lastChildNode: &NodeStatus{ID:omniscient-dragon-6gv5q-794260213,Name:omniscient-dragon-6gv5q.hooks.running,DisplayName:omniscient-dragon-6gv5q.hooks.running,Type:Pod,TemplateName:hook,TemplateRef:nil,Phase:Pending,BoundaryID:,Message:PodInitializing,StartedAt:2023-08-17 00:17:07 +0900 JST,FinishedAt:0001-01-01 00:00:00 +0000 UTC,PodIP:,Daemoned:nil,Inputs:nil,Outputs:nil,Children:[],OutboundNodes:[],TemplateScope:local/,ResourcesDuration:ResourcesDuration{},HostNodeName:k3d-k3s-default-server-0,MemoizationStatus:nil,EstimatedDuration:6,SynchronizationStatus:nil,Progress:0/1,}"
time="2023-08-17T00:17:09.560Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:09.560Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:09.560Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:09.560Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:09.560Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:10.563Z" level=info msg="Processing workflow" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:10.563Z" level=info msg="Task-result reconciliation" namespace=argo numObjs=0 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:10.563Z" level=info msg="node changed" namespace=argo new.message= new.phase=Running new.progress=0/1 nodeID=omniscient-dragon-6gv5q-794260213 old.message=PodInitializing old.phase=Pending old.progress=0/1 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:10.564Z" level=info msg="node changed" namespace=argo new.message= new.phase=Running new.progress=0/1 nodeID=omniscient-dragon-6gv5q-2532542085 old.message=PodInitializing old.phase=Pending old.progress=0/1 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:10.564Z" level=info msg="lastChildNode: &NodeStatus{ID:omniscient-dragon-6gv5q-794260213,Name:omniscient-dragon-6gv5q.hooks.running,DisplayName:omniscient-dragon-6gv5q.hooks.running,Type:Pod,TemplateName:hook,TemplateRef:nil,Phase:Running,BoundaryID:,Message:,StartedAt:2023-08-17 00:17:07 +0900 JST,FinishedAt:0001-01-01 00:00:00 +0000 UTC,PodIP:,Daemoned:nil,Inputs:nil,Outputs:nil,Children:[],OutboundNodes:[],TemplateScope:local/,ResourcesDuration:ResourcesDuration{},HostNodeName:k3d-k3s-default-server-0,MemoizationStatus:nil,EstimatedDuration:6,SynchronizationStatus:nil,Progress:0/1,}"
time="2023-08-17T00:17:10.564Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:10.564Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:10.564Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:10.564Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:10.564Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:10.564Z" level=info msg="Workflow to be dehydrated" Workflow Size=2511
time="2023-08-17T00:17:10.570Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1665 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:13.577Z" level=info msg="Processing workflow" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:13.577Z" level=info msg="Task-result reconciliation" namespace=argo numObjs=2 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:13.577Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-2532542085 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:13.577Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-794260213 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:13.577Z" level=info msg="node changed" namespace=argo new.message= new.phase=Running new.progress=0/1 nodeID=omniscient-dragon-6gv5q-794260213 old.message= old.phase=Running old.progress=0/1 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:13.577Z" level=info msg="node changed" namespace=argo new.message= new.phase=Running new.progress=0/1 nodeID=omniscient-dragon-6gv5q-2532542085 old.message= old.phase=Running old.progress=0/1 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:13.577Z" level=info msg="lastChildNode: &NodeStatus{ID:omniscient-dragon-6gv5q-794260213,Name:omniscient-dragon-6gv5q.hooks.running,DisplayName:omniscient-dragon-6gv5q.hooks.running,Type:Pod,TemplateName:hook,TemplateRef:nil,Phase:Running,BoundaryID:,Message:,StartedAt:2023-08-17 00:17:07 +0900 JST,FinishedAt:0001-01-01 00:00:00 +0000 UTC,PodIP:,Daemoned:nil,Inputs:nil,Outputs:&Outputs{Parameters:[]Parameter{},Artifacts:[]Artifact{Artifact{Name:main-logs,Path:,Mode:nil,From:,ArtifactLocation:ArtifactLocation{ArchiveLogs:nil,S3:&S3Artifact{S3Bucket:S3Bucket{Endpoint:,Bucket:,Region:,Insecure:nil,AccessKeySecret:nil,SecretKeySecret:nil,RoleARN:,UseSDKCreds:false,CreateBucketIfNotPresent:nil,EncryptionOptions:nil,},Key:omniscient-dragon-6gv5q/omniscient-dragon-6gv5q-hook-794260213/main.log,},Git:nil,HTTP:nil,Artifactory:nil,HDFS:nil,Raw:nil,OSS:nil,GCS:nil,Azure:nil,},GlobalName:,Archive:nil,Optional:false,SubPath:,RecurseMode:false,FromExpression:,ArtifactGC:nil,Deleted:false,},},Result:nil,ExitCode:*0,},Children:[],OutboundNodes:[],TemplateScope:local/,ResourcesDuration:ResourcesDuration{},HostNodeName:k3d-k3s-default-server-0,MemoizationStatus:nil,EstimatedDuration:6,SynchronizationStatus:nil,Progress:0/1,}"
time="2023-08-17T00:17:13.577Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:13.578Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:13.578Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:13.578Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:13.578Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:13.578Z" level=info msg="Workflow to be dehydrated" Workflow Size=2761
time="2023-08-17T00:17:13.581Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1674 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:13.583Z" level=info msg="cleaning up pod" action=terminateContainers key=argo/omniscient-dragon-6gv5q-hook-794260213/terminateContainers
time="2023-08-17T00:17:13.583Z" level=info msg="cleaning up pod" action=terminateContainers key=argo/omniscient-dragon-6gv5q-argosay-2532542085/terminateContainers
time="2023-08-17T00:17:13.583Z" level=info msg="https://0.0.0.0:33703/api/v1/namespaces/argo/pods/omniscient-dragon-6gv5q-hook-794260213/exec?command=%2Fvar%2Frun%2Fargo%2Fargoexec&command=kill&command=15&command=1&container=wait&stderr=true&stdout=true&tty=false"
time="2023-08-17T00:17:13.583Z" level=info msg="https://0.0.0.0:33703/api/v1/namespaces/argo/pods/omniscient-dragon-6gv5q-argosay-2532542085/exec?command=%2Fvar%2Frun%2Fargo%2Fargoexec&command=kill&command=15&command=1&container=wait&stderr=true&stdout=true&tty=false"
time="2023-08-17T00:17:13.595Z" level=info msg="signaled container" container=wait error="unable to upgrade connection: container not found (\"wait\")" namespace=argo pod=omniscient-dragon-6gv5q-hook-794260213 stderr="<nil>" stdout="<nil>"
time="2023-08-17T00:17:13.595Z" level=info msg="signaled container" container=wait error="unable to upgrade connection: container not found (\"wait\")" namespace=argo pod=omniscient-dragon-6gv5q-argosay-2532542085 stderr="<nil>" stdout="<nil>"
time="2023-08-17T00:17:14.584Z" level=info msg="Processing workflow" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:14.584Z" level=info msg="Task-result reconciliation" namespace=argo numObjs=2 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:14.585Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-2532542085 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:14.585Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-794260213 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:14.585Z" level=info msg="node unchanged" namespace=argo nodeID=omniscient-dragon-6gv5q-794260213 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:14.585Z" level=info msg="node unchanged" namespace=argo nodeID=omniscient-dragon-6gv5q-2532542085 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:14.585Z" level=info msg="lastChildNode: &NodeStatus{ID:omniscient-dragon-6gv5q-794260213,Name:omniscient-dragon-6gv5q.hooks.running,DisplayName:omniscient-dragon-6gv5q.hooks.running,Type:Pod,TemplateName:hook,TemplateRef:nil,Phase:Running,BoundaryID:,Message:,StartedAt:2023-08-17 00:17:07 +0900 JST,FinishedAt:0001-01-01 00:00:00 +0000 UTC,PodIP:,Daemoned:nil,Inputs:nil,Outputs:&Outputs{Parameters:[]Parameter{},Artifacts:[]Artifact{Artifact{Name:main-logs,Path:,Mode:nil,From:,ArtifactLocation:ArtifactLocation{ArchiveLogs:nil,S3:&S3Artifact{S3Bucket:S3Bucket{Endpoint:,Bucket:,Region:,Insecure:nil,AccessKeySecret:nil,SecretKeySecret:nil,RoleARN:,UseSDKCreds:false,CreateBucketIfNotPresent:nil,EncryptionOptions:nil,},Key:omniscient-dragon-6gv5q/omniscient-dragon-6gv5q-hook-794260213/main.log,},Git:nil,HTTP:nil,Artifactory:nil,HDFS:nil,Raw:nil,OSS:nil,GCS:nil,Azure:nil,},GlobalName:,Archive:nil,Optional:false,SubPath:,RecurseMode:false,FromExpression:,ArtifactGC:nil,Deleted:false,},},Result:nil,ExitCode:*0,},Children:[],OutboundNodes:[],TemplateScope:local/,ResourcesDuration:ResourcesDuration{},HostNodeName:k3d-k3s-default-server-0,MemoizationStatus:nil,EstimatedDuration:6,SynchronizationStatus:nil,Progress:0/1,}"
time="2023-08-17T00:17:14.585Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:14.585Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:14.585Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:14.585Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:14.585Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:14.585Z" level=info msg="Workflow to be dehydrated" Workflow Size=2762
time="2023-08-17T00:17:14.590Z" level=info msg="cleaning up pod" action=terminateContainers key=argo/omniscient-dragon-6gv5q-hook-794260213/terminateContainers
time="2023-08-17T00:17:14.590Z" level=info msg="cleaning up pod" action=terminateContainers key=argo/omniscient-dragon-6gv5q-argosay-2532542085/terminateContainers
time="2023-08-17T00:17:14.591Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1677 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=info msg="Processing workflow" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=info msg="Task-result reconciliation" namespace=argo numObjs=2 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-2532542085 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-794260213 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=info msg="node changed" namespace=argo new.message= new.phase=Succeeded new.progress=0/1 nodeID=omniscient-dragon-6gv5q-794260213 old.message= old.phase=Running old.progress=0/1 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=info msg="Pod failed: Error (exit code 1)" displayName="omniscient-dragon-6gv5q(0)" namespace=argo pod=omniscient-dragon-6gv5q-argosay-2532542085 templateName=argosay workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=info msg="node changed" namespace=argo new.message="Error (exit code 1)" new.phase=Failed new.progress=0/1 nodeID=omniscient-dragon-6gv5q-2532542085 old.message= old.phase=Running old.progress=0/1 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=info msg="lastChildNode: &NodeStatus{ID:omniscient-dragon-6gv5q-794260213,Name:omniscient-dragon-6gv5q.hooks.running,DisplayName:omniscient-dragon-6gv5q.hooks.running,Type:Pod,TemplateName:hook,TemplateRef:nil,Phase:Succeeded,BoundaryID:,Message:,StartedAt:2023-08-17 00:17:07 +0900 JST,FinishedAt:2023-08-17 00:17:12 +0900 JST,PodIP:,Daemoned:nil,Inputs:nil,Outputs:&Outputs{Parameters:[]Parameter{},Artifacts:[]Artifact{Artifact{Name:main-logs,Path:,Mode:nil,From:,ArtifactLocation:ArtifactLocation{ArchiveLogs:nil,S3:&S3Artifact{S3Bucket:S3Bucket{Endpoint:,Bucket:,Region:,Insecure:nil,AccessKeySecret:nil,SecretKeySecret:nil,RoleARN:,UseSDKCreds:false,CreateBucketIfNotPresent:nil,EncryptionOptions:nil,},Key:omniscient-dragon-6gv5q/omniscient-dragon-6gv5q-hook-794260213/main.log,},Git:nil,HTTP:nil,Artifactory:nil,HDFS:nil,Raw:nil,OSS:nil,GCS:nil,Azure:nil,},GlobalName:,Archive:nil,Optional:false,SubPath:,RecurseMode:false,FromExpression:,ArtifactGC:nil,Deleted:false,},},Result:nil,ExitCode:*0,},Children:[],OutboundNodes:[],TemplateScope:local/,ResourcesDuration:ResourcesDuration{cpu: 7s,memory: 5s,},HostNodeName:k3d-k3s-default-server-0,MemoizationStatus:nil,EstimatedDuration:6,SynchronizationStatus:nil,Progress:0/1,}"
time="2023-08-17T00:17:16.596Z" level=info msg="Node omniscient-dragon-6gv5q is Changed to Succeeded"
time="2023-08-17T00:17:16.596Z" level=info msg="node omniscient-dragon-6gv5q phase Running -> Succeeded" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=info msg="node omniscient-dragon-6gv5q finished: 2023-08-16 15:17:16.596558443 +0000 UTC" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=info msg="Running workflow level hooks" lifeCycleHook=succeed namespace=argo node=omniscient-dragon-6gv5q.hooks.succeed workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=warning msg="Node was nil, will be initialized as type Skipped" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=info msg="was unable to obtain node for , letting display name to be nodeName" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=info msg="Pod node omniscient-dragon-6gv5q-854958522 initialized Pending" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.596Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.601Z" level=info msg="Created pod: omniscient-dragon-6gv5q.hooks.succeed (omniscient-dragon-6gv5q-hook-854958522)" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.601Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.601Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.601Z" level=info msg="Workflow to be dehydrated" Workflow Size=3270
time="2023-08-17T00:17:16.604Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1685 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:16.610Z" level=info msg="cleaning up pod" action=labelPodCompleted key=argo/omniscient-dragon-6gv5q-argosay-2532542085/labelPodCompleted
time="2023-08-17T00:17:16.610Z" level=info msg="cleaning up pod" action=labelPodCompleted key=argo/omniscient-dragon-6gv5q-hook-794260213/labelPodCompleted
time="2023-08-17T00:17:17.602Z" level=info msg="Processing workflow" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:17.603Z" level=info msg="Task-result reconciliation" namespace=argo numObjs=2 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:17.603Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-794260213 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:17.603Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-2532542085 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:17.603Z" level=info msg="node changed" namespace=argo new.message=PodInitializing new.phase=Pending new.progress=0/1 nodeID=omniscient-dragon-6gv5q-854958522 old.message= old.phase=Pending old.progress=0/1 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:17.603Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:17.603Z" level=info msg="Running workflow level hooks" lifeCycleHook=succeed namespace=argo node=omniscient-dragon-6gv5q.hooks.succeed workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:17.603Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:17.603Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:17.603Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:17.603Z" level=info msg="Workflow to be dehydrated" Workflow Size=3309
time="2023-08-17T00:17:17.607Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1698 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:18.607Z" level=info msg="Processing workflow" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:18.607Z" level=info msg="Task-result reconciliation" namespace=argo numObjs=2 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:18.607Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-2532542085 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:18.607Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-794260213 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:18.607Z" level=info msg="node changed" namespace=argo new.message= new.phase=Running new.progress=0/1 nodeID=omniscient-dragon-6gv5q-854958522 old.message=PodInitializing old.phase=Pending old.progress=0/1 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:18.607Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:18.607Z" level=info msg="Running workflow level hooks" lifeCycleHook=succeed namespace=argo node=omniscient-dragon-6gv5q.hooks.succeed workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:18.608Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:18.608Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:18.608Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:18.608Z" level=info msg="Workflow to be dehydrated" Workflow Size=3293
time="2023-08-17T00:17:18.611Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1705 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:19.612Z" level=info msg="Processing workflow" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:19.612Z" level=info msg="Task-result reconciliation" namespace=argo numObjs=2 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:19.612Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-2532542085 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:19.612Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-794260213 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:19.612Z" level=info msg="node unchanged" namespace=argo nodeID=omniscient-dragon-6gv5q-854958522 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:19.613Z" level=info msg="Running workflow level hooks" lifeCycleHook=succeed namespace=argo node=omniscient-dragon-6gv5q.hooks.succeed workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:19.613Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:19.613Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:19.613Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:19.613Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:19.614Z" level=info msg="Workflow to be dehydrated" Workflow Size=3294
time="2023-08-17T00:17:19.619Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1707 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:22.613Z" level=info msg="Processing workflow" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:22.613Z" level=info msg="Task-result reconciliation" namespace=argo numObjs=3 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:22.613Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-2532542085 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:22.613Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-794260213 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:22.613Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-854958522 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:22.613Z" level=info msg="node changed" namespace=argo new.message= new.phase=Running new.progress=0/1 nodeID=omniscient-dragon-6gv5q-854958522 old.message= old.phase=Running old.progress=0/1 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:22.613Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:22.613Z" level=info msg="Running workflow level hooks" lifeCycleHook=succeed namespace=argo node=omniscient-dragon-6gv5q.hooks.succeed workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:22.613Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:22.613Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:22.613Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:22.613Z" level=info msg="Workflow to be dehydrated" Workflow Size=3416
time="2023-08-17T00:17:22.617Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1713 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:22.619Z" level=info msg="cleaning up pod" action=terminateContainers key=argo/omniscient-dragon-6gv5q-hook-854958522/terminateContainers
time="2023-08-17T00:17:23.614Z" level=info msg="Processing workflow" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:23.614Z" level=info msg="Task-result reconciliation" namespace=argo numObjs=3 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:23.614Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-2532542085 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:23.614Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-794260213 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:23.614Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-854958522 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:23.614Z" level=info msg="node unchanged" namespace=argo nodeID=omniscient-dragon-6gv5q-854958522 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:23.615Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:23.615Z" level=info msg="Running workflow level hooks" lifeCycleHook=succeed namespace=argo node=omniscient-dragon-6gv5q.hooks.succeed workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:23.615Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:23.615Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:23.615Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:23.615Z" level=info msg="Workflow to be dehydrated" Workflow Size=3417
time="2023-08-17T00:17:23.619Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1714 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:23.620Z" level=info msg="cleaning up pod" action=terminateContainers key=argo/omniscient-dragon-6gv5q-hook-854958522/terminateContainers
time="2023-08-17T00:17:24.620Z" level=info msg="Processing workflow" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:24.620Z" level=info msg="Task-result reconciliation" namespace=argo numObjs=3 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:24.620Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-2532542085 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:24.620Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-794260213 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:24.620Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-854958522 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:24.620Z" level=info msg="node unchanged" namespace=argo nodeID=omniscient-dragon-6gv5q-854958522 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:24.620Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:24.620Z" level=info msg="Running workflow level hooks" lifeCycleHook=succeed namespace=argo node=omniscient-dragon-6gv5q.hooks.succeed workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:24.620Z" level=error msg="was unable to obtain node for " namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:24.620Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:24.620Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:24.620Z" level=info msg="Workflow to be dehydrated" Workflow Size=3417
time="2023-08-17T00:17:24.624Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1714 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:24.625Z" level=info msg="cleaning up pod" action=terminateContainers key=argo/omniscient-dragon-6gv5q-hook-854958522/terminateContainers
time="2023-08-17T00:17:25.623Z" level=info msg="Processing workflow" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:25.623Z" level=info msg="Task-result reconciliation" namespace=argo numObjs=3 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:25.623Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-2532542085 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:25.623Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-794260213 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:25.623Z" level=info msg="task-result changed" namespace=argo nodeID=omniscient-dragon-6gv5q-854958522 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:25.623Z" level=info msg="node changed" namespace=argo new.message= new.phase=Succeeded new.progress=0/1 nodeID=omniscient-dragon-6gv5q-854958522 old.message= old.phase=Running old.progress=0/1 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:25.624Z" level=info msg="Running workflow level hooks" lifeCycleHook=running namespace=argo node=omniscient-dragon-6gv5q.hooks.running workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:25.624Z" level=info msg="Running workflow level hooks" lifeCycleHook=succeed namespace=argo node=omniscient-dragon-6gv5q.hooks.succeed workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:25.624Z" level=info msg="TaskSet Reconciliation" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:25.624Z" level=info msg=reconcileAgentPod namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:25.624Z" level=info msg="Updated phase Running -> Succeeded" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:25.624Z" level=info msg="Marking workflow completed" namespace=argo workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:25.624Z" level=info msg="Workflow to be dehydrated" Workflow Size=3524
time="2023-08-17T00:17:25.627Z" level=info msg="Workflow update successful" namespace=argo phase=Succeeded resourceVersion=1717 workflow=omniscient-dragon-6gv5q
time="2023-08-17T00:17:25.629Z" level=info msg="cleaning up pod" action=deletePod key=argo/omniscient-dragon-6gv5q-1340600742-agent/deletePod
time="2023-08-17T00:17:25.640Z" level=info msg="cleaning up pod" action=labelPodCompleted key=argo/omniscient-dragon-6gv5q-hook-854958522/labelPodCompleted
time="2023-08-17T00:17:43.595Z" level=info msg="cleaning up pod" action=killContainers key=argo/omniscient-dragon-6gv5q-hook-794260213/killContainers
time="2023-08-17T00:17:43.595Z" level=info msg="cleaning up pod" action=killContainers key=argo/omniscient-dragon-6gv5q-argosay-2532542085/killContainers
time="2023-08-17T00:17:52.620Z" level=info msg="cleaning up pod" action=killContainers key=argo/omniscient-dragon-6gv5q-hook-854958522/killContainers

Logs from in your workflow's wait container

N/A
juliev0 commented 1 year ago

Thanks for finding root cause! Please consider contributing a PR.

juliev0 commented 1 year ago

By the way, there are some other open issues related to hooks. I wonder if any of them are the same root cause.

toyamagu-2021 commented 1 year ago

Good point. I'm not sure, but lastChileNode might be problematic when using hook

terrytangyuan commented 1 year ago

Is this a regression?

toyamagu-2021 commented 1 year ago

I think it's not a regression. Works wrong when we use a hook which is introduced as of v3.3

toyamagu-2021 commented 1 year ago

Appendix: Originally I reported for WorkflowLevelHook, but I can reproduce this issue for WorkflowTemplateLevelHook image

spec:
  templates:
    - name: main
      steps:
      - - name: s1
          template: argosay 
          hooks:
            failed:
              template: hook
              arguments: {}
              expression: steps.s1.status == "Failed"
            running:
              template: hook
              arguments: {}
              expression: steps.s1.status == "Running"
            succeed:
              template: hook
              arguments: {}
              expression: steps.s1.status == "Succeeded"
    - name: argosay
      inputs: {}
      outputs: {}
      metadata: {}
      container:
        name: ''
        image: argoproj/argosay:v2
        command:
          - /bin/sh
          - '-c'
        args:
          - /bin/sleep 2; exit 1; /argosay
        resources: {}
      retryStrategy:
        limit: 3
    - name: hook
      inputs: {}
      outputs: {}
      metadata: {}
      container:
        name: ''
        image: argoproj/argosay:v2
        command:
          - /bin/sh
          - '-c'
        args:
          - /bin/sleep 2; /argosay
        resources: {}
  entrypoint: main
  arguments: {}
  hooks:
    failed:
      template: hook
      arguments: {}
      expression: workflow.status == "Failed"
    running:
      template: hook
      arguments: {}
      expression: workflow.status == "Running"
    succeed:
      template: hook
      arguments: {}
      expression: workflow.status == "Succeeded"