実行時エラーの悩み: どこで発生したかわからない

次のプログラムはエラーになるのですが、普通に実行しただけではどこでエラーになったかわかりません。辛いです。

rust

fn hoge() -> anyhow::Result<()> {
    buddhas_face()?;

    Ok(())
}

fn fuga() -> anyhow::Result<()> {
    buddhas_face()?;

    hoge()?;

    Ok(())
}

fn bar() -> anyhow::Result<()> {
    hoge()?;

    fuga()?;

    Ok(())
}

fn main() -> anyhow::Result<()> {
    hoge()?;

    fuga()?;

    bar()?;

    Ok(())
}

/// 4回呼ぶと怒られる関数
fn buddhas_face() -> anyhow::Result<()> {
    use std::sync::{LazyLock, Mutex};

    static CALLED_COUNT: LazyLock<Mutex<u32>> = LazyLock::new(|| Mutex::new(0));

    let mut counter = CALLED_COUNT.lock().unwrap();

    *counter += 1;

    if *counter > 3 {
        anyhow::bail!("buddhas_face called more than three times");
    }

    Ok(())
}

実行してみると buddhas_face が4回以上呼ばれ実行時エラーになります。しかしどのタイミングでエラーになったかがわからず、この情報だけでは修正は難航を極めるでしょう。

$ cargo run
   Compiling project v0.1.0 (/home/namn/workspace/qiita_adv_articles_2025/programs/anyhow_raw/project)
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.30s
     Running `target/debug/project`
Error: buddhas_face called more than three times

小さなプログラムであったとしてもこれは地味なストレスです。今回はどのタイミングでエラーになったかを調べる方法を考えてみます！

解決方法①: `RUST_BACKTRACE=1`

最もシンプルな方法は RUST_BACKTRACE=1 を付ける (環境変数 RUST_BACKTRACE を用いる) 方法でしょう。anyhow利用を問わず、Backtraceが得られるのでエラー発生行がわかります。

以下は筆者のローカル環境で実行した結果です。

$ RUST_BACKTRACE=1 cargo run
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.00s
     Running `target/debug/project`
Error: buddhas_face called more than three times

Stack backtrace:
   0: anyhow::error::<impl anyhow::Error>::msg
             at /home/namn/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.100/src/backtrace.rs:27:14
   1: anyhow::__private::format_err
             at /home/namn/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/anyhow-1.0.100/src/lib.rs:695:13
   2: project::buddhas_face
             at ./src/main.rs:44:9
   3: project::hoge
             at ./src/main.rs:2:5
   4: project::bar
             at ./src/main.rs:16:5
   5: project::main
             at ./src/main.rs:28:5
   6: core::ops::function::FnOnce::call_once
             at /home/namn/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:250:5
   7: std::sys::backtrace::__rust_begin_short_backtrace
             at /home/namn/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/backtrace.rs:158:18
   8: std::rt::lang_start::{{closure}}
             at /home/namn/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/rt.rs:206:18
   9: core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once
             at /rustc/ed61e7d7e242494fb7057f2657300d9e77bb4fcb/library/core/src/ops/function.rs:287:21
  10: std::panicking::catch_unwind::do_call
             at /rustc/ed61e7d7e242494fb7057f2657300d9e77bb4fcb/library/std/src/panicking.rs:590:40
  11: std::panicking::catch_unwind
             at /rustc/ed61e7d7e242494fb7057f2657300d9e77bb4fcb/library/std/src/panicking.rs:553:19
  12: std::panic::catch_unwind
             at /rustc/ed61e7d7e242494fb7057f2657300d9e77bb4fcb/library/std/src/panic.rs:359:14
  13: std::rt::lang_start_internal::{{closure}}
             at /rustc/ed61e7d7e242494fb7057f2657300d9e77bb4fcb/library/std/src/rt.rs:175:24
  14: std::panicking::catch_unwind::do_call
             at /rustc/ed61e7d7e242494fb7057f2657300d9e77bb4fcb/library/std/src/panicking.rs:590:40
  15: std::panicking::catch_unwind
             at /rustc/ed61e7d7e242494fb7057f2657300d9e77bb4fcb/library/std/src/panicking.rs:553:19
  16: std::panic::catch_unwind
             at /rustc/ed61e7d7e242494fb7057f2657300d9e77bb4fcb/library/std/src/panic.rs:359:14
  17: std::rt::lang_start_internal
             at /rustc/ed61e7d7e242494fb7057f2657300d9e77bb4fcb/library/std/src/rt.rs:171:5
  18: std::rt::lang_start
             at /home/namn/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/rt.rs:205:5
  19: main
  20: <unknown>
  21: __libc_start_main
  22: _start

