Heap Corruption in Modbus TCP Master after receiving outside of transaction error

[i01011001]

Checklist

• Checked the issue tracker for similar issues to ensure this is not a duplicate
• Read the documentation to confirm the issue is not addressed there and your configuration is set correctly
• Tested with the latest version to ensure the issue hasn't been fixed

How often does this bug occurs?

often

Expected behavior

Device working properly indefinitely without crashing

Actual behavior (suspected bug)

Device crashes on mbc_master_get_parameter randomly, sometimes the crash occurs within a minute of the device running other times it runs properly for around an hour before crashing

Error logs or terminal output

E (23389) MB_CONTROLLER_MASTER: mbc_master_get_parameter(128): Master get parameter failure, error=(0x107) (ESP_ERR_TIMEOUT).
D (23399) event: running post loop:0x3fcd67cc:32 with handler 0x42021864 and context 0x3fcd5360 on loop 0x3fcd0a08
--- 0x42021864: mbm_on_recv_data at /home/i01011001/code/esp/projects/yeti/managed_components/espressif__esp-modbus/modbus/mb_ports/tcp/port_tcp_master.c:617
D (23419) mb_port.tcp.master: loop:0x3fcd67cc  mbm_on_recv_data: fd: 0
D (23429) w5500.mac: receive len=60
D (23429) mb_port.tcp.master: 0x3fcd67cc, slave #0(58) [192.168.1.159], receive data ready.
D (23439) mb_port.tcp.master: 0x3fcd67cc, packet TID: 0x0019 received.
D (23449) mb_port.timer: mbm_tcp#0x3fcd0970, timer stop, returns 259.
D (23449) mb_object.master: 0x3fcd0970:EV_FRAME_RECEIVED
D (23469) mb_port.tcp.master: 0x3fcd67cc, node #0, socket(#58)(192.168.1.159), get packet TID: 0x0019:0x001a, 0x3fcd8ec8.
D (23479) mb_port.tcp.master: 0x3fcd67cc, node #0, socket(#58)(192.168.1.159), processing time[us] = 803715.
E (23489) mb_object.master: 0x3fcd0970, drop data received outside of transaction.
D (23499) mb_object.master: 0x3fcd0970:EV_ERROR_PROCESS
D (23499) mb_port.timer: mbm_tcp#0x3fcd0970, timer stop, returns 259.
D (23509) mbm_error_cb_respond_timeout: 04 00 02 00 02
D (23509) mb_port.event: mbm_tcp#0x3fcd0970, mb take resource, (300 ticks).
D (23509) mb_object.master: 0x3fcd0970, transaction processing time(us) = 0
D (23339) mbm_rtu@0x3fccf5a8:MB_TRANSMIT: 04 00 00 00 02
D (23519) mb_port.event: mbm_tcp#0x3fcd0970, mb take resource, (300 ticks).
D (23539) mb_port.event: mbm_tcp#0x3fcd0970, mb_port_event_wait_req_finish: returned event = 0x80
D (23539) mbm_tcp#0x3fcd0970:MB_TRANSMIT: 04 00 04 00 02
D (23549) mb_port.tcp.master: 0x3fcd67cc,  send fd: 0, sock_id: 58[192.168.1.159], 0x3fcd8d3b, len: 12
D (23559) mb_driver: 0x3fcd67cc, fd event get: 0x10:0, |MB_EVENT_SEND_DATA
D (23569) event: running post loop:0x3fcd67cc:16 with handler 0x42021658 and context 0x3fcd5310 on loop 0x3fcd0a08
--- 0x42021658: mbm_on_send_data at /home/i01011001/code/esp/projects/yeti/managed_components/espressif__esp-modbus/modbus/mb_ports/tcp/port_tcp_master.c:567
D (23549) mbc_tcp.master: mbc_tcp_master_get_parameter: Bad response to get cid(2) = ESP_ERR_TIMEOUT
D (23579) mb_port.tcp.master: loop:0x3fcd67cc  mbm_on_send_data: fd: 0
D (23589) mb_port.tcp.master: 0x3fcd67cc, get info: 0, sock_id: 58, queue_state: 0, state: 6.
D (23569) mb_port.serial: mbm_rtu@0x3fccf5a8, UART[1] event:
D (23599) mb_port.serial: mbm_rtu@0x3fccf5a8, data event, len: 9.
D (23609) mb_port.tcp.master: 0x3fcd67cc, node #0, socket(#58)(192.168.1.159), send data successful: TID:0x001a, 12 (bytes), errno 119
D (23619) SENT: 00 1a 00 00 00 06 02 04 00 04 00 02
D (23629) w5500.mac: receive len=60
D (23579) mb_port.timer: mbm_tcp#0x3fcd0970, respond enable timeout (500).
D (23639) mb_object.master: 0x3fcd0970:EV_FRAME_SENT
E (23579) MB_CONTROLLER_MASTER: mbc_master_get_parameter(128): Master get parameter failure, error=(0x107) (ESP_ERR_TIMEOUT).
D (23539) mb_port.serial: mbm_rtu@0x3fccf5a8, tx buffer sent: (8) bytes.
D (23659) mbm_rtu@0x3fccf5a8:PORT_SEND: 01 04 00 00 00 02 71 cb
D (23679) mb_port.timer: mbm_rtu@0x3fccf5a8, respond enable timeout (500).
D (23679) mb_object.master: 0x3fccf5a8:EV_FRAME_SENT
D (23699) w5500.mac: receive len=67
D (23699) mb_driver: 0x3fcd67cc, socket event active: 400000000000000
D (23699) port.utils: Enqueue data, length=13, TID=0x1a
D (23699) mb_driver: 0x3fcd67cc, node #0, socket(#58)(192.168.1.159), frame received.
D (23709) mb_driver: 0x3fcd67cc, fd event get: 0x20:0, |MB_EVENT_RECV_DATA
D (23719) event: running post loop:0x3fcd67cc:32 with handler 0x42021864 and context 0x3fcd5360 on loop 0x3fcd0a08
--- 0x42021864: mbm_on_recv_data at /home/i01011001/code/esp/projects/yeti/managed_components/espressif__esp-modbus/modbus/mb_ports/tcp/port_tcp_master.c:617
[YETI_MB] yeti_modbus_component.c[879]:Failed to read all CIDs - consecutive failures: 1/1000
D (23729) mb_port.tcp.master: loop:0x3fcd67cc  mbm_on_recv_data: fd: 0
D (23739) mb_port.tcp.master: 0x3fcd67cc, slave #0(58) [192.168.1.159], receive data ready.
D (23749) mb_port.tcp.master: 0x3fcd67cc, packet TID: 0x001a received.
D (23759) mb_object.master: 0x3fcd0970:EV_FRAME_RECEIVED
D (23759) mb_port.tcp.master: 0x3fcd67cc, node #0, socket(#58)(192.168.1.159), get packet TID: 0x001a:0x001b, 0x3fcd8ec8.
D (23769) mb_port.tcp.master: 0x3fcd67cc, node #0, socket(#58)(192.168.1.159), processing time[us] = 148608.
D (23779) mb_object.master: 0x3fcd0970, frame data received successfully, (0).
D (23789) mbm_tcp#0x3fcd0970:MB_RECV: 04 04 00 00 40 40
D (23789) mb_object.master: 0x3fcd0970:EV_EXECUTE
D (23799) mb_object.master: 0x3fcd0970, set event EV_ERROR_OK
D (23799) mb_object.master: 0x3fcd0970:EV_ERROR_PROCESS
D (23809) mb_port.timer: mbm_tcp#0x3fcd0970, timer stop, returns 259.
D (23809) mbm_error_cb_request_success: 04 00 04 00 02
D (23819) mb_object.master: 0x3fcd0970, transaction processing time(us) = 265291
CORRUPT HEAP: Invalid data at 0x3fcd9148. Expected 0xfefefefe got 0x40400000

