Modbus openHAB2 binding available for alpha testing

HomeAutomation · November 1, 2018, 5:22pm

@ssalonen
@AndrewZ
May I jump in here? I use a ADAM6050 device (12 DI and 6 DO). I use latest 2.4.0 snapshot of modubus binding with OH 2.3 stable

ADAM6050 settings from datasheet:
DI from 0001 length 12
DO from 0017 length 6

My config:

Bridge modbus:tcp:localhostTCP [ host="10.4.1.20", port=502, id=1 ]
{
    Bridge poller discreteInputs [ start=0, length=13, refresh=500, type="discrete" ]
    {
        Thing data di00 [ readStart="0",  readValueType="bit" ]
        Thing data di01 [ readStart="1",  readValueType="bit" ]
        Thing data di02 [ readStart="2",  readValueType="bit" ]
        Thing data di03 [ readStart="3",  readValueType="bit" ]
        Thing data di04 [ readStart="4",  readValueType="bit" ]
        Thing data di05 [ readStart="5",  readValueType="bit" ]       
        Thing data di06 [ readStart="6",  readValueType="bit" ]
        Thing data di07 [ readStart="7",  readValueType="bit" ]
        Thing data di08 [ readStart="8",  readValueType="bit" ]
        Thing data di09 [ readStart="9",  readValueType="bit" ]
        Thing data di10 [ readStart="10", readValueType="bit" ]
        Thing data di11 [ readStart="11", readValueType="bit" ]
    }

    Bridge poller coilsOutputs [ start=16, length=6, refresh=500, type="coil" ]
    {
        Thing data do00 [ readStart="0", readValueType="bit", writeStart="0", writeValueType="bit", writeType="coil" ]
        Thing data do01 [ readStart="1", readValueType="bit", writeStart="1", writeValueType="bit", writeType="coil" ]
        Thing data do02 [ readStart="2", readValueType="bit", writeStart="2", writeValueType="bit", writeType="coil" ]
        Thing data do03 [ readStart="3", readValueType="bit", writeStart="3", writeValueType="bit", writeType="coil" ]
        Thing data do04 [ readStart="4", readValueType="bit", writeStart="4", writeValueType="bit", writeType="coil" ]
        Thing data do05 [ readStart="5", readValueType="bit", writeStart="5", writeValueType="bit", writeType="coil" ]
    }    

    Bridge poller coilsOutputs [ start=17, length=6, refresh=500, type="coil" ]
    {
        Thing data do10 [ readStart="16", readValueType="bit", writeStart="16", writeValueType="bit", writeType="coil" ]
        Thing data do11 [ readStart="17", readValueType="bit", writeStart="17", writeValueType="bit", writeType="coil" ]
        Thing data do12 [ readStart="18", readValueType="bit", writeStart="18", writeValueType="bit", writeType="coil" ]
        Thing data do13 [ readStart="19", readValueType="bit", writeStart="19", writeValueType="bit", writeType="coil" ]
        Thing data do14 [ readStart="20", readValueType="bit", writeStart="20", writeValueType="bit", writeType="coil" ]
        Thing data do15 [ readStart="21", readValueType="bit", writeStart="21", writeValueType="bit", writeType="coil" ]
    }        
}

My items:

Contact DI00            "Digital Input index  0 [%d]"    { channel="modbus:data:localhostTCP:discreteInputs:di00:contact" }
Contact DI01            "Digital Input index  1 [%d]"    { channel="modbus:data:localhostTCP:discreteInputs:di01:contact" }
Contact DI02            "Digital Input index  2 [%d]"    { channel="modbus:data:localhostTCP:discreteInputs:di02:contact" }
Contact DI03            "Digital Input index  3 [%d]"    { channel="modbus:data:localhostTCP:discreteInputs:di03:contact" }
Contact DI04            "Digital Input index  4 [%d]"    { channel="modbus:data:localhostTCP:discreteInputs:di04:contact" }
Contact DI05            "Digital Input index  5 [%d]"    { channel="modbus:data:localhostTCP:discreteInputs:di05:contact" }
Contact DI06            "Digital Input index  6 [%d]"    { channel="modbus:data:localhostTCP:discreteInputs:di06:contact" }
Contact DI07            "Digital Input index  7 [%d]"    { channel="modbus:data:localhostTCP:discreteInputs:di07:contact" }
Contact DI08            "Digital Input index  8 [%d]"    { channel="modbus:data:localhostTCP:discreteInputs:di08:contact" }
Contact DI09            "Digital Input index  9 [%d]"    { channel="modbus:data:localhostTCP:discreteInputs:di09:contact" }
Contact DI10            "Digital Input index 10 [%d]"    { channel="modbus:data:localhostTCP:discreteInputs:di10:contact" }
Contact DI11            "Digital Input index 11 [%d]"    { channel="modbus:data:localhostTCP:discreteInputs:di11:contact" }

Switch DO00             "Digital Output index 0 [%d]"   { channel="modbus:data:localhostTCP:coilsOutputs:do00:switch" }
Switch DO01             "Digital Output index 1 [%d]"   { channel="modbus:data:localhostTCP:coilsOutputs:do01:switch" }
Switch DO02             "Digital Output index 2 [%d]"   { channel="modbus:data:localhostTCP:coilsOutputs:do02:switch" }
Switch DO03             "Digital Output index 3 [%d]"   { channel="modbus:data:localhostTCP:coilsOutputs:do03:switch" }
Switch DO04             "Digital Output index 4 [%d]"   { channel="modbus:data:localhostTCP:coilsOutputs:do04:switch" }
Switch DO05             "Digital Output index 5 [%d]"   { channel="modbus:data:localhostTCP:coilsOutputs:do05:switch" }

Switch DO10             "Digital Output index 0 [%d]"   { channel="modbus:data:localhostTCP:coilsOutputs:do10:switch" }
Switch DO11             "Digital Output index 1 [%d]"   { channel="modbus:data:localhostTCP:coilsOutputs:do11:switch" }
Switch DO12             "Digital Output index 2 [%d]"   { channel="modbus:data:localhostTCP:coilsOutputs:do12:switch" }
Switch DO13             "Digital Output index 3 [%d]"   { channel="modbus:data:localhostTCP:coilsOutputs:do13:switch" }
Switch DO14             "Digital Output index 4 [%d]"   { channel="modbus:data:localhostTCP:coilsOutputs:do14:switch" }
Switch DO15             "Digital Output index 5 [%d]"   { channel="modbus:data:localhostTCP:coilsOutputs:do15:switch" }

