Diagnostic Slack
refresh_requested: Slack takes the socket back every few hours
The dashboard has a sawtooth in it. Every few hours the bot's response count drops to nothing for about forty seconds and then recovers on its own, and because it recovers on its own nobody has ever opened a ticket. The supervisor restarts the process, the restart is logged as normal, and the four or five messages that arrived during the restart are simply not in the app's database.
Slack did that on purpose. It sends a disconnect message with reason: "refresh_requested", warns you about ten seconds beforehand so you can have a replacement connection ready, and expects you to overlap the two. A client that treats the disconnect as an error, or that closes the old socket before opening the new one, drops everything that arrives in the seam.
Socket Mode connections are not meant to be permanent. Slack refreshes them every few hours by sending a disconnect frame with reason: "refresh_requested", preceded by a warning roughly ten seconds earlier. That warning exists for exactly one purpose: open the replacement connection first, and close the old one only once the new one has received hello. Overlap, do not swap.
Two things go wrong. A client that treats any disconnect as a fault dies and is restarted, losing everything that arrives during the restart. A client that reconnects politely but serially — close, then open — loses whatever arrives in between, which is shorter and just as invisible. Both produce the same workspace-side signature and neither logs anything an operator would read as a problem.
The signature is periodicity, and that is what distinguishes this from every other Socket Mode fault. Group the unanswered mentions into clusters, take the interval between cluster starts, and measure how regular it is. A leaked connection pool loses payloads uniformly at random. This loses them in tight bunches, a few tens of seconds wide, arriving on a clock. link_disabled, the other documented reason, is the opposite: it never recovers, because Socket Mode was switched off in the app configuration and reconnecting will not bring it back.
The problem in plain words
What makes this expensive is that it self-heals. Every symptom disappears before anyone can look at it. The process comes back, the connection re-establishes, the queue drains, and the graph returns to normal, so the incident never becomes an incident — it becomes a shrug. Meanwhile the messages that landed in the seam are gone for good: Socket Mode has no redelivery, no acknowledgement window, and no replay. A payload sent to a connection that is closing is not resent to the one that opens next.
The clue everybody misses is the warning frame. Slack tells you ten seconds in advance, which is a strange thing to do unless the client is expected to act on it, and most hand-rolled Socket Mode implementations ignore it entirely. They handle events_api messages, acknowledge them, and treat every other frame as noise. The warning arrives, is discarded, the disconnect arrives ten seconds later, and the client now has to build a connection from scratch while payloads are already being routed elsewhere or dropped.
The serial reconnect is the subtler version and it is written by careful people. Close the socket cleanly, wait for the close handshake, then call apps.connections.open and connect to the URL it returns. That is correct WebSocket hygiene and it is wrong here, because it puts a hole of a second or two between the two connections and Slack has nowhere to put a payload that arrives in it. The gap is small enough that a low-traffic app can go months without noticing and a busy one loses a handful of events every few hours forever.
Then there is link_disabled, which lands in the same handler and means something entirely different. It is not a refresh. It means Socket Mode has been turned off in the app configuration, and every reconnect attempt from here to the heat death of the universe will fail the same way. A client that treats disconnects as uniformly transient will retry that forever, which is how an app ends up silent for a week after somebody toggled a setting.
Why it happens
Periodicity is the whole diagnosis. Every Socket Mode failure looks like missing messages. What separates them is when the messages are missing. Uniform scatter across the window is a connection pool with ghosts in it. A single step with nothing after it is a connection that never opened. Duplicates alongside misses is several replicas. Tight clusters arriving on a regular multi-hour clock is this, and nothing else produces that shape.
The width of each cluster says which of the two mistakes you made. A serial reconnect leaves a seam of seconds; a process that died and was restarted by a supervisor leaves tens of seconds to a few minutes; a gap of a quarter of an hour is not a reconnect at all. The script classifies each cluster by width and reports the mix, because “handle the disconnect” and “stop crashing on the disconnect” are different pieces of work.
The reasons are not interchangeable and the client must branch on them. refresh_requested is routine and wants an overlap. link_disabled is permanent and wants an alarm, not a retry. too_many_websockets is the cap and wants a different note entirely. A single catch around the whole thing is what turns three distinct conditions into one reconnect loop.
Regularity has to be measured, not eyeballed. Three clusters is the minimum from which an interval can be claimed at all, and the script says too-few rather than inventing a cadence from two. Beyond that it uses the coefficient of variation of the intervals, so a genuinely regular refresh passes and a coincidental pair of outages does not.
A cadence outside the plausible range is a different problem wearing this one's clothes. Clusters every four minutes are not Slack refreshing your connection; clusters every eleven days are not either. The script bounds what it will call a refresh cadence and reports the measured interval when it refuses, because the interval itself is usually the clue to whatever is really happening.
None of this requires a socket. The disconnect frames are yours — they arrived at your client and your client logged them, or did not. The gaps are the workspace's, and conversations.history hands them over. Opening a connection to watch for a refresh would mean holding one open for hours and consuming one of the ten the app is allowed, to observe an event the log already recorded.
The fix, as a flow
The red arrow is in the middle here, later than in either of the notes before it, because nothing is wrong with this connection until Slack takes it back. The warning arrives on time, the disconnect arrives on time, and the fault is one line of ordering: close, then open, with a seam in between that has nowhere to put a payload. The fix branch is the only one in the batch that sorts reasons, and the point of it is that two of these four arrive in the same handler and want opposite responses.
How to fix it
Read the disconnect reasons you already have
disconnect_meaning maps each documented reason to what the client should have done: overlap for refresh_requested, stop and alarm for link_disabled, and a pointer elsewhere for too_many_websockets. Pass the reasons your client logged with --reasons. This is the direct evidence, and it costs nothing to collect because it has already been collected.
Find the mentions that never got an answer
unanswered_mentions pages conversations.history and returns the timestamps of mentions with no app reply inside the window. It returns timestamps rather than a count, because the count is not the finding here and the arrangement of them is.
Group them into gaps
clusters splits the timestamps wherever more than --cluster-gap seconds pass without a miss. Each resulting group is one outage. Everything after this step is about the groups rather than the individual losses.
Measure how regular the groups are
regularity takes the cluster start times and returns the mean interval and its coefficient of variation. A refresh schedule produces a small coefficient; unrelated outages produce a large one. Fewer than three clusters returns too-few, because two points make a line whether or not there is a pattern.
Classify each gap by how wide it is
gap_kind sorts a cluster width into swap-gap, restart or outage. Seconds mean a serial reconnect; tens of seconds to minutes mean the process died and came back; longer means something that is not a reconnect at all and should not be filed under this note.
Open the new connection before closing the old one
The repair is an ordering change. On warning, or at the latest on disconnect with refresh_requested, open a replacement connection and keep the old one until the new one has received hello. On link_disabled, stop reconnecting and raise a configuration error. The official Socket Mode clients already do the overlap, which is why the honest repair for most apps is to stop hand-rolling the WebSocket layer.
How to check it worked
After the change, run it again over a window that spans several refreshes. The clusters should stop being periodic, because they should stop existing.
python3 slack_socket_refresh_gaps.py --channel C05OPS9QT --reasons refresh_requested,refresh_requested,refresh_requested
# identity U07BOT9QD (opsbot) in Northwind
# reason refresh_requested scheduled Slack refreshes connections on its own
# clock. Overlap the replacement; do not swap it
# history 1000 message(s) from C05OPS9QT
# misses 14 mention(s) with no reply inside 45s
# clusters 4 gap(s) in the window
# width swap-gap 3 of 4 gap(s) are seconds wide
# width restart 1 of 4 gap(s) is tens of seconds wide
# interval periodic mean 4h 02m between gaps, variation 0.06
# verdict refresh-not-overlapped the losses arrive on Slack's refresh clock
# repair: on warning and on refresh_requested, open the new connection first and
# close the old one only after it receives hello
# repair: branch on the disconnect reason; link_disabled is permanent and is not
# a retry
# note: no connection was opened to establish this; the frames are from your logThe full code
The statistic is the point. clusters turns a list of losses into a list of outages, and regularity asks whether those outages arrive on a clock — which is the one measurement that separates this failure from every other way a Socket Mode app loses messages. gap_kind then says whether each outage is a seam or a restart, because those want different fixes. disconnect_meaning handles the direct evidence, and it exists mainly to keep link_disabled from being retried alongside refresh_requested.
"""Find the periodic gaps a mishandled Socket Mode refresh leaves behind.
Read only. Nothing here opens a WebSocket: observing a refresh directly would
mean holding a connection open for hours, consuming one of the ten an app is
allowed, in order to watch a frame your own client already logged. The frames
come from that log, and the gaps come from conversations.history.
The question is not whether messages were lost - every Socket Mode fault loses
messages. The question is whether they were lost on a schedule, because that is
what Slack refreshing your connection looks like from the workspace side.
"""
import argparse
import logging
import math
import os
import sys
import requests
logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(message)s")
log = logging.getLogger("slack_socket_refresh_gaps")
API = "https://slack.com/api/"
# The documented reasons, and what the client was supposed to do about each.
# A single catch around all of them is how three distinct conditions become one
# reconnect loop that never surfaces any of them.
REASONS = {
"refresh_requested": (
"scheduled",
"Slack refreshes connections on its own clock, every few hours, and warns "
"about ten seconds ahead. Open the replacement first and close the old one "
"once the new one has received hello"),
"warning": (
"notice",
"the ten second warning before a refresh. This is the frame to act on, and "
"the one most hand-rolled clients discard as noise"),
"link_disabled": (
"configuration",
"Socket Mode was switched off in the app configuration. Reconnecting will "
"never succeed. Stop retrying and raise a configuration error"),
"too_many_websockets": (
"cap",
"the app is at its ten connection ceiling. That is a leak or a replica count, "
"and it is a different problem from a refresh"),
}
# Widths. A serial reconnect leaves seconds; a process that died and was
# restarted leaves tens of seconds to minutes; anything longer is not a
# reconnect and should not be filed under this note.
SWAP_SECONDS = 90.0
RESTART_SECONDS = 900.0
def disconnect_meaning(reason):
"""What did this disconnect frame mean, and what should follow it? Pure.
Returns (kind, detail). The value of this function is that link_disabled
and refresh_requested arrive in the same handler and want opposite
responses: one is routine and wants an overlapping reconnect, the other is
permanent and wants an alarm.
"""
text = str(reason or "").strip()
if not text:
return ("unreported", "no reason was supplied; the timing evidence below "
"stands on its own")
if text in REASONS:
return REASONS[text]
return ("unknown", "%s is not one of the documented reasons; read it against the "
"Socket Mode reference before treating it as transient" % text)
def unanswered_mentions(messages, bot_user_id, window=45.0):
"""Timestamps of mentions the app never answered. Pure.
Timestamps rather than a count, because for this note the arrangement is
the finding and the total is almost meaningless.
"""
marker = "<@%s>" % bot_user_id if bot_user_id else None
own, mentions = [], []
for m in messages or []:
ts = str((m or {}).get("ts") or "")
if not ts:
continue
author = (m or {}).get("user") or ""
if (bot_user_id and author == bot_user_id) or (m or {}).get("bot_id"):
own.append(float(ts))
elif marker and marker in str((m or {}).get("text") or ""):
mentions.append(float(ts))
return sorted(ts for ts in mentions
if not any(ts <= o <= ts + float(window) for o in own))
def clusters(stamps, gap=120.0):
"""Group losses into outages. Pure.
A new group starts wherever more than `gap` seconds pass without a miss.
Everything after this point is reasoning about groups rather than about
individual lost messages, which is the shift that makes the diagnosis
possible at all.
"""
ordered = sorted(float(t) for t in stamps or [])
if not ordered:
return []
groups, current = [], [ordered[0]]
for ts in ordered[1:]:
if ts - current[-1] > float(gap):
groups.append(current)
current = [ts]
else:
current.append(ts)
groups.append(current)
return groups
def gap_kind(width):
"""How wide is this outage, and what does that width mean? Pure."""
seconds = float(width or 0.0)
if seconds <= SWAP_SECONDS:
return ("swap-gap", "seconds wide: a serial reconnect that closed before it "
"opened")
if seconds <= RESTART_SECONDS:
return ("restart", "tens of seconds to minutes: the process treated the "
"disconnect as fatal and was restarted")
return ("outage", "too wide to be a reconnect of any kind; this belongs to some "
"other failure")
def regularity(starts, min_clusters=3, tolerance=0.25):
"""Do these outages arrive on a clock? Pure.
Returns (state, mean_interval, cv). The coefficient of variation is the
whole test: a refresh schedule produces a small one and coincidental
outages produce a large one. Fewer than three clusters returns too-few,
because two points describe an interval whether or not a pattern exists.
"""
ordered = sorted(float(t) for t in starts or [])
if len(ordered) < max(3, min_clusters):
return ("too-few", 0.0, 0.0)
gaps = [b - a for a, b in zip(ordered, ordered[1:])]
mean = sum(gaps) / len(gaps)
if mean <= 0:
return ("irregular", 0.0, 0.0)
variance = sum((g - mean) ** 2 for g in gaps) / len(gaps)
cv = round(math.sqrt(variance) / mean, 3)
return (("periodic" if cv <= tolerance else "irregular"), round(mean, 1), cv)
def refresh_verdict(state, mean_interval, kinds, low=1800.0, high=86400.0):
"""Put the timing and the widths together. Pure. Returns (verdict, detail).
The bounds matter. Clusters every four minutes are not Slack refreshing a
connection and neither are clusters every eleven days, so the function
refuses those and reports the interval it measured, because the interval is
usually the clue to whatever is actually happening.
"""
if state == "too-few":
return ("too-few", "fewer than three outages in this window; there is no "
"cadence to claim yet")
if state != "periodic":
return ("not-periodic", "the outages do not arrive on a clock. Evenly "
"scattered losses point at a leaked connection pool "
"instead")
if mean_interval < low or mean_interval > high:
return ("wrong-cadence", "regular, at %.0f seconds apart, which is outside "
"the few-hours cadence a Socket Mode refresh runs "
"on" % mean_interval)
if kinds and all(k == "outage" for k in kinds):
return ("outage-shaped", "regular and on a plausible cadence, but every gap "
"is too wide to be a reconnect. Something else runs "
"on that schedule")
return ("refresh-not-overlapped",
"the losses arrive on Slack's refresh clock, every %.0f seconds, in gaps "
"narrow enough to be the seam between two connections" % mean_interval)
def page_history(session, channel, limit, max_pages):
"""Page conversations.history. A read, and one of two calls made."""
out, cursor, pages = [], "", 0
while pages < max_pages:
params = {"channel": channel, "limit": str(limit)}
if cursor:
params["cursor"] = cursor
body = session.get(API + "conversations.history", params=params,
timeout=30).json()
if body.get("ok") is not True:
log.error("history unavailable %s", body.get("error"))
return out
out.extend(body.get("messages") or [])
cursor = ((body.get("response_metadata") or {}).get("next_cursor") or "")
pages += 1
if not cursor:
break
return out
def main():
ap = argparse.ArgumentParser(description=__doc__)
ap.add_argument("--token-env", default="SLACK_BOT_TOKEN")
ap.add_argument("--channel", required=True)
ap.add_argument("--reasons", default="",
help="comma separated disconnect reasons your client logged")
ap.add_argument("--window", type=float, default=45.0)
ap.add_argument("--cluster-gap", type=float, default=120.0)
ap.add_argument("--limit", type=int, default=200)
ap.add_argument("--max-pages", type=int, default=10)
args = ap.parse_args()
seen = set()
for raw in args.reasons.split(","):
reason = raw.strip()
if not reason or reason in seen:
continue
seen.add(reason)
kind, detail = disconnect_meaning(reason)
log.info("reason %-18s %-12s %s", reason, kind, detail)
token = os.environ.get(args.token_env)
if not token:
log.error("set %s to a bot token with channels:history", 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 (%s) in %s", who.get("user_id"), who.get("user"),
who.get("team"))
messages = page_history(s, args.channel, args.limit, args.max_pages)
log.info("history %d message(s) from %s", len(messages), args.channel)
misses = unanswered_mentions(messages, who.get("user_id"), args.window)
log.info("misses %d mention(s) with no reply inside %.0fs", len(misses),
args.window)
groups = clusters(misses, args.cluster_gap)
log.info("clusters %d gap(s) in the window", len(groups))
kinds, notes = [], {}
for group in groups:
kind, detail = gap_kind(group[-1] - group[0])
kinds.append(kind)
notes[kind] = detail
for kind in sorted(set(kinds)):
log.info("width %-12s %d of %d gap(s): %s", kind, kinds.count(kind),
len(kinds), notes[kind])
state, mean_interval, cv = regularity([g[0] for g in groups])
log.info("interval %-12s mean %.0f seconds between gaps, variation %.3f",
state, mean_interval, cv)
verdict, detail = refresh_verdict(state, mean_interval, kinds)
if verdict != "refresh-not-overlapped":
log.info("verdict %-12s %s", verdict, detail)
if verdict == "not-periodic":
log.info(" next: read the note on the ten connection cap; evenly "
"spread losses are a leaked pool rather than a refresh")
return 0
log.warning("verdict %s %s", verdict, detail)
log.warning(" repair: on warning and on refresh_requested, open the new "
"connection first and close the old one after it receives hello")
log.warning(" repair: branch on the disconnect reason; link_disabled is "
"permanent and reconnecting on it loops forever")
log.warning(" note: no connection was opened to establish this; the frames "
"are from your own log and the gaps are from the workspace")
return 1
if __name__ == "__main__":
sys.exit(main())
/**
* Find the periodic gaps a mishandled Socket Mode refresh leaves behind.
*
* Read only. Nothing here opens a WebSocket: observing a refresh directly
* would mean holding a connection open for hours, consuming one of the ten an
* app is allowed, to watch a frame your own client already logged. The frames
* come from that log and the gaps come from conversations.history.
*
* The question is not whether messages were lost. It is whether they were lost
* on a schedule, because that is what a refresh looks like from outside.
*/
const API = 'https://slack.com/api/';
// The documented reasons, and what the client was supposed to do about each.
export const REASONS = {
refresh_requested: ['scheduled',
'Slack refreshes connections on its own clock, every few hours, and warns about '
+ 'ten seconds ahead. Open the replacement first and close the old one once the '
+ 'new one has received hello'],
warning: ['notice',
'the ten second warning before a refresh. This is the frame to act on, and the '
+ 'one most hand-rolled clients discard as noise'],
link_disabled: ['configuration',
'Socket Mode was switched off in the app configuration. Reconnecting will never '
+ 'succeed. Stop retrying and raise a configuration error'],
too_many_websockets: ['cap',
'the app is at its ten connection ceiling. That is a leak or a replica count, and '
+ 'it is a different problem from a refresh'],
};
export const SWAP_SECONDS = 90;
export const RESTART_SECONDS = 900;
/** What did this disconnect frame mean, and what should follow it? Pure. */
export function disconnectMeaning(reason) {
const text = String(reason ?? '').trim();
if (!text) {
return ['unreported',
'no reason was supplied; the timing evidence below stands on its own'];
}
if (Object.prototype.hasOwnProperty.call(REASONS, text)) return REASONS[text];
return ['unknown', `${text} is not one of the documented reasons; read it against `
+ 'the Socket Mode reference before treating it as transient'];
}
/** Timestamps of mentions the app never answered. Pure. */
export function unansweredMentions(messages, botUserId, window = 45) {
const marker = botUserId ? `<@${botUserId}>` : null;
const own = [];
const mentions = [];
for (const m of messages ?? []) {
const ts = String((m ?? {}).ts ?? '');
if (!ts) continue;
const author = (m ?? {}).user ?? '';
if ((botUserId && author === botUserId) || (m ?? {}).bot_id) own.push(Number(ts));
else if (marker && String((m ?? {}).text ?? '').includes(marker)) {
mentions.push(Number(ts));
}
}
return mentions
.filter((ts) => !own.some((o) => o >= ts && o <= ts + Number(window)))
.sort((a, b) => a - b);
}
/** Group losses into outages. Pure. */
export function clusters(stamps, gap = 120) {
const ordered = (stamps ?? []).map(Number).sort((a, b) => a - b);
if (!ordered.length) return [];
const groups = [];
let current = [ordered[0]];
for (const ts of ordered.slice(1)) {
if (ts - current[current.length - 1] > Number(gap)) {
groups.push(current);
current = [ts];
} else current.push(ts);
}
groups.push(current);
return groups;
}
/** How wide is this outage, and what does that width mean? Pure. */
export function gapKind(width) {
const seconds = Number(width) || 0;
if (seconds <= SWAP_SECONDS) {
return ['swap-gap', 'seconds wide: a serial reconnect that closed before it opened'];
}
if (seconds <= RESTART_SECONDS) {
return ['restart', 'tens of seconds to minutes: the process treated the disconnect '
+ 'as fatal and was restarted'];
}
return ['outage', 'too wide to be a reconnect of any kind; this belongs to some '
+ 'other failure'];
}
/**
* Do these outages arrive on a clock? Pure.
* Returns [state, meanInterval, cv]; the coefficient of variation is the test.
*/
export function regularity(starts, minClusters = 3, tolerance = 0.25) {
const ordered = (starts ?? []).map(Number).sort((a, b) => a - b);
if (ordered.length < Math.max(3, minClusters)) return ['too-few', 0, 0];
const gaps = ordered.slice(1).map((b, i) => b - ordered[i]);
const mean = gaps.reduce((a, b) => a + b, 0) / gaps.length;
if (mean <= 0) return ['irregular', 0, 0];
const variance = gaps.reduce((a, g) => a + ((g - mean) ** 2), 0) / gaps.length;
const cv = Math.round((Math.sqrt(variance) / mean) * 1000) / 1000;
return [cv <= tolerance ? 'periodic' : 'irregular', Math.round(mean * 10) / 10, cv];
}
/** Put the timing and the widths together. Pure. Returns [verdict, detail]. */
export function refreshVerdict(state, meanInterval, kinds, low = 1800, high = 86400) {
if (state === 'too-few') {
return ['too-few',
'fewer than three outages in this window; there is no cadence to claim yet'];
}
if (state !== 'periodic') {
return ['not-periodic', 'the outages do not arrive on a clock. Evenly scattered '
+ 'losses point at a leaked connection pool instead'];
}
if (meanInterval < low || meanInterval > high) {
return ['wrong-cadence', `regular, at ${Math.round(meanInterval)} seconds apart, `
+ 'which is outside the few-hours cadence a Socket Mode refresh runs on'];
}
if (kinds && kinds.length && kinds.every((k) => k === 'outage')) {
return ['outage-shaped', 'regular and on a plausible cadence, but every gap is too '
+ 'wide to be a reconnect. Something else runs on that schedule'];
}
return ['refresh-not-overlapped',
`the losses arrive on Slack refresh clock, every ${Math.round(meanInterval)} `
+ 'seconds, in gaps narrow enough to be the seam between two connections'];
}
function arg(args, name, fallback = null) {
const i = args.indexOf(name);
return i === -1 ? fallback : args[i + 1];
}
async function pageHistory(headers, channel, limit, maxPages) {
const out = [];
let cursor = '';
for (let page = 0; page < maxPages; page += 1) {
const params = new URLSearchParams({ channel, limit: String(limit) });
if (cursor) params.set('cursor', cursor);
const body = await (await fetch(`${API}conversations.history?${params}`,
{ headers })).json();
if (body.ok !== true) {
console.error(`history unavailable ${body.error}`);
return out;
}
out.push(...(body.messages ?? []));
cursor = (body.response_metadata ?? {}).next_cursor ?? '';
if (!cursor) break;
}
return out;
}
async function main() {
const args = process.argv.slice(2);
const seen = new Set();
for (const raw of String(arg(args, '--reasons', '')).split(',')) {
const reason = raw.trim();
if (!reason || seen.has(reason)) continue;
seen.add(reason);
const [kind, detail] = disconnectMeaning(reason);
console.log(`reason ${reason.padEnd(18)} ${kind.padEnd(12)} ${detail}`);
}
const tokenEnv = arg(args, '--token-env', 'SLACK_BOT_TOKEN');
const token = process.env[tokenEnv];
const channel = arg(args, '--channel', '');
if (!token || !channel) {
console.error(`set ${tokenEnv} to a bot token with channels:history, and pass `
+ '--channel');
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} (${who.user}) in ${who.team}`);
const window = Number(arg(args, '--window', '45'));
const messages = await pageHistory(headers, channel,
Number(arg(args, '--limit', '200')), Number(arg(args, '--max-pages', '10')));
console.log(`history ${messages.length} message(s) from ${channel}`);
const misses = unansweredMentions(messages, who.user_id, window);
console.log(`misses ${misses.length} mention(s) with no reply inside ${window}s`);
const groups = clusters(misses, Number(arg(args, '--cluster-gap', '120')));
console.log(`clusters ${groups.length} gap(s) in the window`);
const kinds = groups.map((g) => gapKind(g[g.length - 1] - g[0])[0]);
for (const kind of [...new Set(kinds)].sort()) {
console.log(`width ${kind.padEnd(12)} `
+ `${kinds.filter((k) => k === kind).length} of ${kinds.length} gap(s)`);
}
const [state, meanInterval, cv] = regularity(groups.map((g) => g[0]));
console.log(`interval ${state.padEnd(12)} mean ${Math.round(meanInterval)} seconds `
+ `between gaps, variation ${cv}`);
const [verdict, detail] = refreshVerdict(state, meanInterval, kinds);
if (verdict !== 'refresh-not-overlapped') {
console.log(`verdict ${verdict.padEnd(12)} ${detail}`);
if (verdict === 'not-periodic') {
console.log(' next: read the note on the ten connection cap; evenly spread '
+ 'losses are a leaked pool rather than a refresh');
}
return;
}
console.warn(`verdict ${verdict} ${detail}`);
console.warn(' repair: on warning and on refresh_requested, open the new connection '
+ 'first and close the old one after it receives hello');
console.warn(' repair: branch on the disconnect reason; link_disabled is permanent '
+ 'and reconnecting on it loops forever');
console.warn(' note: no connection was opened to establish this; the frames are '
+ 'from your own log and the gaps are from the workspace');
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 are written around the two ways this check could be wrong in public. It could claim a schedule that is not there, so regularity is tested with two clusters and must answer too-few, and with wildly uneven intervals and must answer irregular. Or it could claim this note for evidence that belongs to a neighbour, so refresh_verdict is tested against a four-minute cadence and against gaps that are hours wide, and refuses both. The reason table is tested for the one pairing that matters: link_disabled and refresh_requested must not come back as the same kind of thing.
from slack_socket_refresh_gaps import (
clusters, disconnect_meaning, gap_kind, refresh_verdict, regularity,
unanswered_mentions,
)
FOUR_HOURS = 14400.0
def test_a_refresh_is_scheduled_and_wants_an_overlap():
kind, detail = disconnect_meaning("refresh_requested")
assert kind == "scheduled"
assert "hello" in detail
def test_link_disabled_is_permanent_and_not_the_same_kind_of_thing():
assert disconnect_meaning("link_disabled")[0] == "configuration"
assert disconnect_meaning("link_disabled")[0] != disconnect_meaning(
"refresh_requested")[0]
def test_the_cap_reason_is_handed_to_the_other_note():
assert disconnect_meaning("too_many_websockets")[0] == "cap"
def test_the_ten_second_warning_is_its_own_frame():
assert disconnect_meaning("warning")[0] == "notice"
def test_an_unknown_reason_is_not_assumed_transient():
kind, detail = disconnect_meaning("something_new")
assert kind == "unknown"
assert "transient" in detail
def test_no_reason_at_all_is_not_a_finding():
assert disconnect_meaning("")[0] == "unreported"
assert disconnect_meaning(None)[0] == "unreported"
def test_only_mentions_without_a_reply_are_returned():
msgs = [{"ts": "100", "user": "U1", "text": "<@UBOT> a"},
{"ts": "110", "user": "UBOT", "text": "ok"},
{"ts": "200", "user": "U2", "text": "<@UBOT> b"}]
assert unanswered_mentions(msgs, "UBOT", 45) == [200.0]
def test_losses_close_together_are_one_outage():
assert clusters([100, 110, 120], 120) == [[100.0, 110.0, 120.0]]
def test_a_long_quiet_stretch_starts_a_new_outage():
assert clusters([100, 110, 5000], 120) == [[100.0, 110.0], [5000.0]]
def test_no_losses_means_no_outages():
assert clusters([]) == []
def test_a_seam_of_seconds_is_a_swap_gap():
assert gap_kind(20)[0] == "swap-gap"
def test_tens_of_seconds_is_a_restart():
assert gap_kind(300)[0] == "restart"
def test_a_gap_of_hours_is_not_a_reconnect_at_all():
assert gap_kind(7200)[0] == "outage"
def test_evenly_spaced_outages_are_periodic():
state, mean, cv = regularity([0, FOUR_HOURS, 2 * FOUR_HOURS, 3 * FOUR_HOURS])
assert state == "periodic"
assert mean == FOUR_HOURS
assert cv == 0.0
def test_wildly_uneven_outages_are_irregular():
assert regularity([0, 100, 50000, 50100])[0] == "irregular"
def test_two_outages_are_not_enough_to_claim_a_cadence():
assert regularity([0, FOUR_HOURS])[0] == "too-few"
assert regularity([])[0] == "too-few"
def test_a_periodic_multi_hour_cadence_of_narrow_gaps_is_the_finding():
verdict, detail = refresh_verdict("periodic", FOUR_HOURS,
["swap-gap", "swap-gap", "restart"])
assert verdict == "refresh-not-overlapped"
assert "seam" in detail
def test_scattered_losses_are_handed_to_the_connection_cap_note():
verdict, detail = refresh_verdict("irregular", FOUR_HOURS, ["swap-gap"])
assert verdict == "not-periodic"
assert "leaked connection pool" in detail
def test_a_four_minute_cadence_is_regular_and_is_not_a_refresh():
assert refresh_verdict("periodic", 240.0, ["swap-gap"])[0] == "wrong-cadence"
def test_gaps_too_wide_to_be_a_reconnect_are_refused_even_when_periodic():
assert refresh_verdict("periodic", FOUR_HOURS, ["outage", "outage"])[0] == (
"outage-shaped")
def test_too_few_outages_survives_into_the_verdict():
assert refresh_verdict("too-few", 0.0, [])[0] == "too-few"
import { test } from 'node:test';
import assert from 'node:assert/strict';
import {
clusters, disconnectMeaning, gapKind, refreshVerdict, regularity,
unansweredMentions,
} from './slack-socket-refresh-gaps.mjs';
const FOUR_HOURS = 14400;
test('a refresh is scheduled and wants an overlap', () => {
const [kind, detail] = disconnectMeaning('refresh_requested');
assert.equal(kind, 'scheduled');
assert.match(detail, /hello/);
});
test('link_disabled is permanent and not the same kind of thing', () => {
assert.equal(disconnectMeaning('link_disabled')[0], 'configuration');
assert.notEqual(disconnectMeaning('link_disabled')[0],
disconnectMeaning('refresh_requested')[0]);
});
test('the cap reason is handed to the other note', () => {
assert.equal(disconnectMeaning('too_many_websockets')[0], 'cap');
});
test('the ten second warning is its own frame', () => {
assert.equal(disconnectMeaning('warning')[0], 'notice');
});
test('an unknown reason is not assumed transient', () => {
const [kind, detail] = disconnectMeaning('something_new');
assert.equal(kind, 'unknown');
assert.match(detail, /transient/);
});
test('no reason at all is not a finding', () => {
assert.equal(disconnectMeaning('')[0], 'unreported');
assert.equal(disconnectMeaning(null)[0], 'unreported');
});
test('only mentions without a reply are returned', () => {
const msgs = [{ ts: '100', user: 'U1', text: '<@UBOT> a' },
{ ts: '110', user: 'UBOT', text: 'ok' },
{ ts: '200', user: 'U2', text: '<@UBOT> b' }];
assert.deepEqual(unansweredMentions(msgs, 'UBOT', 45), [200]);
});
test('losses close together are one outage', () => {
assert.deepEqual(clusters([100, 110, 120], 120), [[100, 110, 120]]);
});
test('a long quiet stretch starts a new outage', () => {
assert.deepEqual(clusters([100, 110, 5000], 120), [[100, 110], [5000]]);
});
test('no losses means no outages', () => {
assert.deepEqual(clusters([]), []);
});
test('a seam of seconds is a swap gap', () => {
assert.equal(gapKind(20)[0], 'swap-gap');
});
test('tens of seconds is a restart', () => {
assert.equal(gapKind(300)[0], 'restart');
});
test('a gap of hours is not a reconnect at all', () => {
assert.equal(gapKind(7200)[0], 'outage');
});
test('evenly spaced outages are periodic', () => {
const [state, mean, cv] = regularity([0, FOUR_HOURS, 2 * FOUR_HOURS,
3 * FOUR_HOURS]);
assert.equal(state, 'periodic');
assert.equal(mean, FOUR_HOURS);
assert.equal(cv, 0);
});
test('wildly uneven outages are irregular', () => {
assert.equal(regularity([0, 100, 50000, 50100])[0], 'irregular');
});
test('two outages are not enough to claim a cadence', () => {
assert.equal(regularity([0, FOUR_HOURS])[0], 'too-few');
assert.equal(regularity([])[0], 'too-few');
});
test('a periodic multi hour cadence of narrow gaps is the finding', () => {
const [verdict, detail] = refreshVerdict('periodic', FOUR_HOURS,
['swap-gap', 'swap-gap', 'restart']);
assert.equal(verdict, 'refresh-not-overlapped');
assert.match(detail, /seam/);
});
test('scattered losses are handed to the connection cap note', () => {
const [verdict, detail] = refreshVerdict('irregular', FOUR_HOURS, ['swap-gap']);
assert.equal(verdict, 'not-periodic');
assert.match(detail, /leaked connection pool/);
});
test('a four minute cadence is regular and is not a refresh', () => {
assert.equal(refreshVerdict('periodic', 240, ['swap-gap'])[0], 'wrong-cadence');
});
test('gaps too wide to be a reconnect are refused even when periodic', () => {
assert.equal(refreshVerdict('periodic', FOUR_HOURS, ['outage', 'outage'])[0],
'outage-shaped');
});
test('too few outages survives into the verdict', () => {
assert.equal(refreshVerdict('too-few', 0, [])[0], 'too-few');
});
FAQ
Is refresh_requested a bug on Slack's side?
No, it is documented behaviour and it is not going away. Socket Mode connections are refreshed periodically by design, and Slack goes out of its way to make it survivable: it sends a warning roughly ten seconds before the disconnect so a client has time to open a replacement. The bug is on the client side, and it is always one of two things. Either the disconnect is treated as an error and the process dies, or the reconnect is done in the wrong order, closing before opening.
Why not just reconnect faster?
Because the gap is not the problem, the ordering is. However fast a serial reconnect is, there is an interval during which your app has no open connection, and a payload that arrives then is gone: Socket Mode has no redelivery, no acknowledgement window and no replay. Making the gap a hundred milliseconds instead of two seconds reduces the loss rate and does not remove it. Overlapping the two connections removes it, because there is never a moment with nothing listening.
How is this different from a leaked connection pool?
By when the losses happen. A pool with dead registrations in it loses payloads uniformly at random, spread evenly across whatever window you look at, because each payload is an independent draw. A mishandled refresh loses payloads in tight bunches on a regular multi-hour clock, with normal service in between. The script measures the coefficient of variation of the intervals between outages precisely so it can tell you which one you have instead of asserting one.
Our client logs link_disabled, not refresh_requested. Same fix?
No, and this is the pairing worth getting right. link_disabled means Socket Mode has been switched off in the app configuration. There is no replacement connection to open, no overlap to arrange, and no number of retries that will help; the app will stay silent until somebody turns Socket Mode back on or configures a Request URL. It arrives in the same handler as a refresh and it wants an alarm rather than a reconnect, which is why the script keeps the two reasons in different categories.
The gaps are periodic but they are twenty minutes wide. Is that this?
Probably not, and the script refuses to call it this. A swap between two connections leaves a seam of seconds; a process that crashed and was restarted by a supervisor leaves tens of seconds to a few minutes. Twenty minutes is something else that runs on a schedule: a deploy, a cron job, a node rotation, a dependency with its own maintenance window. The measured interval and the gap width are both printed, because at that point the interval is the most useful clue you have.
Related field notes
- the other way delivery stops without an error
- the same reconnect problem on the retired transport
- why nothing in the log looked like a failure
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.
- Using Socket Mode - Slack Docs
- node-slack-sdk #1243: refresh_requested handled as a fatal disconnect
- bolt-js #2496: reconnect drops payloads in the swap window
- Events API - Slack Docs
If your setup is misbehaving in a way this note does not cover, message me on LinkedIn with what you are seeing.