debugowanie w Pythonie: Pokazują ostatni N wykonywane linie

Question

chciałbym zobaczyć ostatnie 10 wierszy, które zostały wykonane przez interpreter Pythona zanim ten wyjątek wystąpił:

test_has_perm_in_foobar.py F 
Traceback (most recent call last): 
    File "/.../test_has_perm_in_foobar.py", line 50, in test_has_perm 
    self.assertFalse(check_perm(request, some_object)) 
    File "/usr/lib/python2.7/unittest/case.py", line 416, in assertFalse 
    raise self.failureException(msg) 
AssertionError: True is not false 

Chcę zobaczyć, gdzie check_perm() powrócił True.

Wiem, że mogę użyć interaktywnego debugowania, aby znaleźć pasującą linię, ale jestem leniwy i chcę znaleźć prostszą drogę do linii, gdzie check_perm() zwrócił wartość zwracaną.

Używam pyCharm, ale narzędzie tekstowe, również rozwiąże moje potrzeby.

BTW: Proszę nie mówić mi, jak używać debuggera z krok po kroku i krokiem. Wiem to.

Oto kod do zilustrowania tego.

def check_perm(request, some_object): 
    if condition_1: 
     return True 
    if condition_2: 
     return sub_check(some_object) 
    if condition_3: 
     return sub_check2(some_object) 
    ... 

Istnieje kilka sposobów, gdzie check_perm() mógł wrócić True. Jeśli True został zwrócony z powodu warunek_1, to chcę zobaczyć coś takiego

+   if condition_1: 
+   return True 

Wyjście Mam na myśli jak set -x na powłoce.

Aktualizacja

cgitb, pytest i innych narzędzi może pokazać linie przed linią gdzie twierdzenie nie powiodło się. ALE, pokazują tylko linie bieżącego pliku Pythona. To pytanie dotyczy linii, które zostały wykonane przed stwierdzeniem, ale obejmuje wszystkie pliki. W moim przypadku chcę wiedzieć, gdzie została utworzona wartość zwracana check_perm(). Narzędzia pytest, cgitb, ... nie pokazują tego.

Co szukam jest jak set -x na powłokę:

pomaga ustawić

-x polecenia drukowania i ich argumenty są one wykonywane.

Answer 1

Ponieważ nie mogłem znaleźć rozwiązanie, to pisałem sobie:

with trace_function_calls():  
    self.assertFalse(check_perm(request, some_object)) 

Realizacja trace_function_calls():

class trace_function_calls(object): 
    depth_symbol = '+' 

    def __init__(self, write_method=None, log_lines=True): 
     ''' 
     write_method: A method which gets called for every executed line. Defauls to logger.info 

     # Simple example: 

     with debugutils.trace_function_calls(): 
      method_you_want_to_trace() 
     ''' 
     if write_method is None: 
      write_method=logger.info 
     self.write_method = write_method 
     self.log_lines = log_lines 

    def __enter__(self): 
     self.old = sys.gettrace() 
     self.depth = 0 
     sys.settrace(self.trace_callback) 

    def __exit__(self, type, value, traceback): 
     sys.settrace(self.old) 

    def trace_callback(self, frame, event, arg): 
     # from http://pymotw.com/2/sys/tracing.html#tracing-function-calls 
     if event == 'return': 
      self.depth -= 1 
      return self.trace_callback 

     if event == 'line': 
      if not self.log_lines: 
       return self.trace_callback 
     elif event == 'call': 
      self.depth += 1 
     else: 
      # self.write_method('unknown: %s' % event) 
      return self.trace_callback 

     msg = [] 
     msg.append(self.depth_symbol * self.depth) 

     co = frame.f_code 
     func_name = co.co_name 
     func_line_no = frame.f_lineno 

     func_filename = co.co_filename 
     if not is_python_file_from_my_codebase(func_filename): 
      return self.trace_callback 
     code_line = linecache.getline(func_filename, func_line_no).rstrip() 
     msg.append('%s: %s %r on line %s of %s' % (
      event, func_name, code_line, func_line_no, func_filename)) 
     self.write_method(' '.join(msg)) 
     return self.trace_callback 

