Fix the issue of no 'failed' field in failed ansible module result

[wangxin]

Description of PR

Summary:
Fixes #1941

Type of change

• Bug fix
• Testbed and Framework(new/improvement)
• Test case(new/improvement)

Approach

What is the motivation for this PR?

For failed ansible modules, ansible removes fields including {'failed': True} in the result dict before calling callback function of plugins like pytest_ansible. Because pytest_ansible uses a same callback function for succeeded and failed ansible modules, no field like 'failed' is added back to failed ansible module results by pytest_ansible. If we call res.is_failed(), it will only return True if the ansible module result has non-zero rc field.

For more details, please refer to:

• The is_failed property of failed result of some ansible modules is False ansible/pytest-ansible#47
• localhost wait_for does not return a failure nor exception #1941 (comment)

Related PR:

• Workaround for no Exception issue for some failed ansible modules #1786

How did you do it?

The list of keys to be removed from failed ansible module results is pre-defined in module variable ansible.executor.task_result._IGNORE. This change override this variable to exclude the failed key.

How did you verify/test it?

Prepared a test script:

import logging
import json

logger = logging.getLogger(__name__)


def test_wait1(localhost, duthost, ptfhost):

    res = localhost.wait_for(host='10.250.0.101', port=22, state='stopped', timeout=1)
    logger.info(json.dumps(res, indent=2))

Host 10.250.0.101 is the vlab-01 vs sonic host. It is up and running. Without this fix, the wait_for call will pass. With this fix, it will fail as expected. Full log of running this script:

johnar@4c1f7b289839:~/code/sonic-mgmt/tests$ pytest --inventory veos.vtb --host-pattern vlab-01  --testbed vms-kvm-t0 --testbed_file vtestbed.csv --showlocals --show-capture no --assert plain --log-cli-level debug test_wait.py --skip_sanity --disable_loganalyzer
=========================================================================================================== test session starts ===========================================================================================================
platform linux2 -- Python 2.7.12, pytest-4.6.5, py-1.8.1, pluggy-0.13.1

---------------------------------------------------------------------------------------------------------- live log sessionstart ----------------------------------------------------------------------------------------------------------
10:08:47 DEBUG plugin.py:pytest_report_header:168: pytest_report_header() called
----------------------------------------------------------------------------------------------------------- live log collection -----------------------------------------------------------------------------------------------------------
10:08:47 DEBUG plugin.py:pytest_generate_tests:123: pytest_generate_tests() called
10:08:47 DEBUG plugin.py:pytest_collection_modifyitems:173: pytest_collection_modifyitems() called
10:08:47 DEBUG plugin.py:pytest_collection_modifyitems:174: items: [<Function test_wait1>]

