OpenTelemetry والـ Distributed Tracing: الـ request راح فين وضاع وقته فين

// load.js: ست checkouts في نفس الوقت، واحد منهم بطيء وواحد بيفشل. وبعدين لو فيه collector، نطبع الـ trace
const skus = ["a", "b", "slow", "c", "boom", "d"];
const rs = await Promise.all(skus.map(async (sku) => {
  const s = performance.now();
  const r = await fetch(`http://localhost:3000/checkout?sku=${sku}`);
  await r.text();
  return { sku, status: r.status, ms: performance.now() - s, trace: r.headers.get("x-trace-id") };
}));
await new Promise((r) => setTimeout(r, 100));
console.log("\n--- النتايج ---");
for (const r of rs) console.log(`${r.sku.padEnd(4)} ${r.status} ${r.ms.toFixed(0).padStart(4)}ms ${r.trace ?? "مفيش trace id"}`);

const tree = async (id) => {
  const spans = await (await fetch(`http://localhost:4318/traces/${id}`)).json();
  const t0 = Math.min(...spans.map((s) => s.startTime));
  const print = (parent, depth) => {
    for (const s of spans.filter((x) => x.parentSpanId === parent).sort((a, b) => a.startTime - b.startTime)) {
      const bar = " ".repeat(Math.round((s.startTime - t0) / 10)) + "█".repeat(Math.max(1, Math.round(s.durationMs / 10)));
      console.log(`${"  ".repeat(depth)}${`${s.service} ${s.kind} ${s.name}`.padEnd(46 - depth * 2)} ${String(s.durationMs).padStart(6)}ms ${s.status.code === "ERROR" ? "ERROR " : ""}${bar}`);
      print(s.spanId, depth + 1);
    }
  };
  print(null, 0);
};
try {
  const slow = rs.reduce((a, b) => (b.ms > a.ms ? b : a));
  console.log(`\n--- trace أبطأ request (${slow.sku}) ---`);
  await tree(slow.trace);
  console.log(`\n--- trace اللي فشل (boom) ---`);
  await tree(rs.find((r) => r.sku === "boom").trace);
} catch { console.log("\nمفيش collector، ومفيش traces"); }

$ node server.js & S=$!; sleep 1; node load.js; kill $S
on 3000
[gateway] checkout
[gateway] checkout
[gateway] checkout
[gateway] checkout
[gateway] checkout
[gateway] checkout
[orders] creating order
[orders] creating order
[orders] creating order
[orders] creating order
[inventory] checking stock
[orders] creating order
[inventory] checking stock
[orders] creating order
[inventory] checking stock
[inventory] checking stock
[inventory] checking stock
[inventory] error: stock table locked
[inventory] checking stock

--- النتايج ---
a    200  188ms مفيش trace id
b    200  131ms مفيش trace id
slow 200  501ms مفيش trace id
c    200  133ms مفيش trace id
boom 502  117ms مفيش trace id
d    200  151ms مفيش trace id

--- trace أبطأ request (slow) ---

مفيش collector، ومفيش traces

// tracing.js: tracer صغير على طريقة OpenTelemetry: spans، و context بـ AsyncLocalStorage، و W3C traceparent، و logs فيها trace_id
import { AsyncLocalStorage } from "node:async_hooks";
import { randomBytes } from "node:crypto";

const als = new AsyncLocalStorage();
const hex = (bytes) => randomBytes(bytes).toString("hex");
const TP = /^00-([0-9a-f]{32})-([0-9a-f]{16})-([0-9a-f]{2})$/;

export function parseTraceparent(header) {
  const m = TP.exec(typeof header === "string" ? header.trim() : "");
  if (!m || /^0+$/.test(m[1]) || /^0+$/.test(m[2])) return null;
  return { traceId: m[1], spanId: m[2], sampled: (parseInt(m[3], 16) & 1) === 1 };
}

export const formatTraceparent = ({ traceId, spanId, sampled }) => `00-${traceId}-${spanId}-${sampled ? "01" : "00"}`;
export const currentSpan = () => als.getStore() ?? null;

export function createTracer(service, { exporter = () => {}, sampleRate = 1, rand = Math.random } = {}) {
  async function startActiveSpan(name, { kind = "INTERNAL", attributes = {}, parent } = {}, fn) {
    const p = parent ?? currentSpan();
    const span = {
      traceId: p?.traceId ?? hex(16),
      spanId: hex(8),
      parentSpanId: p?.spanId ?? null,
      name, service, kind,
      sampled: p ? p.sampled : rand() < sampleRate, // head sampling: القرار بيتاخد مرة واحدة في الأول
      startTime: Date.now(),
      durationMs: 0,
      attributes: { ...attributes },
      events: [],
      status: { code: "UNSET" },
    };
    const t0 = performance.now();
    try {
      return await als.run(span, () => fn(span));
    } catch (e) {
      span.status = { code: "ERROR", message: e.message };
      span.events.push({ name: "exception", attributes: { "exception.type": e.name, "exception.message": e.message } });
      throw e;
    } finally {
      span.durationMs = Math.round((performance.now() - t0) * 10) / 10;
      if (span.sampled) exporter(span);
    }
  }
  return { startActiveSpan };
}

export function inject(headers = {}) {
  const s = currentSpan();
  if (s) headers.traceparent = formatTraceparent(s);
  return headers;
}

// SERVER span لكل request، وكمّل من الـ traceparent اللي جاي لو موجود
export const traceMiddleware = (tracer) => (req, res, next) => {
  const parent = parseTraceparent(req.headers.traceparent) ?? undefined;
  tracer.startActiveSpan(`${req.method} ${req.path}`, { kind: "SERVER", parent, attributes: { "http.request.method": req.method, "url.path": req.path } }, (span) =>
    new Promise((done) => {
      res.setHeader("x-trace-id", span.traceId);
      res.on("close", () => {
        span.attributes["http.response.status_code"] = res.statusCode;
        if (req.route) { span.attributes["http.route"] = req.route.path; span.name = `${req.method} ${req.route.path}`; }
        if (res.statusCode >= 500) span.status = { code: "ERROR" };
        done();
      });
      next();
    }),
  );
};

// CLIENT span لكل call طالعة، والـ traceparent بيتبعت معاها
export const tracedFetch = (tracer) => (url, opts = {}) 
…

$ node server.js & S=$!; sleep 1; node load.js; kill $S
on 3000
{"service":"gateway","msg":"checkout","sku":"a","trace_id":"c8b03208238c0222db2fb80f3c67d146","span_id":"6834054d270d7724"}
{"service":"gateway","msg":"checkout","sku":"b","trace_id":"8e1edf812a2905428759acb654a2621f","span_id":"60e9513828ca7e45"}
{"service":"gateway","msg":"checkout","sku":"slow","trace_id":"9267fb541d65f255700367e487b52755","span_id":"b4cc5fb6ce3dcc94"}
{"service":"gateway","msg":"checkout","sku":"c","trace_id":"d2455cbf3d7a7bfd055d01f9cb894c41","span_id":"fd40d61a27a74eda"}
{"service":"gateway","msg":"checkout","sku":"boom","trace_id":"9a9c88469b8adcfb14989758f338f79c","span_id":"77a0de22513e1c5a"}
{"service":"gateway","msg":"checkout","sku":"d","trace_id":"03d79b7952733743976b294d5223654f","span_id":"d7ad7e7bad92e056"}
{"service":"orders","msg":"creating order","sku":"a","trace_id":"c8b03208238c0222db2fb80f3c67d146","span_id":"b9bdd55382ea7a29"}
{"service":"orders","msg":"creating order","sku":"b","trace_id":"8e1edf812a2905428759acb654a2621f","span_id":"04dc0fafd1065085"}
{"service":"orders","msg":"creating order","sku":"slow","trace_id":"9267fb541d65f255700367e487b52755","span_id":"1758142739b22fd
…

// server.js: نفس التلات services، بس كل واحدة ليها tracer، والـ spans بتروح لـ collector على أربعة تلاتة واحد تمانية
import express from "express";
import { createTracer, traceMiddleware, tracedFetch, createLogger } from "./tracing.js";

const sleep = (ms) => new Promise((r) => setTimeout(r, ms));

// collector: بيستقبل الـ spans، زي Jaeger أو Tempo أو OTel Collector، بس في الـ memory
const spans = [];
const collector = express();
collector.get("/traces/:id", (req, res) => res.json(spans.filter((s) => s.traceId === req.params.id)));
collector.get("/traces", (req, res) => res.json(spans.filter((s) => !s.parentSpanId).map((s) => ({ traceId: s.traceId, name: s.name, durationMs: s.durationMs, status: s.status.code }))));
collector.listen(4318);

const svc = (name, port, route, handler) => {
  const tracer = createTracer(name, { exporter: (s) => spans.push(s) });
  const tools = { tracer, fetch: tracedFetch(tracer), log: createLogger(name), span: (n, attributes, fn) => tracer.startActiveSpan(n, { attributes }, fn) };
  const app = express();
  app.use(traceMiddleware(tracer));
  app.get(route, async (req, res) => {
    try { await handler(req, res, tools); } catch (e) { tools.log("error", { error: e.message }); res.status(500).json({ error: e.message }); }
  });
  app.listen(port);
};

svc("inventory", 3002, "/stock", async (req, res, { log, span }) => {
  log("checking stock", { sku: req.query.sku });
  await span("SELECT stock", { "db.system": "postgresql", "db.query.text": "SELECT qty FROM stock WHERE sku = $1" }, async () => {
    if (req.query.sku === "boom") throw new Error("stock table locked");
    await sleep(req.query.sku === "slow" ? 400 : 20);
  });
  res.json({ sku: req.query.sku, stock: 7 });
});

svc("orders", 3001, "/orders", async (req, res, { log, fetch, span }) => {
  log("creating order", { sku: req.query.sku });
  const r = await fetch(`http://localhost:3002/stock?sku=${req.query.sku}`);
  if (!r.ok) return res.status(502).json({ error: "inventory failed" });
  await span("INSERT orders", { "db.system": "postgresql" }, () => sleep(10));
  res.json({ order: 1, ...(await r.json()) });
});

svc("gateway", 3000, "/checkout", async (req, res, { log, fetch, span }) => {
  log("checkout", { sku: req.query.sku });
  await span("auth", {}, () => sleep(5));
  const r = await fetch(`http://localhost:3001/orders?sku=${req.query.sku}`);
  res.status(r.status).json(await r.json());
});
console.log("on 3000");