Re: Need help with dns_query patch

Hi Duane,
thanks for your answer. I'm in contact with users that can reproduce the
bug and provided them an unstripped version for the stack trace. In the
meanwhile they reported that the bug appears with both dnscache (from
djbdns-1.05) and pdnsd, both in standalone and transparent mode.

I'm quoting one of the user on his analisys:

> I have checked the squid and dnscache logs for the timeframe in
> question
> and may have found something. The squid crashes could be identified in
> the access.log file by larger than usual timestamp deltas between
> consecutive log lines. I noticed that http://http.proxy.icq.com/hello
> was the URL I last saw in the crash that followed the cache.log
> entries
> following Jul 12, 9:00:14. Grepping for
> http://http.proxy.icq.com/hello,
> I notice that it is the last URL to be placed into access.log before
> the
> crashes at 8:55 and 9:00. At 9:05, it doesn't seem to have an adverse
> effect:
>
> Tue Jul 12 08:55:55 2005 226 <downstream proxy> TCP_MISS/200 2586
> GET
> http://ebay.doubleclick.net/adi/ebay.de.homepage.inactive/inactive;tn=2;to=h;tr=1;tw=240;ta=center;szs=110x110,110x110;ord=1121151443109;
> - FIRST_UP_PARENT/localhost text/html
>
> Tue Jul 12 08:55:55 2005 314 <downstream proxy> TCP_MISS/200 3227
> GET
> http://ebay.doubleclick.net/adi/ebay.de.homepage.inactive/inactive;tile=1;dcopt=ist;sz=275x300;ord=1121151443109;
> - FIRST_UP_PARENT/localhost text/html
>
> Tue Jul 12 08:55:55 2005 221 <downstream proxy> TCP_MISS/200 346
> GET
> http://http.proxy.icq.com/hello - FIRST_UP_PARENT/localhost AIM/HTTP
>
> Tue Jul 12 09:00:14 2005 121 <downstream proxy> TCP_MISS/302 527
> GET
> http://www.www.gmx.net.edu/ - FIRST_UP_PARENT/localhost text/html
>
> Tue Jul 12 09:00:14 2005 169 <downstream proxy> TCP_MISS/200 16422
> GET http://www.portland.co.uk/404.esp - FIRST_UP_PARENT/localhost
> text/html
>
> --
>
> Tue Jul 12 09:00:17 2005 74 <downstream proxy> TCP_MISS/200 936
> GET
> http://www.portland.co.uk/portland/images/switch.gif -
> FIRST_UP_PARENT/localhostimage/gif
>
> Tue Jul 12 09:00:17 2005 64 <downstream proxy> TCP_MISS/200 1064
> GET
> http://www.portland.co.uk/portland/images/solo.gif -
> FIRST_UP_PARENT/localhost image/gif
>
> Tue Jul 12 09:00:17 2005 230 <downstream proxy> TCP_MISS/200 346
> GET
> http://http.proxy.icq.com/hello - FIRST_UP_PARENT/localhost AIM/HTTP
>
> Tue Jul 12 09:05:32 2005 420 <downstream proxy> TCP_MISS/200 346
> GET
> http://http.proxy.icq.com/hello - FIRST_UP_PARENT/localhost AIM/HTTP
>
> Tue Jul 12 09:05:33 2005 553 <downstream proxy> TCP_MISS/200 316
> GET
> http://64.12.163.134/monitor? - FIRST_UP_PARENT/localhost AIM/HTTP
>
> Tue Jul 12 09:05:33 2005 616 <downstream proxy> TCP_MISS/200 300
> POST
> http://64.12.163.134/data? - FIRST_UP_PARENT/localhost AIM/HTTP
>
> Here's the queries made to dnscache for the debug snippet I'd provided
> (the one that ends in the bug):
>
> 2005-07-12 09:00:13.765430500 query 37711366 01020304:8daa:e6c7 1
> netscape.com.
> 2005-07-12 09:00:14.560191500 query 37711367 01020304:8daa:e5c3 1
> localhost.
> 2005-07-12 09:00:14.621235500 query 37711368 01020304:8dab:7bce 1
> www.www.gmx.net.edu.
> 2005-07-12 09:00:14.697003500 query 37711369 0a010425:0035:32f9 1
> www.portland.co.uk.
> 2005-07-12 09:00:14.779568500 query 37711370 01020304:8dab:fae4 1
> www.portland.co.uk.
> 2005-07-12 09:00:14.978950500 query 37711371 01020304:8dab:7bcf 1
> www.portland.co.uk.
> 2005-07-12 09:00:14.983423500 query 37711372 01020304:8dab:71ec 1
> www.portland.co.uk.
> 2005-07-12 09:00:15.090424500 query 37711373 01020304:8dab:d829 1
> www.portland.co.uk.
> 2005-07-12 09:00:15.193001500 query 37711374 01020304:8dab:7bd0 1
> www.portland.co.uk.
> 2005-07-12 09:00:15.255559500 query 37711375 01020304:8dab:d82a 1
> www.portland.co.uk.
> 2005-07-12 09:00:15.323293500 query 37711376 01020304:8dab:7bd1 1
> www.google.com.
> 2005-07-12 09:00:15.338657500 query 37711377 0a010425:0035:3300 1
> 3.adbrite.com.
> 2005-07-12 09:00:16.133801500 query 37711378 01020304:8dab:d82b 1
> 3.adbrite.com.
> 2005-07-12 09:00:16.363244500 query 37711379 0a010425:0035:330a 1
> www.ftjcfx.com.
> 2005-07-12 09:00:16.365113500 query 37711380 01020304:8dab:7bd2 1
> www.portland.co.uk.
> 2005-07-12 09:00:16.679675500 query 37711381 01020304:8dab:d82c 1
> www.portland.co.uk.
> 2005-07-12 09:00:16.691790500 query 37711382 01020304:8dab:7bd3 1
> www.ftjcfx.com.
> 2005-07-12 09:00:16.795526500 query 37711383 01020304:8dab:05f3 1
> www.portland.co.uk.
> 2005-07-12 09:00:16.985792500 query 37711384 01020304:8dab:71ed 1
> www.portland.co.uk.
> 2005-07-12 09:00:17.046664500 query 37711385 01020304:8dab:05f4 1
> www.portland.co.uk.
> 2005-07-12 09:00:17.081015500 query 37711386 01020304:8dab:71ee 1
> www.portland.co.uk.
> 2005-07-12 09:00:17.113329500 query 37711387 01020304:8dab:7bd4 1
> www.portland.co.uk.
> 2005-07-12 09:00:17.142708500 query 37711388 01020304:8dab:05f5 1
> www.portland.co.uk.
> 2005-07-12 09:00:17.179930500 query 37711389 01020304:8dab:71ef 1
> www.portland.co.uk.
> 2005-07-12 09:00:17.212402500 query 37711390 01020304:8dab:7bd5 1
> www.portland.co.uk.
> 2005-07-12 09:00:17.333044500 query 37711391 01020304:8dab:05f6 1
> www.portland.co.uk.
> 2005-07-12 09:00:17.372066500 query 37711392 01020304:8dab:71f0 1
> http.proxy.icq.com.
> 2005-07-12 09:00:17.402875500 query 37711393 01020304:8dab:fae5 1
> www.portland.co.uk.
> 2005-07-12 09:00:17.469733500 query 37711394 01020304:8dab:05f7 1
> www.portland.co.uk.
> 2005-07-12 09:00:17.606081500 query 37711395 01020304:8daa:a3e8 12
> 130.163.12.64.in-addr.arpa.
> 2005-07-12 09:00:17.606309500 query 37711396 01020304:8daa:599c 12
> 130.163.12.64.in-addr.arpa.
> 2005-07-12 09:00:17.606837500 query 37711397 01020304:8daa:ecee 12
> 130.163.12.64.in-addr.arpa.
> 2005-07-12 09:00:17.607040500 query 37711398 01020304:8daa:b74b 12
> 130.163.12.64.in-addr.arpa.
>
> Maybe it's the answers to the PTR queries for
> 130.163.12.64.in-addr.arpa. in this case? Checking the dnscache logs
> for
> PTR queries from squid (or postfix), I believe that they may well be
> the
> problem, though I can't see anything unusual about them now:
>
> host:~# date; dnsqr ptr 130.163.12.64.in-addr.arpa
> Fri Jul 15 06:23:14 CEST 2005
> 12 130.163.12.64.in-addr.arpa:
> 78 bytes, 1+1+0+0 records, response, noerror
> query: 12 130.163.12.64.in-addr.arpa
> answer: 130.163.12.64.in-addr.arpa 3489 PTR ahp-m01.blue.aol.com
>
> They appear to have been similar when the problem occured, as it says
> in
> the dnscache logs:
>
> 2005-07-12 08:53:11.387717500 query 37710894 01020304:8d87:3111 12
> 130.163.12.64.in-addr.arpa.
> 2005-07-12 08:53:11.387721500 tx 0 12 130.163.12.64.in-addr.arpa. .
> 7f000003
>
> dnscache found no answer to the query above in its cache, so it's
> forwarding the query to a second dnscache on 127.0.0.3. It receives
> the
> same answers as I did just now:
>
> 2005-07-12 08:53:11.489862500 rr 7f000003 3600 ptr
> 130.163.12.64.in-addr.arpa. ahp-m01.blue.aol.com.
> 2005-07-12 08:53:11.492008500 rr 7f000003 3600 ptr
> 130.163.12.64.in-addr.arpa. ahp-m01.blue.aol.com.
> 2005-07-12 08:53:11.493055500 rr 7f000003 3600 ptr
> 130.163.12.64.in-addr.arpa. ahp-m01.blue.aol.com.
> 2005-07-12 08:53:11.512650500 rr 7f000003 3600 ptr
> 130.163.12.64.in-addr.arpa. ahp-m01.blue.aol.com.
>
> In subsequent queries, it answers from its cache:
>
> 2005-07-12 08:53:21.739704500 query 37710945 01020304:8d88:0e7d 12
> 130.163.12.64.in-addr.arpa.
> 2005-07-12 08:53:21.739711500 cached 12 130.163.12.64.in-addr.arpa.
>
> 2005-07-12 08:53:21.740016500 query 37710946 01020304:8d88:776b 12
> 130.163.12.64.in-addr.arpa.
> 2005-07-12 08:53:21.740021500 cached 12 130.163.12.64.in-addr.arpa.
>
> This continues until the four queries I already quoted above appear:
>
> 2005-07-12 09:00:17.606081500 query 37711395 c0a80703:8daa:a3e8 12
> 130.163.12.64.in-addr.arpa.
> 2005-07-12 09:00:17.606088500 cached 12 130.163.12.64.in-addr.arpa.
> 2005-07-12 09:00:17.606309500 query 37711396 c0a80703:8daa:599c 12
> 130.163.12.64.in-addr.arpa.
> 2005-07-12 09:00:17.606313500 cached 12 130.163.12.64.in-addr.arpa.
> 2005-07-12 09:00:17.606837500 query 37711397 c0a80703:8daa:ecee 12
> 130.163.12.64.in-addr.arpa.
> 2005-07-12 09:00:17.606842500 cached 12 130.163.12.64.in-addr.arpa.
> 2005-07-12 09:00:17.607040500 query 37711398 c0a80703:8daa:b74b 12
> 130.163.12.64.in-addr.arpa.
> 2005-07-12 09:00:17.607045500 cached 12 130.163.12.64.in-addr.arpa.

Regards,

-- 
 Luigi Gangitano -- <luigi@debian.org> -- <gangitano@lugroma3.org>
 GPG: 1024D/924C0C26: 12F8 9C03 89D3 DB4A 9972  C24A F19B A618 924C 0C26