第1回　分け行っても分け行ってもバグの中

ソフトウェアにはバグが付きものです。文法的なエラーはコンパイラやインタプリタが見つけてくれるものの、ループの上限を1つ間違える"Off-by-one エラー"（配列a[5]からa[10]の間に要素はいくつあるか？）や、境界値が範囲に含まれるかどうか（⁠「⁠以下」と「未満⁠」⁠）⁠、代入（=）と比較（==）を間違える、といったバグは、コードを書いたことのある人なら誰しも経験していることでしょう。

これらシンプルなバグは、コードの中に途中経過を示すプリント文を仕込んだり、デバッガでステップごとに実行すれば、比較的簡単に発見、修正することができます。

しかしながら、ソフトウェアの規模が大きくなり、さまざまな部分が複雑に絡みあってゆくにつれ、バグも一筋縄では捉えられない、複雑な振る舞いをするようになっていきます。

最初期のコンピュータ研究者（いわゆる「ハッカー⁠」⁠）のスラングを集めた"Jargon file"（⁠「⁠ハッカー大辞典⁠」⁠）では、そのようなバグの複雑な振舞いを量子力学的と見做し、代表的な研究者の名を冠して「ハイゼンバグ（Heisenbug⁠）⁠」や「ボーアバグ（Bohrbug⁠）⁠」と呼んだりしています。

この種のバグが厄介なのは利用状況に依存していることで、特定のユーザやハードウェアの組合せでしか発生せず、再現が困難な問題は、「⁠相性」とか「人を見る」と言って済ませてしまうこともあります（苦笑⁠）⁠。

一方、少々複雑なバグでも、再現性があれば、条件を絞りこんで行くことで解決の糸口が見つかることもあります。最近、その手のバグの典型例を経験したので紹介してみることにしましょう。

発端

Plamo-7.0をリリースしてからしばらくたった頃、Plamo Linuxのメーリングリスト（ML）に「USB-3.0な外付けHDDにインストールしたら起動できない」という報告が届きました。

しばらくMLでやりとりしたところ、どうやらルートパーティションがマウントできなくてカーネルパニックを起しているようです。

USB-3.0の外付けHDDは試したことが無かったので、手頃な価格になってきているこの機会に、手元でも少しイジってみることにしました。

再現

USB-3.0はデータの転送速度を大幅に向上させた新しい規格で、従来のUSBポートにも接続可能なものの、その性能を発揮させるにはUSB-3.0に対応したポートに接続する必要があります。手元のPCにはUSB-3.0用の青色ポートがあったので、さっそくそこに接続してみたところ、Plamo-7.0から問題なく認識でき、あらかじめ用意されていたNTFSパーティションもマウントできました。

HDDが動作することを確認したので、改めてPlamo-7.0のインストーラで再起動し、USB HDD上にルートパーティションを作成して、Plamo-7.0をフルインストールしてみました。

さすがにUSB-3.0はデータの転送速度も速く、インストールはスムーズに終了、ブートローダのgrubもUEFI版が問題なくインストールできました。

「あれれ、特に問題は無さそうでは？」とインストールを終了し再起動、UEFIのブートメニューにはUSB HDDにインストールしたgrubも表示され、選択するとちゃんと起動します。grubのメニューには新しくインストールしたカーネルが表示され、選択してみるとカーネルを読み込んでLinuxが起動…… するかと思ったら即座に画面にエラーメッセージが表われて、カーネルパニックが発生しました。

「なるほど、MLに報告されたのはこの現象か」と、原因を調べることにしました。

分析

Linuxの場合、カーネルの起動直後にパニックが生じるのは、十中八九、ルートパーティションがマウントできないことが原因です。加えてPlamo Linuxではinitrdを使っていないので、ルートパーティションがマウントできない原因は、たいてい「必要なドライバがカーネルに組み込まれていない」ことです。そう考えて、内蔵HDDから起動し直して、USB-3.0を使うために必要なドライバ類を調べてみることにしました。

接続されているUSBデバイスを調べるにはlsusbコマンドが便利です。

