pytest-dev / pytest-timeout

MIT License
216 stars 64 forks source link

Timeout generates INTERNALERROR #31

Closed pytest-timeout-bot closed 5 years ago

pytest-timeout-bot commented 6 years ago

Original report by Marc Finet (Bitbucket: marcrtone, ).


Hello,

I'm experiencing a weird issue with pytest-timeout on my raspberrypi with raspbian stretch (it's ok on my dev machine also debian stretch, but with older pytest/pytest-timeout)

On my raspberrypi:

platform linux -- Python 3.5.3, pytest-3.6.2, py-1.7.0, pluggy-0.6.0 -- /usr/bin/python3
cachedir: .pytest_cache                                                                                        
rootdir: /var/tmp/tests, inifile: pytest.ini    
plugins: timeout-1.0.0                                                                                              
collected 114 items / 113 deselected                                                                                                   

protocol_test.py::test_status_version                                 
------------------------------------------------------------ live log setup ------------------------------------------------------------
15:51:53.935      protocol.py:267  INFO   FT232: True, HIDAPI: False, SPEED: 50, USE_INT: True
------------------------------------------------------------ live log call -------------------------------------------------------------
15:51:54.053 protocol_test.py:399  INFO   test_status_version()

INTERNALERROR> Traceback (most recent call last):                                                                              
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 178, in wrap_session
INTERNALERROR>     session.exitstatus = doit(config, session) or 0                                                               
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 215, in _main
INTERNALERROR>     config.hook.pytest_runtestloop(session=session)  
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/__init__.py", line 617, in __call__
INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)                 
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/__init__.py", line 222, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)                                              
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/__init__.py", line 216, in <lambda>
INTERNALERROR>     firstresult=hook.spec_opts.get('firstresult'),                                        
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 201, in _multicall
INTERNALERROR>     return outcome.get_result()
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 76, in get_result
INTERNALERROR>     raise ex[1].with_traceback(ex[2])                                                                                    
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 180, in _multicall
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 236, in pytest_runtestloop
INTERNALERROR>     item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/__init__.py", line 617, in __call__
INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/__init__.py", line 222, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/__init__.py", line 216, in <lambda>                           
INTERNALERROR>     firstresult=hook.spec_opts.get('firstresult'),                       
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 201, in _multicall
INTERNALERROR>     return outcome.get_result()          
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 76, in get_result
INTERNALERROR>     raise ex[1].with_traceback(ex[2])                               
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 180, in _multicall
INTERNALERROR>     res = hook_impl.function(*args)                                                   
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 64, in pytest_runtest_protocol
INTERNALERROR>     runtestprotocol(item, nextitem=nextitem)                                   
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 79, in runtestprotocol
INTERNALERROR>     reports.append(call_and_report(item, "call", log))  
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 161, in call_and_report
INTERNALERROR>     report = hook.pytest_runtest_makereport(item=item, call=call)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/__init__.py", line 617, in __call__
INTERNALERROR>     return self._hookexec(self, self._nonwrappers + self._wrappers, kwargs)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/__init__.py", line 222, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/__init__.py", line 216, in <lambda>
INTERNALERROR>     firstresult=hook.spec_opts.get('firstresult'),
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 196, in _multicall
INTERNALERROR>     gen.send(outcome)                                                    
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/skipping.py", line 123, in pytest_runtest_makereport
INTERNALERROR>     rep = outcome.get_result()           
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 76, in get_result
INTERNALERROR>     raise ex[1].with_traceback(ex[2])                               
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 180, in _multicall
INTERNALERROR>     res = hook_impl.function(*args)                                                   
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 328, in pytest_runtest_makereport
INTERNALERROR>     longrepr = item.repr_failure(excinfo)                                      
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/python.py", line 672, in repr_failure
INTERNALERROR>     return self._repr_failure_py(excinfo, style=style)  
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/python.py", line 665, in _repr_failure_py
INTERNALERROR>     return super(FunctionMixin, self)._repr_failure_py(excinfo, style=style)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/nodes.py", line 295, in _repr_failure_py                     
INTERNALERROR>     tbfilter=tbfilter,                                                   
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 472, in getrepr
INTERNALERROR>     return fmt.repr_excinfo(self)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 712, in repr_excinfo
INTERNALERROR>     reprtraceback = self.repr_traceback(excinfo)                                                                        
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 659, in repr_traceback
INTERNALERROR>     reprentry = self.repr_traceback_entry(entry, einfo)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 604, in repr_traceback_entry            
INTERNALERROR>     source = self._getentrysource(entry)                                       
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 527, in _getentrysource                 
INTERNALERROR>     source = entry.getsource(self.astcache)     
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 220, in getsource                                   
INTERNALERROR>     self.lineno, source, astnode=astnode
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/source.py", line 349, in getstatementrange_ast
INTERNALERROR>     start, end = get_statement_startend2(lineno, astnode)                                      
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/source.py", line 326, in get_statement_startend2
INTERNALERROR>     for x in ast.walk(node):                                                            
INTERNALERROR>   File "/usr/lib/python3.5/ast.py", line 216, in walk
INTERNALERROR>     node = todo.popleft()                                                                     
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pytest_timeout.py", line 101, in handler
INTERNALERROR>     timeout_sigalrm(item, timeout)                                                             
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pytest_timeout.py", line 227, in timeout_sigalrm
INTERNALERROR>     pytest.fail('Timeout >%ss' % timeout)                                                     
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/outcomes.py", line 96, in fail
INTERNALERROR>     raise Failed(msg=msg, pytrace=pytrace)                                                     
INTERNALERROR> Failed: Timeout >1s            

