MailScanner/SpamAssassin timeouts

Tue May 31 16:27:17 IST 2005

MailScanner/SpamAssassin timeout problems is a regular subject in  
this mailing list, but I didn't find my version in the archive. My  
environment consists of MailScanner 4.41.3, SpamAssassin 3.0.3 and  
ClamAV 0.85.1.

The problem crops up after the MS initiated SA bayes database  
rebuild. As long as the bayes_auto_expire feature is enabled in SA  
configuration and disabled in MS there isn't any problem. If I  
disable auto expiring in SA (bayes_auto_expire 0) and enable it in MS  
(Rebuild Bayes Every = 28800) I get some SA timeouts, but only from  
the MS process which did the bayes database rebuild and only for some  
batches. If I TERM this process the timeout problem is gone. The  
problem also disappears after the periodically restart of this  
process, but if I do not kill the suspicious MS process it disables  
SA network checks and later SA local checks and I get some spam  
unchecked through. The other MS processes do not show any problem  
during these timeouts.

Question:
Is it possible to have a MailScanner process which only does SA bayes  
rebuild and terminates afterwards ?

regards
Thomas Buschor

You'll find some more detailed informations below, some shell  
snippets and a
logfile excerpt.

Shell Snippets
--------------

root# ls -al /var/spool/MailScanner/spamassassin/
total 10246
drwx------  3 mailscn mail    41472 May 26 16:51 ./
drwxr-xr-x  8 mailscn mail      512 May 18 12:47 ../
-rw-------  1 mailscn mail     1040 May 26 16:50 bayes.lock
-rw-------  1 mailscn mail     2060 May 26 16:52  
bayes.lock.zinal.switch.ch.549
-rw-------  1 mailscn mail     5736 May 26 16:51 bayes_journal
-rw-------  1 mailscn mail  9994240 May 26 16:50 bayes_seen
-rw-------  1 mailscn mail  5611520 May 26 16:50 bayes_toks
drwxr-xr-x  2 root    other     512 May 18 10:13 to-learn/

root# ps -ef | grep 549
mailscn   549 29604  0 16:51:14 ?        0:00 /usr/local/bin/perl -I/ 
opt/MailScanner/lib /opt/MailScanner/bin/MailScanner /da
     root   623   611  0 16:53:08 pts/1    0:00 grep 549

==> process with pid 549 is a child process of the later killed MS  
process 29604

root# kill -TERM 29604

root# ps -ef | grep mailscn
mailscn   425    11  0                   0:00 <defunct>
mailscn    57 12276  0 16:48:00 ?        0:03 /usr/local/bin/perl -I/ 
opt/MailScanner/lib /opt/MailScanner/bin/MailScanner /da
mailscn    11 12276  0 16:47:49 ?        0:03 /usr/local/bin/perl -I/ 
opt/MailScanner/lib /opt/MailScanner/bin/MailScanner /da
mailscn 29980 12276  0 16:47:05 ?        0:03 /usr/local/bin/perl -I/ 
opt/MailScanner/lib /opt/MailScanner/bin/MailScanner /da
     root   676   611  0 16:54:04 pts/1    0:00 grep mailscn
mailscn 28710     1  0   May 18 ?        0:00 /usr/exim/bin/exim -C / 
etc/mail/exim.conf.scanout -oP /var/run/exim-scanout.pid
mailscn   645    57  0                   0:00 <defunct>
mailscn 28707     1  0   May 18 ?        0:31 /usr/exim/bin/exim -C / 
etc/mail/exim.conf.scanin -bd
mailscn   672 12276  4 16:53:55 ?        0:02 /usr/local/bin/perl -I/ 
opt/MailScanner/lib /opt/MailScanner/bin/MailScanner /da
mailscn   567 29980  0                   0:00 <defunct>
mailscn 12276     1  0 08:42:37 ?        0:00 /usr/local/bin/perl -I/ 
opt/MailScanner/lib /opt/MailScanner/bin/MailScanner /da
mailscn   449 12276  0 16:50:31 ?        0:03 /usr/local/bin/perl -I/ 
opt/MailScanner/lib /opt/MailScanner/bin/MailScanner /da
mailscn   666   449  0                   0:00 <defunct>

