[SOLVED] Many(+100) modbus pollers, is it slowing down the binding?

rossko57 · December 5, 2018, 3:21pm

I suppose the docs are not very clear that you need not have any persistence installed at all, but if you do have one you then should specify the default one.

Anyway, most people do end up with one even if its only for restore-on-startup, I wouldn’t worry about it. It works happily alongside Modbus for most people.

To look into your problem, I think Sami will need to see those verbose logs of your Dimmer example

ssalonen · December 10, 2018, 7:20pm

@Pe_Man & @Tim2016 any updates?

Looking forward to your report.

@Pe_Man please see this post above for the next steps.

Latest snapshot is now logging more clearly where the time goes, verbose logs will tell. See https://github.com/openhab/openhab2-addons/pull/4304

Pe_Man · December 10, 2018, 8:54pm

Hi,

I have some other issues with the modbus-slave at the moment, I will fix that, then test and come back with the results

Rado1 · December 26, 2018, 5:44pm

Hey,

This weekend I switched to the new modbus binding ever since I notice that the cpu load is much higher when I frequently pol around 10ms.With the previous binding this was not the happening.I read the tread and you where asking for the verbose log’s?In de karaf console i can not set it to verbose so i set it to debug for the modbus binding and this is what came out.Is this what jou need to analyze it?Normaly my cpu load is around 8% with the new binding it is around 35%.

