Amavisd routinely fails to correctly tag Spam via SpamAssassin calls
Quanah Gibson-Mount via amavis-users
amavis-users at amavis.org
Fri Mar 14 20:07:48 CET 2014
This started in a thread on the spamassassin-users list. Multiple people
are finding that Amavis is failing to consistently score spam via
SpamAssassin. Even the logging from Amavis is completely inconsistent,
making this particularly difficult to debug. This appears to affect
multiple versions of Amavis. Help appreciated. In effect, I'm getting
hundreds if not thousands of emails a day that SpamAssassin sees as spam if
run externally from Amavis, but because Amavis is failing to fully run SA,
are getting through. See notes at end on one example email that is clearly
spam.
I've increased my Amavis logging, and the sa_debug level logging that
Amavis passes to SA as well. I'm seeing some really odd things. As I have
dbg logging set, I would expect to see a ton of information coming from
SpamAssassin via Amavis. However, a lot of the time all I ever see is:
Mar 14 13:39:47 edge02 amavis[43522]: (42764-03) SA dbg: util: setuid:
ruid=496 euid=496
Mar 14 13:39:49 edge02 amavis[43531]: (35016-20) SA dbg: util: setuid:
ruid=496 euid=496
Mar 14 13:39:49 edge02 amavis[43532]: (40498-08) SA dbg: util: setuid:
ruid=496 euid=496
That's it. Nothing about what SA did once forked by Amavis. It is like
Amavis is losing the SA child.
Occasionally, I actually see full results, like:
Mar 14 13:39:41 edge02 amavis[43497]: (41774-05) SA dbg: util: setuid:
ruid=496 euid=496
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: calling
callback on key dns:MX:zimbra.com
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: hit
<dns:zimbra.com?type=MX> 20 edge02.zimbra.com.
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: hit
<dns:zimbra.com?type=MX> 10 mail.zimbra.com.
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: hit
<dns:zimbra.com?type=MX> 20 edge01.zimbra.com.
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: dns reply
60797 is OK, 1 answer records
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: calling
callback on key A:ns.rackspace.com
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: uridnsbl:
complete_a_lookup A:ns.rackspace.com
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: uridnsbl:
complete_a_lookup got(1) A for ns.rackspace.com: ns.rackspace.com. 167110
IN A 69.20.95.4
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: launching
A/4.95.20.69.sbl.spamhaus.org for DNSBL:4.95.20.69:sbl.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: bgsend, DNS
servers: [127.0.0.1]:53, [10.110.0.108]:53, [10.110.0.109]:53,
[10.210.0.166]:53, [10.110.0.196]:53, [10.110.0.197]
:53
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: attempt 1/6,
trying connect/sendto to [127.0.0.1]:53
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: providing a
callback for id: 65391/IN/A/4.95.20.69.sbl.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: starting:
URIBL_SBL_A, URI-DNSBL, DNSBL:4.95.20.69:sbl.spamhaus.org (timeout 15.0s,
min 3.0s)
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: launching
A/4.95.20.69.zen.spamhaus.org for DNSBL:4.95.20.69:zen.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: bgsend, DNS
servers: [127.0.0.1]:53, [10.110.0.108]:53, [10.110.0.109]:53,
[10.210.0.166]:53, [10.110.0.196]:53, [10.110.0.197]
:53
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: attempt 1/6,
trying connect/sendto to [127.0.0.1]:53
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: providing a
callback for id: 17284/IN/A/4.95.20.69.zen.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: starting:
URIBL_SBL, URI-DNSBL, DNSBL:4.95.20.69:zen.spamhaus.org (timeout 15.0s, min
3.0s)
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: dns reply
2480 is OK, 1 answer records
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: calling
callback on key A:ns2.rackspace.com
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: uridnsbl:
complete_a_lookup A:ns2.rackspace.com
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: uridnsbl:
complete_a_lookup got(1) A for ns2.rackspace.com: ns2.rackspace.com. 167110
IN A 65.61.188.4
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: launching
A/4.188.61.65.zen.spamhaus.org for DNSBL:4.188.61.65:zen.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: bgsend, DNS
servers: [127.0.0.1]:53, [10.110.0.108]:53, [10.110.0.109]:53,
[10.210.0.166]:53, [10.110.0.196]:53, [10.110.0.197]
:53
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: attempt 1/6,
trying connect/sendto to [127.0.0.1]:53
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: providing a
callback for id: 39622/IN/A/4.188.61.65.zen.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: starting:
URIBL_SBL, URI-DNSBL, DNSBL:4.188.61.65:zen.spamhaus.org (timeout 15.0s,
min 3.0s)
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: dns reply to
47531/IN/A/88.1.80.10.sbl.spamhaus.org: NXDOMAIN
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: calling
callback on key DNSBL:88.1.80.10:sbl.spamhaus.org, rule URIBL_SBL_A
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: uridnsbl:
complete_dnsbl_lookup URIBL_SBL_A DNSBL:88.1.80.10:sbl.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: calling
callback on key DNSBL:88.1.80.10:sbl.spamhaus.org, rule URIBL_SBL_A
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: uridnsbl:
complete_dnsbl_lookup URIBL_SBL_A DNSBL:88.1.80.10:sbl.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: dns reply to
40568/IN/A/88.1.80.10.zen.spamhaus.org: NXDOMAIN
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: calling
callback on key DNSBL:88.1.80.10:zen.spamhaus.org, rule URIBL_SBL
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: uridnsbl:
complete_dnsbl_lookup URIBL_SBL DNSBL:88.1.80.10:zen.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: calling
callback on key DNSBL:88.1.80.10:zen.spamhaus.org, rule URIBL_SBL
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: uridnsbl:
complete_dnsbl_lookup URIBL_SBL DNSBL:88.1.80.10:zen.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: dns reply to
65391/IN/A/4.95.20.69.sbl.spamhaus.org: NXDOMAIN
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: calling
callback on key DNSBL:4.95.20.69:sbl.spamhaus.org, rule URIBL_SBL_A
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: uridnsbl:
complete_dnsbl_lookup URIBL_SBL_A DNSBL:4.95.20.69:sbl.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: dns reply to
17284/IN/A/4.95.20.69.zen.spamhaus.org: NXDOMAIN
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: calling
callback on key DNSBL:4.95.20.69:zen.spamhaus.org, rule URIBL_SBL
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: uridnsbl:
complete_dnsbl_lookup URIBL_SBL DNSBL:4.95.20.69:zen.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: dns reply to
29905/IN/A/4.188.61.65.sbl.spamhaus.org: NXDOMAIN
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: calling
callback on key DNSBL:4.188.61.65:sbl.spamhaus.org, rule URIBL_SBL_A
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: uridnsbl:
complete_dnsbl_lookup URIBL_SBL_A DNSBL:4.188.61.65:sbl.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: dns reply to
39622/IN/A/4.188.61.65.zen.spamhaus.org: NXDOMAIN
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: calling
callback on key DNSBL:4.188.61.65:zen.spamhaus.org, rule URIBL_SBL
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: uridnsbl:
complete_dnsbl_lookup URIBL_SBL DNSBL:4.188.61.65:zen.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: select
found no responses ready (t.o.=0.0)
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.005 s: URIBL_SBL_A, URI-DNSBL, DNSBL:4.188.61.65:sbl.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.024 s: URI-A, A:ns.rackspace.com
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.031 s: URIBL_DBL_ERROR, URI-DNSBL, DNSBL:zimbra.com:dbl.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.037 s: DNSBL-A, dns:A:zimbra.com.rhsbl.ahbl.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.006 s: URIBL_SBL, URI-DNSBL, DNSBL:4.95.20.69:zen.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.025 s: URIBL_PH_SURBL, URI-DNSBL, DNSBL:zimbra.com:multi.surbl.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.007 s: URIBL_SBL_A, URI-DNSBL, DNSBL:4.95.20.69:sbl.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.005 s: URIBL_SBL, URI-DNSBL, DNSBL:4.188.61.65:zen.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.026 s: URI-NS, NS:zimbra.com
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.028 s: URI-A, A:bugzilla.zimbra.com
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.037 s: URI-A, A:zimbra.com
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.024 s: URIBL_BLACK, URI-DNSBL, DNSBL:zimbra.com:multi.uribl.com
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.020 s: URIBL_SBL, URI-DNSBL, DNSBL:88.1.80.10:zen.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.031 s: NO_DNS_FOR_FROM, DNSBL-MX, dns:MX:zimbra.com
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.026 s: URI-A, A:ns2.rackspace.com
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.032 s: URIBL_RHS_DOB, URI-DNSBL,
DNSBL:zimbra.com:dob.sibl.support-intelligence.net
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: async: completed
in 0.021 s: URIBL_SBL_A, URI-DNSBL, DNSBL:88.1.80.10:sbl.spamhaus.org
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: dns: harvested
completed queries
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: rules: running
head tests; score so far=0
Mar 14 13:39:46 edge02 amavis[42741]: (42741-05) SA dbg: rules: running
head_eval tests; score so far=0
(etc)
I even logged a definite SPAM that went in, and there was no report from
Amavis that it was ever even scanned by SpamAssassin AT ALL, yet the end
email had a FEW headers:
X-Virus-Scanned: amavisd-new at edge02.zimbra.com
X-Spam-Flag: NO
X-Spam-Score: 0.79
X-Spam-Level:
X-Spam-Status: No, score=0.79 tagged_above=-10 required=3
tests=[BAYES_50=0.8,
T_RP_MATCHES_RCVD=-0.01] autolearn=ham autolearn_force=no
This is the trace on that email:
Mar 14 13:31:37 edge02 postfix/smtpd[32533]: NOQUEUE: filter: RCPT from
mx3-in.elmodd.com[208.123.118.136]: <GiovanniMiles at mx3-in.elmodd.com>:
Sender address triggers FILTER smtp-amavis:[127.0.0.1]:10026;
from=<GiovanniMiles at mx3-in.elmodd.com> to=<abc at zimbra.com> proto=ESMTP
helo=<mx3-in.elmodd.com>
Mar 14 13:31:37 edge02 postfix/smtpd[32533]: NOQUEUE: filter: RCPT from
mx3-in.elmodd.com[208.123.118.136]: <GiovanniMiles at mx3-in.elmodd.com>:
Sender address triggers FILTER smtp-amavis:[127.0.0.1]:10024;
from=<GiovanniMiles at mx3-in.elmodd.com> to=<abc at zimbra.com> proto=ESMTP
helo=<mx3-in.elmodd.com>
Mar 14 13:31:37 edge02 postfix/smtpd[32533]: 19DECA62B7:
client=mx3-in.elmodd.com[208.123.118.136]
Mar 14 13:31:37 edge02 postfix/cleanup[33471]: 19DECA62B7:
message-id=<746.20140314170846.8946.12975. at server6.mx3-in.elmodd.com.mail>
Mar 14 13:31:37 edge02 postfix/qmgr[9903]: 19DECA62B7:
from=<GiovanniMiles at mx3-in.elmodd.com>, size=2601, nrcpt=1 (queue active)
Mar 14 13:31:37 edge02 amavis[35017]: (35017-11) Net::Server:
2014/03/14-13:31:37 CONNECT TCP Peer: "[127.0.0.1]:60552" Local:
"[127.0.0.1]:10024"
Mar 14 13:31:37 edge02 amavis[35017]: idle_proc, hi : was idle, 43562.0 ms,
total idle 234.991 s, busy 13.708 s
Mar 14 13:31:37 edge02 amavis[35017]: loaded base policy bank
Mar 14 13:31:37 edge02 amavis[35017]: lookup_ip_acl (inet_acl) arr.obj:
key="127.0.0.1" matches "127.0.0.1", result=1
Mar 14 13:31:37 edge02 amavis[35017]: process_request: fileno sock=20,
STDIN=0, STDOUT=1
Mar 14 13:31:37 edge02 amavis[35017]: get_deadline switch_to_my_time(new
request) - deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: prolong_timer switch_to_my_time(new
request): timer 336, was 0, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: process_request:
suggested_protocol="" on a TCP socket
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) SMTP> 220 [127.0.0.1]
ESMTP amavisd-new service ready
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) switch_to_client_time 480
s, smtp response sent
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) idle_proc, 4: was busy,
3.3 ms, total idle 234.991 s, busy 13.711 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) smtp readline: read 24
bytes, new size: 24
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) idle_proc, 5: was idle,
0.4 ms, total idle 234.992 s, busy 13.711 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) SMTP< EHLO
edge02.zimbra.com\r\n
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline
switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer
switch_to_my_time(rx SMTP EHLO): timer 336, was 480, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP> 250-[127.0.0.1]
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP> 250-VRFY
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP> 250-PIPELINING
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP> 250-SIZE
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP>
250-ENHANCEDSTATUSCODES
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP> 250-8BITMIME
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP> 250-DSN
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP> 250 XFORWARD NAME
ADDR PORT PROTO HELO IDENT SOURCE
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) switch_to_client_time 480
s, smtp response sent
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) idle_proc, 6: was busy,
2.5 ms, total idle 234.992 s, busy 13.714 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) smtp readline: read 260
bytes, new size: 260
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) idle_proc, 5: was idle,
0.4 ms, total idle 234.992 s, busy 13.714 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP< XFORWARD
NAME=mx3-in.elmodd.com ADDR=208.123.118.136 PORT=59493\r\n
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline
switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer
switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP> 250 2.5.0 Ok
XFORWARD
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) switch_to_client_time 480
s, smtp response sent
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) idle_proc, 6: was busy,
1.2 ms, total idle 234.992 s, busy 13.715 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) idle_proc, 5: was idle,
0.2 ms, total idle 234.992 s, busy 13.715 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP< XFORWARD
PROTO=ESMTP HELO=mx3-in.elmodd.com IDENT=19DECA62B7 SOURCE=REMOTE\r\n
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline
switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer
switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP> 250 2.5.0 Ok
XFORWARD
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) switch_to_client_time 480
s, smtp response sent
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) idle_proc, 6: was busy,
1.4 ms, total idle 234.992 s, busy 13.716 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) idle_proc, 5: was idle,
0.2 ms, total idle 234.992 s, busy 13.716 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP< MAIL
FROM:<GiovanniMiles at mx3-in.elmodd.com> SIZE=2601\r\n
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline
switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer
switch_to_my_time(rx SMTP MAIL): timer 336, was 480, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) check_mail_begin_task:
task_count=12
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup_ip_acl
(client_ipaddr_policy) arr.obj: key="208.123.118.136", no match
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup [debug_sender] =>
undef, "GiovanniMiles at mx3-in.elmodd.com" does not match
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) mesage size set to a
declared size 2601
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP> 250 2.1.0 Sender
<GiovanniMiles at mx3-in.elmodd.com> OK
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) switch_to_client_time 480
s, smtp response sent
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) idle_proc, 6: was busy,
2.6 ms, total idle 234.992 s, busy 13.719 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) idle_proc, 5: was idle,
0.1 ms, total idle 234.992 s, busy 13.719 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP< RCPT
TO:<xyz at zimbra.com> ORCPT=rfc822;abc at zimbra.com\r\n
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline
switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer
switch_to_my_time(rx SMTP RCPT): timer 336, was 480, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup => undef,
"xyz at zimbra.com", no lookup tables
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_acl(xyz at zimbra.com), no match
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup [local_domains] =>
undef, "xyz at zimbra.com" does not match
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) query_keys:
xyz at zimbra.com, @zimbra.com, @.zimbra.com, zimbra.com, @.com, com, @.
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup_ldap
"xyz at zimbra.com", query keys: "xyz at zimbra.com", "@zimbra.com",
"@.zimbra.com", "zimbra.com", "@.com", "com", "@.", base: , filter:
(&(objectClass=amavisAccount)(zimbraMailStatus=enabled)(|(mail=%m)(zimbraDomainName=%m)))
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ldap begin_work
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup_ldap: searching
base="", scope="sub",
filter="(&(objectClass=amavisAccount)(zimbraMailStatus=enabled)(|(|(mail=xyz at zimbra.com)(mail=@zimbra.com)(mail=@.zimbra.com)(mail=zimbra.com)(mail=@.com)(mail=com)(mail=@.))(|(zimbraDomainName=xyz at zimbra.com)(zimbraDomainName=@zimbra.com)(zimbraDomainName=@.zimbra.com)(zimbraDomainName=zimbra.com)(zimbraDomainName=@.com)(zimbraDomainName=com)(zimbraDomainName=@.))))"
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap(xyz at zimbra.com) matches,
result=(dn=>"uid=xyz,ou=people,dc=zimbra,dc=com")
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap(xyz at zimbra.com) matches, result=(dn=>"dc=zimbra,dc=com")
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisMessageSizeLimit) rec=0, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisMessageSizeLimit) rec=1, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup_ldap_attr, no such
attrs: amavisMessageSizeLimit
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup
[message_size_limit] => undef, "xyz at zimbra.com" does not match
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP> 250 2.1.5 Recipient
<xyz at zimbra.com> OK
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) switch_to_client_time 480
s, smtp response sent
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) idle_proc, 6: was busy,
7.2 ms, total idle 234.992 s, busy 13.726 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) idle_proc, 5: was idle,
0.1 ms, total idle 234.993 s, busy 13.726 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP< DATA\r\n
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline
switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer
switch_to_my_time(rx SMTP DATA): timer 336, was 480, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP:[127.0.0.1]:10024
/opt/zimbra/data/amavisd/tmp/amavis-20140314T132728-35017-vRRaownX:
<GiovanniMiles at mx3-in.elmodd.com> -> <xyz at zimbra.com> SIZE=2601 Received:
from edge02.zimbra.com ([127.0.0.1]) by localhost (edge02.zimbra.com
[127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <xyz at zimbra.com>;
Fri, 14 Mar 2014 13:31:37 -0500 (CDT)
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP> 354 End data with
<CR><LF>.<CR><LF>
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) switch_to_client_time 480
s, smtp response sent
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) switch_to_client_time 480
s, receiving data
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) smtp copy: read 2577 bytes
into buffer, new size: 2577
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) smtp copy: 6 bytes still
buffered at end
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline
switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer
switch_to_my_time(rx data-end): timer 336, was 480, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ESMTP< .<CR><LF>
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) Actual message size 2568 B
less than the declared 2601 B
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) smtp connection cache, dt:
43.6, state: 0
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline
get_body_digest - deadline in 480.0 s, set to 30.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline digest_pre -
deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer digest_pre:
timer 336, was 336, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_body_digest: reading
header section from memory
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_body_digest: sending
h/b separator to DKIM
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline digest_hdr -
deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer digest_hdr:
timer 336, was 336, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_body_digest: reading
mail body from memory
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline digest_body -
deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer digest_body:
timer 336, was 336, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_body_digest: message
size 2568, header+sep 535, body 2033
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) body type (ESMTP BODY):
unlabeled, good (h=0, b=0)
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) body hash:
32959ca2cce04793dad4e7572b5d9810
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ip_from_received:
208.123.118.136
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ip_trace: 208.123.118.136
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup_ip_acl
(public_nets) arr.obj: key="208.123.118.136" matches "::ffff:0:0/96",
result=1
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) Original mail size: 2568;
quota set to: 1284000 bytes (fmin=5, fmax=500, qmin=102400, qmax=314572800)
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) Checking: LoZ44I-4PMMj
[208.123.118.136] <GiovanniMiles at mx3-in.elmodd.com> -> <xyz at zimbra.com>
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) 2822.From:
<Giovanni at mx3-in.elmodd.com>, 2821.Mail_From:
<GiovanniMiles at mx3-in.elmodd.com>
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisLocal) rec=0, "xyz at zimbra.com" result: "1"
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup_ldap_attr, no such
attrs: amavisLocal
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup [local_domains] =>
true, "xyz at zimbra.com" matches, result="1", matching_key="/cached/"
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisBypassVirusChecks) rec=0, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisBypassVirusChecks) rec=1, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup_ldap_attr, no such
attrs: amavisBypassVirusChecks
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup
[bypass_virus_checks] => undef, "xyz at zimbra.com" does not match
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisBypassBannedChecks) rec=0, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisBypassBannedChecks) rec=1, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup_ldap_attr, no such
attrs: amavisBypassBannedChecks
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup
[bypass_banned_checks] => undef, "xyz at zimbra.com" does not match
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisBypassSpamChecks) rec=0, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisBypassSpamChecks) rec=1, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup_ldap_attr, no such
attrs: amavisBypassSpamChecks
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup
[bypass_spam_checks] => undef, "xyz at zimbra.com" does not match
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) Extracting mime components
from a string
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) Issued a new file name:
p001
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) Charging 1985 bytes to
remaining quota 1284000 (out of 1284000, (0%)) - by mime_decode
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) p001 1 Content-Type:
text/plain, size: 1985 B, name:
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline mime_decode -
deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer mime_decode:
timer 336, was 336, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline mime_decode-1
- deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer
mime_decode-1: timer 336, was 336, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) inspect_dsn: parts:
text/plain
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) inspect_dsn: not a bounce
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline dsn_parse -
deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer dsn_parse:
timer 336, was 336, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) decode_parts: level=1,
#parts=1 : p001
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) running file(1) on 1
files, arglist size 18
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) run_command: [38238]
/usr/bin/file p001 </dev/null 2>&1
Mar 14 13:31:37 edge02 amavis[38238]: (35017-12) open_on_specific_fd:
target fd0 closing, to become < /dev/null
Mar 14 13:31:37 edge02 amavis[38238]: (35017-12) open_on_specific_fd:
target fd1 closing, to become (65) &=24
Mar 14 13:31:37 edge02 amavis[38238]: (35017-12) open_on_specific_fd:
target fd1 dup2 from fd24 (65) &=24
Mar 14 13:31:37 edge02 amavis[38238]: (35017-12) open_on_specific_fd:
source fd24 closed
Mar 14 13:31:37 edge02 amavis[38238]: (35017-12) open_on_specific_fd:
target fd2 closing, to become (65) &1
Mar 14 13:31:37 edge02 amavis[38238]: (35017-12) open_on_specific_fd:
target fd2 dup2 from fd1 (65) &1
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) result line from file(1):
p001: ASCII English text, with very long lines\n
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup_re("ASCII English
text, with very long lines") matches key "(?i-xsm:^(ASCII|text)\b)",
result="asc"
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup
[map_full_type_to_short_type] => true, "ASCII English text, with very long
lines" matches, result="asc", matching_key="(?i-xsm:^(ASCII|text)\134b)"
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) File-type of p001: ASCII
English text, with very long lines; (asc)
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) do_ascii: Decoding part
p001
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) do_ascii: Setting
sigaction handler, was 0
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline do_ascii_pre
- deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer
do_ascii_pre: timer 336, was 0, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) do_ascii: Decoding part
p001 (0 items), uulib V0.5pl20
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline do_ascii -
deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer do_ascii:
timer 336, was 336, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) decompose_part: p001 -
atomic
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline parts_decode
- deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer
parts_decode: timer 336, was 336, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisBypassHeaderChecks) rec=0, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisBypassHeaderChecks) rec=1, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup_ldap_attr, no such
attrs: amavisBypassHeaderChecks
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup
[bypass_header_checks] => undef, "xyz at zimbra.com" does not match
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) check_header: 0, OK
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisBypassHeaderChecks) rec=0, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisBypassHeaderChecks) rec=1, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup_ldap_attr, no such
attrs: amavisBypassHeaderChecks
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup
[bypass_header_checks] => undef, "xyz at zimbra.com" does not match
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) Checking for banned types
and filenames
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisBannedRuleNames) rec=0, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12)
lookup_ldap_attr(amavisBannedRuleNames) rec=1, "xyz at zimbra.com" result:
undef
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup_ldap_attr, no such
attrs: amavisBannedRuleNames
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup: (scalar) matches,
result="DEFAULT"
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup [banned_filename],
1 matches for "xyz at zimbra.com", results: "(constant:DEFAULT)"=>"DEFAULT"
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) collect banned table[0]:
xyz at zimbra.com, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x207a6a8)
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) starting banned checks -
traversing message structure tree
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) check_for_banned (p001)
text/plain,.asc
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) doing banned check for
xyz at zimbra.com on text/plain,.asc
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup
[check_bann:xyz at zimbra.com] => undef, ["text/plain",".asc"] does not match
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup
[banned_namepath_re] => undef, "P=p001\tL=1\tM=text/plain\tT=asc" does not
match
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) p.path xyz at zimbra.com:
"P=p001,L=1,M=text/plain,T=asc"
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) banned check: any=0, all=N
(1)
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) lookup
[keep_decoded_original] => true, "MAIL" matches, result="1",
matching_key="(?-xism:^MAIL$)"
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) Issued a new file name:
p002
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) presenting full original
message to scanners as
/opt/zimbra/data/amavisd/tmp/amavis-20140314T132728-35017-vRRaownX/parts/p002
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) Calling virus scanners, 2
files to scan in
/opt/zimbra/data/amavisd/tmp/amavis-20140314T132728-35017-vRRaownX/parts
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) invoking av-scanner
ClamAV-clamd
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ask_daemon: proto=DFLT,
spawn=0, (ClamAV-clamd) /opt/zimbra/data/clamav/clamav.sock
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) run_av (ClamAV-clamd):
query template(1,1): CONTSCAN {}\n
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline run_av_pre -
deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer run_av_pre:
timer 336, was 336, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline run_av_scan -
deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer run_av_scan:
timer 336, was 336, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) run_av Using
(ClamAV-clamd): (code) CONTSCAN
/opt/zimbra/data/amavisd/tmp/amavis-20140314T132728-35017-vRRaownX/parts\n
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline
ask_daemon_internal_connect_pre - deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline
ask_daemon_internal_connect - deadline in 480.0 s, set to 10.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer
ask_daemon_internal_connect: timer 10, was 336, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ClamAV-clamd: Connecting
to socket /opt/zimbra/data/clamav/clamav.sock
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) new socket by
IO::Socket::UNIX to /opt/zimbra/data/clamav/clamav.sock, timeout 10
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) connected to
/opt/zimbra/data/clamav/clamav.sock successfully
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) ClamAV-clamd: Sending
CONTSCAN
/opt/zimbra/data/amavisd/tmp/amavis-20140314T132728-35017-vRRaownX/parts\n
to socket /opt/zimbra/data/clamav/clamav.sock
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) rw_loop: needline=0,
flush=1, wr=1, timeout=10
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) rw_loop: sending 82 chars
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) rw_loop sent 82> CONTSCAN
/opt/zimbra/data/amavisd/tmp/amavis-20140314T132728-35017-vRRaownX/parts\n
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) get_deadline
ask_daemon_internal_scan - deadline in 480.0 s, set to 336.000 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) prolong_timer
ask_daemon_internal_scan: timer 336, was 10, deadline in 480.0 s
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) rw_loop: needline=0,
flush=0, wr=0, timeout=335.997
Mar 14 13:31:37 edge02 amavis[35017]: (35017-12) rw_loop: receiving
Mar 14 13:31:37 edge02 postfix/smtpd[32533]: disconnect from
mx3-in.elmodd.com[208.123.118.136]
Mar 14 13:31:37 edge02 amavis[38239]: (35017-12) SA dbg: util: setuid:
ruid=496 euid=496
Mar 14 13:31:41 edge02 postfix/amavisd/smtpd[35213]: connect from
localhost.localdomain[127.0.0.1]
Mar 14 13:31:41 edge02 postfix/amavisd/smtpd[35213]: 0C556A62E2:
client=localhost.localdomain[127.0.0.1]
Mar 14 13:31:41 edge02 postfix/amavisd/smtpd[35213]: disconnect from
localhost.localdomain[127.0.0.1]
Mar 14 13:31:41 edge02 postfix/amavisd/smtpd[16605]: connect from
localhost.localdomain[127.0.0.1]
Mar 14 13:31:41 edge02 postfix/amavisd/smtpd[16605]: C63A5A62D3:
client=localhost.localdomain[127.0.0.1]
Mar 14 13:31:41 edge02 postfix/cleanup[29062]: C63A5A62D3:
message-id=<746.20140314170846.8946.12975. at server6.mx3-in.elmodd.com.mail>
Mar 14 13:31:41 edge02 postfix/amavisd/smtpd[16605]: disconnect from
localhost.localdomain[127.0.0.1]
Mar 14 13:31:41 edge02 postfix/qmgr[9903]: C63A5A62D3:
from=<GiovanniMiles at mx3-in.elmodd.com>, size=3214, nrcpt=1 (queue active)
Mar 14 13:31:41 edge02 postfix/smtp[36625]: 19DECA62B7:
to=<xyz at zimbra.com>, orig_to=<abc at zimbra.com>,
relay=127.0.0.1[127.0.0.1]:10024, delay=4.9, delays=0.56/0/0.01/4.3,
dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250
2.0.0 Ok: queued as C63A5A62D3)
Mar 14 13:31:41 edge02 postfix/qmgr[9903]: 19DECA62B7: removed
Mar 14 13:31:41 edge02 postfix/lmtp[33042]: C63A5A62D3:
to=<xyz at zimbra.com>, relay=mbs02.zimbra.com[10.110.0.179]:7025, delay=0.1,
delays=0.01/0/0/0.08, dsn=2.1.5, status=sent (250 2.1.5 Delivery OK)
Mar 14 13:31:41 edge02 postfix/qmgr[9903]: C63A5A62D3: removed
As you can see, there is no "spam-tag" line logged at all for this
connection, and yet Amavis clearly added spam headers to the email. There
is also nothing logged about what SpamAssassin did in process 35017-12 at
all.
When I run exact email through SpamAssassin at the command line, I get:
X-Spam-Flag: YES
X-Spam-Status: Yes, score=5.5 required=5.0 tests=RAZOR2_CF_RANGE_51_100,
RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,T_RP_MATCHES_RCVD,UNPARSEABLE_RELAY
autolearn=no autolearn_force=no version=3.4.0
X-Spam-Level: *****
X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on edge02.zimbra.com
--Quanah
--
Quanah Gibson-Mount
Architect - Server
Zimbra, Inc.
--------------------
Zimbra :: the leader in open source messaging and collaboration
More information about the amavis-users
mailing list