Connection pooling in modbus binding

openhab
modbus
binding
Tags: #<Tag:0x00007f6cea366010> #<Tag:0x00007f6cea365cf0> #<Tag:0x00007f6cea3656b0>

(Ssalonen) #200

Checked the code of modbus rtu and indeed the CRC is NOT included in the log message.

Best
Sami


(zelg) #201

having now this config:

serial.slave1.connection=/dev/ttyUSB0:9600:8:none:1:rtu:350:500

item.conf:

Number 	Slave1LDR  					"Lichtmenge [%d]" 			(All) { modbus="slave1:1" }
Number 	Slave1Temp 					"Temperatur [%.1f °C]" 		(All) { channel="modbus:slave1:3" }
Number 	Slave1RH   					"Feuchtigkeit [%d]"  		(All) { channel="modbus:slave1:4" }

i got in my openhab.log this: I tried to trigger the modbus poll over sitemap. but the log doesn't show up any conversation. Is the polling running?

2016-10-31 10:29:20.774 [DEBUG] [inding.modbus.internal.ModbusBinding] - modbusSlave 'slave1' instanciated
2016-10-31 10:29:20.783 [DEBUG] [inding.modbus.internal.ModbusBinding] - Parsed the following slave->endpoint configurations: {slave1=EndpointPoolConfiguration@3ef4c7[passivateBorrowMinMillis=350,interConnectDelayMillis=0,connectMaxTries=3,reconnectAfterMillis=-1,connectTimeoutMillis=0]}. If the endpoint is same, connections are shared between the instances.
2016-10-31 10:29:20.784 [DEBUG] [inding.modbus.internal.ModbusBinding] - Parsed the following pool configurations: {ModbusSerialSlaveEndpoint@84ee61[portName=/dev/ttyUSB0]=EndpointPoolConfiguration@3ef4c7[passivateBorrowMinMillis=350,interConnectDelayMillis=0,connectMaxTries=3,reconnectAfterMillis=-1,connectTimeoutMillis=0]}
2016-10-31 10:29:20.785 [DEBUG] [inding.modbus.internal.ModbusBinding] - config looked good
2016-10-31 10:29:20.788 [INFO ] [b.core.service.AbstractActiveService] - Modbus Polling Service has been started
2016-10-31 10:33:17.127 [DEBUG] [inding.modbus.internal.ModbusBinding] - modbusSlave 'slave1' instanciated
2016-10-31 10:33:17.132 [DEBUG] [inding.modbus.internal.ModbusBinding] - Parsed the following slave->endpoint configurations: {slave1=EndpointPoolConfiguration@838bcc[passivateBorrowMinMillis=350,interConnectDelayMillis=0,connectMaxTries=3,reconnectAfterMillis=-1,connectTimeoutMillis=0]}. If the endpoint is same, connections are shared between the instances.
2016-10-31 10:33:17.135 [DEBUG] [inding.modbus.internal.ModbusBinding] - Parsed the following pool configurations: {ModbusSerialSlaveEndpoint@11edc97[portName=/dev/ttyUSB0]=EndpointPoolConfiguration@838bcc[passivateBorrowMinMillis=350,interConnectDelayMillis=0,connectMaxTries=3,reconnectAfterMillis=-1,connectTimeoutMillis=0]}
2016-10-31 10:33:17.137 [DEBUG] [inding.modbus.internal.ModbusBinding] - config looked good
2016-10-31 10:35:10.422 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Slave1Temp' for widget org.eclipse.smarthome.model.sitemap.Text
2016-10-31 10:35:10.429 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Text
2016-10-31 10:35:10.431 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Text
2016-10-31 10:35:10.433 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Slave1Temp' for widget org.eclipse.smarthome.model.sitemap.Text
2016-10-31 10:35:10.438 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Slave1Temp' for widget org.eclipse.smarthome.model.sitemap.Text
2016-10-31 10:35:10.443 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Slave1RH' for widget org.eclipse.smarthome.model.sitemap.Text

and later the missing EOF starts again (:350:500):

2016-10-31 11:29:44.797 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - Last request: 01 03 00 00 00 05 85 c9
2016-10-31 11:29:44.798 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - failed to read: Error reading response (EOF)
2016-10-31 11:29:44.800 [ERROR] [pi.modbus.io.ModbusSerialTransaction] - execute try 3/3 error: I/O exception - failed to read. Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@ea61c (unit id 1 & transaction 2774). Serial parameters: SerialParameters@8eb2d3[portName=/dev/ttyUSB0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeoutMillis=500]
2016-10-31 11:29:44.801 [ERROR] [pi.modbus.io.ModbusSerialTransaction] - execute reached max tries 3, throwing last error: I/O exception - failed to read. Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@ea61c. Serial parameters: SerialParameters@8eb2d3[portName=/dev/ttyUSB0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeoutMillis=500]
2016-10-31 11:29:44.803 [ERROR] [.binding.modbus.internal.ModbusSlave] - ModbusSlave (slave1): Error getting modbus data for request net.wimpi.modbus.msg.ReadMultipleRegistersRequest@ea61c. Error: I/O exception - failed to read. Endpoint ModbusSerialSlaveEndpoint@349618[portName=/dev/ttyUSB0]. Connection: SerialConnection@963c65[portName=/dev/ttyUSB0,port=/dev/ttyUSB0]