2018-12-26 18:06:31.354 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di23 channels updated: {modbus:data:slave11:slave11Inputs:di23:contact=CLOSED}. readValueType=bit, readIndex=Optional[7] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@7db2b478[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.354 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di24 channels updated: {modbus:data:slave11:slave11Inputs:di24:contact=CLOSED}. readValueType=bit, readIndex=Optional[8] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@7db2b478[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.355 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di25 channels updated: {modbus:data:slave11:slave11Inputs:di25:contact=OPEN}. readValueType=bit, readIndex=Optional[9] -> numeric value 1 and boolValue=true. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@7db2b478[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.356 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di26 channels updated: {modbus:data:slave11:slave11Inputs:di26:contact=CLOSED}. readValueType=bit, readIndex=Optional[10] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@7db2b478[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.357 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di27 channels updated: {modbus:data:slave11:slave11Inputs:di27:contact=CLOSED}. readValueType=bit, readIndex=Optional[11] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@7db2b478[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.357 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di28 channels updated: {modbus:data:slave11:slave11Inputs:di28:contact=CLOSED}. readValueType=bit, readIndex=Optional[12] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@7db2b478[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.358 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di29 channels updated: {modbus:data:slave11:slave11Inputs:di29:contact=CLOSED}. readValueType=bit, readIndex=Optional[13] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@7db2b478[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.358 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di30 channels updated: {}. readValueType=bit, readIndex=Optional[14] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@7db2b478[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.359 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di31 channels updated: {modbus:data:slave11:slave11Inputs:di31:contact=CLOSED}. readValueType=bit, readIndex=Optional[15] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@7db2b478[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.410 [DEBUG] [handler.ModbusPollerThingHandlerImpl] - Thing modbus:poller:slave10:slave10Inputs received coils BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@50255960[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.411 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di00 channels updated: {modbus:data:slave10:slave10Inputs:di00:contact=CLOSED}. readValueType=bit, readIndex=Optional[0] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@50255960[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.411 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di01 channels updated: {modbus:data:slave10:slave10Inputs:di01:contact=CLOSED}. readValueType=bit, readIndex=Optional[1] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@50255960[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.412 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di02 channels updated: {modbus:data:slave10:slave10Inputs:di02:contact=CLOSED}. readValueType=bit, readIndex=Optional[2] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@50255960[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.413 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di03 channels updated: {modbus:data:slave10:slave10Inputs:di03:contact=CLOSED}. readValueType=bit, readIndex=Optional[3] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@50255960[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.414 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di04 channels updated: {modbus:data:slave10:slave10Inputs:di04:contact=CLOSED}. readValueType=bit, readIndex=Optional[4] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@50255960[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.415 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di05 channels updated: {modbus:data:slave10:slave10Inputs:di05:contact=CLOSED}. readValueType=bit, readIndex=Optional[5] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@50255960[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.420 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di06 channels updated: {modbus:data:slave10:slave10Inputs:di06:contact=CLOSED}. readValueType=bit, readIndex=Optional[6] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@50255960[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 18:06:31.421 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di07 channels updated: {modbus:data:slave10:slave10Inputs:di07:contact=CLOSED}. readValueType=bit, readIndex=Optional[7] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@50255960[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

ssalonen · December 26, 2018, 5:58pm

Hi @Rado1, appreciate if you will test with openHAB 2.4 release, using 2.4 release version of the binding.

Please configure logging as adviced in the docs. You can use pastebin.com to share longer logs

Finally, can you please share the thing and item configurations

Rado1 · December 26, 2018, 6:13pm

Hey,

I am using openhab 2.4 release and the 2.4 release of the binding.
Ok i set the logging to TRACE.
This is what came out.

2018-12-26 19:04:28.091 [DEBUG] [handler.ModbusPollerThingHandlerImpl] - Thing modbus:poller:slave11:slave11Inputs received coils BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.093 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.094 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di16 channels updated: {modbus:data:slave11:slave11Inputs:di16:contact=CLOSED}. readValueType=bit, readIndex=Optional[0] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.095 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.097 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di17 channels updated: {modbus:data:slave11:slave11Inputs:di17:contact=CLOSED}. readValueType=bit, readIndex=Optional[1] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.098 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.100 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di18 channels updated: {modbus:data:slave11:slave11Inputs:di18:contact=CLOSED}. readValueType=bit, readIndex=Optional[2] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.101 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.102 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di19 channels updated: {modbus:data:slave11:slave11Inputs:di19:contact=CLOSED}. readValueType=bit, readIndex=Optional[3] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.104 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.105 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di20 channels updated: {modbus:data:slave11:slave11Inputs:di20:contact=CLOSED}. readValueType=bit, readIndex=Optional[4] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.106 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.107 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di21 channels updated: {modbus:data:slave11:slave11Inputs:di21:contact=CLOSED}. readValueType=bit, readIndex=Optional[5] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.108 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.109 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di22 channels updated: {modbus:data:slave11:slave11Inputs:di22:contact=CLOSED}. readValueType=bit, readIndex=Optional[6] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.110 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.111 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di23 channels updated: {modbus:data:slave11:slave11Inputs:di23:contact=CLOSED}. readValueType=bit, readIndex=Optional[7] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.112 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.113 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di24 channels updated: {modbus:data:slave11:slave11Inputs:di24:contact=CLOSED}. readValueType=bit, readIndex=Optional[8] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.114 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'OPEN' (type OpenClosedType). Input data: number value 1 (value type 'bit' taken into account) and bool value true. Transformation: <identity>

2018-12-26 19:04:28.115 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di25 channels updated: {modbus:data:slave11:slave11Inputs:di25:contact=OPEN}. readValueType=bit, readIndex=Optional[9] -> numeric value 1 and boolValue=true. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.116 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.117 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di26 channels updated: {modbus:data:slave11:slave11Inputs:di26:contact=CLOSED}. readValueType=bit, readIndex=Optional[10] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.118 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.120 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di27 channels updated: {modbus:data:slave11:slave11Inputs:di27:contact=CLOSED}. readValueType=bit, readIndex=Optional[11] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.121 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.122 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di28 channels updated: {modbus:data:slave11:slave11Inputs:di28:contact=CLOSED}. readValueType=bit, readIndex=Optional[12] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.123 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.124 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di29 channels updated: {modbus:data:slave11:slave11Inputs:di29:contact=CLOSED}. readValueType=bit, readIndex=Optional[13] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.125 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di30 channels updated: {}. readValueType=bit, readIndex=Optional[14] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.126 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.127 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di31 channels updated: {modbus:data:slave11:slave11Inputs:di31:contact=CLOSED}. readValueType=bit, readIndex=Optional[15] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.171 [DEBUG] [handler.ModbusPollerThingHandlerImpl] - Thing modbus:poller:slave10:slave10Inputs received coils BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.173 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.174 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di00 channels updated: {modbus:data:slave10:slave10Inputs:di00:contact=CLOSED}. readValueType=bit, readIndex=Optional[0] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.175 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.176 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di01 channels updated: {modbus:data:slave10:slave10Inputs:di01:contact=CLOSED}. readValueType=bit, readIndex=Optional[1] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.178 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.179 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di02 channels updated: {modbus:data:slave10:slave10Inputs:di02:contact=CLOSED}. readValueType=bit, readIndex=Optional[2] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.180 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.182 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di03 channels updated: {modbus:data:slave10:slave10Inputs:di03:contact=CLOSED}. readValueType=bit, readIndex=Optional[3] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.183 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.185 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di04 channels updated: {modbus:data:slave10:slave10Inputs:di04:contact=CLOSED}. readValueType=bit, readIndex=Optional[4] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.186 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.187 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di05 channels updated: {modbus:data:slave10:slave10Inputs:di05:contact=CLOSED}. readValueType=bit, readIndex=Optional[5] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.188 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.189 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di06 channels updated: {modbus:data:slave10:slave10Inputs:di06:contact=CLOSED}. readValueType=bit, readIndex=Optional[6] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.190 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.191 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di07 channels updated: {modbus:data:slave10:slave10Inputs:di07:contact=CLOSED}. readValueType=bit, readIndex=Optional[7] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.192 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.193 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di08 channels updated: {modbus:data:slave10:slave10Inputs:di08:contact=CLOSED}. readValueType=bit, readIndex=Optional[8] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.194 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.195 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di09 channels updated: {modbus:data:slave10:slave10Inputs:di09:contact=CLOSED}. readValueType=bit, readIndex=Optional[9] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.196 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.197 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di10 channels updated: {modbus:data:slave10:slave10Inputs:di10:contact=CLOSED}. readValueType=bit, readIndex=Optional[10] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.198 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.199 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di11 channels updated: {modbus:data:slave10:slave10Inputs:di11:contact=CLOSED}. readValueType=bit, readIndex=Optional[11] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.200 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.201 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di12 channels updated: {modbus:data:slave10:slave10Inputs:di12:contact=CLOSED}. readValueType=bit, readIndex=Optional[12] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.202 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.203 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di13 channels updated: {modbus:data:slave10:slave10Inputs:di13:contact=CLOSED}. readValueType=bit, readIndex=Optional[13] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.204 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.205 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di14 channels updated: {modbus:data:slave10:slave10Inputs:di14:contact=CLOSED}. readValueType=bit, readIndex=Optional[14] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.206 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.207 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave10:slave10Inputs:di15 channels updated: {modbus:data:slave10:slave10Inputs:di15:contact=CLOSED}. readValueType=bit, readIndex=Optional[15] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000000000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@4b038330[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.251 [DEBUG] [handler.ModbusPollerThingHandlerImpl] - Thing modbus:poller:slave11:slave11Inputs received coils BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.253 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.254 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di16 channels updated: {modbus:data:slave11:slave11Inputs:di16:contact=CLOSED}. readValueType=bit, readIndex=Optional[0] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.256 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.258 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di17 channels updated: {modbus:data:slave11:slave11Inputs:di17:contact=CLOSED}. readValueType=bit, readIndex=Optional[1] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.259 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.261 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di18 channels updated: {modbus:data:slave11:slave11Inputs:di18:contact=CLOSED}. readValueType=bit, readIndex=Optional[2] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.262 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.264 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di19 channels updated: {modbus:data:slave11:slave11Inputs:di19:contact=CLOSED}. readValueType=bit, readIndex=Optional[3] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.265 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.266 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di20 channels updated: {modbus:data:slave11:slave11Inputs:di20:contact=CLOSED}. readValueType=bit, readIndex=Optional[4] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.267 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.268 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di21 channels updated: {modbus:data:slave11:slave11Inputs:di21:contact=CLOSED}. readValueType=bit, readIndex=Optional[5] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.268 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.270 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di22 channels updated: {modbus:data:slave11:slave11Inputs:di22:contact=CLOSED}. readValueType=bit, readIndex=Optional[6] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.270 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.272 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di23 channels updated: {modbus:data:slave11:slave11Inputs:di23:contact=CLOSED}. readValueType=bit, readIndex=Optional[7] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

2018-12-26 19:04:28.272 [TRACE] [ernal.handler.ModbusDataThingHandler] - Channel contact will be updated to 'CLOSED' (type OpenClosedType). Input data: number value 0 (value type 'bit' taken into account) and bool value false. Transformation: <identity>

2018-12-26 19:04:28.274 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:slave11:slave11Inputs:di24 channels updated: {modbus:data:slave11:slave11Inputs:di24:contact=CLOSED}. readValueType=bit, readIndex=Optional[8] -> numeric value 0 and boolValue=false. Bits BitArrayWrappingBitVector(bits=0000000001000000) for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@2db705fa[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]

`
And here are my thing configuration’s

Bridge modbus:serial:slave1 [ port="/dev/ttyUSB0" ,id=1 , baud=38400, stopBits="1", parity="none", dataBits=8, encoding="rtu" ]{

Bridge poller slave1coils [ start=0, length=8, refresh=0, 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" ]
        Thing data do06 [ readStart="6", readValueType="bit", writeStart="6", writeValueType="bit", writeType="coil" ]
        Thing data do07 [ readStart="7", readValueType="bit", writeStart="7", writeValueType="bit", writeType="coil" ]

    } 
}     
Bridge modbus:serial:slave2 [ port="/dev/ttyUSB0" ,id=2 , baud=38400, stopBits="1", parity="none", dataBits=8, encoding="rtu" ]{

Bridge poller slave2coils [ start=0, length=8, refresh=0, type="coil" ]{
    
        Thing data do08 [ readStart="0", readValueType="bit", writeStart="0", writeValueType="bit", writeType="coil" ]
        Thing data do09 [ readStart="1", readValueType="bit", writeStart="1", writeValueType="bit", writeType="coil" ]
        Thing data do10 [ readStart="2", readValueType="bit", writeStart="2", writeValueType="bit", writeType="coil" ]
        Thing data do11 [ readStart="3", readValueType="bit", writeStart="3", writeValueType="bit", writeType="coil" ]
        Thing data do12 [ readStart="4", readValueType="bit", writeStart="4", writeValueType="bit", writeType="coil" ]
        Thing data do13 [ readStart="5", readValueType="bit", writeStart="5", writeValueType="bit", writeType="coil" ]
        Thing data do14 [ readStart="6", readValueType="bit", writeStart="6", writeValueType="bit", writeType="coil" ]
        Thing data do15 [ readStart="7", readValueType="bit", writeStart="7", writeValueType="bit", writeType="coil" ]

    } 
} 
Bridge modbus:serial:slave3 [ port="/dev/ttyUSB0" ,id=3 , baud=38400, stopBits="1", parity="none", dataBits=8, encoding="rtu" ]{

Bridge poller slave3coils [ start=0, length=8, refresh=0, type="coil" ]{
    
        Thing data do16 [ readStart="0", readValueType="bit", writeStart="0", writeValueType="bit", writeType="coil" ]
        Thing data do17 [ readStart="1", readValueType="bit", writeStart="1", writeValueType="bit", writeType="coil" ]
        Thing data do18 [ readStart="2", readValueType="bit", writeStart="2", writeValueType="bit", writeType="coil" ]
        Thing data do19 [ readStart="3", readValueType="bit", writeStart="3", writeValueType="bit", writeType="coil" ]
        Thing data do20 [ readStart="4", readValueType="bit", writeStart="4", writeValueType="bit", writeType="coil" ]
        Thing data do21 [ readStart="5", readValueType="bit", writeStart="5", writeValueType="bit", writeType="coil" ]
        Thing data do22 [ readStart="6", readValueType="bit", writeStart="6", writeValueType="bit", writeType="coil" ]
        Thing data do23 [ readStart="7", readValueType="bit", writeStart="7", writeValueType="bit", writeType="coil" ]

    } 
}
Bridge modbus:serial:slave4 [ port="/dev/ttyUSB0" ,id=4 , baud=38400, stopBits="1", parity="none", dataBits=8, encoding="rtu" ]{

Bridge poller slave4coils [ start=0, length=8, refresh=0, type="coil" ]{
    
        Thing data do24 [ readStart="0", readValueType="bit", writeStart="0", writeValueType="bit", writeType="coil" ]
        Thing data do25 [ readStart="1", readValueType="bit", writeStart="1", writeValueType="bit", writeType="coil" ]
        Thing data do26 [ readStart="2", readValueType="bit", writeStart="2", writeValueType="bit", writeType="coil" ]
        Thing data do27 [ readStart="3", readValueType="bit", writeStart="3", writeValueType="bit", writeType="coil" ]
        Thing data do28 [ readStart="4", readValueType="bit", writeStart="4", writeValueType="bit", writeType="coil" ]
        Thing data do29 [ readStart="5", readValueType="bit", writeStart="5", writeValueType="bit", writeType="coil" ]
        Thing data do30 [ readStart="6", readValueType="bit", writeStart="6", writeValueType="bit", writeType="coil" ]
        Thing data do31 [ readStart="7", readValueType="bit", writeStart="7", writeValueType="bit", writeType="coil" ]

    } 
}          
Bridge modbus:serial:slave10 [ port="/dev/ttyUSB0" ,id=10 , baud=38400, stopBits="1", parity="none", dataBits=8, encoding="rtu" ]{ 
   
Bridge poller slave10Inputs [ start=0, length=16, refresh=10, 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" ]
       Thing data di12 [ readStart="12", readValueType="bit" ]
       Thing data di13 [ readStart="13", readValueType="bit" ]
       Thing data di14 [ readStart="14", readValueType="bit" ]
       Thing data di15 [ readStart="15", readValueType="bit" ]
          
    }
}   
Bridge modbus:serial:slave11 [ port="/dev/ttyUSB0" ,id=11 , baud=38400, stopBits="1", parity="none", dataBits=8, encoding="rtu" ]{ 
   
Bridge poller slave11Inputs [ start=0, length=16, refresh=10, type="discrete" ]{ 
    
       Thing data di16 [ readStart="0", readValueType="bit" ]
       Thing data di17 [ readStart="1", readValueType="bit" ]
       Thing data di18 [ readStart="2", readValueType="bit" ]
       Thing data di19 [ readStart="3", readValueType="bit" ]
       Thing data di20 [ readStart="4", readValueType="bit" ]
       Thing data di21 [ readStart="5", readValueType="bit" ]
       Thing data di22 [ readStart="6", readValueType="bit" ]
       Thing data di23 [ readStart="7", readValueType="bit" ]
       Thing data di24 [ readStart="8", readValueType="bit" ]
       Thing data di25 [ readStart="9", readValueType="bit" ]
       Thing data di26 [ readStart="10", readValueType="bit" ]
       Thing data di27 [ readStart="11", readValueType="bit" ]
       Thing data di28 [ readStart="12", readValueType="bit" ]
       Thing data di29 [ readStart="13", readValueType="bit" ]
       Thing data di30 [ readStart="14", readValueType="bit" ]
       Thing data di31 [ readStart="15", readValueType="bit" ]
          
    }
}

And item config

Group Verlichting <verlichting>

 
Switch keuken1 "keuken1" ["Lighting"] { channel="modbus:data:slave1:slave1coils:do00:switch" }
Switch keuken2 "keuken2" ["Lighting"] { channel="modbus:data:slave1:slave1coils:do01:switch" } 
Switch keuken3 "keuken3" ["Lighting"] { channel="modbus:data:slave1:slave1coils:do02:switch" }
Switch living1 "living1" ["Lighting"] { channel="modbus:data:slave1:slave1coils:do03:switch" }
Switch living2 "living2" ["Lighting"] { channel="modbus:data:slave1:slave1coils:do04:switch" }
Switch eetkamer1 "eetkamer1" ["Lighting"] { channel="modbus:data:slave1:slave1coils:do05:switch" }
Switch eetkamer2 "eetkamer2" ["Lighting"] { channel="modbus:data:slave1:slave1coils:do06:switch" }
Switch livingwand "livingwand" ["Lighting"] { channel="modbus:data:slave1:slave1coils:do07:switch" }

Switch bureau "bureau" ["Lighting"] { channel="modbus:data:slave2:slave2coils:do08:switch" }
Switch inkomhal "inkomhal" ["Lighting"] { channel="modbus:data:slave2:slave2coils:do09:switch" }
Switch wasplaats "wasplaats" ["Lighting"] { channel="modbus:data:slave2:slave2coils:do10:switch" }
Switch voordeur "voordeur" ["Lighting"] { channel="modbus:data:slave2:slave2coils:do11:switch" }
Switch garage "garage" ["Lighting"] { channel="modbus:data:slave2:slave2coils:do12:switch" }
Switch douche "douche" ["Lighting"] { channel="modbus:data:slave2:slave2coils:do13:switch" }
Switch kelder "kelder" ["Lighting"] { channel="modbus:data:slave2:slave2coils:do14:switch" }
Switch voor "voor" ["Lighting"] { channel="modbus:data:slave2:slave2coils:do15:switch" }

Switch zijkant "zijkant" ["Lighting"] { channel="modbus:data:slave3:slave3coils:do16:switch" }
Switch achter "achter" ["Lighting"] { channel="modbus:data:slave3:slave3coils:do17:switch" }
Switch hal "hal"  ["Lighting"] { channel="modbus:data:slave3:slave3coils:do18:switch" }
Switch orientatie "orientatie" ["Lighting"] { channel="modbus:data:slave3:slave3coils:do19:switch" }
Switch masterbedroom "masterbedroom" ["Lighting"] { channel="modbus:data:slave3:slave3coils:do20:switch" }
Switch badkamer "badkamer" ["Lighting"] { channel="modbus:data:slave3:slave3coils:do21:switch" }

Switch open1 "open1" { channel="modbus:data:slave4:slave4coils:do22:switch" }
Switch open2 "open2" { channel="modbus:data:slave4:slave4coils:do23:switch" }
Switch open3 "open3" { channel="modbus:data:slave4:slave4coils:do24:switch" }
Switch open4 "open4" { channel="modbus:data:slave4:slave4coils:do25:switch" }
Switch open5 "open5" { channel="modbus:data:slave4:slave4coils:do26:switch" }
Switch open6 "open6" { channel="modbus:data:slave4:slave4coils:do27:switch" }
Switch open7 "open7" { channel="modbus:data:slave4:slave4coils:do28:switch" }
Switch open8 "open8" { channel="modbus:data:slave4:slave4coils:do29:switch" }
Switch open9 "open9" { channel="modbus:data:slave4:slave4coils:do30:switch" }
Switch open10 "open10" { channel="modbus:data:slave4:slave4coils:do31:switch" }

Group Verlichtinginputs <verlichting>


Contact verlichting1 "verlichting1[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di00:contact" }
Contact verlichting2 "verlichting2[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di01:contact" }
Contact verlichting3 "verlichting3[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di02:contact" }
Contact verlichting4 "verlichting4[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di03:contact" }
Contact verlichting5 "verlichting5[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di04:contact" }
Contact verlichting6 "verlichting6[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di07:contact" }
Contact verlichting7 "verlichting7[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di05:contact" }
Contact verlichting8 "verlichting8[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di06:contact" }
Contact verlichting9  "verlichting9[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di08:contact" }
Contact verlichting10 "verlichting10[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di09:contact" }
Contact verlichting11 "verlichting11[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di10:contact" }
Contact verlichting12 "verlichting12[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di11:contact" }
Contact verlichting13 "verlichting13[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di12:contact" }
Contact verlichting14 "verlichting14[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di13:contact" }
Contact verlichting15 "verlichting15[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di14:contact" }
Contact verlichting16 "verlichting16[MAP(en.map):%s]"  { channel="modbus:data:slave10:slave10Inputs:di15:contact" }

Contact verlichting17 "verlichting17[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di16:contact" }
Contact verlichting18 "verlichting18[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di17:contact" }
Contact verlichting19 "verlichting19[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di18:contact" }
Contact verlichting20 "verlichting20[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di19:contact" }
Contact verlichting21 "verlichting21[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di20:contact" }
Contact verlichting22 "verlichting22[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di21:contact" }
Contact verlichting23 "verlichting23[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di22:contact" }
Contact verlichting24 "verlichting24[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di23:contact" }
Contact verlichting25 "verlichting25[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di24:contact" }
Contact verlichting26 "verlichting26[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di25:contact" }
Contact verlichting27 "verlichting27[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di26:contact" }
Contact verlichting28 "verlichting28[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di27:contact" }
Contact verlichting29 "verlichting29[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di28:contact" }
Contact verlichting30 "verlichting30[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di29:contact" }
Contact verlichting31 "verlichting31[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di31:contact" }
Contact verlichting32 "verlichting32[MAP(en.map):%s]"  { channel="modbus:data:slave11:slave11Inputs:di32:contact" }


Switch verlichting1dummy "[%s]"
Switch verlichting2dummy "[%s]"
Switch verlichting3dummy "[%s]"
Switch verlichting4dummy "[%s]"
Switch verlichting5dummy "[%s]"
Switch verlichting6dummy "[%s]"
Switch verlichting7dummy "[%s]"
Switch verlichting8dummy "[%s]"
Switch verlichting9dummy "[%s]"
Switch verlichting10dummy "[%s]"
Switch verlichting11dummy "[%s]"
Switch verlichting12dummy "[%s]"
Switch verlichting13dummy "[%s]"
Switch verlichting14dummy "[%s]"
Switch verlichting15dummy "[%s]"
Switch verlichting16dummy "[%s]"

Switch verlichting17dummy "[%s]"
Switch verlichting18dummy "[%s]"
Switch verlichting19dummy "[%s]"
Switch verlichting20dummy "[%s]"
Switch verlichting21dummy "[%s]"
Switch verlichting22dummy "[%s]"
Switch verlichting23dummy "[%s]"
Switch verlichting24dummy "[%s]"
Switch verlichting25dummy "[%s]"
Switch verlichting26dummy "[%s]"
Switch verlichting27dummy "[%s]"
Switch verlichting28dummy "[%s]"
Switch verlichting29dummy "[%s]"
Switch verlichting30dummy "[%s]"
Switch verlichting31dummy "[%s]"
Switch verlichting32dummy "[%s]"

ssalonen · December 26, 2018, 6:19pm

Thanks! The logs are still missing relevant lines. Are you sure you have configured the transport bundle logging as well?

Rado1 · December 26, 2018, 6:25pm

Oh sorry mist that one here it is.

2018-12-26 19:24:07.095 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (10ms) poll task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097]. Current millis: 1545848647095

2018-12-26 19:24:07.096 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097]. Trying to get connection [operation ID 0490df27-132d-4835-80c1-55378e7123c1]

2018-12-26 19:24:07.096 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 1 [operation ID 0490df27-132d-4835-80c1-55378e7123c1]

2018-12-26 19:24:07.117 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 34ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0], to ensure delay between transactions.

2018-12-26 19:24:07.118 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0]]) for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0] took 83 ms

2018-12-26 19:24:07.118 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7] (oneOff=false)! Connection received in 83 ms [operation ID 024958b9-98e0-49de-97b4-b0110c9c300e]

2018-12-26 19:24:07.119 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7]. Got a connection successfully [operation ID 024958b9-98e0-49de-97b4-b0110c9c300e]

2018-12-26 19:24:07.119 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 024958b9-98e0-49de-97b4-b0110c9c300e]

2018-12-26 19:24:07.119 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 024958b9-98e0-49de-97b4-b0110c9c300e]

2018-12-26 19:24:07.120 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID 024958b9-98e0-49de-97b4-b0110c9c300e]

2018-12-26 19:24:07.120 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_INPUT_DISCRETES): 00 00 00 00 00 06 0b 02 00 00 00 10  [operation ID 024958b9-98e0-49de-97b4-b0110c9c300e]

2018-12-26 19:24:07.137 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=2, transaction ID=0): 0b 02 02 00 02  [operation ID 024958b9-98e0-49de-97b4-b0110c9c300e]

2018-12-26 19:24:07.137 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]. Response was net.wimpi.modbus.msg.ReadInputDiscretesResponse@51c9c601

2018-12-26 19:24:07.141 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]. Response was net.wimpi.modbus.msg.ReadInputDiscretesResponse@51c9c601

2018-12-26 19:24:07.142 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0] connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] -> true

2018-12-26 19:24:07.142 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0]...

2018-12-26 19:24:07.143 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] (endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0]) age (265592ms) is below the reconnectAfterMillis (-1ms) limit and connection time (1545848381551) is after the "disconnectBeforeConnectedMillis"=-1. Keep the connection open.

2018-12-26 19:24:07.143 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0]

2018-12-26 19:24:07.144 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0]

2018-12-26 19:24:07.144 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0] took 2 ms

2018-12-26 19:24:07.144 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID 024958b9-98e0-49de-97b4-b0110c9c300e]

2018-12-26 19:24:07.145 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 110 ms, connection: 85, transaction=17, callback=5} [operation ID 024958b9-98e0-49de-97b4-b0110c9c300e]

2018-12-26 19:24:07.145 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (10ms) poll task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7] finished at 1545848647145. Was started at millis: 1545848647034 (=duration of 111 millis)

2018-12-26 19:24:07.155 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (10ms) poll task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7]. Current millis: 1545848647155

2018-12-26 19:24:07.156 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7]. Trying to get connection [operation ID 412fbcf7-5404-4e5d-8749-c096261cb663]

2018-12-26 19:24:07.156 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 1 [operation ID 412fbcf7-5404-4e5d-8749-c096261cb663]

2018-12-26 19:24:07.178 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 34ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0], to ensure delay between transactions.

2018-12-26 19:24:07.179 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0]]) for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0] took 83 ms

2018-12-26 19:24:07.179 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097] (oneOff=false)! Connection received in 83 ms [operation ID 0490df27-132d-4835-80c1-55378e7123c1]

2018-12-26 19:24:07.179 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097]. Got a connection successfully [operation ID 0490df27-132d-4835-80c1-55378e7123c1]

2018-12-26 19:24:07.180 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 0490df27-132d-4835-80c1-55378e7123c1]

2018-12-26 19:24:07.180 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 0490df27-132d-4835-80c1-55378e7123c1]

2018-12-26 19:24:07.180 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID 0490df27-132d-4835-80c1-55378e7123c1]

2018-12-26 19:24:07.181 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_INPUT_DISCRETES): 00 00 00 00 00 06 0a 02 00 00 00 10  [operation ID 0490df27-132d-4835-80c1-55378e7123c1]

2018-12-26 19:24:07.201 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=2, transaction ID=0): 0a 02 02 00 00  [operation ID 0490df27-132d-4835-80c1-55378e7123c1]

2018-12-26 19:24:07.202 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]. Response was net.wimpi.modbus.msg.ReadInputDiscretesResponse@51047556

2018-12-26 19:24:07.207 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]. Response was net.wimpi.modbus.msg.ReadInputDiscretesResponse@51047556

2018-12-26 19:24:07.208 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0] connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] -> true

2018-12-26 19:24:07.208 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0]...

2018-12-26 19:24:07.209 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] (endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0]) age (265658ms) is below the reconnectAfterMillis (-1ms) limit and connection time (1545848381551) is after the "disconnectBeforeConnectedMillis"=-1. Keep the connection open.

2018-12-26 19:24:07.209 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0]

2018-12-26 19:24:07.209 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0]

2018-12-26 19:24:07.210 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0] took 2 ms

2018-12-26 19:24:07.210 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID 0490df27-132d-4835-80c1-55378e7123c1]

2018-12-26 19:24:07.210 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 114 ms, connection: 85, transaction=20, callback=7} [operation ID 0490df27-132d-4835-80c1-55378e7123c1]

2018-12-26 19:24:07.211 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (10ms) poll task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097] finished at 1545848647211. Was started at millis: 1545848647095 (=duration of 116 millis)

2018-12-26 19:24:07.221 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (10ms) poll task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097]. Current millis: 1545848647221

2018-12-26 19:24:07.222 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097]. Trying to get connection [operation ID 8c3a0fa3-9e44-4a8f-8be0-f4b066837a7e]

2018-12-26 19:24:07.222 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 1 [operation ID 8c3a0fa3-9e44-4a8f-8be0-f4b066837a7e]

2018-12-26 19:24:07.245 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 35ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0], to ensure delay between transactions.

2018-12-26 19:24:07.245 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0]]) for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0] took 88 ms

2018-12-26 19:24:07.246 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7] (oneOff=false)! Connection received in 89 ms [operation ID 412fbcf7-5404-4e5d-8749-c096261cb663]

2018-12-26 19:24:07.246 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7]. Got a connection successfully [operation ID 412fbcf7-5404-4e5d-8749-c096261cb663]

2018-12-26 19:24:07.246 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 412fbcf7-5404-4e5d-8749-c096261cb663]

2018-12-26 19:24:07.247 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 412fbcf7-5404-4e5d-8749-c096261cb663]

2018-12-26 19:24:07.247 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID 412fbcf7-5404-4e5d-8749-c096261cb663]

2018-12-26 19:24:07.247 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_INPUT_DISCRETES): 00 00 00 00 00 06 0b 02 00 00 00 10  [operation ID 412fbcf7-5404-4e5d-8749-c096261cb663]

2018-12-26 19:24:07.265 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=2, transaction ID=0): 0b 02 02 00 02  [operation ID 412fbcf7-5404-4e5d-8749-c096261cb663]

2018-12-26 19:24:07.265 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]. Response was net.wimpi.modbus.msg.ReadInputDiscretesResponse@62c617e3

2018-12-26 19:24:07.276 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]. Response was net.wimpi.modbus.msg.ReadInputDiscretesResponse@62c617e3

2018-12-26 19:24:07.277 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0] connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] -> true

2018-12-26 19:24:07.277 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0]...

2018-12-26 19:24:07.278 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] (endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0]) age (265727ms) is below the reconnectAfterMillis (-1ms) limit and connection time (1545848381551) is after the "disconnectBeforeConnectedMillis"=-1. Keep the connection open.

2018-12-26 19:24:07.278 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0]

2018-12-26 19:24:07.278 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0]

2018-12-26 19:24:07.278 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0] took 1 ms

2018-12-26 19:24:07.279 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID 412fbcf7-5404-4e5d-8749-c096261cb663]

2018-12-26 19:24:07.279 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 123 ms, connection: 91, transaction=17, callback=12} [operation ID 412fbcf7-5404-4e5d-8749-c096261cb663]

2018-12-26 19:24:07.279 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (10ms) poll task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7] finished at 1545848647279. Was started at millis: 1545848647155 (=duration of 124 millis)

2018-12-26 19:24:07.291 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (10ms) poll task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7]. Current millis: 1545848647290

2018-12-26 19:24:07.291 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7]. Trying to get connection [operation ID 97c660f2-dc9a-48eb-9001-3bf242795436]

2018-12-26 19:24:07.292 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 1 [operation ID 97c660f2-dc9a-48eb-9001-3bf242795436]

2018-12-26 19:24:07.314 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 35ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0], to ensure delay between transactions.

2018-12-26 19:24:07.314 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0]]) for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0] took 91 ms

2018-12-26 19:24:07.315 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097] (oneOff=false)! Connection received in 92 ms [operation ID 8c3a0fa3-9e44-4a8f-8be0-f4b066837a7e]

2018-12-26 19:24:07.315 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097]. Got a connection successfully [operation ID 8c3a0fa3-9e44-4a8f-8be0-f4b066837a7e]

2018-12-26 19:24:07.316 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 8c3a0fa3-9e44-4a8f-8be0-f4b066837a7e]

2018-12-26 19:24:07.316 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 8c3a0fa3-9e44-4a8f-8be0-f4b066837a7e]

2018-12-26 19:24:07.316 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID 8c3a0fa3-9e44-4a8f-8be0-f4b066837a7e]

2018-12-26 19:24:07.317 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_INPUT_DISCRETES): 00 00 00 00 00 06 0a 02 00 00 00 10  [operation ID 8c3a0fa3-9e44-4a8f-8be0-f4b066837a7e]

2018-12-26 19:24:07.329 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=2, transaction ID=0): 0a 02 02 00 00  [operation ID 8c3a0fa3-9e44-4a8f-8be0-f4b066837a7e]

2018-12-26 19:24:07.330 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]. Response was net.wimpi.modbus.msg.ReadInputDiscretesResponse@40e8ab38

2018-12-26 19:24:07.337 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]. Response was net.wimpi.modbus.msg.ReadInputDiscretesResponse@40e8ab38

2018-12-26 19:24:07.338 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0] connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] -> true

2018-12-26 19:24:07.339 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0]...

2018-12-26 19:24:07.339 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] (endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0]) age (265788ms) is below the reconnectAfterMillis (-1ms) limit and connection time (1545848381551) is after the "disconnectBeforeConnectedMillis"=-1. Keep the connection open.

2018-12-26 19:24:07.340 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0]

2018-12-26 19:24:07.341 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0]

2018-12-26 19:24:07.341 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0] took 3 ms

2018-12-26 19:24:07.341 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID 8c3a0fa3-9e44-4a8f-8be0-f4b066837a7e]

2018-12-26 19:24:07.342 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 120 ms, connection: 95, transaction=11, callback=8} [operation ID 8c3a0fa3-9e44-4a8f-8be0-f4b066837a7e]

2018-12-26 19:24:07.343 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (10ms) poll task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097] finished at 1545848647342. Was started at millis: 1545848647221 (=duration of 121 millis)

2018-12-26 19:24:07.353 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (10ms) poll task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097]. Current millis: 1545848647353

2018-12-26 19:24:07.354 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097]. Trying to get connection [operation ID 9dfb92fb-55f9-4f77-9d82-7f16f0eded5d]

2018-12-26 19:24:07.354 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 1 [operation ID 9dfb92fb-55f9-4f77-9d82-7f16f0eded5d]

2018-12-26 19:24:07.375 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 34ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0], to ensure delay between transactions.

2018-12-26 19:24:07.376 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0]]) for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0] took 83 ms

2018-12-26 19:24:07.376 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7] (oneOff=false)! Connection received in 84 ms [operation ID 97c660f2-dc9a-48eb-9001-3bf242795436]

2018-12-26 19:24:07.376 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7]. Got a connection successfully [operation ID 97c660f2-dc9a-48eb-9001-3bf242795436]

2018-12-26 19:24:07.377 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 97c660f2-dc9a-48eb-9001-3bf242795436]

2018-12-26 19:24:07.377 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 97c660f2-dc9a-48eb-9001-3bf242795436]

2018-12-26 19:24:07.377 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID 97c660f2-dc9a-48eb-9001-3bf242795436]

2018-12-26 19:24:07.378 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_INPUT_DISCRETES): 00 00 00 00 00 06 0b 02 00 00 00 10  [operation ID 97c660f2-dc9a-48eb-9001-3bf242795436]

2018-12-26 19:24:07.394 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=2, transaction ID=0): 0b 02 02 00 02  [operation ID 97c660f2-dc9a-48eb-9001-3bf242795436]

2018-12-26 19:24:07.394 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]. Response was net.wimpi.modbus.msg.ReadInputDiscretesResponse@623b7498

2018-12-26 19:24:07.401 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]. Response was net.wimpi.modbus.msg.ReadInputDiscretesResponse@623b7498

2018-12-26 19:24:07.404 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0] connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] -> true

2018-12-26 19:24:07.406 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0]...

2018-12-26 19:24:07.407 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] (endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0]) age (265855ms) is below the reconnectAfterMillis (-1ms) limit and connection time (1545848381551) is after the "disconnectBeforeConnectedMillis"=-1. Keep the connection open.

2018-12-26 19:24:07.407 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0]

2018-12-26 19:24:07.407 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0]

2018-12-26 19:24:07.408 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0] took 4 ms

2018-12-26 19:24:07.408 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID 97c660f2-dc9a-48eb-9001-3bf242795436]

2018-12-26 19:24:07.408 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 117 ms, connection: 88, transaction=16, callback=10} [operation ID 97c660f2-dc9a-48eb-9001-3bf242795436]

2018-12-26 19:24:07.409 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (10ms) poll task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7] finished at 1545848647409. Was started at millis: 1545848647290 (=duration of 119 millis)

2018-12-26 19:24:07.419 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (10ms) poll task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7]. Current millis: 1545848647419

2018-12-26 19:24:07.420 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7]. Trying to get connection [operation ID 75c5bb5b-ec38-4655-bbff-6bcb70bb1980]

2018-12-26 19:24:07.420 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@4211324a[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@713b46c[slaveId=11,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@b831abf7] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 1 [operation ID 75c5bb5b-ec38-4655-bbff-6bcb70bb1980]

2018-12-26 19:24:07.442 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 34ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0], to ensure delay between transactions.

2018-12-26 19:24:07.442 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0]]) for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0] took 87 ms

2018-12-26 19:24:07.443 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097] (oneOff=false)! Connection received in 88 ms [operation ID 9dfb92fb-55f9-4f77-9d82-7f16f0eded5d]

2018-12-26 19:24:07.445 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097]. Got a connection successfully [operation ID 9dfb92fb-55f9-4f77-9d82-7f16f0eded5d]

2018-12-26 19:24:07.446 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 9dfb92fb-55f9-4f77-9d82-7f16f0eded5d]

2018-12-26 19:24:07.447 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 9dfb92fb-55f9-4f77-9d82-7f16f0eded5d]

2018-12-26 19:24:07.447 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID 9dfb92fb-55f9-4f77-9d82-7f16f0eded5d]

2018-12-26 19:24:07.448 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_INPUT_DISCRETES): 00 00 00 00 00 06 0a 02 00 00 00 10  [operation ID 9dfb92fb-55f9-4f77-9d82-7f16f0eded5d]

2018-12-26 19:24:07.457 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=2, transaction ID=0): 0a 02 02 00 00  [operation ID 9dfb92fb-55f9-4f77-9d82-7f16f0eded5d]

2018-12-26 19:24:07.458 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]. Response was net.wimpi.modbus.msg.ReadInputDiscretesResponse@4a5b8d0

2018-12-26 19:24:07.462 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097 for request ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3]. Response was net.wimpi.modbus.msg.ReadInputDiscretesResponse@4a5b8d0

2018-12-26 19:24:07.463 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0] connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] -> true

2018-12-26 19:24:07.464 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0]...

2018-12-26 19:24:07.464 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] (endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0]) age (265913ms) is below the reconnectAfterMillis (-1ms) limit and connection time (1545848381551) is after the "disconnectBeforeConnectedMillis"=-1. Keep the connection open.

2018-12-26 19:24:07.465 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0]

2018-12-26 19:24:07.465 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0]

2018-12-26 19:24:07.466 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0] took 3 ms

2018-12-26 19:24:07.466 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID 9dfb92fb-55f9-4f77-9d82-7f16f0eded5d]

2018-12-26 19:24:07.466 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 112 ms, connection: 91, transaction=8, callback=5} [operation ID 9dfb92fb-55f9-4f77-9d82-7f16f0eded5d]

2018-12-26 19:24:07.467 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (10ms) poll task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097] finished at 1545848647467. Was started at millis: 1545848647353 (=duration of 114 millis)

2018-12-26 19:24:07.477 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (10ms) poll task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097]. Current millis: 1545848647477

2018-12-26 19:24:07.478 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097]. Trying to get connection [operation ID 1ab57849-d025-4d1a-9efe-703050d1a8ab]

2018-12-26 19:24:07.478 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTaskImpl@5010bae[request=ModbusPollerThingHandlerImpl.ModbusPollerReadRequest@1eb928ea[slaveId=10,functionCode=READ_INPUT_DISCRETES,start=0,length=16,maxTries=3],endpoint=ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0],callback=org.openhab.binding.modbus.internal.handler.ModbusPollerThingHandlerImpl$ReadCallbackDelegator@834b7097] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 1 [operation ID 1ab57849-d025-4d1a-9efe-703050d1a8ab]

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

2018-12-26 19:24:07.480 [vent.ItemStateChangedEvent] - HeatPump_Temperature_6 changed from 49.2 to 49.0

2018-12-26 19:24:07.491 [vent.ItemStateChangedEvent] - HeatPump_Hours_Compressor1 changed from 18643:54:50 to 18643:54:56

2018-12-26 19:24:07.492 [vent.ItemStateChangedEvent] - HeatPump_Hours_Heatpump changed from 18642:05:44 to 18642:05:50

Rado1 · December 26, 2018, 6:38pm

Here are the logs from the modbus binding and the transport bundle together.F9EjmZ3s.txt (54.4 KB)
I hope you can see something in them?

rossko57 · December 26, 2018, 7:20pm

10mS is quite an ambitious polling rate.

Pe_Man · December 26, 2018, 8:40pm

Hi @ssalonen,

I have tried some. I am not 100% comfortable with the karaf console etc, but I think I have gathered the data you asked for. In case something is missing, let me know and I do it for you.

First, I upgraded to latest snapshot today. checking the version like this:

openhab> bundle:list | grep -i modbus
214 x Active   x  80 x 2.5.0.201812250308     x Modbus Binding
221 x Active   x  80 x 2.5.0.201812242048     x openHAB MODBUS Transport Bundle

Second I set the the loglevel like this:

openhab> log:set TRACE  org.openhab.binding.modbus

I changed a light (Sovrum_4__Kontor__Ljusfunktion_Tak_Status) from the sitemap, it took appr 10 seconds before it switched IRL.

This is a clip from the log-viewer: https://pastebin.com/z2eSQTVc

Things: modbus.things - Pastebin.com
Items: modbus.items - Pastebin.com

rossko57 · December 26, 2018, 10:12pm

I would at least try with all polling extended to 100 or 200mS, give your write command a chance to get in the modbus queue.

EDIT - muddled up messages, but this advice should still be sensible for @Rado1

ssalonen · December 27, 2018, 8:58am

@Pe_Man could you please adjust the logging as described in the docs: https://www.openhab.org/addons/bindings/modbus/#enable-verbose-logging

I think we are missing the transport level logging.

Sami

ssalonen · December 27, 2018, 9:16am

Thanks @Rado1, now the logging is correctly configured.

I can see that one round of polling takes around 120 ms:

$ grep timing /tmp/rado1logs
2018-12-26 19:34:00.114 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 131 ms, connection: 103, transaction=12, callback=6} [operation ID 5075f19c-8d93-4406-9767-83bc88486505]
2018-12-26 19:34:00.178 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 117 ms, connection: 88, transaction=11, callback=7} [operation ID 9cfe136d-64f2-492a-9016-0591fd2a6139]
2018-12-26 19:34:00.242 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 115 ms, connection: 88, transaction=12, callback=7} [operation ID 676c6ec8-8e5a-4d53-96c4-381d9408b088]
2018-12-26 19:34:00.306 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 115 ms, connection: 86, transaction=12, callback=9} [operation ID b03de9ba-0686-46d6-aa11-aabdc9d1d364]
2018-12-26 19:34:00.369 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 114 ms, connection: 88, transaction=10, callback=7} [operation ID 1e2e50d0-0adc-4956-8b1b-4cea8293452e]
2018-12-26 19:34:00.431 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 112 ms, connection: 85, transaction=13, callback=6} [operation ID 67bbd000-4bf9-461b-bf0a-d3bf8763a4e6]
2018-12-26 19:34:00.496 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 114 ms, connection: 87, transaction=13, callback=5} [operation ID 50747201-db03-45ef-888d-95d6bce5e313]

Most of the time goes to connection related things (see above). One reason might be that poll period is 10 ms but default period between transactions is 35 ms. We can see that binding is artificially waiting between polls to ensure the silent period.

$ grep Waited /tmp/rado1logs
2018-12-26 19:34:00.143 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 32ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0], to ensure delay between transactions.
2018-12-26 19:34:00.208 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 33ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0], to ensure delay between transactions.
2018-12-26 19:34:00.272 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 33ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0], to ensure delay between transactions.
2018-12-26 19:34:00.337 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 33ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0], to ensure delay between transactions.
2018-12-26 19:34:00.400 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 33ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0], to ensure delay between transactions.
2018-12-26 19:34:00.462 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 33ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0], to ensure delay between transactions.
2018-12-26 19:34:00.527 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 33ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0], to ensure delay between transactions.

It’s quite interesting that you see high CPU consumption… After all, you just have two pollers (that are automatically refreshed), not 100+ as discussed this thread.

UPDATE: please note that the logging increases CPU usage quite heavily. Tune down the logging to increase performance.

Would you please share the modbus1 configuration you had? Also, could you repeat the log collection for a longer time span, say 30 seconds – I would then see the queue statistics.

Best,
Sami

Pe_Man · December 27, 2018, 10:03am

I use 1000ms for read/write registers and 10000ms for read only. You probably meant to quote Rado1?

Pe_Man · December 27, 2018, 10:25am

ok, sorry for the inconvenience.

Same test today, but with loggings correctly set.

2018-12-27 11:06:32.854 [ome.event.ItemCommandEvent] - Item 'Sovrum_4__Kontor__Ljusfunktion_Tak_Status' received command ON
2018-12-27 11:06:32.869 [nt.ItemStatePredictedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status predicted to become ON
2018-12-27 11:06:32.874 [vent.ItemStateChangedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status changed from OFF to ON
2018-12-27 11:06:34.486 [vent.ItemStateChangedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status changed from ON to OFF
2018-12-27 11:06:48.110 [vent.ItemStateChangedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status changed from OFF to ON

I put the extract of the openhab.log here: https://www.dropbox.com/s/j307w03z9fp7y6e/openhab.log%20(modbus-debug)?dl=0

It was to large for pastebin…

ssalonen · December 27, 2018, 11:24am

Thanks @Pe_Man

I can see that majority of the time goes to connections:

$ grep timing peman.log
2018-12-27 11:06:32.802 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 555 ms, connection: 480, transaction=7, callback=21} [operation ID 1954a600-2a42-44fd-b42a-797da1ec58c8]
2018-12-27 11:06:32.914 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 546 ms, connection: 492, transaction=13, callback=14} [operation ID 6c2d7d70-585b-430e-aae6-60928ae29458]
2018-12-27 11:06:33.019 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 560 ms, connection: 512, transaction=20, callback=11} [operation ID 8e3b10f0-634b-4044-9aba-6c4caf1a98fc]
2018-12-27 11:06:33.107 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 531 ms, connection: 502, transaction=7, callback=10} [operation ID 4e931edf-fad8-4d63-9311-cf91358ceb94]
2018-12-27 11:06:33.209 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 531 ms, connection: 493, transaction=18, callback=9} [operation ID e0d5cdff-314e-4d31-b9f8-63b1cd00f54d]
2018-12-27 11:06:33.336 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 528 ms, connection: 465, transaction=34, callback=10} [operation ID d45e3e18-e915-4290-b854-96fbe1f95bb1]

(for reference, explanation of the different categories:

connection: time spent waiting for the turn to get the connection (has to wait other requests to complete), establishing the connection, disconnecting connection
transaction: actual modbus protocol level I/O
callback: time spent “processing” the received data and updating channels and items

)

I think this might be because there are so many pollers competing for time with the slave. Anyways, it might be a good idea to keep the connection open (see reconnectAfterMillis parameter).

You can also see from above that it takes ~550 ms to complete one transaction, which translates to 73 seconds to poll all the 133 slaves!

There 133 pollers which shows up in queue size (130 requests queued). In other words, the queue is full of poll tasks. (queue size used to increase without limit in cases like this before – now it’s contained which is good)

# Sorting queue by poll start
$ grep 'POLL MONITOR:' peman.log|sort --general-numeric-sort --key=14|cut -d' ' -f12-14
READ_MULTIPLE_REGISTERS, start 0,
READ_MULTIPLE_REGISTERS, start 38,
READ_MULTIPLE_REGISTERS, start 76,
READ_MULTIPLE_REGISTERS, start 114,
READ_MULTIPLE_REGISTERS, start 141,
READ_INPUT_REGISTERS, start 162,
READ_MULTIPLE_REGISTERS, start 176,
READ_MULTIPLE_REGISTERS, start 272,
READ_MULTIPLE_REGISTERS, start 349,
READ_MULTIPLE_REGISTERS, start 487,
READ_MULTIPLE_REGISTERS, start 525,
READ_MULTIPLE_REGISTERS, start 587,
READ_MULTIPLE_REGISTERS, start 625,
READ_MULTIPLE_REGISTERS, start 663,
READ_MULTIPLE_REGISTERS, start 701,
READ_MULTIPLE_REGISTERS, start 739,
READ_MULTIPLE_REGISTERS, start 777,
READ_INPUT_REGISTERS, start 808,
READ_MULTIPLE_REGISTERS, start 842,
READ_MULTIPLE_REGISTERS, start 880,
READ_MULTIPLE_REGISTERS, start 918,
READ_MULTIPLE_REGISTERS, start 983,
READ_MULTIPLE_REGISTERS, start 1079,
READ_MULTIPLE_REGISTERS, start 1209,
READ_MULTIPLE_REGISTERS, start 1247,
READ_MULTIPLE_REGISTERS, start 1285,
READ_MULTIPLE_REGISTERS, start 1323,
READ_MULTIPLE_REGISTERS, start 1361,
READ_MULTIPLE_REGISTERS, start 1399,
READ_MULTIPLE_REGISTERS, start 1437,
READ_MULTIPLE_REGISTERS, start 1475,
READ_MULTIPLE_REGISTERS, start 1552,
READ_MULTIPLE_REGISTERS, start 1590,
READ_MULTIPLE_REGISTERS, start 1628,
READ_MULTIPLE_REGISTERS, start 1666,
READ_MULTIPLE_REGISTERS, start 1704,
READ_MULTIPLE_REGISTERS, start 1742,
READ_MULTIPLE_REGISTERS, start 1780,
READ_MULTIPLE_REGISTERS, start 1818,
READ_MULTIPLE_REGISTERS, start 1856,
READ_MULTIPLE_REGISTERS, start 1894,
READ_MULTIPLE_REGISTERS, start 1932,
READ_MULTIPLE_REGISTERS, start 1970,
READ_MULTIPLE_REGISTERS, start 2042,
READ_INPUT_REGISTERS, start 2089,
READ_MULTIPLE_REGISTERS, start 2135,
READ_INPUT_REGISTERS, start 2169,
READ_INPUT_REGISTERS, start 2249,
READ_MULTIPLE_REGISTERS, start 2254,
READ_INPUT_REGISTERS, start 2329,
READ_MULTIPLE_REGISTERS, start 2567,
READ_MULTIPLE_REGISTERS, start 2663,
READ_INPUT_REGISTERS, start 2702,
READ_MULTIPLE_REGISTERS, start 2759,
READ_MULTIPLE_REGISTERS, start 2855,
READ_MULTIPLE_REGISTERS, start 2975,
READ_MULTIPLE_REGISTERS, start 3052,
READ_MULTIPLE_REGISTERS, start 3129,
READ_MULTIPLE_REGISTERS, start 3291,
READ_MULTIPLE_REGISTERS, start 3318,
READ_MULTIPLE_REGISTERS, start 3356,
READ_INPUT_REGISTERS, start 3356,
READ_INPUT_REGISTERS, start 3436,
READ_MULTIPLE_REGISTERS, start 3466,
READ_MULTIPLE_REGISTERS, start 3504,
READ_INPUT_REGISTERS, start 3950,
READ_MULTIPLE_REGISTERS, start 4005,
READ_MULTIPLE_REGISTERS, start 4043,
READ_MULTIPLE_REGISTERS, start 4097,
READ_MULTIPLE_REGISTERS, start 4234,
READ_MULTIPLE_REGISTERS, start 4330,
READ_INPUT_REGISTERS, start 4850,
READ_INPUT_REGISTERS, start 4955,
READ_MULTIPLE_REGISTERS, start 5088,
READ_MULTIPLE_REGISTERS, start 5285,
READ_MULTIPLE_REGISTERS, start 5362,
READ_MULTIPLE_REGISTERS, start 5439,
READ_MULTIPLE_REGISTERS, start 5516,
READ_MULTIPLE_REGISTERS, start 5593,
READ_MULTIPLE_REGISTERS, start 5757,
READ_MULTIPLE_REGISTERS, start 5898,
READ_MULTIPLE_REGISTERS, start 5936,
READ_MULTIPLE_REGISTERS, start 5974,
READ_MULTIPLE_REGISTERS, start 6012,
READ_MULTIPLE_REGISTERS, start 6131,
READ_MULTIPLE_REGISTERS, start 6208,
READ_MULTIPLE_REGISTERS, start 6246,
READ_MULTIPLE_REGISTERS, start 6307,
READ_MULTIPLE_REGISTERS, start 6345,
READ_MULTIPLE_REGISTERS, start 6468,
READ_INPUT_REGISTERS, start 7427,
READ_MULTIPLE_REGISTERS, start 10202,
READ_MULTIPLE_REGISTERS, start 10387,
READ_MULTIPLE_REGISTERS, start 10478,
READ_MULTIPLE_REGISTERS, start 11223,
READ_MULTIPLE_REGISTERS, start 11301,
READ_MULTIPLE_REGISTERS, start 11339,
READ_MULTIPLE_REGISTERS, start 11377,
READ_MULTIPLE_REGISTERS, start 11415,
READ_MULTIPLE_REGISTERS, start 11453,
READ_MULTIPLE_REGISTERS, start 11491,
READ_MULTIPLE_REGISTERS, start 11572,
READ_MULTIPLE_REGISTERS, start 11649,
READ_MULTIPLE_REGISTERS, start 11687,
READ_MULTIPLE_REGISTERS, start 11725,
READ_MULTIPLE_REGISTERS, start 11763,
READ_MULTIPLE_REGISTERS, start 12013,
READ_MULTIPLE_REGISTERS, start 12051,
READ_MULTIPLE_REGISTERS, start 12089,
READ_MULTIPLE_REGISTERS, start 12127,
READ_INPUT_REGISTERS, start 12536,
READ_MULTIPLE_REGISTERS, start 13024,
READ_MULTIPLE_REGISTERS, start 13088,
READ_MULTIPLE_REGISTERS, start 13188,
READ_MULTIPLE_REGISTERS, start 13270,
READ_MULTIPLE_REGISTERS, start 13332,
READ_MULTIPLE_REGISTERS, start 13358,
READ_MULTIPLE_REGISTERS, start 13384,
READ_MULTIPLE_REGISTERS, start 13410,
READ_MULTIPLE_REGISTERS, start 13436,
READ_MULTIPLE_REGISTERS, start 13462,
READ_MULTIPLE_REGISTERS, start 13514,
READ_MULTIPLE_REGISTERS, start 13540,
READ_MULTIPLE_REGISTERS, start 13566,
READ_MULTIPLE_REGISTERS, start 13638,
READ_MULTIPLE_REGISTERS, start 13754,
READ_MULTIPLE_REGISTERS, start 13780,
READ_MULTIPLE_REGISTERS, start 13806,
READ_MULTIPLE_REGISTERS, start 13832,
READ_MULTIPLE_REGISTERS, start 13858,
READ_MULTIPLE_REGISTERS, start 13884,
READ_MULTIPLE_REGISTERS, start 13910,
READ_MULTIPLE_REGISTERS, start 13936,

We can also evaluate how long the tasks are in the queue

$ grep 'POLL MONITOR:' peman.log|grep -o -E 'delay: -?[[:digit:]]+'|sort --general-numeric-sort --key 2
delay: -12510
delay: -12268
delay: -12213
delay: -12211
delay: -12135
delay: -11986
delay: -11919
delay: -11723
delay: -11650
delay: -11444
delay: -11375
delay: -11250
delay: -11182
delay: -11115
delay: -11096
delay: -10765
delay: -10688
delay: -10676
delay: -10565
delay: -10425
delay: -10339
delay: -10139
delay: -10018
delay: -9980
delay: -9938
delay: -9879
delay: -9719
delay: -9558
delay: -9461
delay: -9372
delay: -9193
delay: -9103
delay: -8929
delay: -8903
delay: -8895
delay: -8504
delay: -8436
delay: -8244
delay: -8242
delay: -8188
delay: -8076
delay: -8001
delay: -7829
delay: -7779
delay: -7737
delay: -7650
delay: -7536
delay: -7498
delay: -7180
delay: -7179
delay: -7129
delay: -7060
delay: -6919
delay: -6720
delay: -6689
delay: -6633
delay: -6562
delay: -6562
delay: -6293
delay: -6176
delay: -6164
delay: -6141
delay: -6063
delay: -5939
delay: -5727
delay: -5688
delay: -5673
delay: -5536
delay: -5496
delay: -5473
delay: -4726
delay: -4395
delay: -4195
delay: -3979
delay: -3884
delay: -3811
delay: -3702
delay: -3619
delay: -3509
delay: -3297
delay: -3174
delay: -2967
delay: -2960
delay: -2714
delay: -2697
delay: -2561
delay: -2476
delay: -2472
delay: -2396
delay: -2070
delay: -1963
delay: -1950
delay: -1756
delay: -1660
delay: -1555
delay: -1305
delay: -1157
delay: -1114
delay: -973
delay: -755
delay: -734
delay: -591
delay: -585
delay: -446
delay: -329
delay: -233
delay: -74
delay: -74
delay: 124
delay: 295
delay: 336
delay: 375
delay: 613
delay: 719
delay: 848
delay: 936
delay: 974
delay: 1575
delay: 2006
delay: 2778
delay: 3303
delay: 4844
delay: 5295
delay: 5382
delay: 5768
delay: 6183
delay: 6328
delay: 6761
delay: 7356
delay: 7734
delay: 8673
delay: 9130
delay: 9539

Negative values mean that the poll task has missed it’s scheduled poll time (e.g. 10 s) by that many milliseconds. Positive values mean that scheduled poll time is still in the future. We can see many regular poll tasks are lagging behind the set poll rate.

The amount queued tasks probably explain why you are seeing a lag to when issuing commands to the slave (problem described in OP) – it takes a while before the corresponding data is refreshed from the modbus. I could not confirm this from the logs – there was no writes in the logs.

It is the writing I’d like to have higher pririty on, reading is not so critical.

Could you please adjust reconnectAfterMillis parameter of the tcp thing to 60000 (that is, 1 minute), and please report back.

rossko57 · December 27, 2018, 11:41am

Quite right, I muddled up there.

Pe_Man · December 27, 2018, 12:26pm

ok, changed the thing to 60000 like this

Bridge modbus:tcp:SH2WEB [ host="192.168.1.198", port=502, id=1 , reconnectAfterMillis=60000] {

I don’t see any change in responsetime after this.

replaced log-file: https://www.dropbox.com/s/j307w03z9fp7y6e/openhab.log%20(modbus-debug)?dl=0

2018-12-27 13:15:53.242 [ome.event.ItemCommandEvent] - Item 'Sovrum_4__Kontor__Ljusfunktion_Tak_Status' received command ON
2018-12-27 13:15:53.262 [nt.ItemStatePredictedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status predicted to become ON
2018-12-27 13:15:53.281 [vent.ItemStateChangedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status changed from OFF to ON
2018-12-27 13:15:54.526 [vent.ItemStateChangedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status changed from ON to OFF
2018-12-27 13:15:56.188 [hingStatusInfoChangedEvent] - 'sonos:PLAY3:RINCON_000E587E872A01400' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): The Sonos player RINCON_000E587E872A01400 is not available in local network.
2018-12-27 13:15:56.304 [hingStatusInfoChangedEvent] - 'sonos:zoneplayer:RINCON_000E587E872A01400' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): The Sonos player RINCON_000E587E872A01400 is not available in local network.
2018-12-27 13:15:59.383 [vent.ItemStateChangedEvent] - Sovrum_1__Leo__Temperatur_Temperatur_rum changed from 22.5 to 22.6
2018-12-27 13:16:02.050 [vent.ItemStateChangedEvent] - K_k_Dimbart_ljus_K_kssk_p_Status changed from 0 to 25
2018-12-27 13:16:07.857 [vent.ItemStateChangedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status changed from OFF to ON

Rado1 · December 27, 2018, 4:30pm

I know it is fast but with the old binding i was polling 6 pollers at 1mS without any problem’s.If i pol slower i can not catch every puls the input gets.