From 1e76792d03721254bacfc0ed2d0c6d6d2ad11269 Mon Sep 17 00:00:00 2001 From: mdecimus Date: Fri, 26 Jul 2024 19:44:01 +0200 Subject: [PATCH] Improved tracing (part 3) --- crates/common/src/config/server/listener.rs | 27 +- crates/common/src/config/server/mod.rs | 5 +- crates/common/src/config/tracers.rs | 13 +- crates/common/src/expr/eval.rs | 14 +- crates/common/src/lib.rs | 142 +- crates/common/src/listener/listen.rs | 19 +- crates/common/src/listener/mod.rs | 86 +- crates/common/src/listener/tls.rs | 21 +- crates/common/src/scripts/plugins/bayes.rs | 11 +- crates/common/src/scripts/plugins/mod.rs | 4 +- crates/common/src/tracing/mod.rs | 156 ++ crates/common/src/tracing/stdout.rs | 18 + crates/imap/src/core/client.rs | 2 +- crates/imap/src/core/message.rs | 4 +- crates/imap/src/core/session.rs | 30 +- crates/imap/src/op/append.rs | 17 +- crates/imap/src/op/copy_move.rs | 4 +- crates/imap/src/op/fetch.rs | 28 +- crates/imap/src/op/idle.rs | 4 +- crates/jmap-proto/src/types/collection.rs | 30 +- crates/jmap/src/api/event_source.rs | 19 +- crates/jmap/src/api/http.rs | 261 ++- crates/jmap/src/api/management/dkim.rs | 2 +- crates/jmap/src/api/management/enterprise.rs | 13 +- crates/jmap/src/api/management/mod.rs | 6 +- crates/jmap/src/api/mod.rs | 20 +- crates/jmap/src/api/request.rs | 26 +- crates/jmap/src/auth/oauth/auth.rs | 3 +- crates/jmap/src/auth/oauth/mod.rs | 8 +- crates/jmap/src/auth/oauth/token.rs | 4 +- crates/jmap/src/email/delete.rs | 1 - crates/jmap/src/email/get.rs | 2 +- crates/jmap/src/email/import.rs | 4 +- crates/jmap/src/email/ingest.rs | 16 +- crates/jmap/src/email/set.rs | 4 +- crates/jmap/src/email/snippet.rs | 2 +- crates/jmap/src/principal/query.rs | 5 +- crates/jmap/src/push/manager.rs | 4 +- crates/jmap/src/services/gossip/leave.rs | 2 + crates/jmap/src/services/gossip/mod.rs | 4 +- crates/jmap/src/services/gossip/ping.rs | 3 +- crates/jmap/src/services/gossip/spawn.rs | 4 +- crates/jmap/src/services/index.rs | 10 +- crates/jmap/src/services/ingest.rs | 17 +- crates/jmap/src/services/state.rs | 45 +- crates/jmap/src/sieve/ingest.rs | 24 +- crates/jmap/src/websocket/stream.rs | 21 +- crates/jmap/src/websocket/upgrade.rs | 29 +- crates/managesieve/src/core/client.rs | 22 +- crates/managesieve/src/core/session.rs | 8 +- crates/pop3/src/client.rs | 10 +- crates/pop3/src/op/fetch.rs | 5 +- crates/pop3/src/session.rs | 51 +- crates/smtp/src/core/mod.rs | 1 + crates/smtp/src/core/throttle.rs | 4 +- crates/smtp/src/inbound/auth.rs | 10 +- crates/smtp/src/inbound/data.rs | 50 +- crates/smtp/src/inbound/ehlo.rs | 6 +- crates/smtp/src/inbound/hooks/message.rs | 4 +- crates/smtp/src/inbound/mail.rs | 8 +- crates/smtp/src/inbound/milter/client.rs | 4 +- crates/smtp/src/inbound/milter/message.rs | 10 +- crates/smtp/src/inbound/rcpt.rs | 16 +- crates/smtp/src/inbound/session.rs | 12 +- crates/smtp/src/inbound/spawn.rs | 12 +- crates/smtp/src/inbound/vrfy.rs | 16 +- crates/smtp/src/outbound/dane/verify.rs | 10 +- crates/smtp/src/outbound/delivery.rs | 1896 +++++++++--------- crates/smtp/src/outbound/session.rs | 142 +- crates/smtp/src/queue/dsn.rs | 34 +- crates/smtp/src/queue/spool.rs | 132 +- crates/smtp/src/queue/throttle.rs | 20 +- crates/smtp/src/reporting/analysis.rs | 268 +-- crates/smtp/src/reporting/dkim.rs | 28 +- crates/smtp/src/reporting/dmarc.rs | 150 +- crates/smtp/src/reporting/mod.rs | 21 +- crates/smtp/src/reporting/scheduler.rs | 56 +- crates/smtp/src/reporting/spf.rs | 28 +- crates/smtp/src/reporting/tls.rs | 108 +- crates/smtp/src/scripts/event_loop.rs | 28 +- crates/trc/src/collector.rs | 17 +- crates/trc/src/conv.rs | 19 +- crates/trc/src/imple.rs | 154 +- crates/trc/src/lib.rs | 151 +- crates/trc/src/subscriber.rs | 31 +- crates/utils/src/lib.rs | 8 + crates/utils/src/snowflake.rs | 11 + tests/src/directory/ldap.rs | 44 +- tests/src/directory/mod.rs | 6 +- tests/src/directory/smtp.rs | 14 +- tests/src/directory/sql.rs | 44 +- tests/src/imap/mod.rs | 27 +- tests/src/jmap/auth_acl.rs | 70 +- tests/src/jmap/mod.rs | 50 +- tests/src/jmap/push_subscription.rs | 9 +- tests/src/jmap/thread_merge.rs | 1 + tests/src/jmap/webhooks.rs | 6 +- tests/src/smtp/config.rs | 12 +- tests/src/smtp/inbound/milter.rs | 5 +- tests/src/smtp/session.rs | 2 + 100 files changed, 2892 insertions(+), 2153 deletions(-) create mode 100644 crates/common/src/tracing/mod.rs create mode 100644 crates/common/src/tracing/stdout.rs diff --git a/crates/common/src/config/server/listener.rs b/crates/common/src/config/server/listener.rs index 0abe2148..4889e3a5 100644 --- a/crates/common/src/config/server/listener.rs +++ b/crates/common/src/config/server/listener.rs @@ -13,9 +13,12 @@ use rustls::{ use tokio::net::TcpSocket; use tokio_rustls::TlsAcceptor; -use utils::config::{ - utils::{AsKey, ParseValue}, - Config, +use utils::{ + config::{ + utils::{AsKey, ParseValue}, + Config, + }, + snowflake::SnowflakeIdGenerator, }; use crate::{ @@ -33,18 +36,31 @@ impl Servers { // Parse ACME managers let mut servers = Servers::default(); + // Create sessionId generator + let id_generator = Arc::new( + config + .property::("cluster.node-id") + .map(SnowflakeIdGenerator::with_node_id) + .unwrap_or_default(), + ); + // Parse servers for id in config .sub_keys("server.listener", ".protocol") .map(|s| s.to_string()) .collect::>() { - servers.parse_server(config, id); + servers.parse_server(config, id, id_generator.clone()); } servers } - fn parse_server(&mut self, config: &mut Config, id_: String) { + fn parse_server( + &mut self, + config: &mut Config, + id_: String, + id_generator: Arc, + ) { // Parse protocol let id = id_.as_str(); let protocol = @@ -193,6 +209,7 @@ impl Servers { protocol, listeners, proxy_networks, + id_generator, }); } diff --git a/crates/common/src/config/server/mod.rs b/crates/common/src/config/server/mod.rs index 7a0c8f9b..c9ca9817 100644 --- a/crates/common/src/config/server/mod.rs +++ b/crates/common/src/config/server/mod.rs @@ -4,12 +4,12 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::{fmt::Display, net::SocketAddr, time::Duration}; +use std::{fmt::Display, net::SocketAddr, sync::Arc, time::Duration}; use ahash::AHashMap; use serde::{Deserialize, Serialize}; use tokio::net::TcpSocket; -use utils::config::ipmask::IpAddrMask; +use utils::{config::ipmask::IpAddrMask, snowflake::SnowflakeIdGenerator}; use crate::listener::TcpAcceptor; @@ -29,6 +29,7 @@ pub struct Server { pub listeners: Vec, pub proxy_networks: Vec, pub max_connections: u64, + pub id_generator: Arc, } #[derive(Debug)] diff --git a/crates/common/src/config/tracers.rs b/crates/common/src/config/tracers.rs index 3fca1457..3ce89ccc 100644 --- a/crates/common/src/config/tracers.rs +++ b/crates/common/src/config/tracers.rs @@ -14,18 +14,22 @@ use utils::config::Config; #[derive(Debug)] pub enum Tracer { Stdout { + id: String, level: Level, ansi: bool, }, Log { + id: String, level: Level, appender: RollingFileAppender, ansi: bool, }, Journal { + id: String, level: Level, }, Otel { + id: String, level: Level, tracer: OtelTracer, }, @@ -96,6 +100,7 @@ impl Tracers { } }; tracers.push(Tracer::Log { + id: id.to_string(), level, appender, ansi: config @@ -106,6 +111,7 @@ impl Tracers { } "stdout" => { tracers.push(Tracer::Stdout { + id: id.to_string(), level, ansi: config .property_or_default(("tracer", id, "ansi"), "true") @@ -123,6 +129,7 @@ impl Tracers { exporter = exporter.with_endpoint(endpoint); } tracers.push(Tracer::Otel { + id: id.to_string(), level, tracer: OtelTracer::Gprc(exporter), }); @@ -158,6 +165,7 @@ impl Tracers { } tracers.push(Tracer::Otel { + id: id.to_string(), level, tracer: OtelTracer::Http(exporter), }); @@ -172,7 +180,10 @@ impl Tracers { } "journal" => { if !tracers.iter().any(|t| matches!(t, Tracer::Journal { .. })) { - tracers.push(Tracer::Journal { level }); + tracers.push(Tracer::Journal { + id: id.to_string(), + level, + }); } else { config.new_build_error( ("tracer", id, "type"), diff --git a/crates/common/src/expr/eval.rs b/crates/common/src/expr/eval.rs index 0af300f5..e478cd03 100644 --- a/crates/common/src/expr/eval.rs +++ b/crates/common/src/expr/eval.rs @@ -26,7 +26,7 @@ impl Core { if if_block.is_empty() { trc::event!( Eval(EvalEvent::Result), - SessionId = session_id, + SpanId = session_id, Property = if_block.key.clone(), Result = "" ); @@ -38,7 +38,7 @@ impl Core { Ok(result) => { trc::event!( Eval(EvalEvent::Result), - SessionId = session_id, + SpanId = session_id, Property = if_block.key.clone(), Result = format!("{result:?}"), ); @@ -48,7 +48,7 @@ impl Core { Err(_) => { trc::event!( Eval(EvalEvent::Error), - SessionId = session_id, + SpanId = session_id, Property = if_block.key.clone(), Details = "Failed to convert result", ); @@ -60,7 +60,7 @@ impl Core { Err(err) => { trc::event!( Eval(EvalEvent::Error), - SessionId = session_id, + SpanId = session_id, Property = if_block.key.clone(), CausedBy = err, ); @@ -85,7 +85,7 @@ impl Core { Ok(result) => { trc::event!( Eval(EvalEvent::Result), - SessionId = session_id, + SpanId = session_id, Property = expr_id.to_string(), Result = format!("{result:?}"), ); @@ -95,7 +95,7 @@ impl Core { Err(_) => { trc::event!( Eval(EvalEvent::Error), - SessionId = session_id, + SpanId = session_id, Property = expr_id.to_string(), Details = "Failed to convert result", ); @@ -107,7 +107,7 @@ impl Core { Err(err) => { trc::event!( Eval(EvalEvent::Error), - SessionId = session_id, + SpanId = session_id, Property = expr_id.to_string(), CausedBy = err, ); diff --git a/crates/common/src/lib.rs b/crates/common/src/lib.rs index 23278325..fea509cd 100644 --- a/crates/common/src/lib.rs +++ b/crates/common/src/lib.rs @@ -18,7 +18,6 @@ use config::{ SmtpConfig, }, storage::Storage, - tracers::{OtelTracer, Tracer, Tracers}, }; use directory::{core::secret::verify_secret_hash, Directory, Principal, QueryBy, Type}; use expr::if_block::IfBlock; @@ -27,20 +26,11 @@ use listener::{ tls::TlsManager, }; use mail_send::Credentials; -use opentelemetry::KeyValue; -use opentelemetry_sdk::{ - trace::{self, Sampler}, - Resource, -}; -use opentelemetry_semantic_conventions::resource::{SERVICE_NAME, SERVICE_VERSION}; + use sieve::Sieve; use store::LookupStore; use tokio::sync::{mpsc, oneshot}; -use tracing_appender::non_blocking::WorkerGuard; -use tracing_subscriber::{ - layer::SubscriberExt, util::SubscriberInitExt, EnvFilter, Layer, Registry, -}; -use utils::{config::Config, BlobHash}; +use utils::BlobHash; use webhooks::{manager::WebhookEvent, WebhookPayload, WebhookType, Webhooks}; pub mod addresses; @@ -51,6 +41,7 @@ pub mod expr; pub mod listener; pub mod manager; pub mod scripts; +pub mod tracing; pub mod webhooks; pub static USER_AGENT: &str = concat!("Stalwart/", env!("CARGO_PKG_VERSION"),); @@ -137,7 +128,7 @@ impl Core { trc::event!( Eval(trc::EvalEvent::DirectoryNotFound), Id = name.to_string(), - SessionId = session_id, + SpanId = session_id, ); &self.storage.directory @@ -149,7 +140,7 @@ impl Core { trc::event!( Eval(trc::EvalEvent::StoreNotFound), Id = name.to_string(), - SessionId = session_id, + SpanId = session_id, ); &self.storage.lookup @@ -166,7 +157,7 @@ impl Core { trc::event!( Arc(trc::ArcEvent::SealerNotFound), Id = name.to_string(), - SessionId = session_id, + SpanId = session_id, ); None @@ -183,7 +174,7 @@ impl Core { trc::event!( Dkim(trc::DkimEvent::SignerNotFound), Id = name.to_string(), - SessionId = session_id, + SpanId = session_id, ); None @@ -195,7 +186,7 @@ impl Core { trc::event!( Sieve(trc::SieveEvent::ScriptNotFound), Id = name.to_string(), - SessionId = session_id, + SpanId = session_id, ); None @@ -207,7 +198,7 @@ impl Core { trc::event!( Smtp(trc::SmtpEvent::RemoteIdNotFound), Id = name.to_string(), - SessionId = session_id, + SpanId = session_id, ); None @@ -410,121 +401,6 @@ impl Core { } } -impl Tracers { - pub fn enable(self, config: &mut Config) -> Option> { - let mut layers: Option + Sync + Send>> = None; - let mut guards = Vec::new(); - - for tracer in self.tracers { - let (Tracer::Stdout { level, .. } - | Tracer::Log { level, .. } - | Tracer::Journal { level } - | Tracer::Otel { level, .. }) = tracer; - - let filter = match EnvFilter::builder().parse(format!( - "smtp={level},imap={level},jmap={level},pop3={level},store={level},common={level},utils={level},directory={level},se_common={level}" - )) { - Ok(filter) => { - filter - } - Err(err) => { - config.new_build_error("tracer", format!("Failed to set env filter: {err}")); - continue; - } - }; - - let layer = match tracer { - Tracer::Stdout { ansi, .. } => tracing_subscriber::fmt::layer() - .with_ansi(ansi) - .with_filter(filter) - .boxed(), - Tracer::Log { appender, ansi, .. } => { - let (non_blocking, guard) = tracing_appender::non_blocking(appender); - guards.push(guard); - tracing_subscriber::fmt::layer() - .with_writer(non_blocking) - .with_ansi(ansi) - .with_filter(filter) - .boxed() - } - Tracer::Otel { tracer, .. } => { - let tracer = match tracer { - OtelTracer::Gprc(exporter) => opentelemetry_otlp::new_pipeline() - .tracing() - .with_exporter(exporter), - OtelTracer::Http(exporter) => opentelemetry_otlp::new_pipeline() - .tracing() - .with_exporter(exporter), - } - .with_trace_config( - trace::config() - .with_resource(Resource::new(vec![ - KeyValue::new(SERVICE_NAME, "stalwart-mail".to_string()), - KeyValue::new( - SERVICE_VERSION, - env!("CARGO_PKG_VERSION").to_string(), - ), - ])) - .with_sampler(Sampler::AlwaysOn), - ) - .install_batch(opentelemetry_sdk::runtime::Tokio); - - match tracer { - Ok(tracer) => tracing_opentelemetry::layer() - .with_tracer(tracer) - .with_filter(filter) - .boxed(), - Err(err) => { - config.new_build_error( - "tracer", - format!("Failed to start OpenTelemetry: {err}"), - ); - continue; - } - } - } - Tracer::Journal { .. } => { - #[cfg(unix)] - { - match tracing_journald::layer() { - Ok(layer) => layer.with_filter(filter).boxed(), - Err(err) => { - config.new_build_error( - "tracer", - format!("Failed to start Journald: {err}"), - ); - continue; - } - } - } - - #[cfg(not(unix))] - { - config.new_build_error( - "tracer", - "Journald is only available on Unix systems.", - ); - continue; - } - } - }; - - layers = Some(match layers { - Some(layers) => layers.and_then(layer).boxed(), - None => layer, - }); - } - - match tracing_subscriber::registry().with(layers?).try_init() { - Ok(_) => Some(guards), - Err(err) => { - config.new_build_error("tracer", format!("Failed to start tracing: {err}")); - None - } - } - } -} - trait CredentialsUsername { fn login(&self) -> &str; } diff --git a/crates/common/src/listener/listen.rs b/crates/common/src/listener/listen.rs index 3beb2c76..64d2bf7c 100644 --- a/crates/common/src/listener/listen.rs +++ b/crates/common/src/listener/listen.rs @@ -46,6 +46,7 @@ impl Server { limiter: ConcurrencyLimiter::new(self.max_connections), acceptor, shutdown_rx, + id_generator: self.id_generator, }); let is_tls = matches!(instance.acceptor, TcpAcceptor::Tls { implicit, .. } if implicit); let is_https = is_tls && self.protocol == ServerProtocol::Http; @@ -218,18 +219,6 @@ impl BuildSession for Arc { ); None } else if let Some(in_flight) = self.limiter.is_allowed() { - let todo = "build session id"; - let session_id = 0; - - trc::event!( - Session(trc::SessionEvent::Start), - ListenerId = self.id.clone(), - Protocol = self.protocol, - RemoteIp = remote_ip, - RemotePort = remote_port, - SessionId = session_id, - ); - // Enforce concurrency SessionData { stream, @@ -361,7 +350,7 @@ impl ServerInstance { Tls(trc::TlsEvent::Handshake), ListenerId = self.id.clone(), Protocol = self.protocol, - SessionId = session_id, + SpanId = session_id, Version = format!( "{:?}", stream @@ -386,7 +375,7 @@ impl ServerInstance { Tls(trc::TlsEvent::HandshakeError), ListenerId = self.id.clone(), Protocol = self.protocol, - SessionId = session_id, + SpanId = session_id, Reason = err.to_string(), ); Err(()) @@ -397,7 +386,7 @@ impl ServerInstance { Tls(trc::TlsEvent::NotConfigured), ListenerId = self.id.clone(), Protocol = self.protocol, - SessionId = session_id, + SpanId = session_id, ); Err(()) } diff --git a/crates/common/src/listener/mod.rs b/crates/common/src/listener/mod.rs index 6d5ae780..d6bf0d59 100644 --- a/crates/common/src/listener/mod.rs +++ b/crates/common/src/listener/mod.rs @@ -13,7 +13,7 @@ use tokio::{ sync::watch, }; use tokio_rustls::{Accept, TlsAcceptor}; -use utils::config::ipmask::IpAddrMask; +use utils::{config::ipmask::IpAddrMask, snowflake::SnowflakeIdGenerator}; use crate::{ config::server::ServerProtocol, @@ -37,6 +37,7 @@ pub struct ServerInstance { pub limiter: ConcurrencyLimiter, pub proxy_networks: Vec, pub shutdown_rx: watch::Receiver, + pub id_generator: Arc, } #[derive(Default)] @@ -95,54 +96,99 @@ pub trait SessionManager: Sync + Send + 'static + Clone { tokio::spawn(async move { let start_time = Instant::now(); - let session_id = session.session_id; + let session_id; if is_tls { match session .instance .acceptor - .accept(session.stream, acme_core) + .accept(session.stream, acme_core, &session.instance) .await { TcpAcceptorResult::Tls(accept) => match accept.await { Ok(stream) => { - let session = SessionData { - stream, - local_ip: session.local_ip, - local_port: session.local_port, - remote_ip: session.remote_ip, - remote_port: session.remote_port, - protocol: session.protocol, - session_id: session.session_id, - in_flight: session.in_flight, - instance: session.instance, - }; - manager.handle(session).await; + // Generate sessionId + session.session_id = + session.instance.id_generator.generate().unwrap_or_default(); + session_id = session.session_id; + + trc::event!( + Network(trc::NetworkEvent::ConnectionStart), + ListenerId = session.instance.id.clone(), + Protocol = session.instance.protocol, + RemoteIp = session.remote_ip, + RemotePort = session.remote_port, + SpanId = session.session_id, + ); + + manager + .handle(SessionData { + stream, + local_ip: session.local_ip, + local_port: session.local_port, + remote_ip: session.remote_ip, + remote_port: session.remote_port, + protocol: session.protocol, + session_id: session.session_id, + in_flight: session.in_flight, + instance: session.instance, + }) + .await; } Err(err) => { trc::event!( Tls(trc::TlsEvent::HandshakeError), ListenerId = session.instance.id.clone(), Protocol = session.instance.protocol, - SessionId = session.session_id, + RemoteIp = session.remote_ip, + RemotePort = session.remote_port, Reason = err.to_string(), ); + + return; } }, TcpAcceptorResult::Plain(stream) => { + // Generate sessionId + session.session_id = + session.instance.id_generator.generate().unwrap_or_default(); + session_id = session.session_id; + + trc::event!( + Network(trc::NetworkEvent::ConnectionStart), + ListenerId = session.instance.id.clone(), + Protocol = session.instance.protocol, + RemoteIp = session.remote_ip, + RemotePort = session.remote_port, + SpanId = session.session_id, + ); + session.stream = stream; manager.handle(session).await; } - TcpAcceptorResult::Close => (), + TcpAcceptorResult::Close => return, } } else { + // Generate sessionId + session.session_id = session.instance.id_generator.generate().unwrap_or_default(); + session_id = session.session_id; + + trc::event!( + Network(trc::NetworkEvent::ConnectionStart), + ListenerId = session.instance.id.clone(), + Protocol = session.instance.protocol, + RemoteIp = session.remote_ip, + RemotePort = session.remote_port, + SpanId = session.session_id, + ); + manager.handle(session).await; } trc::event!( - Session(trc::SessionEvent::Stop), - SessionId = session_id, - Duration = start_time.elapsed(), + Network(trc::NetworkEvent::ConnectionStop), + SpanId = session_id, + Elapsed = start_time.elapsed(), ); }); } diff --git a/crates/common/src/listener/tls.rs b/crates/common/src/listener/tls.rs index fb54eb66..0a0b9d4c 100644 --- a/crates/common/src/listener/tls.rs +++ b/crates/common/src/listener/tls.rs @@ -28,7 +28,7 @@ use super::{ resolver::{build_acme_static_resolver, IsTlsAlpnChallenge}, AcmeProvider, }, - SessionStream, TcpAcceptor, TcpAcceptorResult, + ServerInstance, SessionStream, TcpAcceptor, TcpAcceptorResult, }; pub static TLS13_VERSION: &[&SupportedProtocolVersion] = &[&TLS13]; @@ -110,6 +110,7 @@ impl TcpAcceptor { &self, stream: IO, enable_acme: Option>, + instance: &ServerInstance, ) -> TcpAcceptorResult where IO: SessionStream, @@ -133,6 +134,8 @@ impl TcpAcceptor { trc::event!( Acme(trc::AcmeEvent::ClientSuppliedSNI), + ListenerId = instance.id.clone(), + Protocol = instance.protocol, Name = domain.to_string(), Key = key.is_some(), ); @@ -140,7 +143,11 @@ impl TcpAcceptor { key } None => { - trc::event!(Acme(trc::AcmeEvent::ClientMissingSNI)); + trc::event!( + Acme(trc::AcmeEvent::ClientMissingSNI), + ListenerId = instance.id.clone(), + Protocol = instance.protocol, + ); None } @@ -151,13 +158,19 @@ impl TcpAcceptor { .await { Ok(mut tls) => { - trc::event!(Acme(trc::AcmeEvent::TlsAlpnReceived)); + trc::event!( + Acme(trc::AcmeEvent::TlsAlpnReceived), + ListenerId = instance.id.clone(), + Protocol = instance.protocol, + ); let _ = tls.shutdown().await; } Err(err) => { trc::event!( Acme(trc::AcmeEvent::TlsAlpnError), + ListenerId = instance.id.clone(), + Protocol = instance.protocol, Reason = err.to_string(), ); } @@ -171,6 +184,8 @@ impl TcpAcceptor { Err(err) => { trc::event!( Tls(trc::TlsEvent::HandshakeError), + ListenerId = instance.id.clone(), + Protocol = instance.protocol, Reason = err.to_string(), ); } diff --git a/crates/common/src/scripts/plugins/bayes.rs b/crates/common/src/scripts/plugins/bayes.rs index 0c12f3d6..636dd23c 100644 --- a/crates/common/src/scripts/plugins/bayes.rs +++ b/crates/common/src/scripts/plugins/bayes.rs @@ -77,7 +77,7 @@ async fn train(ctx: PluginContext<'_>, is_train: bool) -> trc::Result trc::event!( Spam(trc::SpamEvent::Train), - SessionId = ctx.session_id, + SpanId = ctx.session_id, Spam = is_spam, Size = model.weights.len(), ); @@ -175,7 +175,7 @@ pub async fn exec_classify(ctx: PluginContext<'_>) -> trc::Result { if spam_learns < classifier.min_learns || ham_learns < classifier.min_learns { trc::event!( Spam(trc::SpamEvent::NotEnoughTrainingData), - SessionId = ctx.session_id, + SpanId = ctx.session_id, MinLearns = classifier.min_learns, SpamLearns = spam_learns, HamLearns = ham_learns @@ -199,7 +199,7 @@ pub async fn exec_classify(ctx: PluginContext<'_>) -> trc::Result { trc::event!( Spam(trc::SpamEvent::Classify), - SessionId = ctx.session_id, + SpanId = ctx.session_id, MinLearns = classifier.min_learns, SpamLearns = spam_learns, HamLearns = ham_learns, @@ -251,7 +251,7 @@ pub async fn exec_is_balanced(ctx: PluginContext<'_>) -> trc::Result { trc::event!( Spam(trc::SpamEvent::TrainBalance), - SessionId = ctx.session_id, + SpanId = ctx.session_id, Spam = learn_spam, MinBalance = min_balance, SpamLearns = spam_learns, @@ -292,8 +292,7 @@ impl LookupOrInsert for BayesTokenCache { } else { self.insert_negative(hash); Weights::default() - } - .into()) + }) } } } diff --git a/crates/common/src/scripts/plugins/mod.rs b/crates/common/src/scripts/plugins/mod.rs index 0998f0aa..f2802138 100644 --- a/crates/common/src/scripts/plugins/mod.rs +++ b/crates/common/src/scripts/plugins/mod.rs @@ -104,9 +104,7 @@ impl Core { match result { Ok(result) => result.into(), Err(err) => { - trc::error!(err - .ctx(trc::Key::SessionId, session_id) - .details("Sieve runtime error")); + trc::error!(err.span_id(session_id).details("Sieve runtime error")); Input::FncResult(Variable::default()) } } diff --git a/crates/common/src/tracing/mod.rs b/crates/common/src/tracing/mod.rs new file mode 100644 index 00000000..c0509e33 --- /dev/null +++ b/crates/common/src/tracing/mod.rs @@ -0,0 +1,156 @@ +/* + * SPDX-FileCopyrightText: 2020 Stalwart Labs Ltd + * + * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL + */ + +pub mod stdout; + +use opentelemetry::KeyValue; +use opentelemetry_sdk::{ + trace::{self, Sampler}, + Resource, +}; +use opentelemetry_semantic_conventions::resource::{SERVICE_NAME, SERVICE_VERSION}; +use stdout::spawn_stdout_tracer; +use tracing_appender::non_blocking::WorkerGuard; +use tracing_subscriber::{ + layer::SubscriberExt, util::SubscriberInitExt, EnvFilter, Layer, Registry, +}; +use trc::subscriber::SubscriberBuilder; +use utils::config::Config; + +use crate::config::tracers::{OtelTracer, Tracer, Tracers}; + +impl Tracer { + pub fn spawn(self) { + match self { + Tracer::Stdout { id, level, ansi } => { + spawn_stdout_tracer(SubscriberBuilder::new(id).with_level(level), ansi); + } + Tracer::Log { + id, + level, + appender, + ansi, + } => todo!(), + Tracer::Journal { id, level } => todo!(), + Tracer::Otel { id, level, tracer } => todo!(), + } + } +} + +impl Tracers { + pub fn enable(self, config: &mut Config) -> Option> { + let mut layers: Option + Sync + Send>> = None; + let mut guards = Vec::new(); + + for tracer in self.tracers { + let (Tracer::Stdout { level, .. } + | Tracer::Log { level, .. } + | Tracer::Journal { level, .. } + | Tracer::Otel { level, .. }) = tracer; + + let filter = match EnvFilter::builder().parse(format!( + "smtp={level},imap={level},jmap={level},pop3={level},store={level},common={level},utils={level},directory={level},se_common={level}" + )) { + Ok(filter) => { + filter + } + Err(err) => { + config.new_build_error("tracer", format!("Failed to set env filter: {err}")); + continue; + } + }; + + let layer = match tracer { + Tracer::Stdout { ansi, .. } => tracing_subscriber::fmt::layer() + .with_ansi(ansi) + .with_filter(filter) + .boxed(), + Tracer::Log { appender, ansi, .. } => { + let (non_blocking, guard) = tracing_appender::non_blocking(appender); + guards.push(guard); + tracing_subscriber::fmt::layer() + .with_writer(non_blocking) + .with_ansi(ansi) + .with_filter(filter) + .boxed() + } + Tracer::Otel { tracer, .. } => { + let tracer = match tracer { + OtelTracer::Gprc(exporter) => opentelemetry_otlp::new_pipeline() + .tracing() + .with_exporter(exporter), + OtelTracer::Http(exporter) => opentelemetry_otlp::new_pipeline() + .tracing() + .with_exporter(exporter), + } + .with_trace_config( + trace::config() + .with_resource(Resource::new(vec![ + KeyValue::new(SERVICE_NAME, "stalwart-mail".to_string()), + KeyValue::new( + SERVICE_VERSION, + env!("CARGO_PKG_VERSION").to_string(), + ), + ])) + .with_sampler(Sampler::AlwaysOn), + ) + .install_batch(opentelemetry_sdk::runtime::Tokio); + + match tracer { + Ok(tracer) => tracing_opentelemetry::layer() + .with_tracer(tracer) + .with_filter(filter) + .boxed(), + Err(err) => { + config.new_build_error( + "tracer", + format!("Failed to start OpenTelemetry: {err}"), + ); + continue; + } + } + } + Tracer::Journal { .. } => { + #[cfg(unix)] + { + match tracing_journald::layer() { + Ok(layer) => layer.with_filter(filter).boxed(), + Err(err) => { + config.new_build_error( + "tracer", + format!("Failed to start Journald: {err}"), + ); + continue; + } + } + } + + #[cfg(not(unix))] + { + config.new_build_error( + "tracer", + "Journald is only available on Unix systems.", + ); + continue; + } + } + }; + + layers = Some(match layers { + Some(layers) => layers.and_then(layer).boxed(), + None => layer, + }); + } + + match tracing_subscriber::registry().with(layers?).try_init() { + Ok(_) => Some(guards), + Err(err) => { + config.new_build_error("tracer", format!("Failed to start tracing: {err}")); + None + } + } + } +} diff --git a/crates/common/src/tracing/stdout.rs b/crates/common/src/tracing/stdout.rs new file mode 100644 index 00000000..7e40112b --- /dev/null +++ b/crates/common/src/tracing/stdout.rs @@ -0,0 +1,18 @@ +/* + * SPDX-FileCopyrightText: 2020 Stalwart Labs Ltd + * + * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL + */ + +use trc::{subscriber::SubscriberBuilder, Level}; + +pub(crate) fn spawn_stdout_tracer(builder: SubscriberBuilder, ansi: bool) { + let mut tx = builder.register(); + tokio::spawn(async move { + while let Some(events) = tx.recv().await { + for event in events { + eprintln!("{}", event); + } + } + }); +} diff --git a/crates/imap/src/core/client.rs b/crates/imap/src/core/client.rs index 75d04317..9331a4d3 100644 --- a/crates/imap/src/core/client.rs +++ b/crates/imap/src/core/client.rs @@ -19,7 +19,7 @@ impl Session { pub async fn ingest(&mut self, bytes: &[u8]) -> SessionResult { trc::event!( Imap(trc::ImapEvent::RawInput), - SessionId = self.session_id, + SpanId = self.session_id, Size = bytes.len(), Contents = String::from_utf8_lossy(bytes).into_owned(), ); diff --git a/crates/imap/src/core/message.rs b/crates/imap/src/core/message.rs index f7c2b3ee..2a3df644 100644 --- a/crates/imap/src/core/message.rs +++ b/crates/imap/src/core/message.rs @@ -75,10 +75,10 @@ impl SessionData { trc::event!( Store(trc::StoreEvent::UnexpectedError), AccountId = mailbox.account_id, - Collection = Collection::Mailbox as u8, + Collection = Collection::Mailbox, MailboxId = mailbox.mailbox_id, MessageId = message_id, - SessionId = self.session_id, + SpanId = self.session_id, Details = "Duplicate IMAP UID" ); } diff --git a/crates/imap/src/core/session.rs b/crates/imap/src/core/session.rs index c8093c7b..4c53df4b 100644 --- a/crates/imap/src/core/session.rs +++ b/crates/imap/src/core/session.rs @@ -69,7 +69,7 @@ impl Session { } else { trc::event!( Network(trc::NetworkEvent::Closed), - SessionId = self.session_id, + SpanId = self.session_id, CausedBy = trc::location!() ); break; @@ -78,8 +78,8 @@ impl Session { Ok(Err(err)) => { trc::event!( Network(trc::NetworkEvent::ReadError), - SessionId = self.session_id, - Reason = err, + SpanId = self.session_id, + Reason = err.to_string(), CausedBy = trc::location!() ); break; @@ -87,7 +87,7 @@ impl Session { Err(_) => { trc::event!( Network(trc::NetworkEvent::Timeout), - SessionId = self.session_id, + SpanId = self.session_id, CausedBy = trc::location!() ); self.write_bytes(&b"* BYE Connection timed out.\r\n"[..]).await.ok(); @@ -98,7 +98,7 @@ impl Session { _ = shutdown_rx.changed() => { trc::event!( Network(trc::NetworkEvent::Closed), - SessionId = self.session_id, + SpanId = self.session_id, Reason = "Server shutting down", CausedBy = trc::location!() ); @@ -124,8 +124,8 @@ impl Session { if let Err(err) = session.stream.write_all(greeting).await { trc::event!( Network(trc::NetworkEvent::WriteError), - Reason = err, - SessionId = session.session_id, + Reason = err.to_string(), + SpanId = session.session_id, Details = "Failed to write to stream" ); return Err(()); @@ -165,7 +165,7 @@ impl Session { } else { trc::event!( Network(trc::NetworkEvent::SplitError), - SessionId = self.session_id, + SpanId = self.session_id, Details = "Failed to obtain write half state" ); return Err(()); @@ -179,7 +179,7 @@ impl Session { } else { trc::event!( Network(trc::NetworkEvent::SplitError), - SessionId = self.session_id, + SpanId = self.session_id, Details = "Failed to take ownership of write half" ); @@ -216,7 +216,7 @@ impl Session { trc::event!( Imap(trc::ImapEvent::RawOutput), - SessionId = self.session_id, + SpanId = self.session_id, Size = bytes.len(), Contents = String::from_utf8_lossy(bytes).into_owned(), ); @@ -237,10 +237,10 @@ impl Session { if err.should_write_err() { let disconnect = err.must_disconnect(); let bytes = err.serialize(); - trc::error!(err.session_id(self.session_id)); + trc::error!(err.span_id(self.session_id)); if let Err(err) = self.write_bytes(bytes).await { - trc::error!(err.session_id(self.session_id)); + trc::error!(err.span_id(self.session_id)); false } else { !disconnect @@ -259,7 +259,7 @@ impl super::SessionData { trc::event!( Imap(trc::ImapEvent::RawOutput), - SessionId = self.session_id, + SpanId = self.session_id, Size = bytes.len(), Contents = String::from_utf8_lossy(bytes).into_owned(), ); @@ -279,10 +279,10 @@ impl super::SessionData { pub async fn write_error(&self, err: trc::Error) -> trc::Result<()> { if err.should_write_err() { let bytes = err.serialize(); - trc::error!(err.session_id(self.session_id)); + trc::error!(err.span_id(self.session_id)); self.write_bytes(bytes).await } else { - trc::error!(err.session_id(self.session_id)); + trc::error!(err.span_id(self.session_id)); Ok(()) } } diff --git a/crates/imap/src/op/append.rs b/crates/imap/src/op/append.rs index 6f93d9c5..91f307e0 100644 --- a/crates/imap/src/op/append.rs +++ b/crates/imap/src/op/append.rs @@ -105,6 +105,7 @@ impl SessionData { received_at: message.received_at.map(|d| d as u64), source: IngestSource::Imap, encrypt: self.jmap.core.jmap.encrypt && self.jmap.core.jmap.encrypt_append, + session_id: self.session_id, }) .await { @@ -116,13 +117,15 @@ impl SessionData { last_change_id = Some(email.change_id); } Err(err) => { - return Err(if err.matches(trc::EventType::Limit(trc::LimitEvent::Quota)) { - err.details("Disk quota exceeded.") - .code(ResponseCode::OverQuota) - } else { - err - } - .id(arguments.tag)); + return Err( + if err.matches(trc::EventType::Limit(trc::LimitEvent::Quota)) { + err.details("Disk quota exceeded.") + .code(ResponseCode::OverQuota) + } else { + err + } + .id(arguments.tag), + ); } } } diff --git a/crates/imap/src/op/copy_move.rs b/crates/imap/src/op/copy_move.rs index 1c27453c..1b7efacb 100644 --- a/crates/imap/src/op/copy_move.rs +++ b/crates/imap/src/op/copy_move.rs @@ -406,9 +406,9 @@ impl SessionData { trc::event!( Store(trc::StoreEvent::NotFound), AccountId = account_id, - Collection = Collection::Email as u8, + Collection = Collection::Email, MessageId = id, - SessionId = self.session_id, + SpanId = self.session_id, Details = "Message not found" ); diff --git a/crates/imap/src/op/fetch.rs b/crates/imap/src/op/fetch.rs index 34ec2e67..f87f51cb 100644 --- a/crates/imap/src/op/fetch.rs +++ b/crates/imap/src/op/fetch.rs @@ -280,11 +280,13 @@ impl SessionData { (email.inner, keywords) } else { trc::event!( - event = "not-found", - account_id = account_id, - collection = ?Collection::Email, - document_id = id, - "Message metadata not found"); + Store(trc::StoreEvent::NotFound), + AccountId = account_id, + DocumentId = id, + Collection = Collection::Email, + Details = "Message metadata not found.", + CausedBy = trc::location!(), + ); continue; }; @@ -299,12 +301,16 @@ impl SessionData { { Some(raw_message) => raw_message, None => { - trc::event!(event = "not-found", - account_id = account_id, - collection = ?Collection::Email, - document_id = id, - blob_id = ?email.blob_hash, - "Blob not found"); + trc::event!( + Store(trc::StoreEvent::NotFound), + AccountId = account_id, + DocumentId = id, + Collection = Collection::Email, + BlobId = email.blob_hash.to_hex(), + Details = "Blob not found.", + CausedBy = trc::location!(), + ); + continue; } } diff --git a/crates/imap/src/op/idle.rs b/crates/imap/src/op/idle.rs index affd6e54..bb46a941 100644 --- a/crates/imap/src/op/idle.rs +++ b/crates/imap/src/op/idle.rs @@ -57,7 +57,7 @@ impl Session { self.write_bytes(b"+ Idling, send 'DONE' to stop.\r\n".to_vec()) .await?; - trc::event!(Imap(trc::ImapEvent::IdleStart), SessionId = self.session_id); + trc::event!(Imap(trc::ImapEvent::IdleStart), SpanId = self.session_id); let mut buf = vec![0; 1024]; loop { @@ -67,7 +67,7 @@ impl Session { Ok(Ok(bytes_read)) => { if bytes_read > 0 { if (buf[..bytes_read]).windows(4).any(|w| w == b"DONE") { - trc::event!(Imap(trc::ImapEvent::IdleStop), SessionId = self.session_id); + trc::event!(Imap(trc::ImapEvent::IdleStop), SpanId = self.session_id); return self.write_bytes(StatusResponse::completed(Command::Idle) .with_tag(request.tag) .into_bytes()).await; diff --git a/crates/jmap-proto/src/types/collection.rs b/crates/jmap-proto/src/types/collection.rs index ede1fd14..0fbd6af0 100644 --- a/crates/jmap-proto/src/types/collection.rs +++ b/crates/jmap-proto/src/types/collection.rs @@ -90,16 +90,22 @@ impl TryFrom for DataType { impl Display for Collection { fn fmt(&self, f: &mut Formatter<'_>) -> fmt::Result { + self.as_str().fmt(f) + } +} + +impl Collection { + pub fn as_str(&self) -> &'static str { match self { - Collection::PushSubscription => write!(f, "pushSubscription"), - Collection::Email => write!(f, "email"), - Collection::Mailbox => write!(f, "mailbox"), - Collection::Thread => write!(f, "thread"), - Collection::Identity => write!(f, "identity"), - Collection::EmailSubmission => write!(f, "emailSubmission"), - Collection::SieveScript => write!(f, "sieveScript"), - Collection::Principal => write!(f, "principal"), - Collection::None => write!(f, ""), + Collection::PushSubscription => "pushSubscription", + Collection::Email => "email", + Collection::Mailbox => "mailbox", + Collection::Thread => "thread", + Collection::Identity => "identity", + Collection::EmailSubmission => "emailSubmission", + Collection::SieveScript => "sieveScript", + Collection::Principal => "principal", + Collection::None => "", } } } @@ -122,6 +128,12 @@ impl FromStr for Collection { } } +impl From for trc::Value { + fn from(value: Collection) -> Self { + trc::Value::Static(value.as_str()) + } +} + impl BitmapItem for Collection { fn max() -> u64 { Collection::None as u64 diff --git a/crates/jmap/src/api/event_source.rs b/crates/jmap/src/api/event_source.rs index 6f1ab09c..a1a61355 100644 --- a/crates/jmap/src/api/event_source.rs +++ b/crates/jmap/src/api/event_source.rs @@ -12,14 +12,14 @@ use std::{ use http_body_util::{combinators::BoxBody, StreamBody}; use hyper::{ body::{Bytes, Frame}, - header, StatusCode, + StatusCode, }; use jmap_proto::types::type_state::DataType; use utils::map::bitmap::Bitmap; use crate::{auth::AccessToken, JMAP, LONG_SLUMBER}; -use super::{HttpRequest, HttpResponse, StateChangeResponse}; +use super::{HttpRequest, HttpResponse, HttpResponseBody, StateChangeResponse}; struct Ping { interval: Duration, @@ -96,11 +96,12 @@ impl JMAP { .subscribe_state_manager(access_token.primary_id(), types) .await?; - Ok(hyper::Response::builder() - .status(StatusCode::OK) - .header(header::CONTENT_TYPE, "text/event-stream") - .header(header::CACHE_CONTROL, "no-store") - .body(BoxBody::new(StreamBody::new(async_stream::stream! { + Ok(HttpResponse { + status: StatusCode::OK, + content_type: "text/event-stream".into(), + content_disposition: "".into(), + cache_control: "no-store".into(), + body: HttpResponseBody::Stream(BoxBody::new(StreamBody::new(async_stream::stream! { let mut last_message = Instant::now() - throttle; let mut timeout = ping.as_ref().map(|p| p.interval).unwrap_or(LONG_SLUMBER); @@ -152,7 +153,7 @@ impl JMAP { LONG_SLUMBER }; } - }))) - .unwrap()) + }))), + }) } } diff --git a/crates/jmap/src/api/http.rs b/crates/jmap/src/api/http.rs index 1e47174e..054cd426 100644 --- a/crates/jmap/src/api/http.rs +++ b/crates/jmap/src/api/http.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::{net::IpAddr, sync::Arc}; +use std::{borrow::Cow, net::IpAddr, sync::Arc}; use common::{ expr::{functions::ResolveVariable, *}, @@ -36,8 +36,8 @@ use crate::{ }; use super::{ - management::ManagementApiError, HtmlResponse, HttpRequest, HttpResponse, JmapSessionManager, - JsonResponse, + management::ManagementApiError, HtmlResponse, HttpRequest, HttpResponse, HttpResponseBody, + JmapSessionManager, JsonResponse, }; pub struct HttpSessionData { @@ -168,11 +168,7 @@ impl JMAP { self.authenticate_headers(&req, session.remote_ip).await?; return self - .upgrade_websocket_connection( - req, - access_token, - session.instance.clone(), - ) + .upgrade_websocket_connection(req, access_token, session) .await; } (_, &Method::OPTIONS) => { @@ -253,7 +249,11 @@ impl JMAP { self.is_anonymous_allowed(&session.remote_ip).await?; return self - .handle_device_auth(&mut req, session.resolve_url(&self.core).await) + .handle_device_auth( + &mut req, + session.resolve_url(&self.core).await, + session.session_id, + ) .await; } ("token", &Method::POST) => { @@ -278,7 +278,7 @@ impl JMAP { let (_, access_token) = self.authenticate_headers(&req, session.remote_ip).await?; let body = fetch_body(&mut req, 1024 * 1024, session.session_id).await; return self - .handle_api_manage_request(&req, body, access_token) + .handle_api_manage_request(&req, body, access_token, &session) .await; } "mail" => { @@ -358,7 +358,7 @@ impl JmapInstance { async move { trc::event!( Http(trc::HttpEvent::RequestUrl), - SessionId = session.session_id, + SpanId = session.session_id, Url = req.uri().to_string(), ); @@ -378,13 +378,13 @@ impl JmapInstance { } else { trc::event!( Http(trc::HttpEvent::XForwardedMissing), - SessionId = session.session_id, + SpanId = session.session_id, ); session.remote_ip }; // Parse HTTP request - let mut response = match jmap + let response = match jmap .parse_http_request( req, HttpSessionData { @@ -399,25 +399,30 @@ impl JmapInstance { ) .await { - Ok(response) => { - trc::event!( - Http(trc::HttpEvent::ResponseBody), - SessionId = session.session_id, - Contents = std::str::from_utf8(response.body()) - .unwrap_or("[binary data]") - .to_string(), - Size = response.body().as_ref().len(), - ); - - response - } + Ok(response) => response, Err(err) => { let response = err.into_http_response(); - trc::error!(err.session_id(session.session_id)); + trc::error!(err.span_id(session.session_id)); response } }; + trc::event!( + Http(trc::HttpEvent::ResponseBody), + SpanId = session.session_id, + Contents = match &response.body { + HttpResponseBody::Text(value) => trc::Value::String(value.clone()), + HttpResponseBody::Binary(_) => trc::Value::Static("[binary data]"), + HttpResponseBody::Stream(_) => trc::Value::Static("[stream]"), + _ => trc::Value::None, + }, + Status = response.status.as_u16(), + Size = response.size(), + ); + + // Build response + let mut response = response.build(); + // Add custom headers if !jmap.core.jmap.http_headers.is_empty() { let headers = response.headers_mut(); @@ -436,8 +441,8 @@ impl JmapInstance { { trc::event!( Http(trc::HttpEvent::Error), - SessionId = session.session_id, - reason = http_err.to_string(), + SpanId = session.session_id, + Reason = http_err.to_string(), ); } } @@ -507,7 +512,7 @@ pub async fn fetch_body( } else { trc::event!( Http(trc::HttpEvent::RequestBody), - SessionId = session_id, + SpanId = session_id, Contents = std::str::from_utf8(&bytes) .unwrap_or("[binary data]") .to_string(), @@ -522,7 +527,7 @@ pub async fn fetch_body( trc::event!( Http(trc::HttpEvent::RequestBody), - SessionId = session_id, + SpanId = session_id, Contents = std::str::from_utf8(&bytes) .unwrap_or("[binary data]") .to_string(), @@ -536,17 +541,118 @@ pub trait ToHttpResponse { fn into_http_response(self) -> HttpResponse; } -impl ToHttpResponse for JsonResponse { - fn into_http_response(self) -> HttpResponse { - hyper::Response::builder() - .status(self.status) - .header(header::CONTENT_TYPE, "application/json; charset=utf-8") - .body( - Full::new(Bytes::from(serde_json::to_string(&self.inner).unwrap())) +impl HttpResponse { + pub fn new_empty(status: StatusCode) -> Self { + HttpResponse { + status, + content_type: "".into(), + content_disposition: "".into(), + cache_control: "".into(), + body: HttpResponseBody::Empty, + } + } + + pub fn new_text( + status: StatusCode, + content_type: impl Into>, + body: impl Into, + ) -> Self { + HttpResponse { + status, + content_type: content_type.into(), + content_disposition: "".into(), + cache_control: "".into(), + body: HttpResponseBody::Text(body.into()), + } + } + + pub fn new_binary( + status: StatusCode, + content_type: impl Into>, + body: impl Into>, + ) -> Self { + HttpResponse { + status, + content_type: content_type.into(), + content_disposition: "".into(), + cache_control: "".into(), + body: HttpResponseBody::Binary(body.into()), + } + } + + pub fn size(&self) -> usize { + match &self.body { + HttpResponseBody::Text(value) => value.len(), + HttpResponseBody::Binary(value) => value.len(), + _ => 0, + } + } + + pub fn build( + self, + ) -> hyper::Response> + { + let builder = hyper::Response::builder().status(self.status); + + match self.body { + HttpResponseBody::Text(body) => builder + .header(header::CONTENT_TYPE, self.content_type.as_ref()) + .body( + Full::new(Bytes::from(body)) + .map_err(|never| match never {}) + .boxed(), + ), + HttpResponseBody::Binary(body) => { + let mut builder = builder.header(header::CONTENT_TYPE, self.content_type.as_ref()); + + if !self.content_disposition.is_empty() { + builder = builder.header( + header::CONTENT_DISPOSITION, + self.content_disposition.as_ref(), + ); + } + + if !self.cache_control.is_empty() { + builder = builder.header(header::CACHE_CONTROL, self.cache_control.as_ref()); + } + + builder.body( + Full::new(Bytes::from(body)) + .map_err(|never| match never {}) + .boxed(), + ) + } + HttpResponseBody::Empty => builder.body( + Full::new(Bytes::new()) .map_err(|never| match never {}) .boxed(), - ) - .unwrap() + ), + HttpResponseBody::Stream(stream) => builder + .header(header::CONTENT_TYPE, self.content_type.as_ref()) + .header(header::CACHE_CONTROL, self.cache_control.as_ref()) + .body(stream), + HttpResponseBody::WebsocketUpgrade(derived_key) => builder + .header(header::CONNECTION, "upgrade") + .header(header::UPGRADE, "websocket") + .header("Sec-WebSocket-Accept", &derived_key) + .header("Sec-WebSocket-Protocol", "jmap") + .body( + Full::new(Bytes::from("Switching to WebSocket protocol")) + .map_err(|never| match never {}) + .boxed(), + ), + } + .unwrap() + } +} + +impl ToHttpResponse for JsonResponse { + fn into_http_response(self) -> HttpResponse { + HttpResponse::new_text( + self.status, + "application/json; charset=utf-8", + serde_json::to_string(&self.inner).unwrap_or_default(), + ) } } @@ -627,14 +733,13 @@ impl ToRequestError for trc::Error { trc::LimitEvent::TooManyRequests => RequestError::too_many_requests(), }, trc::EventType::Auth(cause) => match cause { - trc::AuthEvent::Failed => RequestError::unauthorized(), trc::AuthEvent::MissingTotp => { RequestError::blank(403, "TOTP code required", cause.message()) } trc::AuthEvent::TooManyAttempts | trc::AuthEvent::Banned => { RequestError::too_many_auth_attempts() } - trc::AuthEvent::Error => RequestError::unauthorized(), + _ => RequestError::unauthorized(), }, trc::EventType::Resource(cause) => match cause { trc::ResourceEvent::NotFound => RequestError::not_found(), @@ -679,14 +784,12 @@ impl HtmlResponse { impl ToHttpResponse for Response { fn into_http_response(self) -> HttpResponse { - //let c = println!("-> {}", serde_json::to_string_pretty(&self).unwrap()); JsonResponse::new(self).into_http_response() } } impl ToHttpResponse for Session { fn into_http_response(self) -> HttpResponse { - //let c = println!("-> {}", serde_json::to_string_pretty(&self).unwrap()); JsonResponse::new(self).into_http_response() } } @@ -699,40 +802,23 @@ impl ToHttpResponse for ManagementApiError<'_> { impl ToHttpResponse for DownloadResponse { fn into_http_response(self) -> HttpResponse { - hyper::Response::builder() - .status(StatusCode::OK) - .header(header::CONTENT_TYPE, self.content_type) - .header( - header::CONTENT_DISPOSITION, - format!( - "attachment; filename=\"{}\"", - self.filename.replace('\"', "\\\"") - ), + HttpResponse { + status: StatusCode::OK, + content_type: self.content_type.into(), + content_disposition: format!( + "attachment; filename=\"{}\"", + self.filename.replace('\"', "\\\"") ) - .header( - header::CACHE_CONTROL, - "private, immutable, max-age=31536000", - ) - .body( - Full::new(Bytes::from(self.blob)) - .map_err(|never| match never {}) - .boxed(), - ) - .unwrap() + .into(), + cache_control: "private, immutable, max-age=31536000".into(), + body: HttpResponseBody::Binary(self.blob), + } } } impl ToHttpResponse for Resource> { fn into_http_response(self) -> HttpResponse { - hyper::Response::builder() - .status(StatusCode::OK) - .header(header::CONTENT_TYPE, self.content_type) - .body( - Full::new(Bytes::from(self.contents)) - .map_err(|never| match never {}) - .boxed(), - ) - .unwrap() + HttpResponse::new_binary(StatusCode::OK, self.content_type, self.contents) } } @@ -744,41 +830,22 @@ impl ToHttpResponse for UploadResponse { impl ToHttpResponse for RequestError<'_> { fn into_http_response(self) -> HttpResponse { - hyper::Response::builder() - .status(StatusCode::from_u16(self.status).unwrap()) - .header(header::CONTENT_TYPE, "application/problem+json") - .body( - Full::new(Bytes::from(serde_json::to_string(&self).unwrap())) - .map_err(|never| match never {}) - .boxed(), - ) - .unwrap() + HttpResponse::new_text( + StatusCode::from_u16(self.status).unwrap_or(StatusCode::BAD_REQUEST), + "application/problem+json", + serde_json::to_string(&self).unwrap_or_default(), + ) } } impl ToHttpResponse for HtmlResponse { fn into_http_response(self) -> HttpResponse { - hyper::Response::builder() - .status(self.status) - .header(header::CONTENT_TYPE, "text/html; charset=utf-8") - .body( - Full::new(Bytes::from(self.body)) - .map_err(|never| match never {}) - .boxed(), - ) - .unwrap() + HttpResponse::new_text(self.status, "text/html; charset=utf-8", self.body) } } impl ToHttpResponse for StatusCode { fn into_http_response(self) -> HttpResponse { - hyper::Response::builder() - .status(self) - .body( - Full::new(Bytes::new()) - .map_err(|never| match never {}) - .boxed(), - ) - .unwrap() + HttpResponse::new_empty(self) } } diff --git a/crates/jmap/src/api/management/dkim.rs b/crates/jmap/src/api/management/dkim.rs index 860aded5..00589441 100644 --- a/crates/jmap/src/api/management/dkim.rs +++ b/crates/jmap/src/api/management/dkim.rs @@ -236,7 +236,7 @@ pub fn obtain_dkim_public_key(algo: Algorithm, pk: &str) -> trc::Result base64_encode(&pk.public_key()).unwrap_or_default(), ) .unwrap_or_default()), - Err(err) => manage::error(details, err.to_string().into()), + Err(err) => Err(manage::error("Crypto error", err.to_string().into())), } } }, diff --git a/crates/jmap/src/api/management/enterprise.rs b/crates/jmap/src/api/management/enterprise.rs index b50870a5..cf9c8689 100644 --- a/crates/jmap/src/api/management/enterprise.rs +++ b/crates/jmap/src/api/management/enterprise.rs @@ -22,7 +22,10 @@ use trc::AddContext; use utils::{url_params::UrlParams, BlobHash}; use crate::{ - api::{http::ToHttpResponse, HttpRequest, HttpResponse, JsonResponse}, + api::{ + http::{HttpSessionData, ToHttpResponse}, + HttpRequest, HttpResponse, JsonResponse, + }, email::ingest::{IngestEmail, IngestSource}, mailbox::INBOX_ID, JMAP, @@ -54,9 +57,13 @@ impl JMAP { req: &HttpRequest, path: Vec<&str>, body: Option>, + session: &HttpSessionData, ) -> trc::Result { match path.get(1).copied().unwrap_or_default() { - "undelete" => self.handle_undelete_api_request(req, path, body).await, + "undelete" => { + self.handle_undelete_api_request(req, path, body, session) + .await + } _ => Err(trc::ResourceEvent::NotFound.into_err()), } } @@ -66,6 +73,7 @@ impl JMAP { req: &HttpRequest, path: Vec<&str>, body: Option>, + session: &HttpSessionData, ) -> trc::Result { match (path.get(2).copied(), req.method()) { (Some(account_name), &Method::GET) => { @@ -183,6 +191,7 @@ impl JMAP { received_at: (request.time as u64).into(), source: IngestSource::Smtp, encrypt: false, + session_id: session.session_id, }) .await { diff --git a/crates/jmap/src/api/management/mod.rs b/crates/jmap/src/api/management/mod.rs index da0782bb..6515b09b 100644 --- a/crates/jmap/src/api/management/mod.rs +++ b/crates/jmap/src/api/management/mod.rs @@ -23,7 +23,7 @@ use directory::backend::internal::manage; use hyper::Method; use serde::Serialize; -use super::{HttpRequest, HttpResponse}; +use super::{http::HttpSessionData, HttpRequest, HttpResponse}; use crate::{auth::AccessToken, JMAP}; #[derive(Serialize)] @@ -44,6 +44,7 @@ impl JMAP { req: &HttpRequest, body: Option>, access_token: Arc, + session: &HttpSessionData, ) -> trc::Result { let path = req.uri().path().split('/').skip(2).collect::>(); let is_superuser = access_token.is_super_user(); @@ -91,7 +92,8 @@ impl JMAP { // for copyright infringement, breach of contract, and fraud. if self.core.is_enterprise_edition() { - self.handle_enterprise_api_request(req, path, body).await + self.handle_enterprise_api_request(req, path, body, session) + .await } else { Err(manage::unsupported( "This feature is only available in the Enterprise version", diff --git a/crates/jmap/src/api/mod.rs b/crates/jmap/src/api/mod.rs index 2a5819f3..2d9fee0e 100644 --- a/crates/jmap/src/api/mod.rs +++ b/crates/jmap/src/api/mod.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::borrow::Cow; + use hyper::StatusCode; use jmap_proto::types::{id::Id, state::State, type_state::DataType}; use serde::Serialize; @@ -39,9 +41,23 @@ pub struct HtmlResponse { body: String, } +pub enum HttpResponseBody { + Text(String), + Binary(Vec), + Stream(http_body_util::combinators::BoxBody), + WebsocketUpgrade(String), + Empty, +} + +pub struct HttpResponse { + pub status: StatusCode, + pub content_type: Cow<'static, str>, + pub content_disposition: Cow<'static, str>, + pub cache_control: Cow<'static, str>, + pub body: HttpResponseBody, +} + pub type HttpRequest = hyper::Request; -pub type HttpResponse = - hyper::Response>; #[derive(serde::Serialize, serde::Deserialize, Debug)] pub enum StateChangeType { diff --git a/crates/jmap/src/api/request.rs b/crates/jmap/src/api/request.rs index 7ee3c674..0c893cef 100644 --- a/crates/jmap/src/api/request.rs +++ b/crates/jmap/src/api/request.rs @@ -6,7 +6,6 @@ use std::sync::Arc; -use common::listener::ServerInstance; use jmap_proto::{ method::{ get, query, @@ -34,14 +33,13 @@ impl JMAP { request.method_calls.len(), ); let add_created_ids = !response.created_ids.is_empty(); - let instance = &session.instance; for mut call in request.method_calls { // Resolve result and id references if let Err(error) = response.resolve_references(&mut call.method) { let method_error = error.clone(); - trc::error!(error.session_id(session.session_id)); + trc::error!(error.span_id(session.session_id)); response.push_response(call.id, MethodName::error(), method_error); continue; @@ -52,7 +50,7 @@ impl JMAP { // Add response match self - .handle_method_call(call.method, &access_token, &mut next_call, instance) + .handle_method_call(call.method, &access_token, &mut next_call, session) .await { Ok(mut method_response) => { @@ -93,7 +91,7 @@ impl JMAP { Err(error) => { let method_error = error.clone(); - trc::error!(error.session_id(session.session_id)); + trc::error!(error.span_id(session.session_id)); response.push_error(call.id, method_error); } @@ -122,7 +120,7 @@ impl JMAP { method: RequestMethod, access_token: &AccessToken, next_call: &mut Option>, - instance: &Arc, + session: &HttpSessionData, ) -> trc::Result { Ok(match method { RequestMethod::Get(mut req) => match req.take_arguments() { @@ -215,7 +213,7 @@ impl JMAP { } query::RequestArguments::Principal => { if self.core.jmap.principal_allow_lookups || access_token.is_super_user() { - self.principal_query(req).await?.into() + self.principal_query(req, session).await?.into() } else { return Err(trc::JmapEvent::Forbidden .into_err() @@ -232,7 +230,7 @@ impl JMAP { set::RequestArguments::Email => { access_token.assert_has_access(req.account_id, Collection::Email)?; - self.email_set(req, access_token).await?.into() + self.email_set(req, access_token, session).await?.into() } set::RequestArguments::Mailbox(arguments) => { access_token.assert_has_access(req.account_id, Collection::Mailbox)?; @@ -249,9 +247,13 @@ impl JMAP { set::RequestArguments::EmailSubmission(arguments) => { access_token.assert_is_member(req.account_id)?; - self.email_submission_set(req.with_arguments(arguments), instance, next_call) - .await? - .into() + self.email_submission_set( + req.with_arguments(arguments), + &session.instance, + next_call, + ) + .await? + .into() } set::RequestArguments::PushSubscription => { self.push_subscription_set(req, access_token).await?.into() @@ -280,7 +282,7 @@ impl JMAP { RequestMethod::ImportEmail(req) => { access_token.assert_has_access(req.account_id, Collection::Email)?; - self.email_import(req, access_token).await?.into() + self.email_import(req, access_token, session).await?.into() } RequestMethod::ParseEmail(req) => { access_token.assert_has_access(req.account_id, Collection::Email)?; diff --git a/crates/jmap/src/auth/oauth/auth.rs b/crates/jmap/src/auth/oauth/auth.rs index a5e8edd9..38cf87e6 100644 --- a/crates/jmap/src/auth/oauth/auth.rs +++ b/crates/jmap/src/auth/oauth/auth.rs @@ -146,9 +146,10 @@ impl JMAP { &self, req: &mut HttpRequest, base_url: impl AsRef, + session_id: u64, ) -> trc::Result { // Parse form - let client_id = FormData::from_request(req, MAX_POST_LEN) + let client_id = FormData::from_request(req, MAX_POST_LEN, session_id) .await? .remove("client_id") .filter(|client_id| client_id.len() < CLIENT_ID_MAX_LEN) diff --git a/crates/jmap/src/auth/oauth/mod.rs b/crates/jmap/src/auth/oauth/mod.rs index c9a9c604..0a83063a 100644 --- a/crates/jmap/src/auth/oauth/mod.rs +++ b/crates/jmap/src/auth/oauth/mod.rs @@ -202,13 +202,17 @@ pub struct FormData { } impl FormData { - pub async fn from_request(req: &mut HttpRequest, max_len: usize) -> trc::Result { + pub async fn from_request( + req: &mut HttpRequest, + max_len: usize, + session_id: u64, + ) -> trc::Result { match ( req.headers() .get(CONTENT_TYPE) .and_then(|h| h.to_str().ok()) .and_then(|val| val.parse::().ok()), - fetch_body(req, max_len).await, + fetch_body(req, max_len, session_id).await, ) { (Some(content_type), Some(body)) => { let mut fields = HashMap::new(); diff --git a/crates/jmap/src/auth/oauth/token.rs b/crates/jmap/src/auth/oauth/token.rs index e81f22c1..e65a1c80 100644 --- a/crates/jmap/src/auth/oauth/token.rs +++ b/crates/jmap/src/auth/oauth/token.rs @@ -36,7 +36,7 @@ impl JMAP { session_id: u64, ) -> trc::Result { // Parse form - let params = FormData::from_request(req, MAX_POST_LEN).await?; + let params = FormData::from_request(req, MAX_POST_LEN, session_id).await?; let grant_type = params.get("grant_type").unwrap_or_default(); let mut response = TokenResponse::error(ErrorType::InvalidGrant); @@ -158,7 +158,7 @@ impl JMAP { trc::error!(err .caused_by(trc::location!()) .details("Failed to validate refresh token") - .session_id(session_id)); + .span_id(session_id)); TokenResponse::error(ErrorType::InvalidGrant) } }; diff --git a/crates/jmap/src/email/delete.rs b/crates/jmap/src/email/delete.rs index 856899e3..180e3686 100644 --- a/crates/jmap/src/email/delete.rs +++ b/crates/jmap/src/email/delete.rs @@ -10,7 +10,6 @@ use jmap_proto::types::{ collection::Collection, id::Id, keyword::Keyword, property::Property, state::StateChange, type_state::DataType, }; -use rasn::der::de; use store::{ ahash::AHashMap, roaring::RoaringBitmap, diff --git a/crates/jmap/src/email/get.rs b/crates/jmap/src/email/get.rs index 07eb2676..1709e36c 100644 --- a/crates/jmap/src/email/get.rs +++ b/crates/jmap/src/email/get.rs @@ -158,7 +158,7 @@ impl JMAP { AccountId = account_id, DocumentId = id.document_id(), Collection = Collection::Email, - BlobId = metadata.blob_hash.as_slice().to_vec(), + BlobId = metadata.blob_hash.to_hex(), Details = "Blob not found.", CausedBy = trc::location!(), ); diff --git a/crates/jmap/src/email/import.rs b/crates/jmap/src/email/import.rs index a9186c07..a2a780a9 100644 --- a/crates/jmap/src/email/import.rs +++ b/crates/jmap/src/email/import.rs @@ -19,7 +19,7 @@ use jmap_proto::{ use mail_parser::MessageParser; use utils::map::vec_map::VecMap; -use crate::{auth::AccessToken, JMAP}; +use crate::{api::http::HttpSessionData, auth::AccessToken, JMAP}; use super::ingest::{IngestEmail, IngestSource}; @@ -28,6 +28,7 @@ impl JMAP { &self, request: ImportEmailRequest, access_token: &AccessToken, + session: &HttpSessionData, ) -> trc::Result { // Validate state let account_id = request.account_id.document_id(); @@ -122,6 +123,7 @@ impl JMAP { received_at: email.received_at.map(|r| r.into()), source: IngestSource::Jmap, encrypt: self.core.jmap.encrypt && self.core.jmap.encrypt_append, + session_id: session.session_id, }) .await { diff --git a/crates/jmap/src/email/ingest.rs b/crates/jmap/src/email/ingest.rs index 7e8589fe..20604227 100644 --- a/crates/jmap/src/email/ingest.rs +++ b/crates/jmap/src/email/ingest.rs @@ -63,6 +63,7 @@ pub struct IngestEmail<'x> { pub received_at: Option, pub source: IngestSource, pub encrypt: bool, + pub session_id: u64, } #[derive(Clone, Copy, PartialEq, Eq, Debug)] @@ -273,6 +274,10 @@ impl JMAP { } // Build write batch + let mailbox_ids_event = mailbox_ids + .iter() + .map(|m| trc::Value::from(m.mailbox_id)) + .collect::>(); let maybe_thread_id = thread_id .map(MaybeDynamicId::Static) .unwrap_or(MaybeDynamicId::Dynamic(0)); @@ -318,16 +323,15 @@ impl JMAP { // Request FTS index let _ = self.inner.housekeeper_tx.send(Event::IndexStart).await; - let todo = "add session id"; - trc::event!( Store(trc::StoreEvent::Ingest), - AccountId = account_id, + SpanId = params.session_id, + AccountId = params.account_id, DocumentId = document_id, - MailboxId = mailbox_ids.as_slice(), - BlobId = blob_id.hash.as_slice().to_vec(), + MailboxId = mailbox_ids_event, + BlobId = blob_id.hash.to_hex(), ChangeId = change_id, - Size = raw_message_len, + Size = raw_message_len as u64, ); // Send webhook event diff --git a/crates/jmap/src/email/set.rs b/crates/jmap/src/email/set.rs index 84223ec4..c5658d5f 100644 --- a/crates/jmap/src/email/set.rs +++ b/crates/jmap/src/email/set.rs @@ -40,7 +40,7 @@ use store::{ }; use trc::AddContext; -use crate::{auth::AccessToken, mailbox::UidMailbox, JMAP}; +use crate::{api::http::HttpSessionData, auth::AccessToken, mailbox::UidMailbox, JMAP}; use super::{ headers::{BuildHeader, ValueToHeader}, @@ -52,6 +52,7 @@ impl JMAP { &self, mut request: SetRequest, access_token: &AccessToken, + session: &HttpSessionData, ) -> trc::Result { // Prepare response let account_id = request.account_id.document_id(); @@ -720,6 +721,7 @@ impl JMAP { received_at, source: IngestSource::Jmap, encrypt: self.core.jmap.encrypt && self.core.jmap.encrypt_append, + session_id: session.session_id, }) .await { diff --git a/crates/jmap/src/email/snippet.rs b/crates/jmap/src/email/snippet.rs index 6ca56e7f..ed6c5259 100644 --- a/crates/jmap/src/email/snippet.rs +++ b/crates/jmap/src/email/snippet.rs @@ -142,7 +142,7 @@ impl JMAP { AccountId = account_id, DocumentId = email_id.document_id(), Collection = Collection::Email, - BlobId = metadata.blob_hash.as_slice().to_vec(), + BlobId = metadata.blob_hash.to_hex(), Details = "Blob not found.", CausedBy = trc::location!(), ); diff --git a/crates/jmap/src/principal/query.rs b/crates/jmap/src/principal/query.rs index 4ac800e5..ed53c4aa 100644 --- a/crates/jmap/src/principal/query.rs +++ b/crates/jmap/src/principal/query.rs @@ -11,12 +11,13 @@ use jmap_proto::{ }; use store::{query::ResultSet, roaring::RoaringBitmap}; -use crate::JMAP; +use crate::{api::http::HttpSessionData, JMAP}; impl JMAP { pub async fn principal_query( &self, mut request: QueryRequest, + session: &HttpSessionData, ) -> trc::Result { let account_id = request.account_id.document_id(); let mut result_set = ResultSet { @@ -51,7 +52,7 @@ impl JMAP { let mut ids = RoaringBitmap::new(); for id in self .core - .email_to_ids(&self.core.storage.directory, &email) + .email_to_ids(&self.core.storage.directory, &email, session.session_id) .await? { ids.insert(id); diff --git a/crates/jmap/src/push/manager.rs b/crates/jmap/src/push/manager.rs index 3156fdda..2fdc317e 100644 --- a/crates/jmap/src/push/manager.rs +++ b/crates/jmap/src/push/manager.rs @@ -146,7 +146,7 @@ pub fn spawn_push_manager(core: JmapInstance) -> mpsc::Sender { } else { trc::event!( PushSubscription(PushSubscriptionEvent::NotFound), - Id = id, + Id = id.document_id(), ); } } @@ -338,7 +338,7 @@ async fn http_request( PushSubscription(PushSubscriptionEvent::Error), Details = "HTTP POST failed", Url = url, - Reason = err + Reason = err.to_string() ); false diff --git a/crates/jmap/src/services/gossip/leave.rs b/crates/jmap/src/services/gossip/leave.rs index b6bfd2f7..3c729ecf 100644 --- a/crates/jmap/src/services/gossip/leave.rs +++ b/crates/jmap/src/services/gossip/leave.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use trc::ClusterEvent; + use crate::services::gossip::State; use super::request::Request; diff --git a/crates/jmap/src/services/gossip/mod.rs b/crates/jmap/src/services/gossip/mod.rs index 073b156c..88d2e0e9 100644 --- a/crates/jmap/src/services/gossip/mod.rs +++ b/crates/jmap/src/services/gossip/mod.rs @@ -18,6 +18,7 @@ use std::{ time::Instant, }; use tokio::sync::mpsc; +use trc::ClusterEvent; use crate::JmapInstance; @@ -127,7 +128,8 @@ impl Gossiper { trc::event!( Cluster(ClusterEvent::Error), RemoteIp = dest, - Reason = "Failed to send gossip message" + Details = "Failed to send gossip message", + Reason = err.to_string() ); }; } diff --git a/crates/jmap/src/services/gossip/ping.rs b/crates/jmap/src/services/gossip/ping.rs index 2be3b6c7..467654d0 100644 --- a/crates/jmap/src/services/gossip/ping.rs +++ b/crates/jmap/src/services/gossip/ping.rs @@ -179,10 +179,11 @@ impl Gossiper { core.store(new_core.into()); // Reload ACME - if let Err(err) = inner + if inner .housekeeper_tx .send(housekeeper::Event::AcmeReload) .await + .is_err() { trc::event!( Server(trc::ServerEvent::ThreadError), diff --git a/crates/jmap/src/services/gossip/spawn.rs b/crates/jmap/src/services/gossip/spawn.rs index 3b43c22a..280aabf0 100644 --- a/crates/jmap/src/services/gossip/spawn.rs +++ b/crates/jmap/src/services/gossip/spawn.rs @@ -183,7 +183,7 @@ impl GossiperBuilder { Cluster(trc::ClusterEvent::DecryptionError), RemoteIp = addr.ip(), RemotePort = addr.port(), - Contents = bytes, + Contents = (buf[..size]).to_vec(), Reason = err, ); }, @@ -207,7 +207,7 @@ impl GossiperBuilder { trc::event!( Network(trc::NetworkEvent::ListenStop), LocalIp = bind_addr, - LocalPort = port, + LocalPort = bind_port, Protocol = trc::Protocol::Gossip, ); diff --git a/crates/jmap/src/services/index.rs b/crates/jmap/src/services/index.rs index 1ac56081..c20fe3b3 100644 --- a/crates/jmap/src/services/index.rs +++ b/crates/jmap/src/services/index.rs @@ -117,7 +117,7 @@ impl JMAP { FtsIndex(FtsIndexEvent::BlobNotFound), AccountId = event.account_id, DocumentId = event.document_id, - BlobId = metadata.inner.blob_hash.as_slice().to_vec(), + BlobId = metadata.inner.blob_hash.to_hex(), ); continue; }; @@ -189,7 +189,13 @@ impl JMAP { } } - if let Err(err) = self.inner.housekeeper_tx.send(Event::IndexDone).await { + if self + .inner + .housekeeper_tx + .send(Event::IndexDone) + .await + .is_err() + { trc::event!( Server(trc::ServerEvent::ThreadError), Details = "Failed to send event to Housekeeper", diff --git a/crates/jmap/src/services/ingest.rs b/crates/jmap/src/services/ingest.rs index ba125236..02229d44 100644 --- a/crates/jmap/src/services/ingest.rs +++ b/crates/jmap/src/services/ingest.rs @@ -31,7 +31,7 @@ impl JMAP { trc::event!( Store(trc::StoreEvent::IngestError), Reason = "Blob not found.", - SessionId = message.session_id, + SpanId = message.session_id, ); return (0..message.recipients.len()) @@ -43,7 +43,7 @@ impl JMAP { Err(err) => { trc::error!(err .details("Failed to fetch message blob.") - .session_id(message.session_id)); + .span_id(message.session_id)); return (0..message.recipients.len()) .map(|_| DeliveryResult::TemporaryFailure { @@ -72,7 +72,7 @@ impl JMAP { trc::error!(err .details("Failed to lookup recipient.") .ctx(trc::Key::To, rcpt.to_string()) - .session_id(message.session_id)); + .span_id(message.session_id)); recipients.push(vec![]); } } @@ -88,6 +88,7 @@ impl JMAP { &message.sender_address, rcpt, *uid, + message.session_id, active_script, ) .await @@ -120,6 +121,7 @@ impl JMAP { received_at: None, source: IngestSource::Smtp, encrypt: self.core.jmap.encrypt, + session_id: message.session_id, }) .await } @@ -127,7 +129,7 @@ impl JMAP { trc::error!(err .details("Failed to ingest message.") .ctx(trc::Key::To, rcpt.to_string()) - .session_id(message.session_id)); + .span_id(message.session_id)); *status = DeliveryResult::TemporaryFailure { reason: "Transient server failure.".into(), @@ -150,7 +152,7 @@ impl JMAP { .await; } } - Err(mut err) => { + Err(err) => { match err.as_ref() { trc::EventType::Limit(trc::LimitEvent::Quota) => { *status = DeliveryResult::TemporaryFailure { @@ -169,7 +171,8 @@ impl JMAP { reason: err .value_as_str(trc::Key::Reason) .unwrap_or_default() - .to_string(), + .to_string() + .into(), } } _ => { @@ -181,7 +184,7 @@ impl JMAP { trc::error!(err .ctx(trc::Key::To, rcpt.to_string()) - .session_id(message.session_id)); + .span_id(message.session_id)); } } } diff --git a/crates/jmap/src/services/state.rs b/crates/jmap/src/services/state.rs index 0fe992e3..2ab5e916 100644 --- a/crates/jmap/src/services/state.rs +++ b/crates/jmap/src/services/state.rs @@ -90,7 +90,7 @@ pub fn spawn_state_manager(core: JmapInstance, mut change_rx: mpsc::Receiver { - if let Err(err) = push_tx.send(crate::push::Event::Reset).await { + if push_tx.send(crate::push::Event::Reset).await.is_err() { trc::event!( Server(ServerEvent::ThreadError), Details = "Error sending push reset.", @@ -209,7 +209,7 @@ pub fn spawn_state_manager(core: JmapInstance, mut change_rx: mpsc::Receiver true, - Err(err) => { + Err(_) => { trc::event!( Server(ServerEvent::ThreadError), Details = "Error sending state change.", @@ -444,7 +445,7 @@ impl JMAP { let state_tx = self.inner.state_tx.clone(); for event in [Event::UpdateSharedAccounts { account_id }, push_subs] { - if let Err(err) = state_tx.send(event).await { + if state_tx.send(event).await.is_err() { trc::event!( Server(ServerEvent::ThreadError), Details = "Error sending state change.", diff --git a/crates/jmap/src/sieve/ingest.rs b/crates/jmap/src/sieve/ingest.rs index 8946e912..875d3391 100644 --- a/crates/jmap/src/sieve/ingest.rs +++ b/crates/jmap/src/sieve/ingest.rs @@ -41,6 +41,7 @@ impl JMAP { envelope_from: &str, envelope_to: &str, account_id: u32, + session_id: u64, mut active_script: ActiveScript, ) -> trc::Result { // Parse message @@ -224,7 +225,8 @@ impl JMAP { trc::event!( Sieve(SieveEvent::UnexpectedError), Details = "Unknown message id.", - MessageId = message_id + MessageId = message_id, + SpanId = session_id ); } input = true.into(); @@ -302,7 +304,8 @@ impl JMAP { trc::event!( Sieve(SieveEvent::UnexpectedError), Details = "Unknown message id.", - MessageId = message_id + MessageId = message_id, + SpanId = session_id ); } input = true.into(); @@ -334,9 +337,10 @@ impl JMAP { .map(|r| trc::Value::String(r.address_lcase.clone())) .collect::>(), Size = message.raw_message.len(), + SpanId = session_id ); - let result = Session::::sieve( + Session::::sieve( self.smtp.clone(), SessionAddress::new(mail_from.clone()), recipients, @@ -354,14 +358,16 @@ impl JMAP { .map(|r| trc::Value::String(r.address_lcase.clone())) .collect::>(), Size = message.raw_message.len(), - Limit = self.core.jmap.mail_max_size + Limit = self.core.jmap.mail_max_size, + SpanId = session_id, ); } } else { trc::event!( Sieve(SieveEvent::UnexpectedError), Details = "Unknown message id.", - MessageId = message_id + MessageId = message_id, + SpanId = session_id ); continue; @@ -390,7 +396,11 @@ impl JMAP { } Err(err) => { - trc::event!(Sieve(SieveEvent::RuntimeError), Reason = err.to_string()); + trc::event!( + Sieve(SieveEvent::RuntimeError), + Reason = err.to_string(), + SpanId = session_id + ); input = true.into(); } @@ -418,6 +428,7 @@ impl JMAP { trc::event!( Sieve(SieveEvent::UnexpectedError), Details = "Failed to parse Sieve generated message.", + SpanId = session_id ); continue; @@ -435,6 +446,7 @@ impl JMAP { received_at: None, source: IngestSource::Smtp, encrypt: self.core.jmap.encrypt, + session_id, }) .await { diff --git a/crates/jmap/src/websocket/stream.rs b/crates/jmap/src/websocket/stream.rs index d41f21d3..3a3c0109 100644 --- a/crates/jmap/src/websocket/stream.rs +++ b/crates/jmap/src/websocket/stream.rs @@ -6,7 +6,6 @@ use std::{sync::Arc, time::Instant}; -use common::listener::ServerInstance; use futures_util::{SinkExt, StreamExt}; use hyper::upgrade::Upgraded; use hyper_util::rt::TokioIo; @@ -37,7 +36,7 @@ impl JMAP { ) { trc::event!( Jmap(JmapEvent::WebsocketStart), - SessionId = session.session_id, + SpanId = session.session_id, AccountId = access_token.primary_id(), ); @@ -59,7 +58,7 @@ impl JMAP { Err(err) => { trc::error!(err .details("Failed to subscribe to state manager") - .session_id(session.session_id)); + .span_id(session.session_id)); let _ = stream .send(Message::Text( @@ -112,14 +111,14 @@ impl JMAP { } Err(err) => { let response = WebSocketRequestError::from(err.to_request_error()).to_json(); - trc::error!(err.details("Failed to parse WebSocket message").session_id(session.session_id)); + trc::error!(err.details("Failed to parse WebSocket message").span_id(session.session_id)); response }, }; if let Err(err) = stream.send(Message::Text(response)).await { trc::event!(Jmap(JmapEvent::WebsocketError), Details = "Failed to send text message", - SessionId = session.session_id, + SpanId = session.session_id, Reason = err.to_string() ); } @@ -128,7 +127,7 @@ impl JMAP { if let Err(err) = stream.send(Message::Pong(bytes)).await { trc::event!(Jmap(JmapEvent::WebsocketError), Details = "Failed to send pong message", - SessionId = session.session_id, + SpanId = session.session_id, Reason = err.to_string() ); } @@ -146,7 +145,7 @@ impl JMAP { Ok(Some(Err(err))) => { trc::event!(Jmap(JmapEvent::WebsocketError), Details = "Websocket error", - SessionId = session.session_id, + SpanId = session.session_id, Reason = err.to_string() ); break; @@ -157,7 +156,7 @@ impl JMAP { if last_request.elapsed() > timeout { trc::event!( Jmap(JmapEvent::WebsocketStop), - SessionId = session.session_id, + SpanId = session.session_id, Reason = "Idle client" ); @@ -183,7 +182,7 @@ impl JMAP { } else { trc::event!( Jmap(JmapEvent::WebsocketStop), - SessionId = session.session_id, + SpanId = session.session_id, Reason = "State manager channel closed" ); @@ -200,7 +199,7 @@ impl JMAP { trc::event!( Jmap(JmapEvent::WebsocketError), Details = "Failed to send state change message.", - SessionId = session.session_id, + SpanId = session.session_id, Reason = err.to_string() ); } @@ -216,7 +215,7 @@ impl JMAP { trc::event!( Jmap(JmapEvent::WebsocketError), Details = "Failed to send ping message.", - SessionId = session.session_id, + SpanId = session.session_id, Reason = err.to_string() ); break; diff --git a/crates/jmap/src/websocket/upgrade.rs b/crates/jmap/src/websocket/upgrade.rs index e764518d..a0fb2515 100644 --- a/crates/jmap/src/websocket/upgrade.rs +++ b/crates/jmap/src/websocket/upgrade.rs @@ -6,16 +6,14 @@ use std::sync::Arc; -use common::{config::smtp::session, listener::ServerInstance}; -use http_body_util::{BodyExt, Full}; -use hyper::{body::Bytes, Response}; +use hyper::StatusCode; use hyper_util::rt::TokioIo; use tokio_tungstenite::WebSocketStream; use trc::JmapEvent; use tungstenite::{handshake::derive_accept_key, protocol::Role}; use crate::{ - api::{http::HttpSessionData, HttpRequest, HttpResponse}, + api::{http::HttpSessionData, HttpRequest, HttpResponse, HttpResponseBody}, auth::AccessToken, JMAP, }; @@ -84,28 +82,23 @@ impl JMAP { ) .await; } - Err(e) => { + Err(err) => { trc::event!( Jmap(JmapEvent::WebsocketError), Details = "Websocket upgrade failed", - SessionId = session_id, + SpanId = session_id, Reason = err.to_string() ); } } }); - Ok(Response::builder() - .status(hyper::StatusCode::SWITCHING_PROTOCOLS) - .header(hyper::header::CONNECTION, "upgrade") - .header(hyper::header::UPGRADE, "websocket") - .header("Sec-WebSocket-Accept", &derived_key) - .header("Sec-WebSocket-Protocol", "jmap") - .body( - Full::new(Bytes::from("Switching to WebSocket protocol")) - .map_err(|never| match never {}) - .boxed(), - ) - .unwrap()) + Ok(HttpResponse { + status: StatusCode::SWITCHING_PROTOCOLS, + content_type: "".into(), + content_disposition: "".into(), + cache_control: "".into(), + body: HttpResponseBody::WebsocketUpgrade(derived_key), + }) } } diff --git a/crates/managesieve/src/core/client.rs b/crates/managesieve/src/core/client.rs index 3d99cb53..38a192a5 100644 --- a/crates/managesieve/src/core/client.rs +++ b/crates/managesieve/src/core/client.rs @@ -29,7 +29,7 @@ impl Session { let mut disconnect = err.must_disconnect(); if let Err(err) = self.write_error(err).await { - trc::error!(err.session_id(self.session_id)); + trc::error!(err.span_id(self.session_id)); disconnect = true; } @@ -47,7 +47,7 @@ impl Session { } Err(receiver::Error::Error { response }) => { if let Err(err) = self.write_error(response).await { - trc::error!(err.session_id(self.session_id)); + trc::error!(err.span_id(self.session_id)); return SessionResult::Close; } break; @@ -75,7 +75,7 @@ impl Session { } { Ok(response) => { if let Err(err) = self.write(&response).await { - trc::error!(err.session_id(self.session_id)); + trc::error!(err.span_id(self.session_id)); return SessionResult::Close; } @@ -89,7 +89,7 @@ impl Session { let mut disconnect = err.must_disconnect(); if let Err(err) = self.write_error(err).await { - trc::error!(err.session_id(self.session_id)); + trc::error!(err.span_id(self.session_id)); disconnect = true; } @@ -105,7 +105,7 @@ impl Session { .write(format!("OK Ready for {} bytes.\r\n", needs_literal).as_bytes()) .await { - trc::error!(err.session_id(self.session_id)); + trc::error!(err.span_id(self.session_id)); return SessionResult::Close; } } @@ -189,8 +189,8 @@ impl Session { #[inline(always)] pub async fn write(&mut self, bytes: &[u8]) -> trc::Result<()> { trc::event!( - Imap(trc::ManageSieveEvent::RawOutput), - SessionId = self.session_id, + ManageSieve(trc::ManageSieveEvent::RawOutput), + SpanId = self.session_id, Size = bytes.len(), Contents = String::from_utf8_lossy(bytes).into_owned(), ); @@ -212,8 +212,8 @@ impl Session { } pub async fn write_error(&mut self, error: trc::Error) -> trc::Result<()> { - let bytes = err.serialize(); - trc::error!(error.session_id(self.session_id)); + let bytes = error.serialize(); + trc::error!(error.span_id(self.session_id)); self.write(&bytes).await } @@ -227,8 +227,8 @@ impl Session { })?; trc::event!( - Imap(trc::ManageSieveEvent::RawInput), - SessionId = self.session_id, + ManageSieve(trc::ManageSieveEvent::RawInput), + SpanId = self.session_id, Size = len, Contents = String::from_utf8_lossy(bytes.get(0..len).unwrap_or_default()).into_owned(), ); diff --git a/crates/managesieve/src/core/session.rs b/crates/managesieve/src/core/session.rs index 1c2b5a54..910fe6a3 100644 --- a/crates/managesieve/src/core/session.rs +++ b/crates/managesieve/src/core/session.rs @@ -87,7 +87,7 @@ impl Session { } else { trc::event!( Network(trc::NetworkEvent::Closed), - SessionId = self.session_id, + SpanId = self.session_id, CausedBy = trc::location!() ); break; @@ -96,7 +96,7 @@ impl Session { Ok(Err(err)) => { trc::event!( Network(trc::NetworkEvent::ReadError), - SessionId = self.session_id, + SpanId = self.session_id, Reason = err, CausedBy = trc::location!() ); @@ -105,7 +105,7 @@ impl Session { Err(_) => { trc::event!( Network(trc::NetworkEvent::Timeout), - SessionId = self.session_id, + SpanId = self.session_id, CausedBy = trc::location!() ); self @@ -119,7 +119,7 @@ impl Session { _ = shutdown_rx.changed() => { trc::event!( Network(trc::NetworkEvent::Closed), - SessionId = self.session_id, + SpanId = self.session_id, Reason = "Server shutting down", CausedBy = trc::location!() ); diff --git a/crates/pop3/src/client.rs b/crates/pop3/src/client.rs index 3bb3601a..46b2aef9 100644 --- a/crates/pop3/src/client.rs +++ b/crates/pop3/src/client.rs @@ -15,10 +15,12 @@ use crate::{ impl Session { pub async fn ingest(&mut self, bytes: &[u8]) -> SessionResult { - /*let tmp = "dd"; - for line in String::from_utf8_lossy(bytes).split("\r\n") { - println!("<- {:?}", &line[..std::cmp::min(line.len(), 100)]); - }*/ + trc::event!( + Pop3(trc::Pop3Event::RawInput), + SpanId = self.session_id, + Size = bytes.len(), + Contents = String::from_utf8_lossy(bytes).into_owned(), + ); let mut bytes = bytes.iter(); let mut requests = Vec::with_capacity(2); diff --git a/crates/pop3/src/op/fetch.rs b/crates/pop3/src/op/fetch.rs index 10a33be9..1ec57179 100644 --- a/crates/pop3/src/op/fetch.rs +++ b/crates/pop3/src/op/fetch.rs @@ -54,10 +54,7 @@ impl Session { .caused_by(trc::location!())) } } else { - Err(trc::Pop3Event::Error - .into_err() - .details("No such message.") - .caused_by(trc::location!())) + Err(trc::Pop3Event::Error.into_err().details("No such message.")) } } } diff --git a/crates/pop3/src/session.rs b/crates/pop3/src/session.rs index aee621cb..3012858a 100644 --- a/crates/pop3/src/session.rs +++ b/crates/pop3/src/session.rs @@ -85,29 +85,48 @@ impl Session { return true; } SessionResult::Close => { - trc::event!( event = "disconnect", "Disconnecting client."); break; } } } else { - trc::event!( event = "close", "POP3 connection closed by client."); + trc::event!( + Network(trc::NetworkEvent::Closed), + SpanId = self.session_id, + CausedBy = trc::location!() + ); break; } }, Ok(Err(err)) => { - trc::event!( event = "error", reason = %err, "POP3 connection error."); + trc::event!( + Network(trc::NetworkEvent::ReadError), + SpanId = self.session_id, + Reason = err.to_string() , + CausedBy = trc::location!() + ); break; }, Err(_) => { + trc::event!( + Network(trc::NetworkEvent::Timeout), + SpanId = self.session_id, + CausedBy = trc::location!() + ); + self.write_bytes(&b"-ERR Connection timed out.\r\n"[..]).await.ok(); - trc::event!( "POP3 connection timed out."); break; } } }, _ = shutdown_rx.changed() => { + trc::event!( + Network(trc::NetworkEvent::Closed), + SpanId = self.session_id, + Reason = "Server shutting down", + CausedBy = trc::location!() + ); + self.write_bytes(&b"* BYE Server shutting down.\r\n"[..]).await.ok(); - trc::event!( event = "shutdown", "POP3 server shutting down."); break; } }; @@ -137,13 +156,12 @@ impl Session { impl Session { pub async fn write_bytes(&mut self, bytes: impl AsRef<[u8]>) -> trc::Result<()> { let bytes = bytes.as_ref(); - /*for line in String::from_utf8_lossy(bytes.as_ref()).split("\r\n") { - let c = println!("{}", line); - }*/ + trc::event!( - event = "write", - data = std::str::from_utf8(bytes).unwrap_or_default(), - size = bytes.len() + Pop3(trc::Pop3Event::RawOutput), + SpanId = self.session_id, + Size = bytes.len(), + Contents = String::from_utf8_lossy(bytes).into_owned(), ); self.stream.write_all(bytes.as_ref()).await.map_err(|err| { @@ -166,12 +184,15 @@ impl Session { } pub async fn write_err(&mut self, err: trc::Error) -> bool { - trc::event!("POP3 error: {}", err); let disconnect = err.must_disconnect(); + let response = err.serialize(); + let write_err = err.should_write_err(); - if err.should_write_err() { - if let Err(err) = self.write_bytes(err.serialize()).await { - trc::event!("Failed to write error: {}", err); + trc::error!(err.span_id(self.session_id)); + + if write_err { + if let Err(err) = self.write_bytes(response).await { + trc::error!(err.span_id(self.session_id)); return false; } } diff --git a/crates/smtp/src/core/mod.rs b/crates/smtp/src/core/mod.rs index 0e6b4cfc..dd06dfc2 100644 --- a/crates/smtp/src/core/mod.rs +++ b/crates/smtp/src/core/mod.rs @@ -276,6 +276,7 @@ static ref SIEVE: Arc = Arc::new(ServerInstance { limiter: ConcurrencyLimiter::new(0), shutdown_rx: tokio::sync::watch::channel(false).1, proxy_networks: vec![], + id_generator: Arc::new(SnowflakeIdGenerator::new()), }); } diff --git a/crates/smtp/src/core/throttle.rs b/crates/smtp/src/core/throttle.rs index 24b7148f..28902675 100644 --- a/crates/smtp/src/core/throttle.rs +++ b/crates/smtp/src/core/throttle.rs @@ -241,7 +241,7 @@ impl Session { } else { trc::event!( Smtp(SmtpEvent::ConcurrencyLimitExceeded), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Id = t.id.clone(), Limit = limiter.max_concurrent ); @@ -272,7 +272,7 @@ impl Session { { trc::event!( Smtp(SmtpEvent::RateLimitExceeded), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Id = t.id.clone(), Limit = rate.requests, Interval = rate.period.as_secs() diff --git a/crates/smtp/src/inbound/auth.rs b/crates/smtp/src/inbound/auth.rs index edc22d68..c1adcf40 100644 --- a/crates/smtp/src/inbound/auth.rs +++ b/crates/smtp/src/inbound/auth.rs @@ -183,7 +183,7 @@ impl Session { trc::event!( Auth(trc::AuthEvent::Success), Name = self.data.authenticated_as.clone(), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Protocol = trc::Protocol::Smtp, ); @@ -198,10 +198,10 @@ impl Session { return Ok(false); } Err(err) => { - let reason = err.as_ref().clone(); + let reason = *err.as_ref(); trc::error!(err - .session_id(self.data.session_id) + .span_id(self.data.session_id) .protocol(trc::Protocol::Smtp)); match reason { @@ -227,7 +227,7 @@ impl Session { } else { trc::event!( Smtp(SmtpEvent::MissingAuthDirectory), - SessionId = self.data.session_id, + SpanId = self.data.session_id, ); } self.write(b"454 4.7.0 Temporary authentication failure\r\n") @@ -245,7 +245,7 @@ impl Session { } else { trc::event!( Auth(AuthEvent::TooManyAttempts), - SessionId = self.data.session_id, + SpanId = self.data.session_id, ); self.write(b"421 4.3.0 Too many authentication errors, disconnecting.\r\n") diff --git a/crates/smtp/src/inbound/data.rs b/crates/smtp/src/inbound/data.rs index 5bdf89b9..bedf2db2 100644 --- a/crates/smtp/src/inbound/data.rs +++ b/crates/smtp/src/inbound/data.rs @@ -53,7 +53,7 @@ impl Session { } else { trc::event!( Smtp(SmtpEvent::MessageParseFailed), - SessionId = self.data.session_id, + SpanId = self.data.session_id, ); self.send_failure_webhook(WebhookMessageFailure::ParseFailed) @@ -76,7 +76,7 @@ impl Session { { trc::event!( Smtp(SmtpEvent::LoopDetected), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Count = auth_message.received_headers_count(), ); @@ -137,12 +137,9 @@ impl Session { } else { SmtpEvent::DkimFail }), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Strict = strict, - Result = dkim_output - .iter() - .map(|o| trc::Event::from(o)) - .collect::>(), + Result = dkim_output.iter().map(trc::Event::from).collect::>(), Elapsed = time.elapsed(), ); @@ -199,7 +196,7 @@ impl Session { } else { SmtpEvent::ArcFail }), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Strict = strict, Result = trc::Event::from(arc_output.result()), Elapsed = time.elapsed(), @@ -296,7 +293,7 @@ impl Session { } else { SmtpEvent::DmarcFail }), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Strict = strict, Domain = dmarc_output.domain().to_string(), Policy = dmarc_policy.to_string(), @@ -335,7 +332,8 @@ impl Session { // Analyze reports if is_report { - self.core.analyze_report(raw_message.clone()); + self.core + .analyze_report(raw_message.clone(), self.data.session_id); if !rc.analysis.forward { self.data.messages_sent += 1; return (b"250 2.0.0 Message queued for delivery.\r\n"[..]).into(); @@ -395,7 +393,7 @@ impl Session { } Err(err) => { trc::error!(trc::Event::from(err) - .session_id(self.data.session_id) + .span_id(self.data.session_id) .details("Failed to ARC seal message")); } } @@ -497,7 +495,7 @@ impl Session { trc::event!( Smtp(SmtpEvent::PipeSuccess), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Path = command_, Status = output.status.to_string(), ); @@ -505,14 +503,14 @@ impl Session { Ok(Err(err)) => { trc::event!( Smtp(SmtpEvent::PipeError), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Reason = err.to_string(), ); } Err(_) => { trc::event!( Smtp(SmtpEvent::PipeError), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Reason = "Timeout", ); } @@ -521,14 +519,14 @@ impl Session { Ok(Err(err)) => { trc::event!( Smtp(SmtpEvent::PipeError), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Reason = err.to_string(), ); } Err(_) => { trc::event!( Smtp(SmtpEvent::PipeError), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Reason = "Stdin timeout", ); } @@ -536,7 +534,7 @@ impl Session { } else { trc::event!( Smtp(SmtpEvent::PipeError), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Reason = "Stdin not available", ); } @@ -544,7 +542,7 @@ impl Session { Err(err) => { trc::event!( Smtp(SmtpEvent::PipeError), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Reason = err.to_string(), ); } @@ -716,7 +714,7 @@ impl Session { } Err(err) => { trc::error!(trc::Event::from(err) - .session_id(self.data.session_id) + .span_id(self.data.session_id) .details("Failed to DKIM sign message")); } } @@ -762,7 +760,15 @@ impl Session { }); // Queue message - if message.queue(Some(&headers), raw_message, &self.core).await { + if message + .queue( + Some(&headers), + raw_message, + self.data.session_id, + &self.core, + ) + .await + { // Send webhook event if let Some(event) = webhook_event { self.core @@ -784,7 +790,7 @@ impl Session { } else { trc::event!( Smtp(SmtpEvent::QuotaExceeded), - SessionId = self.data.session_id, + SpanId = self.data.session_id, ); self.send_failure_webhook(WebhookMessageFailure::QuotaExceeded) @@ -950,7 +956,7 @@ impl Session { } else { trc::event!( Smtp(SmtpEvent::TooManyMessages), - SessionId = self.data.session_id, + SpanId = self.data.session_id, ); self.write(b"451 4.4.5 Maximum number of messages per session exceeded.\r\n") diff --git a/crates/smtp/src/inbound/ehlo.rs b/crates/smtp/src/inbound/ehlo.rs index 072c5dde..f468cae2 100644 --- a/crates/smtp/src/inbound/ehlo.rs +++ b/crates/smtp/src/inbound/ehlo.rs @@ -24,7 +24,7 @@ impl Session { if self.params.ehlo_reject_non_fqdn && !domain.as_str().has_valid_labels() { trc::event!( Smtp(SmtpEvent::InvalidEhlo), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Domain = domain, ); @@ -33,7 +33,7 @@ impl Session { trc::event!( Smtp(SmtpEvent::Ehlo), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Domain = domain.clone(), ); @@ -56,7 +56,7 @@ impl Session { } else { SmtpEvent::SpfEhloFail }), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Domain = self.data.helo_domain.clone(), Result = trc::Event::from(&spf_output), Elapsed = time.elapsed(), diff --git a/crates/smtp/src/inbound/hooks/message.rs b/crates/smtp/src/inbound/hooks/message.rs index 29f2a294..99d4b2ad 100644 --- a/crates/smtp/src/inbound/hooks/message.rs +++ b/crates/smtp/src/inbound/hooks/message.rs @@ -59,7 +59,7 @@ impl Session { Action::Reject => MtaHookEvent::ActionReject, Action::Quarantine => MtaHookEvent::ActionQuarantine, }), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Id = mta_hook.id.clone(), Contents = response .modifications @@ -154,7 +154,7 @@ impl Session { Err(err) => { trc::event!( MtaHook(MtaHookEvent::Error), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Id = mta_hook.id.clone(), Reason = err, ); diff --git a/crates/smtp/src/inbound/mail.rs b/crates/smtp/src/inbound/mail.rs index 16958d91..13be3f52 100644 --- a/crates/smtp/src/inbound/mail.rs +++ b/crates/smtp/src/inbound/mail.rs @@ -53,7 +53,7 @@ impl Session { } else { SmtpEvent::IprevFail }), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Domain = self.data.helo_domain.clone(), Result = trc::Event::from(&iprev), Elapsed = time.elapsed(), @@ -362,7 +362,7 @@ impl Session { } else { SmtpEvent::SpfFromFail }), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Domain = self.data.helo_domain.clone(), From = if !mail_from.address.is_empty() { mail_from.address.as_str() @@ -387,7 +387,7 @@ impl Session { trc::event!( Smtp(SmtpEvent::MailFrom), - SessionId = self.data.session_id, + SpanId = self.data.session_id, From = self.data.mail_from.as_ref().unwrap().address_lcase.clone(), ); @@ -396,7 +396,7 @@ impl Session { } else { trc::event!( Smtp(SmtpEvent::RateLimitExceeded), - SessionId = self.data.session_id, + SpanId = self.data.session_id, From = self.data.mail_from.as_ref().unwrap().address_lcase.clone(), ); diff --git a/crates/smtp/src/inbound/milter/client.rs b/crates/smtp/src/inbound/milter/client.rs index 3d0e23fc..1e641a29 100644 --- a/crates/smtp/src/inbound/milter/client.rs +++ b/crates/smtp/src/inbound/milter/client.rs @@ -311,7 +311,7 @@ impl MilterClient { async fn write(&mut self, action: Command<'_>) -> super::Result<()> { trc::event!( Milter(MilterEvent::Write), - SessionId = self.session_id, + SpanId = self.session_id, Id = self.id.to_string(), Contents = action.to_string(), ); @@ -331,7 +331,7 @@ impl MilterClient { if let Some(response) = Response::deserialize(&frame) { trc::event!( Milter(MilterEvent::Read), - SessionId = self.session_id, + SpanId = self.session_id, Id = self.id.to_string(), Contents = response.to_string(), ); diff --git a/crates/smtp/src/inbound/milter/message.rs b/crates/smtp/src/inbound/milter/message.rs index d9676a86..a9455cb2 100644 --- a/crates/smtp/src/inbound/milter/message.rs +++ b/crates/smtp/src/inbound/milter/message.rs @@ -57,7 +57,7 @@ impl Session { Ok(new_modifications) => { trc::event!( Milter(MilterEvent::ActionAccept), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Id = milter.id.to_string(), Contents = new_modifications .iter() @@ -93,7 +93,7 @@ impl Session { Action::ConnectionFailure => MilterEvent::ActionConnectionFailure, Action::Accept | Action::Continue => unreachable!(), }), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Id = milter.id.to_string(), ); @@ -141,7 +141,7 @@ impl Session { trc::event!( Milter(code), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Id = milter.id.to_string(), Details = details, ); @@ -320,7 +320,7 @@ impl SessionData { Err(err) => { trc::event!( Milter(MilterEvent::ParseError), - SessionId = self.session_id, + SpanId = self.session_id, Details = "Failed to parse milter mailFrom parameters", Reason = err.to_string(), ); @@ -356,7 +356,7 @@ impl SessionData { Err(err) => { trc::event!( Milter(MilterEvent::ParseError), - SessionId = self.session_id, + SpanId = self.session_id, Details = "Failed to parse milter rcptTo parameters", Reason = err.to_string(), ); diff --git a/crates/smtp/src/inbound/rcpt.rs b/crates/smtp/src/inbound/rcpt.rs index 1beee3b9..711e2af6 100644 --- a/crates/smtp/src/inbound/rcpt.rs +++ b/crates/smtp/src/inbound/rcpt.rs @@ -174,7 +174,7 @@ impl Session { if !is_local_address { trc::event!( Smtp(SmtpEvent::MailboxDoesNotExist), - SessionId = self.data.session_id, + SpanId = self.data.session_id, To = rcpt.address_lcase.clone(), ); @@ -186,7 +186,7 @@ impl Session { } Err(err) => { trc::error!(err - .session_id(self.data.session_id) + .span_id(self.data.session_id) .caused_by(trc::location!()) .details("Failed to verify address.")); @@ -209,7 +209,7 @@ impl Session { { trc::event!( Smtp(SmtpEvent::RelayNotAllowed), - SessionId = self.data.session_id, + SpanId = self.data.session_id, To = rcpt.address_lcase.clone(), ); @@ -219,7 +219,7 @@ impl Session { } Err(err) => { trc::error!(err - .session_id(self.data.session_id) + .span_id(self.data.session_id) .caused_by(trc::location!()) .details("Failed to verify address.")); @@ -242,7 +242,7 @@ impl Session { { trc::event!( Smtp(SmtpEvent::RelayNotAllowed), - SessionId = self.data.session_id, + SpanId = self.data.session_id, To = rcpt.address_lcase.clone(), ); @@ -253,13 +253,13 @@ impl Session { if self.is_allowed().await { trc::event!( Smtp(SmtpEvent::RelayNotAllowed), - SessionId = self.data.session_id, + SpanId = self.data.session_id, To = self.data.rcpt_to.last().unwrap().address_lcase.clone(), ); } else { trc::event!( Smtp(SmtpEvent::RateLimitExceeded), - SessionId = self.data.session_id, + SpanId = self.data.session_id, To = self.data.rcpt_to.last().unwrap().address_lcase.clone(), ); @@ -281,7 +281,7 @@ impl Session { } else { trc::event!( Smtp(SmtpEvent::TooManyInvalidRcpt), - SessionId = self.data.session_id, + SpanId = self.data.session_id, ); self.write(b"421 4.3.0 Too many errors, disconnecting.\r\n") diff --git a/crates/smtp/src/inbound/session.rs b/crates/smtp/src/inbound/session.rs index ccc95060..0d736c35 100644 --- a/crates/smtp/src/inbound/session.rs +++ b/crates/smtp/src/inbound/session.rs @@ -296,7 +296,7 @@ impl Session { if receiver.ingest(&mut iter) { trc::event!( Smtp(SmtpEvent::MessageTooLarge), - SessionId = self.data.session_id, + SpanId = self.data.session_id, ); self.data.message = Vec::with_capacity(0); @@ -342,7 +342,7 @@ impl Session { Ok(_) => { trc::event!( Smtp(SmtpEvent::RawOutput), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Size = bytes.len(), Contents = String::from_utf8_lossy(bytes).into_owned(), ); @@ -352,7 +352,7 @@ impl Session { Err(err) => { trc::event!( Network(NetworkEvent::FlushError), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Reason = err.to_string(), ); Err(()) @@ -361,7 +361,7 @@ impl Session { Err(err) => { trc::event!( Network(NetworkEvent::WriteError), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Reason = err.to_string(), ); @@ -376,7 +376,7 @@ impl Session { Ok(len) => { trc::event!( Smtp(SmtpEvent::RawInput), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Size = len, Contents = String::from_utf8_lossy(bytes.get(0..len).unwrap_or_default()).into_owned(), @@ -387,7 +387,7 @@ impl Session { Err(err) => { trc::event!( Network(NetworkEvent::ReadError), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Reason = err.to_string(), ); diff --git a/crates/smtp/src/inbound/spawn.rs b/crates/smtp/src/inbound/spawn.rs index 0f49e614..319b2f24 100644 --- a/crates/smtp/src/inbound/spawn.rs +++ b/crates/smtp/src/inbound/spawn.rs @@ -122,7 +122,7 @@ impl Session { if self.hostname.is_empty() { trc::event!( Smtp(SmtpEvent::MissingLocalHostname), - SessionId = self.data.session_id, + SpanId = self.data.session_id, ); self.hostname = "localhost".to_string(); } @@ -175,7 +175,7 @@ impl Session { trc::event!( Smtp(SmtpEvent::TransferLimitExceeded), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Size = bytes_read, ); @@ -188,7 +188,7 @@ impl Session { trc::event!( Smtp(SmtpEvent::TimeLimitExceeded), - SessionId = self.data.session_id, + SpanId = self.data.session_id, ); break; @@ -196,7 +196,7 @@ impl Session { } else { trc::event!( Network(trc::NetworkEvent::Closed), - SessionId = self.data.session_id, + SpanId = self.data.session_id, CausedBy = trc::location!() ); @@ -209,7 +209,7 @@ impl Session { Err(_) => { trc::event!( Network(trc::NetworkEvent::Timeout), - SessionId = self.data.session_id, + SpanId = self.data.session_id, CausedBy = trc::location!() ); @@ -224,7 +224,7 @@ impl Session { _ = shutdown_rx.changed() => { trc::event!( Network(trc::NetworkEvent::Closed), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Reason = "Server shutting down", CausedBy = trc::location!() ); diff --git a/crates/smtp/src/inbound/vrfy.rs b/crates/smtp/src/inbound/vrfy.rs index bff9ef91..78254dec 100644 --- a/crates/smtp/src/inbound/vrfy.rs +++ b/crates/smtp/src/inbound/vrfy.rs @@ -43,7 +43,7 @@ impl Session { trc::event!( Smtp(SmtpEvent::Vrfy), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Name = address, Result = values, ); @@ -53,7 +53,7 @@ impl Session { Ok(_) => { trc::event!( Smtp(SmtpEvent::VrfyNotFound), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Name = address, ); @@ -63,7 +63,7 @@ impl Session { let is_not_supported = err.matches(trc::EventType::Store(trc::StoreEvent::NotSupported)); - trc::error!(err.session_id(self.data.session_id).details("VRFY failed")); + trc::error!(err.span_id(self.data.session_id).details("VRFY failed")); if !is_not_supported { self.write(b"252 2.4.3 Unable to verify address at this time.\r\n") @@ -77,7 +77,7 @@ impl Session { _ => { trc::event!( Smtp(SmtpEvent::VrfyDisabled), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Name = address, ); @@ -118,7 +118,7 @@ impl Session { trc::event!( Smtp(SmtpEvent::Expn), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Name = address, Result = values, ); @@ -128,7 +128,7 @@ impl Session { Ok(_) => { trc::event!( Smtp(SmtpEvent::ExpnNotFound), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Name = address, ); @@ -138,7 +138,7 @@ impl Session { let is_not_supported = err.matches(trc::EventType::Store(trc::StoreEvent::NotSupported)); - trc::error!(err.session_id(self.data.session_id).details("VRFY failed")); + trc::error!(err.span_id(self.data.session_id).details("VRFY failed")); if !is_not_supported { self.write(b"252 2.4.3 Unable to expand mailing list at this time.\r\n") @@ -152,7 +152,7 @@ impl Session { _ => { trc::event!( Smtp(SmtpEvent::ExpnDisabled), - SessionId = self.data.session_id, + SpanId = self.data.session_id, Name = address, ); diff --git a/crates/smtp/src/outbound/dane/verify.rs b/crates/smtp/src/outbound/dane/verify.rs index b7cc7ab4..e2d58ac2 100644 --- a/crates/smtp/src/outbound/dane/verify.rs +++ b/crates/smtp/src/outbound/dane/verify.rs @@ -34,7 +34,7 @@ impl TlsaVerify for Tlsa { } else { trc::event!( Dane(DaneEvent::NoCertificatesFound), - SessionId = session_id, + SpanId = session_id, Hostname = hostname.to_string(), ); @@ -53,7 +53,7 @@ impl TlsaVerify for Tlsa { Err(err) => { trc::event!( Dane(DaneEvent::CertificateParseError), - SessionId = session_id, + SpanId = session_id, Hostname = hostname.to_string(), Reason = err.to_string(), ); @@ -96,7 +96,7 @@ impl TlsaVerify for Tlsa { if hash == record.data { trc::event!( Dane(DaneEvent::TlsaRecordMatch), - SessionId = session_id, + SpanId = session_id, Hostname = hostname.to_string(), Type = if is_end_entity { "end-entity" @@ -130,7 +130,7 @@ impl TlsaVerify for Tlsa { { trc::event!( Dane(DaneEvent::AuthenticationSuccess), - SessionId = session_id, + SpanId = session_id, Hostname = hostname.to_string(), ); @@ -138,7 +138,7 @@ impl TlsaVerify for Tlsa { } else { trc::event!( Dane(DaneEvent::AuthenticationFailure), - SessionId = session_id, + SpanId = session_id, Hostname = hostname.to_string(), ); diff --git a/crates/smtp/src/outbound/delivery.rs b/crates/smtp/src/outbound/delivery.rs index c2a26816..bd27ef7e 100644 --- a/crates/smtp/src/outbound/delivery.rs +++ b/crates/smtp/src/outbound/delivery.rs @@ -18,9 +18,10 @@ use mail_send::SmtpClient; use smtp_proto::MAIL_REQUIRETLS; use std::{ net::{IpAddr, Ipv4Addr, SocketAddr}, - time::Duration, + time::{Duration, Instant}, }; use store::write::{now, BatchBuilder, QueueClass, QueueEvent, ValueClass}; +use trc::{DaneEvent, DeliveryEvent, MtaStsEvent, ServerEvent, TlsRptEvent}; use crate::{ core::SMTP, @@ -42,276 +43,298 @@ impl DeliveryAttempt { pub async fn try_deliver(mut self, core: SMTP) { tokio::spawn(async move { // Lock message - self.event = if let Some(event) = core.try_lock_event(self.event).await { - event - } else { - return; - }; + if let Some(event) = core.try_lock_event(self.event).await { + self.event = event; - // Fetch message - let mut message = if let Some(message) = core.read_message(self.event.queue_id).await { - message - } else { - // Message no longer exists, delete queue event. - let mut batch = BatchBuilder::new(); - batch.clear(ValueClass::Queue(QueueClass::MessageEvent(QueueEvent { - due: self.event.due, - queue_id: self.event.queue_id, - }))); - let _ = core.core.storage.data.write(batch.build()).await; - return; - }; + // Fetch message + if let Some(message) = core.read_message(self.event.queue_id).await { + trc::event!( + Delivery(DeliveryEvent::AttemptStart), + SpanId = message.id, + From = if !message.return_path.is_empty() { + trc::Value::String(message.return_path.to_string()) + } else { + trc::Value::Static("<>") + }, + Size = message.size, + Count = message.recipients.len(), + ); - let span = trc::event_span!( - "delivery", - "id" = message.id, - "return_path" = if !message.return_path.is_empty() { - message.return_path.as_ref() + // Attempt delivery + let start_time = Instant::now(); + let span_id = message.id; + self.deliver_task(core, message).await; + + trc::event!( + Delivery(DeliveryEvent::AttemptEnd), + SpanId = span_id, + Elapsed = start_time.elapsed(), + ); } else { - "<>" - }, - "nrcpt" = message.recipients.len(), - "size" = message.size - ); + // Message no longer exists, delete queue event. + let mut batch = BatchBuilder::new(); + batch.clear(ValueClass::Queue(QueueClass::MessageEvent(QueueEvent { + due: self.event.due, + queue_id: self.event.queue_id, + }))); - // Check that the message still has recipients to be delivered - let has_pending_delivery = message.has_pending_delivery(); - - // Send any due Delivery Status Notifications - core.send_dsn(&mut message).await; - - if has_pending_delivery { - // Re-queue the message if its not yet due for delivery - let due = message.next_delivery_event(); - if due > now() { - // Save changes - message - .save_changes(&core, self.event.due.into(), due.into()) - .await; - if core.inner.queue_tx.send(Event::Reload).await.is_err() { - trc::event!("Channel closed while trying to notify queue manager."); + if let Err(err) = core.core.storage.data.write(batch.build()).await { + trc::error!(err + .details("Failed to delete queue event.") + .caused_by(trc::location!())); } - return; - } - } else { - // All message recipients expired, do not re-queue. (DSN has been already sent) - message.remove(&core, self.event.due).await; - if core.inner.queue_tx.send(Event::Reload).await.is_err() { - trc::event!("Channel closed while trying to notify queue manager."); } + } + }); + } + async fn deliver_task(mut self, core: SMTP, mut message: Message) { + // Check that the message still has recipients to be delivered + let has_pending_delivery = message.has_pending_delivery(); + let message_id = message.id; + + // Send any due Delivery Status Notifications + core.send_dsn(&mut message).await; + + if has_pending_delivery { + // Re-queue the message if its not yet due for delivery + let due = message.next_delivery_event(); + if due > now() { + // Save changes + message + .save_changes(&core, self.event.due.into(), due.into()) + .await; + if core.inner.queue_tx.send(Event::Reload).await.is_err() { + trc::event!( + Server(ServerEvent::ThreadError), + Reason = "Channel closed.", + CausedBy = trc::location!(), + SpanId = message_id + ); + } return; } - - // Throttle sender - for throttle in &core.core.smtp.queue.throttle.sender { - if let Err(err) = core - .is_allowed(throttle, &message, &mut self.in_flight, message.id) - .await - { - let event = match err { - throttle::Error::Concurrency { limiter } => { - // Save changes to disk - let next_due = message.next_event_after(now()); - message.save_changes(&core, None, None).await; - - Event::OnHold(OnHold { - next_due, - limiters: vec![limiter], - message: self.event, - }) - } - throttle::Error::Rate { retry_at } => { - // Save changes to disk - let next_event = std::cmp::min( - retry_at, - message.next_event_after(now()).unwrap_or(u64::MAX), - ); - message - .save_changes(&core, self.event.due.into(), next_event.into()) - .await; - - Event::Reload - } - }; - - if core.inner.queue_tx.send(event).await.is_err() { - trc::event!("Channel closed while trying to notify queue manager."); - } - return; - } + } else { + // All message recipients expired, do not re-queue. (DSN has been already sent) + message.remove(&core, self.event.due).await; + if core.inner.queue_tx.send(Event::Reload).await.is_err() { + trc::event!( + Server(ServerEvent::ThreadError), + Reason = "Channel closed.", + CausedBy = trc::location!(), + SpanId = message_id + ); } - let queue_config = &core.core.smtp.queue; - let mut on_hold = Vec::new(); - let no_ip = IpAddr::V4(Ipv4Addr::new(0, 0, 0, 0)); - let mut recipients = std::mem::take(&mut message.recipients); - 'next_domain: for domain_idx in 0..message.domains.len() { - // Only process domains due for delivery - let domain = &message.domains[domain_idx]; - if !matches!(&domain.status, Status::Scheduled | Status::TemporaryFailure(_) - if domain.retry.due <= now()) - { - continue; - } + return; + } - // Create new span for domain - let span = trc::event_span!( - "attempt", - domain = domain.domain, - attempt_number = domain.retry.inner, - ); + // Throttle sender + for throttle in &core.core.smtp.queue.throttle.sender { + if let Err(err) = core + .is_allowed(throttle, &message, &mut self.in_flight, message.id) + .await + { + let event = match err { + throttle::Error::Concurrency { limiter } => { + // Save changes to disk + let next_due = message.next_event_after(now()); + message.save_changes(&core, None, None).await; - // Build envelope - let mut envelope = QueueEnvelope::new(&message, domain_idx); - - // Throttle recipient domain - let mut in_flight = Vec::new(); - for throttle in &queue_config.throttle.rcpt { - if let Err(err) = core - .is_allowed(throttle, &envelope, &mut in_flight, message.id) - .await - { - message.domains[domain_idx].set_throttle_error(err, &mut on_hold); - continue 'next_domain; + Event::OnHold(OnHold { + next_due, + limiters: vec![limiter], + message: self.event, + }) } - } - - // Obtain next hop - let (mut remote_hosts, is_smtp) = match core - .core - .eval_if::(&queue_config.next_hop, &envelope, message.id) - .await - .and_then(|name| core.core.get_relay_host(&name, message.id)) - { - Some(next_hop) if next_hop.protocol == ServerProtocol::Http => { - // Deliver message locally - let delivery_result = message - .deliver_local( - recipients.iter_mut().filter(|r| r.domain_idx == domain_idx), - &core.inner.ipc.delivery_tx, - ) + throttle::Error::Rate { retry_at } => { + // Save changes to disk + let next_event = std::cmp::min( + retry_at, + message.next_event_after(now()).unwrap_or(u64::MAX), + ); + message + .save_changes(&core, self.event.due.into(), next_event.into()) .await; - // Update status for the current domain and continue with the next one - let schedule = core - .core - .eval_if::, _>(&queue_config.retry, &envelope, message.id) - .await - .unwrap_or_else(|| vec![Duration::from_secs(60)]); - message.domains[domain_idx].set_status(delivery_result, &schedule); - continue 'next_domain; + Event::Reload } - Some(next_hop) => ( - vec![NextHop::Relay(next_hop)], - next_hop.protocol == ServerProtocol::Smtp, - ), - None => (Vec::with_capacity(0), true), }; - // Prepare TLS strategy - let mut tls_strategy = TlsStrategy { - mta_sts: core - .core - .eval_if(&queue_config.tls.mta_sts, &envelope, message.id) - .await - .unwrap_or(RequireOptional::Optional), - ..Default::default() - }; - let allow_invalid_certs = core - .core - .eval_if(&queue_config.tls.invalid_certs, &envelope, message.id) - .await - .unwrap_or(false); + if core.inner.queue_tx.send(event).await.is_err() { + trc::event!( + Server(ServerEvent::ThreadError), + Reason = "Channel closed.", + CausedBy = trc::location!(), + SpanId = message_id + ); + } + return; + } + } - // Obtain TLS reporting - let tls_report = match core - .core - .eval_if(&core.core.smtp.report.tls.send, &envelope, message.id) + let queue_config = &core.core.smtp.queue; + let mut on_hold = Vec::new(); + let no_ip = IpAddr::V4(Ipv4Addr::new(0, 0, 0, 0)); + let mut recipients = std::mem::take(&mut message.recipients); + 'next_domain: for domain_idx in 0..message.domains.len() { + // Only process domains due for delivery + let domain = &message.domains[domain_idx]; + if !matches!(&domain.status, Status::Scheduled | Status::TemporaryFailure(_) + if domain.retry.due <= now()) + { + continue; + } + + trc::event!( + Delivery(DeliveryEvent::AttemptCount), + SpanId = message.id, + Domain = domain.domain.clone(), + Count = domain.retry.inner, + ); + + // Build envelope + let mut envelope = QueueEnvelope::new(&message, domain_idx); + + // Throttle recipient domain + let mut in_flight = Vec::new(); + for throttle in &queue_config.throttle.rcpt { + if let Err(err) = core + .is_allowed(throttle, &envelope, &mut in_flight, message.id) .await - .unwrap_or(AggregateFrequency::Never) { - interval @ (AggregateFrequency::Hourly - | AggregateFrequency::Daily - | AggregateFrequency::Weekly) - if is_smtp => - { - match core - .core - .smtp - .resolvers - .dns - .txt_lookup::(format!("_smtp._tls.{}.", domain.domain)) - .await - { - Ok(record) => { - trc::event!( - context = "tlsrpt", - event = "record-fetched", - record = ?record); + message.domains[domain_idx].set_throttle_error(err, &mut on_hold); + continue 'next_domain; + } + } - TlsRptOptions { record, interval }.into() - } - Err(err) => { - trc::event!( - context = "tlsrpt", - "Failed to retrieve TLSRPT record: {}", - err - ); - None - } - } - } - _ => None, - }; - - // Obtain MTA-STS policy for domain - let mta_sts_policy = if tls_strategy.try_mta_sts() && is_smtp { - match core - .lookup_mta_sts_policy( - &domain.domain, - core.core - .eval_if(&queue_config.timeout.mta_sts, &envelope, message.id) - .await - .unwrap_or_else(|| Duration::from_secs(10 * 60)), + // Obtain next hop + let (mut remote_hosts, is_smtp) = match core + .core + .eval_if::(&queue_config.next_hop, &envelope, message.id) + .await + .and_then(|name| core.core.get_relay_host(&name, message.id)) + { + Some(next_hop) if next_hop.protocol == ServerProtocol::Http => { + // Deliver message locally + let delivery_result = message + .deliver_local( + recipients.iter_mut().filter(|r| r.domain_idx == domain_idx), + &core.inner.ipc.delivery_tx, ) + .await; + + // Update status for the current domain and continue with the next one + let schedule = core + .core + .eval_if::, _>(&queue_config.retry, &envelope, message.id) + .await + .unwrap_or_else(|| vec![Duration::from_secs(60)]); + message.domains[domain_idx].set_status(delivery_result, &schedule); + continue 'next_domain; + } + Some(next_hop) => ( + vec![NextHop::Relay(next_hop)], + next_hop.protocol == ServerProtocol::Smtp, + ), + None => (Vec::with_capacity(0), true), + }; + + // Prepare TLS strategy + let mut tls_strategy = TlsStrategy { + mta_sts: core + .core + .eval_if(&queue_config.tls.mta_sts, &envelope, message.id) + .await + .unwrap_or(RequireOptional::Optional), + ..Default::default() + }; + let allow_invalid_certs = core + .core + .eval_if(&queue_config.tls.invalid_certs, &envelope, message.id) + .await + .unwrap_or(false); + + // Obtain TLS reporting + let tls_report = match core + .core + .eval_if(&core.core.smtp.report.tls.send, &envelope, message.id) + .await + .unwrap_or(AggregateFrequency::Never) + { + interval @ (AggregateFrequency::Hourly + | AggregateFrequency::Daily + | AggregateFrequency::Weekly) + if is_smtp => + { + match core + .core + .smtp + .resolvers + .dns + .txt_lookup::(format!("_smtp._tls.{}.", domain.domain)) .await { - Ok(mta_sts_policy) => { + Ok(record) => { trc::event!( - - context = "sts", - event = "policy-fetched", - policy = ?mta_sts_policy, + TlsRpt(TlsRptEvent::RecordFetch), + SpanId = message.id, + Domain = domain.domain.clone(), + Details = format!("{record:?}") ); - mta_sts_policy.into() + TlsRptOptions { record, interval }.into() } Err(err) => { - // Report MTA-STS error - if let Some(tls_report) = &tls_report { - match &err { - mta_sts::Error::Dns(mail_auth::Error::DnsRecordNotFound(_)) => { - if tls_strategy.is_mta_sts_required() { - core.schedule_report(TlsEvent { - policy: PolicyType::Sts(None), - domain: domain.domain.to_string(), - failure: FailureDetails::new(ResultType::Other) - .with_failure_reason_code("MTA-STS is required and no policy was found.") - .into(), - tls_record: tls_report.record.clone(), - interval: tls_report.interval, - }) - .await; - } - } - mta_sts::Error::Dns(mail_auth::Error::DnsError(_)) => (), - _ => { + trc::event!( + TlsRpt(TlsRptEvent::RecordFetchError), + SpanId = message.id, + Domain = domain.domain.clone(), + CausedBy = trc::Event::from(err) + ); + None + } + } + } + _ => None, + }; + + // Obtain MTA-STS policy for domain + let mta_sts_policy = if tls_strategy.try_mta_sts() && is_smtp { + match core + .lookup_mta_sts_policy( + &domain.domain, + core.core + .eval_if(&queue_config.timeout.mta_sts, &envelope, message.id) + .await + .unwrap_or_else(|| Duration::from_secs(10 * 60)), + ) + .await + { + Ok(mta_sts_policy) => { + trc::event!( + MtaSts(MtaStsEvent::PolicyFetch), + SpanId = message.id, + Domain = domain.domain.clone(), + Details = mta_sts_policy.to_string() + ); + + mta_sts_policy.into() + } + Err(err) => { + // Report MTA-STS error + let strict = tls_strategy.is_mta_sts_required(); + if let Some(tls_report) = &tls_report { + match &err { + mta_sts::Error::Dns(mail_auth::Error::DnsRecordNotFound(_)) => { + if strict { core.schedule_report(TlsEvent { policy: PolicyType::Sts(None), domain: domain.domain.to_string(), - failure: FailureDetails::new(&err) - .with_failure_reason_code(err.to_string()) + failure: FailureDetails::new(ResultType::Other) + .with_failure_reason_code( + "MTA-STS is required and no policy was found.", + ) .into(), tls_record: tls_report.record.clone(), interval: tls_report.interval, @@ -319,55 +342,61 @@ impl DeliveryAttempt { .await; } } + mta_sts::Error::Dns(mail_auth::Error::DnsError(_)) => (), + _ => { + core.schedule_report(TlsEvent { + policy: PolicyType::Sts(None), + domain: domain.domain.to_string(), + failure: FailureDetails::new(&err) + .with_failure_reason_code(err.to_string()) + .into(), + tls_record: tls_report.record.clone(), + interval: tls_report.interval, + }) + .await; + } } - - if tls_strategy.is_mta_sts_required() { - trc::event!( - context = "sts", - event = "policy-fetch-failure", - "Failed to retrieve MTA-STS policy: {}", - err - ); - let schedule = core - .core - .eval_if::, _>( - &queue_config.retry, - &envelope, - message.id, - ) - .await - .unwrap_or_else(|| vec![Duration::from_secs(60)]); - message.domains[domain_idx].set_status(err, &schedule); - continue 'next_domain; - } else { - trc::event!( - context = "sts", - event = "policy-fetch-failure", - "Failed to retrieve MTA-STS policy: {}", - err - ); - } - - None } - } - } else { - None - }; - // Obtain remote hosts list - let mx_list; - if is_smtp && remote_hosts.is_empty() { - // Lookup MX - mx_list = match core.core.smtp.resolvers.dns.mx_lookup(&domain.domain).await { - Ok(mx) => mx, - Err(err) => { - trc::event!( + match &err { + mta_sts::Error::Dns(mail_auth::Error::DnsRecordNotFound(_)) => { + trc::event!( + MtaSts(MtaStsEvent::PolicyNotFound), + SpanId = message.id, + Domain = domain.domain.clone(), + Strict = strict, + ); + } + mta_sts::Error::Dns(err) => { + trc::event!( + MtaSts(MtaStsEvent::PolicyFetchError), + SpanId = message.id, + Domain = domain.domain.clone(), + CausedBy = trc::Event::from(err.clone()), + Strict = strict, + ); + } + mta_sts::Error::Http(err) => { + trc::event!( + MtaSts(MtaStsEvent::PolicyFetchError), + SpanId = message.id, + Domain = domain.domain.clone(), + Reason = err.to_string(), + Strict = strict, + ); + } + mta_sts::Error::InvalidPolicy(reason) => { + trc::event!( + MtaSts(MtaStsEvent::InvalidPolicy), + SpanId = message.id, + Domain = domain.domain.clone(), + Reason = reason.clone(), + Strict = strict, + ); + } + } - context = "dns", - event = "mx-lookup-failed", - reason = %err, - ); + if strict { let schedule = core .core .eval_if::, _>( @@ -380,164 +409,259 @@ impl DeliveryAttempt { message.domains[domain_idx].set_status(err, &schedule); continue 'next_domain; } - }; - if let Some(remote_hosts_) = mx_list.to_remote_hosts( - &domain.domain, - core.core - .eval_if(&queue_config.max_mx, &envelope, message.id) - .await - .unwrap_or(5), - ) { - remote_hosts = remote_hosts_; - } else { + None + } + } + } else { + None + }; + + // Obtain remote hosts list + let mx_list; + if is_smtp && remote_hosts.is_empty() { + // Lookup MX + mx_list = match core.core.smtp.resolvers.dns.mx_lookup(&domain.domain).await { + Ok(mx) => mx, + Err(err) => { trc::event!( - context = "dns", - event = "null-mx", - reason = "Domain does not accept messages (mull MX)", + Delivery(DeliveryEvent::MxLookupFailed), + SpanId = message.id, + Domain = domain.domain.clone(), + CausedBy = trc::Event::from(err.clone()), ); + let schedule = core .core .eval_if::, _>(&queue_config.retry, &envelope, message.id) .await .unwrap_or_else(|| vec![Duration::from_secs(60)]); - message.domains[domain_idx].set_status( - Status::PermanentFailure(Error::DnsError( - "Domain does not accept messages (null MX)".to_string(), - )), - &schedule, - ); + message.domains[domain_idx].set_status(err, &schedule); continue 'next_domain; } + }; + + if let Some(remote_hosts_) = mx_list.to_remote_hosts( + &domain.domain, + core.core + .eval_if(&queue_config.max_mx, &envelope, message.id) + .await + .unwrap_or(5), + ) { + remote_hosts = remote_hosts_; + } else { + trc::event!( + Delivery(DeliveryEvent::NullMX), + SpanId = message.id, + Domain = domain.domain.clone(), + ); + + let schedule = core + .core + .eval_if::, _>(&queue_config.retry, &envelope, message.id) + .await + .unwrap_or_else(|| vec![Duration::from_secs(60)]); + message.domains[domain_idx].set_status( + Status::PermanentFailure(Error::DnsError( + "Domain does not accept messages (null MX)".to_string(), + )), + &schedule, + ); + continue 'next_domain; + } + } + + // Try delivering message + let max_multihomed = core + .core + .eval_if(&queue_config.max_multihomed, &envelope, message.id) + .await + .unwrap_or(2); + let mut last_status = Status::Scheduled; + 'next_host: for remote_host in &remote_hosts { + // Validate MTA-STS + envelope.mx = remote_host.hostname(); + if let Some(mta_sts_policy) = &mta_sts_policy { + if !mta_sts_policy.verify(envelope.mx) { + // Report MTA-STS failed verification + if let Some(tls_report) = &tls_report { + core.schedule_report(TlsEvent { + policy: mta_sts_policy.into(), + domain: domain.domain.to_string(), + failure: FailureDetails::new(ResultType::ValidationFailure) + .with_receiving_mx_hostname(envelope.mx) + .with_failure_reason_code("MX not authorized by policy.") + .into(), + tls_record: tls_report.record.clone(), + interval: tls_report.interval, + }) + .await; + } + + let strict = mta_sts_policy.enforce(); + + trc::event!( + MtaSts(MtaStsEvent::NotAuthorized), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Strict = strict, + ); + + if strict { + last_status = Status::PermanentFailure(Error::MtaStsError(format!( + "MX {:?} not authorized by policy.", + envelope.mx + ))); + continue 'next_host; + } + } } - // Try delivering message - let max_multihomed = core - .core - .eval_if(&queue_config.max_multihomed, &envelope, message.id) + // Obtain source and remote IPs + let resolve_result = match core + .resolve_host(remote_host, &envelope, max_multihomed, message.id) .await - .unwrap_or(2); - let mut last_status = Status::Scheduled; - 'next_host: for remote_host in &remote_hosts { - // Validate MTA-STS - envelope.mx = remote_host.hostname(); - if let Some(mta_sts_policy) = &mta_sts_policy { - if !mta_sts_policy.verify(envelope.mx) { - // Report MTA-STS failed verification - if let Some(tls_report) = &tls_report { - core.schedule_report(TlsEvent { - policy: mta_sts_policy.into(), - domain: domain.domain.to_string(), - failure: FailureDetails::new(ResultType::ValidationFailure) - .with_receiving_mx_hostname(envelope.mx) - .with_failure_reason_code("MX not authorized by policy.") - .into(), - tls_record: tls_report.record.clone(), - interval: tls_report.interval, - }) - .await; - } + { + Ok(result) => result, + Err(status) => { + trc::event!( + Delivery(DeliveryEvent::IpLookupFailed), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Details = status.to_string(), + ); + last_status = status; + continue 'next_host; + } + }; + + // Update TLS strategy + tls_strategy.dane = core + .core + .eval_if(&queue_config.tls.dane, &envelope, message.id) + .await + .unwrap_or(RequireOptional::Optional); + tls_strategy.tls = core + .core + .eval_if(&queue_config.tls.start, &envelope, message.id) + .await + .unwrap_or(RequireOptional::Optional); + + // Lookup DANE policy + let dane_policy = if tls_strategy.try_dane() && is_smtp { + let strict = tls_strategy.is_dane_required(); + match core.tlsa_lookup(format!("_25._tcp.{}.", envelope.mx)).await { + Ok(Some(tlsa)) => { + if tlsa.has_end_entities { + trc::event!( + Dane(DaneEvent::TlsaRecordFetch), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Details = format!("{tlsa:?}"), + Strict = strict, + ); + + tlsa.into() + } else { + trc::event!( + Dane(DaneEvent::TlsaRecordInvalid), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Details = format!("{tlsa:?}"), + Strict = strict, + ); + + // Report invalid TLSA record + if let Some(tls_report) = &tls_report { + core.schedule_report(TlsEvent { + policy: tlsa.into(), + domain: domain.domain.to_string(), + failure: FailureDetails::new(ResultType::TlsaInvalid) + .with_receiving_mx_hostname(envelope.mx) + .with_failure_reason_code("Invalid TLSA record.") + .into(), + tls_record: tls_report.record.clone(), + interval: tls_report.interval, + }) + .await; + } + + if strict { + last_status = + Status::PermanentFailure(Error::DaneError(ErrorDetails { + entity: envelope.mx.to_string(), + details: "No valid TLSA records were found".to_string(), + })); + continue 'next_host; + } + None + } + } + Ok(None) => { trc::event!( - context = "sts", - event = "policy-error", - mx = envelope.mx, - "MX not authorized by policy." + Dane(DaneEvent::TlsaRecordNotDnssecSigned), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Strict = strict, ); - if mta_sts_policy.enforce() { - last_status = Status::PermanentFailure(Error::MtaStsError( - format!("MX {:?} not authorized by policy.", envelope.mx), - )); + if strict { + // Report DANE required + if let Some(tls_report) = &tls_report { + core.schedule_report(TlsEvent { + policy: PolicyType::Tlsa(None), + domain: domain.domain.to_string(), + failure: FailureDetails::new(ResultType::DaneRequired) + .with_receiving_mx_hostname(envelope.mx) + .with_failure_reason_code( + "No TLSA DNSSEC records found.", + ) + .into(), + tls_record: tls_report.record.clone(), + interval: tls_report.interval, + }) + .await; + } + + last_status = + Status::PermanentFailure(Error::DaneError(ErrorDetails { + entity: envelope.mx.to_string(), + details: "No TLSA DNSSEC records found".to_string(), + })); continue 'next_host; } + None } - } + Err(err) => { + let not_found = matches!(&err, mail_auth::Error::DnsRecordNotFound(_)); - // Obtain source and remote IPs - let resolve_result = match core - .resolve_host(remote_host, &envelope, max_multihomed, message.id) - .await - { - Ok(result) => result, - Err(status) => { - trc::event!( - - context = "dns", - event = "ip-lookup-failed", - mx = envelope.mx, - status = %status, - ); - - last_status = status; - continue 'next_host; - } - }; - - // Update TLS strategy - tls_strategy.dane = core - .core - .eval_if(&queue_config.tls.dane, &envelope, message.id) - .await - .unwrap_or(RequireOptional::Optional); - tls_strategy.tls = core - .core - .eval_if(&queue_config.tls.start, &envelope, message.id) - .await - .unwrap_or(RequireOptional::Optional); - - // Lookup DANE policy - let dane_policy = if tls_strategy.try_dane() && is_smtp { - match core.tlsa_lookup(format!("_25._tcp.{}.", envelope.mx)).await { - Ok(Some(tlsa)) => { - if tlsa.has_end_entities { - trc::event!( - - context = "dane", - event = "record-fetched", - mx = envelope.mx, - record = ?tlsa, - ); - - tlsa.into() - } else { - trc::event!( - context = "dane", - event = "no-tlsa-records", - mx = envelope.mx, - "No valid TLSA records were found.", - ); - - // Report invalid TLSA record - if let Some(tls_report) = &tls_report { - core.schedule_report(TlsEvent { - policy: tlsa.into(), - domain: domain.domain.to_string(), - failure: FailureDetails::new(ResultType::TlsaInvalid) - .with_receiving_mx_hostname(envelope.mx) - .with_failure_reason_code("Invalid TLSA record.") - .into(), - tls_record: tls_report.record.clone(), - interval: tls_report.interval, - }) - .await; - } - - if tls_strategy.is_dane_required() { - last_status = Status::PermanentFailure(Error::DaneError( - ErrorDetails { - entity: envelope.mx.to_string(), - details: "No valid TLSA records were found" - .to_string(), - }, - )); - continue 'next_host; - } - None - } + if not_found { + trc::event!( + Dane(DaneEvent::TlsaRecordNotFound), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Strict = strict, + ); + } else { + trc::event!( + Dane(DaneEvent::TlsaRecordFetchError), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + CausedBy = trc::Event::from(err.clone()), + Strict = strict, + ); } - Ok(None) => { - if tls_strategy.is_dane_required() { + + if strict { + last_status = if not_found { // Report DANE required if let Some(tls_report) = &tls_report { core.schedule_report(TlsEvent { @@ -546,7 +670,7 @@ impl DeliveryAttempt { failure: FailureDetails::new(ResultType::DaneRequired) .with_receiving_mx_hostname(envelope.mx) .with_failure_reason_code( - "No TLSA DNSSEC records found.", + "No TLSA records found for MX.", ) .into(), tls_record: tls_report.record.clone(), @@ -555,44 +679,236 @@ impl DeliveryAttempt { .await; } - trc::event!( - context = "dane", - event = "tlsa-dnssec-missing", - mx = envelope.mx, - "No TLSA DNSSEC records found." - ); - - last_status = - Status::PermanentFailure(Error::DaneError(ErrorDetails { - entity: envelope.mx.to_string(), - details: "No TLSA DNSSEC records found".to_string(), - })); - continue 'next_host; - } - None + Status::PermanentFailure(Error::DaneError(ErrorDetails { + entity: envelope.mx.to_string(), + details: "No TLSA records found".to_string(), + })) + } else { + err.into() + }; + continue 'next_host; } - Err(err) => { - if tls_strategy.is_dane_required() { + None + } + } + } else { + None + }; + + // Try each IP address + 'next_ip: for remote_ip in resolve_result.remote_ips { + // Set source IP, if any + let source_ip = if remote_ip.is_ipv4() { + resolve_result.source_ipv4 + } else { + resolve_result.source_ipv6 + }; + envelope.local_ip = source_ip.unwrap_or(no_ip); + + // Throttle remote host + let mut in_flight_host = Vec::new(); + envelope.remote_ip = remote_ip; + for throttle in &queue_config.throttle.host { + if let Err(err) = core + .is_allowed(throttle, &envelope, &mut in_flight_host, message.id) + .await + { + message.domains[domain_idx].set_throttle_error(err, &mut on_hold); + continue 'next_domain; + } + } + + // Connect + let conn_timeout = core + .core + .eval_if(&queue_config.timeout.connect, &envelope, message.id) + .await + .unwrap_or_else(|| Duration::from_secs(5 * 60)); + let mut smtp_client = match if let Some(ip_addr) = source_ip { + SmtpClient::connect_using( + ip_addr, + SocketAddr::new(remote_ip, remote_host.port()), + conn_timeout, + ) + .await + } else { + SmtpClient::connect( + SocketAddr::new(remote_ip, remote_host.port()), + conn_timeout, + ) + .await + } { + Ok(smtp_client) => { + trc::event!( + Delivery(DeliveryEvent::Connect), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + LocalIp = source_ip.unwrap_or(no_ip), + RemoteIp = remote_ip, + RemotePort = remote_host.port(), + ); + + smtp_client + } + Err(err) => { + trc::event!( + Delivery(DeliveryEvent::ConnectError), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + LocalIp = source_ip.unwrap_or(no_ip), + RemoteIp = remote_ip, + RemotePort = remote_host.port(), + Reason = err.to_string(), + ); + + last_status = Status::from_smtp_error(envelope.mx, "", err); + continue 'next_ip; + } + }; + + // Obtain session parameters + let local_hostname = core + .core + .eval_if::(&queue_config.hostname, &envelope, message.id) + .await + .filter(|s| !s.is_empty()) + .unwrap_or_else(|| { + trc::event!( + Delivery(DeliveryEvent::MissingOutboundHostname), + SpanId = message.id, + ); + "local.host".to_string() + }); + let params = SessionParams { + session_id: message.id, + core: &core, + credentials: remote_host.credentials(), + is_smtp: remote_host.is_smtp(), + hostname: envelope.mx, + local_hostname: &local_hostname, + timeout_ehlo: core + .core + .eval_if(&queue_config.timeout.ehlo, &envelope, message.id) + .await + .unwrap_or_else(|| Duration::from_secs(5 * 60)), + timeout_mail: core + .core + .eval_if(&queue_config.timeout.mail, &envelope, message.id) + .await + .unwrap_or_else(|| Duration::from_secs(5 * 60)), + timeout_rcpt: core + .core + .eval_if(&queue_config.timeout.rcpt, &envelope, message.id) + .await + .unwrap_or_else(|| Duration::from_secs(5 * 60)), + timeout_data: core + .core + .eval_if(&queue_config.timeout.data, &envelope, message.id) + .await + .unwrap_or_else(|| Duration::from_secs(5 * 60)), + }; + + // Prepare TLS connector + let is_strict_tls = tls_strategy.is_tls_required() + || (message.flags & MAIL_REQUIRETLS) != 0 + || mta_sts_policy.is_some() + || dane_policy.is_some(); + let tls_connector = if allow_invalid_certs || remote_host.allow_invalid_certs() + { + &core.inner.connectors.dummy_verify + } else { + &core.inner.connectors.pki_verify + }; + + let delivery_result = if !remote_host.implicit_tls() { + // Read greeting + smtp_client.timeout = core + .core + .eval_if(&queue_config.timeout.greeting, &envelope, message.id) + .await + .unwrap_or_else(|| Duration::from_secs(5 * 60)); + if let Err(status) = read_greeting(&mut smtp_client, envelope.mx).await { + trc::event!( + Delivery(DeliveryEvent::GreetingFailed), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Details = status.to_string(), + ); + + last_status = status; + continue 'next_host; + } + + // Say EHLO + let capabilities = match say_helo(&mut smtp_client, ¶ms).await { + Ok(capabilities) => capabilities, + Err(status) => { + trc::event!( + Delivery(DeliveryEvent::EhloRejected), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Details = status.to_string(), + ); + + last_status = status; + continue 'next_host; + } + }; + + // Try starting TLS + if tls_strategy.try_start_tls() { + smtp_client.timeout = core + .core + .eval_if(&queue_config.timeout.tls, &envelope, message.id) + .await + .unwrap_or_else(|| Duration::from_secs(3 * 60)); + match try_start_tls( + smtp_client, + tls_connector, + envelope.mx, + &capabilities, + ) + .await + { + StartTlsResult::Success { smtp_client } => { trc::event!( - context = "dane", - event = "tlsa-missing", - mx = envelope.mx, - "No TLSA records found." + Delivery(DeliveryEvent::StartTls), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Protocol = format!( + "{:?}", + smtp_client.tls_connection().protocol_version() + ), + Cipher = format!( + "{:?}", + smtp_client.tls_connection().negotiated_cipher_suite() + ), ); - last_status = - if matches!(&err, mail_auth::Error::DnsRecordNotFound(_)) { - // Report DANE required + // Verify DANE + if let Some(dane_policy) = &dane_policy { + if let Err(status) = dane_policy.verify( + message.id, + envelope.mx, + smtp_client.tls_connection().peer_certificates(), + ) { + // Report DANE verification failure if let Some(tls_report) = &tls_report { core.schedule_report(TlsEvent { - policy: PolicyType::Tlsa(None), + policy: dane_policy.into(), domain: domain.domain.to_string(), failure: FailureDetails::new( - ResultType::DaneRequired, + ResultType::ValidationFailure, ) .with_receiving_mx_hostname(envelope.mx) + .with_receiving_ip(remote_ip) .with_failure_reason_code( - "No TLSA records found for MX.", + "No matching certificates found.", ) .into(), tls_record: tls_report.record.clone(), @@ -601,256 +917,75 @@ impl DeliveryAttempt { .await; } - Status::PermanentFailure(Error::DaneError( - ErrorDetails { - entity: envelope.mx.to_string(), - details: "No TLSA records found".to_string(), - }, - )) - } else { - err.into() - }; - continue 'next_host; + last_status = status; + continue 'next_host; + } + } + + // Report TLS success + if let Some(tls_report) = &tls_report { + core.schedule_report(TlsEvent { + policy: (&mta_sts_policy, &dane_policy).into(), + domain: domain.domain.to_string(), + failure: None, + tls_record: tls_report.record.clone(), + interval: tls_report.interval, + }) + .await; + } + + // Deliver message over TLS + message + .deliver( + smtp_client, + recipients + .iter_mut() + .filter(|r| r.domain_idx == domain_idx), + params, + ) + .await } - None - } - } - } else { - None - }; - - // Try each IP address - 'next_ip: for remote_ip in resolve_result.remote_ips { - // Set source IP, if any - let source_ip = if remote_ip.is_ipv4() { - resolve_result.source_ipv4 - } else { - resolve_result.source_ipv6 - }; - envelope.local_ip = source_ip.unwrap_or(no_ip); - - // Throttle remote host - let mut in_flight_host = Vec::new(); - envelope.remote_ip = remote_ip; - for throttle in &queue_config.throttle.host { - if let Err(err) = core - .is_allowed(throttle, &envelope, &mut in_flight_host, message.id) - .await - { - message.domains[domain_idx].set_throttle_error(err, &mut on_hold); - continue 'next_domain; - } - } - - // Connect - let conn_timeout = core - .core - .eval_if(&queue_config.timeout.connect, &envelope, message.id) - .await - .unwrap_or_else(|| Duration::from_secs(5 * 60)); - let mut smtp_client = match if let Some(ip_addr) = source_ip { - SmtpClient::connect_using( - ip_addr, - SocketAddr::new(remote_ip, remote_host.port()), - conn_timeout, - ) - .await - } else { - SmtpClient::connect( - SocketAddr::new(remote_ip, remote_host.port()), - conn_timeout, - ) - .await - } { - Ok(smtp_client) => { - trc::event!( - - context = "connect", - event = "success", - mx = envelope.mx, - source_ip = %source_ip.unwrap_or(no_ip), - remote_ip = %remote_ip, - remote_port = remote_host.port(), - ); - - smtp_client - } - Err(err) => { - trc::event!( - - context = "connect", - event = "failed", - mx = envelope.mx, - reason = %err, - ); - last_status = Status::from_smtp_error(envelope.mx, "", err); - continue 'next_ip; - } - }; - - // Obtain session parameters - let local_hostname = core - .core - .eval_if::(&queue_config.hostname, &envelope, message.id) - .await - .filter(|s| !s.is_empty()) - .unwrap_or_else(|| { - trc::event!( - context = "queue", - event = "ehlo", - "No outbound hostname configured, using 'local.host'." - ); - "local.host".to_string() - }); - let params = SessionParams { - span: &span, - core: &core, - credentials: remote_host.credentials(), - is_smtp: remote_host.is_smtp(), - hostname: envelope.mx, - local_hostname: &local_hostname, - timeout_ehlo: core - .core - .eval_if(&queue_config.timeout.ehlo, &envelope, message.id) - .await - .unwrap_or_else(|| Duration::from_secs(5 * 60)), - timeout_mail: core - .core - .eval_if(&queue_config.timeout.mail, &envelope, message.id) - .await - .unwrap_or_else(|| Duration::from_secs(5 * 60)), - timeout_rcpt: core - .core - .eval_if(&queue_config.timeout.rcpt, &envelope, message.id) - .await - .unwrap_or_else(|| Duration::from_secs(5 * 60)), - timeout_data: core - .core - .eval_if(&queue_config.timeout.data, &envelope, message.id) - .await - .unwrap_or_else(|| Duration::from_secs(5 * 60)), - }; - - // Prepare TLS connector - let is_strict_tls = tls_strategy.is_tls_required() - || (message.flags & MAIL_REQUIRETLS) != 0 - || mta_sts_policy.is_some() - || dane_policy.is_some(); - let tls_connector = - if allow_invalid_certs || remote_host.allow_invalid_certs() { - &core.inner.connectors.dummy_verify - } else { - &core.inner.connectors.pki_verify - }; - - let delivery_result = if !remote_host.implicit_tls() { - // Read greeting - smtp_client.timeout = core - .core - .eval_if(&queue_config.timeout.greeting, &envelope, message.id) - .await - .unwrap_or_else(|| Duration::from_secs(5 * 60)); - if let Err(status) = read_greeting(&mut smtp_client, envelope.mx).await - { - trc::event!( - - context = "greeting", - event = "invalid", - mx = envelope.mx, - status = %status, - ); - - last_status = status; - continue 'next_host; - } - - // Say EHLO - let capabilities = match say_helo(&mut smtp_client, ¶ms).await { - Ok(capabilities) => capabilities, - Err(status) => { - trc::event!( - - context = "ehlo", - event = "rejected", - mx = envelope.mx, - status = %status, - ); - - last_status = status; - continue 'next_host; - } - }; - - // Try starting TLS - if tls_strategy.try_start_tls() { - smtp_client.timeout = core - .core - .eval_if(&queue_config.timeout.tls, &envelope, message.id) - .await - .unwrap_or_else(|| Duration::from_secs(3 * 60)); - match try_start_tls( + StartTlsResult::Unavailable { + response, smtp_client, - tls_connector, - envelope.mx, - &capabilities, - ) - .await - { - StartTlsResult::Success { smtp_client } => { - trc::event!( - - context = "tls", - event = "success", - mx = envelope.mx, - protocol = ?smtp_client.tls_connection().protocol_version(), - cipher = ?smtp_client.tls_connection().negotiated_cipher_suite(), + } => { + // Report unavailable STARTTLS + let reason = + response.as_ref().map(|r| r.to_string()).unwrap_or_else( + || "STARTTLS was not advertised by host".to_string(), ); - // Verify DANE - if let Some(dane_policy) = &dane_policy { - if let Err(status) = dane_policy.verify( - message.id, - envelope.mx, - smtp_client.tls_connection().peer_certificates(), - ) { - // Report DANE verification failure - if let Some(tls_report) = &tls_report { - core.schedule_report(TlsEvent { - policy: dane_policy.into(), - domain: domain.domain.to_string(), - failure: FailureDetails::new( - ResultType::ValidationFailure, - ) - .with_receiving_mx_hostname(envelope.mx) - .with_receiving_ip(remote_ip) - .with_failure_reason_code( - "No matching certificates found.", - ) - .into(), - tls_record: tls_report.record.clone(), - interval: tls_report.interval, - }) - .await; - } + trc::event!( + Delivery(DeliveryEvent::StartTlsUnavailable), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Details = reason.clone(), + ); - last_status = status; - continue 'next_host; - } - } + if let Some(tls_report) = &tls_report { + core.schedule_report(TlsEvent { + policy: (&mta_sts_policy, &dane_policy).into(), + domain: domain.domain.to_string(), + failure: FailureDetails::new( + ResultType::StartTlsNotSupported, + ) + .with_receiving_mx_hostname(envelope.mx) + .with_receiving_ip(remote_ip) + .with_failure_reason_code(reason) + .into(), + tls_record: tls_report.record.clone(), + interval: tls_report.interval, + }) + .await; + } - // Report TLS success - if let Some(tls_report) = &tls_report { - core.schedule_report(TlsEvent { - policy: (&mta_sts_policy, &dane_policy).into(), - domain: domain.domain.to_string(), - failure: None, - tls_record: tls_report.record.clone(), - interval: tls_report.interval, - }) - .await; - } - - // Deliver message over TLS + if is_strict_tls { + last_status = + Status::from_starttls_error(envelope.mx, response); + continue 'next_host; + } else { + // TLS is not required, proceed in plain-text message .deliver( smtp_client, @@ -861,161 +996,53 @@ impl DeliveryAttempt { ) .await } - StartTlsResult::Unavailable { - response, - smtp_client, - } => { - // Report unavailable STARTTLS - let reason = response - .as_ref() - .map(|r| r.to_string()) - .unwrap_or_else(|| { - "STARTTLS was not advertised by host".to_string() - }); - - trc::event!( - context = "tls", - event = "unavailable", - mx = envelope.mx, - reason = reason, - ); - - if let Some(tls_report) = &tls_report { - core.schedule_report(TlsEvent { - policy: (&mta_sts_policy, &dane_policy).into(), - domain: domain.domain.to_string(), - failure: FailureDetails::new( - ResultType::StartTlsNotSupported, - ) - .with_receiving_mx_hostname(envelope.mx) - .with_receiving_ip(remote_ip) - .with_failure_reason_code(reason) - .into(), - tls_record: tls_report.record.clone(), - interval: tls_report.interval, - }) - .await; - } - - if is_strict_tls { - last_status = - Status::from_starttls_error(envelope.mx, response); - continue 'next_host; - } else { - // TLS is not required, proceed in plain-text - message - .deliver( - smtp_client, - recipients - .iter_mut() - .filter(|r| r.domain_idx == domain_idx), - params, - ) - .await - } - } - StartTlsResult::Error { error } => { - trc::event!( - - context = "tls", - event = "failed", - mx = envelope.mx, - error = %error, - ); - - // Report TLS failure - if let (Some(tls_report), mail_send::Error::Tls(error)) = - (&tls_report, &error) - { - core.schedule_report(TlsEvent { - policy: (&mta_sts_policy, &dane_policy).into(), - domain: domain.domain.to_string(), - failure: FailureDetails::new( - ResultType::CertificateNotTrusted, - ) - .with_receiving_mx_hostname(envelope.mx) - .with_receiving_ip(remote_ip) - .with_failure_reason_code(error.to_string()) - .into(), - tls_record: tls_report.record.clone(), - interval: tls_report.interval, - }) - .await; - } - - last_status = if is_strict_tls { - Status::from_tls_error(envelope.mx, error) - } else { - Status::from_tls_error(envelope.mx, error) - .into_temporary() - }; - continue 'next_host; - } } - } else { - // TLS has been disabled - trc::event!( - context = "tls", - event = "disabled", - mx = envelope.mx, - reason = "TLS is disabled for this host.", - ); + StartTlsResult::Error { error } => { + trc::event!( + Delivery(DeliveryEvent::StartTlsError), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Reason = error.to_string(), + ); - message - .deliver( - smtp_client, - recipients - .iter_mut() - .filter(|r| r.domain_idx == domain_idx), - params, - ) - .await + // Report TLS failure + if let (Some(tls_report), mail_send::Error::Tls(error)) = + (&tls_report, &error) + { + core.schedule_report(TlsEvent { + policy: (&mta_sts_policy, &dane_policy).into(), + domain: domain.domain.to_string(), + failure: FailureDetails::new( + ResultType::CertificateNotTrusted, + ) + .with_receiving_mx_hostname(envelope.mx) + .with_receiving_ip(remote_ip) + .with_failure_reason_code(error.to_string()) + .into(), + tls_record: tls_report.record.clone(), + interval: tls_report.interval, + }) + .await; + } + + last_status = if is_strict_tls { + Status::from_tls_error(envelope.mx, error) + } else { + Status::from_tls_error(envelope.mx, error).into_temporary() + }; + continue 'next_host; + } } } else { - // Start TLS - smtp_client.timeout = core - .core - .eval_if(&queue_config.timeout.tls, &envelope, message.id) - .await - .unwrap_or_else(|| Duration::from_secs(3 * 60)); - let mut smtp_client = - match smtp_client.into_tls(tls_connector, envelope.mx).await { - Ok(smtp_client) => smtp_client, - Err(error) => { - trc::event!( + // TLS has been disabled + trc::event!( + Delivery(DeliveryEvent::StartTlsDisabled), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + ); - context = "tls", - event = "failed", - mx = envelope.mx, - error = %error, - ); - - last_status = Status::from_tls_error(envelope.mx, error); - continue 'next_host; - } - }; - - // Read greeting - smtp_client.timeout = core - .core - .eval_if(&queue_config.timeout.greeting, &envelope, message.id) - .await - .unwrap_or_else(|| Duration::from_secs(5 * 60)); - if let Err(status) = read_greeting(&mut smtp_client, envelope.mx).await - { - trc::event!( - - context = "greeting", - event = "invalid", - mx = envelope.mx, - status = %status, - ); - - last_status = status; - continue 'next_host; - } - - // Deliver message message .deliver( smtp_client, @@ -1023,81 +1050,129 @@ impl DeliveryAttempt { params, ) .await - }; - - // Update status for the current domain and continue with the next one - let schedule = core + } + } else { + // Start TLS + smtp_client.timeout = core .core - .eval_if::, _>(&queue_config.retry, &envelope, message.id) + .eval_if(&queue_config.timeout.tls, &envelope, message.id) .await - .unwrap_or_else(|| vec![Duration::from_secs(60)]); - message.domains[domain_idx].set_status(delivery_result, &schedule); - continue 'next_domain; - } + .unwrap_or_else(|| Duration::from_secs(3 * 60)); + let mut smtp_client = + match smtp_client.into_tls(tls_connector, envelope.mx).await { + Ok(smtp_client) => smtp_client, + Err(error) => { + trc::event!( + Delivery(DeliveryEvent::ImplicitTlsError), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Reason = format!("{error:?}"), + ); + + last_status = Status::from_tls_error(envelope.mx, error); + continue 'next_host; + } + }; + + // Read greeting + smtp_client.timeout = core + .core + .eval_if(&queue_config.timeout.greeting, &envelope, message.id) + .await + .unwrap_or_else(|| Duration::from_secs(5 * 60)); + if let Err(status) = read_greeting(&mut smtp_client, envelope.mx).await { + trc::event!( + Delivery(DeliveryEvent::GreetingFailed), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Details = status.to_string(), + ); + + last_status = status; + continue 'next_host; + } + + // Deliver message + message + .deliver( + smtp_client, + recipients.iter_mut().filter(|r| r.domain_idx == domain_idx), + params, + ) + .await + }; + + // Update status for the current domain and continue with the next one + let schedule = core + .core + .eval_if::, _>(&queue_config.retry, &envelope, message.id) + .await + .unwrap_or_else(|| vec![Duration::from_secs(60)]); + message.domains[domain_idx].set_status(delivery_result, &schedule); + continue 'next_domain; } - - // Update status - let schedule = core - .core - .eval_if::, _>(&queue_config.retry, &envelope, message.id) - .await - .unwrap_or_else(|| vec![Duration::from_secs(60)]); - message.domains[domain_idx].set_status(last_status, &schedule); } - message.recipients = recipients; - // Send Delivery Status Notifications - core.send_dsn(&mut message).await; + // Update status + let schedule = core + .core + .eval_if::, _>(&queue_config.retry, &envelope, message.id) + .await + .unwrap_or_else(|| vec![Duration::from_secs(60)]); + message.domains[domain_idx].set_status(last_status, &schedule); + } + message.recipients = recipients; - // Notify queue manager - let span = span; - let result = if !on_hold.is_empty() { - // Save changes to disk - let next_due = message.next_event_after(now()); - message.save_changes(&core, None, None).await; + // Send Delivery Status Notifications + core.send_dsn(&mut message).await; - trc::event!( - context = "queue", - event = "requeue", - reason = "concurrency-limited", - "Too many outbound concurrent connections, message moved to on-hold queue." - ); + // Notify queue manager + let result = if !on_hold.is_empty() { + // Save changes to disk + let next_due = message.next_event_after(now()); + message.save_changes(&core, None, None).await; - Event::OnHold(OnHold { - next_due, - limiters: on_hold, - message: self.event, - }) - } else if let Some(due) = message.next_event() { - // Save changes to disk - message - .save_changes(&core, self.event.due.into(), due.into()) - .await; + trc::event!( + Delivery(DeliveryEvent::TooManyConcurrent), + SpanId = message_id, + ); - trc::event!( - context = "queue", - event = "requeue", - reason = "delivery-incomplete", - "Delivery was not possible, message re-queued for delivery." - ); + Event::OnHold(OnHold { + next_due, + limiters: on_hold, + message: self.event, + }) + } else if let Some(due) = message.next_event() { + // Save changes to disk + message + .save_changes(&core, self.event.due.into(), due.into()) + .await; - Event::Reload - } else { - // Delete message from queue - message.remove(&core, self.event.due).await; + trc::event!( + Queue(trc::QueueEvent::Rescheduled), + SpanId = message_id, + Due = trc::Value::Timestamp(due) + ); - trc::event!( - context = "queue", - event = "completed", - "Delivery completed." - ); + Event::Reload + } else { + // Delete message from queue + message.remove(&core, self.event.due).await; - Event::Reload - }; - if core.inner.queue_tx.send(result).await.is_err() { - trc::event!("Channel closed while trying to notify queue manager."); - } - }); + trc::event!(Delivery(DeliveryEvent::Completed), SpanId = message_id,); + + Event::Reload + }; + if core.inner.queue_tx.send(result).await.is_err() { + trc::event!( + Server(ServerEvent::ThreadError), + Reason = "Channel closed.", + CausedBy = trc::location!(), + SpanId = message_id + ); + } } } @@ -1111,10 +1186,10 @@ impl Message { match &domain.status { Status::TemporaryFailure(err) if domain.expires <= now => { trc::event!( - - event = "delivery-expired", - domain = domain.domain, - reason = %err, + Delivery(DeliveryEvent::Failed), + SpanId = self.id, + Domain = domain.domain.clone(), + Reason = err.to_string(), ); for rcpt in &mut self.recipients { @@ -1129,9 +1204,10 @@ impl Message { } Status::Scheduled if domain.expires <= now => { trc::event!( - event = "delivery-expired", - domain = domain.domain, - reason = "Queue rate limit exceeded.", + Delivery(DeliveryEvent::Failed), + SpanId = self.id, + Domain = domain.domain.clone(), + Reason = "Queue rate limit exceeded.", ); for rcpt in &mut self.recipients { diff --git a/crates/smtp/src/outbound/session.rs b/crates/smtp/src/outbound/session.rs index a8c53b90..3e36a028 100644 --- a/crates/smtp/src/outbound/session.rs +++ b/crates/smtp/src/outbound/session.rs @@ -18,6 +18,7 @@ use tokio::{ net::TcpStream, }; use tokio_rustls::{client::TlsStream, TlsConnector}; +use trc::DeliveryEvent; use crate::{ core::SMTP, @@ -38,6 +39,7 @@ pub struct SessionParams<'x> { pub timeout_mail: Duration, pub timeout_rcpt: Duration, pub timeout_data: Duration, + pub session_id: u64, } impl Message { @@ -52,11 +54,10 @@ impl Message { Ok(capabilities) => capabilities, Err(status) => { trc::event!( - - context = "ehlo", - event = "rejected", - mx = ¶ms.hostname, - reason = %status, + Delivery(DeliveryEvent::EhloRejected), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + Reason = status.to_string(), ); quit(smtp_client).await; return status; @@ -67,12 +68,12 @@ impl Message { if let Some(credentials) = params.credentials { if let Err(err) = smtp_client.authenticate(credentials, &capabilities).await { trc::event!( - - context = "auth", - event = "failed", - mx = ¶ms.hostname, - reason = %err, + Delivery(DeliveryEvent::AuthFailed), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + Reason = err.to_string(), ); + quit(smtp_client).await; return Status::from_smtp_error(params.hostname, "AUTH ...", err); } @@ -104,12 +105,12 @@ impl Message { .and_then(|r| r.assert_positive_completion()) { trc::event!( - - context = "sender", - event = "rejected", - mx = ¶ms.hostname, - reason = %err, + Delivery(DeliveryEvent::MailFromRejected), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + Reason = err.to_string(), ); + quit(smtp_client).await; return Status::from_smtp_error(params.hostname, &cmd, err); } @@ -143,12 +144,11 @@ impl Message { } severity => { trc::event!( - - context = "rcpt", - event = "rejected", - rcpt = rcpt.address, - mx = ¶ms.hostname, - reason = %response, + Delivery(DeliveryEvent::RcptToRejected), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + To = rcpt.address.to_string(), + Reason = response.to_string(), ); let response = HostResponse { @@ -169,12 +169,11 @@ impl Message { }, Err(err) => { trc::event!( - - context = "rcpt", - event = "failed", - mx = ¶ms.hostname, - rcpt = rcpt.address, - reason = %err, + Delivery(DeliveryEvent::RcptToFailed), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + To = rcpt.address.to_string(), + Reason = err.to_string(), ); // Something went wrong, abort. @@ -194,11 +193,10 @@ impl Message { if let Err(status) = send_message(&mut smtp_client, self, &bdat_cmd, ¶ms).await { trc::event!( - - context = "message", - event = "rejected", - mx = ¶ms.hostname, - reason = %status, + Delivery(DeliveryEvent::MessageRejected), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + Reason = status.to_string(), ); quit(smtp_client).await; @@ -213,12 +211,11 @@ impl Message { if response.code() == 250 { for (rcpt, status) in accepted_rcpts { trc::event!( - - context = "rcpt", - event = "delivered", - rcpt = rcpt.address, - mx = ¶ms.hostname, - response = %status, + Delivery(DeliveryEvent::Delivered), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + To = rcpt.address.to_string(), + Details = status.to_string(), ); rcpt.status = status; @@ -227,11 +224,10 @@ impl Message { } } else { trc::event!( - - context = "message", - event = "rejected", - mx = ¶ms.hostname, - reason = %response, + Delivery(DeliveryEvent::MessageRejected), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + Reason = response.to_string(), ); quit(smtp_client).await; @@ -244,11 +240,10 @@ impl Message { } Err(status) => { trc::event!( - - context = "message", - event = "failed", - mx = ¶ms.hostname, - reason = %status, + Delivery(DeliveryEvent::MailFromRejected), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + Reason = status.to_string(), ); quit(smtp_client).await; @@ -270,12 +265,11 @@ impl Message { rcpt.status = match response.severity() { Severity::PositiveCompletion => { trc::event!( - - context = "rcpt", - event = "delivered", - rcpt = rcpt.address, - mx = ¶ms.hostname, - response = %response, + Delivery(DeliveryEvent::Delivered), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + To = rcpt.address.to_string(), + Details = response.to_string(), ); total_completed += 1; @@ -286,12 +280,11 @@ impl Message { } severity => { trc::event!( - - context = "rcpt", - event = "rejected", - rcpt = rcpt.address, - mx = ¶ms.hostname, - reason = %response, + Delivery(DeliveryEvent::RcptToRejected), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + To = rcpt.address.to_string(), + Reason = response.to_string(), ); let response = HostResponse { @@ -316,11 +309,10 @@ impl Message { } Err(status) => { trc::event!( - - context = "message", - event = "rejected", - mx = ¶ms.hostname, - reason = %status, + Delivery(DeliveryEvent::MessageRejected), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + Reason = status.to_string(), ); quit(smtp_client).await; @@ -544,23 +536,21 @@ pub async fn send_message( }), Ok(None) => { trc::event!( - context = "queue", - event = "error", - "BlobHash {:?} does not exist.", - message.blob_hash, + Queue(trc::QueueEvent::BlobNotFound), + SpanId = message.id, + BlobId = message.blob_hash.to_hex(), + CausedBy = trc::location!() ); Err(Status::TemporaryFailure(Error::Io( "Queue system error.".to_string(), ))) } Err(err) => { - trc::event!( - context = "queue", - event = "error", - "Failed to fetch blobId {:?}: {}", - message.blob_hash, - err - ); + trc::error!(err + .span_id(message.id) + .details("Failed to fetch blobId") + .caused_by(trc::location!())); + Err(Status::TemporaryFailure(Error::Io( "Queue system error.".to_string(), ))) diff --git a/crates/smtp/src/queue/dsn.rs b/crates/smtp/src/queue/dsn.rs index ba01104d..00e9a4d6 100644 --- a/crates/smtp/src/queue/dsn.rs +++ b/crates/smtp/src/queue/dsn.rs @@ -49,7 +49,9 @@ impl SMTP { .await; // Queue DSN - dsn_message.queue(signature.as_deref(), &dsn, self).await; + dsn_message + .queue(signature.as_deref(), &dsn, message.id, self) + .await; } } else { // Handle double bounce @@ -416,21 +418,20 @@ impl Message { } Ok(None) => { trc::event!( - context = "queue", - event = "error", - "Failed to open blob {:?}: not found", - self.blob_hash + Queue(trc::QueueEvent::BlobNotFound), + SpanId = self.id, + BlobId = self.blob_hash.to_hex(), + CausedBy = trc::location!() ); + String::new() } Err(err) => { - trc::event!( - context = "queue", - event = "error", - "Failed to open blob {:?}: {}", - self.blob_hash, - err - ); + trc::error!(err + .span_id(self.id) + .details("Failed to fetch blobId") + .caused_by(trc::location!())); + String::new() } }; @@ -496,12 +497,9 @@ impl Message { if !is_double_bounce.is_empty() { trc::event!( - - context = "queue", - event = "double-bounce", - id = self.id, - failures = ?is_double_bounce, - "Failed delivery of message with null return path.", + Delivery(trc::DeliveryEvent::DoubleBounce), + SpanId = self.id, + To = is_double_bounce ); } } diff --git a/crates/smtp/src/queue/spool.rs b/crates/smtp/src/queue/spool.rs index 0eeb4090..59c34234 100644 --- a/crates/smtp/src/queue/spool.rs +++ b/crates/smtp/src/queue/spool.rs @@ -10,6 +10,7 @@ use std::time::{Duration, SystemTime}; use store::write::key::DeserializeBigEndian; use store::write::{now, BatchBuilder, Bincode, BlobOp, QueueClass, QueueEvent, ValueClass}; use store::{Deserialize, IterateParams, Serialize, ValueKey, U64_LEN}; +use trc::ServerEvent; use utils::BlobHash; use crate::core::SMTP; @@ -83,12 +84,10 @@ impl SMTP { events.push(event); } else { trc::event!( - context = "queue", - event = "locked", - id = event.queue_id, - due = event.due, - expiry = event.lock_expiry - now, - "Queue event locked by another process." + Queue(trc::QueueEvent::Locked), + SpanId = event.queue_id, + Due = trc::Value::Timestamp(event.due), + Expires = trc::Value::Timestamp(event.lock_expiry), ); } Ok(do_continue) @@ -97,12 +96,9 @@ impl SMTP { .await; if let Err(err) = result { - trc::event!( - context = "queue", - event = "error", - "Failed to read from store: {}", - err - ); + trc::error!(err + .details("Failed to read queue.") + .caused_by(trc::location!())); } events @@ -129,16 +125,18 @@ impl SMTP { Ok(_) => Some(event), Err(err) if err.is_assertion_failure() => { trc::event!( - context = "queue", - event = "locked", - id = event.queue_id, - due = event.due, - "Lock busy: Event already locked." + Queue(trc::QueueEvent::LockBusy), + SpanId = event.queue_id, + Due = trc::Value::Timestamp(event.due), + CausedBy = err, ); + None } Err(err) => { - trc::event!(context = "queue", event = "error", "Lock error: {}", err); + trc::error!(err + .details("Failed to lock event.") + .caused_by(trc::location!())); None } } @@ -157,12 +155,10 @@ impl SMTP { Ok(Some(message)) => Some(message.inner), Ok(None) => None, Err(err) => { - trc::event!( - context = "queue", - event = "error", - "Failed to read message from store: {}", - err - ); + trc::error!(err + .details("Failed to read message.") + .caused_by(trc::location!())); + None } } @@ -174,6 +170,7 @@ impl Message { mut self, raw_headers: Option<&[u8]>, raw_message: &[u8], + parent_session_id: u64, core: &SMTP, ) -> bool { // Write blob @@ -203,12 +200,12 @@ impl Message { 0u32.serialize(), ); if let Err(err) = core.core.storage.data.write(batch.build()).await { - trc::event!( - context = "queue", - event = "error", - "Failed to write to data store: {}", - err - ); + trc::error!(err + .details("Failed to write to store.") + .span_id(self.id) + .parent_span_id(parent_session_id) + .caused_by(trc::location!())); + return false; } if let Err(err) = core @@ -218,31 +215,35 @@ impl Message { .put_blob(self.blob_hash.as_slice(), message.as_ref()) .await { - trc::event!( - context = "queue", - event = "error", - "Failed to write to blob store: {}", - err - ); + trc::error!(err + .details("Failed to write blob.") + .span_id(self.id) + .parent_span_id(parent_session_id) + .caused_by(trc::location!())); + return false; } trc::event!( - context = "queue", - event = "scheduled", - id = self.id, - from = if !self.return_path.is_empty() { - self.return_path.as_str() + Queue(trc::QueueEvent::Scheduled), + SpanId = self.id, + ParentSpanId = parent_session_id, + From = if !self.return_path.is_empty() { + trc::Value::String(self.return_path.to_string()) } else { - "<>" + trc::Value::Static("<>") }, - nrcpts = self.recipients.len(), - size = self.size, - "Message queued for delivery." + To = self + .recipients + .iter() + .map(|r| trc::Value::String(r.address_lcase.clone())) + .collect::>(), + Size = self.size, ); // Write message to queue let mut batch = BatchBuilder::new(); + let span_id = self.id; // Reserve quotas for quota_key in &self.quota_keys { @@ -289,21 +290,23 @@ impl Message { ); if let Err(err) = core.core.storage.data.write(batch.build()).await { - trc::event!( - context = "queue", - event = "error", - "Failed to write to store: {}", - err - ); + trc::error!(err + .details("Failed to write to store.") + .span_id(span_id) + .parent_span_id(parent_session_id) + .caused_by(trc::location!())); + return false; } // Queue the message if core.inner.queue_tx.send(Event::Reload).await.is_err() { trc::event!( - context = "queue", - event = "error", - "Queue channel closed: Message queued but won't be sent until next restart." + Server(ServerEvent::ThreadError), + Reason = "Channel closed.", + CausedBy = trc::location!(), + SpanId = span_id, + ParentSpanId = parent_session_id, ); } @@ -397,18 +400,17 @@ impl Message { ); } + let span_id = self.id; batch.set( ValueClass::Queue(QueueClass::Message(self.id)), Bincode::new(self).serialize(), ); if let Err(err) = core.core.storage.data.write(batch.build()).await { - trc::event!( - context = "queue", - event = "error", - "Failed to update queued message: {}", - err - ); + trc::error!(err + .details("Failed to save changes.") + .span_id(span_id) + .caused_by(trc::location!())); false } else { true @@ -445,12 +447,10 @@ impl Message { .clear(ValueClass::Queue(QueueClass::Message(self.id))); if let Err(err) = core.core.storage.data.write(batch.build()).await { - trc::event!( - context = "queue", - event = "error", - "Failed to update queued message: {}", - err - ); + trc::error!(err + .details("Failed to write to update queue.") + .span_id(self.id) + .caused_by(trc::location!())); false } else { true diff --git a/crates/smtp/src/queue/throttle.rs b/crates/smtp/src/queue/throttle.rs index abcd8491..90ec3fb7 100644 --- a/crates/smtp/src/queue/throttle.rs +++ b/crates/smtp/src/queue/throttle.rs @@ -48,12 +48,13 @@ impl SMTP { .await { trc::event!( - context = "throttle", - event = "rate-limit-exceeded", - max_requests = rate.requests, - max_interval = rate.period.as_secs(), - "Queue rate limit exceeded." + Queue(trc::QueueEvent::RateLimitExceeded), + SpanId = session_id, + Id = throttle.id.clone(), + Limit = rate.requests, + Interval = rate.period.as_secs() ); + return Err(Error::Rate { retry_at: now() + next_refill, }); @@ -68,11 +69,12 @@ impl SMTP { in_flight.push(inflight); } else { trc::event!( - context = "throttle", - event = "too-many-requests", - max_concurrent = limiter.max_concurrent, - "Queue concurrency limit exceeded." + Queue(trc::QueueEvent::ConcurrencyLimitExceeded), + SpanId = session_id, + Id = throttle.id.clone(), + Limit = limiter.max_concurrent, ); + return Err(Error::Concurrency { limiter: limiter.clone(), }); diff --git a/crates/smtp/src/reporting/analysis.rs b/crates/smtp/src/reporting/analysis.rs index a88aa482..45b98354 100644 --- a/crates/smtp/src/reporting/analysis.rs +++ b/crates/smtp/src/reporting/analysis.rs @@ -9,7 +9,6 @@ use std::{ collections::hash_map::Entry, io::{Cursor, Read}, sync::Arc, - time::SystemTime, }; use ahash::AHashMap; @@ -25,6 +24,7 @@ use store::{ write::{now, BatchBuilder, Bincode, ReportClass, ValueClass}, Serialize, }; +use trc::IncomingReportEvent; use crate::core::SMTP; @@ -55,13 +55,17 @@ pub struct IncomingReport { } impl SMTP { - pub fn analyze_report(&self, message: Arc>) { + pub fn analyze_report(&self, message: Arc>, session_id: u64) { let core = self.clone(); tokio::spawn(async move { let message = if let Some(message) = MessageParser::default().parse(message.as_ref()) { message } else { - trc::event!(context = "report", "Failed to parse message."); + trc::event!( + IncomingReport(IncomingReportEvent::MessageParseFailed), + SpanId = session_id + ); + return; }; let from = message @@ -163,11 +167,13 @@ impl SMTP { let mut buf = Vec::new(); if let Err(err) = file.read_to_end(&mut buf) { trc::event!( - context = "report", - from = from, - "Failed to decompress report: {}", - err + IncomingReport(IncomingReportEvent::DecompressError), + SpanId = session_id, + From = from.to_string(), + Reason = err.to_string(), + CausedBy = trc::location!() ); + continue; } Cow::Owned(buf) @@ -177,11 +183,13 @@ impl SMTP { Ok(archive) => archive, Err(err) => { trc::event!( - context = "report", - from = from, - "Failed to decompress report: {}", - err + IncomingReport(IncomingReportEvent::DecompressError), + SpanId = session_id, + From = from.to_string(), + Reason = err.to_string(), + CausedBy = trc::location!() ); + continue; } }; @@ -192,20 +200,22 @@ impl SMTP { buf = Vec::with_capacity(file.compressed_size() as usize); if let Err(err) = file.read_to_end(&mut buf) { trc::event!( - context = "report", - from = from, - "Failed to decompress report: {}", - err + IncomingReport(IncomingReportEvent::DecompressError), + SpanId = session_id, + From = from.to_string(), + Reason = err.to_string(), + CausedBy = trc::location!() ); } break; } Err(err) => { trc::event!( - context = "report", - from = from, - "Failed to decompress report: {}", - err + IncomingReport(IncomingReportEvent::DecompressError), + SpanId = session_id, + From = from.to_string(), + Reason = err.to_string(), + CausedBy = trc::location!() ); } } @@ -237,11 +247,13 @@ impl SMTP { } Err(err) => { trc::event!( - context = "report", - from = from, - "Failed to parse DMARC report: {}", - err + IncomingReport(IncomingReportEvent::DmarcParseFailed), + SpanId = session_id, + From = from.to_string(), + Reason = err, + CausedBy = trc::location!() ); + continue; } }, @@ -268,11 +280,13 @@ impl SMTP { } Err(err) => { trc::event!( - context = "report", - from = from, - "Failed to parse TLS report: {:?}", - err + IncomingReport(IncomingReportEvent::TlsRpcParseFailed), + SpanId = session_id, + From = from.to_string(), + Reason = format!("{err:?}"), + CausedBy = trc::location!() ); + continue; } }, @@ -298,10 +312,12 @@ impl SMTP { } None => { trc::event!( - context = "report", - from = from, - "Failed to parse Auth Failure report" + IncomingReport(IncomingReportEvent::ArfParseFailed), + SpanId = session_id, + From = from.to_string(), + CausedBy = trc::location!() ); + continue; } }, @@ -353,12 +369,10 @@ impl SMTP { } let batch = batch.build(); if let Err(err) = core.core.storage.data.write(batch).await { - trc::event!( - context = "report", - event = "error", - "Failed to write incoming report: {}", - err - ); + trc::error!(err + .span_id(session_id) + .caused_by(trc::location!()) + .details("Failed to write report")); } } return; @@ -426,50 +440,30 @@ impl LogReport for Report { } } - let range_from = DateTime::from_timestamp(self.date_range_begin() as i64).to_rfc3339(); - let range_to = DateTime::from_timestamp(self.date_range_end() as i64).to_rfc3339(); - - if (dmarc_reject + dmarc_quarantine + dkim_fail + spf_fail) > 0 { - trc::event!( - context = "dmarc", - event = "analyze", - range_from = range_from, - range_to = range_to, - domain = self.domain(), - report_email = self.email(), - report_id = self.report_id(), - dmarc_pass = dmarc_pass, - dmarc_quarantine = dmarc_quarantine, - dmarc_reject = dmarc_reject, - dmarc_none = dmarc_none, - dkim_pass = dkim_pass, - dkim_fail = dkim_fail, - dkim_none = dkim_none, - spf_pass = spf_pass, - spf_fail = spf_fail, - spf_none = spf_none, - ); - } else { - trc::event!( - context = "dmarc", - event = "analyze", - range_from = range_from, - range_to = range_to, - domain = self.domain(), - report_email = self.email(), - report_id = self.report_id(), - dmarc_pass = dmarc_pass, - dmarc_quarantine = dmarc_quarantine, - dmarc_reject = dmarc_reject, - dmarc_none = dmarc_none, - dkim_pass = dkim_pass, - dkim_fail = dkim_fail, - dkim_none = dkim_none, - spf_pass = spf_pass, - spf_fail = spf_fail, - spf_none = spf_none, - ); - } + trc::event!( + IncomingReport( + if (dmarc_reject + dmarc_quarantine + dkim_fail + spf_fail) > 0 { + IncomingReportEvent::DmarcReportWithWarnings + } else { + IncomingReportEvent::DmarcReport + } + ), + RangeFrom = trc::Value::Timestamp(self.date_range_begin()), + RangeTo = trc::Value::Timestamp(self.date_range_end()), + Domain = self.domain().to_string(), + From = self.email().to_string(), + Id = self.report_id().to_string(), + DmarcPass = dmarc_pass, + DmarcQuarantine = dmarc_quarantine, + DmarcReject = dmarc_reject, + DmarcNone = dmarc_none, + DkimPass = dkim_pass, + DkimFail = dkim_fail, + DkimNone = dkim_none, + SpfPass = spf_pass, + SpfFail = spf_fail, + SpfNone = spf_none, + ); } fn webhook_payload(&self) -> WebhookPayload { @@ -564,35 +558,23 @@ impl LogReport for TlsReport { } } - if policy.summary.total_failure > 0 { - trc::event!( - context = "tlsrpt", - event = "analyze", - range_from = self.date_range.start_datetime.to_rfc3339(), - range_to = self.date_range.end_datetime.to_rfc3339(), - domain = policy.policy.policy_domain, - report_contact = self.contact_info.as_deref().unwrap_or("unknown"), - report_id = self.report_id, - policy_type = ?policy.policy.policy_type, - total_success = policy.summary.total_success, - total_failures = policy.summary.total_failure, - details = ?details, - ); - } else { - trc::event!( - context = "tlsrpt", - event = "analyze", - range_from = self.date_range.start_datetime.to_rfc3339(), - range_to = self.date_range.end_datetime.to_rfc3339(), - domain = policy.policy.policy_domain, - report_contact = self.contact_info.as_deref().unwrap_or("unknown"), - report_id = self.report_id, - policy_type = ?policy.policy.policy_type, - total_success = policy.summary.total_success, - total_failures = policy.summary.total_failure, - details = ?details, - ); - } + trc::event!( + IncomingReport(if policy.summary.total_failure > 0 { + IncomingReportEvent::TlsReportWithWarnings + } else { + IncomingReportEvent::TlsReport + }), + RangeFrom = + trc::Value::Timestamp(self.date_range.start_datetime.to_timestamp() as u64), + RangeTo = trc::Value::Timestamp(self.date_range.end_datetime.to_timestamp() as u64), + Domain = policy.policy.policy_domain.clone(), + From = self.contact_info.as_deref().unwrap_or_default().to_string(), + Id = self.report_id.clone(), + PolicyType = format!("{:?}", policy.policy.policy_type), + TotalSuccesses = policy.summary.total_success, + TotalFailures = policy.summary.total_failure, + Details = format!("{details:?}"), + ); } } @@ -632,28 +614,54 @@ impl LogReport for TlsReport { impl LogReport for Feedback<'_> { fn log(&self) { + let rt = match self.feedback_type() { + mail_auth::report::FeedbackType::Abuse => IncomingReportEvent::AbuseReport, + mail_auth::report::FeedbackType::AuthFailure => IncomingReportEvent::AuthFailureReport, + mail_auth::report::FeedbackType::Fraud => IncomingReportEvent::FraudReport, + mail_auth::report::FeedbackType::NotSpam => IncomingReportEvent::NotSpamReport, + mail_auth::report::FeedbackType::Other => IncomingReportEvent::OtherReport, + mail_auth::report::FeedbackType::Virus => IncomingReportEvent::VirusReport, + }; + + /* + + user_agent = self.user_agent().unwrap_or_default(), + auth_failure = ?self.auth_failure(), + dkim_domain = self.dkim_domain().unwrap_or_default(), + dkim_identity = self.dkim_identity().unwrap_or_default(), + dkim_selector = self.dkim_selector().unwrap_or_default(), + identity_alignment = ?self.identity_alignment(), + + */ + trc::event!( - context = "arf", - event = "analyze", - feedback_type = ?self.feedback_type(), - arrival_date = DateTime::from_timestamp(self.arrival_date().unwrap_or_else(|| { - SystemTime::now() - .duration_since(SystemTime::UNIX_EPOCH) - .map_or(0, |d| d.as_secs()) as i64 - })).to_rfc3339(), - authentication_results = ?self.authentication_results(), - incidents = self.incidents(), - reported_domain = ?self.reported_domain(), - reported_uri = ?self.reported_uri(), - reporting_mta = self.reporting_mta().unwrap_or_default(), - source_ip = ?self.source_ip(), - user_agent = self.user_agent().unwrap_or_default(), - auth_failure = ?self.auth_failure(), - delivery_result = ?self.delivery_result(), - dkim_domain = self.dkim_domain().unwrap_or_default(), - dkim_identity = self.dkim_identity().unwrap_or_default(), - dkim_selector = self.dkim_selector().unwrap_or_default(), - identity_alignment = ?self.identity_alignment(), + IncomingReport(rt), + Date = trc::Value::Timestamp( + self.arrival_date() + .map(|d| d as u64) + .unwrap_or_else(|| { now() }) + ), + Domain = self + .reported_domain() + .iter() + .map(|d| trc::Value::String(d.to_string())) + .collect::>(), + Hostname = self + .reporting_mta() + .map(|d| trc::Value::String(d.to_string())), + Url = self + .reported_uri() + .iter() + .map(|d| trc::Value::String(d.to_string())) + .collect::>(), + RemoteIp = self.source_ip(), + Count = self.incidents(), + Result = format!("{:?}", self.delivery_result()), + Details = self + .authentication_results() + .iter() + .map(|d| trc::Value::String(d.to_string())) + .collect::>(), ); } diff --git a/crates/smtp/src/reporting/dkim.rs b/crates/smtp/src/reporting/dkim.rs index cdefa1f0..ec2bea42 100644 --- a/crates/smtp/src/reporting/dkim.rs +++ b/crates/smtp/src/reporting/dkim.rs @@ -8,6 +8,7 @@ use common::listener::SessionStream; use mail_auth::{ common::verify::VerifySignature, AuthenticatedMessage, AuthenticationResults, DkimOutput, }; +use trc::OutgoingReportEvent; use utils::config::Rate; use crate::core::Session; @@ -31,11 +32,13 @@ impl Session { // Throttle recipient if !self.throttle_rcpt(rcpt, rate, "dkim").await { trc::event!( - context = "report", - report = "dkim", - event = "throttle", - rcpt = rcpt, + OutgoingReport(OutgoingReportEvent::DkimRateLimited), + SpanId = self.data.session_id, + To = rcpt.to_string(), + Limit = rate.requests, + Interval = rate.period ); + return; } @@ -79,16 +82,21 @@ impl Session { .ok(); trc::event!( - context = "report", - report = "dkim", - event = "queue", - rcpt = rcpt, - "Queueing DKIM authentication failure report." + OutgoingReport(OutgoingReportEvent::DkimReport), + SpanId = self.data.session_id, + To = rcpt.to_string(), ); // Send report self.core - .send_report(&from_addr, [rcpt].into_iter(), report, &config.sign, true) + .send_report( + &from_addr, + [rcpt].into_iter(), + report, + &config.sign, + true, + self.data.session_id, + ) .await; } } diff --git a/crates/smtp/src/reporting/dmarc.rs b/crates/smtp/src/reporting/dmarc.rs index e2fb02ac..d2ca4952 100644 --- a/crates/smtp/src/reporting/dmarc.rs +++ b/crates/smtp/src/reporting/dmarc.rs @@ -7,10 +7,7 @@ use std::collections::hash_map::Entry; use ahash::AHashMap; -use common::{ - config::smtp::{report::AggregateFrequency, session}, - listener::SessionStream, -}; +use common::{config::smtp::report::AggregateFrequency, listener::SessionStream}; use mail_auth::{ common::verify::VerifySignature, dmarc::{self, URI}, @@ -22,6 +19,7 @@ use store::{ write::{now, BatchBuilder, Bincode, QueueClass, ReportEvent, ValueClass}, Deserialize, IterateParams, Serialize, ValueKey, }; +use trc::OutgoingReportEvent; use utils::config::Rate; use crate::{ @@ -84,12 +82,13 @@ impl Session { } else { if !dmarc_record.ruf().is_empty() { trc::event!( - - context = "report", - report = "dkim", - event = "unauthorized-ruf", - ruf = ?dmarc_record.ruf(), - "Unauthorized external reporting addresses" + OutgoingReport(OutgoingReportEvent::UnauthorizedReportingAddress), + SpanId = self.data.session_id, + Url = dmarc_record + .ruf() + .iter() + .map(|u| trc::Value::String(u.uri().to_string())) + .collect::>(), ); } vec![] @@ -97,13 +96,15 @@ impl Session { } None => { trc::event!( - - context = "report", - report = "dmarc", - event = "dns-failure", - ruf = ?dmarc_record.ruf(), - "Failed to validate external report addresses", + OutgoingReport(OutgoingReportEvent::ReportingAddressValidationError), + SpanId = self.data.session_id, + Url = dmarc_record + .ruf() + .iter() + .map(|u| trc::Value::String(u.uri().to_string())) + .collect::>(), ); + vec![] } }; @@ -216,25 +217,31 @@ impl Session { .ok(); trc::event!( - - context = "report", - report = "dmarc", - event = "queue", - rcpt = ?rcpts, - "Queueing DMARC authentication failure report." + OutgoingReport(OutgoingReportEvent::DmarcReport), + SpanId = self.data.session_id, + To = rcpts + .iter() + .map(|a| trc::Value::String(a.to_string())) + .collect::>(), ); // Send report self.core - .send_report(&from_addr, rcpts.into_iter(), report, &config.sign, true) + .send_report( + &from_addr, + rcpts.into_iter(), + report, + &config.sign, + true, + self.data.session_id, + ) .await; } else { trc::event!( - - context = "report", - report = "dmarc", - event = "throttle", - ruf = ?dmarc_record.ruf(), + OutgoingReport(OutgoingReportEvent::DmarcRateLimited), + SpanId = self.data.session_id, + Limit = failure_rate.requests, + Interval = failure_rate.period ); } } @@ -292,16 +299,17 @@ impl Session { impl SMTP { pub async fn send_dmarc_aggregate_report(&self, event: ReportEvent) { - let span = trc::event_span!( - "dmarc-report", - domain = event.domain, - range_from = event.seq_id, - range_to = event.due, + let session_id = event.seq_id; + + trc::event!( + OutgoingReport(OutgoingReportEvent::DmarcAggregateReport), + SpanId = session_id, + Domain = event.domain.clone(), + RangeFrom = trc::Value::Timestamp(event.seq_id), + RangeTo = trc::Value::Timestamp(event.due), ); // Generate report - let todo = "generate session id"; - let session_id = 0; let mut serialized_size = serde_json::Serializer::new(SerializedSize::new( self.core .eval_if( @@ -325,13 +333,17 @@ impl SMTP { Ok(Some(report)) => report, Ok(None) => { trc::event!( - event = "missing", - "Failed to read DMARC report: Report not found" + OutgoingReport(OutgoingReportEvent::NotFound), + SpanId = session_id, + CausedBy = trc::location!() ); + return; } Err(err) => { - trc::event!(event = "error", "Failed to read DMARC records: {}", err); + trc::error!(err + .span_id(session_id) + .details("Failed to read DMARC report")); return; } }; @@ -353,24 +365,28 @@ impl SMTP { .collect::>() } else { trc::event!( - - event = "failed", - reason = "unauthorized-rua", - rua = ?rua, - "Unauthorized external reporting addresses" + OutgoingReport(OutgoingReportEvent::UnauthorizedReportingAddress), + SpanId = session_id, + Url = rua + .iter() + .map(|u| trc::Value::String(u.uri().to_string())) + .collect::>(), ); + self.delete_dmarc_report(event).await; return; } } None => { trc::event!( - - event = "failed", - reason = "dns-failure", - rua = ?rua, - "Failed to validate external report addresses", + OutgoingReport(OutgoingReportEvent::ReportingAddressValidationError), + SpanId = session_id, + Url = rua + .iter() + .map(|u| trc::Value::String(u.uri().to_string())) + .collect::>(), ); + self.delete_dmarc_report(event).await; return; } @@ -415,8 +431,15 @@ impl SMTP { ); // Send report - self.send_report(&from_addr, rua.iter(), message, &config.sign, false) - .await; + self.send_report( + &from_addr, + rua.iter(), + message, + &config.sign, + false, + event.seq_id, + ) + .await; self.delete_dmarc_report(event).await; } @@ -565,24 +588,18 @@ impl SMTP { ) .await { - trc::event!( - context = "report", - event = "error", - "Failed to remove repors: {}", - err - ); + trc::error!(err + .caused_by(trc::location!()) + .details("Failed to delete DMARC report")); return; } let mut batch = BatchBuilder::new(); batch.clear(ValueClass::Queue(QueueClass::DmarcReportHeader(event))); if let Err(err) = self.core.storage.data.write(batch.build()).await { - trc::event!( - context = "report", - event = "error", - "Failed to remove repors: {}", - err - ); + trc::error!(err + .caused_by(trc::location!()) + .details("Failed to delete DMARC report")); } } @@ -640,12 +657,9 @@ impl SMTP { ); if let Err(err) = self.core.storage.data.write(builder.build()).await { - trc::event!( - context = "report", - event = "error", - "Failed to write DMARC report event: {}", - err - ); + trc::error!(err + .caused_by(trc::location!()) + .details("Failed to write DMARC report")); } } } diff --git a/crates/smtp/src/reporting/mod.rs b/crates/smtp/src/reporting/mod.rs index c8419521..4cfc1629 100644 --- a/crates/smtp/src/reporting/mod.rs +++ b/crates/smtp/src/reporting/mod.rs @@ -120,6 +120,7 @@ impl SMTP { report: Vec, sign_config: &IfBlock, deliver_now: bool, + parent_session_id: u64, ) { // Build message let from_addr_lcase = from_addr.to_lowercase(); @@ -186,12 +187,18 @@ impl SMTP { } // Queue message - message.queue(signature.as_deref(), &report, self).await; + message + .queue(signature.as_deref(), &report, parent_session_id, self) + .await; } pub async fn schedule_report(&self, report: impl Into) { if self.inner.report_tx.send(report.into()).await.is_err() { - trc::event!(context = "report", "Channel send failed."); + trc::event!( + Server(trc::ServerEvent::ThreadError), + CausedBy = trc::location!(), + Details = "Failed to send event to ReportScheduler" + ); } } @@ -209,16 +216,16 @@ impl SMTP { if !signers.is_empty() { let mut headers = Vec::with_capacity(64); for signer in signers.iter() { - if let Some(signer) = self.core.get_dkim_signer(signer) { + if let Some(signer) = self.core.get_dkim_signer(signer, message.id) { match signer.sign(bytes) { Ok(signature) => { signature.write_header(&mut headers); } Err(err) => { - trc::event!( - context = "dkim", - event = "sign-failed", - reason = %err); + trc::error!(trc::Event::from(err) + .span_id(message.id) + .details("Failed to sign message") + .caused_by(trc::location!())); } } } diff --git a/crates/smtp/src/reporting/scheduler.rs b/crates/smtp/src/reporting/scheduler.rs index 3903db80..83a1c354 100644 --- a/crates/smtp/src/reporting/scheduler.rs +++ b/crates/smtp/src/reporting/scheduler.rs @@ -11,7 +11,7 @@ use mail_auth::dmarc::Dmarc; use std::time::{Duration, Instant, SystemTime}; use store::{ write::{now, BatchBuilder, QueueClass, ReportEvent, ValueClass}, - Deserialize, IterateParams, Serialize, ValueKey, + Deserialize, IterateParams, Key, Serialize, ValueKey, }; use tokio::sync::mpsc; @@ -142,12 +142,9 @@ async fn next_report_event(core: &Core) -> Vec { .await; if let Err(err) = result { - trc::event!( - context = "queue", - event = "error", - "Failed to read from store: {}", - err - ); + trc::error!(err + .caused_by(trc::location!()) + .details("Failed to read from store")); } events @@ -175,51 +172,44 @@ impl SMTP { Ok(_) => true, Err(err) if err.is_assertion_failure() => { trc::event!( - context = "queue", - event = "locked", - key = ?lock, - "Lock busy: Event already locked." + OutgoingReport(trc::OutgoingReportEvent::LockBusy), + Expires = trc::Value::Timestamp(expiry), + CausedBy = err, + Key = ValueKey::from(ValueClass::Queue(lock)).serialize(0) ); false } Err(err) => { - trc::event!( - context = "queue", - event = "error", - "Lock busy: {}", - err - ); + trc::error!(err + .caused_by(trc::location!()) + .details("Failed to lock report")); + false } } } else { trc::event!( - context = "queue", - event = "locked", - key = ?lock, - expiry = expiry - now, - "Lock busy: Report already locked." + OutgoingReport(trc::OutgoingReportEvent::Locked), + Expires = trc::Value::Timestamp(expiry), + Key = ValueKey::from(ValueClass::Queue(lock)).serialize(0) ); + false } } Ok(None) => { trc::event!( - context = "queue", - event = "locked", - key = ?lock, - "Lock busy: Report lock deleted." + OutgoingReport(trc::OutgoingReportEvent::LockDeleted), + Key = ValueKey::from(ValueClass::Queue(lock)).serialize(0) ); + false } Err(err) => { - trc::event!( - context = "queue", - event = "error", - key = ?lock, - "Lock error: {}", - err - ); + trc::error!(err + .caused_by(trc::location!()) + .details("Failed to lock report")); + false } } diff --git a/crates/smtp/src/reporting/spf.rs b/crates/smtp/src/reporting/spf.rs index 98fa029d..10e77afc 100644 --- a/crates/smtp/src/reporting/spf.rs +++ b/crates/smtp/src/reporting/spf.rs @@ -6,6 +6,7 @@ use common::listener::SessionStream; use mail_auth::{report::AuthFailureType, AuthenticationResults, SpfOutput}; +use trc::OutgoingReportEvent; use utils::config::Rate; use crate::core::Session; @@ -21,11 +22,13 @@ impl Session { // Throttle recipient if !self.throttle_rcpt(rcpt, rate, "spf").await { trc::event!( - context = "report", - report = "spf", - event = "throttle", - rcpt = rcpt, + OutgoingReport(OutgoingReportEvent::SpfRateLimited), + SpanId = self.data.session_id, + To = rcpt.to_string(), + Limit = rate.requests, + Interval = rate.period ); + return; } @@ -79,16 +82,21 @@ impl Session { .ok(); trc::event!( - context = "report", - report = "spf", - event = "queue", - rcpt = rcpt, - "Queueing SPF authentication failure report." + OutgoingReport(OutgoingReportEvent::SpfReport), + SpanId = self.data.session_id, + To = rcpt.to_string(), ); // Send report self.core - .send_report(&from_addr, [rcpt].into_iter(), report, &config.sign, true) + .send_report( + &from_addr, + [rcpt].into_iter(), + report, + &config.sign, + true, + self.data.session_id, + ) .await; } } diff --git a/crates/smtp/src/reporting/tls.rs b/crates/smtp/src/reporting/tls.rs index cc1c26a1..25ffd316 100644 --- a/crates/smtp/src/reporting/tls.rs +++ b/crates/smtp/src/reporting/tls.rs @@ -11,7 +11,6 @@ use common::{ config::smtp::{ report::AggregateFrequency, resolver::{Mode, MxPattern}, - session, }, USER_AGENT, }; @@ -30,6 +29,7 @@ use store::{ write::{now, BatchBuilder, Bincode, QueueClass, ReportEvent, ValueClass}, Deserialize, IterateParams, Serialize, ValueKey, }; +use trc::OutgoingReportEvent; use crate::{core::SMTP, queue::RecipientDomain}; @@ -58,15 +58,15 @@ impl SMTP { .map(|e| (e.domain.as_str(), e.seq_id, e.due)) .unwrap(); - let span = trc::event_span!( - "tls-report", - domain = domain_name, - range_from = event_from, - range_to = event_to, - ); + let session_id = event_from; - let todo = "generate session id"; - let session_id = 0; + trc::event!( + OutgoingReport(OutgoingReportEvent::TlsAggregate), + SpanId = session_id, + Domain = domain_name.to_string(), + RangeFrom = trc::Value::Timestamp(event_from), + RangeTo = trc::Value::Timestamp(event_to), + ); // Generate report let mut rua = Vec::new(); @@ -92,12 +92,19 @@ impl SMTP { Ok(Some(report)) => report, Ok(None) => { // This should not happen - trc::event!(event = "empty-report", "No policies found in report"); + trc::event!( + OutgoingReport(OutgoingReportEvent::NotFound), + SpanId = session_id, + CausedBy = trc::location!() + ); self.delete_tls_report(events).await; return; } Err(err) => { - trc::event!(event = "error", "Failed to read TLS report: {}", err); + trc::error!(err + .span_id(session_id) + .caused_by(trc::location!()) + .details("Failed to read TLS report")); return; } }; @@ -109,7 +116,13 @@ impl SMTP { { Ok(report) => report, Err(err) => { - trc::event!(event = "error", "Failed to compress report: {}", err); + trc::event!( + OutgoingReport(OutgoingReportEvent::SubmissionError), + SpanId = session_id, + Reason = err.to_string(), + Details = "Failed to compress report" + ); + self.delete_tls_report(events).await; return; } @@ -141,26 +154,32 @@ impl SMTP { { Ok(response) => { if response.status().is_success() { - trc::event!(context = "http", event = "success", url = uri,); + trc::event!( + OutgoingReport(OutgoingReportEvent::HttpSubmission), + SpanId = session_id, + Url = uri.to_string(), + Status = response.status().as_u16(), + ); + self.delete_tls_report(events).await; return; } else { trc::event!( - - context = "http", - event = "invalid-response", - url = uri, - status = %response.status() + OutgoingReport(OutgoingReportEvent::SubmissionError), + SpanId = session_id, + Url = uri.to_string(), + Status = response.status().as_u16(), + Details = "Invalid HTTP response" ); } } Err(err) => { trc::event!( - - context = "http", - event = "error", - url = uri, - reason = %err + OutgoingReport(OutgoingReportEvent::SubmissionError), + SpanId = session_id, + Url = uri.to_string(), + Reason = err.to_string(), + Details = "HTTP submission error" ); } } @@ -210,12 +229,19 @@ impl SMTP { ); // Send report - self.send_report(&from_addr, rcpts.iter(), message, &config.sign, false) - .await; + self.send_report( + &from_addr, + rcpts.iter(), + message, + &config.sign, + false, + session_id, + ) + .await; } else { trc::event!( - event = "delivery-failed", - "No valid recipients found to deliver report to." + OutgoingReport(OutgoingReportEvent::NoRecipientsFound), + SpanId = session_id, ); } self.delete_tls_report(events).await; @@ -478,12 +504,9 @@ impl SMTP { ); if let Err(err) = self.core.storage.data.write(builder.build()).await { - trc::event!( - context = "report", - event = "error", - "Failed to write TLS report event: {}", - err - ); + trc::error!(err + .caused_by(trc::location!()) + .details("Failed to write TLS report")); } } @@ -515,12 +538,10 @@ impl SMTP { ) .await { - trc::event!( - context = "report", - event = "error", - "Failed to remove reports: {}", - err - ); + trc::error!(err + .caused_by(trc::location!()) + .details("Failed to delete TLS reports")); + return; } @@ -534,12 +555,9 @@ impl SMTP { } if let Err(err) = self.core.storage.data.write(batch.build()).await { - trc::event!( - context = "report", - event = "error", - "Failed to remove reports: {}", - err - ); + trc::error!(err + .caused_by(trc::location!()) + .details("Failed to delete TLS reports")); } } } diff --git a/crates/smtp/src/scripts/event_loop.rs b/crates/smtp/src/scripts/event_loop.rs index 4b67e090..c64e5f17 100644 --- a/crates/smtp/src/scripts/event_loop.rs +++ b/crates/smtp/src/scripts/event_loop.rs @@ -58,7 +58,7 @@ impl SMTP { } else { trc::event!( Sieve(SieveEvent::ScriptNotFound), - SessionId = session_id, + SpanId = session_id, Name = name.as_str().to_string(), ); break; @@ -91,7 +91,7 @@ impl SMTP { } else { trc::event!( Sieve(SieveEvent::ListNotFound), - SessionId = session_id, + SpanId = session_id, Name = list, ); } @@ -152,7 +152,7 @@ impl SMTP { Recipient::List(list) => { trc::event!( Sieve(SieveEvent::NotSupported), - SessionId = session_id, + SpanId = session_id, Name = list, Reason = "Sending to lists is not supported.", ); @@ -262,7 +262,7 @@ impl SMTP { } Err(err) => { trc::error!(trc::Event::from(err) - .session_id(session_id) + .span_id(session_id) .caused_by(trc::location!()) .details("DKIM sign failed")); } @@ -282,11 +282,13 @@ impl SMTP { }; if self.has_quota(&mut message).await { - message.queue(headers.as_deref(), raw_message, self).await; + message + .queue(headers.as_deref(), raw_message, session_id, self) + .await; } else { trc::event!( Sieve(SieveEvent::QuotaExceeded), - SessionId = session_id, + SpanId = session_id, From = message.return_path_lcase, To = message .recipients @@ -313,7 +315,7 @@ impl SMTP { unsupported => { trc::event!( Sieve(SieveEvent::NotSupported), - SessionId = session_id, + SpanId = session_id, Reason = "Unsupported event", Details = format!("{unsupported:?}"), ); @@ -323,7 +325,7 @@ impl SMTP { Err(err) => { trc::event!( Sieve(SieveEvent::RuntimeError), - SessionId = session_id, + SpanId = session_id, Reason = err.to_string(), ); break; @@ -366,7 +368,7 @@ impl SMTP { if keep_id == 0 { trc::event!( Sieve(SieveEvent::ActionAccept), - SessionId = session_id, + SpanId = session_id, Details = modifications .iter() .map(|m| trc::Value::from(format!("{m:?}"))) @@ -377,7 +379,7 @@ impl SMTP { } else if let Some(mut reject_reason) = reject_reason { trc::event!( Sieve(SieveEvent::ActionReject), - SessionId = session_id, + SpanId = session_id, Details = reject_reason.clone(), ); @@ -398,7 +400,7 @@ impl SMTP { if let Some(message) = messages.into_iter().nth(keep_id - 1) { trc::event!( Sieve(SieveEvent::ActionAccept), - SessionId = session_id, + SpanId = session_id, Details = modifications .iter() .map(|m| trc::Value::from(format!("{m:?}"))) @@ -412,7 +414,7 @@ impl SMTP { } else { trc::event!( Sieve(SieveEvent::ActionAcceptReplace), - SessionId = session_id, + SpanId = session_id, Details = modifications .iter() .map(|m| trc::Value::from(format!("{m:?}"))) @@ -422,7 +424,7 @@ impl SMTP { ScriptResult::Accept { modifications } } } else { - trc::event!(Sieve(SieveEvent::ActionDiscard), SessionId = session_id,); + trc::event!(Sieve(SieveEvent::ActionDiscard), SpanId = session_id,); ScriptResult::Discard } diff --git a/crates/trc/src/collector.rs b/crates/trc/src/collector.rs index 2c28e19e..bf6b0edd 100644 --- a/crates/trc/src/collector.rs +++ b/crates/trc/src/collector.rs @@ -39,7 +39,7 @@ impl Collector { // Collect all events let mut do_continue = true; EVENT_RXS.lock().retain_mut(|rx| { - loop { + while do_continue { match rx.try_recv() { Ok(Some(event)) => { if !event.keys.is_empty() { @@ -54,6 +54,7 @@ impl Collector { self.subscribers.extend(subscribers); } else if event.matches(EventType::Server(ServerEvent::Shutdown)) { do_continue = false; + return false; } } } @@ -65,11 +66,21 @@ impl Collector { } } } + + false }); if !self.subscribers.is_empty() { - self.subscribers - .retain_mut(|subscriber| subscriber.send_batch().is_ok()); + if do_continue { + // Send batched events + self.subscribers + .retain_mut(|subscriber| subscriber.send_batch().is_ok()); + } else { + // Send remaining events + for mut subscriber in self.subscribers.drain(..) { + let _ = subscriber.send_batch(); + } + } } do_continue diff --git a/crates/trc/src/conv.rs b/crates/trc/src/conv.rs index 3238b015..f62dc521 100644 --- a/crates/trc/src/conv.rs +++ b/crates/trc/src/conv.rs @@ -32,6 +32,12 @@ impl From for Value { } } +impl From for Value { + fn from(value: i64) -> Self { + Self::Int(value) + } +} + impl From for Value { fn from(value: f64) -> Self { Self::Float(value) @@ -72,7 +78,16 @@ impl From for Value { fn from(value: IpAddr) -> Self { match value { IpAddr::V4(ip) => Value::Ipv4(ip), - IpAddr::V6(ip) => Value::Ipv6(Box::new(ip)), + IpAddr::V6(ip) => Value::Ipv6(ip), + } + } +} + +impl> From> for Value { + fn from(value: Option) -> Self { + match value { + Some(value) => value.into(), + None => Self::None, } } } @@ -85,7 +100,7 @@ impl From for Value { impl From for Value { fn from(value: Event) -> Self { - Self::Event(Box::new(value)) + Self::Event(value) } } diff --git a/crates/trc/src/imple.rs b/crates/trc/src/imple.rs index e7e04f01..06ae542e 100644 --- a/crates/trc/src/imple.rs +++ b/crates/trc/src/imple.rs @@ -104,8 +104,12 @@ impl Event { } #[inline(always)] - pub fn session_id(self, session_id: u64) -> Self { - self.ctx(Key::SessionId, session_id) + 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)] @@ -742,7 +746,6 @@ impl Eq for Error {} impl EventType { pub fn level(&self) -> Level { - let todo = "smtp levels and other todos"; match self { EventType::Store(event) => match event { StoreEvent::SqlQuery | StoreEvent::LdapQuery => Level::Trace, @@ -764,9 +767,44 @@ impl EventType { Pop3Event::RawInput | Pop3Event::RawOutput => Level::Trace, }, EventType::Smtp(event) => match event { - SmtpEvent::Error => Level::Debug, - SmtpEvent::RemoteIdNotFound => Level::Warn, - _ => todo!(), + SmtpEvent::PipeSuccess | SmtpEvent::PipeError | SmtpEvent::Error => Level::Debug, + SmtpEvent::MissingLocalHostname | SmtpEvent::RemoteIdNotFound => Level::Warn, + SmtpEvent::ConcurrencyLimitExceeded + | SmtpEvent::TransferLimitExceeded + | SmtpEvent::RateLimitExceeded + | SmtpEvent::TimeLimitExceeded + | SmtpEvent::MissingAuthDirectory + | SmtpEvent::MessageParseFailed + | SmtpEvent::MessageTooLarge + | SmtpEvent::LoopDetected + | SmtpEvent::DkimPass + | SmtpEvent::DkimFail + | SmtpEvent::ArcPass + | SmtpEvent::ArcFail + | SmtpEvent::SpfEhloPass + | SmtpEvent::SpfEhloFail + | SmtpEvent::SpfFromPass + | SmtpEvent::SpfFromFail + | SmtpEvent::DmarcPass + | SmtpEvent::DmarcFail + | SmtpEvent::IprevPass + | SmtpEvent::IprevFail + | SmtpEvent::QuotaExceeded + | SmtpEvent::TooManyMessages + | SmtpEvent::Ehlo + | SmtpEvent::InvalidEhlo + | SmtpEvent::MailFrom + | SmtpEvent::MailboxDoesNotExist + | SmtpEvent::RelayNotAllowed + | SmtpEvent::RcptTo + | SmtpEvent::TooManyInvalidRcpt + | SmtpEvent::Vrfy + | SmtpEvent::VrfyNotFound + | SmtpEvent::VrfyDisabled + | SmtpEvent::Expn + | SmtpEvent::ExpnNotFound + | SmtpEvent::ExpnDisabled => Level::Info, + SmtpEvent::RawInput | SmtpEvent::RawOutput => Level::Trace, }, EventType::Network(event) => match event { NetworkEvent::ReadError @@ -774,7 +812,9 @@ impl EventType { | NetworkEvent::FlushError | NetworkEvent::Closed => Level::Trace, NetworkEvent::Timeout | NetworkEvent::AcceptError => Level::Debug, - NetworkEvent::ListenStart + NetworkEvent::ConnectionStart + | NetworkEvent::ConnectionStop + | NetworkEvent::ListenStart | NetworkEvent::ListenStop | NetworkEvent::DropBlocked => Level::Info, NetworkEvent::ListenError @@ -887,10 +927,6 @@ impl EventType { | AcmeEvent::DnsRecordNotPropagated | AcmeEvent::DnsRecordLookupFailed => Level::Debug, }, - EventType::Session(event) => match event { - SessionEvent::Start => Level::Info, - SessionEvent::Stop => Level::Info, - }, EventType::Tls(event) => match event { TlsEvent::Handshake => Level::Info, TlsEvent::HandshakeError => Level::Debug, @@ -991,7 +1027,101 @@ impl EventType { | MtaHookEvent::ActionQuarantine => Level::Info, MtaHookEvent::Error => Level::Warn, }, - EventType::Dane(_) => todo!(), + EventType::Dane(event) => match event { + DaneEvent::AuthenticationSuccess + | DaneEvent::AuthenticationFailure + | DaneEvent::NoCertificatesFound + | DaneEvent::CertificateParseError + | DaneEvent::TlsaRecordMatch + | DaneEvent::TlsaRecordFetch + | DaneEvent::TlsaRecordFetchError + | DaneEvent::TlsaRecordNotFound + | DaneEvent::TlsaRecordNotDnssecSigned + | DaneEvent::TlsaRecordInvalid => Level::Info, + }, + EventType::Delivery(event) => match event { + DeliveryEvent::AttemptStart + | DeliveryEvent::AttemptEnd + | DeliveryEvent::Completed + | DeliveryEvent::Failed + | DeliveryEvent::AttemptCount + | DeliveryEvent::MxLookupFailed + | DeliveryEvent::IpLookupFailed + | DeliveryEvent::NullMX + | DeliveryEvent::Connect + | DeliveryEvent::ConnectError + | DeliveryEvent::GreetingFailed + | DeliveryEvent::EhloRejected + | DeliveryEvent::AuthFailed + | DeliveryEvent::MailFromRejected + | DeliveryEvent::Delivered + | DeliveryEvent::RcptToRejected + | DeliveryEvent::RcptToFailed + | DeliveryEvent::MessageRejected + | DeliveryEvent::StartTls + | DeliveryEvent::StartTlsUnavailable + | DeliveryEvent::StartTlsError + | DeliveryEvent::StartTlsDisabled + | DeliveryEvent::ImplicitTlsError + | DeliveryEvent::TooManyConcurrent + | DeliveryEvent::DoubleBounce => Level::Info, + DeliveryEvent::MissingOutboundHostname => Level::Warn, + }, + EventType::Queue(event) => match event { + QueueEvent::RateLimitExceeded + | QueueEvent::ConcurrencyLimitExceeded + | QueueEvent::Scheduled + | QueueEvent::Rescheduled => Level::Info, + QueueEvent::LockBusy | QueueEvent::Locked | QueueEvent::BlobNotFound => { + Level::Debug + } + }, + EventType::TlsRpt(event) => match event { + TlsRptEvent::RecordFetch | TlsRptEvent::RecordFetchError => Level::Info, + }, + EventType::MtaSts(event) => match event { + MtaStsEvent::PolicyFetch + | MtaStsEvent::PolicyNotFound + | MtaStsEvent::PolicyFetchError + | MtaStsEvent::InvalidPolicy + | MtaStsEvent::NotAuthorized => Level::Info, + }, + EventType::IncomingReport(event) => match event { + IncomingReportEvent::DmarcReportWithWarnings + | IncomingReportEvent::TlsReportWithWarnings => Level::Warn, + IncomingReportEvent::DmarcReport + | IncomingReportEvent::TlsReport + | IncomingReportEvent::AbuseReport + | IncomingReportEvent::AuthFailureReport + | IncomingReportEvent::FraudReport + | IncomingReportEvent::NotSpamReport + | IncomingReportEvent::VirusReport + | IncomingReportEvent::OtherReport + | IncomingReportEvent::MessageParseFailed + | IncomingReportEvent::DmarcParseFailed + | IncomingReportEvent::TlsRpcParseFailed + | IncomingReportEvent::ArfParseFailed + | IncomingReportEvent::DecompressError => Level::Info, + }, + EventType::OutgoingReport(event) => match event { + OutgoingReportEvent::LockBusy + | OutgoingReportEvent::LockDeleted + | OutgoingReportEvent::Locked + | OutgoingReportEvent::NotFound => Level::Info, + OutgoingReportEvent::SpfReport + | OutgoingReportEvent::SpfRateLimited + | OutgoingReportEvent::DkimReport + | OutgoingReportEvent::DkimRateLimited + | OutgoingReportEvent::DmarcReport + | OutgoingReportEvent::DmarcRateLimited + | OutgoingReportEvent::DmarcAggregateReport + | OutgoingReportEvent::TlsAggregate + | OutgoingReportEvent::HttpSubmission + | OutgoingReportEvent::UnauthorizedReportingAddress + | OutgoingReportEvent::ReportingAddressValidationError + | OutgoingReportEvent::SubmissionError + | OutgoingReportEvent::NoRecipientsFound => Level::Info, + }, } } } diff --git a/crates/trc/src/lib.rs b/crates/trc/src/lib.rs index 75f4127d..e058b6e6 100644 --- a/crates/trc/src/lib.rs +++ b/crates/trc/src/lib.rs @@ -25,12 +25,12 @@ pub struct Event { #[derive(Copy, Clone, Debug, Hash, Eq, PartialEq)] #[repr(usize)] pub enum Level { - Disable, - Trace, - Debug, - Info, - Warn, - Error, + Disable = 0, + Trace = 1, + Debug = 2, + Info = 3, + Warn = 4, + Error = 5, } #[derive(Debug, Default, Clone)] @@ -45,9 +45,9 @@ pub enum Value { Bytes(Vec), Bool(bool), Ipv4(Ipv4Addr), - Ipv6(Box), + Ipv6(Ipv6Addr), Protocol(Protocol), - Event(Box), + Event(Event), Array(Vec), Level(Level), #[default] @@ -81,7 +81,8 @@ pub enum Key { DocumentId, Collection, AccountId, - SessionId, + SpanId, + ParentSpanId, MessageId, MailboxId, ChangeId, @@ -121,6 +122,22 @@ pub enum Key { Domain, Policy, Elapsed, + RangeFrom, + RangeTo, + DmarcPass, + DmarcQuarantine, + DmarcReject, + DmarcNone, + DkimPass, + DkimFail, + DkimNone, + SpfPass, + SpfFail, + SpfNone, + PolicyType, + TotalSuccesses, + TotalFailures, + Date, } #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] @@ -149,7 +166,6 @@ pub enum EventType { Dane(DaneEvent), Spf(SpfEvent), MailAuth(MailAuthEvent), - Session(SessionEvent), Tls(TlsEvent), Sieve(SieveEvent), Spam(SpamEvent), @@ -159,6 +175,12 @@ pub enum EventType { FtsIndex(FtsIndexEvent), Milter(MilterEvent), MtaHook(MtaHookEvent), + Delivery(DeliveryEvent), + Queue(QueueEvent), + TlsRpt(TlsRptEvent), + MtaSts(MtaStsEvent), + IncomingReport(IncomingReportEvent), + OutgoingReport(OutgoingReportEvent), } #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] @@ -276,6 +298,102 @@ pub enum SmtpEvent { ExpnDisabled, } +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] +pub enum DeliveryEvent { + AttemptStart, + AttemptEnd, + Completed, + Failed, + AttemptCount, + MxLookupFailed, + IpLookupFailed, + NullMX, + Connect, + ConnectError, + MissingOutboundHostname, + GreetingFailed, + EhloRejected, + AuthFailed, + MailFromRejected, + Delivered, + RcptToRejected, + RcptToFailed, + MessageRejected, + StartTls, + StartTlsUnavailable, + StartTlsError, + StartTlsDisabled, + ImplicitTlsError, + TooManyConcurrent, + DoubleBounce, +} + +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] +pub enum QueueEvent { + Scheduled, + Rescheduled, + LockBusy, + Locked, + BlobNotFound, + RateLimitExceeded, + ConcurrencyLimitExceeded, +} + +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] +pub enum IncomingReportEvent { + DmarcReport, + DmarcReportWithWarnings, + TlsReport, + TlsReportWithWarnings, + AbuseReport, + AuthFailureReport, + FraudReport, + NotSpamReport, + VirusReport, + OtherReport, + MessageParseFailed, + DmarcParseFailed, + TlsRpcParseFailed, + ArfParseFailed, + DecompressError, +} + +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] +pub enum OutgoingReportEvent { + SpfReport, + SpfRateLimited, + DkimReport, + DkimRateLimited, + DmarcReport, + DmarcRateLimited, + DmarcAggregateReport, + TlsAggregate, + HttpSubmission, + UnauthorizedReportingAddress, + ReportingAddressValidationError, + NotFound, + SubmissionError, + NoRecipientsFound, + LockBusy, + LockDeleted, + Locked, +} + +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] +pub enum MtaStsEvent { + PolicyFetch, + PolicyNotFound, + PolicyFetchError, + InvalidPolicy, + NotAuthorized, +} + +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] +pub enum TlsRptEvent { + RecordFetch, + RecordFetchError, +} + #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] pub enum DaneEvent { AuthenticationSuccess, @@ -283,6 +401,11 @@ pub enum DaneEvent { NoCertificatesFound, CertificateParseError, TlsaRecordMatch, + TlsaRecordFetch, + TlsaRecordFetchError, + TlsaRecordNotFound, + TlsaRecordNotDnssecSigned, + TlsaRecordInvalid, } #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] @@ -315,12 +438,6 @@ pub enum MtaHookEvent { Error, } -#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] -pub enum SessionEvent { - Start, - Stop, -} - #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] pub enum PushSubscriptionEvent { Success, @@ -368,6 +485,8 @@ pub enum TlsEvent { #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] pub enum NetworkEvent { + ConnectionStart, + ConnectionStop, ListenStart, ListenStop, ListenError, diff --git a/crates/trc/src/subscriber.rs b/crates/trc/src/subscriber.rs index 29f0ed7f..2348aca7 100644 --- a/crates/trc/src/subscriber.rs +++ b/crates/trc/src/subscriber.rs @@ -16,8 +16,14 @@ const MAX_BATCH_SIZE: usize = 32768; pub(crate) static SUBSCRIBER_UPDATE: Mutex> = Mutex::new(Vec::new()); +pub(crate) enum SubscriberUpdate { + Add(Subscriber), + RemoveAll, +} + #[derive(Debug)] pub(crate) struct Subscriber { + pub id: String, pub level: Level, pub disabled: AHashSet, pub tx: mpsc::Sender>>, @@ -26,6 +32,7 @@ pub(crate) struct Subscriber { } pub struct SubscriberBuilder { + pub id: String, pub level: Level, pub disabled: AHashSet, pub lossy: bool, @@ -34,7 +41,9 @@ pub struct SubscriberBuilder { impl Subscriber { #[inline(always)] pub fn push_event(&mut self, trace: Arc) { - if trace.level() >= self.level && !self.disabled.contains(&trace.inner) { + let level = trace.level(); + + if self.level >= trace.level() && !self.disabled.contains(&trace.inner) { self.batch.push(trace); } } @@ -62,8 +71,13 @@ impl Subscriber { } impl SubscriberBuilder { - pub fn new() -> Self { - Default::default() + pub fn new(id: String) -> Self { + Self { + id, + level: Level::Info, + disabled: AHashSet::new(), + lossy: true, + } } pub fn with_level(mut self, level: Level) -> Self { @@ -85,6 +99,7 @@ impl SubscriberBuilder { let (tx, rx) = mpsc::channel(8192); SUBSCRIBER_UPDATE.lock().push(Subscriber { + id: self.id, level: self.level, disabled: self.disabled, tx, @@ -98,13 +113,3 @@ impl SubscriberBuilder { rx } } - -impl Default for SubscriberBuilder { - fn default() -> Self { - Self { - level: Level::Info, - disabled: AHashSet::new(), - lossy: true, - } - } -} diff --git a/crates/utils/src/lib.rs b/crates/utils/src/lib.rs index 7b7f6cf9..1a042447 100644 --- a/crates/utils/src/lib.rs +++ b/crates/utils/src/lib.rs @@ -38,6 +38,14 @@ impl BlobHash { pub fn as_slice(&self) -> &[u8] { self.0.as_ref() } + + pub fn to_hex(&self) -> String { + let mut hex = String::with_capacity(BLOB_HASH_LEN * 2); + for byte in self.0.iter() { + hex.push_str(&format!("{:02x}", byte)); + } + hex + } } impl From<&[u8]> for BlobHash { diff --git a/crates/utils/src/snowflake.rs b/crates/utils/src/snowflake.rs index 70475a7c..25e1e007 100644 --- a/crates/utils/src/snowflake.rs +++ b/crates/utils/src/snowflake.rs @@ -9,6 +9,7 @@ use std::{ time::{Duration, SystemTime}, }; +#[derive(Debug)] pub struct SnowflakeIdGenerator { epoch: SystemTime, node_id: u64, @@ -21,6 +22,16 @@ const NODE_ID_LEN: u64 = 9; const SEQUENCE_MASK: u64 = (1 << SEQUENCE_LEN) - 1; const NODE_ID_MASK: u64 = (1 << NODE_ID_LEN) - 1; +/* + +ID characteristics: + +- 43 bits for milliseconds since January 1st, 2022: 2^43 / (1000 * 60 * 60 * 24 * 365) = 278.92 years +- 9 bits for a node id: 2^9 = 512 nodes +- 12 bits for a sequence number: 2^12 = 4096 ids per millisecond + +*/ + impl SnowflakeIdGenerator { pub fn new() -> Self { Self::with_node_id(rand::random::()) diff --git a/tests/src/directory/ldap.rs b/tests/src/directory/ldap.rs index a7fefaa8..2435cf88 100644 --- a/tests/src/directory/ldap.rs +++ b/tests/src/directory/ldap.rs @@ -134,37 +134,37 @@ async fn ldap_directory() { // Ids by email compare_sorted( - core.email_to_ids(&handle, "jane@example.org") + core.email_to_ids(&handle, "jane@example.org", 0) .await .unwrap(), map_account_ids(base_store, vec!["jane"]).await, ); compare_sorted( - core.email_to_ids(&handle, "jane+alias@example.org") + core.email_to_ids(&handle, "jane+alias@example.org", 0) .await .unwrap(), map_account_ids(base_store, vec!["jane"]).await, ); compare_sorted( - core.email_to_ids(&handle, "info@example.org") + core.email_to_ids(&handle, "info@example.org", 0) .await .unwrap(), map_account_ids(base_store, vec!["bill", "jane", "john"]).await, ); compare_sorted( - core.email_to_ids(&handle, "info+alias@example.org") + core.email_to_ids(&handle, "info+alias@example.org", 0) .await .unwrap(), map_account_ids(base_store, vec!["bill", "jane", "john"]).await, ); compare_sorted( - core.email_to_ids(&handle, "unknown@example.org") + core.email_to_ids(&handle, "unknown@example.org", 0) .await .unwrap(), Vec::::new(), ); assert_eq!( - core.email_to_ids(&handle, "anything@catchall.org") + core.email_to_ids(&handle, "anything@catchall.org", 0) .await .unwrap(), map_account_ids(base_store, vec!["robert"]).await @@ -175,41 +175,47 @@ async fn ldap_directory() { assert!(!handle.is_local_domain("other.org").await.unwrap()); // RCPT TO - assert!(core.rcpt(&handle, "jane@example.org").await.unwrap()); - assert!(core.rcpt(&handle, "info@example.org").await.unwrap()); - assert!(core.rcpt(&handle, "jane+alias@example.org").await.unwrap()); - assert!(core.rcpt(&handle, "info+alias@example.org").await.unwrap()); + assert!(core.rcpt(&handle, "jane@example.org", 0).await.unwrap()); + assert!(core.rcpt(&handle, "info@example.org", 0).await.unwrap()); assert!(core - .rcpt(&handle, "random_user@catchall.org") + .rcpt(&handle, "jane+alias@example.org", 0) .await .unwrap()); - assert!(!core.rcpt(&handle, "invalid@example.org").await.unwrap()); + assert!(core + .rcpt(&handle, "info+alias@example.org", 0) + .await + .unwrap()); + assert!(core + .rcpt(&handle, "random_user@catchall.org", 0) + .await + .unwrap()); + assert!(!core.rcpt(&handle, "invalid@example.org", 0).await.unwrap()); // VRFY compare_sorted( - core.vrfy(&handle, "jane").await.unwrap(), + core.vrfy(&handle, "jane", 0).await.unwrap(), vec!["jane@example.org".to_string()], ); compare_sorted( - core.vrfy(&handle, "john").await.unwrap(), + core.vrfy(&handle, "john", 0).await.unwrap(), vec!["john@example.org".to_string()], ); compare_sorted( - core.vrfy(&handle, "jane+alias@example").await.unwrap(), + core.vrfy(&handle, "jane+alias@example", 0).await.unwrap(), vec!["jane@example.org".to_string()], ); compare_sorted( - core.vrfy(&handle, "info").await.unwrap(), + core.vrfy(&handle, "info", 0).await.unwrap(), Vec::::new(), ); compare_sorted( - core.vrfy(&handle, "invalid").await.unwrap(), + core.vrfy(&handle, "invalid", 0).await.unwrap(), Vec::::new(), ); // EXPN compare_sorted( - core.expn(&handle, "info@example.org").await.unwrap(), + core.expn(&handle, "info@example.org", 0).await.unwrap(), vec![ "bill@example.org".to_string(), "jane@example.org".to_string(), @@ -217,7 +223,7 @@ async fn ldap_directory() { ], ); compare_sorted( - core.expn(&handle, "john@example.org").await.unwrap(), + core.expn(&handle, "john@example.org", 0).await.unwrap(), Vec::::new(), ); } diff --git a/tests/src/directory/mod.rs b/tests/src/directory/mod.rs index d6efc3e2..d97f8730 100644 --- a/tests/src/directory/mod.rs +++ b/tests/src/directory/mod.rs @@ -621,13 +621,13 @@ async fn address_mappings() { let subaddressing = AddressMapping::parse(&mut config, (test, "subaddressing")); assert_eq!( - subaddressing.to_subaddress(&core, ADDR).await, + subaddressing.to_subaddress(&core, ADDR, 0).await, config.value_require((test, "expected-sub")).unwrap(), "failed subaddress for {test:?}" ); assert_eq!( - subaddressing.to_subaddress(&core, ADDR_NO_MATCH).await, + subaddressing.to_subaddress(&core, ADDR_NO_MATCH, 0).await, config .value_require((test, "expected-sub-nomatch")) .unwrap(), @@ -635,7 +635,7 @@ async fn address_mappings() { ); assert_eq!( - catch_all.to_catch_all(&core, ADDR).await, + catch_all.to_catch_all(&core, ADDR, 0).await, config .property_require::>((test, "expected-catch")) .unwrap() diff --git a/tests/src/directory/smtp.rs b/tests/src/directory/smtp.rs index 92415e4b..3b8b2440 100644 --- a/tests/src/directory/smtp.rs +++ b/tests/src/directory/smtp.rs @@ -78,14 +78,14 @@ async fn lmtp_directory() { for (item, expected) in &tests { let result: LookupResult = match item { - Item::IsAccount(v) => core.rcpt(&handle, v).await.unwrap().into(), + Item::IsAccount(v) => core.rcpt(&handle, v, 0).await.unwrap().into(), Item::Authenticate(v) => handle .query(QueryBy::Credentials(v), true) .await .unwrap() .is_some() .into(), - Item::Verify(v) => match core.vrfy(&handle, v).await { + Item::Verify(v) => match core.vrfy(&handle, v, 0).await { Ok(v) => v.into(), Err(e) => { if e.matches(trc::EventType::Store(trc::StoreEvent::NotSupported)) { @@ -95,7 +95,7 @@ async fn lmtp_directory() { } } }, - Item::Expand(v) => match core.expn(&handle, v).await { + Item::Expand(v) => match core.expn(&handle, v, 0).await { Ok(v) => v.into(), Err(e) => { if e.matches(trc::EventType::Store(trc::StoreEvent::NotSupported)) { @@ -122,14 +122,14 @@ async fn lmtp_directory() { requests.push(( tokio::spawn(async move { let result: LookupResult = match &item { - Item::IsAccount(v) => core.rcpt(&handle, v).await.unwrap().into(), + Item::IsAccount(v) => core.rcpt(&handle, v, 0).await.unwrap().into(), Item::Authenticate(v) => handle .query(QueryBy::Credentials(v), true) .await .unwrap() .is_some() .into(), - Item::Verify(v) => match core.vrfy(&handle, v).await { + Item::Verify(v) => match core.vrfy(&handle, v, 0).await { Ok(v) => v.into(), Err(e) => { if e.matches(trc::EventType::Store(trc::StoreEvent::NotSupported)) { @@ -139,7 +139,7 @@ async fn lmtp_directory() { } } }, - Item::Expand(v) => match core.expn(&handle, v).await { + Item::Expand(v) => match core.expn(&handle, v, 0).await { Ok(v) => v.into(), Err(e) => { if e.matches(trc::EventType::Store(trc::StoreEvent::NotSupported)) { @@ -182,7 +182,7 @@ async fn lmtp_directory() { requests.push(( tokio::spawn(async move { let result: LookupResult = match &item { - Item::IsAccount(v) => core.rcpt(&handle, v).await.unwrap().into(), + Item::IsAccount(v) => core.rcpt(&handle, v, 0).await.unwrap().into(), _ => unreachable!(), }; diff --git a/tests/src/directory/sql.rs b/tests/src/directory/sql.rs index 9bc69dc0..8d2136e2 100644 --- a/tests/src/directory/sql.rs +++ b/tests/src/directory/sql.rs @@ -200,37 +200,37 @@ async fn sql_directory() { // Ids by email assert_eq!( - core.email_to_ids(&handle, "jane@example.org") + core.email_to_ids(&handle, "jane@example.org", 0) .await .unwrap(), map_account_ids(base_store, vec!["jane"]).await ); assert_eq!( - core.email_to_ids(&handle, "info@example.org") + core.email_to_ids(&handle, "info@example.org", 0) .await .unwrap(), map_account_ids(base_store, vec!["bill", "jane", "john"]).await ); assert_eq!( - core.email_to_ids(&handle, "jane+alias@example.org") + core.email_to_ids(&handle, "jane+alias@example.org", 0) .await .unwrap(), map_account_ids(base_store, vec!["jane"]).await ); assert_eq!( - core.email_to_ids(&handle, "info+alias@example.org") + core.email_to_ids(&handle, "info+alias@example.org", 0) .await .unwrap(), map_account_ids(base_store, vec!["bill", "jane", "john"]).await ); assert_eq!( - core.email_to_ids(&handle, "unknown@example.org") + core.email_to_ids(&handle, "unknown@example.org", 0) .await .unwrap(), Vec::::new() ); assert_eq!( - core.email_to_ids(&handle, "anything@catchall.org") + core.email_to_ids(&handle, "anything@catchall.org", 0) .await .unwrap(), map_account_ids(base_store, vec!["robert"]).await @@ -241,41 +241,47 @@ async fn sql_directory() { assert!(!handle.is_local_domain("other.org").await.unwrap()); // RCPT TO - assert!(core.rcpt(&handle, "jane@example.org").await.unwrap()); - assert!(core.rcpt(&handle, "info@example.org").await.unwrap()); - assert!(core.rcpt(&handle, "jane+alias@example.org").await.unwrap()); - assert!(core.rcpt(&handle, "info+alias@example.org").await.unwrap()); + assert!(core.rcpt(&handle, "jane@example.org", 0).await.unwrap()); + assert!(core.rcpt(&handle, "info@example.org", 0).await.unwrap()); assert!(core - .rcpt(&handle, "random_user@catchall.org") + .rcpt(&handle, "jane+alias@example.org", 0) .await .unwrap()); - assert!(!core.rcpt(&handle, "invalid@example.org").await.unwrap()); + assert!(core + .rcpt(&handle, "info+alias@example.org", 0) + .await + .unwrap()); + assert!(core + .rcpt(&handle, "random_user@catchall.org", 0) + .await + .unwrap()); + assert!(!core.rcpt(&handle, "invalid@example.org", 0).await.unwrap()); // VRFY assert_eq!( - core.vrfy(&handle, "jane").await.unwrap(), + core.vrfy(&handle, "jane", 0).await.unwrap(), vec!["jane@example.org".to_string()] ); assert_eq!( - core.vrfy(&handle, "john").await.unwrap(), + core.vrfy(&handle, "john", 0).await.unwrap(), vec!["john@example.org".to_string()] ); assert_eq!( - core.vrfy(&handle, "jane+alias@example").await.unwrap(), + core.vrfy(&handle, "jane+alias@example", 0).await.unwrap(), vec!["jane@example.org".to_string()] ); assert_eq!( - core.vrfy(&handle, "info").await.unwrap(), + core.vrfy(&handle, "info", 0).await.unwrap(), Vec::::new() ); assert_eq!( - core.vrfy(&handle, "invalid").await.unwrap(), + core.vrfy(&handle, "invalid", 0).await.unwrap(), Vec::::new() ); // EXPN assert_eq!( - core.expn(&handle, "info@example.org").await.unwrap(), + core.expn(&handle, "info@example.org", 0).await.unwrap(), vec![ "bill@example.org".to_string(), "jane@example.org".to_string(), @@ -283,7 +289,7 @@ async fn sql_directory() { ] ); assert_eq!( - core.expn(&handle, "john@example.org").await.unwrap(), + core.expn(&handle, "john@example.org", 0).await.unwrap(), Vec::::new() ); } diff --git a/tests/src/imap/mod.rs b/tests/src/imap/mod.rs index ef7a5033..70999457 100644 --- a/tests/src/imap/mod.rs +++ b/tests/src/imap/mod.rs @@ -27,7 +27,10 @@ use std::{ use ::managesieve::core::ManageSieveSessionManager; use common::{ - config::server::{ServerProtocol, Servers}, + config::{ + server::{ServerProtocol, Servers}, + tracers::Tracer, + }, webhooks::manager::spawn_webhook_manager, Core, Ipc, IPC_CHANNEL_BUFFER, }; @@ -45,6 +48,7 @@ use tokio::{ net::TcpStream, sync::{mpsc, watch}, }; +use trc::collector::Collector; use utils::config::Config; use crate::{add_test_certs, directory::DirectoryStore, store::TempDir, AssertConfig}; @@ -414,19 +418,14 @@ async fn init_imap_tests(store_id: &str, delete_if_exists: bool) -> IMAPTest { #[tokio::test] pub async fn imap_tests() { if let Ok(level) = std::env::var("LOG") { - let todo = "implement"; - /*tracing::subscriber::set_global_default( - tracing_subscriber::FmtSubscriber::builder() - .with_env_filter( - tracing_subscriber::EnvFilter::builder() - .parse( - format!("smtp={level},imap={level},jmap={level},store={level},utils={level},common={level},pop3={level},directory={level}"), - ) - .unwrap(), - ) - .finish(), - ) - .unwrap();*/ + let level = level.parse().unwrap(); + Collector::set_level(level); + Tracer::Stdout { + id: "stdout".to_string(), + level, + ansi: true, + } + .spawn(); } // Prepare settings diff --git a/tests/src/jmap/auth_acl.rs b/tests/src/jmap/auth_acl.rs index fa127bde..e5493d06 100644 --- a/tests/src/jmap/auth_acl.rs +++ b/tests/src/jmap/auth_acl.rs @@ -139,7 +139,7 @@ pub async fn test(params: &mut JMAPTest) { ); assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_get( email_ids.get("jane").unwrap().first().unwrap(), [Property::Subject].into(), @@ -148,7 +148,7 @@ pub async fn test(params: &mut JMAPTest) { ); assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .mailbox_get(&inbox_id, None::>) .await, ); @@ -169,7 +169,7 @@ pub async fn test(params: &mut JMAPTest) { ); assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_query(None::, None::>) .await, ); @@ -183,7 +183,7 @@ pub async fn test(params: &mut JMAPTest) { // John should have ReadItems access to Inbox assert_eq!( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_get( email_ids.get("jane").unwrap().first().unwrap(), [Property::Subject].into(), @@ -197,7 +197,7 @@ pub async fn test(params: &mut JMAPTest) { ); assert_eq!( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_query(None::, None::>) .await .unwrap() @@ -218,7 +218,7 @@ pub async fn test(params: &mut JMAPTest) { // John should not have access to emails in Jane's Trash folder assert!(john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_get( email_ids.get("jane").unwrap().last().unwrap(), [Property::Subject].into(), @@ -239,7 +239,7 @@ pub async fn test(params: &mut JMAPTest) { .take_blob_id(); john_client .set_default_account_id(&john_id.to_string()) - .blob_copy(&jane_id.to_string(), &blob_id) + .blob_copy(jane_id.to_string(), &blob_id) .await .unwrap(); let blob_id = jane_client @@ -254,14 +254,14 @@ pub async fn test(params: &mut JMAPTest) { assert_forbidden( john_client .set_default_account_id(&john_id.to_string()) - .blob_copy(&jane_id.to_string(), &blob_id) + .blob_copy(jane_id.to_string(), &blob_id) .await, ); // John only has ReadItems access to Inbox but no Read access assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .mailbox_get(&inbox_id, [mailbox::Property::MyRights].into()) .await, ); @@ -271,7 +271,7 @@ pub async fn test(params: &mut JMAPTest) { .unwrap(); assert_eq!( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .mailbox_get(&inbox_id, [mailbox::Property::MyRights].into()) .await .unwrap() @@ -302,7 +302,7 @@ pub async fn test(params: &mut JMAPTest) { .unwrap() .take_blob_id(); let mut request = john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .build(); let email_id = request .import_email() @@ -318,7 +318,7 @@ pub async fn test(params: &mut JMAPTest) { ); assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_copy( &john_id.to_string(), email_ids.get("john").unwrap().last().unwrap(), @@ -340,7 +340,7 @@ pub async fn test(params: &mut JMAPTest) { .unwrap(); let mut request = john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .build(); let email_id = request .import_email() @@ -355,7 +355,7 @@ pub async fn test(params: &mut JMAPTest) { .unwrap() .take_id(); let email_id_2 = john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_copy( &john_id.to_string(), email_ids.get("john").unwrap().last().unwrap(), @@ -391,7 +391,7 @@ pub async fn test(params: &mut JMAPTest) { // Try removing items assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_destroy(&email_id) .await, ); @@ -404,7 +404,7 @@ pub async fn test(params: &mut JMAPTest) { .await .unwrap(); john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_destroy(&email_id) .await .unwrap(); @@ -412,7 +412,7 @@ pub async fn test(params: &mut JMAPTest) { // Try to set keywords assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_set_keyword(&email_id_2, "$seen", true) .await, ); @@ -431,12 +431,12 @@ pub async fn test(params: &mut JMAPTest) { .await .unwrap(); john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_set_keyword(&email_id_2, "$seen", true) .await .unwrap(); john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_set_keyword(&email_id_2, "my-keyword", true) .await .unwrap(); @@ -444,7 +444,7 @@ pub async fn test(params: &mut JMAPTest) { // Try to create a child assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .mailbox_create("John's mailbox", None::<&str>, Role::None) .await, ); @@ -464,7 +464,7 @@ pub async fn test(params: &mut JMAPTest) { .await .unwrap(); let mailbox_id = john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .mailbox_create("John's mailbox", Some(&inbox_id), Role::None) .await .unwrap() @@ -473,7 +473,7 @@ pub async fn test(params: &mut JMAPTest) { // Try renaming a mailbox assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .mailbox_rename(&mailbox_id, "John's private mailbox") .await, ); @@ -486,7 +486,7 @@ pub async fn test(params: &mut JMAPTest) { .await .unwrap(); john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .mailbox_rename(&mailbox_id, "John's private mailbox") .await .unwrap(); @@ -494,7 +494,7 @@ pub async fn test(params: &mut JMAPTest) { // Try moving a message assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_set_mailbox(&email_id_2, &mailbox_id, true) .await, ); @@ -507,7 +507,7 @@ pub async fn test(params: &mut JMAPTest) { .await .unwrap(); john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_set_mailbox(&email_id_2, &mailbox_id, true) .await .unwrap(); @@ -515,7 +515,7 @@ pub async fn test(params: &mut JMAPTest) { // Try deleting a mailbox assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .mailbox_destroy(&mailbox_id, true) .await, ); @@ -535,7 +535,7 @@ pub async fn test(params: &mut JMAPTest) { .unwrap(); assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .mailbox_destroy(&mailbox_id, true) .await, ); @@ -555,7 +555,7 @@ pub async fn test(params: &mut JMAPTest) { .await .unwrap(); john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .mailbox_destroy(&mailbox_id, true) .await .unwrap(); @@ -563,13 +563,13 @@ pub async fn test(params: &mut JMAPTest) { // Try changing ACL assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .mailbox_update_acl(&inbox_id, "bill@example.com", [ACL::Read, ACL::ReadItems]) .await, ); assert_forbidden( bill_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_query(None::, None::>) .await, ); @@ -592,7 +592,7 @@ pub async fn test(params: &mut JMAPTest) { .unwrap(); assert_eq!( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .mailbox_get(&inbox_id, [mailbox::Property::MyRights].into()) .await .unwrap() @@ -610,13 +610,13 @@ pub async fn test(params: &mut JMAPTest) { ] ); john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .mailbox_update_acl(&inbox_id, "bill@example.com", [ACL::Read, ACL::ReadItems]) .await .unwrap(); assert_eq!( bill_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_query( None::, vec![email::query::Comparator::subject()].into() @@ -637,7 +637,7 @@ pub async fn test(params: &mut JMAPTest) { .unwrap(); assert_forbidden( john_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_get( email_ids.get("jane").unwrap().first().unwrap(), [Property::Subject].into(), @@ -651,7 +651,7 @@ pub async fn test(params: &mut JMAPTest) { .is_none()); assert_eq!( bill_client - .set_default_account_id(&jane_id.to_string()) + .set_default_account_id(jane_id.to_string()) .email_get( email_ids.get("jane").unwrap().first().unwrap(), [Property::Subject].into(), diff --git a/tests/src/jmap/mod.rs b/tests/src/jmap/mod.rs index db7a7593..c73ed46e 100644 --- a/tests/src/jmap/mod.rs +++ b/tests/src/jmap/mod.rs @@ -11,7 +11,10 @@ use base64::{ Engine, }; use common::{ - config::server::{ServerProtocol, Servers}, + config::{ + server::{ServerProtocol, Servers}, + tracers::Tracer, + }, manager::config::{ConfigManager, Patterns}, webhooks::manager::spawn_webhook_manager, Core, Ipc, IPC_CHANNEL_BUFFER, @@ -33,6 +36,7 @@ use store::{ IterateParams, Stores, SUBSPACE_PROPERTY, }; use tokio::sync::{mpsc, watch}; +use trc::collector::Collector; use utils::config::Config; use webhooks::{spawn_mock_webhook_endpoint, MockWebhookEndpoint}; @@ -286,20 +290,14 @@ throttle = "100ms" #[tokio::test(flavor = "multi_thread")] pub async fn jmap_tests() { if let Ok(level) = std::env::var("LOG") { - let todo = "implement"; - - /*tracing::subscriber::set_global_default( - tracing_subscriber::FmtSubscriber::builder() - .with_env_filter( - tracing_subscriber::EnvFilter::builder() - .parse( - format!("smtp={level},imap={level},jmap={level},store={level},utils={level},directory={level},common={level}"), - ) - .unwrap(), - ) - .finish(), - ) - .unwrap();*/ + let level = level.parse().unwrap(); + Collector::set_level(level); + Tracer::Stdout { + id: "stdout".to_string(), + level, + ansi: true, + } + .spawn(); } let delete = true; @@ -346,20 +344,14 @@ pub async fn jmap_tests() { #[ignore] pub async fn jmap_stress_tests() { if let Ok(level) = std::env::var("LOG") { - let todo = "implement"; - - /*tracing::subscriber::set_global_default( - tracing_subscriber::FmtSubscriber::builder() - .with_env_filter( - tracing_subscriber::EnvFilter::builder() - .parse( - format!("smtp={level},imap={level},jmap={level},store={level},utils={level},directory={level},common={level}"), - ) - .unwrap(), - ) - .finish(), - ) - .unwrap();*/ + let level = level.parse().unwrap(); + Collector::set_level(level); + Tracer::Stdout { + id: "stdout".to_string(), + level, + ansi: true, + } + .spawn(); } let params = init_jmap_tests( diff --git a/tests/src/jmap/push_subscription.rs b/tests/src/jmap/push_subscription.rs index c205e087..5b97bb68 100644 --- a/tests/src/jmap/push_subscription.rs +++ b/tests/src/jmap/push_subscription.rs @@ -297,7 +297,8 @@ impl common::listener::SessionManager for SessionManager { StatusCode::TOO_MANY_REQUESTS, "too many requests".to_string(), ) - .into_http_response()); + .into_http_response() + .build()); } let is_encrypted = req .headers() @@ -305,7 +306,7 @@ impl common::listener::SessionManager for SessionManager { .map_or(false, |encoding| { encoding.to_str().unwrap() == "aes128gcm" }); - let body = fetch_body(&mut req, 1024 * 1024).await.unwrap(); + let body = fetch_body(&mut req, 1024 * 1024, 0).await.unwrap(); let message = serde_json::from_slice::(&if is_encrypted { ece::decrypt( &push.keypair, @@ -323,7 +324,9 @@ impl common::listener::SessionManager for SessionManager { push.tx.send(message).await.unwrap(); Ok::<_, hyper::Error>( - HtmlResponse::new("ok".to_string()).into_http_response(), + HtmlResponse::new("ok".to_string()) + .into_http_response() + .build(), ) } }), diff --git a/tests/src/jmap/thread_merge.rs b/tests/src/jmap/thread_merge.rs index 2531ad9c..37195e6e 100644 --- a/tests/src/jmap/thread_merge.rs +++ b/tests/src/jmap/thread_merge.rs @@ -249,6 +249,7 @@ async fn test_multi_thread(params: &mut JMAPTest) { received_at: None, source: IngestSource::Smtp, encrypt: false, + session_id: 0, }) .await { diff --git a/tests/src/jmap/webhooks.rs b/tests/src/jmap/webhooks.rs index bffcf98d..97606dc2 100644 --- a/tests/src/jmap/webhooks.rs +++ b/tests/src/jmap/webhooks.rs @@ -115,7 +115,7 @@ pub fn spawn_mock_webhook_endpoint() -> Arc { async move { // Verify HMAC signature let key = hmac::Key::new(hmac::HMAC_SHA256, "ovos-moles".as_bytes()); - let body = fetch_body(&mut req, 1024 * 1024).await.unwrap(); + let body = fetch_body(&mut req, 1024 * 1024, 0).await.unwrap(); let tag = STANDARD.decode(req.headers().get("X-Signature").unwrap().to_str().unwrap()).unwrap(); hmac::verify(&key, &body, &tag).expect("Invalid signature"); @@ -134,13 +134,13 @@ pub fn spawn_mock_webhook_endpoint() -> Arc { content_type: "application/json", contents: "[]".to_string().into_bytes(), } - .into_http_response(), + .into_http_response().build(), ) } else { //let c = print!("rejected webhook: {}", serde_json::to_string_pretty(&request).unwrap()); Ok::<_, hyper::Error>( - RequestError::not_found().into_http_response() + RequestError::not_found().into_http_response().build() ) } diff --git a/tests/src/smtp/config.rs b/tests/src/smtp/config.rs index 786096ac..a618e378 100644 --- a/tests/src/smtp/config.rs +++ b/tests/src/smtp/config.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::{fs, net::IpAddr, path::PathBuf, time::Duration}; +use std::{fs, net::IpAddr, path::PathBuf, sync::Arc, time::Duration}; use common::{ config::{ @@ -262,6 +262,7 @@ fn parse_throttles() { throttle, vec![ Throttle { + id: "0".to_string(), expr: Expression { items: vec![ ExpressionItem::Variable(8), @@ -278,6 +279,7 @@ fn parse_throttles() { .into() }, Throttle { + id: "1".to_string(), expr: Expression::default(), keys: THROTTLE_SENDER_DOMAIN, concurrency: 10000.into(), @@ -300,6 +302,7 @@ fn parse_servers() { // Parse servers let mut config = Config::new(toml).unwrap(); let servers = Servers::parse(&mut config).servers; + let id_generator = Arc::new(utils::snowflake::SnowflakeIdGenerator::new()); let expected_servers = vec![ Server { id: "smtp".to_string(), @@ -314,6 +317,7 @@ fn parse_servers() { }], max_connections: 8192, proxy_networks: vec![], + id_generator: id_generator.clone(), }, Server { id: "smtps".to_string(), @@ -338,6 +342,7 @@ fn parse_servers() { ], max_connections: 1024, proxy_networks: vec![], + id_generator: id_generator.clone(), }, Server { id: "submission".to_string(), @@ -352,6 +357,7 @@ fn parse_servers() { }], max_connections: 8192, proxy_networks: vec![], + id_generator: id_generator.clone(), }, ]; @@ -428,7 +434,7 @@ async fn eval_if() { }], default: Expression::from(false), } - .eval(&envelope, &core) + .eval(&envelope, &core, 0) .await .unwrap() .to_bool(), @@ -479,7 +485,7 @@ async fn eval_dynvalue() { .unwrap_or_else(|| panic!("Missing expect for test {test_name:?}")); assert_eq!( - String::try_from(if_block.eval(&envelope, &core).await.unwrap()).ok(), + String::try_from(if_block.eval(&envelope, &core, 0).await.unwrap()).ok(), expected, "failed for test {test_name:?}" ); diff --git a/tests/src/smtp/inbound/milter.rs b/tests/src/smtp/inbound/milter.rs index 03412384..19b351e6 100644 --- a/tests/src/smtp/inbound/milter.rs +++ b/tests/src/smtp/inbound/milter.rs @@ -553,6 +553,7 @@ async fn milter_client_test() { let mut client = MilterClient::connect( &Milter { enable: IfBlock::empty(""), + id: "test".to_string().into(), addrs: vec![SocketAddr::from(([127, 0, 0, 1], PORT))], hostname: "localhost".to_string(), port: PORT, @@ -809,7 +810,7 @@ pub fn spawn_mock_mta_hook_server() -> watch::Sender { async move { - let request = serde_json::from_slice::(&fetch_body(&mut req, 1024 * 1024).await.unwrap()) + let request = serde_json::from_slice::(&fetch_body(&mut req, 1024 * 1024,0).await.unwrap()) .unwrap(); let response = handle_mta_hook(request, tests); @@ -818,7 +819,7 @@ pub fn spawn_mock_mta_hook_server() -> watch::Sender { content_type: "application/json", contents: serde_json::to_string(&response).unwrap().into_bytes(), } - .into_http_response(), + .into_http_response().build(), ) } }), diff --git a/tests/src/smtp/session.rs b/tests/src/smtp/session.rs index aa1b926b..40c71a15 100644 --- a/tests/src/smtp/session.rs +++ b/tests/src/smtp/session.rs @@ -18,6 +18,7 @@ use tokio::{ use smtp::core::{Session, SessionAddress, SessionData, SessionParameters, State, SMTP}; use tokio_rustls::TlsAcceptor; +use utils::snowflake::SnowflakeIdGenerator; pub struct DummyIo { pub tx_buf: Vec, @@ -359,6 +360,7 @@ impl TestServerInstance for ServerInstance { limiter: ConcurrencyLimiter::new(100), shutdown_rx, proxy_networks: vec![], + id_generator: Arc::new(SnowflakeIdGenerator::new()), } } }