Signals sometimes get lost

[pbrady]

The timeout signal raised during the long running test_wester tests in sympy seem to get lost.

• Pure python cache - signal handled appropriately every time

 $ bin/test sympy/core/tests/test_wester.py --slow --timeout 30 --rerun 10 -k test_W25
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/envs/py27/bin/python  (2.7.8-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        19896835
hash randomization: on (PYTHONHASHSEED=1541313885)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.19 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/envs/py27/bin/python  (2.7.8-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        73556722
hash randomization: on (PYTHONHASHSEED=2050004862)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.16 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/envs/py27/bin/python  (2.7.8-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        26462863
hash randomization: on (PYTHONHASHSEED=3857145256)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.16 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/envs/py27/bin/python  (2.7.8-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        34275668
hash randomization: on (PYTHONHASHSEED=881433688)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.18 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/envs/py27/bin/python  (2.7.8-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        96870713
hash randomization: on (PYTHONHASHSEED=2112371590)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.16 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/envs/py27/bin/python  (2.7.8-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        79399543
hash randomization: on (PYTHONHASHSEED=3148928932)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.16 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/envs/py27/bin/python  (2.7.8-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        79708067
hash randomization: on (PYTHONHASHSEED=1148676525)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.16 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/envs/py27/bin/python  (2.7.8-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        82605636
hash randomization: on (PYTHONHASHSEED=87545409)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.16 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/envs/py27/bin/python  (2.7.8-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        63111394
hash randomization: on (PYTHONHASHSEED=1889469761)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.16 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/envs/py27/bin/python  (2.7.8-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        82749091
hash randomization: on (PYTHONHASHSEED=351423868)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.16 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/envs/py27/bin/python  (2.7.8-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        63640978
hash randomization: on (PYTHONHASHSEED=531375902)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.16 seconds =============

• fastcache with timeout=180

test('sympy/core/tests/test_wester.py', verbose=True, slow=True, timeout=180, kw='test_W25', rerun=10)
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/bin/python3  (3.4.1-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        26510469
hash randomization: on (PYTHONHASHSEED=2396247365)

sympy/core/tests/test_wester.py[1] 
test_W25 T - Timeout                                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 180.28 seconds ============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/bin/python3  (3.4.1-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        61102789
hash randomization: on (PYTHONHASHSEED=417119396)

sympy/core/tests/test_wester.py[1] 
test_W25 T - Timeout                                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 180.24 seconds ============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/bin/python3  (3.4.1-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        35622910
hash randomization: on (PYTHONHASHSEED=2146397325)

sympy/core/tests/test_wester.py[1] 
test_W25 T - Timeout                                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 180.24 seconds ============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/bin/python3  (3.4.1-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        43697130
hash randomization: on (PYTHONHASHSEED=1859372131)

sympy/core/tests/test_wester.py[1] 
test_W25 T - Timeout                                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 180.25 seconds ============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/bin/python3  (3.4.1-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        92941575
hash randomization: on (PYTHONHASHSEED=3865564759)

sympy/core/tests/test_wester.py[1] 
test_W25 f                                                                  [OK]

======= tests finished: 0 passed, 1 expected to fail, in 1044.78 seconds =======

• fastcache with timeout = 30

bin/test sympy/core/tests/test_wester.py --slow --timeout 30 --rerun 10 -k test_W25
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/bin/python  (3.4.1-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        44345956
hash randomization: on (PYTHONHASHSEED=203139206)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.24 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/bin/python  (3.4.1-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        90160511
hash randomization: on (PYTHONHASHSEED=3532862812)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.24 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/bin/python  (3.4.1-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        59158191
hash randomization: on (PYTHONHASHSEED=3762354216)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.25 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/bin/python  (3.4.1-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        71192828
hash randomization: on (PYTHONHASHSEED=561917225)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.24 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/bin/python  (3.4.1-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        22436026
hash randomization: on (PYTHONHASHSEED=2964106396)

sympy/core/tests/test_wester.py[1] T                                        [OK]

============ tests finished: 0 passed, 1 skipped, in 30.24 seconds =============
============================= test process starts ==============================
executable:         /home/ptb/miniconda3/bin/python  (3.4.1-final-0) [CPython]
architecture:       64-bit
cache:              yes
ground types:       python 
random seed:        81004478
hash randomization: on (PYTHONHASHSEED=3399921698)

sympy/core/tests/test_wester.py[1] f                                        [OK]

======= tests finished: 0 passed, 1 expected to fail, in 1423.16 seconds =======

[certik]

Interesting. How can they get lost?

[pbrady]

No Idea. http://stackoverflow.com/questions/25874823/pyerr-checksignals-not-picking-up-signal.

Hopefully someone knows. The alternative will be to increase the splits and not use fastcache for the slow tests.

[asmeurer]

Signals mess with C library functions. See for instance https://github.com/joerick/pyinstrument/issues/16#issuecomment-47174190 (I don't know of a better resource for this now).

[pbrady]

@certik and I talked it through and I think the problem was that I wasn't checking the return value for every call into the Python-C-API (i.e. I knew my argument was hashable so I didn't check the return value of PyDict_SetItem). However, these calls passed control back to the interpreter which would have caught the signal and turned it into an exception via the callback. Thus no call into the Python-C-api is safe! Tricky. I'm testing out patches at the moment.

[pbrady]

Looks like there are still timeout errors even without fastcache https://travis-ci.org/sympy/sympy/jobs/36210280. Maybe this is actually fixed and travis doesn't do timeouts well

[certik]

Exactly I think that the gmpy module might be swallowing signals just like yours did.

[certik]

Actually, that particular failure doesn't use gmpy. Hm.

[pbrady]

I'm tempted to just blame travis. I wonder if others have this issue with signals and travis?

[asmeurer]

I don't know about signals, but Travis does seem to have issues with timeouts sometimes, because the virtual machines can be slow.

[pbrady]

But this particular timeout is the No output for 10 minutes kind when the slow tests have a default timeout of 180s. It could just be a fluke but it's something to watch. It looks like one can avoid using signals but it's tricky to get right http://eli.thegreenplace.net/2011/08/22/how-not-to-set-a-timeout-on-a-computation-in-python

[asmeurer]

Oh that has definitely been happening long before we used fastcache. I at some point disabled the slow tests because of it.

[pbrady]

Ah. I'll probably try to do some more involve testing on my local machine then and just ignore whatever happens on travis.