Core: Repeating error of squeezebox media player component in 0.115

Created on 25 Sep 2020  路  47Comments  路  Source: home-assistant/core

The problem


After update to 0.115 the HA log gets repeating error every 4-5 sec.

Environment

  • Home Assistant Core release with the issue: 0.115.3
  • Last working Home Assistant Core release (if known): 0.114
  • Operating environment (OS/Container/Supervised/Core): Docker/Core
  • Integration causing this issue: Squeezebox (?)
  • Link to integration documentation on our website: https://www.home-assistant.io/integrations/squeezebox/

Problem-relevant configuration.yaml

No yaml, since squezeebox integration works now via GUI setup. 

Traceback/Error logs

2020-09-25 21:57:06 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved                               
Traceback (most recent call last):                                                                                                       
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 592, in _update_entity_states                             
    await asyncio.gather(*tasks)                                                                                                         
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 283, in async_update_ha_state                                      
    self._async_write_ha_state()                                                                                                         
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 322, in _async_write_ha_state                                      
    attr.update(self.state_attributes or {})                                                                                             
  File "/usr/src/homeassistant/homeassistant/components/media_player/__init__.py", line 806, in state_attributes                         
    value = getattr(self, attr)                                                                                                          
  File "/usr/src/homeassistant/homeassistant/components/squeezebox/media_player.py", line 360, in media_duration                         
    return self._player.duration                                                                                                         
  File "/usr/local/lib/python3.8/site-packages/pysqueezebox/player.py", line 105, in duration                                            
    if self.current_track and "duration" in self.current_track:                                                                          
  File "/usr/local/lib/python3.8/site-packages/pysqueezebox/player.py", line 165, in current_track                                       
    return self._status["playlist_loop"][self.current_index]                                                                             
TypeError: 'NoneType' object is not subscriptable  

Additional information

Media players more or less stay working even with this errors.

squeezebox problem in dependency

All 47 comments

I can confirm this.
I'm having the same issue too, since update to 0.115.
Removed the integration, reinstalled ... issue remains.

I think this has something to do with the feedback of squeezebox, since the issued command is beeing execuded on LMS itself.
An example:

- service: squeezebox.call_method data_template: entity_id: "{{ player }}" command: power

Selected player toggles it's power, but every time the message as described by @Spirituss appears in the log.

UPD: this issue significantly affects HA performance - my HA becomes almost unworkable with squeezebox media players. I totally removed this integration and CPU load decreased about 10-20%. Thus, please, find a fix as soon as possible.

It seems to be choking on reporting the media_content_id as part of the player attributes.

Furthermore, if the media_content_type is playlist and the playlist is empty, it throws the error. I can toggle players with empty playlists, but HA throws the error in the frontend, and doesn't update the power state.

Trying to see if keeping at least some type of playlist on each player will reduce the frequency of the errors in the logs.

I've had similar issues with the ADS component after update to 0.113:
https://github.com/home-assistant/core/issues/38150
In the end it had something to do with async not handling the received packets correctly.

Are you guys on 8.0 of LMS or 7.9.x?

7.9.3, the latest available version for piCore.

Logitech Media Server version: 7.9.3 - 1597753178 @ Sun Aug 23 19:27:27 CEST 2020
OS: piCore - NL - utf8
Architecture: armv8l-linux
Perl-version: 5.28.2 - arm-linux-gnueabihf-thread-multi-64int
Audio::Scan: 1.02
IO::Socket::SSL: 2.066
DB Version: DBD::SQLite 1.58 (sqlite 3.22.0)

Ok so it's not LMS version dependent as someone on Discord was running 8.0 and I'm on 7.9.4 and still getting the error.

Manually forced upgrade to 8.0.0 - 1601380107 @ Tue Sep 29 14:25:05 CEST 2020:
Problem remains.