(zelg) #202

serial.slave1.connection=/dev/ttyUSB0:9600:8:none:1:rtu:350:1500

still reading issues:

2016-10-31 11:48:55.507 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - Last request: 01 03 00 00 00 05 85 c9
2016-10-31 11:48:55.508 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - failed to read: CRC Error in received frame: 12 bytes: 01 03 0a 00 00 00 00 00 08 70 13 d8 
2016-10-31 11:48:55.509 [ERROR] [pi.modbus.io.ModbusSerialTransaction] - execute try 1/3 error: I/O exception - failed to read. Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@104586d (unit id 1 & transaction 123). Serial parameters: SerialParameters@11a356[portName=/dev/ttyUSB0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeoutMillis=1500]

and with 500:2500 openhab.log loocks like after a restart (remakr 13min timout bevore EOF issues rises!):

2016-10-31 12:11:23.319 [DEBUG] [ding.modbus.internal.ModbusActivator] - Modbus binding has been started.
2016-10-31 12:11:23.345 [DEBUG] [org.openhab.binding.modbus          ] - ServiceEvent REGISTERED - {org.openhab.model.item.binding.BindingConfigReader, org.openhab.binding.modbus.ModbusBindingProvider}={component.name=org.openhab.binding.modbus.genericbindingprovider, component.id=183, service.id=314, service.bundleid=200, service.scope=bundle} - org.openhab.binding.modbus
2016-10-31 12:11:23.349 [DEBUG] [org.openhab.binding.modbus          ] - ServiceEvent REGISTERED - {org.osgi.service.cm.ManagedService, org.osgi.service.event.EventHandler}={event.topics=openhab/*, service.pid=org.openhab.modbus, component.name=org.openhab.binding.modbus, component.id=182, service.id=316, service.bundleid=200, service.scope=bundle} - org.openhab.binding.modbus
2016-10-31 12:11:23.407 [DEBUG] [org.openhab.binding.modbus          ] - BundleEvent STARTED - org.openhab.binding.modbus
2016-10-31 12:11:23.503 [DEBUG] [inding.modbus.internal.ModbusBinding] - modbusSlave 'slave1' instanciated
2016-10-31 12:11:23.583 [DEBUG] [inding.modbus.internal.ModbusBinding] - Parsed the following slave->endpoint configurations: {slave1=EndpointPoolConfiguration@1a22d36[passivateBorrowMinMillis=500,interConnectDelayMillis=0,connectMaxTries=3,reconnectAfterMillis=-1,connectTimeoutMillis=0]}. If the endpoint is same, connections are shared between the instances.
2016-10-31 12:11:23.584 [DEBUG] [inding.modbus.internal.ModbusBinding] - Parsed the following pool configurations: {ModbusSerialSlaveEndpoint@156fb8a[portName=/dev/ttyUSB0]=EndpointPoolConfiguration@1a22d36[passivateBorrowMinMillis=500,interConnectDelayMillis=0,connectMaxTries=3,reconnectAfterMillis=-1,connectTimeoutMillis=0]}
2016-10-31 12:11:23.586 [DEBUG] [inding.modbus.internal.ModbusBinding] - config looked good
2016-10-31 12:11:23.588 [INFO ] [b.core.service.AbstractActiveService] - Modbus Polling Service has been started
2016-10-31 12:11:24.990 [ERROR] [platform.linux.LinuxCentralProcessor] - Couldn't find physical processor count. Assuming 1.
2016-10-31 12:11:25.418 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro DailyJob at midnight for thing astro:sun:local
2016-10-31 12:11:25.438 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro DailyJob at midnight for thing astro:moon:local
2016-10-31 12:11:25.440 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro PositionalJob with interval of 300 seconds for thing astro:sun:local
2016-10-31 12:11:25.444 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro PositionalJob with interval of 300 seconds for thing astro:moon:local
2016-10-31 12:11:26.045 [ERROR] [platform.linux.LinuxCentralProcessor] - Unable to parse /proc/76/stat
2016-10-31 12:26:17.409 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - Last request: 01 03 00 00 00 05 85 c9
2016-10-31 12:26:17.410 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - failed to read: Error reading response (EOF)
2016-10-31 12:26:17.412 [ERROR] [pi.modbus.io.ModbusSerialTransaction] - execute try 1/3 error: I/O exception - failed to read. Request: net.wimpi.modbus.msg.ReadMultipleRegistersRequest@1e1eff5 (unit id 1 & transaction 856). Serial parameters: SerialParameters@488384[portName=/dev/ttyUSB0,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeoutMillis=2500]
2016-10-31 12:26:20.428 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - Last request: 01 03 00 00 00 05 85 c9
2016-10-31 12:26:20.430 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - failed to read: Error reading response (EOF)

(Ssalonen) #203

Did you notice the errors related to sitemap (ItemUIRegistryImpl)? I think that might be unrelated to the modbus IO issues..

Unfortunately I'm not too familiar with openhab2 to comment those.

I also noticed you have varying way of configuring the binding in the items (channel and modbus parameter)

I'm running out of advice to workaround the EOF issue. If the serial parameters (e.g. Baud or Stop bit) would be off, I would expect it to fail much more, not after 15min. I noticed that you cut the logs before all retries have been tried out, did it work eventually?

Oh one more thing, could please provide the full details about the modbus configuration, really hard to debug with limited information. I was wondering how many registers you are now reading and whether the read timeout is sufficient...

From the technical perspective I'm not sure what the binding should do as the EOF comes from the serial library bundled by openhab (nrjavaserial I believe). I hope it is the same library in openhab2, but not sure.

Best
Sami


(zelg) #204

After hours of reading log-files, this is what's running:

items: on top of the file... yes... yeah!

Number 	Slave1LDR  					"Lichtmenge [%d]" 			{ modbus="slave1:0" }
Number 	Slave1Temp 					"Temperatur [%.1f °C]" 		{ modbus="slave1:1" }
Number 	Slave1RH   					"Feuchtigkeit [%d]"  		{ modbus="slave1:2" }

service:

poll=3000
serial.slave1.connection=/dev/ttyUSB0:19200:8:none:1:rtu
serial.slave1.id=1
serial.slave1.start=0
serial.slave1.length=5
serial.slave1.type=holding
serial.slave1.valuetype=int16

Thanks for any help. I will finally start over with feature implementation...


(Ssalonen) #205

For future records,

I believe the issue was that the default read timeout (1.5s) might have been too little for 9600 baud. Since you increased the baud rate, it was sufficient after all. Let's see if this issue occurs again and if the default need changing. Actually, with little arithmetic we could probably calculate the time it might take to send a single modbus frame in total.


(NickMa) #206

Concerning different baud-rates for the same modbus serial line, mentioned from @carzten2000 (see above) and the fact that

I think it would be helpfull to mention the fact, that it's kind of 'bad practice', in the binding description (wiki, openhab.cfg, ..?). Additionally an error during config-parsing would be nice.
Is there already an information somewhere, am I missing something?
Best


(Rossko57) #207

That is general information for any Modbus serial device, most likely mentioned in the device's documentation and also in general guides to Modbus.


(NickMa) #208

So is history education and yet you know nothing John Snow. :slight_smile:

There is a hint in the wiki which says "Please note that the binding requires that all slaves connecting to the same serial port share the same connection parameters. For additional information, see this discussion in the community forums". But to get there you have to ensure that everything is correct with your modbus connection itself and the set-up parameters, to finally turn on trace level debugging and find out that there's an issue with the baudrate.

a) Error message during config parsing
b) a little more information in the wiki


(Ssalonen) #209

Hi

I believe error message is logged with WARN level. Not a critical error and thus the binding continues (later configurations override previous ones)

Feel free to improve the wiki please, contributions are more than welcome!

Best
Sami

EDIT: correction: WARN is logged only if the retry count / delay between connections is different. The 1.9.0 binding does not re-estabilish / initiate the connection parameters; first time the stop bits etc. have been setup for serial device/serial port, they remain unchanged. So in a way the first poll inits the devices.


(Andrew) #210

Hi

I've recently restored my old modbus setup which was successfully working with OH1.8
Currently I have only 2 devices - SDM120 meter and WP8027ADAM (16x Digital Out).
After reading all the discussions I've played a bit with the timers but still have occasional errors in the log.
Will appreciate all the recommendations.

Here is my modbus.cfg:

poll=1000
serial.slave1.connection=/dev/ttyUSB1:9600:8:none:1:rtu:100:5000
serial.slave1.id=1
serial.slave1.start=0
serial.slave1.length=2
serial.slave1.type=input
serial.slave1.valuetype=float32

serial.slave2.connection=/dev/ttyUSB1:9600:8:none:1:rtu:100:5000
serial.slave2.id=1
serial.slave2.start=6
serial.slave2.length=2
serial.slave2.type=input
serial.slave2.valuetype=float32

serial.slave3.connection=/dev/ttyUSB1:9600:8:none:1:rtu:100:5000
serial.slave3.id=1
serial.slave3.start=12
serial.slave3.length=2
serial.slave3.type=input
serial.slave3.valuetype=float32

serial.slave20.connection=/dev/ttyUSB1:9600:8:none:1:rtu
serial.slave20.id=2
serial.slave20.start=0
serial.slave20.length=4
serial.slave20.type=coil

And here is the log:

2017-04-08 11:38:41.404 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - Last request: 01 04 00 06 00 02 91 ca
2017-04-08 11:38:41.405 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - failed to read: Error reading response (EOF)
2017-04-08 11:38:41.410 [ERROR] [pi.modbus.io.ModbusSerialTransaction] - execute try 1/3 error: I/O exception - failed to read. Request: net.wimpi.modbus.msg.ReadInputRegistersRequest@3564c11b (unit id 1 & transaction 6612). Serial parameters: SerialParameters@7d8473ea[portName=/dev/ttyUSB1,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeoutMillis=5000]
2017-04-08 11:38:41.569 [INFO ] [pi.modbus.io.ModbusSerialTransaction] - execute eventually succeeded with 1 re-tries. Request: net.wimpi.modbus.msg.ReadInputRegistersRequest@3564c11b. Serial parameters: SerialParameters@7d8473ea[portName=/dev/ttyUSB1,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeoutMillis=5000]

(Ssalonen) #211

Hi!

First of all note this comment on docs

Please note that the binding requires that all slaves connecting to the same serial port share the same connection parameters (e.g. baud-rate, parity, ..). In particular are different parameter settings considered bad practice, because they can confuse the instances (slaves) on the modbus. For additional information, see this discussion in the community forums.

Currently one of "slaves" have different connection parameters.

Also this might be useful for you (from docs)

Most important of these is the interTransactionDelayMillis which ensures that Modbus RTU (serial) has enough “silent time” between the transactions, as required by the Modbus/RTU protocol. Furthermore it ensures that modbus slave (applies to both tcp and serial slaves) is not spammed with too many transactions, for example some PLC devices might not be able to handle many requests coming in a short time window.

You might want to try out to change that parameter.

Please also note that it eventually succeeded with the read. Do you have cases where it cannot read even after retries?

Best
Sami


(Andrew) #212

Noted and fixed already.

Yes, I noticed that as well from the previous discussion.
I'm testing now with 350 instead of 100 but wandering what would be the best range for either value to test within?

It was probably the case initially when I started with default parameters. I don't see this anymore.

Thanks!


(Ssalonen) #213

350ms sounds like a conservative upper bound. I would say values over 1000ms make no sense.

Best
Sami


(Andrew) #214

I've made some test over weekend and it seems that "350:3000" will be the safe choice.
I'm curious how it was working in OH1 without adjustments.
Thanks, Sami!


(Ssalonen) #215

The underlying serial library used by openHAB (by all the bindings communicating with serial devices) has received update some time ago, perhaps that is the reason.

Good thing it works for you.

Best
Sami


(Andrew) #216

I've tried to read 4 registers at once instead of 2 - same EOF errors every 1-2 hours :frowning:


(Ssalonen) #217

But does it work after the automatic retry?

Best
Sami


(Andrew) #218

Yes, it works after retry:

2017-04-12 11:17:10.826 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - Last request: 01 04 00 0c 00 02 b1 c8
2017-04-12 11:17:10.826 [ERROR] [t.wimpi.modbus.io.ModbusRTUTransport] - failed to read: Error reading response (EOF)
2017-04-12 11:17:10.829 [ERROR] [pi.modbus.io.ModbusSerialTransaction] - execute try 1/3 error: I/O exception - failed to read. Requ
est: net.wimpi.modbus.msg.ReadInputRegistersRequest@5f2ce543 (unit id 1 & transaction 1741). Serial parameters: SerialParameters@534
0aaa0[portName=/dev/ttyUSB1,baudRate=9600,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo
=false,receiveTimeoutMillis=3000]
2017-04-12 11:17:11.232 [INFO ] [pi.modbus.io.ModbusSerialTransaction] - execute eventually succeeded with 1 re-tries. Request: net.
wimpi.modbus.msg.ReadInputRegistersRequest@5f2ce543. Serial parameters: SerialParameters@5340aaa0[portName=/dev/ttyUSB1,baudRate=960
0,flowControlIn=none,flowControlOut=none,databits=8,stopbits=1,parity=none,encoding=rtu,echo=false,receiveTimeoutMillis=3000]


(Rossko57) #219

It could be noise on your serial line, maybe not helped by poor termination or pullups etc.