Openhab crash after updated to 2.4

Kim_Andersen · December 31, 2018, 11:54am

Removed the oldest serial driver as @Chris suggested…Restart went alot smoother from reboot.
(actually, I think it went too well… Most of the errors and warnings I believe is common due to the startup process).

Velux binding still acting up.
And then this weird “low configured threads…” stuff, which also started after the update to openhab 2.4

2018-12-31 12:39:29.891 [WARN ] [e.jetty.util.thread.ThreadPoolBudget] - Low configured threads: (max=8 - required=1)=7 < warnAt=8 for QueuedThreadPool[ServletModel-12]@175cb01{STARTING,8<=0<=8,i=0,q=0}[ReservedThreadExecutor@a93ee3{s=0/1,p=0}]

I have given up trying to solve this. I´ve read all the subjects about this, tried some of the suggestions. But it doesn´t change anything. I have no idea if this is related to my problems. And speaking from the community, it seems like others don´t as well.

Here is the full log from latest reboot.

2018-12-31 12:38:32.006 [INFO ] [.internal.GenericScriptEngineFactory] - Activated scripting support for ECMAScript
2018-12-31 12:38:32.858 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Modbus manager activated
2018-12-31 12:38:33.699 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2018-12-31 12:38:35.773 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Copenhagen'.
2018-12-31 12:38:35.782 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '55.493533,12.082062'.
2018-12-31 12:38:35.787 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'da_DK'.
2018-12-31 12:38:38.977 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 9bb96452-3fd4-45aa-8c1e-cd6f576ada73, base URL = http://localhost:8080)
2018-12-31 12:38:46.488 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'googlehomemini.items'
2018-12-31 12:38:46.731 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'zwave.items'
2018-12-31 12:38:46.866 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'xiaomidevices.items'
2018-12-31 12:38:46.992 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'unifi.items'
2018-12-31 12:38:47.120 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'windowdoorsensors.items'
2018-12-31 12:38:47.193 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'tplink.items'
2018-12-31 12:38:47.258 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'batterilevel.items'
2018-12-31 12:38:47.629 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'pirs.items'
2018-12-31 12:38:47.767 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'netamo.items'
2018-12-31 12:38:47.951 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nilan.items'
2018-12-31 12:38:48.169 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'div.items'
2018-12-31 12:38:48.220 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'group.items'
2018-12-31 12:38:48.360 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nilan_generated.items'
2018-12-31 12:38:48.397 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'velux.items'
2018-12-31 12:38:48.463 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'zigbee.items'
2018-12-31 12:38:48.602 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ihc.items'
2018-12-31 12:38:48.959 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'network.items'
2018-12-31 12:38:48.990 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hue.items'
2018-12-31 12:38:49.616 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2018-12-31 12:38:52.520 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2018-12-31 12:38:57.585 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'things_on_off.rules'
2018-12-31 12:38:58.600 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'xiaomi_switch.rules'
2018-12-31 12:38:58.993 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'keepIHCalive.rules'
2018-12-31 12:38:59.638 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nilan.rules'
2018-12-31 12:39:00.031 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alarmOnOff.rules'
2018-12-31 12:39:00.604 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'PIRupdate1.rules'
2018-12-31 12:39:00.924 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'pushbutton.rules'
2018-12-31 12:39:01.167 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ventilmotion.rules'
2018-12-31 12:39:01.407 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'telestatOnOffStamp.rules'
2018-12-31 12:39:02.387 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'juletraelys.rules'
2018-12-31 12:39:02.909 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'automaticwindowsONOFF.rules'
2018-12-31 12:39:03.141 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ihcsensorfejl.rules'
2018-12-31 12:39:04.734 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'automaticwindowsNetamo.rules'
2018-12-31 12:39:05.157 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hue_switch.rules'
2018-12-31 12:39:06.340 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'garageport_moving.rules', using it anyway:
The value of the local variable moving is not used
2018-12-31 12:39:06.346 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'garageport_moving.rules'
2018-12-31 12:39:06.988 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'XiaomiSensor.rules'
2018-12-31 12:39:07.408 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'HueLamperIstuen.rules'
2018-12-31 12:39:09.260 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'dummy.sitemap'
2018-12-31 12:39:09.306 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'lillebad.sitemap'
2018-12-31 12:39:09.350 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'unifi.sitemap'
2018-12-31 12:39:09.394 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hueswitches.sitemap'
2018-12-31 12:39:09.449 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'stue.sitemap'
2018-12-31 12:39:09.491 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'aktivitet.sitemap'
2018-12-31 12:39:09.530 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'stortbad.sitemap'
2018-12-31 12:39:09.571 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'spisestue.sitemap'
2018-12-31 12:39:09.611 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'marc.sitemap'
2018-12-31 12:39:09.648 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'grupper.sitemap'
2018-12-31 12:39:09.691 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'vejr.sitemap'
2018-12-31 12:39:09.733 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'zwave.sitemap'
2018-12-31 12:39:09.773 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'xiaomi.sitemap'
2018-12-31 12:39:09.811 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'garage.sitemap'
2018-12-31 12:39:09.840 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'network.sitemap'
2018-12-31 12:39:09.868 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'udelys.sitemap'
2018-12-31 12:39:09.896 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ipcamera.sitemap'
2018-12-31 12:39:09.939 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'varmepanel.sitemap'
2018-12-31 12:39:09.980 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alarm.sitemap'
2018-12-31 12:39:10.016 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'velux.sitemap'
2018-12-31 12:39:10.051 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'koekken.sitemap'
2018-12-31 12:39:10.112 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nilanold.sitemap'
2018-12-31 12:39:10.163 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kontor.sitemap'
2018-12-31 12:39:10.196 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'online.sitemap'
2018-12-31 12:39:10.225 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'bryggers.sitemap'
2018-12-31 12:39:10.254 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'casper.sitemap'
2018-12-31 12:39:10.308 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nilan.sitemap'
2018-12-31 12:39:10.357 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'amanda.sitemap'
2018-12-31 12:39:10.387 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sovevaerelse.sitemap'
2018-12-31 12:39:10.888 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ipcamera.things'
2018-12-31 12:39:11.095 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'unifi.things'
2018-12-31 12:39:11.373 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nilan.things'
2018-12-31 12:39:14.487 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Error during the execution of startup rule 'nilan date items concatenation': For input string: "NULL"
2018-12-31 12:39:20.873 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'chromecast:chromecast:03222cb1b76882c56290c24f73975886' to inbox.
2018-12-31 12:39:20.901 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'chromecast:chromecast:bcb267af78f33cbc1efe3cf46ae4d548' to inbox.
2018-12-31 12:39:20.914 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'chromecast:chromecast:255f3cf49521e13fa5f92fc38ae7ac51' to inbox.
2018-12-31 12:39:20.947 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'tplinksmarthome:hs110:82E954' to inbox.
2018-12-31 12:39:27.410 [INFO ] [ternal.dhcp.DHCPPacketListenerServer] - DHCP request packet listener online
2018-12-31 12:39:27.891 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while reading
su.litvak.chromecast.api.v2.ChromeCastException: Remote socket closed
	at su.litvak.chromecast.api.v2.Channel.read(Channel.java:425) ~[241:org.openhab.binding.chromecast:2.4.0]
	at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) ~[241:org.openhab.binding.chromecast:2.4.0]
	at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [241:org.openhab.binding.chromecast:2.4.0]
2018-12-31 12:39:27.927 [WARN ] [su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message 
2018-12-31 12:39:29.891 [WARN ] [e.jetty.util.thread.ThreadPoolBudget] - Low configured threads: (max=8 - required=1)=7 < warnAt=8 for QueuedThreadPool[ServletModel-12]@175cb01{STARTING,8<=0<=8,i=0,q=0}[ReservedThreadExecutor@a93ee3{s=0/1,p=0}]
2018-12-31 12:39:30.713 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://10.4.28.237:8080
2018-12-31 12:39:30.717 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://10.4.28.237:8443
2018-12-31 12:39:33.992 [ERROR] [e.smarthome.model.script.ThingStatus] - Trust motion sensor is offline or doesn't exist.
2018-12-31 12:39:33.992 [ERROR] [e.smarthome.model.script.ThingStatus] - ZwaveNode10 is offline or doesn't exist.
2018-12-31 12:39:34.009 [ERROR] [e.smarthome.model.script.ThingStatus] - ZwaveNode13 is offline or doesn't exist.
2018-12-31 12:39:34.011 [ERROR] [e.smarthome.model.script.ThingStatus] - Trust motion sensor is offline or doesn't exist.
2018-12-31 12:39:34.011 [ERROR] [e.smarthome.model.script.ThingStatus] - ZwaveNode13 is offline or doesn't exist.
2018-12-31 12:39:34.072 [ERROR] [e.smarthome.model.script.ThingStatus] - ZwaveNode10 is offline or doesn't exist.
2018-12-31 12:39:34.088 [ERROR] [e.smarthome.model.script.ThingStatus] - ZwaveNode8 is offline or doesn't exist.
2018-12-31 12:39:34.096 [ERROR] [e.smarthome.model.script.ThingStatus] - ZwaveNode5 is offline or doesn't exist.
2018-12-31 12:39:34.100 [ERROR] [e.smarthome.model.script.ThingStatus] - ZwaveNode5 is offline or doesn't exist.
2018-12-31 12:39:34.096 [ERROR] [e.smarthome.model.script.ThingStatus] - ZwaveNode11 is offline or doesn't exist.
2018-12-31 12:39:34.155 [ERROR] [e.smarthome.model.script.ThingStatus] - ZwaveNode11 is offline or doesn't exist.
2018-12-31 12:39:34.182 [ERROR] [e.smarthome.model.script.ThingStatus] - ZwaveNode3 is offline or doesn't exist.
2018-12-31 12:39:34.188 [ERROR] [e.smarthome.model.script.ThingStatus] - ZwaveNode8 is offline or doesn't exist.
2018-12-31 12:39:36.682 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2018-12-31 12:39:40.987 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D00019533D3: Starting ZigBee device discovery
2018-12-31 12:39:41.005 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00A05370: Starting ZigBee device discovery
2018-12-31 12:39:41.005 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 0017880102139D00: Starting ZigBee device discovery
2018-12-31 12:39:41.005 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 001788011032A21B: Starting ZigBee device discovery
2018-12-31 12:39:41.043 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:4beca465:0017880102139d00' to inbox.
2018-12-31 12:39:42.848 [ERROR] [e.smarthome.model.script.ThingStatus] - ZwaveNode3 is offline or doesn't exist.
2018-12-31 12:39:42.894 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Garageport moving': The name 'sendPushoverMessage' cannot be resolved to an item or type; line 24, column 1, length 86
2018-12-31 12:39:44.697 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Error during the execution of startup rule 'nilan date items concatenation': For input string: "NULL"
2018-12-31 12:39:44.704 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Garageport moving': The name 'sendPushoverMessage' cannot be resolved to an item or type; line 24, column 1, length 86
2018-12-31 12:39:44.708 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Garageport moving': The name 'sendPushoverMessage' cannot be resolved to an item or type; line 24, column 1, length 86
2018-12-31 12:39:48.352 [INFO ] [e.smarthome.model.script.ThingStatus] - ZwaveNode11 is online.
2018-12-31 12:39:48.361 [INFO ] [e.smarthome.model.script.ThingStatus] - ZwaveNode10 is online.
2018-12-31 12:39:48.381 [INFO ] [e.smarthome.model.script.ThingStatus] - ZwaveNode8 is online.
2018-12-31 12:39:48.403 [INFO ] [e.smarthome.model.script.ThingStatus] - ZwaveNode5 is online.
2018-12-31 12:39:48.410 [INFO ] [e.smarthome.model.script.ThingStatus] - ZwaveNode13 is online.
2018-12-31 12:39:48.422 [INFO ] [e.smarthome.model.script.ThingStatus] - ZwaveNode3 is online.
2018-12-31 12:39:54.958 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 0017880102139D00: Starting ZigBee device discovery
2018-12-31 12:39:54.988 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:4beca465:0017880102139d00' to inbox.
2018-12-31 12:40:15.966 [INFO ] [b.core.service.AbstractActiveService] - Expire Refresh Service has been started
2018-12-31 12:40:15.996 [INFO ] [b.core.service.AbstractActiveService] - IHC / ELKO LS refresh and notification listener service has been started
2018-12-31 12:40:16.000 [INFO ] [nhab.binding.ihc.internal.IhcBinding] - Connecting to IHC / ELKO LS controller [IP='10.4.28.6:777' Username='admin'].
2018-12-31 12:40:20.192 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2018-12-31 12:40:20.284 [ERROR] [org.openhab.binding.velux           ] - bundle org.openhab.binding.velux:2.3.0.201802142040 (259)[binding.velux] :  Cannot register component
org.osgi.service.component.ComponentException: The component name 'binding.velux' has already been registered by Bundle 259 (org.openhab.binding.velux) as Component of Class org.openhab.binding.velux.internal.VeluxHandlerFactory
	at org.apache.felix.scr.impl.ComponentRegistry.checkComponentName(ComponentRegistry.java:235) ~[39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.BundleComponentActivator.loadDescriptor(BundleComponentActivator.java:443) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialize(BundleComponentActivator.java:315) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.BundleComponentActivator.<init>(BundleComponentActivator.java:270) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:379) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.Activator.access$200(Activator.java:49) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:263) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.AbstractExtender.createExtension(AbstractExtender.java:196) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:169) [39:org.apache.felix.scr:2.1.2]
	at org.apache.felix.scr.impl.AbstractExtender.modifiedBundle(AbstractExtender.java:49) [39:org.apache.felix.scr:2.1.2]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482) [?:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415) [?:?]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232) [?:?]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444) [?:?]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:908) [?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:213) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:120) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:112) [?:?]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:168) [?:?]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:476) [?:?]
	at org.eclipse.osgi.container.Module.start(Module.java:467) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1634) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1614) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1585) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1528) [?:?]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) [?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [?:?]
2018-12-31 12:40:25.055 [INFO ] [eclipse.smarthome.model.script.debug] - First table clause
2018-12-31 12:40:25.055 [INFO ] [eclipse.smarthome.model.script.debug] - First table clause
2018-12-31 12:40:25.083 [INFO ] [eclipse.smarthome.model.script.debug] - Choose VeluxAlleLuk
2018-12-31 12:40:25.092 [INFO ] [ipse.smarthome.model.script.skylight] - Sending ON command to VeluxAlleLuk because OutsideTemp = 5.199999809265137 °C  Lux = 85.0 and Alarm = NULL
2018-12-31 12:40:25.103 [INFO ] [eclipse.smarthome.model.script.debug] - Choose VeluxAlleLuk
2018-12-31 12:40:25.446 [INFO ] [ipse.smarthome.model.script.skylight] - Sending ON command to VeluxAlleLuk because OutsideTemp = 5.199999809265137 °C  Lux = 85.0 and Alarm = NULL
2018-12-31 12:40:36.642 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00A05370: Starting ZigBee device discovery
2018-12-31 12:40:37.668 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Automatic control of all skylight windows': The name 'Override' cannot be resolved to an item or type; line 9, column 8, length 8
2018-12-31 12:40:41.907 [ERROR] [converter.ZigBeeConverterSwitchOnoff] - 001788011032A21B: Error 0xffff setting client binding
2018-12-31 12:40:48.071 [INFO ] [.eclipse.smarthome.model.script.info] - Skumring OFF Switch OFF Hue lamps
2018-12-31 12:40:48.966 [INFO ] [lipse.smarthome.model.script.PIR BIN] - HUE_Occu
2018-12-31 12:40:48.984 [INFO ] [lipse.smarthome.model.script.PIR BIN] - stue_pir
2018-12-31 12:40:48.988 [INFO ] [lipse.smarthome.model.script.PIR BIN] - spise_pir
2018-12-31 12:40:49.467 [INFO ] [lipse.smarthome.model.script.PIR BIN] - stue_pir
2018-12-31 12:40:49.488 [INFO ] [.eclipse.smarthome.model.script.info] - Total alarm is disarmed
2018-12-31 12:40:49.608 [INFO ] [ing.velux.handler.VeluxBridgeHandler] - Initializing Velux veluxBridge handler for 'velux:klf200:9b47bbbd'.
2018-12-31 12:40:49.993 [INFO ] [lipse.smarthome.model.script.PIR BIN] - spise_pir
2018-12-31 12:40:51.294 [INFO ] [lipse.smarthome.model.script.PIR BIN] - stue_pir
2018-12-31 12:40:52.263 [INFO ] [lipse.smarthome.model.script.PIR BIN] - spise_pir
2018-12-31 12:40:54.622 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'velux:klf200:9b47bbbd' takes more than 5000ms.
2018-12-31 12:40:54.992 [INFO ] [eclipse.smarthome.model.script.debug] - First table clause
2018-12-31 12:40:55.009 [INFO ] [eclipse.smarthome.model.script.debug] - Choose VeluxAlleLuk
2018-12-31 12:40:55.021 [INFO ] [ipse.smarthome.model.script.skylight] - Sending ON command to VeluxAlleLuk because OutsideTemp = 5.400000095367431640625 °C  Lux = 85.0 and Alarm = OFF
2018-12-31 12:40:55.093 [INFO ] [b.binding.velux.handler.VeluxHandler] - handleCommand() cannot activate unknown scene: Alle_vinduer_luk.
2018-12-31 12:41:03.658 [INFO ] [lipse.smarthome.model.script.PIR BIN] - stue_pir
2018-12-31 12:41:03.658 [INFO ] [lipse.smarthome.model.script.PIR BIN] - spise_pir
2018-12-31 12:41:03.673 [INFO ] [e.smarthome.model.script.ThingStatus] - Trust motion sensor is online.
2018-12-31 12:41:03.771 [INFO ] [lipse.smarthome.model.script.PIR BIN] - HUE_Occu
2018-12-31 12:41:04.986 [INFO ] [lipse.smarthome.model.script.PIR BIN] - stue_pir
2018-12-31 12:41:05.731 [INFO ] [lipse.smarthome.model.script.PIR BIN] - spise_pir
2018-12-31 12:41:06.883 [INFO ] [lipse.smarthome.model.script.PIR BIN] - stue_pir
2018-12-31 12:41:10.315 [INFO ] [ing.velux.handler.VeluxBridgeHandler] - handleCommand() found scenes 14 members: Scene "Stue 50%" (index 4) with silent mode and 4 actions,Scene "Køkken 75%" (index 10) with silent mode and 2 actions,Scene "Stue 75%" (index 14) with silent mode and 4 actions,Scene "Spisestue 100%" (index 6) with silent mode and 2 actions,Scene "Spisestue 50%" (index 3) with silent mode and 2 actions,Scene "Stue 100%" (index 7) with silent mode and 4 actions,Scene "Spisestue 75%" (index 12) with silent mode and 2 actions,Scene "Alle_vinduer_åbne_50" (index 8) with silent mode and 8 actions,Scene "Alle_vinduer_aaben_100" (index 1) with silent mode and 8 actions,Scene "Alle_vinduer_75" (index 17) with silent mode and 8 actions,Scene "Alle_vinduer_luk" (index 0) with silent mode and 8 actions,Scene "Alle_vinduer_vent" (index 15) with silent mode and 8 actions,Scene "Køkken 100%" (index 5) with silent mode and 2 actions,Scene "Køkken 50%" (index 2) with silent mode and 2 actions.
2018-12-31 12:41:11.504 [INFO ] [lipse.smarthome.model.script.PIR BIN] - spise_pir
2018-12-31 12:41:12.433 [INFO ] [lipse.smarthome.model.script.PIR BIN] - stue_pir
2018-12-31 12:41:13.661 [INFO ] [lipse.smarthome.model.script.PIR BIN] - spise_pir
2018-12-31 12:41:13.739 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D00019533D3: Starting ZigBee device discovery

But I guess I wouldn´t know for sure, untill I clear the cache and tmp as well and then reboot again?

hilbrand · December 31, 2018, 12:10pm

You can ignore that warning, See comment: "Low configured threads" warning - #15 by wborn

I also tried the velux jar and got the same error. I think something is wrong with that binding. I saw there is a 2.4 version also: https://github.com/gs4711/org.openhab.binding.velux You might what to try that one instead.

Kim_Andersen · December 31, 2018, 12:23pm

I hate it when people say, “just ignore…”. It isn´t suppose to be there. And specially when things are acting up, it´s highly difficult to “just ignore”.

Thanks for testing this Hilbrand, and getting the same error… Thats an relief.
I do know there is a newer version… I´m just not prepared to update yet, as I believe it requires updating the firmware of the KLF200 gateway as well… And I havn´t had time to do that yet. But it´s on my todo list.
I stil hate it, that things acting up, when upgrading openhab…

Well, I´m going to stop openhab, clear the cache and tmp… Then we´ll se what happens. After that, I´ll test if I can get openhab to crash showing two grafana charts in a sitemap. If it does crash, it is going take untill to the next year to fix

Kim_Andersen · December 31, 2018, 12:50pm

Cleared cache and tmp… Start went surprisingly well… Only a few errors releated to the startup procedure…

But when I entered PaperUI and BasicUI, then this happened:

Log:
openhab_log.txt (71.7 KB)

After the above fatal erros, the system just continued to run without problems. And I could enter PaperUI and BasicUI fine.
Entering a sitemap having two Grafana charts - Took a while to render and show, but it succeded with crashing openhab.

Weird!

EDIT…
Well, staying in the sitemap with two grafana charts was not a good idea. This happened a few seconds after:

2018-12-31 13:49:02.491 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@1496e82' takes more than 5000ms.
2018-12-31 13:49:02.853 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:02.951 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:02.957 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:02.965 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:02.970 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:02.972 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:02.979 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:02.987 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:02.989 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:03.019 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:03.052 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:03.056 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:03.059 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:03.068 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:03.071 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:03.078 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-31 13:49:03.085 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.

And it took down, zigbee binding, chromecast binding, Unifi binding. Chromecast and Unifi binding returned to online by themselves, zigbee didn´t (I knew zigbee wouldnt as Chris has mentioned that in another thread).

I guess Grafana isn´t a good option in my system anymore… Just wish I could find the cause. Maybe later…

hilbrand · December 31, 2018, 12:50pm

If I’m correct the 2.4 binding jar I referred to supports the 1.x version. Looking at the commit history it was added before activity on the version 2 support started, but Guenther @gs4711 might be able to give a definite answer.

Kim_Andersen · December 31, 2018, 12:58pm

I will test then new Velux binding later. I guess it could not harm my system any more

H102 · December 31, 2018, 2:47pm

The RPI may not be the best hardware as memory is limited to 1G and Grafana can sometimes get memory hungry. I know several others run this on their RPI without issue but for troubleshooting maybe try not using Grafana and see what happens.

Best of Luck

Kim_Andersen · January 1, 2019, 5:29pm

I know. But when running openhab 2.3 is was running rock stable. After updating openhab to 2.4, problems started to fall in on me. I find it odd that this should be a hardware issue.

Kim_Andersen · January 1, 2019, 6:21pm

Some news…
I have uninstalled Grafana and updated the Velux binding.
I then stopped openhab and made a reboot, and things looked pretty good.
Then I stopped openhab again, cleared the cache and tmp folder, and made a new reboot…

The very first thing that happens from the reboot after clearing cache and tmp is this:

==> /var/log/openhab2/openhab.log <==

2019-01-01 19:12:15.904 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.binding.zigbee-2.5.0-SNAPSHOT.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.zigbee [197]
  Unresolved requirement: Import-Package: gnu.io
	at org.eclipse.osgi.container.Module.start(Module.java:444) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[?:?]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startAllBundles(DirectoryWatcher.java:1221) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:515) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [10:org.apache.felix.fileinstall:3.6.4]
2019-01-01 19:12:15.951 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.binding.zigbee.ember-2.5.0-SNAPSHOT.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.zigbee.ember [194]
  Unresolved requirement: Import-Package: gnu.io
	at org.eclipse.osgi.container.Module.start(Module.java:444) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[?:?]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startAllBundles(DirectoryWatcher.java:1221) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:515) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [10:org.apache.felix.fileinstall:3.6.4]
2019-01-01 19:12:15.990 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.binding.zigbee-2.5.0-SNAPSHOT.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.zigbee [197]
  Unresolved requirement: Import-Package: gnu.io
	at org.eclipse.osgi.container.Module.start(Module.java:444) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[?:?]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:520) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [10:org.apache.felix.fileinstall:3.6.4]
2019-01-01 19:12:15.998 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.binding.zigbee.ember-2.5.0-SNAPSHOT.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.zigbee.ember [194]
  Unresolved requirement: Import-Package: gnu.io
	at org.eclipse.osgi.container.Module.start(Module.java:444) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[?:?]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:520) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [10:org.apache.felix.fileinstall:3.6.4]

Zigbee do start allright later in the process. I just wonder why I get this warning. @chris ??

Rest of the startup process went fine, including zigbee.

Kim_Andersen · January 1, 2019, 10:13pm

I´m about to clean up my system for “stuff” I think I dont need anymore.
I have three files in my addons folder, which manually was installed long time ago when I installed the Unifi binding. I was told they were needed. But if I remove them from the folder, the Unifi binding still works fine…

So my question is. Does anyone know if these three files are needed:
jackson-annotations-2.9.1.jar
jackson-core-2.9.1.jar
jackson-databind-2.9.1.jar

And what exactly do they do?

Maybe @mgbowman can supply with some info here?

chris · January 1, 2019, 10:42pm

I think we’ve discussed this in other threads already - the error means that it can’t resolve the dependencies - the specific dependency that is missing is the serial driver.

Other than that I can’t really say what is happening.

mgbowman · January 2, 2019, 7:21am

I think those were left over from an old UniFi version that used Jackson for the JSON processing. I think you can safely delete those as the binding now uses GSON that’s provided by the framework.

Kim_Andersen · January 2, 2019, 2:31pm

Okay, thank you Matthew…