Fwd: Problems on Solaris x86
Pascal Maes
pascal.maes at elec.ucl.ac.be
Sat Aug 12 07:37:11 IST 2006
>
> Message: 16
> Date: Fri, 11 Aug 2006 17:21:46 +0100 (BST)
> From: "Drew Marshall" <drew at themarshalls.co.uk>
> Subject: Re: Fwd: Problems on Solaris x86
> To: "MailScanner discussion" <mailscanner at lists.mailscanner.info>
> Message-ID:
> <42275.194.70.180.170.1155313306.squirrel at webmail.r-bit.net>
> Content-Type: text/plain;charset=iso-8859-1
>
> On Fri, August 11, 2006 15:38, Pascal Maes wrote:
>> Now, when I start MailScanner I have the following lines in the
>> logfile :
>>
>> [...]
>
> And no mention of delivery (Or completion of scanning)? At this log
> point
> the batch is only being scanned for spam and not viruses. Can you
> turn on
> SpamAssassin debugging in MailScanner.conf and re-run the debug, it
> may
> yield something such as a permissions error in one of the SA
> processes.
>
> Drew
>
Well I didn't send all the stuff because it's long.
Here it is
1) in debugging mode
1.a) the message is stored in /var/spool/postfix/hold/
Aug 12 08:14:02 smtp-2-3 postfix/smtpd[8758]: [ID 197553 mail.info]
connect from gaia.elec.ucl.ac.be[130.104.236.1]
Aug 12 08:14:27 smtp-2-3 clamsmtpd: [ID 738258 mail.info] 100010:
accepted connection from: 127.0.0.1
Aug 12 08:14:27 smtp-2-3 postfix/smtpd[8760]: [ID 197553 mail.info]
connect from localhost[127.0.0.1]
Aug 12 08:14:27 smtp-2-3 postfix/smtpd[8758]: [ID 197553 mail.info]
NOQUEUE: client=gaia.elec.ucl.ac.be[130.104.236.1]
Aug 12 08:14:27 smtp-2-3 postfix/smtpd[8760]: [ID 197553 mail.info]
EA0A918F9B: client=gaia.elec.ucl.ac.be[130.104.236.1]
Aug 12 08:14:50 smtp-2-3 postfix/cleanup[8761]: [ID 197553 mail.info]
EA0A918F9B: hold: header Received: from smtp-2.dynsipr.ucl.ac.be
(localhost [127.0.0.1])??by smtp-2.dynsipr.ucl.ac.be (Postfix) with
ESMTP id EA0A918F9B??for <pascal.maes at uclouvain.be>; Sat, 12 Aug 2006
08:14:27 +0200 (CEST) from gaia.elec.ucl.ac.be[130.104.236.1];
from=<mp at elec.ucl.ac.be> to=<pascal.maes at uclouvain.be> proto=SMTP
helo=<gaia.elec.ucl.ac.be>
Aug 12 08:14:50 smtp-2-3 postfix/cleanup[8761]: [ID 197553 mail.info]
EA0A918F9B: message-
id=<20060812061427.EA0A918F9B at smtp-2.dynsipr.ucl.ac.be>
Aug 12 08:14:50 smtp-2-3 clamsmtpd: [ID 842912 mail.info] 100010:
from=mp at elec.ucl.ac.be, to=pascal.maes at uclouvain.be, status=CLEAN
Aug 12 08:14:50 smtp-2-3 postfix/smtpd[8760]: [ID 197553 mail.info]
disconnect from localhost[127.0.0.1]
Aug 12 08:14:51 smtp-2-3 postfix/smtpd[8758]: [ID 197553 mail.info]
disconnect from gaia.elec.ucl.ac.be[130.104.236.1]
1.b) MailScanner is launched in debugging mode
# /opt/MailScanner/bin/MailScanner
In Debugging mode, not forking...
Aug 12 08:16:00 localhost MailScanner[8763]: MailScanner E-Mail Virus
Scanner version 4.55.10 starting...
[8763] dbg: logger: adding facilities: all
[8763] dbg: logger: logging level is DBG
[8763] dbg: generic: SpamAssassin version 3.1.4
[8763] dbg: config: score set 0 chosen.
[8763] dbg: util: running in taint mode? no
[8763] dbg: message: ---- MIME PARSER START ----
[8763] dbg: message: main message type: text/plain
[8763] dbg: message: parsing normal part
[8763] dbg: message: added part, type: text/plain
[8763] dbg: message: ---- MIME PARSER END ----
[8763] dbg: dns: is Net::DNS::Resolver available? yes
[8763] dbg: dns: Net::DNS version: 0.58
[8763] dbg: ignore: test message to precompile patterns and load modules
[8763] dbg: config: using "/etc/mail/spamassassin" for site rules pre
files
[8763] dbg: config: read file /etc/mail/spamassassin/init.pre
[8763] dbg: config: read file /etc/mail/spamassassin/v310.pre
[8763] dbg: config: read file /etc/mail/spamassassin/v312.pre
[8763] dbg: config: using "/usr/local/share/spamassassin" for sys
rules pre files
[8763] dbg: config: using "/usr/local/share/spamassassin" for default
rules dir
[8763] dbg: config: read file /usr/local/share/spamassassin/10_misc.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
20_advance_fee.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
20_anti_ratware.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
20_body_tests.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
20_compensate.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
20_dnsbl_tests.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/20_drugs.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
20_fake_helo_tests.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
20_head_tests.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
20_html_tests.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
20_meta_tests.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
20_net_tests.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
20_phrases.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/20_porn.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
20_ratware.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
20_uri_tests.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/23_bayes.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
25_accessdb.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
25_antivirus.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
25_body_tests_es.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
25_body_tests_pl.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/25_dcc.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/25_dkim.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
25_domainkeys.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
25_hashcash.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/25_pyzor.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/25_razor2.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
25_replace.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/25_spf.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
25_textcat.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/25_uribl.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
30_text_de.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
30_text_fr.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
30_text_it.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
30_text_nl.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
30_text_pl.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
30_text_pt_br.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/50_scores.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/60_awl.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
60_whitelist.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
60_whitelist_dkim.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
60_whitelist_spf.cf
[8763] dbg: config: read file /usr/local/share/spamassassin/
60_whitelist_subject.cf
[8763] dbg: config: using "/etc/mail/spamassassin" for site rules dir
[8763] dbg: config: read file /etc/mail/spamassassin/local.cf
[8763] dbg: config: read file /etc/mail/spamassassin/mailscanner.cf
Aug 12 08:16:02 localhost MailScanner[8763]: Using SpamAssassin
results cache
Aug 12 08:16:02 localhost MailScanner[8763]: Connected to
SpamAssassin cache database
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::URIDNSBL from
@INC
[8763] dbg: plugin: registered
Mail::SpamAssassin::Plugin::URIDNSBL=HASH(0x81bd304)
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::Hashcash from
@INC
[8763] dbg: plugin: registered
Mail::SpamAssassin::Plugin::Hashcash=HASH(0x9c9aea0)
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::SPF from @INC
[8763] dbg: plugin: registered Mail::SpamAssassin::Plugin::SPF=HASH
(0x9cbaa00)
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::DCC from @INC
[8763] dbg: dcc: network tests on, registering DCC
[8763] dbg: plugin: registered Mail::SpamAssassin::Plugin::DCC=HASH
(0x9c9de74)
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::Razor2 from @INC
[8763] dbg: razor2: razor2 is available, version 2.61
[8763] dbg: plugin: registered Mail::SpamAssassin::Plugin::Razor2=HASH
(0x9ca007c)
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::SpamCop from
@INC
[8763] dbg: reporter: network tests on, attempting SpamCop
[8763] dbg: plugin: registered
Mail::SpamAssassin::Plugin::SpamCop=HASH(0xa0aa358)
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::AWL from @INC
[8763] dbg: plugin: registered Mail::SpamAssassin::Plugin::AWL=HASH
(0xa0db39c)
[8763] dbg: plugin: loading
Mail::SpamAssassin::Plugin::AutoLearnThreshold from @INC
[8763] dbg: plugin: registered
Mail::SpamAssassin::Plugin::AutoLearnThreshold=HASH(0xa0e13d8)
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::TextCat from
@INC
[8763] dbg: textcat: loading languages file...
[8763] dbg: textcat: loaded 73 language models
[8763] dbg: plugin: registered
Mail::SpamAssassin::Plugin::TextCat=HASH(0xa0c4658)
[8763] dbg: plugin: loading
Mail::SpamAssassin::Plugin::WhiteListSubject from @INC
[8763] dbg: plugin: registered
Mail::SpamAssassin::Plugin::WhiteListSubject=HASH(0xaac7418)
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::MIMEHeader
from @INC
[8763] dbg: plugin: registered
Mail::SpamAssassin::Plugin::MIMEHeader=HASH(0xaae6eb4)
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::ReplaceTags
from @INC
[8763] dbg: plugin: registered
Mail::SpamAssassin::Plugin::ReplaceTags=HASH(0xaaea380)
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::RelayCountry
from @INC
[8763] dbg: plugin: registered
Mail::SpamAssassin::Plugin::RelayCountry=HASH(0xaaed5ac)
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::URIDNSBL from
@INC
[8763] dbg: plugin: did not register
Mail::SpamAssassin::Plugin::URIDNSBL=HASH(0x9d8cf94), already registered
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::Hashcash from
@INC
[8763] dbg: plugin: did not register
Mail::SpamAssassin::Plugin::Hashcash=HASH(0x9d8cf64), already registered
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::SPF from @INC
[8763] dbg: plugin: did not register
Mail::SpamAssassin::Plugin::SPF=HASH(0xaaea578), already registered
[8763] dbg: plugin: loading Mail::SpamAssassin::Plugin::DKIM from @INC
[8763] dbg: plugin: registered Mail::SpamAssassin::Plugin::DKIM=HASH
(0xab309bc)
... lot of stuff
[8763] dbg: plugin: Mail::SpamAssassin::Plugin::ReplaceTags=HASH
(0xaaea380) implements 'finish_parsing_end'
[8763] dbg: replacetags: replacing tags
[8763] dbg: replacetags: done replacing tags
[8763] dbg: bayes: tie-ing to DB file R/O /var/spool/spamassassin/
bayes_toks
[8763] dbg: bayes: tie-ing to DB file R/O /var/spool/spamassassin/
bayes_seen
[8763] dbg: bayes: found bayes db version 3
[8763] dbg: bayes: DB journal sync: last sync: 1155304906
[8763] dbg: config: score set 3 chosen.
[8763] dbg: message: ---- MIME PARSER START ----
[8763] dbg: message: main message type: text/plain
[8763] dbg: message: parsing normal part
[8763] dbg: message: added part, type: text/plain
[8763] dbg: message: ---- MIME PARSER END ----
... and a lot of info from Spamassassin
[8766] dbg: learn: auto-learn? ham=0.1, spam=8, body-points=0, head-
points=1.477, learned-points=-0.74
[8766] dbg: learn: auto-learn? no: inside auto-learn thresholds, not
considered ham or spam
Ignore errors about failing to find EOCD signature
Aug 12 08:16:18 localhost MailScanner[8763]: Message EA0A918F9B.9CB24
from 127.0.0.1 (mp at elec.ucl.ac.be) to uclouvain.be is n'est pas un
polluriel, SpamAssassin (score=1.612, requis 5, BAYES_20 -0.74,
MSGID_FROM_MTA_ID 1.39, NO_REAL_NAME 0.96, SPF_HELO_PASS -0.00,
SPF_PASS -0.00)
Aug 12 08:16:18 localhost MailScanner[8763]: Virus and Content
Scanning: Starting
Stopping now as you are debugging me.
# Aug 12 08:16:27 localhost MailScanner[8763]: Requeue: EA0A918F9B.
9CB24 to 7754518F9C
Aug 12 08:16:27 localhost MailScanner[8763]: Uninfected: Delivered 1
messages
Aug 12 08:16:27 smtp-2-3 postfix/qmgr[6626]: [ID 197553 mail.info]
7754518F9C: from=<mp at elec.ucl.ac.be>, size=1134, nrcpt=1 (queue active)
Aug 12 08:16:27 localhost MailScanner[8763]: MailScanner child dying
of old age
Aug 12 08:16:27 smtp-2-3 postfix/smtp[8773]: [ID 197553 mail.info]
7754518F9C: to=<pascal.maes at elec.ucl.ac.be>,
orig_to=<pascal.maes at uclouvain.be>, relay=gaia.elec.ucl.ac.be
[130.104.236.1]:25, delay=120, delays=119/0.01/0.04/0.27, dsn=2.0.0,
status=sent (250 2.0.0 k7C6H0RQ011339 Message accepted for delivery)
Aug 12 08:16:27 smtp-2-3 postfix/qmgr[6626]: [ID 197553 mail.info]
7754518F9C: removed
As you see, the message is sent.
2) in "real" mode
2.a) MailScanner is launched (only one child)
# /opt/MailScanner/bin/MailScanner
Aug 12 08:24:26 localhost MailScanner[8820]: MailScanner E-Mail Virus
Scanner version 4.55.10 starting...
Aug 12 08:24:28 localhost MailScanner[8820]: Using SpamAssassin
results cache
Aug 12 08:24:28 localhost MailScanner[8820]: Connected to
SpamAssassin cache database
2.b) a message has been sent
Aug 12 08:25:20 smtp-2-3 postfix/smtpd[8821]: [ID 197553 mail.info]
connect from gaia.elec.ucl.ac.be[130.104.236.1]
Aug 12 08:25:31 smtp-2-3 clamsmtpd: [ID 739282 mail.info] 100011:
accepted connection from: 127.0.0.1
Aug 12 08:25:31 smtp-2-3 postfix/smtpd[8824]: [ID 197553 mail.info]
connect from localhost[127.0.0.1]
Aug 12 08:25:31 smtp-2-3 postfix/smtpd[8821]: [ID 197553 mail.info]
NOQUEUE: client=gaia.elec.ucl.ac.be[130.104.236.1]
Aug 12 08:25:31 smtp-2-3 postfix/smtpd[8824]: [ID 197553 mail.info]
CA55418F9B: client=gaia.elec.ucl.ac.be[130.104.236.1]
Aug 12 08:25:37 smtp-2-3 postfix/cleanup[8825]: [ID 197553 mail.info]
CA55418F9B: hold: header Received: from smtp-2.dynsipr.ucl.ac.be
(localhost [127.0.0.1])??by smtp-2.dynsipr.ucl.ac.be (Postfix) with
ESMTP id CA55418F9B??for <pascal.maes at uclouvain.be>; Sat, 12 Aug 2006
08:25:31 +0200 (CEST) from gaia.elec.ucl.ac.be[130.104.236.1];
from=<mp at elec.ucl.ac.be> to=<pascal.maes at uclouvain.be> proto=SMTP
helo=<gaia.elec.ucl.ac.be>
Aug 12 08:25:37 smtp-2-3 postfix/cleanup[8825]: [ID 197553 mail.info]
CA55418F9B: message-
id=<20060812062531.CA55418F9B at smtp-2.dynsipr.ucl.ac.be>
Aug 12 08:25:38 smtp-2-3 clamsmtpd: [ID 847008 mail.info] 100011:
from=mp at elec.ucl.ac.be, to=pascal.maes at uclouvain.be, status=CLEAN
Aug 12 08:25:38 smtp-2-3 postfix/smtpd[8824]: [ID 197553 mail.info]
disconnect from localhost[127.0.0.1]
Aug 12 08:25:41 smtp-2-3 postfix/smtpd[8821]: [ID 197553 mail.info]
disconnect from gaia.elec.ucl.ac.be[130.104.236.1]
# ps -ef | grep MailScanner
postfix 8835 2400 0 08:26:59 ? 0:00 /usr/bin/perl -I/
opt/MailScanner/lib /opt/MailScanner/bin/MailScanner
postfix 8836 8835 34 08:26:59 ? 0:25 /usr/bin/perl -I/
opt/MailScanner/lib /opt/MailScanner/bin/MailScanner
but the message remains in the queue
# ls -l /var/spool/postfix/hold/C
total 4
-rwx------ 1 postfix postfix 1212 Aug 12 08:25 CA55418F9B*
Another strange thing is that MailScanner is comsumming CPU :
# date ; ps -ef | grep MailScanner
Sat Aug 12 08:34:23 CEST 2006
root 8860 8715 0 08:34:24 pts/4 0:00 grep MailScanner
postfix 8835 2400 0 08:26:59 ? 0:00 /usr/bin/perl -I/
opt/MailScanner/lib /opt/MailScanner/bin/MailScanner
postfix 8836 8835 50 08:26:59 ? 7:23 /usr/bin/perl -I/
opt/MailScanner/lib /opt/MailScanner/bin/MailScanner
# top
load averages: 1.71, 75.23,
74.48
08:34:40
45 processes: 42 sleeping, 3 on cpu
CPU states: 49.4% idle, 50.2% user, 0.4% kernel, 0.0% iowait, 0.0%
swap
Memory: 2047M real, 1140M free, 647M swap in use, 2854M swap free
PID USERNAME LWP PRI NICE SIZE RES STATE TIME CPU COMMAND
8836 postfix 1 10 0 85M 73M cpu/1 7:40 49.91%
MailScanner
8861 root 1 59 0 3176K 1216K cpu/0 0:00 0.02% top
--
Pascal
More information about the MailScanner
mailing list