Finda is a Rust application that uses Electron to draw its user interface. This architecture has been great: Rust enables excellent performance and Electron handles the details of OS interop and complex GUI concerns like shaping non-ASCII text and respecting native input mechanisms. (See this blog post for more details).
However, since this architecture is a bit unorthodox (or at least, doesn’t match either “Hello World” of a JavaScript Electron app or Rust command line binary), it took a bit of work to setup proper logging.
This article covers the design considerations and technical details of Finda’s logging mechanisms, in case it’d be useful to others building similar applications. We’ll end with the debugging story that motivated the logging.
Privacy Considerations
Before getting into the technical details, it’s worth noting Finda’s strong privacy stance: Finda never communicates with our servers for any reason. It never checks for updates (nor, an even worse user experience, does Finda automatically download and install updates).
This design requirement means that Finda can’t leverage Electron’s automatic crash reporter.
Instead, Finda relies on customers to email when they encounter any problems.
While this reduces the total number of reported errors, it vastly increases the “signal to noise ratio” of the reports: All reported issues sufficiently affect the user experience for at least one person to take the time to report it!
Several early customers mentioned that they tried to diagnose problems with Finda by looking for errors in OS X’s Console.app. So how can we make sure errors are logged there?
Error logging in Rust
All of Finda’s application logic — tracking open tabs, scanning browser history results, indexing your file system, etc. — is implemented in Rust. The Electron portion just handles input keystrokes and renders the results.
As such, we expect most errors to occur within the Rust code, which will be the focus of this article.
In a single-threaded command line binary, error reporting is straightforward: Panics are simply printed to stderr.
But for a GUI app like Finda, there is no stderr visible to the user, so we have to log the panics elsewhere. For them to show up in OS X’s Console.app, they must be logged to syslog.
To do this, we’ll need to use two crates: log, Rust’s generic logging facade, and syslog, which actually implements logging to OS X’s syslog.
Add these lines to Cargo.toml:
log = "0.4"
syslog = "4.0.0"
Then on application startup we can initialize this logging backend:
#[macro_use]
extern crate log;
use log::LevelFilter;
extern crate syslog;
use syslog::Facility;
fn main(){
// Setup logging
syslog::init(Facility::LOG_USER, LevelFilter::Debug, Some("Finda")).unwrap();
//... rest of application goes here
}
Note that we’re explicitly providing the application name as an argument to syslog.
But this is just the logging infrastructure — what we need to do is make sure we actually log whenever a thread panics.
We could do this ourselves using the std::panic::set_hook() function, but there’s actually a great lil’ crate that’ll save us this bit of typing, the aptly named log panics crate.
Since we want the log messages to include backtraces, we’ll have to enable that flag when we add this crate to our Cargo.toml:
[dependencies.log-panics]
version = "2.0.0"
features = ["with-backtrace"]
Then we just initialize this crate along with the rest of the logging functionality, which brings us to:
#[macro_use]
extern crate log;
use log::LevelFilter;
extern crate syslog;
use syslog::Facility;
extern crate log_panics;
fn main(){
// Setup logging
syslog::init(Facility::LOG_USER, LevelFilter::Debug, Some("Finda")).unwrap();
log_panics::init();
//... rest of application goes here
}
Finally, it’d be nice to have line numbers reported in the backtraces (instead of just addresses), so we need to tell Rust to include debug information in the release build; Add to Cargo.toml:
[profile.release]
debug = true
(Note: I could get line numbers in backtraces for regular Rust CLI builds, but not Neon builds for native Electron extensions — if you have any ideas or want to see a clonable example repository, see the neon issue.)
And with that, any panics will be automatically logged and will show up in OS X’s Console.app, where users can find and report them via email.
Backstory
I must be honest with you, dear reader: I neglected these details of logging infrastructure for the first few months after Finda’s public release. Instead, I happily spent my time implementing new features requested by customers and improving Finda’s performance.
However my hand was forced after two customers reported that their browser histories weren’t appearing in their search results. But aside from that, everything else worked fine — there were no hard crashes, error messages, etc.
My attempts to reproduce the issue were fruitless, and I talked with several other customers, none of whom were having any trouble — history results from Chrome and Firefox consistently appeared for everyone else. (In fact, one of the reporting customers said that he had the same version of Finda on two of his computers — it worked fine on one, but not the other!)
I suspected that the browsers might be running an A/B test that broke the history storage format. However, I couldn’t find any mention in the Chromium or the Firefox commit logs, nor did it seem likely that both browsers would have changed their storage file format at the same time.
When I began to refactor the code that handled indexing browser history results, I discovered the problem:
for profile_root in firefox_home.read_dir().unwrap().filter_map(Result::ok) {
//Index history from this Firefox profile...
}
This code tries to iterate over every folder in ~/Library/Application Support/Firefox/Profiles/, since Finda indexes history results from every Firefox profile.
The read_dir() function returns a Result of an iterator.
So to access the iterator, one must either handle both the success and failure cases explicitly, or (as I did) use unwrap() to assert that the call will always succeed and please just give me the result.
My LISPy self had assumed that if the parent folder didn’t exist, I’d get an “empty” iterator, but (as is clearly documented), “This function will return an error in the following situations […] The provided path doesn’t exist”.
So the unwrap() was causing the thread to panic.
Since this thread handled all history results, when it panicked it meant that neither Firefox nor Chrome search results would be found.
(Finda remained fine otherwise because this panic only affected the thread responsible for indexing browser history, not the threads responsible for processing queries or returning data to the Electron GUI.)
This error also explains why the problem was difficult to reproduce: It only occurred on computers that did not have Firefox installed!
The fix itself was simple: Check that the Firefox profile directory exists before iterating over its children.
Both this fix and the improved logging were released in Finda 468, check it out!