$ lsusb
Bus 002 Device 002: ID 8087:8000 Intel Corp. 
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 002: ID 8087:8008 Intel Corp. 
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 002: ID 0bc2:3322 Seagate RSS LLC SRD0NF2 [Expansion Desktop Drive]
Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 Device 004: ID 0853:0111 Topre Corporation 
Bus 003 Device 003: ID 046d:c52b Logitech, Inc. Unifying Receiver
Bus 003 Device 002: ID 0409:005a NEC Corp. HighSpeed Hub
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

この結果を見ると、Seagate製のUSB-3.0な外付けHDDはBus 004、Device 002に接続しています。

次に、各デバイスの接続関係を調べるため-tオプションを付けてlsusbを実行しました。

$ lsusb -t
/:  Bus 04.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/6p, 5000M
    |__ Port 6: Dev 2, If 0, Class=Mass Storage, Driver=uas, 5000M
/:  Bus 03.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/12p, 480M
    |__ Port 6: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M
        |__ Port 2: Dev 3, If 2, Class=Human Interface Device, Driver=usbhid, 12M
        |__ Port 2: Dev 3, If 0, Class=Human Interface Device, Driver=usbhid, 12M
        |__ Port 2: Dev 3, If 1, Class=Human Interface Device, Driver=usbhid, 12M
        |__ Port 3: Dev 4, If 0, Class=Human Interface Device, Driver=usbhid, 12M
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/2p, 480M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/6p, 480M
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/2p, 480M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/6p, 480M

この結果から、4番目のBusの2番目のデバイスは"Mass Storage"クラスと認識され、"uas"というドライバを使って、5000M（bps）のデータ転送速度で動作していることがわかります。また、このBusの根本（ルートハブ）は"xhci_hcd"というドライバで動作しているようです。

以上から、USB-3.0なHDDを利用するためにはxhci_hcdとuasの2つのドライバが必要なことがわかりました。これらのドライバがモジュールだったらルートパーティションはマウントできないはず、とlsmodで確認したところ、これらはまさにモジュールとして動的に組み込まれていました。

$ lsmod | grep -e xhci -a -e uas
uas                    20480  0
xhci_pci               16384  0
xhci_hcd              106496  1 xhci_pci

これはすなわち「HDDを読むためのドライバが、モジュールとしてHDDの中にある」という状態です。もっとも、この状態を解決するのは簡単で、これらのドライバを「モジュール」ではなく「組み込み」にして、カーネルを再構築するだけです。

make menuconfigして調べてみると、これらのドライバは"Device Drivers"=>"USB Support"の下、"xHCI HCD (USB 3.0) support"と"USB Attached SCSI"が該当するようです。

そこで、これらのドライバをカーネル組み込みに変更してビルドし直し、カーネルパッケージを更新して再度USB-3.0 HDDへのインストールを試みました。

苦闘

「必要なドライバをカーネルに組み込んだから大丈夫」と思っていたのも束の間、インストール後に再起動するとやはりルートパーティションをマウントできずにカーネルパニックになってしまいます。

「カーネルを作り損ねたかな？⁠」⁠、と考えて、内蔵HDDをルートパーティションに指定して、USB HDDにインストールしたカーネルを起動してみると問題なく起動します。さらにその状態なら、USB HDDも正しく認識し、マウントできました。

「まだ足りないドライバがあるのだろうか？」と考えて、USB HDDをマウントする前後で組み込まれるモジュール類を調べてみても違いはありません。

「カーネルにルートパーティションの情報が正しく渡せてないのかな？」と考えて、grub.cfgのカーネルパラメータをいろいろイジってみてもダメ、「⁠パーティションテーブルやファイルシステムが影響しているのでは？」と、USB HDDを初期化し直してパーティションテーブルをGPTからMBRに変更してもダメ、インストールするパーティションをBtrfsからExt4やExt3にしてみてもダメ、悪あがきのつもりでカーネルのバージョンをあれこれ変えてみてもダメ、ドライバ類を半分以下に絞り込んでみてもダメでした。

確実に再現するし、その条件もわかっている、しかしながら、まる2日ほどカーネルのビルドやインストール作業を繰り返しても原因は皆目わからず、次第に出口のない迷路に迷い込んだような気になってきました。

光明

起動時のカーネルパニックが厄介なのは、メッセージが即座に流れて、途中経過が読み取れないことも一因です。もう少しメッセージの出力を遅くできないのかな、と調べてみると、"boot_delay=..."というカーネルパラメータを見つけました。このパラメータはカーネルがメッセージを出力するprintkごとに、指定した時間、待ち時間を設けるというものです。

これを使えばもう少し情報が得られるかも、と考えて、"boot_delay=100"を指定して起動してみたものの、今回のトラブルでは複数のprintkを経ていないようで、表示速度は変わりませんでした。

他に何か似たような機能はないだろうか…、とソースコードのDocumentation/admin-guideディレクトリにあるkernel-parameters.txtを"delay"をキーワードに検索してみると、"rootdelay=..."というパラメータに気がつきました。

このパラメータは「ルートファイルシステムをマウントする際、指定した秒数だけ待つ」という指定です。このパラメータを見た時、「⁠ルートデバイス（ルートファイルシステムを置いているデバイス）が間に合わないのでは？」という可能性がひらめきました。その視点でもう少し読み進めると、"rootwait"という「ルートデバイスが見えるようになるまで待つ」というパラメータがありました。

これを使えば何とかなるかも、と考え、あれこれイジったカーネルやHDDパーティションを元に戻し、USB-3.0用のドライバを組み込んだカーネルをインストール、grub.cfgのカーネルパラメータに"rootwait"の一語を追加してやると、「⁠ビンゴ！⁠」⁠、USB-3.0なHDDをルートデバイスにしてきちんと起動するようになりました。

grubは問題なくカーネルを読み込んでいたため、「⁠ルートデバイスが読めない」という可能性は思い浮かばなかったものの、改めて考え直してみると、grubがカーネルを読み込む際は制限時間がないのに対し、カーネルがルートパーティションをマウントする際は、マウントできなければ即座に「致命的エラー」としてカーネルパニックになります。

一方、USB-3.0では、データの転送速度が速い分、HDDは短時間に大量のデータを読み込む必要があります。そのため起動直後ではスピンアップ等の準備のため、カーネルのマウントリクエストへの対応が間に合わない、そう考えれば"rootwait"の一語で問題が解決したことも納得できます。

冒頭に紹介した"Jargon file"やウィキペディアによると、「⁠ハイゼンベルクの不確定性原理」に由来する「ハイゼンバグ」は「⁠（⁠デバッガやprint文で）調べようとすると振舞いを変えるバグ⁠」⁠、「⁠ボーアの原子模型」に由来する「ボーアバグ」は「特定の状況下で高い再現性を示すバグ」だそうなので、今回の問題は典型的な「ボーアバグ」と言えるでしょう。

「ボーアバグ」の場合、発生する「特定の状況」を把握できれば解決は容易と言われています。しかしながら、今回のように、発生する状況にハードウェアが絡んでくると、ソフトとハードの双方を考慮しないといけなくなって、問題は指数関数的にややこしくなります。今回は何とか解決できたものの、視点や発想を柔軟に保つことの重要さを改めて思いしらされたトラブルでした。

かつての日本では、暑い夏の夜の肝試しに「百物語」が行われていました。「⁠⁠百物語」では、灯しておいた100本のロウソクを、怪談や不思議な話をするごとに1本ずつ消してゆき、最後のロウソクが消えた時、本当の怪異が現れる、と語りつがれていました。

後代になると、本当の怪異が現れては困るから、という理由で、100話目はあえて語らず、99話で話を止めるスタイルが広まったそうです。

気付いている読者もいらっしゃるかと思いますが、本来、今回は「玩式草子」の100回目になる予定でした。しかしながら、バグやトラブル話を100回した結果、本当に解決できないトラブルに現れられても困るので⁠、「⁠⁠百物語」のひそみに習い、99回で連載のタイトルを変えることにしました。

タイトル変更を機に、これからはLinuxやOSSだけでなく、よりさまざまな話題を取りあげて行きたいと思っているので、今後ともご愛読のほど、よろしくお願いします。