argo-workflows: artifactory main pod log storing using workflow-controller-configmap gives nil pointer panic

Summary

I wanted to store the main pod logs of my steps directly on artifactory, so followed the (splintered) docs I found to configure artifactory repo in the workflow-config-map, but I see the wait container (argoexec) crashing

Diagnostics

Using docker executor

What version of Argo Workflows are you running? 3.0.1

apiVersion: argoproj.io/v1alpha1
kind: Workflow
metadata:
  creationTimestamp: "2021-04-21T21:20:08Z"
  generateName: nested-workflow-
  generation: 5
  labels:
    workflows.argoproj.io/phase: Running
  name: nested-wf-test
  namespace: default
  resourceVersion: "150308175"
  selfLink: /apis/argoproj.io/v1alpha1/namespaces/default/workflows/nested-wf-test
  uid: 8f930f77-8a87-4915-9815-ff97b872e952
spec:
  arguments: {}
  entrypoint: nested-workflow-example
  templates:
  - inputs: {}
    metadata: {}
    name: nested-workflow-example
    outputs: {}
    steps:
    - - arguments:
          parameters:
          - name: excluded_node
            value: ""
        continueOn:
          failed: true
        name: runtb
        template: sleepabit
    - - arguments:
          parameters:
          - name: excluded_node
            value: '{{workflow.outputs.parameters.nodename}}'
        continueOn:
          failed: true
        name: retryrun
        template: sleepabit
        when: '{{steps.runtb.status}} != Succeeded'
  - affinity:
      nodeAffinity:
        requiredDuringSchedulingIgnoredDuringExecution:
          nodeSelectorTerms:
          - matchExpressions:
            - key: kubernetes.io/hostname
              operator: NotIn
              values:
              - '{{inputs.parameters.excluded_node}}'
    container:
      args:
      - echo $NODE_NAME > nodename.txt && echo blablabla && sleep 5 && false
      command:
      - sh
      - -c
      env:
      - name: NODE_NAME
        valueFrom:
          fieldRef:
            fieldPath: spec.nodeName
      image: alpine:3.7
      name: ""
      resources: {}
    inputs:
      parameters:
      - name: excluded_node
    metadata: {}
    name: sleepabit
    outputs:
      parameters:
      - globalName: nodename
        name: nodename
        valueFrom:
          path: nodename.txt
    retryStrategy:
      limit: 2
      retryPolicy: OnError
status:
  artifactRepositoryRef:
    default: true
  conditions:
  - status: "False"
    type: PodRunning
  finishedAt: null
  nodes:
    nested-wf-test:
      children:
      - nested-wf-test-4187779359
      displayName: nested-wf-test
      finishedAt: null
      id: nested-wf-test
      name: nested-wf-test
      phase: Running
      progress: 1/2
      startedAt: "2021-04-21T21:20:08Z"
      templateName: nested-workflow-example
      templateScope: local/nested-wf-test
      type: Steps
    nested-wf-test-73877493:
      boundaryID: nested-wf-test
      children:
      - nested-wf-test-1033837250
      displayName: runtb(0)
      finishedAt: "2021-04-21T21:20:24Z"
      hostNodeName: dev11-gsn107-k8s-med-worker-1
      id: nested-wf-test-73877493
      inputs:
        parameters:
        - name: excluded_node
          value: ""
      message: Error (exit code 1)
      name: nested-wf-test[0].runtb(0)
      phase: Failed
      progress: 1/1
      resourcesDuration:
        cpu: 10
        memory: 10
      startedAt: "2021-04-21T21:20:08Z"
      templateName: sleepabit
      templateScope: local/nested-wf-test
      type: Pod
    nested-wf-test-1033837250:
      boundaryID: nested-wf-test
      children:
      - nested-wf-test-3144780967
      displayName: '[1]'
      finishedAt: null
      id: nested-wf-test-1033837250
      name: nested-wf-test[1]
      phase: Running
      progress: 0/1
      startedAt: "2021-04-21T21:20:27Z"
      templateScope: local/nested-wf-test
      type: StepGroup
    nested-wf-test-1133525750:
      boundaryID: nested-wf-test
      children:
      - nested-wf-test-73877493
      displayName: runtb
      finishedAt: "2021-04-21T21:20:27Z"
      id: nested-wf-test-1133525750
      inputs:
        parameters:
        - name: excluded_node
          value: ""
      message: Error (exit code 1)
      name: nested-wf-test[0].runtb
      phase: Failed
      progress: 1/2
      resourcesDuration:
        cpu: 10
        memory: 10
      startedAt: "2021-04-21T21:20:08Z"
      templateName: sleepabit
      templateScope: local/nested-wf-test
      type: Retry
    nested-wf-test-3144780967:
      boundaryID: nested-wf-test
      children:
      - nested-wf-test-3241021146
      displayName: retryrun
      finishedAt: null
      id: nested-wf-test-3144780967
      inputs:
        parameters:
        - name: excluded_node
          value: '{{workflow.outputs.parameters.nodename}}'
      name: nested-wf-test[1].retryrun
      phase: Running
      progress: 0/1
      startedAt: "2021-04-21T21:20:27Z"
      templateName: sleepabit
      templateScope: local/nested-wf-test
      type: Retry
    nested-wf-test-3241021146:
      boundaryID: nested-wf-test
      displayName: retryrun(0)
      finishedAt: null
      id: nested-wf-test-3241021146
      inputs:
        parameters:
        - name: excluded_node
          value: '{{workflow.outputs.parameters.nodename}}'
      message: 'Unschedulable: 0/72 nodes are available: 72 node(s) didn''t match
        node selector.'
      name: nested-wf-test[1].retryrun(0)
      phase: Pending
      progress: 0/1
      startedAt: "2021-04-21T21:20:27Z"
      templateName: sleepabit
      templateScope: local/nested-wf-test
      type: Pod
    nested-wf-test-4187779359:
      boundaryID: nested-wf-test
      children:
      - nested-wf-test-1133525750
      displayName: '[0]'
      finishedAt: "2021-04-21T21:20:27Z"
      id: nested-wf-test-4187779359
      name: nested-wf-test[0]
      phase: Succeeded
      progress: 1/2
      resourcesDuration:
        cpu: 10
        memory: 10
      startedAt: "2021-04-21T21:20:08Z"
      templateScope: local/nested-wf-test
      type: StepGroup
  phase: Running
  progress: 1/2
  resourcesDuration:
    cpu: 10
    memory: 10
  startedAt: "2021-04-21T21:20:08Z"

I then recompiled argoexec to add some extra prints to see the various variables in use:

kubectl logs nested-wf-test-73877493 -c wait -f
time="2021-04-21T21:20:19.230Z" level=info msg="Starting Workflow Executor" version="{untagged 2021-04-21T21:06:04Z 46221c5c901ce3df1ce3144cf6d54705c1e8eb04 untagged clean go1.15.7 gc linux/amd64}"
I0421 21:20:19.231385       1 merged_client_builder.go:121] Using in-cluster configuration
I0421 21:20:19.231668       1 merged_client_builder.go:163] Using in-cluster namespace
time="2021-04-21T21:20:19.235Z" level=info msg="Creating a docker executor"
time="2021-04-21T21:20:19.235Z" level=info msg="Executor (version: untagged, build_date: 2021-04-21T21:06:04Z) initialized (pod: default/nested-wf-test-73877493) with template:\n{\"name\":\"sleepabit\",\"inputs\":{\"parameters\":[{\"name\":\"excluded_node\",\"value\":\"\"}]},\"outputs\":{\"parameters\":[{\"name\":\"nodename\",\"valueFrom\":{\"path\":\"nodename.txt\"},\"globalName\":\"nodename\"}]},\"affinity\":{\"nodeAffinity\":{\"requiredDuringSchedulingIgnoredDuringExecution\":{\"nodeSelectorTerms\":[{\"matchExpressions\":[{\"key\":\"kubernetes.io/hostname\",\"operator\":\"NotIn\",\"values\":[\"\"]}]}]}}},\"metadata\":{},\"container\":{\"name\":\"\",\"image\":\"alpine:3.7\",\"command\":[\"sh\",\"-c\"],\"args\":[\"echo $NODE_NAME \\u003e nodename.txt \\u0026\\u0026 echo blablabla \\u0026\\u0026 sleep 5 \\u0026\\u0026 false\"],\"env\":[{\"name\":\"NODE_NAME\",\"valueFrom\":{\"fieldRef\":{\"fieldPath\":\"spec.nodeName\"}}}],\"resources\":{}},\"archiveLocation\":{\"archiveLogs\":true,\"artifactory\":{\"url\":\"http://artifactory-espoo1.int.net.nokia.com/artifactory/fixedaccess-sw-rpm-local/nested-wf-test/nested-wf-test-73877493\",\"usernameSecret\":{\"name\":\"artifactory-sandbox\",\"key\":\"username\"},\"passwordSecret\":{\"name\":\"artifactory-sandbox\",\"key\":\"password\"}}},\"retryStrategy\":{\"limit\":2,\"retryPolicy\":\"OnError\"}}"
time="2021-04-21T21:20:19.235Z" level=info msg="Starting annotations monitor"
time="2021-04-21T21:20:19.235Z" level=info msg="docker ps --all --no-trunc --format={{.Status}}|{{.Label \"io.kubernetes.container.name\"}}|{{.ID}}|{{.CreatedAt}} --filter=label=io.kubernetes.pod.namespace=default --filter=label=io.kubernetes.pod.name=nested-wf-test-73877493"
time="2021-04-21T21:20:19.235Z" level=info msg="Starting deadline monitor"
time="2021-04-21T21:20:19.280Z" level=info msg="mapped container name \"main\" to container ID \"7c3b4ec01ec4f5015110f7307aaba01caf68d7a90dd20385ea13a95831c2d530\" (created at 2021-04-21 21:20:19 +0000 UTC, status Created)"
time="2021-04-21T21:20:19.280Z" level=info msg="mapped container name \"wait\" to container ID \"b5004cf8e03affa2199aead9ea5767d22a799490e9d24ce9d5066a3376eabd9b\" (created at 2021-04-21 21:20:19 +0000 UTC, status Up)"
time="2021-04-21T21:20:20.235Z" level=info msg="docker wait 7c3b4ec01ec4f5015110f7307aaba01caf68d7a90dd20385ea13a95831c2d530"
time="2021-04-21T21:20:20.280Z" level=info msg="docker ps --all --no-trunc --format={{.Status}}|{{.Label \"io.kubernetes.container.name\"}}|{{.ID}}|{{.CreatedAt}} --filter=label=io.kubernetes.pod.namespace=default --filter=label=io.kubernetes.pod.name=nested-wf-test-73877493"
time="2021-04-21T21:20:21.314Z" level=info msg="docker ps --all --no-trunc --format={{.Status}}|{{.Label \"io.kubernetes.container.name\"}}|{{.ID}}|{{.CreatedAt}} --filter=label=io.kubernetes.pod.namespace=default --filter=label=io.kubernetes.pod.name=nested-wf-test-73877493"
time="2021-04-21T21:20:22.350Z" level=info msg="docker ps --all --no-trunc --format={{.Status}}|{{.Label \"io.kubernetes.container.name\"}}|{{.ID}}|{{.CreatedAt}} --filter=label=io.kubernetes.pod.namespace=default --filter=label=io.kubernetes.pod.name=nested-wf-test-73877493"
time="2021-04-21T21:20:23.384Z" level=info msg="docker ps --all --no-trunc --format={{.Status}}|{{.Label \"io.kubernetes.container.name\"}}|{{.ID}}|{{.CreatedAt}} --filter=label=io.kubernetes.pod.namespace=default --filter=label=io.kubernetes.pod.name=nested-wf-test-73877493"
time="2021-04-21T21:20:24.420Z" level=info msg="docker ps --all --no-trunc --format={{.Status}}|{{.Label \"io.kubernetes.container.name\"}}|{{.ID}}|{{.CreatedAt}} --filter=label=io.kubernetes.pod.namespace=default --filter=label=io.kubernetes.pod.name=nested-wf-test-73877493"
time="2021-04-21T21:20:24.560Z" level=info msg="Main container completed"
time="2021-04-21T21:20:24.560Z" level=info msg="No Script output reference in workflow. Capturing script output ignored"
time="2021-04-21T21:20:24.560Z" level=info msg="Capturing script exit code"
time="2021-04-21T21:20:24.595Z" level=info msg="Saving logs"
time="2021-04-21T21:20:24.595Z" level=info msg="[docker logs 7c3b4ec01ec4f5015110f7307aaba01caf68d7a90dd20385ea13a95831c2d530]"
time="2021-04-21T21:20:24.630Z" level=info msg="art: &Artifact{Name:main-logs,Path:,Mode:nil,From:,ArtifactLocation:ArtifactLocation{ArchiveLogs:nil,S3:nil,Git:nil,HTTP:nil,Artifactory:&ArtifactoryArtifact{URL:/artifactory/fixedaccess-sw-rpm-local/nested-wf-test/nested-wf-test-73877493/main.log,ArtifactoryAuth:ArtifactoryAuth{UsernameSecret:nil,PasswordSecret:nil,},},HDFS:nil,Raw:nil,OSS:nil,GCS:nil,},GlobalName:,Archive:nil,Optional:false,SubPath:,RecurseMode:false,}"
time="2021-04-21T21:20:24.630Z" level=info msg="driverArt: &Artifact{Name:main-logs,Path:,Mode:nil,From:,ArtifactLocation:ArtifactLocation{ArchiveLogs:nil,S3:nil,Git:nil,HTTP:nil,Artifactory:&ArtifactoryArtifact{URL:/artifactory/fixedaccess-sw-rpm-local/nested-wf-test/nested-wf-test-73877493/main.log,ArtifactoryAuth:ArtifactoryAuth{UsernameSecret:nil,PasswordSecret:nil,},},HDFS:nil,Raw:nil,OSS:nil,GCS:nil,},GlobalName:,Archive:nil,Optional:false,SubPath:,RecurseMode:false,}"
time="2021-04-21T21:20:24.630Z" level=info msg="driverArt: &Artifact{Name:main-logs,Path:,Mode:nil,From:,ArtifactLocation:ArtifactLocation{ArchiveLogs:nil,S3:nil,Git:nil,HTTP:nil,Artifactory:&ArtifactoryArtifact{URL:/artifactory/fixedaccess-sw-rpm-local/nested-wf-test/nested-wf-test-73877493/main.log,ArtifactoryAuth:ArtifactoryAuth{UsernameSecret:nil,PasswordSecret:nil,},},HDFS:nil,Raw:nil,OSS:nil,GCS:nil,},GlobalName:,Archive:nil,Optional:false,SubPath:,RecurseMode:false,}"
time="2021-04-21T21:20:24.630Z" level=info msg=NewDriver
time="2021-04-21T21:20:24.630Z" level=info msg=Artifactory
time="2021-04-21T21:20:24.630Z" level=info msg="Artifactory: &ArtifactoryArtifact{URL:/artifactory/fixedaccess-sw-rpm-local/nested-wf-test/nested-wf-test-73877493/main.log,ArtifactoryAuth:ArtifactoryAuth{UsernameSecret:nil,PasswordSecret:nil,},}"
time="2021-04-21T21:20:24.630Z" level=info msg="Alloc=4327 TotalAlloc=9206 Sys=74577 NumGC=4 Goroutines=9"
time="2021-04-21T21:20:24.630Z" level=fatal msg="executor panic: runtime error: invalid memory address or nil pointer dereference\ngoroutine 1 [running]:\nruntime/debug.Stack(0x2053ed2, 0x14, 0xc0006b41c0)\n\t/usr/local/go/src/runtime/debug/stack.go:24 +0x9f\ngithub.com/argoproj/argo-workflows/v3/workflow/executor.(*WorkflowExecutor).HandleError(0xc00037b600, 0x23706c0, 0xc000190020)\n\t/go/src/github.com/argoproj/argo-workflows/workflow/executor/executor.go:126 +0x1d6\npanic(0x1dac5c0, 0x3064ec0)\n\t/usr/local/go/src/runtime/panic.go:975 +0x47a\ngithub.com/argoproj/argo-workflows/v3/workflow/artifacts.NewDriver(0x23706c0, 0xc000190020, 0xc000726240, 0x23324c0, 0xc00037b600, 0xc00071f960, 0xa388f5, 0xc0002330e0, 0x2005e00)\n\t/go/src/github.com/argoproj/argo-workflows/workflow/artifacts/artifacts.go:99 +0xa21\ngithub.com/argoproj/argo-workflows/v3/workflow/executor.(*WorkflowExecutor).InitDriver(0xc00037b600, 0x23706c0, 0xc000190020, 0xc000726240, 0xc00071f9f0, 0x1, 0x1, 0xa8)\n\t/go/src/github.com/argoproj/argo-workflows/workflow/executor/executor.go:586 +0x65\ngithub.com/argoproj/argo-workflows/v3/workflow/executor.(*WorkflowExecutor).saveArtifactFromFile(0xc00037b600, 0x23706c0, 0xc000190020, 0xc000726180, 0x20400e7, 0x8, 0xc000734b60, 0x1f, 0x0, 0xc000190020)\n\t/go/src/github.com/argoproj/argo-workflows/workflow/executor/executor.go:316 +0x1be\ngithub.com/argoproj/argo-workflows/v3/workflow/executor.(*WorkflowExecutor).SaveLogs(0xc00037b600, 0x23706c0, 0xc000190020, 0x0, 0x0, 0xc00071fba0)\n\t/go/src/github.com/argoproj/argo-workflows/workflow/executor/executor.go:542 +0x23d\ngithub.com/argoproj/argo-workflows/v3/cmd/argoexec/commands.waitContainer(0x23706c0, 0xc000190020, 0x0, 0x0)\n\t/go/src/github.com/argoproj/argo-workflows/cmd/argoexec/commands/wait.go:61 +0x61f\ngithub.com/argoproj/argo-workflows/v3/cmd/argoexec/commands.NewWaitCommand.func1(0xc00037ab00, 0xc0000a93e0, 0x0, 0x6)\n\t/go/src/github.com/argoproj/argo-workflows/cmd/argoexec/commands/wait.go:18 +0x3d\ngithub.com/spf13/cobra.(*Command).execute(0xc00037ab00, 0xc0000a9380, 0x6, 0x6, 0xc00037ab00, 0xc0000a9380)\n\t/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:846 +0x2c2\ngithub.com/spf13/cobra.(*Command).ExecuteC(0xc00037a2c0, 0xc000086778, 0xc00071ff78, 0x4062c5)\n\t/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:950 +0x375\ngithub.com/spf13/cobra.(*Command).Execute(...)\n\t/go/pkg/mod/github.com/spf13/cobra@v1.0.0/command.go:887\nmain.main()\n\t/go/src/github.com/argoproj/argo-workflows/cmd/argoexec/main.go:14 +0x2b\n"

