Using the python SMTP DebuggingServer to test SMTP communications

During the development of the dns-domain-expiration-checker script I needed a way to test SMTP mail delivery w/o relying on an actual mail exchanger. While reading through the smtplib and snmpd documentation I came across the SMTP debugging server. This nifty module allows you to run a local mail relay which will print the messages it receives to standard out. To enable it you can load the smtpd module and instruct it to run the DebuggingServer command on the IP and port passed as arguments:

$ python -m smtpd -c DebuggingServer -n localhost:8025

This will fire up a local mail server on localhost:8025 and each messaged received will be printed to STDOUT. If I run my DNS domain expiration script and point it to localhost:8025:

$ –domainname –email –expiredays 2000 –smtpserver localhost –smtpport 8025 –email

The debugging server prints the SMTP headers and body each time the script generates an e-mail:

$ python -m smtpd -c DebuggingServer -n localhost:8025

---------- MESSAGE FOLLOWS ----------
Content-Type: multipart/mixed; boundary="===============3200155514135298957=="
MIME-Version: 1.0
From: root
To: root
Subject: The DNS Domain is set to expire in 1041 days

Content-Type: text/plain; charset="us-ascii"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit

Time to renew
------------ END MESSAGE ------------

Super useful module for troubleshooting SMTP and e-mail communications!

Gathering statistics from your postfix mail logs

I have been supporting postfix mail relays for several years. When you are tasked with ensuring that your SMTP relays work without issue, you need to stay on top of the logs and the current operational state of each server to prevent major problems from occurring. Problems can take the form of blacklisted relays, mail routing loops, spam attacks or people trying to exploit a known issue in the SMTP software. All of these items suck for a site that relies on mail to function.

To help me keep on top of the relays I support, I use a multi-faceted approach. I summarize the log files daily, create scripts to notify me of problems before they cause issues, and try to be proactive about my relays (as much as you can be). To summarize my logs I use a combination of custom developed scripts and the incredibly awesome pflogsumm Perl script. The output of the scripts I developed provides me with specific data, and pflogsum produces a beautiful report that summarizes the overall operation of my Postfix SMTP relays:

$ zcat /var/log/maillog-20110710.gz |

Grand Totals

  19004   received
  20824   delivered
    696   forwarded
      3   deferred  (3  deferrals)
      0   bounced
      0   rejected (0%)
      0   reject warnings
      0   held
      0   discarded (0%)

  57945k  bytes received
 139101k  bytes delivered
     66   senders
     28   sending hosts/domains
    175   recipients
     31   recipient hosts/domains

Per-Day Traffic Summary
    date          received  delivered   deferred    bounced     rejected
    Jul  3 2011      2006       1875 
    Jul  4 2011      2212       1992          2 
    Jul  5 2011      2855       3568 
    Jul  6 2011      3212       3823 
    Jul  7 2011      3212       3962          1 
    Jul  8 2011      2581       2747 
    Jul  9 2011      2665       2654 
    Jul 10 2011       261        203 

Per-Hour Traffic Daily Average
    time          received  delivered   deferred    bounced     rejected
    0000-0100          78         51          0          0          0 
    0100-0200          74         51          0          0          0 
    0200-0300          99         87          0          0          0 
    0300-0400          73         52          0          0          0 
    0400-0500          73         53          0          0          0 
    0500-0600          76         68          0          0          0 
    0600-0700         110        129          0          0          0 
    0700-0800         106        134          0          0          0 
    0800-0900          84         70          0          0          0 
    0900-1000          92        103          0          0          0 
    1000-1100         103        106          0          0          0 
    1100-1200         102        103          0          0          0 
    1200-1300          95         93          0          0          0 
    1300-1400         103        116          0          0          0 
    1400-1500         108        124          0          0          0 
    1500-1600         112        142          0          0          0 
    1600-1700         114        129          0          0          0 
    1700-1800         111        125          0          0          0 
    1800-1900         135        176          0          0          0 
    1900-2000         144        194          0          0          0 
    2000-2100         134        224          0          0          0 
    2100-2200          88        101          0          0          0 
    2200-2300          82         85          0          0          0 
    2300-2400          82         88          0          0          0 

Host/Domain Summary: Message Delivery 
 sent cnt  bytes   defers   avg dly max dly host/domain
 -------- -------  -------  ------- ------- -----------
  10247    81716k       1     0.5 s    5.5 m

Host/Domain Summary: Messages Received 
 msg cnt   bytes   host/domain
 -------- -------  -----------
   3094    22088k

Senders by message count

Recipients by message count

Senders by message size

Recipients by message size

Messages with no size data

message deferral detail
  smtp (total: 3)
         2   25: Connection timed out
         1   lost connection with[

message bounce detail (by relay): none

message reject detail: none

message reject warning detail: none

message hold detail: none

message discard detail: none

smtp delivery failures: none

  smtpd (total: 14)
        14   non-SMTP command from unknown[]: To: 
  trivial-rewrite (total: 430)
       430   database /etc/postfix/transport.db is older than source file /e...

Fatal Errors: none

Panics: none

Master daemon messages: none

I can’t tell you how many times I’ve run this script and seen something in the output that left me wondering WTF?!? Several times I’ve been able to use the output from this script to nip a problem before it becomes a major issue. The output is also handy for developing some additional monitoring for your SMTP services. If you are using postfix you should definitely check out pflogsumm. You will be glad you did!!!

Testing postfix restrictions

The postfix mail delivery system allows one or more restrictions to be placed on incoming messages. These restrictions allow you to block messages when clients don’t use the SMTP handshake as outlined in RFC 821 during delivery, if the name supplied in the HELO is not fully qualified or fails to resolve, or if the connecting host resides on one or more blacklists. Several restrictions come enabled by default, but others need to be manually enabled by adding additional directives to the smtpd_helo_restrictions, smtpd_sender_restrictions and smtpd_recipient_restrictions variables. Since new restrictions can have unexpected results (e.g., lost E-mail), it is beneficial to test these rules prior to enforcing them.

The soft_bounce directive is one way to test out new rules. When soft_bounce is set in the, a message that would be blocked by a restriction is rejected with a soft reject error code (typically something in the 4XX range). The soft reject will force the sending host to queue the message, and attempt redelivery at a later date. Each time a soft bounce occurs, postfix will log a message to the logging facility. Since the server that sent the message will attempt to redeliver the message at a later date, you can tweak the configuration prior to the next delivery attempt if you want to accept mail from the host that matched the restriction. This method does have one major drawback. Numerous MTAs on the Internet use low TTLs on messages in their mail queues, so using soft bounces can result in messages getting returned to the sender if the restriction isn’t adjusted in a timely manner.

An alternative method to soft bounces is the warn_if_reject qualifier. Instead of soft bouncing the message if the sender matches a restriction, the warn_if_reject qualifier will cause postfix to deliver the message, and log a warning when a message matches a restriction. This ensures that mail is delivered if the restriction has an unknown side effect, and allows the mail admin to test restrictions in a non-intrusive way. Warn_if_reject can be applied to all of the postfix restrictions ( I have yet to find a restriction that warn_if_reject doesn’t apply to, but there may be some), and is set by prepending the string “warn_if_reject” to the restriction:

smtpd_helo_restrictions         = permit_mynetworks,
                                  warn_if_reject reject_invalid_hostname,
                                  warn_if_reject reject_unknown_hostname

To get a daily report with messages that matched the restriction, you can use the awesome pflogsum Perl script. Using warn_if_reject has saved me a fair amount of grief, and is a great way to make sure a restriction does what you want it to.