ch39-observability

對應 39. Observability：logs、traces 與 tail

在 GitHub 上檢視·8 個檔案·6.1 KB

取得並執行

這個範例可以獨立 clone 執行，不依賴其他章節。

npx degit mrsuner/cloudflare-serverless-platform-manuals/examples/ch39-observability
cd ch39-observability
npm install

可用指令

npm run dev	# wrangler dev
npm run types	# wrangler types --env-interface Env

說明

ch39-observability — traces, spans and tail, measured locally

Companion example for chapter 39. Measured with wrangler 4.118.0, compatibility date 2026-07-24, on 2026-08-01.

npm install
npm run dev
# with the tail worker attached:
npx wrangler dev -c wrangler.jsonc -c tail-worker/wrangler.jsonc

Route	Shows
GET /probe/tracing	what cloudflare:workers’s tracing exposes, and four things setAttribute silently tolerates
GET /probe/nesting	nested spans, startActiveSpan, and enterSpan’s variadic argument passthrough
GET /probe/logs	structured vs unstructured console.log
GET /boom	throws, so you can look for it in the trace (spoiler: it isn’t there)

The local observability SQL API

wrangler dev exposes a queryable store of everything it recorded. Most of the numbers in chapter 39 came from here:

curl -X POST http://localhost:8787/cdn-cgi/local/explorer/api/local/observability/query \
  -H 'Content-Type: application/json' \
  -d '{"sql":"SELECT name, outcome, duration_ms, json(attributes) FROM spans ORDER BY rowid"}'

Two tables: spans and logs. The spans schema:

CREATE TABLE spans (
  trace_id     TEXT NOT NULL,
  span_id      TEXT NOT NULL,
  parent_id    TEXT,
  service      TEXT,
  name         TEXT,
  kind         TEXT,
  start_ms     INTEGER,
  duration_ms  INTEGER,          -- whole ms; NULL while the span is still running
  outcome      TEXT,
  error        TEXT,
  attributes   BLOB,
  created_at   TEXT DEFAULT (datetime('now')),
  PRIMARY KEY (trace_id, span_id)
)

logs carries trace_id, span_id, seq, ts_ms, level, message, operation — so logs and traces are correlated for you. No manual correlation id needed.

Finding 1 — an uncaught exception records outcome: "ok"

GET /boom throws and returns HTTP 500. The root span:

name | outcome | error
GET  | ok      | NULL

{ "faas.trigger": "http", "http.request.method": "GET",
  "url.full": "http://localhost:8787/boom",
  "faas.invocation_id": "1f5cf7b4…",
  "http.response.status_code": 500,
  "cloudflare.outcome": "ok",
  "cpu_time_ms": 0, "wall_time_ms": 0 }

The exception message appears nowhere in the trace — only in the wrangler console. The Tail Worker agrees: outcome: "ok", exceptionCount: 0, exceptions: [].

This is a local measurement (miniflare + local explorer); production Workers Traces may differ, and I had no account to check. Either way the operational advice is the same and costs nothing: alert on http.response.status_code >= 500, not on outcome != "ok".

Finding 2 — span.isTraced is always true under wrangler dev

The docs say isTraced goes false when the request is not sampled, so it is the correct guard for expensive attribute computation:

tracing.enterSpan("expensive", (span) => {
  if (span.isTraced) span.setAttribute("payload.digest", expensiveHash(body));
  return handle(body);
});

Measured across four configurations:

wrangler.jsonc	span.isTraced
traces.head_sampling_rate: 0.05	true
traces.head_sampling_rate: 0	true
traces.enabled: false	true
observability.enabled: false	true

Spans kept accumulating in the local store even with observability.enabled: false. So the false branch of if (span.isTraced) never executes locally — you cannot measure the saving, and you cannot catch a bug in that branch.

Finding 3 — setAttribute tolerates four things it shouldn’t

None of these throw:

span.setAttribute("ch39.kind", "probe");        // fine
span.setAttribute("ch39.cleared", undefined);   // documented no-op
span.setAttribute("ch39.bad", { a: 1 });        // type says boolean|number|string
span.end();
span.setAttribute("ch39.late", 1);              // after end()
span.end();                                     // again

What actually got stored:

{"ch39.kind":"probe","ch39.bad":"[object Object]"}

• An object is silently String()-ed to "[object Object]". If you want structure, JSON.stringify it yourself.
• Attributes set after end() are dropped without a warning (ch39.late is absent).
• Double end() is a no-op.

Finding 4 — structured vs stringified logs

/probe/logs emits five lines. From the logs table:

Written as	Stored message
console.log("plain string log, …")	["plain string log, not queryable by field"]
console.log(JSON.stringify({event,slug}))	["{\"event\":\"stringified\",\"slug\":\"abc\"}"]
console.log({event,slug,ms,ok})	[{"event":"structured","slug":"abc","ms":12,"ok":true}]
console.log({event,link:{slug,tenant}})	[{"event":"nested","link":{…}}]
console.error({event,code})	level error, object preserved

Rows two and three are the point: JSON.stringify before logging turns a queryable object into an opaque string.

Finding 5 — startActiveSpan exists, the docs deny it

tracing’s prototype carries enterSpan, startActiveSpan and Span. The custom-spans documentation page’s Limitations section still says:

No manual span lifetime management. Spans are always scoped to the enterSpan callback. You cannot start a span and end it later.

That stopped being true on 2026-07-28, when startActiveSpan() and span.end() shipped. Cite the changelog, not that page. enterSpan is not deprecated.

enterSpan(name, cb, ...args) passes its extra arguments straight through and returns whatever the callback returns:

tracing.enterSpan("outer", (outer, a: number, b: number) =>
  tracing.enterSpan("inner", () => a + b), 20, 22);   // -> 42, two nested spans

Finding 6 — the wrangler config schema is wider than the docs

From node_modules/wrangler/config-schema.json:

• observability has nested logs and traces objects. The wrangler configuration reference documents only the top-level enabled and head_sampling_rate.
• logs.head_sampling_rate is accepted by the schema but appears on no documentation page. Unverifiable — use the top-level one.
• All three levels are additionalProperties: false, so typos are rejected.
• streaming_tail_consumers exists (entries take only service, unlike tail_consumers which also takes environment). Nothing on developers.cloudflare.com mentions it.
• logpush’s own description warns: “This will not configure a corresponding Logpush job automatically.”

Finding 7 — Tail Workers develop fine locally, except for errors

npx wrangler dev -c wrangler.jsonc -c tail-worker/wrangler.jsonc

Measured TraceItem keys (18):

cpuTime, diagnosticsChannelEvents, dispatchNamespace, durableObjectId,
entrypoint, event, eventTimestamp, exceptions, executionModel, logs,
outcome, preview, scriptName, scriptTags, scriptVersion, tailAttributes,
truncated, wallTime

event for an HTTP invocation is { request, response }. Locally scriptName is null, and — per Finding 1 — exceptions never arrive, so the error-handling path of your Tail Worker cannot be developed here.

原始碼

• wrangler.jsonc
• package.json
• src/index.ts
• tail-worker/src/index.ts
• tail-worker/tsconfig.json
• tail-worker/wrangler.jsonc
• .gitignore
• tsconfig.json

wrangler.jsonc

{
  "$schema": "./node_modules/wrangler/config-schema.json",
  "name": "ch39-observability",
  "main": "src/index.ts",
  "compatibility_date": "2026-07-24",
  "observability": {
    "enabled": true,
    "head_sampling_rate": 1,
    "logs":   { "enabled": true, "head_sampling_rate": 1, "invocation_logs": true, "persist": true, "destinations": [] },
    "traces": { "enabled": true, "head_sampling_rate": 0.05, "persist": true, "destinations": [] }
  },
  "upload_source_maps": true,
  "tail_consumers": [{ "service": "ch39-tail" }]
}

package.json

{
  "name": "ch39-observability",
  "private": true,
  "type": "module",
  "scripts": { "dev": "wrangler dev", "types": "wrangler types --env-interface Env" },
  "devDependencies": { "wrangler": "^4.118.0", "typescript": "^5.9.2", "@types/node": "^22.0.0" }
}

src/index.ts

import { tracing } from "cloudflare:workers";

const t = (fn: () => unknown): Record<string, unknown> => {
  try {
    const v = fn();
    return { ok: v === undefined ? "(undefined)" : String(v) };
  } catch (e) {
    const err = e as Error;
    return { threwName: err.name, threw: String(err.message ?? e).slice(0, 200) };
  }
};

