特異なバグの民間伝承

常識とはかけ離れて見える問題でも、時には事実を映し出している

バニラアイスを買うと車のエンジンが掛からなくなる現象

ゼネラルモーターズのポンティアック開発部に寄せられた苦情。「家族でいつも夕食後にアイスクリーム屋でアイスを買っている。バニラアイスを買うと車のキーを回してもエンジンがかからない」。社長は懐疑的だったがエンジニアを2名派遣。実際にバニラアイスを買うと再現性あり。エンジンが掛からない。

エンジニアたちは調査を開始した。1日目、チョコアイスを購入。エンジンは掛かる。2日目、ストロベリーを購入。エンジンは掛かる。3日目、バニラアイスを購入。エンジンは掛からない。各方面から検討する。買いに行くのに掛かった時間、使っているガソリンの種類、往復の運転時間など。ややあってひらめく。バニラの時だけ購入時間が短い。

理由は店内のレイアウトにあった。バニラは一番人気のフレーバーであり、店頭のケースに置かれており提供時間が短かった。その他のフレーバーは店奥の別のカウンターに置かれていたため、提供に時間が掛かっていた。

なぜ提供時間の差が車のエンジンが掛からないことと関係あるのか。原因はベーパーロック現象である。停止直後のエンジンは熱いため、液体燃料が気化し泡状になって燃料通路を塞ぎ、エンジンが掛からなくなっていた。バニラ以外のアイスを購入した時は十分な時間があったので燃料が冷却され、ペーパーロックは収まっていた。しかし、バニラは提供が早かったためベーパーロック現象が起きている最中であり、エンジンが掛からなかったというわけである。

プレイステーションのセーブがランダムに破損するバグ

Dave Baggett's answer to What's the hardest bug you've debugged? - Quora

バグがある時、プログラマはまず自分を疑う。1にプログラムを疑い、2にプログラムを疑い、…10000番目にコンパイラを疑う。そしてリストが尽きたところでようやくハードウェアを疑う。これは2度と経験したくないハードウェアバグの話である。

当時、メモリーカードにクラッシュ・バンディクーのデータをロード・セーブするコードを書いていた。プロのゲームプログラマとして、これは1週間程度で終わる簡単な仕事だと思っていた。が、実際には6週間掛かった。もちろんそれに掛かりきりというわけではなかったが、数時間、数日おきにこの問題に舞い戻り苦しんだ。

起きた現象は次の通り。進行状況をセーブしようとする。ほとんど上手くいく。しかし、ごくたまに理由もなく読み込みや書き込みがタイムアウトすることがある。また、短い書き込みでメモリーカードのデータが破損する。プレイヤーがセーブしようとすると、セーブできないだけでなく、データが全消しになることがある。

しばらくして、ソニーのプロデューサーであるコニー・ブースがこの問題について恐怖に陥り始めた。この品質ではゲームが出荷出来ないのは明らかで、6週間経過してもまったく解決の糸口が掴めていなかった。コニー経由でプレステ1のゲーム開発者たちに類似バグがないか呼びかけてみた。しかし反応はなしのつぶてで、メモリーカードについて同様の問題を踏んでいる人は居なかった。

デバッグするしかないため、最小再現例となるテストコードを作る戦略を取った。ゲームにおいてそのようなコードを作ろうとすると、グラフィックや重力ギミックのようなものをすべてスタブコードに置き換えて行く必要があり、これは大変な作業だった。しかしやりきった。コードの塊を削除して、残るはスタートアップ・コード（ゲームを起動するためのシステムセットアップや、レンダリングハードウェアの初期化コードなどなど）だけとなった。テストコードにクラッシュ・バンディクーの実質的なコードは残っていない。ほとんど何もしないコードにも関わらず、ランダムに書き込みバグが発生した。

ある瞬間、午前3時頃、脳裏にある考えが浮かんだ。読み書き（I/O）には正確なタイミング制御を行う必要がある。つまり、クロックに従って読み書きを行う。クロックはCPUに直接接続されていないハードウェアを、CPU上のコードと同期させる。クロックは一方から他方へデータが送られるレート、ボー(Baud)レートを決定する。このタイミングが狂うと、ハードウェアないしソフトウェア、またはその両方が混乱する。これは非常に具合が悪く、大抵はデータの破損につながる。

セットアップコードの何かがタイミングを狂わせている可能性を考える。タイミング関連のテストプログラムを確認するとプレステ1のプログラマブルタイマーが1 kHzに設定されていた。これは比較的早く、プレステ1のデフォルトは100 Hzに設定されているため、ほとんどのゲームは100 Hzで動く。

これは主任エンジニアであるアンディによって設定されたものだった。アンディはやり過ぎることを好むエンジニアで、重力をシミュレーションするのであればできる限り高精度の計算をすべきだと考えていた。

このタイマーの動作Hzを増やすことにより、メモリーカードとプログラムのボーレートが乱れていたら？コードをコメントアウトしてテストプログラムを動かすと、バグは起こらなかった。しかし、このバグはごくたまに起こることが問題なのだった。翌日も、その次の日もテストプログラムを動かし続けた。二度とバグは再発しなかった。

そこで、クラッシュ・バンディクーの製品コードに戻り、メモリーカードに書き込む時だけタイマーを100 Hzに設定し、それ以外では1000 Hzに戻すようにした。すると、やはりデータは破損しなくなった。

しかし、本当の原因は何だったのか？

エラーが起きる際のパターンを発見するため、テストプログラムに何度も戻った。やがて、プレイヤーがプレステ1のコントローラーをガチャガチャしている時にエラーが起きることに気づいた。相関が見えると、再現するのは簡単だった。メモリカードにセーブを始める。その時コントローラをガチャガチャする。するとメモリが壊れる。これはハードウェアバグとしか思えなかった。

コニーのところに戻って、今しがた発見したことを話した。彼女はプレステ1の設計者にそれを伝えた。返ってきた返答はこうだ。「ありえないよ」彼女は言った。「これはハードウェアの問題じゃない」。プレステの設計者と直接話ができないかと頼んだ。

設計者が電話を掛けてきて、相手の拙い英語とこちらの（すごく）拙い日本語で口論になった。最終的に「コントローラーをガチャガチャするとバグが起きる30行のプログラムを送らせてくれ」と言った。相手が折れた。

翌日の夕方（私はLAに居て、彼は東京に居たので、相手はさらに次の日の朝だっただろう）、電話が来て彼はきまり悪そうに謝罪した。これはハードウェアの問題だった。

正確に何が起きていたのかまでは完全に分からないものの、ソニー本社から聞き返した話の印象を述べると、プログラマブルタイマーを十分に高いクロックレートに設定すると、タイマークリスタルの近くにある、マザーボード上の何かと干渉するということだった。その一つがメモリーカードのボーレートコントローラーで、それ一つでコントローラーのボーレートも設定していた。ハードウェアの専門家でないので、この辺りはかなりあやふやだ。

要点としては、マザーボード上の個々のパーツの漏話と、1 kHzでタイマーを動作させているコントローラポートとメモリーカードポートとの組み合わせが、ビットの脱落を引き起こし、カードが破損するというものだった。

鉄のカーテンの向こう側にて

Debugging Behind the Iron Curtain | Jake Poznanski — Robots, Thoughts, AI Rights

筆者の恩師セルゲイが従事していた、1980年代のソ連の列車・貨物を経路案内するソフトウェア開発に関する逸話。PDP-11のソ連製クローンであるSM-1800上でソフトウェアを開発していた。このマイコンは、当時ソ連の主要な輸送拠点であるスヴェルドロフスクに設置されたばかりだった。この新システムは不定期に故障やクラッシュを引き起こすバグがあった。クラッシュは常に全員が帰宅した深夜に発生していた。徹底的な調査にも関わらず、翌日の手動及び自動テストではソフトは正しく動作していた。この手のバグは競合状態（race condition）や並行処理に伴うバグであるのが常だった。鉄道会社からの深夜オンコールにうんざりしていたセルゲイはこのバグの撲滅に乗り出した。第一歩として、鉄道操車場内のどの条件がプログラムクラッシュを引き起こしているかを正確に把握する必要があった。

セルゲイはまずクラッシュの発生履歴を全て収集し、その日時をカレンダーにプロットした。するとパターンが明確に確認できた。さらに数日間その挙動を観察すると、セルゲイは将来の故障タイミングを簡単に予測できることに気づいた。

パターンはこうだ。ウクライナ北部とロシア西部から近くの食肉処理工場に向かう生牛を運ぶ時だけ、プログラムがクラッシュする。それ自体として奇妙なことだが、地元の食肉工場は過去にはもっと近くのカザフスタンの農場から家畜を仕入れていた。

ご存知のように、チェルノブイリ原子力発電所事故は1986年に発生し、致命的なレベルの放射能を拡散させた。放射能は、ウクライナ北部、ベラルーシ、ロシア西部など周辺地域に広範囲な汚染をもたらした。セルゲイは、入線してくる列車に高濃度の放射能が含まれている可能性を疑い、その仮説を検証する方法を考案した。ソ連政府はガイガーカウンターの所持を制限していたため、彼は車両基地に駐屯していた軍人数人と酒を酌み交わした。ウォッカを何杯か飲んだ後、兵士を説得して、疑いのある鉄道車両の1両を測定してもらった。

牛の出荷が放射能で高濃度に汚染されていただけでなく、線路に近い建物にあったSM-1800のメモリのビットをランダムに反転させるほど高いレベルだったのだ。

ソ連では食糧不足が深刻で、政府はチェルノブイリ地域の牛の肉と他の地域の汚染されていない肉を混ぜることを計画した。そうすれば、貴重な資源を無駄にすることなく、肉の平均放射線量を下げることができる。このことを知ったセルゲイは、すぐに移民申請書をあらゆる国に提出した。コンピュータのクラッシュは、時間の経過とともに放射線レベルが下がるにつれて解決した。

月の満ち欠けに依存するバグ

phase of the moon

何らかのプログラムがランダムなパラメータに依存していることをおどけた言い回しにした言葉。用例「この機能はチャンネルがmumbleモードで開いていること、fooスイッチがセットされていること、そして月の満ち欠けに依存する」。

実話として、昔々、月の満ち欠けに依存するバグがあったことが知られている。MITの様々なプログラムから呼び出されていた月の満ち欠けを計算するサブルーチンがあった。GLSはこのルーチンをLISPプログラムに組み込んだ。それを使ってファイルを書き出す。表示すると、ほぼ80文字長のタイムスタンプ行を印字する。たまにメッセージの最初の行が長すぎて次の行にオーバーフローすることがあった。そうすると、書き出したファイルを後で読み込む時プログラムがエラーを吐いてしまう。この行の長さは正確な日時とタイムスタンプが印字される時の位相指定に依存していたため、このバグは文字通り月の満ち欠けに依存していた。

トイレの水を流すと緊急停止する高速列車

[deleted by user] : programming

フランスの高速列車が運行中にランダムに緊急停止する事象があった（ただし、乗客が乗っているときのみ）。緊急停止が起きるたびに運行を停止し、点検するが異常が見つからない。そこで再び運行を再開する。するとまた緊急停止する。

とあるテスト走行中、テストエンジニアがトイレに向かった。トイレを流すと…バァァン！緊急停止だ。エンジニアから機関士に無線連絡「緊急停止のブレーキが掛かる前に何をしてた？」機関士「ええと、下り坂だったからブレーキを掛けてたけど…」

これは奇妙だった。通常走行では下り坂では何十回となくブレーキを掛ける。次の下り坂で機関士が無線で「オーケー、下り坂でブレーキを掛けるぞ」何も起きない。

「こちらがブレーキを掛ける前は何を？」機関士の質問。「いや、トイレに…」「じゃあトイレに行って下り坂に入ったらさっきと同じことをしてくれ」

そこでエンジニアはトイレに行き、機関士が「オーケー、ブレーキしてるぞ」と呼んだところで水を流した。すると果たして緊急停止が起きたのだった。

再現条件がわかり、原因を突き止めることが出来た。

エンジンブレーキの遠隔操作ケーブル（この列車は両端にエンジンが1つずつ付いている）が配線盤の壁から外れ、トイレの排水トラップの電磁弁を制御するリレーの上に落ちていたのだ。リレーが作動すると、ブレーキケーブルに何らかの干渉が起こり、フェイルセーフシステムは単に緊急ブレーキを掛けていたのだった。

FORTRANを嫌うネットワークゲートウェイ

The FORTRAN-hating gateway

数ヶ月前から、本土へのネットワ―ク接続が（時おり）非常に非常に遅くなっていることに気づいた（訳注：当時筆者のJoe Delingerはハワイ大学に在籍）。この状態は10～15分ほど継続し、突然元に戻る。これが起きてしばらくすると、同僚が本土への接続がうまく行かなかったと訴えてくる。彼はFORTRANのソースコードを本土のマシンにコピーする必要があったが、FTPでコピーを遂行するのに十分な時間ネットワークが立ち上がらないため、実施できなかったのだ。

そう、同僚が特定のFORTRANソースファイルをFTPで本土に送ろうとすると、必ずネットワーク障害が起こることが判明したのである。ファイルを圧縮してみると、うまくコピーできた（しかし、残念ながら本土に解凍プログラムがなく、解決しなかった）。仕方なく、FORTRANプログラムを非常に小さなコード片に分割して一つずつ送信した。ほとんどのコード片は問題なくコピーできたが、いくつかのコード片は全くコピーできないか、何度も何度もリトライしてようやくコピーできた。

問題のあるコード片を調べると、一つの共通点があった。大文字のCだけで始まり、大文字のCで終わるコメントブロックが含まれていたのだ（これは同僚が好んでいたコメントスタイルだった）。この時点で、我々は本土にいるネットワークの達人たちに助けを求めるメールを送っていた。当然ながら、彼らはFTPできないコード片に興味津々だったので、メールでいくつかのファイルを送付した……がメールは届かなかった。仕方なく送信不能なファイルがどのようなものかを説明する方法を思いつき、それでうまく行った。

