元エンジニアの再生ブログ

50代、エンジニア出身の部門長

5日間気づかなかった障害 — 「保険」のはずのWSL2 mirroredモードが、今度は自分の首を絞めた話

以前、WSL2をmirroredネットワークモードにしたら、寄合(yoriai)が突然起動しなくなったという事故を記事にした。原因は「NAT時代のポートフォワーディング設定が残ったまま、Windows側のIP Helperと衝突していた」というものだった。

mirroredモード自体は、その前に起きていた別の障害(WSL2の長時間稼働でネットワークのリレーが詰まり、ハングする)への対策として導入したものだ。つまりこの設定は、ある障害を防ぐための「保険」だった。

今回はその保険が、また別の形で牙を剥いた話。しかも今度は、誰も気づかないまま5日間続いていた。

発端: 無関係な検証作業のさなかの一言

ある日、日本語音声合成モデル「Irodori-TTS」をローカルで試すため、GEEKOM A9 Max機のWSL2(Ubuntu)上で作業をしていた。GPU(AMD Radeon 890M)がROCmに対応しておらず、CPU推論にフォールバックする過程で音声再生用のalsa-utilsをインストールした。

sudo apt install -y alsa-utils

このとき依存関係でopenssh-serverとnginxも巻き込まれてインストールされ、設定エラーが出た。一瞬「これが引き金か」と疑ったが、後の調査で単なる偶然の同時発生だと分かる。

作業の合間に、ふと本題とは無関係な一言が出た。

「1on1アシスタントが死んだね……」

これが、長い障害調査の始まりだった。

5日間、気づかれていなかったクラッシュループ

1on1アシスタントは、社内の1on1面談を録音・文字起こしし、離職兆候などを検知する自作アプリで、GEEKOM A9 Max機上でsystemdサービスとして常駐している。

systemctl status 1on1-api.service

結果はactivating (auto-restart)。再起動カウンターを見ると——

restart counter is at 84448

8万4千回。 RestartSec=5(5秒間隔)で単純計算すると約4.9日分に相当する。つまりこのクラッシュループは今日始まったものではなく、5日前からずっと続いていたことになる。誰も気づかないまま。

エラーメッセージはシンプルだった。

ERROR: [Errno 98] error while attempting to bind on address ('0.0.0.0', 8003): address already in use

ポート8003番が「使用中」。ならば何が使っているのか、というごく自然な疑問から、AIと一緒に原因を追う調査が始まった。

誰も掴んでいないのに「使用中」

普通ならss -tlnpやlsof -i :8003で犯人のプロセスがすぐ見つかるはずだった。しかし——

sudo ss -tlnp | grep 8003
# 何も出力されない

誰も掴んでいない。 それなのにbindは失敗し続ける。

同じタイミングで、全く別のサービス(nginx、ポート8002番)でも同様の「使用中なのに実体がない」症状が出ていたことから、これは1on1アシスタント固有の問題ではなく、もっと下のレイヤー、ネットワークスタック自体の異常だと見当がついた。

Windows側でポートの状態を確認すると——

netstat -ano | Select-String "TIME_WAIT" | Measure-Object

結果は16,000件超。WindowsのTCPエフェメラルポート範囲(約16,383個)が、ほぼ完全に埋め尽くされていた。

mirroredネットワークモードという伏兵

冒頭で触れた通り、このマシンは.wslconfigでnetworkingMode=mirroredを使っていた。皮肉なことに、この設定が今回の障害の温床になっていた。WSL2内でuvicornが起動を試みるたびに、mirroredモードの仕組みを介して大量のTCP接続が生成・破棄され、結果としてWindows側のポートプールを食い潰していたと考えられる。

犯人探しの過程では、こんな迷走もあった。接続元プロセスを特定するとsvchost.exe(IP Helperサービス)が出てくる。「IP Helperが悪さをしているのか」とAIが一瞬色めき立ったが、これは単にmirroredモードの通信を中継している実体に過ぎず、真犯人ではなかった。前回の記事でもIP Helperが登場したが、今回はまた別の役回りだった。中継役を疑って時間を溶かすのは、この手の調査でありがちな罠だ。

直しても直しても再発する

TIME_WAITを解消し、いったんは1on1-apiが正常起動するところまで持っていけた。ところが数分後、また同じエラーが再発した。

ここでAIが提案したのは、ある種の「答え合わせ」だった。startとstopを1回ずつ行い、その一瞬にpsでプロセス一覧をポーリングし続けるという方法だ。

sudo systemctl start 1on1-api.service &
for i in {1..20}; do sudo ss -tlnp 2>/dev/null | grep 8003; ps -ef | grep uvicor[n]; sleep 0.3; done

結果、2つのuvicornプロセスが同時に存在する瞬間が実際に捕まった。前のプロセスの後始末が終わる前に、次のプロセスが起動していた。

「起動前に確実にポートを掃除してから立ち上げる」という応急処置(ExecStartPreでのポートクリア)も試したが、効果はなかった。WSL2内には本当に何もいないのに、bindが失敗し続ける——ここでAIは、mirroredモード自体を一時的に無効化するしかない、と判断した。

.wslconfigのnetworkingMode=mirroredをコメントアウトし、WSL2を再起動。1on1-apiは無事、安定して起動した。