What is working is DI0 to DI10. DI11 is not working, but I do not understand why.
DO are not working at all. Can someone give me a hint?

HomeAutomation · November 1, 2018, 5:44pm

I played around a little bit, and after reboot of OH all DI are working and the DO too. It looks like the binding has a problem with reading or interpreting config correct.

HomeAutomation · November 1, 2018, 6:13pm

Now I run into another problem. Even if I use autoupdate to true or false, the switch item is not corresonding with the modbus status

Switch value is 1, Swich ICON is OFF and modbus is ON. Mostly the Switch value is corresponding with the modbus status but the Switch ICON in the sitemap is not. Any idea?

ssalonen · November 2, 2018, 5:43am

Could you please follow the troubleshooting steps and report back here?

Thanks

Sami

HomeAutomation · November 2, 2018, 5:39pm

I checked some other things in my Test-OH installation. It looks like my test pc is to slow. This causes the wrong display of switch status. I will use another test pc next week and give feedback afterwards.

raphael · November 3, 2018, 10:50am

Hi @ssalonen

Sorry for the delayed response.

No 3501: client ACKs with Seq 49
(nothing happens for a while. Would expect Client to send FIN to server 1? Possibly initiate new connection?)

I would expect too, that the server will close the connection completely.

Similar situation happens in the beginning of the log?

Yes same situation happens at the beginning of the log. The situation repeats.

I am wondering what is the ACK at 3454 (and 2951)?

I would say it is the ACK of 3453 (and 2950). 3453 use sequence number 105, which got acknowledged.

EDIT: I think we are having a half-closed connection. Server has cut down the connection but client -> server connection is still active. It might we have the situation described here: https://docs.oracle.com/javase/8/docs/technotes/guides/net/articles/connection_release.html 1

I agree

It might be that once the server sees that it’s getting new data from the pipe (the client->server pipe that is, it was never closed), it just tells to abort the connection, with RST.

I agree, because server is not able to response, because the pipe between server->client is already closed.

I think the binding is checking that half-open connections would not be used – basically see the isConnected check here 1. I wonder if that is working or not here…

I agrees it looks like that isConnected will check if the input or output pipe is closed. So it looks like that it is not working here.

I have no configuration possibilities on server side.

Best regards
Raphael

ssalonen · November 3, 2018, 1:07pm

@raphael could you please capture verbose logs (see docs for instructions)?

Would like to confirm that connection is “checked” before use.

raphael · November 3, 2018, 1:50pm

Hi @ssalonen

Here are the logs capture between two error situations. I have to split the logs into two parts because of the character limitation per post!

First half