結論として、我々は話の全貌を知ることができた。ここ最近、我々のキャンパスと本土との間に、新しいゲートウェイが設置されたのである。このゲートウェイは大文字のCが繰り返されるパケットを送信するのがとてつもなく苦手だったのだ。このゲートウェイはそのようなパケットが数個あると、ゲートウェイのエネルギーを全て吸い尽くしてしまい、他のほとんどのパケットが通過できなくなってしまう。ここで我々はゲートウェイのメーカーにクレームを付けたが、「その通り。繰り返しCのバグを踏みましたね。我々は知っていました」と返されただけだった。結局我々は別のメーカーから新しいゲートウェイを購入して問題に片を付けたのであった（メーカーの言い分としては、FORTRANプログラムを送信できないのは一種の機能だ、ということなのかもしれない）。

難しい日付

Curtis Poe's answer to What is the most interesting bug you have ever solved in a computer program? - Quora

数年前、第III相臨床試験のコストを削減するためにPerlでETLシステムを構築していたときに、約40,000の日付を処理していることに気づいた。40,000の日付のうち2つについて検証できなかった。これらの日付はクライアントが提供したデータから取得したものであり、そうしたデータはしばしば驚きに満ちたものだったので、それほど気にしていなかった。しかし、生データを調べてみると、それらの日付は2011/1/1と2007/1/1であることが分かった。自分が書いたばかりのソフトウェアにバグがあることに気づいたが、後にこのバグは実際には30年前に埋め込まれたものと判明したのである。

ソフトウェアエコシステムに疎い読者には、上記は不可解な響きがする言い方かも知れないが、実際には理に適っている。なぜかというと、はるか昔別の会社に利益をもたらすという意思決定をしたため、ある会社が誤って導入したバグと、また別の会社が意図的に導入したバグを修正するために、私のクライアントは私にお金を支払ったからだ。こうした複雑な経緯を説明するには、バグである機能を導入した第三の会社と、私が修正した曖昧なバグに寄与したその他の歴史的こぼれ話をする必要がある。

古き良き時代、Appleコンピュータの日付は自動的に1904/1/1にリセットされることがあった。理由は至ってシンプル、当時、Appleコンピュータは日付と時刻を把握するためバッテリー駆動の「システムクロック」を採用していたからだ。バッテリの電池が切れるとどうなるのか。Appleコンピュータは日付をエポックからの秒数として把握していた。この意味で、エポックは単に日付を数え始めるための基準日であり、Macintoshコンピュータの場合、そのエポックは1904/1/1となる。そして、システムクロックのバッテリーが死ぬと、1904/1/1が新しい日付となる。しかし、実際にここで何が起きたのかは考える必要がある。

当時、Appleは32ビット整数で開始日からのエポック秒を保持していた。2^32秒すなわち4,294,967,296秒は約136年に相当する。つまり、古いMacでは2040年以降の日付が処理できない。またシステムクロックが電池切れで死ぬと、日時はエポック後0秒にリセットされるので、手動で日時を再設定する必要があった。

しかしながら、日付をエポックからの秒数で保存するというAppleの解決策は、エポック以前の時間を扱えないということも意味する。これは後述するように広範囲に影響を及ぼした。これはアップルが導入した仕様でありバグではなかった。この仕様によりMacintosh OSは2000年問題の影響を受けなくなった（もっとも、多くのMacアプリは上述の制限を回避するため独自の日付システムを導入しており、そのために影響を受けなかった）。

続いて、Lotus1-2-3が登場した。これはIBMのキラーアプリとしてパソコン革命の火付け役となったが、実際にパソコンを世に普及させたのはAppleのVisiCalcである。一つ言えることは、Lotus-1-2-3がなければパソコンはあのように普及していなかっただろうし、パソコンの歴史も今とはかなり違ったものになっていただろうということだ。

ところで、Lotus-1-2-3は誤って1900年をうるう年と認識していた。そのころMicrosoftが最初の表計算プログラムであるMultiplanをリリースしていたが、市場への浸透度は高くなかった。そこでExcelに開発着手したとき、Lotus-1-2-3の行/列の表命名形式を採用するだけでなく、意図的に1900年をうるう年として扱うなど、今日まで禍根を残すバグの互換性を持たせることにした。Lotus-1-2-3にとってこれはただのバグだったが、Excelにとっては、Lotus-1-2-3を使っている人がデータを間違いなくインポートできるよう保証するための機能としてバグを導入したのである。

しかし日付については他にも問題があった。MicrosoftがMacintosh向けに初めてExcelをリリースした時、前述の通り、Macintoshは1904/1/1以前の日付を認識することができなかった。ところで、Excelは1900/1/1をエポックとして利用していた。そこでExcelはエポックがどちらであるかを認識し、それぞのエポックからの相対的な日付を内部データとして保存するよう修正を行った。この点についてMicrosoftのサポートは明確に説明しているが、この修正が私が埋め込んだバグにつながることとなる。

私が構築していたETLシステムは多数の顧客からExcelのスプレッドシートを受け取っていた。これらのスプレッドシートはWindowsで作成されているかもしれないし、Macで作成されたものであるかもしれない。その帰結として、スプレッドシートのエポック日付は1900/1/1かもしれないし、1904/1/1かもしれない。どうやったらどちらのエポックを使っているか判定できるのか。Excelのファイルフォーマットにはどちらのエポックを使っているか示す情報が存在する。しかし、当時Excelから情報を取り出すのに使っていたパーサーは、エポックが1900年と1904年どちらに基づくものかをパースする事ができなかった（今はできる）。Excelのバイナリフォーマットを読み取る方法を調べ、そのパーサのためにパッチを送る時間を費やすという選択肢もあったが、当時私はクライアントとの仕事に忙殺されており、より簡単にエポックを判定するための経験則的コードをサラッと書いた。

Excelにおいて、例えば1998年7月5日という日付があったとして、07-05-98（役立たずな米国式表示）、Jul 5, 98、July 5, 1998、5-Jul-98などなど、多数の役に立たないフォーマットで表示される可能性がある（皮肉にも、私が使っていたバージョンのExcelでは国際標準のISO 8601フォーマットが提供されていなかった）。しかしながら、内部的には、これらのフォーマット化されていない値は、1900年日付システムの場合35981、1904年日付システムの場合34519となる（これらの数値はエポックからの日数を表す）。そこで、堅牢な日付パーサーを使ってフォーマット済の日付から年を抽出し、Excelのパーサーを使ってフォーマットされていない日付から年を抽出するという方策を取った。もし両者が4年ズレていれば、そのスプレッドシートは1904年の日付システムを使っていると分かるだろう。

なぜ単純にフォーマットされた日付を使わないのか。それは例えば1998年7月5日が July, 98 とフォーマットされている場合、月の中の日にちの情報が失われるからだ。（前述の通り）非常に多くの会社から異なる方法で作成されたスプレッドシートを受け取っており、そのすべてを判定できる必要がある。スプレッドシートは絶対なので、我々もそれに従い同様に正しく処理をする必要がある！

そうしているうちに、39082にケツを蹴り飛ばされた。Lotus-1-2-3が1900年をうるう年とみなし、そのバグがExcelに忠実に導入されたことを思い出して欲しい。このバグは1900年に1日追加するため、これに依存する多くの日付計算関数は1日ずれる。すなわち39082は2011/1/1かもしれないし（Mac）、2006/12/31かもしれない（Windows）。私の作った年度抽出パーサーがフォーマットされた値から2011年を抽出する。素晴らしい。しかしExcelのパーサは1900年と1904年どちらの日付システムを利用しているか判定できないので、一般的に利用される1900年日付システムをデフォルトとして設定し、2006年を返す。そして、私のコードは年が5年離れている場合それをエラーとみなしてログ出力し、フォーマットされていない値を返すようにする。

この問題を回避するために、以下のようなコードを書いた（擬似コードであることに注意）

    diff = formatted_year - parsed_year 
    if 0 == diff 
        assume 1900 date system 
    if 4 == diff 
        assume 1904 date system 
    if 5 == diff and month is December and day is 31 
        assume 1904 date system

これにより40,000エントリ全てが正しく処理された。

長大な印刷ジョブが途中で止まる現象

djinn and juice : The Best Debugging Story I've Ever Heard

1980年代初頭、父はStorage Technology社で働いていた。Storage Technology社はテープドライブとテープを高速駆動する空気圧システムを開発していた、今はなき企業である。

彼らはテープドライブを~~ハック~~エンジニアリングして、1台の中央ドライブ（'A'ドライブ）に7台の'B'ドライブを接続し、Aドライブに接続されたRAM上で動く小さなOSからすべてのBドライブへのデータ読み書きを移譲するような構成を作った。

Aドライブを起動する際、Aドライブに接続された周辺ドライブにフロッピーディスクを挿入し、OSをAドライブのRAMにロードする必要があった。このOSは恐ろしいほど原始的で、8ビットのマイクロコントローラからその処理能力を得ていた。

この種の構成のターゲット顧客は銀行や雑誌社など、大量の住所ラベルや取引明細を印刷する必要のある、大量データを持つ企業だった。

ある顧客が問題を抱えていた。印刷の実行途中で、Aドライブが停止し、印刷ジョブ全体が止まってしまうのだ。ドライブを復旧させるのに従業員はドライブ全体を再起動する必要があった。もし6時間掛かる印刷の途中で停止した場合、高価なコンピュータの計算時間が失われ、作業予定時間を大幅に超過することになるだろう。

Storage Technology社は技術者を派遣した。技術者はあれこれやってみたが、テストではバグを再現できなかった。このバグは長大な印刷ジョブの中程で発生するように思えたので、ハードウェアの問題である可能性に一縷の望みを託し、RAM、マイクロコントローラ、ディスクドライブなどテープドライブの思いつく限りの部品を交換してみたが、問題は解決しなかった。

そこで技術者は本社に電話を掛け、専門家を呼ぶことにした。

専門家は椅子とコーヒーを1杯用意し、計算機室に座った。社屋にコンピュータ専用の部屋があった時代である。従業員が長大な印刷ジョブをキューに入れるのを見守り、それがクラッシュするのを待った。誰もが専門家の動向を注視していたが、彼も何が原因なのか見当もつかなかった。そこで彼はもう一度ジョブをキューに入れるよう指示し、従業員と技術者たちはその仕事を再開した。

専門家は再び椅子に座り、ジョブがクラッシュするのを待った。6時間待ち、ようやくクラッシュした。クラッシュした時、計算機室が混雑していたこと以外、何が原因なのかやはり分からなかった。ジョブの再起動を指示し、再び椅子に座った。

3度目のクラッシュで、あることに気づいた。ジョブのクラッシュが、従業員が関係ないドライブのテープを交換している時に起きたのだ。さらに、従業員が床の特定のタイルの上を歩くとすぐにジョブがクラッシュすることにも気づいた。

踏むとジョブがクラッシュする床は、高さ15cm～20cmほどの支柱で支えられたアルミタイルでできていた。コンピュータが必要とする大量の配線は、不注意な従業員が重要なケーブルにけつまずかないようタイル床下に通されていた。タイルは配線が通っている床下の空間にゴミが落ちないよう、非常にキツく敷き詰められていた。

専門家はアルミタイルの一つが歪んでいることに気づいた。従業員が歪んだタイルの角に立つと、タイルの端同士が擦れあった。タイルとタイルをつなぐプラスチックが擦れ合うことで、マイクロスパークが発生し、それが無線周波数干渉（RF干渉）を引き起こしていたのだ。

今でこそRAMはRF干渉から徹底的に保護されているが、当時はそうではなかった。専門家はRF干渉がRAMの状態を破壊し、すなわちRAM上のOSを破壊していたことを突き止めた。

専門家はメンテナンス事務所に電話し、新しいタイルを入手し設置した。すると問題は二度と起こらなかった。

満潮だ！

Journal of godoy (2167)

読者への挑戦状…読み終わるまでに真相が分かるかな。

場所はポーツマス（たぶん）の港のそば、オフィスの4階か5階のサーバールームだった。ある日、メインのDBサーバー（Unix）が落ちた。再起動したが何度も何度も落ちるのでサポート会社に助けを要請した。

サポート会社のヤツ…名前はマークだったと思うけど、キミたちは会ったこともないだろうし、どうでもいいよね。いやダメか。まぁ話を円滑にするためにマークということにしておいてくれ。よし。

マークは数時間後現地に到着した（リーズからポーツマスまでは…かなり長い道のりだ）サーバーの電源を入れると、エラーも起こらずすべて動いた。ありがちな殺伐としたサポート現場で、客はとにかく腹を立てている。彼はログファイルを調査したが、サーバが滅茶苦茶になるような証拠はどこにも見つからなかった。マークは列車に戻り、無意味な一日を過ごした後、リーズへと戻っていった。

その日の夜半、サーバが落ちた。そして小説の筋書きみたいに、サーバーを再起動できなかった。マークはいつものように遠隔からサポートを行ったが、やはり客はサーバを再起動させることができなかった。

列車に乗り、バスに乗り、レモンメレンゲパイに乗り、実際何を乗り継いで来たかは知らんけど、彼はポーツマスに戻った。なんと、サーバーは何の問題もなく再起動した。これは奇跡だ。マークは数時間掛けてOSやソフトウェアに異常がないことを確認し、ほうほうの体でリーズに帰ることができた。

次の日の正午、サーバーがダウンした（頼むから落ち着いてくれ）。ハードウェアサポートを読んでサーバを交換するのが賢明と思われた。しかし交換の10時間後、またダウン。

このパターンが数日続く。サーバーは動くが、起動して10時間後に落ちる、そして2時間は再起動できない。冷却機構を確認し、メモリリークを確認し、とにかく何でも見直したがホコリ一つ出ない。そしてサーバーは落ちる。

1週間は何も問題なく過ぎた…みんなハッピーだった。ハッピー。サーバが10時間動いて…2～3時間落ちて…というお決まりのパターンを繰り返していることを除いては…

そのうち誰かが（その人はITとは全然関係ない人だったと記憶している）言った。

「満潮だ！」

うつろな表情で、おそらくインターホンの向こうのセキュリティに震える声で言った。

「満潮になると落ちる」

