diff --git a/.gitignore b/.gitignore index 424ea99..210e8ae 100644 --- a/.gitignore +++ b/.gitignore @@ -24,3 +24,6 @@ docs/ .claude/ .agents/ skills-lock.json + +# logs +*.log diff --git a/CHANGELOG.md b/CHANGELOG.md index fbe523d..404b019 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,68 @@ All notable changes to this project will be documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [0.1.4] - 2026-08-17 + +### Added + +- New `rate_limited` counter in `HandlerStats`: 429 `Retry-After` waits are + now counted even though they never consume the retry budget, so a + rate-limit storm shows up in the stats instead of reporting zero retries. + +### Fixed + +- Failed handler construction no longer leaves a half-built handler registered + with the logging module. Previously, exit-time `logging.shutdown()` called + `close()` on the half-built instance and printed a stray `AttributeError` + after the real construction error; the registration is now dropped on + failure. The cleanup itself is failure-proof (`contextlib.suppress`), so a + teardown error (e.g. logging internals already torn down at interpreter + shutdown) can never mask the original construction error. +- Live smoke tests no longer race the worker: `close()` returns once the + `shutdown_timeout` elapses even while the daemon worker is still sending its + last batches, so the tests now poll the stats until the counters converge + before asserting. A new live test proves 10 records with `batch_size=5` go + out as exactly two 5-record messages (`batches_sent == 2`). +- Worker shutdown is event-backed: a saturated queue or a `drop_oldest` + eviction can no longer lose the shutdown sentinel and leak the worker + thread (and its HTTP client) after `close()`. +- **Shutdown no longer waits out a long `flush_interval`**: the accumulator + polls the shutdown event between capped waits, so `close()` returns promptly + (≤ ~1s) even with a partial batch pending and the sentinel lost; the pending + batch is still flushed first. +- A close() that interleaves with an in-flight `emit()` no longer orphans the + record: `emit` and `close` are mutually exclusive, so nothing accepted + before `close()` is lost (and `queue_full_policy="block"` can no longer hang + an emitter past shutdown). +- Post-close `emit()` drops and counts the record instead of potentially + hanging the caller under `queue_full_policy="block"`. +- `truncate_text` clamps the marker when the limit is smaller than the marker + itself, so a truncated message can never exceed the cap (Telegram 400s + oversized payloads). +- The one-time 429 heads-up notification now swallows any failure (not just + transport errors), so it can never surface through `send_with_retry`. +- **Batches are no longer split by a pending shutdown.** The shutdown poll now + runs only after a capped wait elapsed with nothing arriving, so records that + keep flowing still group into one batch even when `close()` was called during + the drain (previously every remaining record flushed as its own message). +- A non-200 `sendMessage` response (a 3xx — redirects are never followed — or + a non-200 2xx) is no longer reported as delivered; getMe validation + maps non-JSON 200 bodies to `TelegramConfigError` instead of a bare + `ValueError`; env `TG_CHAT_ID` trailing whitespace is stripped like the + token's; queue `task_done` accounting is now exact, so `queue.join()` can + no longer hang. +- `close()` now enqueues the shutdown sentinel **before** signaling the + worker, so the worker can never exit while the sentinel is still about to be + queued and strand it in the queue (a user's `queue.join()` would hang). +- getMe validation requires an object body with `ok == True` exactly: a + scalar/list JSON body or a merely truthy `ok` (e.g. `1`) maps to + `TelegramConfigError` instead of a raw `AttributeError` or a false accept. +- The clamped truncation marker is nudged off a trailing backslash, so a tiny + `max_length` with MarkdownV2 can never leave a dangling escape pair. +- HTTP redirects are disabled on the send client: a 302/308 with a `Location` + is never followed, so a redirected `sendMessage` request can never be + mistaken for a delivery. + ## [0.1.3] - 2026-08-16 ### Added diff --git a/localtest.bat b/localtest.bat new file mode 100644 index 0000000..decb3f7 --- /dev/null +++ b/localtest.bat @@ -0,0 +1,9 @@ +@echo off +( + uv run mypy || exit /b 1 + uv run ruff format --check . || exit /b 1 + uv run ruff check . || exit /b 1 + uv run pylint tests tg_logging_handler || exit /b 1 + uv run flake8 tests tg_logging_handler || exit /b 1 + uv run pytest --cov=tg_logging_handler || exit /b 1 +) > local.log 2>&1 diff --git a/pyproject.toml b/pyproject.toml index 08e143c..3b0492c 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -4,7 +4,7 @@ build-backend = "hatchling.build" [project] name = "tg-logging-handler" -version = "0.1.3" +version = "0.1.4" description = "Production-grade Telegram destination for Python's standard logging module" readme = "README.md" requires-python = ">=3.10" diff --git a/tests/test_batching.py b/tests/test_batching.py index 27fc0d7..bb7bdfc 100644 --- a/tests/test_batching.py +++ b/tests/test_batching.py @@ -109,3 +109,68 @@ def test_constructor_validates_args() -> None: BatchAccumulator(0, 1.0) with pytest.raises(ValueError): BatchAccumulator(1, -1.0) + + +class _TimeoutQueue: + """Scripted queue whose get() always times out (raises Empty).""" + + def __init__(self) -> None: + self._items: list[object] = [] + + def put_nowait(self, item: object) -> None: + self._items.append(item) + + def get(self, timeout: float | None = None) -> object: + if not self._items: + raise queue.Empty + return self._items.pop(0) + + def task_done(self) -> None: + pass + + +def test_second_get_timeout_returns_partial_batch() -> None: + # The mid-batch get() can time out with nothing new arriving; the partial + # batch must be returned, not lost. Constant clock keeps remaining > 0 so + # the get() is actually attempted (and times out immediately, scripted). + acc, _ = _mk(batch_size=5, flush_interval=1.0, clock=ScriptedClock(0.0, 0.0)) + q = _TimeoutQueue() + q.put_nowait(_record("only")) + batch, shutdown = acc.collect(q, Shutdown, timeout=0) # type: ignore[arg-type] + assert [r.getMessage() for r in batch] == ["only"] + assert not shutdown + + +def test_stop_flushes_partial_batch_promptly() -> None: + # A shutdown requested while a partial batch is mid-collection must flush + # it immediately, not wait out the flush interval (potentially minutes); + # collect polls the stop predicate after a capped wait with nothing + # arriving. + acc, q = _mk(batch_size=10, flush_interval=30.0) + _put(q, "only") + batch, shutdown = acc.collect(q, Shutdown, timeout=0, stop=lambda: True) + assert [r.getMessage() for r in batch] == ["only"] + assert shutdown is False + + +def test_stop_does_not_split_a_flowing_batch() -> None: + # Live-smoke regression: close() sets the shutdown event while the worker + # is still draining a queue full of records. stop must only be consulted + # once a wait actually elapsed with nothing arriving, or every flowing + # record flushes as its own batch. stop=True here must not split the 5 + # queued records (batch_size is exactly 5, so they must come back whole). + acc, q = _mk(batch_size=5, flush_interval=10.0) + _put(q, "a", "b", "c", "d", "e") + batch, shutdown = acc.collect(q, Shutdown, timeout=0, stop=lambda: True) + assert [r.getMessage() for r in batch] == ["a", "b", "c", "d", "e"] + assert not shutdown + + +def test_stop_false_after_capped_wait_keeps_collecting() -> None: + # Stop present but still False when a capped wait elapses: the loop must + # keep going (re-check the interval) instead of aborting an active batch. + acc, q = _mk(batch_size=10, flush_interval=5.0, clock=ScriptedClock(0.0, 0.0, 0.0, 5.0)) + _put(q, "a", "b") + batch, shutdown = acc.collect(q, Shutdown, timeout=0, stop=lambda: False) + assert [r.getMessage() for r in batch] == ["a", "b"] + assert not shutdown diff --git a/tests/test_config_stats.py b/tests/test_config_stats.py index 2ea16ff..aabd59c 100644 --- a/tests/test_config_stats.py +++ b/tests/test_config_stats.py @@ -52,6 +52,14 @@ def test_trailing_newline_token_is_stripped(self) -> None: # must not fail validation or leak into the request URL. assert resolve_credentials("111:abc\n", 1) == ("111:abc", "1") + def test_env_chat_id_trailing_newline_is_stripped( + self, monkeypatch: pytest.MonkeyPatch + ) -> None: + # Same story for chats: .env files routinely end values with a + # newline, and an unstripped one would 400 at send time. + monkeypatch.setenv("TG_CHAT_ID", "-42\n") + assert resolve_credentials("111:abc", None)[1] == "-42" + def test_invalid_short_token_error_is_redacted(self) -> None: # A token too short for a safe partial reveal must not appear in the # error message at all. @@ -163,6 +171,73 @@ def get_nowait(self) -> object: raise queue.Empty return "evicted" + def task_done(self) -> None: + pass + + +class TestValidateToken: + def test_non_json_200_body_is_config_error(self, monkeypatch: pytest.MonkeyPatch) -> None: + # A proxy/gateway can answer 200 with an HTML error page; the docs + # promise TelegramConfigError, never a bare ValueError. + import httpx + + from tg_logging_handler.config import validate_token + + monkeypatch.setattr( + httpx, + "get", + lambda *args, **kwargs: httpx.Response(200, text="gateway error"), + ) + with pytest.raises(TelegramConfigError, match="non-JSON"): + validate_token("111:abc", "https://api.telegram.org") + + def test_network_error_is_config_error(self, monkeypatch: pytest.MonkeyPatch) -> None: + # An unreachable API (offline host, DNS failure) must surface as the + # documented TelegramConfigError, with the offline-escape hatch hint. + import httpx + + from tg_logging_handler.config import validate_token + + def offline(*args: object, **kwargs: object) -> httpx.Response: + raise httpx.ConnectError("offline") + + monkeypatch.setattr(httpx, "get", offline) + with pytest.raises(TelegramConfigError, match="Could not reach Telegram"): + validate_token("111:abc", "https://api.telegram.org") + + @pytest.mark.parametrize("payload", [[], "hello", 42]) + def test_non_object_json_200_body_is_config_error( + self, monkeypatch: pytest.MonkeyPatch, payload: object + ) -> None: + # A 200 that decodes as a scalar/list (never an object) cannot carry + # ok; it must hit the TelegramConfigError path, not an AttributeError. + import httpx + + from tg_logging_handler.config import validate_token + + monkeypatch.setattr( + httpx, + "get", + lambda *args, **kwargs: httpx.Response(200, json=payload), + ) + with pytest.raises(TelegramConfigError, match="rejected"): + validate_token("111:abc", "https://api.telegram.org") + + def test_truthy_but_not_true_ok_is_config_error(self, monkeypatch: pytest.MonkeyPatch) -> None: + # ok == 1 is truthy but not exactly True; only a boolean True means + # the token was accepted. + import httpx + + from tg_logging_handler.config import validate_token + + monkeypatch.setattr( + httpx, + "get", + lambda *args, **kwargs: httpx.Response(200, json={"ok": 1}), + ) + with pytest.raises(TelegramConfigError, match="rejected"): + validate_token("111:abc", "https://api.telegram.org") + class TestQueuePolicy: def test_put_drop_newest_succeeds_when_space(self) -> None: @@ -190,6 +265,16 @@ def test_put_drop_oldest_evicts_to_make_room(self) -> None: assert result.dropped == 1 # evicted the oldest (1) assert list(q.queue) == [2, 3] + def test_put_drop_oldest_task_dones_evicted_items(self) -> None: + # Every eviction is a get(); without a matching task_done(), + # queue.join() would hang forever on a full-and-drained queue. + q: queue.Queue[object] = queue.Queue(maxsize=2) + q.put_nowait(1) + q.put_nowait(2) + queue_policy.put_drop_oldest(q, 3) + # Only items still in the queue may lack a task_done(). + assert q.unfinished_tasks == q.qsize() == 2 + def test_put_drop_oldest_no_eviction_when_space(self) -> None: q: queue.Queue[object] = queue.Queue(maxsize=2) q.put_nowait(1) diff --git a/tests/test_handler.py b/tests/test_handler.py index bf5f9f5..679d8f4 100644 --- a/tests/test_handler.py +++ b/tests/test_handler.py @@ -3,9 +3,11 @@ from __future__ import annotations import logging +import queue import threading import time from collections.abc import Callable +from typing import Any, cast import httpx import pytest @@ -19,6 +21,7 @@ TGLoggingHandler, __all__, ) +from tg_logging_handler.queue_policy import PutResult HandlerFactory = Callable[..., TelegramLoggingHandler] WaitFor = Callable[..., bool] @@ -54,6 +57,23 @@ def test_invalid_token_format_raises() -> None: TelegramLoggingHandler(token="garbage", chat_id=1, validate=False) +def test_failed_construction_unregisters_from_handler_list( + monkeypatch: pytest.MonkeyPatch, +) -> None: + """A half-built handler must not stay registered for exit-time shutdown().""" + monkeypatch.delenv("TG_TOKEN", raising=False) + monkeypatch.delenv("TG_CHAT_ID", raising=False) + + def alive() -> int: + handler_list = cast(Any, logging)._handlerList + return sum(1 for ref in handler_list if isinstance(ref(), TelegramLoggingHandler)) + + before = alive() + with pytest.raises(TelegramConfigError): + TelegramLoggingHandler(validate=False) + assert alive() == before + + def test_env_fallback_constructs(monkeypatch: pytest.MonkeyPatch) -> None: monkeypatch.setenv("TG_TOKEN", TEST_TOKEN) monkeypatch.setenv("TG_CHAT_ID", TEST_CHAT_ID) @@ -248,3 +268,189 @@ def emit_batch(worker_id: int) -> None: assert wait_for(lambda: handler.stats.sent == 2000) stats = handler.stats assert stats.sent + stats.dropped + stats.failed == 2000 + + +def test_close_stops_worker_even_when_queue_was_saturated( + fast_handler_factory: HandlerFactory, mock_api: respx.MockRouter, wait_for: WaitFor +) -> None: + # Regression: with a saturated queue the SHUTDOWN put is suppressed and + # the worker must still terminate (event-backed shutdown); previously it + # leaked the thread and the httpx client forever. + handler = fast_handler_factory(queue_maxsize=1, flush_interval=5.0, shutdown_timeout=1.0) + handler.emit(_record("first")) + handler.emit(_record("second")) # fills the queue: sentinel put is suppressed + handler.close() + assert wait_for(lambda: not handler._worker.is_alive()) + + +def test_emit_after_close_drops_instead_of_blocking( + mock_api: respx.MockRouter, wait_for: WaitFor +) -> None: + # Regression: with queue_full_policy="block" a post-close emit on a full + # queue hung the calling thread forever (no worker drains it). Now it is + # dropped and counted. + handler = TelegramLoggingHandler( + token=TEST_TOKEN, + chat_id=TEST_CHAT_ID, + validate=False, + queue_maxsize=1, + queue_full_policy="block", + flush_interval=30.0, + shutdown_timeout=1.0, + api_base_url=API_BASE, + ) + handler.close() + assert wait_for(lambda: not handler._worker.is_alive()) + before = handler.stats.dropped + handler.emit(_record("post-close")) + assert handler.stats.dropped == before + 1 + + +def test_close_waits_for_in_flight_emit(mock_api: respx.MockRouter) -> None: + # Regression: close() once interleaved its _closed write between an emit's + # guard check and its enqueue, orphaning the record (counted queued but + # never sent; block policy: hung forever). The close lock serializes emit + # vs close: close() blocks until the in-flight emit has fully enqueued, + # so nothing accepted before close() is lost. + handler = TelegramLoggingHandler( + token=TEST_TOKEN, + chat_id=TEST_CHAT_ID, + validate=False, + queue_maxsize=2, + queue_full_policy="block", + flush_interval=5.0, + shutdown_timeout=2.0, + api_base_url=API_BASE, + ) + started = threading.Event() + release = threading.Event() + original = handler._put_policy + + def slow_policy(q: queue.Queue[object], item: object) -> PutResult: + result = original(q, item) + started.set() # emit is now inside the put (holding the close lock) + release.wait(timeout=5.0) + return result + + handler._put_policy = slow_policy + + def do_emit() -> None: + handler.emit(_record("z")) + + emitter = threading.Thread(target=do_emit) + emitter.start() + assert started.wait(timeout=2.0) + + outcome: dict[str, float] = {} + + def do_close() -> None: + t0 = time.monotonic() + handler.close() + outcome["elapsed"] = time.monotonic() - t0 + + closer = threading.Thread(target=do_close) + closer.start() + time.sleep(0.2) + assert "elapsed" not in outcome # close() must wait for the in-flight emit + release.set() + emitter.join(timeout=2.0) + closer.join(timeout=2.0) + assert outcome["elapsed"] < 1.0 # close finished promptly once the emit did + assert not handler._worker.is_alive() + stats = handler.stats + assert stats.queued == 1 + assert stats.sent == 1 # the in-flight record was drained, not orphaned + + +def test_emit_swallows_put_policy_exceptions( + fast_handler_factory: HandlerFactory, +) -> None: + # A policy that raises must never propagate out of emit (stdlib contract). + handler = fast_handler_factory() + + def broken_policy(q: queue.Queue[object], item: object) -> PutResult: + raise RuntimeError("policy exploded") + + handler._put_policy = broken_policy + handler.emit(_record("x")) # must not raise + handler.close() + + +def test_emit_racing_close_drops_instead_of_orphaning( + fast_handler_factory: HandlerFactory, +) -> None: + # An emit whose snapshot was already taken when close() completed must hit + # the authoritative closed check under the lock and drop+count instead of + # enqueueing into a drained pipeline (counted queued, never sent). + handler = fast_handler_factory() + release = threading.Event() + + class SlowStr: + def __str__(self) -> str: + release.wait(timeout=2.0) + return "boom" + + slow = SlowStr() + # getMessage() formats msg % args, invoking SlowStr.__str__ -> the emit + # pauses between the fast-path guard and the close-lock check. + slow_record = logging.LogRecord("t", logging.ERROR, __file__, 1, "%s", (slow,), None) + emitter = threading.Thread(target=handler.emit, args=(slow_record,)) + emitter.start() + time.sleep(0.1) # emit is now inside getMessage, before the lock + handler.close() # real close(): the emit is mid-flight past its snapshot + release.set() + emitter.join(timeout=2.0) + assert handler.stats.dropped == 1 # counted, not orphaned + handler.close() # idempotent no-op + + +def test_close_enqueues_sentinel_before_signaling_worker_shutdown( + fast_handler_factory: HandlerFactory, +) -> None: + # close() must put the SHUTDOWN sentinel before setting the shutdown event: + # the worker's exit check is "event set AND queue empty", so signaling + # first would let it return while the sentinel is still about to be + # enqueued, stranding it in a queue nobody drains (queue.join() hangs). + handler = fast_handler_factory() + order: list[str] = [] + + worker = handler._worker + orig_shutdown = worker.shutdown + + def spy_shutdown() -> None: + order.append("event") + orig_shutdown() + + worker.shutdown = spy_shutdown # type: ignore[method-assign] + + q = handler._queue + orig_put = q.put_nowait + + def spy_put(item: object) -> None: + order.append("sentinel") + orig_put(item) + + q.put_nowait = spy_put # type: ignore[method-assign] + + handler.close() + assert order == ["sentinel", "event"] # sentinel queued before the wakeup + + +def test_close_with_empty_queue_strands_nothing( + fast_handler_factory: HandlerFactory, +) -> None: + # With nothing queued, close() must still leave the queue joinable: the + # sentinel is either consumed by the worker or never enqueued after an + # exit, so queue.join() always completes. + handler = fast_handler_factory() + handler.close() + done = threading.Event() + + def join() -> None: + handler._queue.join() + done.set() + + joiner = threading.Thread(target=join) + joiner.start() + joiner.join(timeout=2.0) + assert done.is_set() # join() completed; no stranded sentinel diff --git a/tests/test_integration.py b/tests/test_integration.py index 6485920..36a0323 100644 --- a/tests/test_integration.py +++ b/tests/test_integration.py @@ -97,10 +97,12 @@ def test_burst_of_100_is_batched( logger.error("msg-%d", i) route = next(r for r in mock_api.routes if "sendMessage" in str(r.pattern)) assert wait_for(lambda: route.call_count == 10) + # Counters update right after the wire call, so wait for the final count + # instead of reading stats in the same instant as the 10th call. + assert wait_for(lambda: handler.stats.sent == 100) logger.handlers.clear() # Every record delivered, none lost, and each wire message carries 10 lines. - assert handler.stats.sent == 100 assert handler.stats.batches_sent == 10 assert all(text.count("\n") == 9 for text in _batch_texts(route)) diff --git a/tests/test_overflow.py b/tests/test_overflow.py index bd96fc3..3cd3551 100644 --- a/tests/test_overflow.py +++ b/tests/test_overflow.py @@ -10,7 +10,7 @@ import pytest from tg_logging_handler._constants import TELEGRAM_MAX_MESSAGE_LENGTH -from tg_logging_handler.overflow import prepare_messages, split_text, truncate_text +from tg_logging_handler.overflow import _safe_cut, prepare_messages, split_text, truncate_text def _strip_header(part: str) -> str: @@ -132,3 +132,51 @@ def test_truncate_escapes_its_marker_for_markdownv2() -> None: out = truncate_text("w" * 500, 100, parse_mode="MarkdownV2") assert out.endswith(escape("\n… [truncated]", "MarkdownV2")) assert len(out) <= 100 + + +def test_safe_cut_odd_backslash_run_backs_up_one() -> None: + # A cut right after a lone backslash would split the MarkdownV2 \X pair; + # the cut must move left by one so the pair moves whole to the next part. + assert _safe_cut("\\a", 1) == 0 + + +def test_safe_cut_even_backslash_run_keeps_cut() -> None: + # Two backslashes are a literal backslash (balanced); the cut is fine. + assert _safe_cut("\\a", 2) == 2 + + +def test_safe_cut_odd_run_respects_floor() -> None: + # Backing up would cross the floor (no forward progress): keep the cut. + # r"\a" is a backslash followed by "a" — a plain "\a" would be the bell + # character and never exercise the backslash run. + assert _safe_cut(r"\a", 1, floor=1) == 1 + + +def test_split_keeps_markdown_v2_escape_pairs_whole() -> None: + # A leading character shifts every escape pair to an odd offset, so hard + # cuts land inside a \_ pair; every pair must stay intact, parts + # reconstruct byte-for-byte, and no body may end mid-escape. + text = "x" + r"\_" * 200 + parts = split_text(text, 100, parse_mode="MarkdownV2") + bodies = [_strip_header(p) for p in parts] + assert "".join(bodies) == text + assert all(_trailing_backslashes(b) % 2 == 0 for b in bodies) + + +def test_truncate_with_tiny_limit_stays_within_limit() -> None: + # A limit smaller than the marker itself must still clamp the result to + # the cap; Telegram rejects oversized payloads with a 400. + assert truncate_text("x" * 100, 5) == "\n… [truncated]"[:5] + for limit in (0, 5, 20): + assert len(truncate_text("x" * 100, limit)) <= limit + assert len(truncate_text("x" * 100, 20, parse_mode="MarkdownV2")) <= 20 + + +@pytest.mark.parametrize("limit", [4, 15]) +def test_truncate_markdownv2_tiny_limits_never_dangle_an_escape(limit: int) -> None: + # Clamping the escaped marker mid-escape would leave a trailing backslash + # (a dangling MarkdownV2 \X pair 400s the send); the clamp must back off + # the odd backslash run, stay within the cap, and keep the text budget. + out = truncate_text("x" * 100, limit, parse_mode="MarkdownV2") + assert len(out) <= limit + assert _trailing_backslashes(out) % 2 == 0 # no dangling escape at the end diff --git a/tests/test_sender_retry.py b/tests/test_sender_retry.py index 120a412..f3fcb98 100644 --- a/tests/test_sender_retry.py +++ b/tests/test_sender_retry.py @@ -105,6 +105,7 @@ def test_429_honors_retry_after_without_consuming_budget() -> None: outcome = _sender(sleep, max_retries=1).send_with_retry("hi") assert outcome.delivered is True assert outcome.retries == 0 # 429s do not consume the retry budget + assert outcome.rate_limited == 2 # both Retry-After waits still counted assert sleep.calls == [7.0, 3.0] # slept exactly the Retry-After values @@ -197,6 +198,7 @@ def test_429_waits_are_capped_so_a_stuck_429_cannot_spin_forever() -> None: outcome = _sender(sleep).send_with_retry("hi") assert outcome.delivered is False # gave up after the cap assert outcome.retries == 0 # 429s never consume the retry budget + assert outcome.rate_limited == _MAX_RATE_LIMIT_WAITS # every wait counted assert len(sleep.calls) == _MAX_RATE_LIMIT_WAITS # slept exactly cap times assert sleep.calls == [1.0] * _MAX_RATE_LIMIT_WAITS @@ -354,3 +356,38 @@ def test_heads_up_notice_failure_is_swallowed() -> None: outcome = _sender(sleep).send_with_retry("real log line") assert outcome.delivered is True assert route.call_count == 3 # send, failed notice, successful resend + + +@respx.mock +def test_3xx_is_a_permanent_failure_not_success() -> None: + # Regression: a 3xx (e.g. a proxy redirect) used to fall through every + # branch and return delivered=True while nothing was sent. It must count + # as failed and consume no retries. + route = respx.post(SEND_URL).mock(return_value=httpx.Response(302)) + sleep = _RecordingSleep() + outcome = _sender(sleep).send_with_retry("hi") + assert outcome.delivered is False + assert outcome.retries == 0 + assert route.call_count == 1 + assert sleep.calls == [] + + +@respx.mock +def test_redirect_with_location_is_never_followed() -> None: + # Redirects are disabled on the client: a 302 carrying a Location must + # surface as-is and fail — the redirect target must never receive the + # sendMessage POST, and its (hypothetical 200) response must never be + # mistaken for a delivery. + redirect_target = respx.get("https://evil.example/hijack").mock( + return_value=httpx.Response(200, json={"ok": True, "result": {"message_id": 9}}) + ) + route = respx.post(SEND_URL).mock( + return_value=httpx.Response(302, headers={"location": "https://evil.example/hijack"}) + ) + sleep = _RecordingSleep() + outcome = _sender(sleep).send_with_retry("hi") + assert outcome.delivered is False + assert outcome.retries == 0 + assert route.call_count == 1 # one POST, never re-issued against the target + assert redirect_target.call_count == 0 # the Location was never fetched + assert sleep.calls == [] diff --git a/tests/test_smoke.py b/tests/test_smoke.py index e29e682..f358916 100644 --- a/tests/test_smoke.py +++ b/tests/test_smoke.py @@ -16,6 +16,8 @@ import logging import os +import time +from collections.abc import Callable from typing import Any import pytest @@ -167,6 +169,31 @@ def _live_handler(**kwargs: Any) -> TelegramLoggingHandler: return TelegramLoggingHandler(**kwargs) +def _wait_for_stats( + handler: TelegramLoggingHandler, + predicate: Callable[[HandlerStats], bool], + timeout: float = 30.0, +) -> HandlerStats: + """Poll ``handler.stats`` until ``predicate`` holds; fail on timeout. + + ``close()`` returns after ``shutdown_timeout`` even when the worker is + still mid-send (a daemon thread finishing its last batches in the + background), so a stats snapshot taken right after close can be + mid-flight. Live tests must not race the worker: poll until the expected + counters converge, then assert. If the deadline passes without the + predicate becoming true, raise instead of returning stale stats so a + test can never pass vacuously on a timeout. + """ + deadline = time.monotonic() + timeout + while True: + stats = handler.stats + if predicate(stats): + return stats + if time.monotonic() >= deadline: + raise TimeoutError(f"stats did not converge within {timeout}s: {stats}") + time.sleep(0.05) + + @requires_live def test_live_validate_and_deliver_batched_logs() -> None: # validate=True does a real getMe at construction; then a batch of records @@ -187,9 +214,9 @@ def test_live_validate_and_deliver_batched_logs() -> None: logger.removeHandler(handler) handler.close() # drains + joins the worker, so all sends complete - stats = handler.stats + stats = _wait_for_stats(handler, lambda s: s.sent == 6) assert stats.queued >= 6 - assert stats.sent >= 1 + assert stats.sent == 6 assert stats.failed == 0 @@ -204,11 +231,12 @@ def test_live_parse_mode_escaping_is_accepted(parse_mode: str) -> None: logger.propagate = False logger.addHandler(handler) try: - logger.warning("specials _ * [ ] ( ) ~ ` > # + - = | { } . ! < & > %s", "x") + logger.warning("specials _ * [ ] ( ) ~ ` > # + - = | { } . ! < > & %s", "x") finally: logger.removeHandler(handler) handler.close() - assert handler.stats.failed == 0 + stats = _wait_for_stats(handler, lambda s: s.sent >= 1) + assert stats.failed == 0 @requires_live @@ -225,5 +253,32 @@ def test_live_split_overflow_delivers_oversized_message() -> None: finally: logger.removeHandler(handler) handler.close() - assert handler.stats.sent >= 1 - assert handler.stats.failed == 0 + stats = _wait_for_stats(handler, lambda s: s.sent >= 1) + assert stats.sent >= 1 + assert stats.failed == 0 + + +@requires_live +def test_live_batch_size_groups_records_5_and_5() -> None: + # 10 real error records (each with a traceback) with batch_size=5 must go + # out as exactly 2 messages (5+5), never as singles or one 10-record + # message: sent counts records, batches_sent counts messages. + handler = _live_handler(batch_size=5, flush_interval=0.5, validate=False) + logger = logging.getLogger("tg-smoke.live.batch-size") + logger.setLevel(logging.ERROR) + logger.propagate = False + logger.addHandler(handler) + try: + for i in range(10): + try: + raise ValueError(f"intentional smoke error {i + 1}/10") + except ValueError: + logger.exception("live smoke batch error %d/10", i + 1) + finally: + logger.removeHandler(handler) + handler.close() + stats = _wait_for_stats(handler, lambda s: s.sent == 10) + assert stats.queued == 10 + assert stats.sent == 10 + assert stats.batches_sent == 2 + assert stats.failed == 0 diff --git a/tests/test_worker.py b/tests/test_worker.py index 4f52824..5f9b56c 100644 --- a/tests/test_worker.py +++ b/tests/test_worker.py @@ -110,3 +110,84 @@ def test_worker_stops_after_flushing_partial_batch_on_shutdown() -> None: assert not worker.is_alive() assert sender.sent == ["one"] assert stats.snapshot().sent == 1 + + +def test_worker_stops_when_sentinel_is_lost_to_full_queue() -> None: + # Regression: with a saturated queue the handler's sentinel put is + # suppressed, and drop_oldest can even evict it. The shutdown event alone + # must still stop the worker after everything queued is drained. + q: queue.Queue[object] = queue.Queue(maxsize=1) + q.put_nowait(_record("only")) + sender = _FakeSender() + stats = StatsCollector() + worker = WorkerThread( + q, + cast(TelegramSender, sender), + stats, + lambda r: r.getMessage(), + batch_size=1, + flush_interval=0.01, + ) + worker.start() + worker.shutdown() # no sentinel involved: the event must be enough + worker.join(timeout=3.0) + assert not worker.is_alive() + assert sender.sent == ["only"] # drained before exit + + +def test_shutdown_event_interrupts_long_interval_wait() -> None: + # Regression: with a partial batch pending inside a long flush_interval, + # shutdown used to wait the whole interval out (the mid-batch get only + # saw the sentinel, which a saturated queue can lose). The event is now + # polled mid-batch, so the worker exits promptly and still flushes the + # pending record. + q: queue.Queue[object] = queue.Queue() + q.put_nowait(_record("pending")) + sender = _FakeSender() + stats = StatsCollector() + worker = WorkerThread( + q, + cast(TelegramSender, sender), + stats, + lambda r: r.getMessage(), + batch_size=10, # one record never fills the batch + flush_interval=60.0, # the long wait shutdown must cut short + ) + worker.start() + worker.shutdown() # event only; no sentinel on the queue at all + worker.join(timeout=3.0) + assert not worker.is_alive() + assert sender.sent == ["pending"] # partial batch flushed before exit + + +def test_worker_counts_rate_limited_waits_in_stats() -> None: + class _RateLimitedSender(_FakeSender): + def send_with_retry(self, text: str) -> SendOutcome: + self.sent.append(text) + # 429s never consume the retry budget, but every wait must count. + return SendOutcome(delivered=True, retries=0, rate_limited=3) + + stats = _run_worker(_RateLimitedSender(), lambda r: r.getMessage(), [_record("x")]) + assert stats.snapshot().rate_limited == 3 + + +def test_sentinel_consumption_has_matching_task_done() -> None: + # Regression: the sentinel is consumed with a get() but never got a + # task_done(), so unfinished_tasks stayed > 0 forever and any + # queue.join() would hang. + q: queue.Queue[object] = queue.Queue() + stats = StatsCollector() + worker = WorkerThread( + q, + cast(TelegramSender, _FakeSender()), + stats, + lambda r: r.getMessage(), + batch_size=1, + flush_interval=0.01, + ) + worker.start() + q.put(_record("x")) + q.put(SHUTDOWN) + worker.join(timeout=3.0) + assert not worker.is_alive() + assert q.unfinished_tasks == 0 diff --git a/tg_logging_handler/batching.py b/tg_logging_handler/batching.py index 06395f1..cc51171 100644 --- a/tg_logging_handler/batching.py +++ b/tg_logging_handler/batching.py @@ -20,6 +20,13 @@ __all__ = ["BatchAccumulator"] +# Longest single wait inside a partial batch. Waiting beyond this (a long +# ``flush_interval``) would keep the worker blind to shutdown for the whole +# interval; the loop re-checks ``stop`` after every capped wait, so shutdown +# latency stays bounded to roughly this value even when the SHUTDOWN sentinel +# is lost to a saturated queue or drop_oldest eviction. +_MAX_RECORD_WAIT = 1.0 + class BatchAccumulator: """Collect queued records into batches flushed by size or elapsed time. @@ -51,6 +58,7 @@ def collect( record_queue: queue.Queue[object], shutdown_sentinel: object, timeout: float | None = None, + stop: Callable[[], bool] | None = None, ) -> tuple[list[LogRecord], bool]: """Drain up to one batch from ``record_queue``. @@ -58,6 +66,14 @@ def collect( batch is empty. Returns ``([], False)`` if nothing arrived and no partial batch was pending. + ``stop``, when given, is polled after a capped wait that elapsed with + nothing arriving; a ``True`` return flushes the partial batch + immediately so the caller can honour a shutdown request without + waiting out a long ``flush_interval``. Records that keep flowing are + never split by ``stop``: once shutdown is requested the caller still + wants everything already accepted drained, and a batch still growing + would otherwise flush per record. + ``batch`` and ``batch_started`` are locals, not instance state: each call drains whatever has arrived and returns it, so a batch never spans two calls. (The flush timer starts on the first record and is @@ -72,6 +88,7 @@ def collect( return [], False if item is shutdown_sentinel: shutdown = True + record_queue.task_done() # the sentinel was consumed like any item else: assert isinstance(item, LogRecord) # only LogRecords are enqueued batch.append(item) @@ -83,11 +100,20 @@ def collect( if remaining <= 0: break # interval elapsed → flush partial batch try: - item = record_queue.get(timeout=remaining) + item = record_queue.get(timeout=min(remaining, _MAX_RECORD_WAIT)) except queue.Empty: + if min(remaining, _MAX_RECORD_WAIT) < remaining: + if stop is not None and stop(): + # A long capped wait elapsed with nothing arriving and a + # shutdown is pending: flush now. Never checked between + # arriving records — a flowing batch must keep growing. + break + continue # capped wait elapsed; re-check the interval break # nothing more arrived within the interval → flush partial if item is shutdown_sentinel: shutdown = True + # consumed item; batch records are task_done'd by the caller + record_queue.task_done() break assert isinstance(item, LogRecord) batch.append(item) diff --git a/tg_logging_handler/config.py b/tg_logging_handler/config.py index bd06b5c..7eb3297 100644 --- a/tg_logging_handler/config.py +++ b/tg_logging_handler/config.py @@ -43,12 +43,14 @@ def resolve_credentials( raise TelegramConfigError(_invalid_token_message(token)) resolved_chat = chat_id if chat_id is not None else os.environ.get("TG_CHAT_ID") - if resolved_chat is None or resolved_chat == "": + if resolved_chat is not None: + resolved_chat = str(resolved_chat).strip() + if not resolved_chat: raise TelegramConfigError( "No chat_id provided. Pass chat_id=... or set the TG_CHAT_ID environment variable." ) - return token, str(resolved_chat) + return token, resolved_chat def resolve_topic_id(topic_id: int | None) -> int | None: @@ -120,7 +122,20 @@ def validate_token(token: str, api_base_url: str) -> None: "Pass validate=False to skip this check in offline environments." ) from exc - if response.status_code != 200 or not response.json().get("ok", False): + try: + body = response.json() + except ValueError as exc: + # A proxy/gateway error page behind a 200 must not surface as a bare + # ValueError; the user is promised TelegramConfigError. + raise TelegramConfigError( + f"Telegram returned a non-JSON response (HTTP {response.status_code}). " + "Check that the bot token is correct." + ) from exc + + # The body must be an object with ok == True exactly: a scalar/list body + # or a merely truthy ok (1, "true") means the token was not accepted. + body_ok = isinstance(body, dict) and body.get("ok") is True + if response.status_code != 200 or not body_ok: raise TelegramConfigError( f"Telegram rejected the token (getMe returned HTTP {response.status_code}). " "Check that the bot token is correct." diff --git a/tg_logging_handler/handler.py b/tg_logging_handler/handler.py index b41dc9f..112d5a0 100644 --- a/tg_logging_handler/handler.py +++ b/tg_logging_handler/handler.py @@ -11,7 +11,8 @@ import copy import logging import queue -from typing import Literal +import threading +from typing import Any, Literal, cast from . import queue_policy from .config import resolve_credentials, resolve_topic_id, validate_token @@ -70,64 +71,102 @@ def __init__( ) -> None: super().__init__(level=level) - if batch_size < 1: - raise ValueError("batch_size must be >= 1") - if flush_interval < 0: - raise ValueError("flush_interval must be >= 0") - if max_retries < 0: - raise ValueError("max_retries must be >= 0") - if queue_maxsize < 0: - raise ValueError("queue_maxsize must be >= 0") - - resolved_token, resolved_chat = resolve_credentials(token, chat_id) - resolved_topic = resolve_topic_id(topic_id) - if validate: - validate_token(resolved_token, api_base_url) - - # Full signature is live: batching + retry/backoff/429, overflow + - # queue policies + full stats, parse_mode escaping. The worker - # escapes each record for parse_mode; the sender forwards parse_mode to - # sendMessage so Telegram renders the (now-safe) entities. - self._shutdown_timeout = shutdown_timeout - self._closed = False - self._stats = StatsCollector() - self._queue: queue.Queue[object] = queue.Queue(maxsize=queue_maxsize) - # Validate the policy name now so a typo fails fast at construction, not - # silently at the first queue overflow. - self._put_policy = queue_policy.select_put_policy(queue_full_policy) - self._sender = TelegramSender( - resolved_token, - resolved_chat, - api_base_url, - parse_mode=parse_mode, - max_retries=max_retries, - message_thread_id=resolved_topic, - ) - self._worker = WorkerThread( - record_queue=self._queue, - sender=self._sender, - stats=self._stats, - format_record=self.format, - batch_size=batch_size, - flush_interval=flush_interval, - overflow=overflow, - parse_mode=parse_mode, - ) - self._worker.start() - atexit.register(self.close) + try: + if batch_size < 1: + raise ValueError("batch_size must be >= 1") + if flush_interval < 0: + raise ValueError("flush_interval must be >= 0") + if max_retries < 0: + raise ValueError("max_retries must be >= 0") + if queue_maxsize < 0: + raise ValueError("queue_maxsize must be >= 0") + + resolved_token, resolved_chat = resolve_credentials(token, chat_id) + resolved_topic = resolve_topic_id(topic_id) + if validate: + validate_token(resolved_token, api_base_url) + + # Full signature is live: batching + retry/backoff/429, overflow + + # queue policies + full stats, parse_mode escaping. The worker + # escapes each record for parse_mode; the sender forwards parse_mode + # to sendMessage so Telegram renders the (now-safe) entities. + self._shutdown_timeout = shutdown_timeout + self._closed = False + # Guards the _closed flag against emit(), which checks it and then + # enqueues: close() must not interleave its write between the + # check and the put, or an in-flight emit would feed a queue no + # one drains (block policy: hang forever; otherwise: a record + # counted queued but never sent). The worker never takes this + # lock, so close() cannot deadlock against the drain. + self._close_lock = threading.Lock() + self._stats = StatsCollector() + self._queue: queue.Queue[object] = queue.Queue(maxsize=queue_maxsize) + # Validate the policy name now so a typo fails fast at construction, + # not silently at the first queue overflow. + self._put_policy = queue_policy.select_put_policy(queue_full_policy) + self._sender = TelegramSender( + resolved_token, + resolved_chat, + api_base_url, + parse_mode=parse_mode, + max_retries=max_retries, + message_thread_id=resolved_topic, + ) + self._worker = WorkerThread( + record_queue=self._queue, + sender=self._sender, + stats=self._stats, + format_record=self.format, + batch_size=batch_size, + flush_interval=flush_interval, + overflow=overflow, + parse_mode=parse_mode, + ) + self._worker.start() + atexit.register(self.close) + except Exception: + # super().__init__ just registered a weakref to this half-built + # instance in logging._handlerList; exit-time logging.shutdown() + # would call close() on it and print a stray AttributeError after + # the real construction error. Drop the weakref, then re-raise. + # The cleanup itself may also fail (e.g. logging internals torn + # down at interpreter shutdown); that must never mask the real + # construction error, so swallow any failure here. + with contextlib.suppress(Exception): + handler_list = cast(Any, logging)._handlerList + with cast(Any, logging)._lock: + handler_list[:] = [ref for ref in handler_list if ref() is not self] + raise def emit(self, record: logging.LogRecord) -> None: """Snapshot ``record`` and enqueue it. Never raises (stdlib contract).""" + if self._closed: + # Fast path; the authoritative check below is under the lock. + self._stats.increment("dropped") + return try: item = self._snapshot(record) - result = self._put_policy(self._queue, item) - # drop_oldest can lose an older record even while enqueueing the new - # one, so count both outcomes from the PutResult. - if result.enqueued: - self._stats.increment("queued") - self._stats.increment("dropped", result.dropped) except Exception: # emit must never propagate self.handleError(record) + return + with self._close_lock: + if self._closed: + # close() interleaved between snapshot and put: no worker + # drains this queue any more, so drop and count instead of + # enqueueing into a dead pipeline (block policy would hang + # this thread forever). + self._stats.increment("dropped") + return + try: + result = self._put_policy(self._queue, item) + except Exception: # emit must never propagate + self.handleError(record) + return + # drop_oldest can lose an older record even while enqueueing the new + # one, so count both outcomes from the PutResult. + if result.enqueued: + self._stats.increment("queued") + self._stats.increment("dropped", result.dropped) @staticmethod def _snapshot(record: logging.LogRecord) -> logging.LogRecord: @@ -150,13 +189,22 @@ def stats(self) -> HandlerStats: def close(self) -> None: """Drain the queue, stop the worker, release the client. Idempotent.""" - if self._closed: - return - self._closed = True - # Queue saturated -> worker still stops via its own drain; worst case we - # wait out shutdown_timeout below. ponytail: rare edge, not worth more. - with contextlib.suppress(queue.Full): - self._queue.put_nowait(SHUTDOWN) + with self._close_lock: + if self._closed: + return + self._closed = True + # Signal stop twice: the event is authoritative (the sentinel below + # is only a wakeup and can be lost to a saturated queue or + # drop_oldest eviction); the worker drains everything queued first, + # then exits. The sentinel goes in BEFORE the event: the worker's + # exit check is "event set AND queue empty", so signaling first + # would let it exit while the sentinel is still about to be + # enqueued, stranding it in a queue nobody drains (queue.join() + # would hang forever). The join below runs outside the lock so an + # emit blocked on a full queue (block policy) can finish draining. + with contextlib.suppress(queue.Full): + self._queue.put_nowait(SHUTDOWN) + self._worker.shutdown() self._worker.join(timeout=self._shutdown_timeout) atexit.unregister(self.close) super().close() diff --git a/tg_logging_handler/overflow.py b/tg_logging_handler/overflow.py index 89a1da0..9dbd086 100644 --- a/tg_logging_handler/overflow.py +++ b/tg_logging_handler/overflow.py @@ -77,6 +77,13 @@ def truncate_text(text: str, max_length: int, parse_mode: str | None = None) -> if len(text) <= max_length: return text marker = escape(_TRUNCATION_MARKER, parse_mode) + # A pathological max_length smaller than the marker itself must still + # yield a result within the cap (Telegram would 400 an oversized body); + # clamp the marker, then keep the remainder of the budget for text. The + # clamped marker is nudged off a trailing backslash so a MarkdownV2 \X + # pair is never split (a dangling backslash 400s the send). + marker = marker[:max_length] + marker = marker[: _safe_cut(marker, len(marker))] keep = _safe_cut(text, max(max_length - len(marker), 0)) return text[:keep] + marker diff --git a/tg_logging_handler/queue_policy.py b/tg_logging_handler/queue_policy.py index e157ccb..2488a01 100644 --- a/tg_logging_handler/queue_policy.py +++ b/tg_logging_handler/queue_policy.py @@ -76,6 +76,7 @@ def put_drop_oldest(q: queue.Queue[object], item: object) -> PutResult: q.get_nowait() except queue.Empty: continue # someone drained it; retry the put + q.task_done() # every get must be matched or queue.join() would hang dropped += 1 if _try_put(q, item): return PutResult(enqueued=True, dropped=dropped) diff --git a/tg_logging_handler/sender.py b/tg_logging_handler/sender.py index 5c48b5d..404d963 100644 --- a/tg_logging_handler/sender.py +++ b/tg_logging_handler/sender.py @@ -38,10 +38,15 @@ class SendOutcome: exhausted, after a permanent failure, or after too many consecutive 429 waits even when the retry budget remains; the worker counts it as ``failed`` so ``sent`` stays accurate. + + ``retries`` counts transient backoff retries (429s never consume the retry + budget); ``rate_limited`` counts the 429 ``Retry-After`` waits so a + rate-limit storm stays visible in the stats even at zero retries. """ delivered: bool retries: int + rate_limited: int = 0 class TelegramSender: @@ -78,6 +83,8 @@ def _get_client(self) -> httpx.Client: """Return the worker-thread-local client, creating it on first use.""" if self._client is None: timeout = httpx.Timeout(DEFAULT_READ_TIMEOUT, connect=DEFAULT_CONNECT_TIMEOUT) + # Redirects stay disabled (httpx default): a 302/308 with a + # Location must surface as-is and fail, never be followed. self._client = httpx.Client(timeout=timeout) return self._client @@ -96,11 +103,14 @@ def send_with_retry(self, text: str) -> SendOutcome: """ attempts = 0 rate_limited = 0 + rate_limited_waits = 0 delay = _BASE_DELAY_SECONDS while True: try: self._send_once(text) - return SendOutcome(delivered=True, retries=attempts) + return SendOutcome( + delivered=True, retries=attempts, rate_limited=rate_limited_waits + ) except TelegramSendError as exc: if exc.retry_after is not None: # 429 rate limit: honor Retry-After without consuming the @@ -115,15 +125,22 @@ def send_with_retry(self, text: str) -> SendOutcome: self._notified_rate_limit = True self._notify_rate_limited() if rate_limited >= _MAX_RATE_LIMIT_WAITS: - return SendOutcome(delivered=False, retries=attempts) + return SendOutcome( + delivered=False, + retries=attempts, + rate_limited=rate_limited_waits, + ) rate_limited += 1 + rate_limited_waits += 1 # Clamp the server's Retry-After to [0, _MAX_DELAY_SECONDS] # so one huge (or negative) header value can't stall the # worker for hours or crash time.sleep. self._sleep(min(max(exc.retry_after, 0.0), _MAX_DELAY_SECONDS)) continue if not exc.retryable or attempts >= self._max_retries: - return SendOutcome(delivered=False, retries=attempts) + return SendOutcome( + delivered=False, retries=attempts, rate_limited=rate_limited_waits + ) attempts += 1 rate_limited = 0 # a non-429 retry breaks the consecutive-429 run jittered = delay * (1.0 + _JITTER_FRACTION * (2.0 * random.random() - 1.0)) @@ -148,7 +165,10 @@ def _notify_rate_limited(self) -> None: payload["message_thread_id"] = self._message_thread_id try: self._get_client().post(self._url, json=payload) - except httpx.HTTPError as exc: + except Exception as exc: + # Broad by design: any failure in the notice path is noise + # (serialization, transport, the very rate limit we report); it + # must never surface through send_with_retry or fail a batch. _diagnostics.report(f"could not send 429 heads-up notification: {exc}") def _send_once(self, text: str) -> None: @@ -194,6 +214,13 @@ def _send_once(self, text: str) -> None: raise TelegramSendError( f"server error {response.status_code}: {response.text}", retryable=True ) + if response.status_code != 200: + # Anything else — a 3xx (redirects are never followed), or a + # non-200 2xx — means nothing was delivered; never report success. + raise TelegramSendError( + f"unexpected status {response.status_code}: {response.text}", + retryable=False, + ) def close(self) -> None: """Close the underlying client. Safe to call when never opened.""" diff --git a/tg_logging_handler/stats.py b/tg_logging_handler/stats.py index 5b99a7c..99096c1 100644 --- a/tg_logging_handler/stats.py +++ b/tg_logging_handler/stats.py @@ -20,6 +20,7 @@ class HandlerStats: sent: int = 0 batches_sent: int = 0 retries: int = 0 + rate_limited: int = 0 failed: int = 0 dropped: int = 0 diff --git a/tg_logging_handler/worker.py b/tg_logging_handler/worker.py index ee311f8..19e14fb 100644 --- a/tg_logging_handler/worker.py +++ b/tg_logging_handler/worker.py @@ -52,11 +52,19 @@ def __init__( self._sender = sender self._stats = stats self._format_record = format_record + # Authoritative stop signal: close() sets it. The SHUTDOWN sentinel is + # only a wakeup hint and can be lost (suppressed put on a saturated + # queue, drop_oldest eviction), so the loop must not rely on it alone. + self._shutdown_event = threading.Event() # batch_size==1 (default) makes the accumulator flush every record. self._accumulator = BatchAccumulator(batch_size=batch_size, flush_interval=flush_interval) self._overflow = overflow self._parse_mode = parse_mode + def shutdown(self) -> None: + """Request a stop after everything currently queued has been drained.""" + self._shutdown_event.set() + def run(self) -> None: try: self._loop() @@ -67,8 +75,8 @@ def _loop(self) -> None: """Run the drain/send cycle until shutdown. Failed-count accounting is deliberate: - - an exception while processing a batch increments ``failed`` once - (the batch, not each record in it); + - an exception while processing a batch increments ``failed`` by + ``len(batch)`` (every record in that batch never reached the wire); - a partial or failed send — ``SendOutcome(delivered=False)`` from retries exhausted, a permanent failure, or too many consecutive 429 waits (``_MAX_RATE_LIMIT_WAITS``) even when the retry budget @@ -80,18 +88,28 @@ def _loop(self) -> None: delivered split still flags the batch). """ while True: + if self._shutdown_event.is_set() and self._queue.empty(): + # The sentinel can be lost (suppressed put on a saturated + # queue, drop_oldest eviction); the event is the reliable stop + # signal. Everything queued before shutdown is drained first. + return # Empty batch -> block up to 1s waiting for a record (a quiet # handler must not busy-poll); partial batch -> collect until size - # or interval, whichever comes first. Shutdown flushes any - # partial batch first, then stops. - batch, shutdown = self._accumulator.collect(self._queue, SHUTDOWN, timeout=1.0) + # or interval, whichever comes first. The accumulator polls the + # shutdown event between its capped waits, so a shutdown is + # honoured within ~1s even when a long flush_interval has a + # partial batch pending and the sentinel was lost. Every batch is + # flushed first; nothing already accepted is dropped. + batch, shutdown = self._accumulator.collect( + self._queue, SHUTDOWN, timeout=1.0, stop=self._shutdown_event.is_set + ) if batch: try: self._process_batch(batch) except Exception as exc: # broad by design, see comment below # A single bad record (format error) must never take the # worker thread down. - self._stats.increment("failed") + self._stats.increment("failed", len(batch)) _diagnostics.report(f"failed to send batch: {exc}") finally: for _ in batch: @@ -141,6 +159,9 @@ def _process_batch(self, batch: list[LogRecord]) -> None: for message in messages: outcome = self._sender.send_with_retry(message) self._stats.increment("retries", outcome.retries) + # 429 Retry-After waits count separately: they never consume the + # retry budget, but a rate-limit storm must still be visible. + self._stats.increment("rate_limited", outcome.rate_limited) delivered_all = delivered_all and outcome.delivered if delivered_all: diff --git a/uv.lock b/uv.lock index 88c45fc..4275428 100644 --- a/uv.lock +++ b/uv.lock @@ -512,7 +512,7 @@ wheels = [ [[package]] name = "tg-logging-handler" -version = "0.1.3" +version = "0.1.4" source = { editable = "." } dependencies = [ { name = "httpx" },