search

n8henrie / fauxmo

Emulated Belkin WeMo devices that work with the Amazon Echo
https://n8henrie.com/2016/02/fauxmo-home-automation-with-the-amazon-echo-raspberry-pi-and-homeassistant/
Other
372 stars 78 forks source link

Device Not Discovered #33

Closed gkrananth closed 6 years ago

gkrananth commented 6 years ago

Windows 10 Machine Python 3.6.7 Fauxmo : 0.4.4

Please find below the verbose

(venv) C:\Users\310093198\AppData\Local\Programs\Python\Python36\venv\Scripts>fauxmo -c config.json -vvv 2017-11-12 12:27:30 fauxmo:37 INFO Fauxmo v0.4.4 2017-11-12 12:27:30 fauxmo:38 DEBUG 3.6.3 (v3.6.3:2c5fed8, Oct 3 2017, 18:11:49) [MSC v.1900 64 bit (AMD64)] 2017-11-12 12:27:30 fauxmo:37 DEBUG Using IP address: 192.168.1.33 2017-11-12 12:27:30 fauxmo:102 DEBUG plugin_vars: {} 2017-11-12 12:27:30 fauxmo:105 DEBUG device config: {'port': 12345, 'on_cmd': 'http://192.168.1.33:8000/get?switch=on', 'off_cmd': 'http://192.168.1.33:8000/get?switch=off', 'method': 'GET', 'name': 'fake switch one'} 2017-11-12 12:27:30 asyncio:1068 INFO <Server sockets=[<socket.socket fd=416, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.33', 12345)>]> is serving 2017-11-12 12:27:30 fauxmo:123 DEBUG Started fauxmo device: {'name': 'fake switch one', 'plugin': <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0x0000029AA6276940>} 2017-11-12 12:27:30 fauxmo:105 DEBUG device config: {'port': 12346, 'on_cmd': 'http://127.0.0.1:8000/digest-auth/auth/fauxmouser/fauxmopass', 'off_cmd': 'http://127.0.0.1:8000/digest-auth/auth/fauxmouser/fauxmopass', 'user': 'fauxmouser', 'password': 'fauxmopass', 'name': 'fake Indigo switch'} 2017-11-12 12:27:30 asyncio:1068 INFO <Server sockets=[<socket.socket fd=780, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.33', 12346)>]> is serving 2017-11-12 12:27:30 fauxmo:123 DEBUG Started fauxmo device: {'name': 'fake Indigo switch', 'plugin': <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0x0000029AA554C8D0>} 2017-11-12 12:27:30 fauxmo:105 DEBUG device config: {'port': 12347, 'on_cmd': 'http://192.168.1.33:8000/put', 'off_cmd': 'http://192.168.1.33:8000/put', 'on_data': {'isOn': 1}, 'off_data': {'isOn': 0}, 'method': 'PUT', 'name': 'fake Indigo switch'} 2017-11-12 12:27:30 asyncio:1068 INFO <Server sockets=[<socket.socket fd=640, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.33', 12347)>]> is serving 2017-11-12 12:27:30 fauxmo:123 DEBUG Started fauxmo device: {'name': 'fake Indigo switch', 'plugin': <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0x0000029AA6331A20>} 2017-11-12 12:27:30 fauxmo:105 DEBUG device config: {'name': 'fake post request', 'port': 12348, 'on_cmd': 'http://192.168.1.33:8000/post', 'off_cmd': 'http://192.168.1.33:8000/post', 'method': 'POST', 'headers': {'x-ha-access': 'your_hass_password'}, 'on_data': {'entity_id': 'switch.fake_hass_switch'}, 'off_data': {'entity_id': 'switch.fake_hass_switch'}} 2017-11-12 12:27:30 asyncio:1068 INFO <Server sockets=[<socket.socket fd=812, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.33', 12348)>]> is serving 2017-11-12 12:27:30 fauxmo:123 DEBUG Started fauxmo device: {'name': 'fake post request', 'plugin': <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0x0000029AA63319E8>} 2017-11-12 12:27:30 fauxmo:105 DEBUG device config: {'name': 'test https request', 'port': 12349, 'on_cmd': 'https://httpbin.org/post', 'off_cmd': 'https://httpbin.org/post', 'method': 'POST', 'headers': {'x-ha-access': 'your_hass_password'}, 'on_data': {'entity_id': 'switch.fake_hass_switch'}, 'off_data': {'entity_id': 'switch.fake_hass_switch'}} 2017-11-12 12:27:30 asyncio:1068 INFO <Server sockets=[<socket.socket fd=816, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.33', 12349)>]> is serving 2017-11-12 12:27:30 fauxmo:123 DEBUG Started fauxmo device: {'name': 'test https request', 'plugin': <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0x0000029AA6331A90>} 2017-11-12 12:27:30 fauxmo:125 INFO Starting UDP server 2017-11-12 12:27:30 asyncio:948 DEBUG Datagram endpoint remote_addr=None created: (<_SelectorDatagramTransport fd=756 read=idle write=<idle, bufsize=0>>, <fauxmo.protocols.SSDPServer object at 0x0000029AA6276748>) 2017-11-12 12:27:46 asyncio:1380 INFO poll took 16297.000 ms: 1 events 2017-11-12 12:27:46 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 12:27:46 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: upnp:rootdevice\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 12:27:46 asyncio:1380 DEBUG poll took 0.000 ms: 1 events 2017-11-12 12:27:46 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 12:27:46 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: ssdp:all\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 12:27:47 asyncio:1380 DEBUG poll took 515.000 ms: 1 events 2017-11-12 12:27:47 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 12:27:47 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: ssdp:all\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 12:27:47 asyncio:1380 DEBUG poll took 407.000 ms: 1 events 2017-11-12 12:27:47 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 12:27:47 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: upnp:rootdevice\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 12:27:47 asyncio:1380 DEBUG poll took 0.000 ms: 1 events 2017-11-12 12:27:47 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 12:27:47 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: ssdp:all\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 12:27:48 asyncio:1380 DEBUG poll took 516.000 ms: 1 events 2017-11-12 12:27:48 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 12:27:48 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: upnp:rootdevice\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 12:27:48 asyncio:1380 DEBUG poll took 0.000 ms: 1 events 2017-11-12 12:27:48 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 12:27:48 fauxmo:171 DEBUG b'M-SEARCH * HTTP/1.1\r\nMX: 3\r\nST: ssdp:all\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n'

confg.json file

{ "FAUXMO": { "ip_address": "192.168.1.33" }, "PLUGINS": { "SimpleHTTPPlugin": { "DEVICES": [ { "port": 12345, "on_cmd": "http://192.168.1.33:8000/get?switch=on", "off_cmd": "http://192.168.1.33:8000/get?switch=off", "method": "GET", "name": "fake switch one" }, { "port": 12346, "on_cmd": "http://127.0.0.1:8000/digest-auth/auth/fauxmouser/fauxmopass", "off_cmd": "http://127.0.0.1:8000/digest-auth/auth/fauxmouser/fauxmopass", "user": "fauxmouser", "password": "fauxmopass", "name": "fake Indigo switch" }, { "port": 12347, "on_cmd": "http://192.168.1.33:8000/put", "off_cmd": "http://192.168.1.33:8000/put", "on_data": {"isOn": 1}, "off_data": {"isOn": 0}, "method": "PUT", "name": "fake Indigo switch" }, { "name": "fake post request", "port": 12348, "on_cmd": "http://192.168.1.33:8000/post", "off_cmd": "http://192.168.1.33:8000/post", "method": "POST", "headers": {"x-ha-access": "your_hass_password"}, "on_data": {"entity_id": "switch.fake_hass_switch"}, "off_data": {"entity_id": "switch.fake_hass_switch"} }, { "name": "test https request", "port": 12349, "on_cmd": "https://httpbin.org/post", "off_cmd": "https://httpbin.org/post", "method": "POST", "headers": {"x-ha-access": "your_hass_password"}, "on_data": {"entity_id": "switch.fake_hass_switch"}, "off_data": {"entity_id": "switch.fake_hass_switch"} } ] } } }

Please help what went wrong. Trying with Echo 2

gkrananth commented 6 years ago

(venv) C:\Users\310093198\AppData\Local\Programs\Python\Python36\venv\Scripts>python -V Python 3.6.3

gkrananth commented 6 years ago

Find Devices Alexa commad verbose

2017-11-12 13:54:10 asyncio:1380 INFO poll took 18922.000 ms: 1 events 2017-11-12 13:54:10 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 13:54:10 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: upnp:rootdevice\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 13:54:10 asyncio:1380 DEBUG poll took 110.000 ms: 1 events 2017-11-12 13:54:10 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 13:54:10 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: ssdp:all\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 13:54:10 asyncio:1380 DEBUG poll took 390.000 ms: 1 events 2017-11-12 13:54:10 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 13:54:10 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: upnp:rootdevice\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 13:54:11 asyncio:1380 DEBUG poll took 500.000 ms: 1 events 2017-11-12 13:54:11 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 13:54:11 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: upnp:rootdevice\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 13:54:11 asyncio:1380 DEBUG poll took 0.000 ms: 1 events 2017-11-12 13:54:11 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 13:54:11 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: ssdp:all\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 13:54:11 asyncio:1380 DEBUG poll took 516.000 ms: 1 events 2017-11-12 13:54:11 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 13:54:11 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: upnp:rootdevice\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 13:54:11 asyncio:1380 DEBUG poll took 0.000 ms: 1 events 2017-11-12 13:54:11 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 13:54:11 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: ssdp:all\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 13:54:12 asyncio:1380 DEBUG poll took 484.000 ms: 1 events 2017-11-12 13:54:12 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 13:54:12 fauxmo:171 DEBUG b'M-SEARCH HTTP/1.1\r\nMX: 3\r\nST: upnp:rootdevice\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 13:54:12 asyncio:1380 DEBUG poll took 0.000 ms: 1 events 2017-11-12 13:54:12 fauxmo:170 DEBUG Received data below from ('192.168.1.22', 50000): 2017-11-12 13:54:12 fauxmo:171 DEBUG b'M-SEARCH * HTTP/1.1\r\nMX: 3\r\nST: ssdp:all\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\n\r\n' 2017-11-12 13:54:32 asyncio:1380 INFO poll took 20234.000 ms: 1 events

n8henrie commented 6 years ago

Please use the issue template, it's provided for a reason. I won't be able to help you unless you provide the requested info, such as what problem you're having and what you've tried.

I'm not sure that I understand what problem you're having, and posting your logs without telling me what problem you're having doesn't help. Please include the below info from the issue template like I asked yesterday.

My Issue

WHYT

Please make sure you've taken these steps before submitting a new issue:

ppirrip commented 6 years ago

I have similar issue.

EDIT: Moved

n8henrie commented 6 years ago

@ppirrip -- please start a new issue, or continue in this (likely) related issue. I suspect your problem is because you're not using an actual Echo device.

ppirrip commented 6 years ago

Thx @n8henrie I have a feeling that is the case (not using an actual Echo device).

Monarch73 commented 6 years ago

I think I know what the problem is. I am facing similar problems for my project that is based on fauxmo.

In the new Amazon Echo Plus they changed something. In the new version, they don't do a "ST: urn:Belkin:device:**" SSDP-request anymore. They just issue a ''ST: ssdp:all'' request. And that doesn't work for fauxmo.

gkrananth commented 6 years ago

So if i change the search option will it work ?

Monarch73 commented 6 years ago

Huh? What search option?

Can you please confirm that you have a Echo Plus?

gkrananth commented 6 years ago

I have Echo version. Is there way to do work around method?

Monarch73 commented 6 years ago

As far as I know there is no work around. To me it appears to be a change in the firmware of the echo that is affecting support for wemo-devices.

What firmware version does your echo have? You can look it up in the alexa app. 2nd gen Echos should have Version 591448720...

gkrananth commented 6 years ago

592452720

gkrananth commented 6 years ago

https://bitbucket.org/xoseperez/fauxmoesp

Using this on ESP8266 for me it is working

Monarch73 commented 6 years ago

That's very helpful to know. Thank you.

In this esp8266 project, they have a better coverage of the SSDP-Requests sent by Alexa. They are listinging for one of these requests:

define UDP_DEVICE_PATTERN_1 "urn:Belkin:device:**"

define UDP_DEVICE_PATTERN_2 "urn:Belkin:device:controllee:1"

define UDP_DEVICE_PATTERN_3 "urn:Belkin:service:basicevent:1"

And thats why fauxmo is failing and fauxmoesp is working.

n8henrie commented 6 years ago

@Monarch73 —

In the new Amazon Echo Plus they changed something. In the new version, they don't do a "ST: urn:Belkin:device:**" SSDP-request anymore. They just issue a ''ST: ssdp:all'' request.

Huh, that’s interesting (and unfortunate). If you’re familiar with WireShark or tcpdump, can you send me a pcap of what you’re seeing with the new Echo?

Monarch73 commented 6 years ago

@n8henrie Someone else sent me his monitorlogs in my project. You can check it here: https://github.com/Monarch73/RFBridge/issues/1

192.168.178.35 is this IP of his Alexa Plus device. I don't own this one.

n8henrie commented 6 years ago

My echo is running 591448720 and working fine with Fauxmo. I'll have to wait and see if more Echo Plus users can chime in on whether they're having issues as well.

Monarch73 commented 6 years ago

@n8henrie My Echo 2nd gen is running the same version and its working fine as well. But there are clear indications that something has changed and/or something will change. On the belkin support website, I have found comments asking wemo-users to install a WeMo-Skill in Alexa-app if their equipment stopped working all of a sudden.

see http://www.belkin.com/us/support-article?articleNum=157351

I am starting to incorporate code from the above mentioned Xose Pérez project into my code to get a broader compatibilty.

ppirrip commented 6 years ago

If I want to give it a try to incorporate fauxmoesp, is that only protocols.py needed to change? Specifically this line?

f'USN: uuid:Socket-1_0-{serial}::urn:Belkin:device:**'
n8henrie commented 6 years ago

Glad to hear it's working for you. Yes, it very well may change -- while I admire your work to future-proof your project, I think I'm going to wait until I know exactly what the changes are before I invest my time. In other news, I'm pushing out several days of work onto the dev branches of both n8henrie/fauxmo and n8henrie/fauxmo-plugins today -- Fauxmo devices can now properly respond to Alexa queries regarding their state, which is nice.

I'll keep an eye out, both my echo and my dot are running 591448720, so I wonder if @gkrananth's 592452720 firmware is causing his issue. If I'm able to reproduce it, it should be a fairly easy fix (as long as it's just fixing the respond_to_search).

