Diagnostic Slack
expired_trigger_id: the modal opened a moment too late
Clicking the button opens the modal about four times out of five. The fifth time the user gets We had some trouble connecting. Try again?, clicks again, and it works. Nobody can reproduce it on a laptop, and it happens constantly in production on Monday mornings.
The logs show views.open returning {"ok": false, "error": "expired_trigger_id"} after 400 milliseconds. Four hundred milliseconds, against a limit everyone remembers as three seconds. The number in the documentation is the ceiling, and what you actually have is whatever is left of it once the click has crossed the internet twice.
A trigger_id is not a session, a token or a handle. It is a single-use permission to interrupt one person with one view, and it expires almost immediately — nominally three seconds from the interaction, in practice often much less, because the clock starts when the user clicks and not when your handler wakes up.
Three errors come out of this and they mean three different things. expired_trigger_id: you were too slow, and everything you did before views.open is why. exchanged_trigger_id: this trigger was already spent, and a trigger opens exactly one view. invalid_trigger_id: the value is not a trigger at all — truncated, from a different payload, or logged and copied by hand.
The repair is one sentence with no exceptions in it: call views.open as the first thing the handler does, before the database read, before the API call, before anything. Open a modal that says Loading, get back a view.id, and fill it in with views.update when the data arrives. views.update takes a view_id and has no deadline at all.
None of this is visible to a read-only token, which is the honest limit here: Slack does not expose trigger state. What is visible is your own timing ledger, which decides it, and the workspace, which shows the side effects that never landed because the modal never opened.
The problem in plain words
The reason this is hard to see is that the budget is spent before your code is involved. Three seconds is measured from the interaction, and by the time the payload reaches your handler it has crossed the internet, been queued by your load balancer, and possibly started a cold container. Reports of expiry inside 500 milliseconds of handler time are common, which means the visible margin can be a fraction of what the documentation implies. You are not spending three seconds. You are spending what is left.
So the ordinary things a handler does become the bug. A lookup in the installation store. A permissions check against your own database. Fetching the options for a select menu so the modal can be rendered fully populated — which is the most reasonable-looking mistake in the whole category, because it produces a better modal and it is exactly the thing that must not happen first.
Single use is the second half. A trigger opens one view. A handler that opens a modal and then pushes a second one onto the stack with the same trigger_id gets exchanged_trigger_id, and every retry of that handler does the same. Slack does hand you a fresh trigger_id on the view_submission payload precisely so you can open a follow-up view after a submit — and code that reaches for the trigger it captured at the start of the flow will use a value that was spent two views ago.
Retries make both worse. When a handler is slow enough to miss the ack, Slack retries the delivery, and the retry arrives carrying a trigger that is now even older. The user clicks again out of frustration, which generates a genuinely fresh trigger, and that one works — which is why the bug presents as intermittent and unreproducible rather than as a deadline.
And a failed views.open is quiet in the wrong way. The user gets a generic connection message, your handler logs one line, and the work the modal was meant to collect simply never happens. There is no half-finished record to find later. The absence is the only evidence.
Why it happens
This deadline is not the ack deadline, and confusing them sends you to the wrong repair. The three-second ack is about returning 2xx and can be satisfied by acknowledging and then working in the background. The trigger deadline cannot: views.open is the work, and moving it into a background queue guarantees expiry. One is fixed by deferring, the other by refusing to defer.
The three errors are three different bugs wearing similar names. Slow, spent and malformed want different fixes, and a handler that retries on all three will loop forever on two of them. The script maps each error to its own cause so the retry policy can too.
The measurement that matters is the handler's own, and only you have it. Slack reports nothing about trigger state, so the ledger is the instrument: when the payload arrived, when views.open was called, what happened in between. Anything under about 150 milliseconds means the call really is first; anything above a second is living on margin that Monday morning will take away.
A trigger used twice is a structural bug, not a slow one. Making the handler faster does nothing for exchanged_trigger_id, and the reflex fix — adding a retry — makes it worse. Counting how often each trigger appears in the ledger separates the two before anyone starts optimising the wrong thing.
Passing a trigger to a call that does not want one is worth naming. views.update identifies a view by view_id. Code that carries a trigger into it has usually misunderstood the model, and that misunderstanding is what produces the reuse in the first place.
The workspace holds the consequence, even though it cannot hold the cause. A modal that never opened is a record that never appeared. If the ledger says the flow started and the channel has nothing to show for it, the missing side effect confirms that these failures are costing real work rather than only producing log lines.
The fix, as a flow
The red box is the fourth one, and every box before it is correct. The payload was valid, the handler woke up, the database answered, the modal was built properly and the call was well formed. It simply arrived after a permission that started counting down when the user clicked, not when your process did. The fix branch sorts by cause rather than by error string, and only the top row is one that going faster will fix.
How to fix it
Record two timestamps per interaction and nothing else
The ledger needs the moment the payload arrived and the moment views.open was called. Everything else in this note is derived from that pair. If your handler does not record them, adding two lines is the first change, because no amount of reading Slack will recover them afterwards.
Check the shape before you interpret the timing
trigger_shape returns usable, not-three-parts, non-numeric-head, not-a-string or missing. A trigger is three dot-separated parts and the first two are numeric. A value that fails this was never going to work at any speed, and it usually means the payload was parsed wrongly or the value was copied out of a log by hand.
Turn each pair of timestamps into a budget verdict
budget returns first-thing under 150 milliseconds, tight under a second, at-risk under three, and expired beyond. The thresholds are deliberately stricter than the documented limit, because the documented limit is measured from the click and you only ever see part of it.
Map every observed error to its own cause
classify separates too-slow, already-spent and malformed. This is the step that decides your retry policy: retrying is defensible for the first, pointless for the second and harmful for the third, and a single catch-all retry treats them identically.
Count how many times each trigger was used
reuse_report finds every trigger_id appearing more than once in the ledger. Each one is an exchanged_trigger_id waiting to happen, and speed will not help. The usual source is a chained modal reusing the trigger it captured at the start rather than the fresh one on the current payload.
Look for the work that never landed
For entries that failed, landed reads conversations.history and asks whether the record the modal was meant to produce ever appeared. That is the read-only half of this note: Slack will not tell you about a trigger, but it will show you the absence of everything that trigger was supposed to lead to.
How to check it worked
Run it against your own interaction ledger and the channel your modals write into.
python3 slack_trigger_budget.py --ledger interactions.json --channel C024BE91L
# identity U024BE7LH in Acme
# ledger 412 interaction(s) read from interactions.json
# shape usable 412 of 412
# budget first-thing 97 tight 148 at-risk 141 expired 26
# budget at-risk i-3312 1180ms before views.open; the documented three
# seconds is measured from the click, not from your handler
# error too-slow 26 x expired_trigger_id
# the options query runs before views.open in this handler
# error already-spent 9 x exchanged_trigger_id
# reuse reused 9 trigger(s) used twice; a trigger opens exactly one view
# source stale-payload 9 entries reused the trigger from the opening payload
# instead of the fresh one on view_submission
# landed missing 35 flow(s) started and produced no record in C024BE91L
# verdict 35 of 412 interactions lost the modal
# repair: call views.open as the first statement, with a Loading view, then fill it
# in with views.update using the returned view.id
# repair: for a chained view use views.push with the trigger_id on the current
# payload; view_submission carries a new one for exactly thisThe full code
Six pure functions and one read, because the cause of this failure is not in Slack. trigger_shape and budget decide almost everything from your own two timestamps. classify keeps the three errors apart, which is what stops a retry policy from looping. reuse_report and source_fault cover the half of this that speed cannot fix. landed is the only one that touches the network, and it asks the workspace what the failures cost.
"""Measure how long your handlers wait before opening a modal, and why they fail.
Read only. Nothing here opens a view, pushes one, or acknowledges anything: a
trigger_id is single use, so a script that exercised one would consume it. The
timings come from a ledger your own handler writes, and the one Slack call made
here is conversations.history, to ask what the failed flows never produced.
Slack exposes no trigger state at all, which is the honest limit of this note.
What it exposes is the consequence: a modal that never opened is a record that
never appeared.
"""
import argparse
import json
import logging
import os
import sys
import requests
logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(message)s")
log = logging.getLogger("slack_trigger_budget")
API = "https://slack.com/api/"
# Deliberately stricter than the documented three seconds. That three seconds
# is measured from the moment the user clicked, and the handler only ever sees
# what is left after the round trip, the queue and any cold start.
FAST_MS = 150
TIGHT_MS = 1000
LIMIT_MS = 3000
# The two calls that spend a trigger. views.update takes a view_id and has no
# deadline, which is the whole basis of the repair.
NEEDS_TRIGGER = ("views.open", "views.push")
def trigger_shape(value):
"""Is this value shaped like a trigger_id at all? Pure.
Three dot-separated parts, the first two numeric. A value that fails this
was never going to work at any speed, and the usual cause is a payload
parsed wrongly or a value copied out of a log by hand.
"""
if value is None or (isinstance(value, str) and not value.strip()):
return ("missing", "no trigger_id on this entry. Interactions carry one and "
"view_submission carries a fresh one; a handler that has "
"none is reading the wrong field")
if not isinstance(value, str):
return ("not-a-string", "a %s. A trigger_id is an opaque string and any "
"numeric handling of it destroys it"
% type(value).__name__)
parts = value.strip().split(".")
if len(parts) != 3:
return ("not-three-parts", "%s has %d dot separated part(s) and a trigger_id "
"has three" % (value[:40], len(parts)))
if not (parts[0].isdigit() and parts[1].isdigit()):
return ("non-numeric-head", "%s does not start with two numeric parts"
% value[:40])
return ("usable", "shaped like a trigger_id")
def budget(received_ms, opened_ms):
"""How much of the trigger's life did the handler spend? Pure.
Returns (verdict, detail, elapsed_ms). first-thing is the only verdict that
means the handler is written the way this note asks for; everything else is
running on margin that a cold start will take away.
"""
try:
elapsed = float(opened_ms) - float(received_ms)
except (TypeError, ValueError):
return ("unmeasured", "the entry does not carry both timestamps, so the "
"handler cannot be judged. Record the arrival and the "
"views.open call", None)
if elapsed < 0:
return ("impossible", "views.open is recorded %.0fms before the payload "
"arrived, which is a clock or a field mix up rather "
"than a fast handler" % -elapsed, elapsed)
if elapsed < FAST_MS:
return ("first-thing", "%.0fms; views.open really is the first thing this "
"handler does" % elapsed, elapsed)
if elapsed < TIGHT_MS:
return ("tight", "%.0fms before views.open. It works today and it is the "
"first thing to break on a cold start" % elapsed, elapsed)
if elapsed < LIMIT_MS:
return ("at-risk", "%.0fms before views.open; the documented three seconds is "
"measured from the click, not from your handler, so the "
"real margin is smaller than this looks" % elapsed, elapsed)
return ("expired", "%.0fms before views.open, past the three second ceiling even "
"before the round trip is counted" % elapsed, elapsed)
def classify(error):
"""Which of the three trigger failures is this? Pure.
They want three different repairs, and a handler that retries all of them
identically will loop forever on two.
"""
err = str(error or "").strip()
if not err:
return ("no-error", "this interaction opened its view")
if err == "expired_trigger_id":
return ("too-slow", "the trigger had already expired when views.open ran. "
"Everything the handler did first is the cause; retrying "
"with the same trigger cannot succeed")
if err == "exchanged_trigger_id":
return ("already-spent", "this trigger had already opened a view. A trigger "
"opens exactly one, and speed has nothing to do with "
"it. Use the trigger on the current payload")
if err == "invalid_trigger_id":
return ("malformed", "Slack did not recognise the value as a trigger. It was "
"truncated, taken from the wrong field, or belongs to "
"another workspace")
if err in ("not_authed", "invalid_auth", "missing_scope", "channel_not_found"):
return ("unrelated", "%s is a token or target problem and has nothing to do "
"with the trigger" % err)
return ("unrecognised", "%s is not one of the trigger errors" % err)
def source_fault(entry):
"""Was the trigger taken from the payload in hand? Pure.
The reuse bug almost always looks like this: a flow captures the trigger it
was opened with and reaches for that one again three views later, when
every payload since has carried a fresh one.
"""
entry = entry or {}
used = str(entry.get("used_for") or "").strip()
origin = str(entry.get("trigger_from") or "").strip().lower()
if not used:
return ("unknown", "the entry does not say which call the trigger was used for")
if used not in NEEDS_TRIGGER:
return ("unnecessary", "%s does not take a trigger_id. views.update "
"identifies a view by view_id and has no deadline at "
"all, which is the call the slow work belongs behind"
% used)
if origin in ("earlier-payload", "original", "first", "captured"):
return ("stale-payload", "the trigger came from an earlier payload. Every "
"interaction carries its own, and view_submission "
"carries a fresh one for exactly this case")
if origin in ("this-payload", "current", "fresh"):
return ("fresh", "the trigger came from the payload being handled")
return ("unknown", "the entry does not say which payload the trigger came from")
def reuse_report(ledger):
"""Which triggers were spent more than once? Pure.
Returns (verdict, detail, repeats). This is the half of the note that speed
cannot fix, so it is counted separately from the timings.
"""
counts = {}
for entry in ledger or []:
tid = str((entry or {}).get("trigger_id") or "")
if tid:
counts[tid] = counts.get(tid, 0) + 1
repeats = {k: v for k, v in counts.items() if v > 1}
if not repeats:
return ("single-use", "every trigger in the ledger was used once", {})
return ("reused", "%d trigger(s) were used more than once. A trigger opens exactly "
"one view, so the second use fails with exchanged_trigger_id "
"however fast the handler is" % len(repeats), repeats)
def landed(marker, messages):
"""Did the work this flow was meant to produce ever appear? Pure.
A failed views.open leaves nothing behind: no half written record, no
partial message. The absence is the only evidence there is.
"""
needle = str(marker or "").strip()
if not needle:
return ("unmarked", "the entry carries no marker, so nothing can be looked for")
for msg in messages or []:
if needle in str((msg or {}).get("text") or ""):
return ("landed", "%s appears in the channel" % needle)
return ("missing", "%s never appeared. The flow started and produced nothing"
% needle)
def load_ledger(path):
raw = json.loads(open(path, encoding="utf-8").read())
if isinstance(raw, dict):
raw = raw.get("interactions") or raw.get("entries") or []
return [r for r in raw or [] if isinstance(r, dict)]
def main():
ap = argparse.ArgumentParser(description=__doc__)
ap.add_argument("--ledger", required=True,
help="a JSON file of interactions, each with trigger_id, "
"received_ms, opened_ms, used_for, trigger_from and error")
ap.add_argument("--channel", action="append", default=[],
help="a channel your modals write into; repeatable")
ap.add_argument("--limit", type=int, default=200,
help="messages to read per channel when checking side effects")
ap.add_argument("--token-env", default="SLACK_BOT_TOKEN",
help="environment variable holding the bot token")
ap.add_argument("--offline", action="store_true",
help="judge the ledger and make no API call at all")
args = ap.parse_args()
ledger = load_ledger(args.ledger)
log.info("ledger %d interaction(s) read from %s", len(ledger), args.ledger)
shapes, budgets, errors, sources = {}, {}, {}, {}
for entry in ledger:
sverdict, sdetail = trigger_shape(entry.get("trigger_id"))
shapes[sverdict] = shapes.get(sverdict, 0) + 1
if sverdict != "usable":
log.warning("shape %-16s %s %s", sverdict, entry.get("id") or "?",
sdetail)
bverdict, bdetail, _ = budget(entry.get("received_ms"), entry.get("opened_ms"))
budgets[bverdict] = budgets.get(bverdict, 0) + 1
if bverdict in ("at-risk", "expired", "impossible"):
log.warning("budget %-16s %s %s", bverdict, entry.get("id") or "?",
bdetail)
cause, cdetail = classify(entry.get("error"))
if cause != "no-error":
errors.setdefault(cause, [0, cdetail])
errors[cause][0] += 1
fverdict, fdetail = source_fault(entry)
if fverdict not in ("fresh", "unknown"):
sources.setdefault(fverdict, [0, fdetail])
sources[fverdict][0] += 1
log.info("shape %s", " ".join("%s %d" % kv for kv in sorted(shapes.items())))
log.info("budget %s", " ".join("%s %d" % kv for kv in sorted(budgets.items())))
for cause, (count, detail) in sorted(errors.items()):
log.warning("error %-16s %d entry(s); %s", cause, count, detail)
for verdict, (count, detail) in sorted(sources.items()):
log.warning("source %-16s %d entry(s); %s", verdict, count, detail)
rverdict, rdetail, repeats = reuse_report(ledger)
(log.warning if rverdict == "reused" else log.info)("reuse %-16s %s",
rverdict, rdetail)
lost = 0
if args.channel and not args.offline:
token = os.environ.get(args.token_env)
if not token:
log.error("set %s, or pass --offline to judge the ledger alone",
args.token_env)
return 2
s = requests.Session()
s.headers.update({"Authorization": "Bearer " + token})
who = s.get(API + "auth.test", timeout=30).json()
if who.get("ok") is not True:
log.error("auth.test unavailable %s", who.get("error"))
return 2
log.info("identity %s in %s", who.get("user_id"), who.get("team"))
for channel in args.channel:
body = s.get(API + "conversations.history", timeout=30,
params={"channel": channel,
"limit": str(args.limit)}).json()
if body.get("ok") is not True:
log.warning("history unavailable %s: %s", channel,
body.get("error"))
continue
messages = body.get("messages") or []
for entry in ledger:
if not entry.get("error"):
continue
verdict, detail = landed(entry.get("marker"), messages)
if verdict == "missing":
lost += 1
if lost:
log.warning("landed missing %d flow(s) started and produced "
"no record", lost)
failed = sum(count for cause, (count, _) in errors.items()
if cause in ("too-slow", "already-spent", "malformed"))
if failed or repeats or budgets.get("expired") or budgets.get("at-risk"):
log.warning("verdict %d interaction(s) lost the modal", failed or lost)
log.warning(" repair: call views.open as the first statement in the handler, "
"with a Loading view, then fill it in with views.update using the "
"view.id it returns")
log.warning(" repair: for a chained view use views.push with the trigger_id "
"on the current payload; view_submission carries a new one for "
"exactly this")
log.warning(" repair: retry expired_trigger_id never, since the trigger is "
"gone; fix the handler order instead")
return 1
log.info("verdict clean every interaction opened its view in time")
return 0
if __name__ == "__main__":
sys.exit(main())
/**
* Measure how long your handlers wait before opening a modal, and why they fail.
*
* Read only. Nothing here opens a view, pushes one, or acknowledges anything: a
* trigger_id is single use, so a script that exercised one would consume it.
* The timings come from a ledger your own handler writes, and the one Slack
* call made here is conversations.history.
*
* Slack exposes no trigger state at all, which is the honest limit of this
* note. What it exposes is the consequence: a modal that never opened is a
* record that never appeared.
*/
import { readFile } from 'node:fs/promises';
const API = 'https://slack.com/api/';
// Deliberately stricter than the documented three seconds, which is measured
// from the moment the user clicked. The handler only ever sees what is left.
const FAST_MS = 150;
const TIGHT_MS = 1000;
const LIMIT_MS = 3000;
// The two calls that spend a trigger. views.update takes a view_id and has no
// deadline, which is the whole basis of the repair.
const NEEDS_TRIGGER = ['views.open', 'views.push'];
/** Is this value shaped like a trigger_id at all? Pure. */
export function triggerShape(value) {
if (value === null || value === undefined
|| (typeof value === 'string' && !value.trim())) {
return ['missing', 'no trigger_id on this entry. Interactions carry one and '
+ 'view_submission carries a fresh one; a handler that has none is reading the '
+ 'wrong field'];
}
if (typeof value !== 'string') {
return ['not-a-string', `a ${typeof value}. A trigger_id is an opaque string and `
+ 'any numeric handling of it destroys it'];
}
const parts = value.trim().split('.');
if (parts.length !== 3) {
return ['not-three-parts', `${value.slice(0, 40)} has ${parts.length} dot `
+ 'separated part(s) and a trigger_id has three'];
}
if (!/^\d+$/.test(parts[0]) || !/^\d+$/.test(parts[1])) {
return ['non-numeric-head', `${value.slice(0, 40)} does not start with two `
+ 'numeric parts'];
}
return ['usable', 'shaped like a trigger_id'];
}
/**
* How much of the trigger's life did the handler spend? Pure.
* Returns [verdict, detail, elapsedMs].
*/
export function budget(receivedMs, openedMs) {
const a = Number(receivedMs);
const b = Number(openedMs);
if (receivedMs === null || receivedMs === undefined || openedMs === null
|| openedMs === undefined || !Number.isFinite(a) || !Number.isFinite(b)) {
return ['unmeasured', 'the entry does not carry both timestamps, so the handler '
+ 'cannot be judged. Record the arrival and the views.open call', null];
}
const elapsed = b - a;
if (elapsed < 0) {
return ['impossible', `views.open is recorded ${(-elapsed).toFixed(0)}ms before `
+ 'the payload arrived, which is a clock or a field mix up rather than a fast '
+ 'handler', elapsed];
}
if (elapsed < FAST_MS) {
return ['first-thing', `${elapsed.toFixed(0)}ms; views.open really is the first `
+ 'thing this handler does', elapsed];
}
if (elapsed < TIGHT_MS) {
return ['tight', `${elapsed.toFixed(0)}ms before views.open. It works today and it `
+ 'is the first thing to break on a cold start', elapsed];
}
if (elapsed < LIMIT_MS) {
return ['at-risk', `${elapsed.toFixed(0)}ms before views.open; the documented `
+ 'three seconds is measured from the click, not from your handler, so the real '
+ 'margin is smaller than this looks', elapsed];
}
return ['expired', `${elapsed.toFixed(0)}ms before views.open, past the three second `
+ 'ceiling even before the round trip is counted', elapsed];
}
/** Which of the three trigger failures is this? Pure. */
export function classify(error) {
const err = String(error ?? '').trim();
if (!err) return ['no-error', 'this interaction opened its view'];
if (err === 'expired_trigger_id') {
return ['too-slow', 'the trigger had already expired when views.open ran. '
+ 'Everything the handler did first is the cause; retrying with the same trigger '
+ 'cannot succeed'];
}
if (err === 'exchanged_trigger_id') {
return ['already-spent', 'this trigger had already opened a view. A trigger opens '
+ 'exactly one, and speed has nothing to do with it. Use the trigger on the '
+ 'current payload'];
}
if (err === 'invalid_trigger_id') {
return ['malformed', 'Slack did not recognise the value as a trigger. It was '
+ 'truncated, taken from the wrong field, or belongs to another workspace'];
}
if (['not_authed', 'invalid_auth', 'missing_scope', 'channel_not_found'].includes(err)) {
return ['unrelated', `${err} is a token or target problem and has nothing to do `
+ 'with the trigger'];
}
return ['unrecognised', `${err} is not one of the trigger errors`];
}
/** Was the trigger taken from the payload in hand? Pure. */
export function sourceFault(entry) {
const e = entry ?? {};
const used = String(e.used_for ?? '').trim();
const origin = String(e.trigger_from ?? '').trim().toLowerCase();
if (!used) {
return ['unknown', 'the entry does not say which call the trigger was used for'];
}
if (!NEEDS_TRIGGER.includes(used)) {
return ['unnecessary', `${used} does not take a trigger_id. views.update `
+ 'identifies a view by view_id and has no deadline at all, which is the call '
+ 'the slow work belongs behind'];
}
if (['earlier-payload', 'original', 'first', 'captured'].includes(origin)) {
return ['stale-payload', 'the trigger came from an earlier payload. Every '
+ 'interaction carries its own, and view_submission carries a fresh one for '
+ 'exactly this case'];
}
if (['this-payload', 'current', 'fresh'].includes(origin)) {
return ['fresh', 'the trigger came from the payload being handled'];
}
return ['unknown', 'the entry does not say which payload the trigger came from'];
}
/**
* Which triggers were spent more than once? Pure.
* Returns [verdict, detail, repeats].
*/
export function reuseReport(ledger) {
const counts = new Map();
for (const entry of ledger ?? []) {
const tid = String((entry ?? {}).trigger_id ?? '');
if (tid) counts.set(tid, (counts.get(tid) ?? 0) + 1);
}
const repeats = Object.fromEntries([...counts.entries()].filter(([, v]) => v > 1));
if (!Object.keys(repeats).length) {
return ['single-use', 'every trigger in the ledger was used once', {}];
}
return ['reused', `${Object.keys(repeats).length} trigger(s) were used more than `
+ 'once. A trigger opens exactly one view, so the second use fails with '
+ 'exchanged_trigger_id however fast the handler is', repeats];
}
/** Did the work this flow was meant to produce ever appear? Pure. */
export function landed(marker, messages) {
const needle = String(marker ?? '').trim();
if (!needle) {
return ['unmarked', 'the entry carries no marker, so nothing can be looked for'];
}
for (const msg of messages ?? []) {
if (String((msg ?? {}).text ?? '').includes(needle)) {
return ['landed', `${needle} appears in the channel`];
}
}
return ['missing', `${needle} never appeared. The flow started and produced nothing`];
}
function arg(args, name, fallback = null) {
const i = args.indexOf(name);
return i === -1 ? fallback : args[i + 1];
}
function argAll(args, name) {
const out = [];
for (let i = 0; i < args.length; i += 1) {
if (args[i] === name && args[i + 1] !== undefined) out.push(args[i + 1]);
}
return out;
}
async function main() {
const args = process.argv.slice(2);
const ledgerFile = arg(args, '--ledger', '');
if (!ledgerFile) {
console.error('pass --ledger FILE with your recorded interaction timings');
process.exitCode = 2;
return;
}
let ledger = JSON.parse(await readFile(ledgerFile, 'utf8'));
if (!Array.isArray(ledger)) ledger = ledger.interactions ?? ledger.entries ?? [];
ledger = ledger.filter((r) => r && typeof r === 'object');
console.log(`ledger ${ledger.length} interaction(s) read from ${ledgerFile}`);
const shapes = {};
const budgets = {};
const errors = new Map();
const sources = new Map();
for (const entry of ledger) {
const [sv, sd] = triggerShape(entry.trigger_id);
shapes[sv] = (shapes[sv] ?? 0) + 1;
if (sv !== 'usable') {
console.warn(`shape ${sv.padEnd(16)} ${entry.id ?? '?'} ${sd}`);
}
const [bv, bd] = budget(entry.received_ms, entry.opened_ms);
budgets[bv] = (budgets[bv] ?? 0) + 1;
if (['at-risk', 'expired', 'impossible'].includes(bv)) {
console.warn(`budget ${bv.padEnd(16)} ${entry.id ?? '?'} ${bd}`);
}
const [cause, cd] = classify(entry.error);
if (cause !== 'no-error') {
const row = errors.get(cause) ?? [0, cd];
errors.set(cause, [row[0] + 1, cd]);
}
const [fv, fd] = sourceFault(entry);
if (fv !== 'fresh' && fv !== 'unknown') {
const row = sources.get(fv) ?? [0, fd];
sources.set(fv, [row[0] + 1, fd]);
}
}
console.log(`shape ${Object.entries(shapes).sort()
.map(([k, v]) => `${k} ${v}`).join(' ')}`);
console.log(`budget ${Object.entries(budgets).sort()
.map(([k, v]) => `${k} ${v}`).join(' ')}`);
for (const [cause, [count, detail]] of [...errors.entries()].sort()) {
console.warn(`error ${cause.padEnd(16)} ${count} entry(s); ${detail}`);
}
for (const [verdict, [count, detail]] of [...sources.entries()].sort()) {
console.warn(`source ${verdict.padEnd(16)} ${count} entry(s); ${detail}`);
}
const [rv, rd, repeats] = reuseReport(ledger);
const reuseLine = `reuse ${rv.padEnd(16)} ${rd}`;
if (rv === 'reused') console.warn(reuseLine); else console.log(reuseLine);
let lost = 0;
const channels = argAll(args, '--channel');
if (channels.length && !args.includes('--offline')) {
const tokenEnv = arg(args, '--token-env', 'SLACK_BOT_TOKEN');
const token = process.env[tokenEnv];
if (!token) {
console.error(`set ${tokenEnv}, or pass --offline to judge the ledger alone`);
process.exitCode = 2;
return;
}
const headers = { Authorization: `Bearer ${token}` };
const who = await (await fetch(`${API}auth.test`, { headers })).json();
if (who.ok !== true) {
console.error(`auth.test unavailable ${who.error}`);
process.exitCode = 2;
return;
}
console.log(`identity ${who.user_id} in ${who.team}`);
const limit = arg(args, '--limit', '200');
for (const channel of channels) {
const qs = new URLSearchParams({ channel, limit: String(limit) }).toString();
// eslint-disable-next-line no-await-in-loop
const body = await (await fetch(`${API}conversations.history?${qs}`, { headers })).json();
if (body.ok !== true) {
console.warn(`history unavailable ${channel}: ${body.error}`);
continue;
}
for (const entry of ledger) {
if (!entry.error) continue;
if (landed(entry.marker, body.messages ?? [])[0] === 'missing') lost += 1;
}
}
if (lost) {
console.warn(`landed missing ${lost} flow(s) started and produced `
+ 'no record');
}
}
const failed = [...errors.entries()]
.filter(([cause]) => ['too-slow', 'already-spent', 'malformed'].includes(cause))
.reduce((sum, [, [count]]) => sum + count, 0);
if (failed || Object.keys(repeats).length || budgets.expired || budgets['at-risk']) {
console.warn(`verdict ${failed || lost} interaction(s) lost the modal`);
console.warn(' repair: call views.open as the first statement in the handler, with '
+ 'a Loading view, then fill it in with views.update using the view.id it returns');
console.warn(' repair: for a chained view use views.push with the trigger_id on the '
+ 'current payload; view_submission carries a new one for exactly this');
console.warn(' repair: retry expired_trigger_id never, since the trigger is gone; '
+ 'fix the handler order instead');
process.exitCode = 1;
} else {
console.log('verdict clean every interaction opened its view in time');
}
}
// Only run when invoked directly, so importing this module in the tests does
// not execute main() and fail the file on a missing ledger.
if (import.meta.url === `file://${process.argv[1]}`) {
main().catch((err) => { console.error(err.message); process.exitCode = 2; });
}
Add a test
The thresholds are the argument, so they are the tests. budget has to call 140 milliseconds first-thing and 1200 at-risk, because the whole note is that a limit you comfortably meet on a warm afternoon is not margin. classify has to keep too-slow and already-spent apart, since one of them is worth retrying and the other will fail identically forever. And reuse_report has to find a trigger used twice even when both uses are fast, because that failure has nothing to do with time.
from slack_trigger_budget import (budget, classify, landed, reuse_report,
source_fault, trigger_shape)
GOOD = "13245.67890.abcdef"
def entry(**kw):
row = {"id": "i-1", "trigger_id": GOOD, "received_ms": 1000, "opened_ms": 1050,
"used_for": "views.open", "trigger_from": "this-payload", "error": ""}
row.update(kw)
return row
def test_three_dotted_parts_with_numeric_heads_is_usable():
assert trigger_shape(GOOD)[0] == "usable"
def test_a_trigger_with_the_wrong_number_of_parts_is_named():
verdict, detail = trigger_shape("13245.67890")
assert verdict == "not-three-parts"
assert "has three" in detail
def test_a_non_numeric_head_is_its_own_verdict():
assert trigger_shape("abc.def.ghi")[0] == "non-numeric-head"
def test_a_number_is_refused_rather_than_stringified():
verdict, detail = trigger_shape(13245.6789)
assert verdict == "not-a-string"
assert "opaque string" in detail
def test_a_missing_trigger_points_at_the_field_being_read():
for value in (None, "", " "):
verdict, detail = trigger_shape(value)
assert verdict == "missing"
assert "wrong field" in detail
def test_opening_immediately_is_the_only_good_verdict():
verdict, detail, elapsed = budget(1000, 1140)
assert verdict == "first-thing"
assert elapsed == 140
assert "first thing" in detail
def test_a_few_hundred_milliseconds_is_already_tight():
assert budget(1000, 1600)[0] == "tight"
def test_over_a_second_is_at_risk_and_says_why_the_margin_is_smaller():
verdict, detail, _ = budget(1000, 2200)
assert verdict == "at-risk"
assert "measured from the click" in detail
def test_past_three_seconds_is_expired():
assert budget(1000, 4500)[0] == "expired"
assert budget(1000, 4000)[0] == "expired"
def test_a_negative_elapsed_is_a_clock_problem_not_a_fast_handler():
verdict, detail, _ = budget(2000, 1000)
assert verdict == "impossible"
assert "clock" in detail
def test_missing_timestamps_are_unmeasured_rather_than_zero():
assert budget(None, 1000)[0] == "unmeasured"
assert budget(1000, None)[0] == "unmeasured"
assert budget("soon", 1000)[0] == "unmeasured"
def test_the_three_trigger_errors_get_three_causes():
assert classify("expired_trigger_id")[0] == "too-slow"
assert classify("exchanged_trigger_id")[0] == "already-spent"
assert classify("invalid_trigger_id")[0] == "malformed"
def test_too_slow_and_already_spent_are_never_collapsed():
assert classify("expired_trigger_id")[0] != classify("exchanged_trigger_id")[0]
assert "cannot succeed" in classify("expired_trigger_id")[1]
assert "speed has nothing to do with it" in classify("exchanged_trigger_id")[1]
def test_an_empty_error_means_the_view_opened():
assert classify("")[0] == "no-error"
assert classify(None)[0] == "no-error"
def test_a_token_error_is_not_dressed_up_as_a_trigger_error():
verdict, detail = classify("missing_scope")
assert verdict == "unrelated"
assert "nothing to do with the trigger" in detail
def test_an_unknown_error_is_not_guessed_at():
assert classify("ratelimited")[0] == "unrecognised"
def test_a_trigger_from_the_current_payload_is_fresh():
assert source_fault(entry())[0] == "fresh"
def test_a_trigger_carried_from_an_earlier_payload_is_the_reuse_bug():
verdict, detail = source_fault(entry(trigger_from="earlier-payload"))
assert verdict == "stale-payload"
assert "view_submission carries a fresh one" in detail
def test_a_trigger_handed_to_views_update_is_unnecessary():
verdict, detail = source_fault(entry(used_for="views.update"))
assert verdict == "unnecessary"
assert "no deadline" in detail
def test_an_entry_that_does_not_say_is_unknown_rather_than_fine():
assert source_fault(entry(trigger_from=""))[0] == "unknown"
assert source_fault(entry(used_for=""))[0] == "unknown"
def test_a_trigger_used_twice_is_found_even_when_both_uses_are_fast():
ledger = [entry(id="i-1", opened_ms=1010), entry(id="i-2", opened_ms=1010)]
verdict, detail, repeats = reuse_report(ledger)
assert verdict == "reused"
assert repeats == {GOOD: 2}
assert "however fast the handler is" in detail
def test_distinct_triggers_are_single_use():
ledger = [entry(trigger_id="1.2.aa"), entry(trigger_id="1.3.bb")]
assert reuse_report(ledger)[0] == "single-use"
assert reuse_report([])[0] == "single-use"
def test_a_marker_in_the_channel_means_the_flow_finished():
verdict, _ = landed("REQ-4127", [{"text": "opened REQ-4127 for review"}])
assert verdict == "landed"
def test_an_absent_marker_is_the_only_evidence_there_is():
verdict, detail = landed("REQ-4127", [{"text": "something else"}])
assert verdict == "missing"
assert "produced nothing" in detail
def test_no_marker_is_not_reported_as_a_missing_record():
assert landed("", [{"text": "anything"}])[0] == "unmarked"
import { test } from 'node:test';
import assert from 'node:assert/strict';
import {
budget, classify, landed, reuseReport, sourceFault, triggerShape,
} from './slack-trigger-budget.mjs';
const GOOD = '13245.67890.abcdef';
const entry = (over = {}) => ({
id: 'i-1', trigger_id: GOOD, received_ms: 1000, opened_ms: 1050,
used_for: 'views.open', trigger_from: 'this-payload', error: '', ...over,
});
test('three dotted parts with numeric heads is usable', () => {
assert.equal(triggerShape(GOOD)[0], 'usable');
});
test('a trigger with the wrong number of parts is named', () => {
const [verdict, detail] = triggerShape('13245.67890');
assert.equal(verdict, 'not-three-parts');
assert.match(detail, /has three/);
});
test('a non numeric head is its own verdict', () => {
assert.equal(triggerShape('abc.def.ghi')[0], 'non-numeric-head');
});
test('a number is refused rather than stringified', () => {
const [verdict, detail] = triggerShape(13245.6789);
assert.equal(verdict, 'not-a-string');
assert.match(detail, /opaque string/);
});
test('a missing trigger points at the field being read', () => {
for (const value of [null, undefined, '', ' ']) {
const [verdict, detail] = triggerShape(value);
assert.equal(verdict, 'missing');
assert.match(detail, /wrong field/);
}
});
test('opening immediately is the only good verdict', () => {
const [verdict, detail, elapsed] = budget(1000, 1140);
assert.equal(verdict, 'first-thing');
assert.equal(elapsed, 140);
assert.match(detail, /first thing/);
});
test('a few hundred milliseconds is already tight', () => {
assert.equal(budget(1000, 1600)[0], 'tight');
});
test('over a second is at risk and says why the margin is smaller', () => {
const [verdict, detail] = budget(1000, 2200);
assert.equal(verdict, 'at-risk');
assert.match(detail, /measured from the click/);
});
test('past three seconds is expired', () => {
assert.equal(budget(1000, 4500)[0], 'expired');
assert.equal(budget(1000, 4000)[0], 'expired');
});
test('a negative elapsed is a clock problem not a fast handler', () => {
const [verdict, detail] = budget(2000, 1000);
assert.equal(verdict, 'impossible');
assert.match(detail, /clock/);
});
test('missing timestamps are unmeasured rather than zero', () => {
assert.equal(budget(null, 1000)[0], 'unmeasured');
assert.equal(budget(1000, undefined)[0], 'unmeasured');
assert.equal(budget('soon', 1000)[0], 'unmeasured');
});
test('the three trigger errors get three causes', () => {
assert.equal(classify('expired_trigger_id')[0], 'too-slow');
assert.equal(classify('exchanged_trigger_id')[0], 'already-spent');
assert.equal(classify('invalid_trigger_id')[0], 'malformed');
});
test('too slow and already spent are never collapsed', () => {
assert.notEqual(classify('expired_trigger_id')[0], classify('exchanged_trigger_id')[0]);
assert.match(classify('expired_trigger_id')[1], /cannot succeed/);
assert.match(classify('exchanged_trigger_id')[1], /speed has nothing to do with it/);
});
test('an empty error means the view opened', () => {
assert.equal(classify('')[0], 'no-error');
assert.equal(classify(null)[0], 'no-error');
});
test('a token error is not dressed up as a trigger error', () => {
const [verdict, detail] = classify('missing_scope');
assert.equal(verdict, 'unrelated');
assert.match(detail, /nothing to do with the trigger/);
});
test('an unknown error is not guessed at', () => {
assert.equal(classify('ratelimited')[0], 'unrecognised');
});
test('a trigger from the current payload is fresh', () => {
assert.equal(sourceFault(entry())[0], 'fresh');
});
test('a trigger carried from an earlier payload is the reuse bug', () => {
const [verdict, detail] = sourceFault(entry({ trigger_from: 'earlier-payload' }));
assert.equal(verdict, 'stale-payload');
assert.match(detail, /view_submission carries a fresh one/);
});
test('a trigger handed to views.update is unnecessary', () => {
const [verdict, detail] = sourceFault(entry({ used_for: 'views.update' }));
assert.equal(verdict, 'unnecessary');
assert.match(detail, /no deadline/);
});
test('an entry that does not say is unknown rather than fine', () => {
assert.equal(sourceFault(entry({ trigger_from: '' }))[0], 'unknown');
assert.equal(sourceFault(entry({ used_for: '' }))[0], 'unknown');
});
test('a trigger used twice is found even when both uses are fast', () => {
const ledger = [entry({ id: 'i-1', opened_ms: 1010 }),
entry({ id: 'i-2', opened_ms: 1010 })];
const [verdict, detail, repeats] = reuseReport(ledger);
assert.equal(verdict, 'reused');
assert.deepEqual(repeats, { [GOOD]: 2 });
assert.match(detail, /however fast the handler is/);
});
test('distinct triggers are single use', () => {
assert.equal(reuseReport([entry({ trigger_id: '1.2.aa' }),
entry({ trigger_id: '1.3.bb' })])[0], 'single-use');
assert.equal(reuseReport([])[0], 'single-use');
});
test('a marker in the channel means the flow finished', () => {
assert.equal(landed('REQ-4127', [{ text: 'opened REQ-4127 for review' }])[0], 'landed');
});
test('an absent marker is the only evidence there is', () => {
const [verdict, detail] = landed('REQ-4127', [{ text: 'something else' }]);
assert.equal(verdict, 'missing');
assert.match(detail, /produced nothing/);
});
test('no marker is not reported as a missing record', () => {
assert.equal(landed('', [{ text: 'anything' }])[0], 'unmarked');
});
FAQ
Is this the same three seconds as the acknowledgement deadline?
It is the same number and a different deadline, and the fixes point in opposite directions. The ack deadline is about returning a 2xx, and the standard repair is to acknowledge immediately and do the work in the background. The trigger deadline cannot be satisfied that way, because opening the view is the work: pushed into a background queue it is guaranteed to expire. Ack fast and open fast, in that order, both in the first few lines.
Why does it expire in under a second when the documentation says three?
Because the clock starts when the user clicks, not when your process wakes up. The payload crosses the internet, waits in whatever sits in front of your handler, and may start a cold container on the way. All of that is spent before your first line runs, and reports of expiry inside a few hundred milliseconds of handler time are common. Treat three seconds as a ceiling you never actually get.
How do I open a modal that needs data I have to fetch first?
Open it empty. Call views.open immediately with a small view that says Loading, keep the view.id it returns, fetch the data, then replace the content with views.update. views.update takes a view_id rather than a trigger and has no deadline, so all the slow work lives safely behind it.
I get exchanged_trigger_id on the second modal in a flow. Why?
Because a trigger opens exactly one view. Pushing a second view needs the trigger_id from the payload you are handling right now, not the one that opened the first view. This is also why view_submission payloads carry their own trigger_id: it exists so you can open something new after a submit, and reaching past it for the original value is the most common way this fails.
Can a read-only script detect this by asking Slack?
No, and it is worth being clear about that. Slack exposes no trigger state, so there is nothing to query. What a read can do is show the consequence: read the channel your modal-driven flow writes into and look for the records that were supposed to appear. A flow that started and left nothing behind is the failure with a cost attached to it.
Related field notes
- the other three second deadline, and the opposite repair
- when the view opens in time and Slack rejects the payload
- why the refusal came back looking like a success
Sources
Every figure in this note is traced to one of these. Prices are list rates and change — check them for your own region before acting.
- views.open method reference - Slack Docs
- views.push method reference - Slack Docs
- Handling user interaction - Slack Docs
- Modals - Slack Docs
If your setup is misbehaving in a way this note does not cover, message me on LinkedIn with what you are seeing.