spamassassin problem with RBL DNS queries

[msst]

Since a couple of days I find some strange error messages coming from spamassassin:

Feb  6 16:19:47 sprinter spamd[7034]: spamd: connection from xxx [127.0.0.1]:47174 to port 783, fd 6
Feb  6 16:19:47 sprinter spamd[7034]: spamd: setuid to mail succeeded
Feb  6 16:19:47 sprinter spamd[7034]: spamd: checking message (unknown) for mail:8
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 29373/IN/A/deutschlandsim.de.multi.surbl.org
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 2391/IN/A/deutschlandsim.de.multi.uribl.com
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 38123/IN/A/deutschlandsim.de.dob.sibl.support-intelligence.net
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 8794/IN/A/deutschlandsim.de.dbl.spamhaus.org
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 36324/IN/NS/deutschlandsim.de
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 35266/IN/A/www.deutschlandsim.de
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 3937/IN/A/service.deutschlandsim.de
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 1975/IN/A/215.194.227.193.zen.spamhaus.org
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 6137/IN/A/71.0.32.128.dnsbl.sorbs.net
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 60353/IN/A/215.194.227.193.dnsbl.sorbs.net
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 26169/IN/TXT/215.194.227.193.sa-accredit.habeas.com
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 8405/IN/A/215.194.227.193.bb.barracudacentral.org
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 64084/IN/A/215.194.227.193.bl.score.senderscore.com
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 64783/IN/TXT/71.0.32.128.bl.spamcop.net
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 28829/IN/TXT/215.194.227.193.bl.spamcop.net
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 59833/IN/A/deutschlandsim.de
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 46370/IN/MX/deutschlandsim.de
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 8791/IN/A/215.194.227.193.psbl.surriel.com
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 56902/IN/TXT/215.194.227.193.sa-trusted.bondedsender.org
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 35839/IN/A/71.0.32.128.zen.spamhaus.org
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 64585/IN/A/215.194.227.193.bl.mailspike.net
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 19446/IN/A/215.194.227.193.wl.mailspike.net
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 21694/IN/A/215.194.227.193.iadb.isipp.com
Feb  6 16:19:47 sprinter spamd[7034]: dns: a likely matching query: 29188/IN/A/215.194.227.193.list.dnswl.org
Feb  6 16:19:48 sprinter spamd[7034]: dns: a likely matching query: 48790/IN/TXT/deutschlandsim.de
Feb  6 16:19:51 sprinter spamd[7034]: dns: a likely matching query: 40310/IN/TXT/mx07.victorvox-ag.de
Feb  6 16:20:04 sprinter spamd[7034]: pyzor: [990] error: TERMINATED, signal 15 (000f)
...

This looked weird so I decided to run a few debug tests on spamassassin, feeding it a sample spam text in debug mode. This indicates some problems with the RBL DNS queries:

Feb  6 18:46:06.110 [8484] dbg: dns: EDNS, UDP payload size 4096
Feb  6 18:46:06.110 [8484] dbg: dns: servers obtained from Net::DNS : [192.168.1.1]:53
Feb  6 18:46:06.111 [8484] dbg: dns: nameservers set to 192.168.1.1
Feb  6 18:46:06.111 [8484] dbg: dns: using socket module: IO::Socket::IP version 0.37
Feb  6 18:46:06.111 [8484] dbg: dns: is Net::DNS::Resolver available? yes
Feb  6 18:46:06.111 [8484] dbg: dns: Net::DNS version: 1.04
Feb  6 18:46:06.112 [8484] dbg: config: time limit 300.0 s
Feb  6 18:46:06.127 [8484] dbg: message: main message type: text/plain
Feb  6 18:46:06.128 [8484] dbg: check: pms new, time limit in 292.594 s

→ DNS resolver seems to be there and loaded properly!

However, further down I find – after a large number of initiated and queued queries:
eb  6 18:46:07.103 [8484] dbg: dns: dns reply to 23441/NO_QUESTION_IN_PACKET: FORMERR
Feb  6 18:46:07.104 [8484] info: dns: a likely matching query: 23441/IN/A/github.net.multi.uribl.com
Feb  6 18:46:07.105 [8484] dbg: dns: dns reply to 48458/NO_QUESTION_IN_PACKET: FORMERR
Feb  6 18:46:07.105 [8484] info: dns: a likely matching query: 48458/IN/A/github.net.multi.surbl.org
Feb  6 18:46:07.106 [8484] dbg: dns: dns reply to 43412/NO_QUESTION_IN_PACKET: REFUSED
Feb  6 18:46:07.107 [8484] info: dns: a likely matching query: 43412/IN/A/github.net.dob.sibl.support-intelligence.net
Feb  6 18:46:07.108 [8484] dbg: dns: dns reply to 59140/NO_QUESTION_IN_PACKET: REFUSED
Feb  6 18:46:07.109 [8484] info: dns: a likely matching query: 59140/IN/A/github.net.dbl.spamhaus.org
Feb  6 18:46:07.110 [8484] dbg: dns: dns reply to 43826/NO_QUESTION_IN_PACKET: REFUSED
Feb  6 18:46:07.111 [8484] info: dns: a likely matching query: 43826/IN/NS/github.net
Feb  6 18:46:07.112 [8484] dbg: dns: dns reply to 53790/NO_QUESTION_IN_PACKET: REFUSED
Feb  6 18:46:07.113 [8484] info: dns: a likely matching query: 53790/IN/A/github-fe123-cp1-prd.iad.github.net
Feb  6 18:46:07.114 [8484] dbg: dns: dns reply to 44114/NO_QUESTION_IN_PACKET: REFUSED
Feb  6 18:46:07.114 [8484] info: dns: a likely matching query: 44114/IN/A/githubapp.com.multi.uribl.com
Feb  6 18:46:07.115 [8484] dbg: dns: dns reply to 45213/NO_QUESTION_IN_PACKET: REFUSED
Feb  6 18:46:07.116 [8484] info: dns: a likely matching query: 45213/IN/A/githubapp.com.multi.surbl.org


This looks like there is a formal problem with the queries. Just no clear what. Even a bit later in the log I see:

Feb  6 18:46:26.516 [8484] dbg: async: aborting after 19.698 s, past original deadline: URI-A, A:shop.github.com
Feb  6 18:46:26.516 [8484] dbg: async: aborting after 19.572 s, past original deadline: URI-NS, NS:ogp.me
Feb  6 18:46:26.517 [8484] dbg: async: aborting after 19.752 s, past original deadline: URIBL_RED, URI-DNSBL, DNSBL:githubapp.com:multi.uribl.com
Feb  6 18:46:26.517 [8484] dbg: async: aborting after 19.755 s, past original deadline: URI-A, A:github-fe123-cp1-prd.iad.github.net
Feb  6 18:46:26.517 [8484] dbg: async: aborting after 19.656 s, past original deadline: URIBL_RHS_DOB, URI-DNSBL, DNSBL:githubusercontent.com:dob.sibl.support-intelligence.net
Feb  6 18:46:26.517 [8484] dbg: async: aborting after 19.498 s, past original deadline: URI-A, A:training.github.com
Feb  6 18:46:26.518 [8484] dbg: async: aborting after 19.612 s, past original deadline: URIBL_RHS_DOB, URI-DNSBL, DNSBL:data-vocabulary.org:dob.sibl.support-intelligence.net
Feb  6 18:46:26.518 [8484] dbg: async: aborting after 19.666 s, past original deadline: URIBL_RED, URI-DNSBL, DNSBL:githubusercontent.com:multi.uribl.com
Feb  6 18:46:26.518 [8484] dbg: async: aborting after 19.669 s, past original deadline: URI-A, A:schema.org
Feb  6 18:46:26.518 [8484] dbg: async: aborting after 19.685 s, past original deadline: URIBL_RHS_DOB, URI-DNSBL, DNSBL:schema.org:dob.sibl.support-intelligence.net
Feb  6 18:46:26.519 [8484] dbg: async: aborting after 19.730 s, past original deadline: URI-NS, NS:githubapp.com
Feb  6 18:46:26.519 [8484] dbg: async: aborting after 19.723 s, past original deadline: URIBL_RED, URI-DNSBL, DNSBL:github.com:multi.uribl.com
Feb  6 18:46:26.519 [8484] dbg: async: aborting after 19.540 s, past original deadline: URI-A, A:github.com
Feb  6 18:46:26.519 [8484] dbg: async: aborting after 19.727 s, past original deadline: URI-A, A:collector.githubapp.com
Feb  6 18:46:26.519 [8484] dbg: async: aborting after 19.777 s, past original deadline: URIBL_CR_SURBL, URI-DNSBL, DNSBL:github.net:multi.surbl.org
Feb  6 18:46:26.520 [8484] dbg: async: aborting after 19.608 s, past original deadline: URIBL_DBL_ABUSE_MALW, URI-DNSBL, DNSBL:data-vocabulary.org:dbl.spamhaus.org
Feb  6 18:46:26.520 [8484] dbg: async: aborting after 19.569 s, past original deadline: URI-A, A:ogp.me
Feb  6 18:46:26.520 [8484] dbg: async: aborting after 19.694 s, past original deadline: URIBL_RED, URI-DNSBL, DNSBL:schema.org:multi.uribl.com
Feb  6 18:46:26.520 [8484] dbg: async: aborting after 19.640 s, past original deadline: URI-A, A:avatars2.githubusercontent.com