root# ll /var/spool/MailScanner/spamassassin/
total 10246
drwx------  3 mailscn mail    41472 May 26 16:53 ./
drwxr-xr-x  8 mailscn mail      512 May 18 12:47 ../
-rw-------  1 mailscn mail     2460 May 26 16:53  
bayes.lock.zinal.switch.ch.549
-rw-------  1 mailscn mail     7896 May 26 16:53 bayes_journal
-rw-------  1 mailscn mail  9994240 May 26 16:50 bayes_seen
-rw-------  1 mailscn mail  5611520 May 26 16:50 bayes_toks
drwxr-xr-x  2 root    other     512 May 18 10:13 to-learn/

==> lock was not cleaned even if using TERM signal

MailScanner log excerpt
-----------------------

Some comments to the logs you'll find below
- rebuilding bayes database lasts more or less 1 minute
   the MS/SA timeout is set to 120s (SpamAssassin Timeout = 120)
- most log entries from the other processes are removed
   (on request I can give you the full log)
- my comments begin with "==>"

May 26 16:43:39 localhost MailScanner[29604]: MailScanner E-Mail  
Virus Scanner version 4.41.3 starting...
May 26 16:43:40 localhost MailScanner[29604]: Read 120 hostnames from  
the phishing whitelist
May 26 16:43:40 localhost MailScanner[29604]: Bayes database rebuild  
is due
May 26 16:43:40 localhost MailScanner[29604]: SpamAssassin Bayes  
database rebuil d starting
May 26 16:44:02 localhost MailScanner[5483]: New Batch: Scanning 1  
messages, 4882 bytes
May 26 16:44:12 localhost MailScanner[5435]: New Batch: Found 2  
messages waiting
May 26 16:44:12 localhost MailScanner[5435]: New Batch: Scanning 1  
messages, 1810 bytes
May 26 16:44:33 localhost MailScanner[5789]: New Batch: Found 3  
messages waiting
May 26 16:44:33 localhost MailScanner[5789]: New Batch: Scanning 1  
messages, 1125 bytes
May 26 16:44:34 localhost MailScanner[29604]: SpamAssassin Bayes  
database rebuild completed

==> bayes rebuild completed in less than 1 minute
     MailScanner.conf: SpamAssassin Timeout = 120

May 26 16:44:36 localhost MailScanner[29604]: Using locktype = posix
May 26 16:44:36 localhost MailScanner[29604]: Creating hardcoded  
struct_flock subroutine for solaris (misc-type)
May 26 16:44:44 localhost MailScanner[5435]: Spam Checks: Found 1  
spam messages
May 26 16:44:44 localhost MailScanner[5435]: Virus and Content  
Scanning: Startin
g
May 26 16:44:44 localhost MailScanner[5789]: Spam Checks: Found 1  
spam messages
May 26 16:44:44 localhost MailScanner[5789]: Virus and Content  
Scanning: Startin
g
May 26 16:44:44 localhost MailScanner[5789]: Uninfected: Delivered 1  
messages
May 26 16:44:44 localhost MailScanner[5435]: Uninfected: Delivered 1  
messages
May 26 16:44:45 localhost MailScanner[5483]: Spam Checks: Found 1  
spam messages
May 26 16:44:45 localhost MailScanner[5483]: Virus and Content  
Scanning: Startin
g
May 26 16:44:45 localhost MailScanner[5483]: Uninfected: Delivered 1  
messages
May 26 16:45:48 localhost MailScanner[29604]: New Batch: Scanning 1  
messages, 4424 bytes

==> below only log entries for MailScanner[29604]
     (the other MS processes run as expected)

