Diagnostic Slack
One mention, two events: app_mention and message both fire
Somebody types @deploybot status and the bot answers, and then answers again, with the identical text, so fast that the two replies land in the same visual block in the client. It happens every time, for everyone, in every channel. It is not flaky and it is not load: it is exactly two, always.
That reliability is the clue. Retries are irregular and spaced in minutes. This is two events, delivered once each, arriving at your process inside the same tick, because a mention in a channel your app is in is two separate events and the app asked for both of them.
When someone writes @bot hello in a channel your app belongs to, Slack sends two events: app_mention, because the text mentions your app, and message.channels, because a message was posted in a channel you subscribe to. They are separate deliveries with separate event_id values and separate types. An app with a replying handler on each replies twice, and no amount of idempotency on event_id will collapse them, because they are genuinely two different events.
So the finding lives in the subscription list, not in the message history. The script reads settings.event_subscriptions.bot_events and asks which human actions land on more than one subscribed event; the mention rows are the ones that produce a deterministic pair. Then it reads a page of channel history as corroboration and measures the gap between consecutive replies, because the spacing is what separates this note from its neighbours: under a second is two subscriptions, sixty or three hundred seconds is a retry.
The problem in plain words
The first hour goes into the wrong place, and it goes there for a good reason. Two identical messages look like a delivery problem, and Slack has a famous delivery problem: it retries anything you do not acknowledge in three seconds. So the team adds an idempotency store keyed on event_id, deploys it, and the bot still answers twice. That is the moment the bug becomes interesting, because the fix that always works has just failed.
It failed because there is nothing to deduplicate. The two deliveries are not two copies of one event, they are one copy each of two events, with different ids, different types and different payload shapes. A dedupe key that is doing its job perfectly will pass both of them through, and it should.
The way in is almost always incremental and almost always sensible in isolation. The app starts with app_mention because it answers when addressed. Later somebody wants it to notice links, or keywords, or a message in a support channel, so they add message.channels and a second handler. Both handlers are correct. The overlap between them is not written down anywhere, is invisible on the configuration screen, which lists the two events on adjacent lines with no hint that one human sentence satisfies both, and appears in production the first time somebody says the bot's name.
Why it happens
These are two events, not one event twice. That single sentence is the whole note. app_mention and message.channels arrive with distinct event_id values, so every deduplication strategy built for retries passes them both, correctly. If your dedupe store is working and the duplicates continue, this is where to look.
The spacing is the discriminator and it is not subtle. Two deliveries caused by one utterance are handled in the same tick and land milliseconds apart. Slack's retries land at roughly sixty and three hundred seconds. There is no overlap between those regimes, so one subtraction on two ts values tells you which note you are reading.
The overlap is a property of the configuration, so it is knowable before anybody complains. You do not need a reproduction. Two lines in bot_events are enough to say that a mention in a public channel will be delivered twice, permanently, to any handler pair that does not coordinate.
The guard belongs in the message handler, not in the mention handler. app_mention is the narrower, better-typed event and it is the one to keep for directed commands. The general message handler is the one that needs to learn to step aside when the text contains your bot user id, because it is the one that was never meant to answer commands in the first place.
Removing a subscription is not always available, which is why the script models a guard. Plenty of apps need message.channels for a real feature. In that case the pair stays subscribed forever and the only correct repair is code that knows about the overlap, so the script reports a declared guard as a resolved state rather than pretending the subscription must go.
The fix, as a flow
The only chain in this section whose cause and effect land in the same second. Every other duplicate in these notes is separated by a minute or five, and that difference is the whole diagnosis, which is why the chain ends on a dedupe store being shipped rather than on the duplicates themselves. The fix branch is one subtraction wide: two red rows for the pair that belongs here, and two plain rows handing the other spacings to the notes that own them.
How to fix it
Read the subscription list, or supply it
With an app configuration token, apps.manifest.export returns settings.event_subscriptions.bot_events. Without one, pass --subscribed once per event; the list is short and it is on the screen in front of you. This is the set the finding is computed from.
Ask which human action lands on two subscribed events
overlap walks a small table of triggers: a mention in a public channel is app_mention plus message.channels, in a private channel message.groups, in a group DM message.mpim. Any row where both are subscribed is a deterministic double delivery.
Declare the guards you already have
If your message handler already skips text containing your bot user id, say so with --guarded message.channels. The row comes back guarded rather than as a finding. A subscription you legitimately need is not a bug, and a report that calls it one gets ignored.
Corroborate from one page of history
Pass --channel and the script reads conversations.history, finds human messages that mention the bot, and looks at the run of bot replies immediately after each one. Two replies to one mention is the symptom made visible, in the workspace, with timestamps.
Subtract the two timestamps and let the gap decide
gap_state sorts a pair into simultaneous under a second, retry-shaped in the sixty and three hundred second windows, and unattributed otherwise. Only the first is this note, and the other two are handed to the notes that own them by name.
Print the guard, not just the diagnosis
The repair is one condition in one handler: ignore any message event whose text contains <@ plus your bot user id, and let app_mention own directed commands. The script prints it with your actual user id substituted in, so it can be pasted.
How to check it worked
After the guard ships, mention the bot once and re-run against the same channel. The subscription overlap is still there, because it is allowed to be; what should be gone is the pair.
python3 slack_event_overlap_audit.py --subscribed app_mention \
--subscribed message.channels --guarded message.channels --channel C01ABCDE9
# identity U0APPBOT11 in acme, bot_id B01ABCDE9
# public channel guarded both events are subscribed and the message.channels
# handler declares that it skips messages addressed to the bot
# history C01ABCDE9 4 mention(s), 0 pair(s)
# verdict clear no mention in this workspace is being delivered twiceThe full code
Three pure functions and two ordinary reads. overlap is the finding: it takes the subscribed events and returns the human actions that land on two of them, which is knowable without a single duplicate ever being posted. gap_state is the discriminator, and it is deliberately the shortest function in the file because the whole argument is one subtraction. mention_twins walks a page of history and only attributes a pair to this note when a mention preceded it, so an echo loop is not filed here by mistake.
"""Find the subscription overlap that delivers one mention as two events.
Read only. One auth.test for the bot's own identifiers, one optional
apps.manifest.export on an app configuration token for the subscribed events,
and one page of conversations.history per channel you name. Nothing is posted,
edited or unsubscribed: the overlap is a property of the subscription list, and
this prints the guard you would add.
"""
import argparse
import logging
import os
import sys
import requests
logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(message)s")
log = logging.getLogger("slack_event_overlap_audit")
API = "https://slack.com/api/"
# One human action, and every event Slack sends because of it. These are not two
# names for one delivery: app_mention and message.channels are separate events
# with separate ids, arriving at the same process inside the same tick. An app
# subscribed to both has two handlers for one sentence.
MENTION_TRIGGERS = {
"public channel": ("app_mention", "message.channels"),
"private channel": ("app_mention", "message.groups"),
"group DM": ("app_mention", "message.mpim"),
}
RANK = {"double-fire": 0, "guarded": 1, "single-path": 2, "not-subscribed": 3}
# Slack retries a delivery it believes failed at roughly 60 and 300 seconds. A
# pair spaced like that is one event delivered twice, which is a different note.
# A pair spaced under a second is two events delivered once each, which is this
# one. There is no overlap between the two regimes, which is what makes a single
# subtraction sufficient.
RETRY_WINDOWS = ((55.0, 70.0), (285.0, 320.0))
SIMULTANEOUS = 1.0
def overlap(subscribed, guarded=None):
"""Which human action is delivered twice. Pure.
Returns rows of (where, events, state, detail), worst first. The states are
deliberately four rather than two: a pair that is subscribed and guarded is
a resolved overlap and not a finding, because plenty of apps need
message.channels for a real feature and will keep it forever.
"""
subs = {str(e).strip() for e in subscribed or [] if str(e).strip()}
guards = {str(e).strip() for e in guarded or [] if str(e).strip()}
rows = []
for where in sorted(MENTION_TRIGGERS):
mention, msg = MENTION_TRIGGERS[where]
both = mention in subs and msg in subs
if both and (msg in guards or mention in guards):
rows.append((where, (mention, msg), "guarded",
"both events are subscribed and the %s handler declares "
"that it skips messages addressed to the bot" % msg))
elif both:
rows.append((where, (mention, msg), "double-fire",
"%s and %s are both subscribed, so one mention in a %s is "
"two deliveries with two event ids and two handler runs"
% (mention, msg, where)))
elif mention in subs or msg in subs:
only = mention if mention in subs else msg
rows.append((where, (mention, msg), "single-path",
"only %s is subscribed, so a mention in a %s reaches the "
"app once" % (only, where)))
else:
rows.append((where, (mention, msg), "not-subscribed",
"neither %s nor %s is subscribed, so nothing arrives from "
"a %s at all" % (mention, msg, where)))
return sorted(rows, key=lambda r: (RANK.get(r[2], 9), r[0]))
def gap_state(delta):
"""What the spacing between two consecutive replies means. Pure.
The shortest function here and the one carrying the argument. Two events
caused by one utterance are handled in the same tick. A retry is a minute
or five minutes later. Nothing lands in between, so the subtraction decides
which note you are reading.
"""
try:
d = abs(float(delta))
except (TypeError, ValueError):
return ("unattributed", "the two timestamps could not be read as numbers")
if d < SIMULTANEOUS:
return ("simultaneous",
"%.3fs apart, which is two events for one message handled in the "
"same tick" % d)
for lo, hi in RETRY_WINDOWS:
if lo <= d <= hi:
return ("retry-shaped",
"%.1fs apart, which is Slack's retry schedule and not a second "
"subscription" % d)
return ("unattributed",
"%.1fs apart, which matches neither a double subscription nor a retry" % d)
def mention_twins(messages, bot_id, bot_user_id):
"""Reply pairs in one page of history, and what put them there. Pure.
messages: as conversations.history returns them, newest first. Returns rows
of (trigger_ts, delta, state, detail).
A run of consecutive replies is only attributed to this note when the human
message in front of it actually mentions the bot. Two replies with no
mention before them is an echo loop or two workers, and filing those here
would send somebody to edit a subscription list that is not the problem.
"""
ordered = sorted([m for m in messages or [] if isinstance(m, dict)],
key=lambda m: float(m.get("ts") or 0))
handle = "<@%s>" % bot_user_id if bot_user_id else ""
def mine(m):
return bool(bot_id) and m.get("bot_id") == bot_id
rows, i = [], 0
while i < len(ordered):
trigger = ordered[i]
if mine(trigger):
i += 1
continue
run, j = [], i + 1
while j < len(ordered) and mine(ordered[j]):
run.append(ordered[j])
j += 1
if len(run) >= 2:
delta = float(run[1].get("ts") or 0) - float(run[0].get("ts") or 0)
addressed = bool(handle) and handle in str(trigger.get("text") or "")
if addressed:
state, detail = gap_state(delta)
else:
state = "unattributed"
detail = ("the message before this pair does not mention the bot, "
"so the pair belongs to the echo loop or the duplicate "
"message note rather than to this one")
rows.append((trigger.get("ts"), delta, state, detail))
i = j if j > i else i + 1
return rows
def verdict(overlap_rows, twin_rows, subscriptions_known=True):
"""Combine the configuration finding with the behavioural one. Pure."""
doubled = [r for r in overlap_rows or [] if r[2] == "double-fire"]
twins = [r for r in twin_rows or [] if r[2] == "simultaneous"]
retries = [r for r in twin_rows or [] if r[2] == "retry-shaped"]
if doubled and twins:
return ("confirmed",
"%d subscription overlap(s) and %d reply pair(s) under a second "
"apart. The configuration explains the behaviour"
% (len(doubled), len(twins)))
if doubled:
return ("configured",
"%d subscription overlap(s). Nothing has to have gone wrong yet: "
"a mention in one of these conversations is two deliveries whether "
"or not anyone has complained" % len(doubled))
if twins and not subscriptions_known:
return ("observed",
"%d reply pair(s) under a second apart, with no subscription list "
"read. Export the manifest, or pass --subscribed, to name the cause"
% len(twins))
if twins:
return ("elsewhere",
"%d reply pair(s) under a second apart, and no overlap in the "
"subscription list. Two processes running the same handler will "
"also produce this" % len(twins))
if retries:
return ("retries",
"%d pair(s) spaced like Slack's retry schedule, which is a "
"dedupe question rather than a subscription one" % len(retries))
return ("clear", "no mention in this workspace is being delivered twice")
def get(session, method, params, label):
"""One GET, asserting on the body rather than the status line."""
r = session.get(API + method, params=params or {}, timeout=30)
body = r.json()
if body.get("ok") is not True:
log.warning("%-10s %-14s %s", label, "unavailable", body.get("error"))
return None
return body
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("--config-token-env", default="SLACK_CONFIG_TOKEN",
help="environment variable holding an app configuration token")
ap.add_argument("--app-id", default="", help="app ID, for the manifest read")
ap.add_argument("--subscribed", action="append", default=[],
help="a subscribed event type, when no manifest is available")
ap.add_argument("--guarded", action="append", default=[],
help="an event whose handler already skips messages that "
"mention the bot; repeatable")
ap.add_argument("--channel", action="append", default=[],
help="channel ID to read one page of history from; repeatable")
args = ap.parse_args()
token = os.environ.get(args.token_env)
if not token:
log.error("set %s; channels:history and the identity read are enough",
args.token_env)
return 2
s = requests.Session()
s.headers.update({"Authorization": "Bearer " + token})
who = get(s, "auth.test", {}, "auth.test")
if not who:
return 2
bot_id, user_id = who.get("bot_id"), who.get("user_id")
log.info("identity %s in %s, bot_id %s", user_id, who.get("team"), bot_id)
subscribed, known = list(args.subscribed), bool(args.subscribed)
config_token = os.environ.get(args.config_token_env)
if config_token and args.app_id:
c = requests.Session()
c.headers.update({"Authorization": "Bearer " + config_token})
body = get(c, "apps.manifest.export", {"app_id": args.app_id}, "manifest")
if body:
subs = (((body or {}).get("manifest") or {}).get("settings")
or {}).get("event_subscriptions") or {}
subscribed = list(subs.get("bot_events") or [])
known = True
if not known:
log.info("manifest skipped no subscription list was read; pass "
"--subscribed for each event on the configuration screen")
rows = overlap(subscribed, args.guarded)
for where, events, state, detail in rows:
line = "%-21s %-14s %s" % (where, state, detail)
if state == "double-fire":
log.warning(line)
else:
log.info(line)
twins = []
for channel in args.channel:
body = get(s, "conversations.history", {"channel": channel, "limit": 200},
channel)
if not body:
continue
found = mention_twins(body.get("messages") or [], bot_id, user_id)
twins.extend(found)
log.info("history %-10s %d pair(s) after a mention", channel, len(found))
for ts, _delta, state, detail in found:
log.info(" %-19s %-14s %s", ts, state, detail)
state, detail = verdict(rows, twins, known)
if state in ("confirmed", "configured", "observed"):
log.warning("verdict %-14s %s", state, detail)
log.warning(" repair: keep app_mention for directed commands and guard the "
"message handler; ignore any message event whose text contains "
"<@%s>", user_id)
log.warning(" repair: if the message subscription exists for a real "
"feature, keep it and add the guard rather than unsubscribing")
log.warning(" repair: do not reach for a dedupe store; these are two event "
"ids and an idempotency key will pass both, correctly")
return 1
log.info("verdict %-14s %s", state, detail)
return 0
if __name__ == "__main__":
sys.exit(main())
/**
* Find the subscription overlap that delivers one mention as two events.
*
* Read only. One auth.test for the bot's own identifiers, one optional
* apps.manifest.export on an app configuration token for the subscribed events,
* and one page of conversations.history per channel you name. Nothing is
* posted, edited or unsubscribed: the overlap is a property of the subscription
* list, and this prints the guard you would add.
*/
const API = 'https://slack.com/api/';
// One human action, and every event Slack sends because of it. These are not
// two names for one delivery: app_mention and message.channels are separate
// events with separate ids, arriving inside the same tick.
const MENTION_TRIGGERS = new Map([
['group DM', ['app_mention', 'message.mpim']],
['private channel', ['app_mention', 'message.groups']],
['public channel', ['app_mention', 'message.channels']],
]);
const RANK = { 'double-fire': 0, guarded: 1, 'single-path': 2, 'not-subscribed': 3 };
// Slack retries at roughly 60 and 300 seconds. A pair spaced like that is one
// event delivered twice; a pair under a second apart is two events delivered
// once each. The regimes do not overlap.
const RETRY_WINDOWS = [[55, 70], [285, 320]];
const SIMULTANEOUS = 1.0;
/**
* Which human action is delivered twice. Pure.
* Four states rather than two: a subscribed pair with a declared guard is a
* resolved overlap, not a finding, because plenty of apps need
* message.channels for a real feature and will keep it forever.
*/
export function overlap(subscribed, guarded = []) {
const subs = new Set((subscribed ?? []).map((e) => String(e).trim()).filter(Boolean));
const guards = new Set((guarded ?? []).map((e) => String(e).trim()).filter(Boolean));
const rows = [];
for (const where of [...MENTION_TRIGGERS.keys()].sort()) {
const [mention, msg] = MENTION_TRIGGERS.get(where);
const both = subs.has(mention) && subs.has(msg);
if (both && (guards.has(msg) || guards.has(mention))) {
rows.push([where, [mention, msg], 'guarded',
`both events are subscribed and the ${msg} handler declares that it skips ` +
'messages addressed to the bot']);
} else if (both) {
rows.push([where, [mention, msg], 'double-fire',
`${mention} and ${msg} are both subscribed, so one mention in a ${where} is ` +
'two deliveries with two event ids and two handler runs']);
} else if (subs.has(mention) || subs.has(msg)) {
const only = subs.has(mention) ? mention : msg;
rows.push([where, [mention, msg], 'single-path',
`only ${only} is subscribed, so a mention in a ${where} reaches the app once`]);
} else {
rows.push([where, [mention, msg], 'not-subscribed',
`neither ${mention} nor ${msg} is subscribed, so nothing arrives from a ` +
`${where} at all`]);
}
}
return rows.sort((a, b) => (RANK[a[2]] ?? 9) - (RANK[b[2]] ?? 9)
|| a[0].localeCompare(b[0]));
}
/**
* What the spacing between two consecutive replies means. Pure.
* The shortest function here and the one carrying the argument.
*/
export function gapState(delta) {
// Number(null) is 0 and Number('') is 0, either of which would sail through a
// finiteness check and be reported as a sub-second gap. Reject the absent
// value before the arithmetic rather than after it.
const d = (delta === null || delta === undefined || delta === '')
? NaN : Math.abs(Number(delta));
if (!Number.isFinite(d)) {
return ['unattributed', 'the two timestamps could not be read as numbers'];
}
if (d < SIMULTANEOUS) {
return ['simultaneous',
`${d.toFixed(3)}s apart, which is two events for one message handled in the ` +
'same tick'];
}
for (const [lo, hi] of RETRY_WINDOWS) {
if (d >= lo && d <= hi) {
return ['retry-shaped',
`${d.toFixed(1)}s apart, which is Slack's retry schedule and not a second ` +
'subscription'];
}
}
return ['unattributed',
`${d.toFixed(1)}s apart, which matches neither a double subscription nor a retry`];
}
/**
* Reply pairs in one page of history, and what put them there. Pure.
* A run of replies is only attributed to this note when the human message in
* front of it actually mentions the bot; two replies with no mention before
* them is an echo loop or two workers.
*/
export function mentionTwins(messages, botId, botUserId) {
const ordered = (messages ?? [])
.filter((m) => m && typeof m === 'object')
.slice()
.sort((a, b) => Number(a.ts ?? 0) - Number(b.ts ?? 0));
const handle = botUserId ? `<@${botUserId}>` : '';
const mine = (m) => Boolean(botId) && m.bot_id === botId;
const rows = [];
let i = 0;
while (i < ordered.length) {
const trigger = ordered[i];
if (mine(trigger)) { i += 1; continue; }
const run = [];
let j = i + 1;
while (j < ordered.length && mine(ordered[j])) { run.push(ordered[j]); j += 1; }
if (run.length >= 2) {
const delta = Number(run[1].ts ?? 0) - Number(run[0].ts ?? 0);
const addressed = Boolean(handle) && String(trigger.text ?? '').includes(handle);
const [state, detail] = addressed ? gapState(delta) : ['unattributed',
'the message before this pair does not mention the bot, so the pair belongs ' +
'to the echo loop or the duplicate message note rather than to this one'];
rows.push([trigger.ts, delta, state, detail]);
}
i = j > i ? j : i + 1;
}
return rows;
}
/** Combine the configuration finding with the behavioural one. Pure. */
export function verdict(overlapRows, twinRows, subscriptionsKnown = true) {
const doubled = (overlapRows ?? []).filter((r) => r[2] === 'double-fire');
const twins = (twinRows ?? []).filter((r) => r[2] === 'simultaneous');
const retries = (twinRows ?? []).filter((r) => r[2] === 'retry-shaped');
if (doubled.length && twins.length) {
return ['confirmed',
`${doubled.length} subscription overlap(s) and ${twins.length} reply pair(s) ` +
'under a second apart. The configuration explains the behaviour'];
}
if (doubled.length) {
return ['configured',
`${doubled.length} subscription overlap(s). Nothing has to have gone wrong ` +
'yet: a mention in one of these conversations is two deliveries whether or ' +
'not anyone has complained'];
}
if (twins.length && !subscriptionsKnown) {
return ['observed',
`${twins.length} reply pair(s) under a second apart, with no subscription ` +
'list read. Export the manifest, or pass --subscribed, to name the cause'];
}
if (twins.length) {
return ['elsewhere',
`${twins.length} reply pair(s) under a second apart, and no overlap in the ` +
'subscription list. Two processes running the same handler will also produce ' +
'this'];
}
if (retries.length) {
return ['retries',
`${retries.length} pair(s) spaced like Slack's retry schedule, which is a ` +
'dedupe question rather than a subscription one'];
}
return ['clear', 'no mention in this workspace is being delivered twice'];
}
async function get(token, method, params, label) {
const qs = new URLSearchParams(params ?? {});
const res = await fetch(`${API}${method}?${qs}`, {
headers: { Authorization: `Bearer ${token}` },
});
const body = await res.json();
if (body.ok !== true) {
console.warn(`${label.padEnd(10)} ${'unavailable'.padEnd(14)} ${body.error}`);
return null;
}
return body;
}
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 tokenEnv = arg(args, '--token-env', 'SLACK_BOT_TOKEN');
const token = process.env[tokenEnv];
if (!token) {
console.error(`set ${tokenEnv}; channels:history and the identity read are enough`);
process.exitCode = 2;
return;
}
const configTokenEnv = arg(args, '--config-token-env', 'SLACK_CONFIG_TOKEN');
const appId = arg(args, '--app-id', '');
const guarded = argAll(args, '--guarded');
const channels = argAll(args, '--channel');
const who = await get(token, 'auth.test', {}, 'auth.test');
if (!who) { process.exitCode = 2; return; }
const botId = who.bot_id;
const userId = who.user_id;
console.log(`identity ${userId} in ${who.team}, bot_id ${botId}`);
let subscribed = argAll(args, '--subscribed');
let known = subscribed.length > 0;
const configToken = process.env[configTokenEnv];
if (configToken && appId) {
const body = await get(configToken, 'apps.manifest.export', { app_id: appId },
'manifest');
if (body) {
subscribed = body?.manifest?.settings?.event_subscriptions?.bot_events ?? [];
known = true;
}
}
if (!known) {
console.log('manifest skipped no subscription list was read; pass ' +
'--subscribed for each event on the configuration screen');
}
const rows = overlap(subscribed, guarded);
for (const [where, , state, detail] of rows) {
const line = `${where.padEnd(21)} ${state.padEnd(14)} ${detail}`;
if (state === 'double-fire') console.warn(line); else console.log(line);
}
const twins = [];
for (const channel of channels) {
// eslint-disable-next-line no-await-in-loop
const body = await get(token, 'conversations.history',
{ channel, limit: '200' }, channel);
if (!body) continue;
const found = mentionTwins(body.messages ?? [], botId, userId);
twins.push(...found);
console.log(`history ${channel.padEnd(10)} ${found.length} pair(s) after a ` +
'mention');
for (const [ts, , state, detail] of found) {
console.log(` ${String(ts).padEnd(19)} ${state.padEnd(14)} ${detail}`);
}
}
const [state, detail] = verdict(rows, twins, known);
if (state === 'confirmed' || state === 'configured' || state === 'observed') {
console.warn(`verdict ${state.padEnd(14)} ${detail}`);
console.warn(' repair: keep app_mention for directed commands and guard the ' +
`message handler; ignore any message event whose text contains <@${userId}>`);
console.warn(' repair: if the message subscription exists for a real feature, ' +
'keep it and add the guard rather than unsubscribing');
console.warn(' repair: do not reach for a dedupe store; these are two event ' +
'ids and an idempotency key will pass both, correctly');
process.exitCode = 1;
} else {
console.log(`verdict ${state.padEnd(14)} ${detail}`);
}
}
// 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 are about the three ways this note could be wrong. A guard has to close the finding, or an app that legitimately needs message.channels gets told to break a feature. A pair sixty seconds apart has to come back retry-shaped and be handed to the note that owns retries, because that is the boundary this whole script exists to draw. And a pair with no mention in front of it must not be attributed here at all, since a bot answering itself is a loop and not an overlap.
from slack_event_overlap_audit import gap_state, mention_twins, overlap, verdict
def rows_by_where(rows):
return {r[0]: r for r in rows}
def test_both_events_subscribed_is_the_finding():
row = rows_by_where(overlap(["app_mention", "message.channels"]))["public channel"]
assert row[2] == "double-fire"
assert "two deliveries" in row[3]
def test_one_event_alone_arrives_once():
row = rows_by_where(overlap(["app_mention"]))["public channel"]
assert row[2] == "single-path"
row = rows_by_where(overlap(["message.channels"]))["public channel"]
assert row[2] == "single-path"
def test_a_declared_guard_closes_the_finding():
rows = rows_by_where(overlap(["app_mention", "message.channels"],
["message.channels"]))
assert rows["public channel"][2] == "guarded"
def test_a_guard_on_one_channel_type_does_not_cover_another():
rows = rows_by_where(overlap(
["app_mention", "message.channels", "message.groups"], ["message.channels"]))
assert rows["public channel"][2] == "guarded"
assert rows["private channel"][2] == "double-fire"
def test_private_channels_and_group_dms_have_their_own_message_event():
rows = rows_by_where(overlap(["app_mention", "message.mpim"]))
assert rows["group DM"][2] == "double-fire"
assert rows["public channel"][2] == "single-path"
def test_nothing_subscribed_is_not_a_finding():
assert rows_by_where(overlap([]))["public channel"][2] == "not-subscribed"
assert overlap(None)[0][2] == "not-subscribed"
def test_findings_sort_above_resolved_rows():
rows = overlap(["app_mention", "message.channels", "message.groups"],
["message.channels"])
assert rows[0][2] == "double-fire"
def test_a_sub_second_gap_is_two_events_for_one_message():
state, detail = gap_state(0.12)
assert state == "simultaneous"
assert "same tick" in detail
def test_a_sixty_second_gap_belongs_to_the_retry_note():
assert gap_state(60.4)[0] == "retry-shaped"
assert gap_state(300.0)[0] == "retry-shaped"
assert "retry schedule" in gap_state(60.4)[1]
def test_a_gap_matching_neither_regime_is_not_attributed():
assert gap_state(9.0)[0] == "unattributed"
assert gap_state(None)[0] == "unattributed"
assert gap_state("later")[0] == "unattributed"
def test_two_replies_to_a_mention_are_the_symptom():
msgs = [
{"ts": "1000.000000", "user": "U9", "text": "hey <@U0BOT> status"},
{"ts": "1000.400000", "bot_id": "B1", "text": "ok"},
{"ts": "1000.480000", "bot_id": "B1", "text": "ok"},
]
rows = mention_twins(msgs, "B1", "U0BOT")
assert len(rows) == 1
assert rows[0][2] == "simultaneous"
def test_history_arriving_newest_first_is_ordered_before_it_is_read():
msgs = [
{"ts": "1000.480000", "bot_id": "B1", "text": "ok"},
{"ts": "1000.400000", "bot_id": "B1", "text": "ok"},
{"ts": "1000.000000", "user": "U9", "text": "hey <@U0BOT> status"},
]
assert mention_twins(msgs, "B1", "U0BOT")[0][2] == "simultaneous"
def test_a_pair_with_no_mention_in_front_of_it_is_not_this_note():
msgs = [
{"ts": "1000.000000", "user": "U9", "text": "morning everyone"},
{"ts": "1000.400000", "bot_id": "B1", "text": "ok"},
{"ts": "1000.480000", "bot_id": "B1", "text": "ok"},
]
rows = mention_twins(msgs, "B1", "U0BOT")
assert rows[0][2] == "unattributed"
assert "echo loop" in rows[0][3]
def test_a_single_reply_to_a_mention_is_not_a_pair():
msgs = [
{"ts": "1000.000000", "user": "U9", "text": "<@U0BOT> status"},
{"ts": "1000.400000", "bot_id": "B1", "text": "ok"},
]
assert mention_twins(msgs, "B1", "U0BOT") == []
def test_replies_from_another_bot_are_not_counted_as_ours():
msgs = [
{"ts": "1000.000000", "user": "U9", "text": "<@U0BOT> status"},
{"ts": "1000.400000", "bot_id": "B2", "text": "ok"},
{"ts": "1000.480000", "bot_id": "B2", "text": "ok"},
]
assert mention_twins(msgs, "B1", "U0BOT") == []
def test_a_retry_shaped_pair_after_a_mention_is_named_as_such():
msgs = [
{"ts": "1000.000000", "user": "U9", "text": "<@U0BOT> status"},
{"ts": "1000.400000", "bot_id": "B1", "text": "ok"},
{"ts": "1060.500000", "bot_id": "B1", "text": "ok"},
]
assert mention_twins(msgs, "B1", "U0BOT")[0][2] == "retry-shaped"
def test_the_configuration_alone_is_enough_to_report():
rows = overlap(["app_mention", "message.channels"])
state, detail = verdict(rows, [])
assert state == "configured"
assert "whether or not anyone has complained" in detail
def test_configuration_plus_observed_pairs_is_confirmed():
rows = overlap(["app_mention", "message.channels"])
twins = [("1000.0", 0.08, "simultaneous", "")]
assert verdict(rows, twins)[0] == "confirmed"
def test_pairs_without_a_subscription_list_ask_for_the_manifest():
twins = [("1000.0", 0.08, "simultaneous", "")]
assert verdict(overlap([]), twins, subscriptions_known=False)[0] == "observed"
def test_pairs_with_a_clean_subscription_list_point_somewhere_else():
twins = [("1000.0", 0.08, "simultaneous", "")]
state, detail = verdict(overlap(["app_mention"]), twins)
assert state == "elsewhere"
assert "Two processes" in detail
def test_retry_shaped_pairs_alone_are_handed_to_the_dedupe_note():
twins = [("1000.0", 60.1, "retry-shaped", "")]
assert verdict(overlap(["app_mention"]), twins)[0] == "retries"
def test_no_overlap_and_no_pairs_is_clear():
assert verdict(overlap(["app_mention"]), [])[0] == "clear"
import { test } from 'node:test';
import assert from 'node:assert/strict';
import {
gapState, mentionTwins, overlap, verdict,
} from './slack-event-overlap-audit.mjs';
const byWhere = (rows) => Object.fromEntries(rows.map((r) => [r[0], r]));
test('both events subscribed is the finding', () => {
const row = byWhere(overlap(['app_mention', 'message.channels']))['public channel'];
assert.equal(row[2], 'double-fire');
assert.match(row[3], /two deliveries/);
});
test('one event alone arrives once', () => {
assert.equal(byWhere(overlap(['app_mention']))['public channel'][2], 'single-path');
assert.equal(byWhere(overlap(['message.channels']))['public channel'][2],
'single-path');
});
test('a declared guard closes the finding', () => {
const rows = byWhere(overlap(['app_mention', 'message.channels'],
['message.channels']));
assert.equal(rows['public channel'][2], 'guarded');
});
test('a guard on one channel type does not cover another', () => {
const rows = byWhere(overlap(
['app_mention', 'message.channels', 'message.groups'], ['message.channels']));
assert.equal(rows['public channel'][2], 'guarded');
assert.equal(rows['private channel'][2], 'double-fire');
});
test('private channels and group dms have their own message event', () => {
const rows = byWhere(overlap(['app_mention', 'message.mpim']));
assert.equal(rows['group DM'][2], 'double-fire');
assert.equal(rows['public channel'][2], 'single-path');
});
test('nothing subscribed is not a finding', () => {
assert.equal(byWhere(overlap([]))['public channel'][2], 'not-subscribed');
assert.equal(overlap(null)[0][2], 'not-subscribed');
});
test('findings sort above resolved rows', () => {
const rows = overlap(['app_mention', 'message.channels', 'message.groups'],
['message.channels']);
assert.equal(rows[0][2], 'double-fire');
});
test('a sub second gap is two events for one message', () => {
const [state, detail] = gapState(0.12);
assert.equal(state, 'simultaneous');
assert.match(detail, /same tick/);
});
test('a sixty second gap belongs to the retry note', () => {
assert.equal(gapState(60.4)[0], 'retry-shaped');
assert.equal(gapState(300)[0], 'retry-shaped');
assert.match(gapState(60.4)[1], /retry schedule/);
});
test('a gap matching neither regime is not attributed', () => {
assert.equal(gapState(9)[0], 'unattributed');
assert.equal(gapState(null)[0], 'unattributed');
assert.equal(gapState('later')[0], 'unattributed');
});
test('two replies to a mention are the symptom', () => {
const msgs = [
{ ts: '1000.000000', user: 'U9', text: 'hey <@U0BOT> status' },
{ ts: '1000.400000', bot_id: 'B1', text: 'ok' },
{ ts: '1000.480000', bot_id: 'B1', text: 'ok' },
];
const rows = mentionTwins(msgs, 'B1', 'U0BOT');
assert.equal(rows.length, 1);
assert.equal(rows[0][2], 'simultaneous');
});
test('history arriving newest first is ordered before it is read', () => {
const msgs = [
{ ts: '1000.480000', bot_id: 'B1', text: 'ok' },
{ ts: '1000.400000', bot_id: 'B1', text: 'ok' },
{ ts: '1000.000000', user: 'U9', text: 'hey <@U0BOT> status' },
];
assert.equal(mentionTwins(msgs, 'B1', 'U0BOT')[0][2], 'simultaneous');
});
test('a pair with no mention in front of it is not this note', () => {
const msgs = [
{ ts: '1000.000000', user: 'U9', text: 'morning everyone' },
{ ts: '1000.400000', bot_id: 'B1', text: 'ok' },
{ ts: '1000.480000', bot_id: 'B1', text: 'ok' },
];
const rows = mentionTwins(msgs, 'B1', 'U0BOT');
assert.equal(rows[0][2], 'unattributed');
assert.match(rows[0][3], /echo loop/);
});
test('a single reply to a mention is not a pair', () => {
const msgs = [
{ ts: '1000.000000', user: 'U9', text: '<@U0BOT> status' },
{ ts: '1000.400000', bot_id: 'B1', text: 'ok' },
];
assert.deepEqual(mentionTwins(msgs, 'B1', 'U0BOT'), []);
});
test('replies from another bot are not counted as ours', () => {
const msgs = [
{ ts: '1000.000000', user: 'U9', text: '<@U0BOT> status' },
{ ts: '1000.400000', bot_id: 'B2', text: 'ok' },
{ ts: '1000.480000', bot_id: 'B2', text: 'ok' },
];
assert.deepEqual(mentionTwins(msgs, 'B1', 'U0BOT'), []);
});
test('a retry shaped pair after a mention is named as such', () => {
const msgs = [
{ ts: '1000.000000', user: 'U9', text: '<@U0BOT> status' },
{ ts: '1000.400000', bot_id: 'B1', text: 'ok' },
{ ts: '1060.500000', bot_id: 'B1', text: 'ok' },
];
assert.equal(mentionTwins(msgs, 'B1', 'U0BOT')[0][2], 'retry-shaped');
});
test('the configuration alone is enough to report', () => {
const [state, detail] = verdict(overlap(['app_mention', 'message.channels']), []);
assert.equal(state, 'configured');
assert.match(detail, /whether or not anyone has complained/);
});
test('configuration plus observed pairs is confirmed', () => {
const twins = [['1000.0', 0.08, 'simultaneous', '']];
assert.equal(verdict(overlap(['app_mention', 'message.channels']), twins)[0],
'confirmed');
});
test('pairs without a subscription list ask for the manifest', () => {
const twins = [['1000.0', 0.08, 'simultaneous', '']];
assert.equal(verdict(overlap([]), twins, false)[0], 'observed');
});
test('pairs with a clean subscription list point somewhere else', () => {
const twins = [['1000.0', 0.08, 'simultaneous', '']];
const [state, detail] = verdict(overlap(['app_mention']), twins);
assert.equal(state, 'elsewhere');
assert.match(detail, /Two processes/);
});
test('retry shaped pairs alone are handed to the dedupe note', () => {
const twins = [['1000.0', 60.1, 'retry-shaped', '']];
assert.equal(verdict(overlap(['app_mention']), twins)[0], 'retries');
});
test('no overlap and no pairs is clear', () => {
assert.equal(verdict(overlap(['app_mention']), [])[0], 'clear');
});
FAQ
I added a dedupe store keyed on event_id and it still replies twice. Why?
Because your dedupe store is working correctly and there is nothing here for it to catch. app_mention and message.channels are two different events with two different event_id values, so an idempotency key sees two distinct events and passes both, which is exactly what you want it to do when two distinct events arrive. Deduplication defends against one event being delivered more than once. This is two events being delivered once each.
How do I tell this apart from a retry without reading any configuration?
Subtract the two timestamps. A double subscription is handled in the same tick and the copies land milliseconds apart, typically under half a second. Slack's retry schedule is roughly sixty seconds and then five minutes, so retried copies land a minute or more apart. Nothing lands in between, which is why one subtraction is enough to pick the note you should be reading.
Should I just unsubscribe from message.channels?
Only if nothing needs it. Many apps subscribe to messages for a genuine feature, such as noticing links or keywords, and in that case the pair stays subscribed forever and the overlap is permanent. The correct repair then is a guard in the message handler: skip any message whose text contains your bot user id, and let app_mention own everything addressed to you. The script reports a declared guard as resolved rather than insisting the subscription go.
Why guard the message handler rather than the app_mention one?
Because app_mention is the narrower event and the better one to keep for directed commands. It carries the mention semantics, it never fires on your own posts, and it is what the feature was written against. The general message handler is the one that was never meant to answer commands, so it is the one that should learn to step aside.
What about a one-to-one DM with the bot? Does that double up too?
It does not need a mention to reach you, which changes the shape of the problem. In a DM the app already receives message.im for everything said to it, so a guard written as “ignore anything that mentions me” can silence the DM path entirely if the same handler serves both. Guard on the pairing rather than on the mention alone: skip a message event only in the conversation types where app_mention would also have fired.
Related field notes
- counting the copies once they are in the channel
- the other twin, arriving sixty seconds later
- when the second message is your own and you answer it
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.
- app_mention event reference - Slack Docs
- message event reference - Slack Docs
- The Events API - Slack Docs
- conversations.history 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.