It works! My productive system now achieves 1732 updates a minute in non-debug mode. Just for the record the configuration I’m using now is:
modbus:poll=5
And like this for 13 different slave IDs:
modbus:serial.someSlave.connection=/dev/ttyS0:38400:8:none:1:rtu:280:3
No errors, just literally thousands of state updates 
I haven’t tried debug mode yet.
Just wanted to let you know as quickly as possible. Great work. Thanks a lot!
Best regards,
Max
Oh this is so great to hear!!
Keep me posted how it works out. Also, if you test writing commands as well, I would appreciate it very much.
I think I’m going to change the order of readTimeout (e.g. 280) and inter transaction delay (e.g. 3ms) to allow overriding the most typical parameters. What do you think should be the default for inter transaction delay, probably we want something that works for most of the users out-of-the-box. We can always document in the wiki “tuning tips” for the high-performance users like you. How about 50ms?
@YMedox @Ferryb4 Do you mind testing the v6 version also?
I would like to have modbus TCP tested as well by multiple people before starting to prepare for the pull request to official modbus binding.
Hi ssalonen,
I have no errors or issues.
I did a poll of 1000 with 16 slaves
It seems that all problems are solved.
Great work
I’m running 1.81 and it doesn’t seem to poll devices. It was running fine under the 1.8.0 Snapshot.
I only added the :100 to the end of each line. It defines the items then it instances slave1 then stops doing anything else with modbus
#modbus:poll=1000
modbus:poll=5
modbus:tcp.slave1.connection=192.168.1.200:502:rtu:100
modbus:tcp.slave1.type=holding
modbus:tcp.slave1.start=39
modbus:tcp.slave1.length=1
#modbus:tcp.slave1.valuetype=uint16
#ADAM 6060 12-Channel Digital I/O Module
modbus:tcp.slave2.connection=192.168.1.106:502:100
modbus:tcp.slave2.type=coil
modbus:tcp.slave2.start=16
modbus:tcp.slave2.length=6
modbus:tcp.slave2.valuetype=bit
modbus:tcp.slave3.connection=192.168.1.106:502:100
modbus:tcp.slave3.type=discrete
modbus:tcp.slave3.start=0
modbus:tcp.slave3.length=5
modbus:tcp.slave3.valuetype=bit
modbus:tcp.slave5.connection=192.168.1.106:502:100
modbus:tcp.slave5.type=input
modbus:tcp.slave5.start=10
modbus:tcp.slave5.length=2
modbus:tcp.slave5.valuetype=float32
#ADAM 6024 12-Channel Universal I/O Module
modbus:tcp.slave4.connection=192.168.1.105:502:100
modbus:tcp.slave4.type=input
modbus:tcp.slave4.start=0
modbus:tcp.slave4.length=6
#Watlow F4
modbus:tcp.slave6.connection=192.168.1.104:502:100
modbus:tcp.slave6.type=input
modbus:tcp.slave6.start=100
modbus:tcp.slave6.length=16
modbus:tcp.slave7.connection=192.168.1.104:502:100
modbus:tcp.slave7.type=input
modbus:tcp.slave7.start=200
modbus:tcp.slave7.length=64
modbus:tcp.slave8.connection=192.168.1.104:502:100
modbus:tcp.slave8.type=holding
modbus:tcp.slave8.start=300
modbus:tcp.slave8.length=64
modbus:tcp.slave9.connection=192.168.1.104:502:100
modbus:tcp.slave9.type=holding
modbus:tcp.slave9.start=2000
modbus:tcp.slave9.length=63
#Motor Control
modbus:tcp.slave10.connection=192.168.1.104:502:100
modbus:tcp.slave10.id=2
modbus:tcp.slave10.type=holding
modbus:tcp.slave10.start=0
modbus:tcp.slave10.length=25
Thanks @LeXLuther422. OK, so something to fix still!
Can you paste your run with TRACE level logs
<logger name="net.wimpi.modbus" level="TRACE" />
<logger name="org.openhab.binding.modbus" level="TRACE" />
Thank you.
it the logback_debug.xml I have them set to trace.
Launching the openHAB runtime...
Listening for transport dt_socket at address: 8001
osgi> 10:49:55.543 [DEBUG] [.s.internal.SchedulerActivator:36 ] - Scheduler has been started.
10:49:55.590 [INFO ] [uartz.impl.StdSchedulerFactory:1175 ] - Using default implementation for ThreadExecutor
10:49:55.621 [INFO ] [rtz.core.SchedulerSignalerImpl:61 ] - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
10:49:55.621 [INFO ] [rg.quartz.core.QuartzScheduler:243 ] - Quartz Scheduler v.2.1.7 created.
10:49:55.621 [INFO ] [org.quartz.simpl.RAMJobStore :154 ] - RAMJobStore initialized.
10:49:55.621 [INFO ] [rg.quartz.core.QuartzScheduler:268 ] - Scheduler meta-data: Quartz Scheduler (v2.1.7) 'openHAB-job-scheduler' with instanceId 'NON_CLUSTERED'
Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
NOT STARTED.
Currently in standby mode.
Number of jobs executed: 0
Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 2 threads.
Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.
10:49:55.621 [INFO ] [uartz.impl.StdSchedulerFactory:1324 ] - Quartz scheduler 'openHAB-job-scheduler' initialized from specified file: './etc/quartz.properties'
10:49:55.621 [INFO ] [uartz.impl.StdSchedulerFactory:1328 ] - Quartz scheduler version: 2.1.7
10:49:55.621 [INFO ] [rg.quartz.core.QuartzScheduler:534 ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.
10:49:55.621 [DEBUG] [o.config.core.ConfigDispatcher:146 ] - Processing openHAB default configuration file 'C:\OpenHAB\configurations\openhab_default.cfg'.
10:49:55.668 [DEBUG] [o.config.core.ConfigDispatcher:168 ] - Processing openHAB main configuration file 'C:\OpenHAB\configurations\openhab.cfg'.
10:49:55.699 [DEBUG] [.o.core.internal.CoreActivator:93 ] - UUID file already exists at 'C:\OpenHAB\webapps\static\uuid' with content '02d9bcdf-6869-48f3-93a3-c8b7cb27f07e'
10:49:55.699 [DEBUG] [.o.core.internal.CoreActivator:115 ] - Created file 'C:\OpenHAB\webapps\static\version' with content '1.8.1'
10:49:55.699 [INFO ] [.o.core.internal.CoreActivator:61 ] - openHAB runtime has been started (v1.8.1).
10:49:55.730 [DEBUG] [a.internal.AutoUpdateActivator:31 ] - AutoUpdate binding has been started.
10:49:56.855 [DEBUG] [.p.i.PersistenceModelActivator:23 ] - Registered 'persistence' configuration parser
10:49:56.871 [DEBUG] [.c.t.i.TransformationActivator:38 ] - Transformation Service has been started.
10:49:56.902 [DEBUG] [m.internal.MultimediaActivator:34 ] - Multimedia I/O bundle has been started.
10:49:56.918 [DEBUG] [.s.i.DiscoveryServiceActivator:27 ] - Discovery service has been started.
10:49:56.918 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl:93 ] - mDNS service has been started
10:49:56.949 [DEBUG] [.io.transport.mqtt.MqttService:123 ] - Starting MQTT Service...
10:49:57.043 [DEBUG] [.i.internal.ItemModelActivator:24 ] - Registered 'item' configuration parser
10:49:57.184 [DEBUG] [o.o.c.i.items.ItemRegistryImpl:137 ] - Item provider 'GenericItemProvider' has been added.
10:49:57.574 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl:53 ] - Service Discovery initialization completed.
10:49:57.746 [INFO ] [.io.transport.mqtt.MqttService:108 ] - MQTT Service initialization completed.
10:49:57.746 [INFO ] [o.i.t.m.i.MqttBrokerConnection:114 ] - Starting MQTT broker connection 'xtralight'
10:49:57.746 [DEBUG] [o.i.t.m.i.MqttBrokerConnection:294 ] - Creating new client for 'tcp://localhost:1883' using id 'OpenHAB' and file store 'C:\DOCUME~1\DAVID~1.LUT\LOCALS~1\Tem
p\1\/xtralight'
10:49:57.965 [DEBUG] [.o.m.s.i.SitemapModelActivator:23 ] - Registered 'sitemap' configuration parser
10:49:58.043 [DEBUG] [io.rest.internal.RESTActivator:33 ] - REST API has been started.
10:49:58.106 [INFO ] [org.atmosphere.util.IOUtils :370 ] - META-INF/services/org.atmosphere.cpr.AtmosphereFramework not found in class loader
10:49:58.137 [INFO ] [sphere.cpr.AtmosphereFramework:2601 ] - Atmosphere is using org.atmosphere.cpr.DefaultAnnotationProcessor for processing annotation
10:49:58.137 [INFO ] [cpr.DefaultAnnotationProcessor:138 ] - AnnotationProcessor class org.atmosphere.cpr.DefaultAnnotationProcessor$BytecodeBasedAnnotationProcessor being used
10:49:58.168 [WARN ] [cpr.DefaultAnnotationProcessor:178 ] - Unable to detect annotations. Application may fail to deploy.
10:49:58.184 [INFO ] [sphere.cpr.AtmosphereFramework:1891 ] - Auto detecting atmosphere handlers /WEB-INF/classes/
10:49:58.199 [INFO ] [sphere.cpr.AtmosphereFramework:639 ] - Installed AtmosphereHandler org.atmosphere.handler.ReflectorServletProcessor mapped to context-path /* and Broadcaster
Class org.atmosphere.jersey.JerseyBroadcaster
10:49:58.199 [INFO ] [sphere.cpr.AtmosphereFramework:1945 ] - Auto detecting WebSocketHandler in /WEB-INF/classes/
10:49:58.199 [INFO ] [sphere.cpr.AtmosphereFramework:1602 ] - Installed WebSocketProtocol org.atmosphere.websocket.protocol.SimpleHttpProtocol
10:49:58.231 [INFO ] [.a.h.ReflectorServletProcessor:103 ] - Installing Servlet com.sun.jersey.spi.container.servlet.ServletContainer
10:49:58.356 [INFO ] [c.s.j.s.i.a.WebApplicationImpl:815 ] - Initiating Jersey application, version 'Jersey: 1.18.1 02/19/2014 03:28 AM'
10:49:58.356 [INFO ] [c.s.j.s.i.a.WebApplicationImpl:826 ] - Adding the following classes declared in META-INF/services/jersey-server-components to the resource configuration:
class org.atmosphere.jersey.AtmosphereResourceConfigurator
10:49:58.418 [INFO ] [j.s.i.a.DeferredResourceConfig:101 ] - Instantiated the Application class org.openhab.io.rest.RESTApplication
10:49:59.293 [INFO ] [sphere.cpr.AtmosphereFramework:2435 ] - AtmosphereInterceptor CORS Interceptor Support will always be executed first
10:49:59.293 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor CORS Interceptor Support with priority FIRST_BEFORE_DEFAULT
10:49:59.293 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Default Response's Headers Interceptor with priority AFTER_DEFAULT
10:49:59.293 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Android Interceptor Support with priority AFTER_DEFAULT
10:49:59.293 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor SSE Interceptor Support with priority AFTER_DEFAULT
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor JSONP Interceptor Support with priority AFTER_DEFAULT
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Atmosphere JavaScript Protocol with priority AFTER_DEFAULT
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Browser disconnection detection with priority AFTER_DEFAULT
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:935 ] - Using EndpointMapper class org.atmosphere.util.DefaultEndpointMapper
10:49:59.309 [WARN ] [sphere.cpr.AtmosphereFramework:941 ] - No BroadcasterCache configured. Broadcasted message between client reconnection will be LOST. It is recommended to con
figure the org.atmosphere.cache.UUIDBroadcasterCache
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:949 ] - Default Broadcaster Class: org.atmosphere.jersey.JerseyBroadcaster
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:950 ] - Broadcaster Polling Wait Time 100
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:951 ] - Shared ExecutorService supported: true
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:958 ] - Messaging Thread Pool Size: 10
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:968 ] - Async I/O Thread Pool Size: 10
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:979 ] - Using BroadcasterFactory: org.atmosphere.cpr.DefaultBroadcasterFactory
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:980 ] - Using WebSocketProcessor: org.atmosphere.websocket.DefaultWebSocketProcessor
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:990 ] - Invoke AtmosphereInterceptor on WebSocket message true
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:991 ] - HttpSession supported: false
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:993 ] - Atmosphere is using DefaultAtmosphereObjectFactory for dependency injection and object creation
10:49:59.324 [INFO ] [sphere.cpr.AtmosphereFramework:994 ] - Atmosphere is using async support: org.atmosphere.container.JettyAsyncSupportWithWebSocket running under container: je
tty/8.1.3.v20120522 with WebSocket enabled.
10:49:59.324 [INFO ] [sphere.cpr.AtmosphereFramework:996 ] - Atmosphere Framework 2.2.5 started.
10:49:59.324 [INFO ] [sphere.cpr.AtmosphereFramework:998 ] -
For Atmosphere Framework Commercial Support, visit
http://www.async-io.org/ or send an email to support@async-io.org
10:49:59.324 [INFO ] [penhab.io.rest.RESTApplication:144 ] - Started REST API at /rest
10:49:59.324 [DEBUG] [o.o.i.s.i.DiscoveryServiceImpl:66 ] - Registering new service _openhab-server._tcp.local. at port 8080
10:49:59.340 [ERROR] [.io.transport.mqtt.MqttService:114 ] - Error starting broker connection
org.eclipse.paho.client.mqttv3.MqttException: Unable to connect to server
at org.eclipse.paho.client.mqttv3.internal.TCPNetworkModule.start(TCPNetworkModule.java:75) ~[na:na]
at org.eclipse.paho.client.mqttv3.internal.ClientComms$ConnectBG.run(ClientComms.java:538) ~[na:na]
at java.lang.Thread.run(Unknown Source) ~[na:1.8.0_66]
Caused by: java.net.ConnectException: Connection refused: connect
at java.net.TwoStacksPlainSocketImpl.socketConnect(Native Method) ~[na:1.8.0_66]
at java.net.AbstractPlainSocketImpl.doConnect(Unknown Source) ~[na:1.8.0_66]
at java.net.AbstractPlainSocketImpl.connectToAddress(Unknown Source) ~[na:1.8.0_66]
at java.net.AbstractPlainSocketImpl.connect(Unknown Source) ~[na:1.8.0_66]
at java.net.PlainSocketImpl.connect(Unknown Source) ~[na:1.8.0_66]
at java.net.SocksSocketImpl.connect(Unknown Source) ~[na:1.8.0_66]
at java.net.Socket.connect(Unknown Source) ~[na:1.8.0_66]
at org.eclipse.paho.client.mqttv3.internal.TCPNetworkModule.start(TCPNetworkModule.java:66) ~[na:na]
... 2 common frames omitted
10:50:05.231 [DEBUG] [o.o.i.s.i.DiscoveryServiceImpl:66 ] - Registering new service _openhab-server-ssl._tcp.local. at port 8443
10:50:06.575 [INFO ] [c.internal.ModelRepositoryImpl:80 ] - Loading model 'atal.sitemap'
10:50:06.825 [INFO ] [c.internal.ModelRepositoryImpl:80 ] - Loading model 'default.sitemap'
10:50:06.872 [INFO ] [c.internal.ModelRepositoryImpl:80 ] - Loading model 'db4o.persist'
10:50:06.903 [INFO ] [c.internal.ModelRepositoryImpl:80 ] - Loading model 'exec.persist'
10:50:06.903 [INFO ] [c.internal.ModelRepositoryImpl:80 ] - Loading model 'logging.persist'
10:50:06.903 [INFO ] [c.internal.ModelRepositoryImpl:80 ] - Loading model 'rrd4j.persist'
10:50:06.950 [INFO ] [c.internal.ModelRepositoryImpl:80 ] - Loading model 'demo.script'
10:50:07.122 [INFO ] [c.internal.ModelRepositoryImpl:80 ] - Loading model 'camera.items'
10:50:07.137 [DEBUG] [i.internal.GenericItemProvider:154 ] - Processing binding configs for items from model 'camera.items'
10:50:07.137 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'camera.items'
10:50:07.153 [INFO ] [c.internal.ModelRepositoryImpl:80 ] - Loading model 'Compressor.items'
10:50:07.153 [DEBUG] [i.internal.GenericItemProvider:154 ] - Processing binding configs for items from model 'Compressor.items'
10:50:07.153 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'camera.items'
10:50:07.153 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'Compressor.items'
10:50:07.169 [INFO ] [c.internal.ModelRepositoryImpl:80 ] - Loading model 'demo.items'
10:50:07.184 [DEBUG] [i.internal.GenericItemProvider:154 ] - Processing binding configs for items from model 'demo.items'
10:50:07.184 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'camera.items'
10:50:07.184 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'Compressor.items'
10:50:07.184 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'demo.items'
10:50:07.184 [INFO ] [c.internal.ModelRepositoryImpl:80 ] - Loading model 'EVChamber.items'
10:50:07.200 [DEBUG] [i.internal.GenericItemProvider:154 ] - Processing binding configs for items from model 'EVChamber.items'
10:50:07.200 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'camera.items'
10:50:07.200 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'Compressor.items'
10:50:07.200 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'demo.items'
10:50:07.200 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'EVChamber.items'
10:50:07.200 [INFO ] [c.internal.ModelRepositoryImpl:80 ] - Loading model 'MQTT.items'
10:50:07.216 [DEBUG] [i.internal.GenericItemProvider:154 ] - Processing binding configs for items from model 'MQTT.items'
10:50:07.216 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'camera.items'
10:50:07.216 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'Compressor.items'
10:50:07.216 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'demo.items'
10:50:07.216 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'EVChamber.items'
10:50:07.216 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'MQTT.items'
10:50:07.231 [INFO ] [c.internal.ModelRepositoryImpl:80 ] - Loading model 'test.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:154 ] - Processing binding configs for items from model 'test.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'camera.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'Compressor.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'demo.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'EVChamber.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'MQTT.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:133 ] - Read items from model 'test.items'
10:50:08.075 [INFO ] [.o.u.w.i.servlet.WebAppServlet:80 ] - Started Classic UI at /classicui/openhab.app
10:50:08.356 [DEBUG] [.r.internal.RuleModelActivator:42 ] - Registered 'rules' configuration parser
10:50:08.372 [DEBUG] [m.r.internal.engine.RuleEngine:77 ] - Started rule engine
10:50:10.700 [DEBUG] [.a.mail.internal.MailActivator:34 ] - Mail action has been started.
10:50:10.700 [DEBUG] [o.o.b.w.i.bus.WeatherActivator:32 ] - Weather binding has been started.
10:50:10.763 [DEBUG] [.w.internal.gfx.WeatherServlet:62 ] - Starting up weather servlet at /weather
10:50:10.778 [DEBUG] [.rrd4j.internal.RRD4jActivator:31 ] - RRD4j persistence bundle has been started.
10:50:10.794 [WARN ] [.p.rrd4j.internal.RRD4jService:389 ] - Unknown property name : org.openhab.persistence.rrd4j
10:50:10.794 [DEBUG] [.p.rrd4j.internal.RRD4jService:358 ] - config 'objectClass' should have the format 'name.configkey'
10:50:10.794 [INFO ] [.p.rrd4j.internal.RRD4jService:401 ] - Removing invalid defintion component = null heartbeat = 0 min/max = 0.0/0.0 step = 0 0 archives(s) = [] 0 items(s) = [
]
10:50:10.794 [DEBUG] [.p.rrd4j.internal.RRD4jService:399 ] - Created default_other = GAUGE heartbeat = 3600 min/max = NaN/NaN step = 1 6 archives(s) = [ MAX xff = 0.999 steps = 1
rows = 3600 MAX xff = 0.999 steps = 10 rows = 1440 MAX xff = 0.999 steps = 60 rows = 1440 MAX xff = 0.999 steps = 900 rows = 2880 MAX xff = 0.999 steps = 21600 rows = 1460 MAX xff
= 0.999 steps = 86400 rows = 3650] 0 items(s) = []
10:50:10.794 [DEBUG] [.p.rrd4j.internal.RRD4jService:399 ] - Created default_numeric = GAUGE heartbeat = 60 min/max = NaN/NaN step = 60 6 archives(s) = [ AVERAGE xff = 0.5 steps =
1 rows = 480 AVERAGE xff = 0.5 steps = 4 rows = 360 AVERAGE xff = 0.5 steps = 14 rows = 644 AVERAGE xff = 0.5 steps = 60 rows = 720 AVERAGE xff = 0.5 steps = 720 rows = 730 AVERAG
E xff = 0.5 steps = 10080 rows = 520] 0 items(s) = []
10:50:10.809 [DEBUG] [.p.internal.PersistenceManager:146 ] - Initializing rrd4j persistence service.
10:50:10.825 [DEBUG] [.p.internal.PersistenceManager:328 ] - Item group 'Weather_Chart' does not exist.
10:50:10.825 [DEBUG] [.p.internal.PersistenceManager:328 ] - Item group 'toner' does not exist.
10:50:10.856 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Temperature_Serv2' -> '70.3400000000000034106051316484808
92181396484375'
10:50:10.856 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Humidity_Serv3' -> '49.2000000000000028421709430404007434
844970703125'
10:50:10.856 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Temperature_Serv1' -> '71.0600000000000022737367544323205
9478759765625'
10:50:10.856 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Humidity_Serv2' -> '61.2000000000000028421709430404007434
844970703125'
10:50:10.872 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'COMP_1_MAIN_Pressure_div' -> '110.34659399999999607189238
30427229404449462890625'
10:50:10.872 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Temperature_Serv3' -> '70.1599999999999965893948683515191
07818603515625'
10:50:10.872 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Humidity_Serv1' -> '58.3999999999999985789145284797996282
5775146484375'
10:50:10.872 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Chamber_TARGET_div' -> '0'
10:50:10.872 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'COMP_1_MAIN_Temp_div' -> '197.099999999999994315658113919
198513031005859375'
10:50:10.888 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Chamber_TEMP1_div' -> '25.3999999999999985789145284797996
2825775146484375'
10:50:10.888 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Chamber_SET1_div' -> '-40'
10:50:10.888 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'AC_Circuit_Serv1' -> 'ON'
10:50:10.888 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'AC_Circuit_Serv3' -> 'ON'
10:50:10.888 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'AC_Circuit_Serv2' -> 'OFF'
10:50:10.888 [DEBUG] [.p.internal.PersistenceManager:377 ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Camera_11' -> 'ON'
10:50:10.903 [DEBUG] [.p.internal.PersistenceManager:428 ] - Scheduled strategy rrd4j.everyMinute with cron expression 0 * * * * ?
10:50:10.919 [DEBUG] [p.r.i.charts.RRD4jChartServlet:118 ] - Starting up rrd chart servlet at /rrdchart.png
10:50:10.934 [DEBUG] [xecPersistenceServiceActivator:33 ] - Exec persistence bundle has been started.
10:50:10.934 [DEBUG] [.p.internal.PersistenceManager:146 ] - Initializing exec persistence service.
10:50:10.934 [DEBUG] [.p.internal.PersistenceManager:428 ] - Scheduled strategy exec.everyMinute with cron expression 0 * * * * ?
10:50:10.934 [DEBUG] [.b.mqtt.internal.MqttActivator:34 ] - MQTT binding has been started.
10:50:10.950 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Humidity_Serv1 (Type=NumberItem, State=Uninitialized)' with 'MqttGener
icBindingProvider' reader.
10:50:10.950 [DEBUG] [b.mqtt.internal.MqttItemConfig:71 ] - Loaded MQTT config for item 'Humidity_Serv1' : 1 subscribers, 0 publishers
10:50:10.950 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Temperature_Serv1 (Type=NumberItem, State=Uninitialized)' with 'MqttGe
nericBindingProvider' reader.
10:50:10.950 [DEBUG] [b.mqtt.internal.MqttItemConfig:71 ] - Loaded MQTT config for item 'Temperature_Serv1' : 1 subscribers, 0 publishers
10:50:10.950 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'AC_Circuit_Serv1 (Type=SwitchItem, State=Uninitialized)' with 'MqttGen
ericBindingProvider' reader.
10:50:10.950 [DEBUG] [b.mqtt.internal.MqttItemConfig:71 ] - Loaded MQTT config for item 'AC_Circuit_Serv1' : 1 subscribers, 0 publishers
10:50:10.950 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Humidity_Serv2 (Type=NumberItem, State=Uninitialized)' with 'MqttGener
icBindingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71 ] - Loaded MQTT config for item 'Humidity_Serv2' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Temperature_Serv2 (Type=NumberItem, State=Uninitialized)' with 'MqttGe
nericBindingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71 ] - Loaded MQTT config for item 'Temperature_Serv2' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'AC_Circuit_Serv2 (Type=SwitchItem, State=Uninitialized)' with 'MqttGen
ericBindingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71 ] - Loaded MQTT config for item 'AC_Circuit_Serv2' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Door_Serv2 (Type=ContactItem, State=Uninitialized)' with 'MqttGenericB
indingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71 ] - Loaded MQTT config for item 'Door_Serv2' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Humidity_Serv3 (Type=NumberItem, State=Uninitialized)' with 'MqttGener
icBindingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71 ] - Loaded MQTT config for item 'Humidity_Serv3' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Temperature_Serv3 (Type=NumberItem, State=Uninitialized)' with 'MqttGe
nericBindingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71 ] - Loaded MQTT config for item 'Temperature_Serv3' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'AC_Circuit_Serv3 (Type=SwitchItem, State=Uninitialized)' with 'MqttGen
ericBindingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71 ] - Loaded MQTT config for item 'AC_Circuit_Serv3' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Door_Serv3 (Type=ContactItem, State=Uninitialized)' with 'MqttGenericB
indingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71 ] - Loaded MQTT config for item 'Door_Serv3' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [m.internal.MqttEventBusBinding:61 ] - MQTT: Activating event bus binding.
10:50:10.966 [DEBUG] [.o.b.ntp.internal.NtpActivator:31 ] - NTP binding has been started.
10:50:10.981 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Date (Type=DateTimeItem, State=Uninitialized)' with 'NtpGenericBinding
Provider' reader.
10:50:10.981 [INFO ] [.service.AbstractActiveService:169 ] - NTP Refresh Service has been started
10:50:10.997 [DEBUG] [.b.snmp.internal.SnmpActivator:35 ] - SNMP binding has been started.
10:50:11.028 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Camera_11 (Type=SwitchItem, State=Uninitialized)' with 'SnmpGenericBin
dingProvider' reader.
10:50:11.059 [DEBUG] [.o.b.snmp.internal.SnmpBinding:91 ] - SNMP binding activated
10:50:11.091 [DEBUG] [.o.b.snmp.internal.SnmpBinding:147 ] - SNMP binding is listening on 0.0.0.0/162
10:50:11.091 [INFO ] [.service.AbstractActiveService:169 ] - SNMP Refresh Service has been started
10:50:11.091 [DEBUG] [.o.b.snmp.internal.SnmpBinding:335 ] - Item 'Camera_11' is about to be refreshed
10:50:11.091 [DEBUG] [.o.b.snmp.internal.SnmpBinding:350 ] - SNMP: Send PDU 192.168.1.251/161 GET[requestID=0, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.2.2.1.8.41 = N
ull]]
10:50:11.106 [DEBUG] [.i.LoggingPersistenceActivator:31 ] - Logging persistence bundle has been started.
10:50:11.106 [DEBUG] [.p.internal.PersistenceManager:146 ] - Initializing logging persistence service.
10:50:11.122 [DEBUG] [o.b.m.internal.ModbusActivator:31 ] - Modbus binding has been started.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'COMP_1_MAIN_Temp (Type=NumberItem, State=Uninitialized)' with 'ModbusG
enericBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'lightstackred (Type=SwitchItem, State=Uninitialized)' with 'ModbusGene
ricBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'lightstackyellow (Type=SwitchItem, State=Uninitialized)' with 'ModbusG
enericBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'lightstackgreen (Type=SwitchItem, State=Uninitialized)' with 'ModbusGe
nericBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'COMP_1_MAIN_Power (Type=SwitchItem, State=Uninitialized)' with 'Modbus
GenericBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Fan1RPM_H (Type=NumberItem, State=Uninitialized)' with 'ModbusGenericB
indingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'COMP_1_MAIN_Pressure (Type=NumberItem, State=Uninitialized)' with 'Mod
busGenericBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_SET1 (Type=NumberItem, State=Uninitialized)' with 'ModbusGener
icBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_TEMP1 (Type=NumberItem, State=Uninitialized)' with 'ModbusGene
ricBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_STAT1 (Type=NumberItem, State=Uninitialized)' with 'ModbusGene
ricBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_STAT_AL1 (Type=NumberItem, State=Uninitialized)' with 'ModbusG
enericBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_Heat (Type=NumberItem, State=Uninitialized)' with 'ModbusGener
icBindingProvider' reader.
10:50:11.138 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_STAT_AL2 (Type=NumberItem, State=Uninitialized)' with 'ModbusG
enericBindingProvider' reader.
10:50:11.138 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_COOL (Type=NumberItem, State=Uninitialized)' with 'ModbusGener
icBindingProvider' reader.
10:50:11.138 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_TARGET (Type=NumberItem, State=Uninitialized)' with 'ModbusGen
ericBindingProvider' reader.
10:50:11.138 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_Fan_Run (Type=NumberItem, State=Uninitialized)' with 'ModbusGe
nericBindingProvider' reader.
10:50:11.138 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_Fan_Speed (Type=NumberItem, State=Uninitialized)' with 'Modbus
GenericBindingProvider' reader.
10:50:11.169 [DEBUG] [.modbus.internal.ModbusBinding:408 ] - modbusSlave 'slave1' instanciated
10:50:11.169 [DEBUG] [.b.http.internal.HttpActivator:34 ] - HTTP binding has been started.
10:50:11.185 [INFO ] [.service.AbstractActiveService:169 ] - HTTP Refresh Service has been started
10:50:11.278 [DEBUG] [.o.b.snmp.internal.SnmpBinding:213 ] - Received PDU from '192.168.1.251/161' 'RESPONSE[requestID=1913325855, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.
1.2.1.2.2.1.8.41 = 1]]'
10:50:11.294 [INFO ] [runtime.busevents :26 ] - Camera_11 state updated to ON
10:50:11.388 [DEBUG] [inding.ntp.internal.NtpBinding:83 ] - Got time from pool.ntp.org: Thursday, March 17, 2016 10:50:11 AM CDT
10:50:11.388 [INFO ] [runtime.busevents :26 ] - Date state updated to 2016-03-17T10:50:11
Thanks for the logs.
So just to double confirm I understand correctly:
Thanks! I need to test this myself as well again
That is correct I was using the 1.8.0 snapshot befor but wanted to try the new binding do I downloaded the jar from the V6 link and it did’t work with 1.8.0snap so I thought I needed to upgrade to the 1.8.1 and it still didn’t work. if I drop the 1.8.0 snap jar back in the folder with 1.8.1 modbus works again
This is what it looks like when I rip the 1.9 out and drop the 1.8 in.
12:07:03.323 [INFO ] [runtime.busevents :26 ] - Camera_11 state updated to ON
12:07:13.262 [DEBUG] [.o.b.snmp.internal.SnmpBinding:335 ] - Item 'Camera_11' is about to be refreshed
12:07:13.262 [DEBUG] [.o.b.snmp.internal.SnmpBinding:350 ] - SNMP: Send PDU 192.168.1.251/161 GET[requestID=0, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.2.2.1.8.41 = N
ull]]
12:07:13.324 [DEBUG] [.o.b.snmp.internal.SnmpBinding:213 ] - Received PDU from '192.168.1.251/161' 'RESPONSE[requestID=1913326779, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.
1.2.1.2.2.1.8.41 = 1]]'
12:07:13.324 [INFO ] [runtime.busevents :26 ] - Camera_11 state updated to ON
12:07:16.574 [DEBUG] [o.b.m.internal.ModbusActivator:39 ] - Modbus binding has been stopped.
12:07:20.731 [DEBUG] [o.b.m.internal.ModbusActivator:30 ] - Modbus binding has been started.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'COMP_1_MAIN_Temp (Type=NumberItem, State=Uninitialized)' with 'ModbusG
enericBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'lightstackred (Type=SwitchItem, State=Uninitialized)' with 'ModbusGene
ricBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'lightstackyellow (Type=SwitchItem, State=Uninitialized)' with 'ModbusG
enericBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'lightstackgreen (Type=SwitchItem, State=Uninitialized)' with 'ModbusGe
nericBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'COMP_1_MAIN_Power (Type=SwitchItem, State=Uninitialized)' with 'Modbus
GenericBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Fan1RPM_H (Type=NumberItem, State=Uninitialized)' with 'ModbusGenericB
indingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'COMP_1_MAIN_Pressure (Type=NumberItem, State=Uninitialized)' with 'Mod
busGenericBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_SET1 (Type=NumberItem, State=Uninitialized)' with 'ModbusGener
icBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_TEMP1 (Type=NumberItem, State=Uninitialized)' with 'ModbusGene
ricBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_STAT1 (Type=NumberItem, State=Uninitialized)' with 'ModbusGene
ricBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_STAT_AL1 (Type=NumberItem, State=Uninitialized)' with 'ModbusG
enericBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_Heat (Type=NumberItem, State=Uninitialized)' with 'ModbusGener
icBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_STAT_AL2 (Type=NumberItem, State=Uninitialized)' with 'ModbusG
enericBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_COOL (Type=NumberItem, State=Uninitialized)' with 'ModbusGener
icBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_TARGET (Type=NumberItem, State=Uninitialized)' with 'ModbusGen
ericBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_Fan_Run (Type=NumberItem, State=Uninitialized)' with 'ModbusGe
nericBindingProvider' reader.
12:07:20.731 [DEBUG] [i.internal.GenericItemProvider:341 ] - Start processing binding configuration of Item 'Chamber_Fan_Speed (Type=NumberItem, State=Uninitialized)' with 'Modbus
GenericBindingProvider' reader.
12:07:20.762 [DEBUG] [.modbus.internal.ModbusBinding:282 ] - modbusSlave 'slave1' instanciated
12:07:20.762 [DEBUG] [.modbus.internal.ModbusBinding:282 ] - modbusSlave 'slave10' instanciated
12:07:20.762 [DEBUG] [.modbus.internal.ModbusBinding:282 ] - modbusSlave 'slave2' instanciated
12:07:20.762 [DEBUG] [.modbus.internal.ModbusBinding:282 ] - modbusSlave 'slave3' instanciated
12:07:20.762 [DEBUG] [.modbus.internal.ModbusBinding:282 ] - modbusSlave 'slave4' instanciated
12:07:20.762 [DEBUG] [.modbus.internal.ModbusBinding:282 ] - modbusSlave 'slave5' instanciated
12:07:20.762 [DEBUG] [.modbus.internal.ModbusBinding:282 ] - modbusSlave 'slave6' instanciated
12:07:20.762 [DEBUG] [.modbus.internal.ModbusBinding:282 ] - modbusSlave 'slave7' instanciated
12:07:20.762 [DEBUG] [.modbus.internal.ModbusBinding:282 ] - modbusSlave 'slave8' instanciated
12:07:20.762 [DEBUG] [.modbus.internal.ModbusBinding:282 ] - modbusSlave 'slave9' instanciated
12:07:20.762 [DEBUG] [.modbus.internal.ModbusBinding:344 ] - config looked good, proceeding with slave-connections
12:07:20.762 [DEBUG] [modbus.net.TCPMasterConnection:68 ] - connect()
12:07:20.778 [DEBUG] [modbus.net.TCPMasterConnection:68 ] - connect()
12:07:20.793 [DEBUG] [modbus.net.TCPMasterConnection:68 ] - connect()
12:07:20.793 [DEBUG] [modbus.net.TCPMasterConnection:68 ] - connect()
12:07:20.825 [DEBUG] [modbus.net.TCPMasterConnection:68 ] - connect()
12:07:20.825 [DEBUG] [modbus.net.TCPMasterConnection:68 ] - connect()
12:07:20.825 [DEBUG] [modbus.net.TCPMasterConnection:68 ] - connect()
12:07:23.278 [DEBUG] [.o.b.snmp.internal.SnmpBinding:335 ] - Item 'Camera_11' is about to be refreshed
12:07:23.278 [DEBUG] [.o.b.snmp.internal.SnmpBinding:350 ] - SNMP: Send PDU 192.168.1.251/161 GET[requestID=0, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.2.2.1.8.41 = N
ull]]
12:07:23.309 [DEBUG] [.o.b.snmp.internal.SnmpBinding:213 ] - Received PDU from '192.168.1.251/161' 'RESPONSE[requestID=1913326781, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.
1.2.1.2.2.1.8.41 = 1]]'
12:07:23.309 [INFO ] [runtime.busevents :26 ] - Camera_11 state updated to ON
12:07:33.278 [DEBUG] [.o.b.snmp.internal.SnmpBinding:335 ] - Item 'Camera_11' is about to be refreshed
12:07:33.278 [DEBUG] [.o.b.snmp.internal.SnmpBinding:350 ] - SNMP: Send PDU 192.168.1.251/161 GET[requestID=0, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.2.2.1.8.41 = N
ull]]
12:07:33.341 [DEBUG] [.o.b.snmp.internal.SnmpBinding:213 ] - Received PDU from '192.168.1.251/161' 'RESPONSE[requestID=1913326783, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.
1.2.1.2.2.1.8.41 = 1]]'
12:07:33.341 [INFO ] [runtime.busevents :26 ] - Camera_11 state updated to ON
12:07:41.732 [DEBUG] [modbus.internal.ModbusTcpSlave:68 ] - ModbusSlave: Error connecting to master: Connection timed out: connect
12:07:41.732 [DEBUG] [modbus.net.TCPMasterConnection:68 ] - connect()
12:07:41.748 [DEBUG] [modbus.net.TCPMasterConnection:68 ] - connect()
12:07:41.763 [DEBUG] [modbus.net.TCPMasterConnection:68 ] - connect()
12:07:43.279 [DEBUG] [.o.b.snmp.internal.SnmpBinding:335 ] - Item 'Camera_11' is about to be refreshed
12:07:43.279 [DEBUG] [.o.b.snmp.internal.SnmpBinding:350 ] - SNMP: Send PDU 192.168.1.251/161 GET[requestID=0, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.2.2.1.8.41 = N
ull]]
12:07:43.310 [DEBUG] [.o.b.snmp.internal.SnmpBinding:213 ] - Received PDU from '192.168.1.251/161' 'RESPONSE[requestID=1913326785, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.
1.2.1.2.2.1.8.41 = 1]]'
12:07:43.310 [INFO ] [runtime.busevents :26 ] - Camera_11 state updated to ON
12:07:44.701 [INFO ] [.service.AbstractActiveService:169 ] - Modbus Polling Service has been started
12:07:45.154 [DEBUG] [m.r.internal.engine.RuleEngine:305 ] - Executing rule 'Chamber Demand conversion'
12:07:45.170 [TRACE] [et.wimpi.modbus.util.BitVector:137 ] - Get bit #0
12:07:45.170 [DEBUG] [modbus.net.TCPMasterConnection:68 ] - connect()
12:07:45.467 [INFO ] [runtime.busevents :26 ] - Chamber_TARGET state updated to 0
12:07:45.467 [INFO ] [runtime.busevents :26 ] - Fan1RPM_H state updated to 0
12:07:45.467 [INFO ] [runtime.busevents :26 ] - COMP_1_MAIN_Power state updated to ON
12:07:45.514 [DEBUG] [riptExtensionClassNameProvider:63 ] - Script actions have changed: AudioActionService, HTTPActionService, PingActionService, ExecActionService, MailActionSe
rvice, TransformationActionService,
12:07:45.748 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored 'Chamber_TARGET_div' with state '0' in rrd4j database
12:07:45.748 [INFO ] [runtime.busevents :26 ] - Chamber_TARGET_div state updated to 0
I think I know what it is slave1 has problems where there is a device on the network with the same IP address and I havn’t been able to track it down. there is an uncaught error on slave one so it just halts.
when I dissabled slave1 and reloaded it it works.
Good to hear that it was IP address conflict.
I tried as well but could not reproduce the issue here (using the v6 + 1.8.1 openhab on linux).
I tried different ways to mess up the binding, for example:
19:46:24.913 [ERROR] [dbusSlaveConnectionFactoryImpl:212 ] - connect try 1/3 error: No route to host. Connection TCPMasterConnection@619ffac9[socket=<null>]. Endpoint ModbusTCPSlaveEndpoint@7980c9cb[address=192.168.1.103,port=502]
Really weird what you are experiencing since if it has configured only one slave, but not the rest, it should not yet connect to the slaves… What did you mean by “uncaught error”? Did you have some error in the logs?
Please keep me posted if you get any other issues.
no I mean by the binding with the new changes doesn’t know what to do with that connection if two devices have the same ip address and hangs up there.
also I noticed that is the only RTU device I have too
#modbus:tcp.slave1.connection=192.168.1.200:502:rtu:100
#modbus:tcp.slave1.type=holding
#modbus:tcp.slave1.start=39
#modbus:tcp.slave1.length=1
#modbus:tcp.slave1.valuetype=uint16
thats all I did and it started working with the others
Btw, the connection string for TCP slaves follow this convention in the new binding
colon ( : ) separated connection settings for a tcp/udp modbus slave. Expecting at most 2 parameters: hostname (mandatory) and optionally (in this order) port number, interTransactionDelayMillis, reconnectAfterMillis, interConnectDelayMillis, connectMaxTries.
Most often you do not need to touch any of the optional parameters with TCP slaves but they are to resolve issues with some specific devices. For example, I need to use interTransactionDelayMillis=50 to give some time for the PLC to “recover” from the previous request.
what about the RTU setting could that have thrown it off?
Ah I didn’t even notice that error in the config! Yes that apparently crashes some part of openhab itself (likely better error handling would be in order in core as well).
I have to improve the error handling.
Note that the binding handles the situation that two openhab modbus slaves have the same ip. Actually, that is the whole point the of this “connection pooling”.
Not sure what you are trying to achieve by setting ip and “rtu” – RTU is supported only with serial connections, not TCP connections. Or was it a pure typo?
The binding fails to parse “rtu” as number (as it should represent inter transaction delay in millis), and apparently makes openhab stuck…
I think it was left there when I was first started messing with modbus tcp and openhab. and I never know it was an error because the previous bindings must have ignored it.
It is true that they used to ignore additional parameters since previously you could only input host and port with TCP slaves. I believe you might get the old binding crash with 192.168.100.1:ThisIsInvalidPort since ThisIsInvalidPort is not a number…
Seems to work. No errors.
1200 Baud => 8.3ms/Character => 3.5*8,3ms = 29.05ms
=> 35ms should be ok for every application
What’s way more important anyway is the value of readTimeout where 280ms is actually quite low. The spec says:
Typically the Response time-out is from 1s to several second at 9600 bps
Although most devices are a lot faster we shouldn’t make something as low as 280ms the default - or at least suggest sth like 1.5s for debugging purposes.
Of course all I’m saying applies to serial lines only. I’ve got no real clue about ModBus TCP 
Excellent feedback @mbs38! I agree that it makes sense to have large read time out, since I expect the 280ms to become tight if reading many many registers.
I shall go with the 35ms and 1.5s with serial slaves. For TCP I shall use 50ms inter transaction delay since it was required at least for my (pretty hefty, but with default settings) PLC.