Panic when formatting Value outside of virtual machines

[VorpalBlade]

Given the following example code (full reproducer project attached as tar.gz below):

reproduce

use std::sync::Arc;

use anyhow::Context;
use rune::{
    termcolor::{ColorChoice, StandardStream},
    ContextError, Diagnostics, Module, Source, Sources, Vm,
};

/// Simple rune extension function that returns anhow error
#[rune::function]
fn hello() -> anyhow::Result<()> {
    Err(anyhow::anyhow!("AIEEEEE")).context("Blah")?;
    Ok(())
}

// Module
#[rune::module(::dummy)]
pub(crate) fn module() -> Result<Module, ContextError> {
    let mut m = Module::from_meta(self::module_meta)?;
    m.function_meta(hello)?;
    Ok(m)
}

#[tokio::main(flavor = "current_thread")]
async fn main() -> anyhow::Result<()> {
    // Set up logging with tracing
    let filter = tracing_subscriber::EnvFilter::builder()
        .with_default_directive(tracing::level_filters::LevelFilter::INFO.into())
        .from_env()?;
    let subscriber = tracing_subscriber::fmt::Subscriber::builder()
        .with_env_filter(filter)
        .finish();
    tracing::subscriber::set_global_default(subscriber)?;

    // Create rune context
    let mut context = rune::Context::default();
    context.install(module()?)?;

    let runtime = Arc::new(context.runtime()?);

    // Load example code
    let code = r#"
    pub fn main() {
        ::dummy::hello()?;
    }"#;
    let mut sources = Sources::new();
    sources.insert(Source::memory(code)?)?;

    // Diagnostics
    let mut diagnostics = Diagnostics::new();

    let result = rune::prepare(&mut sources)
        .with_context(&context)
        .with_diagnostics(&mut diagnostics)
        .build();

    if !diagnostics.is_empty() {
        let mut writer = StandardStream::stderr(ColorChoice::Always);
        diagnostics.emit(&mut writer, &sources)?;
    }
    let unit = result?;
    let mut vm = Vm::new(runtime, Arc::new(unit));

    // Do an async call
    let vm_result = vm.async_call(["main"], ()).await;

    // Print VM-result:
    dbg!(&vm_result);
    Ok(())
}

we get the following panic while running it

