mbc_master_send_request() doesn't work properly (IDFGH-10848)

Asanga-Viraj commented 11 months ago

I am using ESP32 RTU ModBus master. The reading registers are working fine. But, writing register doesn't work properly. I am using mbc_master_send_request() function to write register. This function writes value of previous call each time for a specific reg_start address. An example code is below.

uint16_t temp = 156; mb_param_request_t req = {}; req.command = 6; req.reg_start = 1182; req.reg_size = 1; mbc_master_send_request(&req, (void *)&temp);

temp = 75; req.command = 6; req.reg_start = 1182; req.reg_size = 1; mbc_master_send_request(&req, (void *)&temp); //still writes value 156 ESP_LOGI(TAG, "value:%d", temp); //can check the value from here. It is automatically updated to previous value.

This issue can overcome by calling mbc_master_send_request(&req, (void *)&temp); with zero value before writing actual value. It seems to be calling this function release resources allocated for reg_start address.

What should I do? Am I making invalid requests?

alisitsyn commented 11 months ago

Hi @Asanga-Viraj,

Thank you for the issue. I think more information from you is required to reproduce this issue. I just checked this functionality and can confirm this works as expected with esp-modbus v1.0.11 and latest esp-idf.

The application:

void app_main(void)
{
    // Initialization of device peripheral and objects
    ESP_ERROR_CHECK(master_init());
    vTaskDelay(10);
    esp_err_t err = 0;

    // Write registers to predefined state
    uint16_t register_data = 0x1111;
    // write_modbus_parameter(CID_DEV_REG0, &register_data);
    // register_data = 0x2222;
    // write_modbus_parameter(CID_DEV_REG1, &register_data);

    register_data = 0x3333;
    mb_param_request_t req = {};
    req.slave_addr = 1; // Set of the slave address is required here!!!
    req.command = 6;
    req.reg_start = 1;
    req.reg_size = 1;
    err = mbc_master_send_request(&req, (void *)&register_data);
    ESP_LOGI("TEST", "value:%x(%d)", (int)register_data, (int)err); //can check the value from here. It is automatically updated to previous value.

    register_data = 0x4444;
    req.command = 6;
    req.reg_start = 2;
    req.reg_size = 1;
    err = mbc_master_send_request(&req, (void *)&register_data); //still writes value 156
    ESP_LOGI("TEST", "value:%x(%d)", (int)register_data, (int)err); //can check the value from here. It is automatically updated to previous value.
}

The log of test application:

D (818) MB_PORT_COMMON: 0:EV_MASTER_READY
I (868) MODBUS_MASTER: Modbus master stack initialized...
D (968) MB_PORT_COMMON: xMBMasterRunResTake:Take MB resource (500 ticks).
D (968) MB_PORT_COMMON: xMBMasterRunResTake:Take MB resource (500 ticks).
D (968) MB_PORT_COMMON: 325429:EV_MASTER_FRAME_TRANSMIT
D (968) POLL transmit buffer: 06 00 01 33 33 
D (978) MB_PORT_COMMON: eMBMasterRTUSend: Port enter critical.
D (978) MB_PORT_COMMON: eMBMasterRTUSend: Port exit critical
D (988) MB_PORT_COMMON: xMBMasterPortSerialSendRequest default
D (998) MB_PORT_COMMON: vMBMasterPortTimersRespondTimeoutEnable Respond enable timeout.
D (998) MB_MASTER_SERIAL: MB_TX_buffer sent: (9) bytes.
D (1008) MB_PORT_COMMON: vMBMasterRxSemaRelease:RX semaphore is free.
D (1008) MB_PORT_COMMON: xMBPortSerialWaitEvent, UART event: 1 
D (1018) MB_MASTER_SERIAL: MB_uart[2] event:
D (1028) MB_MASTER_SERIAL: uart rx break.
D (1028) MB_PORT_COMMON: xMBPortSerialWaitEvent, UART event: 1 
D (1038) MB_MASTER_SERIAL: MB_uart[2] event:
D (1038) MB_MASTER_SERIAL: uart rx break.
D (1038) MB_PORT_COMMON: 325429:EV_MASTER_FRAME_SENT
D (1048) MB_PORT_COMMON: xMBPortSerialWaitEvent, UART event: 0 
D (1048) MB_MASTER_SERIAL: MB_uart[2] event:
D (1058) MB_MASTER_SERIAL: Data event, len: 8.
D (1058) MB_MASTER_SERIAL: Received data: 9(bytes in buffer)
D (1068) MB_MASTER_SERIAL: Timeout occured, processed: 9 bytes
D (1078) POLL sent buffer: 06 00 01 33 33 
D (1078) MB_PORT_COMMON: 325429:EV_MASTER_FRAME_RECEIVED
D (1078) MB_PORT_COMMON:  xMBMasterPortSerialGetResponse default
D (1088) MB_PORT_COMMON: eMBMasterRTUReceive: Port enter critical.
D (1098) MB_PORT_COMMON: eMBMasterRTUReceive: Port exit critical
D (1098) MB_PORT_COMMON: 325429: Packet data received successfully (0).
D (1108) POLL receive buffer: 06 00 01 33 33 
D (1108) MB_PORT_COMMON: 325429:EV_MASTER_EXECUTE
D (1118) MB_PORT_COMMON: 325429:set event EV_ERROR_OK
D (1118) MB_PORT_COMMON: 325429:EV_MASTER_ERROR_PROCESS
D (1128) MB_PORT_COMMON: vMBMasterCBRequestSuccess: Callback request success.
D (1138) MB_PORT_COMMON: Transaction (325429), processing time(us) = 156402
D (1138) MB_PORT_COMMON: eMBMasterWaitRequestFinish: returned event = 0x80
I (1148) TEST: value:3333(0)
D (1148) MB_PORT_COMMON: xMBMasterRunResTake:Take MB resource (500 ticks).
D (1158) MB_PORT_COMMON: xMBMasterRunResTake:Take MB resource (500 ticks).
D (1168) MB_PORT_COMMON: 525759:EV_MASTER_FRAME_TRANSMIT
D (1168) POLL transmit buffer: 06 00 02 44 44 
D (1178) MB_PORT_COMMON: eMBMasterRTUSend: Port enter critical.
D (1178) MB_PORT_COMMON: eMBMasterRTUSend: Port exit critical
D (1188) MB_PORT_COMMON: xMBMasterPortSerialSendRequest default
D (1198) MB_PORT_COMMON: vMBMasterPortTimersRespondTimeoutEnable Respond enable timeout.
D (1198) MB_MASTER_SERIAL: MB_TX_buffer sent: (9) bytes.
D (1208) MB_PORT_COMMON: xMBPortSerialWaitEvent, UART event: 1 
D (1218) MB_MASTER_SERIAL: MB_uart[2] event:
D (1218) MB_MASTER_SERIAL: uart rx break.
D (1218) MB_PORT_COMMON: 525759:EV_MASTER_FRAME_SENT
D (1228) POLL sent buffer: 06 00 02 44 44 
D (1238) MB_PORT_COMMON: xMBPortSerialWaitEvent, UART event: 0 
D (1238) MB_MASTER_SERIAL: MB_uart[2] event:
D (1238) MB_MASTER_SERIAL: Data event, len: 8.
D (1248) MB_MASTER_SERIAL: Received data: 9(bytes in buffer)
D (1248) MB_MASTER_SERIAL: Timeout occured, processed: 9 bytes
D (1258) MB_PORT_COMMON: 525759:EV_MASTER_FRAME_RECEIVED
D (1258) MB_PORT_COMMON:  xMBMasterPortSerialGetResponse default
D (1268) MB_PORT_COMMON: eMBMasterRTUReceive: Port enter critical.
D (1278) MB_PORT_COMMON: eMBMasterRTUReceive: Port exit critical
D (1278) MB_PORT_COMMON: 525759: Packet data received successfully (0).
D (1288) POLL receive buffer: 06 00 02 44 44 
D (1288) MB_PORT_COMMON: 525759:EV_MASTER_EXECUTE
D (1298) MB_PORT_COMMON: 525759:set event EV_ERROR_OK
D (1298) MB_PORT_COMMON: 525759:EV_MASTER_ERROR_PROCESS
D (1308) MB_PORT_COMMON: vMBMasterCBRequestSuccess: Callback request success.
D (1318) MB_PORT_COMMON: Transaction (525759), processing time(us) = 136105
D (1318) MB_PORT_COMMON: eMBMasterWaitRequestFinish: returned event = 0x80
I (1328) TEST: value:4444(0)
I (1328) main_task: Returned from app_main()

host software log (RS485 interface):

Rx:001949-11:41:09.766-01 06 00 01 33 33 8C EF
Tx:001950-11:41:09.766-01 06 00 01 33 33 8C EF
Rx:001951-11:41:09.939-01 06 00 02 44 44 1B 39
Tx:001952-11:41:09.940-01 06 00 02 44 44 1B 39

If you are sure that it works incorrectly please send your code to reproduce this issue, log of your application with debug verbosity enabled in kconfig and log of the host application (RS485 bus log).

Thank you.

alisitsyn commented 10 months ago

@Asanga-Viraj,

Any update on this issue? Could you please let me know which version of esp-idf and esp-modbus component you are using?

Asanga-Viraj commented 10 months ago

Hi,

I am running complex system in ESP32 with idf 5.0.2 (release) and modbus 1.0.11 (latest) . I extracted what I did for ModBus write to replicate the issue in a single file. I couldn't replicate the issue. Tried many ways, I couldn't.

So, may be some fault in my side which I didn't recognized. Thank you for your help.

alisitsyn commented 10 months ago

Hi @Asanga-Viraj,

Could you try to describe your complex system? For example: which active objects (tasks, interrupts) you have and how they dependent to each other and their priorities compare to Modbus priorities, Modbus settings in sdkconfig, etc. Do you have the tasks with priority >= 20 in your system.The modbus uses esp-timer and its task priority is 21, and higher priority tasks can apply to its functionality as well. Other components (wifi, bluethooth, lwip related) are also apply to the functionality of the whole system with their high priority tasks (prio up to 23). Does the issue exist only when you use the mbc_master_send_request to write the registers or the regular write API functions work the same way? I think the active objects dependencies is the important point to be investigated on high level design stage. Try to add the task with priority like something like ~20 into your extracted code and check issue again.

Thanks.

Asanga-Viraj commented 10 months ago

Hi @alisitsyn ,

I will try to explain the system as much as I can.

Using IDF version 5.0.2
Using lateset esp_modbus 1.0.11
System consist of internet connectivity 3 interfaces such as WiFi, Ethernet and 4G PPP. Only one interface is running at a time.
Once internet is connected, the system is running MQTT (not SSL) to publish data.
Meanwhile RTU ModBus master is running.
- baud 9600
- parity none
- Slave respond timeout = 300ms
- Slave conversion delay = 200ms
- Modbus serial task queue length = 20
- Modbus port task stack size = 4096
- Modbus serial task RX/TX buffer size = 256
- Modbus port task priority = 10
- Modbus task affinity = CPU0
- Modbus controller notification timeout = 20
- Modbus controller notification queue size = 20
- Modbus controller stack size = 4096
- Modbus stack event queue timeout = 20ms
- Modbus stack use timer for 3.5T symbol time measurement = unticked
- Modbus timer uses ISR dispatch method = unticked
ModBus reading and writing each 200ms
Read data comparison tasks and other several tasks are running.
two esp timers are running for data publishing and led indication.
gpio interrupts are running for digital inputs.

Let me know any more information you may want.

Thanks.

alisitsyn commented 10 months ago

Hi @Asanga-Viraj,

Thank you for update. Could you share the sdkconfig file as well? Your logging information can also help to improve your system.

Read data comparison tasks and other several tasks are running.

Please include the tasks priority for most of your tasks including the tasks which do Modbus read data and comparison. This will help to find solutions for your case.

ModBus reading and writing each 200ms

I would suggest to increase the CONFIG_FMB_MASTER_TIMEOUT_MS_RESPOND at least to 400 ms, even through your slave is able to process request during 200ms or less and increase the read/write period. The 200ms response timeout is to short response time for your baud rate and highly loaded system. How the modbus read/write is scheduled in your code?

Modbus task affinity = CPU0

My suggestion is to change affinity setting to CPU1. This is required because your LWIP related services (WIFI, ethernet, PPP) use high priority tasks and process data intensively. This allows to increase the reliability of Modbus data procesisng due to deterministic aspects of protocol. In this case it is recommended to move deterministic protocols to other CPU. This will significantly increase the reliability of data reading/writing in highly loaded system.

Modbus timer uses ISR dispatch method = unticked

I recommend to set CONFIG_FMB_TIMER_USE_ISR_DISPATCH_METHOD=y. The esp-timer which is used by modbus by default use dispatch method ESP_TIMER_TASK when the above setting is disabled. This may cause the decreased accuracy for response timeout event triggering in case of heavily loaded system. If this setting is enabled, the timeout is dispatched from ISR.

Please try the suggestions above and report the results. Thank you.

Asanga-Viraj commented 10 months ago

Hi,

Thank you for the support. I updated the values as requested and did testing. Still got the issue. It is not happening all the times, but randomly occurs. I updated the code to handle this ModBus mis-writing.

As a information, I added sdkconfig file here.

sdkconfig.zip

alisitsyn commented 9 months ago

Hi @Asanga-Viraj ,

It is very strange. I need to reproduce this, but could not do it yet. Let me know if you have any update for this.

espressif / esp-modbus

mbc_master_send_request() doesn't work properly (IDFGH-10848) #32