Topic: Amavis && strange email deliver
==== REQUIRED BASIC INFO OF YOUR IREDMAIL SERVER ====
- iRedMail version (check /etc/iredmail-release): 1.3.1 MYSQL
- Deployed with iRedMail Easy or the downloadable installer? downloadable
- Linux/BSD distribution name and version: Linux Debian 10
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): Mysql
- Web server (Apache or Nginx): nginx
- Manage mail accounts with iRedAdmin-Pro? Yes
- [IMPORTANT] Related original log or error message is required if you're experiencing an issue.
====
Hi,
I have problem with strange email delivery...
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.007 . dns:A:x.x.x.x.bl.score.senderscore.com
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.010 . dns:MX:xxxxx.xx
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.014 . dns:A:x.x.x.x.list.dnswl.org
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.021 . dns:A:x.x.x.x.dnsbl.sorbs.net
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.026 . dns:A:x.x.x.x.zen.spamhaus.org
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.028 . askdns:TXT:xxxxx.xx
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.042 . dns:A:x.x.x.x.zen.spamhaus.org
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.046 . dns:A:xxxxx.xx
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.048 . dns:A:x.x.x.x.bl.mailspike.net
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.050 . dns:A:x.x.x.x.wl.mailspike.net
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.052 . dns:TXT:x.x.x.x.bl.spamcop.net
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.053 . dns:A:x.x.x.x.dnsbl.sorbs.net
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.063 . askdns:A:xxxxx.xx.fresh.fmb.la.
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.106 . dns:TXT:x.x.x.x.sa-accredit.habeas.com
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.113 . dns:TXT:x.x.x.x.sa-trusted.bondedsender.org
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.123 . dns:A:x.x.x.x.psbl.surriel.com
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.137 . dns:TXT:x.x.x.x.bl.spamcop.net
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: async: timing: 0.138 . dns:A:x.x.x.x.iadb.isipp.com
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: check: tagrun - tag RBL is now ready, value: <dns:xxxxx.xx> [x.x.x.x]
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: check: [...] <dns:xxxxx.xx?type=MX> [10 xxxxxxxxxxx.]
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: check: [...] <dns:x.x.x.x.dnsbl.sorbs.net> [127.0.0.10]
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: rules: running one_line_body tests; score so far=0
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: rules: running head tests; score so far=0
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: rules: running body tests; score so far=0
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: rules: running uri tests; score so far=0
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: rules: running rawbody tests; score so far=0
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: rules: running full tests; score so far=0
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: rules: running meta tests; score so far=0
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: learn: auto-learn: currently using scoreset 1
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: learn: auto-learn: adding head_only points 0.001
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: learn: auto-learn: message score: 0, computed score for autolearn: 0.001
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: learn: auto-learn? ham=0.1, spam=12, body-points=0, head-points=0.001, learned-points=0
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: learn: auto-learn? yes, ham (0.001 < 0.1) autolearn_force=no
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: learn: initializing learner
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: learn: learning ham
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: check: pms new, time limit in 299.822 s
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: plugin: Mail::SpamAssassin::Plugin::WLBLEval=HASH(0x55723fb50030) implements 'check_wb_list', priority 0
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: eval: all '*From' addrs: from@xxxxx.xx
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: eval: all '*To' addrs: to@yyyyy.yy
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: plugin: Mail::SpamAssassin::Plugin::Bayes=HASH(0x55723fb0c4e8) implements 'learn_message', priority 0
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: check: pms new, time limit in 299.820 s
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: locker: mode is 384
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: locker: safe_lock: created /var/lib/amavis/.spamassassin/bayes.lock.yyyyyy.yy.28965
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: locker: safe_lock: trying to get lock on /var/lib/amavis/.spamassassin/bayes with 0 retries
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: locker: safe_lock: link to /var/lib/amavis/.spamassassin/bayes.lock: link ok
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: bayes: tie-ing to DB file R/W /var/lib/amavis/.spamassassin/bayes_toks
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: bayes: tie-ing to DB file R/W /var/lib/amavis/.spamassassin/bayes_seen
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: bayes: found bayes db version 3
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: bayes: tokenized body: 2 tokens
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: bayes: tokenized uri: 0 tokens
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: bayes: tokenized invisible: 0 tokens
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: bayes: tokenized header: 117 tokens
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: bayes: learned '8eebee013fee6c48da5837b3c0afb881cc8c4bc2@sa_generated', atime: 1605482564
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: bayes: untie-ing
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: bayes: files locked, now unlocking lock
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: locker: safe_unlock: unlink /var/lib/amavis/.spamassassin/bayes.lock
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: learn: initializing learner
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: check: is spam? score=0 required=10
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: check: tests=SPF_HELO_NONE,SPF_PASS
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: check: subtests=__ANY_TEXT_ATTACH,__ANY_TEXT_ATTACH_DOC,__BODY_TEXT_LINE,__BODY_TEXT_LINE,__BODY_TEXT_LINE,__BOTH_INR_AND_REF,__CT,__CTE,__CT_TEXT_PLAI
N,__DKIM_DEPENDABLE,__DOS_RCVD_MON,__DOS_RELAYED_EXT,__ENV_AND_HDR_FROM_MATCH,__FROM_FULL_NAME,__HAS_DATE,__HAS_FROM,__HAS_MESSAGE_ID,__HAS_MSGID,__HAS_ORGANIZATION,__HAS_RCVD,__HAS_SUBJECT,__HAS_TO,__HAS_U
A,__HELO_NOT_RDNS,__KAM_BODY_LENGTH_LT_1024,__KAM_BODY_LENGTH_LT_128,__KAM_BODY_LENGTH_LT_256,__KAM_BODY_LENGTH_LT_512,__LAST_EXTERNAL_RELAY_NO_AUTH,__LAST_UNTRUSTED_RELAY_NO_AUTH,__LCL__ENV_AND_HDR_FROM_MA
TCH,__LCL__KAM_BODY_LENGTH_LT_1024,__LCL__KAM_BODY_LENGTH_LT_128,__LCL__KAM_BODY_LENGTH_LT_512,__L_CTE_7BIT,__MIME_VERSION,__MISSING_REF,__MISSING_REPLY,__MOZILLA_MSGID,__MOZILLA_MUA,__MSGID_GUID,__MSGID_OK
_HEX,__MSGID_OK_HOST,__MUA_TBIRD,__NAKED_TO,__NONEMPTY_BODY,__NOT_SPOOFED,__PDS_MSG_1024,__PDS_MSG_512,__RCVD_IN_SORBS,__RDNS_SHORT,__RP_MATCHES_RCVD,__SANE_MSGID,__SINGLE_WORD_LINE,__SINGL...
Nov 16 00:22:45 mail amavis[28965]: (28965-02) ...E_WORD_LINE,__SINGLE_WORD_SUBJ,__SUBJ_SHORT,__TOCC_EXISTS,__TO_NO_ARROWS_R,__TVD_MIME_ATT_TP,__UA_MOZ5
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: timing: total 198 ms - parse: 2.3 (1.2%), extract_message_metadata: 18 (9.2%), get_uri_detail_list: 0.38 (0.2%), tests_pri_-1000: 11 (5.5%), tests_pri_
-950: 2.0 (1.0%), tests_pri_-900: 2.2 (1.1%), tests_pri_-90: 1.92 (1.0%), tests_pri_0: 97 (49.0%), check_spf: 30 (15.0%), poll_dns_idle: 10 (5.1%), check_dkim_adsp: 3.0 (1.5%), tests_pri_20: 2.2 (1.1%), tes
ts_pri_30: 2.4 (1.2%), check_pyzor: 0.29 (0.1%), tests_pri_500: 10 (4.8%), learn: 21 (10.6%), b_learn: 18 (8.9%), b_count_change: 6 (2.9%)
Nov 16 00:22:45 mail amavis[28965]: (28965-02) SA dbg: check: tagrun - tag DKIMDOMAIN is still blocking action 0
Nov 16 00:22:45 mail amavis[28965]: (28965-02) header_edits_for_quar: <from@xxxxx.xx> -> <to@yyyyyy.xx>, Yes, score=0 tag=0 tag2=0 kill=0 tests=[SPF_HELO_NONE=0.001, SPF_PASS=-0.001] autolearn=ham autolearn_force=no
Nov 16 00:22:45 mail amavis[28965]: (28965-02) delivering to sql:, SEND via SQL (DBI:mysql:database=amavisd;host=127.0.0.1;port=3306): <from@xxxxx.xx> -> <to@yyyyyy.xx>, mail_id lPEkqpsXzZNP
Nov 16 00:22:45 mail amavis[28965]: (28965-02) Blocked SPAM {DiscardedInbound,Quarantined}, [x.x.x.x.x]:41501 [x.x.x.x.x] <from@xxxxxx.xx> -> , quarantine: lPEkqpsXzZNP, Queue-ID: D1911C2810, M
essage-ID: <9ee8c648-f7db-46d0-e439-a9e93910b32d@xxxxx.xx>, mail_id: lPEkqpsXzZNP, Hits: 0, size: 915, 308 ms, Tests: [SPF_HELO_NONE=0.001,SPF_PASS=-0.001]
Nov 16 00:22:45 mail amavis[28965]: (28965-02) TIMING-SA total 201 ms - parse: 2.3 (1.2%), extract_message_metadata: 18 (9.1%), get_uri_detail_list: 0.38 (0.2%), tests_pri_-1000: 11 (5.4%), tests_pri_-950:
2.0 (1.0%), tests_pri_-900: 2.2 (1.1%), tests_pri_-90: 1.92 (1.0%), tests_pri_0: 97 (48.4%), check_spf: 30 (14.9%), poll_dns_idle: 10 (5.1%), check_dkim_adsp: 3.0 (1.5%), tests_pri_20: 2.2 (1.1%), tests_pri
_30: 2.4 (1.2%), check_pyzor: 0.29 (0.1%), tests_pri_500: 10 (4.8%), learn: 21 (10.5%), b_learn: 18 (8.8%), b_count_change: 6 (2.9%), get_report: 0.33 (0.2%)
Nov 16 00:22:45 mail postfix/amavis/smtp[29505]: D1911C2810: to=<to@yyyyyy.xx>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.4, delays=0.09/0/0/0.31, dsn=2.7.0, status=sent (250 2.7.0 Ok, discarded, id=28965-02 - spam)
Nov 16 00:22:45 mail postfix/qmgr[16583]: D1911C2810: removed
Nov 16 00:22:45 mail amavis[28965]: (28965-02) size: 915, TIMING [total 313 ms] - SMTP greeting: 2.1 (1%)1, SMTP EHLO: 0.8 (0%)1, SMTP pre-MAIL: 0.8 (0%)1, SMTP MAIL: 1.3 (0%)2, lookup_sql: 2.5 (1%)2, SMTP
pre-DATA-flush: 0.9 (0%)3, SMTP DATA: 37 (12%)15, check_init: 0.2 (0%)15, digest_hdr: 0.8 (0%)15, digest_body_dkim: 0.2 (0%)15, collect_info: 2.0 (1%)16, gen_mail_id: 4.7 (2%)17, mime_decode: 6 (2%)19, get-
file-type1: 17 (6%)25, parts_decode: 0.3 (0%)25, check_header: 0.8 (0%)25, AV-scan-1: 8 (3%)28, lookup_sql: 1.9 (1%)28, lookup_sql: 0.6 (0%)28, lookup_sql: 0.5 (0%)29, spam-wb-list: 0.9 (0%)29, SA msg read:
0.5 (0%)29, SA parse: 3.2 (1%)30, SA check: 197 (63%)93, decide_mail_destiny: 4.3 (1%)94, notif-quar: 0.4 (0%)94, quar-hdrs: 1.1 (0%)95, write-header: 2.2 (1%)95, fwd-sql: 3.5 (1%)97, prepare-dsn: 0.9 (0%)
97, report: 1.2 (0%)97, main_log_entry: 3.2 (1%)98, sql-update: 3.6 (1%)99, SMTP pre-response: 0.2 (0%)99, SMTP response: 0.7 (0%)100, unlink-1-files: 0.2 (0%)100, rundown: 0.7 (0%)100
I have domain policy: check spam, tag email as spam, default spam range
So.. if score is 0 (require 6):
Nov 16 00:22:45 mail amavis[28965]: (28965-02) header_edits_for_quar: <from@xxxxx.xx> -> <to@yyyyyy.xx>, Yes, score=0 tag=0 tag2=0 kill=0 tests=[SPF_HELO_NONE=0.001, SPF_PASS=-0.001] autolearn=ham autolearn_force=no
then why i have:
Nov 16 00:22:45 mail amavis[28965]: (28965-02) Blocked SPAM {DiscardedInbound,Quarantined}, [x.x.x.x.x]:41501 [x.x.x.x.x] <from@xxxxxx.xx> -> , quarantine: lPEkqpsXzZNP, Queue-ID: D1911C2810, M
essage-ID: <9ee8c648-f7db-46d0-e439-a9e93910b32d@xxxxx.xx>, mail_id: lPEkqpsXzZNP, Hits: 0, size:
??
----
Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.