filip/Stalwart
1
0
Fork 0
Code Issues Pull Requests Actions 1 Packages Projects Releases Wiki Activity

Increase SMTP transaction logging details

Browse Source
This commit is contained in:
mdecimus
2024-08-21 16:12:01 +02:00
parent 6d76b26fb8
commit 147d9ded86
47 changed files with 395 additions and 312 deletions
Download Patch File Download Diff File Expand all files Collapse all files

57
crates/smtp/src/outbound/client.rs
View File

@@ -617,3 +617,60 @@ pub enum StartTlsResult {
smtp_client: SmtpClient<TcpStream>,
},
}
pub(crate) fn from_mail_send_error(error: &mail_send::Error) -> trc::Error {
let event = trc::EventType::Smtp(trc::SmtpEvent::Error).into_err();
match error {
mail_send::Error::Io(err) => event.details("I/O Error").reason(err),
mail_send::Error::Tls(err) => event.details("TLS Error").reason(err),
mail_send::Error::Base64(err) => event.details("Base64 Error").reason(err),
mail_send::Error::Auth(err) => event.details("SMTP Authentication Error").reason(err),
mail_send::Error::UnparseableReply => event.details("Unparseable SMTP Reply"),
mail_send::Error::UnexpectedReply(reply) => event
.details("Unexpected SMTP Response")
.ctx(trc::Key::Code, reply.code)
.ctx(trc::Key::Reason, reply.message.clone()),
mail_send::Error::AuthenticationFailed(reply) => event
.details("SMTP Authentication Failed")
.ctx(trc::Key::Code, reply.code)
.ctx(trc::Key::Reason, reply.message.clone()),
mail_send::Error::InvalidTLSName => event.details("Invalid TLS Name"),
mail_send::Error::MissingCredentials => event.details("Missing Authentication Credentials"),
mail_send::Error::MissingMailFrom => event.details("Missing Message Sender"),
mail_send::Error::MissingRcptTo => event.details("Missing Message Recipients"),
mail_send::Error::UnsupportedAuthMechanism => {
event.details("Unsupported Authentication Mechanism")
}
mail_send::Error::Timeout => event.details("Connection Timeout"),
mail_send::Error::MissingStartTls => event.details("STARTTLS not available"),
}
}
pub(crate) fn from_error_status(status: &Status<(), Error>) -> trc::Error {
let event = trc::EventType::Smtp(trc::SmtpEvent::Error).into_err();
let err = match status {
Status::TemporaryFailure(err) | Status::PermanentFailure(err) => err,
Status::Scheduled | Status::Completed(_) => return event, // This should not happen
};
match err {
Error::DnsError(err) => event.details("DNS Error").reason(err),
Error::UnexpectedResponse(reply) => event
.details("Unexpected SMTP Response")
.ctx(trc::Key::Code, reply.response.code)
.ctx(trc::Key::Reason, reply.response.message.clone()),
Error::ConnectionError(err) => event
.details("Connection Error")
.ctx(trc::Key::Reason, err.details.clone()),
Error::TlsError(err) => event
.details("TLS Error")
.ctx(trc::Key::Reason, err.details.clone()),
Error::DaneError(err) => event
.details("DANE Error")
.ctx(trc::Key::Reason, err.details.clone()),
Error::MtaStsError(err) => event.details("MTA-STS Error").reason(err),
Error::RateLimited => todo!(),
Error::ConcurrencyLimited => todo!(),
Error::Io(err) => event.details("I/O Error").reason(err),
}
}

48
crates/smtp/src/outbound/delivery.rs
View File

