Receiving non-matching ACKs from server
aramperes opened this issue · 2 comments
aramperes commented
To debug: this happened with blasting concurrent connections on the same port:
INFO onetun > [46668] Incoming connection from 127.0.0.1:34380
TRACE smoltcp::socket::tcp > #0:192.168.4.2:7000: state=CLOSED=>LISTEN
TRACE smoltcp::socket::tcp > #0:192.168.4.16:46668:192.168.4.2:7000: state=CLOSED=>SYN-SENT
TRACE smoltcp::socket::set > [0]: adding
TRACE smoltcp::socket::set > [1]: adding
TRACE smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: outgoing segment will send data or flags
TRACE smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: sending SYN
TRACE smoltcp::socket::tcp > rtte: sampling at seq=SeqNumber(43)
TRACE onetun > [46668] Virtual interface polled some packets to be processed
TRACE onetun::wg > Sending IP packet: IPv4 src=192.168.4.16 dst=192.168.4.2 proto=TCP
\ TCP src=46668 dst=7000 syn seq=42 win=65535 len=0 mss=1380
DEBUG onetun::wg > Sent 84 bytes to WireGuard endpoint (encrypted IP packet)
DEBUG onetun::wg > WireGuard endpoint sent IP packet of 40 bytes
TRACE onetun::wg > Received IP packet: IPv4 src=192.168.4.2 dst=192.168.4.16 proto=TCP
\ TCP src=7000 dst=46668 seq=1769813973 ack=83519 win=750 len=0
TRACE onetun::wg > Dispatched received IP packet to virtual port 46668
DEBUG smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: expecting a SYN|ACK
DEBUG smoltcp::iface::interface > cannot process ingress packet: dropped by socket
DEBUG smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: retransmitting at t+0.701s
TRACE smoltcp::socket::tcp > rtte: abort sampling due to retransmit
TRACE smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: outgoing segment will send data or flags
TRACE smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: sending SYN
TRACE onetun > [46668] Virtual interface polled some packets to be processed
TRACE onetun::wg > Sending IP packet: IPv4 src=192.168.4.16 dst=192.168.4.2 proto=TCP
\ TCP src=46668 dst=7000 syn seq=42 win=65535 len=0 mss=1380
DEBUG onetun::wg > Sent 84 bytes to WireGuard endpoint (encrypted IP packet)
DEBUG onetun::wg > WireGuard endpoint sent IP packet of 40 bytes
TRACE onetun::wg > Received IP packet: IPv4 src=192.168.4.2 dst=192.168.4.16 proto=TCP
\ TCP src=7000 dst=46668 seq=1769813973 ack=83519 win=750 len=0
TRACE onetun::wg > Dispatched received IP packet to virtual port 46668
DEBUG smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: expecting a SYN|ACK
DEBUG smoltcp::iface::interface > cannot process ingress packet: dropped by socket
DEBUG smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: retransmitting at t+0.700s
TRACE smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: outgoing segment will send data or flags
TRACE smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: sending SYN
TRACE onetun > [46668] Virtual interface polled some packets to be processed
TRACE onetun::wg > Sending IP packet: IPv4 src=192.168.4.16 dst=192.168.4.2 proto=TCP
\ TCP src=46668 dst=7000 syn seq=42 win=65535 len=0 mss=1380
DEBUG onetun::wg > Sent 84 bytes to WireGuard endpoint (encrypted IP packet)
DEBUG onetun::wg > WireGuard endpoint sent IP packet of 40 bytes
TRACE onetun::wg > Received IP packet: IPv4 src=192.168.4.2 dst=192.168.4.16 proto=TCP
\ TCP src=7000 dst=46668 seq=1769813973 ack=83519 win=750 len=0
TRACE onetun::wg > Dispatched received IP packet to virtual port 46668
DEBUG smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: expecting a SYN|ACK
DEBUG smoltcp::iface::interface > cannot process ingress packet: dropped by socket
DEBUG smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: retransmitting at t+0.700s
TRACE smoltcp::socket::tcp > rtte: too many retransmissions, increasing: rtt=600 dev=100 rto=1000
TRACE smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: outgoing segment will send data or flags
TRACE smoltcp::socket::tcp > #1:192.168.4.16:46668:192.168.4.2:7000: sending SYN
So for some reason the server is responding to SYN with a random ACK (that has the right ports and all) and the sequence numbers don't match (seq=42 -> ack=83519). Logically that would mean the port 46668 might already be in use by another connection and the packets are being sent to the wrong interface but that shouldn't happen (as far as I can tell, no other connection on that virtual port 46668 had been opened until then).
Likely this: smoltcp-rs/smoltcp#366
aramperes commented
Confirmed to be a bug from smoltcp; it should respond with RST in those cases, and the virtual client should retry connection on the next poll.