Add elapsed times to message filtering events

This commit is contained in:
mdecimus 2024-08-23 17:09:26 +02:00
parent dcc31e8b3e
commit e4cd866be4
11 changed files with 113 additions and 48 deletions

View file

@ -421,6 +421,9 @@ impl StoreTracer {
| AuthEvent::Banned
| AuthEvent::Error
)
| EventType::Sieve(_)
| EventType::Milter(_)
| EventType::MtaHook(_)
)
})
}

View file

@ -42,10 +42,14 @@ impl JMAP {
path: Vec<&str>,
body: Option<Vec<u8>>,
) -> trc::Result<HttpResponse> {
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,

View file

@ -446,6 +446,7 @@ impl<T: SessionStream> Session<T> {
{
command.arg(argument);
}
let time = Instant::now();
match command
.stdin(Stdio::piped())
.stdout(Stdio::piped())
@ -475,6 +476,7 @@ impl<T: SessionStream> Session<T> {
SpanId = self.data.session_id,
Path = command_,
Result = output.status.to_string(),
Elapsed = time.elapsed(),
);
}
Ok(Err(err)) => {
@ -482,6 +484,7 @@ impl<T: SessionStream> Session<T> {
Smtp(SmtpEvent::PipeError),
SpanId = self.data.session_id,
Reason = err.to_string(),
Elapsed = time.elapsed(),
);
}
Err(_) => {
@ -489,6 +492,7 @@ impl<T: SessionStream> Session<T> {
Smtp(SmtpEvent::PipeError),
SpanId = self.data.session_id,
Reason = "Timeout",
Elapsed = time.elapsed(),
);
}
}
@ -498,6 +502,7 @@ impl<T: SessionStream> Session<T> {
Smtp(SmtpEvent::PipeError),
SpanId = self.data.session_id,
Reason = err.to_string(),
Elapsed = time.elapsed(),
);
}
Err(_) => {
@ -505,6 +510,7 @@ impl<T: SessionStream> Session<T> {
Smtp(SmtpEvent::PipeError),
SpanId = self.data.session_id,
Reason = "Stdin timeout",
Elapsed = time.elapsed(),
);
}
}
@ -513,6 +519,7 @@ impl<T: SessionStream> Session<T> {
Smtp(SmtpEvent::PipeError),
SpanId = self.data.session_id,
Reason = "Stdin not available",
Elapsed = time.elapsed(),
);
}
}
@ -528,12 +535,17 @@ impl<T: SessionStream> Session<T> {
}
// Sieve filtering
if let Some(script) = self
if let Some((script, script_id)) = self
.core
.core
.eval_if::<String, _>(&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<T: SessionStream> Session<T> {
.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,

View file

@ -75,7 +75,7 @@ impl<T: SessionStream> Session<T> {
}
// Sieve filtering
if let Some(script) = self
if let Some((script, script_id)) = self
.core
.core
.eval_if::<String, _>(
@ -84,10 +84,19 @@ impl<T: SessionStream> Session<T> {
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;

View file

@ -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<T: SessionStream> Session<T> {
continue;
}
let time = Instant::now();
match self.run_mta_hook(stage, mta_hook, message).await {
Ok(response) => {
trc::event!(
@ -61,11 +64,7 @@ impl<T: SessionStream> Session<T> {
}),
SpanId = self.data.session_id,
Id = mta_hook.id.clone(),
Contents = response
.modifications
.iter()
.map(|m| format!("{m:?}"))
.collect::<Vec<_>>()
Elapsed = time.elapsed(),
);
let mut new_modifications = Vec::with_capacity(response.modifications.len());
@ -157,6 +156,7 @@ impl<T: SessionStream> Session<T> {
SpanId = self.data.session_id,
Id = mta_hook.id.clone(),
Reason = err,
Elapsed = time.elapsed(),
);
if mta_hook.tempfail_on_error {

View file

@ -121,7 +121,7 @@ impl<T: SessionStream> Session<T> {
.into();
// Sieve filtering
if let Some(script) = self
if let Some((script, script_id)) = self
.core
.core
.eval_if::<String, _>(
@ -130,10 +130,19 @@ impl<T: SessionStream> Session<T> {
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 } => {

View file

@ -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<T: SessionStream> Session<T> {
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::<Vec<_>>(),
Elapsed = time.elapsed(),
);
if !modifications.is_empty() {
@ -95,6 +93,7 @@ impl<T: SessionStream> Session<T> {
}),
SpanId = self.data.session_id,
Id = milter.id.to_string(),
Elapsed = time.elapsed(),
);
return Err(match action {
@ -144,6 +143,7 @@ impl<T: SessionStream> Session<T> {
SpanId = self.data.session_id,
Id = milter.id.to_string(),
Details = details,
Elapsed = time.elapsed(),
);
if milter.tempfail_on_error {

View file

@ -85,8 +85,12 @@ impl<T: SessionStream> Session<T> {
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<T: SessionStream> Session<T> {
.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 } => {

View file

@ -84,15 +84,24 @@ impl<T: SessionStream> Session<T> {
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::<String, _>(&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;

View file

@ -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<Sieve>,
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::<Vec<_>>(),
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::<Vec<_>>(),
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::<Vec<_>>(),
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
}

View file

@ -120,11 +120,13 @@ impl<T: SessionStream> Session<T> {
pub async fn run_script(
&self,
script_id: String,
script: Arc<Sieve>,
params: ScriptParameters<'_>,
) -> ScriptResult {
self.core
.run_script(
script_id,
script,
params
.with_envelope(&self.core.core, self, self.data.session_id)