search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
70.92k stars 29.58k forks source link

ERROR (MainThread) [aiohttp.server] Error handling request #121638

Open DBorello opened 1 month ago

DBorello commented 1 month ago

The problem

My instance recently developed a repeating python exception. It is persistent even in safe mode:

I am happy to help debug. 

2024-07-09 19:29:22.784 ERROR (MainThread) [aiohttp.server] Error handling request
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/aiohttp/web_protocol.py", line 452, in _handle_request
    resp = await request_handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aiohttp/web_app.py", line 543, in _handle
    resp = await handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/soco/events_asyncio.py", line 138, in notify
    variables = parse_event_xml(content)
                ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/soco/events_base.py", line 104, in parse_event_xml
    value = from_didl_string(value)[0]
            ^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/soco/data_structures_entry.py", line 31, in from_didl_string
    root = XML.fromstring(string.encode("utf-8"))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/xml/etree/ElementTree.py", line 1335, in XML
    parser.feed(text)
xml.etree.ElementTree.ParseError: not well-formed (invalid token): line 1, column 372

What version of Home Assistant Core has the issue?

core-2024.7.1

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

No response

Link to integration documentation on our website

No response

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

DBorello commented 1 month ago

This appears to be caused by a Sonos speaker being in "line in" mode. Changing modes stops the error.

DBorello commented 1 month ago

The event that causes the exception:

<e:propertyset xmlns:e="urn:schemas-upnp-org:event-1-0"><e:property><LastChange>&lt;Event xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/AVT/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot;&gt;&lt;InstanceID val=&quot;0&quot;&gt;&lt;TransportState val=&quot;PLAYING&quot;/&gt;&lt;CurrentPlayMode val=&quot;NORMAL&quot;/&gt;&lt;CurrentCrossfadeMode val=&quot;0&quot;/&gt;&lt;NumberOfTracks val=&quot;1&quot;/&gt;&lt;CurrentTrack val=&quot;1&quot;/&gt;&lt;CurrentSection val=&quot;0&quot;/&gt;&lt;CurrentTrackURI val=&quot;x-rincon-stream:RINCON_949F3E5352EC01400&quot;/&gt;&lt;CurrentTrackDuration val=&quot;&quot;/&gt;&lt;CurrentTrackMetaData val=&quot;&amp;lt;DIDL-Lite xmlns:dc=&amp;quot;http://purl.org/dc/elements/1.1/&amp;quot; xmlns:upnp=&amp;quot;urn:schemas-upnp-org:metadata-1-0/upnp/&amp;quot; xmlns:r=&amp;quot;urn:schemas-rinconnetworks-com:metadata-1-0/&amp;quot; xmlns=&amp;quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&amp;quot;&amp;gt;&amp;lt;item id=&amp;quot;-1&amp;quot; parentID=&amp;quot;-1&amp;quot; restricted=&amp;quot;true&amp;quot;&amp;gt;&amp;lt;res protocolInfo=&amp;quot;x-rincon-stream:*:*:*&amp;quot;&amp;gt;x-rincon-stream:RINCON_949F3E5352EC01400&amp;lt;/res&amp;gt;&amp;lt;r:audioInputIcon&amp;gt;AudioComponent&amp;lt;/r:audioInputIcon&amp;gt;&amp;lt;dc:title&amp;gt;Audio Component&amp;lt;/dc:title&amp;gt;&amp;lt;upnp:class&amp;gt;object.item&amp;lt;/upnp:class&amp;gt;&amp;lt;r:episodeNumber&amp;gt;0&amp;lt;/r:episodeNumber&amp;gt;&amp;lt;/item&amp;gt;&amp;lt;/DIDL-Lite&amp;gt;&quot;/&gt;&lt;r:NextTrackURI val=&quot;&quot;/&gt;&lt;r:NextTrackMetaData val=&quot;&quot;/&gt;&lt;r:EnqueuedTransportURI val=&quot;&quot;/&gt;&lt;r:EnqueuedTransportURIMetaData val=&quot;&quot;/&gt;&lt;PlaybackStorageMedium val=&quot;NETWORK&quot;/&gt;&lt;AVTransportURI val=&quot;x-rincon-stream:RINCON_949F3E5352EC01400&quot;/&gt;&lt;AVTransportURIMetaData val=&quot;&amp;lt;DIDL-Lite xmlns:dc=&amp;quot;http://purl.org/dc/elements/1.1/&amp;quot; xmlns:upnp=&amp;quot;urn:schemas-upnp-org:metadata-1-0/upnp/&amp;quot; xmlns:r=&amp;quot;urn:schemas-rinconnetworks-com:metadata-1-0/&amp;quot; xmlns=&amp;quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&amp;quot;&amp;gt;&amp;lt;item id=&amp;quot;playback&amp;quot; parentID=&amp;quot;0&amp;quot; restricted=&amp;quot;false&amp;quot;&amp;gt;&amp;lt;dc:title&amp;gt;loadLineIn&amp;lt;/dc:title&amp;gt;&amp;lt;upnp:class&amp;gt;object.item.audioItem.linein&amp;lt;/upnp:class&amp;gt;&amp;lt;res x-rincon-stream&amp;gt;x-rincon-stream:RINCON_949F3E5352EC01400&amp;lt;/res&amp;gt;&amp;lt;/item&amp;gt;&amp;lt;/DIDL-Lite&amp;gt;&quot;/&gt;&lt;NextAVTransportURI val=&quot;&quot;/&gt;&lt;NextAVTransportURIMetaData val=&quot;&quot;/&gt;&lt;CurrentTransportActions val=&quot;Set, Stop, Play&quot;/&gt;&lt;r:CurrentValidPlayModes val=&quot;&quot;/&gt;&lt;r:DirectControlClientID val=&quot;&quot;/&gt;&lt;r:DirectControlIsSuspended val=&quot;0&quot;/&gt;&lt;r:DirectControlAccountID val=&quot;&quot;/&gt;&lt;TransportStatus val=&quot;OK&quot;/&gt;&lt;r:SleepTimerGeneration val=&quot;0&quot;/&gt;&lt;r:AlarmRunning val=&quot;0&quot;/&gt;&lt;r:SnoozeRunning val=&quot;0&quot;/&gt;&lt;r:RestartPending val=&quot;0&quot;/&gt;&lt;TransportPlaySpeed val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;CurrentMediaDuration val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;RecordStorageMedium val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;PossiblePlaybackStorageMedia val=&quot;NONE, NETWORK&quot;/&gt;&lt;PossibleRecordStorageMedia val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;RecordMediumWriteStatus val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;CurrentRecordQualityMode val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;PossibleRecordQualityModes val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;/InstanceID&gt;&lt;/Event&gt;</LastChange></e:property></e:propertyset>

home-assistant[bot] commented 1 month ago

Hey there @jjlawren, @peterager, mind taking a look at this issue as it has been labeled with an integration (sonos) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `sonos` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign sonos` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

(message by CodeOwnersMention)

sonos documentation sonos source (message by IssueLinks)

PeteRager commented 1 month ago

Did this ever work ok? If so what version?

Any network stuff we should be aware of? Proxies. VPNS.

DBorello commented 1 month ago

I didn’t try on an earlier version.

No other network funny business.

The good news is that it is easy to reproduce.

On Wed, Jul 10, 2024 at 07:29 Pete Sage @.***> wrote:

Did this ever work ok? If so what version?

Any network stuff we should be aware of? Proxies. VPNS.

— Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/121638#issuecomment-2220389208, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAHCVOTMOLAD5TMWZ77DVJLZLUSK5AVCNFSM6AAAAABKT25T4WVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDEMRQGM4DSMRQHA . You are receiving this because you authored the thread.Message ID: @.***>

 -

PeteRager commented 1 month ago

Based on the exception log, it looks like the Sonos speaker is sending invalid XML and the parsing fails. That really should not be happening. Try power cycling that speaker and restarting HA to see if it resolves. Also check to see if Sonos updates are available.

None of my speakers have a line in, so I can't test. I will take a look at the message to see why it isn't parsing.

DBorello commented 1 month ago

I agree that the speaker appears to be sending invalid XML which is odd.

There aren't any Sonos updates available. I restarted the speaker and home assistant, same error.

The source name is "line-in". I wonder if the "-" isn't being properly escaped.

DBorello commented 1 month ago

Source as line-in:

<e:propertyset xmlns:e="urn:schemas-upnp-org:event-1-0"><e:property><LastChange>&lt;Event xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/AVT/&quot; xmlns:r=&quot;urn:schemas-rinconnetworks-com:metadata-1-0/&quot;&gt;&lt;InstanceID val=&quot;0&quot;&gt;&lt;TransportState val=&quot;PLAYING&quot;/&gt;&lt;CurrentPlayMode val=&quot;NORMAL&quot;/&gt;&lt;CurrentCrossfadeMode val=&quot;0&quot;/&gt;&lt;NumberOfTracks val=&quot;1&quot;/&gt;&lt;CurrentTrack val=&quot;1&quot;/&gt;&lt;CurrentSection val=&quot;0&quot;/&gt;&lt;CurrentTrackURI val=&quot;x-rincon-stream:RINCON_949F3E5352EC01400&quot;/&gt;&lt;CurrentTrackDuration val=&quot;&quot;/&gt;&lt;CurrentTrackMetaData val=&quot;&amp;lt;DIDL-Lite xmlns:dc=&amp;quot;http://purl.org/dc/elements/1.1/&amp;quot; xmlns:upnp=&amp;quot;urn:schemas-upnp-org:metadata-1-0/upnp/&amp;quot; xmlns:r=&amp;quot;urn:schemas-rinconnetworks-com:metadata-1-0/&amp;quot; xmlns=&amp;quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&amp;quot;&amp;gt;&amp;lt;item id=&amp;quot;-1&amp;quot; parentID=&amp;quot;-1&amp;quot; restricted=&amp;quot;true&amp;quot;&amp;gt;&amp;lt;res protocolInfo=&amp;quot;x-rincon-stream:*:*:*&amp;quot;&amp;gt;x-rincon-stream:RINCON_949F3E5352EC01400&amp;lt;/res&amp;gt;&amp;lt;r:audioInputIcon&amp;gt;AudioComponent&amp;lt;/r:audioInputIcon&amp;gt;&amp;lt;dc:title&amp;gt;Audio Component&amp;lt;/dc:title&amp;gt;&amp;lt;upnp:class&amp;gt;object.item&amp;lt;/upnp:class&amp;gt;&amp;lt;r:episodeNumber&amp;gt;0&amp;lt;/r:episodeNumber&amp;gt;&amp;lt;/item&amp;gt;&amp;lt;/DIDL-Lite&amp;gt;&quot;/&gt;&lt;r:NextTrackURI val=&quot;&quot;/&gt;&lt;r:NextTrackMetaData val=&quot;&quot;/&gt;&lt;r:EnqueuedTransportURI val=&quot;&quot;/&gt;&lt;r:EnqueuedTransportURIMetaData val=&quot;&quot;/&gt;&lt;PlaybackStorageMedium val=&quot;NETWORK&quot;/&gt;&lt;AVTransportURI val=&quot;x-rincon-stream:RINCON_949F3E5352EC01400&quot;/&gt;&lt;AVTransportURIMetaData val=&quot;&amp;lt;DIDL-Lite xmlns:dc=&amp;quot;http://purl.org/dc/elements/1.1/&amp;quot; xmlns:upnp=&amp;quot;urn:schemas-upnp-org:metadata-1-0/upnp/&amp;quot; xmlns:r=&amp;quot;urn:schemas-rinconnetworks-com:metadata-1-0/&amp;quot; xmlns=&amp;quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&amp;quot;&amp;gt;&amp;lt;item id=&amp;quot;playback&amp;quot; parentID=&amp;quot;0&amp;quot; restricted=&amp;quot;false&amp;quot;&amp;gt;&amp;lt;dc:title&amp;gt;loadLineIn&amp;lt;/dc:title&amp;gt;&amp;lt;upnp:class&amp;gt;object.item.audioItem.linein&amp;lt;/upnp:class&amp;gt;&amp;lt;res x-rincon-stream&amp;gt;x-rincon-stream:RINCON_949F3E5352EC01400&amp;lt;/res&amp;gt;&amp;lt;/item&amp;gt;&amp;lt;/DIDL-Lite&amp;gt;&quot;/&gt;&lt;NextAVTransportURI val=&quot;&quot;/&gt;&lt;NextAVTransportURIMetaData val=&quot;&quot;/&gt;&lt;CurrentTransportActions val=&quot;Set, Stop, Play&quot;/&gt;&lt;r:CurrentValidPlayModes val=&quot;&quot;/&gt;&lt;r:DirectControlClientID val=&quot;&quot;/&gt;&lt;r:DirectControlIsSuspended val=&quot;0&quot;/&gt;&lt;r:DirectControlAccountID val=&quot;&quot;/&gt;&lt;TransportStatus val=&quot;OK&quot;/&gt;&lt;r:SleepTimerGeneration val=&quot;0&quot;/&gt;&lt;r:AlarmRunning val=&quot;0&quot;/&gt;&lt;r:SnoozeRunning val=&quot;0&quot;/&gt;&lt;r:RestartPending val=&quot;0&quot;/&gt;&lt;TransportPlaySpeed val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;CurrentMediaDuration val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;RecordStorageMedium val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;PossiblePlaybackStorageMedia val=&quot;NONE, NETWORK&quot;/&gt;&lt;PossibleRecordStorageMedia val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;RecordMediumWriteStatus val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;CurrentRecordQualityMode val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;PossibleRecordQualityModes val=&quot;NOT_IMPLEMENTED&quot;/&gt;&lt;/InstanceID&gt;&lt;/Event&gt;</LastChange></e:property></e:propertyset>

Source as spotify:

<e:propertyset xmlns:e="urn:schemas-upnp-org:event-1-0"><e:property><ThirdPartyMediaServersX>2:8Yf/tlNYiimpaVAY2aVCUORNZ6sm6v2pGxMbdQEecaJXm6Tr8g5az8p9ny6FR9Du3ofi0QSNZWsZXqQFzZq/hz1Jjy0mPkgNKhI63DU7OvC4PBlUF4FzaTxAUv02MkW6AWGXW8FDcrTB4k05slU2UQ5YMXGK00keK1/F220OkTJ4Hgbx2qV1dsGMjtMouCWi68fH9rx6/iP21WpyRp33W9vU81E01mc2i4WcLefbpr8ryMhSsUEqTGt/nJ59XAAYs4ytS6+OWf/equVDqhUMzQ0EHdne2g34VgFfIanPwRDtIRH7kZ1UysiQ8+VGt+mOOdrsiXEmQesyT1bO3Es9CPR3pqfzRPh5HN06aZkPJsdfz0LQu86L+MlYHrgOHWQw1TmME72v7ETgHe8OhSxHdVTFylfyMxeJL8r/SFHY9GmBGsG3LMiX+q319/BUcQOXck3YjCcYu4osSt5TgLCpmlHv1ANUPB9j3AdOjh04xGfJ8sG94iPR9xQzZjxHKkw2EJsB8J6o0/J+3JALEZLWmeVsPiI4N6+65bl3DP0R1W3cN+OO7KK2wChuxnvQ+LWx8+MDvIPvZ5MNbMHh97r+iTxFOFPppRSNlRQxNUP7RBX/HYcMj1JAZVvYKTv7lVgTw7TsbbdaBp1MtcG0MvuGGgX3TFLzJlVMwavE1l8bViliRO3vhwp/5X6E9Ah5WgWJbGdKltikjwamtut3kDtYRuJ5BDrErweob5x84/p/SZKcKDBUZ7S+09YvoeRCcSkvkA9J4YN6cVJxmvDhdRdE/5pQlRxExqaZzax1FpINHSSX/0ZbN05G9kq6YecqCng9xtmN9JaUMh2vcEVgQaIXnhcWXlAYFlGvPzji90oPNy5Bb4JyCDW9Ho1Pee4AWLxMGv7J8vow6sam/vBM3r8h1O6nM2UomqYwuKkUTX8dP3JADU2I9LBTYjw95H/XIuQjXau+fuKDuq0coLkqD8UXIeX6+7odN8/6l//OUoDqaPt+DBk9R9vXeauKICNKMD9laY1M4PaBnDCzVbPAysHM2dA0lMwAngpu+nEAsfaWcy2UHRoyd+Vb0Nh2V3oisGkYy3Qy9uo/zlPteM8Yj0N+P/JWB74f28RLkmMcBxMtlnhL0lVgn4QZN1rNxc1EQmoSV59LhgRk/Afdedp9PwnGgUFmrpxLXHssPSPeStf1hWE8L56XsVZSUnEU1Huwp6k5CWXYWK2RCnG8xlp3ueT0fIqMKEcHcfi+2WWpp4UshAl9sMs1qu+7XOxDwt5nNgHp3w4kMvVu/t9QR80ATj9JErW2n0sB4dfNwVpBAjMafmn9Jgue4cm/SHINd/PoDP83oZxLun7mxwuUAcqcPFzJ8tYJU9meYO2ywtS8oDvFMhwwTyUrQFeAbsdudtH1we8Fnn5fjSOBQvt+t9nhqQWmu+MRi/ME/p6sydB7dufx//gfh7Dkcq1RZ/8sxFfSheX6fsVRdKepuvWSbQIBxegrqWSmWphR51eLMPGY/ZYag6POhcCyM0QTtHkRp2KM/sfCjXZIFlHaYfUA5rtI3S46EUdYr5y/bSCpam95sLCNPoQXlAmGradmrwlmMK2oqm5XEghIsThiNFg3vHUHWYICzZJAiKsgBhMQlykVVdcrBVoQtebJ7QVwD4DJboHxW1pdyOaGjaPjUaxdUkFSv2FIDq3tizNJnvKvF9T3V0xf9uV0TiMbG+FkmRax0+6DWaHjrB0PiYITbRFMCb71oORQLv7inqggR0i3JHdy0uOUvUvoS0QlSmmoIJDxnp2GunNq3SzL8x/R2mI2ovmo7XzddciMbnwD0tsrgJn30ukH6qzCGPY2LmzkdT+rIrP2qDv+0hUIexKtzzlDnKu6I6Xq/FJjsppThx4OFMrCscRM0fS3emsff5brUOFz6vHA09lOYi78SJmCVHHcIgwAHAJIRf8BQ9EsRhnK02gD/y7eGW46/hjdi196/8g9MKn3PSOwQGJs4sjKiJV3HddDaf8JpVDY5OLCSGM79XcsFTjBYga1wt8NJw0tdlNllJlVuuNaximxtLPNQpHkIuc4B1eNEEoxWN3Fv2RXmAw+zH7UNi9lHMURBX4QUQW1i/LuDg56O8pl7ampItqSjRJ2OQvSHAgadT7LG30G6ak6h1210XDiL3/MA0P4VqtdRj6bKrN+HIeIExrOmM7AuhM4Kf1V7Jd9jMTJ/louT8/WPJ8AW+I=</ThirdPartyMediaServersX></e:property></e:propertyset>

PeteRager commented 1 month ago

With further work I'm able to generate the same error in the SoCo library using a test fixture. There is embedded XML within the XML and it is the parsing of this subelement:

<DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/"
    xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/"
    xmlns:r="urn:schemas-rinconnetworks-com:metadata-1-0/"
    xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/">
    <item id="playback" parentID="0" restricted="false">
        <dc:title>loadLineIn</dc:title>
        <upnp:class>object.item.audioItem.linein</upnp:class>
        <res x-rincon-stream>x-rincon-stream:RINCON_949F3E5352EC01400</res></item></DIDL-Lite>

"res x-rincon-stream" is not a valid XML tag.

PeteRager commented 1 month ago

This appears to be an issue upstream in the SoCo library and have submitted an issue there

https://github.com/SoCo/SoCo/issues/964

DBorello commented 1 month ago

I am glad you were able to reproduce the issue. Thanks for pushing this upstream.

On Sat, Jul 13, 2024 at 08:15 Pete Sage @.***> wrote:

This appears to be an issue upstream in the SoCo library and have submitted an issue there

SoCo/SoCo#964 https://github.com/SoCo/SoCo/issues/964

— Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/121638#issuecomment-2226880366, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAHCVOXFMERCUJ7ZV4T4IVDZMEK4RAVCNFSM6AAAAABKT25T4WVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDEMRWHA4DAMZWGY . You are receiving this because you authored the thread.Message ID: @.***>

 -