Skip to content

Commit efc009d

Browse files
authored
fix: Keep a failing background watcher from breaking a successful actor call (#1027)
### Description `actor.call()` with the default `logger='default'` could raise on a run that had already succeeded. A status poll that failed after retries left the exception on the watcher task; `stop()` then cancelled an already-finished task and `await`ed it, re-raising past `except asyncio.CancelledError`. The sync twin leaked the same failure out of its thread. - Both watcher loops now use the handler `StreamedLog._stream_log` already had: warn on `is_timeout_error`, `logger.exception` otherwise. A failed poll gets reported and the run's own result stands. - The sync watcher's thread is a daemon, so a watcher whose loop never terminates cannot hold up interpreter shutdown. - `StreamedLog.stop()` closes the stream response and caps its join at `_stop_timeout_s` (5s), where it used to join unbounded on a stream that may not speak for hours. - `start()` on both sync classes checks `is_alive()`, so a handle left by a thread that outlived its stop does not block a restart. The close alone is not enough. On Impit 0.13.2 `Response.close()` returns immediately and sets `is_closed=True`, yet a reader blocked in `iter_bytes()` stays blocked, and closing the `Client` does not release it either. The close is kept because it is correct for a custom HTTP client, and the capped join is what makes `stop()` return. ### Why `stop()` is bounded this way - #825 bounded `stop()` by requesting the log stream with a 30s read timeout. - #944 removed that: Impit applies `timeout` to the whole request, streamed body included, so a run logging past the bound was cut off mid-stream with `impit.TimeoutException` (#945). The stream has used `no_timeout` since, with the unbounded `stop()` recorded as a known limitation. - This PR caps the join and closes the response, leaving the stream request alone. `_stream_timeout` stays `no_timeout`, still asserted by `test_streamed_log_sync_requests_stream_with_no_timeout`, so #945 cannot regress. What it fixes is the case #944 left open: a manual `stop()` on a stream gone quiet. Trade-off: a thread outliving the 5s cap keeps running as a daemon, so `stop()` can return before the tail is flushed. On the `actor.call()` path the run's EOF ends the thread first, measured at 0.000s over repeated `apify/hello-world` runs. ### Test plan - 8 unit tests and an integration test that fails a real run's background status polls, each red before the fix. *✍️ Drafted by Claude Code*
1 parent 10ace92 commit efc009d

4 files changed

Lines changed: 461 additions & 28 deletions

File tree

‎src/apify_client/_status_message_watcher.py‎

Lines changed: 30 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -120,11 +120,19 @@ async def __aexit__(
120120
await self.stop()
121121

122122
async def _log_changed_status_message(self) -> None:
123-
while True:
124-
run_data = await self._run_client.get()
125-
if not self._log_run_data(run_data):
126-
break
127-
await asyncio.sleep(self._check_period)
123+
try:
124+
while True:
125+
run_data = await self._run_client.get()
126+
if not self._log_run_data(run_data):
127+
break
128+
await asyncio.sleep(self._check_period)
129+
except Exception as exc:
130+
if self._run_client._http_client.is_timeout_error(exc): # noqa: SLF001
131+
# An expected timeout, so warn rather than leak a traceback.
132+
self._to_logger.warning('Status message redirection stopped: the status request timed out.')
133+
else:
134+
# A failed poll must not escape into `stop` and surface as a failure of the run.
135+
self._to_logger.exception('Status message redirection stopped due to unexpected error:')
128136

129137

130138
@docs_group('Other')
@@ -159,10 +167,11 @@ def start(self) -> Thread:
159167
160168
The caller is responsible for cleanup by calling the `stop` method when done.
161169
"""
162-
if self._logging_thread:
170+
if self._logging_thread and self._logging_thread.is_alive():
163171
raise RuntimeError('Logging thread already active')
164172
self._stop_logging = False
165-
self._logging_thread = threading.Thread(target=self._log_changed_status_message)
173+
# A daemon thread, so a watcher still polling cannot hold up interpreter shutdown.
174+
self._logging_thread = threading.Thread(target=self._log_changed_status_message, daemon=True)
166175
self._logging_thread.start()
167176
return self._logging_thread
168177

@@ -189,9 +198,17 @@ def __exit__(
189198
self.stop()
190199

191200
def _log_changed_status_message(self) -> None:
192-
while True:
193-
if not self._log_run_data(self._run_client.get()):
194-
break
195-
if self._stop_logging:
196-
break
197-
time.sleep(self._check_period)
201+
try:
202+
while True:
203+
if not self._log_run_data(self._run_client.get()):
204+
break
205+
if self._stop_logging:
206+
break
207+
time.sleep(self._check_period)
208+
except Exception as exc:
209+
if self._run_client._http_client.is_timeout_error(exc): # noqa: SLF001
210+
# An expected timeout, so warn rather than leak a traceback.
211+
self._to_logger.warning('Status message redirection stopped: the status request timed out.')
212+
else:
213+
# A failed poll must not escape the background thread.
214+
self._to_logger.exception('Status message redirection stopped due to unexpected error:')

‎src/apify_client/_streamed_log.py‎

Lines changed: 54 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@
1515
from types import TracebackType
1616

1717
from apify_client._resource_clients import LogClient, LogClientAsync
18+
from apify_client.http_clients import HttpResponse
1819
from apify_client.types import Timeout
1920

2021

@@ -98,6 +99,13 @@ class StreamedLog(StreamedLogBase):
9899
call `start` and `stop` manually. Obtain an instance via `RunClient.get_streamed_log`.
99100
"""
100101

102+
_stop_timeout_s: ClassVar[float] = 5
103+
"""Upper bound on how long `stop` waits for the streaming thread to finish.
104+
105+
Closing the response only ends the read on a transport that honours it, which neither Impit nor HTTPX does, so
106+
without a bound `stop` would wait for the next chunk, which on a quiet run may be hours away.
107+
"""
108+
101109
def __init__(self, log_client: LogClient, *, to_logger: logging.Logger, from_start: bool = True) -> None:
102110
"""Initialize `StreamedLog`.
103111
@@ -111,14 +119,15 @@ def __init__(self, log_client: LogClient, *, to_logger: logging.Logger, from_sta
111119
super().__init__(to_logger=to_logger, from_start=from_start)
112120
self._log_client = log_client
113121
self._streaming_thread: Thread | None = None
122+
self._log_stream: HttpResponse | None = None
114123
self._stop_logging = False
115124

116125
def start(self) -> Thread:
117126
"""Start the streaming thread.
118127
119128
The caller is responsible for cleanup by calling the `stop` method when done.
120129
"""
121-
if self._streaming_thread:
130+
if self._streaming_thread and self._streaming_thread.is_alive():
122131
raise RuntimeError('Streaming thread already active')
123132
self._stop_logging = False
124133
# A daemon thread so a stream still blocked on a read can never hold up interpreter shutdown.
@@ -127,13 +136,29 @@ def start(self) -> Thread:
127136
return self._streaming_thread
128137

129138
def stop(self) -> None:
130-
"""Signal the streaming thread to stop logging and wait for it to finish."""
139+
"""Signal the streaming thread to stop logging and wait up to `_stop_timeout_s` for it to finish.
140+
141+
A thread that outlives the wait is a daemon with `_stop_logging` set, so it exits after at most one more chunk,
142+
and only then does its buffered tail reach the logger. Its handle is kept while it is alive, so `start` cannot
143+
revive it beside a second thread on the same buffer.
144+
"""
131145
if not self._streaming_thread:
132146
raise RuntimeError('Streaming thread is not active')
133147
self._stop_logging = True
134-
self._streaming_thread.join()
135-
self._streaming_thread = None
136-
self._stop_logging = False
148+
# Read once; the streaming thread clears the attribute as soon as the stream ends.
149+
log_stream = self._log_stream
150+
if log_stream is not None:
151+
try:
152+
log_stream.close()
153+
except Exception:
154+
# A failing `close` in a custom transport must not fail the caller.
155+
self._to_logger.exception('Closing the log stream failed:')
156+
self._streaming_thread.join(timeout=self._stop_timeout_s)
157+
if self._streaming_thread.is_alive():
158+
# Otherwise log messages arriving after `stop` returned have no explanation.
159+
self._to_logger.debug('Log streaming thread outlived the stop timeout; it ends after the next chunk.')
160+
else:
161+
self._streaming_thread = None
137162

138163
def __enter__(self) -> Self:
139164
"""Start the streaming thread within the context. Exiting the context will finish the streaming thread."""
@@ -151,15 +176,30 @@ def _stream_log(self) -> None:
151176
with self._log_client.stream(raw=True, timeout=self._stream_timeout) as log_stream:
152177
if not log_stream:
153178
return
179+
# Published so `stop` can close the response.
180+
self._log_stream = log_stream
154181
try:
182+
# `stop` may have run before the response existed for it to close.
183+
if self._stop_logging:
184+
return
155185
for data in log_stream.iter_bytes():
156186
self._process_new_data(data)
157187
if self._stop_logging:
158188
break
159189
finally:
160-
# Flush the last buffered part even if the read timed out or was stopped.
161-
self._log_buffer_content(include_last_part=True)
190+
self._log_stream = None
191+
try:
192+
# Flush the last buffered part even if the read timed out or was stopped.
193+
self._log_buffer_content(include_last_part=True)
194+
except Exception:
195+
# A truncated stream leaves an undecodable tail, which is worth a traceback even while a stop
196+
# is in progress.
197+
self._to_logger.exception('Log redirection stopped due to unexpected error:')
162198
except Exception as exc:
199+
if self._stop_logging:
200+
# `stop` closed the stream out from under the read, so the failure is expected.
201+
self._to_logger.debug('Log streaming stopped while `stop` was in progress: %r', exc)
202+
return
163203
if self._log_client._http_client.is_timeout_error(exc): # noqa: SLF001
164204
# The stream cannot continue, so warn and let the thread end instead of leaking a traceback.
165205
self._to_logger.warning('Log streaming stopped: the log stream request timed out.')
@@ -236,8 +276,13 @@ async def _stream_log(self) -> None:
236276
async for data in log_stream.aiter_bytes():
237277
self._process_new_data(data)
238278
finally:
239-
# Flush the last buffered part even if the task is cancelled by `stop()`.
240-
self._log_buffer_content(include_last_part=True)
279+
try:
280+
# Flush the last buffered part even if the task is cancelled by `stop()`.
281+
self._log_buffer_content(include_last_part=True)
282+
except Exception:
283+
# A truncated stream leaves an undecodable tail. Keeping the failure here also keeps the
284+
# cancellation `stop` raised propagating, so the task ends up cancelled as asyncio expects.
285+
self._to_logger.exception('Log redirection stopped due to unexpected error:')
241286
except Exception as exc:
242287
if self._log_client._http_client.is_timeout_error(exc): # noqa: SLF001
243288
# A timeout on the long-lived stream is an expected terminal condition, not an error.

‎tests/integration/test_log.py‎

Lines changed: 55 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,15 +2,23 @@
22

33
from __future__ import annotations
44

5+
import asyncio
6+
import logging
7+
import threading
58
from contextlib import AbstractAsyncContextManager, AbstractContextManager
69
from typing import TYPE_CHECKING
710

811
from .._utils import maybe_await
912
from apify_client._models import ListOfBuilds, Run
13+
from apify_client._resource_clients import RunClient, RunClientAsync
1014
from apify_client.http_clients import HttpResponse
1115

1216
if TYPE_CHECKING:
17+
import pytest
18+
from _pytest.logging import LogCaptureFixture
19+
1320
from apify_client import ApifyClient, ApifyClientAsync
21+
from apify_client.types import Timeout
1422

1523
# Use a simple, fast public actor for testing
1624
HELLO_WORLD_ACTOR = 'apify/hello-world'
@@ -99,3 +107,50 @@ async def test_log_stream_from_run(client: ApifyClient | ApifyClientAsync, *, is
99107
assert len(content) > 0
100108
finally:
101109
await maybe_await(run_client.delete())
110+
111+
112+
async def test_actor_call_returns_run_when_status_poll_fails(
113+
client: ApifyClient | ApifyClientAsync,
114+
caplog: LogCaptureFixture,
115+
monkeypatch: pytest.MonkeyPatch,
116+
*,
117+
is_async: bool,
118+
) -> None:
119+
"""A failing status poll is reported to the logger and leaves `call` returning the run the platform finished."""
120+
logger = logging.getLogger(f'test-status-poll-failure-{"async" if is_async else "sync"}')
121+
122+
# `call` polls the run status from a background task or thread and awaits the run itself on the main one, so
123+
# failing only the background polls leaves the rest of `call` talking to the real API.
124+
if is_async:
125+
main_task = asyncio.current_task()
126+
original_get_async = RunClientAsync.get
127+
128+
async def failing_get_async(self: RunClientAsync, *, timeout: Timeout = 'short') -> Run | None:
129+
if asyncio.current_task() is main_task:
130+
return await original_get_async(self, timeout=timeout)
131+
raise RuntimeError('Simulated status poll failure')
132+
133+
monkeypatch.setattr(RunClientAsync, 'get', failing_get_async)
134+
else:
135+
original_get = RunClient.get
136+
137+
def failing_get(self: RunClient, *, timeout: Timeout = 'short') -> Run | None:
138+
if threading.current_thread() is threading.main_thread():
139+
return original_get(self, timeout=timeout)
140+
raise RuntimeError('Simulated status poll failure')
141+
142+
monkeypatch.setattr(RunClient, 'get', failing_get)
143+
144+
with caplog.at_level(logging.DEBUG, logger=logger.name):
145+
run = await maybe_await(client.actor(HELLO_WORLD_ACTOR).call(logger=logger))
146+
147+
assert isinstance(run, Run)
148+
try:
149+
assert run.status == 'SUCCEEDED'
150+
assert any(
151+
record.levelno == logging.ERROR
152+
and record.message == 'Status message redirection stopped due to unexpected error:'
153+
for record in caplog.records
154+
)
155+
finally:
156+
await maybe_await(client.run(run.id).delete())

0 commit comments

Comments
 (0)