Add structured logging and ensure CLI shuts down cleanly

This commit is contained in:
Shantur Rathore
2025-11-17 20:21:39 +00:00
parent 08d81f8bb5
commit 719a9c9c74
13 changed files with 255 additions and 55 deletions

1
package-lock.json generated
View File

@@ -7914,6 +7914,7 @@
"dependencies": {
"@fastify/cors": "^8.5.0",
"fastify": "^4.28.1",
"pino": "^9.4.0",
"zod": "^3.23.8"
},
"devDependencies": {

View File

@@ -12,6 +12,7 @@
"dependencies": {
"@fastify/cors": "^8.5.0",
"fastify": "^4.28.1",
"pino": "^9.4.0",
"zod": "^3.23.8"
},
"devDependencies": {

View File

@@ -7,9 +7,14 @@ import {
import { ConfigStore } from "./store"
import { EventBus } from "../events/bus"
import type { ConfigFileUpdate } from "./schema"
import { Logger } from "../logger"
export class BinaryRegistry {
constructor(private readonly configStore: ConfigStore, private readonly eventBus?: EventBus) {}
constructor(
private readonly configStore: ConfigStore,
private readonly eventBus: EventBus | undefined,
private readonly logger: Logger,
) {}
list(): BinaryRecord[] {
return this.mapRecords()
@@ -18,12 +23,14 @@ export class BinaryRegistry {
resolveDefault(): BinaryRecord {
const binaries = this.mapRecords()
if (binaries.length === 0) {
this.logger.warn("No configured binaries found, falling back to opencode")
return this.buildFallbackRecord("opencode")
}
return binaries.find((binary) => binary.isDefault) ?? binaries[0]
}
create(request: BinaryCreateRequest): BinaryRecord {
this.logger.info({ path: request.path }, "Registering OpenCode binary")
const entry = {
path: request.path,
version: undefined,
@@ -49,6 +56,7 @@ export class BinaryRegistry {
}
update(id: string, updates: BinaryUpdateRequest): BinaryRecord {
this.logger.info({ id }, "Updating OpenCode binary")
const config = this.configStore.get()
const updatedEntries = config.opencodeBinaries.map((binary) =>
binary.path === id ? { ...binary, label: updates.label ?? binary.label } : binary,
@@ -69,6 +77,7 @@ export class BinaryRegistry {
}
remove(id: string) {
this.logger.info({ id }, "Removing OpenCode binary")
const config = this.configStore.get()
const remaining = config.opencodeBinaries.filter((binary) => binary.path !== id)
const update: ConfigFileUpdate = { opencodeBinaries: remaining }
@@ -82,6 +91,7 @@ export class BinaryRegistry {
}
validatePath(path: string): BinaryValidationResult {
this.logger.debug({ path }, "Validating OpenCode binary path")
return this.validateRecord({
id: path,
path,
@@ -119,6 +129,7 @@ export class BinaryRegistry {
}
private emitChange() {
this.logger.debug("Emitting binaries changed event")
this.eventBus?.publish({ type: "config.binariesChanged", binaries: this.mapRecords() })
}

View File

@@ -1,6 +1,7 @@
import fs from "fs"
import path from "path"
import { EventBus } from "../events/bus"
import { Logger } from "../logger"
import {
AgentModelSelections,
ConfigFile,
@@ -14,7 +15,11 @@ export class ConfigStore {
private cache: ConfigFile = DEFAULT_CONFIG
private loaded = false
constructor(private readonly configPath: string, private readonly eventBus?: EventBus) {}
constructor(
private readonly configPath: string,
private readonly eventBus: EventBus | undefined,
private readonly logger: Logger,
) {}
load(): ConfigFile {
if (this.loaded) {
@@ -27,11 +32,13 @@ export class ConfigStore {
const content = fs.readFileSync(resolved, "utf-8")
const parsed = JSON.parse(content)
this.cache = ConfigFileSchema.parse(parsed)
this.logger.debug({ resolved }, "Loaded existing config file")
} else {
this.cache = DEFAULT_CONFIG
this.logger.info({ resolved }, "No config file found, using defaults")
}
} catch (error) {
console.warn("Failed to load config", error)
this.logger.warn({ err: error }, "Failed to load config, using defaults")
this.cache = DEFAULT_CONFIG
}
@@ -52,6 +59,7 @@ export class ConfigStore {
this.cache = ConfigFileSchema.parse(merged)
this.persist()
this.eventBus?.publish({ type: "config.appChanged", config: this.cache })
this.logger.info("Config updated")
}
private mergeConfig(current: ConfigFile, partial: ConfigFile | ConfigFileUpdate): ConfigFile {
@@ -97,8 +105,9 @@ export class ConfigStore {
const resolved = this.resolvePath(this.configPath)
fs.mkdirSync(path.dirname(resolved), { recursive: true })
fs.writeFileSync(resolved, JSON.stringify(this.cache, null, 2), "utf-8")
this.logger.debug({ resolved }, "Persisted config file")
} catch (error) {
console.warn("Failed to persist config", error)
this.logger.warn({ err: error }, "Failed to persist config")
}
}

View File

@@ -1,8 +1,14 @@
import { EventEmitter } from "events"
import { WorkspaceEventPayload } from "../api-types"
import { Logger } from "../logger"
export class EventBus extends EventEmitter {
constructor(private readonly logger?: Logger) {
super()
}
publish(event: WorkspaceEventPayload): boolean {
this.logger?.debug({ event }, "Publishing workspace event")
return super.emit(event.type, event)
}

View File

@@ -10,12 +10,15 @@ import { FileSystemBrowser } from "./filesystem/browser"
import { EventBus } from "./events/bus"
import { ServerMeta } from "./api-types"
import { InstanceStore } from "./storage/instance-store"
import { createLogger } from "./logger"
interface CliOptions {
port: number
host: string
rootDir: string
configPath: string
logLevel?: string
logDestination?: string
}
function parseCliOptions(argv: string[]): CliOptions {
@@ -34,20 +37,26 @@ function parseCliOptions(argv: string[]): CliOptions {
host: args.get("host") ?? process.env.CLI_HOST ?? "127.0.0.1",
rootDir: args.get("root") ?? process.cwd(),
configPath: args.get("config") ?? process.env.CLI_CONFIG ?? "~/.config/codenomad/config.json",
logLevel: args.get("log-level") ?? process.env.CLI_LOG_LEVEL,
logDestination: args.get("log-destination") ?? process.env.CLI_LOG_DESTINATION,
}
}
async function main() {
const options = parseCliOptions(process.argv.slice(2))
const logger = createLogger({ level: options.logLevel, destination: options.logDestination })
const eventBus = new EventBus()
const configStore = new ConfigStore(options.configPath, eventBus)
const binaryRegistry = new BinaryRegistry(configStore, eventBus)
logger.info({ options }, "Starting CodeNomad CLI server")
const eventBus = new EventBus(logger)
const configStore = new ConfigStore(options.configPath, eventBus, logger)
const binaryRegistry = new BinaryRegistry(configStore, eventBus, logger)
const workspaceManager = new WorkspaceManager({
rootDir: options.rootDir,
configStore,
binaryRegistry,
eventBus,
logger,
})
const fileSystemBrowser = new FileSystemBrowser({ rootDir: options.rootDir })
const instanceStore = new InstanceStore()
@@ -69,13 +78,36 @@ async function main() {
eventBus,
serverMeta,
instanceStore,
logger,
})
await server.start()
logger.info({ port: options.port, host: options.host }, "HTTP server listening")
let shuttingDown = false
const shutdown = async () => {
await server.stop()
await workspaceManager.shutdown()
if (shuttingDown) {
logger.info("Shutdown already in progress, ignoring signal")
return
}
shuttingDown = true
logger.info("Received shutdown signal, closing server")
try {
await server.stop()
logger.info("HTTP server stopped")
} catch (error) {
logger.error({ err: error }, "Failed to stop HTTP server")
}
try {
await workspaceManager.shutdown()
logger.info("Workspace manager shutdown complete")
} catch (error) {
logger.error({ err: error }, "Workspace manager shutdown failed")
}
logger.info("Exiting process")
process.exit(0)
}
@@ -84,6 +116,7 @@ async function main() {
}
main().catch((error) => {
console.error("CLI server crashed", error)
const logger = createLogger()
logger.error({ err: error }, "CLI server crashed")
process.exit(1)
})

View File

@@ -0,0 +1,20 @@
import pino, { Logger as PinoLogger } from "pino"
export type Logger = PinoLogger
interface LoggerOptions {
level?: string
destination?: string
}
export function createLogger(options: LoggerOptions = {}): Logger {
const level = (options.level ?? process.env.CLI_LOG_LEVEL ?? "info").toLowerCase()
const destination = options.destination ?? process.env.CLI_LOG_DESTINATION ?? "stdout"
if (destination && destination !== "stdout") {
const stream = pino.destination({ dest: destination, mkdir: true, sync: false })
return pino({ level }, stream)
}
return pino({ level })
}

View File

@@ -13,6 +13,7 @@ import { registerEventRoutes } from "./routes/events"
import { registerStorageRoutes } from "./routes/storage"
import { ServerMeta } from "../api-types"
import { InstanceStore } from "../storage/instance-store"
import { Logger } from "../logger"
interface HttpServerDeps {
host: string
@@ -24,10 +25,24 @@ interface HttpServerDeps {
eventBus: EventBus
serverMeta: ServerMeta
instanceStore: InstanceStore
logger: Logger
}
export function createHttpServer(deps: HttpServerDeps) {
const app = Fastify({ logger: false })
const fastifyLogger = deps.logger.child({ module: "http" })
const app = Fastify({ logger: fastifyLogger as any })
const sseClients = new Set<() => void>()
const registerSseClient = (cleanup: () => void) => {
sseClients.add(cleanup)
return () => sseClients.delete(cleanup)
}
const closeSseClients = () => {
for (const cleanup of Array.from(sseClients)) {
cleanup()
}
sseClients.clear()
}
app.register(cors, {
origin: true,
@@ -38,12 +53,15 @@ export function createHttpServer(deps: HttpServerDeps) {
registerConfigRoutes(app, { configStore: deps.configStore, binaryRegistry: deps.binaryRegistry })
registerFilesystemRoutes(app, { fileSystemBrowser: deps.fileSystemBrowser })
registerMetaRoutes(app, { serverMeta: deps.serverMeta })
registerEventRoutes(app, { eventBus: deps.eventBus })
registerEventRoutes(app, { eventBus: deps.eventBus, registerClient: registerSseClient })
registerStorageRoutes(app, { instanceStore: deps.instanceStore })
return {
instance: app,
start: () => app.listen({ port: deps.port, host: deps.host }),
stop: () => app.close(),
stop: () => {
closeSseClients()
return app.close()
},
}
}

View File

@@ -4,6 +4,7 @@ import { WorkspaceEventPayload } from "../../api-types"
interface RouteDeps {
eventBus: EventBus
registerClient: (cleanup: () => void) => () => void
}
export function registerEventRoutes(app: FastifyInstance, deps: RouteDeps) {
@@ -26,12 +27,23 @@ export function registerEventRoutes(app: FastifyInstance, deps: RouteDeps) {
reply.raw.write(`:hb ${Date.now()}\n\n`)
}, 15000)
let closed = false
const close = () => {
if (closed) return
closed = true
clearInterval(heartbeat)
unsubscribe()
reply.raw.end?.()
}
request.raw.on("close", close)
request.raw.on("error", close)
const unregister = deps.registerClient(close)
const handleClose = () => {
close()
unregister()
}
request.raw.on("close", handleClose)
request.raw.on("error", handleClose)
})
}

View File

@@ -5,12 +5,14 @@ import { BinaryRegistry } from "../config/binaries"
import { FileSystemBrowser } from "../filesystem/browser"
import { WorkspaceDescriptor, WorkspaceFileResponse, FileSystemEntry } from "../api-types"
import { WorkspaceRuntime } from "./runtime"
import { Logger } from "../logger"
interface WorkspaceManagerOptions {
rootDir: string
configStore: ConfigStore
binaryRegistry: BinaryRegistry
eventBus: EventBus
logger: Logger
}
interface WorkspaceRecord extends WorkspaceDescriptor {}
@@ -20,7 +22,7 @@ export class WorkspaceManager {
private readonly runtime: WorkspaceRuntime
constructor(private readonly options: WorkspaceManagerOptions) {
this.runtime = new WorkspaceRuntime(this.options.eventBus)
this.runtime = new WorkspaceRuntime(this.options.eventBus, this.options.logger)
}
list(): WorkspaceDescriptor[] {
@@ -53,6 +55,8 @@ export class WorkspaceManager {
const binary = this.options.binaryRegistry.resolveDefault()
const workspacePath = path.isAbsolute(folder) ? folder : path.resolve(this.options.rootDir, folder)
this.options.logger.info({ workspaceId: id, folder: workspacePath, binary: binary.path }, "Creating workspace")
const descriptor: WorkspaceRecord = {
id,
path: workspacePath,
@@ -84,12 +88,14 @@ export class WorkspaceManager {
descriptor.status = "ready"
descriptor.updatedAt = new Date().toISOString()
this.options.eventBus.publish({ type: "workspace.started", workspace: descriptor })
this.options.logger.info({ workspaceId: id, port }, "Workspace ready")
return descriptor
} catch (error) {
descriptor.status = "error"
descriptor.error = error instanceof Error ? error.message : String(error)
descriptor.updatedAt = new Date().toISOString()
this.options.eventBus.publish({ type: "workspace.error", workspace: descriptor })
this.options.logger.error({ workspaceId: id, err: error }, "Workspace failed to start")
throw error
}
}
@@ -98,9 +104,12 @@ export class WorkspaceManager {
const workspace = this.workspaces.get(id)
if (!workspace) return undefined
this.options.logger.info({ workspaceId: id }, "Stopping workspace")
const wasRunning = Boolean(workspace.pid)
if (wasRunning) {
await this.runtime.stop(id).catch(() => {})
await this.runtime.stop(id).catch((error) => {
this.options.logger.warn({ workspaceId: id, err: error }, "Failed to stop workspace process cleanly")
})
}
this.workspaces.delete(id)
@@ -111,12 +120,19 @@ export class WorkspaceManager {
}
async shutdown() {
for (const [id] of this.workspaces) {
if (this.workspaces.get(id)?.pid) {
await this.runtime.stop(id).catch(() => {})
this.options.logger.info("Shutting down all workspaces")
for (const [id, workspace] of this.workspaces) {
if (workspace.pid) {
this.options.logger.info({ workspaceId: id }, "Stopping workspace during shutdown")
await this.runtime.stop(id).catch((error) => {
this.options.logger.error({ workspaceId: id, err: error }, "Failed to stop workspace during shutdown")
})
} else {
this.options.logger.debug({ workspaceId: id }, "Workspace already stopped")
}
}
this.workspaces.clear()
this.options.logger.info("All workspaces cleared")
}
private requireWorkspace(id: string): WorkspaceRecord {
@@ -131,6 +147,8 @@ export class WorkspaceManager {
const workspace = this.workspaces.get(workspaceId)
if (!workspace) return
this.options.logger.info({ workspaceId, ...info }, "Workspace process exited")
workspace.pid = undefined
workspace.port = undefined
workspace.updatedAt = new Date().toISOString()

View File

@@ -3,6 +3,7 @@ import { existsSync, statSync } from "fs"
import path from "path"
import { EventBus } from "../events/bus"
import { LogLevel, WorkspaceLogEntry } from "../api-types"
import { Logger } from "../logger"
interface LaunchOptions {
workspaceId: string
@@ -27,7 +28,7 @@ interface ManagedProcess {
export class WorkspaceRuntime {
private processes = new Map<string, ManagedProcess>()
constructor(private readonly eventBus: EventBus) {}
constructor(private readonly eventBus: EventBus, private readonly logger: Logger) {}
async launch(options: LaunchOptions): Promise<{ pid: number; port: number }> {
this.validateFolder(options.folder)
@@ -36,6 +37,7 @@ export class WorkspaceRuntime {
const env = { ...process.env, ...(options.environment ?? {}) }
return new Promise((resolve, reject) => {
this.logger.info({ workspaceId: options.workspaceId, folder: options.folder }, "Launching OpenCode process")
const child = spawn(options.binaryPath, args, {
cwd: options.folder,
env,
@@ -49,22 +51,36 @@ export class WorkspaceRuntime {
let stderrBuffer = ""
let portFound = false
const timeout = setTimeout(() => {
child.kill("SIGKILL")
reject(new Error("Server startup timeout (10s exceeded)"))
}, 10000)
let warningTimer: NodeJS.Timeout | null = null
const cleanup = () => {
clearTimeout(timeout)
const startWarningTimer = () => {
warningTimer = setInterval(() => {
this.logger.warn({ workspaceId: options.workspaceId }, "Workspace runtime has not reported a port yet")
}, 10000)
}
const stopWarningTimer = () => {
if (warningTimer) {
clearInterval(warningTimer)
warningTimer = null
}
}
startWarningTimer()
const cleanupStreams = () => {
stopWarningTimer()
child.stdout?.removeAllListeners()
child.stderr?.removeAllListeners()
child.removeListener("error", handleError)
}
const handleExit = (code: number | null, signal: NodeJS.Signals | null) => {
this.logger.info({ workspaceId: options.workspaceId, code, signal }, "OpenCode process exited")
this.processes.delete(options.workspaceId)
cleanupStreams()
child.removeListener("error", handleError)
child.removeListener("exit", handleExit)
if (!portFound) {
cleanup()
const reason = stderrBuffer || `Process exited with code ${code}`
reject(new Error(reason))
} else {
@@ -73,9 +89,10 @@ export class WorkspaceRuntime {
}
const handleError = (error: Error) => {
cleanup()
this.processes.delete(options.workspaceId)
cleanupStreams()
child.removeListener("exit", handleExit)
this.processes.delete(options.workspaceId)
this.logger.error({ workspaceId: options.workspaceId, err: error }, "Workspace runtime error")
reject(error)
}
@@ -96,8 +113,11 @@ export class WorkspaceRuntime {
const portMatch = line.match(/opencode server listening on http:\/\/.+:(\d+)/i)
if (portMatch) {
portFound = true
cleanup()
resolve({ pid: child.pid!, port: parseInt(portMatch[1], 10) })
cleanupStreams()
child.removeListener("error", handleError)
const port = parseInt(portMatch[1], 10)
this.logger.info({ workspaceId: options.workspaceId, port }, "Workspace runtime allocated port")
resolve({ pid: child.pid!, port })
}
}
}
@@ -114,16 +134,6 @@ export class WorkspaceRuntime {
this.emitLog(options.workspaceId, "error", line)
}
})
child.on("exit", (code, signal) => {
this.processes.delete(options.workspaceId)
if (!portFound) {
cleanup()
const reason = stderrBuffer || `Process exited with code ${code}`
reject(new Error(reason))
}
options.onExit?.({ workspaceId: options.workspaceId, code, signal, requested: managed.requestedStop })
})
})
}
@@ -133,24 +143,48 @@ export class WorkspaceRuntime {
managed.requestedStop = true
const child = managed.child
this.logger.info({ workspaceId }, "Stopping OpenCode process")
await new Promise<void>((resolve, reject) => {
const onExit = () => {
const cleanup = () => {
child.removeListener("exit", onExit)
child.removeListener("error", onError)
}
const onExit = () => {
cleanup()
resolve()
}
const onError = (error: Error) => {
child.removeListener("exit", onExit)
cleanup()
reject(error)
}
const resolveIfAlreadyExited = () => {
if (child.exitCode !== null || child.signalCode !== null) {
this.logger.debug({ workspaceId, exitCode: child.exitCode, signal: child.signalCode }, "Process already exited")
cleanup()
resolve()
return true
}
return false
}
child.once("exit", onExit)
child.once("error", onError)
if (resolveIfAlreadyExited()) {
return
}
this.logger.debug({ workspaceId }, "Sending SIGTERM to workspace process")
child.kill("SIGTERM")
setTimeout(() => {
if (!child.killed) {
this.logger.warn({ workspaceId }, "Process did not stop after SIGTERM, force killing")
child.kill("SIGKILL")
} else {
this.logger.debug({ workspaceId }, "Workspace process stopped gracefully before SIGKILL timeout")
}
}, 2000)
})

View File

@@ -8,7 +8,7 @@ import type {
FileSystemEntry,
InstanceData,
ServerMeta,
WorkspaceCreateRequest,
WorkspaceDescriptor,
WorkspaceFileResponse,
@@ -21,6 +21,15 @@ const DEFAULT_BASE = typeof window !== "undefined" ? window.__CODENOMAD_API_BASE
const DEFAULT_EVENTS_URL = typeof window !== "undefined" ? window.__CODENOMAD_EVENTS_URL__ ?? "/api/events" : "/api/events"
const API_BASE = import.meta.env.VITE_CODENOMAD_API_BASE ?? DEFAULT_BASE
const EVENTS_URL = API_BASE ? `${API_BASE}${DEFAULT_EVENTS_URL}` : DEFAULT_EVENTS_URL
const HTTP_PREFIX = "[HTTP]"
function logHttp(message: string, context?: Record<string, unknown>) {
if (context) {
console.log(`${HTTP_PREFIX} ${message}`, context)
return
}
console.log(`${HTTP_PREFIX} ${message}`)
}
async function request<T>(path: string, init?: RequestInit): Promise<T> {
const url = API_BASE ? new URL(path, API_BASE).toString() : path
@@ -29,17 +38,30 @@ async function request<T>(path: string, init?: RequestInit): Promise<T> {
...(init?.headers ?? {}),
}
const response = await fetch(url, { ...init, headers })
if (!response.ok) {
const message = await response.text()
throw new Error(message || `Request failed with ${response.status}`)
const method = (init?.method ?? "GET").toUpperCase()
const startedAt = Date.now()
logHttp(`${method} ${path}`)
try {
const response = await fetch(url, { ...init, headers })
if (!response.ok) {
const message = await response.text()
logHttp(`${method} ${path} -> ${response.status}`, { durationMs: Date.now() - startedAt, error: message })
throw new Error(message || `Request failed with ${response.status}`)
}
const duration = Date.now() - startedAt
logHttp(`${method} ${path} -> ${response.status}`, { durationMs: duration })
if (response.status === 204) {
return undefined as T
}
return (await response.json()) as T
} catch (error) {
logHttp(`${method} ${path} failed`, { durationMs: Date.now() - startedAt, error })
throw error
}
if (response.status === 204) {
return undefined as T
}
return (await response.json()) as T
}
export const cliApi = {
fetchWorkspaces(): Promise<WorkspaceDescriptor[]> {
return request<WorkspaceDescriptor[]>("/api/workspaces")
@@ -124,16 +146,18 @@ export const cliApi = {
return request(`/api/storage/instances/${encodeURIComponent(id)}`, { method: "DELETE" })
},
connectEvents(onEvent: (event: WorkspaceEventPayload) => void, onError?: () => void) {
console.log(`[SSE] Connecting to ${EVENTS_URL}`)
const source = new EventSource(EVENTS_URL)
source.onmessage = (event) => {
try {
const payload = JSON.parse(event.data) as WorkspaceEventPayload
onEvent(payload)
} catch (error) {
console.error("Failed to parse SSE event", error)
console.error("[SSE] Failed to parse event", error)
}
}
source.onerror = () => {
console.warn("[SSE] EventSource error, closing stream")
onError?.()
}
return source

View File

@@ -3,6 +3,15 @@ import { cliApi } from "./api-client"
const RETRY_BASE_DELAY = 1000
const RETRY_MAX_DELAY = 10000
const SSE_PREFIX = "[SSE]"
function logSse(message: string, context?: Record<string, unknown>) {
if (context) {
console.log(`${SSE_PREFIX} ${message}`, context)
return
}
console.log(`${SSE_PREFIX} ${message}`)
}
class CliEvents {
private handlers = new Map<WorkspaceEventType | "*", Set<(event: WorkspaceEventPayload) => void>>()
@@ -17,8 +26,10 @@ class CliEvents {
if (this.source) {
this.source.close()
}
logSse("Connecting to backend events stream")
this.source = cliApi.connectEvents((event) => this.dispatch(event), () => this.scheduleReconnect())
this.source.onopen = () => {
logSse("Events stream connected")
this.retryDelay = RETRY_BASE_DELAY
}
}
@@ -28,6 +39,7 @@ class CliEvents {
this.source.close()
this.source = null
}
logSse("Events stream disconnected, scheduling reconnect", { delayMs: this.retryDelay })
setTimeout(() => {
this.retryDelay = Math.min(this.retryDelay * 2, RETRY_MAX_DELAY)
this.connect()
@@ -35,6 +47,7 @@ class CliEvents {
}
private dispatch(event: WorkspaceEventPayload) {
logSse(`event ${event.type}`)
this.handlers.get("*")?.forEach((handler) => handler(event))
this.handlers.get(event.type)?.forEach((handler) => handler(event))
}