From 7fa071267c0b62c592243cf00902bc8b64a8ba0a Mon Sep 17 00:00:00 2001 From: Peter Steinberger Date: Tue, 25 Nov 2025 03:48:49 +0100 Subject: [PATCH] feat: add logger and twilio poll backoff --- docs/refactor/plan.md | 7 ++-- src/auto-reply/claude.test.ts | 16 +++++++-- src/auto-reply/claude.ts | 22 ++++++++++-- src/auto-reply/reply.ts | 68 +++++++++++++++++++++++++++++++---- src/index.ts | 2 +- src/logger.ts | 26 ++++++++++++++ src/provider-web.ts | 12 +++---- src/twilio/monitor.ts | 26 ++++++++++---- 8 files changed, 151 insertions(+), 28 deletions(-) create mode 100644 src/logger.ts diff --git a/docs/refactor/plan.md b/docs/refactor/plan.md index 21d2b8914..a25d317e8 100644 --- a/docs/refactor/plan.md +++ b/docs/refactor/plan.md @@ -14,11 +14,12 @@ This is a living note capturing the cleanups underway to keep `warelay` small an - Added prompt/wait helpers (`src/cli/{prompt,wait}.ts`) and Twilio sender discovery module (`src/twilio/senders.ts`). - Slimmed `src/index.ts` to ~130 LOC. - README updated to document direct WhatsApp Web support and Claude output handling. +- Added zod validation for `~/.warelay/warelay.json` and a `--dry-run` flag for `send`. +- Introduced a tiny logger (`src/logger.ts`) and backoff retry in Twilio polling. ## In this pass -- Added config validation for inbound reply settings (claude output format, command/text shape). -- Added `--dry-run` for `send` to print the outbound payload without contacting providers. -- Documented roadmap (this file). +- Wire more modules to the logger; keep colors/verbosity consistent. +- Add minimal retries/backoff for webhook bring-up and port/Tailscale helpers. ## Next candidates (not yet done) - Centralize logging/verbosity (runtime-aware logger wrapper). diff --git a/src/auto-reply/claude.test.ts b/src/auto-reply/claude.test.ts index 743949279..8ac25aa3a 100644 --- a/src/auto-reply/claude.test.ts +++ b/src/auto-reply/claude.test.ts @@ -1,6 +1,6 @@ import { describe, expect, it } from "vitest"; -import { parseClaudeJsonText } from "./claude.js"; +import { parseClaudeJson, parseClaudeJsonText } from "./claude.js"; describe("claude JSON parsing", () => { it("extracts text from single JSON object", () => { @@ -16,5 +16,17 @@ describe("claude JSON parsing", () => { it("returns undefined on invalid JSON", () => { expect(parseClaudeJsonText("not json")).toBeUndefined(); }); -}); + it("extracts text from Claude CLI result field and preserves metadata", () => { + const sample = { + type: "result", + subtype: "success", + result: "hello from result field", + duration_ms: 1234, + usage: { server_tool_use: { tool_a: 2 } }, + }; + const parsed = parseClaudeJson(JSON.stringify(sample)); + expect(parsed?.text).toBe("hello from result field"); + expect(parsed?.parsed).toMatchObject({ duration_ms: 1234 }); + }); +}); diff --git a/src/auto-reply/claude.ts b/src/auto-reply/claude.ts index 3a438048c..d3ba790a4 100644 --- a/src/auto-reply/claude.ts +++ b/src/auto-reply/claude.ts @@ -16,6 +16,7 @@ function extractClaudeText(payload: unknown): string | undefined { } if (typeof payload === "object") { const obj = payload as Record; + if (typeof obj.result === "string") return obj.result; if (typeof obj.text === "string") return obj.text; if (typeof obj.completion === "string") return obj.completion; if (typeof obj.output === "string") return obj.output; @@ -45,17 +46,32 @@ function extractClaudeText(payload: unknown): string | undefined { return undefined; } -export function parseClaudeJsonText(raw: string): string | undefined { - // Handle a single JSON blob or newline-delimited JSON; return the first extracted text. +export type ClaudeJsonParseResult = { + text?: string; + parsed: unknown; +}; + +export function parseClaudeJson(raw: string): ClaudeJsonParseResult | undefined { + // Handle a single JSON blob or newline-delimited JSON; return the first parsed payload. + let firstParsed: unknown; const candidates = [raw, ...raw.split(/\n+/).map((s) => s.trim()).filter(Boolean)]; for (const candidate of candidates) { try { const parsed = JSON.parse(candidate); + if (firstParsed === undefined) firstParsed = parsed; const text = extractClaudeText(parsed); - if (text) return text; + if (text) return { parsed, text }; } catch { // ignore parse errors; try next candidate } } + if (firstParsed !== undefined) { + return { parsed: firstParsed, text: extractClaudeText(firstParsed) }; + } return undefined; } + +export function parseClaudeJsonText(raw: string): string | undefined { + const parsed = parseClaudeJson(raw); + return parsed?.text; +} diff --git a/src/auto-reply/reply.ts b/src/auto-reply/reply.ts index 3f72f99a6..a8955c9d1 100644 --- a/src/auto-reply/reply.ts +++ b/src/auto-reply/reply.ts @@ -1,7 +1,7 @@ import crypto from "node:crypto"; import path from "node:path"; -import { CLAUDE_BIN, parseClaudeJsonText } from "./claude.js"; +import { CLAUDE_BIN, parseClaudeJson } from "./claude.js"; import { applyTemplate, type MsgContext, @@ -39,6 +39,52 @@ type GetReplyOptions = { onReplyStart?: () => Promise | void; }; +function summarizeClaudeMetadata(payload: unknown): string | undefined { + if (!payload || typeof payload !== "object") return undefined; + const obj = payload as Record; + const parts: string[] = []; + + if (typeof obj.duration_ms === "number") { + parts.push(`duration=${obj.duration_ms}ms`); + } + if (typeof obj.duration_api_ms === "number") { + parts.push(`api=${obj.duration_api_ms}ms`); + } + if (typeof obj.num_turns === "number") { + parts.push(`turns=${obj.num_turns}`); + } + if (typeof obj.total_cost_usd === "number") { + parts.push(`cost=$${obj.total_cost_usd.toFixed(4)}`); + } + + const usage = obj.usage; + if (usage && typeof usage === "object") { + const serverToolUse = (usage as { server_tool_use?: Record }) + .server_tool_use; + if (serverToolUse && typeof serverToolUse === "object") { + const toolCalls = Object.values(serverToolUse).reduce((sum, val) => { + if (typeof val === "number") return sum + val; + return sum; + }, 0); + if (toolCalls > 0) parts.push(`tool_calls=${toolCalls}`); + } + } + + const modelUsage = obj.modelUsage; + if (modelUsage && typeof modelUsage === "object") { + const models = Object.keys(modelUsage as Record); + if (models.length) { + const display = + models.length > 2 + ? `${models.slice(0, 2).join(",")}+${models.length - 2}` + : models.join(","); + parts.push(`models=${display}`); + } + } + + return parts.length ? parts.join(", ") : undefined; +} + export async function getReplyFromConfig( ctx: MsgContext, opts?: GetReplyOptions, @@ -216,18 +262,26 @@ export async function getReplyFromConfig( finalArgv, timeoutMs, ); - let trimmed = stdout.trim(); + const rawStdout = stdout.trim(); + let trimmed = rawStdout; if (stderr?.trim()) { logVerbose(`Command auto-reply stderr: ${stderr.trim()}`); } if (reply.claudeOutputFormat === "json" && trimmed) { - // Claude JSON mode: extract the human text for both logging and reply. - const extracted = parseClaudeJsonText(trimmed); - if (extracted) { + // Claude JSON mode: extract the human text for both logging and reply while keeping metadata. + const parsed = parseClaudeJson(trimmed); + if (parsed?.parsed && isVerbose()) { + const summary = summarizeClaudeMetadata(parsed.parsed); + if (summary) logVerbose(`Claude JSON meta: ${summary}`); logVerbose( - `Claude JSON parsed -> ${extracted.slice(0, 120)}${extracted.length > 120 ? "ā€¦" : ""}`, + `Claude JSON raw: ${JSON.stringify(parsed.parsed, null, 2)}`, ); - trimmed = extracted.trim(); + } + if (parsed?.text) { + logVerbose( + `Claude JSON parsed -> ${parsed.text.slice(0, 120)}${parsed.text.length > 120 ? "ā€¦" : ""}`, + ); + trimmed = parsed.text.trim(); } else { logVerbose("Claude JSON parse failed; returning raw stdout"); } diff --git a/src/index.ts b/src/index.ts index a2adc6787..7379eea8e 100644 --- a/src/index.ts +++ b/src/index.ts @@ -20,7 +20,7 @@ import { setMessagingServiceWebhook as setMessagingServiceWebhookImpl, } from "./twilio/update-webhook.js"; import { listRecentMessages, formatMessageLine, uniqueBySid, sortByDateDesc } from "./twilio/messages.js"; -import { CLAUDE_BIN, parseClaudeJsonText } from "./auto-reply/claude.js"; +import { CLAUDE_BIN } from "./auto-reply/claude.js"; import { applyTemplate, type MsgContext, type TemplateContext } from "./auto-reply/templating.js"; import { CONFIG_PATH, diff --git a/src/logger.ts b/src/logger.ts new file mode 100644 index 000000000..a7e03c8fa --- /dev/null +++ b/src/logger.ts @@ -0,0 +1,26 @@ +import { danger, info, success, warn, logVerbose, isVerbose } from "./globals.js"; +import { defaultRuntime, type RuntimeEnv } from "./runtime.js"; + +export function logInfo(message: string, runtime: RuntimeEnv = defaultRuntime) { + runtime.log(info(message)); +} + +export function logWarn(message: string, runtime: RuntimeEnv = defaultRuntime) { + runtime.log(warn(message)); +} + +export function logSuccess( + message: string, + runtime: RuntimeEnv = defaultRuntime, +) { + runtime.log(success(message)); +} + +export function logError(message: string, runtime: RuntimeEnv = defaultRuntime) { + runtime.error(danger(message)); +} + +export function logDebug(message: string) { + // Verbose helper that respects global verbosity flag. + if (isVerbose()) logVerbose(message); +} diff --git a/src/provider-web.ts b/src/provider-web.ts index 0696406c2..d7bfa49cb 100644 --- a/src/provider-web.ts +++ b/src/provider-web.ts @@ -12,12 +12,13 @@ import { } from "@whiskeysockets/baileys"; import pino from "pino"; import qrcode from "qrcode-terminal"; -import { danger, info, isVerbose, logVerbose, success, warn } from "./globals.js"; +import { danger, isVerbose, logVerbose, success, warn } from "./globals.js"; import { ensureDir, jidToE164, toWhatsappJid } from "./utils.js"; import type { Provider } from "./utils.js"; import { waitForever } from "./cli/wait.js"; import { getReplyFromConfig } from "./auto-reply/reply.js"; import { defaultRuntime, type RuntimeEnv } from "./runtime.js"; +import { logInfo, logWarn } from "./logger.js"; const WA_WEB_AUTH_DIR = path.join(os.homedir(), ".warelay", "credentials"); @@ -319,14 +320,13 @@ export async function monitorWebProvider( }, }); - console.log( - info( - "šŸ“” Listening for personal WhatsApp Web inbound messages. Leave this running; Ctrl+C to stop.", - ), + logInfo( + "šŸ“” Listening for personal WhatsApp Web inbound messages. Leave this running; Ctrl+C to stop.", + runtime, ); process.on("SIGINT", () => { void listener.close().finally(() => { - console.log("\nšŸ‘‹ Web monitor stopped"); + logInfo("šŸ‘‹ Web monitor stopped", runtime); runtime.exit(0); }); }); diff --git a/src/twilio/monitor.ts b/src/twilio/monitor.ts index 0cba236dd..50919ea8a 100644 --- a/src/twilio/monitor.ts +++ b/src/twilio/monitor.ts @@ -1,12 +1,12 @@ -import chalk from "chalk"; import type { MessageInstance } from "twilio/lib/rest/api/v2010/account/message.js"; -import { danger, info, logVerbose, warn } from "../globals.js"; +import { danger, warn } from "../globals.js"; import { sleep, withWhatsAppPrefix } from "../utils.js"; import { defaultRuntime, type RuntimeEnv } from "../runtime.js"; import { autoReplyIfConfigured } from "../auto-reply/reply.js"; import { createClient } from "./client.js"; import { readEnv } from "../env.js"; +import { logDebug, logInfo, logWarn } from "../logger.js"; type MonitorDeps = { autoReplyIfConfigured: typeof autoReplyIfConfigured; @@ -58,19 +58,33 @@ export async function monitorTwilio( const deps = opts?.deps ?? defaultDeps; const runtime = opts?.runtime ?? defaultRuntime; const maxIterations = opts?.maxIterations ?? Infinity; + let backoffMs = 1_000; const env = deps.readEnv(runtime); const from = withWhatsAppPrefix(env.whatsappFrom); const client = opts?.client ?? deps.createClient(env); - console.log( + logInfo( `šŸ“” Monitoring inbound messages to ${from} (poll ${pollSeconds}s, lookback ${lookbackMinutes}m)`, + runtime, ); let lastSeenSid: string | undefined; let iterations = 0; while (iterations < maxIterations) { - const messages = - (await deps.listRecentMessages(lookbackMinutes, 50, client)) ?? []; + let messages: ListedMessage[] = []; + try { + messages = + (await deps.listRecentMessages(lookbackMinutes, 50, client)) ?? []; + backoffMs = 1_000; // reset after success + } catch (err) { + logWarn( + `Twilio polling failed (will retry in ${backoffMs}ms): ${String(err)}`, + runtime, + ); + await deps.sleep(backoffMs); + backoffMs = Math.min(backoffMs * 2, 10_000); + continue; + } const inboundOnly = messages.filter((m) => m.direction === "inbound"); // Sort newest -> oldest without relying on external helpers (avoids test mocks clobbering imports). const newestFirst = [...inboundOnly].sort( @@ -95,7 +109,7 @@ async function handleMessages( for (const m of messages) { if (!m.sid) continue; if (lastSeenSid && m.sid === lastSeenSid) break; // stop at previously seen - logVerbose(`[${m.sid}] ${m.from ?? "?"} -> ${m.to ?? "?"}: ${m.body ?? ""}`); + logDebug(`[${m.sid}] ${m.from ?? "?"} -> ${m.to ?? "?"}: ${m.body ?? ""}`); if (m.direction !== "inbound") continue; if (!m.from || !m.to) continue; try {