Watchdog triggering on esp_rmaker_param_update_and_report in timer (MEGH-2604)

[chmoore889]

Following an update to ESP IDF version 4.3 from some older version (4.1 or 4.2 can't quite remember) and pulling the latest version of ESP Rainmaker, a particular call to esp_rmaker_param_update_and_report started triggering the watchdog and showing the following error, which traces back to the following code, which is within the callback for an esp_timer. All other calls to the function work fine.

My whole application was working in the older versions of IDF and Rainmaker that I was using. I saw nothing in the changelogs that indicated breaking changes related to this function. I've tried disabling the watchdog just to see if it was taking too long, but it just blocks forever instead of the watchdog triggering.

Logs:

I (31349) app_driver: Here
I (31349) esp_rmaker_param: Reporting params: {"quick_run":{"prog":[600,600,600,600,600,600,600,600,600,600]}}
E (36339) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (36339) task_wdt: - IDLE (CPU 0)
E (36339) task_wdt: Tasks currently running:
E (36339) task_wdt: CPU 0: esp_timer
E (36339) task_wdt: Print CPU 0 (current core) backtrace


Backtrace:0x400C98A7:0x3FFCA200 0x4002671E:0x3FFCA220 0x40114D3C:0x3FF9F7C0 0x400E7B21:0x3FF9F7E0 0x400E7D8B:0x3FF9F800 0x400E8676:0x3FF9F880 0x400E9FEE:0x3FF9F8B0 0x400EA0BA:0x3FF9F910 0x400EA133:0x3FF9F930 0x400DD9BD:0x3FF9F9B0 0x400D5E19:0x3FF9F9F0 0x400D601D:0x3FF9FA80 0x400D668D:0x3FF9FAA0 0x400D66C1:0x3FF9FAC0 0x400D671D:0x3FF9FAE0 0x400D7ACB:0x3FF9FB00 0x400CDAF8:0x3FF9FB20 0x400CEBA8:0x3FF9FB40 0x40136DA5:0x3FF9FB70 0x400A0D66:0x3FF9FB90 0x400A298B:0x3FF9FBC0 0x400A0215:0x3FF9FC10 0x4008E009:0x3FF9FC30 0x4008B41D:0x3FF9FC50 0x4008B81C:0x3FF9FC70 0x4008B845:0x3FF9FC90 0x40089EA1:0x3FF9FCC0 0x400885B9:0x3FF9FD20 0x400885E2:0x3FF9FD50 0x40030609:0x3FF9FD70
0x400c98a7: task_wdt_isr at C:/esp/esp-idf/components/esp_common/src/task_wdt.c:189

0x4002671e: _xt_lowint1 at C:/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1105

0x40114d3c: aes_ll_get_state at C:/esp/esp-idf/components/hal/esp32s2/include/hal/aes_ll.h:140 (discriminator 1)
(inlined by) aes_hal_wait_done at C:/esp/esp-idf/components/hal/aes_hal.c:92 (discriminator 1)

0x400e7b21: esp_aes_dma_wait_complete at C:/esp/esp-idf/components/mbedtls/port/aes/dma/esp_aes.c:205

0x400e7d8b: esp_aes_process_dma at C:/esp/esp-idf/components/mbedtls/port/aes/dma/esp_aes.c:409

0x400e8676: esp_aes_crypt_ctr at C:/esp/esp-idf/components/mbedtls/port/aes/dma/esp_aes.c:1001

0x400e9fee: esp_aes_gcm_update at C:/esp/esp-idf/components/mbedtls/port/aes/esp_aes_gcm.c:454

0x400ea0ba: esp_aes_gcm_crypt_and_tag_partial_hw at C:/esp/esp-idf/components/mbedtls/port/aes/esp_aes_gcm.c:536

0x400ea133: esp_aes_gcm_crypt_and_tag at C:/esp/esp-idf/components/mbedtls/port/aes/esp_aes_gcm.c:569

0x400dd9bd: mbedtls_cipher_auth_encrypt at C:/esp/esp-idf/components/mbedtls/mbedtls/library/cipher.c:1073

0x400d5e19: ssl_encrypt_buf at C:/esp/esp-idf/components/mbedtls/mbedtls/library/ssl_tls.c:1624

0x400d601d: mbedtls_ssl_write_record at C:/esp/esp-idf/components/mbedtls/mbedtls/library/ssl_tls.c:3492

0x400d668d: ssl_write_real at C:/esp/esp-idf/components/mbedtls/mbedtls/library/ssl_tls.c:8750

0x400d66c1: ssl_write_split at C:/esp/esp-idf/components/mbedtls/mbedtls/library/ssl_tls.c:8780

0x400d671d: mbedtls_ssl_write at C:/esp/esp-idf/components/mbedtls/mbedtls/library/ssl_tls.c:8828

0x400d7acb: __wrap_mbedtls_ssl_write at C:/esp/esp-idf/components/mbedtls/port/dynamic/esp_ssl_tls.c:75 (discriminator 62)

0x400cdaf8: esp_mbedtls_write at C:/esp/esp-idf/components/esp-tls/esp_tls_mbedtls.c:185 (discriminator 15)

0x400ceba8: esp_tls_conn_write at C:/esp/esp-idf/components/esp-tls/esp_tls.h:476
(inlined by) ssl_write at C:/esp/esp-idf/components/tcp_transport/transport_ssl.c:147

0x40136da5: esp_transport_write at C:/esp/esp-idf/components/tcp_transport/transport.c:178

0x400a0d66: mqtt_write_data at C:/esp/esp-idf/components/mqtt/esp-mqtt/mqtt_client.c:868

0x400a298b: esp_mqtt_client_publish at C:/esp/esp-idf/components/mqtt/esp-mqtt/mqtt_client.c:1719

0x400a0215: esp_mqtt_glue_publish at C:/esp/esp-rainmaker/components/rmaker_common/src/esp-mqtt/esp-mqtt-glue.c:144 (discriminator 15)

0x4008e009: esp_rmaker_mqtt_publish at C:/esp/esp-rainmaker/components/esp_rainmaker/src/mqtt/esp_rmaker_mqtt.c:88

0x4008b41d: esp_rmaker_report_param_internal at C:/esp/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_param.c:224

0x4008b81c: esp_rmaker_param_report at C:/esp/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_param.c:659

0x4008b845: esp_rmaker_param_update_and_report at C:/esp/esp-rainmaker/components/esp_rainmaker/src/core/esp_rmaker_param.c:667

0x40089ea1: timer_cb at c:\users\christopher\desktop\sprinkler\firmware\build/../main/app_driver.c:79

0x400885b9: timer_process_alarm at C:/esp/esp-idf/components/esp_timer/src/esp_timer.c:330

0x400885e2: timer_task at C:/esp/esp-idf/components/esp_timer/src/esp_timer.c:349 (discriminator 1)

0x40030609: vPortTaskWrapper at C:/esp/esp-idf/components/freertos/port/xtensa/port.c:168

Code:

ESP_LOGI(TAG, "Here");
esp_rmaker_param_update_and_report(info->run_prog_param, esp_rmaker_array(json));
ESP_LOGI(TAG, "Here2");

[shahpiyushv]

@chmoore889 , esp_timer is actually recommended only when you require high accuracy. This same timer also gets used for Wi-Fi and some other tasks. To be on safer side, it is better to use the FreeRTOS timer instead. Similar change was done in the temperature sensor example here. Can you try that?

[chmoore889]

@shahpiyushv Great thanks! Using the FreeRTOS timer solved the issue. I think it might be beneficial to note somewhere in the documentation that using esp_rmaker_param_update_and_report in esp_timer callbacks might have this issue.

[miroslavpetrov]

I know the issue is closed but I am experiencing exactly the same issue. However, I am using the TimerHandle_t and not esp_timer. This is my app_sensor_update function which is based on the one found in the app_diver.c in temperature sensor example

`static void app_sensor_update(TimerHandle_t handle)
{

//Get Temperature
wakeup_sensor(SENSOR_ADDR);
float temperature = 0, humidity = 0;
read_out(SENSOR_ADDR, T_FIRST_N, &temperature, &humidity);
sleep_sensor(SENSOR_ADDR);
// Report Data
esp_rmaker_param_update_and_report(
esp_rmaker_device_get_param_by_type(switch_device, ESP_RMAKER_PARAM_TEMPERATURE),
esp_rmaker_float(temperature));

// Get Voltage and Current
EM_Meas meas;
ade_acquire(&meas);
// Report data
esp_rmaker_param_update_and_report(esp_rmaker_device_get_param_by_type(switch_device, ESP_RMAKER_PARAM_VOLTAGE),esp_rmaker_float(meas.RMS.sVoltage.A));
esp_rmaker_param_update_and_report(esp_rmaker_device_get_param_by_type(switch_device, ESP_RMAKER_PARAM_CURRENT),esp_rmaker_float(meas.RMS.sCurrent.A));

}`

I am attaching a screenshot of the serial output. Please ignore the i2c driver install error. This was fixed, but the problem with esp_timer persists.

[shahpiyushv]

@miroslavpetrov , a crude approach, but can you add some prints before and after these calls and also enabled the idf level debug logs so that we get more info?

[miroslavpetrov]

@shahpiyushv

this is the debug level log

D (2094726) MQTT_CLIENT: received MQTT_MSG_TYPE_PUBACK, finish QoS1 publish D (2094736) esp_mqtt_glue: MQTT_EVENT_PUBLISHED, msg_id=28693 D (2094746) event: no handlers have been registered for event RMAKER_COMMON_EVENT:5 posted to loop 0x3fca25d8 D (2096336) SSL TLS: add mbedtls RX buffer D (2096336) SSL TLS: end D (2096336) SSL TLS: RX left 3 bytes D (2096336) MQTT_CLIENT: mqtt_message_receive: first byte: 0x40 D (2096346) TRANS_SSL: remain data in cache, need to read again D (2096346) SSL TLS: add mbedtls RX buffer D (2096356) SSL TLS: end D (2096356) SSL TLS: RX left 2 bytes D (2096356) MQTT_CLIENT: mqtt_message_receive: read "remaining length" byte: 0x2 D (2096366) MQTT_CLIENT: mqtt_message_receive: total message length: 4 (already read: 2) D (2096376) TRANS_SSL: remain data in cache, need to read again D (2096376) SSL TLS: add mbedtls RX buffer D (2096386) SSL TLS: end D (2096386) MQTT_CLIENT: mqtt_message_receive: read_len=2 D (2096396) MQTT_CLIENT: mqtt_message_receive: transport_read():4 4 D (2096396) MQTT_CLIENT: msg_type=4, msg_id=28693 D (2096406) MQTT_CLIENT: pending_id=28693, pending_msg_count = 0 D (2097336) SSL TLS: add mbedtls RX buffer D (2097336) SSL TLS: end D (2097336) SSL TLS: RX left 3 bytes D (2097336) MQTT_CLIENT: mqtt_message_receive: first byte: 0x40 D (2097336) TRANS_SSL: remain data in cache, need to read again D (2097346) SSL TLS: add mbedtls RX buffer D (2097346) SSL TLS: end D (2097346) SSL TLS: RX left 2 bytes D (2097356) MQTT_CLIENT: mqtt_message_receive: read "remaining length" byte: 0x2 D (2097356) MQTT_CLIENT: mqtt_message_receive: total message length: 4 (already read: 2) D (2097366) TRANS_SSL: remain data in cache, need to read again D (2097376) SSL TLS: add mbedtls RX buffer D (2097376) SSL TLS: end D (2097386) MQTT_CLIENT: mqtt_message_receive: read_len=2 D (2097386) MQTT_CLIENT: mqtt_message_receive: transport_read():4 4 D (2097396) MQTT_CLIENT: msg_type=4, msg_id=28693 D (2097396) MQTT_CLIENT: pending_id=28693, pending_msg_count = 0 Temperature: 31.61 C, Humidity: 31.75 I (2100876) esp_rmaker_param: Reporting params: {"Switch":{"Temperature":31.60522}} D (2100876) esp_mqtt_glue: Publishing to node/22CXafcYvFiiVAkLsWDcRF/params/local D (2100886) MQTT_CLIENT: mqtt_enqueue id: 6167, type=3 successful D (2100886) OUTBOX: ENQUEUE msgid=6167, msg_type=3, len=81, size=81 E (2108876) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time: E (2108876) task_wdt: - IDLE (CPU 0) E (2108876) task_wdt: Tasks currently running: E (2108876) task_wdt: CPU 0: esp_timer

the lines get scrambled - check the same log at pastebin - https://pastebin.com/ejZ9A3wi