Added error reporting code to track down #4856

Report breadcrumbs for:
  - Syncing
  - History DB operations that delete rows.
  - The delete_everything transaction

Added code to report errors from `delete_everything_history`.

Added changelog entry

CHANGES_UNRELEASED.md

@@ -18,3 +18,9 @@ Use the template below to make assigning a version number during the release cut
   - Description of the change with a link to the pull request ([#0000](https://github.com/mozilla/application-services/pull/0000))
 
 -->
+
+## Error-support
+### What's New
+  - Added a new error reporting system that is intended to eventually replace using `log::error` to report errors
+  - Added code using the new system to track down application-services#4856
+  - Added UniFFI API for this crate.  Consumers should use this to register for error reports and breadcrumbs.

Cargo.lock

@@ -3382,6 +3382,7 @@ version = "0.1.0"
 dependencies = [
  "anyhow",
  "autofill",
+ "error-support",
  "interrupt-support",
  "lazy_static",
  "log",

components/places/src/ffi.rs

@@ -23,6 +23,7 @@ use crate::ConnectionType;
 use crate::VisitObservation;
 use crate::VisitTransition;
 use crate::{PlacesApi, PlacesDb};
+use error_support::report_error;
 use interrupt_support::{register_interrupt, SqlInterruptHandle};
 use parking_lot::Mutex;
 use std::sync::Arc;
@@ -398,7 +399,18 @@ impl PlacesConnection {
     // sync metadata to only sync after most recent visit to prevent
     // further syncing of older data
     fn delete_everything_history(&self) -> Result<()> {
-        self.with_conn(history::delete_everything)
+        // Do some extra work to track down #4856
+        let conn = self.db.lock();
+        let result = history::delete_everything(&conn);
+        if let Err(e) = &result {
+            if matches!(
+                e.kind(),
+                crate::error::ErrorKind::SqlError(rusqlite::Error::QueryReturnedNoRows)
+            ) {
+                report_error!("SqlErrorQueryReturnedNoRows", "{}", e);
+            }
+        }
+        Ok(result?)
     }
 
     // XXX - This just calls wipe_local under the hood...

components/places/src/frecency.rs

@@ -4,6 +4,7 @@
 
 use crate::error::*;
 use crate::types::VisitTransition;
+use error_support::trace_error;
 use rusqlite::Connection;
 use types::Timestamp;
 
@@ -150,7 +151,8 @@ impl<'db, 's> FrecencyComputation<'db, 's> {
         ",
         )?;
         let mut rows = stmt.query(&[(":page_id", &page_id)])?;
-        let row = rows.next()?.ok_or(rusqlite::Error::QueryReturnedNoRows)?;
+        // trace_error to track down #4856
+        let row = trace_error!(rows.next()?.ok_or(rusqlite::Error::QueryReturnedNoRows))?;
         let typed: i32 = row.get("typed")?;
         let visit_count: i32 = row.get("visit_count")?;
         let foreign_count: i32 = row.get("foreign_count")?;

components/places/src/storage/history.rs

@@ -16,6 +16,7 @@ use crate::storage::{
     delete_meta, delete_pending_temp_tables, get_meta, history_metadata, put_meta,
 };
 use crate::types::{SyncStatus, VisitTransition, VisitTransitionSet};
+use error_support::breadcrumb;
 use rusqlite::types::ToSql;
 use rusqlite::Result as RusqliteResult;
 use rusqlite::Row;
@@ -351,6 +352,8 @@ fn insert_tombstone_for_page(db: &PlacesDb, guid: &SyncGuid) -> Result<()> {
 /// Deletes a page. Note that this throws a constraint violation if the page is
 /// bookmarked, or has a keyword or tags.
 fn delete_page(db: &PlacesDb, page_id: RowId) -> Result<()> {
+    // breadcrumb to track down #4856
+    breadcrumb!("delete places page: {}", page_id);
     db.execute_cached(
         "DELETE FROM moz_places
          WHERE id = :page_id",
@@ -407,6 +410,8 @@ pub fn wipe_local(db: &PlacesDb) -> Result<()> {
 
 fn wipe_local_in_tx(db: &PlacesDb) -> Result<()> {
     use crate::frecency::DEFAULT_FRECENCY_SETTINGS;
+    // breadcrumb to track down #4856
+    breadcrumb!("places: wipe_local_in_tx");
     db.execute_all(&[
         "DELETE FROM moz_places WHERE foreign_count == 0",
         "DELETE FROM moz_places_metadata",
@@ -442,7 +447,10 @@ fn wipe_local_in_tx(db: &PlacesDb) -> Result<()> {
     Ok(())
 }
 
+#[allow(unreachable_code)]
 pub fn delete_everything(db: &PlacesDb) -> Result<()> {
+    // breadcrumb to track down #4856
+    breadcrumb!("places history delete_everything: starting transaction");
     let tx = db.begin_transaction()?;
 
     // Remote visits could have a higher date than `now` if our clock is weird.
@@ -466,6 +474,8 @@ pub fn delete_everything(db: &PlacesDb) -> Result<()> {
     reset_in_tx(db, &EngineSyncAssociation::Disconnected)?;
 
     tx.commit()?;
+    // breadcrumb to track down #4856
+    breadcrumb!("places history delete_everything: ending transaction");
 
     // Note: SQLite cannot VACUUM within a transaction.
     db.execute_batch("VACUUM")?;
@@ -634,6 +644,8 @@ impl PageToClean {
 /// are no more foreign keys such as bookmarks) or updating
 /// their frecency.
 fn cleanup_pages(db: &PlacesDb, pages: &[PageToClean]) -> Result<()> {
+    // breadcrumb to track down #4856
+    breadcrumb!("places cleanup_pages()");
     // desktop does this frecency work using a function in a single sql
     // statement - we should see if we can do that too.
     let frec_ids = pages
@@ -952,6 +964,8 @@ pub mod history_sync {
     }
 
     pub fn apply_synced_deletion(db: &PlacesDb, guid: &SyncGuid) -> Result<()> {
+        // breadcrumb to track down #4856
+        breadcrumb!("places apply_synced_deletion: {}", guid);
         db.execute_cached(
             "DELETE FROM moz_places WHERE guid = :guid",
             &[(":guid", guid)],

components/sync_manager/Cargo.toml

@@ -16,6 +16,7 @@ thiserror = "1.0"
 anyhow = "1.0"
 lazy_static = "1.4"
 log = "0.4"
+error-support = { path = "../support/error" }
 sql-support = { path = "../support/sql" }
 url = "2.2"
 serde = "1"

components/sync_manager/src/manager.rs

@@ -5,6 +5,7 @@
 use crate::error::*;
 use crate::types::{ServiceStatus, SyncEngineSelection, SyncParams, SyncReason, SyncResult};
 use crate::{reset, reset_all, wipe};
+use error_support::breadcrumb;
 use parking_lot::Mutex;
 use std::collections::{HashMap, HashSet};
 use std::convert::TryFrom;
@@ -63,6 +64,7 @@ impl SyncManager {
 
     /// Disconnect engines from sync, deleting/resetting the sync-related data
     pub fn disconnect(&self) {
+        breadcrumb!("SyncManager disconnect()");
         for engine_id in SyncEngineId::iter() {
             if let Some(engine) = Self::get_engine(&engine_id) {
                 if let Err(e) = engine.reset(&EngineSyncAssociation::Disconnected) {
@@ -76,14 +78,15 @@ impl SyncManager {
 
     /// Perform a sync.  See [SyncParams] and [SyncResult] for details on how this works
     pub fn sync(&self, params: SyncParams) -> Result<SyncResult> {
+        breadcrumb!("SyncManager::sync started");
         let mut state = self.mem_cached_state.lock();
         let engines = self.calc_engines_to_sync(&params.engines)?;
         let next_sync_after = state.as_ref().and_then(|mcs| mcs.get_next_sync_after());
-        if !backoff_in_effect(next_sync_after, &params) {
+        let result = if !backoff_in_effect(next_sync_after, &params) {
             log::info!("No backoff in effect (or we decided to ignore it), starting sync");
             self.do_sync(params, &mut state, engines)
         } else {
-            log::warn!(
+            breadcrumb!(
                 "Backoff still in effect (until {:?}), bailing out early",
                 next_sync_after
             );
@@ -97,7 +100,9 @@ impl SyncManager {
                 // It would be nice to record telemetry here.
                 telemetry_json: None,
             })
-        }
+        };
+        breadcrumb!("SyncManager sync ended");
+        result
     }
 
     fn do_sync(
@@ -198,7 +203,7 @@ impl SyncManager {
         selection: &SyncEngineSelection,
     ) -> Result<Vec<Box<dyn SyncEngine>>> {
         let mut engine_map: HashMap<_, _> = self.iter_registered_engines().collect();
-        log::trace!(
+        breadcrumb!(
             "Checking engines requested ({:?}) vs local engines ({:?})",
             selection,
             engine_map