...and adjust the `totalFailedConnections` metric name
and description.
This commit should make the periodic stats log messages
and the relevant metric look less scary to users:
P2P connection failures are relatively frequent and are usually
not indicative of the proxy operator having done something wrong.
So let's tone the wording down.
See the discussion: https://gitlab.torproject.org/tpo/anti-censorship/pluggable-transports/snowflake/-/merge_requests/516#note_3173677.
This migrates from using `atomic.LoadInt64` on `int64`
to making the `clients` field itself `atomic.Int64`.
Also `count` now takes `*tokens_t` by reference,
which fixes a linter warning.
It's not clear to me why it warned about this,
but I simplified it anyway.
And `failedConnectionCount`.
Convert the `int` / `uint` to `atomic.Int32` / `atomic.Uint32`.
The race was discovered by running a proxy with the `-race` flag.
Some of the changes do not appear to have a potential race condition,
so there it is purely a refactor,
while in others (e.g. in broker.go and in proxy/lib/snowflake.go)
we do use the same variable from multiple threads / functions.
For the summary log and for Prometheus metrics.
Log output example:
> In the last 1h0m0s, there were 7 completed successful connections. 2 connections failed. Traffic Relayed ↓ 321 KB (0.10 KB/s), ↑ 123 KB (0.05 KB/s).
After !414, we started returning a nil offer from pollOffer if the proxy
was not matched with a client. It's not longer an indication of failure,
so we should remove the "bad offer from broker" log message.
Introduces the option `-log-local-time` which switches to local time
for logging instead of using UTC. Also if this option is applied, a message
is being output to the log on startup about the usage of local time
to draw attention, so the user/operator can take care of anonymity in case
the logs are going to be shared.
Though prior to this change the panic could only happen
if the default relayURL set by the proxy is invalid,
since `datachannelHandler` is only called after a succesful
`checkIsRelayURLAcceptable()`, which ensures that it _is_ valid.
But in the case of invalid default relay URL, a warning is printed
already.
...by default.
This is useful when `RelayDomainNamePattern` is lax (e.g. just "$")
(which is not the case by default, so this is simply
a hardening measure).
TL;DR: The current implementation uses a 32K buffer size for a total of 64K of
buffers/connection, but each read/write is less than 2K according to my measurements.
# Background
The Snwoflake proxy uses as particularly hot function `copyLoop`
(proxy/lib/snowflake.go) to proxy data from a Tor relay to a connected client.
This is currently done using the `io.Copy` function to write all incoming data
both ways.
Looking at the `io.Copy` implementation, it internally uses `io.CopyBuffer`,
which in turn defaults to a buffer of size 32K for copying data (I checked and
the current implementation uses 32K every time).
Since `snowflake-proxy` is intended to be run in a very distributed manner, on
as many machines as possible, minimizing the CPU and memory footprint of each
proxied connection would be ideal, as well as maximising throughput for
clients.
# Hypothesis
There might exist a buffer size `X` that is more suitable for usage in `copyLoop` than 32K.
# Testing
## Using tcpdump
Assuming you use `-ephemeral-ports-range 50000:51000` for `snowflake-proxy`,
you can capture the UDP packets being proxied using
```sh
sudo tcpdump -i <interface> udp portrange 50000-51000
```
which will provide a `length` value for each packet captured. One good start
value for `X` could then be slighly larger than the largest captured packet,
assuming one packet is copied at a time.
Experimentally I found this value to be 1265 bytes, which would make `X = 2K` a
possible starting point.
## Printing actual read
The following snippe was added in `proxy/lib/snowflake.go`:
```go
// Taken straight from standardlib io.copyBuffer
func copyBuffer(dst io.Writer, src io.Reader, buf []byte) (written int64, err error) {
// If the reader has a WriteTo method, use it to do the copy.
// Avoids an allocation and a copy.
if wt, ok := src.(io.WriterTo); ok {
return wt.WriteTo(dst)
}
// Similarly, if the writer has a ReadFrom method, use it to do the copy.
if rt, ok := dst.(io.ReaderFrom); ok {
return rt.ReadFrom(src)
}
if buf == nil {
size := 32 * 1024
if l, ok := src.(*io.LimitedReader); ok && int64(size) > l.N {
if l.N < 1 {
size = 1
} else {
size = int(l.N)
}
}
buf = make([]byte, size)
}
for {
nr, er := src.Read(buf)
if nr > 0 {
log.Printf("Read %d", nr) // THIS IS THE ONLY DIFFERENCE FROM io.CopyBuffer
nw, ew := dst.Write(buf[0:nr])
if nw < 0 || nr < nw {
nw = 0
if ew == nil {
ew = errors.New("invalid write result")
}
}
written += int64(nw)
if ew != nil {
err = ew
break
}
if nr != nw {
err = io.ErrShortWrite
break
}
}
if er != nil {
if er != io.EOF {
err = er
}
break
}
}
return written, err
}
```
and `copyLoop` was amended to use this instead of `io.Copy`.
The `Read: BYTES` was saved to a file using this command
```sh
./proxy -verbose -ephemeral-ports-range 50000:50010 2>&1 >/dev/null | awk '/Read: / { print $4 }' | tee read_sizes.txt
```
I got the result:
min: 8
max: 1402
median: 1402
average: 910.305
Suggested buffer size: 2K
Current buffer size: 32768 (32K, experimentally verified)
## Using a Snowflake Proxy in Tor browser and use Wireshark
I also used Wireshark, and concluded that all packets sent was < 2K.
# Conclusion
As per the commit I suggest changing the buffer size to 2K. Some things I have not been able to answer:
1. Does this make a big impact on performance?
1. Are there any unforseen consequences? What happens if a packet is > 2K (I
think the Go standard libary just splits the packet, but someone please confirm).