コーヒーブレーク中の片手間に潮汐年鑑を研究しているようなITサポートスタッフにとって、この言葉はかなり異質な概念として響いた。

そこで彼らは潮の満ち引きとは関係ないことを説明した。なぜならそれは週単位で変化するものだから。

「先週は小潮で、今週は大潮なんだよ」

王立ヨット協会（RYA）の会員資格をお持ちでない皆様のために、ここで専門用語を少し解説する。潮の満ち引きは月の周期で行われ、地球が回転する12.5時間ごとに太陽と月の引力が潮の満ち引きを発生させる。

一方からもう一方へ、12.5時間のサイクルで、満潮から始まり、途中で干潮になり、そして満潮で終わる。しかし、月の軌道の変化によって、満潮時と干潮時の差も変わる。月が地球と太陽の間にある場合、あるいは地球の反対側にあるとき（満月または新月）、大潮となり、干潮時と満潮時の差が最も大きくなる。半月の時は反対に小潮となる。満潮時と干潮時の差が最も小さくなる。月の周期は28日であるため、大潮、小潮、大潮、小潮、という周期で繰り返す。

話を戻そう。

男が技術者たちに潮汐の原理の要点を説明すると、技術者たちは警察に通報することを考え始めた。これは妥当と言えるだろう。しかし結局はその男が正しいことが分かった。2周間前から、海軍の駆逐艦か何かが近くに係留していた。満潮に向かって潮がある高さに達するたびに、艦橋がサーバールームと一直線上の位置関係になった。艦橋から発せられたレーダー（あるいはジャミング電波のようなもの）が、サーバーをしっちゃかめっちゃかに混乱させていたようだ。

ミサイル・タスク

Kickin' the Darkness: A Coding War Story: What's Your Point?

私は非常に大規模（約400KSLOC≒40万行）なミサイル発射指揮統制システムを、新しいOSとコンパイラに移植する仕事を命じられていた。具体的には、Solaris 2.5.1からSolaris 7へ、Ada 83（Verdix Ada Development System, VADS）からAda 95（Rational Apex Ada）へである。VADSはRational社に買収されており、その製品は時代遅れだった。RationalはApexコンパイラへの移植を容易にするためにVADS固有のパッケージの互換バージョンをなかなかいい感じに実装してくれていた。

私の他に3人が最初のコンパイル作業を手伝い、コードをきれいにコンパイルするのに2週間ほど掛かった。その後、システム全体を実際に動くようにする仕事を私ひとりが受け持った。かいつまんで話すとそれは私が今までに受け持った中で最悪のシステム設計・実装だったので、移植作業を完遂するのにさらに2ヶ月が掛かってしまった。その後、正式なテストに回されたが、これも数ヶ月掛かった。テストを進めるにつれ、見つかったバグをかなり着実に修正していった、しかし、テストが進行するにつれてそのペースも急速に落ち込んでいった（元のコードが本番で稼働実績のあるシステムなので、その機能は非常に堅牢であり、新しいコンパイラの導入に由来するバグしか潰せるものがなかった）。そうして、移行前のシステムと同等の動作確認が取れたところで、私は別のプロジェクトに配置転換された。

感謝祭の日の前、金曜日に電話が掛かってきた。

3週間後にミサイルの発射試験が予定されており、事前試験としてカウントダウンを実施したところコマンドシーケンスがロックされてしまったのだ。本試験でこのような事態が起これば試験は中止となるだろうし、もしこのロックアップが点火から数秒以内に発生した場合、支援システム内で多数の不可逆的な動作が起こり、ミサイルを再処理するために長くそして高く付く遅延が生じるだろう。ミサイルが発射されなかったとして、数多くのかわいそうな人々が多額の費用の問題に苦悩することになることは容易に推察できた（国防総省の人々はお金をぞんざいに扱うという言説には反対する。私が今まで会った契約マネージャーは、予算をまず優先順位の第1位か第2位に考える人しかいなかった。なお2位の場合、スケジュールが優先度1位に入る）。

該当のカウントダウンテストとその変種テストは過去数カ月間に何百回となく実施されたものだったが、ほんの一握りの小さな不具合が起きただけだった。つまり、この問題は発生確率が非常に低かったが、その発生コストは非常に大きかった。発生確率と発生コストをかけ合わせると、結果は私や他のエンジニア、マネージャーにとって最悪の感謝祭となったのだった。

セーフクリティカルな防衛システムのほとんどがそうであるように、このシステムも数多くのログを記録しているため、システムが停止した時に実行されたコード行を特定するのは簡単だった。そして当然のことながら、それらのコード行にはおかしなところは何もなく、同じステートメントがプログラムの実行中、文字通りすでに何千回も正常に実行されていた。

Rational社のApexコンパイラ担当者にも報告を行った。つまり、コンパイラが生成するコードの中で、ベンダーが提供するルーチンが含まれていたからだ。これは文字通り国家的に重要な問題であり、なんとしても原因究明する必要があることを彼らに印象付けた。そのため、彼らの感謝祭週もゴミ箱行きとなった。

ログから分かることにも限界があるため、地元のラボで問題を再現してみることにした。テストを1000回して1回発生するような事象であるため、簡単なことではなかった。根本原因として推察されたのは、コンパイラベンダーが提供するミューテックスのロック開放関数（VADSからの移植パッケージとして提供されていた）が、実際にはアンロックされいないのではないか、ということだった。この関数の呼び出しを行っていたスレッドは、数秒ごとに届くハートビートメッセージを処理していた。

そこで、このハートビートのレートを10Hz、つまり1/10秒毎に上げてプログラムを開始した。約1時間後、システムはロックした。ログを見直すと、前回失敗したときと同じ一連のメッセージが記録されていた。さらに何度か実行したが、プログラムを開始してから45分～90分の間に一貫してロックアップが発生し、毎回同じログが記録された。そのため、（ハートビートレートを増加したぶん）本番と全く同じコードではないものの、一貫した結果が出るため、このストレステストが本番と同じ状況を再現していることを確信した。

次の計略は、バグが起きている候補となるステートメントのどこで実際にロックアップが起きているかを絞り込むことだった。

このシステムの実装にはAdaのタスクが使われていたが、使われ方が非常にまずかった。タスクはAdaの高レベル並行処理命令で、スレッドに似通ったものだが、言語組み込みであるという点が異なる。Adaでは一般的に、2つのタスクが同期通信をする時は、「ランデブー」を行い、ランデブー時にお互いに必要なデータを交換し、交換が終わるとランデブーを解散して独立したプログラム実行を再開する。このシステムは並行処理をそのように実装していなかった。代りに、あるタスクがターゲットとなるタスクとランデブーすると、そのターゲットタスクが別のターゲットタスクとランデブーし、さらに別のターゲットタスクとランデブーし…といった具合に、最終的になんらかの処理が完了するまでランデブーし続け、そこでようやく全てのランデブーが解消されてそれぞれが独立した処理に戻るという形になっていた。結局、この並行処理は一つの大きな関数呼び出しに成り果てており、各入力データを処理している間、「マルチタスク」プロセス全体が停止してしまうのだった。通常時のスループット（データ処理量）が非常に低かったから、今までは単に問題が起きていなかったのである。

この余談の論点は、タスク処理でランデブーが要求されたり、ランデブーの待ち受け（await）状態になると、「タスク切り替え」が起きうる、ということだ。これはCPUが実行可能な別のタスクを処理開始できることを意味する。よって、あるタスクが別のタスクとランデブーする準備が整うと、別のタスクがその列に並んで実行され、最終的にランデブーしているタスクに制御が戻ることがある。タスク切り替えを引き起こすイベントは他にもあり、うち一つはミューテックスを取得したり印刷を行うOS関数を呼び出すことである。

そのため、どの行が問題を引き起こしているかを正確に突き止めるには、タスク切り替えを起こさずに、一連のステートメントの進行状況を記録する方法を見つける必要があった。よって、Put_Line()を呼び出すという手は取れないし、その他システムI/Oを実行するのはNGだった。カウンタ変数のようなものを設定することはできるが、それを印字することはできないので、どのように処理が進行しているのを確認をしたらよいのか、ということだ。

実行ログで観察された事象の一つに、ハートビート処理がフリーズし、最終的にプロセスのI/Oがすべてブロックされ、他の必要な処理が発生しなくなる一方で、実行全体のうち他の独立なタスクは動き続けていたというのがあった。つまり、プロセス全体がブロックされたわけではなく、数珠つなぎになった（クリティカルな）タスクたちがブロックされただけだった。

このヒントが、問題となるステートメントを特定するのに必要なくさびとなった。

まず、列挙型とそのグローバル変数とタスクを含むAdaパッケージを作成した。列挙リテラルは問題のあるコード列の特定のステートメント（Incrementing_Buffer_Index、Locking_Mutex、Mutex_Unlockedなど）をキーとし、その列の中に、対応する列挙型をグローバル変数に代入する代入ステートメントを挿入した。このオブジェクトコードは定数を特定のメモリ位置に格納するだけのものだったため、これを実行することによりタスク切り替えが起こる可能性は極めて低かった。実際、タスクのスイッチバック後に（何らかの理由で）実行が再開されず、ロックするという挙動が一貫していたため、我々がまず疑ったのはタスク切り替えを引き起こしそうなステートメントだった。

モニタリング・タスクは、ループして周期的にグローバル変数の値が変更されたかを検知すること以外は何もしないタスクである。変更を検知すると、そのたびに値をファイルに出力する。その後少し間隔を置いて次のチェックを行う。モニタリング・タスクからファイルを書き出すようにした理由は、問題領域の数珠タスクにおいてタスク切り替えが発生し、このタスクの実行が選択された場合にのみタスクが実行されるからである。モニタリング・タスクで何か（タスク切り替えのような）ことが起きても、問題領域で実行されている他のタスクには何の影響もないはずである。

ここでプログラムに期待していた動作は、問題のコード領域に入ると、そのコードが実行され、各ステートメントが進行するにつれて、グローバル変数が繰り返しリセットされるということだ。タスク切り替えが発生するプログラムの実行レート（10Hz）はモニタリングタスクより遅いため、モニタータスクは十分な頻度でグローバル変数の値を取り出し、それをファイルに書き出すことができる。以上より、通常時の動作では、列挙型のサブセットの系列の繰り返し、特にタスク切り替えが起こる前に変数が最後に保持していた値を表示するはずである。そして、フリーズが起きたときは、そのグローバル変数は何も変化せず、最後に記録された変数はどのステートメントが実行から再開されなかったかを指し示すはずである。

このような計装を備えたプログラムを実行し、フリーズした。そしてモニタリング・タスクは見事に動作した。

プログラムの進行状態をロギングするモニタリング変数は、まさしく期待通りの命令系列を表示した。Mutex Unlock関数を呼び出したところに対応する値で停止したのである。タスクを再開する合図として保存されるはずの値は、それまで問題なく動いていた何千回とは異なり、表示されることはなかった。

Rational社のコンパイラに原因があったのだ。この間、Apexコンパイラ部門のエンジニアたちは熱心にコードを解析し、ミューテックスコードの中に理屈上プログラムをブロックしうる箇所を見つけた。しかし、その確率は非常に低く、ある特定の順序とタイミングでないと発生することはなかった。マーフィーの法則。皆さん。これはマーフィーの法則だ。

回避策として、我々はこの一連のコードを保護するベンダー製のミューテックス関数（OSのミューテックス機能を利用して構築されていた）を、Ada言語ネイティブのミューテックス関数を利用した自作のコードに置き換え、それを使って関連領域へのミューテックス・アクセスを制御した。

上記をコードに組み込んで再テストした。テスト開始から7時間後、問題なくテストは実行されていた。

私のミューテックスパッケージコードはRational社に渡され、コンパイルと逆アセンブルを行い、問題のベンダー製ミューテックス関数が取っていたアプローチとは異なることをアセンブラレベルで確認した。

その後、私の人生の中で最も出席者の多いコードインスペクションが行われた :-) その部屋には1ダース近くのエンジニアとマネージャーがおり、さらに少なくとも1ダースの人間が全国から電話で参加した。たった20行のコードを精査するためにである。

精査を通過し、新しい実行ファイルが正式にビルドされた。そして実行ファイルは、正式なリグレッション・テストのため、テスト組織に引き渡された。数週間後、ミサイルのカウントダウンは完璧に進行し、ミサイルは発射された。

私が冷たい七面鳥が嫌いでなかったのは幸いだった。

よしよし、これはこれでめでたしと言えるが、しかしこのコーディング戦争物語の本当の教訓は何だったのだろうか。

これは厄介な問題だった。並行処理、沢山の通信プロセス、数百KSLOCSのコード、稚拙な設計、稚拙な実装、組み込みシステムへのインターフェース、そして数百万ドルの資金がこの仕事に掛けられていた。プレッシャーに負けそうになったりしないのだろうか。

まずこの問題に取り組んでいた開発者は私だけではなかった。もちろん最初の移植を担当した時は私一人だったので、槍玉に挙がったが、移植をしただけで何十万行ものコードを熟知することができるはずもなく、いや大まかな全体像すら把握できていなかった。国中の他のエンジニアたちも同様にコードやログに目を通していたが、彼らが根本原因について仮説を提出しても、私がそれを否定するのに30秒も掛かることはなかったし、また私が様々な分析を要求された時も、的はずれなものが多いと感じられたので他の人にその作業は押し付けていた。傲慢に聞こえるかも知れない。いや、実際そうなのだが、しかし私がそうした仮説や依頼を却下したのは傲慢さのせいではないと言いたい。

問題の本質を理解していたからである。実際に問題がどこで起きているか、何故起きたかは正確には分からなかったが、しかしどのような問題が起きているかは理解していた。

私はAdaについて、長年にわたり多くの経験と知識を積み上げていた。Adaのアーリーアダプターであり、並行処理とその落とし穴を理解し、Adaのランタイムライブラリがタスクと並行処理をどのように扱うかを知っていたし、生メモリ、レジスタ、アセンブリ言語のような低レベルプログラミングについても理解していた。すなわち、自分はこの業界において深い知識を持ち、確たるニッチを獲得している。バグを回避するに留まらず、非常に繊細な実行環境でバグを発見するための戦略の組み上げ方についても知見を持っていた。

