[zwave] openHAB 2.5.0 Build #1723 exception during startup

[Bruce_Osborne]

Is that a snapshot build?
The log viewer may help point out the flow better.

https://www.cd-jackson.com/index.php/openhab/zwave-log-viewer

[rlkoshak (Rich Koshak)]

Yes, yesterday’s snapshot. I used the log viewer but it doesn’t show anything different than the above. Before I updated from a snapshot from some time last week to the most recent snapshot everything worked fine. With yesterday’s snapshot I get the above errors and warnings and my batter powered devices appear not to work.

[mhilbush (Mark)]

I’m seeing this at startup in the latest snapshot, too. The system where it’s installed loads the zwave binding, but currently has no zwave things defined (including the serial controller).

[michaeljoos]

Did update today from 1721 to 1725 and can confirm the startup error. But my battery powered door sensor from Aeotec does still work. It’s the only zwave sensor I have in my system…

[5iver (Scott Rushworth)]

I just updated to S1725. I get the exception…

2019-10-15 13:22:00.560 [ERROR] [org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker] - Could not send adding finished event for the module 'org.openhab.binding.zwave'!
java.lang.IllegalArgumentException: UID must have at least 2 segments.
        at org.eclipse.smarthome.core.common.AbstractUID.<init>(AbstractUID.java:70) ~[133:org.openhab.core:2.5.0.201910150342]
        at org.eclipse.smarthome.core.common.AbstractUID.<init>(AbstractUID.java:49) ~[133:org.openhab.core:2.5.0.201910150342]
        at org.eclipse.smarthome.core.thing.UID.<init>(UID.java:48) ~[?:?]
        at org.eclipse.smarthome.core.thing.type.ChannelTypeUID.<init>(ChannelTypeUID.java:40) ~[?:?]
        at org.eclipse.smarthome.core.thing.xml.internal.ChannelXmlResult.toChannelDefinition(ChannelXmlResult.java:135) ~[?:?]
        at org.eclipse.smarthome.core.thing.xml.internal.ThingTypeXmlResult.toChannelDefinitions(ThingTypeXmlResult.java:94) ~[?:?]
        at org.eclipse.smarthome.core.thing.xml.internal.ThingTypeXmlResult.getBuilder(ThingTypeXmlResult.java:145) ~[?:?]
        at org.eclipse.smarthome.core.thing.xml.internal.ThingTypeXmlResult.toThingType(ThingTypeXmlResult.java:153) ~[?:?]
        at org.eclipse.smarthome.core.thing.xml.internal.ThingTypeXmlProvider.addingFinished(ThingTypeXmlProvider.java:147) ~[?:?]
        at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.addingFinished(XmlDocumentBundleTracker.java:265) [142:org.openhab.core.config.xml:2.5.0.201910150357]
        at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.parseDocuments(XmlDocumentBundleTracker.java:424) [142:org.openhab.core.config.xml:2.5.0.201910150357]
        at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.processBundle(XmlDocumentBundleTracker.java:398) [142:org.openhab.core.config.xml:2.5.0.201910150357]
        at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.access$6(XmlDocumentBundleTracker.java:393) [142:org.openhab.core.config.xml:2.5.0.201910150357]
        at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$2.run(XmlDocumentBundleTracker.java:363) [142:org.openhab.core.config.xml:2.5.0.201910150357]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
        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) [?:?]

… at startup and a LOT of ThingTypes cannot be identified. These are not just battery powered.

2019-10-15 13:46:28.192 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 88: Device discovery could not resolve to a thingType! 014F:2005:0503::1.65
2019-10-15 13:46:28.212 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 223: Device discovery could not resolve to a thingType! 0109:201A:1AA4::15.10
2019-10-15 13:46:28.200 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 133: Device discovery could not resolve to a thingType! 003B:6341:5044::113.22
2019-10-15 13:46:28.211 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 122: Device discovery could not resolve to a thingType! 011A:0601:0901::5.10
2019-10-15 13:46:28.217 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 87: Device discovery could not resolve to a thingType! 014F:2005:0503::1.65
2019-10-15 13:46:28.211 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 18: Device discovery could not resolve to a thingType! 001D:1B03:0334::0.7
2019-10-15 13:46:28.186 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 7: Device discovery could not resolve to a thingType! 001D:1C02:0334::0.7
2019-10-15 13:46:28.210 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 225: Device discovery could not resolve to a thingType! 0086:0003:0006::1.43
2019-10-15 13:46:28.210 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 226: Device discovery could not resolve to a thingType! 0086:0003:0006::1.43
2019-10-15 13:46:28.202 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 6: Device discovery could not resolve to a thingType! 001D:1B03:0334::0.7
2019-10-15 13:46:28.201 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 19: Device discovery could not resolve to a thingType! 001D:1B03:0334::0.7
2019-10-15 13:46:28.205 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 140: Device discovery could not resolve to a thingType! 014F:2005:0503::1.65
2019-10-15 13:46:28.154 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 120: Device discovery could not resolve to a thingType! 0109:201A:1AA4::15.10
2019-10-15 13:46:28.210 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 224: Device discovery could not resolve to a thingType! 0086:0003:0006::1.43
2019-10-15 13:46:28.229 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 14: Device discovery could not resolve to a thingType! 001D:1C02:0334::0.7
2019-10-15 13:46:28.272 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 230: Device discovery could not resolve to a thingType! 0086:0002:0009::3.64
2019-10-15 13:46:28.287 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 216: Device discovery could not resolve to a thingType! 0109:201A:1AA4::15.10
2019-10-15 13:46:28.292 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 142: Device discovery could not resolve to a thingType! 003B:6341:5044::113.22
2019-10-15 13:46:28.302 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 231: Device discovery could not resolve to a thingType! 0086:0002:0009::3.64
2019-10-15 13:46:28.228 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 218: Device discovery could not resolve to a thingType! 0109:201A:1AA4::15.10
2019-10-15 13:46:28.219 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 227: Device discovery could not resolve to a thingType! 0086:0003:0006::1.43
2019-10-15 13:46:28.218 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 228: Device discovery could not resolve to a thingType! 0086:0003:0006::1.43
2019-10-15 13:46:28.215 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 137: Device discovery could not resolve to a thingType! 001D:1C02:0334::0.7
2019-10-15 13:46:28.284 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 229: Device discovery could not resolve to a thingType! 0086:0002:0009::3.64
2019-10-15 13:46:28.288 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 232: Device discovery could not resolve to a thingType! 0086:0002:0009::3.64
2019-10-15 13:46:28.236 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 221: Device discovery could not resolve to a thingType! 0109:201A:1AA4::15.10
2019-10-15 13:46:28.207 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 183: Device discovery could not resolve to a thingType! 003B:6341:5044::113.22
2019-10-15 13:46:28.209 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 121: Device discovery could not resolve to a thingType! 011A:0601:0901::5.10
2019-10-15 13:46:28.204 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 13: Device discovery could not resolve to a thingType! 001D:1C02:0334::0.7
2019-10-15 13:46:28.207 [WARN ] [org.openhab.binding.zwave.discovery.ZWaveDiscoveryService] - NODE 17: Device discovery could not resolve to a thingType! 001D:1B03:0334::0.

This is odd, since I had the same issue after the resync for some devices, but I got them fixed up. After @chris exported and did a build, the devices worked again. The same devices are affected now, plus many other types.

From a quick look, the Thing XMLs for these devices all appear to have multiple manufacturerRef. There have been two recent commits to the zwave binding. Has anyone tried an older version of the binding and gotten the same results? The exception does not occur after downgrading to 2.5.0.201910040432 and all the Thing XMLs could be read, so this is likely due to a recent zwave PR.

[AndyMB (Andy)]

Me too: posted my symptoms in this post (before reading this thread - lesson learnt ):

[SOLVED] Z-Wave supported devices missing

Hi, @kdsnet3410 you are not alone While trying to sort out a defective z-wave motion sensor I took the opportunity to upgrade to the latest snapshot (1724 ?). I also had a number of things marked for deletion (as shown in Kevin’s habmin screenshot). I deleted these and then re-scanned the network using paper UI. All items were discovered but could not be found within the z-wave device database. Turned on debug logging. Deleted items were all previously working / matched in the devic…

[5iver (Scott Rushworth)]

@Bruce_Osborne, if you are running 2.5M3, could you try running the script to get the latest snapshot version of the binding? This would further confirm this is a binding issue and not something in core.

[Bruce_Osborne]

I have a test build with a new controller & 1 device iun a VM rhat I set up last night. Is that sufficient or do I need more devices?

[mhilbush (Mark)]

You shouldn’t need any devices. I get the exception with just the binding installed and no devices (including no controller thing).

[rlkoshak (Rich Koshak)]

I went ahead and created the issue.

Issue: UID must have at least 2 segments.

[Bruce_Osborne]

I got the 2 minute uninstall error.
I will uninstall te binding manually now.

[5iver (Scott Rushworth)]

Hold up…

[Bruce_Osborne]

Too late. The files seemed to get copied but the script timed out. Restarting OH.

[5iver (Scott Rushworth)]

@Bruce_Osborne

Too late.

The cause is known, Chris did a db update, and the current build has the fix and is ready for download. I’ve tested and everything ran without exceptions. I’ve also pushed a fix for the install script, so it should be working now !

[Bruce_Osborne]

I need to download a new install script?
It would be helpful for those of us with short memories to link to the location we are supposed to install the script to. It took me some digging.
I did not realize your script worked with M3.

UPDATE:
Downloaded the script, selected snapshot & the binding appears to be working.

[5iver (Scott Rushworth)]

@Bruce_Osborne

I need to download a new install script?

The script checks for updates when you run it and will prompt you if you’d like to update when the version of your script is out of date.

[Bruce_Osborne]

So, the fix made it into the latest snapshot?
GitHub says it was updated 2 hours ago & the snapshot binding was built 2 hr 6 minutes ago.

[5iver (Scott Rushworth)]

Yes. The fix…

Database update

[AndyMB (Andy)]

Thanks @chris that’s fixed my issues. Appreciate the speedy fix.

[rlkoshak (Rich Koshak)]

@Bruce_Osborne

So, the fix made it into the latest snapshot?

Actually I don’t think it will appear in the actual OH snapshot (i.e. for those of us who install through PaperUI et al) until tomorrow, right? The current SNAPSHOT is still 1725 as far as I can tell, unless the snapshot build happened in the last hour or so.