Merge lp:~thumper/launchpad/mail-header-oops into lp:launchpad

[Tim Penhey]

[r=lifeless,wallyworld][bug=701976,728827] Lower some log.warning to log.info as warnings generate oopses.

Warnings that are logged are turned into OOPSes by the
OOPS log handler added by the base CronScript class.

I've updated the behaviour of the header checking based
on the comments in bug 701976.

[Martin Pool (mbp)]

+def extract_addresses(mail, raw_mail, file_alias_url, log):
+ # Extract the domain the mail was sent to. Mails sent to
+ # Launchpad should have an X-Launchpad-Original-To header.

Why not turn that into a docstring? And, maybe add things just saying the types of the parameters and the return code. It's the kind of thing that easily has bugs about passing a string vs a list of strings vs a file etc. (Or, you could use a statically type-checked language. :-P)

+ if ORIGINAL_TO_HEADER in mail:
+ return [mail[ORIGINAL_TO_HEADER]]
+
+ if ORIGINAL_TO_HEADER in raw_mail:
+ # Almost certainly a spam email with a blank line in the email headers
+ log.info('Suspected spam: %s' % file_alias_url)

I really do not see how the comment follows from the condition. How can you even have a blank line in the headers? You can have a blank line that causes things that ought to be headers to be part of the body, but no reasonable mail agent will see them as headers then.

Perhaps this should say something like:

 # Doesn't have an X-Launchpad-Original-To in the headers, but does have one in the body, because of a forwarding loop or attempted spam. See <https://bugs.launchpad.net/launchpad/+bug/701976>

[Martin Pool (mbp)]

I'm +1 on the dkim changes, and -1 (pending more information) on the x-l-original-to changes. Having that substring within a message doesn't mean it's spam.

[Tim Penhey (thumper)]

I agree that having that substring within the message doesn't mean it is spam, but having it in the message but not in the headers means that the headers have been messed with somehow, and that is more indicative of spam. I've updated the code to match your suggested wording.

[Martin Pool (mbp)]

I don't understand at the moment how incoming spam can cause the
headers to be split and x-l-original-to not to be attached. That
seems to me to be more likely to be a bug or misconfiguration in our
software.

Martin

[Ian Booth (wallyworld)]

I like the wording change suggested by Martin.
The scenarios tested for seem to match the observed data referred to in the bug report so to me it looks ok.

review: Approve (*code)

[Martin Pool (mbp)]

On 4 March 2011 14:54, Tim Penhey <email address hidden> wrote:
> I agree that having that substring within the message doesn't mean it is spam, but having it in the message but not in the headers means that the headers have been messed with somehow, and that is more indicative of spam.

I think we ought to identify why spam is causing the messages to be
corrupted. Checking for this string is just superstition.

[Martin Pool (mbp)]

Note that we're not checking for a body that looks like it contains headers, which might be a somewhat-reliable indicator of either spam or something broken. We're just looking for that string anywhere in the body. It's reasonably likely to match on messages that do not contain broken headers.

[Robert Collins (lifeless)]

@Martin - spam often has invalid headers (attempting smuggling) and our x-original-to mangler adds it after the invalid header, but our lp parser stops at the invalid point. So this is pretty reliable and won't reject valid mail AFAWCT.

review: Approve

=== modified file 'lib/lp/services/mail/incoming.py'
--- lib/lp/services/mail/incoming.py	2011-03-03 02:29:54 +0000
+++ lib/lp/services/mail/incoming.py	2011-03-09 20:52:00 +0000
@@ -143,19 +143,19 @@
     # in addition to the dkim signature being valid, we have to check that it
     # was actually signed by the user's domain.
     if len(signing_details) != 1:
-        log.errors(
+        log.info(
             'expected exactly one DKIM details record: %r'
             % (signing_details,))
         return False
     signing_domain = signing_details[0]['d']
     from_domain = extract_address_domain(signed_message['From'])
     if signing_domain != from_domain:
-        log.warning("DKIM signing domain %s doesn't match From address %s; "
+        log.info("DKIM signing domain %s doesn't match From address %s; "
             "disregarding signature"
             % (signing_domain, from_domain))
         return False
     if not _isDkimDomainTrusted(signing_domain):
-        log.warning("valid DKIM signature from untrusted domain %s"
+        log.info("valid DKIM signature from untrusted domain %s"
             % (signing_domain,))
         return False
     return True
@@ -262,6 +262,36 @@
         self.setOopsToken('EMAIL')
 
 
+ORIGINAL_TO_HEADER = 'X-Launchpad-Original-To'
+
+
+def extract_addresses(mail, raw_mail, file_alias_url, log):
+    """Extract the domain the mail was sent to.
+
+    Mails sent to Launchpad should have an X-Launchpad-Original-To header.
+    This is added by the MTA before it ends up the mailbox for Launchpad.
+    """
+    if ORIGINAL_TO_HEADER in mail:
+        return [mail[ORIGINAL_TO_HEADER]]
+
+    if ORIGINAL_TO_HEADER in raw_mail:
+        # Doesn't have an X-Launchpad-Original-To in the headers, but does
+        # have one in the body, because of a forwarding loop or attempted
+        # spam.  See <https://bugs.launchpad.net/launchpad/+bug/701976>
+        log.info('Suspected spam: %s' % file_alias_url)
+    else:
+        # This most likely means a email configuration problem, and it should
+        # log an oops.
+        log.warn(
+            "No X-Launchpad-Original-To header was present "
+            "in email: %s" % file_alias_url)
+    # Process all addresses found as a fall back.
+    cc = mail.get_all('cc') or []
+    to = mail.get_all('to') or []
+    names_addresses = getaddresses(to + cc)
+    return [addr for name, addr in names_addresses]
+
+
 def report_oops(file_alias_url=None, error_msg=None):
     """Record an OOPS for the current exception and return the OOPS ID."""
     info = sys.exc_info()
@@ -280,7 +310,7 @@
 
 
 def handleMail(trans=transaction,
-    signature_timestamp_checker=None):
+               signature_timestamp_checker=None):
     # First we define an error handler. We define it as a local
     # function, to avoid having to pass a lot of parameters.
     # pylint: disable-msg=W0631
@@ -394,21 +424,8 @@
                         file_alias_url, notify=False)
                     continue
 
-                # Extract the domain the mail was sent to.  Mails sent to
-                # Launchpad should have an X-Launchpad-Original-To header.
-                if 'X-Launchpad-Original-To' in mail:
-                    addresses = [mail['X-Launchpad-Original-To']]
-                else:
-                    log = logging.getLogger('lp.services.mail')
-                    log.warn(
-                        "No X-Launchpad-Original-To header was present "
-                        "in email: %s" %
-                         file_alias_url)
-                    # Process all addresses found as a fall back.
-                    cc = mail.get_all('cc') or []
-                    to = mail.get_all('to') or []
-                    names_addresses = getaddresses(to + cc)
-                    addresses = [addr for name, addr in names_addresses]
+                addresses = extract_addresses(
+                    mail, raw_mail, file_alias_url, log)
 
                 try:
                     do_paranoid_envelope_to_validation(addresses)
@@ -464,7 +481,6 @@
                 # from being processed.
                 _handle_error(
                     "Unhandled exception", file_alias_url)
-                log = logging.getLogger('canonical.launchpad.mail')
                 if file_alias_url is not None:
                     email_info = file_alias_url
                 else:

=== modified file 'lib/lp/services/mail/tests/incomingmail.txt'
--- lib/lp/services/mail/tests/incomingmail.txt	2010-12-13 17:34:34 +0000
+++ lib/lp/services/mail/tests/incomingmail.txt	2011-03-09 20:52:00 +0000
@@ -101,10 +101,10 @@
 header is missing.)
 
     >>> handleMailForTest()
-    WARNING:lp.services.mail:No X-Launchpad-Original-To header was present ...
-    WARNING:lp.services.mail:No X-Launchpad-Original-To header was present ...
-    WARNING:lp.services.mail:No X-Launchpad-Original-To header was present ...
-    WARNING:lp.services.mail:No X-Launchpad-Original-To header was present ...
+    WARNING:process-mail:No X-Launchpad-Original-To header was present ...
+    WARNING:process-mail:No X-Launchpad-Original-To header was present ...
+    WARNING:process-mail:No X-Launchpad-Original-To header was present ...
+    WARNING:process-mail:No X-Launchpad-Original-To header was present ...
 
 Now we can see that each handler handled the emails sent to its domain:
 
