[Bug] Single DMARC query can take as long as 8 minutes

[d33tah]

Describe the bug

echo _dmarc.ycskd.net | zdns txt took way longer than one could infer from the help screen

To Reproduce

• The version of ZDNS: (main HEAD, release v.X.X.X, etc)

• CLI command ZDNS was run with

echo _dmarc.ycskd.net | time zdns txt \
            --iteration-timeout 6 \
            --iterative \
            --tcp-only \
            --verbosity=5 \
            --conf-file /tmp/zdns.conf 2>&1 | tee /dev/stderr | gzip > /tmp/zdns-debug.log.gz

zdns-debug.log.gz

zdns.conf contained:

nameserver 1.1.1.1

Expected behavior

The command finishes within... 20 seconds? I don't know what's the sensible default timeout, given those options:

> zdns --help 2>&1 | rg timeout
      --iteration-timeout=     timeout for a single iterative step in an iterative query, in seconds. Only applicable with --iterative (default: 8)
      --network-timeout=       timeout for round trip network operations, in seconds (default: 2)
      --retries=               how many times should zdns retry query against a new nameserver if timeout or temporary failure (default: 3)
      --timeout=               timeout for resolving a individual name, in seconds (default: 20)

Additional context

I attach the log.

[d33tah]

Actually, _dmarc.arcstarmusic.com seems to be an even better example. It takes eight minutes to finish:

00h:07m:49s; 0 names scanned; 0.00 names/sec; NaN% success rate; 
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 06:                        [Cycling lookup failed - out of retries. Name:  contact-us-at.edoms.biz , Layer:  edoms.biz , Nameserver:  70.32.1.32:53]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 06:                        [-> error occurred during lookup]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 06:                        [--> Iterative resolution of  contact-us-at.edoms.biz  at  70.32.1.32:53  Failed:  ERROR]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 06:                        [--> No more authorities to try for name  contact-us-at.edoms.biz , terminating]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 05:                    [--> Iterative resolution of  contact-us-at.edoms.biz  at  37.209.194.13:53  Failed:  SERVFAIL]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 04:                [Trying Authority:  {172800 NS 2 IN 1 biz y.gtld.biz.}]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 04:                [Output from extract authorities:  37.209.196.13:53]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 05:                    [Cached retrying lookup. Name:  {1 1 contact-us-at.edoms.biz} , Layer:  biz , Nameserver:  37.209.196.13:53]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 06:                        [Cache request for:  contact-us-at.edoms.biz  ( 1 )]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 07:                            [-> no entry found in cache for  contact-us-at.edoms.biz]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 06:                        [Cache auth check for  edoms.biz]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 07:                            [Cache authority request for:  edoms.biz  ( 2 )]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 08:                                [Cache hit for  edoms.biz :  {[] [{3600 A 1 IN 1 contact-us-at.edoms.biz 70.32.1.32} {3600 A 1 IN 1 contact-us-at.edoms.biz 103.224.182.5} {3600 A 1 IN 1 contact-us-at.edoms.biz 103.224.182.6} {3600 A 1 IN 1 contact-us-at.edoms.biz 103.224.182.9} {3600 A 1 IN 1 contact-us-at.edoms.biz 103.224.182.71} {3600 A 1 IN 1 contact-us-at.edoms.biz 103.224.212.5} {3600 A 1 IN 1 contact-us-at.edoms.biz 103.224.212.9} {3600 A 1 IN 1 contact-us-at.edoms.biz 170.178.168.203} {3600 A 1 IN 1 domain-may-be-for-sale-at.edoms.biz 70.32.1.32} {3600 A 1 IN 1 domain-may-be-for-sale-at.edoms.biz 103.224.182.5} {3600 A 1 IN 1 domain-may-be-for-sale-at.edoms.biz 103.224.182.6} {3600 A 1 IN 1 domain-may-be-for-sale-at.edoms.biz 103.224.182.9} {3600 A 1 IN 1 domain-may-be-for-sale-at.edoms.biz 103.224.182.70} {3600 A 1 IN 1 domain-may-be-for-sale-at.edoms.biz 103.224.212.5} {3600 A 1 IN 1 domain-may-be-for-sale-at.edoms.biz 103.224.212.6} {3600 A 1 IN 1 domain-may-be-for-sale-at.edoms.biz 103.224.212.9} {3600 A 1 IN 1 domain-may-be-for-sale-at.edoms.biz 170.178.168.203}] [{3600 NS 2 IN 1 edoms.biz contact-us-at.edoms.biz.} {3600 NS 2 IN 1 edoms.biz domain-may-be-for-sale-at.edoms.biz.}]   {true 0 false false false false false false 0} <nil> <nil>}]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 06:                        [Cache auth hit for  edoms.biz]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 05:                    [Cycling lookup successful. Name:  contact-us-at.edoms.biz , Layer:  biz , Nameserver:  37.209.196.13:53]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 05:                    [-> Authority found, iterating]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 05:                    [Trying Authority:  {3600 NS 2 IN 1 edoms.biz domain-may-be-for-sale-at.edoms.biz.}]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 05:                    [Output from extract authorities:  70.32.1.32:53]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 06:                        [Cached retrying lookup. Name:  {1 1 contact-us-at.edoms.biz} , Layer:  edoms.biz , Nameserver:  70.32.1.32:53]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 07:                            [Cache request for:  contact-us-at.edoms.biz  ( 1 )]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 08:                                [-> no entry found in cache for  contact-us-at.edoms.biz]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 07:                            [Cache auth check for  contact-us-at.edoms.biz]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 08:                                [Cache authority request for:  contact-us-at.edoms.biz  ( 2 )]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 09:                                    [-> no entry found in cache for  contact-us-at.edoms.biz]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 07:                            [Cache miss for  {1 1 contact-us-at.edoms.biz} , Layer:  edoms.biz , Nameserver:  70.32.1.32:53  going to the wire in retryingLookup]"
time="2025-02-28T12:00:40+01:00" level=debug msg="DEPTH 05:                    [****WIRE LOOKUP***  tcp   A   contact-us-at.edoms.biz   70.32.1.32:53]"
00h:07m:50s; 0 names scanned; 0.00 names/sec; NaN% success rate; 
time="2025-02-28T12:00:41+01:00" level=debug msg="DEPTH 06:                        [Cycling lookup failed - out of retries. Name:  contact-us-at.edoms.biz , Layer:  edoms.biz , Nameserver:  70.32.1.32:53]"
time="2025-02-28T12:00:41+01:00" level=debug msg="DEPTH 06:                        [-> error occurred during lookup]"
time="2025-02-28T12:00:41+01:00" level=debug msg="DEPTH 06:                        [--> Iterative resolution of  contact-us-at.edoms.biz  at  70.32.1.32:53  Failed:  ERROR]"
time="2025-02-28T12:00:41+01:00" level=debug msg="DEPTH 05:                    [Trying Authority:  {3600 NS 2 IN 1 edoms.biz contact-us-at.edoms.biz.}]"
time="2025-02-28T12:00:41+01:00" level=debug msg="DEPTH 05:                    [Output from extract authorities:  70.32.1.32:53]"
time="2025-02-28T12:00:41+01:00" level=debug msg="DEPTH 06:                        [Cached retrying lookup. Name:  {1 1 contact-us-at.edoms.biz} , Layer:  edoms.biz , Nameserver:  70.32.1.32:53]"
time="2025-02-28T12:00:41+01:00" level=debug msg="DEPTH 07:                            [Cache request for:  contact-us-at.edoms.biz  ( 1 )]"
time="2025-02-28T12:00:41+01:00" level=debug msg="DEPTH 08:                                [-> no entry found in cache for  contact-us-at.edoms.biz]"
time="2025-02-28T12:00:41+01:00" level=debug msg="DEPTH 07:                            [Cache auth check for  contact-us-at.edoms.biz]"
time="2025-02-28T12:00:41+01:00" level=debug msg="DEPTH 08:                                [Cache authority request for:  contact-us-at.edoms.biz  ( 2 )]"
time="2025-02-28T12:00:41+01:00" level=debug msg="DEPTH 09:                                    [-> no entry found in cache for  contact-us-at.edoms.biz]"
time="2025-02-28T12:00:41+01:00" level=debug msg="DEPTH 07:                            [Cache miss for  {1 1 contact-us-at.edoms.biz} , Layer:  edoms.biz , Nameserver:  70.32.1.32:53  going to the wire in retryingLookup]"
time="2025-02-28T12:00:41+01:00" level=debug msg="DEPTH 05:                    [****WIRE LOOKUP***  tcp   A   contact-us-at.edoms.biz   70.32.1.32:53]"
00h:07m:51s; 0 names scanned; 0.00 names/sec; NaN% success rate; 
time="2025-02-28T12:00:43+01:00" level=debug msg="DEPTH 06:                        [Cycling lookup failed - out of retries. Name:  contact-us-at.edoms.biz , Layer:  edoms.biz , Nameserver:  70.32.1.32:53]"
time="2025-02-28T12:00:43+01:00" level=debug msg="DEPTH 06:                        [-> error occurred during lookup]"
time="2025-02-28T12:00:43+01:00" level=debug msg="DEPTH 06:                        [--> Iterative resolution of  contact-us-at.edoms.biz  at  70.32.1.32:53  Failed:  ERROR]"
time="2025-02-28T12:00:43+01:00" level=debug msg="DEPTH 06:                        [--> No more authorities to try for name  contact-us-at.edoms.biz , terminating]"
time="2025-02-28T12:00:43+01:00" level=debug msg="DEPTH 05:                    [--> Iterative resolution of  contact-us-at.edoms.biz  at  37.209.196.13:53  Failed:  SERVFAIL]"
time="2025-02-28T12:00:43+01:00" level=debug msg="DEPTH 05:                    [--> No more authorities to try for name  contact-us-at.edoms.biz , terminating]"
time="2025-02-28T12:00:43+01:00" level=debug msg="DEPTH 03:            [Output from extract authorities:  ]"
time="2025-02-28T12:00:43+01:00" level=debug msg="DEPTH 04:                [--> Auth find failed for name  _dmarc.arcstarmusic.com  with status:  SERVFAIL]"
time="2025-02-28T12:00:43+01:00" level=debug msg="DEPTH 04:                [--> No more authorities to try for name  _dmarc.arcstarmusic.com , terminating]"
time="2025-02-28T12:00:43+01:00" level=debug msg="DEPTH 03:            [--> Iterative resolution of  _dmarc.arcstarmusic.com  at  192.26.92.30:53  Failed:  SERVFAIL]"
time="2025-02-28T12:00:43+01:00" level=debug msg="DEPTH 03:            [--> No more authorities to try for name  _dmarc.arcstarmusic.com , terminating]"
time="2025-02-28T12:00:43+01:00" level=debug msg="DEPTH 01:    [MIEKG-OUT: following iterative lookup for  _dmarc.arcstarmusic.com  ( 16 ): status:  SERVFAIL  , err:  no valid nameservers found or all lookups failed]"
{"name":"_dmarc.arcstarmusic.com","results":{"TXT":{"data":{"protocol":"","resolver":""},"duration":471.782543868,"error":"no valid nameservers found or all lookups failed","status":"SERVFAIL","timestamp":"2025-02-28T12:00:43+01:00"}}}
00h:07m:51s; Scan Complete; 1 names scanned; 0.00 names/sec; 0.0% success rate; SERVFAIL: 1
zdns txt --iteration-timeout 6 --iterative --tcp-only --verbosity=5   2>&1  0.17s user 0.09s system 0% cpu 7:51.79 total
tee /dev/stderr  0.02s user 0.04s system 0% cpu 7:51.79 total
zstd > /tmp/zdns-debug.log.zst  0.00s user 0.03s system 0% cpu 7:51.79 total

[d33tah]

It seems to be a regression - tag v1.1.0 doesn't seem to have this issue.

[phillip-stephens]

I'm able to reproduce this issue and agree that this should time out at maximum in 20 seconds given the default timeout values. I'll take a look at what's causing this.