Errors communicating with Maxwell MTA-48 PID

MAKOMO commented 6 years ago

Versions

Python: 3.6
OS: Mac OS X 10.13
Pymodbus: v1.3-branch-python3-plus-pull74, v1.4 pip install, v1.5 pull
Modbus Hardware (if used): 3x Maxwell MTA-48 PIDs

Pymodbus Specific

Server: ---
Client: rtu sync

Description

This issue popped on using pymodbus within the Artisan open-source roast logging app https://github.com/artisan-roaster-scope/artisan. In the use case here, the user configured the app to harvest the product value (PV) from all three PIDs every 2 sec, triggering Artisan to invoke master.read_holding_registers().

On moving Artisan from Py2 to Py3 a while ago, first a variant of the pymodbus python3 branch was used, patched with the pull74 patch as well as some other minor modifications. The exact version used can be generated by applying the patch https://github.com/artisan-roaster-scope/artisan/tree/master/src/patches to the python3 branch of pymodbus.

That worked quite well. However, updating pymodbus via pip to v1.4 (and now also to the v1.5 Pull #285 ) resulted in flaky communication (lots of errors and drop-outs on the application level, including swap of data between channels).

Code and Logs

I activated logging via

import logging
import logging.handlers as Handlers
logging.basicConfig()
myFormatter = logging.Formatter('%(asctime)s - %(message)s')
log = logging.getLogger()
log.setLevel(logging.DEBUG)
filehandler = Handlers.RotatingFileHandler(os.getenv("HOME") + "/Desktop/artisan-logfile-1.3-patched.txt
[artisan-logfile-1.4.txt](https://github.com/riptideio/pymodbus/files/1925147/artisan-logfile-1.4.txt)
", maxBytes=1024*1024)
filehandler.setFormatter(myFormatter)
log.addHandler(filehandler)
# Artisan logger
_logger = logging.getLogger('Artisan')

to the Artisan source and forwarded 3 builds to that user to run on his setup and returning the corresponding log files (had to add logging of send/recv to the pymodbus-v1.3 variant to match the other two versions).

pymodbus v1.3-patched: artisan-logfile-1.3-patched.txt
pymodbus v1.4 (pip): artisan-logfile-1.4.txt
pymoodbus v1.5 (Pull #285 ): artisan-logfile-1.5.txt

I see that the v1.3-patched variant does not contain any trace of a communication error. The resulting data looks flawless. The v1.4 variant contains errors and the pymodbus lib internal retry seems never to be successful. The retry on the Artisan app level mostly succeeds, but not always. The v1.5 variant contains lots of errors, some Python unpack errors and some typos (TRANSCATION_COMPLETE).

Hope we can work that out as we would love to upgrade to an official pymodbus release soon. Note that Artisan is used with a wide range of PLCs and PIDs via MODBUS RTU/TCP/RTU and otherwise runs flawless.

Let me know if you need more information or we can run more tests. Note that I don't have access to that hardware, but the owner (in another country) is quite supportive.

MAKOMO commented 6 years ago

One more detail: the pymodbus v1.3-patched variant runs with retry_on_empty=False, while the other two with retry_on_empty=True.

dhoomakethu commented 6 years ago

@MAKOMO thanks for the logs, From the logs here are the stats I could get.

patched - 1796 transactions 16 failures, approx run time (877 sec or 14 mins)
1.4 - 1746 transactions 20 failures, approx run time (855 sec or 14 mins)
1.5 - 2093 transactions 20 failures, approx run time (1042 secs or 17 mins)

and observations.

If you see the number of failures , they are almost same (1% of transactions are getting failed) .
The patched version , is not retrying to get the correct response on receiving an error from the device
1.4 is retrying (3 times for all failed transactions) to get the correct response on error but somehow is failing to identify the correct response it is getting in 2nd and 3rd retries (definitely a bug)
1.5 is failing to decode the error frames received (definitely a bug).

I will work on the errors on 1.5 and in my honest opinion You could use 1.5 and the performance of your app should not be affected much.

MAKOMO commented 6 years ago

@dhoomakethu Thanks for taking a look at this and for documenting your observation that precise. It is clear that the real issue of the communication errors is electrical noise and maybe the baudrate is to high for this (but cannot be changed for various reasons). Still it was observed that v1.3-patched performed better for the end-user. This is not about performance, which is not too critical in this app.

What the user observed on testing various versions using v1.4 (effect not shown in these logs) is that (under some pymodbus settings) the data harvested from the 3 devices got swapped, so the channel requesting data from PID1 got the data of PID2. Not sure how that is possible as I am not into the details of the MODBUS protocol. I thought that requests and replies hold some unique id to allow to match them. Maybe I am wrong.

So if you could resolve the issue of failed retries and the decoding of the errors that would be perfect, then we could potentially use v1.5 with retries=1 or retries=2 (on the pymodbus level) and the performance should be on par with the current pymodbus-v1.3-patched we are using, right?

Let us know once you have something for us to test and thanks a lot for your work on pymodus and sharing it with us!

MAKOMO commented 6 years ago

Oh, would the retry_on_empty=False or True make a difference here?

dhoomakethu commented 6 years ago

retry_on_empty is useful in the cases where the slave is not returning any response with in the read timeout. In your case ,they all seem to be returning some response so you can choose not to use it . Re. v1.4 swapping responses , Are you trying to read data from different threads ?

MAKOMO commented 6 years ago

Ok, so retry_on_empty cannot harm if performance is not too important, but the value of catching all readings is.

No, there is only one thread communicating on the MODBUS bus and its guarded by semaphores. What might happen is that a request is send to the first PID, the reply comes too late triggering a timeout and Artisan notes an error value, the next request is send to the next PID in the row and the late reply from the first is received before the 2nd PIDs reply and accepted. Is this scenario possible despite each PID has a different slave ID?

dhoomakethu commented 6 years ago

those checks are handled as part of v1.5 , in earlier version pymodbus would blindly accept anything in the receive buffer and process. with v1.5 , there is a check to validate the unit ID before processing the received response.

MAKOMO commented 6 years ago

Excellent news!

dhoomakethu commented 6 years ago

@MAKOMO could you please give a try on this branch . Let me know your findings.

MAKOMO commented 6 years ago

Success! Not one error on the end-user side. Some retries on the Artisan app layer notes in the log, but that one retry always succeeded. Cannot see any pymodbus level retries (maybe not logged) nor the error that triggered Artisan to retry the request. The retries parameter was not explicit set and should default to 3, right?

Looks good! Thanks a lot! Hope to see this soon in the v1.5 release of your lib.

artisan-logfile-1.5-p1.txt

dhoomakethu commented 6 years ago

@MAKOMO thanks for the confirmation, you can expect a new release by the end of this month. And yes, the default retry count is 3 but it works only on empty response.

pymodbus-dev / pymodbus