2018-11-03 14:40:51.793 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 6feace09-7602-44ac-a38f-80c159d4424a]
2018-11-03 14:40:51.795 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 6feace09-7602-44ac-a38f-80c159d4424a]
2018-11-03 14:40:51.798 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID 6feace09-7602-44ac-a38f-80c159d4424a]
2018-11-03 14:40:51.800 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_MULTIPLE_REGISTERS): 00 00 00 00 00 06 01 03 00 4b 00 07  [operation ID 6feace09-7602-44ac-a38f-80c159d4424a]
2018-11-03 14:40:51.803 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Sending request with transaction ID 36231: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@1c6fad2
2018-11-03 14:40:51.810 [ERROR] [wimpi.modbus.io.ModbusTCPTransaction] - execute try 1/1 error: I/O exception: ModbusIOException Premature end of stream (Header truncated).. Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@1c6fad2 (unit id 1 & transaction 36231). Address: /192.168.1.122:502
2018-11-03 14:40:51.812 [ERROR] [wimpi.modbus.io.ModbusTCPTransaction] - execute reached max tries 1, throwing last error: I/O exception: ModbusIOException Premature end of stream (Header truncated).. Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@1c6fad2 (unit id 1 & transaction 36231). Address: /192.168.1.122:502
2018-11-03 14:40:51.816 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3]). Will try again soon. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: ModbusIOException Premature end of stream (Header truncated). [operation ID 6feace09-7602-44ac-a38f-80c159d4424a]
2018-11-03 14:40:51.819 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - destroyObject for connection TCPMasterConnection@1bbf8c0[socket=Socket[addr=/192.168.1.122,port=502,localport=49170]] and endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502] -> closing the connection
2018-11-03 14:40:51.823 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 0 [operation ID 6feace09-7602-44ac-a38f-80c159d4424a]
2018-11-03 14:40:51.827 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Created connection TCPMasterConnection@d9316c[socket=<null>] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]
2018-11-03 14:40:51.830 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2018-11-03 14:40:51.835 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 0ms (interTransactionDelayMillis 250ms) before giving returning connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502], to ensure delay between transactions.
2018-11-03 14:40:51.838 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]]]) for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502] took 11 ms
2018-11-03 14:40:51.840 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add] (oneOff=false)! Connection received in 13 ms [operation ID 6feace09-7602-44ac-a38f-80c159d4424a]
2018-11-03 14:40:51.842 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 2 out of 3 [operation ID 6feace09-7602-44ac-a38f-80c159d4424a]
2018-11-03 14:40:51.843 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 6feace09-7602-44ac-a38f-80c159d4424a]
2018-11-03 14:40:52.051 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (60000ms) poll task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140]. Current millis: 1541252452050
2018-11-03 14:40:52.053 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140]. Trying to get connection [operation ID 377c40ff-844c-4933-819b-ebf1cb61e134]
2018-11-03 14:40:52.056 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 1 [operation ID 377c40ff-844c-4933-819b-ebf1cb61e134]
2018-11-03 14:40:52.072 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 227 [operation ID 6feace09-7602-44ac-a38f-80c159d4424a]
2018-11-03 14:40:52.074 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_MULTIPLE_REGISTERS): 00 00 00 00 00 06 01 03 00 4b 00 07  [operation ID 6feace09-7602-44ac-a38f-80c159d4424a]
2018-11-03 14:40:52.076 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Sending request with transaction ID 36232: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@1acd1e7
2018-11-03 14:40:52.079 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Received response with transaction ID 36232
2018-11-03 14:40:52.082 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=3, transaction ID=36232): 8d 88 00 00 00 11 01 03 0e 02 1c 00 01 00 00 02 8c 00 00 00 00 00 02  [operation ID 6feace09-7602-44ac-a38f-80c159d4424a]
2018-11-03 14:40:52.084 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@a69c9f
2018-11-03 14:40:52.086 [DEBUG] [handler.ModbusPollerThingHandlerImpl] - Thing modbus:poller:6211f7ee received registers RegisterArrayWrappingInputRegister(02 1c 00 01 00 00 02 8c 00 00 00 00 00 02) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3]
2018-11-03 14:40:52.086 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502] connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] -> true
2018-11-03 14:40:52.103 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]...
2018-11-03 14:40:52.108 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] (endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]) age (273ms) is below the reconnectAfterMillis (120000ms) limit and connection time (1541252451835) is after the "disconnectBeforeConnectedMillis"=-1. Keep the connection open.
2018-11-03 14:40:52.111 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]
2018-11-03 14:40:52.119 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]
2018-11-03 14:40:52.122 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID 6feace09-7602-44ac-a38f-80c159d4424a]
2018-11-03 14:40:52.124 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (60000ms) poll task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add] finished at 1541252452124. Was started at millis: 1541252451767 (=duration of 357 millis)
2018-11-03 14:40:52.152 [TRACE] [odbus.handler.ModbusDataThingHandler] - Channel modbus:data:4373e535:number will be updated to '54.0' (type DecimalType). Input data: number value 540 (value type 'int16' taken into account) and bool value true. Transformation: Transformation@1c48607[tranformation=JS(div10.js),transformationServiceName=JS,transformationServiceParam=div10.js]
2018-11-03 14:40:52.162 [DEBUG] [odbus.handler.ModbusDataThingHandler] - Thing modbus:data:4373e535 channels updated: {modbus:data:4373e535:lastReadSuccess=2018-11-03T14:40:52.155+0100, modbus:data:4373e535:number=54.0}. readValueType=int16, readIndex=Optional[75], readSubIndex(or 0)=0, extractIndex=0 -> numeric value 540 and boolValue=true. Registers RegisterArrayWrappingInputRegister(02 1c 00 01 00 00 02 8c 00 00 00 00 00 02) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3]
2018-11-03 14:40:52.166 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@a69c9f
2018-11-03 14:40:52.358 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 239ms (interTransactionDelayMillis 250ms) before giving returning connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502], to ensure delay between transactions.
2018-11-03 14:40:52.361 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]]]) for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502] took 303 ms
2018-11-03 14:40:52.363 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140] (oneOff=false)! Connection received in 305 ms [operation ID 377c40ff-844c-4933-819b-ebf1cb61e134]
2018-11-03 14:40:52.365 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140]. Got a connection successfully [operation ID 377c40ff-844c-4933-819b-ebf1cb61e134]
2018-11-03 14:40:52.367 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 377c40ff-844c-4933-819b-ebf1cb61e134]
2018-11-03 14:40:52.369 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 377c40ff-844c-4933-819b-ebf1cb61e134]
2018-11-03 14:40:52.371 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID 377c40ff-844c-4933-819b-ebf1cb61e134]
2018-11-03 14:40:52.371 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (60000ms) poll task BasicPollTaskImpl@5b40c0[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363]. Current millis: 1541252452370
2018-11-03 14:40:52.373 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_MULTIPLE_REGISTERS): 00 00 00 00 00 06 01 03 00 32 00 0d  [operation ID 377c40ff-844c-4933-819b-ebf1cb61e134]
2018-11-03 14:40:52.375 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Sending request with transaction ID 36233: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@1f6924e
2018-11-03 14:40:52.376 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTaskImpl@5b40c0[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363]. Trying to get connection [operation ID 906d497c-0d49-4db6-988c-7221d2341aaa]
2018-11-03 14:40:52.392 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@5b40c0[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 1 [operation ID 906d497c-0d49-4db6-988c-7221d2341aaa]
2018-11-03 14:40:52.392 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Received response with transaction ID 36233
2018-11-03 14:40:52.394 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=3, transaction ID=36233): 8d 89 00 00 00 1d 01 03 1a 00 01 00 01 00 00 00 00 01 f4 01 5e 00 00 00 07 20 08 00 00 02 20 02 20 01 2c  [operation ID 377c40ff-844c-4933-819b-ebf1cb61e134]
2018-11-03 14:40:52.396 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@8a8ae3
2018-11-03 14:40:52.396 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502] connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] -> true
2018-11-03 14:40:52.398 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]...
2018-11-03 14:40:52.399 [DEBUG] [handler.ModbusPollerThingHandlerImpl] - Thing modbus:poller:803b921a received registers RegisterArrayWrappingInputRegister(00 01 00 01 00 00 00 00 01 f4 01 5e 00 00 00 07 20 08 00 00 02 20 02 20 01 2c) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3]
2018-11-03 14:40:52.400 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] (endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]) age (565ms) is below the reconnectAfterMillis (120000ms) limit and connection time (1541252451835) is after the "disconnectBeforeConnectedMillis"=-1. Keep the connection open.
2018-11-03 14:40:52.405 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]
2018-11-03 14:40:52.419 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]
2018-11-03 14:40:52.422 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID 377c40ff-844c-4933-819b-ebf1cb61e134]
2018-11-03 14:40:52.424 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (60000ms) poll task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140] finished at 1541252452424. Was started at millis: 1541252452050 (=duration of 374 millis)
2018-11-03 14:40:52.468 [TRACE] [odbus.handler.ModbusDataThingHandler] - Channel modbus:data:5359d839:number will be updated to '54.4' (type DecimalType). Input data: number value 544 (value type 'int16' taken into account) and bool value true. Transformation: Transformation@71e066[tranformation=JS(div10.js),transformationServiceName=JS,transformationServiceParam=div10.js]
2018-11-03 14:40:52.477 [DEBUG] [odbus.handler.ModbusDataThingHandler] - Thing modbus:data:5359d839 channels updated: {modbus:data:5359d839:lastReadSuccess=2018-11-03T14:40:52.472+0100, modbus:data:5359d839:number=54.4}. readValueType=int16, readIndex=Optional[60], readSubIndex(or 0)=0, extractIndex=10 -> numeric value 544 and boolValue=true. Registers RegisterArrayWrappingInputRegister(00 01 00 01 00 00 00 00 01 f4 01 5e 00 00 00 07 20 08 00 00 02 20 02 20 01 2c) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3]
2018-11-03 14:40:52.479 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@8a8ae3
2018-11-03 14:40:52.648 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (60000ms) poll task BasicPollTaskImpl@1cada4b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a]. Current millis: 1541252452647
2018-11-03 14:40:52.651 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 231ms (interTransactionDelayMillis 250ms) before giving returning connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502], to ensure delay between transactions.
2018-11-03 14:40:52.652 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTaskImpl@1cada4b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a]. Trying to get connection [operation ID 920fc504-a181-4082-8d74-6341e0fdeaf9]
2018-11-03 14:40:52.654 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]]]) for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502] took 259 ms
2018-11-03 14:40:52.656 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@1cada4b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 1 [operation ID 920fc504-a181-4082-8d74-6341e0fdeaf9]
2018-11-03 14:40:52.657 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@5b40c0[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363] (oneOff=false)! Connection received in 262 ms [operation ID 906d497c-0d49-4db6-988c-7221d2341aaa]
2018-11-03 14:40:52.661 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTaskImpl@5b40c0[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363]. Got a connection successfully [operation ID 906d497c-0d49-4db6-988c-7221d2341aaa]
2018-11-03 14:40:52.664 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 906d497c-0d49-4db6-988c-7221d2341aaa]

Best regards
Raphael

raphael · November 3, 2018, 1:53pm

Hi @ssalonen

Second half

2018-11-03 14:40:52.664 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 906d497c-0d49-4db6-988c-7221d2341aaa]
2018-11-03 14:40:52.670 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 906d497c-0d49-4db6-988c-7221d2341aaa]
2018-11-03 14:40:52.674 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID 906d497c-0d49-4db6-988c-7221d2341aaa]
2018-11-03 14:40:52.687 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_MULTIPLE_REGISTERS): 00 00 00 00 00 06 01 03 00 0a 00 0d  [operation ID 906d497c-0d49-4db6-988c-7221d2341aaa]
2018-11-03 14:40:52.691 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Sending request with transaction ID 36234: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@720cb9
2018-11-03 14:40:52.719 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Received response with transaction ID 36234
2018-11-03 14:40:52.723 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=3, transaction ID=36234): 8d 8a 00 00 00 1d 01 03 1a 00 01 00 01 00 d2 00 be 00 00 08 20 00 00 00 03 00 00 00 50 00 e9 00 50 01 0a  [operation ID 906d497c-0d49-4db6-988c-7221d2341aaa]
2018-11-03 14:40:52.727 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502] connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] -> true
2018-11-03 14:40:52.727 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@83e17a
2018-11-03 14:40:52.730 [DEBUG] [handler.ModbusPollerThingHandlerImpl] - Thing modbus:poller:0578379b received registers RegisterArrayWrappingInputRegister(00 01 00 01 00 d2 00 be 00 00 08 20 00 00 00 03 00 00 00 50 00 e9 00 50 01 0a) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3]
2018-11-03 14:40:52.731 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]...
2018-11-03 14:40:52.740 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] (endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]) age (904ms) is below the reconnectAfterMillis (120000ms) limit and connection time (1541252451835) is after the "disconnectBeforeConnectedMillis"=-1. Keep the connection open.
2018-11-03 14:40:52.746 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]
2018-11-03 14:40:52.749 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]
2018-11-03 14:40:52.752 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID 906d497c-0d49-4db6-988c-7221d2341aaa]
2018-11-03 14:40:52.755 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (60000ms) poll task BasicPollTaskImpl@5b40c0[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363] finished at 1541252452755. Was started at millis: 1541252452370 (=duration of 385 millis)
2018-11-03 14:40:52.796 [TRACE] [odbus.handler.ModbusDataThingHandler] - Channel modbus:data:e23bcc66:number will be updated to '23.3' (type DecimalType). Input data: number value 233 (value type 'int16' taken into account) and bool value true. Transformation: Transformation@754424[tranformation=JS(div10.js),transformationServiceName=JS,transformationServiceParam=div10.js]
2018-11-03 14:40:52.805 [DEBUG] [odbus.handler.ModbusDataThingHandler] - Thing modbus:data:e23bcc66 channels updated: {modbus:data:e23bcc66:number=23.3, modbus:data:e23bcc66:lastReadSuccess=2018-11-03T14:40:52.799+0100}. readValueType=int16, readIndex=Optional[20], readSubIndex(or 0)=0, extractIndex=10 -> numeric value 233 and boolValue=true. Registers RegisterArrayWrappingInputRegister(00 01 00 01 00 d2 00 be 00 00 08 20 00 00 00 03 00 00 00 50 00 e9 00 50 01 0a) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3]
2018-11-03 14:40:52.807 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@83e17a
2018-11-03 14:40:52.989 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 240ms (interTransactionDelayMillis 250ms) before giving returning connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502], to ensure delay between transactions.
2018-11-03 14:40:52.992 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]]]) for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502] took 332 ms
2018-11-03 14:40:52.994 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@1cada4b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a] (oneOff=false)! Connection received in 334 ms [operation ID 920fc504-a181-4082-8d74-6341e0fdeaf9]
2018-11-03 14:40:52.996 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTaskImpl@1cada4b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a]. Got a connection successfully [operation ID 920fc504-a181-4082-8d74-6341e0fdeaf9]
2018-11-03 14:40:52.998 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 920fc504-a181-4082-8d74-6341e0fdeaf9]
2018-11-03 14:40:53.000 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 920fc504-a181-4082-8d74-6341e0fdeaf9]
2018-11-03 14:40:53.001 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID 920fc504-a181-4082-8d74-6341e0fdeaf9]
2018-11-03 14:40:53.003 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_MULTIPLE_REGISTERS): 00 00 00 00 00 06 01 03 00 02 00 01  [operation ID 920fc504-a181-4082-8d74-6341e0fdeaf9]
2018-11-03 14:40:53.005 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Sending request with transaction ID 36235: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@306f88
2018-11-03 14:40:53.008 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Received response with transaction ID 36235
2018-11-03 14:40:53.010 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=3, transaction ID=36235): 8d 8b 00 00 00 05 01 03 02 00 68  [operation ID 920fc504-a181-4082-8d74-6341e0fdeaf9]
2018-11-03 14:40:53.012 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@64a27d
2018-11-03 14:40:53.012 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502] connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] -> true
2018-11-03 14:40:53.014 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]...
2018-11-03 14:40:53.015 [DEBUG] [handler.ModbusPollerThingHandlerImpl] - Thing modbus:poller:b3d11690 received registers RegisterArrayWrappingInputRegister(00 68) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3]
2018-11-03 14:40:53.017 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] (endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]) age (1181ms) is below the reconnectAfterMillis (120000ms) limit and connection time (1541252451835) is after the "disconnectBeforeConnectedMillis"=-1. Keep the connection open.
2018-11-03 14:40:53.019 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]
2018-11-03 14:40:53.021 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]
2018-11-03 14:40:53.023 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID 920fc504-a181-4082-8d74-6341e0fdeaf9]
2018-11-03 14:40:53.026 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (60000ms) poll task BasicPollTaskImpl@1cada4b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a] finished at 1541252453025. Was started at millis: 1541252452647 (=duration of 378 millis)
2018-11-03 14:40:53.072 [TRACE] [odbus.handler.ModbusDataThingHandler] - Channel modbus:data:29bec5c5:number will be updated to '10.4' (type DecimalType). Input data: number value 104 (value type 'int16' taken into account) and bool value true. Transformation: Transformation@991be[tranformation=JS(div10.js),transformationServiceName=JS,transformationServiceParam=div10.js]
2018-11-03 14:40:53.081 [DEBUG] [odbus.handler.ModbusDataThingHandler] - Thing modbus:data:29bec5c5 channels updated: {modbus:data:29bec5c5:number=10.4, modbus:data:29bec5c5:lastReadSuccess=2018-11-03T14:40:53.075+0100}. readValueType=int16, readIndex=Optional[2], readSubIndex(or 0)=0, extractIndex=0 -> numeric value 104 and boolValue=true. Registers RegisterArrayWrappingInputRegister(00 68) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3]
2018-11-03 14:40:53.083 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@64a27d
2018-11-03 14:40:57.464 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>
2018-11-03 14:40:57.467 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 50, length 13, done: false, canceled: false, delay: 54960. Full task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140]
2018-11-03 14:40:57.471 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 75, length 7, done: false, canceled: false, delay: 54661. Full task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add]
2018-11-03 14:40:57.475 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 10, length 13, done: false, canceled: false, delay: 55284. Full task BasicPollTaskImpl@5b40c0[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363]
2018-11-03 14:40:57.478 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 2, length 1, done: false, canceled: false, delay: 55549. Full task BasicPollTaskImpl@1cada4b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a]
2018-11-03 14:40:57.481 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: callbackThreadPool queue size: 0, remaining space 2147483647. Active threads 0
2018-11-03 14:40:57.484 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>
2018-11-03 14:41:07.487 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>
2018-11-03 14:41:07.496 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 50, length 13, done: false, canceled: false, delay: 44930. Full task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140]
2018-11-03 14:41:07.500 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 75, length 7, done: false, canceled: false, delay: 44632. Full task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add]
2018-11-03 14:41:07.503 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 10, length 13, done: false, canceled: false, delay: 45256. Full task BasicPollTaskImpl@5b40c0[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363]
2018-11-03 14:41:07.507 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 2, length 1, done: false, canceled: false, delay: 45521. Full task BasicPollTaskImpl@1cada4b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a]
2018-11-03 14:41:07.509 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: callbackThreadPool queue size: 0, remaining space 2147483647. Active threads 0
2018-11-03 14:41:07.512 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>
2018-11-03 14:41:17.514 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>
2018-11-03 14:41:17.518 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 50, length 13, done: false, canceled: false, delay: 34909. Full task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140]
2018-11-03 14:41:17.522 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 75, length 7, done: false, canceled: false, delay: 34610. Full task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add]
2018-11-03 14:41:17.525 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 10, length 13, done: false, canceled: false, delay: 35234. Full task BasicPollTaskImpl@5b40c0[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363]
2018-11-03 14:41:17.529 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 2, length 1, done: false, canceled: false, delay: 35499. Full task BasicPollTaskImpl@1cada4b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a]
2018-11-03 14:41:17.531 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: callbackThreadPool queue size: 0, remaining space 2147483647. Active threads 0
2018-11-03 14:41:17.534 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>
2018-11-03 14:41:27.537 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>
2018-11-03 14:41:27.540 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 50, length 13, done: false, canceled: false, delay: 24887. Full task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140]
2018-11-03 14:41:27.544 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 75, length 7, done: false, canceled: false, delay: 24588. Full task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add]
2018-11-03 14:41:27.547 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 10, length 13, done: false, canceled: false, delay: 25212. Full task BasicPollTaskImpl@5b40c0[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363]
2018-11-03 14:41:27.551 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 2, length 1, done: false, canceled: false, delay: 25477. Full task BasicPollTaskImpl@1cada4b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a]
2018-11-03 14:41:27.553 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: callbackThreadPool queue size: 0, remaining space 2147483647. Active threads 0
2018-11-03 14:41:27.556 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>
2018-11-03 14:41:37.559 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>
2018-11-03 14:41:37.563 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 50, length 13, done: false, canceled: false, delay: 14864. Full task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140]
2018-11-03 14:41:37.566 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 75, length 7, done: false, canceled: false, delay: 14566. Full task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add]
2018-11-03 14:41:37.570 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 10, length 13, done: false, canceled: false, delay: 15189. Full task BasicPollTaskImpl@5b40c0[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363]
2018-11-03 14:41:37.573 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 2, length 1, done: false, canceled: false, delay: 15454. Full task BasicPollTaskImpl@1cada4b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a]
2018-11-03 14:41:37.576 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: callbackThreadPool queue size: 0, remaining space 2147483647. Active threads 0
2018-11-03 14:41:37.578 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>
2018-11-03 14:41:47.581 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>
2018-11-03 14:41:47.584 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 50, length 13, done: false, canceled: false, delay: 4843. Full task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140]
2018-11-03 14:41:47.588 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 75, length 7, done: false, canceled: false, delay: 4544. Full task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add]
2018-11-03 14:41:47.591 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 10, length 13, done: false, canceled: false, delay: 5168. Full task BasicPollTaskImpl@5b40c0[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363]
2018-11-03 14:41:47.595 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 2, length 1, done: false, canceled: false, delay: 5433. Full task BasicPollTaskImpl@1cada4b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a]
2018-11-03 14:41:47.597 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: callbackThreadPool queue size: 0, remaining space 2147483647. Active threads 0
2018-11-03 14:41:47.600 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>

raphael · November 3, 2018, 1:55pm

Hi @ssalonen

Last part. This part contains logs from the last poll until reconnection.

2018-11-03 14:41:47.581 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>
2018-11-03 14:41:47.584 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 50, length 13, done: false, canceled: false, delay: 4843. Full task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140]
2018-11-03 14:41:47.588 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 75, length 7, done: false, canceled: false, delay: 4544. Full task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add]
2018-11-03 14:41:47.591 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 10, length 13, done: false, canceled: false, delay: 5168. Full task BasicPollTaskImpl@5b40c0[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@106f07f[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=10,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@92278363]
2018-11-03 14:41:47.595 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 2, length 1, done: false, canceled: false, delay: 5433. Full task BasicPollTaskImpl@1cada4b[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@10781ae[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=2,length=1,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@bebc532a]
2018-11-03 14:41:47.597 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: callbackThreadPool queue size: 0, remaining space 2147483647. Active threads 0
2018-11-03 14:41:47.600 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>
2018-11-03 14:41:52.133 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (60000ms) poll task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add]. Current millis: 1541252512132
2018-11-03 14:41:52.136 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add]. Trying to get connection [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.139 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 1, and active 0 [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.142 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 0ms (interTransactionDelayMillis 250ms) before giving returning connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502], to ensure delay between transactions.
2018-11-03 14:41:52.146 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]]]) for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502] took 3 ms
2018-11-03 14:41:52.149 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add] (oneOff=false)! Connection received in 6 ms [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.152 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add]. Got a connection successfully [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.155 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.157 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.160 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.163 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_MULTIPLE_REGISTERS): 00 00 00 00 00 06 01 03 00 4b 00 07  [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.165 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Sending request with transaction ID 36236: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@18034bf
2018-11-03 14:41:52.172 [ERROR] [wimpi.modbus.io.ModbusTCPTransaction] - execute try 1/1 error: I/O exception: ModbusIOException Premature end of stream (Header truncated).. Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@18034bf (unit id 1 & transaction 36236). Address: /192.168.1.122:502
2018-11-03 14:41:52.174 [ERROR] [wimpi.modbus.io.ModbusTCPTransaction] - execute reached max tries 1, throwing last error: I/O exception: ModbusIOException Premature end of stream (Header truncated).. Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@18034bf (unit id 1 & transaction 36236). Address: /192.168.1.122:502
2018-11-03 14:41:52.178 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3]). Will try again soon. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: ModbusIOException Premature end of stream (Header truncated). [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.181 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - destroyObject for connection TCPMasterConnection@d9316c[socket=Socket[addr=/192.168.1.122,port=502,localport=49172]] and endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502] -> closing the connection
2018-11-03 14:41:52.185 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 0 [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.189 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Created connection TCPMasterConnection@16f8702[socket=<null>] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502]
2018-11-03 14:41:52.193 [DEBUG] [wimpi.modbus.net.TCPMasterConnection] - connect()
2018-11-03 14:41:52.198 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 0ms (interTransactionDelayMillis 250ms) before giving returning connection TCPMasterConnection@16f8702[socket=Socket[addr=/192.168.1.122,port=502,localport=49174]] for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502], to ensure delay between transactions.
2018-11-03 14:41:52.202 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@16f8702[socket=Socket[addr=/192.168.1.122,port=502,localport=49174]]]) for endpoint ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502] took 13 ms
2018-11-03 14:41:52.206 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@1925010[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1cb38e8[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=75,length=7,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@58335add] (oneOff=false)! Connection received in 17 ms [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.208 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 2 out of 3 [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.211 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.427 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (60000ms) poll task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140]. Current millis: 1541252512427
2018-11-03 14:41:52.430 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140]. Trying to get connection [operation ID 37a36e3a-8e5b-4f8e-9b77-65d1cfc9a82a]
2018-11-03 14:41:52.432 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@179c1b7[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@18bdaa9[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=50,length=13,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@bda4ab[address=192.168.1.122,port=502],callback=org.openhab.binding.modbus.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@c430e140] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 1 [operation ID 37a36e3a-8e5b-4f8e-9b77-65d1cfc9a82a]
2018-11-03 14:41:52.434 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 221 [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.436 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_MULTIPLE_REGISTERS): 00 00 00 00 00 06 01 03 00 4b 00 07  [operation ID 63edf593-57d1-4f74-a283-cfa66fcc31b6]
2018-11-03 14:41:52.438 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Sending request with transaction ID 36237: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@16fb80b
2018-11-03 14:41:52.440 [TRACE] [wimpi.modbus.io.ModbusTCPTransaction] - Received response with transaction ID 36237

ssalonen · November 3, 2018, 2:15pm

Thanks

“borrowing connection” log statement

means that it was connected already checked that it is fully connected:

github.com

openhab/openhab2-addons/blob/master/addons/io/org.openhab.io.transport.modbus/src/main/java/org/openhab/io/transport/modbus/internal/ModbusManagerImpl.java#L341


    }
    long start = System.currentTimeMillis();
    try {
        connection = Optional.ofNullable(pool.borrowObject(endpoint));
    } catch (Exception e) {
        logger.warn("Error getting a new connection for endpoint {}. Error was: {} {}", endpoint,
                e.getClass().getName(), e.getMessage());
    }
    if (connection.isPresent()) {
        ModbusSlaveConnection slaveConnection = connection.get();
        if (!slaveConnection.isConnected()) {
            logger.trace(
                    "Received connection which is unconnected, preventing use by returning connection to pool.");
            returnConnection(endpoint, connection);
            connection = Optional.empty();
        }
    }
    logger.trace("borrowing connection (got {}) for endpoint {} took {} ms", connection, endpoint,
            System.currentTimeMillis() - start);
    return connection;
}

So this is a dead-end as well…

raphael · November 3, 2018, 3:26pm

Hi @ssalonen

So far we know, that the client will check the status of the connection and that the check is successful. A successful check means the connection is open in both directions. But we also know that this is not true, because the connection is half way closed, at the time of the check. I would expect that the check fails.

public boolean isConnected() {
        // From j2mod originally. Sockets that are not fully open are closed.
        if (m_Connected && m_Socket != null) {
            // Call close() if the connection is not fully "open"
            if (!m_Socket.isConnected() || m_Socket.isClosed() || m_Socket.isInputShutdown()
                    || m_Socket.isOutputShutdown()) {
                close();
            }
        }
        return m_Connected;
}// isConnected

I would expect that isInputShutdown() returns true and therefore m_Connected got set to false within close().

Best regards
Raphael

ssalonen · November 3, 2018, 6:36pm

Turns out those methods do not reveal if the peer has closed the connection: https://stackoverflow.com/a/28467655

Actually, it seems like there is no way to find out the socket state in java https://stackoverflow.com/questions/155243/why-is-it-impossible-without-attempting-i-o-to-detect-that-tcp-socket-was-grac

Someone proposed sending urgent data to detect the socket state: https://stackoverflow.com/a/701076. This is actually what is being done in some variants (j2mod) of the modbus library the binding uses. But I guess it would lead us back to square one (sending data to detect broken connection).

