Diagnostic Slack
Three seconds to acknowledge, and what you spend them on
Somebody submits the modal and gets We had some trouble connecting. Try again? The record was created. It was created twice, actually, and both times correctly. The slash command says operation_timeout and then does the thing anyway.
Nothing here is broken in the sense of producing a wrong answer. Every one of these symptoms is Slack telling you the same single fact: the answer arrived after the deadline, and the deadline is three seconds.
Slack requires an HTTP 2xx within three seconds for every event, every interaction payload and every slash command. Slower is not slow, it is failed: the delivery is counted as unsuccessful and retried, and enough of them in an hour will get event delivery switched off entirely. The clock starts on Slack's side, so DNS, TLS, gateway queueing and a cold start are all spending your budget before your code is reached.
The repair is one sentence and it belongs to this note rather than to any of its neighbours: acknowledge first, then do the work. What makes it worth a script is that the sentence is not always available. Some of the budget cannot be moved after the ack — a cold start is before your code, signature verification has to precede everything, and views.open has to happen inside three seconds of the trigger because that is how long the trigger_id lives. So the useful question is not "am I over" but "how much of this can move, and is what remains inside the budget on its own". The script splits your stage timings at the ack and answers exactly that, after measuring what one ordinary call to Slack costs from the host the handler runs on, because that is the number people leave out.
The problem in plain words
Three seconds sounds generous, and it is, right up until you write down what actually happens in a handler that feels instantaneous when you test it. A Lambda cold start is somewhere between 300 milliseconds and two seconds depending on the runtime and the size of the bundle. An installation-store lookup against a database in another region is 40 milliseconds on a good day and 400 on a bad one. One chat.postMessage is a round trip to Slack's API from wherever you are, which is rarely under 150 milliseconds and is occasionally much worse. A single call to the service the bot is actually a front end for is anything at all.
Add those up honestly and the surprise is not that handlers time out, it is that any of them do not. And the failure is peculiarly hard to read, because the work still happens. The ticket is created, the message is posted, the record is written. The only external sign is a red toast in somebody's Slack client and, later, the same work having happened three or four times. People spend a long time looking for a bug in code that has none, because the code is correct and merely late.
The other half of the problem is that "just ack first" is offered as universal advice and it is not universally available. On a platform that freezes the process the instant the response is returned, work scheduled after the ack simply does not run, and the app moves from timing out to silently dropping every job, which is worse. Deferring is a repair that requires somewhere to defer to.
Why it happens
The clock is Slack's, not yours. Your handler's own timer starts when the request reaches your code. Slack's started at the moment it sent the request, and it includes name resolution, the TLS handshake, whatever queueing your gateway does, and the cold start of the process that is about to serve it. A handler that logs 900 milliseconds of work can still miss a three second deadline without ever knowing.
Late is failed, and failed is retried. There is no partial credit and no separate timeout status. A 200 that arrives at 3.1 seconds is treated exactly like a connection refused: it is a failed delivery, it is retried on the standard schedule, and it counts towards the failure rate that gets subscriptions disabled. That is the whole reason this note sits upstream of two others.
Not all of the budget is deferrable, and the differences matter. Signature verification has to run before you trust the payload, so it is pre-ack by necessity, though it costs microseconds. A cold start is pre-ack because it is not your code. An installation-store lookup is pre-ack in most receivers but is cacheable, which is a different repair from deferring. And views.open is the awkward one: the trigger_id it needs expires in three seconds, so opening a modal cannot be moved into the background at all, only made fast.
Acking is not the same as answering. The 2xx is a receipt, not a reply. The actual answer goes back afterwards through response_url, which is valid for thirty minutes and up to five uses, or through an ordinary chat.postMessage. Handlers that time out are frequently handlers whose author thought the response body was the answer and so could not send it until the work was done.
On a function-as-a-service platform, "after the ack" may not exist. Returning the response can freeze the container, so a promise you did not await is a promise that never resolves. The deferral has to go somewhere durable — a queue, a job table, a second function — before the response is returned, and that hand-off is itself part of the pre-ack budget.
The fix, as a flow
This chain breaks at the acknowledgement rather than at any of the work, and the work is all correct: the ticket is created, the message is posted, the record is written. The fix branch is a split rather than a classification, because the question is not what went wrong but which side of the ack each stage belongs on, and the two red rows at the top are the cases where moving things does not help.
How to fix it
Price one round trip to Slack from the host that runs the handler
The script makes a handful of ordinary read calls and reports the median. This is the number nobody writes into their budget: if a call to Slack from your region costs 190 milliseconds, then a handler that posts a message and updates it inside the ack path has already spent close to 400 of its 3000 on network alone.
Write the stages down, including the ones that are not your code
Cold start, TLS, gateway, signature check, installation lookup, the downstream call, the Slack call, the ack. Take the numbers from whatever you already have — APM spans, structured log timings, a p95 out of CloudWatch. Guessed numbers produce a guessed verdict, which the script will happily print.
Split the list at the ack rather than summing it
Every stage is either something that must happen before the acknowledgement or something that can happen after it. The sum of the first group is the only number the deadline actually cares about, and it is usually a small fraction of the total, which is what makes the repair so effective when it is available.
Check whether deferring is even enough
If the pre-ack group alone is over three seconds, moving work into the background changes nothing and the finding is a cold start or a slow lookup, not an architecture. The script reports that as a separate verdict because it is the case where the standard advice is wrong.
Give the deferred work somewhere to go
A queue, a job row, a second process. Not a bare background task on a platform that freezes after the response, and not a fire-and-forget promise. The hand-off costs a few milliseconds and it happens before the ack, so it belongs in the pre-ack column where the script counts it.
Answer through response_url once you actually have an answer
Thirty minutes, five uses, and it turns a three second budget into a thirty minute one for everything except the receipt. For modals the constraint is different and stricter: trigger_id expires in three seconds, so the call that opens a view has to stay in the fast path.
How to check it worked
Re-run with the stage timings from after the change. The total will be roughly the same, which is the point: nothing got faster, the deadline just stopped applying to most of it.
python3 slack_ack_budget.py --stage cold_start=420 --stage signature_verification=2 \
--stage enqueue=15 --stage ack=3 --stage downstream_http=2600 --stage chat_postMessage=190
# api 190ms median of 5 read call(s) from this host
# budget pre-ack 440ms of 3000ms, 2560ms of headroom
# budget deferred 2790ms moved after the ack
# verdict fixed the deadline applies to 440ms of a 3230ms handlerThe full code
Three pure functions and a few timed GETs. stage_phase is the table that decides what can move, and the entries that cannot are the interesting ones. split_budget sums each side of the ack and produces four verdicts, one of which is that deferring will not save you. api_call_budget turns the measured round trip into a share of the deadline, which is the arithmetic that makes a handler with four Slack calls in it obviously wrong before anybody profiles anything.
"""Split a Slack handler's timings at the acknowledgement and price what is left.
Read only. The network half makes a handful of ordinary read calls and times
them, so the budget arithmetic uses this host's real round trip to Slack rather
than a guess. Nothing is sent to your own Request URL: timing that endpoint
means firing synthetic events at a production handler, which creates records
somebody has to clean up.
"""
import argparse
import logging
import os
import statistics
import sys
import time
import requests
logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(message)s")
log = logging.getLogger("slack_ack_budget")
API = "https://slack.com/api/"
# Every event, interaction payload and slash command wants a 2xx inside this,
# measured from Slack's side rather than from the moment your code is reached.
DEADLINE_MS = 3000
# What each stage is, with respect to the acknowledgement. The phases that are
# not "deferrable" are the whole reason this script exists: "ack first" is
# excellent advice that does nothing at all for a cold start.
STAGE_PHASES = {
"dns": ("before-your-code", "resolution, already spent when your process wakes"),
"tls": ("before-your-code", "the handshake, likewise"),
"gateway": ("before-your-code", "queueing and routing in front of the handler"),
"cold_start": ("before-your-code",
"the runtime booting; not code you can move after an ack"),
"signature_verification": ("must-precede-ack",
"has to run before the payload is trusted, and costs "
"microseconds when done right"),
"body_parse": ("must-precede-ack", "the payload has to be read to be answered"),
"installation_lookup": ("cacheable-pre-ack",
"a store lookup in the receiver; cache it rather than "
"defer it, because the receiver needs the answer"),
"token_lookup": ("cacheable-pre-ack", "the same shape of problem"),
"enqueue": ("must-precede-ack",
"handing the work to a queue is itself pre-ack, and is the cost "
"of being able to defer anything at all"),
"ack": ("must-precede-ack", "writing the 2xx"),
"views_open": ("hard-deadline",
"trigger_id expires three seconds after the interaction, so "
"opening a modal cannot be deferred, only made fast"),
"trigger_id_use": ("hard-deadline", "the same three second expiry"),
"downstream_http": ("deferrable", "the service the bot fronts"),
"database_write": ("deferrable", "record creation"),
"llm_call": ("deferrable", "generation, and never inside an ack path"),
"chat_postMessage": ("deferrable", "the answer, which is not the receipt"),
"chat_update": ("deferrable", "likewise"),
"response_url_post": ("deferrable",
"valid for thirty minutes and five uses, which is the "
"point of it"),
}
def stage_phase(name):
"""Place one stage relative to the acknowledgement. Pure.
Unknown stages are treated as deferrable and said to be assumed, because
guessing them into the pre-ack column would silently inflate the finding.
"""
key = str(name or "").strip()
if key in STAGE_PHASES:
return STAGE_PHASES[key]
return ("deferrable",
"not a stage this script knows; assumed deferrable, so check it")
def split_budget(stages, deadline_ms=DEADLINE_MS):
"""Sum each side of the ack and say whether deferring is enough. Pure.
``stages`` is a sequence of (name, milliseconds). Returns the two sums, the
headroom against the deadline, and one of four verdicts. The one worth
having is "over-even-deferred": the case where the usual advice does not
apply because the immovable half is already too slow.
"""
deadline = max(int(deadline_ms or 0), 1)
pre, deferred, hard = 0.0, 0.0, []
for name, ms in stages or []:
cost = max(float(ms or 0), 0.0)
phase, _why = stage_phase(name)
if phase == "deferrable":
deferred += cost
else:
pre += cost
if phase == "hard-deadline":
hard.append(str(name))
total = pre + deferred
headroom = deadline - pre
if total <= deadline:
verdict = "inside"
elif pre > deadline:
verdict = "over-even-deferred"
elif pre > deadline * 0.66:
verdict = "tight-after-deferring"
else:
verdict = "fixed-by-deferring"
return {"pre_ack_ms": round(pre, 1), "deferrable_ms": round(deferred, 1),
"total_ms": round(total, 1), "headroom_ms": round(headroom, 1),
"deadline_ms": deadline, "hard_deadline_stages": hard,
"verdict": verdict}
def api_call_budget(latency_ms, calls, deadline_ms=DEADLINE_MS):
"""Price the Slack calls a handler makes inside the ack path. Pure.
The measured round trip is the number people leave out of the budget
entirely. Four calls at two hundred milliseconds is nearly a third of the
deadline spent on network before any of your own work is counted.
"""
deadline = max(int(deadline_ms or 0), 1)
one = max(float(latency_ms or 0), 0.0)
n = max(int(calls or 0), 0)
cost = one * n
share = round(cost * 100.0 / deadline, 1)
if n == 0:
verdict = "none-in-path"
elif share >= 50.0:
verdict = "dominant"
elif share >= 20.0:
verdict = "significant"
else:
verdict = "minor"
return {"one_call_ms": round(one, 1), "calls": n, "cost_ms": round(cost, 1),
"share_percent": share, "deadline_ms": deadline, "verdict": verdict}
def time_read_calls(session, samples):
"""Time a few ordinary read calls. GET only, and deliberately few of them."""
timings = []
for _ in range(max(int(samples or 0), 1)):
started = time.monotonic()
r = session.get(API + "auth.test", timeout=30)
body = r.json()
elapsed = (time.monotonic() - started) * 1000.0
if body.get("ok") is not True:
return ([], "auth.test answered 200 with ok: false, error=%s"
% body.get("error"))
timings.append(elapsed)
return (timings, "")
def parse_stage(text):
name, _, value = str(text).partition("=")
try:
return (name.strip(), float(value))
except ValueError:
raise SystemExit("stage %r should look like name=milliseconds" % text)
def main():
ap = argparse.ArgumentParser(description=__doc__)
ap.add_argument("--token-env", default="SLACK_BOT_TOKEN",
help="environment variable holding the bot token")
ap.add_argument("--stage", action="append", default=[],
help="name=milliseconds, repeatable; take the numbers from "
"your own traces")
ap.add_argument("--calls-in-ack-path", type=int, default=0,
help="how many Slack API calls the handler makes before acking")
ap.add_argument("--samples", type=int, default=5,
help="how many read calls to time; keep it small")
args = ap.parse_args()
stages = [parse_stage(s) for s in args.stage]
one_call = 0.0
token = os.environ.get(args.token_env)
if not token:
log.info("api skipped set %s to measure this host's round "
"trip to Slack", args.token_env)
else:
s = requests.Session()
s.headers.update({"Authorization": "Bearer " + token})
timings, err = time_read_calls(s, args.samples)
if err:
log.warning("api unavailable %s", err)
else:
one_call = statistics.median(timings)
log.info("api %-14s median of %d read call(s) from this host",
"%dms" % int(one_call), len(timings))
if args.calls_in_ack_path:
call_cost = api_call_budget(one_call, args.calls_in_ack_path)
(log.info if call_cost["verdict"] in ("minor", "none-in-path")
else log.warning)(
"calls %-14s %d call(s) at %dms is %.1f%% of the %dms deadline",
call_cost["verdict"], call_cost["calls"], int(call_cost["one_call_ms"]),
call_cost["share_percent"], call_cost["deadline_ms"])
if not stages:
log.info("budget no-stages pass --stage name=milliseconds to "
"split a handler at the ack")
return 0
split = split_budget(stages)
log.info("budget pre-ack %.0fms of %dms, %.0fms of headroom",
split["pre_ack_ms"], split["deadline_ms"], split["headroom_ms"])
log.info("budget deferred %.0fms moved after the ack",
split["deferrable_ms"])
for name in split["hard_deadline_stages"]:
log.warning("budget hard-deadline %s cannot be deferred; trigger_id "
"expires in three seconds", name)
if split["verdict"] == "inside":
log.info("verdict inside the whole handler is %.0fms, under "
"the deadline as it stands", split["total_ms"])
return 0
if split["verdict"] == "over-even-deferred":
log.warning("verdict over-even-deferred %.0fms of immovable work "
"against a %dms deadline; acking first changes nothing here",
split["pre_ack_ms"], split["deadline_ms"])
log.warning(" repair: attack the pre-ack stages themselves. A cold start "
"is provisioned concurrency or a warmer runtime; an "
"installation lookup is a cache, not a queue")
return 1
(log.warning if split["verdict"] == "tight-after-deferring" else log.info)(
"verdict %-14s the deadline applies to %.0fms of a %.0fms handler",
split["verdict"], split["pre_ack_ms"], split["total_ms"])
log.warning(" repair: acknowledge first and hand the deferrable %.0fms to a "
"queue. On a platform that freezes the process after the "
"response, the hand-off has to be durable and has to happen "
"before the ack", split["deferrable_ms"])
log.warning(" repair: send the actual answer afterwards through response_url, "
"which is good for thirty minutes and five uses")
return 1
if __name__ == "__main__":
sys.exit(main())
/**
* Split a Slack handler's timings at the acknowledgement and price what is left.
*
* Read only. The network half makes a handful of ordinary read calls and times
* them, so the budget arithmetic uses this host's real round trip to Slack
* rather than a guess. Nothing is sent to your own Request URL.
*/
const API = 'https://slack.com/api/';
// Measured from Slack's side, not from the moment your code is reached.
const DEADLINE_MS = 3000;
// What each stage is with respect to the acknowledgement. The phases that are
// not 'deferrable' are the whole reason this script exists.
const STAGE_PHASES = new Map([
['dns', ['before-your-code', 'resolution, already spent when your process wakes']],
['tls', ['before-your-code', 'the handshake, likewise']],
['gateway', ['before-your-code', 'queueing and routing in front of the handler']],
['cold_start', ['before-your-code',
'the runtime booting; not code you can move after an ack']],
['signature_verification', ['must-precede-ack',
'has to run before the payload is trusted, and costs microseconds when done right']],
['body_parse', ['must-precede-ack', 'the payload has to be read to be answered']],
['installation_lookup', ['cacheable-pre-ack',
'a store lookup in the receiver; cache it rather than defer it, because the ' +
'receiver needs the answer']],
['token_lookup', ['cacheable-pre-ack', 'the same shape of problem']],
['enqueue', ['must-precede-ack',
'handing the work to a queue is itself pre-ack, and is the cost of being ' +
'able to defer anything at all']],
['ack', ['must-precede-ack', 'writing the 2xx']],
['views_open', ['hard-deadline',
'trigger_id expires three seconds after the interaction, so opening a modal ' +
'cannot be deferred, only made fast']],
['trigger_id_use', ['hard-deadline', 'the same three second expiry']],
['downstream_http', ['deferrable', 'the service the bot fronts']],
['database_write', ['deferrable', 'record creation']],
['llm_call', ['deferrable', 'generation, and never inside an ack path']],
['chat_postMessage', ['deferrable', 'the answer, which is not the receipt']],
['chat_update', ['deferrable', 'likewise']],
['response_url_post', ['deferrable',
'valid for thirty minutes and five uses, which is the point of it']],
]);
/**
* Place one stage relative to the acknowledgement. Pure.
* Unknown stages are assumed deferrable and said to be assumed, because
* guessing them into the pre-ack column would inflate the finding.
*/
export function stagePhase(name) {
const key = String(name ?? '').trim();
return STAGE_PHASES.get(key)
?? ['deferrable', 'not a stage this script knows; assumed deferrable, so check it'];
}
/**
* Sum each side of the ack and say whether deferring is enough. Pure.
* The verdict worth having is 'over-even-deferred': the case where the usual
* advice does not apply because the immovable half is already too slow.
*/
export function splitBudget(stages, deadlineMs = DEADLINE_MS) {
const deadline = Math.max(Number(deadlineMs) || 0, 1);
let pre = 0;
let deferred = 0;
const hard = [];
for (const [name, ms] of stages ?? []) {
const cost = Math.max(Number(ms) || 0, 0);
const [phase] = stagePhase(name);
if (phase === 'deferrable') {
deferred += cost;
} else {
pre += cost;
if (phase === 'hard-deadline') hard.push(String(name));
}
}
const total = pre + deferred;
const headroom = deadline - pre;
let verdict = 'fixed-by-deferring';
if (total <= deadline) verdict = 'inside';
else if (pre > deadline) verdict = 'over-even-deferred';
else if (pre > deadline * 0.66) verdict = 'tight-after-deferring';
return {
preAckMs: Math.round(pre * 10) / 10,
deferrableMs: Math.round(deferred * 10) / 10,
totalMs: Math.round(total * 10) / 10,
headroomMs: Math.round(headroom * 10) / 10,
deadlineMs: deadline,
hardDeadlineStages: hard,
verdict,
};
}
/**
* Price the Slack calls a handler makes inside the ack path. Pure.
* The measured round trip is the number people leave out of the budget.
*/
export function apiCallBudget(latencyMs, calls, deadlineMs = DEADLINE_MS) {
const deadline = Math.max(Number(deadlineMs) || 0, 1);
const one = Math.max(Number(latencyMs) || 0, 0);
const n = Math.max(Number(calls) || 0, 0);
const cost = one * n;
const share = Math.round((cost * 1000.0) / deadline) / 10;
let verdict = 'minor';
if (n === 0) verdict = 'none-in-path';
else if (share >= 50.0) verdict = 'dominant';
else if (share >= 20.0) verdict = 'significant';
return {
oneCallMs: Math.round(one * 10) / 10,
calls: n,
costMs: Math.round(cost * 10) / 10,
sharePercent: share,
deadlineMs: deadline,
verdict,
};
}
async function timeReadCalls(token, samples) {
const timings = [];
for (let i = 0; i < Math.max(Number(samples) || 0, 1); i += 1) {
const started = Date.now();
// eslint-disable-next-line no-await-in-loop
const res = await fetch(`${API}auth.test`, {
headers: { Authorization: `Bearer ${token}` },
});
// eslint-disable-next-line no-await-in-loop
const body = await res.json();
const elapsed = Date.now() - started;
if (body.ok !== true) {
return [[], `auth.test answered 200 with ok: false, error=${body.error}`];
}
timings.push(elapsed);
}
return [timings, ''];
}
function median(values) {
const sorted = [...values].sort((a, b) => a - b);
const mid = Math.floor(sorted.length / 2);
return sorted.length % 2 ? sorted[mid] : (sorted[mid - 1] + sorted[mid]) / 2;
}
function arg(args, name, fallback = '') {
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 stages = argAll(args, '--stage').map((text) => {
const [name, value] = String(text).split('=');
const ms = Number(value);
if (!Number.isFinite(ms)) {
console.error(`stage ${text} should look like name=milliseconds`);
process.exit(2);
}
return [name.trim(), ms];
});
const tokenEnv = arg(args, '--token-env', 'SLACK_BOT_TOKEN');
const token = process.env[tokenEnv];
let oneCall = 0;
if (!token) {
console.log(`api skipped set ${tokenEnv} to measure this host's ` +
'round trip to Slack');
} else {
const [timings, err] = await timeReadCalls(token, Number(arg(args, '--samples', 5)));
if (err) {
console.warn(`api unavailable ${err}`);
} else {
oneCall = median(timings);
console.log(`api ${`${Math.trunc(oneCall)}ms`.padEnd(14)} median of ` +
`${timings.length} read call(s) from this host`);
}
}
const callsInPath = Number(arg(args, '--calls-in-ack-path', 0));
if (callsInPath) {
const c = apiCallBudget(oneCall, callsInPath);
const quiet = c.verdict === 'minor' || c.verdict === 'none-in-path';
(quiet ? console.log : console.warn)(
`calls ${c.verdict.padEnd(14)} ${c.calls} call(s) at ` +
`${Math.trunc(c.oneCallMs)}ms is ${c.sharePercent}% of the ${c.deadlineMs}ms deadline`);
}
if (stages.length === 0) {
console.log('budget no-stages pass --stage name=milliseconds to split ' +
'a handler at the ack');
return;
}
const split = splitBudget(stages);
console.log(`budget pre-ack ${Math.round(split.preAckMs)}ms of ` +
`${split.deadlineMs}ms, ${Math.round(split.headroomMs)}ms of headroom`);
console.log(`budget deferred ${Math.round(split.deferrableMs)}ms moved ` +
'after the ack');
for (const name of split.hardDeadlineStages) {
console.warn(`budget hard-deadline ${name} cannot be deferred; trigger_id ` +
'expires in three seconds');
}
if (split.verdict === 'inside') {
console.log(`verdict inside the whole handler is ` +
`${Math.round(split.totalMs)}ms, under the deadline as it stands`);
return;
}
if (split.verdict === 'over-even-deferred') {
console.warn(`verdict over-even-deferred ${Math.round(split.preAckMs)}ms of ` +
`immovable work against a ${split.deadlineMs}ms deadline; acking first ` +
'changes nothing here');
console.warn(' repair: attack the pre-ack stages themselves. A cold start is ' +
'provisioned concurrency or a warmer runtime; an installation lookup is a ' +
'cache, not a queue');
process.exitCode = 1;
return;
}
(split.verdict === 'tight-after-deferring' ? console.warn : console.log)(
`verdict ${split.verdict.padEnd(14)} the deadline applies to ` +
`${Math.round(split.preAckMs)}ms of a ${Math.round(split.totalMs)}ms handler`);
console.warn(` repair: acknowledge first and hand the deferrable ` +
`${Math.round(split.deferrableMs)}ms to a queue. On a platform that freezes ` +
'the process after the response, the hand-off has to be durable and has to ' +
'happen before the ack');
console.warn(' repair: send the actual answer afterwards through response_url, ' +
'which is good for thirty minutes and five uses');
process.exitCode = 1;
}
// Only run when invoked directly, so importing this module in the tests does
// not execute main() and fail the file on a missing token.
if (import.meta.url === `file://${process.argv[1]}`) {
main().catch((err) => { console.error(err.message); process.exitCode = 2; });
}
Add a test
The tests pin the split rather than the totals, because the total is not what the deadline applies to. The same handler, unchanged, is asserted to be over the budget when everything runs before the ack and inside it when the deferrable stages move, and a cold start large enough to blow the deadline on its own is asserted to produce the verdict that says deferring will not help. views_open is pinned as non-deferrable, since it is the one piece of work people move into the background and then cannot understand why the modal never opens.
from slack_ack_budget import api_call_budget, split_budget, stage_phase
HANDLER = [
("cold_start", 420),
("signature_verification", 2),
("installation_lookup", 120),
("downstream_http", 2600),
("chat_postMessage", 190),
("ack", 3),
]
def test_the_same_handler_is_over_the_deadline_and_inside_the_ack_budget():
split = split_budget(HANDLER)
assert split["total_ms"] > 3000
assert split["pre_ack_ms"] == 545.0
assert split["verdict"] == "fixed-by-deferring"
def test_the_deferrable_half_is_where_almost_all_the_time_is():
split = split_budget(HANDLER)
assert split["deferrable_ms"] == 2790.0
assert split["headroom_ms"] == 2455.0
def test_a_handler_that_already_fits_is_left_alone():
split = split_budget([("cold_start", 200), ("downstream_http", 400)])
assert split["verdict"] == "inside"
assert split["total_ms"] == 600.0
def test_an_immovable_half_over_the_deadline_is_its_own_verdict():
split = split_budget([("cold_start", 3400), ("downstream_http", 50)])
assert split["verdict"] == "over-even-deferred"
assert split["headroom_ms"] < 0
def test_the_two_thirds_mark_is_reported_as_tight_rather_than_fixed():
split = split_budget([("cold_start", 2200), ("downstream_http", 4000)])
assert split["verdict"] == "tight-after-deferring"
def test_opening_a_modal_is_never_treated_as_deferrable():
assert stage_phase("views_open")[0] == "hard-deadline"
split = split_budget([("views_open", 800), ("downstream_http", 5000)])
assert split["hard_deadline_stages"] == ["views_open"]
assert split["pre_ack_ms"] == 800.0
def test_the_queue_handoff_is_counted_before_the_ack_not_after_it():
assert stage_phase("enqueue")[0] == "must-precede-ack"
assert split_budget([("enqueue", 15)])["deferrable_ms"] == 0.0
def test_an_unknown_stage_is_assumed_deferrable_and_says_so():
phase, why = stage_phase("some_internal_span")
assert phase == "deferrable"
assert "assumed" in why
def test_four_slack_calls_in_the_ack_path_are_a_third_of_the_budget():
cost = api_call_budget(190, 4)
assert cost["cost_ms"] == 760.0
assert cost["share_percent"] == 25.3
assert cost["verdict"] == "significant"
def test_one_fast_call_is_minor_and_eight_slow_ones_dominate():
assert api_call_budget(120, 1)["verdict"] == "minor"
assert api_call_budget(200, 8)["verdict"] == "dominant"
assert api_call_budget(190, 0)["verdict"] == "none-in-path"
def test_an_empty_stage_list_produces_zeroes_rather_than_a_crash():
split = split_budget([])
assert split["total_ms"] == 0.0
assert split["verdict"] == "inside"
import { test } from 'node:test';
import assert from 'node:assert/strict';
import { apiCallBudget, splitBudget, stagePhase } from './slack-ack-budget.mjs';
const HANDLER = [
['cold_start', 420],
['signature_verification', 2],
['installation_lookup', 120],
['downstream_http', 2600],
['chat_postMessage', 190],
['ack', 3],
];
test('the same handler is over the deadline and inside the ack budget', () => {
const split = splitBudget(HANDLER);
assert.ok(split.totalMs > 3000);
assert.equal(split.preAckMs, 545);
assert.equal(split.verdict, 'fixed-by-deferring');
});
test('the deferrable half is where almost all the time is', () => {
const split = splitBudget(HANDLER);
assert.equal(split.deferrableMs, 2790);
assert.equal(split.headroomMs, 2455);
});
test('a handler that already fits is left alone', () => {
const split = splitBudget([['cold_start', 200], ['downstream_http', 400]]);
assert.equal(split.verdict, 'inside');
assert.equal(split.totalMs, 600);
});
test('an immovable half over the deadline is its own verdict', () => {
const split = splitBudget([['cold_start', 3400], ['downstream_http', 50]]);
assert.equal(split.verdict, 'over-even-deferred');
assert.ok(split.headroomMs < 0);
});
test('the two thirds mark is reported as tight rather than fixed', () => {
const split = splitBudget([['cold_start', 2200], ['downstream_http', 4000]]);
assert.equal(split.verdict, 'tight-after-deferring');
});
test('opening a modal is never treated as deferrable', () => {
assert.equal(stagePhase('views_open')[0], 'hard-deadline');
const split = splitBudget([['views_open', 800], ['downstream_http', 5000]]);
assert.deepEqual(split.hardDeadlineStages, ['views_open']);
assert.equal(split.preAckMs, 800);
});
test('the queue handoff is counted before the ack not after it', () => {
assert.equal(stagePhase('enqueue')[0], 'must-precede-ack');
assert.equal(splitBudget([['enqueue', 15]]).deferrableMs, 0);
});
test('an unknown stage is assumed deferrable and says so', () => {
const [phase, why] = stagePhase('some_internal_span');
assert.equal(phase, 'deferrable');
assert.match(why, /assumed/);
});
test('four slack calls in the ack path are a third of the budget', () => {
const cost = apiCallBudget(190, 4);
assert.equal(cost.costMs, 760);
assert.equal(cost.sharePercent, 25.3);
assert.equal(cost.verdict, 'significant');
});
test('one fast call is minor and eight slow ones dominate', () => {
assert.equal(apiCallBudget(120, 1).verdict, 'minor');
assert.equal(apiCallBudget(200, 8).verdict, 'dominant');
assert.equal(apiCallBudget(190, 0).verdict, 'none-in-path');
});
test('an empty stage list produces zeroes rather than a crash', () => {
const split = splitBudget([]);
assert.equal(split.totalMs, 0);
assert.equal(split.verdict, 'inside');
});
FAQ
Is the three seconds measured at my server or at Slack?
At Slack. The clock starts when the request is sent and stops when the response is complete, so it includes name resolution, the TLS handshake, any queueing in a gateway, and the cold start of the process that serves it. A handler whose own instrumentation reports 900 milliseconds can still be a failed delivery, which is why the stage list in this script starts with things that are not your code.
What actually happens if I miss it?
The delivery is counted as failed and retried on a fixed schedule, so the same work arrives again. Sustained failure has a further consequence: Slack disables event subscriptions for apps that fail the great majority of deliveries in an hour, and does not switch them back on when you recover. Missing the deadline is therefore not a latency problem with a latency-sized consequence.
Can I always fix this by acking first and working in the background?
No, and that is the case the script exists to find. If the immovable stages alone exceed three seconds, deferring moves nothing that was costing you the deadline. A two second cold start plus a 1.2 second installation-store lookup is over the budget before your handler has read the payload, and the repairs there are provisioned concurrency and a cache rather than a queue.
I ack first and the background work never runs. What is wrong?
Almost certainly the platform. Several function-as-a-service runtimes freeze the container the moment the response is returned, so a task you started and did not await is a task that is suspended indefinitely and may never resume. The deferral has to be handed to something durable before the response goes out, and that hand-off is pre-ack work that belongs in the budget.
Why does the script time calls to Slack instead of timing my handler?
Because your handler is already instrumented and Slack's round trip usually is not. The number that goes missing from these budgets is the cost of talking to Slack from wherever the handler runs, and a script holding a read token can measure that honestly in five calls. Timing your own Request URL would mean sending it synthetic events, which creates real records in somebody's workspace.
Related field notes
- what a missed deadline turns into at volume
- where sustained misses end up
- the same three seconds, applied once at setup
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.
- Events API - Slack Docs
- Handling user interaction - Slack Docs
- views.open method reference - Slack Docs
- auth.test method reference - Slack Docs
If your setup is misbehaving in a way this note does not cover, message me on LinkedIn with what you are seeing.