redis-py 8.0でBRPOPが沈黙する ― 新Worker追加で炙り出された隠れ障害2件と「自己修復が障害を隠す」話

家庭内の分散AI推論基盤「Coordinator」に新しいWorker（MacBook Air M1）を追加しようとしたら、その準備作業の途中で既存Workerの隠れ障害が2件見つかりました。どちらも構築初日から発生していたのに、3日間誰も気づかなかった障害です。

この記事で解決すること

  • redis-py 8.0系で BRPOP が「Timeout reading from socket」を出し続ける問題の切り分けと対処
  • PostgreSQLの pg_hba.conf 追加漏れが、自己修復機構（Reaper）によって隠蔽されるメカニズム
  • 「ネットワーク → プロトコル → ライブラリ」の3段切り分けで原因を特定する手順
  • 新Worker追加時に必ず確認すべきチェックリスト

背景: 動いているように見えていたWorker

このシリーズで構築している基盤は、Redisキューでタスクを分散し、各WorkerがOllamaで推論してPostgreSQLに結果を書き込む構成です。6月7日にESXi上のVM（esxi / 192.168.0.41）をCPU Workerとして追加しました。Heartbeatは正常、Redisへの登録も正常、Coordinatorのダッシュボードからは健康そのものに見えていました。

ところが3日後、別件でこのWorkerのログを覗いて凍りつきます。

Jun 10 06:25:34 ai-worker python[3013]: ERROR Unexpected: Timeout reading from socket
Jun 10 06:26:34 ai-worker python[3013]: ERROR Unexpected: Timeout reading from socket
Jun 10 06:27:38 ai-worker python[3013]: ERROR Unexpected: Timeout reading from socket
（以下、約60秒間隔で延々と…）

カウントしてみると3450回。エラーの初出は構築当日の起動2分後でした。つまりこのWorkerは、生まれてから一度もまともに仕事をしていなかった可能性があります。

障害1: redis-py 8.0.0 × Redis Server 8.0.5 でBRPOPが沈黙する

理屈に合わない症状

Workerのメインループは BRPOP（timeout=5秒） でキューを監視しています。空なら5秒でnilが返り、ループが回り続けるだけのはずです。コードを確認すると、Redis接続は socket_timeout を設定していません。

def get_redis(host: str, port: int):
    return redis.Redis(host=host, port=port, decode_responses=True)

socket_timeoutがNone（無限待ち）なら、そもそも「Timeout reading from socket」は原理的に出ないはず。何かが理屈に合いません。

再現テストで実態を掴む

サービスと同条件のBRPOPループを素のスクリプトで5分間回してみました。

import redis, time, traceback
r = redis.Redis(host='192.168.0.40', port=6379, decode_responses=True)
t_start = time.time()
n_ok = n_err = 0
while time.time() - t_start < 300:
    t0 = time.time()
    try:
        r.brpop(["test:esxi:a", "test:esxi:b"], timeout=5)
        n_ok += 1
    except Exception as e:
        n_err += 1
        print(f"[{time.time()-t_start:.0f}s] ERR {type(e).__name__}: {e} (after {time.time()-t0:.1f}s)")
        traceback.print_exc()
        time.sleep(1)
print(f"done: ok={n_ok} err={n_err}")

結果は衝撃的でした。

[60s]  ERR TimeoutError: Timeout reading from socket (after 59.7s)
[173s] ERR TimeoutError: Timeout reading from socket (after 59.1s)
[247s] ERR TimeoutError: Timeout reading from socket (after 58.4s)
done: ok=5 err=3

BRPOP(timeout=5) が5秒で返らず、約59秒間ハングしてからソケットタイムアウトで死んでいます。サーバーが5秒後に返すはずのnilが、クライアントに届いていません。再接続直後は数回成功し、その後また沈黙するという不気味なパターンです。

3段切り分け: ネットワーク → プロトコル → ライブラリ

容疑者を1つずつ消していきます。

第1段: ネットワークは無実か？ Redisサーバーが動いているマシン（ai-core）自身に同じ環境（redis-py 8.0.0）を作り、同じテストを実行しました。結果は ok=3 err=4 ── ローカル接続でも再現。ESXiの仮想NICもLAN経路も無実です。

第2段: RESP3プロトコルは無実か？ エラーのトレースバックが resp3.py を通っていたので、redis-py 8.0がデフォルトで使うRESP3プロトコルを疑い、protocol=2 を指定して再テスト。結果は ok=2 err=4 ── RESP2でも再現。プロトコルも無実です。

第3段: ライブラリのバージョンか？ 正常に動いている既存Worker（ai-core同居）のvenvを確認すると、redis-pyは7.4.0。問題のWorkerは8.0.0でした。同じRedisサーバー（8.0.5）に対して、7.4.0は無エラー、8.0.0はどこから接続しても再現。ライブラリ起因で確定です。

実験 redis-py 接続元 結果 消えた容疑者
esxiから素ループ 8.0.0 LAN越し 再現 ―
ai-coreローカル 8.0.0 ローカル 再現 ネットワーク
protocol=2指定 8.0.0 LAN越し 再現 RESP3
既存Worker実績 7.4.0 ローカル エラー0 → ライブラリ確定

