(Title changed, was “Bindings don’t start consistently after server upgrade (1.8.1)”)
I’ve been running 1.8.1 for some time, and it was working pretty consistently until recently when I upgraded my server (from Fedora 19 to 24, and a faster processor). The openhab install is on a filesystem that’s mounted from a file server, so it is unchanged from the old server to the new. I’m using (among others) the AlarmDecoder and NetworkHealth bindings. On any given startup of OpenHAB, one or both of these bindings may or may not start. When they don’t start, there is no evidence in the log that they even exist – no errors, nothing. When they work, I see messages like “NetworkHealth Refresh Service has been started” along with messages caused by items that use that binding.
Fortunately, once they both load, I can usually leave OpenHAB alone for days or weeks, but if I need to restart the server, I can spend an hour restarting OpenHAB until both of these are running.
What steps can I take to figure out what’s going on?
Here’s a sample log where NetworkHealth loaded, but not AlarmDecoder:
2016-09-15 20:17:38.808 [INFO ] [.o.core.internal.CoreActivator] - openHAB runtime has been started (v1.8.1).
2016-09-15 20:17:39.469 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl] - mDNS service has been started
2016-09-15 20:17:39.489 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl] - Service Discovery initialization completed.
2016-09-15 20:17:39.493 [INFO ] [.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2016-09-15 20:17:40.790 [INFO ] [penhab.io.rest.RESTApplication] - Started REST API at /rest
2016-09-15 20:17:49.281 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'home.sitemap’
2016-09-15 20:17:49.412 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'Kitchen.items’
2016-09-15 20:17:49.429 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'Master.items’
2016-09-15 20:17:49.437 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'temps.items’
2016-09-15 20:17:49.444 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'alarm.items’
2016-09-15 20:17:49.461 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'home.items’
2016-09-15 20:17:49.468 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'LivingRoom.items’
2016-09-15 20:17:49.482 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'Outdoor.items’
2016-09-15 20:17:49.492 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'ops.items’
2016-09-15 20:17:49.499 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'Network.items’
2016-09-15 20:17:50.017 [INFO ] [.o.u.w.i.servlet.WebAppServlet] - Started Classic UI at /classicui/openhab.app
2016-09-15 20:17:56.067 [WARN ] [io.squeezeserver.SqueezeServer] - Empty or null configuration. Ignoring.
2016-09-15 20:17:56.143 [INFO ] [t.AbstractSocketChannelBinding] - The maximum buffer will be set to the default value of 1024
2016-09-15 20:17:56.144 [INFO ] [t.AbstractSocketChannelBinding] - The interval to retry connection setups will be set to the default value of 5
2016-09-15 20:17:56.144 [INFO ] [t.AbstractSocketChannelBinding] - The cron job to reset connections will be set to the default value of 0 0 0 * * ?
2016-09-15 20:17:56.144 [INFO ] [t.AbstractSocketChannelBinding] - The setting to queue write operation until a channel gets connected will be set to the default value of true
2016-09-15 20:17:56.144 [INFO ] [t.AbstractSocketChannelBinding] - The port to listen for incoming connections will be set to the default value of 0
2016-09-15 20:17:56.144 [INFO ] [t.AbstractSocketChannelBinding] - The setting to share channels within an Item will be set to the default value of true
2016-09-15 20:17:56.145 [INFO ] [t.AbstractSocketChannelBinding] - The setting to share channels between the items with the same direction will be set to the default value of true
2016-09-15 20:17:56.145 [INFO ] [t.AbstractSocketChannelBinding] - The setting to share channels between directions will be set to the default value of true
2016-09-15 20:17:56.145 [INFO ] [t.AbstractSocketChannelBinding] - The setting to use address masks for incoming connections will be set to the default value of true
2016-09-15 20:17:56.155 [INFO ] [t.protocol.internal.TCPBinding] - The maximum time out for blocking write operations will be set to the default vaulue of 3000
2016-09-15 20:17:56.155 [INFO ] [t.protocol.internal.TCPBinding] - The blocking nature of read/write operations will be set to the default vaulue of false
2016-09-15 20:17:56.155 [INFO ] [t.protocol.internal.TCPBinding] - The preamble for all write operations will be set to the default vaulue of ""
2016-09-15 20:17:56.155 [INFO ] [t.protocol.internal.TCPBinding] - The postamble for all write operations will be set to the default vaulue of ""
2016-09-15 20:17:56.156 [INFO ] [t.protocol.internal.TCPBinding] - Updating states with returned values will be set to the default vaulue of true
2016-09-15 20:17:56.156 [INFO ] [t.protocol.internal.TCPBinding] - The characterset will be set to the default vaulue of ASCII
2016-09-15 20:17:56.156 [INFO ] [.service.AbstractActiveService] - TCP Refresh Service has been started
2016-09-15 20:17:56.431 [INFO ] [rg.openhab.io.cv.CVApplication] - Started Cometvisu API at /services/cv
2016-09-15 20:17:59.549 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'pond.rules’
2016-09-15 20:17:59.605 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'bedtime.rules’
2016-09-15 20:17:59.622 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'test.rules’
2016-09-15 20:17:59.627 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'gate.rules’
2016-09-15 20:17:59.643 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'network.rules’
2016-09-15 20:17:59.652 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'ops.rules’
2016-09-15 20:18:01.968 [INFO ] [o.o.c.j.i.e.s.ScriptManager ] - Available engines:
2016-09-15 20:18:01.971 [INFO ] [o.o.c.j.i.e.s.ScriptManager ] - Oracle Nashorn
2016-09-15 20:18:01.972 [INFO ] [o.c.j.i.e.scriptmanager.Script] - Loading Script jsr223_demo.py
2016-09-15 20:18:01.973 [WARN ] [o.o.c.j.i.e.s.ScriptManager ] - No Engine found for File: jsr223_demo.py
2016-09-15 20:18:02.146 [INFO ] [.service.AbstractActiveService] - Oceanic Refresh Service has been started
2016-09-15 20:18:02.153 [INFO ] [.service.AbstractActiveService] - RME Refresh Service has been started
2016-09-15 20:18:02.265 [INFO ] [.service.AbstractActiveService] - Exec Refresh Service has been started
2016-09-15 20:18:02.639 [INFO ] [.service.AbstractActiveService] - HTTP Refresh Service has been started
2016-09-15 20:18:02.815 [INFO ] [.service.AbstractActiveService] - Pulseaudio Monitor Service has been started
2016-09-15 20:18:03.671 [INFO ] [.service.AbstractActiveService] - XBMC Refresh Service has been started
2016-09-15 20:18:04.220 [INFO ] [.service.AbstractActiveService] - NetworkHealth Refresh Service has been started
2016-09-15 20:18:04.221 [INFO ] [.service.AbstractActiveService] - NTP Refresh Service has been started
2016-09-15 20:18:04.265 [INFO ] [runtime.busevents ] - Network_rpi state updated to ON
2016-09-15 20:18:04.286 [INFO ] [runtime.busevents ] - Network_pigate state updated to ON
2016-09-15 20:18:04.816 [WARN ] [.o.c.p.e.PersistenceExtensions] - There is no queryable persistence service registered with the name 'rrd4j’
2016-09-15 20:18:04.848 [WARN ] [.o.c.p.e.PersistenceExtensions] - There is no queryable persistence service registered with the name 'rrd4j’
2016-09-15 20:18:04.885 [INFO ] [runtime.busevents ] - Network_rpi_update state updated to 2016-09-15T20:18:04