Add backtrace to error messages #7434

comphead · 2023-08-28T15:54:46Z

Which issue does this PR close?

Part of #7360 .

Rationale for this change

Currently the user getting only error description which sometimes makes investigation more complex, adding optional back trace

What changes are included in this PR?

Adding the optional back trace for the errors being thrown.
By default the backtrace is disabled, to enable it uses Rust mechanism described https://doc.rust-lang.org/std/backtrace/index.html#environment-variables

Added .strip_backtrace() method to Datafusion Errors to get the error message only if the backtrace enabled

User Example

DataFusion CLI v30.0.0
❯ select row_numer() over (partition by a order by a) from (select 1 a);
Error during planning: Invalid function 'row_numer'.
Did you mean 'ROW_NUMBER'?

with backtrace enabled

RUST_BACKTRACE=1 ./target/debug/datafusion-cli 
DataFusion CLI v30.0.0
❯ select row_numer() over (partition by a order by a) from (select 1 a);
Error during planning: Invalid function 'row_numer'.
Did you mean 'ROW_NUMBER'?

backtrace:    0: std::backtrace_rs::backtrace::libunwind::trace
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1: std::backtrace_rs::backtrace::trace_unsynchronized
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2: std::backtrace::Backtrace::create
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/backtrace.rs:332:13
   3: std::backtrace::Backtrace::capture
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/backtrace.rs:298:9
   4: datafusion_common::error::DataFusionError::get_back_trace
             at rust/arrow-datafusion/datafusion/common/src/error.rs:428:26
   5: datafusion_sql::expr::function::<impl datafusion_sql::planner::SqlToRel<S>>::sql_function_to_expr
             at /rust/arrow-datafusion/datafusion/sql/src/expr/function.rs:163:9
   6: datafusion_sql::expr::<impl datafusion_sql::planner::SqlToRel<S>>::sql_expr_to_logical_expr_internal
             at /rust/arrow-datafusion/datafusion/sql/src/expr/mod.rs:429:17
   7: datafusion_sql::expr::<impl datafusion_sql::planner::SqlToRel<S>>::sql_expr_to_logical_expr
             at /rust/arrow-datafusion/datafusion/sql/src/expr/mod.rs:88:40
   8: datafusion_sql::expr::<impl datafusion_sql::planner::SqlToRel<S>>::sql_to_expr
             at rust/arrow-datafusion/datafusion/sql/src/expr/mod.rs:122:24
   9: datafusion_sql::select::<impl datafusion_sql::planner::SqlToRel<S>>::sql_select_to_rex
             at /rust/arrow-datafusion/datafusion/sql/src/select.rs:339:28
  10: datafusion_sql::select::<impl datafusion_sql::planner::SqlToRel<S>>::prepare_select_exprs::{{closure}}
             at /rust/arrow-datafusion/datafusion/sql/src/select.rs:321:25
  11: core::iter::adapters::map::map_try_fold::{{closure}}
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/adapters/map.rs:91:28
  12: core::iter::traits::iterator::Iterator::try_fold
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/traits/iterator.rs:2303:21
  13: <core::iter::adapters::map::Map<I,F> as core::iter::traits::iterator::Iterator>::try_fold
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/adapters/map.rs:117:9
  14: <core::iter::adapters::map::Map<I,F> as core::iter::traits::iterator::Iterator>::try_fold
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/adapters/map.rs:117:9
  15: <core::iter::adapters::fuse::Fuse<I> as core::iter::adapters::fuse::FuseImpl<I>>::try_fold
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/adapters/fuse.rs:368:19
  16: <core::iter::adapters::fuse::Fuse<I> as core::iter::traits::iterator::Iterator>::try_fold
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/adapters/fuse.rs:82:9
  17: core::iter::adapters::flatten::FlattenCompat<I,U>::iter_try_fold
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/adapters/flatten.rs:386:25
  18: <core::iter::adapters::flatten::FlattenCompat<I,U> as core::iter::traits::iterator::Iterator>::try_fold
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/adapters/flatten.rs:524:9
  19: <core::iter::adapters::flatten::FlatMap<I,U,F> as core::iter::traits::iterator::Iterator>::try_fold
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/adapters/flatten.rs:67:9
  20: <core::iter::adapters::GenericShunt<I,R> as core::iter::traits::iterator::Iterator>::try_fold
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/adapters/mod.rs:195:9
  21: core::iter::traits::iterator::Iterator::try_for_each
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/traits/iterator.rs:2365:9
  22: <core::iter::adapters::GenericShunt<I,R> as core::iter::traits::iterator::Iterator>::next
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/adapters/mod.rs:178:14
  23: <alloc::vec::Vec<T> as alloc::vec::spec_from_iter_nested::SpecFromIterNested<T,I>>::from_iter
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/alloc/src/vec/spec_from_iter_nested.rs:26:32
  24: <alloc::vec::Vec<T> as alloc::vec::spec_from_iter::SpecFromIter<T,I>>::from_iter
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/alloc/src/vec/spec_from_iter.rs:33:9
  25: <alloc::vec::Vec<T> as core::iter::traits::collect::FromIterator<T>>::from_iter
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/alloc/src/vec/mod.rs:2696:9
  26: core::iter::traits::iterator::Iterator::collect
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/traits/iterator.rs:1895:9
  27: <core::result::Result<V,E> as core::iter::traits::collect::FromIterator<core::result::Result<A,E>>>::from_iter::{{closure}}
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/result.rs:1932:51
  28: core::iter::adapters::try_process
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/adapters/mod.rs:164:17
  29: <core::result::Result<V,E> as core::iter::traits::collect::FromIterator<core::result::Result<A,E>>>::from_iter
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/result.rs:1932:9
  30: core::iter::traits::iterator::Iterator::collect
             at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/iter/traits/iterator.rs:1895:9
  31: datafusion_sql::select::<impl datafusion_sql::planner::SqlToRel<S>>::prepare_select_exprs
             at /rust/arrow-datafusion/datafusion/sql/src/select.rs:319:9
  32: datafusion_sql::select::<impl datafusion_sql::planner::SqlToRel<S>>::select_to_plan
             at /rust/arrow-datafusion/datafusion/sql/src/select.rs:85:28
  33: datafusion_sql::set_expr::<impl datafusion_sql::planner::SqlToRel<S>>::set_expr_to_plan
             at /rust/arrow-datafusion/datafusion/sql/src/set_expr.rs:30:35
  34: datafusion_sql::query::<impl datafusion_sql::planner::SqlToRel<S>>::query_to_plan_with_schema
             at /rust/arrow-datafusion/datafusion/sql/src/query.rs:80:20
  35: datafusion_sql::query::<impl datafusion_sql::planner::SqlToRel<S>>::query_to_plan
             at /rust/arrow-datafusion/datafusion/sql/src/query.rs:41:9
  36: datafusion_sql::statement::<impl datafusion_sql::planner::SqlToRel<S>>::sql_statement_to_plan_with_context_impl
             at /rust/arrow-datafusion/datafusion/sql/src/statement.rs:137:40
  37: datafusion_sql::statement::<impl datafusion_sql::planner::SqlToRel<S>>::sql_statement_to_plan
             at /rust/arrow-datafusion/datafusion/sql/src/statement.rs:105:9
  38: datafusion_sql::statement::<impl datafusion_sql::planner::SqlToRel<S>>::statement_to_plan
             at /rust/arrow-datafusion/datafusion/sql/src/statement.rs:92:42
  39: datafusion::execution::context::SessionState::statement_to_plan::{{closure}}
             at /rust/arrow-datafusion/datafusion/core/src/execution/context.rs:1859:9
  40: datafusion_cli::exec::exec_and_print::{{closure}}
             at ./src/exec.rs:213:61
  41: datafusion_cli::exec::exec_from_repl::{{closure}}
             at ./src/exec.rs:167:65
  42: datafusion_cli::main::{{closure}}
             at ./src/main.rs:206:14