@@ -252,7 +252,7 @@
     ... """)
     >>> msgid = sendmail(msg, ['edit@malone-domain'])
     >>> handleMailForTest()
-    ERROR:canonical.launchpad.mail:An exception was raised inside the handler:
+    ERROR:process-mail:An exception was raised inside the handler:
     ...
     TestOopsException
 
@@ -300,7 +300,7 @@
     ... """)
     >>> msgid = sendmail(msg, ['edit@malone-domain'])
     >>> handleMailForTest()
-    ERROR:canonical.launchpad.mail:An exception was raised inside the handler:
+    ERROR:process-mail:An exception was raised inside the handler:
     ...
     Unauthorized
 

=== modified file 'lib/lp/services/mail/tests/test_incoming.py'
--- lib/lp/services/mail/tests/test_incoming.py	2011-03-03 02:29:54 +0000
+++ lib/lp/services/mail/tests/test_incoming.py	2011-03-09 20:52:00 +0000
@@ -6,7 +6,7 @@
 import os
 import unittest
 
-from testtools.matchers import Is
+from testtools.matchers import Equals, Is
 import transaction
 from zope.security.management import setSecurityPolicy
 
@@ -19,10 +19,13 @@
     helpers,
     )
 from canonical.testing.layers import LaunchpadZopelessLayer
+from lp.services.log.logger import BufferLogger
 from lp.services.mail.incoming import (
     authenticateEmail,
+    extract_addresses,
     handleMail,
     MailErrorUtility,
+    ORIGINAL_TO_HEADER,
     )
 from lp.services.mail.sendmail import MailController
 from lp.services.mail.stub import TestMailer
@@ -119,6 +122,46 @@
         self.assertThat(authenticateEmail(mail), Is(None))
 
 
+class TestExtractAddresses(TestCaseWithFactory):
+
+    layer = LaunchpadZopelessLayer
+
+    def test_original_to(self):
+        mail = self.factory.makeSignedMessage()
+        original_to = '[e-mail]'
+        mail[ORIGINAL_TO_HEADER] = original_to
+        self.assertThat(
+            extract_addresses(mail, None, None, None),
+            Equals([original_to]))
+
+    def test_original_to_in_body(self):
+        header_to = '[e-mail]'
+        original_to = '[e-mail]'
+        alias = 'librarian-somewhere'
+        body = '%s: %s\n\nsome body stuff' % (
+            ORIGINAL_TO_HEADER, original_to)
+        log = BufferLogger()
+        mail = self.factory.makeSignedMessage(
+            body=body, to_address=header_to)
+        addresses = extract_addresses(mail, mail.as_string(), alias, log)
+        self.assertThat(addresses, Equals([header_to]))
+        self.assertThat(
+            log.getLogBuffer(),
+            Equals('INFO Suspected spam: librarian-somewhere\n'))
+
+    def test_original_to_missing(self):
+        header_to = '[e-mail]'
+        alias = 'librarian-somewhere'
+        log = BufferLogger()
+        mail = self.factory.makeSignedMessage(to_address=header_to)
+        addresses = extract_addresses(mail, mail.as_string(), alias, log)
+        self.assertThat(addresses, Equals([header_to]))
+        self.assertThat(
+            log.getLogBuffer(),
+            Equals('WARNING No X-Launchpad-Original-To header was present '
+                   'in email: librarian-somewhere\n'))
+
+
 def setUp(test):
     test._old_policy = setSecurityPolicy(LaunchpadSecurityPolicy)
     LaunchpadZopelessLayer.switchDbUser(config.processmail.dbuser)

=== modified file 'lib/lp/testing/factory.py'
--- lib/lp/testing/factory.py	2011-03-07 19:06:47 +0000
+++ lib/lp/testing/factory.py	2011-03-09 20:52:00 +0000
@@ -1829,7 +1829,7 @@
 
     def makeSignedMessage(self, msgid=None, body=None, subject=None,
             attachment_contents=None, force_transfer_encoding=False,
-            email_address=None, signing_context=None):
+            email_address=None, signing_context=None, to_address=None):
         """Return an ISignedMessage.
 
         :param msgid: An rfc2822 message-id.
@@ -1847,8 +1847,10 @@
             person = self.makePerson()
             email_address = removeSecurityProxy(person).preferredemail.email
         mail['From'] = email_address
-        mail['To'] = removeSecurityProxy(
-            self.makePerson()).preferredemail.email
+        if to_address is None:
+            to_address = removeSecurityProxy(
+                self.makePerson()).preferredemail.email
+        mail['To'] = to_address
         if subject is None:
             subject = self.getUniqueString('subject')
         mail['Subject'] = subject