n8henrie commented 6 years ago

@Monarch73

And thats why fauxmo is failing and fauxmoesp is working.

I'm not sure if that's the case. All three of those examples have Belkin in them, and @gkrananth's debug output above doesn't have that word at all. If you look at where the debug output (Received data below from) is coming from in datagram_received, no filtering has been done at that point. So I don't think Fauxmo is seeing any of those three requests, and adding support for them would probably not help solve his issue as far as I can tell.

ppirrip commented 6 years ago

I am playing with respond_to_search for those new Belkin changes, so far no luck.

Monarch73 commented 6 years ago

@ppirrip No, not just that. You also need to handle certain TCP-Request correctly. See function fauxmoESP::_onTCPData() in fauxmoESP.cpp

ppirrip commented 6 years ago

I am not sure is this related. From protocols.py, I don't see the following in response_to_search in the log output.

logger.debug(f"Sending response to {addr}:\n{response}")

I will take a look at the _onTCPData() also

ppirrip commented 6 years ago

I think my problem is that there is no "ssdp:discover" msg from the Echo simulator or the AVS device. The other home device (e.g. TP-Link Smart Plug) worked must be b/c of the device cloud from the vendor, and that requires a Home Skill, and maybe that's why Belkin suggest user to install the WeMo home skill.