Are these changes tested?

Yes, existing tests

Are there any user-facing changes?

comphead · 2023-08-28T17:58:04Z

@alamb do you know the reason why some test tasks running with RUST_BACKTRACE: 1 but others not?

alamb · 2023-08-29T11:50:11Z

@alamb do you know the reason why some test tasks running with RUST_BACKTRACE: 1 but others not?

If you mean this:

https://github.com/search?q=repo%3Aapache%2Farrow-datafusion%20RUST_BACKTRACE&type=code

I don't know of any reasons for the discrepancy

comphead · 2023-08-29T15:35:55Z

Changing some tests checking exact error message to .starts_with as some test tasks get run with BACKTRACE=1 so this trigger backtrace and the entire error message won't be stable if the code changes

comphead · 2023-08-30T16:08:11Z

Adding .strip_backtrace() to get only error message if the RUST_BACKTRACE enabled

comphead · 2023-08-30T20:43:42Z

I will add documentation and examples in follow up PR

alamb · 2023-09-05T17:39:49Z

I have been away on vacation but am back now and will catch up with reviews over the next few days. This one looks great @comphead -- thank you

alamb

I think this looks great @comphead -- thank you very much. Does anyone else have any comments about this PR?

alamb · 2023-09-06T16:52:17Z

datafusion/common/src/error.rs

