Silence spammy blueprint warnings and validate blueprint on load (#4303)

### What
- Resolves: #4299

Adding a helper to silence the error messages only solved half the
problem. Nothing prevented this corrupt data from being removed from the
store, and worse, in some cases the corrupt data subsequently prevented
new writes.

We now validate that all the data in the blueprint has a valid schema or
else we refuse to load it.

### Checklist
* [x] I have read and agree to [Contributor
Guide](https://github.com/rerun-io/rerun/blob/main/CONTRIBUTING.md) and
the [Code of
Conduct](https://github.com/rerun-io/rerun/blob/main/CODE_OF_CONDUCT.md)
* [x] I've included a screenshot or gif (if applicable)
* [x] I have tested [demo.rerun.io](https://demo.rerun.io/pr/4303) (if
applicable)
* [x] The PR title and labels are set such as to maximize their
usefulness for the next release's CHANGELOG

- [PR Build Summary](https://build.rerun.io/pr/4303)
- [Docs
preview](https://rerun.io/preview/5a85ed646d8a7c585804909613689c461fa0929e/docs)
<!--DOCS-PREVIEW-->
- [Examples
preview](https://rerun.io/preview/5a85ed646d8a7c585804909613689c461fa0929e/examples)
<!--EXAMPLES-PREVIEW-->
- [Recent benchmark results](https://build.rerun.io/graphs/crates.html)
- [Wasm size tracking](https://build.rerun.io/graphs/sizes.html)

---------

Co-authored-by: Clement Rey <cr.rey.clement@gmail.com>

crates/re_arrow_store/src/store_helpers.rs

@@ -38,15 +38,16 @@ impl DataStore {
     /// Get the latest value for a given [`re_types_core::Component`] and the associated [`RowId`].
     ///
     /// This assumes that the row we get from the store only contains a single instance for this
-    /// component; it will log a warning otherwise.
+    /// component; it will generate a log message of `level` otherwise.
     ///
     /// This should only be used for "mono-components" such as `Transform` and `Tensor`.
     ///
-    /// This is a best-effort helper, it will merely log errors on failure.
-    pub fn query_latest_component<C: Component>(
+    /// This is a best-effort helper, it will merely log messages on failure.
+    pub fn query_latest_component_with_log_level<C: Component>(
         &self,
         entity_path: &EntityPath,
         query: &LatestAtQuery,
+        level: re_log::Level,
     ) -> Option<VersionedComponent<C>> {
         re_tracing::profile_function!();
 
@@ -63,14 +64,16 @@ impl DataStore {
 
                     let err = Box::new(err) as Box<dyn std::error::Error>;
                     if let Some(bt) = bt {
-                        re_log::error_once!(
+                        re_log::log_once!(
+                            level,
                             "Couldn't deserialize component at {entity_path}#{}: {}\n{:#?}",
                             C::name(),
                             re_error::format(&err),
                             bt,
                         );
                     } else {
-                        re_log::error_once!(
+                        re_log::log_once!(
+                            level,
                             "Couldn't deserialize component at {entity_path}#{}: {}",
                             C::name(),
                             re_error::format(&err)
@@ -80,7 +83,8 @@ impl DataStore {
                 }
 
                 let err = Box::new(err) as Box<dyn std::error::Error>;
-                re_log::error_once!(
+                re_log::log_once!(
+                    level,
                     "Couldn't deserialize component at {entity_path}#{}: {}",
                     C::name(),
                     re_error::format(&err)
@@ -92,6 +96,40 @@ impl DataStore {
             .map(|c| (row_id, c).into())
     }
 
+    /// Get the latest value for a given [`re_types_core::Component`] and the associated [`RowId`].
+    ///
+    /// This assumes that the row we get from the store only contains a single instance for this
+    /// component; it will log a warning otherwise.
+    ///
+    /// This should only be used for "mono-components" such as `Transform` and `Tensor`.
+    ///
+    /// This is a best-effort helper, it will merely log errors on failure.
+    #[inline]
+    pub fn query_latest_component<C: Component>(
+        &self,
+        entity_path: &EntityPath,
+        query: &LatestAtQuery,
+    ) -> Option<VersionedComponent<C>> {
+        self.query_latest_component_with_log_level(entity_path, query, re_log::Level::Warn)
+    }
+
+    /// Get the latest value for a given [`re_types_core::Component`] and the associated [`RowId`].
+    ///
+    /// This assumes that the row we get from the store only contains a single instance for this
+    /// component; it will return None and log a debug message otherwise.
+    ///
+    /// This should only be used for "mono-components" such as `Transform` and `Tensor`.
+    ///
+    /// This is a best-effort helper, it will merely logs debug messages on failure.
+    #[inline]
+    pub fn query_latest_component_quiet<C: Component>(
+        &self,
+        entity_path: &EntityPath,
+        query: &LatestAtQuery,
+    ) -> Option<VersionedComponent<C>> {
+        self.query_latest_component_with_log_level(entity_path, query, re_log::Level::Debug)
+    }
+
     /// Call [`Self::query_latest_component`] at the given path, walking up the hierarchy until an instance is found.
     pub fn query_latest_component_at_closest_ancestor<C: Component>(
         &self,
@@ -127,6 +165,24 @@ impl DataStore {
         let query = LatestAtQuery::latest(Timeline::default());
         self.query_latest_component(entity_path, &query)
     }
+
+    /// Get the latest value for a given [`re_types_core::Component`] and the associated [`RowId`], assuming it is timeless.
+    ///
+    /// This assumes that the row we get from the store only contains a single instance for this
+    /// component; it will return None and log a debug message otherwise.
+    ///
+    /// This should only be used for "mono-components" such as `Transform` and `Tensor`.
+    ///
+    /// This is a best-effort helper, it will merely log debug on failure.
+    pub fn query_timeless_component_quiet<C: Component>(
+        &self,
+        entity_path: &EntityPath,
+    ) -> Option<VersionedComponent<C>> {
+        re_tracing::profile_function!();
+
+        let query = LatestAtQuery::latest(Timeline::default());
+        self.query_latest_component_quiet(entity_path, &query)
+    }
 }
 
 // --- Write ---

crates/re_log/src/lib.rs

@@ -30,7 +30,7 @@ pub use tracing::{debug, error, info, trace, warn};
 // The `re_log::info_once!(…)` etc are nice helpers, but the `log-once` crate is a bit lacking.
 // In the future we should implement our own macros to de-duplicate based on the callsite,
 // similar to how the log console in a browser will automatically suppress duplicates.
-pub use log_once::{debug_once, error_once, info_once, trace_once, warn_once};
+pub use log_once::{debug_once, error_once, info_once, log_once, trace_once, warn_once};
 
 pub use {
     channel_logger::*,

crates/re_viewer/src/app_blueprint.rs

@@ -130,6 +130,6 @@ fn load_panel_state(path: &EntityPath, blueprint_db: &re_data_store::StoreDb) ->
     re_tracing::profile_function!();
     blueprint_db
         .store()
-        .query_timeless_component::<PanelView>(path)
+        .query_timeless_component_quiet::<PanelView>(path)
         .map(|p| p.is_expanded)
 }

crates/re_viewer/src/blueprint_validation.rs

@@ -0,0 +1,62 @@
+use re_arrow_store::LatestAtQuery;
+use re_data_store::{EntityPropertiesComponent, StoreDb};
+use re_log_types::Timeline;
+use re_types_core::Component;
+use re_viewport::{
+    blueprint::{AutoSpaceViews, SpaceViewComponent, SpaceViewMaximized, ViewportLayout},
+    external::re_space_view::QueryExpressions,
+};
+
+use crate::blueprint::PanelView;
+
+fn validate_component<C: Component>(blueprint: &StoreDb) -> bool {
+    let query = LatestAtQuery::latest(Timeline::default());
+
+    if let Some(data_type) = blueprint.entity_db().data_store.lookup_datatype(&C::name()) {
+        if data_type != &C::arrow_datatype() {
+            // If the schemas don't match, we definitely have a problem
+            re_log::debug!(
+                "Unexpected datatype for component {:?}.\nFound: {:#?}\nExpected: {:#?}",
+                C::name(),
+                data_type,
+                C::arrow_datatype()
+            );
+            return false;
+        } else {
+            // Otherwise, our usage of serde-fields means we still might have a problem
+            // this can go away once we stop using serde-fields.
+            // Walk the blueprint and see if any cells fail to deserialize for this component type.
+            for path in blueprint.entity_db().entity_paths() {
+                if let Some([Some(cell)]) = blueprint
+                    .entity_db()
+                    .data_store
+                    .latest_at(&query, path, C::name(), &[C::name()])
+                    .map(|(_, cells)| cells)
+                {
+                    if let Err(err) = cell.try_to_native_mono::<C>() {
+                        re_log::debug!(
+                            "Failed to deserialize component {:?}: {:?}",
+                            C::name(),
+                            err
+                        );
+                        return false;
+                    }
+                }
+            }
+        }
+    }
+    true
+}
+
+/// Because blueprints are both read and written the schema must match what
+/// we expect to find or else we will run into all kinds of problems.
+pub fn is_valid_blueprint(blueprint: &StoreDb) -> bool {
+    // TODO(jleibs): Generate this from codegen.
+    validate_component::<AutoSpaceViews>(blueprint)
+        && validate_component::<EntityPropertiesComponent>(blueprint)
+        && validate_component::<PanelView>(blueprint)
+        && validate_component::<QueryExpressions>(blueprint)
+        && validate_component::<SpaceViewComponent>(blueprint)
+        && validate_component::<SpaceViewMaximized>(blueprint)
+        && validate_component::<ViewportLayout>(blueprint)
+}

crates/re_viewer/src/lib.rs

@@ -7,6 +7,8 @@ mod app;
 mod app_blueprint;
 mod app_state;
 mod background_tasks;
+#[cfg(not(target_arch = "wasm32"))]
+mod blueprint_validation;
 pub mod env_vars;
 #[cfg(not(target_arch = "wasm32"))]
 mod loading;

crates/re_viewer/src/store_hub.rs

@@ -319,6 +319,8 @@ impl StoreHub {
         &mut self,
         app_id: &ApplicationId,
     ) -> anyhow::Result<()> {
+        use crate::blueprint_validation::is_valid_blueprint;
+
         re_tracing::profile_function!();
         let blueprint_path = default_blueprint_path(app_id)?;
         if blueprint_path.exists() {
@@ -329,6 +331,10 @@ impl StoreHub {
                 for store in bundle.drain_store_dbs() {
                     if store.store_kind() == StoreKind::Blueprint && store.app_id() == Some(app_id)
                     {
+                        if !is_valid_blueprint(&store) {
+                            re_log::warn!("Blueprint for {app_id} appears invalid - restoring to default. This is expected if you have just upgraded Rerun versions.");
+                            continue;
+                        }
                         // We found the blueprint we were looking for; make it active.
                         // borrow-checker won't let us just call `self.set_blueprint_for_app_id`
                         re_log::debug!(

crates/re_viewport/src/space_view.rs

@@ -360,7 +360,7 @@ impl SpaceViewBlueprint {
         let individual_properties = ctx
             .blueprint
             .store()
-            .query_timeless_component::<EntityPropertiesComponent>(&self.entity_path())
+            .query_timeless_component_quiet::<EntityPropertiesComponent>(&self.entity_path())
             .map(|result| result.value.props);
 
         let resolved_properties = individual_properties.clone().unwrap_or_else(|| {
@@ -401,7 +401,7 @@ impl SpaceViewBlueprint {
             tree.visit_children_recursively(&mut |path: &EntityPath| {
                 if let Some(props) = blueprint
                     .store()
-                    .query_timeless_component::<EntityPropertiesComponent>(path)
+                    .query_timeless_component_quiet::<EntityPropertiesComponent>(path)
                 {
                     let overridden_path =
                         EntityPath::from(&path.as_slice()[props_path.len()..path.len()]);

crates/re_viewport/src/viewport_blueprint.rs

@@ -334,7 +334,7 @@ pub fn load_space_view_blueprint(
 
     let mut space_view = blueprint_db
         .store()
-        .query_timeless_component::<SpaceViewComponent>(path)
+        .query_timeless_component_quiet::<SpaceViewComponent>(path)
         .map(|c| c.value.space_view);
 
     // Blueprint data migrations can leave us unable to parse the expected id from the source-data
@@ -374,7 +374,7 @@ pub fn load_viewport_blueprint(blueprint_db: &re_data_store::StoreDb) -> Viewpor
 
     let auto_space_views = blueprint_db
         .store()
-        .query_timeless_component::<AutoSpaceViews>(&VIEWPORT_PATH.into())
+        .query_timeless_component_quiet::<AutoSpaceViews>(&VIEWPORT_PATH.into())
         .map_or_else(
             || {
                 // Only enable auto-space-views if this is the app-default blueprint
@@ -389,13 +389,13 @@ pub fn load_viewport_blueprint(blueprint_db: &re_data_store::StoreDb) -> Viewpor
 
     let space_view_maximized = blueprint_db
         .store()
-        .query_timeless_component::<SpaceViewMaximized>(&VIEWPORT_PATH.into())
+        .query_timeless_component_quiet::<SpaceViewMaximized>(&VIEWPORT_PATH.into())
         .map(|space_view| space_view.value)
         .unwrap_or_default();
 
     let viewport_layout: ViewportLayout = blueprint_db
         .store()
-        .query_timeless_component::<ViewportLayout>(&VIEWPORT_PATH.into())
+        .query_timeless_component_quiet::<ViewportLayout>(&VIEWPORT_PATH.into())
         .map(|space_view| space_view.value)
         .unwrap_or_default();