Mails stuck in amavisd
Malte Schmidt-Tychsen
it at 2c2.de
Mon Jan 11 01:09:58 CET 2016
Hello,
I have a weird issue. I have an Ubuntu Wily as an lxd host and CentOS
7.2 as an lxd guest. A CentOS 7.1 guest install went fine and everything
works.
But with the 7.2 install the mails keep getting stuck in
/var/spool/amavisd/tmp/ I can neither receive nor send mail. All of it
is in this directory.
The install even worked at first. I could send and receive mails during
testing. But at some point later it stopped. And I am pretty sure I
didn't change anything relevant.
The following log entries are from /var/log/maillog and are all from
sending a single message outbound. Or trying to, as it currently doesn't
work. Does anyone have an idea?
Thank you,
Malte
Jan 10 23:59:34 gilligan imap[1730]: starttls: TLSv1 with cipher
ECDHE-RSA-AES256-SHA (256/256 bits new) no authentication
Jan 10 23:59:34 gilligan imap[1730]: login: localhost [127.0.0.1]
test.tester at my_server_truncated.de PLAIN+TLS User logged in
SESSIONID=<gilligan.my_server_truncated.de-1730-1452470374-1-14980432814048979446>
Jan 10 23:59:34 gilligan postfix/submission/smtpd[1798]: connect from
localhost[127.0.0.1]
Jan 10 23:59:36 gilligan postfix/submission/smtpd[1798]: 1370738E04AF:
client=localhost[127.0.0.1], sasl_method=LOGIN,
sasl_username=test.tester at my_server_truncated.de
Jan 10 23:59:36 gilligan postfix/cleanup[1805]: 1370738E04AF:
message-id=<94795768bfe1f0b9915ea118d6d4f02d at my_server_truncated.de>
Jan 10 23:59:36 gilligan postfix/qmgr[1014]: 1370738E04AF:
from=<test.tester at my_server_truncated.de>, size=368, nrcpt=1 (queue active)
Jan 10 23:59:36 gilligan amavis[1516]: (01516-01) Net::Server:
2016/01/10-23:59:36 CONNECT TCP Peer: "[127.0.0.1]:51062" Local:
"[127.0.0.1]:10024"
Jan 10 23:59:36 gilligan amavis[1516]: idle_proc, hi : was idle,
2187006.1 ms, total idle 2187.008 s, busy 0.612 s
Jan 10 23:59:36 gilligan amavis[1516]: loaded base policy bank
Jan 10 23:59:36 gilligan amavis[1516]: lookup_ip_acl (inet_acl) arr.obj:
key="127.0.0.1" matches "127.0.0.1", result=1
Jan 10 23:59:36 gilligan amavis[1516]: process_request: fileno sock=14,
STDIN=0, STDOUT=1
Jan 10 23:59:36 gilligan amavis[1516]: get_deadline
switch_to_my_time(new request) - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: prolong_timer
switch_to_my_time(new request): timer 288, was 0, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: process_request:
suggested_protocol="" on a TCP socket
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) SMTP> 220 [127.0.0.1]
ESMTP amavisd-new service ready
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) switch_to_client_time
480 s, smtp response sent
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) idle_proc, 4: was
busy, 1.8 ms, total idle 2187.008 s, busy 0.614 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp readline: read 22
bytes, new size: 22
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) idle_proc, 5: was
idle, 0.2 ms, total idle 2187.008 s, busy 0.614 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) SMTP< EHLO
gilligan.my_server_truncated.de\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
switch_to_my_time(rx SMTP EHLO): timer 288, was 480, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP> 250-[127.0.0.1]
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP> 250-VRFY
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP> 250-PIPELINING
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP> 250-SIZE
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP>
250-ENHANCEDSTATUSCODES
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP> 250-8BITMIME
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP> 250-SMTPUTF8
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP> 250-DSN
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP> 250 XFORWARD
NAME ADDR PORT PROTO HELO IDENT SOURCE
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) switch_to_client_time
480 s, smtp response sent
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) idle_proc, 6: was
busy, 1.6 ms, total idle 2187.008 s, busy 0.616 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp readline: read
208 bytes, new size: 208
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) idle_proc, 5: was
idle, 0.4 ms, total idle 2187.008 s, busy 0.616 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP< XFORWARD
NAME=localhost ADDR=127.0.0.1 PORT=60856\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP> 250 2.5.0 Ok
XFORWARD
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) switch_to_client_time
480 s, smtp response sent
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) idle_proc, 6: was
busy, 1.1 ms, total idle 2187.008 s, busy 0.617 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) idle_proc, 5: was
idle, 0.2 ms, total idle 2187.008 s, busy 0.617 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP< XFORWARD
PROTO=ESMTP HELO=my_server_truncated.de IDENT=1370738E04AF SOURCE=LOCAL\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP> 250 2.5.0 Ok
XFORWARD
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) switch_to_client_time
480 s, smtp response sent
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) idle_proc, 6: was
busy, 1.1 ms, total idle 2187.008 s, busy 0.618 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) idle_proc, 5: was
idle, 0.2 ms, total idle 2187.009 s, busy 0.618 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP< MAIL
FROM:<test.tester at my_server_truncated.de> SIZE=368\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
switch_to_my_time(rx SMTP MAIL): timer 288, was 480, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) check_mail_begin_task:
task_count=2
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup_ip_acl
(client_ipaddr_policy) arr.obj: key="127.0.0.1" matches "127.0.0.0/8",
result=1
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) loaded policy bank
"MYNETS"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup [debug_sender]
=> undef, "test.tester at my_server_truncated.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) mesage size set to a
declared size 368
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP> 250 2.1.0
Sender <test.tester at my_server_truncated.de> OK
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) switch_to_client_time
480 s, smtp response sent
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) idle_proc, 6: was
busy, 2.1 ms, total idle 2187.009 s, busy 0.620 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) idle_proc, 5: was
idle, 0.2 ms, total idle 2187.009 s, busy 0.620 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP< RCPT
TO:<it at 2c2.de> ORCPT=rfc822;it at 2c2.de\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
switch_to_my_time(rx SMTP RCPT): timer 288, was 480, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup => undef,
"it at 2c2.de", no lookup tables
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup_acl(it at 2c2.de),
no match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup [local_domains]
=> undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) query_keys: cached
it at 2c2.de
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup_ldap
"it at 2c2.de", query keys: "it at 2c2.de", "@2c2.de", "@.2c2.de", "@.de",
"@.", base: dc=gi7,dc=de, filter: (|(mail=%m)(alias=%m))
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ldap begin_work
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup_ldap: searching
base="dc=gi7,dc=de", scope="sub",
filter="(|(|(mail=it at 2c2.de)(mail=@2c2.de)(mail=@.2c2.de)(mail=@.de)(mail=@.))(|(alias=it at 2c2.de)(alias=@2c2.de)(alias=@.2c2.de)(alias=@.de)(alias=@.)))"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup_ldap,
"it at 2c2.de" no match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisMessageSizeLimit), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[message_size_limit] => undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP> 250 2.1.5
Recipient <it at 2c2.de> OK
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) switch_to_client_time
480 s, smtp response sent
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) idle_proc, 6: was
busy, 4.7 ms, total idle 2187.009 s, busy 0.625 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) idle_proc, 5: was
idle, 0.1 ms, total idle 2187.009 s, busy 0.625 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP< DATA\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
switch_to_my_time(rx SMTP DATA): timer 288, was 480, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP
[127.0.0.1]:10024
/var/spool/amavisd/tmp/amavis-20160110T232308-01516-sZ9s0Gq_:
<test.tester at my_server_truncated.de> -> <it at 2c2.de> SIZE=368 Received:
from gilligan.my_server_truncated.de ([127.0.0.1]) by localhost
(gilligan.my_server_truncated.de [127.0.0.1]) (amavisd-new, port 10024)
with ESMTP for <it at 2c2.de>; Sun, 10 Jan 2016 23:59:36 +0000 (UTC)
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP> 354 End data
with <CR><LF>.<CR><LF>
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) switch_to_client_time
480 s, smtp response sent
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) switch_to_client_time
480 s, receiving data
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp copy: read 377
bytes into buffer, new size: 377
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp copy: 6 bytes
still buffered at end
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
switch_to_my_time(rx data-end): timer 288, was 480, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ESMTP< .<CR><LF>
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp connection cache,
dt: 2187.0, state: 1
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp connection cache,
dt: 2187.0 -> disabling
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
get_body_digest - deadline in 480.0 s, set to 30.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
digest_pre - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
digest_pre: timer 288, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_body_digest:
reading header section from memory
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_body_digest:
feeding header section to DKIM verifier
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_body_digest:
sending h/b separator to DKIM
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
digest_hdr - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
digest_hdr: timer 288, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_body_digest:
reading mail body from memory, 0 DKIM signatures
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
digest_body - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
digest_body: timer 288, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_body_digest:
message size 368, header+sep 316, body 52
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) body type
(8bit-MIMEtransport): unlabeled, good (h=0, b=0)
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) body hash:
d8b7d80cf713ed1b51d3b83aaff9e0b6
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prepending client's IP
address to trace: 127.0.0.1
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup_ip_acl
(public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup_ip_acl
(public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) trace:
ESMTP://[127.0.0.1]:51062 < ESMTP://[127.0.0.1]:60856
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) Original mail size:
368; quota set to: 184000 bytes (fmin=5, fmax=500, qmin=102400,
qmax=314572800)
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) Checking: z3SVxuVMaX3o
MYNETS [127.0.0.1] <test.tester at my_server_truncated.de> -> <it at 2c2.de>
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) 2822.From:
<test.tester at my_server_truncated.de>
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisLocal), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup_acl(it at 2c2.de),
no match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup [local_domains]
=> undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisBypassVirusChecks), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[bypass_virus_checks] => undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisBypassBannedChecks), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[bypass_banned_checks] => undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisBypassSpamChecks), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[bypass_spam_checks] => undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) Extracting mime
components from a string
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) Issued a new file
name: p001
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) Charging 51 bytes to
remaining quota 184000 (out of 184000, (0%)) - by mime_decode
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) p001 1 Content-Type:
text/plain, size: 51 B, name:
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
mime_decode - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
mime_decode: timer 288, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
mime_decode-1 - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
mime_decode-1: timer 288, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) inspect_dsn: parts:
text/plain
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) inspect_dsn: not a bounce
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline dsn_parse
- deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
dsn_parse: timer 288, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) decode_parts: level=1,
#parts=1 : p001
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) running file(1) on 1
files, arglist size 18
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) run_command: [1807]
/usr/bin/file p001 </dev/null 2>&1
Jan 10 23:59:36 gilligan amavis[1807]: (01516-02) open_on_specific_fd:
target fd0 closing, to become < /dev/null
Jan 10 23:59:36 gilligan amavis[1807]: (01516-02) open_on_specific_fd:
target fd1 closing, to become (65) &=19
Jan 10 23:59:36 gilligan amavis[1807]: (01516-02) open_on_specific_fd:
target fd1 dup2 from fd19 (65) &=19
Jan 10 23:59:36 gilligan amavis[1807]: (01516-02) open_on_specific_fd:
source fd19 closed
Jan 10 23:59:36 gilligan amavis[1807]: (01516-02) open_on_specific_fd:
target fd2 closing, to become (65) &1
Jan 10 23:59:36 gilligan amavis[1807]: (01516-02) open_on_specific_fd:
target fd2 dup2 from fd1 (65) &1
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) result line from
file(1): p001: ASCII text\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup_re("ASCII
text") matches key "(?^i:^(ASCII|text)\\b)", result="asc"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[map_full_type_to_short_type] => true, "ASCII text" matches,
result="asc", matching_key="(?^i:^(ASCII|text)\\b)"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) File-type of p001:
ASCII text; (asc)
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) do_ascii: Decoding
part p001
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) do_ascii: Setting
sigaction handler, was 0
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
do_ascii_pre - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
do_ascii_pre: timer 288, was 0, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) do_ascii: Decoding
part p001 (0 items), uulib V0.5pl20
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline do_ascii
- deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
do_ascii: timer 288, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) decompose_part: p001 -
atomic
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
parts_decode - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
parts_decode: timer 288, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisBypassHeaderChecks), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[bypass_header_checks] => undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) check_header: 0, OK
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisBypassHeaderChecks), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[bypass_header_checks] => undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) Checking for banned
types and filenames
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisBannedRuleNames), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup: (scalar)
matches, result="DEFAULT"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[banned_filename], 1 matches for "it at 2c2.de", results:
"(constant:DEFAULT)"=>"DEFAULT"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) collect banned
table[0]: it at 2c2.de, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x3e8e208)
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) starting banned checks
- traversing message structure tree
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) check_for_banned
(p001) text/plain,.asc
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) doing banned check for
it at 2c2.de on text/plain,.asc
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_re(["text/plain",".asc"]), no matches
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[check_bann:it at 2c2.de] => undef, ["text/plain",".asc"] does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[banned_namepath_re] => undef, "P=p001\tL=1\tM=text/plain\tT=asc" does
not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) p.path it at 2c2.de:
"P=p001,L=1,M=text/plain,T=asc"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) banned check: any=0,
all=N (1)
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup_re("MAIL")
matches key "(?^:^MAIL$)", result="1"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[keep_decoded_original] => true, "MAIL" matches, result="1",
matching_key="(?^:^MAIL$)"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) Issued a new file
name: p002
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) presenting full
original message to scanners as
/var/spool/amavisd/tmp/amavis-20160110T232308-01516-sZ9s0Gq_/parts/p002
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) Calling virus
scanners, 2 files to scan in
/var/spool/amavisd/tmp/amavis-20160110T232308-01516-sZ9s0Gq_/parts
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) invoking av-scanner
ClamAV-clamd
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ask_daemon:
proto=DFLT, spawn=0, (ClamAV-clamd) /var/run/clamd.amavisd/clamd.sock
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) run_av (ClamAV-clamd):
query template(1,1): CONTSCAN {}\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
run_av_pre - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
run_av_pre: timer 288, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
run_av_scan - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
run_av_scan: timer 288, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) run_av Using
(ClamAV-clamd): (code) CONTSCAN
/var/spool/amavisd/tmp/amavis-20160110T232308-01516-sZ9s0Gq_/parts\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
ask_daemon_internal_connect_pre - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
ask_daemon_internal_connect - deadline in 480.0 s, set to 10.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
ask_daemon_internal_connect: timer 10, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ClamAV-clamd:
Connecting to socket /var/run/clamd.amavisd/clamd.sock
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) new socket by
IO::Socket::UNIX to /var/run/clamd.amavisd/clamd.sock, timeout set to 10
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) connected to
/var/run/clamd.amavisd/clamd.sock successfully
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) ClamAV-clamd: Sending
CONTSCAN
/var/spool/amavisd/tmp/amavis-20160110T232308-01516-sZ9s0Gq_/parts\n to
socket /var/run/clamd.amavisd/clamd.sock
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: needline=0,
flush=1, wr=1, timeout=10
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: sending 76 chars
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop sent 76>
CONTSCAN
/var/spool/amavisd/tmp/amavis-20160110T232308-01516-sZ9s0Gq_/parts\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
ask_daemon_internal_scan - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
ask_daemon_internal_scan: timer 288, was 10, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: needline=0,
flush=0, wr=0, timeout=287.998
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: receiving
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop read 71 chars<
/var/spool/amavisd/tmp/amavis-20160110T232308-01516-sZ9s0Gq_/parts: OK\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: needline=0,
flush=0, wr=0, timeout=287.998
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: receiving
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop read: got eof
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
ask_daemon_internal - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
ask_daemon_internal: timer 288, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline run_av_3
- deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
run_av_3: timer 288, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) run_av (ClamAV-clamd)
result:
/var/spool/amavisd/tmp/amavis-20160110T232308-01516-sZ9s0Gq_/parts: OK\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) run_av (ClamAV-clamd):
CLEAN
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) run_av (ClamAV-clamd)
result: clean
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) wbl: checking sender
<test.tester at my_server_truncated.de>
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) query_keys: cached
test.tester at my_server_truncated.de
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) wbl: (LDAP) query
keys: "test.tester at my_server_truncated.de", "@my_server_truncated.de",
"@.my_server_truncated.de", "@.de", "@."
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisBlacklistSender), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup => undef,
"it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisWhitelistSender), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup => undef,
"it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[blacklist_recip<it at 2c2.de>] => undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[blacklist_sender<test.tester at my_server_truncated.de>,blacklist_sender]
=> undef, "test.tester at my_server_truncated.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[whitelist_recip<it at 2c2.de>] => undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[whitelist_sender<test.tester at my_server_truncated.de>,whitelist_sender]
=> undef, "test.tester at my_server_truncated.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) query_keys: cached
it at 2c2.de
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup_hash(it at 2c2.de)
matches keys: "."=>ARRAY(0x3e95ba8)
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[score_recip<it at 2c2.de>,score_sender], 1 matches for "it at 2c2.de",
results:
"."=>[Amavis::Lookup::RE=ARRAY(0x3e95278),{amavis-user-admin at lists.sourceforge.net=>"-3",owner-postfix-announce at postfix.org=>"-3",ntbugtraq at listserv.ntbugtraq.com=>"-3",donotreply at sendmail.org=>"-3",slashdot at slashdot.org=>"-3",clp-request at comp.nus.edu.sg=>"-3",nobody at cert.org=>"-3",security-alerts at linuxsecurity.com=>"-3",cvs-commits-list-admin at gnome.org=>"-3",amavis-user-bounces at lists.sourceforge.net=>"-3",notification-return at lists.sophos.com=>"-3",mailman-announce-admin at python.org=>"-3",emailnews at genomeweb.com=>"-5",owner-textbreakingnews at cnnimail12.cnn.com=>"-5",ca+envelope at sendmail.org=>"-3",cert-advisory at us-cert.gov=>"-3",returns.groups.yahoo.com=>"-3",owner-postfix-users at postfix.org=>"-3",.example.net=>"1",securityfocus.com=>"-3",yahoo-dev-null at yahoo-inc.com=>"-3",owner-alert at iss.net=>"-3",sendmail-announce-request at lists.sendmail.org=>"-3",surveys-errors at lists.nua.ie...
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
...=>"-3",spamassassin.apache.org=>"-3",lvs-users-admin at linuxvirtualserver.org=>"-3",sender at example.net=>"3",owner-sendmail-announce at lists.sendmail.org=>"-3",noreply at freshmeat.net=>"-3",ietf-123-owner at loki.ietf.org=>"-3",clusternews at linuxnetworx.com=>"-3",owner-technews at postel.acm.org=>"-3",rt-users-admin at lists.fsck.com=>"-3"}]
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_re("test.tester at my_server_truncated.de"), no matches
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) query_keys: cached
test.tester at my_server_truncated.de
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_hash(test.tester at my_server_truncated.de), no matches
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[score_sender<test.tester at my_server_truncated.de>] => undef,
"test.tester at my_server_truncated.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) SpamControl: calling
spam scanner SpamAssassin
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
spam_scan_sa_pre - deadline in 480.0 s, set to 476.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
spam_scan_sa_pre: timer 476, was 288, deadline in 480.0 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisSaUserConf), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup [sa_userconf]
=> undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisSaUserName), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup [sa_username]
=> undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) SA user config: "",
username: "amavis", 0, (0)it at 2c2.de
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) calling SA parse (0),
SA vers 3.4.0, 3.004000, data as STRING_REF, recips_ind [0], user: "amavis"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline SA check
- deadline in 480.0 s, set to 475.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) CALLING SA check (0)
Jan 10 23:59:36 gilligan postfix/submission/smtpd[1798]: disconnect from
localhost[127.0.0.1]
Jan 10 23:59:36 gilligan imap[1730]: USAGE
test.tester at my_server_truncated.de user: 0.024000 sys: 0.004000
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) DONE SA check (0)
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline
spam_scan_sa - deadline in 479.8 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
spam_scan_sa: timer 288, was 476, deadline in 479.8 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) spam_scan: score=3.748
autolearn=no autolearn_force=no
tests=[NO_RECEIVED=-0.001,NO_RELAYS=-0.001,RCVD_REMOVED=3.75] recips=0
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline spam_scan
- deadline in 479.8 s, set to 288.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) prolong_timer
spam_scan: timer 288, was 288, deadline in 479.8 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisSpamTagLevel), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup: (scalar)
matches, result="-10"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[spam_tag_level] => true, "it at 2c2.de" matches, result="-10",
matching_key="(constant:-10)"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisSpamTag2Level), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup: (scalar)
matches, result="6.2"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[spam_tag2_level] => true, "it at 2c2.de" matches, result="6.2",
matching_key="(constant:6.2)"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisSpamTag3Level), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[spam_tag3_level] => undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisSpamKillLevel), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup: (scalar)
matches, result="6.9"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[spam_kill_level] => true, "it at 2c2.de" matches, result="6.9",
matching_key="(constant:6.9)"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisMessageSizeLimit), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[message_size_limit] => undef, "it at 2c2.de" does not match
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) final_destiny (ccat=0)
is PASS, recip it at 2c2.de
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) final_destiny PASS,
recip it at 2c2.de
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) do_notify_and_quar:
ccat=CleanTag (1,1) ("1,1":CleanTag, "1":Clean, "0":CatchAll)
ccat_block=(), qar_mth=
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
do_notify_and_quarantine: not quarantining, q_method off
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) skip admin
notification, no administrators
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
do_notify_and_quarantine - done
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisForwardMethod), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup: (opaque)
matches, result="smtp:[127.0.0.1]:10025"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[forward_method] => true, "it at 2c2.de" matches,
result="smtp:[127.0.0.1]:10025",
matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) delivery method is 1,
recips: it at 2c2.de
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisSpamTagLevel), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup: (scalar)
matches, result="-10"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[spam_tag_level] => true, "it at 2c2.de" matches, result="-10",
matching_key="(constant:-10)"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
lookup_ldap_attr(amavisSpamTag2Level), "it at 2c2.de" no matching entries
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup: (scalar)
matches, result="6.2"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) lookup
[spam_tag2_level] => true, "it at 2c2.de" matches, result="6.2",
matching_key="(constant:6.2)"
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) headers CLUSTERING:
NEW CLUSTER <it at 2c2.de>: score=3.748, tag=1, tag2=0, local=0, bl=, s=,
mangle=
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) header encoded
(all-ASCII): X-Virus-Scanned: amavisd-new at my_server_truncated.de
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) header:
X-Virus-Scanned: amavisd-new at my_server_truncated.de\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) header encoded
(all-ASCII): Received: from gilligan.my_server_truncated.de
([127.0.0.1])\n by localhost (gilligan.my_server_truncated.de
[127.0.0.1]) (amavisd-new, port 10024)\n with ESMTP\n id z3SVxuVMaX3o\n
for <it at 2c2.de>;\n Sun, 10 Jan 2016 23:59:3:6 +0000 (UTC)
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) header: Received: from
gilligan.my_server_truncated.de ([127.0.0.1])\n\tby localhost
(gilligan.my_server_truncated.de [127.0.0.1]) (amavisd-new, port
10024)\n\twith ESMTP id z3SVxuVMaX3o for <it at 2c2.de>;\n\tSun, 10 Jan
2016 23:59:36 +0000 (UTC)\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) headers CLUSTERING:
done all 1 recips in one go
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) dkim: candidate
originators: From:<test.tester at my_server_truncated.de>
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) dkim: signature
options for test.tester at my_server_truncated.de(From): c=relaxed/simple;
a=rsa-sha256; d=my_server_truncated.de
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) dkim: not signing,
empty signing domain, From: <test.tester at my_server_truncated.de>
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) about to connect to
smtp:[127.0.0.1]:10025, z3SVxuVMaX3o FWD from
<test.tester at my_server_truncated.de> -> <it at 2c2.de>
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) get_deadline fwd_init
- deadline in 479.8 s, set to 480.000 s
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp session reuse
(smtp:[127.0.0.1]:10025), 1 transactions so far
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) establish_or_refresh,
state: ehlo
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp cmd> NOOP
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: needline=0,
flush=1, wr=1, timeout=15
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: receiving
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop read 51 chars<
421 4.4.2 gilligan.my_server_truncated.de Error: timeout exceeded\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: sending 6 chars
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop sent 6> NOOP\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp resp to NOOP
(idle 2187.3 s): 421 4.4.2 gilligan.my_server_truncated.de Error:
timeout exceeded
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02)
Amavis::Out::SMTP::Session close, disconnecting
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) new socket using
IO::Socket::IP to [127.0.0.1]:10025, timeout 35
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) connected to
[127.0.0.1]:10025 successfully
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: needline=1,
flush=0, wr=0, timeout=35
Jan 10 23:59:36 gilligan postfix/smtpd[1809]: connect from
localhost[127.0.0.1]
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: receiving
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop read 35 chars<
220 gilligan.my_server_truncated.de ESMTP Postfix\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp greeting: 220
gilligan.my_server_truncated.de ESMTP Postfix, dt: 15.0 ms
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp cmd> EHLO localhost
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: needline=0,
flush=1, wr=1, timeout=300
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: sending 16 chars
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop sent 16> EHLO
localhost\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: needline=1,
flush=0, wr=0, timeout=300
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: receiving
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop read 191
chars< 250-gilligan.my_server_truncated.de\r\n250-PIPELINING\r\n250-SIZE
10240000\r\n250-VRFY\r\n250-ETRN\r\n250-STARTTLS\r\n250-XFORWARD NAME
ADDR PROTO HELO SOURCE PORT
IDENT\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp resp to EHLO: 250
gilligan.my_server_truncated.de\nPIPELINING\nSIZE
10240000\nVRFY\nETRN\nSTARTTLS\nXFORWARD NAME ADDR PROTO HELO SOURCE
PORT IDENT\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) tls active=0,
capable=1, sec_level=0
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) Remote host presents
itself as: gilligan.my_server_truncated.de, handles DSN, PIPELINING,
8BITMIME
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp cmd> XFORWARD
ADDR=127.0.0.1 NAME=localhost PORT=60856 PROTO=ESMTP
HELO=my_server_truncated.de SOURCE=LOCAL IDENT=1370738E04AF
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: needline=0,
flush=1, wr=1, timeout=300
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: sending 107 chars
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop sent 107>
XFORWARD ADDR=127.0.0.1 NAME=localhost PORT=60856 PROTO=ESMTP
HELO=my_server_truncated.de SOURCE=LOCAL IDENT=1370738E04AF\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: needline=1,
flush=0, wr=0, timeout=300
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: receiving
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop read 14 chars<
250 2.0.0 Ok\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp resp to XFORWARD:
250 2.0.0 Ok
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) AUTH not needed,
user='', MTA offers ''
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp cmd> MAIL
FROM:<test.tester at my_server_truncated.de> BODY=7BIT
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) orcpt_encode rfc822,
it at 2c2.de, encode_for_smtp
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp cmd> RCPT
TO:<it at 2c2.de> ORCPT=rfc822;it at 2c2.de
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) smtp cmd> DATA
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: needline=0,
flush=1, wr=1, timeout=120
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: sending 92 chars
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop sent 92> MAIL
FROM:<test.tester at my_server_truncated.de> BODY=7BIT\r\nRCPT
TO:<it at 2c2.de> ORCPT=rfc822;it at 2c2.de\r\nDATA\r\n
Jan 10 23:59:36 gilligan amavis[1516]: (01516-02) rw_loop: needline=1,
flush=0, wr=0, timeout=300
Jan 10 23:59:37 gilligan postfix/smtpd[1809]: 42DF438E04D9:
client=localhost[127.0.0.1], orig_queue_id=1370738E04AF,
orig_client=localhost[127.0.0.1]
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) rw_loop: receiving
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) rw_loop read 65 chars<
250 2.1.0 Ok\r\n250 2.1.5 Ok\r\n354 End data with <CR><LF>.<CR><LF>\r\n
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) smtp resp to MAIL
(pip): 250 2.1.0 Ok
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) smtp resp to RCPT
(pip) (<it at 2c2.de>): 250 2.1.5 Ok
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) smtp resp to DATA: 354
End data with <CR><LF>.<CR><LF>
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) write_header: 1,
Amavis::Out::SMTP::Protocol=HASH(0x6f1ac98)
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) smtp connection_cache
disabled, sending QUIT
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) smtp cmd> QUIT
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) rw_loop: needline=0,
flush=1, wr=1, timeout=479.244
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) rw_loop: sending 620 chars
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) rw_loop sent 620>
X-Virus-Scanned: amavisd-new at my_server_truncated.de\r\nReceived: from
gilligan.my_server_truncated.de ([127.0.0.1])\r\n\tby localhost
(gilligan.my_server_truncated.de [127.0.0.1]) (amavisd-new, port
10024)\r\n\twith ESMTP id z3SVxuVMaX3o for <it at 2c2.de> [...]
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) rw_loop: needline=1,
flush=0, wr=0, timeout=479.244
Jan 10 23:59:37 gilligan postfix/cleanup[1811]: 42DF438E04D9:
message-id=<94795768bfe1f0b9915ea118d6d4f02d at my_server_truncated.de>
Jan 10 23:59:37 gilligan imap[1736]: starttls: TLSv1 with cipher
ECDHE-RSA-AES256-SHA (256/256 bits new) no authentication
Jan 10 23:59:37 gilligan postfix/qmgr[1014]: 42DF438E04D9:
from=<test.tester at my_server_truncated.de>, size=408, nrcpt=1 (queue active)
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) rw_loop: receiving
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) rw_loop read 53 chars<
250 2.0.0 Ok: queued as 42DF438E04D9\r\n221 2.0.0 Bye\r\n
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) smtp resp to data-dot
(<it at 2c2.de>): 250 2.0.0 Ok: queued as 42DF438E04D9, dt: 83.0 ms
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02)
Amavis::Out::SMTP::Session close, disconnecting
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) get_deadline
fwd-end-chkpnt - deadline in 478.9 s, set to 288.000 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) prolong_timer
fwd-end-chkpnt: timer 288, was 0, deadline in 478.9 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) z3SVxuVMaX3o FWD from
<test.tester at my_server_truncated.de> -> <it at 2c2.de>, BODY=7BIT 250 2.0.0
from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 42DF438E04D9
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) get_deadline
forwarding - deadline in 478.9 s, set to 288.000 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) prolong_timer
forwarding: timer 288, was 288, deadline in 478.9 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) DSN: sender is
credible (orig), SA: 3.748, <test.tester at my_server_truncated.de>
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) lookup: (scalar)
matches, result="18"
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) lookup
[spam_crediblefrom_dsn_cutoff_level_bysender] => true,
"test.tester at my_server_truncated.de" matches, result="18",
matching_key="(constant:18)"
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) dsn: from MTA 250
NonBlocking:CleanTag <test.tester at my_server_truncated.de> ->
<it at 2c2.de>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=,
DSN_passed_on=1, destiny=1, mta_resp: "250 2.0.0 from
MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 42DF438E04D9"
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) DSN: SUCC from MTA 250
NonBlocking:CleanTag, no DSN requested:
<test.tester at my_server_truncated.de> -> <it at 2c2.de>
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02)
delivery_status_notification: notif 0 bytes, suppressed: no
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) one_response_for_all,
per_recip_capable: N, suppressed: N
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) one_response_for_all
<test.tester at my_server_truncated.de>: success, r=0,b=0,d=0,
ndn_needed=0, '250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok:
queued as 42DF438E04D9'
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) notif=N, suppressed=0,
ndn_needed=0, exit=0, 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250
2.0.0 Ok: queued as 42DF438E04D9
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) get_deadline
delivery-notification - deadline in 478.9 s, set to 288.000 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) prolong_timer
delivery-notification: timer 288, was 288, deadline in 478.9 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) status counters:
InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedOriginating,RelayedUntaggedOutbound}
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) get_deadline
snmp-counters - deadline in 478.9 s, set to 288.000 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) prolong_timer
snmp-counters: timer 288, was 288, deadline in 478.9 s
Jan 10 23:59:37 gilligan postfix/smtpd[1809]: disconnect from
localhost[127.0.0.1]
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) orcpt_encode rfc822,
it at 2c2.de, smtputf8
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) Passed CLEAN
{RelayedOutbound}, MYNETS LOCAL [127.0.0.1]:60856
<test.tester at my_server_truncated.de> -> <it at 2c2.de>, Queue-ID:
1370738E04AF, Message-ID:
<94795768bfe1f0b9915ea118d6d4f02d at my_server_truncated.de>, mail_id:
z3SVxuVMaX3o, Hits: 3.748, size: 368, queued_as: 42DF438E04D9, 1119 ms
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) get_deadline
main_log_entry - deadline in 478.9 s, set to 288.000 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) prolong_timer
main_log_entry: timer 288, was 288, deadline in 478.9 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) TIMING-SA total 193 ms
- parse: 0.64 (0.3%), extract_message_metadata: 1.18 (0.6%),
get_uri_detail_list: 0.10 (0.1%), tests_pri_-1000: 4.1 (2.1%),
tests_pri_-950: 0.84 (0.4%), tests_pri_-900: 0.88 (0.5%),
tests_pri_-400: 0.72 (0.4%), tests_pri_0: 174 (90.1%), check_dkim_adsp:
4.4 (2.3%), check_spf: 0.18 (0.1%), check_razor2: 151 (78.3%),
check_pyzor: 0.19 (0.1%), tests_pri_500: 3.5 (1.8%), get_report: 0.46 (0.2%)
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) updating snmp
variables in BDB
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) get_deadline check
done - deadline in 478.9 s, set to 288.000 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) prolong_timer check
done: timer 288, was 288, deadline in 478.9 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) sending SMTP response:
"250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as
42DF438E04D9"
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) ESMTP> 250 2.0.0 from
MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 42DF438E04D9
Jan 10 23:59:37 gilligan postfix/smtp[1806]: 1370738E04AF:
to=<it at 2c2.de>, relay=127.0.0.1[127.0.0.1]:10024, delay=1.5,
delays=0.38/0.01/0/1.1, 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 42DF438E04D9)
Jan 10 23:59:37 gilligan postfix/qmgr[1014]: 1370738E04AF: removed
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) switch_to_client_time
480 s, smtp response sent
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) TempDir::strip:
/var/spool/amavisd/tmp/amavis-20160110T232308-01516-sZ9s0Gq_
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) rmdir_recursively:
/var/spool/amavisd/tmp/amavis-20160110T232308-01516-sZ9s0Gq_/parts, excl=1
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) size: 368, TIMING
[total 1124 ms] - SMTP greeting: 1.7 (0%)0, SMTP EHLO: 1.7 (0%)0, SMTP
pre-MAIL: 4.0 (0%)1, lookup_ldap: 6 (1%)1, SMTP pre-DATA-flush: 1.2
(0%)1, SMTP DATA: 29 (3%)4, check_init: 0.3 (0%)4, digest_hdr: 0.8
(0%)4, digest_body_dkim: 0.4 (0%)4, collect_info: 0.8 (0%)4,
mime_decode: 6 (0%)5, get-file-type1: 8 (1%)5, decompose_part: 0.7
(0%)5, parts_decode: 0.0 (0%)5, check_header: 0.6 (0%)5, AV-scan-1: 8
(1%)6, spam-wb-list: 3.0 (0%)6, SA msg read: 0.5 (0%)6, SA parse: 2.2
(0%)7, SA check: 190 (17%)24, decide_mail_destiny: 4.1 (0%)24,
notif-quar: 0.4 (0%)24, fwd-connect: 22 (2%)26, fwd-xforward: 0.7
(0%)26, fwd-mail-pip: 737 (66%)92, fwd-rcpt-pip: 0.2 (0%)92,
fwd-data-chkpnt: 0.0 (0%)92, write-header: 0.3 (0%)92,
fwd-data-contents: 0.0 (0%)92, fwd-end-chkpnt: 84 (7%)99, prepare-dsn:
0.8 (0%)99, report: 1.3 (0%)99, main_log_entry: 3.6 (0%)100,
update_snmp: 2.6 (0%)100, SMTP pre-response: 0.3 (0%)100, SMTP response:
0.5 (0%)100, unlink-2-fi...
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) ...les: 0.3 (0%)100,
rundown: 0.4 (0%)100
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) idle_proc, 6: was
busy, 1110.2 ms, total idle 2187.009 s, busy 1.735 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) idle_proc, 5: was
idle, 0.1 ms, total idle 2187.009 s, busy 1.735 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) ESMTP< QUIT\r\n
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) get_deadline
switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) prolong_timer
switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) ESMTP> 221 2.0.0
[127.0.0.1] amavisd-new closing transmission channel
Jan 10 23:59:37 gilligan postfix/smtp[1812]: 42DF438E04D9:
to=<it at 2c2.de>, relay=127.0.0.1[127.0.0.1]:10026, delay=0.11,
delays=0.1/0.01/0/0, dsn=2.0.0, status=sent (250 Ok)
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) switch_to_client_time
480 s, smtp response sent
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) SMTP session over,
timer stopped
Jan 10 23:59:37 gilligan postfix/qmgr[1014]: 42DF438E04D9: removed
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) exiting process_request
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) idle_proc, bye: was
busy, 1.1 ms, total idle 2187.009 s, busy 1.736 s
Jan 10 23:59:37 gilligan amavis[1516]: (01516-02) load: 0 %, total idle
2187.009 s, busy 1.736 s
Jan 10 23:59:37 gilligan imap[1736]: login: localhost [127.0.0.1]
test.tester at my_server_truncated.de PLAIN+TLS User logged in
SESSIONID=<gilligan.my_server_truncated.de-1736-1452470377-1-13922711027956660804>
Jan 10 23:59:37 gilligan imap[1736]: USAGE
test.tester at my_server_truncated.de user: 0.020000 sys: 0.000000
Jan 10 23:59:38 gilligan imap[1746]: starttls: TLSv1 with cipher
ECDHE-RSA-AES256-SHA (256/256 bits new) no authentication
Jan 10 23:59:38 gilligan imap[1746]: login: localhost [127.0.0.1]
test.tester at my_server_truncated.de PLAIN+TLS User logged in
SESSIONID=<gilligan.my_server_truncated.de-1746-1452470378-1-15777152171164735376>
Jan 10 23:59:38 gilligan imap[1746]: USAGE
test.tester at my_server_truncated.de user: 0.020000 sys: 0.000000
More information about the users
mailing list