Empty pflogsumm Reports
Rich Shepard
shows up with no values for the fields. See partial example here:
From ro...@appl-ecosys.com Wed Jun 27 04:40:02 2007
Date: Wed, 27 Jun 2007 04:40:01 -0700 (PDT)
From: ro...@appl-ecosys.com
To: rshe...@appl-ecosys.com
Subject: salmo Daily Mail Report for Wednesday, 27 June 2007
Report based on information in /var/log/maillog
Grand Totals
------------
messages
0 received
0 delivered
0 forwarded
0 deferred
0 bounced
0 rejected (0%)
0 reject warnings
0 held
0 discarded (0%)
My search on Google found a single example of similar results, but that
was caused by the maillog rotating before pflogsumm ran. That's not the case
here: /etc/cron.daily has not changed, and 1pflogsumm runs before logrotate.
I have not changed anything by design that could have affected this.
Also, I cannot initiate the script (either from /etc/cron.daily or
/usr/local/bin) and have it run to completion and mail me the report.
Where do I start looking to learn what happened so I can fix it?
TIA,
Rich
--
Richard B. Shepard, Ph.D. | The Environmental Permitting
Applied Ecosystem Services, Inc. | Accelerator(TM)
<http://www.appl-ecosys.com> Voice: 503-667-4517 Fax: 503-667-8863
MrC
> Starting a few days ago, the daily log analysis produced by pflogsumm
> shows up with no values for the fields. See partial example here:
>
>
>
> Grand Totals
> ------------
> messages
>
> 0 received
> 0 delivered
> 0 forwarded
> 0 deferred
> 0 bounced
> 0 rejected (0%)
> 0 reject warnings
> 0 held
> 0 discarded (0%)
>
> My search on Google found a single example of similar results, but that
> was caused by the maillog rotating before pflogsumm ran. That's not
> the case
> here: /etc/cron.daily has not changed, and 1pflogsumm runs before
> logrotate.
> I have not changed anything by design that could have affected this.
>
> Also, I cannot initiate the script (either from /etc/cron.daily or
> /usr/local/bin) and have it run to completion and mail me the report.
>
> Where do I start looking to learn what happened so I can fix it?
>
> TIA,
>
> Rich
>
pflogsumm /dev/null
produces the same results. Start by showing the command that is
actually running (via cron) and any associated log entries.
MrC
Rich Shepard
> Start by showing the command that is actually running (via cron) and any
> associated log entries.
Here's what's been in root's crontab for years:
# Run daily cron jobs at 4:40 every day:
40 4 * * * /usr/bin/run-parts /etc/cron.daily 1> /dev/null
In /etc/cron.daily is 1pdflogsumm (last modified 2006-12-27 07:01). There
are no entries in /var/log/cron* and no mention of pflogsumm in
/var/log/messages.
MrC
> On Wed, 27 Jun 2007, MrC wrote:
>
>> Start by showing the command that is actually running (via cron) and any
>> associated log entries.
>
> Here's what's been in root's crontab for years:
>
> # Run daily cron jobs at 4:40 every day:
> 40 4 * * * /usr/bin/run-parts /etc/cron.daily 1> /dev/null
>
> In /etc/cron.daily is 1pdflogsumm (last modified 2006-12-27 07:01).
> There
I won't hazard a guess at what is inside "1pdflogsumm". It might be
best to show that script.
Rich Shepard
> I won't hazard a guess at what is inside "1pdflogsumm". It might be best
> to show that script.
Here it is:
----------------------------------------------------------------------------
#!/bin/sh
#
# /etc/cron.daily/1pflogsumm
#
# This file is run on a daily basis to analyse your mail logs.
#
# The file is named "1pflogsumm" to ensure that it is run before logrotate
# when the /var/log/maillog files are rotated.
#
# The file is also flagged by rpm as a configuration file, so if you modify
# it, further upgrades to pflogusmm will not be overwriten.
#
# More information at http://jimsun.linxnet.com/postfix_contrib.html
#
# uncomment the next line to completely disable the daily cronjob
# exit 0
# Default location of the log file, if not learnt from LOGFILE
[ -z "${LOGFILE}" ] && [ -f /var/log/maillog ] && LOGFILE=/var/log/maillog
[ -z "${LOGFILE}" ] && [ -f /var/log/mail.log ] && LOGFILE=/var/log/mail.log
EXECUTABLE=/usr/local/bin/pflogsumm
TMPDIR=/etc/postfix # default directory for temporary executable, better than /tmp
TMPEXE=pfls.tmp.$$ # name of executable if Date::Calc module not available
#OPTIONS="--verp_mung=2 --problems_first --iso_date_time -q -u 10 -h 10 -d yesterday"
OPTIONS="--verp_mung=2 --problems_first --iso_date_time -q -u 10 -h 10"
SUBJECT="`hostname` Daily Mail Report for `LC_TIME=C date +\"%A, %d %B %Y\"`"
# Send report to $REPORT_TO if defined, or postmaster@"hostname" otherwise
[ -z "${REPORT_TO}" ] && REPORT_TO="rshe...@appl-ecosys.com"
SENDMAIL=/usr/sbin/sendmail
SENDMAIL_OPTS="-oi -t"
POSTFIX=/usr/sbin/postfix
# Clean up when done or when aborting.
trap "test -r ${TMPDIR}/${TMPEXE} && rm -f ${TMPDIR}/${TMPEXE}" 0 1 2 3 15
# uncomment the next line to disable retrieval of mail statistics
# exit 0
# Check mail log file exists or exit
#[ ! -r "${LOGFILE}" ] && [ -r /var/log/mail/info ] && LOGFILE=/var/log/mail/info
[ ! -r "${LOGFILE}" ] && [ -r /var/log/maillog ] && LOGFILE=/var/log/maillog
[ ! -r "${LOGFILE}" ] && { echo "$0: Can not find a readable mail log file - exiting"; exit 1; }
# if we are not root, use a different TMPDIR
[ `id -u` = 0 ] || TMPDIR=/tmp
# Check pflogsumm.pl exists and exclude the use of Perl's Date::Calc module if it is not available
[ -r ${EXECUTABLE} ] || { echo "$0: ${EXECUTABLE} not found - exiting"; exit 1; }
[ -d ${TMPDIR} ] || { echo "$0: ${TMPDIR} is not a directory - exiting"; exit 1; }
perl -e 'use Date::Calc;' 2>/dev/null || {
sed -e '/# ---Begin:/,/# ---End:/d' < ${EXECUTABLE} > ${TMPDIR}/${TMPEXE}
chmod u=rx,go= ${TMPDIR}/${TMPEXE} || echo "$0: warning - unable to set permissions on ${TMPDIR}/${TMPEXE}"
EXECUTABLE=${TMPDIR}/${TMPEXE}
}
# Ensure the ${EXECUTABLE} and sendmail binaries exist before proceeding
[ -x ${EXECUTABLE} ] || { echo "$0: ${EXECUTABLE} not executable - exiting"; exit 1; }
[ -x ${SENDMAIL} ] || { echo "$0: ${SENDMAIL} not found or not executable - exiting"; exit 1; }
(
cat <<EOF
To: ${REPORT_TO}
Subject: ${SUBJECT}
Report based on information in ${LOGFILE}
EOF
LC_TIME=C ${EXECUTABLE} ${OPTIONS} ${LOGFILE} 2>/dev/null
echo "Report ended with status: $?" ) | ${SENDMAIL} ${SENDMAIL_OPTS}
------------------------------------------------------------------------------------------------
Noel Jones
>On Wed, 27 Jun 2007, MrC wrote:
>
>>I won't hazard a guess at what is inside "1pdflogsumm". It might be best
>>to show that script.
>
> Here it is:
>----------------------------------------------------------------------------
>#!/bin/sh
>#
># /etc/cron.daily/1pflogsumm
So what happens if you run this script from a command promt?
Do your mail logs really exist in /var/log/maillog or /var/log/mail.log??
--
Noel Jones
Rich Shepard
> So what happens if you run this script from a command promt?
Noel,
The same thing as when it runs from cron.daily: 0 counts for everything.
> Do your mail logs really exist in /var/log/maillog or /var/log/mail.log??
Yes. They're still there after all these years and I can view them
manually. As I wrote originally, this was working every day until last
Saturday morning. I've not upgraded the distribution, postfix, or anything
else for a long time (except for Slackware security patches, and those were
long before the script stopped working.)
Noel Jones
>>Do your mail logs really exist in /var/log/maillog or /var/log/mail.log??
>
> Yes. They're still there after all these years and I can view them
>manually. As I wrote originally, this was working every day until last
So what happens if you run pflogsumm manually?
pflogsumm /path/to/logfile
--
Noel Jones
Rich Shepard
> So what happens if you run pflogsumm manually?
> pflogsumm /path/to/logfile
Noel,
Same thing:
[root@salmo ~]# pflogsumm /var/log/maillog.1
Grand Totals
------------
messages
0 received
0 delivered
0 forwarded
0 deferred
0 bounced
0 rejected (0%)
0 reject warnings
0 held
0 discarded (0%)
0 bytes received
0 bytes delivered
0 senders
0 sending hosts/domains
0 recipients
0 recipient hosts/domains
I checked yesterday, and the pflogsumm script has not changed since the
version I've been running. This situation is strange, puzzling, and
frustrating because it came on suddenly and so far resists revealing the
reason.
The mail logs are not empty, either.
Thanks,
pheonix1t
then compress the older logs and rename them to log.1 or something like
this.
Oskar
Duane Hill
Out of sheer curiosity, I just installed the script here myself. It runs
fine using:
pflogsumm v1.1.1
Postfix v2.4.3
FreeBSD v6.2
Sample output:
Grand Totals
------------
messages
255 received
260 delivered
0 forwarded
0 deferred
0 bounced
1 rejected (0%)
0 reject warnings
0 held
0 discarded (0%)
4853k bytes received
4866k bytes delivered
114 senders
70 sending hosts/domains
9 recipients
6 recipient hosts/domains
Rich Shepard
> maybe this is a compressed mail log?
Oskar,
No, they're not. They're plain ASCII text.
And, this all worked flawlessly until last Saturday.
Noel Jones
>On Thu, 28 Jun 2007, Noel Jones wrote:
>
>>So what happens if you run pflogsumm manually?
>>pflogsumm /path/to/logfile
>
>Noel,
>
> Same thing:
what if you pipe the log to pflogsumm??
# cat logfile | pflogsumm
If that works, then you know it's some misguided security
feature. If it doesn't work, sounds like pflogsumm has been changed.
--
Noel Jones
Rich Shepard
>> Have you tried reinstalling the script and dependencies File::MMagic and
>> Date::Calc?
Gary,
I thought that perhaps Date::Calc might have gone AWOL, but it's not.
Running 'perldoc perllocal' shows it's still here:
Tue Jan 30 08:48:10 2007: "Module" Date::Calc
o "installed into: /usr/lib/perl5/site_perl/5.8.8"
o "LINKTYPE: dynamic"
o "VERSION: 5.4"
o "EXE_FILES: "
> What does: 'which perl' say?
[rshepard@salmo ~]$ which perl
/usr/bin/perl
Rich Shepard
> what if you pipe the log to pflogsumm??
> # cat logfile | pflogsumm
No difference.
> If that works, then you know it's some misguided security feature. If it
> doesn't work, sounds like pflogsumm has been changed.
I'll grab the source for 1.1.1 and try that. Of course, the file's mtime
is still several years old:
[root@salmo ~]# ll /usr/local/bin/pflogsumm
-rwxr-xrwx 1 root root 53740 2004-09-13 15:01 /usr/local/bin/pflogsumm*
Daniel L. Miller
> what if you pipe the log to pflogsumm??
>
> # cat logfile | pflogsumm
>
> If that works, then you know it's some misguided security feature. If
> it doesn't work, sounds like pflogsumm has been changed.
>
ago - was surprised when pflogsumm didn't immediately work. The issue
turned out to be the owner and/or privileges on the mail log file.
--
Daniel
Daniel L. Miller
> On Thu, 28 Jun 2007, Noel Jones wrote:
>
>> what if you pipe the log to pflogsumm??
>> # cat logfile | pflogsumm
>
> No difference.
>
>> If that works, then you know it's some misguided security feature.
>> If it doesn't work, sounds like pflogsumm has been changed.
>
> I'll grab the source for 1.1.1 and try that. Of course, the file's
> mtime
> is still several years old:
>
> [root@salmo ~]# ll /usr/local/bin/pflogsumm -rwxr-xrwx 1 root root
> 53740 2004-09-13 15:01 /usr/local/bin/pflogsumm*
>
> Rich
>
On my machine that comes back with -
-rw-r----- 1 root adm 105840 2007-06-28 11:18 /var/log/mail.info
What user is executing pflogsumm in your script? I had a problem
accessing it via my webserver - until I added "www-data" to my "adm" group.
--
Daniel
Rich Shepard
> Show us "ls -al /var/log/maillog.1".
>
> On my machine that comes back with -
> -rw-r----- 1 root adm 105840 2007-06-28 11:18 /var/log/mail.info
[root@salmo ~]# ll /var/log/maillog*
-rw-r--r-- 1 root root 189900 2007-06-28 11:23 /var/log/maillog
-rw-r--r-- 1 root root 460035 2007-06-28 04:40 /var/log/maillog.1
-rw-r--r-- 1 root root 331298 2007-06-27 04:40 /var/log/maillog.2
-rw-r--r-- 1 root root 393395 2007-06-26 04:40 /var/log/maillog.3
-rw-r--r-- 1 root root 149052 2007-06-25 04:40 /var/log/maillog.4
> What user is executing pflogsumm in your script?
root
Allow me to remind everyone that this has worked for about three years. It
stopped last Saturday. The mail file formats have not changed. The pflogsumm script
has not been altered. The cron.daily scripts run in the same sequence as
they did last Friday morning, but now the mail report comes up empty.
Yes, something has changed, and I'm out of ideas what that might be.
Gary Mort
> Allow me to remind everyone that this has worked for about three
> years. It
> stopped last Saturday. The mail file formats have not changed. The
> pflogsumm script
> has not been altered. The cron.daily scripts run in the same sequence as
> they did last Friday morning, but now the mail report comes up empty.
Stop postfix.
Move the existing maillog to maillog.bad
Restart postfix(perhaps restart the server)
Send some test mail
Run pflogsumm and see if it works
If it does, something in your old maillog is corrupt and causing problems
Rich Shepard
> Stop postfix.
> Move the existing maillog to maillog.bad
> Restart postfix(perhaps restart the server)
Gary,
I stopped/re-started postfix, but that did not fix the problem. The mail
logs have rotated each day (Saturday through Thursday), and not all are
corrupted in the same way.
Good thought,
Robert Felber
> On Thu, 28 Jun 2007, Gary Mort wrote:
>
> >Stop postfix.
> >Move the existing maillog to maillog.bad
> >Restart postfix(perhaps restart the server)
>
> Gary,
>
> I stopped/re-started postfix, but that did not fix the problem. The mail
> logs have rotated each day (Saturday through Thursday), and not all are
> corrupted in the same way.
>
> Good thought,
Can you post a log-line?
--
Robert Felber (PGP: 896CF30B)
Munich, Germany
Rich Shepard
> Can you post a log-line?
Sure, Robert. Here's the most recent transaction:
Jun 28 04:43:21 salmo postfix/qmgr[10701]: 15A969A6:
from=<pstricks...@tug.org>, size=14154, nrcpt=1 (queue active)
Jun 28 04:43:21 salmo spamd[2826]: spamd: connection from
localhost.localdomain [127.0.0.1] at port 56804
Jun 28 04:43:21 salmo spamd[2826]: spamd: setuid to spamfilter succeeded
Jun 28 04:43:21 salmo spamd[2826]: spamd: processing message
<OF1DE78230.3CDD3215-ON852573...@epamail.epa.gov> for spamfilter:1006
Rich Shepard
> Sure, Robert. Here's the most recent transaction:
Mea culpa! That was at the start of today's maillog, not the latest.
Noel Jones
>On Thu, 28 Jun 2007, Rich Shepard wrote:
>
>> Sure, Robert. Here's the most recent transaction:
>
> Mea culpa! That was at the start of today's maillog, not the latest.
show some lines that will be counted... like maybe a
"smtpd...reject:" entry, or a "smtp...status=sent" entry.
Here's a couple lines you can pipe through your pflogsumm (remove any
line wrapping)
Jun 27 00:01:01 mgate2 postfix/smtpd[33021]: NOQUEUE: reject: RCPT
from unknown[61.108.188.61]: 550 5.7.1 Client host rejected: cannot
find your reverse hostname, [61.108.188.61];
from=<gte...@spraytower.com> to=<ga1...@example.com> proto=ESMTP
helo=<[61.108.188.61]>
Jun 28 17:04:05 mgate2 postfix/smtp[65924]: E6A01797858:
to=<us...@example.org>, relay=10.10.54.14[10.10.54.14]:25, delay=0.34,
delays=0.07/0.03/0.03/0.2, dsn=2.0.0, status=sent (250 Message queued)
which should give a report something like:
Grand Totals
------------
messages
0 received
1 delivered
0 forwarded
0 deferred
0 bounced
1 rejected (50%)
0 reject warnings
0 held
0 discarded (0%)
0 bytes received
0 bytes delivered
0 senders
0 sending hosts/domains
1 recipients
1 recipient hosts/domains
If that doesn't work, your pflogsumm or its dependancies are broken.
--
Noel Jones
Rich Shepard
> show some lines that will be counted... like maybe a "smtpd...reject:" entry,
> or a "smtp...status=sent" entry.
Good thought, Noel.
> Here's a couple lines you can pipe through your pflogsumm (remove any line
> wrapping) ...
> which should give a report something like:
Grand Totals
------------
messages
0 received
0 delivered
0 forwarded
0 deferred
0 bounced
1 rejected (100%)
0 reject warnings
0 held
0 discarded (0%)
0 bytes received
0 bytes delivered
0 senders
0 sending hosts/domains
0 recipients
0 recipient hosts/domains
message reject detail
---------------------
RCPT
cannot find your reverse hostname (total: 1)
1 61.108.188.61
The one is not shown as received.
I'll look more closely. Perhaps spamd broke and the records are not being
written to the mail logs.
Thanks,
Robert Felber
> On Thu, 28 Jun 2007, Robert Felber wrote:
>
> >Can you post a log-line?
>
> Sure, Robert. Here's the most recent transaction:
>
> Jun 28 04:43:21 salmo postfix/qmgr[10701]: 15A969A6:
> from=<pstricks...@tug.org>, size=14154, nrcpt=1 (queue active)
> Jun 28 04:43:21 salmo spamd[2826]: spamd: connection from
> localhost.localdomain [127.0.0.1] at port 56804 Jun 28 04:43:21 salmo
> spamd[2826]: spamd: setuid to spamfilter succeeded Jun 28 04:43:21 salmo
> spamd[2826]: spamd: processing message
> <OF1DE78230.3CDD3215-ON852573...@epamail.epa.gov> for
> spamfilter:1006
You should have entries as following:
Jun 29 00:06:57 fpsvr1z150 postfix/qmgr[33967]: 8FE7DC3893: from=<amavis-us...@lists.sourceforge.net>, size=4153, nrcpt=1 (queue active)
Jun 29 00:07:02 fpsvr1z150 postfix/smtp[19453]: 8FE7DC3893: to=<r.fe...@ek-muc.de>, relay=127.0.0.1[127.0.0.1]:10024, delay=5.4, delays=0.24/0.04/0.01/5.1, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=06512-05, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as C3653C38C2)
(look for the queue id)
However, the reject line which Noel gave you should tell, that pflogsumm works.
So it might be that there is something with your syslog.
Maybe it helps if you post qmgr+smtp entries or a reject.
peterli...@gmail.com
I got the same problem myself. :|
// Peter
Cody Millard
I started experiencing a problem like this. For me, I changed the postfix instance name to match the email server identity. You MUST included that name change in pflogsumm.
--syslog-name=name
Set syslog-name to look for for Postfix log entries.
By default, pflogsumm looks for entries in logfiles
with a syslog name of "postfix," the default.
If you've set a non-default "syslog_name" parameter
in your Postfix configuration, use this option to
tell pflogsumm what that is.
Check your main.cf for "multi_instance_name = customname" and use that like so:
pflogsumm --syslog-name=postfix-customname /var/log/mail.log