Increase timeout in ServiceInfo.request to handle loaded systems (#895)

bdraco · web-flow · commit 56c7d692d67b · 2021-07-04T09:16:02.000-05:00
It can take a few seconds for a loaded system to run the `async_request` coroutine when the event loop is busy or the system is CPU bound (example being Home Assistant startup).  We now add
an additional `_LOADED_SYSTEM_TIMEOUT` (10s) to the `run_coroutine_threadsafe` calls to ensure the coroutine has the total amount of time to run up to its internal timeout (default of 3000ms). 

Ten seconds is a bit large of a timeout; however, its only unused in cases where we wrap other timeouts. We now expect the only instance the `run_coroutine_threadsafe` result timeout will happen in a production circumstance is when someone is running a `ServiceInfo.request()` in a thread and another thread calls `Zeroconf.close()` at just the right moment that the future is never completed unless the system is so loaded that it is nearly unresponsive.

The timeout for `run_coroutine_threadsafe` is the maximum time a thread can cleanly shut down when zeroconf is closed out in another thread, which should always be longer than the underlying thread operation.
diff --git a/tests/services/test_info.py b/tests/services/test_info.py
@@ -739,3 +739,15 @@ def send(out, addr=const._MDNS_ADDR, port=const._MDNS_PORT):
         zeroconf.get_service_info(f"name.{type_}", type_, 500, question_type=r.DNSQuestionType.QM)
         assert first_outgoing.questions[0].unicast == False
         zeroconf.close()
+
+
+def test_request_timeout():
+    """Test that the timeout does not throw an exception and finishes close to the actual timeout."""
+    zeroconf = r.Zeroconf(interfaces=['127.0.0.1'])
+    start_time = r.current_time_millis()
+    assert zeroconf.get_service_info("_notfound.local.", "notthere._notfound.local.") is None
+    end_time = r.current_time_millis()
+    zeroconf.close()
+    # 3000ms for the default timeout
+    # 1000ms for loaded systems + schedule overhead
+    assert (end_time - start_time) < 3000 + 1000
diff --git a/tests/test_asyncio.py b/tests/test_asyncio.py
@@ -935,3 +935,17 @@ def update_service(self, zc, type_, name) -> None:
         ('add', type_, registration_name),
     ]
     await aiozc.async_close()
+
+
+@pytest.mark.asyncio
+async def test_async_request_timeout():
+    """Test that the timeout does not throw an exception and finishes close to the actual timeout."""
+    aiozc = AsyncZeroconf(interfaces=['127.0.0.1'])
+    await aiozc.zeroconf.async_wait_for_start()
+    start_time = current_time_millis()
+    assert await aiozc.async_get_service_info("_notfound.local.", "notthere._notfound.local.") is None
+    end_time = current_time_millis()
+    await aiozc.async_close()
+    # 3000ms for the default timeout
+    # 1000ms for loaded systems + schedule overhead
+    assert (end_time - start_time) < 3000 + 1000
diff --git a/tests/utils/test_asyncio.py b/tests/utils/test_asyncio.py
@@ -5,14 +5,17 @@
 """Unit tests for zeroconf._utils.asyncio."""
 
 import asyncio
+import concurrent.futures
 import contextlib
 import threading
 import time
 from unittest.mock import patch
 
 import pytest
 
+from zeroconf._core import _CLOSE_TIMEOUT
 from zeroconf._utils import asyncio as aioutils
+from zeroconf.const import _LOADED_SYSTEM_TIMEOUT
 
 
 @pytest.mark.asyncio
@@ -82,7 +85,8 @@ async def _still_running():
 
     def _run_coro() -> None:
         runcoro_thread_ready.set()
-        asyncio.run_coroutine_threadsafe(_still_running(), loop).result(1)
+        with contextlib.suppress(concurrent.futures.TimeoutError):
+            asyncio.run_coroutine_threadsafe(_still_running(), loop).result(1)
 
     runcoro_thread = threading.Thread(target=_run_coro, daemon=True)
     runcoro_thread.start()
@@ -97,3 +101,14 @@ def _run_coro() -> None:
 
     assert loop.is_running() is False
     runcoro_thread.join()
+
+
+def test_cumulative_timeouts_less_than_close_plus_buffer():
+    """Test that the combined async timeouts are shorter than the close timeout with the buffer.
+
+    We want to make sure that the close timeout is the one that gets
+    raised if something goes wrong.
+    """
+    assert (
+        aioutils._TASK_AWAIT_TIMEOUT + aioutils._GET_ALL_TASKS_TIMEOUT + aioutils._WAIT_FOR_LOOP_TASKS_TIMEOUT
+    ) < 1 + _CLOSE_TIMEOUT + _LOADED_SYSTEM_TIMEOUT
diff --git a/zeroconf/_core.py b/zeroconf/_core.py
@@ -62,6 +62,7 @@
     _FLAGS_AA,
     _FLAGS_QR_QUERY,
     _FLAGS_QR_RESPONSE,
+    _LOADED_SYSTEM_TIMEOUT,
     _MAX_MSG_ABSOLUTE,
     _MDNS_ADDR,
     _MDNS_ADDR6,
@@ -172,7 +173,9 @@ def close(self) -> None:
             return
         if not self.loop.is_running():
             return
-        asyncio.run_coroutine_threadsafe(self._async_close(), self.loop).result(_CLOSE_TIMEOUT)
+        asyncio.run_coroutine_threadsafe(self._async_close(), self.loop).result(
+            _CLOSE_TIMEOUT + _LOADED_SYSTEM_TIMEOUT
+        )
 
 
 class AsyncListener(asyncio.Protocol, QuietLogger):
diff --git a/zeroconf/_services/info.py b/zeroconf/_services/info.py
@@ -45,6 +45,7 @@
     _DNS_OTHER_TTL,
     _FLAGS_QR_QUERY,
     _LISTENER_TIME,
+    _LOADED_SYSTEM_TIMEOUT,
     _TYPE_A,
     _TYPE_AAAA,
     _TYPE_PTR,
@@ -427,7 +428,7 @@ def request(
             raise RuntimeError("Use AsyncServiceInfo.async_request from the event loop")
         return asyncio.run_coroutine_threadsafe(
             self.async_request(zc, timeout, question_type), zc.loop
-        ).result(millis_to_seconds(timeout) + 1)
+        ).result(millis_to_seconds(timeout) + _LOADED_SYSTEM_TIMEOUT)
 
     async def async_request(
         self, zc: 'Zeroconf', timeout: float, question_type: Optional[DNSQuestionType] = None
diff --git a/zeroconf/_utils/asyncio.py b/zeroconf/_utils/asyncio.py
@@ -26,8 +26,8 @@
 from typing import Any, List, Optional, Set, cast
 
 _TASK_AWAIT_TIMEOUT = 1
-_GET_ALL_TASKS_TIMEOUT = 1
-_WAIT_FOR_LOOP_TASKS_TIMEOUT = 2  # Must be larger than _TASK_AWAIT_TIMEOUT
+_GET_ALL_TASKS_TIMEOUT = 3
+_WAIT_FOR_LOOP_TASKS_TIMEOUT = 3  # Must be larger than _TASK_AWAIT_TIMEOUT
 
 
 def get_best_available_queue() -> queue.Queue:
diff --git a/zeroconf/const.py b/zeroconf/const.py
@@ -34,6 +34,12 @@
 _DUPLICATE_QUESTION_INTERVAL = _BROWSER_TIME - 1  # ms
 _BROWSER_BACKOFF_LIMIT = 3600  # s
 _CACHE_CLEANUP_INTERVAL = 10000  # ms
+_LOADED_SYSTEM_TIMEOUT = 10  # s
+# If the system is loaded or the event
+# loop was blocked by another task that was doing I/O in the loop
+# (shouldn't happen but it does in practice) we need to give
+# a buffer timeout to ensure a coroutine can finish before
+# the future times out
 
 # Some DNS constants
 
