Master, heap corruption with broadacst requests to responsive slaves (EPROT-69)

[Wittronics-Wisse]

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?

rarely

Expected behavior

Continuous RTU Modbus communication.

Actual behavior (suspected bug)

After a time (observed between 12-36 hours) of continuous reading & writing to Modbus slaves, the heap is overwritten and results in a reset.

Error logs or terminal output

Char #116 before the crash is read 0x0002 . Char #21 is a broadcast.

I (30303956) MODBUS: Read param CID 124
I (30303976) MODBUS: Characteristic #124  () value = (0x004c) parameter read successful.
I (30303976) MODBUS: Read done param CID 124
I (30303993) MODBUS: Read param CID 120
I (30304011) MODBUS: Characteristic #120  () value = (0x002a) parameter read successful.
I (30304012) MODBUS: Read done param CID 120
I (30304038) MODBUS: Read param CID 27
I (30304056) MODBUS: Characteristic #27  () value = (0x8000) parameter read successful.
I (30304057) MODBUS: Read done param CID 27
I (30304073) MODBUS: Read param CID 116
I (30304091) MODBUS: Characteristic #116  () value = (0x0002) parameter read successful.
I (30304092) MODBUS: Read done param CID 116
I (30304108) MODBUS: Read param CID 121
I (30304126) MODBUS: Characteristic #121  () value = (0x0000) parameter read successful.
I (30304126) MODBUS: Read done param CID 121
I (30304153) MODBUS: Read param CID 27
I (30304172) MODBUS: Characteristic #27  () value = (0x8000) parameter read successful.
I (30304172) MODBUS: Read done param CID 27
I (30304189) MODBUS: Write param CID 21
E (30307203) MB_CONTROLLER_MASTER: mbc_master_set_parameter(93): Master set parameter failure, error=(0x107) (ESP_ERR_TIMEOUT).
E (30307204) MODBUS: Characteristic #21 () write fail, err = 0x107 (ESP_ERR_TIMEOUT).
E (30310213) MB_CONTROLLER_MASTER: mbc_master_set_parameter(93): Master set parameter failure, error=(0x103) (ESP_ERR_INVALID_STATE).
E (30310215) MODBUS: Characteristic #21 () write fail, err = 0x103 (ESP_ERR_INVALID_STATE).
I (30313150) MODBUS: Characteristic #21  () value = (0x07df), write successful.
I (30313151) MODBUS: Write done param CID 21
I (30313167) MODBUS: Read param CID 116
E (30313190) MB_CONTROLLER_MASTER: mbc_master_get_parameter(131): Master get parameter failure, error=(0x108) (ESP_ERR_INVALID_RESPONSE).
E (30313192) MODBUS: Characteristic #116  (), read parameter read fail.
I (30313199) MODBUS: Read done param CID 116
CORRUPT HEAP: Invalid data at 0x3ffd2168. Expected 0xfefefefe got 0xfefe0002
I (30313220) MODBUS: Read param CID 121
CORRUPT HEAP: Invalid data at 0x3ffd2168. Expected 0xfefefefe got 0xfefe0002
CORRUPT HEAP: Invalid data at 0x3ffd2168. Expected 0xfe got 0x02
CORRUPT HEAP: Invalid data at 0x3ffd2168. Expected 0xfe got 0x02

And

Second log prints CID information on failed Modbus transactions.

E (117981772) MB_CONTROLLER_MASTER: mbc_master_set_parameter(93): Master set parameter failure, error=(0x107) (ESP_ERR_TIMEOUT).
E (117981774) MODBUS: Write FAIL: Char #21, err = 0x107 (ESP_ERR_TIMEOUT) Try:1
  Slave: 0, RegStart: 0C00, MBParamType: 0, RegSize: 16, ParamSize: 32, ParamOffset: 0, ParamType: 7
E (117983289) MB_CONTROLLER_MASTER: mbc_master_get_parameter(131): Master get parameter failure, error=(0x108) (ESP_ERR_INVALID_RESPONSE).
E (117983292) MODBUS: Read FAIL: Char #116, err = 0x108 (ESP_ERR_INVALID_RESPONSE)
  Slave: 32, RegStart: 0800, MBParamType: 1, RegSize: 1, ParamSize: 2, ParamOffset: 0, ParamType: 1
CORRUPT HEAP: Invalid data at 0x3ffccff0. Expected 0xfefefefe got 0xfefe0002
E (117983325) MODBUS: HEAP corrupt after Read param CID 116
CORRUPT HEAP: Invalid data at 0x3ffccff0. Expected 0xfefefefe got 0xfefe0002
E (117983339) MODBUS: HEAP corrupt before Read param CID 121
CORRUPT HEAP: Invalid data at 0x3ffccff0. Expected 0xfe got 0x02
CORRUPT HEAP: Invalid data at 0x3ffccff0. Expected 0xfe got 0x02

Steps to reproduce the behavior

We have a responsive system, usually a response start between 0-10mS after slave receive.
Baudrate: 230400

To improve response we changed a few lines in the component:
mb_config.h
line:166 Changed so broadcasts can be send more often
#define MB_MASTER_DELAY_MS_CONVERT 20

port_serial.c
line 19: Changed to 1.75mS because 3.5T is too short
#define MB_SERIAL_TOUT (36)

line 159: Removed semaphore for fast systems
// If bus is busy or fragmented data is received, then flush buffer
// if (mb_port_ser_bus_sema_is_busy(&port_obj->base) && port_obj->base.descr.is_master) {
// mb_port_ser_rx_flush(&port_obj->base);
// break;
// }

line 90: Removed unused function after removing semaphore
// static bool mb_port_ser_bus_sema_is_busy(mb_port_base_t *inst)

Communication is continuous. Reading every 50mS, Writing every 5000mS. Most of them are broadcasts.
Time to reproduce is unclear, lays between 12 to 36 hours on most systems.

Project release version

2.1.1

System architecture

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

Operating system

Windows

Operating system version

Windows 11

Shell

CMD

Additional context

I've also experienced problems with flash actions when a timer_delete is called through the Modbus component while NVS is active. I currently do not have that log, but will save it when it happens again.
UART ISR is set in IRAM.

[alisitsyn]

HI @Wittronics-Wisse ,

Thank you for your report. Please send me your sdkconfig file for now.
Thanks.

[alisitsyn]

@Wittronics-Wisse ,

After a time (observed between 12-36 hours) of continuous reading & writing to Modbus slaves, the heap is overwritten and results in a reset.

I need some additional information from you to proceed further with this issue.

1. The sdkconfig file.
2. Better to get the log for this error with verbosity = debug in config menu or just tags mb_port.tcp.master, mb_object.master enabled in the log.
3. Please provide some snippet demonstrating the logic of API calls sequence.

My recommendation when the error occurred or response does not come from slave during slave response time, please wait during slave response time before retry or send next request. This would allow to avoid race conditions.

I've also experienced problems with flash actions when a timer_delete is called through the Modbus component while NVS is active. I currently do not have that log, but will save it when it happens again.
UART ISR is set in IRAM.

I need additional logs ad code snippets to figure out what is the reason for this.

Thanks.

[Wittronics-Wisse]

Hi @alisitsyn ,

Thanks for picking this up!

I've added the sdkconfig file and will try to get more detailed logs. With the verbosity = debug, timing does change, so it could be a while before I can get a log.
The MB_MASTER_DELAY_MS_CONVERT is overwritten from the sdkconfig file to 20mS.
sdkconfig.txt

I've also included a snippet with the 3 function I use to communicate with the stack.
modbus snippet.txt

All communication is done from a single task. The read function is blocking, so there should be no additional requests until the last one is handled.
There are a lot of broadcasts which do wait the slave conversion time (as we have fast slaves, this time was reduced), but not the slave response time. Somehow this broadcast leads to a ESP_ERR_TIMEOUT.

Thanks

[Wittronics-Wisse]

Hi,
I've created the timer irq while NVS is active. Same sdkconfig as my previous post.
TimerDelete.txt

[alisitsyn]

Hi @Wittronics-Wisse ,

I've created the timer irq while NVS is active. Same sdkconfig as my previous post.

As per your log the NVS is active and cpu cache is disabled then timer irq is started which is calling the
mbm_rtu_transp_delete located in flash then the crash happens which is expected. I can only guess about your actual code now. Please provide more snippets if you think your code is correct but crashes due to a bag. If you use timer interrupt with CONFIG_ESP_TIMER_SUPPORTS_ISR_DISPATCH_METHOD enabled, your timer interrupt should be in IRAM and should not call any callbacks placed in flash.

All communication is done from a single task. The read function is blocking, so there should be no additional requests until the last one is handled.

Just as I said: if your blocking read/write request is completed with timeout error please do the wait cycle before send next request in the sequence.

The read function is blocking, so there should be no additional requests until the last one is handled.

The Modbus stack uses dedicated tasks to handle responses from slave and if your slave sends the response later then response time expired and the request call returns , the response should be dropped correctly by stack to avoid race condition to happen. This is why I recommend you to wait before proceed with next request.
This is not case for broadcast requests I will check the concrete situation with broadcast requests and will try to propose solution.

[Wittronics-Wisse]

Hi @alisitsyn ,

CONFIG_ESP_TIMER_SUPPORTS_ISR_DISPATCH_METHOD & CONFIG_ESP_TIMER_USE_ISR_DISPATCH_METHOD are enabled, so the interrupt should be in IRAM already. I'm trying to find where the stack calls the mbm_rtu_transp_delete, is this done in a timer interrupt?

I'll try to get some minimal code to get the NVS crash.

Just as I said: if your blocking read/write request is completed with timeout error please do the wait cycle before send next request in the sequence.

Isn't the slave response wait cycle done after a timeout is received?
Are there any processes stopping async after a successful request, meaning we would have to wait a little before starting a new request?

The slave responses are very fast, I needed to remove the semaphore because it was cleared too late and the buffer was partly flushed before the semaphore was given. The slaves we have in the system are either very fast or do not reply at all. There should be no reason for a slave to respond after the slave response wait if the request was send.

There are some read requests between the broadcasts. But as the log now shows, the first sign of something going wrong is a timeout on a broadcast.

[alisitsyn]

@Wittronics-Wisse ,

CONFIG_ESP_TIMER_SUPPORTS_ISR_DISPATCH_METHOD & CONFIG_ESP_TIMER_USE_ISR_DISPATCH_METHOD are enabled, so the interrupt should be in IRAM already. I'm trying to find where the stack calls the mbm_rtu_transp_delete, is this done in a timer interrupt?

Yes, the esp-timer handlers are in the IRAM then, I just was wondering if you have your own timer callback. The stack calls the mbX_port_timer_expired callback from timer interrupt when the response time is expired. These expired functions are always placed in IRAM and do not call mbm_rtu_transp_delete. This is why your log looks a bit unclear.

Isn't the slave response wait cycle done after a timeout is received?

The response cycle is done but the response sometime comes later then this time or time is not configured correctly. Also, the Modbus protocol has deterministic aspects but is not deterministic and if your segment has many slaves this may apply to their ability to reply promptly. Any way the wait time is recommended as error prevention action due to the issues existing in the protocol itself.

Are there any processes stopping async after a successful request, meaning we would have to wait a little before starting a new request?

The serial queue is monitored in dedicated task. The request API sets the timers and then sends request. A transaction sema is released after end of transaction and then request API unblocks but the line is still monitored to catch responses and drops them if they expired (fake TID={system time} is used for this).

The slave responses are very fast, I needed to remove the semaphore because it was cleared too late and the buffer was partly flushed before the semaphore was given.

Yes, This is correct change. This line flushing is the old way to drop expired data and the fake TID approach is used now means this can be removed as duplicated. There is a plan to check and update this as per process.

The slaves we have in the system are either very fast or do not reply at all. There should be no reason for a slave to respond after the slave response wait if the request was send.

Understand, there is no reason to wait long time then but still can be useful to add some timeout there. Your slave response time can be just decreased accordingly and the wait cycle after timeout request still can be useful to repair from errors.

There are some read requests between the broadcasts. But as the log now shows, the first sign of something going wrong is a timeout on a broadcast.

Got this aspect and will try to check this ASAP.
Update: The issue happens due to the bug in function handlers for broadcast requests. This will be fixed as soon as possible. I will inform you with the changes.

[Wittronics-Wisse]

Hi @alisitsyn,

Good to see there is a fix available.
Do you have an estimate when this fix will be in a new release?

Thanks

[alisitsyn]

Hi @Wittronics-Wisse ,

The fix is planned to be available in release v2.1.3 which will be released up to end of June 2026.

[Wittronics-Wisse]

Hi @alisitsyn ,

Is there an update on the new release timeline? We'd like use the release for our testing and in our product.

Thanks