Connection pooling in modbus binding

ssalonen · January 4, 2016, 7:59pm

@mbs38: Hi and thanks again for the comments.

I think I presented the idea of “pooling” a bit unclearly in the first post. The idea is to pool (or “serialize”) the transactions only if the end point is the same (e.g. same serial port, or same ip+port). If the slave end point is different, the transaction is allowed to execute at the same time some other operation is ongoing on some other end point. Thus if one modbus slave is slow, it does not affect the fast slave. Keeping this in mind, should we still make the number of parallel connections per endpoint configurable? Like you said, for serial it should be definately at most 1.

Very good points about the baud rates, definately agree that this is theoretical but I feel we might get it for free, let’s see. Agree that not worth implementing if it gets hard.

We could have configuration something like this for example, (all of these keep backwards compatibility of course)

slaves MUST define connection or connectionpool, but not both
// define slave that uses a certain connection pool instead of direct connection modbus:tcp.slave1.connectionpool=poolA modbus:tcp.slave1.length=10 modbus:tcp.slave1.type=coil // connection pool p1 definition modbus:pool.poolA.connection=192.168.1.100:502 modbus:pool.poolA.maxconnections=4 // ... and other pool parameters, e.g. reconnect period etc. // Something similar is implemented in the openhab TCP binding

or
2) slaves MUST define connection, and possibly connectionpool
// define slave that uses a certain connection pool (limits connections over slaves) but specifies address directly in the slave modbus:tcp.slave1.connection=192.168.1.100:502 modbus:tcp.slave1.connectionpool=poolA modbus:tcp.slave1.length=10 modbus:tcp.slave1.type=coil // connection pool p1 definition (excluding connection) modbus:pool.poolA.maxconnections=4 // ... and other pool parameters, e.g. reconnect period etc. // Something similar is implemented in the openhab TCP binding
or
3) slaves MUST define connection, OR connectionpool or BOTH. Connection can be speficied in slave OR connectionpool, but not both.

The option 2) resembles java’s ThreadPoolExecutor. Option 3) offers most versability, and offers convenient way for the user to avoid repeating the ip/serial addresses. Out of these I like option 3.

In the java API side I’m thinking something like ThreadPoolExecuter and apache commons pool.

What do you guys think of the configuration proposal?

rossko57 · January 5, 2016, 12:00am

A reminder that a TCP “slave” could be a LAN<->serial gateway, meaning attached to a dependent serial bus with N slaves selected by the ‘id’ parameter definition. They’d need to be 'serialized/queued per gateway to avoid bus collision.
That would seem to fit with any alternatives, with more or less manual adjustments, so long as ‘id’ is preserved.

A problem with multiple differing baud rates on a single line is that all the devices will be handling errors - more or less overhead, depending on the device. That doesn’t rule it out, just means “exercise caution”

mbs38 · January 5, 2016, 1:22pm

That is indeed a very good idea.

It also solves this in a very elegant way: [quote=“rossko57, post:8, topic:5246”]
A reminder that a TCP “slave” could be a LAN<->serial gateway, meaning attached to a dependent serial bus with N slaves selected by the ‘id’ parameter definition. They’d need to be 'serialized/queued per gateway to avoid bus collision.
[/quote] For the sake of completeness: Most Modbus-TCP-Serial gateways have an internal queue to avoid collisions on the serial bus and can therefore handle simultaneous requests (one after the other). Some simpler gateways don’t have an internal queue and recklessly ignore every request that comes in at an inconvenient time…

Tying the serialization to IP+PORT and serial port seems very reasonable to me.

[quote=“ssalonen, post:7, topic:5246”]
Keeping this in mind, should we still make the number of parallel connections per endpoint configurable?
[/quote] Nope. The pooling idea makes it redundant. No need to confuse the user here.

[quote=“ssalonen, post:7, topic:5246”]
Out of these I like option 3.
[/quote] Me too.

ssalonen · January 6, 2016, 3:12pm

Option 3 has one issue: if the connection is specified in the connection pool definition, it is unclear whether what modbus variant (tcp, serial etc.) should be used.

I propose improved configuration (Option 4). We would have to support also the old configuration.

// Definition of connection details to slave. Modbus TCP, ip 192.168.1.5 port 502. 
// At most have 4 concurrent connections
modbus:slaves.slave1.connection=tcp://192.168.1.5:502
modbus:slaves.slave1.maxconnections=4
// other parameters, hypothethical examples follow
// reconnect every ~10mins due issues with long connections with this slave
modbus:slaves.slave1.reconnectevery=360

//
// TCP example
//

// "read 10 coils from modbus slave slave1"
modbus:polldata.slave1coils.slave=slave1
modbus:polldata.slave1coils.length=10
modbus:polldata.slave1coils.type=coil

