Skip to content

Collapse Telegram polling-error noise into onset and recovery lines - #127

Merged
Danswar merged 3 commits into
developfrom
fix/collapse-telegram-polling-noise
Jul 29, 2026
Merged

Collapse Telegram polling-error noise into onset and recovery lines#127
Danswar merged 3 commits into
developfrom
fix/collapse-telegram-polling-noise

Conversation

@Danswar

@Danswar Danswar commented Jul 29, 2026

Copy link
Copy Markdown

Telegram's gateway answers 502/504 during its own restarts. Two node-telegram-bot-api behaviours turn a short outage into a log burst:

  • With no polling_error listener attached, the library falls back to its own console.error('error: [polling_error] %j', error) (src/telegramPolling.js) — unformatted, at error level, bypassing the application logger entirely.
  • The polling loop reschedules on a fixed 300 ms interval with no backoff regardless of error, and ignores Telegram's retry after. A recent eight-second 502 window produced 27 error lines. Some bursts also carry 429 Too Many Requests: retry after N; in every retained instance the 429 opens the burst, ahead of the 502 run — and because the loop ignores retry after, it answers a retry after 5 by polling again a few hundred milliseconds later, repeatedly, before Telegram switches to 502s.

The listener reports one line per distinct failure, repeats an outage that never clears every five minutes, and closes it with one line. Digit runs are masked out of the failure signature so a counting-down retry after N and a rotating gateway address collapse instead of looking new each time; the number of distinct signatures per outage is capped so a per-attempt token in an upstream error body cannot defeat either the collapsing or the memory bound.

Replaying real failure shapes against the built code:

the observed 8s outage, 27x 502 ....   27 raw errors ->  2 lines
a 429-led burst (sibling shape) ....   19 raw errors ->  3 lines
single isolated blip ...............    1 raw error  ->  1 line
revoked token, 20 min of polling ... 4000 raw errors ->  4 lines (outage still open)
2000 polls, every message unique ... 2000 raw errors -> 22 lines, signature set held at 20

Sample output for the 429-led burst row above, replayed from that burst's real timestamps:

WARN  Telegram polling failing (attempt 1): ETELEGRAM: 429 Too Many Requests: retry after 5
WARN  Telegram polling failing (attempt 8): ETELEGRAM: 502 Bad Gateway
WARN  Telegram polling errors stopped after 8s and 19 attempts

Below the two limits noted next, every distinct failure is reported on arrival — including a 429 and a 502 within the same burst — and a permanently failing poll keeps reporting. Two mechanisms deliberately bound the worst case rather than reproducing it, and both cost information. The error text is truncated to the first MAX_POLLING_ERROR_LENGTH characters before it is both logged and reduced to a signature, so anything past that never reaches the log, and failures differing only beyond it collapse into one. And once MAX_POLLING_SIGNATURES distinct failures have been reported within a single outage, a further new failure is no longer reported on arrival: from then on the outage emits at most one line per report interval, carrying whichever failure is in flight when that report falls due — so a new failure that has been superseded by then, or an outage that clears first, is never shown. Both log lines — the onset and the closing one — are at warn on purpose: an outage whose end is invisible under a warn-level log configuration is worse than one extra line. The closing line deliberately says errors stopped rather than recovered — the grace period only establishes that no further error arrived, it does not probe the poll.

Note that no inbound updates are lost during these outages — getUpdates does not advance its offset on failure, so Telegram re-delivers on the next successful poll. This change is about how those failures are logged. The retry cadence itself is unchanged — no backoff is added and retry after is still ignored, so the underlying storm, including the 429 bursts described above, still happens; it just stops being reprinted line by line. Message-delivery correctness is unaffected.

The same listener, byte-identical, is proposed for the JuiceDollar bot in JuiceDollar/api#66. That repo additionally needed the resolveMediaPath guard from #115, which it never received and which left it dropping every video-bearing notification.

Known follow-up, deliberately not in this PR: the missing-asset notice added by #115 is logged at debug here (telegram.service.ts, twitter.service.ts), which is below the repo's default info level and so is not emitted unless LOG_LEVEL is lowered, and assets/socialmedia/{telegram,twitter} still contain only .gitkeep — so the text-only fallback is currently the permanent state and is invisible. JuiceDollar/api#66 raises the equivalent notice to a deduplicated warn. Porting that back, or shipping the actual assets, is worth a separate change; it is outside this PR's scope and pre-exists it.

Verification

  • yarn build clean, prettier --check clean on the touched files.
  • Collapse behaviour replayed against dist/ for each scenario above.
  • No unit tests added: the repo's jest config has rootDir="src" but the sources live at the repo root, so yarn test aborts before test discovery (Validation Error: Directory .../src in the rootDir option was not found) and no test can run today — same constraint noted in Handle missing social-media tokens and assets gracefully #115.

Danswar added 3 commits July 29, 2026 12:33
Without a 'polling_error' listener node-telegram-bot-api writes its own
unformatted console error for every failed poll, at error level and
outside the application logger. The polling loop also retries on a fixed
300ms interval with no backoff, so a brief Telegram gateway outage
produces several lines per second — a recent nine-second 502 window
logged 27 lines — and sustained retries earn a 429 on top of the original
502 because the loop ignores Telegram's retry-after.

Attach a listener that reports one line per distinct failure plus one on
recovery with duration and attempt count. The same outage becomes two
lines, an escalation from 502 to 429 is still surfaced, and an outage
never appears to stay open. Both lines are logged at warn so they remain
visible together under a warn-level log configuration.

No unit tests added: the repo's jest config has rootDir="src" but the
sources live at the repo root, so `yarn test` finds zero tests today.
Review follow-up on the first commit.

The signature used the raw error message compared against the previous
one only, which fails in the two cases that actually occur: "Too Many
Requests: retry after N" counts down and a connect failure carries a
rotating gateway address, so each retry looked like a new failure, and
alternating errors re-reported on every poll. Mask digits out of the
signature and track the signatures already reported within the current
outage.

A permanently failing poll — a revoked token answers 401 forever —
reported once and then stayed silent, because the recovery timer only
fires once errors stop. Repeat the report every five minutes while the
outage is open.

Also move the outage shape into telegram.types.ts next to the other
state types, and truncate the error text, which wraps the upstream
response body.
Second review follow-up.

The signature prefixed the error code onto a message that the library
already prefixes with that same code, so the prefix discriminated
nothing. Use the message alone.

The signature set had no upper bound: a message carrying a per-attempt
token that survives digit masking - a request id in an upstream error
body reaches the parse-error branch verbatim - produced a fresh
signature per poll, which defeated the collapsing and grew the set
without limit. Cap it, past which only the periodic report remains. A
replay of 2000 such polls now yields 22 lines and 20 retained
signatures instead of 2000 of each.

An error arriving more than the grace period after the previous one
opened and closed its own outage, so an isolated blip cost two lines
where it used to cost one. Skip the closing line for a single attempt.

The closing line said "recovered", but nothing probes the poll - the
grace period only establishes that no further error arrived, and a
request that never settles would look the same. Say what is actually
known instead.
@Danswar

Danswar commented Jul 29, 2026

Copy link
Copy Markdown
Author

This went through 12 review passes before it was clean. Recording what changed, since several rounds altered real behaviour:

Code fixes (rounds 1–3)

  • The polling signature compared raw messages against the previous one only. That fails in exactly the two cases that occur: retry after N counts down, and a connect failure carries a rotating gateway address. Digits are now masked out of the signature, and the signatures already reported within the outage are tracked as a set.
  • A permanently failing poll — a revoked token answers 401 forever — reported once and then went silent, because the recovery timer only fires once errors stop. It now repeats every five minutes while the outage is open.
  • The signature set had no upper bound, an isolated blip cost two log lines, and the closing line claimed "recovered" although nothing probes the poll.

Description fixes (rounds 4–12) — all cases where the description claimed more than the code delivers:

  • It said the change was about the retry storm. It adds no backoff and retry after is still ignored; only the reprinting stops.
  • It said nothing that used to be visible becomes silent. The signature cap and the 200-character truncation both cost information, and both are now stated.
  • The 429 was described as an escalation on top of the 502. The logs show the opposite in 14 of 14 retained bursts: the 429 opens the burst and the 502 run follows.
  • Deployed logger behaviour was asserted as fact rather than derived from the repo's default level.

Every replay figure in the description was re-derived against the built code rather than estimated.

@Danswar
Danswar marked this pull request as ready for review July 29, 2026 18:01
@Danswar
Danswar merged commit 14fbf47 into develop Jul 29, 2026
1 check passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant