WEMO Insight Switch not initalized after start openHAB2

Setup, Configuration and Use Runtime
1

Hello,

I’m using 4 WEMO Insight Switches.

I have configure the things and the items in files.
If I start openHAB2 the things were added, initialized and then the state switches to online.

Then I start the classicUI:
The state of the items shows OFF (that is wrong), and the currentPower is not set.

Then I rename the file _default.things to _default.things.xxx.
After a few seconds I rename the file back to _default.things.

Now the state of the items shows ON (that is correct), and the currentPower is set to the correct value.

What is wrong?

Greetings
Horst

events.log (first start)
–>
2016-10-29 18:45:17.951 [ItemChannelLinkAddedEvent ] - Link ‘waschmaschineOgEnergyTotal-wemo:insight:Insight2:energyTotal’ has been added.
2016-10-29 18:45:17.966 [ItemChannelLinkAddedEvent ] - Link ‘trocknerEg-wemo:insight:Insight3:state’ has been added.
2016-10-29 18:45:17.966 [ItemChannelLinkAddedEvent ] - Link ‘trocknerOgCurrentPower-wemo:insight:Insight4:currentPower’ has been added.
2016-10-29 18:45:17.966 [ItemChannelLinkAddedEvent ] - Link ‘waschmaschineEgEnergyTotal-wemo:insight:Insight1:energyTotal’ has been added.
2016-10-29 18:45:17.966 [ItemChannelLinkAddedEvent ] - Link ‘trocknerEgCurrentPower-wemo:insight:Insight3:currentPower’ has been added.
2016-10-29 18:45:17.966 [ItemChannelLinkAddedEvent ] - Link ‘waschmaschineOg-wemo:insight:Insight2:state’ has been added.
2016-10-29 18:45:17.966 [ItemChannelLinkAddedEvent ] - Link ‘trocknerEgEnergyTotal-wemo:insight:Insight3:energyTotal’ has been added.
2016-10-29 18:45:17.966 [ItemChannelLinkAddedEvent ] - Link ‘waschmaschineEg-wemo:insight:Insight1:state’ has been added.
2016-10-29 18:45:17.966 [ItemChannelLinkAddedEvent ] - Link ‘trocknerOg-wemo:insight:Insight4:state’ has been added.
2016-10-29 18:45:17.966 [ItemChannelLinkAddedEvent ] - Link ‘trocknerOgEnergyTotal-wemo:insight:Insight4:energyTotal’ has been added.
2016-10-29 18:45:17.966 [ItemChannelLinkAddedEvent ] - Link ‘waschmaschineEgCurrentPower-wemo:insight:Insight1:currentPower’ has been added.
2016-10-29 18:45:17.966 [ItemChannelLinkAddedEvent ] - Link ‘waschmaschineOgCurrentPower-wemo:insight:Insight2:currentPower’ has been added.
2016-10-29 18:45:20.371 [ThingAddedEvent ] - Thing ‘wemo:insight:Insight1’ has been added.
2016-10-29 18:45:20.371 [ThingAddedEvent ] - Thing ‘wemo:insight:Insight2’ has been added.
2016-10-29 18:45:20.371 [ThingAddedEvent ] - Thing ‘wemo:insight:Insight3’ has been added.
2016-10-29 18:45:20.371 [ThingAddedEvent ] - Thing ‘wemo:insight:Insight4’ has been added.
2016-10-29 18:45:20.424 [hingStatusInfoChangedEvent] - ‘wemo:insight:Insight1’ changed from UNINITIALIZED to INITIALIZING
2016-10-29 18:45:20.424 [hingStatusInfoChangedEvent] - ‘wemo:insight:Insight2’ changed from UNINITIALIZED to INITIALIZING
2016-10-29 18:45:20.440 [hingStatusInfoChangedEvent] - ‘wemo:insight:Insight1’ changed from INITIALIZING to ONLINE
2016-10-29 18:45:20.440 [hingStatusInfoChangedEvent] - ‘wemo:insight:Insight3’ changed from UNINITIALIZED to INITIALIZING
2016-10-29 18:45:20.440 [hingStatusInfoChangedEvent] - ‘wemo:insight:Insight2’ changed from INITIALIZING to ONLINE
2016-10-29 18:45:20.440 [hingStatusInfoChangedEvent] - ‘wemo:insight:Insight4’ changed from UNINITIALIZED to INITIALIZING
2016-10-29 18:45:20.440 [hingStatusInfoChangedEvent] - ‘wemo:insight:Insight4’ changed from INITIALIZING to ONLINE
2016-10-29 18:45:20.440 [hingStatusInfoChangedEvent] - ‘wemo:insight:Insight3’ changed from INITIALIZING to ONLINE
2016-10-29 18:45:21.357 [ThingUpdatedEvent ] - Thing ‘wemo:insight:Insight1’ has been updated.
2016-10-29 18:45:21.357 [ThingUpdatedEvent ] - Thing ‘wemo:insight:Insight2’ has been updated.
2016-10-29 18:45:21.357 [ThingUpdatedEvent ] - Thing ‘wemo:insight:Insight3’ has been updated.
2016-10-29 18:45:21.357 [ThingUpdatedEvent ] - Thing ‘wemo:insight:Insight4’ has been updated.
<–

