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
73.82k stars 30.91k forks source link

LMS: Player is unavailable and log is full of "Task exception was never retrieved" errors #93372

Closed AndreKR closed 1 year ago

AndreKR commented 1 year ago

The problem

I'm using the LMS integration and I have a single player in LMS. LMS is currently playing on this player.

In Home Assistant the player entity is "unavailable" and my log is full of these errors:

2023-05-22 22:54:26.934 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/squeezebox/media_player.py", line 152, in _discovered_player
    await player.async_update()
  File "/usr/local/lib/python3.10/site-packages/pysqueezebox/player.py", line 380, in async_update
    self._status.update(response)
TypeError: 'bool' object is not iterable

They seems to appear about once per minute.

What version of Home Assistant Core has the issue?

core-2023.3.5

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Container

Integration causing the issue

Squeezebox (Logitech Media Server)

Link to integration documentation on our website

https://www.home-assistant.io/integrations/squeezebox

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

home-assistant[bot] commented 1 year ago

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

Code owner commands Code owners of `squeezebox` 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 squeezebox` Removes the current integration label and assignees on the issue, add the integration domain after the command.

(message by CodeOwnersMention)

squeezebox documentation squeezebox source (message by IssueLinks)

rajlaud commented 1 year ago

Thanks for reporting this. I'm updating the underlying pysqueezebox library to more gracefully handle this exception.

That said, I'm not sure why you are getting this error. It would happen if the Logitech Media Server API returned a blank result when trying to query the status of a player. This would happen if Home Assistant can still talk to the player, but the player is not talking to LMS, or its player identifier (usually its MAC address) changed.

Are you still getting the error?

AndreKR commented 1 year ago

Yes, I'm still getting them once every minute. Is there maybe a way I can get you more diagnostic data?

rajlaud commented 1 year ago

Yes. Two things might help:

1) Are you seeing a media player entity show up for your squeezebox? If so, does it ever update, or does it show up as unavailable?

2) Can you please enable debug logging for homeassistant.components.squeezebox and pysqueezebox then attach a snippet of your homeassistant.log file with the output to this issue? Instructions on enabling logging are here: https://www.home-assistant.io/integrations/logger/

rajlaud commented 1 year ago

Also, what version of logitech media server are you running?

AndreKR commented 1 year ago

Are you seeing a media player entity show up for your squeezebox? If so, does it ever update, or does it show up as unavailable?

When I wrote this issue it showed as "unavailable" but then I restarted Home Assistant and since then it is there, showing the correct state and it can also control LMS.

Can you please enable debug logging for homeassistant.components.squeezebox and pysqueezebox then attach a snippet of your homeassistant.log file with the output to this issue? Instructions on enabling logging are here: https://www.home-assistant.io/integrations/logger/

Enabled and restarted HA. Log will be in another comment.

Also, what version of logitech media server are you running?

Logitech Media Server Version: 8.3.1 - 1676361197 @ Fri Feb 17 06:43:16 CET 2023

AndreKR commented 1 year ago

Here's the log. I have redacted the LMS login.

2023-05-26 01:08:23.172 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/squeezebox/media_player.py", line 152, in _discovered_player
    await player.async_update()
  File "/usr/local/lib/python3.10/site-packages/pysqueezebox/player.py", line 380, in async_update
    self._status.update(response)
TypeError: 'bool' object is not iterable
2023-05-26 01:08:25.099 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:08:31.067 DEBUG (MainThread) [pysqueezebox.discovery] Sending discovery message.
2023-05-26 01:08:31.073 DEBUG (MainThread) [pysqueezebox.discovery] Received LMS discovery response from ('192.168.42.5', 3483)
2023-05-26 01:08:31.082 DEBUG (MainThread) [homeassistant.components.squeezebox.config_flow] Reached server discovery flow with info: {'host': '192.168.42.5', 'port': 9000, 'uuid': '11eb4914-3371-47cc-a49b-54799396c31f'}
2023-05-26 01:08:35.099 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:08:45.101 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:08:55.101 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:09:05.103 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:09:15.104 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:09:23.124 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["", ["players", "status"]]}
2023-05-26 01:09:23.136 DEBUG (MainThread) [pysqueezebox.player] Creating SqueezeBox object: Kitchen, a0:e0:0c:a0:00:01
2023-05-26 01:09:23.136 DEBUG (MainThread) [pysqueezebox.server] get_players(None) returning players: [Player('Server(<aiohttp.client.ClientSession object at 0xf056f958>, 192.168.42.5, 9000, [REDACTED], [REDACTED], None, None)', 'a0:e0:0c:a0:00:01', 'Kitchen', {})]
2023-05-26 01:09:23.137 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:09:23.156 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "0", 188, "tags:acdIKlNorTux"]]}
2023-05-26 01:09:23.221 INFO (MainThread) [pysqueezebox.server] Query run on unknown player a0:e0:0c:a0:00:01
2023-05-26 01:09:23.222 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/squeezebox/media_player.py", line 152, in _discovered_player
    await player.async_update()
  File "/usr/local/lib/python3.10/site-packages/pysqueezebox/player.py", line 380, in async_update
    self._status.update(response)
TypeError: 'bool' object is not iterable
2023-05-26 01:09:25.104 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:09:31.071 DEBUG (MainThread) [pysqueezebox.discovery] Sending discovery message.
2023-05-26 01:09:31.073 DEBUG (MainThread) [pysqueezebox.discovery] Received LMS discovery response from ('192.168.42.5', 3483)
2023-05-26 01:09:31.075 DEBUG (MainThread) [homeassistant.components.squeezebox.config_flow] Reached server discovery flow with info: {'host': '192.168.42.5', 'port': 9000, 'uuid': '11eb4914-3371-47cc-a49b-54799396c31f'}
2023-05-26 01:09:35.106 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:09:45.106 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:09:46.711 WARNING (MainThread) [homeassistant.components.onvif] Couldn't connect to camera 'Reolink Camera 1', but will retry later. Error: All connection attempts failed
2023-05-26 01:09:55.106 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:10:05.108 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:10:15.110 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:10:23.138 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["", ["players", "status"]]}
2023-05-26 01:10:23.150 DEBUG (MainThread) [pysqueezebox.player] Creating SqueezeBox object: Kitchen, a0:e0:0c:a0:00:01
2023-05-26 01:10:23.150 DEBUG (MainThread) [pysqueezebox.server] get_players(None) returning players: [Player('Server(<aiohttp.client.ClientSession object at 0xf056f958>, 192.168.42.5, 9000, [REDACTED], [REDACTED], None, None)', 'a0:e0:0c:a0:00:01', 'Kitchen', {})]
2023-05-26 01:10:23.151 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:10:23.167 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "0", 188, "tags:acdIKlNorTux"]]}
2023-05-26 01:10:23.235 INFO (MainThread) [pysqueezebox.server] Query run on unknown player a0:e0:0c:a0:00:01

It repeats over and over again, I copied two full "cycles".

rajlaud commented 1 year ago

Also, what version of logitech media server are you running?

Logitech Media Server Version: 8.3.1 - 1676361197 @ Fri Feb 17 06:43:16 CET 2023

I just upgraded my server to that version, and am not seeing errors, so I think we can rule out some new incompatibility between LMS and the integration.

Here's the log. I have redacted the LMS login.

Thanks - I should have warned you about that appearing in debug mode. I don't use a password myself, so let me try enabling that on my local instance to make sure the root cause isn't auth related.

2023-05-26 01:10:23.150 DEBUG (MainThread) [pysqueezebox.player] Creating SqueezeBox object: Kitchen, a0:e0:0c:a0:00:01
2023-05-26 01:10:23.150 DEBUG (MainThread) [pysqueezebox.server] get_players(None) returning players: [Player('Server(<aiohttp.client.ClientSession object at 0xf056f958>, 192.168.42.5, 9000, [REDACTED], [REDACTED], None, None)', 'a0:e0:0c:a0:00:01', 'Kitchen', {})]
2023-05-26 01:10:23.151 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "-", "1", "tags:acdIKlNorTux"]]}
2023-05-26 01:10:23.167 DEBUG (MainThread) [pysqueezebox.server] URL: http://192.168.42.5:9000/jsonrpc.js Data: {"id": "1", "method": "slim.request", "params": ["a0:e0:0c:a0:00:01", ["status", "0", 188, "tags:acdIKlNorTux"]]}
2023-05-26 01:10:23.235 INFO (MainThread) [pysqueezebox.server] Query run on unknown player a0:e0:0c:a0:00:01

One possibility might be a problem with the network connection between HA and your LMS server, or between your LMS server and the Squeezebox. Limitations in the LMS API make this a little tricky to diagnose.

The plugin is finding your LMS server and connecting to it. It's requesting a list of players and seems to be finding your Kitchen player and creating the object to control it. What's strange is that even after it finds that player and creates the object, it is throwing an unknown player error for that same unique ID (mac address).

Unfortunately the "unknown player" error is a bit ambiguous. LMS doesn't actually give any meaningful response when you query an unknown player; it just abruptly disconnects. So it's possible that rather than an unknown player (i.e., the player disconnected from the server), instead the connection between LMS and the HA integration is being reset.

How does playback sound? If you skip a track, hit play/pause, etc. in the LMS server web interface, does it reliably do the right thing to the player? If so, it's unlikely the problem is between LMS and your player and more likely it is between LMS and HA.

If you ping LMS (192.168.42.5) from the server running HA, do you see dropped packets?

Is the load very high on your LMS server? (Again seems unlikely if playback works). Or on your HA server?

rajlaud commented 1 year ago

Enabling auth didn't make a difference for me.

What squeezebox player or player software are you using?

AndreKR commented 1 year ago

LMS and HA are both on the same server, in Docker containers. The Kitchen player is another Docker container on the same machine, using the giof71/squeezelite image. System load is quite reasonable, between 0.2 and 0.4.

LMS works alright. Skipping to another track also works fine. It takes a second or so because I am playing from a remote Navidrome server using the SqueezeSonic plugin.

I'm running the commands from the log right now over the CLI interface and there seems to be a connection with the contents of the current playlist. I removed those 188 items and now the error is gone.

What exactly does that "Query run on unknown player a0:e0:0c:a0:00:01" mean? Does it mean it ran some command (status 0 188?) and got some unexpected response?

AndreKR commented 1 year ago

I got it to hang on the CLI interface!

image

Not sure what causes it, but it definitely seems to be an LMS issue.

AndreKR commented 1 year ago

After I disconnected from the CLI interface and reconnected, I could issue queries again.

Does your integration maintain a persistent connection or does it reconnect for every request? If the former, one possible workaround would be to reconnect in case of that error, I guess.

Right now (since I cleared the playlist) the error has disappeared, even when I load the same playlist again, so I'm afraid the debug session has come to an end for now.

rajlaud commented 1 year ago

LMS and HA are both on the same server, in Docker containers. The Kitchen player is another Docker container on the same machine, using the giof71/squeezelite image. System load is quite reasonable, between 0.2 and 0.4.

I uses squeezelite too. And on a Raspberry Pi where the load is frequently much higher, so I don't think it is a network or load issue.

What exactly does that "Query run on unknown player a0:e0:0c:a0:00:01" mean? Does it mean it ran some command (status 0 188?) and got some unexpected response?

Yes - that it ran a command on the player and the connection was unexpectedly broken.

The integration uses the LMS JSON RPC interface, so it makes a separate HTTP request for each command. The integration makes a lot of requests to the server; as LMS has no concept of subscribing to state changes/callbacks. So some of these connections should go through and the integration should still work, even if some of the queries fail. The log spam for the uncaught exception should be fixed as soon as my pull request to bump the version of pysqueezebox is merged.

It takes a second or so because I am playing from a remote Navidrome server using the SqueezeSonic plugin.

My only guess is that something about the SqueezeSonic plugin is causing LMS to hang on API calls. It's possibly interesting/noteworthy that this happens over both the CLI interface and the JSON RPC interface.