happyleavesaoc/python-snapcast

data_received sometimes receives less than complete JSON message

airdrummingfool opened this issue · 1 comments

airdrummingfool commented

Sometimes (as often as 1/4 attempts or as rare as 1/20 attempts) when I try to connect to a Snapserver using this library, I get a JSONDecodeError:

INFO:snapcast.control.server:connected to snapserver on Snapserver-Host:1705
ERROR:asyncio:Exception in callback _SelectorSocketTransport._read_ready()
handle: <Handle _SelectorSocketTransport._read_ready()>
Traceback (most recent call last):
  File "/Users/.../.pyenv/versions/3.5.3/lib/python3.5/asyncio/events.py", line 126, in _run
    self._callback(*self._args)
  File "/Users/.../.pyenv/versions/3.5.3/lib/python3.5/asyncio/selector_events.py", line 730, in _read_ready
    self._protocol.data_received(data)
  File "/Users/.../project-env/lib/python3.5/site-packages/snapcast/control/protocol.py", line 40, in data_received
    data = json.loads(cmd)
  File "/Users/.../.pyenv/versions/3.5.3/lib/python3.5/json/__init__.py", line 319, in loads
    return _default_decoder.decode(s)
  File "/Users/.../.pyenv/versions/3.5.3/lib/python3.5/json/decoder.py", line 339, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/Users/.../.pyenv/versions/3.5.3/lib/python3.5/json/decoder.py", line 355, in raw_decode
    obj, end = self.scan_once(s, idx)
json.decoder.JSONDecodeError: Unterminated string starting at: line 1 column 1448 (char 1447)
ERROR:asyncio:Exception in callback _SelectorSocketTransport._read_ready()
handle: <Handle _SelectorSocketTransport._read_ready()>
Traceback (most recent call last):
  File "/Users/.../.pyenv/versions/3.5.3/lib/python3.5/asyncio/events.py", line 126, in _run
    self._callback(*self._args)
  File "/Users/.../.pyenv/versions/3.5.3/lib/python3.5/asyncio/selector_events.py", line 730, in _read_ready
    self._protocol.data_received(data)
  File "/Users/[redacted]/-env/lib/python3.5/site-packages/snapcast/control/protocol.py", line 40, in data_received
    data = json.loads(cmd)
  File "/Users/.../.pyenv/versions/3.5.3/lib/python3.5/json/__init__.py", line 319, in loads
    return _default_decoder.decode(s)
  File "/Users/.../.pyenv/versions/3.5.3/lib/python3.5/json/decoder.py", line 339, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/Users/.../.pyenv/versions/3.5.3/lib/python3.5/json/decoder.py", line 357, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

I added some debug printing, and it appears that at times the data_received callback in protocol.py only receives a partial JSON message, which breaks the JSON parser. When this happens, the JSON message seems to get split in two, I believe in the same place every time: 1448 characters into the message. The second message (the final 1025 characters, for a total of 2473) arrive immediately after (hence the duplicate stack traces - the exception occurs twice in quick succession).

I'm not actively using Snapcast (no audio or log output) when this happens. I haven't seen this behavior outside of this library.

There's a potentially relevant warning in the Python docs for asyncio.data_received:

Note: Whether the data is buffered, chunked or reassembled depends on the transport. In general, you shouldn’t rely on specific semantics and instead make your parsing generic and flexible enough. However, data is always received in the correct order.

My thought is to decode the data in each data_received and then buffer until the decoded string ends in \r\n. Once it ends in \r\n, continue with processing. Does that seem like an acceptable approach?