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

Improve the readability of stack traces #1458

Open
leighmcculloch opened this issue Sep 12, 2024 · 1 comment
Open

Improve the readability of stack traces #1458

leighmcculloch opened this issue Sep 12, 2024 · 1 comment

Comments

@leighmcculloch
Copy link
Member

I think we should improve the readability of the diagnostic event and stack trace outputs that the environment generates on the console and in tests when there are failures.

This is not about improving the contents / data within the diagnostic events, and only the presentation of the existing data, so it is easier to glance and digest.

An example of the existing output as of v21.2.1:

thread 'test::test_sample_policy_call_self' panicked at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-env-host-21.2.1/src/host.rs:768:9:
HostError: Error(Auth, InvalidAction)

Event log (newest first):
   0: [Diagnostic Event] topics:[error, Error(Auth, InvalidAction)], data:"escalating error to panic"
   1: [Diagnostic Event] topics:[error, Error(Auth, InvalidAction)], data:["contract call failed", add, [[Policy, [CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAFCT4], [Temporary], [Admin]]]]
   2: [Failed Diagnostic Event (not emitted)] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAD2KM, topics:[error, Error(Auth, InvalidAction)], data:"caught error from function"
   3: [Failed Diagnostic Event (not emitted)] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAD2KM, topics:[error, Error(Auth, InvalidAction)], data:"escalating error to panic"
   4: [Failed Diagnostic Event (not emitted)] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAD2KM, topics:[error, Error(Auth, InvalidAction)], data:["Unauthorized function call for address", CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAD2KM]
   5: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000001), add], data:[Policy, [CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAFCT4], [Temporary], [Admin]]
   6: [Diagnostic Event] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAD2KM, topics:[fn_return, add], data:Void
   7: [Contract Event] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAD2KM, topics:[sw_v1, add, [Ed25519, [Bytes(a1738d72617d88f775693c9b9033d8bbb99d127ea9ac0f04940dd090350c5b4e)]]], data:[Ed25519, [Admin]]
   8: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000001), add], data:[Ed25519, [Bytes(a1738d72617d88f775693c9b9033d8bbb99d127ea9ac0f04940dd090350c5b4e)], [Persistent], [Admin]]
   9: [Diagnostic Event] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAD2KM, topics:[fn_return, add], data:Void
   10: [Contract Event] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAD2KM, topics:[sw_v1, add, [Secp256r1, [Bytes(f3f8d84ae2da5566c4a70e977c2a49888a66bb8c)]]], data:[Secp256r1, [Bytes(04a38ef5f2713768bd3480eeceaec2b10464a1f3b1ff0a3539c2cd2dd00a83a75d2c7b7e5fdbcfe6af5a602979c57fb44aeca0003cb9d3ae85d7c8d0e633d25ed6)], [Admin]]
   11: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000001), add], data:[Secp256r1, [Bytes(f3f8d84ae2da5566c4a70e977c2a49888a66bb8c)], [Bytes(04a38ef5f2713768bd3480eeceaec2b10464a1f3b1ff0a3539c2cd2dd00a83a75d2c7b7e5fdbcfe6af5a602979c57fb44aeca0003cb9d3ae85d7c8d0e633d25ed6)], [Persistent], [Admin]]

