Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Panic when formatting Value outside of virtual machines #747

Open
VorpalBlade opened this issue Jul 16, 2024 · 5 comments
Open

Panic when formatting Value outside of virtual machines #747

VorpalBlade opened this issue Jul 16, 2024 · 5 comments
Labels
bug Something isn't working

Comments

@VorpalBlade
Copy link
Contributor

VorpalBlade commented Jul 16, 2024

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 VorpalBlade changed the title Panic while formatting anyhow Result wrapped in rune Value Panic in rune-internal tracing logging while formatting anyhow Result wrapped in rune Value Jul 16, 2024
@VorpalBlade
Copy link
Contributor Author

VorpalBlade commented Jul 16, 2024

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
Copy link
Collaborator

udoprog commented Jul 16, 2024

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.

@udoprog udoprog added the bug Something isn't working label Jul 16, 2024
@VorpalBlade
Copy link
Contributor Author

VorpalBlade commented Jul 16, 2024

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
Copy link
Collaborator

udoprog commented Jul 16, 2024

Yeah, we should fix it.

@VorpalBlade
Copy link
Contributor Author

I'll make a PR later today

VorpalBlade added a commit to VorpalBlade/rune that referenced this issue Jul 17, 2024
This ensures that we don't get an error on formatting a value without a debug protocol.

(fixes rune-rs#747)
udoprog pushed a commit that referenced this issue Jul 17, 2024
This ensures that we don't get an error on formatting a value without a debug protocol.

Instead attempt to print *something*

(fixes #747)
@udoprog udoprog changed the title Panic in rune-internal tracing logging while formatting anyhow Result wrapped in rune Value Panic when formatting Value outside of virtual machines Nov 1, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

2 participants