From e3db7b2d81cabc7e4335afc051e28678e3a9dd02 Mon Sep 17 00:00:00 2001 From: Eric Eastwood Date: Mon, 5 Aug 2024 13:20:15 -0500 Subject: [PATCH] Sliding Sync: Easier to understand timeline assertions in tests (#17511) Added `_assertTimelineEqual(...)` because I got fed up trying to understand the crazy diffs from the standard `self.assertEqual(...)`/`self.assertListEqual(...)` Before: ``` [FAIL] Traceback (most recent call last): File "/home/eric/Documents/github/element/synapse/tests/rest/client/sliding_sync/test_rooms_timeline.py", line 103, in test_rooms_limited_initial_sync self.assertListEqual( File "/usr/lib/python3.12/unittest/case.py", line 1091, in assertListEqual self.assertSequenceEqual(list1, list2, msg, seq_type=list) File "/usr/lib/python3.12/unittest/case.py", line 1073, in assertSequenceEqual self.fail(msg) twisted.trial.unittest.FailTest: Lists differ: ['$4QcmnzhdazSnDYcYSZCS_6-MWSzM_dN3RC7TRvW0w[95 chars]isM'] != ['$8N1XJ7e-3K_wxAanLVD3v8KQ96_B5Xj4huGkgy4N4[95 chars]nnU'] First differing element 0: '$4QcmnzhdazSnDYcYSZCS_6-MWSzM_dN3RC7TRvW0wWA' '$8N1XJ7e-3K_wxAanLVD3v8KQ96_B5Xj4huGkgy4N4-E' - ['$4QcmnzhdazSnDYcYSZCS_6-MWSzM_dN3RC7TRvW0wWA', - '$8N1XJ7e-3K_wxAanLVD3v8KQ96_B5Xj4huGkgy4N4-E', ? ^ + ['$8N1XJ7e-3K_wxAanLVD3v8KQ96_B5Xj4huGkgy4N4-E', ? ^ - '$q4PRxQ_pBZkQI1keYuZPTtExQ23DqpUI3-Lxwfj_isM'] + '$4QcmnzhdazSnDYcYSZCS_6-MWSzM_dN3RC7TRvW0wWA', + '$j3Xj-t2F1wH9kUHsI8X5yqS7hkdSyN2owaArfvk8nnU'] ``` After: ``` [FAIL] Traceback (most recent call last): File "/home/eric/Documents/github/element/synapse/tests/rest/client/sliding_sync/test_rooms_timeline.py", line 178, in test_rooms_limited_initial_sync self._assertTimelineEqual( File "/home/eric/Documents/github/element/synapse/tests/rest/client/sliding_sync/test_rooms_timeline.py", line 110, in _assertTimelineEqual self._assertListEqual( File "/home/eric/Documents/github/element/synapse/tests/rest/client/sliding_sync/test_rooms_timeline.py", line 79, in _assertListEqual self.fail(f"{diff_message}\n{message}") twisted.trial.unittest.FailTest: Items must Expected items to be in actual ('?' = missing expected items): [ (10, master) $w-BoqW1PQQFU4TzVJW5OIelugxh0mY12wrfw6mbC6D4 (m.room.message) activity4 (11, master) $sSidTZf1EOQmCVDU4mrH_1-bopMQhwcDUO2IhoemR6M (m.room.message) activity5 ? (12, master) $bgOcc3D-2QSkbk4aBxKVyOOQJGs7ZuncRJwG3cEANZg (m.room.member, @user1:test) join ] Actual ('+' = found expected items): [ + (11, master) $sSidTZf1EOQmCVDU4mrH_1-bopMQhwcDUO2IhoemR6M (m.room.message) activity5 + (10, master) $w-BoqW1PQQFU4TzVJW5OIelugxh0mY12wrfw6mbC6D4 (m.room.message) activity4 (9, master) $FmCNyc11YeFwiJ4an7_q6H0LCCjQOKd6UCr5VKeXXUw (m.room.message, None) activity3 ] ``` --- changelog.d/17511.misc | 1 + .../sliding_sync/test_rooms_timeline.py | 124 +++++++++++++++--- 2 files changed, 104 insertions(+), 21 deletions(-) create mode 100644 changelog.d/17511.misc diff --git a/changelog.d/17511.misc b/changelog.d/17511.misc new file mode 100644 index 0000000000..abc7be44ba --- /dev/null +++ b/changelog.d/17511.misc @@ -0,0 +1 @@ +Easier to understand `timeline` assertions in Sliding Sync tests. diff --git a/tests/rest/client/sliding_sync/test_rooms_timeline.py b/tests/rest/client/sliding_sync/test_rooms_timeline.py index 84a1e0d223..2e9586ca73 100644 --- a/tests/rest/client/sliding_sync/test_rooms_timeline.py +++ b/tests/rest/client/sliding_sync/test_rooms_timeline.py @@ -12,13 +12,14 @@ # . # import logging +from typing import List, Optional from twisted.test.proto_helpers import MemoryReactor import synapse.rest.admin from synapse.rest.client import login, room, sync from synapse.server import HomeServer -from synapse.types import StreamToken +from synapse.types import StreamToken, StrSequence from synapse.util import Clock from tests.rest.client.sliding_sync.test_sliding_sync import SlidingSyncBase @@ -42,6 +43,82 @@ class SlidingSyncRoomsTimelineTestCase(SlidingSyncBase): self.store = hs.get_datastores().main self.storage_controllers = hs.get_storage_controllers() + def _assertListEqual( + self, + actual_items: StrSequence, + expected_items: StrSequence, + message: Optional[str] = None, + ) -> None: + """ + Like `self.assertListEqual(...)` but with an actually understandable diff message. + """ + + if actual_items == expected_items: + return + + expected_lines: List[str] = [] + for expected_item in expected_items: + is_expected_in_actual = expected_item in actual_items + expected_lines.append( + "{} {}".format(" " if is_expected_in_actual else "?", expected_item) + ) + + actual_lines: List[str] = [] + for actual_item in actual_items: + is_actual_in_expected = actual_item in expected_items + actual_lines.append( + "{} {}".format("+" if is_actual_in_expected else " ", actual_item) + ) + + newline = "\n" + expected_string = f"Expected items to be in actual ('?' = missing expected items):\n [\n{newline.join(expected_lines)}\n ]" + actual_string = f"Actual ('+' = found expected items):\n [\n{newline.join(actual_lines)}\n ]" + first_message = "Items must" + diff_message = f"{first_message}\n{expected_string}\n{actual_string}" + + self.fail(f"{diff_message}\n{message}") + + def _assertTimelineEqual( + self, + *, + room_id: str, + actual_event_ids: List[str], + expected_event_ids: List[str], + message: Optional[str] = None, + ) -> None: + """ + Like `self.assertListEqual(...)` for event IDs in a room but will give a nicer + output with context for what each event_id is (type, stream_ordering, content, + etc). + """ + if actual_event_ids == expected_event_ids: + return + + event_id_set = set(actual_event_ids + expected_event_ids) + events = self.get_success(self.store.get_events(event_id_set)) + + def event_id_to_string(event_id: str) -> str: + event = events.get(event_id) + if event: + state_key = event.get_state_key() + state_key_piece = f", {state_key}" if state_key is not None else "" + return ( + f"({event.internal_metadata.stream_ordering: >2}, {event.internal_metadata.instance_name}) " + + f"{event.event_id} ({event.type}{state_key_piece}) {event.content.get('membership', '')}{event.content.get('body', '')}" + ) + + return f"{event_id} " + + self._assertListEqual( + actual_items=[ + event_id_to_string(event_id) for event_id in actual_event_ids + ], + expected_items=[ + event_id_to_string(event_id) for event_id in expected_event_ids + ], + message=message, + ) + def test_rooms_limited_initial_sync(self) -> None: """ Test that we mark `rooms` as `limited=True` when we saturate the `timeline_limit` @@ -85,17 +162,18 @@ class SlidingSyncRoomsTimelineTestCase(SlidingSyncBase): response_body["rooms"][room_id1], ) # Check to make sure the latest events are returned - self.assertEqual( - [ + self._assertTimelineEqual( + room_id=room_id1, + actual_event_ids=[ event["event_id"] for event in response_body["rooms"][room_id1]["timeline"] ], - [ + expected_event_ids=[ event_response4["event_id"], event_response5["event_id"], user1_join_response["event_id"], ], - response_body["rooms"][room_id1]["timeline"], + message=str(response_body["rooms"][room_id1]["timeline"]), ) # Check to make sure the `prev_batch` points at the right place @@ -227,16 +305,17 @@ class SlidingSyncRoomsTimelineTestCase(SlidingSyncBase): + str(response_body["rooms"][room_id1]), ) # Check to make sure the latest events are returned - self.assertEqual( - [ + self._assertTimelineEqual( + room_id=room_id1, + actual_event_ids=[ event["event_id"] for event in response_body["rooms"][room_id1]["timeline"] ], - [ + expected_event_ids=[ event_response2["event_id"], event_response3["event_id"], ], - response_body["rooms"][room_id1]["timeline"], + message=str(response_body["rooms"][room_id1]["timeline"]), ) # All events are "live" @@ -303,18 +382,19 @@ class SlidingSyncRoomsTimelineTestCase(SlidingSyncBase): + str(response_body["rooms"][room_id1]), ) # Check to make sure that the "live" and historical events are returned - self.assertEqual( - [ + self._assertTimelineEqual( + room_id=room_id1, + actual_event_ids=[ event["event_id"] for event in response_body["rooms"][room_id1]["timeline"] ], - [ + expected_event_ids=[ event_response2["event_id"], user1_join_response["event_id"], event_response3["event_id"], event_response4["event_id"], ], - response_body["rooms"][room_id1]["timeline"], + message=str(response_body["rooms"][room_id1]["timeline"]), ) # Only events after the `from_token` are "live" (join, event3, event4) @@ -361,17 +441,18 @@ class SlidingSyncRoomsTimelineTestCase(SlidingSyncBase): response_body, _ = self.do_sync(sync_body, tok=user1_tok) # We should see events before the ban but not after - self.assertEqual( - [ + self._assertTimelineEqual( + room_id=room_id1, + actual_event_ids=[ event["event_id"] for event in response_body["rooms"][room_id1]["timeline"] ], - [ + expected_event_ids=[ event_response3["event_id"], event_response4["event_id"], user1_ban_response["event_id"], ], - response_body["rooms"][room_id1]["timeline"], + message=str(response_body["rooms"][room_id1]["timeline"]), ) # No "live" events in an initial sync (no `from_token` to define the "live" # range) @@ -428,17 +509,18 @@ class SlidingSyncRoomsTimelineTestCase(SlidingSyncBase): response_body, _ = self.do_sync(sync_body, since=from_token, tok=user1_tok) # We should see events before the ban but not after - self.assertEqual( - [ + self._assertTimelineEqual( + room_id=room_id1, + actual_event_ids=[ event["event_id"] for event in response_body["rooms"][room_id1]["timeline"] ], - [ + expected_event_ids=[ event_response3["event_id"], event_response4["event_id"], user1_ban_response["event_id"], ], - response_body["rooms"][room_id1]["timeline"], + message=str(response_body["rooms"][room_id1]["timeline"]), ) # All live events in the incremental sync self.assertEqual(