Mitogen with Molecule?

[dsgnr]

This is possibly pushing the boundaries and no way did I expect this to work, but thought why not try?!

I was attempting to implement Mitogen with Molecule so that the checks etc run quicker.

Here's my molecule.yml:

---
driver:
  name: docker
lint:
  name: yamllint
dependency:
  name: shell
  command: mkdir -p /tmp/molecule/plugins && git clone https://github.com/dw/mitogen.git /tmp/molecule/plugins/mitogen
platforms:
  - name: molecule-centos7
    image: centos:7
  - name: molecule-ubuntu1604
    image: ubuntu:xenial
  - name: molecule-ubuntu1804
    image: ubuntu:bionic
provisioner:
  name: ansible
  config_options:
    defaults:
      strategy_plugins: /tmp/molecule/plugins/mitogen/ansible_mitogen/plugins/strategy
      strategy: mitogen_linear
    ssh_connection:
      pipelining: true
      ssh_args: -o ControlMaster=auto -o ControlPersist=60s
  lint:
    name: ansible-lint
scenario:
  name: default
verifier:
  name: testinfra
  lint:
    name: flake8

Now, it does seem to work through molecule test but there is an error being presented. As this is not exactly a typical use case, I'm not expecting anything from it, rather just querying what this is:

    TASK [Wait for instance(s) deletion to complete] *******************************
    FAILED - RETRYING: Wait for instance(s) deletion to complete (300 retries left).
ERROR! [pid 114126] 13:44:11.383913 E mitogen.ctx.local.114148: mitogen: RouteMonitor(): received DEL_ROUTE for 1004 from mitogen.fork.Stream(u'fork.114151'), expected mitogen.core.Stream('parent')
ERROR! [pid 114126] 13:44:11.399392 E mitogen.ctx.local.114148: mitogen: RouteMonitor(): received DEL_ROUTE for 1003 from mitogen.fork.Stream(u'fork.114151'), expected mitogen.core.Stream('parent')
ERROR! [pid 114126] 13:44:11.437268 E mitogen.ctx.local.114148: mitogen: RouteMonitor(): received DEL_ROUTE for 1005 from mitogen.fork.Stream(u'fork.114151'), expected mitogen.core.Stream('parent')
    changed: [localhost] => (item=None)
    changed: [localhost] => (item=None)
    changed: [localhost] => (item=None)
    changed: [localhost]


_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

cls = <class 'ansible_mitogen.process.MuxProcess'>

    @classmethod
    def start(cls):
        """
        Arrange for the subprocess to be started, if it is not already running.
    
        The parent process picks a UNIX socket path the child will use prior to
        fork, creates a socketpair used essentially as a semaphore, then blocks
        waiting for the child to indicate the UNIX socket is ready for use.
        """
        if cls.worker_sock is not None:
            return
    
        if faulthandler is not None:
            faulthandler.enable()
    
        setup_gil()
        cls.unix_listener_path = mitogen.unix.make_socket_path()
        cls.worker_sock, cls.child_sock = socket.socketpair()
        atexit.register(lambda: clean_shutdown(cls.worker_sock))
        mitogen.core.set_cloexec(cls.worker_sock.fileno())
        mitogen.core.set_cloexec(cls.child_sock.fileno())
    
        if os.environ.get('MITOGEN_PROFILING'):
            mitogen.core.enable_profiling()
    
        cls.original_env = dict(os.environ)
        cls.child_pid = os.fork()
        ansible_mitogen.logging.setup()
        if cls.child_pid:
            cls.child_sock.close()
            cls.child_sock = None
            mitogen.core.io_op(cls.worker_sock.recv, 1)
        else:
            cls.worker_sock.close()
            cls.worker_sock = None
            self = cls()
            self.worker_main()
>           sys.exit()
E           SystemExit

/tmp/molecule/plugins/mitogen/ansible_mitogen/process.py:193: SystemExit
====================== 1 failed, 2 passed in 5.58 seconds ======================

[dw]

Mitogen complains a lot when it does not have to -- a historical mistake. The DEL_ROUTE messages can more or less be ignored, they are really debug messages and I think already they have been made debug messages for 0.2.4, but the shutdown ordering issue is definitely broken.

This looks like a legit bug, so I'll setup Molecule locally and figure out what's going wrong. Mitogen connections have significant extra state (threads and a worker subprocess - the thing that is breaking here) that must be managed carefully during a run.

Thanks for reporting this!

[dsgnr]

No problem at all!

Wasn’t sure if this was a legit issue or just an incompatibility between the two applications (definitely possible).

Let me know you’d like example playbooks that I was testing against. :)

[dw]

This thing is a bit of a time sink :) Any chance you could fire up a ZIP file with an ultra-simple one step + test project that I can work with? Haven't even gotten as far as figuring out where Mitogen plugs in!

[dsgnr]

Hey so i've created a new role here: https://github.com/dsgnr/mitogen-molecule-test
The molecule file that is grabbing Mitogen is in molecule/default/molecule.yml

so molecule lint works fine it seems as that doesn't use Ansible iirc. But molecule test and others are producing the errors. A better output for you, may give you some more information:

=================================== FAILURES ===================================
    _________________ test_hosts_file[ansible://molecule-centos7] __________________

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

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

    tests/test_default.py:10:
    _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
    /usr/local/lib/python2.7/dist-packages/testinfra/host.py:107: in __getattr__
        obj = module_class.get_module(self)
    /usr/local/lib/python2.7/dist-packages/testinfra/modules/base.py:22: in get_module
        klass = cls.get_module_class(_host)
    /usr/local/lib/python2.7/dist-packages/testinfra/modules/file.py:187: in get_module_class
        if host.system_info.type == "linux":
    /usr/local/lib/python2.7/dist-packages/testinfra/modules/systeminfo.py:124: in type
        return self.sysinfo["type"]
    /usr/local/lib/python2.7/dist-packages/testinfra/utils/__init__.py:42: in __get__
        value = obj.__dict__[self.func.__name__] = self.func(obj)
    /usr/local/lib/python2.7/dist-packages/testinfra/modules/systeminfo.py:33: in sysinfo
        sysinfo["type"] = self.check_output("uname -s").lower()
    /usr/local/lib/python2.7/dist-packages/testinfra/host.py:71: in run
        return self.backend.run(command, *args, **kwargs)
    /usr/local/lib/python2.7/dist-packages/testinfra/backend/ansible.py:42: in run
        out = self.run_ansible("shell", module_args=command)
    /usr/local/lib/python2.7/dist-packages/testinfra/backend/ansible.py:57: in run_ansible
        **kwargs)
    /usr/local/lib/python2.7/dist-packages/testinfra/utils/ansible_runner.py:225: in run
        tqm.run(play)
    /usr/local/lib/python2.7/dist-packages/ansible/executor/task_queue_manager.py:291: in run
        play_return = strategy.run(iterator, play_context)
    /tmp/molecule/plugins/mitogen/ansible_mitogen/strategy.py:193: in run
        ansible_mitogen.process.MuxProcess.start()
    _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

    cls = <class 'ansible_mitogen.process.MuxProcess'>

        @classmethod
        def start(cls):
            """
            Arrange for the subprocess to be started, if it is not already running.

            The parent process picks a UNIX socket path the child will use prior to
            fork, creates a socketpair used essentially as a semaphore, then blocks
            waiting for the child to indicate the UNIX socket is ready for use.
            """
            if cls.worker_sock is not None:
                return

            if faulthandler is not None:
                faulthandler.enable()

            setup_gil()
            cls.unix_listener_path = mitogen.unix.make_socket_path()
            cls.worker_sock, cls.child_sock = socket.socketpair()
            atexit.register(lambda: clean_shutdown(cls.worker_sock))
            mitogen.core.set_cloexec(cls.worker_sock.fileno())
            mitogen.core.set_cloexec(cls.child_sock.fileno())

            if os.environ.get('MITOGEN_PROFILING'):
                mitogen.core.enable_profiling()

            cls.original_env = dict(os.environ)
            cls.child_pid = os.fork()
            ansible_mitogen.logging.setup()
            if cls.child_pid:
                cls.child_sock.close()
                cls.child_sock = None
                mitogen.core.io_op(cls.worker_sock.recv, 1)
            else:
                cls.worker_sock.close()
                cls.worker_sock = None
                self = cls()
                self.worker_main()
    >           sys.exit()
    E           SystemExit

    /tmp/molecule/plugins/mitogen/ansible_mitogen/process.py:193: SystemExit
    ====================== 1 failed, 2 passed in 5.37 seconds ======================
    F
Verifier completed successfully.
--> Scenario: 'default'
--> Action: 'destroy'

    PLAY [Destroy] *****************************************************************

    TASK [Destroy molecule instance(s)] ********************************************
    changed: [localhost] => (item=None)
    changed: [localhost] => (item=None)
    changed: [localhost] => (item=None)
    changed: [localhost]

    TASK [Wait for instance(s) deletion to complete] *******************************
ERROR! [pid 39184] 09:24:38.527780 E mitogen.ctx.local.39206: mitogen: RouteMonitor(): received DEL_ROUTE for 1003 from mitogen.fork.Stream(u'fork.39209'), expected mitogen.core.Stream('parent')
    FAILED - RETRYING: Wait for instance(s) deletion to complete (300 retries left).
ERROR! [pid 39184] 09:24:38.553882 E mitogen.ctx.local.39206: mitogen: RouteMonitor(): received DEL_ROUTE for 1004 from mitogen.fork.Stream(u'fork.39209'), expected mitogen.core.Stream('parent')
ERROR! [pid 39184] 09:24:38.706967 E mitogen.ctx.local.39206: mitogen: RouteMonitor(): received DEL_ROUTE for 1005 from mitogen.fork.Stream(u'fork.39209'), expected mitogen.core.Stream('parent')
    changed: [localhost] => (item=None)
    changed: [localhost] => (item=None)
    changed: [localhost] => (item=None)
    changed: [localhost]

Hope this helps!

[dw]

Ok, finally reading the actual logs you pasted, and the problem looks quite straightforward -- and may even be fixed already on recent master.

Somehow Molecule is running Ansible's guts under py.test, which traps all exceptions, and the forked connection multiplexer process is inheriting that test harness. When it attempts to exit normally, the test harness complains.

I bumped into the same issue recently and replaced 'sys.exit()' with 'os._exit()', side-stepping the inherited harness.

I suspect if that is the case, the run actually completed successfully, it just complained a lot. Will try to repro on master shortly.

[dw]

After quite a bit of smashing around, I got 'molecule converge' to DTRT. It appears the previous comment was correct -- the same os._exit() fix applies here too.

One thing I notice while molecule is running -- it seems to restart Ansible /a lot/. That does not bode well for Mitogen, but maybe I'm only seeing these restarts through the tiny window of a stub Molecule config without some big meaty playbooks running.

If you have any more trouble, please don't hesitate to reopen -- sorry this one took so long, and thanks a million for reporting!

---

This is now on the master branch and will make it into the next release. To be updated when a new release is made, subscribe to https://networkgenomics.com/mail/mitogen-announce/

Thanks for reporting this!