Trouble with Wemo binding after rebooting

[chadkuester]

Platform information: -Hardware: RPi 3 B+ (March 2018) -OS: openHABian 1.4.1 -openHAB version: openHAB 2.3.0~20180408143530-1 (Build #1252)

I’m having a terrible time with the Wemo binding. I’ve purchased a new Raspberry PI 3 B+, tried formatting the new SD card four times now, tried a 100% pure Paper UI method, tried a 100% method using text files (wemo.items), tried OH 2.2 and OH 2.3, but I cannot get Wemo to work after a reboot without assistance!

openHABian is awesome! Thanks to whoever put that together. I went through the first time installing everything myself. openHABian is SO much easier!

When the Wemo Binding works - it works great! Paper UI works, HABPanel works, rules work - even clicking on the light switches physically fires the openHAB rules and adjusts other lights accordingly.

But after I reboot… The Wemo binding stops working. I don’t see any error messages. All of the Wemo things go from UNINITIALIZED to INITIALIZING to ONLINE. I can click on a switch in Paper UI… it displays the icon from OFF to ON. The event log says “changed from OFF to ON” but physically nothing happens. All of the watt meters show a dash (vs zero).

Then, while it’s not working, I open up the Wemo app on my phone. My phone works great. I can click on the devices and turn them off and on. The app is very responsive. However - nothing is getting updated in openHAB. Any changes I do on openHAB are not visible on the phone and vice-versa. I’ve waited 2 hours and still no commands work.

While it’s not working, all other bindings are perfect. Astro, Weather Underground and more receive updates and work as expected.

To fix it, I play a song and dance. Normally the best solution for me is to uninstall the Wemo binding, then install the Wemo binding again. Then with Paper UI try turning on a switch. Sometimes I have to go further and re-save the wemo.items file. Then bam! It all starts to work. Now with it working the watt meters have changed from a dash to zero watts. Switches work. Clicking on the Wemo app on my phone updates openHAB.

Any ideas?

-I have all Wemo device set with a DHCP reservation - that’s probably what has helped so much with the phone app working consistently.

-One thing I think is strange… when I unplug one of the Wemo receptacles and reboot, ALL Wemo things come up as ONLINE. Shouldn’t the one that’s unplugged be OFFLINE?

Here’s a copy of my log: https://pastebin.com/nPs9y6Hd

at 14:02 I’m fighting to get it working. 14:04 I refresh wemo.items. 14:05 uninstalled the Wemo binding. 14:07 reinstall Wemo binding. 14:07 things go ONLINE. 14:09 playing with switches. 14:09 things are starting to work. Power results are starting to stream in.

Consistently the Wemo binding fails after every reboot. As long as I don’t reboot, everything is great!

Let me know what else I should try!

Thanks, -Chad

[maggu2810]

Perhaps it would help for diagnostic to set the log level for org.eclipse.smarthome.binding.wemo to TRACE, restart openHAB (I assume it will fail now) and then log the whole log from a openHAB restart till some presses in the UI.

[chadkuester]

https://docs.openhab.org/administration/logging.html#config-file says that log settings are lost when the system is rebooted so I edited /var/lib/openhab2/etc/org.ops4j.pax.logging.cfg

Then I set it to this:

OSGi appender

log4j2.appender.osgi.type = PaxOsgi log4j2.appender.osgi.name = OSGI log4j2.appender.osgi.filter = * log4j2.logger.org_openhab_binding_wemo.level = TRACE log4j2.logger.org_openhab_binding_wemo.name = org.openhab.binding.wemo log4j2.logger.org_eclipse_smarthome_binding_wemom.level = TRACE log4j2.logger.org_eclipse_smarthome_binding_wemom.name = org.eclipse.smarthome.binding.wemoM log4j2.logger.org_eclipse_smarthome_binding_wemo.level = TRACE log4j2.logger.org_eclipse_smarthome_binding_wemo.name = org.eclipse.smarthome.binding.wemo

log4j2.logger.org_openhab_binding_wemo.level was set to WARN and I changed it to TRACE. I hope I did that right.

Then I rebooted the machine, copied the log events from port 9001 and pasted them here: https://pastebin.com/KbZ1X5Pc

What stands out to me is this:

2018-04-11 22:16:29.038 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Setting up WeMo GENA subscription for 'org.eclipse.smarthome.binding.wemo.handler.WemoHandler@193130' FAILED - service.isRegistered(this) is FALSE

I greatly appreciate the help! Thanks!

[triller-telekom]

@hmerk I looked at this issue and since it is your code maybe you can answer my question, and maybe also fix this issue with it too :)