PS : To jest oprogramowanie typu open source. Jeśli chcesz stworzyć pakiet Pythona, zrób to, powiedz mi, to by mnie ucieszyło.

Answer 2

Co z numerem cgitb? Musisz tylko zaimportować ten moduł do swojego kodu.

import cgitb 
cgitb.enable(format='text') 

def f(): 
    a = 1 
    b = 2 
    c = 3 
    x = 0 
    d = a * b * c/x 
    return d 

if __name__ == "__main__": 
    f() 

Daje:

ZeroDivisionError 
Python 3.5.2: /usr/bin/python3 
Mon Dec 19 17:42:34 2016 

A problem occurred in a Python script. Here is the sequence of 
function calls leading up to the error, in the order they occurred. 
/home/user1/123.py in <module>() 
    10  d = a * b * c/x 
    11  return x 
    12 
    13 if __name__ == "__main__": 
    14  f() 
f = <function f> 
/home/user1/123.py in f() 
    8  c = 3 
    9  x = 0 
    10  d = a * b * c/x 
    11  return x 
    12 
d undefined 
a = 1 
b = 2 
c = 3 
x = 0 
ZeroDivisionError: division by zero 
... 
The above is a description of an error in a Python program. Here is 
the original traceback: 

Traceback (most recent call last): 
    File "123.py", line 14, in <module> 
    f() 
    File "123.py", line 10, in f 
    d = a * b * c/x 
ZeroDivisionError: division by zero 

Answer 3

Z tego powodu przełączyłem test na pytest.

Może wyświetlać zmienne lokalne i śledzenie z różnymi poziomami detekcji. Linia, w której wykonano połączenie, jest oznaczona numerem >.

Na przykład w moim projekcie django:

$ py.test --showlocals --tb=long 
=============================== test session starts =============================== 
platform darwin -- Python 3.5.1, pytest-3.0.3, py-1.4.31, pluggy-0.4.0 
Django settings: dj_tg_bot.settings (from ini file) 
rootdir: /Users/el/Projects/dj-tg-alpha-bot, inifile: tox.ini 
plugins: django-3.0.0, cov-2.4.0 
collected 8 items 

tests/test_commands.py ....F 
tests/test_logger.py . 
tests/test_simple.py .. 

==================================== FAILURES ===================================== 
__________________________ TestSimpleCommands.test_start __________________________ 

self = <tests.test_commands.TestSimpleCommands testMethod=test_start> 

    def test_start(self,): 
     """ 
      Test bot accept normally command /start and replies as it should. 
      """ 
>  self._test_message_ok(self.start) 

self  = <tests.test_commands.TestSimpleCommands testMethod=test_start> 

tests/test_commands.py:56: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <tests.test_commands.TestSimpleCommands testMethod=test_start> 
action = {'in': ' /start', 'out': {'parse_mode': 'Markdown', 'reply_markup': '', 'text': 'Welcome'}} 
update = <telegram.update.Update object at 0x113e16cf8>, number = 1 

    def _test_message_ok(self, action, update=None, number=1): 
     if not update: 
      update = self.update 
     with mock.patch("telegram.bot.Bot.sendMessage", callable=mock.MagicMock()) as mock_send: 
      if 'in' in action: 
       update.message.text = action['in'] 
      response = self.client.post(self.webhook_url, update.to_json(), **self.kwargs) 
      # Check response 200 OK 
      self.assertEqual(response.status_code, status.HTTP_200_OK) 
      # Check 
>   self.assertBotResponse(mock_send, action) 

action  = {'in': ' /start', 'out': {'parse_mode': 'Markdown', 'reply_markup': '', 'text': 'Welcome'}} 
mock_send = <MagicMock name='sendMessage' id='4619939344'> 
number  = 1 
response = <Response status_code=200, "application/json"> 
self  = <tests.test_commands.TestSimpleCommands testMethod=test_start> 
update  = <telegram.update.Update object at 0x113e16cf8> 

../../.pyenv/versions/3.5.1/lib/python3.5/site-packages/telegrambot/test/testcases.py:83: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <tests.test_commands.TestSimpleCommands testMethod=test_start> 
mock_send = <MagicMock name='sendMessage' id='4619939344'> 
command = {'in': ' /start', 'out': {'parse_mode': 'Markdown', 'reply_markup': '', 'text': 'Welcome'}} 

    def assertBotResponse(self, mock_send, command): 
>  args, kwargs = mock_send.call_args 
E  TypeError: 'NoneType' object is not iterable 

command = {'in': ' /start', 'out': {'parse_mode': 'Markdown', 'reply_markup': '', 'text': 'Welcome'}} 
mock_send = <MagicMock name='sendMessage' id='4619939344'> 
self  = <tests.test_commands.TestSimpleCommands testMethod=test_start> 

../../.pyenv/versions/3.5.1/lib/python3.5/site-packages/telegrambot/test/testcases.py:61: TypeError 
------------------------------ Captured stderr call ------------------------------- 
Handler not found for {'message': {'from': {'username': 'username_4', 'last_name': 'last_name_4', 'id': 5, 'first_name': 'first_name_4'}, 'chat': {'username': 'username_4', 'last_name': 'last_name_4', 'first_name': 'first_name_4', 'title': 'title_4', 'type': 'private', 'id': 5}, 'text': ' /start', 'message_id': 5, 'date': 1482500826}, 'update_id': 5} 
======================= 1 failed, 7 passed in 2.29 seconds ======================== 
(.env) ✘-1 ~/Projects/dj-tg-alpha-bot [master|✚ 1…8⚑ 12] 
16:47 $ 

Answer 4

Moduł trace ma Bourne Shell zgodny set -x jak funkcji. Parametr trace klasy trace.Trace włącza śledzenie wykonywania linii. Ta klasa pobiera parametr , który jest używany do ignorowania śledzenia modułów lub pakietów znajdujących się pod określonym katalogiem. Używam go tutaj, aby śledzący nie mógł śledzić modułu unittest.

test_has_perm_in_foobar.py

import sys 
import trace 
import unittest 

from app import check_perm 

tracer = trace.Trace(trace=1, ignoredirs=(sys.prefix, sys.exec_prefix)) 

class Test(unittest.TestCase): 
    def test_one(self): 
     tracer.runctx('self.assertFalse(check_perm("dummy", 3))', globals(), locals()) 

if __name__ == '__main__': 
    unittest.main() 

app.py

def sub_check1(some_object): 
    if some_object * 10 == 20: 
     return True 

def sub_check2(some_object): 
    if some_object * 10 == 30: 
     return True 

def check_perm(request, some_object): 
    if some_object == 1: 
     return True 
    if some_object == 2: 
     return sub_check1(some_object) 
    if some_object == 3: 
     return sub_check2(some_object) 

testu;

$ python test_has_perm_in_foobar.py 
--- modulename: test_has_perm_in_foobar, funcname: <module> 
<string>(1): --- modulename: app, funcname: check_perm 
app.py(10):  if some_object == 1: 
app.py(12):  if some_object == 2: 
app.py(14):  if some_object == 3: 
app.py(15):   return sub_check2(some_object) 
--- modulename: app, funcname: sub_check2 
app.py(6):  if some_object * 10 == 30: 
app.py(7):   return True 
F 
====================================================================== 
FAIL: test_one (__main__.Test) 
---------------------------------------------------------------------- 
Traceback (most recent call last): 
    File "test_has_perm_in_foobar.py", line 23, in test_one 
    tracer.runctx('self.assertFalse(check_perm("dummy", 3))', globals(), locals()) 
    File "/usr/lib/python2.7/trace.py", line 513, in runctx 
    exec cmd in globals, locals 
    File "<string>", line 1, in <module> 
AssertionError: True is not false 

---------------------------------------------------------------------- 
Ran 1 test in 0.006s 

FAILED (failures=1) 

