search

n8henrie / fauxmo

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

UnicodeDecodeError in protocols.py #7

Closed n8henrie closed 8 years ago

n8henrie commented 8 years ago

Migrating @acidbath's issue from #5. Getting UnicodeDecodeError even running on wget-ed config-sample.json (which runs without error for me).

  File "/opt/pyenv/versions/3.5.1/lib/python3.5/site-packages/fauxmo/protocols.py", line 150, in datagram_received
    msg = data.decode()
UnicodeDecodeError: 'utf-8' codec can't decode byte 0xa0 in position 389: invalid start byte

WHYT

pi@mqtt-pi:~ $ locale -a
C
C.UTF-8
de_DE.utf8
en_GB.utf8
POSIX
pi@mqtt-pi:~/fauxmo $ file config-sample.json 
config-sample.json: ASCII text

Thinking this may have something to do with his locale being different?

Luckily the most recent debug log (the one I used above) shows where the error is occurring (and is still occurring despite a major rewrite between 0.2.0 and 0.3.0): the msg = data.decode() in datagram_received() in SSDPServer, currently line 150 of protocols.py.

@acidbath -- AFAIK the Echo only supports English -- is that correct?

I think the next step will be to look at the actual TCP stream if you're up for it -- I'll verify the commands and post them here in the next day or two for whenever you have time.

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

n8henrie commented 8 years ago

I just had another thought -- are you sure that this is occurring only when the Echo is searching for new devices? I wonder if there could be another device on your network that is tripping up Fauxmo -- not terribly unlikely with the way things are set up.