コーディング戦争物語の具体的内容は、その問題の性質や環境の特殊性になじまない人にとってはそれほど興味深いものではないかも知れない。しかし、本当に難しい問題を解決するためには何が必要かということを理解する落ち穂拾いとして役に立つ。

本当に難しい問題を解決するためには、コーダーである以上に、そのコードの摂理を理解し、そのコードが環境とどのように作用し、その環境自体がどのように動くかを理解する必要がある。

こうした教訓を体得すれば、あなたも感謝祭の休日を台無しにすることができるだろう。

「魔法」の物語

A Story About ‘Magic'

こちらもJargon Fileから。MITのAIラボにPDP-10が収められており、近くのキャビネットに誰かが自作したと思しきスイッチが設置されていた。「more magic」と書かれたスイッチは、片方にワイヤーが一本しか通っておらず、もう片側にはワイヤーが接続されていなかった。スイッチが2本のワイヤーで接続されていなければ何も出来ないというのは電気の基本的事実である。

これはくだらないジョークだと思い、ボタンを押しても何も起きないと確信し、スイッチを押した。するとコンピュータは即座にクラッシュした。

1年後、この話をハッカーであるDavid Moonにしたところ、正気を疑われたが、実際にそのスイッチを見せてみた。まだキャビネットに接着したままで、ワイヤーは一本しか接続されていなかった。接続の一方はコンピュータ、もう一方の端はアースピンに接続されていたということである。アースに接続されていれば電気的に動作するはずはないので、スイッチを押し、コンピュータはやはり直ちにクラッシュした。

次は長年MITのハッカーとして活躍していたRichard Greenblattにこの話をした。彼もそのスイッチを念入りに確認したが、使い物にならないと結論し、ペンチを持ってきてそいつにケリを付けた。そしてコンピュータを復活させ、それ以来マシンは問題なく動いている。

スイッチがどのようにマシンをクラッシュさせたのかは謎だが、アースピンの近くにある回路が電気的に限界に達しており、スイッチを入れた瞬間に静電容量が変化し、100分の1秒スケールでパルス電流が回路を通過したために、コンピュータの回路が動揺した、という説がある。確かなことは分からないが、実際問題あのスイッチは魔法だったのである。

1994: この話については、その後別の説明がなされている。スイッチ本体が金属製であったとする。スイッチの非接続側がスイッチ本体に接続されていたとする（通常、本体は別のアースラグに接続されているが、例外もある）。ボディはコンピュータのケースに接続されており、おそらく接地されている。そのため、スイッチを入れると回路アースとケースアースが接続され、電圧降下／ジャンプが発生してマシンがリセットされた。これはおそらく、両者の間に電位差があることを苦労して発見した誰かが、冗談でスイッチを配線したのだろう。

火曜日にプリンターが印刷できないバグ

The RISKS Digest Volume 25 Issue 77

今日、あるブログで興味深いバグについての言及を見つけた。そのバグは、時おり一部の人が文書の印刷に失敗するということだった。その後、コメントで妻が火曜日になると印刷が出来ないと不満を漏らしていることを指摘している人がいた。

バグレポートを読むと、他のアプリケーションでは問題なく印刷できたので、OpenOfficeのバグに違いないと主張している人がいた。また、このバグは起こったり起こらなかったりすると指摘する人もいた。別のユーザーは解決策を見つけていた：OpenOfficeを一度削除して、再インストールすることだ（Ubuntuでは簡単な作業だ）。彼は木曜日に、これで印刷の問題が解決したと報告した。

その2週間後の火曜日、その解決策は結局うまく行かなかったと報告された。ほぼ4ヶ月後、あるUbuntuハッカーの妻がOpenOfficeが火曜日に印刷できないと訴えた。

この問題は「file」という*NIXプログラムに起因しているようだった。このユーティリティはファイルの種類を検出するためにパターン処理を行う。例えばファイルが %! で始まり、 PS-Adobeが続く場合、それはPostScriptファイルである。OpenOfficeは日付をPostsScriptファイルとして出力しているようだった。そして火曜日の記述形式は %%CreationDate: (Tue MMM D hh:mm ...のようになるのである。

そして、fileプログラムのパターン認識にはバグがあり、PostScriptファイルの Tueという記述がErlang JAMファイルとして認識されて、それによりプリンタに送られなかったことが推察された。

Erlang JAMファイルのファイル形式は以下の通り。

4 string Tue Jan 22 14:32:44 MET 1991 Erlang JAM file - version 4.2

これは次のようであるべきだった。

4 string Tue\ Jan\ 22\ 14:32:44\ MET\ 1991 Erlang JAM file - version 4.2

fileは1600以上のファイルとマッチングを試みるため、そのうちにこのような間違いがあっても不思議はない。このケースでは、Erlang JAMファイルとの照合をPostScriptファイルより前にマッチングしているのだ。

Bug #248619 “file incorrectly labeled as Erlang JAM file (OOo do...” : Bugs : file package : Ubuntu

死のパケット

Not Just AstLinux Stuff: Packets of Death Not Just AstLinux Stuff: Packets of Death - UPDATE

死のパケット、私がそれをそう呼ぶのは、それが言葉通りの意味だからだ。

Star2Star（訳注：かつて存在した通信企業）には、過去に2つのバージョンのオンプレミス顧客アプライアンスを構築したハードウェアOEMがあった。このアプライアンスの詳細とそれが提供していた魔術については、別の記事で詳しく説明する。今は、こいつが出していた殺人パケットについて焦点を合わせる。

約一年前、我々はこのオンプレミス機器の刷新版をリリースした。当時の機器の性能は、ムーアの法則に則りシンプルな成長をしていた。より大きく、より良く、より速く、より安く。新しいハードウェアは64ビットに対応し、8倍のRAMを搭載し、追加のローカルストレージに対応し、Intel（私が好きなイーサネットコントローラーベンダー）のギガビットイーサネットポートをを4つ備えていた。我々はこの4つのポートについて様々な用途のアイデアを持っていた（今でも持っている）。つまりかなりイケてる製品だったということだ。

この新しいハードウェアは、パフォーマンステストと機能テストを難なく突破した。スピードも信頼性も高かった。最強だ。この緻密な試験の後、我々は徐々にこのハードウェアをテストウェブサイトに展開し始めた。ご想像の通り、問題が起き始めた。

Googleを検索すると、Intel 82574Lイーサネットコントローラには少なくともいくつかの問題があることが分かる。EEPROMの問題、ASPMバグ、MSI-Xの強いクセなどなど。我々はこれに対処するのに数ヶ月を費やした。それでようやく終わったと思った。

それは甘い考えで、事態は悪化の一途を辿った。

完璧なソフトウェアイメージ（とBIOS）を開発し、デプロイしたつもりだった。しかし、それは実地による修練を積んだものではなかった。ユニットは故障し続けた。再起動することにより元に戻ることもあったが、大抵は戻らなかった。故障したということで返送されたユニットを手元でテストしてみると、なんと動作した。

いやいや、それは変じゃね？

当該機器の奇妙な挙動が続いたため、私はかなり気合を入れる必要が出てきた。ラッキーなことに、現場には非常に辛抱強く親切な再販業者が居て、私がデータを収集する間の3時間、電話を繋ぎっぱなしにしていてくれた。この顧客の場所は、なんらかのはっきりしない理由で、ネットワーク上で音声トラフィックを流すことにより、予測的にイーサネット・コントローラをダウンさせることができたのである。

今の話を少し深掘りしてみよう。イーサネットコントローラを「ダウンさせる」というのは、（言葉通り）イーサネットコントローラをダウンさせるということだ。システムとイーサネットインターフェースは正常に表示され、ランダムな量のトラフィックの後、インターフェースがハードウェアエラー（物理層と通信不可）を報告し、リンクを失う。文字通りスイッチとインターフェースのリンクランプが消灯するのだ。それは死んでいた。

こうなると、電源再投入以外の方法では復活しなかった。カーネルモジュールをリロードしたり、マシンを再起動しようとしたりすると、PCIスキャンエラーを起こす。マシンの電源を物理的に落とし、電源を入れ直すまで、インターフェースは死んだままなのである。多くの場合、我々の顧客にとって、これは駆けつけ作業だらけになることを意味した。

この非常に忍耐強い再販業者とデバッグしている間、私はインターフェースが落ちるとすぐにパケットキャプチャを停止するようになっていた。最終的に、次のパターンに気づいた。インターフェースから出る最後のパケットは100 Tryingの暫定レスポンスであり、常に同じレスポンス長だった。それだけでなく、結局、この応答を特定の電話機メーカーのINVITE応答にトレースすることになった。

私は再販業者との電話を切り、仲間をつかまえてエビデンスを披露した。金曜の午後遅くにも関わらず、全員がそれぞれの仕事に取り掛かり、このメーカーの新しいハードウェアと電話を使ったテスト構成を組み上げるために奔走した。

我々は会議室に座り、許す限り素早く電話をダイヤルした。やがて我々は、この問題を再現することに成功した。全デバイス全通話でというわけにはいかなかったが、時おりイーサネットコントローラをクラッシュさせることができた。ただ、全然うまくいかないこともあった。電源の再投入後、再試行するときちんとクラッシュした。いずれにせよ、技術的な問題を鑑別しようとしたことがある人なら誰でも知っているように、最初の課題は問題を再現することである。ようやくここまでたどり着いた。

信じて欲しいのだが、ここまでたどり着くのに本当に長く掛かったのだ。私はOSIスタックの仕組みを知っている、ソフトウェアがどのようにセグメンテーションされるか知っている、SIPパケットの中身がイーサネットアダプターに何かするはずなどないと知っている。しかしそれらの知識は何ら意味をなさなかったのだ。

私たちのデバイス上でのパケットキャプチャと、スイッチのミラーポート上でのパケットの間で、ようやく問題のパケットを分離することができた。問題があったのは送信された100 Tryingではなく、受信したINVITEだったことがわかった。ミラーポートのパケットキャプチャーは、100Tryingが回線に引っかかるのを一切観測できなかった。

今、我々はこのINVITEを観察する必要があった。おそらくユーザースペースでINVITEを処理するdaemonが問題なんじゃないだろうか。やはり送信された100 Tryingじゃないのか。同僚の一人が、SIPソフトウェアをシャットダウンして、問題が継続するかを確認してみようと提案した。SIPソフトウェアは実行されず、100 Tryingは送信されなかった。

まず、問題のパケットを送信するための方法を改良する必要があった。電話から送信されたINVITEを分離し、tcpreplayでコマンドを再生した。数ヶ月の時を経て、ようやくこれらのポートをシャットダウンする1つのパケットを特定できた。これはとてつもない進歩で、自宅に帰って家のラボで構成をいじることができるということを意味していた。

次に話を進める前に、私が見つけた素晴らしいオープンソースソフトウェアに対して敬意をここで表する。Ostinatoはあなたをパケットの忍に変えてくれる。このツールでできることは文字通り無限大で、Ostinatoがなければ私はここから先の調査を進めることが出来なかっただろう。

パケット生成のスイスアーミーナイフを片手に、私は色んなものを突き回してみた。私が見つけたのは衝撃的なものだった。

それはSIP/SDPの奇妙な挙動から始まる。以下のSDPを見ていただきたい：

v=0
o=- 20047 20047 IN IP4 10.41.22.248
s=SDP data
c=IN IP4 10.41.22.248
t=0 0
m=audio 11786 RTP/AVP 18 0 18 9 9 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:9 G722/8000
a=fmtp:101 0-15
a=rtpmap:101 telephone-event/8000
a=ptime:20
a=sendrecv

パッと見て、オーディオ要求が重複しているのは問題だ。しかしそれがイーサネットコントローラに対して影響を及ぼすはずがなかった。まぁ、少なくともイーサネットフレームが大きくなるということはあるだろうが…

だが…ちょっと待って欲しい。ここまでのパケットキャプチャで多くの成功したイーサネットフレームがあったのだ。いくつかのフレームは大きく、いくつかは小さかった。そのことに問題はない。問題のパケットをさらに深掘りする必要がある。Ostinatoの実施と電源の入れ直しを多数実施し、当該フレームにおける問題のパターンをついに分離することができた。

警告：ここから16進数の世界に入ります。

インターフェースのシャットダウンは、特定のオフセットにある特定のバイト値によって引き起こされることが分かった。ここでの特定の値とは位置 0x47f におけるhex値 32 である。16進数での 32 はASCII文字における 2 である。2という文字はどこから来ているのか？

a=ptime:20

我々のSDPは全て同一であった（当然ptimeを含む）。ソースと宛先のURIは全て同一だった。唯一の違いはCall-ID、タグ、ブランチだった。問題のパケットは、文字2がきちんとオフセット位置0x47fに並ぶように、ちょうどいい感じのCall-ID、タグ、ブランチが設定されていた。

ドーン！ちょうどいいCall-ID、タグ、ブランチを使うと、他はどんなゴミデータが入っていても、ptimeの行が正しい位置で終わる限りは、どんなパケットも殺人パケットに変える事ができた。事態はさらに奇妙なことになった。

パケットを生成している間、色々な16進数値を試行していた。この問題がこれ以上こじれることはないだろうと思ったが、そうなった。コントローラの動作は、最初に受信したパケットの特定のオフセット位置の値が、その位置と一致するかに完全に依存していることが分かった。説明すると次のようなことが起きていた：

Byte 0x47f = 31 HEX (1 ASCII) - 無影響だが「予防接種」されない
Byte 0x47f = 32 HEX (2 ASCII) - インターフェースがシャットダウンする
Byte 0x47f = 33 HEX (3 ASCII) - インターフェースがシャットダウンする
Byte 0x47f = 34 HEX (4 ASCII) - インターフェースが「予防接種」される

「無影響」というのは、パケットがインターフェースを殺すことはなかったが、インターフェースを「予防接種」することもなかったということだ（「予防接種」という言葉の意味は後で説明する）。「インターフェースがシャットダウンする」というのは、この問題に関する私の記述（「インターフェースが落ちる」）を思い出して欲しい。ここはニュアンスが難しい。

さらにテストしてみると、私が知る限りのすべてのLinuxバージョン、FreeBSDで、マシンの電源が入っているのに、ブートメディアがないと文句を言われた。これはハードウェアの問題であり、OSは関係ない。なんともはや。

Ostinatoを使ってHTTP POSTやICMP echoリクエストなど、望むものならなんでも殺人パケットの様々な変種をつくることができた。バイト値でデータを生成するように設定されたHTTPサーバ（ヘッダーやホストなどに基づく）を使えば、死のパケットを含むHTTP 200レスポンスを簡単に設定できる。すなわち、ファイアウォールの向こう側にいるクライアントマシンを殺すことができるということだ。

この問題が全体的にいかにも奇妙であることはここまでで説明した通だが、これから説明する「予防接種」はとりわけ奇妙である。最初に受信したパケットの中に1, 2, 3以外の値が含まれていると、インターフェースは死のパケット（2, 3）に対する免疫を獲得することが分かった。また、有効なptime属性は10の乗数で定義されている。Call-ID、タグ、ブランチ、IP、URIなど（このバグだらけのSDPでは）、これらの有効なptime属性は完全に整列する。マジで、どうしてこうなるの？

この問題が散発的であった理由は明らかになった。自分がこの問題の発生条件を突き止めたことに驚いている。15年ネットワークエンジニアをしているが、こんな問題にはお目にかかったことがない。後にも先にもこんなことは二度と起きないだろう。そうならないよう願っている…

Intelのエンジニア2人に連絡を取り、問題を再現するためのデモ機を送った。2週間ほど彼らと仕事を一緒にして、彼らは82574LコントローラのEEPROMに問題があると突き止めた。

彼らは新しいEEPROMとそれを書き出すツールを提供すると申し出た。残念ながら、e1000カーネルモジュールのアンロードと再ロードが必要であり、我々の環境では好まれなかったので、我々はこのツールを配布することができなかった。幸いなことに、EEPROMのレイアウトについて少し知識があれば、bashスクリプトとethtoolの魔法を使って「固定」EEPROM値を保存し、影響するシステム上に書き出すことが出来た。我々はベンダーと連絡を取り、この修正が出荷前のユニットに適用されていることを確認した。しかし、はっきりしないのは、他のIntel製イーサネットコントローラーが他にどれくらい影響を受けたのか、ということだった。

それは今後も注視していくしかないか…

Wi-Fiを殺すパレット

This one has made the rounds on reddit a few times. I shared this personal story... | Hacker News

2005年、私の職場で説明が付かない非常に深刻な問題が発生した。ハリケーンによる予定外の閉鎖の翌日、ユーザーからデータベース接続のタイムアウトに関する苦情の電話が掛かり始めた。32ノード未満の非常にシンプルなネットワークで、帯域幅も殆ど使っていなかったので、DBサーバに15～20分pingを送っても、うち2分くらいは"request timed out"となる事実を確認した時、大きな恐怖を感じた。とにかく私はパフォーマンスモニタリングなどを実施し、複数のソースからサーバにpingを打っていた。サーバー以外のほぼすべてのマシンは、問題なく他のマシンと通信できていた。スイッチの故障や接続不良などを切り分けることも試してみたが、ランダムかつ周期的に発生する障害を説明することはできなかった。

tracerouteを走らせ、様々な機器のプラグを抜き差しするのと並行して、私は同僚に倉庫内のスイッチのライトを観察するように頼んだ。トランシーバーで45～50分ほどやり取りしていたが、彼はこう言った「よし、落ちた。オーケー、また戻った」。彼に何か気づいたことはないかと尋ねた。彼は言った「ああ、気づいたよ。でもバカなことを言っていると思うかも知れないが、毎回荷主が出荷室からパレットを運び出した後2秒以内にサーバーがタイムアウトするんだ」。私は聞き返した「どういうこと…？」。彼は言った「そう、それで次の注文を処理し始めると、サーバーは復帰するんだ」。

私は荷主に駆け寄った。彼が注文の成功を祝うために巨大な磁力増幅器を接続しているのだろうと確信した。きっとフラックスキャパシタからの電磁波が時空連続体に裂け目を作り、約50メートル離れた別の部屋にあるサーバのNICカードを一時的にショートさせたのだろう…。もちろん違った。荷主がやっていたのは、ワイヤレスバーコードスキャナーで全ての箱をスキャンしながら、まず大きな箱をパレットに積み、だんだん小さな箱をその上に載せていくということだけだった。バーコードスキャナーのワイヤレス機能がDBサーバにしがみついて、他の全てのリクエストを失敗させているのだろう。違った。数回のテストの後、バーコードスキャナーのせいではないと分かった。出荷室にある無線ルーターとUPS（無停電電源装置）は正しく設定されており、どちらも正常に機能しているようだった。しかし何か原因があるはずだ。特にハリケーンで職場が閉鎖される前までは、すべてが上手く行っていたのだから。

次のタイムアウト周期が始まると、私は出荷室に駆け込んで、次のパレットを積み上げている作業員を見ていた。彼がパレットの最下段にシャンプーの大きな箱を4つ置いた瞬間、DBサーバのタイムアウトが止まった。これは黒魔術に違いない。箱を取り除いて貰うと、DBサーバーは再びタイムアウトし始めた。私はこの不条理な結果を信じられず、さらに5分間ほど箱の積み上げと積み下げを繰り返したが、結果は全く同じだった。まさにイーサネットの神にひざまずいて慈悲を乞おうとした時、出荷室に置かれている無線ルーターの高さが、パレットに置かれた4つの大きな箱の上面より30cmほど低いことに気づいた。我々はようやく手がかりを掴んだのだ！

パレットに大きな箱が積まれるたびに、ワイヤレスルータが外の倉庫との見通し線を失っていたのだ。10分後、問題は解決した。何が起きていたのかを説明するとこうだ。ハリケーンの最中、停電が起こり、UPSに接続されていない建物内の唯一の機器、すなわちオフィスにあったテスト用ルーターの設定がリセットされたのだ。テスト用ルーターのデフォルト設定は、どういうわけか出荷室にあるルーターの中継機となっていた。この2つのワイヤレスノードは、間にパレットが置かれていない時しか通信できず、通信できる場合でもシグナルは弱かった。2台のワイヤレスルーターが通信するたびに、弊社の小さなネットワークに通信ループが発生し、その結果DBサーバーへのパケットは全て失われていた。DBサーバーはメインルーターから独立したスイッチを持っており、メインルーターから一番遠いノードだった。他のほとんどのPCは同じ16ポートスイッチによって接続されていたので、それらの機器間でpingを打つ際は問題が顕在化しなかったのである。

この4時間に及ぶトラブルシューティングの悪夢を1秒で解決する方法は、テストルーターの電源を切ることである。こうしてDBサーバがタイムアウトすることは二度となかった。

ログインするために座る

所収『珠玉のプログラミング』

プログラマであれば誰もがデバッグが難しいことは知っている。優れたデバッガーはデバッグを簡単に見せることができる。取り乱したプログラマが自身が何時間も追いかけたバグについて述べると、達人はいくつかの質問をして、数分後には問題のあるコードを見据えている。デバッグの専門家は、最初に観察した挙動がどれほど不可解であったとしても、そこに論理的説明が可能であることを決して忘れない。

そのようなデバッガーの姿勢を如実に示すのがIBMのヨークタウンハイツ基礎研究所のとある逸話である。あるプログラマーが新しいワークステーションを導入した。彼が座っている時は何の問題もなく動作していたのだが、立ち上がるとシステムにログインすることができなかった。この挙動は完全に再現性があった：座っている時は必ずログインできたし、立っている時は決してログインできなかった。

このような問題に直面すると、我々のような凡人はただ傍観し驚き入るばかりである。そのワークステーションはどのようにして哀れな人々が座っているか立っているかを知るのだろう？しかしながら、良いデバッガーはそこに理由があることを理解している。電気理論をもとに仮説を立てるのが一番簡単だ。カーペットの下の配線がゆるんでいたとか、あるいは静電気的な問題が起きていたとか。しかし、電気的な問題が100%一貫した結果を返すことはまずない。用心深い同僚がついに正しい問いを発した：プログラマーが座っているときと立っている時で、ログインの仕方になにか違いはあるだろうか？手を差し出して自分で試してみよう。

問題はキーボードにあった：二つのキートップが入れ替わっていたのだ。プログラマーは座っている時はタッチタイピングしており（手元を見ないので）、この問題に気づかなかった。しかし、立っている時は一つ一つキーを見ながらタイピングするので、（キーに印字された文字に）惑わされたのだ。この手がかりと便利なスクリュードライバーを用いて、デバッガーは2つのキートップを入れ替え、すべてうまく行った。

シカゴで構築されたとある銀行システムは何ヶ月もの間正常に動作していた。しかし、国際データを初めて処理させようとした時、予期せず停止することになった。プログラマーは何日もかけてコードを調べたが、プログラムを終了させるようなコマンドは見つからなかった。更に詳しく動作を観察すると、エクアドルのデータを入力するとプログラムが終了するとわかった。更に詳しく調べると、ユーザーが首都の名前としてキト（Quito）を入力すると、プログラムはそれをquitの実行要求と解釈したのである。

ボブ・マーティンはあるシステムが「1度だけ2度動く」のを見たことがある。そのシステムは最初のトランザクションを正しく処理して、その後のすべてのトランザクションで僅かな欠陥を呈した。システムを再起動すると、最初のトランザクションは再び正しく処理され、後続のトランザクションは全て失敗した。マーティンはこの挙動を「1度だけ2度動いた」と表現したが、開発者はプログラムがロードされた時に正しく初期化され、最初のトランザクションの後に正しくリセットされなかった変数を探せばよいとすぐに認識した。

いずれのケースでも、正しい質問が賢明なプログラマーを導き、厄介なバグを迅速に解決させた。「座っている時と立っている時で何か違いはあるだろうか？それぞれの体勢でログインしているところを見せてもらっても？」「プログラムがquitする前に何を入力していたか」「プログラムが失敗し始める前に、正しく動作していたことはあるか？何回？」

リック・レモンズは、デバッグのための最高の授業はマジックショーを見たことだ、と言った。マジシャンは半ダースもの不可能トリックを実行してみせた。レモンズはそれが魔法だと信じる誘惑にかられたが、不可能は不可能ではないことを思い出し、それぞれの離れ業についての明らかな矛盾点を探っていった。彼は物理法則と呼ばれる基礎的事実から出発し、そこからそれぞれのトリックについてのシンプルな説明を導き出す。このような姿勢がレモンズを私がこれまでに見た最高のデバッガーたらしめている。

デバッグについて私が知る中で最高の本はバートン・ルーチェ『推理する医学』（Penguin, 1991）である。本書の主人公は軽度の病人から重病に侵された町まで、複雑なシステムをデバッグする。そこで用いられる問題解決手法はコンピューターシステムのデバッグに直接的に適用できる。これらの実話はフィクションに劣らない魅力を持っているのだ。

ちびっこsshだいじょばない

The little ssh that (sometimes) couldn't | Mina Naguib

まえがき

これは私がこれまでに追跡したバグハントの中で、最も興味深いものの1つを記録した技術記事である。

私が勤務するAdGear Technologies Inc.では、sshは王様である。それはサーバ管理、モニタリング、デプロイ、ログファイルの採取、イベントストリーミングに使われている。sshは堅牢であり、ネイティブunixツールとしての予測可能性があり、とにかく使えるやつだった。

ある日、sshが動作しないというcronメールが不規則に流れるようになるまでは。

タイムアウト

ロンドンDC（DC: データセンター）の中にあるマシンが、モントリオールDCの中にあるデータマシンにイベントログファイルを送信するのにランダムに失敗していた。このジョブはcronによって周期的に開始され、その失敗を以下のように晒していた：

sshが失敗したというcronメール
- 時折ハングする
- 時折タイムアウトエラーにより終了する
モントリオールでの欠落データを検出する社内のサニティチェックのために、警告監視が降りてくる

ロンドンのマシンにログインし、手動でプッシュコマンドを実行したところ、正常に動作した。一時的なネットワークパーティションとして軽く処理することにした。

タイムアウトの続発

しかし失敗は不規則に起こり続けた。日に1回、日に2、3回、金曜日の朝には1時間に数回。何かが悪化しているのは明らかだった。原因が分かるまで手動でファイルをプッシュし続けた。

ロンドンとモントリアルの間には17ホップが存在していた。レイテンシとパケットロスについてのプロファイルを作成した所、いくつかのホップで1-3%のパケットロスが発生していることが分かった。そこでロンドンDCの運用にこれらのホップをルートから外すようチケットを上げた。

ロンドンDCの運用がパケットロスを検証している間に、ロンドンからモントリオールにある第ニのデータセンターへのランダムなタイムアウトが発生した。そのデータセンターへのホップは、最初にパケットロスを観測したのと同じルートではなかった。我々は、パケットロスが主問題なのではないと結論した。同じ頃、ロンドンDCの運用はパケットロスないしタイムアウトを再現することはできず、ロンドン側から見るとすべてが健全に見えると回答した。

啓示

失敗するcronアップロードを手動で追跡しているうちに、興味深いパターンに気づいた。ファイル転送が高速に成功するか、ハングアウトないしタイムアウトしてまったく成功しないかのどちらかになる。ファイルアップロードが低速の場合、成功することはなかった。

起きている問題から余計な大量のデータを取り除き、シンプルな素のsshでシナリオを再現することができた。ロンドンのマシンで ssh mtl-machineを実行すると、即座に動作するか、ハングアップして接続が確立しないかのどちらかだった。これには驚き眉をひそめた。

パケットたちのいるところ

モントリオールにおけるsshサーバーの設定と状態について3重にチェックを行った。

サーバは全ての尺度において健全であるように見えた
sshd DNSの逆引きは有効になっていない
sshdクライアントの最大接続数は十分に大きい値である
sshサーバーは攻撃を受けていない
帯域幅の使用量は飽和しかけていた

仮にサーバーに何か問題があったとしても、モントリオールには2つのデータセンターがあり、別々にハングするのを観察していたのである（だから、サーバー側に問題があるとは考えづらい）。かてて加えて、ロンドンを除く他のデータセンターとモントリオールは問題なく通信していた。ロンドン側の何かがおかしいのである。

tcpdumpを起動し、サマリとwiresharkにロードされたキャプチャしたパケットを確認し始めた。パケットロスや再送の兆候は見られたものの、それはごくわずかに過ぎず、特に問題を引き起こすようなものではなかった。

さらにssh接続が正常に確立した場合のすべての完全な接続と、ssh接続がハングした場合の完全な接続状況をキャプチャした。

以下が、ロンドンからモントリオールへの接続がハングした時のログの論理説明である。

通常のTCPハンドシェイク
あるべきところのTCP ACKパケットを伴う、ssh特有の多数のデータ往来
ロンドンから送信され、モントリオールで受信された特定のパケット
同じパケットをロンドンから再送信し（数度再送信し）、モントリオールで受信したもの
モントリオールはそれに応答していない

なぜモントリオールが応答しないのか全く分からなかった（だからロンドンが再送したと言える）。レイヤー4プロトコルが膠着状態に陥り、この段階で接続が停止していた。さらに腹立たしいことに、ロンドン側でsshの接続試行をキルして、直ちに再実行すると、成功する確率が高い。うまく言った時には、tcpdumpはモントリオールがパケットを受信、応答し、処理は先に進んでいることを示していた。

ロンドンのsshクライアントで冗長デバッグ（-vvv）を有効にしたところ、以下のログを記録した後にハングした。

debug2: kex_parse_kexinit: first_kex_follows 0 
debug2: kex_parse_kexinit: reserved 0 
debug2: mac_setup: found hmac-md5
debug1: kex: server->client aes128-ctr hmac-md5 none
debug2: mac_setup: found hmac-md5
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP

ssh hang SSH2_MSG_KEX_DH_GEX_GROUPでググると色々な結果が出てくる――Wi-Fiが悪い、WindowsのTCPがバグっている、ルーターのバグがTCP片を破棄している――など。LAN側での1つの解決策は、通信経路のMSSを把握し、それを両終端のMTUとして設定することである。

ロンドンサーバーのMTUを1500から下げ続け、マジックナンバーである576まで下げたところでようやく糸口が掴めた。そこまで下げると、sshのハングする挙動を再現することができなくなったのである。sshループスクリプトを実行しながら、MTPUを1500に戻してタイムアプトを引き起こしたり、576に設定し直してタイムアウトの発生を消すことが必要に応じてできるようになった。

残念ながら、ロンドンサーバーはパブリックなウェブサーバーであり、グローバルにMTUを576に設定しても問題は解消しない。しかし、上述の現象はパケットの断片化ないしパケットの再構成がどこかで壊れているということを示唆していた。

tcpdumpで受信パケットを再度確認しても、断片化を示す証拠は見つからなかった。受信パケットサイズと送信パケットサイズは厳密に一致していた。もし何かが576バイト超でパケットを断片化したのであれば、他の何かがうまく再構成したのであろう。

不揃いなきらきら星

さらに掘り下げ、ヘッダーだけでなく、パケットの完全なダンプ（tcpdump -s 0 -X）を観察するようにした。sshが成功した場合とsshが失敗した場合のマジックパケットを比較すると、TCP/IPヘッダーのごく僅かな変化を除き、ほとんど違いは見られなかった。しかしながら、これ以前のパケットは十分に小さく、このパケットがTCPコネクションの中で576バイトを十分に超える最初のパケットであることは明らかだった。

同じパケットを、ハングしたパターンで、ロンドンから出たパケットをモントリオールからキャプチャしたもので比較してみると、何かが私の目に留まった。いわく言い難い微妙な違いで、私はそれを疲労として受け流したが（金曜の深夜だった）、何度かリフレッシュして見直してみた結果、案の定それが考え過ぎではなかったことが分かった。

以下が（IPアドレスを特定する最初の数バイトを除いた）ロンドン発のパケットである：

0x0040:  0b7c aecc 1774 b770 ad92 0000 00b7 6563  .|...t.p......ec
0x0050:  6468 2d73 6861 322d 6e69 7374 7032 3536  dh-sha2-nistp256
0x0060:  2c65 6364 682d 7368 6132 2d6e 6973 7470  ,ecdh-sha2-nistp
0x0070:  3338 342c 6563 6468 2d73 6861 322d 6e69  384,ecdh-sha2-ni
0x0080:  7374 7035 3231 2c64 6966 6669 652d 6865  stp521,diffie-he
0x0090:  6c6c 6d61 6e2d 6772 6f75 702d 6578 6368  llman-group-exch
0x00a0:  616e 6765 2d73 6861 3235 362c 6469 6666  ange-sha256,diff
0x00b0:  6965 2d68 656c 6c6d 616e 2d67 726f 7570  ie-hellman-group
0x00c0:  2d65 7863 6861 6e67 652d 7368 6131 2c64  -exchange-sha1,d
0x00d0:  6966 6669 652d 6865 6c6c 6d61 6e2d 6772  iffie-hellman-gr
0x00e0:  6f75 7031 342d 7368 6131 2c64 6966 6669  oup14-sha1,diffi
0x00f0:  652d 6865 6c6c 6d61 6e2d 6772 6f75 7031  e-hellman-group1
0x0100:  2d73 6861 3100 0000 2373 7368 2d72 7361  -sha1...#ssh-rsa
0x0110:  2c73 7368 2d64 7373 2c65 6364 7361 2d73  ,ssh-dss,ecdsa-s
0x0120:  6861 322d 6e69 7374 7032 3536 0000 009d  ha2-nistp256....
0x0130:  6165 7331 3238 2d63 7472 2c61 6573 3139  aes128-ctr,aes19
0x0140:  322d 6374 722c 6165 7332 3536 2d63 7472  2-ctr,aes256-ctr
0x0150:  2c61 7263 666f 7572 3235 362c 6172 6366  ,arcfour256,arcf
0x0160:  6f75 7231 3238 2c61 6573 3132 382d 6362  our128,aes128-cb
0x0170:  632c 3364 6573 2d63 6263 2c62 6c6f 7766  c,3des-cbc,blowf
0x0180:  6973 682d 6362 632c 6361 7374 3132 382d  ish-cbc,cast128-
0x0190:  6362 632c 6165 7331 3932 2d63 6263 2c61  cbc,aes192-cbc,a
0x01a0:  6573 3235 362d 6362 632c 6172 6366 6f75  es256-cbc,arcfou
0x01b0:  722c 7269 6a6e 6461 656c 2d63 6263 406c  r,rijndael-cbc@l
0x01c0:  7973 6174 6f72 2e6c 6975 2e73 6500 0000  ysator.liu.se...
0x01d0:  9d61 6573 3132 382d 6374 722c 6165 7331  .aes128-ctr,aes1
0x01e0:  3932 2d63 7472 2c61 6573 3235 362d 6374  92-ctr,aes256-ct
0x01f0:  722c 6172 6366 6f75 7232 3536 2c61 7263  r,arcfour256,arc
0x0200:  666f 7572 3132 382c 6165 7331 3238 2d63  four128,aes128-c
0x0210:  6263 2c33 6465 732d 6362 632c 626c 6f77  bc,3des-cbc,blow
0x0220:  6669 7368 2d63 6263 2c63 6173 7431 3238  fish-cbc,cast128
0x0230:  2d63 6263 2c61 6573 3139 322d 6362 632c  -cbc,aes192-cbc,
0x0240:  6165 7332 3536 2d63 6263 2c61 7263 666f  aes256-cbc,arcfo
0x0250:  7572 2c72 696a 6e64 6165 6c2d 6362 6340  ur,rijndael-cbc@
0x0260:  6c79 7361 746f 722e 6c69 752e 7365 0000  lysator.liu.se..
0x0270:  00a7 686d 6163 2d6d 6435 2c68 6d61 632d  ..hmac-md5,hmac-
0x0280:  7368 6131 2c75 6d61 632d 3634 406f 7065  sha1,umac-64@ope
0x0290:  6e73 7368 2e63 6f6d 2c68 6d61 632d 7368  nssh.com,hmac-sh
0x02a0:  6132 2d32 3536 2c68 6d61 632d 7368 6132  a2-256,hmac-sha2
0x02b0:  2d32 3536 2d39 362c 686d 6163 2d73 6861  -256-96,hmac-sha
0x02c0:  322d 3531 322c 686d 6163 2d73 6861 322d  2-512,hmac-sha2-
0x02d0:  3531 322d 3936 2c68 6d61 632d 7269 7065  512-96,hmac-ripe
0x02e0:  6d64 3136 302c 686d 6163 2d72 6970 656d  md160,hmac-ripem
0x02f0:  6431 3630 406f 7065 6e73 7368 2e63 6f6d  d160@openssh.com
0x0300:  2c68 6d61 632d 7368 6131 2d39 362c 686d  ,hmac-sha1-96,hm
0x0310:  6163 2d6d 6435 2d39 3600 0000 a768 6d61  ac-md5-96....hma
0x0320:  632d 6d64 352c 686d 6163 2d73 6861 312c  c-md5,hmac-sha1,
0x0330:  756d 6163 2d36 3440 6f70 656e 7373 682e  umac-64@openssh.
0x0340:  636f 6d2c 686d 6163 2d73 6861 322d 3235  com,hmac-sha2-25
0x0350:  362c 686d 6163 2d73 6861 322d 3235 362d  6,hmac-sha2-256-
0x0360:  3936 2c68 6d61 632d 7368 6132 2d35 3132  96,hmac-sha2-512
0x0370:  2c68 6d61 632d 7368 6132 2d35 3132 2d39  ,hmac-sha2-512-9
0x0380:  362c 686d 6163 2d72 6970 656d 6431 3630  6,hmac-ripemd160
0x0390:  2c68 6d61 632d 7269 7065 6d64 3136 3040  ,hmac-ripemd160@
0x03a0:  6f70 656e 7373 682e 636f 6d2c 686d 6163  openssh.com,hmac
0x03b0:  2d73 6861 312d 3936 2c68 6d61 632d 6d64  -sha1-96,hmac-md
0x03c0:  352d 3936 0000 0015 6e6f 6e65 2c7a 6c69  5-96....none,zli
0x03d0:  6240 6f70 656e 7373 682e 636f 6d00 0000  b@openssh.com...
0x03e0:  156e 6f6e 652c 7a6c 6962 406f 7065 6e73  .none,zlib@opens
0x03f0:  7368 2e63 6f6d 0000 0000 0000 0000 0000  sh.com..........
0x0400:  0000 0000 0000 0000 0000 0000            ............

以下がモントリオールに届いた同じパケットである：

0x0040:  0b7c aecc 1774 b770 ad92 0000 00b7 6563  .|...t.p......ec
0x0050:  6468 2d73 6861 322d 6e69 7374 7032 3536  dh-sha2-nistp256
0x0060:  2c65 6364 682d 7368 6132 2d6e 6973 7470  ,ecdh-sha2-nistp
0x0070:  3338 342c 6563 6468 2d73 6861 322d 6e69  384,ecdh-sha2-ni
0x0080:  7374 7035 3231 2c64 6966 6669 652d 6865  stp521,diffie-he
0x0090:  6c6c 6d61 6e2d 6772 6f75 702d 6578 6368  llman-group-exch
0x00a0:  616e 6765 2d73 6861 3235 362c 6469 6666  ange-sha256,diff
0x00b0:  6965 2d68 656c 6c6d 616e 2d67 726f 7570  ie-hellman-group
0x00c0:  2d65 7863 6861 6e67 652d 7368 6131 2c64  -exchange-sha1,d
0x00d0:  6966 6669 652d 6865 6c6c 6d61 6e2d 6772  iffie-hellman-gr
0x00e0:  6f75 7031 342d 7368 6131 2c64 6966 6669  oup14-sha1,diffi
0x00f0:  652d 6865 6c6c 6d61 6e2d 6772 6f75 7031  e-hellman-group1
0x0100:  2d73 6861 3100 0000 2373 7368 2d72 7361  -sha1...#ssh-rsa
0x0110:  2c73 7368 2d64 7373 2c65 6364 7361 2d73  ,ssh-dss,ecdsa-s
0x0120:  6861 322d 6e69 7374 7032 3536 0000 009d  ha2-nistp256....
0x0130:  6165 7331 3238 2d63 7472 2c61 6573 3139  aes128-ctr,aes19
0x0140:  322d 6374 722c 6165 7332 3536 2d63 7472  2-ctr,aes256-ctr
0x0150:  2c61 7263 666f 7572 3235 362c 6172 6366  ,arcfour256,arcf
0x0160:  6f75 7231 3238 2c61 6573 3132 382d 6362  our128,aes128-cb
0x0170:  632c 3364 6573 2d63 6263 2c62 6c6f 7766  c,3des-cbc,blowf
0x0180:  6973 682d 6362 632c 6361 7374 3132 382d  ish-cbc,cast128-
0x0190:  6362 632c 6165 7331 3932 2d63 6263 2c61  cbc,aes192-cbc,a
0x01a0:  6573 3235 362d 6362 632c 6172 6366 6f75  es256-cbc,arcfou
0x01b0:  722c 7269 6a6e 6461 656c 2d63 6263 406c  r,rijndael-cbc@l
0x01c0:  7973 6174 6f72 2e6c 6975 2e73 6500 0000  ysator.liu.se...
0x01d0:  9d61 6573 3132 382d 6374 722c 6165 7331  .aes128-ctr,aes1
0x01e0:  3932 2d63 7472 2c61 6573 3235 362d 6374  92-ctr,aes256-ct
0x01f0:  722c 6172 6366 6f75 7232 3536 2c61 7263  r,arcfour256,arc
0x0200:  666f 7572 3132 382c 6165 7331 3238 2d63  four128,aes128-c
0x0210:  6263 2c33 6465 732d 6362 632c 626c 6f77  bc,3des-cbc,blow
0x0220:  6669 7368 2d63 6263 2c63 6173 7431 3238  fish-cbc,cast128
0x0230:  2d63 6263 2c61 6573 3139 322d 6362 632c  -cbc,aes192-cbc,
0x0240:  6165 7332 3536 2d63 6263 2c61 7263 666f  aes256-cbc,arcfo
0x0250:  7572 2c72 696a 6e64 6165 6c2d 6362 7340  ur,rijndael-cbs@
0x0260:  6c79 7361 746f 722e 6c69 752e 7365 1000  lysator.liu.se..
0x0270:  00a7 686d 6163 2d6d 6435 2c68 6d61 732d  ..hmac-md5,hmas-
0x0280:  7368 6131 2c75 6d61 632d 3634 406f 7065  sha1,umac-64@ope
0x0290:  6e73 7368 2e63 6f6d 2c68 6d61 632d 7368  nssh.com,hmac-sh
0x02a0:  6132 2d32 3536 2c68 6d61 632d 7368 7132  a2-256,hmac-shq2
0x02b0:  2d32 3536 2d39 362c 686d 6163 2d73 7861  -256-96,hmac-sxa
0x02c0:  322d 3531 322c 686d 6163 2d73 6861 322d  2-512,hmac-sha2-
0x02d0:  3531 322d 3936 2c68 6d61 632d 7269 7065  512-96,hmac-ripe
0x02e0:  6d64 3136 302c 686d 6163 2d72 6970 756d  md160,hmac-ripum
0x02f0:  6431 3630 406f 7065 6e73 7368 2e63 7f6d  d160@openssh.c.m
0x0300:  2c68 6d61 632d 7368 6131 2d39 362c 786d  ,hmac-sha1-96,xm
0x0310:  6163 2d6d 6435 2d39 3600 0000 a768 7d61  ac-md5-96....h}a
0x0320:  632d 6d64 352c 686d 6163 2d73 6861 312c  c-md5,hmac-sha1,
0x0330:  756d 6163 2d36 3440 6f70 656e 7373 782e  umac-64@openssx.
0x0340:  636f 6d2c 686d 6163 2d73 6861 322d 3235  com,hmac-sha2-25
0x0350:  362c 686d 6163 2d73 6861 322d 3235 362d  6,hmac-sha2-256-
0x0360:  3936 2c68 6d61 632d 7368 6132 2d35 3132  96,hmac-sha2-512
0x0370:  2c68 6d61 632d 7368 6132 2d35 3132 3d39  ,hmac-sha2-512=9
0x0380:  362c 686d 6163 2d72 6970 656d 6431 3630  6,hmac-ripemd160
0x0390:  2c68 6d61 632d 7269 7065 6d64 3136 3040  ,hmac-ripemd160@
0x03a0:  6f70 656e 7373 682e 636f 6d2c 686d 7163  openssh.com,hmqc
0x03b0:  2d73 6861 312d 3936 2c68 6d61 632d 7d64  -sha1-96,hmac-}d
0x03c0:  352d 3936 0000 0015 6e6f 6e65 2c7a 7c69  5-96....none,z|i
0x03d0:  6240 6f70 656e 7373 682e 636f 6d00 0000  b@openssh.com...
0x03e0:  156e 6f6e 652c 7a6c 6962 406f 7065 6e73  .none,zlib@opens
0x03f0:  7368 2e63 6f6d 0000 0000 0000 0000 0000  sh.com..........
0x0400:  0000 0000 0000 0000 0000 0000            ............

パッと見て違いが分かるだろうか？もし分からなくても責めたりしないので安心して欲しい。それぞれの文字列をテキストエディタにコピーして、画面を前後に素早く切り替えていくつかの文字列が踊るのを確認してみよう。vimdiffで比較してみると以下のようになる。

vimdiff_packets

おやおやおや。これはパケットロスではない。これはパケット破損である！非常に微妙な、しかし非常に予測可能なパケット破損である。

興味深い点について注を付す：

パケットの下位部分（<576バイト）は影響を受けない
影響を受けている箇所は、毎16バイトの15バイト目であり予測的に破損している
破損の仕方には法則がある。すべてのhがxになり、すべてのcがsになる。

読者の中にはすでにASCIIコード表を確認して答えにたどり着いた人がいるかも知れない：どこかで1で固定されているビット桁が1つ存在するのである。4桁目のビットを1に反転させると、上記の左側の文字を必ず右側の文字に変換することができる。

我々の管理下にある明らかに疑わしいもの（NICカード、受信マシン）は、これまでに観察された失敗のパターン（複数のロンドンサーバー→複数のモントリオールデータセンターやサーバー）より容疑者から外れる。ロンドンに近い上流に何か原因があるはずである。

検証作業に戻ると、さまざまな物事の辻褄が合ってきた。tcpdumpのverboseモード（tcp cksum bad）で以前は見逃していた小さなヒントに気づいた。このパケットを受信したモントリオールのサーバーは、パケットが破損していることに気づくと、それをカーネルレベルで破棄しユーザーランドのsshデーモンに渡していなかった。ロンドン側はパケットを再送し、同様にして破損したパケットを渡し、モントリオールでは同様に無言の破棄を行う。sshとsshdの視点で見ると、接続は膠着状態である。tcpdumpの視点から見ると、パケットロスは存在せず、モントリオールのサーバーはデータを単に無視しているように見えた。

