環境:Python slack_sdk 3.40.1 的內建(builtin)SocketModeClient,外面包 Bolt 的 SocketModeHandler(它預設就是用這個 builtin client),程序跑在 macOS launchd 底下、KeepAlive 開著。症狀:Slack 端回了一次 invalid_auth 之後,SDK 自己重連成功,is_connected() 一直回 True,程序沒有結束,但之後再也沒有任何事件被處理。原本的看門狗只看 is_connected(),所以一次都沒觸發。
依事故紀錄,靜默從 00:09 持續到 11:50(台灣時間),約 11 小時 41 分鐘,最後是人發現 bot 沒回話、手動重啟才恢復。
時間軸
時間(台灣) Slack SDK monitor 執行緒 SDK 讀取執行緒 舊看門狗(60 秒) launchd
----------- --------------- ---------------------- -------------------- ------------------- ---------
00:09 前 送 envelope ───────────────────────────▶ 收得到事件 is_connected()=True 待命
00:09 apps.connections.open
回 invalid_auth ─▶ 記錄錯誤,程序不退出
之後 重連成功 ─────────▶ 新 session 建立
is_connected()=True ✗ 沒有任何 envelope is_connected()=True 程序沒退出
被處理 → 從不計數 → 不重拉
08:22/11:47 使用者 @bot ×2 (沒有回應)
11:50 人工發現 → 手動重啟 ──────────────────────────────────────────────────────────────▶ 新程序、恢復
圖 1:事故時序。00:09 與 11:50 兩個時間點、使用者兩次 @bot 的時間(08:22、11:47)來自事故紀錄與聊天記錄的時間戳;中間「重連成功、沒有 envelope 被處理」是依程序行為與修正後的量測推定,原始 log 摘錄見下一節的說明。
證據:哪些有佐證、哪些沒有
- 有原始碼佐證:
is_connected()與 stale 判斷在 3.40.1 怎麼寫,下一節逐行附上(GitHub tag v3.40.1,與實機安裝的檔案逐位元組比對相同)。 - 有事故紀錄佐證:當天的紀錄原文是「00:09 Slack 回 invalid_auth 後程式還在跑但收不到事件,[使用者]兩次 @[bot]沒反應,到 11:50 才發現」(方括號內為匿名化替換)。
- 沒有原始 log 佐證:重連成功那一行、最後一則 envelope 的時間、新 session 為什麼沒有任何事件(讀取端卡在舊連線、或新連線根本沒開始讀,這兩種可能目前無法區分)。這篇不寫推測出來的 log 內容。
- 本次沒有保留描述故障的對話原文;使用者兩次 @bot 的訊息是一般工作請求,與故障本身無關,只拿它的時間戳當「這段時間確實有人在找 bot」的證據。
SDK 3.40.1 怎麼判斷「還連著」
# builtin/client.py L153-154
def is_connected(self) -> bool:
return self.current_session is not None and self.current_session.is_active()
# builtin/connection.py L197-198
def is_active(self) -> bool:
return self.sock is not None
# builtin/connection.py L84(建立連線時)/L375(讀取執行緒收到 pong 才寫)
self.last_ping_pong_time = None
self.last_ping_pong_time = float(ping_time)
# builtin/connection.py L261, L271(check_state:只有收過 pong 才判 stale)
if self.last_ping_pong_time is not None:
is_stale = disconnected_seconds > self.ping_interval * 4
# client.py L46-48(重連拿新 URL:用的是 app-level token)
def issue_new_wss_url(self) -> str:
response = self.web_client.apps_connections_open(app_token=self.app_token)
# builtin/client.py L286-291(monitor 重連失敗只記 log,程序不退出)
self.connect_to_new_endpoint()
except Exception as e:
self.logger.error("Failed to check the current session or reconnect to the server ...")
程式碼 1:python-slack-sdk v3.40.1 原始碼摘錄,行號對應 GitHub tag v3.40.1(見文末參考資料)。
在 3.40.1 的 builtin client 下,有三件事同時成立,假死就有空間發生:
is_connected()只問「session 物件在不在、它的 socket 是不是None」,不問有沒有執行緒在讀那條 socket。- SDK 自己的 stale 判斷(
ping_interval預設 5 秒,超過 4 倍沒 pong 就斷線重連)只在last_ping_pong_time有值時才做。這個值在新連線建立時是None,要等讀取執行緒真的收到 pong 才寫入。新連線若從沒收到 pong,就永遠不會被判 stale。 - monitor 執行緒重連失敗(例如
apps.connections.open回invalid_auth)只寫一行 error log,程序照常活著,launchd 的KeepAlive沒有理由出手。
這是 3.40.1 builtin client 的行為,不代表每個版本、每種 client(aiohttp、websockets、websocket-client 實作)都一樣,也不是「回了 invalid_auth 就一定假死」。這次 invalid_auth 是 Slack 端暫時性的錯誤,下一輪重連就拿到了新 URL,問題出在之後沒有人在讀。
兩把 token,各測各的
Socket Mode 的連線由 app-level token(xapp 開頭)透過 apps.connections.open 取得 WebSocket URL;收發訊息、呼叫 Web API 用的是 bot token(xoxb 開頭)。web.auth_test() 測的是 bot token,它通過不代表 app token 能開連線,它失敗也不代表 Socket Mode 斷了。要知道 app token 有沒有被拒,最直接的位置是 SDK 每次重連都會走的 issue_new_wss_url():把它包一層,看 apps.connections.open 回什麼。不另外定期打 apps.connections.open,因為每打一次就會發一個新的連線 URL。
修法:看讀取端有沒有在動,判死就硬退出
- pong 年齡:讀
current_session.last_ping_pong_time(只有讀取執行緒收到 pong 才會更新)。這個值是牆上時間,不直接拿來跟「現在」相減(系統時間一校正就會誤判),改用 monotonic 時鐘量「它多久沒變了」。從最後一次看到新 pong 起算,超過寬限 120 秒加門檻 120 秒就判為不健康;這個起點不因重連而重置,不然反覆重連會無限續命。 - SDK 執行緒存活:
current_session_runner(讀取)、message_processor(派送)、current_app_monitor(ping 與重連)任一停了就判死。 - envelope 年齡:6 小時沒有任何 envelope 當最後保險,不當主要依據。
- 授權錯誤:
apps.connections.open回invalid_auth、not_authed、account_inactive、token_revoked、token_expired、invalid_token就不等,直接走退出路徑;網路錯誤(URLError、逾時)不算授權錯誤。 - 判死就
os._exit(1),交給 launchdKeepAlive/systemdRestart=always用乾淨的程序重連。看門狗跑在子執行緒,sys.exit只會結束那條執行緒。 - 看門狗自己也要被看:每一輪檢查的例外全部接住並記 log,連續 5 次失敗才判死;主執行緒每分鐘確認看門狗執行緒還活著、心跳沒停。
"""Socket Mode liveness watchdog for python-slack-sdk 3.40.1 (builtin SocketModeClient).
Do not trust is_connected(): in 3.40.1 it only checks that a socket object exists.
Judge liveness from evidence that the reader side is actually working, and hand
restarts to an external supervisor (launchd KeepAlive / systemd Restart=always).
"""
import logging
import os
import threading
import time
from slack_sdk.errors import SlackApiError
# Errors from apps.connections.open (app-level token) that a reconnect loop cannot fix.
FATAL_AUTH = {"invalid_auth", "not_authed", "account_inactive",
"token_revoked", "token_expired", "invalid_token"}
log = logging.getLogger("liveness")
class LivenessWatchdog:
def __init__(self, client, *, check_every=30, pong_stale=120, startup_grace=120,
bad_limit=180, envelope_stale=6 * 3600, max_check_errors=5,
clock=time.monotonic, exit=os._exit):
self.client = client
self.check_every, self.pong_stale = check_every, pong_stale
self.startup_grace, self.bad_limit = startup_grace, bad_limit
self.envelope_stale, self.max_check_errors = envelope_stale, max_check_errors
self.clock, self._exit = clock, exit
self.fatal = None
self.started = clock()
self.last_envelope = None
self.last_confirmed = self.started # last time a fresh pong was seen, across reconnects
self._lp_sess = self._lp = None # last pong timestamp we observed, and on which session
self._lp_changed = self.started # when (monotonic) that value last changed
self.bad_since = None
self.check_errors = 0
self.last_tick = self.started # proof that the watchdog loop itself is alive
def install(self):
"""Hook the app-token call and the raw message stream."""
orig = self.client.issue_new_wss_url
def issue_new_wss_url(*a, **kw):
try:
return orig(*a, **kw)
except SlackApiError as e:
if e.response.get("error") in FATAL_AUTH:
self.fatal = "apps.connections.open: %s" % e.response.get("error")
raise
self.client.issue_new_wss_url = issue_new_wss_url
self.client.on_message_listeners.append(lambda _m: self._touch())
return self
def _touch(self):
self.last_envelope = self.clock()
def check(self):
"""Return (ok, reason). Pure read of SDK state; never raises on purpose."""
now, c = self.clock(), self.client
if self.fatal:
return False, self.fatal
for name in ("current_session_runner", "message_processor", "current_app_monitor"):
t = getattr(c, name, None)
if name == "current_app_monitor" and not getattr(c, "current_app_monitor_started", False):
continue
if t is not None and not t.is_alive():
return False, "SDK thread %s stopped" % name
sess = c.current_session
if sess is None or not sess.is_active():
return False, "no active session"
ref = self.last_envelope if self.last_envelope is not None else self.started
if now - ref > self.envelope_stale:
return False, "no envelope for %ds" % (now - ref)
# last_ping_pong_time is wall-clock and written only by the reader thread when a pong
# arrives. Do not subtract it from "now" (a clock step would fake freshness); measure
# on the monotonic clock how long ago the value last changed.
lp = sess.last_ping_pong_time
if lp is not None and (sess is not self._lp_sess or lp != self._lp):
self._lp_sess, self._lp, self._lp_changed = sess, lp, now
if lp is not None and now - self._lp_changed <= self.pong_stale:
self.last_confirmed = now
return True, "pong seen %ds ago" % (now - self._lp_changed)
if now - self.last_confirmed > self.startup_grace + self.pong_stale:
return False, "no fresh pong for %ds (across reconnects)" % (now - self.last_confirmed)
return True, "waiting for first pong" if lp is None else "pong getting old"
def step(self):
ok, why = self.check()
now = self.clock()
if ok:
self.bad_since = None
return ok, why
self.bad_since = self.bad_since or now
log.warning("unhealthy: %s (for %ds)", why, now - self.bad_since)
if self.fatal or now - self.bad_since >= self.bad_limit:
self.die(why)
return ok, why
def tick(self):
"""One loop iteration. Any exception is logged; N in a row means the guard itself is broken."""
self.last_tick = self.clock()
try:
self.step()
self.check_errors = 0
except Exception as e: # URLError, timeout, ConnectionError, AttributeError ...
self.check_errors += 1
log.error("check failed (%d/%d): %r", self.check_errors, self.max_check_errors, e)
if self.check_errors >= self.max_check_errors:
self.die("watchdog check keeps failing: %r" % e)
def die(self, reason):
log.error("exit: %s", reason)
self._exit(1) # os._exit: sys.exit in a thread would only end the thread
def run(self, sleep=time.sleep):
while True:
sleep(self.check_every)
self.tick()
def stale(self):
"""For a second observer: has the watchdog loop stopped ticking?"""
return self.clock() - self.last_tick > 5 * self.check_every
程式碼 2:看門狗本體。只讀 SDK 狀態、掛兩個鉤子(issue_new_wss_url 與 on_message_listeners),判死時呼叫注入的 exit,方便測試替換。
def main():
from slack_sdk.socket_mode import SocketModeClient
from slack_sdk.socket_mode.response import SocketModeResponse
from slack_sdk.web import WebClient
logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(message)s")
web = WebClient(token=os.environ["SLACK_BOT_TOKEN"]) # bot token (xoxb...): Web API calls
client = SocketModeClient(app_token=os.environ["SLACK_APP_TOKEN"], # app-level token (xapp...): apps.connections.open
web_client=web)
def on_request(c, req):
c.send_socket_mode_response(SocketModeResponse(envelope_id=req.envelope_id))
# ... handle req.payload here; keep it short or hand it to a queue ...
client.socket_mode_request_listeners.append(on_request)
wd = LivenessWatchdog(client).install()
t = threading.Thread(target=wd.run, daemon=True, name="liveness")
t.start()
try:
client.connect()
except Exception as e: # invalid_auth at startup: back off, then let the supervisor retry
log.error("connect failed: %r", e)
time.sleep(30)
os._exit(1)
while True: # main thread watches the watchdog
time.sleep(60)
if not t.is_alive() or wd.stale():
log.error("exit: watchdog thread is dead or stuck")
os._exit(1)
if __name__ == "__main__":
main()
程式碼 3:接線方式。bot token 給 WebClient,app token 給 SocketModeClient;主執行緒負責看守看門狗本身。
修前/修後對照
| 項目 | 修前 | 修後 |
|---|---|---|
| 判死依據 | 每 60 秒問 is_connected(),連續 5 次 False 才退出 | pong 年齡(跨重連累計)、SDK 三條執行緒、6 小時無 envelope;實際上線版另加派送迴圈 10 分鐘沒轉、事件 handler 跑超過 15 分鐘 |
| 授權錯誤 | 沒看;SDK 記一行 log 後自己重連 | apps.connections.open 回授權錯誤就退出,退避 30 秒起、倍增到 600 秒 |
| 誰重拉 | launchd KeepAlive,但程序從不退出 | 同樣是 launchd KeepAlive,程序會真的退出 |
| 通知 | 退出時發一則 | 單次自癒不發;連續第 2 次重啟仍未恢復才發,之後每 6 次一則,恢復時補一句 |
| 誤報防護 | 無 | 新連線 120 秒寬限;不健康要持續 180 秒才判死;envelope 門檻只當保險 |
| 守衛自身失效 | 例外只包住 is_connected() 一行 | 每輪例外全接、連續 5 次才判死;主執行緒看看門狗心跳 |
表 1:修前與修後的判斷方式。「實際上線版」指事故後部署的版本,本文程式碼 2 是它的精簡版。
側效應:每一項怎麼隔離、怎麼驗
- launchd 節流:
ThrottleInterval預設 10 秒,授權錯誤若一啟動就退,會被每 10 秒拉一次。隔離:授權錯誤先退避(30 秒起倍增,上限 600 秒)再退出。驗:測試裡讓apps.connections.open回invalid_auth,確認退出前的等待 ≥30 秒。 - 正在跑的任務被中斷:退出會丟掉程序內還在跑的工作。隔離:決定重啟後先停止接新工作,排空最多 55 分鐘再退出。驗:模擬「忙碌中」,確認判死後不立即退出、期限到才退。
- 冷清 workspace 誤判:沒人說話時本來就沒有事件。隔離:主判斷用 pong,不用事件;6 小時無 envelope 只當保險。驗:pong 正常、長時間沒事件,不判死。
- API 速率限制:不定期呼叫
auth.test或apps.connections.open,只在 SDK 自己的重連路徑上看結果。驗:測試以 monkeypatch 讓真實的connect_to_new_endpoint()走過鉤子。 - 重啟期間漏事件:從判死到新連線建好之間的事件,不能假設一定會補送。隔離:handler 以 event id 去重,重要的請求在恢復後由人或排程補查。驗:重啟期間送一則訊息,記錄重啟後是否收到。
- 狀態跨重啟:「連續重啟幾次」要寫檔才算得出來。隔離:寫暫存檔後
os.replace,健康一次就歸零。驗:連續判死 5 次,計數為 5;恢復後為 0。 - 通知洗版:隔離:只在連續第 2 次、之後每 6 次發一則,恢復補一句。驗:連續 6 次判死只發 2 則。
- Bolt executor 裡的 handler 卡住:Bolt 把 listener 丟到自己的執行緒池,SDK 層看不到。隔離:用 decorator 記錄每個 handler 的開始時間,超過 15 分鐘判死。驗:讓 handler 不返回,確認判死。
- 兩條路同時要退出:啟動失敗的主執行緒和看門狗可能同時判死。隔離:退出流程加鎖,只計一次、只通知一次。驗:兩個呼叫者同時進入,狀態檔只加 1。
清單 1:第 2、5~9 項在本文精簡版程式碼裡沒有實作,列出來是因為上線版需要它們;第 1、3、4 項精簡版已涵蓋。
驗證:可重現的做法
不必真的弄壞 Slack 連線。以下測試直接用真實的 slack_sdk 3.40.1 SocketModeClient,只把 WebSocket session 與 Web API 呼叫換成程序內的替身:
def test_connected_flag_true_but_no_pong_exits(env):
"""The incident: session object exists, is_connected() is True, reader never records a pong."""
client, wd, clock = env
client.current_session = FakeSession(lp=None)
clock.t += 60
assert wd.step()[0] # still inside the startup grace
clock.t += 300 # grace (120) + pong_stale (120) exceeded
assert client.is_connected() is True # the SDK still says connected
assert not wd.step()[0] # first bad tick: start counting
clock.t += wd.bad_limit
with pytest.raises(Exited):
wd.step()
程式碼 4:重現事故狀態。is_connected() 仍為 True、從沒收到 pong,看門狗在寬限加門檻後退出。
def test_invalid_auth_from_apps_connections_open_exits_now(env, monkeypatch):
client, wd, clock = env
def refuse(**kw):
raise SlackApiError("refused", {"ok": False, "error": "invalid_auth"})
monkeypatch.setattr(client.web_client, "apps_connections_open", refuse)
with pytest.raises(SlackApiError):
client.connect_to_new_endpoint(force=True) # real SDK reconnect path
assert wd.fatal == "apps.connections.open: invalid_auth"
with pytest.raises(Exited):
wd.step() # no bad_limit wait for auth errors
程式碼 5:讓 apps.connections.open 回 invalid_auth,走真實的重連路徑,看門狗立即進入退出。
python3 -m venv .venv && .venv/bin/pip install "slack_sdk==3.40.1" pytest
.venv/bin/python -m pytest -v test_liveness_watchdog.py
# 本文寫作時的實跑結果:10 passed(沒有連 Slack,Web API 與 WebSocket session 都在程序內替換)
反向驗證:把看門狗改回「只信旗標」、拿掉授權錯誤鉤子、把例外處理縮成只接 ValueError,對應的 4 個測試會變紅;把 pong 判斷改回「牆上時間直接相減」,系統時間回撥那個測試會變紅。
到 Slack 後台撤銷 token 只能測「退出路徑」:撤銷之後原本的 token 不會恢復,重啟後新程序照樣拿到 invalid_auth,所以它證明不了修好,只證明看門狗會退出並被重拉。這次事故的 invalid_auth 是 Slack 端暫時性錯誤,不是 token 被撤銷。
外部監督者
<key>KeepAlive</key>
<true/>
<!-- 預設 ThrottleInterval 是 10 秒:兩次啟動至少隔 10 秒(man launchd.plist) -->
[Service]
Restart=always
RestartSec=5
設定 1:launchd plist 與 systemd unit。兩者都只在程序退出時才重拉,所以看門狗的工作是把「假死」變成「真的退出」。
適用範圍與限制
- 原始碼行號與行為以
slack_sdk3.40.1 builtin client 為準;其他版本或其他 client 實作請先對照原始碼。 last_ping_pong_time、current_session_runner等屬性不是公開 API,升級 SDK 後要重跑測試。- pong 正常、派送也正常,但 Slack 端就是不送事件,只剩 6 小時沒 envelope 這條保險。
- 一定要有外部監督者(launchd、systemd、Docker restart policy);程序內重連處理不了這種狀態。
參考資料
- Slack:Python Slack SDK — Socket Mode
- Slack:slack_sdk.socket_mode.builtin.client API reference
- Slack:Using Socket Mode
- Slack:apps.connections.open
- Slack:auth.test
- Slack:Tokens(app-level token 與 bot token)
- python-slack-sdk v3.40.1:socket_mode/client.py
- python-slack-sdk v3.40.1:socket_mode/builtin/client.py
- python-slack-sdk v3.40.1:socket_mode/builtin/connection.py
- Apple:Creating Launch Daemons and Agents(KeepAlive)
- systemd.service(5):Restart=
— 邱柏宇
Slack Socket Mode Went Silent but is_connected() Said True
Environment: the built-in SocketModeClient from Python slack_sdk 3.40.1, wrapped by Bolt’s SocketModeHandler (which uses that builtin client by default), running under macOS launchd with KeepAlive on. Symptom: Slack returned invalid_auth once, the SDK reconnected by itself, is_connected() kept returning True, the process never exited, and no event was handled after that. The existing watchdog only looked at is_connected(), so it never fired.
According to the incident record, the silence lasted from 00:09 to 11:50 (UTC+8), about 11 hours 41 minutes. It ended when a person noticed the bot was not answering and restarted it by hand.
Timeline
Time (UTC+8) Slack SDK monitor thread SDK reader thread old watchdog (60 s) launchd
----------- --------------- ---------------------- -------------------- ------------------- ---------
before 00:09 envelopes ─────────────────────────────▶ events received is_connected()=True idle
00:09 apps.connections.open
-> invalid_auth ─▶ error logged, process stays up
then reconnect OK ─────▶ new session object
is_connected()=True ✗ no envelope is_connected()=True no exit
handled any more -> never counts -> no restart
08:22/11:47 user @bot twice (no reply)
11:50 noticed by a person -> manual restart ──────────────────────────────────────────────▶ new process, recovered
Figure 1: incident sequence. 00:09, 11:50 and the two user mentions (08:22, 11:47) come from the incident record and chat timestamps. “Reconnected, no envelope handled” is inferred from process behaviour and post-fix measurements; see the next section for what raw logs exist.
Evidence: what is backed and what is not
- Backed by source code: how
is_connected()and the stale check work in 3.40.1, line by line below (GitHub tag v3.40.1, byte-identical to the installed files). - Backed by the incident record: the record from that day reads, translated, “At 00:09 Slack returned invalid_auth; the program kept running but received no events; [the user] mentioned [the bot] twice with no response; it was found at 11:50” (brackets mark anonymised substitutions).
- Not backed by raw logs: the reconnect-success line, the time of the last envelope, and why the new session handled nothing (the reader stuck on the old connection, or never starting to read on the new one; the two cannot be told apart yet). No log lines are reconstructed here.
- No conversation describing the outage was kept. The two mentions were ordinary work requests; only their timestamps are used, as evidence that someone was trying to reach the bot during the window.
How SDK 3.40.1 decides it is still connected
# builtin/client.py L153-154
def is_connected(self) -> bool:
return self.current_session is not None and self.current_session.is_active()
# builtin/connection.py L197-198
def is_active(self) -> bool:
return self.sock is not None
# builtin/connection.py L84 (set on connect) / L375 (written only when the reader thread gets a pong)
self.last_ping_pong_time = None
self.last_ping_pong_time = float(ping_time)
# builtin/connection.py L261, L271 (check_state: stale is judged only after a pong)
if self.last_ping_pong_time is not None:
is_stale = disconnected_seconds > self.ping_interval * 4
# client.py L46-48 (reconnect asks for a new URL with the app-level token)
def issue_new_wss_url(self) -> str:
response = self.web_client.apps_connections_open(app_token=self.app_token)
# builtin/client.py L286-291 (a failed reconnect in the monitor is only logged; the process keeps running)
self.connect_to_new_endpoint()
except Exception as e:
self.logger.error("Failed to check the current session or reconnect to the server ...")
Code 1: excerpts from python-slack-sdk v3.40.1. Line numbers match GitHub tag v3.40.1 (see References).
With the 3.40.1 builtin client, three facts together leave room for a zombie connection:
is_connected()only asks whether a session object exists and its socket is notNone. It does not ask whether any thread is reading that socket.- The SDK’s own stale check (
ping_intervaldefaults to 5 s; four intervals without a pong means stale) runs only whenlast_ping_pong_timehas a value. It isNoneon a new connection and is written only when the reader thread actually receives a pong. A new connection that never sees a pong is never judged stale. - When the monitor thread fails to reconnect (for example
apps.connections.openreturnsinvalid_auth), it logs one error line and the process carries on, so launchd’sKeepAlivehas nothing to react to.
This describes the 3.40.1 builtin client. Other versions and other client implementations (aiohttp, websockets, websocket-client) may differ, and an invalid_auth does not always lead to a zombie. In this incident the invalid_auth was transient on Slack’s side; the next reconnect got a fresh URL. The failure was that nothing read from the connection afterwards.
Two tokens, two different checks
A Socket Mode connection is opened with the app-level token (starts with xapp) via apps.connections.open, which returns the WebSocket URL. Web API calls use the bot token (starts with xoxb). web.auth_test() tests the bot token: passing it says nothing about whether the app token can open a connection, and failing it does not mean Socket Mode is down. The most direct place to see whether the app token is rejected is issue_new_wss_url(), which the SDK calls on every reconnect. Wrap it and look at what apps.connections.open returned. Polling apps.connections.open separately is avoided, since every call issues a new connection URL.
The fix: check that the reader is working, and exit hard
- Pong age: read
current_session.last_ping_pong_time, which only the reader thread updates. That value is wall-clock time, so it is not subtracted from “now” (a clock adjustment would fake freshness); instead a monotonic clock measures how long the value has gone unchanged. Counting from the last new pong seen, more than 120 s of grace plus 120 s of staleness marks the client unhealthy. Reconnects do not reset that starting point, otherwise repeated reconnects could extend it forever. - SDK threads alive: if
current_session_runner(reader),message_processor(dispatch) orcurrent_app_monitor(ping and reconnect) has stopped, the client is dead. - Envelope age: six hours without any envelope is a last-resort backstop, not the main signal.
- Auth errors: when
apps.connections.openreturnsinvalid_auth,not_authed,account_inactive,token_revoked,token_expiredorinvalid_token, go straight to the exit path. Network errors (URLError, timeouts) are not auth errors. - Exit with
os._exit(1)and let launchdKeepAliveor systemdRestart=alwaysreconnect from a clean process. The watchdog runs in a thread, wheresys.exitwould end only that thread. - Watch the watchdog: every exception in a check round is caught and logged, and only five failures in a row count as dead. The main thread checks once a minute that the watchdog thread is alive and still ticking.
"""Socket Mode liveness watchdog for python-slack-sdk 3.40.1 (builtin SocketModeClient).
Do not trust is_connected(): in 3.40.1 it only checks that a socket object exists.
Judge liveness from evidence that the reader side is actually working, and hand
restarts to an external supervisor (launchd KeepAlive / systemd Restart=always).
"""
import logging
import os
import threading
import time
from slack_sdk.errors import SlackApiError
# Errors from apps.connections.open (app-level token) that a reconnect loop cannot fix.
FATAL_AUTH = {"invalid_auth", "not_authed", "account_inactive",
"token_revoked", "token_expired", "invalid_token"}
log = logging.getLogger("liveness")
class LivenessWatchdog:
def __init__(self, client, *, check_every=30, pong_stale=120, startup_grace=120,
bad_limit=180, envelope_stale=6 * 3600, max_check_errors=5,
clock=time.monotonic, exit=os._exit):
self.client = client
self.check_every, self.pong_stale = check_every, pong_stale
self.startup_grace, self.bad_limit = startup_grace, bad_limit
self.envelope_stale, self.max_check_errors = envelope_stale, max_check_errors
self.clock, self._exit = clock, exit
self.fatal = None
self.started = clock()
self.last_envelope = None
self.last_confirmed = self.started # last time a fresh pong was seen, across reconnects
self._lp_sess = self._lp = None # last pong timestamp we observed, and on which session
self._lp_changed = self.started # when (monotonic) that value last changed
self.bad_since = None
self.check_errors = 0
self.last_tick = self.started # proof that the watchdog loop itself is alive
def install(self):
"""Hook the app-token call and the raw message stream."""
orig = self.client.issue_new_wss_url
def issue_new_wss_url(*a, **kw):
try:
return orig(*a, **kw)
except SlackApiError as e:
if e.response.get("error") in FATAL_AUTH:
self.fatal = "apps.connections.open: %s" % e.response.get("error")
raise
self.client.issue_new_wss_url = issue_new_wss_url
self.client.on_message_listeners.append(lambda _m: self._touch())
return self
def _touch(self):
self.last_envelope = self.clock()
def check(self):
"""Return (ok, reason). Pure read of SDK state; never raises on purpose."""
now, c = self.clock(), self.client
if self.fatal:
return False, self.fatal
for name in ("current_session_runner", "message_processor", "current_app_monitor"):
t = getattr(c, name, None)
if name == "current_app_monitor" and not getattr(c, "current_app_monitor_started", False):
continue
if t is not None and not t.is_alive():
return False, "SDK thread %s stopped" % name
sess = c.current_session
if sess is None or not sess.is_active():
return False, "no active session"
ref = self.last_envelope if self.last_envelope is not None else self.started
if now - ref > self.envelope_stale:
return False, "no envelope for %ds" % (now - ref)
# last_ping_pong_time is wall-clock and written only by the reader thread when a pong
# arrives. Do not subtract it from "now" (a clock step would fake freshness); measure
# on the monotonic clock how long ago the value last changed.
lp = sess.last_ping_pong_time
if lp is not None and (sess is not self._lp_sess or lp != self._lp):
self._lp_sess, self._lp, self._lp_changed = sess, lp, now
if lp is not None and now - self._lp_changed <= self.pong_stale:
self.last_confirmed = now
return True, "pong seen %ds ago" % (now - self._lp_changed)
if now - self.last_confirmed > self.startup_grace + self.pong_stale:
return False, "no fresh pong for %ds (across reconnects)" % (now - self.last_confirmed)
return True, "waiting for first pong" if lp is None else "pong getting old"
def step(self):
ok, why = self.check()
now = self.clock()
if ok:
self.bad_since = None
return ok, why
self.bad_since = self.bad_since or now
log.warning("unhealthy: %s (for %ds)", why, now - self.bad_since)
if self.fatal or now - self.bad_since >= self.bad_limit:
self.die(why)
return ok, why
def tick(self):
"""One loop iteration. Any exception is logged; N in a row means the guard itself is broken."""
self.last_tick = self.clock()
try:
self.step()
self.check_errors = 0
except Exception as e: # URLError, timeout, ConnectionError, AttributeError ...
self.check_errors += 1
log.error("check failed (%d/%d): %r", self.check_errors, self.max_check_errors, e)
if self.check_errors >= self.max_check_errors:
self.die("watchdog check keeps failing: %r" % e)
def die(self, reason):
log.error("exit: %s", reason)
self._exit(1) # os._exit: sys.exit in a thread would only end the thread
def run(self, sleep=time.sleep):
while True:
sleep(self.check_every)
self.tick()
def stale(self):
"""For a second observer: has the watchdog loop stopped ticking?"""
return self.clock() - self.last_tick > 5 * self.check_every
Code 2: the watchdog. It only reads SDK state, installs two hooks (issue_new_wss_url and on_message_listeners) and calls an injected exit, so tests can replace it.
def main():
from slack_sdk.socket_mode import SocketModeClient
from slack_sdk.socket_mode.response import SocketModeResponse
from slack_sdk.web import WebClient
logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(message)s")
web = WebClient(token=os.environ["SLACK_BOT_TOKEN"]) # bot token (xoxb...): Web API calls
client = SocketModeClient(app_token=os.environ["SLACK_APP_TOKEN"], # app-level token (xapp...): apps.connections.open
web_client=web)
def on_request(c, req):
c.send_socket_mode_response(SocketModeResponse(envelope_id=req.envelope_id))
# ... handle req.payload here; keep it short or hand it to a queue ...
client.socket_mode_request_listeners.append(on_request)
wd = LivenessWatchdog(client).install()
t = threading.Thread(target=wd.run, daemon=True, name="liveness")
t.start()
try:
client.connect()
except Exception as e: # invalid_auth at startup: back off, then let the supervisor retry
log.error("connect failed: %r", e)
time.sleep(30)
os._exit(1)
while True: # main thread watches the watchdog
time.sleep(60)
if not t.is_alive() or wd.stale():
log.error("exit: watchdog thread is dead or stuck")
os._exit(1)
if __name__ == "__main__":
main()
Code 3: wiring. The bot token goes to WebClient, the app token to SocketModeClient; the main thread guards the watchdog itself.
Before and after
| Aspect | Before | After |
|---|---|---|
| Liveness signal | is_connected() every 60 s; exit after 5 consecutive False | Pong age (tracked across reconnects), three SDK threads, 6 h without envelopes; the production version also checks a dispatch loop idle for 10 min and a handler running over 15 min |
| Auth errors | Ignored; the SDK logs a line and reconnects | Auth errors from apps.connections.open trigger exit, with backoff from 30 s doubling up to 600 s |
| Who restarts | launchd KeepAlive, but the process never exits | launchd KeepAlive, and the process really exits |
| Alerts | One message on exit | None for a single self-heal; one after the 2nd consecutive failed restart, then every 6th, plus one on recovery |
| False-positive guard | None | 120 s grace on new connections; unhealthy for 180 s before exit; envelope age is only a backstop |
| Guard failure | Only the is_connected() call was wrapped | All exceptions caught per round, exit after 5 in a row; main thread watches the heartbeat |
Table 1: detection before and after. “Production version” is what was deployed after the incident; Code 2 is a condensed form of it.
Side effects: how each is isolated and verified
- launchd throttling:
ThrottleIntervaldefaults to 10 s, so a process that exits on an auth error at startup is respawned every 10 s. Isolation: back off before exiting on auth errors (30 s, doubling, capped at 600 s). Check: makeapps.connections.openreturninvalid_authin a test and confirm the wait before exit is at least 30 s. - Work in flight: exiting drops jobs still running in the process. Isolation: stop accepting new work once a restart is decided, drain for up to 55 min, then exit. Check: simulate “busy” and confirm the exit waits for the deadline.
- Quiet workspaces: no one talking means no events. Isolation: judge by pong, not events; six hours without envelopes is only a backstop. Check: healthy pongs and a long event-free stretch must not trigger exit.
- API rate limits: no periodic
auth.testorapps.connections.open; results are read from the SDK’s own reconnect path. Check: a monkeypatched test drives the realconnect_to_new_endpoint()through the hook. - Events missed during a restart: events between the exit and the new connection should not be assumed to be redelivered. Isolation: de-duplicate handlers by event id and re-check important requests after recovery. Check: send a message during a restart and record whether it arrives afterwards.
- State across restarts: counting consecutive restarts needs a file. Isolation: write a temp file and
os.replaceit; reset on the first healthy check. Check: five forced exits give a count of 5, recovery gives 0. - Alert floods: Isolation: alert on the 2nd consecutive failure, then every 6th, and once on recovery. Check: six forced exits produce two alerts.
- Handlers stuck inside Bolt’s executor: Bolt runs listeners on its own thread pool, invisible to the SDK layer. Isolation: a decorator records each handler’s start time; over 15 min counts as dead. Check: a handler that never returns triggers exit.
- Two exit paths at once: a failed startup in the main thread and the watchdog may both decide to exit. Isolation: a lock so the exit is counted and alerted once. Check: two concurrent callers increase the state counter by one.
List 1: items 2 and 5–9 are not in the condensed Code 2; they are listed because the production version needs them. Items 1, 3 and 4 are covered by Code 2.
Verification you can reproduce
There is no need to break a real Slack connection. The tests below use the real slack_sdk 3.40.1 SocketModeClient and replace only the WebSocket session and the Web API call in-process:
def test_connected_flag_true_but_no_pong_exits(env):
"""The incident: session object exists, is_connected() is True, reader never records a pong."""
client, wd, clock = env
client.current_session = FakeSession(lp=None)
clock.t += 60
assert wd.step()[0] # still inside the startup grace
clock.t += 300 # grace (120) + pong_stale (120) exceeded
assert client.is_connected() is True # the SDK still says connected
assert not wd.step()[0] # first bad tick: start counting
clock.t += wd.bad_limit
with pytest.raises(Exited):
wd.step()
Code 4: reproduce the incident state. is_connected() is still True and no pong ever arrives; the watchdog exits after the grace period plus the bad-state limit.
def test_invalid_auth_from_apps_connections_open_exits_now(env, monkeypatch):
client, wd, clock = env
def refuse(**kw):
raise SlackApiError("refused", {"ok": False, "error": "invalid_auth"})
monkeypatch.setattr(client.web_client, "apps_connections_open", refuse)
with pytest.raises(SlackApiError):
client.connect_to_new_endpoint(force=True) # real SDK reconnect path
assert wd.fatal == "apps.connections.open: invalid_auth"
with pytest.raises(Exited):
wd.step() # no bad_limit wait for auth errors
Code 5: make apps.connections.open return invalid_auth on the real reconnect path; the watchdog goes straight to exit.
python3 -m venv .venv && .venv/bin/pip install "slack_sdk==3.40.1" pytest
.venv/bin/python -m pytest -v test_liveness_watchdog.py
# Result when this was written: 10 passed (no Slack connection; Web API and WebSocket session are replaced in-process)
Reverse check: switching the watchdog back to trusting the flag, removing the auth hook, and narrowing the exception handler to ValueError turns the four corresponding tests red; going back to subtracting the wall-clock pong time turns the clock-step test red.
Revoking the token in the Slack admin console only tests the exit path. After a revoke the old token stays invalid, so the restarted process gets invalid_auth again; it shows the watchdog exits and is respawned, not that anything is fixed. The invalid_auth in this incident was a transient error on Slack’s side, not a revoked token.
External supervisor
<key>KeepAlive</key>
<true/>
<!-- default ThrottleInterval is 10 s: at most one spawn every 10 seconds (man launchd.plist) -->
[Service]
Restart=always
RestartSec=5
Config 1: launchd plist and systemd unit. Both restart only a process that has exited, so the watchdog’s job is to turn a zombie into a real exit.
Scope and limits
- Line numbers and behaviour refer to the
slack_sdk3.40.1 builtin client. Check the source before applying this to other versions or client implementations. last_ping_pong_time,current_session_runnerand the other attributes used are not public API; rerun the tests after every SDK upgrade.- If pongs and dispatch are healthy but Slack simply sends no events, only the six-hour envelope backstop remains.
- An external supervisor (launchd, systemd, a Docker restart policy) is required; in-process reconnection cannot handle this state.
References
- Slack: Python Slack SDK — Socket Mode
- Slack: slack_sdk.socket_mode.builtin.client API reference
- Slack: Using Socket Mode
- Slack: apps.connections.open
- Slack: auth.test
- Slack: Tokens (app-level vs bot tokens)
- python-slack-sdk v3.40.1: socket_mode/client.py
- python-slack-sdk v3.40.1: socket_mode/builtin/client.py
- python-slack-sdk v3.40.1: socket_mode/builtin/connection.py
- Apple: Creating Launch Daemons and Agents (KeepAlive)
- systemd.service(5): Restart=
— 邱柏宇
延伸閱讀
- 400 不等於壞掉,只是還沒好
- 週報第一行偶發亂碼:UTF-8 字元被 TCP chunk 切半
- 禁止符號不是磁碟壞了,是引導層丟了記憶
- root 建的 .env,ubuntu 永遠讀不到
- 觸發記錄全綠,但任務從來沒有真正開始
https://justfly.idv.tw/s/s1D91AB