Monarch73 commented 6 years ago

@n8henrie

I successfully integrated the code from the other esp8266-project in this change: https://github.com/Monarch73/RFBridge/commit/1aeba6a0db370bc5df903611e348fba0f2447cd4

Apperantly it seems to be working. My issue-reporter says the devices are now beeing discovered by his Echo Plus.

n8henrie commented 6 years ago

Good to know. We'll see if I end up with the same issue when my Echo updates.

ppirrip commented 6 years ago

I can confirm that my RPi with AVS and Echosim.io are not compatible with Fauxmo. Echo dot (firmware ver 519452520) is able to detect the Fauxmo with my sample config.json. I have issue with Alexa not able to turn the fauxmo on/off, but likely is b/c I haven't set it up correctly.

n8henrie commented 6 years ago

Fair enough. I've added lack of AVS / Echoism support to the FAQ, closing.

lombarke commented 6 years ago

I’m not sure why you closed this... my echo also stopped recognizing my “devices” presented by fauxmo and was following this to see if there would be a fix published. It was working fine up until a few days ago... should I open a new issue?

n8henrie commented 6 years ago

@lombarke sorry, this thread has gotten a little muddled, to the point that I’m not entirely sure what’s being tracked here. It would definitely be helpful if others such as yourself would chime in if you think you’re having a related issue, so I can get an idea of the scope of the problem. Can you reply here with your firmware version, your debug output, and a brief description of what is going on (ie what you mean by “stopped recognizing”)?

lombarke commented 6 years ago

@n8henrie yes, absolutely! however i can help... but please understand, i'm nowhere near advanced as a lot of your reporters, so if there's more info i can provide just let me know (and possibly how?). here's my situation: i've got an amazon echo, firmware version 595457420. i installed fauxmo last week (Nov. 14) and everything has been working fine until a day or two(?) ago. today, when i say "alexa, turn 't.v.' off" i'm met with "sorry, i didn't find 't.v.'", despite the fact that i've got a virtual device called 't.v.' via fauxmo (and this had been working pretty flawlessly). probably worth noting i don't think anything's changed on my server at all (macOS 10.12.6). the virtual devices that were working fine are now alternating between being discovered and listed as "offline" (screenshots attached), and i seem to be getting hung up on a line:

fauxmo:102      DEBUG    Attempting to turn on <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0x102f6bcc0>

followed by: 

asyncio:1260     ERROR    Exception in callback _SelectorSocketTransport._read_ready()

when it's hung there, the devices are no longer discoverable, and no longer controllable.

Anyway, here's a dump of my -vvv:

eschermedia:bin escher$ ./fauxmo -vvv
2017-11-23 22:15:27 fauxmo:37       INFO     Fauxmo v0.4.4
2017-11-23 22:15:27 fauxmo:38       DEBUG    3.6.3 (v3.6.3:2c5fed86e0, Oct  3 2017, 00:32:08) 
[GCC 4.2.1 (Apple Inc. build 5666) (dot 3)]
2017-11-23 22:15:27 fauxmo:46       INFO     Using config: config.json
2017-11-23 22:15:27 fauxmo:24       DEBUG    Attempting to get IP address automatically
2017-11-23 22:15:27 fauxmo:37       DEBUG    Using IP address: 192.168.1.101
2017-11-23 22:15:27 fauxmo:102      DEBUG    plugin_vars: {}
2017-11-23 22:15:27 fauxmo:105      DEBUG    device config: {'port': 12340, 'on_cmd': 'http://192.168.1.104/myserver/fakeswitches/01/on', 'off_cmd': 'http://192.168.1.101/television/off', 'method': 'GET', 'name': 'T.V.'}
2017-11-23 22:15:27 asyncio:1068     INFO     <Server sockets=[<socket.socket fd=10, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12340)>]> is serving
2017-11-23 22:15:27 fauxmo:123      DEBUG    Started fauxmo device: {'name': 'T.V.', 'plugin': <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0x102f6bcc0>}
2017-11-23 22:15:27 fauxmo:105      DEBUG    device config: {'port': 12341, 'on_cmd': 'http://192.168.1.101/television/pause', 'off_cmd': 'http://192.168.1.101/television/pause', 'method': 'GET', 'name': 'T.V. Pause'}
2017-11-23 22:15:27 asyncio:1068     INFO     <Server sockets=[<socket.socket fd=11, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12341)>]> is serving
2017-11-23 22:15:27 fauxmo:123      DEBUG    Started fauxmo device: {'name': 'T.V. Pause', 'plugin': <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0x101295e80>}
2017-11-23 22:15:27 fauxmo:125      INFO     Starting UDP server
2017-11-23 22:15:27 asyncio:948      DEBUG    Datagram endpoint remote_addr=None created: (<_SelectorDatagramTransport fd=12 read=idle write=<idle, bufsize=0>>, <fauxmo.protocols.SSDPServer object at 0x102f3ed30>)
2017-11-23 22:15:33 asyncio:1380     INFO     poll took 5384.630 ms: 1 events
2017-11-23 22:15:33 fauxmo:170      DEBUG    Received data below from ('192.168.1.63', 50000):
2017-11-23 22:15:33 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nMX: 15\r\nST: urn:schemas-upnp-org:device:basic:1\r\n\r\n'
2017-11-23 22:15:33 asyncio:1380     DEBUG    poll took 98.294 ms: 1 events
2017-11-23 22:15:33 fauxmo:170      DEBUG    Received data below from ('192.168.1.63', 50000):
2017-11-23 22:15:33 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nMX: 15\r\nST: urn:schemas-upnp-org:device:basic:1\r\n\r\n'
2017-11-23 22:15:33 asyncio:1380     DEBUG    poll took 110.467 ms: 1 events
2017-11-23 22:15:33 fauxmo:170      DEBUG    Received data below from ('192.168.1.63', 50000):
2017-11-23 22:15:33 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nMX: 15\r\nST: urn:Belkin:device:**\r\n\r\n'
2017-11-23 22:15:33 fauxmo:205      DEBUG    Sending response to ('192.168.1.63', 50000):
HTTP/1.1 200 OK
CACHE-CONTROL: max-age=86400
DATE: Fri, 24 Nov 2017 05:15:33 GMT
EXT:
LOCATION: http://192.168.1.101:12340/setup.xml
OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01
01-NLS: fbe08045-891a-4578-abda-2c7f456dbe26
SERVER: Unspecified, UPnP/1.0, Unspecified
ST: urn:Belkin:device:**
USN: uuid:Socket-1_0-cc85abef-58d3-31b5-9d22-15f84f0e9ad9::urn:Belkin:device:**

2017-11-23 22:15:33 fauxmo:205      DEBUG    Sending response to ('192.168.1.63', 50000):
HTTP/1.1 200 OK
CACHE-CONTROL: max-age=86400
DATE: Fri, 24 Nov 2017 05:15:33 GMT
EXT:
LOCATION: http://192.168.1.101:12341/setup.xml
OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01
01-NLS: fb5687c4-4d5f-4d3c-8c17-23eab6eca241
SERVER: Unspecified, UPnP/1.0, Unspecified
ST: urn:Belkin:device:**
USN: uuid:Socket-1_0-e32c15ba-7d29-359e-b1ce-e29bd39a4238::urn:Belkin:device:**

2017-11-23 22:15:33 asyncio:1380     DEBUG    poll took 95.396 ms: 1 events
2017-11-23 22:15:33 fauxmo:170      DEBUG    Received data below from ('192.168.1.63', 50000):
2017-11-23 22:15:33 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nMX: 15\r\nST: urn:Belkin:device:**\r\n\r\n'
2017-11-23 22:15:33 fauxmo:205      DEBUG    Sending response to ('192.168.1.63', 50000):
HTTP/1.1 200 OK
CACHE-CONTROL: max-age=86400
DATE: Fri, 24 Nov 2017 05:15:33 GMT
EXT:
LOCATION: http://192.168.1.101:12340/setup.xml
OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01
01-NLS: 02ba282b-4c60-474b-9d6b-1789fe520793
SERVER: Unspecified, UPnP/1.0, Unspecified
ST: urn:Belkin:device:**
USN: uuid:Socket-1_0-cc85abef-58d3-31b5-9d22-15f84f0e9ad9::urn:Belkin:device:**

2017-11-23 22:15:33 fauxmo:205      DEBUG    Sending response to ('192.168.1.63', 50000):
HTTP/1.1 200 OK
CACHE-CONTROL: max-age=86400
DATE: Fri, 24 Nov 2017 05:15:33 GMT
EXT:
LOCATION: http://192.168.1.101:12341/setup.xml
OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01
01-NLS: 024f09df-2620-41dd-b18c-b0d24ed4d362
SERVER: Unspecified, UPnP/1.0, Unspecified
ST: urn:Belkin:device:**
USN: uuid:Socket-1_0-e32c15ba-7d29-359e-b1ce-e29bd39a4238::urn:Belkin:device:**

2017-11-23 22:15:33 asyncio:1380     DEBUG    poll took 42.076 ms: 1 events
2017-11-23 22:15:33 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:15:33 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:15:33 asyncio:1380     DEBUG    poll took 119.979 ms: 1 events
2017-11-23 22:15:33 asyncio:182      DEBUG    <Server sockets=[<socket.socket fd=11, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12341)>]> got a new connection from ('192.168.1.63', 37342): <socket.socket fd=13, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12341), raddr=('192.168.1.63', 37342)>
2017-11-23 22:15:33 asyncio:182      DEBUG    <Server sockets=[<socket.socket fd=10, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12340)>]> got a new connection from ('192.168.1.63', 55024): <socket.socket fd=14, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12340), raddr=('192.168.1.63', 55024)>
2017-11-23 22:15:33 asyncio:182      DEBUG    <Server sockets=[<socket.socket fd=10, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12340)>]> got a new connection from ('192.168.1.63', 55025): <socket.socket fd=15, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12340), raddr=('192.168.1.63', 55025)>
2017-11-23 22:15:33 fauxmo:38       DEBUG    Connection made with: ('192.168.1.63', 37342)
2017-11-23 22:15:33 asyncio:182      DEBUG    <Server sockets=[<socket.socket fd=11, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12341)>]> got a new connection from ('192.168.1.63', 37345): <socket.socket fd=16, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12341), raddr=('192.168.1.63', 37345)>
2017-11-23 22:15:33 fauxmo:38       DEBUG    Connection made with: ('192.168.1.63', 55024)
2017-11-23 22:15:33 fauxmo:38       DEBUG    Connection made with: ('192.168.1.63', 55025)
2017-11-23 22:15:33 fauxmo:49       DEBUG    Received message:
GET /setup.xml HTTP/1.1
Host: 192.168.1.101:12341
Accept: */*

2017-11-23 22:15:33 fauxmo:51       DEBUG    setup.xml requested by Echo
2017-11-23 22:15:33 fauxmo:85       DEBUG    Fauxmo response to setup request:
HTTP/1.1 200 OK
CONTENT-LENGTH: 357
CONTENT-TYPE: text/xml
DATE: Fri, 24 Nov 2017 05:15:33 GMT
LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT
SERVER: Unspecified, UPnP/1.0, Unspecified
X-User-Agent: Fauxmo
CONNECTION: close

<?xml version="1.0"?>
<root>
<device>
<deviceType>urn:Fauxmo:device:controllee:1</deviceType>
<friendlyName>T.V. Pause</friendlyName>
<manufacturer>Belkin International Inc.</manufacturer>
<modelName>Emulated Socket</modelName>
<modelNumber>3.1415</modelNumber>
<UDN>uuid:Socket-1_0-e32c15ba-7d29-359e-b1ce-e29bd39a4238</UDN>
</device>
</root>

2017-11-23 22:15:33 fauxmo:38       DEBUG    Connection made with: ('192.168.1.63', 37345)
2017-11-23 22:15:33 fauxmo:49       DEBUG    Received message:
GET /setup.xml HTTP/1.1
Host: 192.168.1.101:12340
Accept: */*

2017-11-23 22:15:33 fauxmo:51       DEBUG    setup.xml requested by Echo
2017-11-23 22:15:33 fauxmo:85       DEBUG    Fauxmo response to setup request:
HTTP/1.1 200 OK
CONTENT-LENGTH: 351
CONTENT-TYPE: text/xml
DATE: Fri, 24 Nov 2017 05:15:33 GMT
LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT
SERVER: Unspecified, UPnP/1.0, Unspecified
X-User-Agent: Fauxmo
CONNECTION: close

<?xml version="1.0"?>
<root>
<device>
<deviceType>urn:Fauxmo:device:controllee:1</deviceType>
<friendlyName>T.V.</friendlyName>
<manufacturer>Belkin International Inc.</manufacturer>
<modelName>Emulated Socket</modelName>
<modelNumber>3.1415</modelNumber>
<UDN>uuid:Socket-1_0-cc85abef-58d3-31b5-9d22-15f84f0e9ad9</UDN>
</device>
</root>

2017-11-23 22:15:33 fauxmo:49       DEBUG    Received message:
GET /setup.xml HTTP/1.1
Host: 192.168.1.101:12340
Accept: */*

2017-11-23 22:15:33 fauxmo:51       DEBUG    setup.xml requested by Echo
2017-11-23 22:15:33 fauxmo:85       DEBUG    Fauxmo response to setup request:
HTTP/1.1 200 OK
CONTENT-LENGTH: 351
CONTENT-TYPE: text/xml
DATE: Fri, 24 Nov 2017 05:15:33 GMT
LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT
SERVER: Unspecified, UPnP/1.0, Unspecified
X-User-Agent: Fauxmo
CONNECTION: close

<?xml version="1.0"?>
<root>
<device>
<deviceType>urn:Fauxmo:device:controllee:1</deviceType>
<friendlyName>T.V.</friendlyName>
<manufacturer>Belkin International Inc.</manufacturer>
<modelName>Emulated Socket</modelName>
<modelNumber>3.1415</modelNumber>
<UDN>uuid:Socket-1_0-cc85abef-58d3-31b5-9d22-15f84f0e9ad9</UDN>
</device>
</root>

2017-11-23 22:15:33 fauxmo:49       DEBUG    Received message:
GET /setup.xml HTTP/1.1
Host: 192.168.1.101:12341
Accept: */*

2017-11-23 22:15:33 fauxmo:51       DEBUG    setup.xml requested by Echo
2017-11-23 22:15:33 fauxmo:85       DEBUG    Fauxmo response to setup request:
HTTP/1.1 200 OK
CONTENT-LENGTH: 357
CONTENT-TYPE: text/xml
DATE: Fri, 24 Nov 2017 05:15:33 GMT
LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT
SERVER: Unspecified, UPnP/1.0, Unspecified
X-User-Agent: Fauxmo
CONNECTION: close

<?xml version="1.0"?>
<root>
<device>
<deviceType>urn:Fauxmo:device:controllee:1</deviceType>
<friendlyName>T.V. Pause</friendlyName>
<manufacturer>Belkin International Inc.</manufacturer>
<modelName>Emulated Socket</modelName>
<modelNumber>3.1415</modelNumber>
<UDN>uuid:Socket-1_0-e32c15ba-7d29-359e-b1ce-e29bd39a4238</UDN>
</device>
</root>

