[Dnsmasq-discuss] CPU spinning bug, possibly related to SSHFP queries

[Tore Anderson]

* Geert Stappers

> Could caching be involved?  That we are seeing only when it fails,
> not seeing in the libpcap file what led to the fail?

I think you are right.

It is a cache miss - the bug occurs when SSH-ing to an FQDN for the first time after Dnsmasq has started, so the SSHFP record is not found in cache.

Tracing it in GDB with breakpoints on answer_request() and cache_find_by_name():

Breakpoint 2, cache_find_by_name (crecp=crecp at entry=0x0, name=name at entry=0x1fbfa50 "cr1-osl4.n.bitbit.net", 
    now=now at entry=1575100445, prot=prot at entry=2048) at cache.c:810
810     {
(gdb) bt
#0  cache_find_by_name (crecp=crecp at entry=0x0, name=name at entry=0x1fbfa50 "cr1-osl4.n.bitbit.net", 
    now=now at entry=1575100445, prot=prot at entry=2048) at cache.c:810
#1  0x000000000040d442 in answer_request (header=header at entry=0x1fc2220, limit=0x1fc26d0 "", qlen=qlen at entry=50, 
    local_addr=..., local_addr at entry=..., local_netmask=..., local_netmask at entry=..., now=now at entry=1575100445, 
    ad_reqd=1, do_bit=1, have_pseudoheader=1) at rfc1035.c:1367
#2  0x000000000041c8c6 in receive_query (listen=listen at entry=0x1fc07d0, now=now at entry=1575100445) at forward.c:1563
#3  0x0000000000420e19 in check_dns_listeners (now=now at entry=1575100445) at dnsmasq.c:1760
#4  0x0000000000406638 in main (argc=<optimized out>, argv=<optimized out>) at dnsmasq.c:1192
(gdb) cont
Continuing.

Breakpoint 2, cache_find_by_name (crecp=crecp at entry=0x0, name=name at entry=0x1fbfa50 "cr1-osl4.n.bitbit.net", 
    now=now at entry=1575100445, prot=prot at entry=2048) at cache.c:810
810     {
(gdb) bt
#0  cache_find_by_name (crecp=crecp at entry=0x0, name=name at entry=0x1fbfa50 "cr1-osl4.n.bitbit.net", 
    now=now at entry=1575100445, prot=prot at entry=2048) at cache.c:810
#1  0x000000000040d442 in answer_request (header=header at entry=0x1fc2220, limit=0x1fc26d0 "", qlen=qlen at entry=50, 
    local_addr=..., local_addr at entry=..., local_netmask=..., local_netmask at entry=..., now=now at entry=1575100445, 
    ad_reqd=1, do_bit=1, have_pseudoheader=1) at rfc1035.c:1367
#2  0x000000000041c8c6 in receive_query (listen=listen at entry=0x1fc07d0, now=now at entry=1575100445) at forward.c:1563
#3  0x0000000000420e19 in check_dns_listeners (now=now at entry=1575100445) at dnsmasq.c:1760
#4  0x0000000000406638 in main (argc=<optimized out>, argv=<optimized out>) at dnsmasq.c:1192
(gdb) cont
Continuing.

Breakpoint 2, cache_find_by_name (crecp=crecp at entry=0x0, name=name at entry=0x1fbfa50 "cr1-osl4.n.bitbit.net", 
    now=now at entry=1575100445, prot=prot at entry=2048) at cache.c:810
810     {
(gdb) bt
#0  cache_find_by_name (crecp=crecp at entry=0x0, name=name at entry=0x1fbfa50 "cr1-osl4.n.bitbit.net", 
    now=now at entry=1575100445, prot=prot at entry=2048) at cache.c:810
#1  0x000000000040d442 in answer_request (header=header at entry=0x1fc2220, limit=0x1fc26d0 "", qlen=qlen at entry=50, 
    local_addr=..., local_addr at entry=..., local_netmask=..., local_netmask at entry=..., now=now at entry=1575100445, 
    ad_reqd=1, do_bit=1, have_pseudoheader=1) at rfc1035.c:1367
#2  0x000000000041c8c6 in receive_query (listen=listen at entry=0x1fc07d0, now=now at entry=1575100445) at forward.c:1563
#3  0x0000000000420e19 in check_dns_listeners (now=now at entry=1575100445) at dnsmasq.c:1760
#4  0x0000000000406638 in main (argc=<optimized out>, argv=<optimized out>) at dnsmasq.c:1192
(gdb) cont
Continuing.

Breakpoint 2, cache_find_by_name (crecp=crecp at entry=0x0, name=name at entry=0x1fbfa50 "cr1-osl4.n.bitbit.net", 
    now=now at entry=1575100445, prot=prot at entry=2048) at cache.c:810
810     {
(gdb) bt
#0  cache_find_by_name (crecp=crecp at entry=0x0, name=name at entry=0x1fbfa50 "cr1-osl4.n.bitbit.net", 
    now=now at entry=1575100445, prot=prot at entry=2048) at cache.c:810
#1  0x000000000040d442 in answer_request (header=header at entry=0x1fc2220, limit=0x1fc26d0 "", qlen=qlen at entry=50, 
    local_addr=..., local_addr at entry=..., local_netmask=..., local_netmask at entry=..., now=now at entry=1575100445, 
    ad_reqd=1, do_bit=1, have_pseudoheader=1) at rfc1035.c:1367
#2  0x000000000041c8c6 in receive_query (listen=listen at entry=0x1fc07d0, now=now at entry=1575100445) at forward.c:1563
#3  0x0000000000420e19 in check_dns_listeners (now=now at entry=1575100445) at dnsmasq.c:1760
#4  0x0000000000406638 in main (argc=<optimized out>, argv=<optimized out>) at dnsmasq.c:1192
(gdb)

[....]

I think that this while loop goes on forever:

http://thekelleys.org.uk/gitweb/?p=dnsmasq.git;a=blob;f=src/rfc1035.c;h=502744bd1f847441e8a6dbf485fd9032f2a52e9f;hb=HEAD#l1367

Tore