rune
rune copied to clipboard
Published
20 hours ago •
rune-rs
rune-rs
Panic when formatting Value outside of virtual machines
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
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:?}")
}
}
}
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.
It is convenient for
Valueto implementfmt::Debug, but maybe it shouldn't returnfmt::Errorand 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 withVm::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.