diff --git a/web/src/server/fwd.ts b/web/src/server/fwd.ts index 6f6348b1..f75361cd 100755 --- a/web/src/server/fwd.ts +++ b/web/src/server/fwd.ts @@ -16,7 +16,7 @@ import * as os from 'os'; import chalk from 'chalk'; import { PtyManager } from './pty/index.js'; import { VERSION, BUILD_DATE, GIT_COMMIT } from './version.js'; -import { createLogger, initLogger, closeLogger } from './utils/logger.js'; +import { createLogger, closeLogger } from './utils/logger.js'; const logger = createLogger('fwd'); @@ -40,8 +40,11 @@ function showUsage() { } export async function startVibeTunnelForward(args: string[]) { - // Initialize logger - initLogger(args.includes('--debug')); + // Log startup with version (logger already initialized in cli.ts) + logger.log(chalk.blue(`VibeTunnel Forward v${VERSION}`) + chalk.gray(` (${BUILD_DATE})`)); + if (args.includes('--debug')) { + logger.debug('Debug mode enabled'); + } // Parse command line arguments if (args.length === 0 || args[0] === '--help' || args[0] === '-h') { @@ -62,7 +65,7 @@ export async function startVibeTunnelForward(args: string[]) { const command = remainingArgs; if (command.length === 0) { - logger.error('Error: No command specified'); + logger.error('No command specified'); showUsage(); closeLogger(); process.exit(1); @@ -72,6 +75,7 @@ export async function startVibeTunnelForward(args: string[]) { // Initialize PTY manager const controlPath = path.join(os.homedir(), '.vibetunnel', 'control'); + logger.debug(`Control path: ${controlPath}`); const ptyManager = new PtyManager(controlPath); try { @@ -81,6 +85,9 @@ export async function startVibeTunnelForward(args: string[]) { // Pre-generate session ID if not provided const finalSessionId = sessionId || `fwd_${Date.now()}`; + logger.log(`Creating session for command: ${command.join(' ')}`); + logger.debug(`Session ID: ${finalSessionId}, working directory: ${cwd}`); + const result = await ptyManager.createSession(command, { sessionId: finalSessionId, name: sessionName, @@ -90,10 +97,13 @@ export async function startVibeTunnelForward(args: string[]) { forwardToStdout: true, onExit: async (exitCode: number) => { // Show exit message - logger.log(chalk.yellow('\n✓ VibeTunnel session ended')); + logger.log( + chalk.yellow(`\n✓ VibeTunnel session ended`) + chalk.gray(` (exit code: ${exitCode})`) + ); // Restore terminal settings and clean up stdin if (process.stdin.isTTY) { + logger.debug('Restoring terminal to normal mode'); process.stdin.setRawMode(false); } process.stdin.pause(); @@ -105,6 +115,7 @@ export async function startVibeTunnelForward(args: string[]) { } // Shutdown PTY manager and exit + logger.debug('Shutting down PTY manager'); await ptyManager.shutdown(); // Force exit @@ -126,6 +137,7 @@ export async function startVibeTunnelForward(args: string[]) { // Set up raw mode for terminal input if (process.stdin.isTTY) { + logger.debug('Setting terminal to raw mode for input forwarding'); process.stdin.setRawMode(true); } process.stdin.resume(); @@ -135,10 +147,6 @@ export async function startVibeTunnelForward(args: string[]) { } catch (error) { logger.error('Failed to create or manage session:', error); - if (error instanceof Error) { - logger.error('Error details:', error.message); - } - closeLogger(); process.exit(1); } diff --git a/web/src/server/middleware/auth.ts b/web/src/server/middleware/auth.ts index defefa65..28ee8855 100644 --- a/web/src/server/middleware/auth.ts +++ b/web/src/server/middleware/auth.ts @@ -15,17 +15,17 @@ export function createAuthMiddleware(config: AuthConfig) { return (req: Request, res: Response, next: NextFunction) => { // Skip auth for health check endpoint if (req.path === '/api/health') { + logger.debug('bypassing auth for health check endpoint'); return next(); } // If no auth configured, allow all requests if (!config.basicAuthUsername || !config.basicAuthPassword) { + logger.debug('no auth configured, allowing request'); return next(); } - logger.debug( - `Auth check: ${req.method} ${req.path}, auth header: ${req.headers.authorization || 'none'}` - ); + logger.debug(`auth check for ${req.method} ${req.path} from ${req.ip}`); // Check for Bearer token (for HQ to remote communication) const authHeader = req.headers.authorization; @@ -33,17 +33,17 @@ export function createAuthMiddleware(config: AuthConfig) { const token = authHeader.substring(7); // In HQ mode, bearer tokens are not accepted (HQ uses basic auth) if (config.isHQMode) { + logger.warn(`bearer token rejected in HQ mode from ${req.ip}`); res.setHeader('WWW-Authenticate', 'Basic realm="VibeTunnel"'); return res.status(401).json({ error: 'Bearer token not accepted in HQ mode' }); } else if (config.bearerToken && token === config.bearerToken) { // Token matches what this remote server expects from HQ + logger.log(chalk.green(`authenticated via bearer token from ${req.ip}`)); return next(); } else if (config.bearerToken) { // We have a bearer token configured but it doesn't match - logger.warn(`Bearer token mismatch: expected ${config.bearerToken}, got ${token}`); + logger.warn(`invalid bearer token from ${req.ip}`); } - } else { - logger.debug(`No bearer token in request, bearerToken configured: ${!!config.bearerToken}`); } // Check Basic auth @@ -54,11 +54,13 @@ export function createAuthMiddleware(config: AuthConfig) { if (username === config.basicAuthUsername && password === config.basicAuthPassword) { return next(); + } else { + logger.warn(`failed basic auth attempt from ${req.ip} for user: ${username}`); } } // No valid auth provided - logger.warn(chalk.red(`Unauthorized request to ${req.method} ${req.path} from ${req.ip}`)); + logger.warn(`unauthorized request to ${req.method} ${req.path} from ${req.ip}`); res.setHeader('WWW-Authenticate', 'Basic realm="VibeTunnel"'); res.status(401).json({ error: 'Authentication required' }); }; diff --git a/web/src/server/pty/process-utils.ts b/web/src/server/pty/process-utils.ts index f482cc8e..25f9b1e2 100644 --- a/web/src/server/pty/process-utils.ts +++ b/web/src/server/pty/process-utils.ts @@ -6,6 +6,7 @@ import { spawnSync } from 'child_process'; import { createLogger } from '../utils/logger.js'; +import chalk from 'chalk'; const logger = createLogger('process-utils'); @@ -28,7 +29,7 @@ export class ProcessUtils { return ProcessUtils.isProcessRunningUnix(pid); } } catch (error) { - logger.warn(`Error checking if process ${pid} is running:`, error); + logger.warn(`error checking if process ${pid} is running:`, error); return false; } } @@ -38,6 +39,7 @@ export class ProcessUtils { */ private static isProcessRunningWindows(pid: number): boolean { try { + logger.debug(`checking windows process ${pid} with tasklist`); const result = spawnSync('tasklist', ['/FI', `PID eq ${pid}`, '/NH', '/FO', 'CSV'], { encoding: 'utf8', windowsHide: true, @@ -47,12 +49,15 @@ export class ProcessUtils { // Check if the command succeeded and PID appears in output if (result.status === 0 && result.stdout) { // tasklist outputs CSV format with PID in quotes - return result.stdout.includes(`"${pid}"`); + const exists = result.stdout.includes(`"${pid}"`); + logger.debug(`process ${pid} exists: ${exists}`); + return exists; } + logger.debug(`tasklist command failed with status ${result.status}`); return false; } catch (error) { - logger.warn(`Windows process check failed for PID ${pid}:`, error); + logger.warn(`windows process check failed for PID ${pid}:`, error); return false; } } @@ -103,6 +108,8 @@ export class ProcessUtils { return false; } + logger.debug(`attempting to kill process ${pid} with signal ${signal}`); + try { if (process.platform === 'win32') { // Windows: Use taskkill command for more reliable termination @@ -110,14 +117,21 @@ export class ProcessUtils { windowsHide: true, timeout: 5000, }); - return result.status === 0; + if (result.status === 0) { + logger.log(chalk.green(`process ${pid} killed successfully`)); + return true; + } else { + logger.debug(`taskkill failed with status ${result.status}`); + return false; + } } else { // Unix-like: Use built-in process.kill process.kill(pid, signal); + logger.log(chalk.green(`signal ${signal} sent to process ${pid}`)); return true; } } catch (error) { - logger.warn(`Error killing process ${pid}:`, error); + logger.warn(`error killing process ${pid}:`, error); return false; } } @@ -130,13 +144,18 @@ export class ProcessUtils { const startTime = Date.now(); const checkInterval = 100; // Check every 100ms + logger.debug(`waiting for process ${pid} to exit (timeout: ${timeoutMs}ms)`); + while (Date.now() - startTime < timeoutMs) { if (!ProcessUtils.isProcessRunning(pid)) { + const elapsed = Date.now() - startTime; + logger.log(chalk.green(`process ${pid} exited after ${elapsed}ms`)); return true; } await new Promise((resolve) => setTimeout(resolve, checkInterval)); } + logger.log(chalk.yellow(`process ${pid} did not exit within ${timeoutMs}ms timeout`)); return false; } } diff --git a/web/src/server/pty/pty-manager.ts b/web/src/server/pty/pty-manager.ts index ded37cce..42433a23 100644 --- a/web/src/server/pty/pty-manager.ts +++ b/web/src/server/pty/pty-manager.ts @@ -29,6 +29,7 @@ import { } from '../../shared/types.js'; import { IPty } from '@homebridge/node-pty-prebuilt-multiarch'; import { createLogger } from '../utils/logger.js'; +import chalk from 'chalk'; const logger = createLogger('pty-manager'); @@ -55,6 +56,7 @@ export class PtyManager { private setupTerminalResizeDetection(): void { // Only setup resize detection if we're running in a TTY if (!process.stdout.isTTY) { + logger.debug('Not a TTY, skipping terminal resize detection'); return; } @@ -102,7 +104,7 @@ export class PtyManager { return; } - logger.log(`Terminal resized to ${newCols}x${newRows}, updating active sessions`); + logger.log(chalk.blue(`Terminal resized to ${newCols}x${newRows}`)); // Update stored size this.lastTerminalSize = { cols: newCols, rows: newRows }; @@ -134,13 +136,13 @@ export class PtyManager { timestamp: currentTime, }); - logger.debug(`Resized session ${sessionId} to ${newCols}x${newRows} (terminal resize)`); + logger.debug(`Resized session ${sessionId} to ${newCols}x${newRows} from terminal`); } catch (error) { logger.error(`Failed to resize session ${sessionId}:`, error); } } else { logger.debug( - `Skipping terminal resize for session ${sessionId} - browser resize takes precedence` + `Skipping terminal resize for session ${sessionId} (browser has precedence)` ); } } @@ -226,7 +228,7 @@ export class PtyManager { errorMessage = `Working directory does not exist: '${workingDir}'`; } - logger.error(`PTY spawn error for command '${command.join(' ')}':`, spawnError); + logger.error(`Failed to spawn PTY for command '${command.join(' ')}':`, spawnError); throw new PtyError(errorMessage, 'SPAWN_FAILED'); } @@ -251,6 +253,8 @@ export class PtyManager { sessionInfo.status = 'running'; this.sessionManager.saveSessionInfo(sessionId, sessionInfo); + logger.log(chalk.green(`Session ${sessionId} created successfully (PID: ${ptyProcess.pid})`)); + // Setup PTY event handlers this.setupPtyHandlers(session, options.forwardToStdout || false, options.onExit); @@ -260,6 +264,7 @@ export class PtyManager { // Setup stdin forwarding for fwd mode this.setupStdinForwarding(session); + logger.log(chalk.gray('Stdin forwarding enabled')); } return { @@ -311,7 +316,7 @@ export class PtyManager { process.stdout.write(data); } } catch (error) { - logger.error(`Error writing PTY data for session ${session.id}:`, error); + logger.error(`Failed to write PTY data for session ${session.id}:`, error); } }); @@ -323,7 +328,9 @@ export class PtyManager { asciinemaWriter.writeRawJson(['exit', exitCode || 0, session.id]); asciinemaWriter .close() - .catch((error) => logger.error('Failed to close asciinema writer:', error)); + .catch((error) => + logger.error(`Failed to close asciinema writer for session ${session.id}:`, error) + ); } // Update session status @@ -344,8 +351,8 @@ export class PtyManager { if (onExit) { onExit(exitCode || 0, signal); } - } catch (_error) { - logger.error(`Error handling exit for session ${session.id}:`, _error); + } catch (error) { + logger.error(`Failed to handle exit for session ${session.id}:`, error); } }); @@ -365,7 +372,7 @@ export class PtyManager { try { fs.unlinkSync(socketPath); } catch (_e) { - // Ignore if doesn't exist + // Socket doesn't exist, this is expected } // Create Unix domain socket server @@ -386,15 +393,16 @@ export class PtyManager { // Make socket writable by all try { fs.chmodSync(socketPath, 0o666); - } catch (_e) { - // Ignore chmod errors + } catch (e) { + logger.debug(`Failed to chmod input socket for session ${session.id}:`, e); } + logger.debug(`Input socket created for session ${session.id}`); }); // Store server reference for cleanup session.inputSocketServer = inputServer; } catch (error) { - logger.warn(`Failed to create input socket for session ${session.id}:`, error); + logger.error(`Failed to create input socket for session ${session.id}:`, error); } // Socket-only approach - no FIFO monitoring @@ -434,15 +442,15 @@ export class PtyManager { const message = JSON.parse(line); this.handleControlMessage(session, message); } catch (_e) { - logger.warn('Invalid control message:', line); + logger.warn(`Invalid control message in session ${session.id}: ${line}`); } } } lastControlPosition = stats.size; } - } catch (_error) { - // Control file might be temporarily unavailable + } catch (error) { + logger.debug(`Failed to read control data for session ${session.id}:`, error); } }; @@ -462,7 +470,7 @@ export class PtyManager { // Read any existing data readNewControlData(); } catch (error) { - logger.warn('Failed to set up control pipe:', error); + logger.error(`Failed to set up control pipe for session ${session.id}:`, error); } } @@ -481,7 +489,10 @@ export class PtyManager { session.asciinemaWriter?.writeResize(message.cols, message.rows); } } catch (error) { - logger.warn('Failed to resize session:', error); + logger.warn( + `Failed to resize session ${session.id} to ${message.cols}x${message.rows}:`, + error + ); } } else if (message.cmd === 'kill') { const signal = @@ -493,7 +504,7 @@ export class PtyManager { session.ptyProcess.kill(signal as string); } } catch (error) { - logger.warn('Failed to kill session:', error); + logger.warn(`Failed to kill session ${session.id} with signal ${signal}:`, error); } } } @@ -550,7 +561,8 @@ export class PtyManager { socketClient.on('close', () => { this.inputSocketClients.delete(sessionId); }); - } catch (_error) { + } catch (error) { + logger.debug(`Failed to connect to input socket for session ${sessionId}:`, error); socketClient = undefined; } } @@ -592,7 +604,7 @@ export class PtyManager { fs.appendFileSync(sessionPaths.controlPipePath, messageStr); return true; } catch (error) { - logger.warn(`Failed to send control message to session ${sessionId}:`, error); + logger.error(`Failed to send control message to session ${sessionId}:`, error); } return false; } @@ -641,7 +653,7 @@ export class PtyManager { timestamp: currentTime, }); - logger.debug(`Resized session ${sessionId} to ${cols}x${rows} (browser resize)`); + logger.debug(`Resized session ${sessionId} to ${cols}x${rows} from browser`); } else { // For external sessions, try to send resize via control pipe const resizeMessage: ResizeControlMessage = { @@ -710,7 +722,7 @@ export class PtyManager { if (diskSession.pid && ProcessUtils.isProcessRunning(diskSession.pid)) { logger.log( - `Killing external session ${sessionId} (PID: ${diskSession.pid}) with ${signal}...` + chalk.yellow(`Killing external session ${sessionId} (PID: ${diskSession.pid})`) ); if (signal === 'SIGKILL' || signal === 9) { @@ -731,17 +743,13 @@ export class PtyManager { await new Promise((resolve) => setTimeout(resolve, checkInterval)); if (!ProcessUtils.isProcessRunning(diskSession.pid)) { - logger.log( - `External session ${sessionId} terminated gracefully after ${(i + 1) * checkInterval}ms` - ); + logger.log(chalk.green(`External session ${sessionId} terminated gracefully`)); return; } } // Process didn't terminate gracefully, force kill - logger.log( - `External session ${sessionId} didn't terminate gracefully, sending SIGKILL...` - ); + logger.log(chalk.yellow(`External session ${sessionId} requires SIGKILL`)); process.kill(diskSession.pid, 'SIGKILL'); await new Promise((resolve) => setTimeout(resolve, 100)); } @@ -765,7 +773,7 @@ export class PtyManager { } const pid = session.ptyProcess.pid; - logger.log(`Terminating session ${sessionId} (PID: ${pid}) with SIGTERM...`); + logger.log(chalk.yellow(`Terminating session ${sessionId} (PID: ${pid})`)); try { // Send SIGTERM first @@ -783,31 +791,29 @@ export class PtyManager { // Check if process is still alive if (!ProcessUtils.isProcessRunning(pid)) { // Process no longer exists - it terminated gracefully - logger.log( - `Session ${sessionId} terminated gracefully after ${(i + 1) * checkInterval}ms` - ); + logger.log(chalk.green(`Session ${sessionId} terminated gracefully`)); this.sessions.delete(sessionId); return; } // Process still exists, continue waiting - logger.debug(`Session ${sessionId} still alive after ${(i + 1) * checkInterval}ms...`); + logger.debug(`Session ${sessionId} still running after ${(i + 1) * checkInterval}ms`); } // Process didn't terminate gracefully within 3 seconds, force kill - logger.log(`Session ${sessionId} didn't terminate gracefully, sending SIGKILL...`); + logger.log(chalk.yellow(`Session ${sessionId} requires SIGKILL`)); try { session.ptyProcess.kill('SIGKILL'); // Wait a bit more for SIGKILL to take effect await new Promise((resolve) => setTimeout(resolve, 100)); } catch (_killError) { // Process might have died between our check and SIGKILL - logger.debug(`SIGKILL failed for session ${sessionId}, process likely already dead`); + logger.debug(`SIGKILL failed for session ${sessionId} (process already terminated)`); } // Remove from sessions regardless this.sessions.delete(sessionId); - logger.log(`Session ${sessionId} forcefully terminated with SIGKILL`); + logger.log(chalk.yellow(`Session ${sessionId} forcefully terminated`)); } catch (error) { // Remove from sessions even if kill failed this.sessions.delete(sessionId); @@ -869,7 +875,7 @@ export class PtyManager { // Kill active session if exists (fire-and-forget for cleanup) if (this.sessions.has(sessionId)) { this.killSession(sessionId).catch((error) => { - logger.error(`Error killing session ${sessionId} during cleanup:`, error); + logger.error(`Failed to kill session ${sessionId} during cleanup:`, error); }); } @@ -940,7 +946,7 @@ export class PtyManager { // Clean up all session resources this.cleanupSessionResources(session); } catch (error) { - logger.error(`Error cleaning up session ${sessionId}:`, error); + logger.error(`Failed to cleanup session ${sessionId} during shutdown:`, error); } } @@ -951,7 +957,7 @@ export class PtyManager { try { socket.destroy(); } catch (_e) { - // Ignore errors + // Socket already destroyed } } this.inputSocketClients.clear(); @@ -961,7 +967,7 @@ export class PtyManager { try { removeListener(); } catch (error) { - logger.error('Error removing resize event listener:', error); + logger.error('Failed to remove resize event listener:', error); } } this.resizeEventListeners.length = 0; @@ -985,7 +991,7 @@ export class PtyManager { try { session.ptyProcess?.write(data); } catch (error) { - logger.error('Failed to send input:', error); + logger.error(`Failed to forward stdin to session ${session.id}:`, error); } }); } @@ -1006,7 +1012,7 @@ export class PtyManager { try { fs.unlinkSync(path.join(session.controlDir, 'input.sock')); } catch (_e) { - // Ignore + // Socket already removed } } @@ -1020,7 +1026,7 @@ export class PtyManager { try { fs.unlinkSync(session.controlPipePath); } catch (_e) { - // Ignore + // Control pipe already removed } } } diff --git a/web/src/server/pty/session-manager.ts b/web/src/server/pty/session-manager.ts index 7f3fae62..d8928a9c 100644 --- a/web/src/server/pty/session-manager.ts +++ b/web/src/server/pty/session-manager.ts @@ -13,6 +13,7 @@ import { ProcessUtils } from './process-utils.js'; import { Session, SessionInfo } from '../../shared/types.js'; import { spawnSync } from 'child_process'; import { createLogger } from '../utils/logger.js'; +import chalk from 'chalk'; const logger = createLogger('session-manager'); @@ -21,6 +22,7 @@ export class SessionManager { constructor(controlPath?: string) { this.controlPath = controlPath || path.join(os.homedir(), '.vibetunnel', 'control'); + logger.debug(`initializing session manager with control path: ${this.controlPath}`); this.ensureControlDirectory(); } @@ -30,6 +32,7 @@ export class SessionManager { private ensureControlDirectory(): void { if (!fs.existsSync(this.controlPath)) { fs.mkdirSync(this.controlPath, { recursive: true }); + logger.log(chalk.green(`control directory created: ${this.controlPath}`)); } } @@ -57,6 +60,7 @@ export class SessionManager { // Create FIFO pipe for stdin (or regular file on systems without mkfifo) this.createStdinPipe(paths.stdinPath); + logger.log(chalk.green(`session directory created for ${sessionId}`)); return paths; } @@ -69,6 +73,7 @@ export class SessionManager { if (process.platform !== 'win32') { const result = spawnSync('mkfifo', [stdinPath], { stdio: 'ignore' }); if (result.status === 0) { + logger.debug(`FIFO pipe created: ${stdinPath}`); return; // Successfully created FIFO } } @@ -77,8 +82,11 @@ export class SessionManager { if (!fs.existsSync(stdinPath)) { fs.writeFileSync(stdinPath, ''); } - } catch (_error) { + } catch (error) { // If mkfifo fails, create regular file + logger.debug( + `mkfifo failed (${error instanceof Error ? error.message : 'unknown error'}), creating regular file: ${stdinPath}` + ); if (!fs.existsSync(stdinPath)) { fs.writeFileSync(stdinPath, ''); } @@ -97,6 +105,7 @@ export class SessionManager { const tempPath = sessionJsonPath + '.tmp'; fs.writeFileSync(tempPath, sessionInfoStr, 'utf8'); fs.renameSync(tempPath, sessionJsonPath); + logger.debug(`session info saved for ${sessionId}`); } catch (error) { throw new PtyError( `Failed to save session info: ${error instanceof Error ? error.message : String(error)}`, @@ -118,7 +127,7 @@ export class SessionManager { const content = fs.readFileSync(sessionJsonPath, 'utf8'); return JSON.parse(content) as SessionInfo; } catch (error) { - logger.warn(`Failed to load session info from ${sessionJsonPath}:`, error); + logger.warn(`failed to load session info for ${sessionId}:`, error); return null; } } @@ -141,6 +150,9 @@ export class SessionManager { } this.saveSessionInfo(sessionId, sessionInfo); + logger.log( + `session ${sessionId} status updated to ${status}${pid ? ` (pid: ${pid})` : ''}${exitCode !== undefined ? ` (exit code: ${exitCode})` : ''}` + ); } /** @@ -167,6 +179,11 @@ export class SessionManager { if (sessionInfo.status === 'running' && sessionInfo.pid) { // Update status if process is no longer alive if (!ProcessUtils.isProcessRunning(sessionInfo.pid)) { + logger.log( + chalk.yellow( + `process ${sessionInfo.pid} no longer running for session ${sessionId}` + ) + ); sessionInfo.status = 'exited'; if (sessionInfo.exitCode === undefined) { sessionInfo.exitCode = 1; // Default exit code for dead processes @@ -191,6 +208,7 @@ export class SessionManager { return bTime - aTime; }); + logger.debug(`found ${sessions.length} sessions`); return sessions; } catch (error) { throw new PtyError( @@ -223,6 +241,7 @@ export class SessionManager { if (fs.existsSync(sessionDir)) { // Remove directory and all contents fs.rmSync(sessionDir, { recursive: true, force: true }); + logger.log(chalk.green(`session ${sessionId} cleaned up`)); } } catch (error) { throw new PtyError( @@ -249,6 +268,9 @@ export class SessionManager { } } + if (cleanedSessions.length > 0) { + logger.log(chalk.green(`cleaned up ${cleanedSessions.length} exited sessions`)); + } return cleanedSessions; } catch (error) { throw new PtyError( @@ -299,6 +321,7 @@ export class SessionManager { // For FIFO pipes, we need to open in append mode // For regular files, we also use append mode to avoid conflicts fs.appendFileSync(paths.stdinPath, data); + logger.debug(`wrote ${data.length} bytes to stdin for session ${sessionId}`); } catch (error) { throw new PtyError( `Failed to write to stdin for session ${sessionId}: ${error instanceof Error ? error.message : String(error)}`, @@ -323,6 +346,11 @@ export class SessionManager { // Process is dead, update status const paths = this.getSessionPaths(session.id); if (paths) { + logger.log( + chalk.yellow( + `marking zombie process ${session.pid} as exited for session ${session.id}` + ) + ); this.updateSessionStatus(session.id, 'exited', undefined, 1); updatedSessions.push(session.id); } @@ -332,7 +360,7 @@ export class SessionManager { return updatedSessions; } catch (error) { - logger.warn('Failed to update zombie sessions:', error); + logger.warn('failed to update zombie sessions:', error); return []; } } diff --git a/web/src/server/routes/filesystem.ts b/web/src/server/routes/filesystem.ts index 6dd32ec5..b3d2df5a 100644 --- a/web/src/server/routes/filesystem.ts +++ b/web/src/server/routes/filesystem.ts @@ -6,6 +6,7 @@ import { promisify } from 'util'; import mime from 'mime-types'; import { createReadStream, statSync } from 'fs'; import { createLogger } from '../utils/logger.js'; +import chalk from 'chalk'; const logger = createLogger('filesystem'); @@ -106,8 +107,13 @@ export function createFilesystemRoutes(): Router { const showHidden = req.query.showHidden === 'true'; const gitFilter = req.query.gitFilter as string; // 'all' | 'changed' | 'none' + logger.debug( + `browsing directory: ${requestedPath}, showHidden: ${showHidden}, gitFilter: ${gitFilter}` + ); + // Security check if (!isPathSafe(requestedPath, process.cwd())) { + logger.warn(`access denied for path: ${requestedPath}`); return res.status(403).json({ error: 'Access denied' }); } @@ -116,11 +122,16 @@ export function createFilesystemRoutes(): Router { // Check if path exists and is a directory const stats = await fs.stat(fullPath); if (!stats.isDirectory()) { + logger.warn(`path is not a directory: ${requestedPath}`); return res.status(400).json({ error: 'Path is not a directory' }); } // Get Git status if requested + const gitStatusStart = Date.now(); const gitStatus = gitFilter !== 'none' ? await getGitStatus(fullPath) : null; + if (gitFilter !== 'none') { + logger.debug(`git status check took ${Date.now() - gitStatusStart}ms for ${requestedPath}`); + } // Read directory contents const entries = await fs.readdir(fullPath, { withFileTypes: true }); @@ -163,6 +174,12 @@ export function createFilesystemRoutes(): Router { return a.name.localeCompare(b.name); }); + logger.log( + chalk.green( + `directory browsed successfully: ${requestedPath} (${filteredFiles.length} items)` + ) + ); + res.json({ path: requestedPath, fullPath, @@ -170,7 +187,7 @@ export function createFilesystemRoutes(): Router { files: filteredFiles, }); } catch (error) { - logger.error('Browse error:', error); + logger.error(`failed to browse directory ${req.query.path}:`, error); res.status(500).json({ error: error instanceof Error ? error.message : String(error) }); } }); @@ -183,8 +200,11 @@ export function createFilesystemRoutes(): Router { return res.status(400).json({ error: 'Path is required' }); } + logger.debug(`previewing file: ${requestedPath}`); + // Security check if (!isPathSafe(requestedPath, process.cwd())) { + logger.warn(`access denied for file preview: ${requestedPath}`); return res.status(403).json({ error: 'Access denied' }); } @@ -192,6 +212,7 @@ export function createFilesystemRoutes(): Router { const stats = await fs.stat(fullPath); if (stats.isDirectory()) { + logger.warn(`cannot preview directory: ${requestedPath}`); return res.status(400).json({ error: 'Cannot preview directories' }); } @@ -207,6 +228,9 @@ export function createFilesystemRoutes(): Router { if (isImage) { // For images, return URL to fetch the image + logger.log( + chalk.green(`image preview generated: ${requestedPath} (${formatBytes(stats.size)})`) + ); res.json({ type: 'image', mimeType, @@ -218,6 +242,12 @@ export function createFilesystemRoutes(): Router { const content = await fs.readFile(fullPath, 'utf-8'); const language = getLanguageFromPath(fullPath); + logger.log( + chalk.green( + `text file preview generated: ${requestedPath} (${formatBytes(stats.size)}, ${language})` + ) + ); + res.json({ type: 'text', content, @@ -227,6 +257,9 @@ export function createFilesystemRoutes(): Router { }); } else { // Binary or large files + logger.log( + `binary file preview metadata returned: ${requestedPath} (${formatBytes(stats.size)})` + ); res.json({ type: 'binary', mimeType, @@ -235,7 +268,7 @@ export function createFilesystemRoutes(): Router { }); } } catch (error) { - logger.error('Preview error:', error); + logger.error(`failed to preview file ${req.query.path}:`, error); res.status(500).json({ error: error instanceof Error ? error.message : String(error) }); } }); @@ -248,8 +281,11 @@ export function createFilesystemRoutes(): Router { return res.status(400).json({ error: 'Path is required' }); } + logger.debug(`serving raw file: ${requestedPath}`); + // Security check if (!isPathSafe(requestedPath, process.cwd())) { + logger.warn(`access denied for raw file: ${requestedPath}`); return res.status(403).json({ error: 'Access denied' }); } @@ -257,6 +293,7 @@ export function createFilesystemRoutes(): Router { // Check if file exists if (!statSync(fullPath).isFile()) { + logger.warn(`file not found for raw access: ${requestedPath}`); return res.status(404).json({ error: 'File not found' }); } @@ -267,8 +304,12 @@ export function createFilesystemRoutes(): Router { // Stream the file const stream = createReadStream(fullPath); stream.pipe(res); + + stream.on('end', () => { + logger.log(chalk.green(`raw file served: ${requestedPath}`)); + }); } catch (error) { - logger.error('Raw file error:', error); + logger.error(`failed to serve raw file ${req.query.path}:`, error); res.status(500).json({ error: error instanceof Error ? error.message : String(error) }); } }); @@ -281,21 +322,26 @@ export function createFilesystemRoutes(): Router { return res.status(400).json({ error: 'Path is required' }); } + logger.debug(`getting file content: ${requestedPath}`); + // Security check if (!isPathSafe(requestedPath, process.cwd())) { + logger.warn(`access denied for file content: ${requestedPath}`); return res.status(403).json({ error: 'Access denied' }); } const fullPath = path.resolve(process.cwd(), requestedPath); const content = await fs.readFile(fullPath, 'utf-8'); + logger.log(chalk.green(`file content retrieved: ${requestedPath}`)); + res.json({ path: requestedPath, content, language: getLanguageFromPath(fullPath), }); } catch (error) { - logger.error('Content error:', error); + logger.error(`failed to get file content ${req.query.path}:`, error); res.status(500).json({ error: error instanceof Error ? error.message : String(error) }); } }); @@ -308,8 +354,11 @@ export function createFilesystemRoutes(): Router { return res.status(400).json({ error: 'Path is required' }); } + logger.debug(`getting git diff: ${requestedPath}`); + // Security check if (!isPathSafe(requestedPath, process.cwd())) { + logger.warn(`access denied for git diff: ${requestedPath}`); return res.status(403).json({ error: 'Access denied' }); } @@ -317,17 +366,29 @@ export function createFilesystemRoutes(): Router { const relativePath = path.relative(process.cwd(), fullPath); // Get git diff + const diffStart = Date.now(); const { stdout: diff } = await execAsync(`git diff HEAD -- "${relativePath}"`, { cwd: process.cwd(), }); + const diffTime = Date.now() - diffStart; + if (diffTime > 1000) { + logger.warn(`slow git diff operation: ${requestedPath} took ${diffTime}ms`); + } + + logger.log( + chalk.green( + `git diff retrieved: ${requestedPath} (${diff.length > 0 ? 'has changes' : 'no changes'})` + ) + ); + res.json({ path: requestedPath, diff, hasDiff: diff.length > 0, }); } catch (error) { - logger.error('Diff error:', error); + logger.error(`failed to get git diff for ${req.query.path}:`, error); res.status(500).json({ error: error instanceof Error ? error.message : String(error) }); } }); @@ -341,13 +402,17 @@ export function createFilesystemRoutes(): Router { return res.status(400).json({ error: 'Path and name are required' }); } + logger.log(`creating directory: ${name} in ${dirPath}`); + // Validate name (no slashes, no dots at start) if (name.includes('/') || name.includes('\\') || name.startsWith('.')) { + logger.warn(`invalid directory name attempted: ${name}`); return res.status(400).json({ error: 'Invalid directory name' }); } // Security check if (!isPathSafe(dirPath, process.cwd())) { + logger.warn(`access denied for mkdir: ${dirPath}/${name}`); return res.status(403).json({ error: 'Access denied' }); } @@ -356,12 +421,14 @@ export function createFilesystemRoutes(): Router { // Create directory await fs.mkdir(fullPath, { recursive: true }); + logger.log(chalk.green(`directory created: ${path.relative(process.cwd(), fullPath)}`)); + res.json({ success: true, path: path.relative(process.cwd(), fullPath), }); } catch (error) { - logger.error('Mkdir error:', error); + logger.error(`failed to create directory ${req.body.path}/${req.body.name}:`, error); res.status(500).json({ error: error instanceof Error ? error.message : String(error) }); } }); diff --git a/web/src/server/routes/remotes.ts b/web/src/server/routes/remotes.ts index 52ca5df7..7efdc0ba 100644 --- a/web/src/server/routes/remotes.ts +++ b/web/src/server/routes/remotes.ts @@ -18,10 +18,12 @@ export function createRemoteRoutes(config: RemoteRoutesConfig): Router { // HQ Mode: List all registered remotes router.get('/remotes', (req, res) => { if (!isHQMode || !remoteRegistry) { + logger.debug('remotes list requested but not in HQ mode'); return res.status(404).json({ error: 'Not running in HQ mode' }); } const remotes = remoteRegistry.getRemotes(); + logger.debug(`listing ${remotes.length} registered remotes`); // Convert Set to Array for JSON serialization const remotesWithArraySessionIds = remotes.map((remote) => ({ ...remote, @@ -33,24 +35,30 @@ export function createRemoteRoutes(config: RemoteRoutesConfig): Router { // HQ Mode: Register a new remote router.post('/remotes/register', (req, res) => { if (!isHQMode || !remoteRegistry) { + logger.debug('remote registration attempted but not in HQ mode'); return res.status(404).json({ error: 'Not running in HQ mode' }); } const { id, name, url, token } = req.body; if (!id || !name || !url || !token) { + logger.warn( + `remote registration missing required fields: got id=${!!id}, name=${!!name}, url=${!!url}, token=${!!token}` + ); return res.status(400).json({ error: 'Missing required fields: id, name, url, token' }); } + logger.debug(`attempting to register remote ${name} (${id}) from ${url}`); + try { const remote = remoteRegistry.register({ id, name, url, token }); - logger.log(chalk.green(`Remote registered: ${name} (${id}) from ${url}`)); + logger.log(chalk.green(`remote registered: ${name} (${id}) from ${url}`)); res.json({ success: true, remote }); } catch (error) { if (error instanceof Error && error.message.includes('already registered')) { return res.status(409).json({ error: error.message }); } - logger.error(chalk.red('Failed to register remote:'), error); + logger.error('failed to register remote:', error); res.status(500).json({ error: 'Failed to register remote' }); } }); @@ -58,16 +66,19 @@ export function createRemoteRoutes(config: RemoteRoutesConfig): Router { // HQ Mode: Unregister a remote router.delete('/remotes/:remoteId', (req, res) => { if (!isHQMode || !remoteRegistry) { + logger.debug('remote unregistration attempted but not in HQ mode'); return res.status(404).json({ error: 'Not running in HQ mode' }); } const remoteId = req.params.remoteId; + logger.debug(`attempting to unregister remote ${remoteId}`); const success = remoteRegistry.unregister(remoteId); if (success) { - logger.log(chalk.yellow(`Remote unregistered: ${remoteId}`)); + logger.log(chalk.yellow(`remote unregistered: ${remoteId}`)); res.json({ success: true }); } else { + logger.warn(`attempted to unregister non-existent remote: ${remoteId}`); res.status(404).json({ error: 'Remote not found' }); } }); @@ -75,27 +86,34 @@ export function createRemoteRoutes(config: RemoteRoutesConfig): Router { // HQ Mode: Refresh sessions for a specific remote router.post('/remotes/:remoteName/refresh-sessions', async (req, res) => { if (!isHQMode || !remoteRegistry) { + logger.debug('session refresh attempted but not in HQ mode'); return res.status(404).json({ error: 'Not running in HQ mode' }); } // If server is shutting down, return service unavailable if (isShuttingDown()) { + logger.debug('session refresh rejected during shutdown'); return res.status(503).json({ error: 'Server is shutting down' }); } const remoteName = req.params.remoteName; const { action, sessionId } = req.body; + logger.debug( + `refreshing sessions for remote ${remoteName} (action: ${action}, sessionId: ${sessionId})` + ); // Find remote by name const remotes = remoteRegistry.getRemotes(); const remote = remotes.find((r) => r.name === remoteName); if (!remote) { + logger.warn(`remote not found for session refresh: ${remoteName}`); return res.status(404).json({ error: 'Remote not found' }); } try { // Fetch latest sessions from the remote + const startTime = Date.now(); const response = await fetch(`${remote.url}/api/sessions`, { headers: { Authorization: `Bearer ${remote.token}`, @@ -106,12 +124,15 @@ export function createRemoteRoutes(config: RemoteRoutesConfig): Router { if (response.ok) { const sessions = (await response.json()) as Array<{ id: string }>; const sessionIds = sessions.map((s) => s.id); + const duration = Date.now() - startTime; + remoteRegistry.updateRemoteSessions(remote.id, sessionIds); logger.log( - chalk.green( - `Updated sessions for remote ${remote.name}: ${sessionIds.length} sessions (${action} ${sessionId})` - ) + chalk.green(`updated sessions for remote ${remote.name}: ${sessionIds.length} sessions`) + ); + logger.debug( + `session refresh completed in ${duration}ms (action: ${action}, sessionId: ${sessionId})` ); res.json({ success: true, sessionCount: sessionIds.length }); } else { @@ -120,11 +141,11 @@ export function createRemoteRoutes(config: RemoteRoutesConfig): Router { } catch (error) { // During shutdown, connection failures are expected if (isShuttingDown()) { - logger.log(chalk.yellow(`Remote ${remote.name} refresh failed during shutdown (expected)`)); + logger.log(chalk.yellow(`remote ${remote.name} refresh failed during shutdown (expected)`)); return res.status(503).json({ error: 'Server is shutting down' }); } - logger.error(chalk.red(`Failed to refresh sessions for remote ${remote.name}:`), error); + logger.error(`failed to refresh sessions for remote ${remote.name}:`, error); res.status(500).json({ error: 'Failed to refresh sessions' }); } }); diff --git a/web/src/server/routes/sessions.ts b/web/src/server/routes/sessions.ts index ccaa9b0a..864e03b2 100644 --- a/web/src/server/routes/sessions.ts +++ b/web/src/server/routes/sessions.ts @@ -7,6 +7,7 @@ import { RemoteRegistry } from '../services/remote-registry.js'; import { ActivityMonitor } from '../services/activity-monitor.js'; import { cellsToText } from '../../shared/terminal-text-formatter.js'; import { createLogger } from '../utils/logger.js'; +import chalk from 'chalk'; import * as fs from 'fs'; import * as path from 'path'; import * as os from 'os'; @@ -47,12 +48,13 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // List all sessions (aggregate local + remote in HQ mode) router.get('/sessions', async (req, res) => { + logger.debug('listing all sessions'); try { let allSessions = []; // Get local sessions const localSessions = ptyManager.listSessions(); - logger.log(`Found ${localSessions.length} local sessions`); + logger.debug(`found ${localSessions.length} local sessions`); // Add source info to local sessions const localSessionsWithSource = localSessions.map((session) => ({ @@ -65,7 +67,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // If in HQ mode, aggregate sessions from all remotes if (isHQMode && remoteRegistry) { const remotes = remoteRegistry.getRemotes(); - logger.log(`HQ Mode: Checking ${remotes.length} remote servers for sessions`); + logger.debug(`checking ${remotes.length} remote servers for sessions`); // Fetch sessions from each remote in parallel const remotePromises = remotes.map(async (remote) => { @@ -79,7 +81,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { if (response.ok) { const remoteSessions = await response.json(); - logger.log(`Got ${remoteSessions.length} sessions from remote ${remote.name}`); + logger.debug(`got ${remoteSessions.length} sessions from remote ${remote.name}`); // Track session IDs for this remote const sessionIds = remoteSessions.map((s: Session) => s.id); @@ -94,28 +96,28 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { remoteUrl: remote.url, })); } else { - logger.error( - `Failed to get sessions from remote ${remote.name}: HTTP ${response.status}` + logger.warn( + `failed to get sessions from remote ${remote.name}: HTTP ${response.status}` ); return []; } } catch (error) { - logger.error(`Failed to get sessions from remote ${remote.name}:`, error); + logger.error(`failed to get sessions from remote ${remote.name}:`, error); return []; } }); const remoteResults = await Promise.all(remotePromises); const remoteSessions = remoteResults.flat(); - logger.log(`Total remote sessions: ${remoteSessions.length}`); + logger.debug(`total remote sessions: ${remoteSessions.length}`); allSessions = [...allSessions, ...remoteSessions]; } - logger.log(`Returning ${allSessions.length} total sessions`); + logger.debug(`returning ${allSessions.length} total sessions`); res.json(allSessions); } catch (error) { - logger.error('Error listing sessions:', error); + logger.error('error listing sessions:', error); res.status(500).json({ error: 'Failed to list sessions' }); } }); @@ -123,8 +125,12 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Create new session (local or on remote) router.post('/sessions', async (req, res) => { const { command, workingDir, name, remoteId, spawn_terminal } = req.body; + logger.debug( + `creating new session: command=${JSON.stringify(command)}, remoteId=${remoteId || 'local'}` + ); if (!command || !Array.isArray(command) || command.length === 0) { + logger.warn('session creation failed: invalid command array'); return res.status(400).json({ error: 'Command array is required' }); } @@ -133,12 +139,14 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { if (remoteId && isHQMode && remoteRegistry) { const remote = remoteRegistry.getRemote(remoteId); if (!remote) { + logger.warn(`session creation failed: remote ${remoteId} not found`); return res.status(404).json({ error: 'Remote server not found' }); } - logger.log(`Forwarding session creation to remote ${remote.name}`); + logger.log(chalk.blue(`forwarding session creation to remote ${remote.name}`)); // Forward the request to the remote server + const startTime = Date.now(); const response = await fetch(`${remote.url}/api/sessions`, { method: 'POST', headers: { @@ -161,6 +169,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { } const result = await response.json(); + logger.debug(`remote session creation took ${Date.now() - startTime}ms`); // Track the session in the remote's sessionIds if (result.sessionId) { @@ -180,7 +189,9 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { const sessionName = name || `session_${Date.now()}`; // Request Mac app to spawn terminal - logger.log(`Requesting terminal spawn with command: ${JSON.stringify(command)}`); + logger.log( + chalk.blue(`requesting terminal spawn with command: ${JSON.stringify(command)}`) + ); const spawnResult = await requestTerminalSpawn({ sessionId, sessionName, @@ -190,9 +201,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { if (!spawnResult.success) { if (spawnResult.error?.includes('ECONNREFUSED')) { - logger.log( - 'Terminal spawn requested but socket not available, falling back to normal spawn' - ); + logger.debug('terminal spawn socket not available, falling back to normal spawn'); } else { throw new Error(spawnResult.error || 'Failed to spawn terminal'); } @@ -201,11 +210,12 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { await new Promise((resolve) => setTimeout(resolve, 500)); // Return the session ID - client will poll for the session to appear + logger.log(chalk.green(`terminal spawn requested for session ${sessionId}`)); res.json({ sessionId, message: 'Terminal spawn requested' }); return; } } catch (error) { - logger.error('Error spawning terminal:', error); + logger.error('error spawning terminal:', error); res.status(500).json({ error: 'Failed to spawn terminal', details: error instanceof Error ? error.message : 'Unknown error', @@ -213,9 +223,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { return; } } else if (spawn_terminal && !fs.existsSync(socketPath)) { - logger.log( - 'Terminal spawn requested but socket not available, falling back to normal spawn' - ); + logger.debug('terminal spawn socket not available, falling back to normal spawn'); } // Create local session @@ -223,7 +231,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { name || `session_${Date.now()}_${Math.random().toString(36).substr(2, 9)}`; const cwd = resolvePath(workingDir, process.cwd()); - logger.log(`Creating session with PTY service: ${command.join(' ')} in ${cwd}`); + logger.log(chalk.blue(`creating session: ${command.join(' ')} in ${cwd}`)); const result = await ptyManager.createSession(command, { name: sessionName, @@ -231,13 +239,13 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { }); const { sessionId, sessionInfo } = result; - logger.log(`Session created: ${sessionId} (PID: ${sessionInfo.pid})`); + logger.log(chalk.green(`session ${sessionId} created (PID: ${sessionInfo.pid})`)); // Stream watcher is set up when clients connect to the stream endpoint res.json({ sessionId }); } catch (error) { - logger.error('Error creating session:', error); + logger.error('error creating session:', error); if (error instanceof PtyError) { res.status(500).json({ error: 'Failed to create session', details: error.message }); } else { @@ -248,6 +256,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Get activity status for all sessions router.get('/sessions/activity', async (req, res) => { + logger.debug('getting activity status for all sessions'); try { const activityStatus: Record = {}; @@ -281,7 +290,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { }; } } catch (error) { - logger.error(`Failed to get activity from remote ${remote.name}:`, error); + logger.error(`failed to get activity from remote ${remote.name}:`, error); } return null; }); @@ -299,7 +308,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { res.json(activityStatus); } catch (error) { - logger.error('Error getting activity status:', error); + logger.error('error getting activity status:', error); res.status(500).json({ error: 'Failed to get activity status' }); } }); @@ -328,7 +337,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { return res.json(await response.json()); } catch (error) { - logger.error(`Failed to get activity from remote ${remote.name}:`, error); + logger.error(`failed to get activity from remote ${remote.name}:`, error); return res.status(503).json({ error: 'Failed to reach remote server' }); } } @@ -341,7 +350,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { } res.json(activityStatus); } catch (error) { - logger.error(`Error getting activity status for session ${sessionId}:`, error); + logger.error(`error getting activity status for session ${sessionId}:`, error); res.status(500).json({ error: 'Failed to get activity status' }); } }); @@ -349,6 +358,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Get single session info router.get('/sessions/:sessionId', async (req, res) => { const sessionId = req.params.sessionId; + logger.debug(`getting info for session ${sessionId}`); try { // If in HQ mode, check if this is a remote session @@ -370,7 +380,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { return res.json(await response.json()); } catch (error) { - logger.error(`Failed to get session info from remote ${remote.name}:`, error); + logger.error(`failed to get session info from remote ${remote.name}:`, error); return res.status(503).json({ error: 'Failed to reach remote server' }); } } @@ -384,7 +394,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { } res.json(session); } catch (error) { - logger.error('Error getting session info:', error); + logger.error('error getting session info:', error); res.status(500).json({ error: 'Failed to get session info' }); } }); @@ -392,6 +402,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Kill session (just kill the process) router.delete('/sessions/:sessionId', async (req, res) => { const sessionId = req.params.sessionId; + logger.debug(`killing session ${sessionId}`); try { // If in HQ mode, check if this is a remote session @@ -414,11 +425,11 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Remote killed the session, now update our registry remoteRegistry.removeSessionFromRemote(sessionId); - logger.log(`Remote session ${sessionId} killed on ${remote.name}`); + logger.log(chalk.yellow(`remote session ${sessionId} killed on ${remote.name}`)); return res.json(await response.json()); } catch (error) { - logger.error(`Failed to kill session on remote ${remote.name}:`, error); + logger.error(`failed to kill session on remote ${remote.name}:`, error); return res.status(503).json({ error: 'Failed to reach remote server' }); } } @@ -432,11 +443,11 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { } await ptyManager.killSession(sessionId, 'SIGTERM'); - logger.log(`Local session ${sessionId} killed`); + logger.log(chalk.yellow(`local session ${sessionId} killed`)); res.json({ success: true, message: 'Session killed' }); } catch (error) { - logger.error('Error killing session:', error); + logger.error('error killing session:', error); if (error instanceof PtyError) { res.status(500).json({ error: 'Failed to kill session', details: error.message }); } else { @@ -448,6 +459,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Cleanup session files router.delete('/sessions/:sessionId/cleanup', async (req, res) => { const sessionId = req.params.sessionId; + logger.debug(`cleaning up session ${sessionId} files`); try { // If in HQ mode, check if this is a remote session @@ -470,11 +482,11 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Remote cleaned up the session, now update our registry remoteRegistry.removeSessionFromRemote(sessionId); - logger.log(`Remote session ${sessionId} cleaned up on ${remote.name}`); + logger.log(chalk.yellow(`remote session ${sessionId} cleaned up on ${remote.name}`)); return res.json(await response.json()); } catch (error) { - logger.error(`Failed to cleanup session on remote ${remote.name}:`, error); + logger.error(`failed to cleanup session on remote ${remote.name}:`, error); return res.status(503).json({ error: 'Failed to reach remote server' }); } } @@ -482,11 +494,11 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Local session handling - just cleanup, no registry updates needed ptyManager.cleanupSession(sessionId); - logger.log(`Local session ${sessionId} cleaned up`); + logger.log(chalk.yellow(`local session ${sessionId} cleaned up`)); res.json({ success: true, message: 'Session cleaned up' }); } catch (error) { - logger.error('Error cleaning up session:', error); + logger.error('error cleaning up session:', error); if (error instanceof PtyError) { res.status(500).json({ error: 'Failed to cleanup session', details: error.message }); } else { @@ -497,10 +509,11 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Cleanup all exited sessions (local and remote) router.post('/cleanup-exited', async (req, res) => { + logger.log(chalk.blue('cleaning up all exited sessions')); try { // Clean up local sessions const localCleanedSessions = ptyManager.cleanupExitedSessions(); - logger.log(`Cleaned up ${localCleanedSessions.length} local exited sessions`); + logger.log(chalk.green(`cleaned up ${localCleanedSessions.length} local exited sessions`)); // Remove cleaned local sessions from remote registry if in HQ mode if (isHQMode && remoteRegistry) { @@ -544,7 +557,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { throw new Error(`HTTP ${response.status}`); } } catch (error) { - logger.error(`Failed to cleanup sessions on remote ${remote.name}:`, error); + logger.error(`failed to cleanup sessions on remote ${remote.name}:`, error); remoteResults.push({ remoteName: remote.name, cleaned: 0, @@ -563,7 +576,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { remoteResults, }); } catch (error) { - logger.error('Error cleaning up exited sessions:', error); + logger.error('error cleaning up exited sessions:', error); if (error instanceof PtyError) { res .status(500) @@ -578,6 +591,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { router.get('/sessions/:sessionId/text', async (req, res) => { const sessionId = req.params.sessionId; const includeStyles = req.query.styles !== undefined; + logger.debug(`getting plain text for session ${sessionId}, styles=${includeStyles}`); try { // If in HQ mode, check if this is a remote session @@ -607,7 +621,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { res.setHeader('Content-Type', 'text/plain'); return res.send(text); } catch (error) { - logger.error(`Failed to get text from remote ${remote.name}:`, error); + logger.error(`failed to get text from remote ${remote.name}:`, error); return res.status(503).json({ error: 'Failed to reach remote server' }); } } @@ -629,7 +643,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { res.setHeader('Content-Type', 'text/plain'); res.send(plainText); } catch (error) { - logger.error('Error getting plain text:', error); + logger.error('error getting plain text:', error); res.status(500).json({ error: 'Failed to get terminal text' }); } }); @@ -638,7 +652,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { router.get('/sessions/:sessionId/buffer', async (req, res) => { const sessionId = req.params.sessionId; - logger.debug(`[BUFFER] Client requesting buffer for session ${sessionId}`); + logger.debug(`client requesting buffer for session ${sessionId}`); try { // If in HQ mode, check if this is a remote session @@ -663,7 +677,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { res.setHeader('Content-Type', 'application/octet-stream'); return res.send(Buffer.from(buffer)); } catch (error) { - logger.error(`Failed to get buffer from remote ${remote.name}:`, error); + logger.error(`failed to get buffer from remote ${remote.name}:`, error); return res.status(503).json({ error: 'Failed to reach remote server' }); } } @@ -672,7 +686,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Local session handling const session = ptyManager.getSession(sessionId); if (!session) { - logger.error(`[BUFFER] Session ${sessionId} not found`); + logger.error(`session ${sessionId} not found`); return res.status(404).json({ error: 'Session not found' }); } @@ -683,7 +697,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { const buffer = terminalManager.encodeSnapshot(snapshot); logger.debug( - `[BUFFER] Sending buffer for session ${sessionId}: ${buffer.length} bytes, ` + + `sending buffer for session ${sessionId}: ${buffer.length} bytes, ` + `dimensions: ${snapshot.cols}x${snapshot.rows}, cursor: (${snapshot.cursorX},${snapshot.cursorY})` ); @@ -691,7 +705,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { res.setHeader('Content-Type', 'application/octet-stream'); res.send(buffer); } catch (error) { - logger.error('[BUFFER] Error getting buffer:', error); + logger.error('error getting buffer:', error); res.status(500).json({ error: 'Failed to get terminal buffer' }); } }); @@ -699,9 +713,12 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Stream session output router.get('/sessions/:sessionId/stream', async (req, res) => { const sessionId = req.params.sessionId; + const startTime = Date.now(); logger.log( - `[STREAM] New SSE client connected to session ${sessionId} from ${req.get('User-Agent')?.substring(0, 50) || 'unknown'}` + chalk.blue( + `new SSE client connected to session ${sessionId} from ${req.get('User-Agent')?.substring(0, 50) || 'unknown'}` + ) ); // If in HQ mode, check if this is a remote session @@ -740,16 +757,18 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { } const decoder = new TextDecoder(); + const bytesProxied = { count: 0 }; const pump = async () => { try { while (true) { const { done, value } = await reader.read(); if (done) break; + bytesProxied.count += value.length; const chunk = decoder.decode(value, { stream: true }); res.write(chunk); } } catch (error) { - logger.error(`Stream proxy error for remote ${remote.name}:`, error); + logger.error(`stream proxy error for remote ${remote.name}:`, error); } }; @@ -757,13 +776,17 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Clean up on disconnect req.on('close', () => { - logger.log(`[STREAM] SSE client disconnected from remote session ${sessionId}`); + logger.log( + chalk.yellow( + `SSE client disconnected from remote session ${sessionId} (proxied ${bytesProxied.count} bytes)` + ) + ); controller.abort(); }); return; } catch (error) { - logger.error(`Failed to stream from remote ${remote.name}:`, error); + logger.error(`failed to stream from remote ${remote.name}:`, error); return res.status(503).json({ error: 'Failed to reach remote server' }); } } @@ -782,6 +805,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { const streamPath = sessionPaths.stdoutPath; if (!streamPath || !fs.existsSync(streamPath)) { + logger.warn(`stream path not found for session ${sessionId}`); return res.status(404).json({ error: 'Session stream not found' }); } @@ -806,6 +830,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Add client to stream watcher streamWatcher.addClient(sessionId, streamPath, res); + logger.debug(`SSE stream setup completed in ${Date.now() - startTime}ms`); // Send heartbeat every 30 seconds to keep connection alive const heartbeat = setInterval(() => { @@ -816,7 +841,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Clean up on disconnect req.on('close', () => { - logger.log(`[STREAM] SSE client disconnected from session ${sessionId}`); + logger.log(chalk.yellow(`SSE client disconnected from session ${sessionId}`)); streamWatcher.removeClient(sessionId, res); clearInterval(heartbeat); }); @@ -829,14 +854,19 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Validate that only one of text or key is provided if ((text === undefined && key === undefined) || (text !== undefined && key !== undefined)) { + logger.warn( + `invalid input request for session ${sessionId}: both or neither text/key provided` + ); return res.status(400).json({ error: 'Either text or key must be provided, but not both' }); } if (text !== undefined && typeof text !== 'string') { + logger.warn(`invalid input request for session ${sessionId}: text is not a string`); return res.status(400).json({ error: 'Text must be a string' }); } if (key !== undefined && typeof key !== 'string') { + logger.warn(`invalid input request for session ${sessionId}: key is not a string`); return res.status(400).json({ error: 'Key must be a string' }); } @@ -863,7 +893,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { return res.json(await response.json()); } catch (error) { - logger.error(`Failed to send input to remote ${remote.name}:`, error); + logger.error(`failed to send input to remote ${remote.name}:`, error); return res.status(503).json({ error: 'Failed to reach remote server' }); } } @@ -872,22 +902,22 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Local session handling const session = ptyManager.getSession(sessionId); if (!session) { - logger.error(`Session ${sessionId} not found for input`); + logger.error(`session ${sessionId} not found for input`); return res.status(404).json({ error: 'Session not found' }); } if (session.status !== 'running') { - logger.error(`Session ${sessionId} is not running (status: ${session.status})`); + logger.error(`session ${sessionId} is not running (status: ${session.status})`); return res.status(400).json({ error: 'Session is not running' }); } const inputData = text !== undefined ? { text } : { key }; - logger.debug(`Sending input to session ${sessionId}: ${JSON.stringify(inputData)}`); + logger.debug(`sending input to session ${sessionId}: ${JSON.stringify(inputData)}`); ptyManager.sendInput(sessionId, inputData); res.json({ success: true }); } catch (error) { - logger.error('Error sending input:', error); + logger.error('error sending input:', error); if (error instanceof PtyError) { res.status(500).json({ error: 'Failed to send input', details: error.message }); } else { @@ -902,14 +932,18 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { const { cols, rows } = req.body; if (typeof cols !== 'number' || typeof rows !== 'number') { + logger.warn(`invalid resize request for session ${sessionId}: cols/rows not numbers`); return res.status(400).json({ error: 'Cols and rows must be numbers' }); } if (cols < 1 || rows < 1 || cols > 1000 || rows > 1000) { + logger.warn( + `invalid resize request for session ${sessionId}: cols=${cols}, rows=${rows} out of range` + ); return res.status(400).json({ error: 'Cols and rows must be between 1 and 1000' }); } - logger.log(`Resizing session ${sessionId} to ${cols}x${rows}`); + logger.log(chalk.blue(`resizing session ${sessionId} to ${cols}x${rows}`)); try { // If in HQ mode, check if this is a remote session @@ -934,7 +968,7 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { return res.json(await response.json()); } catch (error) { - logger.error(`Failed to resize session on remote ${remote.name}:`, error); + logger.error(`failed to resize session on remote ${remote.name}:`, error); return res.status(503).json({ error: 'Failed to reach remote server' }); } } @@ -943,22 +977,22 @@ export function createSessionRoutes(config: SessionRoutesConfig): Router { // Local session handling const session = ptyManager.getSession(sessionId); if (!session) { - logger.error(`Session ${sessionId} not found for resize`); + logger.warn(`session ${sessionId} not found for resize`); return res.status(404).json({ error: 'Session not found' }); } if (session.status !== 'running') { - logger.error(`Session ${sessionId} is not running (status: ${session.status})`); + logger.warn(`session ${sessionId} is not running (status: ${session.status})`); return res.status(400).json({ error: 'Session is not running' }); } // Resize the session ptyManager.resizeSession(sessionId, cols, rows); - logger.log(`Successfully resized session ${sessionId} to ${cols}x${rows}`); + logger.log(chalk.green(`session ${sessionId} resized to ${cols}x${rows}`)); res.json({ success: true, cols, rows }); } catch (error) { - logger.error('Error resizing session via PTY service:', error); + logger.error('error resizing session via PTY service:', error); if (error instanceof PtyError) { res.status(500).json({ error: 'Failed to resize session', details: error.message }); } else { @@ -1019,24 +1053,24 @@ async function requestTerminalSpawn(params: { return new Promise((resolve) => { const client = net.createConnection(socketPath, () => { - logger.log(`Connected to terminal spawn service for session ${params.sessionId}`); + logger.debug(`connected to terminal spawn service for session ${params.sessionId}`); client.write(JSON.stringify(spawnRequest)); }); client.on('data', (data) => { try { const response = JSON.parse(data.toString()); - logger.log(`Terminal spawn response:`, response); + logger.debug('terminal spawn response:', response); resolve({ success: response.success, error: response.error }); } catch (error) { - logger.error('Failed to parse terminal spawn response:', error); + logger.error('failed to parse terminal spawn response:', error); resolve({ success: false, error: 'Invalid response from terminal spawn service' }); } client.end(); }); client.on('error', (error) => { - logger.error('Failed to connect to terminal spawn service:', error); + logger.error('failed to connect to terminal spawn service:', error); resolve({ success: false, error: `Connection failed: ${error.message}`, @@ -1049,5 +1083,6 @@ async function requestTerminalSpawn(params: { }); client.setTimeout(5000); // 5 second timeout + logger.debug(`requesting terminal spawn from Mac app for session ${params.sessionId}`); }); } diff --git a/web/src/server/server.ts b/web/src/server/server.ts index 14bbd113..a83f7bb8 100644 --- a/web/src/server/server.ts +++ b/web/src/server/server.ts @@ -156,7 +156,7 @@ function parseArgs(): Config { config.debug = true; } else if (args[i].startsWith('--')) { // Unknown argument - logger.error(chalk.red(`ERROR: Unknown argument: ${args[i]}`)); + logger.error(`Unknown argument: ${args[i]}`); logger.error('Use --help to see available options'); process.exit(1); } @@ -180,9 +180,7 @@ function validateConfig(config: ReturnType) { (config.basicAuthUsername && !config.basicAuthPassword) || (!config.basicAuthUsername && config.basicAuthPassword) ) { - logger.error( - chalk.red('ERROR: Both username and password must be provided for authentication') - ); + logger.error('Both username and password must be provided for authentication'); logger.error( 'Use --username and --password, or set both VIBETUNNEL_USERNAME and VIBETUNNEL_PASSWORD' ); @@ -191,21 +189,21 @@ function validateConfig(config: ReturnType) { // Validate HQ registration configuration if (config.hqUrl && (!config.hqUsername || !config.hqPassword)) { - logger.error(chalk.red('ERROR: HQ username and password required when --hq-url is specified')); + logger.error('HQ username and password required when --hq-url is specified'); logger.error('Use --hq-username and --hq-password with --hq-url'); process.exit(1); } // Validate remote name is provided when registering with HQ if (config.hqUrl && !config.remoteName) { - logger.error(chalk.red('ERROR: Remote name required when --hq-url is specified')); + logger.error('Remote name required when --hq-url is specified'); logger.error('Use --name to specify a unique name for this remote server'); process.exit(1); } // Validate HQ URL is HTTPS unless explicitly allowed if (config.hqUrl && !config.hqUrl.startsWith('https://') && !config.allowInsecureHQ) { - logger.error(chalk.red('ERROR: HQ URL must use HTTPS protocol')); + logger.error('HQ URL must use HTTPS protocol'); logger.error('Use --allow-insecure-hq to allow HTTP for testing'); process.exit(1); } @@ -215,26 +213,22 @@ function validateConfig(config: ReturnType) { (config.hqUrl || config.hqUsername || config.hqPassword) && (!config.hqUrl || !config.hqUsername || !config.hqPassword) ) { - logger.error( - chalk.red('ERROR: All HQ parameters required: --hq-url, --hq-username, --hq-password') - ); + logger.error('All HQ parameters required: --hq-url, --hq-username, --hq-password'); process.exit(1); } // Can't be both HQ mode and register with HQ if (config.isHQMode && config.hqUrl) { - logger.error(chalk.red('ERROR: Cannot use --hq and --hq-url together')); + logger.error('Cannot use --hq and --hq-url together'); logger.error('Use --hq to run as HQ server, or --hq-url to register with an HQ'); process.exit(1); } // If not HQ mode and no HQ URL, warn about authentication if (!config.basicAuthUsername && !config.basicAuthPassword && !config.isHQMode && !config.hqUrl) { - logger.warn(chalk.red('WARNING: No authentication configured!')); + logger.warn('No authentication configured'); logger.warn( - chalk.yellow( - 'Set VIBETUNNEL_USERNAME and VIBETUNNEL_PASSWORD or use --username and --password flags.' - ) + 'Set VIBETUNNEL_USERNAME and VIBETUNNEL_PASSWORD or use --username and --password flags' ); } } @@ -261,7 +255,7 @@ let appCreated = false; export function createApp(): AppInstance { // Prevent multiple app instances if (appCreated) { - logger.error(chalk.red('ERROR: App already created, preventing duplicate instance')); + logger.error('App already created, preventing duplicate instance'); throw new Error('Duplicate app creation detected'); } appCreated = true; @@ -289,13 +283,14 @@ export function createApp(): AppInstance { validateConfig(config); - logger.log('Creating Express app and HTTP server...'); + logger.log('Initializing VibeTunnel server components'); const app = express(); const server = createServer(app); const wss = new WebSocketServer({ server }); // Add JSON body parser middleware app.use(express.json()); + logger.debug('Configured express middleware'); // Control directory for session data const CONTROL_DIR = @@ -305,19 +300,25 @@ export function createApp(): AppInstance { if (!fs.existsSync(CONTROL_DIR)) { fs.mkdirSync(CONTROL_DIR, { recursive: true }); logger.log(chalk.green(`Created control directory: ${CONTROL_DIR}`)); + } else { + logger.debug(`Using existing control directory: ${CONTROL_DIR}`); } // Initialize PTY manager const ptyManager = new PtyManager(CONTROL_DIR); + logger.debug('Initialized PTY manager'); // Initialize Terminal Manager for server-side terminal state const terminalManager = new TerminalManager(CONTROL_DIR); + logger.debug('Initialized terminal manager'); // Initialize stream watcher for file-based streaming const streamWatcher = new StreamWatcher(); + logger.debug('Initialized stream watcher'); // Initialize activity monitor const activityMonitor = new ActivityMonitor(CONTROL_DIR); + logger.debug('Initialized activity monitor'); // Initialize HQ components let remoteRegistry: RemoteRegistry | null = null; @@ -329,9 +330,11 @@ export function createApp(): AppInstance { if (config.isHQMode) { remoteRegistry = new RemoteRegistry(); logger.log(chalk.green('Running in HQ mode')); + logger.debug('Initialized remote registry for HQ mode'); } else if (config.hqUrl && config.hqUsername && config.hqPassword && config.remoteName) { // Generate bearer token for this remote server remoteBearerToken = uuidv4(); + logger.debug(`Generated bearer token for remote server: ${config.remoteName}`); } // Initialize buffer aggregator @@ -340,6 +343,7 @@ export function createApp(): AppInstance { remoteRegistry, isHQMode: config.isHQMode, }); + logger.debug('Initialized buffer aggregator'); // Set up authentication const authMiddleware = createAuthMiddleware({ @@ -351,10 +355,12 @@ export function createApp(): AppInstance { // Apply auth middleware to all API routes app.use('/api', authMiddleware); + logger.debug('Applied authentication middleware to /api routes'); // Serve static files const publicPath = path.join(process.cwd(), 'public'); app.use(express.static(publicPath)); + logger.debug(`Serving static files from: ${publicPath}`); // Health check endpoint (no auth required) app.get('/api/health', (req, res) => { @@ -382,6 +388,7 @@ export function createApp(): AppInstance { activityMonitor, }) ); + logger.debug('Mounted session routes'); app.use( '/api', @@ -390,16 +397,18 @@ export function createApp(): AppInstance { isHQMode: config.isHQMode, }) ); + logger.debug('Mounted remote routes'); // Mount filesystem routes app.use('/api', createFilesystemRoutes()); + logger.debug('Mounted filesystem routes'); // WebSocket endpoint for buffer updates wss.on('connection', (ws, _req) => { if (bufferAggregator) { bufferAggregator.handleClientConnection(ws); } else { - logger.error(chalk.red('[WS] BufferAggregator not initialized')); + logger.error('BufferAggregator not initialized for WebSocket connection'); ws.close(); } }); @@ -426,7 +435,7 @@ export function createApp(): AppInstance { const startServer = () => { const requestedPort = config.port !== null ? config.port : Number(process.env.PORT) || 4020; - logger.log(`Attempting to start server on port ${requestedPort}`); + logger.log(`Starting server on port ${requestedPort}`); // Remove all existing error listeners first to prevent duplicates server.removeAllListeners('error'); @@ -434,15 +443,13 @@ export function createApp(): AppInstance { // Add error handler for port already in use server.on('error', (error: NodeJS.ErrnoException) => { if (error.code === 'EADDRINUSE') { - logger.error(chalk.red(`Error: Port ${requestedPort} is already in use`)); + logger.error(`Port ${requestedPort} is already in use`); logger.error( - chalk.yellow( - 'Please use a different port with --port or stop the existing server' - ) + 'Please use a different port with --port or stop the existing server' ); process.exit(9); // Exit with code 9 to indicate port conflict } else { - logger.error(chalk.red('Server error:'), error); + logger.error('Server error:', error); process.exit(1); } }); @@ -458,11 +465,9 @@ export function createApp(): AppInstance { logger.log(`Username: ${config.basicAuthUsername}`); logger.log(`Password: ${'*'.repeat(config.basicAuthPassword.length)}`); } else { - logger.warn(chalk.red('⚠️ WARNING: Server running without authentication!')); + logger.warn('Server running without authentication'); logger.warn( - chalk.yellow( - 'Anyone can access this server. Use --username and --password or set VIBETUNNEL_USERNAME and VIBETUNNEL_PASSWORD.' - ) + 'Anyone can access this server. Use --username and --password or set VIBETUNNEL_USERNAME and VIBETUNNEL_PASSWORD' ); } @@ -477,8 +482,10 @@ export function createApp(): AppInstance { remoteUrl, remoteBearerToken || '' ); - logger.log(chalk.green('Remote mode: Will accept Bearer token for HQ access')); - logger.log(`Token: ${hqClient.getToken()}`); + logger.log( + chalk.green(`Remote mode: ${config.remoteName} will accept Bearer token for HQ access`) + ); + logger.debug(`Bearer token: ${hqClient.getToken()}`); } // Send message to parent process if running as child (for testing) @@ -489,6 +496,7 @@ export function createApp(): AppInstance { // Register with HQ if configured if (hqClient) { + logger.log(`Registering with HQ at ${config.hqUrl}`); hqClient.register().catch((err) => { logger.error('Failed to register with HQ:', err); }); @@ -503,9 +511,11 @@ export function createApp(): AppInstance { ptyManager, }); controlDirWatcher.start(); + logger.debug('Started control directory watcher'); // Start activity monitor activityMonitor.start(); + logger.debug('Started activity monitor'); }); }; @@ -536,13 +546,13 @@ export function startVibeTunnelServer() { // Prevent multiple server instances if (serverStarted) { - logger.error(chalk.red('ERROR: Server already started, preventing duplicate instance')); + logger.error('Server already started, preventing duplicate instance'); logger.error('This should not happen - duplicate server startup detected'); process.exit(1); } serverStarted = true; - logger.log('Creating app instance...'); + logger.debug('Creating VibeTunnel application instance'); // Create and configure the app const appInstance = createApp(); const { @@ -559,26 +569,26 @@ export function startVibeTunnelServer() { // Update debug mode based on config if (config.debug) { setDebugMode(true); - logger.log('Debug logging enabled'); + logger.log(chalk.gray('Debug logging enabled')); } - logger.log('Starting server...'); startServer(); // Cleanup old terminals every 5 minutes - setInterval( + const _cleanupInterval = setInterval( () => { terminalManager.cleanup(5 * 60 * 1000); // 5 minutes }, 5 * 60 * 1000 ); + logger.debug('Started terminal cleanup interval (5 minutes)'); // Graceful shutdown let localShuttingDown = false; const shutdown = async () => { if (localShuttingDown) { - logger.warn(chalk.red('Force exit...')); + logger.warn('Force exit...'); process.exit(1); } @@ -589,17 +599,21 @@ export function startVibeTunnelServer() { try { // Stop activity monitor activityMonitor.stop(); + logger.debug('Stopped activity monitor'); // Stop control directory watcher if (controlDirWatcher) { controlDirWatcher.stop(); + logger.debug('Stopped control directory watcher'); } if (hqClient) { + logger.debug('Destroying HQ client connection'); await hqClient.destroy(); } if (remoteRegistry) { + logger.debug('Destroying remote registry'); remoteRegistry.destroy(); } @@ -611,12 +625,12 @@ export function startVibeTunnelServer() { // Force exit after 5 seconds if graceful shutdown fails setTimeout(() => { - logger.warn(chalk.red('Graceful shutdown timeout, forcing exit...')); + logger.warn('Graceful shutdown timeout, forcing exit...'); closeLogger(); process.exit(1); }, 5000); } catch (error) { - logger.error(chalk.red('Error during shutdown:'), error); + logger.error('Error during shutdown:', error); closeLogger(); process.exit(1); } @@ -624,6 +638,7 @@ export function startVibeTunnelServer() { process.on('SIGINT', shutdown); process.on('SIGTERM', shutdown); + logger.debug('Registered signal handlers for graceful shutdown'); } // Export for testing diff --git a/web/src/server/services/activity-monitor.ts b/web/src/server/services/activity-monitor.ts index 6b9635fc..40273531 100644 --- a/web/src/server/services/activity-monitor.ts +++ b/web/src/server/services/activity-monitor.ts @@ -2,6 +2,7 @@ import * as fs from 'fs'; import * as path from 'path'; import type { SessionActivity } from '../../shared/types.js'; import { createLogger } from '../utils/logger.js'; +import chalk from 'chalk'; const logger = createLogger('activity-monitor'); @@ -28,10 +29,13 @@ export class ActivityMonitor { * Start monitoring all sessions for activity */ start() { - logger.log('Starting activity monitoring'); + logger.log(chalk.green('activity monitor started')); // Initial scan of existing sessions - this.scanSessions(); + const sessionCount = this.scanSessions(); + if (sessionCount > 0) { + logger.log(chalk.blue(`monitoring ${sessionCount} existing sessions`)); + } // Set up periodic scanning for new sessions this.checkInterval = setInterval(() => { @@ -44,7 +48,7 @@ export class ActivityMonitor { * Stop monitoring */ stop() { - logger.log('Stopping activity monitoring'); + logger.log(chalk.yellow('stopping activity monitor')); if (this.checkInterval) { clearInterval(this.checkInterval); @@ -52,24 +56,30 @@ export class ActivityMonitor { } // Close all watchers + const watcherCount = this.watchers.size; for (const [sessionId, watcher] of this.watchers) { watcher.close(); this.watchers.delete(sessionId); } this.activities.clear(); + + if (watcherCount > 0) { + logger.log(chalk.gray(`closed ${watcherCount} file watchers`)); + } } /** * Scan for sessions and start monitoring new ones */ - private scanSessions() { + private scanSessions(): number { try { if (!fs.existsSync(this.controlPath)) { - return; + return 0; } const entries = fs.readdirSync(this.controlPath, { withFileTypes: true }); + let newSessions = 0; for (const entry of entries) { if (entry.isDirectory()) { @@ -84,27 +94,40 @@ export class ActivityMonitor { // Check if stdout exists if (fs.existsSync(streamOutPath)) { - this.startMonitoringSession(sessionId, streamOutPath); + if (this.startMonitoringSession(sessionId, streamOutPath)) { + newSessions++; + } } } } // Clean up sessions that no longer exist + const sessionsToCleanup = []; for (const [sessionId, _] of this.activities) { const sessionDir = path.join(this.controlPath, sessionId); if (!fs.existsSync(sessionDir)) { + sessionsToCleanup.push(sessionId); + } + } + + if (sessionsToCleanup.length > 0) { + logger.log(chalk.yellow(`cleaning up ${sessionsToCleanup.length} removed sessions`)); + for (const sessionId of sessionsToCleanup) { this.stopMonitoringSession(sessionId); } } + + return newSessions; } catch (error) { - logger.error('Error scanning sessions:', error); + logger.error('failed to scan sessions:', error); + return 0; } } /** * Start monitoring a specific session */ - private startMonitoringSession(sessionId: string, streamOutPath: string) { + private startMonitoringSession(sessionId: string, streamOutPath: string): boolean { try { const stats = fs.statSync(streamOutPath); @@ -124,9 +147,11 @@ export class ActivityMonitor { }); this.watchers.set(sessionId, watcher); - logger.debug(`Started monitoring session ${sessionId}`); + logger.debug(`started monitoring session ${sessionId}`); + return true; } catch (error) { - logger.error(`Error starting monitor for session ${sessionId}:`, error); + logger.error(`failed to start monitor for session ${sessionId}:`, error); + return false; } } @@ -141,7 +166,7 @@ export class ActivityMonitor { } this.activities.delete(sessionId); - logger.debug(`Stopped monitoring session ${sessionId}`); + logger.debug(`stopped monitoring session ${sessionId}`); } /** @@ -156,15 +181,21 @@ export class ActivityMonitor { // Check if file size increased (new output) if (stats.size > activity.lastFileSize) { + const wasActive = activity.isActive; activity.isActive = true; activity.lastActivityTime = Date.now(); activity.lastFileSize = stats.size; + // Log state transition + if (!wasActive) { + logger.debug(`session ${sessionId} became active`); + } + // Write activity status immediately this.writeActivityStatus(sessionId, true); } } catch (error) { - logger.error(`Error handling file change for session ${sessionId}:`, error); + logger.error(`failed to handle file change for session ${sessionId}:`, error); } } @@ -177,6 +208,7 @@ export class ActivityMonitor { for (const [sessionId, activity] of this.activities) { if (activity.isActive && now - activity.lastActivityTime > this.ACTIVITY_TIMEOUT) { activity.isActive = false; + logger.debug(`session ${sessionId} became inactive`); this.writeActivityStatus(sessionId, false); } } @@ -202,12 +234,13 @@ export class ActivityMonitor { activityData.session = sessionData; } catch (_error) { // If we can't read session.json, just proceed without session data + logger.debug(`could not read session.json for ${sessionId}`); } } fs.writeFileSync(activityPath, JSON.stringify(activityData, null, 2)); } catch (error) { - logger.error(`Error writing activity status for session ${sessionId}:`, error); + logger.error(`failed to write activity status for session ${sessionId}:`, error); } } @@ -216,6 +249,7 @@ export class ActivityMonitor { */ getActivityStatus(): Record { const status: Record = {}; + const startTime = Date.now(); // Read from disk to get the most up-to-date status try { @@ -237,6 +271,7 @@ export class ActivityMonitor { status[sessionId] = data; } catch (_error) { // If we can't read the file, create one from current state + logger.debug(`could not read activity.json for ${sessionId}`); const activity = this.activities.get(sessionId); if (activity) { const activityStatus: SessionActivity = { @@ -251,6 +286,9 @@ export class ActivityMonitor { activityStatus.session = sessionData; } catch (_error) { // Ignore session.json read errors + logger.debug( + `could not read session.json for ${sessionId} when creating activity` + ); } } @@ -268,12 +306,20 @@ export class ActivityMonitor { }; } catch (_error) { // Ignore errors + logger.debug(`could not read session.json for ${sessionId}`); } } } } + + const duration = Date.now() - startTime; + if (duration > 100) { + logger.warn( + `activity status scan took ${duration}ms for ${Object.keys(status).length} sessions` + ); + } } catch (error) { - logger.error('Error reading activity status:', error); + logger.error('failed to read activity status:', error); } return status; @@ -294,6 +340,9 @@ export class ActivityMonitor { } } catch (_error) { // Fall back to creating from current state + logger.debug( + `could not read activity.json for session ${sessionId}, creating from current state` + ); const activity = this.activities.get(sessionId); if (activity) { const activityStatus: SessionActivity = { @@ -308,6 +357,9 @@ export class ActivityMonitor { activityStatus.session = sessionData; } catch (_error) { // Ignore session.json read errors + logger.debug( + `could not read session.json for ${sessionId} in getSessionActivityStatus` + ); } } @@ -326,6 +378,7 @@ export class ActivityMonitor { }; } catch (_error) { // Ignore errors + logger.debug(`could not read session.json for ${sessionId} when creating default activity`); } } diff --git a/web/src/server/services/buffer-aggregator.ts b/web/src/server/services/buffer-aggregator.ts index 8f803f8b..122a6289 100644 --- a/web/src/server/services/buffer-aggregator.ts +++ b/web/src/server/services/buffer-aggregator.ts @@ -26,6 +26,7 @@ export class BufferAggregator { constructor(config: BufferAggregatorConfig) { this.config = config; + logger.log(`BufferAggregator initialized (HQ mode: ${config.isHQMode})`); } /** @@ -33,12 +34,15 @@ export class BufferAggregator { */ async handleClientConnection(ws: WebSocket): Promise { logger.log(chalk.blue('New client connected')); + const clientId = `client-${Date.now()}`; + logger.debug(`Assigned client ID: ${clientId}`); // Initialize subscription map for this client this.clientSubscriptions.set(ws, new Map()); // Send welcome message ws.send(JSON.stringify({ type: 'connected', version: '1.0' })); + logger.debug('Sent welcome message to client'); // Handle messages from client ws.on('message', async (message: Buffer) => { @@ -62,7 +66,7 @@ export class BufferAggregator { }); ws.on('error', (error) => { - logger.error(chalk.red('Client WebSocket error:'), error); + logger.error('Client WebSocket error:', error); }); } @@ -96,21 +100,23 @@ export class BufferAggregator { if (isRemoteSession) { // Subscribe to remote session + logger.debug(`Subscribing to remote session ${sessionId} on remote ${isRemoteSession.id}`); await this.subscribeToRemoteSession(clientWs, sessionId, isRemoteSession.id); } else { // Subscribe to local session + logger.debug(`Subscribing to local session ${sessionId}`); await this.subscribeToLocalSession(clientWs, sessionId); } clientWs.send(JSON.stringify({ type: 'subscribed', sessionId })); - logger.debug(`Client subscribed to session ${sessionId}`); + logger.log(chalk.green(`Client subscribed to session ${sessionId}`)); } else if (data.type === 'unsubscribe' && data.sessionId) { const sessionId = data.sessionId; const unsubscribe = subscriptions.get(sessionId); if (unsubscribe) { unsubscribe(); subscriptions.delete(sessionId); - logger.debug(`Client unsubscribed from session ${sessionId}`); + logger.log(chalk.yellow(`Client unsubscribed from session ${sessionId}`)); } // Also unsubscribe from remote if applicable @@ -122,6 +128,13 @@ export class BufferAggregator { remoteConn.subscriptions.delete(sessionId); if (remoteConn.ws.readyState === WebSocket.OPEN) { remoteConn.ws.send(JSON.stringify({ type: 'unsubscribe', sessionId })); + logger.debug( + `Sent unsubscribe request to remote ${remoteConn.remoteName} for session ${sessionId}` + ); + } else { + logger.debug( + `Cannot unsubscribe from remote ${remoteConn.remoteName} - WebSocket not open` + ); } } } @@ -162,6 +175,8 @@ export class BufferAggregator { if (clientWs.readyState === WebSocket.OPEN) { clientWs.send(fullBuffer); + } else { + logger.debug(`Skipping buffer update - client WebSocket not open`); } } catch (error) { logger.error('Error encoding buffer update:', error); @@ -170,8 +185,10 @@ export class BufferAggregator { ); subscriptions.set(sessionId, unsubscribe); + logger.debug(`Created subscription for local session ${sessionId}`); // Send initial buffer + logger.debug(`Sending initial buffer for session ${sessionId}`); const initialSnapshot = await this.config.terminalManager.getBufferSnapshot(sessionId); const buffer = this.config.terminalManager.encodeSnapshot(initialSnapshot); @@ -193,6 +210,9 @@ export class BufferAggregator { if (clientWs.readyState === WebSocket.OPEN) { clientWs.send(fullBuffer); + logger.debug(`Sent initial buffer (${fullBuffer.length} bytes) for session ${sessionId}`); + } else { + logger.warn(`Cannot send initial buffer - client WebSocket not open`); } } catch (error) { logger.error(`Error subscribing to local session ${sessionId}:`, error); @@ -211,9 +231,11 @@ export class BufferAggregator { // Ensure we have a connection to this remote let remoteConn = this.remoteConnections.get(remoteId); if (!remoteConn || remoteConn.ws.readyState !== WebSocket.OPEN) { + logger.debug(`No active connection to remote ${remoteId}, establishing new connection`); // Need to connect to remote const connected = await this.connectToRemote(remoteId); if (!connected) { + logger.warn(`Failed to connect to remote ${remoteId} for session ${sessionId}`); clientWs.send( JSON.stringify({ type: 'error', message: 'Failed to connect to remote server' }) ); @@ -227,6 +249,9 @@ export class BufferAggregator { // Subscribe to the session on the remote remoteConn.subscriptions.add(sessionId); remoteConn.ws.send(JSON.stringify({ type: 'subscribe', sessionId })); + logger.debug( + `Sent subscription request to remote ${remoteConn.remoteName} for session ${sessionId}` + ); // Store an unsubscribe function for the client const subscriptions = this.clientSubscriptions.get(clientWs); @@ -241,10 +266,18 @@ export class BufferAggregator { * Connect to a remote server's WebSocket */ private async connectToRemote(remoteId: string): Promise { - if (!this.config.remoteRegistry) return false; + logger.log(`Connecting to remote ${remoteId}`); + + if (!this.config.remoteRegistry) { + logger.warn('No remote registry available'); + return false; + } const remote = this.config.remoteRegistry.getRemote(remoteId); - if (!remote) return false; + if (!remote) { + logger.warn(`Remote ${remoteId} not found in registry`); + return false; + } try { // Convert HTTP URL to WebSocket URL @@ -255,8 +288,11 @@ export class BufferAggregator { }, }); + logger.debug(`Attempting WebSocket connection to ${wsUrl}`); + await new Promise((resolve, reject) => { const timeout = setTimeout(() => { + logger.warn(`Connection to remote ${remote.name} timed out after 5s`); reject(new Error('Connection timeout')); }, 5000); @@ -285,6 +321,10 @@ export class BufferAggregator { this.handleRemoteMessage(remoteId, data); }); + logger.debug( + `Remote ${remote.name} connection established with ${remoteConn.subscriptions.size} initial subscriptions` + ); + // Handle disconnection ws.on('close', () => { logger.log(chalk.yellow(`Disconnected from remote ${remote.name}`)); @@ -292,13 +332,13 @@ export class BufferAggregator { }); ws.on('error', (error) => { - logger.error(chalk.red(`Remote ${remote.name} WebSocket error:`), error); + logger.error(`Remote ${remote.name} WebSocket error:`, error); }); logger.log(chalk.green(`Connected to remote ${remote.name}`)); return true; } catch (error) { - logger.error(chalk.red(`Failed to connect to remote ${remoteId}:`), error); + logger.error(`Failed to connect to remote ${remoteId}:`, error); return false; } } @@ -335,11 +375,17 @@ export class BufferAggregator { const sessionId = buffer.subarray(5, 5 + sessionIdLength).toString('utf8'); // Forward to all clients subscribed to this session + let forwardedCount = 0; for (const [clientWs, subscriptions] of this.clientSubscriptions) { if (subscriptions.has(sessionId) && clientWs.readyState === WebSocket.OPEN) { clientWs.send(buffer); + forwardedCount++; } } + + if (forwardedCount > 0) { + logger.debug(`Forwarded buffer update for session ${sessionId} to ${forwardedCount} clients`); + } } /** @@ -348,11 +394,14 @@ export class BufferAggregator { private handleClientDisconnect(ws: WebSocket): void { const subscriptions = this.clientSubscriptions.get(ws); if (subscriptions) { + const subscriptionCount = subscriptions.size; // Unsubscribe from all sessions - for (const [_sessionId, unsubscribe] of subscriptions) { + for (const [sessionId, unsubscribe] of subscriptions) { + logger.debug(`Cleaning up subscription for session ${sessionId}`); unsubscribe(); } subscriptions.clear(); + logger.debug(`Cleaned up ${subscriptionCount} subscriptions`); } this.clientSubscriptions.delete(ws); logger.log(chalk.yellow('Client disconnected')); @@ -362,18 +411,28 @@ export class BufferAggregator { * Register a new remote server (called when a remote registers with HQ) */ async onRemoteRegistered(remoteId: string): Promise { + logger.log(`Remote ${remoteId} registered, establishing connection`); // Optionally pre-connect to the remote - await this.connectToRemote(remoteId); + const connected = await this.connectToRemote(remoteId); + if (!connected) { + logger.warn(`Failed to establish connection to newly registered remote ${remoteId}`); + } } /** * Handle remote server unregistration */ onRemoteUnregistered(remoteId: string): void { + logger.log(`Remote ${remoteId} unregistered, closing connection`); const remoteConn = this.remoteConnections.get(remoteId); if (remoteConn) { + logger.debug( + `Closing connection to remote ${remoteConn.remoteName} with ${remoteConn.subscriptions.size} active subscriptions` + ); remoteConn.ws.close(); this.remoteConnections.delete(remoteId); + } else { + logger.debug(`No active connection found for unregistered remote ${remoteId}`); } } @@ -381,16 +440,22 @@ export class BufferAggregator { * Clean up all connections */ destroy(): void { + logger.log(chalk.yellow('Shutting down BufferAggregator')); + // Close all client connections + const clientCount = this.clientSubscriptions.size; for (const [ws] of this.clientSubscriptions) { ws.close(); } this.clientSubscriptions.clear(); + logger.debug(`Closed ${clientCount} client connections`); // Close all remote connections + const remoteCount = this.remoteConnections.size; for (const [_, remoteConn] of this.remoteConnections) { remoteConn.ws.close(); } this.remoteConnections.clear(); + logger.debug(`Closed ${remoteCount} remote connections`); } } diff --git a/web/src/server/services/control-dir-watcher.ts b/web/src/server/services/control-dir-watcher.ts index 7962e628..a2e26001 100644 --- a/web/src/server/services/control-dir-watcher.ts +++ b/web/src/server/services/control-dir-watcher.ts @@ -23,13 +23,14 @@ export class ControlDirWatcher { constructor(config: ControlDirWatcherConfig) { this.config = config; + logger.debug(`Initialized with control dir: ${config.controlDir}, HQ mode: ${config.isHQMode}`); } start(): void { // Create control directory if it doesn't exist if (!fs.existsSync(this.config.controlDir)) { logger.log( - chalk.yellow(`Control directory ${this.config.controlDir} does not exist, creating it...`) + chalk.yellow(`Control directory ${this.config.controlDir} does not exist, creating it`) ); fs.mkdirSync(this.config.controlDir, { recursive: true }); } @@ -53,6 +54,7 @@ export class ControlDirWatcher { try { // Give it a moment for the session.json to be written + logger.debug(`Waiting 100ms for session.json to be written for ${filename}`); await new Promise((resolve) => setTimeout(resolve, 100)); if (fs.existsSync(sessionJsonPath)) { @@ -78,7 +80,7 @@ export class ControlDirWatcher { try { await this.notifyHQAboutSession(sessionId, 'created'); } catch (error) { - logger.error(chalk.red(`Failed to notify HQ about new session ${sessionId}:`), error); + logger.error(`Failed to notify HQ about new session ${sessionId}:`, error); } } @@ -87,7 +89,7 @@ export class ControlDirWatcher { } else if (!fs.existsSync(sessionPath)) { // Session directory was removed const sessionId = filename; - logger.log(chalk.yellow(`Detected removed external session: ${sessionId}`)); + logger.log(chalk.yellow(`Detected removed session: ${sessionId}`)); // If we're a remote server registered with HQ, immediately notify HQ if (this.config.hqClient && !isShuttingDown()) { @@ -96,21 +98,19 @@ export class ControlDirWatcher { } catch (error) { // During shutdown, this is expected if (!isShuttingDown()) { - logger.error( - chalk.red(`Failed to notify HQ about deleted session ${sessionId}:`), - error - ); + logger.error(`Failed to notify HQ about deleted session ${sessionId}:`, error); } } } // If in HQ mode, remove from tracking if (this.config.isHQMode && this.config.remoteRegistry) { + logger.debug(`Removing session ${sessionId} from remote registry`); this.config.remoteRegistry.removeSessionFromRemote(sessionId); } } } catch (error) { - logger.error(chalk.red(`Error handling file change for ${filename}:`), error); + logger.error(`Error handling file change for ${filename}:`, error); } } @@ -118,12 +118,22 @@ export class ControlDirWatcher { sessionId: string, action: 'created' | 'deleted' ): Promise { - if (!this.config.hqClient || isShuttingDown()) return; + if (!this.config.hqClient || isShuttingDown()) { + logger.debug( + `Skipping HQ notification for ${sessionId} (${action}): shutting down or no HQ client` + ); + return; + } const hqUrl = this.config.hqClient.getHQUrl(); const hqAuth = this.config.hqClient.getHQAuth(); const remoteName = this.config.hqClient.getName(); + logger.debug( + `Notifying HQ at ${hqUrl} about ${action} session ${sessionId} from remote ${remoteName}` + ); + const startTime = Date.now(); + // Notify HQ about session change // For now, we'll trigger a session list refresh by calling the HQ's session endpoint // This will cause HQ to update its registry with the latest session information @@ -142,12 +152,14 @@ export class ControlDirWatcher { if (!response.ok) { // If we get a 503 during shutdown, that's expected if (response.status === 503 && isShuttingDown()) { + logger.debug(`Got expected 503 from HQ during shutdown`); return; } - throw new Error(`HQ responded with ${response.status}`); + throw new Error(`HQ responded with ${response.status}: ${await response.text()}`); } - logger.log(chalk.green(`Notified HQ about ${action} session ${sessionId}`)); + const duration = Date.now() - startTime; + logger.log(chalk.green(`Notified HQ about ${action} session ${sessionId} (${duration}ms)`)); } stop(): void { @@ -155,6 +167,8 @@ export class ControlDirWatcher { this.watcher.close(); this.watcher = null; logger.log(chalk.yellow('Control directory watcher stopped')); + } else { + logger.debug('Stop called but watcher was not running'); } } } diff --git a/web/src/server/services/hq-client.ts b/web/src/server/services/hq-client.ts index a8096b5c..8a07346f 100644 --- a/web/src/server/services/hq-client.ts +++ b/web/src/server/services/hq-client.ts @@ -1,5 +1,6 @@ import { v4 as uuidv4 } from 'uuid'; import { createLogger } from '../utils/logger.js'; +import chalk from 'chalk'; const logger = createLogger('hq-client'); @@ -27,9 +28,18 @@ export class HQClient { this.hqUsername = hqUsername; this.hqPassword = hqPassword; this.remoteUrl = remoteUrl; + + logger.debug('hq client initialized', { + hqUrl, + remoteName, + remoteId: this.remoteId, + remoteUrl, + }); } async register(): Promise { + logger.log(`registering with hq at ${this.hqUrl}`); + try { const response = await fetch(`${this.hqUrl}/api/remotes/register`, { method: 'POST', @@ -47,30 +57,45 @@ export class HQClient { if (!response.ok) { const errorBody = await response.json().catch(() => ({ error: response.statusText })); + logger.debug(`registration failed with status ${response.status}`, errorBody); throw new Error(`Registration failed: ${errorBody.error || response.statusText}`); } - logger.log(`Successfully registered with HQ at ${this.hqUrl}`); - logger.log(`Remote ID: ${this.remoteId}`); - logger.log(`Remote name: ${this.remoteName}`); - logger.debug(`Token: ${this.token}`); + logger.log( + chalk.green(`successfully registered with hq: ${this.remoteName} (${this.remoteId})`) + + chalk.gray(` at ${this.hqUrl}`) + ); + logger.debug('registration details', { + remoteId: this.remoteId, + remoteName: this.remoteName, + token: this.token.substring(0, 8) + '...', + }); } catch (error) { - logger.error('Failed to register with HQ:', error); + logger.error('failed to register with hq:', error); throw error; // Let the caller handle retries if needed } } async destroy(): Promise { + logger.log(chalk.yellow(`unregistering from hq: ${this.remoteName} (${this.remoteId})`)); + try { // Try to unregister - await fetch(`${this.hqUrl}/api/remotes/${this.remoteId}`, { + const response = await fetch(`${this.hqUrl}/api/remotes/${this.remoteId}`, { method: 'DELETE', headers: { Authorization: `Basic ${Buffer.from(`${this.hqUsername}:${this.hqPassword}`).toString('base64')}`, }, }); - } catch { - // Ignore errors during shutdown + + if (response.ok) { + logger.debug('successfully unregistered from hq'); + } else { + logger.debug(`unregistration returned status ${response.status}`); + } + } catch (error) { + // Log but don't throw during shutdown + logger.debug('error during unregistration:', error); } } diff --git a/web/src/server/services/remote-registry.ts b/web/src/server/services/remote-registry.ts index c7f4fa90..aecfcf6a 100644 --- a/web/src/server/services/remote-registry.ts +++ b/web/src/server/services/remote-registry.ts @@ -1,5 +1,6 @@ import { isShuttingDown } from '../server.js'; import { createLogger } from '../utils/logger.js'; +import chalk from 'chalk'; const logger = createLogger('remote-registry'); @@ -23,6 +24,10 @@ export class RemoteRegistry { constructor() { this.startHealthChecker(); + logger.debug('remote registry initialized with health check interval', { + interval: this.HEALTH_CHECK_INTERVAL, + timeout: this.HEALTH_CHECK_TIMEOUT, + }); } register( @@ -43,7 +48,7 @@ export class RemoteRegistry { this.remotes.set(remote.id, registeredRemote); this.remotesByName.set(remote.name, registeredRemote); - logger.log(`Remote registered: ${remote.name} (${remote.id}) from ${remote.url}`); + logger.log(chalk.green(`remote registered: ${remote.name} (${remote.id}) from ${remote.url}`)); // Immediately check health of new remote this.checkRemoteHealth(registeredRemote); @@ -54,7 +59,7 @@ export class RemoteRegistry { unregister(remoteId: string): boolean { const remote = this.remotes.get(remoteId); if (remote) { - logger.log(`Remote unregistered: ${remote.name} (${remoteId}`); + logger.log(chalk.yellow(`remote unregistered: ${remote.name} (${remoteId})`)); // Clean up session mappings for (const sessionId of remote.sessionIds) { @@ -68,7 +73,11 @@ export class RemoteRegistry { } getRemote(remoteId: string): RemoteServer | undefined { - return this.remotes.get(remoteId); + const remote = this.remotes.get(remoteId); + if (!remote) { + logger.debug(`remote not found: ${remoteId}`); + } + return remote; } getRemoteByUrl(url: string): RemoteServer | undefined { @@ -86,7 +95,12 @@ export class RemoteRegistry { updateRemoteSessions(remoteId: string, sessionIds: string[]): void { const remote = this.remotes.get(remoteId); - if (!remote) return; + if (!remote) { + logger.debug(`cannot update sessions: remote ${remoteId} not found`); + return; + } + + const oldCount = remote.sessionIds.size; // Remove old session mappings for (const oldSessionId of remote.sessionIds) { @@ -98,23 +112,36 @@ export class RemoteRegistry { for (const sessionId of sessionIds) { this.sessionToRemote.set(sessionId, remoteId); } + + logger.debug(`updated sessions for remote ${remote.name}`, { + oldCount, + newCount: sessionIds.length, + }); } addSessionToRemote(remoteId: string, sessionId: string): void { const remote = this.remotes.get(remoteId); - if (!remote) return; + if (!remote) { + logger.warn(`cannot add session ${sessionId}: remote ${remoteId} not found`); + return; + } remote.sessionIds.add(sessionId); this.sessionToRemote.set(sessionId, remoteId); + logger.debug(`session ${sessionId} added to remote ${remote.name}`); } removeSessionFromRemote(sessionId: string): void { const remoteId = this.sessionToRemote.get(sessionId); - if (!remoteId) return; + if (!remoteId) { + logger.debug(`session ${sessionId} not mapped to any remote`); + return; + } const remote = this.remotes.get(remoteId); if (remote) { remote.sessionIds.delete(sessionId); + logger.debug(`session ${sessionId} removed from remote ${remote.name}`); } this.sessionToRemote.delete(sessionId); @@ -145,13 +172,14 @@ export class RemoteRegistry { if (response.ok) { remote.lastHeartbeat = new Date(); + logger.debug(`health check passed for ${remote.name}`); } else { throw new Error(`HTTP ${response.status}`); } } catch (error) { // During shutdown, don't log errors or unregister remotes if (!isShuttingDown()) { - logger.warn(`Remote failed health check: ${remote.name} (${remote.id}) - ${error}`); + logger.warn(`remote failed health check: ${remote.name} (${remote.id})`, error); // Remove the remote if it fails health check this.unregister(remote.id); } @@ -159,6 +187,7 @@ export class RemoteRegistry { } private startHealthChecker() { + logger.debug('starting health checker'); this.healthCheckInterval = setInterval(() => { // Skip health checks during shutdown if (isShuttingDown()) { @@ -171,14 +200,16 @@ export class RemoteRegistry { ); Promise.all(healthChecks).catch((err) => { - logger.error('Error in health checks:', err); + logger.error('error in health checks:', err); }); }, this.HEALTH_CHECK_INTERVAL); } destroy() { + logger.log(chalk.yellow('destroying remote registry')); if (this.healthCheckInterval) { clearInterval(this.healthCheckInterval); + logger.debug('health checker stopped'); } } } diff --git a/web/src/server/services/stream-watcher.ts b/web/src/server/services/stream-watcher.ts index 6f5cd98b..8216f21e 100644 --- a/web/src/server/services/stream-watcher.ts +++ b/web/src/server/services/stream-watcher.ts @@ -1,5 +1,6 @@ import * as fs from 'fs'; import { Response } from 'express'; +import chalk from 'chalk'; import { createLogger } from '../utils/logger.js'; const logger = createLogger('stream-watcher'); @@ -26,12 +27,14 @@ export class StreamWatcher { process.on('beforeExit', () => { this.cleanup(); }); + logger.debug('stream watcher initialized'); } /** * Add a client to watch a stream file */ addClient(sessionId: string, streamPath: string, response: Response): void { + logger.debug(`adding client to session ${sessionId}`); const startTime = Date.now() / 1000; const client: StreamClient = { response, startTime }; @@ -39,6 +42,7 @@ export class StreamWatcher { if (!watcherInfo) { // Create new watcher for this session + logger.log(chalk.green(`creating new stream watcher for session ${sessionId}`)); watcherInfo = { clients: new Set(), lastOffset: 0, @@ -57,6 +61,9 @@ export class StreamWatcher { watcherInfo.lastOffset = stats.size; watcherInfo.lastSize = stats.size; watcherInfo.lastMtime = stats.mtimeMs; + logger.debug(`initial file size: ${stats.size} bytes`); + } else { + logger.debug(`stream file does not exist yet: ${streamPath}`); } // Start watching for new content @@ -68,8 +75,8 @@ export class StreamWatcher { // Add client to set watcherInfo.clients.add(client); - logger.debug( - `Added client to session ${sessionId}, total clients: ${watcherInfo.clients.size}` + logger.log( + chalk.blue(`client connected to stream ${sessionId} (${watcherInfo.clients.size} total)`) ); } @@ -78,7 +85,10 @@ export class StreamWatcher { */ removeClient(sessionId: string, response: Response): void { const watcherInfo = this.activeWatchers.get(sessionId); - if (!watcherInfo) return; + if (!watcherInfo) { + logger.debug(`no watcher found for session ${sessionId}`); + return; + } // Find and remove client let clientToRemove: StreamClient | undefined; @@ -91,13 +101,15 @@ export class StreamWatcher { if (clientToRemove) { watcherInfo.clients.delete(clientToRemove); - logger.debug( - `Removed client from session ${sessionId}, remaining clients: ${watcherInfo.clients.size}` + logger.log( + chalk.yellow( + `client disconnected from stream ${sessionId} (${watcherInfo.clients.size} remaining)` + ) ); // If no more clients, stop watching if (watcherInfo.clients.size === 0) { - logger.debug(`No more clients for session ${sessionId}, stopping watcher`); + logger.log(chalk.yellow(`stopping watcher for session ${sessionId} (no clients)`)); if (watcherInfo.watcher) { watcherInfo.watcher.close(); } @@ -137,8 +149,8 @@ export class StreamWatcher { client.response.write(`data: ${JSON.stringify(instantEvent)}\n\n`); } } - } catch (_e) { - // Skip invalid lines + } catch (e) { + logger.debug(`skipping invalid JSON line during replay: ${e}`); } } } @@ -160,23 +172,27 @@ export class StreamWatcher { client.response.write(`data: ${JSON.stringify(instantEvent)}\n\n`); } } - } catch (_e) { - // Skip invalid line + } catch (e) { + logger.debug(`skipping invalid JSON in line buffer: ${e}`); } } // If exit event found, close connection if (exitEventFound) { - logger.debug(`Session already has exit event, closing connection`); + logger.log( + chalk.yellow( + `session ${client.response.locals?.sessionId || 'unknown'} already ended, closing stream` + ) + ); client.response.end(); } }); stream.on('error', (error) => { - logger.error(`Error streaming existing content:`, error); + logger.error('failed to stream existing content:', error); }); } catch (error) { - logger.error(`Error creating read stream:`, error); + logger.error('failed to create read stream:', error); } } @@ -184,7 +200,7 @@ export class StreamWatcher { * Start watching a file for changes */ private startWatching(sessionId: string, streamPath: string, watcherInfo: WatcherInfo): void { - logger.debug(`Using file watcher for session ${sessionId}`); + logger.log(chalk.green(`started watching stream file for session ${sessionId}`)); // Use standard fs.watch with stat checking watcherInfo.watcher = fs.watch(streamPath, { persistent: true }, (eventType) => { @@ -195,6 +211,10 @@ export class StreamWatcher { // Only process if size increased (append-only file) if (stats.size > watcherInfo.lastSize || stats.mtimeMs > watcherInfo.lastMtime) { + const sizeDiff = stats.size - watcherInfo.lastSize; + if (sizeDiff > 0) { + logger.debug(`file grew by ${sizeDiff} bytes`); + } watcherInfo.lastSize = stats.size; watcherInfo.lastMtime = stats.mtimeMs; @@ -224,13 +244,13 @@ export class StreamWatcher { } } } catch (error) { - logger.error(`Error reading file changes:`, error); + logger.error('failed to read file changes:', error); } } }); watcherInfo.watcher.on('error', (error) => { - logger.error(`File watcher error for session ${sessionId}:`, error); + logger.error(`file watcher error for session ${sessionId}:`, error); }); } @@ -247,7 +267,7 @@ export class StreamWatcher { } if (Array.isArray(parsed) && parsed.length >= 3) { if (parsed[0] === 'exit') { - logger.debug(`Exit event detected: ${JSON.stringify(parsed)}`); + logger.log(chalk.yellow(`session ${sessionId} ended with exit code ${parsed[2]}`)); eventData = `data: ${JSON.stringify(parsed)}\n\n`; // Send exit event to all clients and close connections @@ -256,7 +276,7 @@ export class StreamWatcher { client.response.write(eventData); client.response.end(); } catch (error) { - logger.error(`Error writing to client:`, error); + logger.error('failed to send exit event to client:', error); } } return; @@ -272,15 +292,17 @@ export class StreamWatcher { // @ts-expect-error - flush exists but not in types if (client.response.flush) client.response.flush(); } catch (error) { - logger.error(`Error writing to client:`, error); - // Client might be disconnected + logger.debug( + `client write failed (likely disconnected): ${error instanceof Error ? error.message : String(error)}` + ); } } return; // Already handled per-client } } - } catch (_e) { + } catch { // Handle non-JSON as raw output + logger.debug(`broadcasting raw output line: ${line.substring(0, 50)}...`); const currentTime = Date.now() / 1000; for (const client of watcherInfo.clients) { const castEvent = [currentTime - client.startTime, 'o', line]; @@ -291,7 +313,9 @@ export class StreamWatcher { // @ts-expect-error - flush exists but not in types if (client.response.flush) client.response.flush(); } catch (error) { - logger.error(`Error writing to client:`, error); + logger.debug( + `client write failed (likely disconnected): ${error instanceof Error ? error.message : String(error)}` + ); } } return; @@ -302,11 +326,16 @@ export class StreamWatcher { * Clean up all watchers and listeners */ private cleanup(): void { - for (const [_sessionId, watcherInfo] of this.activeWatchers) { - if (watcherInfo.watcher) { - watcherInfo.watcher.close(); + const watcherCount = this.activeWatchers.size; + if (watcherCount > 0) { + logger.log(chalk.yellow(`cleaning up ${watcherCount} active watchers`)); + for (const [sessionId, watcherInfo] of this.activeWatchers) { + if (watcherInfo.watcher) { + watcherInfo.watcher.close(); + } + logger.debug(`closed watcher for session ${sessionId}`); } + this.activeWatchers.clear(); } - this.activeWatchers.clear(); } } diff --git a/web/src/server/services/terminal-manager.ts b/web/src/server/services/terminal-manager.ts index 61c66a6e..28860b58 100644 --- a/web/src/server/services/terminal-manager.ts +++ b/web/src/server/services/terminal-manager.ts @@ -2,6 +2,7 @@ import { Terminal as XtermTerminal } from '@xterm/headless'; import * as fs from 'fs'; import * as path from 'path'; import { createLogger } from '../utils/logger.js'; +import chalk from 'chalk'; const logger = createLogger('terminal-manager'); @@ -62,6 +63,9 @@ export class TerminalManager { }; this.terminals.set(sessionId, sessionTerminal); + logger.log( + chalk.green(`Terminal created for session ${sessionId} (${terminal.cols}x${terminal.rows})`) + ); // Start watching the stream file await this.watchStreamFile(sessionId); @@ -84,7 +88,7 @@ export class TerminalManager { // Check if the file exists if (!fs.existsSync(streamPath)) { - logger.warn(`Stream file does not exist for session ${sessionId}: ${streamPath}`); + logger.error(`Stream file does not exist for session ${sessionId}: ${streamPath}`); return; } @@ -136,7 +140,7 @@ export class TerminalManager { } }); - logger.log(`Watching stream file for session ${sessionId}`); + logger.log(chalk.green(`Watching stream file for session ${sessionId}`)); } catch (error) { logger.error(`Failed to watch stream file for session ${sessionId}:`, error); throw error; @@ -163,7 +167,7 @@ export class TerminalManager { if (timestamp === 'exit') { // Session exited - logger.log(`Session ${sessionId} exited with code ${data[1]}`); + logger.log(chalk.yellow(`Session ${sessionId} exited with code ${data[1]}`)); if (sessionTerminal.watcher) { sessionTerminal.watcher.close(); } @@ -197,6 +201,7 @@ export class TerminalManager { async getBufferStats(sessionId: string) { const terminal = await this.getTerminal(sessionId); const buffer = terminal.buffer.active; + logger.debug(`Getting buffer stats for session ${sessionId}: ${buffer.length} total rows`); return { totalRows: buffer.length, @@ -213,6 +218,7 @@ export class TerminalManager { * Get buffer snapshot for a session - always returns full terminal buffer (cols x rows) */ async getBufferSnapshot(sessionId: string): Promise { + const startTime = Date.now(); const terminal = await this.getTerminal(sessionId); const buffer = terminal.buffer.active; @@ -315,6 +321,13 @@ export class TerminalManager { // Keep at least one row const trimmedCells = cells.slice(0, Math.max(1, lastNonBlankRow + 1)); + const duration = Date.now() - startTime; + if (duration > 10) { + logger.debug( + `Buffer snapshot for session ${sessionId} took ${duration}ms (${trimmedCells.length} rows)` + ); + } + return { cols: terminal.cols, rows: trimmedCells.length, @@ -329,6 +342,7 @@ export class TerminalManager { * Encode buffer snapshot to binary format - optimized for minimal data transmission */ encodeSnapshot(snapshot: BufferSnapshot): Buffer { + const startTime = Date.now(); const { cols, rows, viewportY, cursorX, cursorY, cells } = snapshot; // Pre-calculate actual data size for efficiency @@ -410,7 +424,14 @@ export class TerminalManager { } // Return exact size buffer - return buffer.subarray(0, offset); + const result = buffer.subarray(0, offset); + + const duration = Date.now() - startTime; + if (duration > 5) { + logger.debug(`Encoded snapshot: ${result.length} bytes in ${duration}ms (${rows} rows)`); + } + + return result; } /** @@ -568,6 +589,7 @@ export class TerminalManager { } sessionTerminal.terminal.dispose(); this.terminals.delete(sessionId); + logger.log(chalk.yellow(`Terminal closed for session ${sessionId}`)); } } @@ -585,9 +607,13 @@ export class TerminalManager { } for (const sessionId of toRemove) { - logger.log(`Cleaning up stale terminal for session ${sessionId}`); + logger.log(chalk.yellow(`Cleaning up stale terminal for session ${sessionId}`)); this.closeTerminal(sessionId); } + + if (toRemove.length > 0) { + logger.log(chalk.gray(`Cleaned up ${toRemove.length} stale terminals`)); + } } /** @@ -614,6 +640,9 @@ export class TerminalManager { const listeners = this.bufferListeners.get(sessionId); if (listeners) { listeners.add(listener); + logger.log( + chalk.blue(`Buffer listener subscribed for session ${sessionId} (${listeners.size} total)`) + ); } // Return unsubscribe function @@ -621,6 +650,11 @@ export class TerminalManager { const listeners = this.bufferListeners.get(sessionId); if (listeners) { listeners.delete(listener); + logger.log( + chalk.yellow( + `Buffer listener unsubscribed for session ${sessionId} (${listeners.size} remaining)` + ) + ); if (listeners.size === 0) { this.bufferListeners.delete(sessionId); } @@ -654,6 +688,8 @@ export class TerminalManager { const listeners = this.bufferListeners.get(sessionId); if (!listeners || listeners.size === 0) return; + logger.debug(`Notifying ${listeners.size} buffer change listeners for session ${sessionId}`); + try { // Get full buffer snapshot const snapshot = await this.getBufferSnapshot(sessionId); diff --git a/web/src/server/version.ts b/web/src/server/version.ts index 7352087e..cc7fe44a 100644 --- a/web/src/server/version.ts +++ b/web/src/server/version.ts @@ -2,6 +2,7 @@ // This file is updated during the build process import { createLogger } from './utils/logger.js'; +import chalk from 'chalk'; const logger = createLogger('version'); @@ -17,7 +18,9 @@ export const PLATFORM = process.platform; export const ARCH = process.arch; export function getVersionInfo() { - return { + logger.debug('gathering version information'); + + const info = { version: VERSION, buildDate: BUILD_DATE, buildTimestamp: BUILD_TIMESTAMP, @@ -28,11 +31,23 @@ export function getVersionInfo() { uptime: process.uptime(), pid: process.pid, }; + + logger.debug(`version info: ${JSON.stringify(info)}`); + return info; } export function printVersionBanner() { - logger.log(`VibeTunnel Server v${VERSION}`); - logger.log(`Built: ${BUILD_DATE}`); - logger.log(`Platform: ${PLATFORM}/${ARCH} Node ${NODE_VERSION}`); - logger.log(`PID: ${process.pid}`); + logger.log(chalk.green(`VibeTunnel Server v${VERSION}`)); + logger.log(chalk.gray(`Built: ${BUILD_DATE}`)); + logger.log(chalk.gray(`Platform: ${PLATFORM}/${ARCH} Node ${NODE_VERSION}`)); + logger.log(chalk.gray(`PID: ${process.pid}`)); + + if (GIT_COMMIT !== 'development') { + logger.log(chalk.gray(`Commit: ${GIT_COMMIT}`)); + } + + // Log development mode warning + if (GIT_COMMIT === 'development' || !process.env.BUILD_DATE) { + logger.log(chalk.yellow('running in development mode')); + } }