Postfix Monitoring With Mailgraph And pflogsumm

Discussion in 'HOWTO-Related Questions' started by WaveQam, Dec 19, 2006.

  1. WaveQam

    WaveQam New Member

    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
     
  2. falko

    falko Super Moderator

    Please run
    Code:
    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?
     
  3. WaveQam

    WaveQam New Member

    Still no Joy.

    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
     
    Last edited: Dec 20, 2006
  4. WaveQam

    WaveQam New Member

    Still strange

    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
     
    Last edited: Dec 21, 2006
  5. falko

    falko Super Moderator

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

    WaveQam New Member

    Still Strange

    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
     
  7. falko

    falko Super Moderator

    Is 139.142.43.24 your server's public IP address?
     
  8. WaveQam

    WaveQam New Member

    Still strange

    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
     
    Last edited: Dec 22, 2006
  9. falko

    falko Super Moderator

    Is syslog running after 7.00h? Do you see it in the output of
    Code:
    ps aux
    ?
     
  10. WaveQam

    WaveQam New Member

    Still weird - Looging wrong???

    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
     

    Attached Files:

  11. falko

    falko Super Moderator

    Which distribution do you use?
     
  12. WaveQam

    WaveQam New Member

    Disto

    Using Ubuntu 6.06
     
  13. falko

    falko Super Moderator

    What are the outputs of
    Code:
    ls -la /dev/log
    and
    Code:
    ls -la /var/lib/named
    ?
     
  14. WaveQam

    WaveQam New Member


    root@vmail:~# ls -la /dev/log
    srw-rw-rw- 1 root root 0 2006-12-25 06:25 /dev/log
    root@vmail:~# ls -la /var/lib/named
    total 20
    drwxr-xr-x 5 root root 4096 2006-10-17 12:34 .
    drwxr-xr-x 38 root root 4096 2006-12-18 07:56 ..
    drwxr-xr-x 2 root root 4096 2006-12-25 06:25 dev
    drwxr-xr-x 3 root root 4096 2006-10-17 12:34 etc
    drwxr-xr-x 4 root root 4096 2006-10-17 12:34 var
    root@vmail:~#
     
  15. falko

    falko Super Moderator

    Please try this:
    Code:
    cp -pf /dev/log /var/lib/named/dev/
     
  16. WaveQam

    WaveQam New Member

    Still no Joy.

    Falko,

    Merry Christmas and Happy new you to you.

    root@vmail:~# cp -pf /dev/log /var/lib/named/dev/
    cp: cannot open `/dev/log' for reading: No such device or address
    root@vmail:~#

    Darcy
     
  17. falko

    falko Super Moderator

    But /dev/log was existing in your previous post... :confused: What's the output of
    Code:
    ls -la /dev/log
    now?
     
  18. WaveQam

    WaveQam New Member

    Good day Falko,

    Yes it does appear to be there. Is it a symbolic link?

    root@vmail:/dev# ls -al /dev/log
    srw-rw-rw- 1 root root 0 2006-12-27 06:25 /dev/log
    root@vmail:/dev# cp -pf /dev/log /var/lib/named/dev/
    cp: cannot open `/dev/log' for reading: No such device or address
    root@vmail:/dev#

    Darcy
     
  19. WaveQam

    WaveQam New Member

    Very interesting

    I stopped the Logging (/etc/init.d/syslogd stop) and manually run it like this
    syslogd -d (output attached).

    I then started it up again with syslogd -u syslog -a /var/lib/named/dev/log and now I can see messages moving when I tail-f ?var/log/mail.log

    I will have to see when the logging stops again (possibly after rotateing)

    WaveQam
     

    Attached Files:

  20. falko

    falko Super Moderator

    That reminds me of something... What's in /etc/init.d/sysklogd?
     

Share This Page