touilleMan
commented
2 years ago Another failed build, this one is particularly interesting given the failling test (tests/backend/test_s3_blockstore.py::test_s3_read) is basically totally isolated (no custom fixtures, no use of postgresql, no server, no backend etc.)
This let me think the error log comes from a previous test that hasn't finished it teardown...
$ poetry run pytest --log-level=DEBUG --durations=10 --side-effects-timeout=10 -vv -x tests/backend tests/test_cli.py -k 'not test_shuffle_roles' --postgresql --runslow
tests/backend/test_postgres_db.py::test_retry_policy_no_retry PASSED [ 31%]
tests/backend/test_postgres_db.py::test_retry_policy_allow_retry PASSED [ 31%]
tests/backend/test_s3_blockstore.py::test_s3_read FAILED [ 31%]
tests/backend/test_s3_blockstore.py::test_s3_read ERROR [ 31%]
==================================== ERRORS ====================================
______________________ ERROR at teardown of test_s3_read _______________________
caplog = <_pytest.logging.LogCaptureFixture object at 0x7f5871e54280>
@pytest.fixture(autouse=True)
def no_logs_gte_error(caplog):
yield
# TODO: Concurrency bug in Hypercorn when the server is torndown while a
# client websocket is currently disconnecting
# see: https://github.com/Scille/parsec-cloud/issues/2716
def skip_hypercorn_buggy_log(record):
if record.name == "asyncio" and isinstance(record.exc_info, ConnectionError):
return True
if record.name != "hypercorn.error":
return True
if record.exc_text.endswith(
"wsproto.utilities.LocalProtocolError: Connection cannot be closed in state ConnectionState.CLOSED"
):
return False
if record.exc_text.endswith(
"trio.BusyResourceError: another task is currently sending data on this SocketStream"
):
return False
return True
# The test should use `caplog.assert_occured_once` to indicate a log was expected,
# otherwise we consider error logs as *actual* errors.
asserted_records = getattr(caplog, "asserted_records", set())
errors = [
record
for record in caplog.get_records("call")
if record.levelno >= logging.ERROR
and record not in asserted_records
and skip_hypercorn_buggy_log(record)
]
> assert not errors
E assert not [<LogRecord: asyncio, 40, /opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/asyncio/base_events.py, 1786, "Exception in default exception handler">]
tests/conftest.py:277: AssertionError
------------------------------ Captured log call -------------------------------
ERROR asyncio:base_events.py:1786 Exception in default exception handler
Traceback (most recent call last):
File "/home/runner/work/parsec-cloud/parsec-cloud/parsec/backend/s3_blockstore.py", line 42, in read
obj = self._s3.get_object(Bucket=self._s3_bucket, Key=slug)
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1092, in __call__
return self._mock_call(*args, **kwargs)
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1096, in _mock_call
return self._execute_mock_call(*args, **kwargs)
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1151, in _execute_mock_call
raise effect
botocore.exceptions.ClientError: An error occurred (404) when calling the GET operation: Unknown
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/asyncio/base_events.py", line 1779, in call_exception_handler
self.default_exception_handler(context)
File "/home/runner/.cache/pypoetry/virtualenvs/parsec-cloud-dZ-E5qY_-py3.9/lib/python3.9/site-packages/trio_asyncio/_async.py", line 44, in default_exception_handler
raise exception
ConnectionError: unexpected connection_lost() call
WARNING parsec.backend.s3_blockstore:s3_blockstore.py:44 2022-08-17 17:12:11 [warning ] Block read error [parsec.backend.s3_blockstore] block_id=0694a21176354e8295e28a543e5887f9 blockstore_type=S3 organization_id=org42 s3_bucket=parsec s3_region=europe
Traceback (most recent call last):
File "/home/runner/work/parsec-cloud/parsec-cloud/parsec/backend/s3_blockstore.py", line 42, in read
obj = self._s3.get_object(Bucket=self._s3_bucket, Key=slug)
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1092, in __call__
return self._mock_call(*args, **kwargs)
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1096, in _mock_call
return self._execute_mock_call(*args, **kwargs)
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1151, in _execute_mock_call
raise effect
botocore.exceptions.ClientError: An error occurred (404) when calling the GET operation: Unknown
=================================== FAILURES ===================================
_________________________________ test_s3_read _________________________________
value = <trio.Nursery object at 0x7f5871eb30d0>
async def yield_(value=None):
> return await _yield_(value)
../../../.cache/pypoetry/virtualenvs/parsec-cloud-dZ-E5qY_-py3.9/lib/python3.9/site-packages/async_generator/_impl.py:106:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
../../../.cache/pypoetry/virtualenvs/parsec-cloud-dZ-E5qY_-py3.9/lib/python3.9/site-packages/async_generator/_impl.py:99: in _yield_
return (yield _wrap(value))
tests/backend/test_s3_blockstore.py:51: in test_s3_read
_assert_log()
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
def _assert_log():
log = caplog.assert_occured_once("[warning ] Block read error")
assert f"organization_id={org_id}" in log
assert f"block_id={block_id}" in log
> assert len(caplog.messages) == 1
E assert 2 == 1
E + where 2 = len(['Exception in default exception handler', '\x1b[2m2022-08-17 17:12:11\x1b[0m [\x1b[33m\x1b[1mwarning \x1b[0m] \x1b[1mBlock read error \x1b[0m [\x1b[34m\x1b[1mparsec.backend.s3_blockstore\x1b[0m] \x1b[36mblock_id\x1b[0m=\x1b[35m0694a21176354e8295e28a543e5887f9\x1b[0m \x1b[36mblockstore_type\x1b[0m=\x1b[35mS3\x1b[0m \x1b[36morganization_id\x1b[0m=\x1b[35morg42\x1b[0m \x1b[36ms3_bucket\x1b[0m=\x1b[35mparsec\x1b[0m \x1b[36ms3_region\x1b[0m=\x1b[35meurope\x1b[0m\nTraceback (most recent call last):\n File "/home/runner/work/parsec-cloud/parsec-cloud/parsec/backend/s3_blockstore.py", line 42, in read\n obj = self._s3.get_object(Bucket=self._s3_bucket, Key=slug)\n File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1092, in __call__\n return self._mock_call(*args, **kwargs)\n File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1096, in _mock_call\n return self._execute_mock_call(*args, **kwargs)\n File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1151, in _execute_mock_call\n raise effect\nbotocore.exceptions.ClientError: An error occurred (404) when calling the GET operation: Unknown'])
E + where ['Exception in default exception handler', '\x1b[2m2022-08-17 17:12:11\x1b[0m [\x1b[33m\x1b[1mwarning \x1b[0m] \x1b[1mBlock read error \x1b[0m [\x1b[34m\x1b[1mparsec.backend.s3_blockstore\x1b[0m] \x1b[36mblock_id\x1b[0m=\x1b[35m0694a21176354e8295e28a543e5887f9\x1b[0m \x1b[36mblockstore_type\x1b[0m=\x1b[35mS3\x1b[0m \x1b[36morganization_id\x1b[0m=\x1b[35morg42\x1b[0m \x1b[36ms3_bucket\x1b[0m=\x1b[35mparsec\x1b[0m \x1b[36ms3_region\x1b[0m=\x1b[35meurope\x1b[0m\nTraceback (most recent call last):\n File "/home/runner/work/parsec-cloud/parsec-cloud/parsec/backend/s3_blockstore.py", line 42, in read\n obj = self._s3.get_object(Bucket=self._s3_bucket, Key=slug)\n File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1092, in __call__\n return self._mock_call(*args, **kwargs)\n File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1096, in _mock_call\n return self._execute_mock_call(*args, **kwargs)\n File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1151, in _execute_mock_call\n raise effect\nbotocore.exceptions.ClientError: An error occurred (404) when calling the GET operation: Unknown'] = <_pytest.logging.LogCaptureFixture object at 0x7f5871e54280>.messages
tests/backend/test_s3_blockstore.py:26: AssertionError
------------------------------ Captured log call -------------------------------
ERROR asyncio:base_events.py:1786 Exception in default exception handler
Traceback (most recent call last):
File "/home/runner/work/parsec-cloud/parsec-cloud/parsec/backend/s3_blockstore.py", line 42, in read
obj = self._s3.get_object(Bucket=self._s3_bucket, Key=slug)
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1092, in __call__
return self._mock_call(*args, **kwargs)
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1096, in _mock_call
return self._execute_mock_call(*args, **kwargs)
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1151, in _execute_mock_call
raise effect
botocore.exceptions.ClientError: An error occurred (404) when calling the GET operation: Unknown
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/asyncio/base_events.py", line 1779, in call_exception_handler
self.default_exception_handler(context)
File "/home/runner/.cache/pypoetry/virtualenvs/parsec-cloud-dZ-E5qY_-py3.9/lib/python3.9/site-packages/trio_asyncio/_async.py", line 44, in default_exception_handler
raise exception
ConnectionError: unexpected connection_lost() call
WARNING parsec.backend.s3_blockstore:s3_blockstore.py:44 2022-08-17 17:12:11 [warning ] Block read error [parsec.backend.s3_blockstore] block_id=0694a21176354e8295e28a543e5887f9 blockstore_type=S3 organization_id=org42 s3_bucket=parsec s3_region=europe
Traceback (most recent call last):
File "/home/runner/work/parsec-cloud/parsec-cloud/parsec/backend/s3_blockstore.py", line 42, in read
obj = self._s3.get_object(Bucket=self._s3_bucket, Key=slug)
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1092, in __call__
return self._mock_call(*args, **kwargs)
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1096, in _mock_call
return self._execute_mock_call(*args, **kwargs)
File "/opt/hostedtoolcache/Python/3.9.13/x64/lib/python3.9/unittest/mock.py", line 1151, in _execute_mock_call
raise effect
botocore.exceptions.ClientError: An error occurred (404) when calling the GET operation: Unknown
============================= slowest 10 durations =============================
17.49s call tests/backend/test_postgres_concurrency.py::test_concurrency_pki_enrollment_accept
15.09s call tests/backend/test_postgres_concurrency.py::test_concurrency_create_user
6.35s call tests/backend/test_pki.py::test_pki_info_accepted
6.30s call tests/backend/test_pki.py::test_pki_info_rejected
5.44s call tests/backend/test_access.py::test_invited_has_limited_access
5.25s call tests/backend/test_pki.py::test_pki_complete_sequence
5.17s call tests/backend/test_pki.py::test_pki_info
5.14s call tests/backend/test_pki.py::test_pki_reject
5.13s call tests/backend/test_pki.py::test_pki_reject_already_accepted
5.13s call tests/backend/test_administration_rest_api.py::test_organization_stats_data
=========================== short test summary info ============================
FAILED tests/backend/test_s3_blockstore.py::test_s3_read - assert 2 == 1
ERROR tests/backend/test_s3_blockstore.py::test_s3_read - assert not [<LogRec...
https://github.com/Scille/parsec-cloud/runs/7555808465?check_suite_focus=true#step:14:201
Current workaround https://github.com/Scille/parsec-cloud/blob/eea65866a967daeaad0dcdc07153bb54830b8760/tests/conftest.py#L255-L269