Windows could not update the computer’s boot configuration

Windows Server 2016 が GA になったので、週末を利用して、仕事で使っているマシン 2 台の OS を Windows Server 2016 TP5 から RTM に入れ替えたのですが、インストーラーの怪しげな動作でハマったので書いておきます。強引にインストールは終わらせましたが、完全に直っていない上に根本原因が確認できていないので、時間を見つけて調べて追記する予定です。

(2016/10/30 追記)
最終確認はまだですが、NVRAM へのアクセスが失敗していることが原因っぽいです。(詳細は後述)

インストールを行った二台は HP Z420 Workstation と HP Z440 Workstation。前者がメインの開発機で、コードを書いてビルドする以外に、デバッグ用の Hyper-V 仮想マシンを動かしたり、メールを書いたりもします。後者はサブの開発機で、ほぼビルドと仮想マシンのみ。なお Windows 10 ではなく Server 2016 を入れるのは、Universal App などの煩わしい機能が嫌いだからです。サーバー SKU おすすめです。

家で使うマシンも仕事のマシンも同じですが、OS の入れ替えでは常にクリーン インストールを行います。インプレースアップグレードはいまいち動作が信用できないのです。

作業は、サブ機の Z440 から行いました。これには光学ドライブがないので、USB ドライブで Windows PE を起動して、別の USB ドライブに入れておいた Windows Server 2016 のインストーラー (MSDN からダウンロードした ISO を単にコピーしたもの) である setup.exe を起動して行います。前の OS が入っていたパーティションを消して、新しくパーティションを作って入れるだけです。作業としては普通です。

Z440 の作業は何の問題もなかったのですが、同じ USB ドライブを使って Z420 に Server 2016 をインストールしたところ、インストールの最後のフェーズで "Windows could not update the computer’s boot configuration. Installation cannot proceed." が出ました。

01-error
じゃじゃーん

これけっこう深刻なエラー・・・。メッセージの内容を信用するならば、インストーラーの wim イメージをボリュームにコピーした後、ブート情報を書き換えるところが失敗しているわけす。当然マシンは起動しなくなります。Windows RE も起動できません。ちなみにインストールが失敗したディスクからシステムを起動すると "Your PC/Device needs to be repaired – The Boot Configuration Data file is missing some required information. File: \BCD Error code: 0xc0000034" 画面が出ました。BCD 情報を書けなかったのはお前んところのインストーラーなんだけどな!

02-bcd
起動失敗の図

慌てず騒がず、とりあえず以下の作業を順番に試してみました。

  1. まったく同じ作業 (同じ USB ドライブを使って、同じハードディスク (以降ディスク A) をインストール先として指定) を試す → 現象変わらず
  2. 別のハードディスク (以降ディスク B) を使ってみる → 現象変わらず
  3. ディスク B を diskpart の clear コマンドでクリアしてからインストール → 現象変わらず

おいおい・・。一台目の Z440 で上手くいっていることからして、USB ドライブに問題はないはず。ハードディスク側にも問題があるとは思えない。ぱっと思いつくのは、BIOS/UEFI の起動方式とディスク形式の MBR/GPT。ディスクをクリアしても同じ現象が出る時点でインストーラーのバグくさいが、だとすると Z440 でうまくいった説明がつかない。Z420 も Z440 も UEFI のはずなのに。

しばらく悩んだ結果、Z420 と Z440 とで、パーティション構成に唯一の違いがあることに気づきました。Z440 のインストール先ディスクは 150GB なので、まるまる OS 用のパーティションを入れています。一方、Z420 のインストール先ディスク A は 1TB なので、後ろ半分の 500GB はデータ用にして、先頭の 500GB を OS 用にしていました。今回の作業では、前の OS のパーティションだけを消して、インストーラーから新しくパーティションを作り直していました。また、上記作業 2. と 3. の作業でも、インストーラー経由でパーティションを作ってからインストールをしていました。そこで、新しいディスク C を用意して、パーティションを作らず、ディスク全体を指定して OS をインストールしたところ・・・成功。謎は深まるばかり。

そしてすぐに次の問題が発生。インストール後に再起動がかかっても、またも "Your PC/Device needs to be repaired" エラーで Windows 起動しない・・・。インストール成功したんじゃなかったのかよ。

試行錯誤の末、Boot menu を開いてインストール先のディスクを明示的に選択すれば起動することが判明。これで何が起こっているのかは分かった、気がする。

03-boot

Z420 のブート メニュー
(Legacy Boot Sources の WDC WD2500AA.. を選択すれば起動できた)

起動がうまくいったあと、以下の情報を確認しました。

  • ディスク A は GPT 形式になっていて、EFI System Partition は作成されている
    → インストーラーの最後で BCD 情報の書き換えに失敗した理由が不明
  • ディスク B は MBR 形式になっている
  • Z420 の msinfo32 を見ると、BIOS Mode は Legacy
  • Z440 の起動ディスクは GPT 形式
  • Z440 の msinfo32 で、BIOS Mode は UEFI

上記を整理すると・・

  1. Windows インストーラー、及び OS 本体は Z420 を Legacy BIOS だと思っているので、MBR 形式のディスクを対象にしたインストールを試みる。
  2. しかし、インストーラーの中のパーティションを作る部分では、システムを UEFI と認識しているためか、MBR ではなく GPT 形式でパーティションを作る。
  3. Z420 のブートの順番は、UEFI を試してから各ディスクの MBR を使って起動しようとする。このとき、UEFI の Windows Boot Manager がなぜか中途半端に実行できてしまうため、MBR の実行を試そうとしない。
  4. システムは MBR 形式でインストールされているので当然起動できない。

不可解なのは以下の点。

  • そもそも最初に試したときに、BCD 情報が更新できなかった理由
    → 諸悪の根源。これが上手くいっていれば問題はここまで拗れない。
  • インストーラーでパーティションを作るとディスクが GPT になるくせに、実際にシステムをインストールするときは MBR でディスクを切っている。インストーラーがシステムの BIOS モードをチェックするコードが少なくとも二ヶ所あって、一方は Legacy BIOS、他方は UEFI だと認識してしまうっぽい・・?

確か似たような現象を調べたときに、Windows のインストーラーにはディスクをクリアしてディスク形式を変更する機能がないので、インストーラーは Legacy BIOS のシステムでは GPT 形式のディスクを認識せず、逆に UEFI のシステムでは MBR のディスクを認識しなかった記憶があります。この場合、diskpart などを使ってあらかじめディスク形式を変えておく必要があります。

今回の場合は不可解で、GPT と MBR の扱いがかなり混在してしまっている印象がです。そもそもインストーラーやシステムがシステムを Legacy BIOS として認識しているのであれば、GPT で切れたディスクは認識できるべきではないし、インストールが始まる前にエラーになって欲しいものです。イメージのコピーはうまくいって、最後にこけるのは一番タチが悪い。これが Server 2016 のメディアで新しく発生するのか、もっと前の OS のディスクから発生するのかどうかは確かめていません。

今のところ、マシンを再起動するたびに boot menu を起動してディスクを選択しないといけない。超不便。

(2016/10/30 追記)

まだ最終確認は取れていませんが、どうやら NVRAM への読み書きができないハードウェア障害のような気がしてきました。調べた内容を以下に記します。

まず、Windows インストール時のログはインストール先ディスクの $WINDOWS.~BT\Sources\Panther\setupact.log に残っているので、失敗している箇所を確認。

log

2016-10-22 16:46:58, Info       [0x060228] IBS    Callback_UpdateBootFiles:Successfully updated Windows boot files.
2016-10-22 16:46:58, Info                  IBSLIB ModifyBootEntriesLegacy: Not in first boot. No actions to perform. SetupPhase[2]
2016-10-22 16:46:58, Info                  IBSLIB ModifyBootEntriesBCD:Setup phase is [2]
2016-10-22 16:46:58, Info                  IBSLIB BfsInitializeBcdStore flags(0x00000008) RetainElementData:n DelExistinObject:n
2016-10-22 16:46:58, Info                  IBSLIB VolumePathName for H:\Windows is H:\
2016-10-22 16:46:58, Info                  IBSLIB Opening template from \Device\HarddiskVolume7\Windows\System32\config\BCD-Template.
2016-10-22 16:46:58, Info                  IBSLIB System BCD store does not exist, creating.
2016-10-22 16:46:58, Error      [0x064230] IBSLIB Failed to create a new system store. Status = [c0000001]
2016-10-22 16:46:58, Error      [0x0641b8] IBSLIB ModifyBootEntries: Error modifying bcd boot entries. dwRetCode=[0x1F][gle=0x0000001f]
2016-10-22 16:46:58, Info       [0x060216] IBS    CallBack_MungeBootEntries:Failed to modify boot entries; GLE = 31
2016-10-22 16:46:58, Info       [0x0640ae] IBSLIB PublishMessage: Publishing message [Windows could not update the computer’s boot configuration. Installation cannot proceed.]
2016-10-22 16:46:58, Info       [0x0a013d] UI     Accepting Cancel. Exiting Page Progress.

やはり BCD の新規作成に失敗している模様。

とりあえず BIOS の設定 (Advanced –> Device Options) を確認。もともとはこんな設定だった。後で触れるがこの時点でちょっと変。

bios01

とりあえず Option ROM を Legacy から EFI に変えて試してみる。

bios02

なお、ここで Video Options ROMS を EFI に変えてはいけない。間違って変えてしまうと、ビープ音が 6 回鳴ってシステムが起動しない悲しい状態になります。

Advisory: HP Z1, Z220, Z420, Z620, Z820 Workstation – 6 Beeps After Changing BIOS Settings
http://h20564.www2.hp.com/hpsc/doc/public/display?docId=emr_na-c04045903

お決まりだが、見事にこの罠を踏んでしまったのだ。上記 Resolution にあるように、CMOS リセットを行って無事復活。PXE Option ROMS と Mass Storage Option ROMS だけを EFI にして再起動。そして同様にインストーラーを動かすが、状況は変わらず、結局 "Windows could not update the computer’s boot configuration. Installation cannot proceed." で失敗する。

埒が明かなくなってきたので、真面目に setup.exe をデバッグしてみることに。最近の Windows PE では NIC の標準ドライバーが入っているので TCP/IP ネットワークで簡単にユーザーモードのリモート デバッグができます。Windows PE 起動後に以下のコマンドを実行すると、ネットワークが有効になるので dbgsrv.exe を起動できます。

> wpeutil initializenetwork
> wpeutil disablefirewall

詳細は省きますが、問題となっているインストーラーの最終フェーズでは、まず空の BCD を作ってから、インストール イメージ内にある windows\system32\config\BCD-Template と NVRAM の状態を元に BCD にデータを入れていくようなことをやっているようです。空の BCD を作るところは問題なく成功して、NVRAM の内容を取ってくると思われるシステム コールから c0000001 が返ってきていました。カーネル デバッグまではやっていないので、カーネルの中で何が失敗しているのかはまだ不明のままです。

NVRAM がおかしいとすると、Option ROM が Legacy 設定だったにも関わらず "Your PC/Device needs to be repaired – The Boot Configuration Data file is missing some required information. File: \BCD Error code: 0xc0000034" が出る理由も分かるような気もします。NVRAM の内容が Server 2016 を入れる前の状態のまま変わっていない可能性が高く、本来であれば Option ROM を Legacy に変えたら NVRAM はクリアされて、MBR からの起動を自動的に試すのではないだろうか。

デバッガーを使って、NVRAM にアクセスしてエラー コードを返している箇所 (4 箇所あった) で、片っ端からエラーコードを変更してエラーがなかったように見せかける禁断の領域に踏み込んだところ、インストールは終わりましたが、初回起動で OOBE が始まる前の段階で "Windows could not complete the installation. To install Windows on this computer, restart the installation." というポップアップが出て結局起動できず。どうやら Windows 起動時にも NVRAM へのアクセスを行なっているようだ。まあそりゃそうだろう。

image

Z420 で NVRAM をクリアする方法を探してみたが、どうにも見つからない。意図せずして行なった CMOS クリアではクリアされなかった。システム設定で ROM をクリアするオプションはあるのだが、何が消えるか分からないためちょっと恐くて試していない。びびり。

(2016/11/6 追記)

次は、何とかして NVRAM がおかしいという確証が欲しいところです。以下の資料を見ると、実は bcdedit /enum で出力される値は NVRAM variable から来ているらしい。

Presentations and Videos | Unified Extensible Firmware Interface Forum
http://www.uefi.org/learning_center/presentationsandvideos

上記ページからダウンロードできる "Windows Boot Environment" という PDF の 20 ページ目によると

– BCD has 1:1 mappings for some UEFI global variables

– Any time {fwbootmgr} is manipulated, NVRAM is automatically updated

さらに、以下のページによると

Remove Duplicate Firmware Objects in BCD and NVRAM
https://technet.microsoft.com/en-us/library/cc749510(v=ws.10).aspx

When bcdedit opens the BCD, it compares entries in NVRAM with entries in BCD. Entries in NVRAM that were created by the firmware that do not exist in BCD are added to the system BCD. When bcdedit closes the system BCD, any boot manager entries in BCD that are not in NVRAM are added to NVRAM.

同様のことは以下の日本語のブログにもまとめられています。詳しくていい感じ。

PC-UEFI – DXR165の備忘録
http://dxr165.blog.fc2.com/blog-category-45.html

何はともあれ、Windows PE を起動して bcdedit を実行してみます。

X:\windows\system32> bcdedit /enum {fwbootmgr}
The boot configuration data store could not be opened.
A device attached to the system is not functioning.

あっさり失敗。インストーラーを起動するまでもないですね。Server 2016 のメディアが悪いのではなく、やはりハードウェアがおかしいくさい。

さて、次のステップはいよいよ Windows PE のカーネル デバッグだろうか。幸い、Z420 と Z440 を 1394 ケーブルで繋げられたので、これでデバッグすることにする。最近だとイーサネットも使えるらしいが、試したことはない。

上記の bcdedit /enum {fwbootmgr} を実行すると、NT カーネルから HAL を経由し、EFI のランタイム サービス テーブルにおける GetNextVariableName が指すアドレスの関数を呼んで変数名を列挙し、GetVariable で値を取ってきます。ランタイム サービス テーブルの定義は、↓ のファイルにおける EFI_RUNTIME_SERVICES という構造体です。

TianoCore EDK2: MdePkg/Include/Uefi/UefiSpec.h Source File
http://www.bluestop.org/edk2/docs/trunk/_uefi_spec_8h_source.html

ランタイム サービス テーブルは、EFI システム テーブルの一部であり、EFI システム テーブルは efi_main 関数が取る 2 つのパラメーターのうちの一つらしい。

Programming for EFI: Using EFI Services
http://www.rodsbooks.com/efi-programming/efi_services.html

GetNextVariableName のプロトタイプ宣言は分かっているので、呼び出し部分から変数名を GUID を確認しました。102 個ありますが、とりあえず全部載せておきます。

ffffd000`208578a0  "CurrentDevicePath"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "BootCurrent"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "LangCodes"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "PlatformLangCodes"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "SSID"
ffffd000`20857868  707c9176 4e27a4c1 371c1d85 c873cab7
ffffd000`208578a0  "UsbMassDevNum"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "SetupFeatureSupport"
ffffd000`20857868  b6ad93e3 4c8519f7 c58072aa c7db9471
ffffd000`208578a0  "ErrOut"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "ErrOutDev"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "RstSataV"
ffffd000`20857868  193dfefa 4302a445 3aefd899 c6041aad
ffffd000`208578a0  "PNP0510_0_VV"
ffffd000`20857868  560bf58a 4d7e1e0d 80293f95 31e061a2
ffffd000`208578a0  "RstScuV"
ffffd000`20857868  193dfefa 4302a445 3aefd899 c6041aad
ffffd000`208578a0  "BootOptionSupport"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "ConInDev"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "UsbMassDevValid"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "PNP0501_1_VV"
ffffd000`20857868  560bf58a 4d7e1e0d 80293f95 31e061a2
ffffd000`208578a0  "PNP0400_0_VV"
ffffd000`20857868  560bf58a 4d7e1e0d 80293f95 31e061a2
ffffd000`208578a0  "PNP0501_0_VV"
ffffd000`20857868  560bf58a 4d7e1e0d 80293f95 31e061a2
ffffd000`208578a0  "ConOutDev"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "VgaDeviceInfo"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "VgaDeviceCount"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "RstScuO"
ffffd000`20857868  193dfefa 4302a445 3aefd899 c6041aad
ffffd000`208578a0  "DebuggerSerialPortsEnabledVar"
ffffd000`20857868  97ca1a5b 4d1fb760 90d14ba5 902c0392
ffffd000`208578a0  "SerialPortsEnabledVar"
ffffd000`20857868  560bf58a 4d7e1e0d 80293f95 31e061a2
ffffd000`208578a0  "DriverHlthEnable"
ffffd000`20857868  0885f288 4be1418c ad8bafa6 fe08da61
ffffd000`208578a0  "DriverHealthCount"
ffffd000`20857868  7459a7d4 44806533 e279a7bb c943445a
ffffd000`208578a0  "S3SS"
ffffd000`20857868  4bafc2b4 410402dc f1d636b2 849e8db9
ffffd000`208578a0  "RSCInfoAddresss"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "PlatformLang"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "AMITSESetup"
ffffd000`20857868  c811fa38 457942c8 e960bba9 34fbdd4e
ffffd000`208578a0  "UsbSupport"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "SlotEnable"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "FrontUsbEnable"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "RearUsbEnable"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "InternalUsbEnable"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "PowerOnTime"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "MSDigitalMarker"
ffffd000`20857868  c43c9947 4a343578 f38e5fb9 8e43c7a5
ffffd000`208578a0  "NotFirstBoot"
ffffd000`20857868  70040abc 45886387 cdddb187 f57a7d6c
ffffd000`208578a0  "ONBOARD_DEVS_PRESENT"
ffffd000`20857868  d98397ee 457a7a9d 68e5dfa9 18cc87ae
ffffd000`208578a0  "MemoryInfo"
ffffd000`20857868  7ee396a1 431bff7d cd8c53fa c5447c12
ffffd000`208578a0  "MEMajorVersion"
ffffd000`20857868  59416f8c 48c4b82d cb107e88 bbc38ec4
ffffd000`208578a0  "PciSerialPortsLocationVar"
ffffd000`20857868  560bf58a 4d7e1e0d 80293f95 31e061a2
ffffd000`208578a0  "HeciErrorReset"
ffffd000`20857868  31d2fce0 11e164b3 00086cb8 669a0c20
ffffd000`208578a0  "MeInfoSetup"
ffffd000`20857868  78259433 4db37b6d c436e89a 7da1c3c2
ffffd000`208578a0  "NetworkStackVar"
ffffd000`20857868  d1405d16 46957afc 454112bb a295369d
ffffd000`208578a0  "HSTime"
ffffd000`20857868  ae601ef0 11e0360b 0008429e 669a0c20
ffffd000`208578a0  "LastHDS"
ffffd000`20857868  ae601ef0 11e0360b 0008429e 669a0c20
ffffd000`208578a0  "ConsoleLock"
ffffd000`20857868  368cda0d 4b9bcf31 d1e7f68c 7e15ffbf
ffffd000`208578a0  "SetupAmtFeatures"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "SlotPresent"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "MMIOR."
ffffd000`20857868  3b2158f5 48c039d3 530384aa dbc6ba65
ffffd000`208578a0  "SysBuses"
ffffd000`20857868  55e6fc89 40763e74 e9d4c298 10e8c413
ffffd000`208578a0  "ThermalErrorLog"
ffffd000`20857868  707c9176 4e27a4c1 371c1d85 c873cab7
ffffd000`208578a0  "ConOut"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "SetupCpuSockets"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "FrontUsbPresent"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "RearUsbPresent"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "InternalUsbPresent"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "Lang"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "SBRealRevID"
ffffd000`20857868  707c9176 4e27a4c1 371c1d85 c873cab7
ffffd000`208578a0  "TdtAdvancedSetupDataVar"
ffffd000`20857868  7b77fb8b 4d7e1e0d 80393f95 76e061a2
ffffd000`208578a0  "HP_CTRACE"
ffffd000`20857868  707c9176 4e27a4c1 371c1d85 c873cab7
ffffd000`208578a0  "NBRealRevID"
ffffd000`20857868  707c9176 4e27a4c1 371c1d85 c873cab7
ffffd000`208578a0  "MeBiosExtensionSetup"
ffffd000`20857868  1bad711c 4241d451 3785f3b1 700c2e81
ffffd000`208578a0  "HpWriteOnceMetaData"
ffffd000`20857868  707c9176 4e27a4c1 371c1d85 c873cab7
ffffd000`208578a0  "PBRDevicePath"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "TrueStruct"
ffffd000`20857868  7349bea7 420bc95c 1e6dcd8d a88b4d9d
ffffd000`208578a0  "PNP0501_11_NV"
ffffd000`20857868  560bf58a 4d7e1e0d 80293f95 31e061a2
ffffd000`208578a0  "PNP0501_12_NV"
ffffd000`20857868  560bf58a 4d7e1e0d 80293f95 31e061a2
ffffd000`208578a0  "SetupLtsxFeatures"
ffffd000`20857868  ec87d643 4bb5eba4 3e3fe5a1 a90db236
ffffd000`208578a0  "ucal"
ffffd000`20857868  707c9176 4e27a4c1 371c1d85 c873cab7
ffffd000`208578a0  "HpPassphraseStructureVariable"
ffffd000`20857868  707c9176 4e27a4c1 371c1d85 c873cab7
ffffd000`208578a0  "EfiTime"
ffffd000`20857868  9d0da369 46f8540b 5f2ba085 151e302c
ffffd000`208578a0  "Setup"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "PlatformLang"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "Timeout"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "AMITSESetup"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "IDESecDev"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "SystemIds"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "UsbSupport"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "PNP0501_0_NV"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "PNP0501_1_NV"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "PNP0400_0_NV"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "PNP0510_0_NV"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "HpMfgData"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "SlotEnable"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "FrontUsbEnable"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "RearUsbEnable"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "InternalUsbEnable"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "PowerOnTime"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "MSDigitalMarker"
ffffd000`20857868  8173aefa 4574adf0 377139a0 1af24aab
ffffd000`208578a0  "PNP0501_0_NV"
ffffd000`20857868  560bf58a 4d7e1e0d 80293f95 31e061a2
ffffd000`208578a0  "PNP0501_1_NV"
ffffd000`20857868  560bf58a 4d7e1e0d 80293f95 31e061a2
ffffd000`208578a0  "PNP0400_0_NV"
ffffd000`20857868  560bf58a 4d7e1e0d 80293f95 31e061a2
ffffd000`208578a0  "PNP0510_0_NV"
ffffd000`20857868  560bf58a 4d7e1e0d 80293f95 31e061a2
ffffd000`208578a0  "HpMor"
ffffd000`20857868  707c9176 4e27a4c1 371c1d85 c873cab7
ffffd000`208578a0  "PBRDevicePath"
ffffd000`20857868  a9b5f8d2 42c2cb6d ffb501bc 5e33e4aa
ffffd000`208578a0  "PetAlertCfg"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "ConIn"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "Timeout"
ffffd000`20857868  8be4df61 11d293ca e0000daa 8c2b0398
ffffd000`208578a0  "CurrentPolicy"
ffffd000`20857868  77fa9abd 4d320359 f42860bd 4b788fe7
ffffd000`208578a0  "a8ff1f3f4a8c94074056b76e9d7fab3a862c68d3"
ffffd000`20857868  ffffffff ffffffff ffffffff ffffffff

GetNextVariableName からの戻り値は 0 なのですが、最後の変数は名前、GUID ともに明らかに変です。このあと、最後の "a8ff1f3f4a8c94074056b76e9d7fab3a862c68d3" に対して GetVariable すると、戻り値が 14 (= EFI_NOT_FOUND) になります。呼び出し元は hal!HalEnumerateEnvironmentVariablesEx なのですが、GetVariable が失敗すると、この関数は見慣れたエラー コード c0000001 (= STATUS_UNSUCCESSFUL) を返すようになっていました。

というわけで、EFI の GetNextVariableName で列挙された変数名がなぜか GetVariable できないためインストールが上手くいかない、ことが分かりました。アセンブラでどうやって NVRAM にアクセスしているのか分かりませんが、やはり NVRAM が怪しいです。

それにしても HAL の動作には不満が残ります。GetNextVariableName で列挙された値が GetVariable 出来なかった場合は、全体をエラーにするのではなく、その変数だけをスキップして欲しいですね。

Boost.Python debugging

Boost.Python で std::valarray をエクスポートする際、__getitem__ に operator[] を渡すと、インデックスが境界を超えてもエラーにならないため、無限ループに陥る現象について書きました。その後の追加情報を紹介します。

1. 非メンバ関数をクラス メソッドとしてエクスポート

前回は、回避策として valarray を継承したクラスを作って operator::at を新たに定義しました。が、Python の wiki を見ていたところ、Boost.Python の class_ で定義するコンバーターのメンバー関数にはメンバー関数ポインターだけでなく、通常の関数も指定できることが分かりました。

boost.python/ExportingClasses – Python Wiki
https://wiki.python.org/moin/boost.python/ExportingClasses

これを使うと、新たにクラスを定義しなくても __getitem__ を正しく定義できます。

#include <boost/python.hpp>
#include <valarray>
#include <random>
#include <stdio.h>

std::default_random_engine generator;
std::uniform_real_distribution<double> distribution(0.0, 1.0);

typedef std::valarray<double> darray;

class Field {
private:
    darray _data;

public:
    Field(int n) : _data(n) {
        printf("Field::Field(): %p\n", this);
    }
    ~Field() {
        printf("Field::~Field() %p\n", this);
    }

    void Dump() const {
        printf("[");
        for (auto &d : _data) {
            printf("% 3.3f", d);
        }
        printf(" ]\n");
    }

    void Churn() {
        for (auto &d : _data) {
            d = distribution(generator);
        }
    }

    const darray &Positions() const {
        return _data;
    }
};

double GetAt(const darray &arr, size_t n) {
    if (n >= arr.size()) {
        std::__throw_out_of_range_fmt(__N("out_of_range"));
    }
    return arr[n];
}

BOOST_PYTHON_MODULE(ems) {
    using namespace boost::python;

    class_<Field>("Field", init<int>())
        .def("Positions", &Field::Positions,
             return_internal_reference<>())
        .def("Dump", &Field::Dump)
        .def("Churn", &Field::Churn)
        ;

    class_<darray>("darray")
        .def("__getitem__", GetAt)
        .def("__len__", &darray::size)
        ;
}

ここから、壮大に話が逸れていくのですが、前回こんなことを書きました。

もう少し見てみないと分かりませんが、ems.Field オブジェクトが iterator を使ってシーケンシャルにアクセスする種類になっているのが悪いのではないかと思います。何らかの方法で、ems.Field は iterator ではなくインデックスを使ってランダム アクセスすべきものに種別できればちゃんと動くのではないかと。そんな種類があるかどうか分かりませんが。後で調べよう。

今回も結論から書くとたぶんこれは無理です。Boost.Python をデバッグしつつ調べたので、その過程を書いておきます。

2. Boost.Python をソースからビルドして使う

まずデバッグ環境の構築です。Boost のコードは GitHub にあるので、クローンしてからビルドします。

git clone –recursive https://github.com/boostorg/boost.git modular-boost
git checkout refs/tags/boost-1.60.0
cd modular-boost/
./bootstrap.sh
./b2 -a –with-python debug-symbols=on
sudo ./b2 -a –prefix=/usr/local/boost/boost-1.60.0 –with-python debug-symbols=on install
sudo ln -s /usr/local/boost/boost-1.60.0 /usr/local/boost/current

コマンドを作るうえで参考にしたページは↓。Boost をビルドしている人は少ない気がする・・。

TryModBoost – Boost C++ Libraries
https://svn.boost.org/trac/boost/wiki/TryModBoost

Installing Boost.Python on your System
http://boostorg.github.io/python/doc/html/building/installing_boost_python_on_your_.html

Builtin features
http://www.boost.org/build/doc/html/bbv2/overview/builtins/features.html

ビルドには、make ではなく b2 (build boost?) を使います。最新のリポジトリをクローンしてそのままビルドしたところ、文法エラーでビルドが失敗したので、boost-1.60.0 のタグの状態でビルドしました。もう直っているかもしれません。

デバッグ情報を生成するため、debug-symbols=on というオプションをつけています。これは、コードの最適化はデフォルトの ON にしたまま、デバッグ情報を生成するという意味です。普通は variant=debug というオプションをつけて、最適化も off にしたほうがいいです。インライン展開された魔境に挑みたい人のみ、debug-symbols=on を使いましょう。

上記コマンドで、libboost_python が /usr/local/boost/current/lib にできるので、C++ の Makefile を以下のように変更します。Boost,Python は Python API を使うので、API の中をデバッグするため、libpython2.7 のデバッグ情報もあったほうが便利です。以下の Makefile は、ソースからビルドした Python 2.7 が /usr/local/python/current/ にインストールされている前提です。Boost.Python を使って共有ライブラリを作るので、libpython2.7 も PIC でコンパイルする必要があります。つまり、Python の configure で –enable-shared オプションをつけておいてください。

CC=g++
RM=rm -f

TARGET=ems.so
SRCS=$(wildcard *.cpp)
OBJS=$(SRCS:.cpp=.o)

override CFLAGS+=-Wall -fPIC -std=c++11 -O2 -g
LFLAGS=

INCLUDES=-I/usr/local/python/current/include/python2.7 -I/usr/local/boost/current/include
LIBDIRS=-L/usr/local/python/current/lib -L/usr/local/boost/current/lib
LIBS=-lpython2.7 -lboost_python

all: clean $(TARGET)

clean:
        $(RM) $(OBJS) $(TARGET)

$(TARGET): $(OBJS)
        $(CC) -shared $(LFLAGS) $(LIBDIRS) $^ -o $@ $(LIBS)

$(OBJS): $(SRCS)
        $(CC) $(INCLUDES) $(CFLAGS) -c $^

デバッガーを起動する前に、python を実行する前のライブラリの検索パスにも追加しておきます。gdb を起動するときはこんな感じにします。

export PYTHONPATH=/usr/local/lib/python2.7/dist-packages
export LD_LIBRARY_PATH=/usr/local/boost/current/lib:/usr/local/python/current/lib
gdb /usr/local/python/current/bin/python

ここから gdb によるデバッグを行いますが、結果として何か得られたわけではありません。考え方の参考になれば幸いです。

まず、Python API に PyObject_GetIter という関数があります。

Object Protocol — Python 2.7.11 documentation
https://docs.python.org/2/c-api/object.html

valarray のコンバーターである darray に対して Python から列挙を行なおうとすると、PyObject_GetIter が呼ばれます。

john@ubuntu1510:~/Documents/pyc$ export PYTHONPATH=/usr/local/lib/python2.7/dist-packages
john@ubuntu1510:~/Documents/pyc$ export LD_LIBRARY_PATH=/usr/local/boost/current/lib:/usr/local/python/current/lib
john@ubuntu1510:~/Documents/pyc$ gdb /usr/local/python/current/bin/python
GNU gdb (Ubuntu 7.10-1ubuntu2) 7.10
Copyright (C) 2015 Free Software Foundation, Inc.
(略)
Type "apropos word" to search for commands related to "word"…
Reading symbols from /usr/local/python/current/bin/python…done.
(gdb) r
Starting program: /usr/local/python/python-2.7.11/bin/python
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Python 2.7.11 (default, Dec 22 2015, 22:30:16)
[GCC 5.2.1 20151010] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import ems
>>> f = ems.Field(4)
Field::Field(): 0x6d09d0
>>> x = f.Positions()
>>> x
<ems.darray object at 0x7ffff7ed5600>
>>>
Program received signal SIGINT, Interrupt.
0x00007ffff74e4723 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:81
81      ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) b PyObject_GetIter
Breakpoint 1 at 0x7ffff7a261c0: file Objects/abstract.c, line 3085.
(gdb) i b
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   0x00007ffff7a261c0 in PyObject_GetIter at Objects/abstract.c:3085
(gdb) c
Continuing.

>>> [i for i in x]

Breakpoint 1, PyObject_GetIter (o=o@entry=0x7ffff7ed5600) at Objects/abstract.c:3085
3085    {
(gdb) bt 5
#0  PyObject_GetIter (o=o@entry=0x7ffff7ed5600) at Objects/abstract.c:3085
#1  0x00007ffff7ad7db0 in PyEval_EvalFrameEx (f=f@entry=0x7ffff7f7e050,
    throwflag=throwflag@entry=0) at Python/ceval.c:2790
#2  0x00007ffff7ae068c in PyEval_EvalCodeEx (co=co@entry=0x7ffff7ed6930,
    globals=globals@entry=0x7ffff7f6b168, locals=locals@entry=0x7ffff7f6b168, args=args@entry=0x0,
    argcount=argcount@entry=0, kws=kws@entry=0x0, kwcount=0, defs=0x0, defcount=0, closure=0x0)
    at Python/ceval.c:3582
#3  0x00007ffff7ae07a9 in PyEval_EvalCode (co=co@entry=0x7ffff7ed6930,
    globals=globals@entry=0x7ffff7f6b168, locals=locals@entry=0x7ffff7f6b168) at Python/ceval.c:669
#4  0x00007ffff7b05d81 in run_mod (arena=0x66f100, flags=0x7fffffffe370, locals=0x7ffff7f6b168,
    globals=0x7ffff7f6b168, filename=0x7fffffffe370 "", mod=0x6b9ce8) at Python/pythonrun.c:1370
(More stack frames follow…)

関数のコードはこうなっています。引数として与えられた Python オブジェクトに関連付けられた Iterator をオブジェクトとして返す関数です。

Objects/abstract.c
3083 PyObject *
3084 PyObject_GetIter(PyObject *o)
3085 {
3086     PyTypeObject *t = o->ob_type;
3087     getiterfunc f = NULL;
3088     if (PyType_HasFeature(t, Py_TPFLAGS_HAVE_ITER))
3089         f = t->tp_iter;
3090     if (f == NULL) {
3091         if (PySequence_Check(o))
3092             return PySeqIter_New(o);
3093         return type_error("’%.200s’ object is not iterable", o);
3094     }
3095     else {
3096         PyObject *res = (*f)(o);
3097         if (res != NULL && !PyIter_Check(res)) {
3098             PyErr_Format(PyExc_TypeError,
3099                          "iter() returned non-iterator "
3100                          "of type ‘%.100s’",
3101                          res->ob_type->tp_name);

関数の冒頭で、引数の PyTypeObject で Py_TPFLAGS_HAVE_ITER フラグを判定し、有効な場合は関連付けられた iterator である tp_iter を使うようになっています。これをパッと見たときに、valarray からコンバートした darray オブジェクトからこのフラグを削除してみようと考えました。まずは、現時点での TypeObject を見てます。

(gdb) frame
#0  PyObject_GetIter (o=o@entry=0x7ffff7ed5600) at Objects/abstract.c:3085
3085    {
(gdb) p *o->ob_type
$1 = {ob_refcnt = 5, ob_type = 0x7ffff5a7cc40 <boost::python::class_metatype_object>, ob_size = 0,
  tp_name = 0x7ffff7e94954 "darray", tp_basicsize = 48, tp_itemsize = 1,
  tp_dealloc = 0x7ffff7a8b390 <subtype_dealloc>, tp_print = 0x0, tp_getattr = 0x0,
  tp_setattr = 0x0, tp_compare = 0x0, tp_repr = 0x7ffff7a8f390 <object_repr>,
  tp_as_number = 0x6d3c88, tp_as_sequence = 0x6d3dd8, tp_as_mapping = 0x6d3dc0,
  tp_hash = 0x7ffff7a70be0 <_Py_HashPointer>, tp_call = 0x0, tp_str = 0x7ffff7a8acc0 <object_str>,
  tp_getattro = 0x7ffff7a72410 <PyObject_GenericGetAttr>,
  tp_setattro = 0x7ffff7a72670 <PyObject_GenericSetAttr>, tp_as_buffer = 0x6d3e28,
  tp_flags = 153595, tp_doc = 0x0, tp_traverse = 0x7ffff7a8b0a0 <subtype_traverse>,
  tp_clear = 0x7ffff7a8d290 <subtype_clear>, tp_richcompare = 0x0, tp_weaklistoffset = 32,
  tp_iter = 0x0, tp_iternext = 0x7ffff7a72100 <_PyObject_NextNotImplemented>, tp_methods = 0x0,
  tp_members = 0x6d3e68, tp_getset = 0x0,
  tp_base = 0x7ffff5a7cfa0 <boost::python::objects::class_type_object>, tp_dict = 0x7ffff7e98050,
  tp_descr_get = 0x0, tp_descr_set = 0x0, tp_dictoffset = 24,
  tp_init = 0x7ffff7a91f70 <slot_tp_init>, tp_alloc = 0x7ffff7a8ade0 <PyType_GenericAlloc>,
  tp_new = 0x7ffff5856890
     <boost::python::objects::instance_new(PyTypeObject*, PyObject*, PyObject*)>,
  tp_free = 0x7ffff7b1e2b0 <PyObject_GC_Del>, tp_is_gc = 0x0, tp_bases = 0x7ffff7e96410,
  tp_mro = 0x7ffff7e8e780, tp_cache = 0x0, tp_subclasses = 0x0, tp_weaklist = 0x7ffff7e77f70,
  tp_del = 0x0, tp_version_tag = 0}
(gdb) p/x 153595
$2 = 0x257fb

型の名前は "darray" となっており、Py_TPFLAGS_HAVE_ITER (= 0x80) は ON、tp_iter は NULL になっています。気づくまで時間がかかってしまったのですが、この TypeObject の内容と PyObject_GetIter のコードを見る限り、Py_TPFLAGS_HAVE_ITER の有無による影響はなく、いずれの場合でも f == NULL は true になります。そこで PySequence_Check の定義を見ます。

Objects/abstract.c
1843 int
1844 PySequence_Check(PyObject *s)
1845 {
1846     if (s == NULL)
1847         return 0;
1848     if (PyInstance_Check(s))
1849         return PyObject_HasAttrString(s, "__getitem__");
1850     if (PyDict_Check(s))
1851         return 0;
1852     return  s->ob_type->tp_as_sequence &&
1853         s->ob_type->tp_as_sequence->sq_item != NULL;
1854 }

darray オブジェクトは、3 つの if 文には引っかかりませんが、最後の条件で true になります。sq_item の値は slot_sq_item 関数になっています。slot_sq_item 関数は前回のデバッグ時に、iter_iternext から呼び出されており、これらが境界チェックをしていないのが無限ループの原因でした。

(gdb) p *$1.tp_as_sequence
$8 = {sq_length = 0x7ffff7a93f60 <slot_sq_length>, sq_concat = 0x0, sq_repeat = 0x0,
  sq_item = 0x7ffff7a91090 <slot_sq_item>, sq_slice = 0x0, sq_ass_item = 0x0, sq_ass_slice = 0x0,
  sq_contains = 0x0, sq_inplace_concat = 0x0, sq_inplace_repeat = 0x0}

そんなわけで PySequence_Check は true を返すので、PyObject_GetIter から PySeqIter_New が呼ばれて新しい iterator が作られます。その iterator が↓です。gdb に windbg で言うところの ub コマンドが無いのが辛い・・。

(gdb) x/5i 0x7ffff7ad7da1
   0x7ffff7ad7da1 <PyEval_EvalFrameEx+4225>:    mov    %rcx,%rbp
   0x7ffff7ad7da4 <PyEval_EvalFrameEx+4228>:    mov    -0x8(%rbx),%r13
   0x7ffff7ad7da8 <PyEval_EvalFrameEx+4232>:    mov    %r13,%rdi
   0x7ffff7ad7dab <PyEval_EvalFrameEx+4235>:    callq  0x7ffff7a0f550 <PyObject_GetIter@plt>
=> 0x7ffff7ad7db0 <PyEval_EvalFrameEx+4240>:    subq   $0x1,0x0(%r13)
(gdb) p *(seqiterobject*)$rax
$9 = {ob_refcnt = 1, ob_type = 0x7ffff7d9e9c0 <PySeqIter_Type>, it_index = 0,
  it_seq = 0x7ffff7ed5600}

つまり、__getitem__ だけを実装したオブジェクトはシーケンスとして扱われるが、Python はシーケンスもリストも iterator を使ってアクセスし、それは境界をいちいちチェックしない、という仕様になっています。つまりわりとどうしようもないです。冒頭で書いたように、クラス定義をしなくても通常関数をオブジェクト メソッドとして実装できるので、それが正しい解決策なのだと思います。

Boost のデバッグいつ出てくるんだ、という話ですが、Python オブジェクトから Py_TPFLAGS_HAVE_ITER フラグを消す方法を見つけるためにデバッグしました。

3. Boost.Python のコードをデバッグする

上述の o->ob_type が指すオブジェクトがいつ作られているのか、を追いかけます。Boost や Python のコードを見ても、Py_TPFLAGS_HAVE_ITER を個別に設定しているコードは無く、デフォルトの Py_TPFLAGS_DEFAULT で使われているだけです。darray の TypeObject が作られるヒントとしては、TypeObject の ob_type が ob_type = 0x7ffff5a7cc40 <boost::python::class_metatype_object> になっているのが使えます。

class_metatype_object は、Boost.Python のグローバル変数であり、これが使われる場所は一箇所しかありません。それが class_metatype() です。

src/object/class.cpp
315   BOOST_PYTHON_DECL type_handle class_metatype()
316   {
317       if (class_metatype_object.tp_dict == 0)
318       {
319           Py_TYPE(&class_metatype_object) = &PyType_Type;
320           class_metatype_object.tp_base = &PyType_Type;
321           if (PyType_Ready(&class_metatype_object))
322               return type_handle();
323       }
324       return type_handle(borrowed(&class_metatype_object));
325   }

幸い、この関数はインライン展開されないので、ここを起点にします。ポイントは、この関数はモジュールのインポート時に呼ばれることです。そこで、import 後の状態で関数の完全修飾名を調べてから、再度デバッグ ターゲットを実行します。

john@ubuntu1510:~/Documents/pyc$ gdb /usr/local/python/current/bin/python
GNU gdb (Ubuntu 7.10-1ubuntu2) 7.10
(略)
Reading symbols from /usr/local/python/current/bin/python…done.
(gdb) r
Starting program: /usr/local/python/python-2.7.11/bin/python
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Python 2.7.11 (default, Dec 22 2015, 22:30:16)
[GCC 5.2.1 20151010] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import ems # まずは何もせずインポート
>>>
Program received signal SIGINT, Interrupt.
0x00007ffff74e4723 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:81
81      ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) i func class_metatype # 完全修飾名を調べる
All functions matching regular expression "class_metatype":

File libs/python/src/object/class.cpp:
boost::python::type_handle boost::python::objects::class_metatype();

Non-debugging symbols:
0x00007ffff5845c40  boost::python::objects::class_metatype()@plt
(gdb) r # 再実行
The program being debugged has been started already.
Start it from the beginning? (y or n) y
Starting program: /usr/local/python/python-2.7.11/bin/python
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Python 2.7.11 (default, Dec 22 2015, 22:30:16)
[GCC 5.2.1 20151010] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>>
Program received signal SIGINT, Interrupt.
0x00007ffff74e4723 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:81
81      ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) b boost::python::objects::class_metatype # import 前にブレークポイント
Function "boost::python::objects::class_metatype" not defined.
Make breakpoint pending on future shared library load? (y or [n]) y
Breakpoint 1 (boost::python::objects::class_metatype) pending.
(gdb) c
Continuing.

>>> import ems

Breakpoint 1, 0x00007ffff5845c40 in boost::python::objects::class_metatype()@plt ()
   from /usr/local/boost/current/lib/libboost_python.so.1.60.0
(gdb) i b
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   <MULTIPLE>
        breakpoint already hit 1 time
1.1                         y     0x00007ffff5845c40 <boost::python::objects::class_metatype()@plt>
1.2                         y     0x00007ffff5856b00 in boost::python::objects::class_metatype()
                                                   at libs/python/src/object/class.cpp:317
(gdb) disable 1.1 # plt 上のブレークポイントは無効
(gdb) c
Continuing.

Breakpoint 1, boost::python::objects::class_metatype () at libs/python/src/object/class.cpp:317
317           if (class_metatype_object.tp_dict == 0)
(gdb)

もう一点。この方法だと、モジュールがロードされたときにシンボル名をもとにアドレスをに検索するので、対象が共有ライブラリの場合、関数の先頭のアドレス以外に、plt 上のアドレスにもブレークポイントが設定されます。これは邪魔なので無効にしておきます。

PLT とは Procedure Linkage Table の略で、Windows でいうところのインポート テーブルと似たようなものです。

Technovelty – PLT and GOT – the key to code sharing and dynamic libraries
https://www.technovelty.org/linux/plt-and-got-the-key-to-code-sharing-and-dynamic-libraries.html

コールスタックを見ると、shared.cpp に実装された init_module_ems から、class_ クラスのコンストラクタ (#4) 経由で呼ばれています。テンプレートの入れ子で、シンボル名が複雑怪奇です。

(gdb) bt 10
#0  boost::python::objects::class_metatype () at libs/python/src/object/class.cpp:317
#1  0x00007ffff5856bb8 in boost::python::objects::class_type ()
    at libs/python/src/object/class.cpp:473
#2  0x00007ffff5857d8d in boost::python::objects::(anonymous namespace)::new_class (
    doc=<optimized out>, types=0x7fffffffdd90, num_types=1, name=<optimized out>)
    at libs/python/src/object/class.cpp:561
#3  boost::python::objects::class_base::class_base (this=0x7fffffffdbf0,
    name=0x7ffff5a89bd5 "Field", num_types=1, types=0x7fffffffdd90, doc=0x0)
    at libs/python/src/object/class.cpp:591
#4  0x00007ffff5a874be in boost::python::class_<Field, boost::python::detail::not_specified, boost::python::detail::not_specified, boost::python::detail::not_specified>::class_<boost::python::init<int, mpl_::void_, mpl_::void_, mpl_::void_, mpl_::void_, mpl_::void_, mpl_::void_, mpl_::void_, mpl_::void_, mpl_::void_, mpl_::void_, mpl_::void_, mpl_::void_, mpl_::void_, mpl_::void_> > (i=…,
    name=0x7ffff5a89bd5 "Field", this=0x7fffffffdbf0)
    at /usr/local/boost/current/include/boost/python/class.hpp:206
#5  init_module_ems () at shared.cpp:51
#6  0x00007ffff58639f3 in boost::function0<void>::operator() (this=0x7fffffffde50)
    at ./boost/function/function_template.hpp:771
#7  boost::python::handle_exception_impl (f=…) at libs/python/src/errors.cpp:25
#8  0x00007ffff5864736 in boost::python::handle_exception<void (*)()> (
    f=0x7ffff5a87440 <init_module_ems()>) at ./boost/python/errors.hpp:29
#9  boost::python::detail::(anonymous namespace)::init_module_in_scope (
    init_function=<optimized out>, m=0x7ffff7e937c0) at libs/python/src/module.cpp:24
(More stack frames follow…)

#3 の class_base のコンストラクタは以下のように定義されています。

src/object/class.cpp
589   class_base::class_base(
590       char const* name, std::size_t num_types, type_info const* const types, char const* doc)
591       : object(new_class(name, num_types, types, doc))
592   {
593       // Insert the new class object in the registry
594       converter::registration& converters = const_cast<converter::registration&>(
595           converter::registry::lookup(types[0]));
596
597       // Class object is leaked, for now
598       converters.m_class_object = (PyTypeObject*)incref(this->ptr());
599   }

class_metatype() は初期化リストのなかで使われています。ここでの object とは、class_base の基底クラスの一つです。object クラスを new_class 関数の戻り値で初期化すると、m_ptr というメンバー関数が初期化されます。引数の types を元に lookup してきたコンバーターの m_class_object に、その m_ptr を代入する、というのがこのコンストラクターの動作です。

ブレークポイントを設定した class_metatype() は、new_class() から 2 回呼ばれます。line:561 の class_type() 経由と、line:575 です。戻り値に直接関係あるのは後者です。

src/object/class.cpp
548     inline object
549     new_class(char const* name, std::size_t num_types, type_info const* const types, char const*     doc)
550     {
551       assert(num_types >= 1);
552
553       // Build a tuple of the base Python type objects. If no bases
554       // were declared, we’ll use our class_type() as the single base
555       // class.
556       ssize_t const num_bases = (std::max)(num_types – 1, static_cast<std::size_t>(1));
557       handle<> bases(PyTuple_New(num_bases));
558
559       for (ssize_t i = 1; i <= num_bases; ++i)
560       {
561           type_handle c = (i >= static_cast<ssize_t>(num_types)) ? class_type() : get_class(type    s[i]);
562           // PyTuple_SET_ITEM steals this reference
563           PyTuple_SET_ITEM(bases.get(), static_cast<ssize_t>(i – 1), upcast<PyObject>(c.release(    )));
564       }
565
566       // Call the class metatype to create a new class
567       dict d;
568
569       object m = module_prefix();
570       if (m) d["__module__"] = m;
571
572       if (doc != 0)
573           d["__doc__"] = doc;
574
575       object result = object(class_metatype())(name, bases, d);
576       assert(PyType_IsSubtype(Py_TYPE(result.ptr()), &PyType_Type));
577
578       if (scope().ptr() != Py_None)
579           scope().attr(name) = result;
580
581       // For pickle. Will lead to informative error messages if pickling
582       // is not enabled.
583       result.attr("__reduce__") = object(make_instance_reduce_function());
584
585       return result;
586     }
587   }

1 回目の呼び出しはスルーして、2 回目の呼び出しで止めます。

(gdb) b boost::python::objects::class_metatype
Function "boost::python::objects::class_metatype" not defined.
Make breakpoint pending on future shared library load? (y or [n]) y
Breakpoint 1 (boost::python::objects::class_metatype) pending.
(gdb) r
Starting program: /usr/local/python/python-2.7.11/bin/python
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Python 2.7.11 (default, Dec 22 2015, 22:30:16)
[GCC 5.2.1 20151010] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import ems

Breakpoint 1, 0x00007ffff5845c40 in boost::python::objects::class_metatype()@plt ()
   from /usr/local/boost/current/lib/libboost_python.so.1.60.0
(gdb) i b
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   <MULTIPLE>
        breakpoint already hit 1 time
1.1                         y     0x00007ffff5845c40 <boost::python::objects::class_metatype()@plt>
1.2                         y     0x00007ffff5856b00 in boost::python::objects::class_metatype()
                                                   at libs/python/src/object/class.cpp:317
(gdb) disable 1.1
(gdb) c
Continuing.

Breakpoint 1, boost::python::objects::class_metatype () at libs/python/src/object/class.cpp:317
317           if (class_metatype_object.tp_dict == 0)
(gdb) bt 4
#0  boost::python::objects::class_metatype () at libs/python/src/object/class.cpp:317
#1  0x00007ffff5856bb8 in boost::python::objects::class_type ()
    at libs/python/src/object/class.cpp:473
#2  0x00007ffff5857d8d in boost::python::objects::(anonymous namespace)::new_class (
    doc=<optimized out>, types=0x7fffffffdd90, num_types=1, name=<optimized out>)
    at libs/python/src/object/class.cpp:561
#3  boost::python::objects::class_base::class_base (this=0x7fffffffdbf0,
    name=0x7ffff5a89bd5 "Field", num_types=1, types=0x7fffffffdd90, doc=0x0)
    at libs/python/src/object/class.cpp:591
(More stack frames follow…)
(gdb) c
Continuing.

Breakpoint 1, boost::python::objects::class_metatype () at libs/python/src/object/class.cpp:317
317           if (class_metatype_object.tp_dict == 0)
(gdb) bt 3
#0  boost::python::objects::class_metatype () at libs/python/src/object/class.cpp:317
#1  0x00007ffff5857f92 in boost::python::objects::(anonymous namespace)::new_class (
    doc=<optimized out>, types=0x7fffffffdd90, num_types=1, name=<optimized out>)
    at libs/python/src/object/class.cpp:575
#2  boost::python::objects::class_base::class_base (this=0x7fffffffdbf0,
    name=0x7ffff5a89bd5 "Field", num_types=1, types=0x7fffffffdd90, doc=0x0)
    at libs/python/src/object/class.cpp:591
(More stack frames follow…)
(gdb)

line:575 の "object(class_metatype())(name, bases, d);" で、object が関数なのかコンストラクタなのか理解に苦しむところです。後半の (name, bases, d) は operator() 呼び出しだと推測は出来ます。この行は最適化が有効だと全部インライン展開されるので、とりあえず class_metatype() から戻ってきたところでアセンブリを見ます。

(gdb) fin
Run till exit from #0  boost::python::objects::class_metatype ()
    at libs/python/src/object/class.cpp:317
boost::python::objects::(anonymous namespace)::new_class (doc=<optimized out>,
    types=0x7fffffffdd90, num_types=1, name=<optimized out>)
    at libs/python/src/object/class.cpp:575
Value returned is $1 = {m_p = 0x7fffffffdaa0}
(gdb) x/20i $rip
=> 0x7ffff5857f92 <…+690>:   mov    0x60(%rsp),%rbx
   0x7ffff5857f97 <…+695>:   test   %rbx,%rbx
   0x7ffff5857f9a <…+698>:   je     0x7ffff5858582 <…+2210>
   0x7ffff5857fa0 <…+704>:   addq   $0x1,(%rbx)
   0x7ffff5857fa4 <…+708>:   test   %rbp,%rbp
   0x7ffff5857fa7 <…+711>:   mov    0x40(%rsp),%r14
   0x7ffff5857fac <…+716>:   mov    %rbp,%r13
   0x7ffff5857faf <…+719>:   je     0x7ffff5858576 <…+2198>
   0x7ffff5857fb5 <…+725>:   mov    0x18(%rsp),%rdi
   0x7ffff5857fba <…+730>:   callq  0x7ffff5844d40 <_ZN5boost6python9converter19do_return_to_pythonEPKc@plt>
   0x7ffff5857fbf <…+735>:   test   %rax,%rax
   0x7ffff5857fc2 <…+738>:   mov    %rax,%r12
   0x7ffff5857fc5 <…+741>:   je     0x7ffff58585bd <…+2269>
   0x7ffff5857fcb <…+747>:   lea    0x1705a(%rip),%rsi        # 0x7ffff586f02c
   0x7ffff5857fd2 <…+754>:   mov    %r14,%r8
   0x7ffff5857fd5 <…+757>:   mov    %r13,%rcx
   0x7ffff5857fd8 <…+760>:   mov    %r12,%rdx
   0x7ffff5857fdb <…+763>:   mov    %rbx,%rdi
   0x7ffff5857fde <…+766>:   xor    %eax,%eax
   0x7ffff5857fe0 <…+768>:   callq  0x7ffff5845a30 <PyEval_CallFunction@plt>
(gdb)

PyEval_CallFunction という Python API の呼び出しが怪しいのでここで止めます。

(gdb) b PyEval_CallFunction
Breakpoint 2 at 0x7ffff7b00fd0: file Python/modsupport.c, line 544.
(gdb) c
Continuing.

Breakpoint 2, PyEval_CallFunction (
    obj=obj@entry=0x7ffff5a7cc40 <boost::python::class_metatype_object>,
    format=format@entry=0x7ffff586f02c "(OOO)") at Python/modsupport.c:544
544     {
(gdb) bt 5
#0  PyEval_CallFunction (obj=obj@entry=0x7ffff5a7cc40 <boost::python::class_metatype_object>,
    format=format@entry=0x7ffff586f02c "(OOO)") at Python/modsupport.c:544

#1  0x00007ffff5857fe5 in boost::python::call<boost::python::api::object, char const*, boost::python::handle<_object>, boost::python::dict> (a2=…, a1=<synthetic pointer>, a0=<synthetic pointer>,
    callable=0x7ffff5a7cc40 <boost::python::class_metatype_object>) at ./boost/python/call.hpp:66
#2  boost::python::api::object_operators<boost::python::api::object>::operator()<char const*, boost::python::handle<_object>, boost::python::dict> (a2=…, a1=<synthetic pointer>,
    a0=<synthetic pointer>, this=<optimized out>) at ./boost/python/object_call.hpp:19
#3  boost::python::objects::(anonymous namespace)::new_class (doc=<optimized out>,
    types=0x7fffffffdd90, num_types=<optimized out>, name=<optimized out>)
    at libs/python/src/object/class.cpp:575
#4  boost::python::objects::class_base::class_base (this=0x7fffffffdbf0,
    name=0x7ffff5a89bd5 "Field", num_types=<optimized out>, types=0x7fffffffdd90, doc=0x0)
    at libs/python/src/object/class.cpp:591
(More stack frames follow…)
(gdb)

PyEval_CallFunction は、C/C++ から Python の関数を呼ぶための API です。第二引数の format が "(OOO)" になっているので、3 つのオブジェクトからなるタプルを引数として Python の関数を呼んでいます。何の関数を呼ぶのかは、第一引数を見れば分かります。

(gdb) p *obj->ob_type
$4 = {ob_refcnt = 41, ob_type = 0x7ffff7daaf60 <PyType_Type>, ob_size = 0,
  tp_name = 0x7ffff7b4008c "type", tp_basicsize = 872, tp_itemsize = 40,
  tp_dealloc = 0x7ffff7a8b1f0 <type_dealloc>, tp_print = 0x0, tp_getattr = 0x0, tp_setattr = 0x0,
  tp_compare = 0x0, tp_repr = 0x7ffff7a8f600 <type_repr>, tp_as_number = 0x0,
  tp_as_sequence = 0x0, tp_as_mapping = 0x0, tp_hash = 0x7ffff7a70be0 <_Py_HashPointer>,
  tp_call = 0x7ffff7a908a0 <type_call>, tp_str = 0x7ffff7a8acc0 <object_str>,
  tp_getattro = 0x7ffff7a9a2c0 <type_getattro>, tp_setattro = 0x7ffff7a91930 <type_setattro>,
  tp_as_buffer = 0x0, tp_flags = 2148423147,
  tp_doc = 0x7ffff7da8f80 <type_doc> "type(object) -> the object’s type\ntype(name, bases, dict) -> a new type", tp_traverse = 0x7ffff7a8c2c0 <type_traverse>, tp_clear = 0x7ffff7a90370 <type_clear>,
  tp_richcompare = 0x7ffff7a8bac0 <type_richcompare>, tp_weaklistoffset = 368, tp_iter = 0x0,
  tp_iternext = 0x0, tp_methods = 0x7ffff7da9200 <type_methods>,
  tp_members = 0x7ffff7da9500 <type_members>, tp_getset = 0x7ffff7da93e0 <type_getsets>,
  tp_base = 0x7ffff7daadc0 <PyBaseObject_Type>, tp_dict = 0x7ffff7f98280, tp_descr_get = 0x0,
  tp_descr_set = 0x0, tp_dictoffset = 264, tp_init = 0x7ffff7a8d3b0 <type_init>,
  tp_alloc = 0x7ffff7a8ade0 <PyType_GenericAlloc>, tp_new = 0x7ffff7a98200 <type_new>,
  tp_free = 0x7ffff7b1e2b0 <PyObject_GC_Del>, tp_is_gc = 0x7ffff7a8aca0 <type_is_gc>,
  tp_bases = 0x7ffff7f9b090, tp_mro = 0x7ffff7f9a878, tp_cache = 0x0,
  tp_subclasses = 0x7ffff7f4ce60, tp_weaklist = 0x7ffff7f9e050, tp_del = 0x0, tp_version_tag = 11}

名前と doc から、これは Python の組み込み関数 type() であることが分かります。どうやら Boost.Python は、Python の組み込み関数を使って型を作っているようです。テンプレートでこんなことができるとか Boost 凄すぎ・・。

Python のコードの中に、新しい型オブジェクトを作る関数があるはずなので、それを適当なキーワード (Py_TPFLAGS_HAVE_GC とか) を使って探すと、type_new というそれっぽい関数が Objects/typeobject.c に見つかるので、ここで止めます。

(gdb) i b
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   <MULTIPLE>
        breakpoint already hit 3 times
1.1                         n     0x00007ffff5845c40 <boost::python::objects::class_metatype()@plt>
1.2                         y     0x00007ffff5856b00 in boost::python::objects::class_metatype()
                                                   at libs/python/src/object/class.cpp:317
2       breakpoint     keep y   0x00007ffff7b00fd0 in PyEval_CallFunction
                                                   at Python/modsupport.c:544
        breakpoint already hit 1 time
(gdb) disable
(gdb) b type_new
Breakpoint 3 at 0x7ffff7a98200: file Objects/typeobject.c, line 2068.
(gdb) c
Continuing.

Breakpoint 3, type_new (metatype=0x7ffff5a7cc40 <boost::python::class_metatype_object>,
    args=0x7ffff7e8e370, kwds=0x0) at Objects/typeobject.c:2068
2068    {
(gdb) bt 8
#0  type_new (metatype=0x7ffff5a7cc40 <boost::python::class_metatype_object>, args=0x7ffff7e8e370,
    kwds=0x0) at Objects/typeobject.c:2068
#1  0x00007ffff7a908c3 in type_call (type=0x7ffff5a7cc40 <boost::python::class_metatype_object>,
    args=0x7ffff7e8e370, kwds=0x0) at Objects/typeobject.c:729
#2  0x00007ffff7a244e3 in PyObject_Call (
    func=func@entry=0x7ffff5a7cc40 <boost::python::class_metatype_object>,
    arg=arg@entry=0x7ffff7e8e370, kw=<optimized out>) at Objects/abstract.c:2546
#3  0x00007ffff7ad6707 in PyEval_CallObjectWithKeywords (
    func=func@entry=0x7ffff5a7cc40 <boost::python::class_metatype_object>,
    arg=arg@entry=0x7ffff7e8e370, kw=kw@entry=0x0) at Python/ceval.c:4219
#4  0x00007ffff7b01087 in PyEval_CallFunction (
    obj=obj@entry=0x7ffff5a7cc40 <boost::python::class_metatype_object>,
    format=format@entry=0x7ffff586f02c "(OOO)") at Python/modsupport.c:557
#5  0x00007ffff5857fe5 in boost::python::call<boost::python::api::object, char const*, boost::python::handle<_object>, boost::python::dict> (a2=…, a1=<synthetic pointer>, a0=<synthetic pointer>,
    callable=0x7ffff5a7cc40 <boost::python::class_metatype_object>) at ./boost/python/call.hpp:66
#6  boost::python::api::object_operators<boost::python::api::object>::operator()<char const*, boost::python::handle<_object>, boost::python::dict> (a2=…, a1=<synthetic pointer>,
    a0=<synthetic pointer>, this=<optimized out>) at ./boost/python/object_call.hpp:19
#7  boost::python::objects::(anonymous namespace)::new_class (doc=<optimized out>,
    types=0x7fffffffdd90, num_types=<optimized out>, name=<optimized out>)
    at libs/python/src/object/class.cpp:575
(More stack frames follow…)

ここまで来れば、答えは見えました。この関数の中で PyTypeObject を作って返すのですが、tp_flags をセットするときに Py_TPFLAGS_DEFAULT を使っています。したがって、新しい型は必ず Py_TPFLAGS_HAVE_ITER フラグを持っています。というかわざわざデバッグしなくても、Python のドキュメントのどこかに書いてありそう。

2066 static PyObject *
2067 type_new(PyTypeObject *metatype, PyObject *args, PyObject *kwds)
2068 {
2069     PyObject *name, *bases, *dict;
2070     static char *kwlist[] = {"name", "bases", "dict", 0};

2326     /* Initialize tp_flags */
2327     type->tp_flags = Py_TPFLAGS_DEFAULT | Py_TPFLAGS_HEAPTYPE |
2328         Py_TPFLAGS_BASETYPE;

2329     if (base->tp_flags & Py_TPFLAGS_HAVE_GC)
2330         type->tp_flags |= Py_TPFLAGS_HAVE_GC;
2331     if (base->tp_flags & Py_TPFLAGS_HAVE_NEWBUFFER)
2332         type->tp_flags |= Py_TPFLAGS_HAVE_NEWBUFFER;

4. PyTypeObject::tp_flags を動的に変更する方法

Boost.Python や Python の実装を見ても、tp_flags を変更する API は用意されていないようです。しかし boost::python::objects::class_base::class_base の実装から分かるように、各型のひな形となるような TypeObject は、 boost::python::converter::registry::lookup で取ってきたコンバーターの m_class_object から取得できそうです。そこで、以下のようなコードを試してみます。

#include <boost/python.hpp>
#include <valarray>
#include <random>
#include <stdio.h>

std::default_random_engine generator;
std::uniform_real_distribution<double> distribution(0.0, 1.0);

void ChangeType();

typedef std::valarray<double> darray;

class Field {
private:
    darray _data;

public:
    Field(int n) : _data(n) {
        printf("Field::Field(): %p\n", this);
        ChangeType();
    }
    ~Field() {
        printf("Field::~Field() %p\n", this);
    }

    void Dump() const {
        printf("[");
        for (auto &d : _data) {
            printf("% 3.3f", d);
        }
        printf(" ]\n");
    }

    void Churn() {
        for (auto &d : _data) {
            d = distribution(generator);
        }
    }

    const darray &Positions() const {
        return _data;
    }
};

using namespace boost::python;

BOOST_PYTHON_MODULE(ems) {
    class_<Field>("Field", init<int>())
        .def("Positions", &Field::Positions,
             return_internal_reference<>())
        .def("Dump", &Field::Dump)
        .def("Churn", &Field::Churn)
        ;

    class_<darray>("darray")
        .def("__getitem__",
             (const double &(darray::*)(size_t) const)&darray::operator[],
             return_value_policy<copy_const_reference>())
        .def("__len__", &darray::size)
        ;
}

void ChangeType() {
    converter::registration const& converters =
        converter::registry::lookup(type_id<darray>());
    long l = converters.m_class_object->tp_flags;
    converters.m_class_object->tp_flags = l & ~Py_TPFLAGS_HAVE_ITER;
    printf("converters.m_class_object = %p\n", converters.m_class_object);
    printf("tp_flags: %08lx -> %08lx\n", l, converters.m_class_object->tp_flags);
}

ChangeType() という関数を作って、Field のコンストラクターから呼ぶコードを追加しました。これを Python から実行して、darray の tp_flags を確認します。

john@ubuntu1510:~/Documents/pyc$ gdb /usr/local/python/current/bin/python
GNU gdb (Ubuntu 7.10-1ubuntu2) 7.10
(略)
Reading symbols from /usr/local/python/current/bin/python…done.
(gdb) r
Starting program: /usr/local/python/python-2.7.11/bin/python
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Python 2.7.11 (default, Dec 22 2015, 22:30:16)
[GCC 5.2.1 20151010] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import ems
>>> f = ems.Field(4)
Field::Field(): 0x6d09d0
converters.m_class_object = 0x6d3b00
tp_flags: 000257fb -> 0002577b

>>> x = f.Positions()
>>> x
<ems.darray object at 0x7ffff7ed5600>
>>>
Program received signal SIGINT, Interrupt.
0x00007ffff74e4723 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:81
81      ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) p *(PyObject*)0x7ffff7ed5600
$1 = {ob_refcnt = 2, ob_type = 0x6d3b00}
(gdb) p *$1.ob_type
$2 = {ob_refcnt = 5, ob_type = 0x7ffff5a7cc40 <boost::python::class_metatype_object>, ob_size = 0,
  tp_name = 0x7ffff7e94954 "darray", tp_basicsize = 48, tp_itemsize = 1,
  tp_dealloc = 0x7ffff7a8b390 <subtype_dealloc>, tp_print = 0x0, tp_getattr = 0x0,
  tp_setattr = 0x0, tp_compare = 0x0, tp_repr = 0x7ffff7a8f390 <object_repr>,
  tp_as_number = 0x6d3c88, tp_as_sequence = 0x6d3dd8, tp_as_mapping = 0x6d3dc0,
  tp_hash = 0x7ffff7a70be0 <_Py_HashPointer>, tp_call = 0x0, tp_str = 0x7ffff7a8acc0 <object_str>,
  tp_getattro = 0x7ffff7a72410 <PyObject_GenericGetAttr>,
  tp_setattro = 0x7ffff7a72670 <PyObject_GenericSetAttr>, tp_as_buffer = 0x6d3e28,
  tp_flags = 153467, tp_doc = 0x0, tp_traverse = 0x7ffff7a8b0a0 <subtype_traverse>,
  tp_clear = 0x7ffff7a8d290 <subtype_clear>, tp_richcompare = 0x0, tp_weaklistoffset = 32,
  tp_iter = 0x0, tp_iternext = 0x7ffff7a72100 <_PyObject_NextNotImplemented>, tp_methods = 0x0,
  tp_members = 0x6d3e68, tp_getset = 0x0,
  tp_base = 0x7ffff5a7cfa0 <boost::python::objects::class_type_object>, tp_dict = 0x7ffff7e98050,
  tp_descr_get = 0x0, tp_descr_set = 0x0, tp_dictoffset = 24,
  tp_init = 0x7ffff7a91f70 <slot_tp_init>, tp_alloc = 0x7ffff7a8ade0 <PyType_GenericAlloc>,
  tp_new = 0x7ffff5856890
     <boost::python::objects::instance_new(PyTypeObject*, PyObject*, PyObject*)>,
  tp_free = 0x7ffff7b1e2b0 <PyObject_GC_Del>, tp_is_gc = 0x0, tp_bases = 0x7ffff7e96410,
  tp_mro = 0x7ffff7e8e780, tp_cache = 0x0, tp_subclasses = 0x0, tp_weaklist = 0x7ffff7e77f70,
  tp_del = 0x0, tp_version_tag = 0}
(gdb) p/x 153467
$3 = 0x2577b

思惑通り、tp_flags から Py_TPFLAGS_HAVE_ITER を消せました。今回は tp_flags を変えても全く意味がなかったのですが、これで TypeObject の内容は思いのままです。Boost.Python では、初期化時に int など基本型の TypeObject も列挙しているので、基本型の中身を変更する禁じ手も可能です。そんなことをしたらいろいろ壊れそうですが。

How to expose a valarray with Boost.Python

Python のパフォーマンスの不利を補うため、C++ で書いた共有ライブラリを Python のモジュールとして利用することができます。前回の速度比較の結果から、ベクトルの四則演算を std::valarray の形のまま実行すべく C++ のコードを書いたところ、思わぬ結果として Python の罠を見つけたので経緯を含めて紹介します。

1. Boost.Python を使う

まず、C++ で Python モジュールを書く方法ですが、伝統的な Python.h をインクルードして C で書く方法と、Boost.Python のテンプレートを使って C++ で書く方法の 2 通りがあります。Boost の方が圧倒的に楽です。以下のサイトの説明がとても分かりやすい。

c/c++をラップしてpythonで使えるように – Python | Welcome to underground
https://www.quark.kj.yamagata-u.ac.jp/~hiroki/python/?id=19

Boost.Python の機能をざっと紹介してみる – muddy brown thang
http://d.hatena.ne.jp/moriyoshi/20091214/1260779899

その他、ctypes モジュールを使って外部モジュールのエクスポート関数を呼び出す方法 (Windows で言うところの LoadLibrary と GetProcAddress を Python から呼べる) もありますが、これは関数が呼べるだけで、Python のモジュールやオブジェクトを作れるわけではないので、少し趣向が異なります。もし ctypes で間に合うなら一番楽な方法だと思います。

今実現したいのは、次のような動作を実装した C++ クラスを Python モジュールとして見せることです。

  1. std::valarray<double> を内部データとして保持
  2. 演算は valarray のまま実行する
  3. プロット描画のため、valarray を何らかの形で matplotlib.collections.PathCollection.set_offsets(offsets) に渡したい

3. についてですが、matplotlib のリファレンスを見ると、set_offsets の引数は "offsets can be a scalar or a sequence." という妙に曖昧な説明しかありません。

collections — Matplotlib 1.5.0 documentation
http://matplotlib.org/api/collections_api.html#matplotlib.collections.PathCollection

GitHub 上のコードを見ると、引数の offsets はすぐに np.asanyarray によって np.ndarray に変換されて 2 列の行列に変形させられるので、ndarray に変換可能なオブジェクトなら何でもよい、ということになります。

https://github.com/matplotlib/matplotlib/blob/master/lib/matplotlib/collections.py

C++ 側で列数が 2 の numpy.ndarray オブジェクトを作ることができれば速度的にはベストですが、面倒そうなのと、C++ のモジュールが Numpy に依存するのもあまり美しくないので、Python のリストを返すことができれば十分です。そこで、上記のサイトを参考にしつつ動作確認のため以下の C++ コードを書きました。

実行環境は前回と同じです。

  • OS: Ubuntu 15.10
  • gcc (Ubuntu 5.2.1-22ubuntu2) 5.2.1 20151010
  • Python 2.7.10

C++ ソースコード: shared.cpp

#include <boost/python.hpp>
#include <valarray>
#include <random>
#include <stdio.h>

std::default_random_engine generator;
std::uniform_real_distribution<double> distribution(0.0, 1.0);

typedef std::valarray<double> darray;

class Field {
private:
    darray _data;

public:
    Field(int n) : _data(n) {
        printf("Field::Field(): %p\n", this);
    }
    ~Field() {
        printf("Field::~Field() %p\n", this);
    }

    void Dump() const {
        printf("[");
        for (auto &d : _data) {
            printf("% 3.3f", d);
        }
        printf(" ]\n");
    }

    void Churn() {
        for (auto &d : _data) {
            d = distribution(generator);
        }
    }

    const darray &Positions() const {
        return _data;
    }
};

BOOST_PYTHON_MODULE(ems) {
    using namespace boost::python;

    class_<Field>("Field", init<int>())
        .def("Positions", &Field::Positions,
             return_value_policy<copy_const_reference>())
        .def("Dump", &Field::Dump)
        .def("Churn", &Field::Churn)
        ;

    class_<darray>("darray")
        .def("__getitem__",
             (const double &(darray::*)(size_t) const)&darray::operator[],
             return_value_policy<copy_const_reference>())
        .def("__len__", &darray::size)
        ;
}

メイク ファイル: Makefile

CC=g++
RM=rm -f

TARGET=ems.so
SRCS=$(wildcard *.cpp)
OBJS=$(SRCS:.cpp=.o)

override CFLAGS+=-Wall -fPIC -std=c++11 -O2 -g
LFLAGS=

INCLUDES=-I/usr/include/python2.7
LIBS=-lpython2.7 -lboost_python

all: clean $(TARGET)

clean:
        $(RM) $(OBJS) $(TARGET)

$(TARGET): $(OBJS)
        $(CC) -shared $(LFLAGS) $(LIBDIRS) $^ -o $@ $(LIBS)

$(OBJS): $(SRCS)
        $(CC) $(INCLUDES) $(CFLAGS) -c $^

Field クラスを Python オブジェクトとして扱えるようにします。このとき、valarray の const 参照を返すメンバ関数の Field::Positions を Python オブジェクトのメソッドとして実装するため、valarray のコンバーターを別途作って __getitem__ と __len__ メソッドを実装します。これは一種のダック タイピングで、Python 側ではシーケンスとして見えるようになります。

Field::Positions は Field::_data の参照を返すようにしておかないと、Positions を呼ぶたびに valarray をコピーして Python に渡すようになるので、速度が落ちます。しかし、実は上記のコードは間違っています。試しにこのまま Python から使ってみると以下の結果が得られます。

>>> import ems
>>> f = ems.Field(4)
Field::Field(): 0x2011a50
>>> x = f.Positions()
>>> f.Dump()
[ 0.000 0.000 0.000 0.000 ]
>>> x[0]
0.0

>>> f.Churn()
>>> f.Dump()
[ 0.132 0.459 0.219 0.679 ]
>>> x[0]
0.0

>>> quit()
Field::~Field() 0x2011a50
john@ubuntu1510:~/Documents/pyc$

f.Churn() で C++ 側の値を変更した後も、Python 側のシーケンスの値が 0 のままで変わっていません。x = f.Position() したときに、valarray がコピーされたようです。Positions を定義するときの return_value_policy で copy_const_reference ポリシーを使っているのがいけないのです。

    class_<Field>("Field", init<int>())
        .def("Positions", &Field::Positions,
             return_value_policy<copy_const_reference>())

以下のページに記載があるように、このポリシーは "returning a reference-to-const type such that the referenced value is copied into a new Python object." です。ポリシーの名前で勘違いしていましたが、これは、参照をコピーして Python に渡すのではなく、"参照された値" をコピーします。Positions の戻り値となる Python オブジェクトを作るときに、参照に対してコピー コンストラクタを呼んで、そのコピーをオブジェクトに保持させるのだと思います。これでは参照を使う意味がありません。

Boost.Python – <boost/python/copy_const_reference.hpp> – 1.54.0
http://www.boost.org/doc/libs/1_54_0/libs/python/doc/v2/copy_const_reference.html

ここで使うべきポリシーは、return_internal_reference です。説明によると "CallPolicies which allow pointers and references to objects held internally by a free or member function argument or from the target of a member function to be returned safely without making a copy of the referent" となっています。

Boost.Python – <boost/python/return_internal_reference.hpp> – 1.54.0
http://www.boost.org/doc/libs/1_54_0/libs/python/doc/v2/return_internal_reference.html

コードをこう変えます。

class_<Field>("Field", init<int>())
    .def("Positions", &Field::Positions,
         return_internal_reference<>())

これで、C++ オブジェクトへの参照を Python が保持できるようになりました。

>>> import ems
>>> f = ems.Field(4)
Field::Field(): 0xde4a50
>>> f.Dump()
[ 0.000 0.000 0.000 0.000 ]
>>> x = f.Positions()
>>> x[0]
0.0
>>> f.Churn()
>>> f.Dump()
[ 0.132 0.459 0.219 0.679 ]
>>> x[0]
0.13153778773876065

>>> x
<ems.darray object at 0x7fded8919130>
>>> y = f.Positions()
>>> y
<ems.darray object at 0x7fded89193d0>
>>> y[0]
0.13153778773876065
>>> quit()
Field::~Field() 0xde4a50

上記の例で、f.Positions() の戻り値である ems.darray オブジェクトの x と y を単純に表示させた値が異なっています。これも最初勘違いしていましたが、Positions() を呼ぶたびに、ems.darray という Python オブジェクトは常に新しく作られます。それぞれの ems.darray が同じ valarray への参照を内包する構造になっています。

2. Python のハングと原因

ここから本題です。先ほど作った ems.Field を matplotlib の set_offsets に渡すとハングすることが分かりました。上で既に触れたとおり、set_offsets は引数を ndarray に変換しているだけなので、以下のコードで簡単に再現できます。

>>> import ems
>>> import numpy as np
>>> np.__version__
‘1.10.1’
>>> f = ems.Field(4)
Field::Field(): 0x16f90b0
>>> x = f.Positinos()
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
AttributeError: ‘Field’ object has no attribute ‘Positinos’
>>> x = f.Positions()
>>> x[0]
0.0
>>> len(x)
4
>>> a = np.array(x) # ここでハング

__getitem__ と __len__ だけだとリストに見せかけるのは無理なのかと諦めかけていたのですが、偶然、Numpy 1.8 だと問題なく動くことが分かりました。

>>> import ems
>>> import numpy as np
>>> np.__version__
‘1.8.2’
>>> f = ems.Field(4)
Field::Field(): 0x233acf0
>>> x = f.Positions()
>>> a = np.array(x)
>>> x[0]
0.0
>>> a
array([ 0.,  0.,  0.,  0.])

Numpy 側のコードを比べると、1.8.x から 1.9.x にバージョンが上がった時に、PyArray_DTypeFromObjectHelper() のロジックが少し変更されています。520 行目あたりで青字の部分が追加されており、ハングは PySequence_Fast から制御が返ってこないことで発生しています。

https://github.com/numpy/numpy/blob/maintenance/1.8.x/numpy/core/src/multiarray/common.c
https://github.com/numpy/numpy/blob/maintenance/1.9.x/numpy/core/src/multiarray/common.c

/*
* fails if convertable to list but no len is defined which some libraries
* require to get object arrays
*/
size = PySequence_Size(obj);
if (size < 0) {
    goto fail;
}

/* Recursive case, first check the sequence contains only one type */
seq = PySequence_Fast(obj, "Could not convert object to sequence");
if (seq == NULL) {
    goto fail;
}

objects = PySequence_Fast_ITEMS(seq);
common_type = size > 0 ? Py_TYPE(objects[0]) : NULL;
for (i = 1; i < size; ++i) {
    if (Py_TYPE(objects[i]) != common_type) {
        common_type = NULL;
        break;
    }
}

結論から先に書くと、ems.darray の __getitem__ を実装するときに、valarray::operator[] を渡しているのが諸悪の根源でした。

    class_<darray>("darray")
        .def("__getitem__",
             (const double &(darray::*)(size_t) const)&darray::operator[],
             return_value_policy<copy_const_reference>())

ネット上でよく出てくるのは、valarray ではなく vector を Python に渡す方法ですが、この場合の __getitem__ は、operator[] ではなく vector::at を使うものばかりです。恥ずかしながら知らなかったのですが、vector::at と vector::operator[] には大きな違いがありました。vector::at は配列の長さを超えた場合に out_of_range 例外を投げてくれますが、operator[] は何もチェックせずに配列のインデックス アクセスを淡々とこなします。

vector::at – C++ Reference
http://www.cplusplus.com/reference/vector/vector/at/

The function automatically checks whether n is within the bounds of valid elements in the vector, throwing an out_of_range exception if it is not (i.e., if n is greater or equal than its size). This is in contrast with member operator[], that does not check against bounds.

Python 側に作られた ems.Field は iteratable なオブジェクトとして作られ、Python の iterator オブジェクト (seqiterobject 構造体) によって iterate されます。この動作は Objects/iterobject.c にある iter_iternext という関数で行われますが、iterate の終了条件は、戻り値が NULL を返すかどうかです。オブジェクトのサイズはチェックしません。

45 static PyObject *
46 iter_iternext(PyObject *iterator)
47 {
48     seqiterobject *it;
49     PyObject *seq;
50     PyObject *result;
51
52     assert(PySeqIter_Check(iterator));
53     it = (seqiterobject *)iterator;
54     seq = it->it_seq;
55     if (seq == NULL)
56         return NULL;
57     if (it->it_index == LONG_MAX) {
58         PyErr_SetString(PyExc_OverflowError,
59                         "iter index too large");
60         return NULL;
61     }
62
63     result = PySequence_GetItem(seq, it->it_index); // getitem を呼ぶ箇所
64     if (result != NULL) {
65         it->it_index++;
66         return result;
67     }
68     if (PyErr_ExceptionMatches(PyExc_IndexError) ||
69         PyErr_ExceptionMatches(PyExc_StopIteration))
70     {
71         PyErr_Clear();
72         Py_DECREF(seq);
73         it->it_seq = NULL;
74     }
75     return NULL;
76 }

Numpy 1.9.x 以上でハングが起こる原因は、Objects/listobject.c にある listextend で無限ループが発生するからです。iter_iternext がどんなインデックスに対しても値を返してくるので、このループが終わりません。

870     /* Run iterator to exhaustion. */
871     for (;;) {
872         PyObject *item = iternext(it);
873         if (item == NULL) {
874             if (PyErr_Occurred()) {
875                 if (PyErr_ExceptionMatches(PyExc_StopIteration))
876                     PyErr_Clear();
877                 else
878                     goto error;
879             }
880             break;
881         }
882         if (Py_SIZE(self) < self->allocated) {
883             /* steals ref */
884             PyList_SET_ITEM(self, Py_SIZE(self), item);
885             ++Py_SIZE(self);
886         }
887         else {
888             int status = app1(self, item);
889             Py_DECREF(item);  /* append creates a new ref */
890             if (status < 0)
891                 goto error;
892         }
893     }

他の人の役に立つか不明ですが、一応コールスタックなどの情報を含むデバッグ ログを載せておきます。

(gdb) r
Starting program: /usr/local/python/python-2.7.11/bin/python
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Python 2.7.11 (default, Dec 21 2015, 12:40:02)
[GCC 5.2.1 20151010] on linux2
Type "help", "copyright", "credits" or "license" for more information.

>>> import numpy as np
>>> import ems
>>> f = ems.Field(1)
Field::Field(): 0xaa0060
>>> x = f.Positions()
>>> f.Churn()
>>>

Program received signal SIGINT, Interrupt.
0x00007ffff71df723 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:81
81      ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) b slot_sq_item
Breakpoint 1 at 0x4816d0: file Objects/typeobject.c, line 4987.
(gdb) c
Continuing.

>>> a = np.array(x)

Breakpoint 1, slot_sq_item (self=0x7ffff1a92670, i=0) at Objects/typeobject.c:4987
4987    {
(gdb) p i
$1 = 0
(gdb) c
Continuing.
Breakpoint 1, slot_sq_item (self=0x7ffff1a92670, i=1) at Objects/typeobject.c:4987
4987    {
(gdb) p i
$2 = 1 <<<< この時点で既に out-of-range
(gdb) c
Continuing.
Breakpoint 1, slot_sq_item (self=0x7ffff1a92670, i=2) at Objects/typeobject.c:4987
4987    {
(gdb) p i
$3 = 2

(gdb) bt
#0  slot_sq_item (self=0x7ffff1a92670, i=2) at Objects/typeobject.c:4987
#1  0x0000000000444e5d in iter_iternext (iterator=0x7ffff7e96910) at Objects/iterobject.c:63
#2  0x0000000000448e9a in listextend (self=self@entry=0x7ffff1ab4cb0, b=b@entry=0x7ffff7e96910)
    at Objects/listobject.c:872
#3  0x000000000044aeb5 in _PyList_Extend (self=self@entry=0x7ffff1ab4cb0, b=b@entry=0x7ffff7e96910)
    at Objects/listobject.c:910
#4  0x000000000042243c in PySequence_List (v=0x7ffff7e96910) at Objects/abstract.c:2264
#5  PySequence_Fast (v=v@entry=0x7ffff1a92670, m=m@entry=0x7ffff5c299e8 "Could not convert object to sequence")
    at Objects/abstract.c:2293
#6  0x00007ffff5b5473c in PyArray_DTypeFromObjectHelper (obj=obj@entry=0x7ffff1a92670, maxdims=maxdims@entry=32,
    out_dtype=out_dtype@entry=0x7fffffffdea8, string_type=string_type@entry=0)
    at numpy/core/src/multiarray/common.c:531
#7  0x00007ffff5b549c3 in PyArray_DTypeFromObject (obj=obj@entry=0x7ffff1a92670, maxdims=maxdims@entry=32,
    out_dtype=out_dtype@entry=0x7fffffffdea8) at numpy/core/src/multiarray/common.c:184
#8  0x00007ffff5b5de81 in PyArray_GetArrayParamsFromObject (op=0x7ffff1a92670, requested_dtype=<optimized out>,
    writeable=<optimized out>, out_dtype=0x7fffffffdea8, out_ndim=0x7fffffffde9c, out_dims=0x7fffffffdeb0,
    out_arr=0x7fffffffdea0, context=0x0) at numpy/core/src/multiarray/ctors.c:1542
#9  0x00007ffff5b5e26d in PyArray_FromAny (op=op@entry=0x7ffff1a92670, newtype=0x0, min_depth=0, max_depth=0,
    flags=flags@entry=112, context=<optimized out>) at numpy/core/src/multiarray/ctors.c:1674
#10 0x00007ffff5b5e63f in PyArray_CheckFromAny (op=0x7ffff1a92670, descr=<optimized out>, min_depth=min_depth@entry=0,
    max_depth=max_depth@entry=0, requires=112, context=context@entry=0x0) at numpy/core/src/multiarray/ctors.c:1852
#11 0x00007ffff5bd850e in _array_fromobject (__NPY_UNUSED_TAGGEDignored=<optimized out>, args=<optimized out>, kws=0x0)
    at numpy/core/src/multiarray/multiarraymodule.c:1773
#12 0x00000000004b6f2a in call_function (oparg=<optimized out>, pp_stack=0x7fffffffe110) at Python/ceval.c:4350
#13 PyEval_EvalFrameEx (f=f@entry=0x7ffff7fc0c20, throwflag=throwflag@entry=0) at Python/ceval.c:2987
#14 0x00000000004b938c in PyEval_EvalCodeEx (co=co@entry=0x7ffff7ecfe30, globals=globals@entry=0x7ffff7f6c168,
    locals=locals@entry=0x7ffff7f6c168, args=args@entry=0x0, argcount=argcount@entry=0, kws=kws@entry=0x0, kwcount=0,
    defs=0x0, defcount=0, closure=0x0) at Python/ceval.c:3582
#15 0x00000000004b9499 in PyEval_EvalCode (co=co@entry=0x7ffff7ecfe30, globals=globals@entry=0x7ffff7f6c168,
    locals=locals@entry=0x7ffff7f6c168) at Python/ceval.c:669
#16 0x00000000004e2b4d in run_mod (arena=0x856e10, flags=<optimized out>, locals=0x7ffff7f6c168,
    globals=0x7ffff7f6c168, filename=0x546f03 "<stdin>", mod=0x8a1c48) at Python/pythonrun.c:1370
#17 PyRun_InteractiveOneFlags (fp=0x7ffff74a6980 <_IO_2_1_stdin_>, filename=0x546f03 "<stdin>", flags=<optimized out>)
    at Python/pythonrun.c:857
#18 0x00000000004e2dfe in PyRun_InteractiveLoopFlags (fp=fp@entry=0x7ffff74a6980 <_IO_2_1_stdin_>,
    filename=filename@entry=0x546f03 "<stdin>", flags=flags@entry=0x7fffffffe3a0) at Python/pythonrun.c:777
#19 0x00000000004e3366 in PyRun_AnyFileExFlags (fp=0x7ffff74a6980 <_IO_2_1_stdin_>, filename=<optimized out>,
    closeit=0, flags=0x7fffffffe3a0) at Python/pythonrun.c:746
#20 0x0000000000416160 in Py_Main (argc=<optimized out>, argv=<optimized out>) at Modules/main.c:640
#21 0x00007ffff7102a40 in __libc_start_main (main=0x415290 <main>, argc=1, argv=0x7fffffffe568, init=<optimized out>,
    fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffe558) at libc-start.c:289
#22 0x00000000004152c9 in _start ()

4. 回避策

valarray には at 関数がなく、境界チェックをしない operator[] があるのみです。したがって回避策として、valarray をラップする darray クラスを C++ 側で作って、at を追加実装しました。記憶が曖昧ですが、boost を使えば .NET のようにクラスを拡張できたような気がしますが、今回はこれで。

#include <boost/python.hpp>
#include <valarray>
#include <random>
#include <stdio.h>

std::default_random_engine generator;
std::uniform_real_distribution<double> distribution(0.0, 1.0);

class darray : public std::valarray<double> {
public:
    darray() : std::valarray<double>() {}
    darray(size_t n) : std::valarray<double>(n) {}

