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 <oliverw@matrix.org>
This commit is contained in:
reivilibre
1
changelog.d/18736.misc
Normal file
1
changelog.d/18736.misc
Normal file
@@ -0,0 +1 @@
|
||||
Work around `twisted.protocols.amp.TooLong` error by reducing logging in some tests.
|
||||
@@ -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
|
||||
|
||||
@@ -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(
|
||||
|
||||
Reference in New Issue
Block a user