Argo: v2.10.0-rc4 nested maps in loop rendered as Golang map[]

Created on 31 Jul 2020  ·  10Comments  ·  Source: argoproj/argo

Checklist:

  • [x] I've included the version.
  • [x] I've included reproduction steps.
  • [x] I've included the workflow YAML.
  • [x] I've included the logs.

What happened:
Using v2.10.0, when looping over a JSON list with nested object with withParam, references to nested JSON objects results in a Golang style map %v string rather than the nested JSON.

What you expected to happen:
Nested maps should remain the same as the input structure, escaped in the same way as referenced in #3409 (appears mostly fixed in 2.10.x).

How to reproduce it (as minimally and precisely as possible):

Using following workflow:

kind: Workflow
metadata:
  generateName: nested-test-
spec:
  entrypoint: main

  templates:
  - name: main
    inputs:
      parameters:
      - name: things
        value: '[{"nested": {"B": "2 \"foo\""}}]'
    steps:
    - - name: echoitems
        template: echo
        arguments:
          parameters:
            - name: thing
              value: "{{item.nested}}"
        withParam: "{{inputs.parameters.things}}"

  - name: echo
    inputs:
      parameters:
        - name: thing
    container:
      image: busybox
      command: [echo]
      args: ["{{inputs.parameters.thing}}"]

Using ./tools/argo/argov2.10.0-rc4 submit nested-test.yaml --watch

Name:                nested-test-v7v4d
Namespace:           default
ServiceAccount:      default
Status:              Succeeded
Conditions:          
 Completed           True
Created:             Fri Jul 31 19:48:27 +0100 (24 seconds ago)
Started:             Fri Jul 31 19:48:27 +0100 (24 seconds ago)
Finished:            Fri Jul 31 19:48:51 +0100 (now)
Duration:            24 seconds
ResourcesDuration:   4s*(1 cpu),4s*(100Mi memory)

STEP                                       TEMPLATE  PODNAME                       DURATION  MESSAGE
 ✔ nested-test-v7v4d                       main                                                
 └---✔ echoitems(0:nested:map[B:2 "foo"])  echo      nested-test-v7v4d-2387945936  22s

And, showing the workflow logs:

 ./tools/argo/argov2.10.0-rc4 logs nested-test-v7v4d
nested-test-v7v4d-2387945936: 2020-07-31T18:48:48.492777953Z map[B:2 "foo"]

In 2.9.4 I get the expected behaviour:

./tools/argo/argov2.9.4 logs nested-test-ptmh5
nested-test-ptmh5-4036727801: 2020-07-31T18:45:47.098717735Z {"B":"2 \"foo\""}

Anything else we need to know?:

Environment:

  • Argo version:
/tools/argo/argov2.10.0-rc4 version
argo: v2.10.0-rc4+8d6dae6.dirty
  BuildDate: 2020-07-28T22:58:49Z
  GitCommit: 8d6dae6128074445d9bd0222c449643053568db8
  GitTreeState: dirty
  GitTag: v2.10.0-rc4
  GoVersion: go1.13.4
  Compiler: gc
  Platform: linux/amd64
  • Kubernetes version :
clientVersion:
  buildDate: "2020-07-16T14:19:25Z"
  compiler: gc
  gitCommit: dff82dc0de47299ab66c83c626e08b245ab19037
  gitTreeState: clean
  gitVersion: v1.18.6
  goVersion: go1.13.13
  major: "1"
  minor: "18"
  platform: linux/amd64
serverVersion:
  buildDate: "2020-04-30T20:19:45Z"
  compiler: gc
  gitCommit: 52c56ce7a8272c798dbc29846288d7cd9fbae032
  gitTreeState: clean
  gitVersion: v1.18.2
  goVersion: go1.13.9
  major: "1"
  minor: "18"
  platform: linux/amd64

Other debugging information (if applicable):

  • workflow result:
