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
spamassassin problem with RBL DNS queries
Message