Bitcoin Core の結合テストのデバッグのやりかた
こんなニッチな話題の需要がどこにあるのかわかりませんが、結合テストを使ってデバッグする際のやり方について紹介します。
ちなみに結合テストと言っているのは test/functional 以下のテストです。ここのテストは実際にノードを複数起動し、P2P のメッセージや RPC を使い外部から python スクリプトでノードとやり取りして動作を検証しています。ノード対 python スクリプトだけでなく、ノード対ノードのやり取りなどもテストしてあります。 結合テストでは、bitcoinノードの挙動を外部から操作・検証する形でコードが記述してあり、コードもpython で書いてあるので比較的読みやすいです。テストコード自体がノードの仕様を把握するための資料としての利用価値も有ります。また、実際に実行し、ノードが出力するログを見ることで特定の状況でノードがどのような振る舞いをするかを知ることもできます。
結合テストの構成
test/functional/test_framework
テストを便利に書けるフレームワークが提供されています。テストの冒頭で、使うノード数やオプションなどをしてするだけで、ノードを立ち上げてくれたり、メッセージのやり取りを行うための簡易なノード実装(mininode)などが提供されています。
test/functional/**.py
テストの目的ごとに作成された python スクリプト。
test/data
テストで使うjsonファイル。
全件テストの実行
さてここからがデバッグの話です。まずは、すべての統合テストをまとめて実行していきましょう。
前提として、bitcoin本体側のビルドが成功している必要があります。ビルドのやり方は doc以下に環境ごとの ビルドのやり方のドキュメントがあるので、そちらを見てみてください。
では実行します。pythonのバージョンが3系であることを確認しておいてください。
$ python test/functional/test_runnner.py
code:term
$ python test/functional/test_runner.py
Temporary test directory at /tmp/test_runner_₿_🏃_20190315_064919
...............
wallet_hd.py passed, Duration: 8 s
.....................................................
rpc_fundrawtransaction.py passed, Duration: 35 s
.................
p2p_compactblocks.py passed, Duration: 36 s
... 略
TEST | STATUS | DURATION
feature_blocksdir.py | ✓ Passed | 2 s
feature_cltv.py | ✓ Passed | 6 s
feature_config_args.py | ✓ Passed | 2 s
feature_csv_activation.py | ✓ Passed | 10 s
feature_dersig.py | ✓ Passed | 6 s
feature_help.py | ✓ Passed | 1 s
feature_includeconf.py | ✓ Passed | 2 s
feature_logging.py | ✓ Passed | 4 s
feature_nulldummy.py | ✓ Passed | 2 s
feature_proxy.py | ✓ Passed | 2 s
feature_reindex.py | ✓ Passed | 3 s
feature_segwit.py | ✓ Passed | 12 s
feature_uacomment.py | ✓ Passed | 2 s
feature_versionbits_warning.py | ✓ Passed | 4 s
interface_http.py | ✓ Passed | 1 s
interface_rest.py | ✓ Passed | 6 s
mempool_accept.py | ✓ Passed | 6 s
mempool_limit.py | ✓ Passed | 5 s
mempool_persist.py | ✓ Passed | 8 s
mempool_reorg.py | ✓ Passed | 3 s
... 略
実行が終わると上のように全てのテストのステータスが一覧で表示されます。もしテストが失敗した場合は、失敗したファイルの実行時に生成されたノードのログやデータ、test-framework のログなどが /tmp/test_runner_₿_🏃_20190315_064919 内に残されます。
個別のファイルの実行
個別のテストファイルを実行する場合には、そのまま python の普通のスクリプトのように実行できます。例えば feature_block.py を実行するなら、
$ python test/functional/feature_block.py
で実行できます。
これだけだと、テストが成功するとログデータはクリアされて見れないのですが、 --nocleanup オプションを付けて実行することで、ログデータを残すことができます。
code:shell
$ python test/functional/feature_block.py --nocleanup
2019-03-15T07:01:58.892000Z TestFramework (INFO): Initializing test directory /tmp/testl94k_xro
... 略
このような出力になるのですが、ここに表示されている /tmp/textxxxxx というディレクトリに実行時に生成されたログやノードのデータファイルなどがあります。ディレクトリの構成は以下のようになっています。
code:shell
.
├── node0
│ ├── bitcoin.conf
│ ├── blocks
│ ├── regtest
│ │ ├── banlist.dat
│ │ ├── blocks
│ │ ├── chainstate
│ │ ├── debug.log ← ノードのログ
│ │ ├── fee_estimates.dat
│ │ ├── mempool.dat
│ │ ├── peers.dat
│ │ └── wallets
│ │ ├── db.log
│ │ └── wallet.dat
│ ├── stderr
│ │ └── tmp_d7s5xjr
│ └── stdout
│ └── tmph9onk619
└── test_framework.log ←テストのログ
ノードが1台で済むテストの場合はこのように node0 のディレクトリだけですが、複数使う場合は node1, node2 のようにディレクトリが生成されます。
複数のログファイルをまとめて見る
このままだとログを見るにしても各ノードのログファイルとテストのログをバラバラに見比べる必要があって読みにくいです。これらをまとめて見る方法が提供されています。
$ python test/functional/combine_logs.py -c /tmp/testewvfyeo1/ | less -R
これで、各ノード、testのログが色分けされて、時系列で並べられた状態でログを見ることができます。ノード間のやり取りの様子がとても把握しやすいです。テストコードに合わせてこのログを読むことで、ノードの挙動を把握しやすくなります。
ブレイクして調べる
より詳しく挙動を把握するために、テストの途中で RPC などを使ってノードの状態を調べたくなるかもしれません。もちろんテストコードを書き換えて実行すれば、好きな情報をログに出させることもできますが、デバッガを使う方法も有ります。
テストコードの任意の箇所に以下の行を挿入し実行することで、その場所で pdb を使ってデバッグすることができます。任意の python コードを実行しながらノードの状態を調べることができるため、知りたい情報をすぐに引き出すことができて便利です。
code:python
import pdb; pdb.set_trace()
また、実行時に--pdbonfailure オプションをつけてテストを実行することで、テストが失敗した箇所でpdbを起動することも可能です。
ノードのデバッグ
結合テストを実行しながら、ノード側の挙動をもっと詳しく知りたくなることがあるかもしれません。出力されるログだけでは判断できないもっと内部の挙動を調べたい場合です。
現状 cout を使ったいわゆる伝統的なプリントデバッグくらいしかやり方が分かっていません。gdb などでブレイクして調べれるとより便利なのですが、このあたりを上手くやるには test-framework のノード起動処理を把握する必要がありそうです。任意のタイミングでノードを止めて、guiデバッガでリモートデバッグできると最高なんですが、やり方わかる方いらっしゃたら教えていただけると嬉しいです。
以上です。