DEV Community

ushiro
ushiro

Posted on

Your Worker Returned 500 and the Log Says `outcome: "ok"`

I run AI Change Watch, a small independent project that
crawls what 15 AI vendors publish about their own models — deprecation tables, lifecycle pages, pricing
and SDK releases — and records every time one of them changes.

It runs on Cloudflare Workers, which means that when someone tells me "your site 500'd an hour ago",
the obvious tool is useless. wrangler tail is a live stream. It shows you what is happening now.
It cannot show you an hour ago.

There is a way to read the past, and there are four traps in it that cost me most of a day.

The part that works

Workers can write their invocation logs to a queryable store, and a REST endpoint reads it back. First
the worker has to be opted in — this is the whole config:

// wrangler.jsonc
{
  "observability": { "enabled": true }
}
Enter fullscreen mode Exit fullscreen mode

Then you can ask for events in a time range:

curl -sX POST \
  "https://api.cloudflare.com/client/v4/accounts/$ACCOUNT/workers/observability/telemetry/query" \
  -H "Authorization: Bearer $CF_API_TOKEN" \
  -H "Content-Type: application/json" \
  -d '{
    "queryId": "anything",
    "timeframe": { "from": 1786000000000, "to": 1786003600000 },
    "limit": 500,
    "view": "events",
    "parameters": {
      "datasets": ["cloudflare-workers"],
      "filters": [
        { "id": "f1", "key": "$workers.event.response.status",
          "type": "number", "operation": "eq", "value": 500 }
      ]
    }
  }'
Enter fullscreen mode Exit fullscreen mode

from and to are epoch milliseconds, not ISO strings. A read-scoped API token is enough — the
one I already had for deploys worked unchanged.

Each event carries more than you would guess:

$workers.outcome                              ok | exceededCpu | canceled
$workers.cpuTimeMs  /  $workers.wallTimeMs
$workers.event.request.path  /  .search
$workers.event.request.headers['user-agent']
$workers.event.request.cf.asOrganization      the ASN owner
$workers.event.response.status
$metadata.error
Enter fullscreen mode Exit fullscreen mode

That is the tool. Now the traps.

Trap 1: a rendered 500 is a successful invocation

I started by filtering on the field that sounds right:

{ "key": "$workers.outcome", "operation": "eq", "value": "exceededCpu" }
Enter fullscreen mode Exit fullscreen mode

and found nothing, repeatedly, while the site was demonstrably returning 500s.

Because for every one of them:

$workers.outcome = "ok"
Enter fullscreen mode Exit fullscreen mode

The worker ran. It produced a response. It returned it. That the response was an error page is not the
runtime's problem — the invocation succeeded. outcome describes the worker, not the HTTP result.

So outcome is the wrong axis for application errors. Filter on $workers.event.response.status for
what the user saw, and read $metadata.error for the throw. outcome is for failures the runtime
itself noticed: CPU limit, cancellation.

This is worth internalising because it inverts the usual relationship. In most stacks "the request
failed" and "the handler failed" are the same event. At the edge they are two different fields — and
the one with the friendlier name is the one that will not tell you.

Trap 2: a wide time window silently undercounts

This is the one that actually cost me the day.

I asked for 5xx across a 24-hour window, got nine events, and concluded I was chasing a single bug. The
same 24 hours, walked in 4-hour slices and concatenated, returned 956 — across 92 URLs and three
unrelated causes.

I re-ran the comparison today, on 404s, to check it was not a one-off:

24h asked as one query      →  26 events
same 24h in 4h slices       → 266 events
Enter fullscreen mode Exit fullscreen mode

The single query returned 10% of what was there. Not a rounding difference — a different
conclusion. And nothing in the response says so: no truncation flag, no "results were sampled" field.
You get a well-formed answer that happens to be mostly missing.

So the loop, not the query:

const out = [];
for (let h = 24; h > 0; h -= 4) {
  const from = Date.now() - h * 3600_000;
  const to   = Date.now() - (h - 4) * 3600_000;
  const ev = await queryEvents({ from, to, limit: 500 });
  if (ev.length >= 500) console.warn(`slice ${h}h hit the limit — narrow it`);
  out.push(...ev);
}
Enter fullscreen mode Exit fullscreen mode

The ev.length >= 500 check matters as much as the slicing. A slice that returns exactly your limit is
truncated, and you have to narrow that slice further. Without the warning you cannot tell "500 events
happened" from "500 events fit".

Trap 3: exists matches empty strings, and includes ignores case

Two smaller ones, both of which produced confidently wrong numbers before I noticed.

operation: "exists" matches a key that is present but empty. I wanted requests Cloudflare had
identified as verified bots:

{ "key": "$workers.event.request.cf.verifiedBotCategory", "operation": "exists" }
Enter fullscreen mode Exit fullscreen mode

That field is present on every request and is "" on almost all of them, so the filter matched the
entire dataset and I briefly believed the whole site was bot traffic. Use exists only for keys
genuinely absent on what you are excluding — sec-fetch-mode is a real example, since non-browsers do
not send it.

operation: "includes" is case-insensitive. Filtering user agents for bot and for Bot returned
the identical 3,181 events. Convenient once you know; misleading if you were using case to separate two
populations.

Trap 4: event counts are not invocation counts

The events view and the dashboard's invocation count disagree, and both are right. On one day my web
worker showed 24,085 telemetry events against 8,772 invocations — roughly 2.7 events per
invocation.

So:

  • proportions — "what share of requests were 404s", "which UA dominates" — take from the events view
  • absolute totals — "how many requests did this worker serve" — take from workersInvocationsAdaptive in the GraphQL analytics API, not from counting events

Mixing them gives a number that is wrong by a factor you cannot see.

What I actually run now

// Past-tense debugging: "what 500'd between 3am and 4am".
async function queryEvents({ from, to, limit = 500, filters }) {
  const r = await fetch(
    `https://api.cloudflare.com/client/v4/accounts/${ACCOUNT}/workers/observability/telemetry/query`,
    { method: 'POST',
      headers: { Authorization: `Bearer ${TOKEN}`, 'Content-Type': 'application/json' },
      body: JSON.stringify({
        queryId: 'q', timeframe: { from, to }, limit, view: 'events',
        parameters: { datasets: ['cloudflare-workers'], filters },
      }) });
  const d = await r.json();
  return d?.result?.events?.events ?? [];
}
Enter fullscreen mode Exit fullscreen mode

…called from the slicing loop above, with the results grouped in plain JavaScript rather than by asking
the API to group them. (view: "calculations" with a groupBy on a high-cardinality key returns only a
few groups, quietly — the same failure mode as trap 2: a well-formed answer that is mostly missing.)

The retention window is limited. I have reliably queried three days back and would not build a workflow
that assumes more; for anything you need to keep, pull it out and store it yourself.

One more, learned the embarrassing way: cf.asOrganization is the ASN owner, not the bot. Requests
from "Anthropic, PBC" turned out to be a crawler that robots.txt already allowed, and "Amazon
Technologies" was PerplexityBot. Identify declared crawlers by user agent; use the ASN only to catch
traffic whose user agent is lying.

The one-line version

wrangler tail is for watching. For asking, use the telemetry API — and remember that outcome: "ok"
means the worker succeeded, not that your user did
, and that a query covering a wide window will hand
you a confident answer built from a tenth of the data.


The tracker this came out of is at aichangewatch.com — it watches AI
vendor docs for changes, and the 500s that started all this were a REST detail endpoint quietly falling
through to its collection endpoint.

Top comments (0)