hm2_modbus increments hm2_7i96s.0.packet-error-total during LinuxCNC startup

[zz912]

As requested by @hdiethelm , who asked me in #4236:

"Can you create an issue for this or is there already one?"

I am creating this dedicated issue for the problem.

Environment

• LinuxCNC: current master branch
• Mesa: 7i96S with PktUARTTX
• Reproducibility: 100% (every startup)

Important

This issue is not related to the realtime kernel.
I have reproduced it with both:

• PREEMPT_RT
• Xenomai 4

@pcw-mesa has confirmed the same behavior.
#4236 (comment)

Steps to reproduce

In the HAL file, load hm2_modbus, for example:

loadrt hm2_modbus ports="hm2_7i96s.0.pktuart.0" mbccbs="/home/zdenek/linuxcnc/configs/DedaCNC-012/modbus/h100.mbccb" debug=3

Start LinuxCNC.

Expected behavior

After startup:

hm2_7i96s.0.packet-error-total = 0

Actual behavior

After startup:

hm2_7i96s.0.packet-error-total = 1

Additional observations

If the loadrt hm2_modbus ... line is commented out, then after LinuxCNC starts:

hm2_7i96s.0.packet-error-total = 0

Simply loading hm2_modbus is enough to trigger the packet error.

I also disconnected the RS485 wiring completely and the behavior did not change, so the issue does not appear to depend on the physical RS485 connection.

[BsAtHome]

I tried to track down the problem inside the hm2_modbus driver, only to find that the error happens somewhere else:

*** hm2_modbus: rtapi_app_main done
hm2_eth: Soft error write_cnt=6 confirm_write_cnt=31
*** hm2_modbus.0: process first start

The rtapi_app_main() is done and at that time, nothing should be in flight. The PktUART has been configured synchronously in rtapi_app_main before ot is done. When hm2_modbus' process() function is called for the very first time, the error has already happened.

What I think is happening is that there is a faulty pointer in the hm2_7i96s driver in the read part. The soft error trigger is in hm2_eth.c hm2_eth_receive_queued_reads(). This may indicate a stack variable used as a read buffer that needs to be resolved and that will trash the stack. Adding hm2_modbus.0.process just made the error visible, but it is not the cause afaics.

[BsAtHome]

The problem is a logic error in the hm2_eth driver.

The hm2_modbus driver performs synchronous writes to configure the PktUART. This results in exactly 6 packet sent using calls to unqueued write function hm2_eth_write() (via the hm2_pktuart internal code):

hm2_eth: ***hm2_eth_write write_cnt=1 confirm_write_cnt=22031
hm2_eth: ***hm2_eth_write write_cnt=2 confirm_write_cnt=22031
hm2_eth: ***hm2_eth_write write_cnt=3 confirm_write_cnt=22031
hm2_eth: ***hm2_eth_write write_cnt=4 confirm_write_cnt=22031
hm2_eth: ***hm2_eth_write write_cnt=5 confirm_write_cnt=22031
hm2_eth: ***hm2_eth_write write_cnt=6 confirm_write_cnt=22031
*** hm2_modbus: rtapi_app_main done
hm2_eth: Soft error write_cnt=6 confirm_write_cnt=31
*** hm2_modbus.0: process first start

The next step is the normal thread cycle, which begins with a hm2_7i96s.0.read call. This will send a queued set of read commands. The queued read function added a read of the specific board variables and read resolution puts them in confirm_read_cnt and confirm_write_cnt. There is a test in hm2_eth_receive_queued_reads() that looks at the resolution between the packets sent and received.
The flaw is that the error check routine. The write_cnt is no longer zero when hm2_modbus has run its rtapi_app_main() function and that makes the if() detect an error where there is none. Please note that the first read will use the wrong value read from confirm_write_cnt from the board (see the 22031 above and the 31 in the error).
Without hm2_modbus' initialization write_cnt would have been zero and the if() evaluates to false because of a zero write_cnt.

    // (this means that one in 2^32 lost writes will not be diagnosed,
    // each time board->write_cnt overflows)
    if(board->write_cnt && board->write_cnt != board->confirm_write_cnt) {
        LL_PRINT("Soft error write_cnt=%u confirm_write_cnt=%u\n", board->write_cnt, board->confirm_write_cnt);
        result = record_soft_error(board);
    } else {
        decrement_soft_error(board);
    }

The comment in above code is highly misleading because the construct simply hides the logic flaw in the test. It can be traced back to 126d307 where it was first put in place.

The hm2_eth_send_queued_reads() code adds the read_cnt (address 0x10) to be later read as confirm_read_cnt and the hm2_eth_send_queued_writes() code adds the write_cnt (address 0x14) to be later read as confirm_write_cnt. However, the sequence of operations in the thread cycle has the read before the write, making the read of confirm_write_cnt an uninitialized variable (hence the random value 22031 and 31 above).

We need to use a flags to ensure that the queued write has happened before we check for errors. For that we can use a simple flag.

PR in the pipeline.

[grandixximo]

@zz912 The issue closes automatically on merge, @BsAtHome already did testing, you can reopen if it does not work for you.