The error message mentioned above arises due to the condition if (service.isRegistered(this)) in https://github.com/eclipse/smarthome/blob/master/extensions/binding/org.eclipse.smarthome.binding.wemo/src/main/java/org/eclipse/smarthome/binding/wemo/handler/WemoHandler.java#L326 being false.

I greped for registerParticipant through the source of the binding but the result is:

org.eclipse.smarthome.binding.wemo [master]$ grep -rin "registerParticipant" *src/main/java/org/eclipse/smarthome/binding/wemo/handler/WemoLightHandler.java:406:            service.unregisterParticipant(this);
src/main/java/org/eclipse/smarthome/binding/wemo/handler/WemoCoffeeHandler.java:236:            service.unregisterParticipant(this);
src/main/java/org/eclipse/smarthome/binding/wemo/handler/WemoHandler.java:375:            service.unregisterParticipant(this);

So I am wondering if the handler ever gets registered as a UpnpIOParticipant?

[chadkuester]

Yes- it will- if I assist it. So yesterday I removed all other bindings. I removed all other items and just left one Wemo item in my wemo.items list (a lightswitch). That's the log you saw above.

All night long it tried to discover the Wemo device and failed. This morning I assisted it - I removed the Wemo binding and then added it back.

Instantly it's now discovered all of my devices. The lightswitch is now fully working. Why does do I have to remove the binding and add it back after every reboot?

Here's a new pastebin. This one is an overlap of the one above. Trace has been turned on. The PI was rebooted.

https://pastebin.com/vBFVYa8A

All night long from 22:57 to 06:49 it says the same thing over and over:

2018-04-11 22:57:56.025 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Setting up WeMo GENA subscription for 'org.eclipse.smarthome.binding.wemo.handler.WemoHandler@1afde0b' FAILED - service.isRegistered(this) is FALSE

2018-04-11 22:59:56.031 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - WeMo UPnP device Lightswitch-1_0-221603K1300901 not yet registered

at 06:51 this morning I uninstalled the binding and then added it back.

2018-04-12 06:52:56.315 [DEBUG] [l.discovery.WemoDiscoveryParticipant] - Discovered a WeMo Lightswitch thing with UDN 'Lightswitch-1_0-221603K1300901'

2018-04-12 06:52:56.329 [DEBUG] [l.discovery.WemoDiscoveryParticipant] - Created a DiscoveryResult for device 'Kitchen Switch' with UDN 'Lightswitch-1_0-221603K1300901'

2018-04-12 06:54:55.110 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Setting up GENA subscription Lightswitch-1_0-221603K1300901: Subscribing to service basicevent1...

2018-04-12 06:54:55.157 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - WeMo Lightswitch-1_0-221603K1300901: Subscription to service basicevent1 succeeded

2018-04-12 06:54:55.198 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Received pair 'BinaryState':'1' (service 'basicevent1') for thing 'wemo:lightswitch:Lightswitch1'

2018-04-12 06:54:55.201 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - State 'ON' for device 'wemo:lightswitch:Lightswitch1' received

Why does it work if I uninstall the binding and add it back but then it fails if I do nothing but just reboot?

[chadkuester]

Most of my issues appear to be with discovery. Since all of my switches have a DHCP reservation, is it possible to add the IP to each thing to assist with discovery?

For example: Thing wemo:lightswitch:Lightswitch1 "Kitchen Switch" [udn="Lightswitch-1_0-221603K1300901", host="192.168.2.169"]

[hmerk]

To be honest, I have no clue as I do not see such a behaviour within my installation. After restarting openHAB or rebooting my server, all devices are coming back online straight away. I will do some more testing....

[chadkuester]

