Merge pull request #113 from christianlouis/copilot/debug-imap-errors-t-online

Fix IMAP "Too many invalid IMAP commands" / mid-session BYE errors
This commit is contained in:
Christian Krakau-Louis
2026-03-28 21:22:03 +01:00
committed by GitHub
4 changed files with 503 additions and 46 deletions
+5
View File
@@ -28,9 +28,14 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
- Dashboard "Recent Processing Runs" table replaced with a per-account **Mailbox Status** view: each account now shows its last-check status (OK / Error / Pending), relative last-check time, any error message, and lifetime processed/failed counters. The noisy per-run table is gone; full activity history remains available on the Logs page.
- Stats cards updated: "Emails Forwarded Today" → "Emails Processed" (all-time total from account records); "Errors" → "Accounts with Errors" (count of accounts currently showing an error).
- **IMAP: switched to UID-based commands** (`UID SEARCH`, `UID FETCH`, `UID STORE`) instead of volatile sequence-number-based commands. Sequence numbers shift whenever other messages are expunged, causing the wrong messages to be targeted and triggering "Too many invalid IMAP commands" errors on strict servers like T-Online. UIDs remain stable for the lifetime of a mailbox.
### Fixed
- Provider logos now appear on the Mail Accounts page: `provider_name` is correctly saved when creating accounts via the provider wizard and propagated through backend/frontend schemas.
- Fetch-emails button now shows a text label ("Fetch"), a descriptive tooltip, a "Fetching…" loading state, and a brief green "Queued!" confirmation after the action completes.
- **IMAP: eliminated redundant per-message `STORE +FLAGS \Seen`** — RFC822 FETCH implicitly marks a message as `\Seen` on IMAP servers, making the extra round-trip unnecessary. This reduces the total command count by *N* per polling cycle.
- **IMAP: batch `STORE +FLAGS \Deleted`** — when `delete_after_forward` is enabled, all successfully fetched UIDs are now marked for deletion in a single `UID STORE uid1,uid2,…` command instead of one command per message.
- **IMAP: batch re-marking of stale UIDs** — UIDs already tracked in the database that still appear as UNSEEN on the server (e.g. because a previous STORE failed) are now re-marked `\Seen` with a single batch command instead of one STORE per message.
- **IMAP: graceful BYE handling** — the IMAP client is now stored in a variable so the `finally` block always attempts a clean `logout()`. If the server has already sent `BYE` and closed the connection the logout failure is swallowed silently, preventing it from masking the original error.
## v0.3.2 (2026-03-28)
+114 -46
View File
@@ -263,10 +263,26 @@ class MailProcessor:
async def _fetch_imap_emails(
self, max_count: int, already_seen_uids: Set[str]
) -> Tuple[List[bytes], List[str]]:
"""Fetch emails via IMAP, marking each message \\Seen to prevent re-fetch."""
"""Fetch emails via IMAP using UID-based commands.
UIDs are stable identifiers that do not change when other messages are
expunged, unlike IMAP sequence numbers. Sequence-number-based FETCH /
STORE commands can target the wrong message mid-session and cause
servers to report "Too many invalid IMAP commands" (as seen with
t-online). This implementation:
* Uses ``UID SEARCH``, ``UID FETCH``, and ``UID STORE`` throughout.
* Re-marks already-processed UIDs as \\Seen in a single batch command
instead of one STORE per message.
* Relies on the implicit \\Seen flag set by RFC822 FETCH so no
additional per-message STORE is needed for newly fetched mail.
* Batches the \\Deleted STORE into a single command when
``delete_after_forward`` is enabled.
"""
emails: List[bytes] = []
new_uids: List[str] = []
imap_client = None
try:
# Create IMAP client
if self.account.protocol == MailProtocol.IMAP_SSL:
@@ -282,70 +298,122 @@ class MailProcessor:
await imap_client.login(self.account.username, self.password)
await imap_client.select("INBOX")
# Search for unseen messages only
response = await imap_client.search("UNSEEN")
message_ids = response.lines[0].split()
# UID SEARCH returns stable UIDs instead of volatile sequence numbers.
response = await imap_client.uid("search", "UNSEEN")
if (
response.result != "OK"
or not response.lines
or not response.lines[0].strip()
):
logger.info(f"Found 0 unread messages for account {self.account.id}")
# logout is handled by the finally block below
return emails, new_uids
# Limit to max_count
message_ids = message_ids[:max_count]
all_unseen_uids: List[bytes] = response.lines[0].split()
# Limit to max_count before doing any further work.
all_unseen_uids = all_unseen_uids[:max_count]
logger.info(
f"Found {len(message_ids)} unread messages for account {self.account.id}"
f"Found {len(all_unseen_uids)} unread messages for account "
f"{self.account.id}"
)
# Fetch each message
for msg_id in message_ids:
uid_str = msg_id.decode() if isinstance(msg_id, bytes) else str(msg_id)
# Skip messages already tracked in our DB
# Split into stale UIDs (already in our DB but still UNSEEN on the
# server — e.g. a previous STORE failed) and genuinely new UIDs.
stale_uid_bytes: List[bytes] = []
uids_to_fetch: List[bytes] = []
for uid in all_unseen_uids:
uid_str = uid.decode() if isinstance(uid, bytes) else str(uid)
if uid_str in already_seen_uids:
logger.debug(
f"Skipping already-processed IMAP message {uid_str} "
f"for account {self.account.id}"
)
# Still mark as Seen so it doesn't show up in UNSEEN searches
await imap_client.store(msg_id, "+FLAGS", "\\Seen")
continue
stale_uid_bytes.append(uid)
else:
uids_to_fetch.append(uid)
# Re-mark stale UIDs as \Seen in a single batch STORE command so
# they stop appearing in UNSEEN searches without consuming one
# round-trip per message.
if stale_uid_bytes:
uid_set = b",".join(stale_uid_bytes).decode()
try:
response = await imap_client.fetch(msg_id, "(RFC822)")
await imap_client.uid("store", uid_set, "+FLAGS", "\\Seen")
except Exception as e:
logger.warning(
f"Failed to re-mark stale messages as \\Seen for account "
f"{self.account.id}: {e}"
)
# Extract email data from response
email_data = None
for line in response.lines:
if isinstance(line, bytes) and b"RFC822" in line:
# Find the email content
start_idx = line.find(b"{")
if start_idx != -1:
# Email data is in the next parts
continue
elif isinstance(line, bytes) and not line.startswith(b"*"):
email_data = line
break
# Fetch each new message. RFC822 FETCH implicitly sets \Seen on
# the server so no extra STORE per message is required.
fetched_uids: List[bytes] = []
for uid in uids_to_fetch:
uid_str = uid.decode() if isinstance(uid, bytes) else str(uid)
try:
fetch_response = await imap_client.uid("fetch", uid_str, "(RFC822)")
# Extract raw email bytes from the FETCH response lines.
# A UID FETCH response looks like:
# [b'<seq> (UID <uid> RFC822 {<size>}', <email_bytes>, b')']
# Skip the header line (contains "RFC822") and grab the
# first substantive bytes value.
email_data: Optional[bytes] = None
for line in fetch_response.lines:
if not isinstance(line, bytes):
continue
if b"RFC822" in line:
continue
if line.startswith(b"*"):
continue
if line in (b")", b""):
continue
email_data = line
break
if email_data:
emails.append(email_data)
new_uids.append(uid_str)
# Always mark as Seen after fetching so the message is
# not picked up again on the next UNSEEN search.
await imap_client.store(msg_id, "+FLAGS", "\\Seen")
if self.account.delete_after_forward:
await imap_client.store(msg_id, "+FLAGS", "\\Deleted")
fetched_uids.append(uid)
else:
logger.warning(
f"No email data extracted for UID {uid_str} on "
f"account {self.account.id}"
)
except Exception as e:
logger.error(f"Error fetching message {msg_id}: {e}")
logger.error(
f"Error fetching message UID {uid_str} for account "
f"{self.account.id}: {e}"
)
# Expunge deleted messages
if self.account.delete_after_forward:
await imap_client.expunge()
await imap_client.logout()
# Batch-mark fetched messages for deletion if configured (one STORE
# command covers all UIDs instead of N individual commands).
if self.account.delete_after_forward and fetched_uids:
uid_set = b",".join(fetched_uids).decode()
try:
await imap_client.uid("store", uid_set, "+FLAGS", "\\Deleted")
await imap_client.expunge()
except Exception as e:
logger.warning(
f"Failed to delete messages for account "
f"{self.account.id}: {e}"
)
except MailFetchError:
raise
except Exception as e:
logger.error(f"Error fetching IMAP emails: {e}")
logger.error(
f"Error fetching IMAP emails for account {self.account.id}: {e}"
)
raise MailFetchError(f"IMAP fetch error: {str(e)}")
finally:
# Always attempt a clean logout. If the server already sent BYE
# the logout call will fail silently rather than masking the real
# error.
if imap_client is not None:
try:
await imap_client.logout()
except Exception:
pass
return emails, new_uids
@@ -0,0 +1,383 @@
"""
Unit tests for the UID-based IMAP fetch logic in MailProcessor.
These tests verify that _fetch_imap_emails:
- Uses UID SEARCH / UID FETCH / UID STORE commands (not sequence numbers)
- Batches stale-UID re-marking into a single STORE command
- Does NOT issue a per-message STORE for Seen (RFC822 sets it implicitly)
- Batches Deleted STORE into a single command when delete_after_forward=True
- Handles an empty UNSEEN result without error
- Handles individual message fetch failures gracefully
- Always attempts logout in the finally block
"""
import pytest
from unittest.mock import AsyncMock, MagicMock, call, patch
# ---------------------------------------------------------------------------
# Helpers to build lightweight fakes
# ---------------------------------------------------------------------------
def _make_account(
protocol="imap_ssl",
host="imap.example.com",
port=993,
username="user@example.com",
delete_after_forward=False,
account_id=1,
):
"""Return a minimal MailAccount-like mock."""
from app.models.database_models import MailProtocol
account = MagicMock()
account.id = account_id
account.host = host
account.port = port
account.username = username
account.delete_after_forward = delete_after_forward
account.protocol = (
MailProtocol.IMAP_SSL if protocol == "imap_ssl" else MailProtocol.IMAP
)
return account
def _make_imap_response(result="OK", lines=None):
"""Return an object that looks like an aioimaplib ImapResponse."""
resp = MagicMock()
resp.result = result
resp.lines = lines if lines is not None else [b""]
return resp
def _make_fetch_response(uid_str: str, email_bytes: bytes):
"""
Simulate the lines that aioimaplib returns for a UID FETCH (RFC822) call.
The typical structure is:
[b'<seq> (UID <uid> RFC822 {<size>}', <email_data>, b')']
"""
header = f"1 (UID {uid_str} RFC822 {{12345}}".encode()
return _make_imap_response(result="OK", lines=[header, email_bytes, b")"])
# ---------------------------------------------------------------------------
# Tests
# ---------------------------------------------------------------------------
class TestFetchImapEmailsUidCommands:
"""Verify UID-based command usage in _fetch_imap_emails."""
@pytest.fixture
def processor(self):
from app.services.mail_processor import MailProcessor
account = _make_account()
return MailProcessor(account=account, decrypted_password="secret")
@pytest.fixture
def mock_imap(self):
"""A mock aioimaplib client whose async methods are AsyncMock."""
client = MagicMock()
client.wait_hello_from_server = AsyncMock()
client.login = AsyncMock()
client.select = AsyncMock()
client.uid = AsyncMock()
client.logout = AsyncMock()
return client
async def test_uses_uid_search_not_plain_search(self, processor, mock_imap):
"""SEARCH should be issued as UID SEARCH UNSEEN."""
mock_imap.uid.return_value = _make_imap_response(result="OK", lines=[b""])
with patch(
"app.services.mail_processor.aioimaplib.IMAP4_SSL",
return_value=mock_imap,
):
await processor._fetch_imap_emails(10, set())
# uid("search", "UNSEEN") must be the first uid() call
first_uid_call = mock_imap.uid.call_args_list[0]
assert first_uid_call == call("search", "UNSEEN")
async def test_no_messages_returns_empty(self, processor, mock_imap):
"""Empty UNSEEN result should return empty lists without error."""
mock_imap.uid.return_value = _make_imap_response(result="OK", lines=[b""])
with patch(
"app.services.mail_processor.aioimaplib.IMAP4_SSL",
return_value=mock_imap,
):
emails, uids = await processor._fetch_imap_emails(10, set())
assert emails == []
assert uids == []
async def test_fetches_new_message_via_uid_fetch(self, processor, mock_imap):
"""New messages should be fetched with UID FETCH, not plain FETCH."""
raw_email = b"From: sender@example.com\r\nSubject: Test\r\n\r\nBody"
uid = b"42"
def uid_side_effect(command, *args):
if command == "search":
return _make_imap_response(result="OK", lines=[uid])
if command == "fetch":
return _make_fetch_response(uid.decode(), raw_email)
return _make_imap_response()
mock_imap.uid = AsyncMock(side_effect=uid_side_effect)
with patch(
"app.services.mail_processor.aioimaplib.IMAP4_SSL",
return_value=mock_imap,
):
emails, new_uids = await processor._fetch_imap_emails(10, set())
assert emails == [raw_email]
assert new_uids == ["42"]
# The fetch call should use UID FETCH
fetch_call = [
c for c in mock_imap.uid.call_args_list if c.args[0] == "fetch"
]
assert len(fetch_call) == 1
assert fetch_call[0] == call("fetch", "42", "(RFC822)")
async def test_no_per_message_store_for_seen(self, processor, mock_imap):
"""RFC822 implicitly marks \\Seen; no extra STORE per message is needed."""
raw_email = b"From: a@b.com\r\n\r\nHello"
uids = b"10 11 12"
def uid_side_effect(command, *args):
if command == "search":
return _make_imap_response(result="OK", lines=[uids])
if command == "fetch":
uid_str = args[0]
return _make_fetch_response(uid_str, raw_email)
return _make_imap_response()
mock_imap.uid = AsyncMock(side_effect=uid_side_effect)
with patch(
"app.services.mail_processor.aioimaplib.IMAP4_SSL",
return_value=mock_imap,
):
emails, new_uids = await processor._fetch_imap_emails(10, set())
# No STORE command should have been called (delete_after_forward=False)
store_calls = [
c for c in mock_imap.uid.call_args_list if c.args[0] == "store"
]
assert store_calls == [], "Expected no STORE commands for \\Seen"
assert len(emails) == 3
assert new_uids == ["10", "11", "12"]
async def test_stale_uids_batched_in_single_store(self, processor, mock_imap):
"""UIDs already in already_seen_uids must be re-marked in one batch STORE."""
# Two messages: one stale (already in DB), one new
raw_email = b"From: x@y.com\r\n\r\nNew mail"
def uid_side_effect(command, *args):
if command == "search":
return _make_imap_response(result="OK", lines=[b"5 6"])
if command == "fetch":
return _make_fetch_response(args[0], raw_email)
return _make_imap_response()
mock_imap.uid = AsyncMock(side_effect=uid_side_effect)
with patch(
"app.services.mail_processor.aioimaplib.IMAP4_SSL",
return_value=mock_imap,
):
emails, new_uids = await processor._fetch_imap_emails(
10, already_seen_uids={"5"} # UID 5 is stale
)
# Only UID 6 is new
assert new_uids == ["6"]
assert len(emails) == 1
store_calls = [
c for c in mock_imap.uid.call_args_list if c.args[0] == "store"
]
# Exactly one STORE for the stale UID
assert len(store_calls) == 1
assert store_calls[0] == call("store", "5", "+FLAGS", "\\Seen")
async def test_multiple_stale_uids_batched_together(self, processor, mock_imap):
"""Multiple stale UIDs should be sent as a comma-separated set."""
def uid_side_effect(command, *args):
if command == "search":
return _make_imap_response(result="OK", lines=[b"1 2 3 4"])
if command == "fetch":
return _make_fetch_response(args[0], b"email data")
return _make_imap_response()
mock_imap.uid = AsyncMock(side_effect=uid_side_effect)
with patch(
"app.services.mail_processor.aioimaplib.IMAP4_SSL",
return_value=mock_imap,
):
await processor._fetch_imap_emails(10, already_seen_uids={"1", "2"})
store_calls = [
c for c in mock_imap.uid.call_args_list if c.args[0] == "store"
]
assert len(store_calls) == 1
# The UID set string should contain both stale UIDs (order may vary)
uid_set_arg = store_calls[0].args[1]
parts = set(uid_set_arg.split(","))
assert parts == {"1", "2"}
async def test_delete_after_forward_uses_single_batch_store(self):
"""delete_after_forward=True must issue one UID STORE \\Deleted command."""
from app.services.mail_processor import MailProcessor
account = _make_account(delete_after_forward=True)
processor = MailProcessor(account=account, decrypted_password="s")
mock_imap = MagicMock()
mock_imap.wait_hello_from_server = AsyncMock()
mock_imap.login = AsyncMock()
mock_imap.select = AsyncMock()
mock_imap.expunge = AsyncMock()
mock_imap.logout = AsyncMock()
def uid_side_effect(command, *args):
if command == "search":
return _make_imap_response(result="OK", lines=[b"7 8"])
if command == "fetch":
return _make_fetch_response(args[0], b"raw email")
return _make_imap_response()
mock_imap.uid = AsyncMock(side_effect=uid_side_effect)
with patch(
"app.services.mail_processor.aioimaplib.IMAP4_SSL",
return_value=mock_imap,
):
emails, new_uids = await processor._fetch_imap_emails(10, set())
assert new_uids == ["7", "8"]
store_calls = [
c for c in mock_imap.uid.call_args_list if c.args[0] == "store"
]
# Exactly one STORE for deletion covering both UIDs
assert len(store_calls) == 1
uid_set_arg = store_calls[0].args[1]
parts = set(uid_set_arg.split(","))
assert parts == {"7", "8"}
assert store_calls[0].args[2] == "+FLAGS"
assert store_calls[0].args[3] == "\\Deleted"
# expunge must also be called
mock_imap.expunge.assert_awaited_once()
async def test_individual_fetch_failure_does_not_abort(self, processor, mock_imap):
"""A single message fetch error should be logged but not stop processing."""
raw_email = b"From: ok@example.com\r\n\r\nOK"
call_count = {"count": 0}
def uid_side_effect(command, *args):
if command == "search":
return _make_imap_response(result="OK", lines=[b"20 21"])
if command == "fetch":
call_count["count"] += 1
if call_count["count"] == 1:
raise Exception("Connection dropped by server")
return _make_fetch_response(args[0], raw_email)
return _make_imap_response()
mock_imap.uid = AsyncMock(side_effect=uid_side_effect)
with patch(
"app.services.mail_processor.aioimaplib.IMAP4_SSL",
return_value=mock_imap,
):
emails, new_uids = await processor._fetch_imap_emails(10, set())
# Second message should still be processed
assert len(emails) == 1
assert new_uids == ["21"]
async def test_logout_called_even_on_connection_error(self, processor, mock_imap):
"""logout() must be attempted even when the connection drops mid-session."""
mock_imap.uid = AsyncMock(side_effect=Exception("BYE server gone"))
with patch(
"app.services.mail_processor.aioimaplib.IMAP4_SSL",
return_value=mock_imap,
):
from app.services.mail_processor import MailFetchError
with pytest.raises(MailFetchError):
await processor._fetch_imap_emails(10, set())
mock_imap.logout.assert_awaited_once()
async def test_logout_failure_does_not_mask_error(self, processor, mock_imap):
"""If logout itself raises, the original MailFetchError should propagate."""
mock_imap.uid = AsyncMock(side_effect=Exception("server gone"))
mock_imap.logout = AsyncMock(side_effect=Exception("logout also failed"))
with patch(
"app.services.mail_processor.aioimaplib.IMAP4_SSL",
return_value=mock_imap,
):
from app.services.mail_processor import MailFetchError
with pytest.raises(MailFetchError):
await processor._fetch_imap_emails(10, set())
async def test_respects_max_count_limit(self, processor, mock_imap):
"""Only max_count messages should be processed."""
raw_email = b"From: a@b.com\r\n\r\nHi"
def uid_side_effect(command, *args):
if command == "search":
# 5 messages available
return _make_imap_response(result="OK", lines=[b"1 2 3 4 5"])
if command == "fetch":
return _make_fetch_response(args[0], raw_email)
return _make_imap_response()
mock_imap.uid = AsyncMock(side_effect=uid_side_effect)
with patch(
"app.services.mail_processor.aioimaplib.IMAP4_SSL",
return_value=mock_imap,
):
emails, new_uids = await processor._fetch_imap_emails(3, set())
assert len(emails) == 3
assert new_uids == ["1", "2", "3"]
async def test_plain_imap_uses_imap4_not_ssl(self):
"""Non-SSL IMAP accounts must use IMAP4, not IMAP4_SSL."""
from app.services.mail_processor import MailProcessor
account = _make_account(protocol="imap")
processor = MailProcessor(account=account, decrypted_password="pw")
mock_imap = MagicMock()
mock_imap.wait_hello_from_server = AsyncMock()
mock_imap.login = AsyncMock()
mock_imap.select = AsyncMock()
mock_imap.logout = AsyncMock()
mock_imap.uid = AsyncMock(
return_value=_make_imap_response(result="OK", lines=[b""])
)
with patch(
"app.services.mail_processor.aioimaplib.IMAP4",
return_value=mock_imap,
) as mock_cls:
await processor._fetch_imap_emails(10, set())
mock_cls.assert_called_once()
+1
View File
@@ -4,6 +4,7 @@ Comprehensive task breakdown for repository improvements and production readines
## ✅ Recently Completed
- [x] **IMAP reliability: switched to UID-based commands**`_fetch_imap_emails` now uses `UID SEARCH`, `UID FETCH`, and `UID STORE` throughout. Sequence numbers are volatile (they shift on expunge), causing "Too many invalid IMAP commands" on strict servers (e.g. T-Online). UIDs are stable. The per-message `STORE +FLAGS \Seen` (redundant — RFC822 sets it implicitly) and per-message `STORE +FLAGS \Deleted` are replaced with single batch commands. Stale already-seen UIDs are re-marked `\Seen` in one command. Logout is now in a `finally` block so a mid-session `BYE` is handled gracefully.
- [x] Fixed timezone display bug in Mailbox Activity and Admin Logs pages: ISO timestamps without a `Z` suffix were parsed as local time by JavaScript, shifting "Xm ago" / "Xh ago" displays and absolute dates by the client's UTC offset.
- [x] Fixed worker `send_user_notification` using rolled-back DB session causing `greenlet_spawn has not been called` errors; status/`last_check_at` now always committed before sending notifications via a fresh session.
- [x] **Dashboard redesign**: Replaced noisy "Recent Processing Runs" table with a per-account "Mailbox Status" view showing last-check status (OK/Error/Pending), relative timestamp, error messages, and lifetime counters. Stats cards updated to show all-time processed count and accounts-with-errors count.