2017-11-23 22:15:43 asyncio:1380     INFO     poll took 9852.713 ms: 1 events
2017-11-23 22:15:43 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:15:43 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:15:49 asyncio:1380     INFO     poll took 5612.401 ms: 1 events
2017-11-23 22:15:49 asyncio:182      DEBUG    <Server sockets=[<socket.socket fd=10, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12340)>]> got a new connection from ('192.168.1.63', 55027): <socket.socket fd=13, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12340), raddr=('192.168.1.63', 55027)>
2017-11-23 22:15:49 fauxmo:38       DEBUG    Connection made with: ('192.168.1.63', 55027)
2017-11-23 22:15:49 asyncio:1380     DEBUG    poll took 15.520 ms: 1 events
2017-11-23 22:15:49 fauxmo:49       DEBUG    Received message:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.1.101:12340
Accept: */*
Content-type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#GetBinaryState"
Content-Length: 299

<?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"><BinaryState>1</BinaryState></u:GetBinaryState></s:Body></s:Envelope>
2017-11-23 22:15:49 fauxmo:102      DEBUG    Attempting to turn on <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0x102f6bcc0>
2017-11-23 22:17:04 asyncio:1260     ERROR    Exception in callback _SelectorSocketTransport._read_ready()
handle: <Handle _SelectorSocketTransport._read_ready() created at /Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:262>
source_traceback: Object created at (most recent call last):
  File "./fauxmo", line 11, in <module>
    sys.exit(cli())
  File "/Volumes/backup/scripts/venv/lib/python3.6/site-packages/fauxmo/cli.py", line 30, in cli
    main(config_path_str=args.config, verbosity=verbosity)
  File "/Volumes/backup/scripts/venv/lib/python3.6/site-packages/fauxmo/fauxmo.py", line 144, in main
    loop.run_forever()
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/base_events.py", line 421, in run_forever
    self._run_once()
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/base_events.py", line 1418, in _run_once
    handle._run()
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/events.py", line 127, in _run
    self._callback(*self._args)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py", line 262, in _add_reader
    handle = events.Handle(callback, args, self)
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 1318, in do_open
    encode_chunked=req.has_header('Transfer-encoding'))
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1239, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1285, in _send_request
    self.endheaders(body, encode_chunked=encode_chunked)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1234, in endheaders
    self._send_output(message_body, encode_chunked=encode_chunked)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1026, in _send_output
    self.send(msg)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 964, in send
    self.connect()
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 936, in connect
    (self.host,self.port), self.timeout, self.source_address)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/socket.py", line 724, in create_connection
    raise err
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/socket.py", line 713, in create_connection
    sock.connect(sa)
TimeoutError: [Errno 60] Operation timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/events.py", line 127, in _run
    self._callback(*self._args)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py", line 731, in _read_ready
    self._protocol.data_received(data)
  File "/Volumes/backup/scripts/venv/lib/python3.6/site-packages/fauxmo/protocols.py", line 55, in data_received
    self.handle_action(msg)
  File "/Volumes/backup/scripts/venv/lib/python3.6/site-packages/fauxmo/protocols.py", line 103, in handle_action
    success = self.plugin.on()
  File "/Volumes/backup/scripts/venv/lib/python3.6/site-packages/fauxmo/plugins/simplehttpplugin.py", line 100, in set_state
    with self.urlopen(req) as resp:
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 223, in urlopen
    return opener.open(url, data, timeout)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 526, in open
    response = self._open(req, data)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 544, in _open
    '_open', req)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 504, in _call_chain
    result = func(*args)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 1346, in http_open
    return self.do_open(http.client.HTTPConnection, req)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 1320, in do_open
    raise URLError(err)
urllib.error.URLError: <urlopen error [Errno 60] Operation timed out>
2017-11-23 22:17:04 asyncio:1422     WARNING  Executing <Handle _SelectorSocketTransport._read_ready() created at /Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:262> took 75.334 seconds
2017-11-23 22:17:04 asyncio:1380     DEBUG    poll took 0.039 ms: 4 events
2017-11-23 22:17:04 asyncio:734      DEBUG    <_SelectorSocketTransport fd=13 read=polling write=<idle, bufsize=0>> received EOF
2017-11-23 22:17:04 asyncio:182      DEBUG    <Server sockets=[<socket.socket fd=11, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12341)>]> got a new connection from ('192.168.1.63', 37348): <socket.socket fd=15, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12341), raddr=('192.168.1.63', 37348)>
2017-11-23 22:17:04 asyncio:182      DEBUG    <Server sockets=[<socket.socket fd=11, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12341)>]> got a new connection from ('192.168.1.63', 56712): <socket.socket fd=16, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12341), raddr=('192.168.1.63', 56712)>
2017-11-23 22:17:04 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:17:04 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:17:04 asyncio:182      DEBUG    <Server sockets=[<socket.socket fd=10, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12340)>]> got a new connection from ('192.168.1.63', 44157): <socket.socket fd=17, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.101', 12340), raddr=('192.168.1.63', 44157)>
2017-11-23 22:17:04 fauxmo:170      DEBUG    Received data below from ('192.168.1.47', 40585):
2017-11-23 22:17:04 fauxmo:171      DEBUG    b'NOTIFY * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nCache-Control: max-age=3600\r\nNT: upnp:rootdevice\r\nNTS: ssdp:alive\r\nLocation: http://192.168.1.47:8060/\r\nUSN: uuid:015e30d4-1400-1021-805e-dc3a5e62d3f5::upnp:rootdevice\r\n\r\n'
2017-11-23 22:17:04 fauxmo:38       DEBUG    Connection made with: ('192.168.1.63', 37348)
2017-11-23 22:17:04 fauxmo:38       DEBUG    Connection made with: ('192.168.1.63', 56712)
2017-11-23 22:17:04 fauxmo:38       DEBUG    Connection made with: ('192.168.1.63', 44157)
2017-11-23 22:17:04 fauxmo:170      DEBUG    Received data below from ('192.168.1.47', 40585):
2017-11-23 22:17:04 fauxmo:171      DEBUG    b'NOTIFY * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nCache-Control: max-age=3600\r\nNT: roku:ecp\r\nNTS: ssdp:alive\r\nLocation: http://192.168.1.47:8060/\r\nUSN: uuid:roku:ecp:1GS3D5008542\r\n\r\n'
2017-11-23 22:17:04 fauxmo:170      DEBUG    Received data below from ('192.168.1.47', 40585):
2017-11-23 22:17:04 fauxmo:171      DEBUG    b'NOTIFY * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nCache-Control: max-age=3600\r\nNT: urn:dial-multiscreen-org:service:dial:1\r\nNTS: ssdp:alive\r\nLocation: http://192.168.1.47:8060/dial/dd.xml\r\nUSN: uuid:015e30d4-1400-1021-805e-dc3a5e62d3f5::urn:dial-multiscreen-org:service:dial:1\r\n\r\n'
2017-11-23 22:17:04 fauxmo:49       DEBUG    Received message:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.1.101:12341
Accept: */*
Content-type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#GetBinaryState"
Content-Length: 299

<?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"><BinaryState>1</BinaryState></u:GetBinaryState></s:Body></s:Envelope>
2017-11-23 22:17:04 fauxmo:102      DEBUG    Attempting to turn on <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0x101295e80>
2017-11-23 22:17:05 fauxmo:119      DEBUG    HTTP/1.1 200 OK
CONTENT-LENGTH: 0
CONTENT-TYPE: text/xml charset="utf-8"
DATE: Fri, 24 Nov 2017 05:17:05 GMT
EXT:
SERVER: Unspecified, UPnP/1.0, Unspecified
X-User-Agent: Fauxmo
CONNECTION: close

2017-11-23 22:17:05 asyncio:1422     WARNING  Executing <Handle cancelled _SelectorSocketTransport._read_ready() created at /Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:262> took 1.241 seconds
2017-11-23 22:17:05 fauxmo:49       DEBUG    Received message:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.1.101:12341
Accept: */*
Content-type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#GetBinaryState"
Content-Length: 299

<?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"><BinaryState>1</BinaryState></u:GetBinaryState></s:Body></s:Envelope>
2017-11-23 22:17:05 fauxmo:102      DEBUG    Attempting to turn on <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0x101295e80>
2017-11-23 22:17:07 fauxmo:119      DEBUG    HTTP/1.1 200 OK
CONTENT-LENGTH: 0
CONTENT-TYPE: text/xml charset="utf-8"
DATE: Fri, 24 Nov 2017 05:17:07 GMT
EXT:
SERVER: Unspecified, UPnP/1.0, Unspecified
X-User-Agent: Fauxmo
CONNECTION: close

2017-11-23 22:17:07 asyncio:1422     WARNING  Executing <Handle cancelled _SelectorSocketTransport._read_ready() created at /Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:262> took 1.227 seconds
2017-11-23 22:17:07 fauxmo:49       DEBUG    Received message:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.1.101:12340
Accept: */*
Content-type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#GetBinaryState"
Content-Length: 299

<?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"><BinaryState>1</BinaryState></u:GetBinaryState></s:Body></s:Envelope>
2017-11-23 22:17:07 fauxmo:102      DEBUG    Attempting to turn on <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0x102f6bcc0>
2017-11-23 22:18:22 asyncio:1260     ERROR    Exception in callback _SelectorSocketTransport._read_ready()
handle: <Handle _SelectorSocketTransport._read_ready() created at /Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:262>
source_traceback: Object created at (most recent call last):
  File "./fauxmo", line 11, in <module>
    sys.exit(cli())
  File "/Volumes/backup/scripts/venv/lib/python3.6/site-packages/fauxmo/cli.py", line 30, in cli
    main(config_path_str=args.config, verbosity=verbosity)
  File "/Volumes/backup/scripts/venv/lib/python3.6/site-packages/fauxmo/fauxmo.py", line 144, in main
    loop.run_forever()
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/base_events.py", line 421, in run_forever
    self._run_once()
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/base_events.py", line 1418, in _run_once
    handle._run()
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/events.py", line 127, in _run
    self._callback(*self._args)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py", line 262, in _add_reader
    handle = events.Handle(callback, args, self)
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 1318, in do_open
    encode_chunked=req.has_header('Transfer-encoding'))
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1239, in request
    self._send_request(method, url, body, headers, encode_chunked)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1285, in _send_request
    self.endheaders(body, encode_chunked=encode_chunked)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1234, in endheaders
    self._send_output(message_body, encode_chunked=encode_chunked)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 1026, in _send_output
    self.send(msg)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 964, in send
    self.connect()
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/http/client.py", line 936, in connect
    (self.host,self.port), self.timeout, self.source_address)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/socket.py", line 724, in create_connection
    raise err
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/socket.py", line 713, in create_connection
    sock.connect(sa)
TimeoutError: [Errno 60] Operation timed out

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/events.py", line 127, in _run
    self._callback(*self._args)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py", line 731, in _read_ready
    self._protocol.data_received(data)
  File "/Volumes/backup/scripts/venv/lib/python3.6/site-packages/fauxmo/protocols.py", line 55, in data_received
    self.handle_action(msg)
  File "/Volumes/backup/scripts/venv/lib/python3.6/site-packages/fauxmo/protocols.py", line 103, in handle_action
    success = self.plugin.on()
  File "/Volumes/backup/scripts/venv/lib/python3.6/site-packages/fauxmo/plugins/simplehttpplugin.py", line 100, in set_state
    with self.urlopen(req) as resp:
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 223, in urlopen
    return opener.open(url, data, timeout)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 526, in open
    response = self._open(req, data)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 544, in _open
    '_open', req)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 504, in _call_chain
    result = func(*args)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 1346, in http_open
    return self.do_open(http.client.HTTPConnection, req)
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/urllib/request.py", line 1320, in do_open
    raise URLError(err)
urllib.error.URLError: <urlopen error [Errno 60] Operation timed out>
2017-11-23 22:18:22 asyncio:1422     WARNING  Executing <Handle _SelectorSocketTransport._read_ready() created at /Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/asyncio/selector_events.py:262> took 75.282 seconds
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.47', 40585):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'NOTIFY * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nCache-Control: max-age=3600\r\nNT: upnp:rootdevice\r\nNTS: ssdp:alive\r\nLocation: http://192.168.1.47:8060/\r\nUSN: uuid:015e30d4-1400-1021-805e-dc3a5e62d3f5::upnp:rootdevice\r\n\r\n'
2017-11-23 22:18:22 asyncio:734      DEBUG    <_SelectorSocketTransport fd=17 read=polling write=<idle, bufsize=0>> received EOF
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.47', 40585):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'NOTIFY * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nCache-Control: max-age=3600\r\nNT: roku:ecp\r\nNTS: ssdp:alive\r\nLocation: http://192.168.1.47:8060/\r\nUSN: uuid:roku:ecp:1GS3D5008542\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.022 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.47', 40585):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'NOTIFY * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nCache-Control: max-age=3600\r\nNT: urn:dial-multiscreen-org:service:dial:1\r\nNTS: ssdp:alive\r\nLocation: http://192.168.1.47:8060/dial/dd.xml\r\nUSN: uuid:015e30d4-1400-1021-805e-dc3a5e62d3f5::urn:dial-multiscreen-org:service:dial:1\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.021 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.47', 40585):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'NOTIFY * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nCache-Control: max-age=3600\r\nNT: upnp:rootdevice\r\nNTS: ssdp:alive\r\nLocation: http://192.168.1.47:8060/\r\nUSN: uuid:015e30d4-1400-1021-805e-dc3a5e62d3f5::upnp:rootdevice\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.016 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.47', 40585):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'NOTIFY * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nCache-Control: max-age=3600\r\nNT: roku:ecp\r\nNTS: ssdp:alive\r\nLocation: http://192.168.1.47:8060/\r\nUSN: uuid:roku:ecp:1GS3D5008542\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.019 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.47', 40585):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'NOTIFY * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nCache-Control: max-age=3600\r\nNT: urn:dial-multiscreen-org:service:dial:1\r\nNTS: ssdp:alive\r\nLocation: http://192.168.1.47:8060/dial/dd.xml\r\nUSN: uuid:015e30d4-1400-1021-805e-dc3a5e62d3f5::urn:dial-multiscreen-org:service:dial:1\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.019 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 2059):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 5\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nConnection: close\r\nHost: 239.255.255.250:1900\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.016 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 2059):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 5\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nConnection: close\r\nHost: 239.255.255.250:1900\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.015 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.018 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 56995):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nST: upnp:rootdevice\r\nMX: 3\r\nMAN: "ssdp:discover"\r\nHOST: 239.255.255.250:1900\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.013 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.63', 50000):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nMX: 15\r\nST: urn:schemas-upnp-org:device:basic:1\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.013 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.63', 50000):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nMX: 15\r\nST: urn:schemas-upnp-org:device:basic:1\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.013 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.63', 50000):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nMX: 15\r\nST: urn:Belkin:device:**\r\n\r\n'
2017-11-23 22:18:22 fauxmo:205      DEBUG    Sending response to ('192.168.1.63', 50000):
HTTP/1.1 200 OK
CACHE-CONTROL: max-age=86400
DATE: Fri, 24 Nov 2017 05:18:22 GMT
EXT:
LOCATION: http://192.168.1.101:12340/setup.xml
OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01
01-NLS: bdd9ab52-02a1-4210-9dce-25b69a1dc422
SERVER: Unspecified, UPnP/1.0, Unspecified
ST: urn:Belkin:device:**
USN: uuid:Socket-1_0-cc85abef-58d3-31b5-9d22-15f84f0e9ad9::urn:Belkin:device:**

2017-11-23 22:18:22 fauxmo:205      DEBUG    Sending response to ('192.168.1.63', 50000):
HTTP/1.1 200 OK
CACHE-CONTROL: max-age=86400
DATE: Fri, 24 Nov 2017 05:18:22 GMT
EXT:
LOCATION: http://192.168.1.101:12341/setup.xml
OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01
01-NLS: b4a8a069-6f0d-4370-9b1c-aab64d4492e7
SERVER: Unspecified, UPnP/1.0, Unspecified
ST: urn:Belkin:device:**
USN: uuid:Socket-1_0-e32c15ba-7d29-359e-b1ce-e29bd39a4238::urn:Belkin:device:**

