From fbc62ea51e1322f86da739a302446d1b5bab110a Mon Sep 17 00:00:00 2001 From: Firstyear Date: Wed, 11 Oct 2023 21:14:27 +1000 Subject: [PATCH] fix RUV on startup, improve filter output (#2211) --- server/core/src/actors/v1_write.rs | 2 +- server/core/src/lib.rs | 6 +- server/lib/src/filter.rs | 134 ++++++++++++++++++++++++++++- server/lib/src/idm/oauth2.rs | 4 +- server/lib/src/repl/cid.rs | 9 +- server/lib/src/repl/ruv.rs | 26 +++++- server/lib/src/server/recycle.rs | 2 +- server/lib/src/valueset/mod.rs | 4 +- 8 files changed, 167 insertions(+), 20 deletions(-) diff --git a/server/core/src/actors/v1_write.rs b/server/core/src/actors/v1_write.rs index 828ad8962..a8120780b 100644 --- a/server/core/src/actors/v1_write.rs +++ b/server/core/src/actors/v1_write.rs @@ -41,7 +41,7 @@ pub struct QueryServerWriteV1 { impl QueryServerWriteV1 { pub fn new(idms: Arc) -> Self { - info!("Starting query server v1 worker ..."); + debug!("Starting a query server v1 worker ..."); QueryServerWriteV1 { idms } } diff --git a/server/core/src/lib.rs b/server/core/src/lib.rs index f255565a9..6e7ed91c7 100644 --- a/server/core/src/lib.rs +++ b/server/core/src/lib.rs @@ -778,11 +778,7 @@ impl CoreHandle { // Wait on the handles. while let Some((handle_name, handle)) = self.handles.pop() { if let Err(error) = handle.await { - eprintln!( - "Task {} failed to finish: {:?}", - handle_name, - error - ); + eprintln!("Task {} failed to finish: {:?}", handle_name, error); } } diff --git a/server/lib/src/filter.rs b/server/lib/src/filter.rs index e2b9fd6af..4ebcfdab4 100644 --- a/server/lib/src/filter.rs +++ b/server/lib/src/filter.rs @@ -10,6 +10,7 @@ use std::cmp::{Ordering, PartialOrd}; use std::collections::BTreeSet; +use std::fmt; use std::hash::Hash; use std::iter; use std::num::NonZeroU8; @@ -111,7 +112,7 @@ pub enum FC<'a> { } /// This is the filters internal representation -#[derive(Debug, Clone, Hash, PartialEq, PartialOrd, Ord, Eq)] +#[derive(Clone, Hash, PartialEq, PartialOrd, Ord, Eq)] enum FilterComp { // This is attr - value Eq(AttrString, PartialValue), @@ -127,6 +128,61 @@ enum FilterComp { // Not(Box), } +impl fmt::Debug for FilterComp { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self { + FilterComp::Eq(attr, pv) => { + write!(f, "{} eq {:?}", attr, pv) + } + FilterComp::Sub(attr, pv) => { + write!(f, "{} sub {:?}", attr, pv) + } + FilterComp::Pres(attr) => { + write!(f, "{} pres", attr) + } + FilterComp::LessThan(attr, pv) => { + write!(f, "{} lt {:?}", attr, pv) + } + FilterComp::And(list) => { + write!(f, "(")?; + for (i, fc) in list.iter().enumerate() { + write!(f, "{:?}", fc)?; + if i != list.len() - 1 { + write!(f, " and ")?; + } + } + write!(f, ")") + } + FilterComp::Or(list) => { + write!(f, "(")?; + for (i, fc) in list.iter().enumerate() { + write!(f, "{:?}", fc)?; + if i != list.len() - 1 { + write!(f, " or ")?; + } + } + write!(f, ")") + } + FilterComp::Inclusion(list) => { + write!(f, "(")?; + for (i, fc) in list.iter().enumerate() { + write!(f, "{:?}", fc)?; + if i != list.len() - 1 { + write!(f, " inc ")?; + } + } + write!(f, ")") + } + FilterComp::AndNot(inner) => { + write!(f, "and not ( {:?} )", inner) + } + FilterComp::SelfUuid => { + write!(f, "uuid eq self") + } + } + } +} + /// This is the fully resolved internal representation. Note the lack of Not and selfUUID /// because these are resolved into And(Pres(class), AndNot(term)) and Eq(uuid, ...). /// Importantly, we make this accessible to Entry so that it can then match on filters @@ -137,7 +193,7 @@ enum FilterComp { /// where small value - faster index, larger value - slower index. This metadata is extremely /// important for the query optimiser to make decisions about how to re-arrange queries /// correctly. -#[derive(Debug, Clone, Eq)] +#[derive(Clone, Eq)] pub enum FilterResolved { // This is attr - value - indexed slope factor Eq(AttrString, PartialValue, Option), @@ -151,6 +207,58 @@ pub enum FilterResolved { AndNot(Box, Option), } +impl fmt::Debug for FilterResolved { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self { + FilterResolved::Eq(attr, pv, idx) => { + write!(f, "{} ({:?}) eq {:?}", attr, idx, pv) + } + FilterResolved::Sub(attr, pv, idx) => { + write!(f, "{} ({:?}) sub {:?}", attr, idx, pv) + } + FilterResolved::Pres(attr, idx) => { + write!(f, "{} ({:?}) pres", attr, idx) + } + FilterResolved::LessThan(attr, pv, idx) => { + write!(f, "{} ({:?}) lt {:?}", attr, idx, pv) + } + FilterResolved::And(list, idx) => { + write!(f, "({:?} ", idx)?; + for (i, fc) in list.iter().enumerate() { + write!(f, "{:?}", fc)?; + if i != list.len() - 1 { + write!(f, " and ")?; + } + } + write!(f, ")") + } + FilterResolved::Or(list, idx) => { + write!(f, "({:?} ", idx)?; + for (i, fc) in list.iter().enumerate() { + write!(f, "{:?}", fc)?; + if i != list.len() - 1 { + write!(f, " or ")?; + } + } + write!(f, ")") + } + FilterResolved::Inclusion(list, idx) => { + write!(f, "({:?} ", idx)?; + for (i, fc) in list.iter().enumerate() { + write!(f, "{:?}", fc)?; + if i != list.len() - 1 { + write!(f, " inc ")?; + } + } + write!(f, ")") + } + FilterResolved::AndNot(inner, idx) => { + write!(f, "and not ({:?} {:?} )", idx, inner) + } + } + } +} + #[derive(Debug, Clone, PartialEq, Eq)] pub struct FilterInvalid { inner: FilterComp, @@ -161,7 +269,7 @@ pub struct FilterValid { inner: FilterComp, } -#[derive(Debug, Clone, PartialEq, Eq)] +#[derive(Clone, PartialEq, Eq)] pub struct FilterValidResolved { inner: FilterResolved, } @@ -214,11 +322,29 @@ pub enum FilterPlan { /// helps to prevent errors at compile time to assert `Filters` are secuerly. checked /// /// [`Entry`]: ../entry/struct.Entry.html -#[derive(Debug, Clone, Hash, Ord, Eq, PartialOrd, PartialEq)] +#[derive(Clone, Hash, Ord, Eq, PartialOrd, PartialEq)] pub struct Filter { state: STATE, } +impl fmt::Debug for Filter { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + writeln!(f, "Filter(Valid) {:?}", self.state.inner) + } +} + +impl fmt::Debug for Filter { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + writeln!(f, "Filter(Valid) {:?}", self.state.inner) + } +} + +impl fmt::Debug for Filter { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + writeln!(f, "Filter(Invalid) {:?}", self.state.inner) + } +} + impl Filter { // Does this need mut self? Aren't we returning // a new copied filter? diff --git a/server/lib/src/idm/oauth2.rs b/server/lib/src/idm/oauth2.rs index fd09f2f96..2aa1c6e5d 100644 --- a/server/lib/src/idm/oauth2.rs +++ b/server/lib/src/idm/oauth2.rs @@ -319,10 +319,10 @@ impl<'a> Oauth2ResourceServersWriteTransaction<'a> { .into_iter() .map(|ent| { let uuid = ent.get_uuid(); - admin_info!(?uuid, "Checking oauth2 configuration"); + trace!(?uuid, "Checking oauth2 configuration"); // From each entry, attempt to make an oauth2 configuration. if !ent.attribute_equality(Attribute::Class, &EntryClass::OAuth2ResourceServer.into()) { - admin_error!("Missing class oauth2_resource_server"); + error!("Missing class oauth2_resource_server"); // Check we have oauth2_resource_server class return Err(OperationError::InvalidEntryState); } diff --git a/server/lib/src/repl/cid.rs b/server/lib/src/repl/cid.rs index 99e038cf5..f198e179a 100644 --- a/server/lib/src/repl/cid.rs +++ b/server/lib/src/repl/cid.rs @@ -6,7 +6,7 @@ use crate::prelude::*; use kanidm_proto::v1::OperationError; use serde::{Deserialize, Serialize}; -#[derive(Serialize, Deserialize, Debug, PartialEq, Clone, Eq, PartialOrd, Ord, Hash)] +#[derive(Serialize, Deserialize, PartialEq, Clone, Eq, PartialOrd, Ord, Hash)] pub struct Cid { // Mental note: Derive ord always checks in order of struct fields. pub ts: Duration, @@ -27,6 +27,12 @@ impl From for Cid { } } +impl fmt::Debug for Cid { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "{:032}-{}", self.ts.as_nanos(), self.s_uuid) + } +} + impl fmt::Display for Cid { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { write!(f, "{:032}-{}", self.ts.as_nanos(), self.s_uuid) @@ -34,7 +40,6 @@ impl fmt::Display for Cid { } impl Cid { - #[cfg(test)] pub(crate) fn new(s_uuid: Uuid, ts: Duration) -> Self { Cid { s_uuid, ts } } diff --git a/server/lib/src/repl/ruv.rs b/server/lib/src/repl/ruv.rs index 720c2df0f..26aab01a9 100644 --- a/server/lib/src/repl/ruv.rs +++ b/server/lib/src/repl/ruv.rs @@ -232,7 +232,8 @@ impl<'a> fmt::Debug for ReplicationUpdateVectorWriteTransaction<'a> { writeln!(f, "RUV RANGE DUMP")?; self.ranged .iter() - .try_for_each(|(s_uuid, ts)| writeln!(f, "* [{s_uuid} {ts:?}]")) + .flat_map(|(s_uuid, ts_set)| ts_set.iter().map(|ts| Cid::new(*s_uuid, *ts))) + .try_for_each(|cid| writeln!(f, "[{cid}]")) } } @@ -561,6 +562,7 @@ impl<'a> ReplicationUpdateVectorWriteTransaction<'a> { /// db entries are restored, their changesets will re-populate the data that we /// need in the RUV at these points. The reason we need these ranges without IDL /// is so that trim and replication works properly. + #[instrument(level = "debug", name = "ruv::restore", skip_all)] pub(crate) fn restore(&mut self, iter: I) -> Result<(), OperationError> where I: IntoIterator, @@ -589,6 +591,7 @@ impl<'a> ReplicationUpdateVectorWriteTransaction<'a> { Ok(()) } + #[instrument(level = "debug", name = "ruv::rebuild", skip_all)] pub fn rebuild(&mut self, entries: &[Arc]) -> Result<(), OperationError> { // Entries and their internal changestates are the "source of truth" for all changes // that have ever occurred and are stored on this server. So we use them to rebuild our RUV @@ -628,7 +631,16 @@ impl<'a> ReplicationUpdateVectorWriteTransaction<'a> { }); self.data.extend(rebuild_ruv); - self.ranged.extend(rebuild_range); + + // Warning - you can't extend here because this is keyed by UUID. You need + // to go through each key and then merge the sets. + rebuild_range.into_iter().for_each(|(s_uuid, ts_set)| { + if let Some(ex_ts_set) = self.ranged.get_mut(&s_uuid) { + ex_ts_set.extend(ts_set) + } else { + self.ranged.insert(s_uuid, ts_set); + } + }); Ok(()) } @@ -786,6 +798,8 @@ impl<'a> ReplicationUpdateVectorWriteTransaction<'a> { Some(l) => *l, None => { error!("Impossible State - The RUV should not be empty"); + error!(ruv = ?self); + error!(?cid); return Err(OperationError::InvalidState); } }; @@ -793,19 +807,25 @@ impl<'a> ReplicationUpdateVectorWriteTransaction<'a> { if cid.ts != last { if !server_range.remove(&cid.ts) { error!("Impossible State - The RUV is corrupted due to missing sid:ts pair in ranged index"); + error!(ruv = ?self); + error!(?cid); return Err(OperationError::InvalidState); } } else { - trace!("skip trimming maximum cid for s_uuid {}", cid.s_uuid); + debug!("skip trimming maximum cid for s_uuid {}", cid.s_uuid); } if server_range.is_empty() { // remove_suuid.push(cid.s_uuid); error!("Impossible State - The RUV should not be cleared for a s_uuid!"); + error!(ruv = ?self); + error!(?cid); return Err(OperationError::InvalidState); } } None => { error!("Impossible State - The RUV is corrupted due to missing sid in ranged index"); + error!(ruv = ?self); + error!(?cid); return Err(OperationError::InvalidState); } } diff --git a/server/lib/src/server/recycle.rs b/server/lib/src/server/recycle.rs index e8d54e8e3..23f8032bd 100644 --- a/server/lib/src/server/recycle.rs +++ b/server/lib/src/server/recycle.rs @@ -14,7 +14,7 @@ impl<'a> QueryServerWriteTransaction<'a> { self.be_txn .reap_tombstones(&trim_cid) .map_err(|e| { - admin_error!(err = ?e, "Tombstone purge operation failed (backend)"); + error!(err = ?e, "Tombstone purge operation failed (backend)"); e }) .map(|_| { diff --git a/server/lib/src/valueset/mod.rs b/server/lib/src/valueset/mod.rs index 08275393c..b1d4687b6 100644 --- a/server/lib/src/valueset/mod.rs +++ b/server/lib/src/valueset/mod.rs @@ -612,7 +612,7 @@ pub fn from_result_value_iter( mut iter: impl Iterator>, ) -> Result { let Some(init) = iter.next() else { - admin_error!("Empty value iterator"); + trace!("Empty value iterator"); return Err(OperationError::InvalidValueState); }; @@ -673,7 +673,7 @@ pub fn from_result_value_iter( pub fn from_value_iter(mut iter: impl Iterator) -> Result { let Some(init) = iter.next() else { - admin_error!("Empty value iterator"); + trace!("Empty value iterator"); return Err(OperationError::InvalidValueState); };