test: speed up slow loopback tests (closes #1700)

bdraco · bdraco · commit d84f83d2d877 · 2026-05-17T12:33:49.000-07:00
Drops full-suite runtime from ~85s to ~46s by removing real-time waits from tests that don't need them on a loopback socket. - Apply the `quick_timing` fixture to 13 register/announce-heavy tests so probe/announce intervals shrink from 500ms/225ms/125ms to 10ms each. The tests pin behaviour, not the RFC 6762 timing constants, so the production values stay in place for everything outside the fixture's `with patch.object(...)` block. - Introduce `_backdate_cache(zc, ms=1100)` in `tests/__init__.py`. `test_async_updates_from_response` and the inline backdate in `test_cache_flush_bit` use it to satisfy RFC 6762 §10.2's "received more than one second ago" check without `time.sleep`. The helper iterates `store.values()`, not the inner dict directly — when a record is re-added with an equal hash, the dict key stays the original object while the value gets the newer one, so mutating the keys would touch stale objects no one reads. - `test_service_browser_expire_callbacks` and `test_reaper` re-add records via `_async_set_created_ttl(past, 1)` so the expire heap picks up the new `when`; mutating `record.created` alone leaves the heap entry pointing at the original future expiration time and the reaper never wakes the record up. - `test_service_info_async_request` caps the post-unregister `async_get_service_info` to 200ms (the service is gone, the default 3000ms wait is pure overhead) and tightens the `_is_complete=False` TOCTOU-race loop to 1500ms — enough for the initial `_LISTENER_TIME + random_delay` (≈220-320ms) plus margin for the loopback response. - `test_info_asking_default_is_asking_qm_questions_after_the_first_qu` drops its forced-loop timeout from 1200ms to 500ms (covers the QU at t=0 and the QM at t≈_LISTENER_TIME + max random delay). - `test_register_and_lookup_type_by_uppercase_name` replaces `time.sleep(1)` with a 50×20ms poll on the cache. - `test_integration_with_listener_class` drains pending multicast responses on the registrar instead of sleeping for them, same pattern as #1701. All 335 tests still pass and all changed tests are stable across five back-to-back runs.
diff --git a/tests/__init__.py b/tests/__init__.py
@@ -91,6 +91,23 @@ def _clear_cache(zc: Zeroconf) -> None:
     zc.question_history.clear()
 
 
+def _backdate_cache(zc: Zeroconf, ms: int = 1100) -> None:
+    """Backdate every cached record's `created` time by `ms` milliseconds.
+
+    rfc6762#section-10.2 keys off "received more than one second ago", so
+    backdating is equivalent to sleeping `ms` in real time without the
+    wall-clock wait.
+
+    Iterate `store.values()`, not the dict directly — when a record is
+    re-added with an equal hash, the key stays the original object while
+    the value is replaced with the latest; mutating the key would update
+    stale objects no one reads.
+    """
+    for store in zc.cache.cache.values():
+        for record in store.values():
+            record.created -= ms
+
+
 def time_changed_millis(millis: float | None = None) -> None:
     """Call all scheduled events for a time."""
     loop = asyncio.get_running_loop()
diff --git a/tests/services/test_browser.py b/tests/services/test_browser.py
@@ -556,7 +556,7 @@ def on_service_state_change(zeroconf, service_type, state_change, name):
 
 
 @pytest.mark.asyncio
-async def test_asking_default_is_asking_qm_questions_after_the_first_qu():
+async def test_asking_default_is_asking_qm_questions_after_the_first_qu(quick_timing: None) -> None:
     """Verify the service browser's first questions are QU and refresh queries are QM."""
     service_added = asyncio.Event()
     service_removed = asyncio.Event()
@@ -658,7 +658,7 @@ def send(out, addr=const._MDNS_ADDR, port=const._MDNS_PORT, v6_flow_scope=()):
 
 
 @pytest.mark.asyncio
-async def test_ttl_refresh_cancelled_rescue_query():
+async def test_ttl_refresh_cancelled_rescue_query(quick_timing: None) -> None:
     """Verify seeing a name again cancels the rescue query."""
     service_added = asyncio.Event()
     service_removed = asyncio.Event()
@@ -846,7 +846,7 @@ def on_service_state_change(zeroconf, service_type, state_change, name):
             await aiozc.async_close()
 
 
-def test_legacy_record_update_listener():
+def test_legacy_record_update_listener(quick_timing: None) -> None:
     """Test a RecordUpdateListener that does not implement update_records."""
 
     # instantiate a zeroconf instance
@@ -1499,10 +1499,15 @@ def update_service(self, zc, type_, name) -> None:  # type: ignore[no-untyped-de
     # Force the ttl to be 1 second
     now = current_time_millis()
     for cache_record in list(zc.cache.cache.values()):
-        for record in cache_record:
+        for record in cache_record.values():
             zc.cache._async_set_created_ttl(record, now, 1)
 
-    time.sleep(0.3)
+    # Wait for the add callback to fire from the original inject_response.
+    for _ in range(30):
+        time.sleep(0.01)
+        if len(callbacks) == 1:
+            break
+
     info.port = 400
     info._dns_service_cache = None  # we are mutating the record so clear the cache
 
@@ -1511,8 +1516,8 @@ def update_service(self, zc, type_, name) -> None:  # type: ignore[no-untyped-de
         mock_incoming_msg([info.dns_service()]),
     )
 
-    for _ in range(10):
-        time.sleep(0.05)
+    for _ in range(30):
+        time.sleep(0.01)
         if len(callbacks) == 2:
             break
 
@@ -1521,8 +1526,19 @@ def update_service(self, zc, type_, name) -> None:  # type: ignore[no-untyped-de
         ("update", type_, registration_name),
     ]
 
-    for _ in range(25):
-        time.sleep(0.05)
+    # Re-add every cached record with `created` in the past so the
+    # next reaper tick (0.01s) expires them and fires the remove
+    # callback, instead of waiting the full TTL in real time.
+    # Going through `_async_set_created_ttl` updates the expiration
+    # heap; mutating `record.created` directly would leave the heap
+    # entry pointing at the original `when` so the reaper never wakes.
+    past = current_time_millis() - 2000
+    for cache_record in list(zc.cache.cache.values()):
+        for record in list(cache_record.values()):
+            zc.cache._async_set_created_ttl(record, past, 1)
+
+    for _ in range(30):
+        time.sleep(0.01)
         if len(callbacks) == 3:
             break
 
@@ -1567,7 +1583,7 @@ def test_scheduled_ptr_query_dunder_methods():
 
 
 @pytest.mark.asyncio
-async def test_close_zeroconf_without_browser_before_start_up_queries():
+async def test_close_zeroconf_without_browser_before_start_up_queries(quick_timing: None) -> None:
     """Test that we stop sending startup queries if zeroconf is closed out from under the browser."""
     service_added = asyncio.Event()
     type_ = "_http._tcp.local."
@@ -1634,7 +1650,7 @@ def send(out, addr=const._MDNS_ADDR, port=const._MDNS_PORT, v6_flow_scope=()):
 
 
 @pytest.mark.asyncio
-async def test_close_zeroconf_without_browser_after_start_up_queries():
+async def test_close_zeroconf_without_browser_after_start_up_queries(quick_timing: None) -> None:
     """Test that we stop sending rescue queries if zeroconf is closed out from under the browser."""
     service_added = asyncio.Event()
 
diff --git a/tests/test_asyncio.py b/tests/test_asyncio.py
@@ -708,16 +708,21 @@ async def test_service_info_async_request(quick_timing: None) -> None:
     aiosinfo = AsyncServiceInfo(type_, registration_name)
     _clear_cache(aiozc.zeroconf)
     # Generating the race condition is almost impossible
-    # without patching since its a TOCTOU race
+    # without patching since its a TOCTOU race. 1500ms covers
+    # the initial _LISTENER_TIME + random delay (200-320ms) and
+    # leaves plenty of margin for the loopback response to land
+    # before the loop times out.
     with patch("zeroconf.asyncio.AsyncServiceInfo._is_complete", False):
-        await aiosinfo.async_request(aiozc.zeroconf, 3000)
+        await aiosinfo.async_request(aiozc.zeroconf, 1500)
     assert aiosinfo is not None
     assert aiosinfo.addresses == [socket.inet_aton("10.0.1.3")]
 
     task = await aiozc.async_unregister_service(new_info)
     await task
 
-    aiosinfo = await aiozc.async_get_service_info(type_, registration_name)
+    # Cap timeout: the service is gone, so this is expected to return None;
+    # waiting the default 3000ms is pure overhead.
+    aiosinfo = await aiozc.async_get_service_info(type_, registration_name, timeout=200)
     assert aiosinfo is None
 
     await aiozc.async_close()
@@ -784,7 +789,7 @@ def update_service(self, aiozc: Zeroconf, type: str, name: str) -> None:
 
 
 @pytest.mark.asyncio
-async def test_async_context_manager() -> None:
+async def test_async_context_manager(quick_timing: None) -> None:
     """Test using an async context manager."""
     type_ = "_test10-sr-type._tcp.local."
     name = "xxxyyy"
@@ -984,7 +989,7 @@ def update_service(self, zc, type_, name) -> None:  # type: ignore[no-untyped-de
 
 
 @pytest.mark.asyncio
-async def test_integration():
+async def test_integration(quick_timing: None) -> None:
     service_added = asyncio.Event()
     service_removed = asyncio.Event()
     unexpected_ttl = asyncio.Event()
@@ -1176,9 +1181,11 @@ def send(out, addr=const._MDNS_ADDR, port=const._MDNS_PORT):
     # patch the zeroconf send
     with patch.object(zeroconf_info, "async_send", send):
         aiosinfo = AsyncServiceInfo(type_, registration_name)
-        # Patch _is_complete so we send multiple times
+        # Patch _is_complete so we send multiple times. 500ms covers
+        # the QU query at 0ms plus the QM query at ~_LISTENER_TIME +
+        # max random delay (~320ms).
         with patch("zeroconf.asyncio.AsyncServiceInfo._is_complete", False):
-            await aiosinfo.async_request(aiozc.zeroconf, 1200)
+            await aiosinfo.async_request(aiozc.zeroconf, 500)
         try:
             assert first_outgoing.questions[0].unicast is True  # type: ignore[union-attr]
             assert second_outgoing.questions[0].unicast is False  # type: ignore[attr-defined]
diff --git a/tests/test_core.py b/tests/test_core.py
@@ -24,7 +24,7 @@
 from zeroconf._protocol.incoming import DNSIncoming
 from zeroconf.asyncio import AsyncZeroconf
 
-from . import _clear_cache, _inject_response, _wait_for_start, has_working_ipv6
+from . import _backdate_cache, _clear_cache, _inject_response, _wait_for_start, has_working_ipv6
 
 log = logging.getLogger("zeroconf")
 original_logging_level = logging.NOTSET