    const double& at(size_t n) const {
        if (n >= this->size()) {
            std::__throw_out_of_range_fmt(__N("out_of_range"));
        }
        return (*this)[n];
    }
};

class Field {
private:
    darray _data;

public:
    Field(int n) : _data(n) {
        printf("Field::Field(): %p\n", this);
    }
    ~Field() {
        printf("Field::~Field() %p\n", this);
    }

    void Dump() const {
        printf("[");
        for (auto &d : _data) {
            printf("% 3.3f", d);
        }
        printf(" ]\n");
    }

    void Churn() {
        for (auto &d : _data) {
            d = distribution(generator);
        }
    }

    const darray &Positions() const {
        return _data;
    }
};

BOOST_PYTHON_MODULE(ems) {
    using namespace boost::python;

    class_<Field>("Field", init<int>())
        .def("Positions", &Field::Positions,
             return_internal_reference<>())
        .def("Dump", &Field::Dump)
        .def("Churn", &Field::Churn)
        ;

    class_<darray>("darray")
        .def("__getitem__", &darray::at,
             return_value_policy<copy_const_reference>())
        .def("__len__", &darray::size)
        ;
}

Numpy 1.10.1 でも問題なく動作するようになりました。

>>> import ems
>>> import numpy as np
>>> np.__version__
‘1.10.1’
>>> f = ems.Field(4)
Field::Field(): 0x1029880
>>> x = f.Positions()
>>> f.Churn()
>>> f.Dump()
[ 0.132 0.459 0.219 0.679 ]
>>> np.array(x)
array([ 0.13153779,  0.45865013,  0.21895919,  0.67886472])
>>> quit()
Field::~Field() 0x1029880

この場合の動作ですが、darray::at で投げた例外が boost_python ライブラリの中の例外ハンドラーによって捕捉されるようです。たぶん #1 か #2 が例外ハンドラー。

#0  PyErr_SetString (exception=0x7a2ce0 <_PyExc_IndexError>, string=0x7ea428 "out_of_range") at Python/errors.c:68
#1  0x00007ffff56f3471 in boost::python::handle_exception_impl(boost::function0<void>) ()
   from /usr/lib/x86_64-linux-gnu/libboost_python-py27.so.1.58.0
#2  0x00007ffff56e8719 in ?? () from /usr/lib/x86_64-linux-gnu/libboost_python-py27.so.1.58.0
#3  0x0000000000422faa in PyObject_Call (func=func@entry=0x8bce90, arg=arg@entry=0x7ffff0b4f710, kw=kw@entry=0x0)
    at Objects/abstract.c:2546
#4  0x0000000000429dfc in instancemethod_call (func=0x8bce90, arg=0x7ffff0b4f710, kw=0x0) at Objects/classobject.c:2602
#5  0x0000000000422faa in PyObject_Call (func=func@entry=0x7ffff0b3ce60, arg=arg@entry=0x7ffff7e965d0, kw=kw@entry=0x0)
    at Objects/abstract.c:2546
#6  0x0000000000481766 in slot_sq_item (self=<optimized out>, i=<optimized out>) at Objects/typeobject.c:5012
#7  0x0000000000444e5d in iter_iternext (iterator=0x7ffff0b98e50) at Objects/iterobject.c:63
#8  0x0000000000448e9a in listextend (self=self@entry=0x7ffff0b4f5f0, b=b@entry=0x7ffff0b98e50)
    at Objects/listobject.c:872
#9  0x000000000044aeb5 in _PyList_Extend (self=self@entry=0x7ffff0b4f5f0, b=b@entry=0x7ffff0b98e50)
    at Objects/listobject.c:910
#10 0x000000000042243c in PySequence_List (v=0x7ffff0b98e50) at Objects/abstract.c:2264
#11 PySequence_Fast (v=v@entry=0x7ffff0b24670, m=m@entry=0x7ffff4aa09e8 "Could not convert object to sequence")
    at Objects/abstract.c:2293
#12 0x00007ffff49cb73c in PyArray_DTypeFromObjectHelper (obj=obj@entry=0x7ffff0b24670, maxdims=maxdims@entry=32,
    out_dtype=out_dtype@entry=0x7fffffffdea8, string_type=string_type@entry=0)
    at numpy/core/src/multiarray/common.c:531

このハングは、numpy.ndarray に限りません。例えばリスト内包表記で ems::darray を列挙しようとしても再現します。そのときのコールスタックはこのようになります。

#0  darray::at (this=0xb60d30, n=1) at shared.cpp:16
#1  0x00007ffff5e933bb in boost::python::detail::invoke<boost::python::to_python_value<double const&>, double const& (darray::*)(unsigned long) const, boost::python::arg_from_python<darray&>, boost::python::arg_from_python<unsigned long> >
    (rc=…, ac0=…, tc=<synthetic pointer>, f=
    @0x8bcc58: (const double &(darray::*)(const darray * const, unsigned long)) 0x7ffff5e92170 <darray::at(unsigned long) const>) at /usr/include/boost/python/detail/invoke.hpp:88
#2  boost::python::detail::caller_arity<2u>::impl<double const& (darray::*)(unsigned long) const, boost::python::return_value_policy<boost::python::copy_const_reference, boost::python::default_call_policies>, boost::mpl::vector3<double const&, darray&, unsigned long> >::operator() (args_=<optimized out>, this=0x8bcc58)
    at /usr/include/boost/python/detail/caller.hpp:223
#3  boost::python::objects::caller_py_function_impl<boost::python::detail::caller<double const& (darray::*)(unsigned long) const, boost::python::return_value_policy<boost::python::copy_const_reference, boost::python::default_call_policies>, boost::mpl::vector3<double const&, darray&, unsigned long> > >::operator() (this=0x8bcc50, args=<optimized out>,
    kw=<optimized out>) at /usr/include/boost/python/object/py_function.hpp:38
#4  0x00007ffff56eb33d in boost::python::objects::function::call(_object*, _object*) const ()
   from /usr/lib/x86_64-linux-gnu/libboost_python-py27.so.1.58.0
#5  0x00007ffff56eb528 in ?? () from /usr/lib/x86_64-linux-gnu/libboost_python-py27.so.1.58.0
#6  0x00007ffff56f3363 in boost::python::handle_exception_impl(boost::function0<void>) ()
   from /usr/lib/x86_64-linux-gnu/libboost_python-py27.so.1.58.0
#7  0x00007ffff56e8719 in ?? () from /usr/lib/x86_64-linux-gnu/libboost_python-py27.so.1.58.0
#8  0x0000000000422faa in PyObject_Call (func=func@entry=0x8bce90, arg=arg@entry=0x7ffff0b4f758, kw=kw@entry=0x0)
    at Objects/abstract.c:2546
#9  0x0000000000429dfc in instancemethod_call (func=0x8bce90, arg=0x7ffff0b4f758, kw=0x0) at Objects/classobject.c:2602
#10 0x0000000000422faa in PyObject_Call (func=func@entry=0x7ffff0b3ce60, arg=arg@entry=0x7ffff7e964d0, kw=kw@entry=0x0)
    at Objects/abstract.c:2546
#11 0x0000000000481766 in slot_sq_item (self=<optimized out>, i=<optimized out>) at Objects/typeobject.c:5012
#12 0x0000000000444e5d in iter_iternext (iterator=0x7ffff0b98e50) at Objects/iterobject.c:63
#13 0x00000000004b2373 in PyEval_EvalFrameEx (f=f@entry=0x7ffff1b3faa0, throwflag=throwflag@entry=0)
    at Python/ceval.c:2806

フレーム#12 と #13 から分かるように、今度は PyEval_EvalFrameEx から iter_iternext が呼ばれています。仮にこのハングを Python 側で直すとして、iter_iternext の中でサイズをチェックする、というアプローチが考えられます。Numpy のコードから確認できますが、PySequence_Size は darray::__len__ を呼ぶので、サイズは正しく取得できます。が、コードを見る限り、Python の iterator オブジェクトはサイズをチェックしなくても iterator するだけで要素を列挙できるのが利点なので、iter_iternext はこのままのほうが自然です。

もう少し見てみないと分かりませんが、ems.Field オブジェクトが iterator を使ってシーケンシャルにアクセスする種類になっているのが悪いのではないかと思います。何らかの方法で、ems.Field は iterator ではなくインデックスを使ってランダム アクセスすべきものに種別できればちゃんと動くのではないかと。そんな種類があるかどうか分かりませんが。後で調べよう。

4. おまけ – Python のデバッグ環境

Python をデバッグするため、Python そのものをソースからビルドしたので、そのときのコマンドを紹介します。

$ wget https://www.python.org/ftp/python/2.7.11/Python-2.7.11.tgz
$ tar -xvf Python-2.7.11.tgz
$ cd Python-2.7.11/
$ ./configure –prefix=/usr/local/python/python-2.7.11 –enable-unicode=ucs4
$ make
$ sudo make install
$ sudo ln -s /usr/local/python/python-2.7.11 /usr/local/python/current

configure するときに ucs4 を指定しておかないと、numpy をインポートしたときに以下のエラーが出ます。

>>> import numpy as np
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/usr/lib/python2.7/dist-packages/numpy/__init__.py", line 153, in <module>
    from . import add_newdocs
  File "/usr/lib/python2.7/dist-packages/numpy/add_newdocs.py", line 13, in <module>
    from numpy.lib import add_newdoc
  File "/usr/lib/python2.7/dist-packages/numpy/lib/__init__.py", line 8, in <module>
    from .type_check import *
  File "/usr/lib/python2.7/dist-packages/numpy/lib/type_check.py", line 11, in <module>
    import numpy.core.numeric as _nx
  File "/usr/lib/python2.7/dist-packages/numpy/core/__init__.py", line 6, in <module>
    from . import multiarray
ImportError: /usr/lib/python2.7/dist-packages/numpy/core/multiarray.so: undefined symbol: PyUnicodeUCS4_AsUnicodeEscapeString

このままだと、ビルドした Python のモジュール検索パスが空っぽなので、デバッグするときは環境変数を使って、元からあった Python の dist-packages を追加しておきました。たぶんもっとうまいやり方があるはず。

john@ubuntu1510:~/Documents/pyc$ export PYTHONPATH=/usr/local/lib/python2.7/dist-packages
john@ubuntu1510:~/Documents/pyc$ gdb /usr/local/python/current/bin/python
GNU gdb (Ubuntu 7.10-1ubuntu2) 7.10
Copyright (C) 2015 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"…
Reading symbols from /usr/local/python/current/bin/python…done.
(gdb) r
Starting program: /usr/local/python/python-2.7.11/bin/python
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Python 2.7.11 (default, Dec 21 2015, 12:40:02)
[GCC 5.2.1 20151010] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>>

Numpy は、以前 pip でインストールしたものにデバッグ情報が入っていたので、わざわざソースからビルドすることなくそのまま使いました。というか、Numpy のビルドは追加モジュールがいろいろ必要で面倒そうだったので諦めたともいいます。

Debugger Command Cheat Sheet (windbg/gdb/lldb)

たまに gdb や lldb を使うときは、いつも基本的なコマンドをググるのに時間を費やしているので、自分用にコマンドをまとめてみました。こうしてみると、やはり Windows Debugger のコマンドはシンプルで洗練されていて好き。gdb と lldb のコマンドは長すぎるし、そもそもソースコードがあることが前提で、最適化済みのコードや、アセンブリを見てデバッグすることがほとんど想定されていないように思える。随時更新予定です。

(2015/8/3 追記)
.gdbinit や .lldbinit という設定ファイルを作ってカスタム コマンドを定義する方法があるらしい。GitHub に、いろいろな人の設定ファイルが公開されているので、使いやすいものを選んで利用することも可能。

(このブログ、テーブルのスタイルが指定できない・・? 後で何とかしないと。)

Debugger Commands (Last update: Aug. 2, 2015)
Windows Debugger GDB LLDB
bp b br set [-n <func>] [-a <addr>]
bp <addr> "<commands>" commands # br command add
bl info break br list
bc* delete break br del -f
bc# d # br del #
be enable br enable
bd disable br disable
~ info threads th list
.frame frame frame select
gc c c
g <addr>    
q q q
p ni ni
t si si
gu fin fin
r info registers reg r
r rax=0 set $rax = 0 reg w rax 0
k bt bt
dv info locals frame variable
dv <var> p p, po
dt ptype type lookup
u . l1 info line
info frame
frame info
uf disass /r d -b
ln l *<addr> l <addr>
x info line image lookup -n
dd <addr> l10 x/16wx <addr> x/16wx <addr>
dq <addr> l10 x/16gx <addr> x/16gx <addr>
dc <addr> l10 x/16c <addr> x/16c <addr>
db <addr> l10 x/16b <addr> x/16x <addr>
u <addr> l10 x/16i <addr> x/16i <addr>
ed <addr> <value> set *(int*)<addr>=<value> memory write -s 4 <addr> <value>
windbg.exe C-x C-a
C-x C-1
C-x C-2
gui

Other cheat sheets

Pitfalls when debugging Netfilter

Linux カーネル デバッグ実践の第一弾、ということで iptables、すなわち netfilter に手を出しています。思っていたほど魔境ではありませんでした。1 つ 1 つの関数は短いですし、言語が C++ じゃなく C ですし。仕事で読んでいるコードのほうが魔境であることが再確認できました。ただ、コードそのものよりも、vi や bash などのツールに慣れていないので時間がかかります。

デバッグを進めるうちに、Linux カーネル デバッグ特有の罠に嵌ったので、解決方法とともに紹介したいと思います。今後もこのシリーズが続きそうです。

開発環境 (debugger) とテスト環境 (debuggee) は前回の記事の環境をそのまま使います。VMware ESXi 上の Ubuntu Server 14.04.1 に Linux 3.18.2 をインストールした環境です。

1. iptables コマンドで nat テーブルが存在しないと怒られる

今回のデバッグで目指しているのは、iptables でポート フォワードしたときの、オリジナルの宛先 IP アドレスを求める方法を探ることです。背景などの詳細はこちらの記事をご参照下さい。

Setting up a transparent proxy over SSL #4 – netcat/socat | すなのかたまり
https://msmania.wordpress.com/2015/01/10/setting-up-a-transparent-proxy-over-ssl-4-netcatsocat/

何はともあれ、まずは新しい Linux カーネルで上記記事と同じ環境を作るので、iptables コマンドを実行してみました。

$ sudo iptables -t nat -A PREROUTING -i eth0 -p tcp –dport 443 -j REDIRECT –to-port 3130
iptables v1.4.21: can’t initialize iptables table `nat’: Table does not exist (do you need to insmod?)
Perhaps iptables or your kernel needs to be upgraded.

いきなり iptables コマンドがエラーになります。悪い冗談はやめて欲しいですね。

ここでけっこう詰まったのですが、結論から言うと、ビルドしたときの config パラメーターが不足していました。.config ファイルを直接開いて、それっぽい項目を探すと、CONFIG_IP_NF_NAT という設定がコメントになっています。

# CONFIG_IP_NF_NAT is not set

でも make oldconfig したのになぜ・・という話ですが、カーネルが 3.16 から 3.17 になったときに設定の名前が変わったという情報を見つけました。Ubuntu Server 14.04.1 のオリジナルは Linux 3.13.0 だったので、見事に引っかかりました。デフォルトが無効になったのが解せぬ。

> Between linux version 3.16 and 3.17 the option
> CONFIG_NF_NAT_IPV4 changed the name to
> CONFIG_IP_NF_NAT. This option is not enabled in linux-image-3.17-rc5-amd64

https://lists.debian.org/debian-kernel/2014/09/msg00298.html

make oldconfig のログを読み返すと、確かに新しい設定として検出されていました。ええ、Enter キーを長押しにしていたので気づきませんでしたとも。こんなの気付かないよなぁ・・。

*
* IP: Netfilter Configuration
*
IPv4 connection tracking support (required for NAT) (NF_CONNTRACK_IPV4) [M/n/?] m
ARP packet logging (NF_LOG_ARP) [N/m/y] (NEW)
IPv4 packet logging (NF_LOG_IPV4) [M/y] (NEW)
IPv4 nf_tables support (NF_TABLES_IPV4) [M/n/?] m
  IPv4 nf_tables route chain support (NFT_CHAIN_ROUTE_IPV4) [M/n/?] m
IPv4 packet rejection (NF_REJECT_IPV4) [M/y] (NEW)
ARP nf_tables support (NF_TABLES_ARP) [M/n/?] m
IPv4 NAT (NF_NAT_IPV4) [M/n/?] m
  IPv4 nf_tables nat chain support (NFT_CHAIN_NAT_IPV4) [M/n/?] m
  IPv4 masquerade support (NF_NAT_MASQUERADE_IPV4) [N/m/?] (NEW)
  Basic SNMP-ALG support (NF_NAT_SNMP_BASIC) [M/n/?] m
IP tables support (required for filtering/masq/NAT) (IP_NF_IPTABLES) [M/n/y/?] m
  "ah" match support (IP_NF_MATCH_AH) [M/n/?] m
  "ecn" match support (IP_NF_MATCH_ECN) [M/n/?] m
  "rpfilter" reverse path filter match support (IP_NF_MATCH_RPFILTER) [M/n/?] m
  "ttl" match support (IP_NF_MATCH_TTL) [M/n/?] m
  Packet filtering (IP_NF_FILTER) [M/n/?] m
    REJECT target support (IP_NF_TARGET_REJECT) [M/n/?] m
  SYNPROXY target support (IP_NF_TARGET_SYNPROXY) [M/n/?] m
  iptables NAT support (IP_NF_NAT) [N/m/?] (NEW)
  Packet mangling (IP_NF_MANGLE) [M/n/?] m
    CLUSTERIP target support (IP_NF_TARGET_CLUSTERIP) [M/n/?] m
    ECN target support (IP_NF_TARGET_ECN) [M/n/?] m
    "TTL" target support (IP_NF_TARGET_TTL) [M/n/?] m
  raw table support (required for NOTRACK/TRACE) (IP_NF_RAW) [M/n/?] m
  Security table (IP_NF_SECURITY) [M/n/?] m

make menuconfig の位置は ↓ です。

Prompt: iptables NAT support
Location:
  -> Networking support (NET [=y])
    -> Networking options
      -> Network packet filtering framework (Netfilter) (NETFILTER [=y])
        -> IP: Netfilter Configuration
          -> IP tables support (required for filtering/masq/NAT) (IP_NF_IPTABLES [=m])

二度とこのようなことがないように、よく分からない項目も含めて netfilter に関する項目を menuconfig から有効にしておきます。追加で有効にした項目はこちら。

> CONFIG_NETFILTER_DEBUG=y
> CONFIG_NF_TABLES_INET=m
> CONFIG_NFT_MASQ=m
> CONFIG_NFT_QUEUE=m
> CONFIG_NFT_REJECT=m
> CONFIG_NFT_REJECT_INET=m
> CONFIG_NETFILTER_XT_NAT=m
> CONFIG_NFT_REJECT_IPV4=m
> CONFIG_NF_NAT_MASQUERADE_IPV4=m
> CONFIG_NFT_MASQ_IPV4=m
> CONFIG_IP_NF_NAT=m
> CONFIG_IP_NF_TARGET_MASQUERADE=m
> CONFIG_IP_NF_TARGET_NETMAP=m
> CONFIG_IP_NF_TARGET_REDIRECT=m
> CONFIG_NFT_REJECT_IPV6=m
> CONFIG_NF_NAT_MASQUERADE_IPV6=m
> CONFIG_NFT_MASQ_IPV6=m
> CONFIG_IP6_NF_NAT=m
> CONFIG_IP6_NF_TARGET_MASQUERADE=m
> CONFIG_IP6_NF_TARGET_NPT=m

で、ビルドしたら無事に iptables コマンドはうまくいきました。検索すると、同じように困っている人が世界中にいるようでした。oldconfig で Enter キーを長押しした人たちでしょう。

2. Kernel Loadable Modules のシンボルが解決できない

iptables によるポート フォワードの設定はうまくいきました。次は、フォワードされたパケットを補足する簡単なソケット通信のプログラムを書き、ポート フォワードを簡単に引き起こせるようにしておきます。

netfilter のコードを見渡して、IPv4 を NAT するときに実行されそうな処理の一つとして、net/ipv4/netfilter/nf_nat_l3proto_ipv4.c にある nf_nat_ipv4_manip_pkt という関数に目をつけました。そこで、SysRq-g でブレークさせて関数を探すと・・・。ハイ、見つかりません。

(gdb) i functions nf_nat_ipv4_manip_pkt
All functions matching regular expression "nf_nat_ipv4_manip_pkt":

どうせインライン展開でもされているんでしょう、と思って呼び出し元を探そうとすると、関数アドレスがグローバル変数の nf_nat_l3proto_ipv4.manip_pkt に代入されているのを発見しました。というわけで、この関数がインライン展開されるとは思えません。おかしいですね。

nf_ で始まるシンボルを全部表示してみます。

(gdb) i functions ^nf_
All functions matching regular expression "^nf_":

File net/ipv4/netfilter.c:
__sum16 nf_ip_checksum(struct sk_buff *, unsigned int, unsigned int, u_int8_t);
static __sum16 nf_ip_checksum_partial(struct sk_buff *, unsigned int, unsigned int, unsigned int,

(snip)

net/ipv4/netfilter ディレクトリのファイルが全滅しています。ますますおかしい。そこで net/ipv4/netfilter/Makefile の内容を見てみると、以下の行を発見。むむっ、これはもしかして。

nf_nat_ipv4-y       := nf_nat_l3proto_ipv4.o nf_nat_proto_icmp.o
obj-$(CONFIG_NF_NAT_IPV4) += nf_nat_ipv4.o

ふと思いついて lsmod  コマンドを実行しました。どうやらモジュール ファイルが別になっているのが理由のようです。つまり、kdb セッションに繋ぐ前に、開発機にある vmlinux をターゲットとして gdb を起動しているので、vmlinux (すなわち /boot/vmlinuz-**** の中身) のシンボルしか解決できないのでしょう。

john@linux-test:~$ sudo lsmod | grep nf
[sudo] password for john:
nf_conntrack_ipv4      14806  1
nf_defrag_ipv4         12758  1 nf_conntrack_ipv4
nf_nat_ipv4            14115  1 iptable_nat
nf_nat                 22050  2 nf_nat_ipv4,xt_REDIRECT
nf_conntrack          100933  3 nf_nat,nf_nat_ipv4,nf_conntrack_ipv4

Kernel Loaded Module をデバッグするときはどうするのかを調べると、gdb 上で add-symbol-file コマンドを実行して、手動でシンボル ファイルを追加しないといけないらしいです。しかも、モジュール イメージのコード セクションがロードされているアドレスも指定しないといけないとか。何これ。超めんどくさいんですけど。Windows Debugger なら全部自動でやってくれるのに!

幸いなことに、カーネル モジュールのコード セクションは sysfs 仮想ファイル システム経由でで簡単に見つけられます。そこで、以下のスクリプトを書いて、全カーネル モジュールのコード セクションのアドレスを一気にダンプできるようにしました。こういうことはデバッガーのコマンド経由でできるといいのですが。

#!/bin/bash
for file in $(find /sys/module -name .text) ; do
    addr=`cat ${file}`
    echo $addr " : " ${file}
done

とにかく無事アドレスをゲット。

john@linux-test:~$ sudo ./lm.sh  | sort -k1
0xffffffffa0000000  :  /sys/module/floppy/sections/.text
0xffffffffa0012000  :  /sys/module/mac_hid/sections/.text
0xffffffffa0019000  :  /sys/module/mptbase/sections/.text
0xffffffffa0033000  :  /sys/module/mptspi/sections/.text
0xffffffffa003a000  :  /sys/module/mptscsih/sections/.text
0xffffffffa0049000  :  /sys/module/e1000/sections/.text
0xffffffffa006c000  :  /sys/module/parport/sections/.text
0xffffffffa0078000  :  /sys/module/lp/sections/.text
0xffffffffa007e000  :  /sys/module/parport_pc/sections/.text
0xffffffffa0087000  :  /sys/module/shpchp/sections/.text
0xffffffffa0092000  :  /sys/module/serio_raw/sections/.text
0xffffffffa0097000  :  /sys/module/coretemp/sections/.text
0xffffffffa009c000  :  /sys/module/crc_ccitt/sections/.text
0xffffffffa00a1000  :  /sys/module/psmouse/sections/.text
0xffffffffa00be000  :  /sys/module/i2c_piix4/sections/.text
0xffffffffa00c5000  :  /sys/module/vmw_vmci/sections/.text
0xffffffffa00db000  :  /sys/module/vmw_balloon/sections/.text
0xffffffffa00e0000  :  /sys/module/ppdev/sections/.text
0xffffffffa00e6000  :  /sys/module/nf_nat_ipv4/sections/.text
0xffffffffa00eb000  :  /sys/module/irda/sections/.text
0xffffffffa010c000  :  /sys/module/drm/sections/.text
0xffffffffa015b000  :  /sys/module/ttm/sections/.text
0xffffffffa0171000  :  /sys/module/nf_nat/sections/.text
0xffffffffa0178000  :  /sys/module/drm_kms_helper/sections/.text
0xffffffffa0191000  :  /sys/module/vmwgfx/sections/.text
0xffffffffa01bd000  :  /sys/module/x_tables/sections/.text
0xffffffffa01c7000  :  /sys/module/ip_tables/sections/.text
0xffffffffa01cf000  :  /sys/module/nf_conntrack/sections/.text
0xffffffffa01e9000  :  /sys/module/nf_defrag_ipv4/sections/.text
0xffffffffa01ee000  :  /sys/module/nf_conntrack_ipv4/sections/.text
0xffffffffa01f3000  :  /sys/module/iptable_nat/sections/.text
0xffffffffa01f8000  :  /sys/module/xt_tcpudp/sections/.text
0xffffffffa01fd000  :  /sys/module/xt_REDIRECT/sections/.text

ターゲットにする関数は nf_nat_ipv4_manip_pkt で、nf_nat_ipv4  に実装されているはずですが、念のため事前に objdump でオブジェクト ファイルのシンボル テーブルを確認しておきます。

john@linux-dev:/usr/src/linux-3.18.2$ find . -name nf_nat_ipv4.o
./net/ipv4/netfilter/nf_nat_ipv4.o
john@linux-dev:/usr/src/linux-3.18.2$ objdump –syms ./net/ipv4/netfilter/nf_nat_ipv4.o | grep nf_nat_ipv4_manip_pkt
0000000000000330 l     F .text  000000000000011b nf_nat_ipv4_manip_pkt

無事見つかりました。これで一安心です。では実際にデバッガーにシンボル追加して、ブレークポイントを設定します。

(gdb) add-symbol-file ./net/ipv4/netfilter/nf_nat_ipv4.o 0xffffffffa00e6000
add symbol table from file "./net/ipv4/netfilter/nf_nat_ipv4.o" at
        .text_addr = 0xffffffffa00e6000
(y or n) y
Reading symbols from ./net/ipv4/netfilter/nf_nat_ipv4.o…done.

(gdb) i functions nf_nat_ipv4_manip_pkt
All functions matching regular expression "nf_nat_ipv4_manip_pkt":

File net/ipv4/netfilter/nf_nat_l3proto_ipv4.c:
static bool nf_nat_ipv4_manip_pkt(struct sk_buff *, unsigned int, const struct nf_nat_l4proto *,
    const struct nf_conntrack_tuple *, enum nf_nat_manip_type);

(gdb) break nf_nat_ipv4_manip_pkt
Breakpoint 1 at 0xffffffffa00e6330: file net/ipv4/netfilter/nf_nat_l3proto_ipv4.c, line 83.

(gdb) i break
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   0xffffffffa00e6330 in nf_nat_ipv4_manip_pkt
                                                   at net/ipv4/netfilter/nf_nat_l3proto_ipv4.c:83
(gdb) c
Continuing.

ようやくブレークポイントを設定できました。クライアントからパケットを送って、ポート フォワードを引き起こしてみます。

(gdb) c
Continuing.

Breakpoint 1, nf_nat_ipv4_manip_pkt (skb=0xffff88003d1d9600, iphdroff=2685874880,
    l4proto=0xffffffffa01732c0, target=0xffff88003fc03a20, maniptype=NF_NAT_MANIP_DST)
    at net/ipv4/netfilter/nf_nat_l3proto_ipv4.c:83
83      {
(gdb) bt
#0  nf_nat_ipv4_manip_pkt (skb=0xffff88003d1d9600, iphdroff=2685874880,
    l4proto=0xffffffffa01732c0, target=0xffff88003fc03a20, maniptype=NF_NAT_MANIP_DST)
    at net/ipv4/netfilter/nf_nat_l3proto_ipv4.c:83
#1  0xffffffffa0171126 in ?? ()
#2  0xffffffff81ce3ca8 in init_net ()
#3  0x000000003000000a in ?? ()
#4  0x0000000000000000 in ?? ()
(gdb) c
Continuing.

Breakpoint 1, nf_nat_ipv4_manip_pkt (skb=0xffff88003d1d9e00, iphdroff=2685874880,
    l4proto=0xffffffffa01732c0, target=0xffff88003fc03640, maniptype=NF_NAT_MANIP_SRC)
    at net/ipv4/netfilter/nf_nat_l3proto_ipv4.c:83
83      {
(gdb) bt
#0  nf_nat_ipv4_manip_pkt (skb=0xffff88003d1d9e00, iphdroff=2685874880,
    l4proto=0xffffffffa01732c0, target=0xffff88003fc03640, maniptype=NF_NAT_MANIP_SRC)
    at net/ipv4/netfilter/nf_nat_l3proto_ipv4.c:83
#1  0xffffffffa0171126 in ?? ()
#2  0xffffffff81ce3ca8 in init_net ()
#3  0x00000000ac0a2a68 in ?? ()
#4  0x0000000000000000 in ?? ()

読み通り、ポート フォワードのときに nf_nat_ipv4_manip_pkt は実行されました。これを取っ掛かりとしてコードを追いかけていけば何とかなるでしょう。途中のフレームにあるモジュールのシンボルが無いため、コール スタックはおかしなことになっているのが気になります。もう少しシンボルを追加することにします。

上述したコード セクションのアドレスをダンプするスクリプトの出力結果は、アドレス順にソートしてあります。アドレス一覧と nf_nat_ipv4_manip_pkt のリターン アドレス 0xffffffffa0171126  とを比べると、このアドレスは nf_nat のモジュール内であることが分かります。そこで今度は nf_nat のシンボルを追加して、もう一度コール スタックを確認します。

(gdb) add-symbol-file ./net/netfilter/nf_nat.o 0xffffffffa0171000
add symbol table from file "./net/netfilter/nf_nat.o" at
        .text_addr = 0xffffffffa0171000
(y or n) y
Reading symbols from ./net/netfilter/nf_nat.o…done.
(gdb) c
Continuing.

(gdb) bt
#0  nf_nat_ipv4_manip_pkt (skb=0xffff880036799700, iphdroff=2685874880,
    l4proto=0xffffffffa01732c0, target=0xffff88003fc03a20, maniptype=NF_NAT_MANIP_DST)
    at net/ipv4/netfilter/nf_nat_l3proto_ipv4.c:83
#1  0xffffffffa0171126 in nf_nat_packet (ct=<optimized out>, ctinfo=<optimized out>,
    hooknum=<optimized out>, skb=0xffff880036799700) at net/netfilter/nf_nat_core.c:501
#2  0xffffffffa00e6896 in nf_nat_ipv4_fn (ops=0xffffffffa01f5040, skb=0xffff880036799700,
    in=<optimized out>, out=0x0 <irq_stack_union>, do_chain=<optimized out>)
    at net/ipv4/netfilter/nf_nat_l3proto_ipv4.c:339
#3  0xffffffffa00e695e in nf_nat_ipv4_in (ops=<optimized out>, skb=0xffff880036799700,
    in=<optimized out>, out=<optimized out>, do_chain=<optimized out>)
    at net/ipv4/netfilter/nf_nat_l3proto_ipv4.c:359
#4  0xffffffffa01f30a5 in ?? ()
#5  0xffff88003fc03b58 in ?? ()
#6  0xffffffff81694e5e in nf_iterate (head=<optimized out>, skb=0xffff880036799700,
    hook=<optimized out>, indev=0xffff88003651c000, outdev=0x0 <irq_stack_union>,
    elemp=0xffff88003fc03ba0, okfn=0xffffffff8169b650 <ip_rcv_finish>, hook_thresh=-2116913248)
    at net/netfilter/core.c:142
Backtrace stopped: frame did not save the PC

(gdb) c
Continuing.

Breakpoint 1, nf_nat_ipv4_manip_pkt (skb=0xffff880036799800, iphdroff=2685874880,
    l4proto=0xffffffffa01732c0, target=0xffff88003fc03640, maniptype=NF_NAT_MANIP_SRC)
    at net/ipv4/netfilter/nf_nat_l3proto_ipv4.c:83
83      {
(gdb) bt
#0  nf_nat_ipv4_manip_pkt (skb=0xffff880036799800, iphdroff=2685874880,
    l4proto=0xffffffffa01732c0, target=0xffff88003fc03640, maniptype=NF_NAT_MANIP_SRC)
    at net/ipv4/netfilter/nf_nat_l3proto_ipv4.c:83
#1  0xffffffffa0171126 in nf_nat_packet (ct=<optimized out>, ctinfo=<optimized out>,
    hooknum=<optimized out>, skb=0xffff880036799800) at net/netfilter/nf_nat_core.c:501
#2  0xffffffffa00e6896 in nf_nat_ipv4_fn (ops=0xffffffffa01f5078, skb=0xffff880036799800,
    in=<optimized out>, out=0xffff88003651c000, do_chain=<optimized out>)
    at net/ipv4/netfilter/nf_nat_l3proto_ipv4.c:339
#3  0xffffffffa00e6a08 in nf_nat_ipv4_out (ops=<optimized out>, skb=0xffff880036799800,
    in=<optimized out>, out=<optimized out>, do_chain=<optimized out>)
    at net/ipv4/netfilter/nf_nat_l3proto_ipv4.c:389
#4  0xffffffffa01f3085 in ?? ()
#5  0xffff88003fc03768 in ?? ()
#6  0xffffffff81694e5e in nf_iterate (head=<optimized out>, skb=0xffff880036799800,
    hook=<optimized out>, indev=0x0 <irq_stack_union>, outdev=0xffff88003651c000,
    elemp=0xffff88003fc037b0, okfn=0xffffffff8169ff80 <ip_finish_output>, hook_thresh=-2116913184)
    at net/netfilter/core.c:142
Backtrace stopped: frame did not save the PC

まだ完全ではないようですが、先ほどよりは多くの情報が出てきました。

シンボルが解決できないときにコール スタックをうまく辿れなくなるということは、ビルドでは FPO (=Frame Pointer Omission) が有効になっているように見えます。それっぽい設定は以下の 3 箇所ありました。有効になっている SCHED_OMIT_FRAME_POINTER が他の設定を上書きしているのかもしれません。これ以上追いかけていないので、確証はありませんが。

Symbol: FRAME_POINTER [=y]
Type  : boolean
Prompt: Compile the kernel with frame pointers
  Location:
    -> Kernel hacking
(1)   -> Compile-time checks and compiler options
  Defined at lib/Kconfig.debug:296
  Depends on: DEBUG_KERNEL [=y] && (CRIS || M68K || FRV || UML || AVR32 || SUPERH || BLACKF
  Selected by: FAULT_INJECTION_STACKTRACE_FILTER [=n] && FAULT_INJECTION_DEBUG_FS [=n] && S

Symbol: ARCH_WANT_FRAME_POINTERS [=y]
Type  : boolean
  Defined at lib/Kconfig.debug:292
  Selected by: X86 [=y]

Symbol: SCHED_OMIT_FRAME_POINTER [=y]
Type  : boolean
Prompt: Single-depth WCHAN output
  Location:
(2) -> Processor type and features
  Defined at arch/x86/Kconfig:589
  Depends on: X86 [=y]

とりあえずはこの設定でデバッグを続けるか、netfilter をビルトインしてしまうかは迷うところです。

How to Live Debug a Linux Kernel in Ubuntu Server

gdb についても、何とか使えるレベルにはなってきたので、Linux カーネルのデバッグにも手を出してみることにしました。Windows であれば、普通にインストールして bcdedit でカーネル デバッグを有効にするだけでいいのに、Linux だと相当めんどくさいです。しかも人によって実行しているコマンドがばらばら・・これだから Linux は困る。いろいろと検索すると、Linux のカーネルをソースからビルドしてインストールしている人はたくさんいるようですが、カーネルをデバッグしている人となると、一気に数が少なくなる気がします。

最初は、Hyper-V の仮想マシン上にインストールした Ubuntu Server に対して、仮想のシリアル ポートを追加して、Hyper-V ホストの Windows から名前つきパイプ経由でデバッガーを直接繋ぐ環境を作りました。できるにはできたんですが、2009 年に kdb  と kgdb が統合された際、kdb 上で逆アセンブルするためのコマンド id が削除されていました。それだけでも論外なのですが、さらに kdb というデバッガーは gdb とは異なるコマンド セットを持っています。したがって現在の主流は、gdb を使ったリモート デバッグであり、ローカルの kdb に直接繋ぎに行くのは非常に特殊な場合に限られそうです。

KDB FAQ – KGDB Wiki
https://kgdb.wiki.kernel.org/index.php/KDB_FAQ

となると、Hyper-V で環境を作るのが一気にめんどくさくなります。gdb でリモート デバッグを行なうということは、debugger と debuggee の 2 台の Linux が必要になるということです。原理上当然ですし、Windows のカーネル デバッグも同じなので何も文句は無いのですが、問題は Hyper-V の仮想マシン同士をシリアル ポートで繋ぐ簡単な方法がないことです。Hyper-V では、仮想シリアル ポート デバイスを Hyper-V ホストの名前付きパイプにリダイレクトすることができます。しかし試してみたところ、2 つの仮想マシンで 1 つの名前付きパイプを共有して、仮想マシン同士をシリアル通信させることができませんでした。

以下の情報から、2 台の仮想マシンがそれぞれ別の名前付きパイプを使い、Hyper-V ホスト側でそれらの名前付きパイプをリレーするようなプログラムを動かすという方法がひょっとすると可能かもしれませんが試していません。

http://stackoverflow.com/questions/4973554/hyper-v-connecting-vms-through-named-pipe-loses-data

一方、VMware のハイパーバイザーでは、2 台の仮想マシンが 1 つの名前付きパイプを共有することが可能なので、大昔にインストールした VMware ESXi の環境を使うことにしました。いつも通り、OS は Ubuntu Server 14.04.1 を使います。

手順の流れは以下の通りです。

  1. ESXi 上に 2 台の仮想マシンを用意し、Ubuntu Server をインストール
  2. Debugger 上に Linux カーネルのソースをダウンロードし、ビルド
  3. 動作確認のため、ビルドしたカーネルを Debugger 上にインストールして再起動
  4. 必要なファイルを Debugger から Debuggee にコピー
  5. Debuggee 上でブートの設定を行ない、シリアル コンソールからカーネル デバッグを有効化
  6. Debugger からデバッグ開始

まずは ESXi の環境に仮想マシンを 2 台用意し、以下の設定で仮想シリアル ポート デバイスを追加します。

  • Debugger – デバッグする人
    Pipe Name: linux-debug
    Near End: Client
    Far End: A virtual machine
  • Debuggee – デバッグされる人
    Pipe Name: linux-debug
    Near End: Server
    Far End: A virtual machine

image
Debugger

image
Debuggee

Ubuntu Server のインストールでは特別な設定は不要です。OS が用意できたら、次に Linux カーネルをソースからビルドします。ソースは git リポジトリからクローンしてもいいのですが、かなり遅いらしいので、kernel.org からダウンロードします。2015/1/10 現在の最新は 3.18.2 でした。

The Linux Kernel Archives
https://www.kernel.org/

カーネルをビルドするコマンドは人によって千差万別で、どれを使うか迷いましたが、以下のコマンドで落ち着きました。

$ uname -a
Linux linux-dev 3.13.0-32-generic #57-Ubuntu SMP Tue Jul 15 03:51:08 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
$ sudo apt-get install build-essential libtool manpages-dev gdb
$ sudo apt-get install kernel-package libncurses5-dev
$ wget
https://www.kernel.org/pub/linux/kernel/v3.x/linux-3.18.2.tar.xz
$ tar -xvf linux-3.18.2.tar.xz
$ cd linux-3.18.2/
$ cp /boot/config-3.13.0-32-generic .config
$ make oldconfig
$ make menuconfig
$ sudo make-kpkg clean
$ sudo make-kpkg –initrd kernel_image kernel_headers \
> –append_to_version=-poodim -j2

少し補足です。

  • kernel-package
    make-kpkg コマンドのために必要です。このコマンドで、Debian パッケージを作ってインストールします。
  • libncurses5-dev
    make menuconfig コマンドのために必要です。
  • cp /boot/config-3.13.0-32-generic .config ; make oldconfig
    最初に、現在のカーネル設定を元に設定を作ります。一から設定してもいいのですが、互換性維持のためと、設定項目が膨大すぎるためです。というかみんなやってるし。
  • make menuconfig
    メインの設定はここでやります。好きなだけ弄っていってね!
  • –append_to_version=-poodim
    作るカーネルのリリース名のサフィックスを好きなように設定できます。例えば今回のコマンドだと、カーネルのリリース名が "3.18.2-poodim" になります。
  • -j2
    コンパイル時の並列実行数の設定です。ビルド環境の CPU コア数に合わせて設定してください。どれだけ効果があるのかは分かりません。私はこういう設定ではいつも コア数x2 にするようにしています。

menuconfig では、どこも設定を変更する必要はありませんでしたが、カーネル デバッグに必要な項目が有効化されていることを必ず確認しておきましょう。

  • Kernel hacking –> Magic SysRq key –> (0x1) Enable magic SysRq key functions by default
  • Kernel hacking –> Kernel debugging
  • Kernel hacking –> KGDB: kernel debugger –> KGDB: use kgdb over the serial console
  • Kernel hacking –> KGDB: kernel debugger
    –> KGDB_KDB: include kdb frontend for kgdb –> KGDB_KDB: keyboard as input device

image
menuconfig のトップ画面 – Kernel hacking を選んで Enter

image
Kernel hacking 画面 – SysRq と Kernel debugging が有効であることを確認

image
Kernel hacking 画面 – KGDB を選んで Enter

image
KGDB: kernel debugger 画面 – kgdb が有効であることを確認

Ubuntu のサイトにもカーネルのビルド方法の情報がありますが、kernel.org ではなく Ubuntu のリポジトリにあるソースを使うみたいなので、あまり参考になりません。一応リンクを掲載しておきます。

Kernel/BuildYourOwnKernel – Ubuntu Wiki
https://wiki.ubuntu.com/Kernel/BuildYourOwnKernel

以下のページには、メジャーなディストリビューションで使えるコマンドが紹介されています。分かりやすい。

How to compile and install Linux kernel in Ubuntu/Debian and RHEL/CentOS | Rui’s Blog
https://coelhorjc.wordpress.com/2014/12/05/howto-upgrade-to-latest-kernel-in-ubuntu/

ビルドはけっこう時間がかかりますので、のんびり待ちましょう。なお、いくつかのサイトではビルド時に sudo ではなく fakeroot を使うように書かれていましたが、fakeroot だと以下のパーミッション エラーが出たので sudo にしました。

$ fakeroot make-kpkg –initrd kernel_image kernel_headers –append_to_version=poodim -j4
                System.map "/usr/src/linux-3.18.2/debian/linux-image-3.18.2poodim//boot"
run-parts: executing /etc/kernel/postinst.d/apt-auto-removal 3.18.2poodim /usr/src/linux-3.18.2/debian/linux-image-3.18.2poodim//boot/vmlinuz-3.18.2poodim
/etc/kernel/postinst.d/apt-auto-removal: 84: /etc/kernel/postinst.d/apt-auto-removal: cannot create /etc/apt/apt.conf.d//01autoremove-kernels.dpkg-new: Permission denied
run-parts: /etc/kernel/postinst.d/apt-auto-removal exited with return code 2
make[3]: *** [install] Error 1
make[2]: *** [install] Error 2
make[2]: Leaving directory `/usr/src/linux-3.18.2′
make[1]: *** [debian/stamp/install/linux-image-3.18.2poodim] Error 2
make[1]: Leaving directory `/usr/src/linux-3.18.2′
make: *** [kernel_image] Error 2

ビルドが終わると、拡張子 deb の Debian パッケージ ファイルが /usr/src に作られます。

$ ls -l /usr/src
total 128108
drwxrwxr-x 25 john john     4096 Jan 10 19:56 linux-3.18.2
-rw-rw-r–  1 john john 80941176 Jan  8 10:34 linux-3.18.2.tar.xz
drwxr-xr-x 24 root root     4096 Jan 10 16:39 linux-headers-3.13.0-32
drwxr-xr-x  7 root root     4096 Jan 10 16:39 linux-headers-3.13.0-32-generic
drwxr-xr-x 23 root root     4096 Jan 10 21:42 linux-headers-3.18.2-poodim
-rw-r–r–  1 root root  7020266 Jan 10 19:59 linux-headers-3.18.2-poodim_3.18.2-poodim-10.00.Custom_amd64.deb
-rw-r–r–  1 root root 43196770 Jan 10 19:55 linux-image-3.18.2-poodim_3.18.2-poodim-10.00.Custom_amd64.deb

この後、必要なファイルを Debuggee にコピーしますが、その前に、作ったカーネルで OS が無事に動くかどうかを確かめるため、Debugger マシン上にカーネルをインストールして再起動します。ちょっと緊張します。

$ sudo dpkg -i /usr/src/linux-image-3.18.2-poodim_3.18.2-poodim-10.00.Custom_amd64.deb
$ sudo dpkg -i /usr/src/linux-headers-3.18.2-poodim_3.18.2-poodim-10.00.Custom_amd64.deb
$ sudo shutdown -r now

(再起動中)

$ uname -a
Linux linux-dev 3.18.2-poodim #1 SMP Sat Jan 10 17:25:35 PST 2015 x86_64 x86_64 x86_64 GNU/Linux

ここから先は、以下のサイトを参考にしました。

Kgdb – eLinux.org
http://elinux.org/Kgdb

kgdbを用いたカーネルデバッグ環境の構築 – big-eyed-hamsterの日記
http://d.hatena.ne.jp/big-eyed-hamster/20090331/1238470673

以下のファイルを debuggee 上にコピーします。

  • /boot/initrd.img-3.18.2-poodim – ブート時の初期 RAM ディスク
  • /boot/System.map-3.18.2-poodim – カーネルのシンボル テーブル
  • /boot/vmlinuz-3.18.2-poodim – カーネル本体

どうやってコピーしてもいいのですが、今回は Debugger となる linux-dev 上で以下の scp コマンドを実行しました。10.0.0.46 は Debuggee の IP アドレスです。とりあえずホーム ディレクトリにコピー。

$ scp /boot/initrd.img-3.18.2-poodim john@10.0.0.46:~
$ scp /boot/System.map-3.18.2-poodim john@10.0.0.46:~
$ scp /boot/vmlinuz-3.18.2-poodim john@10.0.0.46:~

次に debuggee となる linux-test にログインし、/boot ディレクトリへのコピーと、パーミッションの設定などを行います。

$ cd ~
$ sudo mv  *poodim /boot/
$ cd /boot
$ sudo chown root:root initrd.img-3.18.2-poodim System.map-3.18.2-poodim vmlinuz-3.18.2-poodim
$ sudo chmod 600 vmlinuz-3.18.2-poodim System.map-3.18.2-poodim
$ ls -la /boot
total 58051
drwxr-xr-x  4 root root     1024 Jan 10 22:00 .
drwxr-xr-x 22 root root     4096 Jan 10 16:32 ..
-rw-r–r–  1 root root  1162712 Jul 14 21:29 abi-3.13.0-32-generic
-rw-r–r–  1 root root   165611 Jul 14 21:29 config-3.13.0-32-generic
drwxr-xr-x  5 root root     1024 Jan 10 22:04 grub
-rw-r–r–  1 root root 20084102 Jan 10 16:36 initrd.img-3.13.0-32-generic
-rw-r–r–  1 root root 18521322 Jan 10 21:58 initrd.img-3.18.2-poodim
drwx——  2 root root    12288 Jan 10 16:31 lost+found
-rw-r–r–  1 root root   176500 Mar 12  2014 memtest86+.bin
-rw-r–r–  1 root root   178176 Mar 12  2014 memtest86+.elf
-rw-r–r–  1 root root   178680 Mar 12  2014 memtest86+_multiboot.bin
-rw——-  1 root root  3381262 Jul 14 21:29 System.map-3.13.0-32-generic
-rw——-  1 root root  3526496 Jan 10 21:59 System.map-3.18.2-poodim
-rw——-  1 root root  5798112 Jul 14 21:29 vmlinuz-3.13.0-32-generic
-rw——-  1 root root  6004160 Jan 10 21:59 vmlinuz-3.18.2-poodim

(少し修正)
上記の方法でも、OS の起動は問題ありませんでしたが、/lib/modules へのディレクトリ作成など、必要なセットアップ作業が行われません。したがって、ビルド後に作成された 2 つの Debian パッケージごとコピーして、Debuggee 上でも同様に sudo dpkg -i コマンドによるインストールを行ったほうが安全だと思います。

ブート時に、コピーしたカーネルが読み込まれるようにするため、ブートローダーである grub の設定をします。設定ファイルは /etc/default/grub です。

GRUB_DEFAULT=0
#GRUB_HIDDEN_TIMEOUT=0
GRUB_HIDDEN_TIMEOUT_QUIET=false
GRUB_TIMEOUT=30
GRUB_DISTRIBUTOR=`lsb_release -i -s 2> /dev/null || echo Debian`
GRUB_CMDLINE_LINUX_DEFAULT="kgdbwait kgdboc=ttyS0,115200"
GRUB_CMDLINE_LINUX=""

設定ファイルを変更したら、変更を /boot/grub/grub.cfg に反映させます。コピーしたカーネルが認識されたことが分かります。そのまま再起動します。

$ sudo update-grub
[sudo] password for john:
Generating grub configuration file …
Found linux image: /boot/vmlinuz-3.18.2-poodim
Found initrd image: /boot/initrd.img-3.18.2-poodim
Found linux image: /boot/vmlinuz-3.13.0-32-generic
Found initrd image: /boot/initrd.img-3.13.0-32-generic
Found memtest86+ image: /memtest86+.elf
Found memtest86+ image: /memtest86+.bin
done
john@linux-test:~$ sudo shutdown -r now

なお、上記の方法は現在のバージョンである GRUB 2 の方法です。昔の GRUB では、/boot/grub/menu.lst を編集してカーネルのブート パラメーターを変更していたようです。まだ多くの情報が menu.lst を変更する方法を紹介していますが、menu.lst は現在存在しないので注意してください。

Debuggee である linux-test 再起動すると、コンソール上にはログインのプロンプトではなく、[0]kdb> というプロンプトが表れ、ローカルの kdb セッションが入力待ちになります。Debuggee はこのまま放置しておきます。

image

次に Debugger となる linux-dev のセッションに戻ります。linux-dev の COM1 ポート (/dev/ttyS0) から gdb を使って linux-test に繋ぎに行くわけですが、今使っている作業用ユーザーの john には /dev/ttyS0 にアクセスする権限がありません。sudo で gdb を起動してもいいのですが、sudo しなくてもいいよう権限を与えることにします。まず現在の設定を確認します。

john@linux-dev:~$ ls -la /dev/ttyS0
crw-rw—- 1 root dialout 4, 64 Jan 11 01:02 /dev/ttyS0

john を dialout に参加させればいいようです。設定を反映させるため、ログアウトしてから再ログインします。

$ sudo adduser john dialout
Adding user `john’ to group `dialout’ …
Adding user john to group dialout
Done.
$ groups john
john : john adm dialout cdrom sudo dip plugdev lpadmin sambashare
$ logout

ようやく gdb を起動するところまできました。ここで重要なのは、ただ gdb を起動すればいいというわけではなく、linux-test 上でシンボルが正しく解決されるように、ビルドしたカーネル ファイルをターゲットにする必要があることです。今回の環境だと、/usr/src/linux-3.18.2/vmlinux がカーネルのバイナリです。

$ gdb /usr/src/linux-3.18.2/vmlinux
GNU gdb (Ubuntu 7.7.1-0ubuntu5~14.04.2) 7.7.1
Copyright (C) 2014 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <
http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<
http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<
http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"…
Reading symbols from /usr/src/linux-3.18.2/vmlinux…done.
(gdb) set serial baud 115200
(gdb) target remote /dev/ttyS0
Remote debugging using /dev/ttyS0
kgdb_breakpoint () at kernel/debug/debug_core.c:1051
1051            wmb(); /* Sync point after breakpoint */
(gdb) bt
#0  kgdb_breakpoint () at kernel/debug/debug_core.c:1051
#1  0xffffffff811151f0 in kgdb_initial_breakpoint () at kernel/debug/debug_core.c:949
#2  kgdb_register_io_module (new_dbg_io_ops=0xffffffff81cb6d80 <kgdboc_io_ops>)
    at kernel/debug/debug_core.c:991
#3  0xffffffff8149c9ef in configure_kgdboc () at drivers/tty/serial/kgdboc.c:200
#4  0xffffffff81d8ff5a in init_kgdboc () at drivers/tty/serial/kgdboc.c:229
#5  0xffffffff8100212c in do_one_initcall (fn=0xffffffff81d8ff46 <init_kgdboc>) at init/main.c:791
#6  0xffffffff81d43245 in do_initcall_level (level=<optimized out>) at init/main.c:856
#7  do_initcalls () at init/main.c:864
#8  do_basic_setup () at init/main.c:883
#9  kernel_init_freeable () at init/main.c:1004
#10 0xffffffff8175539e in kernel_init (unused=<optimized out>) at init/main.c:934
#11 <signal handler called>
#12 0x0000000000000000 in irq_stack_union ()
#13 0x0000000000000000 in ?? ()
(gdb)

(ボーレートを指定する set serial baud 115200 は省略しても問題ないみたいです。)

コールスタックから、kgdb_initial_breakpoint() というそれっぽい関数で止まっているのが分かります。あとは、ユーザーモードの gdb と同じように操作できます。とりあえず c で実行を再開して、linux-test にログインします。

あとは普通にデバッグすればいいのですが、この後必要となる操作は、カーネル デバッガーにブレークインする方法です。Windows ならカーネル デバッガー上で Ctrl-C を押せば止まりますが、gdb で Ctrl-C を押しても止まってくれません。

方法は幾つかあり、以下のページに載っています。

Chapter 5. Using kgdb / gdb
https://www.kernel.org/doc/htmldocs/kgdb/EnableKGDB.html

使用頻度が高そうな 2 通りの方法について紹介します。

まずはキーボードを使う場合。goo ランキングで、「実はイマイチ使いどころがわからないWindowsのキー」 の第一位に輝いた SysRq キーを使います。もし SysRq キーが無ければ、PrintScreen ボタンを使います。

実はイマイチ使いどころがわからないWindowsのキー – gooランキング
http://ranking.goo.ne.jp/ranking/category/092/fR4cJvWG2ytj/

Windows では確か全く使われないはずですが、Linux では、マジック SysRq キーと呼ばれ、カーネルに特殊なコマンドを発行するために使います。デバッガーにブレークインするには、SysRq-g を使います。

Magic SysRq key – Wikipedia, the free encyclopedia
http://en.wikipedia.org/wiki/Magic_SysRq_key

ただし、Ubuntu Server のデフォルトでは、誤操作を防ぐためキーボードからの SysRq が無効にされており、まずはそれを有効にします。設定は簡単で、/etc/sysctl.conf ファイルに以下の一行を追加するだけです。

kernel.sysrq = 1

設定を有効にするには、sysctl -p コマンドを実行します。再起動は不要です。

john@linux-test:~$ sudo sysctl -p
kernel.sysrq = 1

キーの押し方は以下のような感じ。Alt+SysRq+G の同時押しでも動きます。

  1. Alt キーを押したままにする
  2. SysRq キーを押して放す (Alt キーは押したまま)
  3. g キーを押して放す(Alt キーは押したまま)
  4. Alt キーを放す

これは、シェルが起動していなくても有効です。例えば、ログインのプロンプトでブレークインさせるとこんな感じ。

image

ログイン画面で Alt+SysRq+G

参考までに、このときのコールスタックはこんな感じ。sysrq_handle_dbg() という関数が呼ばれるみたいです。

(gdb) bt
#0  kgdb_breakpoint () at kernel/debug/debug_core.c:1051
#1  0xffffffff8111424c in sysrq_handle_dbg (key=<optimized out>) at kernel/debug/debug_core.c:810
#2  0xffffffff8147a867 in __handle_sysrq (key=103, check_mask=true) at drivers/tty/sysrq.c:536
#3  0xffffffff8147ac96 in sysrq_handle_keypress (value=<optimized out>, code=<optimized out>,
    sysrq=<optimized out>) at drivers/tty/sysrq.c:797
#4  sysrq_filter (handle=<optimized out>, type=<optimized out>, code=<optimized out>,
    value=<optimized out>) at drivers/tty/sysrq.c:859
#5  0xffffffff815bd579 in input_to_handler (handle=<optimized out>, vals=0xffff88003696b848,
    count=<optimized out>) at drivers/input/input.c:105
#6  0xffffffff815be8a9 in input_pass_values (dev=0xffff880036976800, vals=0xffff88003696b840,
    count=3) at drivers/input/input.c:147
#7  0xffffffff815c0b79 in input_pass_values (count=<optimized out>, vals=<optimized out>,
    dev=<optimized out>) at drivers/input/input.c:395
#8  input_handle_event (dev=0xffff880036976800, type=0, code=0, value=0)
    at drivers/input/input.c:396
#9  0xffffffff815c0ff9 in input_event (dev=0x67 <irq_stack_union+103>, type=<optimized out>,
    code=<optimized out>, value=<optimized out>) at drivers/input/input.c:431
#10 0xffffffff815c71cc in input_sync (dev=<optimized out>) at include/linux/input.h:414
#11 atkbd_interrupt (serio=0xffff880036975000, data=<optimized out>, flags=<optimized out>)
    at drivers/input/keyboard/atkbd.c:511
#12 0xffffffff815ba23a in serio_interrupt (serio=0xffff880036975000, data=34 ‘"’, dfl=0)
    at drivers/input/serio/serio.c:1008
#13 0xffffffff815bb98a in i8042_interrupt (irq=<optimized out>, dev_id=<optimized out>)
    at drivers/input/serio/i8042.c:537
#14 0xffffffff810c4e1e in handle_irq_event_percpu (desc=<optimized out>,
    action=0x1 <irq_stack_union+1>) at kernel/irq/handle.c:143
#15 0xffffffff810c4fc1 in handle_irq_event (desc=0xffff88003f805600) at kernel/irq/handle.c:192
#16 0xffffffff810c7f0f in handle_edge_irq (irq=<optimized out>, desc=0xffff88003f805600)
    at kernel/irq/chip.c:605
#17 0xffffffff810155f2 in generic_handle_irq_desc (desc=<optimized out>, irq=<optimized out>)
    at include/linux/irqdesc.h:128
#18 handle_irq (irq=1, regs=<optimized out>) at arch/x86/kernel/irq_64.c:87
#19 0xffffffff8176eeb3 in do_IRQ (regs=0xffffffff81c03dc8 <init_thread_union+15816>)
    at arch/x86/kernel/irq.c:200
#20 <signal handler called>
#21 0xffffffffffffffce in ?? ()
Cannot access memory at address 0x246

残念ながらマジック SysRq キーを Teraterm 上で使うことはできません。リモート セッションからブレークさせる場合は、/proc/sysrq-trigger に対して g をエコーで送って SysRq-g を実現できます。しかし sysrq-trigger への書き込みは、sudo を使っても Permission denied で怒られてしまいます。

john@linux-test:~$ sudo echo g > /proc/sysrq-trigger
-bash: /proc/sysrq-trigger: Permission denied
john@linux-test:~$ ls -la /proc/sysrq-trigger
–w——- 1 root root 0 Jan 11 01:38 /proc/sysrq-trigger

sysrq-trigger を使うには、sudo ではなく本物の root ユーザーが必要です。Ubuntu Server の初期状態では、root ユーザーにパスワードが割り当てられていないので、パスワードを割り当ててスイッチ ユーザーしてからもう一度実行します。

john@linux-test:~$ sudo passwd root
[sudo] password for john:
Enter new UNIX password:
Retype new UNIX password:
passwd: password updated successfully
john@linux-test:~$ su –
Password:
root@linux-test:~# echo g > /proc/sysrq-trigger

今度はブレークしました。コールスタックの上のほうは、キーボードからブレークさせたときと同じになっています。もたもたしているとリモートセッションがタイムアウトで切れてしまうので、早めに c で実行を再開しておきましょう。

(gdb) bt
#0  kgdb_breakpoint () at kernel/debug/debug_core.c:1051
#1  0xffffffff8111424c in sysrq_handle_dbg (key=<optimized out>) at kernel/debug/debug_core.c:810
#2  0xffffffff8147a867 in __handle_sysrq (key=103, check_mask=false) at drivers/tty/sysrq.c:536
#3  0xffffffff8147ad13 in write_sysrq_trigger (file=<optimized out>, buf=<optimized out>, count=1,
    ppos=<optimized out>) at drivers/tty/sysrq.c:1092
#4  0xffffffff81241e8d in proc_reg_write (file=<optimized out>, buf=<optimized out>,
    count=<optimized out>, ppos=<optimized out>) at fs/proc/inode.c:224
#5  0xffffffff811dd067 in vfs_write (file=0x67 <irq_stack_union+103>,
    buf=0x1bd2408 "g\nload is /sbin/reload\nt\ne-kpkg\nub-script-check\nbkdf2\n", ‘\337’ <repeats 145 times>, <incomplete sequence \337>…, count=<optimized out>, pos=0xffff88003cf13f50)
    at fs/read_write.c:534
#6  0xffffffff811ddae6 in SYSC_write (count=<optimized out>, buf=<optimized out>,
    fd=<optimized out>) at fs/read_write.c:585
#7  SyS_write (fd=<optimized out>, buf=29172744, count=2) at fs/read_write.c:577
#8  <signal handler called>
#9  0x00007f5362cc52f0 in ?? ()
c#10 0xffff88003cf14240 in ?? ()
#11 0x0000000000000000 in ?? ()

これで全ての準備が整ったので、あとは思う存分 Linux カーネルの海に漕ぎ出すだけです。最後に、何か適当なところにブレークポイントを貼って試してみることにしました。

Windows でいう CreateProcess 的な関数はどれかな、と探すと、arch/x86/kernel/process_64.c に start_thread() とかいう CreateThread っぽい関数を見つけたので、これで試すことにしました。ブレークポイントを設定してから、ifconfig などの適当なプロセスを実行します。

(gdb) i functions start_thread
All functions matching regular expression "start_thread":

File arch/x86/kernel/process_64.c:
void start_thread(struct pt_regs *, unsigned long, unsigned long);
void start_thread_ia32(struct pt_regs *, u32, u32);
static void start_thread_common(struct pt_regs *, unsigned long, unsigned long, unsigned int,
    unsigned int, unsigned int);

File drivers/usb/early/ehci-dbgp.c:
static int kgdbdbgp_start_thread(void);
(gdb) break start_thread
Breakpoint 1 at 0xffffffff81011460: file arch/x86/kernel/process_64.c, line 249.
(gdb) c
Continuing.
[New Thread 1445]
[Switching to Thread 1445]

Breakpoint 1, start_thread (regs=0xffff8800369cbf58, new_ip=140737391120576,
    new_sp=140737391120576) at arch/x86/kernel/process_64.c:249
249     {
(gdb) bt
#0  start_thread (regs=0xffff8800369cbf58, new_ip=140737391120576, new_sp=140737391120576)
    at arch/x86/kernel/process_64.c:249
#1  0xffffffff812321c5 in load_elf_binary (bprm=0xffff88003cd50400) at fs/binfmt_elf.c:975
#2  0xffffffff811e34b7 in search_binary_handler (bprm=0xffff8800369cbf58) at fs/exec.c:1374
#3  0xffffffff811e4901 in exec_binprm (bprm=<optimized out>) at fs/exec.c:1416
#4  do_execve_common (filename=0xffff88003c272000, argv=…, envp=…) at fs/exec.c:1513
#5  0xffffffff811e4cd9 in do_execve (__envp=<optimized out>, __argv=<optimized out>,
    filename=<optimized out>) at fs/exec.c:1555
#6  SYSC_execve (envp=<optimized out>, argv=<optimized out>, filename=<optimized out>)
    at fs/exec.c:1609
#7  SyS_execve (filename=<optimized out>, argv=32422696, envp=32196616) at fs/exec.c:1604
#8  0xffffffff8176c6c9 in stub_execve () at arch/x86/kernel/entry_64.S:648
#9  0x00007f196561cdb7 in ?? ()
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

(gdb) p regs
$1 = (struct pt_regs *) 0xffff8800369cbf58
(gdb) p *regs
$2 = {r15 = 0, r14 = 0, r13 = 0, r12 = 0, bp = 0, bx = 0, r11 = 0, r10 = 0, r9 = 0, r8 = 0,
  ax = 0, cx = 0, dx = 0, si = 0, di = 0, orig_ax = 59, ip = 139747051818423, cs = 51,
  flags = 518, sp = 140733820489592, ss = 43}

普通に使えそう。というわけで、Linux カーネルとの距離を少し縮められた気がします。

デバッグ テクニックに関しては、Ubuntu のカーネル チームのサイトが充実していて、今後お世話になりそう。

Kernel/Debugging – Ubuntu Wiki
https://wiki.ubuntu.com/Kernel/Debugging

Debugging Apache installed with apt-get

以前の記事では、ソースからビルドした Apache を gdb でライブ デバッグする方法について触れました。apt-get でダウンロードした Apache では、ディレクトリ構成や構成ファイル名などが異なっているので、デバッグの方法も少し異なります。その方法を紹介します。

Ubuntu では、"apt-get install apache2" コマンドで Apache 2.x をダウンロード/インストールできます。ダウンロードされるバイナリにデバッグ情報は含まれていないので、Apache のコアモジュールをデバッグするのはあまり現実的ではありませんが、自分で作ったモジュールをデバッグするには十分です。

まずは環境を用意します。apt-get install したパッケージは以下の通り。

  • build-essential
  • libtool
  • manpages-dev
  • gdb
  • apache2
  • apache2-dev
  • git

使うバージョンは以下の通り。

  • Ubuntu Server 14.04.1 LTS x64
  • Linux Kernel 3.13.0-32-generic
  • gcc (Ubuntu 4.8.2-19ubuntu1) 4.8.2
  • GNU gdb (Ubuntu 7.7.1-0ubuntu5~14.04.2) 7.7.1
  • Apache/2.4.7 (Ubuntu)
  • git version 1.9.1

新しくサイトを作るのも面倒くさいので、既存の /etc/apache2/sites-available/000-default.conf を以下のように編集します。この段階では、ServerName を追加するだけです。

ServerName http://www.example.com
<VirtualHost *:80>
    ServerAdmin webmaster@localhost
    DocumentRoot /var/www/html

    LogLevel info ssl:warn

    ErrorLog ${APACHE_LOG_DIR}/error.log
    CustomLog ${APACHE_LOG_DIR}/access.log combined
</VirtualHost>

Apache を再起動します。

john@ubuntu14041:~$ sudo service apache2 restart
* Restarting web server apache2         [ OK ]
john@ubuntu14041:~$

ブラウザーからアクセスします。今回は IE11+KB3008923 を使います。

image

これで準備は完了です。では、デバッグ対象となるモジュールを用意します。今回はこれで。

https://github.com/msmania/mod_clover

クローンします。

john@ubuntu14041:~$ git clone https://github.com/msmania/mod_clover.git
Cloning into ‘mod_clover’…
remote: Counting objects: 22, done.
remote: Compressing objects: 100% (15/15), done.
remote: Total 22 (delta 7), reused 20 (delta 5)
Unpacking objects: 100% (22/22), done.
Checking connectivity… done.

ダウンロードされた ./build.sh と ./install.sh はパスが異なっていて使えないので、ビルドとインストールは直に apxs を実行します。

john@ubuntu14041:~/mod_clover$ apxs -c mod_clover.c
/usr/share/apr-1.0/build/libtool –silent –mode=compile –tag=disable-static x86_64-linux-gnu-gcc -std=gnu99 -prefer-pic -pipe -g -O2 -fstack-protector –param=ssp-buffer-size=4 -Wformat -Werror=format-security  -D_FORTIFY_SOURCE=2   -DLINUX -D_REENTRANT -D_GNU_SOURCE  -pthread  -I/usr/include/apache2  -I/usr/include/apr-1.0   -I/usr/include/apr-1.0 -I/usr/include  -c -o mod_clover.lo mod_clover.c && touch mod_clover.slo
/usr/share/apr-1.0/build/libtool –silent –mode=link –tag=disable-static x86_64-linux-gnu-gcc -std=gnu99 -Wl,–as-needed -Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-z,now    -o mod_clover.la  -rpath /usr/lib/apache2/modules -module -avoid-version    mod_clover.lo

john@ubuntu14041:~/mod_clover$ sudo apxs -i mod_clover.la
/usr/share/apache2/build/instdso.sh SH_LIBTOOL=’/usr/share/apr-1.0/build/libtool’ mod_clover.la /usr/lib/apache2/modules
/usr/share/apr-1.0/build/libtool –mode=install install mod_clover.la /usr/lib/apache2/modules/
libtool: install: install .libs/mod_clover.so /usr/lib/apache2/modules/mod_clover.so
libtool: install: install .libs/mod_clover.lai /usr/lib/apache2/modules/mod_clover.la
libtool: finish: PATH="/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/sbin" ldconfig -n /usr/lib/apache2/modules
———————————————————————-
Libraries have been installed in:
   /usr/lib/apache2/modules

If you ever happen to want to link against installed libraries
in a given directory, LIBDIR, you must either use libtool, and
specify the full pathname of the library, or use the `-LLIBDIR’
flag during linking and do at least one of the following:
   – add LIBDIR to the `LD_LIBRARY_PATH’ environment variable
     during execution
   – add LIBDIR to the `LD_RUN_PATH’ environment variable
     during linking
   – use the `-Wl,-rpath -Wl,LIBDIR’ linker flag
   – have your system administrator add LIBDIR to `/etc/ld.so.conf’