==================================================== 113 deselected in 7.75 seconds ====================================================

Same results with pytest-3.10.0 and timeout-1.3.2 (I went to an old setup as my dev machine on which test pass or timeout is correctly handled).

The thread method does not work:

============================================================================================================================== test session starts ==============================================================================================================================
platform linux -- Python 3.5.3, pytest-3.6.2, py-1.7.0, pluggy-0.6.0 -- /usr/bin/python3
cachedir: .pytest_cache
rootdir: /var/tmp/tests, inifile: pytest.ini
plugins: timeout-1.0.0
collected 114 items / 113 deselected                                                                                                                                                                                                                                            

protocol_test.py::test_status_version
-------------------------------------------------------------------------------------------------------------------------------- live log setup ---------------------------------------------------------------------------------------------------------------------------------
15:57:54.376      protocol.py:267  INFO   FT232: True, HIDAPI: False, SPEED: 50, USE_INT: True
--------------------------------------------------------------------------------------------------------------------------------- live log call ---------------------------------------------------------------------------------------------------------------------------------
15:57:54.495 protocol_test.py:399  INFO   test_status_version()
Traceback (most recent call last):
  File "/home/pi/.local/lib/python3.5/site-packages/pytest_timeout.py", line 241, in timeout_timer
    stdout, stderr = capman.suspendcapture(item)
AttributeError: 'CaptureManager' object has no attribute 'suspendcapture'

(and same error with pytest-3.10.0 and timeout-1.3.2)

Notes:

Any help appreciated.

pytest-timeout-bot commented 6 years ago

Original comment by Bruno Oliveira (Bitbucket: nicoddemus, GitHub: nicoddemus).


Thanks for the report!

I've opened https://bitbucket.org/pytest-dev/pytest-timeout/pull-requests/16 with a fix.

pytest-timeout-bot commented 6 years ago

Original comment by Marc Finet (Bitbucket: marcrtone, ).


Thanks for quick action. However:

============================================================================================================================== test session starts ==============================================================================================================================
platform linux -- Python 3.5.3, pytest-3.10.0, py-1.7.0, pluggy-0.8.0 -- /usr/bin/python3
cachedir: .pytest_cache                                                                         
rootdir: /var/tmp/tests, inifile: pytest.ini
plugins: timeout-1.3.2                                                                               
collected 114 items / 113 deselected                                                                                                                                                                                                                                            

