1 Topic by trefnis

  • trefnis
  • Member
  • Offline
  • Registered: 2014-04-30
  • Posts: 2

Topic: slow poll_dns_idle and tests_pri_500

==== Required information ====
- iRedMail version: 1.7.0
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQL
- Linux/BSD distribution name and version: Debian 7.4 (3.2.54-2 x86_64 GNU/Linux)
- Related log if you're reporting an issue:

Apr 30 17:29:22 bpns2 amavis[7860]: (07860-15-3) TIMING-SA total 3927 ms - parse: 5 (0.1%), extract_message_metadata: 56 (1.4%), get_uri_detail_list: 15 (0.4%), tests_pri_-1000: 17 (0.4%), tests_pri_-950: 1.04 (0.0%), tests_pri_-900: 1.12 (0.0%), tests_pri_-400: 106 (2.7%), check_bayes: 83 (2.1%), tests_pri_0: 248 (6.3%), check_dkim_adsp: 3 (0.1%), check_spf: 116 (3.0%), poll_dns_idle: 3548 (90.3%), check_pyzor: 0.20 (0.0%), tests_pri_500: 3467 (88.3%), get_report: 1.84 (0.0%)
====


problem is with slow poll_dns_idle and tests_pri_500
i looked up that it means that the dns response is slow, i use local bind9 and the quary time when i look for sites is ~30-40ms
and most of my mails take 4-8 seconds to deliver, that is to much, some are delivered in 200-300ms and this is how it is supposed to be,

can you help me with this issu ?

----

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,094

Re: slow poll_dns_idle and tests_pri_500

Reference: http://www.gossamer-threads.com/lists/s … ded#157301
Quote:

Mark Martinec (Author of Amavisd) wrote:

The poll_dns_idle is just a state where SpamAssassin is waiting for
DNS replies to come in or a timeout to expire. Apparently at least
some (if not all) of your DNS queries are not being answered.
Typically these are RBS or URIDNSBL tests, so perhaps one of the
queried black/white-lists is down, or some perhaps there is a
DNS resolver problem at your site.

The 14+ (15) seconds timeout comes from your 'rbl_timeout' setting.
You may decrease this value, perhaps down to 6 seconds, if your
DNS resolving is otherwise reasonably fast.

Nevertheless, you should investigate which DNS query is stalled
by adding a '--debug=async' debug area to you spamd or spamassassin,
e.g.:

$ spamassassin -D timing,async -t <test.msg

3 Reply by trefnis (edited by trefnis 2014-05-03 06:42:57)

  • trefnis
  • Member
  • Offline
  • Registered: 2014-04-30
  • Posts: 2

Re: slow poll_dns_idle and tests_pri_500

