1 Topic by spam.lejmr.com

  • spam.lejmr.com
  • Member
  • Offline
  • Registered: 2020-02-14
  • Posts: 4

Topic: SpamAssassin might not be working fine

==== REQUIRED BASIC INFO OF YOUR IREDMAIL SERVER ====
- iRedMail version (check /etc/iredmail-release): 1.0
- Deployed with iRedMail Easy or the downloadable installer?
- Linux/BSD distribution name and version: CentOS 7 (within docker container lejmr/iredmail)
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQL
- Web server (Apache or Nginx): Nginx
- Manage mail accounts with iRedAdmin-Pro? No
- [IMPORTANT] Related original log or error message is required if you're experiencing an issue.
====

Hello guys,

I have been receiving a high number of spam emails. Looking into logs, I can see post-screen fighting with plenty of malicious emails, but I am afraid that post-screen is actually working in iRedMail installation because when a spam email passes post-screen the spam never gets bounced by amavis (utilizing SpamAssasin), so I wonder whether iRedMail delivers working configuration for such a case.. I dit a few configuration changess in order to fight with spams, but nothing really helped. I followed this document: https://docs.iredmail.org/store.spamass … .sql.html.

I have no problem to rollback any of mu changes if that helps to debug the problem.. I am going to document my observations through a sequence of log outputs where I anonymized my personal account by myaccount@example.com. The example is an email that I received in the middle of the night (subsequently, that night I received about 15 similar emails which drove me to write this post).

Postfix log looks like this:

Feb 14 00:30:22 mail postfix/10025/smtpd[5270]: 48JZ666HGJzcfDZ: client=localhost[127.0.0.1]
Feb 14 00:30:22 mail postfix/cleanup[5252]: 48JZ666HGJzcfDZ: message-id=<O1Gy_ThYJTAxcvrfTSF2LH_z8yF0mwAOHKr3FyFYVfY.-0yf93J8lnaGsJz8GKT3PM_KKRNGt8e0404nR0Puigs@politetread.icu>
Feb 14 00:30:22 mail postfix/10025/smtpd[5270]: disconnect from localhost[127.0.0.1]
Feb 14 00:30:22 mail postfix/qmgr[27533]: 48JZ666HGJzcfDZ: from=<approved@politetread.icu>, size=10431, nrcpt=1 (queue active)
Feb 14 00:30:22 mail amavis[24570]: (24570-17) Passed CLEAN {RelayedInbound}, [213.142.151.250]:49496 [213.142.151.250] ESMTP/ESMTP <approved@politetread.icu> -> <myaccount@example.com>, (ESMTP://[213.142.151.250]:49496), Queue-ID: 48JZ635KZ2zcf4R, Message-ID: <O1Gy_ThYJTAxcvrfTSF2LH_z8yF0mwAOHKr3FyFYVfY.-0yf93J8lnaGsJz8GKT3PM_KKRNGt8e0404nR0Puigs@politetread.icu>, mail_id: md4_25w3sVG6, b: wIXj2hZBN, Hits: 1.184, size: 9758, queued_as: 48JZ666HGJzcfDZ, Subject: "Highly Effective Anti-Pollution Clean Air Breathing Mask ---------------------", From: <approved@politetread.icu> (dkim:AUTHOR), helo=politetread.icu, Tests: [DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,HTML_MESSAGE=0.001,RDNS_NONE=1.274,SPF_HELO_PASS=-0.001,SPF_PASS=-0.001,T_REMOTE_IMAGE=0.01,URIBL_BLOCKED=0.001], autolearn=no autolearn_force=no, autolearnscore=1.185, dkim_i=approved@politetread.icu,approved@politetread.icu, dkim_sd=mail:politetread.icu, 1166 ms
Feb 14 00:30:22 mail amavis[24570]: (24570-17) Passed CLEAN, <approved@politetread.icu> -> <myaccount@example.com>, Hits: 1.184, tag=2, tag2=6.2, kill=6.9, queued_as: 48JZ666HGJzcfDZ, L/0/0/0
Feb 14 00:30:22 mail postfix/amavis/smtp[5262]: 48JZ635KZ2zcf4R: to=<myaccount@example.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=3.2, delays=2/0/0.01/1.2, 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 48JZ666HGJzcfDZ)
Feb 14 00:30:22 mail postfix/qmgr[27533]: 48JZ635KZ2zcf4R: removed
Feb 14 00:30:22 mail postfix/pipe[5271]: 48JZ666HGJzcfDZ: to=<myaccount@example.com>, relay=dovecot, delay=0.05, delays=0.01/0/0/0.04, dsn=2.0.0, status=sent (delivered via dovecot service)
Feb 14 00:30:22 mail postfix/qmgr[27533]: 48JZ666HGJzcfDZ: removed

Here in I was very surprised about the amavis status

