Mirrors/chatmail-core
1
0
Fork 0
mirror of https://github.com/chatmail/core.git synced 2026-05-02 04:46:29 +03:00
Code Issues Packages Projects Releases Wiki Activity

refactor: improve SMTP logs and errors

Browse Source
This commit is contained in:
link2xt
2024-06-03 20:35:49 +00:00
parent cc7c235556
commit 79d1c96db4
3 changed files with 32 additions and 33 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
src/imap.rs
View File

@@ -313,7 +313,7 @@ impl Imap {
if !ratelimit_duration.is_zero() { if !ratelimit_duration.is_zero() {
warn!( warn!(
context, context,
"IMAP got rate limited, waiting for {} until can connect", "IMAP got rate limited, waiting for {} until can connect.",
duration_to_str(ratelimit_duration), duration_to_str(ratelimit_duration),
); );
let interrupted = async { let interrupted = async {

16
src/scheduler.rs
View File

@@ -749,7 +749,7 @@ async fn smtp_loop(
) { ) {
use futures::future::FutureExt; use futures::future::FutureExt;
info!(ctx, "starting smtp loop"); info!(ctx, "Starting SMTP loop.");
let SmtpConnectionHandlers { let SmtpConnectionHandlers {
mut connection, mut connection,
stop_receiver, stop_receiver,
@@ -760,14 +760,14 @@ async fn smtp_loop(
let fut = async move { let fut = async move {
let ctx = ctx1; let ctx = ctx1;
if let Err(()) = started.send(()) { if let Err(()) = started.send(()) {
warn!(&ctx, "smtp loop, missing started receiver"); warn!(&ctx, "SMTP loop, missing started receiver.");
return; return;
} }
let mut timeout = None; let mut timeout = None;
loop { loop {
if let Err(err) = send_smtp_messages(&ctx, &mut connection).await { if let Err(err) = send_smtp_messages(&ctx, &mut connection).await {
warn!(ctx, "send_smtp_messages failed: {:#}", err); warn!(ctx, "send_smtp_messages failed: {:#}.", err);
timeout = Some(timeout.unwrap_or(30)); timeout = Some(timeout.unwrap_or(30));
} else { } else {
timeout = None; timeout = None;
@@ -784,7 +784,7 @@ async fn smtp_loop(
} }
// Fake Idle // Fake Idle
info!(ctx, "smtp fake idle - started"); info!(ctx, "SMTP fake idle started.");
match &connection.last_send_error { match &connection.last_send_error {
None => connection.connectivity.set_idle(&ctx).await, None => connection.connectivity.set_idle(&ctx).await,
Some(err) => connection.connectivity.set_err(&ctx, err).await, Some(err) => connection.connectivity.set_err(&ctx, err).await,
@@ -798,7 +798,7 @@ async fn smtp_loop(
let now = tools::Time::now(); let now = tools::Time::now();
info!( info!(
ctx, ctx,
"smtp has messages to retry, planning to retry {} seconds later", t, "SMTP has messages to retry, planning to retry {t} seconds later."
); );
let duration = std::time::Duration::from_secs(t); let duration = std::time::Duration::from_secs(t);
tokio::time::timeout(duration, async { tokio::time::timeout(duration, async {
@@ -812,18 +812,18 @@ async fn smtp_loop(
slept.saturating_add(rand::thread_rng().gen_range((slept / 2)..=slept)), slept.saturating_add(rand::thread_rng().gen_range((slept / 2)..=slept)),
)); ));
} else { } else {
info!(ctx, "smtp has no messages to retry, waiting for interrupt"); info!(ctx, "SMTP has no messages to retry, waiting for interrupt.");
idle_interrupt_receiver.recv().await.unwrap_or_default(); idle_interrupt_receiver.recv().await.unwrap_or_default();
}; };
info!(ctx, "smtp fake idle - interrupted") info!(ctx, "SMTP fake idle interrupted.")
} }
}; };
stop_receiver stop_receiver
.recv() .recv()
.map(|_| { .map(|_| {
info!(ctx, "shutting down smtp loop"); info!(ctx, "Shutting down SMTP loop.");
}) })
.race(fut) .race(fut)
.await; .await;

47
src/smtp.rs
View File

@@ -87,7 +87,7 @@ impl Smtp {
/// Connect using configured parameters. /// Connect using configured parameters.
pub async fn connect_configured(&mut self, context: &Context) -> Result<()> { pub async fn connect_configured(&mut self, context: &Context) -> Result<()> {
if self.has_maybe_stale_connection() { if self.has_maybe_stale_connection() {
info!(context, "Closing stale connection"); info!(context, "Closing stale connection.");
self.disconnect(); self.disconnect();
} }
@@ -364,7 +364,7 @@ pub(crate) async fn smtp_send(
msg_id: MsgId, msg_id: MsgId,
) -> SendResult { ) -> SendResult {
if std::env::var(crate::DCC_MIME_DEBUG).is_ok() { if std::env::var(crate::DCC_MIME_DEBUG).is_ok() {
info!(context, "smtp-sending out mime message:"); info!(context, "SMTP-sending out mime message:");
println!("{message}"); println!("{message}");
} }
@@ -385,7 +385,7 @@ pub(crate) async fn smtp_send(
let status = match send_result { let status = match send_result {
Err(crate::smtp::send::Error::SmtpSend(err)) => { Err(crate::smtp::send::Error::SmtpSend(err)) => {
// Remote error, retry later. // Remote error, retry later.
info!(context, "SMTP failed to send: {:?}", &err); info!(context, "SMTP failed to send: {:?}.", &err);
let res = match err { let res = match err {
async_smtp::error::Error::Permanent(ref response) => { async_smtp::error::Error::Permanent(ref response) => {
@@ -412,10 +412,10 @@ pub(crate) async fn smtp_send(
}; };
if maybe_transient { if maybe_transient {
info!(context, "Permanent error that is likely to actually be transient, postponing retry for later"); info!(context, "Permanent error that is likely to actually be transient, postponing retry for later.");
SendResult::Retry SendResult::Retry
} else { } else {
info!(context, "Permanent error, message sending failed"); info!(context, "Permanent error, message sending failed.");
// If we do not retry, add an info message to the chat. // If we do not retry, add an info message to the chat.
// Yandex error "554 5.7.1 [2] Message rejected under suspicion of SPAM; https://ya.cc/..." // Yandex error "554 5.7.1 [2] Message rejected under suspicion of SPAM; https://ya.cc/..."
// should definitely go here, because user has to open the link to // should definitely go here, because user has to open the link to
@@ -436,20 +436,19 @@ pub(crate) async fn smtp_send(
// Any extended smtp status codes like x.1.1, x.1.2 or x.1.3 that we // Any extended smtp status codes like x.1.1, x.1.2 or x.1.3 that we
// receive as a transient error are misconfigurations of the smtp server. // receive as a transient error are misconfigurations of the smtp server.
// See <https://tools.ietf.org/html/rfc3463#section-3.2> // See <https://tools.ietf.org/html/rfc3463#section-3.2>
info!(context, "Received extended status code {} for a transient error. This looks like a misconfigured SMTP server, let's fail immediately", first_word); info!(context, "Received extended status code {first_word} for a transient error. This looks like a misconfigured SMTP server, let's fail immediately.");
SendResult::Failure(format_err!("Permanent SMTP error: {}", err)) SendResult::Failure(format_err!("Permanent SMTP error: {}", err))
} else { } else {
info!( info!(
context, context,
"Transient error with status code {}, postponing retry for later", "Transient error with status code {first_word}, postponing retry for later."
first_word
); );
SendResult::Retry SendResult::Retry
} }
} else { } else {
info!( info!(
context, context,
"Transient error without status code, postponing retry for later" "Transient error without status code, postponing retry for later."
); );
SendResult::Retry SendResult::Retry
} }
@@ -457,14 +456,14 @@ pub(crate) async fn smtp_send(
_ => { _ => {
info!( info!(
context, context,
"Message sending failed without error returned by the server, retry later" "Message sending failed without error returned by the server, retry later."
); );
SendResult::Retry SendResult::Retry
} }
}; };
// this clears last_success info // this clears last_success info
info!(context, "Failed to send message over SMTP, disconnecting"); info!(context, "Failed to send message over SMTP, disconnecting.");
smtp.disconnect(); smtp.disconnect();
res res
@@ -472,19 +471,19 @@ pub(crate) async fn smtp_send(
Err(crate::smtp::send::Error::Envelope(err)) => { Err(crate::smtp::send::Error::Envelope(err)) => {
// Local error, job is invalid, do not retry. // Local error, job is invalid, do not retry.
smtp.disconnect(); smtp.disconnect();
warn!(context, "SMTP job is invalid: {}", err); warn!(context, "SMTP job is invalid: {err:#}.");
SendResult::Failure(err) SendResult::Failure(err)
} }
Err(crate::smtp::send::Error::NoTransport) => { Err(crate::smtp::send::Error::NoTransport) => {
// Should never happen. // Should never happen.
// It does not even make sense to disconnect here. // It does not even make sense to disconnect here.
error!(context, "SMTP job failed because SMTP has no transport"); error!(context, "SMTP job failed because SMTP has no transport.");
SendResult::Failure(format_err!("SMTP has not transport")) SendResult::Failure(format_err!("SMTP has not transport"))
} }
Err(crate::smtp::send::Error::Other(err)) => { Err(crate::smtp::send::Error::Other(err)) => {
// Local error, job is invalid, do not retry. // Local error, job is invalid, do not retry.
smtp.disconnect(); smtp.disconnect();
warn!(context, "unable to load job: {}", err); warn!(context, "Unable to load SMTP job: {err:#}.");
SendResult::Failure(err) SendResult::Failure(err)
} }
Ok(()) => SendResult::Success, Ok(()) => SendResult::Success,
@@ -558,12 +557,12 @@ pub(crate) async fn send_msg_to_smtp(
.sql .sql
.execute("DELETE FROM smtp WHERE id=?", (rowid,)) .execute("DELETE FROM smtp WHERE id=?", (rowid,))
.await .await
.context("failed to remove message with exceeded retry limit from smtp table")?; .context("Failed to remove message with exceeded retry limit from smtp table")?;
return Ok(()); return Ok(());
} }
info!( info!(
context, context,
"Try number {retries} to send message {msg_id} (entry {rowid}) over SMTP" "Try number {retries} to send message {msg_id} (entry {rowid}) over SMTP."
); );
let recipients_list = recipients let recipients_list = recipients
@@ -572,7 +571,7 @@ pub(crate) async fn send_msg_to_smtp(
|addr| match async_smtp::EmailAddress::new(addr.to_string()) { |addr| match async_smtp::EmailAddress::new(addr.to_string()) {
Ok(addr) => Some(addr), Ok(addr) => Some(addr),
Err(err) => { Err(err) => {
warn!(context, "invalid recipient: {} {:?}", addr, err); warn!(context, "Invalid recipient: {} {:?}.", addr, err);
None None
} }
}, },
@@ -650,7 +649,7 @@ pub(crate) async fn send_msg_to_smtp(
async fn send_mdns(context: &Context, connection: &mut Smtp) -> Result<()> { async fn send_mdns(context: &Context, connection: &mut Smtp) -> Result<()> {
loop { loop {
if !context.ratelimit.read().await.can_send() { if !context.ratelimit.read().await.can_send() {
info!(context, "Ratelimiter does not allow sending MDNs now"); info!(context, "Ratelimiter does not allow sending MDNs now.");
return Ok(()); return Ok(());
} }
@@ -697,7 +696,7 @@ pub(crate) async fn send_smtp_messages(context: &Context, connection: &mut Smtp)
for rowid in rowids { for rowid in rowids {
send_msg_to_smtp(context, connection, rowid) send_msg_to_smtp(context, connection, rowid)
.await .await
.context("failed to send message")?; .context("Failed to send message")?;
} }
// although by slow sending, ratelimit may have been expired meanwhile, // although by slow sending, ratelimit may have been expired meanwhile,
@@ -706,7 +705,7 @@ pub(crate) async fn send_smtp_messages(context: &Context, connection: &mut Smtp)
if !ratelimited { if !ratelimited {
send_mdns(context, connection) send_mdns(context, connection)
.await .await
.context("failed to send MDNs")?; .context("Failed to send MDNs")?;
} }
Ok(()) Ok(())
} }
@@ -762,7 +761,7 @@ async fn send_mdn_msg_id(
match smtp_send(context, &recipients, &body, smtp, msg_id).await { match smtp_send(context, &recipients, &body, smtp, msg_id).await {
SendResult::Success => { SendResult::Success => {
info!(context, "Successfully sent MDN for {}", msg_id); info!(context, "Successfully sent MDN for {msg_id}.");
context context
.sql .sql
.execute("DELETE FROM smtp_mdns WHERE msg_id = ?", (msg_id,)) .execute("DELETE FROM smtp_mdns WHERE msg_id = ?", (msg_id,))
@@ -782,7 +781,7 @@ async fn send_mdn_msg_id(
SendResult::Retry => { SendResult::Retry => {
info!( info!(
context, context,
"Temporary SMTP failure while sending an MDN for {}", msg_id "Temporary SMTP failure while sending an MDN for {msg_id}."
); );
Ok(false) Ok(false)
} }
@@ -798,7 +797,7 @@ async fn send_mdn(context: &Context, smtp: &mut Smtp) -> Result<bool> {
context.sql.execute("DELETE FROM smtp_mdns", []).await?; context.sql.execute("DELETE FROM smtp_mdns", []).await?;
return Ok(false); return Ok(false);
} }
info!(context, "Sending MDNs"); info!(context, "Sending MDNs.");
context context
.sql .sql
@@ -828,7 +827,7 @@ async fn send_mdn(context: &Context, smtp: &mut Smtp) -> Result<bool> {
(msg_id,), (msg_id,),
) )
.await .await
.context("failed to update MDN retries count")?; .context("Failed to update MDN retries count")?;
match send_mdn_msg_id(context, msg_id, contact_id, smtp).await { match send_mdn_msg_id(context, msg_id, contact_id, smtp).await {
Err(err) => { Err(err) => {