2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.63', 50000):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nMX: 15\r\nST: urn:Belkin:device:**\r\n\r\n'
2017-11-23 22:18:22 fauxmo:205      DEBUG    Sending response to ('192.168.1.63', 50000):
HTTP/1.1 200 OK
CACHE-CONTROL: max-age=86400
DATE: Fri, 24 Nov 2017 05:18:22 GMT
EXT:
LOCATION: http://192.168.1.101:12340/setup.xml
OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01
01-NLS: a649740c-4021-4adc-b02c-30f3a6054602
SERVER: Unspecified, UPnP/1.0, Unspecified
ST: urn:Belkin:device:**
USN: uuid:Socket-1_0-cc85abef-58d3-31b5-9d22-15f84f0e9ad9::urn:Belkin:device:**

2017-11-23 22:18:22 fauxmo:205      DEBUG    Sending response to ('192.168.1.63', 50000):
HTTP/1.1 200 OK
CACHE-CONTROL: max-age=86400
DATE: Fri, 24 Nov 2017 05:18:22 GMT
EXT:
LOCATION: http://192.168.1.101:12341/setup.xml
OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01
01-NLS: a02288f7-da28-4563-8551-8715e2c73411
SERVER: Unspecified, UPnP/1.0, Unspecified
ST: urn:Belkin:device:**
USN: uuid:Socket-1_0-e32c15ba-7d29-359e-b1ce-e29bd39a4238::urn:Belkin:device:**

2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.011 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 53035):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 53035):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 56395):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 56395):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.009 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 2059):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 5\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nConnection: close\r\nHost: 239.255.255.250:1900\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 2059):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 5\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nConnection: close\r\nHost: 239.255.255.250:1900\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 56995):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nST: upnp:rootdevice\r\nMX: 3\r\nMAN: "ssdp:discover"\r\nHOST: 239.255.255.250:1900\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.011 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.6', 55539):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nMX: 1\r\nST: urn:dial-multiscreen-org:service:dial:1\r\nUSER-AGENT: Google Chrome/62.0.3202.94 Mac OS X\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.6', 55539):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nMX: 1\r\nST: urn:dial-multiscreen-org:service:dial:1\r\nUSER-AGENT: Google Chrome/62.0.3202.94 Mac OS X\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.6', 55539):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nMX: 1\r\nST: urn:dial-multiscreen-org:service:dial:1\r\nUSER-AGENT: Google Chrome/62.0.3202.94 Mac OS X\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.6', 55539):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nMAN: "ssdp:discover"\r\nMX: 1\r\nST: urn:dial-multiscreen-org:service:dial:1\r\nUSER-AGENT: Google Chrome/62.0.3202.94 Mac OS X\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.011 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 53035):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 53035):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 56395):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 56395):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.011 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.012 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 2059):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 5\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nConnection: close\r\nHost: 239.255.255.250:1900\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 2059):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 5\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nConnection: close\r\nHost: 239.255.255.250:1900\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.011 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.011 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 56995):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nST: upnp:rootdevice\r\nMX: 3\r\nMAN: "ssdp:discover"\r\nHOST: 239.255.255.250:1900\r\n\r\n'
2017-11-23 22:18:22 asyncio:1380     DEBUG    poll took 0.010 ms: 1 events
2017-11-23 22:18:22 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:22 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:23 asyncio:1380     INFO     poll took 1229.408 ms: 1 events
2017-11-23 22:18:23 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:23 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:29 asyncio:1380     INFO     poll took 5634.938 ms: 1 events
2017-11-23 22:18:29 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 53035):
2017-11-23 22:18:29 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2017-11-23 22:18:29 asyncio:1380     DEBUG    poll took 0.023 ms: 1 events
2017-11-23 22:18:29 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 53035):
2017-11-23 22:18:29 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2017-11-23 22:18:29 asyncio:1380     DEBUG    poll took 633.319 ms: 1 events
2017-11-23 22:18:29 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 56395):
2017-11-23 22:18:29 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2017-11-23 22:18:29 asyncio:1380     DEBUG    poll took 0.023 ms: 1 events
2017-11-23 22:18:29 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 56395):
2017-11-23 22:18:29 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2017-11-23 22:18:33 asyncio:1380     INFO     poll took 3721.426 ms: 1 events
2017-11-23 22:18:33 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:33 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:38 asyncio:1380     INFO     poll took 4633.716 ms: 1 events
2017-11-23 22:18:38 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 2059):
2017-11-23 22:18:38 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 5\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nConnection: close\r\nHost: 239.255.255.250:1900\r\n\r\n'
2017-11-23 22:18:38 asyncio:1380     DEBUG    poll took 0.036 ms: 1 events
2017-11-23 22:18:38 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 2059):
2017-11-23 22:18:38 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 5\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.5.13\r\nConnection: close\r\nHost: 239.255.255.250:1900\r\n\r\n'
2017-11-23 22:18:43 asyncio:1380     INFO     poll took 5361.891 ms: 1 events
2017-11-23 22:18:43 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:43 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:18:53 asyncio:1380     INFO     poll took 9996.296 ms: 1 events
2017-11-23 22:18:53 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:18:53 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:19:03 asyncio:1380     INFO     poll took 9995.495 ms: 1 events
2017-11-23 22:19:03 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 64095):
2017-11-23 22:19:03 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nHost: 239.255.255.250:1900\r\nMan: "ssdp:discover"\r\nST: ssdp:all\r\nMX: 5\r\n\r\n'
2017-11-23 22:19:03 asyncio:1380     DEBUG    poll took 340.652 ms: 1 events
2017-11-23 22:19:03 fauxmo:170      DEBUG    Received data below from ('192.168.1.101', 56995):
2017-11-23 22:19:03 fauxmo:171      DEBUG    b'M-SEARCH * HTTP/1.1\r\nST: upnp:rootdevice\r\nMX: 3\r\nMAN: "ssdp:discover"\r\nHOST: 239.255.255.250:1900\r\n\r\n'
screen shot 2017-11-23 at 10 16 46 pm screen shot 2017-11-23 at 10 17 20 pm
n8henrie commented 6 years ago

Thanks for the quick response. This looks like it may be a different problem, so please go ahead and start a new issue for it. Also please make sure you include your config, and upgrade to the most recent Fauxmo version (v0.4.5) and include debug output from that version.

lombarke commented 6 years ago

will do! thanks!

n8henrie commented 6 years ago

Closing as I think these are different issues. @lombarke is using yet a different firmware version, but seems like his search requests are being responded to and devices are being discovered.

drduker commented 6 years ago

This is still an issue for me. Alexa Echo dot v1 and v2 and Echo in use. Running fauxmo on raspberry pi zero w with python3.6.1 and Raspbian Stetch lite. I also have a Raspberry Pi 3 that still works for discovery that was built 6 months ago and for some reason if I remove and readd devices those are still discovered but no new PIs running fauxmo will work. The working raspberry pi uses: https://github.com/kanesurendra/echo-pi