Liveness probe fails with 500 and workflow never reconciled when using semaphores

[atombender]

Version 3.1.1 is failing a lot for us:

$ kubectl get pod
NAME                                   READY   STATUS             RESTARTS   AGE
argo-server-895985bb9-fz2hf            1/1     Running            0          13h
workflow-controller-6c79bf6684-8xlbx   0/1     CrashLoopBackOff   83         9h

$ kubectl describe pod workflow-controller-6c79bf6684-8xlbx
[...]
Events:
  Type     Reason     Age                   From     Message
  ----     ------     ----                  ----     -------
  Warning  Unhealthy  4m54s (x251 over 9h)  kubelet  Liveness probe failed: HTTP probe failed with statuscode: 500
  Warning  BackOff    17s (x952 over 8h)    kubelet  Back-off restarting failed container

$ kubectl -n argo logs workflow-controller-6c79bf6684-8xlbx --tail=10
time="2021-07-16T06:50:23.197Z" level=info msg="Get leases 200"
time="2021-07-16T06:50:23.206Z" level=info msg="Update leases 200"
time="2021-07-16T06:50:28.211Z" level=info msg="Get leases 200"
time="2021-07-16T06:50:28.219Z" level=info msg="Update leases 200"
time="2021-07-16T06:50:33.224Z" level=info msg="Get leases 200"
time="2021-07-16T06:50:33.233Z" level=info msg="Update leases 200"
time="2021-07-16T06:50:38.238Z" level=info msg="Get leases 200"
time="2021-07-16T06:50:38.245Z" level=info msg="Update leases 200"
time="2021-07-16T06:50:42.410Z" level=info msg="List workflows 200"
time="2021-07-16T06:50:42.413Z" level=info msg=healthz age=5m0s err="workflow never reconciled: webhook-test-2h4zr" instanceID= labelSelector="!workflows.argoproj.io/phase,!workflows.argoproj.io/controller-instanceid" managedNamespace=

$ curl -si http://localhost:6060/healthz
HTTP/1.1 500 Internal Server Error
Date: Thu, 15 Jul 2021 21:24:52 GMT
Content-Length: 45
Content-Type: text/plain; charset=utf-8

workflow never reconciled: webhook-test-2h4zr

$ kubectl -n e2e get wf webhook-test-2h4zr
NAME                 STATUS   AGE
webhook-test-2h4zr

$ kubectl -n e2e get wf webhook-test-2h4zr -oyaml
[...]
status:
  artifactRepositoryRef:
    default: true
  finishedAt: null
  message: 'Waiting for e2e/ConfigMap/semaphore/all-workflows lock. Lock status: 1/1 '
  progress: 0/0
  startedAt: null
  storedTemplates: [...]
  synchronization:
    semaphore:
      waiting:
      - semaphore: e2e/ConfigMap/semaphore/all-workflows

---

Message from the maintainers:

Impacted by this bug? Give it a 👍. We prioritise the issues with the most 👍.

[alexec]

Interesting... this workflow does not have status.phase set, so the health check thinks it has never been reconciled - and therefore workflow controller has had a general error.

[sarabala1979]

@atombender can you provide the full workflow yaml (sample which we can reproduce) and controller log for that workflow?

[alexec]

I've committed a change, and our CI will push engineering builds argoproj/workflow-controller:dev-6351 and argoproj/argoexec:dev-6351 in 1h. Can you please test to see if it fixes your issue?

[alexec]

@sarabala1979 I jumped on this issue as (a) it will prevent workflows from running and (b) I wrote the code and (c) I could see a clear fix so knew it would be quick.

[atombender]

Thanks! We haven't seen the issue today, actually, but we've been heavily developing our workflows and things haven't really had a chance to "settle". I will see if I can put this fix into testing soon.

[alexec]

Thank you. The problem will only occur if you are using semaphores.

[atombender]

We haven't tried the build yes, as I need some support from our SRE staff. In the meantime, we got a panic relating to one of these workflows that don't have a status. Does this log help?

[atombender]

New log from the dev-6351 build: https://gist.github.com/atombender/03520de681ca7a09c9535065469ddc22

[alexec]

I've fixed the panic and pushed the change. It should be ready to test in < 1h. Can you please test again?

[atombender]

Deployed it and testing. I'm not seeing any status-less workflow, but it is apparently buggy in a different way: My workflow is stuck progressing on a daemon step that has successfully started.

• Workflow controller log
• Output of kubectl describe pod for stuck pod

Eventually, it fails with "Pod was active on the node longer than the specified deadline", and the workflow fails without any apparently retries, even though my workflow has:

  templateDefaults:
    retryStrategy:
      retryPolicy: onError
      limit: 10

When I roll back to the release version, it works.

[atombender]

I see this with multiple workflows. The initial pods start successfully, but no new steps are scheduled.

[alexec]

Can you try using :latest too?

[atombender]

Same behaviour. In case it's relevant, the wait container just says:

time="2021-07-20T15:38:55.097Z" level=info msg="Starting Workflow Executor" executorType=k8sapi version=untagged
time="2021-07-20T15:38:55.102Z" level=info msg="Creating a K8sAPI executor"
time="2021-07-20T15:38:55.103Z" level=info msg="Executor initialized" [...]
time="2021-07-20T15:38:55.104Z" level=info msg="Starting deadline monitor"
time="2021-07-20T15:38:55.111Z" level=info msg="Watch pods 200"

[alexec]

Looking at the kubectl describe output, your main container is still running, which is not terminated.

Can you double-check that this runs on v3.1.

[atombender]

It's a daemon: true step that's part of a DAG. Reverting to 3.1.2 works.

[alexec]

@atombender can you please raise a separate bug?

[atombender]

Sure.

[atombender]

#6379

[alexec]

So we can close this issue, can you test with a workflow that does not use daemon steps?

[atombender]

We haven't confirmed whether your fix solves this issue. Unfortunately, the problem doesn't always show up, and I have no idea what provokes it, but I will try to reproduce it. We don't have any workflows that don't use daemon steps.

[omerlh]

I am experiencing similar issue but without semaphor - saw this error in the logs:

