Postfix Monitoring With Mailgraph And pflogsumm

[WaveQam]

Good day all,
I have followed this HOWTO (page 2) for Ubuntu and seeing some strange results.

I am getting the graphs, but its like the log file is not being parsed. Also when I login to the server and tail-f /var/log/mail.log I am not seeing any activity but I know mail is flowing.

http://vmail.bc.yourlink.ca/cgi-bin/mailgraph.cgi

Also the pflogsum script did not execute in crontab But I think I fixed this this morning and will have to wait until tommorow to see for sure.

After I initially installed I manually ran the pflogsumm script and got the email. After I fixed crontab I manually ran it again and It looks like the exact same stats from the day before.

I do notice that the contents of the mail.log file are changed after I run the script but its like the messages are not going to mail.log anymore

here is my crontab
root@vmail:/etc# cat crontab
# /etc/crontab: system-wide crontab
# Unlike any other crontab you don't have to run the `crontab'
# command to install the new version when you edit this file.
# This file also has a username field, that none of the other crontabs do.

SHELL=/bin/sh
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin

# m h dom mon dow user command
17 * * * * root run-parts --report /etc/cron.hourly
25 6 * * * root test -x /usr/sbin/anacron || run-parts --report /etc/cron.daily
47 6 * * 7 root test -x /usr/sbin/anacron || run-parts --report /etc/cron.weekly
52 6 1 * * root test -x /usr/sbin/anacron || run-parts --report /etc/cron.monthly
#
0 7 * * * root /usr/local/sbin/postfix_report.sh &> /dev/null
root@vmail:/etc#

here is the dir listing showing my mail.log files
root@vmail:/var/log# ls -al mail.log*
-rw-r----- 1 root adm 1376895 2006-12-19 11:59 mail.log
-rw-r----- 1 root adm 464219 2006-12-17 12:00 mail.log.0.gz
-rw-r----- 1 root adm 297485 2006-12-17 06:47 mail.log.1.gz
-rw-r----- 1 root adm 195488 2006-12-16 07:00 mail.log.2.gz
-rw-r----- 1 root adm 170399 2006-12-14 07:00 mail.log.3.gz
-rw-r----- 1 root adm 187873 2006-12-12 07:00 mail.log.4.gz

What am I missing?
darcy

[falko]

Please run

tail -f /var/log/mail.log

and at the same time send a mail to your server? Do you see any action in your mail log then?

[WaveQam]

Falko,

I did this, It looks like the last messages in the log file is at 07:00:01. The Message was delivered to the mail box but it did not go through mail.log.

root@vmail:~# tail -f /var/log/mail.log
Dec 20 06:59:57 vmail postfix/smtpd[23310]: NOQUEUE: reject: RCPT from mout0.freenet.de[194.97.50.131]: 550 <osprey@nakusp.net>: Recipient address rejected: User unknown in virtual alias table; from=<info@schneider-h-design.de> to=<osprey@nakusp.net> proto=ESMTP helo=<mout0.freenet.de>
Dec 20 06:59:57 vmail postfix/smtpd[23310]: disconnect from mout0.freenet.de[194.97.50.131]
Dec 20 06:59:57 vmail postfix/smtpd[23340]: disconnect from mailhub1.cotas.com.bo[200.58.160.154]
Dec 20 06:59:57 vmail postfix/smtpd[23234]: disconnect from smin199-44.vdial.verat.net[213.244.199.44]
Dec 20 06:59:58 vmail postfix/smtpd[23247]: connect from ea.3f.5746.static.theplanet.com[70.87.63.234]
Dec 20 06:59:59 vmail postfix/smtpd[23247]: NOQUEUE: reject: RCPT from ea.3f.5746.static.theplanet.com[70.87.63.234]: 550 <jfowaistcoat@columbiacable.net>: Recipient address rejected: User unknown in virtual alias table; from=<> to=<jfowaistcoat@columbiacable.net> proto=SMTP helo=<p32.ich-14.com>
Dec 20 06:59:59 vmail postfix/smtpd[23247]: disconnect from ea.3f.5746.static.theplanet.com[70.87.63.234]
Dec 20 07:00:01 vmail postfix/smtpd[23112]: warning: 222.253.169.128: address not listed for hostname localhost
Dec 20 07:00:01 vmail postfix/smtpd[23112]: connect from unknown[222.253.169.128]
Dec 20 07:00:01 vmail postfix/smtpd[23233]: connect from unknown[216.86.127.236]



(note that I sent an email to my mailbox at 10:02 and it was successfully delivered.)






root@vmail:~#

Also it appears as if the pflogsumm script did not run again.
here is the dir listing concerning mail.log

root@vmail:~# ls -al /var/log/mail.log*
-rw-r----- 1 root adm 804019 2006-12-20 07:00 /var/log/mail.log
-rw-r----- 1 root adm 197743 2006-12-19 11:59 /var/log/mail.log.0.gz
-rw-r----- 1 root adm 464219 2006-12-17 12:00 /var/log/mail.log.1.gz
-rw-r----- 1 root adm 297485 2006-12-17 06:47 /var/log/mail.log.2.gz
-rw-r----- 1 root adm 195488 2006-12-16 07:00 /var/log/mail.log.3.gz
-rw-r----- 1 root adm 170399 2006-12-14 07:00 /var/log/mail.log.4.gz

Crontab as per previous message

I once again ran the script manually using
root@vmail:~# /usr/local/sbin/postfix_report.sh &> /dev/null
root@vmail:~#

and the report was delivered to my mailbox. The report is different this time than the previous two reports.

Darcy


Darcy

[WaveQam]

Good day all,

It looks like the plflogsumm script did run this time, infact it appears to have run twice.

When I followed the instructions from page two I did the "crontab -e" to add the line 0 7 * * * /usr/local/sbin/postfix_report.sh &> /dev/null. When I was troubleshooting why I was not getting the report emails, I did a "vi crontab" and added the line 0 7 * * * root /usr/local/sbin/postfix_report.sh &> /dev/null.

So Question #1, Why am I now getting the report twice.

Next, When examining the report, it looks like I am only getting data between 06:00 and 07:00 from my mail.log file.
Per-Hour Traffic Summary
time received delivered deferred bounced rejected
--------------------------------------------------------------------
0000-0100 0 0 0 0 0
0100-0200 0 0 0 0 0
0200-0300 0 0 0 0 0
0300-0400 0 0 0 0 0
0400-0500 0 0 0 0 0
0500-0600 0 0 0 0 0
0600-0700 211 326 40 0 972
0700-0800 0 0 0 0 0
0800-0900 0 0 0 0 0
0900-1000 0 0 0 0 0
1000-1100 0 0 0 0 0
1100-1200 0 0 0 0 0
1200-1300 0 0 0 0 0
1300-1400 0 0 0 0 0
1400-1500 0 0 0 0 0
1500-1600 0 0 0 0 0
1600-1700 0 0 0 0 0
1700-1800 0 0 0 0 0
1800-1900 0 0 0 0 0
1900-2000 0 0 0 0 0
2000-2100 0 0 0 0 0
2100-2200 0 0 0 0 0
2200-2300 0 0 0 0 0
2300-2400 0 0 0 0 0

and when I unzip and cat mail.log.0.gz from the 20th I see the first entry
Dec 20 06:25:09 vmail postfix/qmgr[27187]: CA34E18759D: from=<oekmilitary@kimmscott.com>, size=19166, nrcpt=1 (queue active)

and the last entry
Dec 20 07:00:01 vmail postfix/smtpd[23233]: connect from unknown[216.86.127.236]


When I cat mail.log (current) I see the first line
Dec 21 06:25:06 vmail postfix/qmgr[27187]: E90F11875A1: from=<kitfox@shaw.ca>, size=320834, nrcpt=1 (queue active)
and the last line
Dec 21 07:00:02 vmail postfix/qmgr[27187]: 22FDC1875CA: removed
and this was check at approx 09:11 this am.

Question #2 then becomes,

Why is my mail log only logging traffic between 06:25 and 07:02?

tail -f /var/log/mail.log shows no activity after 7 in the morning.

Weird.

WaveQam

[falko]

Originally Posted by WaveQam

Falko,

I did this, It looks like the last messages in the log file is at 07:00:01. The Message was delivered to the mail box but it did not go through mail.log.

What's the domain name of the email address you tried to send to?

[WaveQam]

Falko,
I thank you for your guidance. This server (vmail.bc.yourlink.ca) is a virtual host for revelstoke.net, columbiacable.net, nakusp.net and soon - coppervalley.net.

I sent the email from darcypa@gmail.com to darcypa@revelstoke.net

I currently have about 1000 email address on the system

darcy

[falko]

Is 139.142.43.24 your server's public IP address?

[WaveQam]

Yes it is.

I checked this am, it looks like the script fired twice again. First email show data for email between 6:00 and 7:00 only again, Second email shows no data at all (zero emails). Both emails were sent at 7:00 AM

I did a 'crontab -e' to remove the added line so I can see if I still get two emails.

Also noticed that syslog also ends at 07:00, I wonder if there is a problem with restarting loging after logrotate.

Here is the logrotate.conf

# see "man logrotate" for details
# rotate log files weekly
weekly

# keep 4 weeks worth of backlogs
rotate 4

# create new (empty) log files after rotating old ones
create

# uncomment this if you want your log files compressed
#compress

# packages drop log rotation information into this directory
include /etc/logrotate.d

# no packages own wtmp, or btmp -- we'll rotate them here
/var/log/wtmp {
missingok
monthly
create 0664 root utmp
rotate 1
}

/var/log/btmp {
missingok
monthly
create 0664 root utmp
rotate 1
}

# system-specific logs may be configured here
/home/revelstoke/logs/access_log /home/revelstoke/logs/error_log {
rotate 5
weekly
compress
postrotate
/usr/sbin/apache2ctl graceful
endscript
}
/home/columbiacable/logs/access_log /home/columbiacable/logs/error_log {
rotate 5
weekly
compress
postrotate
/usr/sbin/apache2ctl graceful
endscript
}
/home/nakusp/logs/access_log /home/nakusp/logs/error_log {
rotate 5
weekly
compress
postrotate
/usr/sbin/apache2ctl graceful
endscript
}
/home/coppervalley/logs/access_log /home/coppervalley/logs/error_log {
rotate 5
weekly
compress
postrotate
/usr/sbin/apache2ctl graceful
endscript
}
/var/log/mail.log {
missingok
daily
rotate 7
create
compress
start 0
}


Darcy

[falko]

Is syslog running after 7.00h? Do you see it in the output of

ps aux

?

[WaveQam]

Checked Todays mail Log.

First entry is at Dec 23 06:25:08, last entry is at Dec 23 07:00:02 - Current time is Dec 23 12:38

This is the only entry for syslog when I ps -aux

syslog 9087 0.0 0.0 1764 704 ? Ss 06:25 0:01 /sbin/syslogd -u syslog -a /var/lib/named/dev/log


Looks like the output is being redireced?

I tried to cat or Tail that location but nothing there

root@vmail:~# tail -f /var/lib/named/dev/log
tail: cannot open `/var/lib/named/dev/log' for reading: No such device or address
tail: no files remaining
root@vmail:~# cat /var/lib/named/dev/log
cat: /var/lib/named/dev/log: No such device or address
root@vmail:~#

root@vmail:/var/lib/named/dev# ls -al
total 8
drwxr-xr-x 2 root root 4096 2006-12-23 06:25 .
drwxr-xr-x 5 root root 4096 2006-10-17 12:34 ..
srw-rw-rw- 1 root root 0 2006-12-23 06:25 log
crw-rw-rw- 1 root root 1, 3 2006-10-17 12:35 null
crw-rw-rw- 1 root root 1, 8 2006-10-17 12:35 random

Complete ps -aux attached


Darcy