Improved tracing (closes #180 closes #417 closes #376 closes #418 closes #517)

This commit is contained in:
mdecimus
2024-07-30 16:12:34 +02:00
parent a45eb50231
commit d29d21692e
65 changed files with 2005 additions and 1112 deletions

View File

@@ -6,9 +6,11 @@
use std::sync::atomic::{AtomicUsize, Ordering};
#[derive(Clone, Debug)]
pub struct Bitset<const N: usize>([usize; N]);
pub struct AtomicBitset<const N: usize>([AtomicUsize; N]);
const USIZE_BITS: usize = std::mem::size_of::<usize>() * 8;
pub(crate) const USIZE_BITS: usize = std::mem::size_of::<usize>() * 8;
const USIZE_BITS_MASK: usize = USIZE_BITS - 1;
impl<const N: usize> AtomicBitset<N> {
@@ -45,6 +47,13 @@ impl<const N: usize> AtomicBitset<N> {
self.0[index / USIZE_BITS].load(Ordering::Relaxed) & (1 << (index & USIZE_BITS_MASK)) != 0
}
pub fn update(&self, bitset: impl AsRef<Bitset<N>>) {
let bitset = bitset.as_ref();
for i in 0..N {
self.0[i].store(bitset.0[i], Ordering::Relaxed);
}
}
pub fn clear_all(&self) {
for i in 0..N {
self.0[i].store(0, Ordering::Relaxed);
@@ -52,6 +61,52 @@ impl<const N: usize> AtomicBitset<N> {
}
}
impl<const N: usize> Bitset<N> {
#[allow(clippy::new_without_default)]
pub const fn new() -> Self {
Self([0; N])
}
#[inline(always)]
pub fn set(&mut self, index: impl Into<usize>) {
let index = index.into();
self.0[index / USIZE_BITS] |= 1 << (index & USIZE_BITS_MASK);
}
#[inline(always)]
pub fn clear(&mut self, index: impl Into<usize>) {
let index = index.into();
self.0[index / USIZE_BITS] &= !(1 << (index & USIZE_BITS_MASK));
}
#[inline(always)]
pub fn get(&self, index: impl Into<usize>) -> bool {
let index = index.into();
self.0[index / USIZE_BITS] & (1 << (index & USIZE_BITS_MASK)) != 0
}
pub fn clear_all(&mut self) {
for i in 0..N {
self.0[i] = 0;
}
}
pub fn is_empty(&self) -> bool {
for i in 0..N {
if self.0[i] != 0 {
return false;
}
}
true
}
}
impl<const N: usize> Default for Bitset<N> {
fn default() -> Self {
Self::new()
}
}
#[cfg(test)]
mod tests {
use super::*;

View File

@@ -17,7 +17,7 @@ use rtrb::{Consumer, Producer, PushError, RingBuffer};
use crate::{
collector::{spawn_collector, CollectorThread},
Event,
Event, EventType,
};
pub(crate) static EVENT_RXS: Mutex<Vec<Receiver>> = Mutex::new(Vec::new());
@@ -37,20 +37,20 @@ thread_local! {
}
pub struct Sender {
tx: Producer<Arc<Event>>,
tx: Producer<Event<EventType>>,
collector: Arc<CollectorThread>,
overflow: Vec<Arc<Event>>,
overflow: Vec<Event<EventType>>,
}
pub struct Receiver {
rx: Consumer<Arc<Event>>,
rx: Consumer<Event<EventType>>,
}
#[derive(Debug)]
pub struct ChannelError;
impl Sender {
pub fn send(&mut self, event: Arc<Event>) -> Result<(), ChannelError> {
pub fn send(&mut self, event: Event<EventType>) -> Result<(), ChannelError> {
while let Some(event) = self.overflow.pop() {
if let Err(PushError::Full(event)) = self.tx.push(event) {
self.overflow.push(event);
@@ -71,7 +71,7 @@ impl Sender {
}
impl Receiver {
pub fn try_recv(&mut self) -> Result<Option<Arc<Event>>, ChannelError> {
pub fn try_recv(&mut self) -> Result<Option<Event<EventType>>, ChannelError> {
match self.rx.pop() {
Ok(event) => Ok(Some(event)),
Err(_) => {
@@ -85,12 +85,12 @@ impl Receiver {
}
}
impl Event {
impl Event<EventType> {
pub fn send(self) {
// SAFETY: EVENT_TX is thread-local.
let _ = EVENT_TX.try_with(|tx| unsafe {
let tx = &mut *tx.get();
if tx.send(Arc::new(self)).is_ok() {
if tx.send(self).is_ok() {
EVENT_COUNT.fetch_add(1, Ordering::Relaxed);
tx.collector.thread().unpark();
}

View File

@@ -5,31 +5,64 @@
*/
use std::{
sync::{
atomic::{AtomicUsize, Ordering},
Arc, OnceLock,
},
sync::{atomic::Ordering, Arc, OnceLock},
thread::{park, Builder, JoinHandle},
time::SystemTime,
};
use ahash::AHashMap;
use arc_swap::ArcSwap;
use parking_lot::Mutex;
use crate::{
bitset::{AtomicBitset, USIZE_BITS},
channel::{EVENT_COUNT, EVENT_RXS},
subscriber::{Subscriber, SUBSCRIBER_UPDATE},
Event, EventType, Level, ServerEvent,
subscriber::{Interests, Subscriber},
DeliveryEvent, Event, EventDetails, EventType, Level, NetworkEvent, ServerEvent,
TOTAL_EVENT_COUNT,
};
pub(crate) static TRACING_LEVEL: AtomicUsize = AtomicUsize::new(Level::Info as usize);
type GlobalInterests = AtomicBitset<{ (TOTAL_EVENT_COUNT + USIZE_BITS - 1) / USIZE_BITS }>;
pub(crate) static INTERESTS: GlobalInterests = GlobalInterests::new();
pub(crate) type CollectorThread = JoinHandle<()>;
pub(crate) static ACTIVE_SUBSCRIBERS: Mutex<Vec<String>> = Mutex::new(Vec::new());
pub(crate) static COLLECTOR_UPDATES: Mutex<Vec<Update>> = Mutex::new(Vec::new());
#[allow(clippy::enum_variant_names)]
pub(crate) enum Update {
Register {
subscriber: Subscriber,
},
Unregister {
id: String,
},
UpdateSubscriber {
id: String,
interests: Interests,
lossy: bool,
},
UpdateLevels {
custom_levels: AHashMap<EventType, Level>,
},
Shutdown,
}
#[derive(Default)]
pub struct Collector {
subscribers: Vec<Subscriber>,
custom_levels: AHashMap<EventType, Level>,
active_spans: AHashMap<u64, Arc<Event<EventDetails>>>,
}
const EV_CONN_START: usize = EventType::Network(NetworkEvent::ConnectionStart).id();
const EV_CONN_END: usize = EventType::Network(NetworkEvent::ConnectionEnd).id();
const EV_ATTEMPT_START: usize = EventType::Delivery(DeliveryEvent::AttemptStart).id();
const EV_ATTEMPT_END: usize = EventType::Delivery(DeliveryEvent::AttemptEnd).id();
const EV_COLLECTOR_UPDATE: usize = EventType::Server(ServerEvent::CollectorUpdate).id();
const STALE_SPAN_CHECK_WATERMARK: usize = 8000;
const SPAN_MAX_HOLD: u64 = 86400;
impl Collector {
fn collect(&mut self) -> bool {
if EVENT_COUNT.swap(0, Ordering::Relaxed) == 0 {
@@ -39,23 +72,81 @@ impl Collector {
// Collect all events
let mut do_continue = true;
EVENT_RXS.lock().retain_mut(|rx| {
let timestamp = SystemTime::now()
.duration_since(SystemTime::UNIX_EPOCH)
.map_or(0, |d| d.as_secs());
while do_continue {
match rx.try_recv() {
Ok(Some(event)) => {
if !event.keys.is_empty() {
// Process events
for subscriber in self.subscribers.iter_mut() {
subscriber.push_event(event.clone());
// Build event
let mut event = Event {
inner: EventDetails {
level: self
.custom_levels
.get(&event.inner)
.copied()
.unwrap_or_else(|| event.inner.level()),
typ: event.inner,
timestamp,
span: None,
},
keys: event.keys,
};
// Track spans
let event_id = event.inner.typ.id();
let event = match event_id {
EV_CONN_START | EV_ATTEMPT_START => {
let event = Arc::new(event);
self.active_spans.insert(
event
.span_id()
.unwrap_or_else(|| panic!("Missing span ID: {event:?}")),
event.clone(),
);
if self.active_spans.len() > STALE_SPAN_CHECK_WATERMARK {
self.active_spans.retain(|_, span| {
timestamp.saturating_sub(span.inner.timestamp)
< SPAN_MAX_HOLD
});
}
event
}
} else {
// Register subscriber
let subscribers = { std::mem::take(&mut (*SUBSCRIBER_UPDATE.lock())) };
if !subscribers.is_empty() {
self.subscribers.extend(subscribers);
} else if event.matches(EventType::Server(ServerEvent::Shutdown)) {
do_continue = false;
return false;
EV_CONN_END | EV_ATTEMPT_END => {
if self
.active_spans
.remove(&event.span_id().expect("Missing span ID"))
.is_none()
{
debug_assert!(false, "Unregistered span ID: {event:?}");
}
Arc::new(event)
}
EV_COLLECTOR_UPDATE => {
if self.update() {
continue;
} else {
do_continue = false;
return false;
}
}
_ => {
if let Some(span_id) = event.span_id() {
if let Some(span) = self.active_spans.get(&span_id) {
event.inner.span = Some(span.clone());
} else {
debug_assert!(false, "Unregistered span ID: {event:?}");
}
}
Arc::new(event)
}
};
// Send to subscribers
for subscriber in self.subscribers.iter_mut() {
subscriber.push_event(event_id, event.clone());
}
}
Ok(None) => {
@@ -86,16 +177,101 @@ impl Collector {
do_continue
}
pub fn set_level(level: Level) {
TRACING_LEVEL.store(level as usize, Ordering::Relaxed);
fn update(&mut self) -> bool {
for update in COLLECTOR_UPDATES.lock().drain(..) {
match update {
Update::Register { subscriber } => {
ACTIVE_SUBSCRIBERS.lock().push(subscriber.id.clone());
self.subscribers.push(subscriber);
}
Update::Unregister { id } => {
ACTIVE_SUBSCRIBERS.lock().retain(|s| s != &id);
self.subscribers.retain(|s| s.id != id);
}
Update::UpdateSubscriber {
id,
interests,
lossy,
} => {
for subscriber in self.subscribers.iter_mut() {
if subscriber.id == id {
subscriber.interests = interests;
subscriber.lossy = lossy;
break;
}
}
}
Update::UpdateLevels { custom_levels } => {
self.custom_levels = custom_levels;
}
Update::Shutdown => return false,
}
}
true
}
pub fn update_custom_levels(levels: AHashMap<EventType, Level>) {
custom_levels().store(Arc::new(levels));
pub fn set_interests(mut interests: Interests) {
if !interests.is_empty() {
for event_type in [
EventType::Network(NetworkEvent::ConnectionStart),
EventType::Network(NetworkEvent::ConnectionEnd),
EventType::Delivery(DeliveryEvent::AttemptStart),
EventType::Delivery(DeliveryEvent::AttemptEnd),
] {
interests.set(event_type);
}
}
INTERESTS.update(interests);
}
pub fn enable_event(event: impl Into<usize>) {
INTERESTS.set(event);
}
pub fn disable_event(event: impl Into<usize>) {
INTERESTS.clear(event);
}
pub fn disable_all_events() {
INTERESTS.clear_all();
}
#[inline(always)]
pub fn has_interest(event: impl Into<usize>) -> bool {
INTERESTS.get(event)
}
pub fn get_subscribers() -> Vec<String> {
ACTIVE_SUBSCRIBERS.lock().clone()
}
pub fn update_custom_levels(custom_levels: AHashMap<EventType, Level>) {
COLLECTOR_UPDATES
.lock()
.push(Update::UpdateLevels { custom_levels });
}
pub fn update_subscriber(id: String, interests: Interests, lossy: bool) {
COLLECTOR_UPDATES.lock().push(Update::UpdateSubscriber {
id,
interests,
lossy,
});
}
pub fn remove_subscriber(id: String) {
COLLECTOR_UPDATES.lock().push(Update::Unregister { id });
}
pub fn shutdown() {
Event::new(EventType::Server(ServerEvent::Shutdown)).send()
COLLECTOR_UPDATES.lock().push(Update::Shutdown);
Collector::reload();
}
pub fn reload() {
Event::new(EventType::Server(ServerEvent::CollectorUpdate)).send()
}
}
@@ -114,26 +290,3 @@ pub(crate) fn spawn_collector() -> &'static Arc<CollectorThread> {
)
})
}
fn custom_levels() -> &'static ArcSwap<AHashMap<EventType, Level>> {
static CUSTOM_LEVELS: OnceLock<ArcSwap<AHashMap<EventType, Level>>> = OnceLock::new();
CUSTOM_LEVELS.get_or_init(|| ArcSwap::from_pointee(Default::default()))
}
impl EventType {
#[inline(always)]
pub fn effective_level(&self) -> Level {
custom_levels()
.load()
.get(self)
.copied()
.unwrap_or_else(|| self.level())
}
}
impl Level {
#[inline(always)]
pub fn is_enabled(&self) -> bool {
*self as usize >= TRACING_LEVEL.load(Ordering::Relaxed)
}
}

View File

@@ -100,18 +100,12 @@ impl From<Duration> for Value {
}
}
impl From<Event> for Value {
fn from(value: Event) -> Self {
impl From<Event<EventType>> for Value {
fn from(value: Event<EventType>) -> Self {
Self::Event(value)
}
}
impl From<Level> for Value {
fn from(value: Level) -> Self {
Self::Level(value)
}
}
impl From<EventType> for Error {
fn from(value: EventType) -> Self {
Error::new(value)
@@ -217,7 +211,7 @@ impl EventType {
}
}
impl From<mail_auth::Error> for Event {
impl From<mail_auth::Error> for Event<EventType> {
fn from(err: mail_auth::Error) -> Self {
match err {
mail_auth::Error::ParseError => {
@@ -294,7 +288,7 @@ impl From<mail_auth::Error> for Event {
}
}
impl From<&mail_auth::DkimResult> for Event {
impl From<&mail_auth::DkimResult> for Event<EventType> {
fn from(value: &mail_auth::DkimResult) -> Self {
match value.clone() {
mail_auth::DkimResult::Pass => Event::new(EventType::Dkim(DkimEvent::Pass)),
@@ -315,7 +309,7 @@ impl From<&mail_auth::DkimResult> for Event {
}
}
impl From<&mail_auth::DmarcResult> for Event {
impl From<&mail_auth::DmarcResult> for Event<EventType> {
fn from(value: &mail_auth::DmarcResult) -> Self {
match value.clone() {
mail_auth::DmarcResult::Pass => Event::new(EventType::Dmarc(DmarcEvent::Pass)),
@@ -333,7 +327,7 @@ impl From<&mail_auth::DmarcResult> for Event {
}
}
impl From<&mail_auth::DkimOutput<'_>> for Event {
impl From<&mail_auth::DkimOutput<'_>> for Event<EventType> {
fn from(value: &mail_auth::DkimOutput<'_>) -> Self {
Event::from(value.result()).ctx_opt(
Key::Contents,
@@ -349,7 +343,7 @@ impl From<&mail_auth::DkimOutput<'_>> for Event {
}
}
impl From<&mail_auth::IprevOutput> for Event {
impl From<&mail_auth::IprevOutput> for Event<EventType> {
fn from(value: &mail_auth::IprevOutput) -> Self {
match value.result().clone() {
mail_auth::IprevResult::Pass => Event::new(EventType::Iprev(IprevEvent::Pass)),
@@ -375,7 +369,7 @@ impl From<&mail_auth::IprevOutput> for Event {
}
}
impl From<&mail_auth::SpfOutput> for Event {
impl From<&mail_auth::SpfOutput> for Event<EventType> {
fn from(value: &mail_auth::SpfOutput) -> Self {
Event::new(EventType::Spf(match value.result() {
mail_auth::SpfResult::Pass => SpfEvent::Pass,

312
crates/trc/src/fmt.rs Normal file
View File

@@ -0,0 +1,312 @@
/*
* SPDX-FileCopyrightText: 2020 Stalwart Labs Ltd <hello@stalw.art>
*
* SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL
*/
use mail_parser::DateTime;
use tokio::io::{AsyncWrite, AsyncWriteExt};
use crate::{Event, EventDetails, Key, Level, Value};
use base64::{engine::general_purpose::STANDARD, Engine};
pub struct FmtWriter<T: AsyncWrite + Unpin> {
writer: T,
ansi: bool,
multiline: bool,
}
#[allow(dead_code)]
enum Color {
Black,
Red,
Green,
Yellow,
Blue,
Magenta,
Cyan,
White,
}
impl<T: AsyncWrite + Unpin> FmtWriter<T> {
pub fn new(writer: T) -> Self {
Self {
writer,
ansi: false,
multiline: false,
}
}
pub fn with_ansi(self, ansi: bool) -> Self {
Self { ansi, ..self }
}
pub fn with_multiline(self, multiline: bool) -> Self {
Self { multiline, ..self }
}
pub async fn write(&mut self, event: &Event<EventDetails>) -> std::io::Result<()> {
// Write timestamp
if self.ansi {
self.writer
.write_all(Color::White.as_code().as_bytes())
.await?;
}
self.writer
.write_all(
DateTime::from_timestamp(event.inner.timestamp as i64)
.to_rfc3339()
.as_bytes(),
)
.await?;
if self.ansi {
self.writer.write_all(Color::reset().as_bytes()).await?;
}
self.writer.write_all(" ".as_bytes()).await?;
// Write level
if self.ansi {
self.writer
.write_all(
match event.inner.level {
Level::Error => Color::Red,
Level::Warn => Color::Yellow,
Level::Info => Color::Green,
Level::Debug => Color::Blue,
Level::Trace => Color::Magenta,
Level::Disable => return Ok(()),
}
.as_code_bold()
.as_bytes(),
)
.await?;
}
self.writer
.write_all(event.inner.level.as_str().as_bytes())
.await?;
if self.ansi {
self.writer.write_all(Color::reset().as_bytes()).await?;
}
self.writer.write_all(" ".as_bytes()).await?;
// Write message
if self.ansi {
self.writer
.write_all(Color::White.as_code_bold().as_bytes())
.await?;
}
self.writer
.write_all(event.inner.typ.name().as_bytes())
.await?;
if self.ansi {
self.writer.write_all(Color::reset().as_bytes()).await?;
}
self.writer
.write_all(if self.multiline { "\n" } else { " " }.as_bytes())
.await?;
// Write keys
if let Some(parent_event) = &event.inner.span {
self.write_keys(&parent_event.keys, &event.keys, 1).await?;
} else {
self.write_keys(&[], &event.keys, 1).await?;
}
if !self.multiline {
self.writer.write_all("\n".as_bytes()).await?;
}
Ok(())
}
async fn write_keys(
&mut self,
span_keys: &[(Key, Value)],
keys: &[(Key, Value)],
indent: usize,
) -> std::io::Result<()> {
Box::pin(async move {
let mut is_first = true;
for (key, value) in span_keys.iter().chain(keys.iter()) {
if matches!(key, Key::SpanId) {
continue;
} else if is_first {
is_first = false;
} else if !self.multiline {
self.writer.write_all(", ".as_bytes()).await?;
}
// Write key
if self.multiline {
for _ in 0..indent {
self.writer.write_all("\t".as_bytes()).await?;
}
}
if self.ansi {
self.writer
.write_all(Color::Cyan.as_code().as_bytes())
.await?;
}
self.writer.write_all(key.name().as_bytes()).await?;
if self.ansi {
self.writer.write_all(Color::reset().as_bytes()).await?;
}
// Write value
self.writer.write_all(" = ".as_bytes()).await?;
self.write_value(value, indent).await?;
if self.multiline && !matches!(value, Value::Event(_)) {
self.writer.write_all("\n".as_bytes()).await?;
}
}
Ok(())
})
.await
}
async fn write_value(&mut self, value: &Value, indent: usize) -> std::io::Result<()> {
Box::pin(async move {
match value {
Value::Static(v) => {
self.writer.write_all(v.as_bytes()).await?;
}
Value::String(v) => {
self.writer.write_all("\"".as_bytes()).await?;
for ch in v.as_bytes() {
match ch {
b'\r' => {
self.writer.write_all("\\r".as_bytes()).await?;
}
b'\n' => {
self.writer.write_all("\\n".as_bytes()).await?;
}
b'\t' => {
self.writer.write_all("\\t".as_bytes()).await?;
}
b'\\' => {
self.writer.write_all("\\\\".as_bytes()).await?;
}
_ => {
self.writer.write_all(&[*ch]).await?;
}
}
}
self.writer.write_all("\"".as_bytes()).await?;
}
Value::UInt(v) => {
self.writer.write_all(v.to_string().as_bytes()).await?;
}
Value::Int(v) => {
self.writer.write_all(v.to_string().as_bytes()).await?;
}
Value::Float(v) => {
self.writer.write_all(v.to_string().as_bytes()).await?;
}
Value::Timestamp(v) => {
self.writer
.write_all(DateTime::from_timestamp(*v as i64).to_rfc3339().as_bytes())
.await?;
}
Value::Duration(v) => {
self.writer.write_all(v.to_string().as_bytes()).await?;
self.writer.write_all("ms".as_bytes()).await?;
}
Value::Bytes(bytes) => {
self.writer.write_all("base64:".as_bytes()).await?;
self.writer
.write_all(STANDARD.encode(bytes).as_bytes())
.await?;
}
Value::Bool(true) => {
self.writer.write_all("true".as_bytes()).await?;
}
Value::Bool(false) => {
self.writer.write_all("false".as_bytes()).await?;
}
Value::Ipv4(v) => {
self.writer.write_all(v.to_string().as_bytes()).await?;
}
Value::Ipv6(v) => {
self.writer.write_all(v.to_string().as_bytes()).await?;
}
Value::Protocol(v) => {
self.writer.write_all(v.name().as_bytes()).await?;
}
Value::Event(e) => {
self.writer.write_all(e.inner.name().as_bytes()).await?;
if !e.keys.is_empty() {
self.writer
.write_all(if self.multiline { "\n" } else { " { " }.as_bytes())
.await?;
self.write_keys(&e.keys, &[], indent + 1).await?;
if !self.multiline {
self.writer.write_all(" }".as_bytes()).await?;
}
} else if self.multiline {
self.writer.write_all("\n".as_bytes()).await?;
}
}
Value::Array(arr) => {
self.writer.write_all("[".as_bytes()).await?;
for (pos, value) in arr.iter().enumerate() {
if pos > 0 {
self.writer.write_all(", ".as_bytes()).await?;
}
self.write_value(value, indent).await?;
}
self.writer.write_all("]".as_bytes()).await?;
}
Value::None => {
self.writer.write_all("(null)".as_bytes()).await?;
}
}
Ok(())
})
.await
}
pub async fn flush(&mut self) -> std::io::Result<()> {
self.writer.flush().await
}
pub fn update_writer(&mut self, writer: T) {
self.writer = writer;
}
}
impl Color {
pub fn as_code(&self) -> &'static str {
match self {
Color::Black => "\x1b[30m",
Color::Red => "\x1b[31m",
Color::Green => "\x1b[32m",
Color::Yellow => "\x1b[33m",
Color::Blue => "\x1b[34m",
Color::Magenta => "\x1b[35m",
Color::Cyan => "\x1b[36m",
Color::White => "\x1b[37m",
}
}
pub fn as_code_bold(&self) -> &'static str {
match self {
Color::Black => "\x1b[30;1m",
Color::Red => "\x1b[31;1m",
Color::Green => "\x1b[32;1m",
Color::Yellow => "\x1b[33;1m",
Color::Blue => "\x1b[34;1m",
Color::Magenta => "\x1b[35;1m",
Color::Cyan => "\x1b[36;1m",
Color::White => "\x1b[37;1m",
}
}
pub fn reset() -> &'static str {
"\x1b[0m"
}
}

View File

@@ -4,48 +4,51 @@
* SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL
*/
use std::{borrow::Cow, cmp::Ordering, fmt::Display, str::FromStr, time::SystemTime};
use std::{borrow::Cow, cmp::Ordering, fmt::Display, str::FromStr};
use crate::*;
impl Event {
pub fn with_capacity(inner: EventType, capacity: usize) -> Self {
impl<T> Event<T> {
pub fn with_capacity(inner: T, capacity: usize) -> Self {
Self {
inner,
keys: Vec::with_capacity(capacity + 2),
keys: Vec::with_capacity(capacity),
}
}
pub fn new(inner: EventType) -> Self {
pub fn new(inner: T) -> Self {
Self {
inner,
keys: Vec::with_capacity(5),
}
}
pub fn with_level(mut self, level: Level) -> Self {
let level = (Key::Level, level.into());
let time = (
Key::Time,
SystemTime::now()
.duration_since(SystemTime::UNIX_EPOCH)
.map_or(0, |d| d.as_secs())
.into(),
);
if self.keys.is_empty() {
self.keys.push(level);
self.keys.push(time);
} else {
let mut keys = Vec::with_capacity(self.keys.len() + 2);
keys.push(level);
keys.push(time);
keys.append(&mut self.keys);
self.keys = keys;
}
self
pub fn value(&self, key: Key) -> Option<&Value> {
self.keys
.iter()
.find_map(|(k, v)| if *k == key { Some(v) } else { None })
}
pub fn value_as_str(&self, key: Key) -> Option<&str> {
self.value(key).and_then(|v| v.as_str())
}
pub fn value_as_uint(&self, key: Key) -> Option<u64> {
self.value(key).and_then(|v| v.to_uint())
}
pub fn take_value(&mut self, key: Key) -> Option<Value> {
self.keys.iter_mut().find_map(|(k, v)| {
if *k == key {
Some(std::mem::take(v))
} else {
None
}
})
}
}
impl Event<EventType> {
#[inline(always)]
pub fn ctx(mut self, key: Key, value: impl Into<Value>) -> Self {
self.keys.push((key, value.into()));
@@ -73,44 +76,10 @@ impl Event {
self.inner == inner
}
#[inline(always)]
pub fn level(&self) -> Level {
if let Some((_, Value::Level(level))) = self.keys.first() {
*level
} else {
debug_assert!(false, "Event has no level");
Level::Disable
}
}
pub fn value(&self, key: Key) -> Option<&Value> {
self.keys
.iter()
.find_map(|(k, v)| if *k == key { Some(v) } else { None })
}
pub fn value_as_str(&self, key: Key) -> Option<&str> {
self.value(key).and_then(|v| v.as_str())
}
pub fn take_value(&mut self, key: Key) -> Option<Value> {
self.keys.iter_mut().find_map(|(k, v)| {
if *k == key {
Some(std::mem::take(v))
} else {
None
}
})
}
#[inline(always)]
pub fn span_id(self, session_id: u64) -> Self {
self.ctx(Key::SpanId, session_id)
}
#[inline(always)]
pub fn parent_span_id(self, session_id: u64) -> Self {
self.ctx(Key::ParentSpanId, session_id)
}
#[inline(always)]
pub fn caused_by(self, error: impl Into<Value>) -> Self {
@@ -208,6 +177,20 @@ impl Event {
}
}
impl Event<EventDetails> {
pub fn span_id(&self) -> Option<u64> {
for (key, value) in &self.keys {
match (key, value) {
(Key::SpanId, Value::UInt(value)) => return Some(*value),
(Key::SpanId, Value::Int(value)) => return Some(*value as u64),
_ => {}
}
}
None
}
}
impl EventType {
#[inline(always)]
pub fn ctx(self, key: Key, value: impl Into<Value>) -> Error {
@@ -690,7 +673,6 @@ impl PartialEq for Value {
(Self::Ipv6(l0), Self::Ipv6(r0)) => l0 == r0,
(Self::Protocol(l0), Self::Protocol(r0)) => l0 == r0,
(Self::Event(l0), Self::Event(r0)) => l0 == r0,
(Self::Level(l0), Self::Level(r0)) => l0 == r0,
(Self::Array(l0), Self::Array(r0)) => l0 == r0,
_ => false,
}
@@ -1013,16 +995,18 @@ impl EventType {
},
EventType::Eval(event) => match event {
EvalEvent::Result => Level::Trace,
EvalEvent::Error => Level::Error,
EvalEvent::DirectoryNotFound => Level::Warn,
EvalEvent::StoreNotFound => Level::Warn,
EvalEvent::Error | EvalEvent::DirectoryNotFound | EvalEvent::StoreNotFound => {
Level::Warn
}
},
EventType::Server(event) => match event {
ServerEvent::Startup => Level::Info,
ServerEvent::Shutdown => Level::Info,
ServerEvent::Licensing => Level::Info,
ServerEvent::StartupError => Level::Error,
ServerEvent::ThreadError => Level::Error,
ServerEvent::Startup | ServerEvent::Shutdown | ServerEvent::Licensing => {
Level::Info
}
ServerEvent::StartupError
| ServerEvent::ThreadError
| ServerEvent::TracingError => Level::Error,
ServerEvent::CollectorUpdate => Level::Disable,
},
EventType::Acme(event) => match event {
AcmeEvent::DnsRecordCreated
@@ -1264,3 +1248,9 @@ impl EventType {
}
}
}
impl From<EventType> for usize {
fn from(value: EventType) -> Self {
value.id()
}
}

View File

@@ -4,25 +4,39 @@
* SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL
*/
pub mod atomic;
pub mod bitset;
pub mod channel;
pub mod collector;
pub mod conv;
pub mod fmt;
pub mod imple;
pub mod macros;
pub mod subscriber;
use std::net::{IpAddr, Ipv4Addr, Ipv6Addr};
use std::{
net::{IpAddr, Ipv4Addr, Ipv6Addr},
sync::Arc,
};
use event_macro::{camel_names, event_family, event_type, total_event_count};
pub type Result<T> = std::result::Result<T, Error>;
pub type Error = Event;
pub type Error = Event<EventType>;
#[derive(Debug, Clone)]
pub struct Event {
inner: EventType,
pub struct Event<T> {
pub inner: T,
keys: Vec<(Key, Value)>,
}
#[derive(Debug, Clone)]
pub struct EventDetails {
pub typ: EventType,
pub timestamp: u64,
pub level: Level,
pub span: Option<Arc<Event<EventDetails>>>,
}
#[derive(Copy, Clone, Debug, Hash, Eq, PartialEq)]
#[repr(usize)]
pub enum Level {
@@ -48,17 +62,15 @@ pub enum Value {
Ipv4(Ipv4Addr),
Ipv6(Ipv6Addr),
Protocol(Protocol),
Event(Event),
Event(Event<EventType>),
Array(Vec<Value>),
Level(Level),
#[default]
None,
}
#[derive(Debug, Default, Clone, Copy, PartialEq, Eq)]
#[camel_names]
pub enum Key {
Level,
Time,
#[default]
CausedBy,
Reason,
@@ -84,8 +96,9 @@ pub enum Key {
DocumentId,
Collection,
AccountId,
QueueId,
SpanId,
ParentSpanId,
ReportId,
MessageId,
MailboxId,
ChangeId,
@@ -151,6 +164,7 @@ pub enum Key {
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_family]
pub enum EventType {
Server(ServerEvent),
Purge(PurgeEvent),
@@ -193,7 +207,7 @@ pub enum EventType {
OutgoingReport(OutgoingReportEvent),
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum HttpEvent {
Error,
RequestUrl,
@@ -202,7 +216,7 @@ pub enum HttpEvent {
XForwardedMissing,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum ClusterEvent {
PeerAlive,
PeerDiscovered,
@@ -220,7 +234,7 @@ pub enum ClusterEvent {
Error,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum HousekeeperEvent {
Start,
Stop,
@@ -230,7 +244,7 @@ pub enum HousekeeperEvent {
PurgeStore,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum FtsIndexEvent {
Index,
Locked,
@@ -239,7 +253,7 @@ pub enum FtsIndexEvent {
MetadataNotFound,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum ImapEvent {
// Commands
GetAcl,
@@ -282,7 +296,7 @@ pub enum ImapEvent {
RawOutput,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum Pop3Event {
// Commands
Delete,
@@ -307,7 +321,7 @@ pub enum Pop3Event {
RawOutput,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum ManageSieveEvent {
// Commands
CreateScript,
@@ -333,7 +347,7 @@ pub enum ManageSieveEvent {
RawOutput,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum SmtpEvent {
Error,
RemoteIdNotFound,
@@ -417,7 +431,7 @@ pub enum SmtpEvent {
RequestTooLarge,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum DeliveryEvent {
AttemptStart,
AttemptEnd,
@@ -459,7 +473,7 @@ pub enum DeliveryEvent {
RawOutput,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum QueueEvent {
Scheduled,
Rescheduled,
@@ -471,7 +485,7 @@ pub enum QueueEvent {
QuotaExceeded,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum IncomingReportEvent {
DmarcReport,
DmarcReportWithWarnings,
@@ -490,7 +504,7 @@ pub enum IncomingReportEvent {
DecompressError,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum OutgoingReportEvent {
SpfReport,
SpfRateLimited,
@@ -511,7 +525,7 @@ pub enum OutgoingReportEvent {
Locked,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum MtaStsEvent {
Authorized,
NotAuthorized,
@@ -521,13 +535,13 @@ pub enum MtaStsEvent {
InvalidPolicy,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum TlsRptEvent {
RecordFetch,
RecordFetchError,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum DaneEvent {
AuthenticationSuccess,
AuthenticationFailure,
@@ -541,7 +555,7 @@ pub enum DaneEvent {
TlsaRecordInvalid,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum MilterEvent {
Read,
Write,
@@ -562,7 +576,7 @@ pub enum MilterEvent {
ParseError,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum MtaHookEvent {
ActionAccept,
ActionDiscard,
@@ -571,14 +585,14 @@ pub enum MtaHookEvent {
Error,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum PushSubscriptionEvent {
Success,
Error,
NotFound,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum SpamEvent {
PyzorError,
ListUpdated,
@@ -590,7 +604,7 @@ pub enum SpamEvent {
NotEnoughTrainingData,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum SieveEvent {
ActionAccept,
ActionAcceptReplace,
@@ -606,7 +620,7 @@ pub enum SieveEvent {
QuotaExceeded,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum TlsEvent {
Handshake,
HandshakeError,
@@ -616,7 +630,7 @@ pub enum TlsEvent {
MultipleCertificatesAvailable,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum NetworkEvent {
ConnectionStart,
ConnectionEnd,
@@ -636,16 +650,18 @@ pub enum NetworkEvent {
DropBlocked,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum ServerEvent {
Startup,
Shutdown,
StartupError,
ThreadError,
TracingError,
Licensing,
CollectorUpdate,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum AcmeEvent {
AuthStart,
AuthPending,
@@ -676,7 +692,7 @@ pub enum AcmeEvent {
Error,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum PurgeEvent {
Started,
Finished,
@@ -687,7 +703,7 @@ pub enum PurgeEvent {
TombstoneCleanup,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum EvalEvent {
Result,
Error,
@@ -695,7 +711,7 @@ pub enum EvalEvent {
StoreNotFound,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum ConfigEvent {
ParseError,
BuildError,
@@ -712,7 +728,7 @@ pub enum ConfigEvent {
AlreadyUpToDate,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum ArcEvent {
ChainTooLong,
InvalidInstance,
@@ -722,7 +738,7 @@ pub enum ArcEvent {
SealerNotFound,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum DkimEvent {
Pass,
Neutral,
@@ -744,7 +760,7 @@ pub enum DkimEvent {
SignerNotFound,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum SpfEvent {
Pass,
Fail,
@@ -755,7 +771,7 @@ pub enum SpfEvent {
None,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum DmarcEvent {
Pass,
Fail,
@@ -764,7 +780,7 @@ pub enum DmarcEvent {
None,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum IprevEvent {
Pass,
Fail,
@@ -773,7 +789,7 @@ pub enum IprevEvent {
None,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum MailAuthEvent {
ParseError,
MissingParameters,
@@ -787,7 +803,7 @@ pub enum MailAuthEvent {
PolicyNotAligned,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum StoreEvent {
// Errors
IngestError,
@@ -825,7 +841,7 @@ pub enum StoreEvent {
IngestDuplicate,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum JmapEvent {
// Calls
MethodCall,
@@ -858,7 +874,7 @@ pub enum JmapEvent {
WebsocketError,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum LimitEvent {
SizeRequest,
SizeUpload,
@@ -871,7 +887,7 @@ pub enum LimitEvent {
TooManyRequests,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum ManageEvent {
MissingParameter,
AlreadyExists,
@@ -881,7 +897,7 @@ pub enum ManageEvent {
Error,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum AuthEvent {
Success,
Failed,
@@ -891,7 +907,7 @@ pub enum AuthEvent {
Error,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[event_type]
pub enum ResourceEvent {
NotFound,
BadParameters,
@@ -901,6 +917,7 @@ pub enum ResourceEvent {
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
#[camel_names]
pub enum Protocol {
Jmap,
Imap,
@@ -914,6 +931,8 @@ pub enum Protocol {
Gossip,
}
pub const TOTAL_EVENT_COUNT: usize = total_event_count!();
pub trait AddContext<T> {
fn caused_by(self, location: &'static str) -> Result<T>;
fn add_context<F>(self, f: F) -> Result<T>

View File

@@ -4,19 +4,17 @@
* SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL
*/
// Helper macro to count the number of arguments
#[macro_export]
macro_rules! event {
($event:ident($($param:expr),* $(,)?) $(, $key:ident = $value:expr)* $(,)?) => {
{
let et = $crate::EventType::$event($($param),*);
let level = et.effective_level();
if level.is_enabled() {
const ET : $crate::EventType = $crate::EventType::$event($($param),*);
const ET_ID : usize = ET.id();
if $crate::collector::Collector::has_interest(ET_ID) {
$crate::Event::with_capacity(
et,
ET,
trc::__count!($($key)*)
).with_level(level)
)
$(
.ctx($crate::Key::$key, $crate::Value::from($value))
)*
@@ -24,16 +22,18 @@ macro_rules! event {
}
}
};
}
($event:ident $(, $key:ident = $value:expr)* $(,)?) => {
#[macro_export]
macro_rules! eventd {
($event:ident($($param:expr),* $(,)?) $(, $key:ident = $value:expr)* $(,)?) => {
{
let et = $crate::EventType::$event;
let level = et.effective_level();
if level.is_enabled() {
let et = $crate::EventType::$event($($param),*);
if $crate::collector::Collector::has_interest(et) {
$crate::Event::with_capacity(
et,
trc::__count!($($key)*)
).init(level)
)
$(
.ctx($crate::Key::$key, $crate::Value::from($value))
)*
@@ -67,10 +67,9 @@ macro_rules! bail {
macro_rules! error {
($err:expr $(,)?) => {
let err = $err;
let level = err.as_ref().effective_level();
if level.is_enabled() {
err.with_level(level).send();
if $crate::collector::Collector::has_interest(err.as_ref().id()) {
err.send();
}
};
}

View File

@@ -6,44 +6,38 @@
use std::sync::Arc;
use ahash::AHashSet;
use parking_lot::Mutex;
use tokio::sync::mpsc::{self, error::TrySendError};
use crate::{channel::ChannelError, Event, EventType, Level, ServerEvent};
use crate::{
bitset::{Bitset, USIZE_BITS},
channel::ChannelError,
collector::{Collector, Update, COLLECTOR_UPDATES},
Event, EventDetails, EventType, Level, TOTAL_EVENT_COUNT,
};
const MAX_BATCH_SIZE: usize = 32768;
pub(crate) static SUBSCRIBER_UPDATE: Mutex<Vec<Subscriber>> = Mutex::new(Vec::new());
pub(crate) enum SubscriberUpdate {
Add(Subscriber),
RemoveAll,
}
pub type Interests = Box<Bitset<{ (TOTAL_EVENT_COUNT + USIZE_BITS - 1) / USIZE_BITS }>>;
#[derive(Debug)]
pub(crate) struct Subscriber {
pub id: String,
pub level: Level,
pub disabled: AHashSet<EventType>,
pub tx: mpsc::Sender<Vec<Arc<Event>>>,
pub interests: Interests,
pub tx: mpsc::Sender<Vec<Arc<Event<EventDetails>>>>,
pub lossy: bool,
pub batch: Vec<Arc<Event>>,
pub batch: Vec<Arc<Event<EventDetails>>>,
}
pub struct SubscriberBuilder {
pub id: String,
pub level: Level,
pub disabled: AHashSet<EventType>,
pub interests: Interests,
pub lossy: bool,
}
impl Subscriber {
#[inline(always)]
pub fn push_event(&mut self, trace: Arc<Event>) {
let level = trace.level();
if self.level >= trace.level() && !self.disabled.contains(&trace.inner) {
pub fn push_event(&mut self, event_id: usize, trace: Arc<Event<EventDetails>>) {
if self.interests.get(event_id) {
self.batch.push(trace);
}
}
@@ -54,7 +48,7 @@ impl Subscriber {
Ok(_) => Ok(()),
Err(TrySendError::Full(mut events)) => {
if self.lossy && events.len() > MAX_BATCH_SIZE {
events.retain(|e| e.level() == Level::Error);
events.retain(|e| e.inner.level == Level::Error);
if events.len() > MAX_BATCH_SIZE {
events.truncate(MAX_BATCH_SIZE);
}
@@ -74,19 +68,29 @@ impl SubscriberBuilder {
pub fn new(id: String) -> Self {
Self {
id,
level: Level::Info,
disabled: AHashSet::new(),
interests: Default::default(),
lossy: true,
}
}
pub fn with_level(mut self, level: Level) -> Self {
self.level = level;
pub fn with_default_interests(mut self, level: Level) -> Self {
for event in EventType::variants() {
if event.level() >= level {
self.interests.set(event);
}
}
self
}
pub fn with_disabled(mut self, disabled: impl IntoIterator<Item = EventType>) -> Self {
self.disabled.extend(disabled);
pub fn with_interests(mut self, interests: Interests) -> Self {
self.interests = interests;
self
}
pub fn set_interests(mut self, interest: impl IntoIterator<Item = impl Into<usize>>) -> Self {
for level in interest {
self.interests.set(level);
}
self
}
@@ -95,20 +99,21 @@ impl SubscriberBuilder {
self
}
pub fn register(self) -> mpsc::Receiver<Vec<Arc<Event>>> {
pub fn register(self) -> mpsc::Receiver<Vec<Arc<Event<EventDetails>>>> {
let (tx, rx) = mpsc::channel(8192);
SUBSCRIBER_UPDATE.lock().push(Subscriber {
id: self.id,
level: self.level,
disabled: self.disabled,
tx,
lossy: self.lossy,
batch: Vec::new(),
COLLECTOR_UPDATES.lock().push(Update::Register {
subscriber: Subscriber {
id: self.id,
interests: self.interests,
tx,
lossy: self.lossy,
batch: Vec::new(),
},
});
// Notify collector
Event::new(EventType::Server(ServerEvent::Startup)).send();
Collector::reload();
rx
}