AttributeError: 'NoneType' object has no attribute 'get_debug'

[lphuberdeau]

Writing unit tests for asyncio code, I have a few tests that fail occasionally with this error. It seems to be timing-related.

I use loop_context() from aiohttp to make sure all tests are isolated.

The problem is essentially that _loop is not set by the time logging is attempted, which may be related to the loop closing and unregistering after wait_for() canceled the job.

Traceback (most recent call last):
  File "/../tests/fixtures.py", line 24, in wrapper
    loop.run_until_complete(f(*args, loop=loop, **kwargs))
  File "/usr/lib/python3.5/asyncio/base_events.py", line 387, in run_until_complete
    return future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 274, in result
    raise self._exception
  File "/usr/lib/python3.5/asyncio/tasks.py", line 239, in _step
    result = coro.send(None)
...
  File "....py", line 48, in ls
    return await asyncio.wait_for(self.read_lines(command), 30.0, loop=self.loop)
  File "/usr/lib/python3.5/asyncio/tasks.py", line 392, in wait_for
    return fut.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 274, in result
    raise self._exception
  File "/usr/lib/python3.5/asyncio/tasks.py", line 239, in _step
    result = coro.send(None)
  File "....py", line 58, in read_lines
    stdin=asyncio.subprocess.DEVNULL
  File "/usr/lib/python3.5/asyncio/subprocess.py", line 212, in create_subprocess_exec
    stderr=stderr, **kwds)
  File "/usr/lib/python3.5/asyncio/base_events.py", line 1079, in subprocess_exec
    bufsize, **kwargs)
  File "/usr/lib/python3.5/asyncio/unix_events.py", line 187, in _make_subprocess_transport
    self._child_watcher_callback, transp)
  File "/usr/lib/python3.5/asyncio/unix_events.py", line 808, in add_child_handler
    self._do_waitpid(pid)
  File "/usr/lib/python3.5/asyncio/unix_events.py", line 841, in _do_waitpid
    if self._loop.get_debug():
AttributeError: 'NoneType' object has no attribute 'get_debug'

In this case, the culprit is this one, but the pattern repeats often in the code.

            if self._loop.get_debug():
                logger.debug('process %s exited with returncode %s',
                             expected_pid, returncode)

[asvetlov]

Hi.
I believe it's aiohttp issue, not asyncio itself.
As aiohttp maintainer I suggest you didn't pass loop instance to create_subprocess_exec call.

For good or for bad aiohttp test suite requires explicit loop everywhere.

[asvetlov]

I've closed the issue to don't make a mess in asyncio bugtracker, please open new one in aiohttp project if needed.

[lphuberdeau]

Isn't there a problem with asyncio since loop was provided to create_subprocess_exec() and it does not reach the lower levels of unix_events in time? It's 5 steps deep in the stack trace.

[asvetlov]

Ok.
Would you provide source code for failing test?

[lphuberdeau]

I've reduced the script to the bare minimum. I did not use loop_context() here or place it in a unit test as it affects the global scope. The only difference with a normal execution is that the default event loop is not set.

import asyncio

asyncio.set_event_loop(None)

loop = asyncio.new_event_loop()


async def read_lines():
    process = await asyncio.create_subprocess_exec(
        *["cat", __file__],
        loop=loop,
        stdout=asyncio.subprocess.PIPE,
        stderr=asyncio.subprocess.DEVNULL,
        stdin=asyncio.subprocess.DEVNULL
    )   

    while not process.stdout.at_eof():
        line = await process.stdout.readline()

    return await process.wait()


async def wait_for_response():
    try:
        await asyncio.wait_for(read_lines(), 0.1, loop=loop)
    except asyncio.TimeoutError:
        pass


loop.run_until_complete(wait_for_response())

Keep in mind, it does not fail every time, but about 1/5 on my system, which is a rather clean ubuntu 16.04.

Full stack trace:

Traceback (most recent call last):
  File "test.py", line 30, in <module>
    loop.run_until_complete(wait_for_response())
  File "/usr/lib/python3.5/asyncio/base_events.py", line 387, in run_until_complete
    return future.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 274, in result
    raise self._exception
  File "/usr/lib/python3.5/asyncio/tasks.py", line 239, in _step
    result = coro.send(None)
  File "test.py", line 25, in wait_for_response
    await asyncio.wait_for(read_lines(), 0.1, loop=loop)
  File "/usr/lib/python3.5/asyncio/tasks.py", line 392, in wait_for
    return fut.result()
  File "/usr/lib/python3.5/asyncio/futures.py", line 274, in result
    raise self._exception
  File "/usr/lib/python3.5/asyncio/tasks.py", line 239, in _step
    result = coro.send(None)
  File "test.py", line 14, in read_lines
    stdin=asyncio.subprocess.DEVNULL
  File "/usr/lib/python3.5/asyncio/subprocess.py", line 212, in create_subprocess_exec
    stderr=stderr, **kwds)
  File "/usr/lib/python3.5/asyncio/base_events.py", line 1079, in subprocess_exec
    bufsize, **kwargs)
  File "/usr/lib/python3.5/asyncio/unix_events.py", line 187, in _make_subprocess_transport
    self._child_watcher_callback, transp)
  File "/usr/lib/python3.5/asyncio/unix_events.py", line 808, in add_child_handler
    self._do_waitpid(pid)
  File "/usr/lib/python3.5/asyncio/unix_events.py", line 841, in _do_waitpid
    if self._loop.get_debug():
