classification
Title: Incorrect tracing for "except" with variable
Type: behavior Stage: resolved
Components: Interpreter Core Versions: Python 3.10
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: Mark.Shannon, barry, nedbat, pablogsal
Priority: release blocker Keywords: 3.10regression, patch

Created on 2021-07-12 22:51 by nedbat, last changed 2021-07-15 17:11 by barry. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 27109 merged Mark.Shannon, 2021-07-13 13:24
PR 27135 merged Mark.Shannon, 2021-07-14 09:42
Messages (11)
msg397365 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2021-07-12 22:51
This construct isn't traced properly:

    except ExceptionName as var:
        if something:
            raise

Here's a reproducer:

-- 8< ---------------------------------
import linecache, sys

def trace(frame, event, arg):
    # The weird globals here is to avoid a NameError on shutdown...
    if frame.f_code.co_filename == globals().get("__file__"):
        lineno = frame.f_lineno
        print("{} {}: {}".format(event[:4], lineno, linecache.getline(__file__, lineno).rstrip()))
    return trace

def f(x):
    try:
        1/0
    except ZeroDivisionError as error:
        if x:
            raise
    return 12

print(sys.version)
sys.settrace(trace)

for x in [0, 1]:
    try:
        print(f(x))
    except:
        print("oops")
-----------------------------------

When run with 3.10.0b4, it produces this output:

  3.10.0b4 (default, Jul 11 2021, 13:51:53) [Clang 12.0.0 (clang-1200.0.32.29)]
  call 10: def f(x):
  line 11:     try:
  line 12:         1/0
  exce 12:         1/0
  line 13:     except ZeroDivisionError as error:
  line 14:         if x:
* line 15:             raise
  line 16:     return 12
  retu 16:     return 12
  12
  call 10: def f(x):
  line 11:     try:
  line 12:         1/0
  exce 12:         1/0
  line 13:     except ZeroDivisionError as error:
  line 14:         if x:
  line 15:             raise
  retu 15:             raise
  oops

The starred line claims that raise is being run, but it is not run at that point.

The variable on the except clause is important.  If you change that line to "except ZeroDivisionError:", then the output is correct:

  3.10.0b4 (default, Jul 11 2021, 13:51:53) [Clang 12.0.0 (clang-1200.0.32.29)]
  call 10: def f(x):
  line 11:     try:
  line 12:         1/0
  exce 12:         1/0
  line 13:     except ZeroDivisionError:
  line 14:         if x:
  line 16:     return 12
  retu 16:     return 12
  12
  call 10: def f(x):
  line 11:     try:
  line 12:         1/0
  exce 12:         1/0
  line 13:     except ZeroDivisionError:
  line 14:         if x:
  line 15:             raise
  retu 15:             raise
  oops
msg397366 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2021-07-12 23:07
Based on https://github.com/nedbat/coveragepy/issues/1187, btw
msg397375 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2021-07-13 01:08
Marking as release blocker for the first release candidate.

Ned, I assume this comes from some recent bug report in coverage, but it would be great if you could ask your users to test the latest beta and report any issue before we release the first candidate. That way we can be more sure that we won't find any future surprise

Thanks in advance
msg397376 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2021-07-13 01:09
I assume this is due to some artificial bytecode for cleaning the variable in the exception
msg397378 - (view) Author: Barry A. Warsaw (barry) * (Python committer) Date: 2021-07-13 01:37
Pablo, this is triggered by my bug report here: https://github.com/nedbat/coveragepy/issues/1187

I tested this again today with the 3.10 git head and still got the coverage misses.  Happy to try any other combinations.
msg397398 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-07-13 13:19
Thanks Ned, you're doing a fantastic job of finding these issues.
Sorry for keeping you so busy with this.

This one was a latent bug, exposed by fixing https://bugs.python.org/issue44570.
msg397471 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-07-14 09:09
New changeset e5862f79c16e28f1ec51d179698739a9b2d8c1d2 by Mark Shannon in branch 'main':
bpo-44616: Mark all clean up instructions at end of named exception block as artificial (GH-27109)
https://github.com/python/cpython/commit/e5862f79c16e28f1ec51d179698739a9b2d8c1d2
msg397473 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-07-14 10:44
New changeset 794ff7d505f852dc4e0f94901dc7387afaead3bb by Mark Shannon in branch '3.10':
bpo-44616: Mark all clean up instructions at end of named exception block as artificial (GH-27109) (GH-27135)
https://github.com/python/cpython/commit/794ff7d505f852dc4e0f94901dc7387afaead3bb
msg397500 - (view) Author: Barry A. Warsaw (barry) * (Python committer) Date: 2021-07-14 17:44
I just retested my test case (see the coveragepy link below) with Python 3.10 git head and coveragepy git head, and I'm still seeing the misses only in Python 3.10:

---------- coverage: platform darwin, python 3.10.0-beta-4 -----------
Name                      Stmts   Miss Branch BrPart  Cover   Missing
---------------------------------------------------------------------
flufl/lock/__init__.py        5      0      0      0   100%
flufl/lock/_lockfile.py     253      0     80      3    99%   412->415, 418->420, 535->exit
---------------------------------------------------------------------


The lines in question:

        if is_locked:
            try:
                os.unlink(self._lockfile)
            except OSError as error:
                if error.errno not in ERRORS:
                    raise
        # Remove our claim file.
        try:
            os.unlink(self._claimfile)
        except OSError as error:
            if error.errno not in ERRORS:
                raise

I'm not sure whether coveragepy needs to be updated or whether there are other lurking bugs in Python 3.10.  I'm reopening this issue until this is resolved.
msg397565 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2021-07-15 16:20
Barry, is it possible you accidentally used the beta 4?  I ran the test suite with a freshly built 3.10, but by mistake was still using the beta, and was surprised.  Once I really got the latest build in place (Python 3.10.0b4+ (heads/3.10:47695e3c88, Jul 15 2021, 11:55:52)), I got these results:

platform darwin -- Python 3.10.0b4+, pytest-6.2.4, py-1.10.0, pluggy-0.13.1
cachedir: .tox/py310/.pytest_cache
rootdir: /System/Volumes/Data/root/src/foo/bug1187/flufl.lock, configfile: setup.cfg, testpaths: test, docs
plugins: cov-2.12.1
collected 108 items

test/test_api.py .                                                                                                                                          [  0%]
test/test_lock.py ...........................                                                                                                               [ 25%]
docs/using.rst ................................................................................                                                             [100%]

======================================================================== warnings summary =========================================================================
.tox/py310/lib/python3.10/site-packages/sybil/integration/pytest.py:58: 80 warnings
  /System/Volumes/Data/root/src/foo/bug1187/flufl.lock/.tox/py310/lib/python3.10/site-packages/sybil/integration/pytest.py:58: PytestDeprecationWarning: A private pytest class or function was used.
    self._request = fixtures.FixtureRequest(self)

-- Docs: https://docs.pytest.org/en/stable/warnings.html

---------- coverage: platform darwin, python 3.10.0-beta-4 -----------
Name                      Stmts   Miss Branch BrPart  Cover   Missing
---------------------------------------------------------------------
flufl/lock/__init__.py        5      0      0      0   100%
flufl/lock/_lockfile.py     253      0     80      0   100%
---------------------------------------------------------------------
TOTAL                       258      0     80      0   100%
Coverage XML written to file coverage.xml

Required test coverage of 100.0% reached. Total coverage: 100.00%
msg397571 - (view) Author: Barry A. Warsaw (barry) * (Python committer) Date: 2021-07-15 17:11
Thanks Ned.  Seems you might be right.  I thought I'd done a clean test, but in any event, I just pulled 3.10 head and verified that it's producing 100% coverage.  Thanks all for the fix!
History
Date User Action Args
2021-07-15 17:11:48barrysetstatus: open -> closed
resolution: fixed
messages: + msg397571
2021-07-15 16:20:08nedbatsetmessages: + msg397565
2021-07-14 17:44:15barrysetstatus: closed -> open
resolution: fixed -> (no value)
messages: + msg397500
2021-07-14 15:22:07pablogsalsetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2021-07-14 10:44:08Mark.Shannonsetmessages: + msg397473
2021-07-14 09:42:37Mark.Shannonsetpull_requests: + pull_request25678
2021-07-14 09:09:08Mark.Shannonsetmessages: + msg397471
2021-07-13 13:24:49Mark.Shannonsetkeywords: + patch
stage: patch review
pull_requests: + pull_request25655
2021-07-13 13:19:48Mark.Shannonsetmessages: + msg397398
2021-07-13 01:37:42barrysetmessages: + msg397378
2021-07-13 01:09:54pablogsalsetmessages: + msg397376
2021-07-13 01:08:08pablogsalsetpriority: normal -> release blocker
nosy: + pablogsal
messages: + msg397375

2021-07-12 23:54:46barrysetnosy: + barry
2021-07-12 23:07:37nedbatsetmessages: + msg397366
2021-07-12 22:51:39nedbatcreate