argo-workflows-workflow-controller-7786c48df-zkwrj controller time="2024-06-23T09:48:19.772Z" level=error msg="recovered from panic &{%!q(*logrus.Logger=&{0xc000098030 map[2:[0xc0007242d0] 3:[0xc0007242d0] 4:[0xc0007242d0]] 0xc0000b9c20 false 4 {{0 0} false} {{} 0xc088e8b000 16 0xc000186000 0 <nil>} 0x4f4480 <nil>}) map[\"fromPhase\":\"Succeeded\" \"namespace\":\"workflows\" \"toPhase\":\"Error\" \"workflow\":\"recon-0394134a-f3ea-43f2-85c5-22fe67c0e06c-rspl8\"] \"2024-06-23 09:48:19.56050614 +0000 UTC m=+368.315614323\" \"panic\" %!q(*runtime.Frame=<nil>) \"workflow is already fulfilled\" \"<nil>\" <nil> \"\"}. Call stack:\ngoroutine 390 [running]:\ngithub.com/argoproj/argo-workflows/v3/util/runtime.RecoverFromPanic(0xc081379da0?)\n\t/go/src/github.com/argoproj/argo-workflows/util/runtime/panic.go:15 +0x65\npanic({0x23d9b00?, 0xc0020ab0a0?})\n\t/usr/local/go/src/runtime/panic.go:920 +0x270\ngithub.com/sirupsen/logrus.(*Entry).log(0xc0020ab030, 0x0, {0xc0311e9ec0, 0x1d})\n\t/go/pkg/mod/github.com/sirupsen/logrus@v1.9.3/entry.go:260 +0x491\ngithub.com/sirupsen/logrus.(*Entry).Log(0xc0020ab030, 0x0, {0xc002783bf0?, 0x7?, 0xc002783a18?})\n\t/go/pkg/mod/github.com/sirupsen/logrus@v1.9.3/entry.go:304 +0x48\ngithub.com/sirupsen/logrus.(*Entry).Panic(...)\n\t/go/pkg/mod/github.com/sirupsen/logrus@v1.9.3/entry.go:342\ngithub.com/argoproj/argo-workflows/v3/workflow/controller.(*wfOperationCtx).markWorkflowPhase(0xc0874423c0, {0x27be158, 0x3a5b2c0}, {0x2414c81, 0x5}, {0xc001a04500, 0xf2})\n\t/go/src/github.com/argoproj/argo-workflows/workflow/controller/operator.go:2291 +0x325\ngithub.com/argoproj/argo-workflows/v3/workflow/controller.(*wfOperationCtx).markWorkflowError(0x24135ec?, {0x27be158, 0x3a5b2c0}, {0x2794340?, 0xc05d12c100?})\n\t/go/src/github.com/argoproj/argo-workflows/workflow/controller/operator.go:2424 +0x56\ngithub.com/argoproj/argo-workflows/v3/workflow/controller.(*wfOperationCtx).operate.func2()\n\t/go/src/github.com/argoproj/argo-workflows/workflow/controller/operator.go:204 +0x234\npanic({0x23d9b00?, 0xc0020aae00?})\n\t/usr/local/go/src/runtime/panic.go:920 +0x270\ngithub.com/sirupsen/logrus.(*Entry).log(0xc0020aad90, 0x0, {0xc0311e9e40, 0x1d})\n\t/go/pkg/mod/github.com/sirupsen/logrus@v1.9.3/entry.go:260 +0x491\ngithub.com/sirupsen/logrus.(*Entry).Log(0xc0020aad90, 0x0, {0xc0027849e8?, 0x7?, 0x30?})\n\t/go/pkg/mod/github.com/sirupsen/logrus@v1.9.3/entry.go:304 +0x48\ngithub.com/sirupsen/logrus.(*Entry).Panic(...)\n\t/go/pkg/mod/github.com/sirupsen/logrus@v1.9.3/entry.go:342\ngithub.com/argoproj/argo-workflows/v3/workflow/controller.(*wfOperationCtx).markWorkflowPhase(0xc0874423c0, {0x27be158, 0x3a5b2c0}, {0x2416255, 0x6}, {0xc089c145b0, 0x64})\n\t/go/src/github.com/argoproj/argo-workflows/workflow/controller/operator.go:2291 +0x325\ngithub.com/argoproj/argo-workflows/v3/workflow/controller.(*wfOperationCtx).markWorkflowFailed(...)\n\t/go/src/github.com/argoproj/argo-workflows/workflow/controller/operator.go:2420\ngithub.com/argoproj/argo-workflows/v3/workflow/controller.(*wfOperationCtx).operate(0xc0874423c0, {0x27be158?, 0x3a5b2c0})\n\t/go/src/github.com/argoproj/argo-workflows/workflow/controller/operator.go:261 +0xaf4\ngithub.com/argoproj/argo-workflows/v3/workflow/controller.(*WorkflowController).processNextItem(0xc000158000, {0x27be158, 0x3a5b2c0})\n\t/go/src/github.com/argoproj/argo-workflows/workflow/controller/controller.go:811 +0x627\ngithub.com/argoproj/argo-workflows/v3/workflow/controller.(*WorkflowController).runWorker(0xc000015ea0?)\n\t/go/src/github.com/argoproj/argo-workflows/workflow/controller/controller.go:734 +0x88\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x30?)\n\t/go/pkg/mod/k8s.io/apimachinery@v0.24.3/pkg/util/wait/wait.go:155 +0x33\nk8s.io/apimachinery/pkg/util/wait.BackoffUntil(0x0?, {0x2796540, 0xc083347290}, 0x1, 0xc0002d12c0)\n\t/go/pkg/mod/k8s.io/apimachinery@v0.24.3/pkg/util/wait/wait.go:156 +0xaf\nk8s.io/apimachinery/pkg/util/wait.JitterUntil(0x17ba8a0?, 0x3b9aca00, 0x0, 0xe0?, 0x17ba9a0?)\n\t/go/pkg/mod/k8s.io/apimachinery@v0.24.3/pkg/util/wait/wait.go:133 +0x7f\nk8s.io/apimachinery/pkg/util/wait.Until(0xc000015f80?, 0xa005aa001?, 0xc000015fa0?)\n\t/go/pkg/mod/k8s.io/apimachinery@v0.24.3/pkg/util/wait/wait.go:90 +0x1e\ncreated by github.com/argoproj/argo-workflows/v3/workflow/controller.(*WorkflowController).Run in goroutine 84\n\t/go/src/github.com/argoproj/argo-workflows/workflow/controller/controller.go:344 +0x1885\n" namespace=workflows workflow=recon-0394134a-f3ea-43f2-85c5-22fe67c0e06c-rspl8

Once I deleted the workflow in the log the controller is live again - but it was very old workflow so I am not sure what happened

[ospiegel91]

were still experiencing this issue, memory util of controller is at 30%.

[agilgur5]

I am experiencing similar issue but without semaphor [sic]

That's a different issue then. Same error message but different cause. Please open a new issue with a reproduction.

This specific issue was with semaphores and was resolved 3 years ago with no further comments.