2020-09-29 15:55:02 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 592, in _update_entity_states await asyncio.gather(*tasks) File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 283, in async_update_ha_state self._async_write_ha_state() File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 322, in _async_write_ha_state attr.update(self.state_attributes or {}) File "/usr/src/homeassistant/homeassistant/components/media_player/__init__.py", line 806, in state_attributes value = getattr(self, attr) File "/usr/src/homeassistant/homeassistant/components/squeezebox/media_player.py", line 360, in media_duration return self._player.duration File "/usr/local/lib/python3.8/site-packages/pysqueezebox/player.py", line 105, in duration if self.current_track and "duration" in self.current_track: File "/usr/local/lib/python3.8/site-packages/pysqueezebox/player.py", line 165, in current_track return self._status["playlist_loop"][self.current_index] TypeError: 'NoneType' object is not subscriptable

This appears to happen when the playlist in the Logitech Media Server is cleared. If you add any song then the error disappears. For now I'm just pausing the playlist rather then clearing it - seems to prevent the error in HA.

@Paul-Faulkner
I added songs to all of my players but it doesn't work.

@Spirituss: I can confirm that the workaround as proposed by Paul-Faulkner works in my case.

Are the integration developers still here? The error log is quite noisy now

Guys, any news on the possible fix?

@rajlaud @frenck @MartinHjelmare

I've noticed y'all have made some commits lately. Can you have a look concerning this issue, or give us an update?

@gijbelsy that's not the way to get help.

@gijbelsy that's not the way to get help.

I'm not trying to GET help, I'm trying to PROVIDE help.
What else should I do?

Pinging devs like that isn't going to get them to work any faster. If you want to help take a look at the code and try to patch it to fix the issue.

Pinging devs like that isn't going to get them to work any faster. If you want to help take a look at the code and try to patch it to fix the issue.

Please... sore toes?

Assignees: No one assigned.... so I mentioned the dev ONCE.
I've tested provided solutions
I've upgraded my own systems to provide information.

Question remains: What else should I do?

Edit: I'm not a Python dev, otherwise I surely would have tried to fix the problem.

Oh it's not my toes. It's the devs toes. You aren't the first one to @ them. Usually doesn't go well for the person @ ing.

At this point unless you can help you can disable logging for the component. That's about it.

Looking at the stack trace, the problem is in the pysqueezebox library.

@FuzzyMistborn : The major problem is not the log being flooded, that's Spirituss mentioning this.
Can you please clarify where in this topic the devs are @, besides my kind request for help ?

@MartinHjelmare : Thanks for the update.

Please keep the issue on topic. We don't need to discuss what was said or not said.

In general, avoid pinging anyone unless they have already made it clear that they want to be pinged, eg by being code owner.

I've noticed that the latest version of pysqueezebox is 0.5.0, while the manifest requires 0.3.1. Perhaps bumping this to the latest version resolves the issue?

It's good to check the library changes first to see what has changed. If you can test the integration with an upgraded library, please go ahead and make a PR.

I'm sorry but as mentioned above, I'm not experienced with deving for HA / github :)
I'm willing to test this on my system and report back, but how do I force the integrated component to use the 0.5.0 library?
Is this possible via custom_components, and then only add the manifest.json, with the updated dependency line?
edit: Since I'm running HA core, on a virtual machine, I have no full access to the under-laying OS. I guess PIP3 install won't work.

Copying the integration directory to a custom component directory and changing the manifest should work.

I can confirm that modifying the manifest dependencies to the latest pysqueezebox library (0.5.0) does resolve the issue.
I'm able to power-on and power-off, change volume with an empty playlist.
The only thing that's still broken is to load a playlist (but this could be due to my automation).
It seems that the latest pysqueezebox changes things how to handle playlists, still figuring this out.

Thanks Martin for pointing me in the right direction.

Update:

The integration works with pysqueezebox lib v 0.5.0.
Service calls are working for squeezebox and media_player, except media_player.play_media gives me the following error:

2020-10-13 14:49:40 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140611870313392] Expecting value: line 1 column 1 (char 0)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 138, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1335, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1370, in _execute_service
    await handler.func(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 204, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 470, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 655, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 507, in _handle_entity_call
    await result
  File "/config/custom_components/squeezebox_custom/media_player.py", line 483, in async_play_media
    content = json.loads(media_id)
  File "/usr/local/lib/python3.8/json/__init__.py", line 357, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.8/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/local/lib/python3.8/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

The way this service (media_player.play_media) is called isn't changed and was working before.

entity_id: media_player.player1
media_content_type: playlist
media_content_id: 'Playlist friendly name'

When I call the service squeezebox.call_method to load the playlist, it's working:

entity_id: media_player.player1
command: playlist
parameters:
  - play
  - Playlist friendly name
  - ''
  - 4

There is a pending pull request to update squeezebox for media browser, which also bumps pysqueezebox to v5.0 and makes some changes to loading playlists. Can you check if you get the same error with those changes? https://github.com/home-assistant/core/pull/40642

Also, for some reason I didn't get see a notice as codeowner on this one. Feel free to ping me squeezebox issues.

The squeezebox integration is working as mentioned above, with the help of pysqueezebox 0.5.0.

When I load the #40642 PR, my log spits out the following, at startup:

2020-10-14 09:48:45 ERROR (MainThread) [homeassistant.helpers.integration_platform] Unexpected error importing squeezebox/logbook.py
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/integration_platform.py", line 30, in _process
    platform = integration.get_platform(platform_name)
  File "/usr/src/homeassistant/homeassistant/loader.py", line 401, in get_platform
    cache[full_name] = importlib.import_module(
  File "/usr/local/lib/python3.8/importlib/__init__.py", line 127, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  File "<frozen importlib._bootstrap>", line 1014, in _gcd_import
  File "<frozen importlib._bootstrap>", line 991, in _find_and_load
  File "<frozen importlib._bootstrap>", line 973, in _find_and_load_unlocked
ModuleNotFoundError: No module named 'custom_components.squeezebox_custom.logbook'
2020-10-14 09:48:45 ERROR (MainThread) [homeassistant.helpers.integration_platform] Unexpected error importing squeezebox/media_source.py
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/integration_platform.py", line 30, in _process
    platform = integration.get_platform(platform_name)
  File "/usr/src/homeassistant/homeassistant/loader.py", line 401, in get_platform
    cache[full_name] = importlib.import_module(
  File "/usr/local/lib/python3.8/importlib/__init__.py", line 127, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  File "<frozen importlib._bootstrap>", line 1014, in _gcd_import
  File "<frozen importlib._bootstrap>", line 991, in _find_and_load
  File "<frozen importlib._bootstrap>", line 973, in _find_and_load_unlocked
ModuleNotFoundError: No module named 'custom_components.squeezebox_custom.media_source'
2020-10-14 09:48:45 ERROR (MainThread) [homeassistant.helpers.integration_platform] Unexpected error importing squeezebox/group.py
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/integration_platform.py", line 30, in _process
    platform = integration.get_platform(platform_name)
  File "/usr/src/homeassistant/homeassistant/loader.py", line 401, in get_platform
    cache[full_name] = importlib.import_module(
  File "/usr/local/lib/python3.8/importlib/__init__.py", line 127, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  File "<frozen importlib._bootstrap>", line 1014, in _gcd_import
  File "<frozen importlib._bootstrap>", line 991, in _find_and_load
  File "<frozen importlib._bootstrap>", line 973, in _find_and_load_unlocked
ModuleNotFoundError: No module named 'custom_components.squeezebox_custom.group'

The error above still remains when trying to play a playlist from the media_player service:

2020-10-14 09:53:50 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.139804042957776] Expecting value: line 1 column 1 (char 0)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 138, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1335, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1370, in _execute_service
    await handler.func(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 204, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 470, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 655, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 507, in _handle_entity_call
    await result
  File "/config/custom_components/squeezebox_custom/media_player.py", line 501, in async_play_media
    content = json.loads(media_id)
  File "/usr/local/lib/python3.8/json/__init__.py", line 357, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.8/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/local/lib/python3.8/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

The service squeezebox.call_method works perfectly.

LMS info:

Logitech Media Server Versie: 8.0.0 - 1602603940 @ Tue Oct 13 18:24:51 CEST 2020
HTTP-poortnummer van server: 9000
Besturingssysteem: piCore - NL - utf8
Platformarchitectuur: armv8l-linux
Perl-versie: 5.28.2 - arm-linux-gnueabihf-thread-multi-64int
Audio::Scan: 1.02
IO::Socket::SSL: 2.066
Databaseversie: DBD::SQLite 1.58 (sqlite 3.22.0)

Thank you. I believe the errors on load are because you are running v0.115, but the media browse code requires v0.116. However, I'd like to understanding the issue loading playlists better. Can you post a sample of the playlist you tried to load?

media_player.play_media expects a dictionary with two keys: index, which is where you are in the playlists, and urls, which should be an array of dictionaries containing at least the key url (other keys will be ignored). You can generate a sample by loading a playlist through other means and then looking at the media_content_id in the state.

I'm running HA 0.116.2, on HA Core Supervisor version 247.
I'm calling the service media_player.play media as follows:

entity_id: media_player.player1
media_content_type: playlist
media_content_id: 'Playlist friendly name'

The playlist itself contains 5 URL streams (radio stations).

The data inside the dictionary I provide differs from what you describe. Has this been changed since HA 0.112 (it was working in this version)?
As from the docs: https://www.home-assistant.io/integrations/media_player/#service-media_playerplay_media it looks that my provided data is correct.

Thanks, I'll check it out. I didn't know that loading a playlist by
friendly name worked before.

>

For what it's worth: just saw the upgrade to 106.3 was available, error in log on startup remains:
```yaml

2020-10-15 17:34:11 ERROR (MainThread) [homeassistant.helpers.integration_platform] Unexpected error importing squeezebox/logbook.py
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/integration_platform.py", line 30, in _process
platform = integration.get_platform(platform_name)
File "/usr/src/homeassistant/homeassistant/loader.py", line 401, in get_platform
cache[full_name] = importlib.import_module(
File "/usr/local/lib/python3.8/importlib/__init__.py", line 127, in import_module
return _bootstrap._gcd_import(name[level:], package, level)
File "", line 1014, in _gcd_import
File "", line 991, in _find_and_load
File "", line 973, in _find_and_load_unlocked
ModuleNotFoundError: No module named 'custom_components.squeezebox_custom.logbook'
2020-10-15 17:34:11 ERROR (MainThread) [homeassistant.helpers.integration_platform] Unexpected error importing squeezebox/group.py
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/integration_platform.py", line 30, in _process
platform = integration.get_platform(platform_name)
File "/usr/src/homeassistant/homeassistant/loader.py", line 401, in get_platform
cache[full_name] = importlib.import_module(
File "/usr/local/lib/python3.8/importlib/__init__.py", line 127, in import_module
return _bootstrap._gcd_import(name[level:], package, level)
File "", line 1014, in _gcd_import
File "", line 991, in _find_and_load
File "", line 973, in _find_and_load_unlocked
ModuleNotFoundError: No module named 'custom_components.squeezebox_custom.group'
2020-10-15 17:34:11 ERROR (MainThread) [homeassistant.helpers.integration_platform] Unexpected error importing squeezebox/media_source.py
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/integration_platform.py", line 30, in _process
platform = integration.get_platform(platform_name)
File "/usr/src/homeassistant/homeassistant/loader.py", line 401, in get_platform
cache[full_name] = importlib.import_module(
File "/usr/local/lib/python3.8/importlib/__init__.py", line 127, in import_module
return _bootstrap._gcd_import(name[level:], package, level)
File "", line 1014, in _gcd_import
File "", line 991, in _find_and_load
File "", line 973, in _find_and_load_unlocked
ModuleNotFoundError: No module named 'custom_components.squeezebox_custom.media_source'

```

Guys, the problem is very annoying. The log file becomes over 50 Mb for just 2 days.

@Spirituss add this to your configuration.yaml

logger:
  default: error
  logs:
    homeassistant.components.squeezebox.media_player: fatal

That will stop the log from getting huge.

@FuzzyMistborn
I added it to configuration.yaml and still receive the following messages:

ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 592, in _update_entity_states
    await asyncio.gather(*tasks)
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 283, in async_update_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 322, in _async_write_ha_state
    attr.update(self.state_attributes or {})
  File "/usr/src/homeassistant/homeassistant/components/media_player/__init__.py", line 809, in state_attributes
    value = getattr(self, attr)
  File "/usr/src/homeassistant/homeassistant/components/squeezebox/media_player.py", line 360, in media_duration
    return self._player.duration
  File "/usr/local/lib/python3.8/site-packages/pysqueezebox/player.py", line 105, in duration
    if self.current_track and "duration" in self.current_track:
  File "/usr/local/lib/python3.8/site-packages/pysqueezebox/player.py", line 165, in current_track
    return self._status["playlist_loop"][self.current_index]
TypeError: 'NoneType' object is not subscriptable

Yes it'll still show up in the log viewed in HASS but it shouldn't appear in the actual log file. I may have the line slightly wrong but the concept is right. If you only allow fatal errors to be logged for the component it'll keep your log small.

@FuzzyMistborn
I don't understand you. I mean homeassistant.log file. I still see these messages there and last time it was about 50Mb.

@gijbelsy
I haven't been able to reproduce the errors you are getting loading the module. What is strange is they seem to refer to a component named squeezebox_custom not the squeezebox component. I can only assume they related to running this as a custom component, but when I put the squeezebox folder in the custom_components folder it works for me. Hopefully PR #40642 will be merged soon so that you don't have to keep running this as a custom component.

Regarding adding playlists, I think behavior has changed since 0.112. Loading by friendly name wasn't officially supported, but
looking back at the code, it would have worked because of the way the command was passed to the squeezebox server.

For the squeezebox plugin, the supported way to load a playlist is by playlist_id (this is a unique identifier, which friendly name is not guaranteed to be), or by a list of urls (this allows snapshots using the scene integration). If you prefer to search by friendly name, you can keep using the squeezebox.call_method. Or if your playlist is identifiable by an url on your server, you could use media_player.play_media with a media_content_type of music and a media_content_id of the url. When you choose media_content_type of music, you can pass any url the squeezebox server recognizes.

@rajlaud

You are correct what squeezebox_custom is concerned. To test the new code, I make use of the custom_component folder and refer to this in my configuration.yaml.

Regarding the playlist-id: How do I retrieve the correct id for the playlist?
When I issue

squeezebox.call_query

entity_id: media_player.bureau
command: playlist
parameters:
  - playlistsinfo

The query_result for the player only returns 'true' ?
Playlist is loaded, and playing in LMS.

The squeezebox CLI can be confusing. The command is playlists (with an s). Without limitation it gives all playlists:

entity_id: media_player.tape
command: "playlists"
parameters: ["0","20"]

If you want to search:

entity_id: media_player.tape
command: "playlists"
parameters: ["0","20","search:Yacht"]

Gives a result like this in player status:

query_result: 
playlists_loop:
  - id: 43177
    playlist: 'Spotify: Yacht Rock + Easy Listening'
count: 1

Thanks for that update.
I can confirm that the error

json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

is no longer appearing when using playlist ID.
Somewhere between v 102 and the latest version, the use of friendly name when playing playlists is no longer supported.

I still have the original issue:

 return self._status["playlist_loop"][self.current_index]                                                                             
TypeError: 'NoneType' object is not subscriptable  

with 0.116.4 (docker) as soon as I have at least one player that has an empty playlist.

Do you make use of the PR as mentioned by rajlaud, or have the manifest.json modified to use the latest version of pysqueezebox ?
The PR of rajlaud isn't merged into 0.116.4 yet. You need to add this manually via the custom_components folder.

Ah sorry my bad. I thought I had read that this was merged in 0.116.4, but it clearly isn't. It's not so much of a pain point though to create a custom_component, so I will patiently wait for the next official release :)

Was this page helpful?
0 / 5 - 0 ratings