Skip to content

add verbose logging #160

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Draft
wants to merge 1 commit into
base: main
Choose a base branch
from
Draft

add verbose logging #160

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
67 changes: 56 additions & 11 deletions src/API.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -56,6 +56,17 @@ import type {
} from "./api-clients/client";
import { PitcherManagerResponse } from "./types";

function generateTraceParent(): string {
// Generate W3C Trace Context traceparent header
// Format: version-trace-id-span-id-trace-flags
const version = '00'; // Current version is 00
const traceId = Array.from({length: 32}, () => Math.floor(Math.random() * 16).toString(16)).join(''); // 128-bit (32 hex chars)
const spanId = Array.from({length: 16}, () => Math.floor(Math.random() * 16).toString(16)).join(''); // 64-bit (16 hex chars)
const traceFlags = '01'; // Sampled flag set to 1

return `${version}-${traceId}-${spanId}-${traceFlags}`;
}

async function enhanceFetch(
request: Request,
instrumentation?: (request: Request) => Promise<Response>
Expand All @@ -73,18 +84,52 @@ async function enhanceFetch(
}`.trim()
);

// Add W3C Trace Context traceparent header for OpenTelemetry correlation
const traceparent = generateTraceParent();
headers.set("traceparent", traceparent);

const enhancedRequest = new Request(request, { headers });

// Log API request details
const requestTimestamp = new Date().toISOString();
console.log(`[${requestTimestamp}] [API REQUEST] ${request.method} ${request.url} traceparent=${traceparent}`);

const startTime = Date.now();

// Create new request with updated headers and optionally add instrumentation
return instrumentation
? instrumentation(
new Request(request, {
headers,
})
)
: fetch(
new Request(request, {
headers,
})
);
const response = instrumentation
? await instrumentation(enhancedRequest)
: await fetch(enhancedRequest);

const duration = Date.now() - startTime;

// Log API response details
const responseTimestamp = new Date().toISOString();
let logMessage = `[${responseTimestamp}] [API RESPONSE] ${response.status} ${response.statusText} (${duration}ms) ${request.method} ${request.url} traceparent=${traceparent}`;

// Add error message for non-success responses
if (!response.ok) {
try {
const responseClone = response.clone();
const responseText = await responseClone.text();
if (responseText) {
// Try to parse as JSON to get error message, fallback to text
try {
const errorData = JSON.parse(responseText);
const errorMessage = errorData.error || errorData.message || responseText;
logMessage += ` error="${errorMessage}"`;
} catch {
logMessage += ` error="${responseText.substring(0, 200)}"`;
}
}
} catch (e) {
logMessage += ` error="[Unable to read error - ${e instanceof Error ? e.message : String(e)}]"`;
}
}

console.log(logMessage);

return response;
}

function createApiClient(
Expand Down
39 changes: 39 additions & 0 deletions src/bin/commands/build.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,11 @@ import { hashDirectory as getFilePaths } from "../utils/files";
import { mkdir, writeFile } from "fs/promises";
import { sleep } from "../../utils/sleep";

function logWithTimestamp(message: string) {
const timestamp = new Date().toISOString();
console.log(`\t[${timestamp}] ${message}`);
}

export type BuildCommandArgs = {
directory: string;
name?: string;
Expand Down Expand Up @@ -120,12 +125,15 @@ export const buildCommand: yargs.CommandModule<
const filePaths = await getFilePaths(argv.directory);

try {
logWithTimestamp(`[BUILD] Creating template with title: ${argv.name || 'undefined'}`);
logWithTimestamp(`[BUILD] Fork from: ${argv.fromSandbox || getDefaultTemplateId(api.getClient())}`);
const templateData = await api.createTemplate({
forkOf: argv.fromSandbox || getDefaultTemplateId(api.getClient()),
title: argv.name,
// We filter out sdk-templates on the dashboard
tags: ["sdk-template"],
});
logWithTimestamp(`[BUILD] Template created successfully with tag: ${templateData.tag}`);

const spinner = ora({ stream: process.stdout });
let spinnerMessages: string[] = templateData.sandboxes.map(() => "");
Expand Down Expand Up @@ -216,16 +224,22 @@ export const buildCommand: yargs.CommandModule<

const tasks = templateData.sandboxes.map(async ({ id }, index) => {
try {
logWithTimestamp(`[BUILD] Processing sandbox ${id} (index: ${index})`);
spinner.start(updateSpinnerMessage(index, "Starting sandbox..."));

logWithTimestamp(`[BUILD] Starting VM ${id} with retry delay 200ms`);
const startResponse = await withCustomError(
api.startVm(id, { retryDelay: 200 }),
"Failed to start sandbox at all"
);
logWithTimestamp(`[BUILD] VM ${id} started successfully`);
let sandboxVM = new Sandbox(id, api, startResponse);

logWithTimestamp(`[BUILD] Connecting to sandbox ${id}`);
let session = await sandboxVM.connect();
logWithTimestamp(`[BUILD] Connected to sandbox ${id}`);

logWithTimestamp(`[BUILD] Writing ${filePaths.length} files to sandbox ${id}`);
spinner.start(
updateSpinnerMessage(index, "Writing files to sandbox...")
);
Expand All @@ -248,9 +262,12 @@ export const buildCommand: yargs.CommandModule<
)
)
).catch((error) => {
logWithTimestamp(`[BUILD] Failed to write files to sandbox ${id}: ${error}`);
throw new Error(`Failed to write files to sandbox: ${error}`);
});
logWithTimestamp(`[BUILD] Files written successfully to sandbox ${id}`);

logWithTimestamp(`[BUILD] Restarting sandbox ${id} for building with tier ${buildTier.name}`);
spinner.start(updateSpinnerMessage(index, "Building sandbox..."));

sandboxVM = await withCustomError(
Expand All @@ -259,14 +276,20 @@ export const buildCommand: yargs.CommandModule<
}),
"Failed to restart sandbox after building"
);
logWithTimestamp(`[BUILD] Sandbox ${id} restarted for building`);

logWithTimestamp(`[BUILD] Reconnecting to sandbox ${id} after restart`);
session = await withCustomError(
sandboxVM.connect(),
"Failed to connect to sandbox after building"
);
logWithTimestamp(`[BUILD] Reconnected to sandbox ${id}`);

logWithTimestamp(`[BUILD] Waiting for setup completion on sandbox ${id}`);
await waitForSetup(session, index);
logWithTimestamp(`[BUILD] Setup completed for sandbox ${id}`);

logWithTimestamp(`[BUILD] Optimizing initial state for sandbox ${id} with tier ${sandboxTier.name}`);
spinner.start(
updateSpinnerMessage(index, "Optimizing initial state...")
);
Expand All @@ -276,13 +299,18 @@ export const buildCommand: yargs.CommandModule<
}),
"Failed to restart sandbox after optimizing initial state"
);
logWithTimestamp(`[BUILD] Sandbox ${id} restarted for optimization`);

logWithTimestamp(`[BUILD] Reconnecting to sandbox ${id} after optimization restart`);
session = await withCustomError(
sandboxVM.connect(),
"Failed to connect to sandbox after optimizing initial state"
);
logWithTimestamp(`[BUILD] Reconnected to sandbox ${id} after optimization`);

logWithTimestamp(`[BUILD] Waiting for setup completion after optimization on sandbox ${id}`);
await waitForSetup(session, index);
logWithTimestamp(`[BUILD] Optimization setup completed for sandbox ${id}`);

const ports = argv.ports || [];
const updatePortSpinner = () => {
Expand All @@ -298,42 +326,53 @@ export const buildCommand: yargs.CommandModule<
};

if (ports.length > 0) {
logWithTimestamp(`[BUILD] Waiting for ports ${ports.join(', ')} to open on sandbox ${id}`);
updatePortSpinner();

await Promise.all(
ports.map(async (port) => {
logWithTimestamp(`[BUILD] Waiting for port ${port} on sandbox ${id}`);
const portInfo = await session.ports.waitForPort(port, {
timeoutMs: 60000,
});
logWithTimestamp(`[BUILD] Port ${port} opened on sandbox ${id} with host: ${portInfo.host}`);

logWithTimestamp(`[BUILD] Testing port ${port} health on sandbox ${id}`);
// eslint-disable-next-line no-constant-condition
while (true) {
const res = await fetch("https://" + portInfo.host);
logWithTimestamp(`[BUILD] Port ${port} health check: ${res.status} ${res.statusText} on sandbox ${id}`);
if (res.status !== 502 && res.status !== 503) {
break;
}

await sleep(1000);
}
logWithTimestamp(`[BUILD] Port ${port} is healthy on sandbox ${id}`);

updatePortSpinner();
})
);
logWithTimestamp(`[BUILD] All ports are ready on sandbox ${id}`);
} else {
logWithTimestamp(`[BUILD] No ports specified, waiting 5 seconds for tasks to run on sandbox ${id}`);
spinner.start(
updateSpinnerMessage(
index,
"No ports to open, waiting 5 seconds for tasks to run..."
)
);
await new Promise((resolve) => setTimeout(resolve, 5000));
logWithTimestamp(`[BUILD] Wait period completed for sandbox ${id}`);
}

logWithTimestamp(`[BUILD] Creating snapshot for sandbox ${id}`);
spinner.start(updateSpinnerMessage(index, "Creating snapshot..."));
await withCustomError(
sdk.sandboxes.hibernate(id),
"Failed to hibernate after building and optimizing sandbox"
);
logWithTimestamp(`[BUILD] Snapshot created successfully for sandbox ${id}`);
spinner.start(updateSpinnerMessage(index, "Snapshot created"));

return id;
Expand Down
20 changes: 18 additions & 2 deletions src/utils/api.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -101,16 +101,32 @@ export async function retryWithDelay<T>(
): Promise<T> {
let lastError: Error;

const startTimestamp = new Date().toISOString();
console.log(`\t[${startTimestamp}] [RETRY] Starting operation with ${retries} max retries, ${delay}ms delay`);

for (let attempt = 1; attempt <= retries; attempt++) {
try {
return await callback();
const attemptTimestamp = new Date().toISOString();
console.log(`\t[${attemptTimestamp}] [RETRY] Attempt ${attempt}/${retries}`);
const startTime = Date.now();
const result = await callback();
const duration = Date.now() - startTime;
const successTimestamp = new Date().toISOString();
console.log(`\t[${successTimestamp}] [RETRY] Attempt ${attempt}/${retries} succeeded (${duration}ms)`);
return result;
} catch (error) {
lastError = error as Error;

const failTimestamp = new Date().toISOString();
console.log(`\t[${failTimestamp}] [RETRY] Attempt ${attempt}/${retries} failed: ${lastError.message}`);

if (attempt === retries) {
const finalFailTimestamp = new Date().toISOString();
console.log(`\t[${finalFailTimestamp}] [RETRY] All ${retries} attempts failed. Final error: ${lastError.message}`);
throw lastError;
}

const waitTimestamp = new Date().toISOString();
console.log(`\t[${waitTimestamp}] [RETRY] Waiting ${delay}ms before retry ${attempt + 1}/${retries}`);
await new Promise((resolve) => setTimeout(resolve, delay));
}
}
Expand Down