From 62d60d1afc9c12cbf51de843111c7b20b3b8defa Mon Sep 17 00:00:00 2001 From: Firstyear Date: Wed, 20 May 2020 10:31:34 +1000 Subject: [PATCH] 99 logging rewrite (#233) * Phase 1 - fix audit log nesting --- kanidmd/src/lib/actors/v1_read.rs | 615 +++++----- kanidmd/src/lib/actors/v1_write.rs | 978 ++++++++-------- kanidmd/src/lib/audit.rs | 259 ++++- kanidmd/src/lib/be/idl_arc_sqlite.rs | 178 +-- kanidmd/src/lib/be/idl_sqlite.rs | 264 +++-- kanidmd/src/lib/be/mod.rs | 109 +- kanidmd/src/lib/plugins/base.rs | 4 +- kanidmd/src/lib/plugins/macros.rs | 53 +- kanidmd/src/lib/plugins/mod.rs | 105 +- kanidmd/src/lib/plugins/refint.rs | 4 +- kanidmd/src/lib/schema.rs | 9 +- kanidmd/src/lib/server.rs | 1576 +++++++++++++------------- 12 files changed, 2186 insertions(+), 1968 deletions(-) diff --git a/kanidmd/src/lib/actors/v1_read.rs b/kanidmd/src/lib/actors/v1_read.rs index ad2f078b7..8a94b5101 100644 --- a/kanidmd/src/lib/actors/v1_read.rs +++ b/kanidmd/src/lib/actors/v1_read.rs @@ -205,7 +205,7 @@ impl Handler for QueryServerReadV1 { fn handle(&mut self, msg: SearchMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("search"); - let res = audit_segment!(&mut audit, || { + let res = lperf_segment!(&mut audit, "actors::v1_read::handle", || { // Begin a read let mut qs_read = self.qs.read(); @@ -241,7 +241,7 @@ impl Handler for QueryServerReadV1 { // the credentials provided is sufficient to say if someone is // "authenticated" or not. let mut audit = AuditScope::new("auth"); - let res = audit_segment!(&mut audit, || { + let res = lperf_segment!(&mut audit, "actors::v1_read::handle", || { audit_log!(audit, "Begin auth event {:?}", msg); // Destructure it. @@ -282,7 +282,7 @@ impl Handler for QueryServerReadV1 { fn handle(&mut self, msg: WhoamiMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("whoami"); - let res = audit_segment!(&mut audit, || { + let res = lperf_segment!(&mut audit, "actors::v1_read::handle", || { // TODO #62: Move this to IdmServer!!! // Begin a read let mut qs_read = self.qs.read(); @@ -337,26 +337,30 @@ impl Handler for QueryServerReadV1 { fn handle(&mut self, msg: InternalSearchMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("internal_search_message"); - let res = audit_segment!(&mut audit, || { - let mut qs_read = self.qs.read(); + let res = lperf_segment!( + &mut audit, + "actors::v1_read::handle", + || { + let mut qs_read = self.qs.read(); - // Make an event from the request - let srch = match SearchEvent::from_internal_message(&mut audit, msg, &mut qs_read) { - Ok(s) => s, - Err(e) => { - audit_log!(audit, "Failed to begin search: {:?}", e); - return Err(e); + // Make an event from the request + let srch = match SearchEvent::from_internal_message(&mut audit, msg, &mut qs_read) { + Ok(s) => s, + Err(e) => { + audit_log!(audit, "Failed to begin search: {:?}", e); + return Err(e); + } + }; + + audit_log!(audit, "Begin event {:?}", srch); + + match qs_read.search_ext(&mut audit, &srch) { + Ok(entries) => SearchResult::new(&mut audit, &mut qs_read, entries) + .map(|ok_sr| ok_sr.into_proto_array()), + Err(e) => Err(e), } - }; - - audit_log!(audit, "Begin event {:?}", srch); - - match qs_read.search_ext(&mut audit, &srch) { - Ok(entries) => SearchResult::new(&mut audit, &mut qs_read, entries) - .map(|ok_sr| ok_sr.into_proto_array()), - Err(e) => Err(e), } - }); + ); self.log.do_send(audit); res } @@ -371,27 +375,32 @@ impl Handler for QueryServerReadV1 { _: &mut Self::Context, ) -> Self::Result { let mut audit = AuditScope::new("internal_search_recycle_message"); - let res = audit_segment!(&mut audit, || { - let mut qs_read = self.qs.read(); + let res = lperf_segment!( + &mut audit, + "actors::v1_read::handle", + || { + let mut qs_read = self.qs.read(); - // Make an event from the request - let srch = - match SearchEvent::from_internal_recycle_message(&mut audit, msg, &mut qs_read) { - Ok(s) => s, - Err(e) => { - audit_log!(audit, "Failed to begin recycled search: {:?}", e); - return Err(e); - } - }; + // Make an event from the request + let srch = + match SearchEvent::from_internal_recycle_message(&mut audit, msg, &mut qs_read) + { + Ok(s) => s, + Err(e) => { + audit_log!(audit, "Failed to begin recycled search: {:?}", e); + return Err(e); + } + }; - audit_log!(audit, "Begin event {:?}", srch); + audit_log!(audit, "Begin event {:?}", srch); - match qs_read.search_ext(&mut audit, &srch) { - Ok(entries) => SearchResult::new(&mut audit, &mut qs_read, entries) - .map(|ok_sr| ok_sr.into_proto_array()), - Err(e) => Err(e), + match qs_read.search_ext(&mut audit, &srch) { + Ok(entries) => SearchResult::new(&mut audit, &mut qs_read, entries) + .map(|ok_sr| ok_sr.into_proto_array()), + Err(e) => Err(e), + } } - }); + ); self.log.do_send(audit); res } @@ -402,50 +411,54 @@ impl Handler for QueryServerReadV1 { fn handle(&mut self, msg: InternalRadiusReadMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("internal_radius_read_message"); - let res = audit_segment!(&mut audit, || { - let mut qs_read = self.qs.read(); + let res = lperf_segment!( + &mut audit, + "actors::v1_read::handle", + || { + let mut qs_read = self.qs.read(); - let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { - Ok(u) => u, - Err(_) => qs_read - .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) - .map_err(|e| { - audit_log!(&mut audit, "Error resolving id to target"); - e - })?, - }; + let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { + Ok(u) => u, + Err(_) => qs_read + .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) + .map_err(|e| { + audit_log!(&mut audit, "Error resolving id to target"); + e + })?, + }; - // Make an event from the request - let srch = match SearchEvent::from_target_uuid_request( - &mut audit, - msg.uat, - target_uuid, - &mut qs_read, - ) { - Ok(s) => s, - Err(e) => { - audit_log!(audit, "Failed to begin search: {:?}", e); - return Err(e); + // Make an event from the request + let srch = match SearchEvent::from_target_uuid_request( + &mut audit, + msg.uat, + target_uuid, + &mut qs_read, + ) { + Ok(s) => s, + Err(e) => { + audit_log!(audit, "Failed to begin search: {:?}", e); + return Err(e); + } + }; + + audit_log!(audit, "Begin event {:?}", srch); + + // We have to use search_ext to guarantee acs was applied. + match qs_read.search_ext(&mut audit, &srch) { + Ok(mut entries) => { + let r = entries + .pop() + // From the entry, turn it into the value + .and_then(|e| { + e.get_ava_single("radius_secret") + .and_then(|v| v.get_radius_secret().map(|s| s.to_string())) + }); + Ok(r) + } + Err(e) => Err(e), } - }; - - audit_log!(audit, "Begin event {:?}", srch); - - // We have to use search_ext to guarantee acs was applied. - match qs_read.search_ext(&mut audit, &srch) { - Ok(mut entries) => { - let r = entries - .pop() - // From the entry, turn it into the value - .and_then(|e| { - e.get_ava_single("radius_secret") - .and_then(|v| v.get_radius_secret().map(|s| s.to_string())) - }); - Ok(r) - } - Err(e) => Err(e), } - }); + ); self.log.do_send(audit); res } @@ -460,38 +473,42 @@ impl Handler for QueryServerReadV1 { _: &mut Self::Context, ) -> Self::Result { let mut audit = AuditScope::new("internal_radius_token_read_message"); - let res = audit_segment!(&mut audit, || { - let mut idm_read = self.idms.proxy_read(); + let res = lperf_segment!( + &mut audit, + "actors::v1_read::handle", + || { + let mut idm_read = self.idms.proxy_read(); - let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { - Ok(u) => u, - Err(_) => idm_read - .qs_read - .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) - .map_err(|e| { - audit_log!(&mut audit, "Error resolving id to target"); - e - })?, - }; + let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { + Ok(u) => u, + Err(_) => idm_read + .qs_read + .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) + .map_err(|e| { + audit_log!(&mut audit, "Error resolving id to target"); + e + })?, + }; - // Make an event from the request - let rate = match RadiusAuthTokenEvent::from_parts( - &mut audit, - &mut idm_read.qs_read, - msg.uat, - target_uuid, - ) { - Ok(s) => s, - Err(e) => { - audit_log!(audit, "Failed to begin search: {:?}", e); - return Err(e); - } - }; + // Make an event from the request + let rate = match RadiusAuthTokenEvent::from_parts( + &mut audit, + &mut idm_read.qs_read, + msg.uat, + target_uuid, + ) { + Ok(s) => s, + Err(e) => { + audit_log!(audit, "Failed to begin search: {:?}", e); + return Err(e); + } + }; - audit_log!(audit, "Begin event {:?}", rate); + audit_log!(audit, "Begin event {:?}", rate); - idm_read.get_radiusauthtoken(&mut audit, &rate) - }); + idm_read.get_radiusauthtoken(&mut audit, &rate) + } + ); self.log.do_send(audit); res } @@ -506,37 +523,41 @@ impl Handler for QueryServerReadV1 { _: &mut Self::Context, ) -> Self::Result { let mut audit = AuditScope::new("internal_unix_token_read_message"); - let res = audit_segment!(&mut audit, || { - let mut idm_read = self.idms.proxy_read(); + let res = lperf_segment!( + &mut audit, + "actors::v1_read::handle", + || { + let mut idm_read = self.idms.proxy_read(); - let target_uuid = Uuid::parse_str(msg.uuid_or_name.as_str()).or_else(|_| { - idm_read - .qs_read - .posixid_to_uuid(&mut audit, msg.uuid_or_name.as_str()) - .map_err(|e| { - audit_log!(&mut audit, "Error resolving as gidnumber continuing ..."); - e - }) - })?; + let target_uuid = Uuid::parse_str(msg.uuid_or_name.as_str()).or_else(|_| { + idm_read + .qs_read + .posixid_to_uuid(&mut audit, msg.uuid_or_name.as_str()) + .map_err(|e| { + audit_log!(&mut audit, "Error resolving as gidnumber continuing ..."); + e + }) + })?; - // Make an event from the request - let rate = match UnixUserTokenEvent::from_parts( - &mut audit, - &mut idm_read.qs_read, - msg.uat, - target_uuid, - ) { - Ok(s) => s, - Err(e) => { - audit_log!(audit, "Failed to begin search: {:?}", e); - return Err(e); - } - }; + // Make an event from the request + let rate = match UnixUserTokenEvent::from_parts( + &mut audit, + &mut idm_read.qs_read, + msg.uat, + target_uuid, + ) { + Ok(s) => s, + Err(e) => { + audit_log!(audit, "Failed to begin search: {:?}", e); + return Err(e); + } + }; - audit_log!(audit, "Begin event {:?}", rate); + audit_log!(audit, "Begin event {:?}", rate); - idm_read.get_unixusertoken(&mut audit, &rate) - }); + idm_read.get_unixusertoken(&mut audit, &rate) + } + ); self.log.do_send(audit); res } @@ -551,37 +572,41 @@ impl Handler for QueryServerReadV1 { _: &mut Self::Context, ) -> Self::Result { let mut audit = AuditScope::new("internal_unixgroup_token_read_message"); - let res = audit_segment!(&mut audit, || { - let mut idm_read = self.idms.proxy_read(); + let res = lperf_segment!( + &mut audit, + "actors::v1_read::handle", + || { + let mut idm_read = self.idms.proxy_read(); - let target_uuid = Uuid::parse_str(msg.uuid_or_name.as_str()).or_else(|_| { - idm_read - .qs_read - .posixid_to_uuid(&mut audit, msg.uuid_or_name.as_str()) - .map_err(|e| { - audit_log!(&mut audit, "Error resolving as gidnumber continuing ..."); - e - }) - })?; + let target_uuid = Uuid::parse_str(msg.uuid_or_name.as_str()).or_else(|_| { + idm_read + .qs_read + .posixid_to_uuid(&mut audit, msg.uuid_or_name.as_str()) + .map_err(|e| { + audit_log!(&mut audit, "Error resolving as gidnumber continuing ..."); + e + }) + })?; - // Make an event from the request - let rate = match UnixGroupTokenEvent::from_parts( - &mut audit, - &mut idm_read.qs_read, - msg.uat, - target_uuid, - ) { - Ok(s) => s, - Err(e) => { - audit_log!(audit, "Failed to begin search: {:?}", e); - return Err(e); - } - }; + // Make an event from the request + let rate = match UnixGroupTokenEvent::from_parts( + &mut audit, + &mut idm_read.qs_read, + msg.uat, + target_uuid, + ) { + Ok(s) => s, + Err(e) => { + audit_log!(audit, "Failed to begin search: {:?}", e); + return Err(e); + } + }; - audit_log!(audit, "Begin event {:?}", rate); + audit_log!(audit, "Begin event {:?}", rate); - idm_read.get_unixgrouptoken(&mut audit, &rate) - }); + idm_read.get_unixgrouptoken(&mut audit, &rate) + } + ); self.log.do_send(audit); res } @@ -592,53 +617,57 @@ impl Handler for QueryServerReadV1 { fn handle(&mut self, msg: InternalSshKeyReadMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("internal_sshkey_read_message"); - let res = audit_segment!(&mut audit, || { - let mut qs_read = self.qs.read(); + let res = lperf_segment!( + &mut audit, + "actors::v1_read::handle", + || { + let mut qs_read = self.qs.read(); - let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { - Ok(u) => u, - Err(_) => qs_read - .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) - .map_err(|e| { - audit_log!(&mut audit, "Error resolving id to target"); - e - })?, - }; + let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { + Ok(u) => u, + Err(_) => qs_read + .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) + .map_err(|e| { + audit_log!(&mut audit, "Error resolving id to target"); + e + })?, + }; - // Make an event from the request - let srch = match SearchEvent::from_target_uuid_request( - &mut audit, - msg.uat, - target_uuid, - &mut qs_read, - ) { - Ok(s) => s, - Err(e) => { - audit_log!(audit, "Failed to begin search: {:?}", e); - return Err(e); + // Make an event from the request + let srch = match SearchEvent::from_target_uuid_request( + &mut audit, + msg.uat, + target_uuid, + &mut qs_read, + ) { + Ok(s) => s, + Err(e) => { + audit_log!(audit, "Failed to begin search: {:?}", e); + return Err(e); + } + }; + + audit_log!(audit, "Begin event {:?}", srch); + + match qs_read.search_ext(&mut audit, &srch) { + Ok(mut entries) => { + let r = entries + .pop() + // get the first entry + .map(|e| { + // From the entry, turn it into the value + e.get_ava_ssh_pubkeys("ssh_publickey") + }) + .unwrap_or_else(|| { + // No matching entry? Return none. + Vec::new() + }); + Ok(r) + } + Err(e) => Err(e), } - }; - - audit_log!(audit, "Begin event {:?}", srch); - - match qs_read.search_ext(&mut audit, &srch) { - Ok(mut entries) => { - let r = entries - .pop() - // get the first entry - .map(|e| { - // From the entry, turn it into the value - e.get_ava_ssh_pubkeys("ssh_publickey") - }) - .unwrap_or_else(|| { - // No matching entry? Return none. - Vec::new() - }); - Ok(r) - } - Err(e) => Err(e), } - }); + ); self.log.do_send(audit); res } @@ -649,65 +678,69 @@ impl Handler for QueryServerReadV1 { fn handle(&mut self, msg: InternalSshKeyTagReadMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("internal_sshkey_tag_read_message"); - let res = audit_segment!(&mut audit, || { - let mut qs_read = self.qs.read(); + let res = lperf_segment!( + &mut audit, + "actors::v1_read::handle", + || { + let mut qs_read = self.qs.read(); - let InternalSshKeyTagReadMessage { - uat, - uuid_or_name, - tag, - } = msg; + let InternalSshKeyTagReadMessage { + uat, + uuid_or_name, + tag, + } = msg; - let target_uuid = match Uuid::parse_str(uuid_or_name.as_str()) { - Ok(u) => u, - Err(_) => qs_read - .name_to_uuid(&mut audit, uuid_or_name.as_str()) - .map_err(|e| { - audit_log!(&mut audit, "Error resolving id to target"); - e - })?, - }; + let target_uuid = match Uuid::parse_str(uuid_or_name.as_str()) { + Ok(u) => u, + Err(_) => qs_read + .name_to_uuid(&mut audit, uuid_or_name.as_str()) + .map_err(|e| { + audit_log!(&mut audit, "Error resolving id to target"); + e + })?, + }; - // Make an event from the request - let srch = match SearchEvent::from_target_uuid_request( - &mut audit, - uat, - target_uuid, - &mut qs_read, - ) { - Ok(s) => s, - Err(e) => { - audit_log!(audit, "Failed to begin search: {:?}", e); - return Err(e); - } - }; + // Make an event from the request + let srch = match SearchEvent::from_target_uuid_request( + &mut audit, + uat, + target_uuid, + &mut qs_read, + ) { + Ok(s) => s, + Err(e) => { + audit_log!(audit, "Failed to begin search: {:?}", e); + return Err(e); + } + }; - audit_log!(audit, "Begin event {:?}", srch); + audit_log!(audit, "Begin event {:?}", srch); - match qs_read.search_ext(&mut audit, &srch) { - Ok(mut entries) => { - let r = entries - .pop() - // get the first entry - .map(|e| { - // From the entry, turn it into the value - e.get_ava_set("ssh_publickey").and_then(|vs| { - // Get the one tagged value - let pv = PartialValue::new_sshkey_tag(tag); - vs.get(&pv) - // Now turn that value to a pub key. - .and_then(|v| v.get_sshkey()) + match qs_read.search_ext(&mut audit, &srch) { + Ok(mut entries) => { + let r = entries + .pop() + // get the first entry + .map(|e| { + // From the entry, turn it into the value + e.get_ava_set("ssh_publickey").and_then(|vs| { + // Get the one tagged value + let pv = PartialValue::new_sshkey_tag(tag); + vs.get(&pv) + // Now turn that value to a pub key. + .and_then(|v| v.get_sshkey()) + }) }) - }) - .unwrap_or_else(|| { - // No matching entry? Return none. - None - }); - Ok(r) + .unwrap_or_else(|| { + // No matching entry? Return none. + None + }); + Ok(r) + } + Err(e) => Err(e), } - Err(e) => Err(e), } - }); + ); self.log.do_send(audit); res } @@ -718,47 +751,51 @@ impl Handler for QueryServerReadV1 { fn handle(&mut self, msg: IdmAccountUnixAuthMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("idm_account_unix_auth"); - let res = audit_segment!(&mut audit, || { - let mut idm_write = self.idms.write(); + let res = lperf_segment!( + &mut audit, + "actors::v1_read::handle", + || { + let mut idm_write = self.idms.write(); - // resolve the id - let target_uuid = Uuid::parse_str(msg.uuid_or_name.as_str()).or_else(|_| { - idm_write - .qs_read - .posixid_to_uuid(&mut audit, msg.uuid_or_name.as_str()) - .map_err(|e| { - audit_log!(&mut audit, "Error resolving as gidnumber continuing ..."); - e - }) - })?; - // Make an event from the request - let uuae = match UnixUserAuthEvent::from_parts( - &mut audit, - &mut idm_write.qs_read, - msg.uat, - target_uuid, - msg.cred, - ) { - Ok(s) => s, - Err(e) => { - audit_log!(audit, "Failed to begin unix auth: {:?}", e); - return Err(e); - } - }; + // resolve the id + let target_uuid = Uuid::parse_str(msg.uuid_or_name.as_str()).or_else(|_| { + idm_write + .qs_read + .posixid_to_uuid(&mut audit, msg.uuid_or_name.as_str()) + .map_err(|e| { + audit_log!(&mut audit, "Error resolving as gidnumber continuing ..."); + e + }) + })?; + // Make an event from the request + let uuae = match UnixUserAuthEvent::from_parts( + &mut audit, + &mut idm_write.qs_read, + msg.uat, + target_uuid, + msg.cred, + ) { + Ok(s) => s, + Err(e) => { + audit_log!(audit, "Failed to begin unix auth: {:?}", e); + return Err(e); + } + }; - audit_log!(audit, "Begin event {:?}", uuae); + audit_log!(audit, "Begin event {:?}", uuae); - let ct = SystemTime::now() - .duration_since(SystemTime::UNIX_EPOCH) - .expect("Clock failure!"); + let ct = SystemTime::now() + .duration_since(SystemTime::UNIX_EPOCH) + .expect("Clock failure!"); - let r = idm_write - .auth_unix(&mut audit, &uuae, ct) - .and_then(|r| idm_write.commit().map(|_| r)); + let r = idm_write + .auth_unix(&mut audit, &uuae, ct) + .and_then(|r| idm_write.commit().map(|_| r)); - audit_log!(audit, "Sending result -> {:?}", r); - r - }); + audit_log!(audit, "Sending result -> {:?}", r); + r + } + ); self.log.do_send(audit); res } diff --git a/kanidmd/src/lib/actors/v1_write.rs b/kanidmd/src/lib/actors/v1_write.rs index e8275fdac..3a7d3d365 100644 --- a/kanidmd/src/lib/actors/v1_write.rs +++ b/kanidmd/src/lib/actors/v1_write.rs @@ -387,23 +387,27 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: CreateMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("create"); - let res = audit_segment!(&mut audit, || { - let mut qs_write = self.qs.write(duration_from_epoch_now()); + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let mut qs_write = self.qs.write(duration_from_epoch_now()); - let crt = match CreateEvent::from_message(&mut audit, msg, &mut qs_write) { - Ok(c) => c, - Err(e) => { - audit_log!(audit, "Failed to begin create: {:?}", e); - return Err(e); - } - }; + let crt = match CreateEvent::from_message(&mut audit, msg, &mut qs_write) { + Ok(c) => c, + Err(e) => { + audit_log!(audit, "Failed to begin create: {:?}", e); + return Err(e); + } + }; - audit_log!(audit, "Begin create event {:?}", crt); + audit_log!(audit, "Begin create event {:?}", crt); - qs_write - .create(&mut audit, &crt) - .and_then(|_| qs_write.commit(&mut audit).map(|_| OperationResponse {})) - }); + qs_write + .create(&mut audit, &crt) + .and_then(|_| qs_write.commit(&mut audit).map(|_| OperationResponse {})) + } + ); // At the end of the event we send it for logging. self.log.do_send(audit); res @@ -415,22 +419,26 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: ModifyMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("modify"); - let res = audit_segment!(&mut audit, || { - let mut qs_write = self.qs.write(duration_from_epoch_now()); - let mdf = match ModifyEvent::from_message(&mut audit, msg, &mut qs_write) { - Ok(m) => m, - Err(e) => { - audit_log!(audit, "Failed to begin modify: {:?}", e); - return Err(e); - } - }; + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let mut qs_write = self.qs.write(duration_from_epoch_now()); + let mdf = match ModifyEvent::from_message(&mut audit, msg, &mut qs_write) { + Ok(m) => m, + Err(e) => { + audit_log!(audit, "Failed to begin modify: {:?}", e); + return Err(e); + } + }; - audit_log!(audit, "Begin modify event {:?}", mdf); + audit_log!(audit, "Begin modify event {:?}", mdf); - qs_write - .modify(&mut audit, &mdf) - .and_then(|_| qs_write.commit(&mut audit).map(|_| OperationResponse {})) - }); + qs_write + .modify(&mut audit, &mdf) + .and_then(|_| qs_write.commit(&mut audit).map(|_| OperationResponse {})) + } + ); self.log.do_send(audit); res } @@ -441,23 +449,27 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: DeleteMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("delete"); - let res = audit_segment!(&mut audit, || { - let mut qs_write = self.qs.write(duration_from_epoch_now()); + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let mut qs_write = self.qs.write(duration_from_epoch_now()); - let del = match DeleteEvent::from_message(&mut audit, msg, &mut qs_write) { - Ok(d) => d, - Err(e) => { - audit_log!(audit, "Failed to begin delete: {:?}", e); - return Err(e); - } - }; + let del = match DeleteEvent::from_message(&mut audit, msg, &mut qs_write) { + Ok(d) => d, + Err(e) => { + audit_log!(audit, "Failed to begin delete: {:?}", e); + return Err(e); + } + }; - audit_log!(audit, "Begin delete event {:?}", del); + audit_log!(audit, "Begin delete event {:?}", del); - qs_write - .delete(&mut audit, &del) - .and_then(|_| qs_write.commit(&mut audit).map(|_| OperationResponse {})) - }); + qs_write + .delete(&mut audit, &del) + .and_then(|_| qs_write.commit(&mut audit).map(|_| OperationResponse {})) + } + ); self.log.do_send(audit); res } @@ -468,24 +480,28 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: InternalDeleteMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("delete"); - let res = audit_segment!(&mut audit, || { - let mut qs_write = self.qs.write(duration_from_epoch_now()); + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let mut qs_write = self.qs.write(duration_from_epoch_now()); - let del = match DeleteEvent::from_parts(&mut audit, msg.uat, msg.filter, &mut qs_write) - { - Ok(d) => d, - Err(e) => { - audit_log!(audit, "Failed to begin delete: {:?}", e); - return Err(e); - } - }; + let del = + match DeleteEvent::from_parts(&mut audit, msg.uat, msg.filter, &mut qs_write) { + Ok(d) => d, + Err(e) => { + audit_log!(audit, "Failed to begin delete: {:?}", e); + return Err(e); + } + }; - audit_log!(audit, "Begin delete event {:?}", del); + audit_log!(audit, "Begin delete event {:?}", del); - qs_write - .delete(&mut audit, &del) - .and_then(|_| qs_write.commit(&mut audit).map(|_| ())) - }); + qs_write + .delete(&mut audit, &del) + .and_then(|_| qs_write.commit(&mut audit).map(|_| ())) + } + ); self.log.do_send(audit); res } @@ -496,28 +512,32 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: ReviveRecycledMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("revive"); - let res = audit_segment!(&mut audit, || { - let mut qs_write = self.qs.write(duration_from_epoch_now()); + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let mut qs_write = self.qs.write(duration_from_epoch_now()); - let rev = match ReviveRecycledEvent::from_parts( - &mut audit, - msg.uat, - msg.filter, - &mut qs_write, - ) { - Ok(r) => r, - Err(e) => { - audit_log!(audit, "Failed to begin revive: {:?}", e); - return Err(e); - } - }; + let rev = match ReviveRecycledEvent::from_parts( + &mut audit, + msg.uat, + msg.filter, + &mut qs_write, + ) { + Ok(r) => r, + Err(e) => { + audit_log!(audit, "Failed to begin revive: {:?}", e); + return Err(e); + } + }; - audit_log!(audit, "Begin revive event {:?}", rev); + audit_log!(audit, "Begin revive event {:?}", rev); - qs_write - .revive_recycled(&mut audit, &rev) - .and_then(|_| qs_write.commit(&mut audit).map(|_| ())) - }); + qs_write + .revive_recycled(&mut audit, &rev) + .and_then(|_| qs_write.commit(&mut audit).map(|_| ())) + } + ); self.log.do_send(audit); res } @@ -529,118 +549,122 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: InternalCredentialSetMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("internal_credential_set_message"); - let res = audit_segment!(&mut audit, || { - let ct = duration_from_epoch_now(); - let mut idms_prox_write = self.idms.proxy_write(ct.clone()); + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let ct = duration_from_epoch_now(); + let mut idms_prox_write = self.idms.proxy_write(ct.clone()); - // Trigger a session clean *before* we take any auth steps. - // It's important to do this before to ensure that timeouts on - // the session are enforced. - idms_prox_write.expire_mfareg_sessions(ct); + // Trigger a session clean *before* we take any auth steps. + // It's important to do this before to ensure that timeouts on + // the session are enforced. + idms_prox_write.expire_mfareg_sessions(ct); - // given the uuid_or_name, determine the target uuid. - // We can either do this by trying to parse the name or by creating a filter - // to find the entry - there are risks to both TBH ... especially when the uuid - // is also an entries name, but that they aren't the same entry. - let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { - Ok(u) => u, - Err(_) => idms_prox_write - .qs_write - .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) - .map_err(|e| { - audit_log!(&mut audit, "Error resolving id to target"); - e - })?, - }; + // given the uuid_or_name, determine the target uuid. + // We can either do this by trying to parse the name or by creating a filter + // to find the entry - there are risks to both TBH ... especially when the uuid + // is also an entries name, but that they aren't the same entry. + let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { + Ok(u) => u, + Err(_) => idms_prox_write + .qs_write + .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) + .map_err(|e| { + audit_log!(&mut audit, "Error resolving id to target"); + e + })?, + }; - // What type of auth set did we recieve? - match msg.sac { - SetCredentialRequest::Password(cleartext) => { - let pce = PasswordChangeEvent::from_parts( - &mut audit, - &mut idms_prox_write.qs_write, - msg.uat, - target_uuid, - cleartext, - msg.appid, - ) - .map_err(|e| { - audit_log!( - audit, - "Failed to begin internal_credential_set_message: {:?}", + // What type of auth set did we recieve? + match msg.sac { + SetCredentialRequest::Password(cleartext) => { + let pce = PasswordChangeEvent::from_parts( + &mut audit, + &mut idms_prox_write.qs_write, + msg.uat, + target_uuid, + cleartext, + msg.appid, + ) + .map_err(|e| { + audit_log!( + audit, + "Failed to begin internal_credential_set_message: {:?}", + e + ); e - ); - e - })?; - idms_prox_write - .set_account_password(&mut audit, &pce) - .and_then(|_| idms_prox_write.commit(&mut audit)) - .map(|_| SetCredentialResponse::Success) - } - SetCredentialRequest::GeneratePassword => { - let gpe = GeneratePasswordEvent::from_parts( - &mut audit, - &mut idms_prox_write.qs_write, - msg.uat, - target_uuid, - msg.appid, - ) - .map_err(|e| { - audit_log!( - audit, - "Failed to begin internal_credential_set_message: {:?}", + })?; + idms_prox_write + .set_account_password(&mut audit, &pce) + .and_then(|_| idms_prox_write.commit(&mut audit)) + .map(|_| SetCredentialResponse::Success) + } + SetCredentialRequest::GeneratePassword => { + let gpe = GeneratePasswordEvent::from_parts( + &mut audit, + &mut idms_prox_write.qs_write, + msg.uat, + target_uuid, + msg.appid, + ) + .map_err(|e| { + audit_log!( + audit, + "Failed to begin internal_credential_set_message: {:?}", + e + ); e - ); - e - })?; - idms_prox_write - .generate_account_password(&mut audit, &gpe) - .and_then(|r| idms_prox_write.commit(&mut audit).map(|_| r)) - .map(|s| SetCredentialResponse::Token(s)) - } - SetCredentialRequest::TOTPGenerate(label) => { - let gte = GenerateTOTPEvent::from_parts( - &mut audit, - &mut idms_prox_write.qs_write, - msg.uat, - target_uuid, - label, - ) - .map_err(|e| { - audit_log!( - audit, - "Failed to begin internal_credential_set_message: {:?}", + })?; + idms_prox_write + .generate_account_password(&mut audit, &gpe) + .and_then(|r| idms_prox_write.commit(&mut audit).map(|_| r)) + .map(|s| SetCredentialResponse::Token(s)) + } + SetCredentialRequest::TOTPGenerate(label) => { + let gte = GenerateTOTPEvent::from_parts( + &mut audit, + &mut idms_prox_write.qs_write, + msg.uat, + target_uuid, + label, + ) + .map_err(|e| { + audit_log!( + audit, + "Failed to begin internal_credential_set_message: {:?}", + e + ); e - ); - e - })?; - idms_prox_write - .generate_account_totp(&mut audit, >e, ct) - .and_then(|r| idms_prox_write.commit(&mut audit).map(|_| r)) - } - SetCredentialRequest::TOTPVerify(uuid, chal) => { - let vte = VerifyTOTPEvent::from_parts( - &mut audit, - &mut idms_prox_write.qs_write, - msg.uat, - target_uuid, - uuid, - chal, - ) - .map_err(|e| { - audit_log!( - audit, - "Failed to begin internal_credential_set_message: {:?}", + })?; + idms_prox_write + .generate_account_totp(&mut audit, >e, ct) + .and_then(|r| idms_prox_write.commit(&mut audit).map(|_| r)) + } + SetCredentialRequest::TOTPVerify(uuid, chal) => { + let vte = VerifyTOTPEvent::from_parts( + &mut audit, + &mut idms_prox_write.qs_write, + msg.uat, + target_uuid, + uuid, + chal, + ) + .map_err(|e| { + audit_log!( + audit, + "Failed to begin internal_credential_set_message: {:?}", + e + ); e - ); - e - })?; - idms_prox_write - .verify_account_totp(&mut audit, &vte, ct) - .and_then(|r| idms_prox_write.commit(&mut audit).map(|_| r)) + })?; + idms_prox_write + .verify_account_totp(&mut audit, &vte, ct) + .and_then(|r| idms_prox_write.commit(&mut audit).map(|_| r)) + } } } - }); + ); self.log.do_send(audit); res } @@ -651,26 +675,30 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: IdmAccountSetPasswordMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("idm_account_set_password"); - let res = audit_segment!(&mut audit, || { - let ct = duration_from_epoch_now(); - let mut idms_prox_write = self.idms.proxy_write(ct.clone()); - idms_prox_write.expire_mfareg_sessions(ct); + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let ct = duration_from_epoch_now(); + let mut idms_prox_write = self.idms.proxy_write(ct.clone()); + idms_prox_write.expire_mfareg_sessions(ct); - let pce = PasswordChangeEvent::from_idm_account_set_password( - &mut audit, - &mut idms_prox_write.qs_write, - msg, - ) - .map_err(|e| { - audit_log!(audit, "Failed to begin idm_account_set_password: {:?}", e); - e - })?; + let pce = PasswordChangeEvent::from_idm_account_set_password( + &mut audit, + &mut idms_prox_write.qs_write, + msg, + ) + .map_err(|e| { + audit_log!(audit, "Failed to begin idm_account_set_password: {:?}", e); + e + })?; - idms_prox_write - .set_account_password(&mut audit, &pce) - .and_then(|_| idms_prox_write.commit(&mut audit)) - .map(|_| OperationResponse::new(())) - }); + idms_prox_write + .set_account_password(&mut audit, &pce) + .and_then(|_| idms_prox_write.commit(&mut audit)) + .map(|_| OperationResponse::new(())) + } + ); self.log.do_send(audit); res } @@ -685,41 +713,45 @@ impl Handler for QueryServerWriteV1 { _: &mut Self::Context, ) -> Self::Result { let mut audit = AuditScope::new("idm_account_regenerate_radius"); - let res = audit_segment!(&mut audit, || { - let ct = duration_from_epoch_now(); - let mut idms_prox_write = self.idms.proxy_write(ct.clone()); - idms_prox_write.expire_mfareg_sessions(ct); + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let ct = duration_from_epoch_now(); + let mut idms_prox_write = self.idms.proxy_write(ct.clone()); + idms_prox_write.expire_mfareg_sessions(ct); - let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { - Ok(u) => u, - Err(_) => idms_prox_write - .qs_write - .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) - .map_err(|e| { - audit_log!(&mut audit, "Error resolving id to target"); + let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { + Ok(u) => u, + Err(_) => idms_prox_write + .qs_write + .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) + .map_err(|e| { + audit_log!(&mut audit, "Error resolving id to target"); + e + })?, + }; + + let rrse = RegenerateRadiusSecretEvent::from_parts( + &mut audit, + &mut idms_prox_write.qs_write, + msg.uat, + target_uuid, + ) + .map_err(|e| { + audit_log!( + audit, + "Failed to begin idm_account_regenerate_radius: {:?}", e - })?, - }; - - let rrse = RegenerateRadiusSecretEvent::from_parts( - &mut audit, - &mut idms_prox_write.qs_write, - msg.uat, - target_uuid, - ) - .map_err(|e| { - audit_log!( - audit, - "Failed to begin idm_account_regenerate_radius: {:?}", + ); e - ); - e - })?; + })?; - idms_prox_write - .regenerate_radius_secret(&mut audit, &rrse) - .and_then(|r| idms_prox_write.commit(&mut audit).map(|_| r)) - }); + idms_prox_write + .regenerate_radius_secret(&mut audit, &rrse) + .and_then(|r| idms_prox_write.commit(&mut audit).map(|_| r)) + } + ); self.log.do_send(audit); res } @@ -730,39 +762,43 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: PurgeAttributeMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("purge_attribute"); - let res = audit_segment!(&mut audit, || { - let mut qs_write = self.qs.write(duration_from_epoch_now()); - let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { - Ok(u) => u, - Err(_) => qs_write - .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) - .map_err(|e| { - audit_log!(&mut audit, "Error resolving id to target"); - e - })?, - }; + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let mut qs_write = self.qs.write(duration_from_epoch_now()); + let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { + Ok(u) => u, + Err(_) => qs_write + .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) + .map_err(|e| { + audit_log!(&mut audit, "Error resolving id to target"); + e + })?, + }; - let mdf = match ModifyEvent::from_target_uuid_attr_purge( - &mut audit, - msg.uat, - target_uuid, - msg.attr, - msg.filter, - &mut qs_write, - ) { - Ok(m) => m, - Err(e) => { - audit_log!(audit, "Failed to begin modify: {:?}", e); - return Err(e); - } - }; + let mdf = match ModifyEvent::from_target_uuid_attr_purge( + &mut audit, + msg.uat, + target_uuid, + msg.attr, + msg.filter, + &mut qs_write, + ) { + Ok(m) => m, + Err(e) => { + audit_log!(audit, "Failed to begin modify: {:?}", e); + return Err(e); + } + }; - audit_log!(audit, "Begin modify event {:?}", mdf); + audit_log!(audit, "Begin modify event {:?}", mdf); - qs_write - .modify(&mut audit, &mdf) - .and_then(|_| qs_write.commit(&mut audit).map(|_| ())) - }); + qs_write + .modify(&mut audit, &mdf) + .and_then(|_| qs_write.commit(&mut audit).map(|_| ())) + } + ); self.log.do_send(audit); res } @@ -773,42 +809,46 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: RemoveAttributeValueMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("remove_attribute_value"); - let res = audit_segment!(&mut audit, || { - let mut qs_write = self.qs.write(duration_from_epoch_now()); - let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { - Ok(u) => u, - Err(_) => qs_write - .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) - .map_err(|e| { - audit_log!(&mut audit, "Error resolving id to target"); - e - })?, - }; + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let mut qs_write = self.qs.write(duration_from_epoch_now()); + let target_uuid = match Uuid::parse_str(msg.uuid_or_name.as_str()) { + Ok(u) => u, + Err(_) => qs_write + .name_to_uuid(&mut audit, msg.uuid_or_name.as_str()) + .map_err(|e| { + audit_log!(&mut audit, "Error resolving id to target"); + e + })?, + }; - let proto_ml = - ProtoModifyList::new_list(vec![ProtoModify::Removed(msg.attr, msg.value)]); + let proto_ml = + ProtoModifyList::new_list(vec![ProtoModify::Removed(msg.attr, msg.value)]); - let mdf = match ModifyEvent::from_parts( - &mut audit, - msg.uat, - target_uuid, - proto_ml, - msg.filter, - &mut qs_write, - ) { - Ok(m) => m, - Err(e) => { - audit_log!(audit, "Failed to begin modify: {:?}", e); - return Err(e); - } - }; + let mdf = match ModifyEvent::from_parts( + &mut audit, + msg.uat, + target_uuid, + proto_ml, + msg.filter, + &mut qs_write, + ) { + Ok(m) => m, + Err(e) => { + audit_log!(audit, "Failed to begin modify: {:?}", e); + return Err(e); + } + }; - audit_log!(audit, "Begin modify event {:?}", mdf); + audit_log!(audit, "Begin modify event {:?}", mdf); - qs_write - .modify(&mut audit, &mdf) - .and_then(|_| qs_write.commit(&mut audit).map(|_| ())) - }); + qs_write + .modify(&mut audit, &mdf) + .and_then(|_| qs_write.commit(&mut audit).map(|_| ())) + } + ); self.log.do_send(audit); res } @@ -819,24 +859,28 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: AppendAttributeMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("append_attribute"); - let res = audit_segment!(&mut audit, || { - let AppendAttributeMessage { - uat, - uuid_or_name, - attr, - values, - filter, - } = msg; - // We need to turn these into proto modlists so they can be converted - // and validated. - let proto_ml = ProtoModifyList::new_list( - values - .into_iter() - .map(|v| ProtoModify::Present(attr.clone(), v)) - .collect(), - ); - self.modify_from_parts(&mut audit, uat, uuid_or_name, proto_ml, filter) - }); + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let AppendAttributeMessage { + uat, + uuid_or_name, + attr, + values, + filter, + } = msg; + // We need to turn these into proto modlists so they can be converted + // and validated. + let proto_ml = ProtoModifyList::new_list( + values + .into_iter() + .map(|v| ProtoModify::Present(attr.clone(), v)) + .collect(), + ); + self.modify_from_parts(&mut audit, uat, uuid_or_name, proto_ml, filter) + } + ); self.log.do_send(audit); res } @@ -847,27 +891,31 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: SetAttributeMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("set_attribute"); - let res = audit_segment!(&mut audit, || { - let SetAttributeMessage { - uat, - uuid_or_name, - attr, - values, - filter, - } = msg; - // We need to turn these into proto modlists so they can be converted - // and validated. - let proto_ml = ProtoModifyList::new_list( - std::iter::once(ProtoModify::Purged(attr.clone())) - .chain( - values - .into_iter() - .map(|v| ProtoModify::Present(attr.clone(), v)), - ) - .collect(), - ); - self.modify_from_parts(&mut audit, uat, uuid_or_name, proto_ml, filter) - }); + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let SetAttributeMessage { + uat, + uuid_or_name, + attr, + values, + filter, + } = msg; + // We need to turn these into proto modlists so they can be converted + // and validated. + let proto_ml = ProtoModifyList::new_list( + std::iter::once(ProtoModify::Purged(attr.clone())) + .chain( + values + .into_iter() + .map(|v| ProtoModify::Present(attr.clone(), v)), + ) + .collect(), + ); + self.modify_from_parts(&mut audit, uat, uuid_or_name, proto_ml, filter) + } + ); self.log.do_send(audit); res } @@ -878,21 +926,25 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: InternalSshKeyCreateMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("internal_sshkey_create"); - let res = audit_segment!(&mut audit, || { - let InternalSshKeyCreateMessage { - uat, - uuid_or_name, - tag, - key, - filter, - } = msg; + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let InternalSshKeyCreateMessage { + uat, + uuid_or_name, + tag, + key, + filter, + } = msg; - // Because this is from internal, we can generate a real modlist, rather - // than relying on the proto ones. - let ml = ModifyList::new_append("ssh_publickey", Value::new_sshkey(tag, key)); + // Because this is from internal, we can generate a real modlist, rather + // than relying on the proto ones. + let ml = ModifyList::new_append("ssh_publickey", Value::new_sshkey(tag, key)); - self.modify_from_internal_parts(&mut audit, uat, uuid_or_name, ml, filter) - }); + self.modify_from_internal_parts(&mut audit, uat, uuid_or_name, ml, filter) + } + ); self.log.do_send(audit); res } @@ -907,25 +959,29 @@ impl Handler for QueryServerWriteV1 { _: &mut Self::Context, ) -> Self::Result { let mut audit = AuditScope::new("idm_account_person_extend"); - let res = audit_segment!(&mut audit, || { - let IdmAccountPersonExtendMessage { uat, uuid_or_name } = msg; + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let IdmAccountPersonExtendMessage { uat, uuid_or_name } = msg; - // The filter_map here means we only create the mods if the gidnumber or shell are set - // in the actual request. - let mods: Vec<_> = vec![Some(Modify::Present( - "class".to_string(), - Value::new_class("person"), - ))] - .into_iter() - .filter_map(|v| v) - .collect(); + // The filter_map here means we only create the mods if the gidnumber or shell are set + // in the actual request. + let mods: Vec<_> = vec![Some(Modify::Present( + "class".to_string(), + Value::new_class("person"), + ))] + .into_iter() + .filter_map(|v| v) + .collect(); - let ml = ModifyList::new_list(mods); + let ml = ModifyList::new_list(mods); - let filter = filter_all!(f_eq("class", PartialValue::new_class("account"))); + let filter = filter_all!(f_eq("class", PartialValue::new_class("account"))); - self.modify_from_internal_parts(&mut audit, uat, uuid_or_name, ml, filter) - }); + self.modify_from_internal_parts(&mut audit, uat, uuid_or_name, ml, filter) + } + ); self.log.do_send(audit); res } @@ -936,34 +992,39 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: IdmAccountUnixExtendMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("idm_account_unix_extend"); - let res = audit_segment!(&mut audit, || { - let IdmAccountUnixExtendMessage { - uat, - uuid_or_name, - gidnumber, - shell, - } = msg; + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let IdmAccountUnixExtendMessage { + uat, + uuid_or_name, + gidnumber, + shell, + } = msg; - // The filter_map here means we only create the mods if the gidnumber or shell are set - // in the actual request. - let mods: Vec<_> = vec![ - Some(Modify::Present( - "class".to_string(), - Value::new_class("posixaccount"), - )), - gidnumber.map(|n| Modify::Present("gidnumber".to_string(), Value::new_uint32(n))), - shell.map(|s| Modify::Present("loginshell".to_string(), Value::new_iutf8(s))), - ] - .into_iter() - .filter_map(|v| v) - .collect(); + // The filter_map here means we only create the mods if the gidnumber or shell are set + // in the actual request. + let mods: Vec<_> = vec![ + Some(Modify::Present( + "class".to_string(), + Value::new_class("posixaccount"), + )), + gidnumber + .map(|n| Modify::Present("gidnumber".to_string(), Value::new_uint32(n))), + shell.map(|s| Modify::Present("loginshell".to_string(), Value::new_iutf8(s))), + ] + .into_iter() + .filter_map(|v| v) + .collect(); - let ml = ModifyList::new_list(mods); + let ml = ModifyList::new_list(mods); - let filter = filter_all!(f_eq("class", PartialValue::new_class("account"))); + let filter = filter_all!(f_eq("class", PartialValue::new_class("account"))); - self.modify_from_internal_parts(&mut audit, uat, uuid_or_name, ml, filter) - }); + self.modify_from_internal_parts(&mut audit, uat, uuid_or_name, ml, filter) + } + ); self.log.do_send(audit); res } @@ -974,32 +1035,37 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: IdmGroupUnixExtendMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("idm_group_unix_extend"); - let res = audit_segment!(&mut audit, || { - let IdmGroupUnixExtendMessage { - uat, - uuid_or_name, - gidnumber, - } = msg; + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let IdmGroupUnixExtendMessage { + uat, + uuid_or_name, + gidnumber, + } = msg; - // The filter_map here means we only create the mods if the gidnumber or shell are set - // in the actual request. - let mods: Vec<_> = vec![ - Some(Modify::Present( - "class".to_string(), - Value::new_class("posixgroup"), - )), - gidnumber.map(|n| Modify::Present("gidnumber".to_string(), Value::new_uint32(n))), - ] - .into_iter() - .filter_map(|v| v) - .collect(); + // The filter_map here means we only create the mods if the gidnumber or shell are set + // in the actual request. + let mods: Vec<_> = vec![ + Some(Modify::Present( + "class".to_string(), + Value::new_class("posixgroup"), + )), + gidnumber + .map(|n| Modify::Present("gidnumber".to_string(), Value::new_uint32(n))), + ] + .into_iter() + .filter_map(|v| v) + .collect(); - let ml = ModifyList::new_list(mods); + let ml = ModifyList::new_list(mods); - let filter = filter_all!(f_eq("class", PartialValue::new_class("group"))); + let filter = filter_all!(f_eq("class", PartialValue::new_class("group"))); - self.modify_from_internal_parts(&mut audit, uat, uuid_or_name, ml, filter) - }); + self.modify_from_internal_parts(&mut audit, uat, uuid_or_name, ml, filter) + } + ); self.log.do_send(audit); res } @@ -1010,37 +1076,41 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: IdmAccountUnixSetCredMessage, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("idm_account_unix_set_cred"); - let res = audit_segment!(&mut audit, || { - let ct = duration_from_epoch_now(); - let mut idms_prox_write = self.idms.proxy_write(ct.clone()); - idms_prox_write.expire_mfareg_sessions(ct); + let res = lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + let ct = duration_from_epoch_now(); + let mut idms_prox_write = self.idms.proxy_write(ct.clone()); + idms_prox_write.expire_mfareg_sessions(ct); - let target_uuid = Uuid::parse_str(msg.uuid_or_name.as_str()).or_else(|_| { + let target_uuid = Uuid::parse_str(msg.uuid_or_name.as_str()).or_else(|_| { + idms_prox_write + .qs_write + .posixid_to_uuid(&mut audit, msg.uuid_or_name.as_str()) + .map_err(|e| { + audit_log!(&mut audit, "Error resolving as gidnumber continuing ..."); + e + }) + })?; + + let upce = UnixPasswordChangeEvent::from_parts( + &mut audit, + &mut idms_prox_write.qs_write, + msg.uat, + target_uuid, + msg.cred, + ) + .map_err(|e| { + audit_log!(audit, "Failed to begin UnixPasswordChangeEvent: {:?}", e); + e + })?; idms_prox_write - .qs_write - .posixid_to_uuid(&mut audit, msg.uuid_or_name.as_str()) - .map_err(|e| { - audit_log!(&mut audit, "Error resolving as gidnumber continuing ..."); - e - }) - })?; - - let upce = UnixPasswordChangeEvent::from_parts( - &mut audit, - &mut idms_prox_write.qs_write, - msg.uat, - target_uuid, - msg.cred, - ) - .map_err(|e| { - audit_log!(audit, "Failed to begin UnixPasswordChangeEvent: {:?}", e); - e - })?; - idms_prox_write - .set_unix_account_password(&mut audit, &upce) - .and_then(|_| idms_prox_write.commit(&mut audit)) - .map(|_| ()) - }); + .set_unix_account_password(&mut audit, &upce) + .and_then(|_| idms_prox_write.commit(&mut audit)) + .map(|_| ()) + } + ); self.log.do_send(audit); res } @@ -1053,16 +1123,20 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: PurgeTombstoneEvent, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("purge tombstones"); - audit_segment!(&mut audit, || { - audit_log!(audit, "Begin purge tombstone event {:?}", msg); - let mut qs_write = self.qs.write(duration_from_epoch_now()); + lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + audit_log!(audit, "Begin purge tombstone event {:?}", msg); + let mut qs_write = self.qs.write(duration_from_epoch_now()); - let res = qs_write - .purge_tombstones(&mut audit) - .and_then(|_| qs_write.commit(&mut audit)); - audit_log!(audit, "Purge tombstones result: {:?}", res); - res.expect("Invalid Server State"); - }); + let res = qs_write + .purge_tombstones(&mut audit) + .and_then(|_| qs_write.commit(&mut audit)); + audit_log!(audit, "Purge tombstones result: {:?}", res); + res.expect("Invalid Server State"); + } + ); // At the end of the event we send it for logging. self.log.do_send(audit); } @@ -1073,16 +1147,20 @@ impl Handler for QueryServerWriteV1 { fn handle(&mut self, msg: PurgeRecycledEvent, _: &mut Self::Context) -> Self::Result { let mut audit = AuditScope::new("purge recycled"); - audit_segment!(&mut audit, || { - audit_log!(audit, "Begin purge recycled event {:?}", msg); - let mut qs_write = self.qs.write(duration_from_epoch_now()); + lperf_segment!( + &mut audit, + "actors::v1_write::handle", + || { + audit_log!(audit, "Begin purge recycled event {:?}", msg); + let mut qs_write = self.qs.write(duration_from_epoch_now()); - let res = qs_write - .purge_recycled(&mut audit) - .and_then(|_| qs_write.commit(&mut audit)); - audit_log!(audit, "Purge recycled result: {:?}", res); - res.expect("Invalid Server State"); - }); + let res = qs_write + .purge_recycled(&mut audit) + .and_then(|_| qs_write.commit(&mut audit)); + audit_log!(audit, "Purge recycled result: {:?}", res); + res.expect("Invalid Server State"); + } + ); // At the end of the event we send it for logging. self.log.do_send(audit); } diff --git a/kanidmd/src/lib/audit.rs b/kanidmd/src/lib/audit.rs index 43e16142e..26dc861e0 100644 --- a/kanidmd/src/lib/audit.rs +++ b/kanidmd/src/lib/audit.rs @@ -1,21 +1,22 @@ use actix::prelude::*; use std::fmt; +// use std::ptr; +use std::cmp::Ordering; use std::time::Duration; use std::time::SystemTime; use chrono::offset::Utc; use chrono::DateTime; +use uuid::adapter::HyphenatedRef; +use uuid::Uuid; #[macro_export] macro_rules! audit_log { ($audit:expr, $($arg:tt)*) => ({ use std::fmt; if cfg!(test) || cfg!(debug_assertions) { - // debug!("DEBUG AUDIT ({}:{} {})-> ", file!(), line!(), $audit.id()); - // debug!($($arg)*) - // debug!("DEBUG AUDIT ({}:{} {})-> ", file!(), line!(), $audit.id()); - // debug!("line: {}", line!()); debug!($($arg)*) + // } else { } $audit.log_event( fmt::format( @@ -35,20 +36,27 @@ macro_rules! audit_log { * }) */ -macro_rules! audit_segment { - ($au:expr, $fun:expr) => {{ +macro_rules! lperf_segment { + ($au:expr, $id:expr, $fun:expr) => {{ use std::time::Instant; - let start = Instant::now(); // start timer. - // run fun with our derived audit event. + let start = Instant::now(); + + // Create a new perf event - this sets + // us as the current active, and the parent + // correctly. + let pe = unsafe { $au.new_perfevent($id) }; + + // fun run time let r = $fun(); // end timer, and diff let end = Instant::now(); let diff = end.duration_since(start); - audit_log!($au, "duration -> {:?}", diff); - $au.set_duration(diff); + // Now we are done, we put our parent back as + // the active. + unsafe { $au.end_perfevent(pe, diff) }; // Return the result. Hope this works! r @@ -85,30 +93,137 @@ macro_rules! try_audit { }; } -#[derive(Serialize, Deserialize)] -enum AuditEvent { - Log(AuditLog), - Scope(AuditScope), -} - #[derive(Debug, Serialize, Deserialize)] struct AuditLog { time: String, - name: String, + data: String, +} + +#[derive(Debug, Serialize)] +pub struct PerfEvent { + id: String, + duration: Option, + contains: Vec, + #[serde(skip_serializing)] + parent: Option<&'static mut PerfEvent>, +} + +impl PerfEvent { + fn process_inner(&self, opd: &Duration) -> PerfProcessed { + let mut contains: Vec<_> = self + .contains + .iter() + .map(|pe| pe.process_inner(opd)) + .collect(); + contains.sort_unstable(); + let duration = self + .duration + .as_ref() + .expect("corrupted perf event") + .clone(); + let percent = (duration.as_secs_f64() / opd.as_secs_f64()) * 100.0; + PerfProcessed { + duration, + id: self.id.clone(), + percent, + contains, + } + } + + fn process(&self) -> PerfProcessed { + let duration = self + .duration + .as_ref() + .expect("corrupted perf event") + .clone(); + let mut contains: Vec<_> = self + .contains + .iter() + .map(|pe| pe.process_inner(&duration)) + .collect(); + contains.sort_unstable(); + PerfProcessed { + duration, + id: self.id.clone(), + percent: 100.0, + contains, + } + } +} + +#[derive(Debug, Serialize)] +pub struct PerfProcessed { + duration: Duration, + id: String, + percent: f64, + contains: Vec, +} + +impl Ord for PerfProcessed { + fn cmp(&self, other: &Self) -> Ordering { + other.duration.cmp(&self.duration) + } +} + +impl PartialOrd for PerfProcessed { + fn partial_cmp(&self, other: &Self) -> Option { + Some(self.cmp(other)) + } +} + +impl Eq for PerfProcessed {} + +impl PartialEq for PerfProcessed { + fn eq(&self, other: &Self) -> bool { + self.duration == other.duration + } +} + +/* + * event + * |--> another_event + * |--> another_event + * | |--> another layer + * | |--> another layer + * | | |--> the abyss layer + * | |--> another layer + */ +impl PerfProcessed { + fn int_write_fmt( + &self, + f: &mut fmt::Formatter, + parents: usize, + uuid: &HyphenatedRef, + ) -> fmt::Result { + write!(f, "perf {}: ", uuid)?; + let d = &self.duration; + let df = d.as_secs() as f64 + d.subsec_nanos() as f64 * 1e-9; + if parents > 0 { + for _i in 0..(parents - 1) { + write!(f, "| ")?; + } + }; + writeln!(f, "|--> {} {1:.9} {2:.3}%", self.id, df, self.percent)?; + self.contains + .iter() + .try_for_each(|pe| pe.int_write_fmt(f, parents + 1, uuid)) + } } // This structure tracks and event lifecycle, and is eventually // sent to the logging system where it's structured and written // out to the current logging BE. -#[derive(Serialize, Deserialize)] +#[derive(Serialize)] pub struct AuditScope { // vec of start/end points of various parts of the event? // We probably need some functions for this. Is there a way in rust // to automatically annotate line numbers of code? - time: String, - name: String, - duration: Option, - events: Vec, + uuid: Uuid, + events: Vec, + perf: Vec, + // active perf event + #[serde(skip_serializing)] + active_perf: Option<&'static mut PerfEvent>, } // Allow us to be sent to the log subsystem @@ -118,10 +233,20 @@ impl Message for AuditScope { impl fmt::Display for AuditScope { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { - let mut _depth = 0; - // write!(f, "{}: begin -> {}", self.time, self.name); - let d = serde_json::to_string_pretty(self).map_err(|_| fmt::Error)?; - write!(f, "{}", d) + let uuid_ref = self.uuid.to_hyphenated_ref(); + self.events + .iter() + .try_for_each(|e| writeln!(f, "{} {}: {}", e.time, uuid_ref, e.data))?; + // First, we pre-process all the perf events to order them + let mut proc_perf: Vec<_> = self.perf.iter().map(|pe| pe.process()).collect(); + + // We still sort them by duration. + proc_perf.sort_unstable(); + + // Now write the perf events + proc_perf + .iter() + .try_for_each(|pe| pe.int_write_fmt(f, 0, &uuid_ref)) } } @@ -131,34 +256,80 @@ impl AuditScope { let datetime: DateTime = t_now.into(); AuditScope { - time: datetime.to_rfc3339(), - name: String::from(name), - duration: None, - events: Vec::new(), + uuid: Uuid::new_v4(), + events: vec![AuditLog { + time: datetime.to_rfc3339(), + data: format!("start {}", name), + }], + perf: vec![], + active_perf: None, } } - pub fn id(&self) -> &str { - self.name.as_str() - } - - pub fn set_duration(&mut self, diff: Duration) { - self.duration = Some(diff); - } - - // Given a new audit event, append it in. - pub fn append_scope(&mut self, scope: AuditScope) { - self.events.push(AuditEvent::Scope(scope)) + pub fn get_uuid(&self) -> &Uuid { + &self.uuid } pub fn log_event(&mut self, data: String) { let t_now = SystemTime::now(); let datetime: DateTime = t_now.into(); - self.events.push(AuditEvent::Log(AuditLog { + self.events.push(AuditLog { time: datetime.to_rfc3339(), - name: data, - })) + data: data, + }) + } + + pub(crate) unsafe fn new_perfevent(&mut self, id: &str) -> &'static mut PerfEvent { + // Does an active event currently exist? + if self.active_perf.is_none() { + // No, we are a new event. + self.perf.push(PerfEvent { + id: id.to_string(), + duration: None, + contains: vec![], + parent: None, + }); + // Get a put ptr, we are now the active. + let xref = self.perf.last_mut().expect("perf alloc failure?") as *mut PerfEvent; + let mref = &mut (*xref); + self.active_perf = Some(mref); + // return the mut ptr. + &mut (*xref) + } else { + // Yes, there is an active event. + // get the currennt active ptr + let xref = if let Some(ref mut iparent) = self.active_perf { + iparent.contains.push(PerfEvent { + id: id.to_string(), + duration: None, + contains: vec![], + parent: None, + }); + iparent.contains.last_mut().expect("perf alloc failure?") as *mut PerfEvent + } else { + panic!("Invalid parent state"); + }; + // Alloc in the vec, set parnt to active, then get a mut pointer + // to ourself, then set ourself as the active. + (*xref).parent = Some(&mut (*xref)); + std::mem::swap(&mut (*xref).parent, &mut self.active_perf); + // return the mut ptr. + &mut (*xref) + } + } + + pub(crate) unsafe fn end_perfevent(&mut self, pe: &'static mut PerfEvent, diff: Duration) { + // assert that we are the current active, else we have active children + // that are unclosed! + // ??? + + // We are done, put the duration into the pe. + pe.duration = Some(diff); + // put parent back as the active. + std::mem::swap(&mut pe.parent, &mut self.active_perf); + // And none the PE + pe.parent = None; } } diff --git a/kanidmd/src/lib/be/idl_arc_sqlite.rs b/kanidmd/src/lib/be/idl_arc_sqlite.rs index 8e91ffb27..c35f6dd2c 100644 --- a/kanidmd/src/lib/be/idl_arc_sqlite.rs +++ b/kanidmd/src/lib/be/idl_arc_sqlite.rs @@ -65,36 +65,38 @@ macro_rules! get_identry { $au:expr, $idl:expr ) => {{ - match $idl { - IDL::Partial(idli) | IDL::Indexed(idli) => { - let mut result: Vec> = Vec::new(); - let mut nidl = IDLBitRange::new(); + lperf_segment!($au, "be::idl_arc_sqlite::get_identry", || { + match $idl { + IDL::Partial(idli) | IDL::Indexed(idli) => { + let mut result: Vec> = Vec::new(); + let mut nidl = IDLBitRange::new(); - idli.into_iter().for_each(|i| { - // For all the id's in idl. - // is it in the cache? - match $self.entry_cache.get(&i) { - Some(eref) => result.push(eref.as_ref().clone()), - None => unsafe { nidl.push_id(i) }, - } - }); + idli.into_iter().for_each(|i| { + // For all the id's in idl. + // is it in the cache? + match $self.entry_cache.get(&i) { + Some(eref) => result.push(eref.as_ref().clone()), + None => unsafe { nidl.push_id(i) }, + } + }); - // Now, get anything from nidl that is needed. - let mut db_result = $self.db.get_identry($au, &IDL::Partial(nidl))?; + // Now, get anything from nidl that is needed. + let mut db_result = $self.db.get_identry($au, &IDL::Partial(nidl))?; - // Clone everything from db_result into the cache. - db_result.iter().for_each(|e| { - $self.entry_cache.insert(e.get_id(), Box::new(e.clone())); - }); + // Clone everything from db_result into the cache. + db_result.iter().for_each(|e| { + $self.entry_cache.insert(e.get_id(), Box::new(e.clone())); + }); - // Merge the two vecs - result.append(&mut db_result); + // Merge the two vecs + result.append(&mut db_result); - // Return - Ok(result) + // Return + Ok(result) + } + IDL::ALLIDS => $self.db.get_identry($au, $idl), } - IDL::ALLIDS => $self.db.get_identry($au, $idl), - } + }) }}; } @@ -129,24 +131,26 @@ macro_rules! get_idl { $itype:expr, $idx_key:expr ) => {{ - // TODO: Find a way to implement borrow for this properly - // First attempt to get from this cache. - let cache_key = IdlCacheKey { - a: $attr.to_string(), - i: $itype.clone(), - k: $idx_key.to_string(), - }; - let cache_r = $self.idl_cache.get(&cache_key); - // If hit, continue. - if let Some(ref data) = cache_r { - return Ok(Some(data.as_ref().clone())); - } - // If miss, get from db *and* insert to the cache. - let db_r = $self.db.get_idl($audit, $attr, $itype, $idx_key)?; - if let Some(ref idl) = db_r { - $self.idl_cache.insert(cache_key, Box::new(idl.clone())) - } - Ok(db_r) + lperf_segment!($audit, "be::idl_arc_sqlite::get_idl", || { + // TODO: Find a way to implement borrow for this properly + // First attempt to get from this cache. + let cache_key = IdlCacheKey { + a: $attr.to_string(), + i: $itype.clone(), + k: $idx_key.to_string(), + }; + let cache_r = $self.idl_cache.get(&cache_key); + // If hit, continue. + if let Some(ref data) = cache_r { + return Ok(Some(data.as_ref().clone())); + } + // If miss, get from db *and* insert to the cache. + let db_r = $self.db.get_idl($audit, $attr, $itype, $idx_key)?; + if let Some(ref idl) = db_r { + $self.idl_cache.insert(cache_key, Box::new(idl.clone())) + } + Ok(db_r) + }) }}; } @@ -285,16 +289,18 @@ impl<'a> IdlArcSqliteTransaction for IdlArcSqliteWriteTransaction<'a> { impl<'a> IdlArcSqliteWriteTransaction<'a> { pub fn commit(self, audit: &mut AuditScope) -> Result<(), OperationError> { - let IdlArcSqliteWriteTransaction { - db, - entry_cache, - idl_cache, - } = self; - // Undo the caches in the reverse order. - db.commit(audit).and_then(|r| { - idl_cache.commit(); - entry_cache.commit(); - Ok(r) + lperf_segment!(audit, "be::idl_arc_sqlite::commit", || { + let IdlArcSqliteWriteTransaction { + db, + entry_cache, + idl_cache, + } = self; + // Undo the caches in the reverse order. + db.commit(audit).and_then(|r| { + idl_cache.commit(); + entry_cache.commit(); + Ok(r) + }) }) } @@ -312,14 +318,16 @@ impl<'a> IdlArcSqliteWriteTransaction<'a> { where I: Iterator>, { - // Danger! We know that the entry cache is valid to manipulate here - // but rust doesn't know that so it prevents the mut/immut borrow. - let e_cache = unsafe { &mut *(&mut self.entry_cache as *mut ArcWriteTxn<_, _>) }; - let m_entries = entries.map(|e| { - e_cache.insert(e.get_id(), Box::new(e.clone())); - e - }); - self.db.write_identries(au, m_entries) + lperf_segment!(au, "be::idl_arc_sqlite::write_identries", || { + // Danger! We know that the entry cache is valid to manipulate here + // but rust doesn't know that so it prevents the mut/immut borrow. + let e_cache = unsafe { &mut *(&mut self.entry_cache as *mut ArcWriteTxn<_, _>) }; + let m_entries = entries.map(|e| { + e_cache.insert(e.get_id(), Box::new(e.clone())); + e + }); + self.db.write_identries(au, m_entries) + }) } pub fn write_identries_raw( @@ -340,14 +348,16 @@ impl<'a> IdlArcSqliteWriteTransaction<'a> { where I: Iterator, { - // Danger! We know that the entry cache is valid to manipulate here - // but rust doesn't know that so it prevents the mut/immut borrow. - let e_cache = unsafe { &mut *(&mut self.entry_cache as *mut ArcWriteTxn<_, _>) }; - let m_idl = idl.map(|i| { - e_cache.remove(i); - i - }); - self.db.delete_identry(au, m_idl) + lperf_segment!(au, "be::idl_arc_sqlite::delete_identry", || { + // Danger! We know that the entry cache is valid to manipulate here + // but rust doesn't know that so it prevents the mut/immut borrow. + let e_cache = unsafe { &mut *(&mut self.entry_cache as *mut ArcWriteTxn<_, _>) }; + let m_idl = idl.map(|i| { + e_cache.remove(i); + i + }); + self.db.delete_identry(au, m_idl) + }) } pub fn write_idl( @@ -358,21 +368,23 @@ impl<'a> IdlArcSqliteWriteTransaction<'a> { idx_key: &str, idl: &IDLBitRange, ) -> Result<(), OperationError> { - let cache_key = IdlCacheKey { - a: attr.to_string(), - i: itype.clone(), - k: idx_key.to_string(), - }; - // On idl == 0 the db will remove this, and synthesise an empty IDL on a miss - // but we can cache this as a new empty IDL instead, so that we can avoid the - // db lookup on this idl. - if idl.len() == 0 { - self.idl_cache - .insert(cache_key, Box::new(IDLBitRange::new())); - } else { - self.idl_cache.insert(cache_key, Box::new(idl.clone())); - } - self.db.write_idl(audit, attr, itype, idx_key, idl) + lperf_segment!(audit, "be::idl_arc_sqlite::write_idl", || { + let cache_key = IdlCacheKey { + a: attr.to_string(), + i: itype.clone(), + k: idx_key.to_string(), + }; + // On idl == 0 the db will remove this, and synthesise an empty IDL on a miss + // but we can cache this as a new empty IDL instead, so that we can avoid the + // db lookup on this idl. + if idl.len() == 0 { + self.idl_cache + .insert(cache_key, Box::new(IDLBitRange::new())); + } else { + self.idl_cache.insert(cache_key, Box::new(idl.clone())); + } + self.db.write_idl(audit, attr, itype, idx_key, idl) + }) } pub fn create_name2uuid(&self, audit: &mut AuditScope) -> Result<(), OperationError> { diff --git a/kanidmd/src/lib/be/idl_sqlite.rs b/kanidmd/src/lib/be/idl_sqlite.rs index 3a335e0ac..1d2425641 100644 --- a/kanidmd/src/lib/be/idl_sqlite.rs +++ b/kanidmd/src/lib/be/idl_sqlite.rs @@ -79,10 +79,12 @@ pub trait IdlSqliteTransaction { au: &mut AuditScope, idl: &IDL, ) -> Result>, OperationError> { - self.get_identry_raw(au, idl)? - .into_iter() - .map(|ide| ide.into_entry()) - .collect() + lperf_segment!(au, "be::idl_sqlite::get_identry", || { + self.get_identry_raw(au, idl)? + .into_iter() + .map(|ide| ide.into_entry()) + .collect() + }) } fn get_identry_raw( @@ -203,49 +205,50 @@ pub trait IdlSqliteTransaction { itype: &IndexType, idx_key: &str, ) -> Result, OperationError> { - if !(self.exists_idx(audit, attr, itype)?) { - audit_log!(audit, "Index {:?} {:?} not found", itype, attr); - return Ok(None); - } - // The table exists - lets now get the actual index itself. - - let query = format!( - "SELECT idl FROM idx_{}_{} WHERE key = :idx_key", - itype.as_idx_str(), - attr - ); - let mut stmt = try_audit!( - audit, - self.get_conn().prepare(query.as_str()), - "SQLite Error {:?}", - OperationError::SQLiteError - ); - let idl_raw: Option> = try_audit!( - audit, - stmt.query_row_named(&[(":idx_key", &idx_key)], |row| row.get(0)) - // We don't mind if it doesn't exist - .optional(), - "SQLite Error {:?}", - OperationError::SQLiteError - ); - - let idl = match idl_raw { - Some(d) => { - serde_cbor::from_slice(d.as_slice()).map_err(|_| OperationError::SerdeCborError)? + lperf_segment!(audit, "be::idl_sqlite::get_idl", || { + if !(self.exists_idx(audit, attr, itype)?) { + audit_log!(audit, "Index {:?} {:?} not found", itype, attr); + return Ok(None); } - // We don't have this value, it must be empty (or we - // have a corrupted index ..... - None => IDLBitRange::new(), - }; - audit_log!( - audit, - "Got idl for index {:?} {:?} -> {:?}", - itype, - attr, - idl - ); + // The table exists - lets now get the actual index itself. - Ok(Some(idl)) + let query = format!( + "SELECT idl FROM idx_{}_{} WHERE key = :idx_key", + itype.as_idx_str(), + attr + ); + let mut stmt = try_audit!( + audit, + self.get_conn().prepare(query.as_str()), + "SQLite Error {:?}", + OperationError::SQLiteError + ); + let idl_raw: Option> = try_audit!( + audit, + stmt.query_row_named(&[(":idx_key", &idx_key)], |row| row.get(0)) + // We don't mind if it doesn't exist + .optional(), + "SQLite Error {:?}", + OperationError::SQLiteError + ); + + let idl = match idl_raw { + Some(d) => serde_cbor::from_slice(d.as_slice()) + .map_err(|_| OperationError::SerdeCborError)?, + // We don't have this value, it must be empty (or we + // have a corrupted index ..... + None => IDLBitRange::new(), + }; + audit_log!( + audit, + "Got idl for index {:?} {:?} -> {:?}", + itype, + attr, + idl + ); + + Ok(Some(idl)) + }) } /* @@ -414,17 +417,19 @@ impl IdlSqliteWriteTransaction { } pub fn commit(mut self, audit: &mut AuditScope) -> Result<(), OperationError> { - audit_log!(audit, "Commiting BE txn"); - assert!(!self.committed); - self.committed = true; + lperf_segment!(audit, "be::idl_sqlite::commit", || { + audit_log!(audit, "Commiting BE txn"); + assert!(!self.committed); + self.committed = true; - self.conn - .execute("COMMIT TRANSACTION", NO_PARAMS) - .map(|_| ()) - .map_err(|e| { - println!("{:?}", e); - OperationError::BackendEngine - }) + self.conn + .execute("COMMIT TRANSACTION", NO_PARAMS) + .map(|_| ()) + .map_err(|e| { + println!("{:?}", e); + OperationError::BackendEngine + }) + }) } pub fn get_id2entry_max_id(&self) -> Result { @@ -460,18 +465,21 @@ impl IdlSqliteWriteTransaction { where I: Iterator>, { - let raw_entries: Result, _> = entries - .map(|e| { - let dbe = e.to_dbentry(); - let data = serde_cbor::to_vec(&dbe).map_err(|_| OperationError::SerdeCborError)?; + lperf_segment!(au, "be::idl_sqlite::write_identries", || { + let raw_entries: Result, _> = entries + .map(|e| { + let dbe = e.to_dbentry(); + let data = + serde_cbor::to_vec(&dbe).map_err(|_| OperationError::SerdeCborError)?; - Ok(IdRawEntry { - id: e.get_id(), - data, + Ok(IdRawEntry { + id: e.get_id(), + data, + }) }) - }) - .collect(); - self.write_identries_raw(au, raw_entries?.into_iter()) + .collect(); + self.write_identries_raw(au, raw_entries?.into_iter()) + }) } pub fn write_identries_raw( @@ -507,30 +515,32 @@ impl IdlSqliteWriteTransaction { where I: Iterator, { - let mut stmt = try_audit!( - au, - self.conn.prepare("DELETE FROM id2entry WHERE id = :id"), - "SQLite Error {:?}", - OperationError::SQLiteError - ); + lperf_segment!(au, "be::idl_sqlite::delete_identry", || { + let mut stmt = try_audit!( + au, + self.conn.prepare("DELETE FROM id2entry WHERE id = :id"), + "SQLite Error {:?}", + OperationError::SQLiteError + ); - idl.try_for_each(|id| { - let iid: i64 = id - .try_into() - .map_err(|_| OperationError::InvalidEntryID) - .and_then(|i| { - if i > 0 { - Ok(i) - } else { - Err(OperationError::InvalidEntryID) - } - })?; + idl.try_for_each(|id| { + let iid: i64 = id + .try_into() + .map_err(|_| OperationError::InvalidEntryID) + .and_then(|i| { + if i > 0 { + Ok(i) + } else { + Err(OperationError::InvalidEntryID) + } + })?; - debug_assert!(iid > 0); + debug_assert!(iid > 0); - stmt.execute(&[&iid]) - .map(|_| ()) - .map_err(|_| OperationError::SQLiteError) + stmt.execute(&[&iid]) + .map(|_| ()) + .map_err(|_| OperationError::SQLiteError) + }) }) } @@ -542,48 +552,52 @@ impl IdlSqliteWriteTransaction { idx_key: &str, idl: &IDLBitRange, ) -> Result<(), OperationError> { - if idl.len() == 0 { - audit_log!(audit, "purging idl -> {:?}", idl); - // delete it - // Delete this idx_key from the table. - let query = format!( - "DELETE FROM idx_{}_{} WHERE key = :key", - itype.as_idx_str(), - attr - ); + lperf_segment!(audit, "be::idl_sqlite::write_idl", || { + if idl.len() == 0 { + audit_log!(audit, "purging idl -> {:?}", idl); + // delete it + // Delete this idx_key from the table. + let query = format!( + "DELETE FROM idx_{}_{} WHERE key = :key", + itype.as_idx_str(), + attr + ); - self.conn - .prepare(query.as_str()) - .and_then(|mut stmt| stmt.execute_named(&[(":key", &idx_key)])) - .map_err(|e| { - audit_log!(audit, "SQLite Error {:?}", e); - OperationError::SQLiteError - }) - } else { - audit_log!(audit, "writing idl -> {:?}", idl); - // Serialise the IDL to Vec - let idl_raw = serde_cbor::to_vec(idl).map_err(|e| { - audit_log!(audit, "Serde CBOR Error -> {:?}", e); - OperationError::SerdeCborError - })?; + self.conn + .prepare(query.as_str()) + .and_then(|mut stmt| stmt.execute_named(&[(":key", &idx_key)])) + .map_err(|e| { + audit_log!(audit, "SQLite Error {:?}", e); + OperationError::SQLiteError + }) + } else { + audit_log!(audit, "writing idl -> {:?}", idl); + // Serialise the IDL to Vec + let idl_raw = serde_cbor::to_vec(idl).map_err(|e| { + audit_log!(audit, "Serde CBOR Error -> {:?}", e); + OperationError::SerdeCborError + })?; - // update or create it. - let query = format!( - "INSERT OR REPLACE INTO idx_{}_{} (key, idl) VALUES(:key, :idl)", - itype.as_idx_str(), - attr - ); + // update or create it. + let query = format!( + "INSERT OR REPLACE INTO idx_{}_{} (key, idl) VALUES(:key, :idl)", + itype.as_idx_str(), + attr + ); - self.conn - .prepare(query.as_str()) - .and_then(|mut stmt| stmt.execute_named(&[(":key", &idx_key), (":idl", &idl_raw)])) - .map_err(|e| { - audit_log!(audit, "SQLite Error {:?}", e); - OperationError::SQLiteError - }) - } - // Get rid of the sqlite rows usize - .map(|_| ()) + self.conn + .prepare(query.as_str()) + .and_then(|mut stmt| { + stmt.execute_named(&[(":key", &idx_key), (":idl", &idl_raw)]) + }) + .map_err(|e| { + audit_log!(audit, "SQLite Error {:?}", e); + OperationError::SQLiteError + }) + } + // Get rid of the sqlite rows usize + .map(|_| ()) + }) } pub fn create_name2uuid(&self, audit: &mut AuditScope) -> Result<(), OperationError> { diff --git a/kanidmd/src/lib/be/mod.rs b/kanidmd/src/lib/be/mod.rs index e2068145a..0b2d14edc 100644 --- a/kanidmd/src/lib/be/mod.rs +++ b/kanidmd/src/lib/be/mod.rs @@ -303,14 +303,16 @@ pub trait BackendTransaction { // // Unlike DS, even if we don't get the index back, we can just pass // to the in-memory filter test and be done. - audit_segment!(au, || { + lperf_segment!(au, "be::search", || { // Do a final optimise of the filter let filt = filt.optimise(); audit_log!(au, "filter optimised to --> {:?}", filt); // Using the indexes, resolve the IDL here, or ALLIDS. // Also get if the filter was 100% resolved or not. - let idl = self.filter2idl(au, filt.to_inner(), FILTER_TEST_THRESHOLD)?; + let idl = lperf_segment!(au, "be::search -> filter2idl", || { + self.filter2idl(au, filt.to_inner(), FILTER_TEST_THRESHOLD) + })?; let entries = try_audit!(au, self.get_idlayer().get_identry(au, &idl)); // Do other things @@ -358,14 +360,16 @@ pub trait BackendTransaction { au: &mut AuditScope, filt: &Filter, ) -> Result { - audit_segment!(au, || { + lperf_segment!(au, "be::exists", || { // Do a final optimise of the filter let filt = filt.optimise(); audit_log!(au, "filter optimised to --> {:?}", filt); // Using the indexes, resolve the IDL here, or ALLIDS. // Also get if the filter was 100% resolved or not. - let idl = self.filter2idl(au, filt.to_inner(), FILTER_TEST_THRESHOLD)?; + let idl = lperf_segment!(au, "be::exists -> filter2idl", || { + self.filter2idl(au, filt.to_inner(), FILTER_TEST_THRESHOLD) + })?; // Now, check the idl -- if it's fully resolved, we can skip this because the query // was fully indexed. @@ -451,9 +455,7 @@ impl<'a> BackendWriteTransaction<'a> { au: &mut AuditScope, entries: Vec>, ) -> Result>, OperationError> { - // figured we would want a audit_segment to wrap internal_create so when doing profiling we can - // tell which function is calling it. either this one or restore. - audit_segment!(au, || { + lperf_segment!(au, "be::create", || { if entries.is_empty() { audit_log!( au, @@ -492,56 +494,58 @@ impl<'a> BackendWriteTransaction<'a> { pre_entries: &[Entry], post_entries: &[Entry], ) -> Result<(), OperationError> { - if post_entries.is_empty() || pre_entries.is_empty() { - audit_log!( - au, - "No entries provided to BE to modify, invalid server call!" - ); - return Err(OperationError::EmptyRequest); - } + lperf_segment!(au, "be::modify", || { + if post_entries.is_empty() || pre_entries.is_empty() { + audit_log!( + au, + "No entries provided to BE to modify, invalid server call!" + ); + return Err(OperationError::EmptyRequest); + } - assert!(post_entries.len() == pre_entries.len()); + assert!(post_entries.len() == pre_entries.len()); - /* - // Assert the Id's exist on the entry, and serialise them. - // Now, that means the ID must be > 0!!! - let ser_entries: Result, _> = post_entries - .iter() - .map(|e| { - let id = i64::try_from(e.get_id()) - .map_err(|_| OperationError::InvalidEntryID) - .and_then(|id| { - if id == 0 { - Err(OperationError::InvalidEntryID) - } else { - Ok(id) - } - })?; + /* + // Assert the Id's exist on the entry, and serialise them. + // Now, that means the ID must be > 0!!! + let ser_entries: Result, _> = post_entries + .iter() + .map(|e| { + let id = i64::try_from(e.get_id()) + .map_err(|_| OperationError::InvalidEntryID) + .and_then(|id| { + if id == 0 { + Err(OperationError::InvalidEntryID) + } else { + Ok(id) + } + })?; - Ok(IdEntry { id, data: e.clone() }) - }) - .collect(); + Ok(IdEntry { id, data: e.clone() }) + }) + .collect(); - let ser_entries = try_audit!(au, ser_entries); + let ser_entries = try_audit!(au, ser_entries); - // Simple: If the list of id's is not the same as the input list, we are missing id's - // - // The entry state checks prevent this from really ever being triggered, but we - // still prefer paranoia :) - if post_entries.len() != ser_entries.len() { - return Err(OperationError::InvalidEntryState); - } - */ + // Simple: If the list of id's is not the same as the input list, we are missing id's + // + // The entry state checks prevent this from really ever being triggered, but we + // still prefer paranoia :) + if post_entries.len() != ser_entries.len() { + return Err(OperationError::InvalidEntryState); + } + */ - // Now, given the list of id's, update them - self.idlayer.write_identries(au, post_entries.iter())?; + // Now, given the list of id's, update them + self.idlayer.write_identries(au, post_entries.iter())?; - // Finally, we now reindex all the changed entries. We do this by iterating and zipping - // over the set, because we know the list is in the same order. - pre_entries - .iter() - .zip(post_entries.iter()) - .try_for_each(|(pre, post)| self.entry_index(au, Some(pre), Some(post))) + // Finally, we now reindex all the changed entries. We do this by iterating and zipping + // over the set, because we know the list is in the same order. + pre_entries + .iter() + .zip(post_entries.iter()) + .try_for_each(|(pre, post)| self.entry_index(au, Some(pre), Some(post))) + }) } pub fn delete( @@ -549,8 +553,7 @@ impl<'a> BackendWriteTransaction<'a> { au: &mut AuditScope, entries: &[Entry], ) -> Result<(), OperationError> { - // Perform a search for the entries --> This is a problem for the caller - audit_segment!(au, || { + lperf_segment!(au, "be::delete", || { if entries.is_empty() { audit_log!( au, @@ -894,7 +897,7 @@ impl<'a> BackendWriteTransaction<'a> { impl Backend { pub fn new(audit: &mut AuditScope, path: &str, pool_size: u32) -> Result { // this has a ::memory() type, but will path == "" work? - audit_segment!(audit, || { + lperf_segment!(audit, "be::new", || { let be = Backend { idlayer: Arc::new(IdlArcSqlite::new(audit, path, pool_size)?), }; diff --git a/kanidmd/src/lib/plugins/base.rs b/kanidmd/src/lib/plugins/base.rs index d17af3b0b..f330f8fe2 100644 --- a/kanidmd/src/lib/plugins/base.rs +++ b/kanidmd/src/lib/plugins/base.rs @@ -176,9 +176,7 @@ impl Plugin for Base { // internal exists is actually a wrapper around a search for uuid internally // // But does it add value? How many people will try to custom define/add uuid? - let mut au_qs = AuditScope::new("qs_exist"); - let r = qs.internal_exists(&mut au_qs, filt_in); - au.append_scope(au_qs); + let r = qs.internal_exists(au, filt_in); match r { Ok(b) => { diff --git a/kanidmd/src/lib/plugins/macros.rs b/kanidmd/src/lib/plugins/macros.rs index 6568895b1..5ff5327ae 100644 --- a/kanidmd/src/lib/plugins/macros.rs +++ b/kanidmd/src/lib/plugins/macros.rs @@ -47,7 +47,7 @@ macro_rules! run_create_test { use crate::utils::duration_from_epoch_now; let mut au = AuditScope::new("run_create_test"); - audit_segment!(au, || { + lperf_segment!(&mut au, "plugins::macros::run_create_test", || { let qs = setup_test!(&mut au, $preload_entries); let ce = match $internal { @@ -57,29 +57,26 @@ macro_rules! run_create_test { }, }; - let mut au_test = AuditScope::new("create_test"); { let mut qs_write = qs.write(duration_from_epoch_now()); - let r = qs_write.create(&mut au_test, &ce); + let r = qs_write.create(&mut au, &ce); debug!("r: {:?}", r); assert!(r == $expect); - $check(&mut au_test, &mut qs_write); + $check(&mut au, &mut qs_write); match r { Ok(_) => { - qs_write.commit(&mut au_test).expect("commit failure!"); + qs_write.commit(&mut au).expect("commit failure!"); } Err(e) => { - audit_log!(&mut au_test, "Rolling back => {:?}", e); + audit_log!(&mut au, "Rolling back => {:?}", e); } } } // Make sure there are no errors. debug!("starting verification"); - let ver = qs.verify(&mut au_test); + let ver = qs.verify(&mut au); debug!("verification -> {:?}", ver); assert!(ver.len() == 0); - - au.append_scope(au_test); }); // Dump the raw audit log. println!("{}", au); @@ -105,7 +102,7 @@ macro_rules! run_modify_test { use crate::utils::duration_from_epoch_now; let mut au = AuditScope::new("run_modify_test"); - audit_segment!(au, || { + lperf_segment!(&mut au, "plugins::macros::run_modify_test", || { let qs = setup_test!(&mut au, $preload_entries); let me = match $internal { @@ -115,29 +112,34 @@ macro_rules! run_modify_test { }, }; - let mut au_test = AuditScope::new("modify_test"); { let mut qs_write = qs.write(duration_from_epoch_now()); - let r = qs_write.modify(&mut au_test, &me); - $check(&mut au_test, &mut qs_write); + let r = lperf_segment!( + &mut au, + "plugins::macros::run_modify_test -> main_test", + || { qs_write.modify(&mut au, &me) } + ); + lperf_segment!( + &mut au, + "plugins::macros::run_modify_test -> post_test check", + || { $check(&mut au, &mut qs_write) } + ); debug!("{:?}", r); assert!(r == $expect); match r { Ok(_) => { - qs_write.commit(&mut au_test).expect("commit failure!"); + qs_write.commit(&mut au).expect("commit failure!"); } Err(e) => { - audit_log!(&mut au_test, "Rolling back => {:?}", e); + audit_log!(&mut au, "Rolling back => {:?}", e); } } } // Make sure there are no errors. debug!("starting verification"); - let ver = qs.verify(&mut au_test); + let ver = qs.verify(&mut au); debug!("verification -> {:?}", ver); assert!(ver.len() == 0); - - au.append_scope(au_test); }); // Dump the raw audit log. println!("{}", au); @@ -162,7 +164,7 @@ macro_rules! run_delete_test { use crate::utils::duration_from_epoch_now; let mut au = AuditScope::new("run_delete_test"); - audit_segment!(au, || { + lperf_segment!(&mut au, "plugins::macros::run_delete_test", || { let qs = setup_test!(&mut au, $preload_entries); let de = match $internal { @@ -172,28 +174,25 @@ macro_rules! run_delete_test { None => unsafe { DeleteEvent::new_internal_invalid($delete_filter.clone()) }, }; - let mut au_test = AuditScope::new("delete_test"); { let mut qs_write = qs.write(duration_from_epoch_now()); - let r = qs_write.delete(&mut au_test, &de); - $check(&mut au_test, &mut qs_write); + let r = qs_write.delete(&mut au, &de); + $check(&mut au, &mut qs_write); assert!(r == $expect); match r { Ok(_) => { - qs_write.commit(&mut au_test).expect("commit failure!"); + qs_write.commit(&mut au).expect("commit failure!"); } Err(e) => { - audit_log!(&mut au_test, "Rolling back => {:?}", e); + audit_log!(&mut au, "Rolling back => {:?}", e); } } } // Make sure there are no errors. debug!("starting verification"); - let ver = qs.verify(&mut au_test); + let ver = qs.verify(&mut au); debug!("verification -> {:?}", ver); assert!(ver.len() == 0); - - au.append_scope(au_test); }); // Dump the raw audit log. println!("{}", au); diff --git a/kanidmd/src/lib/plugins/mod.rs b/kanidmd/src/lib/plugins/mod.rs index a0e375755..4f6b6e454 100644 --- a/kanidmd/src/lib/plugins/mod.rs +++ b/kanidmd/src/lib/plugins/mod.rs @@ -123,14 +123,9 @@ macro_rules! run_pre_create_transform_plugin { $ce:ident, $target_plugin:ty ) => {{ - let mut audit_scope = AuditScope::new(<$target_plugin>::id()); - let r = audit_segment!(audit_scope, || <$target_plugin>::pre_create_transform( - &mut audit_scope, - $qs, - $cand, - $ce, - )); - $au.append_scope(audit_scope); + let r = lperf_segment!($au, <$target_plugin>::id(), || { + <$target_plugin>::pre_create_transform($au, $qs, $cand, $ce) + }); r }}; } @@ -143,14 +138,11 @@ macro_rules! run_pre_create_plugin { $ce:ident, $target_plugin:ty ) => {{ - let mut audit_scope = AuditScope::new(<$target_plugin>::id()); - let r = audit_segment!(audit_scope, || <$target_plugin>::pre_create( - &mut audit_scope, - $qs, - $cand, - $ce, - )); - $au.append_scope(audit_scope); + let r = lperf_segment!( + $au, + <$target_plugin>::id(), + || <$target_plugin>::pre_create($au, $qs, $cand, $ce,) + ); r }}; } @@ -163,14 +155,9 @@ macro_rules! run_post_create_plugin { $ce:ident, $target_plugin:ty ) => {{ - let mut audit_scope = AuditScope::new(<$target_plugin>::id()); - let r = audit_segment!(audit_scope, || <$target_plugin>::post_create( - &mut audit_scope, - $qs, - $cand, - $ce, - )); - $au.append_scope(audit_scope); + let r = lperf_segment!($au, <$target_plugin>::id(), || { + <$target_plugin>::post_create($au, $qs, $cand, $ce) + }); r }}; } @@ -183,14 +170,11 @@ macro_rules! run_pre_modify_plugin { $ce:ident, $target_plugin:ty ) => {{ - let mut audit_scope = AuditScope::new(<$target_plugin>::id()); - let r = audit_segment!(audit_scope, || <$target_plugin>::pre_modify( - &mut audit_scope, - $qs, - $cand, - $ce - )); - $au.append_scope(audit_scope); + let r = lperf_segment!( + $au, + <$target_plugin>::id(), + || <$target_plugin>::pre_modify($au, $qs, $cand, $ce) + ); r }}; } @@ -204,15 +188,9 @@ macro_rules! run_post_modify_plugin { $ce:ident, $target_plugin:ty ) => {{ - let mut audit_scope = AuditScope::new(<$target_plugin>::id()); - let r = audit_segment!(audit_scope, || <$target_plugin>::post_modify( - &mut audit_scope, - $qs, - $pre_cand, - $cand, - $ce - )); - $au.append_scope(audit_scope); + let r = lperf_segment!($au, <$target_plugin>::id(), || { + <$target_plugin>::post_modify($au, $qs, $pre_cand, $cand, $ce) + }); r }}; } @@ -225,14 +203,11 @@ macro_rules! run_pre_delete_plugin { $ce:ident, $target_plugin:ty ) => {{ - let mut audit_scope = AuditScope::new(<$target_plugin>::id()); - let r = audit_segment!(audit_scope, || <$target_plugin>::pre_delete( - &mut audit_scope, - $qs, - $cand, - $ce, - )); - $au.append_scope(audit_scope); + let r = lperf_segment!( + $au, + <$target_plugin>::id(), + || <$target_plugin>::pre_delete($au, $qs, $cand, $ce,) + ); r }}; } @@ -245,14 +220,9 @@ macro_rules! run_post_delete_plugin { $ce:ident, $target_plugin:ty ) => {{ - let mut audit_scope = AuditScope::new(<$target_plugin>::id()); - let r = audit_segment!(audit_scope, || <$target_plugin>::post_delete( - &mut audit_scope, - $qs, - $cand, - $ce, - )); - $au.append_scope(audit_scope); + let r = lperf_segment!($au, <$target_plugin>::id(), || { + <$target_plugin>::post_delete($au, $qs, $cand, $ce) + }); r }}; } @@ -264,13 +234,10 @@ macro_rules! run_verify_plugin { $results:expr, $target_plugin:ty ) => {{ - let mut audit_scope = AuditScope::new(<$target_plugin>::id()); - let mut r = audit_segment!(audit_scope, || <$target_plugin>::verify( - &mut audit_scope, - $qs, + let mut r = lperf_segment!($au, <$target_plugin>::id(), || <$target_plugin>::verify( + $au, $qs, )); $results.append(&mut r); - $au.append_scope(audit_scope); }}; } @@ -281,7 +248,7 @@ impl Plugins { cand: &mut Vec>, ce: &CreateEvent, ) -> Result<(), OperationError> { - audit_segment!(au, || { + lperf_segment!(au, "plugins::run_pre_create_transform", || { run_pre_create_transform_plugin!(au, qs, cand, ce, base::Base) .and_then(|_| { run_pre_create_transform_plugin!( @@ -310,7 +277,7 @@ impl Plugins { cand: &[Entry], ce: &CreateEvent, ) -> Result<(), OperationError> { - audit_segment!(au, || run_pre_create_plugin!( + lperf_segment!(au, "plugins::run_pre_create", || run_pre_create_plugin!( au, qs, cand, @@ -325,7 +292,7 @@ impl Plugins { cand: &[Entry], ce: &CreateEvent, ) -> Result<(), OperationError> { - audit_segment!(au, || run_post_create_plugin!( + lperf_segment!(au, "plugins::run_post_create", || run_post_create_plugin!( au, qs, cand, @@ -347,7 +314,7 @@ impl Plugins { cand: &mut Vec>, me: &ModifyEvent, ) -> Result<(), OperationError> { - audit_segment!(au, || { + lperf_segment!(au, "plugins::run_pre_modify", || { run_pre_modify_plugin!(au, qs, cand, me, protected::Protected) .and_then(|_| run_pre_modify_plugin!(au, qs, cand, me, base::Base)) .and_then(|_| { @@ -367,7 +334,7 @@ impl Plugins { cand: &[Entry], me: &ModifyEvent, ) -> Result<(), OperationError> { - audit_segment!(au, || run_post_modify_plugin!( + lperf_segment!(au, "plugins::run_post_modify", || run_post_modify_plugin!( au, qs, pre_cand, @@ -392,7 +359,7 @@ impl Plugins { cand: &mut Vec>, de: &DeleteEvent, ) -> Result<(), OperationError> { - audit_segment!(au, || run_pre_delete_plugin!( + lperf_segment!(au, "plugins::run_pre_delete", || run_pre_delete_plugin!( au, qs, cand, @@ -407,7 +374,7 @@ impl Plugins { cand: &[Entry], de: &DeleteEvent, ) -> Result<(), OperationError> { - audit_segment!(au, || run_post_delete_plugin!( + lperf_segment!(au, "plugins::run_post_delete", || run_post_delete_plugin!( au, qs, cand, diff --git a/kanidmd/src/lib/plugins/refint.rs b/kanidmd/src/lib/plugins/refint.rs index b92139003..73e88e25e 100644 --- a/kanidmd/src/lib/plugins/refint.rs +++ b/kanidmd/src/lib/plugins/refint.rs @@ -43,11 +43,9 @@ impl ReferentialIntegrity { "uuid could not become reference value".to_string() )) ); - let mut au_qs = AuditScope::new("qs_exist"); // NOTE: This only checks LIVE entries (not using filter_all) let filt_in = filter!(f_eq("uuid", PartialValue::new_uuid(*uuid))); - let r = qs.internal_exists(&mut au_qs, filt_in); - au.append_scope(au_qs); + let r = qs.internal_exists(au, filt_in); let b = try_audit!(au, r); // Is the reference in the result set? diff --git a/kanidmd/src/lib/schema.rs b/kanidmd/src/lib/schema.rs index 2335a5c6d..5cdbb3ddb 100644 --- a/kanidmd/src/lib/schema.rs +++ b/kanidmd/src/lib/schema.rs @@ -616,8 +616,7 @@ impl<'a> SchemaWriteTransaction<'a> { } pub fn generate_in_memory(&mut self, audit: &mut AuditScope) -> Result<(), OperationError> { - let mut au = AuditScope::new("generate_in_memory"); - let r = audit_segment!(au, || { + let r = lperf_segment!(audit, "schema::generate_in_memory", || { // self.classes.clear(); self.attributes.clear(); @@ -1340,8 +1339,8 @@ impl<'a> SchemaWriteTransaction<'a> { }, ); - let r = self.validate(&mut au); - audit_log!(au, "{:?}", r); + let r = self.validate(audit); + audit_log!(audit, "{:?}", r); if r.is_empty() { self.reload_idxmeta(); Ok(()) @@ -1349,8 +1348,6 @@ impl<'a> SchemaWriteTransaction<'a> { Err(OperationError::ConsistencyError(r)) } }); - - audit.append_scope(au); r } } diff --git a/kanidmd/src/lib/server.rs b/kanidmd/src/lib/server.rs index 6e802bc04..d1bf3cba6 100644 --- a/kanidmd/src/lib/server.rs +++ b/kanidmd/src/lib/server.rs @@ -86,22 +86,22 @@ pub trait QueryServerTransaction { au: &mut AuditScope, se: &SearchEvent, ) -> Result>, OperationError> { - /* - * This just wraps search, but it's for the external interface - * so as a result it also reduces the entry set's attributes at - * the end. - */ - let entries = self.search(au, se)?; + lperf_segment!(au, "server::search_ext", || { + /* + * This just wraps search, but it's for the external interface + * so as a result it also reduces the entry set's attributes at + * the end. + */ + let entries = self.search(au, se)?; - let mut audit_acp = AuditScope::new("access_control_profiles"); - let access = self.get_accesscontrols(); - let acp_res = access.search_filter_entry_attributes(&mut audit_acp, se, entries); - au.append_scope(audit_acp); - // Log and fail if something went wrong. - let entries_filtered = try_audit!(au, acp_res); + let access = self.get_accesscontrols(); + let acp_res = access.search_filter_entry_attributes(au, se, entries); + // Log and fail if something went wrong. + let entries_filtered = try_audit!(au, acp_res); - // This is the final entry set that was reduced. - Ok(entries_filtered) + // This is the final entry set that was reduced. + Ok(entries_filtered) + }) } fn search( @@ -109,65 +109,59 @@ pub trait QueryServerTransaction { au: &mut AuditScope, se: &SearchEvent, ) -> Result>, OperationError> { - audit_log!(au, "search: filter -> {:?}", se.filter); + lperf_segment!(au, "server::search", || { + audit_log!(au, "search: filter -> {:?}", se.filter); - // This is an important security step because it prevents us from - // performing un-indexed searches on attr's that don't exist in the - // server. This is why ExtensibleObject can only take schema that - // exists in the server, not arbitrary attr names. - // - // This normalises and validates in a single step. - // - // NOTE: Filters are validated in event conversion. + // This is an important security step because it prevents us from + // performing un-indexed searches on attr's that don't exist in the + // server. This is why ExtensibleObject can only take schema that + // exists in the server, not arbitrary attr names. + // + // This normalises and validates in a single step. + // + // NOTE: Filters are validated in event conversion. - let schema = self.get_schema(); - let idxmeta = schema.get_idxmeta_set(); - // Now resolve all references and indexes. - let vfr = try_audit!(au, se.filter.resolve(&se.event, Some(&idxmeta))); + let schema = self.get_schema(); + let idxmeta = schema.get_idxmeta_set(); + // Now resolve all references and indexes. + let vfr = try_audit!(au, se.filter.resolve(&se.event, Some(&idxmeta))); - // NOTE: We currently can't build search plugins due to the inability to hand - // the QS wr/ro to the plugin trait. However, there shouldn't be a need for search - // plugis, because all data transforms should be in the write path. + // NOTE: We currently can't build search plugins due to the inability to hand + // the QS wr/ro to the plugin trait. However, there shouldn't be a need for search + // plugis, because all data transforms should be in the write path. - let mut audit_be = AuditScope::new("backend_search"); - let res = self - .get_be_txn() - .search(&mut audit_be, &vfr) - .map(|r| r) - .map_err(|_| OperationError::Backend); - au.append_scope(audit_be); + let res = self + .get_be_txn() + .search(au, &vfr) + .map(|r| r) + .map_err(|_| OperationError::Backend); - let res = try_audit!(au, res); + let res = try_audit!(au, res); - // Apply ACP before we let the plugins "have at it". - // WARNING; for external searches this is NOT the only - // ACP application. There is a second application to reduce the - // attribute set on the entries! - // - let mut audit_acp = AuditScope::new("access_control_profiles"); - let access = self.get_accesscontrols(); - let acp_res = access.search_filter_entries(&mut audit_acp, se, res); + // Apply ACP before we let the plugins "have at it". + // WARNING; for external searches this is NOT the only + // ACP application. There is a second application to reduce the + // attribute set on the entries! + // + let access = self.get_accesscontrols(); + let acp_res = access.search_filter_entries(au, se, res); + let acp_res = try_audit!(au, acp_res); - au.append_scope(audit_acp); - let acp_res = try_audit!(au, acp_res); - - Ok(acp_res) + Ok(acp_res) + }) } fn exists(&mut self, au: &mut AuditScope, ee: &ExistsEvent) -> Result { - let mut audit_be = AuditScope::new("backend_exists"); + lperf_segment!(au, "server::exists", || { + let schema = self.get_schema(); + let idxmeta = schema.get_idxmeta_set(); + let vfr = try_audit!(au, ee.filter.resolve(&ee.event, Some(&idxmeta))); - let schema = self.get_schema(); - let idxmeta = schema.get_idxmeta_set(); - let vfr = try_audit!(au, ee.filter.resolve(&ee.event, Some(&idxmeta))); - - let res = self - .get_be_txn() - .exists(&mut audit_be, &vfr) - .map(|r| r) - .map_err(|_| OperationError::Backend); - au.append_scope(audit_be); - res + self.get_be_txn() + .exists(au, &vfr) + .map(|r| r) + .map_err(|_| OperationError::Backend) + }) } // Should this actually be names_to_uuids and we do batches? @@ -187,38 +181,40 @@ pub trait QueryServerTransaction { // Remember, we don't care if the name is invalid, because search // will validate/normalise the filter we construct for us. COOL! fn name_to_uuid(&mut self, audit: &mut AuditScope, name: &str) -> Result { - // For now this just constructs a filter and searches, but later - // we could actually improve this to contact the backend and do - // index searches, completely bypassing id2entry. + lperf_segment!(audit, "server::name_to_uuid", || { + // For now this just constructs a filter and searches, but later + // we could actually improve this to contact the backend and do + // index searches, completely bypassing id2entry. - // construct the filter - // Internal search - DO NOT SEARCH TOMBSTONES AND RECYCLE - let filt = filter!(f_eq("name", PartialValue::new_iutf8s(name))); - audit_log!(audit, "name_to_uuid: name -> {:?}", name); + // construct the filter + // Internal search - DO NOT SEARCH TOMBSTONES AND RECYCLE + let filt = filter!(f_eq("name", PartialValue::new_iutf8s(name))); + audit_log!(audit, "name_to_uuid: name -> {:?}", name); - let res = match self.internal_search(audit, filt) { - Ok(e) => e, - Err(e) => return Err(e), - }; + let res = match self.internal_search(audit, filt) { + Ok(e) => e, + Err(e) => return Err(e), + }; - audit_log!(audit, "name_to_uuid: results -- {:?}", res); + audit_log!(audit, "name_to_uuid: results -- {:?}", res); - if res.is_empty() { - // If result len == 0, error no such result - return Err(OperationError::NoMatchingEntries); - } else if res.len() >= 2 { - // if result len >= 2, error, invaid entry state. - return Err(OperationError::InvalidDBState); - } + if res.is_empty() { + // If result len == 0, error no such result + return Err(OperationError::NoMatchingEntries); + } else if res.len() >= 2 { + // if result len >= 2, error, invaid entry state. + return Err(OperationError::InvalidDBState); + } - // error should never be triggered due to the len checks above. - let e = res.first().ok_or(OperationError::NoMatchingEntries)?; - // Get the uuid from the entry. Again, check it exists, and only one. - let uuid_res: Uuid = *e.get_uuid(); + // error should never be triggered due to the len checks above. + let e = res.first().ok_or(OperationError::NoMatchingEntries)?; + // Get the uuid from the entry. Again, check it exists, and only one. + let uuid_res: Uuid = *e.get_uuid(); - audit_log!(audit, "name_to_uuid: uuid <- {:?}", uuid_res); + audit_log!(audit, "name_to_uuid: uuid <- {:?}", uuid_res); - Ok(uuid_res) + Ok(uuid_res) + }) } fn uuid_to_name( @@ -226,49 +222,51 @@ pub trait QueryServerTransaction { audit: &mut AuditScope, uuid: &Uuid, ) -> Result, OperationError> { - // construct the filter - let filt = filter!(f_eq("uuid", PartialValue::new_uuidr(uuid))); - audit_log!(audit, "uuid_to_name: uuid -> {:?}", uuid); + lperf_segment!(audit, "server::uuid_to_name", || { + // construct the filter + let filt = filter!(f_eq("uuid", PartialValue::new_uuidr(uuid))); + audit_log!(audit, "uuid_to_name: uuid -> {:?}", uuid); - // Internal search - DO NOT SEARCH TOMBSTONES AND RECYCLE - let res = match self.internal_search(audit, filt) { - Ok(e) => e, - Err(e) => return Err(e), - }; + // Internal search - DO NOT SEARCH TOMBSTONES AND RECYCLE + let res = match self.internal_search(audit, filt) { + Ok(e) => e, + Err(e) => return Err(e), + }; - audit_log!(audit, "uuid_to_name: results -- {:?}", res); + audit_log!(audit, "uuid_to_name: results -- {:?}", res); - if res.is_empty() { - // If result len == 0, error no such result - audit_log!(audit, "uuid_to_name: name, no such entry <- Ok(None)"); - return Ok(None); - } else if res.len() >= 2 { - // if result len >= 2, error, invaid entry state. - return Err(OperationError::InvalidDBState); - } - - // fine for 0/1 case, but check len for >= 2 to eliminate that case. - let e = res.first().ok_or(OperationError::NoMatchingEntries)?; - // Get the uuid from the entry. Again, check it exists, and only one. - let name_res = match e.get_ava(&String::from("name")) { - Some(vas) => match vas.first() { - Some(u) => (*u).clone(), - // Name is in an invalid state in the db - None => return Err(OperationError::InvalidEntryState), - }, - None => { - // No attr name, some types this is valid, IE schema. - // return Err(OperationError::InvalidEntryState), + if res.is_empty() { + // If result len == 0, error no such result + audit_log!(audit, "uuid_to_name: name, no such entry <- Ok(None)"); return Ok(None); + } else if res.len() >= 2 { + // if result len >= 2, error, invaid entry state. + return Err(OperationError::InvalidDBState); } - }; - audit_log!(audit, "uuid_to_name: name <- {:?}", name_res); + // fine for 0/1 case, but check len for >= 2 to eliminate that case. + let e = res.first().ok_or(OperationError::NoMatchingEntries)?; + // Get the uuid from the entry. Again, check it exists, and only one. + let name_res = match e.get_ava(&String::from("name")) { + Some(vas) => match vas.first() { + Some(u) => (*u).clone(), + // Name is in an invalid state in the db + None => return Err(OperationError::InvalidEntryState), + }, + None => { + // No attr name, some types this is valid, IE schema. + // return Err(OperationError::InvalidEntryState), + return Ok(None); + } + }; - // Make sure it's the right type ... (debug only) - debug_assert!(name_res.is_insensitive_utf8()); + audit_log!(audit, "uuid_to_name: name <- {:?}", name_res); - Ok(Some(name_res)) + // Make sure it's the right type ... (debug only) + debug_assert!(name_res.is_insensitive_utf8()); + + Ok(Some(name_res)) + }) } fn posixid_to_uuid( @@ -276,40 +274,42 @@ pub trait QueryServerTransaction { audit: &mut AuditScope, name: &str, ) -> Result { - let f_name = Some(f_eq("name", PartialValue::new_iutf8s(name))); + lperf_segment!(audit, "server::posixid_to_uuid", || { + let f_name = Some(f_eq("name", PartialValue::new_iutf8s(name))); - let f_spn = PartialValue::new_spn_s(name).map(|v| f_eq("spn", v)); + let f_spn = PartialValue::new_spn_s(name).map(|v| f_eq("spn", v)); - let f_gidnumber = PartialValue::new_uint32_str(name).map(|v| f_eq("gidnumber", v)); + let f_gidnumber = PartialValue::new_uint32_str(name).map(|v| f_eq("gidnumber", v)); - let x = vec![f_name, f_spn, f_gidnumber]; + let x = vec![f_name, f_spn, f_gidnumber]; - let filt = filter!(f_or(x.into_iter().filter_map(|v| v).collect())); - audit_log!(audit, "posixid_to_uuid: name -> {:?}", name); + let filt = filter!(f_or(x.into_iter().filter_map(|v| v).collect())); + audit_log!(audit, "posixid_to_uuid: name -> {:?}", name); - let res = match self.internal_search(audit, filt) { - Ok(e) => e, - Err(e) => return Err(e), - }; + let res = match self.internal_search(audit, filt) { + Ok(e) => e, + Err(e) => return Err(e), + }; - audit_log!(audit, "posixid_to_uuid: results -- {:?}", res); + audit_log!(audit, "posixid_to_uuid: results -- {:?}", res); - if res.is_empty() { - // If result len == 0, error no such result - return Err(OperationError::NoMatchingEntries); - } else if res.len() >= 2 { - // if result len >= 2, error, invaid entry state. - return Err(OperationError::InvalidDBState); - } + if res.is_empty() { + // If result len == 0, error no such result + return Err(OperationError::NoMatchingEntries); + } else if res.len() >= 2 { + // if result len >= 2, error, invaid entry state. + return Err(OperationError::InvalidDBState); + } - // error should never be triggered due to the len checks above. - let e = res.first().ok_or(OperationError::NoMatchingEntries)?; - // Get the uuid from the entry. Again, check it exists, and only one. - let uuid_res: Uuid = *e.get_uuid(); + // error should never be triggered due to the len checks above. + let e = res.first().ok_or(OperationError::NoMatchingEntries)?; + // Get the uuid from the entry. Again, check it exists, and only one. + let uuid_res: Uuid = *e.get_uuid(); - audit_log!(audit, "posixid_to_uuid: uuid <- {:?}", uuid_res); + audit_log!(audit, "posixid_to_uuid: uuid <- {:?}", uuid_res); - Ok(uuid_res) + Ok(uuid_res) + }) } // From internal, generate an exists event and dispatch @@ -318,18 +318,18 @@ pub trait QueryServerTransaction { au: &mut AuditScope, filter: Filter, ) -> Result { - // Check the filter - let f_valid = filter - .validate(self.get_schema()) - .map_err(OperationError::SchemaViolation)?; - // Build an exists event - let ee = ExistsEvent::new_internal(f_valid); - // Submit it - let mut audit_int = AuditScope::new("internal_exists"); - let res = self.exists(&mut audit_int, &ee); - au.append_scope(audit_int); - // return result - res + lperf_segment!(au, "server::internal_exists", || { + // Check the filter + let f_valid = filter + .validate(self.get_schema()) + .map_err(OperationError::SchemaViolation)?; + // Build an exists event + let ee = ExistsEvent::new_internal(f_valid); + // Submit it + let res = self.exists(au, &ee); + // return result + res + }) } fn internal_search( @@ -337,14 +337,14 @@ pub trait QueryServerTransaction { audit: &mut AuditScope, filter: Filter, ) -> Result>, OperationError> { - let f_valid = filter - .validate(self.get_schema()) - .map_err(OperationError::SchemaViolation)?; - let se = SearchEvent::new_internal(f_valid); - let mut audit_int = AuditScope::new("internal_search"); - let res = self.search(&mut audit_int, &se); - audit.append_scope(audit_int); - res + lperf_segment!(audit, "server::internal_search", || { + let f_valid = filter + .validate(self.get_schema()) + .map_err(OperationError::SchemaViolation)?; + let se = SearchEvent::new_internal(f_valid); + let res = self.search(audit, &se); + res + }) } fn impersonate_search_valid( @@ -354,11 +354,11 @@ pub trait QueryServerTransaction { f_intent_valid: Filter, event: &Event, ) -> Result>, OperationError> { - let se = SearchEvent::new_impersonate(event, f_valid, f_intent_valid); - let mut audit_int = AuditScope::new("impersonate_search"); - let res = self.search(&mut audit_int, &se); - audit.append_scope(audit_int); - res + lperf_segment!(audit, "server::internal_search_valid", || { + let se = SearchEvent::new_impersonate(event, f_valid, f_intent_valid); + let res = self.search(audit, &se); + res + }) } // this applys ACP to filter result entries. @@ -370,13 +370,12 @@ pub trait QueryServerTransaction { event: &Event, ) -> Result>, OperationError> { let se = SearchEvent::new_impersonate(event, f_valid, f_intent_valid); - let mut audit_int = AuditScope::new("impersonate_search_ext"); - let res = self.search_ext(&mut audit_int, &se); - audit.append_scope(audit_int); + let res = self.search_ext(audit, &se); res } // Who they are will go here + /* fn impersonate_search( &mut self, audit: &mut AuditScope, @@ -392,6 +391,7 @@ pub trait QueryServerTransaction { .map_err(OperationError::SchemaViolation)?; self.impersonate_search_valid(audit, f_valid, f_intent_valid, event) } + */ fn impersonate_search_ext( &mut self, @@ -400,13 +400,15 @@ pub trait QueryServerTransaction { filter_intent: Filter, event: &Event, ) -> Result>, OperationError> { - let f_valid = filter - .validate(self.get_schema()) - .map_err(OperationError::SchemaViolation)?; - let f_intent_valid = filter_intent - .validate(self.get_schema()) - .map_err(OperationError::SchemaViolation)?; - self.impersonate_search_ext_valid(audit, f_valid, f_intent_valid, event) + lperf_segment!(audit, "server::internal_search_ext_valid", || { + let f_valid = filter + .validate(self.get_schema()) + .map_err(OperationError::SchemaViolation)?; + let f_intent_valid = filter_intent + .validate(self.get_schema()) + .map_err(OperationError::SchemaViolation)?; + self.impersonate_search_ext_valid(audit, f_valid, f_intent_valid, event) + }) } // Get a single entry by it's UUID. This is heavily relied on for internal @@ -416,25 +418,25 @@ pub trait QueryServerTransaction { audit: &mut AuditScope, uuid: &Uuid, ) -> Result, OperationError> { - let filter = filter!(f_eq("uuid", PartialValue::new_uuid(*uuid))); - let f_valid = filter - .validate(self.get_schema()) - .map_err(OperationError::SchemaViolation)?; - let se = SearchEvent::new_internal(f_valid); - let mut audit_int = AuditScope::new("internal_search_uuid"); - let res = self.search(&mut audit_int, &se); - audit.append_scope(audit_int); - match res { - Ok(vs) => { - if vs.len() > 1 { - return Err(OperationError::NoMatchingEntries); + lperf_segment!(audit, "server::internal_search_uuid", || { + let filter = filter!(f_eq("uuid", PartialValue::new_uuid(*uuid))); + let f_valid = filter + .validate(self.get_schema()) + .map_err(OperationError::SchemaViolation)?; + let se = SearchEvent::new_internal(f_valid); + let res = self.search(audit, &se); + match res { + Ok(vs) => { + if vs.len() > 1 { + return Err(OperationError::NoMatchingEntries); + } + vs.into_iter() + .next() + .ok_or(OperationError::NoMatchingEntries) } - vs.into_iter() - .next() - .ok_or(OperationError::NoMatchingEntries) + Err(e) => Err(e), } - Err(e) => Err(e), - } + }) } fn impersonate_search_ext_uuid( @@ -443,20 +445,22 @@ pub trait QueryServerTransaction { uuid: &Uuid, event: &Event, ) -> Result, OperationError> { - let filter_intent = filter_all!(f_eq("uuid", PartialValue::new_uuid(*uuid))); - let filter = filter!(f_eq("uuid", PartialValue::new_uuid(*uuid))); - let res = self.impersonate_search_ext(audit, filter, filter_intent, event); - match res { - Ok(vs) => { - if vs.len() > 1 { - return Err(OperationError::NoMatchingEntries); + lperf_segment!(audit, "server::internal_search_ext_uuid", || { + let filter_intent = filter_all!(f_eq("uuid", PartialValue::new_uuid(*uuid))); + let filter = filter!(f_eq("uuid", PartialValue::new_uuid(*uuid))); + let res = self.impersonate_search_ext(audit, filter, filter_intent, event); + match res { + Ok(vs) => { + if vs.len() > 1 { + return Err(OperationError::NoMatchingEntries); + } + vs.into_iter() + .next() + .ok_or(OperationError::NoMatchingEntries) } - vs.into_iter() - .next() - .ok_or(OperationError::NoMatchingEntries) + Err(e) => Err(e), } - Err(e) => Err(e), - } + }) } /// Do a schema aware conversion from a String:String to String:Value for modification @@ -680,23 +684,19 @@ impl<'a> QueryServerReadTransaction<'a> { // call various functions for validation, including possibly plugin // verifications. fn verify(&mut self, au: &mut AuditScope) -> Vec> { - let mut audit = AuditScope::new("verify"); - // If we fail after backend, we need to return NOW because we can't // assert any other faith in the DB states. // * backend let be_errs = self.get_be_txn().verify(); if !be_errs.is_empty() { - au.append_scope(audit); return be_errs; } // * in memory schema consistency. - let sc_errs = self.get_schema().validate(&mut audit); + let sc_errs = self.get_schema().validate(au); if !sc_errs.is_empty() { - au.append_scope(audit); return sc_errs; } @@ -706,7 +706,6 @@ impl<'a> QueryServerReadTransaction<'a> { .verify_indexes(); if !idx_errs.is_empty() { - au.append_scope(audit); return idx_errs; } */ @@ -716,10 +715,9 @@ impl<'a> QueryServerReadTransaction<'a> { // do their job. // Now, call the plugins verification system. - let pl_errs = Plugins::run_verify(&mut audit, self); + let pl_errs = Plugins::run_verify(au, self); // Finish up ... - au.append_scope(audit); pl_errs } } @@ -880,357 +878,328 @@ impl QueryServer { impl<'a> QueryServerWriteTransaction<'a> { pub fn create(&mut self, au: &mut AuditScope, ce: &CreateEvent) -> Result<(), OperationError> { - // The create event is a raw, read only representation of the request - // that was made to us, including information about the identity - // performing the request. + lperf_segment!(au, "server::create", || { + // The create event is a raw, read only representation of the request + // that was made to us, including information about the identity + // performing the request. - // Log the request + // Log the request - // TODO #67: Do we need limits on number of creates, or do we constraint - // based on request size in the frontend? + // TODO #67: Do we need limits on number of creates, or do we constraint + // based on request size in the frontend? - // Copy the entries to a writeable form, this involves assigning a - // change id so we can track what's happening. - let candidates: Vec> = - ce.entries.iter().map(|e| e.clone()).collect(); + // Copy the entries to a writeable form, this involves assigning a + // change id so we can track what's happening. + let candidates: Vec> = + ce.entries.iter().map(|e| e.clone()).collect(); - // Do we have rights to perform these creates? - // create_allow_operation - let mut audit_acp = AuditScope::new("access_control_profiles"); - let access = self.get_accesscontrols(); - let acp_res = access.create_allow_operation(&mut audit_acp, ce, &candidates); - au.append_scope(audit_acp); - if !try_audit!(au, acp_res) { - return Err(OperationError::AccessDenied); - } + // Do we have rights to perform these creates? + // create_allow_operation + let access = self.get_accesscontrols(); + let acp_res = access.create_allow_operation(au, ce, &candidates); + if !try_audit!(au, acp_res) { + return Err(OperationError::AccessDenied); + } - // Assign our replication metadata now, since we can proceed with this operation. - let mut candidates: Vec> = candidates - .into_iter() - .map(|e| e.clone().assign_cid(self.cid.clone())) - .collect(); + // Assign our replication metadata now, since we can proceed with this operation. + let mut candidates: Vec> = candidates + .into_iter() + .map(|e| e.clone().assign_cid(self.cid.clone())) + .collect(); - // run any pre plugins, giving them the list of mutable candidates. - // pre-plugins are defined here in their correct order of calling! - // I have no intent to make these dynamic or configurable. + // run any pre plugins, giving them the list of mutable candidates. + // pre-plugins are defined here in their correct order of calling! + // I have no intent to make these dynamic or configurable. - let mut audit_plugin_pre_transform = AuditScope::new("plugin_pre_create_transform"); - let plug_pre_transform_res = Plugins::run_pre_create_transform( - &mut audit_plugin_pre_transform, - self, - &mut candidates, - ce, - ); - au.append_scope(audit_plugin_pre_transform); + let plug_pre_transform_res = + Plugins::run_pre_create_transform(au, self, &mut candidates, ce); - try_audit!( - au, - plug_pre_transform_res, - "Create operation failed (pre_transform plugin), {:?}" - ); + try_audit!( + au, + plug_pre_transform_res, + "Create operation failed (pre_transform plugin), {:?}" + ); - // NOTE: This is how you map from Vec> to Result> - // remember, that you only get the first error and the iter terminates. + // NOTE: This is how you map from Vec> to Result> + // remember, that you only get the first error and the iter terminates. - // Now, normalise AND validate! + // Now, normalise AND validate! - let res: Result>, OperationError> = candidates - .into_iter() - .map(|e| { - e.validate(&self.schema) - .map_err(OperationError::SchemaViolation) - .map(|e| + let res: Result>, OperationError> = candidates + .into_iter() + .map(|e| { + e.validate(&self.schema) + .map_err(OperationError::SchemaViolation) + .map(|e| // Then seal the changes? e.seal()) - }) - .collect(); + }) + .collect(); - let norm_cand: Vec> = try_audit!(au, res); + let norm_cand: Vec> = try_audit!(au, res); - // Run any pre-create plugins now with schema validated entries. - // This is important for normalisation of certain types IE class - // or attributes for these checks. - let mut audit_plugin_pre = AuditScope::new("plugin_pre_create"); - let plug_pre_res = Plugins::run_pre_create(&mut audit_plugin_pre, self, &norm_cand, ce); - au.append_scope(audit_plugin_pre); + // Run any pre-create plugins now with schema validated entries. + // This is important for normalisation of certain types IE class + // or attributes for these checks. + let plug_pre_res = Plugins::run_pre_create(au, self, &norm_cand, ce); - try_audit!(au, plug_pre_res, "Create operation failed (plugin), {:?}"); + try_audit!(au, plug_pre_res, "Create operation failed (plugin), {:?}"); - let mut audit_be = AuditScope::new("backend_create"); - // We may change from ce.entries later to something else? - let res = self.be_txn.create(&mut audit_be, norm_cand).map_err(|e| e); + // We may change from ce.entries later to something else? + let res = self.be_txn.create(au, norm_cand).map_err(|e| e); - au.append_scope(audit_be); + let commit_cand = try_audit!(au, res); + // Run any post plugins - let commit_cand = try_audit!(au, res); - // Run any post plugins + let plug_post_res = Plugins::run_post_create(au, self, &commit_cand, ce); - let mut audit_plugin_post = AuditScope::new("plugin_post_create"); - let plug_post_res = - Plugins::run_post_create(&mut audit_plugin_post, self, &commit_cand, ce); - au.append_scope(audit_plugin_post); + if plug_post_res.is_err() { + audit_log!( + au, + "Create operation failed (post plugin), {:?}", + plug_post_res + ); + return plug_post_res; + } - if plug_post_res.is_err() { + // We have finished all plugs and now have a successful operation - flag if + // schema or acp requires reload. + self.changed_schema = commit_cand.iter().fold(false, |acc, e| { + if acc { + acc + } else { + e.attribute_value_pres("class", &PVCLASS_CLASSTYPE) + || e.attribute_value_pres("class", &PVCLASS_ATTRIBUTETYPE) + } + }); + self.changed_acp = commit_cand.iter().fold(false, |acc, e| { + if acc { + acc + } else { + e.attribute_value_pres("class", &PVCLASS_ACP) + } + }); audit_log!( au, - "Create operation failed (post plugin), {:?}", - plug_post_res + "Schema reload: {:?}, ACP reload: {:?}", + self.changed_schema, + self.changed_acp ); - return plug_post_res; - } - // We have finished all plugs and now have a successful operation - flag if - // schema or acp requires reload. - self.changed_schema = commit_cand.iter().fold(false, |acc, e| { - if acc { - acc - } else { - e.attribute_value_pres("class", &PVCLASS_CLASSTYPE) - || e.attribute_value_pres("class", &PVCLASS_ATTRIBUTETYPE) - } - }); - self.changed_acp = commit_cand.iter().fold(false, |acc, e| { - if acc { - acc - } else { - e.attribute_value_pres("class", &PVCLASS_ACP) - } - }); - audit_log!( - au, - "Schema reload: {:?}, ACP reload: {:?}", - self.changed_schema, - self.changed_acp - ); + // We are complete, finalise logging and return - // We are complete, finalise logging and return - - audit_log!(au, "Create operation success"); - Ok(()) + audit_log!(au, "Create operation success"); + Ok(()) + }) } pub fn delete(&mut self, au: &mut AuditScope, de: &DeleteEvent) -> Result<(), OperationError> { - // Do you have access to view all the set members? Reduce based on your - // read permissions and attrs - // THIS IS PRETTY COMPLEX SEE THE DESIGN DOC - // In this case we need a search, but not INTERNAL to keep the same - // associated credentials. - // We only need to retrieve uuid though ... + lperf_segment!(au, "server::delete", || { + // Do you have access to view all the set members? Reduce based on your + // read permissions and attrs + // THIS IS PRETTY COMPLEX SEE THE DESIGN DOC + // In this case we need a search, but not INTERNAL to keep the same + // associated credentials. + // We only need to retrieve uuid though ... - // Now, delete only what you can see - let pre_candidates = match self.impersonate_search_valid( - au, - de.filter.clone(), - de.filter_orig.clone(), - &de.event, - ) { - Ok(results) => results, - Err(e) => { - audit_log!(au, "delete: error in pre-candidate selection {:?}", e); - return Err(e); + // Now, delete only what you can see + let pre_candidates = match self.impersonate_search_valid( + au, + de.filter.clone(), + de.filter_orig.clone(), + &de.event, + ) { + Ok(results) => results, + Err(e) => { + audit_log!(au, "delete: error in pre-candidate selection {:?}", e); + return Err(e); + } + }; + + // Apply access controls to reduce the set if required. + // delete_allow_operation + let access = self.get_accesscontrols(); + let acp_res = access.delete_allow_operation(au, de, &pre_candidates); + if !try_audit!(au, acp_res) { + return Err(OperationError::AccessDenied); } - }; - // Apply access controls to reduce the set if required. - // delete_allow_operation - let mut audit_acp = AuditScope::new("access_control_profiles"); - let access = self.get_accesscontrols(); - let acp_res = access.delete_allow_operation(&mut audit_acp, de, &pre_candidates); - au.append_scope(audit_acp); - if !try_audit!(au, acp_res) { - return Err(OperationError::AccessDenied); - } + // Is the candidate set empty? + if pre_candidates.is_empty() { + audit_log!(au, "delete: no candidates match filter {:?}", de.filter); + return Err(OperationError::NoMatchingEntries); + }; - // Is the candidate set empty? - if pre_candidates.is_empty() { - audit_log!(au, "delete: no candidates match filter {:?}", de.filter); - return Err(OperationError::NoMatchingEntries); - }; + let mut candidates: Vec> = pre_candidates + .iter() + // Invalidate and assign change id's + .map(|er| er.clone().invalidate(self.cid.clone())) + .collect(); - let mut candidates: Vec> = pre_candidates - .iter() - // Invalidate and assign change id's - .map(|er| er.clone().invalidate(self.cid.clone())) - .collect(); + audit_log!(au, "delete: candidates -> {:?}", candidates); - audit_log!(au, "delete: candidates -> {:?}", candidates); + // Pre delete plugs + let plug_pre_res = Plugins::run_pre_delete(au, self, &mut candidates, de); - // Pre delete plugs - let mut audit_plugin_pre = AuditScope::new("plugin_pre_delete"); - let plug_pre_res = - Plugins::run_pre_delete(&mut audit_plugin_pre, self, &mut candidates, de); - au.append_scope(audit_plugin_pre); - - if plug_pre_res.is_err() { - audit_log!(au, "Delete operation failed (plugin), {:?}", plug_pre_res); - return plug_pre_res; - } - - audit_log!( - au, - "delete: now marking candidates as recycled -> {:?}", - candidates - ); - - let res: Result>, SchemaError> = candidates - .into_iter() - .map(|e| { - e.to_recycled() - .validate(&self.schema) - // seal if it worked. - .map(|r| r.seal()) - }) - .collect(); - - let del_cand: Vec> = match res { - Ok(v) => v, - Err(e) => return Err(OperationError::SchemaViolation(e)), - }; - - let mut audit_be = AuditScope::new("backend_modify"); - - let res = self - .be_txn - .modify(&mut audit_be, &pre_candidates, &del_cand); - au.append_scope(audit_be); - - if res.is_err() { - // be_txn is dropped, ie aborted here. - audit_log!(au, "Delete operation failed (backend), {:?}", res); - return res; - } - - // Post delete plugs - let mut audit_plugin_post = AuditScope::new("plugin_post_delete"); - let plug_post_res = Plugins::run_post_delete(&mut audit_plugin_post, self, &del_cand, de); - au.append_scope(audit_plugin_post); - - if plug_post_res.is_err() { - audit_log!(au, "Delete operation failed (plugin), {:?}", plug_post_res); - return plug_post_res; - } - - // We have finished all plugs and now have a successful operation - flag if - // schema or acp requires reload. - self.changed_schema = del_cand.iter().fold(false, |acc, e| { - if acc { - acc - } else { - e.attribute_value_pres("class", &PVCLASS_CLASSTYPE) - || e.attribute_value_pres("class", &PVCLASS_ATTRIBUTETYPE) + if plug_pre_res.is_err() { + audit_log!(au, "Delete operation failed (plugin), {:?}", plug_pre_res); + return plug_pre_res; } - }); - self.changed_acp = del_cand.iter().fold(false, |acc, e| { - if acc { - acc - } else { - e.attribute_value_pres("class", &PVCLASS_ACP) - } - }); - audit_log!( - au, - "Schema reload: {:?}, ACP reload: {:?}", - self.changed_schema, - self.changed_acp - ); - // Send result - audit_log!(au, "Delete operation success"); - res + audit_log!( + au, + "delete: now marking candidates as recycled -> {:?}", + candidates + ); + + let res: Result>, SchemaError> = candidates + .into_iter() + .map(|e| { + e.to_recycled() + .validate(&self.schema) + // seal if it worked. + .map(|r| r.seal()) + }) + .collect(); + + let del_cand: Vec> = match res { + Ok(v) => v, + Err(e) => return Err(OperationError::SchemaViolation(e)), + }; + + let res = self.be_txn.modify(au, &pre_candidates, &del_cand); + + if res.is_err() { + // be_txn is dropped, ie aborted here. + audit_log!(au, "Delete operation failed (backend), {:?}", res); + return res; + } + + // Post delete plugs + let plug_post_res = Plugins::run_post_delete(au, self, &del_cand, de); + + if plug_post_res.is_err() { + audit_log!(au, "Delete operation failed (plugin), {:?}", plug_post_res); + return plug_post_res; + } + + // We have finished all plugs and now have a successful operation - flag if + // schema or acp requires reload. + self.changed_schema = del_cand.iter().fold(false, |acc, e| { + if acc { + acc + } else { + e.attribute_value_pres("class", &PVCLASS_CLASSTYPE) + || e.attribute_value_pres("class", &PVCLASS_ATTRIBUTETYPE) + } + }); + self.changed_acp = del_cand.iter().fold(false, |acc, e| { + if acc { + acc + } else { + e.attribute_value_pres("class", &PVCLASS_ACP) + } + }); + audit_log!( + au, + "Schema reload: {:?}, ACP reload: {:?}", + self.changed_schema, + self.changed_acp + ); + + // Send result + audit_log!(au, "Delete operation success"); + res + }) } pub fn purge_tombstones(&mut self, au: &mut AuditScope) -> Result<(), OperationError> { - // delete everything that is a tombstone. + lperf_segment!(au, "server::purge_tombstones", || { + // delete everything that is a tombstone. + let cid = try_audit!(au, self.cid.sub_secs(CHANGELOG_MAX_AGE)); + let ts = match self.internal_search( + au, + filter_all!(f_and!([ + f_eq("class", PVCLASS_TOMBSTONE.clone()), + f_lt("last_modified_cid", PartialValue::new_cid(cid)), + ])), + ) { + Ok(r) => r, + Err(e) => return Err(e), + }; - // TODO #68: Has an appropriate amount of time/condition past (ie replication events?) - // Search for tombstones - let cid = try_audit!(au, self.cid.sub_secs(CHANGELOG_MAX_AGE)); - let ts = match self.internal_search( - au, - filter_all!(f_and!([ - f_eq("class", PVCLASS_TOMBSTONE.clone()), - f_lt("last_modified_cid", PartialValue::new_cid(cid)), - ])), - ) { - Ok(r) => r, - Err(e) => return Err(e), - }; + if ts.is_empty() { + audit_log!(au, "No Tombstones present - purge operation success"); + return Ok(()); + } - if ts.is_empty() { - audit_log!(au, "No Tombstones present - purge operation success"); - return Ok(()); - } + // Delete them + let res = self + .be_txn + // Change this to an update, not delete. + .delete(au, &ts); - // Delete them - let mut audit_be = AuditScope::new("backend_delete"); + if res.is_err() { + // be_txn is dropped, ie aborted here. + audit_log!(au, "Tombstone purge operation failed (backend), {:?}", res); + return res; + } - let res = self - .be_txn - // Change this to an update, not delete. - .delete(&mut audit_be, &ts); - au.append_scope(audit_be); - - if res.is_err() { - // be_txn is dropped, ie aborted here. - audit_log!(au, "Tombstone purge operation failed (backend), {:?}", res); - return res; - } - - // Send result - audit_log!(au, "Tombstone purge operation success"); - res + // Send result + audit_log!(au, "Tombstone purge operation success"); + res + }) } pub fn purge_recycled(&mut self, au: &mut AuditScope) -> Result<(), OperationError> { - // Send everything that is recycled to tombstone - // Search all recycled + lperf_segment!(au, "server::purge_recycled", || { + // Send everything that is recycled to tombstone + // Search all recycled - let cid = try_audit!(au, self.cid.sub_secs(RECYCLEBIN_MAX_AGE)); - let rc = match self.internal_search( - au, - filter_all!(f_and!([ - f_eq("class", PVCLASS_RECYCLED.clone()), - f_lt("last_modified_cid", PartialValue::new_cid(cid)), - ])), - ) { - Ok(r) => r, - Err(e) => return Err(e), - }; + let cid = try_audit!(au, self.cid.sub_secs(RECYCLEBIN_MAX_AGE)); + let rc = match self.internal_search( + au, + filter_all!(f_and!([ + f_eq("class", PVCLASS_RECYCLED.clone()), + f_lt("last_modified_cid", PartialValue::new_cid(cid)), + ])), + ) { + Ok(r) => r, + Err(e) => return Err(e), + }; - if rc.is_empty() { - audit_log!(au, "No recycled present - purge operation success"); - return Ok(()); - } + if rc.is_empty() { + audit_log!(au, "No recycled present - purge operation success"); + return Ok(()); + } - // Modify them to strip all avas except uuid - let tombstone_cand: Result, _> = rc - .iter() - .map(|e| { - e.to_tombstone(self.cid.clone()) - .validate(&self.schema) - .map_err(OperationError::SchemaViolation) - // seal if it worked. - .map(|r| r.seal()) - }) - .collect(); + // Modify them to strip all avas except uuid + let tombstone_cand: Result, _> = rc + .iter() + .map(|e| { + e.to_tombstone(self.cid.clone()) + .validate(&self.schema) + .map_err(OperationError::SchemaViolation) + // seal if it worked. + .map(|r| r.seal()) + }) + .collect(); - let tombstone_cand = try_audit!(au, tombstone_cand); + let tombstone_cand = try_audit!(au, tombstone_cand); - // Backend Modify - let mut audit_be = AuditScope::new("backend_modify"); + // Backend Modify + let res = self.be_txn.modify(au, &rc, &tombstone_cand); - let res = self.be_txn.modify(&mut audit_be, &rc, &tombstone_cand); - au.append_scope(audit_be); + if res.is_err() { + // be_txn is dropped, ie aborted here. + audit_log!(au, "Purge recycled operation failed (backend), {:?}", res); + return res; + } - if res.is_err() { - // be_txn is dropped, ie aborted here. - audit_log!(au, "Purge recycled operation failed (backend), {:?}", res); - return res; - } - - // return - audit_log!(au, "Purge recycled operation success"); - res + // return + audit_log!(au, "Purge recycled operation success"); + res + }) } // Should this take a revive event? @@ -1239,251 +1208,240 @@ impl<'a> QueryServerWriteTransaction<'a> { au: &mut AuditScope, re: &ReviveRecycledEvent, ) -> Result<(), OperationError> { - // Revive an entry to live. This is a specialised (limited) - // modify proxy. - // - // impersonate modify will require ability to search the class=recycled - // and the ability to remove that from the object. + lperf_segment!(au, "server::revive_recycled", || { + // Revive an entry to live. This is a specialised (limited) + // modify proxy. + // + // impersonate modify will require ability to search the class=recycled + // and the ability to remove that from the object. - // create the modify - // tl;dr, remove the class=recycled - let modlist = ModifyList::new_list(vec![Modify::Removed( - "class".to_string(), - PVCLASS_RECYCLED.clone(), - )]); + // create the modify + // tl;dr, remove the class=recycled + let modlist = ModifyList::new_list(vec![Modify::Removed( + "class".to_string(), + PVCLASS_RECYCLED.clone(), + )]); - let m_valid = try_audit!( - au, - modlist - .validate(self.get_schema()) - .map_err(OperationError::SchemaViolation) - ); + let m_valid = try_audit!( + au, + modlist + .validate(self.get_schema()) + .map_err(OperationError::SchemaViolation) + ); - // Get the entries we are about to revive. - // we make a set of per-entry mod lists. A list of lists even ... - let revive_cands = - self.impersonate_search_valid(au, re.filter.clone(), re.filter.clone(), &re.event)?; + // Get the entries we are about to revive. + // we make a set of per-entry mod lists. A list of lists even ... + let revive_cands = + self.impersonate_search_valid(au, re.filter.clone(), re.filter.clone(), &re.event)?; - let mut dm_mods: BTreeMap> = BTreeMap::new(); + let mut dm_mods: BTreeMap> = BTreeMap::new(); - revive_cands.into_iter().for_each(|e| { - // Get this entries uuid. - let u: Uuid = e.get_uuid().clone(); + revive_cands.into_iter().for_each(|e| { + // Get this entries uuid. + let u: Uuid = e.get_uuid().clone(); - e.get_ava_reference_uuid("directmemberof").and_then(|list| { - list.into_iter().for_each(|g_uuid| { - dm_mods - .entry(g_uuid.clone()) - .and_modify(|mlist| { - let m = Modify::Present("member".to_string(), Value::new_refer_r(&u)); - mlist.push_mod(m); - }) - .or_insert({ - let m = Modify::Present("member".to_string(), Value::new_refer_r(&u)); - ModifyList::new_list(vec![m]) - }); + e.get_ava_reference_uuid("directmemberof").and_then(|list| { + list.into_iter().for_each(|g_uuid| { + dm_mods + .entry(g_uuid.clone()) + .and_modify(|mlist| { + let m = + Modify::Present("member".to_string(), Value::new_refer_r(&u)); + mlist.push_mod(m); + }) + .or_insert({ + let m = + Modify::Present("member".to_string(), Value::new_refer_r(&u)); + ModifyList::new_list(vec![m]) + }); + }); + Some(()) }); - Some(()) }); - }); - // Now impersonate the modify - self.impersonate_modify_valid( - au, - re.filter.clone(), - re.filter.clone(), - m_valid, - &re.event, - )?; - // If and only if that succeeds, apply the direct membership modifications - // if possible. - let r: Result<_, _> = dm_mods - .into_iter() - .map(|(g, mods)| { - // I think the filter/filter_all shouldn't matter here because the only - // valid direct memberships should be still valid/live references. - let f = filter_all!(f_eq("uuid", PartialValue::new_uuid(g))); - self.internal_modify(au, f, mods) - }) - .collect(); - r + // Now impersonate the modify + self.impersonate_modify_valid( + au, + re.filter.clone(), + re.filter.clone(), + m_valid, + &re.event, + )?; + // If and only if that succeeds, apply the direct membership modifications + // if possible. + let r: Result<_, _> = dm_mods + .into_iter() + .map(|(g, mods)| { + // I think the filter/filter_all shouldn't matter here because the only + // valid direct memberships should be still valid/live references. + let f = filter_all!(f_eq("uuid", PartialValue::new_uuid(g))); + self.internal_modify(au, f, mods) + }) + .collect(); + r + }) } pub fn modify(&mut self, au: &mut AuditScope, me: &ModifyEvent) -> Result<(), OperationError> { - // Get the candidates. - // Modify applies a modlist to a filter, so we need to internal search - // then apply. + lperf_segment!(au, "server::modify", || { + // Get the candidates. + // Modify applies a modlist to a filter, so we need to internal search + // then apply. - // Validate input. + // Validate input. - // Is the modlist non zero? - if me.modlist.len() == 0 { - audit_log!(au, "modify: empty modify request"); - return Err(OperationError::EmptyRequest); - } - - // Is the modlist valid? - // This is now done in the event transform - - // Is the filter invalid to schema? - // This is now done in the event transform - - // This also checks access controls due to use of the impersonation. - let pre_candidates = match self.impersonate_search_valid( - au, - me.filter.clone(), - me.filter_orig.clone(), - &me.event, - ) { - Ok(results) => results, - Err(e) => { - audit_log!(au, "modify: error in pre-candidate selection {:?}", e); - return Err(e); + // Is the modlist non zero? + if me.modlist.len() == 0 { + audit_log!(au, "modify: empty modify request"); + return Err(OperationError::EmptyRequest); } - }; - if pre_candidates.is_empty() { - match me.event.origin { - EventOrigin::Internal => { - audit_log!( - au, - "modify: no candidates match filter ... continuing {:?}", - me.filter - ); - return Ok(()); + // Is the modlist valid? + // This is now done in the event transform + + // Is the filter invalid to schema? + // This is now done in the event transform + + // This also checks access controls due to use of the impersonation. + let pre_candidates = match self.impersonate_search_valid( + au, + me.filter.clone(), + me.filter_orig.clone(), + &me.event, + ) { + Ok(results) => results, + Err(e) => { + audit_log!(au, "modify: error in pre-candidate selection {:?}", e); + return Err(e); } - _ => { - audit_log!( - au, - "modify: no candidates match filter, failure {:?}", - me.filter - ); - return Err(OperationError::NoMatchingEntries); - } - } - }; + }; - // Are we allowed to make the changes we want to? - // modify_allow_operation - let mut audit_acp = AuditScope::new("access_control_profiles"); - let access = self.get_accesscontrols(); - let acp_res = access.modify_allow_operation(&mut audit_acp, me, &pre_candidates); - au.append_scope(audit_acp); - if !try_audit!(au, acp_res) { - return Err(OperationError::AccessDenied); - } - - // Clone a set of writeables. - // Apply the modlist -> Remember, we have a set of origs - // and the new modified ents. - let mut candidates: Vec> = pre_candidates - .iter() - .map(|er| er.clone().invalidate(self.cid.clone())) - .collect(); - - candidates - .iter_mut() - .for_each(|er| er.apply_modlist(&me.modlist)); - - audit_log!(au, "modify: candidates -> {:?}", candidates); - - // Pre mod plugins - let mut audit_plugin_pre = AuditScope::new("plugin_pre_modify"); - // We should probably supply the pre-post cands here. - let plug_pre_res = - Plugins::run_pre_modify(&mut audit_plugin_pre, self, &mut candidates, me); - au.append_scope(audit_plugin_pre); - - if plug_pre_res.is_err() { - audit_log!(au, "Modify operation failed (plugin), {:?}", plug_pre_res); - return plug_pre_res; - } - - // NOTE: There is a potential optimisation here, where if - // candidates == pre-candidates, then we don't need to store anything - // because we effectively just did an assert. However, like all - // optimisations, this could be premature - so we for now, just - // do the CORRECT thing and recommit as we may find later we always - // want to add CSN's or other. - - let res: Result>, SchemaError> = candidates - .into_iter() - .map(|e| e.validate(&self.schema).map(|e| e.seal())) - .collect(); - - let norm_cand: Vec> = match res { - Ok(v) => v, - Err(e) => return Err(OperationError::SchemaViolation(e)), - }; - - // Backend Modify - let mut audit_be = AuditScope::new("backend_modify"); - - let res = self - .be_txn - .modify(&mut audit_be, &pre_candidates, &norm_cand); - au.append_scope(audit_be); - - if res.is_err() { - // be_txn is dropped, ie aborted here. - audit_log!(au, "Modify operation failed (backend), {:?}", res); - return res; - } - - // Post Plugins - // - // memberOf actually wants the pre cand list and the norm_cand list to see what - // changed. Could be optimised, but this is correct still ... - let mut audit_plugin_post = AuditScope::new("plugin_post_modify"); - let plug_post_res = Plugins::run_post_modify( - &mut audit_plugin_post, - self, - &pre_candidates, - &norm_cand, - me, - ); - au.append_scope(audit_plugin_post); - - if plug_post_res.is_err() { - audit_log!(au, "Modify operation failed (plugin), {:?}", plug_post_res); - return plug_post_res; - } - - // We have finished all plugs and now have a successful operation - flag if - // schema or acp requires reload. Remember, this is a modify, so we need to check - // pre and post cands. - self.changed_schema = - norm_cand - .iter() - .chain(pre_candidates.iter()) - .fold(false, |acc, e| { - if acc { - acc - } else { - e.attribute_value_pres("class", &PVCLASS_CLASSTYPE) - || e.attribute_value_pres("class", &PVCLASS_ATTRIBUTETYPE) + if pre_candidates.is_empty() { + match me.event.origin { + EventOrigin::Internal => { + audit_log!( + au, + "modify: no candidates match filter ... continuing {:?}", + me.filter + ); + return Ok(()); + } + _ => { + audit_log!( + au, + "modify: no candidates match filter, failure {:?}", + me.filter + ); + return Err(OperationError::NoMatchingEntries); } - }); - self.changed_acp = norm_cand - .iter() - .chain(pre_candidates.iter()) - .fold(false, |acc, e| { - if acc { - acc - } else { - e.attribute_value_pres("class", &PVCLASS_ACP) } - }); - audit_log!( - au, - "Schema reload: {:?}, ACP reload: {:?}", - self.changed_schema, - self.changed_acp - ); + }; - // return - audit_log!(au, "Modify operation success"); - res + // Are we allowed to make the changes we want to? + // modify_allow_operation + let access = self.get_accesscontrols(); + let acp_res = access.modify_allow_operation(au, me, &pre_candidates); + if !try_audit!(au, acp_res) { + return Err(OperationError::AccessDenied); + } + + // Clone a set of writeables. + // Apply the modlist -> Remember, we have a set of origs + // and the new modified ents. + let mut candidates: Vec> = pre_candidates + .iter() + .map(|er| er.clone().invalidate(self.cid.clone())) + .collect(); + + candidates + .iter_mut() + .for_each(|er| er.apply_modlist(&me.modlist)); + + audit_log!(au, "modify: candidates -> {:?}", candidates); + + // Pre mod plugins + // We should probably supply the pre-post cands here. + let plug_pre_res = Plugins::run_pre_modify(au, self, &mut candidates, me); + + if plug_pre_res.is_err() { + audit_log!(au, "Modify operation failed (plugin), {:?}", plug_pre_res); + return plug_pre_res; + } + + // NOTE: There is a potential optimisation here, where if + // candidates == pre-candidates, then we don't need to store anything + // because we effectively just did an assert. However, like all + // optimisations, this could be premature - so we for now, just + // do the CORRECT thing and recommit as we may find later we always + // want to add CSN's or other. + + let res: Result>, SchemaError> = candidates + .into_iter() + .map(|e| e.validate(&self.schema).map(|e| e.seal())) + .collect(); + + let norm_cand: Vec> = match res { + Ok(v) => v, + Err(e) => return Err(OperationError::SchemaViolation(e)), + }; + + // Backend Modify + let res = self.be_txn.modify(au, &pre_candidates, &norm_cand); + + if res.is_err() { + // be_txn is dropped, ie aborted here. + audit_log!(au, "Modify operation failed (backend), {:?}", res); + return res; + } + + // Post Plugins + // + // memberOf actually wants the pre cand list and the norm_cand list to see what + // changed. Could be optimised, but this is correct still ... + let plug_post_res = Plugins::run_post_modify(au, self, &pre_candidates, &norm_cand, me); + + if plug_post_res.is_err() { + audit_log!(au, "Modify operation failed (plugin), {:?}", plug_post_res); + return plug_post_res; + } + + // We have finished all plugs and now have a successful operation - flag if + // schema or acp requires reload. Remember, this is a modify, so we need to check + // pre and post cands. + self.changed_schema = + norm_cand + .iter() + .chain(pre_candidates.iter()) + .fold(false, |acc, e| { + if acc { + acc + } else { + e.attribute_value_pres("class", &PVCLASS_CLASSTYPE) + || e.attribute_value_pres("class", &PVCLASS_ATTRIBUTETYPE) + } + }); + self.changed_acp = + norm_cand + .iter() + .chain(pre_candidates.iter()) + .fold(false, |acc, e| { + if acc { + acc + } else { + e.attribute_value_pres("class", &PVCLASS_ACP) + } + }); + audit_log!( + au, + "Schema reload: {:?}, ACP reload: {:?}", + self.changed_schema, + self.changed_acp + ); + + // return + audit_log!(au, "Modify operation success"); + res + }) } // These are where searches and other actions are actually implemented. This @@ -1496,11 +1454,9 @@ impl<'a> QueryServerWriteTransaction<'a> { entries: Vec>, ) -> Result<(), OperationError> { // Start the audit scope - let mut audit_int = AuditScope::new("internal_create"); // Create the CreateEvent let ce = CreateEvent::new_internal(entries); - let res = self.create(&mut audit_int, &ce); - audit.append_scope(audit_int); + let res = self.create(audit, &ce); res } @@ -1512,10 +1468,8 @@ impl<'a> QueryServerWriteTransaction<'a> { let f_valid = filter .validate(self.get_schema()) .map_err(OperationError::SchemaViolation)?; - let mut audit_int = AuditScope::new("internal_delete"); let de = DeleteEvent::new_internal(f_valid); - let res = self.delete(&mut audit_int, &de); - audit.append_scope(audit_int); + let res = self.delete(audit, &de); res } @@ -1525,17 +1479,17 @@ impl<'a> QueryServerWriteTransaction<'a> { filter: Filter, modlist: ModifyList, ) -> Result<(), OperationError> { - let f_valid = filter - .validate(self.get_schema()) - .map_err(OperationError::SchemaViolation)?; - let m_valid = modlist - .validate(self.get_schema()) - .map_err(OperationError::SchemaViolation)?; - let mut audit_int = AuditScope::new("internal_modify"); - let me = ModifyEvent::new_internal(f_valid, m_valid); - let res = self.modify(&mut audit_int, &me); - audit.append_scope(audit_int); - res + lperf_segment!(audit, "server::internal_modify", || { + let f_valid = filter + .validate(self.get_schema()) + .map_err(OperationError::SchemaViolation)?; + let m_valid = modlist + .validate(self.get_schema()) + .map_err(OperationError::SchemaViolation)?; + let me = ModifyEvent::new_internal(f_valid, m_valid); + let res = self.modify(audit, &me); + res + }) } pub fn impersonate_modify_valid( @@ -1546,10 +1500,8 @@ impl<'a> QueryServerWriteTransaction<'a> { m_valid: ModifyList, event: &Event, ) -> Result<(), OperationError> { - let mut audit_int = AuditScope::new("impersonate_modify"); let me = ModifyEvent::new_impersonate(event, f_valid, f_intent_valid, m_valid); - let res = self.modify(&mut audit_int, &me); - audit.append_scope(audit_int); + let res = self.modify(audit, &me); res } @@ -1602,16 +1554,16 @@ impl<'a> QueryServerWriteTransaction<'a> { audit: &mut AuditScope, e_str: &str, ) -> Result<(), OperationError> { - let res = audit_segment!(audit, || Entry::from_proto_entry_str(audit, e_str, self) - /* - .and_then(|e: Entry| { - let schema = self.get_schema(); - e.validate(schema).map_err(OperationError::SchemaViolation) - }) - */ - .and_then( - |e: Entry| self.internal_migrate_or_create(audit, e) - )); + let res = lperf_segment!(audit, "server::internal_migrate_or_create_str", || { + Entry::from_proto_entry_str(audit, e_str, self) + /* + .and_then(|e: Entry| { + let schema = self.get_schema(); + e.validate(schema).map_err(OperationError::SchemaViolation) + }) + */ + .and_then(|e: Entry| self.internal_migrate_or_create(audit, e)) + }); audit_log!(audit, "internal_migrate_or_create_str -> result {:?}", res); debug_assert!(res.is_ok()); res @@ -1776,13 +1728,11 @@ impl<'a> QueryServerWriteTransaction<'a> { JSON_SCHEMA_CLASS_SYSTEM_CONFIG, ]; - let mut audit_si = AuditScope::new("start_initialise_schema_idm"); let r: Result, _> = idm_schema .iter() // Each item individually logs it's result - .map(|e_str| self.internal_migrate_or_create_str(&mut audit_si, e_str)) + .map(|e_str| self.internal_migrate_or_create_str(audit, e_str)) .collect(); - audit.append_scope(audit_si); audit_log!(audit, "initialise_schema_idm -> result {:?}", r); debug_assert!(r.is_ok()); @@ -1794,14 +1744,10 @@ impl<'a> QueryServerWriteTransaction<'a> { // First, check the system_info object. This stores some server information // and details. It's a pretty const thing. Also check anonymous, important to many // concepts. - let mut audit_an = AuditScope::new("start_system_core_items"); let res = self - .internal_migrate_or_create_str(&mut audit_an, JSON_SYSTEM_INFO_V1) - .and_then(|_| self.internal_migrate_or_create_str(&mut audit_an, JSON_DOMAIN_INFO_V1)) - .and_then(|_| { - self.internal_migrate_or_create_str(&mut audit_an, JSON_SYSTEM_CONFIG_V1) - }); - audit.append_scope(audit_an); + .internal_migrate_or_create_str(audit, JSON_SYSTEM_INFO_V1) + .and_then(|_| self.internal_migrate_or_create_str(audit, JSON_DOMAIN_INFO_V1)) + .and_then(|_| self.internal_migrate_or_create_str(audit, JSON_SYSTEM_CONFIG_V1)); audit_log!(audit, "initialise_idm p1 -> result {:?}", res); debug_assert!(res.is_ok()); if res.is_err() { @@ -1820,13 +1766,11 @@ impl<'a> QueryServerWriteTransaction<'a> { JSON_IDM_ADMINS_V1, JSON_SYSTEM_ADMINS_V1, ]; - let mut audit_an = AuditScope::new("start_idm_admin_migrations"); let res: Result<(), _> = admin_entries .iter() // Each item individually logs it's result - .map(|e_str| self.internal_migrate_or_create_str(&mut audit_an, e_str)) + .map(|e_str| self.internal_migrate_or_create_str(audit, e_str)) .collect(); - audit.append_scope(audit_an); audit_log!(audit, "initialise_idm p2 -> result {:?}", res); debug_assert!(res.is_ok()); if res.is_err() { @@ -1836,7 +1780,6 @@ impl<'a> QueryServerWriteTransaction<'a> { // Create any system default schema entries. // Create any system default access profile entries. - let mut audit_an = AuditScope::new("start_idm_migrations_internal"); let idm_entries = [ // Builtin groups JSON_IDM_PEOPLE_MANAGE_PRIV_V1, @@ -1897,9 +1840,8 @@ impl<'a> QueryServerWriteTransaction<'a> { let res: Result<(), _> = idm_entries .iter() // Each item individually logs it's result - .map(|e_str| self.internal_migrate_or_create_str(&mut audit_an, e_str)) + .map(|e_str| self.internal_migrate_or_create_str(audit, e_str)) .collect(); - audit.append_scope(audit_an); audit_log!(audit, "initialise_idm p3 -> result {:?}", res); debug_assert!(res.is_ok()); if res.is_err() { @@ -1910,44 +1852,46 @@ impl<'a> QueryServerWriteTransaction<'a> { } fn reload_schema(&mut self, audit: &mut AuditScope) -> Result<(), OperationError> { - audit_log!(audit, "Schema reload started ..."); + lperf_segment!(audit, "server::reload_schema", || { + audit_log!(audit, "Schema reload started ..."); - // supply entries to the writable schema to reload from. - // find all attributes. - let filt = filter!(f_eq("class", PVCLASS_ATTRIBUTETYPE.clone())); - let res = try_audit!(audit, self.internal_search(audit, filt)); - // load them. - let attributetypes: Result, _> = res - .iter() - .map(|e| SchemaAttribute::try_from(audit, e)) - .collect(); - let attributetypes = try_audit!(audit, attributetypes); + // supply entries to the writable schema to reload from. + // find all attributes. + let filt = filter!(f_eq("class", PVCLASS_ATTRIBUTETYPE.clone())); + let res = try_audit!(audit, self.internal_search(audit, filt)); + // load them. + let attributetypes: Result, _> = res + .iter() + .map(|e| SchemaAttribute::try_from(audit, e)) + .collect(); + let attributetypes = try_audit!(audit, attributetypes); - try_audit!(audit, self.schema.update_attributes(attributetypes)); + try_audit!(audit, self.schema.update_attributes(attributetypes)); - // find all classes - let filt = filter!(f_eq("class", PVCLASS_CLASSTYPE.clone())); - let res = try_audit!(audit, self.internal_search(audit, filt)); - // load them. - let classtypes: Result, _> = res - .iter() - .map(|e| SchemaClass::try_from(audit, e)) - .collect(); - let classtypes = try_audit!(audit, classtypes); + // find all classes + let filt = filter!(f_eq("class", PVCLASS_CLASSTYPE.clone())); + let res = try_audit!(audit, self.internal_search(audit, filt)); + // load them. + let classtypes: Result, _> = res + .iter() + .map(|e| SchemaClass::try_from(audit, e)) + .collect(); + let classtypes = try_audit!(audit, classtypes); - try_audit!(audit, self.schema.update_classes(classtypes)); + try_audit!(audit, self.schema.update_classes(classtypes)); - // validate. - let valid_r = self.schema.validate(audit); + // validate. + let valid_r = self.schema.validate(audit); - // Translate the result. - if valid_r.is_empty() { - Ok(()) - } else { - // Log the failures? - audit_log!(audit, "Schema reload failed -> {:?}", valid_r); - Err(OperationError::ConsistencyError(valid_r)) - } + // Translate the result. + if valid_r.is_empty() { + Ok(()) + } else { + // Log the failures? + audit_log!(audit, "Schema reload failed -> {:?}", valid_r); + Err(OperationError::ConsistencyError(valid_r)) + } + }) } fn reload_accesscontrols(&mut self, audit: &mut AuditScope) -> Result<(), OperationError> {