Add basic logging

This commit is contained in:
2026-04-22 12:47:17 +05:30
parent 204b12d5f7
commit 9578502bca
17 changed files with 1385 additions and 238 deletions
+65 -11
View File
@@ -9,6 +9,8 @@ import { spawn } from "node:child_process";
import path from "node:path";
import { fileURLToPath } from "node:url";
import { z } from "zod";
import { LogOperation, logger } from "../lib/logger.js";
import { withSpan } from "../lib/tracing.js";
// #region Zod schemas (not exported)
@@ -232,17 +234,69 @@ export function createEvaluateInEngine262Tool(
timeoutMs = DEFAULT_EXECUTION_TIMEOUT_MS,
) {
return async ({ code }: EvaluateToolInput): Promise<EvaluateToolOutput> => {
try {
// Execute code in isolated child process
const resultJson = await executeInChildProcess(code, timeoutMs);
const log = await logger.forComponent("engine262-runner");
// Parse the result
return JSON.parse(resultJson) as EvaluateToolOutput;
} catch (error) {
// Return error result
return {
error: error instanceof Error ? error.message : String(error),
};
}
log.info(LogOperation.EVALUATE_IN_ENGINE262, { code_length: code.length });
// Truncate code for logging if too long (>500 chars)
const codeForLog =
code.length > 500
? `${code.substring(0, 500)}... (${code.length - 500} more chars)`
: code;
// Only the main evaluating_in_engine262 span logs the full code
return await withSpan(
LogOperation.EVALUATING_IN_ENGINE262,
{ code: codeForLog, code_length: code.length, timeout_ms: timeoutMs },
async () => {
const op = log.start(LogOperation.EVALUATING_IN_ENGINE262, {
code: codeForLog,
code_length: code.length,
timeout_ms: timeoutMs,
});
try {
// Child operations don't need to log the code - it's in the parent span context
log.debug(LogOperation.SPAWNING_CHILD_PROCESS, {
timeout_ms: timeoutMs,
});
// Execute code in isolated child process
const resultJson = await executeInChildProcess(code, timeoutMs);
// Parse the result
const result = JSON.parse(resultJson) as EvaluateToolOutput;
if ("error" in result && result.error) {
log.warn(LogOperation.ENGINE262_ABRUPT_COMPLETION, {
error: result.error,
});
op.end({ status: "error", error: result.error });
} else {
const successResult = result as EvaluateSuccessOutput;
// op.end logs the final completion with all metrics and duration
op.end({
status: "success",
important_sections: successResult.importantSections.length,
other_sections: successResult.otherSections.length,
console_entries: successResult.consoleOutput.length,
});
}
return result;
} catch (err) {
const error = err instanceof Error ? err : new Error(String(err));
log.error(
LogOperation.EVALUATING_IN_ENGINE262,
{ code_length: code.length },
error,
);
op.end({ status: "exception", error: error.message });
return {
error: error.message,
};
}
},
);
};
}
+129 -87
View File
@@ -5,6 +5,8 @@
import type { Table } from "@lancedb/lancedb";
import { z } from "zod";
import { LogOperation, logger } from "../lib/logger.js";
import { withSpan } from "../lib/tracing.js";
// #region Zod schemas (not exported)
@@ -21,6 +23,8 @@ const sectionDataSchema = z.object({
error: z.string().optional(),
sectionTitle: z.string().optional(),
childrensectionids: z.array(z.string()).optional(),
partIndex: z.number().optional(),
totalParts: z.number().optional(),
});
const getSectionContentOutputSchema = z.object({
@@ -81,95 +85,133 @@ export function createGetSectionContentTool(table: Table) {
sectionIds,
recursive,
}: GetSectionContentInput): Promise<GetSectionContentOutput> => {
const sectionsData = new Map<
string,
{
content: string[];
title?: string;
childrenSectionIds?: string[];
}
>();
const queue: string[] = [...sectionIds];
const visited = new Set<string>();
const log = await logger.forComponent("get-section-tool");
while (queue.length > 0) {
const currentId = queue.shift();
if (!currentId || visited.has(currentId)) continue;
visited.add(currentId);
const results = await table
.query()
.where(`sectionid = '${currentId}'`)
.limit(10)
.toArray();
// Sort by partindex to maintain order (nulls last for single-part sections)
const sortedResults = results.sort((a: unknown, b: unknown) => {
const aIndex = (a as { partindex?: number }).partindex ?? Infinity;
const bIndex = (b as { partindex?: number }).partindex ?? Infinity;
return aIndex - bIndex;
});
for (const result of sortedResults) {
const typedResult = result as {
text?: string;
childrensectionids?: unknown;
sectiontitle?: string;
partindex?: number;
totalparts?: number;
};
// Normalize childrensectionids: LanceDB may return an Apache Arrow Vector
// which is iterable but not a plain JS array.
const childrenIds = typedResult.childrensectionids
? Array.from(typedResult.childrensectionids as Iterable<string>)
: undefined;
// Get or create section data
let section = sectionsData.get(currentId);
if (!section) {
section = {
content: [],
title: typedResult.sectiontitle,
childrenSectionIds: childrenIds,
};
sectionsData.set(currentId, section);
}
if (typedResult.text) {
section.content.push(typedResult.text);
}
// Add children to queue for recursive fetching only if recursive is true
if (recursive && childrenIds && childrenIds.length > 0) {
queue.push(...childrenIds);
}
}
}
// Build output array from all requested sections
// Missing sections are included with found: false and error message
const sections = sectionIds.map((id) => {
const data = sectionsData.get(id);
if (data) {
return {
sectionId: id,
content: data.content.join("\n\n"),
found: true,
sectionTitle: data.title,
childrensectionids: data.childrenSectionIds,
};
}
return {
sectionId: id,
content: "",
found: false,
error: `Section '${id}' not found in database`,
};
log.info(LogOperation.GET_SECTION_CONTENT, {
section_count: sectionIds.length,
recursive,
});
return {
sections,
};
return await withSpan(
LogOperation.FETCHING_SECTION_CONTENT,
{ section_count: sectionIds.length, recursive },
async () => {
const op = log.start(LogOperation.FETCHING_SECTION_CONTENT, {
section_ids: sectionIds,
recursive,
});
const sectionsData = new Map<
string,
{
content: string[];
title?: string;
childrenSectionIds?: string[];
}
>();
const queue: string[] = [...sectionIds];
const visited = new Set<string>();
try {
while (queue.length > 0) {
const currentId = queue.shift();
if (!currentId || visited.has(currentId)) continue;
visited.add(currentId);
const results = await table
.query()
.where(`sectionid = '${currentId}'`)
.limit(10)
.toArray();
// Sort by partindex to maintain order (nulls last for single-part sections)
const sortedResults = results.sort((a: unknown, b: unknown) => {
const aIndex = (a as { partindex?: number }).partindex ?? Infinity;
const bIndex = (b as { partindex?: number }).partindex ?? Infinity;
return aIndex - bIndex;
});
for (const result of sortedResults) {
const typedResult = result as {
text?: string;
childrensectionids?: unknown;
sectiontitle?: string;
partindex?: number;
totalparts?: number;
};
// Normalize childrensectionids: LanceDB may return an Apache Arrow Vector
// which is iterable but not a plain JS array.
const childrenIds = typedResult.childrensectionids
? Array.from(typedResult.childrensectionids as Iterable<string>)
: undefined;
// Get or create section data
let section = sectionsData.get(currentId);
if (!section) {
section = {
content: [],
title: typedResult.sectiontitle,
childrenSectionIds: childrenIds,
};
sectionsData.set(currentId, section);
}
if (typedResult.text) {
section.content.push(typedResult.text);
}
// Add children to queue for recursive fetching only if recursive is true
if (recursive && childrenIds && childrenIds.length > 0) {
queue.push(...childrenIds);
}
}
}
// Build output array from all requested sections
// Missing sections are included with found: false and error message
const sections = sectionIds.map((id) => {
const data = sectionsData.get(id);
if (data) {
return {
sectionId: id,
content: data.content.join("\n\n"),
found: true,
sectionTitle: data.title,
childrensectionids: data.childrenSectionIds,
};
}
return {
sectionId: id,
content: "",
found: false,
error: `Section '${id}' not found in database`,
};
});
const totalSectionsFetched = sectionsData.size;
const totalContentLength = sections.reduce(
(sum, s) => sum + s.content.length,
0,
);
op.end({
total_sections: totalSectionsFetched,
total_content_length: totalContentLength,
recursive,
});
return { sections };
} catch (err) {
const error = err instanceof Error ? err : new Error(String(err));
log.error(
LogOperation.FETCHING_SECTION_CONTENT,
{ section_ids: sectionIds },
error,
);
throw err;
}
},
);
};
}
+59 -22
View File
@@ -6,6 +6,8 @@
import { DynamicStructuredTool } from "@langchain/core/tools";
import type Graph from "graphology";
import { z } from "zod";
import { LogOperation, logger } from "../lib/logger.js";
import { withSpan } from "../lib/tracing.js";
const graphExplorerSchema = z.object({
query: z
@@ -27,33 +29,68 @@ export function createGraphExplorerTool(graph: Graph) {
"Explores structural relationships between specification sections and implementation code (functions). Use this to find which spec section a function implements.",
schema: graphExplorerSchema,
func: async ({ query }) => {
let nodeId = query;
if (!graph.hasNode(nodeId)) {
if (graph.hasNode(`func-${query}`)) {
nodeId = `func-${query}`;
}
}
const log = await logger.forComponent("graph-explorer");
if (graph.hasNode(nodeId)) {
const neighbors = graph.neighbors(nodeId);
const nodeAttr = graph.getNodeAttributes(nodeId);
log.info(LogOperation.EXPLORING_GRAPH, { query });
let result = `Information for ${nodeId} (${nodeAttr.type}):\n`;
if (nodeAttr.title) result += `- Title: ${nodeAttr.title}\n`;
if (nodeAttr.file) result += `- File: ${nodeAttr.file}\n`;
result += `\nConnected parts:\n`;
return await withSpan(
LogOperation.EXPLORING_GRAPH,
{ query },
async () => {
const op = log.start(LogOperation.EXPLORING_GRAPH, { query });
neighbors.forEach((neighbor: string) => {
const attr = graph.getNodeAttributes(neighbor);
const edges = graph.edges(nodeId, neighbor);
const edgeAttr = graph.getEdgeAttributes(edges[0]);
result += `- ${neighbor} (${attr.type}) via ${edgeAttr.type}${attr.title ? `: ${attr.title}` : ""}\n`;
});
let nodeId = query;
if (!graph.hasNode(nodeId)) {
if (graph.hasNode(`func-${query}`)) {
nodeId = `func-${query}`;
log.debug(LogOperation.RESOLVING_NODE_ID, {
original: query,
resolved: nodeId,
});
}
}
return result;
}
if (graph.hasNode(nodeId)) {
const neighbors = graph.neighbors(nodeId);
const nodeAttr = graph.getNodeAttributes(nodeId);
return `No information found in graph for ${query}. Use ask262_search_spec_sections to search text.`;
log.debug(LogOperation.NODE_FOUND, {
node_id: nodeId,
type: nodeAttr.type,
neighbor_count: neighbors.length,
});
let result = `Information for ${nodeId} (${nodeAttr.type}):\n`;
if (nodeAttr.title) result += `- Title: ${nodeAttr.title}\n`;
if (nodeAttr.file) result += `- File: ${nodeAttr.file}\n`;
result += `\nConnected parts:\n`;
neighbors.forEach((neighbor: string) => {
const attr = graph.getNodeAttributes(neighbor);
const edges = graph.edges(nodeId, neighbor);
const edgeAttr = graph.getEdgeAttributes(edges[0]);
result += `- ${neighbor} (${attr.type}) via ${edgeAttr.type}${attr.title ? `: ${attr.title}` : ""}\n`;
});
op.end({
status: "found",
node_id: nodeId,
type: nodeAttr.type,
neighbor_count: neighbors.length,
});
return result;
}
log.warn(LogOperation.NODE_NOT_FOUND, {
query,
attempted_id: nodeId,
});
op.end({ status: "not_found", query });
return `No information found in graph for ${query}. Use ask262_search_spec_sections to search text.`;
},
);
},
});
}
+85 -38
View File
@@ -4,6 +4,8 @@
*/
import { RERANKER_MODEL } from "../constants.js";
import { LogOperation, logger } from "../lib/logger.js";
import { withSpan } from "../lib/tracing.js";
const OLLAMA_HOST = process.env.OLLAMA_HOST || "http://localhost:11434";
@@ -23,46 +25,91 @@ export async function rerankDocuments<T extends { pageContent: string }>(
query: string,
documents: T[],
): Promise<RerankResult<T>[]> {
try {
const response = await fetch(`${OLLAMA_HOST}/api/rerank`, {
method: "POST",
headers: { "Content-Type": "application/json" },
body: JSON.stringify({
const log = await logger.forComponent("reranker");
log.info(LogOperation.RERANKING_DOCUMENTS, {
document_count: documents.length,
});
return await withSpan(
LogOperation.RERANKING_DOCUMENTS,
{ document_count: documents.length },
async () => {
const op = log.start(LogOperation.RERANKING_DOCUMENTS, {
document_count: documents.length,
model: RERANKER_MODEL,
query: query,
documents: documents.map((d) => d.pageContent),
}),
});
});
if (!response.ok) {
console.warn(
`Reranker API failed: ${response.statusText}. Returning all documents.`,
);
return documents.map((doc, i) => ({
document: doc,
score: 1.0,
index: i,
}));
}
try {
const response = await fetch(`${OLLAMA_HOST}/api/rerank`, {
method: "POST",
headers: { "Content-Type": "application/json" },
body: JSON.stringify({
model: RERANKER_MODEL,
query: query,
documents: documents.map((d) => d.pageContent),
}),
});
const data = await response.json();
if (!data.results || !Array.isArray(data.results)) {
return documents.map((doc, i) => ({
document: doc,
score: 1.0,
index: i,
}));
}
if (!response.ok) {
log.warn("reranker_api_failed", {
status: response.status,
statusText: response.statusText,
});
op.end({
status: "api_failed",
fallback: true,
document_count: documents.length,
});
return documents.map((doc, i) => ({
document: doc,
score: 1.0,
index: i,
}));
}
return data.results.map(
(result: { index: number; relevance_score: number }) => ({
document: documents[result.index],
score: result.relevance_score,
index: result.index,
}),
);
} catch (error) {
console.warn(`Reranker error: ${error}. Returning all documents.`);
return documents.map((doc, i) => ({ document: doc, score: 1.0, index: i }));
}
const data = await response.json();
if (!data.results || !Array.isArray(data.results)) {
log.warn("reranker_invalid_response", { response: data });
op.end({
status: "invalid_response",
fallback: true,
document_count: documents.length,
});
return documents.map((doc, i) => ({
document: doc,
score: 1.0,
index: i,
}));
}
// op.end logs the final success with all metrics
op.end({
status: "success",
results_count: data.results.length,
});
return data.results.map(
(result: { index: number; relevance_score: number }) => ({
document: documents[result.index],
score: result.relevance_score,
index: result.index,
}),
);
} catch (error) {
const err = error instanceof Error ? error : new Error(String(error));
log.warn("reranker_error", { error: err.message });
op.end({
status: "error",
error: err.message,
fallback: true,
});
return documents.map((doc, i) => ({
document: doc,
score: 1.0,
index: i,
}));
}
},
);
}
+54 -15
View File
@@ -6,6 +6,8 @@
import type { Table } from "@lancedb/lancedb";
import type { Embeddings } from "@langchain/core/embeddings";
import { z } from "zod";
import { LogOperation, logger } from "../lib/logger.js";
import { withSpan } from "../lib/tracing.js";
// #region Zod schemas (not exported)
@@ -72,23 +74,60 @@ export function createSearchSpecSectionsTool(
embeddings: Embeddings,
) {
return async ({ query }: SearchSpecInput): Promise<SearchSpecOutput> => {
// Generate embedding for the query
const queryVector = await embeddings.embedQuery(query);
const log = await logger.forComponent("search-tool");
// Search using LanceDB directly, limit to top 5 results
const results = await table.search(queryVector).limit(5).toArray();
log.info(LogOperation.SEARCH_SPEC_SECTIONS, { query });
// Return documents with metadata as structured objects
const output: SearchSpecResult[] = results.map(
(r: Record<string, unknown>) => ({
sectionId: String(r.sectionid || "unknown"),
sectionTitle: String(r.sectiontitle || "unknown"),
vectorDistance: Number(r._distance || 0),
partIndex: (r.partindex as number | undefined) ?? null,
totalParts: (r.totalparts as number | undefined) ?? null,
}),
return await withSpan(
LogOperation.SEARCHING_SPEC_SECTIONS,
{ query },
async () => {
const op = log.start(LogOperation.SEARCHING_SPEC_SECTIONS, { query });
const SEARCH_LIMIT = 5;
try {
// Generate embedding for the query (timed operation)
const embedOp = log.start(LogOperation.GENERATING_EMBEDDING, {
query,
});
const queryVector = await embeddings.embedQuery(query);
embedOp.end();
// Search using LanceDB directly, limit to top results (timed operation)
const searchOp = log.start(LogOperation.QUERYING_LANCEDB, {
query,
limit: SEARCH_LIMIT,
});
const results = await table
.search(queryVector)
.limit(SEARCH_LIMIT)
.toArray();
searchOp.end({ results_found: results.length });
// Return documents with metadata as structured objects
const output: SearchSpecResult[] = results.map(
(r: Record<string, unknown>) => ({
sectionId: String(r.sectionid || "unknown"),
sectionTitle: String(r.sectiontitle || "unknown"),
vectorDistance: Number(r._distance || 0),
partIndex: (r.partindex as number | undefined) ?? null,
totalParts: (r.totalparts as number | undefined) ?? null,
}),
);
op.end({
results: output.length,
section_ids: output.map((r) => r.sectionId),
});
return { results: output };
} catch (err) {
const error = err instanceof Error ? err : new Error(String(err));
log.error(LogOperation.SEARCHING_SPEC_SECTIONS, { query }, error);
throw err;
}
},
);
return { results: output };
};
}
+3
View File
@@ -66,6 +66,9 @@ export function createEmbeddings(provider?: EmbeddingProvider): Embeddings {
}
}
// Provider logging is done via console.error to stderr
// Detailed embedding operation logging is in the individual embedding classes
/**
* Get the currently configured embedding provider.
*
+43 -3
View File
@@ -1,4 +1,5 @@
import { Embeddings, type EmbeddingsParams } from "@langchain/core/embeddings";
import { LogOperation, logger } from "./logger.js";
/**
* Interface for FireworksEmbeddings parameters.
@@ -97,15 +98,37 @@ export class FireworksEmbeddings extends Embeddings {
return [];
}
const log = await logger.forComponent("fireworks-embeddings");
const op = log.start(LogOperation.EMBEDDING_DOCUMENTS, {
total_documents: documents.length,
batch_size: this.batchSize,
model: this.modelName,
});
const allEmbeddings: number[][] = [];
const totalBatches = Math.ceil(documents.length / this.batchSize);
// Process in batches
for (let i = 0; i < documents.length; i += this.batchSize) {
const batchNum = Math.floor(i / this.batchSize) + 1;
const batch = documents.slice(i, i + this.batchSize);
log.debug(LogOperation.PROCESSING_EMBEDDING_BATCH, {
batch_num: batchNum,
total_batches: totalBatches,
batch_size: batch.length,
});
const batchEmbeddings = await this.embedBatchWithRetry(batch);
allEmbeddings.push(...batchEmbeddings);
}
op.end({
total_documents: documents.length,
batches: totalBatches,
embeddings_generated: allEmbeddings.length,
});
return allEmbeddings;
}
@@ -116,7 +139,15 @@ export class FireworksEmbeddings extends Embeddings {
documents: string[],
attempt = 1,
): Promise<number[][]> {
const log = await logger.forComponent("fireworks-embeddings");
try {
log.debug(LogOperation.PROCESSING_EMBEDDING_BATCH, {
batch_size: documents.length,
attempt,
model: this.modelName,
});
return await this.embedBatch(documents);
} catch (error) {
// Check if it's a rate limit error (429)
@@ -126,13 +157,22 @@ export class FireworksEmbeddings extends Embeddings {
if (isRateLimit && attempt < this.maxRetries) {
const delay = this.initialRetryDelayMs * 2 ** (attempt - 1);
console.error(
`[Fireworks] Rate limit hit. Waiting ${delay}ms before retry ${attempt}/${this.maxRetries}...`,
);
log.warn(LogOperation.RETRYING_RATE_LIMIT, {
attempt,
max_retries: this.maxRetries,
delay_ms: delay,
batch_size: documents.length,
});
await sleep(delay);
return this.embedBatchWithRetry(documents, attempt + 1);
}
log.error(
LogOperation.PROCESSING_EMBEDDING_BATCH,
{ batch_size: documents.length, attempt, is_rate_limit: isRateLimit },
error instanceof Error ? error : new Error(String(error)),
);
// Fail fast for other errors or if retries exhausted
throw error;
}
+424
View File
@@ -0,0 +1,424 @@
/**
* Centralized logging module for Ask262 MCP server.
*
* Provides structured JSON logging with OpenTelemetry-style tracing support.
* Uses Pino for high-performance logging with dual output:
* - File: JSON Lines format for DuckDB querying
* - Console: Pretty-printed for development visibility
*
* @module lib/logger
*/
import { createWriteStream } from "node:fs";
import { mkdir } from "node:fs/promises";
import { join } from "node:path";
import pino from "pino";
import pretty from "pino-pretty";
import { getTraceContext } from "./tracing.js";
/**
* Log levels supported by the logger.
*/
export type LogLevel = "trace" | "debug" | "info" | "warn" | "error";
/**
* Standardized operation names for logging.
* Using an enum ensures consistency across the codebase.
*
* Tense conventions:
* - Present continuous (-ing) for timed operations that have start/end
* - Past tense for lifecycle events and completion states
* - Tool names for MCP tool invocations (logged at info level)
*/
export enum LogOperation {
// Server lifecycle (past tense for events)
SERVER_STARTED = "server_started",
SERVER_STOPPED = "server_stopped",
// HTTP handling (present continuous for timed request handling)
HANDLING_MCP_HTTP_REQUEST = "handling_mcp_http_request",
// MCP Tool invocations (tool names, logged at info level)
SEARCH_SPEC_SECTIONS = "search_spec_sections",
GET_SECTION_CONTENT = "get_section_content",
EVALUATE_IN_ENGINE262 = "evaluate_in_engine262",
// MCP Tool spans (present continuous tense of tool names)
// Note: These are the same as the timed operation names below for consistency
// Vector search operations (present continuous)
SEARCHING_SPEC_SECTIONS = "searching_spec_sections",
GENERATING_EMBEDDING = "generating_embedding",
QUERYING_LANCEDB = "querying_lancedb",
// Section fetch operations (present continuous)
FETCHING_SECTION_CONTENT = "fetching_section_content",
QUERYING_TABLE = "querying_table",
// Code execution operations (present continuous for timed)
EVALUATING_IN_ENGINE262 = "evaluating_in_engine262",
SPAWNING_CHILD_PROCESS = "spawning_child_process",
// Completion states (engine262 spec terminology - normal/abrupt completion)
ENGINE262_NORMAL_COMPLETION = "engine262_normal_completion",
ENGINE262_ABRUPT_COMPLETION = "engine262_abrupt_completion",
// Reranking operations (present continuous)
RERANKING_DOCUMENTS = "reranking_documents",
// Graph exploration (present continuous for actions, past for results)
EXPLORING_GRAPH = "exploring_graph",
RESOLVING_NODE_ID = "resolving_node_id",
NODE_FOUND = "node_found",
NODE_NOT_FOUND = "node_not_found",
// Embedding batch operations (present continuous)
EMBEDDING_DOCUMENTS = "embedding_documents",
PROCESSING_EMBEDDING_BATCH = "processing_embedding_batch",
RETRYING_RATE_LIMIT = "retrying_rate_limit",
}
/**
* Numeric log level values (Pino convention).
*/
const LOG_LEVEL_VALUES: Record<LogLevel, number> = {
trace: 10,
debug: 20,
info: 30,
warn: 40,
error: 50,
};
/**
* Valid log level strings.
*/
const VALID_LOG_LEVELS: LogLevel[] = [
"trace",
"debug",
"info",
"warn",
"error",
];
/**
* Components that can log in the application.
*/
export type LogComponent =
| "http-server"
| "stdio-server"
| "search-tool"
| "get-section-tool"
| "engine262-runner"
| "reranker"
| "graph-explorer"
| "embeddings-factory"
| "fireworks-embeddings";
/**
* Get the file log level from environment.
* HTTP server defaults to 'debug', stdio defaults to 'info'.
*
* @returns The configured file log level
*/
function getFileLogLevel(): LogLevel {
const envLevel = process.env.ASK262_LOG_LEVEL?.toLowerCase();
if (envLevel && VALID_LOG_LEVELS.includes(envLevel as LogLevel)) {
return envLevel as LogLevel;
}
// Default: debug for HTTP, info for stdio
return "debug";
}
/**
* Get the console log level.
* Console shows max('info', file level) - never shows debug.
*
* @returns The calculated console log level
*/
function getConsoleLogLevel(): LogLevel {
const fileLevel = getFileLogLevel();
const fileLevelValue = LOG_LEVEL_VALUES[fileLevel];
const infoLevelValue = LOG_LEVEL_VALUES.info;
// Console level is max of (info, file level)
return fileLevelValue > infoLevelValue ? fileLevel : "info";
}
/**
* Get the log directory from environment.
*
* @returns The configured log directory path
*/
function getLogDir(): string {
return process.env.ASK262_LOG_DIR ?? "./logs";
}
/**
* Ensure the log directory exists.
* Creates the directory recursively if it doesn't exist.
*
* @throws Error if directory cannot be created
*/
async function ensureLogDir(): Promise<void> {
const logDir = getLogDir();
try {
await mkdir(logDir, { recursive: true });
} catch (err) {
const errorMsg = err instanceof Error ? err.message : String(err);
throw new Error(
`Failed to create log directory '${logDir}': ${errorMsg}. ` +
"Check permissions or set ASK262_LOG_DIR to a writable location.",
);
}
}
/**
* Fields to redact from logs for security.
*/
const REDACT_FIELDS = [
"FIREWORKS_API_KEY",
"api_key",
"authorization",
"password",
"secret",
"token",
];
/**
* Create the root Pino logger instance.
*
* @returns Configured Pino logger with dual transport
*/
async function createRootLogger(): Promise<pino.Logger> {
await ensureLogDir();
const logDir = getLogDir();
const logFile = join(logDir, "ask262.jsonl");
const fileLevel = getFileLogLevel();
const consoleLevel = getConsoleLogLevel();
// File transport: JSON Lines format, synchronous writes
const fileStream = createWriteStream(logFile, { flags: "a" });
// Console transport: Pretty printed
const consoleStream = pretty({
colorize: true,
translateTime: "SYS:standard",
ignore: "pid,hostname",
});
return pino(
{
level: fileLevel,
redact: {
paths: REDACT_FIELDS,
remove: true,
censor: "[REDACTED]",
},
mixin() {
// Add trace context if available
const traceCtx = getTraceContext();
if (traceCtx) {
return {
trace_id: traceCtx.traceId,
span_id: traceCtx.spanId,
parent_span_id: traceCtx.parentSpanId,
};
}
return {};
},
formatters: {
level(label: string) {
return { level: label };
},
},
timestamp: () => `,"timestamp":"${new Date().toISOString()}"`,
},
pino.multistream([
{ stream: fileStream, level: fileLevel },
{ stream: consoleStream, level: consoleLevel },
]),
);
}
// Singleton root logger instance
let rootLogger: pino.Logger | null = null;
/**
* Get or create the root logger instance.
*
* @returns The root logger
*/
async function getRootLogger(): Promise<pino.Logger> {
if (!rootLogger) {
rootLogger = await createRootLogger();
}
return rootLogger;
}
/**
* Interface for timed operations.
*/
export interface TimedOperation {
/**
* End the timed operation and log the result.
*
* @param resultAttrs - Additional attributes to log with the result
*/
end(resultAttrs?: Record<string, unknown>): void;
}
/**
* Interface for component-bound loggers.
*/
export interface ComponentLogger {
/**
* Log at trace level.
*
* @param operation - The operation being performed (use LogOperation enum)
* @param attrs - Additional attributes
*/
trace(
operation: LogOperation | string,
attrs?: Record<string, unknown>,
): void;
/**
* Log at debug level.
*
* @param operation - The operation being performed (use LogOperation enum)
* @param attrs - Additional attributes
*/
debug(
operation: LogOperation | string,
attrs?: Record<string, unknown>,
): void;
/**
* Log at info level.
*
* @param operation - The operation being performed (use LogOperation enum)
* @param attrs - Additional attributes
*/
info(operation: LogOperation | string, attrs?: Record<string, unknown>): void;
/**
* Log at warn level.
*
* @param operation - The operation being performed (use LogOperation enum)
* @param attrs - Additional attributes
*/
warn(operation: LogOperation | string, attrs?: Record<string, unknown>): void;
/**
* Log at error level.
*
* @param operation - The operation being performed (use LogOperation enum)
* @param attrs - Additional attributes
* @param error - Optional error to include
*/
error(
operation: LogOperation | string,
attrs?: Record<string, unknown>,
error?: Error,
): void;
/**
* Start a timed operation.
*
* @param operation - The operation name (use LogOperation enum)
* @param attrs - Initial attributes
* @returns Timed operation handle
*/
start(
operation: LogOperation | string,
attrs?: Record<string, unknown>,
): TimedOperation;
}
/**
* Create a logger bound to a specific component.
*
* @param component - The component name (e.g., 'search-tool')
* @returns Component-bound logger
*
* @example
* ```typescript
* const log = logger.forComponent('search-tool');
*
* // Simple log
* log.info('vector_search_started', { query: 'how does array.map work' });
*
* // Timed operation
* const op = log.start('vector_search', { query: 'how does array.map work' });
* const results = await doSearch(query);
* op.end({ results: results.length });
* ```
*/
export async function forComponent(
component: LogComponent,
): Promise<ComponentLogger> {
const root = await getRootLogger();
return {
trace(operation: string, attrs?: Record<string, unknown>) {
root.trace({ component, operation, ...attrs });
},
debug(operation: string, attrs?: Record<string, unknown>) {
root.debug({ component, operation, ...attrs });
},
info(operation: string, attrs?: Record<string, unknown>) {
root.info({ component, operation, ...attrs });
},
warn(operation: string, attrs?: Record<string, unknown>) {
root.warn({ component, operation, ...attrs });
},
error(operation: string, attrs?: Record<string, unknown>, error?: Error) {
if (error) {
root.error({ component, operation, err: error, ...attrs });
} else {
root.error({ component, operation, ...attrs });
}
},
start(operation: string, attrs?: Record<string, unknown>): TimedOperation {
const startTime = performance.now();
// Log start
root.debug({ component, operation, status: "started", ...attrs });
return {
end(resultAttrs?: Record<string, unknown>) {
const durationMs = Math.round(performance.now() - startTime);
root.debug({
component,
operation,
status: "completed",
duration_ms: durationMs,
...attrs,
...resultAttrs,
});
},
};
},
};
}
/**
* Logger factory function.
*
* Use this to get component-bound loggers:
* ```typescript
* const log = await logger.forComponent('search-tool');
* ```
*/
export const logger = {
forComponent,
};
// Export for direct use in simple cases
export { getRootLogger };
+276
View File
@@ -0,0 +1,276 @@
/**
* OpenTelemetry trace context management for Ask262 MCP server.
*
* Provides AsyncLocalStorage-based context propagation for nested operations,
* enabling automatic parent-child span relationships without manual ID passing.
*
* @module lib/tracing
*/
import { AsyncLocalStorage } from "node:async_hooks";
import { randomUUID } from "node:crypto";
import { SpanStatusCode, trace } from "@opentelemetry/api";
/**
* Trace context stored in AsyncLocalStorage.
*/
interface TraceContext {
/** The root trace identifier */
traceId: string;
/** The current span identifier */
spanId: string;
/** Parent span identifier (null for root spans) */
parentSpanId: string | null;
/** Span depth level (0 = root) */
depth: number;
}
// AsyncLocalStorage for automatic context propagation
const traceStorage = new AsyncLocalStorage<TraceContext>();
/**
* Get the current trace context from AsyncLocalStorage.
*
* @returns Current trace context or undefined if not in a trace
*/
function getCurrentContext(): TraceContext | undefined {
return traceStorage.getStore();
}
/**
* Generate a unique span ID.
*
* @returns Short span ID (16 hex chars)
*/
function generateSpanId(): string {
return randomUUID().replace(/-/g, "").slice(0, 16);
}
/**
* Generate a unique trace ID.
*
* @returns Full trace ID (32 hex chars)
*/
function generateTraceId(): string {
return randomUUID().replace(/-/g, "");
}
/**
* Create a new trace context for a root operation.
*
* @param traceId - Optional existing trace ID (e.g., from request header)
* @returns New trace context
*
* @example
* ```typescript
* // Create new trace
* const traceCtx = createTraceContext();
*
* // Or use existing trace ID from request
* const traceCtx = createTraceContext(req.headers['x-request-id'] as string);
* ```
*/
export function createTraceContext(traceId?: string): TraceContext {
return {
traceId: traceId ?? generateTraceId(),
spanId: generateSpanId(),
parentSpanId: null,
depth: 0,
};
}
/**
* Execute a function within a trace context.
*
* This creates a new span and runs the function with that span as the active
* context. Any nested operations will automatically inherit this context.
*
* @param operation - The operation name for the span
* @param attributes - Initial span attributes
* @param fn - The function to execute within the span
* @param traceId - Optional trace ID to use (e.g., from request header)
* @returns Result of the function
*
* @example
* ```typescript
* const result = await withSpan(
* 'mcp_request',
* { tool: 'search-spec-sections' },
* async () => {
* // All code here has access to the span context
* return await handleRequest();
* }
* );
* ```
*/
export async function withSpan<T>(
operation: string,
attributes: Record<string, unknown> = {},
fn: () => Promise<T>,
traceId?: string,
): Promise<T> {
const parentContext = getCurrentContext();
const tracer = trace.getTracer("ask262");
// Build span context
const spanContext: TraceContext = parentContext
? {
traceId: parentContext.traceId,
spanId: generateSpanId(),
parentSpanId: parentContext.spanId,
depth: parentContext.depth + 1,
}
: createTraceContext(traceId);
// Create OTel span for context tracking
const span = tracer.startSpan(operation, {
attributes: {
...attributes,
"span.depth": spanContext.depth,
},
});
// Store in AsyncLocalStorage for nested calls
return traceStorage.run(spanContext, async () => {
try {
const result = await fn();
span.setStatus({ code: SpanStatusCode.OK });
return result;
} catch (err) {
span.setStatus({
code: SpanStatusCode.ERROR,
message: err instanceof Error ? err.message : String(err),
});
span.recordException(err instanceof Error ? err : new Error(String(err)));
throw err;
} finally {
span.end();
}
});
}
/**
* Get the current trace ID if in a trace context.
*
* @returns Trace ID or undefined
*/
export function getTraceId(): string | undefined {
return getCurrentContext()?.traceId;
}
/**
* Get the current span ID if in a trace context.
*
* @returns Span ID or undefined
*/
export function getSpanId(): string | undefined {
return getCurrentContext()?.spanId;
}
/**
* Get the parent span ID if in a trace context.
*
* @returns Parent span ID or undefined/null
*/
export function getParentSpanId(): string | null | undefined {
return getCurrentContext()?.parentSpanId;
}
/**
* Create a process-scoped trace context for stdio server.
*
* This creates a single trace ID that persists for the entire process lifetime,
* suitable for stdio transport where there's no natural request boundary.
*
* @returns Process-scoped trace context
*
* @example
* ```typescript
* // At server startup
* const sessionTraceId = createProcessScopedTrace();
*
* // For each message, use the same trace ID
* await withSpanContext(sessionTraceId, 'mcp_request', async () => {
* // handle message
* });
* ```
*/
export function createProcessScopedTrace(): string {
return generateTraceId();
}
/**
* Execute a function with a specific trace context.
*
* Similar to withSpan but uses an existing trace ID, useful for stdio
* where you want the same trace ID across multiple operations.
*
* @param traceId - The trace ID to use
* @param operation - The operation name
* @param attributes - Span attributes
* @param fn - The function to execute
* @returns Result of the function
*/
export async function withSpanContext<T>(
traceId: string,
operation: string,
attributes: Record<string, unknown> = {},
fn: () => Promise<T>,
): Promise<T> {
// Check if we're already in a context
const existingContext = getCurrentContext();
if (existingContext && existingContext.traceId === traceId) {
// Already in this trace, create child span
return withSpan(operation, attributes, fn);
}
// Create new root span with this trace ID
const spanContext: TraceContext = {
traceId,
spanId: generateSpanId(),
parentSpanId: null,
depth: 0,
};
const tracer = trace.getTracer("ask262");
const span = tracer.startSpan(operation, {
attributes: {
...attributes,
"span.depth": 0,
},
});
return traceStorage.run(spanContext, async () => {
try {
const result = await fn();
span.setStatus({ code: SpanStatusCode.OK });
return result;
} catch (err) {
span.setStatus({
code: SpanStatusCode.ERROR,
message: err instanceof Error ? err.message : String(err),
});
span.recordException(err instanceof Error ? err : new Error(String(err)));
throw err;
} finally {
span.end();
}
});
}
/**
* Trace context for HTTP server requests.
*
* Creates a new trace context for each request, optionally using
* an existing trace ID from request headers.
*
* @param requestId - Optional request ID from headers
* @returns New trace context for this request
*/
export function createHttpTraceContext(requestId?: string): TraceContext {
return createTraceContext(requestId);
}
// Re-export for convenience
export { getCurrentContext as getTraceContext };
+72 -38
View File
@@ -35,6 +35,8 @@ import {
} from "./agent-tools/index.js";
import { DEFAULT_PORT, STORAGE_DIR as STORAGE_DIR_REL } from "./constants.js";
import { createEmbeddings } from "./lib/embeddings-factory.js";
import { LogOperation, logger } from "./lib/logger.js";
import { withSpan } from "./lib/tracing.js";
// Resolve storage path relative to this script's directory
const __filename = fileURLToPath(import.meta.url);
@@ -88,11 +90,7 @@ async function createMcpServer() {
},
},
async ({ query }) => {
console.log(`[TOOL] ${searchSpecToolName}: query="${query}"`);
const result = await searchSpecTool({ query });
console.log(
`[TOOL] ${searchSpecToolName}: ${result.results.length} results`,
);
return {
content: [{ type: "text", text: JSON.stringify(result, null, 2) }],
structuredContent: result,
@@ -115,17 +113,7 @@ async function createMcpServer() {
},
},
async ({ sectionIds, recursive }) => {
console.log(
`[TOOL] ${sectionContentToolName}: sectionIds=[${sectionIds.map((id: string) => `"${id}"`).join(", ")}] recursive=${recursive}`,
);
const result = await getSectionContentTool({ sectionIds, recursive });
const totalContentLength = result.sections.reduce(
(sum: number, s: { content: string }) => sum + s.content.length,
0,
);
console.log(
`[TOOL] ${sectionContentToolName}: ${totalContentLength} chars, ${result.sections.length} sections`,
);
return {
content: [{ type: "text", text: JSON.stringify(result, null, 2) }],
structuredContent: result,
@@ -148,16 +136,8 @@ async function createMcpServer() {
},
},
async ({ code }) => {
console.log(`[TOOL] ${evaluateToolName}: code length=${code.length}`);
const result = await evaluateTool({ code });
const isError = result.error !== undefined;
if (isError) {
console.log(`[TOOL] ${evaluateToolName}: error - ${result.error}`);
} else {
console.log(
`[TOOL] ${evaluateToolName}: ${result.importantSections.length} important, ${result.otherSections.length} other sections`,
);
}
const text = isError ? result.error : JSON.stringify(result, null, 2);
return {
content: [{ type: "text", text }],
@@ -230,6 +210,9 @@ Key principles:
}
export async function main() {
// Initialize HTTP server logger
const log = await logger.forComponent("http-server");
// Create Hono app
const app = new Hono();
@@ -269,6 +252,13 @@ export async function main() {
// MCP endpoint - handles GET and POST (HEAD is handled by middleware above)
// Must be defined BEFORE inspector (which mounts at /) for proper route matching
app.on(["GET", "POST"], "/mcp", async (c) => {
// Get client IP from headers or connection
const clientIp =
c.req.header("x-forwarded-for") || c.req.header("x-real-ip") || "unknown";
// Get trace ID from request header or create new
const traceId = c.req.header("x-request-id") || undefined;
// Get parsed body from Hono (automatic JSON parsing)
let parsedBody: unknown;
if (c.req.method === "POST") {
@@ -280,20 +270,48 @@ export async function main() {
}
}
// Create fresh server and transport for each request (stateless mode)
const server = await createMcpServer();
const transport = new WebStandardStreamableHTTPServerTransport({
sessionIdGenerator: undefined, // Stateless mode
enableJsonResponse: true, // Use JSON responses instead of SSE streaming
});
await server.connect(transport);
// Handle request within trace context (passing trace ID from header if available)
return await withSpan(
LogOperation.HANDLING_MCP_HTTP_REQUEST,
{ method: c.req.method, client_ip: clientIp },
async () => {
const op = log.start(LogOperation.HANDLING_MCP_HTTP_REQUEST, {
method: c.req.method,
client_ip: clientIp,
});
// Use Web Standard handleRequest method
// Hono's c.req.raw is a Web Standard Request
const response = await transport.handleRequest(c.req.raw, { parsedBody });
try {
// Create fresh server and transport for each request (stateless mode)
const server = await createMcpServer();
const transport = new WebStandardStreamableHTTPServerTransport({
sessionIdGenerator: undefined, // Stateless mode
enableJsonResponse: true, // Use JSON responses instead of SSE streaming
});
await server.connect(transport);
// Return the Web Standard Response directly
return response;
// Use Web Standard handleRequest method
// Hono's c.req.raw is a Web Standard Request
const response = await transport.handleRequest(c.req.raw, {
parsedBody,
});
op.end({ status: "success" });
// Return the Web Standard Response directly
return response;
} catch (err) {
const error = err instanceof Error ? err : new Error(String(err));
log.error(
LogOperation.HANDLING_MCP_HTTP_REQUEST,
{ status: "error" },
error,
);
op.end({ status: "error", error: error.message });
throw err;
}
},
traceId,
);
});
// MCP Inspector at root path - auto-connects to /mcp
@@ -308,16 +326,32 @@ export async function main() {
});
// Start the server
console.log(`Ask262 MCP HTTP Server running on http://0.0.0.0:${PORT}`);
console.log(`MCP endpoint: POST http://0.0.0.0:${PORT}/mcp`);
console.log(`Health check: GET http://0.0.0.0:${PORT}/health`);
console.log(`Mode: Stateless JSON (non-streaming)`);
log.info(LogOperation.SERVER_STARTED, {
port: PORT,
transport: "http",
mode: "stateless-json",
endpoints: ["/mcp", "/health"],
});
// Minimal console output for startup visibility
console.error(`Ask262 MCP HTTP Server running on http://0.0.0.0:${PORT}`);
console.error(`MCP endpoint: POST http://0.0.0.0:${PORT}/mcp`);
console.error(`Mode: Stateless JSON (non-streaming)`);
serve({
fetch: app.fetch,
port: PORT,
hostname: "0.0.0.0", // Bind to all interfaces for container/Docker compatibility
});
// Handle graceful shutdown
const shutdown = (signal: string) => {
log.info(LogOperation.SERVER_STOPPED, { signal });
process.exit(0);
};
process.on("SIGTERM", () => shutdown("SIGTERM"));
process.on("SIGINT", () => shutdown("SIGINT"));
}
main().catch((error) => {
+66 -20
View File
@@ -36,6 +36,8 @@ import {
} from "./agent-tools/index.js";
import { STORAGE_DIR as STORAGE_DIR_REL } from "./constants.js";
import { createEmbeddings } from "./lib/embeddings-factory.js";
import { LogOperation, logger } from "./lib/logger.js";
import { createProcessScopedTrace, withSpanContext } from "./lib/tracing.js";
// Resolve storage path relative to this script's directory
const __filename = fileURLToPath(import.meta.url);
@@ -88,6 +90,17 @@ export interface SearchSpecMCPOutput extends McpToolOutputBase {
const embeddings = createEmbeddings();
export async function main() {
// Initialize stdio server logger
const log = await logger.forComponent("stdio-server");
// Create process-scoped trace ID for this session
const sessionTraceId = createProcessScopedTrace();
log.info(LogOperation.SERVER_STARTED, {
transport: "stdio",
trace_id: sessionTraceId,
});
// Connect to LanceDB
const db = await lancedbSdk.connect(STORAGE_DIR);
const table = await db.openTable("spec_vectors");
@@ -124,12 +137,19 @@ export async function main() {
},
},
async ({ query }: SearchSpecMCPInput): Promise<SearchSpecMCPOutput> => {
const result = await searchSpecTool({ query });
return {
content: [{ type: "text", text: JSON.stringify(result, null, 2) }],
structuredContent: result,
isError: false,
};
return await withSpanContext(
sessionTraceId,
"vector_search",
{ tool: searchSpecToolName, query },
async () => {
const result = await searchSpecTool({ query });
return {
content: [{ type: "text", text: JSON.stringify(result, null, 2) }],
structuredContent: result,
isError: false,
};
},
);
},
);
@@ -150,12 +170,19 @@ export async function main() {
sectionIds,
recursive,
}: GetSectionContentMCPInput): Promise<GetSectionContentMCPOutput> => {
const result = await getSectionContentTool({ sectionIds, recursive });
return {
content: [{ type: "text", text: JSON.stringify(result, null, 2) }],
structuredContent: result,
isError: false,
};
return await withSpanContext(
sessionTraceId,
"section_fetch",
{ tool: sectionContentToolName, section_count: sectionIds.length },
async () => {
const result = await getSectionContentTool({ sectionIds, recursive });
return {
content: [{ type: "text", text: JSON.stringify(result, null, 2) }],
structuredContent: result,
isError: false,
};
},
);
},
);
@@ -173,14 +200,21 @@ export async function main() {
},
},
async ({ code }: EvaluateToolMCPInput): Promise<EvaluateToolMCPOutput> => {
const result = await evaluateTool({ code });
const isError = result.error !== undefined;
const text = isError ? result.error : JSON.stringify(result, null, 2);
return {
content: [{ type: "text", text }],
structuredContent: result,
isError,
};
return await withSpanContext(
sessionTraceId,
"code_execution",
{ tool: evaluateToolName, code_length: code.length },
async () => {
const result = await evaluateTool({ code });
const isError = result.error !== undefined;
const text = isError ? result.error : JSON.stringify(result, null, 2);
return {
content: [{ type: "text", text }],
structuredContent: result,
isError,
};
},
);
},
);
@@ -248,6 +282,18 @@ Key principles:
await server.connect(transport);
console.error("Ask262 MCP Server running on stdio");
// Handle graceful shutdown
const shutdown = (signal: string) => {
log.info(LogOperation.SERVER_STOPPED, {
signal,
trace_id: sessionTraceId,
});
process.exit(0);
};
process.on("SIGTERM", () => shutdown("SIGTERM"));
process.on("SIGINT", () => shutdown("SIGINT"));
}
main().catch((error) => {