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

regression: something about stack introspection changed in v7.3.14, which has broken Twisted's test suite #4850

Closed
glyph opened this issue Jan 12, 2024 · 10 comments

Comments

@glyph
Copy link

glyph commented Jan 12, 2024

It's a bit hard, from the vantage point of Twisted's test runner, which depends on stack introspection itself, to figure out exactly what has gone wrong, but you can see a successful test run here: https://github.com/twisted/twisted/actions/runs/7496583256/job/20409555911 and a failed one here: https://github.com/twisted/twisted/actions/runs/7496845771/job/20409666634 where the only difference between them is .13 to .14.

@mattip
Copy link
Member

mattip commented Jan 12, 2024

Doces anything in the changelog remind you of something that could cause these failures? Is there a smaller failing unit test we can run? It seems like there is an error being raised where previously there was none, but I can't tell what the error actually is.

@mattip
Copy link
Member

mattip commented Jan 12, 2024

How do you usually debug this kind of failure?

@glyph
Copy link
Author

glyph commented Jan 12, 2024

Doces anything in the changelog remind you of something that could cause these failures? Is there a smaller failing unit test we can run? It seems like there is an error being raised where previously there was none, but I can't tell what the error actually is.

The one thing in the changelog which dimly rings a bill here was this one:

Add hidden_applevel to _contextvars.Context.run. Discovered in django PR 17500 to revive PyPy support in django

because some (but not all) of the tracebacks implicate contextvars. Otherwise it just looks like sometimes f_back is going missing.

@glyph
Copy link
Author

glyph commented Jan 12, 2024

How do you usually debug this kind of failure?

The semantics of stack-walking rarely change out from under us in the interpreter, so this is a new domain we don't have experience debugging. I guess with the new GIL removal and JIT stuff in CPython we are in for a spicy couple of years but I don't know how to handle it yet :)

@glyph
Copy link
Author

glyph commented Jan 12, 2024

To this question in particular:

Is there a smaller failing unit test we can run? It seems like there is an error being raised where previously there was none, but I can't tell what the error actually is.

twisted.test.test_defgen.InlineCallbacksTests.testStackUsage does fail on its own, and I don't believe it implicates ContextVars, so it might be closer to the heart of the issue? but it's hardly a nicely isolated test for this specific bug. Maybe you could start thoere to find what's going on though?

@mattip
Copy link
Member

mattip commented Jan 13, 2024

All the tests passed for me. Maybe connected to hypothesis testing and #4839 which was fixed in hypothesis 6.92.5?

pypy3.10 -m venv /tmp/venv3pypy310
source /tmp/venv3pypy310/bin/activate
pip install -e .
pip install pyhamcrest hypothesis
trial twisted.test.test_defgen
twisted.test.test_defgen
  DeferredGeneratorTests
    testBasics ...                                                         [OK]
    testBuggy ...                                                          [OK]
    testDeferredYielding ...                                               [OK]
    testHandledTerminalAsyncFailure ...                                    [OK]
    testHandledTerminalFailure ...                                         [OK]
    testNothing ...                                                        [OK]
    testStackUsage ...                                                     [OK]
    testStackUsage2 ...                                                    [OK]
  DeprecateDeferredGeneratorTests
    test_deferredGeneratorDeprecated ...                                   [OK]
    test_waitForDeferredDeprecated ...                                     [OK]
  InlineCallbacksTests
    testBasics ...                                                         [OK]
    testBuggy ...                                                          [OK]
    testHandledTerminalAsyncFailure ...                                    [OK]
    testHandledTerminalFailure ...                                         [OK]
    testNothing ...                                                        [OK]
    testReturnNoValue ...                                                  [OK]
    testReturnValue ...                                                    [OK]
    testStackUsage ...                                                     [OK]
    testStackUsage2 ...                                                    [OK]
    testYieldNonDeferred ...                                               [OK]
    test_internalDefGenReturnValueDoesntLeak ...                           [OK]
    test_internalStopIterationDoesntLeak ...                               [OK]
    test_nonGeneratorReturn ...                                            [OK]
    test_nonGeneratorReturnValue ...                                       [OK]

@glyph
Copy link
Author

glyph commented Jan 13, 2024

FWIW when I run these commands exactly as written I also get passing tests… because zsh cached the wrong trial, and was not actually running tests in the correct venv.

Here's a set of commands that fail reliably for me:

glyph@arabella:~  🐚 🔑   🐳 🫛  🖥️  ✅  ⮐
  ★ ~/Applications/pypy3.10-v7.3.14-macos_arm64/bin/pypy3.10 -m venv twisted-trunk-failure
 ↩ Sat Jan 13 14:12:24 PST 2024
 ↪ Sat Jan 13 14:12:28 PST 2024 (★ ~/Applications/pypy3.10-v7.3.14-macos_arm64/bin/pypy3.10 -m venv twisted-trunk-failure) (4 seconds elapsed)
glyph@arabella:~  🐚 🔑   🐳 🫛  🖥️  ✅  ⮐
  ★ (cd ~/Projects/Twisted; git show)      
 ↩ Sat Jan 13 14:12:46 PST 2024
commit fec087892993114f1e3eb49381cd979871a1a767 (HEAD -> trunk, origin/trunk, origin/HEAD)
Merge: df30455347 23fdfdd036
Author: Glyph <glyph@twistedmatrix.com>
Date:   Fri Jan 12 10:44:46 2024 -0800

    12078 log regression (#12079)

 ↪ Sat Jan 13 14:12:47 PST 2024 (★ (cd ~/Projects/Twisted; git show)) (1 seconds elapsed)                                                                                     
glyph@arabella:~  🐚 🔑   🐳 🫛  🖥️  ✅  ⮐
  ★ ./twisted-trunk-failure/bin/pip install -e ~/Projects/Twisted 
 ↩ Sat Jan 13 14:12:56 PST 2024
Looking in indexes: http://127.0.0.1:3141/root/plus/+simple/
Obtaining file:///Users/glyph/Projects/Twisted
  Installing build dependencies ... done
  Checking if build backend supports build_editable ... done
  Getting requirements to build editable ... done
  Preparing editable metadata (pyproject.toml) ... done
Collecting attrs>=21.3.0
  Downloading http://127.0.0.1:3141/root/pypi/%2Bf/99b/87a485a5820b2/attrs-23.2.0-py3-none-any.whl (60 kB)
     ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 60.8/60.8 kB 244.3 MB/s eta 0:00:00
Collecting automat>=0.8.0
  Downloading http://127.0.0.1:3141/root/pypi/%2Bf/c31/64f8742b9dc44/Automat-22.10.0-py2.py3-none-any.whl (26 kB)
Collecting constantly>=15.1
  Downloading http://127.0.0.1:3141/root/pypi/%2Bf/3fd/9b4d1c3dc1ec9/constantly-23.10.4-py3-none-any.whl (13 kB)
Collecting hyperlink>=17.1.1
  Downloading http://127.0.0.1:3141/root/pypi/%2Bf/e6b/14c37ecb73e89/hyperlink-21.0.0-py2.py3-none-any.whl (74 kB)
     ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 74.6/74.6 kB 195.4 MB/s eta 0:00:00
Collecting incremental>=22.10.0
  Downloading http://127.0.0.1:3141/root/pypi/%2Bf/b86/4a1f30885ee72/incremental-22.10.0-py2.py3-none-any.whl (16 kB)
Collecting typing-extensions>=4.2.0
  Downloading http://127.0.0.1:3141/root/pypi/%2Bf/af7/2aea155e91adf/typing_extensions-4.9.0-py3-none-any.whl (32 kB)
Collecting zope-interface>=5
  Using cached zope.interface-6.1-py3-none-any.whl
Collecting six
  Downloading http://127.0.0.1:3141/root/pypi/%2Bf/8ab/b2f1d86890a2d/six-1.16.0-py2.py3-none-any.whl (11 kB)
Collecting idna>=2.5
  Downloading http://127.0.0.1:3141/root/pypi/%2Bf/c05/567e9c24a6b9f/idna-3.6-py3-none-any.whl (61 kB)
     ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 61.6/61.6 kB 107.2 MB/s eta 0:00:00
Requirement already satisfied: setuptools in ./twisted-trunk-failure/lib/pypy3.10/site-packages (from zope-interface>=5->Twisted==23.10.0.post0) (65.5.0)
Building wheels for collected packages: Twisted
  Building editable for Twisted (pyproject.toml) ... done
  Created wheel for Twisted: filename=twisted-23.10.0.post0-py3-none-any.whl size=5873 sha256=7f46aa41268233f284be350b72e6d777d02769fd0734e1744c9bfd5bc8fe085e
  Stored in directory: /private/var/folders/yl/ndrrqv712fs02p5sdtxhml7h0000gn/T/pip-ephem-wheel-cache-ey_e166m/wheels/90/e4/5b/4609b8d3f8d4d2c116f571a0889a77874236798796142ff846
Successfully built Twisted
Installing collected packages: incremental, zope-interface, typing-extensions, six, idna, constantly, attrs, hyperlink, automat, Twisted
Successfully installed Twisted-23.10.0.post0 attrs-23.2.0 automat-22.10.0 constantly-23.10.4 hyperlink-21.0.0 idna-3.6 incremental-22.10.0 six-1.16.0 typing-extensions-4.9.0 zope-interface-6.1

[notice] A new release of pip is available: 23.0.1 -> 23.3.2
[notice] To update, run: /Users/glyph/twisted-trunk-failure/bin/pypy3.10 -m pip install --upgrade pip
 ↪ Sat Jan 13 14:13:01 PST 2024 (★ ./twisted-trunk-failure/bin/pip install -e ~/Projects/Twisted) (5 seconds elapsed)                                                         
glyph@arabella:~  🐚 🔑   🐳 🫛  🖥️  ✅  ⮐
  ★ ./twisted-trunk-failure/bin/pip install hypothesis pyhamcrest
 ↩ Sat Jan 13 14:23:59 PST 2024
Looking in indexes: http://127.0.0.1:3141/root/plus/+simple/
Collecting hypothesis
  Downloading http://127.0.0.1:3141/root/pypi/%2Bf/bfe/6173e36c8cf07/hypothesis-6.93.0-py3-none-any.whl (431 kB)
     ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 431.6/431.6 kB 273.4 MB/s eta 0:00:00
Collecting pyhamcrest
  Downloading http://127.0.0.1:3141/root/pypi/%2Bf/f69/13d2f392e30e0/pyhamcrest-2.1.0-py3-none-any.whl (54 kB)
     ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 54.6/54.6 kB 227.7 MB/s eta 0:00:00
Requirement already satisfied: attrs>=22.2.0 in ./twisted-trunk-failure/lib/pypy3.10/site-packages (from hypothesis) (23.2.0)
Collecting sortedcontainers<3.0.0,>=2.1.0
  Downloading http://127.0.0.1:3141/root/pypi/%2Bf/a16/3dcaede0f1c02/sortedcontainers-2.4.0-py2.py3-none-any.whl (29 kB)
Collecting exceptiongroup>=1.0.0
  Downloading http://127.0.0.1:3141/root/pypi/%2Bf/4bf/d3996ac73b41e/exceptiongroup-1.2.0-py3-none-any.whl (16 kB)
Installing collected packages: sortedcontainers, pyhamcrest, exceptiongroup, hypothesis
Successfully installed exceptiongroup-1.2.0 hypothesis-6.93.0 pyhamcrest-2.1.0 sortedcontainers-2.4.0

[notice] A new release of pip is available: 23.0.1 -> 23.3.2
[notice] To update, run: /Users/glyph/twisted-trunk-failure/bin/pypy3.10 -m pip install --upgrade pip
 ↪ Sat Jan 13 14:24:02 PST 2024 (★ ./twisted-trunk-failure/bin/pip install hypothesis pyhamcrest) (3 seconds elapsed)                                                         
glyph@arabella:~  🐚 🔑   🐳 🫛  🖥️  ✅  ⮐
  ★ ./twisted-trunk-failure/bin/trial twisted.test.test_defgen   
 ↩ Sat Jan 13 14:24:17 PST 2024
twisted.test.test_defgen
  DeferredGeneratorTests
    testBasics ...                                                         [OK]
    testBuggy ...                                                          [OK]
    testDeferredYielding ...                                               [OK]
    testHandledTerminalAsyncFailure ...                                    [OK]
    testHandledTerminalFailure ...                                         [OK]
    testNothing ...                                                        [OK]
    testStackUsage ...                                                     [OK]
    testStackUsage2 ...                                                    [OK]
  DeprecateDeferredGeneratorTests
    test_deferredGeneratorDeprecated ...                                   [OK]
    test_waitForDeferredDeprecated ...                                     [OK]
  InlineCallbacksTests
    testBasics ...                                                      [ERROR]
    testBuggy ...                                                          [OK]
    testHandledTerminalAsyncFailure ...                                    [OK]
    testHandledTerminalFailure ...                                         [OK]
    testNothing ...                                                        [OK]
    testReturnNoValue ...                                                  [OK]
    testReturnValue ...                                                 [ERROR]
    testStackUsage ...                                                  [ERROR]
    testStackUsage2 ...                                                 [ERROR]
    testYieldNonDeferred ...                                            [ERROR]
    test_internalDefGenReturnValueDoesntLeak ...                         [FAIL]
    test_internalStopIterationDoesntLeak ...                               [OK]
    test_nonGeneratorReturn ...                                            [OK]
    test_nonGeneratorReturnValue ...                                       [OK]

===============================================================================
[FAIL]
Traceback (most recent call last):
  File "/Users/glyph/Projects/Twisted/src/twisted/test/test_defgen.py", line 366, in test_internalDefGenReturnValueDoesntLeak
    tb = self.successResultOf(d)
  File "/Users/glyph/Projects/Twisted/src/twisted/trial/_synctest.py", line 723, in successResultOf
    self.fail(
twisted.trial.unittest.FailTest: Success result expected on <Deferred at 0x1581afef8>, found no result instead

twisted.test.test_defgen.InlineCallbacksTests.test_internalDefGenReturnValueDoesntLeak
===============================================================================
[ERROR]
Traceback (most recent call last):
Failure: twisted.internet.defer.TimeoutError: <twisted.test.test_defgen.InlineCallbacksTests testMethod=testBasics> (testBasics) still running at 120.0 secs

twisted.test.test_defgen.InlineCallbacksTests.testBasics
===============================================================================
[ERROR]
Traceback (most recent call last):
  File "/Users/glyph/Projects/Twisted/src/twisted/test/test_defgen.py", line 312, in testReturnValue
    return _return().addCallback(self.assertEqual, 6)
  File "/Users/glyph/Projects/Twisted/src/twisted/internet/defer.py", line 2256, in unwindGenerator
    return _cancellableInlineCallbacks(gen)
  File "/Users/glyph/Projects/Twisted/src/twisted/internet/defer.py", line 2168, in _cancellableInlineCallbacks
    _inlineCallbacks(None, gen, status, _copy_context())
  File "/Users/glyph/Projects/Twisted/src/twisted/internet/defer.py", line 2042, in _inlineCallbacks
    assert appCodeTrace.tb_next is not None
builtins.AssertionError: 

twisted.test.test_defgen.InlineCallbacksTests.testReturnValue
===============================================================================
[ERROR]
Traceback (most recent call last):
  File "/Users/glyph/Projects/Twisted/src/twisted/test/test_defgen.py", line 99, in testStackUsage
    return self._genStackUsage().addCallback(self.assertEqual, 0)
  File "/Users/glyph/Projects/Twisted/src/twisted/internet/defer.py", line 2256, in unwindGenerator
    return _cancellableInlineCallbacks(gen)
  File "/Users/glyph/Projects/Twisted/src/twisted/internet/defer.py", line 2168, in _cancellableInlineCallbacks
    _inlineCallbacks(None, gen, status, _copy_context())
  File "/Users/glyph/Projects/Twisted/src/twisted/internet/defer.py", line 2042, in _inlineCallbacks
    assert appCodeTrace.tb_next is not None
builtins.AssertionError: 

twisted.test.test_defgen.InlineCallbacksTests.testStackUsage
===============================================================================
[ERROR]
Traceback (most recent call last):
  File "/Users/glyph/Projects/Twisted/src/twisted/test/test_defgen.py", line 106, in testStackUsage2
    return self._genStackUsage2().addCallback(self.assertEqual, 0)
  File "/Users/glyph/Projects/Twisted/src/twisted/internet/defer.py", line 2256, in unwindGenerator
    return _cancellableInlineCallbacks(gen)
  File "/Users/glyph/Projects/Twisted/src/twisted/internet/defer.py", line 2168, in _cancellableInlineCallbacks
    _inlineCallbacks(None, gen, status, _copy_context())
  File "/Users/glyph/Projects/Twisted/src/twisted/internet/defer.py", line 2042, in _inlineCallbacks
    assert appCodeTrace.tb_next is not None
builtins.AssertionError: 

twisted.test.test_defgen.InlineCallbacksTests.testStackUsage2
===============================================================================
[ERROR]
Traceback (most recent call last):
  File "/Users/glyph/Projects/Twisted/src/twisted/test/test_defgen.py", line 290, in testYieldNonDeferred
    return _test().addCallback(self.assertEqual, 5)
  File "/Users/glyph/Projects/Twisted/src/twisted/internet/defer.py", line 2256, in unwindGenerator
    return _cancellableInlineCallbacks(gen)
  File "/Users/glyph/Projects/Twisted/src/twisted/internet/defer.py", line 2168, in _cancellableInlineCallbacks
    _inlineCallbacks(None, gen, status, _copy_context())
  File "/Users/glyph/Projects/Twisted/src/twisted/internet/defer.py", line 2042, in _inlineCallbacks
    assert appCodeTrace.tb_next is not None
builtins.AssertionError: 

twisted.test.test_defgen.InlineCallbacksTests.testYieldNonDeferred
-------------------------------------------------------------------------------
Ran 24 tests in 120.155s

FAILED (failures=1, errors=5, successes=18)
 ↪ Sat Jan 13 14:26:18 PST 2024 (★ ./twisted-trunk-failure/bin/trial twisted.test.test_defgen) (121 seconds elapsed)                                                          
glyph@arabella:~  🐚 🔑   🛑 1  🐳 🫛  🖥️  ✅  ⮐
  ★ 

Note that the tests hang for about 2 minutes on twisted.test.test_defgen.InlineCallbacksTests.testBasics for about 2 minutes.

Our CI does not pin Hypothesis or PyHamcrest, so if that were the bug, we wouldn't be seeing it on current builds.

@mattip
Copy link
Member

mattip commented Jan 13, 2024

Got it: the tests pass if I remove the hidden_app decorator around Context.run

@hidden_applevel
added for the Django tests in f13e48c. That effectively reverts the commit. I wonder if there is some PyPy-specific code that expects a certain stack depth? Adding the decorator makes PyPy more like CPython, since in CPython the code in question is written in C and does not appear in stack traces.

@mattip
Copy link
Member

mattip commented Jan 14, 2024

I think this fixes it:

diff --git a/src/twisted/internet/defer.py b/src/twisted/internet/defer.py
index 36e1d988f9..14aebeaf3d 100644
--- a/src/twisted/internet/defer.py
+++ b/src/twisted/internet/defer.py
@@ -17,7 +17,7 @@ from asyncio import AbstractEventLoop, Future, iscoroutine
 from contextvars import Context as _Context, copy_context as _copy_context
 from enum import Enum
 from functools import wraps
-from sys import exc_info
+from sys import exc_info, implementation
 from types import CoroutineType, GeneratorType, MappingProxyType, TracebackType
 from typing import (
     TYPE_CHECKING,
@@ -54,6 +54,8 @@ from twisted.python.failure import Failure, _extraneous
 
 log = Logger()
 
+_STACK_LEVEL_INCOMPATIBLE = _PYPY and implementation.version < (7, 3, 14)
+
 
 _T = TypeVar("_T")
 _P = ParamSpec("_P")
@@ -2022,8 +2024,8 @@ def _inlineCallbacks(
             appCodeTrace = traceback.tb_next
             assert appCodeTrace is not None
 
-            if _PYPY:
-                # PyPy as of 3.7 adds an extra frame.
+            if _STACK_LEVEL_INCOMPATIBLE:
+                # PyPy as of 3.7 and before 7.3.14 adds an extra frame.
                 appCodeTrace = appCodeTrace.tb_next
                 assert appCodeTrace is not None

@glyph
Copy link
Author

glyph commented Jan 14, 2024

Landed in Twisted, so I think we're done here. Thanks again @mattip !

@glyph glyph closed this as completed Jan 14, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants