第1話 ログに残らない副作用
その夜、俺は二つのバグを見た。
一つ目は、ちゃんとログに残るバグだった。
午前一時四十七分。配送管理サービスの深夜バッチが止まった、という連絡が来た。止まったと言っても、画面が派手に赤くなる種類ではない。倉庫から店舗へ送る荷物の数が、百個に一個くらいの割合で合わなくなる。
現場の言い方に直すと、朝の配送表から荷物が消える。
本当に消えたわけではない。倉庫には箱がある。だが、配送表に載らない箱は、店に届かない箱と同じだ。朝までに直らなければ、倉庫の人間が紙と電話で配送表を作り直すことになる。
運用担当は在庫データの破損を疑っていた。
開発担当はデータベースのロックを疑っていた。
経営側は、明日の朝までに直らなければ配送を手で組む、と言っていた。
どれも分かる。だが、どれも遅い。
俺は相馬透。名義は soma。フリーランスのプログラマだ。
難しい単発案件を高く受ける。難解なバグの修正、アルゴリズムの実装、脆弱性の解析。依頼元が社内で三日潰してから、最後に回ってくる種類のやつを食っている。
「MICA、差分と失敗ログ」
端末の横に置いた小型スピーカーから、乾いた声が返った。
「直近の変更は三件です。配送先集約処理、再送処理、管理画面の表示文言。失敗ログは百二十七件。共通点は再送処理の二回目」
MICA。
正式には Modular Interactive Coding Agent。俺が自分の作業用に組んだ、コードとログと差分を食わせるためのエージェントだ。世の中に転がっている汎用の会話 AI をそのまま使うより、俺の癖に合わせて権限と道具を絞ったほうが速い。
調査対象のリポジトリ、実行ログ、テスト結果、録画、スクリーンショット。食わせたものは黙って整理する。曖昧な慰めは返さない。俺が夜中に悪態をつくと、必要最低限の嫌味だけ返してくる。
「再送処理の二回目だけ？」
「はい。失敗した配送データだけをもう一度流したとき、同じ荷物番号に別店舗の行が上書きされています」
「荷物番号の生成は」
「時刻、店舗コード、連番です」
MICA が並べた失敗ログを、時刻順に見る。
一見ばらばらに見えた荷物番号の末尾が、店舗が変わるたびに同じ形で繰り返していた。
一、二、三。
店舗が変わって、また一、二、三。
「MICA、これ、番号が進んでない。店が変わるたびに巻き戻ってる」
「連番の初期化条件」
「日付変更時です」
「違う。店舗コードが切り替わったときも初期化してる」
「該当箇所を表示します」
画面に出たコードを見て、俺は笑った。
深夜バッチは店舗ごとに荷物をまとめる。失敗した分だけを再送するとき、開発者は処理を軽くするため、対象店舗だけを流すように変えた。
その変更で、連番の前提が壊れた。
たとえば、A店の一個目の荷物と、B店の一個目の荷物が、同じ時刻に処理される。
番号の作り方が雑だと、どちらにも同じ整理番号が付く。
システムは「同じ番号なら同じ荷物だ」と思い込み、後から来たB店の情報で、A店の情報を塗りつぶす。
消えたように見える荷物は、本当に消えたのではない。
別の荷物として、上から書き換えられていた。
データベースは壊れていない。
ロックも悪くない。
壊れていたのは、「同じ番号は二度出ないはず」という人間の思い込みだった。
「修正案」
「荷物番号生成に再送単位の識別子を追加。既存データとの互換を考えるなら、上書き前に一意制約を入れて失敗させる案もあります」
「つまり、同じ整理番号を二度配らないようにする。万が一配ったら、黙って塗りつぶす前に失敗として止める」
「はい」
「両方。先に一意制約で止血。同じ番号を二度登録できない安全装置を入れる。番号の作り方は恒久対応。テストは再送二店舗同時」
「作成します」
三分後、失敗するテストができた。
五分後、修正で通った。
十分後、依頼元へ暫定報告を送った。
原因は荷物番号生成の衝突。同じ番号が二つ出て、後から来た荷物が先の荷物を塗りつぶしていた。影響範囲は、失敗した配送データだけをもう一度流す処理に限定。消えたように見えた荷物は、元ログから復元できる。
手動配送へ切り替える必要はない。
朝までに本番反映するなら、同じ番号を二度登録できない安全装置で上書きを止め、番号の作り方そのものは別リリースで直す。
難しそうに見えるバグほど、実際は小さな前提の破れでできている。
見つければ終わる。
見つけられなければ、会議と怒号と徹夜が増える。
「十五分二十二秒」
MICA が言った。
「何が」
「初回ログ投入から暫定報告までの時間です。請求単価を上げてもよい案件です」
「お前が言うと生々しいな」
「私は利益率を評価しています」
「俺は寝る時間を評価したい」
「新規依頼が一件あります」
「寝る時間は」
「削除されました」
バグは嘘をつかない。
嘘をつくのは、ログを読む人間か、ログを書いた人間か、ログに出ないところで起きた何かだ。
一つ目のバグは、ログに残っていた。上書きされた行、衝突した番号、再送処理の時刻。追えば、ちゃんと尻尾を出した。
二つ目は違った。
午前二時十三分。机の右端に置いたコンビニのレシートが、エアコンの風もないのに、ほんの一ミリだけめくれた。
俺は指を止めた。
画面には、NEXTPULSE の卓上センサー端末管理アプリが開いている。小さな事務所や店舗に置く温湿度センサーをまとめて見るための、地味だが金になる種類のアプリだ。
依頼文は短かった。
差出人は三枝莉央。NEXTPULSE の開発担当。
「特定のデバッグ操作をすると、端末の状態表示が一瞬だけ別の値になる。朝十時までに暫定原因がほしい」
「MICA、状況をもう一度」
「候補は四つです。UI の描画遅延、表示キャッシュ、センサー値の到着順、端末時刻とアプリ側時刻の同期ずれ」
「四つは多い。二つまで落として」
「表示キャッシュと同期ずれを残します。描画遅延は録画フレームと合いません。センサー値の順序違いはイベントログと矛盾します」
「よし」
俺は管理アプリのデバッグパネルを開き、三枝さんが送ってきた手順をなぞった。
端末一覧。
対象センサー。
状態スナップショット。
再読込。
内部状態の確認。
その最後で、画面右下の状態ラベルが一瞬だけ「接続中」から「待機中」に変わり、すぐ戻る。
人間が普通に使っていれば見逃す。録画を一フレームずつ送れば分かる。客先の担当者は気味悪がるだろうが、原因のほとんどは退屈なものだ。
古い値を一瞬表示している。
非同期処理の順番が逆転している。
画面の状態だけが先に切り替わり、裏のデータが追いついていない。
だから俺は、まず退屈な可能性から潰した。
アプリログには、状態ラベルを更新した時刻が残っている。端末ログには、センサー側の応答時刻が残っている。OS ログには、プロセスが固まった形跡はない。
並べると妙だった。
時刻が、きれいすぎる。
本来なら数ミリ秒くらいの揺れは出る。ネットワークを経由すればなおさらだ。なのに問題の瞬間だけ、アプリ側の更新、端末側の応答、画面の再描画が、まるで誰かが定規で引いたみたいに整列していた。
「MICA、ここ」
「表示しました」
俺は三つのログを横に並べた。問題の時刻だけを残し、前後の正常な実行と比較する。
「偶然にしてはそろいすぎてる」
「同期ずれ候補を否定する発言ですか」
「逆だ。同期がずれたからじゃない。ずれてないことが変だ」
「言語化が悪いです」
「分かってるからログを見せてる」
MICA は一秒黙った。
「通常候補にない違和感として記録します。ただし、根拠は弱いです」
「根拠はこれから作る」
俺は手順をもう一度実行した。
画面右下の状態ラベルが、ふっと揺れた。
同時に、机の右端でレシートが動いた。
今度は見間違いじゃなかった。
端が持ち上がる。ほんの少しだけ、紙が呼吸したみたいに浮いて、戻る。
俺は手をキーボードから離した。椅子も動かしていない。息も止めていた。エアコンは切ってある。窓は閉まっている。
「MICA」
「はい」
「画面の外で何か動いた」
「録画はありますか」
「肉眼では見た」
「肉眼観測は信頼度を下げます」
「俺の目を低信頼デバイス扱いするな」
「実績に基づく分類です」
腹は立たない。むしろ正しい。
人間は都合よく見る。疲れていればなおさらだ。深夜二時のフリーランスの目撃証言なんて、バグ報告としては最底辺に近い。
だから俺は、まず自分を疑った。
机の上を片づける。レシートの四隅のうち、左下だけをクリップで押さえる。右上は自由にする。スマホを固定し、机、キーボード、画面端、レシートが同時に入る角度で録画を始めた。
「再現条件を固定する」
「記録します」
「条件。室温二十四度。エアコン停止。窓閉鎖。手順は三枝さんの報告通り。入力はマウスクリックのみ。キーボードには触れない」
「追加条件。操作している人間が眠い」
「黙れ」
「記録しません」
俺は笑いそうになったが、口を閉じた。
笑って息で紙が動いたら、原因を一つ増やすだけだ。
マウスカーソルをデバッグパネルの再読込ボタンへ合わせる。
クリック。
画面右下のラベルが「待機中」に落ち、すぐ戻った。
レシートの右上が、また浮いた。
録画の中で、紙の端は確かに動いていた。大げさではない。紙一枚分にも満たない。だが、表示ズレと同じタイミングで、同じ方向へ、二回。
「MICA、動画を切り出す。フレーム番号で比較」
「受領しました。対象範囲を解析します」
待っている間に、俺はもう一度ログを見た。
アプリログには何もない。
端末ログにもない。
OS ログにもない。
管理アプリがラベルを更新した。センサーが応答した。画面が再描画された。そこまでは記録されている。
だが、机の上の紙が動いたことを、どのログも知らない。
当然だ。アプリは現実のレシートを監視していない。OS は机の上の紙の位置なんて管理していない。センサー端末は温度と湿度を見るだけで、俺の部屋のレシートには興味がない。
だからこそ、変だった。
普通、関係のないものは関係がない。
ところが今、関係のないはずの二つが、同じタイミングで揺れた。
「解析結果」
MICA の声が戻った。
「フレーム二百四十一で状態ラベルの表示が変化。フレーム二百四十二でレシート右上端が上方向へ変位。風、接触、カメラ揺れの候補は低いです」
「低い、ね」
「ゼロではありません。カメラ固定具の微振動、机面の反射、紙の戻り癖、録画圧縮の影響を候補に残します」
「現実で紙が動いた候補は」
「物理現象としては存在します。アプリ操作との因果は未確認です」
「歯切れが悪い」
「現実世界への副作用を、管理アプリの実行結果として扱う根拠が不足しています」
正しい。
根拠が足りない。だから面白い。
俺はエディタに新しいメモを作り、仮説を三つに分けた。
一つ目。単なる表示バグ。レシートは偶然。
二つ目。操作の振動や空気の動きが、思ったより紙に効いている。
三つ目。アプリの状態遷移に、現実側へ漏れる副作用がある。
三つ目を書いた瞬間、普通なら自分で消す。
そんな仕様はない。そんな API もない。プログラムが現実の紙を直接動かすなんて、科学ではなく怪談の棚に置くべきだ。
ただ、俺は怪談が嫌いだ。
説明できないものを説明できないまま飾っておくのは、敗北に似ている。
「MICA、三番目を残す」
「推奨しません」
「理由」
「既存の計算機環境に、現実物体へ直接作用する権限はありません」
「その既存環境の外側で起きてるから、ログにない」
「循環しています」
「仮説なんて最初はだいたい循環してる。再現で切る」
俺はレシートを新しいものに替えた。クリップの位置を変える。机の別の場所へ置く。スマホの角度も変える。ついでに、画面の状態ラベルが見えるよう、録画に小さな鏡を入れた。
クリック。
ラベルが揺れる。
紙の端が浮く。
クリック。
ラベルが揺れる。
紙の端が浮く。
三回目だけ、何も起きなかった。
「そこだ」
俺は声に出していた。
「何がですか」
「毎回じゃない。だけど偶然でもない。再現率がある」
「再現率は現在六十六・七パーセント。試行回数が不足しています」
「足りないのは分母じゃない。条件だ」
俺は三枝さんの依頼文をもう一度開いた。
特定のデバッグ操作。
状態表示が一瞬だけずれる。
朝十時までに暫定原因。
彼女が求めているのは、顧客へ説明できる原因だ。表示キャッシュでした、次のリリースで直します。そう言えれば業務は回る。
だが、机の上のレシートは顧客向け報告書に書けない。
「MICA、暫定報告の通常線を作っておいて。表示キャッシュと同期タイミング。断定はしない」
「作成します。現実側の観測は含めますか」
「含めない」
「了解しました」
「別ファイルで検証ログを作る。名前は side_effect_lab」
「命名が不穏です」
「現象のほうが不穏だ」
俺は録画ファイルの時刻と、アプリログの時刻を合わせた。
画面の表示ズレ。
一フレーム後のレシートの変位。
記録の外にある変化。
バグ修正で大事なのは、怒っている顧客でも、派手な例外でもない。関係ないはずの二つが同じ顔をして並んだ瞬間だ。
そこに因果がある。
あるいは、因果に見える罠がある。
どちらでもいい。切れば分かる。
「ログ上、物理変化は存在しません」
MICA が淡々と言った。
俺は机の右端を見た。
押さえたはずのレシートの角が、さっきより少しだけ、俺のほうへ寄っていた。
存在しないはずのものが、現実では動いている。
俺はキーボードに指を戻した。
「じゃあ、現実のほうをデバッグする」
■ 技術メモ
【ログ】
ログは、プログラムが「何をしたか」を後から追うための記録です。
ただし、ログは万能ではありません。記録するように作られていない出来事は残りません。ログにないから起きていない、とは限らないのがバグ調査の難しいところです。
【一意制約】
一意制約は、同じ値を二つ以上登録できないようにするデータベースのルールです。
作中の配送管理サービスでは、荷物番号が重なったことで上書きが起きていました。こうした場合、一意制約を入れると、間違った上書きを止めて異常を表に出せます。
【再送処理】
通信失敗や一時的なエラーが起きたとき、同じ処理をもう一度行うことがあります。
再送処理は便利ですが、「同じ処理をもう一度行っても結果が壊れないか」を考えて設計しないと、重複登録や上書きの原因になります。
【副作用】
副作用とは、ある処理が本来の目的以外に起こす変化のことです。
画面を更新するだけのつもりが、内部状態を書き換えてしまう。データを読むだけのつもりが、最終アクセス時刻を更新してしまう。そうした「ついでに起きた変化」が、バグの原因になることがあります。
【観測】
バグ調査では、目で見た現象をそのまま信じるより、録画やログで確認できる形にすることが重要です。
再現条件を固定し、同じ操作で同じ結果が起きるかを確かめることで、偶然と原因を分けられます。
■ 作中の用語
【MICA】
相馬透が自分の作業用に作ったコーディングエージェントです。
ログやコードの整理は得意ですが、最初の段階では現実世界を直接見ることはできません。そのため、録画や画像など、透が渡した材料から判断します。
