Merge pull request #4881 from mozilla/update-header-logging-mpp4841

MPP-3839: Update email header logging

emails/policy.py

@@ -73,6 +73,7 @@ class RelayHeaderRegistry(PythonHeaderRegistry):
         as_unstructured = as_unstructured_cls(name, value)
         # Avoid mypy attr-defined error for setting a dynamic attribute
         setattr(header_instance, "as_unstructured", as_unstructured)
+        setattr(header_instance, "as_raw", value)
         return header_instance
 
 

emails/tests/views_tests.py

@@ -641,7 +641,7 @@ class SNSNotificationIncomingTest(SNSNotificationTestBase):
         assert self.ra.num_forwarded == 1
         assert self.ra.last_used_at
         assert (datetime.now(tz=UTC) - self.ra.last_used_at).seconds < 2.0
-        mock_logger.warning.assert_not_called()
+        mock_logger.info.assert_not_called()
 
     @patch("emails.views.info_logger")
     def test_from_with_unquoted_commas_is_parsed(self, mock_logger: Mock) -> None:
@@ -658,25 +658,24 @@ class SNSNotificationIncomingTest(SNSNotificationTestBase):
         self.check_sent_email_matches_fixture(
             "emperor_norton", replace_mime_boundaries=True
         )
-        expected_header_errors = {
-            "incoming": [
-                (
-                    "From",
-                    {
-                        "defect_count": 4,
-                        "parsed_value": (
-                            '"Norton I.", Emperor of the United States'
-                            " <norton@sf.us.example.com>"
-                        ),
-                        "unstructured_value": (
-                            "Norton I., Emperor of the United States"
-                            " <norton@sf.us.example.com>"
-                        ),
-                    },
-                )
-            ]
-        }
-        mock_logger.warning.assert_called_once_with(
+
+        expected_header_errors = [
+            {
+                "header": "From",
+                "direction": "in",
+                "defect_count": 4,
+                "parsed_value": (
+                    '"Norton I.",'
+                    " Emperor of the United States <norton@sf.us.example.com>"
+                ),
+                "raw_value": (
+                    "Norton I.,"
+                    " Emperor of the United States <norton@sf.us.example.com>"
+                ),
+            }
+        ]
+
+        mock_logger.info.assert_called_once_with(
             "_handle_received: forwarding issues",
             extra={"issues": {"headers": expected_header_errors}},
         )
@@ -697,7 +696,7 @@ class SNSNotificationIncomingTest(SNSNotificationTestBase):
                 ],
             },
         )
-        mock_logger.warning.assert_not_called()
+        mock_logger.info.assert_not_called()
 
     @patch("emails.views.info_logger")
     def test_invalid_message_id_is_forwarded(self, mock_logger: Mock) -> None:
@@ -709,23 +708,16 @@ class SNSNotificationIncomingTest(SNSNotificationTestBase):
         self.check_sent_email_matches_fixture(
             "message_id_in_brackets", replace_mime_boundaries=True
         )
