Would appreciate if anyone has a pointer to why the below is happening (and what I could do about it), this behavior is repeatable and reliable. I am a little stumped and not even sure where to start looking, as the issue appears to be
Every time I update or reboot my system (PI3, headless booting from USB disk, snapshot install via apt-get) the system throws a huge amount of errors and typically is misbehaving (timers not kicking in, rules not firing, however, it seems rather unpredictable). This happens every time after a reboot and almost every time after upgrading. Moreover, this happens since months (and I upgrade almost every week)
The RPI3 should (in theory at least unless there is user error) wait long enough with booting for everything to come online, here my /boot/cmdline.txt
dwc_otg.lpm_enable=0 console=serial0,115200 console=tty1 root=PARTUUID=EFC61221-93FE-4787-8D07-F23D4B6A02A1 rootdelay=5 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
Here the link to the rather large logfile
https://zerobin.net/?eeea60160cc3906f#8aAOYTyweA4vdEvClFHQ5EkJXX6/6vM0x41zVugP6GU=
It starts with Apache reporting problems with file install (the sequence in which the addons are being loaded varies, the outcome not though)
A subsequent restart of OH2 via
sudo systemctl restart openhab2.service
makes OH2 start up clean with no errors and all functionality is restored.
Here the logfile after a systemctl restart in comparison
2017-05-06 17:41:31.393 [INFO ] [ore.internal.i18n.LocaleProviderImpl] - Locale set to en_US
2017-05-06 17:41:38.322 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'temperature.items'
2017-05-06 17:41:38.729 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2017-05-06 17:41:38.860 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lights.items'
2017-05-06 17:41:39.109 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2017-05-06 17:41:39.177 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'astro.items'
2017-05-06 17:41:44.671 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'system.rules'
2017-05-06 17:41:50.407 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'scene.rules'
2017-05-06 17:41:51.257 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'TP_Link_plugs.rules', using it anyway:
Function2 is a raw type. References to generic type Function2<P1, P2, Result> should be parameterized
2017-05-06 17:41:51.270 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'TP_Link_plugs.rules'
2017-05-06 17:41:57.354 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Time_of_day_events.rules'
2017-05-06 17:41:58.680 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
2017-05-06 17:41:59.242 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'exec.things'
2017-05-06 17:42:00.967 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2017-05-06 17:42:03.281 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-05-06 17:42:03.653 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-05-06 17:42:04.695 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-daily-moon at midnight for thing astro:moon:home
2017-05-06 17:42:04.695 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-daily-sun at midnight for thing astro:sun:home
2017-05-06 17:42:06.692 [INFO ] [ternal.PilightGenericBindingProvider] - pilight:kaku item LivingroomLamps bound to device LivingroomLamps
2017-05-06 17:42:06.694 [INFO ] [ternal.PilightGenericBindingProvider] - pilight:kaku item BedroomLamps bound to device BedroomLamps
2017-05-06 17:42:06.746 [ERROR] [org.openhab.binding.pilight ] - [org.openhab.binding.pilight.binding(4)] The addBindingProvider method has thrown an exception
java.lang.NullPointerException
[....]
2017-05-06 17:42:06.879 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been started
2017-05-06 17:42:06.933 [INFO ] [b.core.service.AbstractActiveService] - Expire Refresh Service has been started
2017-05-06 17:42:07.924 [INFO ] [b.core.service.AbstractActiveService] - NetworkUpsTools Refresh Service has been started
2017-05-06 17:42:08.129 [INFO ] [eather.internal.common.WeatherConfig] - ProviderConfig[providerName=OPENWEATHERMAP,apiKey=b7af758bd518796edd4be478b1e1bc6d]
2017-05-06 17:42:08.131 [INFO ] [eather.internal.common.WeatherConfig] - LocationConfig[providerName=OPENWEATHERMAP,language=en,updateInterval=10,latitude=41.826151,longitude=12.487939,woeid=<null>,locationId=home,name=Rome]
2017-05-06 17:42:08.448 [INFO ] [ng.pilight.internal.PilightConnector] - Established connection to pilight server at 192.168.1.2:5000
2017-05-06 17:42:09.587 [INFO ] [ulation.internal.HueEmulationServlet] - Started Hue Emulation service at /api
2017-05-06 17:42:09.646 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2017-05-06 17:42:09.647 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mymqtt'
2017-05-06 17:42:10.934 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-05-06 17:42:11.168 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Starting and scheduling weatherJob-home with interval of 10 minutes
2017-05-06 17:42:23.563 [INFO ] [.astro.internal.job.AbstractDailyJob] - Scheduled astro event-jobs for thing astro:moon:home
2017-05-06 17:42:23.643 [INFO ] [.astro.internal.job.AbstractDailyJob] - Scheduled astro event-jobs for thing astro:sun:home
The only noticeable error (NPE caused by pilight seems to be normal, happens since forever and does not seem to cause any other problems)