Skip to content

Forwarder does not respect the unit id when polling serial device #569

New issue
New issue
Closed
#992
Closed
Forwarder does not respect the unit id when polling serial device#569
#992
Labels
Bug
@lampra1

Description

@lampra1
lampra1
opened on Dec 3, 2020

Versions

  • Python: 3.7.9
  • OS: openwrt
  • Pymodbus: 2.4
  • Modbus Hardware on the master: Bus 001 Device 002: ID 1a86:7523 QinHeng Electronics HL-340 USB-Serial adapter

Pymodbus Specific

  • Forwarder example with 2 slave devices
    store = {0x1:RemoteSlaveContext(client),0x2:RemoteSlaveContext(client)}
    context = ModbusServerContext(slaves=store, single=False)

Description

I expect that when polling modbus tcp with device id 2 that the response will originate from the serial device with id 2 not from the serial device with id 1. This is not always the case. The forwarder seems to respect the device id (i.e. does not handle requests for ids not in the store) but the serial poll does not.
I am not fluent with modbus but to me it seems that there is an issue when the modbus tcp request is translated to a serial request.
The only obvious difference that I see in the info below is this warning before sending to device id2 when correct response is received: WARNING:pymodbus.client.sync:Cleanup recv buffer before send: 0x85

### Correct response when polling device 1 & 2 

## Device 1
##==========
DEBUG:pymodbus.server.sync:Started thread to serve client at ('10.200.200.8', 27146)
DEBUG:pymodbus.server.sync:Client Connected [10.200.200.8:27146]
DEBUG:pymodbus.server.sync:Handling data: 0x18 0xd4 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x1e 0x0 0x1
DEBUG:pymodbus.framer.socket_framer:Processing: 0x18 0xd4 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x1e 0x0 0x1
DEBUG:pymodbus.factory:Factory Request[ReadHoldingRegistersRequest: 3]
DEBUG:pymodbus.datastore.remote:validate[3] 30:1
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 5
DEBUG:pymodbus.transaction:SEND: 0x0 0x3 0x0 0x1e 0x0 0x1 0xe5 0xdd
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1607011134.845593, Current Time stamp - 1607011247.894504
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0x1 0x3 0x2 0x0 0x1 0x79 0x84
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 0
DEBUG:pymodbus.transaction:Getting transaction 0
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
DEBUG:pymodbus.datastore.remote:get values[3] 30:1
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 6
DEBUG:pymodbus.transaction:SEND: 0x0 0x3 0x0 0x1e 0x0 0x1 0xe5 0xdd
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1607011247.932957, Current Time stamp - 1607011247.948632
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0x1 0x3 0x2 0x0 0x1 0x79 0x84
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 0
DEBUG:pymodbus.transaction:Getting transaction 0
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
DEBUG:pymodbus.server.sync:send: [ReadRegisterResponse (1)]- b'18d4000000050103020001'


##Device 2
##=================
DEBUG:pymodbus.server.sync:Handling data: 0x18 0xd5 0x0 0x0 0x0 0x6 0x2 0x3 0x0 0x1e 0x0 0x1
DEBUG:pymodbus.framer.socket_framer:Processing: 0x18 0xd5 0x0 0x0 0x0 0x6 0x2 0x3 0x0 0x1e 0x0 0x1
DEBUG:pymodbus.factory:Factory Request[ReadHoldingRegistersRequest: 3]
DEBUG:pymodbus.datastore.remote:validate[3] 30:1
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 7
DEBUG:pymodbus.transaction:SEND: 0x0 0x3 0x0 0x1e 0x0 0x1 0xe5 0xdd
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1607011247.982517, Current Time stamp - 1607011315.260132
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0x1 0x3 0x2 0x0 0x1 0x79 0x84
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 0
DEBUG:pymodbus.transaction:Getting transaction 0
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
DEBUG:pymodbus.datastore.remote:get values[3] 30:1
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 8
DEBUG:pymodbus.transaction:SEND: 0x0 0x3 0x0 0x1e 0x0 0x1 0xe5 0xdd
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1607011315.297763, Current Time stamp - 1607011315.31934
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
WARNING:pymodbus.client.sync:Cleanup recv buffer before send: 0x85
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0x2 0x3 0x2 0x0 0x2 0x7d 0x85
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x2
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 0
DEBUG:pymodbus.transaction:Getting transaction 0
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
DEBUG:pymodbus.server.sync:send: [ReadRegisterResponse (1)]- b'18d5000000050203020002'


##usbmon dump
##===================
##Device 1
ffffffc03dd8b800 2124496240 S Bo:002:02 -115 8 = 0003001e 0001e5dd
ffffffc03dd8b800 2124497247 C Bo:002:02 0 8 >
ffffffc03dd8ba00 2124529266 C Bi:002:02 0 7 = 01030200 017984
ffffffc03dd8ba00 2124529349 S Bi:002:02 -115 32 <
ffffffc03dd8b800 2124549402 S Bo:002:02 -115 8 = 0003001e 0001e5dd
ffffffc03dd8b800 2124550242 C Bo:002:02 0 8 >
ffffffc03dd8b200 2124580242 C Bi:002:02 0 7 = 01030200 017984
ffffffc03dd8b200 2124580275 S Bi:002:02 -115 32 <

