Add SMTP receipt logging for Exchange relay tracing

This commit is contained in:
2026-03-03 16:12:13 +13:00
parent 96333c0d85
commit 4f2b5e0922
5 changed files with 108 additions and 15 deletions

View File

@@ -6,8 +6,10 @@ import json
import logging
import re
import smtplib
from email.generator import BytesGenerator
from email.message import EmailMessage
from email.utils import formataddr
from io import BytesIO
from typing import Any, Dict, Optional
from ..build_info import BUILD_NUMBER
@@ -21,6 +23,8 @@ TEMPLATE_SETTING_PREFIX = "invite_email_template_"
TEMPLATE_KEYS = ("invited", "welcome", "warning", "banned")
EMAIL_PATTERN = re.compile(r"^[^@\s]+@[^@\s]+\.[^@\s]+$")
PLACEHOLDER_PATTERN = re.compile(r"{{\s*([a-zA-Z0-9_]+)\s*}}")
EXCHANGE_MESSAGE_ID_PATTERN = re.compile(r"<([^>]+)>")
EXCHANGE_INTERNAL_ID_PATTERN = re.compile(r"\[InternalId=([^\],]+)")
TEMPLATE_METADATA: Dict[str, Dict[str, Any]] = {
"invited": {
@@ -396,7 +400,56 @@ def smtp_email_delivery_warning() -> Optional[str]:
return None
def _send_email_sync(*, recipient_email: str, subject: str, body_text: str, body_html: str) -> None:
def _flatten_message(message: EmailMessage) -> bytes:
buffer = BytesIO()
BytesGenerator(buffer).flatten(message)
return buffer.getvalue()
def _decode_smtp_message(value: bytes | str | None) -> str:
if value is None:
return ""
if isinstance(value, bytes):
return value.decode("utf-8", errors="replace")
return str(value)
def _parse_exchange_receipt(value: bytes | str | None) -> Dict[str, str]:
message = _decode_smtp_message(value)
receipt: Dict[str, str] = {"raw": message}
message_id_match = EXCHANGE_MESSAGE_ID_PATTERN.search(message)
internal_id_match = EXCHANGE_INTERNAL_ID_PATTERN.search(message)
if message_id_match:
receipt["provider_message_id"] = message_id_match.group(1)
if internal_id_match:
receipt["provider_internal_id"] = internal_id_match.group(1)
return receipt
def _send_via_smtp_session(
smtp: smtplib.SMTP,
*,
from_address: str,
recipient_email: str,
message: EmailMessage,
) -> Dict[str, str]:
mail_code, mail_message = smtp.mail(from_address)
if mail_code >= 400:
raise smtplib.SMTPResponseException(mail_code, mail_message)
rcpt_code, rcpt_message = smtp.rcpt(recipient_email)
if rcpt_code >= 400:
raise smtplib.SMTPRecipientsRefused({recipient_email: (rcpt_code, rcpt_message)})
data_code, data_message = smtp.data(_flatten_message(message))
if data_code >= 400:
raise smtplib.SMTPDataError(data_code, data_message)
receipt = _parse_exchange_receipt(data_message)
receipt["mail_response"] = _decode_smtp_message(mail_message)
receipt["rcpt_response"] = _decode_smtp_message(rcpt_message)
receipt["data_response"] = _decode_smtp_message(data_message)
return receipt
def _send_email_sync(*, recipient_email: str, subject: str, body_text: str, body_html: str) -> Dict[str, str]:
runtime = get_runtime_settings()
host = _normalize_display_text(runtime.magent_notify_email_smtp_host)
port = int(runtime.magent_notify_email_smtp_port or 587)
@@ -437,9 +490,20 @@ def _send_email_sync(*, recipient_email: str, subject: str, body_text: str, body
if username and password:
smtp.login(username, password)
logger.debug("smtp login succeeded host=%s username=%s", host, username)
smtp.send_message(message)
logger.info("smtp send accepted recipient=%s host=%s mode=ssl", recipient_email, host)
return
receipt = _send_via_smtp_session(
smtp,
from_address=from_address,
recipient_email=recipient_email,
message=message,
)
logger.info(
"smtp send accepted recipient=%s host=%s mode=ssl provider_message_id=%s provider_internal_id=%s",
recipient_email,
host,
receipt.get("provider_message_id"),
receipt.get("provider_internal_id"),
)
return receipt
with smtplib.SMTP(host, port, timeout=20) as smtp:
logger.debug("smtp connection opened host=%s port=%s", host, port)
@@ -451,8 +515,20 @@ def _send_email_sync(*, recipient_email: str, subject: str, body_text: str, body
if username and password:
smtp.login(username, password)
logger.debug("smtp login succeeded host=%s username=%s", host, username)
smtp.send_message(message)
logger.info("smtp send accepted recipient=%s host=%s mode=plain", recipient_email, host)
receipt = _send_via_smtp_session(
smtp,
from_address=from_address,
recipient_email=recipient_email,
message=message,
)
logger.info(
"smtp send accepted recipient=%s host=%s mode=plain provider_message_id=%s provider_internal_id=%s",
recipient_email,
host,
receipt.get("provider_message_id"),
receipt.get("provider_internal_id"),
)
return receipt
async def send_templated_email(
@@ -484,7 +560,7 @@ async def send_templated_email(
reason=reason,
overrides=overrides,
)
await asyncio.to_thread(
receipt = await asyncio.to_thread(
_send_email_sync,
recipient_email=resolved_email,
subject=rendered["subject"],
@@ -495,6 +571,11 @@ async def send_templated_email(
return {
"recipient_email": resolved_email,
"subject": rendered["subject"],
**{
key: value
for key, value in receipt.items()
if key in {"provider_message_id", "provider_internal_id", "data_response"}
},
}
@@ -524,7 +605,7 @@ async def send_test_email(recipient_email: Optional[str] = None) -> Dict[str, st
f"<strong>Application URL:</strong> {html.escape(application_url)}</p>"
)
await asyncio.to_thread(
receipt = await asyncio.to_thread(
_send_email_sync,
recipient_email=resolved_email,
subject=subject,
@@ -533,6 +614,13 @@ async def send_test_email(recipient_email: Optional[str] = None) -> Dict[str, st
)
logger.info("SMTP test email sent: recipient=%s", resolved_email)
result = {"recipient_email": resolved_email, "subject": subject}
result.update(
{
key: value
for key, value in receipt.items()
if key in {"provider_message_id", "provider_internal_id", "data_response"}
}
)
warning = smtp_email_delivery_warning()
if warning:
result["warning"] = warning
@@ -575,7 +663,7 @@ async def send_password_reset_email(
"<p>If you did not request this reset, you can ignore this email.</p>"
)
await asyncio.to_thread(
receipt = await asyncio.to_thread(
_send_email_sync,
recipient_email=resolved_email,
subject=subject,
@@ -592,6 +680,11 @@ async def send_password_reset_email(
"recipient_email": resolved_email,
"subject": subject,
"reset_url": reset_url,
**{
key: value
for key, value in receipt.items()
if key in {"provider_message_id", "provider_internal_id", "data_response"}
},
}
warning = smtp_email_delivery_warning()
if warning: