eclipse-threadx / netxduo

Eclipse ThreadX - NetXDuo is an advanced, industrial-grade TCP/IP network stack designed specifically for deeply embedded real-time and IoT applications
https://github.com/eclipse-threadx/rtos-docs/blob/main/rtos-docs/netx-duo/index.md
MIT License
242 stars 137 forks source link

Packet buffer overrun when using web_http_client secure #177

Open Alec-Davis-NZ opened 1 year ago

Alec-Davis-NZ commented 1 year ago

Describe the bug

Packet Pool buffers not belonging to the webclient are freed that were previously consumed by SNTP client and DNS Client, they are however shared with the default packet pool created with nx_ip_create

A clear and concise description of what the bug is. Default TLS 1.2, No TLS 1.3 nor 1.1 nor 1.0

Prior to the HTTPS 64K test file download nx_packet_pool_info_get reports total_packets = 25 free_packets = 21 The 4 packets are I assume are consumed by SNTP and DNS client.

During the HTTPS 64K test file download the download with fail nx_packet_pool_info_get reports total_packets = 25 free_packets = 25

Any further SNTP updates fail and of course further HTTP downloads fail

Development Environment:

the problem you're facing:

To Reproduce Steps to reproduce the behavior: packet pool size is set by

define PAYLOAD_SIZE 1536

define NX_PACKET_POOL_SIZE (( PAYLOAD_SIZE + sizeof(NX_PACKET)) * 25)

define AUX_PAYLOAD_SIZE 256

define NX_PACKET_AUX_POOL_SIZE (( AUX_PAYLOAD_SIZE + sizeof(NX_PACKET)) * 2)

nx_ip_create using NX_PACKET_POOL_SIZE nx_ip_auxiliary_packet_pool_set and set to NX_PACKET_AUX_POOL_SIZE
nx_packet_pool_low_watermark_set(&AppPacketPool, 2) )

create dhcp client create dns client create sntp client call web_https to download 64K

Expected behavior If I have NX_PACKET_POOL_SIZE of (( PAYLOAD_SIZE + sizeof(NX_PACKET)) * 27) the download will work and not over run the last 4 packet buffers being used by SNTP and DNS.

Impact show stopper If we have to use HTTP 1MB firmware.bin is in the clear, which works flawlessly.

Logs and console output If applicable, add console logs or other types of debug information like Wireshark capture as .zip file.

Additional context Add any other context about the problem here. I have enabled NX_ENABLE_DUAL_PACKET_POOL I have set the low water mark to 2

Alec-Davis-NZ commented 1 year ago

I now have tried very similar code in codespaces, my assumption that packets were in use by SNTP and DNS was wrong. Which in nx_ip_create uses the _nx_linux_network_driver instead of nx_stm32_eth_driver, so my guess is the stm32_eth_driver.

In codespaces, the initial packet pool hasn't dropped (as it does on the STM32) before the intial call to the secure web_client get any test files.

So more digging.

wenhui-xie commented 11 months ago

Hi @Alec-Davis-NZ, you are right, the driver may use some packets. Could you share more info about your project? For example, the application code about the web GET part and the Wireshark capture files.

Alec-Davis-NZ commented 10 months ago

I have tried with multiple STM32 dev kits; STM32F429ZITX and last tried an STM32H723Tx both have plenty of RAM. I'm yet to try on STM32F7. They all fail in the same way.

Extracted code segment from our STM32H7 test project. download_example.zip

For an experiment I then tried the Renesas RX72N-ENVISION-KIT, and it worked perfectly, continuously downloading much bigger files than the example I was trying on any of the STM32 devices.

Alec

wenhui-xie commented 10 months ago

Hi @Alec-Davis-NZ, can increasing the packet pool size solve the issues for all the ST projects?

Alec-Davis-NZ commented 10 months ago

No, the last test I did with the STM32H7 was with a packet pool of 35, as shown below.

define PAYLOAD_SIZE 1536

define NX_PACKET_POOL_SIZE (( PAYLOAD_SIZE + sizeof(NX_PACKET)) * 35)

UINT MX_NetXDuo_Init(VOID *memory_ptr)
{
  UINT ret = NX_SUCCESS;
  TX_BYTE_POOL *byte_pool = (TX_BYTE_POOL*)memory_ptr;

  /* USER CODE BEGIN MX_NetXDuo_MEM_POOL */
  /* USER CODE END MX_NetXDuo_MEM_POOL */

  /* USER CODE BEGIN MX_NetXDuo_Init */

    CHAR *pointer;

    printf( "MX_NetXDuo_Init: Start\r\n" );

    /* Allocate the memory for packet_pool.  */
    if ( tx_byte_allocate(byte_pool, (VOID **) &pointer,  NX_PACKET_POOL_SIZE, TX_NO_WAIT) != TX_SUCCESS ) {
        printf( "ERROR: Allocate the memory for packet_pool\r\n" );
        return TX_POOL_ERROR;
    }

    /* Create the Packet pool to be used for packet allocation */
    if ( nx_packet_pool_create(&AppPacketPool, "App Packet Pool", PAYLOAD_SIZE, pointer, NX_PACKET_POOL_SIZE) != NX_SUCCESS ) {
        printf( "ERROR: Create the Packet pool to be used for packet allocation\r\n" );
        return NX_NOT_ENABLED;
    }

    /* Allocate the memory for Ip_Instance */
    if ( tx_byte_allocate(byte_pool, (VOID **) &pointer, 4 * DEFAULT_MEMORY_SIZE, TX_NO_WAIT) != TX_SUCCESS ) {
        printf( "ERROR: Allocate the memory for Ip_Instance\r\n" );
        return TX_POOL_ERROR;
    }

    /* Create the main NX_IP instance */
    if ( nx_ip_create(&IpInstance, "Main Ip instance", NULL_ADDRESS, NULL_ADDRESS, &AppPacketPool, NETWORK_DRIVER,
                      pointer, 4 * DEFAULT_MEMORY_SIZE, DEFAULT_MAIN_PRIORITY) != NX_SUCCESS ) {
        printf( "ERROR: Create the main NX_IP instance\r\n" );
        return NX_NOT_ENABLED;
    }
....
wenhui-xie commented 10 months ago

What status does nx_web_http_client_response_body_get() return when the error occurs? And what's the pool info?

Alec-Davis-NZ commented 10 months ago

I just setup the STM32H7 running at max speed of 550MHZ with 35 packet buffers and it succesfully downloaded a 5148088 Byte file.

Changed to 27 packet buffers

define PAYLOAD_SIZE 1536

define NX_PACKET_POOL_SIZE (( PAYLOAD_SIZE + sizeof(NX_PACKET)) * 27)

It downloaded the 5148088 Byte file once

APP:before nx_web_http_client_response_body_get         total_packets = 27      free_packets = 22       empty_pool_requests = 1033      empty_pool_suspensions = 397    invalid_packet_releases = 0
AUX:before nx_web_http_client_response_body_get         total_packets = 27      free_packets = 22       empty_pool_requests = 1033      empty_pool_suspensions = 397    invalid_packet_releases = 0

APP:after nx_web_http_client_response_body_get  total_packets = 27      free_packets = 20       empty_pool_requests = 1033      empty_pool_suspensions = 397    invalid_packet_releases = 0
AUX:after nx_web_http_client_response_body_get  total_packets = 27      free_packets = 20       empty_pool_requests = 1033      empty_pool_suspensions = 397    invalid_packet_releases = 0
DONE: firmware=1 total bytes=5148088 errors 0

APP:before nx_web_http_client_delete    total_packets = 27      free_packets = 23       empty_pool_requests = 1033      empty_pool_suspensions = 397    invalid_packet_releases = 0
AUX:before nx_web_http_client_delete    total_packets = 27      free_packets = 23       empty_pool_requests = 1033      empty_pool_suspensions = 397    invalid_packet_releases = 0

APP:after nx_web_http_client_delete     total_packets = 27      free_packets = 23       empty_pool_requests = 1033      empty_pool_suspensions = 397    invalid_packet_releases = 0
AUX:after nx_web_http_client_delete     total_packets = 27      free_packets = 23       empty_pool_requests = 1033      empty_pool_suspensions = 397    invalid_packet_releases = 0

And then after a 3 minute delay in the same debug run started downloading the same 5MB file , it failed with "Error with http response body get: get_status=0x1" and the number of free packets is now 26 not 23, as the STM eth driver appears to use 4 packet buffers .

APP:before nx_web_http_client_response_body_get         total_packets = 27      free_packets = 23       empty_pool_requests = 1403      empty_pool_suspensions = 538    invalid_packet_releases = 0
AUX:before nx_web_http_client_response_body_get         total_packets = 27      free_packets = 23       empty_pool_requests = 1403      empty_pool_suspensions = 538    invalid_packet_releases = 0

APP:after nx_web_http_client_response_body_get  total_packets = 27      free_packets = 11       empty_pool_requests = 1406      empty_pool_suspensions = 539    invalid_packet_releases = 0
AUX:after nx_web_http_client_response_body_get  total_packets = 27      free_packets = 11       empty_pool_requests = 1406      empty_pool_suspensions = 539    invalid_packet_releases = 0
DONE: firmware=1 total bytes=1835008 errors 0

APP:before nx_web_http_client_response_body_get         total_packets = 27      free_packets = 22       empty_pool_requests = 1406      empty_pool_suspensions = 539    invalid_packet_releases = 0
AUX:before nx_web_http_client_response_body_get         total_packets = 27      free_packets = 22       empty_pool_requests = 1406      empty_pool_suspensions = 539    invalid_packet_releases = 0

APP:after nx_web_http_client_response_body_get  total_packets = 27      free_packets = 15       empty_pool_requests = 1412      empty_pool_suspensions = 540    invalid_packet_releases = 0
AUX:after nx_web_http_client_response_body_get  total_packets = 27      free_packets = 15       empty_pool_requests = 1412      empty_pool_suspensions = 540    invalid_packet_releases = 0
DONE: firmware=1 total bytes=1851392 errors 0

APP:before nx_web_http_client_response_body_get         total_packets = 27      free_packets = 26       empty_pool_requests = 1412      empty_pool_suspensions = 540    invalid_packet_releases = 0
AUX:before nx_web_http_client_response_body_get         total_packets = 27      free_packets = 26       empty_pool_requests = 1412      empty_pool_suspensions = 540    invalid_packet_releases = 0

*****  huge delay of several minutes ***************

APP:after nx_web_http_client_response_body_get  total_packets = 27      free_packets = 26       empty_pool_requests = 1412      empty_pool_suspensions = 540    invalid_packet_releases = 0
AUX:after nx_web_http_client_response_body_get  total_packets = 27      free_packets = 26       empty_pool_requests = 1412      empty_pool_suspensions = 540    invalid_packet_releases = 0
Error with http response body get: get_status=0x1

APP:Error response body get     total_packets = 27      free_packets = 26       empty_pool_requests = 1412      empty_pool_suspensions = 540    invalid_packet_releases = 0
AUX:Error response body get     total_packets = 27      free_packets = 26       empty_pool_requests = 1412      empty_pool_suspensions = 540    invalid_packet_releases = 0

APP:before nx_web_http_client_delete    total_packets = 27      free_packets = 26       empty_pool_requests = 1412      empty_pool_suspensions = 540    invalid_packet_releases = 0
AUX:before nx_web_http_client_delete    total_packets = 27      free_packets = 26       empty_pool_requests = 1412      empty_pool_suspensions = 540    invalid_packet_releases = 0

APP:after nx_web_http_client_delete     total_packets = 27      free_packets = 27       empty_pool_requests = 1412      empty_pool_suspensions = 540    invalid_packet_releases = 0
AUX:after nx_web_http_client_delete     total_packets = 27      free_packets = 27       empty_pool_requests = 1412      empty_pool_suspensions = 540    invalid_packet_releases = 0
Alec-Davis-NZ commented 10 months ago

Changed to 31 packet buffers, and tidied up the print_packet_pools as I'm not use the AUX_PACKET_POOL.

There is a pattern devoloping here, and thats if empty_pool_requests = 0 empty_pool_suspensions = 0 then it will download, finsih and leave the 4 buffer used by the STM eth driver

APP:before nx_web_http_client_response_body_get         total_packets = 31      free_packets = 25       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0

APP:after nx_web_http_client_response_body_get  total_packets = 31      free_packets = 24       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
DONE: firmware=1 total bytes=5148088 errors 0

APP:before nx_web_http_client_delete    total_packets = 31      free_packets = 27       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0

APP:after nx_web_http_client_delete     total_packets = 31      free_packets = 27       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
Alec-Davis-NZ commented 10 months ago

Still on STM32H7@550MHZ

I changed to 28 packet buffers, I got some empty_pool_requests and empty_pool_suspensions but it download 2 or 3 times.

Changed to 29 packet buffers with "empty_pool_requests = 0 empty_pool_suspensions = 0" and it downloads 5MB fine, will leave running over night

APP:before nx_web_http_client_response_body_get         total_packets = 29      free_packets = 23       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0

APP:after  nx_web_http_client_response_body_get         total_packets = 29      free_packets = 22       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
DONE: firmware=1 total bytes=5148088 errors 0

APP:before nx_web_http_client_delete    total_packets = 29      free_packets = 25       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0

APP:after  nx_web_http_client_delete    total_packets = 29      free_packets = 25       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0

Overnight running outcome: It's been running from 10:25PM to 7:50PM without any packet pool exhaustion. Downloading 15 times an hour - once every 4 minutes.

APP:before nx_web_http_client_response_body_get         total_packets = 29      free_packets = 23       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0

APP:after  nx_web_http_client_response_body_get         total_packets = 29      free_packets = 22       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
DONE: firmware=1 total bytes=5148088 errors 0

APP:before nx_web_http_client_delete    total_packets = 29      free_packets = 25       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0

APP:after  nx_web_http_client_delete    total_packets = 29      free_packets = 25       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
wenhui-xie commented 10 months ago

Hi @Alec-Davis-NZ, we fixed a related bug of receiving TCP packets in version 6.3.0. Could you update your source code to 6.3.0 and check if the issue can be fixed? If not, could you share the Wireshark capture file and user-defined macros for further analysis?

Alec-Davis-NZ commented 10 months ago

Now using netxduo 6.3.0

Using 23 packet buffers and downloading a 16K file it fails, ending with 23 free packet, normally when working it would end with 4 less than the total_packets, so in this case should have been 19.

wireshark capture as requested. stm32h7_NX_PACKET_POOL_SIZE_23_test-16k.zip

APP:before nx_web_http_client_response_body_get         total_packets = 23      free_packets = 18       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
Received header:
        Field name: Content-Type (12 bytes)
        Value: application/octet-stream (24 bytes)

Received header:
        Field name: Last-Modified (13 bytes)
        Value: Wed, 31 May 2023 04:02:14 GMT (29 bytes)

Received header:
        Field name: Accept-Ranges (13 bytes)
        Value: bytes (5 bytes)

Received header:
        Field name: ETag (4 bytes)
        Value: "a8dad2ae7493d91:0" (19 bytes)

Received header:
        Field name: Date (4 bytes)
        Value: Thu, 16 Nov 2023 10:37:41 GMT (29 bytes)

Received header:
        Field name: Connection (10 bytes)
        Value: close (5 bytes)

Received header:
        Field name: Content-Length (14 bytes)
        Value: 16384 (5 bytes)

APP:after  nx_web_http_client_response_body_get         total_packets = 23      free_packets = 11       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0
DONE: firmware=1 total bytes=16151 errors 0

APP:before nx_web_http_client_response_body_get         total_packets = 23      free_packets = 22       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0

APP:after  nx_web_http_client_response_body_get         total_packets = 23      free_packets = 22       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0
DONE: firmware=1 total bytes=16384 errors 0

APP:before nx_web_http_client_delete    total_packets = 23      free_packets = 23       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0

APP:after  nx_web_http_client_delete    total_packets = 23      free_packets = 23       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0
Alec-Davis-NZ commented 10 months ago

Using a 27 packet buffers and downloading a 4096K test file. it downloaded, but had many empty pool requests, (Prior to 6.3.0 27 packets pool size would fail)

Wireshark capture stm32h7_NX_PACKET_POOL_SIZE_27_test-4096k.zip

APP:before nx_web_http_client_response_body_get         total_packets = 27      free_packets = 22       empty_pool_requests = 835       empty_pool_suspensions = 321    invalid_packet_releases = 0

APP:after  nx_web_http_client_response_body_get         total_packets = 27      free_packets = 12       empty_pool_requests = 839       empty_pool_suspensions = 323    invalid_packet_releases = 0
DONE: firmware=1 total bytes=4194304 errors 0

APP:before nx_web_http_client_delete    total_packets = 27      free_packets = 23       empty_pool_requests = 839       empty_pool_suspensions = 323    invalid_packet_releases = 0

APP:after  nx_web_http_client_delete    total_packets = 27      free_packets = 23       empty_pool_requests = 839       empty_pool_suspensions = 323    invalid_packet_releases = 0
wenhui-xie commented 10 months ago

I checked the stm32h7_NX_PACKET_POOL_SIZE_23_test-16k.pcap, it seems that all the bytes are received, and I don't see any error code from the info you pasted.

For the empty pool requests, it is possible that the application don't process in time, then the packets will be queued. If we run out of free packets, there will be empty pool requests.

Alec-Davis-NZ commented 10 months ago

I checked the stm32h7_NX_PACKET_POOL_SIZE_23_test-16k.pcap, it seems that all the bytes are received, and I don't see any error code from the info you pasted.

For the empty pool requests, it is possible that the application don't process in time, then the packets will be queued. If we run out of free packets, there will be empty pool requests.

The error is after the download, all packet buffers were freed, thus no further download happened, APP:after nx_web_http_client_delete total_packets = 23 free_packets = 23 empty_pool_requests = 13

wenhui-xie commented 10 months ago

From the stm32h7_NX_PACKET_POOL_SIZE_23_test-16k.pcap, it seems that the client can only send packets but can not receive packets since packet No.47. Could you add some breakpoints to the driver receive function and _nx_tcp_socket_packet_process() to check if the packet is received or dropped?

Alec-Davis-NZ commented 10 months ago

This download like before appeared to download, but corrupted the free packets, and thus no furhter downloads were able to happen.

image

Copy of nx_tcp_packet_process.c that I used, from 6.3.0 github so that I can point out where I had breakpoints. nx_tcp_packet_process.zip

break point at line 423 always triggered break point at lines 217, 233, 268 and 435 never got triggered.

The console output

MX_NetXDuo_Init: Start

APP:Nx_SNTP_Client application started:         total_packets = 23      free_packets = 23       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
MX_NetXDuo_Init: End
Waiting for DHCP
STM32 IpAddress: 192.168.125.45

Client connected to HTTP server: [202.36.76.35]

nx_web_http_client_created

nx_web_http_client_response_header_callback_set

nx_web_http_client{_secure]_connect

http client request initialized

nx_web_http_client_request_send

APP:before nx_web_http_client_response_body_get         total_packets = 23      free_packets = 18       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
Received header:
        Field name: Content-Type (12 bytes)
        Value: application/octet-stream (24 bytes)

Received header:
        Field name: Last-Modified (13 bytes)
        Value: Wed, 31 May 2023 04:02:14 GMT (29 bytes)

Received header:
        Field name: Accept-Ranges (13 bytes)
        Value: bytes (5 bytes)

Received header:
        Field name: ETag (4 bytes)
        Value: "a8dad2ae7493d91:0" (19 bytes)

Received header:
        Field name: Date (4 bytes)
        Value: Mon, 27 Nov 2023 09:53:57 GMT (29 bytes)

Received header:
        Field name: Connection (10 bytes)
        Value: close (5 bytes)

Received header:
        Field name: Content-Length (14 bytes)
        Value: 16384 (5 bytes)

APP:after  nx_web_http_client_response_body_get         total_packets = 23      free_packets = 11       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0
DONE: firmware=1 total bytes=16151 errors 0

APP:before nx_web_http_client_response_body_get         total_packets = 23      free_packets = 22       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0

APP:after  nx_web_http_client_response_body_get         total_packets = 23      free_packets = 22       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0
DONE: firmware=1 total bytes=16384 errors 0

APP:before nx_web_http_client_delete    total_packets = 23      free_packets = 23       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0

APP:after  nx_web_http_client_delete    total_packets = 23      free_packets = 23       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0

Wireshark capture of this download. stm32h7_NX_PACKET_POOL_SIZE_23_test-16k-3.zip

wenhui-xie commented 10 months ago

Hi @Alec-Davis-NZ, could you step into _nx_tcp_socket_packet_process() to check if any return; line is triggered? If not, could you step into _nx_tcp_socket_state_fin_wait1() and check thesocket_ptr -> nx_tcp_socket_fin_acked is true or false?

Alec-Davis-NZ commented 10 months ago

I added printf before each return; in _nx_tcp_socket_packet_process() but none were triggered I also added addition printf's in each state of nx_tcp_socket_state , see attached file nx_tcp_socket_packet_process

nx_tcp_socket_packet_process.zip

Then at the beginning of in _nx_tcp_socket_state_fin_wait1() another printf but it also was not triggered

VOID  _nx_tcp_socket_state_fin_wait1(NX_TCP_SOCKET *socket_ptr)
{

    printf( "\r\n_nx_tcp_socket_state_fin_wait1: nx_tcp_socket_fin_acked = %d\r\n", socket_ptr -> nx_tcp_socket_fin_acked );

This can be verified by the console output

MX_NetXDuo_Init: Start

APP:Nx_SNTP_Client application started:         total_packets = 23      free_packets = 23       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
MX_NetXDuo_Init: End
Waiting for DHCP
STM32 IpAddress: 192.168.125.45

Client connected to HTTP server: [202.36.76.35]

nx_web_http_client_created

nx_web_http_client_response_header_callback_set
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_SYN_SENT.
tls_metadata_size mismatch! calculated:10128  actual:18432
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.

nx_web_http_client{_secure]_connect

http client request initialized

nx_web_http_client_request_send

APP:before nx_web_http_client_response_body_get         total_packets = 23      free_packets = 18       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
Received header:
        Field name: Content-Type (12 bytes)
        Value: application/octet-stream (24 bytes)

Received header:
        Field name: Last-Modified (13 bytes)
        Value: Wed, 31 May 2023 04:02:14 GMT (29 bytes)

Received header:
        Field name: Accept-Ranges (13 bytes)
        Value: bytes (5 bytes)

Received header:
        Field name: ETag (4 bytes)
        Value: "a8dad2ae7493d91:0" (19 bytes)

Received header:
        Field name: Date (4 bytes)
        Value: Mon, 04 Dec 2023 07:46:35 GMT (29 bytes)

Received header:
        Field name: Connection (10 bytes)
        Value: close (5 bytes)

Received header:
        Field name: Content-Length (14 bytes)
        Value: 16384 (5 bytes)

APP:after  nx_web_http_client_response_body_get         total_packets = 23      free_packets = 11       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0
DONE: firmware=1 total bytes=16151 errors 0

APP:before nx_web_http_client_response_body_get         total_packets = 23      free_packets = 22       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0

APP:after  nx_web_http_client_response_body_get         total_packets = 23      free_packets = 22       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0
DONE: firmware=1 total bytes=16384 errors 0

APP:before nx_web_http_client_delete    total_packets = 23      free_packets = 23       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0

APP:after  nx_web_http_client_delete    total_packets = 23      free_packets = 23       empty_pool_requests = 13        empty_pool_suspensions = 5      invalid_packet_releases = 0
Alec-Davis-NZ commented 10 months ago

As a sanity check, I changed the packet_pool size to 29 as below and the same download worked fine and was able to download multiple times, what is different is we get a state NX_TCP_LAST_ACK #define NX_PACKET_POOL_SIZE (( PAYLOAD_SIZE + sizeof(NX_PACKET)) * 29)

console output below

MX_NetXDuo_Init: Start

APP:Nx_SNTP_Client application started:         total_packets = 29      free_packets = 29       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
MX_NetXDuo_Init: End
Waiting for DHCP
STM32 IpAddress: 192.168.125.45

Client connected to HTTP server: [202.36.76.35]

nx_web_http_client_created

nx_web_http_client_response_header_callback_set
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_SYN_SENT.
tls_metadata_size mismatch! calculated:10128  actual:18432
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.

nx_web_http_client{_secure]_connect

http client request initialized

nx_web_http_client_request_send

APP:before nx_web_http_client_response_body_get         total_packets = 29      free_packets = 24       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
Received header:
        Field name: Content-Type (12 bytes)
        Value: application/octet-stream (24 bytes)

Received header:
        Field name: Last-Modified (13 bytes)
        Value: Wed, 31 May 2023 04:02:14 GMT (29 bytes)

Received header:
        Field name: Accept-Ranges (13 bytes)
        Value: bytes (5 bytes)

Received header:
        Field name: ETag (4 bytes)
        Value: "a8dad2ae7493d91:0" (19 bytes)

Received header:
        Field name: Date (4 bytes)
        Value: Mon, 04 Dec 2023 08:22:49 GMT (29 bytes)

Received header:
        Field name: Connection (10 bytes)
        Value: close (5 bytes)

Received header:
        Field name: Content-Length (14 bytes)
        Value: 16384 (5 bytes)

APP:after  nx_web_http_client_response_body_get         total_packets = 29      free_packets = 12       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
DONE: firmware=1 total bytes=16151 errors 0

APP:before nx_web_http_client_response_body_get         total_packets = 29      free_packets = 23       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_LAST_ACK.

APP:after  nx_web_http_client_response_body_get         total_packets = 29      free_packets = 24       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
DONE: firmware=1 total bytes=16384 errors 0

APP:before nx_web_http_client_delete    total_packets = 29      free_packets = 25       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0

APP:after  nx_web_http_client_delete    total_packets = 29      free_packets = 25       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0

Client connected to HTTP server: [202.36.76.35]

nx_web_http_client_created

nx_web_http_client_response_header_callback_set
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_SYN_SENT.
tls_metadata_size mismatch! calculated:10128  actual:18432
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.

nx_web_http_client{_secure]_connect

http client request initialized

nx_web_http_client_request_send

APP:before nx_web_http_client_response_body_get         total_packets = 29      free_packets = 24       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
Received header:
        Field name: Content-Type (12 bytes)
        Value: application/octet-stream (24 bytes)

Received header:
        Field name: Last-Modified (13 bytes)
        Value: Wed, 31 May 2023 04:02:14 GMT (29 bytes)

Received header:
        Field name: Accept-Ranges (13 bytes)
        Value: bytes (5 bytes)

Received header:
        Field name: ETag (4 bytes)
        Value: "a8dad2ae7493d91:0" (19 bytes)

Received header:
        Field name: Date (4 bytes)
        Value: Mon, 04 Dec 2023 08:23:50 GMT (29 bytes)

Received header:
        Field name: Connection (10 bytes)
        Value: close (5 bytes)

Received header:
        Field name: Content-Length (14 bytes)
        Value: 16384 (5 bytes)

APP:after  nx_web_http_client_response_body_get         total_packets = 29      free_packets = 12       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
DONE: firmware=1 total bytes=16151 errors 0

APP:before nx_web_http_client_response_body_get         total_packets = 29      free_packets = 23       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_LAST_ACK.

APP:after  nx_web_http_client_response_body_get         total_packets = 29      free_packets = 24       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
DONE: firmware=1 total bytes=16384 errors 0

APP:before nx_web_http_client_delete    total_packets = 29      free_packets = 25       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0

APP:after  nx_web_http_client_delete    total_packets = 29      free_packets = 25       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0

Client connected to HTTP server: [202.36.76.35]

nx_web_http_client_created

nx_web_http_client_response_header_callback_set
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_SYN_SENT.
tls_metadata_size mismatch! calculated:10128  actual:18432
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.

nx_web_http_client{_secure]_connect

http client request initialized

nx_web_http_client_request_send

APP:before nx_web_http_client_response_body_get         total_packets = 29      free_packets = 24       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_ESTABLISHED.
Received header:
        Field name: Content-Type (12 bytes)
        Value: application/octet-stream (24 bytes)

Received header:
        Field name: Last-Modified (13 bytes)
        Value: Wed, 31 May 2023 04:02:14 GMT (29 bytes)

Received header:
        Field name: Accept-Ranges (13 bytes)
        Value: bytes (5 bytes)

Received header:
        Field name: ETag (4 bytes)
        Value: "a8dad2ae7493d91:0" (19 bytes)

Received header:
        Field name: Date (4 bytes)
        Value: Mon, 04 Dec 2023 08:24:51 GMT (29 bytes)

Received header:
        Field name: Connection (10 bytes)
        Value: close (5 bytes)

Received header:
        Field name: Content-Length (14 bytes)
        Value: 16384 (5 bytes)

APP:after  nx_web_http_client_response_body_get         total_packets = 29      free_packets = 12       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
DONE: firmware=1 total bytes=16151 errors 0

APP:before nx_web_http_client_response_body_get         total_packets = 29      free_packets = 23       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_LAST_ACK.

APP:after  nx_web_http_client_response_body_get         total_packets = 29      free_packets = 24       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
DONE: firmware=1 total bytes=16384 errors 0

APP:before nx_web_http_client_delete    total_packets = 29      free_packets = 25       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0

APP:after  nx_web_http_client_delete    total_packets = 29      free_packets = 25       empty_pool_requests = 0         empty_pool_suspensions = 0      invalid_packet_releases = 0
wenhui-xie commented 10 months ago

I double-checked the wireshark pcap, the info you printed coincides with the wireshark pcap. The FIN packet(No. 39) was sent from the server, then the client entered the NX_TCP_LAST_ACK state after it sent the FIN back(No. 44). But the last ack packet(No. 45) wasn't received, and the client couldn't receive any packet, so the client kept retransmitting packet No. 43. When the packet pool size is set to 29, the last ack was received and processed(the info "_nx_tcp_socket_packet_process: Process relative to the state of the socket = NX_TCP_LAST_ACK." was printed when processing the last ack packet), so the session can close normally.

wireshark

Since none of the return; lines in _nx_tcp_socket_packet_process() were triggered, the packet may be dropped before entering _nx_tcp_socket_packet_process(). Could you add a breakpoint to _nx_tcp_packet_send_fin(), and when this breakpoint is triggered, add another breakpoint to _nx_tcp_packet_process() to check if any TCP packet is received? If no TCP packet is received, change the second breakpoint to driver layer and debug where the packet is dropped.

Alec-Davis-NZ commented 9 months ago

I see regression tests have been added, specifically netx_web_external_server_test.c, I was hoping that it would guide me in the right direction to download from an external web site, but it could be enhanced, see https://github.com/azure-rtos/netxduo/issues/219

However, I still get the corruption if I try to download 16K of data or more.

wenhui-xie commented 9 months ago

Hi @Alec-Davis-NZ, sorry for misleading you, netx_web_external_server_test.c is unused, I'll delete it.

And for the packet drop issue, I suggest you debug where the packet is dropped referring to my last comment.