Garbled output from nested playbooks

[jbowman-evh]

Running a playbook that calls another playbook produces garbled output on stdout. I encountered this first running Molecule inside an AAP execution environment. I thought it was Molecule related until I found this awx issue (https://github.com/ansible/awx/issues/5380). It seems to be related to ansible-runner instead and is reproduceable outside AAP/awx.

Running nested playbooks is weird, but I don't really have a choice when running Molecule as a command task.

project/debug.yml

---

- hosts: localhost
  gather_facts: false

  vars:
    msg: 'hello world'

  tasks:
    - debug: var=msg

project/nested_debug.yml

---

- hosts: localhost
  gather_facts: false

  vars:
    msg: 'hello'

  tasks:
    - command: 'ansible-playbook debug.yml'
      register: output

    - debug:
        var: output.stdout_lines

Output

$ ansible-runner run project -p nested_debug.yml
[WARNING]: provided hosts list is empty, only localhost is available. Note that
the implicit localhost does not match 'all'

PLAY [localhost] ***************************************************************

TASK [command] *****************************************************************
changed: [localhost]

TASK [debug] *******************************************************************
ok: [localhost] => {
    "output.stdout_lines": [
        "\u001b[KeyJ1dWlkIjogImI1MmNjODRmLWIzODItNDJhYi04NTFmLTkwYzcyNGQyZDljYiJ9\u001b[64D\u001b[K\u001b[Ke30=\u001b[4D\u001b[K\u001b[KeyJ1dWlkIjogIjAwMGQzYTEyLTE4MGYtODczNy1hZWM0LTAwMDAwMDAwMDAwNSJ9\u001b[64D\u001b[K",
        "PLAY [localhost] ***************************************************************",
        "\u001b[Ke30=\u001b[4D\u001b[K\u001b[KeyJ1dWlkIjogIjAwMGQzYTEyLTE4MGYtODczNy1hZWM0LTAwMDAwMDAwMDAwNyJ9\u001b[64D\u001b[K",
        "TASK [debug] *******************************************************************",
        "\u001b[Ke30=\u001b[4D\u001b[K\u001b[KeyJ1dWlkIjogIjMyOWJiNzZkLWJiMDEtNDY4NS1hYTg3LTk1NTZkNjU4NjQ1ZCJ9\u001b[64D\u001b[K\u001b[Ke30=\u001b[4D\u001b[K\u001b[KeyJ1dWlkIjogIjhjZWI1ZTdhLTA4YmMtNDJlMy1hYWVhLTkyZmQyNDQzMjM2ZiJ9\u001b[64D\u001b[Kok: [localhost] => {}",
        "",
        "MSG:",
        "",
        "hello world",
        "\u001b[Ke30=\u001b[4D\u001b[K\u001b[KeyJ1dWlkIjogImVjZTAyMDFhLWMwNzEtNGZkZC04ZmU3LWJkNDAxODlhNGNiYyJ9\u001b[64D\u001b[K",
        "PLAY RECAP *********************************************************************",
        "localhost                  : ok=1    changed=0    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0   ",
        "",
        "\u001b[Ke30=\u001b[4D\u001b[K"
    ]
}

PLAY RECAP *********************************************************************
localhost                  : ok=2    changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0

version

$ ansible-runner --version
2.3.4

[jbowman-evh]

It appears to be dumping out base64 encoded uuids. For example, The first line (excluding \u001b[K) is "eyJ1dWlkIjogImI1MmNjODRmLWIzODItNDJhYi04NTFmLTkwYzcyNGQyZDljYiJ9". Decoded, that is "{"uuid": "b52cc84f-b382-42ab-851f-90c724d2d9cb"}". Why is it getting dumped out? More importantly, is there anything I can do to prevent it?

[sivel]

We've been calling this output "display steganography" required for certain functionalities in AWX, and generally you would never notice it, except that running ansible-playbook via the command module, it will capture that. It happens in this case, because ansible-runner sets a ANSIBLE_STDOUT_CALLBACK, and is being inherited by the subprocess/fork to execute the command module, and therefore the nested ansible-playbook.

This should be avoidable, by explicitly setting the ANSIBLE_STDOUT_CALLBACK env var in your playbook, to the default, or whatever other callback you may want to use:

    - command: 'ansible-playbook debug.yml'
      register: output
      environment:
        ANSIBLE_STDOUT_CALLBACK: default

[bcoca]

or better yet https://docs.ansible.com/ansible/latest/collections/ansible/posix/json_callback.html , then you can 'register/parse' the output almost as if it were a module

[jbowman-evh]

Thanks for the suggestions. Unfortunately, setting the stdout callback to default didn't alter the output.

$ cat project/nested_debug.yml
---

- hosts: localhost
  gather_facts: false

  vars:
    msg: 'hello'

  tasks:
    - command: 'ansible-playbook debug.yml'
      register: output
      environment:
        ANSIBLE_STDOUT_CALLBACK: default

    - debug:
        var: output.stdout_lines
$
$ ansible-runner run project -p nested_debug.yml
[WARNING]: provided hosts list is empty, only localhost is available. Note that
the implicit localhost does not match 'all'

PLAY [localhost] ***************************************************************

TASK [command] *****************************************************************
changed: [localhost]

TASK [debug] *******************************************************************
ok: [localhost] => {
    "output.stdout_lines": [
        "\u001b[KeyJ1dWlkIjogIjZhYmQ1ODQ2LWNiYzgtNDBjMi1hNzM0LTRhMjRkYjkyNTY5YiJ9\u001b[64D\u001b[K",
        "PLAY [localhost] ***************************************************************",
        "\u001b[Ke30=\u001b[4D\u001b[K\u001b[KeyJ1dWlkIjogIjhjZTIzY2FkLWRjMmUtNDFlOS05OTg1LTQ2NDIyMjk5Njc1MSJ9\u001b[64D\u001b[K",
        "TASK [debug] *******************************************************************",
        "\u001b[Ke30=\u001b[4D\u001b[K\u001b[KeyJ1dWlkIjogIjJkZDdiOWVhLWNhMDgtNDc4ZS1iMGY0LWEzYjIzNDNmZWM0NSJ9\u001b[64D\u001b[Kok: [localhost] => {",
        "    \"msg\": \"hello world\"",
        "}",
        "\u001b[Ke30=\u001b[4D\u001b[K\u001b[KeyJ1dWlkIjogImUwODM2MGEyLTg3NmEtNDg4Yi04YTkxLTc2NWRiY2RkMGJiNyJ9\u001b[64D\u001b[K",
        "PLAY RECAP *********************************************************************",
        "\u001b[Ke30=\u001b[4D\u001b[K\u001b[KeyJ1dWlkIjogIjAxZDhjODBkLWNlNzktNDFkZS1hOWI5LWI3NTUzNGI4NmVhOCJ9\u001b[64D\u001b[Klocalhost                  : ok=1    changed=0    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0   ",
        "\u001b[Ke30=\u001b[4D\u001b[K\u001b[KeyJ1dWlkIjogImNkMjZlZDlmLTU5NzUtNDVkZC04OTVkLTYwZWJiOWFkMDQ2YSJ9\u001b[64D\u001b[K",
        "\u001b[Ke30=\u001b[4D\u001b[K"
    ]
}

PLAY RECAP *********************************************************************
localhost                  : ok=2    changed=1    unreachable=0    failed=0    skipped=0    rescued=0    ignored=0

[sivel]

Sorry, looks like you also need to set something like:

      environment:
        ANSIBLE_STDOUT_CALLBACK: default
        ANSIBLE_CALLBACK_PLUGINS: ''

That resolves it for me.

[jbowman-evh]

That works. Thank you so much! I've been working on this elaborate plan to run molecule testing inside my execution environments and the "display steganography" was killing the plan.