Aby kod i dane wyjściowe były jeszcze krótsze, wystarczy śledzić samą wymaganą funkcję.

import trace 
import unittest 

from app import check_perm 

tracer = trace.Trace(trace=1) 

class Test(unittest.TestCase): 
    def test_one(self): 
     self.assertFalse(tracer.runfunc(check_perm, 'dummy', 3)) 

if __name__ == '__main__': 
    unittest.main() 

Test;

$ python test_has_perm_in_foobar.py 
--- modulename: app, funcname: check_perm 
app.py(10):  if some_object == 1: 
app.py(12):  if some_object == 2: 
app.py(14):  if some_object == 3: 
app.py(15):   return sub_check2(some_object) 
--- modulename: app, funcname: sub_check2 
app.py(6):  if some_object * 10 == 30: 
app.py(7):   return True 
F 
====================================================================== 
FAIL: test_one (__main__.Test) 
---------------------------------------------------------------------- 
Traceback (most recent call last): 
    File "test_has_perm_in_foobar.py", line 19, in test_one 
    self.assertFalse(tracer.runfunc(check_perm, 'dummy', 3)) 
AssertionError: True is not false 

---------------------------------------------------------------------- 
Ran 1 test in 0.005s 

FAILED (failures=1) 

Answer 5

Czy rozważałeś następujący przepływ pracy? Czytam twoje BTW, ale twarde reguły czasami powstrzymują nas od rozwiązania naszych problemów (szczególnie jeśli jesteś w pułapce XY), więc zamierzam zaproponować ci użycie debuggera. Wpadam na testy, które zawodzą przez cały czas. Gdy śledzenie całego stosu ma kluczowe znaczenie dla rozwiązania problemu, używam kombinacji pdb i py.test, aby uzyskać cały shebang. Biorąc pod uwagę następujący program ...

import pytest 

@pytest.mark.A 
def test_add(): 

    a = 1 
    b = 2 

    add(a,b) 

def add(a, b): 
    assert a>b 

    return a+b 

def main(): 
    add(1,2) 
    add(2,1) 

if __name__ == "__main__": 
    # execute only if run as a script 
    main() 

uruchamiając komendę py.test -v -tb=short -m A code.py wyniki w następujący wynik ...

art@macky ~/src/python/so-answer-stacktrace: py.test -v --tb=short -m A code.py 
============================= test session starts ============================== 
platform darwin -- Python 2.7.5 -- pytest-2.5.0 -- /Users/art/.pyenv/versions/2.7.5/bin/python 
collected 1 items 

code.py:3: test_add FAILED 

=================================== FAILURES =================================== 
___________________________________ test_add ___________________________________ 
code.py:9: in test_add 
>  add(a,b) 
code.py:12: in add 
>  assert a>b 
E  assert 1 > 2 
=========================== 1 failed in 0.01 seconds =========================== 

jeden prosty sposób, aby zbadać ślad stosu jest spadek punkt pdb debugowania w test, Mark indywidualny test ze znakiem pytest, wywołaj ten test i sprawdź stos wewnątrz debuggera. jak tak ...

def add(a, b): 
    from pdb import set_trace;set_trace() 
    assert a>b 

    return a+b 

Teraz, kiedy ponownie uruchomić tego samego polecenia testową dostaję zawieszony pdb debugger. Podobnie jak ...

art@macky ~/src/python/so-answer-stacktrace: py.test -v --tb=short -m A code.py 
=========================================================================================== test session starts ============================================================================================ 
platform darwin -- Python 2.7.5 -- pytest-2.5.0 -- /Users/art/.pyenv/versions/2.7.5/bin/python 
collected 1 items 

code.py:3: test_add 
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> PDB set_trace (IO-capturing turned off) >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> 
> /Users/art/src/python/so-answer-stacktrace/code.py(13)add() 
-> assert a>b 
(Pdb) 

Jeśli w tym momencie mam wpisać magiczne w dla where i uderzył enter widzę pełną ślad stosu w całej okazałości ...