See any operating system documentation about shared libraries for
more information, such as the ld(1) and ld.so(8) manual pages.
———————————————————————-
chmod 644 /usr/lib/apache2/modules/mod_clover.so

設定は apxs に任せず、手動でやることにします。さっきも編集した /etc/apache2/sites-available/000-default.conf に以下の行 (青字) を追加。

ServerName www.example.com

LoadModule clover_module /usr/lib/apache2/modules/mod_clover.so
AddOutputFilterByType CLOVER text/html

<VirtualHost *:80>
    ServerAdmin webmaster@localhost
    DocumentRoot /var/www/html

    LogLevel info ssl:warn

    ErrorLog ${APACHE_LOG_DIR}/error.log
    CustomLog ${APACHE_LOG_DIR}/access.log combined

    Clover_Dynamic 1
</VirtualHost>

apache 再起動。エラーが出なければモジュールは読み込みは成功です。

john@ubuntu14041:~/mod_clover$ sudo service apache2 restart
* Restarting web server apache2                    [ OK ]

この mod_clover とかいうモジュールの正体ですが、URL に渡すクエリ文字列によって、サーバーが返す HTML の DOCTYPE と IE の Document Mode を変更できる、というものです。といってもフィルター内で HTML の構造を完全にパースしているのではなく、行単位で置換するだけです。あまり融通が利きません。

