music-assistant / hass-music-assistant

Turn your Home Assistant instance into a jukebox, hassle free streaming of your favorite media to Home Assistant media players.
Apache License 2.0
1.36k stars 52 forks source link

Radio source pause/play gets stuck #1830

Closed grigi closed 9 months ago

grigi commented 9 months ago

What version of Music Assistant has the issue?

2024.1.0

The problem

Pausing/Resuming on radio channels don't always resume audio.

How to reproduce

When listening to a radio channel "Classic FM" (the UK one) and pressing the play/pause button on our mediaplayer (slimproto based), if you press it again soon, the radio will resume, but if you press it after a few hours MA will not resume. The player immediately pauses again. Workaround is to re-start the radio.

Relevant log output

No response

Additional information

I feel that if you're listening to internet radio, the play/pause buttons should really operate more like a mute/unmute button.

What version of Home Assistant Core are your running

2024.1.5

What type of installation are you running?

Home Assistant OS

On what type of hardware are you running?

Generic x86-64 (e.g. Intel NUC)

OzGav commented 9 months ago

Please find some supporting logs. A large number of things could have happened in those intervening hours....

grigi commented 9 months ago

I had the issue happen again, and this is the error in the logs (it seems almost unrelated):

2024-01-27 22:25:34.681 ERROR (MainThread) [aiohttp.server] Error handling request
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/aiohttp/web_protocol.py", line 452, in _handle_request
    resp = await request_handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/web_app.py", line 543, in _handle
    resp = await handler(request)
           ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/metadata.py", line 360, in handle_imageproxy
    image_data = await self.get_thumbnail(path, size=size, provider=provider)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/metadata.py", line 344, in get_thumbnail
    thumbnail = await get_image_thumb(self.mass, path, size=size, provider=provider)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/helpers/images.py", line 49, in get_image_thumb
    return await asyncio.to_thread(_create_image)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/asyncio/threads.py", line 25, in to_thread
    return await loop.run_in_executor(None, func_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/concurrent/futures/thread.py", line 58, in run
    result = self.fn(*self.args, **self.kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/helpers/images.py", line 43, in _create_image
    img = Image.open(BytesIO(img_data))
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/PIL/Image.py", line 3309, in open
    raise UnidentifiedImageError(msg)
PIL.UnidentifiedImageError: cannot identify image file <_io.BytesIO object at 0x7f224ab8e5c0>

I repeated the action and got the same error in the logs. Does this help?

OzGav commented 9 months ago

Thanks. If you can add a couple of lines from above the error that would also be good.

grigi commented 9 months ago

Only this:

2024-01-27 19:31:27.095 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2024-01-27 19:31:27.096 INFO (MainThread) [music_assistant.music] Sync task for RadioBrowser completed
authorized
2024-01-27 19:31:27.559 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as 31da2iti4s3xsdifqvrfqfhjq3cu
2024-01-27 19:31:28.116 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
authorized
2024-01-27 20:32:25.973 INFO (MainThread) [music_assistant.providers.spotify] Successfully logged in to Spotify as 31da2iti4s3xsdifqvrfqfhjq3cu

Which doesn't seem relevant to the issue either.

My gut feel is that it has something to do with pausing a radiostream. It will pause the stream, and if you resume it a minute later you're running a minute behind the radio stream. An hour might just be too far behind for the radio stream to handle it, so it just cancels and we get a different error.

marcelveldt commented 9 months ago

If you pause a stream, it will stop after 30 seconds of inactivity anyways - otherwise the entire buffer would overflow and/or you run into out of memory issues. For regular tracks, the last position is remembered so that if you press play again, it will continue where you stopped.

For radio streams this is a whole different story as those are supposed to be realtime. Maybe a few seconds buffered but no more than that.

Sounds like there's a bug in resuming a radio stream if I hear this correctly. I'll try to reproduce.

marcelveldt commented 9 months ago

Reproduced the issue and fixed it. Next beta (beta89) will have the fix included.