Remove backtrace #1464

leighmcculloch · 2024-09-17T05:20:39Z

What

Moved backtrace in the Host's DebugInfo behind a new feature.

Why

The backtrace output is included in the Debug formatting of errors when testutils are enabled, but the trace has not turned out to be that useful in contract tests written with the SDK.

When an error occurs in a contract test the output includes two long stack traces. The first is the one provided by backtrace. The second is one provided by the Rust test harness. Both are very similar and contain approximately the same information. The Rust test harness' trace is actually a little easier to read because it's not quite so verbose.

Here's a before and after of what a test failing looks like before and after this change:

Before

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", exec, [CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAFCT4]]
   2: [Failed Diagnostic Event (not emitted)] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAHK3M, topics:[error, Error(Auth, InvalidAction)], data:"caught error from function"
   3: [Failed Diagnostic Event (not emitted)] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAHK3M, topics:[error, Error(Auth, InvalidAction)], data:"escalating error to panic"
   4: [Failed Diagnostic Event (not emitted)] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAHK3M, topics:[error, Error(Auth, InvalidAction)], data:["Unauthorized function call for address", CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAFCT4]
   5: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000003), exec], data:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAFCT4
   6: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000005), __constructor], data:Void
   7: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000004), __constructor], data:Void
   8: [Diagnostic Event] topics:[log], data:["holder_2", CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAK3IM]
   9: [Diagnostic Event] topics:[log], data:["holder_1", CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAITA4]
   10: [Diagnostic Event] topics:[log], data:["test_id", CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAHK3M]
   11: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000003), __constructor], data:Void
   12: [Diagnostic Event] topics:[log], data:["auth_id", CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAFCT4]
   13: [Diagnostic Event] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAFCT4, topics:[fn_return, init], data:Void
   14: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000002), init], data:[CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAD2KM, 2]
   15: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000002), __constructor], data:Void
   16: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000001), __constructor], data:Void

