Skip to content

Commit ea87853

Browse files
reivilibrereivilibre
authored
Work around twisted.protocols.amp.TooLong error by reducing logging in some tests. (#18736)
Part of: #18537 Works around: twisted/twisted#12482 --------- Signed-off-by: Olivier 'reivilibre <oliverw@matrix.org>
1 parent a31d53b commit ea87853

3 files changed

Lines changed: 173 additions & 147 deletions

File tree

‎changelog.d/18736.misc‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1 @@
1+
Work around `twisted.protocols.amp.TooLong` error by reducing logging in some tests.

‎tests/replication/tcp/streams/test_typing.py‎

Lines changed: 83 additions & 71 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@
1818
# [This file includes modifications made by New Vector Limited]
1919
#
2020
#
21+
import logging
2122
from unittest.mock import Mock
2223

2324
from synapse.handlers.typing import RoomMember, TypingWriterHandler
@@ -99,75 +100,86 @@ def test_reset(self) -> None:
99100
This is emulated by jumping the stream ahead, then reconnecting (which
100101
sends the proper position and RDATA).
101102
"""
102-
typing = self.hs.get_typing_handler()
103-
assert isinstance(typing, TypingWriterHandler)
104-
105-
# Create a typing update before we reconnect so that there is a missing
106-
# update to fetch.
107-
typing._push_update(member=RoomMember(ROOM_ID, USER_ID), typing=True)
108-
109-
self.reconnect()
110-
111-
typing._push_update(member=RoomMember(ROOM_ID, USER_ID), typing=True)
112-
113-
self.reactor.advance(0)
114-
115-
# We should now see an attempt to connect to the master
116-
request = self.handle_http_replication_attempt()
117-
self.assert_request_is_get_repl_stream_updates(request, "typing")
118-
119-
self.mock_handler.on_rdata.assert_called_once()
120-
stream_name, _, token, rdata_rows = self.mock_handler.on_rdata.call_args[0]
121-
self.assertEqual(stream_name, "typing")
122-
self.assertEqual(1, len(rdata_rows))
123-
row: TypingStream.TypingStreamRow = rdata_rows[0]
124-
self.assertEqual(ROOM_ID, row.room_id)
125-
self.assertEqual([USER_ID], row.user_ids)
126-
127-
# Push the stream forward a bunch so it can be reset.
128-
for i in range(100):
129-
typing._push_update(
130-
member=RoomMember(ROOM_ID, "@test%s:blue" % i), typing=True
103+
# FIXME: Because huge RDATA log line is triggered in this test,
104+
# trial breaks, sometimes (flakily) failing the test run.
105+
# ref: https://github.com/twisted/twisted/issues/12482
106+
# To remove this, we would need to fix the above issue and
107+
# update, including in olddeps (so several years' wait).
108+
server_logger = logging.getLogger("tests.server")
109+
server_logger_was_disabled = server_logger.disabled
110+
server_logger.disabled = True
111+
try:
112+
typing = self.hs.get_typing_handler()
113+
assert isinstance(typing, TypingWriterHandler)
114+
115+
# Create a typing update before we reconnect so that there is a missing
116+
# update to fetch.
117+
typing._push_update(member=RoomMember(ROOM_ID, USER_ID), typing=True)
118+
119+
self.reconnect()
120+
121+
typing._push_update(member=RoomMember(ROOM_ID, USER_ID), typing=True)
122+
123+
self.reactor.advance(0)
124+
125+
# We should now see an attempt to connect to the master
126+
request = self.handle_http_replication_attempt()
127+
self.assert_request_is_get_repl_stream_updates(request, "typing")
128+
129+
self.mock_handler.on_rdata.assert_called_once()
130+
stream_name, _, token, rdata_rows = self.mock_handler.on_rdata.call_args[0]
131+
self.assertEqual(stream_name, "typing")
132+
self.assertEqual(1, len(rdata_rows))
133+
row: TypingStream.TypingStreamRow = rdata_rows[0]
134+
self.assertEqual(ROOM_ID, row.room_id)
135+
self.assertEqual([USER_ID], row.user_ids)
136+
137+
# Push the stream forward a bunch so it can be reset.
138+
for i in range(100):
139+
typing._push_update(
140+
member=RoomMember(ROOM_ID, "@test%s:blue" % i), typing=True
141+
)
142+
self.reactor.advance(0)
143+
144+
# Disconnect.
145+
self.disconnect()
146+
147+
# Reset the typing handler
148+
self.hs.get_replication_streams()["typing"].last_token = 0
149+
self.hs.get_replication_command_handler()._streams["typing"].last_token = 0
150+
typing._latest_room_serial = 0
151+
typing._typing_stream_change_cache = StreamChangeCache(
152+
name="TypingStreamChangeCache",
153+
server_name=self.hs.hostname,
154+
current_stream_pos=typing._latest_room_serial,
131155
)
132-
self.reactor.advance(0)
133-
134-
# Disconnect.
135-
self.disconnect()
136-
137-
# Reset the typing handler
138-
self.hs.get_replication_streams()["typing"].last_token = 0
139-
self.hs.get_replication_command_handler()._streams["typing"].last_token = 0
140-
typing._latest_room_serial = 0
141-
typing._typing_stream_change_cache = StreamChangeCache(
142-
name="TypingStreamChangeCache",
143-
server_name=self.hs.hostname,
144-
current_stream_pos=typing._latest_room_serial,
145-
)
146-
typing._reset()
147-
148-
# Reconnect.
149-
self.reconnect()
150-
self.pump(0.1)
151-
152-
# We should now see an attempt to connect to the master
153-
request = self.handle_http_replication_attempt()
154-
self.assert_request_is_get_repl_stream_updates(request, "typing")
155-
156-
# Reset the test code.
157-
self.mock_handler.on_rdata.reset_mock()
158-
self.mock_handler.on_rdata.assert_not_called()
159-
160-
# Push additional data.
161-
typing._push_update(member=RoomMember(ROOM_ID_2, USER_ID_2), typing=False)
162-
self.reactor.advance(0)
163-
164-
self.mock_handler.on_rdata.assert_called_once()
165-
stream_name, _, token, rdata_rows = self.mock_handler.on_rdata.call_args[0]
166-
self.assertEqual(stream_name, "typing")
167-
self.assertEqual(1, len(rdata_rows))
168-
row = rdata_rows[0]
169-
self.assertEqual(ROOM_ID_2, row.room_id)
170-
self.assertEqual([], row.user_ids)
171-
172-
# The token should have been reset.
173-
self.assertEqual(token, 1)
156+
typing._reset()
157+
158+
# Reconnect.
159+
self.reconnect()
160+
self.pump(0.1)
161+
162+
# We should now see an attempt to connect to the master
163+
request = self.handle_http_replication_attempt()
164+
self.assert_request_is_get_repl_stream_updates(request, "typing")
165+
166+
# Reset the test code.
167+
self.mock_handler.on_rdata.reset_mock()
168+
self.mock_handler.on_rdata.assert_not_called()
169+
170+
# Push additional data.
171+
typing._push_update(member=RoomMember(ROOM_ID_2, USER_ID_2), typing=False)
172+
self.reactor.advance(0)
173+
174+
self.mock_handler.on_rdata.assert_called_once()
175+
stream_name, _, token, rdata_rows = self.mock_handler.on_rdata.call_args[0]
176+
self.assertEqual(stream_name, "typing")
177+
self.assertEqual(1, len(rdata_rows))
178+
row = rdata_rows[0]
179+
self.assertEqual(ROOM_ID_2, row.room_id)
180+
self.assertEqual([], row.user_ids)
181+
182+
# The token should have been reset.
183+
self.assertEqual(token, 1)
184+
finally:
185+
server_logger.disabled = server_logger_was_disabled

‎tests/rest/client/test_profile.py‎

Lines changed: 89 additions & 76 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@
2121

2222
"""Tests REST events for /profile paths."""
2323

24+
import logging
2425
import urllib.parse
2526
from http import HTTPStatus
2627
from typing import Any, Dict, Optional
@@ -648,87 +649,99 @@ def test_set_custom_field_profile_too_long(self) -> None:
648649
"""
649650
Attempts to set a custom field that would push the overall profile too large.
650651
"""
651-
# Get right to the boundary:
652-
# len("displayname") + len("owner") + 5 = 21 for the displayname
653-
# 1 + 65498 + 5 for key "a" = 65504
654-
# 2 braces, 1 comma
655-
# 3 + 21 + 65498 = 65522 < 65536.
656-
key = "a"
657-
channel = self.make_request(
658-
"PUT",
659-
f"/_matrix/client/v3/profile/{self.owner}/{key}",
660-
content={key: "a" * 65498},
661-
access_token=self.owner_tok,
662-
)
663-
self.assertEqual(channel.code, 200, channel.result)
664-
665-
# Get the entire profile.
666-
channel = self.make_request(
667-
"GET",
668-
f"/_matrix/client/v3/profile/{self.owner}",
669-
access_token=self.owner_tok,
670-
)
671-
self.assertEqual(channel.code, 200, channel.result)
672-
canonical_json = encode_canonical_json(channel.json_body)
673-
# 6 is the minimum bytes to store a value: 4 quotes, 1 colon, 1 comma, an empty key.
674-
# Be one below that so we can prove we're at the boundary.
675-
self.assertEqual(len(canonical_json), MAX_PROFILE_SIZE - 8)
676-
677-
# Postgres stores JSONB with whitespace, while SQLite doesn't.
678-
if USE_POSTGRES_FOR_TESTS:
679-
ADDITIONAL_CHARS = 0
680-
else:
681-
ADDITIONAL_CHARS = 1
652+
# FIXME: Because we emit huge SQL log lines and trial can't handle these,
653+
# sometimes (flakily) failing the test run,
654+
# disable SQL logging for this test.
655+
# ref: https://github.com/twisted/twisted/issues/12482
656+
# To remove this, we would need to fix the above issue and
657+
# update, including in olddeps (so several years' wait).
658+
sql_logger = logging.getLogger("synapse.storage.SQL")
659+
sql_logger_was_disabled = sql_logger.disabled
660+
sql_logger.disabled = True
661+
try:
662+
# Get right to the boundary:
663+
# len("displayname") + len("owner") + 5 = 21 for the displayname
664+
# 1 + 65498 + 5 for key "a" = 65504
665+
# 2 braces, 1 comma
666+
# 3 + 21 + 65498 = 65522 < 65536.
667+
key = "a"
668+
channel = self.make_request(
669+
"PUT",
670+
f"/_matrix/client/v3/profile/{self.owner}/{key}",
671+
content={key: "a" * 65498},
672+
access_token=self.owner_tok,
673+
)
674+
self.assertEqual(channel.code, 200, channel.result)
682675

683-
# The next one should fail, note the value has a (JSON) length of 2.
684-
key = "b"
685-
channel = self.make_request(
686-
"PUT",
687-
f"/_matrix/client/v3/profile/{self.owner}/{key}",
688-
content={key: "1" + "a" * ADDITIONAL_CHARS},
689-
access_token=self.owner_tok,
690-
)
691-
self.assertEqual(channel.code, 400, channel.result)
692-
self.assertEqual(channel.json_body["errcode"], Codes.PROFILE_TOO_LARGE)
676+
# Get the entire profile.
677+
channel = self.make_request(
678+
"GET",
679+
f"/_matrix/client/v3/profile/{self.owner}",
680+
access_token=self.owner_tok,
681+
)
682+
self.assertEqual(channel.code, 200, channel.result)
683+
canonical_json = encode_canonical_json(channel.json_body)
684+
# 6 is the minimum bytes to store a value: 4 quotes, 1 colon, 1 comma, an empty key.
685+
# Be one below that so we can prove we're at the boundary.
686+
self.assertEqual(len(canonical_json), MAX_PROFILE_SIZE - 8)
687+
688+
# Postgres stores JSONB with whitespace, while SQLite doesn't.
689+
if USE_POSTGRES_FOR_TESTS:
690+
ADDITIONAL_CHARS = 0
691+
else:
692+
ADDITIONAL_CHARS = 1
693+
694+
# The next one should fail, note the value has a (JSON) length of 2.
695+
key = "b"
696+
channel = self.make_request(
697+
"PUT",
698+
f"/_matrix/client/v3/profile/{self.owner}/{key}",
699+
content={key: "1" + "a" * ADDITIONAL_CHARS},
700+
access_token=self.owner_tok,
701+
)
702+
self.assertEqual(channel.code, 400, channel.result)
703+
self.assertEqual(channel.json_body["errcode"], Codes.PROFILE_TOO_LARGE)
693704

694-
# Setting an avatar or (longer) display name should not work.
695-
channel = self.make_request(
696-
"PUT",
697-
f"/profile/{self.owner}/displayname",
698-
content={"displayname": "owner12345678" + "a" * ADDITIONAL_CHARS},
699-
access_token=self.owner_tok,
700-
)
701-
self.assertEqual(channel.code, 400, channel.result)
702-
self.assertEqual(channel.json_body["errcode"], Codes.PROFILE_TOO_LARGE)
705+
# Setting an avatar or (longer) display name should not work.
706+
channel = self.make_request(
707+
"PUT",
708+
f"/profile/{self.owner}/displayname",
709+
content={"displayname": "owner12345678" + "a" * ADDITIONAL_CHARS},
710+
access_token=self.owner_tok,
711+
)
712+
self.assertEqual(channel.code, 400, channel.result)
713+
self.assertEqual(channel.json_body["errcode"], Codes.PROFILE_TOO_LARGE)
703714

704-
channel = self.make_request(
705-
"PUT",
706-
f"/profile/{self.owner}/avatar_url",
707-
content={"avatar_url": "mxc://foo/bar"},
708-
access_token=self.owner_tok,
709-
)
710-
self.assertEqual(channel.code, 400, channel.result)
711-
self.assertEqual(channel.json_body["errcode"], Codes.PROFILE_TOO_LARGE)
715+
channel = self.make_request(
716+
"PUT",
717+
f"/profile/{self.owner}/avatar_url",
718+
content={"avatar_url": "mxc://foo/bar"},
719+
access_token=self.owner_tok,
720+
)
721+
self.assertEqual(channel.code, 400, channel.result)
722+
self.assertEqual(channel.json_body["errcode"], Codes.PROFILE_TOO_LARGE)
712723

713-
# Removing a single byte should work.
714-
key = "b"
715-
channel = self.make_request(
716-
"PUT",
717-
f"/_matrix/client/v3/profile/{self.owner}/{key}",
718-
content={key: "" + "a" * ADDITIONAL_CHARS},
719-
access_token=self.owner_tok,
720-
)
721-
self.assertEqual(channel.code, 200, channel.result)
724+
# Removing a single byte should work.
725+
key = "b"
726+
channel = self.make_request(
727+
"PUT",
728+
f"/_matrix/client/v3/profile/{self.owner}/{key}",
729+
content={key: "" + "a" * ADDITIONAL_CHARS},
730+
access_token=self.owner_tok,
731+
)
732+
self.assertEqual(channel.code, 200, channel.result)
722733

723-
# Finally, setting a field that already exists to a value that is <= in length should work.
724-
key = "a"
725-
channel = self.make_request(
726-
"PUT",
727-
f"/_matrix/client/v3/profile/{self.owner}/{key}",
728-
content={key: ""},
729-
access_token=self.owner_tok,
730-
)
731-
self.assertEqual(channel.code, 200, channel.result)
734+
# Finally, setting a field that already exists to a value that is <= in length should work.
735+
key = "a"
736+
channel = self.make_request(
737+
"PUT",
738+
f"/_matrix/client/v3/profile/{self.owner}/{key}",
739+
content={key: ""},
740+
access_token=self.owner_tok,
741+
)
742+
self.assertEqual(channel.code, 200, channel.result)
743+
finally:
744+
sql_logger.disabled = sql_logger_was_disabled
732745

733746
def test_set_custom_field_displayname(self) -> None:
734747
channel = self.make_request(

0 commit comments

Comments
 (0)
⚡