ESP crashes when trying to destroy websocket. (IDFGH-12584)

Dhruvan1 commented 5 months ago

Answers checklist.

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

IDF version.

4.3.7

Espressif SoC revision.

ESP32 Wrover IE

Operating System used.

Windows

How did you build your project?

Command line with idf.py

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

CMD

Development Kit.

ESP 32 Wrover IE

Power Supply used.

External 3.3V

What is the expected behavior?

Websocket should be properly closed all mallocated memory should be free.

What is the actual behavior?

ESP32 crashing instead of freeing old websocket memory.

Steps to reproduce.

Step create websocket.
Step force to send server close frame.
Step when you receive close frame form server now try to destroy socket. ...

Debug Logs.

D (174181) TRANSPORT_WS: Opcode: 8, mask: 0, len: 2

D (174191) event: running post WEBSOCKET_EVENTS:3 with handler 0x400ebc1c and context 0x3ffe5b1c on loop 0x3ffb5e80
0x400ebc1c: websocket_event_handler at c:\users\bacancy\desktop\current_wd\bac7k4_glcd_fv_2_3\build/../components/ocpp/src/ocpp-client.c:237

W (174191) ocpp: Received data from server:�

D (174191) WEBSOCKET_CLIENT: Received close frame
D (174201) WEBSOCKET_CLIENT: Closing initiated by the server, sending close frame
D (174211) TRANSPORT_WS: Sending raw ws message with opcode 136
D (174211) RANDOM: getrandom(buf=0x3ffea162, buflen=4, flags=0)
D (174221) RANDOM: getrandom returns 4
D (174231) WEBSOCKET_CLIENT:  Waiting for TCP connection to be closed by the server
D (174231) event: running post WEBSOCKET_EVENTS:4 with handler 0x400ebc1c and context 0x3ffe5b1c on loop 0x3ffb5e80
0x400ebc1c: websocket_event_handler at c:\users\bacancy\desktop\current_wd\bac7k4_glcd_fv_2_3\build/../components/ocpp/src/ocpp-client.c:237

E (174241) ocpp: E   ocpp:  264: WEBSOCKET_EVENT_CLOSED 

I (174561) ocpp: E   ocpp: 4438: ==== ocpp_handle_local_client START ====

W (174571) FREEHEAP: Free Heap = 103020
I (174571) ocpp: E   ocpp: 4470: OCPP websocket not connected trying to reconnect (old handle address) 0x3ffe34d4

W (174581) WEBSOCKET_CLIENT: Client was not started
I (174641) app ui: systemTickTimer called....

W (174851) graphic_lcd: Novoton FV : 0.01
W (174851) graphic_lcd: GLCD Id Tag :
W (174851) graphic_lcd: u8EvState 1 u8Mode 8
W (174851) graphic_lcd: u8err_code 0
W (174851) graphic_lcd: fVoltage 263.02 fEnergykwh 0.00
W (174861) graphic_lcd: Charging start time 0:0:0
D (175591) event: deleted loop 0x3ffb5e80
Guru Meditation Error: Core  1 panic'ed (StoreProhibited). Exception was unhandled.

Core  1 register dump:
PC      : 0x400995b6  PS      : 0x00060333  A0      : 0x80099ef9  A1      : 0x3ffec0e0
0x400995b6: insert_free_block at C:/Espressif/frameworks/esp-idf-v4.3.7/components/heap/heap_tlsf.c:237
 (inlined by) block_insert at C:/Espressif/frameworks/esp-idf-v4.3.7/components/heap/heap_tlsf.c:263
 (inlined by) tlsf_free at C:/Espressif/frameworks/esp-idf-v4.3.7/components/heap/heap_tlsf.c:946

A2      : 0x3ffe4364  A3      : 0xa5a5a5a5  A4      : 0xfffffffc  A5      : 0x00000004
A6      : 0x00000014  A7      : 0x3ffebfa0  A8      : 0x3ffe5aec  A9      : 0x00000018
A10     : 0x0000000f  A11     : 0x3ffe5af4  A12     : 0x3ffe43b8  A13     : 0x00000004
A14     : 0x00000001  A15     : 0xff000000  SAR     : 0x0000001c  EXCCAUSE: 0x0000001d
EXCVADDR: 0xa5a5a5b1  LBEG    : 0x4000c46c  LEND    : 0x4000c477  LCOUNT  : 0x00000000

Backtrace:0x400995b3:0x3ffec0e0 0x40099ef6:0x3ffec100 0x40081e6a:0x3ffec120 0x4009ae51:0x3ffec140 0x400943fe:0x3ffec160 0x4014ce89:0x3ffec180 0x400f4fb8:0x3ffec1a0 0x400f612f:0x3ffec1d0 0x4009746d:0x3ffec1f0
0x400995b3: insert_free_block at C:/Espressif/frameworks/esp-idf-v4.3.7/components/heap/heap_tlsf.c:236
 (inlined by) block_insert at C:/Espressif/frameworks/esp-idf-v4.3.7/components/heap/heap_tlsf.c:263
 (inlined by) tlsf_free at C:/Espressif/frameworks/esp-idf-v4.3.7/components/heap/heap_tlsf.c:946

0x40099ef6: multi_heap_free_impl at C:/Espressif/frameworks/esp-idf-v4.3.7/components/heap/multi_heap.c:212

0x40081e6a: heap_caps_free at C:/Espressif/frameworks/esp-idf-v4.3.7/components/heap/heap_caps.c:339

0x4009ae51: free at C:/Espressif/frameworks/esp-idf-v4.3.7/components/newlib/heap.c:46

0x400943fe: vEventGroupDelete at C:/Espressif/frameworks/esp-idf-v4.3.7/components/freertos/event_groups.c:658

0x4014ce89: esp_websocket_client_destroy at C:/Espressif/frameworks/esp-idf-v4.3.7/components/esp_websocket_client/esp_websocket_client.c:457

0x400f4fb8: bac_ocpp_handle_local_client at c:\users\bacancy\desktop\current_wd\bac7k4_glcd_fv_2_3\build/../components/ocpp/src/ocpp-client.c:4479 (discriminator 6)

0x400f612f: ocpp_client_task at c:\users\bacancy\desktop\current_wd\bac7k4_glcd_fv_2_3\build/../components/ocpp/src/ocpp-client.c:5094

0x4009746d: vPortTaskWrapper at C:/Espressif/frameworks/esp-idf-v4.3.7/components/freertos/port/xtensa/port.c:168

ELF file SHA256: c908ef861af12ac4

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:7264
load:0x40078000,len:15132
load:0x40080400,len:3712
0x40080400: _init at ??:?

More Information.

I try to reconnect websocket without esp_websocket_client_destroy() API and it worked but it took 10k malloced memory (instead of releasing old memory and reusing it) memory leak issue generated here. plus i am destroying my websocket from my local task.

Dhruvan1 commented 5 months ago

It was memory leak issue from another task.

Dhruvan1 commented 5 months ago

same code working on ESP IDF 4.3.6 memory leak happning but it is from driver level. this is the log that i got after log tracing enables.

surprisingly when i desabel log tracing then it works fine but it take free 500 bytes less so after every socket disconnect to connect process i lost 500 bytes.

gabsuren commented 4 months ago

@Dhruvan1 I noticed that you closed and reopened the issue. Please be aware that IDF release/4.3 is no longer supported. Are you still experiencing the issue?

Dhruvan1 commented 4 months ago

Yes issue is still there, i found workaround and temporarily fixed it but there is something fishy there not sure what it is. and i still can not call client stop and destroy in linear manner. (before calling this i was manually closing websocket).

if you want to check and fix it then it would be very helpful not for 4.3.7, but also for 5.x.x version also.

espressif / esp-idf