Feb 14 00:30:22 mail amavis[24570]: (24570-17) Passed CLEAN {RelayedInbound}, [213.142.151.250]:49496 [213.142.151.250] ESMTP/ESMTP <approved@politetread.icu> -> <myaccount@example.com>, (ESMTP://[213.142.151.250]:49496), Queue-ID: 48JZ635KZ2zcf4R, Message-ID: <O1Gy_ThYJTAxcvrfTSF2LH_z8yF0mwAOHKr3FyFYVfY.-0yf93J8lnaGsJz8GKT3PM_KKRNGt8e0404nR0Puigs@politetread.icu>, mail_id: md4_25w3sVG6, b: wIXj2hZBN, Hits: 1.184, size: 9758, queued_as: 48JZ666HGJzcfDZ, Subject: "Highly Effective Anti-Pollution Clean Air Breathing Mask ---------------------", From: <approved@politetread.icu> (dkim:AUTHOR), helo=politetread.icu, Tests: [DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,HTML_MESSAGE=0.001,RDNS_NONE=1.274,SPF_HELO_PASS=-0.001,SPF_PASS=-0.001,T_REMOTE_IMAGE=0.01,URIBL_BLOCKED=0.001], autolearn=no autolearn_force=no, autolearnscore=1.185, dkim_i=approved@politetread.icu,approved@politetread.icu, dkim_sd=mail:politetread.icu, 1166 ms

Similarly, the email's header is as follows

Return-Path: <approved@politetread.icu>
Delivered-To: myaccount@example.com
Received: from mail.example.com (localhost [127.0.0.1])
    by mail.example.com (Postfix) with ESMTP id 48JZ666HGJzcfDZ
    for <myaccount@example.com>; Fri, 14 Feb 2020 00:30:22 +0000 (UTC)
X-Virus-Scanned: amavisd-new at mail.example.com
Authentication-Results: mail.example.com (amavisd-new); dkim=pass (1024-bit key)
    header.d=politetread.icu; domainkeys=pass (1024-bit key)
    header.from=approved@politetread.icu header.d=politetread.icu
Received: from mail.example.com ([127.0.0.1])
    by mail.example.com (mail.example.com [127.0.0.1]) (amavisd-new, port 10024)
    with ESMTP id md4_25w3sVG6 for <myaccount@example.com>;
    Fri, 14 Feb 2020 00:30:21 +0000 (UTC)
Received: from politetread.icu (unknown [213.142.151.250])
    by mail.example.com (Postfix) with ESMTP id 48JZ635KZ2zcf4R
    for <myaccount_cachalladdress@example.com>; Fri, 14 Feb 2020 00:30:19 +0000 (UTC)
DKIM-Signature: v=1; a=rsa-sha1; c=relaxed/relaxed; s=mail; d=politetread.icu;
 h=From:Date:MIME-Version:Subject:To:Message-ID:Content-Type; i=approved@politetread.icu;
 bh=jcizARpmzzh/vXmLQkN1LOjOcWA=;
 b=jRkprF5zlGshhHb2QtWX8QFl8QmVuVvjkOGkPvzvhaxi7eXLkULQ6Q4Vc9lr9LcM86dFQwknQ7F9
   2CogiIYXpgppAUk5GY1fT7fpQ69QmYdyMp2IYOwG5uuAIrEPLIXTMgi2o0il4FOh/Kw4D3ZwjCqC
   x+F6yoJ6V7+9SjuPjL8=
DomainKey-Signature: a=rsa-sha1; c=nofws; q=dns; s=mail; d=politetread.icu;
 b=iQMkpAfUgF4nuX/QoAPf7zJdDkNQU1PNgsWt+uu6hulAnI16CIXRjV7PlbXKtL4BS012fPNFTMgJ
   7ETqC1Kjvh8S0CB2sOXxZ32sfOgg+tkQTc5QmnPGE7pD5H5gdNI14ajG5jz4dBpXGwlcBWuTzgv+
   hurl8muRYu+Kw/2s8iw=;
From: "Travel Mask" <approved@politetread.icu>
Date: Thu, 13 Feb 2020 19:24:51 -0500
MIME-Version: 1.0
Subject: Highly Effective Anti-Pollution Clean Air Breathing Mask ---------------------

Here an interesting thing is that the spam was delivered to an alias of my account, as I am using my personal account as a catch-all account too. Don't know if that is related, but might be related?


Based on the score I am seeing in logs it makes sense the email was delivered to my account, but when I scrutinized the actual email in Maildir directory using SpamAssasin I received a very disturbing output:


--------------921627366770447008480132--
Spam detection software, running on the system "mail.example.com",
has identified this incoming email as possible spam.  The original
message has been attached to this so you can view it or label
similar future email.  If you have any questions, see
the administrator of that system for details.

Content preview:  Filter fine pollution particles with the most stylish clean
   breathing mask available No longer be at the mercy of climate change and
  ensure your future by protecting yourself with OxyBreath Pro <http://www.politetread.icu/uselbgkcx/qffjra110707csgl/ruO02Bt7hroUggk2KTy6c8E7FAyoVtK4h7UBzctCztY/XJLvj-QSuvjTaWv2iMQ2f7Bg1dqivhzYg-waAsKdUMxs6gTpVeXnUH8xlCHk9RCiRXMhqCjsnXVTk3r7Etb0YTm-85O_duwZE1JBYJCp2nC3tI67ONvV5K78uYXtjZJedObvEAG7at9dM6ylSdJZVsKW7TZWQnWaB-wVm9y-GWA>
   [...]

Content analysis details:   (12.2 points, 5.0 required)

 pts rule name              description
---- ---------------------- --------------------------------------------------
 0.0 URIBL_BLOCKED          ADMINISTRATOR NOTICE: The query to URIBL was blocked.
                            See
                            http://wiki.apache.org/spamassassin/DnsBlocklists#dnsbl-block
                             for more information.
                            [URIs: politetread.icu]
 2.5 URIBL_DBL_SPAM         Contains a spam URL listed in the Spamhaus DBL
                            blocklist
                            [URIs: politetread.icu]
 3.6 RCVD_IN_SBL_CSS        RBL: Received via a relay in Spamhaus SBL-CSS
                            [213.142.151.250 listed in zen.spamhaus.org]
 2.7 RCVD_IN_PSBL           RBL: Received via a relay in PSBL
                            [213.142.151.250 listed in psbl.surriel.com]
-0.0 SPF_HELO_PASS          SPF: HELO matches SPF record
 0.0 HTML_MESSAGE           BODY: HTML included in message
-0.1 DKIM_VALID_AU          Message has a valid DKIM or DK signature from author's
                            domain
-0.1 DKIM_VALID             Message has at least one valid DKIM or DK signature
 0.1 DKIM_SIGNED            Message has a DKIM or DK signature, not necessarily valid
 1.3 RDNS_NONE              Delivered to internal network by a host with no rDNS
 2.3 DKIMWL_BL              DKIMwl.org - Blacklisted sender
 0.0 T_REMOTE_IMAGE         Message contains an external image

Based on the score I would expect never receive such an email! As mentioned in the beggining of my email, I enabled bayes filtering. Additionally, this example spam email is very similar to one of spam emails I received in the pass and which let let sa-learn to index.

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

2 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,090

Re: SpamAssassin might not be working fine

- Catch-all may give you many spams, especially when you publicly publish your email address on internet.
- Add these rules in /etc/mail/spamassassin/local.cf will help a lot:

#
# Adjust spam scores.
#
score ALL_TRUSTED 0.1

#
# Spamhaus
#
score URIBL_DBL_SPAM 10
score URIBL_DBL_PHISH 10
score URIBL_DBL_MALWARE 10
score URIBL_DBL_BOTNETCC 3
# Contains an abused spamvertized URL listed in the Spamhaus DBL blocklist
score URIBL_DBL_ABUSE_SPAM 10
score URIBL_DBL_ABUSE_REDIR 3
score URIBL_DBL_ABUSE_PHISH 5
score URIBL_DBL_ABUSE_MALW 5
score URIBL_DBL_ABUSE_BOTCC 3
score URIBL_DBL_ERROR 0
# Contains an URL's NS IP listed in the Spamhaus SBL blocklist
score URIBL_SBL 10
# Contains URL's A record listed in the Spamhaus SBL blocklist
score URIBL_SBL_A 10

# multi.surbl.org
score URIBL_WS_SURBL 10
score URIBL_PH_SURBL 10
score URIBL_MW_SURBL 10
score URIBL_CR_SURBL 10
score URIBL_SC_SURBL 10
score URIBL_OB_SURBL 10
score URIBL_AB_SURBL 10
score URIBL_JP_SURBL 10
score URIBL_ABUSE_SURBL 5
score SURBL_BLOCKED 0

# multi.urlbl.com
score URIBL_BLACK 10
#score URIBL_GREY 3
#score URIBL_RED 0
score URIBL_BLOCKED 0

# DNSBL
score RCVD_IN_SBL 10
score RCVD_IN_XBL 10
score RCVD_IN_PBL 10

score RCVD_IN_BL_SPAMCOP_NET 5
score RCVD_IN_PSBL 5
score RCVD_IN_RP_RNBL 5

# SPF
# sender does not match SPF record (fail)
score SPF_FAIL 5

# To == From and direct-to-MX
score TO_EQ_FM_DIRECT_MX 5
# To domain == From domain and HTML image link
score TO_EQ_FM_DOM_HTML_IMG 5
# To domain == From domain and HTML only
score TO_EQ_FM_DOM_HTML_ONLY 5
# To domain == From domain and external SPF failed
score TO_EQ_FM_DOM_SPF_FAIL 5
# To == From and HTML only
score TO_EQ_FM_HTML_ONLY 5
# To == From and external SPF failed
score TO_EQ_FM_SPF_FAIL 5

# Malformed From address
score FROM_ADDR_WS 5

# From: has too many raw illegal characters    
score SUBJ_ILLEGAL_CHARS 5

3 Reply by spam.lejmr.com

  • spam.lejmr.com
  • Member
  • Offline
  • Registered: 2020-02-14
  • Posts: 4

Re: SpamAssassin might not be working fine

Thank you for the suggestion. I will definitely use it, but quite a lot of spam emails that I am getting are not through alias emails.. so this is not a solution to me.


As discussed through Telegram, I will search amavis mail conference to find why amavis gets a different score than what spamassassin gives..

4 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,090

Re: SpamAssassin might not be working fine

The spam source is probably caused by catch-all account, if spammers send email to <not-exist>@your-domain.com, your server will accept the email and delivers it locally.

5 Reply by spam.lejmr.com

  • spam.lejmr.com
  • Member
  • Offline
  • Registered: 2020-02-14
  • Posts: 4

Re: SpamAssassin might not be working fine

ZhangHuangbin wrote:

The spam source is probably caused by catch-all account, if spammers send email to <not-exist>@your-domain.com, your server will accept the email and delivers it locally.

Is there a way how to check such a locally delivered emails? I thinking about adding amavis/spamassasin into the way emails get locally delivered.

6 Reply by spam.lejmr.com

  • spam.lejmr.com
  • Member
  • Offline
  • Registered: 2020-02-14
  • Posts: 4

Re: SpamAssassin might not be working fine

I dont know if this helpes, but amavis in debug mode looks like this:

Feb 18 20:05:33 mail postfix/postscreen[10958]: CONNECT from [213.142.151.123]:17936 to [172.17.0.5]:25
Feb 18 20:05:39 mail postfix/postscreen[10958]: PASS NEW [213.142.151.123]:17936
Feb 18 20:05:39 mail postfix/smtpd[17078]: connect from unknown[213.142.151.123]
Feb 18 20:05:41 mail postfix/smtpd[17078]: 48MX0P2NCTzcf1H: client=unknown[213.142.151.123]
Feb 18 20:05:42 mail postfix/cleanup[17094]: 48MX0P2NCTzcf1H: message-id=<t7jqdatbhWCqIVDZ5YyQPkseONdnJI_E3IvOcJf2qxs.m-D6nUw9HHgPQG3BZvwZHlY1bkbPDF-Qv3OmzFHffkw@pumpkingene.icu>
Feb 18 20:05:48 mail postfix/qmgr[32098]: 48MX0P2NCTzcf1H: from=<bloodpressurex@pumpkingene.icu>, size=32131, nrcpt=1 (queue active)
Feb 18 20:05:48 mail amavis[26931]: (26931-19) Net::Server: 2020/02/18-20:05:48 CONNECT TCP Peer: "[127.0.0.1]:44832" Local: "[127.0.0.1]:10024"
Feb 18 20:05:48 mail amavis[26931]: idle_proc, hi : was idle, 15640923.8 ms, total idle 182644.439 s, busy 54.121 s
Feb 18 20:05:48 mail amavis[26931]: loaded base policy bank
Feb 18 20:05:48 mail amavis[26931]: lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
Feb 18 20:05:48 mail amavis[26931]: process_request: fileno sock=10, STDIN=0, STDOUT=1
Feb 18 20:05:48 mail amavis[26931]: get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 288.000 s
Feb 18 20:05:48 mail amavis[26931]: prolong_timer switch_to_my_time(new request): timer 288, was 0, deadline in 480.0 s
Feb 18 20:05:48 mail amavis[26931]: process_request: suggested_protocol="" on a TCP socket
Feb 18 20:05:48 mail amavis[26931]: (26931-20) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Feb 18 20:05:48 mail amavis[26931]: (26931-20) switch_to_client_time 480 s, smtp response sent
Feb 18 20:05:48 mail amavis[26931]: (26931-20) idle_proc, 4: was busy, 44.3 ms, total idle 182644.439 s, busy 54.166 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) smtp readline: read 21 bytes, new size: 21
Feb 18 20:05:48 mail amavis[26931]: (26931-20) idle_proc, 5: was idle, 0.9 ms, total idle 182644.440 s, busy 54.166 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) SMTP< EHLO mail.example.com\r\n
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 288.000 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 288, was 480, deadline in 480.0 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 250-[127.0.0.1]
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 250-VRFY
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 250-PIPELINING
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 250-SIZE
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 250-ENHANCEDSTATUSCODES
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 250-8BITMIME
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 250-SMTPUTF8
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 250-DSN
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
Feb 18 20:05:48 mail amavis[26931]: (26931-20) switch_to_client_time 480 s, smtp response sent
Feb 18 20:05:48 mail amavis[26931]: (26931-20) idle_proc, 6: was busy, 6.4 ms, total idle 182644.440 s, busy 54.172 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) smtp readline: read 272 bytes, new size: 272
Feb 18 20:05:48 mail amavis[26931]: (26931-20) idle_proc, 5: was idle, 0.4 ms, total idle 182644.440 s, busy 54.172 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP< XFORWARD ADDR=213.142.151.123 PORT=17936\r\n
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 250 2.5.0 Ok XFORWARD
Feb 18 20:05:48 mail amavis[26931]: (26931-20) switch_to_client_time 480 s, smtp response sent
Feb 18 20:05:48 mail amavis[26931]: (26931-20) idle_proc, 6: was busy, 1.4 ms, total idle 182644.440 s, busy 54.173 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) idle_proc, 5: was idle, 0.2 ms, total idle 182644.440 s, busy 54.173 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP< XFORWARD PROTO=ESMTP HELO=pumpkingene.icu IDENT=48MX0P2NCTzcf1H SOURCE=REMOTE\r\n
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 250 2.5.0 Ok XFORWARD
Feb 18 20:05:48 mail amavis[26931]: (26931-20) switch_to_client_time 480 s, smtp response sent
Feb 18 20:05:48 mail amavis[26931]: (26931-20) idle_proc, 6: was busy, 1.0 ms, total idle 182644.440 s, busy 54.174 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) idle_proc, 5: was idle, 0.1 ms, total idle 182644.441 s, busy 54.174 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP< MAIL FROM:<bloodpressurex@pumpkingene.icu> SIZE=32131 BODY=8BITMIME RET=HDRS\r\n
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 288.000 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 288, was 480, deadline in 480.0 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) check_mail_begin_task: task_count=20
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="213.142.151.123", no match
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup [debug_sender] => undef, "bloodpressurex@pumpkingene.icu" does not match
Feb 18 20:05:48 mail amavis[26931]: (26931-20) mesage size set to a declared size 32131
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 250 2.1.0 Sender <bloodpressurex@pumpkingene.icu> OK
Feb 18 20:05:48 mail amavis[26931]: (26931-20) switch_to_client_time 480 s, smtp response sent
Feb 18 20:05:48 mail amavis[26931]: (26931-20) idle_proc, 6: was busy, 16.8 ms, total idle 182644.441 s, busy 54.191 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) idle_proc, 5: was idle, 0.1 ms, total idle 182644.441 s, busy 54.191 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP< RCPT TO:<myaccount@example.com> ORCPT=rfc822;catchallemail@example.com\r\n
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 288.000 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 288, was 480, deadline in 480.0 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup => undef, "myaccount@example.com", no lookup tables
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="1"
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup [local_domains] => true,  "myaccount@example.com" matches, result="1", matching_key="(constant:1)"
Feb 18 20:05:48 mail amavis[26931]: (26931-20) query_keys: cached myaccount@example.com
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup_sql sel_policy "myaccount@example.com", query args: [myaccount@example.com,-3], [catchallemailk,-3], [@example.com,-3], [@.example.com,-3], [@.com,-3], [@.,-3]
Feb 18 20:05:48 mail amavis[26931]: (26931-20) 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
Feb 18 20:05:48 mail amavis[26931]: (26931-20) sql begin, nontransaction
Feb 18 20:05:48 mail amavis[26931]: (26931-20) 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
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup_sql: "myaccount@example.com" matches catchall, local=>undef
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup_sql(myaccount@example.com) matches, result=(id=>"1", priority=>"0", policy_id=>"0", email=>"@.", fullname=>-, id=>"1", policy_name=>-, virus_lover=>-, spam_lover=>-, unchecked_lover=>-, banned_files_lover=>-, bad_header_lover=>-, bypass_virus_checks=>-, bypass_spam_checks=>-, bypass_banned_checks=>-, bypass_header_checks=>-, virus_quarantine_to=>-, 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_subject_tag2=>-, spam_subject_tag3=>-, ...
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ...message_size_limit=>-, banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"1", local=>-)
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup_sql_field(message_size_limit) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup [message_size_limit] => undef, "myaccount@example.com" does not match
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 250 2.1.5 Recipient <myaccount@example.com> OK
Feb 18 20:05:48 mail amavis[26931]: (26931-20) switch_to_client_time 480 s, smtp response sent
Feb 18 20:05:48 mail amavis[26931]: (26931-20) idle_proc, 6: was busy, 19.4 ms, total idle 182644.441 s, busy 54.210 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) idle_proc, 5: was idle, 0.1 ms, total idle 182644.441 s, busy 54.210 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP< DATA\r\n
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 288.000 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) prolong_timer switch_to_my_time(rx SMTP DATA): timer 288, was 480, deadline in 480.0 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP [127.0.0.1]:10024 /var/spool/amavisd/tmp/amavis-20200216T172050-26931-ggcVOhrA: <bloodpressurex@pumpkingene.icu> -> <myaccount@example.com> SIZE=32131 BODY=8BITMIME RET=HDRS Received: from mail.example.com ([127.0.0.1]) by mail.example.com (mail.example.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <myaccount@example.com>; Tue, 18 Feb 2020 20:05:48 +0000 (UTC)
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Feb 18 20:05:48 mail amavis[26931]: (26931-20) switch_to_client_time 480 s, smtp response sent
Feb 18 20:05:48 mail amavis[26931]: (26931-20) switch_to_client_time 480 s, receiving data
Feb 18 20:05:48 mail amavis[26931]: (26931-20) smtp copy: read 32065 bytes into buffer, new size: 32065
Feb 18 20:05:48 mail amavis[26931]: (26931-20) smtp copy: 6 bytes still buffered at end
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 288.000 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) prolong_timer switch_to_my_time(rx data-end): timer 288, was 480, deadline in 480.0 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ESMTP< .<CR><LF>
Feb 18 20:05:48 mail amavis[26931]: (26931-20) Actual message size 32056 B less than the declared 32131 B
Feb 18 20:05:48 mail amavis[26931]: (26931-20) smtp connection cache, dt: 15641.0, state: 0
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_deadline digest_pre - deadline in 480.0 s, set to 288.000 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) prolong_timer digest_pre: timer 288, was 288, deadline in 480.0 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_body_digest: reading header section from memory
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_body_digest: feeding header section to DKIM verifier
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_body_digest: sending h/b separator to DKIM
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_deadline digest_hdr - deadline in 480.0 s, set to 288.000 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) prolong_timer digest_hdr: timer 288, was 288, deadline in 480.0 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_body_digest: reading mail body from memory, 2 DKIM signatures
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_deadline digest_body - deadline in 479.9 s, set to 288.000 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) prolong_timer digest_body: timer 288, was 288, deadline in 479.9 s
Feb 18 20:05:48 mail amavis[26931]: (26931-20) get_body_digest: message size 32056, header+sep 1266, body 30790
Feb 18 20:05:48 mail amavis[26931]: (26931-20) body type (8bit-MIMEtransport): labeled 8BITMIME unnecessarily (h=0, b=0)
Feb 18 20:05:48 mail amavis[26931]: (26931-20) body hash: 2092f8f4c74d82d43ce96231e815d878
Feb 18 20:05:48 mail amavis[26931]: (26931-20) ip_from_received: 213.142.151.123
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup_ip_acl (public_nets) arr.obj: key="213.142.151.123" matches "::ffff:0:0/96", result=1
Feb 18 20:05:48 mail amavis[26931]: (26931-20) trace: ESMTP://[127.0.0.1]:44832 < ESMTP://[213.142.151.123]:17936
Feb 18 20:05:48 mail amavis[26931]: (26931-20) dkim: public key s=mail d=pumpkingene.icu v=DKIM1 k=rsa, 1024-bit key
Feb 18 20:05:48 mail amavis[26931]: (26931-20) dkim: VALID Author+Sender+MailFrom signature by d=pumpkingene.icu, From: <bloodpressurex@pumpkingene.icu>, a=rsa-sha1, c=relaxed/relaxed, s=mail, i=bloodpressurex@pumpkingene.icu
Feb 18 20:05:48 mail amavis[26931]: (26931-20) dkim: public key s=mail d=pumpkingene.icu v=DKIM1 k=rsa, 1024-bit key
Feb 18 20:05:48 mail amavis[26931]: (26931-20) dkim: VALID Author+Sender+MailFrom signature by d=pumpkingene.icu, From: <bloodpressurex@pumpkingene.icu>, a=rsa-sha1, c=nofws, s=mail, i=bloodpressurex@pumpkingene.icu
Feb 18 20:05:48 mail amavis[26931]: (26931-20) Original mail size: 32056; quota set to: 16028000 bytes (fmin=5, fmax=500, qmin=102400, qmax=524288000)
Feb 18 20:05:48 mail amavis[26931]: (26931-20) sql begin, nontransaction
Feb 18 20:05:48 mail amavis[26931]: (26931-20) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Feb 18 20:05:48 mail amavis[26931]: (26931-20) sql begin, nontransaction
Feb 18 20:05:48 mail amavis[26931]: (26931-20) sql: executing clause (3 args): INSERT INTO maddr (partition_tag, email, domain) VALUES (?,?,?)
Feb 18 20:05:48 mail postfix/smtpd[17078]: disconnect from unknown[213.142.151.123]
Feb 18 20:05:48 mail amavis[26931]: (26931-20) sql begin, nontransaction
Feb 18 20:05:48 mail amavis[26931]: (26931-20) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Feb 18 20:05:48 mail amavis[26931]: (26931-20) find_or_save_addr: record inserted, id=9310, bloodpressurex@pumpkingene.icu
Feb 18 20:05:48 mail amavis[26931]: (26931-20) save_info_preliminary 0K71G378jb83, sender id: 9310, bloodpressurex@pumpkingene.icu, new
Feb 18 20:05:48 mail amavis[26931]: (26931-20) sql begin, nontransaction
Feb 18 20:05:48 mail amavis[26931]: (26931-20) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
Feb 18 20:05:48 mail amavis[26931]: (26931-20) orcpt_encode rfc822, catchallemail@example.com, smtputf8
Feb 18 20:05:48 mail amavis[26931]: (26931-20) save_info_preliminary 0K71G378jb83, recip id: 12, myaccount@example.com (ORCPT rfc822;catchallemail@example.com), exists
Feb 18 20:05:48 mail amavis[26931]: (26931-20) sql begin transaction
Feb 18 20:05:48 mail amavis[26931]: (26931-20) 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 (?,?,?,?,?,?,?,?,?,?,?)
Feb 18 20:05:48 mail amavis[26931]: (26931-20) sql commit
Feb 18 20:05:48 mail amavis[26931]: (26931-20) Checking: 0K71G378jb83 [213.142.151.123] <bloodpressurex@pumpkingene.icu> -> <myaccount@example.com>
Feb 18 20:05:48 mail amavis[26931]: (26931-20) 2822.From: <bloodpressurex@pumpkingene.icu>
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup_sql_field(local) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="1"
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup [local_domains] => true,  "myaccount@example.com" matches, result="1", matching_key="(constant:1)"
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup_sql_field(bypass_virus_checks) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="0"
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup [bypass_virus_checks] => false, "myaccount@example.com" matches, result="0", matching_key="(constant:0)"
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup_sql_field(bypass_banned_checks) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup [bypass_banned_checks] => undef, "myaccount@example.com" does not match
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup_sql_field(bypass_spam_checks) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="0"
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup [bypass_spam_checks] => false, "myaccount@example.com" matches, result="0", matching_key="(constant:0)"
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup_sql_field(id) rec=0, "myaccount@example.com" result: "1"
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup [users.id], 1 matches for "myaccount@example.com", results: "/cached/"=>"1"
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup_sql_field(policy_id) rec=0, "myaccount@example.com" result: "0"
Feb 18 20:05:48 mail amavis[26931]: (26931-20) lookup [users.policy_id] => false, "myaccount@example.com" matches, result="0", matching_key="/cached/"
Feb 18 20:05:49 mail amavis[26931]: (26931-20) Extracting mime components from a string
Feb 18 20:05:49 mail amavis[26931]: (26931-20) Issued a new file name: p001
Feb 18 20:05:49 mail amavis[26931]: (26931-20) Issued a new file name: p002
Feb 18 20:05:49 mail amavis[26931]: (26931-20) mime_decode_preamble: 1 lines
Feb 18 20:05:49 mail amavis[26931]: (26931-20) Issued a new pseudo part: p003
Feb 18 20:05:49 mail amavis[26931]: (26931-20) p003 1 Content-Type: multipart/alternative
Feb 18 20:05:49 mail amavis[26931]: (26931-20) Charging 11052 bytes to remaining quota 16028000 (out of 16028000, (0%)) - by mime_decode
Feb 18 20:05:49 mail amavis[26931]: (26931-20) p001 1/1 Content-Type: text/plain, 7bit, size: 11052, SHA1 digest: 978e39ab62654c0f362089956dfa5d79ed9a60ee
Feb 18 20:05:49 mail amavis[26931]: (26931-20) reparenting p001 from p000 to p003
Feb 18 20:05:49 mail amavis[26931]: (26931-20) Charging 18881 bytes to remaining quota 16016948 (out of 16028000, (0%)) - by mime_decode
Feb 18 20:05:49 mail amavis[26931]: (26931-20) p002 1/2 Content-Type: text/html, 7bit, size: 18881, SHA1 digest: 26c110e4cd4c1bb562c446d4a6a0ec116c7551eb
Feb 18 20:05:49 mail amavis[26931]: (26931-20) reparenting p002 from p000 to p003
Feb 18 20:05:49 mail amavis[26931]: (26931-20) get_deadline mime_decode - deadline in 479.8 s, set to 288.000 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) prolong_timer mime_decode: timer 288, was 288, deadline in 479.8 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) get_deadline mime_decode-1 - deadline in 479.8 s, set to 288.000 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) prolong_timer mime_decode-1: timer 288, was 288, deadline in 479.8 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) decode_parts: level=1, #parts=3 : p001, p002, p003
Feb 18 20:05:49 mail amavis[26931]: (26931-20) running file(1) on 2 files, arglist size 23
Feb 18 20:05:49 mail amavis[26931]: (26931-20) run_command: [17122] /usr/bin/file p001 p002 </dev/null 2>&1
Feb 18 20:05:49 mail amavis[17122]: (26931-20) open_on_specific_fd: target fd0 closing, to become < /dev/null
Feb 18 20:05:49 mail amavis[17122]: (26931-20) open_on_specific_fd: target fd1 closing, to become (65) &=14
Feb 18 20:05:49 mail amavis[17122]: (26931-20) open_on_specific_fd: target fd1 dup2 from fd14 (65) &=14
Feb 18 20:05:49 mail amavis[17122]: (26931-20) open_on_specific_fd: source fd14 closed
Feb 18 20:05:49 mail amavis[17122]: (26931-20) open_on_specific_fd: target fd2 closing, to become (65) &1
Feb 18 20:05:49 mail amavis[17122]: (26931-20) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Feb 18 20:05:49 mail amavis[26931]: (26931-20) result line from file(1): p001: ASCII text, with very long lines\n
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_re("ASCII text, with very long lines") matches key "(?^i:^(ASCII|text)\\b)", result="asc"
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [map_full_type_to_short_type] => true,  "ASCII text, with very long lines" matches, result="asc", matching_key="(?^i:^(ASCII|text)\\b)"
Feb 18 20:05:49 mail amavis[26931]: (26931-20) File-type of p001: ASCII text, with very long lines; (asc)
Feb 18 20:05:49 mail amavis[26931]: (26931-20) result line from file(1): p002: HTML document, ASCII text, with very long lines\n
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_re("HTML document, ASCII text, with very long lines") matches key "(?^i:\\btext\\b)", result="asc"
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [map_full_type_to_short_type] => true,  "HTML document, ASCII text, with very long lines" matches, result="asc", matching_key="(?^i:\\btext\\b)"
Feb 18 20:05:49 mail amavis[26931]: (26931-20) File-type of p002: HTML document, ASCII text, with very long lines; (asc)
Feb 18 20:05:49 mail amavis[26931]: (26931-20) decompose_part: p001 - atomic
Feb 18 20:05:49 mail amavis[26931]: (26931-20) decompose_part: p002 - atomic
Feb 18 20:05:49 mail amavis[26931]: (26931-20) get_deadline parts_decode - deadline in 479.6 s, set to 288.000 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) prolong_timer parts_decode: timer 288, was 288, deadline in 479.6 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_sql_field(bypass_header_checks) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [bypass_header_checks] => undef, "myaccount@example.com" does not match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) check_header: 0, OK
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_sql_field(bypass_header_checks) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [bypass_header_checks] => undef, "myaccount@example.com" does not match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) Checking for banned types and filenames
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_sql_field(banned_rulenames) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="DEFAULT"
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [banned_filename], 1 matches for "myaccount@example.com", results: "(constant:DEFAULT)"=>"DEFAULT"
Feb 18 20:05:49 mail amavis[26931]: (26931-20) collect banned table[0]: myaccount@example.com, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x3a4e3f0)
Feb 18 20:05:49 mail amavis[26931]: (26931-20) starting banned checks - traversing message structure tree
Feb 18 20:05:49 mail amavis[26931]: (26931-20) check_for_banned (p003,p001) multipart/alternative | text/plain,.asc
Feb 18 20:05:49 mail amavis[26931]: (26931-20) doing banned check for myaccount@example.com on multipart/alternative | text/plain,.asc
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_re(["multipart/alternative","text/plain",".asc"]), no matches
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [check_bann:myaccount@example.com] => undef, ["multipart/alternative","text/plain",".asc"] does not match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_re("P=p003\tL=1\tM=multipart/alternative\nP=p001\tL=1/1\tM=text/plain\tT=asc"), no matches
Feb 18 20:05:49 mail amavis[26931]: (26931-20) 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
Feb 18 20:05:49 mail amavis[26931]: (26931-20) p.path myaccount@example.com: "P=p003,L=1,M=multipart/alternative | P=p001,L=1/1,M=text/plain,T=asc"
Feb 18 20:05:49 mail amavis[26931]: (26931-20) check_for_banned (p003,p002) multipart/alternative | text/html,.asc
Feb 18 20:05:49 mail amavis[26931]: (26931-20) doing banned check for myaccount@example.com on multipart/alternative | text/html,.asc
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_re(["multipart/alternative","text/html",".asc"]), no matches
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [check_bann:myaccount@example.com] => undef, ["multipart/alternative","text/html",".asc"] does not match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_re("P=p003\tL=1\tM=multipart/alternative\nP=p002\tL=1/2\tM=text/html\tT=asc"), no matches
Feb 18 20:05:49 mail amavis[26931]: (26931-20) 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
Feb 18 20:05:49 mail amavis[26931]: (26931-20) p.path myaccount@example.com: "P=p003,L=1,M=multipart/alternative | P=p002,L=1/2,M=text/html,T=asc"
Feb 18 20:05:49 mail amavis[26931]: (26931-20) banned check: any=0, all=N (1)
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_re("MAIL"), no matches
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [keep_decoded_original] => undef, "MAIL" does not match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) Calling virus scanners, 2 files to scan in /var/spool/amavisd/tmp/amavis-20200216T172050-26931-ggcVOhrA/parts
Feb 18 20:05:49 mail amavis[26931]: (26931-20) invoking av-scanner clamav-socket
Feb 18 20:05:49 mail amavis[26931]: (26931-20) ask_daemon: proto=DFLT, spawn=0, (clamav-socket) /var/run/clamd.amavisd/clamd.socket
Feb 18 20:05:49 mail amavis[26931]: (26931-20) run_av (clamav-socket): query template(1,1): CONTSCAN {}\n
Feb 18 20:05:49 mail amavis[26931]: (26931-20) get_deadline run_av_pre - deadline in 479.6 s, set to 288.000 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) prolong_timer run_av_pre: timer 288, was 288, deadline in 479.6 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) get_deadline run_av_scan - deadline in 479.6 s, set to 288.000 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) prolong_timer run_av_scan: timer 288, was 288, deadline in 479.6 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) run_av Using (clamav-socket): (code) CONTSCAN /var/spool/amavisd/tmp/amavis-20200216T172050-26931-ggcVOhrA/parts\n
Feb 18 20:05:49 mail amavis[26931]: (26931-20) get_deadline ask_daemon_internal_connect_pre - deadline in 479.6 s, set to 288.000 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) get_deadline ask_daemon_internal_connect - deadline in 479.6 s, set to 10.000 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) prolong_timer ask_daemon_internal_connect: timer 10, was 288, deadline in 479.6 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) clamav-socket: Connecting to socket  /var/run/clamd.amavisd/clamd.socket
Feb 18 20:05:49 mail amavis[26931]: (26931-20) new socket by IO::Socket::UNIX to /var/run/clamd.amavisd/clamd.socket, timeout set to 10
Feb 18 20:05:49 mail amavis[26931]: (26931-20) connected to /var/run/clamd.amavisd/clamd.socket successfully
Feb 18 20:05:49 mail amavis[26931]: (26931-20) clamav-socket: Sending CONTSCAN /var/spool/amavisd/tmp/amavis-20200216T172050-26931-ggcVOhrA/parts\n to socket /var/run/clamd.amavisd/clamd.socket
Feb 18 20:05:49 mail amavis[26931]: (26931-20) rw_loop: needline=0, flush=1, wr=1, timeout=10
Feb 18 20:05:49 mail amavis[26931]: (26931-20) rw_loop: sending 76 chars
Feb 18 20:05:49 mail amavis[26931]: (26931-20) rw_loop sent 76> CONTSCAN /var/spool/amavisd/tmp/amavis-20200216T172050-26931-ggcVOhrA/parts\n
Feb 18 20:05:49 mail amavis[26931]: (26931-20) get_deadline ask_daemon_internal_scan - deadline in 479.6 s, set to 288.000 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) prolong_timer ask_daemon_internal_scan: timer 288, was 10, deadline in 479.6 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) rw_loop: needline=0, flush=0, wr=0, timeout=287.994
Feb 18 20:05:49 mail amavis[26931]: (26931-20) rw_loop: receiving
Feb 18 20:05:49 mail amavis[26931]: (26931-20) rw_loop read 71 chars< /var/spool/amavisd/tmp/amavis-20200216T172050-26931-ggcVOhrA/parts: OK\n
Feb 18 20:05:49 mail amavis[26931]: (26931-20) rw_loop: needline=0, flush=0, wr=0, timeout=287.994
Feb 18 20:05:49 mail amavis[26931]: (26931-20) rw_loop: receiving
Feb 18 20:05:49 mail amavis[26931]: (26931-20) rw_loop read: got eof
Feb 18 20:05:49 mail amavis[26931]: (26931-20) get_deadline ask_daemon_internal - deadline in 479.4 s, set to 288.000 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) prolong_timer ask_daemon_internal: timer 288, was 288, deadline in 479.4 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) get_deadline run_av_3 - deadline in 479.4 s, set to 288.000 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) prolong_timer run_av_3: timer 288, was 288, deadline in 479.4 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) run_av (clamav-socket) result: /var/spool/amavisd/tmp/amavis-20200216T172050-26931-ggcVOhrA/parts: OK\n
Feb 18 20:05:49 mail amavis[26931]: (26931-20) run_av (clamav-socket): CLEAN
Feb 18 20:05:49 mail amavis[26931]: (26931-20) run_av (clamav-socket) result: clean
Feb 18 20:05:49 mail amavis[26931]: (26931-20) wbl: checking sender <bloodpressurex@pumpkingene.icu>
Feb 18 20:05:49 mail amavis[26931]: (26931-20) wbl: (SQL) recip <myaccount@example.com>, 1 matches
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="1"
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [local_domains] => true,  "bloodpressurex@pumpkingene.icu" matches, result="1", matching_key="(constant:1)"
Feb 18 20:05:49 mail amavis[26931]: (26931-20) query_keys: bloodpressurex@pumpkingene.icu, bloodpressurex, @pumpkingene.icu, @.pumpkingene.icu, @.icu, @.
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_sql sel_wblist "bloodpressurex@pumpkingene.icu", query args: "1", [bloodpressurex@pumpkingene.icu,-3], [bloodpressurex,-3], [@pumpkingene.icu,-3], [@.pumpkingene.icu,-3], [@.icu,-3], [@.,-3]
Feb 18 20:05:49 mail amavis[26931]: (26931-20) 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
Feb 18 20:05:49 mail amavis[26931]: (26931-20) sql begin, nontransaction
Feb 18 20:05:49 mail amavis[26931]: (26931-20) 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
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_sql, "bloodpressurex@pumpkingene.icu" no match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_sql_field(wb), "bloodpressurex@pumpkingene.icu" no matching records
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup => undef, "bloodpressurex@pumpkingene.icu" does not match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) wbl: (SQL) recip <myaccount@example.com>, rid=1, got: ""
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [blacklist_recip<myaccount@example.com>] => undef, "myaccount@example.com" does not match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [blacklist_sender<bloodpressurex@pumpkingene.icu>,blacklist_sender] => undef, "bloodpressurex@pumpkingene.icu" does not match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [whitelist_recip<myaccount@example.com>] => undef, "myaccount@example.com" does not match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [whitelist_sender<bloodpressurex@pumpkingene.icu>,whitelist_sender] => undef, "bloodpressurex@pumpkingene.icu" does not match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) query_keys: cached myaccount@example.com
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_hash(myaccount@example.com) matches keys: "."=>ARRAY(0x3a188b0)
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [score_recip<myaccount@example.com>,score_sender], 1 matches for "myaccount@example.com", results: "."=>[Amavis::Lookup::RE=ARRAY(0x3a4e528),{amavis-user-admin@lists.sourceforge.net=>"-3",owner-postfix-announce@postfix.org=>"-3",ntbugtraq@listserv.ntbugtraq.com=>"-3",donotreply@sendmail.org=>"-3",slashdot@slashdot.org=>"-3",clp-request@comp.nus.edu.sg=>"-3",nobody@cert.org=>"-3",security-alerts@linuxsecurity.com=>"-3",cvs-commits-list-admin@gnome.org=>"-3",amavis-user-bounces@lists.sourceforge.net=>"-3",notification-return@lists.sophos.com=>"-3",mailman-announce-admin@python.org=>"-3",emailnews@genomeweb.com=>"-5",owner-textbreakingnews@cnnimail12.cnn.com=>"-5",ca+envelope@sendmail.org=>"-3",cert-advisory@us-cert.gov=>"-3",returns.groups.yahoo.com=>"-3",owner-postfix-users@postfix.org=>"-3",.example.net=>"1",securityfocus.com=>"-3",yahoo-dev-null@yahoo-inc.com=>"-3",owner-alert@iss.net=>"-3",sendmail-announce-request@lists.sendmail.org=>"-3",sur...
Feb 18 20:05:49 mail amavis[26931]: (26931-20) ...veys-errors@lists.nua.ie=>"-3",spamassassin.apache.org=>"-3",lvs-users-admin@linuxvirtualserver.org=>"-3",sender@example.net=>"3",owner-sendmail-announce@lists.sendmail.org=>"-3",noreply@freshmeat.net=>"-3",ietf-123-owner@loki.ietf.org=>"-3",clusternews@linuxnetworx.com=>"-3",owner-technews@postel.acm.org=>"-3",rt-users-admin@lists.fsck.com=>"-3"}]
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_re("bloodpressurex@pumpkingene.icu"), no matches
Feb 18 20:05:49 mail amavis[26931]: (26931-20) query_keys: bloodpressurex@pumpkingene.icu, bloodpressurex@, pumpkingene.icu, .pumpkingene.icu, .icu, .
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_hash(bloodpressurex@pumpkingene.icu), no matches
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [score_sender<bloodpressurex@pumpkingene.icu>] => undef, "bloodpressurex@pumpkingene.icu" does not match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) SpamControl: calling spam scanner SpamAssassin
Feb 18 20:05:49 mail amavis[26931]: (26931-20) get_deadline spam_scan_sa_pre - deadline in 479.3 s, set to 476.000 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) prolong_timer spam_scan_sa_pre: timer 476, was 288, deadline in 479.3 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_sql_field(sa_userconf) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [sa_userconf] => undef, "myaccount@example.com" does not match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup_sql_field(sa_username) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:49 mail amavis[26931]: (26931-20) lookup [sa_username] => undef, "myaccount@example.com" does not match
Feb 18 20:05:49 mail amavis[26931]: (26931-20) SA user config: "", username: "amavis", 0, (0)myaccount@example.com
Feb 18 20:05:49 mail amavis[26931]: (26931-20) calling SA parse (0), SA vers 3.4.0, 3.004000, data as STRING_REF, recips_ind [0], user: "amavis"
Feb 18 20:05:49 mail amavis[26931]: (26931-20) get_deadline SA check - deadline in 479.3 s, set to 475.000 s
Feb 18 20:05:49 mail amavis[26931]: (26931-20) mimepart digest: 978e39ab62654c0f362089956dfa5d79ed9a60ee:text/plain
Feb 18 20:05:49 mail amavis[26931]: (26931-20) mimepart digest: 26c110e4cd4c1bb562c446d4a6a0ec116c7551eb:text/html
Feb 18 20:05:49 mail amavis[26931]: (26931-20) CALLING SA check (0)
Feb 18 20:05:53 mail amavis[26931]: (26931-20) DONE SA check (0)
Feb 18 20:05:53 mail amavis[26931]: (26931-20) get_deadline spam_scan_sa - deadline in 475.5 s, set to 286.000 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) prolong_timer spam_scan_sa: timer 286, was 473, deadline in 475.5 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) spam_scan: score=1.183 autolearn=no autolearn_force=no tests=[DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,HTML_MESSAGE=0.001,RDNS_NONE=1.274,SPF_HELO_PASS=-0.001,SPF_PASS=-0.001,T_REMOTE_IMAGE=0.01] recips=0
Feb 18 20:05:53 mail amavis[26931]: (26931-20) get_deadline spam_scan - deadline in 475.5 s, set to 286.000 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) prolong_timer spam_scan: timer 286, was 286, deadline in 475.5 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup => undef, "@pumpkingene.icu", no lookup tables
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup => undef, "@pumpkingene.icu", no lookup tables
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup_sql_field(spam_tag_level) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="2"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup [spam_tag_level] => true,  "myaccount@example.com" matches, result="2", matching_key="(constant:2)"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup_sql_field(spam_tag2_level) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="6.2"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup [spam_tag2_level] => true,  "myaccount@example.com" matches, result="6.2", matching_key="(constant:6.2)"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup_sql_field(spam_tag3_level) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup [spam_tag3_level] => undef, "myaccount@example.com" does not match
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup_sql_field(spam_kill_level) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="6.9"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup [spam_kill_level] => true,  "myaccount@example.com" matches, result="6.9", matching_key="(constant:6.9)"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup_sql_field(message_size_limit) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup [message_size_limit] => undef, "myaccount@example.com" does not match
Feb 18 20:05:53 mail amavis[26931]: (26931-20) final_destiny (ccat=0) is PASS, recip myaccount@example.com
Feb 18 20:05:53 mail amavis[26931]: (26931-20) final_destiny PASS, recip myaccount@example.com
Feb 18 20:05:53 mail amavis[26931]: (26931-20) do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
Feb 18 20:05:53 mail amavis[26931]: (26931-20) do_notify_and_quarantine: not quarantining, q_method off
Feb 18 20:05:53 mail amavis[26931]: (26931-20) skip admin notification, no administrators
Feb 18 20:05:53 mail amavis[26931]: (26931-20) do_notify_and_quarantine - done
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup_sql_field(forward_method) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup [forward_method] => true,  "myaccount@example.com" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) delivery method is 1, recips: myaccount@example.com
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup_sql_field(spam_tag_level) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="2"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup [spam_tag_level] => true,  "myaccount@example.com" matches, result="2", matching_key="(constant:2)"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup_sql_field(spam_tag2_level) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="6.2"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup [spam_tag2_level] => true,  "myaccount@example.com" matches, result="6.2", matching_key="(constant:6.2)"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) headers CLUSTERING: NEW CLUSTER <myaccount@example.com>: score=1.183, tag=0, tag2=0, local=1, bl=, s=, mangle=
Feb 18 20:05:53 mail amavis[26931]: (26931-20) header encoded (all-ASCII): X-Virus-Scanned: amavisd-new at mail.example.com
Feb 18 20:05:53 mail amavis[26931]: (26931-20) header: X-Virus-Scanned: amavisd-new at mail.example.com\n
Feb 18 20:05:53 mail amavis[26931]: (26931-20) fwd: scanner provided a header field X-Spam-Checker-Version, inhibited by %allowed_added_header_fields
Feb 18 20:05:53 mail amavis[26931]: (26931-20) fwd: scanner provided a header field X-Spam-Level, but we preferred our own
Feb 18 20:05:53 mail amavis[26931]: (26931-20) fwd: scanner provided a header field X-Spam-Status, but we preferred our own
Feb 18 20:05:53 mail amavis[26931]: (26931-20) header encoded (all-ASCII): Authentication-Results: mail.example.com (amavisd-new);\n dkim=pass (1024-bit key)\n header.d=pumpkingene.icu;\n domainkeys=pass (1024-bit key)\n header.from=bloodpressurex@pumpkingene.icu\n header.d=pumpkingene.icu
Feb 18 20:05:53 mail amavis[26931]: (26931-20) header: Authentication-Results: mail.example.com (amavisd-new); dkim=pass (1024-bit key)\n\theader.d=pumpkingene.icu; domainkeys=pass (1024-bit key)\n\theader.from=bloodpressurex@pumpkingene.icu header.d=pumpkingene.icu\n
Feb 18 20:05:53 mail amavis[26931]: (26931-20) header encoded (all-ASCII): Received: from mail.example.com ([127.0.0.1])\n by mail.example.com (mail.example.com [127.0.0.1]) (amavisd-new, port 10024)\n with ESMTP\n id 0K71G378jb83\n for <myaccount@example.com>;\n Tue, 18 Feb 2020 20:05:48 +0000 (UTC)
Feb 18 20:05:53 mail amavis[26931]: (26931-20) header: Received: from mail.example.com ([127.0.0.1])\n\tby mail.example.com (mail.example.com [127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id 0K71G378jb83 for <myaccount@example.com>;\n\tTue, 18 Feb 2020 20:05:48 +0000 (UTC)\n
Feb 18 20:05:53 mail amavis[26931]: (26931-20) headers CLUSTERING: done all 1 recips in one go
Feb 18 20:05:53 mail amavis[26931]: (26931-20) about to connect to smtp:[127.0.0.1]:10025, 0K71G378jb83 FWD from <bloodpressurex@pumpkingene.icu> -> <myaccount@example.com>
Feb 18 20:05:53 mail amavis[26931]: (26931-20) get_deadline fwd_init - deadline in 475.5 s, set to 476.000 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) smtp session: setting up a new session
Feb 18 20:05:53 mail amavis[26931]: (26931-20) establish_or_refresh, state: down
Feb 18 20:05:53 mail amavis[26931]: (26931-20) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35
Feb 18 20:05:53 mail amavis[26931]: (26931-20) connected to [127.0.0.1]:10025 successfully
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: needline=1, flush=0, wr=0, timeout=35
Feb 18 20:05:53 mail postfix/10025/smtpd[17138]: connect from localhost[127.0.0.1]
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: receiving
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop read 34 chars< 220 mail.example.com ESMTP Postfix\r\n
Feb 18 20:05:53 mail amavis[26931]: (26931-20) smtp greeting: 220 mail.example.com ESMTP Postfix, dt: 15.2 ms
Feb 18 20:05:53 mail amavis[26931]: (26931-20) smtp cmd> EHLO mail.example.com
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: needline=0, flush=1, wr=1, timeout=300
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: sending 21 chars
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop sent 21> EHLO mail.example.com\r\n
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: needline=1, flush=0, wr=0, timeout=300
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: receiving
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop read 113 chars< 250-mail.example.com\r\n250-PIPELINING\r\n250-SIZE 15728640\r\n250-ETRN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n
Feb 18 20:05:53 mail amavis[26931]: (26931-20) smtp resp to EHLO: 250 mail.example.com\nPIPELINING\nSIZE 15728640\nETRN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
Feb 18 20:05:53 mail amavis[26931]: (26931-20) tls active=0, capable=, sec_level=0
Feb 18 20:05:53 mail amavis[26931]: (26931-20) Remote host presents itself as: mail.example.com, handles DSN, PIPELINING, 8BITMIME
Feb 18 20:05:53 mail amavis[26931]: (26931-20) AUTH not needed, user='', MTA offers ''
Feb 18 20:05:53 mail amavis[26931]: (26931-20) smtp cmd> MAIL FROM:<bloodpressurex@pumpkingene.icu> RET=HDRS BODY=7BIT
Feb 18 20:05:53 mail amavis[26931]: (26931-20) orcpt_encode rfc822, catchallemail@example.com, encode_for_smtp
Feb 18 20:05:53 mail amavis[26931]: (26931-20) smtp cmd> RCPT TO:<myaccount@example.com> ORCPT=rfc822;catchallemail@example.com
Feb 18 20:05:53 mail amavis[26931]: (26931-20) smtp cmd> DATA
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: needline=0, flush=1, wr=1, timeout=120
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: sending 136 chars
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop sent 136> MAIL FROM:<bloodpressurex@pumpkingene.icu> RET=HDRS BODY=7BIT\r\nRCPT TO:<myaccount@example.com> ORCPT=rfc822;catchallemail@example.com\r\nDATA\r\n
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: needline=1, flush=0, wr=0, timeout=300
Feb 18 20:05:53 mail postfix/10025/smtpd[17138]: 48MX0d2pMnzcf3G: client=localhost[127.0.0.1]
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: receiving
Feb 18 20:05:53 mail amavis[26931]: (26931-20) 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
Feb 18 20:05:53 mail amavis[26931]: (26931-20) smtp resp to MAIL (pip): 250 2.1.0 Ok
Feb 18 20:05:53 mail amavis[26931]: (26931-20) smtp resp to RCPT (pip) (<myaccount@example.com>): 250 2.1.5 Ok
Feb 18 20:05:53 mail amavis[26931]: (26931-20) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Feb 18 20:05:53 mail amavis[26931]: (26931-20) write_header: 1, Amavis::Out::SMTP::Protocol=HASH(0x8df61b8)
Feb 18 20:05:53 mail amavis[26931]: (26931-20) smtp connection_cache disabled, sending QUIT
Feb 18 20:05:53 mail amavis[26931]: (26931-20) smtp cmd> QUIT
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: needline=0, flush=1, wr=1, timeout=475.965
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: sending 32540 chars
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop sent 32540> X-Virus-Scanned: amavisd-new at mail.example.com\r\nAuthentication-Results: mail.example.com (amavisd-new); dkim=pass (1024-bit key)\r\n\theader.d=pumpkingene.icu; domainkeys=pass (1024-bit key)\r\n\theader.from= [...]
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: needline=1, flush=0, wr=0, timeout=475.965
Feb 18 20:05:53 mail postfix/cleanup[17094]: 48MX0d2pMnzcf3G: message-id=<t7jqdatbhWCqIVDZ5YyQPkseONdnJI_E3IvOcJf2qxs.m-D6nUw9HHgPQG3BZvwZHlY1bkbPDF-Qv3OmzFHffkw@pumpkingene.icu>
Feb 18 20:05:53 mail postfix/10025/smtpd[17138]: disconnect from localhost[127.0.0.1]
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop: receiving
Feb 18 20:05:53 mail postfix/qmgr[32098]: 48MX0d2pMnzcf3G: from=<bloodpressurex@pumpkingene.icu>, size=32790, nrcpt=1 (queue active)
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rw_loop read 56 chars< 250 2.0.0 Ok: queued as 48MX0d2pMnzcf3G\r\n221 2.0.0 Bye\r\n
Feb 18 20:05:53 mail amavis[26931]: (26931-20) smtp resp to data-dot (<myaccount@example.com>): 250 2.0.0 Ok: queued as 48MX0d2pMnzcf3G, dt: 3.4 ms
Feb 18 20:05:53 mail amavis[26931]: (26931-20) Amavis::Out::SMTP::Session close, disconnecting
Feb 18 20:05:53 mail amavis[26931]: (26931-20) get_deadline fwd-end-chkpnt - deadline in 475.5 s, set to 286.000 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) prolong_timer fwd-end-chkpnt: timer 286, was 0, deadline in 475.5 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) 0K71G378jb83 FWD from <bloodpressurex@pumpkingene.icu> -> <myaccount@example.com>, RET=HDRS BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 48MX0d2pMnzcf3G
Feb 18 20:05:53 mail amavis[26931]: (26931-20) get_deadline forwarding - deadline in 475.5 s, set to 286.000 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) prolong_timer forwarding: timer 286, was 286, deadline in 475.5 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) DSN: sender is credible (dkim), SA: 1.183, <bloodpressurex@pumpkingene.icu>
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="18"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup [spam_crediblefrom_dsn_cutoff_level_bysender] => true,  "bloodpressurex@pumpkingene.icu" matches, result="18", matching_key="(constant:18)"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) dsn: from MTA 250 NonBlocking:Clean <bloodpressurex@pumpkingene.icu> -> <myaccount@example.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 48MX0d2pMnzcf3G"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) DSN: SUCC from MTA 250 NonBlocking:Clean, no DSN requested: <bloodpressurex@pumpkingene.icu> -> <myaccount@example.com>
Feb 18 20:05:53 mail amavis[26931]: (26931-20) delivery_status_notification: notif 0 bytes, suppressed: no
Feb 18 20:05:53 mail amavis[26931]: (26931-20) one_response_for_all, per_recip_capable: N, suppressed: N
Feb 18 20:05:53 mail amavis[26931]: (26931-20) one_response_for_all <bloodpressurex@pumpkingene.icu>: 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 48MX0d2pMnzcf3G'
Feb 18 20:05:53 mail amavis[26931]: (26931-20) 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 48MX0d2pMnzcf3G
Feb 18 20:05:53 mail amavis[26931]: (26931-20) get_deadline delivery-notification - deadline in 475.5 s, set to 286.000 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) prolong_timer delivery-notification: timer 286, was 286, deadline in 475.5 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
Feb 18 20:05:53 mail amavis[26931]: (26931-20) get_deadline snmp-counters - deadline in 475.5 s, set to 286.000 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) prolong_timer snmp-counters: timer 286, was 286, deadline in 475.5 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) orcpt_encode rfc822, catchallemail@example.com, smtputf8
Feb 18 20:05:53 mail amavis[26931]: (26931-20) oldest_public_ip_addr_from_received: 213.142.151.123
Feb 18 20:05:53 mail amavis[26931]: (26931-20) Passed CLEAN {RelayedInbound}, [213.142.151.123]:17936 [213.142.151.123] ESMTP/ESMTP <bloodpressurex@pumpkingene.icu> -> <myaccount@example.com>, (ESMTP://[213.142.151.123]:17936), Queue-ID: 48MX0P2NCTzcf1H, Message-ID: <t7jqdatbhWCqIVDZ5YyQPkseONdnJI_E3IvOcJf2qxs.m-D6nUw9HHgPQG3BZvwZHlY1bkbPDF-Qv3OmzFHffkw@pumpkingene.icu>, mail_id: 0K71G378jb83, b: IJL49MdNg, Hits: 1.183, size: 32056, queued_as: 48MX0d2pMnzcf3G, Subject: "BloodPressureX might be the gadget to save your life", From: <bloodpressurex@pumpkingene.icu> (dkim:AUTHOR), helo=pumpkingene.icu, Tests: [DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,HTML_MESSAGE=0.001,RDNS_NONE=1.274,SPF_HELO_PASS=-0.001,SPF_PASS=-0.001,T_REMOTE_IMAGE=0.01], autolearn=no autolearn_force=no, autolearnscore=1.185, dkim_i=bloodpressurex@pumpkingene.icu,bloodpressurex@pumpkingene.icu, dkim_sd=mail:pumpkingene.icu, 4643 ms
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup_sql_field(spam_tag_level) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="2"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup [spam_tag_level] => true,  "myaccount@example.com" matches, result="2", matching_key="(constant:2)"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup_sql_field(spam_tag2_level) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="6.2"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup [spam_tag2_level] => true,  "myaccount@example.com" matches, result="6.2", matching_key="(constant:6.2)"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup_sql_field(spam_kill_level) rec=0, "myaccount@example.com" result: undef
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup: (scalar) matches, result="6.9"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) lookup [spam_kill_level] => true,  "myaccount@example.com" matches, result="6.9", matching_key="(constant:6.9)"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) Passed CLEAN, <bloodpressurex@pumpkingene.icu> -> <myaccount@example.com>, Hits: 1.183, tag=2, tag2=6.2, kill=6.9, queued_as: 48MX0d2pMnzcf3G, L/0/0/0
Feb 18 20:05:53 mail amavis[26931]: (26931-20) get_deadline main_log_entry - deadline in 475.4 s, set to 286.000 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) prolong_timer main_log_entry: timer 286, was 286, deadline in 475.4 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) sql begin transaction
Feb 18 20:05:53 mail amavis[26931]: (26931-20) 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 (?,?,?,?,?,?,?,?,?,?,?,?)
Feb 18 20:05:53 mail amavis[26931]: (26931-20) save_info_final 0K71G378jb83, orig=N, chks=VSHBD, cont.ty=C, q.type= , q.to=, dsn=N, score=1.183, Message-ID: <t7jqdatbhWCqIVDZ5YyQPkseONdnJI_E3IvOcJf2qxs.m-D6nUw9HHgPQG3BZvwZHlY1bkbPDF-Qv3OmzFHffkw@pumpkingene.icu>, From: '"BloodPressureX" <bloodpressurex@pumpkingene.
icu>', Subject: 'BloodPressureX might be the gadget to save your life'
Feb 18 20:05:53 mail amavis[26931]: (26931-20) 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=?
Feb 18 20:05:53 mail amavis[26931]: (26931-20) sql commit
Feb 18 20:05:53 mail amavis[26931]: (26931-20) TIMING-SA total 3792 ms - parse: 15 (0.4%), b_tie_ro: 15 (0.4%), extract_message_metadata: 62 (1.6%), get_uri_detail_list: 11 (0.3%), tests_pri_-1000: 44 (1.2%), tests_pri_-950: 2.1 (0.1%), tests_pri_-900: 2.2 (0.1%), tests_pri_-90: 1.28 (0.0%), tests_pri_0: 2219 (58.5
%), check_spf: 27 (0.7%), poll_dns_idle: 0.28 (0.0%), tests_pri_20: 1352 (35.6%), check_razor2: 1349 (35.6%), tests_pri_30: 3.8 (0.1%), check_pyzor: 1.16 (0.0%), tests_pri_500: 27 (0.7%), get_report: 0.64 (0.0%)
Feb 18 20:05:53 mail amavis[26931]: (26931-20) get_deadline check done - deadline in 475.4 s, set to 286.000 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) prolong_timer check done: timer 286, was 286, deadline in 475.4 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 48MX0d2pMnzcf3G"
Feb 18 20:05:53 mail amavis[26931]: (26931-20) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 48MX0d2pMnzcf3G
Feb 18 20:05:53 mail amavis[26931]: (26931-20) switch_to_client_time 480 s, smtp response sent
Feb 18 20:05:53 mail postfix/amavis/smtp[17121]: 48MX0P2NCTzcf1H: to=<myaccount@example.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=12, delays=7.6/0.02/0.07/4.6, 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 48MX0d2pMnzcf3G)
Feb 18 20:05:53 mail amavis[26931]: (26931-20) TempDir::strip: /var/spool/amavisd/tmp/amavis-20200216T172050-26931-ggcVOhrA
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rmdir_recursively: /var/spool/amavisd/tmp/amavis-20200216T172050-26931-ggcVOhrA/parts, excl=1
Feb 18 20:05:53 mail postfix/qmgr[32098]: 48MX0P2NCTzcf1H: removed
Feb 18 20:05:53 mail amavis[26931]: (26931-20) size: 32056, TIMING [total 4657 ms] - SMTP greeting: 43 (1%)1, SMTP EHLO: 7 (0%)1, SMTP pre-MAIL: 4.0 (0%)1, SMTP MAIL: 16 (0%)2, lookup_sql: 18 (0%)2, SMTP pre-DATA-flush: 6 (0%)2, SMTP DATA: 3.5 (0%)2, check_init: 2.6 (0%)2, digest_hdr: 25 (1%)3, digest_body_dkim: 44
 (1%)4, collect_info: 9 (0%)4, gen_mail_id: 13 (0%)4, mime_decode: 58 (1%)5, get-file-type2: 244 (5%)11, parts_decode: 1.1 (0%)11, check_header: 2.5 (0%)11, AV-scan-1: 245 (5%)16, lookup_sql: 4.7 (0%)16, spam-wb-list: 3.8 (0%)16, SA msg read: 2.6 (0%)16, SA parse: 20 (0%)17, SA check: 3773 (81%)98, decide_mail_dest
