Python 3.7->3.7: refusing to serve stdlib module 'pathlib'

[dw]

[02:42:42 u1804!8 mitogen] cat a.py

import pathlib

def x():
    return repr(pathlib.Path())
[02:42:43 u1804!9 mitogen]
[02:42:44 u1804!9 mitogen]
[02:42:44 u1804!9 mitogen]
[02:42:44 u1804!9 mitogen]
[02:42:45 u1804!9 mitogen] fg
python3.7


>>> l = r.ssh(hostname='localhost')
>>> l.call(a.x)
02:43:00.541016 W mitogen: ModuleResponder(Router(Broker(0x7f8778135588))): refusing to serve stdlib module 'pathlib'
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/home/dmw/src/mitogen/mitogen/parent.py", line 1508, in call
    return self.default_call_chain.call(fn, *args, **kwargs)
  File "/home/dmw/src/mitogen/mitogen/parent.py", line 1470, in call
    return receiver.get().unpickle(throw_dead=False)
  File "/home/dmw/src/mitogen/mitogen/core.py", line 692, in unpickle
    raise obj
mitogen.core.CallError: exceptions.ImportError: Master does not have u'pathlib'
  File "<stdin>", line 2620, in _dispatch_one
  File "<stdin>", line 2607, in _parse_request
  File "<stdin>", line 491, in import_module
  File "<stdin>", line 1129, in load_module
  File "<string>", line 1, in <module>
  File "master:/home/dmw/src/mitogen/a.py", line 2, in <module>
    import pathlib
  File "<stdin>", line 1107, in load_module

>>>

[dw]

This isn't a bug, it's another confusing error message.

Importer should

1. Explain exactly why the stdlib import was refused -- it's because a cross-major-version stdlib module request happened, which means the python_path is incorrect, or the code is using 3.x or 2.x-only features in a cross-major-version design.

2. The error was buried in a log message. It should be returned as part of the negative import hit response, and raised as an exception by the child, so the error appears in the correct place.

[jamesob]

Also seeing this for master/client with same Python version (3.6.7):

#!/usr/bin/env python3.6
import os
import sys
from pathlib import Path

import mitogen


def install_app():
    os.system('ls {}'.format(Path.home()))


@mitogen.main()
def main(router):
    if len(sys.argv) != 2:
        print(__doc__)
        sys.exit(1)

    context = router.ssh(hostname=sys.argv[1])
    # context = router.fork()
    context.call(install_app)

When run:

Traceback (most recent call last):
  File "mitogen_demo.py", line 13, in <module>
    @mitogen.main()
  File "/home/james/.local/lib/python3.6/site-packages/mitogen/__init__.py", line 118, in wrapper
    func,
  File "/home/james/.local/lib/python3.6/site-packages/mitogen/core.py", line 561, in _profile_hook
    return func(*args)
  File "/home/james/.local/lib/python3.6/site-packages/mitogen/utils.py", line 159, in run_with_router
    return func(router, *args, **kwargs)
  File "mitogen_demo.py", line 21, in main
    context.call(install_app)
  File "/home/james/.local/lib/python3.6/site-packages/mitogen/parent.py", line 1759, in call
    return self.default_call_chain.call(fn, *args, **kwargs)
  File "/home/james/.local/lib/python3.6/site-packages/mitogen/parent.py", line 1718, in call
    return receiver.get().unpickle(throw_dead=False)
  File "/home/james/.local/lib/python3.6/site-packages/mitogen/core.py", line 835, in unpickle
    raise obj
mitogen.core.CallError: exceptions.ImportError: The Mitogen master process was unable to serve u'pathlib'. It may be a native Python extension, or it may be missing entirely. Check the importer debug logs on the master for more information.
  File "<stdin>", line 3099, in _dispatch_one
  File "<stdin>", line 3086, in _parse_request
  File "<stdin>", line 596, in import_module
  File "<stdin>", line 1357, in load_module
  File "<string>", line 1, in <module>
  File "master:mitogen_demo.py", line 4, in <module>
    from pathlib import Path
  File "<stdin>", line 1330, in load_module

Edit: relevant debug logs:

09:00:21 D mitogen.io: Router(Broker(0x7f278004f828))._async_route(Message(0, 1, 1, 102, 0, b"mitogen\x0010\x00_request_module(u'pathlib'): new reques"..51), mitogen.ssh.Stream('ssh.james2'))
09:00:21 D mitogen.ctx.ssh.james2: mitogen: _request_module(u'pathlib'): new request
09:00:21 D mitogen.io: Router(Broker(0x7f278004f828))._async_route(Message(0, 1, 1, 100, 0, b'pathlib'..7), mitogen.ssh.Stream('ssh.james2'))
09:00:21 D mitogen: ssh.james2 requested module pathlib
09:00:21 D mitogen.io: ModuleFinder()._get_module_via_pkgutil('pathlib') -> <_frozen_importlib_external.SourceFileLoader object at 0x7f2780902a90>
09:00:21 D mitogen: ModuleResponder(Router(Broker(0x7f278004f828))): refusing to serve stdlib module 'pathlib'
09:00:21 D mitogen: ssh.james2: sending module pathlib (0.02 KiB)
09:00:21 D mitogen.io: Router(Broker(0x7f278004f828))._async_route(Message(1, 0, 0, 107, None, b'\x80\x02(X\x07\x00\x00\x00pathlibq\x00NNN)tq\x01.'..25), None)
09:00:21 D mitogen.io: mitogen.ssh.Stream('ssh.james2')._send(Message(1, 0, 0, 107, None, b'\x80\x02(X\x07\x00\x00\x00pathlibq\x00NNN)tq\x01.'..25))
09:00:21 D mitogen.io: Broker(0x7f278004f828)._loop_once(None, EpollPoller(0x7f277ffa7470))
09:00:21 D mitogen.io: EpollPoller(0x7f277ffa7470).poll(None)
09:00:21 D mitogen.io: EpollPoller(0x7f277ffa7470): POLLIN: 8
09:00:21 D mitogen.io: mitogen.ssh.Stream('ssh.james2').on_receive()
09:00:21 D mitogen.io: Router(Broker(0x7f278004f828))._async_route(Message(0, 1, 1, 102, 0, b"mitogen\x0010\x00Importer._on_load_module(u'pathlib')"..47), mitogen.ssh.Stream('ssh.james2'))
09:00:21 D mitogen.ctx.ssh.james2: mitogen: Importer._on_load_module(u'pathlib')
09:00:21 D mitogen.io: Router(Broker(0x7f278004f828))._async_route(Message(0, 1, 1, 102, 0, b'mitogen\x0010\x00_dispatch_calls: Message(1, 0, 0, 101, '..743), mitogen.ssh.Stream('ssh.james2'))
09:00:21 D mitogen.ctx.ssh.james2: mitogen: _dispatch_calls: Message(1, 0, 0, 101, 1000, '\x80\x02(NX\x08\x00\x00\x00__main__q\x00NX\x0b\x00\x00\x00install_appq\x01)cmitogen.co'..75) -> CallError(u'exceptions.ImportError: The Mitogen master process was unable to serve u\'pathlib\'. It may be a native Python extension, or it may be missing entirely. Check the importer debug logs on the master for more information.\n  File "<stdin>", line 3099, in _dispatch_one\n  File "<stdin>", line 3086, in _parse_request\n  File "<stdin>", line 596, in import_module\n  File "<stdin>", line 1357, in load_module\n  File "<string>", line 1, in <module>\n  File "master:mitogen_demo.py", line 3, in <module>\n    from pathlib import Path\n  File "<stdin>", line 1330, in load_module\n',)

[jamesob]

My issue ended up being user error; I should've realized the hashbang at the beginning of my script isn't conveyed to the client. When I invoked the example script above and added a version printout, I saw that it was being run with Python 2.7:

09:05:17.173728 I mitogen.ctx.ssh.james2: stdout: 2.7.15rc1 (default, Nov 12 2018, 14:31:15)
09:05:17.174210 I mitogen.ctx.ssh.james2: stdout: [GCC 7.3.0]

Using the python_path kwarg on router.ssh ended up fixing the script:

context = router.ssh(
    hostname=sys.argv[1], python_path=['/usr/bin/env', 'python3'])

[dw]

At the very least, the active Python version should be reported in the logs generated by the bootstrap. There is a separate bug (#478) open for propagating the real ModuleResponder error to the target and then back as a CallError to the master. It's convoluted, but the result should be easier to understand failures of this sort