ssalonen · November 4, 2018, 9:59am

Thanks @rossko57. Now pushed this as example: https://github.com/openhab/openhab2-addons/pull/4196

Btw, I was wrong about the writeValueType – also uint16 is supported in the textual configurations. The PaperUI shows only one version for 16 bit numbers:

There is visual issue that if one has configured uint16 as write value type, it shows as “unselected” / empty in UI.

ssalonen · November 4, 2018, 11:51am

@Nanna_Agesen, your wish has come true! Can you please test this version which brings support for int64?

Following variants are supported when reading 4 consecutive registers a, b, c, and d:

int64 (abcd interpreted as signed 64 bit integer)
uint64 (abcd interpreted as unsigned 64 bit integer)
int64_swap (dcba interpreted as signed 64 bit integer)
uint64_swap (dcba interpreted as unsigned 64 bit integer)

Writing is also supported.

modbus-int64.zip.pdf (402.3 KB)

raphael · November 4, 2018, 1:32pm

Hi @ssalonen

Thanks a lot for your support. At least we know now what happens. I will try to configure the binding in such a way, that the connection will be closed by the client before the server will close it. Otherwise I will ignore the error logs.

Best regards
Raphael

ssalonen · November 7, 2018, 5:19pm

@HomeAutomation you might want to look into recent performance improvements introduced in openHAB 2.4 snapshots and consider if you are affected as well: Many(+100) modbus pollers, is it slowing down the binding?

Perhaps that is why you were facing slow performance. I think the target is to have everything running smoothly with raspberry pi 3 type of HW.

I also suggest to update to latest modbus binding and latest modbus transport, there are some fixes that might show up as “sluggish behaviour”

HomeAutomation · November 22, 2018, 8:09am

The new binding is great, works perfect for me. I see no performance issues. But I have just 48 coils to read/write. I will upgrade to 5 times more in the next weeks. Will see, if this has an impact on the performance.

I have one wish. At the moment if a modbus device is offline, ever polling interval I get a lot of messages in the log, that it is offline. Is it possible, as in other bindings, to send this messages only one time and the if the device comes back an online message.

We can see the current status of the device in paperui and one time in the log. No need to see this every polling interval, blows up my log and other messages are not seen due to the lot of modbus messages.

Just a wish.

pallie42 · December 2, 2018, 7:30pm

Installed the new binding and currently moving everything from 1 RPI to another one, when looking at the logs I see the following:

2018-12-02 20:24:55.138 [ERROR] [wimpi.modbus.io.ModbusTCPTransaction] - execute try 1/1 error: I/O exception: SocketTimeoutException Read timed out. Request: net.wimpi.modbus.msg.ReadInputDiscretesRequest@5fb1ef (unit id 1 & transaction 62935). Address: /192.168.0.112:502

2018-12-02 20:24:55.143 [ERROR] [wimpi.modbus.io.ModbusTCPTransaction] - execute reached max tries 1, throwing last error: I/O exception: SocketTimeoutException Read timed out. Request: net.wimpi.modbus.msg.ReadInputDiscretesRequest@5fb1ef (unit id 1 & transaction 62935). Address: /192.168.0.112:502

2018-12-02 20:24:55.146 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 failed when executing request (ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@91218[slaveId=1,functionCode=READ_INPUT_DISCRETES,start=32768,length=45,maxTries=3]). Will try again soon. Error was I/O error, so reseting the connection. Error details: net.wimpi.modbus.ModbusIOException I/O exception: SocketTimeoutException Read timed out [operation ID bf96ccd5-f064-494b-a4fd-5a780006ea29]

2018-12-02 20:25:06.241 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/1 error: connect timed out. Connection TCPMasterConnection@d6fe19[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502]

2018-12-02 20:25:06.247 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 1, throwing last error: connect timed out. Connection TCPMasterConnection@d6fe19[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502]

2018-12-02 20:25:06.251 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection@d6fe19[socket=Socket[unconnected]] for endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502]: connect timed out

