Shorter and reversed format for traceback

Ideas
1

Current traceback seems optimized for terminal. See this example.

Source code

Output from traceback.print_exception(e):

Traceback (most recent call last):
  File "/Users/inada-n/notes/2024/mini_traceback/sample.py", line 8, in main
    conn = engine.connect()
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 3280, in connect
    return self._connection_cls(self)
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 148, in __init__
    Connection._handle_dbapi_exception_noconnection(
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 2444, in _handle_dbapi_exception_noconnection
    raise sqlalchemy_exception.with_traceback(exc_info[2]) from e
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 146, in __init__
    self._dbapi_connection = engine.raw_connection()
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/engine/base.py", line 3304, in raw_connection
    return self.pool.connect()
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 449, in connect
    return _ConnectionFairy._checkout(self)
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 1263, in _checkout
    fairy = _ConnectionRecord.checkout(pool)
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 712, in checkout
    rec = pool._do_get()
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/pool/impl.py", line 179, in _do_get
    with util.safe_reraise():
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/util/langhelpers.py", line 146, in __exit__
    raise exc_value.with_traceback(exc_tb)
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/pool/impl.py", line 177, in _do_get
    return self._create_connection()
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 390, in _create_connection
    return _ConnectionRecord(self)
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 674, in __init__
    self.__connect()
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 900, in __connect
    with util.safe_reraise():
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/util/langhelpers.py", line 146, in __exit__
    raise exc_value.with_traceback(exc_tb)
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/pool/base.py", line 896, in __connect
    self.dbapi_connection = connection = pool._invoke_creator(self)
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/engine/create.py", line 643, in connect
    return dialect.connect(*cargs, **cparams)
  File "/Users/inada-n/notes/2024/mini_traceback/.venv/lib/python3.12/site-packages/sqlalchemy/engine/default.py", line 617, in connect
    return self.loaded_dbapi.connect(*cargs, **cparams)
sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) unable to open database file
(Background on this error at: https://sqlalche.me/e/20/e3q8)

Note that:

  • If I don’t set chain=False, this traceback becomes two times longer.
  • I used PYTHONNODEBUGRANGES=1 to stop showing range markers.

Although this traceback is good for terminal, this is too large for structured logging + web based log viewer because:

  • On web-based log viewer, users see the top first and scroll down. So the exception and the most recent call should be first.
  • On textural log, one line in traceback is one line in the log. But structured logging with JSON lines can creates more than 8000bytes when traceback in the log record.

So I tried to create toy project named minitraceback. It creates shorter traceback with reversed order:

sqlalchemy.exc.OperationalError: (sqlite3.OperationalError) unable to open database file
(Background on this error at: https://sqlalche.me/e/20/e3q8)
Traceback (most recent call first):
  sqlalchemy/engine/default.py:617 connect
  sqlalchemy/engine/create.py:643 connect
  sqlalchemy/pool/base.py:896 __connect
  sqlalchemy/util/langhelpers.py:146 __exit__
  sqlalchemy/pool/base.py:900 __connect
  sqlalchemy/pool/base.py:674 __init__
  sqlalchemy/pool/base.py:390 _create_connection
  sqlalchemy/pool/impl.py:177 _do_get
  sqlalchemy/util/langhelpers.py:146 __exit__
  sqlalchemy/pool/impl.py:179 _do_get
  sqlalchemy/pool/base.py:712 checkout
  sqlalchemy/pool/base.py:1263 _checkout
  sqlalchemy/pool/base.py:449 connect
  sqlalchemy/engine/base.py:3304 raw_connection
  sqlalchemy/engine/base.py:146 __init__
  sqlalchemy/engine/base.py:2444 _handle_dbapi_exception_noconnection
  sqlalchemy/engine/base.py:148 __init__
  sqlalchemy/engine/base.py:3280 connect
  sample_mini.py:8 main

This looks good for my personal use. But I think shorter&reversed traceback in stdlib traceback would be better because some PaaS/Observability platforms may parse the traceback.

How do you think adding these options to print/format traceback functions in the traceback module?

  • Add reverse=False option.
    • If it is true, traceback is shown in “most recent call first” order.
  • Add showsource=True option.
    • If it is false, source code is not shown.
  • Add remove_path_prefix=False option.
    • If it is true, remove the longest sys.path prefix from the file path.
7 Likes
2

While I don’t see any reason not to allow presenting tracebacks in the opposite order, I’m not sure the quote above is necessarily good motivation. Instead, those tools should probably scroll to the end first and allow scrolling back so in my mind that’s a design error of those tools.

3

Hm this is somewhat a design choice, I think. Most-recent-first is a pretty common experience on the web (blogs, social media, news, forums, etc).

For a very long-running tool you don’t want to load all the logs, and you probably want to show the most recent thing. Putting the newest logs on top and scrolling down for history is a familiar experience from other contexts.

But given all that, this seems like a good thing to include in a structured logging package? As part of setting up such logging, you’d add this tool to reformat exceptions. Is there an additional benefit to incorporating it into the stdlib?

3 Likes
4

For example, OpenTelemetry provides stdlib logging handler that uses stdlib traceback module.

Additionally, OpenTelemetry " Semantic Conventions for Exceptions" says:

A stacktrace as a string in the natural representation for the language runtime. The representation is to be determined and documented by each language SIG.
semantic-conventions/docs/exceptions/exceptions-spans.md at main · open-telemetry/semantic-conventions · GitHub

That is reason for having a standard traceback format for log collection tools, instead of each log library have own traceback format.

2 Likes
5

Java, C#, Go, and many other languages uses “most recent call first” traceback format.
And observability tools are not optimized only for Python.

2 Likes
6

Indeed. Maybe I don’t work with enough systems that mixes the order enough to appreciate it. My experience with reading logs comes mostly from the command line and reading jenkins logs, and in the latter case I wish it auto-scrolled to the bottom because that’s 99% where the error is and what I want to read.

7

I would prefer show_path_prefix=True or include_path_prefix=True. remove_path_prefix=False feels like a double negative to me (the default is to “not remove” the path prefix – aka “keep/show/include” the path prefix :slight_smile: ).

1 Like
8

This is maybe a bit too much bike-shedding, but I disagree: The default is to show the paths as they are present in the traceback objects, i.e. as absolute paths. Removing the prefixes is an extra operation, so it should be enabled. With show_path_prefix=False we are disabling (i.e. False) not removing (i.e. showing) the prefixes, which is way more of a double negative.

Unless I am misunderstanding what is being stored and showing the prefixes is extra work that needs to be performed.

9

No opinion about reverse=False and showsource=True?

There is no time until 3.13 beta. I want to implement one option in 3.13 if possible. My gut feeling, importance is:

  1. showsource (reduce traceback size <1/2)
  2. reverse (show error without scroll)
  3. remove_path_prefix (reduce more traceback size).

If there are no objections, I will start implementing the showsource option.
What is your preferred name for it?

  • showsource
  • showlines
  • source
  • lines
  • Othre (reply)
0 voters
10

Whichever you choose, I recommend using underscores (for example, show_source or show_lines) for readability and accessibility. Compare this screen reader video. It’s also consistent with the other options in traceback.

10 Likes
11

OK. For consisntency with .line, lookup_lines=, and show_group=, I decide to use show_lines.

12

with respect to ordering, I’d like to suggest using a flag named latest_first=True or a similar variant, rather than reverse, as it would be more immediately clear what we’ll get

I take this chance to support this idea, and to mention that in the context of the Jupyter notebooks as well, using latest_first order would result in a more effective feedback

3 Likes