TCP Refusing FIN

mike919192 · September 30, 2024, 8:32pm

Hi. I have FreeRTOS TCP acting as a server with a PC application connecting to it. The connection works very reliably on first connection. I am trying to debug an issue when disconnecting and reconnecting.

About 50% of the time I get a message about Refusing FIN, see the following debug messages. The socket recv function also never returns to indicate that the connection has been closed.

prvIPTask started
XEmacPs detect_phy: DD10140 at address 0.
Start PHY autonegotiation
Waiting for PHY to complete autonegotiation.
autonegotiation complete
link speed: 1000
Network buffers: 64 lowest 64
Socket 6000 -> 0ip:0 State eCLOSED->eTCP_LISTEN
Network buffers: 63 lowest 63
Network buffers: 62 lowest 62
Gain: Socket 6000 now has 1 / 1 child
prvSocketSetMSS: 1460 bytes for C0A81505ip:50300
Socket 6000 -> C0A81505ip:50300 State eCLOSED->eSYN_FIRST
prvWinScaleFactor: uxRxWinSize 2 MSS 1460 Factor 0
Socket 6000 -> C0A81505ip:50300 State eSYN_FIRST->eSYN_RECEIVED
TCP: passive 6000 => C0A81505ip:50300 set ESTAB (scaling 1)
Socket 6000 -> C0A81505ip:50300 State eSYN_RECEIVED->eESTABLISHED
Network buffers: 62 lowest 61
Refusing FIN[6000,50300]: RxCompl 1 tx done 0
TCP: RST received from C0A81505ip:50300 for 6000
Network buffers: 64 lowest 59
FreeRTOS_send: 6000 -> C0A81505ip:50300: no space
error writing to socket

These are the debug messages on successful disconnected and reconnect:

prvIPTask started
XEmacPs detect_phy: DD10140 at address 0.
Start PHY autonegotiation
Waiting for PHY to complete autonegotiation.
autonegotiation complete
link speed: 1000
Network buffers: 64 lowest 64
Socket 6000 -> 0ip:0 State eCLOSED->eTCP_LISTEN
Network buffers: 63 lowest 63
Network buffers: 63 lowest 62
Gain: Socket 6000 now has 1 / 1 child
prvSocketSetMSS: 1460 bytes for C0A81505ip:50540
Socket 6000 -> C0A81505ip:50540 State eCLOSED->eSYN_FIRST
prvWinScaleFactor: uxRxWinSize 2 MSS 1460 Factor 0
Socket 6000 -> C0A81505ip:50540 State eSYN_FIRST->eSYN_RECEIVED
TCP: passive 6000 => C0A81505ip:50540 set ESTAB (scaling 1)
Socket 6000 -> C0A81505ip:50540 State eSYN_RECEIVED->eESTABLISHED
Socket 6000 -> C0A81505ip:50540 State eESTABLISHED->eLAST_ACK
Socket 6000 -> C0A81505ip:50540 State eLAST_ACK->eCLOSE_WAIT
error reading from socket
Lost: Socket 6000 now has 0 / 1 children
FreeRTOS_closesocket[6000 to C0A81505ip:50540]: buffers 64 socks 1
Gain: Socket 6000 now has 1 / 1 child
prvSocketSetMSS: 1460 bytes for C0A81505ip:50543
Socket 6000 -> C0A81505ip:50543 State eCLOSED->eSYN_FIRST
prvWinScaleFactor: uxRxWinSize 2 MSS 1460 Factor 0
Socket 6000 -> C0A81505ip:50543 State eSYN_FIRST->eSYN_RECEIVED
TCP: passive 6000 => C0A81505ip:50543 set ESTAB (scaling 1)
Socket 6000 -> C0A81505ip:50543 State eSYN_RECEIVED->eESTABLISHED

I’m trying to understand what the message means and which side is doing something wrong. Best that I can tell is that the PC application is requesting to close the connection but FreeRTOS is refusing because there is data still in a tx buffer. But at that point my PC application has closed and it seems like the data never gets written.

Let me know if there is any other information I can provide. Thanks

ActoryOu · October 1, 2024, 2:02am

Hi @mike919192,
Looks like the TCP connection somehow doesn’t handle the FIN packet if there are some TX packets pending. Could you provide below info for us to futher analysis?

The PCAP file which is capturing the failing case on server side or client side.
The timing you putting data while the connection is established.
Version of FreeRTOS-Plus-TCP.

Thank you.

mike919192 · October 1, 2024, 12:56pm

Thanks for the reply.

Here is the capture file. There is a successful disconnects at 3s and 47s. The refuse fin occurs at 62s.
refuse_fin.zip (484.6 KB)
The application is client/server model but also has streaming data from the server (FreeRTOS) to the client (PC App) that can be enabled. So far I have not observed the error when the data stream is not enabled. It seems though that it could still happen just much more unlikely.
I am using kernel version 10.5.1 provided by Xilinx so I don’t really have the option of updating the kernel right now. The TCP version is 3.1.0. I could try to update the TCP library presuming its compatible with the older kernel.