workflow controller configmap

apiVersion: v1
data:
  artifactRepository: |
    # archiveLogs will archive the main container logs as an artifact
    archiveLogs: true
    artifactory:
      repoURL: "http://artifactory-espoo1.int.net.nokia.com/artifactory/fixedaccess-sw-rpm-local"
      usernameSecret:
        name: artifactory-sandbox
        key: username
      passwordSecret:
        name: artifactory-sandbox
        key: password
  executor: |
    imagePullPolicy: Always
    args:
    - --loglevel
    - debug
    - --gloglevel
    - "6"
kind: ConfigMap
metadata:
  annotations:
    kubectl.kubernetes.io/last-applied-configuration: |
      {"apiVersion":"v1","kind":"ConfigMap","metadata":{"annotations":{},"name":"workflow-controller-configmap","namespace":"argo"}}
  creationTimestamp: "2021-01-27T18:28:36Z"
  name: workflow-controller-configmap
  namespace: argo
  resourceVersion: "150280397"
  selfLink: /api/v1/namespaces/argo/configmaps/workflow-controller-configmap
  uid: 62afdfd0-32bb-4ed5-88bf-f8db88ed6706

and the secret (base64 removed)

apiVersion: v1
data:
  password: xxxxxxxxxxxxxxx
  username: xxxxxxxxxxx
kind: Secret
metadata:
  creationTimestamp: "2021-04-21T16:17:47Z"
  name: artifactory-sandbox
  namespace: default
  resourceVersion: "149896347"
  selfLink: /api/v1/namespaces/default/secrets/artifactory-sandbox
  uid: 806ba8d8-183b-4210-a39f-06eeb2b2b9e5
type: Opaque

---

Message from the maintainers:

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