molecule + testinfra environment breaks event collection #200

jctanner · 2019-02-01T14:46:48Z

summary

Ansible-runner inside the molecule environment isn't able to store job events in the results object. The events are written to disk and can be read manually. They do have a "partial" suffix in the filename, but are otherwise complete/valid json.

http://tannerjc.net/ansible/tmp/jobdata.tar.gz

ansible-runner version

Reproduced with HEAD and 1.2.0

steps to reproduce

create a venv
pip install ansible
pip install molecule
pip uninstall testinfra
git clone https://github.com/philpep/testinfra
overwrite testinfra/utils/ansible_runner.py with https://gist.github.com/jctanner/512ec07171d95e61a5b7fd5f9103a301
pip install -e testinfra
mkdir roles ; cd roles; molecule init foobar; cd foobar
molecule converge (creates a docker container)
molecule verify (invokes py.test -> testinfra -> ansible_runner.py)

actual result

Molecule raises a NotImplemented exception, which really means that a fact wasn't in the return data (because no events) and the distro algorithm in their code couldn't find a match for null.

(venv) [jtanner@jtw530 role.2]$ molecule verify
--> Validating schema /data/workspace.issues/AP-MOLECULE_COLLECTION_INIT/collections/role.2/molecule/default/molecule.yml.
Validation completed successfully.
--> Test matrix

└── default
    └── verify

--> Scenario: 'default'
--> Action: 'verify'
--> Executing Testinfra tests found in /data/workspace.issues/AP-MOLECULE_COLLECTION_INIT/collections/role.2/molecule/default/tests/...
    ============================= test session starts ==============================
    platform linux -- Python 3.7.2, pytest-3.0.7, py-1.7.0, pluggy-0.4.0
    rootdir: /data/workspace.issues/AP-MOLECULE_COLLECTION_INIT/collections/role.2/molecule/default, inifile:
    plugins: verbose-parametrize-1.4.0, mock-1.10.0, helpers-namespace-2019.1.8, cov-2.6.0, testinfra-1.19.1.dev1+ge82a685.d20190130
