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

[rust] Capture Rust backtrace in case of error (displayed at DEBUG level) #12852

Merged
merged 12 commits into from
Oct 9, 2023

Conversation

bonigarcia
Copy link
Member

Description

This PR uses the anyhow crate to display backtrace in case of error.

Motivation and Context

The standard Rust library for error types does not include a stack trace. This fact can sometimes be problematic for troubleshooting, especially when some standard error (e.g., due to the file system) happens in the internal logic of Selenium Manager. Some typical example is as follows:

Permission denied (os error 13)

There is currently a reported issue in which that error happens. And in that case, we don't know in which code line that error is happening.

To ease the troubleshooting procedure in future issues, this PR includes the anyhow crate for handling errors in all the Selenium Manager Rust logic.

Thanks to this crate, we can capture the backtrace, and with that, we can discover in which line of the Rust code the error happened. To enable the backtrace capture, we set the standard Rust environment variable RUST_BACKTRACE to 1.

For example, consider the following forced error:

$ ./selenium-manager --debug --browser BAD

ERROR   Invalid browser name: BAD

Selenium Manager finished due to a bad name in the specified browser. But if RUST_BACKTRACE is set to 1, in addition, we have the complete backtrace in the output:

$ RUST_BACKTRACE=1 ./selenium-manager --debug --browser BAD
DEBUG   Backtrace:
   0: backtrace::backtrace::trace<anyhow::backtrace::capture::impl$4::create::closure_env$0>
             at C:\Users\boni\.cargo\registry\src\index.crates.io-1cd66030c949c28d\backtrace-0.3.67\src\backtrace\mod.rs:53
   1: anyhow::backtrace::capture::Backtrace::create
             at C:\Users\boni\.cargo\registry\src\index.crates.io-1cd66030c949c28d\anyhow-1.0.75\src\backtrace.rs:216
   2: anyhow::backtrace::capture::Backtrace::capture
             at C:\Users\boni\.cargo\registry\src\index.crates.io-1cd66030c949c28d\anyhow-1.0.75\src\backtrace.rs:204
   3: selenium_manager::get_manager_by_browser
             at .\src\lib.rs:1091
   4: selenium_manager::get_manager_by_browser
             at .\src\lib.rs:1091
   5: selenium_manager::main
             at .\src\main.rs:149
   6: core::ops::function::FnOnce::call_once<void (*)(),tuple$<> >
             at /rustc/90c541806f23a127002de5b4038be731ba1458ca\library\core\src\ops\function.rs:250
   7: std::sys_common::backtrace::__rust_begin_short_backtrace<void (*)(),tuple$<> >
             at /rustc/90c541806f23a127002de5b4038be731ba1458ca\library\std\src\sys_common\backtrace.rs:134
   8: std::sys_common::backtrace::__rust_begin_short_backtrace<void (*)(),tuple$<> >
             at /rustc/90c541806f23a127002de5b4038be731ba1458ca\library\std\src\sys_common\backtrace.rs:134
   9: core::ops::function::impls::impl$2::call_once
             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\core\src\ops\function.rs:287
  10: std::panicking::try::do_call
             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\std\src\panicking.rs:485
  11: std::panicking::try
             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\std\src\panicking.rs:449
  12: std::panic::catch_unwind
             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\std\src\panic.rs:140
  13: std::rt::lang_start_internal::closure$2
             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\std\src\rt.rs:148
  14: std::panicking::try::do_call
             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\std\src\panicking.rs:485
  15: std::panicking::try
             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\std\src\panicking.rs:449
  16: std::panic::catch_unwind
             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\std\src\panic.rs:140
  17: std::rt::lang_start_internal
             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\std\src\rt.rs:148
  18: std::rt::lang_start<tuple$<> >
             at /rustc/90c541806f23a127002de5b4038be731ba1458ca\library\std\src\rt.rs:165
  19: invoke_main
             at D:\a\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:78
  20: __scrt_common_main_seh
             at D:\a\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:288
  21: BaseThreadInitThunk
  22: RtlGetAppContainerNamedObjectPath
  23: RtlGetAppContainerNamedObjectPath

