diff --git a/.github/workflows/docker.yml b/.github/workflows/docker.yml index 9ccb6d19..dc911ba3 100644 --- a/.github/workflows/docker.yml +++ b/.github/workflows/docker.yml @@ -768,3 +768,22 @@ jobs: echo "${route}: mounted (HTTP ${STATUS})" rm -f "${RESPONSE_FILE}" done + + # TC-1176: the 2026-10-14 read hang began ~40 min after a promote. After any + # Phala deploy attempt (including rollbacks and failed verifications, which + # may still have changed prod), start the Write Probe's dense promote watch: + # reads every 30 s for 5 min, then every 5 min for 60 min, paging on 2 slow + # (>5 s) or failed reads in a row. A separate job so the production-secret + # deploy job never holds `actions: write`. + promote-watch: + runs-on: ubuntu-latest + needs: [deploy-phala] + if: ${{ always() && needs.deploy-phala.result != 'skipped' && needs.deploy-phala.result != 'cancelled' }} + timeout-minutes: 5 + permissions: + actions: write + steps: + - name: Dispatch Write Probe promote watch + env: + GH_TOKEN: ${{ github.token }} + run: gh workflow run write-probe.yml -R "${GITHUB_REPOSITORY}" --ref main -f mode=dense diff --git a/.github/workflows/write-probe-tests.yml b/.github/workflows/write-probe-tests.yml new file mode 100644 index 00000000..9e577fd7 --- /dev/null +++ b/.github/workflows/write-probe-tests.yml @@ -0,0 +1,37 @@ +# TC-1176: unit tests for the Write Probe's deadlines, failure classification, +# consecutive-failure rule, heartbeat reporting and dense watch (stub client, +# no node, no secrets). + +name: Write Probe tests + +on: + pull_request: + paths: + - "test/probe/**" + - ".github/workflows/write-probe*.yml" + push: + branches: [main] + paths: + - "test/probe/**" + - ".github/workflows/write-probe*.yml" + +permissions: + contents: read + +jobs: + test: + runs-on: ubuntu-latest + timeout-minutes: 5 + defaults: + run: + working-directory: test/probe + steps: + - uses: actions/checkout@v4 + - uses: actions/setup-node@v4 + with: + node-version: "20" + cache: npm + cache-dependency-path: test/probe/package-lock.json + - run: npm install --no-audit --no-fund + - run: npm run typecheck + - run: npm test diff --git a/.github/workflows/write-probe.yml b/.github/workflows/write-probe.yml index 4f5b372c..f7851c40 100644 --- a/.github/workflows/write-probe.yml +++ b/.github/workflows/write-probe.yml @@ -1,104 +1,264 @@ -# TC-313: Synthetic end-to-end WRITE probe for the prod TinyCloud node. +# TC-313 + TC-1176: synthetic end-to-end probe for the prod TinyCloud node. # -# WHY: During the 2026-07-27/28 write-degradation incident, /healthz returned -# 200 in ~300ms while kv.put took 46s and /delegate blew past Cloudflare's 100s -# ceiling. /healthz and /version never touch the DB or the write path, so -# uptime monitoring stayed green while writes were down. This probe drives a -# REAL signed end-to-end write (signIn -> kv.put -> kv.get -> kv.delete) and -# FAILS the job when any stage is too slow. A failed scheduled job is the alert -# (GitHub sends failure notifications) -- no new always-on infra. +# WHY: /healthz and /version never touch the DB, the read path or the write +# path. On 2026-07-27/28 (TC-313) writes degraded while /healthz stayed green; +# on 2026-10-14 (TC-1176) signed-in KV reads and SQL hung ~62s (504) for every +# account while /healthz, /version, 401s and writes stayed green. This probe +# failed twice during TC-1176 and nobody was paged. # -# OPERATOR SETUP -- set ONE repository secret (Settings -> Secrets and -# variables -> Actions): -# PROBE_PRIVATE_KEY A hex private key (with or without 0x) for a THROWAWAY -# identity used only by the probe. It operates in its own -# isolated space (prefix "tc313-write-probe"), so it never -# touches user data. Do NOT reuse a real user/prod key. -# Optional overrides (secrets or repo variables): -# PROBE_HOST (default https://node.tinycloud.xyz), PROBE_PREFIX, -# PROBE_THRESHOLD_SIGNIN_MS, PROBE_THRESHOLD_PUT_MS, -# PROBE_THRESHOLD_GET_MS, PROBE_THRESHOLD_DELETE_MS. +# WHAT: every 5 minutes, sign in with a throwaway key, read a fixed KV key and a +# fixed SQL row (hard 20s deadline per stage), then the TC-313 write round-trip. +# A good read pings the Better Stack heartbeat "Node authorized reads (Write +# Probe)"; from the 2nd failed read in a row the probe POSTs the heartbeat's +# /fail URL with one line naming the stage, outcome, duration, node build and +# UTC time, which pages team@. A missed heartbeat (GitHub not running the +# schedule) pages after 60 min. Heartbeat as code: tinycloud-dev +# ops/betterstack/uptime.json. # -# READING A FAILURE: the job log prints one line per stage with its latency and -# threshold; the slow stage is flagged SLOW. signIn slowness -> /delegate; put/ -# delete slowness -> DB write path. See test/probe/README.md for full details. +# DENSE MODE (promote watch): `gh workflow run write-probe.yml -f mode=dense` +# reads every 30s for 5 min, then every 5 min for 60 min, with a 5s threshold. +# docker.yml dispatches it after every Phala deploy. While it runs, scheduled +# runs skip so only one probe owns the heartbeat. # -# SLACK (optional, later): if the repo adopts a Slack-notify pattern, add a -# final step guarded by `if: failure()` posting to a SLACK_WEBHOOK_URL secret -# (e.g. slackapi/slack-github-action). Keep it separate so a Slack outage never -# masks the probe verdict. +# SECRETS (Settings -> Secrets and variables -> Actions): +# PROBE_PRIVATE_KEY hex private key of a THROWAWAY identity used only +# by the probe, in its own space (prefix +# "tc313-write-probe"). Never a real user/prod key. +# BETTERSTACK_HEARTBEAT_URL the heartbeat's secret URL (set by piping +# tinycloud-dev ops/betterstack/apply.ts +# --heartbeat-url into `gh secret set`). +# Optional overrides (secrets): PROBE_HOST (default https://node.tinycloud.xyz), +# PROBE_PREFIX, PROBE_THRESHOLD_PUT_MS, PROBE_THRESHOLD_GET_MS, +# PROBE_THRESHOLD_DELETE_MS (write round-trip only). +# +# READING A RUN: one log line per stage — +# [probe] mode=normal sample=1 stage=kv ms=812 threshold_ms=20000 result=ok outcome="ok" +# and the job summary tables every sample. See test/probe/README.md. name: Write Probe +run-name: >- + ${{ github.event_name == 'workflow_dispatch' && inputs.mode == 'dense' && 'Write Probe (dense promote watch)' + || github.event_name == 'workflow_dispatch' && inputs.force_failure && 'Write Probe (forced failure)' + || 'Write Probe' }} on: schedule: - # Every 15 minutes. A red run is the alert. - - cron: "*/15 * * * *" - workflow_dispatch: {} - -# Only one probe at a time; never queue a backlog if a run is slow. -concurrency: - group: write-probe - cancel-in-progress: false + # GitHub delays and drops scheduled runs under load (measured on this + # workflow at */15: p50 gap 19 min, max 54 min), hence the heartbeat's + # 60 min period+grace. Failed reads alert through /fail regardless. + - cron: "*/5 * * * *" + workflow_dispatch: + inputs: + mode: + description: "normal: one probe run. dense: promote watch (reads every 30 s for 5 min, then every 5 min for 60 min; 5 s threshold)" + type: choice + options: [normal, dense] + default: normal + force_failure: + description: "Probe an unresolvable host to exercise the alert path. Two forced runs in a row page team@." + type: boolean + default: false permissions: contents: read jobs: probe: + if: github.event_name != 'workflow_dispatch' || inputs.mode != 'dense' runs-on: ubuntu-latest - # Hard wall below Cloudflare's 100s ceiling * a few stages, so a truly hung - # write path still fails the job instead of hanging the runner. + # Every stage has a 20s deadline, so a hung node can't hold the runner. timeout-minutes: 5 + # Only one normal probe at a time; never queue a backlog. Heartbeat + # ownership with the dense job: this job skips while a dense watch is + # queued or running, and the dense job waits for running normal runs to + # finish before its first sample (separate groups, so a scheduled run can + # never cancel a pending dense watch). + concurrency: + group: write-probe + cancel-in-progress: false + permissions: + contents: read + actions: read # to see whether a dense promote watch is queued or running defaults: run: working-directory: test/probe steps: - # An unconfigured probe must be visibly INACTIVE, not noisily red. Until - # an operator sets PROBE_PRIVATE_KEY the scheduled run would fail every 15 - # minutes on a missing key -- alert fatigue that would bury the real - # write-degradation signal this probe exists to surface. Skip cleanly - # instead; a configured probe still fails loudly on latency, as intended. + # An unconfigured probe must be visibly INACTIVE, not noisily red. - name: Check probe is configured id: gate # Runs before checkout, so override the job's test/probe default. working-directory: ${{ github.workspace }} env: PROBE_PRIVATE_KEY: ${{ secrets.PROBE_PRIVATE_KEY }} + GH_TOKEN: ${{ github.token }} run: | if [ -z "${PROBE_PRIVATE_KEY}" ]; then echo "::notice::PROBE_PRIVATE_KEY is not set; skipping. Set it to activate the write probe." - echo "configured=false" >> "$GITHUB_OUTPUT" + echo "run=false" >> "$GITHUB_OUTPUT" + exit 0 + fi + # A queued or running dense watch owns the heartbeat. Fail closed: if + # the lookup can't be made, skip this run rather than risk two owners + # (a persistent outage of the lookup shows as a missed heartbeat). + for attempt in 1 2 3; do + if dense="$(gh run list -R "$GITHUB_REPOSITORY" --workflow write-probe.yml --limit 30 \ + --json displayTitle,status --jq '[.[] | select(.displayTitle == "Write Probe (dense promote watch)" and .status != "completed")] | length')"; then + break + fi + dense="" + sleep 5 + done + if [ -z "${dense}" ]; then + echo "::warning::Could not check for a dense promote watch; skipping this run." + echo "run=false" >> "$GITHUB_OUTPUT" + elif [ "${dense}" != "0" ]; then + echo "::notice::A dense promote watch is queued or running and owns the heartbeat; skipping this run." + echo "run=false" >> "$GITHUB_OUTPUT" else - echo "configured=true" >> "$GITHUB_OUTPUT" + echo "run=true" >> "$GITHUB_OUTPUT" fi - uses: actions/checkout@v4 - if: steps.gate.outputs.configured == 'true' + if: steps.gate.outputs.run == 'true' - uses: actions/setup-node@v4 - if: steps.gate.outputs.configured == 'true' + if: steps.gate.outputs.run == 'true' with: node-version: "20" cache: npm cache-dependency-path: test/probe/package-lock.json - name: Install probe dependencies - if: steps.gate.outputs.configured == 'true' + if: steps.gate.outputs.run == 'true' run: npm install --no-audit --no-fund - name: Type-check probe - if: steps.gate.outputs.configured == 'true' + if: steps.gate.outputs.run == 'true' run: npm run typecheck - - name: Run write probe - if: steps.gate.outputs.configured == 'true' + # The consecutive-failure count survives between runs as a tiny state + # file in the Actions cache (the newest entry wins on restore). + - name: Restore failure count + if: steps.gate.outputs.run == 'true' + uses: actions/cache/restore@v4 + with: + path: test/probe/.state + key: write-probe-state-${{ github.run_id }}-${{ github.run_attempt }} + restore-keys: write-probe-state- + + - name: Run probe + id: probe + if: steps.gate.outputs.run == 'true' env: + PROBE_MODE: normal + PROBE_FORCE_FAILURE: ${{ github.event_name == 'workflow_dispatch' && inputs.force_failure }} PROBE_PRIVATE_KEY: ${{ secrets.PROBE_PRIVATE_KEY }} + BETTERSTACK_HEARTBEAT_URL: ${{ secrets.BETTERSTACK_HEARTBEAT_URL }} PROBE_HOST: ${{ secrets.PROBE_HOST }} PROBE_PREFIX: ${{ secrets.PROBE_PREFIX }} - PROBE_THRESHOLD_SIGNIN_MS: ${{ secrets.PROBE_THRESHOLD_SIGNIN_MS }} PROBE_THRESHOLD_PUT_MS: ${{ secrets.PROBE_THRESHOLD_PUT_MS }} PROBE_THRESHOLD_GET_MS: ${{ secrets.PROBE_THRESHOLD_GET_MS }} PROBE_THRESHOLD_DELETE_MS: ${{ secrets.PROBE_THRESHOLD_DELETE_MS }} run: npm run probe + + - name: Save failure count + if: always() && steps.gate.outputs.run == 'true' && (steps.probe.outcome == 'success' || steps.probe.outcome == 'failure') + uses: actions/cache/save@v4 + with: + path: test/probe/.state + key: write-probe-state-${{ github.run_id }}-${{ github.run_attempt }} + + dense: + if: github.event_name == 'workflow_dispatch' && inputs.mode == 'dense' + runs-on: ubuntu-latest + # Up to 10 min of handover wait, ~66 min of samples, plus setup. + timeout-minutes: 85 + concurrency: + group: write-probe-dense + cancel-in-progress: false + permissions: + contents: read + actions: read # to wait for running normal probe runs + defaults: + run: + working-directory: test/probe + steps: + - name: Check probe is configured + id: gate + working-directory: ${{ github.workspace }} + env: + PROBE_PRIVATE_KEY: ${{ secrets.PROBE_PRIVATE_KEY }} + run: | + if [ -z "${PROBE_PRIVATE_KEY}" ]; then + echo "::notice::PROBE_PRIVATE_KEY is not set; skipping." + echo "run=false" >> "$GITHUB_OUTPUT" + else + echo "run=true" >> "$GITHUB_OUTPUT" + fi + + # Take over the heartbeat: new normal runs already skip (they see this + # run); wait for any normal run that started earlier to finish, so its + # final ping or /fail and its state save land before ours. Fail closed: + # without a confirmed handover the watch doesn't start (the red run is + # the signal to re-dispatch it). + - name: Wait for running normal probes + if: steps.gate.outputs.run == 'true' + working-directory: ${{ github.workspace }} + env: + GH_TOKEN: ${{ github.token }} + run: | + for _ in $(seq 1 40); do + if busy="$(gh run list -R "$GITHUB_REPOSITORY" --workflow write-probe.yml --limit 30 \ + --json databaseId,displayTitle,status \ + --jq "[.[] | select(.databaseId != ${GITHUB_RUN_ID} and .status == \"in_progress\" and .displayTitle != \"Write Probe (dense promote watch)\")] | length")"; then + [ "${busy}" = "0" ] && exit 0 + echo "waiting for ${busy} running normal probe run(s)" + else + echo "run lookup failed; retrying" + fi + sleep 15 + done + echo "::error::No confirmed handover from normal probe runs after 10 min; not starting the watch. Re-dispatch mode=dense." + exit 1 + + - uses: actions/checkout@v4 + if: steps.gate.outputs.run == 'true' + + - uses: actions/setup-node@v4 + if: steps.gate.outputs.run == 'true' + with: + node-version: "20" + cache: npm + cache-dependency-path: test/probe/package-lock.json + + - name: Install probe dependencies + if: steps.gate.outputs.run == 'true' + run: npm install --no-audit --no-fund + + # Same failure state as normal runs, so a streak carries across modes. + - name: Restore failure count + if: steps.gate.outputs.run == 'true' + uses: actions/cache/restore@v4 + with: + path: test/probe/.state + key: write-probe-state-${{ github.run_id }}-${{ github.run_attempt }} + restore-keys: write-probe-state- + + - name: Promote watch + id: probe + if: steps.gate.outputs.run == 'true' + env: + PROBE_MODE: dense + PROBE_FORCE_FAILURE: ${{ inputs.force_failure }} + PROBE_PRIVATE_KEY: ${{ secrets.PROBE_PRIVATE_KEY }} + BETTERSTACK_HEARTBEAT_URL: ${{ secrets.BETTERSTACK_HEARTBEAT_URL }} + PROBE_HOST: ${{ secrets.PROBE_HOST }} + PROBE_PREFIX: ${{ secrets.PROBE_PREFIX }} + run: npm run probe + + - name: Save failure count + if: always() && steps.gate.outputs.run == 'true' && (steps.probe.outcome == 'success' || steps.probe.outcome == 'failure') + uses: actions/cache/save@v4 + with: + path: test/probe/.state + key: write-probe-state-${{ github.run_id }}-${{ github.run_attempt }} diff --git a/docs/releasing.md b/docs/releasing.md index de7c7997..27b306f5 100644 --- a/docs/releasing.md +++ b/docs/releasing.md @@ -186,6 +186,14 @@ its branch policy before any workflow that names it runs. that profile's space. This exercises `/delegate`, `/invoke` KV and SQL. Run it with stderr visible (no `2>/dev/null`), so a failing request shows its error rather than an empty result. +4. **Watch.** The `promote-watch` job then dispatches the Write Probe's dense + promote watch (TC-1176): signed-in KV and SQL reads every 30 s for 5 min, + then every 5 min for 60 min, paging team@ through Better Stack on 2 reads + in a row over 5 s or failing. The 2026-10-14 read hang began ~40 min after + a promote, which is why it runs for an hour. Check the run titled + `Write Probe (dense promote watch)`; to start one by hand: + `gh workflow run write-probe.yml -R TinyCloudLabs/tinycloud-node --ref main -f mode=dense`. + Details: `test/probe/README.md`. ## Rolling back diff --git a/test/probe/.gitignore b/test/probe/.gitignore new file mode 100644 index 00000000..95f7491e --- /dev/null +++ b/test/probe/.gitignore @@ -0,0 +1 @@ +.state/ diff --git a/test/probe/README.md b/test/probe/README.md index 7ae35f46..b17d483e 100644 --- a/test/probe/README.md +++ b/test/probe/README.md @@ -1,100 +1,200 @@ -# TC-313: Synthetic write probe +# Write Probe (TC-313, TC-1176) + +A small, self-contained probe that drives **real, signed, end-to-end reads and +writes** against the live TinyCloud node. It runs from GitHub Actions +(`.github/workflows/write-probe.yml`, workflow name **Write Probe**) every 5 +minutes, and in a dense **promote watch** after every Phala deploy. + +## Why + +`/healthz` and `/version` never touch the database, the read path or the write +path, so uptime monitoring stays green while users are broken: + +- **2026-07-27/28 (TC-313):** `/healthz` returned 200 in ~300ms while `kv.put` + took 46s and `/delegate` blew past Cloudflare's 100s ceiling. +- **2026-10-14 (TC-1176):** signed-in KV reads and SQL returned 504 after ~62s + for every account from ~23:35 to 23:53 UTC, while `/healthz`, `/version`, + 401s and writes stayed green. This probe failed at 23:36 and 23:50, but a red + scheduled run only e-mails whoever last edited the cron line, so nobody was + paged. + +## What it does + +### Normal mode (every scheduled run) + +**Read half — the paging signal.** Each stage has a hard **20s** client +deadline (`STAGE_DEADLINE_MS`): + +| Stage | What | +|----------|-----------------------------------------------------------------------| +| `signin` | SIWE sign-in + delegation activation | +| `space` | ensure the probe's own space exists (idempotent) | +| `kv` | signed-in `kv.get` of the fixed key `read-probe/fixed` | +| `sql` | signed-in `SELECT v FROM read_probe WHERE id = 1` (default database) | + +The fixed key and row are written once by the probe itself the first time they +are missing; after that they are only read. + +- **Good read** of both KV and SQL: ping the Better Stack heartbeat **Node + authorized reads (Write Probe)**. A ping also resolves an open heartbeat + incident. +- **Failed read** (any stage over 20s or erroring): count it in a small state + file (`.state/probe-state.json`, carried between runs in the Actions cache and + shared with dense mode). KV and SQL are counted separately; a failed `signin` + or `space` counts against both. The heartbeat is pinged only while **both** + are at zero, so a healthy SQL read never hides a broken KV read. From the + **2nd failure in a row** of either, the probe POSTs the heartbeat's `/fail` + URL with one line, which pages team@: + + ``` + TC-1176 node read probe FAIL (2 in a row, normal): stage=kv outcome="timeout >=20s" duration_ms=20004 build=1.20.6 host=node.tinycloud.xyz at=2026-10-15T01:05:07Z + ``` + + `outcome` is one of `timeout >=20s`, `HTTP `, `connection refused`, + `DNS`, `connection reset`, `connect timeout`, `node /info not OK`, + `error `, or `slow >` (dense mode). `build` is the + node version from public `/version`, or `unknown()` if `/version` is + unreachable. **Read it as:** a read stage timing out while `build` is known + means a **read hang** (TC-1176; Amos's runbook: recovery restart); `signin` + failing with `HTTP 5xx`, `connection refused`, `DNS` or `build=unknown(...)` + means the **node is down** (rollback territory). + + While a failure streak lasts, `/fail` is re-sent at most every 4 minutes, + counted from the last report Better Stack **accepted** (2xx): a rejected or + undelivered report is retried on the next sample. One failure alone never + pages: a ~60s node restart during a deploy is absorbed. +- **Heartbeat not accepted:** if a ping or `/fail` gets a non-2xx or no + response, the job ends red (logged as `heartbeat ... NOT accepted`), so a + broken heartbeat shows before it turns into a false "missed" page. + +**Write half — TC-313's round-trip.** `put -> get -> delete` of a fresh key, +each with its latency threshold (default 5s, `PROBE_THRESHOLD_{PUT,GET,DELETE}_MS`) +and the same 20s deadline. A breach fails the job (GitHub e-mail) but does not +touch the heartbeat. + +### Dense mode — promote watch + +`workflow_dispatch` with `mode=dense`: one job that signs in once, then reads + +- every **30s for 5 min** (10 samples, alternating KV and SQL so each sees at + most one request per 30s), then +- every **5 min for 60 min** (12 samples, KV and SQL each). + +A read over **5s** (`DENSE_SLOW_MS`) or failing counts; **2 in a row** of KV or +of SQL POST `/fail` with the same one-line body (`dense` instead of `normal`); +the heartbeat is pinged once both are healthy. The job summary tables every +sample's latency, and the job ends red if any sample failed or a heartbeat +report wasn't accepted. + +**One owner of the heartbeat at a time.** A dense watch starts from the failure +state the last normal run saved and saves its own at the end, so a streak +carries across modes. Scheduled runs skip themselves while a dense watch is +queued or running, and the dense job waits for any normal run already in +progress to finish before its first sample. They use separate concurrency +groups, so a scheduled run can never cancel a pending dense watch. Both checks +fail closed: a scheduled run that can't look up runs (after 3 tries) skips +itself, and a dense watch without a confirmed handover within 10 min ends red +without sampling. Re-dispatch it in that case. + +`docker.yml` dispatches it automatically after every Phala deploy attempt (job +`promote-watch`). To run it by hand (Amos, QA): -A small, self-contained probe that drives a **real, signed, end-to-end write** -against the live TinyCloud node and fails when any stage is too slow. It runs on -a schedule from GitHub Actions (`.github/workflows/write-probe.yml`). +```bash +gh workflow run write-probe.yml -R TinyCloudLabs/tinycloud-node --ref main -f mode=dense +gh run list -R TinyCloudLabs/tinycloud-node --workflow write-probe.yml --limit 3 \ + --json databaseId,displayTitle,status,conclusion,createdAt +``` -## Why (the "healthz is blind to writes" rationale) +The dense run's title is `Write Probe (dense promote watch)`. Watch its +`status`/`conclusion` (`success` = every sample under 5s), the job summary +table, or the log lines below. No secrets are needed to trigger or observe it. -During the 2026-07-27/28 write-degradation incident, `/healthz` returned 200 in -~300ms while `kv.put` took 46s and `/delegate` blew past Cloudflare's 100s -ceiling. `/healthz` and `/version` never touch the database or the write path, -so uptime monitoring stayed green while writes were effectively down. This probe -exercises the write path a real client uses, so degradation shows up as a failed -job (the alert) instead of a silent outage. +## Log format -## What it measures +One line per stage, per sample: -Each stage is timed independently and checked against its own threshold: +``` +[probe] mode=dense sample=3 stage=kv ms=812 threshold_ms=5000 result=ok outcome="ok" +[probe] mode=normal sample=1 stage=kv ms=20004 threshold_ms=20000 result=fail outcome="timeout >=20s" +[probe] read verdict=fail failures_kv=2 failures_sql=0 heartbeat_action=fail +[probe] fail report body: TC-1176 node read probe FAIL (2 in a row, normal): stage=kv ... +[probe] heartbeat fail sent: HTTP 200 +``` -| Stage | Threshold | Why | -|-------------|-----------|-----| -| `signIn` | 15s | SIWE sign-in + delegation activation — the `/delegate` path worst-hit in the incident. Healthy ~1-3s; 15s is far under the 100s CF wall but clearly degraded. | -| `kv.put` | 5s | The write. Healthy sub-second; 5s = write path degrading before a hard failure. | -| `kv.get` | 5s | Read-back verification (also asserts the bytes round-trip). | -| `kv.delete` | 5s | Cleanup; also exercises the write path so the probe space never accumulates data. | +Raw error details are logged as `stage= error: ` with the private +key and heartbeat URL redacted. The heartbeat URL itself is never logged. -Any breach — or any error (network, auth, readback mismatch) — exits non-zero -and fails the job. There is no graceful fallback by design: a silent pass would -recreate the exact blind spot this probe exists to remove. +## Alert timing -Thresholds are overridable via env: `PROBE_THRESHOLD_SIGNIN_MS`, -`PROBE_THRESHOLD_PUT_MS`, `PROBE_THRESHOLD_GET_MS`, `PROBE_THRESHOLD_DELETE_MS`. +| Situation | Pages after | +|-----------------------------------------|-----------------------------------------------| +| Reads hang or fail (normal mode) | the 2nd failed run in a row (~5–15 min) | +| Reads slow or fail after a promote | the 2nd bad dense sample (~30s–5 min) | +| GitHub stops running the probe at all | 60 min without a ping (heartbeat period 5 min + grace 55 min) | -## Approach: SDK, not the `tc` CLI +The long grace is deliberate: GitHub delays and drops scheduled runs under load. +On this workflow (cron `*/15`, 600 runs, 2026-10-06..14) the gap between runs +was p50 19 min, p99 48 min, max 54 min. Read failures don't wait for the grace; +they alert through `/fail`. -The probe uses the published `@tinycloud/node-sdk` (`TinyCloudNode`) — the -canonical programmatic client path (`signIn()` → `kv.put/get/delete`). This is -far less code and infra than the alternatives evaluated: +## No pause for deploys -- The `tc` CLI would require building the whole Rust node binary in CI. -- The `test/load/k6/` path (TC-268) needs a long-running Rust **signer** sidecar - server plus k6 — heavyweight for a 15-minute cron. +Per Amos (TC-1176): the probe keeps running through and after node promotes. A +~60s restart is absorbed by the 2-in-a-row rule, and TC-1176 began ~40 min after +a promote. The only switch is a manual **emergency** one, recorded in TC-1176: -The SDK path installs one npm package and drives the identical end-to-end write -a real user would. +```bash +gh workflow disable "Write Probe" -R TinyCloudLabs/tinycloud-node # stop probing +# and pause the heartbeat ("paused": true in tinycloud-dev ops/betterstack/uptime.json, then apply) +gh workflow enable "Write Probe" -R TinyCloudLabs/tinycloud-node # undo +``` -## Operator setup +## Exercising the alert path -Set **one** GitHub Actions secret on the repository (Settings → Secrets and -variables → Actions): +`force_failure=true` points the run at `https://read-probe-forced-failure.invalid` +(reserved TLD, fails at DNS). Two forced runs in a row really page team@: -- **`PROBE_PRIVATE_KEY`** — a hex private key (with or without `0x`) for a - **throwaway** identity used only by the probe. It operates in its own isolated - space (prefix `tc313-write-probe`), so it never touches user data. Do **not** - reuse a real user or prod key. +```bash +gh workflow run write-probe.yml -R TinyCloudLabs/tinycloud-node --ref main -f force_failure=true +# wait for it to finish, then once more; the next good scheduled run resolves the incident +``` -Optional secret/vars: `PROBE_HOST` (defaults to `https://node.tinycloud.xyz`), -`PROBE_PREFIX`, and the threshold overrides above. +## Operator setup -Generate a throwaway key, e.g.: +GitHub Actions secrets on the repository: -```bash -node -e "console.log('0x'+require('crypto').randomBytes(32).toString('hex'))" -``` +- **`PROBE_PRIVATE_KEY`** — hex private key (with or without `0x`) of a + **throwaway** identity used only by the probe, in its own space (prefix + `tc313-write-probe`). Never a real user or prod key. Generate one with + `node -e "console.log('0x'+require('crypto').randomBytes(32).toString('hex'))"` + and pipe it into `gh secret set`, never through chat. +- **`BETTERSTACK_HEARTBEAT_URL`** — the heartbeat's secret URL. The heartbeat is + managed as code in tinycloud-dev `ops/betterstack/uptime.json`; its README + pipes the URL from `apply.ts --heartbeat-url` straight into `gh secret set`. + Unset, the probe still runs and logs `heartbeat ... skipped`. -## Reading a failure +Optional secrets: `PROBE_HOST` (default `https://node.tinycloud.xyz`), +`PROBE_PREFIX`, and the write thresholds above. -A red scheduled run means the write path crossed a threshold (or errored). The -job log prints one line per stage, e.g.: +## Approach: SDK, not the `tc` CLI -``` -[probe] signIn 1820ms (threshold 15000ms) ok -[probe] put 410ms (threshold 5000ms) ok -[probe] get 205ms (threshold 5000ms) ok -[probe] delete 190ms (threshold 5000ms) ok -[probe] PASS: all stages within thresholds -``` +The probe uses the published `@tinycloud/node-sdk` (`TinyCloudNode`), the +canonical programmatic client path. The `tc` CLI would need building in CI, and +`test/load/k6/` needs a long-running Rust signer sidecar. -On failure the offending stage is flagged `SLOW` and a `FAIL:` summary names -the stage(s) and measured latency. Match the slow stage to the incident -playbook: `signIn` slowness points at `/delegate`; `put`/`delete` slowness -points at the DB write path. +`probe-core.ts` holds everything that doesn't need the SDK (deadlines, outcome +classification, the failure rule, heartbeat reporting, the dense loop); +`write-probe.ts` wires it to `TinyCloudNode`. ## Running locally ```bash cd test/probe npm install -PROBE_PRIVATE_KEY=0x... npm run probe -# type-check only: +npm test # unit tests (stub client; no node, no secrets) npm run typecheck +PROBE_PRIVATE_KEY=0x... npm run probe # normal mode +PROBE_PRIVATE_KEY=0x... PROBE_MODE=dense npm run probe # promote watch (~66 min) ``` -## Wiring failure alerts to Slack (optional, later) - -A failed scheduled job already emails watchers via GitHub's notification -settings — no extra infra. If/when the repo adopts a Slack-notify pattern, add a -final step to the job guarded by `if: failure()` that posts to a -`SLACK_WEBHOOK_URL` secret, e.g. `slackapi/slack-github-action`. Keep it as a -separate `if: failure()` step so a Slack outage never masks the probe verdict. +Without `BETTERSTACK_HEARTBEAT_URL` nothing is reported to Better Stack. diff --git a/test/probe/package.json b/test/probe/package.json index 7431c467..ac5fc051 100644 --- a/test/probe/package.json +++ b/test/probe/package.json @@ -6,7 +6,8 @@ "description": "TC-313 synthetic end-to-end write probe for the TinyCloud prod node.", "scripts": { "typecheck": "tsc --noEmit", - "probe": "tsx write-probe.ts" + "probe": "tsx write-probe.ts", + "test": "tsx --test probe-core.test.ts" }, "dependencies": { "@tinycloud/node-sdk": "^2.10.0" diff --git a/test/probe/probe-core.test.ts b/test/probe/probe-core.test.ts new file mode 100644 index 00000000..daf02d25 --- /dev/null +++ b/test/probe/probe-core.test.ts @@ -0,0 +1,273 @@ +import assert from "node:assert/strict"; +import { mock, test } from "node:test"; +import { + DeadlineError, + INITIAL_STATE, + classify, + decide, + denseWatch, + failBody, + heartbeatUrl, + parseState, + readCheck, + report, + settle, + type Deliver, + type Fetch, + type ReadClient, + type StageResult, +} from "./probe-core"; + +const KEY = "0x4c0883a69102937d6231471b5dbb6204fe5129617082792ae468d01a3f362318"; +const HB = "https://uptime.betterstack.com/api/v1/heartbeat/CANARYtokenAbc123XYZ"; + +const never = () => new Promise(() => {}); + +// Errors in the shapes the SDK actually produces (sdk-services ServiceError). +const http504 = { code: "NETWORK_ERROR", message: `Failed to get key "read-probe/fixed": 504 - gateway`, service: "kv", meta: { status: 504 } }; +const undiciCause = (code: string) => Object.assign(new TypeError("fetch failed"), { cause: Object.assign(new Error(`connect ${code}`), { code }) }); +const network = (code: string) => ({ code: "NETWORK_ERROR", message: "fetch failed", service: "kv", cause: undiciCause(code) }); + +/** A stub client whose stages behave as scripted and record what was called. */ +function stub(behavior: Partial Promise>>): ReadClient & { calls: string[] } { + const calls: string[] = []; + const stage = (name: keyof ReadClient) => () => { + calls.push(name); + return (behavior[name] ?? (async () => {}))(); + }; + return { calls, signIn: stage("signIn"), ensureSpace: stage("ensureSpace"), kvRead: stage("kvRead"), sqlRead: stage("sqlRead") }; +} + +test("outcomes name what failed: deadline, HTTP status, refused, DNS", () => { + assert.equal(classify(new DeadlineError("kv", 20_000)), "timeout >=20s"); + assert.equal(classify(http504), "HTTP 504"); + assert.equal(classify(network("ECONNREFUSED")), "connection refused"); + assert.equal(classify(network("ENOTFOUND")), "DNS"); + assert.equal(classify(network("EAI_AGAIN")), "DNS"); + assert.equal(classify({ code: "KV_NOT_FOUND", message: "Key not found", service: "kv" }), "error KV_NOT_FOUND"); +}); + +test("a hung read fails at its deadline and the check stops there", async () => { + mock.timers.enable({ apis: ["setTimeout"] }); + try { + let kvStarted!: () => void; + const started = new Promise((r) => (kvStarted = r)); + const client = stub({ + kvRead: () => { + kvStarted(); + return never(); + }, + }); + const lines: string[] = []; + const check = readCheck(client, { log: (l) => lines.push(l), secrets: [KEY] }); + await started; + mock.timers.tick(20_000); + const { results, failure } = await check; + assert.equal(failure?.stage, "kv"); + assert.equal(failure?.outcome, "timeout >=20s"); + assert.deepEqual(client.calls, ["signIn", "ensureSpace", "kvRead"], "sql is not attempted after kv failed"); + assert.deepEqual(results.map((r) => r.ok), [true, true, false]); + assert.ok(lines.some((l) => l.includes("stage=kv") && l.includes("result=fail"))); + } finally { + mock.timers.reset(); + } +}); + +test("a failed sign-in is reported as the signin stage, with the HTTP status", async () => { + const client = stub({ signIn: async () => { throw http504; } }); + const { failure } = await readCheck(client, { log: () => {}, secrets: [KEY] }); + assert.deepEqual([failure?.stage, failure?.outcome], ["signin", "HTTP 504"]); + assert.deepEqual(client.calls, ["signIn"]); +}); + +test("a read that completes but exceeds the slow threshold is a failure", async () => { + let now = 0; + const client = stub({ sqlRead: async () => void (now += 5_200) }); + const { failure } = await readCheck(client, { log: () => {}, secrets: [KEY], slowMs: 5_000, stages: ["sql"], now: () => now }); + assert.deepEqual([failure?.stage, failure?.ms, failure?.outcome], ["sql", 5_200, "slow 5.2s >5s"]); +}); + +test("logged error details never contain the key or the heartbeat URL", async () => { + const leaky = { code: "NETWORK_ERROR", message: `bad sig from ${KEY} posting ${HB}`, service: "kv" }; + const client = stub({ kvRead: async () => { throw leaky; } }); + const lines: string[] = []; + await readCheck(client, { log: (l) => lines.push(l), secrets: [KEY, HB] }); + const all = lines.join("\n"); + assert.ok(all.includes("[redacted]")); + assert.ok(!all.includes(KEY) && !all.includes(HB)); +}); + +const fail = (stage: string, outcome = "timeout >=20s", ms = 20_000): StageResult => ({ stage, ms, ok: false, outcome }); +const ok = (stage: string): StageResult => ({ stage, ms: 300, ok: true, outcome: "ok" }); + +test("two failures in a row report /fail; a good read of everything pings and resets", () => { + const t0 = Date.parse("2026-10-15T01:00:00Z"); + const first = decide(INITIAL_STATE, [ok("signin"), ok("space"), fail("kv")], t0); + assert.equal(first.action, "none", "one failure (e.g. a ~60 s node restart) does not alert"); + const second = decide(first.state, [ok("signin"), ok("space"), fail("kv", "HTTP 504", 61_700)], t0 + 300_000); + assert.deepEqual([second.action, second.consecutive, second.failure?.outcome], ["fail", 2, "HTTP 504"]); + const reported = { ...second.state, lastFailReportAt: new Date(t0 + 300_000).toISOString() }; + // Dense samples 30 s apart don't re-post inside the minimum interval... + assert.equal(decide(reported, [fail("kv")], t0 + 330_000).action, "none"); + // ...but a streak that lasts keeps re-reporting. + assert.equal(decide(reported, [fail("kv")], t0 + 600_000).action, "fail"); + const healed = decide(reported, [ok("signin"), ok("space"), ok("kv"), ok("sql")], t0 + 900_000); + assert.deepEqual(healed, { action: "ping", state: INITIAL_STATE, consecutive: 0 }); +}); + +test("a failed sign-in counts against both reads; a healthy SQL read never hides a broken KV read", () => { + const t0 = 0; + const s1 = decide(INITIAL_STATE, [fail("signin", "HTTP 502")], t0); + assert.deepEqual(s1.state.failures, { kv: 1, sql: 1 }); + const s2 = decide(s1.state, [ok("signin"), ok("space"), ok("kv"), ok("sql")], t0 + 1); + assert.equal(s2.action, "ping"); + // KV keeps failing while SQL is fine (dense alternation): no ping, and KV still alerts. + const k1 = decide(INITIAL_STATE, [fail("kv")], t0); + const q1 = decide(k1.state, [ok("sql")], t0 + 30_000); + assert.equal(q1.action, "none"); + const k2 = decide(q1.state, [fail("kv")], t0 + 60_000); + assert.deepEqual([k2.action, k2.failure?.stage, k2.consecutive], ["fail", "kv", 2]); +}); + +test("a rejected /fail is retried on the next failure instead of starting the quiet window", async () => { + const t0 = Date.parse("2026-10-15T01:00:00Z"); + const streak = decide(INITIAL_STATE, [fail("kv")], t0).state; + const attempts: string[] = []; + const rejecting: Deliver = async (action) => (attempts.push(action), { ok: false, line: "heartbeat fail NOT accepted: HTTP 503" }); + const first = await settle(streak, [fail("kv")], t0 + 30_000, rejecting); + assert.deepEqual([first.action, first.delivered, first.state.lastFailReportAt], ["fail", false, undefined]); + const accepting: Deliver = async (action) => (attempts.push(action), { ok: true, line: "heartbeat fail sent: HTTP 200" }); + const second = await settle(first.state, [fail("kv")], t0 + 60_000, accepting); + assert.deepEqual([second.action, second.delivered], ["fail", true]); + assert.equal(second.state.lastFailReportAt, new Date(t0 + 60_000).toISOString()); + assert.deepEqual(attempts, ["fail", "fail"]); +}); + +test("the state file round-trips; a missing or corrupt one starts from zero failures", () => { + const state = decide(decide(INITIAL_STATE, [fail("sql", "HTTP 504", 61_712)], 0).state, [fail("sql")], 1).state; + assert.deepEqual(parseState(JSON.stringify(state)), state); + assert.deepEqual(parseState(undefined), INITIAL_STATE); + assert.deepEqual(parseState("{not json"), INITIAL_STATE); + assert.deepEqual(parseState('{"failures":{"kv":-3,"sql":"x"}}'), INITIAL_STATE); +}); + +test("the /fail body names stage, outcome, duration, build and UTC time on one line", () => { + const failure: StageResult = { stage: "kv", ms: 20_004, ok: false, outcome: "timeout >=20s" }; + const body = failBody({ mode: "normal", consecutive: 2, failure, build: "1.20.6", host: "node.tinycloud.xyz", at: new Date("2026-10-15T01:05:07.123Z") }); + assert.equal( + body, + 'TC-1176 node read probe FAIL (2 in a row, normal): stage=kv outcome="timeout >=20s" duration_ms=20004 build=1.20.6 host=node.tinycloud.xyz at=2026-10-15T01:05:07Z', + ); + assert.ok(!body.includes("\n")); +}); + +test("ping GETs the heartbeat URL, /fail POSTs the body; only 2xx counts; lines never have the URL", async () => { + const sent: { url: string; method?: string; body?: unknown }[] = []; + let status = 200; + const fetchFn: Fetch = async (url, init) => { + sent.push({ url, method: init?.method, body: init?.body }); + return new Response("", { status }); + }; + const url = heartbeatUrl(HB); + assert.deepEqual(await report("ping", url, undefined, fetchFn), { ok: true, line: "heartbeat ping sent: HTTP 200" }); + assert.deepEqual(await report("fail", url, "the body", fetchFn), { ok: true, line: "heartbeat fail sent: HTTP 200" }); + assert.deepEqual(sent, [ + { url: HB, method: "GET", body: undefined }, + { url: `${HB}/fail`, method: "POST", body: "the body" }, + ]); + status = 503; + assert.deepEqual(await report("ping", url, undefined, fetchFn), { ok: false, line: "heartbeat ping NOT accepted: HTTP 503" }); + + const fetchDown: Fetch = async () => { + throw undiciCause("ENOTFOUND"); + }; + assert.deepEqual(await report("fail", url, "x", fetchDown), { ok: false, line: "heartbeat fail NOT delivered: DNS" }); + assert.equal((await report("ping", undefined, undefined, fetchFn)).line, "heartbeat ping skipped: BETTERSTACK_HEARTBEAT_URL not set"); +}); + +test("only a Better Stack heartbeat URL is accepted, and errors don't echo it", () => { + assert.equal(heartbeatUrl(""), undefined); + for (const bad of ["http://uptime.betterstack.com/api/v1/heartbeat/abc", "https://evil.example/api/v1/heartbeat/abc", "https://uptime.betterstack.com/api/v2/monitors", "nope"]) { + assert.throws(() => heartbeatUrl(bad), (e: Error) => !e.message.includes(bad)); + } +}); + +const delivered: Deliver = async (action) => ({ ok: true, line: `heartbeat ${action} sent: HTTP 200` }); + +test("dense watch: alternating reads on the 30 s phase, both on the 5 min phase, one sign-in", async () => { + const client = stub({}); + const sleeps: number[] = []; + let now = 0; + const { samples } = await denseWatch(client, { + log: () => {}, + secrets: [KEY], + deliver: delivered, + schedule: [{ intervalMs: 30_000, count: 4 }, { intervalMs: 300_000, count: 2 }], + clock: () => now, + sleep: async (ms) => { + sleeps.push(ms); + now += ms; + }, + }); + assert.equal(samples.length, 6); + assert.deepEqual(samples.map((s) => s.results.map((r) => r.stage).join("+")), ["signin+space+kv", "sql", "kv", "sql", "kv+sql", "kv+sql"]); + assert.deepEqual(sleeps, [30_000, 30_000, 30_000, 30_000, 300_000]); + assert.equal(client.calls.filter((c) => c === "signIn").length, 1); +}); + +test("dense watch: KV reads over 5 s alert even while SQL is healthy, and only full recovery pings", async () => { + let now = 0; + let kvSlow = 3; + const client = stub({ + kvRead: async () => { + if (kvSlow > 0) { + kvSlow -= 1; + now += 6_000; + } + }, + }); + const reports: string[] = []; + const { samples } = await denseWatch(client, { + log: () => {}, + secrets: [KEY], + deliver: async (action, failure, consecutive) => (reports.push(`${action}:${failure?.stage ?? "-"}:${consecutive}`), { ok: true, line: "" }), + schedule: [{ intervalMs: 30_000, count: 8 }], + clock: () => now, + sleep: async (ms) => void (now += ms), + }); + // kv on odd samples: slow at 1, 3, 5, healthy at 7. sql on even samples, always healthy. + assert.deepEqual(samples.map((s) => s.ok), [false, true, false, true, false, true, true, true]); + // 2nd slow KV (sample 3) reports; sample 5 is inside the 4 min minimum; sample 7 heals KV -> ping. + assert.deepEqual(reports, ["fail:kv:2", "ping:-:0", "ping:-:0"]); +}); + +test("failure history carries across normal and dense runs", async () => { + // A normal run failed KV once just before the promote: the dense watch's first slow KV is the 2nd in a row. + const handedOver = decide(INITIAL_STATE, [ok("signin"), ok("space"), fail("kv")], 0).state; + let now = 0; + const reports: string[] = []; + const saved: number[] = []; + const dense = await denseWatch(stub({ kvRead: async () => void (now += 6_000) }), { + log: () => {}, + secrets: [KEY], + initialState: handedOver, + onState: async (s) => void saved.push(s.failures.kv), + deliver: async (action) => (reports.push(action), { ok: true, line: "" }), + schedule: [{ intervalMs: 30_000, count: 1 }], + clock: () => now, + sleep: async () => {}, + }); + assert.deepEqual(reports, ["fail"]); + assert.deepEqual(saved, [2]); + + // A healthy dense watch clears the streak, so the next normal failure is the 1st, not the 2nd. + const cleared = await denseWatch(stub({}), { + log: () => {}, + secrets: [KEY], + initialState: dense.state, + deliver: delivered, + schedule: [{ intervalMs: 300_000, count: 1 }], + sleep: async () => {}, + }); + assert.equal(decide(cleared.state, [ok("signin"), ok("space"), fail("kv")], 1).action, "none"); +}); diff --git a/test/probe/probe-core.ts b/test/probe/probe-core.ts new file mode 100644 index 00000000..06779972 --- /dev/null +++ b/test/probe/probe-core.ts @@ -0,0 +1,476 @@ +/** + * TC-1176: SDK-free core of the Write Probe — deadlines, failure + * classification, the consecutive-failure rule, Better Stack heartbeat + * reporting and the dense "promote watch" loop. `write-probe.ts` wires these + * to the real `@tinycloud/node-sdk`; `probe-core.test.ts` drives them with a + * stub client, so every timeout and failure path is tested without a node. + * + * Nothing in here may print a secret. Errors are reduced to a classified + * outcome ("timeout >=20s", "HTTP 504", "connection refused", "DNS", ...); + * raw messages only reach the log through `redact`, and the heartbeat URL is + * never logged at all. + */ + +/** Hard client deadline for every stage (the TC-1176 spec: >20 s is a failure). */ +export const STAGE_DEADLINE_MS = 20_000; +/** Dense (post-promote) mode: a read slower than this counts as a failure. */ +export const DENSE_SLOW_MS = 5_000; +/** Failures in a row before the heartbeat gets a `/fail` report. */ +export const FAILURES_TO_ALERT = 2; +/** At most one `/fail` per this interval while a failure streak lasts. */ +export const FAIL_REPORT_MIN_INTERVAL_MS = 240_000; +/** Deadline for the heartbeat ping/fail and the /version lookup. */ +export const REPORT_TIMEOUT_MS = 10_000; + +/** Dense watch: every 30 s for 5 min, then every 5 min for 60 min. */ +export const DENSE_SCHEDULE: readonly Phase[] = [ + { intervalMs: 30_000, count: 10 }, + { intervalMs: 300_000, count: 12 }, +]; + +export type ReadStage = "signin" | "space" | "kv" | "sql"; +export type Phase = { intervalMs: number; count: number }; + +export class DeadlineError extends Error { + constructor( + readonly stage: string, + readonly deadlineMs: number, + ) { + super(`${stage} did not finish within ${deadlineMs}ms`); + this.name = "DeadlineError"; + } +} + +/** Runs `fn`, rejecting with DeadlineError if it hasn't settled within `ms`. */ +export async function withDeadline(stage: string, ms: number, fn: () => Promise): Promise { + let timer: NodeJS.Timeout | undefined; + const deadline = new Promise((_, reject) => { + timer = setTimeout(() => reject(new DeadlineError(stage, ms)), ms); + }); + try { + return await Promise.race([fn(), deadline]); + } finally { + clearTimeout(timer); + } +} + +const NET_CODES: Record = { + ECONNREFUSED: "connection refused", + ENOTFOUND: "DNS", + EAI_AGAIN: "DNS", + ECONNRESET: "connection reset", + ETIMEDOUT: "connect timeout", + UND_ERR_CONNECT_TIMEOUT: "connect timeout", + UND_ERR_SOCKET: "connection reset", +}; + +function field(value: unknown, key: string): unknown { + return value !== null && typeof value === "object" ? Reflect.get(value, key) : undefined; +} + +/** The value and its `cause` chain (SDK ServiceError -> TypeError -> undici error). */ +function causes(error: unknown): unknown[] { + const chain: unknown[] = []; + for (let e = error; e !== undefined && e !== null && chain.length < 6; e = field(e, "cause")) chain.push(e); + return chain; +} + +/** + * One short outcome for an operator, never a raw message: + * "timeout >=20s" | "HTTP 504" | "connection refused" | "DNS" | ... | "error KV_NOT_FOUND". + */ +export function classify(error: unknown): string { + const chain = causes(error); + for (const e of chain) { + if (e instanceof DeadlineError) return `timeout >=${Number((e.deadlineMs / 1000).toFixed(2))}s`; + } + for (const e of chain) { + const status = field(field(e, "meta"), "status") ?? field(e, "status"); + if (typeof status === "number" && status >= 100 && status <= 599) return `HTTP ${status}`; + } + for (const e of chain) { + const code = field(e, "code"); + if (typeof code === "string" && NET_CODES[code]) return NET_CODES[code]; + } + for (const e of chain) { + if (field(e, "name") === "TimeoutError") return "timeout (client)"; + } + // The SDK's sign-in pre-check: a non-2xx /info carries no status or cause. + if (field(error, "name") === "VersionCheckError") return "node /info not OK"; + const code = field(error, "code"); + if (typeof code === "string" && /^[A-Z][A-Z0-9_]{1,40}$/.test(code)) return `error ${code}`; + if (error instanceof Error && /^[A-Za-z]{1,40}$/.test(error.name)) return `error ${error.name}`; + return "error"; +} + +/** Replaces every secret occurrence, strips control characters and caps the length. */ +export function redact(text: string, secrets: readonly string[], max = 300): string { + let out = text; + for (const s of secrets) if (s && s.length >= 8) out = out.split(s).join("[redacted]"); + out = out.replace(/[\u0000-\u001f\u007f]+/g, " "); + return out.length > max ? `${out.slice(0, max)}…` : out; +} + +/** Short, redacted detail for the job log (the outcome alone is what alerts). */ +export function detail(error: unknown, secrets: readonly string[]): string { + const message = field(error, "message"); + return redact(typeof message === "string" ? message : String(error), secrets, 200); +} + +export type StageResult = { + stage: string; + ms: number; + ok: boolean; + /** "ok", "slow 6.2s >5s", or a classify() outcome. */ + outcome: string; +}; + +/** + * Times one stage under the hard deadline. `slowMs` turns a completed but slow + * call into a failure (dense mode: 5 s); in normal mode it equals the deadline. + */ +export async function measure( + stage: string, + fn: () => Promise, + opts: { deadlineMs?: number; slowMs?: number; now?: () => number; onError?: (e: unknown) => void } = {}, +): Promise { + const deadlineMs = opts.deadlineMs ?? STAGE_DEADLINE_MS; + const slowMs = opts.slowMs ?? deadlineMs; + const now = opts.now ?? (() => performance.now()); + const start = now(); + try { + await withDeadline(stage, deadlineMs, fn); + } catch (error) { + opts.onError?.(error); + return { stage, ms: Math.round(now() - start), ok: false, outcome: classify(error) }; + } + const ms = Math.round(now() - start); + if (ms > slowMs) return { stage, ms, ok: false, outcome: `slow ${(ms / 1000).toFixed(1)}s >${slowMs / 1000}s` }; + return { stage, ms, ok: true, outcome: "ok" }; +} + +// ---- consecutive-failure rule ------------------------------------------------ + +/** + * KV and SQL are tracked separately: a sample may read only one of them (dense + * 30 s phase), and a healthy SQL read must not hide a broken KV read. + */ +export const READ_TARGETS = ["kv", "sql"] as const; +export type ReadTarget = (typeof READ_TARGETS)[number]; + +/** Persisted between runs and shared by normal and dense mode. */ +export type ProbeState = { + /** Failed observations in a row, per read target. */ + failures: Record; + /** The latest failure per target, for the `/fail` body. */ + lastFailure: Partial>; + /** ISO time of the last ACCEPTED `/fail` in the current streak. */ + lastFailReportAt?: string; +}; + +export const INITIAL_STATE: ProbeState = { failures: { kv: 0, sql: 0 }, lastFailure: {} }; + +export type Decision = { + action: "ping" | "fail" | "none"; + /** State to keep if the action's delivery succeeds (see settle()). */ + state: ProbeState; + /** The failure named in the `/fail` body: the worst target's latest failure. */ + failure?: StageResult; + consecutive: number; +}; + +/** + * Folds one sample into the state and decides what the heartbeat should hear. + * A kv/sql result updates its own target; a failed signin/space means neither + * could be read, so it counts against both. Targets the sample didn't observe + * keep their count. + * - every target at 0 failures -> ping (resolves an open heartbeat incident); + * - any target at FAILURES_TO_ALERT+ -> `/fail`, at most once per + * FAIL_REPORT_MIN_INTERVAL_MS; + * - otherwise nothing (one failure alone never pages). + */ +export function decide(prev: ProbeState, results: readonly StageResult[], nowMs: number): Decision { + const failures = { ...prev.failures }; + const lastFailure = { ...prev.lastFailure }; + for (const r of results) { + const targets: readonly ReadTarget[] = r.stage === "kv" || r.stage === "sql" ? [r.stage] : r.ok ? [] : READ_TARGETS; + for (const t of targets) { + failures[t] = r.ok ? 0 : failures[t] + 1; + if (r.ok) delete lastFailure[t]; + else lastFailure[t] = r; + } + } + const worst = READ_TARGETS.reduce((a, b) => (failures[b] > failures[a] ? b : a)); + const consecutive = failures[worst]; + if (consecutive === 0) return { action: "ping", state: { failures, lastFailure: {} }, consecutive }; + const state: ProbeState = { failures, lastFailure, ...(prev.lastFailReportAt ? { lastFailReportAt: prev.lastFailReportAt } : {}) }; + const last = prev.lastFailReportAt ? Date.parse(prev.lastFailReportAt) : Number.NaN; + const due = consecutive >= FAILURES_TO_ALERT && !(nowMs - last < FAIL_REPORT_MIN_INTERVAL_MS); + return { action: due ? "fail" : "none", state, failure: lastFailure[worst], consecutive }; +} + +function count(value: unknown): number { + return typeof value === "number" && Number.isInteger(value) && value >= 0 ? value : 0; +} + +/** Tolerates a missing or corrupt state file: start from zero failures. */ +export function parseState(text: string | undefined): ProbeState { + if (!text) return INITIAL_STATE; + try { + const raw: unknown = JSON.parse(text); + const failures = field(raw, "failures"); + const lastFailure = field(raw, "lastFailure"); + const at = field(raw, "lastFailReportAt"); + const restored: Partial> = {}; + for (const t of READ_TARGETS) { + const r = field(lastFailure, t); + const stage = field(r, "stage"); + const ms = field(r, "ms"); + const outcome = field(r, "outcome"); + if (typeof stage === "string" && typeof ms === "number" && typeof outcome === "string") { + restored[t] = { stage: redact(stage, [], 20), ms, ok: false, outcome: redact(outcome, [], 60) }; + } + } + return { + failures: { kv: count(field(failures, "kv")), sql: count(field(failures, "sql")) }, + lastFailure: restored, + ...(typeof at === "string" && !Number.isNaN(Date.parse(at)) ? { lastFailReportAt: at } : {}), + }; + } catch { + return INITIAL_STATE; + } +} + +// ---- heartbeat reporting ------------------------------------------------------- + +/** The one-line `/fail` body: stage, outcome, duration, node build, UTC time. No secrets. */ +export function failBody(f: { + mode: "normal" | "dense"; + consecutive: number; + failure: StageResult; + build: string; + host: string; + at: Date; +}): string { + const line = + `TC-1176 node read probe FAIL (${f.consecutive} in a row, ${f.mode}): ` + + `stage=${f.failure.stage} outcome="${f.failure.outcome}" duration_ms=${f.failure.ms} ` + + `build=${f.build} host=${f.host} at=${f.at.toISOString().replace(/\.\d{3}Z$/, "Z")}`; + return redact(line, [], 400); +} + +/** Accepts only a Better Stack heartbeat URL, so a mis-set secret can't send reports elsewhere. */ +export function heartbeatUrl(raw: string | undefined): URL | undefined { + if (!raw || raw.trim() === "") return undefined; + let url: URL; + try { + url = new URL(raw.trim()); + } catch { + throw new Error("BETTERSTACK_HEARTBEAT_URL is not a URL"); + } + const okHost = url.hostname === "uptime.betterstack.com" || url.hostname === "betteruptime.com" || url.hostname === "incidents.betterstack.com"; + if (url.protocol !== "https:" || !okHost || !/^\/api\/v1\/heartbeat\/[A-Za-z0-9_-]+\/?$/.test(url.pathname) || url.search) { + throw new Error("BETTERSTACK_HEARTBEAT_URL is not a Better Stack heartbeat URL"); + } + return url; +} + +export type Fetch = (input: string, init?: RequestInit) => Promise; + +/** Outcome of a heartbeat call; `line` is safe to log (never the URL). */ +export type Delivery = { ok: boolean; line: string }; + +/** Sends the ping or `/fail`. Only a 2xx counts as delivered. */ +export async function report(action: "ping" | "fail", url: URL | undefined, body: string | undefined, fetchFn: Fetch): Promise { + if (!url) return { ok: true, line: `heartbeat ${action} skipped: BETTERSTACK_HEARTBEAT_URL not set` }; + const target = action === "fail" ? `${url.toString().replace(/\/$/, "")}/fail` : url.toString(); + try { + const res = await fetchFn(target, { + method: action === "fail" ? "POST" : "GET", + ...(action === "fail" ? { body, headers: { "content-type": "text/plain" } } : {}), + signal: AbortSignal.timeout(REPORT_TIMEOUT_MS), + }); + return res.ok + ? { ok: true, line: `heartbeat ${action} sent: HTTP ${res.status}` } + : { ok: false, line: `heartbeat ${action} NOT accepted: HTTP ${res.status}` }; + } catch (error) { + return { ok: false, line: `heartbeat ${action} NOT delivered: ${classify(error)}` }; + } +} + +/** Node build from public /version, or a short reason it's unknown. */ +export async function nodeBuild(host: string, fetchFn: Fetch): Promise { + try { + const res = await fetchFn(`${host.replace(/\/$/, "")}/version`, { signal: AbortSignal.timeout(5_000) }); + if (!res.ok) return `unknown(HTTP ${res.status})`; + const version = field(await res.json(), "version"); + return typeof version === "string" && /^[0-9A-Za-z.+-]{1,40}$/.test(version) ? version : "unknown"; + } catch (error) { + return `unknown(${classify(error)})`; + } +} + +// ---- the read check -------------------------------------------------------------- + +/** What the probe needs from a TinyCloud client; the real one wraps TinyCloudNode. */ +export interface ReadClient { + signIn(): Promise; + ensureSpace(): Promise; + /** Signed-in read of the fixed KV key (provisions it once if absent). */ + kvRead(): Promise; + /** Signed-in tiny SQL select of the fixed row (provisions it once if absent). */ + sqlRead(): Promise; +} + +export type Logger = (line: string) => void; + +/** Delivers the decided ping or `/fail`; `failure` is the stage named in the `/fail` body. */ +export type Deliver = (action: "ping" | "fail", failure: StageResult | undefined, consecutive: number) => Promise; + +export type Settled = { state: ProbeState; action: Decision["action"]; delivered: boolean }; + +/** + * decide() + delivery. A `/fail` only starts its rate-limit window once + * Better Stack accepted it, so a rejected report is retried on the next sample. + */ +export async function settle(prev: ProbeState, results: readonly StageResult[], nowMs: number, deliver: Deliver): Promise { + const d = decide(prev, results, nowMs); + if (d.action === "none") return { state: d.state, action: d.action, delivered: true }; + const { ok } = await deliver(d.action, d.failure, d.consecutive); + const state = d.action === "fail" && ok ? { ...d.state, lastFailReportAt: new Date(nowMs).toISOString() } : d.state; + return { state, action: d.action, delivered: ok }; +} + +export type ReadCheckResult = { results: StageResult[]; failure?: StageResult }; + +/** + * Normal (scheduled) mode, read half: sign in, ensure the space, KV read, SQL + * read — each under the 20 s deadline. Stops at the first failure, which is + * the one named in the `/fail` body. + */ +export async function readCheck( + client: ReadClient, + opts: { + log: Logger; + secrets: readonly string[]; + mode?: string; + sample?: number; + slowMs?: number; + deadlineMs?: number; + stages?: readonly ReadStage[]; + /** Clock for stage durations (tests drive it; default performance.now). */ + now?: () => number; + }, +): Promise { + const deadlineMs = opts.deadlineMs ?? STAGE_DEADLINE_MS; + const slowMs = opts.slowMs ?? deadlineMs; + const mode = opts.mode ?? "normal"; + const sample = opts.sample ?? 1; + const all: [ReadStage, () => Promise, number][] = [ + ["signin", () => client.signIn(), deadlineMs], + ["space", () => client.ensureSpace(), deadlineMs], + ["kv", () => client.kvRead(), slowMs], + ["sql", () => client.sqlRead(), slowMs], + ]; + const wanted = opts.stages ?? ["signin", "space", "kv", "sql"]; + const results: StageResult[] = []; + for (const [stage, fn, stageSlow] of all) { + if (!wanted.includes(stage)) continue; + const r = await measure(stage, fn, { + deadlineMs, + now: opts.now, + slowMs: stageSlow, + onError: (e) => opts.log(`[probe] mode=${mode} sample=${sample} stage=${stage} error: ${detail(e, opts.secrets)}`), + }); + opts.log( + `[probe] mode=${mode} sample=${sample} stage=${r.stage} ms=${r.ms} threshold_ms=${stageSlow} result=${r.ok ? "ok" : "fail"} outcome="${r.outcome}"`, + ); + results.push(r); + if (!r.ok) return { results, failure: r }; + } + return { results }; +} + +export type DenseSample = { sample: number; at: string; results: StageResult[]; ok: boolean }; +export type DenseResult = { samples: DenseSample[]; state: ProbeState; undelivered: number }; + +/** + * Dense promote watch. One sign-in (retried on the next sample if it fails), + * then reads on DENSE_SCHEDULE. Under a 60 s interval each sample reads ONE of + * KV/SQL alternately, so each sees at most one request per 30 s; otherwise both. + * A read over DENSE_SLOW_MS or failing counts. Starts from, and hands back + * through `onState`, the same per-target state as normal mode. + */ +export async function denseWatch( + client: ReadClient, + opts: { + log: Logger; + secrets: readonly string[]; + deliver: Deliver; + initialState?: ProbeState; + onState?: (state: ProbeState) => Promise; + schedule?: readonly Phase[]; + slowMs?: number; + deadlineMs?: number; + sleep?: (ms: number) => Promise; + clock?: () => number; + }, +): Promise { + const schedule = opts.schedule ?? DENSE_SCHEDULE; + const slowMs = opts.slowMs ?? DENSE_SLOW_MS; + const sleep = opts.sleep ?? ((ms: number) => new Promise((r) => setTimeout(r, ms))); + const clock = opts.clock ?? (() => Date.now()); + const samples: DenseSample[] = []; + let state = opts.initialState ?? INITIAL_STATE; + let undelivered = 0; + let signedIn = false; + let next = clock(); + let n = 0; + for (const phase of schedule) { + for (let i = 0; i < phase.count; i++) { + const wait = next - clock(); + if (wait > 0) await sleep(wait); + n += 1; + const reads: ReadStage[] = phase.intervalMs < 60_000 ? [n % 2 === 1 ? "kv" : "sql"] : ["kv", "sql"]; + const stages: ReadStage[] = signedIn ? reads : ["signin", "space", ...reads]; + const at = new Date(clock()).toISOString(); + const { results, failure } = await readCheck(client, { + log: opts.log, + secrets: opts.secrets, + mode: "dense", + sample: n, + slowMs, + deadlineMs: opts.deadlineMs, + now: opts.clock, + stages, + }); + if (!signedIn && results.some((r) => r.stage === "space" && r.ok)) signedIn = true; + const settled = await settle(state, results, clock(), opts.deliver); + state = settled.state; + if (!settled.delivered) undelivered += 1; + opts.log(`[probe] mode=dense sample=${n} failures_kv=${state.failures.kv} failures_sql=${state.failures.sql} heartbeat_action=${settled.action}`); + await opts.onState?.(state); + samples.push({ sample: n, at, results, ok: !failure }); + next += phase.intervalMs; + } + } + return { samples, state, undelivered }; +} + +/** Markdown for $GITHUB_STEP_SUMMARY: every sample's latency. */ +export function summaryTable(title: string, samples: readonly DenseSample[]): string { + const rows = samples.flatMap((s) => + s.results.map((r) => `| ${s.sample} | ${s.at.replace(/\.\d{3}Z$/, "Z")} | ${r.stage} | ${r.ms} | ${r.ok ? "ok" : "FAIL"} | ${r.outcome} |`), + ); + const failed = samples.filter((s) => !s.ok).length; + return [ + `### ${title}`, + "", + `${samples.length} sample(s), ${failed} failed.`, + "", + "| sample | time (UTC) | stage | ms | result | outcome |", + "|---:|---|---|---:|---|---|", + ...rows, + "", + ].join("\n"); +} diff --git a/test/probe/tsconfig.json b/test/probe/tsconfig.json index 9a320c7d..f0d40d33 100644 --- a/test/probe/tsconfig.json +++ b/test/probe/tsconfig.json @@ -3,13 +3,24 @@ "target": "ES2022", "module": "ESNext", "moduleResolution": "node", - "typeRoots": ["./node_modules/@types"], - "lib": ["ES2022", "DOM"], + "typeRoots": [ + "./node_modules/@types" + ], + "lib": [ + "ES2022", + "DOM" + ], "strict": true, "esModuleInterop": true, "skipLibCheck": true, "noEmit": true, - "types": ["node"] + "types": [ + "node" + ] }, - "include": ["write-probe.ts"] + "include": [ + "write-probe.ts", + "probe-core.ts", + "probe-core.test.ts" + ] } diff --git a/test/probe/write-probe.ts b/test/probe/write-probe.ts index 83f5459a..0257202e 100644 --- a/test/probe/write-probe.ts +++ b/test/probe/write-probe.ts @@ -1,53 +1,71 @@ /** - * TC-313: Synthetic end-to-end WRITE probe for the TinyCloud prod node. + * TC-313 + TC-1176: synthetic end-to-end probe for the TinyCloud prod node. * * WHY THIS EXISTS * --------------- - * During the 2026-07-27/28 write-degradation incident, `/healthz` kept - * returning 200 in ~300ms while `kv.put` took 46s and `/delegate` blew past - * Cloudflare's 100s ceiling. Monitoring was blind because `/healthz` and - * `/version` never touch the database or the write path. This probe closes - * that gap: it drives a REAL signed, end-to-end write against the live node - * and fails (which is the alert) when any stage crosses a latency threshold. + * 2026-07-27/28 (TC-313): `/healthz` returned 200 in ~300ms while `kv.put` + * took 46s and `/delegate` blew past Cloudflare's 100s ceiling. + * 2026-10-14 (TC-1176): signed-in KV reads and SQL hung ~62s (504) for every + * account while `/healthz`, `/version`, 401s and writes stayed green. This + * probe failed twice during that window and nobody was paged. * - * WHAT IT MEASURES (each stage timed independently) - * ------------------------------------------------- - * 1. signIn - SIWE sign-in + delegation activation (the /delegate path - * that was worst-hit in the incident). - * 2. kv.put - write a small value. - * 3. kv.get - read it back and verify the bytes round-trip. - * 4. kv.delete - clean up so the probe space never accumulates data. + * WHAT IT DOES (normal mode, every scheduled run) + * ----------------------------------------------- + * Read half — the alerting signal. Each stage has a hard 20s client deadline: + * signin SIWE sign-in + delegation activation + * space ensure the probe's own space exists (idempotent) + * kv signed-in read of a fixed key (written once, on first run) + * sql signed-in `SELECT` of a fixed row (created once, on first run) + * A good read pings the Better Stack heartbeat. A failed read is counted in a + * state file; from the 2nd failure in a row the probe POSTs the heartbeat's + * `/fail` URL with one line naming the stage, outcome, duration, node build + * and UTC time (see probe-core.ts `failBody`). * - * THRESHOLDS (see THRESHOLDS_MS below; override via env) - * ------------------------------------------------------ - * signIn > 15s -> fail. The incident showed /delegate as the first thing - * to blow the CF ceiling; 15s is well under the 100s wall - * but far above a healthy (~1-3s) activation. - * kv.put > 5s -> fail. Healthy puts are sub-second; 5s means the write - * path is degrading before users hit a hard failure. - * kv.get > 5s -> fail. Same rationale on the read path. - * kv.delete > 5s -> fail. Delete also exercises the write path. + * Write half — TC-313's original round-trip (put -> get -> delete), each with + * its latency threshold and the same 20s deadline. A breach fails the job + * (GitHub e-mail) but does not touch the heartbeat. * - * A non-zero exit fails the GitHub Actions job; a failed scheduled job IS the - * alert (GitHub emails the configured recipients). No always-on infra added. + * DENSE MODE (`PROBE_MODE=dense`, the post-promote watch) + * -------------------------------------------------------- + * Reads every 30s for 5 min, then every 5 min for 60 min; a read over 5s or + * any failure counts, 2 in a row POST `/fail`. See probe-core.ts `denseWatch`. * * IDENTITY / SECRETS * ------------------ - * The private key comes from the PROBE_PRIVATE_KEY env var (a GH secret) and - * is NEVER hardcoded. It must be a THROWAWAY key operating in its own probe - * space (the PREFIX below) so the probe never reads or writes user data. + * PROBE_PRIVATE_KEY (GitHub secret) is a THROWAWAY key operating only in its + * own probe space (PREFIX). BETTERSTACK_HEARTBEAT_URL (GitHub secret) is the + * heartbeat's secret URL. Neither is ever printed: errors are reduced to a + * classified outcome and raw details are redacted. */ +import { mkdir, readFile, writeFile, appendFile } from "node:fs/promises"; +import { dirname } from "node:path"; import { TinyCloudNode } from "@tinycloud/node-sdk"; +import { + STAGE_DEADLINE_MS, + denseWatch, + detail, + failBody, + heartbeatUrl, + measure, + nodeBuild, + parseState, + readCheck, + report, + settle, + summaryTable, + type Deliver, + type ProbeState, + type ReadClient, + type StageResult, +} from "./probe-core"; // ---- configuration (env-overridable) --------------------------------------- // The workflow wires optional overrides straight from secrets/vars, which // arrive as EMPTY STRINGS when unset — and `??` only falls back on -// null/undefined, so `"" ?? default` keeps the empty string. Treat blank -// (whitespace-only) env values as absent, otherwise HOST/PREFIX go empty -// (sign-in fails: "Space name cannot be empty") and Number("") coerces every -// threshold to 0 (instant breach). +// null/undefined. Treat blank values as absent, otherwise HOST/PREFIX go empty +// and Number("") coerces every threshold to 0 (instant breach). function envStr(name: string, fallback: string): string { const v = process.env[name]; return v !== undefined && v.trim() !== "" ? v : fallback; @@ -62,135 +80,216 @@ function envMs(name: string, fallback: number): number { return n; } -const HOST = envStr("PROBE_HOST", "https://node.tinycloud.xyz"); -// Dedicated, isolated space prefix for the probe identity. Never shared with -// any user-facing app prefix. +const MODE = envStr("PROBE_MODE", "normal"); +// `force_failure` dispatch input: a host under the reserved .invalid TLD, so +// the run fails at DNS and exercises the alert path end to end. +const FORCED_FAILURE_HOST = "https://read-probe-forced-failure.invalid"; +const HOST = envStr("PROBE_FORCE_FAILURE", "") === "true" ? FORCED_FAILURE_HOST : envStr("PROBE_HOST", "https://node.tinycloud.xyz"); +// Dedicated, isolated space prefix for the probe identity. const PREFIX = envStr("PROBE_PREFIX", "tc313-write-probe"); +const STATE_FILE = envStr("PROBE_STATE_FILE", ".state/probe-state.json"); -const THRESHOLDS_MS = { - signIn: envMs("PROBE_THRESHOLD_SIGNIN_MS", 15_000), +const WRITE_THRESHOLDS_MS = { put: envMs("PROBE_THRESHOLD_PUT_MS", 5_000), get: envMs("PROBE_THRESHOLD_GET_MS", 5_000), delete: envMs("PROBE_THRESHOLD_DELETE_MS", 5_000), } as const; -type Stage = keyof typeof THRESHOLDS_MS; +// The fixed read targets. Written once by the probe itself, then only read. +const FIXED_KEY = "read-probe/fixed"; +const FIXED_VALUE = "tc1176-read-probe-v1"; +const SQL_SELECT = "SELECT v FROM read_probe WHERE id = 1"; -// ---- helpers --------------------------------------------------------------- - -interface StageResult { - stage: Stage; - ms: number; - threshold: number; - breached: boolean; -} - -async function timed( - stage: Stage, - fn: () => Promise, -): Promise<{ value: T; result: StageResult }> { - const start = performance.now(); - const value = await fn(); - const ms = Math.round(performance.now() - start); - const threshold = THRESHOLDS_MS[stage]; - const breached = ms > threshold; - const flag = breached ? "SLOW" : "ok"; - console.log( - `[probe] ${stage.padEnd(8)} ${String(ms).padStart(6)}ms (threshold ${threshold}ms) ${flag}`, - ); - return { value, result: { stage, ms, threshold, breached } }; +class ReadBackMismatch extends Error { + constructor(what: string) { + super(`${what} read-back did not match the fixed value`); + this.name = "ReadBackMismatch"; + } } type Result = { ok: true; data: T } | { ok: false; error: unknown }; -/** - * Unwrap a Result-typed SDK response. We do NOT swallow errors or add a - * graceful fallback: a failed KV op must surface loudly and fail the probe, - * exactly like a threshold breach would. - */ -function unwrap(label: string, result: Result): T { - if (!result.ok) { - throw new Error(`[probe] ${label} failed: ${JSON.stringify(result.error)}`); - } +// A failed SDK call surfaces as its ServiceError (code, meta.status, cause), +// which classify() turns into "HTTP 504", "connection refused", "DNS", ... +function unwrap(result: Result): T { + if (!result.ok) throw result.error; return result.data; } -// ---- probe ----------------------------------------------------------------- +function errorCode(result: Result): string | undefined { + if (result.ok || !result.error || typeof result.error !== "object" || !("code" in result.error)) return undefined; + return typeof result.error.code === "string" ? result.error.code : undefined; +} + +function sdkClient(node: TinyCloudNode): ReadClient { + let kvProvisioned = false; + let sqlProvisioned = false; + return { + signIn: () => node.signIn(), + ensureSpace: async () => { + await node.hostOwnedSpace(PREFIX); + }, + async kvRead() { + let got = await node.kv.get(FIXED_KEY); + if (errorCode(got) === "KV_NOT_FOUND" && !kvProvisioned) { + kvProvisioned = true; + unwrap(await node.kv.put(FIXED_KEY, FIXED_VALUE)); + got = await node.kv.get(FIXED_KEY); + } + if (unwrap<{ data: unknown }>(got).data !== FIXED_VALUE) throw new ReadBackMismatch("kv"); + }, + async sqlRead() { + // Rows are arrays of cell values ({ columns, rows: unknown[][], rowCount }). + let rows = await node.sql.query(SQL_SELECT); + const missing = ["SQL_ERROR", "SQL_DATABASE_NOT_FOUND"].includes(errorCode(rows) ?? "") || (rows.ok && rows.data.rowCount === 0); + if (missing && !sqlProvisioned) { + sqlProvisioned = true; + unwrap(await node.sql.execute("CREATE TABLE IF NOT EXISTS read_probe (id INTEGER PRIMARY KEY, v TEXT NOT NULL)")); + unwrap(await node.sql.execute("INSERT OR REPLACE INTO read_probe (id, v) VALUES (1, ?)", [FIXED_VALUE])); + rows = await node.sql.query(SQL_SELECT); + } + if (unwrap(rows).rows[0]?.[0] !== FIXED_VALUE) throw new ReadBackMismatch("sql"); + }, + }; +} -async function main(): Promise { - const privateKey = process.env.PROBE_PRIVATE_KEY; - if (!privateKey) { - throw new Error( - "PROBE_PRIVATE_KEY is not set. Set it as a GitHub Actions secret " + - "(a throwaway key in its own probe space). See test/probe/README.md.", - ); - } +async function writeSummary(markdown: string): Promise { + const path = process.env.GITHUB_STEP_SUMMARY; + if (path) await appendFile(path, `${markdown}\n`); +} - console.log(`[probe] target host: ${HOST}`); - console.log(`[probe] space prefix: ${PREFIX}`); +// The per-target failure state is shared by normal and dense runs: the Actions +// cache carries this file from one run to the next, whichever mode it is. +async function loadState(): Promise { + return parseState(await readFile(STATE_FILE, "utf8").catch(() => undefined)); +} +async function saveState(state: ProbeState): Promise { + await mkdir(dirname(STATE_FILE), { recursive: true }); + await writeFile(STATE_FILE, `${JSON.stringify(state)}\n`); +} - const node = new TinyCloudNode({ privateKey, host: HOST, prefix: PREFIX }); +// ---- normal (scheduled) run ---------------------------------------------------- + +async function normalRun(node: TinyCloudNode, client: ReadClient, deliver: Deliver, secrets: string[]): Promise { + const log = (line: string) => console.log(line); + const { results, failure } = await readCheck(client, { log, secrets }); - const key = `probe/${Date.now()}`; - const value = `tc313-${Date.now()}`; - const results: StageResult[] = []; - - // 1. Sign-in + delegation activation (worst-hit path in the incident). - results.push((await timed("signIn", () => node.signIn())).result); - - // 1b. Ensure the probe's own space exists. A brand-new probe identity has no - // space yet, so the first write 404s "space not found"; hostOwnedSpace is - // idempotent (fast no-op once the space exists) and returns the space id. - // This is provisioning, not the steady-state write we alert on, so we time - // and log it but do NOT threshold-gate it — a genuine failure throws and - // still fails the probe. (Do not branch on the return value: it is the space - // id string on success and throws on failure, never a falsy sentinel.) - const ensureStart = performance.now(); - const spaceId = await node.hostOwnedSpace(PREFIX); + const settled = await settle(await loadState(), results, Date.now(), deliver); console.log( - `[probe] ${"ensure".padEnd(8)} ${String(Math.round(performance.now() - ensureStart)).padStart(6)}ms -> ${spaceId}`, + `[probe] read verdict=${failure ? "fail" : "ok"} failures_kv=${settled.state.failures.kv} failures_sql=${settled.state.failures.sql} heartbeat_action=${settled.action}`, ); + await saveState(settled.state); - // 2. Write a small value. - results.push( - (await timed("put", async () => unwrap("kv.put", await node.kv.put(key, value)))) - .result, - ); + // Write half (TC-313). Needs a signed-in session in an existing space. + const writes: StageResult[] = []; + if (!failure || (failure.stage !== "signin" && failure.stage !== "space")) { + const key = `probe/${Date.now()}`; + const value = `tc313-${Date.now()}`; + const stages: [keyof typeof WRITE_THRESHOLDS_MS, () => Promise][] = [ + ["put", async () => unwrap(await node.kv.put(key, value))], + [ + "get", + async () => { + if (unwrap<{ data: unknown }>(await node.kv.get(key)).data !== value) throw new ReadBackMismatch("write round-trip"); + }, + ], + ["delete", async () => unwrap(await node.kv.delete(key))], + ]; + for (const [stage, fn] of stages) { + const threshold = WRITE_THRESHOLDS_MS[stage]; + const r = await measure(`write.${stage}`, fn, { + slowMs: threshold, + onError: (e) => console.log(`[probe] mode=normal sample=1 stage=write.${stage} error: ${detail(e, secrets)}`), + }); + console.log( + `[probe] mode=normal sample=1 stage=${r.stage} ms=${r.ms} threshold_ms=${threshold} result=${r.ok ? "ok" : "fail"} outcome="${r.outcome}"`, + ); + writes.push(r); + if (!r.ok) break; + } + } - // 3. Read it back and verify the round-trip. - const { value: readBack, result: getResult } = await timed("get", async () => - unwrap<{ data: unknown }>("kv.get", await node.kv.get(key)), - ); - results.push(getResult); - if (readBack?.data !== value) { - throw new Error( - `[probe] readback mismatch: wrote ${JSON.stringify(value)} but read ${JSON.stringify( - readBack?.data, - )}`, - ); + const all = [...results, ...writes]; + await writeSummary(summaryTable("Write Probe (normal)", [{ sample: 1, at: new Date().toISOString(), results: all, ok: all.every((r) => r.ok) }])); + const breaches = all.filter((r) => !r.ok); + if (breaches.length > 0) { + console.error(`[probe] FAIL: ${breaches.map((b) => `${b.stage} ${b.outcome} (${b.ms}ms)`).join(", ")}`); + return false; + } + if (!settled.delivered) { + // Healthy reads but Better Stack didn't take the ping: fail the job so the + // gap shows before the heartbeat goes "missed". + console.error("[probe] FAIL: heartbeat report was not accepted"); + return false; } + console.log("[probe] PASS: reads and writes within thresholds"); + return true; +} - // 4. Clean up. - results.push( - (await timed("delete", async () => unwrap("kv.delete", await node.kv.delete(key)))) - .result, - ); +// ---- main ---------------------------------------------------------------------- - // ---- verdict ------------------------------------------------------------- - const breaches = results.filter((r) => r.breached); - if (breaches.length > 0) { - console.error( - `[probe] FAIL: ${breaches.length} stage(s) exceeded threshold: ` + - breaches.map((b) => `${b.stage}=${b.ms}ms>${b.threshold}ms`).join(", "), - ); - process.exit(1); +async function main(): Promise { + const privateKey = process.env.PROBE_PRIVATE_KEY; + if (!privateKey) { + console.error("[probe] PROBE_PRIVATE_KEY is not set (a throwaway key in its own probe space). See test/probe/README.md."); + return 1; + } + const mode = MODE === "normal" || MODE === "dense" ? MODE : undefined; + if (!mode) { + console.error(`[probe] PROBE_MODE must be "normal" or "dense"`); + return 1; + } + const rawHeartbeat = process.env.BETTERSTACK_HEARTBEAT_URL; + const secrets = [privateKey, privateKey.replace(/^0x/, ""), rawHeartbeat ?? ""]; + let hbUrl: URL | undefined; + let configOk = true; + try { + hbUrl = heartbeatUrl(rawHeartbeat); + } catch (error) { + // The message names the problem, never the value. + console.error(`[probe] ${error instanceof Error ? error.message : "invalid BETTERSTACK_HEARTBEAT_URL"}; heartbeat reporting disabled for this run`); + configOk = false; + } + if (hbUrl) secrets.push(hbUrl.pathname.split("/").filter(Boolean).pop() ?? ""); + + console.log(`[probe] mode=${MODE} host=${HOST} space_prefix=${PREFIX} stage_deadline_ms=${STAGE_DEADLINE_MS} heartbeat=${hbUrl ? "configured" : "not configured"}`); + + const deliver: Deliver = async (action, failure, consecutive) => { + const body = + action === "fail" && failure + ? failBody({ mode, consecutive, failure, build: await nodeBuild(HOST, fetch), host: new URL(HOST).host, at: new Date() }) + : undefined; + if (body) console.log(`[probe] fail report body: ${body}`); + const delivery = await report(action, hbUrl, body, fetch); + console.log(`[probe] ${delivery.line}`); + return delivery; + }; + + const node = new TinyCloudNode({ privateKey, host: HOST, prefix: PREFIX }); + const client = sdkClient(node); + + if (mode === "dense") { + const { samples, undelivered } = await denseWatch(client, { + log: (line) => console.log(line), + secrets, + deliver, + initialState: await loadState(), + onState: saveState, + }); + await writeSummary(summaryTable("Write Probe promote watch (dense)", samples)); + const failed = samples.filter((s) => !s.ok).length; + console.log(`[probe] dense watch done: ${samples.length} samples, ${failed} failed, ${undelivered} heartbeat report(s) not accepted`); + return failed === 0 && undelivered === 0 && configOk ? 0 : 1; } - console.log("[probe] PASS: all stages within thresholds"); + return (await normalRun(node, client, deliver, secrets)) && configOk ? 0 : 1; } -main().catch((err) => { - // No graceful fallback: any error (network, auth, mismatch) fails the probe - // so the scheduled job goes red and GitHub sends the failure notification. - console.error(err instanceof Error ? (err.stack ?? err.message) : String(err)); - process.exit(1); -}); +// Deadlines leave SDK requests running in the background; exit explicitly so a +// hung request can't keep the process (and the job) alive. +main().then( + (code) => process.exit(code), + (err: unknown) => { + console.error(`[probe] crashed: ${detail(err, [process.env.PROBE_PRIVATE_KEY ?? "", process.env.BETTERSTACK_HEARTBEAT_URL ?? ""])}`); + process.exit(1); + }, +);