決して届かなかった完了イベント：2つのサイレントドロップ
アイテムごとの完了イベントがストリーム全体をクローズし、クライアントはジョブの開始後にサブスクライブしました。作業自体は成功したものの、両方とも通知を取りこぼしました。
あるユーザーから、ダウンロードボタンがいつまでも完了しないとの報告がありました。スピナーは永遠に回り続けていました。当然、レンダリングが失敗したのだろうと推測し、エラーを探しました。エラーはありませんでした。ファイルはオブジェクトストレージに存在し、データベースの行はそれを指しており、同じ入力のローカルでのリプレイでバイト単位で同一のアーティファクトが生成されました。処理は3回成功していました。通知だけが失われ、しかもそれは2つの独立した方法で失われていました。
ログが実際に示していたこと
パイプラインはごく普通のものでした。クライアントがジョブを投稿し、サーバーは 202 を返してバックグラウンドでレンダリングを行い、その後 pub/sub チャネルに完了イベントを発行します。サーバーセントイベントのエンドポイントが、そのイベントをサブスクライブしているブラウザータブにファンアウトします。
私は発行タイムスタンプを SSE 接続ウィンドウと照らし合わせました。各接続はクローズ時にその継続時間をログに記録するため、開始時刻はクローズ時刻から継続時間を引いたものになります。
SSE window (server log) completion published received
13:36:04 - 13:36:33 -> 13:36:44 no subscriber
13:37:14 - 13:41:25 -> 13:41:32 no subscriber
13:45:59 - 13:49:41 -> 13:50:07 no subscriber
3回中3回とも、イベントは空のチャネルに発行されました。Redisのpub/subは、不在のサブスクライバーのためにキューイングを行わないため、メッセージは発行された瞬間に失われました。そのことは1時間以内に明らかになりました。それよりも時間がかかったのは、2つの別々のバグが同じ症状を引き起こしていると認めることでした。
同じログにある別の詳細が、失敗そのものよりも重要であることが判明しました。接続時間が著しく不均一だったのです。2.58s、28.59s、5.79s、35.2s。20秒のハートビートと30分のセッション上限を持つ長寿命のストリームが、2.58秒後にクローズするはずはありません。
ドロップ1：アイテムごとの完了がストリーム全体をクローズした
このシステムのステータスコードは整数で、下3桁がフェーズをエンコードするものでした。あるヘルパーが、ステータスが終端かどうかを判定していました：
func isDone(s Status) bool {
r := s % 1000
return r == 500 || r == 600 || r == 800
}
SSEループは、そのヘルパーを使用して、ストリーミングを停止してリターンするタイミングを決定していました。それより少し前に、「1つのトラックのレンダリングが完了した」ことを示す新しいステータスが追加され、番号は5600でした。5600 % 1000が600になることに、誰も気づきませんでした。
そのため、アイテムごとの正常な完了はすべて終端と分類され、ハンドラーはリターンしてしまいました。ストリームはクローズされました。あるテストで、この非対称性が浮き彫りになりました。
status=5600 (item done) isDone=true terminal=true stream closes
status=5910 (item failed) isDone=false terminal=false stream stays
失敗すると接続は維持され、成功すると切断されました。ユーザーが9つのアイテムをキューに入れると、最初の成功でストリームが閉じられ、ブラウザは1秒間の再接続遅延を待機し、その時間枠内に発行されたすべての完了が失われました。接続時間のばらつきがこのバグの正体であり、数週間にわたって本番環境で確認されていましたが、単なる不安定なネットワークのようにしか見えませんでした。
修正は小さく、重要なのはその後半です：
func isSSETerminal(s Status) bool {
if s == StatusItemDone {
return false
}
return (isDone(s) && s >= StatusFirstPhaseDone) ||
s == StatusError || s == StatusFailed
}
他の呼び出し元がisDoneに依存しているため、これはそのままにしました。そして、0から10000までのすべての整数をウォークスルーし、その1つの値を除いて新しい述語が古い式と一致することをアサートするテストを作成しました。判定を名前付き関数に抽出したことで、そもそもそのテストが可能になりました。元のコードは、HTTPレスポンスライター、データベース読み取り、レートリミッターも所有する230行のハンドラ内にあるインラインのブール値でした。
一般的な教訓は、1つの不適切な定数に関するものではありません。識別子に対する算術演算から制御フローを導出するということは、新しい識別子が追加されるたびに、遠く離れたどこかの振る舞いが意図せず変更されてしまう可能性があることを意味します。ステータス定義にterminal boolフィールドがあれば、この間違いを書くこと自体が不可能だったでしょう。
2つ目の欠落：作業開始後のサブスクライブ
2つ目の欠落はクライアント側にありました。順序は、ジョブをポストし、202を待ち、その後SSE接続を開いて関心を登録するというものでした。
これはレンダリングに時間がかかる場合は機能します。ジョブが高速な場合は失敗します。このバッチのあるアイテムは単一のセグメントしかなく、そのレンダリングは1.5秒で終了しました。これはブラウザがサブスクリプションを登録するよりもずっと前です。そのアイテムは毎回失敗しましたが、30や200セグメントを持つアイテムはほとんど常に機能しました。このバグはデータ依存に見えたため、長期間存続しました。誰も特別だと思わなかった1つの入力でのみ再現されたからです。
明らかな修正方法は、最初にサブスクライブすることです。私もそうしましたが、その順序だけでは不十分でした。実装中にこの問題で苦労したため、その理由を述べる価値があります。クライアントは、ペンディングセットが空になるとすぐに接続をクローズし、そのチェックはメッセージごとに実行されていました。サーバーは、接続が開いた瞬間に初期ステータスフレームを送信します。そのため、単に接続を早期に開くだけでは、接続、初期フレーム受信、ペンディングセットが空、クローズ、という結果になりました。競合状態がすぐに再発したのです。早期にサブスクライブすることと、そのサブスクリプションを維持し続けることは、2つの変更ではなく、1つの変更なのです。
なぜ安直なフォールバックが状況を悪化させたのか
完了イベントが失われる可能性があるため、本能的に回復パスを追加したくなります。私はそれを2度設計しましたが、どちらも破棄しました。
1つ目はクライアントポーリングでした。post後、応答が現れるまで数秒ごとに結果のエンドポイントをポーリングします。ポーリングタイマーとジョブIDがどこに存在しているかに気づくまでは、これは堅牢に見えます。それらはブラウザーのメモリー内に存在します。元のバグレポートには、アイテムが「数回リフレッシュしても」ダウンロードされないとありました。リフレッシュは、まさにそのフォールバックが依存する状態を破壊してしまいます。このフォールバックは、報告された1つのケースを除いて、すべてのケースをカバーしていました。
2つ目はサーバーサイドリプレイでした。各結果をジョブをキーとするハッシュに保存し、クライアントが接続したときに、そのハッシュを読み込んで見つかった結果をリプレイするというものです。これは原則としてリフレッシュを乗り越えられます。しかし実際には、修正しようとした障害よりも悪い障害を生み出しました。クライアントがpost前にsubscribeするようになったため、接続時にアイテムは常に保留中のセットにあります。以前の実行による古い結果がリプレイされ、その保留中のエントリーと照合され、まだ送信さえされていないリクエストへの応答として扱われてしまうのです。ユーザーは気付かないうちに古いアーティファクトを受け取り、それが新しいものだと信じてしまいます。無限に回転するスピナーは、ユーザーが見ることができる悪い結果です。正しく見える間違ったファイルは、それよりも悪いのです。
3つ目の問題もありました。SSEハンドラーは他のコンシューマーと共有されており、そのうちの1つが、failedで終わるステータスをすべて自身の障害として分類していました。保存されたアイテムごとの障害をリプレイすると、無関係な操作でエラーバナーが表示されることになったでしょう。
そのため、フォールバックは完全に廃止され、そもそもイベントを失わないようにすることに労力が注がれました。作業を開始する前にsubscribeし、パネルが開いている間はsubscriptionを開いたままにし、アイテムごとの完了でストリームを閉じるのをやめる、というものです。プライマリーパスよりも弱い回復パスは、冗長性ではありません。それは、同じ条件で失敗する、保守すべき2つ目のものであり、さらに新しい種類のバグを生み出します。
まだカバーされていないこと
フォールバックを削除することは、保証の範囲が狭まることを受け入れることであり、そうでないふりをするのではなく、その点を明確にすることが重要です。これはライブ配信の信頼性であり、永続的な完了ではありません。サーバーがレンダリングの途中で再起動した場合、pub/subリンクが一時的に切断された場合、またはブラウザがバックグラウンドタブでフレームを見逃すほど長くフリーズした場合、通知はやはり失われます。
フォールバックの代わりになったのは、クライアントサイドのタイムアウトです。30分後、アイテムはエラーステートに切り替わり、ユーザーは再試行できます。それは自動回復よりも劣るエクスペリエンスですが、システムが実際に保証する内容を正直に反映したものです。このすべての発端となった単一セグメントのアイテムの場合、再試行には1.5秒かかります。
同じレビューから、2つの小さな調整が生まれました。ストリームのセッションキャップはクライアントのタイムアウトを超える必要がありました。そうしないと、サーバーが先に接続を切り、イベントをドロップさせるまさにその再接続ギャップを作り出してしまいます。また、ユーザーごとにキー設定された接続リミッターは、新しいセッション長よりも短いTTLを持っていました。これは、ライブ接続が自身のカウンターから期限切れになり、制限を超える追加の接続を許可してしまうことを意味しました。どちらも当初の計画にはありませんでした。どちらも、タイムアウトの変更が他に何に影響を及ぼすかを問うことによって発見されました。
FAQ
これは完了通知のための pub/sub に反対する議論ですか？ いいえ。Pub/sub は「今すぐブラウザに伝える」ための合理的なトランスポートです。間違いは、それをストレージとして扱うことです。もしリフレッシュ後も回答が必要なら、その回答はどこか永続的な場所に存在し、アイデンティティによって取得可能でなければなりません。これは、クライアントがたまたま待っているものでキー付けされたリプレイではなく、再構築可能な ID を持つ実際のエンドポイントを意味します。
クライアントだけを修正して、サーバーの変更をスキップしないのはなぜですか？ なぜなら、2つのバグは独立しているからです。早期にサブスクライブすることは、高速なジョブを修正します。それは、最初の成功でストリームが閉じることについては何もしません。そして、それがバッチを壊す原因です。それぞれの修正だけでは、再現可能な失敗が残ります。
終端ステータスのようなバグはどのように見つけますか？ 設計と一致しない期間を探します。ストリームは30分間生存するように設定されていましたが、3秒後に閉じていました。そのギャップはログにずっと存在し、ネットワークの不安定さとして解釈されていました。長寿命の接続が閉じた理由をログに記録し、単に閉じたという事実だけを記録しないようにします。
ステータステーブルを持つジョブキューがあれば、これらすべてを回避できたでしょうか？ おそらくそうでしょう。そして、それが長期的に正しい形です。つまり、送信時に返されるジョブ ID、いつでも読み取り可能なステータス、そして結果を知る唯一の方法ではなく最適化としてのプッシュチャネルです。それは、稼働中のバグの修正よりも大きな変更であり、プレッシャーの中で中途半端に構築するのではなく、それを延期することを明確にする価値があります。