diff --git a/.env.example b/.env.dev similarity index 50% rename from .env.example rename to .env.dev index 9277a2e..0d31f60 100644 --- a/.env.example +++ b/.env.dev @@ -1,3 +1,6 @@ DATABASE_URL=postgresql://postgres:postgres@localhost:5432/handy HANDY_MASTER_SECRET=your-super-secret-key-for-local-development PORT=3005 + +# Uncomment to enable centralized logging for AI debugging (creates .logs directory) +DANGEROUSLY_LOG_TO_SERVER_FOR_AI_AUTO_DEBUGGING=true diff --git a/CLAUDE.md b/CLAUDE.md index fb2e7b6..d95a9a4 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -175,4 +175,97 @@ The project includes a multi-stage Dockerfile: 3. ALWAYS prefer editing an existing file to creating a new one 4. NEVER proactively create documentation files (*.md) or README files unless explicitly requested 5. Use 4 spaces for tabs (not 2 spaces) -6. Use yarn instead of npm for all package management \ No newline at end of file +6. Use yarn instead of npm for all package management + +## Debugging Notes + +### Remote Logging Setup +- Use `DANGEROUSLY_LOG_TO_SERVER_FOR_AI_AUTO_DEBUGGING=true` env var to enable +- Server logs to `.logs/` directory with timestamped files (format: `MM-DD-HH-MM-SS.log`) +- Mobile and CLI send logs to `/logs-combined-from-cli-and-mobile-for-simple-ai-debugging` endpoint + +### Common Issues & Tells + +#### Socket/Connection Issues +- **Tell**: "Sending update to user-scoped connection" but mobile not updating +- **Tell**: Multiple "User disconnected" messages indicate socket instability +- **Tell**: "Response from the Engine was empty" = Prisma database connection lost + +#### Auth Flow Debugging +- CLI must hit `/v1/auth/request` to create auth request +- Mobile scans QR and hits `/v1/auth/response` to approve +- **Tell**: 404 on `/v1/auth/response` = server likely restarted/crashed +- **Tell**: "Auth failed - user not found" = token issue or user doesn't exist + +#### Session Creation Flow +- Sessions created via POST `/v1/sessions` with tag-based deduplication +- Server emits "new-session" update to all user connections +- **Tell**: Sessions created but not showing = mobile app not processing updates +- **Tell**: "pathname /" in mobile logs = app stuck at root screen + +#### Environment Variables +- CLI: Use `yarn dev:local-server` (NOT `yarn dev`) to load `.env.dev-local-server` +- Server: Use `yarn dev` to start with proper env files +- **Tell**: Wrong server URL = check `HAPPY_SERVER_URL` env var +- **Tell**: Wrong home dir = check `HAPPY_HOME_DIR` (should be `~/.happy-dev` for local) + +### Quick Diagnostic Commands + +#### IMPORTANT: Always Start Debugging With These +```bash +# 1. CHECK CURRENT TIME - Logs use local time, know what's current! +date + +# 2. CHECK LATEST LOG FILES - Server creates new logs on restart +ls -la .logs/*.log | tail -5 + +# 3. VERIFY YOU'RE LOOKING AT CURRENT LOGS +# Server logs are named: MM-DD-HH-MM-SS.log (month-day-hour-min-sec) +# If current time is 13:45 and latest log is 08-15-10-57-02.log from 10:57, +# that log started 3 hours ago but may still be active! +tail -1 .logs/[LATEST_LOG_FILE] # Check last entry timestamp +``` + +#### Common Debugging Patterns +```bash +# Check server logs for errors +tail -100 .logs/*.log | grep -E "(error|Error|ERROR|failed|Failed)" + +# Monitor session creation +tail -f .logs/*.log | grep -E "(new-session|Session created)" + +# Check active connections +tail -100 .logs/*.log | grep -E "(Token verified|User connected|User disconnected)" + +# See what endpoints are being hit +tail -100 .logs/*.log | grep "incoming request" + +# Debug socket real-time updates +tail -500 .logs/*.log | grep -A 2 -B 2 "new-session" | tail -30 +tail -200 .logs/*.log | grep -E "(websocket|Socket.*connected|Sending update)" | tail -30 + +# Track socket events from mobile client +tail -300 .logs/*.log | grep "remote-log.*mobile" | grep -E "(SyncSocket|handleUpdate)" | tail -20 + +# Monitor session creation flow end-to-end +tail -500 .logs/*.log | grep "session-create" | tail -20 +tail -500 .logs/*.log | grep "cmed556s4002bvb2020igg8jf" -A 3 -B 3 # Replace with actual session ID + +# Check auth flow for sessions API +tail -300 .logs/*.log | grep "auth-decorator.*sessions" | tail -10 + +# Debug machine registration and online status +tail -500 .logs/*.log | grep -E "(machine-alive|machine-register|update-machine)" | tail -20 +tail -500 .logs/*.log | grep "GET /v1/machines" | tail -10 +tail -500 .logs/*.log | grep "POST /v1/machines" | tail -10 + +# Check what mobile app is seeing +tail -500 .logs/*.log | grep "📊 Storage" | tail -20 +tail -500 .logs/*.log | grep "applySessions.*active" | tail -10 +``` + +#### Time Format Reference +- **CLI logs**: `[HH:MM:SS.mmm]` in local time (e.g., `[13:45:23.738]`) +- **Server logs**: Include both `time` (Unix ms) and `localTime` (HH:MM:ss.mmm) +- **Mobile logs**: Sent with `timestamp` in UTC, converted to `localTime` on server +- **All consolidated logs**: Have `localTime` field for easy correlation \ No newline at end of file diff --git a/package.json b/package.json index 4441978..6beb0ac 100644 --- a/package.json +++ b/package.json @@ -8,12 +8,12 @@ "scripts": { "build": "tsc --noEmit", "start": "tsx ./sources/main.ts", - "dev": "tsx --env-file=.env --env-file=.env.example ./sources/main.ts", + "dev": "lsof -ti tcp:3005 | xargs kill -9 && tsx --env-file=.env --env-file=.env.dev ./sources/main.ts", "test": "vitest run", - "migrate": "dotenv -e .env.example -- prisma migrate dev", + "migrate": "dotenv -e .env.dev -- prisma migrate dev", "generate": "prisma generate", "postinstall": "prisma generate", - "db": "docker run -d -e POSTGRES_PASSWORD=postgres -e POSTGRES_DB=handy -v $(pwd)/.pgdata:/var/lib/postgresql/data -p 5432:5432 postgres", + "db": "docker run -d -e POSTGRES_PASSWORD=postgres -e POSTGRES_DB=handy -v postgres-data:/var/lib/postgresql/data -p 5432:5432 postgres", "redis": "docker run -d -p 6379:6379 redis" }, "devDependencies": { diff --git a/sources/app/api.ts b/sources/app/api.ts index a3ed823..9bdee22 100644 --- a/sources/app/api.ts +++ b/sources/app/api.ts @@ -1,5 +1,5 @@ import fastify, { FastifyInstance } from "fastify"; -import { log } from "@/utils/log"; +import { log, logger } from "@/utils/log"; import { serializerCompiler, validatorCompiler, ZodTypeProvider } from "fastify-type-provider-zod"; import { Server, Socket } from "socket.io"; import { z } from "zod"; @@ -86,13 +86,16 @@ export async function startApi(): Promise<{ app: FastifyInstance; io: Server }> app.decorate('authenticate', async function (request: any, reply: any) { try { const authHeader = request.headers.authorization; + log({ module: 'auth-decorator' }, `Auth check - path: ${request.url}, has header: ${!!authHeader}, header start: ${authHeader?.substring(0, 50)}...`); if (!authHeader || !authHeader.startsWith('Bearer ')) { + log({ module: 'auth-decorator' }, `Auth failed - missing or invalid header`); return reply.code(401).send({ error: 'Missing authorization header' }); } const token = authHeader.substring(7); const verified = await tokenVerifier.verify(token); if (!verified) { + log({ module: 'auth-decorator' }, `Auth failed - invalid token`); return reply.code(401).send({ error: 'Invalid token' }); } @@ -102,8 +105,11 @@ export async function startApi(): Promise<{ app: FastifyInstance; io: Server }> }); if (!user) { + log({ module: 'auth-decorator' }, `Auth failed - user not found: ${verified.user}`); return reply.code(401).send({ error: 'User not found' }); } + + log({ module: 'auth-decorator' }, `Auth success - user: ${user.id}`); request.user = user; } catch (error) { @@ -224,10 +230,13 @@ export async function startApi(): Promise<{ app: FastifyInstance; io: Server }> return reply.code(401).send({ error: 'Invalid public key' }); } + const publicKeyHex = privacyKit.encodeHex(publicKey); + log({ module: 'auth-request' }, `Terminal auth request - publicKey hex: ${publicKeyHex}`); + const answer = await db.terminalAuthRequest.upsert({ - where: { publicKey: privacyKit.encodeHex(publicKey) }, + where: { publicKey: publicKeyHex }, update: {}, - create: { publicKey: privacyKit.encodeHex(publicKey) } + create: { publicKey: publicKeyHex } }); if (answer.response && answer.responseAccountId) { @@ -252,15 +261,26 @@ export async function startApi(): Promise<{ app: FastifyInstance; io: Server }> }) } }, async (request, reply) => { + log({ module: 'auth-response' }, `Auth response endpoint hit - user: ${request.user?.id || 'NO USER'}, publicKey: ${request.body.publicKey.substring(0, 20)}...`); const publicKey = privacyKit.decodeBase64(request.body.publicKey); const isValid = tweetnacl.box.publicKeyLength === publicKey.length; if (!isValid) { + log({ module: 'auth-response' }, `Invalid public key length: ${publicKey.length}`); return reply.code(401).send({ error: 'Invalid public key' }); } + const publicKeyHex = privacyKit.encodeHex(publicKey); + log({ module: 'auth-response' }, `Looking for auth request with publicKey hex: ${publicKeyHex}`); const authRequest = await db.terminalAuthRequest.findUnique({ - where: { publicKey: privacyKit.encodeHex(publicKey) } + where: { publicKey: publicKeyHex } }); if (!authRequest) { + log({ module: 'auth-response' }, `Auth request not found for publicKey: ${publicKeyHex}`); + // Let's also check what auth requests exist + const allRequests = await db.terminalAuthRequest.findMany({ + take: 5, + orderBy: { createdAt: 'desc' } + }); + log({ module: 'auth-response' }, `Recent auth requests in DB: ${JSON.stringify(allRequests.map(r => ({ id: r.id, publicKey: r.publicKey.substring(0, 20) + '...', hasResponse: !!r.response })))}`); return reply.code(404).send({ error: 'Request not found' }); } if (!authRequest.response) { @@ -416,6 +436,7 @@ export async function startApi(): Promise<{ app: FastifyInstance; io: Server }> } }); if (session) { + logger.info({ module: 'session-create', sessionId: session.id, userId, tag }, `Found existing session: ${session.id} for tag ${tag}`); return reply.send({ session: { id: session.id, @@ -437,6 +458,7 @@ export async function startApi(): Promise<{ app: FastifyInstance; io: Server }> const updSeq = await allocateUserSeq(userId); // Create session + logger.info({ module: 'session-create', userId, tag }, `Creating new session for user ${userId} with tag ${tag}`); const session = await db.session.create({ data: { accountId: userId, @@ -444,6 +466,7 @@ export async function startApi(): Promise<{ app: FastifyInstance; io: Server }> metadata: metadata } }); + logger.info({ module: 'session-create', sessionId: session.id, userId }, `Session created: ${session.id}`); // Create update const updContent: PrismaJson.UpdateBody = { @@ -461,15 +484,23 @@ export async function startApi(): Promise<{ app: FastifyInstance; io: Server }> }; // Emit update to connected sockets + const updatePayload = { + id: randomKeyNaked(12), + seq: updSeq, + body: updContent, + createdAt: Date.now() + }; + logger.info({ + module: 'session-create', + userId, + sessionId: session.id, + updateType: 'new-session', + updatePayload: JSON.stringify(updatePayload) + }, `Emitting new-session update to all user connections`); emitUpdateToInterestedClients({ event: 'update', userId, - payload: { - id: randomKeyNaked(12), - seq: updSeq, - body: updContent, - createdAt: Date.now() - }, + payload: updatePayload, recipientFilter: { type: 'all-user-authenticated-connections' } }); @@ -945,7 +976,10 @@ export async function startApi(): Promise<{ app: FastifyInstance; io: Server }> const userId = request.user.id; const { id, metadata } = request.body; - const machine = await db.machine.upsert({ + logger.info({ module: 'machines', machineId: id, userId, hasMetadata: !!metadata }, 'Creating/updating machine'); + + try { + const machine = await db.machine.upsert({ where: { accountId_id: { accountId: userId, @@ -964,9 +998,9 @@ export async function startApi(): Promise<{ app: FastifyInstance; io: Server }> active: true, lastActiveAt: new Date() } - }); - - // Emit update to all user connections + }); + + // Emit update to all user connections const updSeq = await allocateUserSeq(userId); emitUpdateToInterestedClients({ event: 'update', @@ -984,9 +1018,78 @@ export async function startApi(): Promise<{ app: FastifyInstance; io: Server }> }, createdAt: Date.now() } + }); + + return { success: true }; + } catch (error) { + logger.error({ + module: 'machines', + machineId: id, + userId, + error: error instanceof Error ? error.message : String(error), + errorStack: error instanceof Error ? error.stack : undefined + }, 'Failed to create/update machine'); + return reply.code(500).send({ + error: 'Failed to create/update machine', + details: error instanceof Error ? error.message : String(error) + }); + } + }); + + // Combined logging endpoint (only when explicitly enabled) + if (process.env.DANGEROUSLY_LOG_TO_SERVER_FOR_AI_AUTO_DEBUGGING) { + typed.post('/logs-combined-from-cli-and-mobile-for-simple-ai-debugging', { + schema: { + body: z.object({ + timestamp: z.string(), + level: z.string(), + message: z.string(), + messageRawObject: z.any().optional(), + source: z.enum(['mobile', 'cli']), + platform: z.string().optional() + }) + } + }, async (request, reply) => { + const { timestamp, level, message, source, platform } = request.body; + + // Log ONLY to separate remote logger (file only, no console) + const logData = { + source, + platform, + timestamp + }; + + // Use the file-only logger if available + const { fileConsolidatedLogger } = await import('@/utils/log'); + + if (!fileConsolidatedLogger) { + // Should never happen since we check env var above, but be safe + return reply.send({ success: true }); + } + + switch (level.toLowerCase()) { + case 'error': + fileConsolidatedLogger.error(logData, message); + break; + case 'warn': + case 'warning': + fileConsolidatedLogger.warn(logData, message); + break; + case 'debug': + fileConsolidatedLogger.debug(logData, message); + break; + default: + fileConsolidatedLogger.info(logData, message); + } + + return reply.send({ success: true }); }); - - return { success: true }; + } + + // Catch-all route for debugging 404s + app.setNotFoundHandler((request, reply) => { + log({ module: '404-handler' }, `404 - Method: ${request.method}, Path: ${request.url}, Headers: ${JSON.stringify(request.headers)}`); + reply.code(404).send({ error: 'Not found', path: request.url, method: request.method }); }); // Start diff --git a/sources/utils/log.ts b/sources/utils/log.ts index a2d9cc5..d07402a 100644 --- a/sources/utils/log.ts +++ b/sources/utils/log.ts @@ -2,17 +2,37 @@ import pino from 'pino'; import { mkdirSync } from 'fs'; import { join } from 'path'; -const isDebug = process.env.DEBUG === 'true' || process.env.NODE_ENV === 'development'; -const logsDir = join(process.cwd(), '.logs'); +// Single log file name created once at startup +let consolidatedLogFile: string | undefined; -if (isDebug) { +if (process.env.DANGEROUSLY_LOG_TO_SERVER_FOR_AI_AUTO_DEBUGGING) { + const logsDir = join(process.cwd(), '.logs'); try { mkdirSync(logsDir, { recursive: true }); + // Create filename once at startup + const now = new Date(); + const month = String(now.getMonth() + 1).padStart(2, '0'); + const day = String(now.getDate()).padStart(2, '0'); + const hour = String(now.getHours()).padStart(2, '0'); + const min = String(now.getMinutes()).padStart(2, '0'); + const sec = String(now.getSeconds()).padStart(2, '0'); + consolidatedLogFile = join(logsDir, `${month}-${day}-${hour}-${min}-${sec}.log`); + console.log(`[PINO] Remote debugging logs enabled - writing to ${consolidatedLogFile}`); } catch (error) { console.error('Failed to create logs directory:', error); } } +// Format time as HH:MM:ss.mmm in local time +function formatLocalTime(timestamp?: number) { + const date = timestamp ? new Date(timestamp) : new Date(); + const hours = String(date.getHours()).padStart(2, '0'); + const mins = String(date.getMinutes()).padStart(2, '0'); + const secs = String(date.getSeconds()).padStart(2, '0'); + const ms = String(date.getMilliseconds()).padStart(3, '0'); + return `${hours}:${mins}:${secs}.${ms}`; +} + const transports: any[] = []; transports.push({ @@ -21,28 +41,66 @@ transports.push({ colorize: true, translateTime: 'HH:MM:ss.l', ignore: 'pid,hostname', - messageFormat: '{levelLabel} [{time}] {msg}', + messageFormat: '{levelLabel} {msg} | [{time}]', errorLikeObjectKeys: ['err', 'error'], }, }); -if (isDebug) { +if (process.env.DANGEROUSLY_LOG_TO_SERVER_FOR_AI_AUTO_DEBUGGING && consolidatedLogFile) { transports.push({ target: 'pino/file', options: { - destination: join(logsDir, `server-${new Date().toISOString().split('T')[0]}.log`), + destination: consolidatedLogFile, mkdir: true, + messageFormat: '{levelLabel} {msg} | [server time: {time}]', }, }); } +// Main server logger with local time formatting export const logger = pino({ - level: isDebug ? 'debug' : 'info', + level: 'debug', transport: { targets: transports, }, + formatters: { + log: (object: any) => { + // Add localTime to every log entry + return { + ...object, + localTime: formatLocalTime(typeof object.time === 'number' ? object.time : undefined), + }; + } + }, + timestamp: () => `,"time":${Date.now()},"localTime":"${formatLocalTime()}"`, }); +// Optional file-only logger for remote logs from CLI/mobile +export const fileConsolidatedLogger = process.env.DANGEROUSLY_LOG_TO_SERVER_FOR_AI_AUTO_DEBUGGING && consolidatedLogFile ? + pino({ + level: 'debug', + transport: { + targets: [{ + target: 'pino/file', + options: { + destination: consolidatedLogFile, + mkdir: true, + }, + }], + }, + formatters: { + log: (object: any) => { + // Add localTime to every log entry + // Note: source property already exists from CLI/mobile logs + return { + ...object, + localTime: formatLocalTime(typeof object.time === 'number' ? object.time : undefined), + }; + } + }, + timestamp: () => `,"time":${Date.now()},"localTime":"${formatLocalTime()}"`, + }) : undefined; + export function log(src: any, ...args: any[]) { logger.info(src, ...args); }