5 ms·

Stack traces are not the best context for operational debugging. a) stack traces generally don't capture parameters b) stack tracers can be totally desynchron

by q3k 6y ago

Stack traces are not the best context for operational debugging. a) stack traces generally don't capture parameters b) stack tracers can be totally desynchronized with intent flow c) stack traces expose unnecessary internal noise Compare: Traceback (most recent call last): File "/var/prod/deadbeef/models/sql/peers.py", line 1337, in tx db.execute() File "/var/prod/deadbeef/models/sql/session.py", line 1337, in session tx(peers.add(a, b)) File "/var/prod/deadbeef/models/__init__.py", line 1337, in AddBGPPeer session(peers, AddPeers(a, b)) File "/var/prod/deadbeef/views.py", line 1337, in _view_add_peer AddBGPPeer(user, other) File "/var/prod/deadbeef/web.py", line 1337, in handle _view_add_peer(ctx) Exception: DB connector returned: unique constraint failed to: Failed to add peer: models.AddBGPPeer(204480, 204480): insert peer: tx aborted: unique constraint failed The first requires further logging and code reading to understand what might've caused the error. The latter immediately gives you information you need to understand what happened (the validation layer didn't catch an invalid self-reference, causing a database UNIQUE constraint to fail, and the database code caller didn't gracefully translate this error either). I use the following pattern in Go very often: foo, err := m.AddBGPPeer(a, b, secret, list) if err != nil { pretty := list.StringSeparated(", ") return nil, fmt.Errorf("AddBGPPeer(%q, %q, _, %s): %w", a, b, pretty, err) } The fact that Go error handling is just bog standard Go code allows for some quite complex generation of error messages/hints/contexts that couldn't be caught automatically from a stacktrace, or would have some awkward syntax/semantics with more complex syntactic sugar.

diggan 6y ago
In a larger codebase, a combination of both would be more helpful. With the last one, you're not getting the same view as with the latter, and in a large codebase where the error could be triggered from many directions, it would be better to have the first example, at least in my experience. Traceback (most recent call last): File "/var/prod/deadbeef/models/sql/peers.py", line 1337, in tx db.execute() File "/var/prod/deadbeef/models/sql/session.py", line 1337, in session tx(peers.add(a, b)) File "/var/prod/deadbeef/models/__init__.py", line 1337, in AddBGPPeer session(peers, AddPeers(a, b)) File "/var/prod/deadbeef/views.py", line 1337, in _view_add_peer AddBGPPeer(user, other) File "/var/prod/deadbeef/web.py", line 1337, in handle _view_add_peer(ctx) Exception: Failed to add peer: models.AddBGPPeer(204480, 204480): insert peer: tx aborted: unique constraint failed
- q3k 6y ago
  Absolutely. I'm not saying exceptions are bad and harmful, I'm saying that exceptions aren't an automatic solution to good error handling.
chaorace 6y ago
I don't actually know what an intent flow is! I tried to Google around, but all I can seem to find are proprietary keyword mishmashes used for digital payment systems. I'm guessing you're talking about, like, intent in the context of a state machine? Set me straight here if I misunderstand. I see the validity of what you're saying, but only in the context of insufficiently verbose third-party error messages. There's no reason that the exception message could not have been more detailed. In my own projects, I like to design the functions that constitute the "plumbing" in such a way that they rethrow errors with more descriptive errors. We're venturing out into the realm of practice from that of theory, so this is just me sharing for the hell of it, but here's how that looks: // Helper function meant to be reused in many function definitions function throwIfFunctionParameterUndefined(functionName, parameterName, value){ if (value === undefined) throw new TypeError(`${functionName} invoked with undefined parameter ${parameterName}`) } function doThing(paramA, paramB, optionalParam){ // Assert and throw for things we can guarantee in a meaningful way // Since this is plumbing, we trust that higher level functions will catch if this is recoverable const throwIfParameterUndefined = (paramName, value) => throwIfFunctionParameterUndefined('doThing', paramName, value) throwIfParameterUndefined('paramA', paramA) throwIfParameterUndefined('paramB', paramB) // Rethrow errors from third party libraries try { thirdPartyThing() } catch (err){ err.message = 'thirdPartyThing invoked by doThing failed with message:\n' + err.message throw err } }
- q3k 6y ago
  > I don't actually know what an intent flow is! Sorry, I might've made that up :). What I meant is that stracktraces do not necessarily reflect the actual code path that the error was caused by (eg. with deferals to internal work queues), and even if they do, they tend to have terrible SNR (too much technicalities of how your code is structured, not enough information about the data that caused the error in the first place).
