Unexpected behavior of workflows created form cronworkflows

[kobejn-jb]

I'm experiencing unexpected behavior of workflows that are created based on cronworkflows, to be specific I've noticed that it happens with all workflows labeled with workflows.argoproj.io/cron-workflow. Even when I create wf manually using manifest and add this label I'm observing one of following scenarios:

Scenario1: Workflow starts, pod is being created and it finishes, so it this case everything worked as expected.

Scenario2:
In controller logs I see following messages:

time="2021-09-03T13:15:53.501Z" level=info msg="Processing workflow" namespace=argo workflow=cron-test
time="2021-09-03T13:15:53.505Z" level=info msg="Get configmaps 200"
time="2021-09-03T13:15:53.505Z" level=info msg="resolved artifact repository" artifactRepositoryRef=default-artifact-repository
time="2021-09-03T13:15:53.505Z" level=info msg="Updated phase  -> Running" namespace=argo workflow=cron-test

Status in workflow object is not updated and it looks like this:

 Status:
   Finished At:  <nil>
   Started At:   <nil>
 Events:
   Type    Reason           Age   From                 Message
   ----    ------           ----  ----                 -------        
   Normal  WorkflowRunning  6s    workflow-controller  Workflow Running  

Phase is not visible in Status and "Started At" stays empty, event WorkflowRunning appears but pod is not created and nothing happens for 30-40s
(I have build custom controller with some extra logging, local Status object in controller pod representing this wf has Phase set to "Running" but I wasn't able to understand how this status is applied to kubernetes object)

And after 30-40s I see something like this in controller logs:

time="2021-09-03T13:16:29.648Z" level=error msg="error in entry template execution" error="Deadline exceeded" namespace=argo workflow=cron-test
time="2021-09-03T13:16:29.657Z" level=info msg="Update workflows 200"
time="2021-09-03T13:16:29.658Z" level=info msg="Create events 201"
time="2021-09-03T13:16:29.658Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1157279927 workflow=cron-test
...
time="2021-09-03T13:17:15.086Z" level=info msg="Pod node cron-test initialized Pending" namespace=argo workflow=cron-test
time="2021-09-03T13:17:15.104Z" level=info msg="Create pods 201"
time="2021-09-03T13:17:15.104Z" level=info msg="Created pod: cron-test (cron-test)" namespace=argo workflow=cron-test
time="2021-09-03T13:17:15.114Z" level=info msg="Update workflows 200"
time="2021-09-03T13:17:15.114Z" level=info msg="Workflow update successful" namespace=argo phase=Running resourceVersion=1157281920 workflow=cron-test

And Status changes in workflow object:

 Status:                                                                                                                                                                                                         
   Artifact Repository Ref:
     Artifact Repository:
       s3:        
         Access Key Secret:
           Key:     accesskey
         Insecure:  true
         Secret Key Secret:
           Key:         secretkey
     Default:           true
   Estimated Duration:  92
   Finished At:         <nil>
   Phase:               Running
   Progress:            0/0
   Started At:          2021-09-03T13:27:38Z                            
 Events:
   Type     Reason            Age   From                 Message                               
   ----     ------            ----  ----                 -------
   Normal   WorkflowRunning   39s   workflow-controller  Workflow Running
   Warning  WorkflowTimedOut  4s    workflow-controller  error in entry template execution: Deadline exceeded

After that pod is created and rest goes as it should.

Scenario3:
In controller logs I see following messages:

time="2021-09-03T13:15:53.501Z" level=info msg="Processing workflow" namespace=argo workflow=cron-test
time="2021-09-03T13:15:53.505Z" level=info msg="Get configmaps 200"
time="2021-09-03T13:15:53.505Z" level=info msg="resolved artifact repository" artifactRepositoryRef=default-artifact-repository
time="2021-09-03T13:15:53.505Z" level=info msg="Updated phase  -> Running" namespace=argo workflow=cron-test

Status in workflow object is not updated and it looks like this:

 Status:
   Finished At:  <nil>
   Started At:   <nil>
 Events:
   Type    Reason           Age   From                 Message
   ----    ------           ----  ----                 -------        
   Normal  WorkflowRunning  6s    workflow-controller  Workflow Running  

Nothing more happens and workflow never starts.

I don't know go and don't understand insides of controller enough continue debugging, this only happens to one of my argo deployments in one cluster(only argo on this cluster) and I wasn't able to reproduce this on other clusters and it makes me think that this is caused of some unexpected behavior of apiserver. Scenario2 appeared only after kubernetes upgrade form 1.18 to 1.19, before that is was only scenario 1 or 3.

I'm using EKS, tested on versions 1.18, 1.19 and 1.20.
Tested on argo versions 2.12.2 and 3.1.8

Anybody know what might be cause of this behavior?
I wasn't able to find parts of code dependent of label workflows.argoproj.io/cron-workflow any hints would be appreciated.

[kobejn-jb]

I'll add that I'm running similar argo worklows setups on 2 EKS clusters and the issue appears only on one of them.

[wanghong230]

@sarabala1979 Do you have any quick hints here?

[sarabala1979]

workflows.argoproj.io/cron-workflow is just for information purposes. Can you look at the POD status and wait container log to see any API timeout or image pull issue?

[kobejn-jb]

Pod is not created so there are no logs. In scenarios when the pod is actually created form that point everything runs normally.

This is strange with the label workflows.argoproj.io/cron-workflow because when I created workflow than normally works every time only difference was that I've added mentioned label and I've experienced same issues like in scenario 3

[kobejn-jb]

@sarabala1979 any other ideas?

[sarabala1979]

It looks like your k8s api server delaying the request or dropping? Can you check k8s api server logs for pods creation and workflow update?

…

Sent from my iPhone

On Oct 28, 2021, at 7:09 AM, Jakub Bielawski ***@***.***> wrote:  @sarabala1979 any other ideas? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe. Triage notifications on the go with GitHub Mobile for iOS or Android.

[kobejn-jb]

@sarabala1979 Hi, took me a while. I was looking at api server metrics and didn't noticed anything alarming. No errors in workflow read or write requests, same for pods. Reads for workflows can take up to 650ms, writes tops at 125ms. For pods I've seen reads taking up to 25s but this periods do not correlate with the times when I was trying to run cronworkflows, reads take up to 220ms.

I've done another test on my current setup:
EKS: 1.20.7
argo-worfklows: v3.1.8
I've submitted cronworkflow in argo UI and I've experienced behavior described in scenario 2 form my first post above.

When I went thru eks apiserver audit logs I've seen the following requests related to wf I was trying to run:
1."requestReceivedTimestamp": "2021-11-19T09:24:38.859521Z", "stageTimestamp": "2021-11-19T09:24:38.864961Z",
workflow resource is created (by argo-server after I've clicked "submit" on cron wf in UI)
2."requestReceivedTimestamp": "2021-11-19T09:24:39.099789Z","stageTimestamp": "2021-11-19T09:24:39.103152Z",
get of workflow resource by argo-server
3."requestReceivedTimestamp": "2021-11-19T09:24:39.104016Z","stageTimestamp": "2021-11-19T09:24:40.315489Z",
watch of workflow resource by argo-server
4."requestReceivedTimestamp": "2021-11-19T09:24:39.104016Z","stageTimestamp": "2021-11-19T09:24:40.315591Z",
another watch of workflow resource by argo-server
5."requestReceivedTimestamp": "2021-11-19T09:25:37.067686Z","stageTimestamp": "2021-11-19T09:25:37.078395Z",
update of workflow resource by argo-workflow-controller (I think this is when this error happens: error in entry template execution: Deadline exceeded)
6."requestReceivedTimestamp": "2021-11-19T09:26:45.359921Z","stageTimestamp": "2021-11-19T09:26:45.390855Z",
pod resource created by argo-workflows-controller
7."requestReceivedTimestamp": "2021-11-19T09:26:45.392706Z","stageTimestamp": "2021-11-19T09:26:45.401720Z",
workflow resource is updated by argo-worflow-controller after pod was created

From that point workflow executes normally.
It seems that argo-workflows-controller starts to execute my workflow only after error in entry template execution: Deadline exceeded occurs

I've noticed that controller every minute send "list" request to api:
"/apis/argoproj.io/v1alpha1/namespaces/argo/workflows?labelSelector=%21workflows.argoproj.io%2Fphase%2Cworkflows.argoproj.io%2Fcontroller-instanceid%3Dargo-controller"
I'm not sure how controller can pick up workflow resources created between requests because normally I see workflows started being processed immediately after being creation.

Other thing I've noticed, I believe this is not so important but I see that sometimes controller uses "update" and on other times "path" requests and I don't know what's the difference here and why two typed of requests are being used.

[kobejn-jb]

@sarabala1979 Ok, I've found the cause of this problem. It's in workflow/controller/estimation/estimator_factory.go:

func (f *estimatorFactory) NewEstimator(wf *wfv1.Workflow) (Estimator, error) {
        defaultEstimator := &estimator{wf: wf}
        for labelName, indexName := range map[string]string{
                common.LabelKeyWorkflowTemplate:        indexes.WorkflowTemplateIndex,
                common.LabelKeyClusterWorkflowTemplate: indexes.ClusterWorkflowTemplateIndex,
                common.LabelKeyCronWorkflow:            indexes.CronWorkflowIndex,
        } {
                labelValue, exists := wf.Labels[labelName]
                if exists {

This part of code depends on workflows.argoproj.io/cron-workflow existing in workflow resource. To calculate the estimated duration of wf this function tries to find latest execution of wf created form same cronWorkflow (or workflowTemplate, clusterWorkflowTemplate) in kubernetes and when that fails it starts to look in archive. In my case archive is very slow to respond, there are thousands of workflows running daily so it seems that thread just hangs waiting for reply. I've build custom image where function NewEstimator always returns defaultEstimator and problem is gone. I'll check what I can do to speed-up the archive.