and then it is all aborting

Feb  6 18:46:26.528 [8484] dbg: uridnsbl: complete_a_lookup aborted A:training.github.com
Feb  6 18:46:26.528 [8484] dbg: async: calling callback/abort on key A/developer.github.com
Feb  6 18:46:26.529 [8484] dbg: uridnsbl: complete_a_lookup aborted A:developer.github.com
Feb  6 18:46:26.529 [8484] dbg: async: calling callback/abort on key A/assets-cdn.github.com
Feb  6 18:46:26.529 [8484] dbg: uridnsbl: complete_a_lookup aborted A:assets-cdn.github.com
Feb  6 18:46:26.529 [8484] dbg: async: calling callback/abort on key A/ogp.me.multi.uribl.com, rule URIBL_RED
Feb  6 18:46:26.529 [8484] dbg: uridnsbl: complete_dnsbl_lookup aborted URIBL_RED DNSBL:ogp.me:multi.uribl.com
Feb  6 18:46:26.530 [8484] dbg: async: calling callback/abort on key A/ogp.me.multi.uribl.com, rule URIBL_BLACK
Feb  6 18:46:26.530 [8484] dbg: uridnsbl: complete_dnsbl_lookup aborted URIBL_BLACK DNSBL:ogp.me:multi.uribl.com
Feb  6 18:46:26.530 [8484] dbg: async: calling callback/abort on key A/ogp.me.multi.uribl.com, rule URIBL_BLOCKED
Feb  6 18:46:26.530 [8484] dbg: uridnsbl: complete_dnsbl_lookup aborted URIBL_BLOCKED DNSBL:ogp.me:multi.uribl.com
Feb  6 18:46:26.530 [8484] dbg: async: calling callback/abort on key A/ogp.me.multi.uribl.com, rule URIBL_GREY
Feb  6 18:46:26.531 [8484] dbg: uridnsbl: complete_dnsbl_lookup aborted URIBL_GREY DNSBL:ogp.me:multi.uribl.com
Feb  6 18:46:26.531 [8484] dbg: async: calling callback/abort on key NS/data-vocabulary.org
Feb  6 18:46:26.531 [8484] dbg: uridnsbl: complete_ns_lookup aborted NS:data-vocabulary.org
Feb  6 18:46:26.531 [8484] dbg: async: calling callback/abort on key A/githubapp.com.multi.surbl.org, rule URIBL_CR_SURBL
Feb  6 18:46:26.532 [8484] dbg: uridnsbl: complete_dnsbl_lookup aborted URIBL_CR_SURBL DNSBL:githubapp.com:multi.surbl.org
Feb  6 18:46:26.532 [8484] dbg: async: calling callback/abort on key A/githubapp.com.multi.surbl.org, rule URIBL_MW_SURBL
Feb  6 18:46:26.532 [8484] dbg: uridnsbl: complete_dnsbl_lookup aborted URIBL_MW_SURBL DNSBL:githubapp.com:multi.surbl.org
Feb  6 18:46:26.532 [8484] dbg: async: calling callback/abort on key A/githubapp.com.multi.surbl.org, rule URIBL_ABUSE_SURBL
Feb  6 18:46:26.532 [8484] dbg: uridnsbl: complete_dnsbl_lookup aborted URIBL_ABUSE_SURBL DNSBL:githubapp.com:multi.surbl.org
Feb  6 18:46:26.533 [8484] dbg: async: calling callback/abort on key A/githubapp.com.multi.surbl.org, rule URIBL_PH_SURBL
Feb  6 18:46:26.533 [8484] dbg: uridnsbl: complete_dnsbl_lookup aborted URIBL_PH_SURBL DNSBL:githubapp.com:multi.surbl.org
Feb  6 18:46:26.533 [8484] dbg: async: calling callback/abort on key A/githubapp.com.multi.surbl.org, rule SURBL_BLOCKED

–

Conclusion, apparently the DNS checks do not go through. Does anyone have an idea why?

I did a full

perl-cleaner reallyall

run to reinastall perl in case there is a problem.

The DNS resolver is not faulty in general by the way. It works nicely for exim to query the RBLs as I can see from log entries. Also all else works. DNS works, just not for spamassassin?

System uses:
spamassassin 3.4.1-r1
perl 5.22.1

[msst]

Fixed now by downgrading both spamassassin and perl:Net-DNS to stable versions. Interesingly neither both testing nor one of them as testing version seems to work. Something working against each other in the testing versions...