Closed johngo7470 closed 5 years ago
You mention lighttpd a few times -- is this running your CGI script?
Please include your verbose Fauxmo log output.
Should state checks even be performed as part of the simplehttpplugin?
You're right, interestingly the docs don't seem to have updated: https://fauxmo.readthedocs.io/en/latest/fauxmo.plugins.html#module-fauxmo.plugins.simplehttpplugin . Would you mind making an issue so I don't forget to investigate this?
Your Echo does the state checks (and will try to confirm that the state changed after a command was given, or respond that it is "not responding"). I can't stop it from doing so, I can only allow users to configure Fauxmo to reflect these state changes. If your CGI script can reflect the state of the device, you can probably configure it so this will work. If it can't, then you might not be able to get rid of these messages, since this is Echo behavior that I can't change.
Nate
[You mention lighttpd a few times -- is this running your CGI script?]
Yes, somewhat buried in the Curl output up above, is "OK" (preceded by Content-Length: 3) - the "OK" is text from my cgi.
[Your Echo does the state checks (and will try to confirm that the state changed after a command was given, or respond that it is "not responding"). I can't stop it from doing so, I can only allow users to configure Fauxmo to reflect these state changes.]
When I did my test again this evening, I only see two entries in my lighttpd log - one for turning the light on, and one for turning the light off. I do not see any requests for state in my access.log. However, when I add the state parameters back into my config.json, I see a total of six entries in my lighttpd log, 4 of which are requests to the state function. It kinda looks like in simplehttpplugin mode, the state requests from Alexa, are not forwarded to my cgi (which wouldn't be possible anyway, because I haven't defined "state_cmd"), but when state_cmd is defined, even when it shouldn't be, somehow, the state requests are now being forwarded to my cgi state_cmd.
That I am seeing 1 state_cmd request in my http log, just after a successful call to turn my light on (Alexa response with 'ok'), and I'm seeing 3 state_cmd requests when my request to turn off a light, fails (Alexa responds with 'my call light isn't responding')
Here, is the output from -vvv including output for discovery, one request to turn on and one request to turn off. Please note that this was run with my original config.json, which does NOT contain the REST-related state parameters of state_cmd, state_response_on and state_resposne_off:
pi@raspberrypi:~ $ fauxmo -c config.json -vvv 2019-09-09 19:43:38 fauxmo:41 INFO Fauxmo v0.4.9 2019-09-09 19:43:38 fauxmo:42 DEBUG 3.7.3 (default, Apr 3 2019, 05:39:12) [GCC 8.2.0] 2019-09-09 19:43:38 fauxmo:25 DEBUG Attempting to get IP address automatically 2019-09-09 19:43:38 fauxmo:41 DEBUG Using IP address: 192.168.2.106 2019-09-09 19:43:38 fauxmo:111 DEBUG plugin_vars: {} 2019-09-09 19:43:38 fauxmo:114 DEBUG device config: {'port': 12340, 'on_cmd': 'http://192.168.2.106/cgi-bin/light_on.cgi', 'off_cmd': 'http://192.168.2.106/cgi-bin/light_off.cgi', 'method': 'GET', 'name': 'my call light'} 2019-09-09 19:43:38 asyncio:1403 INFO <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> is serving 2019-09-09 19:43:38 fauxmo:133 DEBUG Started fauxmo device: {'name': 'my call light', 'plugin': <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0xb5fb23d0>} 2019-09-09 19:43:38 fauxmo:135 INFO Starting UDP server 2019-09-09 19:43:38 asyncio:1259 DEBUG Datagram endpoint remote_addr=None created: (<_SelectorDatagramTransport fd=8 read=idle write=<idle, bufsize=0>>, <fauxmo.protocols.SSDPServer object at 0xb5fb2130>) 2019-09-09 19:43:40 asyncio:1729 INFO poll took 2659.981 ms: 1 events 2019-09-09 19:43:40 fauxmo:343 DEBUG Received data below from ('192.168.2.170', 45140): 2019-09-09 19:43:40 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 HOST: 239.255.255.250:1900 MAN: "ssdp:discover" MX: 5 ST: urn:schemas-echostar-com:service:EchostarService:1
2019-09-09 19:43:42 asyncio:1729 DEBUG poll took 304.925 ms: 1 events 2019-09-09 19:43:42 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-09 19:43:42 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
2019-09-09 19:43:42 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Tue, 10 Sep 2019 00:43:42 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 67d55586-0602-407a-aba6-7f5ab755a0f6\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: ssdp:all\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all\r\n\r\n' 2019-09-09 19:43:42 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-09 19:43:42 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
2019-09-09 19:43:42 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Tue, 10 Sep 2019 00:43:42 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 91305805-a384-4195-a435-43187b47fe64\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: upnp:rootdevice\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice\r\n\r\n' 2019-09-09 19:43:42 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-09 19:43:42 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
2019-09-09 19:43:42 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Tue, 10 Sep 2019 00:43:42 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 69217b34-822b-42ec-9aa1-24ef3065d985\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: ssdp:all\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all\r\n\r\n' 2019-09-09 19:43:42 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-09 19:43:42 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
2019-09-09 19:43:42 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Tue, 10 Sep 2019 00:43:42 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 6527c345-6efc-4e75-b0dc-69ff5f173ea7\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: upnp:rootdevice\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice\r\n\r\n' 2019-09-09 19:43:42 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-09 19:43:42 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
2019-09-09 19:43:42 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Tue, 10 Sep 2019 00:43:42 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 532fac4c-d6b7-4cf2-95e0-d8ae9b441ef3\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: ssdp:all\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all\r\n\r\n' 2019-09-09 19:43:42 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-09 19:43:42 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
2019-09-09 19:43:42 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Tue, 10 Sep 2019 00:43:42 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 76f90c7f-5079-4cb6-813c-9b7e81914192\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: upnp:rootdevice\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice\r\n\r\n'
2019-09-09 19:43:50 asyncio:1729 INFO poll took 4411.747 ms: 1 events 2019-09-09 19:43:50 asyncio:159 DEBUG <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> got a new connection from ('192.168.2.111', 36744): <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340), raddr=('192.168.2.111', 36744)> 2019-09-09 19:43:50 fauxmo:41 DEBUG Connection made with: ('192.168.2.111', 36744) 2019-09-09 19:43:50 fauxmo:52 DEBUG Received message: GET /setup.xml HTTP/1.1 Content-Type: application/json User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip
2019-09-09 19:43:50 fauxmo:54 INFO setup.xml requested by Echo 2019-09-09 19:43:50 fauxmo:100 DEBUG Fauxmo response to setup request: HTTP/1.1 200 OK CONTENT-LENGTH: 953 CONTENT-TYPE: text/xml DATE: Tue, 10 Sep 2019 00:43:50 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"?>
<?xml version="1.0" encoding="utf-8"?>
2019-09-09 19:44:38 asyncio:1729 INFO poll took 10323.728 ms: 1 events 2019-09-09 19:44:38 asyncio:159 DEBUG <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> got a new connection from ('192.168.2.111', 59209): <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340), raddr=('192.168.2.111', 59209)> 2019-09-09 19:44:38 fauxmo:41 DEBUG Connection made with: ('192.168.2.111', 59209) 2019-09-09 19:44:38 fauxmo:52 DEBUG Received message: POST /upnp/control/basicevent1 HTTP/1.1 SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState" Content-Type: text/xml; charset="utf-8" Accept: User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip Content-Length: 299
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
2019-09-09 19:44:52 asyncio:1729 DEBUG poll took 137.000 ms: 1 events 2019-09-09 19:44:52 asyncio:159 DEBUG <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> got a new connection from ('192.168.2.111', 33765): <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340), raddr=('192.168.2.111', 33765)> 2019-09-09 19:44:52 fauxmo:41 DEBUG Connection made with: ('192.168.2.111', 33765) 2019-09-09 19:44:52 fauxmo:52 DEBUG Received message: POST /upnp/control/basicevent1 HTTP/1.1 SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState" Content-Type: text/xml; charset="utf-8" Accept: User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip Content-Length: 299
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
One side question... when my scripts (URL's) are learned by Alexa, fauxmo would no longer need to be running, yes? I know when Alexa sends requests via https, normally, it wants a Content-Type: application/json in the reply - do my cgi scripts need to return application/json headers? Or is the "local" http protocol a bit more relaxed?
Yes, somewhat buried in the Curl output up above, is "OK" (preceded by Content-Length: 3) - the "OK" is text from my cgi.
Ah, I thought that was just the HTTP status code 200 OK
.
When I did my test again this evening, I only see two entries in my lighttpd log - one for turning the light on, and one for turning the light off. I do not see any requests for state in my access.log. However, when I add the state parameters back into my config.json, I see a total of six entries in my lighttpd log, 4 of which are requests to the state function. It kinda looks like in simplehttpplugin mode, the state requests from Alexa, are not forwarded to my cgi (which wouldn't be possible anyway, because I haven't defined "state_cmd"), but when state_cmd is defined, even when it shouldn't be, somehow, the state requests are now being forwarded to my cgi state_cmd.
Correct. The Echo will still request the state from Fauxmo -- if Fauxmo has no way of determining the state, it responds with "unknown," and the Echo will complain. If your CGI script has an endpoint that can return the device state (not whether a command was successful, but the state), put that into the config, and it should work.
One side question... when my scripts (URL's) are learned by Alexa, fauxmo would no longer need to be running, yes?
Incorrect. The Echo remembers your Fauxmo address:port combination and never "sees" your end device, that all goes through Fauxmo.
I know when Alexa sends requests via https, normally, it wants a Content-Type: application/json
That's news to me: https://github.com/n8henrie/fauxmo/blob/master/protocol_notes.md
in the reply - do my cgi scripts need to return application/json headers? Or is the "local" http protocol a bit more relaxed?
That's up to you: "For more complicated requests (e.g. authentication, sending JSON), check out RESTAPIPlugin in https://github.com/n8henrie/fauxmo-plugins/, which takes advantage of Requests’ rich API." By default SimpleHTTPPlugin is not expecting JSON, but if you want to use JSON you can either configure it accordingly (can often be rigged to work with regular string processing) or use a different plugin.
If your CGI script has an endpoint that can return the device state (not whether a command was successful, but the state), put that into the config, and it should work.
Part of the question, is why it is requesting state, if I'm using simplehttpplugin - shouldn't the "state" configuration parameters be invalid for the simplehttpplugin (only available in the RESTAPIPlugin)?
That's news to me: https://github.com/n8henrie/fauxmo/blob/master/protocol_notes.md
Sorry - I was referring to Alexa Skill communication protocol via https... ;) https://developer.amazon.com/docs/custom-skills/request-and-response-json-reference.html
Seems when Alexa is controlling something on the local network, it skips using https and the need for json responses.
=====
Ok, so getting back to the original problem. When using the basic simplehttpplugin:
"port": 12340,
"on_cmd": "http://192.168.2.106/cgi-bin/light_on.cgi",
"off_cmd": "http://192.168.2.106/cgi-bin/light_off.cgi",
"method": "GET",
"name": "my call light"
Both 'on' and 'off' CGI's are called/executed, but the 'on' request results in Alexa giving a 'not responding' response. When I request the 'off' function, I get a proper response of 'ok'.
The -vvv log for this behavior, is in my prior post of this thread (posted 9/9).
If I add the following "state" parameters to simplehttpplugin (where they shouldn't be honored):
"state_cmd": "http://192.168.2.106/cgi-bin/light_state.cgi",
"state_response_on": "OK",
"state_response_off": "OFF",
it results in the behavior being flipped ('on' will give an 'ok', and 'off' will give a 'not responding), and, I notice in the http log file, that whenever Alexa give an 'ok', I only see one state request, and whenever there is a 'not responding', I see three state requests.
I'm sorry, but I think you're confused on a few issues.
Part of the question, is why it is requesting state, if I'm using simplehttpplugin - shouldn't the "state" configuration parameters be invalid for the simplehttpplugin (only available in the RESTAPIPlugin)?
As I've stated, this is behavior of the Amazon Echo, unrelated to my project Fauxmo. The Echo will always ask for state, no matter what. Please don't go past this sentence until that makes sense, because nothing else will until you see what I'm saying here. This is not something I control, this is behavior that Amazon controls.
Sorry - I was referring to Alexa Skill communication protocol via https... ;)
This project is entirely unrelated to Alexa Skills.
Both 'on' and 'off' CGI's are called/executed, but the 'on' request results in Alexa giving a 'not responding' response. When I request the 'off' function, I get a proper response of 'ok'.
Again, the state behavior is a separate concern and is unrelated to turning a device on or off, except that the Echo makes a get state
request immediately following a set state
(in addition to other times).
Can you show me the full output of the following commands, in order, preferably in a code block?
$ curl http://192.168.2.106/cgi-bin/light_state.cgi
$ curl http://192.168.2.106/cgi-bin/light_on.cgi
$ curl http://192.168.2.106/cgi-bin/light_state.cgi
$ curl http://192.168.2.106/cgi-bin/light_off.cgi
$ curl http://192.168.2.106/cgi-bin/light_state.cgi
Also, please make 2 additional replies, each including the config and respective verbose log output (including an "on" and "off" command) and description of the observed behavior. In the first reply, please use a config with no state
set. In the second, please configure your state_cmd
s according to the cgi script responses that you're expecting.
Hopefully this will help clear things up.
[The Echo will always ask for state, no matter what.]
Unfortunately, this is not quite what I am seeing.
When I only have the following simplehttpplugin block defined:
"port": 12340,
"on_cmd": "http://192.168.2.106/cgi-bin/light_on.cgi",
"off_cmd": "http://192.168.2.106/cgi-bin/light_off.cgi",
"method": "GET",
"name": "my call light"
And I then request Alexa to "turn on my call light" (to which she responds 'my call light is not responding') and then I request Alexa to "turn off my call light" (to which she responds 'ok', there are only two entries in my http access log:
192.168.2.106 192.168.2.106 - [13/Sep/2019:18:27:24 -0500] "GET /cgi-bin/lighton.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:27:36 -0500] "GET /cgi-bin/lightoff.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7"
Then if I modify the simplehttpplugin block to include "state" statements:
"port": 12340,
"on_cmd": "http://192.168.2.106/cgi-bin/light_on.cgi",
"off_cmd": "http://192.168.2.106/cgi-bin/light_off.cgi",
"method": "GET",
**"state_cmd": "http://192.168.2.106/cgi-bin/light_state.cgi",
"state_response_on": "OK",
"state_response_off": "OFF",**
"name": "my call light"
And perform the same test (Alexa, turn on my call light.... Alexa, turn off my call light), I now see 6 entries in my http access log:
192.168.2.106 192.168.2.106 - [13/Sep/2019:18:29:43 -0500] "GET /cgi-bin/lighton.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:29:43 -0500] "GET /cgi-bin/lightstate.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:29:52 -0500] "GET /cgi-bin/lightoff.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:29:52 -0500] "GET /cgi-bin/lightstate.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:29:53 -0500] "GET /cgi-bin/lightstate.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:29:54 -0500] "GET /cgi-bin/lightstate.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7"
Which ever command (on or off) has three state requests in the log, is also the command that Alexa says is not responding (even though it's being executed).
The origination IP address is the same as the destination IP, so I presume these are fauxmo requests to lighttpd (my webserver), not Alexa's requests.
The behavior I'm seeing is very similar to what was reported in Issue number 61 - down to the three requests for call state and the 'not responding' from Alexa.
This is also why I've been asking why "state" statements in a simplehttpplugin block are seemingly being acted upon, when they really shouldn't be there - they should only be valid in a RESTAPIplugin block.
I'll run the commands above, and collect the log, when I get home. I should also be able to provide remote access to you, if you want to take a look, directly.
pi@raspberrypi:~ $ curl http://192.168.2.106/cgi-bin/light_state.cgi OK pi@raspberrypi:~ $ curl http://192.168.2.106/cgi-bin/light_on.cgi OK pi@raspberrypi:~ $ curl http://192.168.2.106/cgi-bin/light_state.cgi OK pi@raspberrypi:~ $ curl http://192.168.2.106/cgi-bin/light_off.cgi OK pi@raspberrypi:~ $ curl http://192.168.2.106/cgi-bin/light_state.cgi OK
lighttpd log:
192.168.2.106 192.168.2.106 - [13/Sep/2019:18:55:37 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "curl/7.64.0" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:55:37 -0500] "GET /cgi-bin/light_on.cgi HTTP/1.1" 200 3 "-" "curl/7.64.0" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:55:37 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "curl/7.64.0" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:55:37 -0500] "GET /cgi-bin/light_off.cgi HTTP/1.1" 200 3 "-" "curl/7.64.0" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:55:37 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "curl/7.64.0"
pi@raspberrypi:~ $ curl -v http://192.168.2.106/cgi-bin/light_state.cgi curl -v http://192.168.2.106/cgi-bin/light_state.cgi curl -v http://192.168.2.106/cgi-bin/light_off.cgi curl -v http://192.168.2.106/cgi-bin/light_state.cgi
GET /cgi-bin/light_state.cgi HTTP/1.1 Host: 192.168.2.106 User-Agent: curl/7.64.0 Accept: /
< HTTP/1.1 200 OK < Content-type: text/plain < Content-Length: 3 < Date: Fri, 13 Sep 2019 23:57:42 GMT < Server: lighttpd/1.4.53 < OK
GET /cgi-bin/light_on.cgi HTTP/1.1 Host: 192.168.2.106 User-Agent: curl/7.64.0 Accept: /
< HTTP/1.1 200 OK < Content-type: text/plain < Content-Length: 3 < Date: Fri, 13 Sep 2019 23:57:42 GMT < Server: lighttpd/1.4.53 < OK
GET /cgi-bin/light_state.cgi HTTP/1.1 Host: 192.168.2.106 User-Agent: curl/7.64.0 Accept: /
< HTTP/1.1 200 OK < Content-type: text/plain < Content-Length: 3 < Date: Fri, 13 Sep 2019 23:57:42 GMT < Server: lighttpd/1.4.53 < OK
GET /cgi-bin/light_off.cgi HTTP/1.1 Host: 192.168.2.106 User-Agent: curl/7.64.0 Accept: /
< HTTP/1.1 200 OK < Content-type: text/plain < Content-Length: 3 < Date: Fri, 13 Sep 2019 23:57:42 GMT < Server: lighttpd/1.4.53 < OK
GET /cgi-bin/light_state.cgi HTTP/1.1 Host: 192.168.2.106 User-Agent: curl/7.64.0 Accept: /
< HTTP/1.1 200 OK < Content-type: text/plain < Content-Length: 3 < Date: Fri, 13 Sep 2019 23:57:43 GMT < Server: lighttpd/1.4.53 < OK
192.168.2.106 192.168.2.106 - [13/Sep/2019:18:57:42 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "curl/7.64.0" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:57:42 -0500] "GET /cgi-bin/light_on.cgi HTTP/1.1" 200 3 "-" "curl/7.64.0" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:57:42 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "curl/7.64.0" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:57:42 -0500] "GET /cgi-bin/light_off.cgi HTTP/1.1" 200 3 "-" "curl/7.64.0" 192.168.2.106 192.168.2.106 - [13/Sep/2019:18:57:43 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "curl/7.64.0"
Without state parameters:
{ "FAUXMO": { "ip_address": "auto" }, "PLUGINS": { "SimpleHTTPPlugin": { "DEVICES": [ { "port": 12340, "on_cmd": "http://192.168.2.106/cgi-bin/light_on.cgi", "off_cmd": "http://192.168.2.106/cgi-bin/light_off.cgi", "method": "GET", "name": "my call light" } ] } } }
-vvv Discovery, on, off (when I asked Alexa to turn On my call light, the on cgi is executed, but Alexa says it didn't respond; when I asked Alexa to turn OFF my call light, the off cgi is executed, and Alexa says 'ok'):
pi@raspberrypi:~ $ fauxmo -c fauxmo_config.json -vvv 2019-09-13 19:11:18 fauxmo:41 INFO Fauxmo v0.4.9 2019-09-13 19:11:18 fauxmo:42 DEBUG 3.7.3 (default, Apr 3 2019, 05:39:12) [GCC 8.2.0] 2019-09-13 19:11:18 fauxmo:25 DEBUG Attempting to get IP address automatically 2019-09-13 19:11:18 fauxmo:41 DEBUG Using IP address: 192.168.2.106 2019-09-13 19:11:18 fauxmo:111 DEBUG plugin_vars: {} 2019-09-13 19:11:18 fauxmo:114 DEBUG device config: {'port': 12340, 'on_cmd': 'http://192.168.2.106/cgi-bin/light_on.cgi', 'off_cmd': 'http://192.168.2.106/cgi-bin/light_off.cgi', 'method': 'GET', 'name': 'my call light'} 2019-09-13 19:11:18 asyncio:1403 INFO <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> is serving 2019-09-13 19:11:18 fauxmo:133 DEBUG Started fauxmo device: {'name': 'my call light', 'plugin': <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0xb60453f0>} 2019-09-13 19:11:18 fauxmo:135 INFO Starting UDP server 2019-09-13 19:11:18 asyncio:1259 DEBUG Datagram endpoint remote_addr=None created: (<_SelectorDatagramTransport fd=8 read=idle write=<idle, bufsize=0>>, <fauxmo.protocols.SSDPServer object at 0xb6045150>) 2019-09-13 19:11:22 asyncio:1729 INFO poll took 3481.009 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: upnp:rootdevice USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::upnp:rootdevice NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.069 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.066 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:InternetGatewayDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:InternetGatewayDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.062 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANConnectionDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANConnectionDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.057 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANIPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANIPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.062 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANPPPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANPPPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.066 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:Layer3Forwarding:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:Layer3Forwarding:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:35 asyncio:1729 INFO poll took 12976.544 ms: 1 events 2019-09-13 19:11:35 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:11:35 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
2019-09-13 19:11:35 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:11:35 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 6c9fa6bc-c224-4027-a84c-117f5578e135\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: ssdp:all\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all\r\n\r\n' 2019-09-13 19:11:35 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:11:35 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
2019-09-13 19:11:35 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:11:35 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 0e29e2cf-cdc0-4256-b905-ee4d3453202a\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: upnp:rootdevice\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice\r\n\r\n' 2019-09-13 19:11:35 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:11:35 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
2019-09-13 19:11:35 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:11:35 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 0ae99f2d-0ea6-4403-b6a0-ca16f8c805ba\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: ssdp:all\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all\r\n\r\n' 2019-09-13 19:11:35 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:11:35 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
2019-09-13 19:11:35 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:11:35 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 316ba336-2554-4503-90d3-026e47574140\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: upnp:rootdevice\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice\r\n\r\n' 2019-09-13 19:11:35 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:11:35 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
2019-09-13 19:11:35 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:11:35 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 69beda6e-6c50-4710-bb1b-390680a3b2f7\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: ssdp:all\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all\r\n\r\n' 2019-09-13 19:11:35 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:11:35 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
2019-09-13 19:11:35 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:11:35 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 3ade1c62-a3f9-46e6-8f3c-5ee9be4a1d68\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: upnp:rootdevice\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice\r\n\r\n' 2019-09-13 19:11:37 asyncio:1737 INFO poll 1451.397 ms took 1453.519 ms: timeout 2019-09-13 19:11:40 asyncio:1729 INFO poll took 2672.930 ms: 1 events 2019-09-13 19:11:40 asyncio:159 DEBUG <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> got a new connection from ('192.168.2.111', 50892): <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340), raddr=('192.168.2.111', 50892)> 2019-09-13 19:11:40 fauxmo:41 DEBUG Connection made with: ('192.168.2.111', 50892) 2019-09-13 19:11:40 fauxmo:52 DEBUG Received message: GET /setup.xml HTTP/1.1 Content-Type: application/json User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip
2019-09-13 19:11:40 fauxmo:54 INFO setup.xml requested by Echo 2019-09-13 19:11:40 fauxmo:100 DEBUG Fauxmo response to setup request: HTTP/1.1 200 OK CONTENT-LENGTH: 953 CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 00:11:40 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"?>
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
2019-09-13 19:11:48 asyncio:1729 INFO poll took 3055.479 ms: 1 events 2019-09-13 19:11:48 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:11:48 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:48 asyncio:1729 DEBUG poll took 0.071 ms: 1 events 2019-09-13 19:11:48 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:11:48 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:51 asyncio:1729 INFO poll took 2965.846 ms: 1 events 2019-09-13 19:11:51 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:11:51 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:51 asyncio:1729 DEBUG poll took 93.879 ms: 1 events 2019-09-13 19:11:51 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:11:51 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:52 asyncio:1729 INFO poll took 1020.773 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: upnp:rootdevice USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::upnp:rootdevice NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.066 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.067 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:InternetGatewayDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:InternetGatewayDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.065 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANConnectionDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANConnectionDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.060 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.063 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANIPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANIPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.065 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANPPPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANPPPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:Layer3Forwarding:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:Layer3Forwarding:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:54 asyncio:1729 INFO poll took 1924.235 ms: 1 events 2019-09-13 19:11:54 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:11:54 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:54 asyncio:1729 DEBUG poll took 0.065 ms: 1 events 2019-09-13 19:11:54 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:11:54 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:57 asyncio:1729 INFO poll took 2963.165 ms: 1 events 2019-09-13 19:11:57 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:11:57 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:57 asyncio:1729 DEBUG poll took 0.066 ms: 1 events 2019-09-13 19:11:57 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:11:57 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:00 asyncio:1729 INFO poll took 2975.658 ms: 1 events 2019-09-13 19:12:00 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:12:00 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:00 asyncio:1729 DEBUG poll took 94.895 ms: 1 events 2019-09-13 19:12:00 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:12:00 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:03 asyncio:1729 INFO poll took 2958.365 ms: 1 events 2019-09-13 19:12:03 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:12:03 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:22 asyncio:1729 INFO poll took 19032.168 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: upnp:rootdevice USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::upnp:rootdevice NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.068 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.064 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:InternetGatewayDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:InternetGatewayDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.065 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANConnectionDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANConnectionDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.059 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.057 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANIPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANIPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.057 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANPPPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANPPPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.062 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:Layer3Forwarding:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:Layer3Forwarding:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:36 asyncio:1729 INFO poll took 14016.214 ms: 1 events 2019-09-13 19:12:36 asyncio:159 DEBUG <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> got a new connection from ('192.168.2.111', 44680): <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340), raddr=('192.168.2.111', 44680)> 2019-09-13 19:12:36 fauxmo:41 DEBUG Connection made with: ('192.168.2.111', 44680) 2019-09-13 19:12:36 fauxmo:52 DEBUG Received message: POST /upnp/control/basicevent1 HTTP/1.1 SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState" Content-Type: text/xml; charset="utf-8" Accept: User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip Content-Length: 299
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
2019-09-13 19:12:47 asyncio:1729 INFO poll took 3067.420 ms: 1 events 2019-09-13 19:12:47 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:12:47 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:49 asyncio:1729 INFO poll took 1840.634 ms: 1 events 2019-09-13 19:12:49 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:12:49 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:50 asyncio:1729 INFO poll took 1122.451 ms: 1 events 2019-09-13 19:12:50 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:12:50 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:52 asyncio:1729 INFO poll took 1942.072 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:12:52 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.067 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: upnp:rootdevice USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::upnp:rootdevice NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.068 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.064 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:InternetGatewayDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:InternetGatewayDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.061 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANConnectionDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANConnectionDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANIPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANIPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.059 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANPPPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANPPPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.063 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:Layer3Forwarding:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:Layer3Forwarding:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:53 asyncio:1729 INFO poll took 1104.370 ms: 1 events 2019-09-13 19:12:53 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:12:53 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:55 asyncio:1729 INFO poll took 1839.729 ms: 1 events 2019-09-13 19:12:55 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:12:55 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:56 asyncio:1729 INFO poll took 1123.398 ms: 1 events 2019-09-13 19:12:56 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:12:56 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:56 asyncio:1729 DEBUG poll took 196.054 ms: 1 events 2019-09-13 19:12:56 asyncio:159 DEBUG <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> got a new connection from ('192.168.2.111', 49238): <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340), raddr=('192.168.2.111', 49238)> 2019-09-13 19:12:56 fauxmo:41 DEBUG Connection made with: ('192.168.2.111', 49238) 2019-09-13 19:12:56 fauxmo:52 DEBUG Received message: POST /upnp/control/basicevent1 HTTP/1.1 SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState" Content-Type: text/xml; charset="utf-8" Accept: User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip Content-Length: 299
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
2019-09-13 19:12:59 asyncio:1729 INFO poll took 1224.487 ms: 1 events 2019-09-13 19:12:59 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:12:59 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:13:01 asyncio:1729 INFO poll took 1839.030 ms: 1 events 2019-09-13 19:13:01 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:13:01 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
^C2019-09-13 19:13:03 asyncio:1729 INFO poll took 2430.484 ms: 1 events 2019-09-13 19:13:03 fauxmo:156 DEBUG Shutdown starting... 2019-09-13 19:13:03 fauxmo:159 DEBUG Shutting down server 0... 2019-09-13 19:13:03 asyncio:607 DEBUG Close <_UnixSelectorEventLoop running=False closed=False debug=True> pi@raspberrypi:~ $
With state parameters added in simplehttpplugin:
{ "FAUXMO": { "ip_address": "auto" }, "PLUGINS": { "SimpleHTTPPlugin": { "DEVICES": [ { "port": 12340, "on_cmd": "http://192.168.2.106/cgi-bin/light_on.cgi", "off_cmd": "http://192.168.2.106/cgi-bin/light_off.cgi", "state_cmd": "http://192.168.2.106/cgi-bin/light_state.cgi", "state_response_on": "OK", "state_response_off": "OFF", "method": "GET", "name": "my call light" } ] } } }
-vvv Discovery, on, off (when I asked Alexa to turn On my call light, the on cgi is executed, and Alexa says 'ok'; when I asked Alexa to turn OFF my call light, the off cgi is executed, but Alexa says my call light did not respond):
pi@raspberrypi:~ $ fauxmo -c fauxmo_config.json -vvv 2019-09-13 19:24:12 fauxmo:41 INFO Fauxmo v0.4.9 2019-09-13 19:24:12 fauxmo:42 DEBUG 3.7.3 (default, Apr 3 2019, 05:39:12) [GCC 8.2.0] 2019-09-13 19:24:12 fauxmo:25 DEBUG Attempting to get IP address automatically 2019-09-13 19:24:12 fauxmo:41 DEBUG Using IP address: 192.168.2.106 2019-09-13 19:24:12 fauxmo:111 DEBUG plugin_vars: {} 2019-09-13 19:24:12 fauxmo:114 DEBUG device config: {'port': 12340, 'on_cmd': 'http://192.168.2.106/cgi-bin/light_on.cgi', 'off_cmd': 'http://192.168.2.106/cgi-bin/light_off.cgi', 'state_cmd': 'http://192.168.2.106/cgi-bin/light_state.cgi', 'state_response_on': 'OK', 'state_response_off': 'OFF', 'method': 'GET', 'name': 'my call light'} 2019-09-13 19:24:12 asyncio:1403 INFO <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> is serving 2019-09-13 19:24:12 fauxmo:133 DEBUG Started fauxmo device: {'name': 'my call light', 'plugin': <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0xb5f72450>} 2019-09-13 19:24:12 fauxmo:135 INFO Starting UDP server 2019-09-13 19:24:12 asyncio:1259 DEBUG Datagram endpoint remote_addr=None created: (<_SelectorDatagramTransport fd=8 read=idle write=<idle, bufsize=0>>, <fauxmo.protocols.SSDPServer object at 0xb5f72150>) 2019-09-13 19:24:22 asyncio:1729 INFO poll took 9778.578 ms: 1 events 2019-09-13 19:24:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: upnp:rootdevice USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::upnp:rootdevice NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:22 asyncio:1729 DEBUG poll took 0.069 ms: 1 events 2019-09-13 19:24:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:22 asyncio:1729 DEBUG poll took 0.067 ms: 1 events 2019-09-13 19:24:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:InternetGatewayDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:InternetGatewayDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:22 asyncio:1729 DEBUG poll took 0.065 ms: 1 events 2019-09-13 19:24:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANConnectionDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANConnectionDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:22 asyncio:1729 DEBUG poll took 0.060 ms: 1 events 2019-09-13 19:24:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:22 asyncio:1729 DEBUG poll took 0.059 ms: 1 events 2019-09-13 19:24:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:22 asyncio:1729 DEBUG poll took 0.057 ms: 1 events 2019-09-13 19:24:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANIPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANIPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:22 asyncio:1729 DEBUG poll took 0.057 ms: 1 events 2019-09-13 19:24:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANPPPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANPPPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:22 asyncio:1729 DEBUG poll took 0.060 ms: 1 events 2019-09-13 19:24:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:Layer3Forwarding:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:Layer3Forwarding:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:23 asyncio:1729 DEBUG poll took 389.769 ms: 1 events 2019-09-13 19:24:23 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:24:23 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
2019-09-13 19:24:23 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:24:23 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 83c6285b-29b8-4bb0-b9b8-a6253a69cc6e\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: ssdp:all\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all\r\n\r\n' 2019-09-13 19:24:23 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:24:23 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
2019-09-13 19:24:23 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:24:23 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: b6c667a1-83f5-495a-a2fb-055fcfa3a87a\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: upnp:rootdevice\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice\r\n\r\n' 2019-09-13 19:24:23 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:24:23 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
2019-09-13 19:24:23 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:24:23 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 48fca8ed-1120-4f83-b244-8cd9d439f8b2\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: ssdp:all\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all\r\n\r\n' 2019-09-13 19:24:23 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:24:23 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
2019-09-13 19:24:23 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:24:23 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 5e83064c-8c3c-448f-9a90-575ceb899cdc\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: upnp:rootdevice\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice\r\n\r\n' 2019-09-13 19:24:23 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:24:23 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
2019-09-13 19:24:23 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:24:23 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 2a801ec4-96a5-4111-bd49-aa49e12d44bb\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: ssdp:all\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all\r\n\r\n' 2019-09-13 19:24:23 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:24:23 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
2019-09-13 19:24:23 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:24:23 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 3f27d946-f93a-4ce9-a7df-be296334da26\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: upnp:rootdevice\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice\r\n\r\n' 2019-09-13 19:24:25 asyncio:1737 INFO poll 1104.061 ms took 1106.197 ms: timeout 2019-09-13 19:24:28 asyncio:1729 INFO poll took 2524.020 ms: 1 events 2019-09-13 19:24:28 asyncio:159 DEBUG <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> got a new connection from ('192.168.2.111', 52872): <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340), raddr=('192.168.2.111', 52872)> 2019-09-13 19:24:28 fauxmo:41 DEBUG Connection made with: ('192.168.2.111', 52872) 2019-09-13 19:24:28 fauxmo:52 DEBUG Received message: GET /setup.xml HTTP/1.1 Content-Type: application/json User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip
2019-09-13 19:24:28 fauxmo:54 INFO setup.xml requested by Echo 2019-09-13 19:24:28 fauxmo:100 DEBUG Fauxmo response to setup request: HTTP/1.1 200 OK CONTENT-LENGTH: 953 CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 00:24:28 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"?>
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
2019-09-13 19:24:35 asyncio:1729 INFO poll took 2965.462 ms: 1 events 2019-09-13 19:24:35 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:24:35 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:24:38 asyncio:1729 INFO poll took 3067.727 ms: 1 events 2019-09-13 19:24:38 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:24:38 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:24:41 asyncio:1729 INFO poll took 2965.535 ms: 1 events 2019-09-13 19:24:41 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:24:41 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:24:44 asyncio:1729 INFO poll took 3067.633 ms: 1 events 2019-09-13 19:24:44 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:24:44 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:24:47 asyncio:1729 INFO poll took 2965.324 ms: 1 events 2019-09-13 19:24:47 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:24:47 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:24:52 asyncio:1729 INFO poll took 5421.830 ms: 1 events 2019-09-13 19:24:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: upnp:rootdevice USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::upnp:rootdevice NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:52 asyncio:1729 DEBUG poll took 0.071 ms: 1 events 2019-09-13 19:24:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:52 asyncio:1729 DEBUG poll took 0.062 ms: 1 events 2019-09-13 19:24:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:InternetGatewayDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:InternetGatewayDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:52 asyncio:1729 DEBUG poll took 0.065 ms: 1 events 2019-09-13 19:24:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANConnectionDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANConnectionDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:52 asyncio:1729 DEBUG poll took 0.057 ms: 1 events 2019-09-13 19:24:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:52 asyncio:1729 DEBUG poll took 0.059 ms: 1 events 2019-09-13 19:24:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:52 asyncio:1729 DEBUG poll took 0.059 ms: 1 events 2019-09-13 19:24:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANIPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANIPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:52 asyncio:1729 DEBUG poll took 0.061 ms: 1 events 2019-09-13 19:24:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANPPPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANPPPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:24:52 asyncio:1729 DEBUG poll took 0.067 ms: 1 events 2019-09-13 19:24:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:24:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:Layer3Forwarding:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:Layer3Forwarding:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:25:17 asyncio:1729 INFO poll took 24952.318 ms: 1 events 2019-09-13 19:25:17 asyncio:159 DEBUG <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> got a new connection from ('192.168.2.111', 53254): <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340), raddr=('192.168.2.111', 53254)> 2019-09-13 19:25:17 fauxmo:41 DEBUG Connection made with: ('192.168.2.111', 53254) 2019-09-13 19:25:17 fauxmo:52 DEBUG Received message: POST /upnp/control/basicevent1 HTTP/1.1 SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState" Content-Type: text/xml; charset="utf-8" Accept: User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip Content-Length: 299
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
2019-09-13 19:25:22 asyncio:1729 DEBUG poll took 0.106 ms: 1 events 2019-09-13 19:25:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:25:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:25:22 asyncio:1729 DEBUG poll took 0.109 ms: 1 events 2019-09-13 19:25:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:25:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:InternetGatewayDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:InternetGatewayDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:25:22 asyncio:1729 DEBUG poll took 0.062 ms: 1 events 2019-09-13 19:25:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:25:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANConnectionDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANConnectionDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:25:22 asyncio:1729 DEBUG poll took 0.061 ms: 1 events 2019-09-13 19:25:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:25:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:25:22 asyncio:1729 DEBUG poll took 0.062 ms: 1 events 2019-09-13 19:25:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:25:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:25:22 asyncio:1729 DEBUG poll took 0.240 ms: 1 events 2019-09-13 19:25:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:25:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANIPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANIPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:25:22 asyncio:1729 DEBUG poll took 0.171 ms: 1 events 2019-09-13 19:25:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:25:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANPPPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANPPPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:25:22 asyncio:1729 DEBUG poll took 0.239 ms: 1 events 2019-09-13 19:25:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:25:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:Layer3Forwarding:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:Layer3Forwarding:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:25:32 asyncio:1729 INFO poll took 10000.498 ms: 1 events 2019-09-13 19:25:32 asyncio:159 DEBUG <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> got a new connection from ('192.168.2.111', 42390): <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340), raddr=('192.168.2.111', 42390)> 2019-09-13 19:25:32 fauxmo:41 DEBUG Connection made with: ('192.168.2.111', 42390) 2019-09-13 19:25:32 fauxmo:52 DEBUG Received message: POST /upnp/control/basicevent1 HTTP/1.1 SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState" Content-Type: text/xml; charset="utf-8" Accept: User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip Content-Length: 299
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
Another interesting data point... when I am making on/off requests and Alexa says it's not responding, that's all she says. When fauxmo is shut down, she says, it's not responding, and adds that I should check the network connection and power supply. In the case that fauxmo was running, Alexa was probably able to establish a connection, but just didn't receive a reply, from which it deduced that the device was listening, but not responding.
tcpdump of the config (without state parameters):
pi@raspberrypi:~ $ sudo tcpdump -s 0 -i wlan0 -A host 192.168.2.111 tcpdump: verbose output suppressed, use -v or -vv for full protocol decode listening on wlan0, link-type EN10MB (Ethernet), capture size 262144 bytes 20:04:30.310201 IP 192.168.2.111.50000 > 239.255.255.250.1900: UDP, length 94 E..z..@........o.....P.l.f.dM-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
20:04:30.310543 IP 192.168.2.111.50000 > 239.255.255.250.1900: UDP, length 101 E.....@........o.....P.l.m$.M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
20:04:30.310940 IP 192.168.2.111.50000 > 239.255.255.250.1900: UDP, length 94 E..z..@........o.....P.l.f.dM-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
20:04:30.311332 IP 192.168.2.111.50000 > 239.255.255.250.1900: UDP, length 101 E.....@........o.....P.l.m$.M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
20:04:30.311857 IP 192.168.2.111.50000 > 239.255.255.250.1900: UDP, length 94 E..z..@........o.....P.l.f.dM-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
20:04:30.312144 IP 192.168.2.111.50000 > 239.255.255.250.1900: UDP, length 101 E.....@........o.....P.l.m$.M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
20:04:30.412336 ARP, Request who-has 192.168.2.111 tell 192.168.2.170, length 28 ........L..U.n.............o 20:04:30.688678 IP 192.168.2.106.1900 > 192.168.2.111.50000: UDP, length 371 E... J@.@......j...o.l.P.{b.HTTP/1.1 200 OK CACHE-CONTROL: max-age=86400 DATE: Sat, 14 Sep 2019 01:04:30 GMT EXT: LOCATION: http://192.168.2.106:12340/setup.xml OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1d5ab456-3b88-4fa2-8b34-14cc07028fb0 SERVER: Fauxmo, UPnP/1.0, Unspecified ST: upnp:rootdevice USN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice
20:04:31.558873 IP 192.168.2.106.1900 > 192.168.2.111.50000: UDP, length 357 E... N@.@......j...o.l.P.m..HTTP/1.1 200 OK CACHE-CONTROL: max-age=86400 DATE: Sat, 14 Sep 2019 01:04:30 GMT EXT: LOCATION: http://192.168.2.106:12340/setup.xml OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: a2321bb6-f58b-46cf-a7bd-a75a7878c4d0 SERVER: Fauxmo, UPnP/1.0, Unspecified ST: ssdp:all USN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all
20:04:31.736351 IP 192.168.2.106.1900 > 192.168.2.111.50000: UDP, length 371 E... \@.@......j...o.l.P.{*.HTTP/1.1 200 OK CACHE-CONTROL: max-age=86400 DATE: Sat, 14 Sep 2019 01:04:30 GMT EXT: LOCATION: http://192.168.2.106:12340/setup.xml OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 63777317-f9d0-47b2-a64d-f95d13afdf43 SERVER: Fauxmo, UPnP/1.0, Unspecified ST: upnp:rootdevice USN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice
20:04:32.203129 IP 192.168.2.106.1900 > 192.168.2.111.50000: UDP, length 357 E... e@.@......j...o.l.P.m|`HTTP/1.1 200 OK CACHE-CONTROL: max-age=86400 DATE: Sat, 14 Sep 2019 01:04:30 GMT EXT: LOCATION: http://192.168.2.106:12340/setup.xml OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 58f0380d-ed0e-441b-9785-22681186a33c SERVER: Fauxmo, UPnP/1.0, Unspecified ST: ssdp:all USN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all
20:04:32.373601 IP 192.168.2.106.1900 > 192.168.2.111.50000: UDP, length 357 E... f@.@......j...o.l.P.m.[HTTP/1.1 200 OK CACHE-CONTROL: max-age=86400 DATE: Sat, 14 Sep 2019 01:04:30 GMT EXT: LOCATION: http://192.168.2.106:12340/setup.xml OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: ff403421-8629-47b2-a614-17220cc6f98c SERVER: Fauxmo, UPnP/1.0, Unspecified ST: ssdp:all USN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all
20:04:32.512038 IP 192.168.2.106.1900 > 192.168.2.111.50000: UDP, length 371 E... n@.@......j...o.l.P.{{ HTTP/1.1 200 OK CACHE-CONTROL: max-age=86400 DATE: Sat, 14 Sep 2019 01:04:30 GMT EXT: LOCATION: http://192.168.2.106:12340/setup.xml OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 644eae6b-343d-4dad-a8d3-079b0cb36a58 SERVER: Fauxmo, UPnP/1.0, Unspecified ST: upnp:rootdevice USN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice
20:04:35.489692 IP 192.168.2.111.50664 > 192.168.2.106.12340: Flags [S], seq 3553544586, win 65535, options [mss 1460,sackOK,TS val 561277 ecr 0,nop,wscale 6], length 0 E..<Y.@.@.Z....o...j..04....................... ...}........ 20:04:35.489799 IP 192.168.2.106.12340 > 192.168.2.111.50664: Flags [S.], seq 2831949940, ack 3553544587, win 28960, options [mss 1460,sackOK,TS val 1878271703 ecr 561277,nop,wscale 7], length 0 E..<..@.@......j...o04.... t......q ........... o.&....}.... 20:04:35.494231 IP 192.168.2.111.50664 > 192.168.2.106.12340: Flags [.], ack 1, win 1369, options [nop,nop,TS val 561277 ecr 1878271703], length 0 E..4Y.@.@.Z....o...j..04...... u...Yg0..... ...}o.&. 20:04:35.500702 IP 192.168.2.111.50664 > 192.168.2.106.12340: Flags [P.], seq 1:206, ack 1, win 1369, options [nop,nop,TS val 561278 ecr 1878271703], length 205 E...Y.@.@.Y....o...j..04...... u...Y....... ...~o.&.GET /setup.xml HTTP/1.1 Content-Type: application/json User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip
20:04:35.500763 IP 192.168.2.106.12340 > 192.168.2.111.50664: Flags [.], ack 206, win 235, options [nop,nop,TS val 1878271714 ecr 561278], length 0 E..4Y.@.@.Z....j...o04.... u...X....j...... o.&....~ 20:04:35.504105 IP 192.168.2.106.12340 > 192.168.2.111.50664: Flags [P.], seq 1:1186, ack 206, win 235, options [nop,nop,TS val 1878271718 ecr 561278], length 1185 E...Y.@.@.V....j...o04.... u...X........... o.&....~HTTP/1.1 200 OK CONTENT-LENGTH: 953 CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 01:04:35 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"?>
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
o./. 20:04:37.762257 IP 192.168.2.111.53759 > 192.168.2.106.12340: Flags [F.], seq 623, ack 511, win 1386, options [nop,nop,TS val 561504 ecr 1878273970], length 0 E..4.z@.@.. ...o...j..04x...8.H"...j....... ...
o./.
20:04:37.762306 IP 192.168.2.106.12340 > 192.168.2.111.53759: Flags [.], ack 624, win 236, options [nop,nop,TS val 1878273976 ecr 561504], length 0
E..4<D@.@.xV...j...o04..8.H"x..............
o./....`
"Alexa, turn on my call light"
20:06:18.311519 IP 192.168.2.111.37717 > 192.168.2.106.12340: Flags [S], seq 1941450206, win 65535, options [mss 1460,sackOK,TS val 571559 ecr 0,nop,wscale 6], length 0 E..<.y@.@......o...j.U04s.-.................... ............ 20:06:18.311599 IP 192.168.2.106.12340 > 192.168.2.111.37717: Flags [S.], seq 2436648682, ack 1941450207, win 28960, options [mss 1460,sackOK,TS val 1878374527 ecr 571559,nop,wscale 7], length 0 E..<..@.@......j...o04.U.<N.s.-...q *9......... o........... 20:06:18.313792 IP 192.168.2.111.37717 > 192.168.2.106.12340: Flags [.], ack 1, win 1369, options [nop,nop,TS val 571559 ecr 1878374527], length 0 E..4.z@.@.. ...o...j.U04s.-..<N....Y....... ....o... 20:06:18.315198 IP 192.168.2.111.37717 > 192.168.2.106.12340: Flags [P.], seq 1:623, ack 1, win 1369, options [nop,nop,TS val 571559 ecr 1878374527], length 622 E....{@.@......o...j.U04s.-..<N....Y2(..... ....o...POST /upnp/control/basicevent1 HTTP/1.1 SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState" Content-Type: text/xml; charset="utf-8" Accept: User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip Content-Length: 299
<?xml version="1.0" encoding="utf-8"?>
..q ........... o........... 20:06:18.365844 IP 192.168.2.111.44176 > 192.168.2.106.12340: Flags [.], ack 1, win 1369, options [nop,nop,TS val 571565 ecr 1878374578], length 0 E..4Y.@.@.Z....o...j..04^..
%.F....Y.9.....
....o...
20:06:18.366200 IP 192.168.2.111.44176 > 192.168.2.106.12340: Flags [P.], seq 1:623, ack 1, win 1369, options [nop,nop,TS val 571565 ecr 1878374578], length 622
E...Y.@.@.X6...o...j..04^..`%.F....Y.......
....o...POST /upnp/control/basicevent1 HTTP/1.1
SOAPACTION: "urn:Belkin:service:basicevent:1#GetBinaryState"
Content-Type: text/xml; charset="utf-8"
Accept:
User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F)
Host: 192.168.2.106:12340
Connection: Keep-Alive
Accept-Encoding: gzip
Content-Length: 299
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
"Alexa, turn off my call light"
20:06:37.799501 IP 192.168.2.111.48301 > 192.168.2.106.12340: Flags [S], seq 1657689045, win 65535, options [mss 1460,sackOK,TS val 573507 ecr 0,nop,wscale 6], length 0 E..<..@.@. ....o...j..04b.S.........^.......... ...C........ 20:06:37.799584 IP 192.168.2.106.12340 > 192.168.2.111.48301: Flags [S.], seq 2934626132, ack 1657689046, win 28960, options [mss 1460,sackOK,TS val 1878394015 ecr 573507,nop,wscale 7], length 0 E..<..@.@......j...o04.....Tb.S...q ........... o......C.... 20:06:37.803372 IP 192.168.2.111.48301 > 192.168.2.106.12340: Flags [.], ack 1, win 1369, options [nop,nop,TS val 573508 ecr 1878394015], length 0 E..4..@.@.!....o...j..04b.S....U...Y....... ...Do... 20:06:37.804319 IP 192.168.2.111.48301 > 192.168.2.106.12340: Flags [P.], seq 1:623, ack 1, win 1369, options [nop,nop,TS val 573508 ecr 1878394015], length 622 E.....@.@......o...j..04b.S....U...Y....... ...Do...POST /upnp/control/basicevent1 HTTP/1.1 SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState" Content-Type: text/xml; charset="utf-8" Accept: User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip Content-Length: 299
<?xml version="1.0" encoding="utf-8"?>
<?xml version="1.0" encoding="utf-8"?>
^C 117 packets captured 117 packets received by filter 0 packets dropped by kernel
Unfortunately, this is not quite what I am seeing.
On mobile, I'll look through this more soon, but you still seem to be totally misunderstanding. What you posted (in the response that contains this quote at least) is entirely in keeping with what I keep saying. Please reread.
You <--> Echo <--> Fauxmo <--> CGI script
When you don't have state_cmd configured, Echo is asking Fauxmo for state, Fauxmo doesn't know, so Echo complains. Fauxmo does not ask the CGI script (because no state_cmd configured), so you only see the on and off requests in your CGI script logs.
Understood that Fauxmo is the go-between, fronting requests and responses to Alexa/Echo, and then turning around and triggering requests through lighttpd...
When you don't have state_cmd configured, Echo is asking Fauxmo for state, Fauxmo doesn't know, so Echo complains.
I agree Fauxmo doesn't know the state, but the tcpdump shows that it assumes the state (based on the command given), and responds with a presumed state, which is understandable. I presume this is what will satisfy Alexa/Echo so that it gives an 'ok'.
I looked through the tcpdump, and compared the state response for the on and off commands. They look identical, except for the value of the state (understandably). And yet, after the on request (which yields a '...not responding' from Alexa), I see three requests for state, coming from Alexa/Echo, suggesting it is not receiving/happy with/believing Fauxmo's pseudo-state reply.
Are the other TCP packets before and after the ON/OFF requests/replies, significant?
First line from ON Fauxmo reply, second line from OFF Fauxmo reply:
HTTP/1.1 200 OK HTTP/1.1 200 OK CONTENT-LENGTH: 277 CONTENT-LENGTH: 277 CONTENT-TYPE: text/xml CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 01:06:18 GMT DATE: Sat, 14 Sep 2019 01:06:37 GMT LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT SERVER: Unspecified, UPnP/1.0, Unspecified SERVER: Unspecified, UPnP/1.0, Unspecified X-User-Agent: Fauxmo X-User-Agent: Fauxmo CONNECTION: close CONNECTION: close
Thank you, this is very helpful. In the future, please consider using codeblocks, which makes it much easier to read).
pi@raspberrypi:~ $ curl http://192.168.2.106/cgi-bin/light_state.cgi
OK
pi@raspberrypi:~ $ curl http://192.168.2.106/cgi-bin/light_on.cgi
OK
pi@raspberrypi:~ $ curl http://192.168.2.106/cgi-bin/light_state.cgi
OK
pi@raspberrypi:~ $ curl http://192.168.2.106/cgi-bin/light_off.cgi
OK
pi@raspberrypi:~ $ curl http://192.168.2.106/cgi-bin/light_state.cgi
OK
So based on this, I don't think your light_state.cgi
endpoint is working -- it looks the same after an on
call as compared to an off
call. Is that right?
First line from ON Fauxmo reply, second line from OFF Fauxmo reply:
You may be onto something here. It looks like I probably added this logic in 2215a9bc1b497d76d94d52402dd76d2e2752a5f8, and I don't seem to have documented my reasoning.
The way it's written, an Echo request to Fauxmo to SetBinaryState
to 0
(off) returns a SetBinaryStateResponse
of 0
, and likewise Echo request to SetBinaryState
to 1
(on) returns SetBinaryStateResponse
of 1
.
However, it could easily be that 0
and 1
in the response are success and failure codes, not on
or off
states.
Will look into this.
In my case, light_state.cgi isn't intended to return state - it's only to give a 200 response, so that Fauxmo will give a thumbs up to Alexa/Echo, so that the user is given an audible 'OK'. Though part of the problem is that I don't think a state request should be forwarded by Fauxmo, because I'm using simplehttpplugin not RESTAPIplugin, but that's a separate topic for a separate thread ;)
I think part of the problem, is that we're chasing too many squirrels. I wish to drop the "state" parameters issue - it's giving clues to the original problem, but I suspect if the original problem is fixed, everything else will fall into place.
The original problem is (which was also reported in Issue number 61), is that with the following config.json, requests to Alexa to turn the device 'on', result in Alexa saying the device is not responding, and requests to turn the device 'off', work fine (Alexa responds with 'ok').
In both cases (requesting on and requesting off), the proper .cgi file is called, and the device operates as expected. The issue appears to be how Echo is configured originally by Fauxmo, or it is due to whatever is being returned to Echo from Fauxmo. In the post above, the tcp replies from Fauxmo looks good for both on and off requests, so my suspicion is that it is an issue with initial configuration messages between Echo and Fauxmo.
{
"FAUXMO": {
"ip_address": "auto"
},
"PLUGINS": {
"SimpleHTTPPlugin": {
"DEVICES": [
{
"port": 12340,
"on_cmd": "http://192.168.2.106/cgi-bin/light_on.cgi",
"off_cmd": "http://192.168.2.106/cgi-bin/light_off.cgi",
"method": "GET",
"name": "my call light"
}
]
}
}
}
Here is the original discovery process, based on the simplehttpplugin without any "state" parameters in config.json, plus an ON request followed by an OFF request:
(when I asked Alexa to turn On my call light, the light_on.cgi is properly executed, but Alexa says the device didn't respond. When I asked Alexa to turn OFF my call light, the light_off.cgi is executed, and Alexa says 'ok'):
pi@raspberrypi:~ $ fauxmo -c fauxmo_config.json -vvv 2019-09-13 19:11:18 fauxmo:41 INFO Fauxmo v0.4.9 2019-09-13 19:11:18 fauxmo:42 DEBUG 3.7.3 (default, Apr 3 2019, 05:39:12) [GCC 8.2.0] 2019-09-13 19:11:18 fauxmo:25 DEBUG Attempting to get IP address automatically 2019-09-13 19:11:18 fauxmo:41 DEBUG Using IP address: 192.168.2.106 2019-09-13 19:11:18 fauxmo:111 DEBUG plugin_vars: {} 2019-09-13 19:11:18 fauxmo:114 DEBUG device config: {'port': 12340, 'on_cmd': 'http://192.168.2.106/cgi-bin/light_on.cgi', 'off_cmd': 'http://192.168.2.106/cgi-bin/light_off.cgi', 'method': 'GET', 'name': 'my call light'} 2019-09-13 19:11:18 asyncio:1403 INFO <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> is serving 2019-09-13 19:11:18 fauxmo:133 DEBUG Started fauxmo device: {'name': 'my call light', 'plugin': <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0xb60453f0>} 2019-09-13 19:11:18 fauxmo:135 INFO Starting UDP server 2019-09-13 19:11:18 asyncio:1259 DEBUG Datagram endpoint remote_addr=None created: (<_SelectorDatagramTransport fd=8 read=idle write=<idle, bufsize=0>>, <fauxmo.protocols.SSDPServer object at 0xb6045150>) 2019-09-13 19:11:22 asyncio:1729 INFO poll took 3481.009 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: upnp:rootdevice USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::upnp:rootdevice NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.069 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.066 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:InternetGatewayDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:InternetGatewayDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.062 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANConnectionDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANConnectionDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.057 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANIPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANIPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.062 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANPPPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANPPPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:22 asyncio:1729 DEBUG poll took 0.066 ms: 1 events 2019-09-13 19:11:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:Layer3Forwarding:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:Layer3Forwarding:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:35 asyncio:1729 INFO poll took 12976.544 ms: 1 events 2019-09-13 19:11:35 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:11:35 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
2019-09-13 19:11:35 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:11:35 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 6c9fa6bc-c224-4027-a84c-117f5578e135\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: ssdp:all\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all\r\n\r\n' 2019-09-13 19:11:35 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:11:35 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
2019-09-13 19:11:35 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:11:35 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 0e29e2cf-cdc0-4256-b905-ee4d3453202a\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: upnp:rootdevice\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice\r\n\r\n' 2019-09-13 19:11:35 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:11:35 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
2019-09-13 19:11:35 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:11:35 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 0ae99f2d-0ea6-4403-b6a0-ca16f8c805ba\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: ssdp:all\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all\r\n\r\n' 2019-09-13 19:11:35 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:11:35 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
2019-09-13 19:11:35 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:11:35 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 316ba336-2554-4503-90d3-026e47574140\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: upnp:rootdevice\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice\r\n\r\n' 2019-09-13 19:11:35 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:11:35 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: ssdp:all
2019-09-13 19:11:35 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:11:35 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 69beda6e-6c50-4710-bb1b-390680a3b2f7\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: ssdp:all\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::ssdp:all\r\n\r\n' 2019-09-13 19:11:35 fauxmo:343 DEBUG Received data below from ('192.168.2.111', 50000): 2019-09-13 19:11:35 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host: 239.255.255.250:1900 Man: "ssdp:discover" MX: 3 ST: upnp:rootdevice
2019-09-13 19:11:35 fauxmo:418 DEBUG Sending response to ('192.168.2.111', 50000) with mx 3.0: b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=86400\r\nDATE: Sat, 14 Sep 2019 00:11:35 GMT\r\nEXT:\r\nLOCATION: http://192.168.2.106:12340/setup.xml\r\nOPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01\r\n01-NLS: 3ade1c62-a3f9-46e6-8f3c-5ee9be4a1d68\r\nSERVER: Fauxmo, UPnP/1.0, Unspecified\r\nST: upnp:rootdevice\r\nUSN: uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167e::upnp:rootdevice\r\n\r\n' 2019-09-13 19:11:37 asyncio:1737 INFO poll 1451.397 ms took 1453.519 ms: timeout 2019-09-13 19:11:40 asyncio:1729 INFO poll took 2672.930 ms: 1 events 2019-09-13 19:11:40 asyncio:159 DEBUG <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> got a new connection from ('192.168.2.111', 50892): <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340), raddr=('192.168.2.111', 50892)> 2019-09-13 19:11:40 fauxmo:41 DEBUG Connection made with: ('192.168.2.111', 50892) 2019-09-13 19:11:40 fauxmo:52 DEBUG Received message: GET /setup.xml HTTP/1.1 Content-Type: application/json User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip
2019-09-13 19:11:40 fauxmo:54 INFO setup.xml requested by Echo 2019-09-13 19:11:40 fauxmo:100 DEBUG Fauxmo response to setup request: HTTP/1.1 200 OK CONTENT-LENGTH: 953 CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 00:11:40 GMT LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT SERVER: Unspecified, UPnP/1.0, Unspecified X-User-Agent: Fauxmo CONNECTION: close 10urn:Belkin:device:controllee:1my call lightBelkin International Inc.Emulated Socket3.1415uuid:Socket-1_0-2f6c3c0c-31d2-3d31-9d62-cb3e34d0167eurn:Belkin:service:basicevent:1urn:Belkin:serviceId:basicevent1/upnp/control/basicevent1/upnp/event/basicevent1/eventservice.xmlurn:Belkin:service:metainfo:1urn:Belkin:serviceId:metainfo1/upnp/control/metainfo1/upnp/event/metainfo1/metainfoservice.xml
2019-09-13 19:11:40 asyncio:1729 DEBUG poll took 94.486 ms: 1 events 2019-09-13 19:11:40 asyncio:159 DEBUG <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> got a new connection from ('192.168.2.111', 38285): <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340), raddr=('192.168.2.111', 38285)> 2019-09-13 19:11:40 fauxmo:41 DEBUG Connection made with: ('192.168.2.111', 38285) 2019-09-13 19:11:40 fauxmo:52 DEBUG Received message: POST /upnp/control/basicevent1 HTTP/1.1 SOAPACTION: "urn:Belkin:service:basicevent:1#GetBinaryState" Content-Type: text/xml; charset="utf-8" Accept: User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip Content-Length: 299 1
2019-09-13 19:11:40 fauxmo:63 INFO request BasicEvent1 2019-09-13 19:11:40 fauxmo:111 DEBUG Handling action for plugin type <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0xb60453f0> 2019-09-13 19:11:40 fauxmo:137 INFO Attempting to get state for my call light 2019-09-13 19:11:40 fauxmo:150 INFO my call light state: unknown 2019-09-13 19:11:40 fauxmo:185 DEBUG HTTP/1.1 200 OK CONTENT-LENGTH: 277 CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 00:11:40 GMT LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT SERVER: Unspecified, UPnP/1.0, Unspecified X-User-Agent: Fauxmo CONNECTION: close
2019-09-13 19:11:40 fauxmo:63 INFO request BasicEvent1 2019-09-13 19:11:40 fauxmo:111 DEBUG Handling action for plugin type <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0xb60453f0> 2019-09-13 19:11:40 fauxmo:137 INFO Attempting to get state for my call light 2019-09-13 19:11:40 fauxmo:150 INFO my call light state: unknown 2019-09-13 19:11:40 fauxmo:185 DEBUG HTTP/1.1 200 OK CONTENT-LENGTH: 277 CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 00:11:40 GMT LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT SERVER: Unspecified, UPnP/1.0, Unspecified X-User-Agent: Fauxmo CONNECTION: close
2019-09-13 19:11:42 fauxmo:63 INFO request BasicEvent1 2019-09-13 19:11:42 fauxmo:111 DEBUG Handling action for plugin type <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0xb60453f0> 2019-09-13 19:11:42 fauxmo:137 INFO Attempting to get state for my call light 2019-09-13 19:11:42 fauxmo:150 INFO my call light state: unknown 2019-09-13 19:11:42 fauxmo:185 DEBUG HTTP/1.1 200 OK CONTENT-LENGTH: 277 CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 00:11:42 GMT LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT SERVER: Unspecified, UPnP/1.0, Unspecified X-User-Agent: Fauxmo CONNECTION: close
2019-09-13 19:11:48 asyncio:1729 INFO poll took 3055.479 ms: 1 events 2019-09-13 19:11:48 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:11:48 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:48 asyncio:1729 DEBUG poll took 0.071 ms: 1 events 2019-09-13 19:11:48 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:11:48 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:51 asyncio:1729 INFO poll took 2965.846 ms: 1 events 2019-09-13 19:11:51 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:11:51 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:51 asyncio:1729 DEBUG poll took 93.879 ms: 1 events 2019-09-13 19:11:51 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:11:51 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:52 asyncio:1729 INFO poll took 1020.773 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: upnp:rootdevice USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::upnp:rootdevice NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.066 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.067 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:InternetGatewayDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:InternetGatewayDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.065 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANConnectionDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANConnectionDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.060 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.063 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANIPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANIPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.065 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANPPPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANPPPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:52 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:11:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:11:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:Layer3Forwarding:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:Layer3Forwarding:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:11:54 asyncio:1729 INFO poll took 1924.235 ms: 1 events 2019-09-13 19:11:54 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:11:54 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:54 asyncio:1729 DEBUG poll took 0.065 ms: 1 events 2019-09-13 19:11:54 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:11:54 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:57 asyncio:1729 INFO poll took 2963.165 ms: 1 events 2019-09-13 19:11:57 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:11:57 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:11:57 asyncio:1729 DEBUG poll took 0.066 ms: 1 events 2019-09-13 19:11:57 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:11:57 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:00 asyncio:1729 INFO poll took 2975.658 ms: 1 events 2019-09-13 19:12:00 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:12:00 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:00 asyncio:1729 DEBUG poll took 94.895 ms: 1 events 2019-09-13 19:12:00 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:12:00 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:03 asyncio:1729 INFO poll took 2958.365 ms: 1 events 2019-09-13 19:12:03 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:12:03 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:22 asyncio:1729 INFO poll took 19032.168 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: upnp:rootdevice USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::upnp:rootdevice NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.068 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.064 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:InternetGatewayDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:InternetGatewayDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.065 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANConnectionDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANConnectionDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.059 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.057 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANIPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANIPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.057 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANPPPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANPPPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:22 asyncio:1729 DEBUG poll took 0.062 ms: 1 events 2019-09-13 19:12:22 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:22 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:Layer3Forwarding:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:Layer3Forwarding:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:36 asyncio:1729 INFO poll took 14016.214 ms: 1 events 2019-09-13 19:12:36 asyncio:159 DEBUG <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> got a new connection from ('192.168.2.111', 44680): <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340), raddr=('192.168.2.111', 44680)> 2019-09-13 19:12:36 fauxmo:41 DEBUG Connection made with: ('192.168.2.111', 44680) 2019-09-13 19:12:36 fauxmo:52 DEBUG Received message: POST /upnp/control/basicevent1 HTTP/1.1 SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState" Content-Type: text/xml; charset="utf-8" Accept: User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip Content-Length: 299 1
2019-09-13 19:12:36 fauxmo:63 INFO request BasicEvent1 2019-09-13 19:12:36 fauxmo:111 DEBUG Handling action for plugin type <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0xb60453f0> 2019-09-13 19:12:36 fauxmo:165 INFO Attempting to turn on my call light 2019-09-13 19:12:36 fauxmo:185 DEBUG HTTP/1.1 200 OK CONTENT-LENGTH: 277 CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 00:12:36 GMT LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT SERVER: Unspecified, UPnP/1.0, Unspecified X-User-Agent: Fauxmo CONNECTION: close
2019-09-13 19:12:36 fauxmo:63 INFO request BasicEvent1 2019-09-13 19:12:36 fauxmo:111 DEBUG Handling action for plugin type <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0xb60453f0> 2019-09-13 19:12:36 fauxmo:137 INFO Attempting to get state for my call light 2019-09-13 19:12:36 fauxmo:150 INFO my call light state: unknown 2019-09-13 19:12:36 fauxmo:185 DEBUG HTTP/1.1 200 OK CONTENT-LENGTH: 277 CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 00:12:36 GMT LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT SERVER: Unspecified, UPnP/1.0, Unspecified X-User-Agent: Fauxmo CONNECTION: close
2019-09-13 19:12:37 fauxmo:63 INFO request BasicEvent1 2019-09-13 19:12:37 fauxmo:111 DEBUG Handling action for plugin type <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0xb60453f0> 2019-09-13 19:12:37 fauxmo:137 INFO Attempting to get state for my call light 2019-09-13 19:12:37 fauxmo:150 INFO my call light state: unknown 2019-09-13 19:12:37 fauxmo:185 DEBUG HTTP/1.1 200 OK CONTENT-LENGTH: 277 CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 00:12:37 GMT LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT SERVER: Unspecified, UPnP/1.0, Unspecified X-User-Agent: Fauxmo CONNECTION: close
2019-09-13 19:12:38 fauxmo:63 INFO request BasicEvent1 2019-09-13 19:12:38 fauxmo:111 DEBUG Handling action for plugin type <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0xb60453f0> 2019-09-13 19:12:38 fauxmo:137 INFO Attempting to get state for my call light 2019-09-13 19:12:38 fauxmo:150 INFO my call light state: unknown 2019-09-13 19:12:38 fauxmo:185 DEBUG HTTP/1.1 200 OK CONTENT-LENGTH: 277 CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 00:12:38 GMT LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT SERVER: Unspecified, UPnP/1.0, Unspecified X-User-Agent: Fauxmo CONNECTION: close
2019-09-13 19:12:47 asyncio:1729 INFO poll took 3067.420 ms: 1 events 2019-09-13 19:12:47 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:12:47 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:49 asyncio:1729 INFO poll took 1840.634 ms: 1 events 2019-09-13 19:12:49 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:12:49 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:50 asyncio:1729 INFO poll took 1122.451 ms: 1 events 2019-09-13 19:12:50 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:12:50 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:52 asyncio:1729 INFO poll took 1942.072 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:12:52 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.067 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: upnp:rootdevice USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::upnp:rootdevice NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.068 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.064 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:InternetGatewayDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:InternetGatewayDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.061 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANConnectionDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANConnectionDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:device:WANDevice:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:device:WANDevice:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.058 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANIPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANIPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.059 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:WANPPPConnection:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:WANPPPConnection:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:52 asyncio:1729 DEBUG poll took 0.063 ms: 1 events 2019-09-13 19:12:52 fauxmo:343 DEBUG Received data below from ('192.168.2.1', 40756): 2019-09-13 19:12:52 fauxmo:344 DEBUG NOTIFY * HTTP/1.1 HOST: 239.255.255.250:1900 CACHE-CONTROL: max-age=60 LOCATION: http://192.168.2.1:1900/rootDesc.xml SERVER: TP-Link/TP-LINK UPnP/1.1 MiniUPnPd/1.8 NT: urn:schemas-upnp-org:service:Layer3Forwarding:1 USN: uuid:e4c797e0-82ce-4f84-b56d-085d9d77c8cd::urn:schemas-upnp-org:service:Layer3Forwarding:1 NTS: ssdp:alive OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01 01-NLS: 1 BOOTID.UPNP.ORG: 1 CONFIGID.UPNP.ORG: 1337
2019-09-13 19:12:53 asyncio:1729 INFO poll took 1104.370 ms: 1 events 2019-09-13 19:12:53 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:12:53 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:55 asyncio:1729 INFO poll took 1839.729 ms: 1 events 2019-09-13 19:12:55 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:12:55 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:56 asyncio:1729 INFO poll took 1123.398 ms: 1 events 2019-09-13 19:12:56 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:12:56 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:12:56 asyncio:1729 DEBUG poll took 196.054 ms: 1 events 2019-09-13 19:12:56 asyncio:159 DEBUG <Server sockets=[<socket.socket fd=7, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340)>]> got a new connection from ('192.168.2.111', 49238): <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.2.106', 12340), raddr=('192.168.2.111', 49238)> 2019-09-13 19:12:56 fauxmo:41 DEBUG Connection made with: ('192.168.2.111', 49238) 2019-09-13 19:12:56 fauxmo:52 DEBUG Received message: POST /upnp/control/basicevent1 HTTP/1.1 SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState" Content-Type: text/xml; charset="utf-8" Accept: User-Agent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; AEOBC Build/LVY48F) Host: 192.168.2.106:12340 Connection: Keep-Alive Accept-Encoding: gzip Content-Length: 299 0
2019-09-13 19:12:56 fauxmo:63 INFO request BasicEvent1 2019-09-13 19:12:56 fauxmo:111 DEBUG Handling action for plugin type <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0xb60453f0> 2019-09-13 19:12:56 fauxmo:160 INFO Attempting to turn off my call light 2019-09-13 19:12:56 fauxmo:185 DEBUG HTTP/1.1 200 OK CONTENT-LENGTH: 277 CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 00:12:56 GMT LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT SERVER: Unspecified, UPnP/1.0, Unspecified X-User-Agent: Fauxmo CONNECTION: close
2019-09-13 19:12:56 fauxmo:63 INFO request BasicEvent1 2019-09-13 19:12:56 fauxmo:111 DEBUG Handling action for plugin type <fauxmo.plugins.simplehttpplugin.SimpleHTTPPlugin object at 0xb60453f0> 2019-09-13 19:12:56 fauxmo:137 INFO Attempting to get state for my call light 2019-09-13 19:12:56 fauxmo:150 INFO my call light state: unknown 2019-09-13 19:12:56 fauxmo:185 DEBUG HTTP/1.1 200 OK CONTENT-LENGTH: 277 CONTENT-TYPE: text/xml DATE: Sat, 14 Sep 2019 00:12:56 GMT LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT SERVER: Unspecified, UPnP/1.0, Unspecified X-User-Agent: Fauxmo CONNECTION: close
2019-09-13 19:12:59 asyncio:1729 INFO poll took 1224.487 ms: 1 events 2019-09-13 19:12:59 fauxmo:343 DEBUG Received data below from ('192.168.2.156', 55988): 2019-09-13 19:12:59 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
2019-09-13 19:13:01 asyncio:1729 INFO poll took 1839.030 ms: 1 events 2019-09-13 19:13:01 fauxmo:343 DEBUG Received data below from ('192.168.2.5', 63181): 2019-09-13 19:13:01 fauxmo:344 DEBUG M-SEARCH * HTTP/1.1 Host:239.255.255.250:1900 ST:urn:schemas-upnp-org:device:InternetGatewayDevice:1 Man:"ssdp:discover" MX:3
^C2019-09-13 19:13:03 asyncio:1729 INFO poll took 2430.484 ms: 1 events 2019-09-13 19:13:03 fauxmo:156 DEBUG Shutdown starting... 2019-09-13 19:13:03 fauxmo:159 DEBUG Shutting down server 0... 2019-09-13 19:13:03 asyncio:607 DEBUG Close <_UnixSelectorEventLoop running=False closed=False debug=True> pi@raspberrypi:~ $
In my case, light_state.cgi isn't intended to return state - it's only to give a 200 response, so that Fauxmo will give a thumbs up to Alexa/Echo, so that the user is given an audible 'OK'.
In this case, based on your curl
output above, your config should include:
"state_response_on": "OK"
"state_response_off": "OK"
I don't see anywhere that your light_state.cgi
would return OFF
, it looks like it only returns OK
.
Though part of the problem is that I don't think a state request should be forwarded by Fauxmo, because I'm using simplehttpplugin not RESTAPIplugin, but that's a separate topic for a separate thread ;)
No, it seems to be an ongoing misunderstanding on your par -- look at your own logs -- when state parameters are not included in the configuration, the state request is not forwarded by Fauxmo. It received the state request from the echo and the plugin by default responds with unknown
. Fauxmo then returns str(int(state.lower() == "on"))
, or '0'
, which gets put into the response for the Echo.
Admittedly this could be improved -- by default it is responding that the device is off
, and I should probably be using enums. But it is not forwarding this request on to the device.
I think part of the problem, is that we're chasing too many squirrels. I wish to drop the "state" parameters issue - it's giving clues to the original problem, but I suspect if the original problem is fixed, everything else will fall into place.
Agreed, feel free to leave it out of your config. I'm interested to know how other libraries are dealing with this issue (homeassistant, FauxmoESP, go-home-iot), just haven't had time yet.
The original problem is (which was also reported in Issue number 61), is that with the following config.json, requests to Alexa to turn the device 'on', result in Alexa saying the device is not responding, and requests to turn the device 'off', work fine (Alexa responds with 'ok').
My guess is it's related to what I pointed out in my last comment and again above -- Fauxmo responds to the Echo's GetBinaryState
response with str(int(state.lower() == "on"))
. The plugin by default responds with "unknown"
, which will result in '0'
, which is interpreted as "off" by the Echo (in keeping with 0 for off and 1 for on in its SetBinaryState
commands). So when you turn it on, the Echo immediately follows up by asking for its state, and Fauxmo responds with '0'
, which it interprets as "off", so it complains. When you turn it off, the Echo immediately follows up by asking for its state, and Fauxmo responds with '0'
, which it interprets as "off", so doesn't complain. This is a symptom of not having set up any proper way to check for state with your cgi script. If you fix your state_cmds
as I've described above, it should always respond that the command succeeded.
This behavior is in part predicated on the fact that the Echo continues to poll the state of a device. I don't remember what happens if Fauxmo just doesn't send a response at all (whether it will forget the device / block further requests pending a response / just move on / other).
In the meantime, I see how this behavior is confusing. I'll need to experiment with different strategies for dealing with absence of state_cmd
, which I think is an open question.
Ways contributors can help:
Thanks for providing all the logs and info as requested @johngo7470, very helpful.
No, it seems to be an ongoing misunderstanding on your part
Ah... in Issue 61, when you said:
? SimpleHTTPlugin doesn't have a state_response_on -- are you looking at RESTAPIPlugin?
I believed the state commands didn't belong in SimpleHTTPplugin (which is why I've repeatedly questioned this, above).
However, I just re-read your README, where it says, "As of Fauxmo v0.4.5, SimpleHTTPPlugin also supports (and Fauxmo requires) a get_state method".
I'll submit a request to update your example scripts... ;)
Ok... so I tried the following config.json: (both state_response_on and state_response_off are set to OK)
{
"FAUXMO": {
"ip_address": "auto"
},
"PLUGINS": {
"SimpleHTTPPlugin": {
"DEVICES": [
{
"port": 12340,
"on_cmd": "http://192.168.2.106/cgi-bin/light_on.cgi",
"off_cmd": "http://192.168.2.106/cgi-bin/light_off.cgi",
"state_cmd": "http://192.168.2.106/cgi-bin/light_state.cgi",
"state_response_on": "OK",
"state_response_off": "OK",
"method": "GET",
"name": "my call light"
}
]
}
}
}
When I asked Alexa to turn ON my call light, my on_CGI script runs, but Alexa said it wasn't responding. When I asked Alexa to turn OFF my call light, my off_CGI script runs, and Alexa said, "ok".
Then I changed the value of (only) state_response_off, to "OFF":
{
"FAUXMO": {
"ip_address": "auto"
},
"PLUGINS": {
"SimpleHTTPPlugin": {
"DEVICES": [
{
"port": 12340,
"on_cmd": "http://192.168.2.106/cgi-bin/light_on.cgi",
"off_cmd": "http://192.168.2.106/cgi-bin/light_off.cgi",
"state_cmd": "http://192.168.2.106/cgi-bin/light_state.cgi",
"state_response_on": "OK",
"state_response_off": "OFF",
"method": "GET",
"name": "my call light"
}
]
}
}
}
When I asked Alexa to turn ON my call light, my on_CGI script runs, and Alexa said, "ok". When I asked Alexa to turn OFF my call light, my off_CGI script runs, but Alexa said it wasn't responding.
In other words, behavior flipped, even though all I did was modify the value of state_response_off.
I've been really confused at why you're seeing that behavior, but I just had a 💡.
Then I changed the value of (only) state_response_off, to "OFF":
Please stop putting "OFF"
there, it is only confusing matters. These values (state_response_on
and state_response_off
) needs to be somewhere in the content returned by your state_cmd
. Your cgi script only returns "OK"
, as shown by your curl
commands above, so this is the only value that makes any sense. As far as I can tell, there is no possible way that "OFF"
will work correctly.
Here's the realization:
It checks for state_response_off
before checking for state_response_on
, and returns early if found. So if you use "OK"
for both values, it will always return "off"
(because it looks for state_response_off
, finds it, and returns).
So that's the issue I think. So when you change your state_response_off
value to something nonsensical (like "OFF"
), it doesn't find it, then proceeds to check for your state_response_on
value.
Regardless, the next steps are the same as I outlined above -- considering if there is a better alternative to just returning str(int(state.lower() == "on"))
, which makes it look like the switch is always off.
Ok... I think I've finally picked up on what you're saying about what state_cmd returns. I changed (and confirmed via curl) that state_cmd now returns "unknown":
pi@raspberrypi:/var/www/html/cgi-bin $ curl -v http://192.168.2.106/cgi-bin/light_state.cgi
* Expire in 0 ms for 6 (transfer 0x1e727c0)
* Trying 192.168.2.106...
* TCP_NODELAY set
* Expire in 200 ms for 4 (transfer 0x1e727c0)
* Connected to 192.168.2.106 (192.168.2.106) port 80 (#0)
> GET /cgi-bin/light_state.cgi HTTP/1.1
> Host: 192.168.2.106
> User-Agent: curl/7.64.0
> Accept: */*
>
< HTTP/1.1 200 OK
< Content-type: text/plain
< Content-Length: 8
< Date: Tue, 17 Sep 2019 11:40:41 GMT
< Server: lighttpd/1.4.53
<
unknown
When I set config.json to: (no entries for state_response_on/state_response_off)
{
"FAUXMO": {
"ip_address": "auto"
},
"PLUGINS": {
"SimpleHTTPPlugin": {
"DEVICES": [
{
"port": 12340,
"on_cmd": "http://192.168.2.106/cgi-bin/light_on.cgi",
"off_cmd": "http://192.168.2.106/cgi-bin/light_off.cgi",
"method": "GET",
"state_cmd": "http://192.168.2.106/cgi-bin/light_state.cgi",
"name": "my call light"
}
]
}
}
}
Both ON/OFF commands, result in Alexa saying "my call light isn't responding.
If I then add state_response_on and state_response_off with a value of "ON" and "OFF" (and state_cmd still returns "unknown"):
{
"FAUXMO": {
"ip_address": "auto"
},
"PLUGINS": {
"SimpleHTTPPlugin": {
"DEVICES": [
{
"port": 12340,
"on_cmd": "http://192.168.2.106/cgi-bin/light_on.cgi",
"off_cmd": "http://192.168.2.106/cgi-bin/light_off.cgi",
"method": "GET",
"state_cmd": "http://192.168.2.106/cgi-bin/light_state.cgi",
"state_response_on": "ON",
"state_response_off": "OFF",
"name": "my call light"
}
]
}
}
}
Alexa responds and says it's not responding, when I ask to turn on the call light. When I asked Alexa to turn OFF my call light, Alexa said, "ok".
Finally, I modified light_state.cgi to return "ON" when I gave the command to turn on my call light, and "OFF" when I gave the command to turn off my call light.
All finally worked perfectly (both ON and OFF requests yeild an 'ok' from Alexa)
So... what this seems to establish, is that when using state (state_cmd, state_response_on, state_response_off), the user must use all three state parameters in their fauxmo entity, and must return the expected state (defined by stateresponse*), or they will receive a 'not responding' from Alexa.
It also appears that allowing state_cmd to return "unknown", does not produce an 'ok' response, as Alexa wants to see the proper state that it set.
It also appears that defining a fauxmo device within simplehttpplugin, requires the inclusion of the three state parameters, to work properly. Failure to include and properly provide expected state from the cgi scripts, will result in 'not responding' for an ON request, but interestingly, will give a response of 'ok' to an OFF request.
My guess is that with 0.4.5 and onward, use of state_ values is indeed required, to satisfy Alexa/Echo, or by default, Fauxmo will always return a state of "0", which results in requests to turn on a device, being successful in that the proper cgi is called, but Alexa is told the state is off. This may also explain why there are three requests from Alexa to check the state - the logic is probably that it is hoping eventually the state will change from "0" to "1" in the response, but that after three tries (three strikes), the 'not responding' response is given to the user, by Alexa.
Ok... I think I've finally picked up on what you're saying about what state_cmd returns.
Fantastic!
When I set config.json to: (no entries for state_response_on/state_response_off) ... Both ON/OFF commands, result in Alexa saying "my call light isn't responding.
While this is the behavior I would hope for, I'm not entirely sure why it's happening. Based on the discussion above, returning unknown
from SimpleHTTPPlugin.get_state
should make for a return_val
of "0"
, which to the Echo should be the same as "off."
If I then add state_response_on and state_response_off with a value of "ON" and "OFF" (and state_cmd still returns "unknown"): ... Alexa responds and says it's not responding, when I ask to turn on the call light. When I asked Alexa to turn OFF my call light, Alexa said, "ok".
Correct, this replicates the behavior we've discussed above. Fauxmo returning unknown
will be returned as "0"
and interterpreted as off
by the Echo.
Finally, I modified light_state.cgi to return "ON" when I gave the command to turn on my call light,
So... what this seems to establish, is that when using state (state_cmd, state_response_on, state_response_off), the user must use all three state parameters in their fauxmo entity, and must return the expected state (defined by stateresponse*), or they will receive a 'not responding' from Alexa.
Correct. This is why state_response_*
exists, so users can potentially avoid this behavior if they wish, and if they can return state.
It also appears that allowing state_cmd to return "unknown", does not produce an 'ok' response, as Alexa wants to see the proper state that it set.
Correct.
It also appears that defining a fauxmo device within simplehttpplugin, requires the inclusion of the three state parameters, to work properly.
I disagree. "Working properly" is toggling the switch, which it does readily without state parameters.
Failure to include and properly provide expected state from the cgi scripts, will result in 'not responding' for an ON request, but interestingly, will give a response of 'ok' to an OFF request.
Correct, this is the (unexpected) behavior I explained above. I'm open to better solutions, but it will require some experimentation to see how the Echo responds to changing the behavior. Ultimately, "Fauxmo" is a "Faux Wemo," and if a user's device accurately can't report state like a Wemo can, then the Echo is not going to behave.
My guess is that with 0.4.5 and onward, use of state_ values is indeed required, to satisfy Alexa/Echo, or by default, Fauxmo will always return a state of "0", which results in requests to turn on a device, being successful in that the proper cgi is called, but Alexa is told the state is off. This may also explain why there are three requests from Alexa to check the state - the logic is probably that it is hoping eventually the state will change from "0" to "1" in the response, but that after three tries (three strikes), the 'not responding' response is given to the user, by Alexa.
Yes, this is correct. But I want to emphasize that people have many different use cases for Fauxmo, and the critical behavior of interest is completing the command (e.g. toggling the switch), and the state stuff is absolutely not required for this, and is therefore not required for Fauxmo's core functionality. The state stuff is optional, and Fauxmo will happily turn switches on and off without it.
Yes, the Echo does try to poll state as well as ensure that a device properly responded to commands (by checking its state), and the Echo will complain loudly if it can't do so.
[It also appears that defining a fauxmo device within simplehttpplugin, requires the inclusion of the three state parameters, to work properly.]
I disagree. "Working properly" is toggling the switch, which it does readily without state parameters.
In my opinion, Alexa giving a response of "...not responding" doesn't fully qualify as working properly, even though it toggles the switch. I believe "working properly", needs to also include an audible 'ok' from Alexa.
Where this seems to not be working (because Alexa is saying "not responding" to ON requests), is when using 0.4.5 (or later Fauxmo), and the SimpleHTTPplugin, does not contain "state_*" kwargs (parameters).
Where everything DOES appear to be working as designed, and working as expected, when using Fauxmo 0.4.5 or later, is when SimpleHTTPplugin device definitions include the three "state_*" kwargs, where they are defined properly, and where the cgi scripts are configured to return proper values.
I understand there are a variety of applications (mine is also unique), but I would think the user always wants to hear 'ok' from Alexa, when a command is given to turn a device on/off. Currently, when using the SimpleHTTPplugin without "state_*" kwargs, it appears Fauxmo 0.4.9 (and presumably 0.4.5) always returns a state of 0, to Alexa/Echo, even when ON is requested.
In my opinion, Alexa giving a response of "...not responding" doesn't fully qualify as working properly, even though it toggles the switch.
You are entitled to your opinion...
Where everything DOES appear to be working as designed
...but you are not entitled to decide how this project was designed, or when it is working as designed, even if you disagree with its design. Quoting from the README:
Fauxmo provides emulated Belkin Wemo devices that the Echo can turn on and off by voice, locally, and with minimal lag time.
I agree that the user experience will usually be better if users are able to include the optional state related configuration, which is why it is provided. Not all use cases can support state, and in such cases the user experience will suffer, but the core functionality should continue to work as designed.
I don't think this discussion is productive, and I'm not interested on continuing to spend time on it. I recommend that we return to ways contributors can help.
Sorry for the confusion - I'm not asking for you to encourage users to use the state params - I'm recommending a change so that users who don't use state params, get an audible 'ok' from echo, when they request a Fauxmo device be turned on. Currently, that is what's not working properly (in my opinion).
Please consider the following change in the SimpleHTTPplugin: (it will resolve my problem, as well as Issue 61, and overall it will improve the user experience)
This change will return getBinaryState=1 to Echo, when user requests a Fauxmo device be turned on, and it will return getBinaryState=0, when the user requests a Fauxmo device be turned off. Currently, it looks like Fauxmo always returns a 0, to both ON and OFF commands (unless using state_ kwargs).
if ( !state_cmd) { //if using SimpleHTTPplugin, but the user hasn't defined a state_cmd URL
if (setBinaryState request from Echo) saved_state = setBinaryState.requested_state;
// if a request comes in to set a state for a Fauxmo device, save the requested state in a variable
if (getBinaryState request && requested_state.cgi returns 200) return saved_state to Echo
// if Echo requests binary state, give back what it requested (as long as cgi returns 200/success)
}
I'm recommending a change so that users who don't use state_ params, get an audible 'ok' from echo, when they request a Fauxmo device be turned on. Currently, that is what's not working properly (in my opinion).
I would consider this as opt-in behavior but honestly would not want it enabled by default. Perhaps something like an ignore_state
config setting that defaults to False
.
The bigger problem is the implementation. I'm pretty sure your logic above won't work, because the request to turn the device on / off and the request to get_state
are separate requests. You can't return something from the first request to the second request. The get_state
request happens to immediately follow the on or off request, but it isn't part of the same request, so you can't return something from the on
or off
request to it. Does that make sense?
EDIT: Correction, in rereading it seems like you understand that they are separate requests.
// if a request comes in to set a state for a Fauxmo device, save the requested state in a variable
Please again refer to my comment above, ways contributors can help, where I addressed this idea specifically:
I really don't want to mess with trying to maintain device state in Fauxmo. Perhaps someone could create a plugin prototype that maintains its own state, which should make the Echo happy.
My concern is that the async nature of the Fauxmo backend could lead to race conditions and unpredictable bugs in trying to maintain state (though this might be totally unfounded, since it is concurrent but not parallel... right?).
Are you interested in prototyping something towards this?
EDIT2: In fact, I think this is a perfect use case for a user plugin as a prototype. Refer to the readme re: fauxmo-plugins and write a plugin that inherits from SimpleHTTPPlugin
. This should give it all the existing methods and functionality. Then just override the existing methods to add something like:
def __init__(self, *args, **kwargs) -> None:
super().__init__(*args, **kwargs)
self._dummy_state = "off"
def on(self) -> bool:
self._dummy_state = "on"
return super().on()
def off(self) -> bool:
self._dummy_state = "off"
return super().off()
def get_state(self) -> str:
return self._dummy_state
If I understand your statement about info from one request returning to another - are you saying python doesn't support non-volatile variables associated with the Fauxmo object? True, I am a noob with regards to python (and actually prefer to write my cgi's in C), but I would be surprised if python can't support squirreling this information away somewhere, in each of the Fauxmo objects.
In any case, now that I know how to use simpleHTTPplugin WITH the state_* kwargs, it's working fine for me - not a problem to implement in all my fauxmo objects, and writing the extra CGI.
Since the basic simpleHTTPplugin will never result in the user hearing 'ok' from Alexa when they request a Fauxmo object be turned on, I think it's worth mentioning this in the README, so that users know it's normal for Alexa/Echo to say "... not responding" when giving the command "Alexa, turn on [fauxmo device name]", when using 0.4.5+ Fauxmo, unless they also implement the state_* parameters in their config.json, and properly process the requests in their CGI's.
BTW, in Issue 61, there are many statements to indicate the statekwargs were not valid/would be ignored within simpleHTTPplugin - it would seem this is outdated information, as they are now valid kwargs. Similarly, your README says that the state* kwargs are "required", even though they are not required. It's not easy to clean these conflicts up, because they refer to pre and post-0.4.5 versions of Fauxmo, but I'm optimistic that the updated simpleHTTPplugin documentation will clear up the details :)
I'm very thankful for Fauxmo - helping a relative of mine who is fully disabled, use their (nurse) call light, change tv channels, control lights, control the phone, etc... your work is helping in ways you may never be able to fully appreciate, for which we users are very appreciative.
are you saying python doesn't support non-volatile variables associated with the Fauxmo object
Just saying that I don't know. (But at least I know that I don't know.) I'm not a technology professional, self-taught, and I've read a few times that mutable state and async code can be trouble.
I think it's worth mentioning this in the README
I've already made some updates locally, have not yet pushed to dev.
I'm very thankful for Fauxmo...
Wow, that's really cool, thanks for sharing!
If you haven't looked into HomeAssistant, it's a great project. It has a built-in Fauxmo-like server that I used for a while and it seemed to work well.
I'll look into making some kind of instance attribute for the last triggered action. Thanks for the dialog.
I tested the following changes in simplehttpplugin.py, and it now allows Alexa to give an audible 'ok', to both ON and OFF requests (with 0.4.9 Fauxmo and 3.7.3 Python)
In SimpleHTTPPlugin __init__:
add: self.requested_state = "unknown"
In on():
add: self.requested_state = "on"
In off():
add: self.requested_state = "off"
In get_state():
in: if self.state_cmd is None:
remove: return "unknown"
add: return self.requested_state
Please note: these changes do NOT query your cgi scripts for the state of your fauxmo device - these changes simply tell Alexa, that the state you requested, is the state Fauxmo set (by running the cgi).
If you really want confirmation on the state of your fauxmo device (based on a response from your ON/OFF cgi scripts), you will need to implement state_cmd, state_response_on, and state_response_off, in your config.json fauxmo device definitions.
Tested successfully with:
{
"FAUXMO": {
"ip_address": "auto"
},
"PLUGINS": {
"SimpleHTTPPlugin": {
"DEVICES": [
{
"port": 12340,
"on_cmd": "http://192.168.2.106/cgi-bin/light_on.cgi",
"off_cmd": "http://192.168.2.106/cgi-bin/light_off.cgi",
"method": "GET",
"name": "my call light"
}
]
}
}
}
This issue can be closed.
I did a modest amount of work towards this over the last couple days, will
be pushing to dev
soon.
Other contributors please hold off until my changes are pushed.
@johngo7470 -- can you install from the dev branch and see what you think?
The new config setting is use_fake_state
and is implemented for SimpleHTTPPlugin
. I also migrated over CommandLinePlugin
and implemented it there as well, and migrated HomeAssistantPlugin
but did not think it was appropriate there (HomeAssistant reports state).
Grazie :)
@johngo7470 Any chance to test the dev branch? I'd like to merge to master and make a new release soon.
Unfortunately, the device this is set up on, is in Michigan, and I've lost contact with it, recently (loss of internet, loss of power, or hardware failure).
I'll be going there this Saturday, and might have a chance to try the dev load, but depends on what I find when I get there. JohnG
On Thursday, October 3, 2019, 9:16:40 PM CDT, Nathan Henrie <notifications@github.com> wrote:
@johngo7470 Any chance to test the dev branch? I'd like to merge to master and make a new release soon.
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.
@johngo7470 any updates? Want to make sure the issue is resolved before merging / pushing / closing.
Hi Nathan, My apologies - I neglected to follow up with you on this. Do I need to do a full re-install of the dev branch, or can I just download the dev version of simplehttpplugin.py? If I can just download the dev of simplehttpplugin.py, where can I download it from? Kind regards,JohnG
On Tuesday, October 22, 2019, 8:05:38 AM CDT, Nathan Henrie <notifications@github.com> wrote:
@johngo7470 any updates? Want to make sure the issue is resolved before merging / pushing / closing.
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.
Ah, I just found the dev branch... (still kinda learning my way around github) Do I need the entire kittenkaboodle, or just the updated simplehttpplugin.py? JohnG
On Tuesday, October 22, 2019, 8:05:38 AM CDT, Nathan Henrie <notifications@github.com> wrote:
@johngo7470 any updates? Want to make sure the issue is resolved before merging / pushing / closing.
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.
Clearly I should read more, before writing... I see your notes showing that init.py and commandlineplugin.py were also updated as part of the fake state change...
I'll try to test your changes this evening. Kind regards, JohnG
On Tuesday, October 22, 2019, 8:05:38 AM CDT, Nathan Henrie <notifications@github.com> wrote:
@johngo7470 any updates? Want to make sure the issue is resolved before merging / pushing / closing.
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.
Good to hear from you.
Give this a shot, let me know if you have trouble: https://github.com/n8henrie/fauxmo#simple-install-of-dev-branch-from-github
Make sure you've uninstalled any old versions first.
I'm off to a bad start... I reverted my RPi to an image from about three months ago...
I started following the installation instructions for fauxmo, and entered the command: sudo pip install --upgrade pip
It came back with, "Successfully installed pip-19.3.1"
Good... (I say to myself)
For grins, I type, "pip --version", and it replies, "pip 9.0.1 from /home/pi/.local/lib/python2.7/site-packages (python 2.7)"
Hmmm... so what happened to pip-19.3.1?
===== Speaking of versions... I typed "python3", and it shows me that 3.5.3 is running.
I seem to recall the last time I tried to get to python3.7, I mangled my installation.
I am genuinely interested in testing your changes, but I seem to be stuck, getting to the latest pip and latest python.
=============
I did a bit of searching and found a recommendation that I not use sudo, as it would try to upgrade the wrong installation. However, if I run without sudo, I receive numerous errors:
pi@raspi:~ $ pip install --upgrade pip
Collecting pip
Using cached https://files.pythonhosted.org/packages/00/b6/9cfa56b4081ad13874b0c6f96af8ce16cfbc1cb06bedf8e9164ce5551ec1/pip-19.3.1-py2.py3-none-any.whl
Installing collected packages: pip
Found existing installation: pip 9.0.1
Uninstalling pip-9.0.1:
Successfully uninstalled pip-9.0.1
Rolling back uninstall of pip
Exception:
Traceback (most recent call last):
File "/home/pi/.local/lib/python2.7/site-packages/pip/basecommand.py", line 215, in main
status = self.run(options, args)
File "/home/pi/.local/lib/python2.7/site-packages/pip/commands/install.py", line 342, in run
prefix=options.prefix_path,
File "/home/pi/.local/lib/python2.7/site-packages/pip/req/req_set.py", line 784, in install
**kwargs
File "/home/pi/.local/lib/python2.7/site-packages/pip/req/req_install.py", line 851, in install
self.move_wheel_files(self.source_dir, root=root, prefix=prefix)
File "/home/pi/.local/lib/python2.7/site-packages/pip/req/req_install.py", line 1064, in move_wheel_files
isolated=self.isolated,
File "/home/pi/.local/lib/python2.7/site-packages/pip/wheel.py", line 345, in move_wheel_files
clobber(source, lib_dir, True)
File "/home/pi/.local/lib/python2.7/site-packages/pip/wheel.py", line 323, in clobber
shutil.copyfile(srcfile, destfile)
File "/usr/lib/python2.7/shutil.py", line 83, in copyfile
with open(dst, 'wb') as fdst:
IOError: [Errno 13] Permission denied: '/usr/local/lib/python2.7/dist-packages/pip-19.3.1.dist-info/top_level.txt'
You are using pip version 9.0.1, however version 19.3.1 is available.
You should consider upgrading via the 'pip install --upgrade pip' command.
Any pearls of wisdom, that can get me back on track?
J
Ok, since pip was 9.0.1, I decided to try the install with what I had...
(understandably) It didn't like that I was running python 3.5.3.
pi@raspi:~ $ python3 -m venv .venv pi@raspi:~ $ spirce ./.venv/bin/activate -bash: spirce: command not found pi@raspi:~ $ source ./.venv/bin/activate (.venv) pi@raspi:~ $ pip install -e git+https://github.com/n8henrie/fauxmo.git@d ev Could not detect requirement name, please specify one with #egg= (.venv) pi@raspi:~ $ pip install git+https://github.com/n8henrie/fauxmo.git@dev Collecting git+https://github.com/n8henrie/fauxmo.git@dev Cloning https://github.com/n8henrie/fauxmo.git (to dev) to /tmp/pip-q23ov_fh-build fauxmo requires Python '>=3.6' but the running Python is 3.5.3 (.venv) pi@raspi:~ $
sudo pip install --upgrade pip
I recommend against ever using sudo pip
for virtually any reason. Anything requiring sudo
should be managed by your package manager (e.g. sudo apt install python3-pip
). You can usually use the --user
flag to make modifications to a version specific to the user in question that doesn't risk messing up your system-wide installation. Also, paths can be tricky, so consider using /path/to/python -m pip
instead of pip
-- should have the same interface, but makes it much more explicit which environment is getting modified.
As an example, for development on my Mac, I may have a system python at /usr/bin/python3
, a homebrew-installed version at /usr/local/bin/python3
, multiple versions that I use for development at e.g. /opt/pyenv/versions/bin/python3
, and then one in the virtualenv for a specific project at /path/to/fauxmo/venv/bin/python3
. Each of these will have its own installation of pip
, and if I just say pip install...
it's easy to confuse which of these is being modified, as opposed to /usr/local/bin/python3 -m pip install
, which ensures that it's my homebrew installation that is being changed. Complexity here is definitely one of Python's drawbacks.
Additionally, you can add the --user
flag to pip
commands, which installs packages to a directory relative to a user's $HOME
, e.g. ~/.local
on Linux (which you'll recognize from your output above). So you may have a /usr/bin/pip
that is being shadowed by a ~/.local/bin/pip
.
These issues can be tricky, even for an experienced pythonista. I recently struggled with something similar that I couldn't resolve with the scalpel, so I had to resort to the axe and do something along the lines of rm -r ~/.local/lib/python3.7/site-packages/pip
.
In general, I would recommend making a virtualenv specific to each project, which ensures that their dependencies don't conflict, and helps ensure that you have permissions to modify whatever you want. In your case, I might do something like the following (not tested):
$ # cd to a subdir for fauxmo within a dir for projects
$ mkdir -p myprojects/fauxmo && cd $_
$ # Make a venv named `.venv`, requires package `python3-venv`
$ /usr/bin/python3 -m venv -m .venv
$ # Upgrade pip in this venv
$ ./.venv/bin/python3 -m pip install --upgrade pip
$ # Alternatively, you can activate the venv and therafter omit the above `./.venv/bin/python3`:
$ source ./.venv/bin/activate
$ pip install git+https://github.com/n8henrie/fauxmo.git@dev
If that worked, you should be able to use fauxmo -c config.json
(since the virtualenv has been activated), or ./.venv/bin/fauxmo -c config.json
if you want to be explicit (or did not activate the virtualenv, or have already run deactivate
to deactivate the virtualenv).
Hope that helps.
(understandably) It didn't like that I was running python 3.5.3.
Now following your instructions for installing 3.7.3 with pyenv...
But if I remember right from last time, typing "python3" will still show 3.5.3 is installed, though I think there's a way to call 3.7 from full path.
pi@raspi:~ $ pyenv install 3.7.3 Downloading Python-3.7.3.tar.xz... -> https://www.python.org/ftp/python/3.7.3/Python-3.7.3.tar.xz Installing Python-3.7.3... Installed Python-3.7.3 to /opt/pyenv/versions/3.7.3
pi@raspi:~ $ python3 Python 3.5.3 (default, Sep 27 2018, 17:25:39) [GCC 6.3.0 20170516] on linux Type "help", "copyright", "credits" or "license" for more information.
pi@raspi:~ $
==============
pi@raspi:~ $ /opt/pyenv/versions/3.7.3/bin/python3 Python 3.7.3 (default, Oct 28 2019, 21:25:37) [GCC 6.3.0 20170516] on linux Type "help", "copyright", "credits" or "license" for more information.
pi@raspi:~ $
Nice work!
$ mkdir -p where/i/want/fauxmo && cd $_
$ /opt/pyenv/versions/3.7.3/bin/python3 -m venv .venv
$ source ./.venv/bin/activate
$ which pip
I guess I installed successfully (though still fuzzy on the whole venv)...
I'll let you know how things go...
pi@raspi:~ $ /opt/pyenv/versions/3.7.3/bin/python3 -m venv .venv
pi@raspi:~ $
pi@raspi:~ $ ./.venv/bin/python3 -m pip install --upgrade pip
Looking in indexes: https://pypi.org/simple, https://www.piwheels.org/simple
Collecting pip
Using cached https://files.pythonhosted.org/packages/00/b6/9cfa56b4081ad13874b0c6f96af8ce16cfbc1cb06bedf8e9164ce5551ec1/pip-19.3.1-py2.py3-none-any.whl
Installing collected packages: pip
Found existing installation: pip 19.0.3
Uninstalling pip-19.0.3:
Successfully uninstalled pip-19.0.3
Successfully installed pip-19.3.1
pi@raspi:~ $ source ./.venv/bin/activate
(.venv) pi@raspi:~ $ pip install git+https://github.com/n8henrie/fauxmo.git@dev
Looking in indexes: https://pypi.org/simple, https://www.piwheels.org/simple
Collecting git+https://github.com/n8henrie/fauxmo.git@dev
Cloning https://github.com/n8henrie/fauxmo.git (to revision dev) to /tmp/pip-req-build-6fnnxwlo
Running command git clone -q https://github.com/n8henrie/fauxmo.git /tmp/pip-req-build-6fnnxwlo
Running command git checkout -b dev --track origin/dev
Switched to a new branch 'dev'
Branch dev set up to track remote branch dev from origin.
Installing build dependencies ... done
Getting requirements to build wheel ... done
Preparing wheel metadata ... done
Building wheels for collected packages: fauxmo
Building wheel for fauxmo (PEP 517) ... done
Created wheel for fauxmo: filename=fauxmo-0.4.9-cp37-none-any.whl size=30119 sha256=6f84a65347b869c414bd8543e538f1ffef06a2231095fdab4a02906d15a1d447
Stored in directory: /tmp/pip-ephem-wheel-cache-zymyipu2/wheels/99/79/6d/38d6be117d03893413bc8e6a7d861ce5ddaa933063db7cb262
Successfully built fauxmo
Installing collected packages: fauxmo
Successfully installed fauxmo-0.4.9
(.venv) pi@raspi:~ $
fauxmo --version
): 0.4.9My Issue
Appears to be the same issue another user was having back in May, though there was no resolution in that case, due to lack of response from the user.
I'm using simplehttpplugin in my config.json:
{ "FAUXMO": { "ip_address": "auto" }, "PLUGINS": { "SimpleHTTPPlugin": { "DEVICES": [ { "port": 12340, "on_cmd": "http://192.168.2.106/cgi-bin/light_on.cgi", "off_cmd": "http://192.168.2.106/cgi-bin/light_off.cgi", "method": "GET", "name": "my call light" } ] } } }
When I ask Alexa to turn my call light on, she responds with "my light isn't responding" When I ask Alexa to turn my call light off, she responds with "ok".
Entries in lighttpd's access log, show both requests are processed:
192.168.2.106 192.168.2.106 - [08/Sep/2019:08:59:41 -0500] "GET /cgi-bin/light_on.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [08/Sep/2019:08:59:53 -0500] "GET /cgi-bin/light_off.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7"
Curl shows both requests give 200:
pi@raspberrypi:~ $ curl -v http://192.168.2.106/cgi-bin/test.cgi
Here's where it gets kinda funky... I tried the same experiment as the user back in May, by modifying config.json with state parameters as follows:
When I did that, I received "ok" to my 'on' request, but then my 'off' request would result in a 'not responding' condition.
lighttpd shows the following activity:
192.168.2.106 192.168.2.106 - [08/Sep/2019:09:33:38 -0500] "GET /cgi-bin/light_on.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [08/Sep/2019:09:33:38 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [08/Sep/2019:09:33:47 -0500] "GET /cgi-bin/light_off.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [08/Sep/2019:09:33:47 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [08/Sep/2019:09:33:48 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [08/Sep/2019:09:33:49 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7"
It gets even more peculiar... then I modified config.json by modifying "state_response_off": "OFF", to "state_response_off": "OK".
Then behavior flipped again - turning the light on was again giving 'not responding' from Alexa, and the off command was yeilding 'ok' from Alexa.
In both cases, the cgi was executed, and the response code appears to be 200, though notice that the cases where Alexa gives me a 'not responding', you see multiple attempts by fauxmo, to retrieve state information, even though these config values (presumably) should be ignored in simplehttpplugin:
192.168.2.106 192.168.2.106 - [08/Sep/2019:09:32:35 -0500] "GET /cgi-bin/light_on.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [08/Sep/2019:09:32:35 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [08/Sep/2019:09:32:36 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [08/Sep/2019:09:32:37 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [08/Sep/2019:09:32:46 -0500] "GET /cgi-bin/light_off.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7" 192.168.2.106 192.168.2.106 - [08/Sep/2019:09:32:46 -0500] "GET /cgi-bin/light_state.cgi HTTP/1.1" 200 3 "-" "Python-urllib/3.7"
Should state checks even be performed as part of the simplehttpplugin? (shouldn't these only occur if I'm using the REST plugin?)
WHYT
Please make sure you've taken these steps before submitting a new issue:
-vvv
) and include relevant outputconfig.json