The backtrace is also captured in the JSON output, which is the relevant one for the integration in the bindings:

$ RUST_BACKTRACE=1 ./selenium-manager --debug --browser BAD --output json

{
  "logs": [
    {
      "level": "ERROR",
      "timestamp": 1696258893,
      "message": "Invalid browser name: BAD"
    },
    {
      "level": "DEBUG",
      "timestamp": 1696258893,
      "message": "Backtrace:\n   0: backtrace::backtrace::trace<anyhow::backtrace::capture::impl$4::create::closure_env$0>\n             at C:\\Users\\boni\\.cargo\\registry\\src\\index.crates.io-1cd66030c949c28d\\backtrace-0.3.67\\src\\backtrace\\mod.rs:53\n   1: anyhow::backtrace::capture::Backtrace::create\n             at C:\\Users\\boni\\.cargo\\registry\\src\\index.crates.io-1cd66030c949c28d\\anyhow-1.0.75\\src\\backtrace.rs:216\n   2: anyhow::backtrace::capture::Backtrace::capture\n             at C:\\Users\\boni\\.cargo\\registry\\src\\index.crates.io-1cd66030c949c28d\\anyhow-1.0.75\\src\\backtrace.rs:204\n   3: selenium_manager::get_manager_by_browser\n             at .\\src\\lib.rs:1091\n   4: selenium_manager::get_manager_by_browser\n             at .\\src\\lib.rs:1091\n   5: selenium_manager::main\n             at .\\src\\main.rs:149\n   6: core::ops::function::FnOnce::call_once<void (*)(),tuple$<> >\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca\\library\\core\\src\\ops\\function.rs:250\n   7: std::sys_common::backtrace::__rust_begin_short_backtrace<void (*)(),tuple$<> >\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca\\library\\std\\src\\sys_common\\backtrace.rs:134\n   8: std::sys_common::backtrace::__rust_begin_short_backtrace<void (*)(),tuple$<> >\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca\\library\\std\\src\\sys_common\\backtrace.rs:134\n   9: core::ops::function::impls::impl$2::call_once\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\core\\src\\ops\\function.rs:287\n  10: std::panicking::try::do_call\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\panicking.rs:485\n  11: std::panicking::try\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\panicking.rs:449\n  12: std::panic::catch_unwind\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\panic.rs:140\n  13: std::rt::lang_start_internal::closure$2\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\rt.rs:148\n  14: std::panicking::try::do_call\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\panicking.rs:485\n  15: std::panicking::try\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\panicking.rs:449\n  16: std::panic::catch_unwind\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\panic.rs:140\n  17: std::rt::lang_start_internal\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\rt.rs:148\n  18: std::rt::lang_start<tuple$<> >\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca\\library\\std\\src\\rt.rs:165\n  19: invoke_main\n             at D:\\a\\_work\\1\\s\\src\\vctools\\crt\\vcstartup\\src\\startup\\exe_common.inl:78\n  20: __scrt_common_main_seh\n             at D:\\a\\_work\\1\\s\\src\\vctools\\crt\\vcstartup\\src\\startup\\exe_common.inl:288\n  21: BaseThreadInitThunk\n  22: RtlGetAppContainerNamedObjectPath\n  23: RtlGetAppContainerNamedObjectPath\n"
    }
  ],
  "result": {
    "code": 65,
    "message": "Invalid browser name: BAD",
    "driver_path": "",
    "browser_path": ""
  }
}

Types of changes

  • Bug fix (non-breaking change which fixes an issue)
  • New feature (non-breaking change which adds functionality)
  • Breaking change (fix or feature that would cause existing functionality to change)

Checklist

  • I have read the contributing document.
  • My change requires a change to the documentation.
  • I have updated the documentation accordingly.
  • I have added tests to cover my changes.
  • All new and existing tests passed.

@titusfortner
Copy link
Member

Do we want to add RUST_BACKTRACE=1 in the bindings for when debug is turned on?

@bonigarcia
Copy link
Member Author

Do we want to add RUST_BACKTRACE=1 in the bindings for when debug is turned on?

Yes, we can do that.

Many times, the backtrace might not be necessary since many of the possible errors are easily traceable. But for errors like os error 13, the troubleshooting is complicated, and the backtrace will help.

@titusfortner
Copy link
Member

but we're only getting the backtrace if there's an error? Or do we get them even when we rescue the error?

@bonigarcia
Copy link
Member Author

I added a new commit to this PR to include the argument --backtrace to enable the backtrace capturing. That can be used in the bindings instead of dealing with the RUST_BACKTRACE=1 env. For user configuration, as usual, this argument can be specified as env (SE_BACKTRACE) or in the config file (se-config.toml).

Regarding your questions:

but we're only getting the backtrace if there's an error? Or do we get them even when we rescue the error?

The backtrace will be only captured when there is an unrecoverable error and the --backtrace is used. Some examples:

Correct operation of SM. Even if --backtrace is specified, no backtrace is added to the logs since there is no error:

./selenium-manager --debug --browser chrome --backtrace

DEBUG   chromedriver not found in PATH
DEBUG   chrome detected at C:\Program Files\Google\Chrome\Application\chrome.exe
DEBUG   Running command: wmic datafile where name='C:\\Program Files\\Google\\Chrome\\Application\\chrome.exe' get Version /value
DEBUG   Output: "\r\r\n\r\r\nVersion=117.0.5938.132\r\r\n\r\r\n\r\r\n\r"
DEBUG   Detected browser: chrome 117.0.5938.132
DEBUG   Required driver: chromedriver 117.0.5938.92
DEBUG   chromedriver 117.0.5938.92 already in the cache
INFO    Driver path: C:\Users\boni\.cache\selenium\chromedriver\win64\117.0.5938.92\chromedriver.exe
INFO    Browser path: C:\Program Files\Google\Chrome\Application\chrome.exe

Error in SM. When --backtrace is specified, the error backtrace is captured:

./selenium-manager --debug --browser BAD --backtrace --output json

{
  "logs": [
    {
      "level": "ERROR",
      "timestamp": 1696323933,
      "message": "Invalid browser name: BAD"
    },
    {
      "level": "DEBUG",
      "timestamp": 1696323933,
      "message": "Backtrace:\n   0: std::backtrace::Backtrace::force_capture\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\backtrace.rs:314\n   1: selenium_manager::flush_and_exit\n             at .\\src\\main.rs:265\n   2: selenium_manager::main::closure$0\n             at .\\src\\main.rs:157\n   3: enum2$<core::result::Result<alloc::boxed::Box<dyn$<selenium_manager::SeleniumManager>,alloc::alloc::Global>,anyhow::Error> >::unwrap_or_else<alloc::boxed::Box<dyn$<selenium_manager::SeleniumManager>,alloc::alloc::Global>,anyhow::Error,selenium_manager::ma\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca\\library\\core\\src\\result.rs:1464\n   4: RtlDeactivateActivationContextUnsafeFast\n   5: core::ops::function::FnOnce::call_once<void (*)(),tuple$<> >\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca\\library\\core\\src\\ops\\function.rs:250\n   6: std::sys_common::backtrace::__rust_begin_short_backtrace<void (*)(),tuple$<> >\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca\\library\\std\\src\\sys_common\\backtrace.rs:134\n   7: std::sys_common::backtrace::__rust_begin_short_backtrace<void (*)(),tuple$<> >\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca\\library\\std\\src\\sys_common\\backtrace.rs:134\n   8: core::ops::function::impls::impl$2::call_once\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\core\\src\\ops\\function.rs:287\n   9: std::panicking::try::do_call\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\panicking.rs:485\n  10: std::panicking::try\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\panicking.rs:449\n  11: std::panic::catch_unwind\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\panic.rs:140\n  12: std::rt::lang_start_internal::closure$2\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\rt.rs:148\n  13: std::panicking::try::do_call\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\panicking.rs:485\n  14: std::panicking::try\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\panicking.rs:449\n  15: std::panic::catch_unwind\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\panic.rs:140\n  16: std::rt::lang_start_internal\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\\std\\src\\rt.rs:148\n  17: std::rt::lang_start<tuple$<> >\n             at /rustc/90c541806f23a127002de5b4038be731ba1458ca\\library\\std\\src\\rt.rs:165\n  18: invoke_main\n             at D:\\a\\_work\\1\\s\\src\\vctools\\crt\\vcstartup\\src\\startup\\exe_common.inl:78\n  19: __scrt_common_main_seh\n             at D:\\a\\_work\\1\\s\\src\\vctools\\crt\\vcstartup\\src\\startup\\exe_common.inl:288\n  20: BaseThreadInitThunk\n  21: RtlGetAppContainerNamedObjectPath\n  22: RtlGetAppContainerNamedObjectPath\n"
    }
  ],
  "result": {
    "code": 65,
    "message": "Invalid browser name: BAD",
    "driver_path": "",
    "browser_path": ""
  }
}

Error in SM. Without --backtrace, the error is not captured:

./selenium-manager --debug --browser BAD --output json

{
  "logs": [
    {
      "level": "ERROR",
      "timestamp": 1696323973,
      "message": "Invalid browser name: BAD"
    }
  ],
  "result": {
    "code": 65,
    "message": "Invalid browser name: BAD",
    "driver_path": "",
    "browser_path": ""
  }
}

@codecov-commenter
Copy link

codecov-commenter commented Oct 3, 2023

Codecov Report

All modified lines are covered by tests ✅

Comparison is base (bceee4e) 56.51% compared to head (892e21f) 56.51%.

❗ Current head 892e21f differs from pull request most recent head 40f82d0. Consider uploading reports for the commit 40f82d0 to get more accurate results

❗ Your organization needs to install the Codecov GitHub app to enable full functionality.

Additional details and impacted files
@@           Coverage Diff           @@
##            trunk   #12852   +/-   ##
=======================================
  Coverage   56.51%   56.51%           
=======================================
  Files          86       86           
  Lines        5255     5255           
  Branches      187      187           
=======================================
  Hits         2970     2970           
  Misses       2098     2098           
  Partials      187      187           

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@bonigarcia
Copy link
Member Author

Having said that, the use of --backtrace in the bindings is optional, as I see it. We have two options:

  1. We can add --backtrace in the bindings when logging is enabled (i.e., in addition to --debug).
  2. We can keep this mechanism for complex troubleshooting issues. If a user reports something complicated to trace (like Permission denied (os error 13)), we can first say to enable logging in the bindings. If the log information is insufficient, we can get the backtrace by setting SE_BACKTRACE=true (or using the config file).

@bonigarcia bonigarcia changed the title [rust] Capture backtrace in case of error [rust] Include --backtrace argument to capture Rust backtrace in case of error Oct 3, 2023
@titusfortner
Copy link
Member

I don't know why I wouldn't always want to know the error when --debug is passed. Can't we just make that the default behavior without the need for --backtrace?

@diemol
Copy link
Member

diemol commented Oct 3, 2023

I agree with @titusfortner. If we get an error, we should add the stack trace (or backtrace). I do not see the need for a new flag.

@bonigarcia
Copy link
Member Author

I added the --backtrace argument because, in most cases, the backtrace info is not strictly required to trace a problem and is quite verbose. But indeed, if we prefer, it can be removed and display the backtrace (at DEBUG level) by default when any error is captured.

So, I did it that way. That change is already part of the PR, so no --backtrace is part of it.

I continue working on this. Yesterday, I discovered that RUST_BACKTRACE=1 seems mandatory to capture the backtrace through anyhow. I will let you know my conclusions.

@bonigarcia bonigarcia changed the title [rust] Include --backtrace argument to capture Rust backtrace in case of error [rust] Capture Rust backtrace in case of error (displayed at DEBUG level) Oct 4, 2023
@bonigarcia
Copy link
Member Author

bonigarcia commented Oct 4, 2023

@diemol @titusfortner

I continued working in this PR to capture the backtrace by default if error. But applied to #12828, I discovered that for capturing the backtrace, the debug symbols need to be included in the release artifacts, and the strip optimization needs to be removed (see modified Cargo.toml):

The problem with this change is the size of the resulting binaries. It is nothing in Windows, but a lot in macOS, and especially Linux. The resulting binaries with debug symbols are as follows (see workflow):

selenium-manager_linux-x64 58.1 MB
selenium-manager_macos-universal 13.3 MB
selenium-manager_windows-x32 3.55 MB

This size increase is not acceptable, IMO, since we are just trying to add a better troubleshooting mechanism (which is not required in many cases).

My recommendation is the following. Since we already have the PR for capturing the backtrace, let's merge it, just in case. It will not work by default, and to enable it, we need to do the following:

  1. Export RUST_BACKTRACE=1
  2. Generate a release binary including the debug symbols. This binary will be shared with the user in case some difficult problem happens.

We will only use it for troubleshooting rare cases (like Permission denied (os error 13)).

@titusfortner
Copy link
Member

Wow, right, we don't want those sizes. Would it make sense to generate both standard and Debug binaries in the github action?

@diemol
Copy link
Member

diemol commented Oct 5, 2023

Generating both types of binaries sounds like a good idea. Where would we leave the debug ones?

@titusfortner
Copy link
Member

If it's only for troubleshooting, we can probably just leave them on GH, but have easy access to it when needed— https://github.com/SeleniumHQ/selenium/actions/workflows/build-selenium-manager.yml?query=branch%3Atrunk

@bonigarcia
Copy link
Member Author

Generating the debug SM binaries in GH Actions is a good idea. I have created a new feature request to track this: #12887.

@titusfortner
Copy link
Member

So the code for this PR won't be used in production built binaries, but is necessary for the Debug binaries if we need to troubleshoot something?

@bonigarcia
Copy link
Member Author

Yes, this PR should not make any difference with respect to the production SM binaries.

The changes included in this changes are:

  • Use of anyhow crate to easily gather backtrace. In addition, this crate will allow to include more context for existing errors (e.g., as explained in [🐛 Bug]: OpenQA.Selenium.NoSuchDriverException  #12675 (comment))
  • Print backtrace when some error is captured and RUST_BACKTRACE=1. This will only happen on demand for troubleshooting difficult cases. And for that, the SM binaries with debug symbols will be necessary (I still need to modify the workflow to create these binaries).

In summary, this PR can be safely merged (I have just rebased it, and it is ready now).

@titusfortner titusfortner merged commit c8d121e into trunk Oct 9, 2023
49 of 52 checks passed
@titusfortner titusfortner deleted the sm_anyhow branch October 9, 2023 11:49
aguspe pushed a commit to aguspe/selenium that referenced this pull request Oct 22, 2023
…vel) (SeleniumHQ#12852)

* [rust] Use anyhow crate to display backtrace in case of error

* [rust] Include --backtrace argument to enable backtrace capture

* [rust] Use --backtrace argument in test

* [rust] Enable using RUST_BACKTRACE to capture backtrace as well

* [rust] Remove --backtrace (display backtrace when error is available at DEBUG level)

* [rust] Include debug info in release artifact and enable backtrace by default

* Revert "[rust] Include debug info in release artifact and enable backtrace by default"

This reverts commit aa57f2a.

* [rust] Remove backtrace for warning message

* [rust] Remove --backtrace from test

* [rust] Fix problems after rebasing

* [rust] Update bazel lock file

* [rust] Remove old download browser function in edge module
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
Status: Done
Development

Successfully merging this pull request may close these issues.

4 participants