// "read 5 holding registers"
modbus:polldata.slave1holding.slave=slave1
modbus:polldata.slave1holding.length=5
modbus:polldata.slave1holding.type=holding

//
// Serial example
//

// Definition of connection conn2. Modbus serial rtu 
// At most have 1 concurrent connections (this could be default as well for serials)
// the URI convention adapted from http://docs.oracle.com/javame/config/cldc/ref-impl/midp2.0/jsr118/javax/microedition/io/CommConnection.html
modbus:slaves.slave2.connection=comm+rtu:/dev/ttyUSB0;baudrate=96600
modbus:slaves.slave2.maxconnections=1

// "read 10 coils from modbus slave slave2"
modbus:polldata.slave2coils.slave=slave2
modbus:polldata.slave2coils.length=10
modbus:polldata.slave2coils.type=coil

// "read 5 holding registers from modbus slave slave2"
modbus:polldata.slave2holding.slave=slave2
modbus:polldata.slave2holding.length=5
modbus:polldata.slave2holding.type=holding

The above format is extensible. If at some point we want to support Modbus RTU over TCP we could have .connection=tcp+rtu://192.168.1.5:502.

All the above configuration changes are in a way optional if everything is serialized by the endpoint, that is maximum connections per endpoint is one. I’m starting to think that we should delay the configuration changes, and possibly in the future make this change – if we find it necessary in the future.

mbs38 · January 11, 2016, 3:11pm

Good point.
First priority should be to get it to work - right now the binding is unusable with serial modbus.

Best regards and thanks for the work you are putting into this.

ssalonen · January 27, 2016, 8:24pm

OK, here’s the first prototype, you can download the experimental plugin here. The source code is in my github modbus-pooling branch.

There are no configuration changes required from the user. The implementation makes sure that at most one read/write operation can access a modbus slave at the same time. It should work as long as we have the same connection setting in each modbus slave.

Different ModbusSerialSlaves can now have different serial parameters, enabling using of multiple serial ports (discussed here). Related issues #2043, #626 and perhaps #1865.

I have done simple integration test but have not yet time to test fully with a proper modbus server. Also, I haven’t had possibility to test with serial devices, so let’s see how this works.

I think this is most critical for serial devices, since command received while polling the data corrupts the data stream. It might help also some tcp servers although PR #3228 (and later PR # 3512, see issue #3818 for more details) probably fixes most cases (but still writing while reading is an issue due to incomplete synchronization).

Hopefully the jar is packaged correctly and contains all the necessary stuff. As this is includes quite large changes from the code side, a thorough testing is needed. Thus I welcome you all to test this down and find out the bugs!

P.S. I will have limited access to email and codes during the next two-three weeks but I’ll try to keep monitoring this thread.

Ferryb4 · January 27, 2016, 9:05pm

Hi Ssalonen,

thank you for your effort.
I just tried the bond but still get errors below.

2016-01-27 22:02:08.390 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 02 03 10 20 00 01 81 33
2016-01-27 22:02:08.391 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
2016-01-27 22:02:08.393 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read
2016-01-27 22:02:09.380 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 01 03 20 80 00 02 ce 23
2016-01-27 22:02:09.381 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
2016-01-27 22:02:09.383 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read
2016-01-27 22:02:10.000 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 02 03 20 00 00 02 cf f8
2016-01-27 22:02:10.001 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
2016-01-27 22:02:10.003 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read
2016-01-27 22:02:10.709 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 01 03 20 20 00 02 ce 01
2016-01-27 22:02:10.711 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
2016-01-27 22:02:10.712 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read

ssalonen · January 27, 2016, 9:11pm

@Ferryb4, hi and thanks for testing this… We will get there!

Can you help me little bit to troubleshoot this

how many slaves you have in openhab.cfg, can you please paste the modbus configuration here?
does it work single slave?
Can you please try with latest official release also (single slave config)? Do you get the same error?

mbs38 · January 27, 2016, 11:21pm

Hi ssalonen,
I’ve tested it too. Stil getting errors:

[ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 0c 04 00 00 00 09 31 11
[ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
[ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read

My openhab.cfg looks like this:

modbus:poll=200
modbus:serial.agsBus16Discretes.connection=/dev/ttyS0:38400:8:none:1:rtu
modbus:serial.agsBus16Discretes.id=16
modbus:serial.agsBus16Discretes.start=0
modbus:serial.agsBus16Discretes.length=1
modbus:serial.agsBus16Discretes.type=discrete
modbus:serial.agsBus16Registers.connection=/dev/ttyS0:38400:8:none:1:rtu

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
modbus:serial.agsBus17Discretes.id=17
modbus:serial.agsBus17Discretes.start=0
modbus:serial.agsBus17Discretes.length=1
modbus:serial.agsBus17Discretes.type=discrete

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

modbus:serial.agsBus12.connection=/dev/ttyS0:38400:8:none:1:rtu
modbus:serial.agsBus12.id=12
modbus:serial.agsBus12.start=0
modbus:serial.agsBus12.length=9
modbus:serial.agsBus12.type=input
modbus:serial.agsBus12.valuetype=int16

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

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

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

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

modbus:serial.agsBus5coils.connection=/dev/ttyS0:38400:8:none:1:rtu
modbus:serial.agsBus5coils.id=5
modbus:serial.agsBus5coils.start=0
modbus:serial.agsBus5coils.length=24
modbus:serial.agsBus5coils.type=coil

modbus:serial.agsBus7.connection=/dev/ttyS0:38400:8:none:1:rtu
modbus:serial.agsBus7.id=7
modbus:serial.agsBus7.start=0
modbus:serial.agsBus7.length=24
modbus:serial.agsBus7.type=coil

modbus:serial.agsBus8.connection=/dev/ttyS0:38400:8:none:1:rtu
modbus:serial.agsBus8.id=8
modbus:serial.agsBus8.start=0
modbus:serial.agsBus8.length=24
modbus:serial.agsBus8.type=coil

modbus:serial.agsBus9.connection=/dev/ttyS0:38400:8:none:1:rtu
modbus:serial.agsBus9.id=9
modbus:serial.agsBus9.start=0
modbus:serial.agsBus9.length=24
modbus:serial.agsBus9.type=coil

Sorry it’s a bit long…

When using only one slave:

modbus:poll=2
modbus:serial.agsBus5coils.connection=/dev/ttyS0:38400:8:none:1:rtu
modbus:serial.agsBus5coils.id=5
modbus:serial.agsBus5coils.start=0
modbus:serial.agsBus5coils.length=24
modbus:serial.agsBus5coils.type=coil

I get no errors and it achieves 30 updates per second.

ssalonen · January 28, 2016, 5:16am

Ok, this helps a bit… So issue comes after many slaves.

Can you please run the multi slave case with TRACE level logging?
Please restart openhab between the tests (do not rely on automatic refresh of openhab.cfg configuration) – I think the current version might not handle that well with serial ports. Will fix this later.

Ferryb4 · January 28, 2016, 6:52am

Hi ssalonen,

My config is:
When i try 1 slave i get no errors.

#
modbus:poll=5000
#
modbus:serial.slave1.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave1.id=1
modbus:serial.slave1.start=4120
modbus:serial.slave1.length=1
modbus:serial.slave1.type=holding
#
modbus:serial.slave2.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave2.id=1
modbus:serial.slave2.start=4128
modbus:serial.slave2.length=1
modbus:serial.slave2.type=holding
#
modbus:serial.slave3.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave3.id=1
modbus:serial.slave3.start=8192
modbus:serial.slave3.length=2
modbus:serial.slave3.type=holding
modbus:serial.slave3.valuetype=float32
#
modbus:serial.slave4.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave4.id=1
modbus:serial.slave4.start=8224
modbus:serial.slave4.length=2
modbus:serial.slave4.type=holding
modbus:serial.slave4.valuetype=float32
#
modbus:serial.slave5.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave5.id=1
modbus:serial.slave5.start=8288
modbus:serial.slave5.length=2
modbus:serial.slave5.type=holding
modbus:serial.slave5.valuetype=float32
#
modbus:serial.slave6.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave6.id=1
modbus:serial.slave6.start=8320
modbus:serial.slave6.length=2
modbus:serial.slave6.type=holding
modbus:serial.slave6.valuetype=float32
#
modbus:serial.slave7.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave7.id=1
modbus:serial.slave7.start=8352
modbus:serial.slave7.length=2
modbus:serial.slave7.type=holding
modbus:serial.slave7.valuetype=float32
#
modbus:serial.slave21.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave21.id=2
modbus:serial.slave21.start=4120
modbus:serial.slave21.length=1
modbus:serial.slave21.type=holding
#
modbus:serial.slave22.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave22.id=2
modbus:serial.slave22.start=4128
modbus:serial.slave22.length=1
modbus:serial.slave22.type=holding
#
modbus:serial.slave23.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave23.id=2
modbus:serial.slave23.start=8192
modbus:serial.slave23.length=2
modbus:serial.slave23.type=holding
modbus:serial.slave23.valuetype=float32
#
modbus:serial.slave24.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave24.id=2
modbus:serial.slave24.start=8224
modbus:serial.slave24.length=2
modbus:serial.slave24.type=holding
modbus:serial.slave24.valuetype=float32
#
modbus:serial.slave25.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave25.id=2
modbus:serial.slave25.start=8288
modbus:serial.slave25.length=2
modbus:serial.slave25.type=holding
modbus:serial.slave25.valuetype=float32
#
modbus:serial.slave26.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave26.id=2
modbus:serial.slave26.start=8320
modbus:serial.slave26.length=2
modbus:serial.slave26.type=holding
modbus:serial.slave26.valuetype=float32
#
modbus:serial.slave27.connection=/dev/ttyAMA0:9600:8:even:1:rtu
modbus:serial.slave27.id=2
modbus:serial.slave27.start=8352
modbus:serial.slave27.length=2
modbus:serial.slave27.type=holding
modbus:serial.slave27.valuetype=float32

With the 1.8.0 binding i get these errors

2016-01-28 07:50:14.334 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 02 03 20 80 00 02 ce 10
2016-01-28 07:50:14.335 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
2016-01-28 07:50:14.336 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read
2016-01-28 07:50:15.134 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 01 03 20 20 00 02 ce 01
2016-01-28 07:50:15.134 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
2016-01-28 07:50:15.135 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read
2016-01-28 07:50:15.743 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 02 03 20 20 00 02 ce 32
2016-01-28 07:50:15.744 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
2016-01-28 07:50:15.745 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read
2016-01-28 07:50:16.354 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 01 03 10 18 00 01 00 cd
2016-01-28 07:50:16.355 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
2016-01-28 07:50:16.355 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read
2016-01-28 07:50:16.963 [ERROR] [i.modbus.io.ModbusRTUTransport] - Last request: 02 03 10 18 00 01 00 fe
2016-01-28 07:50:16.964 [ERROR] [i.modbus.io.ModbusRTUTransport] - failed to read: Error reading response
2016-01-28 07:50:16.965 [ERROR] [w.m.io.ModbusSerialTransaction] - execute try 1 error: I/O exception - failed to read

ssalonen · January 28, 2016, 7:26am

Thank you @Ferryb4. Can you also try out with TRACE level logging (with the new version)?

mbs38 · January 28, 2016, 11:45am

Hi ssalonen,
I’ve restarted openhab each time.

TRACE level logging output with many slaves configured and your new binding version in use:

14:50:21.841 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@46bbed0[serialParameters=net.wimpi.modbus.util.SerialParameters@4c50f55e[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@2f5e3d22 -> true
14:50:21.842 [TRACE] [modbus.internal.ModbusTcpSlave:95   ] - Passivating connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@46bbed0[serialParameters=net.wimpi.modbus.util.SerialParameters@4c50f55e[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:21.842 [TRACE] [o.b.m.internal.BaseModbusSlave:318  ] - ModbusSlave (agsBus16Registers): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@46bbed0[serialParameters=net.wimpi.modbus.util.SerialParameters@4c50f55e[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:21.842 [INFO ] [runtime.busevents             :26   ] - agsBus16InputRegister0 state updated to 24753
14:50:21.842 [TRACE] [modbus.internal.ModbusTcpSlave:87   ] - Activated connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@482a7063[serialParameters=net.wimpi.modbus.util.SerialParameters@308bf240[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:21.842 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@482a7063[serialParameters=net.wimpi.modbus.util.SerialParameters@308bf240[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@2f5e3d22 -> true
14:50:21.842 [INFO ] [runtime.busevents             :26   ] - agsBus16InputRegister1 state updated to 24081
14:50:21.842 [TRACE] [o.b.m.internal.BaseModbusSlave:291  ] - ModbusSlave (agsBus17Discretes): borrowing connection (got net.wimpi.modbus.net.SerialConnection@2f5e3d22) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@482a7063[serialParameters=net.wimpi.modbus.util.SerialParameters@308bf240[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:50:21.876 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@482a7063[serialParameters=net.wimpi.modbus.util.SerialParameters@308bf240[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@2f5e3d22 -> true
14:50:21.876 [TRACE] [modbus.internal.ModbusTcpSlave:95   ] - Passivating connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@482a7063[serialParameters=net.wimpi.modbus.util.SerialParameters@308bf240[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:21.876 [TRACE] [o.b.m.internal.BaseModbusSlave:318  ] - ModbusSlave (agsBus17Discretes): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@482a7063[serialParameters=net.wimpi.modbus.util.SerialParameters@308bf240[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:21.877 [TRACE] [modbus.internal.ModbusTcpSlave:87   ] - Activated connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@29e451bc[serialParameters=net.wimpi.modbus.util.SerialParameters@30d8584[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:21.877 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@29e451bc[serialParameters=net.wimpi.modbus.util.SerialParameters@30d8584[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@2f5e3d22 -> true
14:50:21.877 [TRACE] [o.b.m.internal.BaseModbusSlave:291  ] - ModbusSlave (agsBus17Registers): borrowing connection (got net.wimpi.modbus.net.SerialConnection@2f5e3d22) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@29e451bc[serialParameters=net.wimpi.modbus.util.SerialParameters@30d8584[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:50:21.877 [INFO ] [runtime.busevents             :26   ] - agsBus17Discrete state updated to CLOSED
14:50:21.901 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@29e451bc[serialParameters=net.wimpi.modbus.util.SerialParameters@30d8584[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@2f5e3d22 -> true
14:50:21.901 [TRACE] [modbus.internal.ModbusTcpSlave:95   ] - Passivating connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@29e451bc[serialParameters=net.wimpi.modbus.util.SerialParameters@30d8584[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:21.901 [TRACE] [o.b.m.internal.BaseModbusSlave:318  ] - ModbusSlave (agsBus17Registers): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@29e451bc[serialParameters=net.wimpi.modbus.util.SerialParameters@30d8584[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:21.902 [INFO ] [runtime.busevents             :26   ] - agsBus17InputRegister1 state updated to 24207
14:50:21.902 [TRACE] [modbus.internal.ModbusTcpSlave:87   ] - Activated connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@20b4294e[serialParameters=net.wimpi.modbus.util.SerialParameters@75d5abf2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:21.902 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@20b4294e[serialParameters=net.wimpi.modbus.util.SerialParameters@75d5abf2[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@2f5e3d22 -> true
14:50:21.902 [INFO ] [runtime.busevents             :26   ] - agsBus17InputRegister0 state updated to 24690
14:50:21.902 [TRACE] [o.b.m.internal.BaseModbusSlave:291  ] - ModbusSlave (agsBus5coils): borrowing connection (got net.wimpi.modbus.net.SerialConnection@2f5e3d22) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@20b4294e[serialParameters=net.wimpi.modbus.util.SerialParameters@75d5abf2[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:50:21.924 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@20b4294e[serialParameters=net.wimpi.modbus.util.SerialParameters@75d5abf2[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@2f5e3d22 -> true
14:50:21.925 [TRACE] [modbus.internal.ModbusTcpSlave:95   ] - Passivating connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@20b4294e[serialParameters=net.wimpi.modbus.util.SerialParameters@75d5abf2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:21.925 [TRACE] [o.b.m.internal.BaseModbusSlave:318  ] - ModbusSlave (agsBus5coils): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@20b4294e[serialParameters=net.wimpi.modbus.util.SerialParameters@75d5abf2[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:21.925 [INFO ] [runtime.busevents             :26   ] - IRvorneEventShort state updated to OFF
14:50:21.925 [TRACE] [modbus.internal.ModbusTcpSlave:87   ] - Activated connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@79709eb6[serialParameters=net.wimpi.modbus.util.SerialParameters@31122bd9[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:21.925 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@79709eb6[serialParameters=net.wimpi.modbus.util.SerialParameters@31122bd9[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@2f5e3d22 -> true
14:50:21.925 [TRACE] [o.b.m.internal.BaseModbusSlave:291  ] - ModbusSlave (agsBus11): borrowing connection (got net.wimpi.modbus.net.SerialConnection@2f5e3d22) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@79709eb6[serialParameters=net.wimpi.modbus.util.SerialParameters@31122bd9[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:50:21.925 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'KlingelIRvorne'
14:50:21.926 [INFO ] [runtime.busevents             :26   ] - IRvorneEventLong state updated to OFF
14:50:22.432 [ERROR] [i.modbus.io.ModbusRTUTransport:167  ] - Last request: 0b 01 00 00 00 18 3c aa
14:50:22.432 [ERROR] [i.modbus.io.ModbusRTUTransport:168  ] - failed to read: Error reading response
14:50:22.433 [ERROR] [w.m.io.ModbusSerialTransaction:201  ] - execute try 1 error: I/O exception - failed to read
14:50:22.478 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@79709eb6[serialParameters=net.wimpi.modbus.util.SerialParameters@31122bd9[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@2f5e3d22 -> true
14:50:22.478 [TRACE] [modbus.internal.ModbusTcpSlave:95   ] - Passivating connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@79709eb6[serialParameters=net.wimpi.modbus.util.SerialParameters@31122bd9[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:22.479 [TRACE] [o.b.m.internal.BaseModbusSlave:318  ] - ModbusSlave (agsBus11): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@79709eb6[serialParameters=net.wimpi.modbus.util.SerialParameters@31122bd9[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:22.479 [INFO ] [runtime.busevents             :26   ] - agsBus11Out0 state updated to OFF
14:50:22.479 [TRACE] [modbus.internal.ModbusTcpSlave:87   ] - Activated connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@62c24093[serialParameters=net.wimpi.modbus.util.SerialParameters@69fbc270[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:22.479 [INFO ] [runtime.busevents             :26   ] - agsBus11Out2 state updated to OFF
14:50:22.479 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@62c24093[serialParameters=net.wimpi.modbus.util.SerialParameters@69fbc270[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@2f5e3d22 -> true
14:50:22.479 [TRACE] [o.b.m.internal.BaseModbusSlave:291  ] - ModbusSlave (agsBus7): borrowing connection (got net.wimpi.modbus.net.SerialConnection@2f5e3d22) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@62c24093[serialParameters=net.wimpi.modbus.util.SerialParameters@69fbc270[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:50:22.479 [INFO ] [runtime.busevents             :26   ] - agsBus11Out1 state updated to OFF
14:50:22.480 [INFO ] [runtime.busevents             :26   ] - agsBus11Out4 state updated to OFF
14:50:22.480 [INFO ] [runtime.busevents             :26   ] - agsBus11Out3 state updated to OFF
14:50:22.480 [INFO ] [runtime.busevents             :26   ] - agsBus11Out6 state updated to OFF
14:50:22.480 [INFO ] [runtime.busevents             :26   ] - agsBus11Out5 state updated to OFF
14:50:22.481 [INFO ] [runtime.busevents             :26   ] - agsBus11Out7 state updated to OFF
14:50:22.481 [INFO ] [runtime.busevents             :26   ] - agsBus11EventShortIn0 state updated to ON
14:50:22.481 [INFO ] [runtime.busevents             :26   ] - agsBus11EventShortIn1 state updated to ON
14:50:22.481 [INFO ] [runtime.busevents             :26   ] - agsBus11EventShortIn4 state updated to ON
14:50:22.481 [INFO ] [runtime.busevents             :26   ] - agsBus11EventShortIn5 state updated to ON
14:50:22.481 [INFO ] [runtime.busevents             :26   ] - agsBus11EventShortIn2 state updated to ON
14:50:22.482 [INFO ] [runtime.busevents             :26   ] - agsBus11EventShortIn3 state updated to ON
14:50:22.482 [INFO ] [runtime.busevents             :26   ] - agsBus11EventShortIn6 state updated to ON
14:50:22.482 [INFO ] [runtime.busevents             :26   ] - agsBus11EventShortIn7 state updated to OFF
14:50:22.482 [INFO ] [runtime.busevents             :26   ] - agsBus11EventLongIn5 state updated to OFF
14:50:22.482 [INFO ] [runtime.busevents             :26   ] - agsBus11EventLongIn4 state updated to OFF
14:50:22.482 [INFO ] [runtime.busevents             :26   ] - agsBus11EventLongIn7 state updated to OFF
14:50:22.483 [INFO ] [runtime.busevents             :26   ] - agsBus11EventLongIn6 state updated to OFF
14:50:22.483 [INFO ] [runtime.busevents             :26   ] - agsBus11EventLongIn1 state updated to OFF
14:50:22.483 [INFO ] [runtime.busevents             :26   ] - agsBus11EventLongIn0 state updated to OFF
14:50:22.483 [INFO ] [runtime.busevents             :26   ] - agsBus11EventLongIn3 state updated to OFF
14:50:22.483 [INFO ] [runtime.busevents             :26   ] - agsBus11EventLongIn2 state updated to OFF
14:50:22.514 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@62c24093[serialParameters=net.wimpi.modbus.util.SerialParameters@69fbc270[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@2f5e3d22 -> true
14:50:22.514 [TRACE] [modbus.internal.ModbusTcpSlave:95   ] - Passivating connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@62c24093[serialParameters=net.wimpi.modbus.util.SerialParameters@69fbc270[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:22.514 [TRACE] [o.b.m.internal.BaseModbusSlave:318  ] - ModbusSlave (agsBus7): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@62c24093[serialParameters=net.wimpi.modbus.util.SerialParameters@69fbc270[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:22.515 [INFO ] [runtime.busevents             :26   ] - agsBus7Out0 state updated to OFF
14:50:22.515 [INFO ] [runtime.busevents             :26   ] - agsBus7Out1 state updated to OFF
14:50:22.515 [INFO ] [runtime.busevents             :26   ] - agsBus7Out4 state updated to OFF
14:50:22.516 [INFO ] [runtime.busevents             :26   ] - agsBus7Out5 state updated to OFF
14:50:22.516 [INFO ] [runtime.busevents             :26   ] - agsBus7Out2 state updated to OFF
14:50:22.516 [INFO ] [runtime.busevents             :26   ] - agsBus7Out3 state updated to OFF
14:50:22.516 [INFO ] [runtime.busevents             :26   ] - agsBus7Out6 state updated to OFF
14:50:22.516 [INFO ] [runtime.busevents             :26   ] - agsBus7Out7 state updated to OFF
14:50:22.516 [INFO ] [runtime.busevents             :26   ] - agsBus7EventShortIn2 state updated to ON
14:50:22.517 [INFO ] [runtime.busevents             :26   ] - agsBus7EventShortIn1 state updated to ON
14:50:22.517 [INFO ] [runtime.busevents             :26   ] - agsBus7EventShortIn0 state updated to ON
14:50:22.517 [INFO ] [runtime.busevents             :26   ] - agsBus7EventShortIn6 state updated to ON
14:50:22.517 [INFO ] [runtime.busevents             :26   ] - agsBus7EventShortIn5 state updated to ON
14:50:22.517 [INFO ] [runtime.busevents             :26   ] - agsBus7EventShortIn4 state updated to ON
14:50:22.517 [INFO ] [runtime.busevents             :26   ] - agsBus7EventShortIn3 state updated to ON
14:50:22.517 [INFO ] [runtime.busevents             :26   ] - agsBus7EventShortIn7 state updated to OFF
14:50:22.518 [INFO ] [runtime.busevents             :26   ] - agsBus7EventLongIn7 state updated to OFF
14:50:22.518 [INFO ] [runtime.busevents             :26   ] - agsBus7EventLongIn0 state updated to OFF
14:50:22.518 [INFO ] [runtime.busevents             :26   ] - agsBus7EventLongIn2 state updated to OFF
14:50:22.518 [INFO ] [runtime.busevents             :26   ] - agsBus7EventLongIn1 state updated to OFF
14:50:22.518 [INFO ] [runtime.busevents             :26   ] - agsBus7EventLongIn4 state updated to OFF
14:50:22.518 [INFO ] [runtime.busevents             :26   ] - agsBus7EventLongIn3 state updated to OFF
14:50:22.519 [INFO ] [runtime.busevents             :26   ] - agsBus7EventLongIn6 state updated to OFF
14:50:22.520 [INFO ] [runtime.busevents             :26   ] - agsBus7EventLongIn5 state updated to OFF
14:50:22.715 [TRACE] [modbus.internal.ModbusTcpSlave:87   ] - Activated connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@69a084c6[serialParameters=net.wimpi.modbus.util.SerialParameters@63285eed[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:22.715 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@69a084c6[serialParameters=net.wimpi.modbus.util.SerialParameters@63285eed[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@2f5e3d22 -> true
14:50:22.716 [TRACE] [o.b.m.internal.BaseModbusSlave:291  ] - ModbusSlave (agsBusMasterHolding): borrowing connection (got net.wimpi.modbus.net.SerialConnection@2f5e3d22) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@69a084c6[serialParameters=net.wimpi.modbus.util.SerialParameters@63285eed[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:50:22.737 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@69a084c6[serialParameters=net.wimpi.modbus.util.SerialParameters@63285eed[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@2f5e3d22 -> true
14:50:22.737 [TRACE] [modbus.internal.ModbusTcpSlave:95   ] - Passivating connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@69a084c6[serialParameters=net.wimpi.modbus.util.SerialParameters@63285eed[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:22.737 [TRACE] [o.b.m.internal.BaseModbusSlave:318  ] - ModbusSlave (agsBusMasterHolding): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@69a084c6[serialParameters=net.wimpi.modbus.util.SerialParameters@63285eed[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:22.737 [INFO ] [runtime.busevents             :26   ] - agsBusMasterErrorsTimeout state updated to 3
14:50:22.737 [TRACE] [modbus.internal.ModbusTcpSlave:87   ] - Activated connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@685f3ee5[serialParameters=net.wimpi.modbus.util.SerialParameters@67005b1e[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:22.737 [INFO ] [runtime.busevents             :26   ] - agsBusMasterQueriesToBus state updated to 35763
14:50:22.737 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@685f3ee5[serialParameters=net.wimpi.modbus.util.SerialParameters@67005b1e[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@2f5e3d22 -> true
14:50:22.738 [TRACE] [o.b.m.internal.BaseModbusSlave:291  ] - ModbusSlave (agsBus5): borrowing connection (got net.wimpi.modbus.net.SerialConnection@2f5e3d22) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@685f3ee5[serialParameters=net.wimpi.modbus.util.SerialParameters@67005b1e[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:50:22.738 [INFO ] [runtime.busevents             :26   ] - agsBusMasterSuccessfulTransactions state updated to 51584
14:50:22.738 [INFO ] [runtime.busevents             :26   ] - agsBusMasterErrorsCRC state updated to 69
14:50:22.738 [INFO ] [runtime.busevents             :26   ] - agsBusMasterQueriesToBusMaster state updated to 36605
14:50:22.739 [INFO ] [runtime.busevents             :26   ] - agsBusMasterTimeoutThreshold state updated to 2500
14:50:22.757 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@685f3ee5[serialParameters=net.wimpi.modbus.util.SerialParameters@67005b1e[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@2f5e3d22 -> true
14:50:22.757 [TRACE] [modbus.internal.ModbusTcpSlave:95   ] - Passivating connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@685f3ee5[serialParameters=net.wimpi.modbus.util.SerialParameters@67005b1e[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:22.758 [TRACE] [o.b.m.internal.BaseModbusSlave:318  ] - ModbusSlave (agsBus5): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@685f3ee5[serialParameters=net.wimpi.modbus.util.SerialParameters@67005b1e[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:22.758 [INFO ] [runtime.busevents             :26   ] - IRvorne state updated to CLOSED
14:50:22.758 [TRACE] [modbus.internal.ModbusTcpSlave:87   ] - Activated connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@15a78876[serialParameters=net.wimpi.modbus.util.SerialParameters@3f972ddf[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:22.758 [INFO ] [runtime.busevents             :26   ] - Klingel state updated to CLOSED
14:50:22.758 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@15a78876[serialParameters=net.wimpi.modbus.util.SerialParameters@3f972ddf[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@2f5e3d22 -> true
14:50:22.758 [TRACE] [o.b.m.internal.BaseModbusSlave:291  ] - ModbusSlave (agsBus8): borrowing connection (got net.wimpi.modbus.net.SerialConnection@2f5e3d22) for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@15a78876[serialParameters=net.wimpi.modbus.util.SerialParameters@3f972ddf[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:50:22.759 [INFO ] [runtime.busevents             :26   ] - Stahltuer state updated to OPEN
14:50:22.759 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'Ampel'
14:50:22.763 [INFO ] [runtime.busevents             :22   ] - agsBus7Out5 received command OFF
14:50:22.764 [INFO ] [runtime.busevents             :22   ] - agsBus7Out4 received command OFF
14:50:22.781 [TRACE] [modbus.internal.ModbusTcpSlave:102  ] - Validated endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@15a78876[serialParameters=net.wimpi.modbus.util.SerialParameters@3f972ddf[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@2f5e3d22 -> true
14:50:22.782 [TRACE] [modbus.internal.ModbusTcpSlave:95   ] - Passivating connection net.wimpi.modbus.net.SerialConnection@2f5e3d22 for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@15a78876[serialParameters=net.wimpi.modbus.util.SerialParameters@3f972ddf[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]
14:50:22.782 [TRACE] [o.b.m.internal.BaseModbusSlave:318  ] - ModbusSlave (agsBus8): returned connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@15a78876[serialParameters=net.wimpi.modbus.util.SerialParameters@3f972ddf[portName=/dev/ttyS0,baudRate=38400,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeout=500]]

Ferryb4 · January 28, 2016, 7:18pm

Hi ssalonen,

Here is my trace.

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
2016-01-28 20:16:59.230 [TRACE] [modbus.internal.ModbusTcpSlave] - Activated 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]]
2016-01-28 20:16:59.231 [TRACE] [modbus.internal.ModbusTcpSlave] - Validated 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]] connection net.wimpi.modbus.net.SerialConnection@969773 -> false
2016-01-28 20:16:59.233 [WARN ] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave3): Error getting a new connection 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]]. Error was: Unable to validate object
2016-01-28 20:16:59.234 [TRACE] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave3): borrowing connection (got null) 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]] took 30009 ms
2016-01-28 20:16:59.235 [WARN ] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave3) not connected -- aborting read request net.wimpi.modbus.msg.ReadMultipleRegistersRequest@1bc59e5
2016-01-28 20:16:59.236 [ERROR] [o.b.m.internal.BaseModbusSlave] - ModbusSlave (slave3) error getting response from slave. Invalidating connection
java.lang.NullPointerException: null
	at org.openhab.binding.modbus.internal.BaseModbusSlave.update(BaseModbusSlave.java:348) ~[bundlefile:na]
	at org.openhab.binding.modbus.internal.ModbusBinding.execute(ModbusBinding.java:259) [bundlefile:na]
	at org.openhab.core.binding.AbstractActiveBinding$BindingActiveService.execute(AbstractActiveBinding.java:156) [org.openhab.core_1.8.0.jar:na]
	at org.openhab.core.service.AbstractActiveService$RefreshThread.run(AbstractActiveService.java:173) [org.openhab.core_1.8.0.jar:na]
2016-01-28 20:16:59.239 [TRACE] [modbus.internal.ModbusTcpSlave] - Created connection for endpoint org.openhab.binding.modbus.internal.pooling.ModbusSerialSlaveEndpoint@259797[serialParameters=net.wimpi.modbus.util.SerialParameters@199ae80[portName=/dev/ttyAMA0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=even,encoding=rtu,echo=false,receiveTimeout=500]]

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