_default.things:
–>
wemo:insight:Insight1 [ udn=“Insight-1_0-221450K1200xx1”]
wemo:insight:Insight2 [ udn=“Insight-1_0-221503K1200xx2”]
wemo:insight:Insight3 [ udn=“Insight-1_0-221514K1200xx3”]
wemo:insight:Insight4 [ udn=“Insight-1_0-221540K1200xx4”]
<–

_default.items:
–>
Group gUG “Untergeschoss” [ “home-group” ]

Group UG_Waschkueche “Waschküche” (gUG)

Switch waschmaschineEg “EG Waschmaschine” (UG_Waschkueche) {channel=“wemo:insight:Insight1:state”}
Number waschmaschineEgCurrentPower “EG Stromverbrauch [%.00f]” (UG_Waschkueche) {channel=“wemo:insight:Insight1:currentPower”}
Number waschmaschineEgEnergyTotal “EG WSumme [%.00f]” (UG_Waschkueche) {channel=“wemo:insight:Insight1:energyTotal”}

Switch waschmaschineOg “OG Waschmaschine” (UG_Waschkueche) {channel=“wemo:insight:Insight2:state”}
Number waschmaschineOgCurrentPower “OG Stromverbrauch [%.00f]” (UG_Waschkueche) {channel=“wemo:insight:Insight2:currentPower”}
Number waschmaschineOgEnergyTotal “OG WSumme [%.00f]” (UG_Waschkueche) {channel=“wemo:insight:Insight2:energyTotal”}

Switch trocknerEg “EG Trockner” (UG_Waschkueche) {channel=“wemo:insight:Insight3:state”}
Number trocknerEgCurrentPower “EG Stromverbrauch [%.00f]” (UG_Waschkueche) {channel=“wemo:insight:Insight3:currentPower”}
Number trocknerEgEnergyTotal “EG TSumme [%.00f]” (UG_Waschkueche) {channel=“wemo:insight:Insight3:energyTotal”}

Switch trocknerOg “OG Trockner” (UG_Waschkueche) {channel=“wemo:insight:Insight4:state”}
Number trocknerOgCurrentPower “OG Stromverbrauch [%.00f]” (UG_Waschkueche) {channel=“wemo:insight:Insight4:currentPower”}
Number trocknerOgEnergyTotal “OG TSumme [%.00f]” (UG_Waschkueche) {channel=“wemo:insight:Insight4:energyTotal”}
<–

2

Please try to change your thing definition to

wemo:insight:Insight-1_0-221450K200xx1 [ udn="Insight-1_0-221450K1200xx1"]
3

Hello Hans-Jörg,

I have changed the entry of the _default.things to:
wemo:insight:Insight-1_0-221450K1200xx1 [ udn=“Insight-1_0-221450K1200xx1”]

and the entry of the _default.items to:
Switch waschmaschineEg “EG Waschmaschine” (UG_Waschkueche) {channel=“wemo:insight:Insight-1_0-221450K1200xx1:state”}

but the result is the same …

Greetings
Horst

4

Please post some more information about your setup (machine, os, java version) and your wemo debug log entries
Changing logging to debug is done on karaf console by typing

log:set DEBUG org.eclipse.smarthome.binding.wemo

5

development:
machine: Intel® Core™ i7-3632QM CPU @ 2.20GHz
os: Windows 10 64bit
java: JDK8.112

