AI observability: how do you trace and log LLM calls in prod?

// A tiny OpenTelemetry-shaped tracer: nested spans with GenAI attribute names,
// a W3C traceparent header across a service hop, and a tail-sampling decision.
// Fake clock and counter-based IDs keep the output deterministic.
const crypto = require("crypto");
let clock = 0, idSeq = 0;
const newId = (len) => crypto.createHash("sha256").update(`id-${++idSeq}`).digest("hex").slice(0, len);
const finished = [];
const headers = [];

function startSpan(name, kind, parent, attrs = {}) {
  return { name, kind, traceId: parent ? parent.traceId : newId(32), spanId: newId(16),
           parentId: parent ? parent.spanId : null, start: clock, attrs: { ...attrs }, status: "OK" };
}
function endSpan(span, ms, attrs = {}) {
  clock += ms;
  span.end = clock;
  Object.assign(span.attrs, attrs);
  finished.push(span);
}
const traceparent = (s) => `00-${s.traceId}-${s.spanId}-01`;
function fromTraceparent(h) {
  const [ver, traceId, spanId, flags] = h.split("-");
  if (ver !== "00" || traceId.length !== 32 || spanId.length !== 16) throw new Error("bad traceparent");
  return { traceId, spanId, sampled: flags === "01" };
}

// Stub model call: returns canned usage the way a provider response would.
function chat(parent, model, inTok, outTok, ms, finish) {
  const s = startSpan(`chat ${model}`, "CLIENT", parent, { "gen_ai.operation.name": "chat",
    "gen_ai.provider.name": "openai", "gen_ai.request.model": model, "gen_ai.request.temperature": 0 });
  endSpan(s, ms, { "gen_ai.response.model": `${model}-2026-08-01`, "gen_ai.usage.input_tokens": inTok,
    "gen_ai.usage.output_tokens": outTok, "gen_ai.response.finish_reasons": [finish] });
}
// The order service is another process: it only receives the HTTP header.
function orderService(header, fail) {
  headers.push(header);
  const ctx = fromTraceparent(header);
  const s = startSpan("GET /orders/{id}", "SERVER", ctx, { "http.response.status_code": fail ? 503 : 200 });
  if (fail) s.status = "ERROR";
  endSpan(s, fail ? 2000 : 120);
}

function handleRequest(question, opts) {
  const root = startSpan("invoke_agent support-bot", "INTERNAL", null, { "gen_ai.operation.name": "invoke_agent",
    "app.prompt.version": "support@v7", "app.feature": "support-chat" });
  const ret = startSpan("retrieve kb", "CLIENT", root, { "db.system.name": "pgvector" });
  endSpan(ret, 80, { "app.retrieval.doc_count": 4 });
  chat(root, "gpt-x", 2400, 40, opts.slowModel ? 4200 : 900, "tool_calls");
  const tool = startSpan("execute_tool lookup_order", "INTERNAL", root, { "gen_ai.operation.name": "execute_tool",
    "gen_ai.tool.name": "lookup_order" });
  orderService(traceparent(tool), opts.toolFails);         // header crosses the network
  if (opts.toolFails) tool.status = "ERROR";
  endSpan(tool, 5);
  chat(root, "gpt-x", 2600, 160, 1100, "stop");
  root.attrs["app.question.chars"] = question.length;      // a size, not the text
  endSpan(root, 2);
  return root.traceId;
}

const t1 = handleRequest("Where is order A-991?", {});
console.log(`trace ${t1}`);
console.log(`traceparent sent to the order service: ${headers[0]}`);
const spans = finished.filter((s) => s.traceId === t1).sort((a, b) => a.start - b.start || b.end - a.end);
const depth = (s) => (s.parentId ? 1 + depth(spans.find((p) => p.spanId === s.parentId)) : 0);
for (const s of spans) {
  const gen = Object.keys(s.attrs).filter((k) => k.startsWith("gen_ai.usage") || k === "gen_ai.response.finish_reasons")
    .map((k) => `${k.replace("gen_ai.", "")}=${s.attrs[k]}`).join(" ");
  console.log(`${String(s.start).padStart(5)}ms ${String(s.end - s.start).padStart(5)}ms  ${"  ".repeat(depth(s))}` +
    `${s.name} [${s.kind}] span=${s.spanId.slice(0, 6)} parent=${s.parentId ? s.parentId.slice(0, 6) : "-"}${gen ? "  " + gen : ""}`);
}
const tok = spans.reduce((a, s) => a + (s.attrs["gen_ai.usage.input_tokens"] || 0) + (s.attrs["gen_ai.usage.output_tokens"] || 0), 0);
console.log(`spans=${spans.length} model_calls=${spans.filter((s) => s.kind === "CLIENT" && s.name.startsWith("chat")).length} tokens=${tok}`);

// Tail sampling: decide per whole trace, after it finished.
const all = [t1, handleRequest("Refund status?", { toolFails: true }), handleRequest("Change my address", { slowModel: true }),
  handleRequest("Hi", {}), handleRequest("Opening hours?", {}), handleRequest("Cancel order", {})];
console.log("tail sampling (keep errors, keep > 3000 ms, keep about 1 in 3 of the rest by trace id):");
for (const id of all) {
  const ss = finished.filter((s) => s.traceId === id);
  const dur = Math.max(...ss.map((s) => s.end)) - Math.min(...ss.map((s) => s.start));
  const err = ss.some((s) => s.status === "ERROR");
  const keep = err ? "keep: error" : dur > 3000 ? "keep: slow" : parseInt(id.slice(-8), 16) % 3 === 0 ? "keep: sampled" : "drop";
  console.log(`  ${id.slice(0, 8)} ${String(ss.length).padStart(2)} spans ${String(dur).padStart(5)} ms  ${keep}`);
}