直したはずが、まだ死んでいた

AIが「復旧しました」と報告したところ、返ってきたのは一言。

「アプリは死んだままです」

確認すると、外部URL(さくらVPS経由で公開しているエンドポイント)へのアクセスが502 Bad Gatewayを返していた。ローカルでは200 OKなのに、外部からは繋がらない。

ここで初めて気づいた。WSL2を再起動すると、WSL2の内部IPアドレスが変わる。 そして外部公開の経路は、Windows側のnetsh interface portproxyで「特定のIPアドレス」宛にトラフィックを転送する仕組みだった。

netsh interface portproxy show all

案の定、8003番のフォワーディング先は、mirroredモード時代の古い設定(Windows機自身のLAN IP)を指したままだった。

「仕込んでいたはず」を巡る食い違い

ここで、もう一つの教訓的なやり取りがあった。AIが「IPが変わるたびに手作業でポートフォワーディングを直す必要がある」と説明したところ、返ってきたのはこうだった。

「これも自動起動しるようにしていたはずだけど」

AI側の記憶と、実際に組まれていた仕組みが食い違っていた。過去の会話ログを検索し直すと、たしかに自動化の仕組みは存在していた。ログオン時にタスクスケジューラで自動実行される、ポートフォワーディング復旧用のPowerShellスクリプトだ。

このスクリプトは非常によく作り込まれていて、コメントには過去の障害の記録まで残されていた。

# WHY THIS FILE EXISTS
#   netsh portproxy rules are stored in the registry under
#     HKLM\SYSTEM\CurrentControlSet\Services\PortProxy\v4tov4\tcp
#   and some Windows updates wipe them. That happened once before:
#   the 8002 rule came back because the old startup script re-added
#   it every logon, but 8003 had only ever been set by hand, so the
#   1on1 site stayed down until it was re-registered manually.

「Windows Updateがポートフォワーディングのレジストリを消すことがある」というのは、既知の過去の障害パターンだった。 そしてこのスクリプトは、Windowsへのログオン時にタスクスケジューラで自動実行される設計になっていた。

しかし今回行った操作はwsl --shutdownによるWSL2だけの再起動であり、Windowsへのログオンは発生していない。自動修復の仕組みが発火する条件を満たしていなかったのだ。

手動でスクリプトを実行すると、WSLの内部IPを取得してポートフォワーディングを張り直し、ヘルスチェックも200を返した。ブラウザからのアクセスも復旧した。

引き金は5日前のWindows Update

一連の調査を終えて、最後に残った疑問はこれだった。そもそも、5日前に何があったのか。

Windows Updateの履歴を確認すると、気づいた日からちょうど5日前の未明に、複数の更新プログラムが自動適用され、Windowsが再起動していたことが分かった。再起動カウンタからの試算(84448回×5秒≒4.9日)と、この日数はぴったり一致した。

つまり、こういう連鎖だったと推測される。

  1. 5日前の未明、Windows Updateが自動適用され、Windowsが再起動
  2. WSL2も連動して再起動し、内部IPが変化
  3. 本来ならログオン時に復旧スクリプトが自動でポートフォワーディングを直すはずが、何らかの理由でこのタイミングでは機能しなかった(あるいは8003番だけ取りこぼした)
  4. 1on1-apiはポートbindに失敗し、5秒おきのクラッシュループに突入
  5. 外部からは502、社内の誰も気づかないまま5日が経過
  6. 無関係なTTS検証作業のさなか、たまたま気づいた

振り返って

この障害は、単一の原因ではなく、複数の「保険」がすべて同時にすり抜けた結果だった。

  • mirroredネットワークモードは、別の障害(WSL2のハング)への対策として入れたものだったが、今回は逆に仇になった
  • ポートフォワーディングの自動修復スクリプトは、過去の同種障害(Windows Updateによるレジストリ消失)を踏まえて丁寧に作られていたが、「ログオン時」という発火条件の外側(WSL2単体の再起動)では機能しなかった
  • 監視の仕組みがなかったため、5日間、誰も気づけなかった

一つひとつの対策は理にかなっていた。それでも、想定していなかった組み合わせ(Windows Update起因の再起動 → 自動修復スクリプトの発火条件から外れる操作での再起動)が、穴として残っていた。

インフラの「自動復旧の仕組み」は、それ自体が正しく動いているかを検証する仕組みとセットでなければ、本当の意味での安心にはならない——というのが、今回の一番の学びだった。

今後の対策候補

  • 1on1アシスタントに外形監視(ヘルスチェック+アラート通知)を追加し、次回は5日ではなく数分で気づけるようにする
  • ポートフォワーディング復旧スクリプトを、ログオン時だけでなく、WSL2起動時にも発火するよう見直す
  • クラッシュループの再起動回数に上限を設け(StartLimitBurst)、異常な連続失敗時はサービスを止めて通知する設計に変える

前回の記事の教訓「journalに何も残らない障害がいちばん高くつく」は、今回も繰り返された。プロセスは動こうとしているのに繋がらない、正常終了ではないのに痕跡が薄い——この手の障害は、アプリ側のログをいくら見ても答えが出ない。レイヤをひとつ下げて見る判断を、もっと早くできるようにしたい。