From 6abe0f388f79caf45c8e5dd5b031c423b8863aaf Mon Sep 17 00:00:00 2001 From: fretchen Date: Sun, 20 Sep 2026 08:17:08 +0200 Subject: [PATCH 1/6] x402 fixes --- scw_js/README.md | 17 +++++ scw_js/llm_x402_cron.ts | 16 ++--- scw_js/scripts/recover_channels.ts | 24 +++++--- scw_js/test/llm_x402_cron.test.ts | 8 +-- scw_js/test/x402_channel_sync.test.ts | 89 +++++++++++++++++++++++---- scw_js/x402_channel_sync.ts | 87 +++++++++++++++++++------- 6 files changed, 188 insertions(+), 53 deletions(-) diff --git a/scw_js/README.md b/scw_js/README.md index 8ca424822..7f3916792 100644 --- a/scw_js/README.md +++ b/scw_js/README.md @@ -144,6 +144,23 @@ The assistant's two web tools, sold per call. `search_service.ts` proxies Brave' **The SSRF defence is unchanged by payment.** A payment authorises a fetch, not a fetch of `169.254.169.254`. See the header comment of [`web_fetch_service.ts`](./web_fetch_service.ts). +**Refunds, and the one exercise that tests them.** Cooperative refunds are the seller's job (`llmx402cron`, or `scripts/recover_channels.ts` on demand), and the SDK builds each one entirely from the **stored** channel record — the amount from `balance - chargedCumulativeAmount`, the candidate filter from `balance !== 0`, and the signature from `refundNonce`. All three are caches of chain state, and all three have gone stale in production. `resyncChannelState` re-reads them before every sweep, which is the only thing standing between a working refund and a permanently broken one. + +The failure mode that hid for months: a successful refund **deletes** the channel record, and a later deposit with the same voucher signer recreates it with `refundNonce: 0` while the chain has moved on. Every later refund is then signed against a consumed nonce and reverts (`0x164f1afe`) — and because the SDK's refund loop has no per-channel catch, one such channel blocks the whole sweep. 2.08 USDC accumulated behind it. + +No unit test can catch that: every test here replaces the chain with a mock that agrees with the local record by construction. The exercise that _would_ catch it needs a real chain, and it must **refund the same channel twice** — a single refund passes and proves nothing, because the nonce only goes stale after the first one. On Base Sepolia (free USDC, and the escrow contract is deployed there): + +```bash +# 1. buyer: open a channel and spend on it — scw_js/notebooks/sc_llm_x402_buyer.ipynb (USE_BASE, testnet) +# 2. seller: claim what is owed, then refund the rest +npx tsx scripts/recover_channels.ts eip155:84532 --apply +# 3. buyer: run the notebook again — same voucher signer, so the SAME channelId is re-funded +# 4. seller: refund a second time. THIS is the step that used to revert. +npx tsx scripts/recover_channels.ts eip155:84532 --apply +``` + +Run it before touching the refund path. It is deliberately not in CI: it needs a funded key and a network, and CI stays hermetic. + ### `growth_api.ts` - Growth Agent Draft Approval API for reviewing, editing, and approving AI-generated social media drafts. Used by the Growth Agent notebooks and cron job. diff --git a/scw_js/llm_x402_cron.ts b/scw_js/llm_x402_cron.ts index 25644dd12..a9e921a06 100644 --- a/scw_js/llm_x402_cron.ts +++ b/scw_js/llm_x402_cron.ts @@ -9,7 +9,7 @@ import { useEnhancedRefundRequirements, type FacilitatorFeeConfig, } from "./x402_server.js"; -import { resyncChannelBalances } from "./x402_channel_sync.js"; +import { resyncChannelState } from "./x402_channel_sync.js"; import type { ScwEvent } from "./types.js"; const logger = pino({ level: process.env.LOG_LEVEL ?? "info" }); @@ -198,13 +198,13 @@ export async function handle( let refunds: number | undefined; let refundError: string | undefined; try { - // The stored `balance` is a cache that drifts low (handleAfterVerify writes the - // facilitator's PRE-deposit reading and depends on handleAfterSettle to correct it). - // The SDK refunds `balance - chargedCumulativeAmount` from that cache and skips - // channels whose cached balance is 0, so without this a funded channel is either - // passed over or given a negative refund amount. Observed live: two Optimism - // channels holding 1.0 and 6.5 USDC both cached "0". - await resyncChannelBalances(scheme.getStorage(), network); + // The SDK builds a refund entirely from the stored record — amount, candidate filter and + // signing nonce — and all three are caches that have gone stale in production. A stale + // `balance` skips a funded channel or computes a negative amount; a stale `refundNonce` + // signs against a nonce the chain already consumed, which reverts and, because the SDK's + // refund loop has no per-channel catch, blocks every other refund in the sweep behind it. + // 2.08 USDC accumulated that way. See resyncChannelState. + await resyncChannelState(scheme.getStorage(), network); // The SDK builds refund requirements with `extra: {}`, which the facilitator rejects // as receiver_authorizer_mismatch. Applied after the claim so claim/settle are // untouched. See useEnhancedRefundRequirements. diff --git a/scw_js/scripts/recover_channels.ts b/scw_js/scripts/recover_channels.ts index 72cb7dde0..d5dbcad57 100644 --- a/scw_js/scripts/recover_channels.ts +++ b/scw_js/scripts/recover_channels.ts @@ -29,7 +29,7 @@ import { getBatchSettlementNetworks, useEnhancedRefundRequirements, } from "../x402_server.js"; -import { resyncChannelBalances } from "../x402_channel_sync.js"; +import { resyncChannelState } from "../x402_channel_sync.js"; dotenv.config(); @@ -69,15 +69,23 @@ async function main(): Promise { // SDK refunds `balance - chargedCumulativeAmount` from it — a stale zero either skips the // channel (the balance!==0 filter) or computes a negative amount. Two live Optimism // channels holding 1.0 and 6.5 USDC both cached "0". - console.log("Re-syncing cached balances from chain..."); - const synced = await resyncChannelBalances(scheme.getStorage(), network, { dryRun: !APPLY }); + console.log("Re-syncing cached channel state from chain..."); + const synced = await resyncChannelState(scheme.getStorage(), network, { dryRun: !APPLY }); for (const s of synced) { - if (s.corrected) { - console.log( - ` ${s.channelId.slice(0, 18)}… stored ${usdc(s.storedBalance)} -> chain ${usdc(s.chainBalance)} USDC` + - (APPLY ? "" : " (dry run: not written)"), - ); + if (!s.corrected) continue; + const drifted: string[] = []; + if (s.storedBalance !== s.chainBalance) { + drifted.push(`balance ${usdc(s.storedBalance)} -> ${usdc(s.chainBalance)} USDC`); } + // A stale nonce is the difference between a refund that works and one that reverts, so it is + // reported as its own line rather than folded into a generic "was stale". + if (s.storedRefundNonce !== s.chainRefundNonce) { + drifted.push(`refundNonce ${s.storedRefundNonce} -> ${s.chainRefundNonce}`); + } + console.log( + ` ${s.channelId.slice(0, 18)}… ${drifted.join(", ")}` + + (APPLY ? "" : " (dry run: not written)"), + ); } console.log(` ${synced.filter((s) => s.corrected).length} of ${synced.length} were stale.\n`); diff --git a/scw_js/test/llm_x402_cron.test.ts b/scw_js/test/llm_x402_cron.test.ts index 7675ff3c9..046c73724 100644 --- a/scw_js/test/llm_x402_cron.test.ts +++ b/scw_js/test/llm_x402_cron.test.ts @@ -9,7 +9,7 @@ const { mockGetFacilitatorFeeConfig, mockReadContract, mockLoggerWarn, - mockResyncChannelBalances, + mockResyncChannelState, mockUseEnhancedRefundRequirements, } = vi.hoisted(() => ({ mockCreateLLMResourceServer: vi.fn(), @@ -18,13 +18,13 @@ const { mockGetFacilitatorFeeConfig: vi.fn(), mockReadContract: vi.fn(), mockLoggerWarn: vi.fn(), - mockResyncChannelBalances: vi.fn(), + mockResyncChannelState: vi.fn(), mockUseEnhancedRefundRequirements: vi.fn(), })); // Hits a real RPC otherwise. Its own behaviour is covered in x402_channel_sync.test.ts. vi.mock("../x402_channel_sync.js", () => ({ - resyncChannelBalances: mockResyncChannelBalances, + resyncChannelState: mockResyncChannelState, })); vi.mock("../x402_server.js", () => ({ @@ -92,7 +92,7 @@ describe("llm_x402_cron", () => { createChannelManager: mockCreateChannelManager, getStorage: vi.fn().mockReturnValue({}), }); - mockResyncChannelBalances.mockResolvedValue([]); + mockResyncChannelState.mockResolvedValue([]); mockUseEnhancedRefundRequirements.mockResolvedValue(undefined); mockCreateLLMResourceServer.mockReturnValue({ resourceServer: {}, diff --git a/scw_js/test/x402_channel_sync.test.ts b/scw_js/test/x402_channel_sync.test.ts index cb0de8b37..5a6b5231a 100644 --- a/scw_js/test/x402_channel_sync.test.ts +++ b/scw_js/test/x402_channel_sync.test.ts @@ -13,7 +13,7 @@ vi.mock("@fretchen/chain-utils", () => ({ getRpcUrl: vi.fn(() => "https://rpc.example"), })); -import { resyncChannelBalances } from "../x402_channel_sync.js"; +import { resyncChannelState } from "../x402_channel_sync.js"; const OP = "eip155:10"; @@ -53,7 +53,22 @@ function makeStorage(channels: Channel[]) { }; } -describe("resyncChannelBalances", () => { +/** + * Two reads per channel now — `channels()` and `refundNonce()` — so the mock routes on + * functionName. `setChain` is the only way tests should drive it: a positional mock would silently + * feed the nonce to the balance read the moment the call order changed. + */ +function setChain({ + balance = 0n, + totalClaimed = 0n, + refundNonce = 0n, +}: { balance?: bigint; totalClaimed?: bigint; refundNonce?: bigint } = {}) { + mockReadContract.mockImplementation(({ functionName }: { functionName: string }) => + Promise.resolve(functionName === "refundNonce" ? refundNonce : [balance, totalClaimed]), + ); +} + +describe("resyncChannelState", () => { beforeEach(() => { vi.clearAllMocks(); }); @@ -66,9 +81,9 @@ describe("resyncChannelBalances", () => { */ it("corrects a stale-zero cached balance from the chain", async () => { const { storage, updateChannel, channels } = makeStorage([makeChannel()]); - mockReadContract.mockResolvedValue([1_000_000n, 0n]); + setChain({ balance: 1_000_000n }); - const results = await resyncChannelBalances(storage, OP); + const results = await resyncChannelState(storage, OP); expect(results[0].corrected).toBe(true); expect(results[0].storedBalance).toBe("0"); @@ -79,9 +94,9 @@ describe("resyncChannelBalances", () => { it("leaves an already-correct record untouched", async () => { const { storage, updateChannel } = makeStorage([makeChannel({ balance: "400000" })]); - mockReadContract.mockResolvedValue([400_000n, 0n]); + setChain({ balance: 400_000n }); - const results = await resyncChannelBalances(storage, OP); + const results = await resyncChannelState(storage, OP); expect(results[0].corrected).toBe(false); expect(updateChannel).not.toHaveBeenCalled(); @@ -89,9 +104,9 @@ describe("resyncChannelBalances", () => { it("writes nothing in dry-run mode but still reports the drift", async () => { const { storage, updateChannel } = makeStorage([makeChannel()]); - mockReadContract.mockResolvedValue([6_500_000n, 0n]); + setChain({ balance: 6_500_000n }); - const results = await resyncChannelBalances(storage, OP, { dryRun: true }); + const results = await resyncChannelState(storage, OP, { dryRun: true }); expect(results[0].corrected).toBe(true); expect(results[0].chainBalance).toBe("6500000"); @@ -103,7 +118,7 @@ describe("resyncChannelBalances", () => { const { storage, updateChannel, channels } = makeStorage([makeChannel({ balance: "400000" })]); mockReadContract.mockRejectedValue(new Error("RPC down")); - const results = await resyncChannelBalances(storage, OP); + const results = await resyncChannelState(storage, OP); expect(results).toHaveLength(0); expect(updateChannel).not.toHaveBeenCalled(); @@ -112,10 +127,62 @@ describe("resyncChannelBalances", () => { it("also corrects totalClaimed, so outstanding vouchers are not re-claimed", async () => { const { storage, channels } = makeStorage([makeChannel({ balance: "0", totalClaimed: "0" })]); - mockReadContract.mockResolvedValue([1_000_000n, 35_147n]); + setChain({ balance: 1_000_000n, totalClaimed: 35_147n }); - await resyncChannelBalances(storage, OP); + await resyncChannelState(storage, OP); expect(channels[0].totalClaimed).toBe("35147"); }); + + /** + * The bug this function grew a second read for. A successful refund deletes the channel record; + * a later deposit with the same voucher signer recreates it with `refundNonce: 0` while the chain + * has moved to 1. The SDK then signs every refund against a consumed nonce, the contract reverts + * with 0x164f1afe, and since its refund loop has no per-channel catch, that one channel blocks + * the whole sweep. Two Optimism channels sat like that with 2.08 USDC behind them. + */ + it("corrects a stale refundNonce, which is what makes a refund signable at all", async () => { + const { storage, updateChannel, channels } = makeStorage([ + makeChannel({ balance: "544239", totalClaimed: "52897", refundNonce: 0 }), + ]); + setChain({ balance: 544_239n, totalClaimed: 52_897n, refundNonce: 1n }); + + const results = await resyncChannelState(storage, OP); + + // The balance agrees with the chain; the nonce alone is the drift, and it must still count. + expect(results[0].corrected).toBe(true); + expect(results[0].storedRefundNonce).toBe(0); + expect(results[0].chainRefundNonce).toBe(1); + expect(updateChannel).toHaveBeenCalledTimes(1); + expect(channels[0].refundNonce).toBe(1); + }); + + it("leaves a record alone when only the nonce read fails", async () => { + const { storage, updateChannel, channels } = makeStorage([makeChannel({ balance: "400000" })]); + mockReadContract.mockImplementation(({ functionName }: { functionName: string }) => + functionName === "refundNonce" + ? Promise.reject(new Error("RPC down")) + : Promise.resolve([1_000_000n, 0n]), + ); + + const results = await resyncChannelState(storage, OP); + + // Half-corrected is its own flavour of drift, so a partial read writes nothing at all. + expect(results).toHaveLength(0); + expect(updateChannel).not.toHaveBeenCalled(); + expect(channels[0].balance).toBe("400000"); + }); + + it("reports an in-sync nonce without correcting anything", async () => { + const { storage, updateChannel } = makeStorage([ + makeChannel({ balance: "400000", refundNonce: 2 }), + ]); + setChain({ balance: 400_000n, refundNonce: 2n }); + + const results = await resyncChannelState(storage, OP); + + expect(results[0].corrected).toBe(false); + expect(results[0].chainRefundNonce).toBe(2); + expect(updateChannel).not.toHaveBeenCalled(); + }); }); diff --git a/scw_js/x402_channel_sync.ts b/scw_js/x402_channel_sync.ts index 77686b594..40c470839 100644 --- a/scw_js/x402_channel_sync.ts +++ b/scw_js/x402_channel_sync.ts @@ -21,31 +21,55 @@ const CHANNELS_ABI = [ }, ] as const; +/** The contract's per-channel refund nonce, which `channels()` does not return — it lives in its + * own getter. Selector `0xf0dc792e`. */ +const REFUND_NONCE_ABI = [ + { + type: "function", + name: "refundNonce", + inputs: [{ name: "channelId", type: "bytes32" }], + outputs: [{ name: "", type: "uint256" }], + stateMutability: "view", + }, +] as const; + export interface ChannelSyncResult { channelId: string; storedBalance: string; chainBalance: string; + storedRefundNonce: number; + chainRefundNonce: number; corrected: boolean; } /** - * Refresh each stored channel's `balance`/`totalClaimed` from the escrow contract. + * Refresh everything the CHAIN owns on each stored channel — `balance`, `totalClaimed` and + * `refundNonce` — before any of it is used to build a refund. + * + * Why this is needed before any refund: the SDK builds a refund entirely from the STORED record + * (server/index.mjs refundChannel) — the amount from `balance - chargedCumulativeAmount`, the + * candidate filter from `balance !== 0`, and the signature from `refundNonce`. Every one of those + * is a cache, and each has gone stale in production: * - * Why this is needed before any refund: the SDK computes a refund as - * `balance - chargedCumulativeAmount` from the STORED record (server/index.mjs refundChannel), - * and filters refund candidates on `balance !== 0`. The stored balance is only a cache — - * `handleAfterVerify` writes the facilitator's PRE-deposit reading and relies on - * `handleAfterSettle` to correct it afterwards, so any request that dies in between leaves a - * stale-low figure behind for good. + * - **`balance`.** `handleAfterVerify` writes the facilitator's PRE-deposit reading and relies on + * `handleAfterSettle` to correct it, so a request that dies in between leaves a stale-low figure + * behind for good. Two live Optimism channels holding 1.0 and 6.5 USDC both cached `balance: 0`; + * refunding from that cache would have skipped them (the zero filter) or computed a NEGATIVE + * amount. Either way the 7.5 USDC stays locked. + * - **`refundNonce`.** A successful refund DELETES the channel record, and a later deposit with the + * same voucher signer recreates it — same `channelId`, `refundNonce` back to 0, while the chain + * has moved to 1. Every subsequent refund is then signed against a consumed nonce and the + * contract reverts with `0x164f1afe`. Two Optimism channels sat like that: refunds had never + * worked on either, and because the SDK's `refundChannels` throws on the first failure with no + * per-channel catch, one of them blocked the whole sweep — including a third channel whose nonce + * was fine. 2.08 USDC accumulated behind it. * - * That is not hypothetical: two live Optimism channels holding 1.0 and 6.5 USDC both cached - * `balance: "0"`. Refunding from that cache would have skipped them entirely (the zero - * filter) or computed a NEGATIVE refund amount (0 - chargedCumulative). Either way the 7.5 - * USDC stays locked. + * That last point is the reason this function exists in its current shape: it is the one place that + * re-reads the chain, so it is the one place that can stop a cached mirror from drifting. * * Read-only against the chain; the only writes are corrections to our own S3 records. */ -export async function resyncChannelBalances( +export async function resyncChannelState( storage: ChannelStorage, network: string, { dryRun = false }: { dryRun?: boolean } = {}, @@ -61,13 +85,26 @@ export async function resyncChannelBalances( for (const channel of channels) { let chainBalance: bigint; let chainTotalClaimed: bigint; + let chainRefundNonce: bigint; try { - [chainBalance, chainTotalClaimed] = (await client.readContract({ - address: BATCH_SETTLEMENT_ADDRESS, - abi: CHANNELS_ABI, - functionName: "channels", - args: [channel.channelId as `0x${string}`], - })) as [bigint, bigint]; + // Both reads together: a record corrected from one and not the other would be a third + // flavour of the same drift this function exists to prevent. + const [channelState, refundNonce] = await Promise.all([ + client.readContract({ + address: BATCH_SETTLEMENT_ADDRESS, + abi: CHANNELS_ABI, + functionName: "channels", + args: [channel.channelId as `0x${string}`], + }) as Promise<[bigint, bigint]>, + client.readContract({ + address: BATCH_SETTLEMENT_ADDRESS, + abi: REFUND_NONCE_ABI, + functionName: "refundNonce", + args: [channel.channelId as `0x${string}`], + }) as Promise, + ]); + [chainBalance, chainTotalClaimed] = channelState; + chainRefundNonce = refundNonce; } catch (err) { // A bad read must never overwrite a good record — leave it exactly as it is. logger.warn({ err, network, channelId: channel.channelId }, "Channel state read failed"); @@ -76,12 +113,15 @@ export async function resyncChannelBalances( const corrected = chainBalance.toString() !== channel.balance || - chainTotalClaimed.toString() !== channel.totalClaimed; + chainTotalClaimed.toString() !== channel.totalClaimed || + Number(chainRefundNonce) !== channel.refundNonce; results.push({ channelId: channel.channelId, storedBalance: channel.balance, chainBalance: chainBalance.toString(), + storedRefundNonce: channel.refundNonce, + chainRefundNonce: Number(chainRefundNonce), corrected, }); @@ -95,6 +135,7 @@ export async function resyncChannelBalances( ...current, balance: chainBalance.toString(), totalClaimed: chainTotalClaimed.toString(), + refundNonce: Number(chainRefundNonce), } : current, ); @@ -102,10 +143,12 @@ export async function resyncChannelBalances( { network, channelId: channel.channelId, - from: channel.balance, - to: chainBalance.toString(), + balanceFrom: channel.balance, + balanceTo: chainBalance.toString(), + refundNonceFrom: channel.refundNonce, + refundNonceTo: Number(chainRefundNonce), }, - "Corrected stale cached channel balance", + "Corrected stale cached channel state", ); } From 4a3c53efbd75e8a73682af23254c67a300a31ee8 Mon Sep 17 00:00:00 2001 From: fretchen Date: Sun, 20 Sep 2026 08:35:38 +0200 Subject: [PATCH 2/6] modern facilitator --- x402_facilitator/package-lock.json | 18 ++++---- x402_facilitator/package.json | 4 +- x402_facilitator/test/x402_settle.test.js | 53 +++++++++++++++++++++++ x402_facilitator/x402_settle.ts | 47 +++++++++++++++++--- 4 files changed, 105 insertions(+), 17 deletions(-) diff --git a/x402_facilitator/package-lock.json b/x402_facilitator/package-lock.json index 26c84bad5..204c0bfbb 100644 --- a/x402_facilitator/package-lock.json +++ b/x402_facilitator/package-lock.json @@ -10,8 +10,8 @@ "license": "MIT", "dependencies": { "@fretchen/chain-utils": "file:../shared/chain-utils", - "@x402/core": "^2.17.0", - "@x402/evm": "^2.17.0", + "@x402/core": "^2.26.0", + "@x402/evm": "^2.26.0", "dotenv": "^16.0.0", "pino": "^9.0.0", "viem": "^2.54.2", @@ -4367,9 +4367,9 @@ } }, "node_modules/@x402/core": { - "version": "2.18.0", - "resolved": "https://registry.npmjs.org/@x402/core/-/core-2.18.0.tgz", - "integrity": "sha512-3LB5m0Yx7C38ks8jDqTGYPZ2FnLzlH9pTlGvE8er2ujS1ri12sXXvWwnmYsmh3ZkXSDbV3BKU8oRKULatPp0Hg==", + "version": "2.26.0", + "resolved": "https://registry.npmjs.org/@x402/core/-/core-2.26.0.tgz", + "integrity": "sha512-8dlXip9u0JjyELzzFz48vntuMajvUjA8IYpitfaW423m53bR49amZDIn3n4gXRYoNEKzGB9Rtn8at35WHz61cA==", "license": "Apache-2.0", "dependencies": { "zod": "^3.24.2" @@ -4385,12 +4385,12 @@ } }, "node_modules/@x402/evm": { - "version": "2.18.0", - "resolved": "https://registry.npmjs.org/@x402/evm/-/evm-2.18.0.tgz", - "integrity": "sha512-iiA5zqqJMcFdMEO+nvdctiWHcSn1EBpN8Dic0beGoxmoWX2Y8DnDHEROL/E0S3bUFpQlwTKkp4rie4wvqhsBvg==", + "version": "2.26.0", + "resolved": "https://registry.npmjs.org/@x402/evm/-/evm-2.26.0.tgz", + "integrity": "sha512-dcDxdWsEqyqmr0BsTXbvDNbL2KCjSvqcQV6VtSu7eTeDmi6RfI/T4IPSst5iI8M2Ys34Wc48AikJepuE7Bojgw==", "license": "Apache-2.0", "dependencies": { - "@x402/core": "~2.18.0", + "@x402/core": "~2.26.0", "viem": "^2.48.11", "zod": "^3.24.2" } diff --git a/x402_facilitator/package.json b/x402_facilitator/package.json index 98285df92..8ee765612 100644 --- a/x402_facilitator/package.json +++ b/x402_facilitator/package.json @@ -36,8 +36,8 @@ "license": "MIT", "dependencies": { "@fretchen/chain-utils": "file:../shared/chain-utils", - "@x402/core": "^2.17.0", - "@x402/evm": "^2.17.0", + "@x402/core": "^2.26.0", + "@x402/evm": "^2.26.0", "dotenv": "^16.0.0", "pino": "^9.0.0", "viem": "^2.54.2", diff --git a/x402_facilitator/test/x402_settle.test.js b/x402_facilitator/test/x402_settle.test.js index 8f276cc6e..37268303a 100644 --- a/x402_facilitator/test/x402_settle.test.js +++ b/x402_facilitator/test/x402_settle.test.js @@ -454,6 +454,59 @@ describe("x402_settle with mocked facilitator", () => { expect(result.transaction).toBe(""); }); + /** + * `settlement_pending` (new in @x402/evm 2.23) is the one `success: false` that is not terminal: + * the transaction was broadcast and only the receipt wait failed, so it may still confirm. The + * hash is what lets a caller reconcile instead of blindly retrying, and hard-coding + * `transaction: ""` on the failure path would throw it away. + */ + it("passes the broadcast hash through on settlement_pending", async () => { + const mockFacilitator = { + settle: vi.fn().mockResolvedValue({ + success: false, + errorReason: "settlement_pending", + errorMessage: "receipt wait timed out", + transaction: "0xbroadcastbutunconfirmed", + network: "eip155:11155420", + }), + }; + + vi.spyOn(verifyModule, "verifyPayment").mockResolvedValue({ + isValid: true, + payer: "0xf39Fd6e51aad88F6F4ce6aB8827279cffFb92266", + }); + vi.spyOn(facilitatorInstance, "getFacilitator").mockReturnValue(mockFacilitator); + + const result = await settlePayment(validPaymentPayload, validPaymentRequirements); + + expect(result.success).toBe(false); + expect(result.errorReason).toBe("settlement_pending"); + expect(result.transaction).toBe("0xbroadcastbutunconfirmed"); + }); + + /** The contrast that gives the case above its meaning: a genuinely terminal failure never + * broadcast anything, so it must not hand back a hash to reconcile against. */ + it("still reports no transaction for a terminal settlement failure", async () => { + const mockFacilitator = { + settle: vi.fn().mockResolvedValue({ + success: false, + errorReason: "insufficient_allowance", + transaction: "0xshouldnotbesurfaced", + }), + }; + + vi.spyOn(verifyModule, "verifyPayment").mockResolvedValue({ + isValid: true, + payer: "0xf39Fd6e51aad88F6F4ce6aB8827279cffFb92266", + }); + vi.spyOn(facilitatorInstance, "getFacilitator").mockReturnValue(mockFacilitator); + + const result = await settlePayment(validPaymentPayload, validPaymentRequirements); + + expect(result.success).toBe(false); + expect(result.transaction).toBe(""); + }); + it("extracts insufficient_funds error reason from exception", async () => { vi.spyOn(verifyModule, "verifyPayment").mockResolvedValue({ isValid: true, diff --git a/x402_facilitator/x402_settle.ts b/x402_facilitator/x402_settle.ts index ea0decc06..2fb8769f9 100644 --- a/x402_facilitator/x402_settle.ts +++ b/x402_facilitator/x402_settle.ts @@ -54,6 +54,24 @@ export type FacilitatorFeePaid = z.infer; */ export type SettleResult = SettleResponseBody & { errorMessage?: string }; +/** + * The one `success: false` that is **not** a terminal failure. + * + * Added by @x402/evm 2.23 for every settle path (eip3009/permit2 for `exact` and `upto`, and + * batch-settlement's settle/claim/deposit/refund): when the transaction has been **broadcast** but + * waiting for its receipt fails — an RPC error, a timeout — the chain may still confirm it. Before + * 2.23 that came back as a terminal failure, so a caller could conclude "settlement failed" about a + * transaction that in fact succeeded, and retry it. + * + * What makes it recoverable is the `transaction` hash that comes with it, so the caller can + * reconcile on chain before deciding anything. Which is precisely why the failure branches below + * must stop hard-coding `transaction: ""`. + * + * Declared here rather than imported: neither `@x402/core` nor `@x402/evm` exports its constant + * from a public entry point (it lives in an internal chunk in both), so the string is the contract. + */ +const SETTLEMENT_PENDING = "settlement_pending"; + /** * Derive the single receiver a batch-settlement claim/settle command pays out to. * @@ -372,16 +390,27 @@ export async function settlePayment( const payer = claims?.[0]?.voucher?.channel?.payer; if (!result.success) { + const pending = result.errorReason === SETTLEMENT_PENDING; logger.warn( - { errorReason: result.errorReason, errorMessage: result.errorMessage }, - "Batch-settlement claim/settle failed", + { + errorReason: result.errorReason, + errorMessage: result.errorMessage, + // Only meaningful when pending — a terminal failure never broadcast anything. + ...(pending && { transaction: result.transaction, network }), + }, + pending + ? "Batch-settlement claim/settle broadcast but unconfirmed — reconcile on chain" + : "Batch-settlement claim/settle failed", ); return { success: false, errorReason: result.errorReason, errorMessage: result.errorMessage, payer, - transaction: "", + // Pass the broadcast hash through. Hard-coding "" here would throw away the one thing + // that makes settlement_pending recoverable, leaving the caller unable to tell a + // transaction that never happened from one that may already have confirmed. + transaction: pending ? (result.transaction ?? "") : "", network, }; } @@ -476,16 +505,22 @@ export async function settlePayment( const result = await facilitator.settle(paymentPayload as any, paymentRequirements as any); if (!result.success) { + const pending = result.errorReason === SETTLEMENT_PENDING; logger.warn( - { errorReason: result.errorReason, errorMessage: result.errorMessage }, - "Settlement failed", + { + errorReason: result.errorReason, + errorMessage: result.errorMessage, + ...(pending && { transaction: result.transaction, network: accepted?.network }), + }, + pending ? "Settlement broadcast but unconfirmed — reconcile on chain" : "Settlement failed", ); return { success: false, errorReason: result.errorReason, errorMessage: result.errorMessage, payer: verifyResult.payer, - transaction: "", + // See SETTLEMENT_PENDING: the hash is what the caller reconciles against. + transaction: pending ? (result.transaction ?? "") : "", network: accepted?.network as string, }; } From a5b00421f345dbe8f55f6dfe1547b3ad80f9d949 Mon Sep 17 00:00:00 2001 From: fretchen Date: Sun, 20 Sep 2026 11:25:37 +0200 Subject: [PATCH 3/6] clean up --- growth-agent/README.md | 45 ++++----- scw_js/README.md | 23 +++++ scw_js/llm_x402_cron.ts | 70 +++++++++++++- scw_js/scripts/logs.ts | 153 ++++++++++++++++++++++++++++++ scw_js/test/llm_x402_cron.test.ts | 100 ++++++++++++++++++- x402_facilitator/README.md | 11 +++ 6 files changed, 374 insertions(+), 28 deletions(-) create mode 100644 scw_js/scripts/logs.ts diff --git a/growth-agent/README.md b/growth-agent/README.md index 1be971b8c..14a353927 100644 --- a/growth-agent/README.md +++ b/growth-agent/README.md @@ -27,13 +27,13 @@ Export it as a picture with `uv run python scripts/run_local.py --graph` (writes ## Stack -| Component | Technology | -|---|---| -| Runtime | Python 3.11 (Scaleway Serverless Container) | -| LLM | IONOS AI Model Hub (Llama 3.3 70B) by default — see below | -| Social | Mastodon REST API, Bluesky AT Protocol | -| Storage | Scaleway S3 | -| Package manager | uv | +| Component | Technology | +| --------------- | --------------------------------------------------------- | +| Runtime | Python 3.11 (Scaleway Serverless Container) | +| LLM | IONOS AI Model Hub (Llama 3.3 70B) by default — see below | +| Social | Mastodon REST API, Bluesky AT Protocol | +| Storage | Scaleway S3 | +| Package manager | uv | ### LLM provider @@ -41,10 +41,10 @@ The provider is selected at runtime by the `LLM_PROVIDER` env var — `ionos` (d `mistral` — and each needs its matching API key. Set `LLM_MODEL` to override the provider's default model. Selection logic is in `agent/llm_client.py` (`LLMClient.from_env()`). -| `LLM_PROVIDER` | API key env var | -| --- | --- | +| `LLM_PROVIDER` | API key env var | +| ----------------- | ----------------- | | `ionos` (default) | `IONOS_API_TOKEN` | -| `mistral` | `MISTRAL_API_KEY` | +| `mistral` | `MISTRAL_API_KEY` | ## Development @@ -137,12 +137,12 @@ uv run python scripts/run_local.py --diagnose This shows the content queue, next scheduled drafts, LLM analysis status, and recent run logs. Log statuses: -| Status | Meaning | -|---|---| -| `completed` | Handler ran successfully | -| `started` | Handler was invoked but never finished (timeout or crash) | -| `crashed` | Handler hit an unexpected error (traceback included) | -| No log for today | Cron did not fire at all | +| Status | Meaning | +| ---------------- | --------------------------------------------------------- | +| `completed` | Handler ran successfully | +| `started` | Handler was invoked but never finished (timeout or crash) | +| `crashed` | Handler hit an unexpected error (traceback included) | +| No log for today | Cron did not fire at all | ### 2. Run individual tasks locally @@ -177,17 +177,18 @@ kill %1 This runs all daily tasks (analytics, publish, pipeline refill) and weekly tasks (insights on Monday) — exactly what Scaleway executes on `0 8 * * *`. -### 4. Inspect container logs in Grafana (Cockpit) +### 4. Inspect logs -Grafana gives you the actual stdout/stderr from the running container — useful when the cron fires but no S3 log is written (e.g. startup crash before `_get_storage()` succeeds). +Grafana/Cockpit dashboards have not worked for this account — they render empty. Read the logs +through Cockpit's Loki API instead, with the script in `scw_js`: ```bash -# After bin/deploy.sh, retrieve the URL once: -cd terraform -tofu output grafana_url +cd ../scw_js && npx tsx scripts/logs.ts growth --since 24h ``` -Open the URL and log in with your Scaleway account (IAM — no separate Grafana user needed). In Grafana: **Explore → Loki**, query: `{service_name="growth-agent"}`. +One Cockpit token covers the whole Scaleway project, so that command reads this container's logs as +well as every serverless function's. Setup and caveats are in +[`scw_js/README.md`](../scw_js/README.md) → _Reading the logs_. ### Common issues diff --git a/scw_js/README.md b/scw_js/README.md index 7f3916792..c2db3ec00 100644 --- a/scw_js/README.md +++ b/scw_js/README.md @@ -224,6 +224,29 @@ npm run dev:llmx402 npm run dev:llmx402cron ``` +## Reading the logs + +Not the Scaleway console, and not Grafana — both show nothing useful here. `scripts/logs.ts` queries +Cockpit's Loki API directly: + +```bash +npx tsx scripts/logs.ts # which functions are logging +npx tsx scripts/logs.ts facilitator --since 36h --grep "Settlement failed" +npx tsx scripts/logs.ts llmx402cron --since 48h --grep "Refund sweep" +``` + +**It reads the whole Scaleway project, not just this package** — Cockpit is scoped per project, so +the facilitator, analytics and comment-service logs come out of the same command. The script lives +here only because this is where the operational scripts live. + +Needs `SCW_COCKPIT_LOGS_URL` and `SCW_COCKPIT_LOGS_TOKEN` in `.env`. That token is a **Cockpit** +token with `read_only_logs` scope — `SCW_SECRET_KEY` is rejected with a 403 — created with +`scw cockpit token create name= token-scopes.0=read_only_logs region=fr-par`. Its secret is +shown once, so save it immediately: a token whose secret is lost can only be deleted. + +Worth knowing before an incident: a function that has not run inside the `--since` window does not +appear in the discovery listing at all, so widen the window before concluding anything is missing. + ## Deployment ```bash diff --git a/scw_js/llm_x402_cron.ts b/scw_js/llm_x402_cron.ts index a9e921a06..a2db7b561 100644 --- a/scw_js/llm_x402_cron.ts +++ b/scw_js/llm_x402_cron.ts @@ -10,6 +10,7 @@ import { type FacilitatorFeeConfig, } from "./x402_server.js"; import { resyncChannelState } from "./x402_channel_sync.js"; +import type { Channel } from "@x402/evm/batch-settlement/server"; import type { ScwEvent } from "./types.js"; const logger = pino({ level: process.env.LOG_LEVEL ?? "info" }); @@ -60,9 +61,38 @@ interface NetworkResult { refundError?: string; /** How many more claims the current fee approval covers, when it could be read. */ feeAllowanceClaimsLeft?: number; + /** Cached channel records that disagreed with the chain and were corrected. Reported, not + * escalated: the repair is the design, but drift means something upstream is wrong. */ + driftCorrected?: number; + /** Escrow this network's channels still hold, in USDC atomic units. Context for the check + * below, not a condition of its own. */ + escrowHeld?: string; + /** Channels that should have been refunded by now and were not — see assertSweptClean. */ + stuckChannels?: string[]; error?: string; } +/** + * The sweep's own post-condition: after a run, no channel idle past `REFUND_IDLE_SECS` should + * still be holding refundable escrow. + * + * This is the check that would have caught the incident this file's comments describe, and it + * would have caught it without anyone knowing what was wrong. Refunds failed for four unrelated + * reasons over the same period — a stale cached `balance`, a stale `refundNonce`, a + * `refund_transaction_failed` on Base, a `withdraw_delay_mismatch` on Base Sepolia — and every one + * of them presents identically here: escrow that should have gone home and did not. A check + * written against the *outcome* survives the causes. + * + * Deliberately binary, with no threshold to tune: either the sweep did its job or it did not. + */ +function findStuckChannels(channels: Channel[]): string[] { + const idleBefore = Date.now() - REFUND_IDLE_SECS * 1000; + return channels + .filter((c) => c.lastRequestTimestamp < idleBefore) + .filter((c) => BigInt(c.balance) > BigInt(c.chargedCumulativeAmount)) + .map((c) => c.channelId); +} + /** * How many more claims this receiver's USDC approval for the facilitator covers. * @@ -197,6 +227,7 @@ export async function handle( // never hides a good claim. let refunds: number | undefined; let refundError: string | undefined; + let driftCorrected: number | undefined; try { // The SDK builds a refund entirely from the stored record — amount, candidate filter and // signing nonce — and all three are caches that have gone stale in production. A stale @@ -204,7 +235,17 @@ export async function handle( // signs against a nonce the chain already consumed, which reverts and, because the SDK's // refund loop has no per-channel catch, blocks every other refund in the sweep behind it. // 2.08 USDC accumulated that way. See resyncChannelState. - await resyncChannelState(scheme.getStorage(), network); + const synced = await resyncChannelState(scheme.getStorage(), network); + driftCorrected = synced.filter((s) => s.corrected).length; + if (driftCorrected > 0) { + // Warn, not info: the repair working is the design, but a record that disagreed with + // the chain means something upstream wrote it wrong. The stale refundNonce was being + // corrected on every run, at info level, while refunds failed for weeks. + logger.warn( + { network, driftCorrected, of: synced.length }, + "Cached channel state had drifted from the chain and was corrected", + ); + } // The SDK builds refund requirements with `extra: {}`, which the facilitator rejects // as receiver_authorizer_mismatch. Applied after the claim so claim/settle are // untouched. See useEnhancedRefundRequirements. @@ -220,13 +261,28 @@ export async function handle( logger.error({ err, network }, "Refund sweep failed"); } + // The sweep's post-condition, checked against storage as it now stands. Runs even when the + // refund step threw: a failed sweep is exactly when escrow is most likely left behind. + const remaining = await scheme.getStorage().list(); + const escrowHeld = remaining.reduce((sum, c) => sum + BigInt(c.balance), 0n); + const stuckChannels = findStuckChannels(remaining); + if (stuckChannels.length > 0) { + logger.error( + { network, stuckChannels, escrowHeld: escrowHeld.toString() }, + "Channels are past the refund threshold and still hold escrow — the sweep did not do its job", + ); + } + results.push({ network, claims: claims.length, settled: settle !== undefined, ...(refunds !== undefined && { refunds }), ...(refundError !== undefined && { refundError }), + ...(driftCorrected !== undefined && { driftCorrected }), ...(claimsLeft !== null && { feeAllowanceClaimsLeft: claimsLeft }), + escrowHeld: escrowHeld.toString(), + ...(stuckChannels.length > 0 && { stuckChannels }), }); } catch (err) { logger.error({ err, network }, "claimAndSettle failed"); @@ -238,7 +294,17 @@ export async function handle( } } - const hasErrors = results.some((r) => r.error !== undefined); + // Every way this run can have failed, not just the one that throws. + // + // `refundError` used to be invisible here: it is a different key from `error`, so a run that + // claimed correctly and refunded nothing returned 200 and Scaleway recorded a successful + // invocation. That is how a broken refund sweep ran twice a day for weeks without anyone + // noticing. `stuckChannels` is the outcome-level version of the same signal, and catches the + // cases where nothing threw at all. + const hasErrors = results.some( + (r) => + r.error !== undefined || r.refundError !== undefined || (r.stuckChannels?.length ?? 0) > 0, + ); return { statusCode: hasErrors ? 500 : 200, headers, diff --git a/scw_js/scripts/logs.ts b/scw_js/scripts/logs.ts new file mode 100644 index 000000000..3cc1efb89 --- /dev/null +++ b/scw_js/scripts/logs.ts @@ -0,0 +1,153 @@ +/** + * Read any Scaleway function's logs from the terminal. + * + * Why this exists: the answer to an incident is routinely one log line, and until now there was no + * way to reach it. The Scaleway console's log view and the Grafana/Cockpit dashboards both showed + * nothing usable, so a refund that had been failing on every cron run for days was diagnosed by + * replaying transactions on-chain instead — while `"Settlement failed"` sat in the facilitator's + * logs the whole time, carrying the exact revert selector. + * + * **One token, the whole project.** Cockpit is scoped to the Scaleway *project*, not to a service, + * so this reads every function in the account — `facilitator`, `llmx402`, `llmx402cron`, + * `searchapi`, `genimgx402token`, `growthapi`, comments — even though the script lives in `scw_js`. + * It is here because this package already holds the operational scripts; it is not about scw_js. + * Do NOT copy it per package: that would mean the same secret in five gitignored files with no way + * to rotate them together. + * + * Needs `SCW_COCKPIT_LOGS_URL` and `SCW_COCKPIT_LOGS_TOKEN` in `scw_js/.env`. The token is a + * **Cockpit** token (`read_only_logs` scope) — a different credential type from `SCW_SECRET_KEY`, + * which is rejected here with a 403. Create one with: + * + * scw cockpit token create name= token-scopes.0=read_only_logs region=fr-par + * + * Its secret is shown exactly once, so save it immediately; a token whose secret is lost cannot be + * used or audited, only deleted. + * + * Usage (from scw_js/): + * npx tsx scripts/logs.ts # what can I query? (labels + names) + * npx tsx scripts/logs.ts facilitator # last hour, by name fragment + * npx tsx scripts/logs.ts facilitator --since 36h --grep "Settlement failed" + * npx tsx scripts/logs.ts '{resource_name="…"}' --raw # full LogQL, unformatted output + */ +import dotenv from "dotenv"; + +dotenv.config(); + +const URL_BASE = process.env.SCW_COCKPIT_LOGS_URL; +const TOKEN = process.env.SCW_COCKPIT_LOGS_TOKEN; + +if (!URL_BASE || !TOKEN) { + console.error( + "Missing SCW_COCKPIT_LOGS_URL / SCW_COCKPIT_LOGS_TOKEN in scw_js/.env — see this file's header.", + ); + process.exit(1); +} + +/** `36h`, `90m`, `45s` → milliseconds. Relative only: an incident is always "recently", and an + * absolute range is one more thing to get wrong at 2am. */ +function parseSince(raw: string): number { + const match = /^(\d+)([smhd])$/.exec(raw.trim()); + if (!match) { + throw new Error(`--since must look like 30m, 6h or 2d — got ${raw}`); + } + const scale = { s: 1_000, m: 60_000, h: 3_600_000, d: 86_400_000 }[match[2]]!; + return Number(match[1]) * scale; +} + +function flag(name: string, fallback?: string): string | undefined { + const i = process.argv.indexOf(`--${name}`); + return i === -1 ? fallback : process.argv[i + 1]; +} + +const RAW = process.argv.includes("--raw"); +const positional = process.argv.slice(2).filter((a, i, all) => { + if (a.startsWith("--")) return false; + return !all[i - 1]?.startsWith("--") || all[i - 1] === "--raw"; +}); + +const sinceMs = parseSince(flag("since", "1h")!); +const end = Date.now(); +const start = end - sinceMs; +const ns = (ms: number) => `${ms}000000`; + +async function loki( + path: string, + params: Record = {}, +): Promise> { + const url = new global.URL(`${URL_BASE}${path}`); + for (const [k, v] of Object.entries(params)) url.searchParams.set(k, v); + const res = await fetch(url, { headers: { "X-Token": TOKEN! } }); + if (!res.ok) { + // Never echo the token, not even truncated — this output gets pasted into issues. + throw new Error(`${path} failed: HTTP ${res.status} ${(await res.text()).slice(0, 200)}`); + } + return (await res.json()) as Record; +} + +/** + * With no selector, say what is queryable rather than making the caller guess. + * + * Guessing is how the previous attempt failed: `growth-agent/README.md` documents + * `{service_name="growth-agent"}`, a *container* label, and serverless functions do not carry it. + * Note the values are time-windowed by `--since`, so a function that has not run recently is + * absent — widen the window before concluding it does not exist. + */ +async function describe(): Promise { + const labels = (await loki("/loki/api/v1/labels", { start: ns(start), end: ns(end) })) + .data as string[]; + console.log(`labels: ${labels.join(", ")}\n`); + + const names = ( + await loki("/loki/api/v1/label/resource_name/values", { start: ns(start), end: ns(end) }) + ).data as string[]; + console.log(`functions logging in the last ${flag("since", "1h")}:`); + for (const name of names ?? []) console.log(` ${name}`); + console.log(`\nQuery one with: npx tsx scripts/logs.ts --since 6h`); +} + +async function query(target: string): Promise { + // A bare word is matched as a substring of resource_name, because the deployed names carry a + // namespace prefix nobody remembers (`mypersonaljscloudivnad9dy-llmx402`). Anything starting + // with `{` is passed through as LogQL untouched. + const selector = target.startsWith("{") ? target : `{resource_name=~".*${target}.*"}`; + const grep = flag("grep"); + const q = grep ? `${selector} |= ${JSON.stringify(grep)}` : selector; + + const body = await loki("/loki/api/v1/query_range", { + query: q, + start: ns(start), + end: ns(end), + limit: flag("limit", "100")!, + direction: "backward", + }); + + const streams = (body.data as { result?: { values: [string, string][] }[] })?.result ?? []; + const lines = streams.flatMap((s) => s.values).sort((a, b) => Number(a[0]) - Number(b[0])); + + if (lines.length === 0) { + console.log(`no lines for ${q} in the last ${flag("since", "1h")}`); + return; + } + + for (const [ts, line] of lines) { + const when = new Date(Number(ts) / 1e6).toISOString().replace("T", " ").slice(0, 19); + if (RAW) { + console.log(`${when} ${line}`); + continue; + } + // Scaleway wraps each line as {"message": ""}, so the useful text is + // one level in. Anything that does not fit that shape is printed as-is rather than swallowed. + let text = line; + try { + const parsed = JSON.parse(line) as { message?: string }; + if (typeof parsed.message === "string") text = parsed.message; + } catch { + /* not JSON — print the raw line */ + } + console.log(`${when} ${text}`); + } + console.log(`\n${lines.length} line(s). --raw for the unwrapped payload, --limit to widen.`); +} + +const target = positional[0]; +await (target ? query(target) : describe()); diff --git a/scw_js/test/llm_x402_cron.test.ts b/scw_js/test/llm_x402_cron.test.ts index 046c73724..c8ee69eae 100644 --- a/scw_js/test/llm_x402_cron.test.ts +++ b/scw_js/test/llm_x402_cron.test.ts @@ -72,6 +72,7 @@ describe("llm_x402_cron", () => { let mockClaimAndSettle: ReturnType; let mockRefundIdleChannels: ReturnType; let mockSchemeFor: ReturnType; + let mockStorageList: ReturnType; beforeEach(() => { vi.clearAllMocks(); @@ -88,9 +89,12 @@ describe("llm_x402_cron", () => { }); // One scheme per network, each owning storage scoped to that network's S3 prefix. + // list() is read by the post-condition check after every sweep. Default: nothing left + // behind, which is what a healthy run looks like. + mockStorageList = vi.fn().mockResolvedValue([]); mockSchemeFor = vi.fn().mockReturnValue({ createChannelManager: mockCreateChannelManager, - getStorage: vi.fn().mockReturnValue({}), + getStorage: vi.fn().mockReturnValue({ list: mockStorageList }), }); mockResyncChannelState.mockResolvedValue([]); mockUseEnhancedRefundRequirements.mockResolvedValue(undefined); @@ -144,6 +148,10 @@ describe("llm_x402_cron", () => { settled: true, refunds: 0, feeAllowanceClaimsLeft: 100, + // Reported on every run, including the healthy one: "we checked and found nothing" is the + // signal that distinguishes a working sweep from one that never looked. + driftCorrected: 0, + escrowHeld: "0", }); }); @@ -184,6 +192,8 @@ describe("llm_x402_cron", () => { settled: false, refunds: 0, feeAllowanceClaimsLeft: 100, + driftCorrected: 0, + escrowHeld: "0", }); }); @@ -277,13 +287,20 @@ describe("llm_x402_cron", () => { ); }); - it("a failing refund sweep never masks a successful claim", async () => { + /** + * A failed refund sweep still reports its successful claim — but the RUN fails. + * + * It used to return 200: `refundError` is a different key from `error`, and only `error` was + * counted, so Scaleway recorded a successful invocation. That is how a refund sweep that failed + * twice a day went unnoticed for weeks. The claim detail below is what must not be masked; the + * status code is what must not lie. + */ + it("a failing refund sweep fails the run without masking a successful claim", async () => { mockRefundIdleChannels.mockRejectedValue(new Error("facilitator rejected refund")); const res = await handle(makeEvent() as never, {}); - // The claim succeeded, so the run is still a 200 and still reports its claims. - expect(res.statusCode).toBe(200); + expect(res.statusCode).toBe(500); const body = JSON.parse(res.body) as { results: Array<{ claims?: number; refunds?: number; refundError?: string }>; }; @@ -292,6 +309,81 @@ describe("llm_x402_cron", () => { expect(body.results[0].refunds).toBeUndefined(); }); + // ═══════════════════════════════════════════════════════════ + // The sweep's post-condition + // + // Refunds failed for four unrelated reasons over one period — a stale cached balance, a stale + // refundNonce, a refund_transaction_failed on Base, a withdraw_delay_mismatch on Base Sepolia. + // Every one presents identically as escrow that should have gone home and did not, so the check + // is written against that outcome rather than any of the causes. + // ═══════════════════════════════════════════════════════════ + + /** Idle past the threshold, still holding escrow: the sweep did not do its job, whatever the + * reason — including a reason nobody has thought of yet. */ + function stuckChannel(overrides: Record = {}) { + return { + channelId: "0xstuck", + balance: "544239", + chargedCumulativeAmount: "52897", + lastRequestTimestamp: Date.now() - 48 * 3600 * 1000, + ...overrides, + }; + } + + it("fails the run when a channel is past the refund threshold and still holds escrow", async () => { + mockStorageList.mockResolvedValue([stuckChannel()]); + + const res = await handle(makeEvent() as never, {}); + + expect(res.statusCode).toBe(500); + const body = JSON.parse(res.body) as { results: Array<{ stuckChannels?: string[] }> }; + expect(body.results[0].stuckChannels).toEqual(["0xstuck"]); + }); + + /** Nothing thrown, refunds reported as done — and escrow still sitting there. This is the case + * no error-based check can see, and the reason the post-condition is written at all. */ + it("catches stuck escrow even when the sweep reported success", async () => { + mockRefundIdleChannels.mockResolvedValue([{ transaction: "0xabc" }]); + mockStorageList.mockResolvedValue([stuckChannel()]); + + const res = await handle(makeEvent() as never, {}); + + expect(res.statusCode).toBe(500); + }); + + it("passes a channel that is idle but has nothing left to refund", async () => { + mockStorageList.mockResolvedValue([stuckChannel({ balance: "52897" })]); + + const res = await handle(makeEvent() as never, {}); + + expect(res.statusCode).toBe(200); + const body = JSON.parse(res.body) as { + results: Array<{ stuckChannels?: string[]; escrowHeld?: string }>; + }; + expect(body.results[0].stuckChannels).toBeUndefined(); + expect(body.results[0].escrowHeld).toBe("52897"); + }); + + it("passes a funded channel that is still in active use", async () => { + mockStorageList.mockResolvedValue([stuckChannel({ lastRequestTimestamp: Date.now() })]); + + const res = await handle(makeEvent() as never, {}); + + expect(res.statusCode).toBe(200); + }); + + /** Drift is reported but not escalated: the repair working is the design. What must not happen + * is the silence — the stale refundNonce was corrected on every run while refunds failed. */ + it("reports corrected drift without failing the run", async () => { + mockResyncChannelState.mockResolvedValue([{ corrected: true }, { corrected: false }]); + + const res = await handle(makeEvent() as never, {}); + + expect(res.statusCode).toBe(200); + const body = JSON.parse(res.body) as { results: Array<{ driftCorrected?: number }> }; + expect(body.results[0].driftCorrected).toBe(1); + }); + // ═══════════════════════════════════════════════════════════ // Fee-allowance early warning // diff --git a/x402_facilitator/README.md b/x402_facilitator/README.md index 35e542e7b..e35e9b3ce 100644 --- a/x402_facilitator/README.md +++ b/x402_facilitator/README.md @@ -4,6 +4,17 @@ A production-ready x402 v2 Facilitator for Optimism, enabling EIP-3009 USDC paym **Production Endpoint:** https://facilitator.fretchen.eu +> **Logs.** This function's logs are read with `scw_js/scripts/logs.ts`, not from the Scaleway +> console or Grafana: +> +> ```bash +> cd ../scw_js && npx tsx scripts/logs.ts facilitator --since 24h --grep "Settlement failed" +> ``` +> +> One Cockpit token covers the whole project, so the script reads this function from there. The +> `errorMessage` field on a failed settle carries the decoded EVM revert — deliberately logged +> only, never returned over HTTP. + ## Overview The x402 Facilitator bridges the gap between Resource Servers and blockchain payments. It provides three core functions: From 22922c920da7d12253c7302c1c55c81b46d88856 Mon Sep 17 00:00:00 2001 From: fretchen Date: Sun, 20 Sep 2026 14:24:54 +0200 Subject: [PATCH 4/6] First logs coming in --- scw_js/README.md | 37 +++++++++++++ scw_js/alerts/payments.yaml | 92 +++++++++++++++++++++++++++++++++ scw_js/scripts/alerts.ts | 100 ++++++++++++++++++++++++++++++++++++ 3 files changed, 229 insertions(+) create mode 100644 scw_js/alerts/payments.yaml create mode 100644 scw_js/scripts/alerts.ts diff --git a/scw_js/README.md b/scw_js/README.md index c2db3ec00..2dc84fc0e 100644 --- a/scw_js/README.md +++ b/scw_js/README.md @@ -247,6 +247,43 @@ shown once, so save it immediately: a token whose secret is lost can only be del Worth knowing before an incident: a function that has not run inside the `--since` window does not appear in the discovery listing at all, so widen the window before concluding anything is missing. +## Alerting on log content + +Scaleway's built-in alerts are metric-based, and the failure that motivated this section produced no +error metric at all — the facilitator answered HTTP 200 with `success: false` and the revert reason +buried in the body. That is only ever visible as text in a log line, so `alerts/payments.yaml` +defines Loki ruler rules that watch for it directly. + +```bash +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 --delete payments +``` + +Needs `SCW_COCKPIT_RULES_TOKEN` in `.env` — a **separate** Cockpit token from the read-only one +above, scoped `full_access_logs_rules`: +`scw cockpit token create name= token-scopes.0=full_access_logs_rules region=fr-par`. Kept +separate because `logs.ts` is run casually and often and should only ever be able to read; this one +can write and delete alerting rules. + +Four rules, deliberately few — see the comments at the top of `alerts/payments.yaml` for the +reasoning on which four and why the rest were left out. One constraint worth knowing before writing +a fifth: **Scaleway's Loki ruler caps a range-vector window at 1h.** `llmx402cron` runs every 12h, +so a rule cannot stay pinned "firing" across the gap between runs the way a naive `[13h]` window +would suggest — that gets rejected outright. Every rule here uses `[1h]`, which resolves after an +hour and re-fires on the next cron run if the problem persists. Read a resolved notification as "no +new occurrence in the last hour", not as "fixed". + +Push is a manual, explicit step — never wired into deploy. Alerting rules changing as a side effect +of shipping code is its own kind of surprise, and a rule silently dropped by a deploy looks +identical to a system that is simply quiet. + +**A rule that has never fired is not known to work.** Before trusting a new one, push a throwaway +group matching a log line that occurs on every routine run (e.g. `"claimAndSettle completed"`), +confirm the email arrives with the summary/description actually populated, then +`--delete` it. This is exactly how `PaymentCronFailed` was proven to work in practice — pushing a +test rule surfaced a real, previously-unnoticed `withdraw_delay_mismatch` failure on Base Sepolia. + ## Deployment ```bash diff --git a/scw_js/alerts/payments.yaml b/scw_js/alerts/payments.yaml new file mode 100644 index 000000000..1f4fe3f57 --- /dev/null +++ b/scw_js/alerts/payments.yaml @@ -0,0 +1,92 @@ +# Loki alerting rules for the x402 payment path. +# +# Pushed with `npx tsx scripts/alerts.ts --push`; never on deploy. Alerting config that changes as +# a side effect of shipping code is its own kind of surprise. +# +# ── Why these four and not more ──────────────────────────────────────────────────────────────── +# Each rule has to mean "a human needs to do something". The failure mode of alerting is not +# missing an alert, it is sending enough useless ones that people stop reading — which is how the +# refund bug survived for weeks in a log line that was printed every 12 hours. +# +# So: no rule on `"Settlement failed"` as a whole, because most of those are a caller's bad +# signature or their own empty allowance, not our problem. No rule on +# `"Cached channel state had drifted"`, because the repair working is the design. +# +# ── Why the windows are [1h] ─────────────────────────────────────────────────────────────────── +# Scaleway's Loki ruler caps a range-vector window at 1h — a rule written as `[13h]` is rejected +# outright (`matrix selector range 13h0m0s exceeds maximum allowed limit of 1h0m0s`), so there is +# no way to keep an alert pinned open across the 12h gap between `llmx402cron` runs. +# +# The honest design given that cap: `[1h]` fires within an hour of the bad line appearing, then +# resolves — and if the underlying problem is still there, the next cron run produces the same +# line and the rule fires again 12h later. You get paged every time it recurs, just not +# continuously in between. A resolved notification here means "no new occurrence in the last +# hour", not "fixed" — read it that way, don't take it as confirmation. +name: payments +interval: 1m +rules: + # The post-condition of the refund sweep, and the most valuable rule here: it is written against + # the OUTCOME, so it fires for causes nobody has thought of yet. Four unrelated bugs — a stale + # cached balance, a stale refundNonce, a failed refund transaction on Base, a withdrawDelay + # mismatch on Base Sepolia — all present identically as escrow that should have gone home. + - alert: RefundEscrowStuck + expr: | + sum(count_over_time({resource_name=~".+llmx402cron"} |= "still hold escrow" [1h])) > 0 + for: 0m + labels: + severity: critical + area: payments + annotations: + summary: "Escrow is stuck: channels are past the refund threshold and still hold funds" + description: >- + The refund sweep ran and left money behind. This fires on the outcome, so the cause is + open — read the run before assuming which one it is. + Investigate: cd scw_js && npx tsx scripts/logs.ts llmx402cron --since 24h --grep "still hold escrow" + Then: npx tsx scripts/recover_channels.ts eip155:10 (dry run; --apply to recover) + + # The cron's own failures. Always ours, never a caller's. + - alert: PaymentCronFailed + expr: | + sum(count_over_time({resource_name=~".+llmx402cron"} |~ "Refund sweep failed|claimAndSettle failed" [1h])) > 0 + for: 0m + labels: + severity: critical + area: payments + annotations: + summary: "The payment cron failed a claim or refund sweep" + description: >- + Claims or refunds threw. The error reason is in the log line. + Investigate: cd scw_js && npx tsx scripts/logs.ts llmx402cron --since 24h --grep "failed" + + # Only the subset of settle failures that are OUR problem. A bad signature or a caller's empty + # allowance is their business and must not page us. + - alert: FacilitatorNeedsAttention + expr: | + sum(count_over_time({resource_name=~".+facilitator"} |= "Settlement failed" |~ "refund_simulation_failed|insufficient_fee_allowance|settlement_pending" [15m])) > 0 + for: 0m + labels: + severity: critical + area: payments + annotations: + summary: "Facilitator settlement needs attention (not a caller error)" + description: >- + One of: a refund simulation reverted, our fee allowance ran out, or a settlement was + broadcast but never confirmed (settlement_pending carries a tx hash to reconcile). + The decoded EVM revert is in errorMessage, which is logged and never returned over HTTP. + Investigate: cd scw_js && npx tsx scripts/logs.ts facilitator --since 2h --grep "Settlement failed" + + # Days of lead time. claim/settle skip /verify, so this path gets no `remainingSettlements` + # warning from the facilitator — without this the approval simply runs out one day. + - alert: FeeAllowanceLow + expr: | + sum(count_over_time({resource_name=~".+llmx402cron"} |= "Fee allowance nearly exhausted" [1h])) > 0 + for: 0m + labels: + severity: warning + area: payments + annotations: + summary: "Facilitator fee allowance is nearly exhausted" + description: >- + Claims will start failing with insufficient_fee_allowance once it runs out. Re-approve USDC + for the facilitator's spender address from the receiver wallet. + Investigate: cd scw_js && npx tsx scripts/logs.ts llmx402cron --since 24h --grep "allowance" diff --git a/scw_js/scripts/alerts.ts b/scw_js/scripts/alerts.ts new file mode 100644 index 000000000..c963278f8 --- /dev/null +++ b/scw_js/scripts/alerts.ts @@ -0,0 +1,100 @@ +/** + * Manage the Cockpit (Loki) alerting rules that watch our log lines. + * + * Why log-based rules: Scaleway's preconfigured alerts are metric-based, and the failure that + * started all this produced no error metric at all — the facilitator answered 200 with + * `success: false` and the revert reason in the body. It was only ever visible as text in a log + * line. See `logs.ts` for the companion read-only tool. + * + * Needs `SCW_COCKPIT_LOGS_URL` and `SCW_COCKPIT_RULES_TOKEN` in `scw_js/.env`. Deliberately a + * *different* token from `SCW_COCKPIT_LOGS_TOKEN`: `logs.ts` is run casually and often and should + * keep a credential that can only read, while this one can write and delete alerting rules. + * + * scw cockpit token create name= token-scopes.0=full_access_logs_rules region=fr-par + * + * Usage (from scw_js/): + * 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/experiment.yaml + * npx tsx scripts/alerts.ts --delete payments + * + * 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. + */ +import { readFileSync } from "node:fs"; +import dotenv from "dotenv"; + +dotenv.config(); + +const URL_BASE = process.env.SCW_COCKPIT_LOGS_URL; +const TOKEN = process.env.SCW_COCKPIT_RULES_TOKEN; + +if (!URL_BASE || !TOKEN) { + console.error( + "Missing SCW_COCKPIT_LOGS_URL / SCW_COCKPIT_RULES_TOKEN in scw_js/.env — see this file's header.", + ); + process.exit(1); +} + +/** Loki namespaces its rule groups. One per package keeps `--delete` from reaching across + * packages, and keeps the listing readable once something other than scw_js has rules. */ +const NAMESPACE = "scw-js"; + +async function ruler(path: string, init: RequestInit = {}): Promise { + const res = await fetch(`${URL_BASE}/loki/api/v1/rules${path}`, { + ...init, + headers: { "X-Token": TOKEN!, ...(init.headers ?? {}) }, + }); + const text = await res.text(); + // An empty ruler answers 404 with "no rule groups found" — that is success, not an error, and + // it looks identical to a missing namespace. A real permission problem is a bare 403. + if (!res.ok && !(res.status === 404 && text.includes("no rule groups found"))) { + // Never echo the token, not even truncated — this output gets pasted into issues. + throw new Error(`${init.method ?? "GET"} ${path} failed: HTTP ${res.status} ${text.slice(0, 300)}`); + } + return text; +} + +async function list(): Promise { + const text = await ruler(""); + console.log(text.trim() || "(empty)"); + console.log(`\nPush with: npx tsx scripts/alerts.ts --push`); +} + +async function push(file: string): Promise { + const yaml = readFileSync(file, "utf8"); + await ruler(`/${NAMESPACE}`, { + method: "POST", + headers: { "Content-Type": "application/yaml" }, + body: yaml, + }); + console.log(`pushed ${file} to namespace ${NAMESPACE}\n`); + await list(); +} + +async function remove(group: string): Promise { + await ruler(`/${NAMESPACE}/${encodeURIComponent(group)}`, { method: "DELETE" }); + console.log(`deleted group ${group} from namespace ${NAMESPACE}\n`); + await list(); +} + +function flag(name: string): string | undefined { + const i = process.argv.indexOf(`--${name}`); + if (i === -1) return undefined; + const next = process.argv[i + 1]; + return next?.startsWith("--") ? undefined : next; +} + +if (process.argv.includes("--delete")) { + const group = flag("delete"); + if (!group) { + console.error("--delete needs a group name, e.g. --delete payments"); + process.exit(1); + } + await remove(group); +} else if (process.argv.includes("--push")) { + await push(flag("push") ?? "alerts/payments.yaml"); +} else { + await list(); +} From 6ad68e146ca0f6c0d458d025485d1600d36521f5 Mon Sep 17 00:00:00 2001 From: fretchen Date: Sun, 20 Sep 2026 14:38:49 +0200 Subject: [PATCH 5/6] fix the bugs with the x402 processing --- scw_js/scripts/alerts.ts | 4 +- scw_js/test/llm_x402_cron.test.ts | 36 +++++++++++ scw_js/test/x402_refund_requirements.test.ts | 58 ++++++++++++++++- scw_js/x402_server.ts | 27 +++++++- x402_facilitator/openapi.json | 8 +++ .../test/x402_facilitator.test.ts | 64 +++++++++++++++++++ x402_facilitator/x402_facilitator.ts | 4 ++ x402_facilitator/x402_schemas.ts | 28 ++++++++ 8 files changed, 225 insertions(+), 4 deletions(-) diff --git a/scw_js/scripts/alerts.ts b/scw_js/scripts/alerts.ts index c963278f8..c8ef0594e 100644 --- a/scw_js/scripts/alerts.ts +++ b/scw_js/scripts/alerts.ts @@ -51,7 +51,9 @@ async function ruler(path: string, init: RequestInit = {}): Promise { // it looks identical to a missing namespace. A real permission problem is a bare 403. if (!res.ok && !(res.status === 404 && text.includes("no rule groups found"))) { // Never echo the token, not even truncated — this output gets pasted into issues. - throw new Error(`${init.method ?? "GET"} ${path} failed: HTTP ${res.status} ${text.slice(0, 300)}`); + throw new Error( + `${init.method ?? "GET"} ${path} failed: HTTP ${res.status} ${text.slice(0, 300)}`, + ); } return text; } diff --git a/scw_js/test/llm_x402_cron.test.ts b/scw_js/test/llm_x402_cron.test.ts index c8ee69eae..3e01636a7 100644 --- a/scw_js/test/llm_x402_cron.test.ts +++ b/scw_js/test/llm_x402_cron.test.ts @@ -287,6 +287,42 @@ describe("llm_x402_cron", () => { ); }); + /** + * The resync must come FIRST, and this ordering is the whole reason refunds work at all. + * + * The SDK refunds `balance - chargedCumulativeAmount` read from the stored record, and signs + * the refund against the stored `refundNonce`. Both are caches of chain state that the verify + * path zeroes, so a sweep run against unsynced storage either skips the channel (the SDK's own + * `balance === 0n` filter) or signs against an already-consumed nonce and reverts on chain. + * + * Nothing asserted this before — the ordering held by accident of source order, which is not + * the same as being guaranteed. + */ + it("resyncs cached channel state before sweeping, not after", async () => { + await handle(makeEvent() as never, {}); + + expect(mockResyncChannelState).toHaveBeenCalled(); + expect(mockResyncChannelState.mock.invocationCallOrder[0]).toBeLessThan( + mockRefundIdleChannels.mock.invocationCallOrder[0], + ); + }); + + /** + * A resync that throws must fail the run rather than let the sweep proceed on stale state. + * It sits inside the same try as the sweep, so it surfaces as `refundError` — asserted here + * so that staying true is a deliberate choice, not an accident of where the try block ends. + */ + it("fails the run when the resync throws, instead of sweeping stale state", async () => { + mockResyncChannelState.mockRejectedValue(new Error("S3 unavailable")); + + const result = await handle(makeEvent() as never, {}); + + expect(result.statusCode).toBe(500); + const body = JSON.parse(result.body); + expect(body.results[0].refundError).toBe("S3 unavailable"); + expect(mockRefundIdleChannels).not.toHaveBeenCalled(); + }); + /** * A failed refund sweep still reports its successful claim — but the RUN fails. * diff --git a/scw_js/test/x402_refund_requirements.test.ts b/scw_js/test/x402_refund_requirements.test.ts index f5e3fdfd0..e363b72e5 100644 --- a/scw_js/test/x402_refund_requirements.test.ts +++ b/scw_js/test/x402_refund_requirements.test.ts @@ -52,7 +52,7 @@ describe("useEnhancedRefundRequirements", () => { * Present in @x402/evm 2.25 and 2.26 alike, so this guard stays until the SDK enhances its * own refund requirements. */ - it("replaces the manager's empty extra with receiverAuthorizer and withdrawDelay", async () => { + it("replaces the manager's empty extra with the receiverAuthorizer", async () => { const scheme = makeScheme(); const manager = makeManager(); expect(manager.buildPaymentRequirements().extra).toEqual({}); @@ -65,7 +65,61 @@ describe("useEnhancedRefundRequirements", () => { const extra = (manager.buildPaymentRequirements() as { extra: Record }).extra; expect(extra.receiverAuthorizer).toBe(AUTHORIZER); - expect(extra.withdrawDelay).toBe(86400); + }); + + /** + * This one asserts an ABSENCE, and an earlier version of this file asserted the opposite + * (`expect(extra.withdrawDelay).toBe(86400)`) — so read the reason before restoring it. + * + * `withdrawDelay` is one of the seven fields hashed into `computeChannelId`, so it is fixed + * per channel at creation. The enhancer stamps the CURRENT server config instead, and the + * facilitator compares the two: + * + * if (extra?.withdrawDelay !== undefined && config.withdrawDelay !== Number(extra.withdrawDelay)) + * return ErrWithdrawDelayMismatch; + * + * When LLM_WITHDRAW_DELAY_SECONDS went 900 -> 86400, every channel opened under the old value + * became permanently unrefundable — `withdraw_delay_mismatch` on every 12h sweep, escrow + * stranded with no route back, because the stored 900 is correct and cannot be migrated. + * + * Omitting the field skips that equality branch. The channel is still bound by the + * `computeChannelId(config) === channelId` check that runs first, so this drops a policy + * assertion, not a security one. + */ + it("omits withdrawDelay, so a channel opened under an older config can still be refunded", async () => { + const scheme = makeScheme(); + const manager = makeManager(); + + await useEnhancedRefundRequirements(scheme as never, manager, { + network: "eip155:10", + asset: USDC, + payTo: PAY_TO, + }); + + const extra = (manager.buildPaymentRequirements() as { extra: Record }).extra; + expect(extra).not.toHaveProperty("withdrawDelay"); + }); + + /** + * The bug this fixes, stated as the caller sees it: the server's current delay disagreeing + * with a stored channel's own delay must never be what blocks a refund. Pinned against the + * class rather than the numbers, so it keeps meaning if the default changes again. + */ + it("produces the same refund requirements whatever the server's current withdrawDelay is", async () => { + const extras = await Promise.all( + [900, 86400, 2592000].map(async (delay) => { + const manager = makeManager(); + await useEnhancedRefundRequirements(makeScheme(delay) as never, manager, { + network: "eip155:10", + asset: USDC, + payTo: PAY_TO, + }); + return (manager.buildPaymentRequirements() as { extra: Record }).extra; + }), + ); + + expect(extras[0]).toEqual(extras[1]); + expect(extras[1]).toEqual(extras[2]); }); it("keeps the network, asset and payTo the facilitator cross-checks against", async () => { diff --git a/scw_js/x402_server.ts b/scw_js/x402_server.ts index 04a4dab33..bdd06c395 100644 --- a/scw_js/x402_server.ts +++ b/scw_js/x402_server.ts @@ -240,8 +240,33 @@ export async function useEnhancedRefundRequirements( }, [], ); + + // Drop `withdrawDelay`, which the enhancer stamps from the CURRENT server config. It is part + // of `computeChannelId` (payer, payerAuthorizer, receiver, receiverAuthorizer, token, + // withdrawDelay, salt), so it is fixed per channel at creation and can never be updated — a + // different delay is a different channel. The facilitator's validateChannelConfig compares + // the payload's stored config against this field: + // + // if (extra?.withdrawDelay !== undefined && config.withdrawDelay !== Number(extra.withdrawDelay)) + // return ErrWithdrawDelayMismatch; + // + // so once LLM_WITHDRAW_DELAY_SECONDS changed (900 -> 86400, commit 313e76df), every channel + // opened before it became permanently unrefundable: `withdraw_delay_mismatch` on every sweep, + // escrow stranded with no way back. Absent, the equality branch is skipped; the range check + // that follows still applies (MIN_WITHDRAW_DELAY is 900). + // + // Safe to omit because the check immediately above it in the same function already binds the + // config cryptographically — `computeChannelId(config) === channelId` fails first if anything + // in the config was forged. The equality test is policy ("this channel matches today's + // setting"), not security, and enforcing today's policy on an old channel only strands funds. + // `receiverAuthorizer` is kept: that one the facilitator fails closed on, and it is why this + // function exists. + const enhancedExtra = (enhanced as { extra?: Record }).extra ?? {}; + const { withdrawDelay: _configuredDelay, ...extraWithoutDelay } = enhancedExtra; + const refundRequirements = { ...enhanced, extra: extraWithoutDelay }; + (manager as { buildPaymentRequirements: () => unknown }).buildPaymentRequirements = () => - enhanced; + refundRequirements; } export interface BatchSettlementPaymentRequirementsOptions { diff --git a/x402_facilitator/openapi.json b/x402_facilitator/openapi.json index 44a4abba6..cb69ee262 100644 --- a/x402_facilitator/openapi.json +++ b/x402_facilitator/openapi.json @@ -200,6 +200,14 @@ "type": "integer", "minimum": -9007199254740991, "maximum": 9007199254740991 + }, + "extra": { + "description": "Scheme-specific state from the verifier, passed through verbatim. For batch-settlement this carries the on-chain channel state (balance, totalClaimed, refundNonce, withdrawRequestedAt) that the seller caches — omitting it makes the seller cache zeros.", + "type": "object", + "propertyNames": { + "type": "string" + }, + "additionalProperties": {} } }, "required": ["isValid"], diff --git a/x402_facilitator/test/x402_facilitator.test.ts b/x402_facilitator/test/x402_facilitator.test.ts index fad48fb1f..5feeebb19 100644 --- a/x402_facilitator/test/x402_facilitator.test.ts +++ b/x402_facilitator/test/x402_facilitator.test.ts @@ -126,6 +126,70 @@ describe("x402_facilitator handlers", () => { expect(body.payer).toBe("0xf39Fd6e51aad88F6F4ce6aB8827279cffFb92266"); }); + /** + * The September incident, in one assertion. This endpoint used to build its response from a + * fixed field list and silently drop `extra`, which for batch-settlement carries the channel + * state the seller caches. The seller's SDK writes its record from that field WHOLESALE, + * defaulting each key to zero: + * + * const ex = result.extra ?? {}; + * const balance = readExtraString(ex, "balance", "0"); + * const refundNonce = readExtraNumber(ex, "refundNonce", 0); + * + * So dropping it did not leave the seller's record alone — it zeroed the real balance and + * nonce on every single verify, which surfaced as "payment channel too low" on funded + * channels and refunds reverting on an already-consumed nonce. + * + * Nothing asserted this passthrough before, which is exactly how it was lost. + */ + it("forwards the scheme's extra, which the seller caches as its channel state", async () => { + const channelState = { + channelId: "0xdd9e576d5d30096bce8ed29916ee2d3faaf3a34269011b881eccfb0e082719d7", + balance: "21300", + totalClaimed: "5680", + withdrawRequestedAt: 0, + refundNonce: "1", + }; + verifyPayment.mockResolvedValue({ + isValid: true, + payer: "0xf39Fd6e51aad88F6F4ce6aB8827279cffFb92266", + extra: channelState, + }); + + const event = { + httpMethod: "POST", + body: JSON.stringify({ + paymentPayload: { accepted: { network: "eip155:10" } }, + paymentRequirements: { amount: "1000000" }, + }), + }; + const result = await handleVerify(event, {}); + + // Verbatim: the seller reads these keys directly, so a reshaped or partial copy is as + // damaging as none at all. + expect(JSON.parse(result.body).extra).toEqual(channelState); + }); + + it("omits extra entirely when the scheme produced none", async () => { + verifyPayment.mockResolvedValue({ + isValid: true, + payer: "0xf39Fd6e51aad88F6F4ce6aB8827279cffFb92266", + }); + + const event = { + httpMethod: "POST", + body: JSON.stringify({ + paymentPayload: { accepted: { network: "eip155:10" } }, + paymentRequirements: { amount: "1000000" }, + }), + }; + const result = await handleVerify(event, {}); + + // Absent, not `"extra": null` — the seller tests `result.extra ?? {}`, and a null would + // read as "no state" just the same, but an explicit null is a claim we have none. + expect(JSON.parse(result.body)).not.toHaveProperty("extra"); + }); + it("should return invalid payment result with reason", async () => { verifyPayment.mockResolvedValue({ isValid: false, diff --git a/x402_facilitator/x402_facilitator.ts b/x402_facilitator/x402_facilitator.ts index f70a7c062..9806c2982 100644 --- a/x402_facilitator/x402_facilitator.ts +++ b/x402_facilitator/x402_facilitator.ts @@ -318,6 +318,10 @@ async function handlePaymentRequest( ...(result.remainingSettlements !== undefined && { remainingSettlements: result.remainingSettlements, }), + // Must be forwarded, not summarised: the seller writes its cached channel record + // straight from this, and a missing `extra` makes it cache zeros rather than leave + // the record alone. See VerifyResponseSchema.extra. /settle already does this. + ...(result.extra !== undefined && { extra: result.extra }), }; return { statusCode: 200, diff --git a/x402_facilitator/x402_schemas.ts b/x402_facilitator/x402_schemas.ts index dae1a1313..de27c133a 100644 --- a/x402_facilitator/x402_schemas.ts +++ b/x402_facilitator/x402_schemas.ts @@ -80,6 +80,34 @@ export const VerifyResponseSchema = z.object({ "still covers. Present only when a fee is configured and the allowance could be " + "read — an early warning before it hits zero.", ), + /** + * Scheme-specific state, forwarded from the scheme verifier untouched. + * + * Omitting it is not cosmetic — it corrupts the seller's channel store. The seller's SDK + * writes its cached channel record straight from this field, WHOLESALE, with zero defaults: + * + * const ex = result.extra ?? {}; + * const balance = readExtraString(ex, "balance", "0"); + * const refundNonce = readExtraNumber(ex, "refundNonce", 0); + * + * A response without `extra` therefore does not leave the record alone, it overwrites the + * real balance and nonce with zeros on every verify — and stamps `onchainSyncedAt`, marking + * the poisoned record fresh so later local verifies copy the zeros forward. That was the + * September incident: "payment channel too low" on funded channels, and refunds reverting on + * a consumed nonce while escrow sat unrecoverable. + * + * Never rebuild it field by field here: verify reads flat keys, settle reads a nested + * `channelState`, and hand-assembling either is how it was lost in the first place. + */ + extra: z + .record(z.string(), z.unknown()) + .optional() + .describe( + "Scheme-specific state from the verifier, passed through verbatim. For " + + "batch-settlement this carries the on-chain channel state (balance, totalClaimed, " + + "refundNonce, withdrawRequestedAt) that the seller caches — omitting it makes the " + + "seller cache zeros.", + ), }); export type VerifyResponseBody = z.infer; From 4921474a722180dfeeab8e16dccfff6404ecc36c Mon Sep 17 00:00:00 2001 From: fretchen Date: Sun, 20 Sep 2026 14:48:53 +0200 Subject: [PATCH 6/6] fix after review --- scw_js/alerts/payments.yaml | 8 ++- scw_js/llm_x402_cron.ts | 15 ++++- scw_js/scripts/recover_channels.ts | 7 +++ scw_js/test/alerts_payments.test.ts | 56 +++++++++++++++++++ scw_js/test/llm_x402_cron.test.ts | 15 +++++ scw_js/test/x402_channel_sync.test.ts | 24 +++++++- scw_js/x402_channel_sync.ts | 7 +++ x402_facilitator/openapi.json | 2 +- .../test/x402_facilitator.test.ts | 32 +++++++++++ x402_facilitator/test/x402_settle.test.js | 13 +++++ x402_facilitator/x402_facilitator.ts | 5 +- x402_facilitator/x402_schemas.ts | 5 +- 12 files changed, 181 insertions(+), 8 deletions(-) create mode 100644 scw_js/test/alerts_payments.test.ts diff --git a/scw_js/alerts/payments.yaml b/scw_js/alerts/payments.yaml index 1f4fe3f57..bac182bd6 100644 --- a/scw_js/alerts/payments.yaml +++ b/scw_js/alerts/payments.yaml @@ -60,9 +60,15 @@ rules: # Only the subset of settle failures that are OUR problem. A bad signature or a caller's empty # allowance is their business and must not page us. + # + # `refund_[a-z_]*failed` matches the family, not a list: it started as refund_simulation_failed + # alone and missed refund_transaction_failed, one of the four causes of the incident above, which + # then paged nothing until the 12-hourly cron tripped RefundEscrowStuck. withdraw_delay_mismatch + # stays out deliberately — it is a channel-config disagreement a buyer can cause, and the outcome + # rule above already catches the version of it that costs anyone money. - alert: FacilitatorNeedsAttention expr: | - sum(count_over_time({resource_name=~".+facilitator"} |= "Settlement failed" |~ "refund_simulation_failed|insufficient_fee_allowance|settlement_pending" [15m])) > 0 + sum(count_over_time({resource_name=~".+facilitator"} |= "Settlement failed" |~ "refund_[a-z_]*failed|insufficient_fee_allowance|settlement_pending" [1h])) > 0 for: 0m labels: severity: critical diff --git a/scw_js/llm_x402_cron.ts b/scw_js/llm_x402_cron.ts index a2db7b561..66535252a 100644 --- a/scw_js/llm_x402_cron.ts +++ b/scw_js/llm_x402_cron.ts @@ -64,8 +64,8 @@ interface NetworkResult { /** Cached channel records that disagreed with the chain and were corrected. Reported, not * escalated: the repair is the design, but drift means something upstream is wrong. */ driftCorrected?: number; - /** Escrow this network's channels still hold, in USDC atomic units. Context for the check - * below, not a condition of its own. */ + /** Escrow this network's channels still hold (deposits minus what has been claimed out), in + * USDC atomic units. Context for the check below, not a condition of its own. */ escrowHeld?: string; /** Channels that should have been refunded by now and were not — see assertSweptClean. */ stuckChannels?: string[]; @@ -264,7 +264,16 @@ export async function handle( // The sweep's post-condition, checked against storage as it now stands. Runs even when the // refund step threw: a failed sweep is exactly when escrow is most likely left behind. const remaining = await scheme.getStorage().list(); - const escrowHeld = remaining.reduce((sum, c) => sum + BigInt(c.balance), 0n); + // `balance` is cumulative DEPOSITS — claims do not decrement it, they move funds out via + // `totalClaimed` (the SDK validates a voucher's cumulative maxClaimable against `balance`, + // so it has to keep growing). Summing `balance` alone therefore reports money that has + // already been collected as still at risk, in the field printed next to the stuck-escrow + // error. Clamped at zero so a record caught mid-drift reads as nothing held rather than a + // negative total. + const escrowHeld = remaining.reduce((sum, c) => { + const held = BigInt(c.balance) - BigInt(c.totalClaimed); + return sum + (held > 0n ? held : 0n); + }, 0n); const stuckChannels = findStuckChannels(remaining); if (stuckChannels.length > 0) { logger.error( diff --git a/scw_js/scripts/recover_channels.ts b/scw_js/scripts/recover_channels.ts index d5dbcad57..671311a0f 100644 --- a/scw_js/scripts/recover_channels.ts +++ b/scw_js/scripts/recover_channels.ts @@ -73,10 +73,17 @@ async function main(): Promise { const synced = await resyncChannelState(scheme.getStorage(), network, { dryRun: !APPLY }); for (const s of synced) { if (!s.corrected) continue; + // One entry per term of resyncChannelState's `corrected` predicate, so a corrected channel + // can never print as a bare id with nothing after it. const drifted: string[] = []; if (s.storedBalance !== s.chainBalance) { drifted.push(`balance ${usdc(s.storedBalance)} -> ${usdc(s.chainBalance)} USDC`); } + if (s.storedTotalClaimed !== s.chainTotalClaimed) { + drifted.push( + `totalClaimed ${usdc(s.storedTotalClaimed)} -> ${usdc(s.chainTotalClaimed)} USDC`, + ); + } // A stale nonce is the difference between a refund that works and one that reverts, so it is // reported as its own line rather than folded into a generic "was stale". if (s.storedRefundNonce !== s.chainRefundNonce) { diff --git a/scw_js/test/alerts_payments.test.ts b/scw_js/test/alerts_payments.test.ts new file mode 100644 index 000000000..532ccf25c --- /dev/null +++ b/scw_js/test/alerts_payments.test.ts @@ -0,0 +1,56 @@ +/** + * The alert rules are pushed as raw text by `scripts/alerts.ts` and never exercised locally, so + * nothing else would notice a rule that stopped matching the line it was written for. These two + * checks are the ones a human cannot do by eye: whether a filter still matches real log text, and + * whether every window respects the 1h cap Scaleway's ruler enforces. + */ +import { describe, it, expect } from "vitest"; +import { readFileSync } from "node:fs"; +import { fileURLToPath } from "node:url"; + +const yaml = readFileSync( + fileURLToPath(new URL("../alerts/payments.yaml", import.meta.url)), + "utf8", +); + +/** The `|~ "..."` line filter of a named rule, as a usable RegExp. */ +function lineFilterOf(alertName: string): RegExp { + const rule = yaml.slice(yaml.indexOf(`alert: ${alertName}`)); + const match = /\|~ "([^"]+)"/.exec(rule); + if (!match) throw new Error(`No |~ filter found for ${alertName}`); + return new RegExp(match[1]); +} + +describe("alerts/payments.yaml", () => { + /** Scaleway's Loki ruler rejects a range window above 1h outright, and a shorter one silently + * narrows the window in which a 12-hourly cron's line can be seen. */ + it("uses the 1h range window everywhere", () => { + // Matched inside count_over_time only: the header comment names a rejected `[13h]` to explain + // why the cap exists, and a check that failed on prose would teach people to delete the prose. + const windows = [...yaml.matchAll(/count_over_time\([^)]*\[(\d+[smhd])\]/g)].map((m) => m[1]); + expect(windows.length).toBeGreaterThan(0); + expect([...new Set(windows)]).toEqual(["1h"]); + }); + + describe("FacilitatorNeedsAttention", () => { + const filter = lineFilterOf("FacilitatorNeedsAttention"); + + it.each([ + "refund_simulation_failed", + "refund_transaction_failed", + "insufficient_fee_allowance", + "settlement_pending", + ])("pages on %s", (reason) => { + expect(filter.test(`{"errorReason":"${reason}","msg":"Settlement failed"}`)).toBe(true); + }); + + /** The rule exists to be narrower than "Settlement failed": a caller's bad signature or empty + * allowance is their problem, and paging on it is how people stop reading alerts. */ + it.each(["invalid_signature", "insufficient_funds", "authorization_already_used"])( + "stays quiet on the caller error %s", + (reason) => { + expect(filter.test(`{"errorReason":"${reason}","msg":"Settlement failed"}`)).toBe(false); + }, + ); + }); +}); diff --git a/scw_js/test/llm_x402_cron.test.ts b/scw_js/test/llm_x402_cron.test.ts index 3e01636a7..869379123 100644 --- a/scw_js/test/llm_x402_cron.test.ts +++ b/scw_js/test/llm_x402_cron.test.ts @@ -360,6 +360,7 @@ describe("llm_x402_cron", () => { return { channelId: "0xstuck", balance: "544239", + totalClaimed: "0", chargedCumulativeAmount: "52897", lastRequestTimestamp: Date.now() - 48 * 3600 * 1000, ...overrides, @@ -400,6 +401,20 @@ describe("llm_x402_cron", () => { expect(body.results[0].escrowHeld).toBe("52897"); }); + /** `balance` is cumulative deposits, so a channel with claim history holds less than it has + * received. Reporting the deposits would overstate the money at risk in the very line the + * stuck-escrow alert points a human at. */ + it("reports escrow net of what has already been claimed out", async () => { + mockStorageList.mockResolvedValue([ + stuckChannel({ balance: "544239", totalClaimed: "52897", chargedCumulativeAmount: "52897" }), + ]); + + const res = await handle(makeEvent() as never, {}); + + const body = JSON.parse(res.body) as { results: Array<{ escrowHeld?: string }> }; + expect(body.results[0].escrowHeld).toBe("491342"); + }); + it("passes a funded channel that is still in active use", async () => { mockStorageList.mockResolvedValue([stuckChannel({ lastRequestTimestamp: Date.now() })]); diff --git a/scw_js/test/x402_channel_sync.test.ts b/scw_js/test/x402_channel_sync.test.ts index 5a6b5231a..d99ca931c 100644 --- a/scw_js/test/x402_channel_sync.test.ts +++ b/scw_js/test/x402_channel_sync.test.ts @@ -129,9 +129,31 @@ describe("resyncChannelState", () => { const { storage, channels } = makeStorage([makeChannel({ balance: "0", totalClaimed: "0" })]); setChain({ balance: 1_000_000n, totalClaimed: 35_147n }); - await resyncChannelState(storage, OP); + const results = await resyncChannelState(storage, OP); expect(channels[0].totalClaimed).toBe("35147"); + expect(results[0].storedTotalClaimed).toBe("0"); + expect(results[0].chainTotalClaimed).toBe("35147"); + }); + + /** + * `corrected` is true when any of the three chain-owned fields drifted, so the result has to + * carry all three: with only the balance and nonce pairs reported, a channel whose totalClaimed + * alone had moved came out of `scripts/recover_channels.ts` as a bare id with no reason after it. + */ + it("reports a totalClaimed-only drift, which nothing else in the result would show", async () => { + const { storage } = makeStorage([ + makeChannel({ balance: "544239", totalClaimed: "0", refundNonce: 1 }), + ]); + setChain({ balance: 544_239n, totalClaimed: 52_897n, refundNonce: 1n }); + + const results = await resyncChannelState(storage, OP); + + expect(results[0].corrected).toBe(true); + expect(results[0].storedBalance).toBe(results[0].chainBalance); + expect(results[0].storedRefundNonce).toBe(results[0].chainRefundNonce); + expect(results[0].storedTotalClaimed).toBe("0"); + expect(results[0].chainTotalClaimed).toBe("52897"); }); /** diff --git a/scw_js/x402_channel_sync.ts b/scw_js/x402_channel_sync.ts index 40c470839..9d418b95c 100644 --- a/scw_js/x402_channel_sync.ts +++ b/scw_js/x402_channel_sync.ts @@ -37,6 +37,11 @@ export interface ChannelSyncResult { channelId: string; storedBalance: string; chainBalance: string; + /** Carried for the same reason as the balance pair: `corrected` is true when ANY of the three + * chain-owned fields drifted, so a caller that reports the drift needs all three or it prints + * a channel id with no reason after it. */ + storedTotalClaimed: string; + chainTotalClaimed: string; storedRefundNonce: number; chainRefundNonce: number; corrected: boolean; @@ -120,6 +125,8 @@ export async function resyncChannelState( channelId: channel.channelId, storedBalance: channel.balance, chainBalance: chainBalance.toString(), + storedTotalClaimed: channel.totalClaimed, + chainTotalClaimed: chainTotalClaimed.toString(), storedRefundNonce: channel.refundNonce, chainRefundNonce: Number(chainRefundNonce), corrected, diff --git a/x402_facilitator/openapi.json b/x402_facilitator/openapi.json index cb69ee262..3361d0ce6 100644 --- a/x402_facilitator/openapi.json +++ b/x402_facilitator/openapi.json @@ -223,7 +223,7 @@ "type": "string" }, "transaction": { - "description": "On-chain settlement tx hash. Empty string on failure.", + "description": "On-chain settlement tx hash. Empty string on a terminal failure; on errorReason settlement_pending it carries the broadcast-but-unconfirmed hash to reconcile.", "type": "string" }, "network": { diff --git a/x402_facilitator/test/x402_facilitator.test.ts b/x402_facilitator/test/x402_facilitator.test.ts index 5feeebb19..4ae366320 100644 --- a/x402_facilitator/test/x402_facilitator.test.ts +++ b/x402_facilitator/test/x402_facilitator.test.ts @@ -395,6 +395,38 @@ describe("x402_facilitator handlers", () => { expect(body.transaction).toBe(""); }); + /** + * The contrast to the case above. `settlement_pending` is the one `success: false` that is + * recoverable: the transaction was broadcast and only the receipt wait timed out, so the + * hash has to survive the HTTP boundary — blanking it leaves the caller unable to tell a + * settlement that never happened from one that may already have confirmed, and retrying is + * then a double payment. + */ + it("forwards the broadcast hash on settlement_pending instead of blanking it", async () => { + settlePayment.mockResolvedValue({ + success: false, + errorReason: "settlement_pending", + payer: "0xf39Fd6e51aad88F6F4ce6aB8827279cffFb92266", + transaction: "0xbroadcastbutunconfirmed", + network: "eip155:10", + }); + + const event = { + httpMethod: "POST", + body: JSON.stringify({ + paymentPayload: { accepted: { network: "eip155:10" } }, + paymentRequirements: { amount: "1000000" }, + }), + }; + const result = await handleSettle(event, {}); + + expect(result.statusCode).toBe(200); + const body = JSON.parse(result.body); + expect(body.success).toBe(false); + expect(body.errorReason).toBe("settlement_pending"); + expect(body.transaction).toBe("0xbroadcastbutunconfirmed"); + }); + it("should handle unexpected settlement error", async () => { settlePayment.mockRejectedValue(new Error("Unexpected error")); diff --git a/x402_facilitator/test/x402_settle.test.js b/x402_facilitator/test/x402_settle.test.js index 37268303a..d286bdd3a 100644 --- a/x402_facilitator/test/x402_settle.test.js +++ b/x402_facilitator/test/x402_settle.test.js @@ -18,6 +18,19 @@ vi.mock("viem", async () => { blockNumber: 12345678n, transactionHash: hash, })), + // @x402/evm 2.26 added an asset-is-a-contract precheck to the exact scheme's verify: + // `verifyEIP3009` calls `startAssetContractCheck`, which eth_getCode's the token and + // treats an empty result as "not a deployed contract". Without this the mock throws + // `publicClient.getCode is not a function`. + // + // It has to be mocked even though no assertion here cares about it, because the check is + // started in a constructor and only awaited later — so a verify that returns early (a bad + // signature, say) abandons the promise and its rejection surfaces as an UNHANDLED one. + // Vitest then exits non-zero with every test still reported as passing, which is how this + // stayed invisible until CI failed on it. + // + // Any non-"0x" bytecode satisfies the check; the value is never inspected. + getCode: vi.fn(async () => "0x60806040"), })), createWalletClient: vi.fn(() => ({ writeContract: vi.fn( diff --git a/x402_facilitator/x402_facilitator.ts b/x402_facilitator/x402_facilitator.ts index 9806c2982..1e2d1aacc 100644 --- a/x402_facilitator/x402_facilitator.ts +++ b/x402_facilitator/x402_facilitator.ts @@ -294,7 +294,10 @@ async function handlePaymentRequest( success: false, errorReason: result.errorReason, payer: result.payer, - transaction: "", + // Forwarded, not blanked: settlePayment already returns "" for every terminal failure + // and the broadcast hash for settlement_pending — the one failure a caller can + // reconcile on chain instead of retrying a transaction that may have confirmed. + transaction: result.transaction ?? "", network: result.network, }; return { diff --git a/x402_facilitator/x402_schemas.ts b/x402_facilitator/x402_schemas.ts index de27c133a..0be9321f6 100644 --- a/x402_facilitator/x402_schemas.ts +++ b/x402_facilitator/x402_schemas.ts @@ -136,7 +136,10 @@ export const SettleResponseSchema = z.object({ transaction: z .string() .optional() - .describe("On-chain settlement tx hash. Empty string on failure."), + .describe( + "On-chain settlement tx hash. Empty string on a terminal failure; on " + + "errorReason settlement_pending it carries the broadcast-but-unconfirmed hash to reconcile.", + ), network: z.string().optional().describe("CAIP-2 network id the settlement ran on."), errorReason: z.string().optional().describe("Present when success is false."), fee: z