Huge error log after update or reboot, restart with systemctl is clean though

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 rootwait

Here the link to the rather large logfile
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
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
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 ] [] - 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)

I get the same…

Every time I perform a snapshot upgrade (this causes a restart), OH2 goes crazy and produces about 20 Megs of error log.
I restart it immediately after and all is clean and great… Not really something that bothers me much since my OH2 system is very stable when started the second time.

I think that it has something to do with “ScriptServiceUtil not initialized yet!” but I am not sure (i see lots of these errors)

1 Like

Thanks @Dim
Agreed with all, except for the times when for one reason or another the pi restarts while I am out of town (and that is not as rare of a use case as I would want it to be). Then, nothing works and all home automation has to wait until i come back.
Mmmmh, maybe i will need to install a VPN server after all

1 Like

This only happens after an apt upgrade, right? Afaik, this is due to the fact that this removes the OSGi cache directory (userdata/cache) and Karaf rebuilds it on the first startup based on the new runtime.

I do not know how to solve this - someone would have to dig into Karaf and see what would be the best way to update an existing installation.


Yup, only after apt-upgrade.
It’s not a big deal for me since I always perform a restart of the OH2 service after each apt-get upgrade.

I observe this behavior after reboots (power outage or sudo reboot) and yes, after apt-upgrade; the latter as Angelo said is less of an issue.