Hello Folks,
I have a MTA setup of [Postfix + Amavis-new + ClamAV + Spamassasin] of
which only the spamassasin part is disabled. Now i wish to enable the
Spamcontrol part.
But after enabling the spamassasin option in amavis-new, it shows the below
mentioned error.
*(!!)SA failed: Can't locate object method "get_tag" via package
"Mail::SpamAssassin::PerMsgStatus" at (eval 86) line 425, <GEN6> line 29.
at (eval 86) line 467, <GEN6> line 29*.
Also the above line number, does is refer to "spamd" ?
I have already checked the mailing-list for such errors but none are
referring to my case here.
Any help is to direct me towards solving the case would be appreciated.
My Setup details:
Postfix version: 2.7.3
Amavis-new version : 2.6.4-4
Spamassasin version : SpamAssassin version 3.0.1 running on Perl version
5.8.5
[root@host spamassassin]# cat /etc/sysconfig/spamassassin
# Options to spamd
SPAMDOPTIONS="-d -c -m5 -H"
[root@host spamassassin]# cat local.cf
# These values can be overridden by editing ~/.spamassassin/user_prefs.cf
# (see spamassassin(1) for details)
# These should be safe assumptions and allow for simple visual sifting
# without risking lost emails.
required_hits 5
report_safe 0
rewrite_header Subject [SPAM]
[root@host spamassassin]# ps -elf | grep spam
5 S root 29836 1 46 81 0 - 7184 pause 09:38 ? 00:00:00
/usr/bin/spamd -d -c -m5 -H
1 S root 29839 29836 0 78 0 - 7184 - 09:38 ? 00:00:00
spamd child
1 S root 29840 29836 0 78 0 - 7184 - 09:38 ? 00:00:00
spamd child
1 S root 29841 29836 0 81 0 - 7184 - 09:38 ? 00:00:00
spamd child
1 S root 29842 29836 0 81 0 - 7184 - 09:38 ? 00:00:00
spamd child
1 S root 29843 29836 0 81 0 - 7184 - 09:38 ? 00:00:00
spamd child
4 R root 29845 28512 0 78 0 - 1171 - 09:38 pts/2 00:00:00
grep spam
Please find attached the debug info of a message trace for the error
mentioned.
Please let me know if any other additional detail is required
With Regards
Anirudha Patil
mobile no: 9221306620
email-id: anirudha.pa...@hotmail.com
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) SMTP> 220 [127.0.0.1]
ESMTP amavisd-new service ready
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) SMTP< EHLO myhostname\r\n
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP> 250-[127.0.0.1]
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP> 250-VRFY
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP> 250-PIPELINING
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP> 250-SIZE
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP>
250-ENHANCEDSTATUSCODES
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP> 250-8BITMIME
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP> 250-DSN
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP> 250 XFORWARD NAME
ADDR PORT PROTO HELO SOURCE
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP< XFORWARD
NAME=myhostname ADDR=127.0.0.1 PORT=32859\r\n
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP> 250 2.5.0 Ok
XFORWARD
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP< XFORWARD
PROTO=ESMTP HELO=mydomain SOURCE=LOCAL\r\n
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP> 250 2.5.0 Ok
XFORWARD
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP< MAIL
FROM:<anirudha@myhostname> SIZE=445\r\n
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) check_mail_begin_task:
task_count=1
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) TempDir::prepare: creating
directory /var/amavis/tmp/amavis-20130211T090908-29615
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) TempDir::prepare_file:
creating file /var/amavis/tmp/amavis-20130211T090908-29615/email.txt
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) lookup_ip_acl:
key="127.0.0.1" matches "127.0.0.0/8", result=1
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) loaded policy bank "MYNETS"
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) lookup [debug_sender] =>
undef, "anirudha@myhostname" does not match
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP> 250 2.1.0 Sender
<anirudha@myhostname> OK
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP< RCPT
TO:<myuser@mydomain> ORCPT=rfc822;myuser@mydomain\r\n
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP> 250 2.1.5 Recipient
<myuser@mydomain> OK
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP< DATA\r\n
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP::10024
/var/amavis/tmp/amavis-20130211T090908-29615: <anirudha@myhostname> ->
<myuser@mydomain> SIZE=445 Received: from myhostname ([127.0.0.1]) by localhost
(myhostn...@apl.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for
<myuser@mydomain>; Mon, 11 Feb 2013 09:09:08 -0500 (EST)
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP> 354 End data with
<CR><LF>.<CR><LF>
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ESMTP< .<CR><LF>
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) body type (ESMTP BODY):
unlabeled, good (h=0, b=0)
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) body hash:
4dea7466963bd8fc5b083eebd62494a9
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) Original mail size: 445;
quota set to: 222500 bytes
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) Checking: zV1thM+SxmOf
MYNETS [127.0.0.1] <anirudha@myhostname> -> <myuser@mydomain>
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) 2822.From:
<anirudha@myhostname>
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) lookup [local_domains] =>
true, "myuser@mydomain" matches, result="1", matching_key=".mydomain"
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) lookup
[bypass_virus_checks] => undef, "myuser@mydomain" does not match
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) lookup
[bypass_banned_checks] => undef, "myuser@mydomain" does not match
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) lookup
[bypass_spam_checks] => undef, "myuser@mydomain" does not match
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) Extracting mime components
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) Issued a new file name:
p001
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) Charging 60 bytes to
remaining quota 222500 (out of 222500, (0%)) - by mime_decode
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) p001 1 Content-Type:
text/plain, size: 60 B, name:
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) decode_parts: level=1,
#parts=1 : p001
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) lookup
[map_full_type_to_short_type] => true, "ASCII text" matches, result="asc",
matching_key="(?i-xsm:^(ASCII|text)\\b)"
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) File-type of p001: ASCII
text; (asc)
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) do_ascii: Decoding part
p001
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) do_ascii: Setting
sigaction handler, was 0
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) do_ascii: Decoding part
p001 (0 items), uulib V0.5pl20
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) decompose_part: p001 -
atomic
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) lookup
[bypass_header_checks] => undef, "myuser@mydomain" does not match
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) lookup
[bypass_header_checks] => undef, "myuser@mydomain" does not match
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) Checking for banned types
and filenames
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) lookup [banned_filename],
1 matches for "myuser@mydomain", results: "(constant:DEFAULT)"=>"DEFAULT"
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) collect banned table[0]:
myuser@mydomain, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0xa299e28)
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) starting banned checks -
traversing message structure tree
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) check_for_banned (p001)
text/plain,.asc
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) lookup
[check_bann:myuser@mydomain] => undef, ["text/plain",".asc"] does not match
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) lookup
[banned_namepath_re] => undef, "P=p001\tL=1\tM=text/plain\tT=asc" does not match
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) p.path myuser@mydomain:
"P=p001,L=1,M=text/plain,T=asc"
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) banned check: any=0, all=N
(1)
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) lookup
[keep_decoded_original] => true, "MAIL" matches, result="1",
matching_key="(?-xism:^MAIL$)"
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) Issued a new file name:
p002
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) presenting full original
message to scanners as /var/amavis/tmp/amavis-20130211T090908-29615/parts/p002
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ask_av Using
(ClamAV-clamd): CONTSCAN /var/amavis/tmp/amavis-20130211T090908-29615/parts\n
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ClamAV-clamd: Connecting
to socket /tmp/clamd.socket
Feb 11 09:09:08 myhostname amavis[29615]: (29615-01) ClamAV-clamd: Sending
CONTSCAN /var/amavis/tmp/amavis-20130211T090908-29615/parts\n to UNIX socket
/tmp/clamd.socket
Feb 11 09:09:10 myhostname amavis[29615]: (29615-01) ask_av (ClamAV-clamd)
result: /var/amavis/tmp/amavis-20130211T090908-29615/parts: OK\n
Feb 11 09:09:10 myhostname amavis[29615]: (29615-01) run_av (ClamAV-clamd):
CLEAN
Feb 11 09:09:10 myhostname amavis[29615]: (29615-01) run_av (ClamAV-clamd)
result: clean
Feb 11 09:09:10 myhostname amavis[29615]: (29615-01) wbl: checking sender
<anirudha@myhostname>
Feb 11 09:09:10 myhostname amavis[29615]: (29615-01) lookup
[blacklist_recip<myuser@mydomain>] => undef, "myuser@mydomain" does not match
Feb 11 09:09:10 myhostname amavis[29615]: (29615-01) lookup
[blacklist_sender<anirudha@myhostname>,blacklist_sender] => undef,
"anirudha@myhostname" does not match
Feb 11 09:09:10 myhostname amavis[29615]: (29615-01) lookup
[whitelist_recip<myuser@mydomain>] => undef, "myuser@mydomain" does not match
Feb 11 09:09:10 myhostname amavis[29615]: (29615-01) lookup
[whitelist_sender<anirudha@myhostname>,whitelist_sender] => undef,
"anirudha@myhostname" does not match
Feb 11 09:09:10 myhostname amavis[29615]: (29615-01) lookup
[score_recip<myuser@mydomain>,score_sender], 1 matches for "myuser@mydomain",
results: "."=>[Amavis::Lookup::RE=ARRAY(0xa33a0e8),HASH(0xa33a154)]
Feb 11 09:09:10 myhostname amavis[29615]: (29615-01) lookup
[score_sender<anirudha@myhostname>] => undef, "anirudha@myhostname" does not
match
Feb 11 09:09:10 myhostname amavis[29615]: (29615-01) CALLING SA check
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) (!!)SA failed: Can't
locate object method "get_tag" via package "Mail::SpamAssassin::PerMsgStatus"
at (eval 86) line 425, <GEN6> line 29. at (eval 86) line 467, <GEN6> line 29.
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) spam_scan: score=
autolearn= tests=[]
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) lookup [spam_tag_level] =>
true, "myuser@mydomain" matches, result="2", matching_key="(constant:2)"
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) lookup [spam_tag2_level]
=> true, "myuser@mydomain" matches, result="6.2", matching_key="(constant:6.2)"
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) lookup [spam_tag3_level]
=> undef, "myuser@mydomain" does not match
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) lookup [spam_kill_level]
=> true, "myuser@mydomain" matches, result="6.9", matching_key="(constant:6.9)"
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) do_notify_and_quar:
ccat=Clean (1,0) ("1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) skip admin notification,
no administrators
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) lookup [spam_tag_level] =>
true, "myuser@mydomain" matches, result="2", matching_key="(constant:2)"
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) lookup [spam_tag2_level]
=> true, "myuser@mydomain" matches, result="6.2", matching_key="(constant:6.2)"
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) lookup
[spam_modifies_subj] => true, "myuser@mydomain" matches, result="1",
matching_key="(constant:1)"
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) headers CLUSTERING: NEW
CLUSTER <myuser@mydomain>: score=x, tag=0, tag2=0, local=1, bl=, s=, mangle=
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) (about to connect to
[127.0.0.1]:10025) FWD via SMTP: <anirudha@myhostname> -> <myuser@mydomain>
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) smtp session: setting up a
new session
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) smtp creating socket by
IO::Socket::INET to [127.0.0.1]:10025
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) smtp resp to greeting: 220
myhostname ESMTP Postfix
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) smtp cmd> EHLO localhost
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) smtp resp to EHLO: 250
myhostname\nPIPELINING\nSIZE
20971520\nVRFY\nETRN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) AUTH not needed, user='',
MTA offers ''
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) smtp cmd> MAIL
FROM:<anirudha@myhostname> BODY=7BIT
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) smtp cmd> RCPT
TO:<myuser@mydomain> ORCPT=rfc822;myuser@mydomain
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) smtp cmd> DATA
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) smtp resp to MAIL (pip):
250 2.1.0 Ok
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) smtp resp to RCPT (pip)
(<myuser@mydomain>): 250 2.1.5 Ok
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) smtp resp to DATA: 354 End
data with <CR><LF>.<CR><LF>
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) smtp resp to data-dot
(<myuser@mydomain>): 250 2.0.0 Ok: queued as BD3BA78072
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) Amavis::Out::SMTP::Session
close, keeping connection
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) FWD via SMTP:
<anirudha@myhostname> -> <myuser@mydomain>,BODY=7BIT 250 2.0.0 Ok, id=29615-01,
from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as BD3BA78072
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) DSN: sender is credible
(orig), SA: 0.000, <anirudha@myhostname>
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) lookup => true,
"anirudha@myhostname" matches, result="18", matching_key="(constant:18)"
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) notif=N, suppressed=0,
ndn_needed=0, exit=0, 250 2.0.0 Ok, id=29615-01, from MTA([127.0.0.1]:10025):
250 2.0.0 Ok: queued as BD3BA78072
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) lookup_ip_acl
(publicnetworks): key="127.0.0.1" matches "!127.0.0.0/8", result=0
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) Passed CLEAN, MYNETS LOCAL
[127.0.0.1] [127.0.0.1] <anirudha@myhostname> -> <myuser@mydomain>, Message-ID:
<20130211140842.7D47C7806E@myhostname>, mail_id: zV1thM+SxmOf, Hits: -, size:
445, queued_as: BD3BA78072, 9805 ms
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) sending SMTP response:
"250 2.0.0 Ok, id=29615-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued
as BD3BA78072"
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) ESMTP> 250 2.0.0 Ok,
id=29615-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as BD3BA78072
Feb 11 09:09:17 myhostname postfix/smtp[29646]: 7D47C7806E:
to=<myuser@mydomain>, relay=127.0.0.1[127.0.0.1]:10024, delay=42,
delays=33/0.04/0.03/9.8, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=29615-01,
from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as BD3BA78072)
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) TempDir::strip:
/var/amavis/tmp/amavis-20130211T090908-29615
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) rmdir_recursively:
/var/amavis/tmp/amavis-20130211T090908-29615/parts, excl=1
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) TIMING [total 9812 ms] -
SMTP greeting: 22 (0%)0, SMTP EHLO: 2 (0%)0, SMTP pre-MAIL: 2 (0%)0, mkdir
tempdir: 1 (0%)0, create email.txt: 1 (0%)0, SMTP pre-DATA-flush: 7 (0%)0, SMTP
DATA: 39 (0%)1, check_init: 2 (0%)1, digest_hdr: 1 (0%)1, digest_body: 1 (0%)1,
gen_mail_id: 3 (0%)1, mkdir parts: 3 (0%)1, mime_decode: 27 (0%)1,
get-file-type1: 109 (1%)2, decompose_part: 3 (0%)2, parts_decode: 0 (0%)2,
check_header: 2 (0%)2, AV-scan-1: 2357 (24%)26, spam-wb-list: 4 (0%)26, SA
parse: 5 (0%)26, SA check: 7140 (73%)99, update_cache: 14 (0%)99,
decide_mail_destiny: 2 (0%)99, fwd-connect: 28 (0%)100, fwd-mail-pip: 3
(0%)100, fwd-rcpt-pip: 0 (0%)100, fwd-data-chkpnt: 0 (0%)100, write-header: 1
(0%)100, fwd-data-contents: 0 (0%)100, fwd-end-chkpnt: 7 (0%)100, prepare-dsn:
2 (0%)100, main_log_entry: 20 (0%)100, update_snmp: 3 (0%)100, SMTP
pre-response: 0 (0%)100, SMTP response: 1 (0%)100, unlink-2-files: 1 (0%)100,
rundown: 1 (0%)100
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) ESMTP< QUIT\r\n
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) ESMTP> 221 2.0.0
[127.0.0.1] amavisd-new closing transmission channel
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) SMTP session over, timer
stopped
Feb 11 09:09:17 myhostname amavis[29615]: (29615-01) load: 100 %, total idle
0.000 s, busy 9.817 s