@@ -301,7 +301,7 @@ def mock_split_incoming_msg(
             # all old records with that name, rrtype, and rrclass that were received
             # more than one second ago are declared invalid,
             # and marked to expire from the cache in one second.
-            time.sleep(1.1)
+            _backdate_cache(zeroconf)
 
             # service updated. currently only text record can be updated
             service_text = b"path=/~humingchun/"
@@ -310,12 +310,12 @@ def mock_split_incoming_msg(
             assert dns_text is not None
             assert cast(r.DNSText, dns_text).text == service_text  # service_text is b'path=/~humingchun/'
 
-            time.sleep(1.1)
+            _backdate_cache(zeroconf)
 
             # The split message only has a SRV and A record.
             # This should not evict TXT records from the cache
             _inject_response(zeroconf, mock_split_incoming_msg(r.ServiceStateChange.Updated))
-            time.sleep(1.1)
+            _backdate_cache(zeroconf)
             dns_text = zeroconf.cache.get_by_details(service_name, const._TYPE_TXT, const._CLASS_IN)
             assert dns_text is not None
             assert cast(r.DNSText, dns_text).text == service_text  # service_text is b'path=/~humingchun/'
@@ -426,7 +426,7 @@ def test_goodbye_all_services():
     zc.close()
 
 
-def test_register_service_with_custom_ttl():
+def test_register_service_with_custom_ttl(quick_timing: None) -> None:
     """Test a registering a service with a custom ttl."""
 
     # instantiate a zeroconf instance
@@ -453,7 +453,7 @@ def test_register_service_with_custom_ttl():
     zc.close()
 
 
-def test_logging_packets(caplog):
+def test_logging_packets(caplog: pytest.LogCaptureFixture, quick_timing: None) -> None:
     """Test packets are only logged with debug logging."""
 
     # instantiate a zeroconf instance
diff --git a/tests/test_engine.py b/tests/test_engine.py
@@ -39,9 +39,17 @@ async def test_reaper():
         original_entries = list(itertools.chain(*(cache.entries_with_name(name) for name in cache.names())))
         record_with_10s_ttl = r.DNSAddress("a", const._TYPE_SOA, const._CLASS_IN, 10, b"a")
         record_with_1s_ttl = r.DNSAddress("a", const._TYPE_SOA, const._CLASS_IN, 1, b"b")
+        # Backdate the short-lived record so it expires at the next
+        # reaper tick instead of waiting the full TTL in real time.
+        record_with_1s_ttl.created -= 2000
         zeroconf.cache.async_add_records([record_with_10s_ttl, record_with_1s_ttl])
         question = r.DNSQuestion("_hap._tcp._local.", const._TYPE_PTR, const._CLASS_IN)
         now = r.current_time_millis()
+        # Add the question at `past` so the reaper's next tick will see
+        # `current_time - past > _DUPLICATE_QUESTION_INTERVAL` and prune it,
+        # while the initial `suppresses(now, ...)` check still sees the
+        # question as recent (since `now - past == 999`, not strictly `> 999`).
+        past = now - 999
         other_known_answers: set[r.DNSRecord] = {
             r.DNSPointer(
                 "_hap._tcp.local.",
@@ -51,10 +59,10 @@ async def test_reaper():
                 "known-to-other._hap._tcp.local.",
             )
         }
-        zeroconf.question_history.add_question_at_time(question, now, other_known_answers)
+        zeroconf.question_history.add_question_at_time(question, past, other_known_answers)
         assert zeroconf.question_history.suppresses(question, now, other_known_answers)
         entries_with_cache = list(itertools.chain(*(cache.entries_with_name(name) for name in cache.names())))
-        await asyncio.sleep(1.2)
+        await asyncio.sleep(0.1)
         entries = list(itertools.chain(*(cache.entries_with_name(name) for name in cache.names())))
         assert zeroconf.cache.get(record_with_1s_ttl) is None
         await aiozc.async_close()
@@ -77,6 +85,10 @@ async def test_reaper_aborts_when_done():
         assert zeroconf.cache.get(record_with_10s_ttl) is not None
         assert zeroconf.cache.get(record_with_1s_ttl) is not None
         await aiozc.async_close()
-        await asyncio.sleep(1.2)
+        # Backdate to immediate expiry so we don't have to wait the full
+        # TTL; the assertion is that the reaper has stopped, so a
+        # short sleep is enough to give it a chance to (incorrectly) run.
+        record_with_1s_ttl.created -= 2000
+        await asyncio.sleep(0.1)
         assert zeroconf.cache.get(record_with_10s_ttl) is not None
         assert zeroconf.cache.get(record_with_1s_ttl) is not None
diff --git a/tests/test_handlers.py b/tests/test_handlers.py
@@ -215,15 +215,18 @@ def test_register_and_lookup_type_by_uppercase_name(self):
         out = r.DNSOutgoing(const._FLAGS_QR_QUERY)
         out.add_question(r.DNSQuestion(type_.upper(), const._TYPE_PTR, const._CLASS_IN))
         zc.send(out)
-        time.sleep(1)
         info = ServiceInfo(type_, registration_name)
-        info.load_from_cache(zc)
+        for _ in range(50):
+            time.sleep(0.02)
+            info.load_from_cache(zc)
+            if info.addresses:
+                break
         assert info.addresses == [socket.inet_pton(socket.AF_INET, "1.2.3.4")]
         assert info.properties == {b"version": b"1.0"}
         zc.close()
 
 
-def test_ptr_optimization():
+def test_ptr_optimization(quick_timing: None) -> None:
     # instantiate a zeroconf instance
     zc = Zeroconf(interfaces=["127.0.0.1"])
 
@@ -597,7 +600,7 @@ async def test_probe_answered_immediately_with_uppercase_name():
     zc.close()
 
 
-def test_qu_response():
+def test_qu_response(quick_timing: None) -> None:
     """Handle multicast incoming with the QU bit set."""
     # instantiate a zeroconf instance
     zc = Zeroconf(interfaces=["127.0.0.1"])
@@ -1351,8 +1354,12 @@ async def test_cache_flush_bit():
         else:
             assert entry.ttl == 1
 
-    # Wait for the ttl 1 records to expire
-    await asyncio.sleep(1.1)
+    # Backdate the ttl=1 records so they are already expired when
+    # load_from_cache runs — equivalent to sleeping 1.1s without the wait.
+    for store in zc.cache.cache.values():
+        for cached in store.values():
+            if cached.ttl == 1:
+                cached.created -= 1100
 
     loaded_info = r.ServiceInfo(type_, registration_name)
     loaded_info.load_from_cache(zc)
diff --git a/tests/test_services.py b/tests/test_services.py
@@ -5,7 +5,6 @@
 import logging
 import os
 import socket
-import time
 import unittest
 from threading import Event
 from typing import Any
@@ -113,8 +112,10 @@ def update_service(self, zeroconf, type, name):
             service_added.wait(1)
             assert service_added.is_set()
 
-            # short pause to allow multicast timers to expire
-            time.sleep(0.5)
+            # Drain pending multicast announces from the registrar instead
+            # of sleeping for them — same pattern as PR #1701.
+            zeroconf_registrar.out_queue.queue.clear()
+            zeroconf_registrar.out_delay_queue.queue.clear()
 
             zeroconf_browser.add_service_listener(type_, DuplicateListener())
             duplicate_service_added.wait(
diff --git a/tests/test_updates.py b/tests/test_updates.py
@@ -29,7 +29,7 @@ def teardown_module():
         log.setLevel(original_logging_level)
 
 
-def test_legacy_record_update_listener():
+def test_legacy_record_update_listener(quick_timing: None) -> None:
     """Test a RecordUpdateListener that does not implement update_records."""
 
     # instantiate a zeroconf instance
