Skip to content
Merged
Show file tree
Hide file tree
Changes from 3 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions changelog.d/18736.misc
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Work around `twisted.protocols.amp.TooLong` error by reducing logging in some tests.
151 changes: 80 additions & 71 deletions tests/replication/tcp/streams/test_typing.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -99,75 +100,83 @@ def test_reset(self) -> None:
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)

# 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()

typing._push_update(member=RoomMember(ROOM_ID, USER_ID), typing=True)

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")

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
# A huge RDATA log line is triggered in this test, which breaks trial
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
# A huge RDATA log line is triggered in this test, which breaks trial
# Because we emit a huge RDATA log line and trial sometimes crashes on these,
# disable that logger for this test

# ref: https://github.com/twisted/twisted/issues/12482
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Alternative to actually call this out as a FIXME.

Suggested change
# A huge RDATA log line is triggered in this test, which breaks trial
# ref: https://github.com/twisted/twisted/issues/12482
# FIXME: Because we emit a huge RDATA log line and trial sometimes crashes on
# these, disable that logger for this test. This can be removed once
# https://github.com/twisted/twisted/issues/12482 is solved and we update
# Twisted to version that includes the fix.

(applies to other spot as well)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

annoyingly, given the olddeps trial run, we actually can't remove this for several years even if we fix Trial :D

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(guess I should add that caveat to the comment though)

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)

self.reconnect()

typing._push_update(member=RoomMember(ROOM_ID, USER_ID), typing=True)

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")

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
)
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)

# 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,
)
typing._reset()

# Reconnect.
self.reconnect()
self.pump(0.1)

# 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")

# Reset the test code.
self.mock_handler.on_rdata.reset_mock()
self.mock_handler.on_rdata.assert_not_called()

# 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)
typing._reset()

# Reconnect.
self.reconnect()
self.pump(0.1)

# 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")

# Reset the test code.
self.mock_handler.on_rdata.reset_mock()
self.mock_handler.on_rdata.assert_not_called()

# 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)
finally:
server_logger.disabled = server_logger_was_disabled
162 changes: 86 additions & 76 deletions tests/rest/client/test_profile.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -648,87 +649,96 @@ def test_set_custom_field_profile_too_long(self) -> None:
"""
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)

# 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
# Because we emit huge SQL log lines and trial sometimes crashes on these,
# disable SQL logging for this test
# ref: https://github.com/twisted/twisted/issues/12482
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)

# 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)
# 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

# 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(
Expand Down
Loading