[PLUG] Mail log reporting: cron issue?

[Rich Shepard]

On Fri, 22 May 2009, Joe Pruett wrote:

> i forgot that the main script is running sendmail directly, pflogsum
> doesn't do that.  so you should always get email from running that script,
> even if pflogsum produced no output.  you should also see an entry in
> maillog for that sendmail invocation.  tweak your script and add -v to
> SENDMAIL_OPTS so you can see what it has to say about things.

Joe,

   I think this points to procmail as the issue:

[root at salmo /etc/cron.daily]# ./1pflogsumm 
+ '[' -z '' ']'
+ '[' -f /var/log/maillog ']'
+ LOGFILE=/var/log/maillog
+ EXECUTABLE=/usr/local/bin/pflogsumm
+ TMPDIR=/etc/postfix
+ TMPEXE=pfls.tmp.27979
+ OPTIONS='--verp_mung=2 --problems_first --iso_date_time  -q -u 10 -h 10'
++ hostname
++ LC_TIME=C
++ date '+%A, %d %B %Y'
+ SUBJECT='salmo Daily Mail Report for Friday, 22 May 2009'
+ '[' -z '' ']'
+ REPORT_TO=rshepard at appl-ecosys.com
+ SENDMAIL=/usr/sbin/sendmail
+ SENDMAIL_OPTS='-oi -t -v'
+ POSTFIX=/usr/sbin/postfix
+ trap 'test -r /etc/postfix/pfls.tmp.27979 && rm -f
/etc/postfix/pfls.tmp.27979' 0 1 2 3 15
+ '[' '!' -r /var/log/maillog ']'
+ '[' '!' -r /var/log/maillog ']'
++ id -u
+ '[' 0 = 0 ']'
+ '[' -r /usr/local/bin/pflogsumm ']'
+ '[' -d /etc/postfix ']'
+ perl -e 'use Date::Calc;'
+ '[' -x /usr/local/bin/pflogsumm ']'
+ '[' -x /usr/sbin/sendmail ']'
+ cat
+ /usr/sbin/sendmail -oi -t -v
+ LC_TIME=C
+ /usr/local/bin/pflogsumm --verp_mung=2 --problems_first --iso_date_time -q
-u 10 -h 10 /var/log/maillog
+ echo 'Report ended with status: 0'
rshepard at appl-ecosys.com... Connecting to [127.0.0.1] via relay...
220 salmo.appl-ecosys.com ESMTP Postfix
>>> EHLO salmo.appl-ecosys.com
250-salmo.appl-ecosys.com
250-PIPELINING
250-SIZE 32768000
250-VRFY
250-ETRN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250 DSN
>>> MAIL From:<root at salmo.appl-ecosys.com> SIZE=21150
250 2.1.0 Ok
>>> RCPT To:<rshepard at appl-ecosys.com>
>>> DATA
250 2.1.5 Ok
354 End data with <CR><LF>.<CR><LF>
>>> .
250 2.0.0 Ok: queued as 7FFF4FEA
rshepard at appl-ecosys.com... Sent (Ok: queued as 7FFF4FEA)
Closing connection to [127.0.0.1]
>>> QUIT
221 2.0.0 Bye
+ test -r /etc/postfix/pfls.tmp.27979

and:

[root at salmo ~]# grep 7FFF4FEA /var/log/maillog
May 22 10:43:05 salmo postfix/smtpd[27958]: 7FFF4FEA:
client=localhost.localdomain[127.0.0.1]
May 22 10:43:05 salmo postfix/cleanup[27966]: 7FFF4FEA:
message-id=<200905221743.n4MHh52g027985 at salmo.appl-ecosys.com>
May 22 10:43:05 salmo postfix/qmgr[25843]: 7FFF4FEA:
from=<root at salmo.appl-ecosys.com>, size=22135, nrcpt=1 (queue active)
May 22 10:43:05 salmo sendmail[27985]: n4MHh52g027985:
to=rshepard at appl-ecosys.com, ctladdr=root (0/0), delay=00:00:00,
xdelay=00:00:00, mailer=relay, pri=51150, relay=[127.0.0.1] [127.0.0.1],
dsn=2.0.0, stat=Sent (Ok: queued as 7FFF4FEA)
May 22 10:43:14 salmo postfix/local[27968]: 7FFF4FEA:
to=<rshepard at appl-ecosys.com>, relay=local, delay=8.5, delays=0.23/0/0/8.3,
dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail)
May 22 10:43:14 salmo postfix/qmgr[25843]: 7FFF4FEA: removed

and:

[rshepard at salmo ~]$ grep 10:43:14 procmail/log
[rshepard at salmo ~]$

   ~/procmail/log has no entries between 10:11 and 10:21 this morning.

   So, this is the procmail issue with which Kurt and I have been wrestling.
Certain senders seem to cause procmail to fail delivery. It seems definite
now that that's where the problem lies. _Why_ 1pflogsumm reports, mail from
gte.net, united.com, and a company domain are not delivered when almost
anything else is delivered is particulary bothersome. I've no idea of mail
that hasn't been delivered when I was not expecting it.

Rich