#  ${nexthop} ${user}
submission inet n       -       n       -       -       smtpd
  -o smtpd_tls_security_level=encrypt
  -o smtpd_sasl_auth_enable=yes
  -o smtpd_client_restrictions=permit_mynetworks,permit_sasl_authenticated,reject
  -o content_filter=smtp-amavis:[127.0.0.1]:10026

# Use dovecot deliver program as LDA.
dovecot unix    -       n       n       -       -      pipe
    flags=DRh user=vmail:vmail argv=/usr/libexec/dovecot/deliver -f ${sender} -d ${user}@${domain} -m ${extension}

--
    -o smtp_send_xforward_command=yes
    -o disable_dns_lookups=yes
    -o max_use=20

127.0.0.1:10025 inet n  -   -   -   -  smtpd
    -o content_filter=
    -o mynetworks_style=host
    -o mynetworks=127.0.0.0/8
    -o local_recipient_maps=
    -o relay_recipient_maps=
    -o strict_rfc821_envelopes=yes

# postconf -n
alias_database = hash:/etc/postfix/aliases
alias_maps = hash:/etc/postfix/aliases
allow_min_user = no
allow_percent_hack = no
biff = no
bounce_queue_lifetime = 4h
broken_sasl_auth_clients = yes
command_directory = /usr/sbin
config_directory = /etc/postfix
content_filter = smtp-amavis:[127.0.0.1]:10024
daemon_directory = /usr/libexec/postfix
data_directory = /var/lib/postfix
debug_peer_level = 2
debugger_command = PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin ddd $daemon_directory/$process_name $process_id & sleep 5
delay_warning_time = 0h
disable_vrfy_command = yes
dovecot_destination_recipient_limit = 1
enable_original_recipient = no
home_mailbox = Maildir/
html_directory = no
inet_interfaces = all
inet_protocols = ipv4
mail_owner = postfix
mailbox_command = /usr/libexec/dovecot/deliver
mailq_path = /usr/bin/mailq.postfix
manpage_directory = /usr/share/man
maximal_backoff_time = 4000s
maximal_queue_lifetime = 4h
message_size_limit = 15728640
minimal_backoff_time = 300s
mydestination = $myhostname, localhost, localhost.localdomain
mydomain = my_domain
myhostname = my_mail_server
mynetworks = 127.0.0.1
mynetworks_style = host
myorigin = my_mail_server
newaliases_path = /usr/bin/newaliases.postfix
proxy_read_maps = $canonical_maps $lmtp_generic_maps $local_recipient_maps $mydestination $mynetworks $recipient_bcc_maps $recipient_canonical_maps $relay_domains $relay_recipient_maps $relocated_maps $sender_bcc_maps $sender_canonical_maps $smtp_generic_maps $smtpd_sender_login_maps $transport_maps $virtual_alias_domains $virtual_alias_maps $virtual_mailbox_domains $virtual_mailbox_maps $smtpd_sender_restrictions
queue_directory = /var/spool/postfix
queue_run_delay = 300s
readme_directory = /usr/share/doc/postfix-2.11.0/README_FILES
recipient_bcc_maps = proxy:mysql:/etc/postfix/mysql/recipient_bcc_maps_user.cf, proxy:mysql:/etc/postfix/mysql/recipient_bcc_maps_domain.cf
recipient_delimiter = +
relay_domains = $mydestination, proxy:mysql:/etc/postfix/mysql/relay_domains.cf
sample_directory = /usr/share/doc/postfix-2.11.0/samples
sender_bcc_maps = proxy:mysql:/etc/postfix/mysql/sender_bcc_maps_user.cf, proxy:mysql:/etc/postfix/mysql/sender_bcc_maps_domain.cf
sendmail_path = /usr/sbin/sendmail.postfix
setgid_group = postdrop
smtp-amavis_destination_recipient_limit = 1
smtp_data_init_timeout = 240s
smtp_data_xfer_timeout = 600s
smtp_tls_CAfile = $smtpd_tls_CAfile
smtp_tls_loglevel = 0
smtp_tls_note_starttls_offer = yes
smtp_tls_security_level = may
smtpd_data_restrictions = reject_unauth_pipelining
smtpd_end_of_data_restrictions = check_policy_service inet:127.0.0.1:7777
smtpd_helo_required = yes
smtpd_helo_restrictions = permit_mynetworks, permit_sasl_authenticated, reject_non_fqdn_helo_hostname, reject_invalid_helo_hostname, check_helo_access pcre:/etc/postfix/helo_access.pcre
smtpd_recipient_restrictions = reject_unknown_recipient_domain reject_non_fqdn_recipient reject_unlisted_recipient check_policy_service inet:127.0.0.1:7777 permit_mynetworks permit_sasl_authenticated reject_unauth_destination
smtpd_reject_unlisted_recipient = yes
smtpd_reject_unlisted_sender = yes
smtpd_sasl_auth_enable = yes
smtpd_sasl_local_domain =
smtpd_sasl_path = private/dovecot-auth
smtpd_sasl_security_options = noanonymous
smtpd_sasl_type = dovecot
smtpd_sender_login_maps = proxy:mysql:/etc/postfix/mysql/sender_login_maps.cf
smtpd_sender_restrictions = reject_unknown_sender_domain reject_non_fqdn_sender reject_unlisted_sender permit_mynetworks reject_sender_login_mismatch permit_sasl_authenticated check_sender_access pcre:/etc/postfix/sender_access.pcre
smtpd_tls_CAfile = /etc/pki/tls/certs/gd_bundle-g2-g1.crt
smtpd_tls_auth_only = yes
smtpd_tls_cert_file = /etc/pki/tls/certs/my_mail_server.pem
smtpd_tls_dh1024_param_file = /etc/pki/tls/dhparams.pem
smtpd_tls_exclude_ciphers = aNULL, eNULL, EXPORT, DES, RC4, MD5, PSK, aECDH, EDH-DSS-DES-CBC3-SHA, EDH-RSA-DES-CDC3-SHA, KRB5-DE5, CBC3-SHA
smtpd_tls_key_file = /etc/pki/tls/private/my_mail_server.key
smtpd_tls_loglevel = 0
smtpd_tls_security_level = may
swap_bangpath = no
tls_random_source = dev:/dev/urandom
transport_maps = proxy:mysql:/etc/postfix/mysql/transport_maps_user.cf, proxy:mysql:/etc/postfix/mysql/transport_maps_domain.cf
unknown_local_recipient_reject_code = 550
virtual_alias_domains =
virtual_alias_maps = proxy:mysql:/etc/postfix/mysql/virtual_alias_maps.cf, proxy:mysql:/etc/postfix/mysql/domain_alias_maps.cf, proxy:mysql:/etc/postfix/mysql/catchall_maps.cf, proxy:mysql:/etc/postfix/mysql/domain_alias_catchall_maps.cf
virtual_gid_maps = static:2000
virtual_mailbox_base = /var/vmail
virtual_mailbox_domains = proxy:mysql:/etc/postfix/mysql/virtual_mailbox_domains.cf
virtual_mailbox_maps = proxy:mysql:/etc/postfix/mysql/virtual_mailbox_maps.cf
virtual_minimum_uid = 2000
virtual_transport = dovecot
virtual_uid_maps = static:2000

May 13 06:27:11 mx postfix/smtpd[3567]: connect from mail.external.org[77.77.77.77]
May 13 06:27:12 mx postfix/smtpd[3567]: ECCBF23A62: client=mail.external.org[77.77.77.77]
May 13 06:27:13 mx postfix/cleanup[3571]: ECCBF23A62: message-id=<CAA961YLJ9MxFoet7Y-9HjAL4NSNkLLPkWeNooeoTqLDiNDRD=@mail.external.org>
May 13 06:27:13 mx postfix/qmgr[31913]: ECCBF23A62: from=<sender@external.org>, size=12428, nrcpt=1 (queue active)
May 13 06:27:13 mx amavis[3553]: Net::Server: 2016/05/13-06:27:13 CONNECT TCP Peer: "127.0.0.1:33323" Local: "127.0.0.1:10024"
May 13 06:27:13 mx amavis[3553]: loaded base policy bank
May 13 06:27:13 mx amavis[3553]: lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
May 13 06:27:13 mx amavis[3553]: process_request: fileno sock=11, STDIN=0, STDOUT=1
May 13 06:27:13 mx amavis[3553]: get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: prolong_timer switch_to_my_time(new request): timer 336, was 0, deadline in 480.0 s
May 13 06:27:13 mx amavis[3553]: process_request: suggested_protocol="" on a TCP socket
May 13 06:27:13 mx amavis[3553]: (03553-01) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
May 13 06:27:13 mx amavis[3553]: (03553-01) switch_to_client_time 480 s, smtp response sent
May 13 06:27:13 mx amavis[3553]: (03553-01) idle_proc, 4: was busy, 4.9 ms, total idle 0.000 s, busy 0.005 s
May 13 06:27:13 mx amavis[3553]: (03553-01) smtp readline: read 21 bytes, new size: 21
May 13 06:27:13 mx amavis[3553]: (03553-01) idle_proc, 5: was idle, 0.3 ms, total idle 0.000 s, busy 0.005 s
May 13 06:27:13 mx amavis[3553]: (03553-01) SMTP< EHLO mail.mydomain.org\r\n
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 336, was 480, deadline in 480.0 s
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP> 250-[127.0.0.1]
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP> 250-VRFY
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP> 250-PIPELINING
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP> 250-SIZE
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP> 250-ENHANCEDSTATUSCODES
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP> 250-8BITMIME
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP> 250-DSN
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
May 13 06:27:13 mx amavis[3553]: (03553-01) switch_to_client_time 480 s, smtp response sent
May 13 06:27:13 mx amavis[3553]: (03553-01) idle_proc, 6: was busy, 1.4 ms, total idle 0.000 s, busy 0.006 s
May 13 06:27:13 mx amavis[3553]: (03553-01) smtp readline: read 268 bytes, new size: 268
May 13 06:27:13 mx amavis[3553]: (03553-01) idle_proc, 5: was idle, 0.3 ms, total idle 0.001 s, busy 0.006 s
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP< XFORWARD NAME=mail.external.org ADDR=77.77.77.77 PORT=36407\r\n
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP> 250 2.5.0 Ok XFORWARD
May 13 06:27:13 mx amavis[3553]: (03553-01) switch_to_client_time 480 s, smtp response sent
May 13 06:27:13 mx amavis[3553]: (03553-01) idle_proc, 6: was busy, 0.6 ms, total idle 0.001 s, busy 0.007 s
May 13 06:27:13 mx amavis[3553]: (03553-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.007 s
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP< XFORWARD PROTO=ESMTP HELO=mail.external.org IDENT=ECCBF23A62 SOURCE=REMOTE\r\n
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP> 250 2.5.0 Ok XFORWARD
May 13 06:27:13 mx amavis[3553]: (03553-01) switch_to_client_time 480 s, smtp response sent
May 13 06:27:13 mx amavis[3553]: (03553-01) idle_proc, 6: was busy, 0.6 ms, total idle 0.001 s, busy 0.008 s
May 13 06:27:13 mx amavis[3553]: (03553-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.008 s
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP< MAIL FROM:<sender@external.org> SIZE=12428\r\n
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 336, was 480, deadline in 480.0 s
May 13 06:27:13 mx amavis[3553]: (03553-01) check_mail_begin_task: task_count=1
May 13 06:27:13 mx amavis[3553]: (03553-01) TempDir::prepare_dir: created directory /var/spool/amavisd/tmp/amavis-20160513T062713-03553-2ZzyALCj
May 13 06:27:13 mx amavis[3553]: (03553-01) TempDir::prepare_file: creating file /var/spool/amavisd/tmp/amavis-20160513T062713-03553-2ZzyALCj/email.txt
May 13 06:27:13 mx amavis[3553]: (03553-01) TempDir::prepare_file: layers: unix,perlio
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="77.77.77.77", no match
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [debug_sender] => undef, "sender@external.org" does not match
May 13 06:27:13 mx amavis[3553]: (03553-01) mesage size set to a declared size 12428
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP> 250 2.1.0 Sender <sender@external.org> OK
May 13 06:27:13 mx amavis[3553]: (03553-01) switch_to_client_time 480 s, smtp response sent
May 13 06:27:13 mx amavis[3553]: (03553-01) idle_proc, 6: was busy, 7.9 ms, total idle 0.001 s, busy 0.015 s
May 13 06:27:13 mx amavis[3553]: (03553-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.015 s
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP< RCPT TO:<target@mydomain.org> ORCPT=rfc822;target@mydomain.org\r\n
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 336, was 480, deadline in 480.0 s
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup => undef, "target@mydomain.org", no lookup tables
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_acl(target@mydomain.org) matches key "mydomain.org", result=1
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [local_domains] => true,  "target@mydomain.org" matches, result="1", matching_key="mydomain.org"
May 13 06:27:13 mx amavis[3553]: (03553-01) query_keys: target@mydomain.org, target, @mydomain.org, @.mydomain.org, @.com, @.
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_sql sel_policy "target@mydomain.org", query args: [target@mydomain.org,-3], [target,-3], [@mydomain.org,-3], [@.mydomain.org,-3], [@.com,-3], [@.,-3]
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_sql select: SELECT users.*, policy.*, users.id FROM users LEFT JOIN policy ON users.policy_id=policy.id WHERE users.email IN (?,?,?,?,?,?) ORDER BY users.priority DESC
May 13 06:27:13 mx amavis[3553]: (03553-01) sql begin, nontransaction
May 13 06:27:13 mx amavis[3553]: (03553-01) Connecting to SQL database server
May 13 06:27:13 mx amavis[3553]: (03553-01) connect_to_sql: trying 'DBI:mysql:database=amavisd;host=127.0.0.1;port=3306'
May 13 06:27:13 mx amavis[3553]: (03553-01) connect_to_sql: 'DBI:mysql:database=amavisd;host=127.0.0.1;port=3306' succeeded
May 13 06:27:13 mx amavis[3553]: (03553-01) sql: preparing and executing (6 args): SELECT users.*, policy.*, users.id FROM users LEFT JOIN policy ON users.policy_id=policy.id WHERE users.email IN (?,?,?,?,?,?) ORDER BY users.priority DESC
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_sql, "target@mydomain.org" no match
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_sql_field(message_size_limit), "target@mydomain.org" no matching records
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [message_size_limit] => undef, "target@mydomain.org" does not match
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP> 250 2.1.5 Recipient <target@mydomain.org> OK
May 13 06:27:13 mx amavis[3553]: (03553-01) switch_to_client_time 480 s, smtp response sent
May 13 06:27:13 mx amavis[3553]: (03553-01) idle_proc, 6: was busy, 7.3 ms, total idle 0.001 s, busy 0.023 s
May 13 06:27:13 mx amavis[3553]: (03553-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.023 s
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP< DATA\r\n
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer switch_to_my_time(rx SMTP DATA): timer 336, was 480, deadline in 480.0 s
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP::10024 /var/spool/amavisd/tmp/amavis-20160513T062713-03553-2ZzyALCj: <sender@external.org> -> <target@mydomain.org> SIZE=12428 Received: from mail.mydomain.org ([127.0.0.1]) by localhost (mail.mydomain.org [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <target@mydomain.org>; Fri, 13 May 2016 06:27:13 -0700 (PDT)
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP> 354 End data with <CR><LF>.<CR><LF>
May 13 06:27:13 mx amavis[3553]: (03553-01) switch_to_client_time 480 s, smtp response sent
May 13 06:27:13 mx amavis[3553]: (03553-01) switch_to_client_time 480 s, receiving data
May 13 06:27:13 mx amavis[3553]: (03553-01) smtp copy: read 12438 bytes into buffer, new size: 12438
May 13 06:27:13 mx amavis[3553]: (03553-01) smtp copy: 6 bytes still buffered at end
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer switch_to_my_time(rx data-end): timer 336, was 480, deadline in 480.0 s
May 13 06:27:13 mx amavis[3553]: (03553-01) ESMTP< .<CR><LF>
May 13 06:27:13 mx amavis[3553]: (03553-01) Actual message size 12429 B greater than the declared 12428 B
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline digest_pre - deadline in 480.0 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer digest_pre: timer 336, was 336, deadline in 480.0 s
May 13 06:27:13 mx amavis[3553]: (03553-01) get_body_digest: reading header section from memory
May 13 06:27:13 mx amavis[3553]: (03553-01) get_body_digest: sending h/b separator to DKIM
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline digest_hdr - deadline in 479.9 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer digest_hdr: timer 336, was 0, deadline in 479.9 s
May 13 06:27:13 mx amavis[3553]: (03553-01) get_body_digest: reading mail body from memory
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline digest_body - deadline in 479.9 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer digest_body: timer 336, was 336, deadline in 479.9 s
May 13 06:27:13 mx amavis[3553]: (03553-01) get_body_digest: message size adjusted 12429 -> 12428, header+sep 2454, body 9974
May 13 06:27:13 mx amavis[3553]: (03553-01) body type (ESMTP BODY): unlabeled, good (h=0, b=0)
May 13 06:27:13 mx amavis[3553]: (03553-01) body hash: b98c39712666db1a1a1ac7f4cc94b6df
May 13 06:27:13 mx amavis[3553]: (03553-01) references: <20CA2636-8F3E-4632-980C-3B585B447B3F@mydomain.org>
May 13 06:27:13 mx amavis[3553]: (03553-01) ip_from_received: 77.77.77.77
May 13 06:27:13 mx amavis[3553]: (03553-01) ip_from_received: no IP address in:  by mail.external.org with SMTP id n129so22748228wmn.1\n        for <target@mydomain.org>; Fri, 13 May 2016 06:27:12 -0700 (PDT)\n
May 13 06:27:13 mx amavis[3553]: (03553-01) ip_from_received: no IP address in:  by 88.88.88.88 with HTTP; Fri, 13 May 2016 06:27:11 -0700 (PDT)\n
May 13 06:27:13 mx amavis[3553]: (03553-01) ip_trace: 77.77.77.77 < x < x
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_ip_acl (public_nets) arr.obj: key="77.77.77.77" matches "::ffff:0:0/96", result=1
May 13 06:27:13 mx amavis[3553]: (03553-01) dkim: public key s=20120113 d=external.org k=rsa, 2048-bit key
May 13 06:27:13 mx amavis[3553]: (03553-01) dkim: VALID Author+Sender+MailFrom signature by d=external.org, From: <sender@external.org>, a=rsa-sha256, c=relaxed/relaxed, s=20120113, i=@external.org
May 13 06:27:13 mx amavis[3553]: (03553-01) Original mail size: 12428; quota set to: 6214000 bytes (fmin=5, fmax=500, qmin=102400, qmax=524288000)
May 13 06:27:13 mx amavis[3553]: (03553-01) sql begin, nontransaction
May 13 06:27:13 mx amavis[3553]: (03553-01) sql: preparing and executing (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
May 13 06:27:13 mx amavis[3553]: (03553-01) save_info_preliminary ZZAxZetdftYq, sender id: 36220, sender@external.org, exists
May 13 06:27:13 mx amavis[3553]: (03553-01) sql begin, nontransaction
May 13 06:27:13 mx amavis[3553]: (03553-01) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
May 13 06:27:13 mx amavis[3553]: (03553-01) save_info_preliminary ZZAxZetdftYq, recip id: 132, target@mydomain.org, exists
May 13 06:27:13 mx amavis[3553]: (03553-01) sql begin transaction
May 13 06:27:13 mx amavis[3553]: (03553-01) sql: preparing and executing (11 args): INSERT INTO msgs (partition_tag, mail_id, secret_id, am_id, time_num, time_iso, sid, policy, client_addr, size, host) VALUES (?,?,?,?,?,?,?,?,?,?,?)
May 13 06:27:13 mx amavis[3553]: (03553-01) sql commit
May 13 06:27:13 mx amavis[3553]: (03553-01) Checking: ZZAxZetdftYq [77.77.77.77] <sender@external.org> -> <target@mydomain.org>
May 13 06:27:13 mx amavis[3553]: (03553-01) 2822.From: <sender@external.org>
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_sql_field(local), "target@mydomain.org" no matching records
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_acl(target@mydomain.org) matches key "mydomain.org", result=1
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [local_domains] => true,  "target@mydomain.org" matches, result="1", matching_key="mydomain.org"
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_sql_field(bypass_virus_checks), "target@mydomain.org" no matching records
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [bypass_virus_checks] => undef, "target@mydomain.org" does not match
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_sql_field(bypass_banned_checks), "target@mydomain.org" no matching records
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [bypass_banned_checks] => undef, "target@mydomain.org" does not match
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_sql_field(bypass_spam_checks), "target@mydomain.org" no matching records
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [bypass_spam_checks] => undef, "target@mydomain.org" does not match
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_sql_field(id), "target@mydomain.org" no matching records
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [users.id] => undef, "target@mydomain.org" does not match
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_sql_field(policy_id), "target@mydomain.org" no matching records
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [users.policy_id] => undef, "target@mydomain.org" does not match
May 13 06:27:13 mx amavis[3553]: (03553-01) Extracting mime components from a string
May 13 06:27:13 mx amavis[3553]: (03553-01) Issued a new file name: p001
May 13 06:27:13 mx postfix/smtpd[3567]: disconnect from mail.external.org[77.77.77.77]
May 13 06:27:13 mx amavis[3553]: (03553-01) Issued a new file name: p002
May 13 06:27:13 mx amavis[3553]: (03553-01) Issued a new pseudo part: p003
May 13 06:27:13 mx amavis[3553]: (03553-01) p003 1 Content-Type: multipart/alternative
May 13 06:27:13 mx amavis[3553]: (03553-01) Charging 3018 bytes to remaining quota 6214000 (out of 6214000, (0%)) - by mime_decode
May 13 06:27:13 mx amavis[3553]: (03553-01) p001 1/1 Content-Type: text/plain, size: 3018 B, name:
May 13 06:27:13 mx amavis[3553]: (03553-01) reparenting p001 from p000 to p003
May 13 06:27:13 mx amavis[3553]: (03553-01) Charging 6191 bytes to remaining quota 6210982 (out of 6214000, (0%)) - by mime_decode
May 13 06:27:13 mx amavis[3553]: (03553-01) p002 1/2 Content-Type: text/html, size: 6191 B, name:
May 13 06:27:13 mx amavis[3553]: (03553-01) reparenting p002 from p000 to p003
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline mime_decode - deadline in 479.9 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer mime_decode: timer 336, was 336, deadline in 479.9 s
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline mime_decode-1 - deadline in 479.9 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer mime_decode-1: timer 336, was 336, deadline in 479.9 s
May 13 06:27:13 mx amavis[3553]: (03553-01) inspect_dsn: parts: multipart/alternative, text/plain, text/html
May 13 06:27:13 mx amavis[3553]: (03553-01) inspect_dsn: not a bounce
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline dsn_parse - deadline in 479.9 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer dsn_parse: timer 336, was 336, deadline in 479.9 s
May 13 06:27:13 mx amavis[3553]: (03553-01) decode_parts: level=1, #parts=3 : p001, p002, p003
May 13 06:27:13 mx amavis[3553]: (03553-01) running file(1) on 2 files, arglist size 23
May 13 06:27:13 mx amavis[3553]: (03553-01) run_command: [3578] /usr/bin/file p001 p002 </dev/null 2>&1
May 13 06:27:13 mx amavis[3578]: (03553-01) open_on_specific_fd: target fd0 closing, to become < /dev/null
May 13 06:27:13 mx amavis[3578]: (03553-01) open_on_specific_fd: target fd1 closing, to become (65) &=15
May 13 06:27:13 mx amavis[3578]: (03553-01) open_on_specific_fd: target fd1 dup2 from fd15 (65) &=15
May 13 06:27:13 mx amavis[3578]: (03553-01) open_on_specific_fd: source fd15 closed
May 13 06:27:13 mx amavis[3578]: (03553-01) open_on_specific_fd: target fd2 closing, to become (65) &1
May 13 06:27:13 mx amavis[3578]: (03553-01) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
May 13 06:27:13 mx amavis[3553]: (03553-01) result line from file(1): p001: UTF-8 Unicode English text\n
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_re("UTF-8 Unicode English text") matches key "(?i-xsm:\btext\b)", result="asc"
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [map_full_type_to_short_type] => true,  "UTF-8 Unicode English text" matches, result="asc", matching_key="(?i-xsm:\134btext\134b)"
May 13 06:27:13 mx amavis[3553]: (03553-01) File-type of p001: UTF-8 Unicode English text; (asc)
May 13 06:27:13 mx amavis[3553]: (03553-01) result line from file(1): p002: UTF-8 Unicode English text, with very long lines\n
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_re("UTF-8 Unicode English text, with very long lines") matches key "(?i-xsm:\btext\b)", result="asc"
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [map_full_type_to_short_type] => true,  "UTF-8 Unicode English text, with very long lines" matches, result="asc", matching_key="(?i-xsm:\134btext\134b)"
May 13 06:27:13 mx amavis[3553]: (03553-01) File-type of p002: UTF-8 Unicode English text, with very long lines; (asc)
May 13 06:27:13 mx amavis[3553]: (03553-01) decompose_part: p001 - atomic
May 13 06:27:13 mx amavis[3553]: (03553-01) decompose_part: p002 - atomic
May 13 06:27:13 mx amavis[3553]: (03553-01) get_deadline parts_decode - deadline in 479.9 s, set to 336.000 s
May 13 06:27:13 mx amavis[3553]: (03553-01) prolong_timer parts_decode: timer 336, was 336, deadline in 479.9 s
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_sql_field(bypass_header_checks), "target@mydomain.org" no matching records
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [bypass_header_checks] => undef, "target@mydomain.org" does not match
May 13 06:27:13 mx amavis[3553]: (03553-01) check_header: 0, OK
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_sql_field(bypass_header_checks), "target@mydomain.org" no matching records
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [bypass_header_checks] => undef, "target@mydomain.org" does not match
May 13 06:27:13 mx amavis[3553]: (03553-01) Checking for banned types and filenames
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_sql_field(banned_rulenames), "target@mydomain.org" no matching records
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup: (scalar) matches, result="DEFAULT"
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [banned_filename], 1 matches for "target@mydomain.org", results: "(constant:DEFAULT)"=>"DEFAULT"
May 13 06:27:13 mx amavis[3553]: (03553-01) collect banned table[0]: target@mydomain.org, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x3d32818)
May 13 06:27:13 mx amavis[3553]: (03553-01) starting banned checks - traversing message structure tree
May 13 06:27:13 mx amavis[3553]: (03553-01) check_for_banned (p003,p001) multipart/alternative | text/plain,.asc
May 13 06:27:13 mx amavis[3553]: (03553-01) doing banned check for target@mydomain.org on multipart/alternative | text/plain,.asc
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_re(["multipart/alternative","text/plain",".asc"]), no matches
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [check_bann:target@mydomain.org] => undef, ["multipart/alternative","text/plain",".asc"] does not match
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_re("P=p003\tL=1\tM=multipart/alternative\nP=p001\tL=1/1\tM=text/plain\tT=asc"), no matches
May 13 06:27:13 mx amavis[3553]: (03553-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
May 13 06:27:13 mx amavis[3553]: (03553-01) p.path target@mydomain.org: "P=p003,L=1,M=multipart/alternative | P=p001,L=1/1,M=text/plain,T=asc"
May 13 06:27:13 mx amavis[3553]: (03553-01) check_for_banned (p003,p002) multipart/alternative | text/html,.asc
May 13 06:27:13 mx amavis[3553]: (03553-01) doing banned check for target@mydomain.org on multipart/alternative | text/html,.asc
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_re(["multipart/alternative","text/html",".asc"]), no matches
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [check_bann:target@mydomain.org] => undef, ["multipart/alternative","text/html",".asc"] does not match
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_re("P=p003\tL=1\tM=multipart/alternative\nP=p002\tL=1/2\tM=text/html\tT=asc"), no matches
May 13 06:27:13 mx amavis[3553]: (03553-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
May 13 06:27:13 mx amavis[3553]: (03553-01) p.path target@mydomain.org: "P=p003,L=1,M=multipart/alternative | P=p002,L=1/2,M=text/html,T=asc"
May 13 06:27:13 mx amavis[3553]: (03553-01) banned check: any=0, all=N (1)
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup_re("MAIL") matches key "(?-xism:^MAIL$)", result="1"
May 13 06:27:13 mx amavis[3553]: (03553-01) lookup [keep_decoded_original] => true,  "MAIL" matches, result="1", matching_key="(?-xism:^MAIL$)"
May 13 06:27:13 mx amavis[3553]: (03553-01) Issued a new file name: p004
May 13 06:27:13 mx amavis[3553]: (03553-01) presenting full original message to scanners as /var/spool/amavisd/tmp/amavis-20160513T062713-03553-2ZzyALCj/parts/p004
May 13 06:27:13 mx amavis[3553]: (03553-01) Calling virus scanners, 3 files to scan in /var/spool/amavisd/tmp/amavis-20160513T062713-03553-2ZzyALCj/parts
May 13 06:27:21 mx amavis[3553]: (03553-01) DONE SA check (0)
May 13 06:27:21 mx amavis[3553]: (03553-01) get_deadline spam_scan_sa - deadline in 472.4 s, set to 331.000 s
May 13 06:27:21 mx amavis[3553]: (03553-01) prolong_timer spam_scan_sa: timer 331, was 469, deadline in 472.4 s
May 13 06:27:21 mx amavis[3553]: (03553-01) spam_scan: score=-2.698 autolearn=ham tests=[BAYES_00=-1.9,DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,FREEMAIL_FROM=0.001,HTML_MESSAGE=0.001,RCVD_IN_DNSWL_LOW=-0.7,SPF_PASS=-0.001,URIBL_BLOCKED=0.001] recips=0
May 13 06:27:21 mx amavis[3553]: (03553-01) get_deadline spam_scan - deadline in 472.4 s, set to 331.000 s
May 13 06:27:21 mx amavis[3553]: (03553-01) prolong_timer spam_scan: timer 331, was 331, deadline in 472.4 s
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup => undef, "@external.org", no lookup tables
May 13 06:27:21 mx amavis[3553]: (03553-01) penpals: low score, no need for penpals aid
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup_sql_field(spam_tag_level), "target@mydomain.org" no matching records
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup: (scalar) matches, result="2"
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup [spam_tag_level] => true,  "target@mydomain.org" matches, result="2", matching_key="(constant:2)"
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup_sql_field(spam_tag2_level), "target@mydomain.org" no matching records
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup: (scalar) matches, result="6.2"
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup [spam_tag2_level] => true,  "target@mydomain.org" matches, result="6.2", matching_key="(constant:6.2)"
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup_sql_field(spam_tag3_level), "target@mydomain.org" no matching records
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup [spam_tag3_level] => undef, "target@mydomain.org" does not match
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup_sql_field(spam_kill_level), "target@mydomain.org" no matching records
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup: (scalar) matches, result="6.9"
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup [spam_kill_level] => true,  "target@mydomain.org" matches, result="6.9", matching_key="(constant:6.9)"
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup_sql_field(message_size_limit), "target@mydomain.org" no matching records
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup [message_size_limit] => undef, "target@mydomain.org" does not match
May 13 06:27:21 mx amavis[3553]: (03553-01) final_destiny (ccat=0) is PASS, recip target@mydomain.org
May 13 06:27:21 mx amavis[3553]: (03553-01) final_destiny PASS, recip target@mydomain.org
May 13 06:27:21 mx amavis[3553]: (03553-01) do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
May 13 06:27:21 mx amavis[3553]: (03553-01) do_notify_and_quarantine: not quarantining, q_method off
May 13 06:27:21 mx amavis[3553]: (03553-01) skip admin notification, no administrators
May 13 06:27:21 mx amavis[3553]: (03553-01) do_notify_and_quarantine - done
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup_sql_field(forward_method), "target@mydomain.org" no matching records
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup [forward_method] => true,  "target@mydomain.org" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
May 13 06:27:21 mx amavis[3553]: (03553-01) delivery method is 1, recips: target@mydomain.org
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup_sql_field(spam_tag_level), "target@mydomain.org" no matching records
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup: (scalar) matches, result="2"
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup [spam_tag_level] => true,  "target@mydomain.org" matches, result="2", matching_key="(constant:2)"
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup_sql_field(spam_tag2_level), "target@mydomain.org" no matching records
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup: (scalar) matches, result="6.2"
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup [spam_tag2_level] => true,  "target@mydomain.org" matches, result="6.2", matching_key="(constant:6.2)"
May 13 06:27:21 mx amavis[3553]: (03553-01) headers CLUSTERING: NEW CLUSTER <target@mydomain.org>: score=-2.698, tag=0, tag2=0, local=1, bl=, s=, mangle=
May 13 06:27:21 mx amavis[3553]: (03553-01) header: X-Virus-Scanned: amavisd-new at mail.mydomain.org\n
May 13 06:27:21 mx amavis[3553]: (03553-01) fwd: scanner provided a header field X-Spam-Checker-Version, inhibited by %allowed_added_header_fields
May 13 06:27:21 mx amavis[3553]: (03553-01) fwd: scanner provided a header field X-Spam-Level, but we preferred our own
May 13 06:27:21 mx amavis[3553]: (03553-01) fwd: scanner provided a header field X-Spam-Status, but we preferred our own
May 13 06:27:21 mx amavis[3553]: (03553-01) fwd: scanner provided a header field X-Spam-DCC, inhibited by %allowed_added_header_fields
May 13 06:27:21 mx amavis[3553]: (03553-01) header: Authentication-Results: mail.mydomain.org (amavisd-new); dkim=pass (2048-bit key)\n\theader.d=external.org\n
May 13 06:27:21 mx amavis[3553]: (03553-01) header: Received: from mail.mydomain.org ([127.0.0.1])\n\tby localhost (mail.mydomain.org [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id ZZAxZetdftYq for <target@mydomain.org>;\n\tFri, 13 May 2016 06:27:13 -0700 (PDT)\n
May 13 06:27:21 mx amavis[3553]: (03553-01) headers CLUSTERING: done all 1 recips in one go
May 13 06:27:21 mx amavis[3553]: (03553-01) dkim: not signing mail which is not originating from our site
May 13 06:27:21 mx amavis[3553]: (03553-01) about to connect to smtp:[127.0.0.1]:10025, ZZAxZetdftYq FWD from <sender@external.org> -> <target@mydomain.org>
May 13 06:27:21 mx amavis[3553]: (03553-01) get_deadline fwd_init - deadline in 472.3 s, set to 473.000 s
May 13 06:27:21 mx amavis[3553]: (03553-01) smtp session: setting up a new session
May 13 06:27:21 mx amavis[3553]: (03553-01) establish_or_refresh, state: down
May 13 06:27:21 mx amavis[3553]: (03553-01) new socket using IO::Socket::INET6 to [127.0.0.1]:10025, timeout 35
May 13 06:27:21 mx amavis[3553]: (03553-01) connected to [127.0.0.1]:10025 successfully
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: needline=1, flush=0, wr=0, timeout=35
May 13 06:27:21 mx postfix/smtpd[3582]: connect from mail.mydomain.org[127.0.0.1]
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: receiving
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop read 34 chars< 220 mail.mydomain.org ESMTP Postfix\r\n
May 13 06:27:21 mx amavis[3553]: (03553-01) smtp greeting: 220 mail.mydomain.org ESMTP Postfix, dt: 10.2 ms
May 13 06:27:21 mx amavis[3553]: (03553-01) smtp cmd> EHLO localhost
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: needline=0, flush=1, wr=1, timeout=300
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: sending 16 chars
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop sent 16> EHLO localhost\r\n
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: receiving
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop read 113 chars< 250-mail.mydomain.org\r\n250-PIPELINING\r\n250-SIZE 15728640\r\n250-ETRN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n
May 13 06:27:21 mx amavis[3553]: (03553-01) smtp resp to EHLO: 250 mail.mydomain.org\nPIPELINING\nSIZE 15728640\nETRN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
May 13 06:27:21 mx amavis[3553]: (03553-01) tls active=0, capable=, sec_level=0
May 13 06:27:21 mx amavis[3553]: (03553-01) Remote host presents itself as: mail.mydomain.org, handles DSN, handles PIPELINING
May 13 06:27:21 mx amavis[3553]: (03553-01) AUTH not needed, user='', MTA offers ''
May 13 06:27:21 mx amavis[3553]: (03553-01) smtp cmd> MAIL FROM:<sender@external.org> BODY=7BIT
May 13 06:27:21 mx amavis[3553]: (03553-01) smtp cmd> RCPT TO:<target@mydomain.org> ORCPT=rfc822;target@mydomain.org
May 13 06:27:21 mx amavis[3553]: (03553-01) smtp cmd> DATA
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: needline=0, flush=1, wr=1, timeout=120
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: sending 117 chars
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop sent 117> MAIL FROM:<sender@external.org> BODY=7BIT\r\nRCPT TO:<target@mydomain.org> ORCPT=rfc822;target@mydomain.org\r\nDATA\r\n
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
May 13 06:27:21 mx postfix/smtpd[3582]: 21CB823A6E: client=mail.mydomain.org[127.0.0.1]
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: receiving
May 13 06:27:21 mx amavis[3553]: (03553-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
May 13 06:27:21 mx amavis[3553]: (03553-01) smtp resp to MAIL (pip): 250 2.1.0 Ok
May 13 06:27:21 mx amavis[3553]: (03553-01) smtp resp to RCPT (pip) (<target@mydomain.org>): 250 2.1.5 Ok
May 13 06:27:21 mx amavis[3553]: (03553-01) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
May 13 06:27:21 mx amavis[3553]: (03553-01) write_header: 1, Amavis::Out::SMTP::Protocol=HASH(0x7907268)
May 13 06:27:21 mx amavis[3553]: (03553-01) smtp connection_cache disabled, sending QUIT
May 13 06:27:21 mx amavis[3553]: (03553-01) smtp cmd> QUIT
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: needline=0, flush=1, wr=1, timeout=472.977
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: sending 12801 chars
May 13 06:27:21 mx postfix/cleanup[3571]: 21CB823A6E: message-id=<CAA961YLJ9MxFoet7Y-9HjAL4NSNkLLPkWeNooeoTqLDiNDRD=g@mail.external.org>
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop sent 12801> X-Virus-Scanned: amavisd-new at mail.mydomain.org\r\nAuthentication-Results: mail.mydomain.org (amavisd-new); dkim=pass (2048-bit key)\r\n\theader.d=external.org\r\nReceived: from mail.mydomain.org ([127.0.0.1])\r\n\tby lo [...]
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: needline=1, flush=0, wr=0, timeout=472.977
May 13 06:27:21 mx postfix/smtpd[3582]: disconnect from mail.mydomain.org[127.0.0.1]
May 13 06:27:21 mx postfix/qmgr[31913]: 21CB823A6E: from=<sender@external.org>, size=12971, nrcpt=1 (queue active)
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop: receiving
May 13 06:27:21 mx amavis[3553]: (03553-01) rw_loop read 51 chars< 250 2.0.0 Ok: queued as 21CB823A6E\r\n221 2.0.0 Bye\r\n
May 13 06:27:21 mx amavis[3553]: (03553-01) smtp resp to data-dot (<target@mydomain.org>): 250 2.0.0 Ok: queued as 21CB823A6E, dt: 14.2 ms
May 13 06:27:21 mx amavis[3553]: (03553-01) Amavis::Out::SMTP::Session close, disconnecting
May 13 06:27:21 mx amavis[3553]: (03553-01) get_deadline fwd-end-chkpnt - deadline in 472.3 s, set to 331.000 s
May 13 06:27:21 mx amavis[3553]: (03553-01) prolong_timer fwd-end-chkpnt: timer 331, was 0, deadline in 472.3 s
May 13 06:27:21 mx amavis[3553]: (03553-01) ZZAxZetdftYq FWD from <sender@external.org> -> <target@mydomain.org>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 21CB823A6E
May 13 06:27:21 mx amavis[3553]: (03553-01) get_deadline forwarding - deadline in 472.3 s, set to 331.000 s
May 13 06:27:21 mx amavis[3553]: (03553-01) prolong_timer forwarding: timer 331, was 331, deadline in 472.3 s
May 13 06:27:21 mx amavis[3553]: (03553-01) DSN: sender is credible (dkim), SA: -2.698, <sender@external.org>
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup: (scalar) matches, result="18"
May 13 06:27:21 mx amavis[3553]: (03553-01) lookup [spam_crediblefrom_dsn_cutoff_level_bysender] => true,  "sender@external.org" matches, result="18", matching_key="(constant:18)"
May 13 06:27:21 mx amavis[3553]: (03553-01) dsn: from MTA 250 NonBlocking:Clean <sender@external.org> -> <target@mydomain.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 21CB823A6E"
May 13 06:27:21 mx amavis[3553]: (03553-01) DSN: SUCC from MTA 250 NonBlocking:Clean, no DSN requested: <sender@external.org> -> <target@mydomain.org>
May 13 06:27:21 mx amavis[3553]: (03553-01) delivery_status_notification: notif 0 bytes, suppressed: no
May 13 06:27:21 mx amavis[3553]: (03553-01) one_response_for_all, per_recip_capable: N, suppressed: N
May 13 06:27:21 mx amavis[3553]: (03553-01) one_response_for_all <sender@external.org>: 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 21CB823A6E'
May 13 06:27:21 mx amavis[3553]: (03553-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 21CB823A6E
May 13 06:27:21 mx amavis[3553]: (03553-01) get_deadline delivery-notification - deadline in 472.3 s, set to 331.000 s
May 13 06:27:21 mx amavis[3553]: (03553-01) prolong_timer delivery-notification: timer 331, was 331, deadline in 472.3 s
May 13 06:27:21 mx amavis[3553]: (03553-01) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
May 13 06:27:21 mx amavis[3553]: (03553-01) get_deadline snmp-counters - deadline in 472.3 s, set to 331.000 s
May 13 06:27:21 mx amavis[3553]: (03553-01) prolong_timer snmp-counters: timer 331, was 331, deadline in 472.3 s
May 13 06:27:21 mx amavis[3553]: (03553-01) oldest_public_ip_addr_from_received: 77.77.77.77
May 13 06:27:21 mx amavis[3553]: (03553-01) Passed CLEAN {RelayedInbound}, [77.77.77.77]:36407 [77.77.77.77]  -> , Queue-ID: ECCBF23A62, Message-ID: , mail_id: ZZAxZetdftYq, Hits: -2.698, size: 12428, queued_as: 21CB823A6E, dkim_sd=20120113:external.org, 7754 ms, Tests: [BAYES_00=-1.9,DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,FREEMAIL_FROM=0.001,HTML_MESSAGE=0.001,RCVD_IN_DNSWL_LOW=-0.7,SPF_PASS=-0.001,URIBL_BLOCKED=0.001]
May 13 06:27:21 mx amavis[3553]: (03553-01) get_deadline main_log_entry - deadline in 472.3 s, set to 331.000 s
May 13 06:27:21 mx amavis[3553]: (03553-01) prolong_timer main_log_entry: timer 331, was 331, deadline in 472.3 s
May 13 06:27:21 mx amavis[3553]: (03553-01) sql begin transaction
May 13 06:27:21 mx amavis[3553]: (03553-01) sql: preparing and executing (12 args): INSERT INTO msgrcpt (partition_tag, mail_id, rseqnum, rid, is_local, content, ds, rs, bl, wl, bspam_level, smtp_resp) VALUES (?,?,?,?,?,?,?,?,?,?,?,?)
May 13 06:27:21 mx amavis[3553]: (03553-01) save_info_final ZZAxZetdftYq, orig=N, chks=VSHBD, cont.ty=C, q.type= , q.to=, dsn=N, score=-2.698, Message-ID: <CAA961YLJ9MxFoet7Y-9HjAL4NSNkLLPkWeNooeoTqLDiNDRD=g@mail.external.org>, From: 'Dmitry <sender@external.org>', Subject: 'Fwd: There's still time for your Private Jet Rental'
May 13 06:27:21 mx amavis[3553]: (03553-01) sql: preparing and executing (12 args): UPDATE msgs SET content=?, quar_type=?, quar_loc=?, dsn_sent=?, spam_level=?, message_id=?, from_addr=?, subject=?, client_addr=?, originating=? WHERE partition_tag=? AND mail_id=?
May 13 06:27:21 mx amavis[3553]: (03553-01) sql commit
May 13 06:27:21 mx amavis[3553]: (03553-01) TIMING-SA total 7487 ms - parse: 2 (0.0%), extract_message_metadata: 24 (0.3%), get_uri_detail_list: 14 (0.2%), tests_pri_-1000: 3 (0.0%), tests_pri_-950: 1.08 (0.0%), tests_pri_-900: 1.15 (0.0%), tests_pri_-400: 44 (0.6%), check_bayes: 43 (0.6%), tests_pri_0: 2391 (31.9%), check_spf: 464 (6.2%), poll_dns_idle: 5302 (70.8%), check_dcc: 123 (1.6%), check_razor2: 1176 (15.7%), check_pyzor: 201 (2.7%), tests_pri_500: 4885 (65.2%), learn: 112 (1.5%), get_report: 1.78 (0.0%)
May 13 06:27:21 mx amavis[3553]: (03553-01) updating snmp variables in BDB
May 13 06:27:21 mx amavis[3553]: (03553-01) get_deadline check done - deadline in 472.3 s, set to 331.000 s
May 13 06:27:21 mx amavis[3553]: (03553-01) prolong_timer check done: timer 331, was 331, deadline in 472.3 s
May 13 06:27:21 mx amavis[3553]: (03553-01) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 21CB823A6E"
May 13 06:27:21 mx amavis[3553]: (03553-01) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 21CB823A6E
May 13 06:27:21 mx postfix/smtp[3576]: ECCBF23A62: to=<target@mydomain.org>, relay=127.0.0.1[127.0.0.1]:10024, delay=8.3, delays=0.51/0.01/0.01/7.8, 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 21CB823A6E)
May 13 06:27:21 mx amavis[3553]: (03553-01) switch_to_client_time 480 s, smtp response sent
May 13 06:27:21 mx amavis[3553]: (03553-01) TempDir::strip: /var/spool/amavisd/tmp/amavis-20160513T062713-03553-2ZzyALCj
May 13 06:27:21 mx amavis[3553]: (03553-01) rmdir_recursively: /var/spool/amavisd/tmp/amavis-20160513T062713-03553-2ZzyALCj/parts, excl=1
May 13 06:27:21 mx postfix/qmgr[31913]: ECCBF23A62: removed
May 13 06:27:21 mx amavis[3553]: (03553-01) size: 12428, TIMING [total 7776 ms] - sql-prepare: 2.7 (0%)0, SMTP greeting: 2.2 (0%)0, SMTP EHLO: 1.8 (0%)0, SMTP pre-MAIL: 2.2 (0%)0, mkdir tempdir: 1.1 (0%)0, create email.txt: 5 (0%)0, sql-connect: 7 (0%)0, lookup_sql: 0.8 (0%)0, SMTP pre-DATA-flush: 1.9 (0%)0, SMTP DATA: 22 (0%)1, check_init: 0.5 (0%)1, digest_hdr: 55 (1%)1, digest_body_dkim: 3.0 (0%)1, collect_info: 3.3 (0%)1, gen_mail_id: 17 (0%)2, mkdir parts: 2.8 (0%)2, mime_decode: 14 (0%)2, get-file-type2: 19 (0%)2, parts_decode: 0.3 (0%)2, check_header: 1.2 (0%)2, AV-scan-1: 30 (0%)3, spam-wb-list: 2.9 (0%)3, SA msg read: 0.8 (0%)3, SA parse: 4.3 (0%)3, SA check: 7474 (96%)99, decide_mail_destiny: 17 (0%)99, notif-quar: 0.7 (0%)99, fwd-connect: 19 (0%)99, fwd-mail-pip: 8 (0%)99, fwd-rcpt-pip: 0.4 (0%)99, fwd-data-chkpnt: 0.1 (0%)99, write-header: 1.1 (0%)99, fwd-data-contents: 0.3 (0%)99, fwd-end-chkpnt: 17 (0%)100, prepare-dsn: 2.6 (0%)100, report: 3.3 (0%)100, main_log_entry: 9 (0%)100, s...
May 13 06:27:21 mx amavis[3553]: (03553-01) ...ql-update: 16 (0%)100, update_snmp: 2.5 (0%)100, SMTP pre-response: 0.5 (0%)100, SMTP response: 0.8 (0%)100, unlink-3-files: 0.5 (0%)100, rundown: 0.8 (0%)100
May 13 06:27:21 mx amavis[3553]: (03553-01) idle_proc, 6: was busy, 7752.9 ms, total idle 0.001 s, busy 7.776 s
May 13 06:27:21 mx amavis[3553]: (03553-01) idle_proc, 5: was idle, 0.2 ms, total idle 0.001 s, busy 7.776 s
May 13 06:27:21 mx amavis[3553]: (03553-01) ESMTP< QUIT\r\n
May 13 06:27:21 mx amavis[3553]: (03553-01) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 336.000 s
May 13 06:27:21 mx amavis[3553]: (03553-01) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 336, was 480, deadline in 480.0 s
May 13 06:27:21 mx amavis[3553]: (03553-01) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
May 13 06:27:21 mx amavis[3553]: (03553-01) switch_to_client_time 480 s, smtp response sent
May 13 06:27:21 mx amavis[3553]: (03553-01) SMTP session over, timer stopped
May 13 06:27:21 mx amavis[3553]: (03553-01) extra modules loaded: unicore/lib/gc_sc/Alnum.pl, unicore/lib/gc_sc/Alpha.pl
May 13 06:27:21 mx amavis[3553]: (03553-01) exiting process_request
May 13 06:27:21 mx amavis[3553]: (03553-01) idle_proc, bye: was busy, 3.3 ms, total idle 0.001 s, busy 7.779 s
May 13 06:27:21 mx amavis[3553]: (03553-01) load: 100 %, total idle 0.001 s, busy 7.779 s
May 13 06:27:21 mx postfix/pipe[3583]: 21CB823A6E: to=<target@mydomain.org>, relay=dovecot, delay=0.18, delays=0.02/0.01/0/0.15, dsn=2.0.0, status=sent (delivered via dovecot service)
May 13 06:27:21 mx postfix/qmgr[31913]: 21CB823A6E: removed