@@ -444,7 +467,7 @@ macro_rules! make_error {
                #[macro_export]
                macro_rules! $NAME {
                    ($d($d args:expr),*) => {
-                        Err(DataFusionError::$ERR(format!($d($d args),*).into()))
+                        Err(DataFusionError::$ERR(format!("{}{}", format!($d($d args),*), DataFusionError::get_back_trace()).into()))


this is pretty clever, to use the macro like this

github-actions bot added sql SQL Planner logical-expr Logical plan and expressions labels Aug 28, 2023

comphead mentioned this pull request Aug 28, 2023

Improve DataFusion error handling #7360

Open

23 tasks

github-actions bot added the core Core DataFusion crate label Aug 29, 2023

comphead force-pushed the dev branch from 87e520d to 80bd033 Compare August 29, 2023 15:33

github-actions bot added physical-expr Physical Expressions optimizer Optimizer rules labels Aug 30, 2023

comphead force-pushed the dev branch from e8df378 to 7b125ea Compare August 30, 2023 19:58

comphead marked this pull request as ready for review August 30, 2023 20:45

comphead marked this pull request as draft September 1, 2023 15:49

github-actions bot added the sqllogictest SQL Logic Tests (.slt) label Sep 2, 2023

comphead force-pushed the dev branch from c7a51b6 to 183becf Compare September 2, 2023 23:55

comphead marked this pull request as ready for review September 3, 2023 01:20

alamb approved these changes Sep 6, 2023

View reviewed changes

comphead added 10 commits September 6, 2023 12:28

Adding back trace

8e8ffb6

fmt

71dff87

fmt

7cdf6d4

tests

b126caf

tests

492a209

tests

7f099f4

clippy

0fcef85

strip_backtrace

878a9d3

tests

64d209e

moved backtrace

2a1423a

comphead added 2 commits September 6, 2023 12:30

tests

a490b68

tests

c0d7287

comphead force-pushed the dev branch from 183becf to c0d7287 Compare September 6, 2023 19:30

alamb changed the title ~~Adding back trace~~ Add backtrace to error messages Sep 7, 2023

alamb merged commit 2ffda2a into apache:main Sep 7, 2023

crepererum mentioned this pull request Sep 11, 2023

Performance Regression: Backtraces in errors slow down planning time (Expensive backtraces) #7522

Closed

comphead mentioned this pull request Sep 11, 2023

Make backtrace as a cargo feature #7527

Merged

comphead mentioned this pull request Sep 22, 2023

Minor: Adding backtrace documentation #7628

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add backtrace to error messages #7434

Add backtrace to error messages #7434

comphead commented Aug 28, 2023 •

edited

Loading

comphead commented Aug 28, 2023

alamb commented Aug 29, 2023

comphead commented Aug 29, 2023

comphead commented Aug 30, 2023

comphead commented Aug 30, 2023

alamb commented Sep 5, 2023

alamb left a comment

alamb Sep 6, 2023

Add backtrace to error messages #7434

Add backtrace to error messages #7434

Conversation

comphead commented Aug 28, 2023 • edited Loading

Which issue does this PR close?

Rationale for this change

What changes are included in this PR?

Are these changes tested?

Are there any user-facing changes?

comphead commented Aug 28, 2023

alamb commented Aug 29, 2023

comphead commented Aug 29, 2023

comphead commented Aug 30, 2023

comphead commented Aug 30, 2023

alamb commented Sep 5, 2023

alamb left a comment

Choose a reason for hiding this comment

alamb Sep 6, 2023

Choose a reason for hiding this comment

comphead commented Aug 28, 2023 •

edited

Loading