spamassassin -D timing,async -t < 1399017681.M818508P16365.bpns2\,S\=1201\,W\=1232\:2\,S
maj  2 10:03:25.353 [16555] warn: config: created user preferences file: /root/.spamassassin/user_prefs
maj  2 10:03:25.816 [16555] info: config: failed to parse line, skipping, in "/etc/spamassassin/local.cf": desribe JOBBANK jobbankpoland
maj  2 10:03:25.816 [16555] info: config: failed to parse line, skipping, in "/etc/spamassassin/local.cf": desribe JOBPOLSKA poszukujemy
maj  2 10:03:25.818 [16555] info: config: SpamAssassin failed to parse line, no value provided for "describe", skipping: describe tag11
maj  2 10:03:26.209 [16555] dbg: async: starting: DNSBL-A, dns:A:bel-pol.com.pl.rhsbl.ahbl.org. (timeout 15.0s, min 3.0s)
maj  2 10:03:26.210 [16555] dbg: async: starting: NO_DNS_FOR_FROM, DNSBL-A, dns:A:bel-pol.com.pl (timeout 15.0s, min 3.0s)
maj  2 10:03:26.210 [16555] dbg: async: starting: NO_DNS_FOR_FROM, DNSBL-MX, dns:MX:bel-pol.com.pl (timeout 15.0s, min 3.0s)
maj  2 10:03:26.212 [16555] dbg: async: starting: DNSBL-A, dns:A:bel-pol.com.pl.fulldom.rfc-ignorant.org. (timeout 15.0s, min 3.0s)
maj  2 10:03:26.216 [16555] dbg: async: select found 3 responses ready (t.o.=0.0)
maj  2 10:03:26.216 [16555] dbg: async: completed in 0.004 s: DNSBL-A, dns:A:bel-pol.com.pl.fulldom.rfc-ignorant.org.
maj  2 10:03:26.216 [16555] dbg: async: completed in 0.003 s: NO_DNS_FOR_FROM, DNSBL-A, dns:A:bel-pol.com.pl
maj  2 10:03:26.216 [16555] dbg: async: completed in 0.004 s: NO_DNS_FOR_FROM, DNSBL-MX, dns:MX:bel-pol.com.pl
maj  2 10:03:26.216 [16555] dbg: async: queries completed: 3, started: 0
maj  2 10:03:26.216 [16555] dbg: async: queries active: DNSBL-A=1 at Fri May 2 10:03:26 2014
maj  2 10:03:26.369 [16555] dbg: async: select found no responses ready (t.o.=0.0)
maj  2 10:03:26.369 [16555] dbg: async: queries completed: 0, started: 0
maj  2 10:03:26.369 [16555] dbg: async: queries active: DNSBL-A=1 at Fri May 2 10:03:26 2014
maj  2 10:03:26.488 [16555] dbg: async: select found no responses ready (t.o.=0.0)
maj  2 10:03:26.488 [16555] dbg: async: queries completed: 0, started: 0
maj  2 10:03:26.489 [16555] dbg: async: queries active: DNSBL-A=1 at Fri May 2 10:03:26 2014
maj  2 10:03:26.496 [16555] dbg: async: select found no responses ready (t.o.=0.0)
maj  2 10:03:26.496 [16555] dbg: async: queries completed: 0, started: 0
maj  2 10:03:26.496 [16555] dbg: async: queries active: DNSBL-A=1 at Fri May 2 10:03:26 2014
maj  2 10:03:27.497 [16555] dbg: async: select found no responses ready (t.o.=1.0)
maj  2 10:03:27.497 [16555] dbg: async: queries completed: 0, started: 0
maj  2 10:03:27.497 [16555] dbg: async: queries active: DNSBL-A=1 at Fri May 2 10:03:27 2014
maj  2 10:03:28.499 [16555] dbg: async: select found no responses ready (t.o.=1.0)
maj  2 10:03:28.499 [16555] dbg: async: queries completed: 0, started: 0
maj  2 10:03:28.499 [16555] dbg: async: queries active: DNSBL-A=1 at Fri May 2 10:03:28 2014
maj  2 10:03:29.500 [16555] dbg: async: select found no responses ready (t.o.=1.0)
maj  2 10:03:29.501 [16555] dbg: async: queries completed: 0, started: 0
maj  2 10:03:29.501 [16555] dbg: async: queries active: DNSBL-A=1 at Fri May 2 10:03:29 2014
maj  2 10:03:30.502 [16555] dbg: async: select found no responses ready (t.o.=1.0)
maj  2 10:03:30.502 [16555] dbg: async: queries completed: 0, started: 0
maj  2 10:03:30.502 [16555] dbg: async: queries active: DNSBL-A=1 at Fri May 2 10:03:30 2014
maj  2 10:03:31.504 [16555] dbg: async: select found no responses ready (t.o.=1.0)
maj  2 10:03:31.504 [16555] dbg: async: queries completed: 0, started: 0
maj  2 10:03:31.504 [16555] dbg: async: queries active: DNSBL-A=1 at Fri May 2 10:03:31 2014
maj  2 10:03:32.506 [16555] dbg: async: select found no responses ready (t.o.=1.0)
maj  2 10:03:32.506 [16555] dbg: async: queries completed: 0, started: 0
maj  2 10:03:32.506 [16555] dbg: async: queries active: DNSBL-A=1 at Fri May 2 10:03:32 2014
maj  2 10:03:33.507 [16555] dbg: async: select found no responses ready (t.o.=1.0)
maj  2 10:03:33.508 [16555] dbg: async: queries completed: 0, started: 0
maj  2 10:03:33.508 [16555] dbg: async: queries active: DNSBL-A=1 at Fri May 2 10:03:33 2014
maj  2 10:03:33.508 [16555] dbg: async: reducing select timeout from 1.0 to 1.0 s
maj  2 10:03:34.460 [16555] dbg: async: select found no responses ready (t.o.=1.0)
maj  2 10:03:34.460 [16555] dbg: async: queries completed: 0, started: 0
maj  2 10:03:34.461 [16555] dbg: async: escaping: lost or timed out requests or responses
maj  2 10:03:34.461 [16555] dbg: async: aborting after 8.252 s, deadline shrunk: DNSBL-A, dns:A:bel-pol.com.pl.rhsbl.ahbl.org.
maj  2 10:03:34.461 [16555] dbg: async: aborted 1 remaining lookups
maj  2 10:03:34.461 [16555] dbg: async: timing: 0.003 . dns:A:bel-pol.com.pl
maj  2 10:03:34.461 [16555] dbg: async: timing: 0.004 . dns:A:bel-pol.com.pl.fulldom.rfc-ignorant.org.
maj  2 10:03:34.461 [16555] dbg: async: timing: 0.004 . dns:MX:bel-pol.com.pl
maj  2 10:03:34.461 [16555] dbg: async: timing: 8.252 X dns:A:bel-pol.com.pl.rhsbl.ahbl.org.
maj  2 10:03:34.552 [16555] dbg: timing: total 9212 ms - init: 856 (9.3%), parse: 0.73 (0.0%), extract_message_metadata: 10 (0.1%), poll_dns_idle: 7960 (86.4%), get_uri_detail_list: 0.46 (0.0%), tests_pri_-1000: 10 (0.1%), compile_gen: 114 (1.2%), compile_eval: 20 (0.2%), tests_pri_-950: 4 (0.0%), tests_pri_-900: 4 (0.0%), tests_pri_-400: 3 (0.0%), tests_pri_0: 263 (2.9%), dkim_load_modules: 27 (0.3%), check_dkim_signature: 0.58 (0.0%), check_dkim_adsp: 5 (0.0%), check_spf: 23 (0.3%), check_pyzor: 0.16 (0.0%), tests_pri_500: 8037 (87.2%), learn: 19 (0.2%)


i found that lines disturbing:
maj  2 10:03:26.209 [16555] dbg: async: starting: DNSBL-A, dns:A:bel-pol.com.pl.rhsbl.ahbl.org. (timeout 15.0s, min 3.0s)
maj  2 10:03:26.212 [16555] dbg: async: starting: DNSBL-A, dns:A:bel-pol.com.pl.fulldom.rfc-ignorant.org. (timeout 15.0s, min 3.0s)
maj  2 10:03:26.216 [16555] dbg: async: completed in 0.004 s: DNSBL-A, dns:A:bel-pol.com.pl.fulldom.rfc-ignorant.org.
maj  2 10:03:34.461 [16555] dbg: async: aborting after 8.252 s, deadline shrunk: DNSBL-A, dns:A:bel-pol.com.pl.rhsbl.ahbl.org.

bel-pol.com.pl is my domain, i wonder why is it as a link with the rhsbl.ahbl.org

this line is the problem
maj  2 10:03:34.461 [16555] dbg: async: aborting after 8.252 s, deadline shrunk: DNSBL-A, dns:A:bel-pol.com.pl.rhsbl.ahbl.org.

any idea how to fix that ?

edit:
i just found that in /usr/share/spamassassin/

i just want to ask for other rbl that is not offline, i dont want to stay with no spam protection except my own rules,
as for now i had to disable the rhsbl.ahbl.org adress

4 Reply by ZhangHuangbin

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

Re: slow poll_dns_idle and tests_pri_500

trefnis wrote:

bel-pol.com.pl is my domain, i wonder why is it as a link with the rhsbl.ahbl.org

SpamAssassin is trying to check SBL service with your domain name, this is normal.

If you want to disable rhsbl.ahbl.org, just set its score to 0 in /etc/mail/spamassassin/local.cf. For example:

1: Check which rule defines 'rhsbl.ahbl.org':

# cd /usr/share/spamassassin/
# grep -i 'ahbl' 20_dnsbl_tests.cf 
header DNS_FROM_AHBL_RHSBL      eval:check_rbl_envfrom('ahbl', 'rhsbl.ahbl.org.')
describe DNS_FROM_AHBL_RHSBL    Envelope sender listed in dnsbl.ahbl.org
tflags DNS_FROM_AHBL_RHSBL      net
reuse  DNS_FROM_AHBL_RHSBL

2: You see the rule name is DNS_FROM_AHBL_RHSBL. So turn it off in /etc/mail/spamassassin/local.cf:

score DNS_FROM_AHBL_RHSBL 0