diff --git a/.github/workflows/deploy-bunny-js.yml b/.github/workflows/deploy-bunny-js.yml index 132bc3e49..a416eb899 100644 --- a/.github/workflows/deploy-bunny-js.yml +++ b/.github/workflows/deploy-bunny-js.yml @@ -8,7 +8,8 @@ name: Deploy Bunny JS twins # # This workflow ships CODE only. Each script's environment (BRAVE_API_KEY, # MISTRAL_API_KEY, the receiver authorizer key, the S3 channel-store credentials, RPC -# URLs, SEARCH_SERVICE_URL) is configured on the script itself — bunny dashboard or +# URLs, SEARCH_SERVICE_URL, the Cockpit observability pair SCW_COCKPIT_PUSH_TOKEN + +# COCKPIT_LOKI_URL) is configured on the script itself — bunny dashboard or # `bunny scripts env set` — and is deliberately not part of CI: a repo leak must not be # a secrets leak. # diff --git a/bunny_js/README.md b/bunny_js/README.md index c31dacc1f..89ad7c51d 100644 --- a/bunny_js/README.md +++ b/bunny_js/README.md @@ -19,8 +19,12 @@ Only `scw_js`'s `llmx402cron` remains, claiming the channels these twins charge. the shared seller stack (`x402_server.ts`, channel storage/sync), the services (`search_service.ts`, `web_fetch_service.ts` with the SSRF defence), schemas, discovery, favicon, `openapi.search.json`. Two deliberate deviations: - - `logger.ts` is a pino-shaped console shim — pino is a Node-runtime library; bunny logs go - to the dashboard, and the observability `logger.error` alert convention does not apply. + - `logger.ts` is a pino-shaped console shim — pino is a Node-runtime library; the lines go to + the bunny dashboard AND, since the Cockpit integration, to Scaleway's custom Loki data + source: `withLogFlush()` wraps each entry handler, so buffered lines are pushed per + request to Cockpit, where one datasource-managed alert rule on `level="error"` pages by + email (the `logger.error` convention applies again — see + [`observability/bunny-edge-script-observability-kiss-implementation-plan.md`](../observability/bunny-edge-script-observability-kiss-implementation-plan.md)). - `utils.ts` ports only the platform-neutral half (CORS/parseJsonBody); the ScwResponse envelope helpers are not ported — there is no Scaleway envelope here. - `src/runtime-shims.ts` — pins the Node `Buffer`/`process` globals the ported code assumes, @@ -66,6 +70,8 @@ it is inert without another credential, plain — and plain stays inspectable wh | `FACILITATOR_URL` | plain (code default ok) | `https://facilitator.fretchen.eu` | | `LLM_WITHDRAW_DELAY_SECONDS` | plain (code default ok) | 86400 — must match production | | `SEARCH_SERVICE_URL` | plain | advertised `resource.url` base; the bunny trial URL while trialing, production default otherwise | +| `SCW_COCKPIT_PUSH_TOKEN` | secret (`--secret`) | Cockpit push-only token — authenticates the Loki log flush to the observability data source (see the observability README/implementation plan) | +| `COCKPIT_LOKI_URL` | plain | push URL of the custom Cockpit logs data source — public and inert without the token | ## Known limits / decisions @@ -158,8 +164,10 @@ and the `.bunny/script.json` link comes out of the create step. One-time sequenc other twins take their id from the create output (or `bunny scripts list`) instead. 2. Upload the env from `.env` with `bunny scripts env set`, marking the sensitive keys with `--secret` (RECEIVER_AUTHORIZER_PRIVATE_KEY, BRAVE_API_KEY, MISTRAL_API_KEY, - SCW_ACCESS_KEY, SCW_SECRET_KEY, RPC_URL_*). Skip `TEST_WALLET_PRIVATE_KEY` — buyer-side - only, the server must never see it. Verify with `bunny scripts env list`. Per script: + SCW_ACCESS_KEY, SCW_SECRET_KEY, RPC_URL_*, SCW_COCKPIT_PUSH_TOKEN). Skip + `TEST_WALLET_PRIVATE_KEY` — buyer-side only, the server must never see it. Verify with + `bunny scripts env list`. Per script — all three also get the Cockpit observability pair + (`SCW_COCKPIT_PUSH_TOKEN` as `--secret`, `COCKPIT_LOKI_URL` plain): - **searchapi** — the channel stack + `BRAVE_API_KEY` (web_search/fetch) + `SCW_S3_*`. - **llm** — the channel stack + `MISTRAL_API_KEY` (chat_completion) + `SCW_S3_*`. - **mcp** — the union: both `BRAVE_API_KEY` and `MISTRAL_API_KEY` (its bundle embeds diff --git a/bunny_js/src/llm.ts b/bunny_js/src/llm.ts index 30b076188..7dbcd41c8 100644 --- a/bunny_js/src/llm.ts +++ b/bunny_js/src/llm.ts @@ -7,6 +7,7 @@ */ import "./runtime-shims.js"; import * as BunnySDK from "@bunny.net/edgescript-sdk"; +import { withLogFlush } from "./logger.js"; import { handleLLMRequest } from "./llm_routes.js"; -BunnySDK.net.http.serve(handleLLMRequest); +BunnySDK.net.http.serve(withLogFlush("bunny-llm-agent", handleLLMRequest)); diff --git a/bunny_js/src/logger.ts b/bunny_js/src/logger.ts index 8472bec11..928caa58e 100644 --- a/bunny_js/src/logger.ts +++ b/bunny_js/src/logger.ts @@ -4,11 +4,31 @@ * Deno isolate bundle. The call surface is kept pino-shaped — `logger.info(obj, msg)`, * `logger.error({ err }, msg)` — because the ported files use that convention verbatim. * - * The `logger.error` convention (observability alert rules key on it) does not carry over - * to bunny: the edge script's logs live in the bunny dashboard, not Loki, and shipping - * structured logs out is a documented follow-up if this twin graduates. + * On top of the console output (the bunny dashboard's own log view), every line is buffered + * and flushed to Scaleway Cockpit's custom Loki data source at the end of the request + * (observability/bunny-edge-script-observability-kiss-implementation-plan.md), where a + * single datasource-managed alert rule on `level="error"` pages by email — the same + * `logger.error` = "ours, and should be alertable" convention the Scaleway functions have. */ +type BufferedLine = { level: string; event: object }; + +const lines: BufferedLine[] = []; + +/** Per-script `service` label (searchapi/llm/mcp differ); set by withLogFlush at entry setup. */ +let serviceLabel = "bunny-js"; + +/** + * Loki rejects duplicate timestamps within one push (`duplicate timestamp for series`) by + * dropping the whole batch, so a monotonic per-isolate counter keeps same-millisecond lines + * strictly increasing. String concat for the nanosecond part: `Date.now() * 1e6` as a number + * exceeds Number.MAX_SAFE_INTEGER. + */ +let nsCounter = 0; +function nsTimestamp(): string { + return `${Date.now()}${String(++nsCounter).padStart(6, "0")}`; +} + function emit(level: string, arg: unknown, maybeMsg?: string): void { const [obj, msg] = typeof arg === "string" ? [{}, arg] : [(arg as object) ?? {}, maybeMsg ?? ""]; // pino prints `level then message then context`; JSON-lines keeps the same fields. @@ -20,6 +40,80 @@ function emit(level: string, arg: unknown, maybeMsg?: string): void { } else { console.log(line); } + // debug stays console-only — never buffered: the llm twins log { prompt } at + // debug, and user content must not egress to Cockpit. On scw the pino gate + // (LOG_LEVEL ?? "info") suppressed these lines; buffering them here would be + // a NEW egress, not parity with the pre-move setup. + if (level !== "debug") { + lines.push({ level, event: { message: msg, ...obj } }); + } +} + +/** + * Pushes the buffered lines to Cockpit as one Loki batch. Best-effort by design — no retry, + * no queue — but AWAITED when the buffer is non-empty: the edge runtime has no waitUntil, so + * an un-awaited fetch racing the handler's return would be lost most of the time. A failed + * push is console.error'd, so an ingest outage stays visible in the bunny dashboard instead + * of silently eating every alert. Auth is Scaleway's documented `X-Token` header; unpushed + * when URL/token are unset (local dev, tests). + */ +export async function flushLogs(): Promise { + const batch = lines.splice(0); + const url = process.env.COCKPIT_LOKI_URL; + const token = process.env.SCW_COCKPIT_PUSH_TOKEN; + if (batch.length === 0 || !url || !token) { + return; + } + const byLevel = new Map(); + for (const { level, event } of batch) { + const vals = byLevel.get(level) ?? []; + vals.push([nsTimestamp(), JSON.stringify(event)]); + byLevel.set(level, vals); + } + try { + const res = await fetch(url, { + method: "POST", + // A slow/brownout Cockpit must not stall every logged request: the flush is + // awaited precisely because the runtime has no waitUntil, and this timeout + // is what keeps that await from becoming a latency coupling to ingest + // health. An abort lands in the catch below like any other failure. + signal: AbortSignal.timeout(1500), + // Labels stay {service, level} only — high-cardinality labels are the classic Loki trap. + headers: { "X-Token": token, "Content-Type": "application/json" }, + body: JSON.stringify({ + streams: [...byLevel].map(([level, values]) => ({ + stream: { service: serviceLabel, level }, + values, + })), + }), + }); + if (!res.ok) { + console.error( + JSON.stringify({ level: "error", msg: "log flush failed", status: res.status }), + ); + } + } catch (err) { + console.error(JSON.stringify({ level: "error", msg: "log flush failed", err: String(err) })); + } +} + +/** + * Wraps a script entry handler so the buffered lines reach Cockpit however the request ended — + * early returns (OPTIONS, discovery, the 404, the unpaid 402) and throws alike, which is why + * this wraps the entry's top-level handler instead of touching any route file's returns. + */ +export function withLogFlush( + service: string, + handler: (request: Request) => Promise, +): (request: Request) => Promise { + serviceLabel = service; + return async (request: Request): Promise => { + try { + return await handler(request); + } finally { + await flushLogs(); + } + }; } export const logger = { diff --git a/bunny_js/src/mcp.ts b/bunny_js/src/mcp.ts index d7a159987..e240a262c 100644 --- a/bunny_js/src/mcp.ts +++ b/bunny_js/src/mcp.ts @@ -7,6 +7,7 @@ */ import "./runtime-shims.js"; import * as BunnySDK from "@bunny.net/edgescript-sdk"; +import { withLogFlush } from "./logger.js"; import { handleMCPRequest } from "./mcp_routes.js"; -BunnySDK.net.http.serve(handleMCPRequest); +BunnySDK.net.http.serve(withLogFlush("bunny-mcp-agent", handleMCPRequest)); diff --git a/bunny_js/src/searchapi.ts b/bunny_js/src/searchapi.ts index c4c353be8..1d6fb8d96 100644 --- a/bunny_js/src/searchapi.ts +++ b/bunny_js/src/searchapi.ts @@ -9,6 +9,7 @@ */ import "./runtime-shims.js"; import * as BunnySDK from "@bunny.net/edgescript-sdk"; +import { withLogFlush } from "./logger.js"; import { handleRequest } from "./searchapi_routes.js"; -BunnySDK.net.http.serve(handleRequest); +BunnySDK.net.http.serve(withLogFlush("bunny-web-agent", handleRequest)); diff --git a/bunny_js/test/logger.test.ts b/bunny_js/test/logger.test.ts new file mode 100644 index 000000000..9ce2849a4 --- /dev/null +++ b/bunny_js/test/logger.test.ts @@ -0,0 +1,226 @@ +import { afterEach, beforeEach, describe, expect, test, vi } from "vitest"; +import { flushLogs, logger, withLogFlush } from "../src/logger.js"; + +// The flush mechanics only — no network. fetch is stubbed per test; env vars are set/cleared +// so a test can exercise both ends deliberately (hermetic even on a machine whose shell +// happens to export COCKPIT_* variables). +const realFetch = globalThis.fetch; +const mockFetch = vi.fn(); + +const TEST_URL = "https://logs.example.invalid/loki/api/v1/push"; + +beforeEach(() => { + mockFetch.mockReset(); + mockFetch.mockResolvedValue({ ok: true, status: 204 }); + globalThis.fetch = mockFetch as unknown as typeof fetch; + process.env.COCKPIT_LOKI_URL = TEST_URL; + process.env.SCW_COCKPIT_PUSH_TOKEN = "test-token"; +}); + +afterEach(async () => { + globalThis.fetch = realFetch; + delete process.env.COCKPIT_LOKI_URL; + delete process.env.SCW_COCKPIT_PUSH_TOKEN; + // Drain whatever a test left behind, with the real fetch restored and no config: a no-op. + await flushLogs(); +}); + +function singlePushBody() { + expect(mockFetch).toHaveBeenCalledTimes(1); + const [calledUrl, init] = mockFetch.mock.calls[0] as [string, RequestInit]; + expect(calledUrl).toBe(TEST_URL); + return { + init, + body: JSON.parse(init.body as string), + }; +} + +describe("flushLogs", () => { + test("batches one Loki push per flush, X-Token-authenticated, with the fields the alert side keys on", async () => { + logger.error({ err: "boom" }, "Request handler error"); + logger.error({ err: "boom2" }, "Paid request handler error"); + await flushLogs(); + + const { init, body } = singlePushBody(); + const headers = init.headers as Record; + expect(headers["X-Token"]).toBe("test-token"); + expect(headers["Content-Type"]).toBe("application/json"); + + // One stream for the two error lines; the alert rule keys on exactly these labels. + expect(body.streams).toHaveLength(1); + const stream = body.streams[0]; + expect(stream.stream).toEqual({ service: "bunny-js", level: "error" }); + expect(stream.values).toHaveLength(2); + expect(JSON.parse(stream.values[0][1])).toEqual({ + message: "Request handler error", + err: "boom", + }); + expect(JSON.parse(stream.values[1][1])).toEqual({ + message: "Paid request handler error", + err: "boom2", + }); + + // pino-shaped string call: the string IS the message. + mockFetch.mockClear(); + logger.warn("brave timeout"); + await flushLogs(); + const second = singlePushBody().body.streams[0]; + expect(second.stream.level).toBe("warn"); + expect(JSON.parse(second.values[0][1])).toEqual({ message: "brave timeout" }); + }); + + test("same-millisecond lines get strictly increasing nanosecond timestamps as strings", async () => { + logger.error({ attempt: 1 }, "same ms"); + logger.error({ attempt: 2 }, "same ms"); + logger.error({ attempt: 3 }, "same ms"); + await flushLogs(); + + const { body } = singlePushBody(); + const [ts1, ts2, ts3] = body.streams[0].values.map(([ts]: [string]) => ts); + expect(ts1).toMatch(/^\d{19}$/); // nanoseconds, not the ms Date.now() would give + expect(BigInt(ts2)).toBeGreaterThan(BigInt(ts1)); + expect(BigInt(ts3)).toBeGreaterThan(BigInt(ts2)); + }); + + test("levels split into separate streams; labels stay {service, level} only", async () => { + logger.info("quiet"); + logger.warn("caller's fault"); + logger.error("ours"); + await flushLogs(); + + const { body } = singlePushBody(); + expect(body.streams).toHaveLength(3); + const byLevel = new Map( + body.streams.map((s: { stream: { level: string } }) => [s.stream.level, s.stream] as const), + ); + expect([...byLevel.keys()].sort()).toEqual(["error", "info", "warn"]); + for (const labels of byLevel.values()) { + expect(Object.keys(labels).sort()).toEqual(["level", "service"]); + } + }); + + test("debug lines are console-only — they never reach the Cockpit buffer", async () => { + // The llm twins log { prompt } at debug; scw's pino gate (LOG_LEVEL ?? "info") + // suppressed those lines pre-move, so shipping them would be a new egress of + // user content, not parity. Regression guard: debug alone must not even fetch. + logger.debug({ prompt: "user's private chat message" }, "Generating answer for prompt"); + await flushLogs(); + expect(mockFetch).not.toHaveBeenCalled(); + + // And mixed with a buffered level, debug stays out of the payload. + logger.debug({ prompt: "another one" }, "Generating answer for prompt"); + logger.info("settlement bookkeeping"); + await flushLogs(); + const { body } = singlePushBody(); + expect(body.streams).toHaveLength(1); + expect(body.streams[0].stream.level).toBe("info"); + expect(body.streams[0].values).toHaveLength(1); + expect(JSON.stringify(body.streams[0].values)).not.toContain("prompt"); + }); + + test("the flush fetch is bounded by an abort signal (timeout regression guard)", async () => { + // The flush is awaited (no waitUntil at the edge), so without a timeout a + // brownout Cockpit stalls every logged request. The fetch init must carry + // an AbortSignal — AbortSignal.timeout(1500) in the implementation. + logger.error({ err: "x" }, "Request handler error"); + await flushLogs(); + const [, init] = mockFetch.mock.calls[0] as [string, RequestInit]; + expect(init.signal).toBeInstanceOf(AbortSignal); + }); + + test("a timed-out (aborted) fetch never throws out of flushLogs, and surfaces in the console", async () => { + mockFetch.mockRejectedValue(new Error("This operation was aborted")); + const consoleError = vi.spyOn(console, "error").mockImplementation(() => {}); + logger.error({ err: "x" }, "Request handler error"); + let failureLine: unknown; + try { + await expect(flushLogs()).resolves.toBeUndefined(); + const failure = consoleError.mock.calls + .map((c) => c[0]) + .find((l) => /log flush failed/.test(String(l))); + expect(failure).toBeDefined(); + failureLine = failure; + } finally { + consoleError.mockRestore(); + } + expect(JSON.parse(failureLine as string)).toMatchObject({ msg: "log flush failed" }); + expect(mockFetch).toHaveBeenCalledTimes(1); + }); + + test("empty buffer sends no fetch at all (the happy-path request stays free)", async () => { + logger.error("seen"); + await flushLogs(); + expect(mockFetch).toHaveBeenCalledTimes(1); + mockFetch.mockClear(); + + await flushLogs(); + expect(mockFetch).not.toHaveBeenCalled(); + }); + + test("a rejected fetch never throws out of flushLogs, and surfaces in the console", async () => { + mockFetch.mockRejectedValue(new Error("network gone")); + const consoleError = vi.spyOn(console, "error").mockImplementation(() => {}); + logger.error({ err: "x" }, "Request handler error"); + try { + await expect(flushLogs()).resolves.toBeUndefined(); + // mockRestore would reset the spy's history — assert while the spy still records. + expect( + consoleError.mock.calls.filter((c) => /log flush failed/.test(String(c[0]))), + ).toHaveLength(1); + } finally { + consoleError.mockRestore(); + } + expect(mockFetch).toHaveBeenCalledTimes(1); + }); + + test("a non-2xx push is reported, and an ingest outage never throws", async () => { + mockFetch.mockResolvedValue({ ok: false, status: 401 }); + const consoleError = vi.spyOn(console, "error").mockImplementation(() => {}); + logger.error({ err: "x" }, "Request handler error"); + let flushFailureLine: unknown; + try { + await expect(flushLogs()).resolves.toBeUndefined(); + const failure = consoleError.mock.calls + .map((c) => c[0]) + .find((l) => /log flush failed/.test(String(l))); + expect(failure).toBeDefined(); + flushFailureLine = failure; + } finally { + consoleError.mockRestore(); + } + expect(JSON.parse(flushFailureLine as string)).toMatchObject({ + msg: "log flush failed", + status: 401, + }); + expect(mockFetch).toHaveBeenCalledTimes(1); + }); +}); + +describe("withLogFlush", () => { + test("flushes when the handler returns early — the wrapper, not per-return call sites", async () => { + const handler = vi.fn(async () => { + logger.error({ path: "/nope" }, "Route not found"); + return new Response("404", { status: 404 }); + }); + const wrapped = withLogFlush("bunny-web-agent", handler); + const res = await wrapped(new Request("https://x.example/nope")); + expect(res.status).toBe(404); + expect(mockFetch).toHaveBeenCalledTimes(1); + + // The per-script service label from the wrapper reaches the stream labels. + const { body } = singlePushBody(); + expect(body.streams[0].stream).toEqual(expect.objectContaining({ service: "bunny-web-agent" })); + }); + + test("flushes even when the handler throws — and does not swallow the error", async () => { + const handler = vi.fn(async () => { + logger.error({ err: "uncaught" }, "Request handler error"); + throw new Error("handler blew up"); + }); + const wrapped = withLogFlush("bunny-mcp-agent", handler); + await expect(wrapped(new Request("https://x.example/"))).rejects.toThrow("handler blew up"); + expect(mockFetch).toHaveBeenCalledTimes(1); + const { body } = singlePushBody(); + expect(body.streams[0].stream).toEqual(expect.objectContaining({ service: "bunny-mcp-agent" })); + }); +}); diff --git a/observability/README.md b/observability/README.md index 0ee4a498d..388336a20 100644 --- a/observability/README.md +++ b/observability/README.md @@ -4,14 +4,19 @@ Project-wide log access and alerting for every Scaleway function in this repo: ` `walletreportcron`, `llmx402cron`, `genimgx402token`, `growthapi`, the comment service and analytics. It belongs to no single service. Cockpit is scoped to the Scaleway _project_, so one token and one set of rules cover all of them. (The llm/search/mcp sellers moved -to bunny_js — Edge Script logging has no Loki rules here.) - -| Path | What | -| ------------------- | -------------------------------------------------------------------------------------------------------- | -| `alerts/*.yaml` | Loki ruler rules. `payments.yaml`: facilitator + claim/refund cron; `services.yaml`: the scw_js services | -| `scripts/logs.ts` | Read any function's logs from the terminal | -| `scripts/alerts.ts` | List / push / delete rule groups (namespace `fretchen`) | -| `alertCoverage.ts` | Parser behind `scw_js/` and `x402_facilitator/`'s `test/alert_coverage.test.ts` | +to bunny_js — they flush per request to a **custom logs data source** (`bunny-logs`) in the same +Cockpit via the Loki push API with a push-only Cockpit token, and their one rule +(`BunnySellersNeedAttention`, on `level="error"`) lives in `alerts/bunny.yaml`, pushed to that +data source's own ruler with `--url` — a ruler rule only sees its own source, so the +default-source rules cannot cover them. Read the bunny data source in Grafana → Explore; +`scripts/logs.ts` still queries only the default (Scaleway) source.) + +| Path | What | +| ------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | +| `alerts/*.yaml` | Loki ruler rules. `payments.yaml`: facilitator + claim/refund cron; `services.yaml`: the scw_js services. `bunny.yaml`: the bunny twins, on the custom data source's own ruler | +| `scripts/logs.ts` | Read any function's logs from the terminal | +| `scripts/alerts.ts` | List / push / delete rule groups (namespace `fretchen`) | +| `alertCoverage.ts` | Parser behind `scw_js/` and `x402_facilitator/`'s `test/alert_coverage.test.ts` | Setup: `npm install`, then create `.env` as described under [Credentials](#credentials). @@ -40,13 +45,17 @@ watch for it directly. npx tsx scripts/alerts.ts # list the rule groups currently on the ruler npx tsx scripts/alerts.ts --push # push alerts/payments.yaml npx tsx scripts/alerts.ts --push alerts/services.yaml +npx tsx scripts/alerts.ts --push alerts/bunny.yaml --url https://db123d37-9094-4e15-badc-706071190ed7.logs.cockpit.fr-par.scw.cloud npx tsx scripts/alerts.ts --delete payments ``` -**Three rules in total, on purpose: Scaleway bills each active alert rule** (€0.015/day, checked +**Four rules in total, on purpose: Scaleway bills each active alert rule** (€0.015/day, checked 2026-10-04), while the phrases a rule matches are free. `services.yaml` holds one rule (`ServicesNeedAttention`) and `payments.yaml` two (`PaymentCronNeedsAttention`, -`FacilitatorNeedsAttention`). A new failure mode is a new alternative in the matching rule's line +`FacilitatorNeedsAttention`) on the default logs source; `bunny.yaml` holds the fourth +(`BunnySellersNeedAttention`) on the custom bunny-logs data source's own ruler — the count was +raised from three deliberately, because no phrase in a default-source rule can see that source's +logs. A new failure mode is a new alternative in the matching rule's line filter, never a new rule; `test/alerts_budget.test.ts` fails if the count grows. The comment at the top of each file explains the budget and what each branch of the filter means. diff --git a/observability/alerts/bunny.yaml b/observability/alerts/bunny.yaml new file mode 100644 index 000000000..f3c3c1bef --- /dev/null +++ b/observability/alerts/bunny.yaml @@ -0,0 +1,45 @@ +# Loki alerting rule for the bunny_js Edge Script twins (searchapi / llm / mcp) — the x402 +# sellers that left scw_js. Same namespace and doctrine as the other files, but pushed to a +# DIFFERENT ruler: the twins flush their logs to the custom `bunny-logs` data source, not the +# default one the Scaleway functions write to, and a ruler rule only ever sees its own data +# source's logs. The push therefore names that source's ruler URL explicitly: +# +# npx tsx scripts/alerts.ts --push alerts/bunny.yaml \ +# --url https://db123d37-9094-4e15-badc-706071190ed7.logs.cockpit.fr-par.scw.cloud +# +# ── ONE RULE, FOURTH OF FOUR (cost) ───────────────────────────────────────────────────── +# Same budget doctrine as services.yaml (every active rule is billed ~€0.015/day, checked +# 2026-10-04). The count was raised from three to four DELIBERATELY: phrases in a rule are +# free, but no phrase can make a rule on the DEFAULT source see this source's logs — the +# twins' phrases were removed from services.yaml when they moved for exactly that reason. +# test/alerts_budget.test.ts pins bunny.yaml at 1 so a fifth rule fails CI, not the bill. +# +# ── Why level="error" and no phrase list ──────────────────────────────────────────────── +# The twins push via the Loki push API with `level` as a REAL stream label, so one label match +# covers every `logger.error` call site (the "ours, and should be alertable" convention) — unlike +# the Scaleway functions, whose lines arrive JSON-encoded inside an envelope, forcing the bare- +# phrase style of services.yaml and its `msg=` trap. WHICH case fired is in the line payload: +# read it with `| json` in Explore. (`service` distinguishes the three twins.) +# +# ── Window ────────────────────────────────────────────────────────────────────────────── +# [1h], like every rule here: the ruler's maximum, and the doctrine that a "resolved" +# notification means "no new occurrence in the last hour", not "fixed". +name: bunny +interval: 1m +rules: + - alert: BunnySellersNeedAttention + expr: | + sum(count_over_time({service=~"bunny-web-agent|bunny-llm-agent|bunny-mcp-agent", level="error"}[1h])) > 0 + for: 0m + labels: + severity: critical + area: services + annotations: + summary: "A bunny Edge Script seller needs attention (searchapi / llm / mcp x402 sellers)" + description: >- + A logger.error line arrived from one of the bunny twins — by convention that is "ours, and + should be alertable" (a caller's fault is logger.warn and does not fire this). Open Explore + on the bunny-logs data source with + {service=~"bunny-web-agent|bunny-llm-agent|bunny-mcp-agent", level="error"} | json and read + the message. A "log flush failed" line means the ingest itself was down; it is + console.error'd to the bunny dashboard too. diff --git a/observability/alerts/services.yaml b/observability/alerts/services.yaml index b540ff268..d5af244c3 100644 --- a/observability/alerts/services.yaml +++ b/observability/alerts/services.yaml @@ -15,8 +15,9 @@ # description and the log line say which phrase fired. # # Covers genimgx402token and growthapi. The claim/refund cron is NOT here; `payments.yaml` owns -# llmx402cron and the facilitator. The llm/search/mcp sellers moved to bunny_js (Edge Script -# logging, no Loki rules) — they no longer appear in any selector here. +# llmx402cron and the facilitator. The llm/search/mcp sellers moved to bunny_js — they no longer +# appear in any selector here, because their logs now live in the custom bunny-logs data source, +# which this ruler cannot see (they are covered by `bunny.yaml`, pushed with --url). # # ── Why now ──────────────────────────────────────────────────────────────────────────────────── # Because /imagegen is a paid, public route: a BFL outage breaks something a stranger has paid diff --git a/observability/bunny-edge-script-observability-kiss-implementation-plan.md b/observability/bunny-edge-script-observability-kiss-implementation-plan.md new file mode 100644 index 000000000..dd5276162 --- /dev/null +++ b/observability/bunny-edge-script-observability-kiss-implementation-plan.md @@ -0,0 +1,133 @@ +# Observability for `bunny_js` — KISS Implementation Plan + +**Architecture:** script logs → Scaleway Cockpit (custom Loki data source, `fr-par`) → datasource-managed alert rule → Scaleway Alert manager → email. +Logs from the remaining Scaleway functions (cron, growthapi, facilitator later) land in the same Cockpit **natively and free** — one Grafana for the whole stack. +No phone push, no webhooks, no self-hosted components, no third-party log vendor. **No uptime/heartbeat layer** — there is none today either (the repo's only "health check" is growth-agent's own `/health` route; nothing ever probes the twins from outside), and log-based alerting alone is the accepted scope. The known blind spot this leaves — "the whole pipeline is dead" produces _no_ error lines, so no alert — is accepted for now (see trade-offs). + +**Why Cockpit over Better Stack:** EU jurisdiction (French company, no CLOUD Act ambiguity); unified view with the Scaleway half of the stack; retention 7 days free vs. Better Stack's 3; ingestion is metered but rounds to ~€0 at this volume (custom-data ingestion is billed per GB; pushing your own data is not free-tier, just negligible here). + +--- + +## 1. Cockpit setup (one-time, ~15 min) + +- [x] Console → **Cockpit → Data sources** → create a custom **logs data source** (`bunny-logs`) in region `fr-par`. Push URL: `https://db123d37-9094-4e15-badc-706071190ed7.logs.cockpit.fr-par.scw.cloud/loki/api/v1/push`. +- [x] Create a **Cockpit token with Push Logs permission** (`push_logs` scope, same region as the data source). Called it `bunny_push_logs`; env var `SCW_COCKPIT_PUSH_TOKEN` (NOT `COCKPIT_LOGS_TOKEN` — `observability/.env` already has `SCW_COCKPIT_LOGS_TOKEN`, the read-only query token; the names must not collide). Lives in `bunny_js/.env`. +- [x] **Alert manager enabled + email contact existing** — already active for the Scaleway functions' ruler rules (they page through it), so the bunny rule reuses it. No new contact needed. +- [x] **Alert rule live — pushed via `scripts/alerts.ts` to the custom source's ruler, not hand-created in Grafana.** The rules token (`full_access_logs_rules`) reaches the custom data source's ruler too (probed 2026-11-06: GET → 404 "no rule groups found" = empty; the push-scoped token correctly gets 403). The rule is committed as `observability/alerts/bunny.yaml` (`BunnySellersNeedAttention`), `alerts.ts` gained a `--url` override, and `test/alerts_budget.test.ts` pins the count at **four** — better doctrine fidelity than the original Grafana-by-hand idea: committed file, budget test, no dashboard fiddling. Pushed with: + ```bash + npx tsx scripts/alerts.ts --push alerts/bunny.yaml --url https://db123d37-9094-4e15-badc-706071190ed7.logs.cockpit.fr-par.scw.cloud + ``` + Rule query (window `[1h]` per the repo-wide ruler convention, which the budget test enforces): + ```logql + sum(count_over_time({service=~"bunny-web-agent|bunny-llm-agent|bunny-mcp-agent", level="error"}[1h])) > 0 + ``` + One rule covers every `logger.error` call site in all three twins. (Per-script `service` labels — see §2 — so a query can distinguish the twins; the rule itself stays single.) +- [x] **Why a NEW rule (the twins were covered in scw_js):** a ruler rule evaluates only the data source it lives in. The twins' phrases were removed from `alerts/services.yaml` at the move (its header says so), because their logs left the DEFAULT logs source — and they now return in the CUSTOM `bunny-logs` source, which `ServicesNeedAttention` cannot query, phrases or no phrases. Scaleway accepts external pushes only into custom sources, and the twins' own `level` arrives as a real Loki label (unlike scw's JSON-encoded envelope), so one `{level="error"}` match replaces the whole phrase list. +- [x] **Rule budget:** the repo deliberately caps ruler rules (Scaleway bills each active rule ~€0.015/day). The bunny rule is the deliberate fourth — post hoc verified in the Cockpit billing dashboards at the §4 weekly check — and `test/alerts_budget.test.ts` now pins `bunny.yaml: 1`, so a fifth rule fails CI instead of the bill. + +**Auth, verified 2026-11-06 by curl probe against the live endpoint:** `X-Token: ` → **204**, and (contrary to the old assumption in this plan) `Authorization: Bearer ` → **204** as well; no auth → 401. Both work — the implementation uses Scaleway's documented `X-Token`. Bonus finding: the observability **read-only logs token** (`SCW_COCKPIT_LOGS_TOKEN`) queries the custom source's `query_range` fine (the rules token 403s on queries — its scope is exactly rules, as documented), so extending `scripts/logs.ts` to the bunny source later is trivial. A probe info line from setup sits in the source (harmless). + +## 2. Code changes — IMPLEMENTED (post-review fixes included) + +Implemented in `bunny_js/src/logger.ts` (buffer, awaited `flushLogs`, monotonic ns counter, `withLogFlush`), wired into all three entries (`searchapi.ts` / `llm.ts` / `mcp.ts` with `bunny-web-agent` / `bunny-llm-agent` / `bunny-mcp-agent`), covered by `bunny_js/test/logger.test.ts` (11 tests, including the review's regression guards). `npm run check` green. The authoritative code is the shipped `logger.ts` — the earlier sketch below is kept only for the design rationale; three of its details were corrected in review: + +- **Auth:** both `X-Token` and `Authorization: Bearer` are accepted by Cockpit (probed: 204/204; only no-auth gets 401) — the implementation uses the documented `X-Token`. +- **The flush is AWAITED when non-empty** (no `waitUntil` in Bunny's SDK), and the fetch carries **`signal: AbortSignal.timeout(1500)`** — without a bound, the await couples every logged request's latency to ingest health. +- **`debug` is console-only, never buffered** — the llm twins log `{ prompt }` at debug, scw's pino gate (`LOG_LEVEL ?? "info"`) suppressed those lines pre-move, and shipping them would be a new egress of user content, not parity. + +```ts +// sketch — see src/logger.ts for the shipped version +const lines: { level: string; event: object }[] = []; +let nsCounter = 0; // two errors in the same ms must not collide + +// info/warn/error buffer { level, event: { message, ...fields } }; debug does NOT +// (user content stays dashboard-only). Console output keeps its old shape. + +export async function flushLogs(): Promise { + const batch = lines.splice(0); + if (!batch.length || !url || !token) return; // happy path: zero latency, no subrequest + // group one Loki stream per level; ns suffix keeps same-ms lines strictly + // increasing (a duplicate timestamp loses the WHOLE push) + try { + const res = await fetch(url, { + method: "POST", + signal: AbortSignal.timeout(1500), // awaited => must be bounded + headers: { "X-Token": token, "Content-Type": "application/json" }, + body: JSON.stringify({ streams: [...byLevel].map(...) }), + }); + if (!res.ok) console.error(...); // visible in the bunny dashboard + } catch (err) { + console.error(...); // never breaks the response + } +} +``` + +**Entry files (`searchapi.ts`, `llm.ts`, `mcp.ts`) — not the route files.** There is no single `routes.ts`: three handler files with ten-plus early `return` paths each (OPTIONS, discovery, 402, 404). Editing returns per file is unmaintainable and misses paths. Instead, one decorator, applied once per entry: + +```ts +// logger.ts (or a small flush.ts) +export function withLogFlush(handler: (req: Request) => Promise) { + return async (req: Request): Promise => { + try { + return await handler(req); + } finally { + await flushLogs(); // covers early returns AND handler throws + } + }; +} + +// each entry file +BunnySDK.net.http.serve(withLogFlush(handleRequest)); +``` + +Subrequest budget: +1 per request at most (only when the buffer is non-empty) — well within the 50/request cap. + +**New unit test (`bunny_js/test/`)** — the buffer/flush mechanics, not a tautology. The old `alert_coverage` idea ("assert every `logger.error` writes a `level: "error"` stream") is true by construction of the single `emit` function and can never catch anything, so there is no `alert_coverage` test for bunny_js. Instead, one small test asserts: buffer fills from `logger.error`; a single non-empty flush posts one batched `{streams}` payload with `X-Token` auth (mock fetch); an empty buffer does no fetch at all; same-millisecond lines get strictly increasing timestamps (no duplicate); a failing fetch does not throw out of the decorator. + +## 3. Environment (per the repo's own secret criterion: authenticates ⇒ secret) — SET ON ALL THREE SCRIPTS + +Both values are in `bunny_js/.env` for local dev (token linespacing fixed: `KEY = value` was normalized to `KEY=value` — Deno `--env-file` parsing), and were set live via the bunny CLI (2026-11-06): searchapi (linked), `fretchen-llm` (--id), `fretchen-mcp` (--id). The env values are inert until the next deploy ships the flush code. + +**Nothing goes into the GitHub deploy Action.** `deploy-bunny-js.yml` ships code only — each script's env is deliberately bunny-side ("a repo leak must not be a secrets leak"), so the deploy (Action or manual CLI) picks the pair up automatically; carrying the token as a repo/CI secret would weaken that design. + +| Variable | bunny kind | Why | +| ------------------------ | ---------- | ----------------------------------------------- | +| `SCW_COCKPIT_PUSH_TOKEN` | `--secret` | authenticates the Loki push (`push_logs` scope) | +| `COCKPIT_LOKI_URL` | plain | public host, inert without the token | + +**Per script — all three.** `bunny scripts env set` acts on the directory-linked script (searchapi) only; llm and mcp need their values set against their own script ids explicitly. The GitHub Action ships code, not env — a script without its env vars silently logs only to the dashboard. + +```bash +# searchapi (linked): +bunny scripts env set SCW_COCKPIT_PUSH_TOKEN --secret +bunny scripts env set COCKPIT_LOKI_URL .logs.cockpit.fr-par.scw.cloud/loki/api/v1/push> +# llm + mcp: same two commands against / +``` + +## 4. Verification + +- [x] curl probe against the live push URL: `X-Token` → 204 (`Authorization: Bearer` also 204 — both accepted; no auth → 401). A probe line sits in the data source as `level="info"`. +- [x] Unit-tested (`test/logger.test.ts`, 11 tests): one batched `{streams}` push with `X-Token` auth; one stream per level with labels `{service, level}` only; same-millisecond lines get strictly increasing 19-digit ns timestamps; empty buffer sends no fetch; **debug never reaches the buffer (privacy regression guard)**; **the fetch init carries an AbortSignal (timeout regression guard)**; rejected, non-2xx and aborted pushes never throw and surface via `console.error`; `withLogFlush` flushes on early returns AND handler throws. +- [x] **Review fixes (2026-11-07)**: `AbortSignal.timeout(1500)` bounds the awaited flush; `debug` lines stopped buffering (prompt egress closed); `alerts.ts` refuses `--push alerts/bunny.yaml` without `--url` (silent wrong-ruler push closed). Remaining post-merge findings-flow actions: THREAT_MODEL token row + `bunny_js/SECURITY.md` line for the push-only Cockpit token. +- [x] **Rule fired end-to-end at setup (2026-11-06):** one `level="error"` probe line was pushed through the exact ingest path the scripts will use (X-Token → 204), confirmed stored via `query_range` `{service="bunny-web-agent", level="error"}`, the mounted rule matched it (1m interval, `[1h]`, `for: 0m`), and **the alert-manager email arrived** — the full chain is proven, per the doctrine that a rule that has never fired is not known to work. Expect one "resolved" email roughly an hour later when the probe ages out of the window; the probe lines themselves age out with the free 7-day retention. No test trigger to remove — there was no temporary route, only the probe line. +- [ ] **Ship the flush code: merge `observ` → `main` → `deploy-bunny-js.yml` publishes all three twins (it triggers on push to `main` touching `bunny_js/**`; PRs only run CI).** Env is already set on the scripts, the rule is live — no config changes ride along with the deploy. The manual three-deploy in the README (`npm run deploy` + llm/mcp by script id) is the out-of-band laptop path and NOT needed here: a laptop deploy publishes the same new code minutes earlier, but the next merge to main would republish anyway (last deployment wins), and deploying unmerged state from a branch is the exact divergence that doctrine avoids. After the Action's deploys, the first real `logger.error` from a paid request flows the probe's path from inside the isolate. +- [ ] Confirm `{level="error"}` is empty on a normal traffic day (the probe ages out within the hour). +- [ ] Glance at Cockpit usage in the console after a week: ingestion should read ~0 GB (custom-data ingestion is billed per GB, but rounds to ~€0 here); while there, confirm the fourth alert rule's actual billing. + +## 5. Convention changes (vs the Scaleway setup) + +- `logger.error` semantics unchanged: "ours, and should page" — now it pages by email via the single `level = error` alert rule. A caller's fault is `logger.warn`, as before. +- The pino-shaped console shim stays as-is; Cockpit replaces the Better Stack plan (and the old per-call-site Loki-rule idea) entirely. No `alert_coverage` test for bunny_js (see §2). +- **Three docs updated in the same change (done):** + - `bunny_js/README.md`: logger deviation bullet now describes the flush + alerted `logger.error` convention; env table gained the two Cockpit rows; the first-deploy env list includes the pair. + - `bunny_js/src/logger.ts` header comment: same claim, same fix. + - `observability/README.md`: intro now describes the custom `bunny-logs` data source and the found-a-place-for-everything-new rule (`alerts/bunny.yaml`, pushed to its own ruler via `--url`, pinned in the budget test at four). `scripts/logs.ts` still queries only the default source — the bunny data source is read via Grafana → Explore for now (its read token verifies against the custom source, so extending the CLI later is trivial). + +## 6. Accepted trade-offs (deliberate) + +- **No outside-in liveness check** — deliberately out of scope now. A dead pipeline emits no error lines, so no alert fires; discovery is via users (or the bunny dashboard showing silence). The earlier draft considered a tiny `*/5` Scaleway cron probing `GET /search` → 402 and pushing an error line on failure; dropped because no such layer has ever existed for the twins and it is outside the KISS line. If silent-death ever bites, that cron sketch is the escape hatch — but note it must be a NEW function: attaching a 5-minute trigger to `llmx402cron` would run its channel-claim logic 144× more often. +- **No retry, no queue:** a genuinely lost line happens only if the isolate dies between error and flush. The awaited non-empty flush removes the much more mundane loss mode (fetch cancelled at response time). +- **Minutes, not seconds:** alert latency = rule evaluation (1m interval) + email delivery. Inherent to email-grade alerting. +- **Higher platform concentration:** Scaleway now hosts compute (cron), logs, alerting, and the email delivery — if Scaleway itself is down, alerts are silent. Accepted at personal scale; escape hatches are (a) TEM as a direct secondary channel for rare money-path events (`mint_failed`), or (b) an alert-manager webhook (ntfy/Telegram) if this ever stops being acceptable. +- **Metered, not free-tier:** ingestion is billed per GB (rounds to ~€0 here), custom-log retention is free for 7 days, extendable 1 day–5 years at cost; the fourth alert rule adds ~€0.015/day, pinned inside the `alerts_budget.test.ts` budget (see §1). +- **Loki quirks:** nanosecond string timestamps + duplicate-rejection (see code comment), `X-Token` auth, datasource-managed alert rules only — all one-time gotchas, not ongoing work. diff --git a/observability/scripts/alerts.ts b/observability/scripts/alerts.ts index 108fa45c3..c7271dd4d 100644 --- a/observability/scripts/alerts.ts +++ b/observability/scripts/alerts.ts @@ -16,10 +16,16 @@ * npx tsx scripts/alerts.ts # list the rule groups on the ruler * npx tsx scripts/alerts.ts --push # upload alerts/payments.yaml * npx tsx scripts/alerts.ts --push alerts/services.yaml + * npx tsx scripts/alerts.ts --push alerts/bunny.yaml --url https://.logs.cockpit.fr-par.scw.cloud * npx tsx scripts/alerts.ts --delete payments * * `--push` refuses a file with uncommitted changes (see assertCommitted): commit, then push. * + * `--url ` targets another data source's ruler. The default is the Scaleway functions' + * logs source; alerts/bunny.yaml lives on the custom bunny-logs data source, which that ruler + * cannot see — a ruler rule only ever evaluates its own data source's logs, so it must be + * pushed at its own URL (same token, same namespace). + * * Push is never wired into deploy. Alerting config that changes as a side effect of shipping code * is its own kind of surprise — and a rule silently removed by a deploy is indistinguishable from * a system that is simply quiet. @@ -30,7 +36,7 @@ import dotenv from "dotenv"; dotenv.config(); -const URL_BASE = process.env.SCW_COCKPIT_LOGS_URL; +const URL_BASE = flag("url") ?? process.env.SCW_COCKPIT_LOGS_URL; const TOKEN = process.env.SCW_COCKPIT_RULES_TOKEN; if (!URL_BASE || !TOKEN) { @@ -89,8 +95,31 @@ function assertCommitted(file: string): void { } } +/** + * Rules whose group must NOT land on the default ruler — they live on a custom data source's own + * ruler (a ruler rule only ever sees its own data source's logs). Pushing one with the default + * URL succeeds silently, bills ~€0.015/day and matches nothing, so this refuses instead. + * Value: the custom source's API base, for the error message. + */ +const CUSTOM_RULER_FILES: Record = { + "alerts/bunny.yaml": "https://db123d37-9094-4e15-badc-706071190ed7.logs.cockpit.fr-par.scw.cloud", +}; + +function assertRulerUrl(file: string): void { + const customBase = CUSTOM_RULER_FILES[file]; + if (customBase && !flag("url")) { + console.error( + `refusing to push ${file} to the default ruler: its rules evaluate the custom bunny-logs ` + + `data source, which that ruler cannot see — the group would be billed daily and match ` + + `nothing. Add:\n --url ${customBase}`, + ); + process.exit(1); + } +} + async function push(file: string): Promise { assertCommitted(file); + assertRulerUrl(file); const yaml = readFileSync(file, "utf8"); await ruler(`/${NAMESPACE}`, { method: "POST", diff --git a/observability/test/alerts_budget.test.ts b/observability/test/alerts_budget.test.ts index bdf550081..cbb17a55d 100644 --- a/observability/test/alerts_budget.test.ts +++ b/observability/test/alerts_budget.test.ts @@ -16,6 +16,10 @@ import { fileURLToPath } from "node:url"; const RULE_BUDGET: Record = { "services.yaml": 1, // ServicesNeedAttention "payments.yaml": 2, // PaymentCronNeedsAttention, FacilitatorNeedsAttention + // Fourth of four, raised from three DELIBERATELY (2026-11-06): the bunny twins' logs live in + // the custom bunny-logs data source, which no phrase in the rules above can see — so their + // coverage is necessarily its own (pushed) rule, not another line filter. + "bunny.yaml": 1, // BunnySellersNeedAttention }; const read = (file: string) =>