From a45eb5023137d3d2e5f42573377f7f1b3d53938f Mon Sep 17 00:00:00 2001 From: mdecimus Date: Sun, 28 Jul 2024 15:21:22 +0200 Subject: [PATCH] Improved tracing (part 4) --- crates/common/Cargo.toml | 1 + crates/common/src/config/mod.rs | 6 +- crates/common/src/config/network.rs | 11 +- crates/common/src/config/smtp/queue.rs | 6 +- crates/common/src/lib.rs | 151 +---- crates/common/src/listener/mod.rs | 2 +- crates/common/src/tracing/mod.rs | 1 + .../manager.rs => tracing/webhook.rs} | 2 - crates/common/src/webhooks/collector.rs | 33 - crates/common/src/webhooks/mod.rs | 334 ---------- crates/directory/src/backend/ldap/lookup.rs | 94 ++- crates/directory/src/backend/ldap/pool.rs | 12 +- crates/directory/src/lib.rs | 12 + crates/imap/src/core/client.rs | 2 +- crates/imap/src/core/session.rs | 4 +- crates/imap/src/op/acl.rs | 140 ++-- crates/imap/src/op/append.rs | 19 +- crates/imap/src/op/authenticate.rs | 4 +- crates/imap/src/op/capability.rs | 20 +- crates/imap/src/op/close.rs | 17 +- crates/imap/src/op/copy_move.rs | 31 +- crates/imap/src/op/create.rs | 16 + crates/imap/src/op/delete.rs | 13 + crates/imap/src/op/enable.rs | 16 + crates/imap/src/op/expunge.rs | 21 +- crates/imap/src/op/fetch.rs | 34 +- crates/imap/src/op/idle.rs | 14 +- crates/imap/src/op/list.rs | 20 +- crates/imap/src/op/logout.rs | 11 + crates/imap/src/op/namespace.rs | 6 + crates/imap/src/op/noop.rs | 10 + crates/imap/src/op/rename.rs | 21 +- crates/imap/src/op/search.rs | 18 +- crates/imap/src/op/select.rs | 16 +- crates/imap/src/op/status.rs | 16 +- crates/imap/src/op/store.rs | 57 +- crates/imap/src/op/subscribe.rs | 24 +- crates/imap/src/op/thread.rs | 15 +- crates/jmap/src/api/http.rs | 14 +- crates/jmap/src/api/request.rs | 39 +- crates/jmap/src/auth/authenticate.rs | 28 +- crates/jmap/src/email/copy.rs | 22 +- crates/jmap/src/email/crypto.rs | 4 +- crates/jmap/src/email/ingest.rs | 41 +- crates/jmap/src/lib.rs | 48 +- crates/jmap/src/services/index.rs | 5 + crates/jmap/src/services/ingest.rs | 15 +- crates/jmap/src/sieve/set.rs | 31 +- crates/main/Cargo.toml | 2 +- crates/main/src/main.rs | 13 +- crates/managesieve/src/core/client.rs | 4 +- crates/managesieve/src/op/authenticate.rs | 18 +- crates/managesieve/src/op/capability.rs | 12 + crates/managesieve/src/op/checkscript.rs | 24 +- crates/managesieve/src/op/deletescript.rs | 12 + crates/managesieve/src/op/getscript.rs | 11 + crates/managesieve/src/op/havespace.rs | 10 + crates/managesieve/src/op/listscripts.rs | 11 + crates/managesieve/src/op/logout.rs | 6 + crates/managesieve/src/op/mod.rs | 6 + crates/managesieve/src/op/noop.rs | 6 + crates/managesieve/src/op/putscript.rs | 41 +- crates/managesieve/src/op/renamescript.rs | 16 +- crates/managesieve/src/op/setactive.rs | 11 + crates/pop3/src/client.rs | 46 +- crates/pop3/src/op/authenticate.rs | 7 +- crates/pop3/src/op/delete.rs | 32 +- crates/pop3/src/op/fetch.rs | 10 + crates/pop3/src/op/list.rs | 45 ++ crates/pop3/src/session.rs | 2 +- crates/smtp/src/core/mod.rs | 1 - crates/smtp/src/inbound/auth.rs | 15 +- crates/smtp/src/inbound/data.rs | 118 +--- crates/smtp/src/inbound/mail.rs | 78 +++ crates/smtp/src/inbound/rcpt.rs | 28 + crates/smtp/src/inbound/session.rs | 121 +++- crates/smtp/src/outbound/client.rs | 611 ++++++++++++++++++ crates/smtp/src/outbound/delivery.rs | 159 ++++- crates/smtp/src/outbound/local.rs | 2 + crates/smtp/src/outbound/mod.rs | 2 +- crates/smtp/src/outbound/session.rs | 304 +++------ crates/smtp/src/queue/dsn.rs | 141 ++-- crates/smtp/src/queue/quota.rs | 22 + crates/smtp/src/queue/spool.rs | 3 + crates/smtp/src/reporting/analysis.rs | 185 +----- crates/smtp/src/reporting/dkim.rs | 1 + crates/smtp/src/reporting/dmarc.rs | 1 + crates/smtp/src/reporting/mod.rs | 40 -- crates/smtp/src/reporting/spf.rs | 1 + crates/store/src/backend/rocksdb/read.rs | 2 +- crates/trc/src/atomic.rs | 118 ++++ crates/trc/src/conv.rs | 14 +- crates/trc/src/imple.rs | 167 ++++- crates/trc/src/lib.rs | 152 ++++- tests/Cargo.toml | 2 +- tests/src/imap/mod.rs | 9 +- tests/src/jmap/auth_acl.rs | 22 +- tests/src/jmap/event_source.rs | 4 +- tests/src/jmap/mod.rs | 9 +- tests/src/jmap/webhooks.rs | 13 +- tests/src/smtp/config.rs | 4 +- tests/src/store/import_export.rs | 2 +- 102 files changed, 2634 insertions(+), 1539 deletions(-) rename crates/common/src/{webhooks/manager.rs => tracing/webhook.rs} (99%) delete mode 100644 crates/common/src/webhooks/collector.rs delete mode 100644 crates/common/src/webhooks/mod.rs create mode 100644 crates/smtp/src/outbound/client.rs create mode 100644 crates/trc/src/atomic.rs diff --git a/crates/common/Cargo.toml b/crates/common/Cargo.toml index 8faa95f3..8233604d 100644 --- a/crates/common/Cargo.toml +++ b/crates/common/Cargo.toml @@ -68,3 +68,4 @@ tracing-journald = "0.3" [features] test_mode = [] enterprise = [] +foundation = [] diff --git a/crates/common/src/config/mod.rs b/crates/common/src/config/mod.rs index 3d9d5829..834dc6ea 100644 --- a/crates/common/src/config/mod.rs +++ b/crates/common/src/config/mod.rs @@ -11,10 +11,7 @@ use directory::{Directories, Directory}; use store::{BlobBackend, BlobStore, FtsStore, LookupStore, Store, Stores}; use utils::config::Config; -use crate::{ - expr::*, listener::tls::TlsManager, manager::config::ConfigManager, webhooks::Webhooks, Core, - Network, -}; +use crate::{expr::*, listener::tls::TlsManager, manager::config::ConfigManager, Core, Network}; use self::{ imap::ImapConfig, jmap::settings::JmapConfig, scripts::Scripting, smtp::SmtpConfig, @@ -141,7 +138,6 @@ impl Core { jmap: JmapConfig::parse(config), imap: ImapConfig::parse(config), tls: TlsManager::parse(config), - web_hooks: Webhooks::parse(config), storage: Storage { data, blob, diff --git a/crates/common/src/config/network.rs b/crates/common/src/config/network.rs index 50eb0f24..2ca07528 100644 --- a/crates/common/src/config/network.rs +++ b/crates/common/src/config/network.rs @@ -4,20 +4,11 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::{str::FromStr, time::Duration}; - use crate::{ expr::{if_block::IfBlock, tokenizer::TokenMap}, listener::blocked::{AllowedIps, BlockedIps}, - webhooks::{Webhook, WebhookType, Webhooks}, Network, }; -use ahash::AHashSet; -use base64::{engine::general_purpose::STANDARD, Engine}; -use hyper::{ - header::{HeaderName, HeaderValue, AUTHORIZATION, CONTENT_TYPE}, - HeaderMap, -}; use utils::config::Config; use super::CONNECTION_VARS; @@ -55,6 +46,7 @@ impl Network { } } +/* impl Webhooks { pub fn parse(config: &mut Config) -> Self { let mut hooks = Webhooks { @@ -183,3 +175,4 @@ impl FromStr for WebhookType { } } } +*/ diff --git a/crates/common/src/config/smtp/queue.rs b/crates/common/src/config/smtp/queue.rs index 4ef9d729..f471ba04 100644 --- a/crates/common/src/config/smtp/queue.rs +++ b/crates/common/src/config/smtp/queue.rs @@ -98,6 +98,7 @@ pub struct QueueQuotas { #[derive(Clone)] pub struct QueueQuota { + pub id: String, pub expr: Expression, pub keys: u16, pub size: Option, @@ -435,7 +436,7 @@ fn parse_queue_quota(config: &mut Config) -> QueueQuotas { .map(|s| s.to_string()) .collect::>() { - if let Some(quota) = parse_queue_quota_item(config, ("queue.quota", "a_id)) { + if let Some(quota) = parse_queue_quota_item(config, ("queue.quota", "a_id), "a_id) { if (quota.keys & THROTTLE_RCPT) != 0 || quota .expr @@ -461,7 +462,7 @@ fn parse_queue_quota(config: &mut Config) -> QueueQuotas { capacities } -fn parse_queue_quota_item(config: &mut Config, prefix: impl AsKey) -> Option { +fn parse_queue_quota_item(config: &mut Config, prefix: impl AsKey, id: &str) -> Option { let prefix = prefix.as_key(); // Skip disabled throttles @@ -500,6 +501,7 @@ fn parse_queue_quota_item(config: &mut Config, prefix: impl AsKey) -> Option, } @@ -83,7 +79,6 @@ pub enum DeliveryEvent { pub struct Ipc { pub delivery_tx: mpsc::Sender, - pub webhook_tx: mpsc::Sender, } #[derive(Debug)] @@ -208,10 +203,9 @@ impl Core { pub async fn authenticate( &self, directory: &Directory, - ipc: &Ipc, + session_id: u64, credentials: &Credentials, remote_ip: IpAddr, - protocol: ServerProtocol, return_member_of: bool, ) -> trc::Result> { // First try to authenticate the user against the default directory @@ -220,20 +214,13 @@ impl Core { .await { Ok(Some(principal)) => { - // Send webhook event - if self.has_webhook_subscribers(WebhookType::AuthSuccess) { - ipc.send_webhook( - WebhookType::AuthSuccess, - WebhookPayload::Authentication { - login: credentials.login().to_string(), - protocol, - remote_ip, - typ: principal.typ.into(), - as_master: None, - }, - ) - .await; - } + trc::event!( + Auth(trc::AuthEvent::Success), + Name = credentials.login().to_string(), + AccountId = principal.id, + SpanId = session_id, + Type = principal.typ.as_str(), + ); return Ok(principal); } @@ -257,20 +244,13 @@ impl Core { if username == fallback_admin => { if verify_secret_hash(fallback_pass, secret).await? { - // Send webhook event - if self.has_webhook_subscribers(WebhookType::AuthSuccess) { - ipc.send_webhook( - WebhookType::AuthSuccess, - WebhookPayload::Authentication { - login: username.to_string(), - protocol, - remote_ip, - typ: Type::Superuser.into(), - as_master: None, - }, - ) - .await; - } + trc::event!( + Auth(trc::AuthEvent::Success), + Name = username.clone(), + SpanId = session_id, + Type = Type::Superuser.as_str(), + ); + return Ok(Principal::fallback_admin(fallback_pass)); } } @@ -280,120 +260,41 @@ impl Core { if verify_secret_hash(master_pass, secret).await? { let username = username.strip_suffix(master_user).unwrap(); let username = username.strip_suffix('%').unwrap_or(username); - return if let Some(principal) = directory + + if let Some(principal) = directory .query(QueryBy::Name(username), return_member_of) .await? { - // Send webhook event - if self.has_webhook_subscribers(WebhookType::AuthSuccess) { - ipc.send_webhook( - WebhookType::AuthSuccess, - WebhookPayload::Authentication { - login: username.to_string(), - protocol, - remote_ip, - typ: principal.typ.into(), - as_master: true.into(), - }, - ) - .await; - } - Ok(principal) - } else { - // Send webhook event - if self.has_webhook_subscribers(WebhookType::AuthFailure) { - ipc.send_webhook( - WebhookType::AuthFailure, - WebhookPayload::Authentication { - login: username.to_string(), - protocol, - remote_ip, - typ: None, - as_master: true.into(), - }, - ) - .await; - } + trc::event!( + Auth(trc::AuthEvent::Success), + Name = username.to_string(), + SpanId = session_id, + AccountId = principal.id, + Type = principal.typ.as_str(), + ); - Err(trc::AuthEvent::Failed - .ctx(trc::Key::Name, username.to_string()) - .ctx(trc::Key::RemoteIp, remote_ip)) - }; + return Ok(principal); + } } } _ => {} } if let Err(err) = result { - // Send webhook event - if self.has_webhook_subscribers(WebhookType::AuthError) { - ipc.send_webhook( - WebhookType::AuthError, - WebhookPayload::Error { - message: err.to_string(), - }, - ) - .await; - } - Err(err) } else if self.has_fail2ban() { let login = credentials.login(); if self.is_fail2banned(remote_ip, login.to_string()).await? { - // Send webhook event - if self.has_webhook_subscribers(WebhookType::AuthBanned) { - ipc.send_webhook( - WebhookType::AuthBanned, - WebhookPayload::Authentication { - login: credentials.login().to_string(), - protocol, - remote_ip, - typ: None, - as_master: None, - }, - ) - .await; - } - Err(trc::AuthEvent::Banned .into_err() .ctx(trc::Key::RemoteIp, remote_ip) .ctx(trc::Key::Name, login.to_string())) } else { - // Send webhook event - if self.has_webhook_subscribers(WebhookType::AuthFailure) { - ipc.send_webhook( - WebhookType::AuthFailure, - WebhookPayload::Authentication { - login: credentials.login().to_string(), - protocol, - remote_ip, - typ: None, - as_master: None, - }, - ) - .await; - } - Err(trc::AuthEvent::Failed .ctx(trc::Key::RemoteIp, remote_ip) .ctx(trc::Key::Name, login.to_string())) } } else { - // Send webhook event - if self.has_webhook_subscribers(WebhookType::AuthFailure) { - ipc.send_webhook( - WebhookType::AuthFailure, - WebhookPayload::Authentication { - login: credentials.login().to_string(), - protocol, - remote_ip, - typ: None, - as_master: None, - }, - ) - .await; - } Err(trc::AuthEvent::Failed .ctx(trc::Key::RemoteIp, remote_ip) .ctx(trc::Key::Name, credentials.login().to_string())) diff --git a/crates/common/src/listener/mod.rs b/crates/common/src/listener/mod.rs index d6bf0d59..daf27deb 100644 --- a/crates/common/src/listener/mod.rs +++ b/crates/common/src/listener/mod.rs @@ -186,7 +186,7 @@ pub trait SessionManager: Sync + Send + 'static + Clone { } trc::event!( - Network(trc::NetworkEvent::ConnectionStop), + Network(trc::NetworkEvent::ConnectionEnd), SpanId = session_id, Elapsed = start_time.elapsed(), ); diff --git a/crates/common/src/tracing/mod.rs b/crates/common/src/tracing/mod.rs index c0509e33..4c75462f 100644 --- a/crates/common/src/tracing/mod.rs +++ b/crates/common/src/tracing/mod.rs @@ -5,6 +5,7 @@ */ pub mod stdout; +//pub mod webhook; use opentelemetry::KeyValue; use opentelemetry_sdk::{ diff --git a/crates/common/src/webhooks/manager.rs b/crates/common/src/tracing/webhook.rs similarity index 99% rename from crates/common/src/webhooks/manager.rs rename to crates/common/src/tracing/webhook.rs index 610a2a77..c7e0450f 100644 --- a/crates/common/src/webhooks/manager.rs +++ b/crates/common/src/tracing/webhook.rs @@ -17,8 +17,6 @@ use ring::hmac; use tokio::sync::mpsc; use utils::snowflake::SnowflakeIdGenerator; -use super::{Webhook, WebhookEvents, WebhookPayload, WebhookType}; - pub enum WebhookEvent { Send { typ: WebhookType, diff --git a/crates/common/src/webhooks/collector.rs b/crates/common/src/webhooks/collector.rs deleted file mode 100644 index b9a8be73..00000000 --- a/crates/common/src/webhooks/collector.rs +++ /dev/null @@ -1,33 +0,0 @@ -/* - * SPDX-FileCopyrightText: 2020 Stalwart Labs Ltd - * - * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL - */ - -use std::sync::Arc; - -use crate::{Core, Ipc}; - -use super::{manager::WebhookEvent, WebhookPayload, WebhookType}; - -impl Core { - #[inline(always)] - pub fn has_webhook_subscribers(&self, event_type: WebhookType) -> bool { - self.web_hooks.events.contains(&event_type) - } -} - -impl Ipc { - pub async fn send_webhook(&self, event_type: WebhookType, payload: WebhookPayload) { - if let Err(err) = self - .webhook_tx - .send(WebhookEvent::Send { - typ: event_type, - payload: Arc::new(payload), - }) - .await - { - //trc::event!("Failed to send webhook event: {:?}", err); - } - } -} diff --git a/crates/common/src/webhooks/mod.rs b/crates/common/src/webhooks/mod.rs deleted file mode 100644 index 9c5944c7..00000000 --- a/crates/common/src/webhooks/mod.rs +++ /dev/null @@ -1,334 +0,0 @@ -/* - * SPDX-FileCopyrightText: 2020 Stalwart Labs Ltd - * - * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL - */ - -use std::{net::IpAddr, sync::Arc, time::Duration}; - -use ahash::{AHashMap, AHashSet}; -use chrono::{DateTime, Utc}; -use hyper::HeaderMap; -use mail_auth::report::{ - tlsrpt::{PolicyType, ResultType}, - AuthFailureType, DeliveryResult, FeedbackType, IdentityAlignment, -}; -use serde::{Deserialize, Serialize}; - -use crate::config::server::ServerProtocol; - -pub mod collector; -pub mod manager; - -#[derive(Clone, Default)] -pub struct Webhooks { - pub events: AHashSet, - pub hooks: AHashMap>, -} - -#[derive(Clone)] -pub struct Webhook { - pub id: u64, - pub url: String, - pub key: String, - pub timeout: Duration, - pub throttle: Duration, - pub tls_allow_invalid_certs: bool, - pub headers: HeaderMap, - pub events: AHashSet, -} - -#[derive(Debug, Serialize, Deserialize, Default)] -pub struct WebhookEvents { - pub events: Vec, -} - -#[derive(Debug, Serialize, Deserialize)] -pub struct WebhookEvent { - pub id: u64, - #[serde(rename = "createdAt")] - pub created_at: DateTime, - #[serde(rename = "type")] - pub typ: WebhookType, - pub data: Arc, -} - -#[derive(Debug, Serialize, Deserialize, Clone, Copy, PartialEq, Eq, Hash)] -pub enum WebhookType { - #[serde(rename = "auth.success")] - AuthSuccess, - #[serde(rename = "auth.failure")] - AuthFailure, - #[serde(rename = "auth.banned")] - AuthBanned, - #[serde(rename = "auth.error")] - AuthError, - #[serde(rename = "message.accepted")] - MessageAccepted, - #[serde(rename = "message.rejected")] - MessageRejected, - #[serde(rename = "message.appended")] - MessageAppended, - #[serde(rename = "account.over-quota")] - AccountOverQuota, - #[serde(rename = "dsn")] - DSN, - #[serde(rename = "double-bounce")] - DoubleBounce, - #[serde(rename = "report.incoming.dmarc")] - IncomingDmarcReport, - #[serde(rename = "report.incoming.tls")] - IncomingTlsReport, - #[serde(rename = "report.incoming.arf")] - IncomingArfReport, - #[serde(rename = "report.outgoing")] - OutgoingReport, -} - -#[derive(Debug, Serialize, Deserialize)] -#[serde(untagged)] -pub enum WebhookPayload { - Authentication { - login: String, - protocol: ServerProtocol, - #[serde(rename = "remoteIp")] - remote_ip: IpAddr, - #[serde(rename = "accountType")] - #[serde(skip_serializing_if = "Option::is_none")] - typ: Option, - #[serde(rename = "isMasterLogin")] - #[serde(skip_serializing_if = "Option::is_none")] - as_master: Option, - }, - Error { - message: String, - }, - MessageAccepted { - #[serde(rename = "queueId")] - id: u64, - #[serde(rename = "remoteIp")] - #[serde(skip_serializing_if = "Option::is_none")] - remote_ip: Option, - #[serde(rename = "localPort")] - #[serde(skip_serializing_if = "Option::is_none")] - local_port: Option, - #[serde(rename = "authenticatedAs")] - #[serde(skip_serializing_if = "Option::is_none")] - authenticated_as: Option, - #[serde(rename = "returnPath")] - return_path: String, - recipients: Vec, - #[serde(rename = "nextRetry")] - next_retry: DateTime, - #[serde(rename = "nextDSN")] - next_dsn: DateTime, - expires: DateTime, - size: usize, - }, - MessageRejected { - reason: WebhookMessageFailure, - #[serde(rename = "remoteIp")] - remote_ip: IpAddr, - #[serde(rename = "localPort")] - local_port: u16, - #[serde(rename = "authenticatedAs")] - #[serde(skip_serializing_if = "Option::is_none")] - authenticated_as: Option, - #[serde(rename = "returnPath")] - #[serde(skip_serializing_if = "Option::is_none")] - return_path: Option, - #[serde(skip_serializing_if = "Vec::is_empty")] - recipients: Vec, - }, - MessageAppended { - #[serde(rename = "accountId")] - account_id: u32, - #[serde(rename = "mailboxIds")] - mailbox_ids: Vec, - source: WebhookIngestSource, - encrypt: bool, - size: usize, - }, - DSN { - #[serde(rename = "queueId")] - id: u64, - sender: String, - status: Vec, - #[serde(rename = "createdAt")] - created: DateTime, - }, - IncomingDmarcReport { - #[serde(rename = "rangeFrom")] - range_from: String, - #[serde(rename = "rangeTo")] - range_to: String, - domain: String, - #[serde(rename = "reportEmail")] - report_email: String, - #[serde(rename = "reportId")] - report_id: String, - #[serde(rename = "dmarcPass")] - dmarc_pass: u32, - #[serde(rename = "dmarcQuarantine")] - dmarc_quarantine: u32, - #[serde(rename = "dmarcReject")] - dmarc_reject: u32, - #[serde(rename = "dmarcNone")] - dmarc_none: u32, - #[serde(rename = "dkimPass")] - dkim_pass: u32, - #[serde(rename = "dkimFail")] - dkim_fail: u32, - #[serde(rename = "dkimNone")] - dkim_none: u32, - #[serde(rename = "spfPass")] - spf_pass: u32, - #[serde(rename = "spfFail")] - spf_fail: u32, - #[serde(rename = "spfNone")] - spf_none: u32, - }, - IncomingTlsReport { - policies: Vec, - }, - IncomingArfReport { - #[serde(rename = "feedbackType")] - feedback_type: FeedbackType, - #[serde(rename = "arrivalDate")] - #[serde(skip_serializing_if = "Option::is_none")] - arrival_date: Option, - #[serde(rename = "authenticationResults")] - #[serde(skip_serializing_if = "Vec::is_empty")] - authentication_results: Vec, - incidents: u32, - #[serde(rename = "reportedDomains")] - #[serde(skip_serializing_if = "Vec::is_empty")] - reported_domain: Vec, - #[serde(rename = "reportedUris")] - #[serde(skip_serializing_if = "Vec::is_empty")] - reported_uri: Vec, - #[serde(rename = "reportingMTA")] - #[serde(skip_serializing_if = "Option::is_none")] - reporting_mta: Option, - #[serde(rename = "sourceIp")] - #[serde(skip_serializing_if = "Option::is_none")] - source_ip: Option, - #[serde(rename = "userAgent")] - #[serde(skip_serializing_if = "Option::is_none")] - user_agent: Option, - #[serde(rename = "authFailureType")] - #[serde(skip_serializing_if = "has_no_auth_failure")] - auth_failure: AuthFailureType, - #[serde(rename = "deliveryResult")] - #[serde(skip_serializing_if = "has_no_delivery_result")] - delivery_result: DeliveryResult, - #[serde(rename = "dkimDomain")] - #[serde(skip_serializing_if = "Option::is_none")] - dkim_domain: Option, - #[serde(rename = "dkimIdentity")] - #[serde(skip_serializing_if = "Option::is_none")] - dkim_identity: Option, - #[serde(rename = "dkimSelector")] - #[serde(skip_serializing_if = "Option::is_none")] - dkim_selector: Option, - #[serde(rename = "identityAlignment")] - #[serde(skip_serializing_if = "has_no_alignment")] - identity_alignment: IdentityAlignment, - }, - AccountOverQuota { - #[serde(rename = "accountId")] - account_id: u32, - #[serde(rename = "quotaLimit")] - quota_limit: usize, - #[serde(rename = "quotaUsed")] - quota_used: usize, - #[serde(rename = "objectSize")] - object_size: usize, - }, -} - -#[derive(Debug, Serialize, Deserialize)] -pub struct WebhookTlsPolicy { - #[serde(rename = "rangeFrom")] - pub range_from: String, - #[serde(rename = "rangeTo")] - pub range_to: String, - pub domain: String, - #[serde(rename = "reportContact")] - #[serde(skip_serializing_if = "Option::is_none")] - pub report_contact: Option, - #[serde(rename = "reportId")] - pub report_id: String, - #[serde(rename = "policyType")] - pub policy_type: PolicyType, - #[serde(rename = "totalSuccesses")] - pub total_successes: u32, - #[serde(rename = "totalFailures")] - pub total_failures: u32, - pub details: AHashMap, -} - -#[derive(Debug, Serialize, Deserialize)] -pub struct WebhookDSN { - pub address: String, - #[serde(rename = "remoteHost")] - #[serde(skip_serializing_if = "Option::is_none")] - pub remote_host: Option, - #[serde(rename = "type")] - pub typ: WebhookDSNType, - pub message: String, - #[serde(rename = "nextRetry")] - #[serde(skip_serializing_if = "Option::is_none")] - pub next_retry: Option>, - #[serde(skip_serializing_if = "Option::is_none")] - pub expires: Option>, - #[serde(skip_serializing_if = "Option::is_none")] - #[serde(rename = "retryCount")] - pub retry_count: Option, -} - -#[derive(Debug, Serialize, Deserialize)] -#[serde(rename_all = "camelCase")] -pub enum WebhookDSNType { - Success, - TemporaryFailure, - PermanentFailure, -} - -#[derive(Debug, Serialize, Deserialize, Clone, Copy)] -#[serde(rename_all = "camelCase")] -pub enum WebhookMessageFailure { - ParseFailed, - LoopDetected, - DkimPolicy, - ArcPolicy, - DmarcPolicy, - MilterReject, - SieveDiscard, - SieveReject, - QuotaExceeded, - ServerFailure, -} - -#[derive(Debug, Serialize, Deserialize, Clone, Copy)] -#[serde(rename_all = "lowercase")] -pub enum WebhookIngestSource { - Smtp, - Jmap, - Imap, -} - -fn has_no_alignment(alignment: &IdentityAlignment) -> bool { - matches!( - alignment, - IdentityAlignment::None | IdentityAlignment::Unspecified - ) -} - -fn has_no_delivery_result(result: &DeliveryResult) -> bool { - matches!(result, DeliveryResult::Unspecified) -} - -fn has_no_auth_failure(failure: &AuthFailureType) -> bool { - matches!(failure, AuthFailureType::Unspecified) -} diff --git a/crates/directory/src/backend/ldap/lookup.rs b/crates/directory/src/backend/ldap/lookup.rs index 82897501..63baa697 100644 --- a/crates/directory/src/backend/ldap/lookup.rs +++ b/crates/directory/src/backend/ldap/lookup.rs @@ -69,9 +69,19 @@ impl LdapDirectory { ldap3::drive!(conn); - ldap.simple_bind(&auth_bind.build(username), secret) + let dn = auth_bind.build(username); + + trc::event!(Store(trc::StoreEvent::LdapBind), Details = dn.clone()); + + if ldap + .simple_bind(&dn, secret) .await - .map_err(|err| err.into_error().caused_by(trc::location!()))?; + .map_err(|err| err.into_error().caused_by(trc::location!()))? + .success() + .is_err() + { + return Ok(None); + } match self .find_principal(&mut ldap, &self.mappings.filter_name.build(username)) @@ -159,6 +169,7 @@ impl LdapDirectory { } pub async fn email_to_ids(&self, address: &str) -> trc::Result> { + let filter = self.mappings.filter_email.build(address.as_ref()); let rs = self .pool .get() @@ -167,7 +178,7 @@ impl LdapDirectory { .search( &self.mappings.base_dn, Scope::Subtree, - &self.mappings.filter_email.build(address.as_ref()), + &filter, &self.mappings.attr_name, ) .await @@ -176,6 +187,15 @@ impl LdapDirectory { .map(|(rs, _res)| rs) .map_err(|err| err.into_error().caused_by(trc::location!()))?; + trc::event!( + Store(trc::StoreEvent::LdapQuery), + Details = filter, + Result = rs + .iter() + .map(|e| trc::Value::from(format!("{e:?}"))) + .collect::>() + ); + let mut ids = Vec::with_capacity(rs.len()); for entry in rs { let entry = SearchEntry::construct(entry); @@ -193,6 +213,7 @@ impl LdapDirectory { } pub async fn rcpt(&self, address: &str) -> trc::Result { + let filter = self.mappings.filter_email.build(address.as_ref()); self.pool .get() .await @@ -200,18 +221,29 @@ impl LdapDirectory { .streaming_search( &self.mappings.base_dn, Scope::Subtree, - &self.mappings.filter_email.build(address.as_ref()), + &filter, &self.mappings.attr_email_address, ) .await .map_err(|err| err.into_error().caused_by(trc::location!()))? .next() .await - .map(|entry| entry.is_some()) + .map(|entry| { + let success = entry.is_some(); + + trc::event!( + Store(trc::StoreEvent::LdapQuery), + Details = filter, + Result = entry.map(|e| trc::Value::from(format!("{e:?}"))) + ); + + success + }) .map_err(|err| err.into_error().caused_by(trc::location!())) } pub async fn vrfy(&self, address: &str) -> trc::Result> { + let filter = self.mappings.filter_verify.build(address); let mut stream = self .pool .get() @@ -220,7 +252,7 @@ impl LdapDirectory { .streaming_search( &self.mappings.base_dn, Scope::Subtree, - &self.mappings.filter_verify.build(address), + &filter, &self.mappings.attr_email_address, ) .await @@ -244,10 +276,20 @@ impl LdapDirectory { } } + trc::event!( + Store(trc::StoreEvent::LdapQuery), + Details = filter, + Result = emails + .iter() + .map(|e| trc::Value::from(e.clone())) + .collect::>() + ); + Ok(emails) } pub async fn expn(&self, address: &str) -> trc::Result> { + let filter = self.mappings.filter_expand.build(address); let mut stream = self .pool .get() @@ -256,7 +298,7 @@ impl LdapDirectory { .streaming_search( &self.mappings.base_dn, Scope::Subtree, - &self.mappings.filter_expand.build(address), + &filter, &self.mappings.attr_email_address, ) .await @@ -280,10 +322,20 @@ impl LdapDirectory { } } + trc::event!( + Store(trc::StoreEvent::LdapQuery), + Details = filter, + Result = emails + .iter() + .map(|e| trc::Value::from(e.clone())) + .collect::>() + ); + Ok(emails) } pub async fn is_local_domain(&self, domain: &str) -> trc::Result { + let filter = self.mappings.filter_domains.build(domain); self.pool .get() .await @@ -291,14 +343,24 @@ impl LdapDirectory { .streaming_search( &self.mappings.base_dn, Scope::Subtree, - &self.mappings.filter_domains.build(domain), + &filter, Vec::::new(), ) .await .map_err(|err| err.into_error().caused_by(trc::location!()))? .next() .await - .map(|entry| entry.is_some()) + .map(|entry| { + let success = entry.is_some(); + + trc::event!( + Store(trc::StoreEvent::LdapQuery), + Details = filter, + Result = entry.map(|e| trc::Value::from(format!("{e:?}"))) + ); + + success + }) .map_err(|err| err.into_error().caused_by(trc::location!())) } } @@ -319,6 +381,15 @@ impl LdapDirectory { .map_err(|err| err.into_error().caused_by(trc::location!()))? .success() .map(|(rs, _)| { + trc::event!( + Store(trc::StoreEvent::LdapQuery), + Details = filter.to_string(), + Result = rs + .iter() + .map(|e| trc::Value::from(format!("{e:?}"))) + .collect::>() + ); + rs.into_iter().next().map(|entry| { self.mappings .entry_to_principal(SearchEntry::construct(entry)) @@ -332,11 +403,6 @@ impl LdapMappings { fn entry_to_principal(&self, entry: SearchEntry) -> Principal { let mut principal = Principal::default(); - trc::event!( - Store(trc::StoreEvent::LdapQuery), - Value = format!("{entry:?}") - ); - for (attr, value) in entry.attrs { if self.attr_name.contains(&attr) { principal.name = value.into_iter().next().unwrap_or_default(); diff --git a/crates/directory/src/backend/ldap/pool.rs b/crates/directory/src/backend/ldap/pool.rs index 7e55fa40..f5491fd2 100644 --- a/crates/directory/src/backend/ldap/pool.rs +++ b/crates/directory/src/backend/ldap/pool.rs @@ -21,8 +21,18 @@ impl managed::Manager for LdapConnectionManager { ldap3::drive!(conn); + trc::event!( + Store(trc::StoreEvent::LdapBind), + Details = self + .bind_dn + .as_ref() + .map(|b| trc::Value::String(b.dn.clone())), + ); + if let Some(bind) = &self.bind_dn { - ldap.simple_bind(&bind.dn, &bind.password).await?; + ldap.simple_bind(&bind.dn, &bind.password) + .await? + .success()?; } Ok(ldap) diff --git a/crates/directory/src/lib.rs b/crates/directory/src/lib.rs index 887eeada..61bb2582 100644 --- a/crates/directory/src/lib.rs +++ b/crates/directory/src/lib.rs @@ -122,6 +122,18 @@ impl Type { Self::List => "list", } } + + pub fn as_str(&self) -> &'static str { + match self { + Self::Individual => "Individual", + Self::Group => "Group", + Self::Resource => "Resource", + Self::Location => "Location", + Self::Superuser => "Superuser", + Self::List => "List", + Self::Other => "Other", + } + } } #[derive(Default, Clone, Debug)] diff --git a/crates/imap/src/core/client.rs b/crates/imap/src/core/client.rs index 9331a4d3..1952da3c 100644 --- a/crates/imap/src/core/client.rs +++ b/crates/imap/src/core/client.rs @@ -21,7 +21,7 @@ impl Session { Imap(trc::ImapEvent::RawInput), SpanId = self.session_id, Size = bytes.len(), - Contents = String::from_utf8_lossy(bytes).into_owned(), + Contents = trc::Value::from_maybe_string(bytes), ); let mut bytes = bytes.iter(); diff --git a/crates/imap/src/core/session.rs b/crates/imap/src/core/session.rs index 4c53df4b..25e43732 100644 --- a/crates/imap/src/core/session.rs +++ b/crates/imap/src/core/session.rs @@ -218,7 +218,7 @@ impl Session { Imap(trc::ImapEvent::RawOutput), SpanId = self.session_id, Size = bytes.len(), - Contents = String::from_utf8_lossy(bytes).into_owned(), + Contents = trc::Value::from_maybe_string(bytes), ); let mut stream = self.stream_tx.lock().await; @@ -261,7 +261,7 @@ impl super::SessionData { Imap(trc::ImapEvent::RawOutput), SpanId = self.session_id, Size = bytes.len(), - Contents = String::from_utf8_lossy(bytes).into_owned(), + Contents = trc::Value::from_maybe_string(bytes), ); let mut stream = self.stream_tx.lock().await; diff --git a/crates/imap/src/op/acl.rs b/crates/imap/src/op/acl.rs index 54f3394e..06ed52bc 100644 --- a/crates/imap/src/op/acl.rs +++ b/crates/imap/src/op/acl.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::sync::Arc; +use std::{sync::Arc, time::Instant}; use common::listener::SessionStream; use directory::QueryBy; @@ -43,12 +43,13 @@ use crate::{ impl Session { pub async fn handle_get_acl(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); let arguments = request.parse_acl(self.version)?; let is_rev2 = self.version.is_rev2(); let data = self.state.session_data(); spawn_op!(data, { - let (_, values, _) = data + let (mailbox, values, _) = data .get_acl_mailbox(&arguments, true) .await .imap_ctx(&arguments.tag, trc::location!())?; @@ -115,6 +116,16 @@ impl Session { } } + trc::event!( + Imap(trc::ImapEvent::GetAcl), + SpanId = data.session_id, + Name = arguments.mailbox_name.clone(), + AccountId = mailbox.account_id, + MailboxId = mailbox.mailbox_id, + Count = permissions.len(), + Elapsed = op_start.elapsed() + ); + data.write_bytes( StatusResponse::completed(Command::GetAcl) .with_tag(arguments.tag) @@ -131,6 +142,7 @@ impl Session { } pub async fn handle_my_rights(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); let arguments = request.parse_acl(self.version)?; let data = self.state.session_data(); let is_rev2 = self.version.is_rev2(); @@ -140,54 +152,69 @@ impl Session { .get_acl_mailbox(&arguments, false) .await .imap_ctx(&arguments.tag, trc::location!())?; + let rights = if access_token.is_shared(mailbox.account_id) { + let acl = values.inner.effective_acl(&access_token); + let mut rights = Vec::with_capacity(5); + if acl.contains(Acl::ReadItems) { + rights.push(Rights::Read); + rights.push(Rights::Lookup); + } + if acl.contains(Acl::AddItems) { + rights.push(Rights::Insert); + } + if acl.contains(Acl::RemoveItems) { + rights.push(Rights::DeleteMessages); + rights.push(Rights::Expunge); + } + if acl.contains(Acl::ModifyItems) { + rights.push(Rights::Seen); + rights.push(Rights::Write); + } + if acl.contains(Acl::CreateChild) { + rights.push(Rights::CreateMailbox); + } + if acl.contains(Acl::Delete) { + rights.push(Rights::DeleteMailbox); + } + if acl.contains(Acl::Submit) { + rights.push(Rights::Post); + } + rights + } else { + vec![ + Rights::Read, + Rights::Lookup, + Rights::Insert, + Rights::DeleteMessages, + Rights::Expunge, + Rights::Seen, + Rights::Write, + Rights::CreateMailbox, + Rights::DeleteMailbox, + Rights::Post, + ] + }; + + trc::event!( + Imap(trc::ImapEvent::MyRights), + SpanId = data.session_id, + Name = arguments.mailbox_name.clone(), + AccountId = mailbox.account_id, + MailboxId = mailbox.mailbox_id, + Details = rights + .iter() + .map(|r| trc::Value::String(r.to_string())) + .collect::>(), + Elapsed = op_start.elapsed() + ); + data.write_bytes( StatusResponse::completed(Command::MyRights) .with_tag(arguments.tag) .serialize( MyRightsResponse { mailbox_name: arguments.mailbox_name, - rights: if access_token.is_shared(mailbox.account_id) { - let acl = values.inner.effective_acl(&access_token); - let mut rights = Vec::with_capacity(5); - if acl.contains(Acl::ReadItems) { - rights.push(Rights::Read); - rights.push(Rights::Lookup); - } - if acl.contains(Acl::AddItems) { - rights.push(Rights::Insert); - } - if acl.contains(Acl::RemoveItems) { - rights.push(Rights::DeleteMessages); - rights.push(Rights::Expunge); - } - if acl.contains(Acl::ModifyItems) { - rights.push(Rights::Seen); - rights.push(Rights::Write); - } - if acl.contains(Acl::CreateChild) { - rights.push(Rights::CreateMailbox); - } - if acl.contains(Acl::Delete) { - rights.push(Rights::DeleteMailbox); - } - if acl.contains(Acl::Submit) { - rights.push(Rights::Post); - } - rights - } else { - vec![ - Rights::Read, - Rights::Lookup, - Rights::Insert, - Rights::DeleteMessages, - Rights::Expunge, - Rights::Seen, - Rights::Write, - Rights::CreateMailbox, - Rights::DeleteMailbox, - Rights::Post, - ] - }, + rights, } .into_bytes(is_rev2), ), @@ -197,6 +224,7 @@ impl Session { } pub async fn handle_set_acl(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); let command = request.command; let arguments = request.parse_acl(self.version)?; let data = self.state.session_data(); @@ -293,6 +321,11 @@ impl Session { } } + let grants = acl + .iter() + .map(|r| trc::Value::from(r.account_id)) + .collect::>(); + // Write changes let mailbox_id = mailbox.mailbox_id; let mut batch = BatchBuilder::new(); @@ -328,6 +361,16 @@ impl Session { // Invalidate ACLs data.jmap.inner.access_tokens.remove(&acl_account_id); + trc::event!( + Imap(trc::ImapEvent::SetAcl), + SpanId = data.session_id, + Name = arguments.mailbox_name.clone(), + AccountId = mailbox.account_id, + MailboxId = mailbox.mailbox_id, + Details = grants, + Elapsed = op_start.elapsed() + ); + data.write_bytes( StatusResponse::completed(command) .with_tag(arguments.tag) @@ -338,7 +381,16 @@ impl Session { } pub async fn handle_list_rights(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); let arguments = request.parse_acl(self.version)?; + + trc::event!( + Imap(trc::ImapEvent::ListRights), + SpanId = self.session_id, + Name = arguments.mailbox_name.clone(), + Elapsed = op_start.elapsed() + ); + self.write_bytes( StatusResponse::completed(Command::ListRights) .with_tag(arguments.tag) diff --git a/crates/imap/src/op/append.rs b/crates/imap/src/op/append.rs index 91f307e0..a889a009 100644 --- a/crates/imap/src/op/append.rs +++ b/crates/imap/src/op/append.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::sync::Arc; +use std::{sync::Arc, time::Instant}; use imap_proto::{ protocol::{append::Arguments, select::HighestModSeq}, @@ -25,6 +25,7 @@ use super::{ImapContext, ToModSeq}; impl Session { pub async fn handle_append(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); let arguments = request.parse_append(self.version)?; let (data, selected_mailbox) = self.state.session_mailbox_state(); @@ -47,7 +48,7 @@ impl Session { spawn_op!(data, { let response = data - .append_messages(arguments, selected_mailbox, mailbox, is_qresync) + .append_messages(arguments, selected_mailbox, mailbox, is_qresync, op_start) .await? .into_bytes(); @@ -63,6 +64,7 @@ impl SessionData { selected_mailbox: Option>, mailbox: MailboxId, is_qresync: bool, + op_start: Instant, ) -> trc::Result { // Verify ACLs let account_id = mailbox.account_id; @@ -142,6 +144,19 @@ impl SessionData { .await; } + trc::event!( + Imap(trc::ImapEvent::Append), + SpanId = self.session_id, + Name = arguments.mailbox_name.clone(), + AccountId = account_id, + MailboxId = mailbox_id, + DocumentId = created_ids + .iter() + .map(|r| trc::Value::from(r.id)) + .collect::>(), + Elapsed = op_start.elapsed() + ); + if !created_ids.is_empty() { let uids = created_ids.iter().map(|id| id.uid).collect(); let uid_validity = match selected_mailbox { diff --git a/crates/imap/src/op/authenticate.rs b/crates/imap/src/op/authenticate.rs index 387e1cc1..a68254af 100644 --- a/crates/imap/src/op/authenticate.rs +++ b/crates/imap/src/op/authenticate.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use common::{config::server::ServerProtocol, listener::SessionStream}; +use common::listener::SessionStream; use imap_proto::{ protocol::{authenticate::Mechanism, capability::Capability}, receiver::{self, Request}, @@ -78,7 +78,7 @@ impl Session { let access_token = match credentials { Credentials::Plain { username, secret } | Credentials::XOauth2 { username, secret } => { self.jmap - .authenticate_plain(&username, &secret, self.remote_addr, ServerProtocol::Imap) + .authenticate_plain(&username, &secret, self.remote_addr, self.session_id) .await } Credentials::OAuthBearer { token } => { diff --git a/crates/imap/src/op/capability.rs b/crates/imap/src/op/capability.rs index 72473545..e4814079 100644 --- a/crates/imap/src/op/capability.rs +++ b/crates/imap/src/op/capability.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use crate::core::Session; use common::listener::SessionStream; use imap_proto::{ @@ -17,6 +19,15 @@ use imap_proto::{ impl Session { pub async fn handle_capability(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); + trc::event!( + Imap(trc::ImapEvent::Capabilities), + SpanId = self.session_id, + Tls = self.is_tls, + Strict = !self.jmap.core.imap.allow_plain_auth, + Elapsed = op_start.elapsed() + ); + self.write_bytes( StatusResponse::completed(Command::Capability) .with_tag(request.tag) @@ -34,6 +45,13 @@ impl Session { } pub async fn handle_id(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); + trc::event!( + Imap(trc::ImapEvent::Id), + SpanId = self.session_id, + Elapsed = op_start.elapsed() + ); + self.write_bytes( StatusResponse::completed(Command::Id) .with_tag(request.tag) @@ -42,7 +60,7 @@ impl Session { "* ID (\"name\" \"Stalwart IMAP\" \"version\" \"", env!("CARGO_PKG_VERSION"), "\" \"vendor\" \"Stalwart Labs Ltd.\" ", - "\"support-url\" \"https://stalw.art/imap\")\r\n" + "\"support-url\" \"https://stalw.art\")\r\n" ) .as_bytes() .to_vec(), diff --git a/crates/imap/src/op/close.rs b/crates/imap/src/op/close.rs index 570f98c9..88f690a3 100644 --- a/crates/imap/src/op/close.rs +++ b/crates/imap/src/op/close.rs @@ -4,17 +4,32 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use crate::core::{Session, State}; use common::listener::SessionStream; use imap_proto::{receiver::Request, Command, StatusResponse}; +use trc::AddContext; impl Session { pub async fn handle_close(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); let (data, mailbox) = self.state.select_data(); + if mailbox.is_select { - data.expunge(mailbox, None).await.ok(); + data.expunge(mailbox.clone(), None, op_start) + .await + .caused_by(trc::location!())?; } + trc::event!( + Imap(trc::ImapEvent::Close), + SpanId = self.session_id, + AccountId = mailbox.id.account_id, + MailboxId = mailbox.id.mailbox_id, + Elapsed = op_start.elapsed() + ); + self.state = State::Authenticated { data }; self.write_bytes( StatusResponse::completed(Command::Close) diff --git a/crates/imap/src/op/copy_move.rs b/crates/imap/src/op/copy_move.rs index 1b7efacb..445e0796 100644 --- a/crates/imap/src/op/copy_move.rs +++ b/crates/imap/src/op/copy_move.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::sync::Arc; +use std::{sync::Arc, time::Instant}; use imap_proto::{ protocol::copy_move::Arguments, receiver::Request, Command, ResponseCode, ResponseType, @@ -38,6 +38,7 @@ impl Session { is_move: bool, is_uid: bool, ) -> trc::Result<()> { + let op_start = Instant::now(); let arguments = request.parse_copy_move(self.version)?; let (data, src_mailbox) = self.state.mailbox_state(); let is_qresync = self.is_qresync; @@ -78,6 +79,7 @@ impl Session { is_move, is_uid, is_qresync, + op_start, ) .await }) @@ -85,6 +87,7 @@ impl Session { } impl SessionData { + #[allow(clippy::too_many_arguments)] pub async fn copy_move( &self, arguments: Arguments, @@ -93,6 +96,7 @@ impl SessionData { is_move: bool, is_uid: bool, is_qresync: bool, + op_start: Instant, ) -> trc::Result<()> { // Convert IMAP ids to JMAP ids. let ids = src_mailbox @@ -247,6 +251,7 @@ impl SessionData { vec![dest_mailbox_id], Vec::new(), None, + self.session_id, ) .await .imap_ctx(&arguments.tag, trc::location!())? @@ -280,7 +285,7 @@ impl SessionData { self.email_untag_or_delete( src_account_id, src_mailbox.id.mailbox_id, - destroy_ids, + &destroy_ids, &mut changelog, ) .await @@ -348,6 +353,28 @@ impl SessionData { src_uids.sort_unstable(); dest_uids.sort_unstable(); + trc::event!( + Imap(if is_move { + trc::ImapEvent::Move + } else { + trc::ImapEvent::Copy + }), + SpanId = self.session_id, + SourceAccountId = src_mailbox.id.account_id, + SourceMailboxId = src_mailbox.id.mailbox_id, + SourceUid = src_uids + .iter() + .map(|r| trc::Value::from(*r)) + .collect::>(), + AccountId = dest_mailbox.account_id, + MailboxId = dest_mailbox.mailbox_id, + Uid = dest_uids + .iter() + .map(|r| trc::Value::from(*r)) + .collect::>(), + Elapsed = op_start.elapsed() + ); + let response = if is_move { self.write_bytes( StatusResponse::ok("Copied UIDs") diff --git a/crates/imap/src/op/create.rs b/crates/imap/src/op/create.rs index 05fa71dc..4d249f7c 100644 --- a/crates/imap/src/op/create.rs +++ b/crates/imap/src/op/create.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use crate::{ core::{Account, Mailbox, Session, SessionData}, op::ImapContext, @@ -53,6 +55,8 @@ impl Session { impl SessionData { pub async fn create_folder(&self, arguments: Arguments) -> trc::Result { + let op_start = Instant::now(); + // Refresh mailboxes self.synchronize_mailboxes(false) .await @@ -122,6 +126,18 @@ impl SessionData { ) .await; + trc::event!( + Imap(trc::ImapEvent::CreateMailbox), + SpanId = self.session_id, + Name = arguments.mailbox_name.clone(), + AccountId = params.account_id, + MailboxId = create_ids + .iter() + .map(|&id| trc::Value::from(id)) + .collect::>(), + Elapsed = op_start.elapsed() + ); + // Add created mailboxes to session std::mem::drop( self.add_created_mailboxes(&mut params, change_id, create_ids) diff --git a/crates/imap/src/op/delete.rs b/crates/imap/src/op/delete.rs index 29400f2b..2849507b 100644 --- a/crates/imap/src/op/delete.rs +++ b/crates/imap/src/op/delete.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use crate::{ core::{Session, SessionData}, spawn_op, @@ -44,6 +46,8 @@ impl Session { impl SessionData { pub async fn delete_folder(&self, arguments: Arguments) -> trc::Result { + let op_start = Instant::now(); + // Refresh mailboxes self.synchronize_mailboxes(false) .await @@ -111,6 +115,15 @@ impl SessionData { } } + trc::event!( + Imap(trc::ImapEvent::DeleteMailbox), + SpanId = self.session_id, + Name = arguments.mailbox_name, + AccountId = account_id, + MailboxId = mailbox_id, + Elapsed = op_start.elapsed() + ); + Ok(StatusResponse::ok("Mailbox deleted.").with_tag(arguments.tag)) } } diff --git a/crates/imap/src/op/enable.rs b/crates/imap/src/op/enable.rs index 4ddfb8e2..0ee178e4 100644 --- a/crates/imap/src/op/enable.rs +++ b/crates/imap/src/op/enable.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use crate::core::Session; use common::listener::SessionStream; use imap_proto::{ @@ -14,10 +16,13 @@ use imap_proto::{ impl Session { pub async fn handle_enable(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); + let arguments = request.parse_enable()?; let mut response = enable::Response { enabled: Vec::with_capacity(arguments.capabilities.len()), }; + for capability in arguments.capabilities { match capability { Capability::IMAP4rev2 => { @@ -41,6 +46,17 @@ impl Session { response.enabled.push(capability); } + trc::event!( + Imap(trc::ImapEvent::Enable), + SpanId = self.session_id, + Details = response + .enabled + .iter() + .map(|c| trc::Value::from(format!("{c:?}"))) + .collect::>(), + Elapsed = op_start.elapsed() + ); + self.write_bytes( StatusResponse::ok("ENABLE successful.") .with_tag(arguments.tag) diff --git a/crates/imap/src/op/expunge.rs b/crates/imap/src/op/expunge.rs index 4441a930..3576143b 100644 --- a/crates/imap/src/op/expunge.rs +++ b/crates/imap/src/op/expunge.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::sync::Arc; +use std::{sync::Arc, time::Instant}; use ahash::AHashMap; use imap_proto::{ @@ -34,6 +34,7 @@ impl Session { request: Request, is_uid: bool, ) -> trc::Result<()> { + let op_start = Instant::now(); let (data, mailbox) = self.state.select_data(); // Validate ACL @@ -78,7 +79,7 @@ impl Session { }; // Expunge - data.expunge(mailbox.clone(), sequence) + data.expunge(mailbox.clone(), sequence, op_start) .await .imap_ctx(&request.tag, trc::location!())?; @@ -108,6 +109,7 @@ impl SessionData { &self, mailbox: Arc, sequence: Option>, + op_start: Instant, ) -> trc::Result<()> { // Obtain message ids let account_id = mailbox.id.account_id; @@ -144,12 +146,21 @@ impl SessionData { self.email_untag_or_delete( account_id, mailbox.id.mailbox_id, - deleted_ids, + &deleted_ids, &mut changelog, ) .await .caused_by(trc::location!())?; + trc::event!( + Imap(trc::ImapEvent::Expunge), + SpanId = self.session_id, + AccountId = account_id, + MailboxId = mailbox.id.mailbox_id, + DocumentId = deleted_ids.iter().map(trc::Value::from).collect::>(), + Elapsed = op_start.elapsed() + ); + // Write changes on source account if !changelog.is_empty() { let change_id = self.jmap.commit_changes(account_id, changelog).await?; @@ -170,7 +181,7 @@ impl SessionData { &self, account_id: u32, mailbox_id: u32, - deleted_ids: RoaringBitmap, + deleted_ids: &RoaringBitmap, changelog: &mut ChangeLogBuilder, ) -> trc::Result<()> { let mailbox_id = UidMailbox::new_unassigned(mailbox_id); @@ -181,7 +192,7 @@ impl SessionData { .get_properties::>, _, _>( account_id, Collection::Email, - &deleted_ids, + deleted_ids, Property::MailboxIds, ) .await diff --git a/crates/imap/src/op/fetch.rs b/crates/imap/src/op/fetch.rs index f87f51cb..1b9d29b2 100644 --- a/crates/imap/src/op/fetch.rs +++ b/crates/imap/src/op/fetch.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::{borrow::Cow, sync::Arc}; +use std::{borrow::Cow, sync::Arc, time::Instant}; use crate::{ core::{SelectedMailbox, Session, SessionData}, @@ -44,6 +44,7 @@ impl Session { request: Request, is_uid: bool, ) -> trc::Result<()> { + let op_start = Instant::now(); let arguments = request.parse_fetch()?; let (data, mailbox) = self.state.select_data(); @@ -68,6 +69,7 @@ impl Session { is_qresync, is_rev2, enabled_condstore, + op_start, ) .await?; data.write_bytes(response.into_bytes()).await @@ -76,6 +78,7 @@ impl Session { } impl SessionData { + #[allow(clippy::too_many_arguments)] pub async fn fetch( &self, mut arguments: Arguments, @@ -84,6 +87,7 @@ impl SessionData { is_qresync: bool, _is_rev2: bool, enabled_condstore: bool, + op_start: Instant, ) -> trc::Result { // Validate VANISHED parameter if arguments.include_vanished { @@ -178,6 +182,15 @@ impl SessionData { ) .await?; } + + trc::event!( + Imap(trc::ImapEvent::Fetch), + SpanId = self.session_id, + AccountId = account_id, + MailboxId = mailbox.id.mailbox_id, + Elapsed = op_start.elapsed() + ); + return Ok( StatusResponse::completed(Command::Fetch(is_uid)).with_tag(arguments.tag) ); @@ -255,6 +268,11 @@ impl SessionData { .map(|(id, imap_id)| (imap_id.seqnum, imap_id.uid, id)) .collect::>(); ids.sort_unstable_by_key(|(seqnum, _, _)| *seqnum); + let fetched_ids = ids + .iter() + .map(|id| trc::Value::from(id.2)) + .collect::>(); + for (seqnum, uid, id) in ids { // Obtain attributes and keywords let (email, keywords) = if let (Some(email), Some(keywords)) = ( @@ -544,6 +562,20 @@ impl SessionData { } } + trc::event!( + Imap(trc::ImapEvent::Fetch), + SpanId = self.session_id, + AccountId = account_id, + MailboxId = mailbox.id.mailbox_id, + DocumentId = fetched_ids, + Details = arguments + .attributes + .iter() + .map(|c| trc::Value::from(format!("{c:?}"))) + .collect::>(), + Elapsed = op_start.elapsed() + ); + // Condstore was enabled with this command if enabled_condstore { self.write_bytes( diff --git a/crates/imap/src/op/idle.rs b/crates/imap/src/op/idle.rs index bb46a941..4699b1d4 100644 --- a/crates/imap/src/op/idle.rs +++ b/crates/imap/src/op/idle.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::sync::Arc; +use std::{sync::Arc, time::Instant}; use ahash::AHashSet; use imap_proto::{ @@ -32,6 +32,7 @@ use crate::{ impl Session { pub async fn handle_idle(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); let (data, mailbox, types) = match &self.state { State::Authenticated { data, .. } => { (data.clone(), None, Bitmap::from_iter([DataType::Mailbox])) @@ -57,8 +58,13 @@ impl Session { self.write_bytes(b"+ Idling, send 'DONE' to stop.\r\n".to_vec()) .await?; - trc::event!(Imap(trc::ImapEvent::IdleStart), SpanId = self.session_id); + trc::event!( + Imap(trc::ImapEvent::IdleStart), + SpanId = self.session_id, + Elapsed = op_start.elapsed() + ); + let op_start = Instant::now(); let mut buf = vec![0; 1024]; loop { tokio::select! { @@ -67,7 +73,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), SpanId = self.session_id); + trc::event!(Imap(trc::ImapEvent::IdleStop), SpanId = self.session_id, Elapsed = op_start.elapsed()); return self.write_bytes(StatusResponse::completed(Command::Idle) .with_tag(request.tag) .into_bytes()).await; @@ -215,6 +221,7 @@ impl SessionData { }; if !changed_ids.is_empty() { + let op_start = Instant::now(); return self .fetch( fetch::Arguments { @@ -234,6 +241,7 @@ impl SessionData { is_qresync, is_rev2, false, + op_start, ) .await .caused_by(trc::location!()) diff --git a/crates/imap/src/op/list.rs b/crates/imap/src/op/list.rs index 3db893ec..6d7e670b 100644 --- a/crates/imap/src/op/list.rs +++ b/crates/imap/src/op/list.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use crate::{ core::{Session, SessionData}, spawn_op, @@ -24,6 +26,7 @@ use super::ImapContext; impl Session { pub async fn handle_list(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); let command = request.command; let is_lsub = command == Command::Lsub; let arguments = if !is_lsub { @@ -36,7 +39,7 @@ impl Session { let data = self.state.session_data(); let version = self.version; - spawn_op!(data, data.list(arguments, is_lsub, version).await) + spawn_op!(data, data.list(arguments, is_lsub, version, op_start).await) } else { self.write_bytes( StatusResponse::completed(command) @@ -66,6 +69,7 @@ impl SessionData { arguments: Arguments, is_lsub: bool, version: ProtocolVersion, + op_start: Instant, ) -> trc::Result<()> { let (tag, reference_name, mut patterns, selection_options, return_options) = match arguments { @@ -256,6 +260,20 @@ impl SessionData { } } + trc::event!( + Imap(if !is_lsub { + trc::ImapEvent::List + } else { + trc::ImapEvent::Lsub + }), + SpanId = self.session_id, + Details = list_items + .iter() + .map(|item| trc::Value::from(item.mailbox_name.clone())) + .collect::>(), + Elapsed = op_start.elapsed() + ); + // Write response self.write_bytes( StatusResponse::completed(if !is_lsub { diff --git a/crates/imap/src/op/logout.rs b/crates/imap/src/op/logout.rs index 0e3c1f1a..9d16b095 100644 --- a/crates/imap/src/op/logout.rs +++ b/crates/imap/src/op/logout.rs @@ -4,12 +4,16 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use crate::core::Session; use common::listener::SessionStream; use imap_proto::{receiver::Request, Command, StatusResponse}; impl Session { pub async fn handle_logout(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); + let mut response = StatusResponse::bye( concat!( "Stalwart IMAP4rev2 v", @@ -19,6 +23,13 @@ impl Session { .to_string(), ) .into_bytes(); + + trc::event!( + Imap(trc::ImapEvent::Logout), + SpanId = self.session_id, + Elapsed = op_start.elapsed() + ); + response.extend( StatusResponse::completed(Command::Logout) .with_tag(request.tag) diff --git a/crates/imap/src/op/namespace.rs b/crates/imap/src/op/namespace.rs index fbd83ab8..3935955e 100644 --- a/crates/imap/src/op/namespace.rs +++ b/crates/imap/src/op/namespace.rs @@ -14,6 +14,12 @@ use imap_proto::{ impl Session { pub async fn handle_namespace(&mut self, request: Request) -> trc::Result<()> { + trc::event!( + Imap(trc::ImapEvent::Namespace), + SpanId = self.session_id, + Elapsed = trc::Value::Duration(0) + ); + self.write_bytes( StatusResponse::completed(Command::Namespace) .with_tag(request.tag) diff --git a/crates/imap/src/op/noop.rs b/crates/imap/src/op/noop.rs index 536dce7b..a13a342f 100644 --- a/crates/imap/src/op/noop.rs +++ b/crates/imap/src/op/noop.rs @@ -4,12 +4,16 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use crate::core::{Session, State}; use common::listener::SessionStream; use imap_proto::{receiver::Request, Command, StatusResponse}; impl Session { pub async fn handle_noop(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); + if let State::Selected { data, mailbox, .. } = &self.state { data.write_changes( &Some(mailbox.clone()), @@ -21,6 +25,12 @@ impl Session { .await?; } + trc::event!( + Imap(trc::ImapEvent::Noop), + SpanId = self.session_id, + Elapsed = op_start.elapsed() + ); + self.write_bytes( StatusResponse::completed(request.command) .with_tag(request.tag) diff --git a/crates/imap/src/op/rename.rs b/crates/imap/src/op/rename.rs index e061c554..1cfc3058 100644 --- a/crates/imap/src/op/rename.rs +++ b/crates/imap/src/op/rename.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::collections::BTreeMap; +use std::{collections::BTreeMap, time::Instant}; use crate::{ core::{Session, SessionData}, @@ -29,18 +29,23 @@ use super::ImapContext; impl Session { pub async fn handle_rename(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); let arguments = request.parse_rename(self.version)?; let data = self.state.session_data(); spawn_op!(data, { - let response = data.rename_folder(arguments).await?; + let response = data.rename_folder(arguments, op_start).await?; data.write_bytes(response.into_bytes()).await }) } } impl SessionData { - pub async fn rename_folder(&self, arguments: Arguments) -> trc::Result { + pub async fn rename_folder( + &self, + arguments: Arguments, + op_start: Instant, + ) -> trc::Result { // Refresh mailboxes self.synchronize_mailboxes(false) .await @@ -246,6 +251,16 @@ impl SessionData { } } + trc::event!( + Imap(trc::ImapEvent::RenameMailbox), + SpanId = self.session_id, + AccountId = params.account_id, + OldName = arguments.mailbox_name, + Name = arguments.new_mailbox_name, + MailboxId = mailbox_id, + Elapsed = op_start.elapsed() + ); + Ok(StatusResponse::completed(Command::Rename).with_tag(arguments.tag)) } } diff --git a/crates/imap/src/op/search.rs b/crates/imap/src/op/search.rs index 12d18152..3b5e699a 100644 --- a/crates/imap/src/op/search.rs +++ b/crates/imap/src/op/search.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::sync::Arc; +use std::{sync::Arc, time::Instant}; use common::listener::SessionStream; use imap_proto::{ @@ -41,6 +41,7 @@ impl Session { is_sort: bool, is_uid: bool, ) -> trc::Result<()> { + let op_start = Instant::now(); let mut arguments = if !is_sort { request.parse_search(self.version) } else { @@ -69,6 +70,7 @@ impl Session { results_tx, prev_saved_search.clone(), is_uid, + op_start, ) .await { @@ -103,6 +105,7 @@ impl SessionData { results_tx: Option>>>, prev_saved_search: Option>>>, is_uid: bool, + op_start: Instant, ) -> trc::Result { // Run query let (result_set, include_highest_modseq) = self @@ -205,6 +208,19 @@ impl SessionData { results_tx.send(saved_results).ok(); } + trc::event!( + Imap(if !is_sort { + trc::ImapEvent::Search + } else { + trc::ImapEvent::Sort + }), + SpanId = self.session_id, + AccountId = mailbox.id.account_id, + MailboxId = mailbox.id.mailbox_id, + Total = total, + Elapsed = op_start.elapsed() + ); + // Build response Ok(Response { is_uid, diff --git a/crates/imap/src/op/select.rs b/crates/imap/src/op/select.rs index d76a1607..20da1d5a 100644 --- a/crates/imap/src/op/select.rs +++ b/crates/imap/src/op/select.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::sync::Arc; +use std::{sync::Arc, time::Instant}; use imap_proto::{ protocol::{ @@ -26,6 +26,7 @@ use super::{ImapContext, ToModSeq}; impl Session { pub async fn handle_select(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); let is_select = request.command == Command::Select; let command = request.command; let arguments = request.parse_select(self.version)?; @@ -119,12 +120,25 @@ impl Session { true, is_rev2, false, + Instant::now(), ) .await .imap_ctx(&arguments.tag, trc::location!())?; } } + trc::event!( + Imap(trc::ImapEvent::Select), + SpanId = self.session_id, + Name = arguments.mailbox_name.clone(), + AccountId = mailbox.id.account_id, + MailboxId = mailbox.id.mailbox_id, + Total = total_messages, + UidNext = uid_next, + UidValidity = uid_validity, + Elapsed = op_start.elapsed() + ); + // Build response let response = Response { mailbox: ListItem::new(arguments.mailbox_name), diff --git a/crates/imap/src/op/status.rs b/crates/imap/src/op/status.rs index e418b494..78315892 100644 --- a/crates/imap/src/op/status.rs +++ b/crates/imap/src/op/status.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::sync::Arc; +use std::{sync::Arc, time::Instant}; use crate::{ core::{Mailbox, Session, SessionData}, @@ -34,6 +34,7 @@ use super::ToModSeq; impl Session { pub async fn handle_status(&mut self, request: Request) -> trc::Result<()> { + let op_start = Instant::now(); let arguments = request.parse_status(self.version)?; let version = self.version; let data = self.state.session_data(); @@ -49,6 +50,19 @@ impl Session { .status(arguments.mailbox_name, &arguments.items) .await .imap_ctx(&arguments.tag, trc::location!())?; + + trc::event!( + Imap(trc::ImapEvent::Status), + SpanId = data.session_id, + Name = status.mailbox_name.clone(), + Details = arguments + .items + .iter() + .map(|c| trc::Value::from(format!("{c:?}"))) + .collect::>(), + Elapsed = op_start.elapsed() + ); + let mut buf = Vec::with_capacity(32); status.serialize(&mut buf, version.is_rev2()); data.write_bytes( diff --git a/crates/imap/src/op/store.rs b/crates/imap/src/op/store.rs index f7ec4781..24b5b932 100644 --- a/crates/imap/src/op/store.rs +++ b/crates/imap/src/op/store.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::sync::Arc; +use std::{sync::Arc, time::Instant}; use crate::{ core::{message::MAX_RETRIES, SelectedMailbox, Session, SessionData}, @@ -39,13 +39,15 @@ impl Session { request: Request, is_uid: bool, ) -> trc::Result<()> { + let op_start = Instant::now(); let arguments = request.parse_store()?; - let (data, mailbox) = self.state.select_data(); let is_condstore = self.is_condstore || mailbox.is_condstore; spawn_op!(data, { - let response = data.store(arguments, mailbox, is_uid, is_condstore).await?; + let response = data + .store(arguments, mailbox, is_uid, is_condstore, op_start) + .await?; data.write_bytes(response).await }) @@ -59,6 +61,7 @@ impl SessionData { mailbox: Arc, is_uid: bool, is_condstore: bool, + op_start: Instant, ) -> trc::Result> { // Resync messages if needed let account_id = mailbox.id.account_id; @@ -152,6 +155,20 @@ impl SessionData { response = response.with_code(response_code) } if ids.is_empty() { + trc::event!( + Imap(trc::ImapEvent::Store), + SpanId = self.session_id, + AccountId = mailbox.id.account_id, + MailboxId = mailbox.id.mailbox_id, + Type = format!("{:?}", arguments.operation), + Details = arguments + .keywords + .iter() + .map(|c| trc::Value::from(format!("{c:?}"))) + .collect::>(), + Elapsed = op_start.elapsed() + ); + return Ok(response.into_bytes()); } let mut items = Response { @@ -161,12 +178,12 @@ impl SessionData { // Process each change let set_keywords = arguments .keywords - .into_iter() - .map(Keyword::from) + .iter() + .map(|k| Keyword::from(k.clone())) .collect::>(); let mut changelog = ChangeLogBuilder::new(); let mut changed_mailboxes = AHashSet::new(); - 'outer: for (id, imap_id) in ids { + 'outer: for (id, imap_id) in &ids { let mut try_count = 0; loop { // Obtain current keywords @@ -175,13 +192,13 @@ impl SessionData { .get_property::>>( account_id, Collection::Email, - id, + *id, Property::Keywords, ) .await .imap_ctx(response.tag.as_ref().unwrap(), trc::location!())?, self.jmap - .get_property::(account_id, Collection::Email, id, Property::ThreadId) + .get_property::(account_id, Collection::Email, *id, Property::ThreadId) .await .imap_ctx(response.tag.as_ref().unwrap(), trc::location!())?, ) { @@ -228,7 +245,7 @@ impl SessionData { batch .with_account_id(account_id) .with_collection(Collection::Email) - .update_document(id); + .update_document(*id); keywords.update_batch(&mut batch, Property::Keywords); if changelog.change_id == u64::MAX { changelog.change_id = self @@ -247,7 +264,7 @@ impl SessionData { .get_property::>( account_id, Collection::Email, - id, + *id, Property::MailboxIds, ) .await @@ -258,7 +275,7 @@ impl SessionData { } } } - changelog.log_update(Collection::Email, Id::from_parts(thread_id, id)); + changelog.log_update(Collection::Email, Id::from_parts(thread_id, *id)); // Add item to response let modseq = changelog.change_id + 1; @@ -329,6 +346,24 @@ impl SessionData { .await; } + trc::event!( + Imap(trc::ImapEvent::Store), + SpanId = self.session_id, + AccountId = mailbox.id.account_id, + MailboxId = mailbox.id.mailbox_id, + DocumentId = ids + .iter() + .map(|id| trc::Value::from(*id.0)) + .collect::>(), + Type = format!("{:?}", arguments.operation), + Details = arguments + .keywords + .iter() + .map(|c| trc::Value::from(format!("{c:?}"))) + .collect::>(), + Elapsed = op_start.elapsed() + ); + // Send response Ok(response.serialize(items.serialize())) } diff --git a/crates/imap/src/op/subscribe.rs b/crates/imap/src/op/subscribe.rs index b1cdebd3..075d4101 100644 --- a/crates/imap/src/op/subscribe.rs +++ b/crates/imap/src/op/subscribe.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use crate::{ core::{Session, SessionData}, spawn_op, @@ -28,12 +30,18 @@ impl Session { request: Request, is_subscribe: bool, ) -> trc::Result<()> { + let op_start = Instant::now(); let arguments = request.parse_subscribe(self.version)?; let data = self.state.session_data(); spawn_op!(data, { let response = data - .subscribe_folder(arguments.tag, arguments.mailbox_name, is_subscribe) + .subscribe_folder( + arguments.tag, + arguments.mailbox_name, + is_subscribe, + op_start, + ) .await?; data.write_bytes(response.into_bytes()).await @@ -47,6 +55,7 @@ impl SessionData { tag: String, mailbox_name: String, subscribe: bool, + op_start: Instant, ) -> trc::Result { // Refresh mailboxes self.synchronize_mailboxes(false) @@ -153,6 +162,19 @@ impl SessionData { } } + trc::event!( + Imap(if subscribe { + trc::ImapEvent::Subscribe + } else { + trc::ImapEvent::Unsubscribe + }), + SpanId = self.session_id, + AccountId = account_id, + MailboxId = mailbox_id, + Name = mailbox_name, + Elapsed = op_start.elapsed() + ); + Ok(StatusResponse::ok(if subscribe { "Mailbox subscribed." } else { diff --git a/crates/imap/src/op/thread.rs b/crates/imap/src/op/thread.rs index 307a941c..1c4738f3 100644 --- a/crates/imap/src/op/thread.rs +++ b/crates/imap/src/op/thread.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::sync::Arc; +use std::{sync::Arc, time::Instant}; use crate::{ core::{SelectedMailbox, Session, SessionData}, @@ -28,6 +28,7 @@ impl Session { request: Request, is_uid: bool, ) -> trc::Result<()> { + let op_start = Instant::now(); let command = request.command; let mut arguments = request.parse_thread()?; let (data, mailbox) = self.state.mailbox_state(); @@ -35,7 +36,7 @@ impl Session { spawn_op!(data, { let tag = std::mem::take(&mut arguments.tag); - match data.thread(arguments, mailbox, is_uid).await { + match data.thread(arguments, mailbox, is_uid, op_start).await { Ok(response) => { data.write_bytes( StatusResponse::completed(command) @@ -56,6 +57,7 @@ impl SessionData { arguments: Arguments, mailbox: Arc, is_uid: bool, + op_start: Instant, ) -> trc::Result { // Run query let (result_set, _) = self.query(arguments.filter, &mailbox, &None).await?; @@ -97,6 +99,15 @@ impl SessionData { .collect::>(); threads.sort_unstable(); + trc::event!( + Imap(trc::ImapEvent::Thread), + SpanId = self.session_id, + AccountId = mailbox.id.account_id, + MailboxId = mailbox.id.mailbox_id, + Count = threads.len(), + Elapsed = op_start.elapsed() + ); + // Build response Ok(Response { is_uid, threads }) } diff --git a/crates/jmap/src/api/http.rs b/crates/jmap/src/api/http.rs index 054cd426..edcc455e 100644 --- a/crates/jmap/src/api/http.rs +++ b/crates/jmap/src/api/http.rs @@ -65,7 +65,7 @@ impl JMAP { ("", &Method::POST) => { // Authenticate request let (_in_flight, access_token) = - self.authenticate_headers(&req, session.remote_ip).await?; + self.authenticate_headers(&req, &session).await?; let request = fetch_body( &mut req, @@ -94,7 +94,7 @@ impl JMAP { ("download", &Method::GET) => { // Authenticate request let (_in_flight, access_token) = - self.authenticate_headers(&req, session.remote_ip).await?; + self.authenticate_headers(&req, &session).await?; if let (Some(_), Some(blob_id), Some(name)) = ( path.next().and_then(|p| Id::from_bytes(p.as_bytes())), @@ -123,7 +123,7 @@ impl JMAP { ("upload", &Method::POST) => { // Authenticate request let (_in_flight, access_token) = - self.authenticate_headers(&req, session.remote_ip).await?; + self.authenticate_headers(&req, &session).await?; if let Some(account_id) = path.next().and_then(|p| Id::from_bytes(p.as_bytes())) @@ -158,14 +158,14 @@ impl JMAP { ("eventsource", &Method::GET) => { // Authenticate request let (_in_flight, access_token) = - self.authenticate_headers(&req, session.remote_ip).await?; + self.authenticate_headers(&req, &session).await?; return self.handle_event_source(req, access_token).await; } ("ws", &Method::GET) => { // Authenticate request let (_in_flight, access_token) = - self.authenticate_headers(&req, session.remote_ip).await?; + self.authenticate_headers(&req, &session).await?; return self .upgrade_websocket_connection(req, access_token, session) @@ -181,7 +181,7 @@ impl JMAP { ("jmap", &Method::GET) => { // Authenticate request let (_in_flight, access_token) = - self.authenticate_headers(&req, session.remote_ip).await?; + self.authenticate_headers(&req, &session).await?; return Ok(self .handle_session_resource( @@ -275,7 +275,7 @@ impl JMAP { } // Authenticate user - let (_, access_token) = self.authenticate_headers(&req, session.remote_ip).await?; + let (_, access_token) = self.authenticate_headers(&req, &session).await?; let body = fetch_body(&mut req, 1024 * 1024, session.session_id).await; return self .handle_api_manage_request(&req, body, access_token, &session) diff --git a/crates/jmap/src/api/request.rs b/crates/jmap/src/api/request.rs index 0c893cef..95ac2ed0 100644 --- a/crates/jmap/src/api/request.rs +++ b/crates/jmap/src/api/request.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::sync::Arc; +use std::{sync::Arc, time::Instant}; use jmap_proto::{ method::{ @@ -15,6 +15,7 @@ use jmap_proto::{ response::{Response, ResponseMethod}, types::collection::Collection, }; +use trc::JmapEvent; use crate::{auth::AccessToken, JMAP}; @@ -49,8 +50,15 @@ impl JMAP { let mut next_call = None; // Add response + let method_name = call.name.as_str(); match self - .handle_method_call(call.method, &access_token, &mut next_call, session) + .handle_method_call( + call.method, + method_name, + &access_token, + &mut next_call, + session, + ) .await { Ok(mut method_response) => { @@ -91,7 +99,10 @@ impl JMAP { Err(error) => { let method_error = error.clone(); - trc::error!(error.span_id(session.session_id)); + trc::error!(error + .span_id(session.session_id) + .ctx_unique(trc::Key::AccountId, access_token.primary_id()) + .caused_by(method_name)); response.push_error(call.id, method_error); } @@ -118,11 +129,13 @@ impl JMAP { async fn handle_method_call( &self, method: RequestMethod, + method_name: &'static str, access_token: &AccessToken, next_call: &mut Option>, session: &HttpSessionData, ) -> trc::Result { - Ok(match method { + let op_start = Instant::now(); + let response = match method { RequestMethod::Get(mut req) => match req.take_arguments() { get::RequestArguments::Email(arguments) => { access_token.assert_has_access(req.account_id, Collection::Email)?; @@ -261,7 +274,7 @@ impl JMAP { set::RequestArguments::SieveScript(arguments) => { access_token.assert_is_member(req.account_id)?; - self.sieve_script_set(req.with_arguments(arguments), access_token) + self.sieve_script_set(req.with_arguments(arguments), access_token, session) .await? .into() } @@ -277,7 +290,9 @@ impl JMAP { .assert_has_access(req.account_id, Collection::Email)? .assert_has_access(req.from_account_id, Collection::Email)?; - self.email_copy(req, access_token, next_call).await?.into() + self.email_copy(req, access_token, next_call, session) + .await? + .into() } RequestMethod::ImportEmail(req) => { access_token.assert_has_access(req.account_id, Collection::Email)?; @@ -317,6 +332,16 @@ impl JMAP { } RequestMethod::Echo(req) => req.into(), RequestMethod::Error(error) => return Err(error), - }) + }; + + trc::event!( + Jmap(JmapEvent::MethodCall), + Name = method_name, + SpanId = session.session_id, + AccountId = access_token.primary_id(), + Elapsed = op_start.elapsed(), + ); + + Ok(response) } } diff --git a/crates/jmap/src/auth/authenticate.rs b/crates/jmap/src/auth/authenticate.rs index fe20d9d6..b278941f 100644 --- a/crates/jmap/src/auth/authenticate.rs +++ b/crates/jmap/src/auth/authenticate.rs @@ -6,14 +6,14 @@ use std::{net::IpAddr, sync::Arc, time::Instant}; -use common::{config::server::ServerProtocol, listener::limiter::InFlight}; +use common::listener::limiter::InFlight; use directory::{Principal, QueryBy}; use hyper::header; use mail_parser::decoders::base64::base64_decode; use mail_send::Credentials; use utils::map::ttl_dashmap::TtlMap; -use crate::JMAP; +use crate::{api::http::HttpSessionData, JMAP}; use super::AccessToken; @@ -21,7 +21,7 @@ impl JMAP { pub async fn authenticate_headers( &self, req: &hyper::Request, - remote_ip: IpAddr, + session: &HttpSessionData, ) -> trc::Result<(InFlight, Arc)> { if let Some((mechanism, token)) = req .headers() @@ -34,7 +34,7 @@ impl JMAP { } else { let access_token = if mechanism.eq_ignore_ascii_case("basic") { // Enforce rate limit for authentication requests - self.is_auth_allowed_soft(&remote_ip).await?; + self.is_auth_allowed_soft(&session.remote_ip).await?; // Decode the base64 encoded credentials if let Some((account, secret)) = base64_decode(token.as_bytes()) @@ -45,8 +45,13 @@ impl JMAP { }) }) { - self.authenticate_plain(&account, &secret, remote_ip, ServerProtocol::Http) - .await? + self.authenticate_plain( + &account, + &secret, + session.remote_ip, + session.session_id, + ) + .await? } else { return Err(trc::AuthEvent::Error .into_err() @@ -56,7 +61,7 @@ impl JMAP { } } else if mechanism.eq_ignore_ascii_case("bearer") { // Enforce anonymous rate limit for bearer auth requests - self.is_anonymous_allowed(&remote_ip).await?; + self.is_anonymous_allowed(&session.remote_ip).await?; let (account_id, _, _) = self.validate_access_token("access_token", &token).await?; @@ -64,7 +69,7 @@ impl JMAP { self.get_access_token(account_id).await? } else { // Enforce anonymous rate limit - self.is_anonymous_allowed(&remote_ip).await?; + self.is_anonymous_allowed(&session.remote_ip).await?; return Err(trc::AuthEvent::Error .into_err() .reason("Unsupported authentication mechanism.") @@ -85,7 +90,7 @@ impl JMAP { .map(|in_flight| (in_flight, access_token)) } else { // Enforce anonymous rate limit - self.is_anonymous_allowed(&remote_ip).await?; + self.is_anonymous_allowed(&session.remote_ip).await?; Err(trc::AuthEvent::Error .into_err() @@ -128,19 +133,18 @@ impl JMAP { username: &str, secret: &str, remote_ip: IpAddr, - protocol: ServerProtocol, + session_id: u64, ) -> trc::Result { match self .core .authenticate( &self.core.storage.directory, - &self.smtp.inner.ipc, + session_id, &Credentials::Plain { username: username.to_string(), secret: secret.to_string(), }, remote_ip, - protocol, true, ) .await diff --git a/crates/jmap/src/email/copy.rs b/crates/jmap/src/email/copy.rs index cb6eaa9d..f3d1f7aa 100644 --- a/crates/jmap/src/email/copy.rs +++ b/crates/jmap/src/email/copy.rs @@ -41,7 +41,10 @@ use store::{ use trc::AddContext; use utils::map::vec_map::VecMap; -use crate::{auth::AccessToken, mailbox::UidMailbox, services::housekeeper::Event, JMAP}; +use crate::{ + api::http::HttpSessionData, auth::AccessToken, mailbox::UidMailbox, + services::housekeeper::Event, JMAP, +}; use super::{ index::{EmailIndexBuilder, TrimTextValue, VisitValues, MAX_ID_LENGTH, MAX_SORT_FIELD_LENGTH}, @@ -55,6 +58,7 @@ impl JMAP { request: CopyRequest, access_token: &AccessToken, next_call: &mut Option>, + session: &HttpSessionData, ) -> trc::Result { let account_id = request.account_id.document_id(); let from_account_id = request.from_account_id.document_id(); @@ -219,6 +223,7 @@ impl JMAP { mailboxes, keywords, received_at, + session.session_id, ) .await? { @@ -278,6 +283,7 @@ impl JMAP { mailboxes: Vec, keywords: Vec, received_at: Option, + session_id: u64, ) -> trc::Result> { // Obtain metadata let mut metadata = if let Some(metadata) = self @@ -298,11 +304,19 @@ impl JMAP { }; // Check quota - if !self + match self .has_available_quota(account_id, account_quota, metadata.size as i64) - .await? + .await { - return Ok(Err(SetError::over_quota())); + Ok(_) => (), + Err(err) => { + if err.matches(trc::EventType::Limit(trc::LimitEvent::Quota)) { + trc::error!(err.account_id(account_id).span_id(session_id)); + return Ok(Err(SetError::over_quota())); + } else { + return Err(err); + } + } } // Set receivedAt diff --git a/crates/jmap/src/email/crypto.rs b/crates/jmap/src/email/crypto.rs index bbff83aa..3c864d0f 100644 --- a/crates/jmap/src/email/crypto.rs +++ b/crates/jmap/src/email/crypto.rs @@ -170,7 +170,7 @@ impl EncryptMessage for Message<'_> { .supported() .alive() .revoked(false) - .key_flags(&KeyFlags::empty().set_transport_encryption()) + .key_flags(KeyFlags::empty().set_transport_encryption()) { keys.push(key); } @@ -449,7 +449,7 @@ fn has_pgp_keys(cert: openpgp::Cert) -> bool { .supported() .alive() .revoked(false) - .key_flags(&KeyFlags::empty().set_transport_encryption()) + .key_flags(KeyFlags::empty().set_transport_encryption()) .next() .is_some() } diff --git a/crates/jmap/src/email/ingest.rs b/crates/jmap/src/email/ingest.rs index 20604227..1ab80662 100644 --- a/crates/jmap/src/email/ingest.rs +++ b/crates/jmap/src/email/ingest.rs @@ -6,7 +6,6 @@ use std::{borrow::Cow, time::Duration}; -use common::webhooks::{WebhookIngestSource, WebhookPayload, WebhookType}; use jmap_proto::{ object::Object, types::{ @@ -80,13 +79,9 @@ impl JMAP { pub async fn email_ingest(&self, mut params: IngestEmail<'_>) -> trc::Result { // Check quota let mut raw_message_len = params.raw_message.len() as i64; - if !self - .has_available_quota(params.account_id, params.account_quota, raw_message_len) + self.has_available_quota(params.account_id, params.account_quota, raw_message_len) .await - .caused_by(trc::location!())? - { - return Err(trc::LimitEvent::Quota.into_err()); - } + .caused_by(trc::location!())?; // Parse message let mut raw_message = Cow::from(params.raw_message); @@ -166,6 +161,13 @@ impl JMAP { .results .is_empty() { + trc::event!( + Store(trc::StoreEvent::IngestDuplicate), + SpanId = params.session_id, + AccountId = params.account_id, + MessageId = message_id.to_string(), + ); + return Ok(IngestedEmail { id: Id::default(), change_id: u64::MAX, @@ -334,31 +336,6 @@ impl JMAP { Size = raw_message_len as u64, ); - // Send webhook event - if self - .core - .has_webhook_subscribers(WebhookType::MessageAppended) - { - self.smtp - .inner - .ipc - .send_webhook( - WebhookType::MessageAppended, - WebhookPayload::MessageAppended { - account_id: params.account_id, - mailbox_ids: params.mailbox_ids, - source: match params.source { - IngestSource::Smtp => WebhookIngestSource::Smtp, - IngestSource::Jmap => WebhookIngestSource::Jmap, - IngestSource::Imap => WebhookIngestSource::Imap, - }, - encrypt: params.encrypt, - size: raw_message_len as usize, - }, - ) - .await; - } - Ok(IngestedEmail { id, change_id, diff --git a/crates/jmap/src/lib.rs b/crates/jmap/src/lib.rs index 36977692..c6f12906 100644 --- a/crates/jmap/src/lib.rs +++ b/crates/jmap/src/lib.rs @@ -12,11 +12,7 @@ use std::{ }; use auth::{rate_limit::ConcurrencyLimiters, AccessToken}; -use common::{ - manager::webadmin::WebAdminManager, - webhooks::{WebhookPayload, WebhookType}, - Core, DeliveryEvent, SharedCore, -}; +use common::{manager::webadmin::WebAdminManager, Core, DeliveryEvent, SharedCore}; use dashmap::DashMap; use directory::QueryBy; use email::cache::Threads; @@ -345,36 +341,22 @@ impl JMAP { account_id: u32, account_quota: i64, item_size: i64, - ) -> trc::Result { + ) -> trc::Result<()> { if account_quota == 0 { - return Ok(true); - } - let used_quota = self.get_used_quota(account_id).await?; - if used_quota + item_size <= account_quota { - Ok(true) - } else { - // Send webhook - if self - .core - .has_webhook_subscribers(WebhookType::AccountOverQuota) - { - self.smtp - .inner - .ipc - .send_webhook( - WebhookType::AccountOverQuota, - WebhookPayload::AccountOverQuota { - account_id, - quota_limit: account_quota as usize, - quota_used: used_quota as usize, - object_size: item_size as usize, - }, - ) - .await; - } - - Ok(false) + return Ok(()); } + self.get_used_quota(account_id) + .await + .and_then(|used_quota| { + if used_quota + item_size <= account_quota { + Ok(()) + } else { + Err(trc::LimitEvent::Quota + .into_err() + .ctx(trc::Key::Limit, account_quota as u64) + .ctx(trc::Key::Used, used_quota as u64)) + } + }) } pub async fn filter( diff --git a/crates/jmap/src/services/index.rs b/crates/jmap/src/services/index.rs index c20fe3b3..dfaaa9e8 100644 --- a/crates/jmap/src/services/index.rs +++ b/crates/jmap/src/services/index.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use jmap_proto::types::{collection::Collection, property::Property}; use store::{ fts::index::FtsDocument, @@ -89,6 +91,7 @@ impl JMAP { // Add entries to the index for event in entries { + let op_start = Instant::now(); // Lock index if !self.try_lock_index(&event).await { continue; @@ -142,7 +145,9 @@ impl JMAP { trc::event!( FtsIndex(FtsIndexEvent::Index), AccountId = event.account_id, + Collection = Collection::Email, DocumentId = event.document_id, + Elapsed = op_start.elapsed(), ); } diff --git a/crates/jmap/src/services/ingest.rs b/crates/jmap/src/services/ingest.rs index 02229d44..70074de0 100644 --- a/crates/jmap/src/services/ingest.rs +++ b/crates/jmap/src/services/ingest.rs @@ -32,6 +32,7 @@ impl JMAP { Store(trc::StoreEvent::IngestError), Reason = "Blob not found.", SpanId = message.session_id, + CausedBy = trc::location!() ); return (0..message.recipients.len()) @@ -43,7 +44,8 @@ impl JMAP { Err(err) => { trc::error!(err .details("Failed to fetch message blob.") - .span_id(message.session_id)); + .span_id(message.session_id) + .caused_by(trc::location!())); return (0..message.recipients.len()) .map(|_| DeliveryResult::TemporaryFailure { @@ -72,7 +74,8 @@ impl JMAP { trc::error!(err .details("Failed to lookup recipient.") .ctx(trc::Key::To, rcpt.to_string()) - .span_id(message.session_id)); + .span_id(message.session_id) + .caused_by(trc::location!())); recipients.push(vec![]); } } @@ -103,7 +106,13 @@ impl JMAP { { Ok(Some(p)) => p.quota as i64, Ok(None) => 0, - Err(_) => { + Err(err) => { + trc::error!(err + .details("Failed to obtain account quota.") + .ctx(trc::Key::To, rcpt.to_string()) + .span_id(message.session_id) + .caused_by(trc::location!())); + *status = DeliveryResult::TemporaryFailure { reason: "Transient server failure.".into(), }; diff --git a/crates/jmap/src/sieve/set.rs b/crates/jmap/src/sieve/set.rs index ea83a8f4..5faa2b82 100644 --- a/crates/jmap/src/sieve/set.rs +++ b/crates/jmap/src/sieve/set.rs @@ -33,7 +33,7 @@ use store::{ BlobClass, }; -use crate::{auth::AccessToken, JMAP}; +use crate::{api::http::HttpSessionData, auth::AccessToken, JMAP}; struct SetContext<'x> { account_id: u32, @@ -58,6 +58,7 @@ impl JMAP { &self, mut request: SetRequest, access_token: &AccessToken, + session: &HttpSessionData, ) -> trc::Result { let account_id = request.account_id.document_id(); let mut sieve_ids = self @@ -78,7 +79,10 @@ impl JMAP { let mut changes = ChangeLogBuilder::new(); for (id, object) in request.unwrap_create() { if sieve_ids.len() as usize <= self.core.jmap.sieve_max_scripts { - match self.sieve_set_item(object, None, &ctx).await? { + match self + .sieve_set_item(object, None, &ctx, session.session_id) + .await? + { Ok((mut builder, Some(blob))) => { // Store blob let blob_id = builder.changes_mut().unwrap().blob_id_mut().unwrap(); @@ -167,7 +171,12 @@ impl JMAP { .clone(); match self - .sieve_set_item(object, (document_id, sieve).into(), &ctx) + .sieve_set_item( + object, + (document_id, sieve).into(), + &ctx, + session.session_id, + ) .await? { Ok((mut builder, blob)) => { @@ -384,6 +393,7 @@ impl JMAP { changes_: Object, update: Option<(u32, HashedValue>)>, ctx: &SetContext<'_>, + session_id: u64, ) -> trc::Result>), SetError>> { // Vacation script cannot be modified if matches!(update.as_ref().and_then(|(_, obj)| obj.inner.properties.get(&Property::Name)), Some(Value::Text ( value )) if value.eq_ignore_ascii_case("vacation")) @@ -488,11 +498,18 @@ impl JMAP { // Check access if let Some(mut bytes) = self.blob_download(&blob_id, ctx.access_token).await? { // Check quota - if !self + match self .has_available_quota(ctx.account_id, ctx.account_quota, bytes.len() as i64) - .await? - { - return Ok(Err(SetError::over_quota())); + .await { + Ok(_) => (), + Err(err) => { + if err.matches(trc::EventType::Limit(trc::LimitEvent::Quota)) { + trc::error!(err.account_id(ctx.account_id).span_id(session_id)); + return Ok(Err(SetError::over_quota())); + } else { + return Err(err); + } + }, } // Compile script diff --git a/crates/main/Cargo.toml b/crates/main/Cargo.toml index 52781d2a..346094e1 100644 --- a/crates/main/Cargo.toml +++ b/crates/main/Cargo.toml @@ -37,7 +37,7 @@ jemallocator = "0.5.0" default = ["sqlite", "postgres", "mysql", "rocks", "elastic", "s3", "redis", "enterprise"] #default = ["sqlite", "postgres", "mysql", "rocks", "elastic", "s3", "redis", "foundationdb", "enterprise"] sqlite = ["store/sqlite"] -foundationdb = ["store/foundation"] +foundationdb = ["store/foundation", "common/foundation"] postgres = ["store/postgres"] mysql = ["store/mysql"] rocks = ["store/rocks"] diff --git a/crates/main/src/main.rs b/crates/main/src/main.rs index 879963f9..9d0688a9 100644 --- a/crates/main/src/main.rs +++ b/crates/main/src/main.rs @@ -6,10 +6,7 @@ use std::time::Duration; -use common::{ - config::server::ServerProtocol, manager::boot::BootManager, - webhooks::manager::spawn_webhook_manager, Ipc, IPC_CHANNEL_BUFFER, -}; +use common::{config::server::ServerProtocol, manager::boot::BootManager, Ipc, IPC_CHANNEL_BUFFER}; use imap::core::{ImapSessionManager, IMAP}; use jmap::{api::JmapSessionManager, services::gossip::spawn::GossiperBuilder, JMAP}; use managesieve::core::ManageSieveSessionManager; @@ -34,15 +31,9 @@ async fn main() -> std::io::Result<()> { let mut config = init.config; let core = init.core; - // Spawn webhook manager - let webhook_tx = spawn_webhook_manager(core.clone()); - // Setup IPC channels let (delivery_tx, delivery_rx) = mpsc::channel(IPC_CHANNEL_BUFFER); - let ipc = Ipc { - delivery_tx, - webhook_tx, - }; + let ipc = Ipc { delivery_tx }; // Init servers let smtp = SMTP::init(&mut config, core.clone(), ipc).await; diff --git a/crates/managesieve/src/core/client.rs b/crates/managesieve/src/core/client.rs index 38a192a5..2380e8ef 100644 --- a/crates/managesieve/src/core/client.rs +++ b/crates/managesieve/src/core/client.rs @@ -192,7 +192,7 @@ impl Session { ManageSieve(trc::ManageSieveEvent::RawOutput), SpanId = self.session_id, Size = bytes.len(), - Contents = String::from_utf8_lossy(bytes).into_owned(), + Contents = trc::Value::from_maybe_string(bytes), ); self.stream.write_all(bytes).await.map_err(|err| { @@ -230,7 +230,7 @@ impl Session { ManageSieve(trc::ManageSieveEvent::RawInput), SpanId = self.session_id, Size = len, - Contents = String::from_utf8_lossy(bytes.get(0..len).unwrap_or_default()).into_owned(), + Contents = trc::Value::from_maybe_string(bytes.get(0..len).unwrap_or_default()), ); Ok(len) diff --git a/crates/managesieve/src/op/authenticate.rs b/crates/managesieve/src/op/authenticate.rs index 5755d04d..80e7b298 100644 --- a/crates/managesieve/src/op/authenticate.rs +++ b/crates/managesieve/src/op/authenticate.rs @@ -4,10 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use common::{ - config::server::ServerProtocol, - listener::{limiter::ConcurrencyLimiter, SessionStream}, -}; +use common::listener::{limiter::ConcurrencyLimiter, SessionStream}; use imap::op::authenticate::{decode_challenge_oauth, decode_challenge_plain}; use imap_proto::{ protocol::authenticate::Mechanism, @@ -74,12 +71,7 @@ impl Session { let access_token = match credentials { Credentials::Plain { username, secret } | Credentials::XOauth2 { username, secret } => { self.jmap - .authenticate_plain( - &username, - &secret, - self.remote_addr, - ServerProtocol::ManageSieve, - ) + .authenticate_plain(&username, &secret, self.remote_addr, self.session_id) .await } Credentials::OAuthBearer { token } => { @@ -140,6 +132,12 @@ impl Session { pub async fn handle_unauthenticate(&mut self) -> trc::Result> { self.state = State::NotAuthenticated { auth_failures: 0 }; + trc::event!( + ManageSieve(trc::ManageSieveEvent::Unauthenticate), + SpanId = self.session_id, + Elapsed = trc::Value::Duration(0) + ); + Ok(StatusResponse::ok("Unauthenticate successful.").into_bytes()) } diff --git a/crates/managesieve/src/op/capability.rs b/crates/managesieve/src/op/capability.rs index 82c2e092..13f825db 100644 --- a/crates/managesieve/src/op/capability.rs +++ b/crates/managesieve/src/op/capability.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use common::listener::SessionStream; use jmap_proto::request::capability::Capabilities; @@ -11,6 +13,8 @@ use crate::core::{Session, StatusResponse}; impl Session { pub async fn handle_capability(&self, message: &'static str) -> trc::Result> { + let op_start = Instant::now(); + let mut response = Vec::with_capacity(128); response.extend_from_slice(b"\"IMPLEMENTATION\" \"Stalwart ManageSieve\"\r\n"); response.extend_from_slice(b"\"VERSION\" \"1.0\"\r\n"); @@ -54,6 +58,14 @@ impl Session { response.extend_from_slice(b"\"SIEVE\" \"\"\r\n"); } + trc::event!( + ManageSieve(trc::ManageSieveEvent::Capabilities), + SpanId = self.session_id, + Tls = self.stream.is_tls(), + Strict = !self.jmap.core.imap.allow_plain_auth, + Elapsed = op_start.elapsed() + ); + Ok(StatusResponse::ok(message).serialize(response)) } } diff --git a/crates/managesieve/src/op/checkscript.rs b/crates/managesieve/src/op/checkscript.rs index 229903af..c014ea0b 100644 --- a/crates/managesieve/src/op/checkscript.rs +++ b/crates/managesieve/src/op/checkscript.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use imap_proto::receiver::Request; use tokio::io::{AsyncRead, AsyncWrite}; @@ -11,18 +13,34 @@ use crate::core::{Command, Session, StatusResponse}; impl Session { pub async fn handle_checkscript(&mut self, request: Request) -> trc::Result> { + let op_start = Instant::now(); + if request.tokens.is_empty() { return Err(trc::ManageSieveEvent::Error .into_err() .details("Expected script as a parameter.")); } + let script = request.tokens.into_iter().next().unwrap().unwrap_bytes(); self.jmap .core .sieve .untrusted_compiler - .compile(&request.tokens.into_iter().next().unwrap().unwrap_bytes()) - .map(|_| StatusResponse::ok("Script is valid.").into_bytes()) - .map_err(|err| trc::ManageSieveEvent::Error.into_err().details(err.to_string())) + .compile(&script) + .map(|_| { + trc::event!( + ManageSieve(trc::ManageSieveEvent::CheckScript), + SpanId = self.session_id, + Size = script.len(), + Elapsed = op_start.elapsed() + ); + + StatusResponse::ok("Script is valid.").into_bytes() + }) + .map_err(|err| { + trc::ManageSieveEvent::Error + .into_err() + .details(err.to_string()) + }) } } diff --git a/crates/managesieve/src/op/deletescript.rs b/crates/managesieve/src/op/deletescript.rs index 5f935db9..f7a79d3e 100644 --- a/crates/managesieve/src/op/deletescript.rs +++ b/crates/managesieve/src/op/deletescript.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use imap_proto::receiver::Request; use jmap_proto::types::collection::Collection; use store::write::log::ChangeLogBuilder; @@ -14,6 +16,8 @@ use crate::core::{Command, ResponseCode, Session, StatusResponse}; impl Session { pub async fn handle_deletescript(&mut self, request: Request) -> trc::Result> { + let op_start = Instant::now(); + let name = request .tokens .into_iter() @@ -41,6 +45,14 @@ impl Session { .await .caused_by(trc::location!())?; + trc::event!( + ManageSieve(trc::ManageSieveEvent::DeleteScript), + SpanId = self.session_id, + Name = name, + DocumentId = document_id, + Elapsed = op_start.elapsed() + ); + Ok(StatusResponse::ok("Deleted.").into_bytes()) } else { Err(trc::ManageSieveEvent::Error diff --git a/crates/managesieve/src/op/getscript.rs b/crates/managesieve/src/op/getscript.rs index 7c578913..fcb60f33 100644 --- a/crates/managesieve/src/op/getscript.rs +++ b/crates/managesieve/src/op/getscript.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use imap_proto::receiver::Request; use jmap::sieve::set::ObjectBlobId; use jmap_proto::{ @@ -17,6 +19,7 @@ use crate::core::{Command, ResponseCode, Session, StatusResponse}; impl Session { pub async fn handle_getscript(&mut self, request: Request) -> trc::Result> { + let op_start = Instant::now(); let name = request .tokens .into_iter() @@ -73,6 +76,14 @@ impl Session { response.extend(script); response.extend_from_slice(b"\r\n"); + trc::event!( + ManageSieve(trc::ManageSieveEvent::GetScript), + SpanId = self.session_id, + Name = name, + DocumentId = document_id, + Elapsed = op_start.elapsed() + ); + Ok(StatusResponse::ok("").serialize(response)) } } diff --git a/crates/managesieve/src/op/havespace.rs b/crates/managesieve/src/op/havespace.rs index d9e61d35..05eeb59e 100644 --- a/crates/managesieve/src/op/havespace.rs +++ b/crates/managesieve/src/op/havespace.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use imap_proto::receiver::Request; use tokio::io::{AsyncRead, AsyncWrite}; use trc::AddContext; @@ -12,6 +14,7 @@ use crate::core::{Command, ResponseCode, Session, StatusResponse}; impl Session { pub async fn handle_havespace(&mut self, request: Request) -> trc::Result> { + let op_start = Instant::now(); let mut tokens = request.tokens.into_iter(); let name = tokens .next() @@ -51,6 +54,13 @@ impl Session { .caused_by(trc::location!())? <= access_token.quota as i64 { + trc::event!( + ManageSieve(trc::ManageSieveEvent::HaveSpace), + SpanId = self.session_id, + Size = size, + Elapsed = op_start.elapsed() + ); + Ok(StatusResponse::ok("").into_bytes()) } else { Err(trc::ManageSieveEvent::Error diff --git a/crates/managesieve/src/op/listscripts.rs b/crates/managesieve/src/op/listscripts.rs index 93e9653b..5d3b004e 100644 --- a/crates/managesieve/src/op/listscripts.rs +++ b/crates/managesieve/src/op/listscripts.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use jmap_proto::{ object::Object, types::{collection::Collection, property::Property, value::Value}, @@ -15,6 +17,7 @@ use crate::core::{Session, StatusResponse}; impl Session { pub async fn handle_listscripts(&mut self) -> trc::Result> { + let op_start = Instant::now(); let account_id = self.state.access_token().primary_id(); let document_ids = self .jmap @@ -28,6 +31,7 @@ impl Session { } let mut response = Vec::with_capacity(128); + let count = document_ids.len(); for document_id in document_ids { if let Some(script) = self @@ -59,6 +63,13 @@ impl Session { } } + trc::event!( + ManageSieve(trc::ManageSieveEvent::ListScripts), + SpanId = self.session_id, + Total = count, + Elapsed = op_start.elapsed() + ); + Ok(StatusResponse::ok("").serialize(response)) } } diff --git a/crates/managesieve/src/op/logout.rs b/crates/managesieve/src/op/logout.rs index 05550827..73b3c7c0 100644 --- a/crates/managesieve/src/op/logout.rs +++ b/crates/managesieve/src/op/logout.rs @@ -10,6 +10,12 @@ use crate::core::{Session, StatusResponse}; impl Session { pub async fn handle_logout(&mut self) -> trc::Result> { + trc::event!( + ManageSieve(trc::ManageSieveEvent::Logout), + SpanId = self.session_id, + Elapsed = trc::Value::Duration(0) + ); + Ok(StatusResponse::ok(concat!( "Stalwart ManageSieve v", env!("CARGO_PKG_VERSION"), diff --git a/crates/managesieve/src/op/mod.rs b/crates/managesieve/src/op/mod.rs index ff3808f4..bd92df4d 100644 --- a/crates/managesieve/src/op/mod.rs +++ b/crates/managesieve/src/op/mod.rs @@ -23,6 +23,12 @@ pub mod setactive; impl Session { pub async fn handle_start_tls(&self) -> trc::Result> { + trc::event!( + ManageSieve(trc::ManageSieveEvent::StartTls), + SpanId = self.session_id, + Elapsed = trc::Value::Duration(0) + ); + Ok(StatusResponse::ok("Begin TLS negotiation now").into_bytes()) } } diff --git a/crates/managesieve/src/op/noop.rs b/crates/managesieve/src/op/noop.rs index c1d13669..74f5f66c 100644 --- a/crates/managesieve/src/op/noop.rs +++ b/crates/managesieve/src/op/noop.rs @@ -11,6 +11,12 @@ use crate::core::{Command, ResponseCode, Session, StatusResponse}; impl Session { pub async fn handle_noop(&mut self, request: Request) -> trc::Result> { + trc::event!( + ManageSieve(trc::ManageSieveEvent::Noop), + SpanId = self.session_id, + Elapsed = trc::Value::Duration(0) + ); + Ok(if let Some(tag) = request .tokens .into_iter() diff --git a/crates/managesieve/src/op/putscript.rs b/crates/managesieve/src/op/putscript.rs index 2181532e..67236742 100644 --- a/crates/managesieve/src/op/putscript.rs +++ b/crates/managesieve/src/op/putscript.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use imap_proto::receiver::Request; use jmap::sieve::set::{ObjectBlobId, SCHEMA}; use jmap_proto::{ @@ -23,6 +25,7 @@ use crate::core::{Command, ResponseCode, Session, StatusResponse}; impl Session { pub async fn handle_putscript(&mut self, request: Request) -> trc::Result> { + let op_start = Instant::now(); let mut tokens = request.tokens.into_iter(); let name = tokens .next() @@ -47,21 +50,14 @@ impl Session { // Check quota let access_token = self.state.access_token(); let account_id = access_token.primary_id(); - if !self - .jmap + self.jmap .has_available_quota( account_id, access_token.quota as i64, script_bytes.len() as i64, ) .await - .caused_by(trc::location!())? - { - return Err(trc::ManageSieveEvent::Error - .into_err() - .details("Quota exceeded.") - .code(ResponseCode::Quota)); - } + .caused_by(trc::location!())?; if self .jmap @@ -96,7 +92,9 @@ impl Session { .details(err.to_string()) .code(ResponseCode::QuotaMaxSize) } else { - trc::ManageSieveEvent::Error.into_err().details(err.to_string()) + trc::ManageSieveEvent::Error + .into_err() + .details(err.to_string()) }); } } @@ -181,6 +179,16 @@ impl Session { .write_batch(batch) .await .caused_by(trc::location!())?; + + trc::event!( + ManageSieve(trc::ManageSieveEvent::UpdateScript), + SpanId = self.session_id, + Name = name.to_string(), + DocumentId = document_id, + Size = script_size, + Elapsed = op_start.elapsed(), + + ); } else { // Write script blob let blob_id = BlobId::new( @@ -213,15 +221,24 @@ impl Session { .custom( ObjectIndexBuilder::new(SCHEMA).with_changes( Object::with_capacity(3) - .with_property(Property::Name, name) + .with_property(Property::Name, name.clone()) .with_property(Property::IsActive, Value::Bool(false)) .with_property(Property::BlobId, Value::BlobId(blob_id)), ), ); - self.jmap + let assigned_ids = self + .jmap .write_batch(batch) .await .caused_by(trc::location!())?; + + trc::event!( + ManageSieve(trc::ManageSieveEvent::CreateScript), + SpanId = self.session_id, + Name = name, + DocumentId = assigned_ids.last_document_id().ok(), + Elapsed = op_start.elapsed() + ); } Ok(StatusResponse::ok("Success.").into_bytes()) diff --git a/crates/managesieve/src/op/renamescript.rs b/crates/managesieve/src/op/renamescript.rs index b8f76c1b..2c283b0e 100644 --- a/crates/managesieve/src/op/renamescript.rs +++ b/crates/managesieve/src/op/renamescript.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use imap_proto::receiver::Request; use jmap::sieve::set::SCHEMA; use jmap_proto::{ @@ -18,6 +20,7 @@ use crate::core::{Command, ResponseCode, Session, StatusResponse}; impl Session { pub async fn handle_renamescript(&mut self, request: Request) -> trc::Result> { + let op_start = Instant::now(); let mut tokens = request.tokens.into_iter(); let name = tokens .next() @@ -80,7 +83,9 @@ impl Session { .custom( ObjectIndexBuilder::new(SCHEMA) .with_current(script) - .with_changes(Object::with_capacity(1).with_property(Property::Name, new_name)), + .with_changes( + Object::with_capacity(1).with_property(Property::Name, new_name.clone()), + ), ); if !batch.is_empty() { self.jmap @@ -95,6 +100,15 @@ impl Session { .caused_by(trc::location!())?; } + trc::event!( + ManageSieve(trc::ManageSieveEvent::RenameScript), + SpanId = self.session_id, + OldName = name, + Name = new_name, + DocumentId = document_id, + Elapsed = op_start.elapsed() + ); + Ok(StatusResponse::ok("Success.").into_bytes()) } } diff --git a/crates/managesieve/src/op/setactive.rs b/crates/managesieve/src/op/setactive.rs index 59a32d2b..6e87cce4 100644 --- a/crates/managesieve/src/op/setactive.rs +++ b/crates/managesieve/src/op/setactive.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use imap_proto::receiver::Request; use jmap_proto::types::collection::Collection; use store::write::log::ChangeLogBuilder; @@ -14,6 +16,7 @@ use crate::core::{Command, Session, StatusResponse}; impl Session { pub async fn handle_setactive(&mut self, request: Request) -> trc::Result> { + let op_start = Instant::now(); let name = request .tokens .into_iter() @@ -51,6 +54,14 @@ impl Session { .await .caused_by(trc::location!())?; } + + trc::event!( + ManageSieve(trc::ManageSieveEvent::SetActive), + SpanId = self.session_id, + Name = name, + Elapsed = op_start.elapsed() + ); + Ok(StatusResponse::ok("Success").into_bytes()) } } diff --git a/crates/pop3/src/client.rs b/crates/pop3/src/client.rs index 46b2aef9..e70b1c7d 100644 --- a/crates/pop3/src/client.rs +++ b/crates/pop3/src/client.rs @@ -19,7 +19,7 @@ impl Session { Pop3(trc::Pop3Event::RawInput), SpanId = self.session_id, Size = bytes.len(), - Contents = String::from_utf8_lossy(bytes).into_owned(), + Contents = trc::Value::from_maybe_string(bytes), ); let mut bytes = bytes.iter(); @@ -108,6 +108,12 @@ impl Session { self.handle_uidl(msg).await.map(|_| SessionResult::Continue) } Command::Noop => { + trc::event!( + Pop3(trc::Pop3Event::Noop), + SpanId = self.session_id, + Elapsed = trc::Value::Duration(0) + ); + self.write_ok("NOOP").await.map(|_| SessionResult::Continue) } Command::Rset => self.handle_rset().await.map(|_| SessionResult::Continue), @@ -119,6 +125,14 @@ impl Session { vec![Mechanism::OAuthBearer] }; + trc::event!( + Pop3(trc::Pop3Event::Capabilities), + SpanId = self.session_id, + Tls = self.stream.is_tls(), + Strict = !self.jmap.core.imap.allow_plain_auth, + Elapsed = trc::Value::Duration(0) + ); + self.write_bytes( Response::Capability:: { mechanisms, @@ -129,14 +143,28 @@ impl Session { .await .map(|_| SessionResult::Continue) } - Command::Stls => self - .write_ok("Begin TLS negotiation now") - .await - .map(|_| SessionResult::UpgradeTls), - Command::Utf8 => self - .write_ok("UTF8 enabled") - .await - .map(|_| SessionResult::Continue), + Command::Stls => { + trc::event!( + Pop3(trc::Pop3Event::StartTls), + SpanId = self.session_id, + Elapsed = trc::Value::Duration(0) + ); + + self.write_ok("Begin TLS negotiation now") + .await + .map(|_| SessionResult::UpgradeTls) + } + Command::Utf8 => { + trc::event!( + Pop3(trc::Pop3Event::Utf8), + SpanId = self.session_id, + Elapsed = trc::Value::Duration(0) + ); + + self.write_ok("UTF8 enabled") + .await + .map(|_| SessionResult::Continue) + } Command::Auth { mechanism, params } => self .handle_sasl(mechanism, params) .await diff --git a/crates/pop3/src/op/authenticate.rs b/crates/pop3/src/op/authenticate.rs index faa0dc62..c3662c29 100644 --- a/crates/pop3/src/op/authenticate.rs +++ b/crates/pop3/src/op/authenticate.rs @@ -4,10 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use common::{ - config::server::ServerProtocol, - listener::{limiter::ConcurrencyLimiter, SessionStream}, -}; +use common::listener::{limiter::ConcurrencyLimiter, SessionStream}; use imap::op::authenticate::{decode_challenge_oauth, decode_challenge_plain}; use jmap::auth::rate_limit::ConcurrencyLimiters; use mail_parser::decoders::base64::base64_decode; @@ -68,7 +65,7 @@ impl Session { let access_token = match credentials { Credentials::Plain { username, secret } | Credentials::XOauth2 { username, secret } => { self.jmap - .authenticate_plain(&username, &secret, self.remote_addr, ServerProtocol::Pop3) + .authenticate_plain(&username, &secret, self.remote_addr, self.session_id) .await } Credentials::OAuthBearer { token } => { diff --git a/crates/pop3/src/op/delete.rs b/crates/pop3/src/op/delete.rs index fba19ddc..5e1e4f80 100644 --- a/crates/pop3/src/op/delete.rs +++ b/crates/pop3/src/op/delete.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use common::listener::SessionStream; use jmap_proto::types::{state::StateChange, type_state::DataType}; use store::roaring::RoaringBitmap; @@ -13,10 +15,11 @@ use crate::{protocol::response::Response, Session, State}; impl Session { pub async fn handle_dele(&mut self, msgs: Vec) -> trc::Result<()> { + let op_start = Instant::now(); let mailbox = self.state.mailbox_mut(); let mut response = Vec::new(); - for msg in msgs { + for msg in &msgs { if let Some(message) = mailbox.messages.get_mut(msg.saturating_sub(1) as usize) { if !message.deleted { response.extend_from_slice(format!("+OK message {msg} deleted\r\n").as_bytes()); @@ -31,10 +34,18 @@ impl Session { } } + trc::event!( + Pop3(trc::Pop3Event::Delete), + SpanId = self.session_id, + Id = msgs, + Elapsed = op_start.elapsed() + ); + self.write_bytes(response).await } pub async fn handle_rset(&mut self) -> trc::Result<()> { + let op_start = Instant::now(); let mut count = 0; let mailbox = self.state.mailbox_mut(); for message in &mut mailbox.messages { @@ -43,15 +54,27 @@ impl Session { message.deleted = false; } } + + trc::event!( + Pop3(trc::Pop3Event::Reset), + SpanId = self.session_id, + Count = count as u64, + Elapsed = op_start.elapsed() + ); + self.write_ok(format!("{count} messages undeleted")).await } pub async fn handle_quit(&mut self) -> trc::Result<()> { + let op_start = Instant::now(); + let mut deleted_docs = Vec::new(); + if let State::Authenticated { mailbox, .. } = &self.state { let mut deleted = RoaringBitmap::new(); for message in &mailbox.messages { if message.deleted { deleted.insert(message.id); + deleted_docs.push(trc::Value::from(message.id)); } } @@ -97,6 +120,13 @@ impl Session { self.write_ok("Stalwart POP3 bids you farewell.").await?; } + trc::event!( + Pop3(trc::Pop3Event::Quit), + SpanId = self.session_id, + DocumentId = deleted_docs, + Elapsed = op_start.elapsed() + ); + Ok(()) } } diff --git a/crates/pop3/src/op/fetch.rs b/crates/pop3/src/op/fetch.rs index 1ec57179..3d395e1c 100644 --- a/crates/pop3/src/op/fetch.rs +++ b/crates/pop3/src/op/fetch.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use common::listener::SessionStream; use jmap::email::metadata::MessageMetadata; use jmap_proto::types::{collection::Collection, property::Property}; @@ -14,6 +16,7 @@ use crate::{protocol::response::Response, Session}; impl Session { pub async fn handle_fetch(&mut self, msg: u32, lines: Option) -> trc::Result<()> { + let op_start = Instant::now(); let mailbox = self.state.mailbox(); if let Some(message) = mailbox.messages.get(msg.saturating_sub(1) as usize) { if let Some(metadata) = self @@ -33,6 +36,13 @@ impl Session { .await .caused_by(trc::location!())? { + trc::event!( + Pop3(trc::Pop3Event::Fetch), + SpanId = self.session_id, + DocumentId = message.id, + Elapsed = op_start.elapsed() + ); + self.write_bytes( Response::Message:: { bytes, diff --git a/crates/pop3/src/op/list.rs b/crates/pop3/src/op/list.rs index a0f0985a..433ac42d 100644 --- a/crates/pop3/src/op/list.rs +++ b/crates/pop3/src/op/list.rs @@ -4,15 +4,26 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use common::listener::SessionStream; use crate::{protocol::response::Response, Session}; impl Session { pub async fn handle_list(&mut self, msg: Option) -> trc::Result<()> { + let op_start = Instant::now(); let mailbox = self.state.mailbox(); if let Some(msg) = msg { if let Some(message) = mailbox.messages.get(msg.saturating_sub(1) as usize) { + trc::event!( + Pop3(trc::Pop3Event::ListMessage), + SpanId = self.session_id, + DocumentId = message.id, + Size = message.size, + Elapsed = op_start.elapsed() + ); + self.write_ok(format!("{} {}", msg, message.size)).await } else { Err(trc::Pop3Event::Error @@ -21,6 +32,13 @@ impl Session { .caused_by(trc::location!())) } } else { + trc::event!( + Pop3(trc::Pop3Event::List), + SpanId = self.session_id, + Count = mailbox.messages.len(), + Elapsed = op_start.elapsed() + ); + self.write_bytes( Response::List(mailbox.messages.iter().map(|m| m.size).collect::>()) .serialize(), @@ -30,9 +48,19 @@ impl Session { } pub async fn handle_uidl(&mut self, msg: Option) -> trc::Result<()> { + let op_start = Instant::now(); let mailbox = self.state.mailbox(); if let Some(msg) = msg { if let Some(message) = mailbox.messages.get(msg.saturating_sub(1) as usize) { + trc::event!( + Pop3(trc::Pop3Event::UidlMessage), + SpanId = self.session_id, + DocumentId = message.id, + Uid = message.uid, + UidValidity = mailbox.uid_validity, + Elapsed = op_start.elapsed() + ); + self.write_ok(format!("{} {}{}", msg, mailbox.uid_validity, message.uid)) .await } else { @@ -42,6 +70,13 @@ impl Session { .caused_by(trc::location!())) } } else { + trc::event!( + Pop3(trc::Pop3Event::Uidl), + SpanId = self.session_id, + Count = mailbox.messages.len(), + Elapsed = op_start.elapsed() + ); + self.write_bytes( Response::List( mailbox @@ -57,7 +92,17 @@ impl Session { } pub async fn handle_stat(&mut self) -> trc::Result<()> { + let op_start = Instant::now(); let mailbox = self.state.mailbox(); + + trc::event!( + Pop3(trc::Pop3Event::Stat), + SpanId = self.session_id, + Count = mailbox.total, + Size = mailbox.size, + Elapsed = op_start.elapsed() + ); + self.write_ok(format!("{} {}", mailbox.total, mailbox.size)) .await } diff --git a/crates/pop3/src/session.rs b/crates/pop3/src/session.rs index 3012858a..ca0ae1d9 100644 --- a/crates/pop3/src/session.rs +++ b/crates/pop3/src/session.rs @@ -161,7 +161,7 @@ impl Session { Pop3(trc::Pop3Event::RawOutput), SpanId = self.session_id, Size = bytes.len(), - Contents = String::from_utf8_lossy(bytes).into_owned(), + Contents = trc::Value::from_maybe_string(bytes), ); self.stream.write_all(bytes.as_ref()).await.map_err(|err| { diff --git a/crates/smtp/src/core/mod.rs b/crates/smtp/src/core/mod.rs index dd06dfc2..6df47656 100644 --- a/crates/smtp/src/core/mod.rs +++ b/crates/smtp/src/core/mod.rs @@ -413,7 +413,6 @@ impl Default for Inner { }, ipc: Ipc { delivery_tx: mpsc::channel(1).0, - webhook_tx: mpsc::channel(1).0, }, script_cache: Default::default(), } diff --git a/crates/smtp/src/inbound/auth.rs b/crates/smtp/src/inbound/auth.rs index c1adcf40..38cf1398 100644 --- a/crates/smtp/src/inbound/auth.rs +++ b/crates/smtp/src/inbound/auth.rs @@ -169,24 +169,15 @@ impl Session { .core .authenticate( directory, - &self.core.inner.ipc, + self.data.session_id, &credentials, self.data.remote_ip, - self.instance.protocol, false, ) .await { Ok(principal) => { self.data.authenticated_as = authenticated_as.to_lowercase(); - - trc::event!( - Auth(trc::AuthEvent::Success), - Name = self.data.authenticated_as.clone(), - SpanId = self.data.session_id, - Protocol = trc::Protocol::Smtp, - ); - self.data.authenticated_emails = principal .emails .into_iter() @@ -200,9 +191,7 @@ impl Session { Err(err) => { let reason = *err.as_ref(); - trc::error!(err - .span_id(self.data.session_id) - .protocol(trc::Protocol::Smtp)); + trc::error!(err.span_id(self.data.session_id)); match reason { trc::EventType::Auth(trc::AuthEvent::Failed) => { diff --git a/crates/smtp/src/inbound/data.rs b/crates/smtp/src/inbound/data.rs index bedf2db2..9afc59ad 100644 --- a/crates/smtp/src/inbound/data.rs +++ b/crates/smtp/src/inbound/data.rs @@ -11,12 +11,10 @@ use std::{ time::{Duration, Instant, SystemTime}, }; -use chrono::{TimeZone, Utc}; use common::{ config::smtp::{auth::VerifyStrategy, session::Stage}, listener::SessionStream, scripts::ScriptModification, - webhooks::{WebhookMessageFailure, WebhookPayload, WebhookType}, }; use mail_auth::{ common::{headers::HeaderWriter, verify::VerifySignature}, @@ -56,9 +54,6 @@ impl Session { SpanId = self.data.session_id, ); - self.send_failure_webhook(WebhookMessageFailure::ParseFailed) - .await; - return (&b"550 5.7.7 Failed to parse message.\r\n"[..]).into(); }; @@ -80,9 +75,6 @@ impl Session { Count = auth_message.received_headers_count(), ); - self.send_failure_webhook(WebhookMessageFailure::LoopDetected) - .await; - return (&b"450 4.4.6 Too many Received headers. Possible loop detected.\r\n"[..]) .into(); } @@ -144,9 +136,6 @@ impl Session { ); if rejected { - self.send_failure_webhook(WebhookMessageFailure::DkimPolicy) - .await; - // 'Strict' mode violates the advice of Section 6.1 of RFC6376 return if dkim_output .iter() @@ -203,9 +192,6 @@ impl Session { ); if strict && !pass { - self.send_failure_webhook(WebhookMessageFailure::ArcPolicy) - .await; - return if matches!(arc_output.result(), DkimResult::TempError(_)) { (&b"451 4.7.29 ARC validation failed.\r\n"[..]).into() } else { @@ -315,9 +301,6 @@ impl Session { } if rejected { - self.send_failure_webhook(WebhookMessageFailure::DmarcPolicy) - .await; - return if is_temp_fail { (&b"451 4.7.1 Email temporarily rejected per DMARC policy.\r\n"[..]).into() } else { @@ -409,9 +392,6 @@ impl Session { } } Err(response) => { - self.send_failure_webhook(WebhookMessageFailure::MilterReject) - .await; - return response.into_bytes(); } }; @@ -428,9 +408,6 @@ impl Session { } } Err(response) => { - self.send_failure_webhook(WebhookMessageFailure::MilterReject) - .await; - return response.into_bytes(); } }; @@ -617,15 +594,9 @@ impl Session { modifications } ScriptResult::Reject(message) => { - self.send_failure_webhook(WebhookMessageFailure::SieveReject) - .await; - return message.into_bytes().into(); } ScriptResult::Discard => { - self.send_failure_webhook(WebhookMessageFailure::SieveDiscard) - .await; - return (b"250 2.0.0 Message queued for delivery.\r\n"[..]).into(); } }; @@ -728,36 +699,6 @@ impl Session { if self.core.has_quota(&mut message).await { // Prepare webhook event let queue_id = message.id; - let webhook_event = self - .core - .core - .has_webhook_subscribers(WebhookType::MessageAccepted) - .then(|| WebhookPayload::MessageAccepted { - id: queue_id, - remote_ip: self.data.remote_ip.into(), - local_port: self.data.local_port.into(), - authenticated_as: (!self.data.authenticated_as.is_empty()) - .then(|| self.data.authenticated_as.clone()), - return_path: message.return_path_lcase.clone(), - recipients: message - .recipients - .iter() - .map(|r| r.address_lcase.clone()) - .collect(), - next_retry: Utc - .timestamp_opt(message.next_delivery_event() as i64, 0) - .single() - .unwrap_or_else(Utc::now), - next_dsn: Utc - .timestamp_opt(message.next_dsn() as i64, 0) - .single() - .unwrap_or_else(Utc::now), - expires: Utc - .timestamp_opt(message.expires() as i64, 0) - .single() - .unwrap_or_else(Utc::now), - size: message.size, - }); // Queue message if message @@ -769,33 +710,13 @@ impl Session { ) .await { - // Send webhook event - if let Some(event) = webhook_event { - self.core - .inner - .ipc - .send_webhook(WebhookType::MessageAccepted, event) - .await; - } - self.state = State::Accepted(queue_id); self.data.messages_sent += 1; (b"250 2.0.0 Message queued for delivery.\r\n"[..]).into() } else { - self.send_failure_webhook(WebhookMessageFailure::ServerFailure) - .await; - (b"451 4.3.5 Unable to accept message at this time.\r\n"[..]).into() } } else { - trc::event!( - Smtp(SmtpEvent::QuotaExceeded), - SpanId = self.data.session_id, - ); - - self.send_failure_webhook(WebhookMessageFailure::QuotaExceeded) - .await; - (b"452 4.3.1 Mail system full, try again later.\r\n"[..]).into() } } @@ -964,6 +885,11 @@ impl Session { Ok(false) } } else { + trc::event!( + Smtp(SmtpEvent::RcptToMissing), + SpanId = self.data.session_id, + ); + self.write(b"503 5.5.1 RCPT is required first.\r\n").await?; Ok(false) } @@ -1010,38 +936,4 @@ impl Session { headers.extend_from_slice(Date::now().to_rfc822().as_bytes()); headers.extend_from_slice(b"\r\n"); } - - async fn send_failure_webhook(&self, reason: WebhookMessageFailure) { - if self - .core - .core - .has_webhook_subscribers(WebhookType::MessageRejected) - { - self.core - .inner - .ipc - .send_webhook( - WebhookType::MessageRejected, - WebhookPayload::MessageRejected { - reason, - remote_ip: self.data.remote_ip, - local_port: self.data.local_port, - authenticated_as: (!self.data.authenticated_as.is_empty()) - .then(|| self.data.authenticated_as.clone()), - return_path: self - .data - .mail_from - .as_ref() - .map(|m| m.address_lcase.clone()), - recipients: self - .data - .rcpt_to - .iter() - .map(|r| r.address_lcase.clone()) - .collect(), - }, - ) - .await; - } - } } diff --git a/crates/smtp/src/inbound/mail.rs b/crates/smtp/src/inbound/mail.rs index 13be3f52..59ca34a0 100644 --- a/crates/smtp/src/inbound/mail.rs +++ b/crates/smtp/src/inbound/mail.rs @@ -25,14 +25,29 @@ impl Session { || self.params.spf_ehlo.verify() || self.params.spf_mail_from.verify()) { + trc::event!( + Smtp(SmtpEvent::DidNotSayEhlo), + SpanId = self.data.session_id, + ); + return self .write(b"503 5.5.1 Polite people say EHLO first.\r\n") .await; } else if self.data.mail_from.is_some() { + trc::event!( + Smtp(SmtpEvent::MultipleMailFrom), + SpanId = self.data.session_id, + ); + return self .write(b"503 5.5.1 Multiple MAIL commands not allowed.\r\n") .await; } else if self.params.auth_require && self.data.authenticated_as.is_empty() { + trc::event!( + Smtp(SmtpEvent::MailFromUnauthenticated), + SpanId = self.data.session_id, + ); + return self .write(b"503 5.5.1 You must authenticate first.\r\n") .await; @@ -103,6 +118,21 @@ impl Session { e == &address_lcase || (e.starts_with('@') && address_lcase.ends_with(e)) })) { + trc::event!( + Smtp(SmtpEvent::MailFromUnauthorized), + SpanId = self.data.session_id, + From = address_lcase, + Details = [trc::Value::String(self.data.authenticated_as.to_string())] + .into_iter() + .chain( + self.data + .authenticated_emails + .iter() + .map(|e| trc::Value::String(e.to_string())) + ) + .collect::>() + ); + return self .write(b"501 5.5.4 You are not allowed to send from this address.\r\n") .await; @@ -175,6 +205,14 @@ impl Session { .await { let mail_from = self.data.mail_from.as_mut().unwrap(); + + trc::event!( + Smtp(SmtpEvent::MailFromRewritten), + SpanId = self.data.session_id, + OldName = mail_from.address_lcase.clone(), + Name = new_address.clone(), + ); + if new_address.contains('@') { mail_from.address_lcase = new_address.to_lowercase(); mail_from.domain = mail_from.address_lcase.domain_part().to_string(); @@ -197,6 +235,10 @@ impl Session { .await .unwrap_or(false) { + trc::event!( + Smtp(SmtpEvent::RequireTlsDisabled), + SpanId = self.data.session_id, + ); self.data.mail_from = None; return self .write(b"501 5.5.4 REQUIRETLS has been disabled.\r\n") @@ -215,6 +257,13 @@ impl Session { self.data.delivery_by = from.by; } else { self.data.mail_from = None; + + trc::event!( + Smtp(SmtpEvent::DeliverByInvalid), + SpanId = self.data.session_id, + Details = from.by, + ); + return self .write( format!( @@ -226,6 +275,10 @@ impl Session { .await; } } else { + trc::event!( + Smtp(SmtpEvent::DeliverByDisabled), + SpanId = self.data.session_id, + ); self.data.mail_from = None; return self .write(b"501 5.5.4 DELIVERBY extension has been disabled.\r\n") @@ -243,10 +296,19 @@ impl Session { if (-6..6).contains(&from.mt_priority) { self.data.priority = from.mt_priority as i16; } else { + trc::event!( + Smtp(SmtpEvent::MtPriorityInvalid), + SpanId = self.data.session_id, + Details = from.mt_priority, + ); self.data.mail_from = None; return self.write(b"501 5.5.4 Invalid priority value.\r\n").await; } } else { + trc::event!( + Smtp(SmtpEvent::MtPriorityDisabled), + SpanId = self.data.session_id, + ); self.data.mail_from = None; return self .write(b"501 5.5.4 MT-PRIORITY extension has been disabled.\r\n") @@ -262,6 +324,12 @@ impl Session { .await .unwrap_or(25 * 1024 * 1024) { + trc::event!( + Smtp(SmtpEvent::MessageTooLarge), + SpanId = self.data.session_id, + Size = from.size, + ); + self.data.mail_from = None; return self .write(b"552 5.3.4 Message too big for system.\r\n") @@ -290,6 +358,11 @@ impl Session { if hold_for <= max_hold { self.data.future_release = hold_for; } else { + trc::event!( + Smtp(SmtpEvent::FutureReleaseInvalid), + SpanId = self.data.session_id, + Details = hold_for, + ); self.data.mail_from = None; return self .write( @@ -301,6 +374,10 @@ impl Session { .await; } } else { + trc::event!( + Smtp(SmtpEvent::FutureReleaseDisabled), + SpanId = self.data.session_id, + ); self.data.mail_from = None; return self .write(b"501 5.5.4 FUTURERELEASE extension has been disabled.\r\n") @@ -315,6 +392,7 @@ impl Session { .await .unwrap_or(false) { + trc::event!(Smtp(SmtpEvent::DsnDisabled), SpanId = self.data.session_id,); self.data.mail_from = None; return self .write(b"501 5.5.4 DSN extension has been disabled.\r\n") diff --git a/crates/smtp/src/inbound/rcpt.rs b/crates/smtp/src/inbound/rcpt.rs index 711e2af6..04cd8382 100644 --- a/crates/smtp/src/inbound/rcpt.rs +++ b/crates/smtp/src/inbound/rcpt.rs @@ -28,8 +28,17 @@ impl Session { } if self.data.mail_from.is_none() { + trc::event!( + Smtp(SmtpEvent::MailFromMissing), + SpanId = self.data.session_id, + ); return self.write(b"503 5.5.1 MAIL is required first.\r\n").await; } else if self.data.rcpt_to.len() >= self.params.rcpt_max { + trc::event!( + Smtp(SmtpEvent::TooManyRecipients), + SpanId = self.data.session_id, + Limit = self.params.rcpt_max, + ); return self.write(b"451 4.5.3 Too many recipients.\r\n").await; } @@ -40,6 +49,7 @@ impl Session { || to.orcpt.is_some()) && !self.params.rcpt_dsn { + trc::event!(Smtp(SmtpEvent::DsnDisabled), SpanId = self.data.session_id,); return self .write(b"501 5.5.4 DSN extension has been disabled.\r\n") .await; @@ -56,6 +66,11 @@ impl Session { }; if self.data.rcpt_to.contains(&rcpt) { + trc::event!( + Smtp(SmtpEvent::RcptToDuplicate), + SpanId = self.data.session_id, + To = rcpt.address_lcase, + ); return self.write(b"250 2.1.5 OK\r\n").await; } self.data.rcpt_to.push(rcpt); @@ -133,6 +148,14 @@ impl Session { .await { let rcpt = self.data.rcpt_to.last_mut().unwrap(); + + trc::event!( + Smtp(SmtpEvent::RcptToRewritten), + SpanId = self.data.session_id, + OldName = rcpt.address_lcase.clone(), + Name = new_address.clone(), + ); + if new_address.contains('@') { rcpt.address_lcase = new_address.to_lowercase(); rcpt.domain = rcpt.address_lcase.domain_part().to_string(); @@ -143,6 +166,11 @@ impl Session { // Check for duplicates let rcpt = self.data.rcpt_to.last().unwrap(); if self.data.rcpt_to.iter().filter(|r| r == &rcpt).count() > 1 { + trc::event!( + Smtp(SmtpEvent::RcptToDuplicate), + SpanId = self.data.session_id, + To = rcpt.address_lcase.clone(), + ); self.data.rcpt_to.pop(); return self.write(b"250 2.1.5 OK\r\n").await; } diff --git a/crates/smtp/src/inbound/session.rs b/crates/smtp/src/inbound/session.rs index 0d736c35..7ff6e101 100644 --- a/crates/smtp/src/inbound/session.rs +++ b/crates/smtp/src/inbound/session.rs @@ -43,6 +43,11 @@ impl Session { if self.instance.protocol == ServerProtocol::Smtp { self.handle_ehlo(host, true).await?; } else { + trc::event!( + Smtp(SmtpEvent::LhloExpected), + SpanId = self.data.session_id, + ); + self.write(b"500 5.5.1 Invalid command.\r\n").await?; } } @@ -90,8 +95,19 @@ impl Session { .unwrap_or_default() .into(); if auth == 0 || self.params.auth_directory.is_none() { + trc::event!( + Smtp(SmtpEvent::AuthNotAllowed), + SpanId = self.data.session_id, + ); + self.write(b"503 5.5.1 AUTH not allowed.\r\n").await?; } else if !self.data.authenticated_as.is_empty() { + trc::event!( + Smtp(SmtpEvent::AlreadyAuthenticated), + SpanId = self.data.session_id, + Details = self.data.authenticated_as.clone(), + ); + self.write(b"503 5.5.1 Already authenticated.\r\n").await?; } else if let Some(mut token) = SaslToken::from_mechanism(mechanism & auth) @@ -107,6 +123,11 @@ impl Session { continue 'outer; } } else { + trc::event!( + Smtp(SmtpEvent::AuthMechanismNotSupported), + SpanId = self.data.session_id, + ); + self.write( b"554 5.7.8 Authentication mechanism not supported.\r\n", ) @@ -114,6 +135,8 @@ impl Session { } } Request::Noop { .. } => { + trc::event!(Smtp(SmtpEvent::Vrfy), SpanId = self.data.session_id,); + self.write(b"250 2.0.0 OK\r\n").await?; } Request::Vrfy { value } => { @@ -125,6 +148,11 @@ impl Session { Request::StartTls => { if !self.stream.is_tls() { if self.instance.acceptor.is_tls() { + trc::event!( + Smtp(SmtpEvent::StartTls), + SpanId = self.data.session_id, + ); + self.write(b"220 2.0.0 Ready to start TLS.\r\n").await?; #[cfg(any(test, feature = "test_mode"))] if self.data.helo_domain.contains("badtls") { @@ -133,41 +161,75 @@ impl Session { self.state = State::default(); return Ok(false); } else { + trc::event!( + Smtp(SmtpEvent::StartTlsUnavailable), + SpanId = self.data.session_id, + ); + self.write(b"502 5.7.0 TLS not available.\r\n").await?; } } else { + trc::event!( + Smtp(SmtpEvent::StartTlsAlready), + SpanId = self.data.session_id, + ); + self.write(b"504 5.7.4 Already in TLS mode.\r\n").await?; } } Request::Rset => { + trc::event!(Smtp(SmtpEvent::Rset), SpanId = self.data.session_id,); + self.reset(); self.write(b"250 2.0.0 OK\r\n").await?; } Request::Quit => { + trc::event!(Smtp(SmtpEvent::Quit), SpanId = self.data.session_id,); + self.write(b"221 2.0.0 Bye.\r\n").await?; return Err(()); } Request::Help { .. } => { - self.write( - b"250 2.0.0 Help can be found at https://stalw.art/docs/\r\n", - ) - .await?; + trc::event!(Smtp(SmtpEvent::Help), SpanId = self.data.session_id,); + + self.write(b"250 2.0.0 Help can be found at https://stalw.art\r\n") + .await?; } Request::Helo { host } => { if self.instance.protocol == ServerProtocol::Smtp { self.handle_ehlo(host, false).await?; } else { - self.write(b"500 5.5.1 Invalid command.\r\n").await?; + trc::event!( + Smtp(SmtpEvent::LhloExpected), + SpanId = self.data.session_id, + ); + + self.write(b"500 5.5.1 Invalid command: LHLO expected.\r\n") + .await?; } } Request::Lhlo { host } => { if self.instance.protocol == ServerProtocol::Lmtp { self.handle_ehlo(host, true).await?; } else { - self.write(b"502 5.5.1 Invalid command.\r\n").await?; + trc::event!( + Smtp(SmtpEvent::EhloExpected), + SpanId = self.data.session_id, + ); + + self.write(b"502 5.5.1 Invalid command: EHLO expected.\r\n") + .await?; } } - Request::Etrn { .. } | Request::Atrn { .. } | Request::Burl { .. } => { + cmd @ (Request::Etrn { .. } + | Request::Atrn { .. } + | Request::Burl { .. }) => { + trc::event!( + Smtp(SmtpEvent::CommandNotImplemented), + SpanId = self.data.session_id, + Details = format!("{cmd:?}"), + ); + self.write(b"502 5.5.1 Command not implemented.\r\n") .await?; } @@ -175,19 +237,40 @@ impl Session { Err(err) => match err { Error::NeedsMoreData { .. } => break 'outer, Error::UnknownCommand | Error::InvalidResponse { .. } => { + trc::event!( + Smtp(SmtpEvent::InvalidCommand), + SpanId = self.data.session_id, + ); + self.write(b"500 5.5.1 Invalid command.\r\n").await?; } Error::InvalidSenderAddress => { + trc::event!( + Smtp(SmtpEvent::InvalidSenderAddress), + SpanId = self.data.session_id, + ); + self.write(b"501 5.1.8 Bad sender's system address.\r\n") .await?; } Error::InvalidRecipientAddress => { + trc::event!( + Smtp(SmtpEvent::InvalidRecipientAddress), + SpanId = self.data.session_id, + ); + self.write( b"501 5.1.3 Bad destination mailbox address syntax.\r\n", ) .await?; } Error::SyntaxError { syntax } => { + trc::event!( + Smtp(SmtpEvent::SyntaxError), + SpanId = self.data.session_id, + Details = syntax + ); + self.write( format!("501 5.5.2 Syntax error, expected: {syntax}\r\n") .as_bytes(), @@ -195,6 +278,12 @@ impl Session { .await?; } Error::InvalidParameter { param } => { + trc::event!( + Smtp(SmtpEvent::InvalidParameter), + SpanId = self.data.session_id, + Details = param + ); + self.write( format!("501 5.5.4 Invalid parameter {param:?}.\r\n") .as_bytes(), @@ -202,6 +291,12 @@ impl Session { .await?; } Error::UnsupportedParameter { param } => { + trc::event!( + Smtp(SmtpEvent::UnsupportedParameter), + SpanId = self.data.session_id, + Details = param.clone() + ); + self.write( format!("504 5.5.4 Unsupported parameter {param:?}.\r\n") .as_bytes(), @@ -282,6 +377,11 @@ impl Session { continue 'outer; } } else { + trc::event!( + Smtp(SmtpEvent::AuthExchangeTooLong), + SpanId = self.data.session_id, + ); + self.auth_error( b"500 5.5.6 Authentication Exchange line is too long.\r\n", ) @@ -309,6 +409,11 @@ impl Session { } State::RequestTooLarge(receiver) => { if receiver.ingest(&mut iter) { + trc::event!( + Smtp(SmtpEvent::RequestTooLarge), + SpanId = self.data.session_id, + ); + self.write(b"554 5.3.4 Line is too long.\r\n").await?; state = State::default(); } else { @@ -344,7 +449,7 @@ impl Session { Smtp(SmtpEvent::RawOutput), SpanId = self.data.session_id, Size = bytes.len(), - Contents = String::from_utf8_lossy(bytes).into_owned(), + Contents = trc::Value::from_maybe_string(bytes), ); Ok(()) diff --git a/crates/smtp/src/outbound/client.rs b/crates/smtp/src/outbound/client.rs new file mode 100644 index 00000000..5216f826 --- /dev/null +++ b/crates/smtp/src/outbound/client.rs @@ -0,0 +1,611 @@ +/* + * SPDX-FileCopyrightText: 2020 Stalwart Labs Ltd + * + * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL + */ + +use std::{ + net::{IpAddr, SocketAddr}, + time::Duration, +}; + +use mail_send::{smtp::AssertReply, Credentials}; +use rustls::ClientConnection; +use rustls_pki_types::ServerName; +use smtp_proto::{ + response::{ + generate::BitToString, + parser::{ResponseReceiver, MAX_RESPONSE_LENGTH}, + }, + EhloResponse, Response, AUTH_CRAM_MD5, AUTH_DIGEST_MD5, AUTH_LOGIN, AUTH_OAUTHBEARER, + AUTH_PLAIN, AUTH_XOAUTH2, EXT_START_TLS, +}; +use tokio::{ + io::{AsyncRead, AsyncReadExt, AsyncWrite, AsyncWriteExt}, + net::{TcpSocket, TcpStream}, +}; +use tokio_rustls::{client::TlsStream, TlsConnector}; +use trc::DeliveryEvent; + +use crate::queue::{Error, Message, Status}; + +use super::session::SessionParams; + +pub struct SmtpClient { + pub stream: T, + pub timeout: Duration, + pub session_id: u64, +} + +impl SmtpClient { + pub async fn authenticate( + &mut self, + credentials: impl AsRef>, + capabilities: impl AsRef>, + ) -> mail_send::Result<&mut Self> + where + U: AsRef + PartialEq + Eq + std::hash::Hash, + { + let credentials = credentials.as_ref(); + let capabilities = capabilities.as_ref(); + let mut available_mechanisms = match &credentials { + Credentials::Plain { .. } => AUTH_CRAM_MD5 | AUTH_DIGEST_MD5 | AUTH_LOGIN | AUTH_PLAIN, + Credentials::OAuthBearer { .. } => AUTH_OAUTHBEARER, + Credentials::XOauth2 { .. } => AUTH_XOAUTH2, + } & capabilities.auth_mechanisms; + + // Try authenticating from most secure to least secure + let mut has_err = None; + let mut has_failed = false; + + while available_mechanisms != 0 && !has_failed { + let mechanism = 1 << ((63 - available_mechanisms.leading_zeros()) as u64); + available_mechanisms ^= mechanism; + match self.auth(mechanism, credentials).await { + Ok(_) => { + return Ok(self); + } + Err(err) => match err { + mail_send::Error::UnexpectedReply(reply) => { + has_failed = reply.code() == 535; + has_err = reply.into(); + } + mail_send::Error::UnsupportedAuthMechanism => (), + _ => return Err(err), + }, + } + } + + if let Some(has_err) = has_err { + Err(mail_send::Error::AuthenticationFailed(has_err)) + } else { + Err(mail_send::Error::UnsupportedAuthMechanism) + } + } + + pub(crate) async fn auth( + &mut self, + mechanism: u64, + credentials: &Credentials, + ) -> mail_send::Result<()> + where + U: AsRef + PartialEq + Eq + std::hash::Hash, + { + let mut reply = if (mechanism & (AUTH_PLAIN | AUTH_XOAUTH2 | AUTH_OAUTHBEARER)) != 0 { + self.cmd( + format!( + "AUTH {} {}\r\n", + mechanism.to_mechanism(), + credentials.encode(mechanism, "")?, + ) + .as_bytes(), + ) + .await? + } else { + self.cmd(format!("AUTH {}\r\n", mechanism.to_mechanism()).as_bytes()) + .await? + }; + + for _ in 0..3 { + match reply.code() { + 334 => { + reply = self + .cmd( + format!("{}\r\n", credentials.encode(mechanism, reply.message())?) + .as_bytes(), + ) + .await?; + } + 235 => { + return Ok(()); + } + _ => { + return Err(mail_send::Error::UnexpectedReply(reply)); + } + } + } + + Err(mail_send::Error::UnexpectedReply(reply)) + } + + pub async fn read_greeting(&mut self, hostname: &str) -> Result<(), Status<(), Error>> { + tokio::time::timeout(self.timeout, self.read()) + .await + .map_err(|_| Status::timeout(hostname, "reading greeting"))? + .and_then(|r| r.assert_code(220)) + .map_err(|err| Status::from_smtp_error(hostname, "", err)) + } + + pub async fn read_smtp_data_response( + &mut self, + hostname: &str, + bdat_cmd: &Option, + ) -> Result, Status<(), Error>> { + tokio::time::timeout(self.timeout, self.read()) + .await + .map_err(|_| Status::timeout(hostname, "reading SMTP DATA response"))? + .map_err(|err| { + Status::from_smtp_error(hostname, bdat_cmd.as_deref().unwrap_or("DATA"), err) + }) + } + + pub async fn read_lmtp_data_response( + &mut self, + hostname: &str, + num_responses: usize, + ) -> Result>, Status<(), Error>> { + tokio::time::timeout(self.timeout, async { self.read_many(num_responses).await }) + .await + .map_err(|_| Status::timeout(hostname, "reading LMTP DATA responses"))? + .map_err(|err| Status::from_smtp_error(hostname, "", err)) + } + + pub async fn write_chunks(&mut self, chunks: &[&[u8]]) -> Result<(), mail_send::Error> { + for chunk in chunks { + self.stream + .write_all(chunk) + .await + .map_err(mail_send::Error::from)?; + } + self.stream.flush().await.map_err(mail_send::Error::from) + } + + pub async fn send_message( + &mut self, + message: &Message, + bdat_cmd: &Option, + params: &SessionParams<'_>, + ) -> Result<(), Status<(), Error>> { + match params + .core + .core + .storage + .blob + .get_blob(message.blob_hash.as_slice(), 0..usize::MAX) + .await + { + Ok(Some(raw_message)) => tokio::time::timeout(params.timeout_data, async { + if let Some(bdat_cmd) = bdat_cmd { + trc::event!( + Delivery(DeliveryEvent::RawOutput), + SpanId = self.session_id, + Contents = bdat_cmd.clone() + ); + + self.write_chunks(&[bdat_cmd.as_bytes(), &raw_message]) + .await + } else { + trc::event!( + Delivery(DeliveryEvent::RawOutput), + SpanId = self.session_id, + Contents = "DATA\r\n" + ); + + self.write_chunks(&[b"DATA\r\n"]).await?; + self.read().await?.assert_code(354)?; + self.write_message(&raw_message) + .await + .map_err(mail_send::Error::from) + } + }) + .await + .map_err(|_| Status::timeout(params.hostname, "sending message"))? + .map_err(|err| { + Status::from_smtp_error(params.hostname, bdat_cmd.as_deref().unwrap_or("DATA"), err) + }), + Ok(None) => { + trc::event!( + 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::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(), + ))) + } + } + } + + pub async fn say_helo( + &mut self, + params: &SessionParams<'_>, + ) -> Result, Status<(), Error>> { + let cmd = if params.is_smtp { + format!("EHLO {}\r\n", params.local_hostname) + } else { + format!("LHLO {}\r\n", params.local_hostname) + }; + + trc::event!( + Delivery(DeliveryEvent::RawOutput), + SpanId = self.session_id, + Contents = cmd.clone() + ); + + tokio::time::timeout(params.timeout_ehlo, async { + self.stream.write_all(cmd.as_bytes()).await?; + self.stream.flush().await?; + self.read_ehlo().await + }) + .await + .map_err(|_| Status::timeout(params.hostname, "reading EHLO response"))? + .map_err(|err| Status::from_smtp_error(params.hostname, &cmd, err)) + } + + pub async fn quit(mut self: SmtpClient) { + trc::event!( + Delivery(DeliveryEvent::RawOutput), + SpanId = self.session_id, + Contents = "QUIT\r\n" + ); + + let _ = tokio::time::timeout(Duration::from_secs(10), async { + if self.stream.write_all(b"QUIT\r\n").await.is_ok() && self.stream.flush().await.is_ok() + { + let mut buf = [0u8; 128]; + let _ = self.stream.read(&mut buf).await; + } + }) + .await; + } + + pub async fn read_ehlo(&mut self) -> mail_send::Result> { + let mut buf = vec![0u8; 8192]; + let mut buf_concat = Vec::with_capacity(0); + + loop { + let br = self.stream.read(&mut buf).await?; + + if br == 0 { + return Err(mail_send::Error::UnparseableReply); + } + + trc::event!( + Delivery(DeliveryEvent::RawInput), + SpanId = self.session_id, + Contents = trc::Value::from_maybe_string(&buf[..br]) + ); + + let mut iter = if buf_concat.is_empty() { + buf[..br].iter() + } else if br + buf_concat.len() < MAX_RESPONSE_LENGTH { + buf_concat.extend_from_slice(&buf[..br]); + buf_concat.iter() + } else { + return Err(mail_send::Error::UnparseableReply); + }; + + match EhloResponse::parse(&mut iter) { + Ok(reply) => return Ok(reply), + Err(err) => match err { + smtp_proto::Error::NeedsMoreData { .. } => { + if buf_concat.is_empty() { + buf_concat = buf[..br].to_vec(); + } + } + smtp_proto::Error::InvalidResponse { code } => { + match ResponseReceiver::from_code(code).parse(&mut iter) { + Ok(response) => { + return Err(mail_send::Error::UnexpectedReply(response)); + } + Err(smtp_proto::Error::NeedsMoreData { .. }) => { + if buf_concat.is_empty() { + buf_concat = buf[..br].to_vec(); + } + } + Err(_) => return Err(mail_send::Error::UnparseableReply), + } + } + _ => { + return Err(mail_send::Error::UnparseableReply); + } + }, + } + } + } + + pub async fn read(&mut self) -> mail_send::Result> { + let mut buf = vec![0u8; 8192]; + let mut parser = ResponseReceiver::default(); + + loop { + let br = self.stream.read(&mut buf).await?; + + if br > 0 { + trc::event!( + Delivery(DeliveryEvent::RawInput), + SpanId = self.session_id, + Contents = trc::Value::from_maybe_string(&buf[..br]) + ); + + match parser.parse(&mut buf[..br].iter()) { + Ok(reply) => return Ok(reply), + Err(err) => match err { + smtp_proto::Error::NeedsMoreData { .. } => (), + _ => { + return Err(mail_send::Error::UnparseableReply); + } + }, + } + } else { + return Err(mail_send::Error::UnparseableReply); + } + } + } + + pub async fn read_many(&mut self, num: usize) -> mail_send::Result>> { + let mut buf = vec![0u8; 1024]; + let mut response = Vec::with_capacity(num); + let mut parser = ResponseReceiver::default(); + + 'outer: loop { + let br = self.stream.read(&mut buf).await?; + + if br > 0 { + let mut iter = buf[..br].iter(); + + trc::event!( + Delivery(DeliveryEvent::RawInput), + SpanId = self.session_id, + Contents = trc::Value::from_maybe_string(&buf[..br]) + ); + + loop { + match parser.parse(&mut iter) { + Ok(reply) => { + response.push(reply); + if response.len() != num { + parser.reset(); + } else { + break 'outer; + } + } + Err(err) => match err { + smtp_proto::Error::NeedsMoreData { .. } => break, + _ => { + return Err(mail_send::Error::UnparseableReply); + } + }, + } + } + } else { + return Err(mail_send::Error::UnparseableReply); + } + } + + Ok(response) + } + + /// Sends a command to the SMTP server and waits for a reply. + pub async fn cmd(&mut self, cmd: impl AsRef<[u8]>) -> mail_send::Result> { + tokio::time::timeout(self.timeout, async { + let cmd = cmd.as_ref(); + + trc::event!( + Delivery(DeliveryEvent::RawOutput), + SpanId = self.session_id, + Contents = trc::Value::from_maybe_string(cmd) + ); + + self.stream.write_all(cmd).await?; + self.stream.flush().await?; + self.read().await + }) + .await + .map_err(|_| mail_send::Error::Timeout)? + } + + pub async fn write_message(&mut self, message: &[u8]) -> tokio::io::Result<()> { + // Transparency procedure + let mut is_cr_or_lf = false; + + // As per RFC 5322bis, section 2.3: + // CR and LF MUST only occur together as CRLF; they MUST NOT appear + // independently in the body. + // For this reason, we apply the transparency procedure when there is + // a CR or LF followed by a dot. + + trc::event!( + Delivery(DeliveryEvent::RawOutput), + SpanId = self.session_id, + Contents = "[message]", + Size = message.len() + ); + + let mut last_pos = 0; + for (pos, byte) in message.iter().enumerate() { + if *byte == b'.' && is_cr_or_lf { + if let Some(bytes) = message.get(last_pos..pos) { + self.stream.write_all(bytes).await?; + self.stream.write_all(b".").await?; + last_pos = pos; + } + is_cr_or_lf = false; + } else { + is_cr_or_lf = *byte == b'\n' || *byte == b'\r'; + } + } + if let Some(bytes) = message.get(last_pos..) { + self.stream.write_all(bytes).await?; + } + self.stream.write_all("\r\n.\r\n".as_bytes()).await?; + self.stream.flush().await + } +} + +impl SmtpClient { + /// Upgrade the connection to TLS. + pub async fn start_tls( + mut self, + tls_connector: &TlsConnector, + hostname: &str, + ) -> mail_send::Result>> { + // Send STARTTLS command + self.cmd(b"STARTTLS\r\n") + .await? + .assert_positive_completion()?; + + self.into_tls(tls_connector, hostname).await + } + + pub async fn into_tls( + self, + tls_connector: &TlsConnector, + hostname: &str, + ) -> mail_send::Result>> { + tokio::time::timeout(self.timeout, async { + Ok(SmtpClient { + stream: tls_connector + .connect( + ServerName::try_from(hostname) + .map_err(|_| mail_send::Error::InvalidTLSName)? + .to_owned(), + self.stream, + ) + .await + .map_err(|err| { + let kind = err.kind(); + if let Some(inner) = err.into_inner() { + match inner.downcast::() { + Ok(error) => mail_send::Error::Tls(error), + Err(error) => { + mail_send::Error::Io(std::io::Error::new(kind, error)) + } + } + } else { + mail_send::Error::Io(std::io::Error::new(kind, "Unspecified")) + } + })?, + timeout: self.timeout, + session_id: self.session_id, + }) + }) + .await + .map_err(|_| mail_send::Error::Timeout)? + } +} + +impl SmtpClient { + /// Connects to a remote host address + pub async fn connect( + remote_addr: SocketAddr, + timeout: Duration, + session_id: u64, + ) -> mail_send::Result { + tokio::time::timeout(timeout, async { + Ok(SmtpClient { + stream: TcpStream::connect(remote_addr).await?, + timeout, + session_id, + }) + }) + .await + .map_err(|_| mail_send::Error::Timeout)? + } + + /// Connects to a remote host address using the provided local IP + pub async fn connect_using( + local_ip: IpAddr, + remote_addr: SocketAddr, + timeout: Duration, + session_id: u64, + ) -> mail_send::Result { + tokio::time::timeout(timeout, async { + let socket = if local_ip.is_ipv4() { + TcpSocket::new_v4()? + } else { + TcpSocket::new_v6()? + }; + socket.bind(SocketAddr::new(local_ip, 0))?; + + Ok(SmtpClient { + stream: socket.connect(remote_addr).await?, + timeout, + session_id, + }) + }) + .await + .map_err(|_| mail_send::Error::Timeout)? + } + + pub async fn try_start_tls( + mut self, + tls_connector: &TlsConnector, + hostname: &str, + capabilities: &EhloResponse, + ) -> StartTlsResult { + if capabilities.has_capability(EXT_START_TLS) { + match self.cmd("STARTTLS\r\n").await { + Ok(response) => { + if response.code() == 220 { + match self.into_tls(tls_connector, hostname).await { + Ok(smtp_client) => StartTlsResult::Success { smtp_client }, + Err(error) => StartTlsResult::Error { error }, + } + } else { + StartTlsResult::Unavailable { + response: response.into(), + smtp_client: self, + } + } + } + Err(error) => StartTlsResult::Error { error }, + } + } else { + StartTlsResult::Unavailable { + smtp_client: self, + response: None, + } + } + } +} + +impl SmtpClient> { + pub fn tls_connection(&self) -> &ClientConnection { + self.stream.get_ref().1 + } +} + +pub enum StartTlsResult { + Success { + smtp_client: SmtpClient>, + }, + Error { + error: mail_send::Error, + }, + Unavailable { + response: Option>, + smtp_client: SmtpClient, + }, +} diff --git a/crates/smtp/src/outbound/delivery.rs b/crates/smtp/src/outbound/delivery.rs index bd27ef7e..275a17cb 100644 --- a/crates/smtp/src/outbound/delivery.rs +++ b/crates/smtp/src/outbound/delivery.rs @@ -4,8 +4,9 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use crate::outbound::dane::verify::TlsaVerify; +use crate::outbound::client::SmtpClient; use crate::outbound::mta_sts::verify::VerifyPolicy; +use crate::outbound::{client::StartTlsResult, dane::verify::TlsaVerify}; use common::config::{ server::ServerProtocol, smtp::{queue::RequireOptional, report::AggregateFrequency}, @@ -14,7 +15,6 @@ use mail_auth::{ mta_sts::TlsRpt, report::tlsrpt::{FailureDetails, ResultType}, }; -use mail_send::SmtpClient; use smtp_proto::MAIL_REQUIRETLS; use std::{ net::{IpAddr, Ipv4Addr, SocketAddr}, @@ -29,12 +29,7 @@ use crate::{ reporting::{tls::TlsRptOptions, PolicyType, TlsEvent}, }; -use super::{ - lookup::ToNextHop, - mta_sts, - session::{read_greeting, say_helo, try_start_tls, SessionParams, StartTlsResult}, - NextHop, TlsStrategy, -}; +use super::{lookup::ToNextHop, mta_sts, session::SessionParams, NextHop, TlsStrategy}; use crate::queue::{ throttle, DeliveryAttempt, Domain, Error, Event, OnHold, QueueEnvelope, Status, }; @@ -141,6 +136,12 @@ impl DeliveryAttempt { let next_due = message.next_event_after(now()); message.save_changes(&core, None, None).await; + trc::event!( + Delivery(DeliveryEvent::ConcurrencyLimitExceeded), + Id = throttle.id.clone(), + SpanId = message_id, + ); + Event::OnHold(OnHold { next_due, limiters: vec![limiter], @@ -153,6 +154,14 @@ impl DeliveryAttempt { retry_at, message.next_event_after(now()).unwrap_or(u64::MAX), ); + + trc::event!( + Delivery(DeliveryEvent::RateLimitExceeded), + Id = throttle.id.clone(), + SpanId = message_id, + NextRetry = trc::Value::Timestamp(next_event) + ); + message .save_changes(&core, self.event.due.into(), next_event.into()) .await; @@ -203,6 +212,13 @@ impl DeliveryAttempt { .is_allowed(throttle, &envelope, &mut in_flight, message.id) .await { + trc::event!( + Delivery(DeliveryEvent::RateLimitExceeded), + Id = throttle.id.clone(), + SpanId = message_id, + Domain = domain.domain.clone(), + ); + message.domains[domain_idx].set_throttle_error(err, &mut on_hold); continue 'next_domain; } @@ -267,6 +283,7 @@ impl DeliveryAttempt { | AggregateFrequency::Weekly) if is_smtp => { + let time = Instant::now(); match core .core .smtp @@ -280,7 +297,8 @@ impl DeliveryAttempt { TlsRpt(TlsRptEvent::RecordFetch), SpanId = message.id, Domain = domain.domain.clone(), - Details = format!("{record:?}") + Details = format!("{record:?}"), + Elapsed = time.elapsed(), ); TlsRptOptions { record, interval }.into() @@ -290,7 +308,8 @@ impl DeliveryAttempt { TlsRpt(TlsRptEvent::RecordFetchError), SpanId = message.id, Domain = domain.domain.clone(), - CausedBy = trc::Event::from(err) + CausedBy = trc::Event::from(err), + Elapsed = time.elapsed(), ); None } @@ -301,6 +320,7 @@ impl DeliveryAttempt { // Obtain MTA-STS policy for domain let mta_sts_policy = if tls_strategy.try_mta_sts() && is_smtp { + let time = Instant::now(); match core .lookup_mta_sts_policy( &domain.domain, @@ -316,7 +336,8 @@ impl DeliveryAttempt { MtaSts(MtaStsEvent::PolicyFetch), SpanId = message.id, Domain = domain.domain.clone(), - Details = mta_sts_policy.to_string() + Details = mta_sts_policy.to_string(), + Elapsed = time.elapsed(), ); mta_sts_policy.into() @@ -365,6 +386,7 @@ impl DeliveryAttempt { SpanId = message.id, Domain = domain.domain.clone(), Strict = strict, + Elapsed = time.elapsed(), ); } mta_sts::Error::Dns(err) => { @@ -374,6 +396,7 @@ impl DeliveryAttempt { Domain = domain.domain.clone(), CausedBy = trc::Event::from(err.clone()), Strict = strict, + Elapsed = time.elapsed(), ); } mta_sts::Error::Http(err) => { @@ -383,6 +406,7 @@ impl DeliveryAttempt { Domain = domain.domain.clone(), Reason = err.to_string(), Strict = strict, + Elapsed = time.elapsed(), ); } mta_sts::Error::InvalidPolicy(reason) => { @@ -392,6 +416,7 @@ impl DeliveryAttempt { Domain = domain.domain.clone(), Reason = reason.clone(), Strict = strict, + Elapsed = time.elapsed(), ); } } @@ -421,6 +446,7 @@ impl DeliveryAttempt { let mx_list; if is_smtp && remote_hosts.is_empty() { // Lookup MX + let time = Instant::now(); mx_list = match core.core.smtp.resolvers.dns.mx_lookup(&domain.domain).await { Ok(mx) => mx, Err(err) => { @@ -429,6 +455,7 @@ impl DeliveryAttempt { SpanId = message.id, Domain = domain.domain.clone(), CausedBy = trc::Event::from(err.clone()), + Elapsed = time.elapsed(), ); let schedule = core @@ -448,12 +475,23 @@ impl DeliveryAttempt { .await .unwrap_or(5), ) { + trc::event!( + Delivery(DeliveryEvent::MxLookup), + SpanId = message.id, + Domain = domain.domain.clone(), + Details = remote_hosts_ + .iter() + .map(|h| trc::Value::String(h.hostname().to_string())) + .collect::>(), + Elapsed = time.elapsed(), + ); remote_hosts = remote_hosts_; } else { trc::event!( Delivery(DeliveryEvent::NullMX), SpanId = message.id, Domain = domain.domain.clone(), + Elapsed = time.elapsed(), ); let schedule = core @@ -482,6 +520,7 @@ impl DeliveryAttempt { // Validate MTA-STS envelope.mx = remote_host.hostname(); if let Some(mta_sts_policy) = &mta_sts_policy { + let strict = mta_sts_policy.enforce(); if !mta_sts_policy.verify(envelope.mx) { // Report MTA-STS failed verification if let Some(tls_report) = &tls_report { @@ -498,8 +537,6 @@ impl DeliveryAttempt { .await; } - let strict = mta_sts_policy.enforce(); - trc::event!( MtaSts(MtaStsEvent::NotAuthorized), SpanId = message.id, @@ -515,15 +552,40 @@ impl DeliveryAttempt { ))); continue 'next_host; } + } else { + trc::event!( + MtaSts(MtaStsEvent::Authorized), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Strict = strict, + ); } } // Obtain source and remote IPs + let time = Instant::now(); let resolve_result = match core .resolve_host(remote_host, &envelope, max_multihomed, message.id) .await { - Ok(result) => result, + Ok(result) => { + trc::event!( + Delivery(DeliveryEvent::IpLookup), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Details = result + .remote_ips + .iter() + .map(|ip| trc::Value::from(*ip)) + .collect::>(), + Limit = max_multihomed, + Elapsed = time.elapsed(), + ); + + result + } Err(status) => { trc::event!( Delivery(DeliveryEvent::IpLookupFailed), @@ -531,6 +593,7 @@ impl DeliveryAttempt { Domain = domain.domain.clone(), Hostname = envelope.mx.to_string(), Details = status.to_string(), + Elapsed = time.elapsed(), ); last_status = status; @@ -552,6 +615,7 @@ impl DeliveryAttempt { // Lookup DANE policy let dane_policy = if tls_strategy.try_dane() && is_smtp { + let time = Instant::now(); let strict = tls_strategy.is_dane_required(); match core.tlsa_lookup(format!("_25._tcp.{}.", envelope.mx)).await { Ok(Some(tlsa)) => { @@ -563,6 +627,7 @@ impl DeliveryAttempt { Hostname = envelope.mx.to_string(), Details = format!("{tlsa:?}"), Strict = strict, + Elapsed = time.elapsed(), ); tlsa.into() @@ -574,6 +639,7 @@ impl DeliveryAttempt { Hostname = envelope.mx.to_string(), Details = format!("{tlsa:?}"), Strict = strict, + Elapsed = time.elapsed(), ); // Report invalid TLSA record @@ -609,6 +675,7 @@ impl DeliveryAttempt { Domain = domain.domain.clone(), Hostname = envelope.mx.to_string(), Strict = strict, + Elapsed = time.elapsed(), ); if strict { @@ -648,6 +715,7 @@ impl DeliveryAttempt { Domain = domain.domain.clone(), Hostname = envelope.mx.to_string(), Strict = strict, + Elapsed = time.elapsed(), ); } else { trc::event!( @@ -657,6 +725,7 @@ impl DeliveryAttempt { Hostname = envelope.mx.to_string(), CausedBy = trc::Event::from(err.clone()), Strict = strict, + Elapsed = time.elapsed(), ); } @@ -713,12 +782,19 @@ impl DeliveryAttempt { .is_allowed(throttle, &envelope, &mut in_flight_host, message.id) .await { + trc::event!( + Delivery(DeliveryEvent::RateLimitExceeded), + SpanId = message.id, + Id = throttle.id.clone(), + RemoteIp = remote_ip, + ); message.domains[domain_idx].set_throttle_error(err, &mut on_hold); continue 'next_domain; } } // Connect + let time = Instant::now(); let conn_timeout = core .core .eval_if(&queue_config.timeout.connect, &envelope, message.id) @@ -729,12 +805,14 @@ impl DeliveryAttempt { ip_addr, SocketAddr::new(remote_ip, remote_host.port()), conn_timeout, + message_id, ) .await } else { SmtpClient::connect( SocketAddr::new(remote_ip, remote_host.port()), conn_timeout, + message_id, ) .await } { @@ -747,6 +825,7 @@ impl DeliveryAttempt { LocalIp = source_ip.unwrap_or(no_ip), RemoteIp = remote_ip, RemotePort = remote_host.port(), + Elapsed = time.elapsed(), ); smtp_client @@ -761,6 +840,7 @@ impl DeliveryAttempt { RemoteIp = remote_ip, RemotePort = remote_host.port(), Reason = err.to_string(), + Elapsed = time.elapsed(), ); last_status = Status::from_smtp_error(envelope.mx, "", err); @@ -829,7 +909,7 @@ impl DeliveryAttempt { .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 { + if let Err(status) = smtp_client.read_greeting(envelope.mx).await { trc::event!( Delivery(DeliveryEvent::GreetingFailed), SpanId = message.id, @@ -843,8 +923,20 @@ impl DeliveryAttempt { } // Say EHLO - let capabilities = match say_helo(&mut smtp_client, ¶ms).await { - Ok(capabilities) => capabilities, + let time = Instant::now(); + let capabilities = match smtp_client.say_helo(¶ms).await { + Ok(capabilities) => { + trc::event!( + Delivery(DeliveryEvent::Ehlo), + SpanId = message.id, + Domain = domain.domain.clone(), + Hostname = envelope.mx.to_string(), + Details = capabilities.capabilities(), + Elapsed = time.elapsed(), + ); + + capabilities + } Err(status) => { trc::event!( Delivery(DeliveryEvent::EhloRejected), @@ -852,6 +944,7 @@ impl DeliveryAttempt { Domain = domain.domain.clone(), Hostname = envelope.mx.to_string(), Details = status.to_string(), + Elapsed = time.elapsed(), ); last_status = status; @@ -861,18 +954,15 @@ impl DeliveryAttempt { // Try starting TLS if tls_strategy.try_start_tls() { + let time = Instant::now(); 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 + match smtp_client + .try_start_tls(tls_connector, envelope.mx, &capabilities) + .await { StartTlsResult::Success { smtp_client } => { trc::event!( @@ -888,6 +978,7 @@ impl DeliveryAttempt { "{:?}", smtp_client.tls_connection().negotiated_cipher_suite() ), + Elapsed = time.elapsed(), ); // Verify DANE @@ -961,6 +1052,7 @@ impl DeliveryAttempt { Domain = domain.domain.clone(), Hostname = envelope.mx.to_string(), Details = reason.clone(), + Elapsed = time.elapsed(), ); if let Some(tls_report) = &tls_report { @@ -1004,6 +1096,7 @@ impl DeliveryAttempt { Domain = domain.domain.clone(), Hostname = envelope.mx.to_string(), Reason = error.to_string(), + Elapsed = time.elapsed(), ); // Report TLS failure @@ -1081,7 +1174,7 @@ impl DeliveryAttempt { .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 { + if let Err(status) = smtp_client.read_greeting(envelope.mx).await { trc::event!( Delivery(DeliveryEvent::GreetingFailed), SpanId = message.id, @@ -1135,7 +1228,7 @@ impl DeliveryAttempt { message.save_changes(&core, None, None).await; trc::event!( - Delivery(DeliveryEvent::TooManyConcurrent), + Delivery(DeliveryEvent::ConcurrencyLimitExceeded), SpanId = message_id, ); @@ -1145,17 +1238,19 @@ impl DeliveryAttempt { message: self.event, }) } else if let Some(due) = message.next_event() { + trc::event!( + Queue(trc::QueueEvent::Rescheduled), + SpanId = message_id, + NextRetry = trc::Value::Timestamp(message.next_delivery_event()), + NextDsn = trc::Value::Timestamp(message.next_dsn()), + Expires = trc::Value::Timestamp(message.expires()), + ); + // Save changes to disk message .save_changes(&core, self.event.due.into(), due.into()) .await; - trc::event!( - Queue(trc::QueueEvent::Rescheduled), - SpanId = message_id, - Due = trc::Value::Timestamp(due) - ); - Event::Reload } else { // Delete message from queue diff --git a/crates/smtp/src/outbound/local.rs b/crates/smtp/src/outbound/local.rs index 48d1014c..eab43b1c 100644 --- a/crates/smtp/src/outbound/local.rs +++ b/crates/smtp/src/outbound/local.rs @@ -62,6 +62,7 @@ impl Message { trc::event!( Server(ServerEvent::ThreadError), CausedBy = trc::location!(), + SpanId = self.id, Reason = "Result channel closed", ); return Status::local_error(); @@ -72,6 +73,7 @@ impl Message { trc::event!( Server(ServerEvent::ThreadError), CausedBy = trc::location!(), + SpanId = self.id, Reason = "TX channel closed", ); return Status::local_error(); diff --git a/crates/smtp/src/outbound/mod.rs b/crates/smtp/src/outbound/mod.rs index c1083137..5f963f65 100644 --- a/crates/smtp/src/outbound/mod.rs +++ b/crates/smtp/src/outbound/mod.rs @@ -17,9 +17,9 @@ use crate::queue::{ spool::QueueEventLock, DeliveryAttempt, Error, ErrorDetails, HostResponse, Status, }; +pub mod client; pub mod dane; pub mod delivery; - pub mod local; pub mod lookup; pub mod mta_sts; diff --git a/crates/smtp/src/outbound/session.rs b/crates/smtp/src/outbound/session.rs index 3e36a028..a1d007c0 100644 --- a/crates/smtp/src/outbound/session.rs +++ b/crates/smtp/src/outbound/session.rs @@ -5,19 +5,15 @@ */ use common::config::smtp::queue::RequireOptional; -use mail_send::{smtp::AssertReply, Credentials, SmtpClient}; +use mail_send::{smtp::AssertReply, Credentials}; use smtp_proto::{ - EhloResponse, Response, Severity, EXT_CHUNKING, EXT_DSN, EXT_REQUIRE_TLS, EXT_SIZE, - EXT_SMTP_UTF8, EXT_START_TLS, MAIL_REQUIRETLS, MAIL_RET_FULL, MAIL_RET_HDRS, MAIL_SMTPUTF8, - RCPT_NOTIFY_DELAY, RCPT_NOTIFY_FAILURE, RCPT_NOTIFY_NEVER, RCPT_NOTIFY_SUCCESS, + EhloResponse, Severity, EXT_CHUNKING, EXT_DSN, EXT_REQUIRE_TLS, EXT_SIZE, EXT_SMTP_UTF8, + MAIL_REQUIRETLS, MAIL_RET_FULL, MAIL_RET_HDRS, MAIL_SMTPUTF8, RCPT_NOTIFY_DELAY, + RCPT_NOTIFY_FAILURE, RCPT_NOTIFY_NEVER, RCPT_NOTIFY_SUCCESS, }; -use std::fmt::Write; use std::time::Duration; -use tokio::{ - io::{AsyncRead, AsyncReadExt, AsyncWrite, AsyncWriteExt}, - net::TcpStream, -}; -use tokio_rustls::{client::TlsStream, TlsConnector}; +use std::{fmt::Write, time::Instant}; +use tokio::io::{AsyncRead, AsyncWrite}; use trc::DeliveryEvent; use crate::{ @@ -27,7 +23,7 @@ use crate::{ use crate::queue::{Error, Message, Recipient, Status}; -use super::TlsStrategy; +use super::{client::SmtpClient, TlsStrategy}; pub struct SessionParams<'x> { pub core: &'x SMTP, @@ -50,34 +46,55 @@ impl Message { params: SessionParams<'_>, ) -> Status<(), Error> { // Obtain capabilities - let capabilities = match say_helo(&mut smtp_client, ¶ms).await { - Ok(capabilities) => capabilities, + let time = Instant::now(); + let capabilities = match smtp_client.say_helo(¶ms).await { + Ok(capabilities) => { + trc::event!( + Delivery(DeliveryEvent::Ehlo), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + Details = capabilities.capabilities(), + Elapsed = time.elapsed(), + ); + + capabilities + } Err(status) => { trc::event!( Delivery(DeliveryEvent::EhloRejected), SpanId = params.session_id, Hostname = params.hostname.to_string(), Reason = status.to_string(), + Elapsed = time.elapsed(), ); - quit(smtp_client).await; + smtp_client.quit().await; return status; } }; // Authenticate if let Some(credentials) = params.credentials { + let time = Instant::now(); if let Err(err) = smtp_client.authenticate(credentials, &capabilities).await { trc::event!( Delivery(DeliveryEvent::AuthFailed), SpanId = params.session_id, Hostname = params.hostname.to_string(), Reason = err.to_string(), + Elapsed = time.elapsed(), ); - quit(smtp_client).await; + smtp_client.quit().await; return Status::from_smtp_error(params.hostname, "AUTH ...", err); } + trc::event!( + Delivery(DeliveryEvent::Auth), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + Elapsed = time.elapsed(), + ); + // Refresh capabilities // Disabled as some SMTP servers deauthenticate after EHLO /*capabilities = match say_helo(&mut smtp_client, ¶ms).await { @@ -90,13 +107,14 @@ impl Message { mx = ¶ms.hostname, reason = %status, ); - quit(smtp_client).await; + smtp_client.quit().await; return status; } };*/ } // MAIL FROM + let time = Instant::now(); smtp_client.timeout = params.timeout_mail; let cmd = self.build_mail_from(&capabilities); if let Err(err) = smtp_client @@ -109,18 +127,28 @@ impl Message { SpanId = params.session_id, Hostname = params.hostname.to_string(), Reason = err.to_string(), + Elapsed = time.elapsed(), ); - quit(smtp_client).await; + smtp_client.quit().await; return Status::from_smtp_error(params.hostname, &cmd, err); } + trc::event!( + Delivery(DeliveryEvent::MailFrom), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + From = self.return_path.to_string(), + Elapsed = time.elapsed(), + ); + // RCPT TO let mut total_rcpt = 0; let mut total_completed = 0; let mut accepted_rcpts = Vec::new(); smtp_client.timeout = params.timeout_rcpt; for rcpt in recipients { + let time = Instant::now(); total_rcpt += 1; if matches!( &rcpt.status, @@ -134,6 +162,15 @@ impl Message { match smtp_client.cmd(cmd.as_bytes()).await { Ok(response) => match response.severity() { Severity::PositiveCompletion => { + trc::event!( + Delivery(DeliveryEvent::RcptTo), + SpanId = params.session_id, + Hostname = params.hostname.to_string(), + To = rcpt.address.to_string(), + Details = response.to_string(), + Elapsed = time.elapsed(), + ); + accepted_rcpts.push(( rcpt, Status::Completed(HostResponse { @@ -149,6 +186,7 @@ impl Message { Hostname = params.hostname.to_string(), To = rcpt.address.to_string(), Reason = response.to_string(), + Elapsed = time.elapsed(), ); let response = HostResponse { @@ -174,10 +212,11 @@ impl Message { Hostname = params.hostname.to_string(), To = rcpt.address.to_string(), Reason = err.to_string(), + Elapsed = time.elapsed(), ); // Something went wrong, abort. - quit(smtp_client).await; + smtp_client.quit().await; return Status::from_smtp_error(params.hostname, "", err); } } @@ -185,27 +224,30 @@ impl Message { // Send message if !accepted_rcpts.is_empty() { - let bdat_cmd = if capabilities.has_capability(EXT_CHUNKING) { - format!("BDAT {} LAST\r\n", self.size).into() - } else { - None - }; + let time = Instant::now(); + let bdat_cmd = capabilities + .has_capability(EXT_CHUNKING) + .then(|| format!("BDAT {} LAST\r\n", self.size)); - if let Err(status) = send_message(&mut smtp_client, self, &bdat_cmd, ¶ms).await { + if let Err(status) = smtp_client.send_message(self, &bdat_cmd, ¶ms).await { trc::event!( Delivery(DeliveryEvent::MessageRejected), SpanId = params.session_id, Hostname = params.hostname.to_string(), Reason = status.to_string(), + Elapsed = time.elapsed(), ); - quit(smtp_client).await; + smtp_client.quit().await; return status; } if params.is_smtp { // Handle SMTP response - match read_smtp_data_response(&mut smtp_client, params.hostname, &bdat_cmd).await { + match smtp_client + .read_smtp_data_response(params.hostname, &bdat_cmd) + .await + { Ok(response) => { // Mark recipients as delivered if response.code() == 250 { @@ -216,6 +258,7 @@ impl Message { Hostname = params.hostname.to_string(), To = rcpt.address.to_string(), Details = status.to_string(), + Elapsed = time.elapsed(), ); rcpt.status = status; @@ -228,9 +271,10 @@ impl Message { SpanId = params.session_id, Hostname = params.hostname.to_string(), Reason = response.to_string(), + Elapsed = time.elapsed(), ); - quit(smtp_client).await; + smtp_client.quit().await; return Status::from_smtp_error( params.hostname, bdat_cmd.as_deref().unwrap_or("DATA"), @@ -240,24 +284,22 @@ impl Message { } Err(status) => { trc::event!( - Delivery(DeliveryEvent::MailFromRejected), + Delivery(DeliveryEvent::MessageRejected), SpanId = params.session_id, Hostname = params.hostname.to_string(), Reason = status.to_string(), + Elapsed = time.elapsed(), ); - quit(smtp_client).await; + smtp_client.quit().await; return status; } } } else { // Handle LMTP responses - match read_lmtp_data_response( - &mut smtp_client, - params.hostname, - accepted_rcpts.len(), - ) - .await + match smtp_client + .read_lmtp_data_response(params.hostname, accepted_rcpts.len()) + .await { Ok(responses) => { for ((rcpt, _), response) in accepted_rcpts.into_iter().zip(responses) { @@ -270,6 +312,7 @@ impl Message { Hostname = params.hostname.to_string(), To = rcpt.address.to_string(), Details = response.to_string(), + Elapsed = time.elapsed(), ); total_completed += 1; @@ -285,6 +328,7 @@ impl Message { Hostname = params.hostname.to_string(), To = rcpt.address.to_string(), Reason = response.to_string(), + Elapsed = time.elapsed(), ); let response = HostResponse { @@ -313,16 +357,17 @@ impl Message { SpanId = params.session_id, Hostname = params.hostname.to_string(), Reason = status.to_string(), + Elapsed = time.elapsed(), ); - quit(smtp_client).await; + smtp_client.quit().await; return status; } } } } - quit(smtp_client).await; + smtp_client.quit().await; if total_completed == total_rcpt { Status::Completed(()) } else { @@ -404,191 +449,6 @@ impl Recipient { } } -pub enum StartTlsResult { - Success { - smtp_client: SmtpClient>, - }, - Error { - error: mail_send::Error, - }, - Unavailable { - response: Option>, - smtp_client: SmtpClient, - }, -} - -pub async fn try_start_tls( - mut smtp_client: SmtpClient, - tls_connector: &TlsConnector, - hostname: &str, - capabilities: &EhloResponse, -) -> StartTlsResult { - if capabilities.has_capability(EXT_START_TLS) { - match smtp_client.cmd("STARTTLS\r\n").await { - Ok(response) => { - if response.code() == 220 { - match smtp_client.into_tls(tls_connector, hostname).await { - Ok(smtp_client) => StartTlsResult::Success { smtp_client }, - Err(error) => StartTlsResult::Error { error }, - } - } else { - StartTlsResult::Unavailable { - response: response.into(), - smtp_client, - } - } - } - Err(error) => StartTlsResult::Error { error }, - } - } else { - StartTlsResult::Unavailable { - smtp_client, - response: None, - } - } -} - -pub async fn read_greeting( - smtp_client: &mut SmtpClient, - hostname: &str, -) -> Result<(), Status<(), Error>> { - tokio::time::timeout(smtp_client.timeout, smtp_client.read()) - .await - .map_err(|_| Status::timeout(hostname, "reading greeting"))? - .and_then(|r| r.assert_code(220)) - .map_err(|err| Status::from_smtp_error(hostname, "", err)) -} - -pub async fn read_smtp_data_response( - smtp_client: &mut SmtpClient, - hostname: &str, - bdat_cmd: &Option, -) -> Result, Status<(), Error>> { - tokio::time::timeout(smtp_client.timeout, smtp_client.read()) - .await - .map_err(|_| Status::timeout(hostname, "reading SMTP DATA response"))? - .map_err(|err| { - Status::from_smtp_error(hostname, bdat_cmd.as_deref().unwrap_or("DATA"), err) - }) -} - -pub async fn read_lmtp_data_response( - smtp_client: &mut SmtpClient, - hostname: &str, - num_responses: usize, -) -> Result>, Status<(), Error>> { - tokio::time::timeout(smtp_client.timeout, async { - smtp_client.read_many(num_responses).await - }) - .await - .map_err(|_| Status::timeout(hostname, "reading LMTP DATA responses"))? - .map_err(|err| Status::from_smtp_error(hostname, "", err)) -} - -pub async fn write_chunks( - smtp_client: &mut SmtpClient, - chunks: &[&[u8]], -) -> Result<(), mail_send::Error> { - for chunk in chunks { - smtp_client - .stream - .write_all(chunk) - .await - .map_err(mail_send::Error::from)?; - } - smtp_client - .stream - .flush() - .await - .map_err(mail_send::Error::from) -} - -pub async fn send_message( - smtp_client: &mut SmtpClient, - message: &Message, - bdat_cmd: &Option, - params: &SessionParams<'_>, -) -> Result<(), Status<(), Error>> { - match params - .core - .core - .storage - .blob - .get_blob(message.blob_hash.as_slice(), 0..usize::MAX) - .await - { - Ok(Some(raw_message)) => tokio::time::timeout(params.timeout_data, async { - if let Some(bdat_cmd) = bdat_cmd { - write_chunks(smtp_client, &[bdat_cmd.as_bytes(), &raw_message]).await - } else { - write_chunks(smtp_client, &[b"DATA\r\n"]).await?; - smtp_client.read().await?.assert_code(354)?; - smtp_client - .write_message(&raw_message) - .await - .map_err(mail_send::Error::from) - } - }) - .await - .map_err(|_| Status::timeout(params.hostname, "sending message"))? - .map_err(|err| { - Status::from_smtp_error(params.hostname, bdat_cmd.as_deref().unwrap_or("DATA"), err) - }), - Ok(None) => { - trc::event!( - 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::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(), - ))) - } - } -} - -pub async fn say_helo( - smtp_client: &mut SmtpClient, - params: &SessionParams<'_>, -) -> Result, Status<(), Error>> { - let cmd = if params.is_smtp { - format!("EHLO {}\r\n", params.local_hostname) - } else { - format!("LHLO {}\r\n", params.local_hostname) - }; - tokio::time::timeout(params.timeout_ehlo, async { - smtp_client.stream.write_all(cmd.as_bytes()).await?; - smtp_client.stream.flush().await?; - smtp_client.read_ehlo().await - }) - .await - .map_err(|_| Status::timeout(params.hostname, "reading EHLO response"))? - .map_err(|err| Status::from_smtp_error(params.hostname, &cmd, err)) -} - -pub async fn quit(mut smtp_client: SmtpClient) { - let _ = tokio::time::timeout(Duration::from_secs(10), async { - if smtp_client.stream.write_all(b"QUIT\r\n").await.is_ok() - && smtp_client.stream.flush().await.is_ok() - { - let mut buf = [0u8; 128]; - let _ = smtp_client.stream.read(&mut buf).await; - } - }) - .await; -} - impl TlsStrategy { #[inline(always)] pub fn try_dane(&self) -> bool { diff --git a/crates/smtp/src/queue/dsn.rs b/crates/smtp/src/queue/dsn.rs index 00e9a4d6..88d73b8e 100644 --- a/crates/smtp/src/queue/dsn.rs +++ b/crates/smtp/src/queue/dsn.rs @@ -4,8 +4,6 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use chrono::{TimeZone, Utc}; -use common::webhooks::{WebhookDSN, WebhookDSNType, WebhookPayload, WebhookType}; use mail_builder::headers::content_type::ContentType; use mail_builder::headers::HeaderType; use mail_builder::mime::{make_boundary, BodyPart, MimePart}; @@ -27,8 +25,8 @@ use super::{ impl SMTP { pub async fn send_dsn(&self, message: &mut Message) { - // Send webhook event - self.send_dsn_webhook(message).await; + // Send DSN events + self.log_dsn(message).await; if !message.return_path.is_empty() { // Build DSN @@ -59,18 +57,8 @@ impl SMTP { } } - async fn send_dsn_webhook(&self, message: &Message) { - let typ = if !message.return_path.is_empty() { - WebhookType::DSN - } else { - WebhookType::DoubleBounce - }; - if !self.core.has_webhook_subscribers(typ) { - return; - } - + async fn log_dsn(&self, message: &Message) { let now = now(); - let mut webhook_data = Vec::new(); for rcpt in &message.recipients { if rcpt.has_flag(RCPT_DSN_SENT) { @@ -80,73 +68,69 @@ impl SMTP { let domain = &message.domains[rcpt.domain_idx]; match &rcpt.status { Status::Completed(response) => { - webhook_data.push(WebhookDSN { - address: rcpt.address_lcase.clone(), - typ: WebhookDSNType::Success, - remote_host: response.hostname.clone().into(), - message: response.response.to_string(), - next_retry: None, - expires: None, - retry_count: None, - }); + trc::event!( + Delivery(trc::DeliveryEvent::DsnSuccess), + SpanId = message.id, + To = rcpt.address_lcase.clone(), + Hostname = response.hostname.clone(), + Details = response.response.to_string(), + ); } Status::TemporaryFailure(response) if domain.notify.due <= now => { - webhook_data.push(WebhookDSN { - address: rcpt.address_lcase.clone(), - typ: WebhookDSNType::TemporaryFailure, - remote_host: response.hostname.entity.clone().into(), - message: response.response.to_string(), - next_retry: Utc.timestamp_opt(domain.retry.due as i64, 0).single(), - expires: Utc.timestamp_opt(domain.expires as i64, 0).single(), - retry_count: domain.retry.inner.into(), - }); + trc::event!( + Delivery(trc::DeliveryEvent::DsnTempFail), + SpanId = message.id, + To = rcpt.address_lcase.clone(), + Hostname = response.hostname.entity.clone(), + Details = response.response.to_string(), + NextRetry = trc::Value::Timestamp(domain.retry.due), + Expires = trc::Value::Timestamp(domain.expires), + Count = domain.retry.inner, + ); } Status::PermanentFailure(response) => { - webhook_data.push(WebhookDSN { - address: rcpt.address_lcase.clone(), - typ: WebhookDSNType::PermanentFailure, - remote_host: response.hostname.entity.clone().into(), - message: response.response.to_string(), - next_retry: None, - expires: None, - retry_count: domain.retry.inner.into(), - }); + trc::event!( + Delivery(trc::DeliveryEvent::DsnPermFail), + SpanId = message.id, + To = rcpt.address_lcase.clone(), + Hostname = response.hostname.entity.clone(), + Details = response.response.to_string(), + Count = domain.retry.inner, + ); } Status::Scheduled => { // There is no status for this address, use the domain's status. match &domain.status { Status::PermanentFailure(err) => { - webhook_data.push(WebhookDSN { - address: rcpt.address_lcase.clone(), - typ: WebhookDSNType::PermanentFailure, - remote_host: None, - message: err.to_string(), - next_retry: None, - expires: None, - retry_count: domain.retry.inner.into(), - }); + trc::event!( + Delivery(trc::DeliveryEvent::DsnPermFail), + SpanId = message.id, + To = rcpt.address_lcase.clone(), + Details = err.to_string(), + Count = domain.retry.inner, + ); } Status::TemporaryFailure(err) if domain.notify.due <= now => { - webhook_data.push(WebhookDSN { - address: rcpt.address_lcase.clone(), - typ: WebhookDSNType::TemporaryFailure, - remote_host: None, - message: err.to_string(), - next_retry: Utc.timestamp_opt(domain.retry.due as i64, 0).single(), - expires: Utc.timestamp_opt(domain.expires as i64, 0).single(), - retry_count: domain.retry.inner.into(), - }); + trc::event!( + Delivery(trc::DeliveryEvent::DsnTempFail), + SpanId = message.id, + To = rcpt.address_lcase.clone(), + Details = err.to_string(), + NextRetry = trc::Value::Timestamp(domain.retry.due), + Expires = trc::Value::Timestamp(domain.expires), + Count = domain.retry.inner, + ); } Status::Scheduled if domain.notify.due <= now => { - webhook_data.push(WebhookDSN { - address: rcpt.address_lcase.clone(), - typ: WebhookDSNType::TemporaryFailure, - remote_host: None, - message: "Concurrency limited".to_string(), - next_retry: Utc.timestamp_opt(domain.retry.due as i64, 0).single(), - expires: Utc.timestamp_opt(domain.expires as i64, 0).single(), - retry_count: domain.retry.inner.into(), - }); + trc::event!( + Delivery(trc::DeliveryEvent::DsnTempFail), + SpanId = message.id, + To = rcpt.address_lcase.clone(), + Details = "Concurrency limited", + NextRetry = trc::Value::Timestamp(domain.retry.due), + Expires = trc::Value::Timestamp(domain.expires), + Count = domain.retry.inner, + ); } _ => continue, } @@ -154,25 +138,6 @@ impl SMTP { _ => continue, } } - - // Send webhook event - if !webhook_data.is_empty() { - self.inner - .ipc - .send_webhook( - typ, - WebhookPayload::DSN { - id: message.id, - sender: message.return_path_lcase.clone(), - status: webhook_data, - created: Utc - .timestamp_opt(message.created as i64, 0) - .single() - .unwrap_or_else(Utc::now), - }, - ) - .await; - } } } diff --git a/crates/smtp/src/queue/quota.rs b/crates/smtp/src/queue/quota.rs index ca052bbc..c75c49e5 100644 --- a/crates/smtp/src/queue/quota.rs +++ b/crates/smtp/src/queue/quota.rs @@ -9,6 +9,7 @@ use store::{ write::{BatchBuilder, QueueClass, ValueClass}, ValueKey, }; +use trc::QueueEvent; use crate::core::{throttle::NewKey, SMTP}; @@ -24,6 +25,13 @@ impl SMTP { .check_quota(quota, message, message.size, 0, &mut quota_keys, message.id) .await { + trc::event!( + Queue(QueueEvent::QuotaExceeded), + SpanId = message.id, + Id = quota.id.clone(), + Type = "Sender" + ); + return false; } } @@ -42,6 +50,13 @@ impl SMTP { ) .await { + trc::event!( + Queue(QueueEvent::QuotaExceeded), + SpanId = message.id, + Id = quota.id.clone(), + Type = "Domain" + ); + return false; } } @@ -60,6 +75,13 @@ impl SMTP { ) .await { + trc::event!( + Queue(QueueEvent::QuotaExceeded), + SpanId = message.id, + Id = quota.id.clone(), + Type = "Recipient" + ); + return false; } } diff --git a/crates/smtp/src/queue/spool.rs b/crates/smtp/src/queue/spool.rs index 59c34234..bbc26211 100644 --- a/crates/smtp/src/queue/spool.rs +++ b/crates/smtp/src/queue/spool.rs @@ -239,6 +239,9 @@ impl Message { .map(|r| trc::Value::String(r.address_lcase.clone())) .collect::>(), Size = self.size, + NextRetry = trc::Value::Timestamp(self.next_delivery_event()), + NextDsn = trc::Value::Timestamp(self.next_dsn()), + Expires = trc::Value::Timestamp(self.expires()), ); // Write message to queue diff --git a/crates/smtp/src/reporting/analysis.rs b/crates/smtp/src/reporting/analysis.rs index 45b98354..18c0b336 100644 --- a/crates/smtp/src/reporting/analysis.rs +++ b/crates/smtp/src/reporting/analysis.rs @@ -12,13 +12,12 @@ use std::{ }; use ahash::AHashMap; -use common::webhooks::{WebhookPayload, WebhookTlsPolicy, WebhookType}; use mail_auth::{ flate2::read::GzDecoder, report::{tlsrpt::TlsReport, ActionDisposition, DmarcResult, Feedback, Report}, zip, }; -use mail_parser::{DateTime, MessageParser, MimeHeaders, PartType}; +use mail_parser::{MessageParser, MimeHeaders, PartType}; use store::{ write::{now, BatchBuilder, Bincode, ReportClass, ValueClass}, @@ -227,20 +226,6 @@ impl SMTP { let report = match report.format { Format::Dmarc(_) => match Report::parse_xml(&data) { Ok(report) => { - // Send webhook - if core - .core - .has_webhook_subscribers(WebhookType::IncomingDmarcReport) - { - core.inner - .ipc - .send_webhook( - WebhookType::IncomingDmarcReport, - report.webhook_payload(), - ) - .await; - } - // Log report.log(); Format::Dmarc(report) @@ -259,22 +244,7 @@ impl SMTP { }, Format::Tls(_) => match TlsReport::parse_json(&data) { Ok(report) => { - // Send webhook - if core - .core - .has_webhook_subscribers(WebhookType::IncomingTlsReport) - { - core.inner - .ipc - .send_webhook( - WebhookType::IncomingTlsReport, - report.webhook_payload(), - ) - .await; - } - // Log - report.log(); Format::Tls(report) } @@ -292,20 +262,6 @@ impl SMTP { }, Format::Arf(_) => match Feedback::parse_arf(&data) { Some(report) => { - // Send webhook - if core - .core - .has_webhook_subscribers(WebhookType::IncomingArfReport) - { - core.inner - .ipc - .send_webhook( - WebhookType::IncomingArfReport, - report.webhook_payload(), - ) - .await; - } - // Log report.log(); Format::Arf(report.into_owned()) @@ -383,7 +339,6 @@ impl SMTP { trait LogReport { fn log(&self); - fn webhook_payload(&self) -> WebhookPayload; } impl LogReport for Report { @@ -465,81 +420,6 @@ impl LogReport for Report { SpfNone = spf_none, ); } - - fn webhook_payload(&self) -> WebhookPayload { - let mut dmarc_pass = 0; - let mut dmarc_quarantine = 0; - let mut dmarc_reject = 0; - let mut dmarc_none = 0; - let mut dkim_pass = 0; - let mut dkim_fail = 0; - let mut dkim_none = 0; - let mut spf_pass = 0; - let mut spf_fail = 0; - let mut spf_none = 0; - - for record in self.records() { - let count = std::cmp::min(record.count(), 1); - - match record.action_disposition() { - ActionDisposition::Pass => { - dmarc_pass += count; - } - ActionDisposition::Quarantine => { - dmarc_quarantine += count; - } - ActionDisposition::Reject => { - dmarc_reject += count; - } - ActionDisposition::None | ActionDisposition::Unspecified => { - dmarc_none += count; - } - } - match record.dmarc_dkim_result() { - DmarcResult::Pass => { - dkim_pass += count; - } - DmarcResult::Fail => { - dkim_fail += count; - } - DmarcResult::Unspecified => { - dkim_none += count; - } - } - match record.dmarc_spf_result() { - DmarcResult::Pass => { - spf_pass += count; - } - DmarcResult::Fail => { - spf_fail += count; - } - DmarcResult::Unspecified => { - spf_none += count; - } - } - } - - 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(); - - WebhookPayload::IncomingDmarcReport { - range_from, - range_to, - domain: self.domain().to_string(), - report_email: self.email().to_string(), - report_id: self.report_id().to_string(), - dmarc_pass, - dmarc_quarantine, - dmarc_reject, - dmarc_none, - dkim_pass, - dkim_fail, - dkim_none, - spf_pass, - spf_fail, - spf_none, - } - } } impl LogReport for TlsReport { @@ -577,39 +457,6 @@ impl LogReport for TlsReport { ); } } - - fn webhook_payload(&self) -> WebhookPayload { - let mut policies = Vec::with_capacity(self.policies.len()); - - for policy in self.policies.iter().take(5) { - let mut details = AHashMap::with_capacity(policy.failure_details.len()); - for failure in &policy.failure_details { - let num_failures = std::cmp::min(1, failure.failed_session_count); - match details.entry(failure.result_type) { - Entry::Occupied(mut e) => { - *e.get_mut() += num_failures; - } - Entry::Vacant(e) => { - e.insert(num_failures); - } - } - } - - policies.push(WebhookTlsPolicy { - range_from: self.date_range.start_datetime.to_rfc3339(), - range_to: self.date_range.end_datetime.to_rfc3339(), - domain: policy.policy.policy_domain.clone(), - report_contact: self.contact_info.clone(), - report_id: self.report_id.clone(), - policy_type: policy.policy.policy_type, - total_successes: policy.summary.total_success, - total_failures: policy.summary.total_failure, - details, - }); - } - - WebhookPayload::IncomingTlsReport { policies } - } } impl LogReport for Feedback<'_> { @@ -664,34 +511,4 @@ impl LogReport for Feedback<'_> { .collect::>(), ); } - - fn webhook_payload(&self) -> WebhookPayload { - WebhookPayload::IncomingArfReport { - feedback_type: self.feedback_type(), - arrival_date: self - .arrival_date() - .map(|a| DateTime::from_timestamp(a).to_rfc3339()), - authentication_results: self - .authentication_results() - .iter() - .map(|t| t.to_string()) - .collect(), - incidents: self.incidents(), - reported_domain: self - .reported_domain() - .iter() - .map(|t| t.to_string()) - .collect(), - reported_uri: self.reported_uri().iter().map(|t| t.to_string()).collect(), - reporting_mta: self.reporting_mta().map(|t| t.to_string()), - source_ip: self.source_ip(), - user_agent: self.user_agent().map(|t| t.to_string()), - auth_failure: self.auth_failure(), - delivery_result: self.delivery_result(), - dkim_domain: self.dkim_domain().map(|t| t.to_string()), - dkim_identity: self.dkim_identity().map(|t| t.to_string()), - dkim_selector: self.dkim_selector().map(|t| t.to_string()), - identity_alignment: self.identity_alignment(), - } - } } diff --git a/crates/smtp/src/reporting/dkim.rs b/crates/smtp/src/reporting/dkim.rs index ec2bea42..815855b0 100644 --- a/crates/smtp/src/reporting/dkim.rs +++ b/crates/smtp/src/reporting/dkim.rs @@ -84,6 +84,7 @@ impl Session { trc::event!( OutgoingReport(OutgoingReportEvent::DkimReport), SpanId = self.data.session_id, + From = from_addr.to_string(), To = rcpt.to_string(), ); diff --git a/crates/smtp/src/reporting/dmarc.rs b/crates/smtp/src/reporting/dmarc.rs index d2ca4952..343ea725 100644 --- a/crates/smtp/src/reporting/dmarc.rs +++ b/crates/smtp/src/reporting/dmarc.rs @@ -219,6 +219,7 @@ impl Session { trc::event!( OutgoingReport(OutgoingReportEvent::DmarcReport), SpanId = self.data.session_id, + From = from_addr.to_string(), To = rcpts .iter() .map(|a| trc::Value::String(a.to_string())) diff --git a/crates/smtp/src/reporting/mod.rs b/crates/smtp/src/reporting/mod.rs index 4cfc1629..c2eb845e 100644 --- a/crates/smtp/src/reporting/mod.rs +++ b/crates/smtp/src/reporting/mod.rs @@ -6,14 +6,12 @@ use std::{io, sync::Arc, time::SystemTime}; -use chrono::{TimeZone, Utc}; use common::{ config::smtp::{ report::{AddressMatch, AggregateFrequency}, resolver::{Policy, Tlsa}, }, expr::if_block::IfBlock, - webhooks::{WebhookPayload, WebhookType}, USER_AGENT, }; use mail_auth::{ @@ -148,44 +146,6 @@ impl SMTP { } } - // Send webhook - if self - .core - .has_webhook_subscribers(WebhookType::OutgoingReport) - { - self.inner - .ipc - .send_webhook( - WebhookType::OutgoingReport, - WebhookPayload::MessageAccepted { - id: message.id, - remote_ip: None, - local_port: None, - authenticated_as: None, - return_path: message.return_path_lcase.clone(), - recipients: message - .recipients - .iter() - .map(|r| r.address_lcase.clone()) - .collect(), - next_retry: Utc - .timestamp_opt(message.next_delivery_event() as i64, 0) - .single() - .unwrap_or_else(Utc::now), - next_dsn: Utc - .timestamp_opt(message.next_dsn() as i64, 0) - .single() - .unwrap_or_else(Utc::now), - expires: Utc - .timestamp_opt(message.expires() as i64, 0) - .single() - .unwrap_or_else(Utc::now), - size: message.size, - }, - ) - .await; - } - // Queue message message .queue(signature.as_deref(), &report, parent_session_id, self) diff --git a/crates/smtp/src/reporting/spf.rs b/crates/smtp/src/reporting/spf.rs index 10e77afc..232e424b 100644 --- a/crates/smtp/src/reporting/spf.rs +++ b/crates/smtp/src/reporting/spf.rs @@ -85,6 +85,7 @@ impl Session { OutgoingReport(OutgoingReportEvent::SpfReport), SpanId = self.data.session_id, To = rcpt.to_string(), + From = from_addr.to_string(), ); // Send report diff --git a/crates/store/src/backend/rocksdb/read.rs b/crates/store/src/backend/rocksdb/read.rs index 287de2c7..893443ba 100644 --- a/crates/store/src/backend/rocksdb/read.rs +++ b/crates/store/src/backend/rocksdb/read.rs @@ -25,7 +25,7 @@ impl RocksDbStore { db.get_pinned_cf( &db.cf_handle(std::str::from_utf8(&[key.subspace()]).unwrap()) .unwrap(), - &key.serialize(0), + key.serialize(0), ) .map_err(into_error) .and_then(|value| { diff --git a/crates/trc/src/atomic.rs b/crates/trc/src/atomic.rs new file mode 100644 index 00000000..be45b0d7 --- /dev/null +++ b/crates/trc/src/atomic.rs @@ -0,0 +1,118 @@ +/* + * SPDX-FileCopyrightText: 2020 Stalwart Labs Ltd + * + * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL + */ + +use std::sync::atomic::{AtomicUsize, Ordering}; + +pub struct AtomicBitset([AtomicUsize; N]); + +const USIZE_BITS: usize = std::mem::size_of::() * 8; +const USIZE_BITS_MASK: usize = USIZE_BITS - 1; + +impl AtomicBitset { + #[allow(clippy::new_without_default)] + #[allow(clippy::declare_interior_mutable_const)] + pub const fn new() -> Self { + Self({ + const INIT: AtomicUsize = AtomicUsize::new(0); + let mut array = [INIT; N]; + let mut i = 0; + while i < N { + array[i] = AtomicUsize::new(0); + i += 1; + } + array + }) + } + + #[inline(always)] + pub fn set(&self, index: impl Into) { + let index = index.into(); + self.0[index / USIZE_BITS].fetch_or(1 << (index & USIZE_BITS_MASK), Ordering::Relaxed); + } + + #[inline(always)] + pub fn clear(&self, index: impl Into) { + let index = index.into(); + self.0[index / USIZE_BITS].fetch_and(!(1 << (index & USIZE_BITS_MASK)), Ordering::Relaxed); + } + + #[inline(always)] + pub fn get(&self, index: impl Into) -> bool { + let index = index.into(); + self.0[index / USIZE_BITS].load(Ordering::Relaxed) & (1 << (index & USIZE_BITS_MASK)) != 0 + } + + pub fn clear_all(&self) { + for i in 0..N { + self.0[i].store(0, Ordering::Relaxed); + } + } +} + +#[cfg(test)] +mod tests { + use super::*; + + const TEST_SIZE: usize = 1000; + type TestBitset = AtomicBitset<{ (TEST_SIZE + USIZE_BITS - 1) / USIZE_BITS }>; + static BITSET: TestBitset = TestBitset::new(); + + #[test] + fn test_atomic_bitset() { + for i in 0..TEST_SIZE { + assert!(!BITSET.get(i), "Bit {} should be unset in new BITSET", i); + } + + for i in 0..TEST_SIZE { + assert!(!BITSET.get(i), "Bit {} should be initially unset", i); + BITSET.set(i); + assert!(BITSET.get(i), "Bit {} should be set after setting", i); + } + + BITSET.clear_all(); + + for i in 0..TEST_SIZE { + BITSET.set(i); + assert!(BITSET.get(i), "Bit {} should be set before clearing", i); + BITSET.clear(i); + assert!(!BITSET.get(i), "Bit {} should be unset after clearing", i); + } + + BITSET.clear_all(); + + // Set even bits + for i in (0..TEST_SIZE).step_by(2) { + BITSET.set(i); + } + + // Check all bits + for i in 0..TEST_SIZE { + if i % 2 == 0 { + assert!(BITSET.get(i), "Even bit {} should be set", i); + } else { + assert!(!BITSET.get(i), "Odd bit {} should be unset", i); + } + } + + // Clear even bits and set odd bits + for i in 0..TEST_SIZE { + if i % 2 == 0 { + BITSET.clear(i); + } else { + BITSET.set(i); + } + } + + // Check all bits again + for i in 0..TEST_SIZE { + if i % 2 == 0 { + assert!(!BITSET.get(i), "Even bit {} should now be unset", i); + } else { + assert!(BITSET.get(i), "Odd bit {} should now be set", i); + } + } + } +} diff --git a/crates/trc/src/conv.rs b/crates/trc/src/conv.rs index f62dc521..ebf37415 100644 --- a/crates/trc/src/conv.rs +++ b/crates/trc/src/conv.rs @@ -6,6 +6,8 @@ use std::{borrow::Cow, fmt::Debug, time::Duration}; +use mail_auth::common::headers::HeaderWriter; + use crate::*; impl AsRef for Error { @@ -333,7 +335,17 @@ impl From<&mail_auth::DmarcResult> for Event { impl From<&mail_auth::DkimOutput<'_>> for Event { fn from(value: &mail_auth::DkimOutput<'_>) -> Self { - Event::from(value.result()).ctx_opt(Key::Contents, value.signature().map(|s| s.to_string())) + Event::from(value.result()).ctx_opt( + Key::Contents, + value.signature().map(|s| { + let mut buf = Vec::new(); + s.write_header(&mut buf); + + String::from_utf8(buf) + .map(Value::String) + .unwrap_or_else(|err| Value::Bytes(err.into_bytes())) + }), + ) } } diff --git a/crates/trc/src/imple.rs b/crates/trc/src/imple.rs index 06ae542e..d08c96c8 100644 --- a/crates/trc/src/imple.rs +++ b/crates/trc/src/imple.rs @@ -574,6 +574,14 @@ impl NetworkEvent { } impl Value { + pub fn from_maybe_string(value: &[u8]) -> Self { + if let Ok(value) = std::str::from_utf8(value) { + Self::String(value.to_string()) + } else { + Self::Bytes(value.to_vec()) + } + } + pub fn to_uint(&self) -> Option { match self { Self::UInt(value) => Some(*value), @@ -748,26 +756,141 @@ impl EventType { pub fn level(&self) -> Level { match self { EventType::Store(event) => match event { - StoreEvent::SqlQuery | StoreEvent::LdapQuery => Level::Trace, + StoreEvent::SqlQuery | StoreEvent::LdapQuery | StoreEvent::LdapBind => Level::Trace, StoreEvent::NotFound => Level::Debug, - StoreEvent::Ingest => Level::Info, - _ => Level::Error, + StoreEvent::Ingest | StoreEvent::IngestDuplicate => Level::Info, + StoreEvent::IngestError + | StoreEvent::AssertValueFailed + | StoreEvent::FoundationDBError + | StoreEvent::MySQLError + | StoreEvent::PostgreSQLError + | StoreEvent::RocksDBError + | StoreEvent::SQLiteError + | StoreEvent::LdapError + | StoreEvent::ElasticSearchError + | StoreEvent::RedisError + | StoreEvent::S3Error + | StoreEvent::FilesystemError + | StoreEvent::PoolError + | StoreEvent::DataCorruption + | StoreEvent::DecompressError + | StoreEvent::DeserializeError + | StoreEvent::NotConfigured + | StoreEvent::NotSupported + | StoreEvent::UnexpectedError + | StoreEvent::CryptoError => Level::Error, + StoreEvent::BlobMissingMarker => Level::Warn, }, EventType::Jmap(_) => Level::Debug, EventType::Imap(event) => match event { - ImapEvent::Error | ImapEvent::IdleStart | ImapEvent::IdleStop => Level::Debug, + ImapEvent::GetAcl + | ImapEvent::SetAcl + | ImapEvent::MyRights + | ImapEvent::ListRights + | ImapEvent::Append + | ImapEvent::Capabilities + | ImapEvent::Id + | ImapEvent::Close + | ImapEvent::Copy + | ImapEvent::Move + | ImapEvent::CreateMailbox + | ImapEvent::DeleteMailbox + | ImapEvent::RenameMailbox + | ImapEvent::Enable + | ImapEvent::Expunge + | ImapEvent::Fetch + | ImapEvent::List + | ImapEvent::Lsub + | ImapEvent::Logout + | ImapEvent::Namespace + | ImapEvent::Noop + | ImapEvent::Search + | ImapEvent::Sort + | ImapEvent::Select + | ImapEvent::Status + | ImapEvent::Store + | ImapEvent::Subscribe + | ImapEvent::Unsubscribe + | ImapEvent::Thread + | ImapEvent::Error + | ImapEvent::IdleStart + | ImapEvent::IdleStop => Level::Debug, ImapEvent::RawInput | ImapEvent::RawOutput => Level::Trace, }, EventType::ManageSieve(event) => match event { - ManageSieveEvent::Error => Level::Debug, + ManageSieveEvent::CreateScript + | ManageSieveEvent::UpdateScript + | ManageSieveEvent::GetScript + | ManageSieveEvent::DeleteScript + | ManageSieveEvent::RenameScript + | ManageSieveEvent::CheckScript + | ManageSieveEvent::HaveSpace + | ManageSieveEvent::ListScripts + | ManageSieveEvent::SetActive + | ManageSieveEvent::Capabilities + | ManageSieveEvent::StartTls + | ManageSieveEvent::Unauthenticate + | ManageSieveEvent::Logout + | ManageSieveEvent::Noop + | ManageSieveEvent::Error => Level::Debug, ManageSieveEvent::RawInput | ManageSieveEvent::RawOutput => Level::Trace, }, EventType::Pop3(event) => match event { - Pop3Event::Error => Level::Debug, + Pop3Event::Delete + | Pop3Event::Reset + | Pop3Event::Quit + | Pop3Event::Fetch + | Pop3Event::List + | Pop3Event::ListMessage + | Pop3Event::Uidl + | Pop3Event::UidlMessage + | Pop3Event::Stat + | Pop3Event::Noop + | Pop3Event::Capabilities + | Pop3Event::StartTls + | Pop3Event::Utf8 + | Pop3Event::Error => Level::Debug, Pop3Event::RawInput | Pop3Event::RawOutput => Level::Trace, }, EventType::Smtp(event) => match event { - SmtpEvent::PipeSuccess | SmtpEvent::PipeError | SmtpEvent::Error => Level::Debug, + SmtpEvent::DidNotSayEhlo + | SmtpEvent::EhloExpected + | SmtpEvent::LhloExpected + | SmtpEvent::MailFromUnauthenticated + | SmtpEvent::MailFromUnauthorized + | SmtpEvent::MailFromRewritten + | SmtpEvent::MailFromMissing + | SmtpEvent::MultipleMailFrom + | SmtpEvent::RcptToDuplicate + | SmtpEvent::RcptToRewritten + | SmtpEvent::RcptToMissing + | SmtpEvent::RequireTlsDisabled + | SmtpEvent::DeliverByDisabled + | SmtpEvent::DeliverByInvalid + | SmtpEvent::FutureReleaseDisabled + | SmtpEvent::FutureReleaseInvalid + | SmtpEvent::MtPriorityDisabled + | SmtpEvent::MtPriorityInvalid + | SmtpEvent::DsnDisabled + | SmtpEvent::AuthExchangeTooLong + | SmtpEvent::AlreadyAuthenticated + | SmtpEvent::Noop + | SmtpEvent::StartTls + | SmtpEvent::StartTlsUnavailable + | SmtpEvent::StartTlsAlready + | SmtpEvent::Rset + | SmtpEvent::Quit + | SmtpEvent::Help + | SmtpEvent::CommandNotImplemented + | SmtpEvent::InvalidCommand + | SmtpEvent::InvalidSenderAddress + | SmtpEvent::InvalidRecipientAddress + | SmtpEvent::InvalidParameter + | SmtpEvent::UnsupportedParameter + | SmtpEvent::SyntaxError + | SmtpEvent::PipeSuccess + | SmtpEvent::PipeError + | SmtpEvent::Error => Level::Debug, SmtpEvent::MissingLocalHostname | SmtpEvent::RemoteIdNotFound => Level::Warn, SmtpEvent::ConcurrencyLimitExceeded | SmtpEvent::TransferLimitExceeded @@ -789,7 +912,6 @@ impl EventType { | SmtpEvent::DmarcFail | SmtpEvent::IprevPass | SmtpEvent::IprevFail - | SmtpEvent::QuotaExceeded | SmtpEvent::TooManyMessages | SmtpEvent::Ehlo | SmtpEvent::InvalidEhlo @@ -803,7 +925,11 @@ impl EventType { | SmtpEvent::VrfyDisabled | SmtpEvent::Expn | SmtpEvent::ExpnNotFound - | SmtpEvent::ExpnDisabled => Level::Info, + | SmtpEvent::AuthNotAllowed + | SmtpEvent::AuthMechanismNotSupported + | SmtpEvent::ExpnDisabled + | SmtpEvent::RequestTooLarge + | SmtpEvent::TooManyRecipients => Level::Info, SmtpEvent::RawInput | SmtpEvent::RawOutput => Level::Trace, }, EventType::Network(event) => match event { @@ -813,7 +939,7 @@ impl EventType { | NetworkEvent::Closed => Level::Trace, NetworkEvent::Timeout | NetworkEvent::AcceptError => Level::Debug, NetworkEvent::ConnectionStart - | NetworkEvent::ConnectionStop + | NetworkEvent::ConnectionEnd | NetworkEvent::ListenStart | NetworkEvent::ListenStop | NetworkEvent::DropBlocked => Level::Info, @@ -1063,15 +1189,27 @@ impl EventType { | DeliveryEvent::StartTlsError | DeliveryEvent::StartTlsDisabled | DeliveryEvent::ImplicitTlsError - | DeliveryEvent::TooManyConcurrent | DeliveryEvent::DoubleBounce => Level::Info, - DeliveryEvent::MissingOutboundHostname => Level::Warn, + DeliveryEvent::ConcurrencyLimitExceeded + | DeliveryEvent::RateLimitExceeded + | DeliveryEvent::MissingOutboundHostname => Level::Warn, + DeliveryEvent::DsnSuccess + | DeliveryEvent::DsnTempFail + | DeliveryEvent::DsnPermFail => Level::Info, + DeliveryEvent::MxLookup + | DeliveryEvent::IpLookup + | DeliveryEvent::Ehlo + | DeliveryEvent::Auth + | DeliveryEvent::MailFrom + | DeliveryEvent::RcptTo => Level::Debug, + DeliveryEvent::RawInput | DeliveryEvent::RawOutput => Level::Trace, }, EventType::Queue(event) => match event { QueueEvent::RateLimitExceeded | QueueEvent::ConcurrencyLimitExceeded | QueueEvent::Scheduled - | QueueEvent::Rescheduled => Level::Info, + | QueueEvent::Rescheduled + | QueueEvent::QuotaExceeded => Level::Info, QueueEvent::LockBusy | QueueEvent::Locked | QueueEvent::BlobNotFound => { Level::Debug } @@ -1084,7 +1222,8 @@ impl EventType { | MtaStsEvent::PolicyNotFound | MtaStsEvent::PolicyFetchError | MtaStsEvent::InvalidPolicy - | MtaStsEvent::NotAuthorized => Level::Info, + | MtaStsEvent::NotAuthorized + | MtaStsEvent::Authorized => Level::Info, }, EventType::IncomingReport(event) => match event { IncomingReportEvent::DmarcReportWithWarnings diff --git a/crates/trc/src/lib.rs b/crates/trc/src/lib.rs index e058b6e6..e4b381eb 100644 --- a/crates/trc/src/lib.rs +++ b/crates/trc/src/lib.rs @@ -4,6 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +pub mod atomic; pub mod channel; pub mod collector; pub mod conv; @@ -77,7 +78,9 @@ pub enum Key { Property, Path, Url, + Used, Name, + OldName, DocumentId, Collection, AccountId, @@ -96,6 +99,7 @@ pub enum Key { Renewal, Attempt, NextRetry, + NextDsn, LocalIp, LocalPort, RemoteIp, @@ -138,6 +142,12 @@ pub enum Key { TotalSuccesses, TotalFailures, Date, + Uid, + UidValidity, + UidNext, + SourceAccountId, + SourceMailboxId, + SourceUid, } #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] @@ -231,23 +241,94 @@ pub enum FtsIndexEvent { #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] pub enum ImapEvent { - Error, - RawInput, - RawOutput, + // Commands + GetAcl, + SetAcl, + MyRights, + ListRights, + Append, + Capabilities, + Id, + Close, + Copy, + Move, + CreateMailbox, + DeleteMailbox, + RenameMailbox, + Enable, + Expunge, + Fetch, IdleStart, IdleStop, + List, + Lsub, + Logout, + Namespace, + Noop, + Search, + Sort, + Select, + Status, + Store, + Subscribe, + Unsubscribe, + Thread, + + // Errors + Error, + + // Debugging + RawInput, + RawOutput, } #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] pub enum Pop3Event { + // Commands + Delete, + Reset, + Quit, + Fetch, + List, + ListMessage, + Uidl, + UidlMessage, + Stat, + Noop, + Capabilities, + StartTls, + Utf8, + + // Errors Error, + + // Debugging RawInput, RawOutput, } #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] pub enum ManageSieveEvent { + // Commands + CreateScript, + UpdateScript, + GetScript, + DeleteScript, + RenameScript, + CheckScript, + HaveSpace, + ListScripts, + SetActive, + Capabilities, + StartTls, + Unauthenticate, + Logout, + Noop, + + // Errors Error, + + // Debugging RawInput, RawOutput, } @@ -278,14 +359,25 @@ pub enum SmtpEvent { DmarcFail, IprevPass, IprevFail, - QuotaExceeded, TooManyMessages, Ehlo, InvalidEhlo, + DidNotSayEhlo, + EhloExpected, + LhloExpected, + MailFromUnauthenticated, + MailFromUnauthorized, + MailFromRewritten, + MailFromMissing, MailFrom, + MultipleMailFrom, MailboxDoesNotExist, RelayNotAllowed, RcptTo, + RcptToDuplicate, + RcptToRewritten, + RcptToMissing, + TooManyRecipients, TooManyInvalidRcpt, RawInput, RawOutput, @@ -296,6 +388,33 @@ pub enum SmtpEvent { Expn, ExpnNotFound, ExpnDisabled, + RequireTlsDisabled, + DeliverByDisabled, + DeliverByInvalid, + FutureReleaseDisabled, + FutureReleaseInvalid, + MtPriorityDisabled, + MtPriorityInvalid, + DsnDisabled, + AuthNotAllowed, + AuthMechanismNotSupported, + AuthExchangeTooLong, + AlreadyAuthenticated, + Noop, + StartTls, + StartTlsUnavailable, + StartTlsAlready, + Rset, + Quit, + Help, + CommandNotImplemented, + InvalidCommand, + InvalidSenderAddress, + InvalidRecipientAddress, + InvalidParameter, + UnsupportedParameter, + SyntaxError, + RequestTooLarge, } #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] @@ -305,17 +424,23 @@ pub enum DeliveryEvent { Completed, Failed, AttemptCount, + MxLookup, MxLookupFailed, + IpLookup, IpLookupFailed, NullMX, Connect, ConnectError, MissingOutboundHostname, GreetingFailed, + Ehlo, EhloRejected, + Auth, AuthFailed, + MailFrom, MailFromRejected, Delivered, + RcptTo, RcptToRejected, RcptToFailed, MessageRejected, @@ -324,8 +449,14 @@ pub enum DeliveryEvent { StartTlsError, StartTlsDisabled, ImplicitTlsError, - TooManyConcurrent, + ConcurrencyLimitExceeded, + RateLimitExceeded, DoubleBounce, + DsnSuccess, + DsnTempFail, + DsnPermFail, + RawInput, + RawOutput, } #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] @@ -337,6 +468,7 @@ pub enum QueueEvent { BlobNotFound, RateLimitExceeded, ConcurrencyLimitExceeded, + QuotaExceeded, } #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] @@ -381,11 +513,12 @@ pub enum OutgoingReportEvent { #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] pub enum MtaStsEvent { + Authorized, + NotAuthorized, PolicyFetch, PolicyNotFound, PolicyFetchError, InvalidPolicy, - NotAuthorized, } #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] @@ -486,7 +619,7 @@ pub enum TlsEvent { #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] pub enum NetworkEvent { ConnectionStart, - ConnectionStop, + ConnectionEnd, ListenStart, ListenStop, ListenError, @@ -685,13 +818,18 @@ pub enum StoreEvent { // Traces SqlQuery, LdapQuery, + LdapBind, // Events Ingest, + IngestDuplicate, } #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] pub enum JmapEvent { + // Calls + MethodCall, + // Method errors InvalidArguments, RequestTooLarge, diff --git a/tests/Cargo.toml b/tests/Cargo.toml index b85de775..4304c274 100644 --- a/tests/Cargo.toml +++ b/tests/Cargo.toml @@ -8,7 +8,7 @@ resolver = "2" default = ["sqlite", "postgres", "mysql", "rocks", "elastic", "s3", "redis", "foundationdb"] #default = ["sqlite", "postgres", "mysql", "rocks", "elastic", "s3", "redis", "foundationdb"] sqlite = ["store/sqlite"] -foundationdb = ["store/foundation"] +foundationdb = ["store/foundation", "common/foundation"] postgres = ["store/postgres"] mysql = ["store/mysql"] rocks = ["store/rocks"] diff --git a/tests/src/imap/mod.rs b/tests/src/imap/mod.rs index 70999457..590e1449 100644 --- a/tests/src/imap/mod.rs +++ b/tests/src/imap/mod.rs @@ -31,7 +31,6 @@ use common::{ server::{ServerProtocol, Servers}, tracers::Tracer, }, - webhooks::manager::spawn_webhook_manager, Core, Ipc, IPC_CHANNEL_BUFFER, }; @@ -309,15 +308,9 @@ async fn init_imap_tests(store_id: &str, delete_if_exists: bool) -> IMAPTest { // Parse acceptors servers.parse_tcp_acceptors(&mut config, shared_core.clone()); - // Spawn webhook manager - let webhook_tx = spawn_webhook_manager(shared_core.clone()); - // Setup IPC channels let (delivery_tx, delivery_rx) = mpsc::channel(IPC_CHANNEL_BUFFER); - let ipc = Ipc { - delivery_tx, - webhook_tx, - }; + let ipc = Ipc { delivery_tx }; // Init servers let smtp = SMTP::init(&mut config, shared_core.clone(), ipc).await; diff --git a/tests/src/jmap/auth_acl.rs b/tests/src/jmap/auth_acl.rs index e5493d06..a45496a7 100644 --- a/tests/src/jmap/auth_acl.rs +++ b/tests/src/jmap/auth_acl.rs @@ -154,7 +154,7 @@ pub async fn test(params: &mut JMAPTest) { ); assert_forbidden( john_client - .set_default_account_id(&sales_id.to_string()) + .set_default_account_id(sales_id.to_string()) .email_get( email_ids.get("sales").unwrap().first().unwrap(), [Property::Subject].into(), @@ -163,7 +163,7 @@ pub async fn test(params: &mut JMAPTest) { ); assert_forbidden( john_client - .set_default_account_id(&sales_id.to_string()) + .set_default_account_id(sales_id.to_string()) .mailbox_get(&inbox_id, None::>) .await, ); @@ -238,7 +238,7 @@ pub async fn test(params: &mut JMAPTest) { .unwrap() .take_blob_id(); john_client - .set_default_account_id(&john_id.to_string()) + .set_default_account_id(john_id.to_string()) .blob_copy(jane_id.to_string(), &blob_id) .await .unwrap(); @@ -253,7 +253,7 @@ pub async fn test(params: &mut JMAPTest) { .take_blob_id(); assert_forbidden( john_client - .set_default_account_id(&john_id.to_string()) + .set_default_account_id(john_id.to_string()) .blob_copy(jane_id.to_string(), &blob_id) .await, ); @@ -284,7 +284,7 @@ pub async fn test(params: &mut JMAPTest) { // Try to add items using import and copy let blob_id = john_client - .set_default_account_id(&john_id.to_string()) + .set_default_account_id(john_id.to_string()) .upload( Some(&john_id.to_string()), concat!( @@ -703,7 +703,7 @@ pub async fn test(params: &mut JMAPTest) { // Insert a message in Sales's inbox let blob_id = john_client - .set_default_account_id(&sales_id.to_string()) + .set_default_account_id(sales_id.to_string()) .upload( Some(&sales_id.to_string()), concat!( @@ -737,7 +737,7 @@ pub async fn test(params: &mut JMAPTest) { // Both Jane and John should be able to see this message, but not Bill assert_eq!( john_client - .set_default_account_id(&sales_id.to_string()) + .set_default_account_id(sales_id.to_string()) .email_get(&email_id, [Property::Subject].into(),) .await .unwrap() @@ -748,7 +748,7 @@ pub async fn test(params: &mut JMAPTest) { ); assert_eq!( jane_client - .set_default_account_id(&sales_id.to_string()) + .set_default_account_id(sales_id.to_string()) .email_get(&email_id, [Property::Subject].into(),) .await .unwrap() @@ -759,7 +759,7 @@ pub async fn test(params: &mut JMAPTest) { ); assert_forbidden( bill_client - .set_default_account_id(&sales_id.to_string()) + .set_default_account_id(sales_id.to_string()) .email_get(&email_id, [Property::Subject].into()) .await, ); @@ -772,14 +772,14 @@ pub async fn test(params: &mut JMAPTest) { server.inner.sessions.clear(); assert_forbidden( john_client - .set_default_account_id(&sales_id.to_string()) + .set_default_account_id(sales_id.to_string()) .email_get(&email_id, [Property::Subject].into()) .await, ); // Destroy test account data for id in [john_id, bill_id, jane_id, sales_id] { - params.client.set_default_account_id(&id.to_string()); + params.client.set_default_account_id(id.to_string()); destroy_all_mailboxes(params).await; } assert_is_empty(server).await; diff --git a/tests/src/jmap/event_source.rs b/tests/src/jmap/event_source.rs index 5885260d..d868bbee 100644 --- a/tests/src/jmap/event_source.rs +++ b/tests/src/jmap/event_source.rs @@ -112,9 +112,7 @@ pub async fn test(params: &mut JMAPTest) { assert_state(&mut event_rx, &account_id, &[TypeState::Mailbox]).await; // Destroy Inbox - params - .client - .set_default_account_id(&account_id.to_string()); + params.client.set_default_account_id(account_id.to_string()); params .client .mailbox_destroy(&Id::from(INBOX_ID).to_string(), true) diff --git a/tests/src/jmap/mod.rs b/tests/src/jmap/mod.rs index c73ed46e..445571f8 100644 --- a/tests/src/jmap/mod.rs +++ b/tests/src/jmap/mod.rs @@ -16,7 +16,6 @@ use common::{ tracers::Tracer, }, manager::config::{ConfigManager, Patterns}, - webhooks::manager::spawn_webhook_manager, Core, Ipc, IPC_CHANNEL_BUFFER, }; use hyper::{header::AUTHORIZATION, Method}; @@ -477,15 +476,9 @@ async fn init_jmap_tests(store_id: &str, delete_if_exists: bool) -> JMAPTest { // Parse acceptors servers.parse_tcp_acceptors(&mut config, shared_core.clone()); - // Spawn webhook manager - let webhook_tx = spawn_webhook_manager(shared_core.clone()); - // Setup IPC channels let (delivery_tx, delivery_rx) = mpsc::channel(IPC_CHANNEL_BUFFER); - let ipc = Ipc { - delivery_tx, - webhook_tx, - }; + let ipc = Ipc { delivery_tx }; // Init servers let smtp = SMTP::init(&mut config, shared_core.clone(), ipc).await; diff --git a/tests/src/jmap/webhooks.rs b/tests/src/jmap/webhooks.rs index 97606dc2..8119bb29 100644 --- a/tests/src/jmap/webhooks.rs +++ b/tests/src/jmap/webhooks.rs @@ -13,10 +13,7 @@ use std::{ }; use base64::{engine::general_purpose::STANDARD, Engine}; -use common::{ - manager::webadmin::Resource, - webhooks::{WebhookEvent, WebhookEvents}, -}; +use common::manager::webadmin::Resource; use hyper::{body, server::conn::http1, service::service_fn}; use hyper_util::rt::TokioIo; use jmap::api::http::{fetch_body, ToHttpResponse}; @@ -29,7 +26,7 @@ use super::JMAPTest; pub struct MockWebhookEndpoint { pub tx: watch::Sender, - pub events: Mutex>, + pub events: Mutex>, pub reject: AtomicBool, } @@ -120,7 +117,11 @@ pub fn spawn_mock_webhook_endpoint() -> Arc { hmac::verify(&key, &body, &tag).expect("Invalid signature"); // Deserialize JSON - let request = serde_json::from_slice::(&body) + #[derive(serde::Deserialize)] + struct WebhookRequest { + events: Vec, + } + let request = serde_json::from_slice::(&body) .expect("Failed to parse JSON"); if !endpoint.reject.load(Ordering::Relaxed) { diff --git a/tests/src/smtp/config.rs b/tests/src/smtp/config.rs index a618e378..ab11ac7a 100644 --- a/tests/src/smtp/config.rs +++ b/tests/src/smtp/config.rs @@ -262,7 +262,7 @@ fn parse_throttles() { throttle, vec![ Throttle { - id: "0".to_string(), + id: "0000".to_string(), expr: Expression { items: vec![ ExpressionItem::Variable(8), @@ -279,7 +279,7 @@ fn parse_throttles() { .into() }, Throttle { - id: "1".to_string(), + id: "0001".to_string(), expr: Expression::default(), keys: THROTTLE_SENDER_DOMAIN, concurrency: 10000.into(), diff --git a/tests/src/store/import_export.rs b/tests/src/store/import_export.rs index 7123bc18..f71933b2 100644 --- a/tests/src/store/import_export.rs +++ b/tests/src/store/import_export.rs @@ -130,7 +130,7 @@ pub async fn test(db: Store) { batch.ops.push(Operation::Bitmap { class: BitmapClass::Text { field, - token: BitmapHash::new(&random_bytes(field as usize + 2)), + token: BitmapHash::new(random_bytes(field as usize + 2)), }, set: true, });