Connection pooling in modbus binding

ssalonen · December 21, 2015, 9:24am

Hi everyone,

I have been investigating how to implement connection pooling in the modbus binding. In my case I have PLC that can accept only single connection at a time. This is really problematic with the binding since currently I need to configure several modbus slaves in order to read different data types, for example:


modbus:tcp.slave1reals.connection=192.168.1.100:502
modbus:tcp.slave1reals.id=1
modbus:tcp.slave1reals.type=holding
modbus:tcp.slave1reals.start=1
modbus:tcp.slave1reals.length=6
modbus:tcp.slave1reals.valuetype=float32

modbus:tcp.slave1modes.connection=192.168.1.100:502
modbus:tcp.slave1modes.id=1
modbus:tcp.slave1modes.type=holding
modbus:tcp.slave1modes.start=6
modbus:tcp.slave1modes.length=1
modbus:tcp.slave1modes.valuetype=bit

Ideally, I would like to see single connection to be established to 192.168.1.100:502. Actually this is recommended by MODBUS messaging on TCP/IP implementation guide, p. 15:

It is recommended for a MODBUS Client to open a minimum of TCP connections with a remote
MODBUS server (with the same IP address). One connection per application could be a good choice.

I’m thinking of refactoring Connection creation from the Slaves using a connection factory. For TCP connections, the same connection would be returned if the InetAddress and port is same. Similarly InetAddress and SerialParamters would be used for UDP connections and serial connections, respectively.

It might not be needed even to lock access to the connection (at least in TCP/UDP?), not sure yet. If locking is needed, synchronized(connection) scopes in getModbusData and executeCommand should ensure that single write/read operation is going on at the same. This kind locking is not strictly necessary for TCP (that’s why there transaction ids), see modbus.org MODBUS messaging on TCP/IP implementation guide, p. 15:

Several MODBUS transactions can be activated simultaneously on the same TCP Connection.
Remark: If this is done then the MODBUS transaction identifier must be used to uniquely identify the
matching requests and responses.

Currently I have been working with simple fixes to connection closing in my pull request #3512. Furthermore, I’ve been starting to make tests, in a separate branch modbus-binding-tests, for detection regression and bugs.

So developers out there, does this seem like a reasonable path to take?

Best,
ssalonen

P.S. I’ve beeen investigating how would it turn out if the registers and types (e.g. “holding”) are defined in the items instead of the openhab.cfg. The proof-of-concept looks promising (connections are re-used) but that kind of change might mean breaking backwards compatibility or complicated branching if we keep to the backwards compatibility. Furthermore, there are some issues like amount of requests made (one request per each item).

rossko57 · December 21, 2015, 10:37pm

I know nothing of the binding nuts and bolts, but this sounds like it would go a way towards addressing reported problems with serial networks, apparently rooted in not fully observing the query-response Modbus rules. I guess the unique path for serial that needs queuing would be the COM port or equivalent.

ssalonen · December 29, 2015, 7:30am

Thanks! Yeah actually good point about serial connections, the com port is only criteria for “pooling” the connection. Serial parameters should not affect the pooling, instead the connection needs to be configured with the correct parameters before each query.

More about the related configuration change experimentation:

I have been also experimenting with the idea of separating modbus connection configuration from item configuration. This relates to the connection pooling somewhat. I think it would be useful to define the connections in openhab.cfg, i.e.

ip address & port or serial params and serial encoding

The items could then define

the valuetype, e.g. float32
modbus function code to use (holding/coil etc)
register/coil address

This way the connection can be specified only once and all the items would use the same connection.

I can think of following pros & cons:

single slave definition = physical slave. In the current implementation, one needs to define as many modbus slaves as you have valuetypes and types. For example, if one is reading float32 & int16 input registers, discrete inputs and float32 holding registers, 4 modbus slaves need to be define (each havings its own valuetype and type)
would allow configuration specific to items. E.g. whether to write floats are rounded integers, but read them as float32.

when polling data from slaves, naive implementation make as many requests to the modbus server as there are items. The current implementation is effective as it reads consecutive registers (e.g. registers between 0-50) using a single request.
configuration change is backwards incompatible. However, we could support both the old and new way of configuring (if slave has length configured, it would use the old way; otherwise the new way. If using new way, items could define the rest of the modbus query parameters)

mbs38 · January 2, 2016, 3:14pm

Yes and no. It should be configurable. Some (smaller) TCP Modbus devices have problems with more than X requests or are only able to handle one request at a time (similiar to serial modbus…). We should implement a configuration option that forces the serialization of all requests to insure that these devices don’t get overloaded.

This would also make things very convenient from a user’s perspective. Usually one needs to set the right baudrate on each Modbus slave device so that every device on the bus uses the same baudrate. If we could change the baudrate, whenever necessary, there would be no need to set all slaves to a certain baudrate. Of course it’s not the best way to go (it’s a hack!) but it usualy works and it will work on small networks.

This is a very important point. On RS485 Modbus networks the performance can go from good to completely useless if you make a single request for each register/coil/discrete.

ssalonen · January 2, 2016, 5:15pm

Hi and thanks for the comments!

@mbs38: do you think we need two ways of operation, “serialized” and “non-serialized”, or is simply serialized enough?

Can you explain more why you consider the different baudrates a hack? Were you referring that it’s a bit theoretical that different baud rate are used in the same serial port? I think you quite right on that.

Good point about the perfomance loss on serial lines. I think it’s best to implement the pooling on top of current way of slave configuration, and not introduce any new “Item specific” configuration.

mbs38 · January 4, 2016, 2:10pm

Hi ssalonen,
“serialized” is mandatory for serial (RS485 & RS232, single and multiple slaves) and it doesn’t decrease performance in TCP operation. But the latter only applies if there is only one TCP slave. Multiple TCP slaves can and should be triggered simultaneously; thus improving the overall performance significantly (slow slaves can respond slowly, fast slaves can respond quickly if we serialize this we are actually crippling the performance of modbus TCP).
Therefore my recommendation: always serialize request in serial mode, optionally serialize requests in TCP mode.

Operation with different baudrates on a single serial line is not really in the modbus spec. It is also a bit unsafe. 16bit CRC is not very safe and a slave might misinterpret requests for other slaves at a different baudrate and do potentially dangerous things. Although I do think that this is rather theoretical, it mitght be useful in some situations. If it comes for free while solving other issues: go for it. If it takes a lot of extra work just don’t do it.

[quote=“ssalonen, post:5, topic:5246”]
I think it’s best to implement the pooling on top of current way of slave configuration, and not introduce any new “Item specific” configuration.
[/quote]

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]]