diff --git a/crates/common/src/telemetry/tracers/store.rs b/crates/common/src/telemetry/tracers/store.rs index c7e71c19..a6297528 100644 --- a/crates/common/src/telemetry/tracers/store.rs +++ b/crates/common/src/telemetry/tracers/store.rs @@ -421,6 +421,9 @@ impl StoreTracer { | AuthEvent::Banned | AuthEvent::Error ) + | EventType::Sieve(_) + | EventType::Milter(_) + | EventType::MtaHook(_) ) }) } diff --git a/crates/jmap/src/api/management/sieve.rs b/crates/jmap/src/api/management/sieve.rs index 80fa9d5f..7a27de7c 100644 --- a/crates/jmap/src/api/management/sieve.rs +++ b/crates/jmap/src/api/management/sieve.rs @@ -42,10 +42,14 @@ impl JMAP { path: Vec<&str>, body: Option>, ) -> trc::Result { - let script = match ( - path.get(1) - .and_then(|name| self.core.sieve.scripts.get(*name)) - .cloned(), + let (script, script_id) = match ( + path.get(1).and_then(|name| { + self.core + .sieve + .scripts + .get(*name) + .map(|s| (s.clone(), name.to_string())) + }), req.method(), ) { (Some(script), &Method::POST) => script, @@ -94,7 +98,7 @@ impl JMAP { } // Run script - let result = match self.smtp.run_script(script, params, 0).await { + let result = match self.smtp.run_script(script_id, script, params, 0).await { ScriptResult::Accept { modifications } => Response::Accept { modifications }, ScriptResult::Replace { message, diff --git a/crates/smtp/src/inbound/data.rs b/crates/smtp/src/inbound/data.rs index 985cf655..c0fe7656 100644 --- a/crates/smtp/src/inbound/data.rs +++ b/crates/smtp/src/inbound/data.rs @@ -446,6 +446,7 @@ impl Session { { command.arg(argument); } + let time = Instant::now(); match command .stdin(Stdio::piped()) .stdout(Stdio::piped()) @@ -475,6 +476,7 @@ impl Session { SpanId = self.data.session_id, Path = command_, Result = output.status.to_string(), + Elapsed = time.elapsed(), ); } Ok(Err(err)) => { @@ -482,6 +484,7 @@ impl Session { Smtp(SmtpEvent::PipeError), SpanId = self.data.session_id, Reason = err.to_string(), + Elapsed = time.elapsed(), ); } Err(_) => { @@ -489,6 +492,7 @@ impl Session { Smtp(SmtpEvent::PipeError), SpanId = self.data.session_id, Reason = "Timeout", + Elapsed = time.elapsed(), ); } } @@ -498,6 +502,7 @@ impl Session { Smtp(SmtpEvent::PipeError), SpanId = self.data.session_id, Reason = err.to_string(), + Elapsed = time.elapsed(), ); } Err(_) => { @@ -505,6 +510,7 @@ impl Session { Smtp(SmtpEvent::PipeError), SpanId = self.data.session_id, Reason = "Stdin timeout", + Elapsed = time.elapsed(), ); } } @@ -513,6 +519,7 @@ impl Session { Smtp(SmtpEvent::PipeError), SpanId = self.data.session_id, Reason = "Stdin not available", + Elapsed = time.elapsed(), ); } } @@ -528,12 +535,17 @@ impl Session { } // Sieve filtering - if let Some(script) = self + if let Some((script, script_id)) = self .core .core .eval_if::(&dc.script, self, self.data.session_id) .await - .and_then(|name| self.core.core.get_sieve_script(&name, self.data.session_id)) + .and_then(|name| { + self.core + .core + .get_sieve_script(&name, self.data.session_id) + .map(|s| (s, name)) + }) { let params = self .build_script_parameters("data") @@ -584,7 +596,7 @@ impl Session { .unwrap_or_default(), ); - let modifications = match self.run_script(script.clone(), params).await { + let modifications = match self.run_script(script_id, script.clone(), params).await { ScriptResult::Accept { modifications } => modifications, ScriptResult::Replace { message, diff --git a/crates/smtp/src/inbound/ehlo.rs b/crates/smtp/src/inbound/ehlo.rs index f468cae2..74371432 100644 --- a/crates/smtp/src/inbound/ehlo.rs +++ b/crates/smtp/src/inbound/ehlo.rs @@ -75,7 +75,7 @@ impl Session { } // Sieve filtering - if let Some(script) = self + if let Some((script, script_id)) = self .core .core .eval_if::( @@ -84,10 +84,19 @@ impl Session { self.data.session_id, ) .await - .and_then(|name| self.core.core.get_sieve_script(&name, self.data.session_id)) + .and_then(|name| { + self.core + .core + .get_sieve_script(&name, self.data.session_id) + .map(|s| (s, name)) + }) { if let ScriptResult::Reject(message) = self - .run_script(script.clone(), self.build_script_parameters("ehlo")) + .run_script( + script_id, + script.clone(), + self.build_script_parameters("ehlo"), + ) .await { self.data.mail_from = None; diff --git a/crates/smtp/src/inbound/hooks/message.rs b/crates/smtp/src/inbound/hooks/message.rs index 99d4b2ad..b2b8750a 100644 --- a/crates/smtp/src/inbound/hooks/message.rs +++ b/crates/smtp/src/inbound/hooks/message.rs @@ -4,6 +4,8 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ +use std::time::Instant; + use ahash::AHashMap; use common::{ config::smtp::session::{MTAHook, Stage}, @@ -50,6 +52,7 @@ impl Session { continue; } + let time = Instant::now(); match self.run_mta_hook(stage, mta_hook, message).await { Ok(response) => { trc::event!( @@ -61,11 +64,7 @@ impl Session { }), SpanId = self.data.session_id, Id = mta_hook.id.clone(), - Contents = response - .modifications - .iter() - .map(|m| format!("{m:?}")) - .collect::>() + Elapsed = time.elapsed(), ); let mut new_modifications = Vec::with_capacity(response.modifications.len()); @@ -157,6 +156,7 @@ impl Session { SpanId = self.data.session_id, Id = mta_hook.id.clone(), Reason = err, + Elapsed = time.elapsed(), ); if mta_hook.tempfail_on_error { diff --git a/crates/smtp/src/inbound/mail.rs b/crates/smtp/src/inbound/mail.rs index 5e57c722..f215090a 100644 --- a/crates/smtp/src/inbound/mail.rs +++ b/crates/smtp/src/inbound/mail.rs @@ -121,7 +121,7 @@ impl Session { .into(); // Sieve filtering - if let Some(script) = self + if let Some((script, script_id)) = self .core .core .eval_if::( @@ -130,10 +130,19 @@ impl Session { self.data.session_id, ) .await - .and_then(|name| self.core.core.get_sieve_script(&name, self.data.session_id)) + .and_then(|name| { + self.core + .core + .get_sieve_script(&name, self.data.session_id) + .map(|s| (s, name)) + }) { match self - .run_script(script.clone(), self.build_script_parameters("mail")) + .run_script( + script_id, + script.clone(), + self.build_script_parameters("mail"), + ) .await { ScriptResult::Accept { modifications } => { diff --git a/crates/smtp/src/inbound/milter/message.rs b/crates/smtp/src/inbound/milter/message.rs index aa5ede83..1bcbde1b 100644 --- a/crates/smtp/src/inbound/milter/message.rs +++ b/crates/smtp/src/inbound/milter/message.rs @@ -4,7 +4,7 @@ * SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL */ -use std::borrow::Cow; +use std::{borrow::Cow, time::Instant}; use common::{ config::smtp::session::{Milter, Stage}, @@ -53,16 +53,14 @@ impl Session { continue; } + let time = Instant::now(); match self.connect_and_run(milter, message).await { Ok(new_modifications) => { trc::event!( Milter(MilterEvent::ActionAccept), SpanId = self.data.session_id, Id = milter.id.to_string(), - Contents = new_modifications - .iter() - .map(|m| m.to_string()) - .collect::>(), + Elapsed = time.elapsed(), ); if !modifications.is_empty() { @@ -95,6 +93,7 @@ impl Session { }), SpanId = self.data.session_id, Id = milter.id.to_string(), + Elapsed = time.elapsed(), ); return Err(match action { @@ -144,6 +143,7 @@ impl Session { SpanId = self.data.session_id, Id = milter.id.to_string(), Details = details, + Elapsed = time.elapsed(), ); if milter.tempfail_on_error { diff --git a/crates/smtp/src/inbound/rcpt.rs b/crates/smtp/src/inbound/rcpt.rs index 1cbe0787..b0acde6d 100644 --- a/crates/smtp/src/inbound/rcpt.rs +++ b/crates/smtp/src/inbound/rcpt.rs @@ -85,8 +85,12 @@ impl Session { self.data.session_id, ) .await - .and_then(|name| self.core.core.get_sieve_script(&name, self.data.session_id)) - .cloned(); + .and_then(|name| { + self.core + .core + .get_sieve_script(&name, self.data.session_id) + .map(|s| (s.clone(), name)) + }); if rcpt_script.is_some() || !self.core.core.smtp.session.rcpt.rewrite.is_empty() @@ -100,9 +104,13 @@ impl Session { .any(|m| m.run_on_stage.contains(&Stage::Rcpt)) { // Sieve filtering - if let Some(script) = rcpt_script { + if let Some((script, script_id)) = rcpt_script { match self - .run_script(script.clone(), self.build_script_parameters("rcpt")) + .run_script( + script_id, + script.clone(), + self.build_script_parameters("rcpt"), + ) .await { ScriptResult::Accept { modifications } => { diff --git a/crates/smtp/src/inbound/spawn.rs b/crates/smtp/src/inbound/spawn.rs index 9f8d8dca..fb551037 100644 --- a/crates/smtp/src/inbound/spawn.rs +++ b/crates/smtp/src/inbound/spawn.rs @@ -84,15 +84,24 @@ impl Session { let config = &self.core.core.smtp.session.connect; // Sieve filtering - if let Some(script) = self + if let Some((script, script_id)) = self .core .core .eval_if::(&config.script, self, self.data.session_id) .await - .and_then(|name| self.core.core.get_sieve_script(&name, self.data.session_id)) + .and_then(|name| { + self.core + .core + .get_sieve_script(&name, self.data.session_id) + .map(|s| (s, name)) + }) { if let ScriptResult::Reject(message) = self - .run_script(script.clone(), self.build_script_parameters("connect")) + .run_script( + script_id, + script.clone(), + self.build_script_parameters("connect"), + ) .await { let _ = self.write(message.as_bytes()).await; diff --git a/crates/smtp/src/scripts/event_loop.rs b/crates/smtp/src/scripts/event_loop.rs index 666ae216..e617729e 100644 --- a/crates/smtp/src/scripts/event_loop.rs +++ b/crates/smtp/src/scripts/event_loop.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 common::scripts::plugins::PluginContext; use mail_auth::common::headers::HeaderWriter; @@ -29,11 +29,13 @@ use super::{ScriptModification, ScriptParameters, ScriptResult}; impl SMTP { pub async fn run_script( &self, + script_id: String, script: Arc, params: ScriptParameters<'_>, session_id: u64, ) -> ScriptResult { // Create filter instance + let time = Instant::now(); let mut instance = self .core .sieve @@ -62,8 +64,9 @@ impl SMTP { } else { trc::event!( Sieve(SieveEvent::ScriptNotFound), + Id = script_id.clone(), SpanId = session_id, - Id = name.as_str().to_string(), + Details = name.as_str().to_string(), ); break; } @@ -95,8 +98,9 @@ impl SMTP { } else { trc::event!( Sieve(SieveEvent::ListNotFound), + Id = script_id.clone(), SpanId = session_id, - Id = list, + Details = list, ); } } @@ -157,8 +161,9 @@ impl SMTP { Recipient::List(list) => { trc::event!( Sieve(SieveEvent::NotSupported), + Id = script_id.clone(), SpanId = session_id, - Id = list, + Details = list, Reason = "Sending to lists is not supported.", ); } @@ -300,6 +305,7 @@ impl SMTP { trc::event!( Sieve(SieveEvent::QuotaExceeded), SpanId = session_id, + Id = script_id.clone(), From = message.return_path_lcase, To = message .recipients @@ -326,6 +332,7 @@ impl SMTP { unsupported => { trc::event!( Sieve(SieveEvent::NotSupported), + Id = script_id.clone(), SpanId = session_id, Reason = "Unsupported event", Details = format!("{unsupported:?}"), @@ -336,6 +343,7 @@ impl SMTP { Err(err) => { trc::event!( Sieve(SieveEvent::RuntimeError), + Id = script_id.clone(), SpanId = session_id, Reason = err.to_string(), ); @@ -380,18 +388,18 @@ impl SMTP { trc::event!( Sieve(SieveEvent::ActionAccept), SpanId = session_id, - Details = modifications - .iter() - .map(|m| trc::Value::from(format!("{m:?}"))) - .collect::>(), + Id = script_id, + Elapsed = time.elapsed(), ); ScriptResult::Accept { modifications } } else if let Some(mut reject_reason) = reject_reason { trc::event!( Sieve(SieveEvent::ActionReject), + Id = script_id, SpanId = session_id, Details = reject_reason.clone(), + Elapsed = time.elapsed(), ); if !reject_reason.ends_with('\n') { @@ -412,10 +420,8 @@ impl SMTP { trc::event!( Sieve(SieveEvent::ActionAccept), SpanId = session_id, - Details = modifications - .iter() - .map(|m| trc::Value::from(format!("{m:?}"))) - .collect::>(), + Id = script_id, + Elapsed = time.elapsed(), ); ScriptResult::Replace { @@ -426,16 +432,19 @@ impl SMTP { trc::event!( Sieve(SieveEvent::ActionAcceptReplace), SpanId = session_id, - Details = modifications - .iter() - .map(|m| trc::Value::from(format!("{m:?}"))) - .collect::>(), + Id = script_id, + Elapsed = time.elapsed(), ); ScriptResult::Accept { modifications } } } else { - trc::event!(Sieve(SieveEvent::ActionDiscard), SpanId = session_id,); + trc::event!( + Sieve(SieveEvent::ActionDiscard), + SpanId = session_id, + Id = script_id, + Elapsed = time.elapsed() + ); ScriptResult::Discard } diff --git a/crates/smtp/src/scripts/exec.rs b/crates/smtp/src/scripts/exec.rs index 3b16472b..ec85c80b 100644 --- a/crates/smtp/src/scripts/exec.rs +++ b/crates/smtp/src/scripts/exec.rs @@ -120,11 +120,13 @@ impl Session { pub async fn run_script( &self, + script_id: String, script: Arc, params: ScriptParameters<'_>, ) -> ScriptResult { self.core .run_script( + script_id, script, params .with_envelope(&self.core.core, self, self.data.session_id)