TLS stops working after initializing the SPI Master device (IDFGH-11065)

[DemTerritory]

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.2-dev-2756-g2bc1f2f574

Operating System used.

Windows

How did you build your project?

VS Code IDE

If you are using Windows, please specify command line type.

None

Development Kit.

ESP32-S3 LOLIN Mini

Power Supply used.

USB

What is the expected behavior?

If the SPI Master device is not initialized, then TLS works normally. After initialization SPI, TLS hangs and watchdog got triggered.

What is the actual behavior?

If the SPI Master device is not initialized, then TLS works normally. After initialization SPI, TLS hangs and watchdog got triggered.

Steps to reproduce.

If the SPI Master device is not initialized, then TLS works normally:
ret_bytes = esp_tls_conn_write(tls, header.c_str(), header.length()); // OK !!!

After initialization SPI, TLS hangs and watchdog got triggered:
ESP_ERROR_CHECK(spi_bus_initialize(DAC_HOST, &dac_bus_cfg, SPI_DMA_DISABLED)); // SPI_DMA_DISABLED !!!
...
ret_bytes = esp_tls_conn_write(tls, header.c_str(), header.length()); // hangs up !!!

In backtrace pay attention to "esp_aes_dma_wait_complete", despite the fact that I did not enable DMA for SPI

Debug Logs.

backtrace (pay attention to "esp_aes_dma_wait_complete"): 
E (8259) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
E (8259) task_wdt:  - IDLE (CPU 0)
E (8259) task_wdt: Tasks currently running:
E (8259) task_wdt: CPU 0: main
E (8259) task_wdt: CPU 1: IDLE
E (8259) task_wdt: Print CPU 0 (current core) backtrace

0x4200d67a: task_wdt_timeout_handling at C:/Users/Alex/.espressif/esp-idf/components/esp_system/task_wdt/task_wdt.c:461
 (inlined by) task_wdt_isr at C:/Users/Alex/.espressif/esp-idf/components/esp_system/task_wdt/task_wdt.c:585

0x40377331: _xt_lowint1 at C:/Users/Alex/.espressif/esp-idf/components/xtensa/xtensa_vectors.S:1236

0x42022ead: esp_aes_dma_wait_complete at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/dma/esp_aes.c:237
 (inlined by) esp_aes_process_dma at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/dma/esp_aes.c:454

0x420232ea: esp_aes_crypt_ctr at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/dma/esp_aes.c:1074

0x420246f2: esp_aes_gcm_update at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/esp_aes_gcm.c:481

0x420247f0: esp_aes_gcm_crypt_and_tag_partial_hw at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/esp_aes_gcm.c:578

0x42024837: esp_aes_gcm_crypt_and_tag at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/esp_aes_gcm.c:705

0x4201aefb: mbedtls_cipher_aead_encrypt at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/mbedtls/library/cipher.c:1350
 (inlined by) mbedtls_cipher_auth_encrypt_ext at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/mbedtls/library/cipher.c:1524

0x42015d81: mbedtls_ssl_encrypt_buf at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/mbedtls/library/ssl_msg.c:993

0x420163da: mbedtls_ssl_write_record at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/mbedtls/library/ssl_msg.c:2757

0x42016a1a: ssl_write_real at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/mbedtls/library/ssl_msg.c:5685
 (inlined by) mbedtls_ssl_write at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/mbedtls/library/ssl_msg.c:5721

0x42014707: esp_mbedtls_write at C:/Users/Alex/.espressif/esp-idf/components/esp-tls/esp_tls_mbedtls.c:266

0x420a2d16: esp_tls_conn_write at C:/Users/Alex/.espressif/esp-idf/components/esp-tls/esp_tls.c:137

0x42007f6d: app_main at C:/Distr/ESP-IDF/dac8562/main/main.cpp:428 (discriminator 13)

More Information.

No response

[DemTerritory]

Disabling SPI before sending data does not re-enable TLS (:

spi_bus_remove_device(dac_dev);
spi_bus_free(DAC_HOST);
ret_bytes = esp_tls_conn_write(tls, header.c_str(), header.length()); // Does not work

[ginkgm]

Hi @DemTerritory

Could you provide a minimal code to reproduce the issue? This will help us to locate the issue faster, thanks!

[DemTerritory]

I made a short demo of the error based on the "Wi-Fi Station Example". The result of his work: "Task watchdog got triggered". If you comment out "Initialize the SPI bus" then everything is ok.

[DemTerritory]

void app_main(void)
{
//Initialize NVS
esp_err_t ret = nvs_flash_init();
if (ret == ESP_ERR_NVS_NO_FREE_PAGES || ret == ESP_ERR_NVS_NEW_VERSION_FOUND) {
ESP_ERROR_CHECK(nvs_flash_erase());
ret = nvs_flash_init();
}
ESP_ERROR_CHECK(ret);

ESP_LOGI(TAG, "ESP_WIFI_MODE_STA");
wifi_init_sta();




// SPI config
#define DAC_HOST     SPI3_HOST
#define PIN_DAC_CLK  GPIO_NUM_35
#define PIN_DAC_MOSI GPIO_NUM_18
#define PIN_DAC_CS   GPIO_NUM_16

spi_device_handle_t dac_dev;
esp_err_t err;

spi_bus_config_t dac_bus_cfg = {
    .mosi_io_num = PIN_DAC_MOSI,
    .miso_io_num = -1,
    .sclk_io_num = PIN_DAC_CLK,
    .flags = SPICOMMON_BUSFLAG_MASTER | SPICOMMON_BUSFLAG_GPIO_PINS | SPICOMMON_BUSFLAG_MOSI | SPICOMMON_BUSFLAG_SCLK,
};
spi_device_interface_config_t dac_dev_cfg = {
    .command_bits = 0,
    .address_bits = 8,
    .mode = 1,                                  //SPI mode 1: (CPOL, CPHA)
    .clock_speed_hz = SPI_MASTER_FREQ_20M,
    .spics_io_num = PIN_DAC_CS,                 //CS pin
    .flags = SPI_DEVICE_3WIRE | SPI_DEVICE_NO_DUMMY,
    .queue_size = 1,
};
    

//Initialize the SPI bus
err = spi_bus_initialize(DAC_HOST, &dac_bus_cfg, SPI_DMA_DISABLED);
ESP_ERROR_CHECK(err);
ESP_LOGI(TAG, "SPI bus init");
err = spi_bus_add_device(DAC_HOST, &dac_dev_cfg, &dac_dev);
ESP_ERROR_CHECK(err);
ESP_LOGI(TAG, "SPI device init");



// TLS
tls_keep_alive_cfg_t keep_alive_cfg = {
    .keep_alive_enable = true,
    .keep_alive_idle = 1200,
    .keep_alive_interval = 300,
};
esp_tls_cfg_t tls_cfg = {
    .timeout_ms = INT32_MAX,
    .keep_alive_cfg = &keep_alive_cfg,
    .crt_bundle_attach = esp_crt_bundle_attach
};


esp_tls_t *tls = esp_tls_init();
if (tls)
    ESP_LOGI(TAG, "TSL init ok");
else 
    ESP_LOGE(TAG, "Failed TLS init!");

string part_url = "https://google.com";
const char *url = part_url.c_str();
ret = esp_tls_conn_http_new_sync(url, &tls_cfg, tls);
ESP_LOGI(TAG, "TLS/SSL connection open = %d", ret);



char *tls_response = (char *) heap_caps_calloc(200, 1, MALLOC_CAP_8BIT);
assert(tls_response);

uint32_t return_bytes;
string test_header;
test_header = "POST / HTTP/1.1\r\n"
                "Host: google.com\r\n"
                "Content-Type: application/json\r\n"
                "Connection: keep-alive\r\n"
                "Content-Length: 6\r\n\r\n"
                "\"test\"";
return_bytes = esp_tls_conn_write(tls, test_header.c_str(), test_header.length());
ESP_LOGI(TAG, "post_data ret = %lu", return_bytes);
ESP_LOGI(TAG, "Data transfered");
return_bytes = esp_tls_conn_read(tls, tls_response, 200);
ESP_LOGI(TAG, "response read = %lu", return_bytes);

}

[DemTerritory]

I (1608) wifi station: connected to ap SSID:Misty password:qwerty
I (1618) wifi station: SPI bus init
I (1618) wifi station: SPI device init
I (1618) wifi station: TSL init ok
I (1938) esp-x509-crt-bundle: Certificate validated
I (2488) wifi station: TLS/SSL connection open = 1
E (7488) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
E (7488) task_wdt: - IDLE (CPU 0)
E (7488) task_wdt: Tasks currently running:
E (7488) task_wdt: CPU 0: main
E (7488) task_wdt: CPU 1: IDLE
E (7488) task_wdt: Print CPU 0 (current core) backtrace

Backtrace: 0x4200C03A:0x3FC98850 0x40377259:0x3FC98880 0x42077ACD:0x3FCA27C0 0x420220D9:0x3FCA27E0 0x42022502:0x3FCA2820 0x4202390A:0x3FCA2850 0x42023A08:0x3FCA28B0 0x42023A4F:0x3FCA28E0 0x4201A357:0x3FCA2920 0x42013E01:0x3FCA2960 0x42014433:0x3FCA2A10 0x42014A6E:0x3FCA2A50 0x420133C4:0x3FCA2A70 0x420766DA:0x3FCA2AA0 0x4200828D:0x3FCA2AC0 0x4207C7A3:0x3FCA2BE0
0x4200c03a: task_wdt_timeout_handling at C:/Users/Alex/.espressif/esp-idf/components/esp_system/task_wdt/task_wdt.c:461
(inlined by) task_wdt_isr at C:/Users/Alex/.espressif/esp-idf/components/esp_system/task_wdt/task_wdt.c:585

0x40377259: _xt_lowint1 at C:/Users/Alex/.espressif/esp-idf/components/xtensa/xtensa_vectors.S:1236

0x42077acd: esp_aes_dma_done at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/dma/esp_aes_gdma_impl.c:18

0x420220d9: esp_aes_wait_dma_done at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/dma/esp_aes.c:118
(inlined by) esp_aes_dma_wait_complete at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/dma/esp_aes.c:239
(inlined by) esp_aes_process_dma at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/dma/esp_aes.c:454

0x42022502: esp_aes_crypt_ctr at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/dma/esp_aes.c:1074

0x4202390a: esp_aes_gcm_update at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/esp_aes_gcm.c:481

0x42023a08: esp_aes_gcm_crypt_and_tag_partial_hw at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/esp_aes_gcm.c:578

0x42023a4f: esp_aes_gcm_crypt_and_tag at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/port/aes/esp_aes_gcm.c:705

0x4201a357: mbedtls_cipher_aead_encrypt at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/mbedtls/library/cipher.c:1350
(inlined by) mbedtls_cipher_auth_encrypt_ext at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/mbedtls/library/cipher.c:1524

0x42013e01: mbedtls_ssl_encrypt_buf at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/mbedtls/library/ssl_msg.c:993

0x42014433: mbedtls_ssl_write_record at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/mbedtls/library/ssl_msg.c:2757

0x42014a6e: ssl_write_real at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/mbedtls/library/ssl_msg.c:5685
(inlined by) mbedtls_ssl_write at C:/Users/Alex/.espressif/esp-idf/components/mbedtls/mbedtls/library/ssl_msg.c:5721

0x420133c4: esp_mbedtls_write at C:/Users/Alex/.espressif/esp-idf/components/esp-tls/esp_tls_mbedtls.c:266 (discriminator 15)

0x420766da: esp_tls_conn_write at C:/Users/Alex/.espressif/esp-idf/components/esp-tls/esp_tls.c:137

0x4200828d: app_main at C:/Distr/ESP-IDF/tls_error_demo/main/tls_error_demo.cpp:272

0x4207c7a3: main_task at C:/Users/Alex/.espressif/esp-idf/components/freertos/app_startup.c:208 (discriminator 13)

[DemTerritory]

Are you going to fix this bug? I have an additional clarification to this issue. The TLS hang only occurs when the spi bus is initialized in SPI_DMA_DISABLED mode. If the mode is SPI_DMA_CH_AUTO, then TLS works correctly. I have to use DMA to send/receive two bytes to get around the bug

[kayzen9]

try creting separate task for tls operation with large stack. I had same problem when doing tls operation in app_main, it can fail due to small stack. ..

[DemTerritory]

I have provided above a simple example demonstrating this error. It does not launch additional tasks, it does not limit or allocate memory, but it freezes TLS after SPI initialization. No, the problem here is not with memory, the problem is with the SPI driver, which breaks something in DMA. The encryption functions in the ESP32-S3 are implemented in hardware and are invoked using DMA. The SPI driver can also use DMA. When initialized in SPI_DMA_DISABLED mode, SPI should not touch anything in DMA, but it still does something there and breaks DMA. The log shows that the watchdog timer is triggered because the call "esp_aes_wait_dma_done" was waiting too long for completion.

Yes, I tried in my program to increase the stack of a task that sends results via TLS. There were 4000 bytes, I made 14000 bytes, then 24000, 34000 - the result did not change

[ginkgm]

Hi @DemTerritory ,

Thanks for detailed issue report, your information helped a lot! We have confirmed this is an issue in the SPI driver.

Here's the fix in review:

From 83152215232b048aa510330eae2ef17d1bd8041d Mon Sep 17 00:00:00 2001
From: Xiao Xufeng <[email protected]>
Date: Tue, 24 Oct 2023 02:52:51 +0800
Subject: [PATCH] fix(spi): fixed undesired touching to DMA

Closes https://github.com/espressif/esp-idf/issues/12241
---
 components/hal/spi_hal.c          | 4 +++-
 components/hal/spi_slave_hal.c    | 4 +++-
 components/hal/spi_slave_hd_hal.c | 4 +++-
 3 files changed, 9 insertions(+), 3 deletions(-)

diff --git a/components/hal/spi_hal.c b/components/hal/spi_hal.c
index d928fe997e48..25b77b8ef6b3 100644
--- a/components/hal/spi_hal.c
+++ b/components/hal/spi_hal.c
@@ -71,7 +71,9 @@ void spi_hal_init(spi_hal_context_t *hal, uint32_t host_id, const spi_hal_config
     spi_ll_set_mosi_free_level(hw, 0);
 #endif
     spi_ll_master_init(hw);
-    s_spi_hal_dma_init_config(hal);
+    if (config->dma_enabled) {
+        s_spi_hal_dma_init_config(hal);
+    }
 
     //Force a transaction done interrupt. This interrupt won't fire yet because
     //we initialized the SPI interrupt as disabled. This way, we can just
diff --git a/components/hal/spi_slave_hal.c b/components/hal/spi_slave_hal.c
index 7c437a0b3fa3..9d61e12042af 100644
--- a/components/hal/spi_slave_hal.c
+++ b/components/hal/spi_slave_hal.c
@@ -41,7 +41,9 @@ void spi_slave_hal_init(spi_slave_hal_context_t *hal, const spi_slave_hal_config
     hal->dma_in = hal_config->dma_in;
     hal->dma_out = hal_config->dma_out;
 
-    s_spi_slave_hal_dma_init_config(hal);
+    if (hal->use_dma) {
+        s_spi_slave_hal_dma_init_config(hal);
+    }
     spi_ll_slave_init(hal->hw);
 
     //Force a transaction done interrupt. This interrupt won't fire yet because we initialized the SPI interrupt as
diff --git a/components/hal/spi_slave_hd_hal.c b/components/hal/spi_slave_hd_hal.c
index c2bf88a5597b..81a5bf5dfacc 100644
--- a/components/hal/spi_slave_hd_hal.c
+++ b/components/hal/spi_slave_hd_hal.c
@@ -71,7 +71,9 @@ void spi_slave_hd_hal_init(spi_slave_hd_hal_context_t *hal, const spi_slave_hd_h
     hal->rx_dma_head = &hal->rx_dummy_head;
 
     //Configure slave
-    s_spi_slave_hd_hal_dma_init_config(hal);
+    if (hal_config->dma_enabled) {
+        s_spi_slave_hd_hal_dma_init_config(hal);
+    }
 
     spi_ll_slave_hd_init(hw);
     spi_ll_set_addr_bitlen(hw, hal_config->address_bits);
-- 
GitLab

Hopefully this will show up on Github soon. If you still find problems with the patch above, please poke me.

Thanks again!

Michael

[DemTerritory]

Yes this fix works for me.
TLS + spi_bus_initialize (SPICOMMON_BUSFLAG_MASTER, SPI_DMA_DISABLED) now works. Thank you!

[ginkgm]

You are welcome!