フィルターが正しく動作できるように、/var/www/html/index.html を少し手直しして、ファイルの出だしを以下のようにします。変更は、1 行目の空行の削除と、x-ua-compatible メタ情報の追加の二ヶ所です。

<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="
http://www.w3.org/1999/xhtml">
  <!–
    Modified from the Debian original for Ubuntu
    Last updated: 2014-03-19
    See:
https://launchpad.net/bugs/1288690
  –>
  <head>
    <meta http-equiv="Content-Type" content="text/html; charset=UTF-8" />
    <meta http-equiv="x-ua-compatible" content="IE=edge" />
    <title>Apache2 Ubuntu Default Page: It works</title>
    <style type="text/css" media="screen">
  * {
    margin: 0px 0px 0px 0px;

例えばオリジナルの URL が http://11.10.90.10/ だったときに、http://11.10.90.10/?t=1&m=9 という URL でアクセスすると、DOCTYPE が HTML5、Document Mode が IE9 になる、はずです。

実際に開いてみると、DOCTYPE は XHTML1.0 のまま、DocMode も edge のままでフィルターが動いてくれません。ではデバッガーをアタッチして見てみます。

image

アタッチすべきプロセスを ps で確かめると、/usr/sbin/apache2 だと分かります。ワーカー プロセスが複数起動されているので、デバッグのためには –X オプションを付けてシングル プロセス モードで起動したいところです。

john@ubuntu14041:~$ ps -ef | grep apache
root     18052     1  0 17:16 ?        00:00:00 /usr/sbin/apache2 -k start
www-data 18055 18052  0 17:16 ?        00:00:00 /usr/sbin/apache2 -k start
www-data 18056 18052  0 17:16 ?        00:00:00 /usr/sbin/apache2 -k start
www-data 18057 18052  0 17:16 ?        00:00:00 /usr/sbin/apache2 -k start
www-data 18058 18052  0 17:16 ?        00:00:00 /usr/sbin/apache2 -k start
www-data 18059 18052  0 17:16 ?        00:00:00 /usr/sbin/apache2 -k start
www-data 18068 18052  0 17:17 ?        00:00:00 /usr/sbin/apache2 -k start
john     18090  1376  0 17:30 pts/0    00:00:00 grep –color=auto apache

ソースからビルドした httpd のときのように、apache2 を gdb 下で直接実行しようとしてもうまくいきません。

john@ubuntu14041:~$ sudo service apache2 stop
[sudo] password for john:
* Stopping web server apache2 *

john@ubuntu14041:~$ sudo gdb /usr/sbin/apache2
GNU gdb (Ubuntu 7.7.1-0ubuntu5~14.04.2) 7.7.1
Copyright (C) 2014 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <
http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<
http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<
http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"…
Reading symbols from /usr/sbin/apache2…(no debugging symbols found)…done.
(gdb) r -X
Starting program: /usr/sbin/apache2 -X
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[Thu Jan 01 17:32:59.261766 2015] [core:warn] [pid 18128] AH00111: Config variable ${APACHE_LOCK_DIR} is not defined
[Thu Jan 01 17:32:59.261944 2015] [core:warn] [pid 18128] AH00111: Config variable ${APACHE_PID_FILE} is not defined
[Thu Jan 01 17:32:59.262003 2015] [core:warn] [pid 18128] AH00111: Config variable ${APACHE_RUN_USER} is not defined
[Thu Jan 01 17:32:59.262065 2015] [core:warn] [pid 18128] AH00111: Config variable ${APACHE_RUN_GROUP} is not defined
[Thu Jan 01 17:32:59.262127 2015] [core:warn] [pid 18128] AH00111: Config variable ${APACHE_LOG_DIR} is not defined
[Thu Jan 01 17:32:59.370505 2015] [core:warn] [pid 18128] AH00111: Config variable ${APACHE_RUN_DIR} is not defined
[Thu Jan 01 17:32:59.370823 2015] [core:warn] [pid 18128] AH00111: Config variable ${APACHE_LOG_DIR} is not defined
[Thu Jan 01 17:32:59.374724 2015] [core:warn] [pid 18128] AH00111: Config variable ${APACHE_LOG_DIR} is not defined
[Thu Jan 01 17:32:59.374848 2015] [core:warn] [pid 18128] AH00111: Config variable ${APACHE_LOG_DIR} is not defined
AH00526: Syntax error on line 74 of /etc/apache2/apache2.conf:
Invalid Mutex directory in argument file:${APACHE_LOCK_DIR}
[Inferior 1 (process 18128) exited with code 01]
(gdb)

赤字で示したエラー メッセージから、環境変数が足りないことが分かります。試行錯誤したところ、起動スクリプトである apache2ctl を編集するのが最も簡単だったので、その方法を紹介します。なお apachectl は、apache2ctl へのシンボリック リンクです。

john@ubuntu14041:~$ ls -l /usr/sbin/ap*
-rwxr-xr-x 1 root root 637496 Jul 22 07:38 /usr/sbin/apache2
-rwxr-xr-x 1 root root   6402 Jan  3  2014 /usr/sbin/apache2ctl
lrwxrwxrwx 1 root root     10 Jul 22 07:37 /usr/sbin/apachectl -> apache2ctl
lrwxrwxrwx 1 root root      9 Apr  3  2014 /usr/sbin/apparmor_status -> aa-status

apache2ctl は、start や stop といったパラメーターを取ることができますが、そこにデバッグ用のオプションを追加します。追加するのは以下の青字で示した 3 行です。

case $ARGV in
start)
    # ssl_scache shouldn’t be here if we’re just starting up.
    # (this is bad if there are several apache2 instances running)
    rm -f ${APACHE_RUN_DIR:-/var/run/apache2}/*ssl_scache*
    $HTTPD ${APACHE_ARGUMENTS} -k $ARGV
    ERROR=$?
    ;;
stop|graceful-stop)
    $HTTPD ${APACHE_ARGUMENTS} -k $ARGV
    ERROR=$?
    ;;
debug)
    gdb $HTTPD
    ;;

restart|graceful)
(..snip..)

起動します。今度はうまくいきました。r -X した後にワーカー スレッドが作られたことを示すログが出力されないことから、apt-get するパッケージの Apache はマルチスレッド モデルではないようです。

john@ubuntu14041:~$ sudo apachectl debug
GNU gdb (Ubuntu 7.7.1-0ubuntu5~14.04.2) 7.7.1
Copyright (C) 2014 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <
http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<
http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<
http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"…
Reading symbols from /usr/sbin/apache2…(no debugging symbols found)…done.
(gdb) r -X
Starting program: /usr/sbin/apache2 -X
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".

念のため別コンソールからシングル プロセス モードになっているかを確認します。

john@ubuntu14041:~/mod_clover$ ps -ef | grep apache
root     18173  1376  0 17:41 pts/0    00:00:00 sudo apachectl debug
root     18174 18173  0 17:41 pts/0    00:00:00 /bin/sh /usr/sbin/apachectl debug
root     18176 18174  1 17:41 pts/0    00:00:00 gdb /usr/sbin/apache2
www-data 18178 18176  0 17:41 pts/0    00:00:00 /usr/sbin/apache2 -X
john     18183  3010  0 17:42 pts/2    00:00:00 grep –color=auto apache

プロセス名は apache2 なので、任意のタイミングでブレークさせるときは以下のコマンドを実行します。

john@ubuntu14041:~/mod_clover$ sudo killall -SIGTRAP apache2

マルチスレッド モデルではないため、ソースからビルドした Apache と異なり、デバッガーのコンソール上で Ctrl-C を押してもブレーク/再開させることができます。

^C
Program received signal SIGINT, Interrupt.
0x00007ffff725b573 in __epoll_wait_nocancel () at ../sysdeps/unix/syscall-template.S:81
81      in ../sysdeps/unix/syscall-template.S
(gdb) c
Continuing.

デバッガーの準備ができたところで、mod_clover のハンドラーでブレークさせます。

(gdb) i functions clover
All functions matching regular expression "clover":

File mod_clover.c:
static apr_status_t clover_handler(ap_filter_t *, apr_bucket_brigade *);
static void clover_register_hooks(apr_pool_t *);
(gdb) break clover_handler
Breakpoint 1 at 0x7ffff1827030: file mod_clover.c, line 220.
(gdb) c
Continuing.

(ブラウザーから http://11.10.90.10/?t=1&m=9 にアクセス)

Breakpoint 1, clover_handler (f=0x7fffec22d308, bb=0x7fffec22d9f0) at mod_clover.c:220
220     static apr_status_t clover_handler(ap_filter_t *f, apr_bucket_brigade *bb) {
(gdb) bt
#0  clover_handler (f=0x7fffec22d308, bb=0x7fffec22d9f0) at mod_clover.c:220
#1  0x00007ffff4ca2194 in ?? () from /usr/lib/apache2/modules/mod_filter.so
#2  0x00007ffff54c7841 in ?? () from /usr/lib/apache2/modules/mod_deflate.so
#3  0x00007ffff4ca2194 in ?? () from /usr/lib/apache2/modules/mod_filter.so
#4  0x000055555559a0af in ?? ()
#5  0x00005555555aa680 in ap_run_handler ()
#6  0x00005555555aabc9 in ap_invoke_handler ()
#7  0x00005555555c016a in ap_process_async_request ()
#8  0x00005555555c0444 in ap_process_request ()
#9  0x00005555555bcf02 in ?? ()
#10 0x00005555555b3cc0 in ap_run_process_connection ()
#11 0x00007ffff4896767 in ?? () from /usr/lib/apache2/modules/mod_mpm_prefork.so
#12 0x00007ffff489696c in ?? () from /usr/lib/apache2/modules/mod_mpm_prefork.so
#13 0x00007ffff48976b1 in ?? () from /usr/lib/apache2/modules/mod_mpm_prefork.so
#14 0x000055555559169e in ap_run_mpm ()
#15 0x000055555558ae36 in main ()

ハンドラーは呼ばれているようです。デバッグ情報がないのでシンボル名は ?? になっていますが、mod_clover が呼ばれる前に、mod_deflate フィルターの処理が実行されているのが見えます。mod_deflate は圧縮を行うフィルターなので、mod_clover に流れてくるデータがテキストではなく圧縮されたデータになっていて、正しく処理できていない、ということが予想できます。

フィルターの順番を入れ替える前に、実際にどのようなデータが来ているのかをデバッガーから確認します。

mod_clover の処理は、流れてくる bucket brigade を行単位に再構成し、正規表現にマッチした行を置き換えるという動作になっています。apr_brigade_pflatten 関数によって 1 行分の文字列を作成しているので、この関数が返す文字列を見てみます。

gdb の操作に慣れるため、あえて最適化されたコードのままデバッグを行ない、アセンブリ言語をベースにコードを追いかけることにします。行番号があまり当てにならないので、disassemble で clover_handler をダンプしてどこでブレークさせるかを考えます。以下は apr_brigade_pflatten 呼び出しのあたりを抜き出したものです。

0x00007ffff1827134 <+260>:   e9 dc 00 00 00  jmpq   0x7ffff1827215 <clover_handler+485>
0x00007ffff1827139 <+265>:   0f 1f 80 00 00 00 00    nopl   0x0(%rax)
0x00007ffff1827140 <+272>:   48 8b 45 08     mov    0x8(%rbp),%rax
0x00007ffff1827144 <+276>:   48 8b 55 00     mov    0x0(%rbp),%rdx
0x00007ffff1827148 <+280>:   48 8b 7b 08     mov    0x8(%rbx),%rdi
0x00007ffff182714c <+284>:   48 89 10        mov    %rdx,(%rax)
0x00007ffff182714f <+287>:   48 8b 45 00     mov    0x0(%rbp),%rax
0x00007ffff1827153 <+291>:   48 8b 55 08     mov    0x8(%rbp),%rdx
0x00007ffff1827157 <+295>:   48 89 50 08     mov    %rdx,0x8(%rax)
0x00007ffff182715b <+299>:   48 8d 47 08     lea    0x8(%rdi),%rax
0x00007ffff182715f <+303>:   48 89 45 00     mov    %rax,0x0(%rbp)
0x00007ffff1827163 <+307>:   48 8b 47 10     mov    0x10(%rdi),%rax
0x00007ffff1827167 <+311>:   48 89 45 08     mov    %rax,0x8(%rbp)
0x00007ffff182716b <+315>:   48 8b 47 10     mov    0x10(%rdi),%rax
0x00007ffff182716f <+319>:   48 89 28        mov    %rbp,(%rax)
0x00007ffff1827172 <+322>:   48 89 6f 10     mov    %rbp,0x10(%rdi)
0x00007ffff1827176 <+326>:   48 c7 44 24 50 00 00 00 00      movq   $0x0,0x50(%rsp)
0x00007ffff182717f <+335>:   48 8b 4b 10     mov    0x10(%rbx),%rcx
0x00007ffff1827183 <+339>:   48 8b 54 24 10  mov    0x10(%rsp),%rdx
0x00007ffff1827188 <+344>:   4c 89 f6        mov    %r14,%rsi
0x00007ffff182718b <+347>:   e8 10 fb ff ff  callq  0x7ffff1826ca0 <apr_brigade_pflatten@plt>
0x00007ffff1827190 <+352>:   85 c0   test   %eax,%eax
0x00007ffff1827192 <+354>:   0f 85 78 02 00 00       jne    0x7ffff1827410 <clover_handler+992>
0x00007ffff1827198 <+360>:   8b 53 38        mov    0x38(%rbx),%edx
0x00007ffff182719b <+363>:   45 31 ff        xor    %r15d,%r15d
0x00007ffff182719e <+366>:   85 d2   test   %edx,%edx
0x00007ffff18271a0 <+368>:   0f 84 ea 01 00 00       je     0x7ffff1827390 <clover_handler+864>
0x00007ffff18271a6 <+374>:   8b 43 3c        mov    0x3c(%rbx),%eax
0x00007ffff18271a9 <+377>:   c7 43 38 01 00 00 00    movl   $0x1,0x38(%rbx)
0x00007ffff18271b0 <+384>:   85 c0   test   %eax,%eax
0x00007ffff18271b2 <+386>:   0f 84 80 01 00 00       je     0x7ffff1827338 <clover_handler+776>
0x00007ffff18271b8 <+392>:   48 8b 74 24 58  mov    0x58(%rsp),%rsi
0x00007ffff18271bd <+397>:   49 8b 44 24 18  mov    0x18(%r12),%rax
0x00007ffff18271c2 <+402>:   4d 85 ff        test   %r15,%r15
0x00007ffff18271c5 <+405>:   4c 89 ff        mov    %r15,%rdi
0x00007ffff18271c8 <+408>:   48 0f 44 7c 24 60       cmove  0x60(%rsp),%rdi
0x00007ffff18271ce <+414>:   48 8b 40 08     mov    0x8(%rax),%rax
0x00007ffff18271d2 <+418>:   48 8b 90 80 00 00 00    mov    0x80(%rax),%rdx
0x00007ffff18271d9 <+425>:   e8 f2 fa ff ff  callq  0x7ffff1826cd0 <apr_bucket_transient_create@plt>

x64 Linux の呼び出し規約は、System V Application Binary Interface (ABI) として定義されています。仕様は ↓ にあります。

AMD64 Documentation
http://www.x86-64.org/documentation.html

"Figure 3.4: Register Usage" の図にパラメーターを渡す時に使われるレジスターの一覧があります。整数の場合、rdi -> rsi -> rdx -> rcx -> r8 -> r9 の順番で使われるようです。何これ Windows と全然違う・・・

デバッガーに戻り、今回確認したい文字列は第二パラメーターの linestr なので、rsi レジスターに入るはずです。デバッグ時のログはこんな感じ・・

(gdb) break *0x00007ffff182718b
Breakpoint 3 at 0x7ffff182718b: file mod_clover.c, line 295.
(gdb) c
Continuing.

(ブラウザーから http://11.10.90.10/?t=1&m=9 にアクセス)

Breakpoint 3, 0x00007ffff182718b in clover_handler (f=0x7fffec22f308, bb=0x7fffec22f9f0)
    at mod_clover.c:295
295                             status = apr_brigade_pflatten(context->snippets, &linestr, &linelength, context->subpool);
(gdb) i r r14 rsi
r14            0x7fffffffde20   140737488346656
rsi            0x7fffffffde20   140737488346656
(gdb) x/g 0x7fffffffde20
0x7fffffffde20: 0x0000000000000000
(gdb) ni
296                             if ( status!=APR_SUCCESS ) {
(gdb) i r eax
eax            0x0      0
(gdb) i r r14 rsi
r14            0x7fffffffde20   140737488346656
rsi            0x7fffec222056   140737155047510
(gdb) x/g $r14
0x7fffffffde20: 0x00007fffec2260a8
(gdb) p linestr
$1 = 0x7fffec2260a8 "37\213\b"
(gdb) x/s 0x00007fffec2260a8
0x7fffec2260a8: "37\213\b"
(gdb) x/8x 0x00007fffec2260a8
0x7fffec2260a8: 0x1f    0x8b    0x08    0x00    0x00    0x00    0x00    0x00
(gdb) c
Continuing.

Breakpoint 3, 0x00007ffff182718b in clover_handler (f=0x7fffec22f308, bb=0x7fffec22f9f0)
    at mod_clover.c:295
295                             status = apr_brigade_pflatten(context->snippets, &linestr, &linelength, context->subpool);
(gdb) ni
296                             if ( status!=APR_SUCCESS ) {
(gdb) x/g $r14
0x7fffffffde20: 0x00007fffec2262b0
(gdb) x/8b 0x00007fffec2262b0
0x7fffec2262b0: 0xbe    0x00    0x65    0x22    0x30    0x2a    0x53    0x85
(gdb) p linestr
$2 = 0x7fffec2262b0 "\276"
(gdb)

青字で示した行が、mod_deflate から流れてきたデータです。確かに文字列ではありません。念のため Network Monitor でパケットを確認すると、デバッガーに表示されているものと全く同じ 1F 8B 08 00 00 … で始まるバイナリ データが HTTP 応答として返ってきています。

image

というわけで、フィルター処理の順番として、mod_deflate の前に mod_clover を実行させる必要があります。

有効化されているモジュールのロード、及び初期設定パラメーターは、/etc/apache2/apache2.conf に記載されている IncludeOptional によってインクルードされるので、その前に mod_clover に関する設定を記述します。青字の 2 行を追加しました。000-default.conf からは、LoadModule と AddOutputFilterByType を消しておきます。

#
# LogLevel: Control the severity of messages logged to the error_log.
# Available values: trace8, …, trace1, debug, info, notice, warn,
# error, crit, alert, emerg.
# It is also possible to configure the log level for particular modules, e.g.
# "LogLevel info ssl:warn"
#
LogLevel warn

LoadModule clover_module /usr/lib/apache2/modules/mod_clover.so
AddOutputFilterByType CLOVER text/html

# Include module configuration:
IncludeOptional mods-enabled/*.load
IncludeOptional mods-enabled/*.conf

# Include list of ports to listen on
Include ports.conf

Apache を再起動し、http://11.10.90.10/?t=1&m=9 を開きます。今度は、DOCTYPE が HTML5、DocMode が IE9 になっており、mod_clover が意図通りに動いています。フィルターの順番を変えただけなので、HTTP 応答の圧縮も正しく行われています。

image