Backtrace (newest first):
   0: backtrace::backtrace::libunwind::trace
             at /Users/leighmcculloch/.cargo/registry/src/index.crates.io-6f17d22bba15001f/backtrace-0.3.74/src/backtrace/libunwind.rs:116:5
      backtrace::backtrace::trace_unsynchronized
             at /Users/leighmcculloch/.cargo/registry/src/index.crates.io-6f17d22bba15001f/backtrace-0.3.74/src/backtrace/mod.rs:66:5
   1: backtrace::backtrace::trace
             at /Users/leighmcculloch/.cargo/registry/src/index.crates.io-6f17d22bba15001f/backtrace-0.3.74/src/backtrace/mod.rs:53:14
   2: backtrace::capture::Backtrace::create
             at /Users/leighmcculloch/.cargo/registry/src/index.crates.io-6f17d22bba15001f/backtrace-0.3.74/src/capture.rs:292:9
   3: backtrace::capture::Backtrace::new_unresolved
             at /Users/leighmcculloch/.cargo/registry/src/index.crates.io-6f17d22bba15001f/backtrace-0.3.74/src/capture.rs:287:9
   4: soroban_env_host::host::error::<impl soroban_env_host::host::Host>::maybe_get_debug_info::{{closure}}
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-env-230c62c6b1f3d3f1/75b7821/soroban-env-host/src/host/error.rs:299:37
   5: soroban_env_host::budget::Budget::with_shadow_mode
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-env-230c62c6b1f3d3f1/75b7821/soroban-env-host/src/budget.rs:1039:21
   6: soroban_env_host::host::Host::with_debug_mode
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-env-230c62c6b1f3d3f1/75b7821/soroban-env-host/src/host.rs:650:24
   7: soroban_env_host::host::error::<impl soroban_env_host::host::Host>::maybe_get_debug_info
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-env-230c62c6b1f3d3f1/75b7821/soroban-env-host/src/host/error.rs:296:13
   8: soroban_env_host::host::error::<impl soroban_env_host::host::Host>::error::{{closure}}
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-env-230c62c6b1f3d3f1/75b7821/soroban-env-host/src/host/error.rs:280:23
   9: soroban_env_host::budget::Budget::with_shadow_mode
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-env-230c62c6b1f3d3f1/75b7821/soroban-env-host/src/budget.rs:1039:21
  10: soroban_env_host::host::Host::with_debug_mode
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-env-230c62c6b1f3d3f1/75b7821/soroban-env-host/src/host.rs:650:24
  11: soroban_env_host::host::error::<impl soroban_env_host::host::Host>::error
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-env-230c62c6b1f3d3f1/75b7821/soroban-env-host/src/host/error.rs:267:9
  12: <soroban_env_host::host::Host as soroban_env_common::env::EnvBase>::escalate_error_to_panic
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-env-230c62c6b1f3d3f1/75b7821/soroban-env-host/src/host.rs:838:26
  13: soroban_sdk::env::internal::reject_err::{{closure}}
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-sdk-0ab58a716c671239/a101940/soroban-sdk/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/leighmcculloch/.cargo/git/checkouts/rs-soroban-sdk-0ab58a716c671239/a101940/soroban-sdk/src/env.rs:52:9
  16: <soroban_sdk::env::Env as soroban_env_common::env::Env>::call
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-sdk-0ab58a716c671239/a101940/soroban-sdk/src/env.rs:1796:13
  17: soroban_sdk::env::Env::invoke_contract
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-sdk-0ab58a716c671239/a101940/soroban-sdk/src/env.rs:379:18
  18: auth::tests::TestContractClient::exec
             at /Users/leighmcculloch/Code/talk-stellar-meridian24-testing/auth/src/tests.rs:17:1
  19: auth::tests::unit_test
             at /Users/leighmcculloch/Code/talk-stellar-meridian24-testing/auth/src/tests.rs:61:5
  20: auth::tests::unit_test::{{closure}}
             at /Users/leighmcculloch/Code/talk-stellar-meridian24-testing/auth/src/tests.rs:35:15
  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/leighmcculloch/.cargo/git/checkouts/rs-soroban-env-230c62c6b1f3d3f1/75b7821/soroban-env-host/src/host.rs:839:9
   3: soroban_sdk::env::internal::reject_err::{{closure}}
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-sdk-0ab58a716c671239/a101940/soroban-sdk/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/leighmcculloch/.cargo/git/checkouts/rs-soroban-sdk-0ab58a716c671239/a101940/soroban-sdk/src/env.rs:52:9
   6: <soroban_sdk::env::Env as soroban_env_common::env::Env>::call
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-sdk-0ab58a716c671239/a101940/soroban-sdk/src/env.rs:1796:13
   7: soroban_sdk::env::Env::invoke_contract
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-sdk-0ab58a716c671239/a101940/soroban-sdk/src/env.rs:379:18
   8: auth::tests::TestContractClient::exec
             at ./src/tests.rs:17:1
   9: auth::tests::unit_test
             at ./src/tests.rs:61:5
  10: auth::tests::unit_test::{{closure}}
             at ./src/tests.rs:35:15
  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

After

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", exec, [CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAFCT4]]
   2: [Failed Diagnostic Event (not emitted)] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAHK3M, topics:[error, Error(Auth, InvalidAction)], data:"caught error from function"
   3: [Failed Diagnostic Event (not emitted)] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAHK3M, topics:[error, Error(Auth, InvalidAction)], data:"escalating error to panic"
   4: [Failed Diagnostic Event (not emitted)] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAHK3M, topics:[error, Error(Auth, InvalidAction)], data:["Unauthorized function call for address", CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAFCT4]
   5: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000003), exec], data:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAFCT4
   6: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000005), __constructor], data:Void
   7: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000004), __constructor], data:Void
   8: [Diagnostic Event] topics:[log], data:["holder_2", CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAK3IM]
   9: [Diagnostic Event] topics:[log], data:["holder_1", CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAITA4]
   10: [Diagnostic Event] topics:[log], data:["test_id", CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAHK3M]
   11: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000003), __constructor], data:Void
   12: [Diagnostic Event] topics:[log], data:["auth_id", CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAFCT4]
   13: [Diagnostic Event] contract:CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAFCT4, topics:[fn_return, init], data:Void
   14: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000002), init], data:[CAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAD2KM, 2]
   15: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000002), __constructor], data:Void
   16: [Diagnostic Event] topics:[fn_call, Bytes(0000000000000000000000000000000000000000000000000000000000000001), __constructor], data:Void

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/leighmcculloch/Code/rs-soroban-env/soroban-env-host/src/host.rs:839:9
   3: soroban_sdk::env::internal::reject_err::{{closure}}
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-sdk-0ab58a716c671239/a101940/soroban-sdk/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/leighmcculloch/.cargo/git/checkouts/rs-soroban-sdk-0ab58a716c671239/a101940/soroban-sdk/src/env.rs:52:9
   6: <soroban_sdk::env::Env as soroban_env_common::env::Env>::call
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-sdk-0ab58a716c671239/a101940/soroban-sdk/src/env.rs:1796:13
   7: soroban_sdk::env::Env::invoke_contract
             at /Users/leighmcculloch/.cargo/git/checkouts/rs-soroban-sdk-0ab58a716c671239/a101940/soroban-sdk/src/env.rs:379:18
   8: auth::tests::TestContractClient::exec
             at ./src/tests.rs:17:1
   9: auth::tests::unit_test
             at ./src/tests.rs:61:5
  10: auth::tests::unit_test::{{closure}}
             at ./src/tests.rs:35:15
  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

Note

I'm not attached to this change if we need back traces for something, but if we need to keep them, I'm interested in how we can silence them for errors in contract tests.

Bonuses

As a bonus, this removes 7 deps from the dep graph for contract developers! 🎉

dmkozh

I also have never found this to be too useful, but I'm curious if maybe @graydon had some uses in mind.

graydon · 2024-09-17T20:52:29Z

Hmm, I think I would like to keep them but it's only a mild preference. I think I mostly only see/use them when debugging test failures in the soroban host, and even then I fairly often want to look around, so set breakpoints in the IDE debugger. I won't block this if you both feel like they're not pulling their weight (and especially if users never get any value out of them, I'm certain we added them primarily for user benefit). Are you sure all/most scenarios users get a test-runner panic it'll have sufficient user-contract context in it?

leighmcculloch · 2024-09-17T20:57:19Z

As far as I can tell I haven't seen a case where I didn't otherwise have a backtrace available. Iirc we built the back tracing first, and then later added really good error handling and propogation to panics, (I think you did both! Thanks!!!), and so it's possible we just made the existing back tracing redundant.

Another way I could change this proposal is keep the backtrace, and only output it in the debug fmt if an env var is set, such as SOROBAN_BACKTRACE=1, or put it behind another feature? Wdyt?

graydon · 2024-09-17T22:39:33Z

I think I would prefer that, yes. Again, not a super-duper preference but, for example, in core we've repeatedly spent person-months to try to even get backtraces reliably reporting (the C++ library often fights with them amazingly) to debug field issues, I'd like to keep the ability close-ish at hand if it's not a huge burden.

This reverts commit 6ce8e01.

leighmcculloch · 2024-09-17T22:48:31Z

I've pushed an update putting backtrace behind a new feature flag. I think this has the best tradeoffs because of the dep graph, as it'll remove the dep graph from contract developers.

… without testutils

Remove backtrace

6ce8e01

leighmcculloch marked this pull request as ready for review September 17, 2024 05:24

leighmcculloch requested review from graydon, sisuresh, dmkozh and a team as code owners September 17, 2024 05:24

dmkozh approved these changes Sep 17, 2024

View reviewed changes

leighmcculloch added 2 commits September 18, 2024 08:43

Revert "Remove backtrace"

4558728

This reverts commit 6ce8e01.

Put backtrace behind a feature

28fec5d

leighmcculloch added 3 commits September 18, 2024 09:47

remove dependence on backtrace <> testutils to allow use of backtrace…

3977e7f

… without testutils

remove backtrace from testutils feature

92a480a

fix

2b7aadb

dmkozh approved these changes Sep 18, 2024

View reviewed changes

leighmcculloch added this pull request to the merge queue Sep 18, 2024

Merged via the queue into main with commit fa8f615 Sep 18, 2024
12 checks passed

leighmcculloch deleted the remove-backtrace branch September 18, 2024 00:54

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Remove backtrace #1464

Remove backtrace #1464

leighmcculloch commented Sep 17, 2024 •

edited

Loading

dmkozh left a comment

graydon commented Sep 17, 2024

leighmcculloch commented Sep 17, 2024 •

edited

Loading

graydon commented Sep 17, 2024

leighmcculloch commented Sep 17, 2024

Remove backtrace #1464

Remove backtrace #1464

Conversation

leighmcculloch commented Sep 17, 2024 • edited Loading

What

Why

Before

After

Note

Bonuses

dmkozh left a comment

Choose a reason for hiding this comment

graydon commented Sep 17, 2024

leighmcculloch commented Sep 17, 2024 • edited Loading

graydon commented Sep 17, 2024

leighmcculloch commented Sep 17, 2024

leighmcculloch commented Sep 17, 2024 •

edited

Loading

leighmcculloch commented Sep 17, 2024 •

edited

Loading