macOS版のRustでpanic時のスタックトレースに行番号を出す
macの環境でrustのプログラムを実行してpanicしたときに、スタックトレースを見てもどこでおちたのかわからなかったので、調べてみました。
試したバージョン
- macos
% cargo --version
cargo-0.18.0-nightly (fdfdb5f 2017-02-16)
- linux
% docker run --rm -v $(pwd):/source jimmycuadra/rust cargo --version
cargo 0.16.0-nightly (6e0c18c 2017-01-27)
panic時にどこで落ちたか分からない？？
例えば下記のようなプログラムがあったとします。
01: fn main() {
02: let test: Option<i32> = None;
03:
04: println!("xxx");
05: println!("yyy");
06: println!("test is {}", test.unwrap());
07: println!("zzz");
08: }
変数testがNoneなので、6行目のunwrap()でpanicするのですが、 macOS版のcargo runでRUST_BACKTRACE=1をつけて実行すると下記のようになります。
% RUST_BACKTRACE=1 cargo run
Finished dev [unoptimized + debuginfo] target(s) in 0.0 secs
Running `target/debug/rust-better-stacktrace`
xxx
yyy
thread 'main' panicked at 'called `Option::unwrap()` on a `None` value', src/libcore/option.rs:323
stack backtrace:
1: 0x10dbefd59 - std::sys::imp::backtrace::tracing::imp::write::h9559bd7cb15d72ad
2: 0x10dbf122e - std::panicking::default_hook::{{closure}}::h4b3f2b69c9ce844d
3: 0x10dbf0edb - std::panicking::default_hook::h61d415f2381a7336
4: 0x10dbf15e7 - std::panicking::rust_panic_with_hook::h8e6300d8e8aca457
5: 0x10dbf1484 - std::panicking::begin_panic::h08622fbe5a379aac
6: 0x10dbf13f2 - std::panicking::begin_panic_fmt::ha00d3aa9db91f578
7: 0x10dbf1357 - rust_begin_unwind
8: 0x10dc11a20 - core::panicking::panic_fmt::h58d018e87f211baf
9: 0x10dc11924 - core::panicking::panic::h4e2dc358c3b23d48
10: 0x10dbe9634 - <core::option::Option<T>>::unwrap::hd19ecad304e85b2f
11: 0x10dbe9808 - rust_better_stacktrace::main::hd6e610e90450cf55
12: 0x10dbf305a - __rust_maybe_catch_panic
13: 0x10dbf18a6 - std::rt::lang_start::he28fbf70e98a2b18
14: 0x10dbe98f9 - main
11行目にrust_better_stacktrace::main::hd6e610e90450cf55があるので、関数mainの中で起きたことは分かっても具体的に、どのファイルの、どの行なのかわかりませんね。
で、調べてみると、本家のissueに
Backtrace does not include file and line number on non-Linux platforms #24346
というのが立っていまして、linux以外のOSでは現状スタックトレースにファイル名と行番号がでないとのこと。(https://github.com/rust-lang/rust/issues/24346#issuecomment-170711555)
試しにlinux環境のrustで試してみると下記のようにとてもわかり易くバックトレースが出ます。
% RUST_BACKTRACE=1 cargo run
Finished debug [unoptimized + debuginfo] target(s) in 0.0 secs
Running `target/debug/rust-better-stacktrace`
xxx
yyy
thread 'main' panicked at 'called `Option::unwrap()` on a `None` value', /buildslave/rust-buildbot/slave/stable-dist-rustc-linux/build/src/libcore/option.rs:323
stack backtrace:
linux/build/src/libcore/macros.rs:21
--- 長いので省略 ---
11: 0x556838c49beb - rust_better_stacktrace::main::hfdf401c58b6d709f
at /source/src/main.rs:6
--- 長いので省略 ---
main.rsの6行目で発生したのがぱっと分かっていいですね。
macでもなんとかファイルと行番号を知る
じゃ、macでは無理なのかと思っていましたが、上記のissueでデバッガー(lldb)で実行すれば分かる、というコメントがありました。
どうもpanicのときに実行されるrust_begin_unwindにブレイクポイントを貼っておいて、そこまでのバックトレースをデバッガで見る、ということのようでした。試してみます。
# デバッグビルドの方の実行ファイルでlldbを起動
% lldb target/debug/rust-better-stacktrace
# 以下lldbのプロンプト
# rust_begin_unwindにブレイクポイントを貼ります。
(lldb) b rust_begin_unwind
Breakpoint 1: where = rust-better-stacktrace`std::panicking::rust_begin_panic + 4 at panicking.rs:464, address = 0x0000000100009324
# で、実行
(lldb) run
# すると想定通りブレイクポイントで止まります
Process 48841 launched: '/Users/pocari/dev/tmp/20170221/rust-better-stacktrace/rust-better-stacktrace/target/debug/rust-better-stacktrace' (x86_64)
xxx
yyy
rust-better-stacktrace was compiled with optimization - stepping may behave oddly; variables may not be available.
Process 48841 stopped
* thread #1: tid = 0x9be70, 0x0000000100009324 rust-better-stacktrace`std::panicking::rust_begin_panic + 4 at panicking.rs:464, queue = 'com.apple.main-thread', stop reason = breakpoint 1.1
frame #0: 0x0000000100009324 rust-better-stacktrace`std::panicking::rust_begin_panic + 4 at panicking.rs:464 [opt]
で、ここでbtでバックトレースを表示させます。
(lldb) bt
* thread #1: tid = 0x9be70, 0x0000000100009324 rust-better-stacktrace`std::panicking::rust_begin_panic + 4 at panicking.rs:464, queue = 'com.apple.main-thread', stop reason = b
* frame #0: 0x0000000100009324 rust-better-stacktrace`std::panicking::rust_begin_panic + 4 at panicking.rs:464 [opt]
frame #1: 0x0000000100029a21 rust-better-stacktrace`core::panicking::panic_fmt + 129 at panicking.rs:69 [opt]
frame #2: 0x0000000100029925 rust-better-stacktrace`core::panicking::panic + 101 at panicking.rs:49 [opt]
frame #3: 0x0000000100001635 rust-better-stacktrace`core::option::{{impl}}::unwrap<i32>(self=Option<i32> @ 0x00007fff5fbff020) + 85 at macros.rs:21
frame #4: 0x0000000100001809 rust-better-stacktrace`rust_better_stacktrace::main + 169 at main.rs:6
frame #5: 0x000000010000b05b rust-better-stacktrace`panic_unwind::__rust_maybe_catch_panic + 27 at lib.rs:98 [opt]
frame #6: 0x00000001000098a7 rust-better-stacktrace`std::rt::lang_start [inlined] std::panicking::try<(),fn()> + 44 at panicking.rs:429 [opt]
frame #7: 0x000000010000987b rust-better-stacktrace`std::rt::lang_start [inlined] std::panic::catch_unwind<fn(),()> at panic.rs:361 [opt]
frame #8: 0x000000010000987b rust-better-stacktrace`std::rt::lang_start + 347 at rt.rs:57 [opt]
frame #9: 0x00000001000018fa rust-better-stacktrace`main + 42
frame #10: 0x00007fff8b64e5ad libdyld.dylib`start + 1
するとframe #4のフレーム情報から
frame #4: 0x0000000100001809 rust-better-stacktrace`rust_better_stacktrace::main + 169 at main.rs:6
main.rsの6行目という情報が見えますね！
まとめ
macでもファイル名と行番号を見ようと思えば見られるようですが、やっぱ面倒ですよね。
最近結構頻繁に目にするようになってきたRustですが、そのうちlinux以外のOSでもこの辺整備されてくれるといいなーと思います。