export default {
  async fetch(req: Request, _env: Env, _ctx: ExecutionContext): Promise<Response> {
    const url = new URL(req.url);

    // ---- What does `tracing` actually expose? --------------------------
    if (url.pathname === "/probe/tracing") {
      const shape = {
        tracingType: typeof tracing,
        keys: Object.getOwnPropertyNames(Object.getPrototypeOf(tracing)).sort(),
        enterSpan: typeof (tracing as unknown as Record<string, unknown>).enterSpan,
        startActiveSpan: typeof (tracing as unknown as Record<string, unknown>).startActiveSpan,
        Span: typeof (tracing as unknown as Record<string, unknown>).Span,
      };

      // isTraced tells you whether this span is actually being recorded --
      // the guard to put around expensive attribute computation.
      let inner: Record<string, unknown> = {};
      const returned = tracing.enterSpan("probe-span", (span) => {
        inner = {
          spanCtor: span.constructor?.name,
          isTraced: span.isTraced,
          setAttribute: t(() => span.setAttribute("ch39.kind", "probe")),
          setAttributeUndefined: t(() => span.setAttribute("ch39.cleared", undefined)),
          // Objects are not allowed: the type says boolean | number | string.
          setAttributeObject: t(() =>
            (span.setAttribute as unknown as (k: string, v: unknown) => void)("ch39.bad", { a: 1 }),
          ),
          end: t(() => span.end()),
          // What happens if you touch a span after end()?
          setAttributeAfterEnd: t(() => span.setAttribute("ch39.late", 1)),
          endTwice: t(() => span.end()),
        };
        return "return-value-passes-through";
      });

      return Response.json({ shape, inner, returned });
    }

    // ---- Nesting, and the callback-argument passthrough ----------------
    if (url.pathname === "/probe/nesting") {
      const result = tracing.enterSpan("outer", (outer, a: number, b: number) => {
        outer.setAttribute("ch39.depth", 0);
        return tracing.enterSpan("inner", (inner) => {
          inner.setAttribute("ch39.depth", 1);
          return a + b;
        });
      }, 20, 22);

      const active = tracing.startActiveSpan("active-outer", (span) => {
        span.setAttribute("ch39.variant", "startActiveSpan");
        return span.isTraced;
      });

      return Response.json({ nestedReturn: result, activeIsTraced: active });
    }

    // ---- Structured logging --------------------------------------------
    // Only JSON OBJECTS get their fields extracted and indexed. A string
    // (even a JSON-shaped one) stays an opaque message.
    if (url.pathname === "/probe/logs") {
      console.log("plain string log, not queryable by field");
      console.log(JSON.stringify({ event: "stringified", slug: "abc" }));
      console.log({ event: "structured", slug: "abc", ms: 12, ok: true });
      console.log({ event: "nested", link: { slug: "abc", tenant: "t1" } });
      console.error({ event: "boom", code: "E_DEMO" });
      return Response.json({ emitted: 5 });
    }

    if (url.pathname === "/boom") {
      throw new Error("ch39 deliberate failure");
    }

    return new Response(
      [
        "ch39-observability probes:",
        "  GET /probe/tracing  what cloudflare:workers `tracing` exposes",
        "  GET /probe/nesting  nested spans + argument passthrough",
        "  GET /probe/logs     structured vs unstructured console.log",
        "  GET /boom           throws, so you can find it in the trace",
      ].join("\n"),
      { headers: { "content-type": "text/plain" } },
    );
  },
} satisfies ExportedHandler<Env>;

tail-worker/src/index.ts

export default {
  // `events` is an ARRAY -- one TraceItem per invocation in the batch.
  async tail(events: TraceItem[], _env: unknown, _ctx: ExecutionContext): Promise<void> {
    for (const e of events) {
      console.log(JSON.stringify({
        tailShape: Object.keys(e).sort(),
        scriptName: e.scriptName,
        outcome: e.outcome,
        eventType: e.event ? Object.keys(e.event).sort() : null,
        logCount: e.logs?.length ?? 0,
        exceptionCount: e.exceptions?.length ?? 0,
        exceptions: e.exceptions?.map((x) => ({ name: x.name, message: x.message })) ?? [],
        diagnosticsChannelEvents: e.diagnosticsChannelEvents?.length ?? 0,
      }));
    }
  },
};

tail-worker/tsconfig.json

{
  "compilerOptions": {
    "target": "esnext", "lib": ["esnext"], "module": "esnext",
    "moduleResolution": "bundler", "types": ["../worker-configuration.d.ts"],
    "strict": true, "skipLibCheck": true, "noEmit": true, "isolatedModules": true
  },
  "include": ["src/**/*.ts"]
}

tail-worker/wrangler.jsonc

{
  "$schema": "../node_modules/wrangler/config-schema.json",
  "name": "ch39-tail",
  "main": "src/index.ts",
  "compatibility_date": "2026-07-24"
}

.gitignore

node_modules/
.wrangler/
worker-configuration.d.ts

tsconfig.json

{
  "compilerOptions": {
    "target": "esnext", "lib": ["esnext"], "module": "esnext",
    "moduleResolution": "bundler", "types": ["./worker-configuration.d.ts", "node"],
    "strict": true, "skipLibCheck": true, "noEmit": true, "isolatedModules": true
  },
  "include": ["src/**/*.ts", "worker-configuration.d.ts"]
}