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 出来なかった場合は、全体をエラーにするのではなく、その変数だけをスキップして欲しいですね。

広告

Brute-force attack against NTLMv2 Response

2016 年 9 月の Windows Update で、NTLM SSO の動作に関連する脆弱性 CVE-2016-3352 が修正されたようです。

Microsoft Security Bulletin MS16-110 – Important
https://technet.microsoft.com/library/security/MS16-110

An information disclosure vulnerability exists when Windows fails to properly validate NT LAN Manager (NTLM) Single Sign-On (SSO) requests during Microsoft Account (MSA) login sessions. An attacker who successfully exploited the vulnerability could attempt to brute force a user’s NTLM password hash.

To exploit the vulnerability, an attacker would have to trick a user into browsing to a malicious website, or to an SMB or UNC path destination, or convince a user to load a malicious document that initiates an NTLM SSO validation request without the consent of the user.

CVE – CVE-2016-3352
http://cve.mitre.org/cgi-bin/cvename.cgi?name=CVE-2016-3352

Microsoft Windows 8.1, Windows RT 8.1, and Windows 10 Gold, 1511, and 1607 do not properly check NTLM SSO requests for MSA logins, which makes it easier for remote attackers to determine passwords via a brute-force attack on NTLM password hashes, aka "Microsoft Information Disclosure Vulnerability."

"NTLM SSO" などのキーワードで適当にインターネット検索すると、今年 8 月に書かれた以下の記事が見つかります。

The Register – Reminder: IE, Edge, Outlook etc still cough up your Windows, VPN credentials to strangers
http://www.theregister.co.uk/2016/08/02/smb_attack_is_back/?mt=1474231650819

画面キャプチャーを見ると、なんと Microsoft アカウントのパスワードが解析されてしまっています。そして Youtube の埋め込み動画では、SMB パケットがブラウザーからリークしていることを示しています。つまり、SMB パケットに埋め込まれた NTLM メッセージに対して brute-force 攻撃をしかけることで Microsoft アカウントのパスワードを解析できる、ことを示しているようです。

これは理論的に可能でしょう。が、もしそれが 「簡単に」 できるのであれば、それは NTLM プロトコルの死を意味するべきであり、パッチとして一朝一夕に対応できるものではないはずです。SSLv3 や RC4 と同様にそのプロトコルの使用を止めるべきですが、非ドメイン環境において NTLM の代わりとなるような認証プロトコルは Windows には実装されていないはずです。

というわけで、NTLM に対する brute-force がどれぐらい簡単なのかを調べることにしました。まず、NTLM プロトコルがどうやってユーザー認証を行っているかを説明します。と言っても以下の PDF を読み解くだけです。

[MS-NLMP]: NT LAN Manager (NTLM) Authentication Protocol
https://msdn.microsoft.com/en-us/library/cc236621.aspx

NTLM が混乱を招く点として、一つのプロトコルが複数のプロトコル バージョン (LanMan, NTLMv1, NTLMv2) に対応していることです。Wiki の情報を見ると NTLMv2 は NT 4.0 SP4 から採用されているので、 NTLMv2 だけで現在は問題なく生きていけるはずです。ただし XP などの古い OS において、さらに古い OS との互換性のために NTLMv1 や Lanman に fallback するような動作が有効になっている場合があります。このへんの細かい話は長くなりそうなので、以下の KB に丸投げします。

NT LAN Manager – Wikipedia, the free encyclopedia
https://en.wikipedia.org/wiki/NT_LAN_Manager

How to prevent Windows from storing a LAN manager hash of your password in Active Directory and local SAM databases
https://support.microsoft.com/en-us/kb/299656

Security guidance for NTLMv1 and LM network authentication
https://support.microsoft.com/en-us/kb/2793313

NTLM は Challenge Reponse Authentication の一つで、簡単に書くとサーバーとクライアントが以下 3 つのメッセージを交換することで認証が行われます。(仕様によると Connectionless モードの場合は Negotiate が存在しないようですが、見たことがないのでパス。)

Client: "I want you to authenticate me."
(= Negotiate Message)

Server: "Sure. Challenge me. Use 0x0123456789abcdef as a ServerChallenge."
(= Challenge Message)

Client: "My response is !@#$%^&*()_+…"
(= Authenticate Message)

NTLM は単体で使われるプロトコルではなく、必ず別のプロトコルに埋め込まれて使われます。例えば SMB の中で使われる場合には、SMB Session Setup コマンドに埋め込まれます。ダイレクト SMB ポートである 445/tcp をキャプチャーしたときの Network Monitor 上での見え方は以下の通りです。

01
SMB packets over 445/tcp (Lines highlited in purple contain NTLM messages)

02
NTLM Negotiate Message

03
NTLM Challenge Message

04
NTLM Authenticate Message

セクション 3.3.2 NTLMv2 Authentication から、パスワードを解析するのに必要な疑似コードの計算式だけを抜き出すと以下の通りです。

[MS-NLMP]: NTLM v2 Authentication – 3.3.2 NTLM v2 Authentication
https://msdn.microsoft.com/en-us/library/cc236700.aspx

Define NTOWFv2(Passwd, User, UserDom) As
  HMAC_MD5(MD4(UNICODE(Passwd)),
           UNICODE(ConcatenationOf(Uppercase(User), UserDom)))
EndDefine

Set temp to ConcatenationOf(Responserversion,
                            HiResponserversion,
                            Z(6),
                            Time,
                            ClientChallenge,
                            Z(4),
                            ServerName, Z(4))
Set NTProofStr to HMAC_MD5(ResponseKeyNT,
                           ConcatenationOf(CHALLENGE_MESSAGE.ServerChallenge,
                                           temp))
Set NtChallengeResponse to ConcatenationOf(NTProofStr, temp)

使用しているハッシュ関数は HMAC_MD5 と MD4 のみ。入力データはいろいろあって面倒そうに見えますが、それほど難しくありません。特に、疑似コードの中で temp として扱われているバージョンやタイムスタンプなどのメタ情報が、ハッシュ値である NTProofStr と連結してそのまま Authenticate Message の NtChallengeResponse になっているからです。図示したものを ↓ に示します。図中の Metainfo が、上記擬似コードで言うところの temp です。

実際に処理するときは、パスワードを UTF-16 に変換する点と、ユーザー名を大文字に変換する点に注意が必要です。

05
Calculation of NtChallengeResponse in NTLMv2

これで材料が出揃ったのでコードを書きます。まずサーバー側のコードとして、Samba サーバーが NTLM メッセージを処理しているときに、brute-force に必要となる情報をテキスト ファイルとして書き出すようにします。これによって、前述の Youtube 動画がやっていることとほぼ同じことができます。

Yandex SMB hash capture on IE with email message – YouTube
https://www.youtube.com/watch?v=GCDuuY7UDwA

msmania/samba at ntlm-hack
https://github.com/msmania/samba/tree/ntlm-hack

テキスト ファイルと同じ内容をレベル 0 のデバッグ メッセージとしても出力するようにしました。gdb を使って smbd を実行しておくと、SMB 経由で NTLM 認証が行なわれたときにコンソールにログが記録されます。出力される情報はこんな感じです。後でまとめて grep できるようにあえてテキスト ファイルにしました。

Domain:
User: ladyg
Client: LIVINGROOM-PC
UserAndDomain=4c004100440059004700
Challenge=ae65c9f0192d64b9
Auth=0101000000000000b62acefc2d11d201ea3017d2f290d64e00..(長いので省略)
Response=39329a4a4e9052fe3d4dea4ea9c79ac5

次に、Samba サーバーが書き出したテキスト ファイルに対して実際に brute-force を行うプログラムを書きます。hashcat に新しいモードを付け足すことができればベストだったのですが、OpenCL を勉強する時間がなかったので、OpenSSL の関数を呼び出すだけの簡単なプログラムになりました。

msmania/ntlm-crack
https://github.com/msmania/ntlm-crack

このプログラムは Samba が生成したテキスト ファイルに対して、別の引数として指定したのテキスト ファイルの各行をパスワードとして NTLMv2 Reponse を生成し、Samba が出力したデータと一致するかどうかを比較します。パスワード一覧ファイルは、ネット上で探せば簡単に見つかります。ntlm-crack リポジトリにサンプルとして入れてある 10_million_password_list_top_1000.txt は、以下のリポジトリからコピーしたものです。

GitHub – danielmiessler/SecLists
https://github.com/danielmiessler/SecLists

では実際にコマンドを実行して brute-force の速度を計測します。マシン スペックは以下の通り。Windows マシンであればもっと新しいマシンで hashcat をぶん回せたのですが・・無念。

  • OS: Ubuntu 16.04.1 LTS (GNU/Linux 4.4.0-36-generic x86_64)
  • CPU: Intel(R) Core(TM) i5-2520M CPU @ 2.50GHz (Sandy Bridge)

とりあえず 100 万通りのパスワードを試してみます。

$ ./t -f sample.in -l /data/src/SecLists/Passwords/10_million_password_list_top_1000000.txt
No matching password in /data/src/SecLists/Passwords/10_million_password_list_top_1000000.txt.
Tried 999999 strings in 3343 msec.
$ ./t -f sample.in -l /data/src/SecLists/Passwords/10_million_password_list_top_1000000.txt
No matching password in /data/src/SecLists/Passwords/10_million_password_list_top_1000000.txt.
Tried 999999 strings in 3372 msec.
$ ./t -f sample.in -l /data/src/SecLists/Passwords/10_million_password_list_top_1000000.txt
No matching password in /data/src/SecLists/Passwords/10_million_password_list_top_1000000.txt.
Tried 999999 strings in 3344 msec.

大体 3 秒ちょいです。特に工夫をしたわけでもないのですが、予想していたより速いです。UTF-16 変換の処理を予め済ませて、かつ並列処理をすれば 1M/s は軽く越えられそう。

もちろん実際に使われているのはこんな子供騙しではありません。参考として 4 年前の記事ですが、25-GPU を使って 95^8 通りのハッシュを 5.5 時間で生成できたと書かれています。ここでいう NTLM cryptographic algorithm が厳密に何を意味するのかは書かれていません。巷では、UTF-16 エンコードしたパスワードの MD4 ハッシュを NTLM ハッシュと呼ぶことが多く、仮にそうだとすると、5.5 時間という数字には HMAC-MD5 を 2 回計算する部分が含まれていません。試しに、今回作った ntlm-crack から HMAC-MD5 の演算を飛ばして再度実行してみます。

$ ./t -f sample.in -l /data/src/SecLists/Passwords/10_million_password_list_top_1000000.txt
No matching password in /data/src/SecLists/Passwords/10_million_password_list_top_1000000.txt.
Tried 999999 strings in 347 msec.
$ ./t -f sample.in -l /data/src/SecLists/Passwords/10_million_password_list_top_1000000.txt
No matching password in /data/src/SecLists/Passwords/10_million_password_list_top_1000000.txt.
Tried 999999 strings in 347 msec.
$ ./t -f sample.in -l /data/src/SecLists/Passwords/10_million_password_list_top_1000000.txt
No matching password in /data/src/SecLists/Passwords/10_million_password_list_top_1000000.txt.
Tried 999999 strings in 346 msec.

計算時間が約 1/10 で済んでしまいました。この比率が 25-GPU マシンにも適用されるとすると、8 文字のパスワードをクラックするのに 4 年前は 55 時間かかっていたはずです。怪しい概算ですが。

25-GPU cluster cracks every standard Windows password in <6 hours | Ars Technica
http://arstechnica.com/security/2012/12/25-gpu-cluster-cracks-every-standard-windows-password-in-6-hours/

今年は AlphaGo のニュースが衝撃でしたが、そのときの Nature 論文では 1,920 CPUs + 280 GPUs のマシンで AlphaGo を動かしたという実績が書かれているので、個人での所有は難しいにしても、あるべきところ (Google や NSA?) には 4 桁のプロセッサーを動かせるマシンが存在していると仮定できます。これで 2 桁分稼げるので、10 桁程度のパスワードであれば数日で解ける恐れがあります。12 桁のパスワードにしておけば年単位の時間が必要になるので安心かも・・・?

話が逸れておきましたが、冒頭の CVE-2016-3352 の話に戻ります。Security Bulletin には、以下のような修正がなされたと書かれています。つまり、誰彼構わず NTLM SSO 認証のための SMB パケットを送るのは止めた、ということでしょうか。

The security update addresses the vulnerability by preventing NTLM SSO authentication to non-private SMB resources when users are signed in to Windows via a Microsoft Account network firewall profile for users who are signed in to Windows via a Microsoft account (https://www.microsoft.com/account) and connected to a “Guest or public networks” firewall profile.

この修正ができたということは、 「不特定多数のサーバーに SMB パケットを送ってしまう動作があったため、本来できないはずの brute-force 攻撃の標的になってしまう」 ことが問題とされていたわけです。これでようやく、Security Bulletin の "An attacker who successfully exploited the vulnerability could attempt to brute force" という部分が腑に落ちました。この件に関して言えば、brute-force の成功が現実的かどうかは関係なく、brute-force が可能であることそのものが問題だったわけです。NTLM はまだ生きていていいんだ。

あえてケチをつけるならば、CVE の方の記述における "to determine passwords via a brute-force attack on NTLM password hashes" でしょうか。NTLM は複数のハッシュ (MD4 と HMAC-MD5) を使いますが、NTLM password hash と書くと、パスワードのハッシュ、すなわち一段階目の MD4 ハッシュを想定するのが普通です。しかし、MD4 ハッシュは一回目の HMAC-MD5 の鍵として使われるだけで、ネットワーク上を流れることはなく、brute-force の攻撃対象にはなりません。Microsoft 側の Security Bulletin では "attempt to brute force a user’s NTLM password hash" となっており、こちらの記述のほうがより正確な気がします。最近の流行は pass-the-hash 攻撃なので、平文のパスワードに替えて、ハッシュ値が brute-force の標的であってもおかしくはありません。

ところで、なぜ Microsoft アカウントに関する言及があるかというと、冒頭で紹介した The Register の記事にもありますが、Microsoft アカウントのユーザー名がユーザーのメール アドレスであり、OneDrive や MSDN などのサービスのアカウントとしても使われているからです。世界のどこかにあるパソコンのユーザー アカウント "Mike" のパスワードが分かってもできることは限られていますが、Microsoft アカウントのパスワードが解析されると大変なことになります。だからこそ今までこの古いバグが放置されてきたのかもしれません。ただ、ユーザー名が平文で SMB として流れるのは気持ち悪いですが。

(2016/9/19 追記)

9 月のアップデート後に、LAN ディスクや SAMBA にアクセスできなくなったというツイートやフォーラムを幾つか見つけましたが、おそらく CVE-2016-3352 に対する修正が原因と思われます。どうするんでしょうかね。

update kb3185614の不具合について、LANDISKへの接続やリモートアクセスができなくなる – マイクロソフト コミュニティ
http://answers.microsoft.com/ja-jp/windows/forum/windows_10-update/update/f5219540-a2a5-4b09-b9b6-e944dcbbed38

SUDO for Windows

Windows で動く Linux の sudo コマンド的なものを作って GitHub で公開しました。

msmania/sudo: SUDO for Windows
https://github.com/msmania/sudo

Windows でコンソールを使った作業をする場合、必要がない限りは、管理者権限のない制限付きトークンのコマンド プロンプト (もしくは PowerShell) で作業すると思います。Windows の困ったところは、管理者権限が必要なコマンドを実行するときには、新しいコンソールを別途起動しないといけないことです。しかし、1 コマンド実行したいだけなのに、わざわざ新しくコンソールを開いて使い終わったら閉じるのは時間がもったいないのです。というわけで、通常のコンソールと管理者権限のコンソールの二窓体制で作業する、というのが日常かと思います。しかし、最近の Windows は無駄にグラフィカルで、ウィンドウを切り替えるときの Alt+Tab やタスクバー アイコンのプレビューがいちいち大袈裟です。今度はこれをレジストリで無効にしておく、というような具合に、理不尽なカスタマイズが次々と必要になります。そこで、sudo を作ることにしました。

代替策も探しましたが、意外とありません。例えば、runas.exe を使って built-in の Administrator ユーザーでログオンすれば管理者権限は使えます。しかし次の 2 点において不満があり使えません。

  • runas.exe で cmd.exe を起動すると、結局新しいコンソールが起動する
  • Build-in の Administrator 以外では管理者権限にならない

SysInternals の psexec.exe を使うと runas みたいなことができますが、こちらはそもそも管理者権限がないと実行できないので本末転倒です。

sudo に求めたい要件は以下の通りです。

  1. 通常のコンソール上でそのまま作業できる (= 新しいコンソールは開かない)
  2. Administrator ではなく、管理者グループに所属している作業ユーザーで管理者権限を使える
  3. .NET やスクリプト経由ではなく、ネイティブの sudo.exe が欲しい

GitHub 上を "sudo windows" などで検索すると、幾つかそれっぽいプロジェクトは見つかりますが、1. の要件を満たしてくれません。

maxpat78/Sudo: Executes a command requesting for elevated privileges in Windows Vista and newer OS.
https://github.com/maxpat78/Sudo

jpassing/elevate: elevate — start elevated processes from the command line
https://github.com/jpassing/elevate

どちらも動作原理は同じで、ShellExecute API を lpVerb="runas" で実行しています。UAC プロンプトを表示させて管理者権限を得るには一番簡単な方法なのですが、コンソールから cmd.exe を起動すると別のコンソールが開いてしまうのでこれは使えません。

ShellExecute function (Windows)
https://msdn.microsoft.com/en-us/library/windows/desktop/bb762153(v=vs.85).aspx

ShellExecute が駄目となると CreateProcess でプロセスを作るしかありません (他に WinExec という化石のような API もありますが)。が、以下のブログに記載があるように、CreateProcess で権限昇格が必要なプロセスを起動することはできません。

Dealing with Administrator and standard user’s context | Windows SDK Support Team Blog
https://blogs.msdn.microsoft.com/winsdk/2010/05/31/dealing-with-administrator-and-standard-users-context/

CreateProcess() and CreateProcessWithLogonW do not have new flags to launch the child process as elevated. Internally, CreateProcess() checks whether the target application requires elevation by looking for a manifest, determining if it is an installer, or if it has an app compat shim. If CreateProcess() determines the target application requires elevation, it simply fails with ERROR_ELEVATION_REQUIRED(740). It will not contact the AIS to perform the elevation prompt or run the app.

最後の AIS というのは Application Information Service (AppInfo サービス) という UAC を司る憎いやつです。いや、実際はお世話になっているのですが。

Understanding and Configuring User Account Control in Windows Vista
https://technet.microsoft.com/en-us/library/cc709628(v=ws.10).aspx

となると残された道は 1 つしかなく、sudo.exe を昇格させて実行し、そこから CreateProcess で子プロセスを作る方法です。権限は自動的に継承されるので、子プロセスも昇格されたままになるはずです。

さらに要件 1. を満たすためには、もう一捻り必要です。sudo.exe をコンソール アプリケーション、すなわち /SUBSYSTEM:CONSOLE オプションを使ってリンクした場合、そのコンソール プログラムを昇格していないコンソール上から起動すると、UAC プロンプトの後にやはり新たなコンソールが起動して、プログラム終了時にコンソールが破棄される動作になるので、標準出力が見えません。したがって、sudo.exe は /SUBSYSTEM:WINDOWS を使ってリンクしなければなりません。この場合、単純にプログラムから printf などで標準出力に文字を出力しても、データは破棄されるだけでどこにも表示されません。そこで、プログラムの標準出力を親プロセスのコンソールに関連付けて、小プロセスからの標準出力を受け取って親プロセスの標準出力にリダイレクトするようにします。うう面倒くさい・・。

小プロセスの標準入出力をパイプとして受け取る部分は、以下のサンプルのコードを流用できます。

Creating a Child Process with Redirected Input and Output (Windows)
https://msdn.microsoft.com/en-us/library/windows/desktop/ms682499(v=vs.85).aspx

親プロセスのコンソールを自分の標準出力に関連付ける部分は、AttachConsole API に ATTACH_PARENT_PROCESS を渡すことで簡単に実現できます。

AttachConsole function (Windows)
https://msdn.microsoft.com/en-us/library/windows/desktop/ms681952(v=vs.85).aspx

sudo.exe 起動時に UAC プロンプトを表示させるには、マニフェスト XML で requestedExecutionLevel を highestAvailable に設定するだけです。Mt.exe を使うと、exe にマニフェストを埋め込むことが出来るので、Makefile の中でリンカーの後に Mt.exe を実行するように記述します。

Mt.exe (Windows)
https://msdn.microsoft.com/en-us/library/aa375649(v=vs.85).aspx

これらを組み合わせれば、基本の動きはほぼ達成できますが、最初の MSDN のサンプルには若干問題があります。サンプルをそのままコピーして標準出力に文字を出力するだけの簡単なプロセス (ipconfig.exe など) を実行すると、文字は出力されるのですが、ipconfig.exe が終了しても sudo.exe が終わりません。ReadFromPipe における ReadFile の呼び出しで、子プロセスが終了しているにも関わらず制御が返ってこないためです。原因は、STARTUPINFO 構造体に渡した子プロセス用のパイプへのハンドル、すなわち g_hChildStd_OUT_Wr と g_hChildStd_IN_Rd を閉じていないためと考えられます。ちゃんと確かめていないのですが、STARTUPINFO 構造体に渡したハンドルは、複製されてから小プロセスに渡されるので、子プロセス側で標準入出力のハンドルを破棄しても、複製元の g_hChildStd_OUT_Wr と g_hChildStd_IN_Rd を自分で保持している限りパイプが有効で、ReadFile はそれを待ち続けているのだと思います。じゃあ単純に CreateProcess の後でをさっさとハンドルをクローズしてしまえばよいかというと、大方のシナリオでは動くとは思いますが、微妙だと思います。子プロセスによっては、すぐに標準出力にデータを出力しない動作をするものがあってもおかしくありません。しかし、sudo.exe 側はパイプにデータが残っているかどうかだけで出力を続けるかどうかを判断しているので、子プロセスが動作中にも関わらずループを抜けてしまうかもしれません。

現時点のバージョンの sudo.exe では、単純に CreateProcess のあと子プロセスが終了するまで WaitForSingleObject で待って、その後でじっくりとパイプの中を読み出すようにしました。この実装も微妙で、子プロセスの出力量が膨大であったときにパイプが溢れる可能性がありますし、そもそも子プロセスが終わるまで待っているのは美しくありません。そのうち、子プロセスの状態を監視するようなスレッドを作って対応します。

WaitForSingleObject は使うものの、INIFINITE を渡して永遠に待ち続けるのはさすがに嫌だったので、タイムアウト値を設けることにしました。初め、このタイムアウト値は環境変数経由で設定しようと思っていました。そうすれば、CreateProcess の第二引数には WinMain の引数の pCmdLine をそのまま渡すだけで済むので、楽ができるのです。しかし、ここでも Windows のコマンド プロンプトの困った仕様が立ちはだかります。コマンドを実行している時だけに有効になる一時的な環境変数が使えないのです。正式に何というのかわかりませんが、つまり以下のようなことができません。make を実行するときによく使いますね。

$ cat test.sh
echo $HOGE

$ echo $HOGE

$ HOGE=1 ./test.sh
1

$ echo $HOGE

$

一応、似たようなことはできます。それが以下のフォーラムで出てきているやり方で、cmd /C を使って子プロセスの中で set コマンドを実行してから目的のコマンドを実行する方法です。

Setting environment variable for just one command in Windows cmd.exe – Super User
http://superuser.com/questions/223104/setting-environment-variable-for-just-one-command-in-windows-cmd-exe

ちなみにこの中で紹介されている、/V オプションを使った環境変数の遅延評価は、子プロセスでは必要ですが孫プロセスでは不要です。マニアックですが、こんな感じです。

> cmd /C "set HOGE=1 && echo %HOGE% !HOGE! && cmd /c echo %HOGE% !HOGE!"
%HOGE% !HOGE!
1 !HOGE!

> cmd /V /C "set HOGE=1 && echo %HOGE% !HOGE! && cmd /c echo %HOGE% !HOGE!"
%HOGE% 1
1 1

したがって、sudo.exe を使って cmd /c "set TIMEOUT=10 && sudo ipconfig" 的なことをやれば一応は環境変数からタイムアウト値を取れる、と思えますが結局駄目でした。UAC 昇格を要求するコマンドを起動した場合、環境変数が引き継がれません。これは Linux の sudo のデフォルト動作と同じですが、sudo に -E オプションを付加すると環境変数を引き継ぐことができます。

$ echo $HOGE

$ HOGE=1 sudo ./test.sh

$ HOGE=1 sudo -E ./test.sh
1

上記の理由で、環境変数を使うのは諦めて引数を取ることにしました。空白などの扱いを自分で決めたかったので pCmdLine をパースするステート マシンを 1 から書きました。それが CCommandOptions クラスですが、無駄に長いです。たぶんもっとまともな実装方法があると思います。アルゴリズムは苦手・・。

とりあえずこれで要件を満たすコマンドができました。出力例は ↓ の通りです。ここまで書いて言うのもなんですが、UAC ポップアップの表示が遅いので、もっさりした動作にしかなりません。なんだかんだスピードを求めるなら二窓体制が無難かも。

> sudo /t 10 powershell "get-vm | ?{$_.State -eq ‘Running’} | select -ExpandProperty networkadapters | select vmname, macaddress, switchname, ipaddresses | fl *"
[sudo] START
Spawning a process (Timeout = 10 sec.)

VMName : VM1
MacAddress : 00155DFE7A01
SwitchName : External
IPAddresses : {10.124.252.117, fe80::8d2d:7dca:4498:82f9, 2001:4898:200:13:fc0e:945e:ffce:2bb5,
2001:4898:200:13:8d2d:7dca:4498:82f9}

[sudo] END
Press Enter to exit …

WorkQueue Model with POSIX Threads

少し前の記事で書きましたが、MNIST を MDS で処理する計算は、全て Python で書いたせいかパフォーマンスが悪く、N=10000 のデータにも関わらず N=200 程度で 6 分もかかってしまい、話になりませんでした。

MNIST with MDS in Python | すなのかたまり
https://msmania.wordpress.com/2015/12/13/mnist-with-mds-in-python/

しかし、ここまでやってようやく気づいてしまったのは、Field クラスは C++ で書いてしまったほうがよかったかもしれない、ということ。Sandy Bridge だから行列計算に AVX 命令を使えば高速化できそう。というか Python の SciPy は AVX 使ってくれないのかな。ノードにかかる運動ベクトルをラムダ式のリストにしてリスト内包表記で計算できるなんてエレガント・・という感じだったのに。

そこで、AVX 命令を使って演算するモジュールを C++ で書いて Boost.Python 経由で読み込むように書き換えてみました。(ばねの力を計算する部分で少しアルゴリズムも少し変えています。) 結果、期待していたよりもパフォーマンスが上がり、N=1000 でも 1 分弱、N=10000 の場合でも 1 時間程度で結果を得ることができました。

パラメーターをいろいろ変えて試しているので動きが統一されていませんが、結果はそれなりに統一されています。例えば、青色 (=1) のデータは、データ間の距離がかなり短いらしく収束が早いことがすぐに分かります。逆に、灰色 (= 8) や白色 (= 7) のデータは他の数字と混じっており、ユークリッド距離だけだと区別が難しそうです。緑 (= 4) と紺色 (= 9) は同じエリアを共有しがちですが、確かに数字の形を考えると、似ていると言えなくもありません。。

http://ubuntu-web.cloudapp.net/ems/cmodule.htm

image

結果の考察はさておいて、もう少し欲を出してみたくなりました。そこで試みたのは 2 点。

  1. ノードを動かす前に、各ノード間をばねで繋ぐ際のユークリッド距離の計算が遅い
  2. オイラー法の計算の並列化

1. は未だ Python でやっており、N=10000 の場合だと、C(10000, 2) = 49,995,000 回も 784 次元座標のユークリッド距離を計算していることになるので、馬鹿にならない時間がかかります。入力データは変わらないので、予め全部の距離を計算してファイルに書き出しておくことにしました。おそらく、ファイルを読むだけの方が距離を計算するのよりは早いはずです。

2. はそのままマルチスレッド化です。1 時間も 1 CPU だけが仕事をしているのは何かもったいないので、何とか並列化したいところ。アイディアとしては、扱っている 2 次元データを次元毎にスレッドを分けて計算したい、というものです。

結果から書くと、1 は成功、2 は失敗です。1. だけ実装して、N=10000 で 1 時間を切ることはできました。

計算の大部分を占めるのが、Field::Move で、最初にばねの力を足し合わせるためのループから Field::Spring::load を呼んでいます。次元毎に処理を分けるのは Move() 後半のループで、コード自体は簡単に書けましたが、パフォーマンスはほぼ同じか、少し悪くなりました。前半のばねの計算のところでは、ばね毎の計算を分けて各スレッドに割り振ってみましたが、こちらのパフォーマンスは最悪で、2 倍以上落ちました。

void Field::Spring::load() {
    std::valarray<double> diff(_field->_dim);
    int i, n = _field->_m.size();
    double norm = .0;
    for (i = 0 ; i < _field->_dim ; ++i) {
        diff[i] = _field->_position[_n2 + i * n] – _field->_position[_n1 + i * n];
        norm += diff[i] * diff[i];
    }
    norm = sqrt(norm);
    for (i = 0 ; i < _field->_dim ; ++i) {
        double f = _k * (1 – _l / norm) * diff[i];
        _field->_accel[_n1 + n * i] += f / _field->_m[_n1];
        _field->_accel[_n2 + n * i] += -f / _field->_m[_n2];
    }
}

void Field::Move(double dt) {
    int i, j, n = _m.size();
    _accel = .0;
    for (auto &f : _forces) {
        if (f != nullptr) {
            f->load(); <<<< この呼び出しを WorkItem にする
        }
    }
    for (i = 0 ; i < _dim ; ++i) {
        for (j = 0 ; j < n ; ++j) { <<<< このループを WorkItem にする
            int idx = j + i * n;
            _velocity[idx] += dt * _accel[idx];
            _velocity[idx] -= _velocity[idx] * _friction[j] / _m[j];
            _position[idx] += dt * _velocity[idx];
        }
    }
}

コードは dev-mt ブランチにまとめています。コミットの順番を間違えた上、マージのやり方も微妙でコミット履歴がぐちゃぐちゃ・・

msmania/ems at dev-mt · GitHub
https://github.com/msmania/ems/tree/dev-mt

Linux でマルチスレッドのプログラムをまともに書いたことがなかったので、最善か分かりませんが、Windows でよくある、WorkQueue/WorkItem モデル (正式名称が分からない) を POSIX Thread を使って一から書きました。もしかすると標準や Boost に既にいいのがありそうですが。

ヘッダーの workq.h

class WorkQueue {
public:
    class Job {
    public:
        virtual ~Job() {}
        virtual void Run() = 0;
    };

private:
    enum WorkItemType {
        wiRun,
        wiExit,
        wiSync
    };

    class Event {
    private:
        pthread_mutex_t _lock;
        pthread_cond_t _cond;
        int _waitcount;
        int _maxcount;

    public:
        Event(int maxcount);
        virtual ~Event();
        void Wait();
    };

    class WorkItem {
    private:
        WorkItemType _type;
        void *_context;

    public:
        WorkItem(WorkItemType type, void *context);
        virtual ~WorkItem();
        virtual void Run();
    };

    int _numthreads;
    std::vector<pthread_t> _threads;
    Event _sync;
    pthread_mutex_t _taskqlock;
    std::queue<WorkItem*> _taskq;

    static void *StartWorkerthread(void *p);
    void *Workerthread(void *p);

public:
    WorkQueue(int numthreads);
    virtual ~WorkQueue();
    int CreateThreads();
    void JoinAll();
    void AddTask(Job *job);
    void Sync();
    void Exit();
};

ソースの workq.cpp

#include <pthread.h>
#include <unistd.h>
#include <vector>
#include <queue>
#include "workq.h"

#ifdef _LOG
#include <stdio.h>
#define LOGINFO printf
#else
#pragma GCC diagnostic ignored "-Wunused-value"
#define LOGINFO
#endif

WorkQueue::Event::Event(int maxcount) : _waitcount(0), _maxcount(maxcount) {
    pthread_mutex_init(&_lock, nullptr);
    pthread_cond_init(&_cond, nullptr);
}

WorkQueue::Event::~Event() {
    pthread_cond_destroy(&_cond);
    pthread_mutex_destroy(&_lock);
}

// Test Command: for i in {1..1000}; do ./t; done
void WorkQueue::Event::Wait() {
    LOGINFO("[%lx] start:wait\n", pthread_self());
    pthread_mutex_lock(&_lock);
    if (__sync_bool_compare_and_swap(&_waitcount, _maxcount, 0)) {
        pthread_cond_broadcast(&_cond);
    }
    else {
        __sync_fetch_and_add(&_waitcount, 1);
        pthread_cond_wait(&_cond, &_lock);
    }
    pthread_mutex_unlock(&_lock);
}

WorkQueue::WorkItem::WorkItem(WorkItemType type, void *context)
    : _type(type), _context(context) {}

WorkQueue::WorkItem::~WorkItem() {}

void WorkQueue::WorkItem::Run() {
    switch (_type) {
    case wiExit:
        LOGINFO("[%lx] exiting\n", pthread_self());
        pthread_exit(nullptr);
        break;
    case wiSync:
        if (_context) {
            ((Event*)_context)->Wait();
        }
        break;
    case wiRun:
        ((Job*)_context)->Run();
        break;
    default:
        break;
    }
}

void *WorkQueue::StartWorkerthread(void *p) {
    void *ret = nullptr;
    if (p) {
        ret = ((WorkQueue*)p)->Workerthread(p);
    }
    return ret;
}

void *WorkQueue::Workerthread(void *p) {
    while (true) {
        WorkItem *task = nullptr;
        pthread_mutex_lock(&_taskqlock);
        if (!_taskq.empty()) {
            task = _taskq.front();
            _taskq.pop();
        }
        pthread_mutex_unlock(&_taskqlock);
        if (task != nullptr) {
            task->Run();
            delete task;
        }
        else {
            usleep(10000);
        }
    }
}

WorkQueue::WorkQueue(int numthreads) : _numthreads(numthreads), _sync(numthreads) {
    pthread_mutex_init(&_taskqlock, nullptr);
    _threads.reserve(numthreads);
}

WorkQueue::~WorkQueue() {
    if (_threads.size() > 0) {
        JoinAll();
    }
    pthread_mutex_destroy(&_taskqlock);
}

int WorkQueue::CreateThreads() {
    int ret = 0;
    pthread_attr_t attr;
    pthread_attr_init(&attr);
    pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_JOINABLE);
    for (int i = 0; i<_numthreads ; ++i) {
        pthread_t p = 0;
        ret = pthread_create(&p, &attr, StartWorkerthread, this);
        if (ret == 0) {
            _threads.push_back(p);
        }
        else {
            LOGINFO("pthread_create failed – %08x\n", ret);
            break;
        }
    }
    pthread_attr_destroy(&attr);
    return ret;
}

void WorkQueue::JoinAll() {
    for (auto &t : _threads) {
        pthread_join(t, nullptr);
    }
    _threads.clear();
}

void WorkQueue::AddTask(Job *job) {
    pthread_mutex_lock(&_taskqlock);
    _taskq.push(new WorkItem(wiRun, job));
    pthread_mutex_unlock(&_taskqlock);
}

void WorkQueue::Sync() {
    pthread_mutex_lock(&_taskqlock);
    for (int i = 0 ; i<_numthreads; ++i) {
        _taskq.push(new WorkItem(wiSync, &_sync));
    }
    pthread_mutex_unlock(&_taskqlock);
    _sync.Wait();
}

void WorkQueue::Exit() {
    pthread_mutex_lock(&_taskqlock);
    for (int i = 0 ; i<_numthreads; ++i) {
        _taskq.push(new WorkItem(wiExit, nullptr));
    }
    pthread_mutex_unlock(&_taskqlock);
}

WorkQueue クラスがキューを持っていて、各ワーカー スレッドが放り込まれた WorkItem を逐次処理します。それに加えてある種の同期処理を付け加えました。今回の例で言えば、ばねの力を計算する WorkItem を全部投げ終わった後、速度や位置の計算をするためには、全てのばねの計算が完了していないといけません。つまり、WorkItem が全て処理されたかどうかを WorkQueue 側で判断できる機構が必要になります。

同期処理は、pthread に加えて条件変数 (condition varialbe) を使って実現しています。これは Windows のカーネル オブジェクトの一つであるイベントに似ています。WorkQueue::Sync() を呼ぶと、条件変数のシグナル待ちを引き起こす WorkItem をワーカー スレッドの数だけ投げ込んで、待機状態になったスレッドの数がワーカー スレッドと同じになるまで、Sync() を呼び出しているスレッドもを待機させておく、という動作を行ないます。

話を戻して、ばねの力の計算、すなわち Field::Spring::load() の並列化が失敗した原因は明白で、個々のワークアイテムが細かすぎたことと、ばねの力を加速度のベクトルに代入するときに排他ロックを獲得する必要があるからでしょう。これのせいで、WorkItem を出し入れしているコストがだいぶ高くついてしまいます。もし double をアトミックに加算する命令があれば排他ロックしなくてもいいのですが・・・。アルゴリズムでカバーするとすれば、ばねにつながっているノードがスレッドごとに重複しないように WorkItem を分ける方法がありますが、これだと、全部で C(10000, 2) = 49,995,000ある計算を C(5000, 2) 12,497,500 分は 2 スレッドで処理して残りの 25,000,000 は 1 スレッドで処理する、という感じになって、大して得しなそうなので断念しました。他にもっとうまい分け方を思いついたら試してみます。

速度と位置の計算は、単純に次元毎にスレッドを分けられるため排他ロックの必要はありませんが、やはり WorkItem が細かいので並列化のコストのほうが高くなってしまったのだと考えられます。3 次元プロットだったら使えるのかもしれませんが、まだそこまで手を出す段階じゃない・・。

こんなので土曜日が無駄になってしまった。もったいない。

Use matplotlib in a virtualenv with your own Python build

真っ新の状態の Ubuntu 15.10 に、Python 2.7 をソースからビルドして、matplotlib を virtualenv で動かせるようになるまで一日ぐらいハマったので、コマンドをまとめておきます。

まず、ビルドに必要なパッケージを入れます。

sudo apt-get update
sudo apt-get install build-essential git openssh-server vim

今回インストールするパッケージは以下の通り。2016/1/4 時点での最新バージョンです。

名前 URL バージョン 依存関係
OpenSSL http://www.openssl.org/source/ 1.0.2e なし
zlib http://zlib.net/ 1.2.8 なし
Tcl http://tcl.tk/software/tcltk/download.html 8.6.4 なし
Tk http://tcl.tk/software/tcltk/download.html 8.6.4 Tcl
libx11-dev
Python https://www.python.org/downloads/ 2.7.11 OpenSSL
zlib
Tcl
Tk

Python 以外にソースからビルドが必要になるコンポーネントの理由は↓。もちろん apt-get でインストールすることもできます。

  • numpy/scipy/matplotlib をインストールするときに pip を使う
  • pip は HTTPS で zip をダウンロードしてくるので、OpenSSL と zlib が必要
  • matplotlib でプロットを GUI 表示するために ビルトイン モジュールである _tkinter が必要

まずは OpenSSL。コードは GitHub からクローンします。

$ git clone https://github.com/openssl/openssl.git
$ cd openssl/
$ git checkout refs/tags/OpenSSL_1_0_2e
$ ./config shared –prefix=/usr/local/openssl/openssl-1.0.2e
$ make
$ sudo make install
$ sudo ln -s /usr/local/openssl/openssl-1.0.2e /usr/local/openssl/current

次 zlib。

$ wget http://zlib.net/zlib-1.2.8.tar.gz
$ tar -xvf zlib-1.2.8.tar.gz
$ cd zlib-1.2.8/
$ ./configure –prefix=/usr/local/zlib/zlib-1.2.8
$ make
$ sudo make install
$ sudo ln -s /usr/local/zlib/zlib-1.2.8 /usr/local/zlib/current

次 Tcl。

$ wget http://prdownloads.sourceforge.net/tcl/tcl8.6.4-src.tar.gz
$ tar -xvf tcl8.6.4-src.tar.gz
$ cd tcl8.6.4/unix/
$ ./configure –prefix=/usr/local/tcl/tcl-8.6.4 –enable-shared
$ make
$ sudo make install
$ sudo ln -s /usr/local/tcl/tcl-8.6.4 /usr/local/tcl/current

そして Tk。

$ sudo apt-get install libx11-dev
$ wget
http://prdownloads.sourceforge.net/tcl/tk8.6.4-src.tar.gz
$ tar -xvf tk8.6.4-src.tar.gz
$ cd tk8.6.4/unix/
$ ./configure –prefix=/usr/local/tk/tk-8.6.4 –enable-shared \
–with-tcl=/usr/local/tcl/current/lib
$ make
$ sudo make install
$ sudo ln -s /usr/local/tk/tk-8.6.4 /usr/local/tk/current

ちなみに libx11-dev がインストールされていないと、以下のコンパイル エラーが出ます。

In file included from /usr/src/tk8.6.4/unix/../generic/tkPort.h:21:0,
                 from /usr/src/tk8.6.4/unix/../generic/tkInt.h:19,
                 from /usr/src/tk8.6.4/unix/../generic/tkStubLib.c:14:
/usr/src/tk8.6.4/unix/../generic/tk.h:96:25: fatal error: X11/Xlib.h: No such file or directory
compilation terminated.
Makefile:1164: recipe for target ‘tkStubLib.o’ failed

ここまでは余裕です。次に 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/
$ export LDFLAGS=’-L/usr/local/openssl/current/lib -L/usr/local/zlib/current/lib -L/usr/local/tcl/current/lib -L/usr/local/tk/current/lib’
$ export CPPFLAGS=’-I/usr/local/openssl/current/include -I/usr/local/zlib/current/include -I/usr/local/tcl/current/include -I/usr/local/tk/current/include’
$ export LD_LIBRARY_PATH=/usr/local/openssl/current/lib:/usr/local/zlib/current/lib:/usr/local/tcl/current/lib:/usr/local/tk/current/lib
$ ./configure –prefix=/usr/local/python/python-2.7.11 \
–enable-shared –enable-unicode=ucs4
$ make
$ sudo make install
$ sudo ln -s /usr/local/python/python-2.7.11 /usr/local/python/current

make の最後に以下のようなログが出力されるので、必要なビルトイン モジュール (_ssl, _tkinter, zlib) がコンパイルされ、ログに表示されていないことを確認してください。

Python build finished, but the necessary bits to build these modules were not found:
_bsddb             _curses            _curses_panel
_sqlite3           bsddb185           bz2
dbm                dl                 gdbm
imageop            readline           sunaudiodev
To find the necessary bits, look in setup.py in detect_modules() for the module’s name.

失敗例を示します。以下の例では、zlib と _ssl がコンパイルされていないので、後続の手順を実行できません。

Python build finished, but the necessary bits to build these modules were not found:
_bsddb             _curses            _curses_panel
_sqlite3           bsddb185           bz2
dbm                dl                 gdbm
imageop            readline           sunaudiodev
zlib
To find the necessary bits, look in setup.py in detect_modules() for the module’s name.

Failed to build these modules:
_ssl

Python ビルド時のポイントは以下の通りです。

  • ヘッダーやライブラリの有無を自動的に確認し、存在する場合のみモジュールが インストールされる
    (Apache の configure のように、–with-xxx というオプションは存在しない)
  • 予めビルドしておいた zlib や tcl/tk のパスを認識させる必要がある
  • configure 前に環境変数 LDFLAGS, CPPFLAGS を設定しておくと、configure で Makefile に値が反映される
  • ビルトイン モジュールがロードされたときに、依存関係のある共有モジュール tcl/tk を正しく見つからければならないため、環境変数 LD_LIBRARY_PATH で対応
    (後述するが、LD_LIBRARY_PATH ではなく ldconfig でグローバルに追加しておいてもよい。というかその方が楽。)

ここでハマりやすいポイントは共有モジュールの検索パスの追加です。共有モジュールが見つからないと、ビルド後のエクスポート関数のチェックで失敗して、以下のようなエラーが出ます。

// OpenSSL の共有モジュールが見つからない場合
*** WARNING: renaming "_ssl" since importing it failed: build/lib.linux-x86_64-2.7/_ssl.so: undefined symbol: SSLv2_method

// Tcl/Tk の共有モジュールが見つからない場合
*** WARNING: renaming "_tkinter" since importing it failed: build/lib.linux-x86_64-2.7/_tkinter.so: undefined symbol: Tcl_GetCharLength

余談になりますが、./configure –help でパラメーターを確認すると、–with-libs オプションと LIBS 環境変数を使って、追加のライブラリをリンクすることができるように書かれています。今回は共有ライブラリなので、これらのオプションを使ってライブラリを追加する必要がありませんが、実は LIBS 環境変数は罠で、–with-libs オプションを使わないと駄目です。configure を実行すると、–with-libs の値を含めて LIBS 変数を一から作るので、configure 前に LIBS を指定しても上書きされてしまいます。また、ヘルプの書式も分かりにくいのですが、configure は –with-libs の値をそのまま LIBS に追加し、それがリンカのパラメーターの一部になります。したがって、仮に –with-libs を使うときは –with-libs=’-lssl -lz’ というように -l オプションをつけないといけません。実に紛らわしいヘルプです。

