diff --git a/backend/CLAUDE.md b/backend/CLAUDE.md index d081ca1f..71e8a248 100644 --- a/backend/CLAUDE.md +++ b/backend/CLAUDE.md @@ -53,8 +53,17 @@ thin: it proxies OpenAI requests with the server-held API key and writes study l static root doesn't exist. Cache rules: `no-store` for `.html`/`manifest.xml` (they reference content-hashed bundles by name), `immutable` for hashed assets. - **Telemetry** (`src/posthog.ts`): optional PostHog error capture; a no-op when - `POSTHOG_PROJECT_TOKEN` is unset. `deletePosthogPerson` (used by both erasure - paths) hits the PostHog *management* API and needs `POSTHOG_PERSONAL_API_KEY` + + `POSTHOG_PROJECT_TOKEN` is unset. **Nothing here may be awaited on the request + path.** `posthogMiddleware` used to `await posthog.flush()` after every request; + `flush()` rejects on any non-2xx, so when the ingestion host started returning 526 + every request 500'd (and, because flushes serialize, hung) — health probe included, + which failed a deploy. Ingestion is now left to posthog-node's background batching, + with retries/timeouts capped so a dead host costs seconds rather than ~49s; the tail + is drained by `shutdownPosthog()` on SIGTERM. `/api/ping` is deliberately not + captured. `POSTHOG_HOST` defaults to PostHog US **directly** — the + `e.thoughtful-ai.com` reverse proxy is for the browser SDK (ad blockers) and only + adds a failure mode server-side. `deletePosthogPerson` (used by both erasure paths) + hits the PostHog *management* API and needs `POSTHOG_PERSONAL_API_KEY` + `POSTHOG_PROJECT_ID`; without them it warns and no-ops. - **Tool launcher** (`src/toolGrants.ts`): the handoff grant flow for launching external writing tools from the sidebar (see `docs/tool-launcher-plan.md`, Phase 1). diff --git a/backend/README.md b/backend/README.md index aa1af957..f35aa15a 100644 --- a/backend/README.md +++ b/backend/README.md @@ -42,6 +42,7 @@ Listens on `5000` in Docker (`PORT=5000`). `OPENAI_API_KEY`, `OPENAI_DEMO_API_KEY` (pays for sessionless/demo requests), `LOG_SECRET` (gates the log-viewer endpoints + `/api/usage_summary`), `DATA_DIR` (root for `app.db` + `logs/`), `PORT` (default 8000), `DEBUG`, `POSTHOG_PROJECT_TOKEN`, -`POSTHOG_HOST`, `LOG_DIR` (overrides just the logs subdir). Auth (Better Auth) adds +`POSTHOG_HOST` (defaults to `https://us.i.posthog.com`; the server does not go through +the browser-SDK reverse proxy), `LOG_DIR` (overrides just the logs subdir). Auth (Better Auth) adds `BETTER_AUTH_ENABLED`, `BETTER_AUTH_SECRET`, `GOOGLE_CLIENT_ID`, `GOOGLE_CLIENT_SECRET`, and related vars — see [CLAUDE.md](CLAUDE.md) for the full list. diff --git a/backend/src/__tests__/posthog.test.ts b/backend/src/__tests__/posthog.test.ts new file mode 100644 index 00000000..4613d0ac --- /dev/null +++ b/backend/src/__tests__/posthog.test.ts @@ -0,0 +1,135 @@ +import { createServer, type Server } from 'node:http'; +import type { AddressInfo } from 'node:net'; +import { afterAll, beforeAll, beforeEach, describe, expect, it, vi } from 'vitest'; + +/** + * Regression test for the outage where a failing PostHog ingestion host took the + * whole backend down: posthogMiddleware used to `await posthog.flush()` after every + * request, and flush() rejects on any non-2xx from the host. A transient 526 from + * the analytics reverse proxy therefore turned every request — including the k8s + * health probe — into a 500, and the deploy never went ready. + * + * Telemetry must stay strictly off the request's critical path: it may not decide a + * response's status, and it may not add to its latency. + * + * The bad host here is a real local HTTP server rather than a mocked `fetch`: + * posthog-node resolves the global fetch once when *it* is imported, which is + * outside Vitest's module registry, so a `vi.stubGlobal('fetch', …)` in this file + * may never be the one it calls. + */ + +let server: Server; +let hostUrl: string; +/** Swapped per test to make the ingestion host fail in a particular way. */ +let handle: (respond: (status: number) => void) => void; +/** + * Bodies of the batches the fake PostHog received. Assertions match on the event + * names inside them rather than counting requests: a client from an earlier test + * can still have a chained flush in flight, so only the contents identify who sent + * what. + */ +let batches: string[] = []; + +beforeAll(async () => { + server = createServer((req, res) => { + let body = ''; + req.on('data', (chunk) => { + body += chunk; + }); + req.on('end', () => { + batches.push(body); + handle((status) => res.writeHead(status).end('error')); + }); + }); + await new Promise((resolve) => server.listen(0, '127.0.0.1', resolve)); + hostUrl = `http://127.0.0.1:${(server.address() as AddressInfo).port}`; +}); + +afterAll(async () => { + await new Promise((resolve) => server.close(resolve)); +}); + +// posthog.ts builds its client from the environment at module load, so each test +// stubs the env, resets the module registry, and re-imports. +async function loadApp(route: string) { + vi.stubEnv('POSTHOG_PROJECT_TOKEN', 'phc_test_token'); + vi.stubEnv('DISABLE_POSTHOG', ''); + vi.stubEnv('POSTHOG_HOST', hostUrl); + vi.resetModules(); + + const { posthogMiddleware } = await import('../posthog.js'); + const { Hono } = await import('hono'); + const app = new Hono(); + app.use('*', posthogMiddleware); + app.get(route, (c) => c.json({ ok: true })); + return app; +} + +// posthog-node batches: it only sends once flushAt (20) events are queued, so a run +// of requests is what provokes an ingestion attempt at all. +const OVER_FLUSH_AT = 25; + +beforeEach(() => { + batches = []; + handle = (respond) => respond(526); // what the reverse proxy was returning +}); + +describe('posthogMiddleware with a failing PostHog host', () => { + it('serves requests normally while ingestion 526s', async () => { + const app = await loadApp('/api/thing'); + + for (let i = 0; i < OVER_FLUSH_AT; i++) { + const res = await app.request('/api/thing'); + expect(res.status).toBe(200); + expect(await res.json()).toEqual({ ok: true }); + } + + // The failing ingestion really was attempted — otherwise this test would + // pass just as well with telemetry silently doing nothing. + await vi.waitFor(() => + expect(batches.some((b) => b.includes('GET /api/thing'))).toBe(true), + ); + }); + + it('does not make requests wait on a hung ingestion host', async () => { + handle = () => { + /* accept the connection, never respond */ + }; + const app = await loadApp('/api/thing'); + + const started = Date.now(); + for (let i = 0; i < OVER_FLUSH_AT; i++) { + expect((await app.request('/api/thing')).status).toBe(200); + } + // The client's own requestTimeout is 3s; the old await-flush middleware + // would have blocked for at least that long before failing the request. + expect(Date.now() - started).toBeLessThan(1000); + }); + + it('does not capture health-probe requests', async () => { + const app = await loadApp('/api/ping'); + + for (let i = 0; i < OVER_FLUSH_AT; i++) { + expect((await app.request('/api/ping')).status).toBe(200); + } + // Well past flushAt with nothing queued, so no probe ever reaches PostHog. + await new Promise((r) => setTimeout(r, 100)); + expect(batches.filter((b) => b.includes('/api/ping'))).toEqual([]); + }); +}); + +describe('captureException with a failing PostHog host', () => { + it('resolves promptly instead of throwing or hanging', async () => { + handle = () => { + /* accept the connection, never respond */ + }; + vi.stubEnv('POSTHOG_PROJECT_TOKEN', 'phc_test_token'); + vi.stubEnv('POSTHOG_HOST', hostUrl); + vi.resetModules(); + const { captureException } = await import('../posthog.js'); + + const started = Date.now(); + await captureException(new Error('boom')); + expect(Date.now() - started).toBeLessThan(1000); + }); +}); diff --git a/backend/src/posthog.ts b/backend/src/posthog.ts index 72818dfd..00dbcd4e 100644 --- a/backend/src/posthog.ts +++ b/backend/src/posthog.ts @@ -2,8 +2,11 @@ import { createMiddleware } from 'hono/factory'; import { PostHog } from 'posthog-node'; const token = (process.env.POSTHOG_PROJECT_TOKEN ?? '').trim() || "placeholder-token"; +// Defaults to PostHog US directly, NOT the e.thoughtful-ai.com reverse proxy: the +// server has no ad-blocker to evade (that's only worth it for the browser SDK), so +// the proxy added a hop that could — and did — fail on its own. // Strip any trailing slash so building management-API URLs (deletePosthogPerson) -// can't produce a double slash — the shipped POSTHOG_HOST default ends in '/', and +// can't produce a double slash — an explicitly-set POSTHOG_HOST may end in '/', and // many reverse proxies 404 on `//api/...`. const host = ((process.env.POSTHOG_HOST ?? '').trim() || 'https://us.i.posthog.com').replace( @@ -13,15 +16,40 @@ const host = const shouldDisablePosthog = token === "placeholder-token" || process.env.DISABLE_POSTHOG === '1'; -const posthog = new PostHog(token, { host, disabled: shouldDisablePosthog }); +const posthog = new PostHog(token, { + host, + disabled: shouldDisablePosthog, + // Telemetry must never be able to hold a request (or the whole process) open. + // posthog-node's defaults are 10s per attempt x 4 attempts with 3s between them + // — ~49s of hanging per flush when the ingestion host is down. Ingestion is + // fire-and-forget analytics, so cap it at a few seconds and let the batch drop. + requestTimeout: 3000, + fetchRetryCount: 1, + fetchRetryDelay: 1000, +}); export const posthogMiddleware = createMiddleware(async (c, next) => { - posthog.capture({ - distinctId: 'server', - event: `${c.req.method} ${c.req.path}`, - }); + // Health probes are not product analytics: they'd add a queue entry (and a + // distinct event name) every few seconds forever. + if (c.req.path !== '/api/ping') { + try { + posthog.capture({ + distinctId: 'server', + event: `${c.req.method} ${c.req.path}`, + }); + } catch { + // Never let telemetry break the request path. + } + } await next(); - await posthog.flush(); + // Deliberately NOT `await posthog.flush()`. That made every request wait on — + // and 500 on — a PostHog ingestion failure: flush() rejects on any non-2xx, + // the rejection propagated out of this middleware into app.onError, and + // because flush() serializes behind the previous flush the latency compounded + // across concurrent requests. A transient 526 from the analytics host thereby + // took the whole backend down, health probe included. posthog-node already + // flushes in the background (batches of 20, or every 10s) and swallows its own + // errors there; shutdownPosthog() drains the tail on SIGTERM. }); export async function captureException( @@ -31,7 +59,9 @@ export async function captureException( try { const err = error instanceof Error ? error : new Error(String(error)); posthog.captureException(err, undefined, properties); - await posthog.flush(); + // No flush() here either — see posthogMiddleware. The background flush + // timer sends this within ~10s without putting the ingestion host on the + // critical path of an error response. } catch { // Never let error tracking break the request path. } diff --git a/docker-compose-prod.yml b/docker-compose-prod.yml index 4532ceb3..ead5ddd5 100644 --- a/docker-compose-prod.yml +++ b/docker-compose-prod.yml @@ -11,7 +11,9 @@ services: # on OpenAI's side. Unset => sessionless requests are refused. See openaiProxy.ts. - OPENAI_DEMO_API_KEY=${OPENAI_DEMO_API_KEY:-} - POSTHOG_PROJECT_TOKEN=${POSTHOG_PROJECT_TOKEN:-} - - POSTHOG_HOST=${POSTHOG_HOST:-https://e.thoughtful-ai.com/} + # Straight to PostHog US — see docker-compose.yml for why the backend does + # not go through the e.thoughtful-ai.com reverse proxy. + - POSTHOG_HOST=${POSTHOG_HOST:-https://us.i.posthog.com} # Management API (personal key + project id) — required for "delete my data" # to purge a user's PostHog person/events. Unset => deletion no-ops with a # warning (see deletePosthogPerson). Verified post-deploy in issue #517. diff --git a/docker-compose.yml b/docker-compose.yml index 0c7a248e..7c6a4896 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -19,7 +19,11 @@ services: - OPENAI_DEMO_API_KEY=${OPENAI_DEMO_API_KEY:-} - LOG_SECRET=${LOG_SECRET} - POSTHOG_PROJECT_TOKEN=${POSTHOG_PROJECT_TOKEN:-} - - POSTHOG_HOST=${POSTHOG_HOST:-https://e.thoughtful-ai.com/} + # Server-side ingestion goes straight to PostHog US, not the + # e.thoughtful-ai.com reverse proxy. The proxy exists to get past browser ad + # blockers, which is irrelevant here, and it added a hop whose outage (a + # Cloudflare 526) used to take the backend down with it. + - POSTHOG_HOST=${POSTHOG_HOST:-https://us.i.posthog.com} # Management API (personal key + project id) — required for "delete my data" # to purge a user's PostHog person/events. Unset => deletion no-ops with a # warning (see deletePosthogPerson).