Feature

package.json

@@ -25,6 +25,8 @@
     "fs": "^0.0.1-security",
     "multer": "^2.1.1",
     "p-queue": "^9.2.0",
+    "pino": "^10.3.1",
+    "pino-http": "^11.0.0",
     "unzipper": "^0.12.3"
   },
   "devDependencies": {

src/app.ts

@@ -1,8 +1,13 @@
 import express from "express";
+import pinoHttp from "pino-http";
 import { deployRouter } from "./routes/deploy.js";
 import { invokeRouter } from "./routes/invoke.js";
+import { httpLoggerOptions } from "./utils/logger.js";
 
 export const app = express();
+
+// @ts-expect-error
+app.use(pinoHttp(httpLoggerOptions));
 app.use(express.json());
 app.use("/deploy", deployRouter);
 app.use("/f", invokeRouter);

src/deploy/firecracker.ts

@@ -2,14 +2,36 @@ import { spawn } from "child_process";
 import fs from "fs";
 import axios from "axios";
 import path from "path";
+import { firecrackerLogger } from "../utils/logger.js";
 
 export async function startFirecrackerProcess(apiSock: string) {
+  firecrackerLogger.debug({ apiSock }, "spawning firecracker process");
+
   const fc = spawn("firecracker", ["--api-sock", apiSock]);
 
-  fc.on("error", console.error);
-  fc.stderr.on("data", (d) => console.error(d.toString()));
+  fc.on("error", (err) => {
+    firecrackerLogger.error(
+      { err, apiSock },
+      "firecracker process error",
+    );
+  });
+
+  fc.stderr.on("data", (d) => {
+    firecrackerLogger.warn(
+      { apiSock, stderr: d.toString().trim() },
+      "firecracker stderr output",
+    );
+  });
+
+  fc.on("exit", (code, signal) => {
+    firecrackerLogger.info(
+      { apiSock, exitCode: code, signal },
+      "firecracker process exited",
+    );
+  });
 
   await waitForFile(apiSock, 5000);
+  firecrackerLogger.debug({ apiSock }, "firecracker API socket ready");
 
   return fc;
 }
@@ -21,6 +43,10 @@ export async function waitForFile(path: any, timeout = 5000) {
     if (fs.existsSync(path)) return;
 
     if (Date.now() - start > timeout) {
+      firecrackerLogger.error(
+        { path, timeoutMs: timeout },
+        "timeout waiting for file",
+      );
       throw new Error("timeout waiting for socket");
     }
 
@@ -43,28 +69,36 @@ export async function configureVM(
   functionId: string,
   image: string,
 ) {
+  firecrackerLogger.debug({ functionId }, "configuring VM");
+
   await client.put("/machine-config", {
     vcpu_count: 1,
     mem_size_mib: 128,
   });
+  firecrackerLogger.debug({ functionId, vcpu: 1, memMib: 128 }, "machine config set");
 
   await client.put("/boot-source", {
     kernel_image_path: path.resolve("vmlinux"),
     boot_args: "console=ttyS0 reboot=k panic=1 pci=off init=/init -- /start.sh",
   });
+  firecrackerLogger.debug({ functionId }, "boot source configured");
 
   await client.put("/drives/rootfs", {
     drive_id: "rootfs",
     path_on_host: image,
     is_root_device: true,
     is_read_only: false,
   });
+  firecrackerLogger.debug({ functionId, image }, "rootfs drive attached");
 
+  const guestCid = Math.floor(Math.random() * 10000) + 3;
+  const vsockPath = `/tmp/vsock-${functionId}.sock`;
   await client.put("/vsock", {
     vsock_id: "vsock0",
-    guest_cid: Math.floor(Math.random() * 10000) + 3,
-    uds_path: `/tmp/vsock-${functionId}.sock`,
+    guest_cid: guestCid,
+    uds_path: vsockPath,
   });
+  firecrackerLogger.debug({ functionId, guestCid, vsockPath }, "vsock configured");
 
   await client.put("/logger", {
     log_path: `firecracker.log`,
@@ -75,13 +109,15 @@ export async function configureVM(
   await client.put("/actions", {
     action_type: "InstanceStart",
   });
+  firecrackerLogger.info({ functionId }, "VM instance started");
 }
 
 export function waitForVMReady(fc: any) {
   return new Promise<void>((resolve, reject) => {
     let buffer = "";
 
     const timeout = setTimeout(() => {
+      firecrackerLogger.error("VM startup timeout — READY signal not received within 50s");
       reject(new Error("VM startup timeout"));
     }, 50000);
 
@@ -90,26 +126,49 @@ export function waitForVMReady(fc: any) {
 
       if (buffer.includes("READY")) {
         clearTimeout(timeout);
+        firecrackerLogger.debug("VM READY signal received");
         setTimeout(resolve, 200);
       }
     });
   });
 }
 
 export async function snapshotVM(client: any, functionId: string) {
+  firecrackerLogger.debug({ functionId }, "pausing VM for snapshot");
   await client.patch("/vm", { state: "Paused" });
 
+  const snapshotPath = path.resolve(`snapshot/snapshot-${functionId}`);
+  const memPath = path.resolve(`mem/mem-${functionId}`);
+
   await client.put("/snapshot/create", {
     snapshot_type: "Full",
-    snapshot_path: path.resolve(`snapshot/snapshot-${functionId}`),
-    mem_file_path: path.resolve(`mem/mem-${functionId}`),
+    snapshot_path: snapshotPath,
+    mem_file_path: memPath,
   });
+
+  firecrackerLogger.info(
+    { functionId, snapshotPath, memPath },
+    "VM snapshot created",
+  );
 }
 
 export async function cleanupResources(paths: any) {
-  await Promise.allSettled([
+  firecrackerLogger.debug(
+    { outputDir: paths.outputDir, apiSock: paths.apiSock, vsock: paths.vsock },
+    "cleaning up deployment resources",
+  );
+
+  const results = await Promise.allSettled([
     fs.promises.rm(paths.outputDir, { recursive: true, force: true }),
     fs.promises.rm(paths.apiSock),
     fs.promises.rm(paths.vsock),
   ]);
+
+  const failed = results.filter((r) => r.status === "rejected");
+  if (failed.length > 0) {
+    firecrackerLogger.warn(
+      { failedCount: failed.length, errors: failed.map((r: any) => r.reason?.message) },
+      "some cleanup operations failed (non-critical)",
+    );
+  }
 }

src/deploy/pipeline.ts

@@ -10,51 +10,114 @@ import {
 import fs from "fs";
 import crypto from "crypto";
 import { getPaths } from "../utils/path.js";
+import { pipelineLogger } from "../utils/logger.js";
 
 export async function deployFunction(zipPath: string) {
   const functionId = crypto.randomBytes(8).toString("hex");
   const paths = getPaths(functionId);
   let fc: ReturnType<typeof startFirecrackerProcess> extends Promise<infer T> ? T : never;
 
+  pipelineLogger.info(
+    { functionId, zipPath },
+    "starting deployment pipeline",
+  );
+
   try {
+    // ── Stage 1: Extract zip ──────────────────────────────────────
     const t0 = performance.now();
     await extractZip(zipPath, paths.outputDir);
-    console.log("extract:", performance.now() - t0);
+    const extractDuration = performance.now() - t0;
+    pipelineLogger.info(
+      { functionId, stage: "extract", durationMs: extractDuration },
+      "zip extraction completed",
+    );
     await fs.promises.unlink(zipPath);
 
+    // ── Stage 2: Prepare rootfs ───────────────────────────────────
     const t1 = performance.now();
     const image = await prepareRootfs(functionId);
-    console.log("rootfs:", performance.now() - t1);
+    const rootfsDuration = performance.now() - t1;
+    pipelineLogger.info(
+      { functionId, stage: "rootfs", durationMs: rootfsDuration, image },
+      "rootfs preparation completed",
+    );
 
+    // ── Stage 3: Spawn Firecracker ────────────────────────────────
     const t2 = performance.now();
     fc = await startFirecrackerProcess(paths.apiSock);
-    console.log("fc spawn:", performance.now() - t2);
+    const spawnDuration = performance.now() - t2;
+    pipelineLogger.info(
+      { functionId, stage: "fc-spawn", durationMs: spawnDuration },
+      "firecracker process spawned",
+    );
 
+    // ── Stage 4: Configure VM ─────────────────────────────────────
     const t3 = performance.now();
     const readyPromise = waitForVMReady(fc);
     const client = createFcCient(paths.apiSock);
 
     const t4 = performance.now();
     await configureVM(client, functionId, image);
-    console.log("configure Vm: ", performance.now() - t4);
+    const configureDuration = performance.now() - t4;
+    pipelineLogger.info(
+      { functionId, stage: "configure-vm", durationMs: configureDuration },
+      "VM configured",
+    );
 
+    // ── Stage 5: Wait for VM ready ────────────────────────────────
     await readyPromise;
-    console.log("wait for vmReady: ", performance.now() - t3);
+    const readyDuration = performance.now() - t3;
+    pipelineLogger.info(
+      { functionId, stage: "vm-ready", durationMs: readyDuration },
+      "VM reported READY",
+    );
 
+    // ── Stage 6: Snapshot ─────────────────────────────────────────
     const t5 = performance.now();
     await snapshotVM(client, functionId);
-    console.log("snapshot time: ", performance.now() - t5);
+    const snapshotDuration = performance.now() - t5;
+    pipelineLogger.info(
+      { functionId, stage: "snapshot", durationMs: snapshotDuration },
+      "VM snapshot created",
+    );
+
+    const totalDuration = performance.now() - t0;
+    pipelineLogger.info(
+      {
+        functionId,
+        stage: "complete",
+        totalDurationMs: totalDuration,
+        stages: {
+          extractMs: extractDuration,
+          rootfsMs: rootfsDuration,
+          spawnMs: spawnDuration,
+          configureMs: configureDuration,
+          readyMs: readyDuration,
+          snapshotMs: snapshotDuration,
+        },
+      },
+      "deployment pipeline completed successfully",
+    );
 
     return {
       functionId,
       url: `http://localhost:3000/f/${functionId}`,
     };
+  } catch (err) {
+    pipelineLogger.error(
+      { functionId, err },
+      "deployment pipeline failed",
+    );
+    throw err;
   } finally {
     // Always kill the FC process — whether deploy succeeded or failed
     try { fc!?.kill("SIGKILL"); } catch { }
 
     const t6 = performance.now();
     await cleanupResources(paths);
-    console.log("cleanupResources: ", performance.now() - t6);
+    pipelineLogger.debug(
+      { functionId, stage: "cleanup", durationMs: performance.now() - t6 },
+      "post-deploy cleanup completed",
+    );
   }
 }

src/deploy/rootfs.ts

@@ -1,36 +1,49 @@
 import extract from "extract-zip";
 import { exec as execCb, spawn } from "child_process";
 import { promisify } from "util";
+import { rootfsLogger } from "../utils/logger.js";
 
 const exec = promisify(execCb);
 
 export async function extractZip(zip: string, outputDir: string) {
+  rootfsLogger.debug({ zip, outputDir }, "extracting zip archive");
+
   await extract(zip, {
     dir: outputDir,
     onEntry: (entry) => {
       if (entry.fileName.includes("..")) {
+        rootfsLogger.error(
+          { fileName: entry.fileName },
+          "path traversal detected in zip — aborting",
+        );
         throw new Error("Invalid zip content");
       }
     },
   });
+
+  rootfsLogger.debug({ zip, outputDir }, "zip extraction completed");
 }
 
 export async function prepareRootfs(functionId: string) {
   const baseImage = "rootfs.ext4";
   const image = `rootfs/rootfs-${functionId}.ext4`;
 
+  rootfsLogger.debug({ functionId, baseImage, image }, "copying base rootfs image");
   await exec(`cp --reflink=auto ${baseImage} ${image}`);
 
   const mountDir = `/mnt/rootfs-${functionId}`;
   const extracted = `extracted/${functionId}`;
 
   await exec(`sudo mkdir -p ${mountDir}`);
+  rootfsLogger.debug({ functionId, mountDir, image }, "mounting rootfs image");
   await exec(`sudo mount -o loop ${image} ${mountDir}`);
 
+  rootfsLogger.debug({ functionId, from: extracted, to: `${mountDir}/app/` }, "copying user code into rootfs");
   await exec(`sudo cp -r ${extracted}/. ${mountDir}/app/`);
 
   await exec(`sudo umount ${mountDir}`);
   await exec(`sudo rm -rf ${mountDir}`);
+  rootfsLogger.debug({ functionId, image }, "rootfs prepared and unmounted");
 
   return image;
 }