jgehrcke / gipc

gevent-cooperative child processes and inter-process communication
https://gehrcke.de/gipc
MIT License
83 stars 13 forks source link

test_orphaned_signal_handler: rare instability #89

Closed jgehrcke closed 3 years ago

jgehrcke commented 4 years ago

https://travis-ci.org/jgehrcke/gipc/jobs/618426367

test/test_gipc.py::TestSignals::test_signal_handlers_default PASSED      [100%]
=================================== FAILURES ===================================
___________________ TestSignals.test_orphaned_signal_watcher ___________________
self = <test_gipc.TestSignals object at 0x000000010d3d4138>
    def test_orphaned_signal_watcher(self):
        # Install libev-based signal watcher.
        s = gevent.signal(signal.SIGTERM, signals_test_sigterm_handler)
        # Normal behavior: signal handlers become inherited by children.
        # Bogus behavior of libev-based signal watchers in child process:
        # They should not be active anymore when 'orphaned' (when their
        # corresponding event loop has been destroyed). What happens, however:
        # The old handler stays active and registering a new handler does not
        # 'overwrite' the old one -- both are active.
        # Since this test is about testing the behavior of 'orphaned' libev
        # signal watchers, the signal must be transmitted *after* event loop
        # recreation, so wait here for the child process to go through
        # the hub & event loop destruction (and recreation) process before
        # sending the signal. Waiting is realized with sync through pipe.
        # Without cleanup code in gipc, the inherited but orphaned libev signal
        # watcher would be active in the fresh event loop and trigger the
        # handler. This is a problem. With cleanup code, this handler must
        # never be called. Child exitcode 20 means that the inherited handler
        # has been called, -15 (-signal.SIGTERM) means that the child was
        # actually killed by SIGTERM within a certain short time interval.
        # Returncode 0 would mean that the child finished normally after that
        # short time interval.
        with pipe() as (r, w):
            p = start_process(signals_test_child_a, (w,))
            assert r.get() == p.pid
            os.kill(p.pid, signal.SIGTERM)
            p.join()
            if not WINDOWS:
>               assert p.exitcode == -signal.SIGTERM
E               assert 0 == -15
E                 -0
E                 +-15
test/test_gipc.py:1305: AssertionError
----------------------------- Captured stderr call -----------------------------
02:54:44,679.9  [19974]start_process# Invoke target `<function signals_test_child_a at 0x00000001108fe980>` in child process.
02:54:44,682.9  [19974]start# SIGCHLD watcher for 20024 started.
02:54:44,683.6  [19974]start_process# Invalidate <_GIPCWriter_b413c4 fd: 23> in parent.
02:54:44,684.3  [19974]close# Invalidating <_GIPCWriter_b413c4 fd: 23> ...
02:54:44,707.2  [20024]_child# _child start. target: `<function signals_test_child_a at 0x00000001108fe980>`
02:54:44,712.0  [20024]_child# Delete current hub's threadpool.
02:54:44,712.9  [20024]_child# Destroy hub and default loop.
02:54:44,714.6  [20024]_child# Created new hub and default event loop.
02:54:44,715.1  [20024]_child# Invalidate <_GIPCReader_c0ae88 fd: 21> in child.
02:54:44,715.7  [20024]_set_legit_process# Legitimate <_GIPCReader_c0ae88 fd: 21> for current process.
02:54:44,716.4  [20024]close# Invalidating <_GIPCReader_c0ae88 fd: 21> ...
02:54:44,717.1  [20024]_set_legit_process# Legitimate <_GIPCWriter_b413c4 fd: 23> for current process.
02:54:44,717.7  [20024]_child# Handle `<_GIPCWriter_b413c4 fd: 23>` is now valid in child.
02:54:44,740.7  [19974]_on_sigchld# SIGCHLD watcher callback for 20024 invoked. Exitcode stored: 0
02:54:44,742.7  [19974]close# Invalidating <_GIPCReader_c0ae88 fd: 21> ...
------------------------------ Captured log call -------------------------------
DEBUG    gipc:gipc.py:285 Invoke target `<function signals_test_child_a at 0x00000001108fe980>` in child process.
DEBUG    gipc:gipc.py:463 SIGCHLD watcher for 20024 started.
DEBUG    gipc:gipc.py:303 Invalidate <_GIPCWriter_b413c4 fd: 23> in parent.
DEBUG    gipc:gipc.py:607 Invalidating <_GIPCWriter_b413c4 fd: 23> ...
DEBUG    gipc:gipc.py:478 SIGCHLD watcher callback for 20024 invoked. Exitcode stored: 0
DEBUG    gipc:gipc.py:607 Invalidating <_GIPCReader_c0ae88 fd: 21> ...
===================== 1 failed, 78 passed in 11.90 seconds =====================

Thanks past @jgehrcke for this code comment.

jgehrcke commented 3 years ago

Not seen in a long time.