Error XMLParseError: not well-formed (invalid token): line 9, column 26 occurred in method async_update for Denon AVR receiver

[markdstjohn]

I'm getting failures from Home Assistant that I'm pretty sure trace back to a parsing error occurring in async_get_sources_deviceinfo. This issue is sporadic and sometimes goes away when I power cycle my receiver.

Here's the relevant info from the Home Assistant log file:

2023-11-06 14:21:09.740 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Error XMLParseError: not well-formed (invalid token): line 9, column 26 occurred in method async_update for Denon AVR receiver
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/asyncstdlib/_lrucache.py", line 407, in __call__
    result = self.__cache[key]
             ~~~~~~~~~~~~^^^^^
KeyError: <asyncstdlib._lrucache.CallKey object at 0x7f5ebcefb0>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/xml/etree/ElementTree.py", line 1709, in feed
    self.parser.Parse(data, False)
xml.parsers.expat.ExpatError: not well-formed (invalid token): line 9, column 26

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/denonavr/decorators.py", line 46, in wrapper
    return await func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/denonavr/api.py", line 193, in async_get_xml
    xml_root = fromstring(res.text)
               ^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/defusedxml/common.py", line 126, in fromstring
    parser.feed(text)
  File "/usr/local/lib/python3.11/xml/etree/ElementTree.py", line 1711, in feed
    self._raiseerror(v)
  File "/usr/local/lib/python3.11/xml/etree/ElementTree.py", line 1618, in _raiseerror
    raise err