Backtrace (newest first):
   0: backtrace::backtrace::libunwind::trace
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/backtrace-0.3.69/src/backtrace/libunwind.rs:93:5
      backtrace::backtrace::trace_unsynchronized
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/backtrace-0.3.69/src/backtrace/mod.rs:66:5
   1: backtrace::backtrace::trace
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/backtrace-0.3.69/src/backtrace/mod.rs:53:14
   2: backtrace::capture::Backtrace::create
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/backtrace-0.3.69/src/capture.rs:176:9
   3: backtrace::capture::Backtrace::new_unresolved
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/backtrace-0.3.69/src/capture.rs:170:9
   4: soroban_env_host::host::error::<impl soroban_env_host::host::Host>::maybe_get_debug_info::{{closure}}
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-env-host-21.2.1/src/host/error.rs:293:37
   5: soroban_env_host::budget::Budget::with_shadow_mode
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-env-host-21.2.1/src/budget.rs:972:21
   6: soroban_env_host::host::Host::with_debug_mode
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-env-host-21.2.1/src/host.rs:615:24
   7: soroban_env_host::host::error::<impl soroban_env_host::host::Host>::maybe_get_debug_info
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-env-host-21.2.1/src/host/error.rs:290:13
   8: soroban_env_host::host::error::<impl soroban_env_host::host::Host>::error::{{closure}}
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-env-host-21.2.1/src/host/error.rs:274:23
   9: soroban_env_host::budget::Budget::with_shadow_mode
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-env-host-21.2.1/src/budget.rs:972:21
  10: soroban_env_host::host::Host::with_debug_mode
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-env-host-21.2.1/src/host.rs:615:24
  11: soroban_env_host::host::error::<impl soroban_env_host::host::Host>::error
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-env-host-21.2.1/src/host/error.rs:261:9
  12: <soroban_env_host::host::Host as soroban_env_common::env::EnvBase>::escalate_error_to_panic
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-env-host-21.2.1/src/host.rs:767:26
  13: soroban_sdk::env::internal::reject_err::{{closure}}
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-sdk-21.7.0/src/env.rs:52:23
  14: core::result::Result<T,E>::map_err
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/result.rs:854:27
  15: soroban_sdk::env::internal::reject_err
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-sdk-21.7.0/src/env.rs:52:9
  16: <soroban_sdk::env::Env as soroban_env_common::env::Env>::call
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-sdk-21.7.0/src/env.rs:1667:13
  17: soroban_sdk::env::Env::invoke_contract
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-sdk-21.7.0/src/env.rs:379:18
  18: webauthn_wallet::ContractClient::add
             at src/lib.rs:28:1
  19: webauthn_wallet::test::test_sample_policy_call_self
             at src/test.rs:128:5
  20: webauthn_wallet::test::test_sample_policy_call_self::{{closure}}
             at src/test.rs:30:34
  21: core::ops::function::FnOnce::call_once
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/ops/function.rs:250:5


stack backtrace:
   0: rust_begin_unwind
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:665:5
   1: core::panicking::panic_fmt
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panicking.rs:74:14
   2: <soroban_env_host::host::Host as soroban_env_common::env::EnvBase>::escalate_error_to_panic
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-env-host-21.2.1/src/host.rs:768:9
   3: soroban_sdk::env::internal::reject_err::{{closure}}
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-sdk-21.7.0/src/env.rs:52:23
   4: core::result::Result<T,E>::map_err
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/result.rs:854:27
   5: soroban_sdk::env::internal::reject_err
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-sdk-21.7.0/src/env.rs:52:9
   6: <soroban_sdk::env::Env as soroban_env_common::env::Env>::call
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-sdk-21.7.0/src/env.rs:1667:13
   7: soroban_sdk::env::Env::invoke_contract
             at /Users/tylervanderhoeven/.cargo/registry/src/index.crates.io-6f17d22bba15001f/soroban-sdk-21.7.0/src/env.rs:379:18
   8: webauthn_wallet::ContractClient::add
             at ./src/lib.rs:28:1
   9: webauthn_wallet::test::test_sample_policy_call_self
             at ./src/test.rs:128:5
  10: webauthn_wallet::test::test_sample_policy_call_self::{{closure}}
             at ./src/test.rs:30:34
  11: core::ops::function::FnOnce::call_once
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/ops/function.rs:250:5
  12: core::ops::function::FnOnce::call_once
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/ops/function.rs:250:5
@leighmcculloch
Copy link
Member Author

leighmcculloch commented Sep 12, 2024

Some examples of panic outputs in different environments for inspiration are below. They use very simple inputs, so their utility may be limited, but maybe we can learn something from them. I also understand that the diagnostic events are not stack traces, and they don't point to code, but developers sort of treat them as similar, as a way to understand where the program was when something went wrong.

Rust
fn main() {
	f1(1)
}

fn f1(i: u32) {
	f2()
}

fn f2() {
	f3()
}

fn f3() {
	panic!("oh no")
}
thread 'main' panicked at src/main.rs:14:5:
oh no
stack backtrace:
   0: rust_begin_unwind
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:665:5
   1: core::panicking::panic_fmt
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panicking.rs:74:14
   2: ruttest::f3
             at ./src/main.rs:14:2
   3: ruttest::f2
             at ./src/main.rs:10:2
   4: ruttest::f1
             at ./src/main.rs:6:2
   5: ruttest::main
             at ./src/main.rs:2:2
   6: core::ops::function::FnOnce::call_once
             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/ops/function.rs:250:5
Go
package main

func main() {
	f1(1)
}

func f1(i int) {
	f2()
}

func f2() {
	f3()
}

func f3() {
	panic("oh no")
}
panic: oh no

goroutine 1 [running]:
main.f3(...)
        /Users/leighmcculloch/Code/gotest/main.go:16
main.f2(...)
        /Users/leighmcculloch/Code/gotest/main.go:12
main.f1(...)
        /Users/leighmcculloch/Code/gotest/main.go:8
main.main()
        /Users/leighmcculloch/Code/gotest/main.go:4 +0x38