If you start and run Fauxmo without having the Echo search for devices do you also get the error? (The Echo seems to automatically search for devices every half hour or so, so if you get the error after a half hour of waiting that doesn't count.)

If you start and run Fauxmo and wait say 30 seconds, then have the Echo search for devices, do you then immediately get the error?

n8henrie commented 8 years ago

Can you try this debug build? It should catch the error and print out the data that's tripping things up to give us a better idea what's going on. Further, it should drop you into pdb on hitting the error so you can inspect the local variables if desired. If you haven't used PDB before, I highly recommend you check it out. Interface is a little weird at first, but an extremely helpful part of the Python standard library for debugging these tricky issues.

fauxmo-031-debug.tar.gz

You should be able to install this debug build into a virtualenv like so, assuing python3 points to Python 3.5:

# Create a venv
python3 -m venv venv

# Download the build:
wget https://github.com/n8henrie/fauxmo/files/220387/fauxmo-031-debug.tar.gz

# Activate the venv
source venv/bin/activate

# Install into activated venv
pip install fauxmo-031-debug.tar.gz

# Run venv build, ensure it reports Fauxmo 0.3.1 at the top
fauxmo -c /path/to/config.json -vvv

After that, as soon as it gets the UnicodeDecodeError, you should see it print out the byte message causing the error, like so (in this case the problem being b'\xa0\n'):

--------------------------------------------------------------------------------
Error decoding data below:
2016-04-14 23:23:13 fauxmo:155      WARNING  b'\xa0\n'
2016-04-14 23:23:13 fauxmo:156      WARNING  
--------------------------------------------------------------------------------

Afterwards, you should see a prompt with (Pdb). This is basically the Fauxmo code paused at the location of the error. You can for example type the name of the variable data and it should show you the same value as above (e.g. b'\xa0\n'). Further, you can enter data.decode() and see that it raises UnicodeDecodeErrror -- or you can even import modules, or use it basically like an interactive Python interpreter to explore what's going on when you're experiencing a bug.

For the record, all I did for this build was to change data.decode() to:

try:
    data.decode()
except UnicodeDecodeError:
    logger.warning(... log some stuff here .... )
    import pdb; pdb.set_trace()
acidbath commented 8 years ago

I'll definitely look into it - but I'm off for work again and won't see home any earlier than next Tuesday.

n8henrie commented 8 years ago

No worries, safe travels.

n8henrie commented 8 years ago

I think the build above may help us get a better idea what's causing the error, and this build may fix it.

Whenever you get back in town, give a shot to the debug build above to see if it sheds some light on the issue, and afterwards try installing and running this build, which I think might solve the error.

fauxmo-0.3.1.tar.gz

n8henrie commented 8 years ago

I've pushed a couple of changes to the dev branch that I'm pretty excited about, including the commits from this issue, as well as changes to restore compatibility with Python 3.4.2 -- so you don't necessarily need pyenv anymore, the default Jessie Python3 should work again.

You should be able to test it out directly from GitHub: pip install git+https://github.com/n8henrie/fauxmo.git@dev

acidbath commented 8 years ago

Hello again.

My two free days are extremely busy, so I hardly have any time tinkering around with the raspi.

I gave version 3.4.2 a try and the utf-8 error seems to be fixed!

Yet echo - and that's the strange thing - won't find any devices anymore?!

Here's the debug output:

2016-04-21 14:29:24 fauxmo:19       INFO     Fauxmo version 0.3.2
2016-04-21 14:29:24 fauxmo:39       DEBUG    3.4.2 (default, Oct 19 2014, 13:31:11) 
[GCC 4.9.1]
2016-04-21 14:29:24 fauxmo:16       DEBUG    Attempting to get IP address automatically
2016-04-21 14:29:24 fauxmo:29       DEBUG    Using IP address: 192.168.27.247
2016-04-21 14:29:24 asyncio:778      INFO     <Server sockets=[<socket.socket fd=8, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12345)>]> is serving
2016-04-21 14:29:24 fauxmo:81       DEBUG    {'name': 'living room ceiling', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x76510570>}
2016-04-21 14:29:24 asyncio:778      INFO     <Server sockets=[<socket.socket fd=9, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12346)>]> is serving
2016-04-21 14:29:24 fauxmo:81       DEBUG    {'name': 'living room wall', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x76510510>}
2016-04-21 14:29:25 asyncio:778      INFO     <Server sockets=[<socket.socket fd=10, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12347)>]> is serving
2016-04-21 14:29:25 fauxmo:81       DEBUG    {'name': 'front office', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x761301f0>}
2016-04-21 14:29:25 asyncio:778      INFO     <Server sockets=[<socket.socket fd=11, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12348)>]> is serving
2016-04-21 14:29:25 fauxmo:81       DEBUG    {'name': 'rear office', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x76130310>}
2016-04-21 14:29:25 asyncio:778      INFO     <Server sockets=[<socket.socket fd=12, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12349)>]> is serving
2016-04-21 14:29:25 fauxmo:81       DEBUG    {'name': 'pantry', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x761303b0>}
2016-04-21 14:29:25 asyncio:778      INFO     <Server sockets=[<socket.socket fd=13, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12350)>]> is serving
2016-04-21 14:29:25 fauxmo:81       DEBUG    {'name': 'laundry', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x76130450>}
2016-04-21 14:29:25 asyncio:778      INFO     <Server sockets=[<socket.socket fd=14, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12351)>]> is serving
2016-04-21 14:29:25 fauxmo:81       DEBUG    {'name': 'kitchen', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x76130530>}
2016-04-21 14:29:25 asyncio:778      INFO     <Server sockets=[<socket.socket fd=15, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12352)>]> is serving
2016-04-21 14:29:25 fauxmo:81       DEBUG    {'name': 'entrance', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x761305d0>}
2016-04-21 14:29:25 asyncio:778      INFO     <Server sockets=[<socket.socket fd=16, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12353)>]> is serving
2016-04-21 14:29:25 fauxmo:81       DEBUG    {'name': 'bathroom ceiling', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x76130650>}
2016-04-21 14:29:25 asyncio:778      INFO     <Server sockets=[<socket.socket fd=17, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12354)>]> is serving
2016-04-21 14:29:25 fauxmo:81       DEBUG    {'name': 'bathroom wall', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x76130690>}
2016-04-21 14:29:25 asyncio:778      INFO     <Server sockets=[<socket.socket fd=18, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12355)>]> is serving
2016-04-21 14:29:25 fauxmo:81       DEBUG    {'name': 'dressing room', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x761306d0>}
2016-04-21 14:29:25 asyncio:778      INFO     <Server sockets=[<socket.socket fd=19, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12356)>]> is serving
2016-04-21 14:29:25 fauxmo:81       DEBUG    {'name': 'hallway', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x76130710>}
2016-04-21 14:29:25 asyncio:778      INFO     <Server sockets=[<socket.socket fd=20, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12357)>]> is serving
2016-04-21 14:29:25 fauxmo:81       DEBUG    {'name': 'bedroom', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x76130750>}
2016-04-21 14:29:25 asyncio:778      INFO     <Server sockets=[<socket.socket fd=21, family=AddressFamily.AF_INET, type=2049, proto=6, laddr=('192.168.27.247', 12358)>]> is serving
2016-04-21 14:29:25 fauxmo:81       DEBUG    {'name': 'fake tv', 'action_handler': <fauxmo.handlers.rest.RESTAPIHandler object at 0x76130790>}
2016-04-21 14:29:25 fauxmo:107      INFO     Starting UDP server
2016-04-21 14:29:25 asyncio:689      INFO     Datagram endpoint local_addr=('0.0.0.0', 1900) remote_addr=None created: (<_SelectorDatagramTransport fd=22 read=polling write=<idle, bufsize=0>>, <fauxmo.protocols.SSDPServer object at 0x7619ef30>)
2016-04-21 14:29:28 asyncio:1039     INFO     poll took 3732.639 ms: 1 events
2016-04-21 14:29:28 fauxmo:159      DEBUG    Received data below from ('192.168.27.212', 32768):
2016-04-21 14:29:28 fauxmo:160      DEBUG    b'NOTIFY * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nCACHE-CONTROL: max-age = 1800\r\nLOCATION: http://192.168.27.212:1400/xml/device_description.xml\r\nNT: uuid:RINCON_000E581C64B201400\r\nNTS: ssdp:alive\r\nSERVER: Linux UPnP/1.0 Sonos/31.9-26010 (BR100)\r\nUSN: uuid:RINCON_000E581C64B201400\r\nX-RINCON-HOUSEHOLD: Sonos_p98hrm3iLtaA98CFNfpYf9Wfu2\r\nX-RINCON-BOOTSEQ: 16\r\nX-RINCON-WIFIMODE: 0\r\n\r\n'
2016-04-21 14:29:29 fauxmo:159      DEBUG    Received data below from ('192.168.27.212', 32768):
2016-04-21 14:29:29 fauxmo:160      DEBUG    b'NOTIFY * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nCACHE-CONTROL: max-age = 1800\r\nLOCATION: http://192.168.27.212:1400/xml/device_description.xml\r\nNT: urn:schemas-upnp-org:device:ZonePlayer:1\r\nNTS: ssdp:alive\r\nSERVER: Linux UPnP/1.0 Sonos/31.9-26010 (BR100)\r\nUSN: uuid:RINCON_000E581C64B201400::urn:schemas-upnp-org:device:ZonePlayer:1\r\nX-RINCON-HOUSEHOLD: Sonos_p98hrm3iLtaA98CFNfpYf9Wfu2\r\nX-RINCON-BOOTSEQ: 16\r\nX-RINCON-WIFIMODE: 0\r\n\r\n'
2016-04-21 14:29:29 fauxmo:159      DEBUG    Received data below from ('192.168.27.212', 32768):
2016-04-21 14:29:29 fauxmo:160      DEBUG    b'NOTIFY * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nCACHE-CONTROL: max-age = 1800\r\nLOCATION: http://192.168.27.212:1400/xml/device_description.xml\r\nNT: upnp:rootdevice\r\nNTS: ssdp:alive\r\nSERVER: Linux UPnP/1.0 Sonos/31.9-26010 (BR100)\r\nUSN: uuid:RINCON_000E581C64B201400::upnp:rootdevice\r\nX-RINCON-HOUSEHOLD: Sonos_p98hrm3iLtaA98CFNfpYf9Wfu2\r\nX-RINCON-BOOTSEQ: 16\r\nX-RINCON-WIFIMODE: 0\r\n\r\n'
2016-04-21 14:29:46 asyncio:1039     INFO     poll took 17200.901 ms: 1 events
2016-04-21 14:29:46 fauxmo:159      DEBUG    Received data below from ('192.168.27.61', 56611):
2016-04-21 14:29:46 fauxmo:160      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.4.11\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2016-04-21 14:29:46 fauxmo:159      DEBUG    Received data below from ('192.168.27.61', 56611):
2016-04-21 14:29:46 fauxmo:160      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.4.11\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'
2016-04-21 14:29:48 asyncio:1039     INFO     poll took 2233.599 ms: 1 events
2016-04-21 14:29:48 fauxmo:159      DEBUG    Received data below from ('192.168.27.210', 44803):
2016-04-21 14:29:48 fauxmo:160      DEBUG    b'NOTIFY * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nCACHE-CONTROL: max-age = 1800\r\nLOCATION: http://192.168.27.210:1400/xml/device_description.xml\r\nNT: uuid:RINCON_000E58C4BDD001400\r\nNTS: ssdp:alive\r\nSERVER: Linux UPnP/1.0 Sonos/31.9-26010 (ZPS1)\r\nUSN: uuid:RINCON_000E58C4BDD001400\r\nX-RINCON-HOUSEHOLD: Sonos_p98hrm3iLtaA98CFNfpYf9Wfu2\r\nX-RINCON-BOOTSEQ: 161\r\nX-RINCON-WIFIMODE: 0\r\n\r\n'
2016-04-21 14:29:49 fauxmo:159      DEBUG    Received data below from ('192.168.27.210', 44803):
2016-04-21 14:29:49 fauxmo:160      DEBUG    b'NOTIFY * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nCACHE-CONTROL: max-age = 1800\r\nLOCATION: http://192.168.27.210:1400/xml/device_description.xml\r\nNT: urn:schemas-upnp-org:device:ZonePlayer:1\r\nNTS: ssdp:alive\r\nSERVER: Linux UPnP/1.0 Sonos/31.9-26010 (ZPS1)\r\nUSN: uuid:RINCON_000E58C4BDD001400::urn:schemas-upnp-org:device:ZonePlayer:1\r\nX-RINCON-HOUSEHOLD: Sonos_p98hrm3iLtaA98CFNfpYf9Wfu2\r\nX-RINCON-BOOTSEQ: 161\r\nX-RINCON-WIFIMODE: 0\r\n\r\n'
2016-04-21 14:29:49 fauxmo:159      DEBUG    Received data below from ('192.168.27.210', 44803):
2016-04-21 14:29:49 fauxmo:160      DEBUG    b'NOTIFY * HTTP/1.1\r\nHOST: 239.255.255.250:1900\r\nCACHE-CONTROL: max-age = 1800\r\nLOCATION: http://192.168.27.210:1400/xml/device_description.xml\r\nNT: upnp:rootdevice\r\nNTS: ssdp:alive\r\nSERVER: Linux UPnP/1.0 Sonos/31.9-26010 (ZPS1)\r\nUSN: uuid:RINCON_000E58C4BDD001400::upnp:rootdevice\r\nX-RINCON-HOUSEHOLD: Sonos_p98hrm3iLtaA98CFNfpYf9Wfu2\r\nX-RINCON-BOOTSEQ: 161\r\nX-RINCON-WIFIMODE: 0\r\n\r\n'
2016-04-21 14:30:21 asyncio:1039     INFO     poll took 32185.597 ms: 1 events
2016-04-21 14:30:21 fauxmo:159      DEBUG    Received data below from ('192.168.27.202', 50076):
2016-04-21 14:30:21 fauxmo:160      DEBUG    b'M-SEARCH * HTTP/1.1\r\nMX: 1\r\nST: upnp:rootdevice\r\nMAN: "ssdp:discover"\r\nUser-Agent: UPnP/1.0 DLNADOC/1.50 Platinum/1.0.4.11\r\nHost: 239.255.255.250:1900\r\nConnection: close\r\n\r\n'

I've tried

echo -e "M-SEARCH\r\nurn:Belkin:device:**" | nc.traditional -u 239.255.255.250 1900

and it triggers an immediate reaction:

2016-04-21 14:40:02 fauxmo:159      DEBUG    Received data below from ('192.168.27.247', 37536):
2016-04-21 14:40:02 fauxmo:160      DEBUG    b'M-SEARCH\r\nurn:Belkin:device:**\n'

Starting tomorrow I'll be gone 5 days this time - so again I have to appologize for my delayed answers. Work is pretty annoying when it comes to living in a hotel half the month. :-/

acidbath commented 8 years ago

Oh, and what I forgot: yes, Echo only supports English. For the moment it's only sold in the US from what I've heard. Maybe the Sonos devices send some utf-8 encoded strings?! One of the sonos speakers is located in the "Küche" (which means kitchen) - maybe that triggerd the encoding error in the past?!

n8henrie commented 8 years ago

Great that the UTF8 bug is gone -- I'll close this issue and re-open the other one then. Yes, I imagine there is some other device broadcasting that Fauxmo was picking up and choking on. Thanks for your help resolving this.