From 7b5c3b1c3cfd56d87f06a35fa480f72923281e0a Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 16 Oct 2026 22:18:39 +0000 Subject: [PATCH] fix: ask the head poll for 100 comments and log only long empty streaks Co-Authored-By: Toldry Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_019ddUNNyEKK7YQuAyfKfGwi --- AGENTS.md | 7 ++-- .../+quieter-empty-head-polls.changed.md | 6 ++++ src/racb/comment_reader.py | 22 +++++++++---- src/racb/main.py | 10 ++++-- tests/unit/test_comment_reader.py | 33 +++++++++++++++++++ tests/unit/test_main.py | 12 +++++++ 6 files changed, 79 insertions(+), 11 deletions(-) create mode 100644 changelog.d/+quieter-empty-head-polls.changed.md diff --git a/AGENTS.md b/AGENTS.md index 7298426..c7e69c5 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -121,8 +121,9 @@ A banned target (a 404 whose body says `"reason": "banned"`, `SUBREDDIT_IS_BANNE `STREAM_READERS` threads, keeping only what r/all could show (`is_shown_on_r_all`: not private or on a user profile). `/api/info` comments have no `over_18` or `quarantine` field, so Phase 1 drops NSFW and quarantined ones by their submission (`phase1.is_hidden_from_r_all`, no extra request). The head poll - asks the listing for 25 comments and takes the newest, because `limit=1` sometimes returns none. An empty - listing anyway only skips that poll (one WARNING per streak); the next poll catches up. Subreddits that opted out of r/all cannot be told apart, so their comments + asks the listing for 100 comments and takes the newest, because smaller limits often return none. An empty + listing anyway only skips that poll and is counted in the heartbeat (`head: N polls (M empty)`); the next + poll catches up. Only `EMPTY_HEAD_POLLS_BEFORE_WARNING` (6) empty polls in a row log a WARNING. Subreddits that opted out of r/all cannot be told apart, so their comments are read too. `STREAM_SOURCE=listing` instead reads `reddit.subreddit('all').stream.comments(skip_existing=True, pause_after=-1)` one request at a time, which sees only a fraction of r/all (section 9). @@ -466,6 +467,8 @@ uv run pytest -m integration - `reads`: ID blocks (or listing batches) fetched, and how many comments each returned (all of them, before the r/all filter). With `STREAM_SOURCE=listing`, about 100 comments/request means the listing returned full pages, so the bot was falling behind r/all. + - `head`: polls for the newest comment ID, and how many of them got an empty r/all listing. Empty polls + cost nothing but a few seconds of delay; only a long streak, which also logs a WARNING, stops new reads. - `behind`: age of the newest comment read, and (`ids` only) how many IDs wait to be read. Growing values mean the readers do not keep up; `N ID block(s) failed` and `N IDs skipped` count comments given up on. diff --git a/changelog.d/+quieter-empty-head-polls.changed.md b/changelog.d/+quieter-empty-head-polls.changed.md new file mode 100644 index 0000000..5491231 --- /dev/null +++ b/changelog.d/+quieter-empty-head-polls.changed.md @@ -0,0 +1,6 @@ +**Empty r/all head polls no longer flood the log.** Reddit returned an empty r/all comment listing on about +every other head poll after 3.1.1 was deployed, and each streak logged a WARNING and an INFO line, roughly +every 30 seconds. The head poll now asks for 100 comments instead of 25, which should make empty listings +rarer. Empty polls are counted in the heartbeat (`head: N polls (M empty)`), and a WARNING is logged only +after 6 empty polls in a row, since only a streak that long noticeably delays reading. No comments are lost +either way: the next successful poll queues every block up to the newest comment. diff --git a/src/racb/comment_reader.py b/src/racb/comment_reader.py index e7c1c21..38e58df 100644 --- a/src/racb/comment_reader.py +++ b/src/racb/comment_reader.py @@ -39,8 +39,13 @@ BLOCK_SIZE = 100 # Comments the head poll asks for. Reddit filters the r/all listing after applying the limit, so asking for -# one comment sometimes returns none (seen live on 2026-10-16); the newest of a few is the head -HEAD_LISTING_LIMIT = 25 +# one comment sometimes returns none (seen live on 2026-10-16); the newest of a few is the head. Even 25 came +# back empty on about every other poll on 2026-10-16, so ask for the most one request can return +HEAD_LISTING_LIMIT = 100 + +# Empty head polls in a row before a WARNING is logged. A few are normal and cost nothing (the next poll +# catches up), so they are only counted in the heartbeat; a long streak means no new comments are being queued +EMPTY_HEAD_POLLS_BEFORE_WARNING = 6 # Seconds to wait between two head polls (each poll itself takes a few seconds). It only sets how soon a new # comment is read, not how many: every block up to the head is queued at once. Fewer polls, fewer requests. @@ -180,16 +185,19 @@ def poll_head(self): started = time.monotonic() head = self.fetch_head() if self.metrics: - self.metrics.record_head_poll(time.monotonic() - started) + self.metrics.record_head_poll(time.monotonic() - started, empty=head is None) if head is None: # Nothing is lost: the next poll queues every block up to the head it finds self.empty_head_polls += 1 - if self.empty_head_polls == 1: - logger.warning('The r/all comment listing returned no comments; trying again at the next poll') + if self.empty_head_polls == EMPTY_HEAD_POLLS_BEFORE_WARNING: + logger.warning( + f'The r/all comment listing returned no comments {self.empty_head_polls} polls in a row; ' + 'no new comments are queued until it does' + ) return - if self.empty_head_polls: + if self.empty_head_polls >= EMPTY_HEAD_POLLS_BEFORE_WARNING: logger.info(f'The r/all comment listing has comments again after {self.empty_head_polls} empty poll(s)') - self.empty_head_polls = 0 + self.empty_head_polls = 0 with self._lock: if self.next_id is None: self._choose_start(head) diff --git a/src/racb/main.py b/src/racb/main.py index 0813e4d..6aa3e68 100644 --- a/src/racb/main.py +++ b/src/racb/main.py @@ -61,6 +61,7 @@ def __init__(self): self.interval_request_seconds = 0.0 self.interval_head_polls = 0 self.interval_head_seconds = 0.0 + self.interval_empty_head_polls = 0 self.interval_failed_blocks = 0 self.interval_skipped_ids = 0 # Creation time of the newest comment read so far, and how many IDs wait to be read @@ -95,10 +96,13 @@ def record_request(self, seconds, comments_returned): self.interval_request_seconds += seconds self.interval_request_comments += comments_returned - def record_head_poll(self, seconds): + def record_head_poll(self, seconds, empty=False): + """Counts one head poll; `empty` if the r/all listing returned no comments.""" with self._lock: self.interval_head_polls += 1 self.interval_head_seconds += seconds + if empty: + self.interval_empty_head_polls += 1 def record_failed_block(self): """Counts a block of comment IDs given up on after repeated errors.""" @@ -140,6 +144,7 @@ def log_heartbeat(self): self.interval_request_seconds = 0.0 self.interval_head_polls = 0 self.interval_head_seconds = 0.0 + self.interval_empty_head_polls = 0 self.interval_failed_blocks = 0 self.interval_skipped_ids = 0 self.last_log_time = now @@ -157,8 +162,9 @@ def _reading_summary(self, now): else: parts.append('reads: 0 requests') if self.interval_head_polls: + empty = f' ({self.interval_empty_head_polls:,} empty)' if self.interval_empty_head_polls else '' parts.append( - f'head: {self.interval_head_polls:,} polls, ' + f'head: {self.interval_head_polls:,} polls{empty}, ' f'{self.interval_head_seconds / self.interval_head_polls:.2f} s/poll' ) behind = [] diff --git a/tests/unit/test_comment_reader.py b/tests/unit/test_comment_reader.py index f18a63f..d2b9f93 100644 --- a/tests/unit/test_comment_reader.py +++ b/tests/unit/test_comment_reader.py @@ -157,6 +157,39 @@ def test_an_empty_head_listing_is_skipped_and_the_next_poll_catches_up(): assert queued_blocks(reader) == [1001, 1101, 1201] +@pytest.mark.unit +def test_only_a_long_streak_of_empty_head_polls_is_logged(caplog): + import logging + reader, _ = make_reader(head=1000) + reader.poll_head() + reader.fetch_head = lambda: None + with caplog.at_level(logging.INFO, logger='racb.comment_reader'): + for _ in range(comment_reader.EMPTY_HEAD_POLLS_BEFORE_WARNING - 1): + reader.poll_head() + assert not caplog.records + reader.poll_head() + reader.poll_head() + assert [record.levelname for record in caplog.records] == ['WARNING'] + reader.fetch_head = lambda: 1000 + reader.poll_head() + assert [record.levelname for record in caplog.records] == ['WARNING', 'INFO'] + assert reader.empty_head_polls == 0 + + +@pytest.mark.unit +def test_a_short_streak_of_empty_head_polls_logs_nothing(caplog): + import logging + reader, _ = make_reader(head=1000) + reader.poll_head() + head = {'value': None} + reader.fetch_head = lambda: head['value'] + with caplog.at_level(logging.INFO, logger='racb.comment_reader'): + reader.poll_head() + head['value'] = 1000 + reader.poll_head() + assert not caplog.records + + @pytest.mark.unit def test_run_survives_an_empty_head_listing(): errors = [] diff --git a/tests/unit/test_main.py b/tests/unit/test_main.py index ad68114..2cbd96f 100644 --- a/tests/unit/test_main.py +++ b/tests/unit/test_main.py @@ -286,6 +286,18 @@ def stream(): phase1_workers.submit.assert_called_once_with('first') +@pytest.mark.unit +def test_heartbeat_counts_empty_head_polls(caplog): + import logging + metrics = StreamMetrics() + metrics.record_head_poll(1.0) + metrics.record_head_poll(3.0, empty=True) + with caplog.at_level(logging.INFO, logger='racb.main'): + metrics.log_heartbeat() + assert 'head: 2 polls (1 empty), 2.00 s/poll' in caplog.records[-1].getMessage() + assert metrics.interval_empty_head_polls == 0 + + @pytest.mark.unit def test_heartbeat_reports_reads_and_lag(caplog): import logging