AttributeError: 'NoneType' object has no attribute 'get_debug'
Exception ignored in: <bound method BaseSubprocessTransport.__del__ of <_UnixSubprocessTransport closed pid=20737 running stdout=<_UnixReadPipeTransport closing fd=8 open>>>
Traceback (most recent call last):
  File "/usr/lib/python3.5/asyncio/base_subprocess.py", line 126, in __del__
  File "/usr/lib/python3.5/asyncio/base_subprocess.py", line 101, in close
  File "/usr/lib/python3.5/asyncio/unix_events.py", line 376, in close
  File "/usr/lib/python3.5/asyncio/unix_events.py", line 404, in _close
  File "/usr/lib/python3.5/asyncio/base_events.py", line 497, in call_soon
  File "/usr/lib/python3.5/asyncio/base_events.py", line 506, in _call_soon
  File "/usr/lib/python3.5/asyncio/base_events.py", line 334, in _check_closed
RuntimeError: Event loop is closed

[vxgmichel]

I couldn’t reproduce the issue but there is definitely something off here. In the example, process.wait would hang forever if it weren't for asyncio.wait_forand its 0.1s timeout. This happens because the child watcher for the subprocess is not bound to loop:

     assert  asyncio.get_child_watcher()._loop is loop  # Fail!

It is actually bound to None since get_event_loop has never been called:

     assert  asyncio.get_child_watcher()._loop is not None  # Fail!

This explains why the stack trace reports an AttributeError for if self._loop.get_debug().

The culprit is in loop._make_subprocess_transport:

    with events.get_child_watcher() as watcher:

This creates the child watcher through policy._init_watcher:

                self._watcher = SafeChildWatcher()
                if isinstance(threading.current_thread(),
                              threading._MainThread):
                    self._watcher.attach_loop(self._local._loop)

The root of the problem is the fact that the child watcher is created by the policy and not the loop. There's more information about child watchers in the PEP 3156.

[lphuberdeau]

I did have some occurrences of .wait() hanging forever.

Is there anything I can do to help resolve this issue?

[vxgmichel]

Now I understand the design better:

• Since only the main thread can register signals, the child watcher has to be bound to the main loop (the loop running in the main thread).
• It is fine for other loops to watch subprocesses, as long as the main loop is running (so the main loop can notify the other ones using call_soon_threadsafe).

I can propose the following fix for _UnixSelectorEventLoop._make_subprocess_transport (untested):

    def _make_subprocess_transport(self, protocol, args, shell,
                                   stdin, stdout, stderr, bufsize,
                                   extra=None, **kwargs):
        with events.get_child_watcher() as watcher:
            if watcher._loop is not self and \
               isinstance(threading.current_thread(), threading._MainThread):
                watcher.attach_loop(self)
            [...]

It is also possible to move this test to _init_watcher, but get_child_watcher would require an optional loop=None argument, which is a bit misleading since it will be ignored if the function is called from a different thread.

Maybe some warnings could also be useful in case the main loop is not defined or not running.

[lphuberdeau]

I've tested the proposed fix locally and it does seem to resolve the issue.

Methodology:

while python test.py; do :; done

Without the fix, dumps the stacktrace within a second.

With the fix, runs forever as expected. (I also verified that it still behaves as expected)

[1st1]

I can propose the following fix for _UnixSelectorEventLoop._make_subprocess_transport (untested):

This is a nice workaround, albeit it feels a bit "hacky". Maybe we should modify BaseEventLoop.run_forever (or _UnixSelectorEventLoop.run_forever) to check if it's the main loop and install the watcher?

Also, should we raise an exception if there is no main event loop and you're trying to still use subprocess?

[lphuberdeau]

Testing async code is hard enough. Isolating the loop is the most reliable way I found to make sure the tests don't interfere with each other or randomly dump exceptions to the output.

Throwing exceptions if the main loop is not set is probably not ideal from this perspective.

[vxgmichel]

@1st1

Maybe we should modify BaseEventLoop.run_forever (or _UnixSelectorEventLoop.run_forever) to check if it's the main loop and install the watcher?

Is it acceptable to have the SIGCHLD signal registered for every asyncio program, even though it might not be used at all? Could this create problems on other platforms?

Also, should we raise an exception if there is no main event loop and you're trying to still use subprocess?

I guess in some cases, the sub-loops might be started first, and the main loop after. So raising an exception might be a bit too strict, but some warnings would be nice.

[1st1]

Throwing exceptions if the main loop is not set is probably not ideal from this perspective.

Without exceptions you wouldn't know that your program doesn't work at all. If there is no main event loop, child watchers won't receive UNIX signals at all. I've only quickly glanced over current implementation, and it seems to be the case.

Silently ignoring the problem will only make testing async code harder.