Since upgrading to unstable 1104/1106 OH2.2.0 doesnt run

Just to confirm that’s after making sure the quotes are gone from both /etc/openhab2/services/addons.cfg and /var/lib/openhab2/etc/org.openhab.addons.cfg, before restarting? Do the the quotes come back?

I agree with @Benjy - the quotes in the /etc/openhab2/services/addons.cfg are definitely wrong (and I assume you entered them yourself? If so, do you remember why? Do we have a flaw anywhere in the documentation?).

I very much expect the problem to be solved if you stop your openHAB, clean both cfg files from the quotes and then restart.

1 Like

I have just done something slightly different - I have gone into Openhabian Configuration tool, selected openHAB related, then openHAB 2.2 unstable, and let it do its thing.

OH restarted itself, there are no untoward entries in the log, and I now have quotes around the entries in /etc/openhab2/services/addons.cfg and no UIs showing up on the dashboard.

That is literally the only thing I did.

Edit: I have manually removed the quotes from that file, and restarted OH. It came back up again OK. However, when stopping the service, the quotes have reappeared.

So I see multiple posts on the Blacklisting problems, and I also got hit with again last night. It seems this time the first black list error hit about midnight. Then the last item in my events log is at 6am.

Per @Kai I also did change this yesterday afternoon, by stopping OH2, making change and restarting.
could you try to edit two lines in the file etc/org.apache.felix.fileinstall-deploy.cfgto:

felix.fileinstall.start.level = 100
felix.fileinstall.active.level = 100

I may back up my system later due a uninstall/purgh of OH2, then reinstall from scratch and restore to see if makes any difference. Perhaps moving from a past stable/beta to testing is doing something?

The Event log around midnight

2017-12-06 00:43:15.049 [vent.ItemStateChangedEvent] - astro_moon_home_position_azimuth changed from 123.68 to 123.98
2017-12-06 00:43:25.854 [vent.ItemStateChangedEvent] - astro_moon_home_position_elevation changed from 55.14 to 55.29
2017-12-06 00:43:25.855 [vent.ItemStateChangedEvent] - Moon_Azimuth changed from 123.68 to 123.98
2017-12-06 00:43:26.664 [vent.ItemStateChangedEvent] - zwave_serial_zstick_1587fb1d72a_serial_sof changed from 2990 to 2991
2017-12-06 00:43:26.669 [vent.ItemStateChangedEvent] - zwave_serial_zstick_1587fb1d72a_serial_ack changed from 2053 to 2054
2017-12-06 00:43:26.669 [vent.ItemStateChangedEvent] - zwave_serial_zstick_1587fb1d72a_serial_sof changed from 2991 to 2992
2017-12-06 00:43:26.674 [vent.ItemStateChangedEvent] - zwave_serial_zstick_1587fb1d72a_serial_ack changed from 2054 to 2055
2017-12-06 00:43:26.675 [vent.ItemStateChangedEvent] - zwave_serial_zstick_1587fb1d72a_serial_sof changed from 2992 to 2993
2017-12-06 00:43:26.746 [vent.ItemStateChangedEvent] - zwave_serial_zstick_1587fb1d72a_serial_ack changed from 2055 to 2056
2017-12-06 00:43:26.748 [vent.ItemStateChangedEvent] - zwave_serial_zstick_1587fb1d72a_serial_sof changed from 2993 to 2994
2017-12-06 00:43:27.276 [vent.ItemStateChangedEvent] - Moon_Elevation changed from 55.14 to 55.29

and OH log at same time.

2017-12-06 00:00:45.377 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest finished.
2017-12-06 00:30:00.015 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest executed...
2017-12-06 00:30:00.066 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '[phantomjs, /etc/openhab2/scripts/weather.js]'
2017-12-06 00:30:42.541 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest finished.
2017-12-06 00:43:26.849 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.apache.karaf.event.service.EventCollector}={event.topics=*, service.id=129, service.bundleid=53, service.scope=singleton} | Bundle(org.apache.karaf.event_4.1.3 [53])] due to timeout!
2017-12-06 00:43:27.273 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.apache.karaf.event.service.EventCollector}={event.topics=*, service.id=129, service.bundleid=53, service.scope=singleton} | Bundle(org.apache.karaf.event_4.1.3 [53])] due to timeout!
2017-12-06 01:00:00.013 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest executed...
2017-12-06 01:00:00.319 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '[phantomjs, /etc/openhab2/scripts/weather.js]'
2017-12-06 01:00:40.668 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest finished.

And last entries at 6am in the Event

