classification
Title: Wrong lineno in traceback when formatting strings with % and multilines
Type: behavior Stage: resolved
Components: Interpreter Core Versions: Python 3.7
process
Status: closed Resolution: out of date
Dependencies: Superseder:
Assigned To: Nosy List: ammar2, kinow, serhiy.storchaka
Priority: normal Keywords:

Created on 2019-07-22 04:30 by kinow, last changed 2019-07-22 08:24 by kinow. This issue is now closed.

Messages (5)
msg348277 - (view) Author: Bruno P. Kinoshita (kinow) * Date: 2019-07-22 04:30
Hi,

Tested on Python 3.7 on Ubuntu LTS. But I believe this affects previous versions too, as found it from an issue posted in Jinja2 in 2013: https://github.com/pallets/jinja/issues/276

This code simulates the issue where the traceback has the wrong line number (without using any Jinja2 code):

```
class Z(object):
    def __str__(self):
        raise ValueError('Z error')


def raise_generator():
    yield 'three values are: %s %s %s' % (
        'primeiro',
        Z(),  # traceback must point to this lineno 9
        'terceiro'  # but points to this lineno 10 (__str__ only, __eq__ is OK)
    )


print(list(raise_generator()))
```

The output:

```
Traceback (most recent call last):
  File "/home/kinow/Development/python/workspace/cylc-flow/cylc/flow/tests/Z.py", line 14, in <module>
    print(list(raise_generator()))
  File "/home/kinow/Development/python/workspace/cylc-flow/cylc/flow/tests/Z.py", line 10, in raise_generator
    'terceiro'  # but points to this lineno 10 (__str__ only, __eq__ is OK)
  File "/home/kinow/Development/python/workspace/cylc-flow/cylc/flow/tests/Z.py", line 3, in __str__
    raise ValueError('Z error')
ValueError: Z error
```

Jinja uses something similar to the class Z to raise errors when the template has undefined variables. The curious part is that if instead of simply formatting the string with "%s" % (Z()) you use "%s" % (str(Z())) or if you callZ().__str__(), then the traceback reports the correct line number.

Not sure if intentional, but would be nice if the traceback reported the correct line number, and I think other applications could end up having the same issue.

This is my first issue, so I apologize if I did not include enough information, or if there is anything missing in this ticket. Let me know if I need to update it with more information or formatting the code.

Would be happy to work on this if this is considered an easy-to-fix issue.

Thanks all for your work on Python,

Bruno P. Kinoshita
msg348279 - (view) Author: Ammar Askar (ammar2) * (Python committer) Date: 2019-07-22 06:25
Please try this on the latest version of Python, there was a behavior change implemented in issue12458 that might make this a non-issue.
msg348280 - (view) Author: Bruno P. Kinoshita (kinow) * Date: 2019-07-22 06:45
Hi Ammar, thanks for the quick reply and for the suggestion.

Tried on the latest version on master, and looks like it's indeed different, though still looks like it is displaying the wrong line number.

```
kinow@localhost:~/Development/python/workspace/cpython$ python
Python 3.9.0a0 (heads/master:b530a4460b, Jul 22 2019, 18:38:44) 
[GCC 7.4.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> 
kinow@localhost:~/Development/python/workspace/cpython$ python z.py
Traceback (most recent call last):
  File "/home/kinow/Development/python/workspace/cpython/z.py", line 14, in <module>
    print(list(raise_generator()))
  File "/home/kinow/Development/python/workspace/cpython/z.py", line 7, in raise_generator
    yield 'three values are: %s %s %s' % (
  File "/home/kinow/Development/python/workspace/cpython/z.py", line 3, in __str__
    raise ValueError('Z error')
ValueError: Z error
```

It is now displaying the line number 7, where the yield statement begins, instead of where it actually happened (line 9).

And once again, if I replace `Z()` by `Z().__str__()`, then it displays the right line number.

```
kinow@localhost:~/Development/python/workspace/cpython$ python z.py
Traceback (most recent call last):
  File "/home/kinow/Development/python/workspace/cpython/z.py", line 14, in <module>
    print(list(raise_generator()))
  File "/home/kinow/Development/python/workspace/cpython/z.py", line 9, in raise_generator
    Z().__str__(),  # traceback must point to this lineno 9
  File "/home/kinow/Development/python/workspace/cpython/z.py", line 3, in __str__
    raise ValueError('Z error')
ValueError: Z error
```
msg348284 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2019-07-22 07:28
Line 9 is not where the error actually happened. The exception is raised not when you call Z(), but when you implicitly call Z.__str__() when evaluate the % operator.

In Python 3.8 the traceback points to the start of the subexpression that raises an exception.

So this issue has been fixed in 3.8. The fix was not backported to 3.7 because it is a large change which affects other code that traces execution or analyses tracebacks (e.g. coverage.py).
msg348290 - (view) Author: Bruno P. Kinoshita (kinow) * Date: 2019-07-22 08:24
Hi,

Thanks for the explanation. Could you elaborate a bit on this one:

>In Python 3.8 the traceback points to the start of the subexpression that raises an exception.

Just wanted to understand why I get the desired line number when I call Z().__str__(), but when I call simply Z() is returns - as you clarified - the start of the subexpression.
History
Date User Action Args
2019-07-22 08:24:40kinowsetmessages: + msg348290
2019-07-22 07:28:56serhiy.storchakasetstatus: open -> closed
resolution: out of date
messages: + msg348284

stage: resolved
2019-07-22 06:45:25kinowsetmessages: + msg348280
2019-07-22 06:25:11ammar2setnosy: + serhiy.storchaka, ammar2
messages: + msg348279
2019-07-22 04:30:20kinowcreate