この発見をロンドンDCの運用に送ったところ、数分でアウトバウンドルートが劇的に変更された。最初のルーターホップから、その後のほとんどのホップまで変わった。そしてハングアップの問題は消失した。

金曜深夜にバグを修正するのは心地よい。問題とサポートスタッフを週末に持ち越さずに済み、リラックスできるからだ :)

ウォーリーをさがせ

我々はこの問題にもはや悩まされることがなくなり、システムがバックログに追いついたことに満足していた。私は実際にパケット破損の原因となったデバイスを見つける腕試しをしてみることにした。

ロンドンのルートが古い経路を通らないように更新され、問題を簡単に再現することができなかった。私は、モントリオールでロンドンから古いルートでアクセスできるFreeBSDマシンを持っている友人がいないか訪ねて回った。

次に、sshとは関係なしにパケット破損が予測的に発生することを確認したかった。これはいくつかのパイプ処理を組み合わせることで簡単に示すことができた。

モントリオールでは以下のようにする：

nc -l -p 4000 > /dev/null

それからロンドンでは以下のようにする：

cat /dev/zero | nc mtl 4000

繰り返しになるが、ランダムな要因を考慮し、リトライループを設定している。すると、以前の結論を支持するパケットを得ることができた。以下はその結果の一部である。送信したのは単なるヌル（ゼロ）のストリームであることに注意：

0x0210  .....
0x0220  0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0230  0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0240  0000 0000 0000 0000 0000 0000 0000 0000 ................
0x0250  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0260  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0270  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0280  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0290  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x02a0  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x02b0  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x02c0  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x02d0  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x02e0  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x02f0  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0300  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0310  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0320  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0330  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0340  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0350  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0360  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0370  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0380  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x0390  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x03a0  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x03b0  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x03c0  0000 0000 0000 0000 0000 0000 0000 1000 ................
0x03d0  0000 0000 0000 0000 0000 0000 0000 0000 ................
0x03e0  .....

バグが再現されたので、経路に沿った17ホップのうち、どれがパケットを破損させているのか切り分ける方法が必要だった。それぞれのホップに属するクラスタのプロバイダーを呼びつけてシステムのチェックを依頼するなどということはできない。

そこで、各ルーターに徐々にpingを打つのがベストな方法に思えた。576バイトを十分に超えるICMPパケットを、データをNULL埋めして手作りした。そして、ロンドンからモントリオールのマシンにpingした。

パケットは完全に正常に戻ってきた。破損はなかった。

速度・パディング・サイズ、あらゆるバリエーションを試したが、無駄だった。返ってきたICMP pingパケットに破損は見られなかった。

netcatのパイプをTCPからUDPに置き換えてみた。しかしながら、パケットの破損は起きなかった。

パケットの破損を再現するにはTCPである必要があり――TCPは2つのエンドポイントが必要なのである。私はすべての17ルーターホップに対して直接話せるオープンなTCPポートがあるか無駄に試してみたが、失敗に終わった。

外部の人間が問題のデバイスを突き止める方法はないように思えた…

鏡よ鏡

パケット破損が発生したか否かを検出するには、以下のシナリオのうちいずれかが必要となる：

宛先側でパケットを調査するために、会話中のTCPピアを制御する必要がある
- TCPチェックサムが失敗するとパケットが届かなくなるユーザーランドだけでなく、root + tcpdumpで到着したパケットを調査する
受信したデータをミラーバックするエコーサーバーとして動作するTCPピア。送信ノードでデータを調査し、そこで破損を検出できる

ふと、2つ目のシナリオにおけるデータが利用できることに思い当たった。考えてみて欲しい：この問題の最初の兆候として、sshクライアントがパケットを破損させるホップを介してsshサーバと通信する際にハングアップするという観察があった。これは能動的にechoシグナルを飛ばす代わりに使える、優れた受動的シグナルである。

そしてインターネットには多くのオープンsshサーバーがあり、我々の調査の助けになってくれる。

これらのサーバーを利用するのにアカウントは不要だ――ssh接続をキックスタートして、暗号交換フェーズが成功するかハングアップするか確認するだけでいい（もちろんパケット破損の発生のランダム性を考慮して適当な回数リトライする必要があるが）

こうして以下の計画が立案された：

素晴らしいnmapを使い（特に、ランダムIPモード）、地理的に分散したオープンsshサーバーのリストを作成する
各サーバーをテストして以下のように分類する
- 無応答・予測不能・ファイアウォール化されている場合：無視する
- N回のリトライの後、正常に通信できた："good"とマークする
- N回のリトライの後、秘密交換のフェーズでハングする："bad"とマークする
"good"および"bad"とマークされたサーバーについて、それらへのtracerouteの結果を覚えておく

これは次のようなアイデアに基づいている："bad"とマークされたサーバーは、tracerouteでいくつかのホップを共有するだろう。そしてその疑わしいホップの集合から、"good"のtracerouteで現れたホップの集合を差し引く。うまくいけば、1つか2つ程度のホップが残るだろう。

上記の手順を1時間ほどかけて行った後、データの調査を終えた。16台のサーバーが"BAD", 25台のサーバーが"GOOD"と分類された。

最初の課題は"BAD"サーバーのすべてのtracerouteに現れるホップのリストを見つけることだった。データをきれいに整理すると、偽陽性の結果を除くために"GOOD"リストを作成する必要はないことに気づいた。"BAD"リストだけを見ても、すべての"BAD"サーバーに共通するホップは1つだけしか残っていなかった。

参考までに、対象となるプロバイダーは2社あった：ロンドン→Nホップ目の「上流1」→Yホップ目の「上流2」

Yホップ目の「上流2」――「上流1」と「上流2」の間のエッジで、ランダムなTCPパケットの破損、多くのリトライ、そして、プロトコルの論理的な行き来に依存するハングアップ、あるいは伝送速度の低下が起こっていたのだ。この通信経路の不調により通信が切断されたテレフォニープロバイダーがいるかもしれないし、顧客やセールスを失った小売業者がいるかもしれないし、（与えた損害について）可能性は尽きないと言えるだろう。

私はロンドンDCの運用に当該シングルホップのIPアドレスを報告した。うまくいけば上流1にエスカレーションしてこの問題を修正してくれるかもしれない。

/filed under crazy devops war stories

更新

「上流1」を通じて、私が指摘したホップ（「上流2」の最初のホップ）が内部で「管理モジュールの故障」を起こし、BGPと二つの内部ネットワーク間のルーティングに影響していることを確認した。故障したモジュールの交換を受け取るまで、そのルートはまだダウンしている（回避ルーティングは行っている）。

ロック・ミュージック・フィルター

Well, while we're at it, here's my crazy MTU-related war story, although not as ... | Hacker News

（The little ssh that (sometimes) couldn'tを受けてのHNコメント）

よし、ついでに、ここまでクレイジーではないものの、私のクレイジーなMTU戦記について紹介しよう。

LAN上で動作するオーディオストリーミングアプリのユーザーとトラブルシューティングしていた時の話だ。そのユーザーはクラシック音楽のストリーミングはできたがロック音楽はストリーミングできなかった。嘘じゃないよ。クラシックは問題なく再生できるのに、ロックをストリーミングすると、数分後に接続断が起きるのである。

アプリケーションは音楽のチャンクを取り、可逆圧縮を行い、各チャンクを別々のUDPパケットで相手側に送信していた。LAN環境では一般的にIPv6のほうが信頼性が高いため、可能な限りIPv6の利用を試みていたが、必要であればIPv4を喜んで使っていた。

ユーザーと膨大な量のトラブルシューティングを行ったり来たりしながら、ようやく原因を突き止めた。彼はネットワークインターフェースのMTUを1200バイトに設定していたのだ。IPv6は1280バイト以下のMTUではIPレベルでの自動フラグメント化を行わないため、大きなパケットを送信できなかったのである。ストリーミングアプリケーションが1200バイトより大きなパケットを送信しようとするとエラーになり、接続が抜けてしまっていたのだ。

なぜロック音楽だけに限りこの問題が起きたのか？それは、単純な理由であることが分かった。可逆圧縮コーデックは必然的に可変ビットレートであり、クラシック音楽はロック音楽より圧縮率が高くなる。クラシックをストリーミングする時は、オーディオの各チャンクは1200バイト以下に圧縮され、ロック音楽では時おり1200バイトを超えるパケットが発生していた。

そのユーザーはMTUが低い理由を把握しておらず、低くする必要も特になかったため、MTUを上げ直してすべてがうまくいった。

完全にUSBの問題

[deleted by user] : programming

私は大学卒業後すぐに就職し、公開5ヶ月前の家電機器開発に携わっていた。そのデバイスはLinuxで動いており、私がカーネル空間をいじくり回すという発想に慣れていなかった頃、みんなでバグをトリアージするための会議に引きずり込まれた。たくさんのバグ、本当に数多くのバグがあった。どれも「ありえない、どうしてこうなった？」と言いたくなるようなものばかりだった。

「メモリ破壊だ」と彼らは叫んだ。「いやいや、バグを直そうよ」と私は思った。クラッシュダンプを見ると…なんじゃこりゃ？標準ライブラリ関数を使って2つの文字列を連結している間に、プログラムが不正な命令を実行している。ふーむ、こいつは妙だな…次のログ：スワップ領域がないデバイスでスワップからページを取得できなかった（なぜ取得できないのかすぐわかった）。

よしよし。金曜日の午後に短いプログラムを書いた。このプログラムはシステムRAMの80%で1つの配列割り当てを行い、連続した整数を書き込む。そしてそれはEnterキーの打ち込みを待ちうけており、配列の内容にまだ書き込みを行っているかを確認する。ロードしてプログラムを実行してみる。30秒ほど待機し確認する。いや、問題なし。さらに何度か繰り返す。ハハ、やっぱりメモリ破壊なんか起きてないじゃん。最後にデバッグケーブル（USB）を素早く10秒ほど抜き、それから差し込むということを何度かやってみた。バン！90エラー。

マジかよ…

わかったわかった。なのでUSBポート周りをいじり回し、動くようにした。これはUSBに関連するバグなのか？しかしUSBドライバが魔法のビットエラーをランダムにまき散らす「マジックビットフェアリーアルゴリズム」を実装しているようには思えない。ということは、ハードウェアに原因が？それもないだろう。しかし我々はこのデバイスのUSBポートに15,000ボルト静電気銃を使ってあらゆる薄汚い検証をすることを止めなかった。ずっと前に別の製品開発に移っていたハードウェアエンジニアたちは、この問題で頭を掻きむしるために引き戻された。ハードウェアが本当に、本当に、本当に頑健であることを示すのにどれほどの時間を無駄にしたか、私は正確に覚えていない。接地は問題なし、電圧は安定している、クロックは時間通りに時を刻み、DDRラインのレイアウトは涙がちょちょぎれるほど美しかった。

ハードウェアチームがテストしていたデバイスはどんどん不安定になっていた。私の推測では、デバイスがメモリに何かをロードし、ビットエラーが発生し、それをおそらく間違った箇所のフラッシュドライブにflushして戻す。（ページテーブルがしばしば破損しており、ファイル追跡構造も同様に破損していた可能性は否定できない。コンテンツが間違った箇所に書き込まれ、ファイルシステム構造が壊れた可能性がある）。時間の経過とともにこれらのデバイスは安定的にブートできないほど品質が低下し始めた。あるハードウェアエンジニアがついに決心し、ラップトップのなかで塩漬けにしていたイメージを使って、ファームウェアをリセットした。そのイメージは比較的古いものだった。

「おい、こいつはソフトウェアの問題だ」

「マジで？？ビットフェアリーなんて書いてないんだが？」彼は3ヶ月前の古いソフトウェアビルドをフラッシュし、問題は消え失せた。この時点で、多くの人々を長々と的外れな骨折り損へと導いた責任を感じ、夜通し残ってここ数ヶ月分のパッチをバイナリ探索した（OS全体に渡るフルソフトウェアビルドは思ったより全然時間が掛かるため…）

それで、結局マジックパッチはどれだったのか？我々が評価中のチップのドライバをカーネルに追加した人がいた。このチップはデバイスに搭載されなかった。よし！魔女を見つけたぞ！火炙りだ！

この時点で多くの人がミッション達成を宣言した。リリースを間近に控え、彼らはシンプルに退歩したのち前進するためのパッチを絞り込めたことを喜んでいた。我々は極端な予断を持ってパッチを差し戻し、イメージをビルドし、テストを実施し、すべて順調だった。そこから数日以内に同じ欠陥がカーネルに再導入されたことを知るべくもなく…

だがちょっと待って欲しい。もしチップが我々のボードに搭載されていないなら、ドライバはどうやって我々をめちゃくちゃにしたのだろう。lsmodを実行してみたが、ドライバはロードされていない…。「よしわかった。モジュールファイルを削除して再起動してみよう。ちょっと待って、エラーが起き続けている。それはおかしい…」

一体何が起きているのだろうか。

私はパッチを深く観察し始めた。それはチップベンダーが提供してきた素敵な10,000行のCファイルだった。これをカオスと呼ぶのはあまりに寛大に過ぎるだろう。（彼らの名誉のために言うと、彼らは数週間後よりまともなドライバを提供してきた）。それを少し覗いた後、私は「ビット演算のたのしみ」のような複雑な実装はないと結論づけた。では他に何があったのか？ 5行のコードから派生した48バイトの構造体、ブートストラップファイルの中の非常に小さな構造体が、このチップをどのバス・アドレスで見つけるか示していた。大量のドライバを削除し、この構造体は残した。それでも問題はまだ残存していた。

というわけで、少年少女のみなさん、これはアラインメントの問題になった。どうしたことか、48バイトの構造体を残しておくと、メモリ上で何かが移動してそれが問題を引き起こすようなのだ。私はそのファイルに32ビットより大きく64バイトより小さいデータを入れると問題が起きるところまで絞り込んだ。この範囲を突き止めたところで本当に問題が解決したわけではなかったが、その時は生産的なことをしていると感じていた。

カーネルビルドにおいてはSystemp.mapという整ったファイルが出力される。これはカーネルにコンパイルされたすべての変数が、カーネル仮想アドレス空間のどこにあるかをリストしたものだ。.dataセクションの半ばで48バイトの小さな構造体を発見した。.dataセクションは初期化された変数で満たされており、カーネルのバイナリがRAMに展開されると、コンパイルされたイメージからそれらの変数で埋められる。System.mapをガイドとして用い、かなり行き当たりばったりなバイナリ検索を実装した。これは結局、様々なCファイルのリンカ順序をバイナリ検索することに行き着いた。比較すべき変数を確認し、カーネル内のどのファイルにそれが含まれるか見つけ、そのランダムなファイルの隣に48バイトのマジック構造体を置いて、問題が再現可能か否かを確認してみた。

この探索は.dataの最後の数要素まで到達したが、何の成果も得られなかった。問題は初期化された変数メモリには存在しなかったのである。System.mapをさらに下へスクロールすると、私が無視していたセクション全体――.bssセクションという初期化されていない変数が格納されている領域――があることに気づいた。前回の失敗から学び、まず頭とお尻をテストしてみた。案の定、未初期化の変数を最初に置くと問題が発生し、セクションの最後に置くと問題は起きなかった。犯人を見つけるのは時間の問題だった。問題の原因となった変数の動きは…

関数ポインタ？？

いったいどうしたら関数ポインタのアラインメントが我々のシステムの停止に関わっているというのだろう。ARMではアラインされていないアクセスからワードを読み込むことはできない。すなわち、32ビット変数はすべて4で割り切ることが可能なメモリ・アドレスに配置する必要がある。これは関数ポインタにおいても何も変わらないはずで、常に最小値を取っているはずだ。実際、問題のケースにおいては、アドレスは64以上の2のべき乗で割り切れるものだった。それ未満なら問題は起きない。ポインターのアラインメントがあまりに良すぎたのである。

ポインタのアラインメントが良くて良すぎるということはありえない。少なくともこのバグが起きるまではそうではなかった。

しかしこの関数ポインタはあなたの信頼しているようなポインタではなかった。こいつはどこか特別なところを指していたのである。CPUの中にはSRAMという領域があり、さまざまなブートストラップ時の用途として、RAMが使用できないときに利用する。待機時の電力を節約するため、我々はSRAMにルーチンをコピーし、この特別な関数ポインタでポイントして、必要時にそれを呼び出す。このルーチンは何をするのか？このルーチンの元となったアセンブリファイルを見てみよう。当時、私はARMアセンブリのプロではなかったが、書いてあるコメントは十分に傾聴に値するものだった。

// Calculate the address of a memory mapped control register
// メモリマップコントロールレジスタのアドレスを計算する
...
...
// Now we turn off the memory controller and put the LPDDR into self refresh mode
// メモリコントローラーをオフにし、LPDDRをセルフリフレッシュモードにする

待て。こいつは何をしているんだ？基本的なレジスタ操作を行ってからメモリコントローラをオフにするまで、かなり性急ではないだろうか。私はこのルーチンを書いたベンダーに、書き忘れたステップがあるのではないかと質問するメールを送った。

彼らの回答（3日後）は「確かに。そこには間違いなくメモリバリアを書く必要があったわ」というものだった。L2キャッシュの構造の性格上、64で割り切れるメモリアドレスに書き込みを行った時に、特別なTLBのメンテナンスが必要であることが分かった。このようなケースでは、コントローラをオフにしてもRAMを依然として使用していることになる。

ほとんどの変数に最低4バイトのアラインメントが要求され、最後に書き込まれるのが64バイト以上であることはないということを考えると、コンパイルするたびに1/16の確率で完全に使えないシステムが生まれていたことになる。

最終的に製品はメモリ・バリアがある状態で出荷され、極めて盤石な、顧客に愛されるものとなった。

ところで、最初の疑問について答えを与えると、USBを利用している間は低電力状態に移行できないため、USBケーブルを接続している時はこの問題は起こらなかったのである。これは完全にUSBの問題である。

間違ったエラーメッセージ

WebTV Anecdotes

1996年9月17日の深夜、WebTVサービスがオンラインになる予定の前日、わたしたちのグループ（リック・デイリ、レナート・レーヴストランド、私（アンディ・マクファデン）、おそらくアーノルド・デ・レオン、およびその他数人の私が覚えていない人々）が、パロアルトのアルマ通り275番地にある運用センターに集合していた。ネットワーク運用とサービスソフトウェアエンジニアが公式なWebTV立ち上げの証人となるために集っていた。

時が来ると、ネット運用の一人であるブライス・ジャスマーがWebTVボックスで登録手続きを開始した。どんなオンラインサービスでもそうだが、良いユーザー名はすぐ取られてしまうので、一般ユーザーらがそれをサインアップする前に登録するのが重要だった。それに、本番のサービスに登録した最初の人物になることは、何かイケてる感じがすることだった。この日までに作られたアカウントは、全て使い捨てのテストアカウントだったから。

我々のうち数人は、期待と寝不足にめまいを感じながら、彼がタイピングするのを見ていた。彼は名前、住所、そしてその他個人情報を入力し、ユーザー名を入力していた。これはメールアドレスとして使われる名前である。彼は jazz と入力したので、メールアドレスは jazz@webtv.net となった。ワイヤレスキーボードのEnterキーを押すと、エラーダイアログが立ち上がったことを示すドゥン！という音が聞こえた。全員がスクリーンに目を向けた。

何が起きたのか理解するためには、サービスの挙動について少し理解しておくことが重要だ。WebTVは家族志向のサービスであり、すべてのユーザー名を始めとするその他外部から見える機能について下品な表現がないことをスクリーニングする必要があった。ありとあらゆる表現を補足することは不可能だが、あからさまなものを捕らえることは難しいことではない。

ユーザー名は正規表現のセットと比較された。正規表現でそれぞれのパターンと突き合わせることができる。例えば fu.*bar は fu で始まり bar で終わる全ての文字列にマッチする。注意深く選定されたパターンを用いて、shitake や matsushita のような下品な言葉が単語中に埋め込まれた単語は受諾しつつ、あからさまな単語だけを補足して拒否することができる。

同様の仕組みは postmaster, root, admin, help というような禁止名をユーザーが選ぶことを防ぐのにも使われた。それは以下のようなテキストファイルで管理していた：

admin.*
User names may not start with "admin".
postmaster
You're not the postmaster.
poop
That's a bad word.
weenie
That's a bad word.

各エントリは2行からなっている。1行目はマッチする正規表現であり、2行目はユーザーに表示されるエラーメッセージである。サービスはこのファイルを読み込み、2行ずつデータを取り込み、ユーザー名が入力されるとそれをすべての正規表現と比較する。何かマッチすれば最初にマッチした行のエラーメッセージが表示される。何もマッチしなかった場合、ユーザー名は受諾される。

ファイルを読み込むコードはコメント行をスキップする方法を知っていたが、空行を特別扱いはしなかった。

誰かが下品な表現を含むファイルに変更を加え、その際に予約名の終わりと汚い言葉の前に空白行を1行追加していたのだ。コードがフィルターリストを読み込むと、空白行を正規表現として捉え、後続する単語をエラーメッセージとして取り扱った。ラッキーなことに、空白の正規表現はいかなる文字列にもマッチする表現である。

真夜中である。みんな少しグロッキーになっていた。ブライスがユーザー名を入力すると、メッセージボックスが非常にシンプルなメッセージを返した。

fkdialog

我々は爆笑し始めた。他の人たちもやってきて、何が起きたのか不思議がった。我々はスクリーンを指さす。みんな爆笑し始める。

別の建物で、マーク・アームストロング（QA担当者）がブルースリーク（創業者の一人）と一緒に16台のWebTVボックスがならんだラックの前に座っていた。Racksvilleと名付けられたこの装置群は、ビデオマルチプレクサを通じて大型テレビに接続され、16台のボックスを同時に映し出している。かれらは赤外線キーボードを使ってコマンドをブロードキャストし、すべてのボックスの登録手続きを開始した。我々はスピーカーフォンで彼らを呼び出した。

我々「今どうなってる？」

二人「全部うまくいってるよ」

我々「ああそう…。ボックスを登録する時に何か気づくかもしれないよ」

二人「ホントに？まだ何も変なことは起きてないよ」

我々「まぁまぁ」

二人「分かった。いま郵便番号を今入力してるよ…大丈夫だ。（カタカタ）（停止）ウワッ！！」

馴れ馴れしいダイアログが16ボックスの画面全てに表示された。二人はこの不具合をいずれ近いうちに修正するのがよいのではないかと提案した。我々はそれはナイスアイデアだと思った。

我々はフィルターファイルを修正し、最終的には空行を飛ばして処理するようコードを変更した。私が知る限り、WebTVサービスが実際の顧客に対して「oh, f**k」と言った事例は知られていない。

coalg / diary