対処: バージョンピン留め + コードの堅牢化

根本原因のさらに深い層（redis-py 8.0内部の何が変わったのか）の追跡は費用対効果が合わないので、「7.4.0は同一サーバーで実績あり、8.0.0は実証的に壊れている」を根拠にエンジニアリング判断をしました。

対処1: バージョンピン留め

pip install "redis==7.4.0"

対処2: Worker共通コード（worker_base.py）の堅牢化（v6.2）。将来どのマシンに8.0系が入っても静かに壊れないようにする保険です。

# 変更1: 接続確立にのみタイムアウトを設定
def get_redis(host: str, port: int):
    # socket_timeout は BRPOP のブロック待ちと干渉して
    # TimeoutError を誘発するため、意図的に設定しない（None=無制限）
    return redis.Redis(
        host=host, port=port, decode_responses=True,
        socket_connect_timeout=10,
        socket_keepalive=True,
    )

# 変更2: メインループで TimeoutError も「想定内の接続障害」として捕捉
        except (redis.exceptions.ConnectionError,
                redis.exceptions.TimeoutError) as e:
            log.error(f"Redis lost/timeout: {e}. Retry in 5s...")
            time.sleep(5)

変更2が地味に重要です。元のコードは ConnectionError しか個別捕捉しておらず、TimeoutError は汎用の except Exception に落ちて「Unexpected」としてログを汚すだけでした。redis-pyの TimeoutError は ConnectionError の派生ではないため、明示的に並べる必要があります。

適用後、10分間でエラー0件。3日間続いた沈黙が終わりました。

障害2: pg_hba.confの許可漏れを、Reaperの自己修復が隠していた

1件目の調査中、新Worker用にPostgreSQLの pg_hba.conf を確認していて気づきました。esxi（192.168.0.41）を許可する行が存在しない。

133:host    coordinator     coordinator     192.168.0.4/32          md5
134:host    coordinator     coordinator     192.168.0.196/32        md5
135:host    coordinator     coordinator     192.168.0.42/32         md5
（.41 がどこにもない）

このWorkerは推論結果をPostgreSQLに直接書き込む設計です。つまり仮にRedisからタスクを取れていたとしても、書き込みの時点で認証エラーになっていたはず。それなのに、なぜ誰も気づかなかったのか？

自己修復が障害を見えなくするメカニズム

答えは、この基盤に組み込んだ自己修復機構（Reaper）が障害を隠蔽していたからです。流れはこうなります。

  1. Workerがキューからタスクを取得
  2. 処理開始のDB書き込み（CASクレーム）が pg_hba エラーで失敗 → タスクはDB上 pending のまま
  3. Reaperの ghost_pending トリガーが「放置されたpendingタスク」を検出
  4. 別の健康なWorkerへ自動再投入 → そちらで正常完了

利用者から見ると、回答は（少し遅れて）ちゃんと返ってくる。Heartbeatや登録はHTTP経由なので監視上も正常。「動いているように見える」の正体は、隣のWorkerが尻拭いをし続けている状態でした。

皮肉なことに、この後MacBook Air（192.168.0.43）を追加した際の初回テストで、全く同じ現象をリアルタイムで観測できました。MacBook指名で投入したタスクが、pg_hba漏れ → Reaper再投入を経て worker=ai-core として完了したのです。以前の記事で実装した ghost_pending トリガーが設計通り機能している実証にはなりましたが、自己修復は「障害の影響を消す」のであって「障害を直す」のではない、という設計の本質を突きつけられた形です。

対処自体は1行追加して reload するだけです。

host    coordinator     coordinator     192.168.0.41/32         md5
# 追記後
sudo systemctl reload postgresql

教訓: 新Worker追加チェックリスト

これでWorker追加のたびにOSごとの地雷を踏んできたことになります（WSL2のportproxy、Linuxのpg_hba、そして次回記事のmacOS編へ続く）。今回の経験から、引継ぎ資料に「新Worker追加時の落とし穴チェックリスト」を新設しました。要点は3つです。

  • pg_hba.conf の /32 追加と reload を必ずセットで。HeartbeatとRedisが正常でも、DB書き込みは別経路。
  • redis-py はバージョンをピン留めする（当面 redis==7.4.0）。素の pip install redis は地雷を踏む。
  • 追加直後に必ず指名タスクを1本流し、結果テーブルの worker カラムが新Worker名で done になることを確認する。自己修復機構がある環境では、これをしない限り「動いている」を信用してはいけない。

まとめ

新しいWorkerを1台追加しようとしただけで、既存環境の隠れ障害が2件発掘されました。どちらの障害にも共通するのは「システムが正常に見えることと、正常であることは別物」だということです。特に自己修復機構を入れた分散システムでは、修復が効いている限り障害は表に出てきません。修復ログの監視（Reaperが何をどれだけ再投入したかのメトリクス化）が次の宿題になりそうです。

次回は、この騒動の本来の目的だったMacBook Air M1のWorker参加について、macOS固有の落とし穴（Homebrew版Ollamaのバグ、ローカルネットワーク許可、launchd化）を全部踏んだ記録をまとめます。