Skip to content

Commit 789c6f8

Browse files
ShinyChangclaude
andauthored
fix(slack): detect half-open Socket Mode via ping + idle-timeout reconnect (#1120)
* fix(slack): detect half-open Socket Mode via ping + idle-timeout reconnect Slack's inbound Socket Mode WebSocket can go half-open (e.g. a NAT idle-timeout silently drops inbound frames with no Close/FIN), which leaves read.next() blocked forever so the reconnect loop never fires. The bot then goes deaf to @mentions for hours while still logging "Slack Socket Mode connected" (only outbound cron posts keep it looking alive). Add a proactive WebSocket ping plus an idle-timeout that forces a reconnect when no inbound frame (including Slack's own server pings) has arrived within 75s, and align the reconnect delay with the gateway adapter's capped exponential backoff (reset-on-success, interruptible by shutdown). The idle and backoff decisions are pure functions with unit tests. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com> * fix(slack): bound Slack Web API I/O to keep the read loop responsive Follow-up to the heartbeat change: inline Slack Web API awaits in the read loop (conversations.replies, bot_participated_in_thread, trusted-bot lookup) could delay the idle-timeout watchdog tick. Keep gating serial in the read loop (the batching ADR's canonical adapter pattern) and bound the I/O instead of moving it off-thread: - give the Slack Web API client a 30s request timeout (was unbounded) - resolve bot_user_id once before the loop (no cold-cache auth.test inline) - send the turn-limit warning off the bot_turns lock, with its result logged Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com> --------- Co-authored-by: Claude Opus 4.8 <noreply@anthropic.com>
1 parent 78f4129 commit 789c6f8

1 file changed

Lines changed: 136 additions & 30 deletions

File tree

src/slack.rs