-        expected_header_errors = {
-            "incoming": [
-                (
-                    "Message-ID",
-                    {
-                        "defect_count": 1,
-                        "parsed_value": (
-                            "<[d7c5838b5ab944f89e3f0c1b85674aef====@example.com]>"
-                        ),
-                        "unstructured_value": (
-                            "<[d7c5838b5ab944f89e3f0c1b85674aef====@example.com]>"
-                        ),
-                    },
-                )
-            ]
-        }
-        mock_logger.warning.assert_called_once_with(
+        expected_header_errors = [
+            {
+                "header": "Message-ID",
+                "direction": "in",
+                "defect_count": 1,
+                "parsed_value": "<[d7c5838b5ab944f89e3f0c1b85674aef====@example.com]>",
+                "raw_value": "<[d7c5838b5ab944f89e3f0c1b85674aef====@example.com]>",
+            }
+        ]
+        mock_logger.info.assert_called_once_with(
             "_handle_received: forwarding issues",
             extra={"issues": {"headers": expected_header_errors}},
         )
@@ -747,7 +739,19 @@ class SNSNotificationIncomingTest(SNSNotificationTestBase):
         assert self.ra.num_forwarded == 1
         assert self.ra.last_used_at
         assert (datetime.now(tz=UTC) - self.ra.last_used_at).seconds < 2.0
-        mock_logger.warning.assert_not_called()
+        expected_header_errors = [
+            {
+                "header": "Subject",
+                "direction": "in",
+                "defect_count": 1,
+                "parsed_value": "An encoded newline\n",
+                "raw_value": "An =?UTF-8?Q?encoded_newline=0A?=",
+            }
+        ]
+        mock_logger.info.assert_called_once_with(
+            "_handle_received: forwarding issues",
+            extra={"issues": {"headers": expected_header_errors}},
+        )
 
 
 class SNSNotificationRepliesTest(SNSNotificationTestBase):
@@ -2357,9 +2361,13 @@ def test_replace_headers_read_error_is_handled() -> None:
         issues = _replace_headers(email, new_headers)
 
     # The mocked exception was handled and logged
-    assert issues == {
-        "incoming": [("X-Fail", {"exception_on_read": "RuntimeError('I failed.')"})]
-    }
+    assert issues == [
+        {
+            "header": "X-Fail",
+            "direction": "in",
+            "exception_on_read": "RuntimeError('I failed.')",
+        }
+    ]
 
     # _replace_headers continued working with the remaining data, the headers are now
     # set to the desired new values.

emails/types.py

@@ -23,18 +23,24 @@ AWS_MailJSON = dict[str, Any]
 
 
 class EmailHeaderExceptionOnReadIssue(TypedDict):
+    header: str
+    direction: Literal["in"]
     exception_on_read: str
 
 
 class EmailHeaderExceptionOnWriteIssue(TypedDict):
+    header: str
+    direction: Literal["out"]
     exception_on_write: str
     value: str
 
 
 class EmailHeaderDefectIssue(TypedDict):
+    header: str
+    direction: Literal["in", "out"]
     defect_count: int
     parsed_value: str
-    unstructured_value: str
+    raw_value: str
 
 
 EmailHeaderIssue = (
@@ -43,8 +49,6 @@ EmailHeaderIssue = (
     | EmailHeaderDefectIssue
 )
 
-EmailHeaderIssues = dict[
-    Literal["incoming", "outgoing"], list[tuple[str, EmailHeaderIssue]]
-]
+EmailHeaderIssues = list[EmailHeaderIssue]
 
 EmailForwardingIssues = dict[Literal["headers"], EmailHeaderIssues]

emails/views.py

@@ -3,7 +3,6 @@ import json
 import logging
 import re
 import shlex
-from collections import defaultdict
 from copy import deepcopy
 from datetime import UTC, datetime
 from email import message_from_bytes
@@ -784,7 +783,7 @@ def _handle_received(message_json: AWS_SNSMessageJSON) -> HttpResponse:
     if has_text:
         incr_if_enabled("email_with_text_content", 1)
     if issues:
-        info_logger.warning(
+        info_logger.info(
             "_handle_received: forwarding issues", extra={"issues": issues}
         )
 
@@ -1026,25 +1025,36 @@ def _replace_headers(
     # Look for headers to drop
     to_drop: list[str] = []
     replacements: set[str] = {_k.lower() for _k in headers.keys()}
-    issues: EmailHeaderIssues = defaultdict(list)
+    issues: EmailHeaderIssues = []
 
     # Detect non-compliant headers in incoming emails
     for header in email.keys():
         try:
             value = email[header]
         except Exception as e:
-            issues["incoming"].append((header, {"exception_on_read": repr(e)}))
+            issues.append(
+                {"header": header, "direction": "in", "exception_on_read": repr(e)}
+            )
             value = None
         if getattr(value, "defects", None):
-            issues["incoming"].append(
-                (
-                    header,
-                    {
-                        "defect_count": len(value.defects),
-                        "parsed_value": str(value),
-                        "unstructured_value": str(value.as_unstructured),
-                    },
-                )
+            issues.append(
+                {
+                    "header": header,
+                    "direction": "in",
+                    "defect_count": len(value.defects),
+                    "parsed_value": str(value),
+                    "raw_value": str(value.as_raw),
+                }
+            )
+        elif getattr(getattr(value, "_parse_tree", None), "all_defects", []):
+            issues.append(
+                {
+                    "header": header,
+                    "direction": "in",
+                    "defect_count": len(value._parse_tree.all_defects),
+                    "parsed_value": str(value),
+                    "raw_value": str(value.as_raw),
+                }
             )
 
     # Collect headers that will not be forwarded
@@ -1067,28 +1077,39 @@ def _replace_headers(
         try:
             email[header] = value.rstrip("\r\n")
         except Exception as e:
-            issues["outgoing"].append(
-                (header, {"exception_on_write": repr(e), "value": value})
+            issues.append(
+                {
+                    "header": header,
+                    "direction": "out",
+                    "exception_on_write": repr(e),
+                    "value": value,
+                }
             )
             continue
         try:
             parsed_value = email[header]
         except Exception as e:
-            issues["outgoing"].append((header, {"exception_on_read": repr(e)}))
+            issues.append(
+                {
+                    "header": header,
+                    "direction": "out",
+                    "exception_on_write": repr(e),
+                    "value": value,
+                }
+            )
             continue
         if parsed_value.defects:
-            issues["outgoing"].append(
-                (
-                    header,
-                    {
-                        "defect_count": len(parsed_value.defects),
-                        "parsed_value": str(parsed_value),
-                        "unstructured_value": str(parsed_value.as_unstructured),
-                    },
-                )
+            issues.append(
+                {
+                    "header": header,
+                    "direction": "out",
+                    "defect_count": len(parsed_value.defects),
+                    "parsed_value": str(parsed_value),
+                    "raw_value": str(parsed_value.as_raw),
+                },
             )
 
-    return dict(issues)
+    return issues
 
 
 def _convert_html_content(