@@ -4,7 +4,7 @@
* SPDX-License-Identifier: AGPL-3.0-only OR LicenseRef-SEL
*/
use crate::outbound::client::SmtpClient;
use crate::outbound::client::{from_error_status, from_mail_send_error, SmtpClient};
use crate::outbound::mta_sts::verify::VerifyPolicy;
use crate::outbound::{client::StartTlsResult, dane::verify::TlsaVerify};
use common::config::{
@@ -325,7 +325,15 @@ impl DeliveryAttempt {
TlsRpt(TlsRptEvent::RecordFetch),
SpanId = message.span_id,
Domain = domain.domain.clone(),
Details = format!("{record:?}"),
Details = record
.rua
.iter()
.map(|uri| trc::Value::from(match uri {
mail_auth::mta_sts::ReportUri::Mail(uri)
| mail_auth::mta_sts::ReportUri::Http(uri) =>
uri.to_string(),
}))
.collect::<Vec<_>>(),
Elapsed = time.elapsed(),
);
@@ -364,7 +372,12 @@ impl DeliveryAttempt {
MtaSts(MtaStsEvent::PolicyFetch),
SpanId = message.span_id,
Domain = domain.domain.clone(),
Details = mta_sts_policy.to_string(),
Strict = mta_sts_policy.enforce(),
Details = mta_sts_policy
.mx
.iter()
.map(|mx| trc::Value::String(mx.to_string()))
.collect::<Vec<_>>(),
Elapsed = time.elapsed(),
);
@@ -885,7 +898,7 @@ impl DeliveryAttempt {
LocalIp = source_ip,
RemoteIp = remote_ip,
RemotePort = remote_host.port(),
Reason = err.to_string(),
CausedBy = from_mail_send_error(&err),
Elapsed = time.elapsed(),
);
@@ -1018,11 +1031,17 @@ impl DeliveryAttempt {
Hostname = envelope.mx.to_string(),
Version = format!(
"{:?}",
smtp_client.tls_connection().protocol_version()
smtp_client
.tls_connection()
.protocol_version()
.unwrap()
),
Details = format!(
"{:?}",
smtp_client.tls_connection().negotiated_cipher_suite()
smtp_client
.tls_connection()
.negotiated_cipher_suite()
.unwrap()
),
Elapsed = time.elapsed(),
);
@@ -1097,7 +1116,12 @@ impl DeliveryAttempt {
SpanId = message.span_id,
Domain = domain.domain.clone(),
Hostname = envelope.mx.to_string(),
Details = reason.clone(),
Code = response.as_ref().map(|r| r.code()),
Details = response
.as_ref()
.map(|r| r.message().as_str())
.unwrap_or("STARTTLS was not advertised by host")
.to_string(),
Elapsed = time.elapsed(),
);
@@ -1141,7 +1165,7 @@ impl DeliveryAttempt {
SpanId = message.span_id,
Domain = domain.domain.clone(),
Hostname = envelope.mx.to_string(),
Reason = error.to_string(),
Reason = from_mail_send_error(&error),
Elapsed = time.elapsed(),
);
@@ -1206,7 +1230,7 @@ impl DeliveryAttempt {
SpanId = message.span_id,
Domain = domain.domain.clone(),
Hostname = envelope.mx.to_string(),
Reason = format!("{error:?}"),
Reason = from_mail_send_error(&error),
);
last_status = Status::from_tls_error(envelope.mx, error);
@@ -1226,7 +1250,7 @@ impl DeliveryAttempt {
SpanId = message.span_id,
Domain = domain.domain.clone(),
Hostname = envelope.mx.to_string(),
Details = status.to_string(),
Details = from_error_status(&status),
);
last_status = status;
@@ -1333,12 +1357,12 @@ impl Message {
for (idx, domain) in self.domains.iter_mut().enumerate() {
match &domain.status {
Status::TemporaryFailure(err) if domain.expires <= now => {
Status::TemporaryFailure(_) if domain.expires <= now => {
trc::event!(
Delivery(DeliveryEvent::Failed),
SpanId = self.span_id,
Domain = domain.domain.clone(),
Reason = err.to_string(),
Reason = from_error_status(&domain.status),
);
for rcpt in &mut self.recipients {

84
crates/smtp/src/outbound/session.rs
View File

@@ -5,7 +5,7 @@
*/
use common::config::smtp::queue::RequireOptional;
use mail_send::{smtp::AssertReply, Credentials};
use mail_send::Credentials;
use smtp_proto::{
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,
@@ -16,6 +16,7 @@ use std::{fmt::Write, time::Instant};
use tokio::io::{AsyncRead, AsyncWrite};
use trc::DeliveryEvent;
use crate::outbound::client::{from_error_status, from_mail_send_error};
use crate::{
core::SMTP,
queue::{ErrorDetails, HostResponse, RCPT_STATUS_CHANGED},
@@ -64,7 +65,7 @@ impl Message {
Delivery(DeliveryEvent::EhloRejected),
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
Reason = status.to_string(),
CausedBy = from_error_status(&status),
Elapsed = time.elapsed(),
);
smtp_client.quit().await;
@@ -80,7 +81,7 @@ impl Message {
Delivery(DeliveryEvent::AuthFailed),
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
Reason = err.to_string(),
CausedBy = from_mail_send_error(&err),
Elapsed = time.elapsed(),
);
@@ -117,31 +118,38 @@ impl Message {
let time = Instant::now();
smtp_client.timeout = params.timeout_mail;
let cmd = self.build_mail_from(&capabilities);
if let Err(err) = smtp_client
.cmd(cmd.as_bytes())
.await
.and_then(|r| r.assert_positive_completion())
{
trc::event!(
Delivery(DeliveryEvent::MailFromRejected),
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
Reason = err.to_string(),
Elapsed = time.elapsed(),
);
match smtp_client.cmd(cmd.as_bytes()).await.and_then(|r| {
if r.is_positive_completion() {
Ok(r)
} else {
Err(mail_send::Error::UnexpectedReply(r))
}
}) {
Ok(response) => {
trc::event!(
Delivery(DeliveryEvent::MailFrom),
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
From = self.return_path.to_string(),
Code = response.code,
Details = response.message.to_string(),
Elapsed = time.elapsed(),
);
}
Err(err) => {
trc::event!(
Delivery(DeliveryEvent::MailFromRejected),
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
CausedBy = from_mail_send_error(&err),
Elapsed = time.elapsed(),
);
smtp_client.quit().await;
return Status::from_smtp_error(params.hostname, &cmd, err);
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;
@@ -167,7 +175,8 @@ impl Message {
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
To = rcpt.address.to_string(),
Details = response.to_string(),
Code = response.code,
Details = response.message.to_string(),
Elapsed = time.elapsed(),
);
@@ -185,7 +194,8 @@ impl Message {
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
To = rcpt.address.to_string(),
Reason = response.to_string(),
Code = response.code,
Details = response.message.to_string(),
Elapsed = time.elapsed(),
);
@@ -211,7 +221,7 @@ impl Message {
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
To = rcpt.address.to_string(),
Reason = err.to_string(),
CausedBy = from_mail_send_error(&err),
Elapsed = time.elapsed(),
);
@@ -234,7 +244,7 @@ impl Message {
Delivery(DeliveryEvent::MessageRejected),
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
Reason = status.to_string(),
CausedBy = from_error_status(&status),
Elapsed = time.elapsed(),
);
@@ -257,7 +267,8 @@ impl Message {
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
To = rcpt.address.to_string(),
Details = status.to_string(),
Code = response.code,
Details = response.message.to_string(),
Elapsed = time.elapsed(),
);
@@ -270,7 +281,8 @@ impl Message {
Delivery(DeliveryEvent::MessageRejected),
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
Reason = response.to_string(),
Code = response.code,
Details = response.message.to_string(),
Elapsed = time.elapsed(),
);
@@ -287,7 +299,7 @@ impl Message {
Delivery(DeliveryEvent::MessageRejected),
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
Reason = status.to_string(),
CausedBy = from_error_status(&status),
Elapsed = time.elapsed(),
);
@@ -311,7 +323,8 @@ impl Message {
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
To = rcpt.address.to_string(),
Details = response.to_string(),
Code = response.code,
Details = response.message.to_string(),
Elapsed = time.elapsed(),
);
@@ -327,7 +340,8 @@ impl Message {
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
To = rcpt.address.to_string(),
Reason = response.to_string(),
Code = response.code,
Details = response.message.to_string(),
Elapsed = time.elapsed(),
);
@@ -356,7 +370,7 @@ impl Message {
Delivery(DeliveryEvent::MessageRejected),
SpanId = params.session_id,
Hostname = params.hostname.to_string(),
Reason = status.to_string(),
CausedBy = from_error_status(&status),
Elapsed = time.elapsed(),
);

18
crates/smtp/src/queue/dsn.rs
View File

@@ -17,6 +17,7 @@ use std::time::Duration;
use store::write::now;
use crate::core::SMTP;
use crate::outbound::client::from_error_status;
use super::{
Domain, Error, ErrorDetails, HostResponse, Message, MessageSource, QueueEnvelope, Recipient,
@@ -79,7 +80,8 @@ impl SMTP {
SpanId = message.span_id,
To = rcpt.address_lcase.clone(),
Hostname = response.hostname.clone(),
Details = response.response.to_string(),
Code = response.response.code,
Details = response.response.message.to_string(),
);
}
Status::TemporaryFailure(response) if domain.notify.due <= now => {
@@ -88,7 +90,8 @@ impl SMTP {
SpanId = message.span_id,
To = rcpt.address_lcase.clone(),
Hostname = response.hostname.entity.clone(),
Details = response.response.to_string(),
Code = response.response.code,
Details = response.response.message.to_string(),
NextRetry = trc::Value::Timestamp(domain.retry.due),
Expires = trc::Value::Timestamp(domain.expires),
Total = domain.retry.inner,
@@ -100,28 +103,29 @@ impl SMTP {
SpanId = message.span_id,
To = rcpt.address_lcase.clone(),
Hostname = response.hostname.entity.clone(),
Details = response.response.to_string(),
Code = response.response.code,
Details = response.response.message.to_string(),
Total = domain.retry.inner,
);
}
Status::Scheduled => {
// There is no status for this address, use the domain's status.
match &domain.status {
Status::PermanentFailure(err) => {
Status::PermanentFailure(_) => {
trc::event!(
Delivery(trc::DeliveryEvent::DsnPermFail),
SpanId = message.span_id,
To = rcpt.address_lcase.clone(),
Details = err.to_string(),
Details = from_error_status(&domain.status),
Total = domain.retry.inner,
);
}
Status::TemporaryFailure(err) if domain.notify.due <= now => {
Status::TemporaryFailure(_) if domain.notify.due <= now => {
trc::event!(
Delivery(trc::DeliveryEvent::DsnTempFail),
SpanId = message.span_id,
To = rcpt.address_lcase.clone(),
Details = err.to_string(),
Details = from_error_status(&domain.status),
NextRetry = trc::Value::Timestamp(domain.retry.due),
Expires = trc::Value::Timestamp(domain.expires),
Total = domain.retry.inner,