exit status 2
Node
function f1(i) {
  f2();
}

function f2() {
  f3();
}

function f3() {
  throw "oh no";
}

f1(1);
/Users/leighmcculloch/Code/nodtest/main.js:10
  throw "oh no";
  ^
oh no
Thrown at:
    at f3 (/Users/leighmcculloch/Code/nodtest/main.js:10:3)
    at f2 (/Users/leighmcculloch/Code/nodtest/main.js:6:3)
    at f1 (/Users/leighmcculloch/Code/nodtest/main.js:2:3)
    at /Users/leighmcculloch/Code/nodtest/main.js:13:1
    at Module._compile (node:internal/modules/cjs/loader:1378:14)
    at Module._extensions..js (node:internal/modules/cjs/loader:1437:10)
    at Module.load (node:internal/modules/cjs/loader:1212:32)
    at Module._load (node:internal/modules/cjs/loader:1028:12)
    at executeUserEntryPoint (node:internal/modules/run_main:142:12)
    at node:internal/main/run_main_module:28:49
Bun
function f1(i) {
  f2();
}

function f2() {
  f3();
}

function f3() {
  throw "oh no";
}

f1(1);
error: oh no
Deno
function f1(i: u32) {
  f2();
}

function f2() {
  f3();
}

function f3() {
  throw "oh no";
}

f1(1);
error: Uncaught (in promise) "oh no"
Python
def f1(i):
  f2()

def f2():
  f3()

def f3():
  raise Exception("oh no")

f1(1)
Traceback (most recent call last):
  File "/Users/leighmcculloch/Code/pytest/main.py", line 10, in <module>
    f1(1)
  File "/Users/leighmcculloch/Code/pytest/main.py", line 2, in f1
    f2()
  File "/Users/leighmcculloch/Code/pytest/main.py", line 5, in f2
    f3()
  File "/Users/leighmcculloch/Code/pytest/main.py", line 8, in f3
    raise Exception("oh no")
Exception: oh no
Ruby
def f1(i)
  f2()
end

def f2()
  f3()
end

def f3()
  raise "oh no"
end

f1(1)
main.rb:10:in `f3': oh no (RuntimeError)
        from main.rb:6:in `f2'
        from main.rb:2:in `f1'
        from main.rb:13:in `<main>'
Java
public class Main {
    public static void main(String[] args) {
        f1(1);
    }

    public static void f1(int i) {
        f2();
    }

    public static void f2() {
        f3();
    }

    public static void f3() {
        throw new RuntimeException("oh no");
    }
}
Exception in thread "main" java.lang.RuntimeException: oh no
  at Main.f3(Main.java:15)
  at Main.f2(Main.java:11)
  at Main.f1(Main.java:7)
  at Main.main(Main.java:3)
.NET
using System;
          
public class Program
{
  public static void Main()
  {
    f1(1);
  }
  
  public static void f1(int i) {
    f2();
  }
  
  public static void f2() {
    f3();
  }
  
  public static void f3() {
    throw new Exception("oh no");
  }
}
Run-time exception (line 19): oh no

Stack Trace:

[System.Exception: oh no]
   at Program.f3() :line 19
   at Program.f2() :line 15
   at Program.f1(Int32 i) :line 11
   at Program.Main() :line 7
Swift
import Foundation

func f1(i: Int) {
    f2();
}

func f2() {
    f3();
}

func f3() {
    fatalError("oh no");
}

f1(i: 1);
main/main.swift:12: Fatal error: oh no
[1]    30171 trace trap  ./main
Zig
pub fn main() !void {
  f1(1);
}

fn f1(_: i32) void {
  f2();
}

fn f2() void {
  f3();
}

fn f3() void {
  @panic("oh no");
}
thread 22449779 panic: oh no
/Users/leighmcculloch/Code/zigtest/main.zig:14:3: 0x102242e4b in f3 (main)
  @panic("oh no");
  ^
/Users/leighmcculloch/Code/zigtest/main.zig:10:5: 0x1022416af in f2 (main)
  f3();
    ^
/Users/leighmcculloch/Code/zigtest/main.zig:6:5: 0x102240797 in f1 (main)
  f2();
    ^
/Users/leighmcculloch/Code/zigtest/main.zig:2:5: 0x102240777 in main (main)
  f1(1);
    ^
/opt/homebrew/Cellar/zig/0.13.0/lib/zig/std/start.zig:524:37: 0x1022409fb in main (main)
            const result = root.main() catch |err| {
                                    ^
???:?:?: 0x189b2a0df in ??? (???)
???:?:?: 0x9900ffffffffffff in ??? (???)
[1]    33104 abort      zig run main.zig

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant