classification
Title: assertRaises as a context manager keeps tracebacks and frames alive
Type: Stage: resolved
Components: Extension Modules Versions: Python 3.4, Python 3.3
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: akuchling, eric.araujo, ezio.melotti, haypo, michael.foord, ocean-city, pitrou, python-dev
Priority: normal Keywords: needs review, patch

Created on 2010-09-10 07:18 by ocean-city, last changed 2014-04-28 23:26 by pitrou. This issue is now closed.

Files
File name Uploaded Description Edit
py3k_fix_tarfile.patch ocean-city, 2010-09-10 07:18 review
test_tar_pipe_open_read_error.py ocean-city, 2010-09-12 05:09 small test script to reproduce the issue
test_tar_pipe_open_read_error_v2.py ocean-city, 2010-09-14 02:00
test_assert_raises.py ocean-city, 2010-09-14 06:00 small test script to reproduce
py3k_fix__AssertRaisesContext.patch ocean-city, 2010-09-14 06:06 The patch to fix review
test_traceback_freed.py ocean-city, 2010-09-16 04:15
Messages (17)
msg115984 - (view) Author: Hirokazu Yamamoto (ocean-city) * (Python committer) Date: 2010-09-10 07:18
I noticed regrtest claimed it cannot delete folder after test_tarfile
ran. It was like this.

Traceback (most recent call last):
  File "e:\python-dev\py3k\lib\runpy.py", line 160, in _run_module_as_main
    "__main__", fname, loader, pkg_name)
  File "e:\python-dev\py3k\lib\runpy.py", line 73, in _run_code
    exec(code, run_globals)
  File "e:\python-dev\py3k\lib\test\test_tarfile.py", line 1566, in <module>
    test_main()
  File "e:\python-dev\py3k\lib\test\test_tarfile.py", line 1563, in test_main
    shutil.rmtree(TEMPDIR)
  File "e:\python-dev\py3k\lib\shutil.py", line 283, in rmtree
    onerror(os.remove, fullname, sys.exc_info())
  File "e:\python-dev\py3k\lib\shutil.py", line 281, in rmtree
    os.remove(fullname)
WindowsError: [Error 32] プロセスはファイルにアクセスできません。別のプロセスが
使用中です。: 'E:\\PYTHON~1\\py3k\\@test_5276_tmp\\tmp.tar'

# It says "Process cannot access the file. Another process is using it."

I tried to reproduce this by running test_tarfile alone, but failed.
But I succeeded to do it with following command.
  py3k -m test.regrtest test_capi test_tarfile

(Probably there is timing problem like GC... The reason why I think
so is below)

I think _Stream object left opened after exception occured in (even
after returned from function Tarfile#open) because it lives in stack
frame. Because t._extfileobj is True by default, TarFile object won't close it explicitly.
msg116130 - (view) Author: Éric Araujo (eric.araujo) * (Python committer) Date: 2010-09-11 23:07
Just to be sure: Have you checked this bug doesn’t apply to 2.7?  Can you add a regression test?
msg116149 - (view) Author: Hirokazu Yamamoto (ocean-city) * (Python committer) Date: 2010-09-12 05:09
I created separate small test case to reproduce, and I tried it on
Python2.7, I couldn't reproduce the issue. And tried it on Python3.1,
I couldn't there neither. (Sorry about that... I included 3.1 in
version box)

And exception might not be related. Because error still occurred
even if I removed "#" before exc_clear() in my attached script.

But if I removed "#" before gc.collect(), test case runs fine.

And I copied Python3.1's Lib/tarfile.py into Python3.2's Lib,
still error occurred. Maybe it's not problem of tarfile module
itself ....?
msg116245 - (view) Author: Éric Araujo (eric.araujo) * (Python committer) Date: 2010-09-12 23:06
I think the tests should go into 2.7 and 3.1 even if they don’t have the bug.  Adding Antoine to nosy, since he’s listed for gc in Misc/maintainers.rst.
msg116360 - (view) Author: Hirokazu Yamamoto (ocean-city) * (Python committer) Date: 2010-09-14 02:00
I tried test_tar_pipe_open_read_error_v2.py on py3k,
I saw 3 uncollectable objects are reported. But they
are *collected* by gc.collect() without
gc.set_debug(gc.DEBUG_LEAK). (I'm not familiar to gc,
so maybe this is normal)

