Stuck at retransmitting syn

[robko23]

Hi, this might be an error on my side, but it seems weird. I have following code:

...mcu initialization ommited
    info!("Initializing spi");
    let spi = {
        let miso = gpiob.pb14.into_alternate();
        let mosi = gpiob.pb15.into_alternate();
        let sck = gpiob.pb13;

        hal::spi::Spi2::new(dp.SPI2, (sck, miso, mosi), enc28j60::MODE, 1.MHz(), &clocks)
    };
    let mut delay = Timer::delay(Timer::syst(cp.SYST, &clocks));

    info!("Initializing enc28j60 driver");
    let enc28j60 = {
        let mut ncs = gpioa.pa4.into_push_pull_output();
        ncs.set_high();
        let mut reset = gpioa.pa3.into_push_pull_output();
        reset.set_high();

        enc28j60::Enc28j60::new(
            spi,
            ncs,
            enc28j60::Unconnected,
            reset,
            &mut delay,
            7168,
            SRC_MAC,
        )
        .ok()
        .unwrap()
    };

    info!("Initializing smoltcp");
    let mut rx_buf = [0u8; 1024];
    let mut tx_buf = [0u8; 1024];
    let mut eth = Phy::new(enc28j60, &mut rx_buf, &mut tx_buf);

    let local_addr = Ipv4Address::new(192, 168, 128, 131);
    let ip_addr = IpCidr::new(IpAddress::Ipv4(local_addr), 24);

    let mut config = smoltcp::iface::Config::new(HardwareAddress::Ethernet(EthernetAddress(SRC_MAC)));
    config.random_seed = DWT::cycle_count() as u64;
    let mut iface = smoltcp::iface::Interface::new(
        config,
        &mut eth,
        smoltcp::time::Instant::from_micros(DWT::cycle_count()),
    );
    iface.update_ip_addrs(|ipa| {
        ipa.push(ip_addr).unwrap();
    });
    iface
        .routes_mut()
        .add_default_ipv4_route(Ipv4Address::new(192, 168, 128, 1))
        .unwrap();
    info!("smoltcp initialized");
    use smoltcp::socket::tcp;

    let mut tcp_rx_buffer = [0u8; 1500];
    let tcp_rx_buffer = tcp::SocketBuffer::new(&mut tcp_rx_buffer[..]);
    let mut tcp_tx_buffer = [0u8; 1500];
    let tcp_tx_buffer = tcp::SocketBuffer::new(&mut tcp_tx_buffer[..]);
    let tcp_socket = Socket::new(tcp_rx_buffer, tcp_tx_buffer);
    let mut sockets_storage: [_; 1] = Default::default();
    let mut socket_set = SocketSet::new(&mut sockets_storage[..]);

    let handle = socket_set.add(tcp_socket);
    let socket = socket_set.get_mut::<Socket>(handle);

    // socket.set_keep_alive(Some(Duration::from_secs(5)));
    // socket.set_timeout(Some(Duration::from_secs(3)));
    socket
        .connect(
            iface.context(),
            IpEndpoint::new(
                IpAddress::Ipv4(Ipv4Address::new(192, 168, 128, 81)),
                9999,
            ),
            get_ephemeral_port(),
        )
        .unwrap();

    info!("Initialized");
    let mut time: i64 = 0;
    let mut prev_conn_state = false;
    loop {
        time += 1;
        iface.poll(
            smoltcp::time::Instant::from_millis(time),
            &mut eth,
            &mut socket_set,
        );
        let socket = socket_set.get_mut::<Socket>(handle);
        if socket.is_active() && !prev_conn_state {
            info!("connected: {}", socket.state());
        } else if !socket.is_active() && prev_conn_state {
            info!("disconnected");
        }
        prev_conn_state = socket.is_active();

        if socket.may_recv() {
            let can_send = socket.can_send();
            let data = socket
                .recv(|data| {
                    if !data.is_empty() {
                        let str_repr =
                            core::str::from_utf8(data.as_ref()).unwrap_or("(invalid utf8)");
                        info!("recv: {:?} ({})", data, str_repr);
                    }
                    (data.len(), data)
                })
                .unwrap();
            if can_send && !data.is_empty() {
                info!("Sending reply");
                socket.send_slice("Hello world!\n".as_bytes()).unwrap();
            }
        }
        delay.delay_ms(1);
    }

It is basically the "client" example merged with enc28j60 driver. On my computer I have a nc process listening on port 9999. In wireshark, I can see SYN sent to my PC and nc responding with ACK, however, smoltcp is not registering this and is "flooding" my PC with SYN packets. The entire wireshark pcap is here: https://www.mediafire.com/file/fs7g7tffyb917l9/smoltcp.pcap/file (will be deleted on 28/10/23) Here are the logs from the MCU:

