Clamd dying same time each day.

Discussion in 'Server Operation' started by mpl, Feb 7, 2011.

  1. mpl

    mpl New Member

    Good Day All,
    For the life of me I cannot figure out why clamav-daemon dies at the same time each day. After a simple "/etc/init.d/clamav-daemon start" we are good to go for another day. I think I have narrowed this down to some cron job but which one? Seems like the server.sh script is running at this time each day. Help please?

    Debian 10 Perfect Server ispconfig 3

    Feb 6 06:28:27 webserver amavis[2134]: (02134-03) (!!)ClamAV-clamd av-scanner FAILED: run_av error: Too many retries to talk to /var/run/clamav/clamd.ctl (Can't connect to UNIX socket /var/run/clamav/clamd.ctl: Connection refused) at (eval 88) line 309.

    Feb 7 06:28:15 webserver amavis[2133]: (02133-06) (!!)ClamAV-clamd av-scanner FAILED: run_av error: Too many retries to talk to /var/run/clamav/clamd.ctl (Can't connect to UNIX socket /var/run/clamav/clamd.ctl: Connection refused) at (eval 88) line 309.

    Best Regards,
    Mike
     
  2. falko

    falko Super Moderator ISPConfig Developer

    I guess it is some cron job in /etc/cron.daily/.
     
  3. mpl

    mpl New Member

    Hello Falco ;-)
    Yep, that's what I am thinking...
    Here is something that just started today. I guess I need to figure this out before I can see where clamav is failing. Any ideas? Is it possible to step through the php script to figure out where this message is coming from?
    1st.
    webserver:/etc/cron.daily# crontab -l
    * * * * * /usr/local/ispconfig/server/server.sh > /dev/null 2>> /var/log/ispconfig/cron.log
    30 00 * * * /usr/local/ispconfig/server/cron_daily.sh > /dev/null 2>> /var/log/ispconfig/cron.log
    webserver:/etc/cron.daily# /usr/local/ispconfig/server/server.sh
    2nd.
    webserver:/etc/cron.daily# /usr/local/ispconfig/server/server.sh
    finished.
    3rd.
    webserver:/etc/cron.daily# /usr/local/ispconfig/server/cron_daily.sh
    Warning: Truncating oversized referrer field
    Warning: Truncating oversized referrer field
    Warning: Truncating oversized referrer field
    Warning: Truncating oversized referrer field
    Warning: Truncating oversized referrer field
    //////////////////////////////////////////////////////////////
    So I check cron_daily.sh
    webserver:/home/www# cat /usr/local/ispconfig/server/cron_daily.sh
    #!/bin/sh

    PATH=/sbin:/usr/sbin:/bin:/usr/bin:/usr/local/sbin:/usr/local/bin:/usr/X11R6/bin

    /usr/bin/php -q /usr/local/ispconfig/server/cron_daily.php
     
  4. falko

    falko Super Moderator ISPConfig Developer

    Can you post the output of
    Code:
    ls -la /etc/cron.daily/
    ?
     
  5. mpl

    mpl New Member

    Here you go! Thanks so much Falco ;-)

    webserver:/etc/postfix# ls -la /etc/cron.daily/
    total 84
    drwxr-xr-x 2 root root 4096 2011-01-22 13:26 .
    drwxr-xr-x 105 root root 4096 2011-02-09 16:18 ..
    -rwxr-xr-x 1 root root 199 2008-07-26 03:29 amavisd-new
    -rwxr-xr-x 1 root root 633 2010-12-11 13:59 apache2
    -rwxr-xr-x 1 root root 7482 2010-05-12 16:25 apt
    -rwxr-xr-x 1 root root 314 2008-12-04 21:51 aptitude
    -rwxr-xr-x 1 root root 77 2008-09-16 04:28 apt-show-versions
    -rwxr-xr-x 1 root root 502 2007-11-20 02:35 bsdmainutils
    -rwxr-xr-x 1 root root 4073 2010-12-10 09:01 exim4-base
    -rwxr-xr-x 1 root root 89 2008-10-08 11:34 logrotate
    -rwxr-xr-x 1 root root 954 2009-01-24 07:31 man-db
    -rwxr-xr-x 1 root root 438 2008-10-28 06:18 mlocate
    -rwxr-xr-x 1 root root 1154 2009-11-22 12:35 ntp
    -rw-r--r-- 1 root root 102 2008-09-28 05:33 .placeholder
    -rwxr-xr-x 1 root root 345 2008-09-29 04:52 quota
    -rwxr-xr-x 1 root root 651 2008-08-25 13:03 rkhunter
    -rwxr-xr-x 1 root root 1142 2010-01-01 13:58 spamassassin
    -rwxr-xr-x 1 root root 330 2010-08-11 11:12 squirrelmail
    -rwxr-xr-x 1 root root 3349 2008-09-28 05:33 standard
    -rwxr-xr-x 1 root root 1450 2008-10-27 16:02 webalizer
     
  6. falko

    falko Super Moderator ISPConfig Developer

    That looks ok. What's the output of
    Code:
    crontab -l
    ?

    BTW, you could set up monit and make it restart clamd whenever it is not running.
     
  7. mpl

    mpl New Member

    Here you go Falco...
    webserver:/# crontab -l
    * * * * * /usr/local/ispconfig/server/server.sh > /dev/null 2>> /var/log/ispconfig/cron.log
    30 00 * * * /usr/local/ispconfig/server/cron_daily.sh > /dev/null 2>> /var/log/ispconfig/cron.log

    and...
    webserver:/# monit status
    The monit daemon 4.10.1 uptime: 6m

    Process 'clamavd'
    status running
    monitoring status monitored
    pid 29329
    parent pid 1
    uptime 10h 15m
    childrens 0
    memory kilobytes 96088
    memory kilobytes total 96088
    memory percent 37.4%
    memory percent total 37.4%
    cpu percent 0.0%
    cpu percent total 0.0%
    unix socket response time 0.002s to /var/run/clamav/clamd.ctl [DEFAULT]
    data collected Thu Feb 10 21:52:54 2011

    System 'webserver.kd8q.com'
    status running
    monitoring status monitored
    load average [0.01] [0.04] [0.02]
    cpu 0.2%us 0.1%sy 0.2%wa
    memory usage 179852 kB [70.1%]
    data collected Thu Feb 10 21:52:54 2011

    BTW...Thanks for suggesting Monit! Wonderful tool and just what I needed. I had actually started a script to restart clamav each day until I figured out why it was dying but Monit is a much better solution ;-) Many thanks Falco :)

    Oh and believe I figured out the "Warning: Truncating oversized referrer field" from earlier to be an error in Mysql caused by amavis-new and clamav both being dead. I think I will set up monit for amavis as well so I can hopefully catch when these two are actually choking!
     
  8. mpl

    mpl New Member

    What do you make of this????

    webserver:/var/run/amavis# monit summary
    The monit daemon 4.10.1 uptime: 5m

    Process 'amavisd' not monitored

    File 'amavisd_bin' accessible
    File 'amavisd_rc' accessible
    Process 'apache' running
    Process 'clamd' running
    File 'clamavd_bin' accessible
    File 'clamavd_rc' accessible
    Process 'postfix' running
    File 'postfix_rc' accessible
    Process 'spamd' running
    File 'spamd_bin' accessible
    File 'spamd_rc' accessible
    Process 'syslogd' running
    File 'syslogd_file' accessible
    System 'webserver.kd8q.com' running

    webserver:/var/run/amavis# monit validate
    Sendmail error: 554 5.7.1 <*********@gmail.com>: Relay access denied
    Alert handler failed, retry scheduled for next cycle
    'amavisd' process is not runningSendmail error: 554 5.7.1 <**********@gmail.com>: Relay access denied
    'amavisd' trying to restart'amavisd' start: /etc/init.d/amavis
    Starting amavisd: 'amavisd' failed to startSendmail error: 554 5.7.1 <*********@gmail.com>: Relay access denied
    webserver:/var/run/amavis# amavisd-new.

    But then look at this.....

    webserver:/var/run/amavis# netstat -tap
    Active Internet connections (servers and established)
    Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name
    tcp 0 0 *:imaps *:* LISTEN 3187/dovecot
    tcp 0 0 *:pop3s *:* LISTEN 3187/dovecot
    tcp 0 0 *:53443 *:* LISTEN 2043/rpc.statd
    tcp 0 0 localhost:10024 *:* LISTEN 6469/amavisd (virgitcp 0 0 localhost:10025 *:* LISTEN 3141/master
    tcp 0 0 *:mysql *:* LISTEN 2374/mysqld
    tcp 0 0 *:pop3 *:* LISTEN 3187/dovecot
    tcp 0 0 *:imap2 *:* LISTEN 3187/dovecot
    tcp 0 0 localhost:spamd *:* LISTEN 2445/spamd.pid
    tcp 0 0 *:sunrpc *:* LISTEN 2032/portmap
    tcp 0 0 *:ftp *:* LISTEN 10528/pure-ftpd (SE
    tcp 0 0 webserver.kd8q.c:domain *:* LISTEN 2273/named
    tcp 0 0 localhost:domain *:* LISTEN 2273/named
    tcp 0 0 *:ssh *:* LISTEN 2287/sshd
    tcp 0 0 localhost:ipp *:* LISTEN 19914/cupsd
    tcp 0 0 *:smtp *:* LISTEN 3141/master
    tcp 0 0 localhost:953 *:* LISTEN 2273/named
    tcp 0 0 localhost:2812 *:* LISTEN 6461/monit
    tcp 0 0 localhost:mysql localhost:58702 ESTABLISHED 2374/mysqld
    tcp 0 0 webserver.kd8q.co:56376 cpe-184-57-205-235:smtp TIME_WAIT -
    tcp 50 0 localhost:42757 localhost:10025 CLOSE_WAIT 29417/amavisd (ch1-
    tcp 0 0 localhost:58686 localhost:mysql TIME_WAIT -
    tcp 0 0 localhost:smtp localhost:35268 TIME_WAIT -
    tcp 0 0 localhost:58702 localhost:mysql ESTABLISHED 6973/smtpd
    tcp 0 300 webserver.kd8q.com:ssh 63-253-225-1:supfiledbg ESTABLISHED 4686/sshd: www [pri
    tcp 0 0 localhost:mysql localhost:58685 TIME_WAIT -
    tcp 0 0 localhost:58704 localhost:mysql ESTABLISHED 6973/smtpd
    tcp 0 0 localhost:58684 localhost:mysql TIME_WAIT -
    tcp 0 0 localhost:58703 localhost:mysql ESTABLISHED 6973/smtpd
    tcp 0 0 localhost:mysql localhost:58703 ESTABLISHED 2374/mysqld
    tcp 0 0 localhost:mysql localhost:58704 ESTABLISHED 2374/mysqld
    tcp6 0 0 [::]:http-alt [::]:* LISTEN 305/apache2
    tcp6 0 0 [::]:www [::]:* LISTEN 305/apache2
    tcp6 0 0 [::]:tproxy [::]:* LISTEN 305/apache2
    tcp6 0 0 [::]:ftp [::]:* LISTEN 10528/pure-ftpd (SE
    tcp6 0 0 [::]:domain [::]:* LISTEN 2273/named
    tcp6 0 0 [::]:ssh [::]:* LISTEN 2287/sshd
    tcp6 0 0 localhost:ipp [::]:* LISTEN 19914/cupsd
    tcp6 0 0 localhost:953 [::]:* LISTEN 2273/named
    tcp6 0 0 [::]:https [::]:* LISTEN 305/apache2

    So amavis is running but monit thinks it is not and cannot send the email??? Strange :confused:
     
    Last edited: Feb 11, 2011
  9. falko

    falko Super Moderator ISPConfig Developer

    Are there any errors in your mail log (in the /var/log/ directory)?
     
  10. mpl

    mpl New Member

    Hey Falco,
    The truth is, I believe the issue with amavis and monit was due to some disk errors that have been solved now :eek:

    Code:
    webserver:/var/log# monit summary
    The monit daemon 4.10.1 uptime: 9h 15m 
    
    Process 'amavisd'                   running
    File 'amavisd_bin'                  accessible
    File 'amavisd_rc'                   accessible
    Process 'apache'                    running
    Process 'clamd'                     running
    File 'clamavd_bin'                  accessible
    File 'clamavd_rc'                   accessible
    Process 'postfix'                   running
    File 'postfix_rc'                   accessible
    Process 'spamd'                     running
    File 'spamd_bin'                    accessible
    File 'spamd_rc'                     accessible
    Process 'syslogd'                   running
    File 'syslogd_file'                 accessible
    System 'webserver.kd8q.com'         running
    
    So that part is solved but...
    I still cannot figure out why clamav is dying ???

    Code:
    Feb 12 01:20:32 webserver amavis[2275]: (02275-05) (!!)ClamAV-clamd av-scanner FAILED: run_av error: Too many retries to talk to /var/run/clamav/clamd.ctl (Can't connect to UNIX socket /var/run/clamav/clamd.ctl: Connection refused) at (eval 88) line 309.
    Feb 12 01:22:33 webserver amavis[2275]: (02275-06-6) (!!)TROUBLE in check_mail: virus_scan FAILED: virus_scan: ALL VIRUS SCANNERS FAILED: ClamAV-clamd av-scanner FAILED: run_av error: Too many retries to talk to /var/run/clamav/clamd.ctl (Can't connect to UNIX socket /var/run/clamav/clamd.ctl: Connection refused) at (eval 88) line 309.; ClamAV-clamscan av-scanner FAILED: run_av error: run_av: Exceeded allowed time at (eval 88) line 516.
    At least monit gets clamav restarted but I would sure like to get to the bottom of this. I have to believe something is happening with a cron job. This may sound like a silly question, but where do the "root" emails disappear too on an ispconfig3 system? I think the fact that I cannot find them and I noticed most times the mail queue contained a mail to root at almost the exact time clamav dies, that maybe this is related!
    Thank to all for your help :)
     
  11. falko

    falko Super Moderator ISPConfig Developer

    Is this a physical system or a virtual machine?

    Take a look at /etc/aliases. On most systems there is an alias for root that points to postmaster which means mails for root are forwarded to the user postmaster.
     
  12. mpl

    mpl New Member

    Hello Falco,
    This is a virtual machine. Here is my aliases file.
    webserver:/etc# cat aliases
    # /etc/aliases
    mailer-daemon: postmaster
    postmaster: root
    nobody: root
    hostmaster: root
    usenet: root
    news: root
    webmaster: root
    www: root
    ftp: root
    abuse: root
    noc: root
    security: root
    root: root
    clamav: root

    So I guess I still don't understand how to find the root mails. Also, here is something strange (to me anyway) that just showed up. I don't ever remember seeing any mails for getmail@ until yesterday?
    Thanks for all your help Falco....you have been very gracious ;-)
     
  13. mpl

    mpl New Member

    Here is a stalled email from the queue and a bit of the mail log as well!

    Data from: 2011-02-14 23:10
    -Queue ID- --Size-- ----Arrival Time---- -Sender/Recipient-------
    4559221C11A* 616 Mon Feb 14 23:10:01 [email protected]
    [email protected]

    -- 0 Kbytes in 1 Request.

    Feb 14 22:50:01 webserver postfix/pickup[9075]: 390CE21C11A: uid=5001 from=
    Feb 14 22:50:01 webserver postfix/cleanup[10913]: 390CE21C11A: message-id=<[email protected]>
    Feb 14 22:50:01 webserver postfix/qmgr[2952]: 390CE21C11A: from=, size=616, nrcpt=1 (queue active)
    Feb 14 22:50:02 webserver postfix/smtpd[10889]: connect from localhost[127.0.0.1]
    Feb 14 22:50:02 webserver postfix/smtpd[10889]: lost connection after CONNECT from localhost[127.0.0.1]
    Feb 14 22:50:02 webserver postfix/smtpd[10889]: disconnect from localhost[127.0.0.1]
    Feb 14 22:50:02 webserver dovecot: pop3-login: Disconnected: rip=127.0.0.1, lip=127.0.0.1, secured
    Feb 14 22:50:02 webserver dovecot: imap-login: Disconnected: rip=127.0.0.1, lip=127.0.0.1, secured
    Feb 14 22:50:02 webserver postfix/smtpd[10946]: connect from localhost[127.0.0.1]
    Feb 14 22:50:02 webserver postfix/smtpd[10946]: ADA5A21C119: client=localhost[127.0.0.1]
    Feb 14 22:50:02 webserver postfix/cleanup[10913]: ADA5A21C119: message-id=<[email protected]>
    Feb 14 22:50:02 webserver postfix/qmgr[2952]: ADA5A21C119: from=, size=1060, nrcpt=1 (queue active)
    Feb 14 22:50:02 webserver postfix/smtpd[10946]: disconnect from localhost[127.0.0.1]
    Feb 14 22:50:02 webserver amavis[7933]: (07933-19) Passed CLEAN, -> , Message-ID: <[email protected]>, mail_id: be5o4lYGS-gW, Hits: 2.829, size: 616, queued_as: ADA5A21C119, 1321 ms
    Feb 14 22:50:02 webserver postfix/smtp[10917]: 390CE21C11A: to=, orig_to=, relay=127.0.0.1[127.0.0.1]:10024, delay=1.7, delays=0.37/0.02/0.01/1.3, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=07933-19, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as ADA5A21C119)
    Feb 14 22:50:02 webserver postfix/qmgr[2952]: 390CE21C11A: removed
    Feb 14 22:50:02 webserver postfix/local[10947]: ADA5A21C119: to=, relay=local, delay=0.15, delays=0.06/0.05/0/0.05, dsn=2.0.0, status=sent (delivered to command: procmail -a "$EXTENSION")
    Feb 14 22:50:02 webserver postfix/qmgr[2952]: ADA5A21C119: removed
    Feb 14 22:50:24 webserver postfix/smtpd[10889]: connect from localhost[127.0.0.1]
    Feb 14 22:50:24 webserver postfix/smtpd[10889]: disconnect from localhost[127.0.0.1]
    Feb 14 22:52:24 webserver postfix/smtpd[10966]: connect from localhost[127.0.0.1]
    Feb 14 22:52:24 webserver postfix/smtpd[10966]: disconnect from localhost[127.0.0.1]
    Feb 14 22:54:24 webserver postfix/smtpd[10981]: connect from localhost[127.0.0.1]
    Feb 14 22:54:24 webserver postfix/smtpd[10981]: disconnect from localhost[127.0.0.1]
    Feb 14 22:55:01 webserver postfix/pickup[10951]: 5E02E21C11A: uid=5001 from=
    Feb 14 22:55:01 webserver postfix/cleanup[10994]: 5E02E21C11A: message-id=<[email protected]>
    Feb 14 22:55:01 webserver postfix/qmgr[2952]: 5E02E21C11A: from=, size=616, nrcpt=1 (queue active)
    Feb 14 22:55:02 webserver postfix/smtpd[10981]: connect from localhost[127.0.0.1]
    Feb 14 22:55:02 webserver postfix/smtpd[10981]: lost connection after CONNECT from localhost[127.0.0.1]
    Feb 14 22:55:02 webserver postfix/smtpd[10981]: disconnect from localhost[127.0.0.1]
    Feb 14 22:55:02 webserver dovecot: pop3-login: Disconnected: rip=127.0.0.1, lip=127.0.0.1, secured
    Feb 14 22:55:02 webserver dovecot: imap-login: Disconnected: rip=127.0.0.1, lip=127.0.0.1, secured
    Feb 14 22:55:07 webserver postfix/smtpd[11029]: connect from localhost[127.0.0.1]
    Feb 14 22:55:07 webserver postfix/smtpd[11029]: 112BF21C119: client=localhost[127.0.0.1]
    Feb 14 22:55:07 webserver postfix/cleanup[10994]: 112BF21C119: message-id=<[email protected]>
    Feb 14 22:55:07 webserver postfix/qmgr[2952]: 112BF21C119: from=, size=1060, nrcpt=1 (queue active)
    Feb 14 22:55:07 webserver amavis[10968]: (10968-01) Passed CLEAN, -> , Message-ID: <[email protected]>, mail_id: 1orlfAQSWHF5, Hits: 2.829, size: 616, queued_as: 112BF21C119, 5781 ms
    Feb 14 22:55:08 webserver postfix/smtp[10998]: 5E02E21C11A: to=, orig_to=, relay=127.0.0.1[127.0.0.1]:10024, delay=7.2, delays=0.18/0.02/1.7/5.4, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=10968-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 112BF21C119)

    Thanks Again!
     
  14. falko

    falko Super Moderator ISPConfig Developer

    Ok, there's no alias for root, so I guess mails for root ended up in the /var/spool/mail/ or /var/mail/ directory.
    You might want to create an alias like
    Code:
    root: [email protected]
    in /etc/aliases to have root emails forwarded to you.
    Please run
    Code:
    newaliases
    after you have modified /etc/aliases and restart Postfix.
     

Share This Page