I didn't see uncollectable objects in release27-maint
and release31-maint.

And I replaced py3k's Lib/unittest with release31-maint's
one, the error was gone. Maybe problem is in Lib/unittest.
Actually, if I run the code in test_null_tarfile without
unittest, everything runs fine.

E:\python-dev>py3k test_tar_pipe_open_read_error_v2.py
.
----------------------------------------------------------------------
Ran 1 test in 0.050s

OK
===========================
gc: collectable <cell 00C4F968>
gc: collectable <tuple 00BF1968>
gc: collectable <function 00C53C98>
gc: collectable <tuple 00BF5C78>
gc: collectable <function 00C53CF8>
gc: collectable <tuple 00BF99A0>
gc: collectable <function 00C53D58>
gc: collectable <tuple 00C2D8C0>
gc: collectable <function 00C53DB8>
gc: collectable <tuple 00C37348>
gc: collectable <function 00C53E18>
gc: collectable <tuple 00C37460>
gc: collectable <function 00C53E78>
gc: collectable <tuple 00C37540>
gc: collectable <function 00C53ED8>
gc: collectable <function 00C53F38>
gc: collectable <type 00C73CE0>
gc: collectable <dict 00C4DD58>
gc: collectable <getset_descriptor 00C52AB8>
gc: collectable <getset_descriptor 00C52AF8>
gc: collectable <tuple 00AF7778>
gc: collectable <frame 00C28D70>
gc: collectable <method 00AE6278>
gc: collectable <frame 00C299A8>
gc: collectable <tuple 00BD4498>
gc: collectable <frame 00C29B50>
gc: collectable <frame 00C29CF8>
gc: collectable <frame 00C753A0>
gc: collectable <frame 00C75F40>
gc: collectable <tuple 00C375E8>
gc: collectable <frame 00C760E8>
gc: collectable <method 00C52B38>
gc: collectable <frame 00C766C8>
gc: collectable <_io.FileIO 00C52D38>
gc: collectable <_io.BufferedWriter 00BF0758>
gc: collectable <frame 00C78F80>
gc: collectable <tuple 00AEB9F8>
gc: collectable <_AssertRaisesContext 00C4FAF0>
gc: collectable <dict 00C554D0>
gc: collectable <frame 00C79328>
gc: collectable <TarFile 00C4FB98>
gc: collectable <frame 00C89390>
gc: collectable <dict 00C55770>
gc: collectable <list 00AEF978>
gc: collectable <frame 00C89780>
gc: collectable <frame 00C8A040>
gc: collectable <frame 00C89CC0>
gc: collectable <frame 00C89E70>
gc: collectable <traceback 00C56038>
gc: collectable <tuple 00C4F850>
gc: collectable <IOError 00C508F8>
gc: collectable <tuple 00C4FC08>
gc: collectable <ReadError 00C4CC50>
gc: collectable <method 00AE6338>
gc: collectable <tuple 00BF5150>
gc: collectable <tuple_iterator 00C4FA80>
gc: collectable <map 00C4FAB8>
gc: collectable <list 00AFAD38>
gc: uncollectable <_Stream 00C4FB28>
gc: uncollectable <dict 00C55620>
gc: uncollectable <_LowLevelFile 00C4FB60>
===========================
Traceback (most recent call last):
  File "test_tar_pipe_open_read_error_v2.py", line 25, in test_main
    unittest.main()
  File "e:\python-dev\py3k\lib\unittest\main.py", line 95, in __init__
    self.runTests()
  File "e:\python-dev\py3k\lib\unittest\main.py", line 231, in runTests
    sys.exit(not self.result.wasSuccessful())
SystemExit: False

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "test_tar_pipe_open_read_error_v2.py", line 33, in <module>
    test_main()
  File "test_tar_pipe_open_read_error_v2.py", line 30, in test_main
    shutil.rmtree(TEMPDIR)
  File "e:\python-dev\py3k\lib\shutil.py", line 283, in rmtree
    onerror(os.remove, fullname, sys.exc_info())
  File "e:\python-dev\py3k\lib\shutil.py", line 281, in rmtree
    os.remove(fullname)
WindowsError: [Error 32] プロセスはファイルにアクセスできません。別のプロセスが
使用中です。: 'c:\\docume~1\\ocean\\locals~1\\temp\\__foobarbaz__\\tmp.tar'
gc: 61 uncollectable objects at shutdown:
[54634 refs]
msg116368 - (view) Author: Hirokazu Yamamoto (ocean-city) * (Python committer) Date: 2010-09-14 06:00
The error went away when I commented out following line.

Lib/unittest/case.py(133)
        self.exception = exc_value.with_traceback(None)

I found this by brute force.... I noticed that
test_tar_pipe_open_read_error_v2.py starts to fail from r75241.
It stores exc_value into _AssertRaisesContext#exception.

And when the exception was re-raised like this, (_Stream#_read)

            try:
                buf = self.cmp.decompress(buf)
            except IOError:
                raise ReadError("invalid compressed data")

IOError will be set to ReadError's *__cause__* attribute.
ReadError's traceback is cleared in unittest, but IOError's
traceback is not. It contains reference to frame which contains
_AssertRaisesContext object. And ReadError will be set to
_AssertRaisesContext's *exception* attribute, cyclic reference
is made. It cannot be freed without GC.

# gc.get_referents() was really helpful.

I'll attach the test script "test_assert_raises.py" to reproduce
the error. The result should be like this.

E:\python-dev>py3k test_assert_raises.py
--------------------------
[('foo 2',), None, RuntimeError('foo 1',)]
RuntimeError('foo 1',)
[('foo 1',), <traceback object at 0x00BD2738>]
<traceback object at 0x00BD2738>
--------------------------
.
----------------------------------------------------------------------
Ran 1 test in 0.090s

OK
===========================
gc: collectable <cell 00BD0B28>
gc: collectable <tuple 00BD0B60>
gc: collectable <function 00BCFE78>
gc: collectable <tuple 00BD0AF0>
gc: collectable <function 00BCFED8>
gc: collectable <tuple 00BD0BD0>
gc: collectable <function 00BCFF38>
gc: collectable <tuple 00BD0C08>
gc: collectable <function 00BCFF98>
gc: collectable <tuple 00BD0C40>
gc: collectable <function 00BD4038>
gc: collectable <tuple 00BD0C78>
gc: collectable <function 00BD4098>
gc: collectable <tuple 00BD0CB0>
gc: collectable <function 00BD40F8>
gc: collectable <function 00BD4158>
gc: collectable <type 00C07550>
gc: collectable <dict 00B1FAB8>
gc: collectable <getset_descriptor 00BD2678>
gc: collectable <getset_descriptor 00BD26B8>
gc: collectable <tuple 00AC53F8>
gc: collectable <frame 00C08858>
gc: collectable <method 00AC43F8>
gc: collectable <frame 00C09628>
gc: collectable <tuple 00BD0038>
gc: collectable <frame 00C097D0>
gc: collectable <frame 00C09978>
gc: collectable <frame 00C0C1B8>
gc: collectable <frame 00C0CEF0>
gc: collectable <tuple 00BD0E38>
gc: collectable <frame 00C0D098>
gc: collectable <method 00AC43B8>
gc: collectable <frame 00C0D810>
gc: collectable <_AssertRaisesContext 00BD0F18>
gc: collectable <frame 00C0DF18>
gc: collectable <tuple 00BD0EA8>
gc: collectable <RuntimeError 00B9FC50>
gc: collectable <traceback 00BD2738>
gc: collectable <tuple 00BD0F50>
gc: collectable <ValueError 00B9FC98>
gc: collectable <dict 00B22818>
gc: collectable <method 00AC4338>
gc: collectable <tuple 00BD0B98>
gc: collectable <tuple_iterator 00BD0E70>
gc: collectable <map 00BD0EE0>
gc: collectable <list 00B21938>
===========================
gc: 46 uncollectable objects at shutdown:
[45415 refs]
msg116369 - (view) Author: Hirokazu Yamamoto (ocean-city) * (Python committer) Date: 2010-09-14 06:06
Here is the patch to fix this issue. (Please forget first patch)

E:\python-dev>py3k -m test.regrtest test_tarfile
[1/1] test_tarfile
1 test OK.
[85902 refs]

E:\python-dev>py3k test_assert_raises.py
--------------------------
[('foo 2',), None, RuntimeError('foo 1',)]
RuntimeError('foo 1',)
[('foo 1',), None]
None
--------------------------
.
----------------------------------------------------------------------
Ran 1 test in 0.050s

OK
===========================
gc: collectable <cell 00C824D0>
gc: collectable <tuple 00C82508>
gc: collectable <function 00C80E18>
gc: collectable <tuple 00C82498>
gc: collectable <function 00C80E78>
gc: collectable <tuple 00C82578>
gc: collectable <function 00C80ED8>
gc: collectable <tuple 00C825B0>
gc: collectable <function 00C80F38>
gc: collectable <tuple 00C825E8>
gc: collectable <function 00C80F98>
gc: collectable <tuple 00C82620>
gc: collectable <function 00C85038>
gc: collectable <tuple 00C82658>
gc: collectable <function 00C85098>
gc: collectable <function 00C850F8>
gc: collectable <type 00B78010>
gc: collectable <dict 00B31578>
gc: collectable <getset_descriptor 00C7CD78>
gc: collectable <getset_descriptor 00C7CDB8>
gc: collectable <tuple 00AC53F8>
===========================
gc: collectable <TextTestResult 00C827A8>
gc: collectable <_WritelnDecorator 00C82690>
gc: collectable <dict 00B316C8>
gc: collectable <dict 00B31818>
gc: collectable <list 00B1D3B8>
gc: collectable <list 00C7CC78>
gc: collectable <list 00B2B878>
gc: collectable <list 00C7CCF8>
gc: collectable <list 00B1D2B8>
gc: collectable <TestCase 00C82770>
gc: collectable <dict 00B314D0>
gc: collectable <dict 00B31770>
gc: collectable <list 00B1CF38>
gc: collectable <method 00AC4438>
gc: collectable <method 00AC45F8>
gc: collectable <method 00AC4638>
gc: collectable <method 00AC42F8>
gc: collectable <method 00AC45B8>
gc: collectable <method 00AC4538>
gc: 40 uncollectable objects at shutdown:
[45216 refs]
msg116379 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2010-09-14 09:49
You shouldn't use DEBUG_LEAK except for debugging purposes :)

As the doc mentions: “To debug a leaking program call gc.set_debug(gc.DEBUG_LEAK). Notice that this includes gc.DEBUG_SAVEALL, causing garbage-collected objects to be saved in gc.garbage for inspection.”

It's true that the message at shutdown should be eliminated in this case, though.
Anyway, I've committed a fix in r84798.
msg116508 - (view) Author: Hirokazu Yamamoto (ocean-city) * (Python committer) Date: 2010-09-16 04:15
Here is the simple test case to demonstrate this issue.
msg117229 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2010-09-23 20:19
Adding Michael for review of py3k_fix__AssertRaisesContext.patch.
msg117295 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2010-09-24 15:29
Note that the original issue (test_tarfile failures on the Windows buildbots) now seems fixed thanks to the various tarfile and test_tarfile improvements.

I have no opinion on whether assertRaises should take care of cleaning the tracebacks or not. As the test_tarfile issue shows, the resource consumption issues were tied to actual bugs both in the library and in the test suite.
msg117401 - (view) Author: Hirokazu Yamamoto (ocean-city) * (Python committer) Date: 2010-09-26 05:21
> Note that the original issue (test_tarfile failures on the Windows
> buildbots) now seems fixed thanks to the various tarfile and
> test_tarfile improvements.

Yes, thanks. :-)
msg181816 - (view) Author: Michael Foord (michael.foord) * (Python committer) Date: 2013-02-10 16:06
The patch py3k_fix__AssertRaisesContext.patch looks good. A test would be nice. The code already attempts to sanitize the traceback, so sanitizing __cause__ and __context__ seems reasonable.
msg194514 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-08-05 21:34
frame.clear() was committed in issue17934, it would allow a less brutal resolution.
msg199115 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2013-10-06 19:33
See issue1565525 for the new helper function in the traceback module.
msg217442 - (view) Author: Roundup Robot (python-dev) Date: 2014-04-28 23:25
New changeset 6ab3193e890e by Antoine Pitrou in branch '3.4':
Issue #9815: assertRaises now tries to clear references to local variables in the exception's traceback.
http://hg.python.org/cpython/rev/6ab3193e890e

New changeset 553fe27521be by Antoine Pitrou in branch 'default':
Issue #9815: assertRaises now tries to clear references to local variables in the exception's traceback.
http://hg.python.org/cpython/rev/553fe27521be
msg217443 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2014-04-28 23:26
I've committed an alternate patch using traceback.clear_frames().
History
Date User Action Args
2014-04-28 23:26:39pitrousetstatus: open -> closed
resolution: fixed
messages: + msg217443

stage: needs patch -> resolved
2014-04-28 23:25:48python-devsetnosy: + python-dev
messages: + msg217442
2014-03-06 23:50:14hayposetnosy: + haypo
2013-10-06 19:33:12pitrousetnosy: + akuchling

messages: + msg199115
stage: patch review -> needs patch
2013-10-06 19:31:14terry.reedysetversions: - Python 3.2
2013-08-05 21:34:28pitrousetmessages: + msg194514
2013-02-10 16:06:20michael.foordsetmessages: + msg181816
versions: + Python 3.3, Python 3.4
2011-04-04 13:48:31ezio.melottisetnosy: + ezio.melotti
2010-09-26 05:21:36ocean-citysetmessages: + msg117401
2010-09-24 15:29:18pitrousettitle: test_tarfile sometimes ends with error "Cannot remove dir" -> assertRaises as a context manager keeps tracebacks and frames alive
messages: + msg117295
stage: commit review -> patch review
2010-09-23 20:19:42pitrousetnosy: + michael.foord
messages: + msg117229
2010-09-23 19:50:05ocean-citysetkeywords: + needs review
2010-09-16 04:15:53ocean-citysetfiles: + test_traceback_freed.py

messages: + msg116508
2010-09-14 09:49:09pitrousetmessages: + msg116379
2010-09-14 06:06:51ocean-citysetfiles: + py3k_fix__AssertRaisesContext.patch

messages: + msg116369
versions: - Python 3.1
2010-09-14 06:00:21ocean-citysetfiles: + test_assert_raises.py

messages: + msg116368
2010-09-14 02:00:32ocean-citysetfiles: + test_tar_pipe_open_read_error_v2.py

messages: + msg116360
versions: + Python 3.1
2010-09-12 23:06:47eric.araujosetnosy: + pitrou
messages: + msg116245
2010-09-12 05:09:43ocean-citysetfiles: + test_tar_pipe_open_read_error.py

messages: + msg116149
versions: - Python 3.1
2010-09-11 23:07:41eric.araujosetnosy: + eric.araujo

messages: + msg116130
title: test_tarfile sometimes ends with error "Cannot remoe dir" -> test_tarfile sometimes ends with error "Cannot remove dir"
2010-09-10 07:19:04ocean-citysetstage: commit review
2010-09-10 07:18:18ocean-citycreate