[Mailman-Users] Message received by mailman and archives, but won't deliver

You see just one outgoing message in your mail log? What, precisely is
actually showing up in your outgoing sendmail logs?

Are you sure that your outgoing mail isn't being routed through
another mail server somewhere, which might be throwing it away or
causing it to be mis-recognized as spam?

There are a number of lists, one has about 5K people on it. If I send
a message to one that has only 5 people on it, I see something like:

Aug 30 18:25:00 innopacusers sm-mta[32967]: l7UIOfmI032960:
to=<name.removed at colorado.edu>, delay�:00:13, xdelay�:00:03,
mailer=esmtp, pri5445, relay=mx15.colorado.edu. [128.138.128.115],
dsn=2.0.0, stat=Sent (Ok: queued as D091E692112)
Aug 30 18:25:02 innopacusers sm-mta[32967]: l7UIOfmI032960:
to=<name.removed2 at mail.lib.msu.edu>, delay�:00:15, xdelay�:00:02,
mailer=esmtp, pri5445, relay=mail1.mail.lib.msu.edu. [35.8.223.61],
dsn=2.0.0, stat=Sent (
<47eed6660708301124u6bda99bbo92e00b4180ccad48 at mail.gmail.com> Queued
mail for delivery)
Aug 30 18:25:02 innopacusers sm-mta[32967]: STARTTLS=client,
relay=relay.oregonstate.edu., version=TLSv1/SSLv3, verifyúIL,
cipher=DHE-RSA-AES256-SHA, bits%6/256
Aug 30 18:25:02 innopacusers sm-mta[32967]: l7UIOfmI032960:
to=<name.removed3 at oregonstate.edu>, delay�:00:15, xdelay�:00:00,
mailer=esmtp, pri5445, relay=relay.oregonstate.edu.
[128.193.15.33], dsn=2.0.0, stat=Sent (Ok: queued as 90B39410794)
Aug 30 18:25:03 innopacusers sm-mta[32960]: l7UIOfmJ032960:
from=<webguru-bounces at innopacusers.org>, size445, class=-30,
nrcpts=1, msgid=<47eed6660708301124u6bda99bbo92e00b4180ccad48 at mail.gmail.com>,
proto=ESMTP, daemon=MTA-v4, relay=localhost [127.0.0.1]
Aug 30 18:25:04 innopacusers sm-mta[32976]: l7UIOfmJ032960:
to=<name.removed4 at gmail.com>, delay�:00:01, xdelay�:00:01,
mailer=esmtp, pri•445, relay=gmail-smtp-in.l.google.com.
[64.233.167.114], dsn=2.0.0, stat=Sent (OK 1188498304 u62si752714pyb)

"webguru" is the name of this test list. The strange thing is that
we've been running for years with no problems. Yesterday, I was
getting errors with invalid character sets that seemed to be gumming
things up. I messed around with it to no avail, so I upgraded to the
latest version. I cleared out everything in process just to make sure
that nothing that hadn't been processed wasn't blocking everything
else.

When the problem was first reported, the logs looked OK to me, so I
told them there was a a delivery problem at their end. Then calls and
emails started pouring in, and I realized that I hadn't received any
messages even though I use gmail with no filters and I usually get
dozens of messages from one of our lists each day. I checked to make
sure we're not blacklisted and that seemed OK too. The weird thing is
that I can send email from the command line no problem, and
administrative messages (subscribe, unsubscribe, etc) seem to get
through just fine.

kyle

Further clarification on this problem.

It turns out that not everything is showing in the post log. After a
certain amount of time, the messages that are not getting through
appear in qfiles/out/*.pck

I turned debug=1 in SMTPDirect.py but haven't uncovered anything.

This is nuts, I'm willing to entertain even crazy speculation at this point.

kyle

Check your Mailman "error" log file. I'm guessing that there is one or
more malformed messages in the Mailman queue that is hosing things up.

Problem is, the real problem is usually before the errors start
showing up in the logs. Start with what shows up in the logs and work
backwards.

I don't recall the exact FAQ number or URL, but search the FAQ wizard
for "troubleshooting".

How much time? They should appear almost immediately in qfiles/out/
unless they've been spending time in qfiles/retry/.

What is in Mailman's smtp-failure log? What does Mailman's smtp log
look like? does it show the symptom of a backlogged qfiles/out/ queue?
Namely, many successive entries being timestamped at intervals equal
to the processing time of the entry.


What 'debug=1'? If you mean you just set

debug=1

in SMTPDirect.py, this will do nothing. The only additional debugging
switch that applies to SMTPDirect.py is described at
<http://www.python.org/cgi-bin/faqw-mm.py?req=show&file=faq04.073.htp>,
and be sure to note that this won't work and will only cause
additional problems if your Python version is less than 2.4.


If the messages that aren't being delivered are remaining in Mailman's
qfiles/retry and qfiles/out queues, report what you find in Mailman's
smtp-failure (and as Brad suggested, error) logs and what you find
from examination of Mailman's smtp log.

If the messages are accepted by sendmail and then fail to be delivered,
that part at least is a sendmail issue.

Also see
<http://www.python.org/cgi-bin/faqw-mm.py?req=show&file=faq04.078.htp>.

In fact, in a well running Mailman installation qfiles/out/ is normally
empty except for the occasional entry you see for a second or so while
it's waiting to be picked up. (In 2.1.9, it will remain longer as a
*.bak file while it is being processed by
OutgoingRunner/SMTPDirect.py.)

If *.pck files are hanging around in qfiles/out/, either there is a
backlog (probably due to a configuration issue if it persists), or
there is some problem with OutgoingRunner.

Thanks for the advice -- I believe your suggestion that the issue is
related to OutgoingRunner is most likely correct, but I'm not out of
the woods yet.
This was probably the wrong thing to do, but out of frustration, I
blasted out my installation, put in a clean install, and recovered the
list itself from backup using instructions at
http://www.python.org/cgi-bin/faqw-mm.py?req=show&fileúq03.004.htp

This has had the effect of clearing logs and removing ineffective and
possibly harmful changes I made. I'm still having problems delivering
mail.

I've sent a few messages to the lists over the past couple hours. Here
is what I'm seeing:

1) The files are appearing almost immediately in qfiles/out/ where
they seem to stay. Nothing is in retry or the other qfiles
directories.

2) Even a couple hours later, nothing shows up in post, smtp, or
smtp-failure. However, someone who belonged to one of the lists sent
one through. I found the entry

Aug 31 02:18:53 2007 (40546)
<01F67337-E566-4AA4-B684-01C9E2F3F9FB at mac.com> smtp to innopac for
2014 recips, completed in 11231.212 seconds

The amount of time for the transaction seems insane. Load is
practically nonexistent.

3) When I send a message to the list, maillog makes it look like
everything happened. For example, if I send it to the list with 4
people in it

Aug 31 02:47:54 innopacusers sm-mta[52010]: l7V2lmww052010:
from=<namedeleted at gmail.com>, sizeX88, class=0, nrcpts=1,
msgid=<47eed6660708301947g661c9557ocaeb52af48e48260 at mail.gmail.com>,
proto=ESMTP, daemon
=MTA-v4, relay=wa-out-1112.google.com [209.85.146.180]
Aug 31 02:48:01 innopacusers sm-mta[52012]: l7V2lmww052010:
to=namedeleted2 at bus.umich.edu, delay�:00:07, xdelay�:00:02,
mailer=esmtp, pri6118, relay=bus-ex02.bus.umich.edu.
[141.211.239.195], dsn=2.0.0, stat=Sent (
<47eed6660708301947g661c9557ocaeb52af48e48260 at mail.gmail.com> Queued
mail for delivery)
Aug 31 02:48:02 innopacusers sm-mta[52012]: l7V2lmww052010:
to=namedeleted3 at Colorado.edu , delay�:00:08
, xdelay�:00:01, mailer=esmtp, pri6118, relay=mx10.colorado.edu.
[128.138.128.110], dsn=2.0.0, statSent (Ok: queued as 31AB7C4A4B0)
Aug 31 02:48:03 innopacusers sm-mta[52012]: l7V2lmww052010:
to=namedeleted4 at gmail.com, delay�:00:09, x
delay�:00:01, mailer=esmtp, pri6118,
relay=gmail-smtp-in.l.google.com. [64.233.167.27], dsn=2.0.0,
stat=Sent (OK 1188528483 a70si1963649pye)
Aug 31 02:48:04 innopacusers sm-mta[52012]: l7V2lmww052010:
to=fleckn at mail.lib.msu.edu, delay�:00:10, x
delay�:00:01, mailer=esmtp, pri6118,
relay=mail1.mail.lib.msu.edu. [35.8.223.61], dsn=2.0.0, stat=Sent (
<47eed6660708301947g661c9557ocaeb52af48e48260 at mail.gmail.com> Queued
mail for delivery)
Aug 31 02:48:22 innopacusers sm-mta[52012]:
l7V2lmww052010:to=namedeleted5 at oregonstate.edu, delay�:00:28,
xdelay�:00:18, mailer=esmtp, pri6118,
relay=relay.oregonstate.edu. [128.193.15.33], dsn=2.0.0, stat=Sent
(Ok: queued as 5D01C410AE6)

The handoff to mailman shows up and it appears in /qfiles/out
Aug 31 02:40:58 innopacusers sm-mta[51781]: l7V2ep7j051777:
to="|/usr/local/bin/stripmime.pl|/usr/local/mailman/mail/mailman post
webguru" , ctladdr=(26/0), delay�:00:01,
xdelay�:
00:01, mailer=prog, pri1857, dsn=2.0.0, stat=Sent
This sounds like my problem. OutgoingRunner is running

mailman 40546 0.0 1.7 19204 17236 ?? S 11:11PM 0:01.49
/usr/local/bin/python2.4 /usr/local/mailman/bin/qrunner
--runner=OutgoingRunner:0:1 -s

I can easily buy that there's a config issue, but the strange thing is
that we were functional for years and all of a sudden quit working
(having said that, we have a hosted server, so it's conceivable
something was done to our machine -- it's happened before).

I don't understand how OutgoingRunner works -- any suggestions for
directions for me to explore in seeing if my sendmail or mailman
config is screwing things up? Thanks,

kyle

Your SMTP delivery to sendmail is incredibly slow. This is your entire
problem. Your out queue is hoplessly backlogged due to the time it is
taking to process SMTP. You will never catch up.

You need to make changes in sendmail. See
<http://www.python.org/cgi-bin/faqw-mm.py?query=performance&querytype=simple&casefold=yes&req=search>,
particularly 4.11 and 6.3, and make sure you are not doing DNS
verifies on mail from Mailman.


This doesn't look like a message from Mailman. A message from a mailman
list will normally be from listname-bounces at example.com
(webguru-bounces at innopacusers.org in this case). And, if this came
from Mailman, there would be entries in Mailman's post and smtp logs.


Mailman can do content filtering with I think more control than
stripmime.pl


What Mailman version is this?


OutgoingRunner picks up the oldest qfiles/out/*.pck file, gets the
message and metadata from it and passes them to SMTPDirect.py for
processing. When SMTPDirect.py returns, it picks up the next entry and
repeats until there are no entries left. Then it sleeps for
QRUNNER_SLEEP_TIME (default 1 second) and looks for any new entries.

That's the basic flow assuming no errors or exceptions.

See the above FAQ articles.

Thanks for the tip -- this sounds like it's most likely what I need to
fix. I'll read up and see if I can't nail this.
Hmmm... It just so happens that this listname coincides with a former
alias that forwarded messages to the same people. The aliases file
looks OK, but I wonder if sendmail is getting the info from someplace
else. I need to test this process with a list that doesn't have this
issue.
Thanks for the info -- this helps me understand what's going on better.

kyle

Just in case someone else experiences insanely slow delivery, DNS
verifies on mail from mailman turned out to be the problem in my case.
I turned that off and made sure I could relay from localhost, and
everything works great.

kyle