protocol_test.py::test_status_version                  
-------------------------------------------------------------------------------------------------------------------------------- live log setup ---------------------------------------------------------------------------------------------------------------------------------
11:26:45.540      protocol.py:267  INFO   FT232: True, HIDAPI: False, SPEED: 50, USE_INT: True
--------------------------------------------------------------------------------------------------------------------------------- live log call ---------------------------------------------------------------------------------------------------------------------------------
11:26:45.655 protocol_test.py:399  INFO   test_status_version()

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Stack of MainThread (1995755536) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  File "/home/pi/.local/bin/pytest", line 11, in <module>
    sys.exit(main())
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/config/__init__.py", line 76, in main
    return config.hook.pytest_cmdline_main(config=config)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/hooks.py", line 284, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 67, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 61, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 218, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 185, in wrap_session
    session.exitstatus = doit(config, session) or 0
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 225, in _main
    config.hook.pytest_runtestloop(session=session)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/hooks.py", line 284, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 67, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 61, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 246, in pytest_runtestloop
    item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/hooks.py", line 284, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 67, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 61, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 77, in pytest_runtest_protocol
    runtestprotocol(item, nextitem=nextitem)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 92, in runtestprotocol
    reports.append(call_and_report(item, "call", log))
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 174, in call_and_report
    report = hook.pytest_runtest_makereport(item=item, call=call)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/hooks.py", line 284, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 67, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 61, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 251, in pytest_runtest_makereport
    longrepr = item.repr_failure(excinfo)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/python.py", line 726, in repr_failure
    return self._repr_failure_py(excinfo, style=style)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/nodes.py", line 393, in _repr_failure_py
    truncate_locals=truncate_locals,
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 513, in getrepr
    return fmt.repr_excinfo(self)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 761, in repr_excinfo
    reprtraceback = self.repr_traceback(excinfo)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 706, in repr_traceback
    reprentry = self.repr_traceback_entry(entry, einfo)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 651, in repr_traceback_entry
    source = self._getentrysource(entry)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 571, in _getentrysource
    source = entry.getsource(self.astcache)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 232, in getsource
    self.lineno, source, astnode=astnode
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/source.py", line 298, in getstatementrange_ast
    start, end = get_statement_startend2(lineno, astnode)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/source.py", line 271, in get_statement_startend2
    for x in ast.walk(node):

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

The calltrace sometimes differ.

pytest-timeout-bot commented 6 years ago

Original comment by Bruno Oliveira (Bitbucket: nicoddemus, GitHub: nicoddemus).


Hmmm indeed I was too quick to mention that my PR fixes your issue, it only addresses this error:

AttributeError: 'CaptureManager' object has no attribute 'suspendcapture'

About the error you posted last, unless I'm missing something it seems the timeout is triggering appropriately (see the +++ Timeout +++ message). If not, what output did you expect?

pytest-timeout-bot commented 5 years ago

Original comment by Marc Finet (Bitbucket: marcrtone, ).


I was not expecting a call trace with none of my code, i.e. the same output as when it times out with the signal method (that I have on my dev machine).

E.g. If I run this simple test:

from time import sleep

import pytest

@pytest.mark.timeout(1, method='signal')
def test_timeout_signal():
    sleep(2)
    pass

I have

============================================================================================================================== test session starts ==============================================================================================================================
platform linux -- Python 3.5.3, pytest-3.10.0, py-1.7.0, pluggy-0.8.0 -- /usr/bin/python3
cachedir: .pytest_cache
rootdir: /var/tmp/tests, inifile: pytest.ini
plugins: timeout-1.3.2
collected 116 items / 115 deselected                                                                                                                                                                                                                                            

test_timeout.py::test_timeout_signal FAILED                                                                                                                                                                                                                               [100%]

=================================================================================================================================== FAILURES ====================================================================================================================================
______________________________________________________________________________________________________________________________ test_timeout_signal ______________________________________________________________________________________________________________________________

    @pytest.mark.timeout(1, method='signal')
    def test_timeout_signal():
>       sleep(2)
E       Failed: Timeout >1.0s

test_timeout.py:23: Failed
=================================================================================================================== 1 failed, 115 deselected in 2.82 seconds ====================================================================================================================

So far, so good,

But, if I have

from time import sleep

import pytest

@pytest.mark.timeout(1, method='thread')
def test_timeout_thread():
    sleep(2)
    pass

It outputs nothing:

pi@raspberrypi:/var/tmp/tests $ ~/.local/bin/pytest -k test_timeout_thread
============================================================================================================================== test session starts ==============================================================================================================================
platform linux -- Python 3.5.3, pytest-3.10.0, py-1.7.0, pluggy-0.8.0 -- /usr/bin/python3
cachedir: .pytest_cache
rootdir: /var/tmp/tests, inifile: pytest.ini
plugins: timeout-1.3.2
collected 116 items / 115 deselected                                                                                                                                                                                                                                            

test_timeout.py::test_timeout_thread pi@raspberrypi:/var/tmp/tests $ echo $?
1

There is no \n at end of the test, my shell prompt is displayed as this

pytest-timeout-bot commented 5 years ago

Original comment by Bruno Oliveira (Bitbucket: nicoddemus, GitHub: nicoddemus).


I see, thanks. Then my proposed PR might fix this, I see the exact same behavior (no output at all when timeout is reached) when using the plugin with pytest 3.10.

Just waiting for an approval from @flub and we can make a new release. :thumbsup:

pytest-timeout-bot commented 5 years ago

Original comment by Marc Finet (Bitbucket: marcrtone, ).


Then my proposed PR might fix this

But I do have your patch and the failure, so to me you patch does not solve this missing output.

And any hint regarding the original problem (i.e. the INTERNALERROR) ?

pytest-timeout-bot commented 5 years ago

Original comment by Bruno Oliveira (Bitbucket: nicoddemus, GitHub: nicoddemus).


But I do have your patch and the failure, so to me you patch does not solve this missing output.

Hmm can you double check that my patch is really applied? Sorry to ask to double-check, is just that your behavior is definitely what I see on windows when using thread time out mode.

And any hint regarding the original problem (i.e. the INTERNALERROR) ?

INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pytest_timeout.py", line 227, in timeout_sigalrm
INTERNALERROR>     pytest.fail('Timeout >%ss' % timeout)                                                     
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/outcomes.py", line 96, in fail
INTERNALERROR>     raise Failed(msg=msg, pytrace=pytrace)                                                     
INTERNALERROR> Failed: Timeout >1s            

It seems that due to changes how pytest handles it, the error raised by pytest-timeout should be:

pytest.fail('Timeout >%ss' % timeout, pytrace=False)                                                     

Instead.

pytest-timeout-bot commented 5 years ago

Original comment by Marc Finet (Bitbucket: marcrtone, ).


My bad, my manual patch was faulty (I didn't find how to get a patch from bitbucket's interface), and I removed the capman.suspend_global_capture(item) line.

I now have:

============================================================================================================================== test session starts ==============================================================================================================================
platform linux -- Python 3.5.3, pytest-3.10.0, py-1.7.0, pluggy-0.8.0 -- /usr/bin/python3
cachedir: .pytest_cache                                                                                
rootdir: /var/tmp/tests, inifile: pytest.ini
plugins: timeout-1.3.2                                                               
collected 22 items / 21 deselected                                                                                                                                                                                                                                              

test_timeout.py::test_timeout_thread                                                                                                                                                                                                                                             
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Stack of MainThread (1995956240) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  File "/home/pi/.local/bin/pytest", line 11, in <module>                                                                                                                   
    sys.exit(main())                                                                                                                                                          
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/config/__init__.py", line 76, in main                                                                    
    return config.hook.pytest_cmdline_main(config=config)                                                                                         
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/hooks.py", line 284, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 67, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 61, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)                             
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 218, in pytest_cmdline_main
    return wrap_session(config, _main)               
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 185, in wrap_session                                                      
    session.exitstatus = doit(config, session) or 0                                                        
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 225, in _main
    config.hook.pytest_runtestloop(session=session)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/hooks.py", line 284, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 67, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 61, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 246, in pytest_runtestloop
    item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/hooks.py", line 284, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 67, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)         
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 61, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 77, in pytest_runtest_protocol
    runtestprotocol(item, nextitem=nextitem)                                                                  
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 92, in runtestprotocol
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 92, in runtestprotocol
    reports.append(call_and_report(item, "call", log))
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 172, in call_and_report
    call = call_runtest_hook(item, when, **kwds)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 196, in call_runtest_hook
    treat_keyboard_interrupt_as_exception=item.config.getvalue("usepdb"),
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 212, in __init__
    self.result = func()
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 194, in <lambda>
    lambda: ihook(item=item, **kwds),
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/hooks.py", line 284, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 67, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 61, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 122, in pytest_runtest_call
    item.runtest()
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/python.py", line 1425, in runtest
    self.ihook.pytest_pyfunc_call(pyfuncitem=self)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/hooks.py", line 284, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 67, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 61, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/pi/.local/lib/python3.5/site-packages/_pytest/python.py", line 166, in pytest_pyfunc_call
    testfunction(**testargs)
  File "/var/tmp/tests/test-timeout/test_timeout.py", line 17, in test_timeout_thread
    sleep(2)

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

