stackprinter
stackprinter copied to clipboard
cknd
Stackprinter shows full log for suppressed_paths
In my application stackprinter ignores the passed in supressed_paths and I am not sure why (this has already worked and I am not sure what changed).
I can't seem to create a short snippet which reproduces the error but in my application it fails every time.
This is the function where I get the traceback.
If I set a break point with the debugger I see that suppressed_paths is indeed properly populated. However if I inspect the returned lines I see the traceback with the included library files.
I have created a testcase for pytest which fails every time.
Excerpt from github actions (just open the tox part in line 12)
ERROR WrapperTest:wrapper.py:179 File "/opt/hostedtoolcache/Python/3.9.0/x64/lib/python3.9/asyncio/base_events.py", line 1056, in create_connection
ERROR WrapperTest:wrapper.py:179 967 async def create_connection(
ERROR WrapperTest:wrapper.py:179 968 self, protocol_factory, host=None, port=None,
ERROR WrapperTest:wrapper.py:179 969 *, ssl=None, family=0,
ERROR WrapperTest:wrapper.py:179 970 proto=0, flags=0, sock=None,
from pathlib import Path
import aiohttp, typing
import asyncio
import re
import stackprinter
SUPPRESSED_PATHS = (
re.compile(f'[/\\\\]{Path(__file__).name}$'), # this file
# rule file loader
re.compile(r'[/\\]rule_file.py$'),
re.compile(r'[/\\]runpy.py$'),
# Worker functions
re.compile(r'[/\\]wrappedfunction.py$'),
# Don't print stack for used libraries
re.compile(r'[/\\](site-packages|lib)[/\\]asyncio[/\\]'),
re.compile(r'[/\\]site-packages[/\\]aiohttp[/\\]'),
re.compile(r'[/\\]site-packages[/\\]voluptuous[/\\]'),
re.compile(r'[/\\]site-packages[/\\]pydantic[/\\]'),
)
SKIP_TB = tuple(re.compile(k.pattern.replace('$', ', ')) for k in SUPPRESSED_PATHS)
def format_exception(e: typing.Union[Exception, typing.Tuple[typing.Any, typing.Any, typing.Any]]) -> typing.List[str]:
tb = []
skip = 0
lines = stackprinter.format(e, line_wrap=0, truncate_vals=2000, suppressed_paths=SUPPRESSED_PATHS).splitlines()
for i, line in enumerate(lines):
if not skip:
for s in SKIP_TB:
if s.search(line):
# if it's just a two line traceback we skip it
if lines[i + 1].startswith(' ') and lines[i + 2].startswith('File'):
skip = 2
continue
if skip:
skip -= 1
continue
tb.append(line)
return tb
class PrintException:
def __enter__(self):
pass
def __exit__(self, exc_type, exc_val, exc_tb):
# no exception -> we exit gracefully
if exc_type is None and exc_val is None:
return True
for l in format_exception((exc_type, exc_val, exc_tb)):
print(l)
return True
def test_run():
async def test():
async with aiohttp.ClientSession(timeout=aiohttp.ClientTimeout(0.01)) as session:
async with session.get('http://localhost:12345') as resp:
pass
with PrintException():
asyncio.get_event_loop().run_until_complete(test())
Do you have any idea what the issue might be?
It would be really nice if you could check out the dev branch and run pytest on the test_wrapper.py file.
The tests need the following libraries additionally to the ones in requirements.txt:
pytest pytest-asyncio asynctest
The regex looks wrong to me
import re
pattern = re.compile(r'[/\\](site-packages|lib)[/\\]asyncio[/\\]')
filename = "/opt/hostedtoolcache/Python/3.9.0/x64/lib/python3.9/asyncio/base_events.py"
print(pattern.match(filename)) # None
You are indeed correct but I copied the wrong part of the log
ERROR WrapperTest:wrapper.py:179 File "/home/runner/work/HABApp/HABApp/.tox/py39/lib/python3.9/site-packages/aiohttp/client.py", line 1117, in __aenter__
ERROR WrapperTest:wrapper.py:179 1116 async def __aenter__(self) -> _RetType:
ERROR WrapperTest:wrapper.py:179 --> 1117 self._resp = await self._coro
ERROR WrapperTest:wrapper.py:179 ..................................................
ERROR WrapperTest:wrapper.py:179 self = <aiohttp.client._RequestContextManager object at 0x7fbbec836f80>
ERROR WrapperTest:wrapper.py:179 _RetType = ~_RetType
ERROR WrapperTest:wrapper.py:179 self._resp = # AttributeError
ERROR WrapperTest:wrapper.py:179 self = <aiohttp.client._RequestContextManager object at 0x7fbbec836f80>
ERROR WrapperTest:wrapper.py:179 self._coro = <coroutine object ClientSession._request at 0x7fbbec6f67c0>
ERROR WrapperTest:wrapper.py:179 ..................................................
It is re.search instead of match so my regex is correct (in this case):
import re
pattern = re.compile(r'[/\\]site-packages[/\\]aiohttp[/\\]')
filename = "/home/runner/work/HABApp/HABApp/.tox/py39/lib/python3.9/site-packages/aiohttp/client.py"
print(pattern.search(filename)) # <re.Match object; span=(55, 78), match='/site-packages/aiohttp/'>
Hey! I want to help, so I just cloned your repo to run the test case - I didn't immediately succeed though: I'm on your Develop branch, in a fresh virtualenv with the requirements.txt installed, and ran pytest -k test_exception_format, but this failed during test collection
================================================================================================== ERRORS ==================================================================================================
____________________________________________________________________________ ERROR collecting conf_testing/rules/test_habapp.py ____________________________________________________________________________
conf_testing/rules/test_habapp.py:60: in <module>
TestItemEvents()
conf_testing/rules/test_habapp.py:11: in __init__
super().__init__()
conf_testing/lib/HABAppTests/test_base.py:60: in __init__
super().__init__()
HABApp/rule/rule.py:43: in __init__
__vars = sys._getframe(depth).f_globals
E ValueError: call stack is not deep enough
So I can't reproduce the error, and don't know how to help..
👉 Here is an alternative suggestion, let's flip this around: Can you put some debug prints inside stackprinter itself and rerun the test on your end? Meaning, you'd uninstall stackprinter from the python environment that runs your app and reinstall it there as an editable package (pip install -e path/to/the/stackprinter-git-repo), and edit formatting.py Line 77 and/or the match function, setting a pdb.set_trace() there or printing all the values. Maybe that brings us closer to a minimal test case
Hey! I want to help, so I just cloned your repo to run the test case - I didn't immediately succeed though: I'm on your Develop branch, in a fresh virtualenv with the requirements.txt installed, and ran pytest -k test_exception_format, but this failed during test collection
Thank you for your help and sorry - I should have provided more information! You have to run the pytest from the /tests folder in the repository, otherwise conf_testing gets picked up which are runtime tests for the application. Or just add conf_testing to the ignored folders by adding --ignore=conf_testing
But actually I created test_exception_format under /tests/test_core/test_wrapper.py so it would be enough if you just run this one test case. I removed all other things from the file so here is the code for a minimal test case that fails reproducably:
import asyncio
import logging
from unittest.mock import MagicMock
import aiohttp
import pytest
import HABApp
from HABApp.core.wrapper import ExceptionToHABApp
log = logging.getLogger('WrapperTest')
@pytest.fixture
def p_mock():
post_event = HABApp.core.EventBus.post_event
HABApp.core.EventBus.post_event = m = MagicMock()
yield m
HABApp.core.EventBus.post_event = post_event
# @pytest.mark.skip(reason="Behavior still unclear")
def test_exception_format(p_mock):
async def test():
async with aiohttp.ClientSession(timeout=aiohttp.ClientTimeout(0.01)) as session:
async with session.get('http://localhost:12345'):
pass
with ExceptionToHABApp(log):
asyncio.get_event_loop().run_until_complete(test())
tb = p_mock.call_args[0][1].traceback
# verbose asyncio
assert 'self = <ProactorEventLoop running=False closed=False debug=True>' not in tb
# verbose aiohttp
assert 'async def __aenter__(self) -> _RetType:' not in tb
The call to stackprinter is in /HABApp/core/wrapper.py in format_exception
I added a print statement to the is_boring:
True = match(c:\HABApp_venv\lib\site-packages\aiohttp\client.py)
True = match(c:\HABApp_venv\lib\site-packages\aiohttp\helpers.py)
but the traceback is
File "c:\HABApp_venv\lib\site-packages\aiohttp\client.py", line 1117, in __aenter__
1116 async def __aenter__(self) -> _RetType:
--> 1117 self._resp = await self._coro
..................................................
self = <aiohttp.client._RequestContextManager object at 0x000000000548B340>
_RetType = ~_RetType
self._resp = # AttributeError
self = <aiohttp.client._RequestContextManager object at 0x000000000548B340>
self._coro = <coroutine object ClientSession._request at 0x0000000005492140>
..................................................
File "c:\HABApp_venv\lib\site-packages\aiohttp\helpers.py", line 656, in __exit__
raise asyncio.TimeoutError from None
---- (full traceback above) ----
File "c:\HABApp\tests\test_core\test_wrapper.py", line 30, in test_exception_format
asyncio.get_event_loop().run_until_complete(test())
File "c:\HABApp\tests\test_core\test_wrapper.py", line 26, in test
async with session.get('http://localhost:12345'):
File "c:\HABApp_venv\lib\site-packages\aiohttp\helpers.py", line 656, in __exit__
raise asyncio.TimeoutError from None
TimeoutError
Funny thing is you can see part in the same folder is compacted (the two lines above ---- (full traceback above) ---- but the part before is not.
Looking at that log output, I just realized something - could it be that it is working as advertised? From the docs
suppressed_paths: list of regex patterns
Set less verbose formatting for frames whose code lives in certain paths
(e.g. library code). Files whose path matches any of the given regex
patterns will be considered boring. The first call to boring code is
rendered with fewer code lines (but with argument values still visible),
while deeper calls within boring code get a single line and no variable
values.
i.e., it still shows a bit of info about the first call into suppressed code. (I did that so that I can still see with which arguments e.g. a library function was called)
Hm - I guess the aiohttp library uses so much files that I thought something was not working as expected because it is always an extended frame. Guess I will have to clean the trace back manually.
Thank you for your help :+1:
Would it be possible to pass this in as an argument or add another list for pathts that will be suppressed completely?
I have to keep the maintainability of the code in mind (and it's already somewhat riddled with edge cases), so I'd be a bad maintainer if I didn't hesitate here. Can you explain some more what the consequences of not offering that flag are? Meaning, does it just waste 4 extra lines of screen space when a crash happens (that doesn't sound too bad given how long the tracebacks can be anyway), or are there other ramifications
It's just that these lines add up and currently a normal trace back is ~3 screens long for my application. I guess I can do this in post processing with a regex and cut the unwanted parts but an parameter or something machine readable would be much nicer.
Is that because the call stack goes in and out of that library multiple times? Right now my mental picture is that the new flag would compress just one frame (the frame where the stack enters aiohttp), saving just 3-4 lines out of 3 screens full
Yes, it is because it's like this: my_code -> asyncio/file1 -> my_code -> aiohttp/file2 -> aiohttp/file3
The full trace back from the simple testcase above is like this:
------------------------------ Captured log call ------------------------------
ERROR WrapperTest:wrapper.py:177 Error "" in test_exception_format:
ERROR WrapperTest:wrapper.py:179 File "c:\HABApp\tests\test_core\test_wrapper.py", line 67, in test_exception_format
ERROR WrapperTest:wrapper.py:179 60 def test_exception_format(p_mock):
ERROR WrapperTest:wrapper.py:179 (...)
ERROR WrapperTest:wrapper.py:179 63 async with session.get('http://localhost:12345'):
ERROR WrapperTest:wrapper.py:179 64 pass
ERROR WrapperTest:wrapper.py:179 65
ERROR WrapperTest:wrapper.py:179 66 with ExceptionToHABApp(log):
ERROR WrapperTest:wrapper.py:179 --> 67 asyncio.get_event_loop().run_until_complete(test())
ERROR WrapperTest:wrapper.py:179 68
ERROR WrapperTest:wrapper.py:179 ..................................................
ERROR WrapperTest:wrapper.py:179 p_mock = <MagicMock id='88126896'>
ERROR WrapperTest:wrapper.py:179 ExceptionToHABApp = <class 'HABApp.core.wrapper.ExceptionToHABApp'>
ERROR WrapperTest:wrapper.py:179 log = <Logger WrapperTest (WARNING)>
ERROR WrapperTest:wrapper.py:179 test = <function 'test_exception_format.<locals>.test' test_wrapper.py:61>
ERROR WrapperTest:wrapper.py:179 ..................................................
ERROR WrapperTest:wrapper.py:179
ERROR WrapperTest:wrapper.py:179 File "c:\Python38\lib\asyncio\base_events.py", line 616, in run_until_complete
ERROR WrapperTest:wrapper.py:179 580 def run_until_complete(self, future):
ERROR WrapperTest:wrapper.py:179 (...)
ERROR WrapperTest:wrapper.py:179 --> 616 return future.result()
ERROR WrapperTest:wrapper.py:179 ..................................................
ERROR WrapperTest:wrapper.py:179 self = <ProactorEventLoop running=False closed=False debug=True>
ERROR WrapperTest:wrapper.py:179 future = <Task finished name='Task-1' coro=<test_exception_format.<locals>.test() done, defined at c:\HABApp\tests\test_core\test_wrapper.py:61> exception=TimeoutError() created at c:\Python38\lib\asyncio\base_events.py:595>
ERROR WrapperTest:wrapper.py:179 ..................................................
ERROR WrapperTest:wrapper.py:179
ERROR WrapperTest:wrapper.py:179 File "c:\HABApp\tests\test_core\test_wrapper.py", line 63, in test
ERROR WrapperTest:wrapper.py:179 61 async def test():
ERROR WrapperTest:wrapper.py:179 62 async with aiohttp.ClientSession(timeout=aiohttp.ClientTimeout(0.01)) as session:
ERROR WrapperTest:wrapper.py:179 --> 63 async with session.get('http://localhost:12345'):
ERROR WrapperTest:wrapper.py:179 64 pass
ERROR WrapperTest:wrapper.py:179 ..................................................
ERROR WrapperTest:wrapper.py:179 aiohttp.ClientSession = <class 'aiohttp.client.ClientSession'>
ERROR WrapperTest:wrapper.py:179 aiohttp.ClientTimeout = <class 'aiohttp.client.ClientTimeout'>
ERROR WrapperTest:wrapper.py:179 session = <aiohttp.client.ClientSession object at 0x0000000005411760>
ERROR WrapperTest:wrapper.py:179 ..................................................
ERROR WrapperTest:wrapper.py:179
ERROR WrapperTest:wrapper.py:179 File "c:\HABApp_venv\lib\site-packages\aiohttp\client.py", line 1117, in __aenter__
ERROR WrapperTest:wrapper.py:179 1116 async def __aenter__(self) -> _RetType:
ERROR WrapperTest:wrapper.py:179 --> 1117 self._resp = await self._coro
ERROR WrapperTest:wrapper.py:179 ..................................................
ERROR WrapperTest:wrapper.py:179 self = <aiohttp.client._RequestContextManager object at 0x00000000054FFE00>
ERROR WrapperTest:wrapper.py:179 _RetType = ~_RetType
ERROR WrapperTest:wrapper.py:179 self._resp = # AttributeError
ERROR WrapperTest:wrapper.py:179 self = <aiohttp.client._RequestContextManager object at 0x00000000054FFE00>
ERROR WrapperTest:wrapper.py:179 self._coro = <coroutine object ClientSession._request at 0x000000000551D740>
ERROR WrapperTest:wrapper.py:179 ..................................................
ERROR WrapperTest:wrapper.py:179
ERROR WrapperTest:wrapper.py:179 File "c:\HABApp_venv\lib\site-packages\aiohttp\helpers.py", line 656, in __exit__
ERROR WrapperTest:wrapper.py:179 raise asyncio.TimeoutError from None
ERROR WrapperTest:wrapper.py:179 ---- (full traceback above) ----
ERROR WrapperTest:wrapper.py:179 File "c:\HABApp\tests\test_core\test_wrapper.py", line 67, in test_exception_format
ERROR WrapperTest:wrapper.py:179 asyncio.get_event_loop().run_until_complete(test())
ERROR WrapperTest:wrapper.py:179 File "c:\HABApp\tests\test_core\test_wrapper.py", line 63, in test
ERROR WrapperTest:wrapper.py:179 async with session.get('http://localhost:12345'):
ERROR WrapperTest:wrapper.py:179 File "c:\HABApp_venv\lib\site-packages\aiohttp\helpers.py", line 656, in __exit__
ERROR WrapperTest:wrapper.py:179 raise asyncio.TimeoutError from None
ERROR WrapperTest:wrapper.py:179
ERROR WrapperTest:wrapper.py:179 TimeoutError
Imho in this case the library calls just don't help. I think I can group the trace back in into file specific parts and then further compress the file specific output with a couple of regexes. However it would be nicer if there would be an option to get the output as a list of frames, so I don't have split the text myself. What do you think?
got it! I'll need to poke around in the source code to see how messy the various options would be. It touches areas that have been waiting for a refactor..
If you can tell me what you are trying to do maybe I can help out. Also it would be nice if you can merge my small PRs first so I don't have to rebase.
I'm playing around with the idea of returning more structured data over here https://github.com/cknd/stackprinter/pull/47 - it's less hard to do than I thought, and probably an overall architecture improvement
Sounds great and I am really looking forward to it. What I'd really love is to get the frame data and then modify how stackprinter formats them
e.g.
parts = get_exception_data(e) # this returns the frames
# each part has some properties that control how it is formatted
# These are already set properly
for part in parts:
if part.file.name == 'ignored_lib.py':
part.format.reduced = True
traceback = format_parts(parts) # this formats the frames as usual
This would also be nice for you, so in your "normal" format function you can just call
return format_parts(get_exception_data(e))
Ah I see
I agree that that would be a nice API. And a better architecture for stackprinter internally (e.g. Frames are objects with a format method, tracebacks are lists of frames..). At that point it approaches a rewrite though (which should include heavy use of @alexmojaki's stack_data library btw, another long planned refactor). In fact, if you want to roll your own formatter, using stack_data instead of stackprinter could be a promising route -- this library gives you a clean, structured representation of everything that happens in the frames of a stack, for DIY formatting