##Device 2
ffffffc03dd8b800 2191862925 S Bo:002:02 -115 8 = 0003001e 0001e5dd
ffffffc03dd8b800 2191864054 C Bo:002:02 0 8 >
ffffffc03dd8ba00 2191894072 C Bi:002:02 0 8 = 01030200 01798485
ffffffc03dd8ba00 2191894148 S Bi:002:02 -115 32 <
ffffffc03dd8b800 2191921828 S Bo:002:02 -115 8 = 0003001e 0001e5dd
ffffffc03dd8b800 2191922058 C Bo:002:02 0 8 >
ffffffc03dd8b200 2191955053 C Bi:002:02 0 7 = 02030200 027d85
ffffffc03dd8b200 2191955087 S Bi:002:02 -115 32 <

### Bad response when polling device 2 

##Polling Device 1
##=============
DEBUG:pymodbus.server.sync:Handling data: 0x18 0xd6 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x1e 0x0 0x1
DEBUG:pymodbus.framer.socket_framer:Processing: 0x18 0xd6 0x0 0x0 0x0 0x6 0x1 0x3 0x0 0x1e 0x0 0x1
DEBUG:pymodbus.factory:Factory Request[ReadHoldingRegistersRequest: 3]
DEBUG:pymodbus.datastore.remote:validate[3] 30:1
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 9
DEBUG:pymodbus.transaction:SEND: 0x0 0x3 0x0 0x1e 0x0 0x1 0xe5 0xdd
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1607011315.357063, Current Time stamp - 1607011642.620016
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0x1 0x3 0x2 0x0 0x1 0x79 0x84
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 0
DEBUG:pymodbus.transaction:Getting transaction 0
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
DEBUG:pymodbus.datastore.remote:get values[3] 30:1
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 10
DEBUG:pymodbus.transaction:SEND: 0x0 0x3 0x0 0x1e 0x0 0x1 0xe5 0xdd
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1607011642.658191, Current Time stamp - 1607011642.67946
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0x1 0x3 0x2 0x0 0x1 0x79 0x84
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 0
DEBUG:pymodbus.transaction:Getting transaction 0
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
DEBUG:pymodbus.server.sync:send: [ReadRegisterResponse (1)]- b'18d6000000050103020001'

##Polling Device 2
##=============
DEBUG:pymodbus.server.sync:Handling data: 0x18 0xd7 0x0 0x0 0x0 0x6 0x2 0x3 0x0 0x1e 0x0 0x1
DEBUG:pymodbus.framer.socket_framer:Processing: 0x18 0xd7 0x0 0x0 0x0 0x6 0x2 0x3 0x0 0x1e 0x0 0x1
DEBUG:pymodbus.factory:Factory Request[ReadHoldingRegistersRequest: 3]
DEBUG:pymodbus.datastore.remote:validate[3] 30:1
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 11
DEBUG:pymodbus.transaction:SEND: 0x0 0x3 0x0 0x1e 0x0 0x1 0xe5 0xdd
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1607011642.715754, Current Time stamp - 1607011650.938875
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0x1 0x3 0x2 0x0 0x1 0x79 0x84
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 0
DEBUG:pymodbus.transaction:Getting transaction 0
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
DEBUG:pymodbus.datastore.remote:get values[3] 30:1
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 12
DEBUG:pymodbus.transaction:SEND: 0x0 0x3 0x0 0x1e 0x0 0x1 0xe5 0xdd
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1607011650.980093, Current Time stamp - 1607011650.997104
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0x1 0x3 0x2 0x0 0x1 0x79 0x84
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 0
DEBUG:pymodbus.transaction:Getting transaction 0
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
DEBUG:pymodbus.server.sync:send: [ReadRegisterResponse (1)]- b'18d7000000050203020001'

##Usbmon dump
##===================
##Polling Device 1
ffffffc03dd8b800 2519222446 S Bo:002:02 -115 8 = 0003001e 0001e5dd
ffffffc03dd8b800 2519223467 C Bo:002:02 0 8 >
ffffffc03dd8ba00 2519253494 C Bi:002:02 0 7 = 01030200 017984
ffffffc03dd8ba00 2519253576 S Bi:002:02 -115 32 <
ffffffc03dd8b800 2519280816 S Bo:002:02 -115 8 = 0003001e 0001e5dd
ffffffc03dd8b800 2519281461 C Bo:002:02 0 8 >
ffffffc03dd8b200 2519313104 C Bi:002:02 0 7 = 01030200 017984
ffffffc03dd8b200 2519313144 S Bi:002:02 -115 32 <

##Polling Device 2
ffffffc03dd8b800 2527542186 S Bo:002:02 -115 8 = 0003001e 0001e5dd
ffffffc03dd8b800 2527542601 C Bo:002:02 0 8 >
ffffffc03dd8ba00 2527576601 C Bi:002:02 0 7 = 01030200 017984
ffffffc03dd8ba00 2527576681 S Bi:002:02 -115 32 <
ffffffc03dd8b800 2527597878 S Bo:002:02 -115 8 = 0003001e 0001e5dd
ffffffc03dd8b800 2527598569 C Bo:002:02 0 8 >
ffffffc03dd8b200 2527626602 C Bi:002:02 0 7 = 01030200 017984
ffffffc03dd8b200 2527626676 S Bi:002:02 -115 32 <

Metadata

Metadata

Assignees

No one assigned

    Labels

    Bug

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions