Scoring questions
Computer Bob
bob at inter-control.com
Tue Jan 30 17:44:56 CET 2018
I will just post the debug this way and hope it gets through.
-------------------------------------------------------------------------------------------------
Jan 30 10:07:18.391 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
Net::Server: 2018/01/30-10:07:18 CONNECT TCP Peer: "[127.0.0.1]:49220"
Local: "[127.0.0.1]:10024"
Jan 30 10:07:18.392 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
loaded base policy bank
Jan 30 10:07:18.393 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1",
result=1
Jan 30 10:07:18.393 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
process_request: fileno sock=12, STDIN=0, STDOUT=1
Jan 30 10:07:18.394 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set
to 288.000 s
Jan 30 10:07:18.394 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
prolong_timer switch_to_my_time(new request): timer 288, was 0, deadline
in 480.0 s
Jan 30 10:07:18.395 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
process_request: suggested_protocol="" on a TCP socket
Jan 30 10:07:18.396 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Jan 30 10:07:18.396 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) switch_to_client_time 480 s, smtp response sent
Jan 30 10:07:18.396 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) idle_proc, 4: was busy, 5.5 ms, total idle 0.000 s, busy 0.005 s
Jan 30 10:07:18.397 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp readline: read 42 bytes, new size: 42
Jan 30 10:07:18.397 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) idle_proc, 5: was idle, 0.4 ms, total idle 0.000 s, busy 0.005 s
Jan 30 10:07:18.397 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) SMTP< EHLO M1-2.mymailserver.com\r\n
Jan 30 10:07:18.397 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in
480.0 s, set to 288.000 s
Jan 30 10:07:18.397 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 288, was
480, deadline in 480.0 s
Jan 30 10:07:18.398 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 250-[127.0.0.1]
Jan 30 10:07:18.398 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 250-VRFY
Jan 30 10:07:18.398 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 250-PIPELINING
Jan 30 10:07:18.398 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 250-SIZE
Jan 30 10:07:18.398 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 250-ENHANCEDSTATUSCODES
Jan 30 10:07:18.398 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 250-8BITMIME
Jan 30 10:07:18.398 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 250-SMTPUTF8
Jan 30 10:07:18.398 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 250-DSN
Jan 30 10:07:18.398 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
Jan 30 10:07:18.398 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) switch_to_client_time 480 s, smtp response sent
Jan 30 10:07:18.398 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) idle_proc, 6: was busy, 1.7 ms, total idle 0.000 s, busy 0.007 s
Jan 30 10:07:18.399 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp readline: read 145 bytes, new size: 145
Jan 30 10:07:18.399 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) idle_proc, 5: was idle, 0.3 ms, total idle 0.001 s, busy 0.007 s
Jan 30 10:07:18.399 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP< XFORWARD SOURCE=LOCAL\r\n
Jan 30 10:07:18.399 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline
in 480.0 s, set to 288.000 s
Jan 30 10:07:18.399 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288,
was 480, deadline in 480.0 s
Jan 30 10:07:18.399 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 250 2.5.0 Ok XFORWARD
Jan 30 10:07:18.399 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) switch_to_client_time 480 s, smtp response sent
Jan 30 10:07:18.399 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) idle_proc, 6: was busy, 0.6 ms, total idle 0.001 s, busy 0.008 s
Jan 30 10:07:18.399 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.008 s
Jan 30 10:07:18.399 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP< MAIL FROM:<skinny.body at ciaobbweb.com> SIZE=40267
BODY=8BITMIME\r\n
Jan 30 10:07:18.400 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in
480.0 s, set to 288.000 s
Jan 30 10:07:18.400 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 288, was
480, deadline in 480.0 s
Jan 30 10:07:18.400 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) check_mail_begin_task: task_count=1
Jan 30 10:07:18.401 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) TempDir::prepare_dir: created directory
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0
Jan 30 10:07:18.401 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) TempDir::prepare_file: creating file
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0/email.txt
Jan 30 10:07:18.401 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) TempDir::prepare_file: layers: unix,perlio
Jan 30 10:07:18.402 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="0.0.0.0",
no match
Jan 30 10:07:18.403 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [debug_sender] => undef, "skinny.body at ciaobbweb.com"
does not match
Jan 30 10:07:18.403 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) mesage size set to a declared size 40267
Jan 30 10:07:18.403 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 250 2.1.0 Sender <skinny.body at ciaobbweb.com> OK
Jan 30 10:07:18.403 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) switch_to_client_time 480 s, smtp response sent
Jan 30 10:07:18.403 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) idle_proc, 6: was busy, 3.8 ms, total idle 0.001 s, busy 0.012 s
Jan 30 10:07:18.403 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.012 s
Jan 30 10:07:18.403 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP< RCPT TO:<bob1 at myorg.org> ORCPT=rfc822;bob1 at myorg.org\r\n
Jan 30 10:07:18.404 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in
480.0 s, set to 288.000 s
Jan 30 10:07:18.404 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 288, was
480, deadline in 480.0 s
Jan 30 10:07:18.404 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup => undef, "bob1 at myorg.org", no lookup tables
Jan 30 10:07:18.404 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 250 2.1.5 Recipient <bob1 at myorg.org> OK
Jan 30 10:07:18.404 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) switch_to_client_time 480 s, smtp response sent
Jan 30 10:07:18.404 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) idle_proc, 6: was busy, 1.1 ms, total idle 0.001 s, busy 0.013 s
Jan 30 10:07:18.405 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.013 s
Jan 30 10:07:18.405 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP< DATA\r\n
Jan 30 10:07:18.405 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in
480.0 s, set to 288.000 s
Jan 30 10:07:18.405 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer switch_to_my_time(rx SMTP DATA): timer 288, was
480, deadline in 480.0 s
Jan 30 10:07:18.406 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP :10024
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0:
<skinny.body at ciaobbweb.com> -> <bob1 at myorg.org> SIZE=40267 BODY=8BITMIME
Received: from M1-2.mymailserver.com ([127.0.0.1]) by localhost
(m1-2.mymailserver.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP
for <bob1 at myorg.org>; Tue, 30 Jan 2018 10:07:18 -0600 (CST)
Jan 30 10:07:18.406 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Jan 30 10:07:18.406 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) switch_to_client_time 480 s, smtp response sent
Jan 30 10:07:18.406 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) switch_to_client_time 480 s, receiving data
Jan 30 10:07:18.437 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp copy: read 40199 bytes into buffer, new size: 40199
Jan 30 10:07:18.438 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp copy: 6 bytes still buffered at end
Jan 30 10:07:18.438 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline switch_to_my_time(rx data-end) - deadline in
480.0 s, set to 288.000 s
Jan 30 10:07:18.438 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer switch_to_my_time(rx data-end): timer 288, was
480, deadline in 480.0 s
Jan 30 10:07:18.438 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP< .<CR><LF>
Jan 30 10:07:18.439 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Actual message size 40190 B less than the declared 40267 B
Jan 30 10:07:18.439 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline get_body_digest - deadline in 480.0 s, set to
30.000 s
Jan 30 10:07:18.439 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline digest_pre - deadline in 480.0 s, set to 288.000 s
Jan 30 10:07:18.439 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer digest_pre: timer 288, was 288, deadline in 480.0 s
Jan 30 10:07:18.441 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) DNS resolver created, UDP payload size 1220, NS:
192.168.3.150, 192.168.3.150
Jan 30 10:07:18.441 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_body_digest: reading header section from memory
Jan 30 10:07:18.442 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_body_digest: feeding header section to DKIM verifier
Jan 30 10:07:18.442 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_body_digest: sending h/b separator to DKIM
Jan 30 10:07:18.443 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline digest_hdr - deadline in 480.0 s, set to 288.000 s
Jan 30 10:07:18.443 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer digest_hdr: timer 288, was 288, deadline in 480.0 s
Jan 30 10:07:18.443 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_body_digest: reading mail body from memory, 0 DKIM signatures
Jan 30 10:07:18.443 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline digest_body - deadline in 480.0 s, set to 288.000 s
Jan 30 10:07:18.443 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer digest_body: timer 288, was 288, deadline in
480.0 s
Jan 30 10:07:18.444 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_body_digest: message size 40190, header+sep 811, body 39379
Jan 30 10:07:18.444 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) body type (8bit-MIMEtransport): labeled 8BITMIME
unnecessarily (h=0, b=0)
Jan 30 10:07:18.444 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) body hash: c93cd5e827ff040d3cfc2ac612a2c8f6
Jan 30 10:07:18.445 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ip_from_received: no IP address in: by M1-2.mymailserver.com
(Postfix, from userid 1001)\n\tid 5CDF7604E0; Tue, 30 Jan 2018 10:07:18
-0600 (CST)\n
Jan 30 10:07:18.446 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ip_from_received: 192.140.22.179
Jan 30 10:07:18.447 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches
"!127.0.0.0/8", result=0
Jan 30 10:07:18.447 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup_ip_acl (public_nets) arr.obj: key="192.140.22.179"
matches "::ffff:0:0/96", result=1
Jan 30 10:07:18.447 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) trace: ESMTP://[127.0.0.1]:49220 < x < ESMTPS://192.140.22.179
Jan 30 10:07:18.448 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) client IP address unknown, fetched from Received: 127.0.0.1
Jan 30 10:07:18.448 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Original mail size: 40190; quota set to: 20095000 bytes
(fmin=5, fmax=500, qmin=102400, qmax=314572800)
Jan 30 10:07:18.449 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Checking: viK49HCkVsDs [127.0.0.1]
<skinny.body at ciaobbweb.com> -> <bob1 at myorg.org>
Jan 30 10:07:18.449 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) 2822.From: <skinny.body at ciaobbweb.com>
Jan 30 10:07:18.449 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup_acl(bob1 at myorg.org) matches key "myorg.org", result=1
Jan 30 10:07:18.449 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [local_domains] => true, "bob1 at myorg.org" matches,
result="1", matching_key="myorg.org"
Jan 30 10:07:18.449 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [bypass_virus_checks] => undef, "bob1 at myorg.org" does
not match
Jan 30 10:07:18.450 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [bypass_banned_checks] => undef, "bob1 at myorg.org" does
not match
Jan 30 10:07:18.450 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [bypass_spam_checks] => undef, "bob1 at myorg.org" does
not match
Jan 30 10:07:18.451 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Extracting mime components from a string
Jan 30 10:07:18.456 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Issued a new file name: p001
Jan 30 10:07:18.460 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Issued a new file name: p002
Jan 30 10:07:18.461 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Issued a new pseudo part: p003
Jan 30 10:07:18.461 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) p003 1 Content-Type: multipart/alternative
Jan 30 10:07:18.462 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Charging 904 bytes to remaining quota 20095000 (out of
20095000, (0%)) - by mime_decode
Jan 30 10:07:18.462 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) p001 1/1 Content-Type: text/plain, size: 904 B, name:
Jan 30 10:07:18.462 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) reparenting p001 from p000 to p003
Jan 30 10:07:18.462 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Charging 37480 bytes to remaining quota 20094096 (out of
20095000, (0%)) - by mime_decode
Jan 30 10:07:18.463 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) p002 1/2 Content-Type: text/html, size: 37480 B, name:
Jan 30 10:07:18.463 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) reparenting p002 from p000 to p003
Jan 30 10:07:18.463 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline mime_decode - deadline in 480.0 s, set to 288.000 s
Jan 30 10:07:18.463 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer mime_decode: timer 288, was 288, deadline in
480.0 s
Jan 30 10:07:18.464 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline mime_decode-1 - deadline in 480.0 s, set to
288.000 s
Jan 30 10:07:18.464 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer mime_decode-1: timer 288, was 288, deadline in
480.0 s
Jan 30 10:07:18.464 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) decode_parts: level=1, #parts=3 : p001, p002, p003
Jan 30 10:07:18.464 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) running file(1) on 2 files, arglist size 23
Jan 30 10:07:18.467 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) run_command: [4594] /usr/bin/file p001 p002 </dev/null 2>&1
Jan 30 10:07:18.482 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) result line from file(1): p001: ASCII text, with very long
lines\n
Jan 30 10:07:18.483 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup_re("ASCII text, with very long lines") matches key
"(?^i:^(ASCII|text)\\b)", result="asc"
Jan 30 10:07:18.483 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [map_full_type_to_short_type] => true, "ASCII text,
with very long lines" matches, result="asc",
matching_key="(?^i:^(ASCII|text)\\b)"
Jan 30 10:07:18.483 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) File-type of p001: ASCII text, with very long lines; (asc)
Jan 30 10:07:18.484 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) result line from file(1): p002: HTML document, ASCII text,
with very long lines\n
Jan 30 10:07:18.484 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup_re("HTML document, ASCII text, with very long lines")
matches key "(?^i:\\btext\\b)", result="asc"
Jan 30 10:07:18.484 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [map_full_type_to_short_type] => true, "HTML
document, ASCII text, with very long lines" matches, result="asc",
matching_key="(?^i:\\btext\\b)"
Jan 30 10:07:18.484 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) File-type of p002: HTML document, ASCII text, with very long
lines; (asc)
Jan 30 10:07:18.485 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) decompose_part: p001 - atomic
Jan 30 10:07:18.485 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) decompose_part: p002 - atomic
Jan 30 10:07:18.485 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline parts_decode - deadline in 480.0 s, set to 288.000 s
Jan 30 10:07:18.485 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer parts_decode: timer 288, was 288, deadline in
480.0 s
Jan 30 10:07:18.486 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [bypass_header_checks] => undef, "bob1 at myorg.org" does
not match
Jan 30 10:07:18.486 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) check_header: 0, OK
Jan 30 10:07:18.486 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [bypass_header_checks] => undef, "bob1 at myorg.org" does
not match
Jan 30 10:07:18.486 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Checking for banned types and filenames
Jan 30 10:07:18.486 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup: (scalar) matches, result="DEFAULT"
Jan 30 10:07:18.487 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [banned_filename], 1 matches for "bob1 at myorg.org",
results: "(constant:DEFAULT)"=>"DEFAULT"
Jan 30 10:07:18.487 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) collect banned table[0]: bob1 at myorg.org, tables:
DEFAULT=>Amavis::Lookup::RE=ARRAY(0x9335e2c)
Jan 30 10:07:18.487 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) starting banned checks - traversing message structure tree
Jan 30 10:07:18.487 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) check_for_banned (p003,p001) multipart/alternative |
text/plain,.asc
Jan 30 10:07:18.487 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) doing banned check for bob1 at myorg.org on
multipart/alternative | text/plain,.asc
Jan 30 10:07:18.488 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup_re(["multipart/alternative","text/plain",".asc"]), no
matches
Jan 30 10:07:18.488 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [check_bann:bob1 at myorg.org] => undef,
["multipart/alternative","text/plain",".asc"] does not match
Jan 30 10:07:18.488 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [banned_namepath_re] => undef,
"P=p003\tL=1\tM=multipart/alternative\nP=p001\tL=1/1\tM=text/plain\tT=asc"
does not match
Jan 30 10:07:18.488 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) p.path bob1 at myorg.org: "P=p003,L=1,M=multipart/alternative |
P=p001,L=1/1,M=text/plain,T=asc"
Jan 30 10:07:18.488 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) check_for_banned (p003,p002) multipart/alternative |
text/html,.asc
Jan 30 10:07:18.488 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) doing banned check for bob1 at myorg.org on
multipart/alternative | text/html,.asc
Jan 30 10:07:18.488 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup_re(["multipart/alternative","text/html",".asc"]), no
matches
Jan 30 10:07:18.489 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [check_bann:bob1 at myorg.org] => undef,
["multipart/alternative","text/html",".asc"] does not match
Jan 30 10:07:18.489 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [banned_namepath_re] => undef,
"P=p003\tL=1\tM=multipart/alternative\nP=p002\tL=1/2\tM=text/html\tT=asc"
does not match
Jan 30 10:07:18.489 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) p.path bob1 at myorg.org: "P=p003,L=1,M=multipart/alternative |
P=p002,L=1/2,M=text/html,T=asc"
Jan 30 10:07:18.489 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) banned check: any=0, all=N (1)
Jan 30 10:07:18.489 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup_re("MAIL"), no matches
Jan 30 10:07:18.489 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [keep_decoded_original] => undef, "MAIL" does not match
Jan 30 10:07:18.490 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Calling virus scanners, 2 files to scan in
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0/parts
Jan 30 10:07:18.490 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) invoking av-scanner ClamAV-clamd
Jan 30 10:07:18.490 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd)
/var/run/clamav/clamd.ctl
Jan 30 10:07:18.490 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) run_av (ClamAV-clamd): query template(1,1): CONTSCAN {}\n
Jan 30 10:07:18.490 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline run_av_pre - deadline in 479.9 s, set to 288.000 s
Jan 30 10:07:18.490 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer run_av_pre: timer 288, was 288, deadline in 479.9 s
Jan 30 10:07:18.491 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline run_av_scan - deadline in 479.9 s, set to 288.000 s
Jan 30 10:07:18.491 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer run_av_scan: timer 288, was 288, deadline in
479.9 s
Jan 30 10:07:18.491 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) run_av Using (ClamAV-clamd): (code) CONTSCAN
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0/parts\n
Jan 30 10:07:18.491 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline ask_daemon_internal_connect_pre - deadline in
479.9 s, set to 288.000 s
Jan 30 10:07:18.491 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline ask_daemon_internal_connect - deadline in 479.9
s, set to 10.000 s
Jan 30 10:07:18.491 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer ask_daemon_internal_connect: timer 10, was 288,
deadline in 479.9 s
Jan 30 10:07:18.491 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ClamAV-clamd: Connecting to socket /var/run/clamav/clamd.ctl
Jan 30 10:07:18.491 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.ctl,
timeout set to 10
Jan 30 10:07:18.492 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) connected to /var/run/clamav/clamd.ctl successfully
Jan 30 10:07:18.492 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ClamAV-clamd: Sending CONTSCAN
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0/parts\n to
socket /var/run/clamav/clamd.ctl
Jan 30 10:07:18.492 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=0, flush=1, wr=1, timeout=10
Jan 30 10:07:18.493 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: sending 73 chars
Jan 30 10:07:18.493 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop sent 73> CONTSCAN
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0/parts\n
Jan 30 10:07:18.493 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline ask_daemon_internal_scan - deadline in 479.9 s,
set to 288.000 s
Jan 30 10:07:18.493 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer ask_daemon_internal_scan: timer 288, was 10,
deadline in 479.9 s
Jan 30 10:07:18.493 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.998
Jan 30 10:07:18.520 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: receiving
Jan 30 10:07:18.520 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop read 68 chars<
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0/parts: OK\n
Jan 30 10:07:18.521 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.998
Jan 30 10:07:18.521 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: receiving
Jan 30 10:07:18.521 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop read: got eof
Jan 30 10:07:18.521 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline ask_daemon_internal - deadline in 479.9 s, set
to 288.000 s
Jan 30 10:07:18.521 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer ask_daemon_internal: timer 288, was 288,
deadline in 479.9 s
Jan 30 10:07:18.521 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline run_av_3 - deadline in 479.9 s, set to 288.000 s
Jan 30 10:07:18.521 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer run_av_3: timer 288, was 288, deadline in 479.9 s
Jan 30 10:07:18.521 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) run_av (ClamAV-clamd) result:
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0/parts: OK\n
Jan 30 10:07:18.522 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) run_av (ClamAV-clamd): CLEAN
Jan 30 10:07:18.522 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) run_av (ClamAV-clamd) result: clean
Jan 30 10:07:18.522 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) invoking av-scanner AVG Anti-Virus
Jan 30 10:07:18.522 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ask_daemon: proto=DFLT, spawn=0, (AVG Anti-Virus) 127.0.0.1:54322
Jan 30 10:07:18.522 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) run_av (AVG Anti-Virus): query template(1,1): SCAN {}\n
Jan 30 10:07:18.522 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline run_av_pre - deadline in 479.9 s, set to 288.000 s
Jan 30 10:07:18.522 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer run_av_pre: timer 288, was 288, deadline in 479.9 s
Jan 30 10:07:18.523 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline run_av_scan - deadline in 479.9 s, set to 288.000 s
Jan 30 10:07:18.523 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer run_av_scan: timer 288, was 288, deadline in
479.9 s
Jan 30 10:07:18.523 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) run_av Using (AVG Anti-Virus): (code) SCAN
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0/parts\n
Jan 30 10:07:18.523 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline ask_daemon_internal_connect_pre - deadline in
479.9 s, set to 288.000 s
Jan 30 10:07:18.523 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline ask_daemon_internal_connect - deadline in 479.9
s, set to 10.000 s
Jan 30 10:07:18.523 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer ask_daemon_internal_connect: timer 10, was 288,
deadline in 479.9 s
Jan 30 10:07:18.523 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) AVG Anti-Virus: Connecting to socket 127.0.0.1:54322
Jan 30 10:07:18.524 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) new socket using IO::Socket::IP to [127.0.0.1]:54322, timeout 10
Jan 30 10:07:18.525 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) connected to [127.0.0.1]:54322 successfully
Jan 30 10:07:18.525 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) AVG Anti-Virus: Sending SCAN
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0/parts\n to
socket 127.0.0.1:54322
Jan 30 10:07:18.525 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=0, flush=1, wr=1, timeout=10
Jan 30 10:07:18.525 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: receiving
Jan 30 10:07:18.525 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop read 128 chars< 220-AVG daemon mode scanner
(AVG)\r\n220-Program version 13.0.3115\r\n220-Virus Database: Version
4793/15359 2018-01-30\r\n220 Ready\r\n
Jan 30 10:07:18.525 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: sending 69 chars
Jan 30 10:07:18.525 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop sent 69> SCAN
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0/parts\n
Jan 30 10:07:18.525 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline ask_daemon_internal_scan - deadline in 479.9 s,
set to 288.000 s
Jan 30 10:07:18.526 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer ask_daemon_internal_scan: timer 288, was 10,
deadline in 479.9 s
Jan 30 10:07:18.526 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.997
Jan 30 10:07:18.541 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: receiving
Jan 30 10:07:18.541 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop read 8 chars< 200 ok\r\n
Jan 30 10:07:18.542 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.997
Jan 30 10:07:18.542 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: receiving
Jan 30 10:07:18.542 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop read: got eof
Jan 30 10:07:18.542 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline ask_daemon_internal - deadline in 479.9 s, set
to 288.000 s
Jan 30 10:07:18.542 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer ask_daemon_internal: timer 288, was 288,
deadline in 479.9 s
Jan 30 10:07:18.542 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline run_av_3 - deadline in 479.9 s, set to 288.000 s
Jan 30 10:07:18.542 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer run_av_3: timer 288, was 288, deadline in 479.9 s
Jan 30 10:07:18.543 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) run_av (AVG Anti-Virus) result: 220-AVG daemon mode scanner
(AVG)\r\n220-Program version 13.0.3115\r\n220-Virus Database: Version
4793/15359 2018-01-30\r\n220 Ready\r\n200 ok\r\n
Jan 30 10:07:18.543 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) run_av (AVG Anti-Virus): CLEAN
Jan 30 10:07:18.543 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) run_av (AVG Anti-Virus) result: clean
Jan 30 10:07:18.543 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) wbl: checking sender <skinny.body at ciaobbweb.com>
Jan 30 10:07:18.544 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [blacklist_recip<bob1 at myorg.org>] => undef,
"bob1 at myorg.org" does not match
Jan 30 10:07:18.544 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup
[blacklist_sender<skinny.body at ciaobbweb.com>,blacklist_sender] => undef,
"skinny.body at ciaobbweb.com" does not match
Jan 30 10:07:18.544 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [whitelist_recip<bob1 at myorg.org>] => undef,
"bob1 at myorg.org" does not match
Jan 30 10:07:18.544 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup_acl(skinny.body at ciaobbweb.com), no match
Jan 30 10:07:18.545 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup
[whitelist_sender<skinny.body at ciaobbweb.com>,whitelist_sender] => undef,
"skinny.body at ciaobbweb.com" does not match
Jan 30 10:07:18.545 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) query_keys: bob1 at myorg.org, bob1@, myorg.org, .myorg.org, .org, .
Jan 30 10:07:18.545 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup_hash(bob1 at myorg.org) matches keys: "."=>ARRAY(0x9379398)
Jan 30 10:07:18.545 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [score_recip<bob1 at myorg.org>,score_sender], 1 matches
for "bob1 at myorg.org", results: "."=>[Amavis::Lookup::RE=ARRAY(0x9378b64),{}]
Jan 30 10:07:18.546 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup_re("skinny.body at ciaobbweb.com"), no matches
Jan 30 10:07:18.546 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [score_sender<skinny.body at ciaobbweb.com>] => undef,
"skinny.body at ciaobbweb.com" does not match
Jan 30 10:07:18.546 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) SpamControl: calling spam scanner SpamAssassin
Jan 30 10:07:18.546 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline spam_scan_sa_pre - deadline in 479.9 s, set to
476.000 s
Jan 30 10:07:18.546 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer spam_scan_sa_pre: timer 476, was 288, deadline
in 479.9 s
Jan 30 10:07:18.547 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) SA user config: "", username: "amavis", 0, (0)bob1 at myorg.org
Jan 30 10:07:18.547 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) calling SA parse (0), SA vers 3.4.1, 3.004001, data as
STRING_REF, recips_ind [0], user: "amavis"
Jan 30 10:07:18.547 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline SA check - deadline in 479.9 s, set to 475.000 s
Jan 30 10:07:18.551 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) CALLING SA check (0)
Jan 30 10:07:19.102 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) DONE SA check (0)
Jan 30 10:07:19.103 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline spam_scan_sa - deadline in 479.3 s, set to 288.000 s
Jan 30 10:07:19.103 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer spam_scan_sa: timer 288, was 476, deadline in
479.3 s
Jan 30 10:07:19.103 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) spam_scan: score=0 autolearn=ham autolearn_force=no
tests=[none] recips=0
Jan 30 10:07:19.104 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline spam_scan - deadline in 479.3 s, set to 288.000 s
Jan 30 10:07:19.104 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer spam_scan: timer 288, was 288, deadline in 479.3 s
Jan 30 10:07:19.104 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [spam_tag_level] => undef, "bob1 at myorg.org" does not match
Jan 30 10:07:19.104 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup: (scalar) matches, result="5"
Jan 30 10:07:19.104 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [spam_tag2_level] => true, "bob1 at myorg.org" matches,
result="5", matching_key="(constant:5)"
Jan 30 10:07:19.105 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [spam_tag3_level] => undef, "bob1 at myorg.org" does not
match
Jan 30 10:07:19.105 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup: (scalar) matches, result="5"
Jan 30 10:07:19.105 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [spam_kill_level] => true, "bob1 at myorg.org" matches,
result="5", matching_key="(constant:5)"
Jan 30 10:07:19.105 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) final_destiny (ccat=0) is PASS, recip bob1 at myorg.org
Jan 30 10:07:19.105 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) final_destiny PASS, recip bob1 at myorg.org
Jan 30 10:07:19.106 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) do_notify_and_quar: ccat=CleanTag (1,1) ("1,1":CleanTag,
"1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Jan 30 10:07:19.106 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) do_notify_and_quarantine: not quarantining, q_method off
Jan 30 10:07:19.106 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) skip admin notification, no administrators
Jan 30 10:07:19.106 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) do_notify_and_quarantine - done
Jan 30 10:07:19.106 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Jan 30 10:07:19.107 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [forward_method] => true, "bob1 at myorg.org" matches,
result="smtp:[127.0.0.1]:10025",
matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Jan 30 10:07:19.107 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) delivery method is 1, recips: bob1 at myorg.org
Jan 30 10:07:19.107 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup: (scalar) matches, result="1"
Jan 30 10:07:19.107 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [remove_existing_spam_headers] => true,
"bob1 at myorg.org" matches, result="1", matching_key="(constant:1)"
Jan 30 10:07:19.108 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [spam_tag_level] => undef, "bob1 at myorg.org" does not match
Jan 30 10:07:19.108 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup: (scalar) matches, result="5"
Jan 30 10:07:19.108 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [spam_tag2_level] => true, "bob1 at myorg.org" matches,
result="5", matching_key="(constant:5)"
Jan 30 10:07:19.108 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [spam_subject_tag] => undef, "bob1 at myorg.org" does not
match
Jan 30 10:07:19.108 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) headers CLUSTERING: NEW CLUSTER <bob1 at myorg.org>: score=0,
tag=1, tag2=0, local=1, bl=, s=, mangle=
Jan 30 10:07:19.109 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) header encoded (all-ASCII): X-Virus-Scanned: Debian
amavisd-new at M1-2.dettenwanger.com
Jan 30 10:07:19.109 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) header: X-Virus-Scanned: Debian amavisd-new at
M1-2.dettenwanger.com\n
Jan 30 10:07:19.109 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) header encoded (all-ASCII): X-Spam-Flag: NO
Jan 30 10:07:19.109 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) header: X-Spam-Flag: NO\n
Jan 30 10:07:19.109 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) header encoded (all-ASCII): X-Spam-Score: 0
Jan 30 10:07:19.109 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) header: X-Spam-Score: 0\n
Jan 30 10:07:19.109 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) header encoded (all-ASCII): X-Spam-Level:
Jan 30 10:07:19.109 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) header: X-Spam-Level:\n
Jan 30 10:07:19.110 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) header encoded (all-ASCII): X-Spam-Status: No,\n score=0\n
required=5\n tests=[none]\n autolearn=ham autolearn_force=no
Jan 30 10:07:19.110 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) header: X-Spam-Status: No, score=0 required=5
tests=[none]\n\tautolearn=ham autolearn_force=no\n
Jan 30 10:07:19.110 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) fwd: scanner provided a header field X-Spam-Checker-Version,
inhibited by %allowed_added_header_fields
Jan 30 10:07:19.111 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) header encoded (all-ASCII): Received: from
M1-2.mymailserver.com ([127.0.0.1])\n by localhost
(m1-2.mymailserver.com [127.0.0.1]) (amavisd-new, port 10024)\n with
ESMTP\n id viK49HCkVsDs\n for <bob1 at myorg.org>;\n Tue, 30 Jan 2018
10:07:18 -0600 (CST)
Jan 30 10:07:19.111 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) header: Received: from M1-2.mymailserver.com
([127.0.0.1])\n\tby localhost (m1-2.mymailserver.com [127.0.0.1])
(amavisd-new, port 10024)\n\twith ESMTP id viK49HCkVsDs for
<bob1 at myorg.org>;\n\tTue, 30 Jan 2018 10:07:18 -0600 (CST)\n
Jan 30 10:07:19.111 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) headers CLUSTERING: done all 1 recips in one go
Jan 30 10:07:19.111 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) spam-tag, <skinny.body at ciaobbweb.com> -> <bob1 at myorg.org>,
No, score=0 required=5 tests=[none] autolearn=ham autolearn_force=no
Jan 30 10:07:19.112 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) about to connect to smtp:[127.0.0.1]:10025, viK49HCkVsDs FWD
from <skinny.body at ciaobbweb.com> -> <bob1 at myorg.org>
Jan 30 10:07:19.112 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline fwd_init - deadline in 479.3 s, set to 480.000 s
Jan 30 10:07:19.112 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp session: setting up a new session
Jan 30 10:07:19.112 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) establish_or_refresh, state: down
Jan 30 10:07:19.112 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35
Jan 30 10:07:19.113 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) connected to [127.0.0.1]:10025 successfully
Jan 30 10:07:19.113 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=1, flush=0, wr=0, timeout=35
Jan 30 10:07:19.127 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: receiving
Jan 30 10:07:19.127 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop read 64 chars< 220 M1-2.mymailserver.com ESMTP
Postfix (Ubuntu)\r\n
Jan 30 10:07:19.127 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp greeting: 220 M1-2.mymailserver.com ESMTP Postfix
(Ubuntu), dt: 14.6 ms
Jan 30 10:07:19.127 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp cmd> EHLO localhost
Jan 30 10:07:19.127 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=0, flush=1, wr=1, timeout=300
Jan 30 10:07:19.128 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: sending 16 chars
Jan 30 10:07:19.128 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop sent 16> EHLO localhost\r\n
Jan 30 10:07:19.128 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Jan 30 10:07:19.128 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: receiving
Jan 30 10:07:19.128 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop read 158 chars<
250-M1-2.mymailserver.com\r\n250-PIPELINING\r\n250-SIZE
31457280\r\n250-VRFY\r\n250-ETRN\r\n250-STARTTLS\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250
DSN\r\n
Jan 30 10:07:19.129 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp resp to EHLO: 250
M1-2.mymailserver.com\nPIPELINING\nSIZE
31457280\nVRFY\nETRN\nSTARTTLS\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
Jan 30 10:07:19.129 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) tls active=0, capable=1, sec_level=0
Jan 30 10:07:19.129 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Remote host presents itself as: M1-2.mymailserver.com,
handles DSN, PIPELINING, 8BITMIME
Jan 30 10:07:19.130 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) AUTH not needed, user='', MTA offers ''
Jan 30 10:07:19.130 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp cmd> MAIL FROM:<skinny.body at ciaobbweb.com> BODY=7BIT
Jan 30 10:07:19.130 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) orcpt_encode rfc822, bob1 at myorg.org, encode_for_smtp
Jan 30 10:07:19.130 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp cmd> RCPT TO:<bob1 at myorg.org> ORCPT=rfc822;bob1 at myorg.org
Jan 30 10:07:19.131 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp cmd> DATA
Jan 30 10:07:19.131 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=0, flush=1, wr=1, timeout=120
Jan 30 10:07:19.131 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: sending 107 chars
Jan 30 10:07:19.131 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop sent 107> MAIL FROM:<skinny.body at ciaobbweb.com>
BODY=7BIT\r\nRCPT TO:<bob1 at myorg.org>
ORCPT=rfc822;bob1 at myorg.org\r\nDATA\r\n
Jan 30 10:07:19.131 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Jan 30 10:07:19.136 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: receiving
Jan 30 10:07:19.136 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) 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 30 10:07:19.137 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp resp to MAIL (pip): 250 2.1.0 Ok
Jan 30 10:07:19.137 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp resp to RCPT (pip) (<bob1 at myorg.org>): 250 2.1.5 Ok
Jan 30 10:07:19.138 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Jan 30 10:07:19.138 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) write_header: 1, Amavis::Out::SMTP::Protocol=HASH(0xc13c210)
Jan 30 10:07:19.138 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) deleted: X-Spam-Checker-Version: SpamAssassin 3.4.1
(2015-04-28) on\n\tM1-2.mymailserver.com
Jan 30 10:07:19.139 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=0, flush=1, wr=1, timeout=180
Jan 30 10:07:19.139 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: sending 40537 chars
Jan 30 10:07:19.139 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop sent 40537> X-Virus-Scanned: Debian amavisd-new at
M1-2.dettenwanger.com\r\nX-Spam-Flag: NO\r\nX-Spam-Score:
0\r\nX-Spam-Level:\r\nX-Spam-Status: No, score=0 required=5
tests=[none]\r\n\tautolearn=ham autolearn_force=no\r\nRe [...]
Jan 30 10:07:19.140 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=1, flush=0, wr=1, timeout=479.972
Jan 30 10:07:19.140 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: sending 5 chars
Jan 30 10:07:19.140 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop sent 5> \r\n.\r\n
Jan 30 10:07:19.140 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: needline=1, flush=0, wr=0, timeout=479.972
Jan 30 10:07:19.179 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop: receiving
Jan 30 10:07:19.179 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rw_loop read 36 chars< 250 2.0.0 Ok: queued as 20E27604B4\r\n
Jan 30 10:07:19.180 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) smtp resp to data-dot (<bob1 at myorg.org>): 250 2.0.0 Ok:
queued as 20E27604B4, dt: 39.3 ms
Jan 30 10:07:19.180 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Amavis::Out::SMTP::Session close, keeping connection
Jan 30 10:07:19.180 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline fwd-end-chkpnt - deadline in 479.3 s, set to
288.000 s
Jan 30 10:07:19.180 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer fwd-end-chkpnt: timer 288, was 0, deadline in
479.3 s
Jan 30 10:07:19.181 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) viK49HCkVsDs FWD from <skinny.body at ciaobbweb.com> ->
<bob1 at myorg.org>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025):
250 2.0.0 Ok: queued as 20E27604B4
Jan 30 10:07:19.181 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline forwarding - deadline in 479.3 s, set to 288.000 s
Jan 30 10:07:19.181 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer forwarding: timer 288, was 288, deadline in 479.3 s
Jan 30 10:07:19.182 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) DSN: sender NOT credible, SA: 0.000, <skinny.body at ciaobbweb.com>
Jan 30 10:07:19.182 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup: (scalar) matches, result="7"
Jan 30 10:07:19.182 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) lookup [spam_dsn_cutoff_level_bysender] => true,
"skinny.body at ciaobbweb.com" matches, result="7", matching_key="(constant:7)"
Jan 30 10:07:19.182 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) dsn: from MTA 250 NonBlocking:CleanTag
<skinny.body at ciaobbweb.com> -> <bob1 at myorg.org>: 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
20E27604B4"
Jan 30 10:07:19.183 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) DSN: SUCC from MTA 250 NonBlocking:CleanTag, no DSN
requested: <skinny.body at ciaobbweb.com> -> <bob1 at myorg.org>
Jan 30 10:07:19.183 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) delivery_status_notification: notif 0 bytes, suppressed: no
Jan 30 10:07:19.183 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) one_response_for_all, per_recip_capable: N, suppressed: N
Jan 30 10:07:19.183 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) one_response_for_all <skinny.body at ciaobbweb.com>: 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 20E27604B4'
Jan 30 10:07:19.184 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) 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 20E27604B4
Jan 30 10:07:19.184 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline delivery-notification - deadline in 479.3 s, set
to 288.000 s
Jan 30 10:07:19.184 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer delivery-notification: timer 288, was 288,
deadline in 479.3 s
Jan 30 10:07:19.184 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) status counters:
InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
Jan 30 10:07:19.184 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline snmp-counters - deadline in 479.3 s, set to
288.000 s
Jan 30 10:07:19.184 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer snmp-counters: timer 288, was 288, deadline in
479.3 s
Jan 30 10:07:19.185 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) orcpt_encode rfc822, bob1 at myorg.org, smtputf8
Jan 30 10:07:19.190 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) oldest_public_ip_addr_from_received: 192.140.22.179
Jan 30 10:07:19.193 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) Passed CLEAN {RelayedInbound}, [127.0.0.1] [192.140.22.179]
<skinny.body at ciaobbweb.com> -> <bob1 at myorg.org>, Message-ID:
<WMjfAEt7u5.JzidMDB.5hAHoVX.IrH7cNEeIytd2 at web2.ciaobbweb.com>, mail_id:
viK49HCkVsDs, Hits: 0, size: 40190, queued_as: 20E27604B4, 801 ms
Jan 30 10:07:19.193 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline main_log_entry - deadline in 479.2 s, set to
288.000 s
Jan 30 10:07:19.193 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer main_log_entry: timer 288, was 288, deadline in
479.2 s
Jan 30 10:07:19.193 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) TIMING-SA total 554 ms - parse: 3.0 (0.5%),
extract_message_metadata: 28 (5.1%), get_uri_detail_list: 5 (0.9%),
tests_pri_0: 263 (47.4%), check_spf: 111 (19.9%), poll_dns_idle: 225
(40.6%), tests_pri_500: 130 (23.5%), learn: 125 (22.5%), b_learn: 119
(21.5%), b_count_change: 67 (12.0%), get_report: 0.06 (0.0%)
Jan 30 10:07:19.193 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) updating snmp variables in BDB
Jan 30 10:07:19.195 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline check done - deadline in 479.2 s, set to 288.000 s
Jan 30 10:07:19.195 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer check done: timer 288, was 288, deadline in 479.2 s
Jan 30 10:07:19.195 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) sending SMTP response: "250 2.0.0 from
MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 20E27604B4"
Jan 30 10:07:19.195 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0
Ok: queued as 20E27604B4
Jan 30 10:07:19.196 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) switch_to_client_time 480 s, smtp response sent
Jan 30 10:07:19.196 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) TempDir::strip:
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0
Jan 30 10:07:19.196 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) rmdir_recursively:
/var/lib/amavis/tmp/amavis-20180130T100718-03621-WTglx9E0/parts, excl=1
Jan 30 10:07:19.198 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) size: 40190, TIMING [total 807 ms] - SMTP greeting: 5 (1%)1,
SMTP EHLO: 2.1 (0%)1, SMTP pre-MAIL: 1.4 (0%)1, mkdir tempdir: 1.4
(0%)1, create email.txt: 0.4 (0%)1, SMTP pre-DATA-flush: 4.6 (1%)2, SMTP
DATA: 32 (4%)6, check_init: 0.6 (0%)6, digest_hdr: 3.4 (0%)6,
digest_body_dkim: 1.5 (0%)7, collect_info: 3.7 (0%)7, mkdir parts: 2.4
(0%)7, mime_decode: 13 (2%)9, get-file-type2: 22 (3%)12, parts_decode:
0.6 (0%)12, check_header: 1.0 (0%)12, AV-scan-1: 36 (4%)16, AV-scan-2:
21 (3%)19, spam-wb-list: 3.0 (0%)19, SA msg read: 0.9 (0%)19, SA parse:
4.2 (1%)20, SA check: 551 (68%)88, decide_mail_destiny: 3.8 (0%)89,
notif-quar: 0.6 (0%)89, fwd-connect: 23 (3%)92, fwd-mail-pip: 7 (1%)92,
fwd-rcpt-pip: 0.5 (0%)93, fwd-data-chkpnt: 0.1 (0%)93, write-header: 1.1
(0%)93, fwd-data-contents: 1.0 (0%)93, fwd-end-chkpnt: 41 (5%)98,
prepare-dsn: 2.7 (0%)98, report: 2.7 (0%)99, main_log_entry: 7 (1%)99,
update_snmp: 1.7 (0%)100, SMTP pre-response: 0.4 (0%)100, SMTP response:
0.5 (0%)100, unlink-2-files: 0.7 (0%)100, rundown: 0.9 (0%)100
Jan 30 10:07:19.198 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) idle_proc, 6: was busy, 793.3 ms, total idle 0.001 s, busy
0.806 s
Jan 30 10:07:19.198 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) idle_proc, 5: was idle, 0.2 ms, total idle 0.001 s, busy 0.806 s
Jan 30 10:07:19.198 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP< QUIT\r\n
Jan 30 10:07:19.199 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in
480.0 s, set to 288.000 s
Jan 30 10:07:19.199 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was
480, deadline in 480.0 s
Jan 30 10:07:19.199 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission
channel
Jan 30 10:07:19.199 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) switch_to_client_time 480 s, smtp response sent
Jan 30 10:07:19.199 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) SMTP session over, timer stopped
Jan 30 10:07:19.202 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) exiting process_request
Jan 30 10:07:19.202 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) idle_proc, bye: was busy, 4.1 ms, total idle 0.001 s, busy
0.810 s
Jan 30 10:07:19.202 M1-2.mymailserver.com /usr/sbin/amavisd-new[3621]:
(03621-01) load: 100 %, total idle 0.001 s, busy 0.810 s
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.amavis.org/pipermail/amavis-users/attachments/20180130/f7e3d0bc/attachment.html>
More information about the amavis-users
mailing list