FYI- my phone shows the firmware version of the Wemo as WeMo_WW_2.00.11057.PVT-OWRT-LS

Also- I upgraded the firmware in my WAP - Ubiquiti PRO (UAP-AC-PRO-US) but that didn't help.

I've also checked the settings and logs in my firewall (pfSense). I suspect that's not the issue though because the wireless box is plugged directly in my switch (it's not going through the firewall).

[hmerk]

@chadkuester Do you have a feeling since when you face this issue? Did it happen with an earlier firmware? My WeMo devices are still on an older firmware version, so I have to update them to see if Belkin again did some breaking changes.....

[hmerk]

@chadkuester I can not reproduce the behaviour you are seeing. All my WeMo devices come online straight away. @triller-telekom Yes, handlers get registered, otherwise there would be no active GENA subscription, which is definitely working.

[hmerk]

@chadkuester Do you just have a WeMo Lightswitch ? Any other device type you could test ?

[chadkuester]

When did I first face this issue? I'm just started with openHAB about a week ago. Starting with 2.2 and 2.3 - both were giving me this issue. In the beginning, when things stopped working, I had assumed that I messed up a file somewhere and ruined the machine, so I formatted and started over. After my 4th buildup running openHabian from scratch, I've finally traced the issue of Wemo failing to the event of restarting the service (or rebooting the Pi). In the beginning, I had created all objects 100% in PaperUI. Then after reprogramming everything so many times, I switched to text config files.

Before you had mentioned that it works for you, I had wondered if everyone was having this issue with Wemo. Now I know it's something in my config causing the problem.

About two weeks ago while using the Wemo app on my phone, I received a notification to update the firmware for all Wemo devices, which I did. I'm wishing now I had not.

Other than the Wemo firmware, the only other item that sounds different in my config is that I'm running a brand new version of the Rasberry Pi that just came out in March 2018. It runs just a bit faster than the previous model. I've wondered if it's causing a timing issue in the code.

I have a bunch of Wemo devices - 12 total - 4 light switches and 8 outlets. I'll put the full file back in then rerun the test and send over the logs.

Thanks again everyone for your continued assistance on this! I am very thankful to have your assistance! I'm very interested in this project!

[chadkuester]

With the service stopped, I started the openhab2 service, recorded the log, then stopped the service again.

On my first pastebin below, everything worked on the first try! I don’t think that’s happened before! On my 2nd pastebin, it failed. Had I tried to uninstall/reinstall the Wemo binding it probably would have worked. For an example of me uninstalling/reinstalling to make it work, see my pastebin in this thread way up above.

Wemo Working: https://pastebin.com/Ypbcp5Mp

Wemo Failed: https://pastebin.com/9k1qtHi9

Some things in the log that catch my attention:

(A) I keep getting this:

2018-04-12 22:54:36.142 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Setting up WeMo GENA subscription for 'org.eclipse.smarthome.binding.wemo.handler.WemoHandler@157cfca' FAILED - service.isRegistered(this) is FALSE

Is this normal?

(B) when everything is working, ALL of my things show up as ONLINE - even Insight units that are unplugged!

Is this supposed to happen? With everything working - try this - if you make up a UDN number and add it to your things file, it shows up as ONLINE!

Here’s the line I just added: Thing wemo:insight:Insight-DoesNotExist "Does not exist" [udn="Insight-1_0-221446K1202E9"]

This doesn’t sound right to me. Based on the status list from https://docs.openhab.org/concepts/things.html, I would have expected them to show up as OFFLINE.

(C) Unclosed string:

The log shows this line: 2018-04-12 22:54:35.957 [DEBUG] [ing.wemo.internal.WemoHandlerFactory] - Trying to create a handler for ThingType 'wemo:insight

Notice how the single apostrophe at the end is missing from the end of the string. I think this is just a simple typo though. extensions\binding\org.eclipse.smarthome.binding.wemo\src\main\java\org\eclipse\smarthome\binding\wemo\internal\WemoHandlerFactory.java shows: logger.debug("Trying to create a handler for ThingType '{}", thingTypeUID);

(D) Might be nothing, but when I compare the instance that worked vs the one that failed, I notice that the events occur in a different order.

Specifically- the line about it changing from UNINITIALIZED to INITIALIZING. In the working model it’s the last line. In the failed log it occurs in the middle as line “3”.

Working:

2018-04-12 22:54:36.173 [DEBUG] [ing.wemo.internal.WemoHandlerFactory] - Creating a WemoHandler for thing 'wemo:insight:Insight-1_0-221352K1200AE2' with UDN 'Insight-1_0-221352K1200AE2'
 2018-04-12 22:54:36.194 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Creating a WemoHandler for thing 'wemo:insight:Insight-1_0-221352K1200AE2'
 2018-04-12 22:54:36.203 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Initializing WemoHandler for UDN 'Insight-1_0-221352K1200AE2'
 2018-04-12 22:54:36.204 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Setting up WeMo GENA subscription for 'org.eclipse.smarthome.binding.wemo.handler.WemoHandler@8be423' FAILED - service.isRegistered(this) is FALSE
 2018-04-12 22:54:36.206 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - WeMo UPnP device Insight-1_0-221352K1200AE2 not yet registered
 2018-04-12 22:54:36.208 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Setting up WeMo GENA subscription for 'org.eclipse.smarthome.binding.wemo.handler.WemoHandler@8be423' FAILED - service.isRegistered(this) is FALSE
 2018-04-12 22:54:36.234 [hingStatusInfoChangedEvent] - 'wemo:insight:Insight-1_0-221352K1200AE2' changed from UNINITIALIZED to INITIALIZING
 2018-04-12 22:54:36.237 [hingStatusInfoChangedEvent] - 'wemo:insight:Insight-1_0-221352K1200AE2' changed from INITIALIZING to ONLINE

Failed:

2018-04-12 23:06:59.731 [DEBUG] [ing.wemo.internal.WemoHandlerFactory] - Creating a WemoHandler for thing 'wemo:insight:Insight-1_0-221352K1200AE2' with UDN 'Insight-1_0-221352K1200AE2'
 2018-04-12 23:06:59.738 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Creating a WemoHandler for thing 'wemo:insight:Insight-1_0-221352K1200AE2'
 **2018-04-12 23:06:59.749 [hingStatusInfoChangedEvent] - 'wemo:insight:Insight-1_0-221352K1200AE2' changed from UNINITIALIZED to INITIALIZING**
 2018-04-12 23:06:59.753 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Initializing WemoHandler for UDN 'Insight-1_0-221352K1200AE2'
 2018-04-12 23:06:59.757 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Setting up WeMo GENA subscription for 'org.eclipse.smarthome.binding.wemo.handler.WemoHandler@1b86a4b' FAILED - service.isRegistered(this) is FALSE
 2018-04-12 23:06:59.759 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - WeMo UPnP device Insight-1_0-221352K1200AE2 not yet registered
 2018-04-12 23:06:59.762 [DEBUG] [ome.binding.wemo.handler.WemoHandler] - Setting up WeMo GENA subscription for 'org.eclipse.smarthome.binding.wemo.handler.WemoHandler@1b86a4b' FAILED - service.isRegistered(this) is FALSE
 2018-04-12 23:06:59.765 [TRACE] [ome.binding.wemo.handler.WemoHandler] - Command 'REFRESH' received for channel 'wemo:insight:Insight-1_0-221352K1200AE2:state'
 2018-04-12 23:06:59.765 [hingStatusInfoChangedEvent] - 'wemo:insight:Insight-1_0-221352K1200AE2' changed from INITIALIZING to ONLINE

[hmerk]

It is not neccesarily a timing issue with your Pi, as I am running openHAB on a NUC. Setting things OFFLINE when they are unplugged is not completely implemented, but coming with the next Binding version. I am about to rewrite major parts of the code to make it more robust and to support additional devices, like Dimmer Switch. Unfortunately, I can not tell when this will be ready, cause of private issues/priorities. In the meantime, just check if it helps to just stop the WeMo Binding on Karaf console and restart it, instead of doing an uninstall and reinstall.

[chadkuester]

OK. I'll sit tight. I do have a workaround. The power hardly ever goes out and I could always add a UPS.

Thanks for looking into this!