production:
machine: raspberryPi 2

console output:
–>
openhab> log:set DEBUG org.eclipse.smarthome.binding.wemo
openhab> Exception in thread “Bundle processor thread” java.lang.NullPointerException
at org.eclipse.smarthome.core.thing.internal.ThingManager.isVetoed(ThingManager.java:670)
at org.eclipse.smarthome.core.thing.internal.ThingManager.initializeHandler(ThingManager.java:649)
at org.eclipse.smarthome.core.thing.internal.ThingManager.bundleFinished(ThingManager.java:783)
at org.eclipse.smarthome.config.xml.osgi.AbstractAsyncBundleProcessor.informListeners(AbstractAsyncBundleProcessor.java:253)
at org.eclipse.smarthome.config.xml.osgi.AbstractAsyncBundleProcessor.access$3(AbstractAsyncBundleProcessor.java:251)
at org.eclipse.smarthome.config.xml.osgi.AbstractAsyncBundleProcessor$1.run(AbstractAsyncBundleProcessor.java:242)
at java.lang.Thread.run(Unknown Source)
<–

events.log
–>
2016-10-30 11:42:21.798 [ItemChannelLinkAddedEvent ] - Link ‘waschmaschineOg-wemo:insight:Insight-1_0-221503K1200xx1:state’ has been added.
2016-10-30 11:42:21.800 [ItemChannelLinkAddedEvent ] - Link ‘waschmaschineEg-wemo:insight:Insight-1_0-221450K1200xx2:state’ has been added.
2016-10-30 11:42:23.565 [ThingAddedEvent ] - Thing ‘wemo:insight:Insight-1_0-221450K1200xx2’ has been added.
2016-10-30 11:42:23.612 [ThingAddedEvent ] - Thing ‘wemo:insight:Insight-1_0-221503K1200xx1’ has been added.
2016-10-30 11:42:23.625 [ThingUpdatedEvent ] - Thing ‘wemo:insight:Insight-1_0-221450K1200xx2’ has been updated.
2016-10-30 11:42:23.634 [ThingUpdatedEvent ] - Thing ‘wemo:insight:Insight-1_0-221503K1200xx1’ has been updated.
<–

openhab.log
–>
2016-10-30 11:42:20.395 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model '_default.items’
2016-10-30 11:42:21.698 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model '_default.sitemap’
2016-10-30 11:42:21.902 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model '_default.things’
2016-10-30 11:42:23.223 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2016-10-30 11:42:23.315 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2016-10-30 11:42:23.376 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2016-10-30 11:42:23.444 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2016-10-30 11:42:23.523 [DEBUG] [org.eclipse.smarthome.binding.wemo ] - BundleEvent STARTING - org.eclipse.smarthome.binding.wemo
2016-10-30 11:42:23.525 [DEBUG] [org.eclipse.smarthome.binding.wemo ] - BundleEvent STARTED - org.eclipse.smarthome.binding.wemo
2016-10-30 11:42:23.536 [DEBUG] [org.eclipse.smarthome.binding.wemo ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.eclipse.smarthome.binding.wemo.internal.WemoHandlerFactory, component.id=173, service.id=304, service.bundleid=198, service.scope=bundle} - org.eclipse.smarthome.binding.wemo
2016-10-30 11:42:23.563 [DEBUG] [ing.wemo.internal.WemoHandlerFactory] - Trying to create a handler for ThingType 'wemo:insight
2016-10-30 11:42:23.563 [DEBUG] [ing.wemo.internal.WemoHandlerFactory] - Creating a WemoHandler for thing ‘wemo:insight:Insight-1_0-221450K1200xx2’ with UDN 'Insight-1_0-221450K1200xx2’
2016-10-30 11:42:23.569 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Creating a WemoHandler for thing 'wemo:insight:Insight-1_0-221450K1200xx2’
2016-10-30 11:42:23.573 [DEBUG] [org.eclipse.smarthome.binding.wemo ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=wemo:insight, thing.id=wemo:insight:Insight-1_0-221450K1200xx2, service.id=305, service.bundleid=198, service.scope=singleton} - org.eclipse.smarthome.binding.wemo
2016-10-30 11:42:23.588 [WARN ] [ome.core.thing.internal.ThingManager] - Attempt to register a handler twice for thing wemo:insight:Insight-1_0-221450K1200xx2 at the same time will be ignored.
2016-10-30 11:42:23.609 [DEBUG] [ing.wemo.internal.WemoHandlerFactory] - Trying to create a handler for ThingType 'wemo:insight
2016-10-30 11:42:23.611 [DEBUG] [ing.wemo.internal.WemoHandlerFactory] - Creating a WemoHandler for thing ‘wemo:insight:Insight-1_0-221503K1200xx1’ with UDN 'Insight-1_0-221503K1200xx1’
2016-10-30 11:42:23.611 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Creating a WemoHandler for thing 'wemo:insight:Insight-1_0-221503K1200xx1’
2016-10-30 11:42:23.612 [DEBUG] [org.eclipse.smarthome.binding.wemo ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=wemo:insight, thing.id=wemo:insight:Insight-1_0-221503K1200xx1, service.id=306, service.bundleid=198, service.scope=singleton} - org.eclipse.smarthome.binding.wemo
2016-10-30 11:42:23.621 [DEBUG] [.wemo.discovery.WemoDiscoveryService] - Starting WeMo UPnP discovery…
2016-10-30 11:42:23.622 [DEBUG] [.wemo.discovery.WemoDiscoveryService] - Starting UPnP RootDevice search…
2016-10-30 11:42:23.622 [DEBUG] [org.eclipse.smarthome.binding.wemo ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={component.name=org.eclipse.smarthome.binding.wemo.discovery.WemoDiscoveryService, component.id=174, service.id=307, service.bundleid=198, service.scope=bundle} - org.eclipse.smarthome.binding.wemo
2016-10-30 11:42:23.625 [DEBUG] [org.eclipse.smarthome.binding.wemo ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={component.name=org.eclipse.smarthome.binding.wemo.discovery.WemoDiscoveryParticipant, component.id=175, service.id=308, service.bundleid=198, service.scope=bundle} - org.eclipse.smarthome.binding.wemo
2016-10-30 11:42:36.135 [DEBUG] [o.discovery.WemoDiscoveryParticipant] - Discovered a WeMo Insight thing with UDN 'Insight-1_0-221503K1200xx1’
2016-10-30 11:42:36.136 [DEBUG] [o.discovery.WemoDiscoveryParticipant] - Created a DiscoveryResult for device ‘Waschmaschine OG’ with UDN 'Insight-1_0-221503K1200xx1’
2016-10-30 11:42:36.297 [DEBUG] [o.discovery.WemoDiscoveryParticipant] - Discovered a WeMo Insight thing with UDN 'Insight-1_0-221514K1200B37’
2016-10-30 11:42:36.298 [DEBUG] [o.discovery.WemoDiscoveryParticipant] - Created a DiscoveryResult for device ‘Trockner EG’ with UDN 'Insight-1_0-221514K1200B37’
2016-10-30 11:42:39.822 [DEBUG] [o.discovery.WemoDiscoveryParticipant] - Discovered a WeMo Insight thing with UDN 'Insight-1_0-221450K1200xx2’
2016-10-30 11:42:39.824 [DEBUG] [o.discovery.WemoDiscoveryParticipant] - Created a DiscoveryResult for device ‘Waschmaschine EG’ with UDN ‘Insight-1_0-221450K1200xx2’
<–

6

Would you please remove the “xx” parts from your .items file and try again, as I don’t think thats your wemo’s serial number.

7

The wemo’s serial number in the .items is without the “xx” parts.
I’ve the serial number replaced only in the logfile.

8

I have been trying to track down this problem through various posts on the forum here and I think the problem that you are having is the exact same problem that I have too! I had a little bit of time and started to do some debugging on the issue - it’s been a problem for me ever since i started using OpenHAB2. I have done some debugging and this is what i’ve found…

It appears when you just startup (or restart) openHab2 there are dependencies that are started and are not all available when “things” are loaded. This impacts the smart home wemo module functions (two of them: onSubscription (used in initialize and other critical areas) and onUpdate) due to the service.isRegistered(this) check.

if you use the console and just issue a bundle:restart for the wemo bundle you can see that it fires right up (which is what you are simulating with renaming the files - it reloads the items and has the same effect for this problem).

Logs for a full startup: http://pastebin.com/TUrr4g3s
Logs for a install of the bundle while running: http://pastebin.com/hDiyTw11

The effect of those checks are what you and I see when - It doesn’t setup the subscription or timer loops which poll the devices for updates and is why i believe we are seeing what we are.

I am thinking there might be an alternative place to setup these subscriptions in the code instead of during the initialize in the WemoHandler function (which is where this is called).

Updated functions to add debug code - so you can see how the log messages are generated

    private synchronized void onSubscription() {
        if (service.isRegistered(this)) {
            logger.debug("Setting up WeMo GENA subscription for '{}'", this);

            ThingTypeUID thingTypeUID = thing.getThingTypeUID();

            if (thingTypeUID.equals(THING_TYPE_INSIGHT)) {
                service.addSubscription(this, "insight1", SUBSCRIPTION_DURATION);
            } else {
                service.addSubscription(this, "basicevent1", SUBSCRIPTION_DURATION);
            }
        } else {
            logger.error("Setting up WeMo GENA subscription for '{}' FAILED - service.isRegistered(this) is FALSE",
                    this);
        }
    }


    private synchronized void onUpdate() {
        if (service.isRegistered(this)) {
            if (refreshJob == null || refreshJob.isCancelled()) {
                Configuration config = getThing().getConfiguration();
                int refreshInterval = DEFAULT_REFRESH_INTERVAL;
                Object refreshConfig = config.get("refresh");
                if (refreshConfig != null) {
                    refreshInterval = ((BigDecimal) refreshConfig).intValue();
                }
                refreshJob = scheduler.scheduleAtFixedRate(refreshRunnable, 0, refreshInterval, TimeUnit.SECONDS);
            }
        } else {
            logger.error("onUpdate FAILED for '{}' service.isRegistered(this) was FALSE", this);
        }
    }

Any help on this one would be greatly appreciated. I’m hoping this might provide some clues as to what is going on to someone that is little bit more familiar with the OpenHAB2 APIs and the Wemo code to have that ahhh-ha moment.

9

It also looks like the Sonos plugin had a similar problem about 3 months ago (although it appears it was partially traced back to problems with the upnp implementation… https://www.bountysource.com/issues/36284795-sonos-binding-problem-with-channels-init-at-oh-startup

But there is a lot of code in the Sonos bundle in how it handles interaction with upnp. Going to look to see how they did this… maybe a way to work around the issue (they do the subscriptions a bit differently and retry it part of the polling so it will eventually work - and remove isRegistered check to create the polling loop.

10

I think i have this fixed - or at least a work around. It will now work without having to restart or move bundles around. The drawback right now is it will take up to 2 minutes due to the default polling interval for it to start to read current status - but this only happens once when you start it up.

Here’s my compiled version of the JAR - http://www.ktechs.net/pvt_filz/org.eclipse.smarthome.binding.wemo-0.9.0-SNAPSHOT.jar
Here’s a link to my branch if you wish to build your own: https://github.com/DigitalBites/smarthome/tree/fix_wemo-startup-issues

Directions to install

openhab> bundle:list | grep -i wemo
202 | Active   |  80 | 0.9.0.201611120403    | Eclipse SmartHome Wemo Binding
openhab> bundle:stop 202
openhab> bundle:uninstall 202

Backup and then copy the above JAR file to your installation: /opt/openhab/openhab-offline-2.0.0-snapshot-20161111/runtime/system/org/eclipse/smarthome/binding/org.eclipse.smarthome.binding.wemo/0.9.0-SNAPSHOT/

openhab> bundle:install "file:///opt/openhab/openhab-offline-2.0.0-snapshot-20161111/runtime/system/org/eclipse/smarthome/binding/org.eclipse.smarthome.binding.wemo/0.9.0-SNAPSHOT/org.eclipse.smarthome.binding.wemo-0.9.0-SNAPSHOT.jar"
Bundle ID: 203
openhab> bundle:list | grep -i wemo
203 | Installed |  80 | 0.9.0.201611120452    | Eclipse SmartHome Wemo Binding
openhab> bundle:start 203
11

Hello Jayson,

great, it works. :slight_smile:
Thank you for your efforts in this matter.

You should push this fix to an openHAB developer.

Greetings
Horst

1 Like
12

@DigitalBites
Thanks for tracking this down. I will review your PR and comment on this.
@Horst the developer (me) is already reading this😉

Best
Hans-Jörg