testDevTracesEveryCall

tcmts.cli.test.e2e.traces.testDevTracesEveryCall · #pmer4wra · term

tcm dev --trace-calls: each call to one of the codebase's functions on the server is a span inside the call it was made in, so a server function's trace is the whole tree of what it ran, async calls included, its statements where they ran; and what it calls behaves as it did (its result, and its source written out).

import { okIn, plainEnv, strip, tcmBin, tempDir, withChildren } from "#codebase/tcmts/cli/test/e2e/harness";
import { hashOf } from "#codebase/tcmts/cli/test/e2e/jobs";
import { SHOP_CALLS } from "#codebase/tcmts/cli/test/e2e/traces";
import assert from "node:assert/strict";
import { spawn } from "node:child_process";
import fs from "node:fs";
import path from "node:path";

export const testDevTracesEveryCall = () =>
  withChildren(async (keep) => {
    const dir = tempDir("traces-calls");
    const tcm = (...args: string[]) => strip(okIn(dir, ...args));
    const waitFor = async (cond: () => boolean | Promise<boolean>, what: string, ms = 20000) => {
      for (
        const end = Date.now() + ms;
        Date.now() < end;
        await new Promise((r) => setTimeout(r, 200))
      )
        if (await cond()) return;
      throw new Error(`timed out waiting for ${what}`);
    };
    tcm("init");
    tcm("lib", "add", "tcm", "server", "--at", "lib.server");
    fs.writeFileSync(path.join(dir, "scratch.ts"), SHOP_CALLS);
    tcm("add");
    const child = keep(
      spawn(process.execPath, [tcmBin(), "dev", "shop.main", "--port", "0", "--trace-calls"], {
        cwd: dir,
        env: plainEnv(),
      }),
    );
    let out = "";
    child.stdout.setEncoding("utf8").on("data", (d: string) => (out += d));
    child.stderr.setEncoding("utf8").on("data", (d: string) => (out += d));
    await waitFor(
      () => /calls\s+each call to the codebase's functions is traced too/.test(out),
      "tcm dev",
    );
    const url = /url\s+(http:\/\/\S+)/.exec(out)![1]!;
    const call = async (name: string, args: unknown[], headers: Record<string, string> = {}) => {
      const r = await fetch(new URL(`/__tcm/rpc/${hashOf(dir, name)}`, url), {
        method: "POST",
        headers: { "content-type": "application/json", ...headers },
        body: JSON.stringify(args),
      });
      return { status: r.status, body: await r.text() };
    };
    for (const n of ["pear", "apple"]) assert.equal((await call("shop.add", [n])).status, 200);
    const trace = "e".repeat(32);
    const listed = await call("shop.list", [], { traceparent: `00-${trace}-${"f".repeat(16)}-01` });
    assert.deepEqual(
      JSON.parse(listed.body),
      ["APPLE", "PEAR"],
      "a traced function answers as it did",
    );
    assert.match(
      (await call("shop.sourceOfLabel", [])).body,
      /return name\.toUpperCase\(\)/,
      "and its source, written out, is its own",
    );

    await waitFor(
      () => /fn shop\.label/.test(tcm("traces", "--trace", trace.slice(0, 8))),
      "the calls' spans",
    );
    const tree = tcm("traces", "--trace", trace.slice(0, 8));
    // the server function, and inside it each call it made, what they called, and their statements
    assert.match(tree, /ms {2}call shop\.list\n/);
    assert.match(tree, /ms {4}fn shop\.names\n/);
    assert.match(tree, /ms {6}sql items SELECT/);
    assert.match(tree, /ms {4}fn shop\.order\n/);
    assert.equal(tree.match(/ms {6}fn shop\.label\n/g)?.length, 2, "each call its own span");
    assert.doesNotMatch(
      tree,
      /fn shop\.list/,
      "the server function's own call is its span already",
    );
    assert.match(tcm("traces"), /shop\.label\s+fn\s+2\s/);
  })

testDevTracesEveryCall

uses