Modbus v1 to v2 conversion

pallie42 · April 13, 2020, 5:36pm

Hi All,

I’m currently reinstalling openhab and wanted to use this as an opportunity to also move to the ‘new’ modbus binding. So far I have been able to migrate most of my items to the new config however I don’t see how I can get my rollershutters working.

I’m connecting to a beckhoff and it is expecting to have an update of 2 values:

the position of the blind (0-100)
update of a boolean so it goes to the defined position

In the old config I had the following setup for my rollershutter item:

Rollershutter ScreenLivGr “Living Groot Raam [%.1f]” (ALL) {autoupdate=“false”,modbus=">[slave2:30],>[slave1:30:transformation=JS(add1.js)],<[slave4:30:transformation=JS(identity.js)]"}

Slave1:30 in the example above took care of the position update and slave2:30 of the boolean update.

How should you approach this best in the new binding?

rossko57 · April 13, 2020, 6:07pm

The version 2 binding does allow you to inject a script for “advanced writing” that can coordinate multiple write actions by encoding as JSON.

pallie42 · April 17, 2020, 7:18pm

Thanks! I created the following script:

(function(cmd) {
   
    var value = cmd;
	var value2 = 1;
    var address = "32798";
	var address2 = "32810";
    if(value === undefined || address === undefined) {
        // unknown command, do not write anything
        return "[]";
    } else {
        return (
            "["
              + "{\"functionCode\": 6, \"address\":" + address.toString() + ", \"value\": [" + value +  "] }"
            + "," + "{\"functionCode\": 6, \"address\":" + address2.toString() + ", \"value\": [" + value2 +  "] }" + "]"
        );
    }
})(input)

the problem is that 1 out of 10 the write to modbus is reversed:

2020-04-17 21:12:37.490 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Successful write, matching request BasicModbusWriteRegisterRequestBlueprint@2429c6[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3]

2020-04-17 21:12:37.564 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Successful write, matching request BasicModbusWriteRegisterRequestBlueprint@1195c26[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 0f),maxTries=3]

Can I influence the order of writing? I would always like to write first the value and afterwards the 1 as this will activate the rollershutter to go to the value

rossko57 · April 17, 2020, 7:51pm

Have you any actual evidence of that? I ask because messages getting logged and datestamped out of order does not prove the order of events.

I would expect your JSON write elements to get queued for the binding to action in the order they are written. Queued transfers to a single endpoint (IP address or serial port) should all be managed serially, i.e. finish one before starting the next, just what you need. I wouldn’t really expect even some error/retry activity to mess that up.

It might just be possible for a scheduled read poll or some other write to get inserted into the queue between your JSON writes, which might upset your slave, but shouldn’t affect order.

@ssalonen , could there be some asynchronous jiggery-pokery here?

pallie42 · April 17, 2020, 8:18pm

I see 9/10 expected behavior of the rollershutter and when it’s not working as expected the order is reversed in the logs

rossko57 · April 17, 2020, 8:24pm

Fair enough, we’ll wait on binding expertise.

ssalonen · April 17, 2020, 8:58pm

I would expect things to happen in order but perhaps there is something that does not respect the order…

Can you repeat the issue again with verbose logging (see docs for exact instructions) enabled please?

pallie42 · April 18, 2020, 7:33am

This output contains a correct write and a ‘failed’ one:

2020-04-18 09:14:15.656 [TRACE] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:localhostTCP:holding:ScreenLivGrH ‘Modbus Data’ received command ‘69’ to channel ‘modbus:data:localhostTCP:holding:ScreenLivGrH:dimmer’
2020-04-18 09:14:15.678 [TRACE] [ernal.handler.ModbusDataThingHandler] - Submitting write task: BasicWriteTask@190657b[request=BasicModbusWriteRegisterRequestBlueprint@15852d8[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 45),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7] (based from transformation [{“functionCode”: 6, “address”:32798, “value”: [69] },{“functionCode”: 6, “address”:32810, “value”: [1] }])
2020-04-18 09:14:15.683 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Scheduling one-off write task BasicWriteTask@190657b[request=BasicModbusWriteRegisterRequestBlueprint@15852d8[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 45),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7]
2020-04-18 09:14:15.687 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Will now execute one-off write task BasicWriteTask@190657b[request=BasicModbusWriteRegisterRequestBlueprint@15852d8[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 45),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7], waited in thread pool for 3
2020-04-18 09:14:15.688 [TRACE] [ernal.handler.ModbusDataThingHandler] - Submitting write task: BasicWriteTask@1f3c1a0[request=BasicModbusWriteRegisterRequestBlueprint@17cd158[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7] (based from transformation [{“functionCode”: 6, “address”:32798, “value”: [69] },{“functionCode”: 6, “address”:32810, “value”: [1] }])
2020-04-18 09:14:15.691 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicWriteTask@190657b[request=BasicModbusWriteRegisterRequestBlueprint@15852d8[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 45),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7]. Trying to get connection [operation ID b1c47de7-827a-4315-8d08-3a398da8a54c]
2020-04-18 09:14:15.691 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Scheduling one-off write task BasicWriteTask@1f3c1a0[request=BasicModbusWriteRegisterRequestBlueprint@17cd158[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7]
2020-04-18 09:14:15.694 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicWriteTask@190657b[request=BasicModbusWriteRegisterRequestBlueprint@15852d8[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 45),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7] (oneOff=true)! Waiting for connection. Idle connections for this endpoint: 1, and active 0 [operation ID b1c47de7-827a-4315-8d08-3a398da8a54c]
2020-04-18 09:14:15.695 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Will now execute one-off write task BasicWriteTask@1f3c1a0[request=BasicModbusWriteRegisterRequestBlueprint@17cd158[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7], waited in thread pool for 5
2020-04-18 09:14:15.697 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-04-18 09:14:15.699 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicWriteTask@1f3c1a0[request=BasicModbusWriteRegisterRequestBlueprint@17cd158[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7]. Trying to get connection [operation ID b1ed4c46-1281-41d6-976c-2ccfa23a96c3]
2020-04-18 09:14:15.703 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicWriteTask@1f3c1a0[request=BasicModbusWriteRegisterRequestBlueprint@17cd158[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7] (oneOff=true)! Waiting for connection. Idle connections for this endpoint: 0, and active 1 [operation ID b1ed4c46-1281-41d6-976c-2ccfa23a96c3]
2020-04-18 09:14:15.704 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 0ms (interTransactionDelayMillis 60ms) before giving returning connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57940]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502], to ensure delay between transactions.
2020-04-18 09:14:15.708 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57940]]]) for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] took 11 ms
2020-04-18 09:14:15.712 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicWriteTask@190657b[request=BasicModbusWriteRegisterRequestBlueprint@15852d8[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 45),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7] (oneOff=true)! Connection received in 15 ms [operation ID b1c47de7-827a-4315-8d08-3a398da8a54c]
2020-04-18 09:14:15.715 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicWriteTask@190657b[request=BasicModbusWriteRegisterRequestBlueprint@15852d8[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 45),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7]. Got a connection successfully [operation ID b1c47de7-827a-4315-8d08-3a398da8a54c]
2020-04-18 09:14:15.718 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID b1c47de7-827a-4315-8d08-3a398da8a54c]
2020-04-18 09:14:15.721 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID b1c47de7-827a-4315-8d08-3a398da8a54c]
2020-04-18 09:14:15.724 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID b1c47de7-827a-4315-8d08-3a398da8a54c]
2020-04-18 09:14:15.727 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with read request (FC=WRITE_SINGLE_REGISTER): 00 00 00 00 00 06 02 06 80 1e 00 45 [operation ID b1c47de7-827a-4315-8d08-3a398da8a54c]
2020-04-18 09:14:15.730 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Sending request with transaction ID 24964: net.wimpi.modbus.msg.WriteSingleRegisterRequest@b48112
2020-04-18 09:14:15.743 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Received response with transaction ID 24964
2020-04-18 09:14:15.746 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for write request (FC=6, transaction ID=24964): 61 84 00 00 00 06 02 06 80 1e 00 45 [operation ID b1c47de7-827a-4315-8d08-3a398da8a54c]
2020-04-18 09:14:15.747 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Calling write response callback org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7 for request BasicModbusWriteRegisterRequestBlueprint@15852d8[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 45),maxTries=3]. Response was ModbusResponseImpl(responseFC=6)
2020-04-18 09:14:15.750 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Successful write, matching request BasicModbusWriteRegisterRequestBlueprint@15852d8[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 45),maxTries=3]
2020-04-18 09:14:15.753 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Called write response callback org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7 for request BasicModbusWriteRegisterRequestBlueprint@15852d8[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 45),maxTries=3]. Response was ModbusResponseImpl(responseFC=6)
2020-04-18 09:14:15.755 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57940]] -> true
2020-04-18 09:14:15.757 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57940]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]…
2020-04-18 09:14:15.759 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57940]] (endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]) age 56ms is over the reconnectAfterMillis=0ms limit or has been connection time (1587194055703) is after the “disconnectBeforeConnectedMillis”=1587150537379 -> disconnecting.
2020-04-18 09:14:15.762 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - …Passivated connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57940]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]
2020-04-18 09:14:15.764 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]
2020-04-18 09:14:15.766 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] took 11 ms
2020-04-18 09:14:15.767 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-04-18 09:14:15.768 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID b1c47de7-827a-4315-8d08-3a398da8a54c]
2020-04-18 09:14:15.770 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 79 ms, connection: 28, transaction=15, callback=8} [operation ID b1c47de7-827a-4315-8d08-3a398da8a54c]
2020-04-18 09:14:15.820 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 49ms (interTransactionDelayMillis 60ms) before giving returning connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57942]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502], to ensure delay between transactions.
2020-04-18 09:14:15.822 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57942]]]) for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] took 115 ms
2020-04-18 09:14:15.823 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicWriteTask@1f3c1a0[request=BasicModbusWriteRegisterRequestBlueprint@17cd158[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7] (oneOff=true)! Connection received in 117 ms [operation ID b1ed4c46-1281-41d6-976c-2ccfa23a96c3]
2020-04-18 09:14:15.825 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicWriteTask@1f3c1a0[request=BasicModbusWriteRegisterRequestBlueprint@17cd158[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7]. Got a connection successfully [operation ID b1ed4c46-1281-41d6-976c-2ccfa23a96c3]
2020-04-18 09:14:15.827 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID b1ed4c46-1281-41d6-976c-2ccfa23a96c3]
2020-04-18 09:14:15.828 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID b1ed4c46-1281-41d6-976c-2ccfa23a96c3]
2020-04-18 09:14:15.829 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID b1ed4c46-1281-41d6-976c-2ccfa23a96c3]
2020-04-18 09:14:15.831 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with read request (FC=WRITE_SINGLE_REGISTER): 00 00 00 00 00 06 02 06 80 2a 00 01 [operation ID b1ed4c46-1281-41d6-976c-2ccfa23a96c3]
2020-04-18 09:14:15.833 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Sending request with transaction ID 24965: net.wimpi.modbus.msg.WriteSingleRegisterRequest@1fd9228
2020-04-18 09:14:15.845 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Received response with transaction ID 24965
2020-04-18 09:14:15.847 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for write request (FC=6, transaction ID=24965): 61 85 00 00 00 06 02 06 80 2a 00 01 [operation ID b1ed4c46-1281-41d6-976c-2ccfa23a96c3]
2020-04-18 09:14:15.849 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Calling write response callback org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7 for request BasicModbusWriteRegisterRequestBlueprint@17cd158[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3]. Response was ModbusResponseImpl(responseFC=6)
2020-04-18 09:14:15.850 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Successful write, matching request BasicModbusWriteRegisterRequestBlueprint@17cd158[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3]
2020-04-18 09:14:15.853 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Called write response callback org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7 for request BasicModbusWriteRegisterRequestBlueprint@17cd158[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3]. Response was ModbusResponseImpl(responseFC=6)
2020-04-18 09:14:15.854 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57942]] -> true
2020-04-18 09:14:15.856 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57942]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]…
2020-04-18 09:14:15.858 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57942]] (endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]) age 87ms is over the reconnectAfterMillis=0ms limit or has been connection time (1587194055770) is after the “disconnectBeforeConnectedMillis”=1587150537379 -> disconnecting.
2020-04-18 09:14:15.860 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - …Passivated connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57942]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]
2020-04-18 09:14:15.862 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]
2020-04-18 09:14:15.864 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] took 9 ms
2020-04-18 09:14:15.865 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID b1ed4c46-1281-41d6-976c-2ccfa23a96c3]
2020-04-18 09:14:15.867 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 168 ms, connection: 128, transaction=15, callback=6} [operation ID b1ed4c46-1281-41d6-976c-2ccfa23a96c3]
2020-04-18 09:14:17.536 [TRACE] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:localhostTCP:holding:ScreenLivGrH ‘Modbus Data’ received command ‘0’ to channel ‘modbus:data:localhostTCP:holding:ScreenLivGrH:dimmer’
2020-04-18 09:14:17.561 [TRACE] [ernal.handler.ModbusDataThingHandler] - Submitting write task: BasicWriteTask@138b765[request=BasicModbusWriteRegisterRequestBlueprint@15e1b0a[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 00),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7] (based from transformation [{“functionCode”: 6, “address”:32798, “value”: [0] },{“functionCode”: 6, “address”:32810, “value”: [1] }])
2020-04-18 09:14:17.565 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Scheduling one-off write task BasicWriteTask@138b765[request=BasicModbusWriteRegisterRequestBlueprint@15e1b0a[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 00),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7]
2020-04-18 09:14:17.570 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Will now execute one-off write task BasicWriteTask@138b765[request=BasicModbusWriteRegisterRequestBlueprint@15e1b0a[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 00),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7], waited in thread pool for 5
2020-04-18 09:14:17.570 [TRACE] [ernal.handler.ModbusDataThingHandler] - Submitting write task: BasicWriteTask@1833352[request=BasicModbusWriteRegisterRequestBlueprint@1d82f58[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7] (based from transformation [{“functionCode”: 6, “address”:32798, “value”: [0] },{“functionCode”: 6, “address”:32810, “value”: [1] }])
2020-04-18 09:14:17.573 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicWriteTask@138b765[request=BasicModbusWriteRegisterRequestBlueprint@15e1b0a[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 00),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7]. Trying to get connection [operation ID a7865652-2d9e-4dfa-8d36-288e9b4c86ef]
2020-04-18 09:14:17.575 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Scheduling one-off write task BasicWriteTask@1833352[request=BasicModbusWriteRegisterRequestBlueprint@1d82f58[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7]
2020-04-18 09:14:17.611 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Will now execute one-off write task BasicWriteTask@1833352[request=BasicModbusWriteRegisterRequestBlueprint@1d82f58[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7], waited in thread pool for 4
2020-04-18 09:14:17.615 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicWriteTask@1833352[request=BasicModbusWriteRegisterRequestBlueprint@1d82f58[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7]. Trying to get connection [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]
2020-04-18 09:14:17.617 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicWriteTask@1833352[request=BasicModbusWriteRegisterRequestBlueprint@1d82f58[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7] (oneOff=true)! Waiting for connection. Idle connections for this endpoint: 1, and active 0 [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]
2020-04-18 09:14:17.576 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicWriteTask@138b765[request=BasicModbusWriteRegisterRequestBlueprint@15e1b0a[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 00),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7] (oneOff=true)! Waiting for connection. Idle connections for this endpoint: 1, and active 0 [operation ID a7865652-2d9e-4dfa-8d36-288e9b4c86ef]
2020-04-18 09:14:17.620 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-04-18 09:14:17.624 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 0ms (interTransactionDelayMillis 60ms) before giving returning connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57944]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502], to ensure delay between transactions.
2020-04-18 09:14:17.626 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57944]]]) for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] took 6 ms
2020-04-18 09:14:17.628 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicWriteTask@1833352[request=BasicModbusWriteRegisterRequestBlueprint@1d82f58[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7] (oneOff=true)! Connection received in 9 ms [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]
2020-04-18 09:14:17.630 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicWriteTask@1833352[request=BasicModbusWriteRegisterRequestBlueprint@1d82f58[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7]. Got a connection successfully [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]
2020-04-18 09:14:17.632 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]
2020-04-18 09:14:17.633 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]
2020-04-18 09:14:17.635 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]
2020-04-18 09:14:17.637 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with read request (FC=WRITE_SINGLE_REGISTER): 00 00 00 00 00 06 02 06 80 2a 00 01 [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]
2020-04-18 09:14:17.639 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Sending request with transaction ID 24966: net.wimpi.modbus.msg.WriteSingleRegisterRequest@1c146e7
2020-04-18 09:14:17.650 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Received response with transaction ID 24966
2020-04-18 09:14:17.652 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for write request (FC=6, transaction ID=24966): 61 86 00 00 00 06 02 06 80 2a 00 01 [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]
2020-04-18 09:14:17.654 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Calling write response callback org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7 for request BasicModbusWriteRegisterRequestBlueprint@1d82f58[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3]. Response was ModbusResponseImpl(responseFC=6)
2020-04-18 09:14:17.658 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Successful write, matching request BasicModbusWriteRegisterRequestBlueprint@1d82f58[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3]
2020-04-18 09:14:17.660 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Called write response callback org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7 for request BasicModbusWriteRegisterRequestBlueprint@1d82f58[slaveId=2,reference=32810,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01),maxTries=3]. Response was ModbusResponseImpl(responseFC=6)
2020-04-18 09:14:17.662 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57944]] -> true
2020-04-18 09:14:17.664 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57944]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]…
2020-04-18 09:14:17.666 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57944]] (endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]) age 43ms is over the reconnectAfterMillis=0ms limit or has been connection time (1587194057623) is after the “disconnectBeforeConnectedMillis”=1587150537379 -> disconnecting.
2020-04-18 09:14:17.669 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - …Passivated connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57944]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]
2020-04-18 09:14:17.671 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]
2020-04-18 09:14:17.673 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] took 10 ms
2020-04-18 09:14:17.674 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]
2020-04-18 09:14:17.676 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 60 ms, connection: 21, transaction=13, callback=9} [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]
2020-04-18 09:14:17.683 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 12ms (interConnectDelayMillis 0ms, interTransactionDelayMillis 60ms) before connecting disconnected connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57944]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502], to allow delay between connections re-connects
2020-04-18 09:14:17.685 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-04-18 09:14:17.726 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 38ms (interTransactionDelayMillis 60ms) before giving returning connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57946]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502], to ensure delay between transactions.
2020-04-18 09:14:17.728 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57946]]]) for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] took 108 ms
2020-04-18 09:14:17.730 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicWriteTask@138b765[request=BasicModbusWriteRegisterRequestBlueprint@15e1b0a[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 00),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7] (oneOff=true)! Connection received in 110 ms [operation ID a7865652-2d9e-4dfa-8d36-288e9b4c86ef]
2020-04-18 09:14:17.732 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicWriteTask@138b765[request=BasicModbusWriteRegisterRequestBlueprint@15e1b0a[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 00),maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7]. Got a connection successfully [operation ID a7865652-2d9e-4dfa-8d36-288e9b4c86ef]
2020-04-18 09:14:17.733 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID a7865652-2d9e-4dfa-8d36-288e9b4c86ef]
2020-04-18 09:14:17.735 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID a7865652-2d9e-4dfa-8d36-288e9b4c86ef]
2020-04-18 09:14:17.736 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID a7865652-2d9e-4dfa-8d36-288e9b4c86ef]
2020-04-18 09:14:17.738 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with read request (FC=WRITE_SINGLE_REGISTER): 00 00 00 00 00 06 02 06 80 1e 00 00 [operation ID a7865652-2d9e-4dfa-8d36-288e9b4c86ef]
2020-04-18 09:14:17.739 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Sending request with transaction ID 24967: net.wimpi.modbus.msg.WriteSingleRegisterRequest@137fb2d
2020-04-18 09:14:17.751 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Received response with transaction ID 24967
2020-04-18 09:14:17.753 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for write request (FC=6, transaction ID=24967): 61 87 00 00 00 06 02 06 80 1e 00 00 [operation ID a7865652-2d9e-4dfa-8d36-288e9b4c86ef]
2020-04-18 09:14:17.755 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Calling write response callback org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7 for request BasicModbusWriteRegisterRequestBlueprint@15e1b0a[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 00),maxTries=3]. Response was ModbusResponseImpl(responseFC=6)
2020-04-18 09:14:17.756 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Successful write, matching request BasicModbusWriteRegisterRequestBlueprint@15e1b0a[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 00),maxTries=3]
2020-04-18 09:14:17.758 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Called write response callback org.openhab.binding.modbus.internal.handler.ModbusDataThingHandler@179a9f7 for request BasicModbusWriteRegisterRequestBlueprint@15e1b0a[slaveId=2,reference=32798,functionCode=WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 00),maxTries=3]. Response was ModbusResponseImpl(responseFC=6)
2020-04-18 09:14:17.766 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57946]] -> true
2020-04-18 09:14:17.768 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57946]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]…
2020-04-18 09:14:17.770 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57946]] (endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]) age 81ms is over the reconnectAfterMillis=0ms limit or has been connection time (1587194057688) is after the “disconnectBeforeConnectedMillis”=1587150537379 -> disconnecting.
2020-04-18 09:14:17.772 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - …Passivated connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57946]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]
2020-04-18 09:14:17.774 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502]
2020-04-18 09:14:17.776 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] took 11 ms
2020-04-18 09:14:17.777 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID a7865652-2d9e-4dfa-8d36-288e9b4c86ef]
2020-04-18 09:14:17.780 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 207 ms, connection: 122, transaction=14, callback=11} [operation ID a7865652-2d9e-4dfa-8d36-288e9b4c86ef]
2020-04-18 09:14:25.216 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] -
2020-04-18 09:14:25.219 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_INPUT_DISCRETES, start 32768, length 45, done: false, canceled: false, delay: 11079. Full task BasicPollTaskImpl@d03559[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@15ee052[slaveId=2,functionCode=READ_INPUT_DISCRETES,start=32768,length=45,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@3e949a84]
2020-04-18 09:14:25.230 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_INPUT_REGISTERS, start 32768, length 45, done: false, canceled: false, delay: 11375. Full task BasicPollTaskImpl@1957c7b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@16c10ae[slaveId=2,functionCode=READ_INPUT_REGISTERS,start=32768,length=45,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@7a006d83]
2020-04-18 09:14:25.233 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduledThreadPoolExecutor queue size: 2, remaining space 2147483647. Active threads 1
2020-04-18 09:14:25.235 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>
2020-04-18 09:14:35.237 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] -
2020-04-18 09:14:35.241 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_INPUT_DISCRETES, start 32768, length 45, done: false, canceled: false, delay: 1057. Full task BasicPollTaskImpl@d03559[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@15ee052[slaveId=2,functionCode=READ_INPUT_DISCRETES,start=32768,length=45,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@3e949a84]
2020-04-18 09:14:35.244 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_INPUT_REGISTERS, start 32768, length 45, done: false, canceled: false, delay: 1361. Full task BasicPollTaskImpl@1957c7b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@16c10ae[slaveId=2,functionCode=READ_INPUT_REGISTERS,start=32768,length=45,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@7a006d83]
2020-04-18 09:14:35.247 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduledThreadPoolExecutor queue size: 2, remaining space 2147483647. Active threads 1
2020-04-18 09:14:35.249 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>
2020-04-18 09:14:36.299 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (50000ms) poll task BasicPollTaskImpl@d03559[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@15ee052[slaveId=2,functionCode=READ_INPUT_DISCRETES,start=32768,length=45,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@3e949a84]. Current millis: 1587194076298
2020-04-18 09:14:36.302 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTaskImpl@d03559[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@15ee052[slaveId=2,functionCode=READ_INPUT_DISCRETES,start=32768,length=45,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@3e949a84]. Trying to get connection [operation ID e19e0a10-f87c-4c77-bf20-c6449d0a64fd]
2020-04-18 09:14:36.305 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@d03559[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@15ee052[slaveId=2,functionCode=READ_INPUT_DISCRETES,start=32768,length=45,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@3e949a84] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 1, and active 0 [operation ID e19e0a10-f87c-4c77-bf20-c6449d0a64fd]
2020-04-18 09:14:36.308 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2020-04-18 09:14:36.315 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 0ms (interTransactionDelayMillis 60ms) before giving returning connection TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57952]] for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502], to ensure delay between transactions.
2020-04-18 09:14:36.319 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57952]]]) for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] took 10 ms
2020-04-18 09:14:36.323 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@d03559[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@15ee052[slaveId=2,functionCode=READ_INPUT_DISCRETES,start=32768,length=45,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@3e949a84] (oneOff=false)! Connection received in 14 ms [operation ID e19e0a10-f87c-4c77-bf20-c6449d0a64fd]
2020-04-18 09:14:36.326 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTaskImpl@d03559[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@15ee052[slaveId=2,functionCode=READ_INPUT_DISCRETES,start=32768,length=45,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@3e949a84]. Got a connection successfully [operation ID e19e0a10-f87c-4c77-bf20-c6449d0a64fd]
2020-04-18 09:14:36.330 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID e19e0a10-f87c-4c77-bf20-c6449d0a64fd]
2020-04-18 09:14:36.333 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID e19e0a10-f87c-4c77-bf20-c6449d0a64fd]
2020-04-18 09:14:36.336 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID e19e0a10-f87c-4c77-bf20-c6449d0a64fd]
2020-04-18 09:14:36.339 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_INPUT_DISCRETES): 00 00 00 00 00 06 02 02 80 00 00 2d [operation ID e19e0a10-f87c-4c77-bf20-c6449d0a64fd]
2020-04-18 09:14:36.343 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Sending request with transaction ID 24968: net.wimpi.modbus.msg.ReadInputDiscretesRequest@7c2a08
2020-04-18 09:14:36.350 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Received response with transaction ID 24968
2020-04-18 09:14:36.354 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=2, transaction ID=24968): 61 88 00 00 00 09 02 02 06 01 08 00 00 00 00 [operation ID e19e0a10-f87c-4c77-bf20-c6449d0a64fd]
2020-04-18 09:14:36.357 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@3e949a84 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@15ee052[slaveId=2,functionCode=READ_INPUT_DISCRETES,start=32768,length=45,maxTries=3]. Response was net.wimpi.modbus.msg.ReadInputDiscretesResponse@6f03bc

pallie42 · April 18, 2020, 7:43am

Another more practical question. How can I pass the address to write to dynamically into the writetransform and JSON creation?

rossko57 · April 18, 2020, 9:53am

The simple answer - you can pass only one thing into a transformation, which is the state of your Item. That’s it.

It’s theoretically possible to pass multiple bits of info encoded into your one state, and have your transformation script decode it for processing.
I’d be suspicious that it’s simply the wrong approach to your need, though.

pallie42 · April 18, 2020, 10:40am

Ok but that would mean that I have to write a seperate one for each dimmer/rollshutter/… while in the previous binding I just passed two values to two different addresses.

Or do you see a different approach?

rossko57 · April 18, 2020, 11:08am

Not really. It’s a weird approach to using Modbus, but there are plenty of weird Modbus schemes out there. I think to be honest you were lucky that it worked reliably with binding v1.

I’ve yet to work through your trace log properly, but will make an advance guess that it may be to do with scheduling writes for the same “now” millisecond; pretty sure quartz scheduler is granular at 1mS.
I ran into a rules createTimer() bug with that root cause, although the end result there was disappearing tasks rather than random ordering.

rossko57 · April 18, 2020, 11:43am

I think the “write order swap” issue is around TCP disconnect/reconnect on every transfer.

You might be able to improve your chances pending a proper fix, by moving away from default behaviour, explained here -

