Formerly we sent twice on pollChan, but because it was unbuffered, the
second send was almost always dropped. KCP's own ACK packets should also
serve as another source of what are effectively polling queries at a
rate proportional to the rate at which we are receiving.
I did some performance tests of downloading 10 MiB between two servers
with 100 ms RTT between them. Server:
dnstt-server -udp :53 -privkey-file server.key t.example.com 127.0.0.1:9321
ncat -l -k -v 9321 --send-only --sh-exec 'dd bs=1M count=10 if=/dev/urandom'
Client:
dnstt-client -pubkey-file server.pub t.example.com 127.0.0.1:7000
ncat --recv-only 127.0.0.1 7000 | pv -t -r -a -b -i 0.2 > /dev/null
I did the download under every treatment twice and recorded the download
rate in KiB/s.
First, the results for the commit before this one. I also hacked in
fewer sends on pollChan for each packet received. The result for 1 poll
are about the same as for 2 polls, which is expected, with the
observation that the unbuffered pollChan was usually dropping the second
send. 0 polls results in a very slow rate (possibly driven only by smux
keepalive packets). ("~" means I stopped waiting for the download after
about 2 minutes.)
resolver method pollChan cap SetACKNoDelay polls KiB/s KiB/s
-------- ------ ------------ ------------- ----- ----- -----
direct udp unbuffered false 2 146 159 (status quo before this commit)
dns.google udp unbuffered false 2 58.3 60.2 (status quo before this commit)
dns.google doh unbuffered false 2 125 126 (status quo before this commit)
direct udp unbuffered false 1 155 165
dns.google udp unbuffered false 1 57.5 58.7
dns.google doh unbuffered false 1 124 123
direct udp unbuffered false 0 ~7 ~11
dns.google udp unbuffered false 0 ~6 ~5
dns.google doh unbuffered false 0 ~6 ~6
Now, the result after this commit. A buffered pollChan with 1 poll per
receive has almost identical performance to an unbuffered pollChan with
1 or 2 polls per receive, which is expected. Using 2 polls rather than 1
actually helps performance a fair bit in the direct/UDP and Google/UDP
treatments, but hurts performance in the Google/DoH treatment. 0 polls
still yields poor performance.
resolver method pollChan cap SetACKNoDelay polls KiB/s KiB/s
-------- ------ ------------ ------------- ----- ----- -----
direct udp 16 false 2 174 175
dns.google udp 16 false 2 76.0 75.3
dns.google doh 16 false 2 68.7 68.0
direct udp 16 false 1 149 151 (this commit)
dns.google udp 16 false 1 60.2 60.3 (this commit)
dns.google doh 16 false 1 123 121 (this commit)
direct udp 16 false 0 ~7 ~8
dns.google udp 16 false 0 ~5 ~5
dns.google doh 16 false 0 ~6 ~7
I tried the additional modification of calling conn.SetACKNoDelay(true).
My guess was that this would cause every received data packet to be
ACKed immediately, which should have the same function as a poll.
Unexpectedly for me, SetACKNoDelay(true) actually slows down the
direct/UDP and Google/DoH cases a lot. But strangely, Google/UDP becomes
faster (and 1 poll is even faster than 2 polls in that case). Strangest
of all, SetACKNoDelay(true) makes the 0-poll Google/UDP and Google/DoH
treatments run reasonably fast. My best guess as to why that is the case
is that routing through a Google resolver tends to disorder the packet
sequence, which maybe results in more ACKs, which effectively act as
polls.
resolver method pollChan cap SetACKNoDelay polls KiB/s KiB/s
-------- ------ ------------ ------------- ----- ----- -----
direct udp 16 true 2 87.7 84.2
dns.google udp 16 true 2 82.7 68.9
dns.google doh 16 true 2 59.8 60.8
direct udp 16 true 1 54.1 47.8
dns.google udp 16 true 1 97.5 100
dns.google doh 16 true 1 71.4 70.9
direct udp 16 true 0 ~9 ~8
dns.google udp 16 true 0 48.0 48.6
dns.google doh 16 true 0 59.2 59.2
In my testing locally, specifying -dot with a non-responsive TCP port
would time out after about 30 seconds anyway:
$ time ./dnstt-client -dot tns.example.com:8000 -pubkey-file server.pub t.example.com 127.0.0.1:7000
dial tcp 45.79.134.119:8000: connect: connection timed out
real 0m31.398s
user 0m0.006s
sys 0m0.003s
Which is in line with the documentation for net.Dialer:
https://golang.org/pkg/net/#Dialer
With or without a timeout, the operating system may impose its
own earlier timeout. For instance, TCP timeouts are often around
3 minutes.
But may as well be explicit.
This commit has the side effect of changing the error message from
"connection timed out" to "i/o timeout".
$ time ./dnstt-client -dot tns.example.com:8000 -pubkey-file server.pub t.example.com 127.0.0.1:7000
dial tcp 45.79.134.119:8000: i/o timeout
real 0m30.007s
user 0m0.003s
sys 0m0.007s
I tried setting the dialTimeout to 40 seconds, and in that case the
system timeout take precedence after ≈31 seconds, with the "connection
timed out" error as before.
This is issue UCB-02-007 from the 2021 security audit of Turbo Tunnel by
Cure53.
The audit report additionally recommends calling SetReadDeadline before
each read operation. I have chosen not to do that. It is intended that
the TLS connection should be able to remain idle if there is nothing to
send. As DNS is a query–response protocol, one might expect a response
(and within a certain amount of time) only after sending a query;
sendLoop could refresh the ReadDeadline for recvLoop every time it sends
a query. But a malicious DoT server could keep a useless connection
alive anyway by sending Slowloris-style short responses within each
deadline, and an external adversary could capable of delaying responses
could deny service indefinitely or simply block the server. In any case,
the smux KeepAliveTimeout serves as a check that prevents stalled
connections from remaining indefinitely.
In my testing locally, these dials would time out after about 30 seconds
anyway:
2021/04/20 23:26:46 begin session 54cafb53
2021/04/20 23:26:47 begin stream 54cafb53:3
2021/04/20 23:27:19 stream 54cafb53:3 handleStream: stream 54cafb53:3 connect upstream: dial tcp X.X.X.X:YYYY: connect: connection timed out
2021/04/20 23:27:19 end stream 54cafb53:3
Which is in line with the documentation for net.Dialer:
https://golang.org/pkg/net/#Dialer
With or without a timeout, the operating system may impose its
own earlier timeout. For instance, TCP timeouts are often around
3 minutes.
But may as well be explicit.
This commit has the side effect of changing the error message from
"connection timed out" to "i/o timeout".
2021/04/20 23:28:08 begin session 05b0a46e
2021/04/20 23:28:09 begin stream 05b0a46e:3
2021/04/20 23:28:39 stream 05b0a46e:3 handleStream: stream 05b0a46e:3 connect upstream: dial tcp X.X.X.X:YYYY: i/o timeout
2021/04/20 23:28:39 end stream 05b0a46e:3
The usual use case for upstream is that it is a localhost IP address and
port, but it may also be a hostname and port. net.DialTCP resolves the
hostname once and for all, and only uses one of the hostname's IP
addresses if there are more than one. net.Dial will try all the IP
addresses in turn until it is able to establish a connection.
Now upstream is kept as a string variable all the way through the call
chain. For the sake of usability, we try resolving the address with
net.ResolveTCPAddr in main, to emit an error or warning right away,
rather than deferring it to the first stream.
Recent versions of go (at least go1.14) automatically add a `go` line to
go.mod with every command, such as `go build`. Adding one here so that
builds don't wind up changing a versioned file. There doesn't seem to be
much importance to what number goes here
(https://utcc.utoronto.ca/~cks/space/blog/programming/GoModulesGoVersions).
I've just verified that the programs build with go1.11.
This log line would formerly be emitted for a query with 0 questions:
FORMERR: too many questions (0)
The Nmap DNSStatusRequest probe is a query with 0 questions.
There was a logic error in the code. The nextP variable was used to
store the packet that was too big to pack into the most recent DNS
response. But nextP was not tied to any particular ClientID; instead it
would be sent to whatever client happened to be the recipient of the
next response.
The confusion didn't cause connections to fail completely; any
misdirected packets were treated as out-of-sequence garbage by KCP and
dropped. But it hurt performance a lot: I saw a download go from 300
KB/s to 50 KB/s just by connecting a second client with a different
ClientID (not even sending or receiving with the second client). The
reason is that a fraction of the packets intended for the downloading
client were instead sent to the idle client, which to the downloading
client looks like a packet drop, requiring a retransmission by the
server.
We fix it by placing the leftover packet in a per-ClientID stash, rather
than a variable shared by all ClientIDs.
I want a way to "unread" a packet from an send queue, in the case where
I'm packing packets into a fixed space and don't know when I'm done
until I've read one too many packets. There's no way to insert the extra
packet at the head of the cannel representing the send queue, so that it
will be the next thing received from OutgoingQueue. Instead, add an
separate one-element queue called the stash. The caller can stash an
excess packet, then prioritize checking it in the next round by calling
Unstash before OutgoingQueue.
I don't know what I was thinking in
f1ee951fd6. The way it was written, if
there were not immediately additional packets to pack into the
downstream, it would stop trying to pack and would instead wait until
the maxResponseDelay or another response to send. What I meant is that
the timer and the next-response channel should have priority, if either
of those is true *and* there is additional downstream available to pack.
Only when both of those are false should we try to pack downstream data.
The server would log "NXDOMAIN: 0 bytes are too short to contain a
ClientID" even in the common cases where it got an A or NS query from
the resolver (possibly from QNAME minimization).
David Fifield