Cannot use WebSocket Client due to constant disconnects (TZ-1191)

[simondean]

Checklist

• Checked the issue tracker for similar issues to ensure this is not a duplicate
• Read the documentation to confirm the issue is not addressed there and your configuration is set correctly
• Tested with the latest version to ensure the issue hasn't been fixed

How often does this bug occurs?

always

Expected behavior

WebSocket client's connection stays open for multiple minutes and is reused for sending multiple WebSocket messages

Actual behavior (suspected bug)

Every few seconds the client connection disconnects with this error:

E (83821) websocket_client: esp_transport_connect() failed with -1, transport_error=ESP_OK, tls_error_code=0, tls_flags=0, esp_ws_handshake_status_code=101, errno=119
I (83831) esp_ot_br: WEBSOCKET_EVENT_ERROR
E (83831) esp_ot_br: Last error HTTP status code: 0x65
E (83831) esp_ot_br: Last error reported from tls stack: 0xb33fffff
I (83841) websocket_client: Reconnect after 10000 ms
I (83841) esp_ot_br: WEBSOCKET_EVENT_DISCONNECTED
E (83841) esp_ot_br: Last error HTTP status code: 0x65

Error logs or terminal output

Detecting chip type... ESP32-S3
Running idf_monitor in directory **redacted**/esp/esp-thread-br/examples/basic_thread_border_router
Executing "**redacted**/.espressif/python_env/idf5.4_py3.12_env/bin/python **redacted**/esp/esp-idf/tools/idf_monitor.py -p /dev/cu.usbmodem**redacted** -b 115200 --toolchain-prefix xtensa-esp32s3-elf- --target esp32s3 --revision 0 **redacted**/esp/esp-thread-br/examples/basic_thread_border_router/build/esp_ot_br.elf -m '**redacted**/.espressif/python_env/idf5.4_py3.12_env/bin/python' '**redacted**/esp/esp-idf/tools/idf.py'"...
--- esp-idf-monitor 1.5.0 on /dev/cu.usbmodem**redacted** 115200
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x15 (USB_UART_CHIP_RESET),boot:0xb (SPI_FAST_FLASH_BOOT)
Saved PC:0x40048de8
--- 0x40048de8: uart_rx_readbuff in ROM

SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce2820,len:0x1874
load:0x403c8700,len:0x4
load:0x403c8704,len:0xc80
load:0x403cb700,len:0x2eb0
entry 0x403c8914
I (26) boot: ESP-IDF v5.4-dev-3201-g46acfdce96 2nd stage bootloader
I (27) boot: compile time Sep 29 2024 10:50:35
I (27) boot: Multicore bootloader
I (27) boot: chip revision: v0.2
I (27) boot: efuse block revision: v1.3
I (28) boot.esp32s3: Boot SPI Speed : 80MHz
I (28) boot.esp32s3: SPI Mode       : DIO
I (28) boot.esp32s3: SPI Flash Size : 4MB
I (28) boot: Enabling RNG early entropy source...
I (28) boot: Partition Table:
I (29) boot: ## Label            Usage          Type ST Offset   Length
I (29) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (29) boot:  1 otadata          OTA data         01 00 0000f000 00002000
I (30) boot:  2 phy_init         RF data          01 01 00011000 00001000
I (30) boot:  3 ota_0            OTA app          00 10 00020000 00190000
I (31) boot:  4 ota_1            OTA app          00 11 001b0000 00190000
I (31) boot:  5 web_storage      Unknown data     01 82 00340000 00019000
I (32) boot:  6 rcp_fw           Unknown data     01 82 00359000 000a0000
I (32) boot: End of partition table
I (32) esp_image: segment 0: paddr=00020020 vaddr=3c0d0020 size=4c638h (312888) map
I (88) esp_image: segment 1: paddr=0006c660 vaddr=3fc95800 size=0330ch ( 13068) load
I (91) esp_image: segment 2: paddr=0006f974 vaddr=40374000 size=006a4h (  1700) load
I (92) esp_image: segment 3: paddr=00070020 vaddr=42000020 size=c0764h (788324) map
I (231) esp_image: segment 4: paddr=0013078c vaddr=403746a4 size=110dch ( 69852) load
I (247) esp_image: segment 5: paddr=00141870 vaddr=600fe100 size=00018h (    24) load
I (254) boot: Loaded app from partition at offset 0x20000
I (254) boot: Disabling RNG early entropy source...
I (255) cpu_start: Multicore app
I (264) cpu_start: Pro cpu start user code
I (264) cpu_start: cpu freq: 160000000 Hz
I (264) app_init: Application information:
I (265) app_init: Project name:     esp_ot_br
I (265) app_init: App version:      v1.0-88-g34812fe-dirty
I (265) app_init: Compile time:     Sep 29 2024 11:19:10
I (266) app_init: ELF file SHA256:  cdde91be4...
I (266) app_init: ESP-IDF:          v5.4-dev-3201-g46acfdce96
I (266) efuse_init: Min chip rev:     v0.0
I (266) efuse_init: Max chip rev:     v0.99 
I (266) efuse_init: Chip rev:         v0.2
I (267) heap_init: Initializing. RAM available for dynamic allocation:
I (267) heap_init: At 3FCA63A8 len 00043368 (268 KiB): RAM
I (267) heap_init: At 3FCE9710 len 00005724 (21 KiB): RAM
I (268) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (268) heap_init: At 600FE118 len 00001ED0 (7 KiB): RTCRAM
I (269) spi_flash: detected chip: gd
I (269) spi_flash: flash io: dio
W (269) spi_flash: Detected size(8192k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (270) sleep_gpio: Configure to isolate all GPIO pins in sleep state
I (271) sleep_gpio: Enable automatic switching of GPIO sleep configuration
I (271) main_task: Started on CPU0
I (281) main_task: Calling app_main()
I (331) RCP_UPDATE: RCP: using update sequence 0
I (331) uart: ESP_INTR_FLAG_IRAM flag not set while CONFIG_UART_ISR_IN_IRAM is enabled, flag updated
I (331) OPENTHREAD: spinel UART interface initialization completed
I (331) main_task: Returned from app_main()
I(341) OPENTHREAD:[I] P-SpinelDrive-: co-processor reset: RESET_POWER_ON
E(341) OPENTHREAD:[C] P-SpinelDrive-: Software reset co-processor successfully
I(381) OPENTHREAD:[I] ChildSupervsn-: Timeout: 0 -> 190
I(391) OPENTHREAD:[I] Settings------: Read NetworkInfo {rloc:0xa800, extaddr:92fd023a0467599b, role:leader, mode:0x0f, version:5, keyseq:0x0, ...
I(401) OPENTHREAD:[I] Settings------: ... pid:0x52639581, mlecntr:0x7d8, maccntr:0x7d0, mliid:bf9006afdc475e59}
I (411) esp_ot_br: Internal RCP Version: openthread-esp32/8e4454b285-f32c18bc0; esp32h2;  2024-08-09 14:34:53 UTC
I (411) esp_ot_br: Running  RCP Version: openthread-esp32/8e4454b285-f32c18bc0; esp32h2;  2024-08-09 14:34:53 UTC
I (411) OPENTHREAD: OpenThread attached to netif
> I (441) esp_eth.netif.netif_glue: 48:ca:43:06:de:d3
I (441) esp_eth.netif.netif_glue: ethernet attached to netif
I (451) ethernet_connect: Waiting for IP(s).
> I (2451) ethernet_connect: Ethernet Link Up
I (3451) esp_netif_handlers: example_netif_eth ip: **redacted**, mask: 255.255.255.0, gw: **redacted**
I (3451) ethernet_connect: Got IPv4 event: Interface "example_netif_eth" address: **redacted**
I (4331) ethernet_connect: Got IPv6 event: Interface "example_netif_eth" address: fe80:0000:0000:0000:4aca:43ff:fe06:ded3, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I(4331) OPENTHREAD:[N] RoutingManager: BR ULA prefix: fd65:a53:7c64::/48 (loaded)
I(4341) OPENTHREAD:[N] RoutingManager: Local on-link prefix: fdde:ad00:beef:cafe::/64
I (4351) OPENTHREAD: Platform UDP bound to port 49153
I(4351) OPENTHREAD:[N] Mle-----------: Role disabled -> detached
I (4371) OT_STATE: netif up
I (4371) OPENTHREAD: NAT64 ready
I (4381) esp_ot_br: Network interface name: en2
I (4381) esp_ot_br: Connecting to wss://echo.websocket.events...
W (4381) websocket_client: `reconnect_timeout_ms` is not set, or it is less than or equal to zero, using default time out 10000 (milliseconds)
W (4391) websocket_client: `network_timeout_ms` is not set, or it is less than or equal to zero, using default time out 10000 (milliseconds)
E (4391) OT_DNS64: Cannot find NAT64 prefix
E (4391) esp-tls: couldn't get hostname for :echo.websocket.events: getaddrinfo() returns 202, addrinfo=0
E (4391) esp-tls: Failed to open new connection
E (4391) transport_base: Failed to open a new connection
E (4391) transport_ws: Error connecting to host echo.websocket.events:443
E (4401) websocket_client: esp_transport_connect() failed with -1, transport_error=ESP_ERR_ESP_TLS_CANNOT_RESOLVE_HOSTNAME, tls_error_code=0, tls_flags=0, esp_ws_handshake_status_code=0, errno=0
I (4401) esp_ot_br: WEBSOCKET_EVENT_ERROR
I (4401) websocket_client: Reconnect after 10000 ms
I (4401) esp_ot_br: WEBSOCKET_EVENT_DISCONNECTED
E (4401) esp_ot_br: Last error reported from esp-tls: 0x8001
E (4401) esp_ot_br: Last error reported from tls stack: 0x3fcb6564
I (5331) OPENTHREAD: Received RIO
I (5331) OPENTHREAD: prefix FD84:C890:3B8C:: lifetime 1800

I (5441) OPENTHREAD: Received RIO
I (5441) OPENTHREAD: prefix FD32:C77E:51A7:1:: lifetime 1800

I (5451) OPENTHREAD: Multicast listener add: FF05::2
I (5521) OPENTHREAD: Received RIO
I (5521) OPENTHREAD: prefix FD32:C77E:51A7:1:: lifetime 1800

I (5551) OPENTHREAD: Received RIO
I (5551) OPENTHREAD: prefix FD32:C77E:51A7:1:: lifetime 1800

I (5641) OPENTHREAD: Received RIO
I (5641) OPENTHREAD: prefix FD33:2DFB:12CA:1:: lifetime 1800

I (5751) OPENTHREAD: Received RIO
I (5751) OPENTHREAD: prefix FD32:C77E:51A7:1:: lifetime 1800

I (5751) OPENTHREAD: Multicast listener add: FF05::2
I (6651) OPENTHREAD: Multicast listener add: FF05::2
I (7331) ethernet_connect: Got IPv6 event: Interface "example_netif_eth" address: fd69:d7d7:61ad:eaad:4aca:43ff:fe06:ded3, type: ESP_IP6_ADDR_IS_UNIQUE_LOCAL
I (9471) OPENTHREAD: Received RIO
I (9471) OPENTHREAD: prefix FD84:C890:3B8C:: lifetime 1800

I (13811) OPENTHREAD: Received RIO
I (13811) OPENTHREAD: prefix FD84:C890:3B8C:: lifetime 1800

E (14411) OT_DNS64: Cannot find NAT64 prefix
E (14411) esp-tls: couldn't get hostname for :echo.websocket.events: getaddrinfo() returns 202, addrinfo=0
E (14411) esp-tls: Failed to open new connection
E (14411) transport_base: Failed to open a new connection
E (14411) transport_ws: Error connecting to host echo.websocket.events:443
E (14411) websocket_client: esp_transport_connect() failed with -1, transport_error=ESP_ERR_ESP_TLS_CANNOT_RESOLVE_HOSTNAME, tls_error_code=0, tls_flags=0, esp_ws_handshake_status_code=0, errno=0
I (14421) esp_ot_br: WEBSOCKET_EVENT_ERROR
E (14421) esp_ot_br: Last error reported from esp-tls: 0x8001
E (14421) esp_ot_br: Last error reported from tls stack: 0x3fcbb550
I (14421) websocket_client: Reconnect after 10000 ms
I (14421) esp_ot_br: WEBSOCKET_EVENT_DISCONNECTED
E (14421) esp_ot_br: Last error reported from tls stack: 0x3fcb6564
I (18081) OPENTHREAD: Received RIO
I (18081) OPENTHREAD: prefix FD84:C890:3B8C:: lifetime 1800

E (29421) OT_DNS64: Cannot find NAT64 prefix
E (29421) esp-tls: couldn't get hostname for :echo.websocket.events: getaddrinfo() returns 202, addrinfo=0
E (29421) esp-tls: Failed to open new connection
E (29421) transport_base: Failed to open a new connection
E (29421) transport_ws: Error connecting to host echo.websocket.events:443
E (29421) websocket_client: esp_transport_connect() failed with -1, transport_error=ESP_ERR_ESP_TLS_CANNOT_RESOLVE_HOSTNAME, tls_error_code=0, tls_flags=0, esp_ws_handshake_status_code=0, errno=0
I (29431) esp_ot_br: WEBSOCKET_EVENT_ERROR
E (29431) esp_ot_br: Last error reported from esp-tls: 0x8001
E (29431) esp_ot_br: Last error reported from tls stack: 0x3fcbb550
I (29431) websocket_client: Reconnect after 10000 ms
I (29431) esp_ot_br: WEBSOCKET_EVENT_DISCONNECTED
E (29431) esp_ot_br: Last error reported from tls stack: 0x3fcb6564
I(30651) OPENTHREAD:[N] Mle-----------: RLOC16 a800 -> fffe
I(30961) OPENTHREAD:[N] Mle-----------: Attach attempt 1, AnyPartition reattaching with Active Dataset
I(37521) OPENTHREAD:[N] RouterTable---: Allocate router id 42
I(37521) OPENTHREAD:[N] Mle-----------: RLOC16 fffe -> a800
I(37521) OPENTHREAD:[N] Mle-----------: Role detached -> leader
I(37531) OPENTHREAD:[N] Mle-----------: Partition ID 0x6cdb7184
I (37541) OPENTHREAD: Platform UDP bound to port 49154
I (38131) OPENTHREAD: Received RIO
I (38131) OPENTHREAD: prefix FD84:C890:3B8C:: lifetime 1800

I (38311) OPENTHREAD: Received RIO
I (38321) OPENTHREAD: prefix FD32:C77E:51A7:1:: lifetime 1800

I (38321) OPENTHREAD: Multicast listener add: FF05::2
I (38411) OPENTHREAD: Received RIO
I (38411) OPENTHREAD: prefix FD32:C77E:51A7:1:: lifetime 1800

I (38431) OPENTHREAD: Received RIO
I (38431) OPENTHREAD: prefix FD32:C77E:51A7:1:: lifetime 1800

I (38651) OPENTHREAD: Received RIO
I (38651) OPENTHREAD: prefix FD32:C77E:51A7:1:: lifetime 1800

I (38701) OPENTHREAD: Received RIO
I (38701) OPENTHREAD: prefix FD32:C77E:51A7:1:: lifetime 1800

I (38701) OPENTHREAD: Multicast listener add: FF05::2
I (39361) OPENTHREAD: Multicast listener add: FF05::2
I (40201) OPENTHREAD: Platform UDP bound to port 53536
I (40201) OPENTHREAD: Platform UDP bound to port 49155
I (41681) OT_STATE: Set dns server address: FD65:A53:7C64:2::101:101
I (42221) OPENTHREAD: Received RIO
I (42221) OPENTHREAD: prefix FD32:C77E:51A7:1:: lifetime 1800

I (42231) OPENTHREAD: Multicast listener add: FF05::2
I (42261) OPENTHREAD: Received RIO
I (42271) OPENTHREAD: prefix FD32:C77E:51A7:1:: lifetime 1800

I (42271) OPENTHREAD: Received RIO
I (42271) OPENTHREAD: prefix FD84:C890:3B8C:: lifetime 1800

I (42491) OPENTHREAD: Received RIO
I (42491) OPENTHREAD: prefix FD32:C77E:51A7:1:: lifetime 1800

I (42611) OPENTHREAD: Received RIO
I (42611) OPENTHREAD: prefix FD32:C77E:51A7:1:: lifetime 1800

I (42631) OPENTHREAD: Received RIO
I (42631) OPENTHREAD: prefix FD33:2DFB:12CA:1:: lifetime 1800

I (43011) OPENTHREAD: Multicast listener add: FF05::2
I (44771) esp-x509-crt-bundle: Certificate validated
I (46161) esp_ot_br: WEBSOCKET_EVENT_CONNECTED
I (47191) OPENTHREAD: Received RIO
I (47191) OPENTHREAD: prefix FD33:2DFB:12CA:1:: lifetime 1800

I (50261) esp_ot_br: WEBSOCKET_EVENT_DATA
I (50261) esp_ot_br: Received opcode=1
W (50261) esp_ot_br: Received=echo.websocket.events sponsored by Lob.com
W (50271) esp_ot_br: Total payload length=42, data_len=42, current payload offset=0

I (50271) esp_ot_br: WEBSOCKET_EVENT_DATA
I (50271) esp_ot_br: Received opcode=10
W (50271) esp_ot_br: Received=
W (50281) esp_ot_br: Total payload length=0, data_len=0, current payload offset=0

I (51451) OPENTHREAD: Received RIO
I (51451) OPENTHREAD: prefix FD84:C890:3B8C:: lifetime 1800

I (54401) esp_ot_br: Successfully sent message
I (55151) esp_ot_br: WEBSOCKET_EVENT_DATA
I (55151) esp_ot_br: Received opcode=2
W (55161) esp_ot_br: Received=
W (55161) esp_ot_br: Total payload length=50, data_len=50, current payload offset=0

E (62721) transport_base: poll_read select error 113, errno = Software caused connection abort, fd = 54
E (62721) websocket_client: esp_transport_poll_read() returned -1, transport_error=ESP_OK, tls_error_code=0, tls_flags=0, errno=119
I (62721) esp_ot_br: WEBSOCKET_EVENT_ERROR
I (62731) websocket_client: Reconnect after 10000 ms
I (62731) esp_ot_br: WEBSOCKET_EVENT_DISCONNECTED
E (62731) esp_ot_br: Last error reported from tls stack: 0xb33fffff
E (62741) esp_ot_br: Last error captured as transport's socket errno: 0x71
I (73051) esp-x509-crt-bundle: Certificate validated
E (83821) transport_ws: Error read response for Upgrade header GET / HTTP/1.1
Connection: Upgrade
Host: echo.websocket.events:443
User-Agent: ESP32 Websocket Client
Upgrade: websocket
Sec-WebSocket-Version: 13
Sec-WebSocket-Key: **redacted**


E (83821) websocket_client: esp_transport_connect() failed with -1, transport_error=ESP_OK, tls_error_code=0, tls_flags=0, esp_ws_handshake_status_code=101, errno=119
I (83831) esp_ot_br: WEBSOCKET_EVENT_ERROR
E (83831) esp_ot_br: Last error HTTP status code: 0x65
E (83831) esp_ot_br: Last error reported from tls stack: 0xb33fffff
I (83841) websocket_client: Reconnect after 10000 ms
I (83841) esp_ot_br: WEBSOCKET_EVENT_DISCONNECTED
E (83841) esp_ot_br: Last error HTTP status code: 0x65
I (94231) esp-x509-crt-bundle: Certificate validated
I (95641) esp_ot_br: WEBSOCKET_EVENT_CONNECTED
I (95671) esp_ot_br: WEBSOCKET_EVENT_DATA
I (95671) esp_ot_br: Received opcode=1
W (95671) esp_ot_br: Received=echo.websocket.events sponsored by Lob.com
W (95671) esp_ot_br: Total payload length=42, data_len=42, current payload offset=0


**redacted**@**redacted** ~/e/e/e/basic_thread_border_router (websocket-client-disconnects)>

Steps to reproduce the behavior

See #104 which replicates the issue. I have also reproduced the issue in a normal codebase (not the Thread Boarded Route codebase) and confirmed the issue does not occur there

Project release version

unreleased master

System architecture

ARM 64-bit (Apple M1/M2, Raspberry Pi 4/5)

Operating system

MacOS

Operating system version

Sonoma

Shell

Fish

Additional context

No response

[chshu]

@simondean Could you remove this line: https://github.com/espressif/esp-thread-br/blob/main/examples/common/thread_border_router/src/border_router_launch.c#L171, and try again? The issue seems caused by the default netif configuration.

[simondean]

Hi. I've just checked and it still happens if I remove this line:

    ESP_ERROR_CHECK(esp_netif_set_default_netif(openthread_netif));

Log output with line removed (same output as with line in place):

I (218429) esp_ot_br: WEBSOCKET_EVENT_CONNECTED
I (222289) esp_ot_br: WEBSOCKET_EVENT_DATA
I (222289) esp_ot_br: Received opcode=1
W (222289) esp_ot_br: Received=echo.websocket.events sponsored by Lob.com
W (222289) esp_ot_br: Total payload length=42, data_len=42, current payload offset=0

I (222309) esp_ot_br: WEBSOCKET_EVENT_DATA
I (222309) esp_ot_br: Received opcode=10
W (222309) esp_ot_br: Received=
W (222309) esp_ot_br: Total payload length=0, data_len=0, current payload offset=0

I (224439) esp_ot_br: Successfully sent message
I (234469) esp_ot_br: Successfully sent message
E (235299) transport_base: poll_read select error 113, errno = Software caused connection abort, fd = 54
E (235299) websocket_client: esp_transport_poll_read() returned -1, transport_error=ESP_OK, tls_error_code=0, tls_flags=0, errno=119
I (235299) esp_ot_br: WEBSOCKET_EVENT_ERROR
E (235299) esp_ot_br: Last error HTTP status code: 0x65
I (235299) websocket_client: Reconnect after 10000 ms
I (235309) esp_ot_br: WEBSOCKET_EVENT_DISCONNECTED
E (235309) esp_ot_br: Last error HTTP status code: 0x65
E (235309) esp_ot_br: Last error captured as transport's socket errno: 0x71
I (240319) OPENTHREAD: Received RIO
I (240319) OPENTHREAD: prefix FD84:C890:3B8C:: lifetime 1800

[chshu]

@simondean Do you have any update on the issue?

The logs didn't indicate any issue related to the BR feature, but some websocket issue, you can double check it using a Wi-Fi only device.