pallie42 · April 18, 2020, 12:08pm

Ok I have adjusted that. I have the feeling that if I put the refresh paramter to a longer interval that it improves the behavior

rossko57 · April 18, 2020, 1:32pm

Had a poke at the trace log. The “disordered” event summary -

// we begin with OH command
09:14:17.536 [TRACE] [ernal.handler.ModbusDataThingHandler] - Thing ...received command ‘0’ ...

// lets call this "write A", payload 00 wanted to be written first
09:14:17.561 [TRACE] [ernal.handler.ModbusDataThingHandler] - Submitting write task: BasicWriteTask@138b765[request=...WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 00)...
09:14:17.565 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Scheduling one-off write task BasicWriteTask@138b765[...
09:14:17.570 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Will now execute one-off write task BasicWriteTask@138b765[..., waited in thread pool for 5

// but this system is multi-threading
// lets call this "write B", payload 01, beginning its journey and wanted to be written second
09:14:17.570 [TRACE] [ernal.handler.ModbusDataThingHandler] - Submitting write task: BasicWriteTask@1833352[...WRITE_SINGLE_REGISTER,registers=ModbusRegisterArrayImpl(00 01)...

// write A still moving along
09:14:17.573 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicWriteTask@138b765[... Trying to get connection [operation ID a7865652-2d9e-4dfa-8d36-288e9b4c86ef]

// write B also progressing
09:14:17.575 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Scheduling one-off write task BasicWriteTask@1833352[...
09:14:17.611 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Will now execute one-off write task BasicWriteTask@1833352[...], waited in thread pool for 4
09:14:17.615 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicWriteTask@1833352[...]. Trying to get connection [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]
09:14:17.617 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicWriteTask@1833352[...Waiting for connection. Idle connections for this endpoint: 1, and active 0 [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]

// now here's an oddity.
//  The log above is write B arriving at "Waiting for connection", timestamped 617

// the log below is write A arriving at the same point
//  - with an EARLIER timestamp 576, but appearing in the log AFTER.   
// Something somewhere had a little sleep, the logger itself perhaps doing write to disc, no idea.
09:14:17.576 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicWriteTask@138b765[... Waiting for connection. Idle connections for this endpoint: 1, and active 0 [operation ID a7865652-2d9e-4dfa-8d36-288e9b4c86ef]

// this feels like it ought to be the part where B has got ahead of A in the race for a TCP connection?
// at this point both writes are waiting for the same TCP resource

// so now TCP becomes available
09:14:17.620 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
09:14:17.624 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 0ms .. to ensure delay between transactions.
09:14:17.626 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@f1542[socket=Socket[addr=/192.168.0.37,port=502,localport=57944]]]) for endpoint ModbusTCPSlaveEndpoint@56c345[address=192.168.0.37,port=502] took 6 ms

// and here is write B securing the new connection,
// so now the writes will be out of order, because A  cannot move on until B has finished
09:14:17.628 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicWriteTask@1833352[...Connection received in 9 ms [operation ID a33c0b3e-2832-4e42-906e-504832f65fca]

I’m not sure what could be done here, perhaps a fixed delay between issuing writes from the “JSON interpreter” part? I imagine it would be very difficult to do anything else.
Perhaps instead, it’s the race for TCP that needs to be single-threaded? Or choosing the lowest task reference number?

There’s no evidence of it happening here, but it does remain possible for a scheduled poll or suchlike to slip into the workflow between the two parts of your JSON write. All perfectly “legal” from openHABs viewpoint, but your PLC might not like it, I don’t know. A fixed delay would increase the chances of this.

ssalonen · April 18, 2020, 5:48pm

Yes it seems that order is guaranteed to some extent : the write tasks are always ordered fifo “Will now execute one-off write task” but unfortunately then race to get the connection (after which only one thread is executing as noted by @rossko57) . In some cases the first thread takes longer time to reach this synchronization point even though it got a “head start”.

As a workaround, I would try to limit number of threads to one

In services/runtime.cfg:

org.eclipse.smarthome.threadpool:modbusManagerPollerThreadPool=1

Restart openhab after this.

This should not have any downsides at all when you are dealing with single slave. Perhaps the default should be changed…

Reference and more information (e.g. Checking that setting takes effect) [SOLVED] Openhab2 2.5.0 RuleEngine Number of threads

rossko57 · April 18, 2020, 6:00pm

I didn’t realise thread allocation could be micro-managed to that degree. (I assume “poller” includes modbus writes in this case, essentially the same operation from OH perspective)
It ought to do the trick, with no real impact.

ssalonen · April 18, 2020, 8:32pm

Yeah naming is from the time there were two separate thread pools for reading and writing (which turned out to be completely unnecessary)

pallie42 · April 19, 2020, 7:55am

That seems to resolve it. Thanks!

Still need to find out how I can do this without making a seperate JS for each rollershutter/dimmer but this is already fixing the basis