(Pdb) w 
    /Users/art/.pyenv/versions/2.7.5/bin/py.test(9)<module>() 
-> load_entry_point('pytest==2.5.0', 'console_scripts', 'py.test')() 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/config.py(19)main() 
-> return config.hook.pytest_cmdline_main(config=config) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(376)__call__() 
-> return self._docall(methods, kwargs) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(387)_docall() 
-> res = mc.execute() 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(288)execute() 
-> res = method(**kwargs) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/main.py(111)pytest_cmdline_main() 
-> return wrap_session(config, _main) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/main.py(81)wrap_session() 
-> doit(config, session) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/main.py(117)_main() 
-> config.hook.pytest_runtestloop(session=session) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(376)__call__() 
-> return self._docall(methods, kwargs) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(387)_docall() 
-> res = mc.execute() 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(288)execute() 
-> res = method(**kwargs) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/main.py(137)pytest_runtestloop() 
-> item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(376)__call__() 
-> return self._docall(methods, kwargs) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(387)_docall() 
-> res = mc.execute() 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(288)execute() 
-> res = method(**kwargs) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/runner.py(62)pytest_runtest_protocol() 
-> runtestprotocol(item, nextitem=nextitem) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/runner.py(72)runtestprotocol() 
-> reports.append(call_and_report(item, "call", log)) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/runner.py(106)call_and_report() 
-> call = call_runtest_hook(item, when, **kwds) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/runner.py(124)call_runtest_hook() 
-> return CallInfo(lambda: ihook(item=item, **kwds), when=when) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/runner.py(137)__init__() 
-> self.result = func() 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/runner.py(124)<lambda>() 
-> return CallInfo(lambda: ihook(item=item, **kwds), when=when) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/main.py(161)call_matching_hooks() 
-> return hookmethod.pcall(plugins, **kwargs) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(380)pcall() 
-> return self._docall(methods, kwargs) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(387)_docall() 
-> res = mc.execute() 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(288)execute() 
-> res = method(**kwargs) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/runner.py(86)pytest_runtest_call() 
-> item.runtest() 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/python.py(1076)runtest() 
-> self.ihook.pytest_pyfunc_call(pyfuncitem=self) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/main.py(161)call_matching_hooks() 
-> return hookmethod.pcall(plugins, **kwargs) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(380)pcall() 
-> return self._docall(methods, kwargs) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(387)_docall() 
-> res = mc.execute() 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/core.py(288)execute() 
-> res = method(**kwargs) 
    /Users/art/.pyenv/versions/2.7.5/lib/python2.7/site-packages/pytest-2.5.0-py2.7.egg/_pytest/python.py(188)pytest_pyfunc_call() 
-> testfunction(**testargs) 
    /Users/art/src/python/so-answer-stacktrace/code.py(9)test_add() 
-> add(a,b) 
> /Users/art/src/python/so-answer-stacktrace/code.py(13)add() 
-> assert a>b 
(Pdb) 

zrobić wiele pracy w frameworkach. pdb + where daje wszystko, aż do faktycznego punktu wejścia programu. Widać tam pochowane moje funkcje, a także ramy biegacza testowego. Gdyby to było Django lub Flask, zobaczyłbym wszystkie ramki stosów związane z wewnętrznymi strukturami.Jest to moja przerwa dla wszystkich, gdy wszystko idzie naprawdę źle.

Jeśli masz test z dużą ilością powtórzeń lub warunków, możesz odwieszać się od nowa na tych samych liniach. Rozwiązaniem jest sprytne podejście do wyboru instrumentu przy pomocy pdb. Zagnieżdżanie go w warunkowej lub instrumentacyjnej iteracji/rekurencji z warunkiem (zasadniczo mówiąc: Kiedy to staje się True, następnie zawiesić, aby sprawdzić, co się dzieje). Ponadto, pdb pozwala spojrzeć na cały kontekst środowiska wykonawczego (przypisania, stan itp.).

Dla twojego przypadku wygląda na to, że porządkowa oprzyrządowanie check_perm jest w porządku.