songtianlun/happy-server
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

devx: dangerous logging endpoint

Browse Source
This commit is contained in:
Kirill Dubovitskiy 2025-08-15 19:13:45 -07:00
parent 4006d63232
commit 3a804f24c8
5 changed files with 284 additions and 27 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

3
.env.example → .env.dev
View File

@ -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

95
CLAUDE.md
View File

@ -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
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

6
package.json
View File

@ -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": {

135
sources/app/api.ts
View File

@ -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

72
sources/utils/log.ts
View File

@ -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);
}