ソースコードの該当部分を抜粋しました。

   2: project::buddhas_face
             at ./src/main.rs:44:9
   3: project::hoge
             at ./src/main.rs:2:5
   4: project::bar
             at ./src/main.rs:16:5
   5: project::main
             at ./src/main.rs:28:5

28行目 → 16行目 → 2行目 → 44行目という遷移で、 bar 関数を呼んだタイミングが4回目だったことがわかります！

しかし小さいながらもいくつか不満があります...

RUST_BACKTRACE=1 が必要であること

つけ忘れてエラーが起きた時にもう一度走らせなければならない
アプリ配布後にユーザーに利用してもらう際、特に工夫しない場合はバックトレースが得られない
非同期でわかりやすいトレースが得られないかもしれない... ¹

出力される情報が多すぎること

見た通りです。ぱっと見ではエラー発生行がわかりません。

というわけで、他にも手段がないか検討してみます！

解決方法①の2: color-eyreできれいに表示する

後者の「出力される情報が多すぎること」に関してはanyhowの代わりにcolor-eyreというクレートを用いることで解決されます！

rust

use color_eyre::eyre;

fn hoge() -> eyre::Result<()> {
    buddhas_face()?;

    Ok(())
}

fn fuga() -> eyre::Result<()> {
    buddhas_face()?;

    hoge()?;

    Ok(())
}

fn bar() -> eyre::Result<()> {
    hoge()?;

    fuga()?;

    Ok(())
}

fn main() -> eyre::Result<()> {
    color_eyre::install()?; // バックトレース出力に必要

    hoge()?;

    fuga()?;

    bar()?;

    Ok(())
}

/// 4回呼ぶと怒られる関数
fn buddhas_face() -> eyre::Result<()> {
    use std::sync::{LazyLock, Mutex};

    static CALLED_COUNT: LazyLock<Mutex<u32>> = LazyLock::new(|| Mutex::new(0));

    let mut counter = CALLED_COUNT.lock().unwrap();

    *counter += 1;

    if *counter > 3 {
        eyre::bail!("buddhas_face called more than three times");
    }

    Ok(())
}

筆者の手元での実行結果です。

$ RUST_LIB_BACKTRACE=full cargo run
   Compiling project v0.1.0 (/home/namn/workspace/qiita_adv_articles_2025/programs/color-eyre/project)
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.29s
     Running `target/debug/project`
Error: 
   0: buddhas_face called more than three times