$ /usr/src/Python-2.7.11/configure –help
`configure’ configures python 2.7 to adapt to many kinds of systems.

Usage: /usr/src/Python-2.7.11/configure [OPTION]… [VAR=VALUE]…

(snip)

  –with-libs=’lib1 …’  link against additional libs

(snip)

  CFLAGS      C compiler flags
  LDFLAGS     linker flags, e.g. -L<lib dir> if you have libraries in a
              nonstandard directory <lib dir>
  LIBS        libraries to pass to the linker, e.g. -l<library>
  CPPFLAGS    (Objective) C/C++ preprocessor flags, e.g. -I<include dir> if
              you have headers in a nonstandard directory <include dir>
  CPP         C preprocessor

(snip)

これで Python の準備はできました。次に pip をインストールします。方法は幾つかありますが、ここでは get-pip.py を使います。

Installation — pip 7.1.2 documentation
https://pip.pypa.io/en/stable/installing/

ダウンロード時になぜか証明書エラーが出るので –no-check-certificate オプションをつけていますが、基本的には不要です。

$ wget –no-check-certificate https://bootstrap.pypa.io/get-pip.py
$ sudo -H /usr/local/python/current/bin/python get-pip.py

今までの手順通りにやると、ここでエラーが出るはずです。

$ sudo -H /usr/local/python/current/bin/python get-pip.py
Traceback (most recent call last):
  File "get-pip.py", line 17759, in <module>
    main()
  File "get-pip.py", line 162, in main
    bootstrap(tmpdir=tmpdir)
  File "get-pip.py", line 82, in bootstrap
    import pip
  File "/tmp/tmpuPVaWi/pip.zip/pip/__init__.py", line 15, in <module>
  File "/tmp/tmpuPVaWi/pip.zip/pip/vcs/subversion.py", line 9, in <module>
  File "/tmp/tmpuPVaWi/pip.zip/pip/index.py", line 30, in <module>
  File "/tmp/tmpuPVaWi/pip.zip/pip/wheel.py", line 35, in <module>
  File "/tmp/tmpuPVaWi/pip.zip/pip/_vendor/distlib/scripts.py", line 14, in <module>
  File "/tmp/tmpuPVaWi/pip.zip/pip/_vendor/distlib/compat.py", line 31, in <module>
ImportError: cannot import name HTTPSHandler

理由は、sudo で実行している python には LD_LIBRARY_PATH によるライブラリの検索パスが反映されていないためです。sudo -H LD_LIBRARY_PATH=*** /usr/local/python/current/bin/python *** というように一行で実行することもできますが、システム ワイドに検索パスを追加しておいた方が後々楽です。

ここでは /etc/ld.so.conf.d/local.conf というファイルを新しく作って ldconfig を実行します。

john@ubuntu1510:/usr/src$ sudo vi /etc/ld.so.conf.d/local.conf <<< 作成
john@ubuntu1510:/usr/src$ cat /etc/ld.so.conf.d/local.conf
/usr/local/openssl/current/lib
/usr/local/zlib/current/lib
/usr/local/tcl/current/lib
/usr/local/tk/current/lib

john@ubuntu1510:/usr/src$ sudo ldconfig
john@ubuntu1510:/usr/src$ ldconfig -v | grep ^/ <<< 確認
/sbin/ldconfig.real: Path `/lib/x86_64-linux-gnu’ given more than once
/sbin/ldconfig.real: Path `/usr/lib/x86_64-linux-gnu’ given more than once
/usr/lib/x86_64-linux-gnu/libfakeroot:
/usr/local/lib:
/usr/local/openssl/current/lib:
/usr/local/zlib/current/lib:
/usr/local/tcl/current/lib:
/usr/local/tk/current/lib:

/lib/x86_64-linux-gnu:
/sbin/ldconfig.real: /lib/x86_64-linux-gnu/ld-2.21.so is the dynamic linker, ignoring

/usr/lib/x86_64-linux-gnu:
/usr/lib/x86_64-linux-gnu/mesa-egl:
/usr/lib/x86_64-linux-gnu/mesa:
/lib:
/usr/lib:
/sbin/ldconfig.real: Can’t create temporary cache file /etc/ld.so.cache~: Permission denied

これで get-pip.py はうまく実行できるはずです。

$ sudo -H /usr/local/python/current/bin/python get-pip.py
[sudo] password for john:
Collecting pip
  Downloading pip-7.1.2-py2.py3-none-any.whl (1.1MB)
    100% |????????????????????????????????| 1.1MB 204kB/s
Collecting setuptools
  Downloading setuptools-19.2-py2.py3-none-any.whl (463kB)
    100% |????????????????????????????????| 466kB 693kB/s
Collecting wheel
  Downloading wheel-0.26.0-py2.py3-none-any.whl (63kB)
    100% |????????????????????????????????| 65kB 5.4MB/s
Installing collected packages: pip, setuptools, wheel
Successfully installed pip-7.1.2 setuptools-19.2 wheel-0.26.0

pip がインストールされたので、これを使って virtualenv をインストールします。本来であれば、この時点で /usr/local/bin/pip のようなスクリプトが作られて、pip コマンドを実行できるはずなのですか、これまでの手順だとなぜか作られません。それほど支障にはならないので、pip コマンドの代わりに python -m pip <command> という風に python を直に実行します。

$ sudo -H /usr/local/python/current/bin/python -m pip install virtualenv
Collecting virtualenv
  Downloading virtualenv-13.1.2-py2.py3-none-any.whl (1.7MB)
    100% |????????????????????????????????| 1.7MB 333kB/s
Installing collected packages: virtualenv
Successfully installed virtualenv-13.1.2

virtualenv 環境を作ります。

$ /usr/local/python/current/bin/python -m virtualenv ~/Documents/pydev
New python executable in /home/john/Documents/pydev/bin/python
Installing setuptools, pip, wheel…done.
$ cd ~/Documents/pydev/
$ source bin/activate
(pydev)$

virtualenv 内では pip コマンドが使えます。依存パッケージを予めインストールし、普通に pip を使うだけです。

$ sudo apt-get install libblas-dev libatlas-dev liblapack-dev \
gfortran libfreetype6-dev libpng12-dev
$ pip install numpy scipy matplotlib

依存パッケージが存在しなかった時のエラーは以下の通りです。

// scipy インストール時のエラー (1)
  File "scipy/linalg/setup.py", line 20, in configuration
    raise NotFoundError(‘no lapack/blas resources found’)
numpy.distutils.system_info.NotFoundError: no lapack/blas resources found

// scipy インストール時のエラー (2)
building ‘dfftpack’ library
error: library dfftpack has Fortran sources but no Fortran compiler found

// matplotlib インストール時のエラー
* The following required packages can not be built:
* freetype, png

最後に、scatter plot のサンプルを使って動作確認をします。

shapes_and_collections example code: scatter_demo.py — Matplotlib 1.5.0 documentation
http://matplotlib.org/examples/shapes_and_collections/scatter_demo.html

(pydev)$ export TK_LIBRARY=/usr/local/tk/current/lib/tk8.6
(pydev)$ wget
http://matplotlib.org/mpl_examples/shapes_and_collections/scatter_demo.py
(pydev)$ python scatter_demo.py

以下のようなプロットが表示されれば成功です。

scatterdemo

ここで環境変数 TK_LIBRARY を設定しているのは、python からは Tcl が呼ばれているらしく、tk.tcl の検索パスが /usr/local/tcl であり、/usr/local/tk を検索してくれないためです。ファイルは tk 以下にあります。

$ find /usr/local -name tk.tcl
/usr/local/tk/tk-8.6.4/lib/tk8.6/tk.tcl

具体的には、以下のようなエラーが出ます。

  File "/usr/local/python/current/lib/python2.7/lib-tk/Tkinter.py", line 1814, in __init__
    self.tk = _tkinter.create(screenName, baseName, className, interactive, wantobjects, useTk, sync, use)
_tkinter.TclError: Can’t find a usable tk.tcl in the following directories:
    /usr/local/tcl/tcl-8.6.4/lib/tcl8.6/tk8.6 /usr/local/tcl/tcl-8.6.4/lib/tk8.6
/home/john/Documents/pydev/lib/tk8.6 /home/john/Documents/lib/tk8.6 /home/john/Documents/pydev/library

環境変数で対応するのが気持ち悪い場合は、Tcl と Tk を同じディレクトリにインストールしてしまうという手があります。tcl と tk の代わりに、tktcl というディレクトリを作った場合の例を以下にします。こっちのほうがシンプルになってよいかもしれません。

$ wget http://prdownloads.sourceforge.net/tcl/tcl8.6.4-src.tar.gz
$ tar -xvf tcl8.6.4-src.tar.gz
$ cd tcl8.6.4/unix/
$ ./configure –prefix=/usr/local/tktcl/tktcl-8.6.4 –enable-shared
$ make
$ sudo make install
$ sudo ln -s /usr/local/tktcl/tktcl-8.6.4 /usr/local/tktcl/current

$ sudo apt-get install libx11-dev
$ wget
http://prdownloads.sourceforge.net/tcl/tk8.6.4-src.tar.gz
$ tar -xvf tk8.6.4-src.tar.gz
$ cd tk8.6.4/unix/
$ ./configure –prefix=/usr/local/tktcl/tktcl-8.6.4 –enable-shared \
–with-tcl=/usr/local/tktcl/current/lib
$ make
$ sudo make install

$ cat /etc/ld.so.conf.d/local.conf
/usr/local/openssl/current/lib
/usr/local/zlib/current/lib
/usr/local/tktcl/current/lib

$ 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/
$ export LDFLAGS=’-L/usr/local/openssl/current/lib -L/usr/local/zlib/current/lib -L/usr/local/tktcl/current/lib’
$ export CPPFLAGS=’-I/usr/local/openssl/current/include -I/usr/local/zlib/current/include -I/usr/local/tktcl/current/include’
$ ./configure –prefix=/usr/local/python/python-2.7.11 \
–enable-shared –enable-unicode=ucs4
$ make
$ sudo make install
$ sudo ln -s /usr/local/python/python-2.7.11 /usr/local/python/current

今回紹介した matplotlib を virtualenv で使う方法は、ずいぶんとハマっている人が多いです。最初につまずくのは、plt.show() を実行しても何も表示されないという現象です。ほとんどの場合において、Python の _tkinter モジュールが正しくインストールされていないため、matplotlib の backend が non-interactive の agg になっていることが理由と考えられます。これは matplotlib をインポートした後に get_backend() を実行することで確認できます。

// GUI が表示される場合
>>> import matplotlib
>>> matplotlib.get_backend()
u’TkAgg’

// GUI が表示されない場合
>>> import matplotlib
>>> matplotlib.get_backend()
u’agg’

Matplotlib のページを見ると、virtualenv を作るときに –system-site-packages オプションを使うと解決できる、とも書かれていますが、少なくとも今回紹介した手順では、このオプションを使わなくても GUI 表示が可能でした。

Working with Matplotlib in Virtual environments — Matplotlib 1.5.0 documentation
http://matplotlib.org/faq/virtualenv_faq.html

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 のビルドは追加モジュールがいろいろ必要で面倒そうだったので諦めたともいいます。