Errors on RecursiveResolver Server

[pd-448482]

Hi, so I have been trying out the server functionality via command line and I get some issues around the dns server upstream dns requests. I'm on python version 3.8.10 and async-dns version 2.0.0. I ran the client multiple times and captured the debug output from the server.

user@vm:~/dns-test$ python3 -m async_dns.resolver -n tcp://127.0.0.1:5354 -- www.google.com
user@vm:~/dns-test$ python3 -m async_dns.resolver -n tcp://127.0.0.1:5354 -- www.google.com
Traceback (most recent call last):
  File "/usr/lib/python3.8/runpy.py", line 194, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/usr/lib/python3.8/runpy.py", line 87, in _run_code
    exec(code, run_globals)
  File "/home/user/.local/lib/python3.8/site-packages/async_dns/resolver/__main__.py", line 68, in <module>
    loop.run_until_complete(resolve_hostnames(_parse_args()))
  File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/home/user/.local/lib/python3.8/site-packages/async_dns/resolver/__main__.py", line 56, in resolve_hostnames
    res, _ = fut.result()
  File "/home/user/.local/lib/python3.8/site-packages/async_dns/resolver/__main__.py", line 31, in resolve_hostname
    return await resolver.query(hostname, qtype)
  File "/home/user/.local/lib/python3.8/site-packages/async_dns/resolver/base_resolver.py", line 64, in query
    return await asyncio.wait_for(self._query(fqdn, qtype),
  File "/usr/lib/python3.8/asyncio/tasks.py", line 494, in wait_for
    return fut.result()
  File "/home/user/.local/lib/python3.8/site-packages/async_dns/resolver/util.py", line 23, in wrapped
    return await future
  File "/home/user/.local/lib/python3.8/site-packages/async_dns/resolver/proxy_resolver.py", line 91, in _query
    res = await self.request(fqdn, qtype, addr)
  File "/home/user/.local/lib/python3.8/site-packages/async_dns/resolver/base_resolver.py", line 73, in request
    assert result.r != 2, 'Remote server fail'
AssertionError: Remote server fail
user@vm:~/dns-test$ python3 -m async_dns.resolver -n tcp://127.0.0.1:5354 -- www.google.com
www.google.com [A] <a: 142.250.64.68>
www.google.com [AAAA] <aaaa: 2607:f8b0:4006:806::2004>

user@vm:~/dns-test$ LOGLEVEL=DEBUG python3 -m async_dns.server -b "localhost:5354"
INFO:async_dns.core:DNS server v2 - by Gerald
DEBUG:asyncio:Using selector: EpollSelector
INFO:async_dns.core:====================
INFO:async_dns.core:Remote:	tcp://127.0.0.1:5354
INFO:async_dns.core:***
INFO:async_dns.core:Remote:	udp://127.0.0.1:5354
INFO:async_dns.core:====================
INFO:async_dns.core:RecursiveResolver started
DEBUG:async_dns.core:[RecursiveResolver._get_nameservers][] [udp://198.41.0.4:53, udp://199.9.14.201:53, udp://192.33.4.12:53, udp://199.7.91.13:53, udp://192.203.230.10:53, udp://192.5.5.241:53, udp://192.112.36.4:53, udp://198.97.190.53:53, udp://192.36.148.17:53, udp://192.58.128.30:53, udp://193.0.14.129:53, udp://199.7.83.42:53, udp://202.12.27.33:53]
DEBUG:async_dns.core:[DNSClient:query][ANY][www.google.com] udp://198.41.0.4:53
DEBUG:async_dns.core:[server_handle][ANY][www.google.com] Traceback (most recent call last):
  File "/home/user/.local/lib/python3.8/site-packages/async_dns/server/__init__.py", line 20, in handle_dns
    res, cached = await resolver.query(question.name, question.qtype)
  File "/home/user/.local/lib/python3.8/site-packages/async_dns/resolver/base_resolver.py", line 64, in query
    return await asyncio.wait_for(self._query(fqdn, qtype),
  File "/usr/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

INFO:async_dns.core:[tcp|remote|127.0.0.1|ANY] www.google.com -1 0 
DEBUG:async_dns.core:[RecursiveResolver._get_nameservers][] [udp://198.41.0.4:53, udp://199.9.14.201:53, udp://192.33.4.12:53, udp://199.7.91.13:53, udp://192.203.230.10:53, udp://192.5.5.241:53, udp://192.112.36.4:53, udp://198.97.190.53:53, udp://192.36.148.17:53, udp://192.58.128.30:53, udp://193.0.14.129:53, udp://199.7.83.42:53, udp://202.12.27.33:53]
DEBUG:async_dns.core:[DNSClient:query][ANY][www.google.com] udp://198.41.0.4:53
DEBUG:async_dns.core:[DNSClient:query][ANY][www.google.com] udp://192.12.94.30:53
DEBUG:async_dns.core:[DNSClient:query][ANY][www.google.com] udp://216.239.34.10:53
INFO:async_dns.core:[tcp|remote|127.0.0.1|ANY] www.google.com 2 76 
DEBUG:async_dns.core:[RecursiveResolver._get_nameservers][google.com] [udp://216.239.34.10:53, udp://216.239.32.10:53, udp://216.239.36.10:53, udp://216.239.38.10:53]
INFO:async_dns.core:[tcp|cache|127.0.0.1|ANY] www.google.com 0 76 

So the first request got a TimeoutError. The second request got a Remote server fail. Then the third got a successful request. The most common behavior I experience when I start up the server is to just get the TimeoutError on every call. Eventually, after the server running for some amount of time, I will have a call that returns the Remote Server Fail, then the rest of the calls work.

I never have any problems resolving a hostname via a utility like nslookup using my normal dns settings. I'm running this in an ubuntu vm.

[gera2ld]

The recursive server query domains recursively from scratch, so it has to send several requests one after another on cache miss, e.g. for www.example.com, first query .com, then example.com, then www.example.com. The whole request times out if the sum of request time is longer than the predefined value (3s). Since there is no cache at the beginning, early requests are likely to time out.

So this issue is the result of a design defect and we don't have much to do right now. One way to mitigate it is to send some requests once server starts and wait for the records of roots and top level domains to be cached.