xml.etree.ElementTree.ParseError: not well-formed (invalid token): line 9, column 26

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/denonavr/media_player.py", line 181, in wrapper
    return await func(self, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/denonavr/media_player.py", line 323, in async_update
    await receiver.async_update()
  File "/usr/local/lib/python3.11/site-packages/denonavr/denonavr.py", line 183, in async_update
    await self.input.async_update(global_update=True, cache_id=cache_id)
  File "/usr/local/lib/python3.11/site-packages/denonavr/input.py", line 409, in async_update
    await self.async_update_inputfuncs(
  File "/usr/local/lib/python3.11/site-packages/denonavr/input.py", line 603, in async_update_inputfuncs
    await self._async_update_inputfuncs_avr_x(
  File "/usr/local/lib/python3.11/site-packages/denonavr/input.py", line 623, in _async_update_inputfuncs_avr_x
    receiver_sources = await self.async_get_sources_deviceinfo()
                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/denonavr/input.py", line 421, in async_get_sources_deviceinfo
    xml = await self._device.api.async_get_xml(
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/denonavr/decorators.py", line 100, in wrapper
    return await func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/asyncstdlib/_lrucache.py", line 410, in __call__
    result = await self.__wrapped__(*args, **kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/denonavr/decorators.py", line 81, in wrapper
    raise AvrInvalidResponseError(
denonavr.exceptions.AvrInvalidResponseError: XMLParseError: not well-formed (invalid token): line 9, column 26
2023-11-06 14:25:49.838 ERROR (MainThread) [homeassistant.components.denonavr.media_player] Error XMLParseError: not well-formed (invalid token): line 9, column 30 occurred in method async_update for Denon AVR receiver
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/asyncstdlib/_lrucache.py", line 407, in __call__
    result = self.__cache[key]
             ~~~~~~~~~~~~^^^^^
KeyError: <asyncstdlib._lrucache.CallKey object at 0x7f5af3c490>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/xml/etree/ElementTree.py", line 1709, in feed
    self.parser.Parse(data, False)
xml.parsers.expat.ExpatError: not well-formed (invalid token): line 9, column 30

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/denonavr/decorators.py", line 46, in wrapper
    return await func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/denonavr/api.py", line 193, in async_get_xml
    xml_root = fromstring(res.text)
               ^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/defusedxml/common.py", line 126, in fromstring
    parser.feed(text)
  File "/usr/local/lib/python3.11/xml/etree/ElementTree.py", line 1711, in feed
    self._raiseerror(v)
  File "/usr/local/lib/python3.11/xml/etree/ElementTree.py", line 1618, in _raiseerror
    raise err
xml.etree.ElementTree.ParseError: not well-formed (invalid token): line 9, column 30

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/denonavr/media_player.py", line 181, in wrapper
    return await func(self, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/denonavr/media_player.py", line 323, in async_update
    await receiver.async_update()
  File "/usr/local/lib/python3.11/site-packages/denonavr/denonavr.py", line 183, in async_update
    await self.input.async_update(global_update=True, cache_id=cache_id)
  File "/usr/local/lib/python3.11/site-packages/denonavr/input.py", line 409, in async_update
    await self.async_update_inputfuncs(
  File "/usr/local/lib/python3.11/site-packages/denonavr/input.py", line 603, in async_update_inputfuncs
    await self._async_update_inputfuncs_avr_x(
  File "/usr/local/lib/python3.11/site-packages/denonavr/input.py", line 623, in _async_update_inputfuncs_avr_x
    receiver_sources = await self.async_get_sources_deviceinfo()
                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/denonavr/input.py", line 421, in async_get_sources_deviceinfo
    xml = await self._device.api.async_get_xml(
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/denonavr/decorators.py", line 100, in wrapper
    return await func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/asyncstdlib/_lrucache.py", line 410, in __call__
    result = await self.__wrapped__(*args, **kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/denonavr/decorators.py", line 81, in wrapper
    raise AvrInvalidResponseError(
denonavr.exceptions.AvrInvalidResponseError: XMLParseError: not well-formed (invalid token): line 9, column 30
2023-11-06 14:50:28.688 ERROR (MainThread) [frontend.js.latest.202307051]

Here's what happens if I try to use the library:

>>> import asyncio
>>> import denonavr
>>> d = denonavr.DenonAVR("192.168.1.61")
>>> await d.async_setup()                                                                                                                                               
Traceback (most recent call last):                                                                                                                                              
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/anyio/_core/_tasks.py", line 115, in fail_after                                                                     
    yield cancel_scope
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpcore/_backends/anyio.py", line 114, in connect_tcp
    stream: anyio.abc.ByteStream = await anyio.connect_tcp(
                                   ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/anyio/_core/_sockets.py", line 217, in connect_tcp
    async with create_task_group() as tg:
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/anyio/_backends/_asyncio.py", line 674, in __aexit__
    raise cancelled_exc_while_waiting_tasks
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/anyio/_backends/_asyncio.py", line 654, in __aexit__
    await asyncio.wait(self.cancel_scope._tasks)
  File "/usr/lib/python3.11/asyncio/tasks.py", line 418, in wait
    return await _wait(fs, timeout, return_when, loop)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/asyncio/tasks.py", line 525, in _wait
    await waiter
asyncio.exceptions.CancelledError: Cancelled by cancel scope 7f7e86b09b10

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpcore/_exceptions.py", line 10, in map_exceptions
    yield
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpcore/_backends/anyio.py", line 113, in connect_tcp
    with anyio.fail_after(timeout):
  File "/usr/lib/python3.11/contextlib.py", line 155, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/anyio/_core/_tasks.py", line 118, in fail_after
    raise TimeoutError
TimeoutError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpx/_transports/default.py", line 66, in map_httpcore_exceptions
    yield
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpx/_transports/default.py", line 366, in handle_async_request
    resp = await self._pool.handle_async_request(req)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpcore/_async/connection_pool.py", line 268, in handle_async_request
    raise exc
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpcore/_async/connection_pool.py", line 251, in handle_async_request
    response = await connection.handle_async_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpcore/_async/connection.py", line 99, in handle_async_request
    raise exc
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpcore/_async/connection.py", line 76, in handle_async_request
    stream = await self._connect(request)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpcore/_async/connection.py", line 124, in _connect
    stream = await self._network_backend.connect_tcp(**kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpcore/_backends/auto.py", line 30, in connect_tcp
    return await self._backend.connect_tcp(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpcore/_backends/anyio.py", line 112, in connect_tcp
    with map_exceptions(exc_map):
  File "/usr/lib/python3.11/contextlib.py", line 155, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpcore/_exceptions.py", line 14, in map_exceptions
    raise to_exc(exc) from exc
httpcore.ConnectTimeout

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/denonavr/decorators.py", line 46, in wrapper
    return await func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/denonavr/api.py", line 138, in async_get
    res = await client.get(endpoint, timeout=self.timeout)
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpx/_client.py", line 1757, in get
    return await self.request(
           ^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpx/_client.py", line 1530, in request
    return await self.send(request, auth=auth, follow_redirects=follow_redirects)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpx/_client.py", line 1617, in send
    response = await self._send_handling_auth(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpx/_client.py", line 1645, in _send_handling_auth
    response = await self._send_handling_redirects(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpx/_client.py", line 1682, in _send_handling_redirects
    response = await self._send_single_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpx/_client.py", line 1719, in _send_single_request
    response = await transport.handle_async_request(request)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpx/_transports/default.py", line 365, in handle_async_request
    with map_httpcore_exceptions():
  File "/usr/lib/python3.11/contextlib.py", line 155, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/httpx/_transports/default.py", line 83, in map_httpcore_exceptions
    raise mapped_exc(message) from exc
httpx.ConnectTimeout

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/lib/python3.11/concurrent/futures/_base.py", line 456, in result
    return self.__get_result()
           ^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/concurrent/futures/_base.py", line 401, in __get_result
    raise self._exception
  File "<console>", line 1, in <module>
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/denonavr/denonavr.py", line 142, in async_setup
    await self._device.async_setup()
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/denonavr/foundation.py", line 152, in async_setup
    await self.async_get_device_info()
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/denonavr/foundation.py", line 378, in async_get_device_info
    res = await self.api.async_get(command, port=port)
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/mstjohn/denonavr/lib/python3.11/site-packages/denonavr/decorators.py", line 57, in wrapper
    raise AvrTimoutError(f"TimeoutException: {err}", err.request) from err
denonavr.exceptions.AvrTimoutError: TimeoutException:

I've confirmed that these steps work fine on a different AVR-3312CI that I have in my house.

[markdstjohn]

Interestingly enough, the problem just went away in Home Assistant, and I can now successfully run the following commands:

>>> import asyncio
>>> import denonavr
>>> d = denonavr.DenonAVR("192.168.1.61")
>>> await d.async_setup()
>>> await d.async_update()
>>> print(d.volume)
-13.5

However, this problem has been coming and going pretty much since I started using Home Assistant, and it really causes a lot of instability for me.

[ol-iver]

This is a firmware bug of your receiver. Some receivers stop serving certains endpoints every now and then. The only thing which seems to help is unplugging your receiver for a couple of seconds.