[issue21645] asyncio: Race condition in signal handling on FreeBSD

[STINNER Victor]

STINNER Victor added the comment:

I ran test_asyncio on my own FreeBSD VM, with the sandbox/issue21645 repository and I got a new (different) error on signal handling: RuntimeError('reentrant call inside') when writing into sys.stderr. To be fair: this bug was introduced by my changes in this repository adding debug traces ("logger.error("handle signal %s" % sig)").

IMO the Py_AddPendingCall() function in Python is dangerous: the callback should be "signal-safe" but this concept is not defined Python. In the C language, there is a strict list of allowed functions, in Python it's unclear: the reentrant call is just an example. It's probably easy to deadlock if you call the "wrong" function".

Py_AddPendingCall() injects arbitrary Python code between *any* other Python bytecode, it's like the evil greenlet with greenthreads.

That's why I consider that it would be safer to call _handle_signal() from the event loop, not using Py_AddPendingCall():
https://code.google.com/p/tulip/issues/detail?id=192

Output of the new bug on FreeBSD:
-----------
[1085] C signal_handler: sig_num=20, thread=34380739584
C signal_handler: trip signal (tripped=0)
[1085] trip_signal(20)
trip_signal(20); write()
trip_signal(20); write() -> 1
[1085] Py_AddPendingCall(checksignals_witharg), thread=34380739584
--- Logging error ---
Traceback (most recent call last):
  File "/usr/home/haypo/prog/python/default/Lib/logging/__init__.py", line 980, in emit
    stream.write(self.terminator)
RuntimeError: reentrant call inside <_io.BufferedWriter name='<stderr>'>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/home/haypo/prog/python/default/Lib/logging/__init__.py", line 980, in emit
    stream.write(self.terminator)
  File "/usr/home/haypo/prog/python/default/Lib/asyncio/unix_events.py", line 95, in _handle_signal
    logger.error("handle signal %s" % sig)
  File "/usr/home/haypo/prog/python/default/Lib/logging/__init__.py", line 1302, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/usr/home/haypo/prog/python/default/Lib/logging/__init__.py", line 1408, in _log
    self.handle(record)
  File "/usr/home/haypo/prog/python/default/Lib/logging/__init__.py", line 1418, in handle
    self.callHandlers(record)
  File "/usr/home/haypo/prog/python/default/Lib/logging/__init__.py", line 1480, in callHandlers
    hdlr.handle(record)
  File "/usr/home/haypo/prog/python/default/Lib/logging/__init__.py", line 852, in handle
    self.emit(record)
  File "/usr/home/haypo/prog/python/default/Lib/logging/__init__.py", line 983, in emit
    self.handleError(record)
  File "/usr/home/haypo/prog/python/default/Lib/logging/__init__.py", line 904, in handleError
    sys.stderr.write('--- Logging error ---\n')
RuntimeError: reentrant call inside <_io.BufferedWriter name='<stderr>'>
Call stack:
  File "/usr/home/haypo/prog/python/default/Lib/runpy.py", line 170, in _run_module_as_main
    "__main__", mod_spec)
  File "/usr/home/haypo/prog/python/default/Lib/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/usr/home/haypo/prog/python/default/Lib/test/__main__.py", line 3, in <module>
    regrtest.main_in_temp_cwd()
  File "/usr/home/haypo/prog/python/default/Lib/test/regrtest.py", line 1562, in main_in_temp_cwd
    main()
  File "/usr/home/haypo/prog/python/default/Lib/test/regrtest.py", line 763, in main
    match_tests=ns.match_tests)
  File "/usr/home/haypo/prog/python/default/Lib/test/regrtest.py", line 978, in runtest
    display_failure=not verbose)
  File "/usr/home/haypo/prog/python/default/Lib/test/regrtest.py", line 1278, in runtest_inner
    test_runner()
  File "/usr/home/haypo/prog/python/default/Lib/test/test_asyncio/__init__.py", line 29, in test_main
    run_unittest(suite())
  File "/usr/home/haypo/prog/python/default/Lib/test/support/__init__.py", line 1758, in run_unittest
    _run_suite(suite)
  File "/usr/home/haypo/prog/python/default/Lib/test/support/__init__.py", line 1724, in _run_suite
    result = runner.run(suite)
  File "/usr/home/haypo/prog/python/default/Lib/unittest/runner.py", line 168, in run
    test(result)
  File "/usr/home/haypo/prog/python/default/Lib/unittest/suite.py", line 87, in __call__
    return self.run(*args, **kwds)
  File "/usr/home/haypo/prog/python/default/Lib/unittest/suite.py", line 125, in run
    test(result)
  File "/usr/home/haypo/prog/python/default/Lib/unittest/suite.py", line 87, in __call__
    return self.run(*args, **kwds)
  File "/usr/home/haypo/prog/python/default/Lib/unittest/suite.py", line 125, in run
    test(result)
  File "/usr/home/haypo/prog/python/default/Lib/unittest/suite.py", line 87, in __call__
    return self.run(*args, **kwds)
  File "/usr/home/haypo/prog/python/default/Lib/unittest/suite.py", line 125, in run
    test(result)
  File "/usr/home/haypo/prog/python/default/Lib/unittest/case.py", line 625, in __call__
    return self.run(*args, **kwds)
  File "/usr/home/haypo/prog/python/default/Lib/unittest/case.py", line 577, in run
    testMethod()
  File "/usr/home/haypo/prog/python/default/Lib/test/test_asyncio/test_streams.py", line 647, in test_read_all_from_pipe_reader
    self.loop.run_until_complete(proc.wait())
  File "/usr/home/haypo/prog/python/default/Lib/asyncio/base_events.py", line 265, in run_until_complete
    self.run_forever()
  File "/usr/home/haypo/prog/python/default/Lib/asyncio/base_events.py", line 238, in run_forever
    self._run_once()
  File "/usr/home/haypo/prog/python/default/Lib/asyncio/base_events.py", line 984, in _run_once
    logger.error("[pid %s] _run_once: thread=%s" % (os.getpid(), threading.get_ident()))
Message: '[pid 1085] _run_once: thread=34380739584'
-----------

----------

_______________________________________
Python tracker <report at bugs.python.org>
<http://bugs.python.org/issue21645>
_______________________________________