[SOLVED] WeMo Reliability

You won’t see anything, as you logger setting seems to be wrong.

log:set TRACE org.openhab.binding.wemo

Hi @hmerk
The wemo binding has been working perfectly for the past couple months. Thank you for making those changes! Unfortunately, for the past two weeks or so many of the devices do not respond on the first attempt. That, of course, means rules don’t really work…

Here is an excerpt from the trace log: (This is me toggling the switch ON which works then OFF which fails - so its toggled ON and OFF a second time which finally succeeds.)

2020-06-04 06:51:58.504 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Command 'ON' received for channel 'wemo:socket:socket06:state'
2020-06-04 06:51:58.504 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49151'
2020-06-04 06:51:58.654 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49152'
2020-06-04 06:51:58.658 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49153'
2020-06-04 06:51:58.662 [TRACE] [ng.wemo.internal.handler.WemoHandler] - WeMo device Socket-1_0-221742K010D5CF responded at Port 49153
2020-06-04 06:52:14.576 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Command 'OFF' received for channel 'wemo:socket:socket06:state'
2020-06-04 06:52:14.576 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49151'
2020-06-04 06:52:14.826 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49152'
2020-06-04 06:52:15.077 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49153'
2020-06-04 06:52:15.328 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49154'
2020-06-04 06:52:15.578 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49155'
2020-06-04 06:52:15.829 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49156'
2020-06-04 06:52:16.080 [ERROR] [ng.wemo.internal.handler.WemoHandler] - Failed to send command 'OFF' for device 'wemo:socket:socket06': Invalid URI host: null (authority: 10.111.16.160:null)
2020-06-04 06:56:05.843 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Command 'ON' received for channel 'wemo:socket:socket06:state'
2020-06-04 06:56:05.844 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49151'
2020-06-04 06:56:05.932 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49152'
2020-06-04 06:56:06.009 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49153'
2020-06-04 06:56:06.217 [TRACE] [ng.wemo.internal.handler.WemoHandler] - WeMo device Socket-1_0-221742K010D5CF responded at Port 49153
2020-06-04 06:56:08.474 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Command 'OFF' received for channel 'wemo:socket:socket06:state'
2020-06-04 06:56:08.475 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49151'
2020-06-04 06:56:08.481 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49152'
2020-06-04 06:56:08.485 [TRACE] [ng.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/10.111.16.160:49153'
2020-06-04 06:56:08.489 [TRACE] [ng.wemo.internal.handler.WemoHandler] - WeMo device Socket-1_0-221742K010D5CF responded at Port 49153

Does this tell you anything useful? I can provide more complete trace logs if need be. Nothing significant has changed in my network. Perhaps this has something to do with “wemo accounts”? (I have not enabled this feature).

my setup:

openHAB 2.5.4 release build
239 │ Active │ 80 │ 2.5.5 │ openHAB Add-ons :: Bundles :: Wemo Binding
All of my things are manually configured.

Perhaps the Timeout is too low as you suggest above… see ping here:

64 bytes from 10.111.16.160: icmp_seq=57 ttl=64 time=4.207 ms
64 bytes from 10.111.16.160: icmp_seq=58 ttl=64 time=189.329 ms
Request timeout for icmp_seq 60
Request timeout for icmp_seq 61
Request timeout for icmp_seq 62
64 bytes from 10.111.16.160: icmp_seq=59 ttl=64 time=4413.272 ms
64 bytes from 10.111.16.160: icmp_seq=60 ttl=64 time=3409.271 ms
64 bytes from 10.111.16.160: icmp_seq=61 ttl=64 time=2405.692 ms
64 bytes from 10.111.16.160: icmp_seq=62 ttl=64 time=1402.245 ms
64 bytes from 10.111.16.160: icmp_seq=63 ttl=64 time=398.447 ms
64 bytes from 10.111.16.160: icmp_seq=64 ttl=64 time=41.735 ms
64 bytes from 10.111.16.160: icmp_seq=66 ttl=64 time=1420.391 ms
64 bytes from 10.111.16.160: icmp_seq=67 ttl=64 time=418.582 ms
64 bytes from 10.111.16.160: icmp_seq=68 ttl=64 time=3.252 ms
64 bytes from 10.111.16.160: icmp_seq=69 ttl=64 time=5.349 ms
64 bytes from 10.111.16.160: icmp_seq=70 ttl=64 time=2721.036 ms
64 bytes from 10.111.16.160: icmp_seq=71 ttl=64 time=1717.114 ms
64 bytes from 10.111.16.160: icmp_seq=72 ttl=64 time=712.171 ms
64 bytes from 10.111.16.160: icmp_seq=73 ttl=64 time=2.259 ms
64 bytes from 10.111.16.160: icmp_seq=74 ttl=64 time=2.927 ms
64 bytes from 10.111.16.160: icmp_seq=75 ttl=64 time=3037.321 ms
64 bytes from 10.111.16.160: icmp_seq=76 ttl=64 time=2033.985 ms
64 bytes from 10.111.16.160: icmp_seq=78 ttl=64 time=751.724 ms
64 bytes from 10.111.16.160: icmp_seq=79 ttl=64 time=9.301 ms
64 bytes from 10.111.16.160: icmp_seq=80 ttl=64 time=1754.552 ms
64 bytes from 10.111.16.160: icmp_seq=81 ttl=64 time=751.148 ms
64 bytes from 10.111.16.160: icmp_seq=83 ttl=64 time=102.924 ms
64 bytes from 10.111.16.160: icmp_seq=84 ttl=64 time=18.028 ms
Request timeout for icmp_seq 86
64 bytes from 10.111.16.160: icmp_seq=85 ttl=64 time=2071.524 ms
64 bytes from 10.111.16.160: icmp_seq=86 ttl=64 time=1069.969 ms
64 bytes from 10.111.16.160: icmp_seq=87 ttl=64 time=66.407 ms
64 bytes from 10.111.16.160: icmp_seq=88 ttl=64 time=3.880 ms
64 bytes from 10.111.16.160: icmp_seq=89 ttl=64 time=3.734 ms
64 bytes from 10.111.16.160: icmp_seq=90 ttl=64 time=3006.887 ms
64 bytes from 10.111.16.160: icmp_seq=91 ttl=64 time=2003.580 ms
64 bytes from 10.111.16.160: icmp_seq=92 ttl=64 time=999.346 ms
64 bytes from 10.111.16.160: icmp_seq=93 ttl=64 time=4.247 ms
64 bytes from 10.111.16.160: icmp_seq=94 ttl=64 time=2.253 ms
64 bytes from 10.111.16.160: icmp_seq=95 ttl=64 time=2370.804 ms
64 bytes from 10.111.16.160: icmp_seq=98 ttl=64 time=307.985 ms
64 bytes from 10.111.16.160: icmp_seq=99 ttl=64 time=3.202 ms
64 bytes from 10.111.16.160: icmp_seq=100 ttl=64 time=80.987 ms
Request timeout for icmp_seq 101
64 bytes from 10.111.16.160: icmp_seq=101 ttl=64 time=1313.122 ms
64 bytes from 10.111.16.160: icmp_seq=102 ttl=64 time=311.124 ms
64 bytes from 10.111.16.160: icmp_seq=103 ttl=64 time=1.952 ms
64 bytes from 10.111.16.160: icmp_seq=104 ttl=64 time=2.529 ms
Request timeout for icmp_seq 106
64 bytes from 10.111.16.160: icmp_seq=107 ttl=64 time=107.842 ms
64 bytes from 10.111.16.160: icmp_seq=108 ttl=64 time=13.122 ms
64 bytes from 10.111.16.160: icmp_seq=109 ttl=64 time=2.477 ms

There is no reason in my network that this should be so poor. I did this with several devices with the same result.

This really looks like a poor Network. I have set the timeout in the binding to 250ms, so there should be a delay less than two seconds between Pressing a button in openHAB and sending the command to the WeMo Switch/Insight.
Following your logs, we would need to set the timeout to at least 4500ms, which could result in a delay of 31.5 seconds from button press to reaction.
I am not convinced to do that, as it might result in many other users complaining about really slow response times.

This version of the WeMo binding has worked excellent since 10.19.2019. I have the Plugs, Switches and Insight Plugs totally 22 devices. I’m running OH 2.4.

openhab> list -s |grep wemo
206 │ Active │ 80 │ 2.5.0.201910181352 │ org.openhab.binding.wemo
openhab>

Best, Jay

It is the same version than the actual release version.

That worked.

I’m getting this response:

08:51:01.859 [DEBUG] [ing.wemo.internal.handler.WemoHandler] - WeMo UPnP device Socket-1_0-XXXX not yet registered
08:51:01.860 [DEBUG] [ing.wemo.internal.handler.WemoHandler] - Setting up WeMo GENA subscription for 'org.openhab.binding.wemo.internal.handler.WemoHandler@XXXX' FAILED - service.isRegistered(this) is FALSE

I’m getting this same message for each of my Wemo devices, I think. When I reboot, everything resets to be ok. I’m getting a jumble of messages (which I’m happy to post if they’re useful), but they all boil down to receiving data from the Wemos.

09:00:02.524 [DEBUG] [ing.wemo.internal.handler.WemoHandler] - Checking WeMo GENA subscription for 'org.openhab.binding.wemo.internal.handler.WemoHandler@XXX'
09:00:02.525 [TRACE] [ing.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/192.168.1.151:49152'
09:00:02.526 [TRACE] [ing.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/192.168.1.193:49152'
09:00:02.527 [TRACE] [ing.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/192.168.1.151:49153'
09:00:02.539 [TRACE] [ing.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/192.168.1.193:49153'
09:00:02.539 [TRACE] [ing.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/192.168.1.151:49154'
09:00:02.552 [TRACE] [ing.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/192.168.1.197:49151'
09:00:02.552 [TRACE] [ing.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/192.168.1.191:49151'
09:00:02.593 [TRACE] [ing.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/192.168.1.193:49154'
09:00:02.593 [TRACE] [ing.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/192.168.1.197:49152'
09:00:02.594 [TRACE] [ing.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/192.168.1.191:49152'
09:00:02.594 [TRACE] [ing.wemo.internal.handler.WemoHandler] - WeMo device Lightswitch-1_0-xxx responded at Port 49154
09:00:02.595 [TRACE] [ing.wemo.internal.handler.WemoHandler] - WeMo device Lightswitch-1_0-xxx responded at Port 49154
09:00:02.595 [TRACE] [ing.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/192.168.1.191:49153'
09:00:02.596 [TRACE] [ing.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/192.168.1.197:49153'
09:00:02.597 [TRACE] [ing.wemo.internal.handler.WemoHandler] - Ping WeMo device at '/192.168.1.191:49154'
09:00:02.626 [TRACE] [ing.wemo.internal.handler.WemoHandler] - WeMo device Socket-1_0-xxx responded at Port 49154
09:00:02.627 [TRACE] [ing.wemo.internal.handler.WemoHandler] - State response '<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body>
<u:GetBinaryStateResponse xmlns:u="urn:Belkin:service:basicevent:1">
<BinaryState>0</BinaryState>
</u:GetBinaryStateResponse>
</s:Body> </s:Envelope>' for device 'wemo:lightswitch:ChristmasOutdoor' received
09:00:02.627 [TRACE] [ing.wemo.internal.handler.WemoHandler] - New state '0' for device 'wemo:lightswitch:ChristmasOutdoor' received
09:00:02.627 [DEBUG] [ing.wemo.internal.handler.WemoHandler] - Received pair 'BinaryState':'0' (service 'basicevent1') for thing 'wemo:lightswitch:ChristmasOutdoor'
09:00:02.628 [DEBUG] [ing.wemo.internal.handler.WemoHandler] - State 'OFF' for device 'wemo:lightswitch:ChristmasOutdoor' received

My (pre-reset) ping times seem ok:

xxx@xxx:~# ping 192.168.1.xxx
PING 192.168.1.xxx (192.168.1.xxx) 56(84) bytes of data.
64 bytes from 192.168.1.xxx: icmp_seq=1 ttl=64 time=11.3 ms
64 bytes from 192.168.1.xxx: icmp_seq=2 ttl=64 time=3.91 ms
64 bytes from 192.168.1.xxx: icmp_seq=3 ttl=64 time=3.19 ms
64 bytes from 192.168.1.xxx: icmp_seq=4 ttl=64 time=1.78 ms
64 bytes from 192.168.1.xxx: icmp_seq=5 ttl=64 time=7.09 ms
64 bytes from 192.168.1.xxx: icmp_seq=6 ttl=64 time=4.20 ms
^C
--- 192.168.1.xxx ping statistics ---
6 packets transmitted, 6 received, 0% packet loss, time 12ms
rtt min/avg/max/mdev = 1.781/5.243/11.294/3.139 ms

Any chance it has to do with Wemo’s recent switch to using accounts?

I found a couple other posts on the forum that deal with my error (they seemed quite old and the solution was to use the 2.5.0 snapshot jar, and I’m already on 2.5.5 stable), but it made me think there is a problem with UPNP. FWIW, I’m getting the following warnings whenever I start my installation:

09:20:07.056 [WARN ] [rg.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 192.168.1.xxx
09:20:08.124 [WARN ] [rg.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 192.168.1.xxx
09:20:21.473 [INFO ] [.openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
09:20:21.935 [WARN ] [mulation.internal.HueEmulationService] - The UPnP Server service has not been started!

Notwithstanding these errors, my Hue Emulation works fine.

Ouch :slight_smile: You’re probably right. I was hoping it wasn’t just me since this came out of nowhere with no recent changes.

Of course, 31.5s would be way too long.

I haven’t been keeping up with this conversation, but I also have a similar issue with my Wemo Motion sensor that is only fixed after I restart the binding.

The Wemo accounts don’t impact local communication. In my case, this has definitely been going on for a long time. I just haven’t worried about it since the disconnects are infrequent.

The log you provided does not show an issue with polling device state. GENA event errors occur from time to time, but this is an issue in Belkins firmware.

Just warnings, nothing to worry about.

Please post a trace log for occuring errors/issues.

Nope, it’s the last version you compiled for me when you got everything working last year. I have NOT upgraded to any released versions after your peer review of changes you had to make a few months ago.

Best, Jay

The WemoHandler class should be the same, the new devices have been added with separate handler classes.
Could you please pm me your version and I will compare both.

Sure, I’ll do that next time I see it happening. My motion sensor is only used to turn on the lights when I stumble to the kitchen for a glass of water late at night, so debugging isn’t exactly a priority. :wink:

1 Like

I couldn’t tell you whether I got these errors periodically before, but now they are ongoing for hours at a time. Everything will work fine for a while, then openhab will stop communicating with Wemo (inbound and outbound). I will start getting the “not yet registered” and GENA errors. When I reboot, things will clear up for a while. And eventually it will come back online on its own. But while it’s offline, my things and items are showing as online in PaperUI and REST, but there’s no communication between OH and the wemo devices. All the other bindings are working fine.

I can appreciate that there would be intermittent GENA errors, but when they last for hours it seems unusual.

@hmerk the problem is that you are relying on a port connect() to determine if the port is working, and when the Wemo changes its port to the next higher number, the logic keeps guessing that the original port is valid because it doesn’t actually ask for anything back. I changed the logic to use an http request, which fixes the problem for me.

The PR is 7874.

1 Like

What openHAB and Java version are you using ?
Sometimes the GENA errors occur, but not in a way you describe. You are the first one bringin this to attention.

Thanks for you PR, looks quite good. Please address the comments made by @cpmeister.

Nevertheless, this will just solve the issue with respongin a wrong port, but might not solve not responding at all. That’s basically the issue mentioned the last couple of weeks.