pipeline_tcp_client example is crashing and resetting (AUD-3891)

[spaceMan00]

esp-adf: v2.4 Hardware: Lyrat v4.3

The example pipeline_tcp_client is throwing error: E (4153) TRANSPORT_BASE: Failed to open a new connection: 258 and then it is rebooting. I am running successfully the python script tcp_server.py and it's giving the following log: Get the esp32.mp3 size is 11212301 starting listen on ip 192.168.0.109, port 1212 waiting for client to connect

I tried to connect to the tcp server using a 3rd party app and I was able to successfully download the mp3 file which indicates the issue is not from the python server.

Here are the ESP32 logs:

I (27) boot: ESP-IDF v4.4-329-g3c9657fa4e-dirty 2nd stage bootloader I (27) boot: compile time 21:51:36 I (27) boot: chip revision: 3 I (32) boot_comm: chip revision: 3, min. bootloader chip revision: 0 I (39) boot.esp32: SPI Speed : 40MHz I (43) boot.esp32: SPI Mode : DIO I (48) boot.esp32: SPI Flash Size : 8MB I (52) boot: Enabling RNG early entropy source... I (58) boot: Partition Table: I (61) boot: ## Label Usage Type ST Offset Length I (69) boot: 0 nvs WiFi data 01 02 00009000 00004000 I (76) boot: 1 phy_init RF data 01 01 0000d000 00001000 I (84) boot: 2 factory factory app 00 00 00010000 00300000 I (91) boot: End of partition table I (95) boot_comm: chip revision: 3, min. application chip revision: 0 I (102) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=22c5ch (142428) map I (163) esp_image: segment 1: paddr=00032c84 vaddr=3ffb0000 size=03900h ( 14592) load I (169) esp_image: segment 2: paddr=0003658c vaddr=40080000 size=09a8ch ( 39564) load I (185) esp_image: segment 3: paddr=00040020 vaddr=400d0020 size=9fd5ch (654684) map I (422) esp_image: segment 4: paddr=000dfd84 vaddr=40089a8c size=0ce5ch ( 52828) load I (444) esp_image: segment 5: paddr=000ecbe8 vaddr=50000000 size=00010h ( 16) load I (455) boot: Loaded app from partition at offset 0x10000 I (456) boot: Disabling RNG early entropy source... I (467) cpu_start: Pro cpu up. I (467) cpu_start: Starting app cpu, entry point is 0x40081388 0x40081388: call_start_cpu1 at /Users/bassamjalgha/Documents/Source/firmwares/firmware-roadie-coach-adf/esp-adf/esp-idf/components/esp_system/port/cpu_start.c:160

I (454) cpu_start: App cpu up. I (481) cpu_start: Pro cpu start user code I (482) cpu_start: cpu freq: 160000000 I (482) cpu_start: Application information: I (486) cpu_start: Project name: tcp_client_example I (492) cpu_start: App version: 1 I (496) cpu_start: Compile time: Jun 20 2022 21:56:41 I (502) cpu_start: ELF file SHA256: 5940d0778723fcda... I (508) cpu_start: ESP-IDF: v4.4-329-g3c9657fa4e-dirty I (515) heap_init: Initializing. RAM available for dynamic allocation: I (522) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM I (528) heap_init: At 3FFB7858 len 000287A8 (161 KiB): DRAM I (535) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (541) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (547) heap_init: At 400968E8 len 00009718 (37 KiB): IRAM I (555) spi_flash: detected chip: gd I (558) spi_flash: flash io: dio I (563) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (633) TCP_CLIENT_EXAMPLE: [ 1 ] Start codec chip I (663) TCP_CLIENT_EXAMPLE: [2.0] Create audio pipeline for playback I (663) TCP_CLIENT_EXAMPLE: [2.1] Create i2s stream to write data to codec chip I (663) TCP_CLIENT_EXAMPLE: [2.2] Create mp3 decoder to decode mp3 file I (673) TCP_CLIENT_EXAMPLE: [2.2] Create tcp client stream to read data I (683) TCP_CLIENT_EXAMPLE: [2.3] Register all elements to audio pipeline I (683) TCP_CLIENT_EXAMPLE: [2.4] Link it together tcp-->mp3-->i2s I (693) TCP_CLIENT_EXAMPLE: [ 3 ] Start and wait for Wi-Fi network E (703) gpio: gpio_install_isr_service(449): GPIO isr service already installed W (2803) PERIPH_WIFI: WiFi Event cb, Unhandle event_base:WIFI_EVENT, event_id:4 W (2813) wifi:idx:0 (ifx:0, e8:48:b8:80:26:c3), tid:0, ssn:2, winSize:64 I (4133) TCP_CLIENT_EXAMPLE: [ 4 ] Set up event listener I (4133) TCP_CLIENT_EXAMPLE: [4.1] Listening event from all elements of pipeline I (4133) TCP_CLIENT_EXAMPLE: [4.2] Listening event from peripherals I (4143) TCP_CLIENT_EXAMPLE: [ 5 ] Start audio_pipeline E (4153) TRANSPORT_BASE: Failed to open a new connection: 258 Guru Meditation Error: Core 0 panic'ed (StoreProhibited). Exception was unhandled.

Core 0 register dump: PC : 0x40112b31 PS : 0x00060c30 A0 : 0x8016b78c A1 : 0x3ffce070
0x40112b31: tcp_connect at /Users/bassamjalgha/Documents/Source/firmwares/firmware-roadie-coach-adf/esp-adf/esp-idf/components/tcp_transport/transport_ssl.c:132 (discriminator 3)

A2 : 0x00000102 A3 : 0x3f403484 A4 : 0x000004bc A5 : 0x000003e8
A6 : 0x3ffd1494 A7 : 0x00000000 A8 : 0x80112b31 A9 : 0x3ffce020
A10 : 0x00000001 A11 : 0x3f416ab0 A12 : 0x3f416b08 A13 : 0x00001039
A14 : 0x3f416ab0 A15 : 0x00000102 SAR : 0x00000004 EXCCAUSE: 0x0000001d
EXCVADDR: 0x00000000 LBEG : 0x400014fd LEND : 0x4000150d LCOUNT : 0xfffffffc

Backtrace:0x40112b2e:0x3ffce0700x4016b789:0x3ffce0a0 0x400db821:0x3ffce0c0 0x400d7f8e:0x3ffce0f0 0x400d846c:0x3ffce120 0x400d856e:0x3ffce140 0x400d93bd:0x3ffce170 0x400d876b:0x3ffce1b0 0x4008d909:0x3ffce1e0 0x40112b2e: tcp_connect at /Users/bassamjalgha/Documents/Source/firmwares/firmware-roadie-coach-adf/esp-adf/esp-idf/components/tcp_transport/transport_ssl.c:131 (discriminator 3)

0x4016b789: esp_transport_connect at /Users/bassamjalgha/Documents/Source/firmwares/firmware-roadie-coach-adf/esp-adf/esp-idf/components/tcp_transport/transport.c:173

0x400db821: _tcp_open at /Users/bassamjalgha/Documents/Source/firmwares/firmware-roadie-coach-adf/esp-adf/components/audio_stream/tcp_client_stream.c:92 (discriminator 2)

0x400d7f8e: audio_element_process_init at /Users/bassamjalgha/Documents/Source/firmwares/firmware-roadie-coach-adf/esp-adf/components/audio_pipeline/audio_element.c:175

0x400d846c: audio_element_on_cmd_resume at /Users/bassamjalgha/Documents/Source/firmwares/firmware-roadie-coach-adf/esp-adf/components/audio_pipeline/audio_element.c:279

0x400d856e: audio_element_on_cmd at /Users/bassamjalgha/Documents/Source/firmwares/firmware-roadie-coach-adf/esp-adf/components/audio_pipeline/audio_element.c:320 (discriminator 13)

0x400d93bd: audio_event_iface_waiting_cmd_msg at /Users/bassamjalgha/Documents/Source/firmwares/firmware-roadie-coach-adf/esp-adf/components/audio_pipeline/audio_event_iface.c:246

0x400d876b: audio_element_task at /Users/bassamjalgha/Documents/Source/firmwares/firmware-roadie-coach-adf/esp-adf/components/audio_pipeline/audio_element.c:473

0x4008d909: vPortTaskWrapper at /Users/bassamjalgha/Documents/Source/firmwares/firmware-roadie-coach-adf/esp-adf/esp-idf/components/freertos/port/xtensa/port.c:131

[HengYongChao]

Hi @spaceMan00

I (4143) TCP_CLIENT_EXAMPLE: [ 5 ] Start audio_pipeline
E (4153) TRANSPORT_BASE: Failed to open a new connection: 258
Guru Meditation Error: Core 0 panic'ed (StoreProhibited). Exception was unhandled.

Error number 258 means #define ESP_ERR_INVALID_ARG 0x102 /*!< Invalid argument */.

I guess the parameters for
esp_tls_plain_tcp_connect is null. And EXCVADDR: 0x00000000 value also proved it.

Please check the sockfd and error_handle paramters.

[spaceMan00]

Hello @HengYongChao,

ssl->sockfd is -1 and err_handle is NULL (which is what is causing the reset as it seems not to be handled).

The reason it is NULL is because t->base is NULL in esp_transport_get_error_handle.

What does this mean? And how can I solve this? Thank you for the help.

[soloex1991eric]

Did you manage to find a solution?

[spaceMan00]

Not yet, I'm waiting to see if @HengYongChao has any suggestions.

[soloex1991eric]

Not yet, I'm waiting to see if @HengYongChao has any suggestions.

Noted, thanks

[HengYongChao]

Hi @spaceMan00

static int tcp_connect(esp_transport_handle_t t, const char *host, int port, int timeout_ms)
{
    transport_esp_tls_t *ssl = ssl_get_context_data(t);
    esp_tls_last_error_t *err_handle = esp_transport_get_error_handle(t);

    ssl->cfg.timeout_ms = timeout_ms;
    esp_err_t err = esp_tls_plain_tcp_connect(host, strlen(host), port, &ssl->cfg, err_handle, &ssl->sockfd);
    if (err != ESP_OK) {
        ESP_LOGE(TAG, "Failed to open a new connection: %d", err);
        err_handle->last_error = err;
        ssl->sockfd = INVALID_SOCKET;
        return -1;
    }
    return 0;
}

I can't reproduce your problem locally. But I guess, as I mentioned earlier, your problem is that the parameter check of this esp_tls_plain_tcp_connect() function is not passed, you can check the parameters you pass in, please add print code to debug above parameters.

[spaceMan00]

@HengYongChao The parameter err_handle of esp_tls_plain_tcp_connect is NULL which is causing the problem. The reason it is NULL is because t->base is NULL in esp_transport_get_error_handle. Why would it be NULL? I am using the example provided in esp-adf: v2.4 with ESP-IDF v4.4. I didn't customize.

[piligrim-a3]

Parameter error_handle fill in method esp_transport_list_add. Method _esp_err_t tcp_open in file tcp_client_stream.c.

static esp_err_t _tcp_open(audio_element_handle_t self)
{
    AUDIO_NULL_CHECK(TAG, self, return ESP_FAIL);

    tcp_stream_t *tcp = (tcp_stream_t *)audio_element_getdata(self);
    if (tcp->is_open) {
        ESP_LOGE(TAG, "Already opened");
        return ESP_FAIL;
    }
    ESP_LOGI(TAG, "Host is %s, port is %d\n", tcp->host, tcp->port);
    esp_transport_handle_t t = esp_transport_tcp_init();
    esp_transport_list_handle_t transport_list = esp_transport_list_init();
    esp_transport_list_add(transport_list, t, "http");
    AUDIO_NULL_CHECK(TAG, t, return ESP_FAIL);
    tcp->sock = esp_transport_connect(t, tcp->host, tcp->port, CONNECT_TIMEOUT_MS);
    if (tcp->sock < 0) {
        _get_socket_error_code_reason(__func__,  tcp->sock);
        esp_transport_destroy(t);
        esp_transport_list_destroy(transport_list);
        return ESP_FAIL;
    }
    tcp->is_open = true;
    tcp->t = t;
    _dispatch_event(self, tcp, NULL, 0, TCP_STREAM_STATE_CONNECTED);

    return ESP_OK;
}

But the problem of freeing memory remains.

[spaceMan00]

This solves it. Thank you @piligrim-a3. I am freeing by adding the transport_list handle to tcp_stream_t and destroying it in _tcp_destroy. I really hope someone will PR a proper fix for this.

[HengYongChao]

Hi @spaceMan00 @piligrim-a3 We refind this issue, will fix asap.

[jason-mao]

It has been fixed on e794786c748795d81aea4ac84c3dab06bf9caf63