017-12-06 06:00:08.814 [vent.ItemStateChangedEvent] - Wunderground_WindSpeed changed from 5.0 to 8.0
2017-12-06 06:00:11.219 [hingStatusInfoChangedEvent] - 'zwave:device:1587fb1d72a:node20' changed from OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controller to ONLINE
2017-12-06 06:00:17.375 [vent.ItemStateChangedEvent] - zwave_serial_zstick_1587fb1d72a_serial_sof changed from 6732 to 6733
2017-12-06 06:00:17.378 [vent.ItemStateChangedEvent] - Wunderground_WindChill changed from -2 to -4
2017-12-06 06:00:17.411 [vent.ItemStateChangedEvent] - zwave_device_1587fb1d72a_node20_meter_watts changed from 967.123 to 916.646
2017-12-06 06:00:17.411 [vent.ItemStateChangedEvent] - Home_Energy_Watts changed from 967.123 to 916.646
2017-12-06 06:00:17.411 [vent.ItemStateChangedEvent] - Wunderground_FeelTemp changed from -2 to -4
2017-12-06 06:00:17.411 [vent.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2017-12-06T05:59:13.258-0500 to 2017-12-06T06:00:17.371-0500
2017-12-06 06:00:17.411 [vent.ItemStateChangedEvent] - Date changed from 2017-12-06T05:59:13.258-0500 to 2017-12-06T06:00:17.371-0500
2017-12-06 06:00:17.411 [vent.ItemStateChangedEvent] - CTime changed from 2017-12-06T05:59:13.258-0500 to 2017-12-06T06:00:17.371-0500
2017-12-06 06:00:17.412 [vent.ItemStateChangedEvent] - CurrentDate changed from 2017-12-06T05:59:13.258-0500 to 2017-12-06T06:00:17.371-0500
2017-12-06 06:00:17.460 [vent.ItemStateChangedEvent] - ntp_ntp_local_string changed from 2017-12-06 05:59:13 EST to 2017-12-06 06:00:17 EST

And the OH2 log

2017-12-06 05:30:44.878 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest finished.
2017-12-06 06:00:00.008 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest executed...
2017-12-06 06:00:00.098 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '[phantomjs, /etc/openhab2/scripts/weather.js]'
2017-12-06 06:00:17.787 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=49, service.id=147, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
2017-12-06 06:00:17.992 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=49, service.id=147, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
2017-12-06 06:00:45.963 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest finished.
2017-12-06 06:28:54.843 [ERROR] [t.mqtt.internal.MqttBrokerConnection] - MQTT connection to broker was lost
org.eclipse.paho.client.mqttv3.MqttException: Connection lost
	at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:146) [231:org.openhab.io.transport.mqtt:1.11.0.201712040209]
	at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.io.EOFException
	at java.io.DataInputStream.readByte(DataInputStream.java:267) ~[?:?]
	at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:65) ~[?:?]
	at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:107) ~[?:?]
	... 1 more
2017-12-06 06:28:55.048 [ERROR] [io.openhabcloud.internal.CloudClient] - Socket.IO error: {}
io.socket.engineio.client.EngineIOException: websocket error
	at io.socket.engineio.client.Transport.onError(Transport.java:71) [230:org.openhab.io.openhabcloud:2.2.0.201712041044]
	at io.socket.engineio.client.transports.WebSocket.access$500(WebSocket.java:28) [230:org.openhab.io.openhabcloud:2.2.0.201712041044]
	at io.socket.engineio.client.transports.WebSocket$2$5.run(WebSocket.java:150) [230:org.openhab.io.openhabcloud:2.2.0.201712041044]
	at io.socket.thread.EventThread$2.run(EventThread.java:80) [230:org.openhab.io.openhabcloud:2.2.0.201712041044]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.io.EOFException
	at okio.RealBufferedSource.require(RealBufferedSource.java:59) ~[?:?]
	at okio.RealBufferedSource.readByte(RealBufferedSource.java:72) ~[?:?]
	at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.java:115) ~[?:?]
	at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.java:104) ~[?:?]
	at okhttp3.internal.ws.RealWebSocket.readMessage(RealWebSocket.java:97) ~[?:?]
	at okhttp3.ws.WebSocketCall.createWebSocket(WebSocketCall.java:152) ~[?:?]
	at okhttp3.ws.WebSocketCall.access$000(WebSocketCall.java:41) ~[?:?]
	at okhttp3.ws.WebSocketCall$1.onResponse(WebSocketCall.java:97) ~[?:?]
	at okhttp3.RealCall$AsyncCall.execute(RealCall.java:126) ~[?:?]
	at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32) ~[?:?]
	... 3 more
2017-12-06 06:28:57.516 [ERROR] [t.mqtt.internal.MqttBrokerConnection] - MQTT connection to 'mosquitto' was lost: Connection lost : ReasonCode 32109 : Cause : null
2017-12-06 06:28:57.517 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting connection helper to periodically try restore connection to broker 'mosquitto'
2017-12-06 06:28:58.065 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = 5e173177-a9ee-47cc-a2bb-ec0f655ee0f8, base URL = http://localhost:8080)
2017-12-06 06:29:06.812 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 5e173177-a9ee-47cc-a2bb-ec0f655ee0f8, base URL = http://localhost:8080)
2017-12-06 06:29:08.658 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mosquitto'
2017-12-06 06:30:01.732 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest executed...
2017-12-06 06:30:01.857 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '[phantomjs, /etc/openhab2/scripts/weather.js]'
2017-12-06 06:30:42.025 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest finished.

Thanks for the further tests, @ptmuldoon!

This change was only for addressing your startup problems with bundles in the addons folder (not about the blacklisting). Can I assume from your latest logs (where you do not mention such exceptions anymore) that those are solved? Or did it only happen at the first start after an upgrade? Then yes, doing a backup/restore should show whether the problem still exists.

Regarding your logs: If I understand it right, although you had a hick-up at 00:43, your system continued to work until 06:00, correct?
What exactly happened at 06:28? Both MQTT and openHAB-Cloud seem to have lost their connection - did you cut off the Internet or shut down your instance at that moment?

No idea if I would have lost internet in the middle of the night so uncertain their. And yes, possible increasing the timeing to 100 took care of the addon’s problem.

Yes, it appears things still worked till about 6am as I see that is the last time my Wunderground posting. And I see you asked for a jstack log, so I ran one as I have yet to reboot the system yet. And I was forced to use the -F option.

ptmuldoon@OpenHab2:~$ sudo jstack 12432 > stack.txt
12432: Unable to open socket file: target process not responding or HotSpot VM not loaded
The -F option can be used when the target process is not responding
ptmuldoon@OpenHab2:~$ sudo jstack -F 12432 > stack.txt

Note, change extension back to txt if you can download it.

stack.xml (155.8 KB)

Thanks for the thread dump! (even though I cannot find anything really suspicious in it…)

My addons.config file appears to be being updated with the added quotes as OH starts.

@Kai I configured nearly nothing by myself and i got the same problem like @Confused.

@Benjy

/etc/openhab2/services/addons.cfg

package = expert

remote = true

ui = "paper,basic"

/var/lib/openhab2/etc/org.openhab.addons.cfg


package = expert
ui = paper,basic
transformation = map,regex,xslt,exec,javascript,scale,xpath,jsonpath
remote = true
binding = homematic,milight,wol1,network
misc = restdocs,openhabcloud,ruleengine

EDIT:
After updating to the latest build(openHAB 2.2.0 Build #1114), i can confirm the problem is gone.
First i had to remove the quotes once, but then everything seems to be fine.
Even after a reboot or a service restart.

EDIT2
Tested twice - problem seems to be solved!

Well done ! :slight_smile:

1 Like

Just gone from a rebuilt 1112 on clean OS, to 1114 via ‘apt-get install openhab2’, and stuck again at the very same place.

‘Please wait, loading UIs’…

Damnit!

May not help @Vini but I had a basic functional 1112, did an ‘apt-get update’ to 1114 seemed to go OK but OH wasn’t happy after start, log showed loading the items and things but never UI. Was wondering then how it handles the addons update because I’m running ‘online addons’ at the moment so decided maybe then OH was busy trying to do the addon updates to match core so I restarted OH after 5 minutes or so and it came up fine with the UIs, I hadn’t changed/fixed anything else.

Is it safe to start using the addons package again?

There seems to be a problem with the bindings. can’t find any bindings anymore ?
Probably a problem with the online repo?

I never understood “offline/online” addons. I always used to install openhab2-addons until I first encountered this issue and opened this thread.

After learning about online bindings and getting in such a mess, when I rebuilt, I didn’t install “openhab2-addons” and it worked.

Many reboots, were performed at 1112, then, sure enough, as soon as I updated (to 1114) the problem has returned. The service starts, everything seems to load, but no UIs (and no functionality). I gave it 8 hours and it was sat ‘loading’, I’ve just bounced it now, will see what happens. I’m not confident.

Time & a reboot seems to have helped. Like you say @RayMYP, it must have been grabbing the bindings etc…

Perhaps some notification on the loading screen of whats happening behind the scenes could be useful, as opposed to a static/generic message and spinner??

I have a clean installation of 1114. There’s nothing at all. Only after the installation was selected - standard (3 interfaces were installed). Upgrade to 1115, the result is like you, there are no interfaces until you reboot. I think addons are not to do with it.

Had the Blacklist hit me again at 6:36am this morning. This has been recurring each morning right about this time each day.

I will create a separate test VM running Ubuntu 16 later today, Then install OH2 latest snapshop with perhaps just the ntp binding installed and then see what happens tomorrow AM with that one.

Looks like same/similar errors in the log. And I did confirm this morning my home has not lost internet service, with my modem uptime showing up for last 7+ days.

2017-12-07 05:30:37.779 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest finished.
2017-12-07 06:00:00.011 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest executed...
2017-12-07 06:00:00.060 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '[phantomjs, /etc/openhab2/scripts/weather.js]'
2017-12-07 06:00:38.787 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest finished.
2017-12-07 06:36:49.638 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=31, service.id=136, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
2017-12-07 06:36:49.649 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest executed...
2017-12-07 06:36:49.863 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=31, service.id=136, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
2017-12-07 06:36:50.184 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=31, service.id=136, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
2017-12-07 06:36:50.185 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, org.eclipse.smarthome.core.events.EventPublisher}={event.topics=smarthome, component.name=org.eclipse.smarthome.core.internal.events.OSGiEventManager, component.id=31, service.id=136, service.bundleid=111, service.scope=bundle} | Bundle(org.eclipse.smarthome.core_0.9.0.201712011551 [111])] due to timeout!
2017-12-07 06:36:50.625 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '[phantomjs, /etc/openhab2/scripts/weather.js]'
2017-12-07 06:36:50.663 [ERROR] [o.client.mqttv3.internal.ClientState] - openhabserver: Timed out as no write activity, keepAlive=60,000 lastOutboundActivity=1,512,646,120,283 lastInboundActivity=1,512,646,120,283 time=1,512,646,598,691 lastPing=1,512,646,120,283
2017-12-07 06:36:52.445 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = 5e173177-a9ee-47cc-a2bb-ec0f655ee0f8, base URL = http://localhost:8080)
2017-12-07 06:36:53.081 [ERROR] [t.mqtt.internal.MqttBrokerConnection] - MQTT connection to broker was lost
org.eclipse.paho.client.mqttv3.MqttException: Connection lost
	at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:146) [231:org.openhab.io.transport.mqtt:1.11.0.201712060210]
	at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.io.EOFException
	at java.io.DataInputStream.readByte(DataInputStream.java:267) ~[?:?]
	at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:65) ~[?:?]
	at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:107) ~[?:?]
	... 1 more
2017-12-07 06:36:55.173 [ERROR] [t.mqtt.internal.MqttBrokerConnection] - MQTT connection to 'mosquitto' was lost: Connection lost : ReasonCode 32109 : Cause : null
2017-12-07 06:36:55.173 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting connection helper to periodically try restore connection to broker 'mosquitto'
2017-12-07 06:37:05.174 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mosquitto'
2017-12-07 06:37:06.415 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 5e173177-a9ee-47cc-a2bb-ec0f655ee0f8, base URL = http://localhost:8080)

@ptmuldoon Latest distro #1117 now comes with deactivated blacklisting - you should therefore not encounter the issue anymore…

Ok, That’s good news. I froze up again this morning at 6:41am per the logs, and will upgrade now to 1117 and see how tomorrow goes.

Seems like it’s not fixed and made it into the release. 2.2 stable and I am getting

23:16:58.564 [WARN ] [org.apache.karaf.services.eventadmin ] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler}={event.topics=openhab/*, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=247, service.id=385, service.bundleid=236, service.scope=bundle} | Bundle(org.openhab.binding.mqtt_1.11.0 [236])] due to timeout!
23:16:58.616 [WARN ] [org.apache.karaf.services.eventadmin ] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler}={event.topics=openhab/*, component.name=org.openhab.binding.mqtt.MqttItemBinding, component.id=247, service.id=385, service.bundleid=236, service.scope=bundle} | Bundle(org.openhab.binding.mqtt_1.11.0 [236])] due to timeout! 

Normally I wouldn’t really care, but this is preventing my MQTT from sending data. Great, now 90% of the house stopped working.

Reinstalling MQTT Binding fixed it. I don’t care about the blacklisted messages now anymore.

1 Like