Could not make HTTP call to WeMo, (binding does not rediscover after starting)

For OH 2.3, Iad an interesting problem today with one of my wemo mini switches. One them stopped responding to ON/OFF commands from openhab. My other wemo devices were fine, just one of the switches. The problematic switch has a static ip and the wemo app on my phone works fine – just seems openhab lost track of it.

All I get in the log file is :slight_smile:

2018-10-14 13:56:24.099 [DEBUG] [.smarthome.binding.wemo.internal.http.WemoHttpCall] - Could not make HTTP call to WeMo
2018-10-14 13:56:27.717 [DEBUG] [.smarthome.binding.wemo.internal.http.WemoHttpCall] - Could not make HTTP call to WeMo
2018-10-14 13:56:34.397 [DEBUG] [.smarthome.binding.wemo.internal.http.WemoHttpCall] - Could not make HTTP call to WeMo

I also get a few:

2018-10-14 14:00:48.454 [DEBUG] [eclipse.smarthome.binding.wemo.handler.WemoHandler] - WeMo Socket-1_0-221816K0103611: Subscription to service basicevent1 failed
2018-10-14 14:02:40.448 [DEBUG] [eclipse.smarthome.binding.wemo.handler.WemoHandler] - Setting up GENA subscription Socket-1_0-221816K0103611: Subscribing to service basicevent1…
2018-10-14 14:02:50.476 [DEBUG] [eclipse.smarthome.binding.wemo.handler.WemoHandler] - WeMo Socket-1_0-221816K0103611: Subscription to service basicevent1 failed
2018-10-14 14:04:42.463 [DEBUG] [eclipse.smarthome.binding.wemo.handler.WemoHandler] - Setting up GENA subscription Socket-1_0-221816K0103611: Subscribing to service basicevent1…
2018-10-14 14:04:52.505 [DEBUG] [eclipse.smarthome.binding.wemo.handler.WemoHandler] - WeMo Socket-1_0-221816K0103611: Subscription to service basicevent1 failed

If there is any additional logging that I can add please let me know. Just want to point this out.

There is nothing we could do I am afraid.
The device is not responding on requests, even it is working in original app. What you could try is restart the WeMo device and then restart openHAB.

Thanks. I just restarted openhab and it worked again.

I just thought that the wemo app worked the same way as openhab, so was confused when they both didn’t operate the same.

Changing this to not SOLVED, since it happened again to me :slight_smile:

I had a few minutes to debug this further. It looks like, at least, the wemo mini switch is changing the ports that it communicates on. The binding may not be rediscovering and using the new port.

Here is a tcpdump summary of openhab trying to set the switch:

22:31:33.736114 IP alarmpi.33050 > wemominikeg.local.49154: Flags [S], seq 218943257, win 29200, options [mss 1460,sackOK,TS val 373431294 ecr 0,nop,wscale 7], length 0
22:31:33.737780 IP wemominikeg.local.49154 > alarmpi.33050: Flags [R.], seq 0, ack 218943258, win 0, length 0

It is trying to communicate to the switch over port 49154, I assume from initial discovery. However the device is no longer listening on that port. I didn’t have time to do a full debug of this so downloaded
https://github.com/iancmcc/ouimeaux and let it do the discovery and found that it is now using port 49157

(ouimeaux-env) root@alarmpi:~/ouimeaux/ouimeaux-env# wemo -d status
DEBUG:ouimeaux.discovery:Binding datagram server to 192.168.1.43:54321
INFO:ouimeaux.environment:Discovering devices
DEBUG:ouimeaux.discovery:Broadcasting M-SEARCH to 239.255.255.250:1900
DEBUG:ouimeaux.discovery:Received a response from 192.168.1.208:55271
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 192.168.1.208:49157
DEBUG:urllib3.connectionpool:http://192.168.1.208:49157 "GET /setup.xml HTTP/1.1" 200 4484
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 192.168.1.208:49157
DEBUG:urllib3.connectionpool:http://192.168.1.208:49157 "GET /setupservice.xml HTTP/1.1" 200 4091
DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 192.168.1.208:49157
DEBUG:urllib3.connectionpool:http://192.168.1.208:49157 "GET /timesyncservice.xml HTTP/1.1" 200 1630

I wrote a quick shell script to just throw the SOAP packet at the mini switch to turn the switch off/on port 49157 and it worked fine. I can control the switch. So I guess the wemo binding does not do periodic re-discovery? Also 49157 was not usually in the list of wemo ports that I had previously. I’m wondering if the wemo mini is the first one to use it, and also change its ports periodically.

root@alarmpi:~/root# ./wemotest3.sh 192.168.1.208 0
try port 192.168.1.208:49152
nc: connect to 192.168.1.208 port 49152 (tcp) failed: Connection refused
try port 192.168.1.208:49153
Connection to 192.168.1.208 49153 port [tcp/*] succeeded!
try port 192.168.1.208:49154
nc: connect to 192.168.1.208 port 49154 (tcp) failed: Connection refused
try port 192.168.1.208:49155
Connection to 192.168.1.208 49155 port [tcp/*] succeeded!
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
<s:Body>
<s:Fault>
<faultcode>s:Client</faultcode>
<faultstring>UPnPError</faultstring>

try port 192.168.1.208:49156
Connection to 192.168.1.208 49156 port [tcp/*] succeeded!
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">

<faultstring>UPnPError</faultstring>
<detail>
<UPnPError xmlns="urn:schemas-upnp-org:control-1-0">
<errorCode>-1</errorCode>
<errorDescription>Invalid Action</errorDescription>
</UPnPError>

</s:Envelope>

try port 1 92.168.1.208:49157

Connection to 192.168.1.208 49157 port [tcp/*] succeeded!
<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>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body>
<u:SetBinaryStateResponse xmlns:u="urn:Belkin:service:basicevent:1">
<BinaryState>1</BinaryState>
<CountdownEndTime>0</CountdownEndTime>
<deviceCurrentTime>1540177142</deviceCurrentTime>
</u:SetBinaryStateResponse>
</s:Body> </s:Envelope>
<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>1</BinaryState>
</u:GetBinaryStateResponse>

For now, I can at least control these type of wemo devices by just running a shell script which does the SOAP request to turn on/off. If anyone needs the scrip.

#!/bin/sh
ip=$1
state=$2
for port in 49152 49153 49154 49155 49156 49157
do
echo try port $ip:$port
echo " "
nc -zv $ip $port
curl -m 2 -X POST  -H 'Content-type: text/xml; charset="utf-8"' -H "SOAPACTION: \"urn:Belkin:service:basicevent:1#GetBinaryState\"" -H 'Accept:' --data "<?xml version=\"1.0\" encoding=\"utf-8\"?><s:Envelope xmlns:s=\"http://schemas.xmlsoap.org/soap/envelope/\" s:encodingStyle=\"http://schemas.xmlsoap.org/soap/encoding/\"><s:Body><u:GetBinaryState xmlns:u=\"urn:Belkin:service:basicevent:1\"></u:GetBinaryState></s:Body></s:Envelope>" -s http://$ip:$port/upnp/control/basicevent1
echo
curl -m 2 -X POST  -H 'Content-type: text/xml; charset="utf-8"' -H "SOAPACTION: \"urn:Belkin:service:basicevent:1#SetBinaryState\"" --data "<?xml version=\"1.0\" encoding=\"utf-8\"?><s:Envelope xmlns:s=\"http://schemas.xmlsoap.org/soap/envelope/\" s:encodingStyle=\"http://schemas.xmlsoap.org/soap/encoding/\"><s:Body><u:SetBinaryState xmlns:u=\"urn:Belkin:service:basicevent:1\"><BinaryState>$state</BinaryState></u:SetBinaryState></s:Body></s:Envelope>" -s http://$ip:$port/upnp/control/basicevent1
echo
curl -m 2 -X POST  -H 'Content-type: text/xml; charset="utf-8"' -H "SOAPACTION: \"urn:Belkin:service:basicevent:1#GetBinaryState\"" --data "<?xml version=\"1.0\" encoding=\"utf-8\"?><s:Envelope xmlns:s=\"http://schemas.xmlsoap.org/soap/envelope/\" s:encodingStyle=\"http://schemas.xmlsoap.org/soap/encoding/\"><s:Body><u:GetBinaryState xmlns:u=\"urn:Belkin:service:basicevent:1\"></u:GetBinaryState></s:Body></s:Envelope>" -s http://$ip:$port/upnp/control/basicevent1
done

Looking at the code, it appears this binding only does discovery at activation. For cases where the wemo device may decide to change its port in the Location discovery response, the device will not be accessible. I believe my device changed its port when I restarted my wifi on the router – not sure if this is a wemo mini thing or just the latest firmeware.

However when I restart, or (stop-start) the binding, the probem does not resolve. I see the following logs:

2018-10-22 01:07:34.066 [DEBUG] [nding.wemo.internal.discovery.WemoDiscoveryService] - Starting UPnP RootDevice search...
2018-10-22 01:07:34.144 [DEBUG] [g.wemo.internal.discovery.WemoDiscoveryParticipant] - Discovered a WeMo Socket thing with UDN 'Socket-1_0-221816K0103611'
2018-10-22 01:07:34.148 [DEBUG] [g.wemo.internal.discovery.WemoDiscoveryParticipant] - Created a DiscoveryResult for device 'Kegerator' with UDN 'Socket-1_0-221816K0103611'
2018-10-22 01:07:34.260 [DEBUG] [smarthome.binding.wemo.internal.WemoHandlerFactory] - Trying to create a handler for ThingType 'wemo:socket
2018-10-22 01:07:34.264 [DEBUG] [smarthome.binding.wemo.internal.WemoHandlerFactory] - Creating a WemoHandler for thing 'wemo:socket:Socket-1_0-221816K0103611' with UDN 'Socket-1_0-221816K0103611'
2018-10-22 01:07:34.268 [DEBUG] [eclipse.smarthome.binding.wemo.handler.WemoHandler] - Creating a WemoHandler for thing 'wemo:socket:Socket-1_0-221816K0103611'
2018-10-22 01:07:34.291 [DEBUG] [eclipse.smarthome.binding.wemo.handler.WemoHandler] - Initializing WemoHandler for UDN 'Socket-1_0-221816K0103611'
2018-10-22 01:07:34.295 [DEBUG] [eclipse.smarthome.binding.wemo.handler.WemoHandler] - Checking WeMo GENA subscription for 'org.eclipse.smarthome.binding.wemo.handler.WemoHandler@3eb115'
2018-10-22 01:07:34.299 [DEBUG] [eclipse.smarthome.binding.wemo.handler.WemoHandler] - Setting up GENA subscription Socket-1_0-221816K0103611: Subscribing to service basicevent1...
2018-10-22 01:07:34.313 [DEBUG] [smarthome.binding.wemo.internal.WemoHandlerFactory] - Trying to create a handler for ThingType 'wemo:socket
2018-10-22 01:07:34.326 [DEBUG] [.smarthome.binding.wemo.internal.http.WemoHttpCall] - Could not make HTTP call to WeMo

Unfortunately the code does not print out WHAT the discovery result actually is, but I know that the switch is sending back a valid discovery by doing one outside of openhab. It is returning:

HTTP/1.1 200 OK
CACHE-CONTROL: max-age=86400
DATE: Mon, 22 Oct 2018 05:22:33 GMT
EXT:
LOCATION: http://192.168.1.208:49157/setup.xml
OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01
01-NLS: e421321a-1dd1-11b2-ae9e-d396178ab2d2
SERVER: Unspecified, UPnP/1.0, Unspecified
X-User-Agent: redsonic
ST: upnp:rootdevice
USN: uuid:Socket-1_0-221816K0103611::upnp:rootdevice

And confirmed by going to that address and issues the normal on/off commands (which works fine).

So in summary, wemo can change the port for SOAP calls, the openhab wemo binding never does rediscovery to pick it up, and trying to restart or stop/start the binding does not fix the problem.

Any idea would be appreciated.
Thanks.

2 Likes

Thanks for sharing, but this also confirms not to be a WeMo Binding related issue.
The Binding relies in JUPnP as the underlying UPnP libraries, to be precise uses the discovery results from that.
If the device changes its configuration (namely the port), it should send a notify message with the new details.
I will tray to make a workaround by triggering a “rediscovery” periodically to check wether this can solve the issue.

It may be sending the notify message around the time the wifi changes and thus it gets lost. Also I could forsee if the openhab machine is off network or unavailable when these notify packets are sent, that you also may have the problem. I think Upnp discovery may also be UDP?

The confusing part is that binding reports that it has discovered a wemo socket and created a discovery result after the binding is restarted, or stop/started. Yet it continues to use the original discovery value. It would be helpful to print this info out, but I can see it with tcpdump. Shouldn’t the binding pick up the new value from the discovery when it is restarted?

On Binding start, a UPnP discovery is triggered and the registry should be updated with the new results.
I am refactoring the binding for some other reasons and will try to see how we can solve this issue.
But cause of very limited time for coding atm, I can not give any eta.
Once I have finished the refactoring, I will post the news her, as we also will have some new devices supported by the binding.