post: when a proxy timeout returns HTML instead of JSON (EN+ZH)
Deploy / build (push) Successful in 24s
Deploy / build (push) Successful in 24s
499 post-mortem: an O(n) library audit inside a polled GET on a one-core cgroup, three reverse-proxy hops, and the status no monitor watches. - measured: 13.6 s idle / 17.7-98.5-35.8 s probes / 76-2507 s under load - evidence triad: 7x 499 @ portal, zero app-log entries, in-container repro - fix: 300 s TTL cache + single-flight refresh + refreshing/cached_at flags, text-first client reader, ?refresh=1 - result: cached path 200 in 0.24-0.36 s (median 0.26 s) - art: ideogram4 base frame + 4 derived targets, art-meta evidence line - LinkedIn companion: docs/linkedin/batch-07-linkedin-posts.md
This commit is contained in:
1 parent
7b363779c5
commit
ec2b89130b
10 files changed
+594
No files matched your search
@@ -0,0 +1,53 @@
|
||||
# LinkedIn Technical Posts — Batch 07
|
||||
|
||||
> **Target Audience**: CTOs, Engineering Directors, and Principal/Staff Hiring Managers in the US, Europe, and Singapore.
|
||||
> **Positioning**: Senior Full-Stack / DevOps / Platform Architect.
|
||||
> **Tone & Persona**: Authoritative, production-tested, quantitative, first-person singular (`I`), zero-fluff, no-seller/no-homelab voice.
|
||||
> **Status**: Ready for publication / scheduling.
|
||||
|
||||
---
|
||||
|
||||
## Post 01: The Proxy That Answered a JSON Request With HTML
|
||||
|
||||
* **Target Article**: `when-a-proxy-timeout-returns-html-instead-of-json`
|
||||
* **Canonical URL**: `https://blog.hoelee.com/posts/when-a-proxy-timeout-returns-html-instead-of-json/`
|
||||
* **Category**: Full-Stack / Edge Engineering
|
||||
* **Character Count**: ~2,150 chars
|
||||
|
||||
```text
|
||||
A production admin card failed with one line: "SyntaxError: Unexpected token '<', "<!DOCTYPE ".
|
||||
|
||||
Read literally, that message accuses the frontend. It sent the investigation into the wrong process for hours.
|
||||
|
||||
The payload was HTML. An application server does not do that on a JSON route. A reverse proxy does, when it stops waiting and serves its own error page.
|
||||
|
||||
Root cause: GET /api/automation computed a library-wide audit inside the request thread. 289 notes, each split into chapters, each chapter hashed, each audio target stat()'d. Then the number was rendered on a polled card.
|
||||
|
||||
At 289 notes that request took 13.6 s. Three consecutive probes: 17.7 s / 98.5 s / 35.8 s. The request had to cross three proxy hops, each with its own timeout, none of them visible to the application.
|
||||
|
||||
Three artefacts found the fault without guessing:
|
||||
|
||||
- Portal access log: 7 requests, every one 499 with 0 body bytes, zero 4xx, zero 5xx.
|
||||
- Application log: no entry at all for that path. The request never arrived.
|
||||
- In-container probe: reproduced the 17.7 / 98.5 / 35.8 s timings.
|
||||
|
||||
499 is what nginx writes when the CLIENT hangs up first. It is not a 5xx, so no error-rate dashboard saw it, and FastAPI never logged it. The card could stay broken for weeks while every health check answered green.
|
||||
|
||||
The fix was not a bigger timeout. Once the audit moved off the request path, the app began logging its own duration:
|
||||
|
||||
76.1 s. 82.3 s. 93.5 s. 124.2 s. 165.1 s. 633.6 s. 1282.5 s. 2507.2 s.
|
||||
|
||||
Same code, same library, a 184x spread — because the container is pinned to one core at a quarter of default CPU weight. Raising the proxy timeout from 120 s to 300 s does not fix a 2,507-second computation. It only moves the wall.
|
||||
|
||||
What I shipped: a 300 s TTL cache with single-flight background refresh and startup warm-up; a refreshing flag plus cached_at so stale numbers render as "computing" instead of a fake zero; and a text-first response reader that keeps the status and the first 80 bytes, so a proxy abort now prints "HTTP 503 · <!DOCTYPE html>" and names the failing layer.
|
||||
|
||||
Result: the cached read path answers 200 in 0.24–0.36 s across five consecutive calls. Median 0.26 s against the 13.6 s audit it replaced — 52x at the median, 38–57x across the spread.
|
||||
|
||||
The most useful line in the whole post-mortem was the one that lied.
|
||||
|
||||
An HTML error page handed to a JSON caller is not a syntax error. It is a proxy telling you, in the only language it has, that it stopped waiting before your code woke up.
|
||||
|
||||
Full measurement chain, both code diffs, and the five rules I now apply to every panel endpoint: https://blog.hoelee.com/posts/when-a-proxy-timeout-returns-html-instead-of-json/
|
||||
|
||||
What does your access-log 499 ratio look like on the endpoints nobody polls?
|
||||
```
|
||||
Binary file not shown.
|
After Width: | Height: | Size: 52 KiB |
Binary file not shown.
|
After Width: | Height: | Size: 34 KiB |
Binary file not shown.
|
After Width: | Height: | Size: 4.8 KiB |
Binary file not shown.
|
After Width: | Height: | Size: 13 KiB |
Binary file not shown.
|
After Width: | Height: | Size: 59 KiB |
Binary file not shown.
|
After Width: | Height: | Size: 60 KiB |
@@ -321,5 +321,15 @@
|
||||
"evidence": "89 covers in 48m · 35% safe zone · Laplacian filter",
|
||||
"ogTitle_en": "Batch Generating 80+ Technical Covers",
|
||||
"ogTitle_zh": "ComfyUI 批量闭环 80+ 张技术封面"
|
||||
},
|
||||
"when-a-proxy-timeout-returns-html-instead-of-json": {
|
||||
"evidence": "13.6 s -> 0.26 s · 2507 s worst · 499 at the gate",
|
||||
"ogTitle_en": "The Proxy That Replied in HTML",
|
||||
"ogTitle_zh": "反代用 HTML 回答了 JSON",
|
||||
"tags": [
|
||||
"nginx",
|
||||
"timeouts",
|
||||
"caching"
|
||||
]
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,298 @@
|
||||
---
|
||||
ogImage: "/og/when-a-proxy-timeout-returns-html-instead-of-json.jpg"
|
||||
banner: "/banners/when-a-proxy-timeout-returns-html-instead-of-json.jpg"
|
||||
title: "When a Proxy Timeout Returns HTML Instead of JSON: A 499 Post-Mortem"
|
||||
description: "Why a self-hosted admin card failed with 'Unexpected token <': an O(n) library audit running inside a GET request, three reverse-proxy hops, and the 499 status no monitor watches — measured from 13.6 s on an idle box to 2,507 s on a busy one."
|
||||
pubDate: 2026-10-28
|
||||
category: engineering
|
||||
blueprint: self-hosted-infrastructure
|
||||
blueprintLayer: L2-edge-proxy-runtime
|
||||
tags: ["nginx", "fastapi", "reverse-proxy", "timeouts", "caching", "observability", "stale-while-revalidate"]
|
||||
draft: false
|
||||
summary:
|
||||
audience: "Full-Stack Engineers, SREs & Platform Architects Who Own Their Own Edge"
|
||||
painPoint: "An admin dashboard card died with a JavaScript syntax error, which pointed every investigation at the frontend — while the real failure was an O(n) audit burning one pinned CPU core behind three proxy hops that silently abort at their own timeouts."
|
||||
impact:
|
||||
- metric: "Endpoint Latency −98%"
|
||||
detail: "Moved a 289-to-341-note library audit off the request thread into a single-flight background refresher; the cached read path now answers in 0.24–0.36 s over five consecutive calls instead of 13.6 s idle and 2,507 s under load."
|
||||
- metric: "Failure Now Names Its Layer"
|
||||
detail: "Replaced a blind res.json() with a text-first reader that preserves the HTTP status and the first 80 bytes of an HTML error page, so a proxy abort reports 'HTTP 503 · <!DOCTYPE …' instead of an unactionable SyntaxError."
|
||||
- metric: "Zero Fabricated Zeros"
|
||||
detail: "Added a refreshing flag plus cached_at timestamp with a 3-second client retry, so a stale audit renders as 'computing' rather than as a false zero on a compliance-adjacent counter."
|
||||
stack: ["FastAPI", "Python threads", "nginx", "authentik", "Docker", "cgroups"]
|
||||
jumpLinks:
|
||||
business: "#the-card-that-blamed-javascript"
|
||||
architecture: "#failure-mode-an-audit-inside-a-get"
|
||||
result: "#the-result"
|
||||
dynamicCta: true
|
||||
---
|
||||
|
||||
## The card that blamed JavaScript
|
||||
|
||||
The bug report arrived as one line of text from a live panel:
|
||||
|
||||
```
|
||||
读取自动处理状态失败:SyntaxError: Unexpected token '<', "<!DOCTYPE "
|
||||
```
|
||||
|
||||
Read literally, that message accuses the frontend. A `SyntaxError` on a `<` character is what
|
||||
`JSON.parse` throws when the payload is not JSON, and the reflexive conclusion — a stale bundle, a
|
||||
typo in a serialiser, a wrong `Content-Type` — puts the investigation in the wrong process for
|
||||
hours.
|
||||
|
||||
The payload was HTML. Something in front of the application had produced a document starting with
|
||||
`<!DOCTYPE`. An application server does not do that on a JSON route; a reverse proxy does. The
|
||||
error message was therefore a map of the fault, drawn by the layer that was *not* at fault: the
|
||||
browser faithfully reported that it had been handed the wrong kind of document.
|
||||
|
||||
What follows is the post-mortem, the measurements that identified the actual cause, and the three
|
||||
contract changes that made the class of failure impossible to misdiagnose again.
|
||||
|
||||
---
|
||||
|
||||
## Failure mode: an audit inside a GET
|
||||
|
||||
The failing route was a status endpoint behind a publishing console:
|
||||
|
||||
```
|
||||
GET /api/automation
|
||||
```
|
||||
|
||||
It returns three counters and three feature flags. Two of the counters are cheap; the third is
|
||||
`tts_stale`, and computing it calls a library-wide audit — enumerate every markdown note, split
|
||||
each into chapters, hash the content of each chapter, then `stat` the corresponding audio target
|
||||
for each one. All of it ran **inside the request thread**, on every single poll of the card.
|
||||
|
||||
```python
|
||||
# The shape that broke: a GET that measures the whole library
|
||||
@app.get("/api/automation")
|
||||
def automation_get():
|
||||
notes = [p for p in sorted(CONTENT_DIR.glob("*.md")) if not p.stem.endswith(".en")]
|
||||
missing_cover = [...]
|
||||
stale = tts_mod.stale_targets(content_dir=CONTENT_DIR, audio_root=AUDIO_DIR) # O(n) audit
|
||||
return {"counts": {"notes": len(notes), "tts_stale": len(stale)}, ...}
|
||||
```
|
||||
|
||||
At 289 notes this is a 13.6-second request. That number alone should have disqualified it from
|
||||
living on a polled card, but the second half of the problem is what turned it into an outage: the
|
||||
request has to cross three reverse-proxy hops before it reaches that function — an SSO gate, a
|
||||
portal nginx, and the container network — and each hop owns a timeout that the application neither
|
||||
sets nor can see.
|
||||
|
||||
The portal's `/api/` location is `proxy_read_timeout 120s` in the live configuration. The SSO gate
|
||||
in front of it gave up earlier. Once a hop's clock expires it does what an nginx does: it stops
|
||||
waiting, closes the upstream connection, and serves **its own HTML error page** to the browser. The
|
||||
frontend then ran `await res.json()` on that document and produced the `SyntaxError` quoted above.
|
||||
|
||||
Nothing in that chain returns a 500. The application never learned the request existed.
|
||||
|
||||
---
|
||||
|
||||
## The evidence triad that proved nothing had failed
|
||||
|
||||
Three artefacts, taken together, located the fault without guesswork. Individually, each is
|
||||
ambiguous; one of them actively misleads.
|
||||
|
||||
| Evidence | Observation | What it eliminates |
|
||||
|---|---|---|
|
||||
| Portal access log | 7 requests for the path, **every one `499` with 0 body bytes**, zero 4xx, zero 5xx | Rules out application errors and authentication rejects |
|
||||
| Application log (uvicorn) | **No entry at all** for the path during the incident window | Proves the request never reached the app — the proxy aborted first |
|
||||
| In-container probe | Same call direct to the app: **17.7 s / 98.5 s / 35.8 s** on three consecutive attempts | Confirms the slowness is real and inside the audit, not a network artefact |
|
||||
|
||||
`499` is the status nginx writes when the **client** closes the connection before the response is
|
||||
sent. It is not an error the server acknowledges, it is not a 5xx, and FastAPI's access log never
|
||||
sees it — so the panel could stay broken for weeks while every uptime check, every error-rate
|
||||
dashboard and every "is the service healthy?" question answered green. The status that describes
|
||||
the failure is written by the hop that gave up, about a request the application never received.
|
||||
|
||||
The misleading artefact was the loudest one: the `SyntaxError`. It is a true statement about the
|
||||
document and a false statement about the cause.
|
||||
|
||||
---
|
||||
|
||||
## The hidden variable: 13.6 s idle, 2,507 s on a busy box
|
||||
|
||||
Before the fix, the audit's cost looked like a constant. It is not. The console container is
|
||||
pinned to a single core (`cpuset "4"`) at a quarter of default CPU weight (`cpu_shares 256`), on a
|
||||
host that also runs an HEVC transcode gate and a content pipeline. The audit competes for that one
|
||||
core with everything else on it.
|
||||
|
||||
After the fix moved the audit off the request path, the application began logging its own duration,
|
||||
which turned the hypothesis into a measurement:
|
||||
|
||||
```
|
||||
automation counts refreshed in 76.1s
|
||||
automation counts refreshed in 82.3s
|
||||
automation counts refreshed in 93.5s
|
||||
automation counts refreshed in 124.2s
|
||||
automation counts refreshed in 93.5s → 165.1s
|
||||
automation counts refreshed in 633.6s
|
||||
automation counts refreshed in 1282.5s
|
||||
automation counts refreshed in 2507.2s
|
||||
```
|
||||
|
||||
Same code, same 341-note library, one order of magnitude of spread — and a worst case **184×
|
||||
slower than the figure measured on an idle box**. That single fact dissolves the naive fix. Raising
|
||||
the proxy timeout from 120 s to 300 s does not solve a 2,507-second computation; it only converts a
|
||||
failure that arrives at 120 s into a failure that arrives at 300 s, five minutes later, with a
|
||||
longer window of consumed capacity.
|
||||
|
||||
The lesson is the one I keep relearning at the edge: **an endpoint's latency is not a property of
|
||||
its code, it is a property of the CPU it is allowed to borrow.** A one-core cgroup limit turns an
|
||||
O(n) file audit into an unbounded operation whose runtime is dictated by whatever else is running
|
||||
beside it.
|
||||
|
||||
---
|
||||
|
||||
## The fix: separate the read path from the compute path
|
||||
|
||||
Three contract changes, each small enough to test independently.
|
||||
|
||||
**1. The read path never computes.** Counts live behind a TTL cache (300 s, `AUTOMATION_COUNTS_TTL_SEC`
|
||||
to tune). A request either gets a fresh cached value or gets the previous value immediately with
|
||||
`refreshing: true`, while a single daemon thread recomputes. Single-flight is enforced with a lock
|
||||
and a flag, so a burst of polls cannot start a burst of audits. The cache is warmed once at startup,
|
||||
inside the app's lifespan hook, so the first human to open the panel does not pay for it.
|
||||
|
||||
<details class="tech-deep-dive">
|
||||
<summary>🔍 View the stale-while-revalidate implementation — cache, single-flight refresh thread, startup warm (52 lines)</summary>
|
||||
|
||||
```python
|
||||
_AUTOMATION_TTL_SEC = float(os.environ.get("AUTOMATION_COUNTS_TTL_SEC", "300") or 300)
|
||||
_automation_cache: Dict[str, Any] = {"data": None, "at": 0.0}
|
||||
_automation_refreshing_flag = [False]
|
||||
_automation_lock = threading.RLock()
|
||||
|
||||
|
||||
@app.get("/api/automation", tags=["ops"])
|
||||
def automation_get(refresh: bool = False):
|
||||
"""Panels must never block on an audit."""
|
||||
flags = autoflow.settings(db=db)
|
||||
now = time.time()
|
||||
cached = dict(_automation_cache)
|
||||
fresh = cached["data"] is not None and (now - cached["at"]) < _AUTOMATION_TTL_SEC
|
||||
if refresh or not fresh:
|
||||
_start_automation_refresh()
|
||||
return {
|
||||
"flags": flags,
|
||||
"counts": (cached["data"] or {}).get("counts")
|
||||
or {"notes": 0, "missing_cover": 0, "tts_stale": 0},
|
||||
"refreshing": _automation_refreshing() or not fresh,
|
||||
"cached_at": (datetime.fromtimestamp(cached["at"]).isoformat(timespec="seconds")
|
||||
if cached["at"] else None),
|
||||
}
|
||||
|
||||
|
||||
def _automation_counts() -> Dict[str, Any]:
|
||||
"""The slow half: cover gap + stale TTS over the whole library."""
|
||||
notes = [p for p in sorted(CONTENT_DIR.glob("*.md")) if not p.stem.endswith(".en")]
|
||||
missing_cover = [...]
|
||||
stale = tts_mod.stale_targets(content_dir=CONTENT_DIR, audio_root=AUDIO_DIR)
|
||||
return {"counts": {"notes": len(notes), "missing_cover": len(missing_cover),
|
||||
"tts_stale": len(stale)},
|
||||
"missing_cover": missing_cover[:20]}
|
||||
|
||||
|
||||
def _start_automation_refresh() -> None:
|
||||
with _automation_lock:
|
||||
if _automation_refreshing_flag[0]:
|
||||
return
|
||||
_automation_refreshing_flag[0] = True
|
||||
|
||||
def _run() -> None:
|
||||
started = time.time()
|
||||
try:
|
||||
data = _automation_counts()
|
||||
_automation_cache.update({"data": data, "at": time.time()})
|
||||
except Exception as exc: # a broken audit must not 500 the card
|
||||
logging.warning("automation counts failed: %s", exc)
|
||||
finally:
|
||||
_automation_refreshing_flag[0] = False
|
||||
logging.info("automation counts refreshed in %.1fs", time.time() - started)
|
||||
|
||||
threading.Thread(target=_run, name="automation-counts", daemon=True).start()
|
||||
```
|
||||
|
||||
</details>
|
||||
|
||||
**2. A stale value must announce itself.** The response carries `refreshing` and `cached_at`, and
|
||||
the card renders `计算中…` next to the numbers while a recompute is in flight, then retries in three
|
||||
seconds. The alternative — showing `0` until data arrives — is worse than being slow, because a
|
||||
zero on a backlog counter is indistinguishable from "nothing to do".
|
||||
|
||||
**3. The client never parses blindly.** `res.json()` was the actual defect on the browser side: it
|
||||
inferred "malformed JSON" from "HTML error page" and discarded both the status code and the body
|
||||
that would have named the failing hop.
|
||||
|
||||
<details class="tech-deep-dive">
|
||||
<summary>🔍 View the text-first response reader and the retry contract (22 lines)</summary>
|
||||
|
||||
```javascript
|
||||
function autoReadJson(res) {
|
||||
// A proxy timeout / 502 / 503 returns an HTML error page. Blind res.json() turns that into
|
||||
// "Unexpected token '<'" and hides which layer failed — keep the status and the head instead.
|
||||
return res.text().then(function (text) {
|
||||
try {
|
||||
return { data: JSON.parse(text) };
|
||||
} catch (e) {
|
||||
var head = String(text || '').trim().slice(0, 80).replace(/\s+/g, ' ');
|
||||
return { error: 'HTTP ' + res.status + ' · ' + (head || 'empty response') };
|
||||
}
|
||||
});
|
||||
}
|
||||
|
||||
// refreshing: show the last known numbers, label them, come back in three seconds.
|
||||
document.getElementById('auto-counts').textContent =
|
||||
'笔记 ' + counts.notes + ' · 缺封面 ' + counts.missing_cover
|
||||
+ ' · 待朗读 ' + counts.tts_stale + (data.refreshing ? ' · 计算中…' : '');
|
||||
if (data.refreshing) { autoRetryTimer = setTimeout(window.autoReload, 3000); }
|
||||
```
|
||||
|
||||
</details>
|
||||
|
||||
A fourth change is smaller but load-bearing: `?refresh=1` forces a recompute. Tests and humans both
|
||||
need a way to demand fresh numbers without waiting out a TTL, and without that affordance the test
|
||||
suite would have had to sleep for minutes.
|
||||
|
||||
The test contract changed with the endpoint, which is the part most people skip: the suite now
|
||||
polls until the background thread lands instead of asserting numbers on the first response. 28 tests
|
||||
pass; the DOM contract check still confirms 16 cards, 68 buttons and 124 element ids, so the frontend
|
||||
rewrite did not quietly drop a control.
|
||||
|
||||
---
|
||||
|
||||
## Reflection: five rules for panel endpoints
|
||||
|
||||
1. **A dashboard endpoint is not a query interface.** It is the most frequently called and least
|
||||
cached surface in an admin UI. Anything O(n) over user data belongs in a background job with a
|
||||
publish step, not in the GET that a browser polls on focus.
|
||||
2. **Your timeout budget is the smallest hop, not the sum.** Four proxies each "allowing" 120 s do
|
||||
not add up; the request dies at whichever clock expires first, and the application cannot see any
|
||||
of them. The application-side budget has to be an order of magnitude under the smallest one.
|
||||
3. **`499` deserves an alert.** It is the only signal that reports "the caller gave up", and it
|
||||
bypasses every 5xx-based monitor. A ratio of 499s to 200s on a single path, scraped from the
|
||||
access log, detects this entire class of failure for almost no cost.
|
||||
4. **Never trust `res.json()` on a proxied route.** Read text, keep the status, keep the first line.
|
||||
The error message is the only artefact the next engineer will have.
|
||||
5. **Stale-while-revalidate beats a bigger number.** Raising a timeout moves the wall; decoupling
|
||||
compute from read removes it — and it removes it for the worst case you have not measured yet
|
||||
(2,507 s here), not just the one you did (13.6 s).
|
||||
|
||||
---
|
||||
|
||||
## The result
|
||||
|
||||
- **Cached read path: 200 in 0.24–0.36 s** across five consecutive calls measured inside the
|
||||
container — a median of 0.26 s against the 13.6 s audit it replaced, **52× faster at the median
|
||||
and 38–57× across the spread**.
|
||||
- **Worst observed case eliminated as a user-facing risk.** The audit still takes 2,507 s when the
|
||||
box is saturated; it now costs a background thread instead of a broken card, and the panel keeps
|
||||
answering throughout.
|
||||
- **Correctness preserved, not masked.** Counts at the time of writing: 341 notes, 1 missing cover,
|
||||
47 notes pending audio — the same computation, moved.
|
||||
- **The failure can no longer masquerade.** If any hop aborts again, the card prints
|
||||
`HTTP 503 · <!DOCTYPE html>…` and the investigation starts at the right layer.
|
||||
|
||||
The single most useful line in this whole exercise was the one that lied: `Unexpected token '<'`.
|
||||
An HTML error page handed to a JSON caller is not a syntax error — it is a proxy telling you, in the
|
||||
only language it has, that it stopped waiting before your code ever woke up.
|
||||
@@ -0,0 +1,233 @@
|
||||
---
|
||||
ogImage: "/og/zh-when-a-proxy-timeout-returns-html-instead-of-json.jpg"
|
||||
banner: "/banners/when-a-proxy-timeout-returns-html-instead-of-json.jpg"
|
||||
title: "反代超时返回 HTML,前端报 SyntaxError:一次 499 事故复盘"
|
||||
description: "后台卡片报「Unexpected token '<'」,所有线索都指向前端,真正的故障却是一个跑在 GET 请求线程里的全库审计:289 到 341 篇笔记逐一切章、算哈希、stat 音频,穿过三层反代,实测从空闲时的 13.6 秒恶化到满载时的 2507 秒。"
|
||||
pubDate: 2026-10-28
|
||||
category: engineering
|
||||
blueprint: self-hosted-infrastructure
|
||||
blueprintLayer: L2-edge-proxy-runtime
|
||||
tags: ["nginx", "fastapi", "反向代理", "超时", "缓存", "可观测性", "stale-while-revalidate"]
|
||||
draft: false
|
||||
summary:
|
||||
audience: "自建边缘层的全栈工程师、SRE 与平台架构师"
|
||||
painPoint: "一张后台卡片被一句 JavaScript 语法错误判了死刑,排查方向全被带到前端;真实死因是一个 O(n) 全库审计占住单核、被三层反代各自的超时闸门无声掐断。"
|
||||
impact:
|
||||
- metric: "端点延迟 −98%"
|
||||
detail: "把 289 至 341 篇笔记的全库审计挪出请求线程,改由单飞后台线程刷新;缓存读路径连续五次实测 0.24–0.36 秒,替代空闲时 13.6 秒、满载时 2507 秒的同步审计。"
|
||||
- metric: "故障自动指明层级"
|
||||
detail: "用「先读文本、保留状态码与首 80 字节」的读取器替代裸 res.json(),反代中断时面板直接打印「HTTP 503 · <!DOCTYPE …」,不再是无法定位的 SyntaxError。"
|
||||
- metric: "绝不显示假零"
|
||||
detail: "新增 refreshing 标记与 cached_at 时间戳,前端显示「计算中…」并 3 秒后自动补取,避免把陈旧值渲染成合规相关计数器上的一个假 0。"
|
||||
stack: ["FastAPI", "Python 线程", "nginx", "authentik", "Docker", "cgroups"]
|
||||
jumpLinks:
|
||||
business: "#the-card-that-blamed-javascript"
|
||||
architecture: "#failure-mode-an-audit-inside-a-get"
|
||||
result: "#the-result"
|
||||
dynamicCta: true
|
||||
---
|
||||
|
||||
## 把责任推给 JavaScript 的卡片 <a id="the-card-that-blamed-javascript"></a>
|
||||
|
||||
线上面板报上来只有一行字:
|
||||
|
||||
```
|
||||
读取自动处理状态失败:SyntaxError: Unexpected token '<', "<!DOCTYPE "
|
||||
```
|
||||
|
||||
字面上读,这句话是在指控前端。`JSON.parse` 遇到 `<` 才会抛 `SyntaxError`,于是第一反应必然是「打包缓存过期」「序列化写错」「`Content-Type` 配错」——排查方向被钉在了错误的进程里,一钉就是几个小时。
|
||||
|
||||
真相是响应体本身就是 HTML。应用前面某一层吐出了一个以 `<!DOCTYPE` 开头的文档。JSON 路由上的应用服务器不会干这种事,反向代理会。所以这条错误信息其实是一张很精确的故障地图,只是画图的那一层**不是**出问题的那一层:浏览器只是老老实实报告「我拿到的是另一种文档」。
|
||||
|
||||
下面是完整复盘:定位真因的几组实测数据,以及让这一类故障再也无法被误判的三处契约改动。
|
||||
|
||||
---
|
||||
|
||||
## 故障形态:藏在 GET 里的全库审计 <a id="failure-mode-an-audit-inside-a-get"></a>
|
||||
|
||||
出问题的路由是发布控制台的一张状态卡片:
|
||||
|
||||
```
|
||||
GET /api/automation
|
||||
```
|
||||
|
||||
它返回三个开关和三个计数。两个计数很便宜,第三个叫 `tts_stale`,为了算它要跑一遍全库审计:枚举所有 markdown 笔记、逐篇切章节、对每章内容算哈希、再对每个目标音频文件 `stat` 一次。而这一切**就跑在请求线程里**,卡片每轮询一次就重算一次。
|
||||
|
||||
```python
|
||||
# 出问题的写法:一个 GET,顺手把整个库量一遍
|
||||
@app.get("/api/automation")
|
||||
def automation_get():
|
||||
notes = [p for p in sorted(CONTENT_DIR.glob("*.md")) if not p.stem.endswith(".en")]
|
||||
missing_cover = [...]
|
||||
stale = tts_mod.stale_targets(content_dir=CONTENT_DIR, audio_root=AUDIO_DIR) # O(n) 审计
|
||||
return {"counts": {"notes": len(notes), "tts_stale": len(stale)}, ...}
|
||||
```
|
||||
|
||||
289 篇笔记时这是一次 13.6 秒的请求。光这个数字就已经足够取消它在轮询卡片上的资格,但让它从「慢」变成「坏」的是另一半原因:这个请求要穿过三层反向代理才摸到这个函数——一层 SSO 门禁、一层 portal nginx、再进容器网络——每一层都有自己的超时,而应用既设不了、也看不见。
|
||||
|
||||
portal 的 `/api/` 位置在现行配置里是 `proxy_read_timeout 120s`,而它前面的 SSO 门禁放弃得更早。任何一层的计时器一到,它就按 nginx 的本分处理:停止等待、断开上游连接、把**自己的 HTML 错误页**交给浏览器。前端接着对这份文档执行 `await res.json()`,于是就有了那行 `SyntaxError`。
|
||||
|
||||
整条链上没有任何一环返回 500。应用从头到尾都不知道这个请求存在过。
|
||||
|
||||
---
|
||||
|
||||
## 三条证据钉死「其实什么都没坏」
|
||||
|
||||
三个产物合起来就能定位故障,不需要猜。单独看每一条都是歧义的,其中一条还会主动误导。
|
||||
|
||||
| 证据 | 观测值 | 排除了什么 |
|
||||
|---|---|---|
|
||||
| portal 访问日志 | 该路径 7 次请求,**全是 `499`、响应体 0 字节**,无 4xx、无 5xx | 排除应用报错与鉴权拒绝 |
|
||||
| 应用日志(uvicorn) | 故障窗口内该路径**一条记录都没有** | 证明请求根本没到应用,是代理先放弃的 |
|
||||
| 容器内直连打点 | 同一调用直连应用:连续三次 **17.7 秒 / 98.5 秒 / 35.8 秒** | 确认慢是真的、且慢在审计内部,不是网络抖动 |
|
||||
|
||||
`499` 是 nginx 在**客户端**先断开连接时写下的状态码。它不是服务端承认的错误,不是 5xx,FastAPI 的访问日志也永远看不到它——所以这张卡片可以坏上几个星期,而所有存活探测、错误率看板、「服务健康吗」的问答统统是绿的。真正描述这次故障的状态码,由放弃等待的那一层写下,指向的是一个应用从未收到的请求。
|
||||
|
||||
而最响的那条证据恰好在误导:`SyntaxError`。它对文档的描述是准确的,对原因的判断是错的。
|
||||
|
||||
---
|
||||
|
||||
## 隐藏变量:空闲时 13.6 秒,满载时 2507 秒
|
||||
|
||||
修之前,审计的耗时看起来像个常数。它不是。控制台容器被钉在单核(`cpuset "4"`),CPU 权重只有默认值的四分之一(`cpu_shares 256`),而宿主机上还跑着 HEVC 转码闸门和内容流水线。这场审计要跟别的任务抢那一个核。
|
||||
|
||||
把审计挪出请求路径之后,应用开始自己记录耗时,假设才变成测量:
|
||||
|
||||
```
|
||||
automation counts refreshed in 76.1s
|
||||
automation counts refreshed in 82.3s
|
||||
automation counts refreshed in 93.5s
|
||||
automation counts refreshed in 124.2s
|
||||
automation counts refreshed in 165.1s
|
||||
automation counts refreshed in 633.6s
|
||||
automation counts refreshed in 1282.5s
|
||||
automation counts refreshed in 2507.2s
|
||||
```
|
||||
|
||||
同一份代码、同一个 341 篇的库,一个数量级的跨度,最坏值比空闲机上量到的数字**慢 184 倍**。这一条就足以否定那个「朴素修法」:把反代超时从 120 秒抬到 300 秒,解决不了一个 2507 秒的计算,只是把 120 秒失败改成 300 秒失败,晚五分钟、多占五分钟容量。
|
||||
|
||||
这就是我在边缘层反复吃到的教训:**端点延迟不是代码的属性,而是它被允许借用多少 CPU 的属性。** 单核 cgroup 限流会把一次 O(n) 文件审计变成耗时由邻居决定的无界操作。
|
||||
|
||||
---
|
||||
|
||||
## 修法:把读路径和计算路径彻底拆开
|
||||
|
||||
三处契约改动,每一处都小到可以独立验证。
|
||||
|
||||
**一、读路径绝不计算。** 计数放进 TTL 缓存(300 秒,`AUTOMATION_COUNTS_TTL_SEC` 可调)。请求要么拿到新鲜缓存,要么立刻拿到上一次的值并带 `refreshing: true`,同时由一个后台 daemon 线程重算。单飞用一把锁加一个标记守住,成串的轮询不会变成成串的审计。缓存还会在应用 lifespan 里预热一次,第一个打开面板的人不用替所有人付这笔账。
|
||||
|
||||
<details class="tech-deep-dive">
|
||||
<summary>🔍 查看 stale-while-revalidate 实现 —— 缓存、单飞刷新线程与启动预热(52 行)</summary>
|
||||
|
||||
```python
|
||||
_AUTOMATION_TTL_SEC = float(os.environ.get("AUTOMATION_COUNTS_TTL_SEC", "300") or 300)
|
||||
_automation_cache: Dict[str, Any] = {"data": None, "at": 0.0}
|
||||
_automation_refreshing_flag = [False]
|
||||
_automation_lock = threading.RLock()
|
||||
|
||||
|
||||
@app.get("/api/automation", tags=["ops"])
|
||||
def automation_get(refresh: bool = False):
|
||||
"""面板绝不在审计上阻塞。"""
|
||||
flags = autoflow.settings(db=db)
|
||||
now = time.time()
|
||||
cached = dict(_automation_cache)
|
||||
fresh = cached["data"] is not None and (now - cached["at"]) < _AUTOMATION_TTL_SEC
|
||||
if refresh or not fresh:
|
||||
_start_automation_refresh()
|
||||
return {
|
||||
"flags": flags,
|
||||
"counts": (cached["data"] or {}).get("counts")
|
||||
or {"notes": 0, "missing_cover": 0, "tts_stale": 0},
|
||||
"refreshing": _automation_refreshing() or not fresh,
|
||||
"cached_at": (datetime.fromtimestamp(cached["at"]).isoformat(timespec="seconds")
|
||||
if cached["at"] else None),
|
||||
}
|
||||
|
||||
|
||||
def _automation_counts() -> Dict[str, Any]:
|
||||
"""慢的那一半:全库缺封面 + 过期朗读目标。"""
|
||||
notes = [p for p in sorted(CONTENT_DIR.glob("*.md")) if not p.stem.endswith(".en")]
|
||||
missing_cover = [...]
|
||||
stale = tts_mod.stale_targets(content_dir=CONTENT_DIR, audio_root=AUDIO_DIR)
|
||||
return {"counts": {"notes": len(notes), "missing_cover": len(missing_cover),
|
||||
"tts_stale": len(stale)},
|
||||
"missing_cover": missing_cover[:20]}
|
||||
|
||||
|
||||
def _start_automation_refresh() -> None:
|
||||
with _automation_lock:
|
||||
if _automation_refreshing_flag[0]:
|
||||
return
|
||||
_automation_refreshing_flag[0] = True
|
||||
|
||||
def _run() -> None:
|
||||
started = time.time()
|
||||
try:
|
||||
data = _automation_counts()
|
||||
_automation_cache.update({"data": data, "at": time.time()})
|
||||
except Exception as exc: # 审计坏了也不能把卡片打成 500
|
||||
logging.warning("automation counts failed: %s", exc)
|
||||
finally:
|
||||
_automation_refreshing_flag[0] = False
|
||||
logging.info("automation counts refreshed in %.1fs", time.time() - started)
|
||||
|
||||
threading.Thread(target=_run, name="automation-counts", daemon=True).start()
|
||||
```
|
||||
|
||||
</details>
|
||||
|
||||
**二、陈旧值必须自己说出来。** 响应里带 `refreshing` 与 `cached_at`,卡片在重算期间把「计算中…」挂在数字后面,3 秒后自动补取一次。反面做法——在数据到达前先显示 `0`——比慢更糟,因为积压计数器上的 0 与「确实没事可做」长得一模一样。
|
||||
|
||||
**三、客户端绝不盲解析。** 真正躺在浏览器侧的缺陷是 `res.json()`:它把「收到了 HTML 错误页」推断成「JSON 格式错误」,顺手丢掉了状态码和本该指出故障层级的那段正文。
|
||||
|
||||
<details class="tech-deep-dive">
|
||||
<summary>🔍 查看「先读文本」的响应读取器与重试契约(22 行)</summary>
|
||||
|
||||
```javascript
|
||||
function autoReadJson(res) {
|
||||
// 反代超时 / 502 / 503 回的是 HTML 错误页;裸 res.json() 会把它变成
|
||||
// "Unexpected token '<'",并把「哪一层挂了」这条信息彻底吞掉。
|
||||
return res.text().then(function (text) {
|
||||
try {
|
||||
return { data: JSON.parse(text) };
|
||||
} catch (e) {
|
||||
var head = String(text || '').trim().slice(0, 80).replace(/\s+/g, ' ');
|
||||
return { error: 'HTTP ' + res.status + ' · ' + (head || '空响应') };
|
||||
}
|
||||
});
|
||||
}
|
||||
|
||||
// refreshing 时:先显示上一次的数字并标注状态,3 秒后再来一次
|
||||
document.getElementById('auto-counts').textContent =
|
||||
'笔记 ' + counts.notes + ' · 缺封面 ' + counts.missing_cover
|
||||
+ ' · 待朗读 ' + counts.tts_stale + (data.refreshing ? ' · 计算中…' : '');
|
||||
if (data.refreshing) { autoRetryTimer = setTimeout(window.autoReload, 3000); }
|
||||
```
|
||||
|
||||
</details>
|
||||
|
||||
第四处改动更小但很关键:`?refresh=1` 强制重算。测试和人一样,都需要一条「立刻要新数字」的通道,否则整套测试只能靠 sleep 等 TTL 过期。
|
||||
|
||||
测试契约跟着端点一起改了,这是大多数人会跳过的一步:用例现在轮询到后台线程落地为止,而不是对第一次响应就断言数字。28 个测试通过;DOM 契约检查仍然确认 16 张卡片、68 个按钮、124 个元素 id,说明前端那轮改写没有悄悄丢掉控件。
|
||||
|
||||
---
|
||||
|
||||
## 复盘:我此后对每个面板端点都套用的五条规矩
|
||||
|
||||
1. **看板端点不是查询接口。** 它是后台里调用最频繁、缓存最少的表面,任何对用户数据的 O(n) 计算都属于后台任务加一次发布,不属于浏览器聚焦时轮询的那个 GET。
|
||||
2. **超时预算等于最小那一跳,不是各跳之和。** 四层反代各自「允许」120 秒并不叠加:请求死在最先到期的那个时钟上,而应用一个都看不见。应用侧的预算必须比最小的那个还低一个数量级。
|
||||
3. **`499` 值得配一条告警。** 它是唯一一个表达「调用方放弃了」的信号,且天然绕开所有基于 5xx 的监控。从访问日志抓单条路径上 499 与 200 的比值,几乎零成本覆盖这一整类故障。
|
||||
4. **在反代后面永远不要信 `res.json()`。** 先读文本,留下状态码,留下第一行。下一个接手的人手里只有这条错误信息。
|
||||
5. **stale-while-revalidate 优于一个更大的数字。** 抬高超时只是把墙往后推;把计算与读拆开才是把墙拆掉——而且拆掉的是你还没量到的那个最坏值(这里的 2507 秒),不只是量到的那个(13.6 秒)。
|
||||
|
||||
---
|
||||
|
||||
## 交付结果 <a id="the-result"></a>
|
||||
|
||||
- **缓存读路径:连续五次容器内实测 200,0.24–0.36 秒**,中位 0.26 秒,对照它所替代的 13.6 秒审计——**中位快 52 倍,整个区间快 38–57 倍**。
|
||||
- **最坏情况不再暴露给使用者。** 宿主机饱和时审计仍要 2507 秒,但它现在只花掉一个后台线程,而不是一张坏掉的卡片,面板全程照常应答。
|
||||
- **正确性保留而非掩盖。** 撰写时的计数:341 篇笔记、1 个缺封面、47 篇待生成朗读——同一个计算,只是搬了位置。
|
||||
- **故障再也无法伪装。** 任何一跳再次中断,卡片会打印 `HTTP 503 · <!DOCTYPE html>…`,排查从正确的层级开始。
|
||||
|
||||
整件事里最有用的一行,恰恰是那行说谎的 `Unexpected token '<'`。把 HTML 错误页递给一个 JSON 调用方,不是语法错误——那是反代用它唯一会说的语言在告诉你:你的代码还没醒,它就已经不等了。
|
||||
Reference in new issue
Block a user