May 26 16:47:58 localhost MailScanner[29604]: New Batch: Found 2  
messages waiting
May 26 16:47:58 localhost MailScanner[29604]: New Batch: Scanning 1  
messages, 2025 bytes
May 26 16:48:14 localhost MailScanner[29604]: Spam Checks: Found 1  
spam messages
May 26 16:48:14 localhost MailScanner[29604]: Virus and Content  
Scanning: Starting
May 26 16:48:15 localhost MailScanner[29604]: Uninfected: Delivered 1  
messages
May 26 16:49:03 localhost MailScanner[29604]: New Batch: Scanning 1  
messages, 70836 bytes
May 26 16:49:20 localhost MailScanner[29604]: Spam Checks: Found 1  
spam messages
May 26 16:49:20 localhost MailScanner[29604]: Virus and Content  
Scanning: Starting
May 26 16:49:20 localhost MailScanner[29604]:  
ClamAVModule::INFECTED:: Worm.Mytob.T:: ./1DbJfS-00001w-V9/document.zip
May 26 16:49:20 localhost MailScanner[29604]:  
ClamAVModule::INFECTED:: Worm.Mytob.T:: ./1DbJfS-00001w-V9/ 
document.htm  .exe
May 26 16:49:20 localhost MailScanner[29604]: Virus Scanning: ClamAV  
Module found 2 infections
May 26 16:49:20 localhost MailScanner[29604]: Infected message  
1DbJfS-00001w-V9 came from ::1.57096
May 26 16:49:20 localhost MailScanner[29604]: Virus Scanning: Found 2  
viruses
May 26 16:49:20 localhost MailScanner[29604]: Filename Checks:  
Windows/DOS Executable (1DbJfS-00001w-V9  
document.htm                                     .exe)
May 26 16:49:20 localhost MailScanner[29604]: Filetype Checks: No  
executables (1DbJfS-00001w-V9  
document.htm                                     .exe)
May 26 16:49:20 localhost MailScanner[29604]: Other Checks: Found 2  
problems
May 26 16:49:20 localhost MailScanner[29604]: Saved entire message  
to /var/spool/MailScanner/quarantine/20050526/1DbJfS-00001w-V9
May 26 16:49:20 localhost MailScanner[29604]: Saved infected  
"document.zip" to /var/spool/MailScanner/quarantine/ 
20050526/1DbJfS-00001w-V9
May 26 16:49:20 localhost MailScanner[29604]: Saved infected  
"document.htm  .exe" to /var/spool/MailScanner/quarantine/ 
20050526/1DbJfS-00001w-V9
May 26 16:49:21 localhost MailScanner[29604]: Silent: Delivered 1  
messages containing silent viruses
May 26 16:49:39 localhost MailScanner[29604]: New Batch: Scanning 1  
messages, 3177 bytes
May 26 16:50:49 localhost MailScanner[29604]: Virus and Content  
Scanning: Starting
May 26 16:50:49 localhost MailScanner[29604]: Uninfected: Delivered 1  
messages
May 26 16:51:13 localhost MailScanner[29604]: New Batch: Scanning 1  
messages, 14192 bytes
May 26 16:53:14 localhost MailScanner[29604]: SpamAssassin timed out  
and was killed, failure 1 of 10

==> 1st timeout occured

May 26 16:53:15 localhost MailScanner[29604]: Virus and Content  
Scanning: Starting
May 26 16:53:15 localhost MailScanner[29604]: Uninfected: Delivered 1  
messages

==> kill -TERM 29604
==> no more Timeouts

------------------------ MailScanner list ------------------------
To unsubscribe, email jiscmail at jiscmail.ac.uk with the words:
'leave mailscanner' in the body of the email.
Before posting, read the Wiki (http://wiki.mailscanner.info/) and
the archives (http://www.jiscmail.ac.uk/lists/mailscanner.html).

Support MailScanner development - buy the book off the website!