starred/hickory-dns

Fork 0

mirror of https://github.com/hickory-dns/hickory-dns.git synced 2026-04-25 03:05:51 +03:00

[GH-ISSUE #2049] Axfr and AxfrStream issues with big zones #862

New issue

Open

opened 2026-03-16 00:37:42 +03:00 by kerem · 3 comments

kerem commented

2026-03-16 00:37:42 +03:00

Owner

Originally created by @darnuria on GitHub (Oct 5, 2023).
Original GitHub issue: https://github.com/hickory-dns/hickory-dns/issues/2049

EDIT: Maybe related to : https://github.com/bluejekyll/trust-dns/issues/351 as pointer by @bluejekyll in discussion.

Hello! Sorry it's a bit messy found it while playing around with Axfr (zone_transfers) parts of the client lib.

Describe the bug

LARGE AXFR (TCP) may triggers unexpected patterns such as ServerTimeout (tested with powerdns) and trigger future_channel mpsc queue full.

(with 30s read_timeout tcp; found the issue with other values but have to recheck)

To Reproduce

Tested out to make an AXFR of a zone with 200 000 records. Why would I do that? Because I wanted to check biggest zone at work with trust-dns.

Expected behavior

Axfr may handle huge zone and not only one per one.

AxfrStream should handle streaming zone fast enough and handle backpressure if the sender is full because the worker at the other side of the channel is slower than the producer.

Did something like a dig-like just axfring for testing out.

System:

OS: Archlinux / linux 6.1
Architecture: x86_64
rustc version: 1.75.0-nightly

Version:
Crate: client Library
Version: 0.23

Additional context
Add any other context about the problem here.

Code

Logs lead me to here for the mpsc full debug:

https://github.com/bluejekyll/trust-dns/blob/4a1c4fe2d1ad7e987ad23de9dbf4c927d84212c1/crates/proto/src/xfer/dns_multiplexer.rs#L402

And bout the zero bytes:

https://github.com/bluejekyll/trust-dns/blob/a7d4184792fc26c41de0f56bb671aa7dd7705b18/crates/proto/src/tcp/tcp_stream.rs#L397

Reproduction code

use std::{net::SocketAddr, time::Duration};

use futures::StreamExt;
use trust_dns_client::{client::ClientHandle, rr::Name, tcp::TcpClientStream};
use trust_dns_proto::{iocompat::AsyncIoTokioAsStd };

use env_logger::Env;

use std::io::Write;

fn main() {
    let env = Env::default()
        .filter_or("RUST_LOG_LEVEL", "TRACE")
        .write_style_or("RUST_LOG_STYLE", "never");

    env_logger::Builder::from_env(env)
        .format_timestamp(None)
        .format(|buf, record| writeln!(buf, "[{}] {}", record.level(), record.args()))
        .init();

    let runtime = tokio::runtime::Builder::new_multi_thread()
        .worker_threads(2)
        .enable_io()
        .enable_time()
        .thread_name("dns-axfr")
        .build()
        .unwrap();
    let ret = runtime.block_on(async {
        let name_server = "127.0.0.1:53560".parse::<SocketAddr>().unwrap();
        let zone_origin =
            Name::from_ascii("absurlylongdomainlongdomainlongdomainbutstilllnotlogenough.fr.")
                .unwrap();
        
        let tcp_timeout = Duration::from_secs(30);
        let dns_timeout = Duration::from_secs(30);
        let (tcp_stream, stream_handle) =
            TcpClientStream::<AsyncIoTokioAsStd<tokio::net::TcpStream>>::with_timeout(
                name_server,
                tcp_timeout,
            );

        let (mut client, xfr_bg) = trust_dns_client::client::AsyncClient::with_timeout(
            tcp_stream,
            stream_handle,
            dns_timeout,
            None,
        )
        .await
        .unwrap();

        let handle = trust_dns_proto::spawn_bg(&runtime, xfr_bg);

        let mut xfr_stream = client.zone_transfer(zone_origin, None);
        // let mut buffer = String::with_capacity(1024);
        while let Some(zone_data) = xfr_stream.next().await {
            let zone_data = zone_data.unwrap();
            let name = zone_data.query().unwrap().name();
            for rr in zone_data.answers() {
                let data = rr.data().unwrap();
                println!("{} {} {}", rr.name(), rr.ttl(), data);
            }
        }
        handle.abort();
        // handle.await; // Cause network timeout but it's an other story
    });
}

Logs

getting:

[...]
[WARN] error notifying wait, possible future leak: TrySendError { kind: Full }
[...]
[DEBUG] reading length 2
[DEBUG] zero bytes read, stream closed?
[DEBUG] error=stream closed stream=TCP(127.0.0.1:53560)
[DEBUG] io_stream is done, shutting down
thread 'main' panicked at /src/main.rs:104:43:
called `Result::unwrap()` on an `Err` value: Error { kind: Proto(ProtoError { kind: Message("stream closed") }) }
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

log server side:

Oct 05 18:38:03 AXFR-out zone 'absurlylongdomainlongdomainlongdomainbutstilllnotlogenough.fr', client '127.0.0.1', transfer initiated
Oct 05 18:38:03 AXFR-out zone 'absurlylongdomainlongdomainlongdomainbutstilllnotlogenough.fr', client '127.0.0.1:47682', allowed: client IP is in allow-axfr-ips
Oct 05 18:38:05 AXFR-out zone 'absurlylongdomainlongdomainlongdomainbutstilllnotlogenough.fr', client '127.0.0.1', done signing: 9190.62 sigs/s, 
Oct 05 18:38:05 AXFR-out zone 'absurlylongdomainlongdomainlongdomainbutstilllnotlogenough.fr', client '127.0.0.1', AXFR finished
Oct 05 18:38:10 TCP Connection Thread died because of network error: Timeout reading data

With prints and debug trace

# after the last record
# Server is on port 53560.
2023-10-05 18:38:19.123320 IP localhost.53560 > localhost.57482: Flags [.], seq 5702414:5767897, ack 95, win 512, options [nop,nop,TS val 2220302904 ecr 2220302899], length 65483 [prefix length(334) != length(65481)] (invalid)
2023-10-05 18:38:19.126117 IP localhost.53560 > localhost.57482: Flags [.], seq 5767897:5833380, ack 95, win 512, options [nop,nop,TS val 2220302907 ecr 2220302899], length 65483 [prefix length(51698) != length(65481)] (invalid)
2023-10-05 18:38:19.149297 IP localhost.57482 > localhost.53560: Flags [.], ack 5833380, win 23439, options [nop,nop,TS val 2220302930 ecr 2220302900], length 0
2023-10-05 18:38:19.149358 IP localhost.53560 > localhost.57482: Flags [P.], seq 5833380:5885201, ack 95, win 512, options [nop,nop,TS val 2220302930 ecr 2220302930], length 51821 [prefix length(26990) != length(51819)] (invalid)
2023-10-05 18:38:19.153466 IP localhost.57482 > localhost.53560: Flags [.], ack 5885201, win 23999, options [nop,nop,TS val 2220302934 ecr 2220302930], length 0

# Checkout the time 5 sec after the last one.
2023-10-05 18:38:24.160561 IP localhost.53560 > localhost.57482: Flags [F.], seq 5885201, ack 95, win 512, options [nop,nop,TS val 2220307941 ecr 2220302934], length 0
2023-10-05 18:38:24.160891 IP localhost.57482 > localhost.53560: Flags [F.], seq 95, ack 5885202, win 23999, options [nop,nop,TS val 2220307942 ecr 2220307941], length 0
2023-10-05 18:38:24.160927 IP localhost.53560 > localhost.57482: Flags [.], ack 96, win 512, options [nop,nop,TS val 2220307942 ecr 2220307942], length 0

Same tcpdump removed the print of the dig-like but kept logging

2023-10-05 18:47:07.263360 IP localhost.54320 > localhost.53560: Flags [.], ack 5858415, win 512, options [nop,nop,TS val 2220831044 ecr 2220831003], length 0
2023-10-05 18:47:07.263406 IP localhost.53560 > localhost.54320: Flags [P.], seq 5858415:5887910, ack 95, win 512, options [nop,nop,TS val 2220831044 ecr 2220831044], length 29495 [prefix length(12184) != length(29493)] (invalid)
2023-10-05 18:47:07.265092 IP localhost.54320 > localhost.53560: Flags [F.], seq 95, ack 5887910, win 512, options [nop,nop,TS val 2220831046 ecr 2220831044], length 0
2023-10-05 18:47:07.265159 IP localhost.53560 > localhost.54320: Flags [F.], seq 5887910, ack 96, win 512, options [nop,nop,TS val 2220831046 ecr 2220831046], length 0
2023-10-05 18:47:07.265182 IP localhost.54320 > localhost.53560: Flags [.], ack 5887911, win 512, options [nop,nop,TS val 2220831046 ecr 2220831046], length 0

End of TCP dump of dig

2023-10-05 18:44:16.346775 IP localhost.53560 > localhost.34329: Flags [F.], seq 5887505, ack 107, win 512, options [nop,nop,TS val 2220660128 ecr 2220658448], length 0
2023-10-05 18:44:16.390127 IP localhost.34329 > localhost.53560: Flags [.], ack 5887506, win 17151, options [nop,nop,TS val 2220660171 ecr 2220660128], length 0
2023-10-05 18:44:17.457370 IP localhost.34329 > localhost.53560: Flags [F.], seq 107, ack 5887506, win 19544, options [nop,nop,TS val 2220661238 ecr 2220660128], length 0
2023-10-05 18:44:17.457384 IP localhost.53560 > localhost.34329: Flags [.], ack 108, win 512, options [nop,nop,TS val 2220661238 ecr 2220661238], length 0

Originally created by @darnuria on GitHub (Oct 5, 2023). Original GitHub issue: https://github.com/hickory-dns/hickory-dns/issues/2049 EDIT: **Maybe related to** : https://github.com/bluejekyll/trust-dns/issues/351 as pointer by @bluejekyll in discussion. Hello! Sorry it's a bit messy found it while playing around with Axfr (zone_transfers) parts of the client lib. **Describe the bug** LARGE AXFR (TCP) may triggers unexpected patterns such as ServerTimeout (tested with powerdns) and trigger `future_channel` mpsc queue full. (with 30s read_timeout tcp; found the issue with other values but have to recheck) **To Reproduce** Tested out to make an AXFR of a zone with 200 000 records. Why would I do that? Because I wanted to check biggest zone at work with trust-dns. **Expected behavior** Axfr may handle huge zone and not only one per one. AxfrStream should handle streaming zone fast enough and handle backpressure if the sender is full because the worker at the other side of the channel is slower than the producer. Did something like a dig-like just axfring for testing out. **System:** - OS: Archlinux / linux 6.1 - Architecture: x86_64 - rustc version: 1.75.0-nightly **Version:** Crate: client Library Version: 0.23 **Additional context** Add any other context about the problem here. ## Code Logs lead me to here for the mpsc full debug: <https://github.com/bluejekyll/trust-dns/blob/4a1c4fe2d1ad7e987ad23de9dbf4c927d84212c1/crates/proto/src/xfer/dns_multiplexer.rs#L402> And bout the zero bytes: <https://github.com/bluejekyll/trust-dns/blob/a7d4184792fc26c41de0f56bb671aa7dd7705b18/crates/proto/src/tcp/tcp_stream.rs#L397> ## Reproduction code ```rust use std::{net::SocketAddr, time::Duration}; use futures::StreamExt; use trust_dns_client::{client::ClientHandle, rr::Name, tcp::TcpClientStream}; use trust_dns_proto::{iocompat::AsyncIoTokioAsStd }; use env_logger::Env; use std::io::Write; fn main() { let env = Env::default() .filter_or("RUST_LOG_LEVEL", "TRACE") .write_style_or("RUST_LOG_STYLE", "never"); env_logger::Builder::from_env(env) .format_timestamp(None) .format(|buf, record| writeln!(buf, "[{}] {}", record.level(), record.args())) .init(); let runtime = tokio::runtime::Builder::new_multi_thread() .worker_threads(2) .enable_io() .enable_time() .thread_name("dns-axfr") .build() .unwrap(); let ret = runtime.block_on(async { let name_server = "127.0.0.1:53560".parse::<SocketAddr>().unwrap(); let zone_origin = Name::from_ascii("absurlylongdomainlongdomainlongdomainbutstilllnotlogenough.fr.") .unwrap(); let tcp_timeout = Duration::from_secs(30); let dns_timeout = Duration::from_secs(30); let (tcp_stream, stream_handle) = TcpClientStream::<AsyncIoTokioAsStd<tokio::net::TcpStream>>::with_timeout( name_server, tcp_timeout, ); let (mut client, xfr_bg) = trust_dns_client::client::AsyncClient::with_timeout( tcp_stream, stream_handle, dns_timeout, None, ) .await .unwrap(); let handle = trust_dns_proto::spawn_bg(&runtime, xfr_bg); let mut xfr_stream = client.zone_transfer(zone_origin, None); // let mut buffer = String::with_capacity(1024); while let Some(zone_data) = xfr_stream.next().await { let zone_data = zone_data.unwrap(); let name = zone_data.query().unwrap().name(); for rr in zone_data.answers() { let data = rr.data().unwrap(); println!("{} {} {}", rr.name(), rr.ttl(), data); } } handle.abort(); // handle.await; // Cause network timeout but it's an other story }); } ``` ## Logs getting: ``` [...] [WARN] error notifying wait, possible future leak: TrySendError { kind: Full } [...] [DEBUG] reading length 2 [DEBUG] zero bytes read, stream closed? [DEBUG] error=stream closed stream=TCP(127.0.0.1:53560) [DEBUG] io_stream is done, shutting down thread 'main' panicked at /src/main.rs:104:43: called `Result::unwrap()` on an `Err` value: Error { kind: Proto(ProtoError { kind: Message("stream closed") }) } note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace ``` log server side: ```log Oct 05 18:38:03 AXFR-out zone 'absurlylongdomainlongdomainlongdomainbutstilllnotlogenough.fr', client '127.0.0.1', transfer initiated Oct 05 18:38:03 AXFR-out zone 'absurlylongdomainlongdomainlongdomainbutstilllnotlogenough.fr', client '127.0.0.1:47682', allowed: client IP is in allow-axfr-ips Oct 05 18:38:05 AXFR-out zone 'absurlylongdomainlongdomainlongdomainbutstilllnotlogenough.fr', client '127.0.0.1', done signing: 9190.62 sigs/s, Oct 05 18:38:05 AXFR-out zone 'absurlylongdomainlongdomainlongdomainbutstilllnotlogenough.fr', client '127.0.0.1', AXFR finished Oct 05 18:38:10 TCP Connection Thread died because of network error: Timeout reading data ``` With prints and debug trace ```tcpdump # after the last record # Server is on port 53560. 2023-10-05 18:38:19.123320 IP localhost.53560 > localhost.57482: Flags [.], seq 5702414:5767897, ack 95, win 512, options [nop,nop,TS val 2220302904 ecr 2220302899], length 65483 [prefix length(334) != length(65481)] (invalid) 2023-10-05 18:38:19.126117 IP localhost.53560 > localhost.57482: Flags [.], seq 5767897:5833380, ack 95, win 512, options [nop,nop,TS val 2220302907 ecr 2220302899], length 65483 [prefix length(51698) != length(65481)] (invalid) 2023-10-05 18:38:19.149297 IP localhost.57482 > localhost.53560: Flags [.], ack 5833380, win 23439, options [nop,nop,TS val 2220302930 ecr 2220302900], length 0 2023-10-05 18:38:19.149358 IP localhost.53560 > localhost.57482: Flags [P.], seq 5833380:5885201, ack 95, win 512, options [nop,nop,TS val 2220302930 ecr 2220302930], length 51821 [prefix length(26990) != length(51819)] (invalid) 2023-10-05 18:38:19.153466 IP localhost.57482 > localhost.53560: Flags [.], ack 5885201, win 23999, options [nop,nop,TS val 2220302934 ecr 2220302930], length 0 # Checkout the time 5 sec after the last one. 2023-10-05 18:38:24.160561 IP localhost.53560 > localhost.57482: Flags [F.], seq 5885201, ack 95, win 512, options [nop,nop,TS val 2220307941 ecr 2220302934], length 0 2023-10-05 18:38:24.160891 IP localhost.57482 > localhost.53560: Flags [F.], seq 95, ack 5885202, win 23999, options [nop,nop,TS val 2220307942 ecr 2220307941], length 0 2023-10-05 18:38:24.160927 IP localhost.53560 > localhost.57482: Flags [.], ack 96, win 512, options [nop,nop,TS val 2220307942 ecr 2220307942], length 0 ``` Same tcpdump removed the print of the dig-like but kept logging ``` 2023-10-05 18:47:07.263360 IP localhost.54320 > localhost.53560: Flags [.], ack 5858415, win 512, options [nop,nop,TS val 2220831044 ecr 2220831003], length 0 2023-10-05 18:47:07.263406 IP localhost.53560 > localhost.54320: Flags [P.], seq 5858415:5887910, ack 95, win 512, options [nop,nop,TS val 2220831044 ecr 2220831044], length 29495 [prefix length(12184) != length(29493)] (invalid) 2023-10-05 18:47:07.265092 IP localhost.54320 > localhost.53560: Flags [F.], seq 95, ack 5887910, win 512, options [nop,nop,TS val 2220831046 ecr 2220831044], length 0 2023-10-05 18:47:07.265159 IP localhost.53560 > localhost.54320: Flags [F.], seq 5887910, ack 96, win 512, options [nop,nop,TS val 2220831046 ecr 2220831046], length 0 2023-10-05 18:47:07.265182 IP localhost.54320 > localhost.53560: Flags [.], ack 5887911, win 512, options [nop,nop,TS val 2220831046 ecr 2220831046], length 0 ``` End of TCP dump of dig ``` 2023-10-05 18:44:16.346775 IP localhost.53560 > localhost.34329: Flags [F.], seq 5887505, ack 107, win 512, options [nop,nop,TS val 2220660128 ecr 2220658448], length 0 2023-10-05 18:44:16.390127 IP localhost.34329 > localhost.53560: Flags [.], ack 5887506, win 17151, options [nop,nop,TS val 2220660171 ecr 2220660128], length 0 2023-10-05 18:44:17.457370 IP localhost.34329 > localhost.53560: Flags [F.], seq 107, ack 5887506, win 19544, options [nop,nop,TS val 2220661238 ecr 2220660128], length 0 2023-10-05 18:44:17.457384 IP localhost.53560 > localhost.34329: Flags [.], ack 108, win 512, options [nop,nop,TS val 2220661238 ecr 2220661238], length 0 ```

kerem added the

perf

crate:server

compliance

labels

2026-03-16 00:37:42 +03:00

kerem commented

2026-03-16 00:37:54 +03:00

Author

Owner

@bluejekyll commented on GitHub (Oct 5, 2023):

Yes, this is a known issue, I think it’s the same as reported here #351

@bluejekyll commented on GitHub (Oct 5, 2023): Yes, this is a known issue, I think it’s the same as reported here #351

kerem commented

2026-03-16 00:37:59 +03:00

Author

Owner

@darnuria commented on GitHub (Oct 6, 2023):

Oh thanks did a quick search about AXFR and stream and issue and didn't find out, was already late in Europe. Feel free to close I can report the info you think are useful there. :)

EDIT: Will try to spend some time reading carefully the other issue to checkout if it's really the same or if it add some info. Cannot promise to do it today but next-week I can try if you think it's worth it.

@darnuria commented on GitHub (Oct 6, 2023): Oh thanks did a quick search about AXFR and stream and issue and didn't find out, was already late in Europe. Feel free to close I can report the info you think are useful there. :) EDIT: Will try to spend some time reading carefully the other issue to checkout if it's really the same or if it add some info. Cannot promise to do it today but next-week I can try if you think it's worth it.

kerem commented

2026-03-16 00:38:04 +03:00

Author

Owner

@bluejekyll commented on GitHub (Oct 6, 2023):

A quick synopsis on this, I think to fix this we need to change or add a new method into the Authority/Catalog for this operation to properly work. Right now, if I remember correctly, we return the entire zone in a single call and then stream that back. That's bad for large zones. What we need is a continuation call, like get first 0..N record, get next N..(N + N) records, etc. That would allow us to properly stream back an entire very large zone.

We also probably have some other deficiencies that we will need to take care of as well, for example, we really need an on disk option for zone lookups and not store them entirely in memory. I think there might be an old issue for that.

@bluejekyll commented on GitHub (Oct 6, 2023): A quick synopsis on this, I think to fix this we need to change or add a new method into the Authority/Catalog for this operation to properly work. Right now, if I remember correctly, we return the entire zone in a single call and then stream that back. That's bad for large zones. What we need is a continuation call, like get first 0..N record, get next N..(N + N) records, etc. That would allow us to properly stream back an entire very large zone. We also probably have some other deficiencies that we will need to take care of as well, for example, we really need an on disk option for zone lookups and not store them entirely in memory. I think there might be an old issue for that.

kerem referenced this issue

2026-03-16 02:23:18 +03:00

[PR #862] [CLOSED] Bump chrono from 0.4.7 to 0.4.8 #1748