Correct #2501

[janiversen]

#2501 was made to allow the server to use transaction, and this share code, but it was WRONG.

This pull request reconsiders how the transaction future is used.

[janiversen]

@philj56 feel free to test this one, the future should be working now.

I still have a problem with an example, which I want to include here, so it will not be merged for some hours.

[philj56]

@janiversen I've given this a go, but I still get the cancelled errors. Here's a snippet of the debug log up until the error occurs, and a slightly trimmed traceback:

2024-12-17 09:31:33,723 DEBUG base:101 Frame advanced, resetting header!!
2024-12-17 09:31:33,724 DEBUG transport:386 send: 0x1 0x2 0x0 0xf 0x1 0xd7 0x9 0xc7
2024-12-17 09:31:33,726 DEBUG transport:329 recv: 0x1 0x2 0x3b 0x7 0xaf 0x82 0x47 0x82 0x91 0x14 0x0 0x0 0x0 0x20 0x5 0x0 0x0 0x0 0x48 0x1 0x0 0x0 0x0 0x52 0x0 0x0 0x0 0x0 0x0 0xc0 0x0 0x10 0x4 0x1 0x8 0x40 0x4 0x8 0x10 0x20 0x41 0x44 0x4 0x4 0x0 0x80 0x0 0x0 0x1 0x0 0x2 0x2 0x20 0x26 0x20 0x40 0x4 0x0 0x2 0x0 0x1 0x0 0x3d 0x45 old_data:  addr=None
2024-12-17 09:31:33,727 DEBUG base:91 Processing: 0x1 0x2 0x3b 0x7 0xaf 0x82 0x47 0x82 0x91 0x14 0x0 0x0 0x0 0x20 0x5 0x0 0x0 0x0 0x48 0x1 0x0 0x0 0x0 0x52 0x0 0x0 0x0 0x0 0x0 0xc0 0x0 0x10 0x4 0x1 0x8 0x40 0x4 0x8 0x10 0x20 0x41 0x44 0x4 0x4 0x0 0x80 0x0 0x0 0x1 0x0 0x2 0x2 0x20 0x26 0x20 0x40 0x4 0x0 0x2 0x0 0x1 0x0 0x3d 0x45
2024-12-17 09:31:33,727 DEBUG decoders:113 decoded PDU function_code(2 sub -1) -> ReadDiscreteInputsResponse(dev_id=0, transaction_id=0, address=0, count=0, bits=[True, True, True, False, False, False, False, False, True, True, True, True, False, True, False, True, False, True, False, False, False, False, False, True, True, True, True, False, False, False, True, False, False, True, False, False, False, False, False, True, True, False, False, False, True, False, False, True, False, False, True, False, True, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, True, False, False, True, False, True, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, True, False, False, True, False, True, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, True, False, False, True, False, True, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, True, True, False, False, False, False, False, False, False, False, False, False, False, False, True, False, False, False, False, False, True, False, False, False, False, False, True, False, False, False, False, False, False, False, False, False, False, True, False, False, False, False, False, False, False, False, False, False, True, False, False, False, True, False, False, False, False, False, False, False, False, True, False, False, False, False, False, False, False, False, True, False, False, False, False, False, False, False, False, True, False, False, True, False, False, False, False, False, True, False, False, False, True, False, False, False, True, False, False, False, True, False, False, False, False, False, False, False, True, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, True, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, True, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, True, False, False, False, False, False, False, False, True, False, False, False, False, False, False, False, False, False, False, False, True, False, False, False, True, True, False, False, True, False, False, False, False, False, False, False, True, False, False, False, False, False, False, False, False, True, False, False, False, True, False, False, False, False, False, False, False, False, False, False, False, False, False, False, True, False, False, False, False, False, False, False, False, False, False, False, False, False, False, True, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False], registers=[], status=1) 
2024-12-17 09:31:33,727 DEBUG base:101 Frame advanced, resetting header!!
2024-12-17 09:31:33,727 DEBUG transport:386 send: 0x1 0x1 0x0 0x1 0x0 0xba 0xec 0x79
2024-12-17 09:31:33,730 DEBUG transport:329 recv: 0x1 0x1 0x18 0x2 0x0 0x0 0x10 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x34 0xb0 old_data:  addr=None
2024-12-17 09:31:33,730 DEBUG base:91 Processing: 0x1 0x1 0x18 0x2 0x0 0x0 0x10 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x34 0xb0
2024-12-17 09:31:33,731 DEBUG decoders:113 decoded PDU function_code(1 sub -1) -> ReadCoilsResponse(dev_id=0, transaction_id=0, address=0, count=0, bits=[False, True, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, True, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False, False], registers=[], status=1) 
2024-12-17 09:31:33,731 DEBUG base:101 Frame advanced, resetting header!!
2024-12-17 09:31:33,731 DEBUG transport:386 send: 0x1 0x10 0x2 0xe 0x0 0x2 0x4 0x31 0xba 0x3f 0x64 0x54 0x41
2024-12-17 09:31:33,735 DEBUG transport:329 recv: 0x1 0x10 0x2 0xe 0x0 0x2 0x21 0xb3 old_data:  addr=None
2024-12-17 09:31:33,735 DEBUG base:91 Processing: 0x1 0x10 0x2 0xe 0x0 0x2 0x21 0xb3
2024-12-17 09:31:33,735 DEBUG decoders:113 decoded PDU function_code(16 sub -1) -> WriteMultipleRegistersResponse(dev_id=0, transaction_id=0, address=526, count=2, bits=[], registers=[], status=1) 
2024-12-17 09:31:33,735 DEBUG base:101 Frame advanced, resetting header!!
2024-12-17 09:31:33,736 DEBUG transport:386 send: 0x1 0x10 0x2 0xe 0x0 0x2 0x4 0x31 0xba 0x3f 0x64 0x54 0x41
2024-12-17 09:31:33,809 DEBUG transport:329 recv: 0x1 0x10 0x2 0xe 0x0 0x2 0x21 0xb3 old_data:  addr=None
2024-12-17 09:31:33,809 DEBUG base:91 Processing: 0x1 0x10 0x2 0xe 0x0 0x2 0x21 0xb3
2024-12-17 09:31:33,809 DEBUG decoders:113 decoded PDU function_code(16 sub -1) -> WriteMultipleRegistersResponse(dev_id=0, transaction_id=0, address=526, count=2, bits=[], registers=[], status=1) 
2024-12-17 09:31:33,809 DEBUG base:101 Frame advanced, resetting header!!
2024-12-17 09:31:33,820 DEBUG transport:386 send: 0x1 0x10 0x2 0xe 0x0 0x2 0x4 0x31 0xba 0x3f 0x64 0x54 0x41

Error calling Python override of QThread::run(): Traceback (most recent call last):
  ....
  File "modbus_driver.py", line 506, in write_settings
    result = await self._client.write_registers(group[0].address, values, slave=group[0].device)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "...\Lib\site-packages\pymodbus\transaction\transaction.py", line 140, in execute
    response = await asyncio.wait_for(
               ^^^^^^^^^^^^^^^^^^^^^^^
        self.response_future, timeout=self.comm_params.timeout_connect
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    )
    ^
  File "...\Lib\asyncio\tasks.py", line 507, in wait_for
    return await fut
           ^^^^^^^^^
asyncio.exceptions.CancelledError

Nothing seems particularly wrong up until the cancelled error to me.
For context, this is happening in the following scenario:

• Modbus communication is handled in one thread, with a short timeout set on the connection, and a high rate of messages.
• Some very heavy python processing is happening in another thread, which I assume is causing delays in the Modbus thread due to the GIL.

Presumably that just causes the timeout to trigger more frequently, making the issue more apparent.

This doesn't happen if the future is reset on TimeoutError, e.g. if self.response_future is indented once more here:

pymodbus/pymodbus/transaction/transaction.py

Lines 146 to 148 in 499f648

	except asyncio.exceptions.TimeoutError:
	count_retries += 1
	self.response_future = asyncio.Future()

[janiversen]

Good catch, it should have be indented, corrected on dev.

[janiversen]

hmmm that was not correct, will have to investigate.

[janiversen]

Now it should be corrected.

[philj56]

That seems to work, thanks for the quick responses & fix!