collected 1 itemss

    tests/test_default.py F

    =================================== FAILURES ===================================
    _____________________ test_hosts_file[ansible://instance] ______________________

    host = <testinfra.host.Host object at 0x7f54a11e9da0>

        def test_hosts_file(host):
    >       f = host.file('/etc/hosts')

    tests/test_default.py:10:
    _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
    ../../../../testinfra.jctanner/testinfra/host.py:107: in __getattr__
        obj = module_class.get_module(self)
    ../../../../testinfra.jctanner/testinfra/modules/base.py:22: in get_module
        klass = cls.get_module_class(_host)
    _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

    cls = <class 'testinfra.modules.file.File'>
    host = <testinfra.host.Host object at 0x7f54a11e9da0>

        @classmethod
        def get_module_class(cls, host):
            if host.system_info.type == "linux":
                return GNUFile
            elif host.system_info.type == "netbsd":
                return NetBSDFile
            elif host.system_info.type.endswith("bsd"):
                return BSDFile
            elif host.system_info.type == "darwin":
                return DarwinFile
            else:
    >           raise NotImplementedError
    E           NotImplementedError

    ../../../../testinfra.jctanner/testinfra/modules/file.py:196: NotImplementedError
    ----------------------------- Captured stdout call -----------------------------


    =========================== 1 failed in 5.26 seconds ===========================

The text was updated successfully, but these errors were encountered:

jctanner · 2019-02-01T15:05:37Z

Attempting to reduce this down to something simple hasn't yielded a reproducer yet ...

(venv) [jtanner@jtw530 runner_reproducer]$ cat run.py
#!/usr/bin/env python

import os
import sh
import logging

from molecule.logger import get_logger
from molecule.util import run_command

LOG = get_logger(__name__)


def main():
    options = {
        'ansible-inventory': '/tmp/foobar',
        'connection': 'ansible',
        'p': 'no:cacheprovider'
    }
    ptest = sh.Command('py.test').bake(
        options,
        'runner_bug.py',
        _cwd=os.getcwd(),
        _out=LOG.out,
        _err=LOG.error
    )

    # this is not fine? ...
    print('# ENVIRONMENT v')
    print(ptest._partial_call_args.get('env', {}))
    print('# ENVIRONMENT ^')
    run_command(ptest, debug=False)


if __name__ == '__main__':
    main()

(venv) [jtanner@jtw530 runner_reproducer]$ cat runner_bug.py
#!/usr/bin/env python


import tempfile

from testinfra.utils.ansible_runner import AnsibleRunner


def test_events():

    invfh,invfile = tempfile.mkstemp()
    with open(invfile, 'w') as f:
        f.write('localhost,')

    ar = AnsibleRunner.get_runner(invfile)
    result = ar.run('localhost', 'shell', 'echo "foobar"')

    assert 'cmd' in result
    assert 'stdout' in result
    assert 'stderr' in result
    assert result['stdout'] == 'foobar'


def main():
    test_events()


if __name__ == "__main__":
    main()

(venv) [jtanner@jtw530 runner_reproducer]$ ./run.py
# ENVIRONMENT v
{}
# ENVIRONMENT ^
    ============================= test session starts ==============================
    platform linux -- Python 3.7.2, pytest-3.0.7, py-1.7.0, pluggy-0.4.0
    rootdir: /data/workspace.issues/AP-MOLECULE_COLLECTION_INIT/runner_reproducer, inifile:
    plugins: verbose-parametrize-1.4.0, mock-1.10.0, helpers-namespace-2019.1.8, cov-2.6.0, testinfra-1.19.1.dev1+ge82a685.d20190130
collected 1 itemss

    runner_bug.py .

    =========================== 1 passed in 1.20 seconds ===========================

jctanner · 2019-02-01T15:21:47Z

The file descriptors for stdout/stderr are the same in both cases ...

# events are not captured
 0.0s __init__: self=<display_callback.module.AWXMinimalCallbackModule object>
 0.0s __init__: inf=('/proc/self/fd/0', '/dev/pts/30')
 0.0s __init__: inf=('/proc/self/fd/1', '/dev/pts/30')
 0.0s __init__: inf=('/proc/self/fd/2', '/dev/pts/30')
 0.0s __init__:
      inf=('/proc/self/fd/3', '/data/workspace.issues/AP-MOLECULE_COLLECTION_INIT/bcoca_ansible.allow_content/bin/ansible')
 0.0s __init__: inf=('/proc/self/fd/4', '/dev/urandom')
 0.0s __init__: inf=('/proc/self/fd/5', '/proc/18332/fd/pipe:[13331126]')
 0.0s __init__: inf=('/proc/self/fd/6', '/proc/18332/fd/pipe:[13331126]')
 0.0s __init__: inf=('/proc/self/fd/7', '/tmp/#13331131 (deleted)')
 0.0s __init__: inf=('/proc/self/fd/8', '/proc/18332/fd/8')

# events are captured
 0.0s __init__: self=<display_callback.module.AWXMinimalCallbackModule object>
 0.0s __init__: inf=('/proc/self/fd/0', '/dev/pts/30')
 0.0s __init__: inf=('/proc/self/fd/1', '/dev/pts/30')
 0.0s __init__: inf=('/proc/self/fd/2', '/dev/pts/30')
 0.0s __init__:
      inf=('/proc/self/fd/3', '/data/workspace.issues/AP-MOLECULE_COLLECTION_INIT/bcoca_ansible.allow_content/bin/ansible')
 0.0s __init__: inf=('/proc/self/fd/4', '/dev/urandom')
 0.0s __init__: inf=('/proc/self/fd/5', '/proc/18775/fd/pipe:[13334793]')
 0.0s __init__: inf=('/proc/self/fd/6', '/proc/18775/fd/pipe:[13334793]')
 0.0s __init__: inf=('/proc/self/fd/7', '/tmp/#13334798 (deleted)')
 0.0s __init__: inf=('/proc/self/fd/8', '/proc/18775/fd/8')

jctanner · 2019-02-01T17:00:39Z

I think I've found the culprit. This line in utils.py calls a regex to check if the data coming from pexpect should be emitted:

https://github.com/ansible/ansible-runner/blob/master/ansible_runner/utils.py#L242

When running outside of molecule, there are matches. When running inside molecule there are NO matches. I've captured example data from both scenarios and uploaded to ...

http://tannerjc.net/ansible/tmp/regex_info.tar.gz

jctanner · 2019-02-01T17:02:19Z

Some examples of data that should have matched in the regex but did not ...

((venv) [jtanner@jtw530 runner_reproducer]$ cat /tmp/matches.bug/bad.txt | tail -n25
!MATCH:ansible 2.8.0.dev0
  config file = /tmp/molecule/role.2/default/ansible.cfg
  configured module search path = ['/data/workspace.issues/AP-MOLECULE_COLLECTION_INIT/molecule.NEWPR/molecule/provisioner/ansible/plugins/libraries', '/tmp/molecule/role.2/default/library', '/data/workspace.issues/AP-MOLECULE_COLLECTION_INIT/collections/role.2/library']
  ansible python module location = /data/workspace.issues/AP-MOLECULE_COLLECTION_INIT/bcoca_ansible.allow_content/lib/ansible
  executable location = /data/workspace.issues/AP-MOLECULE_COLLECTION_INIT/venv/bin/ansible
  python version = 3.7.2 (default, Jan  3 2019, 09:14:01) [GCC 8.2.1 20181215 (Red Hat 8.2.1-6)]
Using /tmp/molecule/role.2/default/ansible.cfg as config file
host_list declined parsing /tmp/tmpee916zob/inventory/ansible_inventory.yml as it did not pass it's verify_file() method
script declined parsing /tmp/tmpee916zob/inventory/ansible_inventory.yml as it did not pass it's verify_file() method
Parsed /tmp/tmpee916zob/inventory/ansible_inventory.yml inventory source with yaml plugin
META: ran handlers
<instance> ESTABLISH DOCKER CONNECTION FOR USER: root
<instance> EXEC ['/usr/bin/docker', b'exec', b'-i', 'instance', '/bin/sh', '-c', "/bin/sh -c 'echo ~ && sleep 0'"]
<instance> EXEC ['/usr/bin/docker', b'exec', b'-i', 'instance', '/bin/sh', '-c', '/bin/sh -c \'( umask 77 && mkdir -p "` echo /root/.ansible/tmp/ansible-tmp-1549040138.1649194-45170402785306 `" && echo ansible-tmp-1549040138.1649194-45170402785306="` echo /root/.ansible/tmp/ansible-tmp-1549040138.1649194-45170402785306 `" ) && sleep 0\'']
Using module file /data/workspace.issues/AP-MOLECULE_COLLECTION_INIT/bcoca_ansible.allow_content/lib/ansible/modules/commands/command.py
<instance> PUT /home/jtanner/.ansible/tmp/ansible-local-18293u8chzyr9/tmpf94oiuze TO /root/.ansible/tmp/ansible-tmp-1549040138.1649194-45170402785306/AnsiballZ_command.py
<instance> EXEC ['/usr/bin/docker', b'exec', b'-i', 'instance', '/bin/sh', '-c', "/bin/sh -c 'chmod u+x /root/.ansible/tmp/ansible-tmp-1549040138.1649194-45170402785306/ /root/.ansible/tmp/ansible-tmp-1549040138.1649194-45170402785306/AnsiballZ_command.py && sleep 0'"]
<instance> EXEC ['/usr/bin/docker', b'exec', b'-i', 'instance', '/bin/sh', '-c', "/bin/sh -c '/usr/bin/python /root/.ansible/tmp/ansible-tmp-1549040138.1649194-45170402785306/AnsiballZ_command.py && sleep 0'"]
<instance> EXEC ['/usr/bin/docker', b'exec', b'-i', 'instance', '/bin/sh', '-c', "/bin/sh -c 'rm -f -r /root/.ansible/tmp/ansible-tmp-1549040138.1649194-45170402785306/ > /dev/null 2>&1 && sleep 0'"]
instance | CHANGED | rc=0 >>
4.19.13-300.fc29.x86_64

META: ran handlers
META: ran handlers

matburt · 2019-02-15T16:53:19Z

This is tricky, it looks like something is adding ansicolor codes to what Runner expects to be b64 encoded data, normally our event payloads look like:

\x1b[KB64DATA\x1b[K

Our b64 payload start/end separator is \x1b[K

This gets put together with stdout

\x1b[KB64DATA\x1b[Kstdout is here

B64DATA can be broken down into chunks that are identified with something like this: \x1b[ND where N is the size of the previous chunk.

Something is inserting ansicolor clear codes into what should be a plain b64 string.

\x1b[K\x1b[0m\x1b[0mB64DATA\x1b[0m\x1b[0m\x1b[K

and I'm not sure yet why that's happening.

matburt · 2019-03-04T16:30:54Z

This looks like it's happening because molecule uses a library called colorama which automatically sends ansi reset codes every time you call .write() on stdout:

https://github.com/ansible/molecule/blob/334c6699cd380873aecc8986d7336f6fcb1634ba/molecule/util.py#L38

matburt · 2019-03-04T16:52:02Z

After disabling colorama on molecule I can get past this error.

decentral1se · 2019-03-21T11:09:12Z

btw, molecule now honours a PY_COLORS variable, see ansible/molecule#1533 👍

matburt · 2019-03-21T16:04:43Z

What does this mean for molecule+runner integration?

matburt self-assigned this Feb 13, 2019

jctanner mentioned this issue Mar 1, 2019

AnsibleRunnerV2 broken on upstream changes to PlaybookCLI in devel pytest-dev/pytest-testinfra#401

Closed

matburt closed this as completed Mar 4, 2019

jctanner mentioned this issue Mar 4, 2019

Switch to ansible-runner pytest-dev/pytest-testinfra#410

Closed

decentral1se mentioned this issue Mar 21, 2019

Respect PY_COLORS variable ansible/molecule#1533

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

molecule + testinfra environment breaks event collection #200

molecule + testinfra environment breaks event collection #200

jctanner commented Feb 1, 2019 •

edited

Loading

jctanner commented Feb 1, 2019 •

edited

Loading

jctanner commented Feb 1, 2019

jctanner commented Feb 1, 2019

jctanner commented Feb 1, 2019 •

edited

Loading

matburt commented Feb 15, 2019 •

edited

Loading

matburt commented Mar 4, 2019

matburt commented Mar 4, 2019

decentral1se commented Mar 21, 2019

matburt commented Mar 21, 2019

molecule + testinfra environment breaks event collection #200

molecule + testinfra environment breaks event collection #200

Comments

jctanner commented Feb 1, 2019 • edited Loading

summary

ansible-runner version

steps to reproduce

actual result

jctanner commented Feb 1, 2019 • edited Loading

jctanner commented Feb 1, 2019

jctanner commented Feb 1, 2019

jctanner commented Feb 1, 2019 • edited Loading

matburt commented Feb 15, 2019 • edited Loading

matburt commented Mar 4, 2019

matburt commented Mar 4, 2019

decentral1se commented Mar 21, 2019

matburt commented Mar 21, 2019

jctanner commented Feb 1, 2019 •

edited

Loading

jctanner commented Feb 1, 2019 •

edited

Loading

jctanner commented Feb 1, 2019 •

edited

Loading

matburt commented Feb 15, 2019 •

edited

Loading