Eighteen days ago I audited this blog's watchdogs and wrote that
1,973 runs had bought me 15 lines in the ledger.
That piece asked the watchdog three questions: is its list alive, what does it fall
over together with, and who closes its ledger. All three were questions of coverage
and delivery — is the watchdog looking at the right thing, and is it in a state to
look at all.
Today I came back with a fourth, and not having thought of it that day bothers me
more than the finding itself. Even if the watchdog watches the right workflow and
runs exactly on time, can it call what it sees a fault? Not a coverage
question, not a delivery question — a vocabulary question. How many words does the
alarm have for recognising trouble?
The answer is one.
Two channels, one word
failure-alert.yml has two jobs. The instant channel fires the moment a watched
workflow finishes and sends mail. Its gate is a single line:
if: ${{ github.event.workflow_run.conclusion == 'failure' }}
The hourly poll looks at every workflow, but what it asks the API is this:
"$API/actions/runs?status=failure&per_page=30"
I wrote the two channels on different days, out of different fears. I called one
event-driven and the other scheduled; I was pleased that one spoke by mail and the
other through an issue. That was where my sense of redundancy came from. Putting
them side by side today, I saw that both hang off the same string — the string
failure. Two channels, one word.
Backing up an alarm is not making the same sentence come out of two mouths.
Conclusion words are a list, not a set
GitHub's REST documentation enumerates the permitted values of the status
parameter on the run-listing endpoint one by one: completed, action_required,
cancelled, failure, neutral, skipped, stale, success, timed_out,
in_progress, queued, requested, waiting, pending. The parameter's own
description is explicit: "Returns workflow runs with the check run status or
conclusion that you specify."
timed_out stands there on its own. So failure does not mean "everything
that went wrong"; it means, letter for letter, failure.
I did not trust the documentation's word for it; the count ran against my own
repository's records. As of today 4,461 runs are retained (the oldest from 14
September, 19:05 UTC; anything earlier is deleted by my own log cleanup).
status= |
Runs |
|---|---|
failure |
20 |
cancelled |
15 |
timed_out |
0 |
action_required · stale · neutral
|
0 |
Then I pulled the run IDs of both sets and intersected them: the intersection is
empty. The twenty failure runs and the fifteen cancelled runs are entirely
different runs. Fifteen runs ended in a word that neither of my two channels can
read. They break down as 8 Social Media Post, 6 Deploy Only and 1 Push on main.
I also tried a value that isn't on the list, because the conclusion invalid YAML
produces is called startup_failure and it isn't there. I expected a 422:
$ gh api -i ".../actions/runs?status=startup_failure&per_page=1"
HTTP/2.0 200 OK → total_count: 0
$ gh api -i ".../actions/runs?status=zzzbogus&per_page=1"
HTTP/2.0 200 OK → total_count: 0
A made-up value gives the same answer. The API does not reject an unknown status;
it silently maps it to the empty set. Rejection would have shown me the
mistake. As it stands, an alarm querying a conclusion that does not exist reports
"zero problems" and looks right doing it.
The night of 27 September: seven cancellations in a row
Social Media Post runs hourly. Over 27–28 September it has 56 runs. Everything up
to 21:31 is green. Then comes this sequence:
| Run created (UTC) | Conclusion |
|---|---|
| 27 Sep 21:31:24 | success |
| 27 Sep 22:32:38 | cancelled |
| 27 Sep 23:30:35 | cancelled |
| 28 Sep 00:42:03 | cancelled |
| 28 Sep 01:32:27 | cancelled |
| 28 Sep 02:34:07 | cancelled |
| 28 Sep 03:35:25 | cancelled |
| 28 Sep 04:35:35 | cancelled |
| 28 Sep 05:07:15 | success |
Seven runs, back to back, cancelled. That night has an eighth cancellation too —
07:35:13 — but it is a different animal: its job started at 07:35:18 and was
cancelled at 07:39:35, so it was cut down while running. I could not work out the
reason from the records. The mechanism below explains the seven above, not the
eighth.
The run holding the group was not working, it was waiting
My first guess was "the 21:31 run hung and blocked everything behind it." That was
wrong, and being wrong is the heart of the matter.
The job of the run created at 21:31:24 started at 05:07:54 on 28 September and
finished at 05:10:50. The job took 2 minutes 56 seconds; before that it waited
7 hours 36 minutes 30 seconds in the queue. The runner it landed on is
mac-mustafaerbay-2-1790572065, a slot from the Mac pool. That was the day the
repository moved to the organisation; my own alarm file says so in its comments. I
cannot prove the migration caused the wait — I have no incident record for that
day — but it is certainly the day the runner pool changed hands. The run did not
break; it simply waited to be given a machine. Its conclusion says exactly that:
success.
Two durations must not be confused here. 7 hours 36 minutes is how long a single
run sat in the queue. The stretch in which the hourly poster executed nothing
at all is longer: from the job that finished at 20:33:02 on 27 September to the one
that finished at 05:10:50 on 28 September, 8 hours 37 minutes 48 seconds. (And
neither is the 7.0-hour watchdog absence from the 11 October piece — that was a
separate event, where the scheduler never woke the watchdog at all.)
What cancelled the seven runs behind it was not a fault but my own configuration.
social-post.yml says:
# Concurrency: ayni anda birden fazla run calismasin (race condition: ayni
# post iki kez paylasilmasin diye).
concurrency:
group: social-post
cancel-in-progress: false
I wrote that comment myself: my concern was the race condition, making sure the
same article wasn't shared twice. I put cancel-in-progress: false there in that
frame. The part of the documentation I had not read is in the second half. GitHub
first defines the queue: "When a concurrent job or workflow is queued, if another
job or workflow using the same concurrency group in the repository is in progress,
the queued job or workflow will be pending." Then it gives that queue's length:
"single (default): At most one job or workflow run can be pending in the
concurrency group." And then what happens next: "By default, any existing
pending job or workflow in the same concurrency group will be canceled and the
new queued job or workflow will take its place."
The queue is not a line, it's a single seat. The 22:32 run sits down; the 23:30 run
arrives, lifts it out and takes its place; 00:42 arrives and lifts out 23:30. For
seven hours every new run advanced by cancelling the one waiting before it. When I
wrote false I did not know I was protecting only the running job, and that
protecting the waiting one needed queue: max.
The alarm woke seven times and wrote nothing
This is the part where I stopped short.
Social Media Post is one of the four workflows the instant channel watches by name.
So the alarm did not miss these cancellations. The workflow_run event fires
regardless of the run's conclusion. That night the alert workflow has 26 runs; 11
of them are the hourly poll, concluding success. The seven that match the
cancellations are these:
| Alert run (UTC) | Conclusion |
|---|---|
| 27 Sep 23:30:37 | skipped |
| 28 Sep 00:42:06 | skipped |
| 28 Sep 01:32:31 | skipped |
| 28 Sep 02:34:10 | skipped |
| 28 Sep 03:35:28 | skipped |
| 28 Sep 04:35:38 | skipped |
| 28 Sep 05:07:18 | skipped |
Look at the timestamps: each lands two to four seconds after the next run was
created. That is the mechanism — the waiting run is cancelled the instant its
replacement arrives, and workflow_run fires at that moment. Seven cancellations,
seven wake-ups, seven skipped.
I opened one of those runs: both jobs were skipped. alert-on-failure was skipped
because the conclusion was not failure; scheduled-poll was skipped because the
event was not schedule. Both gates worked correctly. There is no bug in the
logic; the bug is in the string.
The worst state for an alarm is not silence. It is waking up, looking, saying
"that word isn't in my dictionary", and going back to sleep.
I had written about something similar on the kernel side:
a task sitting 55 seconds in D state produced zero warnings because it never hit
khungtaskd's threshold.
That day I thought it was a subtlety peculiar to the kernel. It isn't. The same
class of mistake is sitting in my own YAML, inside a six-line if.
So what did it cost me? Nothing
This is where I was going to write "seven shares were dropped." Before writing it I
went and checked, and I'm glad I did.
git log shows the whole night. That day's article was pushed at 16:33:54 UTC on
27 September, and the chore(social): mark posts as shared marker landed at
16:38:30 — shared within five minutes. The next article arrived at 06:17:36 on 28
September, its marker at 06:26:29. In between, across the window that contains
every one of the cancellations, no new article was published at all.
Sharper still: the run that finally executed at 05:10:50 and concluded success
produced no marker commit. For each platform the sharing script filters to
posts whose socialMedia flag is false; had anything been queued, that run would
have shared it. It didn't, because there was nothing to share.
So all seven cancelled runs were empty. The blind spot is real, the mechanism is
real, the loss is zero.
And that is exactly the uncomfortable part. My blind spot has been sitting there
for six months; the reason it has cost nothing so far is not my design but the
calendar being empty that night. Had an article been published at 23:00 in that
window, it would have waited unshared until 06:26 the next morning and no indicator
would have turned red. A blind spot looks free for as long as you don't measure it;
that zero is sampling luck, not safety.
The axis I wasn't measuring was the queue
The one number that could actually have seen this event was the number I never
looked at: how long a job waits for a machine.
So today's state went on the scale. Of the last 300 runs (23–29 October) 241
succeeded; I pulled the timestamps of those runs' 305 jobs. My baseline is the
interval from the run being created to the job starting (created_at →
started_at). Queue wait: median 4 seconds, mean 22 seconds, p90 32 seconds,
worst case 465 seconds. Only 26 of the 305 jobs waited longer than a minute.
Queueing amounts to 20.9% of total execution time. The sample is mixed: 28 jobs
were skipped without ever waiting for a machine, and 36 ran on GitHub's own
runners; both pull the distribution down.
The order of magnitude is clear all the same. 27 September's 27,390 seconds is
roughly 6,850 times that median — three and a half orders of magnitude. With a
distribution like that in hand, setting a threshold is easy. I had none, because I
was never counting that axis.
In the same runs I wanted to test another hypothesis: "maybe a step is swallowing
the error with continue-on-error". Of the 2,502 steps in those 241 green runs,
2,463 concluded success, 39 skipped and zero failure. But I can't present
that as a refutation: the repository's three continue-on-error lines live in
lighthouse-audit.yml and content-generate.yml, and neither workflow ran in the
window at all (Generate Content was retired in September; Lighthouse Audit has 2
runs in the entire record). The hypothesis wasn't falsified; it was untestable.
What I was looking for wasn't there, because there was no data to look at either.
timed_out won't save me
"Let me add timed_out to the vocabulary," I thought, and then I read the limits.
GitHub's documentation gives two separate rows for job execution time: "6 hours" on
GitHub's own runners, and "5 days" on self-hosted runners. The ceiling at run
level is 35 days.
Every workflow I wrote myself runs self-hosted; 241 of the 305 jobs measured above
ran on gitsrv slots. (The other 36 ran on GitHub's machines — the CodeQL default
setup, which has no runs-on file in the repository.) So the number that applies
to my own pipeline is five days. A run that hangs, in the queue or inside the job,
waits five days to become timed_out. For those five days its status is
in_progress; the ?status=failure query does not see it, and neither does a
timed_out filter, because it isn't that yet. Hanging is a state no word in the
conclusion vocabulary describes.
Prometheus's alerting guidance puts it another way: "Aim to have as few alerts as
possible, by alerting on symptoms that are associated with end-user pain rather
than trying to catch every possible way that pain could be caused." My gates were
watching a conclusion's label, not a symptom — and recognising just one of the ways
that label could be produced.
The second blind spot on the same line
Look at the poll's query once more: ?status=failure&per_page=30. The second thing
I missed while arguing about vocabulary is that 30.
Results come back newest first, and my own jq applies the 65-minute filter. So
for me to miss a failure, thirty newer failures must exist — which, given a
65-minute window, means more than thirty failures inside 65 minutes. Impossible on
an ordinary day; not impossible on a storm day. The gate goes blind exactly when it
is needed most, and I didn't notice while debating a single word.
What if I inverted the gate
"Write a denylist instead of an allowlist" is easy to say. I wanted the number
before saying it, because in alarm design the expensive mistake is not the gap,
it's the noise.
The window runs from 14 September 19:05 to today: 44.8 days. I applied three gates
to the same records:
| Gate | Events raised | Per day |
|---|---|---|
conclusion == 'failure' (today's) |
20 | 0.45 |
conclusion != 'success' (naive inverse) |
990 | 22.1 |
anything but success and skipped
|
35 | 0.78 |
The middle row shows why "just invert it" isn't enough: 955 of the retained runs
are skipped, and 954 of those are the alarm's own skipped wake-ups. The naive
inverse would produce 22 notifications a day; within a week I'd have filed them
into a filter, and that filter would become my new blind spot.
The third row works: 0.78 events a day, 75% more than today's gate, and that 75%
includes the seven cancellations of 27 September. Because it is written by leaving
two words out rather than adding two words in, a conclusion I haven't thought of
yet will still catch on the gate next time.
One caveat: this figure was computed from the records I still have, and those span
only 44.8 days. The ratio could shift over a longer window. What won't shift is
that the naive inverse produces noise.
A fourth question for the watchdog
I'm adding a fourth question to the three, and I think it's the cheapest of them,
because the answer is written down in the configuration file:
How many words does it have for a fault? Read the equality at the gate. If it
hangs off a single string, every conclusion outside that string is silence for you.
Then open your platform's list of conclusions and count it; the difference is the
size of your blind spot. Then ask about the states that aren't on the list at all:
hanging, waiting in a queue, never starting. Those aren't conclusions, they're
durations — a gate that filters on conclusions cannot see them.
Three changes follow for my own pipeline.
First, turn the gate into an exclusion. Writing cancelled and timed_out next to
failure means landing in the same place on the next conclusion type I haven't
considered; the table above shows the exclusion gate does the same job without the
noise.
Second, turn the seat into a line:
concurrency:
group: social-post
cancel-in-progress: false
queue: max
With two caveats: the documentation says queue: max cannot be combined with
cancel-in-progress: true (mine is false, so no problem), and the line's ceiling
is 100 — once it's full, overflowing runs are cancelled again. So this setting does
not remove the blind spot; it reinstates it at scale. There's also a duplicate-share
risk: the piled-up runs will execute back to back once the pool returns. In my
pipeline the socialMedia flag holds that line, but whoever opens the queue should
first confirm that flag survives a race.
Third, and this is the real one, add a single number that measures the symptom. In
my pipeline that number is the age of the most recent chore(social): mark posts as commit, given that an unshared published article exists. It never reads a
shared
conclusion, it needs no failure string, and it would not have turned red on the
night of 27 September either — because there genuinely was no unshared article.
That is what a good symptom alarm looks like: it does not invent a fault that isn't
there, and it doesn't miss one that is.
Conclusion
Nothing broke in this incident and nothing was lost. The code was right, the gates
worked correctly, the runner pool narrowed because of an overnight migration, the
system recovered on its own, and all seven cancelled runs were empty anyway.
What stayed with me was the kind of fault. The thing I wrote to watch my own
automation was looking for a word, not a class of failure. I wrote its
dictionary, and I put into it only what I was afraid of that day. The world the
alarm can see was exactly as wide as my imagination on the day I wrote it — and in
that world there was no such thing as cancelled.
The strangest part is that the blind spot cost me nothing for six months. When an
unmeasured risk never sends a bill, I confused the absence of the risk with the
absence of evidence. The question I'll ask before adding the next watchdog is no
longer "what should I watch": it's what's missing from the vocabulary of the
watchdogs I already have, and why that gap hasn't sent me a bill yet.
Official Sources
- GitHub REST API — List workflow runs for a repository (the full value list for the
statusparameter) - GitHub Actions — Workflow syntax:
concurrency,cancel-in-progressandqueuebehaviour (source of the three quotes above) - GitHub Actions — Concurrency concept: at most one pending run in the queue
- GitHub Actions — Limits: job execution time, 6 hours GitHub-hosted, 5 days self-hosted
- GitHub Actions — the
workflow_runevent and its activity types - Prometheus — Alerting: symptom-based alert design
Top comments (0)