diff --git a/CHANGELOG.md b/CHANGELOG.md index aafeb9d..f55b4df 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,53 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Added + +- **Friendly error messages**: Introduced `_format_connection_error()` helper in + `mail_processor.py` that translates raw OS/socket/SSL/POP3/IMAP exceptions into + human-readable sentences including the host:port and actionable guidance (DNS + failure, TLS error, connection timeout, authentication rejection, etc.). The + helper is applied at every `raise MailFetchError` / `raise MailConnectionError` + site and in both `_test_pop3_connection` and `_test_imap_connection`. + +- **Per-account debug logging** (`debug_logging` column on `MailAccount`): when + enabled, the next processing run records a structured connection trace + (connect timing, TLS details, auth, INBOX selection, message UIDs/sizes, + elapsed milliseconds per phase) via the new `MailDebugRecorder` class. The + trace is persisted as a `ProcessingLog` row with `level="DEBUG"` and surfaced + in the "Mailbox Activity" logs page as a collapsible "Connection trace" panel. + Debug logging auto-disables after 5 completed runs in a 24-hour window. + +- **"Clear error" button**: new `POST /api/v1/mail-accounts/{id}/clear-error` + endpoint that nulls `last_error_message`/`last_error_at` and resets `status` + to `ACTIVE` when currently `ERROR`. Wired into the error banners on both the + Accounts page and the Mailbox Activity (Logs) page. + +- **Debug-logging toggle** in the account edit form (Add/Edit Account modal): + checkbox labelled "Debug logging (auto-disables after 5 runs)". + +- Alembic migration `0002_add_debug_logging.py` adding the `debug_logging` + boolean column to `mail_accounts` (idempotent via `ADD COLUMN IF NOT EXISTS`). + +### Fixed + +- **Empty IMAP error messages** — `IMAP fetch error:` with a blank suffix was + caused by `asyncio.TimeoutError` and `aioimaplib.Abort` having an empty + `str()`. The new `_format_connection_error()` helper always produces a + non-empty, human-readable message. + +- **Cryptic DNS error** — `POP3 fetch error: [Errno -5] No address associated + with hostname` is now surfaced as `Could not resolve hostname 'pop.web.de' — + check that the server address is correct (DNS lookup failed: …)`. + +- **Sticky ERROR status after transient fetch failures**: the `tasks.py` + processing loop previously set `account.status = ERROR` and + `last_error_message = "{N} emails failed to forward"` even when the + connection and fetch succeeded but some individual email-forward operations + failed. Now, a successful fetch (no exception from `fetch_emails`) always + clears `last_error_message`/`last_error_at` and sets `status = ACTIVE`, + regardless of per-email forwarding failures. Per-email failures continue to + be tracked in `ProcessingLog` and the run's `emails_failed` counter. ### Fixed - OAuth Google sign-in: added `exc_info=True` to the catch-all exception handler in `auth_service.py` so the full traceback is always emitted to the log instead of only `str(e)`. diff --git a/backend/alembic/versions/0002_add_debug_logging.py b/backend/alembic/versions/0002_add_debug_logging.py new file mode 100644 index 0000000..0d09e41 --- /dev/null +++ b/backend/alembic/versions/0002_add_debug_logging.py @@ -0,0 +1,37 @@ +"""Add debug_logging column to mail_accounts + +Revision ID: 0002 +Revises: 0001 +Create Date: 2026-05-03 + +Adds a boolean ``debug_logging`` column to ``mail_accounts``. + +When True, the next processing run will record a detailed connection trace +(timings, phase-by-phase events, message UIDs/sizes) and persist it as a +``ProcessingLog`` row with ``level='DEBUG'``. The column auto-resets to +False after 5 completed runs in a 24-hour window to prevent it being left +on indefinitely. + +The column defaults to False so all existing rows are unaffected. +Using IF NOT EXISTS makes the migration idempotent against fresh installs +where create_all() already created the column. +""" + +from alembic import op + +# revision identifiers, used by Alembic. +revision = "0002" +down_revision = "0001" +branch_labels = None +depends_on = None + + +def upgrade() -> None: + op.execute( + "ALTER TABLE mail_accounts " + "ADD COLUMN IF NOT EXISTS debug_logging BOOLEAN NOT NULL DEFAULT FALSE" + ) + + +def downgrade() -> None: + op.execute("ALTER TABLE mail_accounts DROP COLUMN IF EXISTS debug_logging") diff --git a/backend/app/api/v1/endpoints/mail_accounts.py b/backend/app/api/v1/endpoints/mail_accounts.py index 34174a2..a738c27 100644 --- a/backend/app/api/v1/endpoints/mail_accounts.py +++ b/backend/app/api/v1/endpoints/mail_accounts.py @@ -104,6 +104,7 @@ async def create_mail_account( check_interval_minutes=account_in.check_interval_minutes, max_emails_per_check=account_in.max_emails_per_check, delete_after_forward=account_in.delete_after_forward, + debug_logging=account_in.debug_logging, provider_name=account_in.provider_name, ) @@ -243,6 +244,42 @@ async def toggle_mail_account( return account +@router.post("/{account_id}/clear-error", response_model=MailAccountResponse) +async def clear_account_error( + account_id: int, + current_user: User = Depends(get_current_active_user), + db: AsyncSession = Depends(get_db), +): + """Clear the error status of a mail account. + + Resets last_error_message, last_error_at and sets status to ACTIVE + if the account is currently in ERROR state. Use this after fixing the + underlying problem (e.g. wrong password, DNS issue) to immediately remove + the error indicator without waiting for the next successful fetch. + """ + result = await db.execute( + select(MailAccount).where( + MailAccount.id == account_id, MailAccount.user_id == current_user.id + ) + ) + account = result.scalar_one_or_none() + + if not account: + raise HTTPException( + status_code=status.HTTP_404_NOT_FOUND, detail="Mail account not found" + ) + + account.last_error_message = None # type: ignore[assignment] + account.last_error_at = None # type: ignore[assignment] + if account.status == AccountStatus.ERROR: + account.status = AccountStatus.ACTIVE # type: ignore[assignment] + + await db.commit() + await db.refresh(account) + + return account + + @router.post("/{account_id}/pull-now", status_code=status.HTTP_202_ACCEPTED) async def pull_now( account_id: int, diff --git a/backend/app/models/database_models.py b/backend/app/models/database_models.py index 192d182..9a4926e 100644 --- a/backend/app/models/database_models.py +++ b/backend/app/models/database_models.py @@ -171,6 +171,9 @@ class MailAccount(Base): provider_name = Column(String(100), nullable=True) # e.g., "Gmail", "GMX" auto_detected = Column(Boolean, default=False) + # Debug logging + debug_logging = Column(Boolean, default=False) + # Statistics total_emails_processed = Column(Integer, default=0) total_emails_failed = Column(Integer, default=0) diff --git a/backend/app/models/schemas.py b/backend/app/models/schemas.py index f630f60..da5673b 100644 --- a/backend/app/models/schemas.py +++ b/backend/app/models/schemas.py @@ -114,6 +114,7 @@ class MailAccountBase(BaseModel): max_emails_per_check: int = Field(default=50, gt=0, le=1000) delete_after_forward: bool = True provider_name: Optional[str] = Field(None, max_length=100) + debug_logging: bool = False class MailAccountCreate(MailAccountBase): @@ -137,6 +138,7 @@ class MailAccountUpdate(BaseModel): max_emails_per_check: Optional[int] = Field(None, gt=0, le=1000) delete_after_forward: Optional[bool] = None provider_name: Optional[str] = Field(None, max_length=100) + debug_logging: Optional[bool] = None class MailAccountResponse(MailAccountBase): diff --git a/backend/app/services/mail_processor.py b/backend/app/services/mail_processor.py index 6b9cfe6..f54f01b 100644 --- a/backend/app/services/mail_processor.py +++ b/backend/app/services/mail_processor.py @@ -7,7 +7,10 @@ import asyncio import poplib import re import smtplib +import socket import ssl +import time as _time +from datetime import datetime, timezone from email import parser from email.mime.text import MIMEText from email.mime.multipart import MIMEMultipart @@ -45,12 +48,200 @@ class MailForwardError(Exception): pass +def _format_connection_error( + exc: BaseException, + host: str = "", + port: int = 0, + protocol: str = "", +) -> str: + """Return a human-readable error message for a mail connection failure. + + Never returns an empty string – always includes the exception type as a + fallback so the dashboard always shows an actionable message. + """ + loc = f"{host}:{port}" if host else "" + proto = f"{protocol} " if protocol else "" + + # DNS resolution failure (socket.gaierror is a subclass of OSError) + if isinstance(exc, socket.gaierror): + if host: + return ( + f"Could not resolve hostname '{host}' — check that the server " + f"address is correct (DNS lookup failed: {exc})" + ) + return f"DNS lookup failed: {exc}" + + # Connection / operation timeout + if isinstance(exc, (socket.timeout, asyncio.TimeoutError, TimeoutError)): + if loc: + return ( + f"{proto}connection to {loc} timed out — the server may be " + f"slow or blocking connections" + ) + return f"{proto}connection timed out" + + # Connection refused by the server + if isinstance(exc, ConnectionRefusedError): + if loc: + return ( + f"Connection refused by {loc} — check that the host and port " + f"are correct and the server is running" + ) + return f"Connection refused: {exc}" + + # Server closed the connection unexpectedly + if isinstance(exc, ConnectionResetError): + if loc: + return f"Connection reset by {loc} — the server closed the connection unexpectedly" + return f"Connection reset: {exc}" + + # TLS certificate verification failure + if isinstance(exc, ssl.SSLCertVerificationError): + reason = getattr(exc, "reason", "") or str(exc) + if loc: + return f"TLS certificate verification failed for {loc}: {reason}" + return f"TLS certificate verification failed: {reason}" + + # Generic TLS/SSL error + if isinstance(exc, ssl.SSLError): + reason = getattr(exc, "reason", "") or str(exc) + if loc: + return f"TLS/SSL error connecting to {loc}: {reason}" + return f"TLS/SSL error: {reason}" + + # POP3 protocol error (auth rejection, server-side error, etc.) + if isinstance(exc, poplib.error_proto): + msg = str(exc).strip() or repr(exc) + msg_lower = msg.lower() + if any( + k in msg_lower + for k in ( + "auth", + "login", + "password", + "user", + "pass", + "invalid", + "denied", + "failed", + ) + ): + if loc: + return f"Authentication rejected by {loc}: {msg}" + return f"POP3 authentication failed: {msg}" + if loc: + return f"POP3 server {loc} returned an error: {msg}" + return f"POP3 error: {msg}" + + # IMAP connection aborted by the server + try: + if isinstance(exc, aioimaplib.Abort): + msg = str(exc).strip() or "server closed the connection" + if loc: + return f"IMAP connection to {loc} was aborted: {msg}" + return f"IMAP connection aborted: {msg}" + except TypeError: + # aioimaplib may be mocked in tests, making Abort a non-type + pass + + # Generic OSError with an OS-level error code + if isinstance(exc, OSError) and exc.errno: + strerror = exc.strerror or str(exc) + if loc: + return f"Network error connecting to {loc}: {strerror}" + return f"Network error: {strerror}" + + # Catch-all: produce a non-empty string regardless of the exception type + msg = str(exc).strip() + if not msg: + # Some exceptions (e.g. bare asyncio.TimeoutError) have no message + msg = type(exc).__name__ + if loc: + return f"{proto}error communicating with {loc}: {msg}" + return f"{type(exc).__name__}: {msg or repr(exc)}" + + +# Maximum number of entries / bytes kept in a single debug trace +_MAX_TRACE_ENTRIES = 200 +_MAX_TRACE_BYTES = 65_536 # 64 KiB + + +class MailDebugRecorder: + """Collects a structured trace of an IMAP/POP3 connection for debug display. + + Thread-safe for list.append() calls thanks to the CPython GIL. The + recorder is passed into :class:`MailProcessor` when + ``account.debug_logging`` is True and persisted as a + ``ProcessingLog`` row with ``level="DEBUG"`` at the end of the run. + """ + + def __init__(self) -> None: + self._entries: List[Dict[str, Any]] = [] + self._total_bytes: int = 0 + self._truncated: bool = False + + def record( + self, + phase: str, + message: str, + data: Optional[Dict[str, Any]] = None, + ) -> None: + """Append a trace entry (no-op once the size cap is reached).""" + if self._truncated: + return + entry: Dict[str, Any] = { + "ts": datetime.now(timezone.utc).isoformat(), + "phase": phase, + "msg": message, + } + if data: + entry["data"] = data + try: + entry_bytes = len(str(entry)) + except Exception: + entry_bytes = 256 # conservative fallback + if ( + len(self._entries) >= _MAX_TRACE_ENTRIES + or self._total_bytes + entry_bytes > _MAX_TRACE_BYTES + ): + self._entries.append( + { + "ts": entry["ts"], + "phase": "truncated", + "msg": ( + f"Trace truncated after {len(self._entries)} entries " + f"(size limit {_MAX_TRACE_BYTES // 1024} KiB reached)" + ), + } + ) + self._truncated = True + return + self._entries.append(entry) + self._total_bytes += entry_bytes + + def has_entries(self) -> bool: + return bool(self._entries) + + def __len__(self) -> int: + return len(self._entries) + + def as_details(self) -> Dict[str, Any]: + """Return the trace as a dict suitable for storage in error_details.""" + return {"trace": self._entries, "truncated": self._truncated} + + class MailProcessor: """Handles mail fetching and forwarding operations""" - def __init__(self, account: MailAccount, decrypted_password: str): + def __init__( + self, + account: MailAccount, + decrypted_password: str, + debug_recorder: Optional[MailDebugRecorder] = None, + ): self.account = account self.password = decrypted_password + self._debug = debug_recorder async def test_connection(self) -> Tuple[bool, str]: """ @@ -70,9 +261,11 @@ class MailProcessor: """Test POP3 connection""" try: loop = asyncio.get_event_loop() + _dbg = self._debug # Run blocking POP3 operations in thread pool def connect_pop3(): + _t0 = _time.monotonic() if self.account.protocol == MailProtocol.POP3_SSL: context = ssl.create_default_context() pop_conn = poplib.POP3_SSL( @@ -85,14 +278,32 @@ class MailProcessor: pop_conn = poplib.POP3( self.account.host, self.account.port, timeout=10 ) + if _dbg: + _dbg.record( + "connect", + f"Connected to {self.account.host}:{self.account.port} " + f"({'SSL' if self.account.protocol == MailProtocol.POP3_SSL else 'plain'})", + {"elapsed_ms": round((_time.monotonic() - _t0) * 1000)}, + ) # Try authentication + _t1 = _time.monotonic() pop_conn.user(self.account.username) pop_conn.pass_(self.password) + if _dbg: + _dbg.record( + "auth", + f"Authenticated as {self.account.username}", + {"elapsed_ms": round((_time.monotonic() - _t1) * 1000)}, + ) # Get mailbox stats message_count, mailbox_size = pop_conn.stat() - + if _dbg: + _dbg.record( + "stat", + f"Mailbox has {message_count} messages ({mailbox_size} bytes)", + ) pop_conn.quit() return message_count, mailbox_size @@ -100,13 +311,16 @@ class MailProcessor: return True, f"Connection successful. {message_count} messages in mailbox." - except poplib.error_proto as e: - error_msg = str(e) - if "authentication" in error_msg.lower() or "auth" in error_msg.lower(): - return False, f"Authentication failed: {error_msg}" - return False, f"POP3 protocol error: {error_msg}" except Exception as e: - return False, f"Connection failed: {str(e)}" + return ( + False, + _format_connection_error( + e, + str(self.account.host), + int(self.account.port), + "POP3", + ), + ) async def _test_imap_connection(self) -> Tuple[bool, str]: """Test IMAP connection""" @@ -121,28 +335,64 @@ class MailProcessor: host=self.account.host, port=self.account.port, timeout=10 ) + _t0 = _time.monotonic() await imap_client.wait_hello_from_server() + if self._debug: + self._debug.record( + "connect", + f"Connected to {self.account.host}:{self.account.port} " + f"({'SSL' if self.account.protocol == MailProtocol.IMAP_SSL else 'plain'})", + {"elapsed_ms": round((_time.monotonic() - _t0) * 1000)}, + ) # Authenticate + _t1 = _time.monotonic() response = await imap_client.login(self.account.username, self.password) if response.result != "OK": - return False, f"Authentication failed: {response.lines}" + return ( + False, + f"Authentication rejected by {self.account.host}:{self.account.port}: " + f"{response.lines}", + ) + if self._debug: + self._debug.record( + "auth", + f"Authenticated as {self.account.username}", + {"elapsed_ms": round((_time.monotonic() - _t1) * 1000)}, + ) # Select inbox await imap_client.select("INBOX") + if self._debug: + self._debug.record("select", "Selected INBOX") # Get message count response = await imap_client.search("ALL") message_ids = response.lines[0].split() message_count = len(message_ids) + if self._debug: + self._debug.record( + "search", + f"INBOX contains {message_count} messages", + ) await imap_client.logout() + if self._debug: + self._debug.record("logout", "Logged out successfully") return True, f"Connection successful. {message_count} messages in mailbox." except Exception as e: - return False, f"IMAP connection failed: {str(e)}" + return ( + False, + _format_connection_error( + e, + str(self.account.host), + int(self.account.port), + "IMAP", + ), + ) async def fetch_emails( self, @@ -178,8 +428,10 @@ class MailProcessor: try: loop = asyncio.get_event_loop() + _dbg = self._debug # capture for thread-pool closure def fetch_pop3() -> Tuple[List[bytes], List[str]]: + _t_conn = _time.monotonic() # Connect if self.account.protocol == MailProtocol.POP3_SSL: context = ssl.create_default_context() @@ -193,10 +445,24 @@ class MailProcessor: pop_conn = poplib.POP3( # type: ignore[assignment] str(self.account.host), int(self.account.port), timeout=30 ) + if _dbg: + _dbg.record( + "connect", + f"Connected to {self.account.host}:{self.account.port} " + f"({'SSL' if self.account.protocol == MailProtocol.POP3_SSL else 'plain'})", + {"elapsed_ms": round((_time.monotonic() - _t_conn) * 1000)}, + ) # Authenticate + _t_auth = _time.monotonic() pop_conn.user(str(self.account.username)) pop_conn.pass_(self.password) + if _dbg: + _dbg.record( + "auth", + f"Authenticated as {self.account.username}", + {"elapsed_ms": round((_time.monotonic() - _t_auth) * 1000)}, + ) # Retrieve UIDL map: {msg_number: uid_string} uidl_response = pop_conn.uidl() @@ -207,6 +473,13 @@ class MailProcessor: uid_map[int(parts[0])] = parts[1].strip() num_messages = len(uid_map) + if _dbg: + _dbg.record( + "uidl", + f"Mailbox contains {num_messages} messages; " + f"{len(already_seen_uids)} already downloaded", + {"total": num_messages, "already_seen": len(already_seen_uids)}, + ) logger.info( f"Found {num_messages} messages for account {self.account.id}" ) @@ -228,26 +501,59 @@ class MailProcessor: continue try: + _t_msg = _time.monotonic() response, lines, octets = pop_conn.retr(msg_num) email_data = b"\r\n".join(lines) fetched.append(email_data) fetched_uids.append(uid) fetched_count += 1 + elapsed = round((_time.monotonic() - _t_msg) * 1000) logger.info( f"Retrieved message {msg_num} (uid={uid}) " f"from account {self.account.id}" ) + if _dbg: + _dbg.record( + "fetch_msg", + f"Fetched message {msg_num} (uid={uid}): " + f"{len(email_data)} bytes", + { + "msg_num": msg_num, + "uid": uid, + "size_bytes": len(email_data), + "elapsed_ms": elapsed, + }, + ) except Exception as e: logger.error(f"Error retrieving message {msg_num}: {e}") + if _dbg: + _dbg.record( + "fetch_error", + f"Failed to retrieve message {msg_num} (uid={uid}): {e}", + {"msg_num": msg_num, "uid": uid}, + ) pop_conn.quit() + if _dbg: + _dbg.record( + "quit", + f"Disconnected — fetched {fetched_count} new message(s)", + {"fetched": fetched_count}, + ) return fetched, fetched_uids emails, new_uids = await loop.run_in_executor(None, fetch_pop3) except Exception as e: logger.error(f"Error fetching POP3 emails: {e}") - raise MailFetchError(f"POP3 fetch error: {str(e)}") + raise MailFetchError( + _format_connection_error( + e, + str(self.account.host), + int(self.account.port), + "POP3", + ) + ) return emails, new_uids @@ -290,28 +596,72 @@ class MailProcessor: host=self.account.host, port=self.account.port, timeout=30 ) + _t_conn = _time.monotonic() await imap_client.wait_hello_from_server() + if self._debug: + self._debug.record( + "connect", + f"Connected to {self.account.host}:{self.account.port} " + f"({'SSL' if self.account.protocol == MailProtocol.IMAP_SSL else 'plain'})", + {"elapsed_ms": round((_time.monotonic() - _t_conn) * 1000)}, + ) + + _t_auth = _time.monotonic() await imap_client.login(self.account.username, self.password) + if self._debug: + self._debug.record( + "auth", + f"Authenticated as {self.account.username}", + {"elapsed_ms": round((_time.monotonic() - _t_auth) * 1000)}, + ) + await imap_client.select("INBOX") + if self._debug: + self._debug.record("select", "Selected INBOX") # Step 1: Standard sequence-based SEARCH for UNSEEN messages. # aioimaplib's .uid() wrapper explicitly blocks "search", so we # use the plain SEARCH command and resolve to UIDs in step 2. + _t_search = _time.monotonic() response = await imap_client.search("UNSEEN") if ( response.result != "OK" or not response.lines or not response.lines[0].strip() ): + if self._debug: + self._debug.record( + "search", + "SEARCH UNSEEN returned 0 messages", + {"elapsed_ms": round((_time.monotonic() - _t_search) * 1000)}, + ) logger.info(f"Found 0 unread messages for account {self.account.id}") # logout is handled by the finally block below return emails, new_uids seq_nums: List[bytes] = response.lines[0].split() if not seq_nums: + if self._debug: + self._debug.record( + "search", + "SEARCH UNSEEN returned 0 messages", + {"elapsed_ms": round((_time.monotonic() - _t_search) * 1000)}, + ) logger.info(f"Found 0 unread messages for account {self.account.id}") return emails, new_uids + if self._debug: + self._debug.record( + "search", + f"SEARCH UNSEEN found {len(seq_nums)} message(s); " + f"limiting to {min(len(seq_nums), max_count)}", + { + "total_unseen": len(seq_nums), + "max_count": max_count, + "elapsed_ms": round((_time.monotonic() - _t_search) * 1000), + }, + ) + # Limit to max_count before doing any further work. seq_nums = seq_nums[:max_count] @@ -333,6 +683,16 @@ class MailProcessor: f"Found {len(all_unseen_uids)} unread messages for account " f"{self.account.id}" ) + if self._debug: + self._debug.record( + "fetch_uids", + f"Resolved {len(all_unseen_uids)} UID(s); " + f"{len(already_seen_uids)} already downloaded", + { + "uids": [u.decode() for u in all_unseen_uids[:10]], + "already_seen": len(already_seen_uids), + }, + ) # Step 4: Split into stale UIDs (already in our DB but still # UNSEEN on the server — e.g. a previous STORE failed) and @@ -346,6 +706,14 @@ class MailProcessor: else: uids_to_fetch.append(uid) + if self._debug and stale_uid_bytes: + self._debug.record( + "stale_uids", + f"Re-marking {len(stale_uid_bytes)} stale UID(s) as \\Seen " + f"(already downloaded but still UNSEEN on server)", + {"count": len(stale_uid_bytes)}, + ) + # 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. @@ -368,6 +736,7 @@ class MailProcessor: for uid in uids_to_fetch: uid_str = uid.decode() if isinstance(uid, bytes) else str(uid) try: + _t_msg = _time.monotonic() fetch_response = await imap_client.uid( "fetch", uid_str, "(BODY.PEEK[])" ) @@ -396,8 +765,19 @@ class MailProcessor: break if email_data and email_data.strip(): + elapsed = round((_time.monotonic() - _t_msg) * 1000) emails.append(email_data) new_uids.append(uid_str) + if self._debug: + self._debug.record( + "fetch_msg", + f"Fetched UID {uid_str}: {len(email_data)} bytes", + { + "uid": uid_str, + "size_bytes": len(email_data), + "elapsed_ms": elapsed, + }, + ) else: logger.warning( f"No email data extracted for UID {uid_str} on " @@ -406,12 +786,27 @@ class MailProcessor: "this may indicate a server-side error producing empty " "IMAP responses" ) + if self._debug: + self._debug.record( + "fetch_empty", + f"UID {uid_str} returned empty body — skipped", + { + "uid": uid_str, + "raw_bytes": len(email_data) if email_data else 0, + }, + ) except Exception as e: logger.error( f"Error fetching message UID {uid_str} for account " f"{self.account.id}: {e}" ) + if self._debug: + self._debug.record( + "fetch_error", + f"Failed to fetch UID {uid_str}: {e}", + {"uid": uid_str}, + ) except MailFetchError: raise @@ -419,7 +814,19 @@ class MailProcessor: logger.error( f"Error fetching IMAP emails for account {self.account.id}: {e}" ) - raise MailFetchError(f"IMAP fetch error: {str(e)}") + if self._debug: + self._debug.record( + "error", + f"Fatal error: {_format_connection_error(e, str(self.account.host), int(self.account.port), 'IMAP')}", + ) + raise MailFetchError( + _format_connection_error( + e, + str(self.account.host), + int(self.account.port), + "IMAP", + ) + ) finally: # Always attempt a clean logout. If the server already sent BYE # the logout call will fail silently rather than masking the real @@ -427,6 +834,8 @@ class MailProcessor: if imap_client is not None: try: await imap_client.logout() + if self._debug: + self._debug.record("logout", "Logged out successfully") except Exception: pass diff --git a/backend/app/workers/tasks.py b/backend/app/workers/tasks.py index 3d14b36..c9a5434 100644 --- a/backend/app/workers/tasks.py +++ b/backend/app/workers/tasks.py @@ -6,6 +6,7 @@ import asyncio import email as email_lib import time from datetime import datetime, timedelta, timezone +from typing import Optional from celery import Task import logging @@ -31,12 +32,12 @@ from app.models.database_models import ( DownloadedMessageId, UserSmtpConfig, ) -from app.services.mail_processor import MailProcessor +from app.services.mail_processor import MailProcessor, MailDebugRecorder from app.services.gmail_service import GmailService, GmailAuthError from app.services.config_service import ConfigService from app.services.notification_service import send_user_notification from app.core.config import settings -from sqlalchemy import select, delete, or_ +from sqlalchemy import select, delete, or_, func logger = logging.getLogger(__name__) @@ -116,8 +117,13 @@ async def process_mail_account(account_id: int): ) already_seen_uids = set(seen_result.scalars().all()) + # Create debug recorder if debug logging is enabled for this account + _debug_recorder: Optional[MailDebugRecorder] = ( + MailDebugRecorder() if account.debug_logging else None # type: ignore[attr-defined] + ) + # Create processor - processor = MailProcessor(account, password) + processor = MailProcessor(account, password, debug_recorder=_debug_recorder) # Fetch emails (returns raw bytes + new UIDs) emails, new_uids = await processor.fetch_emails( @@ -465,6 +471,20 @@ async def process_mail_account(account_id: int): post_exc, ) + # Persist debug connection trace (if debug logging was enabled) + if _debug_recorder and _debug_recorder.has_entries(): + db.add( + ProcessingLog( + user_id=account.user_id, + mail_account_id=account.id, + processing_run_id=run.id, + level="DEBUG", + message=f"Connection trace ({len(_debug_recorder)} entries)", + success=True, + error_details=_debug_recorder.as_details(), + ) + ) + # Persist new message UIDs so they are not processed again for uid in successfully_forwarded_uids: if uid not in already_seen_uids: @@ -513,15 +533,36 @@ async def process_mail_account(account_id: int): account.total_emails_failed += emails_failed # type: ignore[assignment] account.last_check_at = datetime.now(timezone.utc) # type: ignore[assignment] - if emails_failed == 0: - account.last_successful_check_at = datetime.now(timezone.utc) # type: ignore[assignment] - account.status = AccountStatus.ACTIVE # type: ignore[assignment] - account.last_error_message = None # type: ignore[assignment] - account.last_error_at = None # type: ignore[assignment] - else: - account.status = AccountStatus.ERROR # type: ignore[assignment] - account.last_error_at = datetime.now(timezone.utc) # type: ignore[assignment] - account.last_error_message = f"{emails_failed} emails failed to forward" # type: ignore[assignment] + # The fetch/connection succeeded: always clear any connection-level error + # and mark the account ACTIVE regardless of per-email forwarding failures. + # Per-email failures are already tracked in ProcessingLog and the + # run's emails_failed counter so the user can drill into them without + # having the account badge stuck in ERROR indefinitely. + account.last_successful_check_at = datetime.now(timezone.utc) # type: ignore[assignment] + account.status = AccountStatus.ACTIVE # type: ignore[assignment] + account.last_error_message = None # type: ignore[assignment] + account.last_error_at = None # type: ignore[assignment] + + # Auto-disable debug logging after 5 completed runs in the past 24 h + # to prevent it being left on indefinitely. + if account.debug_logging: # type: ignore[attr-defined] + _24h_ago = datetime.now(timezone.utc) - timedelta(hours=24) + _debug_run_count = ( + await db.execute( + select(func.count(ProcessingRun.id)).where( + ProcessingRun.mail_account_id == account.id, + ProcessingRun.started_at >= _24h_ago, + ProcessingRun.status.in_(["completed", "partial_failure"]), + ) + ) + ).scalar_one() + if _debug_run_count >= 5: + account.debug_logging = False # type: ignore[assignment] + logger.info( + "Auto-disabled debug logging for account %s after %d runs in 24 h", + account.id, + _debug_run_count, + ) await db.commit() diff --git a/backend/tests/unit/test_format_connection_error.py b/backend/tests/unit/test_format_connection_error.py new file mode 100644 index 0000000..92778b0 --- /dev/null +++ b/backend/tests/unit/test_format_connection_error.py @@ -0,0 +1,264 @@ +""" +Unit tests for _format_connection_error() and MailDebugRecorder. + +These tests verify: + - _format_connection_error returns human-readable, non-empty strings + for every relevant exception type. + - MailDebugRecorder caps its trace at the configured limits and never + includes password or credential data in its output. +""" + +import asyncio +import poplib +import socket +import ssl + + +from app.services.mail_processor import ( + MailDebugRecorder, + _format_connection_error, + _MAX_TRACE_ENTRIES, +) + +# --------------------------------------------------------------------------- +# _format_connection_error – helpers +# --------------------------------------------------------------------------- + + +def _fmt(exc: BaseException, host: str = "mail.example.com", port: int = 993) -> str: + return _format_connection_error(exc, host, port, "IMAP") + + +# --------------------------------------------------------------------------- +# DNS failure (socket.gaierror) +# --------------------------------------------------------------------------- + + +class TestFormatConnectionErrorDns: + def test_gaierror_includes_hostname(self): + exc = socket.gaierror(-5, "No address associated with hostname") + msg = _fmt(exc, host="pop.web.de", port=995) + assert "pop.web.de" in msg + assert "DNS" in msg or "resolve" in msg.lower() + + def test_gaierror_never_empty(self): + exc = socket.gaierror(-2, "Name or service not known") + assert _fmt(exc) + + def test_gaierror_without_host(self): + exc = socket.gaierror(-5, "No address associated with hostname") + msg = _format_connection_error(exc) + assert msg + assert "DNS" in msg or "lookup" in msg.lower() + + +# --------------------------------------------------------------------------- +# Timeout +# --------------------------------------------------------------------------- + + +class TestFormatConnectionErrorTimeout: + def test_socket_timeout_includes_host_port(self): + exc = socket.timeout("timed out") + msg = _fmt(exc, host="imap.gmx.net", port=993) + # Verify both the host and timeout indicator appear in the message + assert "imap.gmx.net" in msg + assert "993" in msg + assert "timed out" in msg.lower() or "timeout" in msg.lower() + + def test_asyncio_timeout_error(self): + exc = asyncio.TimeoutError() + msg = _fmt(exc) + assert msg # never empty even though str() is "" + assert "timed out" in msg.lower() or "timeout" in msg.lower() + + def test_bare_timeout_error(self): + """Python 3.11+ TimeoutError (subclass of OSError) should be handled.""" + exc = TimeoutError("timed out") + msg = _fmt(exc) + assert msg + + +# --------------------------------------------------------------------------- +# Connection refused / reset +# --------------------------------------------------------------------------- + + +class TestFormatConnectionErrorRefused: + def test_connection_refused_includes_host_port(self): + exc = ConnectionRefusedError(111, "Connection refused") + msg = _fmt(exc, host="smtp.example.com", port=587) + # Verify both host and port appear in the message + assert "smtp.example.com" in msg + assert "587" in msg + assert "refused" in msg.lower() + + def test_connection_reset(self): + exc = ConnectionResetError(104, "Connection reset by peer") + msg = _fmt(exc) + assert msg + assert "reset" in msg.lower() + + +# --------------------------------------------------------------------------- +# SSL errors +# --------------------------------------------------------------------------- + + +class TestFormatConnectionErrorSsl: + def test_ssl_cert_verification(self): + try: + # Create a real SSLCertVerificationError if possible + exc = ssl.SSLCertVerificationError( + 1, "[SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed" + ) + except Exception: + exc = ssl.SSLError(1, "CERTIFICATE_VERIFY_FAILED") # type: ignore[assignment] + msg = _fmt(exc) + assert msg + assert "TLS" in msg or "SSL" in msg or "certificate" in msg.lower() + + def test_ssl_generic_error(self): + exc = ssl.SSLError(1, "wrong version number") + msg = _fmt(exc) + assert msg + assert "TLS" in msg or "SSL" in msg + + +# --------------------------------------------------------------------------- +# POP3 protocol errors +# --------------------------------------------------------------------------- + + +class TestFormatConnectionErrorPop3: + def test_auth_error_identifies_auth_failure(self): + exc = poplib.error_proto("-ERR authentication failed") + msg = _format_connection_error(exc, "pop.example.com", 995, "POP3") + # Verify both host and port appear in the message + assert "pop.example.com" in msg + assert "995" in msg + assert "Authentication" in msg or "authentication" in msg + + def test_generic_pop3_error(self): + exc = poplib.error_proto("-ERR mailbox is locked") + msg = _format_connection_error(exc, "pop.example.com", 995, "POP3") + assert msg + assert "POP3" in msg + + def test_empty_pop3_error(self): + """Even a bare error_proto with no message must produce a non-empty string.""" + exc = poplib.error_proto(b"") + msg = _format_connection_error(exc, "pop.example.com", 995, "POP3") + assert msg + + +# --------------------------------------------------------------------------- +# Catch-all: empty-string exception +# --------------------------------------------------------------------------- + + +class TestFormatConnectionErrorFallback: + def test_empty_string_exception(self): + """An exception whose str() is empty must still produce a non-empty message.""" + exc = asyncio.TimeoutError() + assert str(exc) == "" # confirm the premise + msg = _fmt(exc) + assert msg + assert len(msg) > 0 + + def test_generic_exception(self): + exc = RuntimeError("something went wrong") + msg = _fmt(exc) + assert "something went wrong" in msg or "RuntimeError" in msg + + def test_no_host(self): + exc = RuntimeError("test") + msg = _format_connection_error(exc) + assert msg + + +# --------------------------------------------------------------------------- +# MailDebugRecorder +# --------------------------------------------------------------------------- + + +class TestMailDebugRecorder: + def test_record_entry_appears_in_trace(self): + rec = MailDebugRecorder() + rec.record("connect", "Connected to mail.example.com:993", {"elapsed_ms": 42}) + details = rec.as_details() + assert len(details["trace"]) == 1 + entry = details["trace"][0] + assert entry["phase"] == "connect" + assert entry["msg"] == "Connected to mail.example.com:993" + assert entry["data"]["elapsed_ms"] == 42 + assert not details["truncated"] + + def test_has_entries_false_when_empty(self): + rec = MailDebugRecorder() + assert not rec.has_entries() + + def test_has_entries_true_after_record(self): + rec = MailDebugRecorder() + rec.record("auth", "Logged in") + assert rec.has_entries() + + def test_size_cap_triggers_truncation(self): + """Recording beyond _MAX_TRACE_BYTES silently truncates.""" + rec = MailDebugRecorder() + # Each entry is ~100 chars; flood until truncated + long_msg = "x" * 1000 + for i in range(200): + rec.record("flood", long_msg, {"i": i}) + details = rec.as_details() + assert details["truncated"] + # After truncation, recording new entries is a no-op + prev_count = len(rec) + rec.record("after_truncate", "should be ignored") + assert len(rec) == prev_count + + def test_entry_cap_triggers_truncation(self): + """Recording more than _MAX_TRACE_ENTRIES entries truncates.""" + rec = MailDebugRecorder() + for i in range(_MAX_TRACE_ENTRIES + 10): + rec.record("phase", f"entry {i}") + assert rec.as_details()["truncated"] + # Total entries should be MAX + 1 (the truncation sentinel) + assert len(rec.as_details()["trace"]) <= _MAX_TRACE_ENTRIES + 1 + + def test_no_password_in_trace_from_production_phases(self): + """Production instrumentation records only usernames and counts, never passwords. + + The recorder itself has no auto-redaction; the contract is that callers + (the instrumented IMAP/POP3 code) must never pass credential data. + This test verifies the expected production-phase entries contain no + password strings. + """ + password = "s3cr3tP@ssw0rd!" + rec = MailDebugRecorder() + # Simulate the entries that production code actually records + rec.record("auth", "Authenticated as user@example.com", {"elapsed_ms": 5}) + rec.record("stat", "Mailbox has 3 messages", {"count": 3}) + + import json + + serialised = json.dumps(rec.as_details()) + # The password must not appear in any of these entries + assert password not in serialised + + def test_timestamps_are_iso_format(self): + rec = MailDebugRecorder() + rec.record("connect", "ok") + ts = rec.as_details()["trace"][0]["ts"] + # Should be parseable as ISO 8601 + from datetime import datetime + + datetime.fromisoformat(ts) # raises if invalid + + def test_multiple_phases_ordered(self): + rec = MailDebugRecorder() + for phase in ["connect", "auth", "select", "search", "fetch_msg", "logout"]: + rec.record(phase, f"{phase} done") + details = rec.as_details() + phases = [e["phase"] for e in details["trace"]] + assert phases == ["connect", "auth", "select", "search", "fetch_msg", "logout"] diff --git a/backend/tests/unit/test_mail_accounts.py b/backend/tests/unit/test_mail_accounts.py index d3e5ef5..be5f145 100644 --- a/backend/tests/unit/test_mail_accounts.py +++ b/backend/tests/unit/test_mail_accounts.py @@ -81,6 +81,7 @@ def _make_account(**overrides) -> MagicMock: check_interval_minutes=5, max_emails_per_check=50, delete_after_forward=True, + debug_logging=False, provider_name="Gmail", auto_detected=False, total_emails_processed=100, diff --git a/backend/tests/unit/test_mail_processor_pop3.py b/backend/tests/unit/test_mail_processor_pop3.py index 3169f57..b7f27e9 100644 --- a/backend/tests/unit/test_mail_processor_pop3.py +++ b/backend/tests/unit/test_mail_processor_pop3.py @@ -172,7 +172,7 @@ class TestTestPop3Connection: success, msg = await proc._test_pop3_connection() assert success is False - assert "Authentication failed" in msg + assert "Authentication rejected" in msg or "authentication" in msg.lower() @patch("app.services.mail_processor.poplib") async def test_pop3_protocol_error(self, mock_poplib): @@ -189,7 +189,7 @@ class TestTestPop3Connection: success, msg = await proc._test_pop3_connection() assert success is False - assert "POP3 protocol error" in msg + assert "POP3" in msg and "error" in msg.lower() @patch("app.services.mail_processor.poplib") async def test_pop3_generic_exception(self, mock_poplib): @@ -204,7 +204,7 @@ class TestTestPop3Connection: success, msg = await proc._test_pop3_connection() assert success is False - assert "Connection failed" in msg + assert msg # must be non-empty # --------------------------------------------------------------------------- @@ -280,7 +280,7 @@ class TestTestImapConnection: success, msg = await proc._test_imap_connection() assert success is False - assert "Authentication failed" in msg + assert "Authentication" in msg or "rejected" in msg @patch("app.services.mail_processor.aioimaplib") async def test_imap_generic_exception(self, mock_aioimaplib): @@ -292,7 +292,7 @@ class TestTestImapConnection: success, msg = await proc._test_imap_connection() assert success is False - assert "IMAP connection failed" in msg + assert msg # must be non-empty # --------------------------------------------------------------------------- @@ -498,13 +498,18 @@ class TestFetchPop3Emails: @patch("app.services.mail_processor.poplib") async def test_connection_failure_raises_mail_fetch_error(self, mock_poplib): - """Connection failure raises MailFetchError.""" + """Connection failure raises MailFetchError with non-empty message.""" + import poplib as real_poplib + + mock_poplib.error_proto = real_poplib.error_proto mock_poplib.POP3_SSL.side_effect = OSError("connection refused") account = _make_account(protocol="pop3_ssl") proc = MailProcessor(account, "secret") - with pytest.raises(MailFetchError, match="POP3 fetch error"): + with pytest.raises(MailFetchError) as exc_info: await proc._fetch_pop3_emails(10, set()) + # Message should be non-empty and describe the failure + assert str(exc_info.value) @patch("app.services.mail_processor.poplib") async def test_empty_mailbox(self, mock_poplib): diff --git a/docs/TODO.md b/docs/TODO.md index f19c0fd..58113c4 100644 --- a/docs/TODO.md +++ b/docs/TODO.md @@ -4,6 +4,25 @@ Comprehensive task breakdown for repository improvements and production readines ## ✅ Recently Completed +- [x] **IMAP/POP3 diagnostics — Step 1: Friendly error messages**: Added + `_format_connection_error()` helper that converts raw OS/socket/SSL/POP3/IMAP + exceptions into human-readable sentences with host:port context. Applied at + every `raise MailFetchError`/`MailConnectionError` site. Fixes blank "IMAP + fetch error:" messages and cryptic DNS errno strings. + +- [x] **IMAP/POP3 diagnostics — Step 2: Auto-clear stale error state**: Successful + fetches now always clear `last_error_message`/`last_error_at` and set + `status=ACTIVE`, even when some individual email forwards fail. Added + `POST /mail-accounts/{id}/clear-error` endpoint and "Clear" buttons on the + Accounts and Mailbox Activity pages. + +- [x] **IMAP/POP3 diagnostics — Step 3: Per-account debug logging**: Added + `debug_logging` boolean column (migration `0002`), `MailDebugRecorder` class, + instrumented all connection phases (connect, auth, select, search, fetch UIDs, + per-message fetch, logout), persisted as `ProcessingLog[level=DEBUG]`. + Auto-disables after 5 runs in 24 h. Toggle in account edit form. Connection + trace viewer in Mailbox Activity logs page. + - [x] **Google OAuth consent screen legal compliance**: Added English Privacy Policy (`/privacy`) with Google API Limited Use Disclosure, Terms of Service (`/terms`), legal footer links on the home page (resolves Google's "homepage has no privacy policy link" verification rejection), login page, and register page (consent text). Cross-link from `/datenschutz` to `/privacy` added. - [x] **Fix Pydantic V2 deprecation warnings**: Replaced `.dict()` with `.model_dump()` in `admin.py` and `notifications.py`. Fixed `RuntimeWarning: coroutine never awaited` for `db.add()` in test mocks (`test_tasks.py`, `test_config_service.py`). diff --git a/frontend/src/app/accounts/page.tsx b/frontend/src/app/accounts/page.tsx index 6409e1a..03eadd4 100644 --- a/frontend/src/app/accounts/page.tsx +++ b/frontend/src/app/accounts/page.tsx @@ -4,7 +4,7 @@ import { AuthGuard } from '@/components/AuthGuard'; import { DashboardLayout } from '@/components/DashboardLayout'; import { useQuery, useMutation, useQueryClient } from '@tanstack/react-query'; import { mailAccountsApi, MailAccount } from '@/lib/api'; -import { Plus, Edit2, Trash2, CheckCircle, XCircle, AlertTriangle, Power, RefreshCw } from 'lucide-react'; +import { Plus, Edit2, Trash2, CheckCircle, XCircle, AlertTriangle, Power, RefreshCw, RotateCcw } from 'lucide-react'; import { useState } from 'react'; import Image from 'next/image'; import { AddMailAccountModal } from '@/components/AddMailAccountModal'; @@ -115,6 +115,13 @@ export default function AccountsPage() { }, }); + const clearErrorMutation = useMutation({ + mutationFn: mailAccountsApi.clearError, + onSuccess: () => { + queryClient.invalidateQueries({ queryKey: ['mail-accounts'] }); + }, + }); + const handleEdit = (account: MailAccount) => { setEditingAccount(account); setIsModalOpen(true); @@ -253,9 +260,20 @@ export default function AccountsPage() { {account.last_error_message && (
{account.last_error_message}
+{account.last_error_message}
+{account.last_error_message}
+{account.last_error_message}
+| {formatDate(log.timestamp)} @@ -100,7 +143,7 @@ function RunDetailRow({ run }: { run: ProcessingRun }) { ))} |
No per-email logs for this run.
- )} + ) : null}{account.last_error_message}
+{account.last_error_message}
+