Bug 6711 - DnsResolver: "dns: no callback for id", DNS answer packets ignored as unsolicited
Summary: DnsResolver: "dns: no callback for id", DNS answer packets ignored as unsolic...
Status: RESOLVED DUPLICATE of bug 6819
Alias: None
Product: Spamassassin
Classification: Unclassified
Component: Libraries (show other bugs)
Version: SVN Trunk (Latest Devel Version)
Hardware: All All
: P2 normal
Target Milestone: 3.4.0
Assignee: SpamAssassin Developer Mailing List
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2011-11-29 13:42 UTC by Mark Martinec
Modified: 2013-01-17 00:34 UTC (History)
0 users



Attachment Type Modified Status Actions Submitter/CLA Status

Note You need to log in before you can comment on or make changes to this bug.
Description Mark Martinec 2011-11-29 13:42:26 UTC
A few times per day I see in the logs an info message from SpamAssassin:

  SA info: dns: no callback for id: 8235/avivabiology.com/NS/IN, ignored;
    packet: ;; Answer received from ... (86 bytes)

followed by a dump of a captured normal DNS answer packet.

Adding some debug logging, so far I can recognize two distinct cases
of how this happens:

case#1:
  SA dbg: dns: providing a callback for id: 8235/avivabiology.com/NS/IN
  SA dbg: dns: providing a callback for id: 8235/avivabiology.com/NS/IN
  SA info: dns: no callback for id: 8235/avivabiology.com/NS/IN, ignored;
    packet: ;; Answer received from ::1 (86 bytes)

case#2:
  SA dbg: dns: providing a callback for id: 23893/news.dormeo..si/ANY/IN
  SA info: dns: no callback for id: 23893/news.dormeo.si/ANY/IN, ignored;
    packet: ;; Answer received from ::1 (256 bytes)

  SA info: dns: [...] ;; HEADER SECTION
  SA info: dns: [...] ;; id = 23893
  SA info: dns: [...] ;; qr = 1 opcode = QUERY aa = 0 tc = 0 rd = 1
  SA info: dns: [...] ;; ra = 1 ad = 0 cd = 0 rcode = NOERROR
  SA info: dns: [...] ;; qdcount = 1 ancount = 4 nscount = 0 arcount = 0
  SA info: dns: [...] 
  SA info: dns: [...] ;; QUESTION SECTION (1 record)
  SA info: dns: [...] ;; news.dormeo.si. IN ANY
  SA info: dns: [...] 
  SA info: dns: [...] ;; ANSWER SECTION (4 records)
  SA info: dns: [...] news.dormeo.si. 1922 IN A 91.198.190.101
  SA info: dns: [...] news.dormeo.si. 1922 IN MX 10 mail.avenija.com.
  SA info: dns: [...] news.dormeo.si. 1922 IN TXT
    "v=spf1 ip4:91.198.190.1/24 ip4:91.220.213.1/24 include:icpbounce.com -all"
  SA info: dns: [...] news.dormeo.si. 1922 IN TXT
    "spf2.0/pra ip4:91.198.190.1/24 ip4:91.220.213.1/24
     include:icpbounce.com -all"
  SA info: dns: [...] 
  SA info: dns: [...] ;; AUTHORITY SECTION (0 records)
  SA info: dns: [...] 
  SA info: dns: [...] ;; ADDITIONAL SECTION (0 records)

  SA dbg: dns: bgabort: 23893/news.dormeo..si/ANY/IN

In case#1 it seems that two queries for "avivabiology.com/NS" are issued.
As the query IDs are stored in %{$self->{id_to_callback}} as hash keys,
there is only one copy of the ID kept in evidence, so when the first
DNS answer arrives and clears the ID from evidence, the second answer
appears unsolicited and is ditched with a warning. In addition, the first
of the two callbacks is never called.

In case#2 the queried domain contains and empty label field (two consecutive
dots). Somewhere this gets sanitized so the DNS query section goes for 
news.dormeo.si (no double dot), and the answer is in accordance - but this
does not match the remembered query ID in %{$self->{id_to_callback}} and
it is ditched as unsolicited. At the end the bgabort gives up on waiting
for 23893/news.dormeo..si/ANY/IN

Probably not new and not a showstopper for 3.4.0, but eventually it should
be addressed.
Comment 1 Mark Martinec 2013-01-17 00:34:16 UTC
The case #1 is now avoided by a rewrite in Bug 6884, duplicate DNS queries
are merged into one query by the new AsyncLoop::bgsend_and_start_lookup().

Case #2 is a duplicate for Bug 6819, now handled more gracefully.

Closing.

*** This bug has been marked as a duplicate of bug 6819 ***