Provide more structured log output

[tyll]

Currently the logs are just big text files that do not make it obvious why a test failed or why there was an error. Ideally when a test fails, the name of the tests and the assertion would be properly shown and in case something regarding the infrastructure fails, it would show only the error (and maybe even try again).

[richm]

Can you give me an example of what you would like the output to look like? I'm not sure I understand.

[tyll]

This is an idea:

Testing /tmp/tmpzgmmyoh5/tests/tests_bridge.yml...SUCCESS
Testing /tmp/tmpzgmmyoh5/tests/tests_bridge_other_provider.yml...SUCCESS
Testing /tmp/tmpzgmmyoh5/tests/tests_default.yml...SUCCESS
Testing /tmp/tmpzgmmyoh5/tests/tests_default_other_provider.yml...SUCCESS
Testing /tmp/tmpzgmmyoh5/tests/tests_ethernet.yml...SUCCESS
Testing /tmp/tmpzgmmyoh5/tests/tests_ethernet_other_provider.yml...SUCCESS
Testing /tmp/tmpzgmmyoh5/tests/tests_helpers-and-asserts.yml...SUCCESS
Testing /tmp/tmpzgmmyoh5/tests/tests_states.yml...FAILURE

Failed task:
TASK [linux-system-roles.network : Configure networking connection profiles] ***
task path: /tmp/tmpzgmmyoh5/tests/roles/linux-system-roles.network/tasks/main.yml:50
 [WARNING]: [001] <error> #0, state:down persistent_state:absent, 'statebr':
Connection not found on system and 'type' not specified
fatal: [/cache/CentOS-7-x86_64-GenericCloud-1901.qcow2c]: FAILED! => {"changed": false, "msg": "error: Connection not found on system and 'type' not specified"}
	to retry, use: --limit @/tmp/tmpzgmmyoh5/tests/tests_states.retry

This is based on:
https://fedorapeople.org/groups/linuxsystemroles/logs/linux-system-roles-network-pull-linux-system-roles_network-118-2b0cd96-centos-7-20190904-174705/artifacts/test.log.html

Instead of having to dig through the big ansible.log file, it would be nice to get only the failure in the overwiew.

[tyll]

Here is an example from a current failure:

https://fedorapeople.org/groups/linuxsystemroles/logs/linux-system-roles-network-pull-linux-system-roles_network-200-2b7e16a-fedora-32-20200506-161452/artifacts/test.log.html

Use cached Fedora-Cloud-Base-32-1.6.x86_64.qcow2
+ git init --quiet /tmp/tmpj7fr713o
+ GIT_TERMINAL_PROMPT=0 git -C /tmp/tmpj7fr713o fetch --quiet --depth=1 https://github.com/linux-system-roles/network pull/200/head
+ git -C /tmp/tmpj7fr713o checkout --quiet FETCH_HEAD
Testing /tmp/tmpj7fr713o/tests/tests_802_1x_nm.yml...FAILURE

and finding the failed task in https://fedorapeople.org/groups/linuxsystemroles/logs/linux-system-roles-network-pull-linux-system-roles_network-200-2b7e16a-fedora-32-20200506-161452/artifacts/ansible.log is not so obvious and it also not clear what is going on here. I see

TASK [linux-system-roles.network : Check which services are running] ***********
task path: /tmp/tmpj7fr713o/tests/roles/linux-system-roles.network/tasks/main.yml:4
fatal: [/cache/Fedora-Cloud-Base-32-1.6.x86_64.qcow2]: FAILED! => {"censored": "the output has been hidden due to the fact that 'no_log: true' was specified for this result", "changed": false}

TASK [linux-system-roles.network : Check which services are running] ***********
task path: /tmp/tmpj7fr713o/tests/roles/linux-system-roles.network/tasks/main.yml:4
fatal: [/cache/Fedora-Cloud-Base-32-1.6.x86_64.qcow2]: FAILED! => {"censored": "the output has been hidden due to the fact that 'no_log: true' was specified for this result", "changed": false}
...ignoring

After spending some time thinking about this, I assume the second line comes from the rescue block but the log is not very helpful to make it easy to understand.

[richm]

Is it sufficient to do something like grep -F ']: FAILED! => {' /path/to/ansible.log to show the failures from the ansible log?

[tyll]

Some good output here would be:

Use cached Fedora-Cloud-Base-32-1.6.x86_64.qcow2
+ git init --quiet /tmp/tmpj7fr713o
+ GIT_TERMINAL_PROMPT=0 git -C /tmp/tmpj7fr713o fetch --quiet --depth=1 https://github.com/linux-system-roles/network pull/200/head
+ git -C /tmp/tmpj7fr713o checkout --quiet FETCH_HEAD
Testing /tmp/tmpj7fr713o/tests/tests_802_1x_nm.yml...FAILURE
TEST: 802.1x profile with private key password and ca cert: FAILED

Failed task:
TASK [linux-system-roles.network : Check which services are running] ***********
task path: /tmp/tmpj7fr713o/tests/roles/linux-system-roles.network/tasks/main.yml:4
fatal: [/cache/Fedora-Cloud-Base-32-1.6.x86_64.qcow2]: FAILED! => {"censored": "the output has been hidden due to the fact that 'no_log: true' was specified for this result", "changed": false}

Ideally, "Failed task" would also be a link to the correct line in the ansible.log file.

The problem with grep is that it would also need to ignore the ignored errors and ideally the cleanup steps. For this file it outputs:

grep -F ']: FAILED! => {' ansible.log 
fatal: [/cache/Fedora-Cloud-Base-32-1.6.x86_64.qcow2]: FAILED! => {"censored": "the output has been hidden due to the fact that 'no_log: true' was specified for this result", "changed": false}
fatal: [/cache/Fedora-Cloud-Base-32-1.6.x86_64.qcow2]: FAILED! => {"censored": "the output has been hidden due to the fact that 'no_log: true' was specified for this result", "changed": false}
fatal: [/cache/Fedora-Cloud-Base-32-1.6.x86_64.qcow2]: FAILED! => {"changed": false, "msg": "error: Connection not found on system and 'type' not specified"}

This might does not help much.

[seocam]

I'm not sure if this insights would help you but currently I'm working on something similar on ansible-freeipa. I've basically wrapped up each playbook execution in a test_method that could be discovered and executed by py.test.

The reason behind it was that pytest already provides formatting for output (and verbosity levels) and also provide a way to save test results in junit.xml files (what we use to display results in our jenkins).

pytest also allow us to run all or select some tests to be executed.

That's what the output currently looks like:

(ansible) scampos@cetus:~/src/ansible-freeipa (fix-test-entry-point *)$ IPA_SERVER_HOST=192.168.124.9 py.test -v -k hbac
============================================= test session starts =============================================

collected 37 items / 33 deselected / 4 selected                                                               

tests/test_playbook_runs.py::hbacsvc::test_hbacsvc PASSED                                               [ 25%]
tests/test_playbook_runs.py::hbacsvcgroup::test_hbacsvcgroup PASSED                                     [ 50%]
tests/test_playbook_runs.py::hbacrule::test_hbacrule FAILED                                             [ 75%]
tests/test_playbook_runs.py::hbacrule::test_hbacrule_categories PASSED                                  [100%]

================================================== FAILURES ===================================================
___________________________________________ hbacrule.test_hbacrule ____________________________________________

self = <test_playbook_runs.hbacrule testMethod=test_hbacrule>
test_path = '/home/scampos/src/ansible-freeipa/tests/hbacrule/test_hbacrule.yml'

    @pytest.mark.skipif(
        os.getenv("IPA_SERVER_HOST") is None,
        reason="Environment variable IPA_SERVER_HOST must be set",
    )
    @prepare_test(test_name, test_path)
    def method(self, test_path):
        result = run_playbook(test_path)
        errors = result.stderr.read()
>       assert result.returncode == 0, errors
E       AssertionError: b'[WARNING]: Module did not set no_log for update_password
E         fatal: [192.168.124.9]: FAILED! => {"changed": false, "msg": "dnsrecord_show failed: 168.124.9.: DNS zone not found"}'
E       assert 2 == 0
E         +2
E         -0

tests/test_playbook_runs.py:92: AssertionError
-------------------------------------------- Captured stdout call ---------------------------------------------

PLAY [Test hbacrule] ***********************************************************

TASK [Gathering Facts] *********************************************************
ok: [192.168.124.9]

TASK [Get Domain from server name] *********************************************
ok: [192.168.124.9]

TASK [Ensure test hosts are absent] ********************************************

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

=========================================== short test summary info ===========================================
FAILED tests/test_playbook_runs.py::hbacrule::test_hbacrule - AssertionError: b'[WARNING]: Module did not se...
============================ 1 failed, 3 passed, 33 deselected in 98.03s (0:01:38) ============================

[tyll]

Thx @seocam interesting idea - this seems to be implemented here: https://github.com/freeipa/ansible-freeipa/blob/master/tests/test_playbook_runs.py

[seocam]

Correct. There is a working in a branch integrating that with travis and containers as well.
That's how the output looks like on travis: https://travis-ci.com/github/seocam/ansible-freeipa/jobs/349689944

[tyll]

FYI: Just realized that normal ansible playbook output is easier to read (at least for me) since it contains colors. This is lost in the log files, making the experience worse for the CI than when running it locally.

[seocam]

If you are running on Travis, CircleCI or Azure I believe you still can see colors. The problem is that our CIs usually report results in text files.

We are about to add ansible-freeipa upstream tests to Azure:

That's what a CI run looks like: https://dev.azure.com/seocam/seocam-ansible-freeipa/_build/results?buildId=93&view=logs&j=0acb617c-a6cc-522f-5a7d-bb6fac943f3a&t=749d40db-ac6d-520b-64ee-b1d04780698c

Since pytest generates junit.xml the report is imported by azure and is displayed in this dashboard: https://dev.azure.com/seocam/seocam-ansible-freeipa/_build/results?buildId=93&view=ms.vss-test-web.build-test-results-tab

If you click in an individual test you can see it's results (basically the end of the ansible-playbook output): https://dev.azure.com/seocam/seocam-ansible-freeipa/_build/results?buildId=93&view=ms.vss-test-web.build-test-results-tab&runId=68&resultId=100014&paneView=debug

I'm considering converting the script we are using for colleting ansible playbook and wrapping in TestCases (this) to a pytest plugin.

[tyll]

How are you organizing your tests? Is it one playbook/test? Do you structure setup/assert/cleanup somehow? I took a quick look and couldn't find this structure. I am currently experimenting with a structure in https://github.com/tyll/network/blob/absent_down/tests/playbooks/tests_states.yml

This would also make it easier to move to one test/playbook or structure it better when calling with pytest. The setup/cleanup tasks could be a fixtures with yield in between and then the test/asserts the actual content of the test group the output better, too.

[richm]

@nhosoi ^^^

[seocam]

On ansible-freeipa we use tests/<test_group>/test_<somethig>.yml.

<test_group> is just a way to group similar tests. In my current script the name of the directory is used as the name of the class that will extend unittest.TestCase. test_<somethig> (without extension) is used as the name of the test method.

For example:

• tests/dnsrecord/test_dnsrecord.yml
• tests/dnsrecord/test_compatibility_with_ansible_module.yml
• tests/dnsrecord/test_dnsrecord_full_records.yml

Would create a TestCase class dnsrecord with methods: dnsrecotest_dnsrecord, test_compatibility_with_ansible_module and test_dnsrecord_full_records

Each test_<something>.yml include setup, execution, idempotency check and cleanup are currently all contained in the same file. Note that "verification"/"assertion" is not part of those ansible-freeipa test playbooks yet. Currently verification is done in different private repo (we are looking to change that as well).

We have made an experience recently adding "setup" and "clean" playbooks inside the grouping directory but each of the playbooks are currently including those playbooks: https://github.com/freeipa/ansible-freeipa/tree/master/tests/dnsrecord

If we follow a similar structure that the dnsrecord record example we could turn setup/cleanup into setup/teardown TestCase methods. I'm just under impression I'm recreating something really similar to molecule but using pytest as entrypoint.

@tyll in your example it seems like you have 2 levels of grouping: file and block. Each block would be the actual test_ "method", right? I suppose you could also use directories for grouping.

[tyll]

@tyll in your example it seems like you have 2 levels of grouping: file and block. Each block would be the actual test_ "method", right? I suppose you could also use directories for grouping.

Yes, each block with a task like - include_tasks: tasks/run_test.yml would be a test method. Some tasks are used as a setup in one test but as the actual test in the other test definition.