INFO  Initializing spi
INFO  Initializing enc28j60 driver
INFO  Initializing smoltcp
INFO  smoltcp initialized
TRACE [0]: adding
TRACE state=Closed=>SynSent
INFO  Initialized
INFO  Received packet
TRACE filled 192.168.128.81 => Ethernet(Address([80, 235, 246, 190, 108, 173])) (was empty)
INFO  Received packet
INFO  Received packet
INFO  Received packet
INFO  Received packet
INFO  Received packet
INFO  Received packet
INFO  Received packet
INFO  Received packet
INFO  Received packet
INFO  Received packet
INFO  Received packet
INFO  Received packet
TRACE outgoing segment will send data or flags
TRACE sending SYN
TRACE rtte: sampling at seq=3722885587
INFO  Received packet
INFO  connected: SynSent
INFO  Received packet
DEBUG unacceptable RST (expecting RST|ACK) in response to initial SYN
INFO  Received packet
INFO  Received packet
DEBUG retransmitting at t+0.700s
TRACE rtte: abort sampling due to retransmit
TRACE outgoing segment will send data or flags
TRACE sending SYN
INFO  Received packet
INFO  Received packet
INFO  Received packet
DEBUG retransmitting at t+0.700s
TRACE outgoing segment will send data or flags
TRACE sending SYN
INFO  Received packet
INFO  Received packet
DEBUG unacceptable RST (expecting RST|ACK) in response to initial SYN
DEBUG retransmitting at t+0.700s
TRACE rtte: too many retransmissions, increasing: rtt=600 dev=100 rto=1000
TRACE outgoing segment will send data or flags
TRACE sending SYN
INFO  Received packet
INFO  Received packet
INFO  Received packet
DEBUG retransmitting at t+1.000s
TRACE outgoing segment will send data or flags
TRACE sending SYN
INFO  Received packet
INFO  Received packet
DEBUG retransmitting at t+1.000s
TRACE outgoing segment will send data or flags
TRACE sending SYN
INFO  Received packet

The physical connection to the enc28j60 is working, I added a log statement every time a packet is received. The fun part is that this setup is working in like 1/20 runs. Any idea why this is happening? What I have done wrong?

[robko23]

My further attempts on debugging this revealed that the same sometimes happens with ARP and does not even get to the SYN part.

INFO  Initializing spi
INFO  Initializing enc28j60 driver
INFO  Initializing smoltcp
INFO  smoltcp initialized
TRACE [0]: adding
TRACE state=Closed=>SynSent
INFO  Initialized
TRACE outgoing segment will send data or flags
TRACE sending SYN
DEBUG address 192.168.128.81 not in neighbor cache, sending ARP request
TRACE SocketHandle(0): neighbor 192.168.128.81 missing, silencing until t+1.000s
INFO  connected: SynSent
TRACE SocketHandle(0): neighbor 192.168.128.81 silence timer expired, rediscovering
TRACE outgoing segment will send data or flags
TRACE sending SYN
DEBUG address 192.168.128.81 not in neighbor cache, sending ARP request
TRACE SocketHandle(0): neighbor 192.168.128.81 missing, silencing until t+1.000s
TRACE SocketHandle(0): neighbor 192.168.128.81 silence timer expired, rediscovering
TRACE outgoing segment will send data or flags
TRACE sending SYN
DEBUG address 192.168.128.81 not in neighbor cache, sending ARP request
TRACE SocketHandle(0): neighbor 192.168.128.81 missing, silencing until t+1.000s
TRACE SocketHandle(0): neighbor 192.168.128.81 silence timer expired, rediscovering
TRACE outgoing segment will send data or flags
TRACE sending SYN
DEBUG address 192.168.128.81 not in neighbor cache, sending ARP request
TRACE SocketHandle(0): neighbor 192.168.128.81 missing, silencing until t+1.000s
TRACE SocketHandle(0): neighbor 192.168.128.81 silence timer expired, rediscovering
TRACE outgoing segment will send data or flags
TRACE sending SYN

[Dirbaio]

check that get_ephemeral_port() is returning a different port every run, for example from a hardware RNG. If it returns the same port after a reboot, you can get fun issues when the same 4-tuple is reused, because the state for it on the PC side is left over from previous runs.

Otherwise it might be a bug in the enc28j60 driver, check if it's dropping packets. if it is I'd suggest filing an issue against it, since it's not a smoltcp issue.

If it's this one, it's unmaintained since 2019. Embassy has another newer, maintained driver based of a fork of the japaric one, See example (for nRF, you can port it to stm32 combining it with stm32 spi). I can personally confirm that one works well, I've been using in production for a few years.

[robko23]

Thanks for the ideas! I found out that get_ephemeral_port() was always returning the same port, so I changed it to be somewhat random (my MCU doesn't have HW RNG). However, it still doesn't work. I will try to change the library (I am using japaric's) and hopefully it will start working

[robko23]

I have ported my app to embassy and can confirm the driver is working