------------------------------------------------------------------------------------------------------------- live log setup --------------------------------------------------------------------------------------------------------------
10:08:47 INFO __init__.py:set_default:14: Completeness level not set during test execution. Setting to default level: CompletenessLevel.basic
10:08:47 INFO __init__.py:check_test_completeness:128: Test has no defined levels. Continue without test completeness checks
10:08:47 DEBUG devices.py:_run:69: /var/johnar/code/sonic-mgmt/tests/common/devices.py::_get_platform_info#256: [vlab-01] AnsibleModule::command, args=["show platform summary"], kwargs={}
10:08:48 DEBUG registry.py:register_crypt_handler:294: registered 'md5_crypt' handler: <class 'passlib.handlers.md5_crypt.md5_crypt'>
10:08:49 DEBUG devices.py:_run:83: /var/johnar/code/sonic-mgmt/tests/common/devices.py::_get_platform_info#256: [vlab-01] AnsibleModule::command Result => {"stderr_lines": [], "cmd": ["show", "platform", "summary"], "end": "2020-08-07 10:08:33.480523", "_ansible_no_log": false, "stdout": "Platform: x86_64-kvm_x86_64-r0\nHwSKU: Force10-S6000\nASIC: vs", "changed": true, "rc": 0, "start": "2020-08-07 10:08:32.692223", "failed": false, "stderr": "", "delta": "0:00:00.788300", "invocation": {"module_args": {"warn": true, "executable": null, "_uses_shell": false, "strip_empty_ends": true, "_raw_params": "show platform summary", "removes": null, "argv": null, "creates": null, "chdir": null, "stdin_add_newline": true, "stdin": null}}, "stdout_lines": ["Platform: x86_64-kvm_x86_64-r0", "HwSKU: Force10-S6000", "ASIC: vs"], "ansible_facts": {"discovered_interpreter_python": "/usr/bin/python"}, "warnings": ["Platform linux on host vlab-01 is using the discovered Python interpreter at /usr/bin/python, but future installation of another Python interpreter could change this. See https://docs.ansible.com/ansible/2.8/reference_appendices/interpreter_discovery.html for more information."]}
10:08:49 DEBUG devices.py:_run:69: /var/johnar/code/sonic-mgmt/tests/common/devices.py::_get_asic_count#219: [vlab-01] AnsibleModule::shell, args=["cat /usr/share/sonic/device/x86_64-kvm_x86_64-r0/asic.conf"], kwargs={}
10:08:50 DEBUG devices.py:_run:83: /var/johnar/code/sonic-mgmt/tests/common/devices.py::_get_asic_count#219: [vlab-01] AnsibleModule::shell Result => {"stderr_lines": [], "cmd": "cat /usr/share/sonic/device/x86_64-kvm_x86_64-r0/asic.conf", "end": "2020-08-07 10:08:33.951074", "_ansible_no_log": false, "stdout": "NUM_ASIC=1", "changed": true, "rc": 0, "start": "2020-08-07 10:08:33.943587", "stderr": "", "delta": "0:00:00.007487", "invocation": {"module_args": {"warn": true, "executable": null, "_uses_shell": true, "strip_empty_ends": true, "_raw_params": "cat /usr/share/sonic/device/x86_64-kvm_x86_64-r0/asic.conf", "removes": null, "argv": null, "creates": null, "chdir": null, "stdin_add_newline": true, "stdin": null}}, "stdout_lines": ["NUM_ASIC=1"], "failed": false}
10:08:50 DEBUG devices.py:_get_asic_count:220: [u'NUM_ASIC=1']
10:08:50 DEBUG devices.py:_get_asic_count:228: num_asic = 1
10:08:50 DEBUG devices.py:_gather_facts:209: Gathered SonicHost facts: {"platform": "x86_64-kvm_x86_64-r0", "hwsku": "Force10-S6000", "asic_type": "vs", "num_asic": 1}
10:08:50 DEBUG devices.py:_run:69: /var/johnar/code/sonic-mgmt/tests/common/devices.py::_get_os_version#272: [vlab-01] AnsibleModule::command, args=["sonic-cfggen -y /etc/sonic/sonic_version.yml -v build_version"], kwargs={}
10:08:51 DEBUG devices.py:_run:83: /var/johnar/code/sonic-mgmt/tests/common/devices.py::_get_os_version#272: [vlab-01] AnsibleModule::command Result => {"stderr_lines": [], "cmd": ["sonic-cfggen", "-y", "/etc/sonic/sonic_version.yml", "-v", "build_version"], "end": "2020-08-07 10:08:34.784111", "_ansible_no_log": false, "stdout": "master.388-211d1e7e", "changed": true, "rc": 0, "start": "2020-08-07 10:08:34.351304", "stderr": "", "delta": "0:00:00.432807", "invocation": {"module_args": {"warn": true, "executable": null, "_uses_shell": false, "strip_empty_ends": true, "_raw_params": "sonic-cfggen -y /etc/sonic/sonic_version.yml -v build_version", "removes": null, "argv": null, "creates": null, "chdir": null, "stdin_add_newline": true, "stdin": null}}, "stdout_lines": ["master.388-211d1e7e"], "failed": false}
10:08:51 DEBUG devices.py:critical_services:191: ['swss', 'syncd', 'database', 'teamd', 'bgp', 'pmon', 'lldp', 'snmp']
10:08:51 DEBUG devices.py:critical_services:191: ['swss', 'syncd', 'database', 'teamd', 'bgp', 'pmon', 'lldp', 'snmp']
10:08:51 INFO conftest.py:creds:334: dut vlab-01 belongs to groups [u'lab', u'sonic', 'fanout']
10:08:51 INFO conftest.py:creds:345: skip empty var file ../ansible/group_vars/all/corefile_uploader.yml
10:08:51 INFO conftest.py:creds:345: skip empty var file ../ansible/group_vars/all/env.yml
10:08:51 INFO __init__.py:sanity_check:45: Start pre-test sanity check
10:08:51 INFO __init__.py:sanity_check:89: Sanity check settings: skip_sanity=True, check_items=set(['services', 'bgp', 'interfaces', 'processes', 'dbmemory']), allow_recover=False, recover_method=adaptive, post_check=False
10:08:51 INFO __init__.py:sanity_check:92: Skip sanity check according to command line argument or configuration of test script.
10:08:51 INFO __init__.py:loganalyzer:15: Log analyzer is disabled
-------------------------------------------------------------------------------------------------------------- live log call --------------------------------------------------------------------------------------------------------------
10:08:51 DEBUG devices.py:_run:69: /var/johnar/code/sonic-mgmt/tests/test_wait.py::test_wait1#9: [localhost] AnsibleModule::wait_for, args=[], kwargs={"host": "10.250.0.101", "port": 22, "timeout": 1, "state": "stopped"}
10:08:52 DEBUG devices.py:_run:83: /var/johnar/code/sonic-mgmt/tests/test_wait.py::test_wait1#9: [localhost] AnsibleModule::wait_for Result => {"failed": true, "_ansible_no_log": false, "invocation": {"module_args": {"active_connection_states": ["ESTABLISHED", "FIN_WAIT1", "FIN_WAIT2", "SYN_RECV", "SYN_SENT", "TIME_WAIT"], "host": "10.250.0.101", "connect_timeout": 5, "delay": 0, "search_regex": null, "state": "stopped", "sleep": 1, "timeout": 1, "exclude_hosts": null, "msg": null, "path": null, "port": 22}}, "msg": "Timeout when waiting for 10.250.0.101:22 to stop.", "changed": false, "elapsed": 1}
Loading callback plugin json of type stdout, v2.0 from /usr/local/lib/python2.7/dist-packages/ansible/plugins/callback/json.pyc
Loading callback plugin json of type stdout, v2.0 from /usr/local/lib/python2.7/dist-packages/ansible/plugins/callback/json.pyc
FAILED                                                                                                                                                                                                                              [100%]