[tracing-subscriber] Unable to format the following event, ignoring: Attributes { metadata: Metadata { name: "op_return_internal", target: "rune::runtime::vm", level: Level(Info), module_path: "rune::runtime::vm", location: /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rune-0.13.3/src/runtime/vm.rs:2061, fields: {return_value, clean}, callsite: Identifier(0x5801307286a0), kind: Kind(SPAN) }, values: ValueSet { return_value: Err(thread 'main' panicked at library/std/src/io/stdio.rs:1118:9:
failed printing to stderr: formatter error
stack backtrace:
   0: rust_begin_unwind
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/panicking.rs:652:5
   1: core::panicking::panic_fmt
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/panicking.rs:72:14
   2: std::io::stdio::print_to
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/io/stdio.rs:1118:9
   3: std::io::stdio::_eprint
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/io/stdio.rs:1205:5
   4: <tracing_subscriber::fmt::fmt_layer::Layer<S,N,E,W> as tracing_subscriber::layer::Layer<S>>::on_new_span
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/fmt/fmt_layer.rs:825:17
   5: <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::new_span
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/layer/layered.rs:127:9
   6: <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::new_span
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/layer/layered.rs:126:18
   7: <tracing_subscriber::fmt::Subscriber<N,E,F,W> as tracing_core::subscriber::Subscriber>::new_span
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-subscriber-0.3.18/src/fmt/mod.rs:388:9
   8: tracing_core::dispatcher::Dispatch::new_span
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-core-0.1.32/src/dispatcher.rs:561:9
   9: tracing::span::Span::make_with
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/span.rs:569:18
  10: tracing::span::Span::new_with
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/span.rs:448:9
  11: tracing::span::Span::new::{{closure}}
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/span.rs:437:44
  12: tracing_core::dispatcher::get_default
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-core-0.1.32/src/dispatcher.rs:391:16
  13: tracing::span::Span::new
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.40/src/span.rs:437:9
  14: rune::runtime::vm::Vm::op_return_internal
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rune-0.13.3/src/runtime/vm.rs:2061:5
  15: rune::runtime::vm::Vm::op_try
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rune-0.13.3/src/runtime/vm.rs:2554:38
  16: rune::runtime::vm::Vm::run
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rune-0.13.3/src/runtime/vm.rs:3244:32
  17: rune::runtime::vm_execution::VmExecution<T>::inner_async_resume::{{closure}}
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rune-0.13.3/src/runtime/vm_execution.rs:213:27
  18: rune::runtime::vm_execution::VmExecution<T>::async_resume::{{closure}}
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rune-0.13.3/src/runtime/vm_execution.rs:206:35
  19: rune::runtime::vm_execution::VmExecution<T>::async_complete::{{closure}}
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rune-0.13.3/src/runtime/vm_execution.rs:160:43
  20: rune::runtime::vm::Vm::async_call::{{closure}}
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/rune-0.13.3/src/runtime/vm.rs:447:18
  21: dummy::main::{{closure}}
             at ./src/main.rs:65:49
  22: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/future/future.rs:123:9
  23: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::{{closure}}::{{closure}}
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/scheduler/current_thread/mod.rs:659:57
  24: tokio::runtime::coop::with_budget
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/coop.rs:107:5
  25: tokio::runtime::coop::budget
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/coop.rs:73:5
  26: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::{{closure}}
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/scheduler/current_thread/mod.rs:659:25
  27: tokio::runtime::scheduler::current_thread::Context::enter
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/scheduler/current_thread/mod.rs:404:19
  28: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/scheduler/current_thread/mod.rs:658:36
  29: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/scheduler/current_thread/mod.rs:737:68
  30: tokio::runtime::context::scoped::Scoped<T>::set
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/context/scoped.rs:40:9
  31: tokio::runtime::context::set_scheduler::{{closure}}
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/context.rs:180:26
  32: std::thread::local::LocalKey<T>::try_with
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/thread/local.rs:286:12
  33: std::thread::local::LocalKey<T>::with
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/std/src/thread/local.rs:262:9
  34: tokio::runtime::context::set_scheduler
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/context.rs:180:9
  35: tokio::runtime::scheduler::current_thread::CoreGuard::enter
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/scheduler/current_thread/mod.rs:737:27
  36: tokio::runtime::scheduler::current_thread::CoreGuard::block_on
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/scheduler/current_thread/mod.rs:646:19
  37: tokio::runtime::scheduler::current_thread::CurrentThread::block_on::{{closure}}
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/scheduler/current_thread/mod.rs:175:28
  38: tokio::runtime::context::runtime::enter_runtime
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/context/runtime.rs:65:16
  39: tokio::runtime::scheduler::current_thread::CurrentThread::block_on
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/scheduler/current_thread/mod.rs:167:9
  40: tokio::runtime::runtime::Runtime::block_on
             at /home/arvid/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.38.1/src/runtime/runtime.rs:347:47
  41: dummy::main
             at ./src/main.rs:69:5
  42: core::ops::function::FnOnce::call_once
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library/core/src/ops/function.rs:250:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

Example project triggering this: rune_fmt_panic.tar.gz

[VorpalBlade]

Before I switched from log to tracing for my project I would get this when attempting to unwrap the returned result in my user code. I came up with this monstrosity as a workaround. But this doesn't help now that it crashes internally in tracing.

/// Attempt to format the error in the best way possible.
///
/// Unfortunately this is awkward with dynamic Rune values.
fn try_format_error(phase: Phase, e: &rune::Value) -> anyhow::Result<()> {
    match e.clone().into_any() {
        rune::runtime::VmResult::Ok(any) => {
            match any.clone().downcast_into_ref::<anyhow::Error>() {
                Ok(err) => {
                    anyhow::bail!("Got error result from {phase}: {:?}", *err);
                }
                Err(err) => {
                    let ty = try_get_type_info(e, "error");
                    anyhow::bail!(
                        "Got error result from {phase}, but it was not an anyhow error: {err:?}, type info: {ty}: {any:?}",
                    );
                }
            }
        }
        rune::runtime::VmResult::Err(not_any) => {
            tracing::error!("Got error result from {phase}, it was not an Any: {not_any:?}. Trying other approches at printing the error.");
        }
    }
    // Attempt to format the error
    let formatted = catch_unwind(AssertUnwindSafe(|| {
        format!("Got error result from {phase}: {e:?}")
    }));
    match formatted {
        Ok(str) => anyhow::bail!(str),
        Err(_) => {
            let ty = try_get_type_info(e, "error");
            anyhow::bail!(
                "Got error result from {phase}, but got a panic while attempting to format said error for printing, {ty}",
            );
        }
    }
}

/// Best effort attempt at gettint the type info and printing it
fn try_get_type_info(e: &rune::Value, what: &str) -> String {
    match e.type_info() {
        rune::runtime::VmResult::Ok(ty) => format!("type info for {what}: {ty:?}"),
        rune::runtime::VmResult::Err(err) => {
            format!("failed getting type info for {what}: {err:?}")
        }
    }
}

[udoprog]

Well, Value returns fmt::Error if debug printing errors. For non-builtin values, this would be the case if it's called outside of a vm.

For some reason we've also opted to instrument the return value here. This is not correct and should be removed since formatting might fail.

It is convenient for Value to implement fmt::Debug, but maybe it shouldn't return fmt::Error and instead debug print the errors that occurred to avoid issues like these. It's also a footgun since it definitely will not work unless called inside a vm externally with Vm::with.

[VorpalBlade]

It is convenient for Value to implement fmt::Debug, but maybe it shouldn't return fmt::Error and instead debug print the errors that occurred to avoid issues like these. It's also a footgun since it definitely will not work unless called inside a vm externally with Vm::with.

My understanding is that std::fmt::Error is for when the formatting itself fails. And the Rust standard library will in fact panic in format!() when this happen.

So if I understand you correctly and it error when printing an error (as opposed when to the formatting fails) this seems incorrect and like a misunderstanding.

[udoprog]

Yeah, we should fix it.

[VorpalBlade]

I'll make a PR later today