コンテンツへスキップ

ストリーミングログから「今どのサイトを処理中か」を当てる難しさ — 逆走するログとマーカー方式

複数サイトのメンテナンスを順番に実行する画面で、進行状況をリアルタイムに見せたい。「今このサイトを処理中」を青枠で、「完了したサイト」を緑枠で示す ── よくある UI です。

実装の入口で選んだのは「バックエンドが流すストリーミングログを監視して、今どのサイトを処理中か推定する」方式でした。これがなかなか手強く、3 回の修正を重ねてようやく安定しました。今回はその試行錯誤を、設計判断の記録として残しておきます。

最初の設計 — 「サイトが切り替わったら前を完了マーク」

ログには各サイトの処理が [サイト名] メンテナンスを開始 のように流れてきます。最初の実装はシンプルでした。

// 初期実装(後にバグの温床と判明)
function _setRunningSiteId(siteId) {
    if (_runningSiteId && _runningSiteId !== siteId) {
        _markCompleted(_runningSiteId);  // 別サイトに切り替わった = 前は完了
    }
    _runningSiteId = siteId;
}

「ログに新しいサイト名が出てきた = 前のサイトは終わった」という推論です。直感的には正しそうに見えます。

バグ 1 — ログの「逆走」で未実行サイトが完了扱いになる

ユーザー実機検証で「2 サイト選択して実行したら、まだ実行していない 2 サイト目が緑枠(完了)になる」事故が報告されました。

原因は、ストリーミングログには複数サイトの名前が前後する形で混ざって出力されることがあった点です。

タイミング1: ログに [サイトA]      → _runningSiteId = A
タイミング2: ログに [サイトB]      → A を完了マーク + _runningSiteId = B
タイミング3: ログに [サイトA] 再出現 → B を完了マーク + _runningSiteId = A

タイミング 3 で、まだ処理が始まってすらいない B が「完了」と誤判定される。「切り替わったら前を完了」というルールが、ログの非単調な出方に対して脆かったわけです。

対策 1 — 実行順インデックスで逆走を弾く

実行ボタン押下時に「実行予定サイトの ID 配列(実行順)」を保存し、インデックスが前に戻る切り替えは無視する防御を入れました。

let _runningSiteIdOrder = [];   // 実行予定の site_id 配列(実行順)
let _runningSiteIdIndex = -1;   // 現在のインデックス

function _setRunningSiteId(siteId) {
    const newIdx = _runningSiteIdOrder.indexOf(siteId);
    if (newIdx < _runningSiteIdIndex) {
        return;  // 逆走 = 無視(例: index=1 実行中に index=0 のログ再出現)
    }
    _runningSiteIdIndex = newIdx;
    _runningSiteId = siteId;
}

あわせて、完了マークは切り替え時ではなく メンテ実行終了時に実行順配列へまとめて付与する設計に集約しました。「処理中」の推定と「完了」の確定を分離したわけです。

バグ 2 — 真の根本原因は「初期化ループの先行ログ」だった

逆走防御を入れても、別の事故が再現しました。「A が実行中なのに、B が実行中表示になる」。

ログを精査して真の根本原因が見えました。バックエンド(maintenance_agent.py)が、メンテ実処理のに、すべての対象サイトの初期化ログを先に流していたのです。

[サイトA]   SSHプロファイルから接続情報を注入
[サイトB]   SSHプロファイルから接続情報を注入
[サイトC]   SSHプロファイルから接続情報を注入
[サイトA]   メンテナンスを開始   ← ここから実際の処理
[サイトA]   バックアップ作成中
...

旧来の検出ロジックは「[...] を含む全行」から候補を拾っていたため、初期化ループの末尾サイト(最後に注入ログが出た C)を「実行中」と誤検出していました。これが「A 実行中なのに B/C が実行中表示」の正体です。逆走防御は「順序」の問題には効きましたが、「そもそも拾う行を間違えている」問題には無力でした。

対策 2 — マーカー方式(拾う行を 1 種類に絞る)

解決は拍子抜けするほどシンプルでした。「メンテナンスを開始」という、各サイトの実処理開始時に 1 回だけ出る行だけを検出対象にする。

const _START_MARKER = /メンテナンスを開始|Starting maintenance/;

function _detectRunningSiteFromLog(lines) {
    for (let i = lines.length - 1; i >= 0; i--) {
        if (!_START_MARKER.test(lines[i])) continue;  // マーカー行以外は無視
        const siteName = extractBracketName(lines[i]);
        // ... allSites と照合して _setRunningSiteId
        return;
    }
}

[サイトB] SSHプロファイル注入 のような初期化行は完全に無視され、[サイトA] メンテナンスを開始 が出た瞬間にだけ _runningSiteId が動く。「ログ全体から状態を推測する」のをやめて、「状態遷移を表す明確なマーカーを 1 つ決めて、それだけを見る」設計への転換でした。

バグ 3 — 完了マークのリセットが過剰だった

最後はもっと細かい話です。「メンテ実行開始時に完了マーク(緑枠)を全件クリア」する処理を入れていたのですが、ユーザーから「24 時間以内にメンテしたサイトは緑枠のままのはずでは?」と指摘がありました。

確かにその通りで、メンテ対象内のサイトだけリセットすべきところを、対象外(別の機会に最近メンテしたサイト)の緑枠まで消していました。リセット範囲を実行対象に限定して解決。「状態をクリアする」処理は、クリア範囲を常に意識しないと、無関係な状態を巻き込みます。

学び — ストリーミングログから状態を推定する設計の心得

3 回の修正から取り出せる原則は次の 3 つでした。

  1. ログ全体から状態を推測しない・明確なマーカーを 1 つ決める — 「ログに出てきた名前 = 処理中」のような緩い推論は、ログの非単調な出方(初期化の先行出力・名前の前後混在)に対して脆い。「この行が出たらこの状態」という 1 対 1 のマーカーを決めると、推論の曖昧さが消える
  2. 「処理中の推定」と「完了の確定」を分離する — 切り替えと同時に前を完了扱いする設計は、切り替え自体が誤検出されると完了も誤る。完了の確定は実行終了時にまとめて行うほうが、推定の揺れに巻き込まれない
  3. 状態クリアは範囲を常に意識する — 「全部リセット」は楽だが、無関係な状態まで巻き込む。クリアする対象は実行スコープに限定する

「リアルタイムに進行状況を見せたい」という素朴な要求の裏に、ストリーミングという非同期データソースから状態を推定する難しさが潜んでいました。同じように「ログを監視して UI に状態を反映する」設計を組む場面では、最初からマーカー方式で組むのが、3 回の手戻りを避ける近道だと思います。