iny: 10 (0%)98, notif-quar: 1.3 (0%)98, fwd-connect: 29 (1%)98, fwd-mail-pip: 12 (0%)99, fwd-rcpt-pip: 0.6 (0%)99, fwd-data-chkpnt: 0.1 (0%)99, write-header: 1.5 (0%)99, fwd-data-contents: 0.8 (0%)99, fwd-end-chkpnt: 6 (0%)99, prepare-dsn: 4.2 (0%)99, report: 6 (0%)99, main_log_entry: 31 (1%)100, sql-update: 5 (0%)
100, SMTP pre-response: 0.7 (0%)100, SMTP response: 0.2 (0%)100, ...
Feb 18 20:05:53 mail amavis[26931]: (26931-20) ...unlink-2-files: 0.8 (0%)100, rundown: 1.0 (0%)100
Feb 18 20:05:53 mail amavis[26931]: (26931-20) idle_proc, 6: was busy, 4568.0 ms, total idle 182644.441 s, busy 58.778 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) idle_proc, 5: was idle, 0.1 ms, total idle 182644.441 s, busy 58.778 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) ESMTP< QUIT\r\n
Feb 18 20:05:53 mail amavis[26931]: (26931-20) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Feb 18 20:05:53 mail amavis[26931]: (26931-20) switch_to_client_time 480 s, smtp response sent
Feb 18 20:05:53 mail amavis[26931]: (26931-20) SMTP session over, timer stopped
Feb 18 20:05:53 mail amavis[26931]: (26931-20) Requesting process rundown after 20 tasks (and 20 sessions)
Feb 18 20:05:53 mail amavis[26931]: (26931-20) TempDir::DESTROY called
Feb 18 20:05:53 mail amavis[26931]: (26931-20) TempDir removal: empty tempdir is being removed: /var/spool/amavisd/tmp/amavis-20200216T172050-26931-ggcVOhrA
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rmdir_recursively: /var/spool/amavisd/tmp/amavis-20200216T172050-26931-ggcVOhrA, excl=
Feb 18 20:05:53 mail amavis[26931]: (26931-20) rmdir_recursively: /var/spool/amavisd/tmp/amavis-20200216T172050-26931-ggcVOhrA/parts, excl=
Feb 18 20:05:53 mail amavis[26931]: (26931-20) exiting process_request
Feb 18 20:05:53 mail amavis[26931]: (26931-20) idle_proc, bye: was busy, 14.0 ms, total idle 182644.441 s, busy 58.792 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) load: 0 %, total idle 182644.441 s, busy 58.792 s
Feb 18 20:05:53 mail amavis[26931]: (26931-20) child_goes_idle (child finishing)
Feb 18 20:05:53 mail amavis[26931]: (26931-20) disconnecting from SQL
Feb 18 20:05:53 mail amavis[26931]: (26931-20) child_goes_idle: disconnected SQL-storage (child finishing)
Feb 18 20:05:53 mail amavis[26931]: (26931-20) SA rundown_child (0)
Feb 18 20:05:53 mail amavis[26931]: (26931-20) SpamControl: rundown_child on SpamAssassin done
Feb 18 20:05:53 mail amavis[26931]: (26931-20) child_finish_hook: invoking DESTROY methods
Feb 18 20:05:53 mail amavis[26931]: (26931-20) Amavis::Out::SQL::Log DESTROY called
Feb 18 20:05:53 mail amavis[26931]: (26931-20) Amavis::Lookup::SQL DESTROY called
Feb 18 20:05:53 mail amavis[26931]: (26931-20) Net::Server: Child leaving (20)
Feb 18 20:05:53 mail postfix/pipe[17140]: 48MX0d2pMnzcf3G: to=<myaccount@example.com>, relay=dovecot, delay=0.09, delays=0.01/0.02/0/0.06, dsn=2.0.0, status=sent (delivered via dovecot service)
Feb 18 20:05:53 mail postfix/qmgr[32098]: 48MX0d2pMnzcf3G: removed
Feb 18 20:05:53 mail amavis[26931]: (26931-20) Amavis::Out::SQL::Connection DESTROY called
Feb 18 20:05:53 mail amavis[26931]: (26931-20) Amavis::Lookup::SQL DESTROY called
Feb 18 20:05:53 mail amavis[26912]: sd_notify (no socket): STATUS=Starting child process(es), ready for work.
Feb 18 20:05:53 mail amavis[26912]: Net::Server: Starting "1" children