Unexpected TCP connection resets on nRF9160

We are using modem firmware 1.3.5 on nRF9160.

When packet loss is high, we sometimes see connection resets (NRF_ECONNRESET) reported by the modem that don't seem to be explainable by the packets the server has sent.

I have documented such a case in the attached files and will explain it here. On the client side, NRF_MODEM_LIB_TRACE_LEVEL_IP_ONLY was used.

The nRF91 opens a TCP connection to a server and tries to send data:

client ->   SYN   -> server
client <- SYN,ACK <- server
client -> ACK LOST
client -> PSH,ACK LOST
client -> PSH,ACK LOST (retransmission)
client <- SYN,ACK <- server (retransmission)
client -> ACK LOST (duplicate)

At this point, the nRF91 aborts the nrf_poll function with POLLERR. Querying the SO_ERROR using nrf_getsockopt yields 104 (NRF_ECONNRESET).

Is this expected behaviour? As far as I know, ECONNRESET should indicate that the server has sent a RST packet, which was not the case here. Not that in the logs, you can see the server sending a RST packet, but that is much later.

Server packet trace:

Client (nRF91) packet trace (note that the timestamps are wrong):

trace.bin0882.server.pcapng6330.log.txtclient.pcapng

Parents
  • Modem team;

    Modem trace was taken in such a limited set that it doesn’t help here. Anyway, as customer has analyzed TCP packets are lost during TCP handshake. Due not receiving ACK to SYN ACK server sends TCP RST which causes modem to send Socket closed notification to application. This is causing the error NRF_ECONNRESET. The ~5sec delay between modem data transmission and POLLERR nicely matches to attached picture, where modem TCP traffic is presented. Everything is working as expected.

     

    [09:00:02,170] INFO - [00:00:03.568,359] <inf> srv_lte: Transition to ON
    [09:00:02,464] INFO - [00:00:03.608,032] <inf> srv_lte: State ON
    [09:00:02,464] INFO - [00:00:03.680,389] <inf> srv_lte: C:RMOD0 H:0 Wait for registration
    [09:00:04,382] INFO - [00:00:05.790,924] <inf> srv_lte: PLMN=22801 ECI=1060502 EARFCN=6300 RSRP=-88dBm RSRQ=-7.5dB SNR=16dB
    [09:00:04,616] INFO - [00:00:05.868,072] <inf> srv_lte: C:RMOD0 H:0 Resolve 159.168.140.122:10040
    [09:00:04,617] INFO - [00:00:05.871,704] <inf> srv_lte: C:RMOD0 H:0 S:0 Connecting to 159.168.140.122:10040
    [09:00:04,617] INFO - [00:00:05.929,199] <inf> srv_lte: C:RMOD0 H:0 S:0 Connected
    [09:00:04,617] INFO - [00:00:05.931,152] <inf> srv_lte: C:RMOD0 H:0 S:0 RX thread start
    [09:00:04,617] INFO - [00:00:05.931,396] <inf> srv_lte: C:RMOD0 H:0 S:0 Sending 61 byte(s)
    [09:00:09,421] INFO - [00:00:10.660,736] <wrn> srv_lte: C:RMOD0 H:0 S:0 POLLERR
    [09:00:09,421] INFO - [00:00:10.662,506] <inf> srv_lte: C:RMOD0 H:0 S:0 SO_ERROR=104
    [09:00:09,421] INFO - [00:00:10.764,099] <inf> srv_lte: Transition to OFF
    [09:00:09,421] INFO - [00:00:10.766,113] <inf> srv_lte: C:RMOD0 H:0 S:0 RX thread end
    [09:00:11,203] INFO - [00:00:12.395,233] <inf> srv_lte: State OFF

Reply
  • Modem team;

    Modem trace was taken in such a limited set that it doesn’t help here. Anyway, as customer has analyzed TCP packets are lost during TCP handshake. Due not receiving ACK to SYN ACK server sends TCP RST which causes modem to send Socket closed notification to application. This is causing the error NRF_ECONNRESET. The ~5sec delay between modem data transmission and POLLERR nicely matches to attached picture, where modem TCP traffic is presented. Everything is working as expected.

     

    [09:00:02,170] INFO - [00:00:03.568,359] <inf> srv_lte: Transition to ON
    [09:00:02,464] INFO - [00:00:03.608,032] <inf> srv_lte: State ON
    [09:00:02,464] INFO - [00:00:03.680,389] <inf> srv_lte: C:RMOD0 H:0 Wait for registration
    [09:00:04,382] INFO - [00:00:05.790,924] <inf> srv_lte: PLMN=22801 ECI=1060502 EARFCN=6300 RSRP=-88dBm RSRQ=-7.5dB SNR=16dB
    [09:00:04,616] INFO - [00:00:05.868,072] <inf> srv_lte: C:RMOD0 H:0 Resolve 159.168.140.122:10040
    [09:00:04,617] INFO - [00:00:05.871,704] <inf> srv_lte: C:RMOD0 H:0 S:0 Connecting to 159.168.140.122:10040
    [09:00:04,617] INFO - [00:00:05.929,199] <inf> srv_lte: C:RMOD0 H:0 S:0 Connected
    [09:00:04,617] INFO - [00:00:05.931,152] <inf> srv_lte: C:RMOD0 H:0 S:0 RX thread start
    [09:00:04,617] INFO - [00:00:05.931,396] <inf> srv_lte: C:RMOD0 H:0 S:0 Sending 61 byte(s)
    [09:00:09,421] INFO - [00:00:10.660,736] <wrn> srv_lte: C:RMOD0 H:0 S:0 POLLERR
    [09:00:09,421] INFO - [00:00:10.662,506] <inf> srv_lte: C:RMOD0 H:0 S:0 SO_ERROR=104
    [09:00:09,421] INFO - [00:00:10.764,099] <inf> srv_lte: Transition to OFF
    [09:00:09,421] INFO - [00:00:10.766,113] <inf> srv_lte: C:RMOD0 H:0 S:0 RX thread end
    [09:00:11,203] INFO - [00:00:12.395,233] <inf> srv_lte: State OFF

Children
No Data
Related