From 6a0c9105b4f8a9c7a7e4c740167c7763fafaee6f Mon Sep 17 00:00:00 2001 From: owenpearson Date: Tue, 16 Dec 2025 18:07:28 +0000 Subject: [PATCH 1/6] ci: add debug logging for test failure --- test/ably/realtime/realtimepresence_test.py | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/test/ably/realtime/realtimepresence_test.py b/test/ably/realtime/realtimepresence_test.py index e7073983..d40f09df 100644 --- a/test/ably/realtime/realtimepresence_test.py +++ b/test/ably/realtime/realtimepresence_test.py @@ -287,17 +287,24 @@ async def setup(self, use_binary_protocol): self.test_vars = await TestApp.get_test_vars() self.use_binary_protocol = use_binary_protocol + protocol = 'msgpack' if use_binary_protocol else 'json' + self.client1 = await TestApp.get_ably_realtime( client_id='client1', use_binary_protocol=use_binary_protocol ) + print(f"[{protocol}] FIXTURE SETUP: Created client1 id={id(self.client1)}, state={self.client1.connection.state}") + self.client2 = await TestApp.get_ably_realtime( client_id='client2', use_binary_protocol=use_binary_protocol ) + print(f"[{protocol}] FIXTURE SETUP: Created client2 id={id(self.client2)}, state={self.client2.connection.state}") yield + print(f"[{protocol}] FIXTURE TEARDOWN: client1 id={id(self.client1)}, state={self.client1.connection.state}") + print(f"[{protocol}] FIXTURE TEARDOWN: client2 id={id(self.client2)}, state={self.client2.connection.state}") await self.client1.close() await self.client2.close() @@ -335,20 +342,27 @@ async def test_presence_message_action(self): """ Test RTP8c: PresenceMessage should have correct action string. """ + protocol = 'msgpack' if self.use_binary_protocol else 'json' + print(f"[{protocol}] TEST START: client1 id={id(self.client1)}, state={self.client1.connection.state}") + channel_name = self.get_channel_name('message_action') channel1 = self.client1.channels.get(channel_name) + print(f"[{protocol}] TEST: Got channel, client1.state={self.client1.connection.state}") received = asyncio.Future() def on_presence(msg): received.set_result(msg) + print(f"[{protocol}] TEST: About to subscribe, client1.state={self.client1.connection.state}") await channel1.presence.subscribe(on_presence) + print(f"[{protocol}] TEST: About to enter, client1.state={self.client1.connection.state}") await channel1.presence.enter() msg = await asyncio.wait_for(received, timeout=5.0) assert msg.action == PresenceAction.ENTER + print(f"[{protocol}] TEST END: client1.state={self.client1.connection.state}") @pytest.mark.parametrize('use_binary_protocol', [True, False], ids=['msgpack', 'json']) From 8b44d5bcbf540a4cadfd68a12274f057cc3f1ee9 Mon Sep 17 00:00:00 2001 From: owenpearson Date: Tue, 16 Dec 2025 18:44:25 +0000 Subject: [PATCH 2/6] stop capturing stdout --- .github/workflows/check.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/check.yml b/.github/workflows/check.yml index 53f78b0a..c1be2ada 100644 --- a/.github/workflows/check.yml +++ b/.github/workflows/check.yml @@ -46,4 +46,4 @@ jobs: - name: Generate rest sync code and tests run: uv run unasync - name: Test with pytest - run: uv run pytest --verbose --tb=short --reruns 3 + run: uv run pytest -s --verbose --tb=short --reruns 3 From 3f4d08c50f8ebdfd3983763ced3ce91ea8aadf9c Mon Sep 17 00:00:00 2001 From: owenpearson Date: Wed, 17 Dec 2025 10:35:21 +0000 Subject: [PATCH 3/6] use test_instance --- test/ably/realtime/realtimepresence_test.py | 36 ++++++++++++++------- 1 file changed, 25 insertions(+), 11 deletions(-) diff --git a/test/ably/realtime/realtimepresence_test.py b/test/ably/realtime/realtimepresence_test.py index d40f09df..00d42cac 100644 --- a/test/ably/realtime/realtimepresence_test.py +++ b/test/ably/realtime/realtimepresence_test.py @@ -282,31 +282,45 @@ class TestRealtimePresenceSubscribe(BaseAsyncTestCase): """Test presence.subscribe() functionality.""" @pytest.fixture(autouse=True) - async def setup(self, use_binary_protocol): + async def setup(self, use_binary_protocol, request): """Set up test fixtures.""" - self.test_vars = await TestApp.get_test_vars() - self.use_binary_protocol = use_binary_protocol + test_instance = request.instance + + test_instance.test_vars = await TestApp.get_test_vars() + test_instance.use_binary_protocol = use_binary_protocol protocol = 'msgpack' if use_binary_protocol else 'json' - self.client1 = await TestApp.get_ably_realtime( + test_instance.client1 = await TestApp.get_ably_realtime( client_id='client1', use_binary_protocol=use_binary_protocol ) - print(f"[{protocol}] FIXTURE SETUP: Created client1 id={id(self.client1)}, state={self.client1.connection.state}") + print( + f"[{protocol}] FIXTURE SETUP: Created client1 id={id(test_instance.client1)}, " + f"state={test_instance.client1.connection.state}" + ) - self.client2 = await TestApp.get_ably_realtime( + test_instance.client2 = await TestApp.get_ably_realtime( client_id='client2', use_binary_protocol=use_binary_protocol ) - print(f"[{protocol}] FIXTURE SETUP: Created client2 id={id(self.client2)}, state={self.client2.connection.state}") + print( + f"[{protocol}] FIXTURE SETUP: Created client2 id={id(test_instance.client2)}, " + f"state={test_instance.client2.connection.state}" + ) yield - print(f"[{protocol}] FIXTURE TEARDOWN: client1 id={id(self.client1)}, state={self.client1.connection.state}") - print(f"[{protocol}] FIXTURE TEARDOWN: client2 id={id(self.client2)}, state={self.client2.connection.state}") - await self.client1.close() - await self.client2.close() + print( + f"[{protocol}] FIXTURE TEARDOWN: client1 id={id(test_instance.client1)}, " + f"state={test_instance.client1.connection.state}" + ) + print( + f"[{protocol}] FIXTURE TEARDOWN: client2 id={id(test_instance.client2)}, " + f"state={test_instance.client2.connection.state}" + ) + await test_instance.client1.close() + await test_instance.client2.close() async def test_presence_subscribe_unattached(self): """ From 7ae93916641ec89a3dfd71d09b455c859d0867a8 Mon Sep 17 00:00:00 2001 From: owenpearson Date: Wed, 17 Dec 2025 11:29:59 +0000 Subject: [PATCH 4/6] add more debug prints --- ably/realtime/realtimepresence.py | 22 ++++++++++++++++++++++ 1 file changed, 22 insertions(+) diff --git a/ably/realtime/realtimepresence.py b/ably/realtime/realtimepresence.py index 2702846d..b279131f 100644 --- a/ably/realtime/realtimepresence.py +++ b/ably/realtime/realtimepresence.py @@ -362,6 +362,10 @@ async def _send_presence(self, presence_messages: list[dict]) -> None: 'presence': presence_messages } + print( + f"[PRESENCE DEBUG] _send_presence: Sending {len(presence_messages)} messages " + f"on channel {self.channel.name}" + ) await self.channel.ably.connection.connection_manager.send_protocol_message(protocol_msg) async def _queue_presence(self, wire_msg: dict) -> None: @@ -468,6 +472,10 @@ async def subscribe(self, *args) -> None: Raises: AblyException: If channel state prevents subscription """ + print( + f"[PRESENCE DEBUG] subscribe: Called on channel {self.channel.name}, " + f"channel.state={self.channel.state}" + ) # RTP6d: Implicitly attach if self.channel.state in [ChannelState.INITIALIZED, ChannelState.DETACHED, ChannelState.DETACHING]: asyncio.create_task(self.channel.attach()) @@ -477,11 +485,13 @@ async def subscribe(self, *args) -> None: # subscribe(listener) listener = args[0] self._subscriptions.on(listener) + print("[PRESENCE DEBUG] subscribe: Registered listener for all events") elif len(args) == 2: # subscribe(event, listener) event = args[0] listener = args[1] self._subscriptions.on(event, listener) + print(f"[PRESENCE DEBUG] subscribe: Registered listener for event '{event}'") else: raise ValueError('Invalid subscribe arguments') @@ -524,6 +534,10 @@ def set_presence( is_sync: True if this is part of a SYNC operation sync_channel_serial: Optional sync cursor for tracking sync progress """ + print( + f"[PRESENCE DEBUG] set_presence: Received {len(presence_set)} messages " + f"on channel {self.channel.name}, is_sync={is_sync}" + ) log.info( f'RealtimePresence.set_presence(): ' f'received presence for {len(presence_set)} members; ' @@ -588,8 +602,16 @@ def set_presence( broadcast_messages.append(synthesized_leave) # Broadcast messages to subscribers + print( + f"[PRESENCE DEBUG] set_presence: Broadcasting {len(broadcast_messages)} messages " + f"to subscribers on channel {self.channel.name}" + ) for presence in broadcast_messages: action_name = PresenceAction._action_name(presence.action).lower() + print( + f"[PRESENCE DEBUG] set_presence: Emitting '{action_name}' " + f"for client_id={presence.client_id}" + ) self._subscriptions._emit(action_name, presence) def on_attached(self, has_presence: bool = False) -> None: From b850fb6e797582ee6004ef4db7ff90e77f6188f6 Mon Sep 17 00:00:00 2001 From: owenpearson Date: Wed, 17 Dec 2025 12:23:20 +0000 Subject: [PATCH 5/6] test --- ably/realtime/realtimepresence.py | 22 ----- test/ably/realtime/realtimepresence_test.py | 101 +++++++++----------- 2 files changed, 47 insertions(+), 76 deletions(-) diff --git a/ably/realtime/realtimepresence.py b/ably/realtime/realtimepresence.py index b279131f..2702846d 100644 --- a/ably/realtime/realtimepresence.py +++ b/ably/realtime/realtimepresence.py @@ -362,10 +362,6 @@ async def _send_presence(self, presence_messages: list[dict]) -> None: 'presence': presence_messages } - print( - f"[PRESENCE DEBUG] _send_presence: Sending {len(presence_messages)} messages " - f"on channel {self.channel.name}" - ) await self.channel.ably.connection.connection_manager.send_protocol_message(protocol_msg) async def _queue_presence(self, wire_msg: dict) -> None: @@ -472,10 +468,6 @@ async def subscribe(self, *args) -> None: Raises: AblyException: If channel state prevents subscription """ - print( - f"[PRESENCE DEBUG] subscribe: Called on channel {self.channel.name}, " - f"channel.state={self.channel.state}" - ) # RTP6d: Implicitly attach if self.channel.state in [ChannelState.INITIALIZED, ChannelState.DETACHED, ChannelState.DETACHING]: asyncio.create_task(self.channel.attach()) @@ -485,13 +477,11 @@ async def subscribe(self, *args) -> None: # subscribe(listener) listener = args[0] self._subscriptions.on(listener) - print("[PRESENCE DEBUG] subscribe: Registered listener for all events") elif len(args) == 2: # subscribe(event, listener) event = args[0] listener = args[1] self._subscriptions.on(event, listener) - print(f"[PRESENCE DEBUG] subscribe: Registered listener for event '{event}'") else: raise ValueError('Invalid subscribe arguments') @@ -534,10 +524,6 @@ def set_presence( is_sync: True if this is part of a SYNC operation sync_channel_serial: Optional sync cursor for tracking sync progress """ - print( - f"[PRESENCE DEBUG] set_presence: Received {len(presence_set)} messages " - f"on channel {self.channel.name}, is_sync={is_sync}" - ) log.info( f'RealtimePresence.set_presence(): ' f'received presence for {len(presence_set)} members; ' @@ -602,16 +588,8 @@ def set_presence( broadcast_messages.append(synthesized_leave) # Broadcast messages to subscribers - print( - f"[PRESENCE DEBUG] set_presence: Broadcasting {len(broadcast_messages)} messages " - f"to subscribers on channel {self.channel.name}" - ) for presence in broadcast_messages: action_name = PresenceAction._action_name(presence.action).lower() - print( - f"[PRESENCE DEBUG] set_presence: Emitting '{action_name}' " - f"for client_id={presence.client_id}" - ) self._subscriptions._emit(action_name, presence) def on_attached(self, has_presence: bool = False) -> None: diff --git a/test/ably/realtime/realtimepresence_test.py b/test/ably/realtime/realtimepresence_test.py index 00d42cac..244aa6dc 100644 --- a/test/ably/realtime/realtimepresence_test.py +++ b/test/ably/realtime/realtimepresence_test.py @@ -35,24 +35,26 @@ class TestRealtimePresenceBasics(BaseAsyncTestCase): """Test basic presence operations: enter, leave, update.""" @pytest.fixture(autouse=True) - async def setup(self, use_binary_protocol): + async def setup(self, use_binary_protocol, request): """Set up test fixtures.""" - self.test_vars = await TestApp.get_test_vars() - self.use_binary_protocol = use_binary_protocol + test_instance = request.instance + + test_instance.test_vars = await TestApp.get_test_vars() + test_instance.use_binary_protocol = use_binary_protocol - self.client1 = await TestApp.get_ably_realtime( + test_instance.client1 = await TestApp.get_ably_realtime( client_id='client1', use_binary_protocol=use_binary_protocol ) - self.client2 = await TestApp.get_ably_realtime( + test_instance.client2 = await TestApp.get_ably_realtime( client_id='client2', use_binary_protocol=use_binary_protocol ) yield - await self.client1.close() - await self.client2.close() + await test_instance.client1.close() + await test_instance.client2.close() async def test_presence_enter_without_attach(self): """ @@ -188,24 +190,26 @@ class TestRealtimePresenceGet(BaseAsyncTestCase): """Test presence.get() functionality.""" @pytest.fixture(autouse=True) - async def setup(self, use_binary_protocol): + async def setup(self, use_binary_protocol, request): """Set up test fixtures.""" - self.test_vars = await TestApp.get_test_vars() - self.use_binary_protocol = use_binary_protocol + test_instance = request.instance + + test_instance.test_vars = await TestApp.get_test_vars() + test_instance.use_binary_protocol = use_binary_protocol - self.client1 = await TestApp.get_ably_realtime( + test_instance.client1 = await TestApp.get_ably_realtime( client_id='client1', use_binary_protocol=use_binary_protocol ) - self.client2 = await TestApp.get_ably_realtime( + test_instance.client2 = await TestApp.get_ably_realtime( client_id='client2', use_binary_protocol=use_binary_protocol ) yield - await self.client1.close() - await self.client2.close() + await test_instance.client1.close() + await test_instance.client2.close() async def test_presence_enter_get(self): """ @@ -289,36 +293,18 @@ async def setup(self, use_binary_protocol, request): test_instance.test_vars = await TestApp.get_test_vars() test_instance.use_binary_protocol = use_binary_protocol - protocol = 'msgpack' if use_binary_protocol else 'json' - test_instance.client1 = await TestApp.get_ably_realtime( client_id='client1', use_binary_protocol=use_binary_protocol ) - print( - f"[{protocol}] FIXTURE SETUP: Created client1 id={id(test_instance.client1)}, " - f"state={test_instance.client1.connection.state}" - ) test_instance.client2 = await TestApp.get_ably_realtime( client_id='client2', use_binary_protocol=use_binary_protocol ) - print( - f"[{protocol}] FIXTURE SETUP: Created client2 id={id(test_instance.client2)}, " - f"state={test_instance.client2.connection.state}" - ) yield - print( - f"[{protocol}] FIXTURE TEARDOWN: client1 id={id(test_instance.client1)}, " - f"state={test_instance.client1.connection.state}" - ) - print( - f"[{protocol}] FIXTURE TEARDOWN: client2 id={id(test_instance.client2)}, " - f"state={test_instance.client2.connection.state}" - ) await test_instance.client1.close() await test_instance.client2.close() @@ -356,27 +342,26 @@ async def test_presence_message_action(self): """ Test RTP8c: PresenceMessage should have correct action string. """ - protocol = 'msgpack' if self.use_binary_protocol else 'json' - print(f"[{protocol}] TEST START: client1 id={id(self.client1)}, state={self.client1.connection.state}") - channel_name = self.get_channel_name('message_action') channel1 = self.client1.channels.get(channel_name) - print(f"[{protocol}] TEST: Got channel, client1.state={self.client1.connection.state}") received = asyncio.Future() def on_presence(msg): received.set_result(msg) - print(f"[{protocol}] TEST: About to subscribe, client1.state={self.client1.connection.state}") await channel1.presence.subscribe(on_presence) - print(f"[{protocol}] TEST: About to enter, client1.state={self.client1.connection.state}") + + # Wait for channel to attach before entering to avoid race with SYNC + await channel1.attach() + await channel1.presence.enter() msg = await asyncio.wait_for(received, timeout=5.0) - assert msg.action == PresenceAction.ENTER - print(f"[{protocol}] TEST END: client1.state={self.client1.connection.state}") + # RTP8c: Should receive ENTER action since we're entering for the first time + assert msg.action == PresenceAction.ENTER, \ + f"Expected ENTER action, got {msg.action}" @pytest.mark.parametrize('use_binary_protocol', [True, False], ids=['msgpack', 'json']) @@ -384,20 +369,22 @@ class TestRealtimePresenceEnterClient(BaseAsyncTestCase): """Test enterClient/updateClient/leaveClient functionality.""" @pytest.fixture(autouse=True) - async def setup(self, use_binary_protocol): + async def setup(self, use_binary_protocol, request): """Set up test fixtures.""" - self.test_vars = await TestApp.get_test_vars() - self.use_binary_protocol = use_binary_protocol + test_instance = request.instance + + test_instance.test_vars = await TestApp.get_test_vars() + test_instance.use_binary_protocol = use_binary_protocol # Use wildcard auth for enterClient - self.client = await TestApp.get_ably_realtime( + test_instance.client = await TestApp.get_ably_realtime( client_id='*', use_binary_protocol=use_binary_protocol ) yield - await self.client.close() + await test_instance.client.close() async def test_enter_client_multiple(self): """ @@ -469,10 +456,12 @@ class TestRealtimePresenceConnectionLifecycle(BaseAsyncTestCase): """Test presence behavior during connection lifecycle events.""" @pytest.fixture(autouse=True) - async def setup(self, use_binary_protocol): + async def setup(self, use_binary_protocol, request): """Set up test fixtures.""" - self.test_vars = await TestApp.get_test_vars() - self.use_binary_protocol = use_binary_protocol + test_instance = request.instance + + test_instance.test_vars = await TestApp.get_test_vars() + test_instance.use_binary_protocol = use_binary_protocol yield async def test_presence_enter_without_connect(self): @@ -597,10 +586,12 @@ class TestRealtimePresenceAutoReentry(BaseAsyncTestCase): """Test automatic re-entry of presence after connection suspension.""" @pytest.fixture(autouse=True) - async def setup(self, use_binary_protocol): + async def setup(self, use_binary_protocol, request): """Set up test fixtures.""" - self.test_vars = await TestApp.get_test_vars() - self.use_binary_protocol = use_binary_protocol + test_instance = request.instance + + test_instance.test_vars = await TestApp.get_test_vars() + test_instance.use_binary_protocol = use_binary_protocol yield async def test_presence_auto_reenter_after_suspend(self): @@ -756,10 +747,12 @@ class TestRealtimePresenceSyncBehavior(BaseAsyncTestCase): """Test presence SYNC behavior and state management.""" @pytest.fixture(autouse=True) - async def setup(self, use_binary_protocol): + async def setup(self, use_binary_protocol, request): """Set up test fixtures.""" - self.test_vars = await TestApp.get_test_vars() - self.use_binary_protocol = use_binary_protocol + test_instance = request.instance + + test_instance.test_vars = await TestApp.get_test_vars() + test_instance.use_binary_protocol = use_binary_protocol yield async def test_presence_refresh_on_detach(self): From d1da75b6223287af5e6cba7050762f3e8cf2022a Mon Sep 17 00:00:00 2001 From: owenpearson Date: Wed, 17 Dec 2025 15:03:21 +0000 Subject: [PATCH 6/6] test --- ably/realtime/realtimepresence.py | 2 +- test/ably/realtime/realtimepresence_test.py | 9 +++++---- 2 files changed, 6 insertions(+), 5 deletions(-) diff --git a/ably/realtime/realtimepresence.py b/ably/realtime/realtimepresence.py index 2702846d..78a97cf2 100644 --- a/ably/realtime/realtimepresence.py +++ b/ably/realtime/realtimepresence.py @@ -470,7 +470,7 @@ async def subscribe(self, *args) -> None: """ # RTP6d: Implicitly attach if self.channel.state in [ChannelState.INITIALIZED, ChannelState.DETACHED, ChannelState.DETACHING]: - asyncio.create_task(self.channel.attach()) + await self.channel.attach() # Parse arguments: similar to channel subscribe if len(args) == 1: diff --git a/test/ably/realtime/realtimepresence_test.py b/test/ably/realtime/realtimepresence_test.py index 244aa6dc..28d98cc0 100644 --- a/test/ably/realtime/realtimepresence_test.py +++ b/test/ably/realtime/realtimepresence_test.py @@ -288,7 +288,12 @@ class TestRealtimePresenceSubscribe(BaseAsyncTestCase): @pytest.fixture(autouse=True) async def setup(self, use_binary_protocol, request): """Set up test fixtures.""" + protocol = 'msgpack' if use_binary_protocol else 'json' test_instance = request.instance + print(f"[{protocol}] FIXTURE: request.instance = {test_instance}, id = {id(test_instance) if test_instance else 'None'}") + + if test_instance is None: + raise RuntimeError(f"[{protocol}] FIXTURE ERROR: request.instance is None!") test_instance.test_vars = await TestApp.get_test_vars() test_instance.use_binary_protocol = use_binary_protocol @@ -352,10 +357,6 @@ def on_presence(msg): received.set_result(msg) await channel1.presence.subscribe(on_presence) - - # Wait for channel to attach before entering to avoid race with SYNC - await channel1.attach() - await channel1.presence.enter() msg = await asyncio.wait_for(received, timeout=5.0)