From ea87853188e76f8d854a3de20da62376d89fd6f9 Mon Sep 17 00:00:00 2001 From: reivilibre Date: Wed, 30 Jul 2025 13:03:56 +0100 Subject: [PATCH] Work around `twisted.protocols.amp.TooLong` error by reducing logging in some tests. (#18736) Part of: https://github.com/element-hq/synapse/issues/18537 Works around: https://github.com/twisted/twisted/issues/12482 --------- Signed-off-by: Olivier 'reivilibre --- changelog.d/18736.misc | 1 + tests/replication/tcp/streams/test_typing.py | 128 ++++++++------- tests/rest/client/test_profile.py | 161 ++++++++++--------- 3 files changed, 158 insertions(+), 132 deletions(-) create mode 100644 changelog.d/18736.misc diff --git a/changelog.d/18736.misc b/changelog.d/18736.misc new file mode 100644 index 000000000..f9a66d465 --- /dev/null +++ b/changelog.d/18736.misc @@ -0,0 +1 @@ +Work around `twisted.protocols.amp.TooLong` error by reducing logging in some tests. diff --git a/tests/replication/tcp/streams/test_typing.py b/tests/replication/tcp/streams/test_typing.py index c8958189f..e2b229910 100644 --- a/tests/replication/tcp/streams/test_typing.py +++ b/tests/replication/tcp/streams/test_typing.py @@ -18,6 +18,7 @@ # [This file includes modifications made by New Vector Limited] # # +import logging from unittest.mock import Mock from synapse.handlers.typing import RoomMember, TypingWriterHandler @@ -99,75 +100,86 @@ class TypingStreamTestCase(BaseStreamTestCase): This is emulated by jumping the stream ahead, then reconnecting (which sends the proper position and RDATA). """ - typing = self.hs.get_typing_handler() - assert isinstance(typing, TypingWriterHandler) + # FIXME: Because huge RDATA log line is triggered in this test, + # trial breaks, sometimes (flakily) failing the test run. + # ref: https://github.com/twisted/twisted/issues/12482 + # To remove this, we would need to fix the above issue and + # update, including in olddeps (so several years' wait). + server_logger = logging.getLogger("tests.server") + server_logger_was_disabled = server_logger.disabled + server_logger.disabled = True + try: + typing = self.hs.get_typing_handler() + assert isinstance(typing, TypingWriterHandler) - # Create a typing update before we reconnect so that there is a missing - # update to fetch. - typing._push_update(member=RoomMember(ROOM_ID, USER_ID), typing=True) + # Create a typing update before we reconnect so that there is a missing + # update to fetch. + typing._push_update(member=RoomMember(ROOM_ID, USER_ID), typing=True) - self.reconnect() + self.reconnect() - typing._push_update(member=RoomMember(ROOM_ID, USER_ID), typing=True) + typing._push_update(member=RoomMember(ROOM_ID, USER_ID), typing=True) - self.reactor.advance(0) + self.reactor.advance(0) - # We should now see an attempt to connect to the master - request = self.handle_http_replication_attempt() - self.assert_request_is_get_repl_stream_updates(request, "typing") + # We should now see an attempt to connect to the master + request = self.handle_http_replication_attempt() + self.assert_request_is_get_repl_stream_updates(request, "typing") - self.mock_handler.on_rdata.assert_called_once() - stream_name, _, token, rdata_rows = self.mock_handler.on_rdata.call_args[0] - self.assertEqual(stream_name, "typing") - self.assertEqual(1, len(rdata_rows)) - row: TypingStream.TypingStreamRow = rdata_rows[0] - self.assertEqual(ROOM_ID, row.room_id) - self.assertEqual([USER_ID], row.user_ids) + self.mock_handler.on_rdata.assert_called_once() + stream_name, _, token, rdata_rows = self.mock_handler.on_rdata.call_args[0] + self.assertEqual(stream_name, "typing") + self.assertEqual(1, len(rdata_rows)) + row: TypingStream.TypingStreamRow = rdata_rows[0] + self.assertEqual(ROOM_ID, row.room_id) + self.assertEqual([USER_ID], row.user_ids) - # Push the stream forward a bunch so it can be reset. - for i in range(100): - typing._push_update( - member=RoomMember(ROOM_ID, "@test%s:blue" % i), typing=True + # Push the stream forward a bunch so it can be reset. + for i in range(100): + typing._push_update( + member=RoomMember(ROOM_ID, "@test%s:blue" % i), typing=True + ) + self.reactor.advance(0) + + # Disconnect. + self.disconnect() + + # Reset the typing handler + self.hs.get_replication_streams()["typing"].last_token = 0 + self.hs.get_replication_command_handler()._streams["typing"].last_token = 0 + typing._latest_room_serial = 0 + typing._typing_stream_change_cache = StreamChangeCache( + name="TypingStreamChangeCache", + server_name=self.hs.hostname, + current_stream_pos=typing._latest_room_serial, ) - self.reactor.advance(0) + typing._reset() - # Disconnect. - self.disconnect() + # Reconnect. + self.reconnect() + self.pump(0.1) - # Reset the typing handler - self.hs.get_replication_streams()["typing"].last_token = 0 - self.hs.get_replication_command_handler()._streams["typing"].last_token = 0 - typing._latest_room_serial = 0 - typing._typing_stream_change_cache = StreamChangeCache( - name="TypingStreamChangeCache", - server_name=self.hs.hostname, - current_stream_pos=typing._latest_room_serial, - ) - typing._reset() + # We should now see an attempt to connect to the master + request = self.handle_http_replication_attempt() + self.assert_request_is_get_repl_stream_updates(request, "typing") - # Reconnect. - self.reconnect() - self.pump(0.1) + # Reset the test code. + self.mock_handler.on_rdata.reset_mock() + self.mock_handler.on_rdata.assert_not_called() - # We should now see an attempt to connect to the master - request = self.handle_http_replication_attempt() - self.assert_request_is_get_repl_stream_updates(request, "typing") + # Push additional data. + typing._push_update(member=RoomMember(ROOM_ID_2, USER_ID_2), typing=False) + self.reactor.advance(0) - # Reset the test code. - self.mock_handler.on_rdata.reset_mock() - self.mock_handler.on_rdata.assert_not_called() + self.mock_handler.on_rdata.assert_called_once() + stream_name, _, token, rdata_rows = self.mock_handler.on_rdata.call_args[0] + self.assertEqual(stream_name, "typing") + self.assertEqual(1, len(rdata_rows)) + row = rdata_rows[0] + self.assertEqual(ROOM_ID_2, row.room_id) + self.assertEqual([], row.user_ids) - # Push additional data. - typing._push_update(member=RoomMember(ROOM_ID_2, USER_ID_2), typing=False) - self.reactor.advance(0) - - self.mock_handler.on_rdata.assert_called_once() - stream_name, _, token, rdata_rows = self.mock_handler.on_rdata.call_args[0] - self.assertEqual(stream_name, "typing") - self.assertEqual(1, len(rdata_rows)) - row = rdata_rows[0] - self.assertEqual(ROOM_ID_2, row.room_id) - self.assertEqual([], row.user_ids) - - # The token should have been reset. - self.assertEqual(token, 1) + # The token should have been reset. + self.assertEqual(token, 1) + finally: + server_logger.disabled = server_logger_was_disabled diff --git a/tests/rest/client/test_profile.py b/tests/rest/client/test_profile.py index efe5e955a..936e573bc 100644 --- a/tests/rest/client/test_profile.py +++ b/tests/rest/client/test_profile.py @@ -21,6 +21,7 @@ """Tests REST events for /profile paths.""" +import logging import urllib.parse from http import HTTPStatus from typing import Any, Dict, Optional @@ -648,87 +649,99 @@ class ProfileTestCase(unittest.HomeserverTestCase): """ Attempts to set a custom field that would push the overall profile too large. """ - # Get right to the boundary: - # len("displayname") + len("owner") + 5 = 21 for the displayname - # 1 + 65498 + 5 for key "a" = 65504 - # 2 braces, 1 comma - # 3 + 21 + 65498 = 65522 < 65536. - key = "a" - channel = self.make_request( - "PUT", - f"/_matrix/client/v3/profile/{self.owner}/{key}", - content={key: "a" * 65498}, - access_token=self.owner_tok, - ) - self.assertEqual(channel.code, 200, channel.result) + # FIXME: Because we emit huge SQL log lines and trial can't handle these, + # sometimes (flakily) failing the test run, + # disable SQL logging for this test. + # ref: https://github.com/twisted/twisted/issues/12482 + # To remove this, we would need to fix the above issue and + # update, including in olddeps (so several years' wait). + sql_logger = logging.getLogger("synapse.storage.SQL") + sql_logger_was_disabled = sql_logger.disabled + sql_logger.disabled = True + try: + # Get right to the boundary: + # len("displayname") + len("owner") + 5 = 21 for the displayname + # 1 + 65498 + 5 for key "a" = 65504 + # 2 braces, 1 comma + # 3 + 21 + 65498 = 65522 < 65536. + key = "a" + channel = self.make_request( + "PUT", + f"/_matrix/client/v3/profile/{self.owner}/{key}", + content={key: "a" * 65498}, + access_token=self.owner_tok, + ) + self.assertEqual(channel.code, 200, channel.result) - # Get the entire profile. - channel = self.make_request( - "GET", - f"/_matrix/client/v3/profile/{self.owner}", - access_token=self.owner_tok, - ) - self.assertEqual(channel.code, 200, channel.result) - canonical_json = encode_canonical_json(channel.json_body) - # 6 is the minimum bytes to store a value: 4 quotes, 1 colon, 1 comma, an empty key. - # Be one below that so we can prove we're at the boundary. - self.assertEqual(len(canonical_json), MAX_PROFILE_SIZE - 8) + # Get the entire profile. + channel = self.make_request( + "GET", + f"/_matrix/client/v3/profile/{self.owner}", + access_token=self.owner_tok, + ) + self.assertEqual(channel.code, 200, channel.result) + canonical_json = encode_canonical_json(channel.json_body) + # 6 is the minimum bytes to store a value: 4 quotes, 1 colon, 1 comma, an empty key. + # Be one below that so we can prove we're at the boundary. + self.assertEqual(len(canonical_json), MAX_PROFILE_SIZE - 8) - # Postgres stores JSONB with whitespace, while SQLite doesn't. - if USE_POSTGRES_FOR_TESTS: - ADDITIONAL_CHARS = 0 - else: - ADDITIONAL_CHARS = 1 + # Postgres stores JSONB with whitespace, while SQLite doesn't. + if USE_POSTGRES_FOR_TESTS: + ADDITIONAL_CHARS = 0 + else: + ADDITIONAL_CHARS = 1 - # The next one should fail, note the value has a (JSON) length of 2. - key = "b" - channel = self.make_request( - "PUT", - f"/_matrix/client/v3/profile/{self.owner}/{key}", - content={key: "1" + "a" * ADDITIONAL_CHARS}, - access_token=self.owner_tok, - ) - self.assertEqual(channel.code, 400, channel.result) - self.assertEqual(channel.json_body["errcode"], Codes.PROFILE_TOO_LARGE) + # The next one should fail, note the value has a (JSON) length of 2. + key = "b" + channel = self.make_request( + "PUT", + f"/_matrix/client/v3/profile/{self.owner}/{key}", + content={key: "1" + "a" * ADDITIONAL_CHARS}, + access_token=self.owner_tok, + ) + self.assertEqual(channel.code, 400, channel.result) + self.assertEqual(channel.json_body["errcode"], Codes.PROFILE_TOO_LARGE) - # Setting an avatar or (longer) display name should not work. - channel = self.make_request( - "PUT", - f"/profile/{self.owner}/displayname", - content={"displayname": "owner12345678" + "a" * ADDITIONAL_CHARS}, - access_token=self.owner_tok, - ) - self.assertEqual(channel.code, 400, channel.result) - self.assertEqual(channel.json_body["errcode"], Codes.PROFILE_TOO_LARGE) + # Setting an avatar or (longer) display name should not work. + channel = self.make_request( + "PUT", + f"/profile/{self.owner}/displayname", + content={"displayname": "owner12345678" + "a" * ADDITIONAL_CHARS}, + access_token=self.owner_tok, + ) + self.assertEqual(channel.code, 400, channel.result) + self.assertEqual(channel.json_body["errcode"], Codes.PROFILE_TOO_LARGE) - channel = self.make_request( - "PUT", - f"/profile/{self.owner}/avatar_url", - content={"avatar_url": "mxc://foo/bar"}, - access_token=self.owner_tok, - ) - self.assertEqual(channel.code, 400, channel.result) - self.assertEqual(channel.json_body["errcode"], Codes.PROFILE_TOO_LARGE) + channel = self.make_request( + "PUT", + f"/profile/{self.owner}/avatar_url", + content={"avatar_url": "mxc://foo/bar"}, + access_token=self.owner_tok, + ) + self.assertEqual(channel.code, 400, channel.result) + self.assertEqual(channel.json_body["errcode"], Codes.PROFILE_TOO_LARGE) - # Removing a single byte should work. - key = "b" - channel = self.make_request( - "PUT", - f"/_matrix/client/v3/profile/{self.owner}/{key}", - content={key: "" + "a" * ADDITIONAL_CHARS}, - access_token=self.owner_tok, - ) - self.assertEqual(channel.code, 200, channel.result) + # Removing a single byte should work. + key = "b" + channel = self.make_request( + "PUT", + f"/_matrix/client/v3/profile/{self.owner}/{key}", + content={key: "" + "a" * ADDITIONAL_CHARS}, + access_token=self.owner_tok, + ) + self.assertEqual(channel.code, 200, channel.result) - # Finally, setting a field that already exists to a value that is <= in length should work. - key = "a" - channel = self.make_request( - "PUT", - f"/_matrix/client/v3/profile/{self.owner}/{key}", - content={key: ""}, - access_token=self.owner_tok, - ) - self.assertEqual(channel.code, 200, channel.result) + # Finally, setting a field that already exists to a value that is <= in length should work. + key = "a" + channel = self.make_request( + "PUT", + f"/_matrix/client/v3/profile/{self.owner}/{key}", + content={key: ""}, + access_token=self.owner_tok, + ) + self.assertEqual(channel.code, 200, channel.result) + finally: + sql_logger.disabled = sql_logger_was_disabled def test_set_custom_field_displayname(self) -> None: channel = self.make_request(