[Mailman-Users] delay on mailman sending out messages

Mon Mar 6 18:02:17 EST 2017

On 03/06/2017 10:31 AM, Bruce Harrison wrote:
> I'm running Mailman 2.1.7
> 
> In the past month or two.  I'm seeing Mailman delaying sending out messages.  In the logs I see where it's posted, then in /var/logs/maillog I see sending start immediately and then somewhere along the line a delay of an hour or two, then it finishes sending. Or it delays initially then starts sending.
> This hasn't been happening in the past.  We in the process of moving a lot of our mail users to O365
> Not sure what's going on or how best to troubleshoot.  Any ideas?

I assume from the above that your concern is the delays following this

> Post Log
> Mar 03 13:34:57 2017 (1223) post to information from munger at utm.edu, size=37061, message-id=<320E686FEA4720449A309FC08FC6F49D01023D575A at EXCH2010MBOX2.utm.edu>, success log

entry and not with the delay between this

> /var/logs/maillog
> Mar  3 09:11:23 mailman sendmail[17197]: v23FBNsO017197: from=<munger at utm.edu>, size=35583, class=0, nrcpts=1, msgid=<320E686FEA4720449A309FC08FC6F49D01023D575A at EXCH2010MBOX2.utm.edu>, proto=ESMTP, daemon=MTA, relay=mail-dm3nam03lp0023.outbound.protection.outlook.com [207.46.163.23]

and the rest.  When the post log entry is written at 13:34:57, Mailman
has finished the delivery of the message for all recipients to sendmail.
Further delays are entirely within sendmail.

> Mar  3 13:34:56 mailman sendmail[22801]: v23JYu9r022801: from=<information-bounces at mailman.utm.edu>, size=37061, class=-30, nrcpts=150, msgid=<320E686FEA4720449A309FC08FC6F49D01023D575A at EXCH2010MBOX2.utm.edu>, proto=ESMTP, daemon=MTA, relay=localhost [127.0.0.1] (may be forged)
> Mar  3 13:34:56 mailman sendmail[22801]: v23JYu9s022801: from=<information-bounces at mailman.utm.edu>, size=37061, class=-30, nrcpts=500, msgid=<320E686FEA4720449A309FC08FC6F49D01023D575A at EXCH2010MBOX2.utm.edu>, proto=ESMTP, daemon=MTA, relay=localhost [127.0.0.1] (may be forged)
> Mar  3 13:34:57 mailman sendmail[22801]: v23JYu9t022801: from=<information-bounces at mailman.utm.edu>, size=37061, class=-30, nrcpts=500, msgid=<320E686FEA4720449A309FC08FC6F49D01023D575A at EXCH2010MBOX2.utm.edu>, proto=ESMTP, daemon=MTA, relay=localhost [127.0.0.1] (may be forged)
> Mar  3 13:34:57 mailman sendmail[22801]: v23JYu9u022801: from=<information-bounces at mailman.utm.edu>, size=37061, class=-30, nrcpts=500, msgid=<320E686FEA4720449A309FC08FC6F49D01023D575A at EXCH2010MBOX2.utm.edu>, proto=ESMTP, daemon=MTA, relay=localhost [127.0.0.1] (may be forged)
> Mar  3 13:34:57 mailman sendmail[22801]: v23JYu9v022801: from=<information-bounces at mailman.utm.edu>, size=37061, class=-30, nrcpts=8, msgid=<320E686FEA4720449A309FC08FC6F49D01023D575A at EXCH2010MBOX2.utm.edu>, proto=ESMTP, daemon=MTA, relay=localhost [127.0.0.1] (may be forged)
> Mar  3 13:34:57 mailman sendmail[22801]: v23JYu9w022801: from=<information-bounces at mailman.utm.edu>, size=37061, class=-30, nrcpts=7, msgid=<320E686FEA4720449A309FC08FC6F49D01023D575A at EXCH2010MBOX2.utm.edu>, proto=ESMTP, daemon=MTA, relay=localhost [127.0.0.1] (may be forged)

The above are sendmail's receipt of the delivered "chunks" from mailman.
Mailman is dividing the recipient list into chunks by top level domain.
See the comments in the code near the beginning of the definition of the
process function in Mailman/Handlers/SMTPDirect.py and the chunkify
function for how this is done.

In your case, SMTP_MAX_RCPTS is the default 500 and your recipients for
this message are split into 6 chunks of 150, 500, 500, 500, 8 and 7
recipients respectively and those are delivered to sendmail in 6 smtp
transactions, each with the respective number of RCPT TO recipients.

Then sendmail begins delivery.

> Mar  3 13:35:02 mailman sendmail[22811]: v23JYu9v022801: to=<trinitypresb at frontiernet.net>,<mcochran at wljt.org>,<khicks at utfcu.org>,<trinitypastor at frontiernet.net>,<mshumake at wljt.org>,<mnperry at comcast.net>,<mreese at wljt.org>,<mfield at charter.net>, delay=00:00:05, xdelay=00:00:05, mailer=relay, pri=331061, relay=xmail.utm.edu. [10.51.0.154], dsn=2.0.0, stat=Sent (<320E686FEA4720449A309FC08FC6F49D01023D575A at EXCH2010MBOX2.utm.edu> [InternalId=7717462] Queued mail for delivery)

This chunk with 8 recipients in various domains is delivered quickly

> Mar  3 13:35:02 mailman sendmail[22805]: v23JYu9s022801: to=<thibbard at utm.edu>,<clovette at utm.edu>,<dahender at utm.edu>,<mbrooks at utm.edu>,<afulle14 at utm.edu>,<kroudenb at utm.edu>,<bjohnson at utm.edu>,<ndavis at utm.edu>,<jimerson at utm.edu>,<sburliso at utm.edu>,<thutche2 at utm.edu>,<hchen38 at utm.edu>,<nashbaug at utm.edu>,<mparish1 at utm.edu>,<jjohn275 at utm.edu>,<tgallien at utm.edu>,<sgoldmon at utm.edu>,<agardner at utm.edu>,<ddietrich at utm.edu>,<jfishe37 at utm.edu>,<ahuffma2 at utm.edu>,<kwheel19 at utm.edu>,<lmccurley at utm.edu>,<kelmwhit at ut.utm.edu>,<khammond at utm.edu>,<jscott61 at utm.edu>,<aricha54 at utm.edu>,<rpruit10 at utm.edu>,<ewheeler at utm.edu>,<lgibson at utm.edu>,<shalkias at utm.edu>,<akeller at utm.edu>,<phewitt at utm.edu>,<dabel at utm.edu>,<dryan11 at utm.edu>,<jdavis at utm.edu>, [more], delay=00:00:06, xdelay=00:00:06, mailer=relay, pri=15091061, relay=xmail.utm.edu. [10.51.0.154], dsn=2.0.0, stat=Sent (<320E686FEA4720449A309FC08FC6F49D01023D575A at EXCH2010MBOX2.utm.edu> [InternalId=7717459] Queued mail for delivery)

as is this chunk with a large number of utm recipients.
> .
> .
> .
> Mar  3 13:35:30 mailman sendmail[22805]: v23JYu9s022801: to=<jjones98 at utm.edu>,<pwatkins at utm.edu>,<dmccull1 at utm.edu>,<dwilliams-boyd at utm.edu>,<jbyrd24 at utm.edu>,<ajohn171 at utm.edu>,<jgoyret at utm.edu>,<sholt at utm.edu>,<mgibson at utm.edu>,<jhende33 at utm.edu>,<bgiles at utm.edu>,<lwarren at utm.edu>,<mtraynom at utm.edu>,<blee37 at utm.edu>,<jjohn324 at utm.edu>,<rjones at utm.edu>,<sdyer at utm.edu>,<sperry19 at utm.edu>,<djorda19 at utm.edu>,<cposadny at utm.edu>,<tharri70 at utm.edu>,<gfelts at utm.edu>,<cnichols at utm.edu>,<jlavalle at utm.edu>,<jschomme at utm.edu>,<volds at utm.edu>, delay=00:00:34, xdelay=00:00:06, mailer=relay, pri=15091061, relay=xmail.utm.edu. [10.51.0.154], dsn=2.0.0, stat=Sent (<320E686FEA4720449A309FC08FC6F49D01023D575A at EXCH2010MBOX2.utm.edu> [InternalId=7717507] Queued mail for delivery)

and this one with more utm recips.

> Mar  3 14:41:17 mailman sendmail[24288]: v23JYu9w022801: to=<chaamerw2000 at yahoo.com>,<jesse.kowalewski at sodexo.com>,<kevin_mclemore at hotmail.com>,<msudzum at worldtrav.com>,<njanemiller25 at gmail.com>,<sully12980 at aol.com>,<vlhiggs at gmail.com>, delay=01:06:20, xdelay=00:00:02, mailer=relay, pri=481061, relay=xmail.utm.edu. [10.51.0.154], dsn=2.0.0, stat=Sent (<320E686FEA4720449A309FC08FC6F49D01023D575A at EXCH2010MBOX2.utm.edu> [InternalId=7719913] Queued mail for delivery)

this chunk with 7 recips in various domains is delayed over an hour. I
don't know much about sendmail, but this could be because there was some
issue contacting the MX for one of the seven and the whole message was
deferred.

> Mar  3 14:42:43 mailman sendmail[24288]: v23JYu9r022801: to=<dsimmons at utm.edu>,<emoser at utm.edu>,<epritch2 at utm.edu>,<ereed21 at utm.edu>,<esimmons at utm.edu>,<espivey at utm.edu>,<ewhite38 at utm.edu>,<ffackler at utm.edu>,<gbrown at utm.edu>,<geckert at utm.edu>,<gibson at utm.edu>,<hknox at utm.edu>,<jash5 at utm.edu>,<jclark at utm.edu>,<jdonal11 at utm.edu>,<jesbensh at utm.edu>,<jforsyt5 at utm.edu>,<jgreenwood at utm.edu>,<jhahn at utm.edu>,<jjone239 at utm.edu>,<jlamb5 at utm.edu>,<jlongac1 at utm.edu>,<jmack at utm.edu>,<jmathern at utm.edu>,<jonrmitc at ut.utm.edu>,<jstreet7 at utm.edu>,<jyocum at utm.edu>,<kcurrie at utm.edu>,<kelliot4 at utm.edu>,<kericson at utm.edu>,<kevans31 at utm.edu>,<khealy at utm.edu>,<kprzybeck at utm.edu>,<krimfuhs at ut.utm.edu>,<kwill126 at utm.edu>,<ldavis at utm.edu>,<learls at utm.edu>, [more], delay=01:07:47, xdelay=00:00:05, mailer=relay, pri=4771061, relay=xmail.utm.edu. [10.51.0.154], dsn=2.0.0, stat=Sent (<320E686FEA4720449A309FC08FC6F49D01023D575A at EXCH2010MBOX2.utm.edu> [InternalId=7719987] Queued mail for delivery)

And similarly for this one with utm recips. Maybe one recip had a
transient mailbox issue trhat caused the entire message to be deferred.

There are some older articles in the faq at <https://wiki.list.org/>.
Search titles for performance.

I recommend:
Consider upgrading Mailman. 2.1.7 is very old. Upgrades won't address
this issue specifically, but many new features and bug fixes have
occurred since 2.1.7 was released over 11 years ago.

Set

VERP_DELIVERY_INTERVAL = 1

in mm_cfg.py. This will improve bounce recognition, but mainly it has
the same effect as setting SMTP_MAX_RCPTS = 1 so each recipient is sent
in a single SMTP transaction so sendmail delivery to a large chunk of
recips is not impacted by one delay.

If you don't want to go that far, or if this causes Mailman -> sendmail
delivery to take too long. at least try something like

SMTP_MAX_RCPTS = 10

The bottom line is this is all in sendmail and this list is not the best
resource for sendmail issues. Most of us are more versed in Postfix or Exim.

-- 
Mark Sapiro <mark at msapiro.net>        The highway is for gamblers,
San Francisco Bay Area, California    better use your sense - B. Dylan