Which is far more verbose than the 'signal' version. Is it expected ? I expect also to have the end of pytest: test_timeout.py::test_timeout_signal FAILED

Regarding the 'signal' mode, with your patch (i.e. forcing pytrace to False), it still raises a INTERNALERROR:

[...]
INTERNALERROR>     timeout_sigalrm(item, params.timeout)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pytest_timeout.py", line 313, in timeout_sigalrm
INTERNALERROR>     pytest.fail('Timeout >%ss' % timeout, pytrace=False)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/outcomes.py", line 113, in fail
INTERNALERROR>     raise Failed(msg=msg, pytrace=pytrace)
INTERNALERROR> Failed: Timeout >1.0s
pytest-timeout-bot commented 5 years ago

Original comment by Bruno Oliveira (Bitbucket: nicoddemus, GitHub: nicoddemus).


My bad, my manual patch was faulty

Ahh OK, thanks for confirming it.

Which is far more verbose than the 'signal' version. Is it expected ?

Yes, because using the thread mode the only option to stop the current execution is to dump all threads and killing the process forcibly.

Regarding the 'signal' mode, with your patch (i.e. forcing pytrace to False), it still raises a INTERNALERROR:

Hmm this is interesting. Can you post the full output please?

pytest-timeout-bot commented 5 years ago

Original comment by Marc Finet (Bitbucket: marcrtone, ).


Ok for the 'thread' mode. I would prefer the 'signal' mode then.

For the full trace, it's pretty much the same as the original one (except the pluggy part that has been upgraded from 0.6.0 to 0.8.0)

pi@raspberrypi:/var/tmp/tests $ ~/.local/bin/pytest -k version
============================================================================================================================== test session starts ==============================================================================================================================
platform linux -- Python 3.5.3, pytest-3.10.0, py-1.7.0, pluggy-0.8.0 -- /usr/bin/python3
cachedir: .pytest_cache                                                                                                
rootdir: /var/tmp/tests, inifile: pytest.ini              
plugins: timeout-1.3.2                                                                                           
collected 116 items / 115 deselected                                                                                                                                                                                                                                            

protocol_test.py::test_status_version                                   
-------------------------------------------------------------------------------------------------------------------------------- live log setup ---------------------------------------------------------------------------------------------------------------------------------
16:14:48.636      protocol.py:267  INFO   FT232: True, HIDAPI: False, SPEED: 50, USE_INT: True
--------------------------------------------------------------------------------------------------------------------------------- live log call ---------------------------------------------------------------------------------------------------------------------------------
16:14:48.746 protocol_test.py:399  INFO   test_status_version()

