[jitinp7]

Summary

AnsibleHelper.run() reads the otopi callback file, sleeps 0.1s, and then checks whether ansible-playbook has exited. If the process exits during that sleep, its last callback line is still unread. That line is the RESULT object from v2_playbook_on_stats, and _process_output() replaces _cb_results with it.

The return code was stored before that drain, so RESULT removed ansible-playbook_rc. misc.py Closing up then raised KeyError, and deploy cleanup deleted the engine VM even though the playbook exited 0.

Store the return code after the leftover callback lines are consumed.

Reproduction

Seen twice during hosted-engine --deploy with the packaged ovirt-hosted-engine-setup-2.7.2-1.el9.noarch on Oracle Linux 9.8, kernel 5.14.0-687.5.3.el9_8. rpm -V showed the installed ansible_utils.py, callback plugin, and misc.py were unmodified. The same sequence is in current master.

It is timing-dependent. One deploy ran four playbooks. Three kept the return code. One lost it:

• ansible-playbook rc: 0, then PLAY RECAP failed: 0 — key kept
• PLAY RECAP failed: 0, then ansible-playbook rc: 0 — key kept
• ansible-playbook rc: 0, then PLAY RECAP ok: 214 changed: 72 failed: 0 — RESULT replaced the dictionary — KeyError: 'ansible-playbook_rc'
• cleanup playbook — key kept

An earlier deploy showed the same pair one millisecond apart: "ansible-playbook rc: 0", then KeyError in Closing up. The result dictionary still had the playbook facts (otopi_localvm_dir, appliance size, admin username) and no ansible-playbook_rc. The same KeyError was reported on the users list in April 2023: https://lists.ovirt.org/archives/list/users@ovirt.org/thread/QO2Z6OJTERAJCCLYHC6CLRQKVUUJRG2C/

Log lines to look for, in order:

ansible-playbook rc: 0
PLAY RECAP ... ok: ... failed: 0
Failed to execute stage 'Closing up': 'ansible-playbook_rc'

Testing

tests/ansible_utils_test.py drives AnsibleHelper.run() with a fake playbook.

• test_result_already_read_keeps_return_code writes the RESULT line before the process exits. This passes on the old and new code.
• test_result_written_during_sleep_keeps_return_code writes the RESULT line during the 0.1s sleep. On the old code this raises KeyError: 'ansible-playbook_rc'. With this change it returns ansible-playbook_rc == 0 and keeps otopi_localvm_dir.

hosted-engine --deploy was then run to completion multiple times with this ordering. Each run finished and the engine VM stayed in place. Those runs show a normal deploy still completes. The late-RESULT unit test is what forces the 0.1s window, which a successful deploy can miss.

[peter-boden]

A few comments + I would put the fix and the accompanying tests in the same commit.

[peter-boden]

This adds partial-line buffering, a half-read line from the main loop is now joined with the rest instead of being parsed as two broken fragments?
It isn't needed for the rc fix, it's not mentioned in the commit message, and it has no test. I would either revert and just move the rc assignment, or add a test(s) for it and mention it in the message.

[peter-boden]

This test also passes on the pre-fix code, so it doesn't really test anything. The RESULT is written before the process starts, and the main loop reads it before poll() reports the exit. The drain loop never sees it. Only test_result_written_during_sleep_keeps_return_code fails without the fix (I checked: KeyError: 'ansible-playbook_rc'). Please drop this test, or change it so the RESULT is written after the last poll, so it exercises the drain.

[jitinp7]

A few comments + I would put the fix and the accompanying tests in the same commit.

Thanks. I'll put the fix and the test in one commit, keep the existing drain and only move the ansible-playbook_rc assignment to after it, and drop test_result_already_read_keeps_return_code. The late RESULT test is the one that fails on the old code.