Improve error message in case of failure in test_wait_result

[ogrisel]

Observed when running tox -e py27 on linux:

=================================================================================== FAILURES ===================================================================================
________________________________________________________________________ TestCondition.test_wait_result ________________________________________________________________________

self = <tests.test_synchronize.TestCondition instance at 0x7f754456ea70>

    @pytest.mark.skipif(sys.platform == "win32" and
                        sys.version_info[:2] < (3, 3),
                        reason="Condition.wait always returned None before 3.3"
                        " and we do not overload win32 Condition")
    def test_wait_result(self):
        if sys.platform != 'win32':
            pid = os.getpid()
        else:
            pid = None
    
        c = loky_context.Condition()
        with c:
            assert not c.wait(0)
            assert not c.wait(0.1)
    
            p = loky_context.Process(target=self._test_wait_result,
                                     args=(c, pid))
            p.start()
    
            assert c.wait(10)
            if pid is not None:
                with pytest.raises(KeyboardInterrupt):
                    c.wait(10)
>           p.join()

c          = <Condition(<RLock(None, 0)>, 0)>
p          = <LokyProcess(LokyProcess-423, stopped)>
pid        = 20335
self       = <tests.test_synchronize.TestCondition instance at 0x7f754456ea70>

tests/test_synchronize.py:348: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
loky/backend/synchronize.py:249: in __exit__
    return self._lock.__exit__(*args)
loky/backend/synchronize.py:108: in __exit__
    return self._semlock.release()
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <loky.backend.semlock.SemLock object at 0x7f75490656d0>

    def release(self):
        if self.kind == RECURSIVE_MUTEX:
            assert self._is_mine(), (
>               "attempt to release recursive lock not owned by thread")
E           AssertionError: attempt to release recursive lock not owned by thread

self       = <loky.backend.semlock.SemLock object at 0x7f75490656d0>

loky/backend/semlock.py:193: AssertionError
----------------------------------------------------------------------------- Captured stderr call -----------------------------------------------------------------------------
[DEBUG:MainProcess:MainThread] created semlock with handle 140141780742144 and name "/loky-20335-L08GeF"
[DEBUG:MainProcess:MainThread] created semlock with handle 140141780738048 and name "/loky-20335-CO5Aui"
[DEBUG:MainProcess:MainThread] created semlock with handle 140141780733952 and name "/loky-20335-bGApZz"
[DEBUG:MainProcess:MainThread] created semlock with handle 140141780729856 and name "/loky-20335-0LIgU2"
[DEBUG:MainProcess:MainThread] launch python with cmd:
['/home/ogrisel/code/loky/.tox/py27/bin/python2.7', '-m', 'loky.backend.popen_loky_posix', '--name-process', 'LokyProcess-423', '--pipe', '19', '--semaphore', '12']
[DEBUG:LokyProcess-423:MainThread] recreated blocker with handle 140141780742144 and name "/loky-20335-L08GeF"
[DEBUG:LokyProcess-423:MainThread] recreated blocker with handle 140141780738048 and name "/loky-20335-CO5Aui"
[DEBUG:LokyProcess-423:MainThread] recreated blocker with handle 140141780733952 and name "/loky-20335-bGApZz"
[DEBUG:LokyProcess-423:MainThread] recreated blocker with handle 140141780729856 and name "/loky-20335-0LIgU2"
[INFO:LokyProcess-423:MainThread] child process calling self.run()
[INFO:LokyProcess-423:MainThread] process shutting down
[DEBUG:LokyProcess-423:MainThread] running all "atexit" finalizers with priority >= 0
[DEBUG:LokyProcess-423:MainThread] running the remaining "atexit" finalizers
[INFO:LokyProcess-423:MainThread] process exiting with exitcode 0
[INFO:LokyProcess-423:Dummy-1] process shutting down
[DEBUG:LokyProcess-423:Dummy-1] running all "atexit" finalizers with priority >= 0
[DEBUG:LokyProcess-423:Dummy-1] running the remaining "atexit" finalizers
========================================================= 1 failed, 132 passed, 5 skipped, 1 xpassed in 67.89 seconds ==========================================================
ERROR: InvocationError: '/home/ogrisel/code/loky/.tox/py27/bin/py.test -lv --maxfail=2 --timeout=10'

[ogrisel]

To make it easier to debug we could report the thread ident and names in the assertion error message.

[tomMoral]

We could but when this appears in the test report, this is from the MainThread. Here we seems to have an issue on a lock which is not safe. I will investigate when I get more time.

[ogrisel]

I mean report the ids and names of both threads: the one that owns the SemLock instead and the one trying to release it.

[tomMoral]

I see. That was something I wanted to do for a long time as this will also permits to improve debugging of deadlocks. So I think it would be a really good addition. I will give it a shot asap.

IMO, the main issue is that most of the time, it is another process which holds the lock and thus, we cannot access the current owner.

[ogrisel]

I haven't seen this in a while but I still think it would be interesting to improve the assertion error message to be more informative.