Connection pooling in modbus binding

ssalonen · January 28, 2016, 7:23pm

@mbs38 If I read your logs correctly, there is quite many queries in just few seconds, naturally understandable because you have so many slaves pointing to the same serial device.

However, since you only got execute try 1 error but not the execute try 2 error, it seems that the transaction completed successfully the second time! By default the openhab binding should try 3 times.

If you let it run for a longer period, do you get any log statements such as

“Error getting modbus data for request” (DEBUG level, will fix it to ERROR)
“error when executing write request” (ERROR level)

Those should be hint of actually failed read/write transaction.

I think it might be natural to get some errors, considering the way the serial library is used. Might be hard to change that.

I will try to improved the logging so errors will become more clear…

ssalonen · January 28, 2016, 7:27pm

@Ferryb4, thanks for posting the logs. Your issue seems to be different from @mbs38, it seems that the connection failed to the serial device.

2016-01-28 20:16:59.227 [TRACE] [modbus.internal.ModbusTcpSlave] - Error connecting connection net.wimpi.modbus.net.SerialConnection@969773 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@872c61[serialParameters=net.wimpi.modbus.util.SerialParameters@12005a6[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]: Modbus Serial Master

Do always get that error?
If you let it run a longer period of time, do you get even a single Activated connection without the error Error connecting connection?
can you paste longer log?

Ferryb4 · January 28, 2016, 7:38pm

Hi,

The strange thing is that I get the correct values

  2016-01-28 20:31:37.042 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 02 03 20 80 00 02 ce 10
    2016-01-28 20:31:37.043 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
    2016-01-28 20:31:37.044 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read
    2016-01-28 20:31:37.139 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@16f455f[serialParameters=net.wimpi.modbus.util.SerialParameters@147e2a5[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:37.141 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@16f455f[serialParameters=net.wimpi.modbus.util.SerialParameters@147e2a5[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:37.143 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave26): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@16f455f[serialParameters=net.wimpi.modbus.util.SerialParameters@147e2a5[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:37.147 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7e08b3[serialParameters=net.wimpi.modbus.util.SerialParameters@15c72b8[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:37.149 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7e08b3[serialParameters=net.wimpi.modbus.util.SerialParameters@15c72b8[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:37.152 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave7): borrowing connection (got net.wimpi.modbus.net.SerialConnection@6a6068) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7e08b3[serialParameters=net.wimpi.modbus.util.SerialParameters@15c72b8[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 4 ms
    2016-01-28 20:31:37.672 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 01 03 20 a0 00 02 cf e9
    2016-01-28 20:31:37.673 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
    2016-01-28 20:31:37.674 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read
    2016-01-28 20:31:37.769 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7e08b3[serialParameters=net.wimpi.modbus.util.SerialParameters@15c72b8[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:37.771 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7e08b3[serialParameters=net.wimpi.modbus.util.SerialParameters@15c72b8[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:37.772 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave7): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7e08b3[serialParameters=net.wimpi.modbus.util.SerialParameters@15c72b8[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:37.775 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@e90361[serialParameters=net.wimpi.modbus.util.SerialParameters@10780e5[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:37.777 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@e90361[serialParameters=net.wimpi.modbus.util.SerialParameters@10780e5[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:37.779 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave24): borrowing connection (got net.wimpi.modbus.net.SerialConnection@6a6068) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@e90361[serialParameters=net.wimpi.modbus.util.SerialParameters@10780e5[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 4 ms
    2016-01-28 20:31:38.292 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 02 03 20 20 00 02 ce 32
    2016-01-28 20:31:38.293 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
    2016-01-28 20:31:38.294 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read
    2016-01-28 20:31:38.389 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@e90361[serialParameters=net.wimpi.modbus.util.SerialParameters@10780e5[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:38.391 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@e90361[serialParameters=net.wimpi.modbus.util.SerialParameters@10780e5[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:38.392 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave24): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@e90361[serialParameters=net.wimpi.modbus.util.SerialParameters@10780e5[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:38.395 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@8dfe00[serialParameters=net.wimpi.modbus.util.SerialParameters@1aabb21[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:38.397 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@8dfe00[serialParameters=net.wimpi.modbus.util.SerialParameters@1aabb21[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:38.399 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave25): borrowing connection (got net.wimpi.modbus.net.SerialConnection@6a6068) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@8dfe00[serialParameters=net.wimpi.modbus.util.SerialParameters@1aabb21[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 4 ms
    2016-01-28 20:31:38.494 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@8dfe00[serialParameters=net.wimpi.modbus.util.SerialParameters@1aabb21[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:38.495 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@8dfe00[serialParameters=net.wimpi.modbus.util.SerialParameters@1aabb21[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:38.497 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave25): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@8dfe00[serialParameters=net.wimpi.modbus.util.SerialParameters@1aabb21[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:38.499 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13701f3[serialParameters=net.wimpi.modbus.util.SerialParameters@1823286[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:38.501 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13701f3[serialParameters=net.wimpi.modbus.util.SerialParameters@1823286[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:38.504 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave21): borrowing connection (got net.wimpi.modbus.net.SerialConnection@6a6068) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13701f3[serialParameters=net.wimpi.modbus.util.SerialParameters@1823286[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 4 ms
    2016-01-28 20:31:38.595 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13701f3[serialParameters=net.wimpi.modbus.util.SerialParameters@1823286[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:38.596 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13701f3[serialParameters=net.wimpi.modbus.util.SerialParameters@1823286[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:38.598 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave21): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13701f3[serialParameters=net.wimpi.modbus.util.SerialParameters@1823286[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:38.600 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13ab236[serialParameters=net.wimpi.modbus.util.SerialParameters@37a4b9[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:38.602 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13ab236[serialParameters=net.wimpi.modbus.util.SerialParameters@37a4b9[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:38.604 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave23): borrowing connection (got net.wimpi.modbus.net.SerialConnection@6a6068) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13ab236[serialParameters=net.wimpi.modbus.util.SerialParameters@37a4b9[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 4 ms
    2016-01-28 20:31:38.700 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13ab236[serialParameters=net.wimpi.modbus.util.SerialParameters@37a4b9[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:38.702 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13ab236[serialParameters=net.wimpi.modbus.util.SerialParameters@37a4b9[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:38.703 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave23): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13ab236[serialParameters=net.wimpi.modbus.util.SerialParameters@37a4b9[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:38.706 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@166557b[serialParameters=net.wimpi.modbus.util.SerialParameters@964ad0[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:38.708 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@166557b[serialParameters=net.wimpi.modbus.util.SerialParameters@964ad0[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:38.710 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave3): borrowing connection (got net.wimpi.modbus.net.SerialConnection@6a6068) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@166557b[serialParameters=net.wimpi.modbus.util.SerialParameters@964ad0[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 4 ms
    2016-01-28 20:31:39.232 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 01 03 20 00 00 02 cf cb
    2016-01-28 20:31:39.233 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
    2016-01-28 20:31:39.235 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read
    2016-01-28 20:31:39.330 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@166557b[serialParameters=net.wimpi.modbus.util.SerialParameters@964ad0[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:39.332 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@166557b[serialParameters=net.wimpi.modbus.util.SerialParameters@964ad0[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:39.333 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave3): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@166557b[serialParameters=net.wimpi.modbus.util.SerialParameters@964ad0[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:39.336 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4cdd69[serialParameters=net.wimpi.modbus.util.SerialParameters@71cf0b[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:39.338 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4cdd69[serialParameters=net.wimpi.modbus.util.SerialParameters@71cf0b[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:39.340 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave1): borrowing connection (got net.wimpi.modbus.net.SerialConnection@6a6068) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4cdd69[serialParameters=net.wimpi.modbus.util.SerialParameters@71cf0b[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 4 ms
    2016-01-28 20:31:39.431 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4cdd69[serialParameters=net.wimpi.modbus.util.SerialParameters@71cf0b[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:39.433 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4cdd69[serialParameters=net.wimpi.modbus.util.SerialParameters@71cf0b[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:39.434 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave1): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4cdd69[serialParameters=net.wimpi.modbus.util.SerialParameters@71cf0b[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:39.438 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@10b7d0a[serialParameters=net.wimpi.modbus.util.SerialParameters@b1e365[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:39.454 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@10b7d0a[serialParameters=net.wimpi.modbus.util.SerialParameters@b1e365[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:39.457 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave5): borrowing connection (got net.wimpi.modbus.net.SerialConnection@6a6068) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@10b7d0a[serialParameters=net.wimpi.modbus.util.SerialParameters@b1e365[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 18 ms
    2016-01-28 20:31:39.552 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@10b7d0a[serialParameters=net.wimpi.modbus.util.SerialParameters@b1e365[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:39.553 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@10b7d0a[serialParameters=net.wimpi.modbus.util.SerialParameters@b1e365[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:39.555 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave5): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@10b7d0a[serialParameters=net.wimpi.modbus.util.SerialParameters@b1e365[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:39.559 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@6a6068 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@184dadf[serialParameters=net.wimpi.modbus.util.SerialParameters@2fabd1[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
    2016-01-28 20:31:39.561 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@184dadf[serialParameters=net.wimpi.modbus.util.SerialParameters@2fabd1[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true
    2016-01-28 20:31:39.564 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave22): borrowing connection (got net.wimpi.modbus.net.SerialConnection@6a6068) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@184dadf[serialParameters=net.wimpi.modbus.util.SerialParameters@2fabd1[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 5 ms
    2016-01-28 20:31:40.082 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 02 03 10 20 00 01 81 33
    2016-01-28 20:31:40.083 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
    2016-01-28 20:31:40.084 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read
    2016-01-28 20:31:40.178 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@184dadf[serialParameters=net.wimpi.modbus.util.SerialParameters@2fabd1[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@6a6068 -> true

ssalonen · January 28, 2016, 7:48pm

It seems that it eventually works, just like with @mbs38 (since there is not execute try 2 error)

Can you both @mbs38 and @Ferryb4 please try out with the new version I uploaded, the link is the same. You should have better logging there which clearly indicates whether request has failed or eventually managed to success. Then the log should be more clear…

Ferryb4 · January 28, 2016, 8:01pm

2016-01-28 20:59:06.811 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 01 03 20 80 00 02 ce 23
2016-01-28 20:59:06.815 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
2016-01-28 20:59:06.819 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 0 error: I/O exception - failed to read. Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@187ddf9. Serial parameters: net.wimpi.modbus.util.SerialParameters@7a2b99[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]
2016-01-28 20:59:06.919 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13fbe14[serialParameters=net.wimpi.modbus.util.SerialParameters@1f1f40e[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:06.921 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13fbe14[serialParameters=net.wimpi.modbus.util.SerialParameters@1f1f40e[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:06.922 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave6): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@13fbe14[serialParameters=net.wimpi.modbus.util.SerialParameters@1f1f40e[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:11.926 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1511c80[serialParameters=net.wimpi.modbus.util.SerialParameters@7a2b99[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
2016-01-28 20:59:11.927 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1511c80[serialParameters=net.wimpi.modbus.util.SerialParameters@7a2b99[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:11.928 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave3): borrowing connection (got net.wimpi.modbus.net.SerialConnection@81b074) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1511c80[serialParameters=net.wimpi.modbus.util.SerialParameters@7a2b99[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 2 ms
2016-01-28 20:59:12.022 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1511c80[serialParameters=net.wimpi.modbus.util.SerialParameters@7a2b99[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:12.023 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1511c80[serialParameters=net.wimpi.modbus.util.SerialParameters@7a2b99[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:12.024 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave3): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1511c80[serialParameters=net.wimpi.modbus.util.SerialParameters@7a2b99[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:12.026 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1d4281[serialParameters=net.wimpi.modbus.util.SerialParameters@1d3b8a1[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
2016-01-28 20:59:12.027 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1d4281[serialParameters=net.wimpi.modbus.util.SerialParameters@1d3b8a1[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:12.028 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave7): borrowing connection (got net.wimpi.modbus.net.SerialConnection@81b074) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1d4281[serialParameters=net.wimpi.modbus.util.SerialParameters@1d3b8a1[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 2 ms
2016-01-28 20:59:12.122 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1d4281[serialParameters=net.wimpi.modbus.util.SerialParameters@1d3b8a1[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:12.123 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1d4281[serialParameters=net.wimpi.modbus.util.SerialParameters@1d3b8a1[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:12.124 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave7): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1d4281[serialParameters=net.wimpi.modbus.util.SerialParameters@1d3b8a1[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:12.126 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@a09d88[serialParameters=net.wimpi.modbus.util.SerialParameters@1bb080e[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
2016-01-28 20:59:12.126 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@a09d88[serialParameters=net.wimpi.modbus.util.SerialParameters@1bb080e[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:12.127 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave5): borrowing connection (got net.wimpi.modbus.net.SerialConnection@81b074) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@a09d88[serialParameters=net.wimpi.modbus.util.SerialParameters@1bb080e[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 2 ms
2016-01-28 20:59:12.224 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@a09d88[serialParameters=net.wimpi.modbus.util.SerialParameters@1bb080e[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:12.225 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@a09d88[serialParameters=net.wimpi.modbus.util.SerialParameters@1bb080e[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:12.225 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave5): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@a09d88[serialParameters=net.wimpi.modbus.util.SerialParameters@1bb080e[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:12.227 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@18be030[serialParameters=net.wimpi.modbus.util.SerialParameters@1d49f77[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
2016-01-28 20:59:12.228 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@18be030[serialParameters=net.wimpi.modbus.util.SerialParameters@1d49f77[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:12.229 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave22): borrowing connection (got net.wimpi.modbus.net.SerialConnection@81b074) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@18be030[serialParameters=net.wimpi.modbus.util.SerialParameters@1d49f77[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 2 ms
2016-01-28 20:59:12.741 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 02 03 10 20 00 01 81 33
2016-01-28 20:59:12.744 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
2016-01-28 20:59:12.745 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 0 error: I/O exception - failed to read. Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@f419d. Serial parameters: net.wimpi.modbus.util.SerialParameters@7a2b99[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]
2016-01-28 20:59:12.835 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@18be030[serialParameters=net.wimpi.modbus.util.SerialParameters@1d49f77[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:12.836 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@18be030[serialParameters=net.wimpi.modbus.util.SerialParameters@1d49f77[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:12.837 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave22): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@18be030[serialParameters=net.wimpi.modbus.util.SerialParameters@1d49f77[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:12.838 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@9c0c57[serialParameters=net.wimpi.modbus.util.SerialParameters@1971433[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
2016-01-28 20:59:12.839 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@9c0c57[serialParameters=net.wimpi.modbus.util.SerialParameters@1971433[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:12.841 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave2): borrowing connection (got net.wimpi.modbus.net.SerialConnection@81b074) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@9c0c57[serialParameters=net.wimpi.modbus.util.SerialParameters@1971433[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 2 ms
2016-01-28 20:59:13.361 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 01 03 10 20 00 01 81 00
2016-01-28 20:59:13.362 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
2016-01-28 20:59:13.362 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 0 error: I/O exception - failed to read. Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@d68051. Serial parameters: net.wimpi.modbus.util.SerialParameters@7a2b99[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]
2016-01-28 20:59:13.453 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@9c0c57[serialParameters=net.wimpi.modbus.util.SerialParameters@1971433[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:13.454 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@9c0c57[serialParameters=net.wimpi.modbus.util.SerialParameters@1971433[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:13.455 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave2): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@9c0c57[serialParameters=net.wimpi.modbus.util.SerialParameters@1971433[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:13.456 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@42779b[serialParameters=net.wimpi.modbus.util.SerialParameters@165b873[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
2016-01-28 20:59:13.457 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@42779b[serialParameters=net.wimpi.modbus.util.SerialParameters@165b873[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:13.458 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave25): borrowing connection (got net.wimpi.modbus.net.SerialConnection@81b074) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@42779b[serialParameters=net.wimpi.modbus.util.SerialParameters@165b873[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 2 ms
2016-01-28 20:59:13.971 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 02 03 20 60 00 02 cf e6
2016-01-28 20:59:13.972 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
2016-01-28 20:59:13.973 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 0 error: I/O exception - failed to read. Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@4bc3e7. Serial parameters: net.wimpi.modbus.util.SerialParameters@7a2b99[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]
2016-01-28 20:59:14.067 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@42779b[serialParameters=net.wimpi.modbus.util.SerialParameters@165b873[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:14.068 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@42779b[serialParameters=net.wimpi.modbus.util.SerialParameters@165b873[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:14.069 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave25): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@42779b[serialParameters=net.wimpi.modbus.util.SerialParameters@165b873[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:14.070 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@bf960d[serialParameters=net.wimpi.modbus.util.SerialParameters@e1f038[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
2016-01-28 20:59:14.071 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@bf960d[serialParameters=net.wimpi.modbus.util.SerialParameters@e1f038[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:14.072 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave27): borrowing connection (got net.wimpi.modbus.net.SerialConnection@81b074) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@bf960d[serialParameters=net.wimpi.modbus.util.SerialParameters@e1f038[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 2 ms
2016-01-28 20:59:14.178 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@bf960d[serialParameters=net.wimpi.modbus.util.SerialParameters@e1f038[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:14.192 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@bf960d[serialParameters=net.wimpi.modbus.util.SerialParameters@e1f038[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:14.193 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave27): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@bf960d[serialParameters=net.wimpi.modbus.util.SerialParameters@e1f038[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:14.194 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@335403[serialParameters=net.wimpi.modbus.util.SerialParameters@2ea48c[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
2016-01-28 20:59:14.195 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@335403[serialParameters=net.wimpi.modbus.util.SerialParameters@2ea48c[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:14.196 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave23): borrowing connection (got net.wimpi.modbus.net.SerialConnection@81b074) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@335403[serialParameters=net.wimpi.modbus.util.SerialParameters@2ea48c[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 2 ms
2016-01-28 20:59:14.291 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@335403[serialParameters=net.wimpi.modbus.util.SerialParameters@2ea48c[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:14.292 [TRACE] [modbus.internal.ModbusTcpSlave] - Passivating connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@335403[serialParameters=net.wimpi.modbus.util.SerialParameters@2ea48c[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:14.293 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave23): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@335403[serialParameters=net.wimpi.modbus.util.SerialParameters@2ea48c[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]
2016-01-28 20:59:14.297 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated connection net.wimpi.modbus.net.SerialConnection@81b074 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@12c1071[serialParameters=net.wimpi.modbus.util.SerialParameters@1c4956e[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
2016-01-28 20:59:14.299 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@12c1071[serialParameters=net.wimpi.modbus.util.SerialParameters@1c4956e[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@81b074 -> true
2016-01-28 20:59:14.300 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave1): borrowing connection (got net.wimpi.modbus.net.SerialConnection@81b074) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@12c1071[serialParameters=net.wimpi.modbus.util.SerialParameters@1c4956e[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]] took 6 ms

mbs38 · January 29, 2016, 11:03am

Hi ssalonen,

It seems that it eventually works, just like with @mbs38 (since there is not execute try 2 error)

The performance is still well below what I’ve seen with a single slave and hasn’t improved at all. I got 30 successful queries per second with a single slave and about 1 to 2 with 12 slaves. The performance also degrades over time, which I’ve seen with the unmodified 1.8 binding too. In the first couple of seconds after starting openhab it achieves between 3 and 5 successful queries per second and that slows down to 1 to 2 successful queries per second.


14:09:13.364 [ERROR] [i.modbus.io.ModbusRTUTransport:167  ] - Last request: 05 02 00 00 00 08 78 48
14:09:13.364 [ERROR] [i.modbus.io.ModbusRTUTransport:168  ] - failed to read: Error reading response
14:09:13.364 [ERROR] [w.m.io.ModbusSerialTransaction:198  ] - execute try 0 error: I/O exception - failed to read. Request: net.wimpi.modbus.msg.ReadInputDiscretesRequest@2ce4fef7. Serial parameters: net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]
14:09:13.411 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1e85f7eb[serialParameters=net.wimpi.modbus.util.SerialParameters@75b3d3ab[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.411 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1e85f7eb[serialParameters=net.wimpi.modbus.util.SerialParameters@75b3d3ab[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.412 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus5): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@1e85f7eb[serialParameters=net.wimpi.modbus.util.SerialParameters@75b3d3ab[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.412 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4c538c15[serialParameters=net.wimpi.modbus.util.SerialParameters@542fcbdb[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.412 [INFO ] [runtime.busevents             :26   ] - IRvorne state updated to CLOSED
14:09:13.412 [INFO ] [runtime.busevents             :26   ] - Klingel state updated to CLOSED
14:09:13.412 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'Ampel'
14:09:13.412 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4c538c15[serialParameters=net.wimpi.modbus.util.SerialParameters@542fcbdb[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.413 [INFO ] [runtime.busevents             :26   ] - Stahltuer state updated to OPEN
14:09:13.413 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus5coils): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4c538c15[serialParameters=net.wimpi.modbus.util.SerialParameters@542fcbdb[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 1 ms
14:09:13.414 [INFO ] [runtime.busevents             :22   ] - agsBus7Out5 received command OFF
14:09:13.415 [INFO ] [runtime.busevents             :22   ] - agsBus7Out4 received command OFF
14:09:13.447 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4c538c15[serialParameters=net.wimpi.modbus.util.SerialParameters@542fcbdb[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.447 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4c538c15[serialParameters=net.wimpi.modbus.util.SerialParameters@542fcbdb[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.447 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus5coils): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@4c538c15[serialParameters=net.wimpi.modbus.util.SerialParameters@542fcbdb[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.447 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'KlingelIRvorne'
14:09:13.448 [INFO ] [runtime.busevents             :26   ] - IRvorneEventShort state updated to OFF
14:09:13.448 [INFO ] [runtime.busevents             :26   ] - IRvorneEventLong state updated to OFF
14:09:13.452 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@37e35940[serialParameters=net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.452 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@37e35940[serialParameters=net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.453 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus3): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@37e35940[serialParameters=net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 3 ms
14:09:13.483 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@37e35940[serialParameters=net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.483 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@37e35940[serialParameters=net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.484 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus3): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@37e35940[serialParameters=net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.484 [INFO ] [runtime.busevents             :26   ] - Mitteleingang state updated to OPEN
14:09:13.484 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@6e8caf8[serialParameters=net.wimpi.modbus.util.SerialParameters@459495f1[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.484 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@6e8caf8[serialParameters=net.wimpi.modbus.util.SerialParameters@459495f1[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.484 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus17Discretes): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@6e8caf8[serialParameters=net.wimpi.modbus.util.SerialParameters@459495f1[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 0 ms
14:09:13.518 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@6e8caf8[serialParameters=net.wimpi.modbus.util.SerialParameters@459495f1[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.518 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@6e8caf8[serialParameters=net.wimpi.modbus.util.SerialParameters@459495f1[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.518 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus17Discretes): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@6e8caf8[serialParameters=net.wimpi.modbus.util.SerialParameters@459495f1[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.519 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@d709f94[serialParameters=net.wimpi.modbus.util.SerialParameters@6993b008[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.519 [INFO ] [runtime.busevents             :26   ] - agsBus17Discrete state updated to CLOSED
14:09:13.519 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@d709f94[serialParameters=net.wimpi.modbus.util.SerialParameters@6993b008[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.519 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus2): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@d709f94[serialParameters=net.wimpi.modbus.util.SerialParameters@6993b008[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 0 ms
14:09:13.542 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@d709f94[serialParameters=net.wimpi.modbus.util.SerialParameters@6993b008[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.542 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@d709f94[serialParameters=net.wimpi.modbus.util.SerialParameters@6993b008[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.542 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus2): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@d709f94[serialParameters=net.wimpi.modbus.util.SerialParameters@6993b008[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.543 [INFO ] [runtime.busevents             :26   ] - Holztuer state updated to OPEN
14:09:13.543 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@5d13990b[serialParameters=net.wimpi.modbus.util.SerialParameters@7915701c[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.543 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@5d13990b[serialParameters=net.wimpi.modbus.util.SerialParameters@7915701c[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.543 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus4): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@5d13990b[serialParameters=net.wimpi.modbus.util.SerialParameters@7915701c[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 0 ms
14:09:13.567 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@5d13990b[serialParameters=net.wimpi.modbus.util.SerialParameters@7915701c[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.567 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@5d13990b[serialParameters=net.wimpi.modbus.util.SerialParameters@7915701c[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.567 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus4): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@5d13990b[serialParameters=net.wimpi.modbus.util.SerialParameters@7915701c[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.567 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7017f2b0[serialParameters=net.wimpi.modbus.util.SerialParameters@6cf4f50[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.567 [INFO ] [runtime.busevents             :26   ] - Hintereingang state updated to OPEN
14:09:13.567 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7017f2b0[serialParameters=net.wimpi.modbus.util.SerialParameters@6cf4f50[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.567 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBusMasterCoils): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7017f2b0[serialParameters=net.wimpi.modbus.util.SerialParameters@6cf4f50[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 0 ms
14:09:13.579 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7017f2b0[serialParameters=net.wimpi.modbus.util.SerialParameters@6cf4f50[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.579 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7017f2b0[serialParameters=net.wimpi.modbus.util.SerialParameters@6cf4f50[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.579 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBusMasterCoils): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@7017f2b0[serialParameters=net.wimpi.modbus.util.SerialParameters@6cf4f50[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.579 [INFO ] [runtime.busevents             :26   ] - agsBusMasterControlDoors state updated to ON
14:09:13.579 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@30e85940[serialParameters=net.wimpi.modbus.util.SerialParameters@1fab33a3[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.580 [INFO ] [runtime.busevents             :26   ] - agsBusMasterControlMasterSwitchOn state updated to ON
14:09:13.580 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@30e85940[serialParameters=net.wimpi.modbus.util.SerialParameters@1fab33a3[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.580 [INFO ] [runtime.busevents             :26   ] - agsBusMasterControlMasterSwitchOff state updated to ON
14:09:13.580 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus11): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@30e85940[serialParameters=net.wimpi.modbus.util.SerialParameters@1fab33a3[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 1 ms
14:09:13.643 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@30e85940[serialParameters=net.wimpi.modbus.util.SerialParameters@1fab33a3[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.643 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@30e85940[serialParameters=net.wimpi.modbus.util.SerialParameters@1fab33a3[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.644 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus11): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@30e85940[serialParameters=net.wimpi.modbus.util.SerialParameters@1fab33a3[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:13.644 [INFO ] [runtime.busevents             :26   ] - agsBus11Out0 state updated to OFF
14:09:13.644 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@396dfcf6[serialParameters=net.wimpi.modbus.util.SerialParameters@75acfcc2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:13.644 [INFO ] [runtime.busevents             :26   ] - agsBus11Out2 state updated to ON
14:09:13.644 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@396dfcf6[serialParameters=net.wimpi.modbus.util.SerialParameters@75acfcc2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:13.644 [INFO ] [runtime.busevents             :26   ] - agsBus11Out1 state updated to ON
14:09:13.644 [TRACE] [o.b.m.internal.BaseModbusSlave:293  ] - ModbusSlave (agsBus8): borrowing connection (got net.wimpi.modbus.net.SerialConnection@5fc7d9ff) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@396dfcf6[serialParameters=net.wimpi.modbus.util.SerialParameters@75acfcc2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] took 0 ms
14:09:13.647 [INFO ] [runtime.busevents             :26   ] - agsBus11EventLongIn2 state updated to OFF
14:09:14.089 [DEBUG] [o.o.i.s.i.DiscoveryServiceImpl:80   ] - Unregistering service _openhab-server-ssl._tcp.local. at port 8443
14:09:14.151 [ERROR] [i.modbus.io.ModbusRTUTransport:167  ] - Last request: 08 01 00 00 00 18 3c 99
14:09:14.151 [ERROR] [i.modbus.io.ModbusRTUTransport:168  ] - failed to read: Error reading response
14:09:14.151 [ERROR] [w.m.io.ModbusSerialTransaction:198  ] - execute try 0 error: I/O exception - failed to read. Request: net.wimpi.modbus.msg.ReadCoilsRequest@78f7f111. Serial parameters: net.wimpi.modbus.util.SerialParameters@553638aa[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]
14:09:14.180 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@396dfcf6[serialParameters=net.wimpi.modbus.util.SerialParameters@75acfcc2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:14.180 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Passivating connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@396dfcf6[serialParameters=net.wimpi.modbus.util.SerialParameters@75acfcc2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:14.180 [TRACE] [o.b.m.internal.BaseModbusSlave:320  ] - ModbusSlave (agsBus8): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@396dfcf6[serialParameters=net.wimpi.modbus.util.SerialParameters@75acfcc2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:09:14.181 [INFO ] [runtime.busevents             :26   ] - agsBus8Out0 state updated to ON
14:09:14.181 [TRACE] [modbus.internal.ModbusTcpSlave:93   ] - Activated connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@373a1ecd[serialParameters=net.wimpi.modbus.util.SerialParameters@735e2852[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] -- connect() ok
14:09:14.181 [TRACE] [modbus.internal.ModbusTcpSlave:109  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@373a1ecd[serialParameters=net.wimpi.modbus.util.SerialParameters@735e2852[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]] connection net.wimpi.modbus.net.SerialConnection@5fc7d9ff -> true
14:09:14.181 [INFO ] [runtime.busevents             :26   ] - agsBus8Out1 state updated to ON

ssalonen · January 29, 2016, 8:06pm

Thank you very much, definetely that does not sound too good.

Even with the new logs I’m missing some log entries: we should get either “execute eventually succeeded with X tries…” or “execute try 3 reached max tries 3 error, throwing last error: …”. I have to test myself why we do not see those log messages.

I’ve also realized that the current implementation might still re-use the modbus transaction id even though the end point (modbus slave device) is the same. That definitely needs fixing, not sure if that might cause some of the slow downs or errors…

I have limited access to internet during the next two weeks but I will look at this and come up with a new version to test.

Thank you again both for trying this out!

mbs38 · February 1, 2016, 11:24pm

You’re welcome. If you come up with something new I’ll be happy to provide feedback again.

M

rossko57 · February 7, 2016, 1:19pm

Just a suggestion, while “queuing” is being looked into. I’m developing a multi-slave Modbus application; don’t have enough hardware yet to help much with testing. But I am playing with configuration so far as I can.

I set up two TCP slaves in openhab.cfg and see the expected timeouts as they don’t yet exist. Monitoring the actual communication attempts shows batches of four attempts, as expected from 1 try + 3 retries.

My observation is that the retry mechanism fixates on each slave in turn, i.e. 4 tries at slaveA, followed by 4 tries at slaveB. This is not ideal as one missing/faulty slave would appear to prevent polling of any remaining working slaves for a long while (4 x timeout periods)? It would be better if retry attempts could be scheduled to the back of the queue, so that normal polling of other slaves could take place in between retries. poll SlaveA(timeout) - poll SlaveB - poll SlaveC - retry Slave A etc.

That might all be completely impractical of course!! just offering for consideration. It’s only a problem when some other error already exists, but would help make Modbus based systems more robust.

mbs38 · February 8, 2016, 8:38pm

Good point.

ssalonen · February 14, 2016, 2:40pm

All right, have had some time to progress this project once again. So I commented a while ago the issue on transaction ids, that is an issue only for TCP modbus since the transaction id is not used with serial.

My tests with local modbus TCP server can now handle huge amount of queries and commands simultaneously so I think we are going to the right direction.

I’ve been trying to figure the remaining serial issues and starting to think that the issues might be due to the way we use the serial devices in the java side. Cannot be 100% sure but I do see that

modbus binding does use “receive threshold” which should apparently make the serial input stream read operation blocking. If it is not blocking, the read() operation returns -1 (EOF).
receiveTimeout was used only with RTU modbus
quite many other openhab serial bindings set the receiveThreshold

I’ve now made sure the modbus binding calls m_CommPort.enableReceiveThreshold(1) before read(). In addition, timeout now applies to all transports. Finally, logging has been improved further.

The configuration of timeout is done with the connection key in openhab.cfg. In addition to to the old parameters:

devicePort (mandatory)
baudRate (optional)
dataBits
parity
stopBits
encoding

You can now configure:

timeout (in milliseconds)
flowControlIn
flowControlOut

For example, serial connection with 1000ms (=1sec) timeout
modbus:serial.slave2.connection=/dev/ttyAMA0:9600:8:even:1:rtu:1000

The timeout has been made configurable, useful at least for this testing phase.

@mbs38 @Ferryb4 Can you please try out again with this new version:
https://github.com/ssalonen/openhab/files/129697/org.openhab.binding.modbus-1.9.0-SNAPSHOT-pooling_serial_fixes_20160214_98b5a32.zip (modbus-pooling-test-version2 tag in my github repository)

To make the testing easier, please

have an minimal configuration (for example two slaves that just read data)
TRACE level logging enabled
reasonable timeout configured for all slaves. Please use exactly the same baud, parity, dataBits, stopBits, encoding and timeout if the port name is the same. Otherwise the connection is not shared and simultaneous requests are executed on the same serial device. Make sure timeout is smaller than the modbus poll period.
latest release version of openhab

When you have issues, please

paste the logs here (or even better use pastebin.com for long logs to make this thread more readable)
the associated openhab.cfg configuration
openhab item definitions.
modbus device you are using, and related devices (gateways etc)
standard you use for serial communication, e.g. RS-232 (based on the comments in the code, RS-485 might not work yet due to echo handling – we should make this configurable as well)

Best,
Sami

Ferryb4 · February 14, 2016, 3:35pm

Hi ssalonen,

I installed the new binding on my RPI. The log files are here.

Items

Group All

    /*Modbus*/
    Group Modbus_1 "Diepvries" (All)


    Number MB_1_05 "Voltage [%.1f Volt]" (Modbus_1){modbus="slave5:0"}

    /*Modbus_2*/
    Group Modbus_2 "Diepvries" (All)

    Number MB_2_05 "Voltage [%.1f Volt]" (Modbus_2){modbus="slave25:0"}

Config

############################### Modbus Binding ########################################
#
#
modbus:poll=10000
# Voltage
modbus:serial.slave5.connection=/dev/ttyAMA0:9600:8:even:1:rtu:1000
modbus:serial.slave5.id=1
modbus:serial.slave5.start=8192
modbus:serial.slave5.length=2
modbus:serial.slave5.type=holding
modbus:serial.slave5.valuetype=float32

# Voltage
modbus:serial.slave25.connection=/dev/ttyAMA0:9600:8:even:1:rtu:1000
modbus:serial.slave25.id=2
modbus:serial.slave25.start=8192
modbus:serial.slave25.length=2
modbus:serial.slave25.type=holding
modbus:serial.slave25.valuetype=float32

I use a RPi 2 with a RB-RS485 .
On my bus are two energy meters connected from Inepro PRO1 - MID - Modbus.

The Registers can you find here.

mbs38 · February 14, 2016, 6:31pm

Hi ssalonen,

I’ve tried it with the following config:

modbus:poll=200

modbus:serial.agsBus16Registers.connection=/dev/ttyS0:38400:8:none:1:rtu:100
modbus:serial.agsBus16Registers.id=16
modbus:serial.agsBus16Registers.start=0
modbus:serial.agsBus16Registers.length=2
modbus:serial.agsBus16Registers.type=input
modbus:serial.agsBus16Registers.valuetype=int16

modbus:serial.agsBus17Discretes.connection=/dev/ttyS0:38400:8:none:1:rtu:100
modbus:serial.agsBus17Discretes.id=17
modbus:serial.agsBus17Discretes.start=0
modbus:serial.agsBus17Discretes.length=1
modbus:serial.agsBus17Discretes.type=discrete

items:
Number agsBus16InputRegister1 “bus voltage: [%d mV]”{ modbus=“agsBus16Registers:1” }
Number agsBus16InputRegister0 “supply output voltage [%d mV]” { modbus=“agsBus16Registers:0” }
Contact agsBus17Discrete { modbus=“agsBus17Discretes:0” }

Here are the logs: http://pastebin.com/tQabp3iG

I am using a Modbus router that acts as a RS232 to RS485 converter => there are no echos.
Btw: Most USB to RS485 converters have the TXen and RXen pins of their RS485 line transceiver tied together, which means that they cannot receive while they are sending. So usually there won’t be any echos even though it’s RS485 (!). We need to make surethat nobody gets confused about this

[quote=“ssalonen, post:31, topic:5246”]
The timeout has been made configurable, useful at least for this testing phase.
[/quote] This has already proven to be a useful feature. By lowering the timeout, I was able to improve the performance significantly - however the errors persist…

[quote=“ssalonen, post:31, topic:5246”]
Make sure timeout is smaller than the modbus poll period.
[/quote] Why? In order to achieve the highest possible polling rate we want the modbus poll period to be 0ms. (meaning that once you’re finished with all devices, start again from the beginning and do not wait X milliseconds)

ssalonen · February 14, 2016, 7:52pm

thank you both @mbs38 and @Ferryb4. I shall look the logs…

@mbs38, I can’t see any errors in the logs? Did you paste it fully? I do see some state updates, so it’s working better? Or do the errors come only with more slaves?

In order to achieve the highest possible polling rate we want the modbus poll period to be 0ms. (meaning that once you’re finished with all devices, start again from the beginning and do not wait X milliseconds)

Yes, I do get this. With large timeout this would block the “0ms polling” since even one “timeout” might block the normal fast loop. Not sure if this happens often though and what would be the case…

Btw: Most USB to RS485 converters have the TXen and RXen pins of their RS485 line transceiver tied together, which means that they cannot receive while they are sending. So usually there won’t be any echos even though it’s RS485 (!). We need to make surethat nobody gets confused about this

Thanks for explaining this, did not know this. That’s good then, so that should not be an issue.

mbs38 · February 14, 2016, 8:38pm

For some reason I’m not getting any errors if start openhab by running start_debug.sh but I get tons of errors when running start.sh

I need to dig into my logging setup.

ssalonen · February 14, 2016, 9:26pm

Ok that’s quite interesting. If you find out a logging configuration that works for you, perhaps @Ferryb4 could also use that. I was missing some DEBUG level log statements still, or then I just misread the code…

mbs38 · February 14, 2016, 9:43pm

I’ve tried it with more slaves and shorter timeout and polling settings:

Config: http://pastebin.com/2Hh1bbpn

Now I get errors:
Logs: http://pastebin.com/3qKk5sr0

mbs38 · February 14, 2016, 10:49pm

Ok now things are getting weird:
When I change this line in logback_debug.xml

logger name=“org.openhab.binding.modbus” level=“DEBUG”

to

logger name=“org.openhab.binding.modbus” level=“TRACE”

the performance is doubled (amount of successful master-slave transactions). The configuration remained the same ( http://pastebin.com/2Hh1bbpn ).

rossko57 · February 18, 2016, 8:47pm

I have broken my cheap chinese TCP gateway, but am able to try the updated binding with a RS-485 serial setup
Two slaves configured, both part of one real device:
modbus:serial.slave4R.connection=COM5:9600:8:none:1:rtu:1000
modbus:tcp.slave4R.id=40
modbus:tcp.slave4R.type=coil
modbus:tcp.slave4R.start=16
modbus:tcp.slave4R.length=4
modbus:serial.slave4I.connection=COM5:9600:8:none:1:rtu:1000
modbus:tcp.slave4I.id=40
modbus:tcp.slave4I.type=discrete
modbus:tcp.slave4I.start=32
modbus:tcp.slave4I.length=4

All seems to work fine, no errors reported. Randomly commanding coil items on and off (so as to intersperse traffic with polls) doesn’t seem to cause issues.

ssalonen · February 19, 2016, 5:49am

Glad to hear it! If you don’t mind, can you please test it with the released official version modbus binding as well? Just to confirm that the new version fixes something

Thanks!