2018-12-02 20:25:06.257 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502] -- aborting request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@eb13c1[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=45,maxTries=3] [operation ID cbdaa2c5-6ed0-449e-ad95-d9060cec810c]

2018-12-02 20:25:06.263 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:61205b16 'Dimmer Living' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502])

==> /var/log/openhab2/events.log <==

2018-12-02 20:25:06.277 [hingStatusInfoChangedEvent] - 'modbus:data:61205b16' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Error (ModbusConnectionException) with read. Request: ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@eb13c1[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=45,maxTries=3]. Description: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502]). Message: Error connecting to endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502]

2018-12-02 20:25:06.283 [hingStatusInfoChangedEvent] - 'modbus:poller:6ae12ba6' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Error with read: org.openhab.io.transport.modbus.ModbusConnectionException: Error connecting to endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502]

2018-12-02 20:25:06.294 [hingStatusInfoChangedEvent] - 'modbus:data:61205b16' changed from OFFLINE (COMMUNICATION_ERROR): Error (ModbusConnectionException) with read. Request: ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@eb13c1[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=45,maxTries=3]. Description: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502]). Message: Error connecting to endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502] to ONLINE

==> /var/log/openhab2/openhab.log <==

2018-12-02 20:25:16.269 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/1 error: connect timed out. Connection TCPMasterConnection@e7dd1[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f566fa[address=192.168.0.112,port=502]

2018-12-02 20:25:16.273 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 1, throwing last error: connect timed out. Connection TCPMasterConnection@e7dd1[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@f566fa[address=192.168.0.112,port=502]

2018-12-02 20:25:16.278 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection@e7dd1[socket=Socket[unconnected]] for endpoint ModbusTCPSlaveEndpoint@f566fa[address=192.168.0.112,port=502]: connect timed out

2018-12-02 20:25:16.283 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusTCPSlaveEndpoint@f566fa[address=192.168.0.112,port=502] -- aborting request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@91218[slaveId=1,functionCode=READ_INPUT_DISCRETES,start=32768,length=45,maxTries=3] [operation ID bf96ccd5-f064-494b-a4fd-5a780006ea29]

2018-12-02 20:25:16.288 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:29118162 'Keuken Werkblad' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@f566fa[address=192.168.0.112,port=502])

==> /var/log/openhab2/events.log <==

2018-12-02 20:25:16.301 [hingStatusInfoChangedEvent] - 'modbus:data:29118162' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Error (ModbusConnectionException) with read. Request: ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@91218[slaveId=1,functionCode=READ_INPUT_DISCRETES,start=32768,length=45,maxTries=3]. Description: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@f566fa[address=192.168.0.112,port=502]). Message: Error connecting to endpoint ModbusTCPSlaveEndpoint@f566fa[address=192.168.0.112,port=502]

2018-12-02 20:25:16.309 [hingStatusInfoChangedEvent] - 'modbus:poller:60aa2e5f' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Error with read: org.openhab.io.transport.modbus.ModbusConnectionException: Error connecting to endpoint ModbusTCPSlaveEndpoint@f566fa[address=192.168.0.112,port=502]

2018-12-02 20:25:16.319 [hingStatusInfoChangedEvent] - 'modbus:data:29118162' changed from OFFLINE (COMMUNICATION_ERROR): Error (ModbusConnectionException) with read. Request: ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@91218[slaveId=1,functionCode=READ_INPUT_DISCRETES,start=32768,length=45,maxTries=3]. Description: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@f566fa[address=192.168.0.112,port=502]). Message: Error connecting to endpoint ModbusTCPSlaveEndpoint@f566fa[address=192.168.0.112,port=502] to ONLINE

==> /var/log/openhab2/openhab.log <==

2018-12-02 20:25:26.294 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - connect try 1/1 error: connect timed out. Connection TCPMasterConnection@d82dae[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502]

2018-12-02 20:25:26.297 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - re-connect reached max tries 1, throwing last error: connect timed out. Connection TCPMasterConnection@d82dae[socket=Socket[unconnected]]. Endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502]

2018-12-02 20:25:26.302 [ERROR] [ing.ModbusSlaveConnectionFactoryImpl] - Error connecting connection TCPMasterConnection@d82dae[socket=Socket[unconnected]] for endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502]: connect timed out

2018-12-02 20:25:26.307 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502] -- aborting request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@eb13c1[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=45,maxTries=3] [operation ID e97955d8-994f-41ae-8af1-eaa2a2b482d5]

2018-12-02 20:25:26.312 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:61205b16 'Dimmer Living' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502])

==> /var/log/openhab2/events.log <==

2018-12-02 20:25:26.326 [hingStatusInfoChangedEvent] - 'modbus:data:61205b16' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Error (ModbusConnectionException) with read. Request: ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@eb13c1[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=45,maxTries=3]. Description: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502]). Message: Error connecting to endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502]

2018-12-02 20:25:26.426 [hingStatusInfoChangedEvent] - 'modbus:poller:60aa2e5f' changed from OFFLINE (COMMUNICATION_ERROR): Error with read: org.openhab.io.transport.modbus.ModbusConnectionException: Error connecting to endpoint ModbusTCPSlaveEndpoint@f566fa[address=192.168.0.112,port=502] to ONLINE

2018-12-02 20:25:26.841 [hingStatusInfoChangedEvent] - 'modbus:poller:6ae12ba6' changed from OFFLINE (COMMUNICATION_ERROR): Error with read: org.openhab.io.transport.modbus.ModbusConnectionException: Error connecting to endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502] to ONLINE

2018-12-02 20:25:26.846 [hingStatusInfoChangedEvent] - 'modbus:data:61205b16' changed from OFFLINE (COMMUNICATION_ERROR): Error (ModbusConnectionException) with read. Request: ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@eb13c1[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=32768,length=45,maxTries=3]. Description: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502]). Message: Error connecting to endpoint ModbusTCPSlaveEndpoint@a10a2e[address=192.168.0.112,port=502] to ONLINE

Kergilo · December 5, 2018, 9:48am

Hello,

I can use the modbus RTU binding when I’m using a USB dongle but my problem is that it doesn’t work when I’m using a transceiver with my nanopi. I think it could be because this transceiver needs a RTS control line. Can you help me to find a solution please?

Thank you.