Idempotence tests incorrectly succeed when Ansible callback plugin is not default

[chrwang]

Prerequisites

• This was not already reported in the past (duplicate check)
• It does reproduce it with code from main branch (latest unreleased version)
• I include a minimal example for reproducing the bug
• The bug is not trivial, as for those a direct pull-request is preferred
• Running pip check does not report any conflicts
• I was able to reproduce the issue on a different machine
• The issue is not specific to any driver other than 'default' one

Environment

❯ molecule --version
molecule 6.0.2 using python 3.11
    ansible:2.15.4
    azure:23.5.0 from molecule_plugins
    containers:23.5.0 from molecule_plugins requiring collections: ansible.posix>=1.3.0 community.docker>=1.9.1 containers.podman>=1.8.1
    default:6.0.2 from molecule
    docker:23.5.0 from molecule_plugins requiring collections: community.docker>=3.0.2 ansible.posix>=1.4.0
    ec2:23.5.0 from molecule_plugins
    gce:23.5.0 from molecule_plugins requiring collections: google.cloud>=1.0.2 community.crypto>=1.8.0
    podman:23.5.0 from molecule_plugins requiring collections: containers.podman>=1.7.0 ansible.posix>=1.3.0
    vagrant:23.5.0 from molecule_plugins

Linux 4.18.0-348.23.1.el8_5.x86_64 #1 SMP Fri Jul 22 09:30:58 CDT 2022 x86_64 x86_64 x86_64 GNU/Linux

❯ python3 --version
Python 3.11.2

What happened

What happened?

We have CI that uses molecule to automatically test pull requests to our internal company repositories of Ansible roles. We discovered that idempotent tests were showing as passed in CI, but when locally they would fail. This was narrowed down to the difference being that locally, we use the default ansible.builtin.default callback, while we use ansible.builtin.junit callback in CI.

What did we expect to happen?

We expected tests to fail in CI as they were locally.

Root cause?

I believe this is the root cause. In idempotence.py, we have the following function:

molecule/src/molecule/command/idempotence.py

Lines 62 to 78 in 01631c7

	def _is_idempotent(self, output):
	"""Parse the output of the provisioning for changed and returns a bool.
	:param output: A string containing the output of the ansible run.
	:return: bool
	"""
	# Remove blank lines to make regex matches easier
	output = re.sub(r"\n\s*\n*", "\n", output)
	# Look for any non-zero changed lines
	changed = re.search(r"(changed=[1-9][0-9]*)", output)
	if changed:
	# Not idempotent
	return False
	return True

Specifically, the following line:

changed = re.search(r"(changed=[1-9][0-9]*)", output)

molecule is detecting the changed_when status from the ansible output by specifically looking for the changed=[some_number] format that exists in the default callback. However, with other callback plugins Ansible doesn't print those lines and instead uses other formats. For example, in ansible.builtin.json we instead get:

   "stats": {
        "localhost": {
            "changed": 2,
            "failures": 0,
            "ignored": 0,
            "ok": 4,
            "rescued": 0,
            "skipped": 2,
            "unreachable": 0
        }
    }

I'm happy to put in PRs for this, but I'd like to hear what the maintainers think about how to restructure this function. Writing a regex per parser seems highly undesirable and a pain to maintain. String parsing doesn't seem like the most ideal way to go about this, but because there's so many different callback plugin types that might be unavoidable.

Reproducing example

Gist here: https://gist.github.com/chrwang/bad5de8f073bd6a8cedc1332f2737768

Directory structure:

❯ ll
total 12
-rw-r--r-- 1 chwang swdev 285 Oct  5 09:26 converge.yml
-rw-r--r-- 1 chwang swdev 153 Oct  5 09:24 molecule.yml
-rw-r--r-- 1 chwang swdev 167 Oct  5 09:25 verify.yml
❯ cd ../
❯ ll
total 0
drwxr-xr-x 2 chwang swdev 64 Oct  5 09:22 idempotence_test
❯ cd ../
❯ ll
total 0
drwxr-xr-x 3 chwang swdev 30 Oct  5 09:27 molecule
❯ pwd
/tmp/molecule_test

Command run for success:

❯ PY_COLORS=1 molecule test -s idempotence_test

Command(s) run for failure:

❯ export ANSIBLE_STDOUT_CALLBACK=ansible.builtin.junit
❯ PY_COLORS=1 molecule test -s idempotence_test

[chriscroome]

Out of interest does setting ANSIBLE_CALLBACK_RESULT_FORMAT have an effect on this? I find the output more readable when it is set to yaml rather than the default which I guess is json.

[chrwang]

Out of interest does setting ANSIBLE_CALLBACK_RESULT_FORMAT have an effect on this? I find the output more readable when it is set to yaml rather than the default which I guess is json.

It does not in this case, as the format of the ok/changed/failed lines in the play recap seem to be independent of ANSIBLE_CALLBACK_RESULT_FORMAT and rather depends on the callback plugin itself instead. i.e. in both json and yaml modes with the default callback plugin I see the following format printed for the recap:

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

I think that env var controls output format from tasks themselves rather than the recap, and as molecule is looking for the lines from the recap, whatever gets printed by the task itself shouldn't matter (unless you happen to print changed=2 exactly in a debug message or something...)

[ssbarnea]

I PR would be welcomed here. The right way to address this should be to enforce use of a specific callback (included in core), so we can analyze the output.

[chrwang]

RFC: Use the ansible.posix.json callback? That seems the most easily parseable / standard one to use.