Can't resolve resourcesDuration for metrics in some templates

[andrew-arkhipov]

Summary

I have two templates, one is a dummy template straight from the docs (e.g. flakey), and the other is work-specific that is much more complex, though I'm providing a simpler one as an example. When specifying Prometheus metrics, {{resourcesDuration.cpu|memory}} works just fine in the dummy workflow template, but it doesn't work in the actual template that I'm trying to add it to.

Just a note: unfortunately I cannot make this bug reproducible because it contains IP/info that is under strict compliance guidelines, and I'd rather be safe than sorry.

What happened/what you expected to happen?

I expected {{resourcesDuration.cpu|memory}} to resolve when running a workflow template and get emitted as a Prometheus metric.

Diagnostics

I attempted to put a Prometheus metrics section in the yaml file in every possible location. I also tried reducing the template down to basic parts, such as just using one dag with simple, workflow-related tasks. Please keep in mind I have very little experience with Argo workflows so I'm still learning.

What Kubernetes provider are you using?

AWS

What version of Argo Workflows are you running?

3.0.2

What executor are you running? Docker/K8SAPI/Kubelet/PNS/Emissary

Kubelet

Did this work in a previous version? I.e. is it a regression?

Don't know

This template is just one of the simpler ones we are using. I can provide a more complex one later if requested, but similar to this one it won't be usable since I'll need to redact information.

apiVersion: argoproj.io/v1alpha1
kind: WorkflowTemplate
metadata:
  namespace: workflows
  name: is-valid
spec:
  artifactRepositoryRef:
    configMap: workflow-controller-configmap
    key: artifactRepository
  ttlStrategy:
    secondsAfterCompletion: 604800  # 7 days, time to live after workflow is completed, replaces ttlSecondsAfterFinished
    secondsAfterSuccess: 604800     # 7 days, time to live after workflow is successful
    secondsAfterFailure: 604800     # 7 days, time to live after workflow fails

  templates:
  - name: is-valid  # This template succeeds (exit code 0) if the input exit code implies no retry is necessary, and fails otherwise.
    metrics:
      prometheus:
        - name: success_count_total # this one works
          labels:
            - key: name
              value: is-valid
          help: "Stage execution success counter"
          when: '{{status}} == Succeeded'
          counter:
            value: '1'
        - name: failure_count_total # this one works
          labels:
            - key: name
              value: is-valid
          help: "Stage execution failure counter"
          when: '{{status}} == Failed'
          counter:
            value: '1'
        - name: error_count_total # this one works
          labels:
            - key: name
              value: is-valid
          help: "Stage execution error counter"
          when: '{{status}} == Error'
          counter:
            value: '1'
       - name: resource_duration_cpu # this one doesn't work
          labels:
            key: name
            value: is-valid
          gauge:
            realtime: false
            value: "{{resourcesDuration.cpu}}"
       - name: resource_duration_memory # this one doesn't work
          labels:
            key: name
            value: is-valid
          gauge:
            realtime: false
            value: "{{resourcesDuration.memory}}"
    serviceAccountName: argo-workflow-watcher
    inputs:
      parameters:
      - name: exit-code  # This represents the exit code of the pod that we are considering for retry.
      - name: exit-code-retry-values  # This represents the list of exit codes/regexes that we will retry on.
    retryStrategy:
      limit: "4"
      backoff:
        duration: "10"
      retryPolicy: "OnError"
    container:
      image: # redacted
      imagePullPolicy: IfNotPresent
      command: [bash, -c]
      args: [
        "sleep 60; retry_values=({{inputs.parameters.exit-code-retry-values}}); for e in ${retry_values[*]}; do if [[ {{inputs.parameters.exit-code}} == $e ]]; then exit 1; fi; done;"
      ]

Paste the logs from the workflow controller:
kubectl logs -n argo deploy/workflow-controller | grep ${workflow}

Paste the logs from your workflow's wait container:
kubectl logs -c wait -l workflows.argoproj.io/workflow=${workflow}

I don't have perms for the above commands, unfortunately. I will try to get someone who does to run them but in the meantime, all I can provide is the following:

MetricsError: unable to substitute parameters for metric 'resource_duration_cpu': failed to resolve {{resourcesDuration.cpu}}, unable to substitute parameters for metric 'resource_duration_memory': failed to resolve {{resourcesDuration.memory}}

---

Message from the maintainers:

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

[alexec]

I don't see any examples of {{resourcesDuration in the code-base?

[andrew-arkhipov]

I don't see any examples of {{resourcesDuration in the code-base?

See variables.md. It's right there.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[alexec]

See variables.md. It's right there.

That could be a mistake and should probably be corrected.

[kennytrytek]

Here's a simple example to reproduce this issue:

apiVersion: argoproj.io/v1alpha1
kind: Workflow
metadata:
  generateName: whale-my-resources-
spec:
  metrics:
      prometheus:
        - name: cpu
          help: cpu
          gauge:
            realtime: true
            value: "{{resourcesDuration.cpu}}"
  entrypoint: whalesay
  templates:
  - name: whalesay
    script:
      image: alpine:3
      command: [/bin/sh]
      source: |
        sleep 20

Submit the workflow:

$ argo submit ./wmr.yaml

Log entry from the controller:

 controller | time="2021-11-27T22:11:19.626Z" level=debug msg="Log changes patch: {\"status\":{\"conditions\":[{\"message\":\"unable to substitute parameters for metric 'cpu': failed to resolve {{resourcesDuration.cpu}}, unable to substitute parameters for metric 'cpu': failed to resolve {{resourcesDuration.cpu}}, unable to substitute parameters for metric 'cpu': failed to resolve {{resourcesDuration.cpu}}, unable to substitute parameters for metric 'cpu': failed to resolve {{resourcesDuration.cpu}}\",\"status\":\"True\",\"type\":\"MetricsError\"},{\"status\":\"True\",\"type\":\"PodRunning\"}],\"nodes\":{\"whale-my-resources-kfchm\":{\"message\":null,\"phase\":\"Running\"}}}}"

This is certainly an unexpected behavior, since it seems like there is code added to make these metrics resolvable:
https://github.com/argoproj/argo-workflows/blob/v3.2.4/workflow/controller/steps.go#L541-L545

	if node.ResourcesDuration != nil {
		for name, duration := range node.ResourcesDuration {
			localScope[fmt.Sprintf("%s.%s", common.LocalVarResourcesDuration, name)] = fmt.Sprint(duration.Duration().Seconds())
		}
	}

Interestingly, if I change the metrics section to look like this:

metrics:
    prometheus:
      - name: duration
        help: duration
        gauge:
          realtime: true
          value: "{{workflow.duration}}"

The log message looks like this, with a correctly populated resourcesDuration field:

 controller | time="2021-11-27T22:26:19.314Z" level=debug msg="Log changes patch: {\"metadata\":{\"labels\":{\"workflows.argoproj.io/completed\":\"true\",\"workflows.argoproj.io/phase\":\"Succeeded\",\"workflows.argoproj.io/workflow-archiving-status\":\"Pending\"}},\"status\":{\"conditions\":[{\"status\":\"False\",\"type\":\"PodRunning\"},{\"status\":\"True\",\"type\":\"Completed\"}],\"finishedAt\":\"2021-11-28T04:26:19Z\",\"nodes\":{\"whale-my-resources-5nr76\":{\"finishedAt\":\"2021-11-28T04:26:18Z\",\"outputs\":{\"artifacts\":[{\"name\":\"main-logs\",\"s3\":{\"key\":\"whale-my-resources-5nr76/whale-my-resources-5nr76/main.log\"}}],\"exitCode\":\"0\"},\"phase\":\"Succeeded\",\"progress\":\"1/1\",\"resourcesDuration\":{\"cpu\":41,\"memory\":33}}},\"phase\":\"Succeeded\"}}"

I can continue looking at this and try to figure out why it doesn't like resourcesDuration.