Test failure in test_executemany_server_failure_during_writes

musicinmybrain commented 1 year ago

asyncpg version: 0.29.0
PostgreSQL version: 15.4
Do you use a PostgreSQL SaaS? If so, which? Can you reproduce the issue with a local PostgreSQL install?: N/A, building the python-asyncpg package on Fedora Linux infrastructure
Python version: 3.12.0
Platform: Fedora Linux Rawhide, ~~s390x architecture (only!)~~
Do you use pgbouncer?: No
Did you install asyncpg with pip?: No, I am the maintainer of the distribution package.
If you built asyncpg locally, which version of Cython did you use?: 0.29.35
Can the issue be reproduced under both asyncio and uvloop?: ~~No, only asyncio.~~ yes

This is new in 0.29.0. I don’t have any idea why it is happening.

~~I can’t reproduce this with PYTHONASYNCIODEBUG=1, nor can I reproduce it with USE_UVLOOP=1.~~ I have now seen this on x86_64 with asyncio and PYTHONASYNCIODEBUG=1.

~~I don’t have interactive access to an s390x machine, but~~ I am happy to run experiments or test proposed fixes by submitting package test builds on Fedora infrastructure. For the time being, I plan to simply skip this test ~~on s390x~~.

=================================== FAILURES ===================================
________ TestExecuteMany.test_executemany_server_failure_during_writes _________
Traceback (most recent call last):
  File "/usr/lib64/python3.12/unittest/case.py", line 58, in testPartExecutor
    yield
  File "/usr/lib64/python3.12/unittest/case.py", line 634, in run
    self._callTestMethod(testMethod)
  File "/usr/lib64/python3.12/unittest/case.py", line 589, in _callTestMethod
    if method() is not None:
       ^^^^^^^^
  File "/builddir/build/BUILDROOT/python-asyncpg-0.29.0-1.fc40.s390x/usr/lib64/python3.12/site-packages/asyncpg/_testbase/__init__.py", line 92, in wrapper
    self.loop.run_until_complete(coro)
  File "/usr/lib64/python3.12/asyncio/base_events.py", line 664, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "/builddir/build/BUILD/asyncpg-0.29.0/tests/test_execute.py", line 215, in test_executemany_server_failure_during_writes
    self.assertLess(pos, 128, 'should stop early')
  File "/usr/lib64/python3.12/unittest/case.py", line 1257, in assertLess
    self.fail(self._formatMessage(msg, standardMsg))
  File "/usr/lib64/python3.12/unittest/case.py", line 715, in fail
    raise self.failureException(msg)
AssertionError: 128 not less than 128 : should stop early

musicinmybrain commented 1 year ago

I edited the original report because I have now seen this on x86_64 with asyncio and PYTHONASYNCIODEBUG=1 on Fedora 39:

=================================== FAILURES ===================================
________ TestExecuteMany.test_executemany_server_failure_during_writes _________
Traceback (most recent call last):
  File "/builddir/build/BUILD/asyncpg-0.29.0/tests/test_execute.py", line 215, in test_executemany_server_failure_during_writes
    self.assertLess(pos, 128, 'should stop early')
  File "/usr/lib64/python3.12/unittest/case.py", line 1257, in assertLess
    self.fail(self._formatMessage(msg, standardMsg))
  File "/usr/lib64/python3.12/unittest/case.py", line 715, in fail
    raise self.failureException(msg)
AssertionError: 128 not less than 128 : should stop early
=============================== warnings summary ===============================
tests/test_adversity.py::TestConnectionLoss::test_pool_release_timeout
  /usr/lib64/python3.12/asyncio/events.py:84: ResourceWarning: unclosed <socket.socket fd=19, family=2, type=1, proto=0, laddr=('127.0.0.1', 41479), raddr=('127.0.0.1', 49274)>
    self._context.run(self._callback, *self._args)
  Enable tracemalloc to get traceback where the object was allocated.
  See https://docs.pytest.org/en/stable/how-to/capture-warnings.html#resource-warnings for more info.

tests/test_adversity.py::TestConnectionLoss::test_pool_release_timeout
  /usr/lib64/python3.12/asyncio/events.py:84: ResourceWarning: unclosed <socket.socket fd=12, family=2, type=1, proto=0, laddr=('127.0.0.1', 35146), raddr=('127.0.0.1', 47067)>
    self._context.run(self._callback, *self._args)
  Enable tracemalloc to get traceback where the object was allocated.
  See https://docs.pytest.org/en/stable/how-to/capture-warnings.html#resource-warnings for more info.

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
=========================== short test summary info ============================
FAILED tests/test_execute.py::TestExecuteMany::test_executemany_server_failure_during_writes
= 1 failed, 302 passed, 2 skipped, 1 deselected, 2 warnings in 153.72s (0:02:33) =

musicinmybrain commented 2 weeks ago

I just confirmed this is still present with 0.30.0 and Python 3.13.0 in Fedora 42/Rawhide. Doing builds on all of x86_64, aarch64, ppc64le, and s390x, the first build succeeded and the second build failed on s390x only:

=================================== FAILURES ===================================
________ TestExecuteMany.test_executemany_server_failure_during_writes _________
Traceback (most recent call last):
  File "/usr/lib64/python3.13/unittest/case.py", line 58, in testPartExecutor
    yield
  File "/usr/lib64/python3.13/unittest/case.py", line 651, in run
    self._callTestMethod(testMethod)
    ~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^
  File "/usr/lib64/python3.13/unittest/case.py", line 606, in _callTestMethod
    if method() is not None:
       ~~~~~~^^
  File "/builddir/build/BUILD/python-asyncpg-0.30.0-build/BUILDROOT/usr/lib64/python3.13/site-packages/asyncpg/_testbase/__init__.py", line 92, in wrapper
    self.loop.run_until_complete(coro)
    ~~~~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^
  File "/usr/lib64/python3.13/asyncio/base_events.py", line 721, in run_until_complete
    return future.result()
           ~~~~~~~~~~~~~^^
  File "/builddir/build/BUILD/python-asyncpg-0.30.0-build/asyncpg-0.30.0/tests/test_execute.py", line 254, in test_executemany_server_failure_during_writes
    self.assertLess(pos, 128, 'should stop early')
    ~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.13/unittest/case.py", line 1279, in assertLess
    self.fail(self._formatMessage(msg, standardMsg))
    ~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib64/python3.13/unittest/case.py", line 732, in fail
    raise self.failureException(msg)
AssertionError: 128 not less than 128 : should stop early
=========================== short test summary info ============================
FAILED tests/test_execute.py::TestExecuteMany::test_executemany_server_failure_during_writes
============= 1 failed, 307 passed, 5 skipped in 84.34s (0:01:24) ==============

In this case, the failure happened when neither PYTHONASYNCIODEBUG=1 nor USE_UVLOOP=1 was set, although I don’t have any reason to believe that’s significant.

I assume that if I did more builds, I would see more flaky failures including some on other architectures.

MagicStack / asyncpg

Test failure in test_executemany_server_failure_during_writes #1099