Here you go. The log has been anonymized. There is also a clamav error that it cannot connect to socket. This appeared after the bug fix.
Jun 11 13:19:12 mail postfix/postscreen[3319]: CONNECT from [209.85.213.44]:33656 to [mail.srv.ip.addr]:25
Jun 11 13:19:18 mail postfix/postscreen[3319]: PASS NEW [209.85.213.44]:33656
Jun 11 13:19:18 mail postfix/smtpd[3738]: connect from mail-vk0-f44.google.com[209.85.213.44]
Jun 11 13:19:18 mail postfix/smtpd[3738]: Anonymous TLS connection established from mail-vk0-f44.google.com[209.85.213.44]: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Jun 11 13:19:18 mail postfix/smtpd[3738]: BBBC480617: client=mail-vk0-f44.google.com[209.85.213.44]
Jun 11 13:19:18 mail postfix/cleanup[4657]: BBBC480617: message-id=<CAOAxBm+YqzFRTv-wtpVHKz1LKqD28NtzKCR2h1ZvE2jOFcz7qg@mail.gmail.com>
Jun 11 13:19:18 mail postfix/qmgr[3126]: BBBC480617: from=<mygoogletestacct@gmail.com>, size=3064, nrcpt=1 (queue active)
Jun 11 13:19:18 mail amavis[3993]: (03993-03) Net::Server: 2018/06/11-13:19:18 CONNECT TCP Peer: "[127.0.0.1]:51872" Local: "[127.0.0.1]:10024"
Jun 11 13:19:18 mail amavis[3993]: idle_proc, hi : was idle, 212796.2 ms, total idle 428.923 s, busy 78.843 s
Jun 11 13:19:18 mail amavis[3993]: loaded base policy bank
Jun 11 13:19:18 mail amavis[3993]: lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
Jun 11 13:19:18 mail amavis[3993]: process_request: fileno sock=10, STDIN=0, STDOUT=1
Jun 11 13:19:18 mail amavis[3993]: get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 288.000 s
Jun 11 13:19:18 mail amavis[3993]: prolong_timer switch_to_my_time(new request): timer 288, was 0, deadline in 480.0 s
Jun 11 13:19:18 mail amavis[3993]: process_request: suggested_protocol="" on a TCP socket
Jun 11 13:19:18 mail amavis[3993]: (03993-04) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Jun 11 13:19:18 mail amavis[3993]: (03993-04) switch_to_client_time 480 s, smtp response sent
Jun 11 13:19:18 mail amavis[3993]: (03993-04) idle_proc, 4: was busy, 1.2 ms, total idle 428.923 s, busy 78.844 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) smtp readline: read 26 bytes, new size: 26
Jun 11 13:19:18 mail amavis[3993]: (03993-04) idle_proc, 5: was idle, 7.7 ms, total idle 428.931 s, busy 78.844 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) SMTP< EHLO mail.domain.com\r\n
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 288.000 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 288, was 480, deadline in 480.0 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 250-[127.0.0.1]
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 250-VRFY
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 250-PIPELINING
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 250-SIZE
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 250-ENHANCEDSTATUSCODES
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 250-8BITMIME
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 250-SMTPUTF8
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 250-DSN
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
Jun 11 13:19:18 mail amavis[3993]: (03993-04) switch_to_client_time 480 s, smtp response sent
Jun 11 13:19:18 mail amavis[3993]: (03993-04) idle_proc, 6: was busy, 0.6 ms, total idle 428.931 s, busy 78.844 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) smtp readline: read 277 bytes, new size: 277
Jun 11 13:19:18 mail amavis[3993]: (03993-04) idle_proc, 5: was idle, 0.6 ms, total idle 428.932 s, busy 78.844 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP< XFORWARD NAME=mail-vk0-f44.google.com ADDR=209.85.213.44 PORT=33656\r\n
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 250 2.5.0 Ok XFORWARD
Jun 11 13:19:18 mail amavis[3993]: (03993-04) switch_to_client_time 480 s, smtp response sent
Jun 11 13:19:18 mail amavis[3993]: (03993-04) idle_proc, 6: was busy, 0.3 ms, total idle 428.932 s, busy 78.845 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) idle_proc, 5: was idle, 0.0 ms, total idle 428.932 s, busy 78.845 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP< XFORWARD PROTO=ESMTP HELO=mail-vk0-f44.google.com IDENT=BBBC480617 SOURCE=REMOTE\r\n
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 250 2.5.0 Ok XFORWARD
Jun 11 13:19:18 mail amavis[3993]: (03993-04) switch_to_client_time 480 s, smtp response sent
Jun 11 13:19:18 mail amavis[3993]: (03993-04) idle_proc, 6: was busy, 0.3 ms, total idle 428.932 s, busy 78.845 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) idle_proc, 5: was idle, 0.0 ms, total idle 428.932 s, busy 78.845 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP< MAIL FROM:<mygoogletestacct@gmail.com> SIZE=3064\r\n
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 288.000 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 288, was 480, deadline in 480.0 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) check_mail_begin_task: task_count=4
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="209.85.213.44", no match
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup [debug_sender] => undef, "mygoogletestacct@gmail.com" does not match
Jun 11 13:19:18 mail amavis[3993]: (03993-04) mesage size set to a declared size 3064
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 250 2.1.0 Sender <mygoogletestacct@gmail.com> OK
Jun 11 13:19:18 mail amavis[3993]: (03993-04) switch_to_client_time 480 s, smtp response sent
Jun 11 13:19:18 mail amavis[3993]: (03993-04) idle_proc, 6: was busy, 0.9 ms, total idle 428.932 s, busy 78.846 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) idle_proc, 5: was idle, 0.0 ms, total idle 428.932 s, busy 78.846 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP< RCPT TO:<jorge@domain.com> ORCPT=rfc822;jorge@domain.com\r\n
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 288.000 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 288, was 480, deadline in 480.0 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup => undef, "jorge@domain.com", no lookup tables
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup: (scalar) matches, result="1"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup [local_domains] => true, "jorge@domain.com" matches, result="1", matching_key="(constant:1)"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) query_keys: cached jorge@domain.com
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql sel_policy "jorge@domain.com", query args: [jorge@domain.com,-3], [jorge,-3], [@domain.com,-3], [@.domain.com,-3], [@.com,-3], [@.,-3]
Jun 11 13:19:18 mail amavis[3993]: (03993-04) 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
Jun 11 13:19:18 mail amavis[3993]: (03993-04) sql begin, nontransaction
Jun 11 13:19:18 mail amavis[3993]: (03993-04) sql: executing clause (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
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql: "jorge@domain.com" matches catchall, local=>undef
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql(jorge@domain.com) matches, result=(id=>"3", priority=>"7", policy_id=>"3", email=>"jorge@domain.com", fullname=>-, id=>"3", policy_name=>"policy_user_jorge@domain.com", virus_lover=>"N", spam_lover=>"N", unchecked_lover=>"N", banned_files_lover=>"N", bad_header_lover=>"N", bypass_virus_checks=>"N", bypass_spam_checks=>"N", bypass_banned_checks=>"N", bypass_header_checks=>"N", virus_quarantine_to=>"sql:", spam_quarantine_to=>"sql:", banned_quarantine_to=>"sql:", unchecked_quarantine_to=>-, bad_header_quarantine_to=>"sql:", clean_quarantine_to=>-, archive_quarantine_to=>-, spam_tag_level=>"-999", spam_tag2_level=>"7", spam_tag3_level=>"7", spam_kill_level=>"7", spam_dsn_cutoff_level=>"10", spam_quarantine_cutoff_level=>"20", addr_extension_virus=>-, addr_extension_spam=>-, addr_extension_banned=>-, addr_extension_bad_header=>-, warnvirusrecip=>-, warnbannedrecip=>-, warnbadhrecip=>-, newvirus_admin=>-, virus_admin=>-, banned_admin=...
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ...>-, bad_header_admin=>-, spam_admin=>-, spam_subject_tag=>-, spam_subject_tag2=>-, spam_subject_tag3=>-, message_size_limit=>-, banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"3")
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql(jorge@domain.com) matches, result=(id=>"1", priority=>"0", policy_id=>"1", email=>"@.", fullname=>-, id=>"1", policy_name=>"@.", virus_lover=>"N", spam_lover=>"Y", unchecked_lover=>-, banned_files_lover=>"Y", bad_header_lover=>"Y", bypass_virus_checks=>"N", bypass_spam_checks=>"N", bypass_banned_checks=>"N", bypass_header_checks=>"N", virus_quarantine_to=>"virus-quarantine", spam_quarantine_to=>"", banned_quarantine_to=>"", unchecked_quarantine_to=>-, bad_header_quarantine_to=>"", clean_quarantine_to=>-, archive_quarantine_to=>-, spam_tag_level=>-, spam_tag2_level=>-, spam_tag3_level=>-, spam_kill_level=>-, spam_dsn_cutoff_level=>-, spam_quarantine_cutoff_level=>-, addr_extension_virus=>-, addr_extension_spam=>-, addr_extension_banned=>-, addr_extension_bad_header=>-, warnvirusrecip=>-, warnbannedrecip=>-, warnbadhrecip=>-, newvirus_admin=>-, virus_admin=>-, banned_admin=>-, bad_header_admin=>-, spam_admin=>-, spam_subject_tag=>-, spam_s...
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ...ubject_tag2=>-, spam_subject_tag3=>-, message_size_limit=>-, banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"1", local=>-)
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql_field(message_size_limit) rec=0, "jorge@domain.com" result: undef
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql_field(message_size_limit) rec=1, "jorge@domain.com" result: undef
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup [message_size_limit] => undef, "jorge@domain.com" does not match
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 250 2.1.5 Recipient <jorge@domain.com> OK
Jun 11 13:19:18 mail postfix/smtpd[3738]: disconnect from mail-vk0-f44.google.com[209.85.213.44] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Jun 11 13:19:18 mail amavis[3993]: (03993-04) switch_to_client_time 480 s, smtp response sent
Jun 11 13:19:18 mail amavis[3993]: (03993-04) idle_proc, 6: was busy, 8.0 ms, total idle 428.932 s, busy 78.854 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) idle_proc, 5: was idle, 0.1 ms, total idle 428.932 s, busy 78.854 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP< DATA\r\n
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 288.000 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) prolong_timer switch_to_my_time(rx SMTP DATA): timer 288, was 480, deadline in 480.0 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP [127.0.0.1]:10024 /var/lib/amavis/tmp/amavis-20180611T131051-03993-j7Deenma: <mygoogletestacct@gmail.com> -> <jorge@domain.com> SIZE=3064 Received: from mail.domain.com ([127.0.0.1]) by mail.domain.com (mail.domain.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <jorge@domain.com>; Mon, 11 Jun 2018 13:19:18 -0600 (MDT)
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Jun 11 13:19:18 mail amavis[3993]: (03993-04) switch_to_client_time 480 s, smtp response sent
Jun 11 13:19:18 mail amavis[3993]: (03993-04) switch_to_client_time 480 s, receiving data
Jun 11 13:19:18 mail amavis[3993]: (03993-04) smtp copy: read 3073 bytes into buffer, new size: 3073
Jun 11 13:19:18 mail amavis[3993]: (03993-04) smtp copy: 6 bytes still buffered at end
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 288.000 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) prolong_timer switch_to_my_time(rx data-end): timer 288, was 480, deadline in 480.0 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ESMTP< .<CR><LF>
Jun 11 13:19:18 mail amavis[3993]: (03993-04) smtp connection cache, dt: 212.8, state: 0
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_deadline digest_pre - deadline in 480.0 s, set to 288.000 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) prolong_timer digest_pre: timer 288, was 288, deadline in 480.0 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_body_digest: reading header section from memory
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_body_digest: feeding header section to DKIM verifier
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_body_digest: sending h/b separator to DKIM
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_deadline digest_hdr - deadline in 480.0 s, set to 288.000 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) prolong_timer digest_hdr: timer 288, was 288, deadline in 480.0 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_body_digest: reading mail body from memory, 1 DKIM signatures
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_deadline digest_body - deadline in 480.0 s, set to 288.000 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) prolong_timer digest_body: timer 288, was 288, deadline in 480.0 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_body_digest: message size 3064, header+sep 2611, body 453
Jun 11 13:19:18 mail amavis[3993]: (03993-04) body type (8bit-MIMEtransport): unlabeled, good (h=0, b=0)
Jun 11 13:19:18 mail amavis[3993]: (03993-04) body hash: 9c1c0d8f31d09712f91e3f596eb1f5eb
Jun 11 13:19:18 mail amavis[3993]: (03993-04) references: <CAOAxBmLLYyGm8RNkRwyUctc9BGtuT0L-aLvxLML1DADbPX1emA@mail.gmail.com>
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ip_from_received: 209.85.213.44
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ip_from_received: no IP address in: by mail-vk0-f44.google.com with SMTP id 200-v6so12981612vkc.0\n for <jorge@domain.com>; Mon, 11 Jun 2018 12:19:18 -0700 (PDT)\n
Jun 11 13:19:18 mail amavis[3993]: (03993-04) ip_from_received: no IP address in: by 2002:a67:7c5:0:0:0:0:0 with HTTP; Mon, 11 Jun 2018 12:19:11 -0700 (PDT)\n
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_ip_acl (public_nets) arr.obj: key="209.85.213.44" matches "::ffff:0:0/96", result=1
Jun 11 13:19:18 mail amavis[3993]: (03993-04) trace: ESMTP://[127.0.0.1]:51872 < ESMTPS://[209.85.213.44]:33656 < SMTP://x < HTTP://x
Jun 11 13:19:18 mail amavis[3993]: (03993-04) dkim: public key s=20161025 d=gmail.com k=rsa, 2048-bit key
Jun 11 13:19:18 mail amavis[3993]: (03993-04) query_keys: cached mygoogletestacct@gmail.com
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_hash(mygoogletestacct@gmail.com), no matches
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup [AuthToPB,author_to_policy_bank] => undef, "mygoogletestacct@gmail.com" does not match
Jun 11 13:19:18 mail amavis[3993]: (03993-04) query_keys: cached mygoogletestacct@gmail.com
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_hash(mygoogletestacct@gmail.com), no matches
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup [AuthToPB,author_to_policy_bank] => undef, "mygoogletestacct@gmail.com" does not match
Jun 11 13:19:18 mail amavis[3993]: (03993-04) dkim: VALID Author+Sender+MailFrom signature by d=gmail.com, From: <mygoogletestacct@gmail.com>, a=rsa-sha256, c=relaxed/relaxed, s=20161025, i=@gmail.com
Jun 11 13:19:18 mail amavis[3993]: (03993-04) Original mail size: 3064; quota set to: 1532000 bytes (fmin=5, fmax=500, qmin=102400, qmax=524288000)
Jun 11 13:19:18 mail amavis[3993]: (03993-04) sql begin, nontransaction
Jun 11 13:19:18 mail amavis[3993]: (03993-04) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Jun 11 13:19:18 mail amavis[3993]: (03993-04) save_info_preliminary 2ozrh0W03q0Y, sender id: 5083, mygoogletestacct@gmail.com, exists
Jun 11 13:19:18 mail amavis[3993]: (03993-04) sql begin, nontransaction
Jun 11 13:19:18 mail amavis[3993]: (03993-04) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Jun 11 13:19:18 mail amavis[3993]: (03993-04) orcpt_encode rfc822, jorge@domain.com, smtputf8
Jun 11 13:19:18 mail amavis[3993]: (03993-04) save_info_preliminary 2ozrh0W03q0Y, recip id: 3937, jorge@domain.com (ORCPT rfc822;jorge@domain.com), exists
Jun 11 13:19:18 mail amavis[3993]: (03993-04) sql begin transaction
Jun 11 13:19:18 mail amavis[3993]: (03993-04) sql: executing clause (11 args): INSERT INTO msgs (partition_tag, mail_id, secret_id, am_id, time_num, time_iso, sid, policy, client_addr, size, host) VALUES (?,?,?,?,?,?,?,?,?,?,?)
Jun 11 13:19:18 mail amavis[3993]: (03993-04) sql commit
Jun 11 13:19:18 mail amavis[3993]: (03993-04) Checking: 2ozrh0W03q0Y [209.85.213.44] <mygoogletestacct@gmail.com> -> <jorge@domain.com>
Jun 11 13:19:18 mail amavis[3993]: (03993-04) 2822.From: <mygoogletestacct@gmail.com>
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql_field(local) rec=0, "jorge@domain.com" result: "1"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql_field, no such fields: local
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup [local_domains] => true, "jorge@domain.com" matches, result="1", matching_key="/cached/"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql_field(bypass_virus_checks) rec=0, "jorge@domain.com" result: "0"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup [bypass_virus_checks] => false, "jorge@domain.com" matches, result="0", matching_key="/cached/"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql_field(bypass_banned_checks) rec=0, "jorge@domain.com" result: "0"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup [bypass_banned_checks] => false, "jorge@domain.com" matches, result="0", matching_key="/cached/"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql_field(bypass_spam_checks) rec=0, "jorge@domain.com" result: "0"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup [bypass_spam_checks] => false, "jorge@domain.com" matches, result="0", matching_key="/cached/"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql_field(id) rec=0, "jorge@domain.com" result: "3"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql_field(id) rec=1, "jorge@domain.com" result: "1"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup [users.id], 2 matches for "jorge@domain.com", results: "/cached/"=>"3", "/cached/"=>"1"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup_sql_field(policy_id) rec=0, "jorge@domain.com" result: "3"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) lookup [users.policy_id] => true, "jorge@domain.com" matches, result="3", matching_key="/cached/"
Jun 11 13:19:18 mail amavis[3993]: (03993-04) Extracting mime components from a string
Jun 11 13:19:18 mail amavis[3993]: (03993-04) Issued a new file name: p001
Jun 11 13:19:18 mail amavis[3993]: (03993-04) Issued a new file name: p002
Jun 11 13:19:18 mail amavis[3993]: (03993-04) Issued a new pseudo part: p003
Jun 11 13:19:18 mail amavis[3993]: (03993-04) p003 1 Content-Type: multipart/alternative
Jun 11 13:19:18 mail amavis[3993]: (03993-04) Charging 71 bytes to remaining quota 1532000 (out of 1532000, (0%)) - by mime_decode
Jun 11 13:19:18 mail amavis[3993]: (03993-04) p001 1/1 Content-Type: text/plain, size: 71 B, name:
Jun 11 13:19:18 mail amavis[3993]: (03993-04) reparenting p001 from p000 to p003
Jun 11 13:19:18 mail amavis[3993]: (03993-04) Charging 185 bytes to remaining quota 1531929 (out of 1532000, (0%)) - by mime_decode
Jun 11 13:19:18 mail amavis[3993]: (03993-04) p002 1/2 Content-Type: text/html, size: 185 B, name:
Jun 11 13:19:18 mail amavis[3993]: (03993-04) reparenting p002 from p000 to p003
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_deadline mime_decode - deadline in 479.9 s, set to 288.000 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) prolong_timer mime_decode: timer 288, was 288, deadline in 479.9 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) get_deadline mime_decode-1 - deadline in 479.9 s, set to 288.000 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) prolong_timer mime_decode-1: timer 288, was 288, deadline in 479.9 s
Jun 11 13:19:18 mail amavis[3993]: (03993-04) decode_parts: level=1, #parts=3 : p001, p002, p003
Jun 11 13:19:18 mail amavis[3993]: (03993-04) running file(1) on 2 files, arglist size 23
Jun 11 13:19:18 mail amavis[3993]: (03993-04) run_command: [4659] /usr/bin/file p001 p002 </dev/null 2>&1
Jun 11 13:19:18 mail amavis[4659]: (03993-04) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jun 11 13:19:18 mail amavis[4659]: (03993-04) open_on_specific_fd: target fd1 closing, to become (65) &=14
Jun 11 13:19:18 mail amavis[4659]: (03993-04) open_on_specific_fd: target fd1 dup2 from fd14 (65) &=14
Jun 11 13:19:18 mail amavis[4659]: (03993-04) open_on_specific_fd: source fd14 closed
Jun 11 13:19:18 mail amavis[4659]: (03993-04) open_on_specific_fd: target fd2 closing, to become (65) &1
Jun 11 13:19:18 mail amavis[4659]: (03993-04) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jun 11 13:19:19 mail amavis[3993]: (03993-04) result line from file(1): p001: ASCII text\n
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup_re("ASCII text") matches key "(?^i:^(ASCII|text)\\b)", result="asc"
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup [map_full_type_to_short_type] => true, "ASCII text" matches, result="asc", matching_key="(?^i:^(ASCII|text)\\b)"
Jun 11 13:19:19 mail amavis[3993]: (03993-04) File-type of p001: ASCII text; (asc)
Jun 11 13:19:19 mail amavis[3993]: (03993-04) result line from file(1): p002: ASCII text\n
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup_re("ASCII text") matches key "(?^i:^(ASCII|text)\\b)", result="asc"
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup [map_full_type_to_short_type] => true, "ASCII text" matches, result="asc", matching_key="(?^i:^(ASCII|text)\\b)"
Jun 11 13:19:19 mail amavis[3993]: (03993-04) File-type of p002: ASCII text; (asc)
Jun 11 13:19:19 mail amavis[3993]: (03993-04) decompose_part: p001 - atomic
Jun 11 13:19:19 mail amavis[3993]: (03993-04) decompose_part: p002 - atomic
Jun 11 13:19:19 mail amavis[3993]: (03993-04) get_deadline parts_decode - deadline in 479.9 s, set to 288.000 s
Jun 11 13:19:19 mail amavis[3993]: (03993-04) prolong_timer parts_decode: timer 288, was 288, deadline in 479.9 s
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup_sql_field(bypass_header_checks) rec=0, "jorge@domain.com" result: "0"
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup [bypass_header_checks] => false, "jorge@domain.com" matches, result="0", matching_key="/cached/"
Jun 11 13:19:19 mail amavis[3993]: (03993-04) check_header: 0, OK
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup_sql_field(bypass_header_checks) rec=0, "jorge@domain.com" result: "0"
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup [bypass_header_checks] => false, "jorge@domain.com" matches, result="0", matching_key="/cached/"
Jun 11 13:19:19 mail amavis[3993]: (03993-04) Checking for banned types and filenames
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup_sql_field(banned_rulenames) rec=0, "jorge@domain.com" result: undef
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup_sql_field(banned_rulenames) rec=1, "jorge@domain.com" result: undef
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup: (scalar) matches, result="DEFAULT"
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup [banned_filename], 1 matches for "jorge@domain.com", results: "(constant:DEFAULT)"=>"DEFAULT"
Jun 11 13:19:19 mail amavis[3993]: (03993-04) collect banned table[0]: jorge@domain.com, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x55ebb16b2008)
Jun 11 13:19:19 mail amavis[3993]: (03993-04) starting banned checks - traversing message structure tree
Jun 11 13:19:19 mail amavis[3993]: (03993-04) check_for_banned (p003,p001) multipart/alternative | text/plain,.asc
Jun 11 13:19:19 mail amavis[3993]: (03993-04) doing banned check for jorge@domain.com on multipart/alternative | text/plain,.asc
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup_re(["multipart/alternative","text/plain",".asc"]), no matches
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup [check_bann:jorge@domain.com] => undef, ["multipart/alternative","text/plain",".asc"] does not match
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup_re("P=p003\tL=1\tM=multipart/alternative\nP=p001\tL=1/1\tM=text/plain\tT=asc"), no matches
Jun 11 13:19:19 mail amavis[3993]: (03993-04) 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
Jun 11 13:19:19 mail amavis[3993]: (03993-04) p.path jorge@domain.com: "P=p003,L=1,M=multipart/alternative | P=p001,L=1/1,M=text/plain,T=asc"
Jun 11 13:19:19 mail amavis[3993]: (03993-04) check_for_banned (p003,p002) multipart/alternative | text/html,.asc
Jun 11 13:19:19 mail amavis[3993]: (03993-04) doing banned check for jorge@domain.com on multipart/alternative | text/html,.asc
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup_re(["multipart/alternative","text/html",".asc"]), no matches
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup [check_bann:jorge@domain.com] => undef, ["multipart/alternative","text/html",".asc"] does not match
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup_re("P=p003\tL=1\tM=multipart/alternative\nP=p002\tL=1/2\tM=text/html\tT=asc"), no matches
Jun 11 13:19:19 mail amavis[3993]: (03993-04) 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
Jun 11 13:19:19 mail amavis[3993]: (03993-04) p.path jorge@domain.com: "P=p003,L=1,M=multipart/alternative | P=p002,L=1/2,M=text/html,T=asc"
Jun 11 13:19:19 mail amavis[3993]: (03993-04) banned check: any=0, all=N (1)
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup_re("MAIL"), no matches
Jun 11 13:19:19 mail amavis[3993]: (03993-04) lookup [keep_decoded_original] => undef, "MAIL" does not match
Jun 11 13:19:19 mail amavis[3993]: (03993-04) Calling virus scanners, 2 files to scan in /var/lib/amavis/tmp/amavis-20180611T131051-03993-j7Deenma/parts
Jun 11 13:19:19 mail amavis[3993]: (03993-04) invoking av-scanner clamav-socket
Jun 11 13:19:19 mail amavis[3993]: (03993-04) ask_daemon: proto=DFLT, spawn=0, (clamav-socket) /var/run/clamav/clamd.ctl
Jun 11 13:19:19 mail amavis[3993]: (03993-04) run_av (clamav-socket): query template(1,1): CONTSCAN {}\n
Jun 11 13:19:19 mail amavis[3993]: (03993-04) get_deadline run_av_pre - deadline in 479.9 s, set to 288.000 s
Jun 11 13:19:19 mail amavis[3993]: (03993-04) prolong_timer run_av_pre: timer 288, was 288, deadline in 479.9 s
Jun 11 13:19:19 mail amavis[3993]: (03993-04) get_deadline run_av_scan - deadline in 479.9 s, set to 288.000 s
Jun 11 13:19:19 mail amavis[3993]: (03993-04) prolong_timer run_av_scan: timer 288, was 288, deadline in 479.9 s
Jun 11 13:19:19 mail amavis[3993]: (03993-04) run_av Using (clamav-socket): (code) CONTSCAN /var/lib/amavis/tmp/amavis-20180611T131051-03993-j7Deenma/parts\n
Jun 11 13:19:19 mail amavis[3993]: (03993-04) get_deadline ask_daemon_internal_connect_pre - deadline in 479.9 s, set to 288.000 s
Jun 11 13:19:19 mail amavis[3993]: (03993-04) get_deadline ask_daemon_internal_connect - deadline in 479.9 s, set to 10.000 s
Jun 11 13:19:19 mail amavis[3993]: (03993-04) prolong_timer ask_daemon_internal_connect: timer 10, was 288, deadline in 479.9 s
Jun 11 13:19:19 mail amavis[3993]: (03993-04) clamav-socket: Connecting to socket /var/run/clamav/clamd.ctl
Jun 11 13:19:19 mail amavis[3993]: (03993-04) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.ctl, timeout set to 10
Jun 11 13:19:19 mail amavis[3993]: (03993-04) (!)connect to /var/run/clamav/clamd.ctl failed, attempt #1: Can't connect to a UNIX socket /var/run/clamav/clamd.ctl: No such file or directory
Jun 11 13:19:19 mail amavis[3993]: (03993-04) get_deadline ask_daemon_internal - deadline in 479.9 s, set to 288.000 s
Jun 11 13:19:19 mail amavis[3993]: (03993-04) prolong_timer ask_daemon_internal: timer 288, was 10, deadline in 479.9 s
Jun 11 13:19:19 mail amavis[3993]: (03993-04) clamav-socket: All attempts (1) failed connecting to /var/run/clamav/clamd.ctl, retrying (1)
Jun 11 13:19:19 mail amavis[3993]: (03993-04) clamav-socket: sleeping for 1 s
Jun 11 13:19:20 mail amavis[3993]: (03993-04) get_deadline ask_daemon_internal_connect - deadline in 478.9 s, set to 10.000 s
Jun 11 13:19:20 mail amavis[3993]: (03993-04) prolong_timer ask_daemon_internal_connect: timer 10, was 287, deadline in 478.9 s
Jun 11 13:19:20 mail amavis[3993]: (03993-04) clamav-socket: Connecting to socket /var/run/clamav/clamd.ctl, retry #1
Jun 11 13:19:20 mail amavis[3993]: (03993-04) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.ctl, timeout set to 10
Jun 11 13:19:20 mail amavis[3993]: (03993-04) (!)connect to /var/run/clamav/clamd.ctl failed, attempt #1: Can't connect to a UNIX socket /var/run/clamav/clamd.ctl: No such file or directory
Jun 11 13:19:20 mail amavis[3993]: (03993-04) get_deadline ask_daemon_internal - deadline in 478.9 s, set to 288.000 s
Jun 11 13:19:20 mail amavis[3993]: (03993-04) prolong_timer ask_daemon_internal: timer 288, was 10, deadline in 478.9 s
Jun 11 13:19:20 mail amavis[3993]: (03993-04) (!)clamav-socket: All attempts (1) failed connecting to /var/run/clamav/clamd.ctl, retrying (2)
Jun 11 13:19:20 mail amavis[3993]: (03993-04) clamav-socket: sleeping for 6 s
Jun 11 13:19:26 mail amavis[3993]: (03993-04) get_deadline ask_daemon_internal_connect - deadline in 472.9 s, set to 10.000 s
Jun 11 13:19:26 mail amavis[3993]: (03993-04) prolong_timer ask_daemon_internal_connect: timer 10, was 282, deadline in 472.9 s
Jun 11 13:19:26 mail amavis[3993]: (03993-04) clamav-socket: Connecting to socket /var/run/clamav/clamd.ctl, retry #2
Jun 11 13:19:26 mail amavis[3993]: (03993-04) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.ctl, timeout set to 10
Jun 11 13:19:26 mail amavis[3993]: (03993-04) (!)connect to /var/run/clamav/clamd.ctl failed, attempt #1: Can't connect to a UNIX socket /var/run/clamav/clamd.ctl: No such file or directory
Jun 11 13:19:26 mail amavis[3993]: (03993-04) get_deadline ask_daemon_internal - deadline in 472.9 s, set to 284.000 s
Jun 11 13:19:26 mail amavis[3993]: (03993-04) prolong_timer ask_daemon_internal: timer 284, was 10, deadline in 472.9 s
Jun 11 13:19:26 mail amavis[3993]: (03993-04) get_deadline run_av_5 - deadline in 472.9 s, set to 284.000 s
Jun 11 13:19:26 mail amavis[3993]: (03993-04) prolong_timer run_av_5: timer 284, was 284, deadline in 472.9 s
Jun 11 13:19:26 mail amavis[3993]: (03993-04) (!)clamav-socket av-scanner FAILED: run_av error: Too many retries to talk to /var/run/clamav/clamd.ctl (All attempts (1) failed connecting to /var/run/clamav/clamd.ctl) at (eval 112) line 613.\n
Jun 11 13:19:26 mail amavis[3993]: (03993-04) (!)WARN: all primary virus scanners failed, considering backups
Jun 11 13:19:26 mail amavis[3993]: (03993-04) invoking av-scanner clamav-clamscan
Jun 11 13:19:26 mail amavis[3993]: (03993-04) run_av (clamav-clamscan): query template(0,1): --stdout --disable-summary -r --tempdir=/var/lib/amavis/tmp {}
Jun 11 13:19:26 mail amavis[3993]: (03993-04) get_deadline run_av_pre - deadline in 472.9 s, set to 284.000 s
Jun 11 13:19:26 mail amavis[3993]: (03993-04) prolong_timer run_av_pre: timer 284, was 284, deadline in 472.9 s
Jun 11 13:19:26 mail amavis[3993]: (03993-04) get_deadline run_av_scan - deadline in 472.9 s, set to 284.000 s
Jun 11 13:19:26 mail amavis[3993]: (03993-04) prolong_timer run_av_scan: timer 284, was 284, deadline in 472.9 s
Jun 11 13:19:26 mail amavis[3993]: (03993-04) run_av Using (clamav-clamscan): /usr/bin/clamscan --stdout --disable-summary -r --tempdir=/var/lib/amavis/tmp /var/lib/amavis/tmp/amavis-20180611T131051-03993-j7Deenma/parts
Jun 11 13:19:26 mail amavis[3993]: (03993-04) run_command: [4667] /usr/bin/clamscan --stdout --disable-summary -r --tempdir=/var/lib/amavis/tmp /var/lib/amavis/tmp/amavis-20180611T131051-03993-j7Deenma/parts </dev/null 2>&1
Jun 11 13:19:26 mail amavis[4667]: (03993-04) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jun 11 13:19:26 mail amavis[4667]: (03993-04) open_on_specific_fd: target fd1 closing, to become (65) &=14
Jun 11 13:19:26 mail amavis[4667]: (03993-04) open_on_specific_fd: target fd1 dup2 from fd14 (65) &=14
Jun 11 13:19:26 mail amavis[4667]: (03993-04) open_on_specific_fd: source fd14 closed
Jun 11 13:19:26 mail amavis[4667]: (03993-04) open_on_specific_fd: target fd2 closing, to become (65) &1
Jun 11 13:19:26 mail amavis[4667]: (03993-04) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jun 11 13:19:42 mail amavis[3993]: (03993-04) collect_results from [4667] (clamav-clamscan), 426 bytes, (limit 204800)
Jun 11 13:19:42 mail amavis[3993]: (03993-04) get_deadline run_av_4 - deadline in 456.0 s, set to 274.000 s
Jun 11 13:19:42 mail amavis[3993]: (03993-04) prolong_timer run_av_4: timer 274, was 267, deadline in 456.0 s
Jun 11 13:19:42 mail amavis[3993]: (03993-04) run_av: /usr/bin/clamscan exit 0, WARNING: Ignoring deprecated option --disable-summary\n/var/lib/amavis/tmp/amavis-20180611T131051-03993-j7Deenma/parts/p001: OK\n/var/lib/amavis/tmp/amavis-20180611T131051-03993-j7Deenma/parts/p002: OK\n\n----------- SCAN SUMMARY -----------\nKnown viruses: 6545092\nEngine version: 0.99.4\nScanned directories: 1\nScanned files: 2\nInfected files: 0\nData scanned: 0.00 MB\nData read: 0.00 MB (ratio 0.00:1)\nTime: 16.792 sec (0 m 16 s)
[b]Jun 11 13:19:42 mail amavis[3993]: (03993-04) run_av (clamav-clamscan): CLEAN
Jun 11 13:19:42 mail amavis[3993]: (03993-04) run_av (clamav-clamscan) result: clean
Jun 11 13:19:42 mail amavis[3993]: (03993-04) wbl: checking sender <mygoogletestacct@gmail.com>
Jun 11 13:19:42 mail amavis[3993]: (03993-04) wbl: (SQL) recip <jorge@domain.com>, 2 matches
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup: (scalar) matches, result="1"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup [local_domains] => true, "mygoogletestacct@gmail.com" matches, result="1", matching_key="(constant:1)"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) query_keys: cached mygoogletestacct@gmail.com
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql sel_wblist "mygoogletestacct@gmail.com", query args: "3", [mygoogletestacct@gmail.com,-3], [mygoogletestacct,-3], [@gmail.com,-3], [@.gmail.com,-3], [@.com,-3], [@.,-3]
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql select: SELECT wb FROM wblist JOIN mailaddr ON wblist.sid=mailaddr.id WHERE wblist.rid=? AND mailaddr.email IN (?,?,?,?,?,?) ORDER BY mailaddr.priority DESC
Jun 11 13:19:42 mail amavis[3993]: (03993-04) sql begin, nontransaction
Jun 11 13:19:42 mail amavis[3993]: (03993-04) sql: executing clause (7 args): SELECT wb FROM wblist JOIN mailaddr ON wblist.sid=mailaddr.id WHERE wblist.rid=? AND mailaddr.email IN (?,?,?,?,?,?) ORDER BY mailaddr.priority DESC
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql, "mygoogletestacct@gmail.com" no match
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(wb), "mygoogletestacct@gmail.com" no matching records
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup => undef, "mygoogletestacct@gmail.com" does not match
Jun 11 13:19:42 mail amavis[3993]: (03993-04) wbl: (SQL) recip <jorge@domain.com>, rid=3, got: ""
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup: (scalar) matches, result="1"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup [local_domains] => true, "mygoogletestacct@gmail.com" matches, result="1", matching_key="(constant:1)"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) query_keys: cached mygoogletestacct@gmail.com
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql sel_wblist "mygoogletestacct@gmail.com", query args: "1", [mygoogletestacct@gmail.com,-3], [mygoogletestacct,-3], [@gmail.com,-3], [@.gmail.com,-3], [@.com,-3], [@.,-3]
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql select: SELECT wb FROM wblist JOIN mailaddr ON wblist.sid=mailaddr.id WHERE wblist.rid=? AND mailaddr.email IN (?,?,?,?,?,?) ORDER BY mailaddr.priority DESC
Jun 11 13:19:42 mail amavis[3993]: (03993-04) sql begin, nontransaction
Jun 11 13:19:42 mail amavis[3993]: (03993-04) sql: executing clause (7 args): SELECT wb FROM wblist JOIN mailaddr ON wblist.sid=mailaddr.id WHERE wblist.rid=? AND mailaddr.email IN (?,?,?,?,?,?) ORDER BY mailaddr.priority DESC
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql(mygoogletestacct@gmail.com) matches, result=(wb=>"W")
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(wb) rec=0, "mygoogletestacct@gmail.com" result: "W"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup => true, "mygoogletestacct@gmail.com" matches, result="W", matching_key="wb=>"W""
Jun 11 13:19:42 mail amavis[3993]: (03993-04) wbl: (SQL) recip <jorge@domain.com>, rid=1, got: "W"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) wbl: (SQL) recip <jorge@domain.com> whitelisted sender <mygoogletestacct@gmail.com>
Jun 11 13:19:42 mail amavis[3993]: (03993-04) query_keys: cached jorge@domain.com
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_hash(jorge@domain.com) matches keys: "."=>ARRAY(0x55ebb17d1170)
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup [score_recip<jorge@domain.com>,score_sender], 1 matches for "jorge@domain.com", results: "."=>[Amavis::Lookup::RE=ARRAY(0x55ebb17bbea8),{}]
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_re("mygoogletestacct@gmail.com"), no matches
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup [score_sender<mygoogletestacct@gmail.com>] => undef, "mygoogletestacct@gmail.com" does not match
Jun 11 13:19:42 mail amavis[3993]: (03993-04) wbl: whitelisted sender <mygoogletestacct@gmail.com>
Jun 11 13:19:42 mail amavis[3993]: (03993-04) sender white/blacklisted, skipping spam_scan
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup => undef, "@gmail.com", no lookup tables
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(spam_tag_level) rec=0, "jorge@domain.com" result: "-999"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup [spam_tag_level] => true, "jorge@domain.com" matches, result="-999", matching_key="/cached/"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(spam_tag2_level) rec=0, "jorge@domain.com" result: "7"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup [spam_tag2_level] => true, "jorge@domain.com" matches, result="7", matching_key="/cached/"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(spam_tag3_level) rec=0, "jorge@domain.com" result: "7"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup [spam_tag3_level] => true, "jorge@domain.com" matches, result="7", matching_key="/cached/"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(spam_kill_level) rec=0, "jorge@domain.com" result: "7"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup [spam_kill_level] => true, "jorge@domain.com" matches, result="7", matching_key="/cached/"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(message_size_limit) rec=0, "jorge@domain.com" result: undef
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(message_size_limit) rec=1, "jorge@domain.com" result: undef
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup [message_size_limit] => undef, "jorge@domain.com" does not match
Jun 11 13:19:42 mail amavis[3993]: (03993-04) final_destiny (ccat=0) is PASS, recip jorge@domain.com
Jun 11 13:19:42 mail amavis[3993]: (03993-04) final_destiny PASS, recip jorge@domain.com[/b]
Jun 11 13:19:42 mail amavis[3993]: (03993-04) do_notify_and_quar: ccat=CleanTag (1,1) ("1,1":CleanTag, "1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Jun 11 13:19:42 mail amavis[3993]: (03993-04) do_notify_and_quarantine: not quarantining, q_method off
Jun 11 13:19:42 mail amavis[3993]: (03993-04) skip admin notification, no administrators
Jun 11 13:19:42 mail amavis[3993]: (03993-04) do_notify_and_quarantine - done
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(forward_method) rec=0, "jorge@domain.com" result: undef
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(forward_method) rec=1, "jorge@domain.com" result: undef
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup [forward_method] => true, "jorge@domain.com" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) delivery method is 1, recips: jorge@domain.com
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(spam_tag_level) rec=0, "jorge@domain.com" result: "-999"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup [spam_tag_level] => true, "jorge@domain.com" matches, result="-999", matching_key="/cached/"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(spam_tag2_level) rec=0, "jorge@domain.com" result: "7"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup [spam_tag2_level] => true, "jorge@domain.com" matches, result="7", matching_key="/cached/"
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(spam_subject_tag) rec=0, "jorge@domain.com" result: undef
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup_sql_field(spam_subject_tag) rec=1, "jorge@domain.com" result: undef
Jun 11 13:19:42 mail amavis[3993]: (03993-04) lookup [spam_subject_tag] => undef, "jorge@domain.com" does not match
Jun 11 13:19:42 mail amavis[3993]: (03993-04) headers CLUSTERING: NEW CLUSTER <jorge@domain.com>: score=x, tag=1, tag2=0, local=1, bl=, s=, mangle=
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header encoded (all-ASCII): X-Virus-Scanned: Debian amavisd-new at domain.com
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header: X-Virus-Scanned: Debian amavisd-new at domain.com\n
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header encoded (all-ASCII): X-Spam-Flag: NO
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header: X-Spam-Flag: NO\n
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header encoded (all-ASCII): X-Spam-Score: 0
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header: X-Spam-Score: 0\n
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header encoded (all-ASCII): X-Spam-Level:
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header: X-Spam-Level:\n
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header encoded (all-ASCII): X-Spam-Status: No,\n score=x\n tagged_above=-999\n required=7\n WHITELISTED\n tests=[]\n autolearn=unavailable
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header: X-Spam-Status: No, score=x tagged_above=-999 required=7 WHITELISTED tests=[]\n\tautolearn=unavailable\n
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header encoded (all-ASCII): Authentication-Results: mail.domain.com (amavisd-new);\n dkim=pass (2048-bit key)\n header.d=gmail.com
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header: Authentication-Results: mail.domain.com (amavisd-new);\n\tdkim=pass (2048-bit key) header.d=gmail.com\n
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header encoded (all-ASCII): Received: from mail.domain.com ([127.0.0.1])\n by mail.domain.com (mail.domain.com [127.0.0.1]) (amavisd-new, port 10024)\n with ESMTP\n id 2ozrh0W03q0Y\n for <jorge@domain.com>;\n Mon, 11 Jun 2018 13:19:18 -0600 (MDT)
Jun 11 13:19:42 mail amavis[3993]: (03993-04) header: Received: from mail.domain.com ([127.0.0.1])\n\tby mail.domain.com (mail.domain.com [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id 2ozrh0W03q0Y for <jorge@domain.com>;\n\tMon, 11 Jun 2018 13:19:18 -0600 (MDT)\n
Jun 11 13:19:42 mail amavis[3993]: (03993-04) headers CLUSTERING: done all 1 recips in one go
Jun 11 13:19:42 mail amavis[3993]: (03993-04) spam-tag, <mygoogletestacct@gmail.com> -> <jorge@domain.com>, No, score=x tagged_above=-999 required=7 WHITELISTED tests=[] autolearn=unavailable
Jun 11 13:19:42 mail amavis[3993]: (03993-04) about to connect to smtp:[127.0.0.1]:10025, 2ozrh0W03q0Y FWD from <mygoogletestacct@gmail.com> -> <jorge@domain.com>
Jun 11 13:19:42 mail amavis[3993]: (03993-04) get_deadline fwd_init - deadline in 456.0 s, set to 457.000 s
Jun 11 13:19:42 mail amavis[3993]: (03993-04) smtp session: setting up a new session
Jun 11 13:19:42 mail amavis[3993]: (03993-04) establish_or_refresh, state: down
Jun 11 13:19:42 mail amavis[3993]: (03993-04) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35
Jun 11 13:19:42 mail amavis[3993]: (03993-04) connected to [127.0.0.1]:10025 successfully
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop: needline=1, flush=0, wr=0, timeout=35
Jun 11 13:19:42 mail postfix/10025/smtpd[4678]: connect from mail.domain.com[127.0.0.1]
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop: receiving
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop read 39 chars< 220 mail.domain.com ESMTP Postfix\r\n
Jun 11 13:19:42 mail amavis[3993]: (03993-04) smtp greeting: 220 mail.domain.com ESMTP Postfix, dt: 18.3 ms
Jun 11 13:19:42 mail amavis[3993]: (03993-04) smtp cmd> EHLO mail.domain.com
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop: needline=0, flush=1, wr=1, timeout=300
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop: sending 26 chars
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop sent 26> EHLO mail.domain.com\r\n
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop: needline=1, flush=0, wr=0, timeout=300
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop: receiving
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop read 132 chars< 250-mail.domain.com\r\n250-PIPELINING\r\n250-SIZE 15728640\r\n250-ETRN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250-DSN\r\n250 SMTPUTF8\r\n
Jun 11 13:19:42 mail amavis[3993]: (03993-04) smtp resp to EHLO: 250 mail.domain.com\nPIPELINING\nSIZE 15728640\nETRN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN\nSMTPUTF8
Jun 11 13:19:42 mail amavis[3993]: (03993-04) tls active=0, capable=, sec_level=0
Jun 11 13:19:42 mail amavis[3993]: (03993-04) Remote host presents itself as: mail.domain.com, handles DSN, PIPELINING, 8BITMIME, SMTPUTF8
Jun 11 13:19:42 mail amavis[3993]: (03993-04) AUTH not needed, user='', MTA offers ''
Jun 11 13:19:42 mail amavis[3993]: (03993-04) smtp cmd> MAIL FROM:<mygoogletestacct@gmail.com> BODY=7BIT
Jun 11 13:19:42 mail amavis[3993]: (03993-04) orcpt_encode rfc822, jorge@domain.com, encode_for_smtp
Jun 11 13:19:42 mail amavis[3993]: (03993-04) smtp cmd> RCPT TO:<jorge@domain.com> ORCPT=rfc822;jorge@domain.com
Jun 11 13:19:42 mail amavis[3993]: (03993-04) smtp cmd> DATA
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop: needline=0, flush=1, wr=1, timeout=120
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop: sending 126 chars
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop sent 126> MAIL FROM:<mygoogletestacct@gmail.com> BODY=7BIT\r\nRCPT TO:<jorge@domain.com> ORCPT=rfc822;jorge@domain.com\r\nDATA\r\n
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop: needline=1, flush=0, wr=0, timeout=300
Jun 11 13:19:42 mail postfix/10025/smtpd[4678]: E1D5780748: client=mail.domain.com[127.0.0.1]
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop: receiving
Jun 11 13:19:42 mail amavis[3993]: (03993-04) 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
Jun 11 13:19:42 mail amavis[3993]: (03993-04) smtp resp to MAIL (pip): 250 2.1.0 Ok
Jun 11 13:19:42 mail amavis[3993]: (03993-04) smtp resp to RCPT (pip) (<jorge@domain.com>): 250 2.1.5 Ok
Jun 11 13:19:42 mail amavis[3993]: (03993-04) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Jun 11 13:19:42 mail amavis[3993]: (03993-04) write_header: 1, Amavis::Out::SMTP::Protocol=HASH(0x55ebb76c0240)
Jun 11 13:19:42 mail amavis[3993]: (03993-04) smtp connection_cache disabled, sending QUIT
Jun 11 13:19:42 mail amavis[3993]: (03993-04) smtp cmd> QUIT
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop: needline=0, flush=1, wr=1, timeout=456.963
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop: sending 3617 chars
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop sent 3617> X-Virus-Scanned: Debian amavisd-new at domain.com\r\nX-Spam-Flag: NO\r\nX-Spam-Score: 0\r\nX-Spam-Level:\r\nX-Spam-Status: No, score=x tagged_above=-999 required=7 WHITELISTED tests=[]\r\n\tautolearn=unavail [...]
Jun 11 13:19:42 mail amavis[3993]: (03993-04) rw_loop: needline=1, flush=0, wr=0, timeout=456.963
Jun 11 13:19:42 mail postfix/cleanup[4657]: E1D5780748: message-id=<CAOAxBm+YqzFRTv-wtpVHKz1LKqD28NtzKCR2h1ZvE2jOFcz7qg@mail.gmail.com>
Jun 11 13:19:43 mail postfix/qmgr[3126]: E1D5780748: from=<mygoogletestacct@gmail.com>, size=3806, nrcpt=1 (queue active)
Jun 11 13:19:43 mail amavis[3993]: (03993-04) rw_loop: receiving
Jun 11 13:19:43 mail amavis[3993]: (03993-04) rw_loop read 51 chars< 250 2.0.0 Ok: queued as E1D5780748\r\n221 2.0.0 Bye\r\n
Jun 11 13:19:43 mail amavis[3993]: (03993-04) smtp resp to data-dot (<jorge@domain.com>): 250 2.0.0 Ok: queued as E1D5780748, dt: 6.8 ms
Jun 11 13:19:43 mail amavis[3993]: (03993-04) Amavis::Out::SMTP::Session close, disconnecting
Jun 11 13:19:43 mail amavis[3993]: (03993-04) get_deadline fwd-end-chkpnt - deadline in 456.0 s, set to 274.000 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) prolong_timer fwd-end-chkpnt: timer 274, was 0, deadline in 456.0 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) 2ozrh0W03q0Y FWD from <mygoogletestacct@gmail.com> -> <jorge@domain.com>, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E1D5780748
Jun 11 13:19:43 mail amavis[3993]: (03993-04) get_deadline forwarding - deadline in 456.0 s, set to 274.000 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) prolong_timer forwarding: timer 274, was 274, deadline in 456.0 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) DSN: sender is credible (dkim), SA: 0.000, <mygoogletestacct@gmail.com>
Jun 11 13:19:43 mail amavis[3993]: (03993-04) lookup: (scalar) matches, result="18"
Jun 11 13:19:43 mail amavis[3993]: (03993-04) lookup [spam_crediblefrom_dsn_cutoff_level_bysender] => true, "mygoogletestacct@gmail.com" matches, result="18", matching_key="(constant:18)"
Jun 11 13:19:43 mail amavis[3993]: (03993-04) dsn: from MTA 250 NonBlocking:CleanTag <mygoogletestacct@gmail.com> -> <jorge@domain.com>: 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 E1D5780748"
Jun 11 13:19:43 mail amavis[3993]: (03993-04) DSN: SUCC from MTA 250 NonBlocking:CleanTag, no DSN requested: <mygoogletestacct@gmail.com> -> <jorge@domain.com>
Jun 11 13:19:43 mail amavis[3993]: (03993-04) delivery_status_notification: notif 0 bytes, suppressed: no
Jun 11 13:19:43 mail amavis[3993]: (03993-04) one_response_for_all, per_recip_capable: N, suppressed: N
Jun 11 13:19:43 mail amavis[3993]: (03993-04) one_response_for_all <mygoogletestacct@gmail.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 E1D5780748'
Jun 11 13:19:43 mail amavis[3993]: (03993-04) 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 E1D5780748
Jun 11 13:19:43 mail amavis[3993]: (03993-04) get_deadline delivery-notification - deadline in 456.0 s, set to 274.000 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) prolong_timer delivery-notification: timer 274, was 274, deadline in 456.0 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
Jun 11 13:19:43 mail amavis[3993]: (03993-04) get_deadline snmp-counters - deadline in 456.0 s, set to 274.000 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) prolong_timer snmp-counters: timer 274, was 274, deadline in 456.0 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) orcpt_encode rfc822, jorge@domain.com, smtputf8
Jun 11 13:19:43 mail amavis[3993]: (03993-04) oldest_public_ip_addr_from_received: 209.85.213.44
Jun 11 13:19:43 mail postfix/10025/smtpd[4678]: disconnect from mail.domain.com[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
[b]Jun 11 13:19:43 mail amavis[3993]: (03993-04) Passed CLEAN [/b]{RelayedInbound}, [209.85.213.44]:33656 [209.85.213.44] <mygoogletestacct@gmail.com> -> <jorge@domain.com>, Queue-ID: BBBC480617, Message-ID: <CAOAxBm+YqzFRTv-wtpVHKz1LKqD28NtzKCR2h1ZvE2jOFcz7qg@mail.gmail.com>, mail_id: 2ozrh0W03q0Y, Hits: -, size: 3064, queued_as: E1D5780748, dkim_sd=20161025:gmail.com, 24091 ms
Jun 11 13:19:43 mail amavis[3993]: (03993-04) get_deadline main_log_entry - deadline in 456.0 s, set to 274.000 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) prolong_timer main_log_entry: timer 274, was 274, deadline in 456.0 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) sql begin transaction
Jun 11 13:19:43 mail amavis[3993]: (03993-04) sql: executing clause (12 args): INSERT INTO msgrcpt (partition_tag, mail_id, rseqnum, rid, is_local, content, ds, rs, bl, wl, bspam_level, smtp_resp) VALUES (?,?,?,?,?,?,?,?,?,?,?,?)
Jun 11 13:19:43 mail amavis[3993]: (03993-04) save_info_final 2ozrh0W03q0Y, orig=N, chks=VHBD, cont.ty=C, q.type= , q.to=, dsn=N, score=0, Message-ID: <CAOAxBm+YqzFRTv-wtpVHKz1LKqD28NtzKCR2h1ZvE2jOFcz7qg@mail.gmail.com>, [b]From: 'Jorge <mygoogletestacct@gmail.com>', Subject: 'Fwd: GTube test'[/b]
Jun 11 13:19:43 mail amavis[3993]: (03993-04) sql: executing clause (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=?
Jun 11 13:19:43 mail amavis[3993]: (03993-04) sql commit
Jun 11 13:19:43 mail amavis[3993]: (03993-04) get_deadline check done - deadline in 456.0 s, set to 274.000 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) prolong_timer check done: timer 274, was 274, deadline in 456.0 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E1D5780748"
Jun 11 13:19:43 mail amavis[3993]: (03993-04) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E1D5780748
Jun 11 13:19:43 mail amavis[3993]: (03993-04) switch_to_client_time 480 s, smtp response sent
Jun 11 13:19:43 mail amavis[3993]: (03993-04) TempDir::strip: /var/lib/amavis/tmp/amavis-20180611T131051-03993-j7Deenma
Jun 11 13:19:43 mail amavis[3993]: (03993-04) rmdir_recursively: /var/lib/amavis/tmp/amavis-20180611T131051-03993-j7Deenma/parts, excl=1
Jun 11 13:19:43 mail postfix/amavis/smtp[4658]: BBBC480617: to=<jorge@domain.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=24, delays=0.1/0.01/0.01/24, 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 E1D5780748)
Jun 11 13:19:43 mail postfix/qmgr[3126]: BBBC480617: removed
Jun 11 13:19:43 mail amavis[3993]: (03993-04) size: 3064, TIMING [total 24107 ms] - SMTP greeting: 1.1 (0%)0, SMTP EHLO: 8 (0%)0, SMTP pre-MAIL: 1.4 (0%)0, lookup_sql: 7 (0%)0, SMTP pre-DATA-flush: 2.6 (0%)0, SMTP DATA: 34 (0%)0, check_init: 0.2 (0%)0, digest_hdr: 1.7 (0%)0, digest_body_dkim: 21 (0%)0, collect_info: 4.4 (0%)0, gen_mail_id: 9 (0%)0, mime_decode: 17 (0%)0, get-file-type2: 56 (0%)1, parts_decode: 1.1 (0%)1, check_header: 4.7 (0%)1, AV-scan-1: 7008 (29%)30, AV-scan-2: 16840 (70%)100, lookup_sql: 6 (0%)100, lookup_sql: 1.9 (0%)100, spam-wb-list: 2.4 (0%)100, decide_mail_destiny: 0.9 (0%)100, notif-quar: 0.2 (0%)100, fwd-connect: 29 (0%)100, fwd-mail-pip: 16 (0%)100, fwd-rcpt-pip: 0.2 (0%)100, fwd-data-chkpnt: 0.0 (0%)100, write-header: 0.5 (0%)100, fwd-data-contents: 0.0 (0%)100, fwd-end-chkpnt: 7 (0%)100, prepare-dsn: 0.7 (0%)100, report: 1.0 (0%)100, main_log_entry: 8 (0%)100, sql-update: 9 (0%)100, SMTP pre-response: 0.2 (0%)100, SMTP response: 0.2 (0%)100, unlink-2-files: 0.2 (0%)1...
Jun 11 13:19:43 mail amavis[3993]: (03993-04) ...00, rundown: 5 (0%)100
Jun 11 13:19:43 mail amavis[3993]: (03993-04) idle_proc, 6: was busy, 24087.5 ms, total idle 428.932 s, busy 102.941 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) idle_proc, 5: was idle, 0.1 ms, total idle 428.932 s, busy 102.941 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) ESMTP< QUIT\r\n
Jun 11 13:19:43 mail amavis[3993]: (03993-04) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Jun 11 13:19:43 mail amavis[3993]: (03993-04) switch_to_client_time 480 s, smtp response sent
Jun 11 13:19:43 mail amavis[3993]: (03993-04) SMTP session over, timer stopped
Jun 11 13:19:43 mail amavis[3993]: (03993-04) exiting process_request
Jun 11 13:19:43 mail amavis[3993]: (03993-04) idle_proc, bye: was busy, 1.1 ms, total idle 428.932 s, busy 102.943 s
Jun 11 13:19:43 mail amavis[3993]: (03993-04) load: 19 %, total idle 428.932 s, busy 102.943 s
Jun 11 13:19:43 mail postfix/pipe[4684]: E1D5780748: to=<jorge@domain.com>, relay=dovecot, delay=0.12, delays=0.01/0.02/0/0.09, dsn=2.0.0, status=sent (delivered via dovecot service)
Jun 11 13:19:43 mail postfix/qmgr[3126]: E1D5780748: removed
All the inbound senders get whitelisted in this manner and the spam check is skipped.