================================================================================================================ FAILURES =================================================================================================================
_______________________________________________________________________________________________________________ test_wait1 ________________________________________________________________________________________________________________

localhost = <tests.common.devices.Localhost object at 0x7f4c340d4450>, duthost = <tests.common.devices.SonicHost object at 0x7f4c33f59710>, ptfhost = <tests.common.devices.PTFHost object at 0x7f4c33f59b10>

    def test_wait1(localhost, duthost, ptfhost):
    
>       res = localhost.wait_for(host='10.250.0.101', port=22, state='stopped', timeout=1)

duthost    = <tests.common.devices.SonicHost object at 0x7f4c33f59710>
localhost  = <tests.common.devices.Localhost object at 0x7f4c340d4450>
ptfhost    = <tests.common.devices.PTFHost object at 0x7f4c33f59b10>

test_wait.py:9: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <tests.common.devices.Localhost object at 0x7f4c340d4450>, module_args = (), complex_args = {'host': '10.250.0.101', 'port': 22, 'state': 'stopped', 'timeout': 1}, previous_frame = <frame object at 0x379ae40>
filename = '/var/johnar/code/sonic-mgmt/tests/test_wait.py', line_number = 9, function_name = 'test_wait1', lines = ["    res = localhost.wait_for(host='10.250.0.101', port=22, state='stopped', timeout=1)\n"], index = 0
module_ignore_errors = False, module_async = False

    def _run(self, *module_args, **complex_args):
    
        previous_frame = inspect.currentframe().f_back
        filename, line_number, function_name, lines, index = inspect.getframeinfo(previous_frame)
    
        logging.debug("{}::{}#{}: [{}] AnsibleModule::{}, args={}, kwargs={}"\
            .format(filename, function_name, line_number, self.hostname,
                    self.module_name, json.dumps(module_args), json.dumps(complex_args)))
    
        module_ignore_errors = complex_args.pop('module_ignore_errors', False)
        module_async = complex_args.pop('module_async', False)
    
        if module_async:
            def run_module(module_args, complex_args):
                return self.module(*module_args, **complex_args)[self.hostname]
            pool = ThreadPool()
            result = pool.apply_async(run_module, (module_args, complex_args))
            return pool, result
    
        res = self.module(*module_args, **complex_args)[self.hostname]
        logging.debug("{}::{}#{}: [{}] AnsibleModule::{} Result => {}"\
            .format(filename, function_name, line_number, self.hostname, self.module_name, json.dumps(res)))
    
        if (res.is_failed or 'exception' in res) and not module_ignore_errors:
>           raise RunAnsibleModuleFail("run module {} failed".format(self.module_name), res)
E           RunAnsibleModuleFail: run module wait_for failed, Ansible Results =>
E           {
E               "changed": false, 
E               "elapsed": 1, 
E               "failed": true, 
E               "invocation": {
E                   "module_args": {
E                       "active_connection_states": [
E                           "ESTABLISHED", 
E                           "FIN_WAIT1", 
E                           "FIN_WAIT2", 
E                           "SYN_RECV", 
E                           "SYN_SENT", 
E                           "TIME_WAIT"
E                       ], 
E                       "connect_timeout": 5, 
E                       "delay": 0, 
E                       "exclude_hosts": null, 
E                       "host": "10.250.0.101", 
E                       "msg": null, 
E                       "path": null, 
E                       "port": 22, 
E                       "search_regex": null, 
E                       "sleep": 1, 
E                       "state": "stopped", 
E                       "timeout": 1
E                   }
E               }, 
E               "msg": "Timeout when waiting for 10.250.0.101:22 to stop."
E           }

complex_args = {'host': '10.250.0.101', 'port': 22, 'state': 'stopped', 'timeout': 1}
filename   = '/var/johnar/code/sonic-mgmt/tests/test_wait.py'
function_name = 'test_wait1'
index      = 0
line_number = 9
lines      = ["    res = localhost.wait_for(host='10.250.0.101', port=22, state='stopped', timeout=1)\n"]
module_args = ()
module_async = False
module_ignore_errors = False
previous_frame = <frame object at 0x379ae40>
res        = {u'failed': True, '_ansible_no_log': False, u'invocation': {u'module_args': {u...ut when waiting for 10.250.0.101:22 to stop.', 'changed': False, u'elapsed': 1}
self       = <tests.common.devices.Localhost object at 0x7f4c340d4450>

common/devices.py:86: RunAnsibleModuleFail
======================================================================================================== 1 failed in 5.54 seconds =========================================================================================================
johnar@4c1f7b289839:~/code/sonic-mgmt/tests$ 

The failed ansible module has field {"failed": true} now.

Any platform specific information?

Supported testbed topology if it's a new test case?

Documentation