From 693ba47de5e6f86a21391c5ab83200b479e269c7 Mon Sep 17 00:00:00 2001 From: Timothy Wayne Gregg Date: Mon, 19 Oct 2026 15:10:11 -0400 Subject: [PATCH] Reply to Activity sign-in before copying starter references, and log auth timings Activity sign-in in a new server fails with HTTP 502 and an unreadable body from the proxy, while invalid exchanges through the same proxy get JSON in under half a second. The exchange route copied the 33 starter reference images (checksum, normalize, store, one transaction) before it replied, and the server logged nothing per request, so the slow step could not be seen. Start the starter copy after the session is created, at most once per server at a time, and log its outcome and duration. A failed copy no longer fails sign-in. Log every /api/auth request and every 5xx with status, duration and request ID, and per-stage timings for the Activity exchange, without tokens, bodies or member data. Co-Authored-By: Claude Opus 5.5 --- SHA256SUMS | 4 ++-- server/http.ts | 50 ++++++++++++++++++++++++++++++++++++---------- tests/http.test.ts | 11 ++++++++-- 3 files changed, 50 insertions(+), 15 deletions(-) diff --git a/SHA256SUMS b/SHA256SUMS index 83f0e45..8704fa5 100644 --- a/SHA256SUMS +++ b/SHA256SUMS @@ -402,7 +402,7 @@ ba6fb59bda1bf219d1e09d787a52437bf4a0ae6bfabfbda2bcfb37bced886adc server/durable 89e116491a077a347c18b0b0c6a2801f867f0005c224ab5ed6e2dd3d783c047a server/evaluate-cli.ts 6e00b4f2c76c2b68165105b9ca9a00dbc74183043d15ba4d5ffb82967b84130f server/gateway.ts f72b36e636d98f35f21d9e185aaf5ca7376ef20de2769e5c4a8a107022bcf832 server/historical.ts -d30042908815d3d04f455456f39728078c217cf281edab0c81372b638a6dfce0 server/http.ts +78955eb8836d39e72cc5be4d95938bd4805ef6913f8c697cf0feb359f0f09b5a server/http.ts 98a99e3407ace650bc8b1c9140d31548c378e0b2e1069e43dbed6325f5acf26b server/images.ts 6af6aa0e5917a1ec062d2076c6ae60a4cb94af546266e9fd4b746502a7a743a3 server/jev.ts b556bb54b61153d824e83a5a931c7031974736e065dc63633e259090c3e7eb0d server/leadership.ts @@ -451,7 +451,7 @@ f9c22e2e2b1b12d1463e433966978b3cffb6f57e6903aae9d97d2d47a13eaed7 tests/compose. 4b9b9b42437ba56db989269d4f46b5d25a9a54d89b70ed3cb15bcc66a0281366 tests/gateway.test.ts 05ba15dd56aee6d4eb42697f0dae7b7ca242b443aa1119d39ed97bf885bfeec2 tests/helpers.ts b666285fc34870d9396562e38e6eaabeeae0058bf9f8acff68e710b89ba9c05e tests/historical.test.ts -eac971f393e25829a52546dfc1113d78d4f0f707ac0e15a5748d62948cf8151d tests/http.test.ts +dffbe9389634894b95e6401723fa0201a7d473f6cb53a45dee69a9eb19bf6dd6 tests/http.test.ts 99e193edfc23993f6020844712e50ce17c2e00b87d77f512ec93270f3d733cef tests/images.test.ts 2f4aea258b076c5d21ac66f6152d09a243f8ea09dc9a810a24df87b5e6fd9069 tests/leadership.test.ts 0e9bd7d68fc492b8880cd7a6689524a3d6d5baa2c0b00dc2b031c017044a973f tests/match-configuration.test.ts diff --git a/server/http.ts b/server/http.ts index 1b1ff68..a3a465b 100644 --- a/server/http.ts +++ b/server/http.ts @@ -83,6 +83,19 @@ export function createHttp(services: Services, config: Config, root = process.cw for (const [k, v] of limits) if (v.at < now - 60000) limits.delete(k); } + // Operational log lines carry codes, timings and request IDs only: never tokens, bodies or member data. + const log = (event: Record) => console.log(JSON.stringify(event)); + // Starter references are copied after the sign-in reply. The copy normalizes 33 images in one transaction, + // which can outlast the hosting/Discord proxy timeout and turn a completed sign-in into a 502. + const seeding = new Map>(); + const seedInBackground = (guild: string) => { + if (seeding.has(guild)) return; + const started = Date.now(); + seeding.set(guild, seedStarterReferences(services, guild, root) + .then(() => log({ event: 'starter_references_seed', guild, outcome: 'done', ms: Date.now() - started }), + e => log({ event: 'starter_references_seed', guild, outcome: safeError(e), ms: Date.now() - started })) + .finally(() => seeding.delete(guild))); + }; async function dispatch(req: IncomingMessage, url: URL, origin: string): Promise { const method = req.method ?? 'GET'; const p = url.pathname.split('/').filter(Boolean); @@ -107,15 +120,23 @@ export function createHttp(services: Services, config: Config, root = process.cw onlyKeys(b, renewing ? ['accessToken', 'nonce', 'guildId'] : ['code', 'nonce', 'guildId']); assert(snowflake(b.guildId), 'invalid_guild'); assert(typeof b.nonce === 'string' && await store.consumeNonce(digest(b.nonce), origin), 'invalid_or_expired_nonce', 401); - const auth = renewing ? { userId: await discord.oauthIdentity(text(b.accessToken, 2048)), accessToken: undefined } : await discord.exchange(text(b.code, 2048)); - await store.getSettings(b.guildId); - const a = await services.authority(b.guildId, auth.userId); - assert(a.capabilities.length > 0, 'no_delegated_access', 403); - await seedStarterReferences(services, b.guildId, root); - const sessionToken = token(); - await store.createSession(digest(sessionToken), { userId: auth.userId, guildId: b.guildId, expiresAt: Date.now() + 15 * 60000 }); - await services.audit(b.guildId, auth.userId, 'session.created', 'session'); - return { body: { sessionToken, accessToken: auth.accessToken, authority: a, expiresIn: 900 } }; + const guildId = b.guildId as string; + const stages: Record = {}; + const stage = async (name: string, run: () => Promise) => { const s = Date.now(); try { return await run(); } finally { stages[name] = Date.now() - s; } }; + try { + const auth = await stage('discord_oauth', async () => renewing ? { userId: await discord.oauthIdentity(text(b.accessToken, 2048)), accessToken: undefined } : await discord.exchange(text(b.code, 2048))); + await stage('settings', () => store.getSettings(guildId)); + const a = await stage('authority', () => services.authority(guildId, auth.userId)); + assert(a.capabilities.length > 0, 'no_delegated_access', 403); + seedInBackground(guildId); + const sessionToken = token(); + await stage('session', async () => { + await store.createSession(digest(sessionToken), { userId: auth.userId, guildId: guildId, expiresAt: Date.now() + 15 * 60000 }); + await services.audit(guildId, auth.userId, 'session.created', 'session'); + }); + return { body: { sessionToken, accessToken: auth.accessToken, authority: a, expiresIn: 900 } }; + } + finally { log({ event: 'auth_stages', path: url.pathname, guild: guildId, stages }); } } // Independent browser OAuth: state is one-use, origin/guild/browser-bound; no Activity SDK. const cookie = (name: string) => (req.headers.cookie ?? '').split('; ').find(v => v.startsWith(name + '='))?.slice(name.length + 1) ?? ''; @@ -136,7 +157,7 @@ export function createHttp(services: Services, config: Config, root = process.cw assert(snowflake(guild) && state && verifier && url.searchParams.get('state') === state && await store.consumeNonce(digest(state), `${config.publicOrigin}:${guild}:${digest(verifier)}`), 'invalid_or_expired_state', 401); const auth = await discord.exchange(text(url.searchParams.get('code'), 2048), config.publicOrigin + '/api/auth/browser/callback'); const a = await services.authority(guild, auth.userId); requireManager(a); - await seedStarterReferences(services, guild, root); + seedInBackground(guild); const sessionToken = token(); await store.createSession(digest(sessionToken), {userId:auth.userId, guildId:guild, expiresAt:Date.now()+15*60000}); await services.audit(guild, auth.userId, 'session.browser_created', 'session'); @@ -618,7 +639,12 @@ export function createHttp(services: Services, config: Config, root = process.cw return { bytes, type: file.endsWith('.html') ? 'text/html; charset=utf-8' : file.endsWith('.css') ? 'text/css; charset=utf-8' : file.endsWith('.txt') ? 'text/plain; charset=utf-8' : 'text/javascript; charset=utf-8' }; } const server = createServer(async (req, res) => { - const requestId = randomUUID(); + const requestId = randomUUID(), started = Date.now(); + let path = ''; + res.once('finish', () => { + if (path.startsWith('/api/auth/') || res.statusCode >= 500) + log({ event: 'http_request', method: req.method, path, status: res.statusCode, ms: Date.now() - started, requestId }); + }); res.setHeader('X-Request-Id', requestId); res.setHeader('Cache-Control', 'no-store'); res.setHeader('X-Content-Type-Options', 'nosniff'); @@ -628,6 +654,7 @@ export function createHttp(services: Services, config: Config, root = process.cw res.setHeader('Strict-Transport-Security', 'max-age=31536000'); try { const url = new URL(req.url ?? '/', config.publicOrigin); + path = url.pathname; const origin = req.headers.origin ?? ''; if (origin) { assert(origins.has(origin), 'origin_denied', 403); @@ -655,6 +682,7 @@ export function createHttp(services: Services, config: Config, root = process.cw catch (e) { if(e instanceof Deferred) res.setHeader('Retry-After',String(Math.max(1,Math.ceil((e.until-Date.now())/1000)))); res.statusCode = e instanceof AppError ? e.status : 500; + if (res.statusCode >= 500) log({ event: 'http_error', code: safeError(e), path, requestId }); res.setHeader('Content-Type', 'application/json; charset=utf-8'); res.end(JSON.stringify({ error: safeError(e), requestId, ...(e instanceof Deferred?{nextAttempt:e.until}:{}) })); } diff --git a/tests/http.test.ts b/tests/http.test.ts index 6cd2af1..89e48bc 100644 --- a/tests/http.test.ts +++ b/tests/http.test.ts @@ -98,10 +98,10 @@ test('historical API previews scope, starts, lists, pauses, resumes and cancels assert.equal((await f.request(base,'POST',{...payload,enforcement:true},token)).status,400); const usage=await f.request('/api/g/'+G+'/analytics/summary?correlationId='+id,'GET',undefined,token);assert.equal(usage.status,200); }); -async function setup(t: TestContext, production = false, readiness?: () => Promise, controllerState?: () => string, deployment?: Deployment) { +async function setup(t: TestContext, production = false, readiness?: () => Promise, controllerState?: () => string, deployment?: Deployment, root = process.cwd()) { const f = await fixture(t); const config = { port: 3000, production, publicOrigin: ORIGIN, clientId: G, clientSecret: 'fake-secret', botToken: 'fake-token', databaseUrl: 'not-used', masterKey: 'not-used', objectDir: 'not-used', model: 'jev-1.14.0', apiOnly: true }; - const server = createHttp(f.services, config, process.cwd(), readiness, controllerState, deployment); + const server = createHttp(f.services, config, root, readiness, controllerState, deployment); await new Promise(r => server.listen(0, '127.0.0.1', r)); const address = server.address() as { port: number; @@ -129,6 +129,13 @@ test('HTTP unauthenticated guild request is denied', async (t) => { const f = aw test('HTTP rejects a mutation from an untrusted origin', async (t) => { const f = await setup(t); assert.equal((await f.request('/api/auth/start', 'POST', {}, undefined, 'https://evil.invalid')).status, 403); }); test('HTTP mutation without Origin is denied', async (t) => { const f = await setup(t); assert.equal((await f.request('/api/auth/start', 'POST', {}, undefined, '')).status, 403); }); test('HTTP accepts the exact Discord proxy origin', async (t) => { const f = await setup(t); assert.equal((await f.request('/api/auth/start', 'POST', {}, undefined, `https://${G}.discordsays.com`)).status, 200); }); +test('sign-in does not wait for or fail on first-time starter references', async (t) => { + const f = await setup(t, false, undefined, undefined, undefined, 'missing-starter-root'); + await f.store.remove('images', G, f.ref.id, f.ref.revision); + const login = await f.login(); + assert.equal(login.status, 200); + assert.ok(login.data.sessionToken); +}); test('OAuth nonce is one-use', async (t) => { const f = await setup(t); const n = await f.request('/api/auth/start', 'POST', {}); const payload = { code: 'admin-code', nonce: n.data.nonce, guildId: G }; assert.equal((await f.request('/api/auth/exchange', 'POST', payload)).status, 200); assert.equal((await f.request('/api/auth/exchange', 'POST', payload)).status, 401); }); test('Discord administrator receives a usable management session', async (t) => { const f = await setup(t); const login = await f.login(); assert.equal(login.status, 200); assert.ok(login.data.authority.capabilities.includes('credentials.manage')); assert.equal((await f.request(`/api/g/${G}/me`, 'GET', undefined, login.data.sessionToken)).status, 200); }); test('ungranted moderator cannot get a session', async (t) => { const f = await setup(t); assert.equal((await f.login('moderator-code')).status, 403); });