[Bug]: Watchdog triggered while using HTTP API

[leshniak]

Category

WiFi

Hardware

T-Lora v2 1.6

Firmware Version

2.5.14.8df7a035 (fresh install)

Description

The device sometimes hangs and reboots itself while connecting to it through HTTP API. I can't reproduce the bug all the time, but my clue is that it happens more often when I'm observing increased traffic over the mesh (in comparison to negligible traffic).

Relevant log output

[2024-12-01 22:34:24] [HTTPS:I] Request: GET /api/v1/fromradio?all=false (FID=53)
[2024-12-01 22:34:24] DEBUG | 22:34:18 6586 [WebServer] webAPI handleAPIv1FromRadio
[2024-12-01 22:34:24] DEBUG | 22:34:18 6586 [WebServer] Send known nodes
[2024-12-01 22:34:24] INFO  | 22:34:18 6586 [WebServer] nodeinfo: num=0x43587d64, lastseen=1732950813, id=!43587d64, name=Technodzik MQTT
[2024-12-01 22:34:24] DEBUG | 22:34:18 6586 [WebServer] webAPI handleAPIv1FromRadio, len 137
[2024-12-01 22:34:24] [HTTPS:I] Request: GET /api/v1/fromradio?all=false (FID=53)
[2024-12-01 22:34:24] DEBUG | 22:34:18 6586 [WebServer] webAPI handleAPIv1FromRadio
[2024-12-01 22:34:24] DEBUG | 22:34:18 6586 [WebServer] Send known nodes
[2024-12-01 22:34:24] INFO  | 22:34:18 6586 [WebServer] nodeinfo: num=0xbdfb791c, lastseen=1732888366, id=!bdfb791c, name=SP3VN
[2024-12-01 22:34:24] DEBUG | 22:34:18 6586 [WebServer] webAPI handleAPIv1FromRadio, len 111
[2024-12-01 22:34:24] [HTTPS:I] New connection. Socket FID=55
[2024-12-01 22:34:24] [HTTPS:I] Request: GET /json/report (FID=55)
[2024-12-01 22:34:24] [HTTPS:I] Request: GET /api/v1/fromradio?all=false (FID=53)
[2024-12-01 22:34:24] DEBUG | 22:34:18 6586 [WebServer] webAPI handleAPIv1FromRadio
[2024-12-01 22:34:24] DEBUG | 22:34:18 6586 [WebServer] Send known nodes
[2024-12-01 22:34:24] INFO  | 22:34:18 6586 [WebServer] nodeinfo: num=0x6c73dec0, lastseen=1732912162, id=!6c73dec0, name=######kl0
[2024-12-01 22:34:24] DEBUG | 22:34:18 6586 [WebServer] webAPI handleAPIv1FromRadio, len 102
[2024-12-01 22:34:24] E (6678729) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
[2024-12-01 22:35:54] E (6678729) task_wdt:  - loopTask (CPU 1)
[2024-12-01 22:35:54] E (6678729) task_wdt: Tasks currently running:
[2024-12-01 22:35:54] E (6678729) task_wdt: CPU 0: IDLE0
[2024-12-01 22:35:54] E (6678729) task_wdt: CPU 1: IDLE1
[2024-12-01 22:35:54] E (6678729) task_wdt: Aborting.
[2024-12-01 22:35:54]
[2024-12-01 22:35:54] abort() was called at PC 0x4014cbfc on core 0
[2024-12-01 22:35:54]
[2024-12-01 22:35:54]
[2024-12-01 22:35:54] Backtrace: 0x4008414d:0x3ffbfb7c |<-CORRUPTED
[2024-12-01 22:35:54]
[2024-12-01 22:35:54]
[2024-12-01 22:35:54]
[2024-12-01 22:35:54]
[2024-12-01 22:35:54] ELF file SHA256: 57ed6e0b164966e6
[2024-12-01 22:35:54]
[2024-12-01 22:35:54] E (2120) esp_core_dump_flash: Core dump flash config is corrupted! CRC=0x7bd5c66f instead of 0x0
[2024-12-01 22:35:54] Rebooting...

[leshniak]

Another log - this time no reboot, but it became unresponsive via WiFi.

WARN  | 14:03:22 55657 [Router] ToPhone queue is full, drop packet
DEBUG | 14:03:22 55657 [Router] Module 'routing' considered
DEBUG | 14:03:22 55657 [Router] MQTT onSend - Publish 
DEBUG | 14:03:22 55657 [Router] encrypted message
DEBUG | 14:03:22 55657 [Router] MQTT Publish msh/PL/2/e/LongFast/!06c987f0, 86 bytes
[HTTPS:I] Request: GET /api/v1/fromradio?all=false (FID=53)
DEBUG | 14:03:22 55657 (Client not yet interested in packets)
DEBUG | 14:03:22 55657 [WebServer] webAPI handleAPIv1FromRadio
DEBUG | 14:03:22 55657 [WebServer] webAPI handleAPIv1FromRadio, len 6
DEBUG | 14:03:25 55660 [RadioIf] Started Tx (id=0x14d5e69b fr=0xae to=0xff, WantAck=0, HopLim=0 Ch=0x8 encrypted rxtime=1733144602 rxSNR=12 rxRSSI=-67 hopStart=3 priority=64)
DEBUG | 14:03:25 55660 [RadioIf] Packet TX: 493ms
DEBUG | 14:03:26 55660 [RadioIf] Completed sending (id=0x14d5e69b fr=0xae to=0xff, WantAck=0, HopLim=0 Ch=0x8 encrypted rxtime=1733144602 rxSNR=12 rxRSSI=-67 hopStart=3 priority=64)
DEBUG | 14:03:39 55674 [Power] Battery: usbPower=1, isCharging=1, batMv=4210, batPct=100
[HTTPS:I] Connection timeout. FID=53
[HTTPS:I] Connection closed. Socket FID=53
INFO  | 14:03:50 55685 [mqtt] Use non-TLS-encrypted session
INFO  | 14:03:50 55685 [mqtt] Connect directly to MQTT server 192.168.5.2, port: 1883, username: , password: 
[55688662][I][WiFiClient.cpp:260] connect(): select returned due to timeout 3000 ms for fd 52
ERROR | 14:03:53 55688 [mqtt] Failed to contact MQTT server directly (1/5)
DEBUG | 14:03:59 55694 [Power] Battery: usbPower=1, isCharging=1, batMv=4210, batPct=100
DEBUG | 14:04:04 55699 [RadioIf] Lora RX (id=0x3890069c fr=0xae to=0xff, WantAck=0, HopLim=0 Ch=0x8 encrypted rxSNR=12 rxRSSI=-67 hopStart=3)
DEBUG | 14:04:04 55699 [RadioIf] Packet RX: 493ms

More context in a file: dump.txt

[leshniak]

~~I would say related to #5458.~~

[danpospisil]

I am seeing the exact same thing on my T-Beam - both the watchdog reboot and sometimes WiFi unresponsive until MQTT reconnects WiFi after 5 fails. I can easily reproduce this when I try to access HTTPS Web UI.

[118457][E][vfs_api.cpp:105] open(): /littlefs/static/index.html does not exist, no permits for creation
[HTTPS:I] Request: GET /index-siIur9KN.js (FID=52)
[HTTPS:I] New connection. Socket FID=53
[HTTPS:E] SSL_new failed. Aborting handshake. FID=53
[HTTPS:I] Connection closed. Socket FID=53
[118700][E][vfs_api.cpp:105] open(): /littlefs/static/index-siIur9KN.js does not exist, no permits for creation
E (221111) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (221111) task_wdt:  - loopTask (CPU 1)
E (221111) task_wdt: Tasks currently running:
E (221111) task_wdt: CPU 0: IDLE
E (221111) task_wdt: CPU 1: IDLE
E (221111) task_wdt: Aborting.

abort() was called at PC 0x4014cfb0 on core 0


Backtrace: 0x400844ed:0x3ffbf44c |<-CORRUPTED




ELF file SHA256: 885f0c027d25d49f

E (12418) esp_core_dump_flash: Core dump flash config is corrupted! CRC=0x7bd5c66f instead of 0x0
Rebooting...
ets Jul 29 2019 12:21:46

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:1184
load:0x40078000,len:13192
load:0x40080400,len:3028
entry 0x400805e4
E (841) esp_core_dump_flash: No core du▒▒ѥѥ▒▒▒found!
E (841) esp_core_dump_flash: No core dump partition found!
[    12][D][esp32-hal-cpu.c:244] setCpuFrequencyMhz(): PLL: 480 / 2 = 240 Mhz, APB: 80000000 Hz
[   464][I][esp32-hal-psram.c:96] psramInit(): PSRAM enabled
▒▒@INFO  | ??:??:?? 0

//\ E S H T /\ S T / C

INFO  | ??:??:?? 0 Booted, wake cause 0 (boot count 1), reset_reason=reset
DEBUG | ??:??:?? 0 Filesystem files (524288/1048576 Bytes):