Location:
   src/main.rs:48

  ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ BACKTRACE ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━
                                ⋮ 6 frames hidden ⋮                               
   7: project::buddhas_face::h0500e60548f7a60c
      at /home/namn/workspace/qiita_adv_articles_2025/programs/color-eyre/project/src/main.rs:48
        46 │ 
        47 │     if *counter > 3 {
        48 >         eyre::bail!("buddhas_face called more than three times");
        49 │     }
        50 │ 
   8: project::hoge::hf2ba5808e4bfe5ad
      at /home/namn/workspace/qiita_adv_articles_2025/programs/color-eyre/project/src/main.rs:4
         2 │ 
         3 │ fn hoge() -> eyre::Result<()> {
         4 >     buddhas_face()?;
         5 │ 
         6 │     Ok(())
   9: project::bar::hb0f43b64abf1bf11
      at /home/namn/workspace/qiita_adv_articles_2025/programs/color-eyre/project/src/main.rs:18
        16 │ 
        17 │ fn bar() -> eyre::Result<()> {
        18 >     hoge()?;
        19 │ 
        20 │     fuga()?;
  10: project::main::h33fdf4be197c9e8b
      at /home/namn/workspace/qiita_adv_articles_2025/programs/color-eyre/project/src/main.rs:32
        30 │     fuga()?;
        31 │ 
        32 >     bar()?;
        33 │ 
        34 │     Ok(())
  11: core::ops::function::FnOnce::call_once::h6a3f6cda2169809d
      at /home/namn/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:250
       248 │     /// Performs the call operation.
       249 │     #[unstable(feature = "fn_traits", issue = "29625")]
       250 >     extern "rust-call" fn call_once(self, args: Args) -> Self::Output;
       251 │ }
       252 │ 
  12: std::sys::backtrace::__rust_begin_short_backtrace::h70f5fbbe40f8e036
      at /home/namn/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/backtrace.rs:158
       156 │     F: FnOnce() -> T,
       157 │ {
       158 >     let result = f();
       159 │ 
       160 │     // prevent this frame from being tail-call optimised away
                                ⋮ 14 frames hidden ⋮                              

Run with COLORBT_SHOW_HIDDEN=1 environment variable to disable frame filtering.

出力される文字数的な意味ではあまり変わらないかもしれませんが、素のBacktraceと比べると余計な情報が落ち、かなり読みやすいバックトレースが得られました！

解決方法②: `anyhow::Context::with_context` を使う

RUST_BACKTRACE=1 を付けなくてもエラー発生行を得たい場合、anyhow::Context::with_context²を利用したゴリ押しの方法があります！

その方法とは、すべての ? の前に with_context メソッドを挿入し、そこで line!() マクロを呼ぶものです！ line!() マクロはこのマクロが記述された行数に置き換わります。

rust

use anyhow::Context as _;

fn hoge() -> anyhow::Result<()> {
    buddhas_face().with_context(|| line!())?;

    Ok(())
}

fn fuga() -> anyhow::Result<()> {
    buddhas_face().with_context(|| line!())?;

    hoge().with_context(|| line!())?;

    Ok(())
}

fn bar() -> anyhow::Result<()> {
    hoge().with_context(|| line!())?;

    fuga().with_context(|| line!())?;

    Ok(())
}

fn main() -> anyhow::Result<()> {
    hoge().with_context(|| line!())?;

    fuga().with_context(|| line!())?;

    bar().with_context(|| line!())?;

    Ok(())
}

/// 4回呼ぶと怒られる関数
fn buddhas_face() -> anyhow::Result<()> {
    use std::sync::{LazyLock, Mutex};

    static CALLED_COUNT: LazyLock<Mutex<u32>> = LazyLock::new(|| Mutex::new(0));

    let mut counter = CALLED_COUNT.lock().unwrap();

    *counter += 1;

    if *counter > 3 {
        anyhow::bail!("buddhas_face called more than three times");
    }

    Ok(())
}

anyhow::Context::with_context メソッドを呼ぶと、コンテキストがスタックされていきます。この性質により、実行してみると以下のようにバックトレースもどきが得られます！

$ cargo run
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.00s
     Running `target/debug/project`
Error: 30

Caused by:
    0: 18
    1: 4
    2: buddhas_face called more than three times

発生したエラー行数さえわかればデバッグできるので、あながちアリな選択肢ではないでしょうか...？非同期かどうかに関係なくほしい情報が得られるというメリットもあります！

Rustで小さなCLIツールを作る際、筆者がよく取る方法です。

解決方法②の2: hooqを使う

とはいえ全部の ? の前に .with_context(|| line!()) を書くのはいささか可読性が悪化しますね？

そこで筆者が発明したのがhooqマクロです！ #[hooq(anyhow)] を各関数の頭につけると、各 ? と式の間に .with_context(|| ...) が挿入されます。

rust

use hooq::hooq;

#[hooq(anyhow)]
fn hoge() -> anyhow::Result<()> {
    buddhas_face()?;

    Ok(())
}

#[hooq(anyhow)]
fn fuga() -> anyhow::Result<()> {
    buddhas_face()?;

    hoge()?;

    Ok(())
}

#[hooq(anyhow)]
fn bar() -> anyhow::Result<()> {
    hoge()?;

    fuga()?;

    Ok(())
}

#[hooq(anyhow)]
fn main() -> anyhow::Result<()> {
    hoge()?;

    fuga()?;

    bar()?;

    Ok(())
}

/// 4回呼ぶと怒られる関数
#[hooq(anyhow)]
fn buddhas_face() -> anyhow::Result<()> {
    use std::sync::{LazyLock, Mutex};

    static CALLED_COUNT: LazyLock<Mutex<u32>> = LazyLock::new(|| Mutex::new(0));

    let mut counter = CALLED_COUNT.lock().unwrap();

    *counter += 1;

    if *counter > 3 {
        // hooqを使う場合は bail! ではなくこちらの方が都合が良いです
        return Err(anyhow::anyhow!("buddhas_face called more than three times"));
    }

    Ok(())
}

cargo expandした様子

rust

#![feature(prelude_import)]
#[macro_use]
extern crate std;
#[prelude_import]
use std::prelude::rust_2024::*;
use hooq::hooq;
#[allow(unused)]
use ::anyhow::Context as _;
fn hoge() -> anyhow::Result<()> {
    buddhas_face()
        .with_context(|| {
            let path = "src/main.rs";
            let line = 5usize;
            let col = 19usize;
            let expr = "   5>    buddhas_face()?\n    |";
            ::alloc::__export::must_use({
                ::alloc::fmt::format(
                    format_args!("[{0}:{1}:{2}]\n{3}", path, line, col, expr),
                )
            })
        })?;
    Ok(())
}
#[allow(unused)]
use ::anyhow::Context as _;
fn fuga() -> anyhow::Result<()> {
    buddhas_face()
        .with_context(|| {
            let path = "src/main.rs";
            let line = 12usize;
            let col = 19usize;
            let expr = "  12>    buddhas_face()?\n    |";
            ::alloc::__export::must_use({
                ::alloc::fmt::format(
                    format_args!("[{0}:{1}:{2}]\n{3}", path, line, col, expr),
                )
            })
        })?;
    hoge()
        .with_context(|| {
            let path = "src/main.rs";
            let line = 14usize;
            let col = 11usize;
            let expr = "  14>    hoge()?\n    |";
            ::alloc::__export::must_use({
                ::alloc::fmt::format(
                    format_args!("[{0}:{1}:{2}]\n{3}", path, line, col, expr),
                )
            })
        })?;
    Ok(())
}
#[allow(unused)]
use ::anyhow::Context as _;
fn bar() -> anyhow::Result<()> {
    hoge()
        .with_context(|| {
            let path = "src/main.rs";
            let line = 21usize;
            let col = 11usize;
            let expr = "  21>    hoge()?\n    |";
            ::alloc::__export::must_use({
                ::alloc::fmt::format(
                    format_args!("[{0}:{1}:{2}]\n{3}", path, line, col, expr),
                )
            })
        })?;
    fuga()
        .with_context(|| {
            let path = "src/main.rs";
            let line = 23usize;
            let col = 11usize;
            let expr = "  23>    fuga()?\n    |";
            ::alloc::__export::must_use({
                ::alloc::fmt::format(
                    format_args!("[{0}:{1}:{2}]\n{3}", path, line, col, expr),
                )
            })
        })?;
    Ok(())
}
#[allow(unused)]
use ::anyhow::Context as _;
fn main() -> anyhow::Result<()> {
    hoge()
        .with_context(|| {
            let path = "src/main.rs";
            let line = 30usize;
            let col = 11usize;
            let expr = "  30>    hoge()?\n    |";
            ::alloc::__export::must_use({
                ::alloc::fmt::format(
                    format_args!("[{0}:{1}:{2}]\n{3}", path, line, col, expr),
                )
            })
        })?;
    fuga()
        .with_context(|| {
            let path = "src/main.rs";
            let line = 32usize;
            let col = 11usize;
            let expr = "  32>    fuga()?\n    |";
            ::alloc::__export::must_use({
                ::alloc::fmt::format(
                    format_args!("[{0}:{1}:{2}]\n{3}", path, line, col, expr),
                )
            })
        })?;
    bar()
        .with_context(|| {
            let path = "src/main.rs";
            let line = 34usize;
            let col = 10usize;
            let expr = "  34>    bar()?\n    |";
            ::alloc::__export::must_use({
                ::alloc::fmt::format(
                    format_args!("[{0}:{1}:{2}]\n{3}", path, line, col, expr),
                )
            })
        })?;
    Ok(())
}
#[allow(unused)]
use ::anyhow::Context as _;
/// 4回呼ぶと怒られる関数
fn buddhas_face() -> anyhow::Result<()> {
    use std::sync::{LazyLock, Mutex};
    static CALLED_COUNT: LazyLock<Mutex<u32>> = LazyLock::new(|| Mutex::new(0));
    let mut counter = CALLED_COUNT.lock().unwrap();
    *counter += 1;
    if *counter > 3 {
        return Err(
                ::anyhow::__private::must_use({
                    let error = ::anyhow::__private::format_err(
                        format_args!("buddhas_face called more than three times"),
                    );
                    error
                }),
            )
            .with_context(|| {
                let path = "src/main.rs";
                let line = 52usize;
                let col = 9usize;
                let expr = "  52>    return Err(anyhow::anyhow!(\"buddhas_face called more than three times\"))\n    |";
                ::alloc::__export::must_use({
                    ::alloc::fmt::format(
                        format_args!("[{0}:{1}:{2}]\n{3}", path, line, col, expr),
                    )
                })
            });
    }
    Ok(())
}

実行結果は次のとおりになります。

$ cargo run
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.01s
     Running `target/debug/project`
Error: [src/main.rs:34:10]
  34>    bar()?
    |

Caused by:
    0: [src/main.rs:21:11]
         21>    hoge()?
           |
    1: [src/main.rs:5:19]
          5>    buddhas_face()?
           |
    2: [src/main.rs:52:9]
         52>    return Err(anyhow::anyhow!("buddhas_face called more than three times"))
           |
    3: buddhas_face called more than three times

RUST_BACKTRACE=1 を使わない手段の中では、バックトレースもどきを最も楽に取得できる方法だと思います！

まとめ

実行時エラー発生時に、バックトレース的なものを得る手段をいくつか紹介しました！

RUST_BACKTRACE=1 の方法を一番上に掲載したものの、うまく言語化できない悩みがあり、筆者はかなり長い期間解決方法②の .with_context(|| ...) を多用してきました。それがhooqマクロを作ろうと思ったきっかけだったりします。

本記事の内容がRustの実行時エラーデバッグの一助になれば幸いです、ここまで読んでいただきありがとうございました！

試してみたのですが今回みたいなシンプルな例だと特に問題はなかったので本記事においては根拠なき難癖です。とはいえ実際不便な場合もあると考えられるので(そうでなければ tracing クレートは要らない...は言い過ぎ？)、別な記事で難しい例を考えてみたいですね。 ↩
.context(...) ではなく .with_context(|| ...) を利用している理由ですが、後者の方は遅延評価されるため、 format!() マクロなどでヒープ確保文字列などを生成させる場合などに若干パフォーマンスが良いためです。 line!() マクロしか記述しない場合は大差ないかもしれません。 ↩