DEBU[0000] CLI version                                   version="{v2.10.0-rc4+8d6dae6.dirty 2020-07-28T22:58:49Z 8d6dae6128074445d9bd0222c449643053568db8 v2.10.0-rc4 dirty go1.13.4 gc linux/amd64}"
DEBU[0000] Client options                                opts="{{ false false}  0x1708120 <nil> 0x1708170}"
Name:                nested-test-v7v4d
Namespace:           default
ServiceAccount:      default
Status:              Succeeded
Conditions:          
 Completed           True
Created:             Fri Jul 31 19:48:27 +0100 (15 minutes ago)
Started:             Fri Jul 31 19:48:27 +0100 (15 minutes ago)
Finished:            Fri Jul 31 19:48:51 +0100 (15 minutes ago)
Duration:            24 seconds
ResourcesDuration:   4s*(1 cpu),4s*(100Mi memory)

STEP                                       TEMPLATE  PODNAME                       DURATION  MESSAGE
 ✔ nested-test-v7v4d                       main                                                
 └---✔ echoitems(0:nested:map[B:2 "foo"])  echo      nested-test-v7v4d-2387945936  22s
  • workflow-controller logs:
time="2020-07-31T18:48:27Z" level=info msg="Processing workflow" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="Updated phase  -> Running" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="Steps node nested-test-v7v4d initialized Running" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="StepGroup node nested-test-v7v4d-1392141231 initialized Running" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="Pod node nested-test-v7v4d-2387945936 initialized Pending" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="Created pod: nested-test-v7v4d[0].echoitems(0:nested:map[B:2 \"foo\"]) (nested-test-v7v4d-2387945936)" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="Workflow step group node nested-test-v7v4d-1392141231 not yet completed" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="Workflow update successful" namespace=default phase=Running resourceVersion=2562 workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="Processing workflow" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="Updating node nested-test-v7v4d-2387945936 message: ContainerCreating"
time="2020-07-31T18:48:27Z" level=info msg="Skipped pod nested-test-v7v4d[0].echoitems(0:nested:map[B:2 \"foo\"]) (nested-test-v7v4d-2387945936) creation: already exists" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="Workflow step group node nested-test-v7v4d-1392141231 not yet completed" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="Workflow update successful" namespace=default phase=Running resourceVersion=2564 workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="Processing workflow" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="Skipped pod nested-test-v7v4d[0].echoitems(0:nested:map[B:2 \"foo\"]) (nested-test-v7v4d-2387945936) creation: already exists" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:27Z" level=info msg="Workflow step group node nested-test-v7v4d-1392141231 not yet completed" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:28Z" level=info msg="Processing workflow" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:28Z" level=info msg="Skipped pod nested-test-v7v4d[0].echoitems(0:nested:map[B:2 \"foo\"]) (nested-test-v7v4d-2387945936) creation: already exists" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:28Z" level=info msg="Workflow step group node nested-test-v7v4d-1392141231 not yet completed" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:49Z" level=info msg="Processing workflow" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:49Z" level=info msg="Updating node nested-test-v7v4d-2387945936 status Pending -> Running"
time="2020-07-31T18:48:49Z" level=info msg="Workflow step group node nested-test-v7v4d-1392141231 not yet completed" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:49Z" level=info msg="Workflow update successful" namespace=default phase=Running resourceVersion=2639 workflow=nested-test-v7v4d
time="2020-07-31T18:48:49Z" level=info msg="Processing workflow" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:49Z" level=info msg="insignificant pod change" key=default/nested-test-v7v4d-2387945936
time="2020-07-31T18:48:49Z" level=info msg="Setting node nested-test-v7v4d-2387945936 outputs"
time="2020-07-31T18:48:49Z" level=info msg="Workflow step group node nested-test-v7v4d-1392141231 not yet completed" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:49Z" level=info msg="Workflow update successful" namespace=default phase=Running resourceVersion=2641 workflow=nested-test-v7v4d
time="2020-07-31T18:48:49Z" level=info msg="Processing workflow" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:49Z" level=info msg="Workflow step group node nested-test-v7v4d-1392141231 not yet completed" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="Processing workflow" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="Updating node nested-test-v7v4d-2387945936 status Running -> Succeeded"
time="2020-07-31T18:48:51Z" level=info msg="Step group node &NodeStatus{ID:nested-test-v7v4d-1392141231,Name:nested-test-v7v4d[0],DisplayName:[0],Type:StepGroup,TemplateName:main,TemplateRef:nil,Phase:Running,BoundaryID:nested-test-v7v4d,Message:,StartedAt:2020-07-31 18:48:27 +0000 UTC,FinishedAt:0001-01-01 00:00:00 +0000 UTC,PodIP:,Daemoned:nil,Inputs:nil,Outputs:nil,Children:[nested-test-v7v4d-2387945936],OutboundNodes:[],StoredTemplateID:,WorkflowTemplateName:,TemplateScope:local/nested-test-v7v4d,ResourcesDuration:ResourcesDuration{},HostNodeName:,} successful" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="node nested-test-v7v4d-1392141231 phase Running -> Succeeded" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="node nested-test-v7v4d-1392141231 finished: 2020-07-31 18:48:51.830208255 +0000 UTC" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="Outbound nodes of nested-test-v7v4d-2387945936 is [nested-test-v7v4d-2387945936]" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="Outbound nodes of nested-test-v7v4d is [nested-test-v7v4d-2387945936]" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="node nested-test-v7v4d phase Running -> Succeeded" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="node nested-test-v7v4d finished: 2020-07-31 18:48:51.830410974 +0000 UTC" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="Checking daemoned children of nested-test-v7v4d" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="Updated phase Running -> Succeeded" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="Marking workflow completed" namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="Checking daemoned children of " namespace=default workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="Workflow update successful" namespace=default phase=Succeeded resourceVersion=2650 workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="nested-test-v7v4d released all acquired locks"
time="2020-07-31T18:48:51Z" level=info msg="Labeled pod default/nested-test-v7v4d-2387945936 completed"
time="2020-07-31T18:48:51Z" level=info msg="Workflow update successful" namespace=default phase=Succeeded resourceVersion=2650 workflow=nested-test-v7v4d
time="2020-07-31T18:48:51Z" level=info msg="Labeled pod default/nested-test-v7v4d-2387945936 completed"


Message from the maintainers:

If you are impacted by this bug please add a 👍 reaction to this issue! We often sort issues this way to know what to prioritize.

bug regression
Source
picture tanenbaum

All 10 comments

metadata:
  name: nested-test-dzzj8
  generateName: nested-test-
  namespace: argo
  selfLink: /apis/argoproj.io/v1alpha1/namespaces/argo/workflows/nested-test-dzzj8
  uid: fda9ecc9-1a7a-4e17-be3a-cfe09247ae7f
  resourceVersion: '61786'
  generation: 6
  creationTimestamp: '2020-07-31T19:14:57Z'
  labels:
    workflows.argoproj.io/completed: 'true'
    workflows.argoproj.io/creator: admin
    workflows.argoproj.io/phase: Succeeded
spec:
  templates:
    - name: main
      arguments: {}
      inputs:
        parameters:
          - name: things
            value: '[{"nested": {"B": "2 \"foo\""}}]'
      outputs: {}
      metadata: {}
      steps:
        - - name: echoitems
            template: echo
            arguments:
              parameters:
                - name: thing
                  value: '{{item.nested}}'
            withParam: '{{inputs.parameters.things}}'
    - name: echo
      arguments: {}
      inputs:
        parameters:
          - name: thing
      outputs: {}
      metadata: {}
      container:
        name: ''
        image: busybox
        command:
          - echo
        args:
          - '{{inputs.parameters.thing}}'
        resources: {}
  entrypoint: main
  arguments: {}
status:
  phase: Succeeded
  startedAt: '2020-07-31T19:14:57Z'
  finishedAt: '2020-07-31T19:15:06Z'
  nodes:
    nested-test-dzzj8:
      id: nested-test-dzzj8
      name: nested-test-dzzj8
      displayName: nested-test-dzzj8
      type: Steps
      templateName: main
      templateScope: local/nested-test-dzzj8
      phase: Succeeded
      startedAt: '2020-07-31T19:14:57Z'
      finishedAt: '2020-07-31T19:15:06Z'
      inputs:
        parameters:
          - name: things
            value: '[{"nested": {"B": "2 \"foo\""}}]'
      children:
        - nested-test-dzzj8-4277542052
      outboundNodes:
        - nested-test-dzzj8-3548477305
    nested-test-dzzj8-3548477305:
      id: nested-test-dzzj8-3548477305
      name: 'nested-test-dzzj8[0].echoitems(0:nested:map[B:2 "foo"])'
      displayName: 'echoitems(0:nested:map[B:2 "foo"])'
      type: Pod
      templateName: echo
      templateScope: local/nested-test-dzzj8
      phase: Succeeded
      boundaryID: nested-test-dzzj8
      startedAt: '2020-07-31T19:14:57Z'
      finishedAt: '2020-07-31T19:15:02Z'
      resourcesDuration:
        cpu: 4
        memory: 2
      inputs:
        parameters:
          - name: thing
            value: 'map[B:2 "foo"]'
      outputs:
        artifacts:
          - name: main-logs
            archiveLogs: true
            s3:
              endpoint: 'minio:9000'
              bucket: my-bucket
              insecure: true
              accessKeySecret:
                name: my-minio-cred
                key: accesskey
              secretKeySecret:
                name: my-minio-cred
                key: secretkey
              key: nested-test-dzzj8/nested-test-dzzj8-3548477305/main.log
        exitCode: '0'
      hostNodeName: k3d-k3s-default-server
    nested-test-dzzj8-4277542052:
      id: nested-test-dzzj8-4277542052
      name: 'nested-test-dzzj8[0]'
      displayName: '[0]'
      type: StepGroup
      templateName: main
      templateScope: local/nested-test-dzzj8
      phase: Succeeded
      boundaryID: nested-test-dzzj8
      startedAt: '2020-07-31T19:14:57Z'
      finishedAt: '2020-07-31T19:15:06Z'
      children:
        - nested-test-dzzj8-3548477305
  conditions:
    - type: Completed
      status: 'True'
  resourcesDuration:
    cpu: 4
    memory: 2
alexec picture alexec on 31 Jul 2020

@tanenbaum could you please add some detail on how you are impacted please?

alexec picture alexec on 3 Aug 2020

@tanenbaum could you please add some detail on how you are impacted please?

This would be helpful, the string you pointed out is only used as part of the generated task name, it should have no bearing on the rest of the Workflow execution.

simster7 picture simster7 on 3 Aug 2020
👍1

I think my title and initial bits are misleading. Not only is it rendered as a map[] in the task name, that's what is passed into the job too.

From the above logs:

 ./tools/argo/argov2.10.0-rc4 logs nested-test-v7v4d
nested-test-v7v4d-2387945936: 2020-07-31T18:48:48.492777953Z map[B:2 "foo"]

map[B:2 "foo"] is what gets logged in the echo template. It should be {"B":"2 \"foo\""} - the expected output works in 2.9.x but not in 2.10.x.

This breaks a few of my workflows where I have nested JSON maps inside lists that are enumerated via withParam.

tanenbaum picture tanenbaum on 3 Aug 2020

Let's try a more explicit example, where the template will parse the JSON before logging out:

kind: Workflow
metadata:
  generateName: nested-test-
spec:
  entrypoint: main

  templates:
  - name: main
    inputs:
      parameters:
      - name: things
        value: '[{"nested": {"B": "foo"}}, {"nested": {"B": "bar"}}]'
    steps:
    - - name: parseitems
        template: parseJSON
        arguments:
          parameters:
            - name: json
              value: "{{item.nested}}"
        withParam: "{{inputs.parameters.things}}"

  - name: parseJSON
    inputs:
      parameters:
        - name: json
    script:
      image: node:lts-alpine
      command: [node]
      source: |
        json = JSON.parse('{{inputs.parameters.json}}')
        console.log(JSON.stringify(json))

In 2.9.4 this works fine:

./tools/argo/argov2.9.4 get --loglevel debug nested-test-dcv69
DEBU[0000] CLI version                                   version="{v2.9.4 2020-07-24T21:18:51Z 20d2ace3d5344db68ce1bc2a250bbb1ba9862613 v2.9.4 clean go1.13 gc linux/amd64}"
DEBU[0000] Client options                                opts="{{ false false}  0x16764f0 0xc00004d630}"
Name:                nested-test-dcv69
Namespace:           default
ServiceAccount:      default
Status:              Succeeded
Conditions:          
 Completed           True
Created:             Mon Aug 03 18:48:36 +0100 (1 minute ago)
Started:             Mon Aug 03 18:48:36 +0100 (1 minute ago)
Finished:            Mon Aug 03 18:48:49 +0100 (1 minute ago)
Duration:            13 seconds
ResourcesDuration:   22s*(1 cpu),22s*(100Mi memory)

STEP                                     TEMPLATE   PODNAME                       DURATION  MESSAGE
 ✔ nested-test-dcv69                     main                                                 
 └-·-✔ parseitems(0:nested:{"B":"foo"})  parseJSON  nested-test-dcv69-888622109   11s         
   └-✔ parseitems(1:nested:{"B":"bar"})  parseJSON  nested-test-dcv69-2692141545  11s

In 2.10.0-rc4 the %v formatted string is passed instead:

./tools/argo/argov2.10.0-rc4 submit nested-test.yaml --watch --log
Name:                nested-test-z5j2r
Namespace:           default
ServiceAccount:      default
Status:              Pending
Created:             Mon Aug 03 18:45:43 +0100 (now)
nested-test-z5j2r-923915964: 2020-08-03T17:45:52.456098631Z undefined:1
nested-test-z5j2r-923915964: 2020-08-03T17:45:52.456121353Z map[B:bar]
nested-test-z5j2r-923915964: 2020-08-03T17:45:52.456125527Z ^
nested-test-z5j2r-923915964: 2020-08-03T17:45:52.456128705Z 
nested-test-z5j2r-923915964: 2020-08-03T17:45:52.456131804Z SyntaxError: Unexpected token m in JSON at position 0
nested-test-z5j2r-923915964: 2020-08-03T17:45:52.456134838Z     at JSON.parse (<anonymous>)
nested-test-z5j2r-923915964: 2020-08-03T17:45:52.456137853Z     at Object.<anonymous> (/argo/staging/script:1:13)
Name:                nested-test-z5j2r
Namespace:           default
ServiceAccount:      default
Status:              Failed
Message:             child 'nested-test-z5j2r-4052524676' failed
Conditions:          
 Completed           True
Created:             Mon Aug 03 18:45:43 +0100 (12 seconds ago)
Started:             Mon Aug 03 18:45:43 +0100 (12 seconds ago)
Finished:            Mon Aug 03 18:45:55 +0100 (now)
Duration:            12 seconds
ResourcesDuration:   19s*(1 cpu),19s*(100Mi memory)

STEP                                    TEMPLATE   PODNAME                       DURATION  MESSAGE
 ✖ nested-test-z5j2r                    main                                               child 'nested-test-z5j2r-4052524676' failed  
 └-·-✖ parseitems(0:nested:map[B:foo])  parseJSON  nested-test-z5j2r-4052524676  11s       failed with exit code 1                      
   └-✖ parseitems(1:nested:map[B:bar])  parseJSON  nested-test-z5j2r-923915964   10s       failed with exit code 1
tanenbaum picture tanenbaum on 3 Aug 2020

Looking into this

simster7 picture simster7 on 3 Aug 2020
👍1

@tanenbaum I see what the issue is here. The whole variable is getting mapped to a Go value, not just the name of the task. This is certainly a bug, thank you for reporting. @alexec may I fix this?

simster7 picture simster7 on 3 Aug 2020

@simster7 I broke it, so I'd like to fix it (broke in #3290). I think I've identified the area of code that is the problem.

alexec picture alexec on 3 Aug 2020

Ah - just changed in #3659 .

alexec picture alexec on 3 Aug 2020

Fixed and available in v2.10.0-rc5.

alexec picture alexec on 4 Aug 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

kounoike picture kounoike  ·  4Comments
hden picture hden  ·  3Comments
CermakM picture CermakM  ·  3Comments
vicaire picture vicaire  ·  4Comments
jessesuen picture jessesuen  ·  4Comments