assert failed: multi_heap_malloc multi_heap_poisoning.c:261 (ret)


Backtrace: 0x40375f09:0x3fcdd8a0 0x4037f0c9:0x3fcdd8c0 0x40387e4d:0x3fcdd8e0 0x40385c64:0x3fcdda00 0x40376b39:0x3fcdda20 0x40376c45:0x3fcdda40 0x40376c75:0x3fcdda70 0x403769f2:0x3fcdda90 0x40376a4a:0x3fcddae0 0x40376484:0x3fcddb00 0x403764b9:0x3fcddb20 0x40387ec4:0x3fcddb40 0x40387ee8:0x3fcddb60 0x4201d7f7:0x3fcddb80 0x4201aaa9:0x3fcddbf0 0x420186a6:0x3fcddc20 0x42018723:0x3fcddc80 0x42018761:0x3fcddcb0 0x420187cd:0x3fcddcf0 0x4037fbd5:0x3fcddd10
--- 0x40375f09: panic_abort at /home/i01011001/code/esp/idf/esp-idf/components/esp_system/panic.c:469
--- 0x4037f0c9: esp_system_abort at /home/i01011001/code/esp/idf/esp-idf/components/esp_system/port/esp_system_chip.c:87
--- 0x40387e4d: __assert_func at /home/i01011001/code/esp/idf/esp-idf/components/newlib/assert.c:80
--- 0x40385c64: multi_heap_malloc at /home/i01011001/code/esp/idf/esp-idf/components/heap/multi_heap_poisoning.c:261
--- 0x40376b39: aligned_or_unaligned_alloc at /home/i01011001/code/esp/idf/esp-idf/components/heap/heap_caps_base.c:83
--- 0x40376c45: heap_caps_aligned_alloc_base at /home/i01011001/code/esp/idf/esp-idf/components/heap/heap_caps_base.c:158
--- 0x40376c75: heap_caps_malloc_base at /home/i01011001/code/esp/idf/esp-idf/components/heap/heap_caps_base.c:178
--- 0x403769f2: trace_malloc at /home/i01011001/code/esp/idf/esp-idf/components/heap/include/heap_trace.inc:116
--- 0x40376a4a: __wrap_heap_caps_malloc_base at /home/i01011001/code/esp/idf/esp-idf/components/heap/include/heap_trace.inc:178
--- 0x40376484: heap_caps_malloc at /home/i01011001/code/esp/idf/esp-idf/components/heap/heap_caps.c:84
--- 0x403764b9: heap_caps_malloc_default at /home/i01011001/code/esp/idf/esp-idf/components/heap/heap_caps.c:110
--- 0x40387ec4: _calloc_r at /home/i01011001/code/esp/idf/esp-idf/components/newlib/heap.c:65
--- 0x40387ee8: calloc at /home/i01011001/code/esp/idf/esp-idf/components/newlib/heap.c:29
--- 0x4201d7f7: mbc_tcp_master_get_parameter at /home/i01011001/code/esp/projects/yeti/managed_components/espressif__esp-modbus/modbus/mb_controller/tcp/mbc_tcp_master.c:401
--- 0x4201aaa9: mbc_master_get_parameter at /home/i01011001/code/esp/projects/yeti/managed_components/espressif__esp-modbus/modbus/mb_controller/common/esp_modbus_master.c:127
--- 0x420186a6: yeti_modbus_process_single_cid at /home/i01011001/code/esp/projects/yeti/components/yeti-modbus-component/yeti_modbus_component.c:823
--- 0x42018723: yeti_modbus_process_polling_cycle at /home/i01011001/code/esp/projects/yeti/components/yeti-modbus-component/yeti_modbus_component.c:850
--- 0x42018761: yeti_modbus_master_operation at /home/i01011001/code/esp/projects/yeti/components/yeti-modbus-component/yeti_modbus_component.c:900
--- 0x420187cd: yeti_modbus_master_tcp_operation at /home/i01011001/code/esp/projects/yeti/components/yeti-modbus-component/yeti_modbus_component.c:646
--- 0x4037fbd5: vPortTaskWrapper at /home/i01011001/code/esp/idf/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:139

Steps to reproduce the behavior

using TCP modbus to get data from a slave

Project release version

2.0.1

System architecture

Intel/AMD 64-bit (modern PC, older Mac)

Operating system

Linux

Operating system version

NixOS

Shell

ZSH

Additional context

the log level is set to debug

[alisitsyn]

@i01011001,

In order to reproduce the issue please send minimal code to reproduce, your whole log and sdkconfig. Please also use the latest esp-modbus update, not the v2.0.1. What is the esp-idf version used with your project? Please clarify your data dictionary and data structures used to keep the read parameters.
Do you access the data structures from some other tasks?

In the log above you are using the modbus master TCP and Modbus master RTU. Do you use any shared data between them? If yes, please clarify how.

Thanks.

[i01011001]

• I use esp-idf version 5.4.2
• This error occurs even if I use the v2.1.0 with only using master TCP
• This error only occur when using master TCP not when I'm only using master RTU
• heres my sdkconfig
• here's the error log without the debug logs

[VasylBaranetskyi]

I am facing the same issue only with Modbus RTU; sometimes it takes about 8 hours to reproduce

[alisitsyn]

@VasylBaranetskyi, @i01011001,

Thank you for update. I see many issues in this period due to transition to esp-idf v6.0. I will try to check and fix this as soon as possible.

[i01011001]

Thanks @alisitsyn,

the crashes seem to have stopped after switching to the Bugfix/fix master multiple errors handling

[alisitsyn]

@i01011001,

Thank you for test report. The fix will be ready soon and will be included to the next release.

[alisitsyn]

The fix has been merged with commit: [58dc8c1]