Aug 5, 2024: iRedMail-1.7.1 has been released.

**SViRU** · 2016-05-25 23:49:41

SViRU
Member
Offline

Registered: 2016-01-06
Posts: 8

Topic: Whitelist not working?

==== Required information ====
- iRedMail version (check /etc/iredmail-release): 0.9.4
- Linux/BSD distribution name and version: FreeBSD
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQL
- Web server (Apache or Nginx): Apache
- Manage mail accounts with iRedAdmin-Pro? Yes
- Related log if you're reporting an issue:
====

Hello
We have some problems with Whitelist

Despite the addition of the sender to whitelist (System -> Anti SPam -> Whitelist -> For Inbound Mails -> Whitelisted senders: @senderdomain.com )
Amavis treats the mail from this sender as SPAM

/var/log/iredapd/iredapd.log:

2016-05-24 15:32:12 INFO [XX.XX.XX.XX] RCPT, xyz@senderdomain.com -> user@mydomain.com, OK inbound_wblist=(1, 49, 'W')
2016-05-24 15:32:12 INFO [XX.XX.XX.XX] END-OF-MESSAGE, xyz@senderdomain.com -> user@mydomain.com, DUNNO

/var/log/maillog:

May 25 15:24:15 mx amavis[97597]: (97597-14) Blocked SPAM {DiscardedInbound,Quarantined}, [XX.XX.XX.XX]:56966 [XX.XX.XX.XX] <xyz@senderdomain.com> -> <user@mydomain.com>, quarantine: aBnsJLRRqBJW, Queue-ID: 40AE03E5B11, Message-ID: <842164080@senderdomain.com>, mail_id: aBnsJLRRqBJW, Hits: 10.017, size: 1623, 3433 ms
May 25 15:24:15 mx postfix/smtp[97955]: 40AE03E5B11: to=<user@mydomain.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=5.3, delays=1.9/0/0/3.4, dsn=2.7.0, status=sent (250 2.7.0 Ok, discarded, id=97597-14 - spam)
May 25 15:24:15 mx postfix/qmgr[31958]: 40AE03E5B11: removed

I release every time the message with option (Release selected and whitelist entire sender domains) but it does not help

----

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

**ZhangHuangbin** · 2016-05-26 14:48:24

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Whitelist not working?

Please turn on debug mode in Amavisd, then show us full log related to this testing email. We need to check the SQL queries performed by Amavisd to figure out why it doesn't use the whitelists.

FYI: http://www.iredmail.org/docs/debug.amavisd.html

**SViRU** · 2016-05-27 21:07:53

SViRU
Member
Offline

Registered: 2016-01-06
Posts: 8

Re: Whitelist not working?

Full log with debug mode 5

/var/log/maillog:

May 27 14:48:10 mx postfix/qmgr[4999]: 335EF3E5B3B: from=<xyz@senderdomain.com>, size=6797, nrcpt=1 (queue active)
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP [127.0.0.1]:10024 /var/amavis/tmp/amavis-20160527T143817-23507-BOC07nfe: <xyz@senderdomain.com> -> <user@mydomain.com> SIZE=6797 BODY=7BIT RET=FULL ENVID=<842919547-1@senderdomain.com> Received: from mx2.mydomain.com ([127.0.0.1]) by mx.mydomain.com(mx2.mydomain.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <user@mydomain.com>; Fri, 27 May 2016 14:48:10 +0200 (CEST)
May 27 14:48:10 mx amavis[23507]: (23507-14) Checking: AH9Soo8IZvIR [XX.XX.XX.XX] <xyz@senderdomain.com> -> <user@mydomain.com>
May 27 14:48:10 mx amavis[23507]: (23507-14) p001 1 Content-Type: text/plain, size: 5486 B, name:
May 27 14:48:10 mx amavis[23507]: (23507-14) _WARN: bayes: bayes db version 0 is not able to be used, aborting! at /usr/local/lib/perl5/site_perl/Mail/SpamAssassin/BayesStore/DBM.pm line 208.
May 27 14:48:22 mx amavis[23507]: (23507-14) header_edits_for_quar: <xyz@senderdomain.com> -> <user@mydomain.com>, Yes, score=8.276 tag=2 tag2=6.2 kill=6.9 tests=[FROM_MISSPACED=1.999, FROM_MISSP_XPRIO=2.499, RCVD_IN_DNSWL_LOW=-0.7, RCVD_IN_MSPIKE_H3=-0.01, RCVD_IN_MSPIKE_WL=-0.01, TO_NO_BRKTS_FROM_MSSP=2.499, XPRIO=1.999] autolearn=no autolearn_force=no
May 27 14:48:22 mx amavis[23507]: (23507-14) delivering to sql:, SEND via SQL (DBI:mysql:database=amavisd;host=127.0.0.1;port=3306): <xyz@senderdomain.com> -> <user@mydomain.com>, mail_id AH9Soo8IZvIR
May 27 14:48:22 mx amavis[23507]: (23507-14) Blocked SPAM {DiscardedInbound,Quarantined}, [XX.XX.XX.XX]:39894 [XX.XX.XX.XX] <xyz@senderdomain.com> -> <user@mydomain.com>, quarantine: AH9Soo8IZvIR, Queue-ID: 335EF3E5B3B, Message-ID: <842919547@senderdomain.com>, mail_id: AH9Soo8IZvIR, Hits: 8.276, size: 6796, 11884 ms
May 27 14:48:22 mx amavis[23507]: (23507-14) TIMING-SA total 11691 ms - parse: 1.83 (0.0%), extract_message_metadata: 26 (0.2%), get_uri_detail_list: 8 (0.1%), tests_pri_-1000: 19 (0.2%), tests_pri_-950: 1.30 (0.0%), tests_pri_-900: 1.35 (0.0%), tests_pri_-400: 1.28 (0.0%), tests_pri_0: 309 (2.6%), tests_pri_500: 11318 (96.8%), poll_dns_idle: 11253 (96.2%), get_report: 0.47 (0.0%)
May 27 14:48:22 mx postfix/smtp[23644]: 335EF3E5B3B: to=<user@mydomain.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=16, delays=4.5/0/0/12, dsn=2.7.0, status=sent (250 2.7.0 Ok, discarded, id=23507-14 - spam)
May 27 14:48:22 mx postfix/qmgr[4999]: 335EF3E5B3B: removed
May 27 14:48:22 mx amavis[23507]: (23507-14) size: 6796, TIMING [total 11891 ms] - SMTP greeting: 2.3 (0%)0, SMTP EHLO: 1.7 (0%)0, SMTP pre-MAIL: 2.3 (0%)0, SMTP pre-DATA-flush: 4.7 (0%)0, SMTP DATA: 100 (1%)1, check_init: 0.5 (0%)1, digest_hdr: 1.0 (0%)1, digest_body_dkim: 0.6 (0%)1, collect_info: 2.2 (0%)1, gen_mail_id: 3.5 (0%)1, mime_decode: 7 (0%)1, get-file-type1: 21 (0%)1, parts_decode: 0.2 (0%)1, check_header: 0.7 (0%)1, AV-scan-1: 12 (0%)1, spam-wb-list: 1.9 (0%)1, SA msg read: 0.6 (0%)1, SA parse: 2.4 (0%)1, SA check: 11687 (98%)100, decide_mail_destiny:
6 (0%)100, notif-quar: 0.8 (0%)100, quar-hdrs: 2.5 (0%)100, write-header: 2.9 (0%)100, fwd-sql: 12 (0%)100, prepare-dsn: 1.8 (0%)100, report: 1.5 (0%)100, main_log_entry: 4.1 (0%)100, sql-update: 2.6 (0%)100, update_snmp: 1.9 (0%)100, SMTP pre-response: 0.4 (0%)100, SMTP response: 1.1 (0%)100, unlink-2-files: 0.3 (0%)100, rundown: 0.5 (0%)100

**ZhangHuangbin** · 2016-05-28 08:47:22

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Whitelist not working?

This is not FULL log. I expect more with log_level=5 in Amavisd, especially sql queries and returned results.

**SViRU** · 2016-05-31 21:22:48

SViRU
Member
Offline

Registered: 2016-01-06
Posts: 8

Re: Whitelist not working?

ZhangHuangbin wrote:

This is not FULL log. I expect more with log_level=5 in Amavisd, especially sql queries and returned results.

ok i found more details logs in /var/log/debug

May 27 14:48:10 mx amavis[23507]: (23507-14) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
May 27 14:48:10 mx amavis[23507]: (23507-14) switch_to_client_time 480 s, smtp response sent
May 27 14:48:10 mx amavis[23507]: (23507-14) idle_proc, 4: was busy, 2.4 ms, total idle 487.444 s, busy 105.421 s
May 27 14:48:10 mx amavis[23507]: (23507-14) smtp readline: read 17 bytes, new size: 17
May 27 14:48:10 mx amavis[23507]: (23507-14) idle_proc, 5: was idle, 0.3 ms, total idle 487.444 s, busy 105.421 s
May 27 14:48:10 mx amavis[23507]: (23507-14) SMTP< EHLO mx2.mydomain.com\r\n
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 288, was 480, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 250-[127.0.0.1]
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 250-VRFY
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 250-PIPELINING
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 250-SIZE
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 250-ENHANCEDSTATUSCODES
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 250-8BITMIME
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 250-SMTPUTF8
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 250-DSN
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
May 27 14:48:10 mx amavis[23507]: (23507-14) switch_to_client_time 480 s, smtp response sent
May 27 14:48:10 mx amavis[23507]: (23507-14) idle_proc, 6: was busy, 1.4 ms, total idle 487.444 s, busy 105.422 s
May 27 14:48:10 mx amavis[23507]: (23507-14) smtp readline: read 349 bytes, new size: 349
May 27 14:48:10 mx amavis[23507]: (23507-14) idle_proc, 5: was idle, 0.3 ms, total idle 487.445 s, busy 105.422 s
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP< XFORWARD NAME=senderserver.com ADDR=X.X.X.X PORT=39894\r\n
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 250 2.5.0 Ok XFORWARD
May 27 14:48:10 mx amavis[23507]: (23507-14) switch_to_client_time 480 s, smtp response sent
May 27 14:48:10 mx amavis[23507]: (23507-14) idle_proc, 6: was busy, 0.7 ms, total idle 487.445 s, busy 105.423 s
May 27 14:48:10 mx amavis[23507]: (23507-14) idle_proc, 5: was idle, 0.1 ms, total idle 487.445 s, busy 105.423 s
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP< XFORWARD PROTO=ESMTP HELO=senderserver.com IDENT=335EF3E5B3B SOURCE=REMOTE\r\n
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was 480, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 250 2.5.0 Ok XFORWARD
May 27 14:48:10 mx amavis[23507]: (23507-14) switch_to_client_time 480 s, smtp response sent
May 27 14:48:10 mx amavis[23507]: (23507-14) idle_proc, 6: was busy, 0.7 ms, total idle 487.445 s, busy 105.424 s
May 27 14:48:10 mx amavis[23507]: (23507-14) idle_proc, 5: was idle, 0.1 ms, total idle 487.445 s, busy 105.424 s
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP< MAIL FROM:<xyz@senderdomain.com> SIZE=6797 BODY=7BIT ENVID=<842919547-1@senderdomain.com> RET=FULL\r\n
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 288, was 480, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) check_mail_begin_task: task_count=14
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="X.X.X.X", no match
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [debug_sender] => undef, "xyz@senderdomain.com" does not match
May 27 14:48:10 mx amavis[23507]: (23507-14) mesage size set to a declared size 6797
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 250 2.1.0 Sender <xyz@senderdomain.com> OK
May 27 14:48:10 mx amavis[23507]: (23507-14) switch_to_client_time 480 s, smtp response sent
May 27 14:48:10 mx amavis[23507]: (23507-14) idle_proc, 6: was busy, 2.1 ms, total idle 487.445 s, busy 105.426 s
May 27 14:48:10 mx amavis[23507]: (23507-14) idle_proc, 5: was idle, 0.1 ms, total idle 487.445 s, busy 105.426 s
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP< RCPT TO:<user@mydomain.com> ORCPT=rfc822;user@mydomain.com NOTIFY=FAILURE\r\n
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 288, was 480, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup => undef, "user@mydomain.com", no lookup tables
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 250 2.1.5 Recipient <user@mydomain.com> OK
May 27 14:48:10 mx amavis[23507]: (23507-14) switch_to_client_time 480 s, smtp response sent
May 27 14:48:10 mx amavis[23507]: (23507-14) idle_proc, 6: was busy, 0.9 ms, total idle 487.445 s, busy 105.427 s
May 27 14:48:10 mx amavis[23507]: (23507-14) idle_proc, 5: was idle, 0.1 ms, total idle 487.445 s, busy 105.427 s
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP< DATA\r\n
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer switch_to_my_time(rx SMTP DATA): timer 288, was 480, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP> 354 End data with <CR><LF>.<CR><LF>
May 27 14:48:10 mx amavis[23507]: (23507-14) switch_to_client_time 480 s, smtp response sent
May 27 14:48:10 mx amavis[23507]: (23507-14) switch_to_client_time 480 s, receiving data
May 27 14:48:10 mx amavis[23507]: (23507-14) smtp copy: read 6805 bytes into buffer, new size: 6805
May 27 14:48:10 mx amavis[23507]: (23507-14) smtp copy: 6 bytes still buffered at end
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer switch_to_my_time(rx data-end): timer 288, was 480, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) ESMTP< .<CR><LF>
May 27 14:48:10 mx amavis[23507]: (23507-14) Actual message size 6796 B less than the declared 6797 B
May 27 14:48:10 mx amavis[23507]: (23507-14) smtp connection cache, dt: 29.9, state: 1
May 27 14:48:10 mx amavis[23507]: (23507-14) smtp connection cache, dt: 29.9 -> disabling
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline digest_pre - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer digest_pre: timer 288, was 288, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) get_body_digest: reading header section from memory
May 27 14:48:10 mx amavis[23507]: (23507-14) get_body_digest: feeding header section to DKIM verifier
May 27 14:48:10 mx amavis[23507]: (23507-14) get_body_digest: sending h/b separator to DKIM
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline digest_hdr - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer digest_hdr: timer 288, was 288, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) get_body_digest: reading mail body from memory, 0 DKIM signatures
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline digest_body - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer digest_body: timer 288, was 288, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) get_body_digest: message size 6796, header+sep 822, body 5974
May 27 14:48:10 mx amavis[23507]: (23507-14) body type (8bit-MIMEtransport): labeled 7BIT, good (h=0, b=0)
May 27 14:48:10 mx amavis[23507]: (23507-14) body hash: 844c5571a2d4f7b422d0dde472dce630
May 27 14:48:10 mx amavis[23507]: (23507-14) ip_from_received: X.X.X.X
May 27 14:48:10 mx amavis[23507]: (23507-14) ip_from_received: 127.0.0.1
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup_ip_acl (public_nets) arr.obj: key="X.X.X.X" matches "::ffff:0:0/96", result=1
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
May 27 14:48:10 mx amavis[23507]: (23507-14) trace: ESMTP://[127.0.0.1]:32071 < ESMTPS://[X.X.X.X]:39894 < 127.0.0.1
May 27 14:48:10 mx amavis[23507]: (23507-14) Original mail size: 6796; quota set to: 3398000 bytes (fmin=5, fmax=500, qmin=102400, qmax=314572800)
May 27 14:48:10 mx amavis[23507]: (23507-14) sql begin, nontransaction
May 27 14:48:10 mx amavis[23507]: (23507-14) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
May 27 14:48:10 mx amavis[23507]: (23507-14) save_info_preliminary AH9Soo8IZvIR, sender id: 500328, xyz@senderdomain.com, exists
May 27 14:48:10 mx amavis[23507]: (23507-14) sql begin, nontransaction
May 27 14:48:10 mx amavis[23507]: (23507-14) sql: executing clause (2 args): SELECT id FROM maddr WHERE partition_tag=? AND email=?
May 27 14:48:10 mx amavis[23507]: (23507-14) orcpt_encode rfc822, user@mydomain.com, smtputf8
May 27 14:48:10 mx amavis[23507]: (23507-14) save_info_preliminary AH9Soo8IZvIR, recip id: 334, user@mydomain.com (ORCPT rfc822;user@mydomain.com), exists
May 27 14:48:10 mx amavis[23507]: (23507-14) sql begin transaction
May 27 14:48:10 mx amavis[23507]: (23507-14) 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 (?,?,?,?,?,?,?,?,?,?,?)
May 27 14:48:10 mx amavis[23507]: (23507-14) sql commit
May 27 14:48:10 mx amavis[23507]: (23507-14) 2822.From: <xyz@senderdomain.com>
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup: (scalar) matches, result="1"
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [local_domains] => true, "user@mydomain.com" matches, result="1", matching_key="(constant:1)"
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [bypass_virus_checks] => undef, "user@mydomain.com" does not match
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [bypass_banned_checks] => undef, "user@mydomain.com" does not match
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [bypass_spam_checks] => undef, "user@mydomain.com" does not match
May 27 14:48:10 mx amavis[23507]: (23507-14) Extracting mime components from a string
May 27 14:48:10 mx amavis[23507]: (23507-14) Issued a new file name: p001
May 27 14:48:10 mx amavis[23507]: (23507-14) Charging 5486 bytes to remaining quota 3398000 (out of 3398000, (0%)) - by mime_decode
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline mime_decode - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer mime_decode: timer 288, was 288, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline mime_decode-1 - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer mime_decode-1: timer 288, was 288, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) inspect_dsn: parts: text/plain
May 27 14:48:10 mx amavis[23507]: (23507-14) inspect_dsn: not a bounce
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline dsn_parse - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer dsn_parse: timer 288, was 288, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) decode_parts: level=1, #parts=1 : p001
May 27 14:48:10 mx amavis[23507]: (23507-14) running file(1) on 1 files, arglist size 24
May 27 14:48:10 mx amavis[23507]: (23507-14) run_command: [25648] /usr/local/bin/file p001 </dev/null 2>&1
May 27 14:48:10 mx amavis[25648]: (23507-14) open_on_specific_fd: target fd0 closing, to become < /dev/null
May 27 14:48:10 mx amavis[25648]: (23507-14) open_on_specific_fd: target fd1 closing, to become (513) &=22
May 27 14:48:10 mx amavis[25648]: (23507-14) open_on_specific_fd: target fd1 dup2 from fd22 (513) &=22
May 27 14:48:10 mx amavis[25648]: (23507-14) open_on_specific_fd: source fd22 closed
May 27 14:48:10 mx amavis[25648]: (23507-14) open_on_specific_fd: target fd2 closing, to become (513) &1
May 27 14:48:10 mx amavis[25648]: (23507-14) open_on_specific_fd: target fd2 dup2 from fd1 (513) &1
May 27 14:48:10 mx amavis[23507]: (23507-14) result line from file(1): p001: UTF-8 Unicode text\n
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup_re("UTF-8 Unicode text") matches key "(?^i:^UTF.* Unicode text\\b)", result="txt"
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [map_full_type_to_short_type] => true, "UTF-8 Unicode text" matches, result="txt", matching_key="(?^i:^UTF.* Unicode text\\b)"
May 27 14:48:10 mx amavis[23507]: (23507-14) File-type of p001: UTF-8 Unicode text; (txt)
May 27 14:48:10 mx amavis[23507]: (23507-14) decompose_part: p001 - atomic
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline parts_decode - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer parts_decode: timer 288, was 288, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [bypass_header_checks] => undef, "user@mydomain.com" does not match
May 27 14:48:10 mx amavis[23507]: (23507-14) check_header: 0, OK
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [bypass_header_checks] => undef, "user@mydomain.com" does not match
May 27 14:48:10 mx amavis[23507]: (23507-14) Checking for banned types and filenames
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup: (scalar) matches, result="DEFAULT"
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [banned_filename], 1 matches for "user@mydomain.com", results: "(constant:DEFAULT)"=>"DEFAULT"
May 27 14:48:10 mx amavis[23507]: (23507-14) collect banned table[0]: user@mydomain.com, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x8067bff90)
May 27 14:48:10 mx amavis[23507]: (23507-14) starting banned checks - traversing message structure tree
May 27 14:48:10 mx amavis[23507]: (23507-14) check_for_banned (p001) text/plain,.txt
May 27 14:48:10 mx amavis[23507]: (23507-14) doing banned check for user@mydomain.com on text/plain,.txt
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup_re(["text/plain",".txt"]), no matches
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [check_bann:user@mydomain.com] => undef, ["text/plain",".txt"] does not match
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [banned_namepath_re] => undef, "P=p001\tL=1\tM=text/plain\tT=txt" does not match
May 27 14:48:10 mx amavis[23507]: (23507-14) p.path user@mydomain.com: "P=p001,L=1,M=text/plain,T=txt"
May 27 14:48:10 mx amavis[23507]: (23507-14) banned check: any=0, all=N (1)
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup_re("MAIL") matches key "(?^:^MAIL$)", result="1"
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [keep_decoded_original] => true, "MAIL" matches, result="1", matching_key="(?^:^MAIL$)"
May 27 14:48:10 mx amavis[23507]: (23507-14) Issued a new file name: p002
May 27 14:48:10 mx amavis[23507]: (23507-14) presenting full original message to scanners as /var/amavis/tmp/amavis-20160527T143817-23507-BOC07nfe/parts/p002
May 27 14:48:10 mx amavis[23507]: (23507-14) Calling virus scanners, 2 files to scan in /var/amavis/tmp/amavis-20160527T143817-23507-BOC07nfe/parts
May 27 14:48:10 mx amavis[23507]: (23507-14) invoking av-scanner ClamAV-clamd
May 27 14:48:10 mx amavis[23507]: (23507-14) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd) /var/run/clamav/clamd.sock
May 27 14:48:10 mx amavis[23507]: (23507-14) run_av (ClamAV-clamd): query template(1,1): CONTSCAN {}\n
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline run_av_pre - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer run_av_pre: timer 288, was 288, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline run_av_scan - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer run_av_scan: timer 288, was 288, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) run_av Using (ClamAV-clamd): (code) CONTSCAN /var/amavis/tmp/amavis-20160527T143817-23507-BOC07nfe/parts\n
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline ask_daemon_internal_connect_pre - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline ask_daemon_internal_connect - deadline in 480.0 s, set to 10.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer ask_daemon_internal_connect: timer 10, was 288, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) ClamAV-clamd: Connecting to socket /var/run/clamav/clamd.sock
May 27 14:48:10 mx amavis[23507]: (23507-14) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.sock, timeout set to 10
May 27 14:48:10 mx amavis[23507]: (23507-14) connected to /var/run/clamav/clamd.sock successfully
May 27 14:48:10 mx amavis[23507]: (23507-14) ClamAV-clamd: Sending CONTSCAN /var/amavis/tmp/amavis-20160527T143817-23507-BOC07nfe/parts\n to socket /var/run/clamav/clamd.sock
May 27 14:48:10 mx amavis[23507]: (23507-14) rw_loop: needline=0, flush=1, wr=1, timeout=10
May 27 14:48:10 mx amavis[23507]: (23507-14) rw_loop: sending 69 chars
May 27 14:48:10 mx amavis[23507]: (23507-14) rw_loop sent 69> CONTSCAN /var/amavis/tmp/amavis-20160527T143817-23507-BOC07nfe/parts\n
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline ask_daemon_internal_scan - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer ask_daemon_internal_scan: timer 288, was 10, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) rw_loop: needline=0, flush=0, wr=0, timeout=287.999
May 27 14:48:10 mx amavis[23507]: (23507-14) rw_loop: receiving
May 27 14:48:10 mx amavis[23507]: (23507-14) rw_loop read 64 chars< /var/amavis/tmp/amavis-20160527T143817-23507-BOC07nfe/parts: OK\n
May 27 14:48:10 mx amavis[23507]: (23507-14) rw_loop: needline=0, flush=0, wr=0, timeout=287.999
May 27 14:48:10 mx amavis[23507]: (23507-14) rw_loop: receiving
May 27 14:48:10 mx amavis[23507]: (23507-14) rw_loop read: got eof
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline ask_daemon_internal - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer ask_daemon_internal: timer 288, was 288, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline run_av_3 - deadline in 480.0 s, set to 288.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer run_av_3: timer 288, was 288, deadline in 480.0 s
May 27 14:48:10 mx amavis[23507]: (23507-14) run_av (ClamAV-clamd) result: /var/amavis/tmp/amavis-20160527T143817-23507-BOC07nfe/parts: OK\n
May 27 14:48:10 mx amavis[23507]: (23507-14) run_av (ClamAV-clamd): CLEAN
May 27 14:48:10 mx amavis[23507]: (23507-14) run_av (ClamAV-clamd) result: clean
May 27 14:48:10 mx amavis[23507]: (23507-14) wbl: checking sender <xyz@senderdomain.com>
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [blacklist_recip<user@mydomain.com>] => undef, "user@mydomain.com" does not match
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [blacklist_sender<xyz@senderdomain.com>,blacklist_sender] => undef, "xyz@senderdomain.com" does not match
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [whitelist_recip<user@mydomain.com>] => undef, "user@mydomain.com" does not match
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [whitelist_sender<xyz@senderdomain.com>,whitelist_sender] => undef, "xyz@senderdomain.com" does not match
May 27 14:48:10 mx amavis[23507]: (23507-14) query_keys: user@mydomain.com, user@, mydomain.com, .mydomain.com, .pl, .
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup_hash(user@mydomain.com) matches keys: "."=>ARRAY(0x8067cb8e8)
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [score_recip<user@mydomain.com>,score_sender], 1 matches for "user@mydomain.com", results: "."=>[Amavis::Lookup::RE=ARRAY(0x8067cb4c8),{rt-users-a
dmin@lists.fsck.com=>"-3",ca+envelope@sendmail.org=>"-3",amavis-user-bounces@lists.sourceforge.net=>"-3",security-alerts@linuxsecurity.com=>"-3",clusternews@linuxnetworx.com=>"-3",slashdot@s
lashdot.org=>"-3",owner-textbreakingnews@cnnimail12.cnn.com=>"-5",sender@example.net=>"3",returns.groups.yahoo.com=>"-3",spamassassin.apache.org=>"-3",owner-alert@iss.net=>"-3",donotreply@sendmail.org=>"-3",ietf-123-owner@loki.ietf.org=>"-3",mailman-announce-admin@python.org=>"-3",owner-postfix-announce@postfix.org=>"-3",sendmail-announce-request@lists.sendmail.org=>"-3",securi
tyfocus.com=>"-3",.example.net=>"1",cert-advisory@us-cert.gov=>"-3",owner-technews@postel.acm.org=>"-3",lvs-users-admin@linuxvirtualserver.org=>"-3",cvs-commits-list-admin@gnome.org=>"-3",em
ailnews@genomeweb.com=>"-5",amavis-user-admin@lists.sourcefor...
May 27 14:48:10 mx amavis[23507]: (23507-14) ...ge.net=>"-3",ntbugtraq@listserv.ntbugtraq.com=>"-3",noreply@freshmeat.net=>"-3",notification-return@lists.sophos.com=>"-3",surveys-errors@list
s.nua.ie=>"-3",yahoo-dev-null@yahoo-inc.com=>"-3",owner-sendmail-announce@lists.sendmail.org=>"-3",owner-postfix-users@postfix.org=>"-3",clp-request@comp.nus.edu.sg=>"-3",nobody@cert.org=>"-
3"}]
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup_re("xyz@senderdomain.com"), no matches
May 27 14:48:10 mx amavis[23507]: (23507-14) query_keys: xyz@senderdomain.com, xyz@senderdomain.com, xyz@, senderdomain.com, .senderdomain.com, .com, .
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup_hash(xyz@senderdomain.com), no matches
May 27 14:48:10 mx amavis[23507]: (23507-14) lookup [score_sender<xyz@senderdomain.com>] => undef, "xyz@senderdomain.com" does not match
May 27 14:48:10 mx amavis[23507]: (23507-14) SpamControl: calling spam scanner SpamAssassin
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline spam_scan_sa_pre - deadline in 479.9 s, set to 476.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) prolong_timer spam_scan_sa_pre: timer 476, was 288, deadline in 479.9 s
May 27 14:48:10 mx amavis[23507]: (23507-14) SA user config: "", username: "vscan", 0, (0)user@mydomain.com
May 27 14:48:10 mx amavis[23507]: (23507-14) calling SA parse (0), SA vers 3.4.1, 3.004001, data as STRING_REF, recips_ind [0], user: "vscan"
May 27 14:48:10 mx amavis[23507]: (23507-14) get_deadline SA check - deadline in 479.9 s, set to 475.000 s
May 27 14:48:10 mx amavis[23507]: (23507-14) CALLING SA check (0)

**ZhangHuangbin** · 2016-06-01 15:57:46

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Whitelist not working?

Seems Amavisd didn't lookup white/blacklist stored in SQL database. Please show us output of command below:

grep '@lookup_sql_dsn' /usr/local/etc/amavisd.conf

**SViRU** · 2016-06-01 16:17:21

SViRU
Member
Offline

Registered: 2016-01-06
Posts: 8

Re: Whitelist not working?

eh, probably just uncommented?

# @lookup_sql_dsn =
# @storage_sql_dsn = @lookup_sql_dsn; # none, same, or separate database
#@lookup_sql_dsn = (

**ZhangHuangbin** · 2016-06-01 16:19:48

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,088

Re: Whitelist not working?

With default iRedMail setting, Amavisd should have both @storage_sql_dsn and @lookup_sql_dsn enabled, like this:

# Reporting and quarantining.
@storage_sql_dsn = (
    ['DBI:.....'],
);

# Lookup for per-recipient, per-domain and global policy.
@lookup_sql_dsn = @storage_sql_dsn;

**SViRU** · 2016-06-01 16:30:25

SViRU
Member
Offline

Registered: 2016-01-06
Posts: 8

Re: Whitelist not working?

ok, so my fault, I'm sorry, and thank you very much for your help

Aug 5, 2024: iRedMail-1.7.1 has been released.

[ Closed ] Whitelist not working?

Posts: 9

1 Topic by SViRU 2016-05-25 23:49:41

Topic: Whitelist not working?

2 Reply by ZhangHuangbin 2016-05-26 14:48:24

Re: Whitelist not working?

3 Reply by SViRU 2016-05-27 21:07:53 (edited by SViRU 2016-05-31 21:03:49)

Re: Whitelist not working?

4 Reply by ZhangHuangbin 2016-05-28 08:47:22

Re: Whitelist not working?

5 Reply by SViRU 2016-05-31 21:22:48 (edited by SViRU 2016-05-31 21:33:48)

Re: Whitelist not working?

6 Reply by ZhangHuangbin 2016-06-01 15:57:46

Re: Whitelist not working?

7 Reply by SViRU 2016-06-01 16:17:21

Re: Whitelist not working?

8 Reply by ZhangHuangbin 2016-06-01 16:19:48

Re: Whitelist not working?

9 Reply by SViRU 2016-06-01 16:30:25

Re: Whitelist not working?

Posts: 9