Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Tracebacks should contain the first line of continuation lines #56667

Closed
psss mannequin opened this issue Jul 1, 2011 · 18 comments
Closed

Tracebacks should contain the first line of continuation lines #56667

psss mannequin opened this issue Jul 1, 2011 · 18 comments
Labels
3.8 only security fixes interpreter-core (Objects, Python, Grammar, and Parser dirs) type-feature A feature request or enhancement

Comments

@psss
Copy link
Mannequin

psss mannequin commented Jul 1, 2011

BPO 12458
Nosy @birkenfeld, @terryjreedy, @ncoghlan, @giampaolo, @nedbat, @ezio-melotti, @bitdancer, @florentx, @akheron, @ezyang, @serhiy-storchaka, @kushaldas, @sigmavirus24, @DimitrisJim, @beck
PRs
  • bpo-12458: Fix line numbers for multiline expressions. #8774
  • Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.

    Show more details

    GitHub fields:

    assignee = None
    closed_at = <Date 2018-09-24.16:30:48.023>
    created_at = <Date 2011-07-01.05:46:46.446>
    labels = ['interpreter-core', 'type-feature', '3.8']
    title = 'Tracebacks should contain the first line of continuation lines'
    updated_at = <Date 2021-06-15.21:07:26.867>
    user = 'https://bugs.python.org/psss'

    bugs.python.org fields:

    activity = <Date 2021-06-15.21:07:26.867>
    actor = 'ezyang'
    assignee = 'none'
    closed = True
    closed_date = <Date 2018-09-24.16:30:48.023>
    closer = 'serhiy.storchaka'
    components = ['Interpreter Core']
    creation = <Date 2011-07-01.05:46:46.446>
    creator = 'psss'
    dependencies = []
    files = []
    hgrepos = []
    issue_num = 12458
    keywords = ['patch']
    message_count = 18.0
    messages = ['139544', '144813', '188120', '188133', '188159', '188167', '188171', '188174', '188186', '188187', '188188', '188656', '188662', '230445', '323576', '325533', '326925', '395897']
    nosy_count = 20.0
    nosy_names = ['georg.brandl', 'terry.reedy', 'ncoghlan', 'giampaolo.rodola', 'nedbat', 'ezio.melotti', 'psss', 'r.david.murray', 'flox', 'lesmana', 'petri.lehtinen', 'ezyang', 'serhiy.storchaka', 'kushal.das', 'icordasc', 'dmi.baranov', 'dingo_dasher', 'ers81239', 'Jim Fasarakis-Hilliard', 'beck']
    pr_nums = ['8774']
    priority = 'normal'
    resolution = 'fixed'
    stage = 'resolved'
    status = 'closed'
    superseder = None
    type = 'enhancement'
    url = 'https://bugs.python.org/issue12458'
    versions = ['Python 3.8']

    @psss
    Copy link
    Mannequin Author

    psss mannequin commented Jul 1, 2011

    Currently, python tracebacks shows the last of continuation lines
    when a function spans across multiple lines. This line usually
    contains some function parameter only and thus is not very useful
    for debugging the problem.

    For example:

        Traceback (most recent call last):
        File "./tcms-run", line 48, in <module>
            summary=options.summary)
        File "/tmp/nitrate/Nitrate.py", line 600, in __init__
            raise NitrateError("Need either id or test plan")

    If the traceback contained the beginning of the continuation line
    it would be IMHO much more clear where/how the problem happened.

        Traceback (most recent call last):
        File "./tcms-run", line 48, in <module>
            run = TestRun(plan=plan, distro=options.distro,
        File "/tmp/nitrate/Nitrate.py", line 600, in __init__
            raise NitrateError("Need either id or test plan")

    Version: Both Python 2 and Python 3.

    Trivial reproducer:

        def fun1(par):
            raise Exception
        def fun2():
            fun1(
                    par="value")
        fun2()

    Actual results:

        Traceback (most recent call last):
        File "/tmp/traceback.py", line 10, in <module>
            fun2()
        File "/tmp/traceback.py", line 8, in fun2
            par="value")
        File "/tmp/traceback.py", line 4, in fun1
            raise Exception
        Exception

    @psss psss mannequin added type-bug An unexpected behavior, bug, or error interpreter-core (Objects, Python, Grammar, and Parser dirs) labels Jul 1, 2011
    @ezio-melotti
    Copy link
    Member

    This is an interesting proposal.

    The line number comes from Python/traceback.c:120:
        tb->tb_lineno = PyFrame_GetLineNumber(frame);
    and this function is defined in Objects/frameobject.c:35:
    int PyFrame_GetLineNumber(PyFrameObject *f) {
        if (f->f_trace)
            return f->f_lineno;
        else
            return PyCode_Addr2Line(f->f_code, f->f_lasti);
    }
    and documented as "Return the line number that frame is currently executing.", so that would explain why it's pointing to the last line.

    I'm not sure if there's an easy way to get the line where the beginning of the expression is, but if you find a way to get it, we could try to use it in PyFrame_GetLineNumber and see how it works.

    @terryjreedy
    Copy link
    Member

    This is an enhancement request (at best), not a bug report. I would close it because I think it somewhat dubious, unreasonable, and not helpful.

    First, I think tracebacks *should* report 'the spot of the foul' for each call frame. What would sometimes be helpful when multiple operations are performed in one line would be to also have the column number reported, along with a ^ to indicate the exact point of error. So I think instead misreporting the location of an instruction pointer could be deceptive and not helpful.

    I think it unreasonable to ask the traceback reporter to guess which one line would be most helpful to report. The OP suggests somehow tracing back to the *first* line of a multiline statement. But on python-ideas, G. Rodola noted the following

    assert \
        1 == 0, \
            "error"
    Traceback (most recent call last):
      File "foo.py", line 3, in <module>
        "error"
    AssertionError: error

    and requested that the *second* or *middle* line should be reported. (But what if the asserted expression itself covered multiple lines?)

    I say sometimes 'not helpful' since the traceback already says what function the pointer is in, if it is in one, and therefore what function what called by the previous frame. In the 'reproducer', 'raise Exception' is in fun1, so in fun2, 'par="value")' must have been preceded by 'fun1(...' on a previous line. So replacing 'par="value")' with 'fun1(...' would not add information.

    I think debugging multiline statements will usually requires looking at the whole statement and a few more. To make this easy, one can use a more sophisticated environment than dumb consoles. For instance, if one executes a top-level script from an Idle edit window, one can right click on a traceback in the Shell window and select 'Go to file/line'. Idle will open the file, if necessary, and highlight the line.

    @terryjreedy terryjreedy added type-feature A feature request or enhancement and removed type-bug An unexpected behavior, bug, or error labels Apr 30, 2013
    @ezio-melotti
    Copy link
    Member

    I think all the lines involved in a multi-line expression should be reported.

    Take for example this simple code:
    x = [int(c, 16)
    for c in '0123456789ABCDEFG'
    if c.isdigit() or c.isupper()]

    With Python 2 the traceback is:
    Traceback (most recent call last):
      File "deleteme.py", line 3, in <module>
        if c.isdigit() or c.isupper()]
    ValueError: invalid literal for int() with base 16: 'G'

    Which is not very helpful, because you don't see the int() call that is causing the error in the first place and you don't see where the G comes from.

    Incidentally, for this specific case, the traceback is a bit better on Python3:
    Traceback (most recent call last):
      File "deleteme.py", line 2, in <module>
        for c in '0123456789ABGDEF'
      File "deleteme.py", line 3, in <listcomp>
        if c.isdigit() or c.isupper()]
    ValueError: invalid literal for int() with base 16: 'G'

    But this still misses the int() call.

    IMHO it would be better to have something like:
      Traceback (most recent call last):
      File "deleteme.py", lines 1-3, in <module>
        x = [int(c, 16)
             for c in '0123456789ABCDEFG'
             if c.isdigit() or c.isupper()]
    ValueError: invalid literal for int() with base 16: 'G'

    If this is rejected for some reason, I think printing the first line -- rather than the last -- would still be an improvement, because in most of the cases the first line contains more information (e.g. the name of the function with a multi-line list of args, a raise/assert with the name of the exception and part of the message, the operation done for each element of a genexp/listcomp).

    @giampaolo
    Copy link
    Contributor

    But on python-ideas, G. Rodola noted the following
    assert \
    1 == 0, \
    "error"
    [...]
    and requested that the *second* or *middle* line should be reported.

    No, I was suggesting (assuming it's reasonably possible in terms of implementation) to report the whole block (3 lines) as-is.
    Note that the same would apply for functions.
    For example this:

        self.assertEqual(1, 
                         2)

    Currently prints:

        Traceback (most recent call last):
          File "foo.py", line 7, in test_foo
            2)
        AssertionError: 1 != 2

    While instead it should:

        Traceback (most recent call last):
          File "foo.py", line 6, in test_foo
            self.assertEqual(1, 
                             2)
        AssertionError: 1 != 2

    @bitdancer
    Copy link
    Member

    I agree that printing all the lines would be best, and printing the first line would be second best. I suspect once someone works out how to do the latter it is just as easy to do the former, though :)

    @terryjreedy
    Copy link
    Member

    OK, you would make tracebacks even longer by adding lines that might or might not be be useful. Suppose the error is not the assertion itself, but in one of the expressions (in this case, being compared for equality):
    self.assertEqual(1/0,
    1000)
    Or reverse the two expressions, or replace the method call with an assert statement and join the expressions with '=='. Would you still print both lines?

    My experience on python-list is that people more often have a problem with a whole line being too much context, not too little. Someone writes 'print(complicated_expression)' and gets a Unicode error. Is the problem the expression or the printing of the result to a limited charset console? Both cases have been posted. I sometimes advise people to break their elegant one-liners into two or more lines to make the actual error expression more obvious. If we were to revise the CPython compiler and traceback generator, that is what I think the aim should be. Such a change would include printing multiple lines when the expression spans multiple lines. This might have to be limited to debug builds.

    @bitdancer
    Copy link
    Member

    The point is to print one logical line. Printing a fragment of the logical line is clearly not very helpful...I have found myself a number of times looking for the bug in the fragment printed, and (quickly, but still...) then remembering that the traceback just prints the last physical line and the problem might be earlier.

    Providing a caret is probably impossible. I don't think the bytecode contains enough information to even make a guess as to where a caret should go. I'm not even sure we can get the logical line.

    @terryjreedy
    Copy link
    Member

    >> Printing a fragment of the logical line is clearly not very helpful

    Given the unbounded and recursive nature of 'logical line', I disagree with that as a general, versus special-case, statement.

    Consider:
    r(a()/b(),
    d()/e(),
    g=h()/i(),
    )
    If either e() or i() returns 0, printing all 4 lines is less helpful, by adding noise (which line has the error?), than just printing the 1 line with the ZeroDivisionError. The context is irrelevant.

    Or consider:
    mymegalist = {
    a,
    b,
    ... <500 lines, one item per line>
    xyz,
    }
    If 1 of the expressions raises an error, do you really want all 500 lines in the traceback? Again, the context is probably irrelevant.

    Quite aside from this, 'd()/e(),' and 'g=h()/i(),' are both legal logical lines in themselves (though with different semantics) as well as being fragments of the r call.

    Moreover, the multiline r call above may itself be just a fragment of a call to another function (further indented). The practical difficulty for the proposal, even if limited to multiline calls, is that any bare call could either be part of a larger expression by returning something or be a statement operating through side-effects. Similarly, any 'var=f()' call could either be an assignment statement or keyword arg expression in some other call.

    @ezio-melotti
    Copy link
    Member

    Consider:
    r(a()/b(),
    d()/e(),
    g=h()/i(),
    )

    I tried to run this, with e() == 0, and got:
    Traceback (most recent call last):
      File "deleteme.py", line 6, in <module>
        d()/e(),
    ZeroDivisionError: division by zero

    This is actually a good point, because in this specific case the traceback is correct, and showing all the lines would make things worse.

    If 1 of the expressions raises an error, do you really want
    all 500 lines in the traceback?

    I assume it wouldn't be too difficult to limit the output to 3-5 lines max.

    Someone should try to fiddle with the code I indicated in msg144813, and see what can be done. If there are enough informations it might be possible to keep reporting a single line for the aforementioned case, but report more lines for the cases listed in the other messages; if there aren't enough informations we will have to abandon the idea (or find a way to retrieve them).

    @terryjreedy
    Copy link
    Member

    idlelib has two files that *might* be helpful to anyone who wants to pursue this: PyParse.py and HyperParser.py. One use of the latter is for calltips. When the user types '(', the HyperParser is used first to determine whether the '(' is preceded by an operator (making it a grouper) or not (making it a call operator). In the later case, it parses backwards to find the beginning of the callable expression, which is then evaluated to get the callable (if it does not contain an embedded call) and hence the signature. Parsing forward and back from a given line might be similar.

    @kushaldas
    Copy link
    Member

    I have been able to get the logical line details (start of it), now working on to print the required lines.
    The current way of showing source lines removes any indentation, but to show all the physical lines (related to the logical line) one should show the indentation to match the source. Is this the correct way I should go forward?

    @bitdancer
    Copy link
    Member

    Can you preserve just the *additional* indentation? That is, strip the excess leading whitespace, but preserve the logical indentation, like textwrap.dedent does?

    @serhiy-storchaka
    Copy link
    Member

    Here is yet one example.

    x = 1; y = 0; z = 0
    (
        1/x +
        1/y +
        1/z
    )

    The traceback looks correct:

    Traceback (most recent call last):
      File "1.py", line 4, in <module>
        1/y +
    ZeroDivisionError: division by zero

    But for following code:

    x = 0; y = 1; z = 0
    (
        1/x +
        1/y +
        1/z
    )

    the traceback is the same and it is totally wrong.

    This is because generated bytecode is:

    1 0 LOAD_CONST 0 (0)
    3 STORE_NAME 0 (x)
    6 LOAD_CONST 1 (1)
    9 STORE_NAME 1 (y)
    12 LOAD_CONST 0 (0)
    15 STORE_NAME 2 (z)

    4 18 LOAD_CONST 1 (1)
    21 LOAD_NAME 0 (x)
    24 BINARY_TRUE_DIVIDE
    25 LOAD_CONST 1 (1)
    28 LOAD_NAME 1 (y)
    31 BINARY_TRUE_DIVIDE
    32 BINARY_ADD

    5 33 LOAD_CONST 1 (1)
    36 LOAD_NAME 2 (z)
    39 BINARY_TRUE_DIVIDE
    40 BINARY_ADD
    41 POP_TOP
    42 LOAD_CONST 2 (None)
    45 RETURN_VALUE

    1/x and 1/y have the same line number.

    @serhiy-storchaka
    Copy link
    Member

    Seems PR 8774 fixes all mentioned examples (as well as examples in bpo-34372), except that tracebacks show the single line number of the first line of the multiline expression instead of the range of lines as was suggested. Showing the range of lines requires much more significant changes and changing the marshal format.

    The drawback is minor increasing the size of code objects in memory (due to saving additional line numbers in lnotab), pyc files, and disassembly output for multiline expressions.

    @serhiy-storchaka serhiy-storchaka added the 3.8 only security fixes label Aug 15, 2018
    @serhiy-storchaka
    Copy link
    Member

    New changeset da8d72c by Serhiy Storchaka in branch 'master':
    bpo-12458: Fix line numbers for multiline expressions. (GH-8774)
    da8d72c

    @nedbat
    Copy link
    Member

    nedbat commented Oct 2, 2018

    The other drawback is changing how the trace function is notified in a few scenarios.

    @ezyang
    Copy link
    Mannequin

    ezyang mannequin commented Jun 15, 2021

    Supposing I like the old behavior (line number of the end of the statement), is there any way to recover that line number from the traceback after this change?

    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    3.8 only security fixes interpreter-core (Objects, Python, Grammar, and Parser dirs) type-feature A feature request or enhancement
    Projects
    None yet
    Development

    No branches or pull requests

    7 participants