ActoryOu · October 2, 2024, 2:43am

Hi @mike919192,
Thanks for sharing!

There is only one FIN packet recorded in this file. Does this behavior match your expectation? For other connections, it triggers RST packet directly instead of FIN. What’s the difference between these tests for closing the connection?

Apart from that, the client side sent the RST packet after FIN, but the connection is still alive after that. I think there is a missing handling to update the receive sequence. Could you try apply below change into your project? We’d try to find a formal solution for you soon.

In source/FreeRTOS_TCP_State_Handling.c: line 596~606

if( ( bRxComplete == 0 ) || ( bTxDone == 0 ) )
{
    /* Refusing FIN: Rx incomplete 1 optlen 4 tx done 1. */
    FreeRTOS_debug_printf( ( "Refusing FIN[%u,%u]: RxCompl %d tx done %d\n",
                             pxSocket->usLocalPort,
                             pxSocket->u.xTCP.usRemotePort,
                             ( int ) bRxComplete,
                             ( int ) bTxDone ) );
    xMayClose = pdFALSE;
+    pxTCPWindow->rx.ulCurrentSequenceNumber = pxTCPWindow->rx.ulFINSequenceNumber + 1U;
}

Thank you.

htibosch · October 2, 2024, 5:45am

The two TCP peers:

Client: 192.168.21.5,  Win = 64240 "laptop"   port 49833
Server: 192.168.21.10, Win =  2920 "FreeRTOS" port  6000

Actory is right, there is only one FIN packet in the PCAP file. You can find it by setting the filter “tcp.flags.fin==true”. And you can inspect the stream by filtering “tcp.stream eq 2”.

The FIN packet is sent while 192.168.21.10 is still sending lots of data.

packet IP
10271 x.5  FIN packet
10272 x.10 TCP data 1460 bytes
10273 x.10 TCP data 1460 bytes
10274 x.5  RST pack

My intuition:

Laptop is a bit impatient. The peer on the laptop calls shutdown and doesn’t wait for the results of the shutdown. In stead it closes the socket.

Now when x.5 receives data, it doesn’t have a socket to received it. The socket has been closed.

A shutdown needs time. After calling shutdown() you must treat the socket as “connected” and continue to receive data. The shutdown is ready as soon as:

Either recv() returns an error code
A timeout has occurred

You should do the equivalent of the following on the laptop side:

static void shutdown_socket( Socket_t sck )
{
    TickType_t start_time;

    FreeRTOS_shutdown( sck, FREERTOS_SHUT_RDWR );
    start_time = xTaskGetTickCount( );

    do {
        int rc = FreeRTOS_recv( sck, buffer, sizeof buffer, 0 );
        if( ( rc < 0 ) &&
            ( rc != -pdFREERTOS_ERRNO_EAGAIN ) &&
            ( rc != -pdFREERTOS_ERRNO_EINTR ) )
        {
            /* A fatal error is reported, we can stop waiting. */
            break;
        }
        if( rc > 0 )
        {
          /* Use the received data. */
        }
    } while( ( xTaskGetTickCount( ) - start_time ) < pdMS_TO_TICKS( 1000 ) );

    FreeRTOS_closesocket( sck );
}

Did you program the client your self? Using Winsock or Linux?

mike919192 · October 2, 2024, 3:05pm

Thank you both for the great help so far. I’ll try to summarize what I’ve found so far.

This workaround seems to have worked! Here is the capture from a test with the workaround and also the debug messages. In the capture there are normal disconnects at 13s and 27s. The REFUSE FIN happens at 50s.
refuse_fin_workaround.zip (479.8 KB)

Gain: Socket 6000 now has 1 / 1 child
prvSocketSetMSS: 1460 bytes for C0A81505ip:50565
Socket 6000 -> C0A81505ip:50565 State eCLOSED->eSYN_FIRST
prvWinScaleFactor: uxRxWinSize 2 MSS 1460 Factor 0
Socket 6000 -> C0A81505ip:50565 State eSYN_FIRST->eSYN_RECEIVED
TCP: passive 6000 => C0A81505ip:50565 set ESTAB (scaling 1)
Socket 6000 -> C0A81505ip:50565 State eSYN_RECEIVED->eESTABLISHED
Starting network tasks
TCP: RST received from C0A81505ip:50565 for 6000
Socket 6000 -> C0A81505ip:50565 State eESTABLISHED->eCLOSED
error reading from socket
Lost: Socket 6000 now has 0 / 1 children
FreeRTOS_closesocket[6000 to C0A81505ip:50565]: buffers 64 socks 1
Rx task is deleting itself
Notify txTask to shutdown
Tx task is deleting itself
Gain: Socket 6000 now has 1 / 1 child
prvSocketSetMSS: 1460 bytes for C0A81505ip:50569
Socket 6000 -> C0A81505ip:50569 State eCLOSED->eSYN_FIRST
prvWinScaleFactor: uxRxWinSize 2 MSS 1460 Factor 0
Socket 6000 -> C0A81505ip:50569 State eSYN_FIRST->eSYN_RECEIVED
TCP: passive 6000 => C0A81505ip:50569 set ESTAB (scaling 1)
Socket 6000 -> C0A81505ip:50569 State eSYN_RECEIVED->eESTABLISHED
Starting network tasks
TCP: RST received from C0A81505ip:50569 for 6000
Socket 6000 -> C0A81505ip:50569 State eESTABLISHED->eCLOSED
error reading from socket
Lost: Socket 6000 now has 0 / 1 children
FreeRTOS_closesocket[6000 to C0A81505ip:50569]: buffers 64 socks 1
Rx task is deleting itself
Notify txTask to shutdown
error writing to socket
Tx task is deleting itself
Gain: Socket 6000 now has 1 / 1 child
prvSocketSetMSS: 1460 bytes for C0A81505ip:50576
Socket 6000 -> C0A81505ip:50576 State eCLOSED->eSYN_FIRST
prvWinScaleFactor: uxRxWinSize 2 MSS 1460 Factor 0
Socket 6000 -> C0A81505ip:50576 State eSYN_FIRST->eSYN_RECEIVED
TCP: passive 6000 => C0A81505ip:50576 set ESTAB (scaling 1)
Socket 6000 -> C0A81505ip:50576 State eSYN_RECEIVED->eESTABLISHED
Starting network tasks
Refusing FIN[6000,50576]: RxCompl 1 tx done 0
TCP: RST received from C0A81505ip:50576 for 6000
Socket 6000 -> C0A81505ip:50576 State eESTABLISHED->eCLOSED
error reading from socket
Lost: Socket 6000 now has 0 / 1 children
FreeRTOS_closesocket[6000 to C0A81505ip:50576]: buffers 64 socks 1
Rx task is deleting itself
Notify txTask to shutdown
error writing to socket
Tx task is deleting itself

The PC App is using winsock. Its also very old and frankly badly programmed. Your intuition seems to be right though. There is no call at all to the shutdown function the PC app only calls closesocket. This is maybe why the FIN packets are missing even on the “successful” disconnects. I can try to make your suggestions to make it better behaved, but have not yet while testing the workaround.

htibosch · October 3, 2024, 5:29am

@ActoryOu wrote:

if( ( bRxComplete == 0 ) || ( bTxDone == 0 ) )
{
    /* Refusing FIN: Rx incomplete 1 optlen 4 tx done 1. */
    FreeRTOS_debug_printf( ( "Refusing FIN[%u,%u]: RxCompl %d tx done %d\n",
                             pxSocket->usLocalPort,
                             pxSocket->u.xTCP.usRemotePort,
                             ( int ) bRxComplete,
                             ( int ) bTxDone ) );
    xMayClose = pdFALSE;
+    pxTCPWindow->rx.ulCurrentSequenceNumber =
+        pxTCPWindow->rx.ulFINSequenceNumber + 1U;
}

Genius!

Thank you Actory! After your change, the RST packet will be accepted:

packet IP  Contents
10270 x.5  ACK packet           SEQ 697
10271 x.5  FIN packet           SEQ 697
10272 x.10 TCP data 1460 bytes
10273 x.10 TCP data 1460 bytes
10274 x.5  RST pack             SEQ 698 as expected

The FIN packet is handled as a 1-byte packet, and so ulCurrentSequenceNumber must be increased by 1.

Normally this happens in prvTCPHandleFin() :

    static BaseType_t prvTCPHandleFin( FreeRTOS_Socket_t * pxSocket,
                                       const NetworkBufferDescriptor_t * pxNetworkBuffer )
    {
        if( ( ucTCPFlags & tcpTCP_FLAG_FIN ) != 0U )
        {
            pxTCPWindow->rx.ulCurrentSequenceNumber =
                pxTCPWindow->rx.ulFINSequenceNumber + 1U;
        }
    }

… but prvTCPHandleFin() is only called when the stack agrees to close the connection.

In Mike’s PCAP file, the stack refused the FIN packet, and so it didn’t call prvTCPHandleFin(). And therefor, it also refused the RST packet with SEQ 698.

My suggestion was to let the client do a graceful shutdown (shutdown - wait - closesocket), which will prevent the whole problem.

Combining both changes will give the best results

mike919192 · October 3, 2024, 10:57am

Thanks again for all the support. I am assuming that the suggested change is considered a workaround for now correct? Is this going to be considered a bug and will a more thorough fix be merged into the TCP library? For me its not too bad to essentially use a 1 line change fork in the short term, but long term it would be better to be able to use the standard release.

ActoryOu · October 3, 2024, 12:14pm

The PR has been raised for this. Please help take a look.

Thank you.