Alexa keeps saying "device not responding" - Githubissues

n8henrie / fauxmo

Emulated Belkin WeMo devices that work with the Amazon Echo

https://n8henrie.com/2016/02/fauxmo-home-automation-with-the-amazon-echo-raspberry-pi-and-homeassistant/

Other

377 stars 78 forks source link

Alexa keeps saying "device not responding" #124

Closed skorokithakis closed 7 months ago

skorokithakis commented 8 months ago

Issues not following the template may be closed for that reason alone.
Operating system and version: Raspbian 12
Python version: 3.11.2
Fauxmo version (fauxmo --version): v0.8.0
Echo device type (e.g. Echo, Echo Plus, Dot): Echo Dot
Echo Firmware Version: Not sure

My Issue

I'm trying to get my Home Assistant devices working with Alexa via fauxmo, but the devices only work intermittently, and Alexa frequently complains about the device not responding, even though the device usually does turn on/off. I get a lot of this in the log:

2024-03-09 13:14:08 fauxmo:199      WARNING  Unable to complete command for Bedroom lamp:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.1.200:35650
Content-Type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#GetBinaryState"
Content-Length: 298

<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetBinaryState xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>1</BinaryState></u:GetBinaryState></s:Body></s:Envelope>

{
  "FAUXMO": {
    "ip_address": "192.168.1.200"
  },
  "PLUGINS": {
    "RESTAPIPlugin": {
      "DEVICES": [
        {
          "headers": {
            "Authorization": "Bearer mytoken",
            "Content-Type": "application/json"
          },
          "method": "POST",
          "name": "Patio light",
          "off_cmd": "http://localhost:81/api/services/light/turn_off",
          "off_json": {
            "entity_id": "light.patio_lights_l1"
          },
          "on_cmd": "http://localhost:81/api/services/light/turn_on",
          "on_json": {
            "entity_id": "light.patio_lights_l1"
          },
          "port": 41095,
          "state_cmd": "http://localhost:81/api/states/light.patio_lights_l1",
          "state_method": "GET",
          "state_response_off": "\"state\":\"off\"",
          "state_response_on": "\"state\":\"on\""
        }
    ]}
}

WHYT

I've tried the Home Assistant plugin, the REST plugin, as well as faking the state, but nothing works consistently.

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

[X] Try to reproduce the issue with Fauxmo installed in a venv
[X] Ensure you're running a supported version of Python
- Requires Python >= 3.2 for Fauxmo < 0.3.0
- Requires Python >= 3.4.4 for Fauxmo >= 0.3.0
- Requires Python >= 3.6.0 for Fauxmo >= 0.4.0
[X] Run Fauxmo in debug mode (-vvv) and include relevant output
[X] Include your Fauxmo config.json
[X] Search the existing (including closed) issues
[X] Please use codeblocks around your debug output and config

n8henrie commented 8 months ago

You haven't given me verbose (-vvv) log output with sufficient context, so I can't be very helpful.

That error message usually means that the called command didn't succeed, so you'll need to debug flakiness there.

FWIW I'm using 0.8 with the HomeAssistantPlugin and it's running well, no issues.

n8henrie commented 8 months ago

Also, any errors in your HomeAssistant log?

skorokithakis commented 8 months ago

Ahh, sorry, here's the full log (no errors on Home Assistant):

2024-03-09 14:25:12 asyncio:167      DEBUG    <Server sockets=(<asyncio.TransportSocket fd=8, family=2, type=1, proto=6, laddr=('192.168.1.200', 8454)>,)> got a new connection from ('192.168.1.111', 46796): <socket.socket fd=44, family=2, type=1, proto=6, laddr=('192.168.1.200', 8454), raddr=('192.168.1.111', 46796)>
2024-03-09 14:25:12 fauxmo:46       DEBUG    Connection made with: ('192.168.1.111', 46796)
2024-03-09 14:25:12 fauxmo:58       DEBUG    Received message:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.1.200:8454
Content-Type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#SetBinaryState"
Content-Length: 298

<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:SetBinaryState xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>0</BinaryState></u:SetBinaryState></s:Body></s:Envelope>
2024-03-09 14:25:12 fauxmo:69       INFO     request BasicEvent1
2024-03-09 14:25:12 fauxmo:122      DEBUG    Handling action for plugin type RESTAPIPlugin(method='POST', state_method='GET', headers={'Authorization': 'Bearer mytoken', 'Content-Type': 'application/json'}, auth=None, on_cmd='http://localhost:81/api/services/light/turn_on', off_cmd='http://localhost:81/api/services/light/turn_off', state_cmd='http://localhost:81/api/states/light.a60_smart_bulb_cct_rgb', on_data=None, off_data=None, state_data=None, on_json={'entity_id': 'light.a60_smart_bulb_cct_rgb'}, off_json={'entity_id': 'light.a60_smart_bulb_cct_rgb'}, state_json=None, state_response_on='"state":"on"', state_response_off='"state":"off"', _name='Lounge lamp', _port=8454, _latest_action='on')
2024-03-09 14:25:12 fauxmo:168      INFO     Attempting to turn off Lounge lamp
2024-03-09 14:25:12 fauxmo:193      DEBUG    HTTP/1.1 200 OK
CONTENT-LENGTH: 277
CONTENT-TYPE: text/xml
DATE: Sat, 09 Mar 2024 14:25:12 GMT
LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT
SERVER: Unspecified, UPnP/1.0, Unspecified
X-User-Agent: Fauxmo
CONNECTION: close

<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:SetBinaryStateResponse xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>0</BinaryState></u:SetBinaryStateResponse></s:Body></s:Envelope>
2024-03-09 14:25:12 asyncio:1917     WARNING  Executing <Handle cancelled _SelectorSocketTransport._read_ready() created at /usr/lib/python3.11/asyncio/selector_events.py:263> took 0.108 seconds
2024-03-09 14:25:12 asyncio:167      DEBUG    <Server sockets=(<asyncio.TransportSocket fd=8, family=2, type=1, proto=6, laddr=('192.168.1.200', 8454)>,)> got a new connection from ('192.168.1.111', 46804): <socket.socket fd=44, family=2, type=1, proto=6, laddr=('192.168.1.200', 8454), raddr=('192.168.1.111', 46804)>
2024-03-09 14:25:12 fauxmo:46       DEBUG    Connection made with: ('192.168.1.111', 46804)
2024-03-09 14:25:12 fauxmo:58       DEBUG    Received message:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.1.200:8454
Content-Type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#GetBinaryState"
Content-Length: 298

<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetBinaryState xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>1</BinaryState></u:GetBinaryState></s:Body></s:Envelope>
2024-03-09 14:25:12 fauxmo:69       INFO     request BasicEvent1
2024-03-09 14:25:12 fauxmo:122      DEBUG    Handling action for plugin type RESTAPIPlugin(method='POST', state_method='GET', headers={'Authorization': 'Bearer mytoken', 'Content-Type': 'application/json'}, auth=None, on_cmd='http://localhost:81/api/services/light/turn_on', off_cmd='http://localhost:81/api/services/light/turn_off', state_cmd='http://localhost:81/api/states/light.a60_smart_bulb_cct_rgb', on_data=None, off_data=None, state_data=None, on_json={'entity_id': 'light.a60_smart_bulb_cct_rgb'}, off_json={'entity_id': 'light.a60_smart_bulb_cct_rgb'}, state_json=None, state_response_on='"state":"on"', state_response_off='"state":"off"', _name='Lounge lamp', _port=8454, _latest_action='off')
2024-03-09 14:25:12 fauxmo:151      INFO     Attempting to get state for Lounge lamp
on
2024-03-09 14:25:12 fauxmo:157      INFO     Lounge lamp state: on
2024-03-09 14:25:13 fauxmo:193      DEBUG    HTTP/1.1 200 OK
CONTENT-LENGTH: 277
CONTENT-TYPE: text/xml
DATE: Sat, 09 Mar 2024 14:25:13 GMT
LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT
SERVER: Unspecified, UPnP/1.0, Unspecified
X-User-Agent: Fauxmo
CONNECTION: close

<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetBinaryStateResponse xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>1</BinaryState></u:GetBinaryStateResponse></s:Body></s:Envelope>
2024-03-09 14:25:13 asyncio:167      DEBUG    <Server sockets=(<asyncio.TransportSocket fd=8, family=2, type=1, proto=6, laddr=('192.168.1.200', 8454)>,)> got a new connection from ('192.168.1.111', 46808): <socket.socket fd=44, family=2, type=1, proto=6, laddr=('192.168.1.200', 8454), raddr=('192.168.1.111', 46808)>
2024-03-09 14:25:13 fauxmo:46       DEBUG    Connection made with: ('192.168.1.111', 46808)
2024-03-09 14:25:13 fauxmo:58       DEBUG    Received message:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.1.200:8454
Content-Type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#GetBinaryState"
Content-Length: 298

<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetBinaryState xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>1</BinaryState></u:GetBinaryState></s:Body></s:Envelope>
2024-03-09 14:25:13 fauxmo:69       INFO     request BasicEvent1
2024-03-09 14:25:13 fauxmo:122      DEBUG    Handling action for plugin type RESTAPIPlugin(method='POST', state_method='GET', headers={'Authorization': 'Bearer mytoken', 'Content-Type': 'application/json'}, auth=None, on_cmd='http://localhost:81/api/services/light/turn_on', off_cmd='http://localhost:81/api/services/light/turn_off', state_cmd='http://localhost:81/api/states/light.a60_smart_bulb_cct_rgb', on_data=None, off_data=None, state_data=None, on_json={'entity_id': 'light.a60_smart_bulb_cct_rgb'}, off_json={'entity_id': 'light.a60_smart_bulb_cct_rgb'}, state_json=None, state_response_on='"state":"on"', state_response_off='"state":"off"', _name='Lounge lamp', _port=8454, _latest_action='off')
2024-03-09 14:25:13 fauxmo:151      INFO     Attempting to get state for Lounge lamp
on
2024-03-09 14:25:13 fauxmo:157      INFO     Lounge lamp state: on
2024-03-09 14:25:13 fauxmo:193      DEBUG    HTTP/1.1 200 OK
CONTENT-LENGTH: 277
CONTENT-TYPE: text/xml
DATE: Sat, 09 Mar 2024 14:25:13 GMT
LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT
SERVER: Unspecified, UPnP/1.0, Unspecified
X-User-Agent: Fauxmo
CONNECTION: close

<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetBinaryStateResponse xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>1</BinaryState></u:GetBinaryStateResponse></s:Body></s:Envelope>
2024-03-09 14:25:13 asyncio:167      DEBUG    <Server sockets=(<asyncio.TransportSocket fd=8, family=2, type=1, proto=6, laddr=('192.168.1.200', 8454)>,)> got a new connection from ('192.168.1.111', 46812): <socket.socket fd=44, family=2, type=1, proto=6, laddr=('192.168.1.200', 8454), raddr=('192.168.1.111', 46812)>
2024-03-09 14:25:13 fauxmo:46       DEBUG    Connection made with: ('192.168.1.111', 46812)
2024-03-09 14:25:13 fauxmo:58       DEBUG    Received message:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.1.200:8454
Content-Type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#GetBinaryState"
Content-Length: 298

<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetBinaryState xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>1</BinaryState></u:GetBinaryState></s:Body></s:Envelope>
2024-03-09 14:25:13 fauxmo:69       INFO     request BasicEvent1
2024-03-09 14:25:13 fauxmo:122      DEBUG    Handling action for plugin type RESTAPIPlugin(method='POST', state_method='GET', headers={'Authorization': 'Bearer mytoken', 'Content-Type': 'application/json'}, auth=None, on_cmd='http://localhost:81/api/services/light/turn_on', off_cmd='http://localhost:81/api/services/light/turn_off', state_cmd='http://localhost:81/api/states/light.a60_smart_bulb_cct_rgb', on_data=None, off_data=None, state_data=None, on_json={'entity_id': 'light.a60_smart_bulb_cct_rgb'}, off_json={'entity_id': 'light.a60_smart_bulb_cct_rgb'}, state_json=None, state_response_on='"state":"on"', state_response_off='"state":"off"', _name='Lounge lamp', _port=8454, _latest_action='off')
2024-03-09 14:25:13 fauxmo:151      INFO     Attempting to get state for Lounge lamp
on
2024-03-09 14:25:13 fauxmo:157      INFO     Lounge lamp state: on
2024-03-09 14:25:13 fauxmo:193      DEBUG    HTTP/1.1 200 OK
CONTENT-LENGTH: 277
CONTENT-TYPE: text/xml
DATE: Sat, 09 Mar 2024 14:25:13 GMT
LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT
SERVER: Unspecified, UPnP/1.0, Unspecified
X-User-Agent: Fauxmo
CONNECTION: close

<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetBinaryStateResponse xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>1</BinaryState></u:GetBinaryStateResponse></s:Body></s:Envelope>
2024-03-09 14:25:13 asyncio:167      DEBUG    <Server sockets=(<asyncio.TransportSocket fd=13, family=2, type=1, proto=6, laddr=('192.168.1.200', 41083)>,)> got a new connection from ('192.168.1.113', 33996): <socket.socket fd=44, family=2, type=1, proto=6, laddr=('192.168.1.200', 41083), raddr=('192.168.1.113', 33996)>
2024-03-09 14:25:13 fauxmo:46       DEBUG    Connection made with: ('192.168.1.113', 33996)
2024-03-09 14:25:13 fauxmo:58       DEBUG    Received message:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.1.200:41083
Content-Type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#GetBinaryState"
Content-Length: 298

<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetBinaryState xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>1</BinaryState></u:GetBinaryState></s:Body></s:Envelope>
2024-03-09 14:25:13 fauxmo:69       INFO     request BasicEvent1
2024-03-09 14:25:13 fauxmo:122      DEBUG    Handling action for plugin type RESTAPIPlugin(method='POST', state_method='GET', headers={'Authorization': 'Bearer mytoken', 'Content-Type': 'application/json'}, auth=None, on_cmd='http://localhost:81/api/services/light/turn_on', off_cmd='http://localhost:81/api/services/light/turn_off', state_cmd='http://localhost:81/api/states/light.lumary_smart_slim_panel_light_a3_2', on_data=None, off_data=None, state_data=None, on_json={'entity_id': 'light.lumary_smart_slim_panel_light_a3_2'}, off_json={'entity_id': 'light.lumary_smart_slim_panel_light_a3_2'}, state_json=None, state_response_on='"state":"on"', state_response_off='"state":"off"', _name='Hallway door', _port=41083)
2024-03-09 14:25:13 fauxmo:151      INFO     Attempting to get state for Hallway door
off
2024-03-09 14:25:13 fauxmo:157      INFO     Hallway door state: off
2024-03-09 14:25:13 fauxmo:193      DEBUG    HTTP/1.1 200 OK
CONTENT-LENGTH: 277
CONTENT-TYPE: text/xml
DATE: Sat, 09 Mar 2024 14:25:13 GMT
LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT
SERVER: Unspecified, UPnP/1.0, Unspecified
X-User-Agent: Fauxmo
CONNECTION: close

<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetBinaryStateResponse xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>0</BinaryState></u:GetBinaryStateResponse></s:Body></s:Envelope>
2024-03-09 14:25:13 asyncio:167      DEBUG    <Server sockets=(<asyncio.TransportSocket fd=33, family=2, type=1, proto=6, laddr=('192.168.1.200', 34367)>,)> got a new connection from ('192.168.1.113', 39478): <socket.socket fd=44, family=2, type=1, proto=6, laddr=('192.168.1.200', 34367), raddr=('192.168.1.113', 39478)>
2024-03-09 14:25:13 fauxmo:46       DEBUG    Connection made with: ('192.168.1.113', 39478)
2024-03-09 14:25:13 fauxmo:58       DEBUG    Received message:
POST /upnp/control/basicevent1 HTTP/1.1
Host: 192.168.1.200:34367
Content-Type: text/xml; charset="utf-8"
SOAPACTION: "urn:Belkin:service:basicevent:1#GetBinaryState"
Content-Length: 298

<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetBinaryState xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>1</BinaryState></u:GetBinaryState></s:Body></s:Envelope>
2024-03-09 14:25:13 fauxmo:69       INFO     request BasicEvent1
2024-03-09 14:25:13 fauxmo:122      DEBUG    Handling action for plugin type RESTAPIPlugin(method='POST', state_method='GET', headers={'Authorization': 'Bearer mytoken', 'Content-Type': 'application/json'}, auth=None, on_cmd='http://localhost:81/api/services/light/turn_on', off_cmd='http://localhost:81/api/services/light/turn_off', state_cmd='http://localhost:81/api/states/light.lounge_lights_l1', on_data=None, off_data=None, state_data=None, on_json={'entity_id': 'light.lounge_lights_l1'}, off_json={'entity_id': 'light.lounge_lights_l1'}, state_json=None, state_response_on='"state":"on"', state_response_off='"state":"off"', _name='Dining room ceiling', _port=34367)
2024-03-09 14:25:13 fauxmo:151      INFO     Attempting to get state for Dining room ceiling
off
2024-03-09 14:25:13 fauxmo:157      INFO     Dining room ceiling state: off
2024-03-09 14:25:13 fauxmo:193      DEBUG    HTTP/1.1 200 OK
CONTENT-LENGTH: 277
CONTENT-TYPE: text/xml
DATE: Sat, 09 Mar 2024 14:25:13 GMT
LAST-MODIFIED: Sat, 01 Jan 2000 00:01:15 GMT
SERVER: Unspecified, UPnP/1.0, Unspecified
X-User-Agent: Fauxmo
CONNECTION: close

<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:GetBinaryStateResponse xmlns:u="urn:Belkin:service:basicevent:1"><BinaryState>0</BinaryState></u:GetBinaryStateResponse></s:Body></s:Envelope>

It might be that only this single device is misbehaving, the other ones I've tried seem to be fixed with this method.

n8henrie commented 8 months ago

Thanks for quick response.

Unfortunately that verbose log doesn't seem to include the same / similar error as above.

I'm looking for Unable to complete command, but with maybe 50 lines or so of context before and after.

skorokithakis commented 8 months ago

The lines are pasted above are the lines just before me asking Alexa to turn the device on (or off, I don't remember which) to just after Alexa said "device not responding". I'm not sure why the message has gone away, but this is definitely the full context from before I trigger it to after Alexa's response.

n8henrie commented 8 months ago

Fair enough, but without that context I'm not sure what I can do to help -- the output just before that in particular should have some relevant data that is not printed unless you're showing verbose output. Are you running as a systemd service? If so, consider changing the service file to run with verbose output and then you should be able to search the journald output for that string after a little while.

skorokithakis commented 8 months ago

I run in Docker, I can give you as much output as you like, I just figured I wouldn't spam you with irrelevants. Here's the full output, from start to finish:

In this session, I had two commands be "not responding", even though the device changed state. I think it might have something to do with the speed of the response, because this particular device uses a proprietary Tuya protocol, whereas the others (the ones that work more reliably) are Zigbee, and thus faster to respond.

n8henrie commented 8 months ago

Unfortunately that doesn't include Unable to complete command. As mentioned above -- if you can get me output with about 50 lines before and after this I think I could be more helpful.

I understand that this is not always happening when you experience the issue, but I think it's the best place to start.

n8henrie commented 7 months ago

Bump.

This issue is pending a response and is blocked until I have more info. To keep the issue list groomed, I will often close these stalled issues if they go a prolonged time without a response. In this case, I will give it another week or so.

skorokithakis commented 7 months ago

Sorry, I think the "unable to complete command" was due to misconfiguration. The output above is when it legitimately happened. I don't have access to the Alexa right now, but you can close this issue and I can reopen it when I can debug more.

n8henrie commented 7 months ago

No worries, thanks for the quick response! Feel free to ping for a reopen, happy to help.