INTERNALERROR> Traceback (most recent call last):                                                         
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 185, in wrap_session
INTERNALERROR>     session.exitstatus = doit(config, session) or 0
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 225, in _main
INTERNALERROR>     config.hook.pytest_runtestloop(session=session)                                                                                                                                                                                                               
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/hooks.py", line 284, in __call__
INTERNALERROR>     return self._hookexec(self, self.get_hookimpls(), kwargs)                     
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 67, in _hookexec
INTERNALERROR>     return self._hookexec(self, self.get_hookimpls(), kwargs)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 67, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 61, in <lambda>
INTERNALERROR>     firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 208, in _multicall
INTERNALERROR>     return outcome.get_result()
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 80, in get_result
INTERNALERROR>     raise ex[1].with_traceback(ex[2])
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 187, in _multicall
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/main.py", line 246, in pytest_runtestloop
INTERNALERROR>     item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/hooks.py", line 284, in __call__
INTERNALERROR>     return self._hookexec(self, self.get_hookimpls(), kwargs)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 67, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 61, in <lambda>
INTERNALERROR>     firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 208, in _multicall
INTERNALERROR>     return outcome.get_result()
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 80, in get_result
INTERNALERROR>     raise ex[1].with_traceback(ex[2])
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 187, in _multicall
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 77, in pytest_runtest_protocol
INTERNALERROR>     runtestprotocol(item, nextitem=nextitem)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 92, in runtestprotocol
INTERNALERROR>     reports.append(call_and_report(item, "call", log))
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 174, in call_and_report
INTERNALERROR>     report = hook.pytest_runtest_makereport(item=item, call=call)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/hooks.py", line 284, in __call__
INTERNALERROR>     return self._hookexec(self, self.get_hookimpls(), kwargs)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 67, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook, methods, kwargs)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/manager.py", line 61, in <lambda>
INTERNALERROR>     firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 203, in _multicall
INTERNALERROR>     gen.send(outcome)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/skipping.py", line 127, in pytest_runtest_makereport
INTERNALERROR>     rep = outcome.get_result()
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 80, in get_result
INTERNALERROR>     raise ex[1].with_traceback(ex[2])
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pluggy/callers.py", line 187, in _multicall
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/runner.py", line 251, in pytest_runtest_makereport
INTERNALERROR>     longrepr = item.repr_failure(excinfo)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/python.py", line 726, in repr_failure
INTERNALERROR>     return self._repr_failure_py(excinfo, style=style)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/nodes.py", line 393, in _repr_failure_py
INTERNALERROR>     truncate_locals=truncate_locals,
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 513, in getrepr
INTERNALERROR>     return fmt.repr_excinfo(self)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 761, in repr_excinfo
INTERNALERROR>     reprtraceback = self.repr_traceback(excinfo)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 706, in repr_traceback
INTERNALERROR>     reprentry = self.repr_traceback_entry(entry, einfo)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 651, in repr_traceback_entry
INTERNALERROR>     source = self._getentrysource(entry)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 571, in _getentrysource
INTERNALERROR>     source = entry.getsource(self.astcache)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/code.py", line 232, in getsource
INTERNALERROR>     self.lineno, source, astnode=astnode
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/source.py", line 298, in getstatementrange_ast
INTERNALERROR>     start, end = get_statement_startend2(lineno, astnode)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/_code/source.py", line 272, in get_statement_startend2
INTERNALERROR>     if isinstance(x, (ast.stmt, ast.ExceptHandler)):
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pytest_timeout.py", line 140, in handler
INTERNALERROR>     timeout_sigalrm(item, params.timeout)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pytest_timeout.py", line 313, in timeout_sigalrm
INTERNALERROR>     pytest.fail('Timeout >%ss' % timeout, pytrace=False)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/outcomes.py", line 113, in fail
INTERNALERROR>     raise Failed(msg=msg, pytrace=pytrace)
INTERNALERROR> Failed: Timeout >1.0s

================================================================================================================== 115 deselected, 1 warnings in 8.19 seconds =================================================================================================================

Note that my dev machine (that does not have problem) does not have pluggy:

Test session starts (platform: linux, Python 3.5.3, pytest 3.6.2, pytest-sugar 0.9.1)
cachedir: .pytest_cache
rootdir: <redacted>, inifile: pytest.ini
plugins: sugar-0.9.1, pylama-7.4.3, timeout-1.0.0
pytest-timeout-bot commented 5 years ago

Original comment by Bruno Oliveira (Bitbucket: nicoddemus, GitHub: nicoddemus).


Thanks for posting.

It seems this INTERNALERROR is just a side effect of how pytest-timeout works: you see, last lines of the traceback are:

INTERNALERROR>     if isinstance(x, (ast.stmt, ast.ExceptHandler)):
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pytest_timeout.py", line 140, in handler
INTERNALERROR>     timeout_sigalrm(item, params.timeout)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/pytest_timeout.py", line 313, in timeout_sigalrm
INTERNALERROR>     pytest.fail('Timeout >%ss' % timeout, pytrace=False)
INTERNALERROR>   File "/home/pi/.local/lib/python3.5/site-packages/_pytest/outcomes.py", line 113, in fail
INTERNALERROR>     raise Failed(msg=msg, pytrace=pytrace)
INTERNALERROR> Failed: Timeout >1.0s

The alarm signal which pytest-timeout schedules to interrupt the current test, is being triggered right in the midle of an isinstance call; IOW, an alarm might happen at any point during pytest execution, it might happen even in a try/except clause for the Failed exception raised by pytest-timeout. What this means is that depending exactly where the signal is triggered, you might see a nice Failed message or an internal error.

@flub please correct me if I'm wrong.

pytest-timeout-bot commented 5 years ago

Original comment by Floris Bruynooghe (Bitbucket: flub, GitHub: flub).


Sounds about right. Interrupting at random times is always going to come with rough edges which is why it should be a last-resort option.