jcelerier 6y ago
I don't understand the mindset you have to be in, in order to prefer the second error example to the first
- q3k 6y ago
  Production outage at 2am.
- Measter 6y ago
  The mindset is that an program output like this in the event of a user input error is not good: Cup 60 skins in DB 104 drivers in DB thread 'main' panicked at 'Could not find car folder or its skins: acrl_poorsche_911_gt3_cup_2017', src\main.rs:104:17 stack backtrace: 0: 0x7ff72a06deca - std::backtrace_rs::backtrace::dbghelp::trace at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\..\..\backtrace\src\backtrace\dbghelp.rs:98 1: 0x7ff72a06deca - std::backtrace_rs::backtrace::trace_unsynchronized at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\..\..\backtrace\src\backtrace\mod.rs:66 2: 0x7ff72a06deca - std::sys_common::backtrace::_print_fmt at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\sys_common\backtrace.rs:79 3: 0x7ff72a06deca - std::sys_common::backtrace::_print::{{impl}}::fmt at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\sys_common\backtrace.rs:58 4: 0x7ff729fb93bb - core::fmt::write at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\core\src\fmt\mod.rs:1080 5: 0x7ff72a06c9e8 - std::io::Write::write_fmt<std::sys::windows::stdio::Stderr> at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\io\mod.rs:1516 6: 0x7ff72a06bd18 - std::sys_common::backtrace::_print at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\sys_common\backtrace.rs:61 7: 0x7ff72a06bd18 - std::sys_common::backtrace::print at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\sys_common\backtrace.rs:48 8: 0x7ff72a06bd18 - std::panicking::default_hook::{{closure}} at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:206 9: 0x7ff72a06bd18 - std::panicking::default_hook at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:227 10: 0x7ff72a06bd18 - std::panicking::rust_panic_with_hook at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:577 11: 0x7ff72a073ab5 - std::panicking::begin_panic_handler::{{closure}} at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:484 12: 0x7ff72a073a77 - std::sys_common::backtrace::__rust_end_short_backtrace<closure-0,!> at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\sys_common\backtrace.rs:153 13: 0x7ff72a073a1f - std::panicking::begin_panic_handler at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:483 14: 0x7ff72a0739e0 - std::panicking::begin_panic_fmt at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:437 15: 0x7ff729f3501e - __ImageBase 16: 0x7ff729f3f9eb - __ImageBase 17: 0x7ff729f51486 - main 18: 0x7ff729f40277 - main 19: 0x7ff72a0885f0 - invoke_main at d:\agent\_work\63\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:78 20: 0x7ff72a0885f0 - __scrt_common_main_seh at d:\agent\_work\63\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:288 21: 0x7ffeb18b7034 - BaseThreadInitThunk 22: 0x7ffeb1e9cec1 - RtlUserThreadStart That stack track is completely worthless. It tells you literally nothing. Worse, is that while the actual problem is printed, it gets lost with the mess of noise after it. Whereas an error output like this is clearer: Cup 60 skins in DB 104 drivers in DB Error: Failed to verify series data Caused by: Could not find car folder or its skins: acrl_poorsche_911_gt3_cup_2017 The core error is that a car or skin folder was missing, and that error caused verification to fail. That's what should be printed, because that's what is relevant.

by q3k 6y ago

diggan 6y ago

In a larger codebase, a combination of both would be more helpful. With the last one, you're not getting the same view as with the latter, and in a large codebase where the error could be triggered from many directions, it would be better to have the first example, at least in my experience. Traceback (most recent call last): File "/var/prod/deadbeef/models/sql/peers.py", line 1337, in tx db.execute() File "/var/prod/deadbeef/models/sql/session.py", line 1337, in session tx(peers.add(a, b)) File "/var/prod/deadbeef/models/__init__.py", line 1337, in AddBGPPeer session(peers, AddPeers(a, b)) File "/var/prod/deadbeef/views.py", line 1337, in _view_add_peer AddBGPPeer(user, other) File "/var/prod/deadbeef/web.py", line 1337, in handle _view_add_peer(ctx) Exception: Failed to add peer: models.AddBGPPeer(204480, 204480): insert peer: tx aborted: unique constraint failed

q3k 6y ago
Absolutely. I'm not saying exceptions are bad and harmful, I'm saying that exceptions aren't an automatic solution to good error handling.

chaorace 6y ago

I don't actually know what an intent flow is! I tried to Google around, but all I can seem to find are proprietary keyword mishmashes used for digital payment systems. I'm guessing you're talking about, like, intent in the context of a state machine? Set me straight here if I misunderstand. I see the validity of what you're saying, but only in the context of insufficiently verbose third-party error messages. There's no reason that the exception message could not have been more detailed. In my own projects, I like to design the functions that constitute the "plumbing" in such a way that they rethrow errors with more descriptive errors. We're venturing out into the realm of practice from that of theory, so this is just me sharing for the hell of it, but here's how that looks: // Helper function meant to be reused in many function definitions function throwIfFunctionParameterUndefined(functionName, parameterName, value){ if (value === undefined) throw new TypeError(`${functionName} invoked with undefined parameter ${parameterName}`) } function doThing(paramA, paramB, optionalParam){ // Assert and throw for things we can guarantee in a meaningful way // Since this is plumbing, we trust that higher level functions will catch if this is recoverable const throwIfParameterUndefined = (paramName, value) => throwIfFunctionParameterUndefined('doThing', paramName, value) throwIfParameterUndefined('paramA', paramA) throwIfParameterUndefined('paramB', paramB) // Rethrow errors from third party libraries try { thirdPartyThing() } catch (err){ err.message = 'thirdPartyThing invoked by doThing failed with message:\n' + err.message throw err } }

q3k 6y ago
> I don't actually know what an intent flow is! Sorry, I might've made that up :). What I meant is that stracktraces do not necessarily reflect the actual code path that the error was caused by (eg. with deferals to internal work queues), and even if they do, they tend to have terrible SNR (too much technicalities of how your code is structured, not enough information about the data that caused the error in the first place).

jcelerier 6y ago

I don't understand the mindset you have to be in, in order to prefer the second error example to the first

q3k 6y ago
Production outage at 2am.
Measter 6y ago
The mindset is that an program output like this in the event of a user input error is not good: Cup 60 skins in DB 104 drivers in DB thread 'main' panicked at 'Could not find car folder or its skins: acrl_poorsche_911_gt3_cup_2017', src\main.rs:104:17 stack backtrace: 0: 0x7ff72a06deca - std::backtrace_rs::backtrace::dbghelp::trace at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\..\..\backtrace\src\backtrace\dbghelp.rs:98 1: 0x7ff72a06deca - std::backtrace_rs::backtrace::trace_unsynchronized at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\..\..\backtrace\src\backtrace\mod.rs:66 2: 0x7ff72a06deca - std::sys_common::backtrace::_print_fmt at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\sys_common\backtrace.rs:79 3: 0x7ff72a06deca - std::sys_common::backtrace::_print::{{impl}}::fmt at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\sys_common\backtrace.rs:58 4: 0x7ff729fb93bb - core::fmt::write at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\core\src\fmt\mod.rs:1080 5: 0x7ff72a06c9e8 - std::io::Write::write_fmt<std::sys::windows::stdio::Stderr> at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\io\mod.rs:1516 6: 0x7ff72a06bd18 - std::sys_common::backtrace::_print at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\sys_common\backtrace.rs:61 7: 0x7ff72a06bd18 - std::sys_common::backtrace::print at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\sys_common\backtrace.rs:48 8: 0x7ff72a06bd18 - std::panicking::default_hook::{{closure}} at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:206 9: 0x7ff72a06bd18 - std::panicking::default_hook at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:227 10: 0x7ff72a06bd18 - std::panicking::rust_panic_with_hook at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:577 11: 0x7ff72a073ab5 - std::panicking::begin_panic_handler::{{closure}} at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:484 12: 0x7ff72a073a77 - std::sys_common::backtrace::__rust_end_short_backtrace<closure-0,!> at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\sys_common\backtrace.rs:153 13: 0x7ff72a073a1f - std::panicking::begin_panic_handler at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:483 14: 0x7ff72a0739e0 - std::panicking::begin_panic_fmt at /rustc/7eac88abb2e57e752f3302f02be5f3ce3d7adfb4\/library\std\src\panicking.rs:437 15: 0x7ff729f3501e - __ImageBase 16: 0x7ff729f3f9eb - __ImageBase 17: 0x7ff729f51486 - main 18: 0x7ff729f40277 - main 19: 0x7ff72a0885f0 - invoke_main at d:\agent\_work\63\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:78 20: 0x7ff72a0885f0 - __scrt_common_main_seh at d:\agent\_work\63\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:288 21: 0x7ffeb18b7034 - BaseThreadInitThunk 22: 0x7ffeb1e9cec1 - RtlUserThreadStart That stack track is completely worthless. It tells you literally nothing. Worse, is that while the actual problem is printed, it gets lost with the mess of noise after it. Whereas an error output like this is clearer: Cup 60 skins in DB 104 drivers in DB Error: Failed to verify series data Caused by: Could not find car folder or its skins: acrl_poorsche_911_gt3_cup_2017 The core error is that a car or skin folder was missing, and that error caused verification to fail. That's what should be printed, because that's what is relevant.