Empty pflogsumm Reports

[Rich Shepard]

Starting a few days ago, the daily log analysis produced by pflogsumm
shows up with no values for the fields. See partial example here:

From ***@appl-ecosys.com Wed Jun 27 04:40:02 2007
Date: Wed, 27 Jun 2007 04:40:01 -0700 (PDT)
From: ***@appl-ecosys.com
To: ***@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

[MrC]

Post by Rich Shepard
Starting a few days ago, the daily log analysis produced by pflogsumm
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

The command

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.

Rich

[MrC]

Post by Rich Shepard

Start by showing the command that is actually running (via cron) and any
associated log entries.

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.

Post by Rich Shepard
are no entries in /var/log/cron* and no mention of pflogsumm in
/var/log/messages.
Rich

[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="***@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}
------------------------------------------------------------------------------------------------

Rich

[Noel Jones]

Post by Rich Shepard

I won't hazard a guess at what is inside "1pdflogsumm". It might be best
to show that script.

----------------------------------------------------------------------------
#!/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??

[Rich Shepard]

Post by Noel Jones
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.

Post by 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
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.)

Rich

[Noel Jones]

Post by Rich Shepard

Post by 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

[Rich Shepard]

Post by Noel Jones
So what happens if you run pflogsumm manually?
pflogsumm /path/to/logfile

Noel,

Same thing:

[***@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,

Rich

[pheonix1t]

Post by Rich Shepard

Post by Noel Jones
So what happens if you run pflogsumm manually?
pflogsumm /path/to/logfile

Noel,
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,
Rich

maybe this is a compressed mail log? most systems do log rotate and
then compress the older logs and rename them to log.1 or something like
this.

Oskar

[Rich Shepard]

Post by pheonix1t
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.

Rich

[Duane Hill]

Post by Rich Shepard

Post by Noel Jones
So what happens if you run pflogsumm manually?
pflogsumm /path/to/logfile

Noel,
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.

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

[Noel Jones]

Post by Noel Jones
So what happens if you run pflogsumm manually?
pflogsumm /path/to/logfile

Noel,

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.

[Rich Shepard]

Post by Noel Jones
what if you pipe the log to pflogsumm??
# cat logfile | pflogsumm

No difference.

Post by Noel Jones
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:

[***@salmo ~]# ll /usr/local/bin/pflogsumm
-rwxr-xrwx 1 root root 53740 2004-09-13 15:01 /usr/local/bin/pflogsumm*

Rich

[Daniel L. Miller]

Post by Rich Shepard

Post by Noel Jones
what if you pipe the log to pflogsumm??
# cat logfile | pflogsumm

No difference.

Post by Noel Jones
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
53740 2004-09-13 15:01 /usr/local/bin/pflogsumm*
Rich

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

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.

[Rich Shepard]

Post by Daniel L. Miller
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

[***@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

Post by Daniel L. Miller
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.

Rich

[Gary Mort]

Post by Rich Shepard
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]

Post by Gary Mort
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,

Rich

[Robert Felber]

Post by Rich Shepard

Post by Gary Mort
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?

[Rich Shepard]

Post by Robert Felber
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-ON85257308.003BE74D-***@epamail.epa.gov> for spamfilter:1006

Rich

[Rich Shepard]

Mea culpa! That was at the start of today's maillog, not the latest.

Rich

[Noel Jones]

Post by Rich Shepard
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=<***@spraytower.com> to=<***@example.com> proto=ESMTP
helo=<[61.108.188.61]>
Jun 28 17:04:05 mgate2 postfix/smtp[65924]: E6A01797858:
to=<***@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.

[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) ...

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,

Rich

[p***@gmail.com]

Rich, did you manage to fix this problem?
I got the same problem myself. :|

// Peter

Post by 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) ...

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,
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: [phone]

[Cody Millard]

Hello!

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

[Robert Felber]

Post by Rich Shepard

Post by Robert Felber
Can you post a log-line?

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
spamfilter:1006

You should have entries as following:

Jun 29 00:06:57 fpsvr1z150 postfix/qmgr[33967]: 8FE7DC3893: from=<amavis-user-***@lists.sourceforge.net>, size=4153, nrcpt=1 (queue active)
Jun 29 00:07:02 fpsvr1z150 postfix/smtp[19453]: 8FE7DC3893: to=<***@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.

[Daniel L. Miller]

Post by Noel Jones
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.

I second that. I had a problem setting up a new server a little while
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.

[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?

[***@salmo ~]$ which perl
/usr/bin/perl

Rich