classification
Title: Tracebacks should contain the first line of continuation lines
Type: enhancement Stage: needs patch
Components: Interpreter Core Versions: Python 3.5
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: Jim Fasarakis-Hilliard, dingo_dasher, dmi.baranov, ers81239, ezio.melotti, flox, georg.brandl, giampaolo.rodola, icordasc, kushal.das, lesmana, ncoghlan, petri.lehtinen, psss, r.david.murray, serhiy.storchaka, terry.reedy
Priority: normal Keywords:

Created on 2011-07-01 05:46 by psss, last changed 2017-03-14 17:25 by Jim Fasarakis-Hilliard.

Messages (14)
msg139544 - (view) Author: Petr Splichal (psss) Date: 2011-07-01 05:46
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
msg144813 - (view) Author: Ezio Melotti (ezio.melotti) * (Python committer) Date: 2011-10-03 10:49
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.
msg188120 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2013-04-30 00:33
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.
msg188133 - (view) Author: Ezio Melotti (ezio.melotti) * (Python committer) Date: 2013-04-30 07:12
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).
msg188159 - (view) Author: Giampaolo Rodola' (giampaolo.rodola) * (Python committer) Date: 2013-04-30 13:06
> 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
msg188167 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2013-04-30 14:38
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 :)
msg188171 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2013-04-30 17:19
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.
msg188174 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2013-04-30 18:58
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.
msg188186 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2013-04-30 21:20
>>> 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.
msg188187 - (view) Author: Ezio Melotti (ezio.melotti) * (Python committer) Date: 2013-04-30 21:30
> 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).
msg188188 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2013-04-30 22:02
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.
msg188656 - (view) Author: Kushal Das (kushal.das) * (Python committer) Date: 2013-05-07 13:56
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?
msg188662 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2013-05-07 14:58
Can you preserve just the *additional* indentation?  That is, strip the excess leading whitespace, but preserve the logical indentation, like textwrap.dedent does?
msg230445 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2014-11-01 10:16
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.
History
Date User Action Args
2017-03-14 17:25:34Jim Fasarakis-Hilliardsetnosy: + Jim Fasarakis-Hilliard
2016-12-23 13:59:33serhiy.storchakalinkissue29051 dependencies
2015-03-18 13:39:04r.david.murraysetnosy: + ers81239
2015-03-18 13:38:38r.david.murraylinkissue23687 superseder
2014-11-01 10:16:18serhiy.storchakasetmessages: + msg230445
2014-10-31 19:02:20ezio.melottisetnosy: + serhiy.storchaka
2014-10-07 08:11:32giampaolo.rodolasetstage: test needed -> needs patch
versions: + Python 3.5, - Python 3.4
2014-10-07 01:30:32r.david.murraysetnosy: + dingo_dasher
2014-10-07 01:30:05r.david.murraylinkissue22573 superseder
2013-05-07 14:58:50r.david.murraysetmessages: + msg188662
2013-05-07 13:56:39kushal.dassetmessages: + msg188656
2013-04-30 22:02:18terry.reedysetmessages: + msg188188
2013-04-30 21:30:47ezio.melottisetnosy: + kushal.das
messages: + msg188187
2013-04-30 21:20:21terry.reedysetmessages: + msg188186
2013-04-30 18:58:08r.david.murraysetmessages: + msg188174
2013-04-30 17:19:03terry.reedysetmessages: + msg188171
2013-04-30 14:38:29r.david.murraysetnosy: + r.david.murray
messages: + msg188167
2013-04-30 13:06:09giampaolo.rodolasetmessages: + msg188159
2013-04-30 09:16:06dmi.baranovsetnosy: + dmi.baranov
2013-04-30 07:12:22ezio.melottisetmessages: + msg188133
2013-04-30 00:33:36terry.reedysetversions: + Python 3.4, - Python 2.7, Python 3.2, Python 3.3
nosy: + terry.reedy

messages: + msg188120

type: behavior -> enhancement
2013-04-29 18:27:47giampaolo.rodolasetnosy: + giampaolo.rodola
2013-04-29 17:45:22icordascsetnosy: + icordasc
2011-10-18 13:29:15floxsetnosy: + flox
2011-10-03 10:49:34ezio.melottisetversions: + Python 3.3, - Python 2.6
nosy: + ncoghlan, ezio.melotti, georg.brandl

messages: + msg144813

stage: test needed
2011-10-02 16:58:12lesmanasetnosy: + lesmana
2011-07-03 20:07:20petri.lehtinensetnosy: + petri.lehtinen
2011-07-01 05:46:46pssscreate