mart-w/kanidm
1
0
Fork 0
mirror of https://github.com/kanidm/kanidm.git synced 2025-02-23 20:47:01 +01:00
Code Issues Actions Packages Projects Releases Wiki Activity

99 logging rewrite (#233)

Browse source 
* Phase 1 - fix audit log nesting
This commit is contained in:
Firstyear 2020-05-20 10:31:34 +10:00 committed by GitHub
parent d4e73ef5c9
commit 62d60d1afc
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
12 changed files with 2186 additions and 1968 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

615
kanidmd/src/lib/actors/v1_read.rs
View file

@ -205,7 +205,7 @@ impl Handler<SearchMessage> 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<SearchMessage>", || {
// Begin a read
let mut qs_read = self.qs.read();
@ -241,7 +241,7 @@ impl Handler<AuthMessage> 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<AuthMessage>", || {
audit_log!(audit, "Begin auth event {:?}", msg);
// Destructure it.
@ -282,7 +282,7 @@ impl Handler<WhoamiMessage> 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<WhoamiMessage>", || {
// TODO #62: Move this to IdmServer!!!
// Begin a read
let mut qs_read = self.qs.read();
@ -337,26 +337,30 @@ impl Handler<InternalSearchMessage> 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<InternalSearchMessage>",
|| {
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<InternalSearchRecycledMessage> 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<InternalSearchRecycledMessage>",
|| {
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<InternalRadiusReadMessage> 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<InternalRadiusReadMessage>",
|| {
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<InternalRadiusTokenReadMessage> 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<InternalRadiusTokenReadMessage>",
|| {
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<InternalUnixUserTokenReadMessage> 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<InternalUnixUserTokenReadMessage>",
|| {
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<InternalUnixGroupTokenReadMessage> 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<InternalUnixGroupTokenReadMessage>",
|| {
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<InternalSshKeyReadMessage> 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<InternalSshKeyReadMessage>",
|| {
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<InternalSshKeyTagReadMessage> 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<InternalSshKeyTagReadMessage>",
|| {
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<IdmAccountUnixAuthMessage> 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<IdmAccountUnixAuthMessage>",
|| {
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
}

978
kanidmd/src/lib/actors/v1_write.rs
View file

File diff suppressed because it is too large Load diff

259
kanidmd/src/lib/audit.rs
View file

@ -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<Duration>,
contains: Vec<PerfEvent>,
#[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<PerfProcessed>,
}
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<Ordering> {
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<Duration>,
events: Vec<AuditEvent>,
uuid: Uuid,
events: Vec<AuditLog>,
perf: Vec<PerfEvent>,
// 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<Utc> = 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<Utc> = 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;
}
}

178
kanidmd/src/lib/be/idl_arc_sqlite.rs
View file

@ -65,36 +65,38 @@ macro_rules! get_identry {
$au:expr,
$idl:expr
) => {{
match $idl {
IDL::Partial(idli) | IDL::Indexed(idli) => {
let mut result: Vec<Entry<_, _>> = 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<Entry<_, _>> = 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<Item = &'b Entry<EntrySealed, EntryCommitted>>,
{
// 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<I>(
@ -340,14 +348,16 @@ impl<'a> IdlArcSqliteWriteTransaction<'a> {
where
I: Iterator<Item = u64>,
{
// 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> {

264
kanidmd/src/lib/be/idl_sqlite.rs
View file

@ -79,10 +79,12 @@ pub trait IdlSqliteTransaction {
au: &mut AuditScope,
idl: &IDL,
) -> Result<Vec<Entry<EntrySealed, EntryCommitted>>, 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<Option<IDLBitRange>, 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<Vec<u8>> = 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<Vec<u8>> = 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<u64, OperationError> {
@ -460,18 +465,21 @@ impl IdlSqliteWriteTransaction {
where
I: Iterator<Item = &'b Entry<EntrySealed, EntryCommitted>>,
{
let raw_entries: Result<Vec<_>, _> = 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<Vec<_>, _> = 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<I>(
@ -507,30 +515,32 @@ impl IdlSqliteWriteTransaction {
where
I: Iterator<Item = u64>,
{
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<u8>
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<u8>
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> {

109
kanidmd/src/lib/be/mod.rs
View file

@ -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<FilterValidResolved>,
) -> Result<bool, OperationError> {
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<Entry<EntrySealed, EntryNew>>,
) -> Result<Vec<Entry<EntrySealed, EntryCommitted>>, 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<EntrySealed, EntryCommitted>],
post_entries: &[Entry<EntrySealed, EntryCommitted>],
) -> 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<Vec<IdEntry>, _> = 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<Vec<IdEntry>, _> = 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<EntrySealed, EntryCommitted>],
) -> 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<Self, OperationError> {
// 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)?),
};

4
kanidmd/src/lib/plugins/base.rs
View file

@ -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) => {

53
kanidmd/src/lib/plugins/macros.rs
View file

@ -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);

105
kanidmd/src/lib/plugins/mod.rs
View file

@ -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<Entry<EntryInvalid, EntryNew>>,
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<EntrySealed, EntryNew>],
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<EntrySealed, EntryCommitted>],
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<Entry<EntryInvalid, EntryCommitted>>,
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<EntrySealed, EntryCommitted>],
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<Entry<EntryInvalid, EntryCommitted>>,
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<EntrySealed, EntryCommitted>],
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,

4
kanidmd/src/lib/plugins/refint.rs
View file

@ -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?

9
kanidmd/src/lib/schema.rs
View file

@ -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
}
}

1576
kanidmd/src/lib/server.rs
View file

File diff suppressed because it is too large Load diff