Lines changed: 136 additions & 30 deletions
Original file line numberDiff line numberDiff line change
@@ -93,7 +93,12 @@ impl SlackAdapter {
9393
assistant_mode: bool,
9494
) -> Self {
9595
Self {
96-
client: reqwest::Client::new(),
96+
// Bound every Slack Web API call; an unbounded inline gating call in the
97+
// read loop could otherwise stall the Socket Mode idle-timeout watchdog.
98+
client: reqwest::Client::builder()
99+
.timeout(std::time::Duration::from_secs(30))
100+
.build()
101+
.unwrap_or_else(|_| reqwest::Client::new()),
97102
bot_token,
98103
bot_user_id: tokio::sync::OnceCell::new(),
99104
user_cache: tokio::sync::Mutex::new(HashMap::new()),
@@ -674,6 +679,28 @@ impl ChatAdapter for SlackAdapter {
674679
/// Hard cap on consecutive bot messages in a thread. Prevents runaway loops.
675680
const MAX_CONSECUTIVE_BOT_TURNS: usize = 1000;
676681

682+
/// Socket Mode keepalive. Slack's inbound WebSocket can go half-open (e.g. a NAT
683+
/// idle-timeout silently drops inbound frames with no Close/FIN), which leaves
684+
/// `read.next()` blocked forever, so the reconnect loop never fires and the bot
685+
/// goes deaf while still showing as connected. We proactively ping and force a
686+
/// reconnect when no inbound frame (including Slack's own pings) has arrived
687+
/// within the idle window. Reconnect backoff mirrors the gateway adapter.
688+
const PING_INTERVAL_SECS: u64 = 30;
689+
const IDLE_TIMEOUT_SECS: u64 = 75;
690+
const MAX_BACKOFF_SECS: u64 = 30;
691+
692+
/// Next reconnect delay: double, capped. Reset to 1 on a successful connect.
693+
fn next_backoff(cur: u64) -> u64 {
694+
(cur * 2).min(MAX_BACKOFF_SECS)
695+
}
696+
697+
/// The socket is considered dead (half-open) when no inbound frame has arrived
698+
/// within `timeout`; Slack sends periodic pings, so silence past the window
699+
/// means the inbound path is gone.
700+
fn socket_idle(since_last_inbound: std::time::Duration, timeout: std::time::Duration) -> bool {
701+
since_last_inbound >= timeout
702+
}
703+
677704
/// Run the Slack adapter using Socket Mode (persistent WebSocket, no public URL needed).
678705
/// Reconnects automatically on disconnect.
679706
#[allow(clippy::too_many_arguments)]
@@ -694,6 +721,10 @@ pub async fn run_slack_adapter(
694721
) -> Result<()> {
695722
let bot_token = adapter.bot_token().to_string();
696723
let bot_turns = Arc::new(tokio::sync::Mutex::new(BotTurnTracker::new(max_bot_turns)));
724+
// Warm the bot-user-id cache once so the per-message path never does the
725+
// cold-cache `auth.test` inline in the read loop.
726+
let _ = adapter.get_bot_user_id().await;
727+
let mut backoff_secs = 1u64;
697728

698729
loop {
699730
// Check for shutdown before (re)connecting
@@ -705,8 +736,12 @@ pub async fn run_slack_adapter(
705736
let ws_url = match get_socket_mode_url(&app_token).await {
706737
Ok(url) => url,
707738
Err(e) => {
708-
error!("failed to get Socket Mode URL: {e}");
709-
tokio::time::sleep(std::time::Duration::from_secs(5)).await;
739+
error!(err = %e, backoff = backoff_secs, "failed to get Socket Mode URL, retrying");
740+
tokio::select! {
741+
_ = tokio::time::sleep(std::time::Duration::from_secs(backoff_secs)) => {}
742+
_ = shutdown_rx.changed() => { return Ok(()); }
743+
}
744+
backoff_secs = next_backoff(backoff_secs);
710745
continue;
711746
}
712747
};
@@ -715,11 +750,17 @@ pub async fn run_slack_adapter(
715750
match tokio_tungstenite::connect_async(&ws_url).await {
716751
Ok((ws_stream, _)) => {
717752
info!("Slack Socket Mode connected");
753+
backoff_secs = 1; // reset on success
718754
let (mut write, mut read) = ws_stream.split();
755+
let mut ping_interval =
756+
tokio::time::interval(std::time::Duration::from_secs(PING_INTERVAL_SECS));
757+
ping_interval.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Delay);
758+
let mut last_inbound = std::time::Instant::now();
719759

720760
loop {
721761
tokio::select! {
722762
msg_result = read.next() => {
763+
last_inbound = std::time::Instant::now();
723764
let Some(msg_result) = msg_result else { break };
724765
match msg_result {
725766
Ok(tungstenite::Message::Text(text)) => {
@@ -864,34 +905,47 @@ pub async fn run_slack_adapter(
864905
} else {
865906
format!("{}:{}", channel_id, event["ts"].as_str().unwrap_or(""))
866907
};
867-
{
908+
// Classify under the lock (order-sensitive, kept in the read
909+
// loop), but run any warning send AFTER releasing it; holding
910+
// the tracker mutex across `chat.postMessage` would stall turn
911+
// tracking for every thread, not just this one.
912+
let turn_action = {
868913
let mut tracker = bot_turns.lock().await;
869914
if is_bot {
870-
match tracker.classify_bot_message(&turn_key) {
871-
TurnAction::Continue => {}
872-
TurnAction::SilentStop => continue,
873-
TurnAction::WarnAndStop { severity, turns, user_message } => {
874-
match severity {
875-
TurnSeverity::Hard => warn!(channel_id, turns, "hard bot turn limit reached"),
876-
TurnSeverity::Soft => info!(channel_id, turns, max = max_bot_turns, "soft bot turn limit reached"),
877-
}
878-
let channel_allowed = allow_all_channels
879-
|| allowed_channels.contains(channel_id);
880-
if !is_own_bot_msg && channel_allowed {
881-
let warn_channel = ChannelRef {
882-
platform: "slack".into(),
883-
channel_id: channel_id.to_string(),
884-
thread_id: event["thread_ts"].as_str().map(|s| s.to_string()),
885-
parent_id: None,
886-
origin_event_id: None,
887-
};
888-
let _ = adapter.send_message(&warn_channel, &user_message).await;
915+
tracker.classify_bot_message(&turn_key)
916+
} else {
917+
if is_plain_user_message(subtype, msg_text) {
918+
tracker.on_human_message(&turn_key);
919+
}
920+
TurnAction::Continue
921+
}
922+
};
923+
match turn_action {
924+
TurnAction::Continue => {}
925+
TurnAction::SilentStop => continue,
926+
TurnAction::WarnAndStop { severity, turns, user_message } => {
927+
match severity {
928+
TurnSeverity::Hard => warn!(channel_id, turns, "hard bot turn limit reached"),
929+
TurnSeverity::Soft => info!(channel_id, turns, max = max_bot_turns, "soft bot turn limit reached"),
930+
}
931+
let channel_allowed = allow_all_channels
932+
|| allowed_channels.contains(channel_id);
933+
if !is_own_bot_msg && channel_allowed {
934+
let warn_channel = ChannelRef {
935+
platform: "slack".into(),
936+
channel_id: channel_id.to_string(),
937+
thread_id: event["thread_ts"].as_str().map(|s| s.to_string()),
938+
parent_id: None,
939+
origin_event_id: None,
940+
};
941+
let adapter = adapter.clone();
942+
tokio::spawn(async move {
943+
if let Err(e) = adapter.send_message(&warn_channel, &user_message).await {
944+
warn!(error = %e, "failed to send bot turn limit warning");
889945
}
890-
continue;
891-
}
946+
});
892947
}
893-
} else if is_plain_user_message(subtype, msg_text) {
894-
tracker.on_human_message(&turn_key);
948+
continue;
895949
}
896950
}
897951

@@ -1058,6 +1112,22 @@ pub async fn run_slack_adapter(
10581112
_ => {}
10591113
}
10601114
}
1115+
_ = ping_interval.tick() => {
1116+
if socket_idle(
1117+
last_inbound.elapsed(),
1118+
std::time::Duration::from_secs(IDLE_TIMEOUT_SECS),
1119+
) {
1120+
warn!(
1121+
idle_secs = last_inbound.elapsed().as_secs(),
1122+
"Slack Socket Mode idle past timeout (likely half-open), forcing reconnect"
1123+
);
1124+
break;
1125+
}
1126+
if let Err(e) = write.send(tungstenite::Message::Ping(Vec::new())).await {
1127+
warn!(error = %e, "Slack Socket Mode ping failed, reconnecting");
1128+
break;
1129+
}
1130+
}
10611131
_ = shutdown_rx.changed() => {
10621132
info!("Slack adapter received shutdown signal");
10631133
let _ = write.send(tungstenite::Message::Close(None)).await;
@@ -1067,12 +1137,16 @@ pub async fn run_slack_adapter(
10671137
}
10681138
}
10691139
Err(e) => {
1070-
error!("failed to connect to Slack Socket Mode: {e}");
1140+
error!(err = %e, backoff = backoff_secs, "failed to connect to Slack Socket Mode, retrying");
10711141
}
10721142
}
10731143

1074-
warn!("reconnecting to Slack Socket Mode in 5s...");
1075-
tokio::time::sleep(std::time::Duration::from_secs(5)).await;
1144+
warn!(backoff = backoff_secs, "reconnecting to Slack Socket Mode");
1145+
tokio::select! {
1146+
_ = tokio::time::sleep(std::time::Duration::from_secs(backoff_secs)) => {}
1147+
_ = shutdown_rx.changed() => { return Ok(()); }
1148+
}
1149+
backoff_secs = next_backoff(backoff_secs);
10761150
}
10771151
}
10781152

@@ -2216,3 +2290,35 @@ mod tests {
22162290
assert!(adapter.renders_native_tables());
22172291
}
22182292
}
2293+
2294+
#[cfg(test)]
2295+
mod socket_keepalive_tests {
2296+
use super::{next_backoff, socket_idle, IDLE_TIMEOUT_SECS, MAX_BACKOFF_SECS};
2297+
use std::time::Duration;
2298+
2299+
/// Backoff doubles and caps, matching the gateway adapter (1,2,4,8,16,30,30…).
2300+
#[test]
2301+
fn backoff_doubles_then_caps() {
2302+
let mut b = 1u64;
2303+
let seq: Vec<u64> = (0..8)
2304+
.map(|_| {
2305+
let cur = b;
2306+
b = next_backoff(b);
2307+
cur
2308+
})
2309+
.collect();
2310+
assert_eq!(seq, vec![1, 2, 4, 8, 16, MAX_BACKOFF_SECS, MAX_BACKOFF_SECS, MAX_BACKOFF_SECS]);
2311+
assert_eq!(next_backoff(MAX_BACKOFF_SECS), MAX_BACKOFF_SECS);
2312+
}
2313+
2314+
/// A half-open socket (no inbound past the window) is detected; an active one
2315+
/// (recent inbound, e.g. a Slack ping) is not. This is the deaf-socket guard.
2316+
#[test]
2317+
fn idle_detects_half_open_at_boundary() {
2318+
let timeout = Duration::from_secs(IDLE_TIMEOUT_SECS);
2319+
assert!(!socket_idle(Duration::from_secs(0), timeout));
2320+
assert!(!socket_idle(Duration::from_secs(IDLE_TIMEOUT_SECS - 1), timeout));
2321+
assert!(socket_idle(Duration::from_secs(IDLE_TIMEOUT_SECS), timeout));
2322+
assert!(socket_idle(Duration::from_secs(IDLE_TIMEOUT_SECS + 10), timeout));
2323+
}
2324+
}

0 commit comments

Comments
 (0)