Mixed up responses and callbacks

[Doug Latornell]

I'm trying to use the async client to build a data logging utility. The big goal is to periodically read ranges of coils and holding registers from several PLC and store the values in a database. At the moment though, I can't seem to get the correct callbacks associated with the responses from the PLC. I've boiled the issue down to this fairly short example:

import logging
from twisted.internet import reactor
from twisted.internet.endpoints import TCP4ClientEndpoint
from pymodbus.constants import Defaults
from pymodbus.client.async import ModbusClientFactory

logging.basicConfig()
log = logging.getLogger()
log.setLevel(logging.DEBUG)

def show_bit(response):
    log.debug('65th bit = {0}'.format(response.getBit(65)))

def show_hreg(response):
    log.debug('42nd hreg = {0}'.format(response.getRegister(42)))

def foo(protocol):
    r1 = protocol.read_coils(1400, 400)
    r1.addCallback(show_bit)
    r2 = protocol.read_holding_registers(1400, 100)
    r2.addCallback(show_hreg)
    reactor.callLater(1, protocol.transport.loseConnection)
    reactor.callLater(1.5, reactor.stop)

endpoint = TCP4ClientEndpoint(reactor, '172.20.1.1', Defaults.Port)
protocol = endpoint.connect(ModbusClientFactory())
protocol.addCallback(foo)
reactor.run()

The result of running that code is:

DEBUG:pymodbus.client.async:Client connected to modbus server
DEBUG:pymodbus.transaction:0x0 0x2 0x0 0x0 0x0 0xcb 0x0 0x3 0xc8 0x2 0xd 0x2 0x1e 0x2 0xa 0x2 0xb 0x2 0xa 0x2 0x11 0x2 0x13 0x2
0xc 0x2 0xb 0x2 0x19 0x2 0x28 0x14 0x91 0x14 0x90 0x14 0x8f 0x14 0x8a 0x14 0x4c 0x14 0x9d 0x14 0x9e 0x14 0x9c 0x14 0x9a 0x14
0x58 0x14 0x9c 0x14 0x9e 0x14 0x4e 0x3 0x84 0x14 0xbf 0x14 0xb0 0x14 0xba 0x14 0xb0 0x3 0x84 0x0 0x4 0x0 0xfd 0x0 0x1 0x1 0x51
0x0 0x0 0x1 0xb7 0x0 0xcc 0x0 0x0 0x1 0x10 0x1 0x6f 0x0 0xc8 0x2 0xcf 0x0 0x4f 0x2 0xaf 0x0 0x23 0x0 0x4 0x2 0x24 0x0 0xa8 0x0
0xa9 0x0 0xa9 0x0 0x0 0x0 0x0 0x0 0x3 0x0 0x20 0x1 0x68 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x2 0x0 0x2 0x0 0x2 0x0 0x2
0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x1 0x13 0x2 0x7b 0x2 0x79 0x0 0x0 0x2 0x16 0x3 0x84 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0xd
0x48 0xc 0xe4 0xd 0x48 0xc 0xe4 0x1e 0x78 0x1d 0x4c 0x1c 0xe8 0x1a 0xc2 0x19 0x64 0x19 0x0 0x15 0x4a 0x14 0x50 0x14 0x28 0x0 0x0
0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0xd 0x48
DEBUG:pymodbus.factory:Factory Response[3]
Unhandled error in Deferred:
Unhandled Error
Traceback (most recent call last):
  File "/home/doug/.virtualenvs/beaver/lib/python2.7/site-packages/pymodbus/transaction.py", line 235, in processIncomingPacket
    callback(result) # defer or push to a thread?
  File "/home/doug/.virtualenvs/beaver/lib/python2.7/site-packages/pymodbus/client/async.py", line 91, in _callback
    self._requests.popleft().callback(reply)
  File "/home/doug/.virtualenvs/beaver/lib/python2.7/site-packages/twisted/internet/defer.py", line 368, in callback
    self._startRunCallbacks(result)
  File "/home/doug/.virtualenvs/beaver/lib/python2.7/site-packages/twisted/internet/defer.py", line 464, in _startRunCallbacks
    self._runCallbacks()
--- <exception caught here> ---
  File "/home/doug/.virtualenvs/beaver/lib/python2.7/site-packages/twisted/internet/defer.py", line 551, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "beaver/foo.py", line 16, in show_bit
    log.debug('65th bit = {0}'.format(response.getBit(65)))
exceptions.AttributeError: 'ReadHoldingRegistersResponse' object has no attribute 'getBit'
DEBUG:pymodbus.transaction:0x0 0x1 0x0 0x0 0x0 0x35 0x0 0x1 0x32 0x0 0x0 0x0 0xd3 0x90 0x80 0x4e 0x15 0xf 0x0 0x80 0x0 0x0 0x0 0x0
0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0xf8 0xb6 0xf 0xe0 0x3 0x20 0xc0 0x80 0x63 0xc0 0x31 0xe6 0x9c 0x63 0x0 0x0 0x0
0xe0 0x7f 0x4c 0xfd 0x0
DEBUG:pymodbus.factory:Factory Response[1]
Unhandled error in Deferred:
Unhandled Error
Traceback (most recent call last):
  File "/home/doug/.virtualenvs/beaver/lib/python2.7/site-packages/pymodbus/transaction.py", line 235, in processIncomingPacket
    callback(result) # defer or push to a thread?
  File "/home/doug/.virtualenvs/beaver/lib/python2.7/site-packages/pymodbus/client/async.py", line 91, in _callback
    self._requests.popleft().callback(reply)
  File "/home/doug/.virtualenvs/beaver/lib/python2.7/site-packages/twisted/internet/defer.py", line 368, in callback
    self._startRunCallbacks(result)
  File "/home/doug/.virtualenvs/beaver/lib/python2.7/site-packages/twisted/internet/defer.py", line 464, in _startRunCallbacks
    self._runCallbacks()
--- <exception caught here> ---
  File "/home/doug/.virtualenvs/beaver/lib/python2.7/site-packages/twisted/internet/defer.py", line 551, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "beaver/foo.py", line 20, in show_hreg
    log.debug('42nd hreg = {0}'.format(response.getRegister(42)))
exceptions.AttributeError: 'ReadCoilsResponse' object has no attribute 'getRegister'
DEBUG:pymodbus.client.async:Client disconnected from modbus server:
[Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionDone'>: Connection was closed cleanly.]

My reading of this is that the first response is the result of the read_coils() call and the show_bit() callback is being called, as expected, but the value of response inside the callback is a ReadHoldingRegistersResponse object rather than the expected ReadCoilsResponse object. Then the second response is the result of the read_holding_registers() call and the show_hreg() callback is called, but it is getting a ReadCoilResponse object to work on instead of the expected ReadHoldingRegistersResponse object.

The code works as expected if I remove either of the protocol.read_... calls and its corresponding callback. Oddly, it also works if I swap the order to:

    r2 = protocol.read_holding_registers(1400, 100)
    r2.addCallback(show_hreg)
    r1 = protocol.read_coils(1400, 400)
    r1.addCallback(show_bit)


I don't know whether I'm misunderstanding something about PyModbus, or about Twisted here. I welcome any advice.

[Doug Latornell]

I resolved this by by bundling the deferreds that are returned by the read_*() calls into a DeferredList, and adding the data parser as a callback on the DeferredList.

For my data logging application I can call a function that sets up the DeferredList and its callback as the argument of a twisted.internet.task.LoopingCall().

[Bashwork]

You are right, the results are coming back out of order (it is weird that switching them makes it correct).  The reason is that the deferred implementation is popping the latest one assuming that the device is going to handle requests in order of received, however, that is a little optimistic as there is no guarantee that the order is preserved.  What needs to occur is that the request response should be matched by the TID they use.  I will start working on a patch that should correct your error.  For now, the method you supplied below seems like a good stop gap.

Galen

[Bashwork]

If you would like to test your previous code, the following commit should fix your issue:

https://github.com/bashwork/pymodbus/commit/e921ec02b323124978d4fc1c03a20dfe6d73b7e5 

[Doug Latornell]

Thanks, Galen.

I tested that with the example in this thread and got a traceback. Looks like a typo in async.py. See https://github.com/bashwork/pymodbus/commit/e921ec02b323124978d4fc1c03a20dfe6d73b7e5#commitcomment-1473190

[Galen Collins]

Shoot, I forgot to run those tests.  Thanks for testing; I'll fix this when I get home tonight.

Galen