Modbus wrong value

MriX · July 27, 2020, 5:32pm

Hey there,

I’m trying to get a value out of my SMA Sunny Boy 3.0 via Modbus. This works fine for one device, but the same configuration for another device has a strange behavior. Sometimes it shows the correct value, but the it switches to a value in binary code (e.g. 256, 512, 1024, 2048). When I use a Windows tool to read out the modbus register it always shows the correct value. Has anyone a clue why the Binding sometimes overrides to correct value with (256, 512 or 1024 …)? Maybe @mrbig?

Trace log:

2020-07-27 19:19:31.035 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (5000ms) poll task BasicPollTask@38d21bdc[request=ModbusPollerThingHandler.ModbusPollerReadRequest@1c5c5c8d[slaveId=3,functionCode=READ_MULTIPLE_REGISTERS,start=30775,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f]. Current millis: 1595870371035
2020-07-27 19:19:31.038 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTask@38d21bdc[request=ModbusPollerThingHandler.ModbusPollerReadRequest@1c5c5c8d[slaveId=3,functionCode=READ_MULTIPLE_REGISTERS,start=30775,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f]. Trying to get connection [operation ID f929ce8a-e019-48d9-9f60-f8c19e40b1aa]
2020-07-27 19:19:31.040 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTask@38d21bdc[request=ModbusPollerThingHandler.ModbusPollerReadRequest@1c5c5c8d[slaveId=3,functionCode=READ_MULTIPLE_REGISTERS,start=30775,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 0 [operation ID f929ce8a-e019-48d9-9f60-f8c19e40b1aa]
2020-07-27 19:19:31.042 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Created connection TCPMasterConnection@7d1d82c3[socket=<null>] for endpoint ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502]
2020-07-27 19:19:31.060 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-07-27 19:19:31.062 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 0ms (interTransactionDelayMillis 60ms) before giving returning connection TCPMasterConnection@7d1d82c3[socket=Socket[addr=/192.168.6.115,port=502,localport=39716]] for endpoint ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502], to ensure delay between transactions.
2020-07-27 19:19:31.067 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@7d1d82c3[socket=Socket[addr=/192.168.6.115,port=502,localport=39716]]]) for endpoint ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502] took 24 ms
2020-07-27 19:19:31.073 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTask@38d21bdc[request=ModbusPollerThingHandler.ModbusPollerReadRequest@1c5c5c8d[slaveId=3,functionCode=READ_MULTIPLE_REGISTERS,start=30775,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f] (oneOff=false)! Connection received in 31 ms [operation ID f929ce8a-e019-48d9-9f60-f8c19e40b1aa]
2020-07-27 19:19:31.075 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTask@38d21bdc[request=ModbusPollerThingHandler.ModbusPollerReadRequest@1c5c5c8d[slaveId=3,functionCode=READ_MULTIPLE_REGISTERS,start=30775,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f]. Got a connection successfully [operation ID f929ce8a-e019-48d9-9f60-f8c19e40b1aa]
2020-07-27 19:19:31.092 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID f929ce8a-e019-48d9-9f60-f8c19e40b1aa]
2020-07-27 19:19:31.093 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID f929ce8a-e019-48d9-9f60-f8c19e40b1aa]
2020-07-27 19:19:31.095 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID f929ce8a-e019-48d9-9f60-f8c19e40b1aa]
2020-07-27 19:19:31.096 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_MULTIPLE_REGISTERS): 00 00 00 00 00 06 03 03 78 37 00 02  [operation ID f929ce8a-e019-48d9-9f60-f8c19e40b1aa]
2020-07-27 19:19:31.101 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Sending request with transaction ID 7: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@6afa22b4
2020-07-27 19:19:31.241 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Received response with transaction ID 7
2020-07-27 19:19:31.243 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=3, transaction ID=7): 00 07 00 00 00 07 03 03 04 00 00 01 00  [operation ID f929ce8a-e019-48d9-9f60-f8c19e40b1aa]
2020-07-27 19:19:31.245 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f for request ModbusPollerThingHandler.ModbusPollerReadRequest@1c5c5c8d[slaveId=3,functionCode=READ_MULTIPLE_REGISTERS,start=30775,length=2,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@5659d0d7
2020-07-27 19:19:31.247 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:sb3000-haus:sb3000-haus_input1 received response PollResult(failure=null)
2020-07-27 19:19:31.250 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel number will be updated to '256' (type DecimalType). Input data: number value 256 (value type 'int32' taken into account) and bool value true. Transformation: <identity>
2020-07-27 19:19:31.262 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:sb3000-haus:sb3000-haus_input1:sb3000-haus_power channels updated: {modbus:data:sb3000-haus:sb3000-haus_input1:sb3000-haus_power:number=256}. readValueType=int32, readIndex=Optional[30775], readSubIndex(or 0)=0, extractIndex=0 -> numeric value 256 and boolValue=true. Registers ModbusRegisterArrayImpl(00 00 01 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@1c5c5c8d[slaveId=3,functionCode=READ_MULTIPLE_REGISTERS,start=30775,length=2,maxTries=3]
2020-07-27 19:19:31.266 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f for request ModbusPollerThingHandler.ModbusPollerReadRequest@1c5c5c8d[slaveId=3,functionCode=READ_MULTIPLE_REGISTERS,start=30775,length=2,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@5659d0d7
2020-07-27 19:19:31.270 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502] connection TCPMasterConnection@7d1d82c3[socket=Socket[addr=/192.168.6.115,port=502,localport=39716]] -> true
2020-07-27 19:19:31.273 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection TCPMasterConnection@7d1d82c3[socket=Socket[addr=/192.168.6.115,port=502,localport=39716]] for endpoint ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502]...
2020-07-27 19:19:31.278 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection TCPMasterConnection@7d1d82c3[socket=Socket[addr=/192.168.6.115,port=502,localport=39716]] (endpoint ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502]) age 215ms is over the reconnectAfterMillis=0ms limit or has been connection time (1595870371062) is after the "disconnectBeforeConnectedMillis"=-1 -> disconnecting.
2020-07-27 19:19:31.281 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection TCPMasterConnection@7d1d82c3[socket=Socket[addr=/192.168.6.115,port=502,localport=39716]] for endpoint ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502]
2020-07-27 19:19:31.286 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502]
2020-07-27 19:19:31.289 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502] took 18 ms
2020-07-27 19:19:31.292 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID f929ce8a-e019-48d9-9f60-f8c19e40b1aa]
2020-07-27 19:19:31.295 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 258 ms, connection: 53, transaction=143, callback=25} [operation ID f929ce8a-e019-48d9-9f60-f8c19e40b1aa]
2020-07-27 19:19:31.300 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (5000ms) poll task BasicPollTask@38d21bdc[request=ModbusPollerThingHandler.ModbusPollerReadRequest@1c5c5c8d[slaveId=3,functionCode=READ_MULTIPLE_REGISTERS,start=30775,length=2,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@541237e3[address=192.168.6.115,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@56e9d40f] finished at 1595870371299. Was started at millis: 1595870371035 (=duration of 264 millis)

Thing:

Bridge modbus:tcp:sb3000-haus [ host="192.168.6.115", port=502, id=3 ] {
    Bridge poller sb3000-haus_input1 [ start=30775, length=2, refresh=5000, type="holding" ] {
        Thing data sb3000-haus_power [ readStart="30775", readValueType="int32" ]
    }
}

Item:

Number SB3000_power "SB3.0 Haus Leistung [%d W]" <energy> { channel="modbus:data:sb3000-haus:sb3000-haus_input1:sb3000-haus_power:number" }

Sitemap:

Text item=SB3000_power

Event log:

2020-07-27 19:29:45.480 [vent.ItemStateChangedEvent] - SB3000_power changed from 278 to 256
2020-07-27 19:29:55.673 [vent.ItemStateChangedEvent] - SB3000_power changed from 256 to 279
2020-07-27 19:30:00.796 [vent.ItemStateChangedEvent] - SB3000_power changed from 279 to 256
2020-07-27 19:30:05.890 [vent.ItemStateChangedEvent] - SB3000_power changed from 256 to 270
2020-07-27 19:30:10.997 [vent.ItemStateChangedEvent] - SB3000_power changed from 270 to 256
2020-07-27 19:30:26.315 [vent.ItemStateChangedEvent] - SB3000_power changed from 256 to 276
2020-07-27 19:30:31.420 [vent.ItemStateChangedEvent] - SB3000_power changed from 276 to 256
2020-07-27 19:31:37.822 [vent.ItemStateChangedEvent] - SB3000_power changed from 256 to 265
2020-07-27 19:31:42.926 [vent.ItemStateChangedEvent] - SB3000_power changed from 265 to 256
2020-07-27 19:31:53.128 [vent.ItemStateChangedEvent] - SB3000_power changed from 256 to 265
2020-07-27 19:31:58.235 [vent.ItemStateChangedEvent] - SB3000_power changed from 265 to 264
2020-07-27 19:32:03.333 [vent.ItemStateChangedEvent] - SB3000_power changed from 264 to 256

mrbig · July 27, 2020, 7:22pm

Hello,
according to your log, the data that was read from the inverter is actually 256, the 4 bytes were:

are you sure you are reading from the right address? With modbus it’s easy to be 1 address off, because the address values can be documented according to different standards.

rossko57 · July 27, 2020, 8:43pm

If you have been editing your Things, beware a hidden trap; due to the way data is read using scheduled poller jobs you can end up with multiple polls using different parameters.
If you get weird behaviour after Thing editing, restart the binding modules, or openHAB, before assuming there is still a problem.

MriX · July 27, 2020, 9:04pm

@mrbig Yes I’m sure that this is the right address, because a other modbus explorer returns the correct value from the same register. Tomorrow I can re-enable trace logs and see what the hex code is when OpenHAB gets the correct value.

@rossko57 Thanks for that hint. Actually I already tried the following:

restart OpenHAB
restart operating system
clear OpenHAB Cache
create new items/things
reinstall modbus binding

Nothing of these actions helped.

rossko57 · July 27, 2020, 9:30pm

Have you checked PaperUI’s view of your Modbus Things against what you expect to be created from your xxx.things files? If you’ve been thrashing around with this, maybe you’ve tinkered with PaperUI Thing/channel creation too?

Do you really only have one Modbus data Thing, or is there more to your xxx.things file?

MriX · July 28, 2020, 5:16am

Firstly I tried to create a modbus thing via the PaperUI, but that was another device with a different IP. I removed all my PaperUI things and recreated them in the config file, because this seemed to be easier to configure.
For debugging purposes I removed all modbus things except the one which does not work. The PaperUI shows that correct:

MriX · July 28, 2020, 6:19am

Now I got it working by setting the length to 4.
I don’t understand why, because the documentation says length 2 and the modbus explorer got the correct value with length 2.
@rossko57 Can you explain this behavior?

rossko57 · July 28, 2020, 10:15am

Oh yes, some SMA devices are badly behaved in Modbus terms, and do have that quirk. I’d forgotten about that, it does get tripped over usually in most experiments with SMA, there are many threads here.

Try it again, be interesting if you can actually show different behaviour.

Note that some SMA devices will respond with different data on different Modbus ID numbers, always take care with that. id=3 seems to the most useful.

ssalonen · July 28, 2020, 3:22pm

Yep… device seems to have issues (length=2 vs length=4) and this has been reproduced with third party tools as well. Discussed in detail here: https://github.com/openhab/openhab1-addons/issues/4931 (still valid it seems)