search

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.37k stars 52 forks source link

Interrupted Music #1669

Closed BucciMobile closed 9 months ago

BucciMobile commented 11 months ago

What version of Music Assistant has the issue?

2.0.0b75

The problem

Faced the problem, that music suddenly and without any action by user stops playing. Most of the times it needs about 1-2min till it stops, when testing this morning it only needed around 30 seconds.

Sonos System is working fine, even in HA -no problems f.e. with the Dashboard: Sonos card.

How to reproduce

Started a Music-Playlist on Qobuz via Interface by pressing "Play". Group 1 is selected as speaker: (Sonos Beam with 2 rear Play:1 "Wohnzimmer", and one Symfonisk "Flur"). No actions taken after starting the music. Music will stop after some seconds.

With first interruption tested it without any playlist/album (so no music is in the playlist). The one title started and was interrupted within seconds.

Relevant log output

2023-12-06 07:35:47.886 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Connection from 172.30.32.2 2023-12-06 07:35:48.112 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command players/all 2023-12-06 07:35:48.160 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command players/queue/all 2023-12-06 07:35:48.207 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command providers/manifests 2023-12-06 07:35:48.249 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command providers 2023-12-06 07:35:48.851 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/synctasks 2023-12-06 07:35:49.294 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/recently_played_items 2023-12-06 07:35:49.296 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/artists/library_items 2023-12-06 07:35:49.297 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/albums/library_items 2023-12-06 07:35:49.299 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/recently_played_items 2023-12-06 07:35:49.301 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/recently_played_items 2023-12-06 07:35:49.303 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/tracks/library_items 2023-12-06 07:35:49.306 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/browse 2023-12-06 07:35:49.308 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/item_by_uri 2023-12-06 07:35:50.018 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/radio/library_items 2023-12-06 07:35:50.114 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/playlists/library_items 2023-12-06 07:36:02.458 WARNING (MainThread) [asyncio] Executing <Task pending name='Task-41851' coro=<RequestHandler._handle_request() running at /usr/local/lib/python3.11/site-packages/aiohttp/web_protocol.py:458> wait_for=<Future pending cb=[_chain_future.._call_check_cancel() at /usr/local/lib/python3.11/asyncio/futures.py:387, Task.task_wakeup()] created at /usr/local/lib/python3.11/asyncio/base_events.py:427> cb=[Task.task_wakeup()] created at /usr/local/lib/python3.11/site-packages/aiohttp/web_protocol.py:508> took 0.103 seconds 2023-12-06 07:36:02.893 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/playlists/get_playlist 2023-12-06 07:36:03.047 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/playlists/playlist_tracks 2023-12-06 07:36:09.587 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command players/queue/play_media 2023-12-06 07:36:09.590 DEBUG (MainThread) [music_assistant.event] queue_items_updated ugp_1 2023-12-06 07:36:09.592 DEBUG (MainThread) [music_assistant.event] queue_updated ugp_1 2023-12-06 07:36:09.648 DEBUG (MainThread) [music_assistant.event] queue_items_updated ugp_1 2023-12-06 07:36:09.653 DEBUG (MainThread) [music_assistant.event] queue_updated ugp_1 2023-12-06 07:36:09.662 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue Gruppen: 1 2023-12-06 07:36:09.663 DEBUG (MainThread) [music_assistant.players] Handling command cmd_stop for player Lautsprecher Flur 2023-12-06 07:36:09.745 DEBUG (Thread-744 (process_request_thread)) [music_assistant.providers.sonos] Received AVTransport event for Player Lautsprecher Flur 2023-12-06 07:36:09.754 DEBUG (MainThread) [music_assistant.event] queue_updated ugp_1 2023-12-06 07:36:09.757 DEBUG (MainThread) [music_assistant.event] player_updated ugp_1 2023-12-06 07:36:09.760 DEBUG (MainThread) [music_assistant.event] player_updated RINCON_542A1B5D01D201400 2023-12-06 07:36:09.761 DEBUG (MainThread) [music_assistant.players] Handling command cmd_sync for player Lautsprecher Flur 2023-12-06 07:36:09.781 DEBUG (MainThread) [music_assistant.event] player_updated RINCON_542A1B5D01D201400 2023-12-06 07:36:09.968 DEBUG (Thread-745 (process_request_thread)) [music_assistant.providers.sonos] Received AVTransport event for Player Wohnzimmer-Lautsprecher 2023-12-06 07:36:09.974 DEBUG (MainThread) [music_assistant.streams] Got GET request to /ugp_1/multi/LYoFFtdKYhUzJyKswULXEC/RINCON_542A1B892BFB01400/932446de5dc74a03bd42ef0247111280.mp3 from 192.168.178.58 headers: <CIMultiDictProxy('Connection': 'close', 'Host': '192.168.178.133:8096', 'Accept': '/', 'User-Agent': 'Linux UPnP/1.0 Sonos/76.2-47142 (ZPS14)', 'X-Sonos-SWGen': '2', 'X-Sonos-Firmware': '76.2-47142', 'X-Sonos-Muse-Api': '1.37.0', 'X-Sonos-Id-Hash': 'luSwAyNX39QPNUthXGo6Dp9WkkKcv2U9nwniv6/akS4=')>

2023-12-06 07:36:09.976 DEBUG (MainThread) [music_assistant.streams] Start serving multi-subscriber Queue flow audio stream for queue Gruppen: 1 to player Wohnzimmer-Lautsprecher 2023-12-06 07:36:10.011 DEBUG (MainThread) [music_assistant.streams.streamjob_LYoFFtdKYhUzJyKswULXEC] Subscribed client RINCON_542A1B892BFB01400 2023-12-06 07:36:10.047 DEBUG (MainThread) [music_assistant.streams] Start Streaming queue track: qobuz://track/69300602 (Lady Gaga - Applause) for queue Gruppen: 1 - crossfade: True 2023-12-06 07:36:10.053 DEBUG (MainThread) [music_assistant.audio] start media stream for: qobuz://track/69300602 2023-12-06 07:36:10.084 DEBUG (Thread-746 (process_request_thread)) [music_assistant.providers.sonos] Received ZoneGroupTopology event for Player Arbeitszimmer 2023-12-06 07:36:10.130 DEBUG (Thread-747 (process_request_thread)) [music_assistant.providers.sonos] Received ZoneGroupTopology event for Player Schlafzimmer-Sonos 2023-12-06 07:36:11.862 WARNING (MainThread) [asyncio] Executing <Task pending name='Task-41866' coro=<MultiClientStreamJob._stream_job_runner() running at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/streams.py:213> wait_for=<Future pending cb=[Task.task_wakeup()] created at /usr/local/lib/python3.11/asyncio/base_events.py:427> created at /usr/local/lib/python3.11/asyncio/tasks.py:384> took 0.193 seconds 2023-12-06 07:36:12.029 WARNING (MainThread) [asyncio] Executing <Task pending name='Task-41866' coro=<MultiClientStreamJob._stream_job_runner() running at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/streams.py:213> wait_for=<Future pending cb=[Task.task_wakeup()] created at /usr/local/lib/python3.11/asyncio/base_events.py:427> created at /usr/local/lib/python3.11/asyncio/tasks.py:384> took 0.145 seconds 2023-12-06 07:36:12.340 WARNING (MainThread) [asyncio] Executing <Task pending name='Task-41866' coro=<MultiClientStreamJob._stream_job_runner() running at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/streams.py:213> wait_for=<Future pending cb=[Task.task_wakeup()] created at /usr/local/lib/python3.11/asyncio/base_events.py:427> created at /usr/local/lib/python3.11/asyncio/tasks.py:384> took 0.206 seconds 2023-12-06 07:36:12.353 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command config/providers 2023-12-06 07:36:12.469 DEBUG (MainThread) [music_assistant.streams] Starting multi client stream job for queue Gruppen: 1 with 1 out of 1 connected clients 2023-12-06 07:36:12.561 DEBUG (Thread-748 (process_request_thread)) [music_assistant.providers.sonos] Received ZoneGroupTopology event for Player Wohnzimmer-Lautsprecher 2023-12-06 07:36:12.563 DEBUG (Thread-749 (process_request_thread)) [music_assistant.providers.sonos] Received ZoneGroupTopology event for Player Lautsprecher Flur 2023-12-06 07:36:12.575 DEBUG (MainThread) [music_assistant.streams] Got GET request to /ugp_1/multi/LYoFFtdKYhUzJyKswULXEC/RINCON_542A1B892BFB01400/932446de5dc74a03bd42ef0247111280.mp3 from 192.168.178.58 headers: <CIMultiDictProxy('Accept': '/', 'Host': '192.168.178.133:8096', 'User-Agent': 'Linux UPnP/1.0 Sonos/76.2-47142 (ZPS14) Nullsoft Winamp3 version 3.0 (compatible)', 'Icy-MetaData': '1')>

2023-12-06 07:36:12.577 WARNING (MainThread) [music_assistant.streams] Player RINCON_542A1B892BFB01400 is making multiple requests to the same stream, playback may be disturbed! 2023-12-06 07:36:12.577 DEBUG (MainThread) [music_assistant.streams] Start serving multi-subscriber Queue flow audio stream for queue Gruppen: 1 to player Wohnzimmer-Lautsprecher 2023-12-06 07:36:12.601 DEBUG (MainThread) [music_assistant.streams.streamjob_LYoFFtdKYhUzJyKswULXEC] Client RINCON_542A1B892BFB01400 is joining while the stream is already started 2023-12-06 07:36:12.612 DEBUG (Thread-750 (process_request_thread)) [music_assistant.providers.sonos] Received AVTransport event for Player Lautsprecher Flur 2023-12-06 07:36:12.617 DEBUG (Thread-751 (process_request_thread)) [music_assistant.providers.sonos] Received AVTransport event for Player Wohnzimmer-Lautsprecher 2023-12-06 07:36:12.671 DEBUG (MainThread) [music_assistant.event] player_updated RINCON_542A1B5D01D201400 2023-12-06 07:36:12.679 DEBUG (MainThread) [music_assistant.event] player_updated ugp_1 2023-12-06 07:36:12.984 WARNING (MainThread) [asyncio] Executing <Task pending name='Task-41866' coro=<MultiClientStreamJob._stream_job_runner() running at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/streams.py:213> wait_for=<Future pending cb=[Task.task_wakeup()] created at /usr/local/lib/python3.11/asyncio/base_events.py:427> created at /usr/local/lib/python3.11/asyncio/tasks.py:384> took 0.205 seconds 2023-12-06 07:36:13.297 DEBUG (Thread-752 (process_request_thread)) [music_assistant.providers.sonos] Received ZoneGroupTopology event for Player Wohnzimmer-Lautsprecher 2023-12-06 07:36:13.300 WARNING (MainThread) [asyncio] Executing <Task pending name='Task-41866' coro=<MultiClientStreamJob._stream_job_runner() running at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/streams.py:213> wait_for=<Future pending cb=[Task.task_wakeup()] created at /usr/local/lib/python3.11/asyncio/base_events.py:427> created at /usr/local/lib/python3.11/asyncio/tasks.py:384> took 0.112 seconds 2023-12-06 07:36:13.324 DEBUG (Thread-753 (process_request_thread)) [music_assistant.providers.sonos] Received ZoneGroupTopology event for Player Lautsprecher Flur 2023-12-06 07:36:13.673 DEBUG (Thread-754 (process_request_thread)) [music_assistant.providers.sonos] Received ZoneGroupTopology event for Player Schlafzimmer-Sonos 2023-12-06 07:36:13.816 DEBUG (Thread-755 (process_request_thread)) [music_assistant.providers.sonos] Received ZoneGroupTopology event for Player Arbeitszimmer 2023-12-06 07:36:14.120 DEBUG (Thread-756 (process_request_thread)) [music_assistant.providers.sonos] Received ZoneGroupTopology event for Player Wohnzimmer-Lautsprecher 2023-12-06 07:36:14.122 WARNING (MainThread) [asyncio] Executing <Task pending name='Task-41866' coro=<MultiClientStreamJob._stream_job_runner() running at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/streams.py:213> wait_for=<Future pending cb=[Task.task_wakeup()] created at /usr/local/lib/python3.11/asyncio/base_events.py:427> created at /usr/local/lib/python3.11/asyncio/tasks.py:384> took 0.122 seconds 2023-12-06 07:36:14.130 DEBUG (Thread-757 (process_request_thread)) [music_assistant.providers.sonos] Received ZoneGroupTopology event for Player Lautsprecher Flur 2023-12-06 07:36:14.435 DEBUG (Thread-758 (process_request_thread)) [music_assistant.providers.sonos] Received ZoneGroupTopology event for Player Schlafzimmer-Sonos 2023-12-06 07:36:14.592 DEBUG (Thread-759 (process_request_thread)) [music_assistant.providers.sonos] Received ZoneGroupTopology event for Player Arbeitszimmer 2023-12-06 07:36:14.922 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command config/core 2023-12-06 07:36:15.002 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/artists/library_items 2023-12-06 07:36:15.096 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/albums/library_items 2023-12-06 07:36:15.121 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/tracks/library_items 2023-12-06 07:36:15.159 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/playlists/library_items 2023-12-06 07:36:15.173 DEBUG (Thread-760 (process_request_thread)) [music_assistant.providers.sonos] Received AVTransport event for Player Wohnzimmer-Lautsprecher 2023-12-06 07:36:15.196 DEBUG (MainThread) [music_assistant.event] player_updated RINCON_542A1B892BFB01400 2023-12-06 07:36:15.201 DEBUG (MainThread) [music_assistant.event] queue_updated ugp_1 2023-12-06 07:36:15.203 DEBUG (MainThread) [music_assistant.event] player_updated ugp_1 2023-12-06 07:36:15.240 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/radio/library_items 2023-12-06 07:36:15.252 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/item_by_uri 2023-12-06 07:36:15.262 DEBUG (Thread-761 (process_request_thread)) [music_assistant.providers.sonos] Received AVTransport event for Player Wohnzimmer-Lautsprecher 2023-12-06 07:36:22.505 DEBUG (MainThread) [music_assistant.streams.streamjob_LYoFFtdKYhUzJyKswULXEC] Unsubscribed client RINCON_542A1B892BFB01400 2023-12-06 07:36:23.515 INFO (MainThread) [music_assistant.providers.slimproto] Player a0d7b954-airsonos disconnected 2023-12-06 07:36:23.516 DEBUG (MainThread) [music_assistant.event] queue_updated aa:aa:9e:3e:57:0a 2023-12-06 07:36:23.522 DEBUG (MainThread) [music_assistant.event] player_updated aa:aa:9e:3e:57:0a 2023-12-06 07:36:24.508 DEBUG (MainThread) [music_assistant.streams.streamjob_LYoFFtdKYhUzJyKswULXEC] Cleaning up, all clients disappeared... 2023-12-06 07:36:24.512 DEBUG (MainThread) [music_assistant.audio] media stream aborted for: qobuz://track/69300602 2023-12-06 07:36:24.530 DEBUG (MainThread) [music_assistant.audio] Start analyzing audio for qobuz://track/69300602 2023-12-06 07:36:26.923 WARNING (MainThread) [asyncio] Executing <Task finished name='Task-41971' coro=<Process._read_stream() done, defined at /usr/local/lib/python3.11/asyncio/subprocess.py:170> result=b'\x82D\x06#^...f\xff\xff\xff' created at /usr/local/lib/python3.11/asyncio/tasks.py:680> took 1.035 seconds 2023-12-06 07:36:26.947 DEBUG (MainThread) [music_assistant.audio] Integrated loudness of qobuz://track/69300602 is: -7.7 2023-12-06 07:36:27.931 DEBUG (MainThread) [music_assistant.event] queue_updated ugp_1 2023-12-06 07:36:27.960 DEBUG (MainThread) [music_assistant.webserver] [140637079951632] Handling command music/item_by_uri 2023-12-06 07:37:59.155 DEBUG (Thread-762 (process_request_thread)) [music_assistant.providers.sonos] Received AVTransport event for Player Wohnzimmer-Lautsprecher 2023-12-06 07:38:02.150 DEBUG (MainThread) [music_assistant.streams] Got GET request to /ugp_1/multi/LYoFFtdKYhUzJyKswULXEC/RINCON_542A1B892BFB01400/932446de5dc74a03bd42ef0247111280.mp3 from 192.168.178.58 headers: <CIMultiDictProxy('Accept': '/', 'Host': '192.168.178.133:8096', 'User-Agent': 'Linux UPnP/1.0 Sonos/76.2-47142 (ZPS14) Nullsoft Winamp3 version 3.0 (compatible)', 'Icy-MetaData': '1')>

2023-12-06 07:38:02.151 DEBUG (MainThread) [music_assistant.streams] Start serving multi-subscriber Queue flow audio stream for queue Gruppen: 1 to player Wohnzimmer-Lautsprecher 2023-12-06 07:38:02.159 DEBUG (MainThread) [music_assistant.streams.streamjob_LYoFFtdKYhUzJyKswULXEC] Client RINCON_542A1B892BFB01400 is joining while the stream is already started 2023-12-06 07:38:02.182 DEBUG (Thread-763 (process_request_thread)) [music_assistant.providers.sonos] Received AVTransport event for Player Wohnzimmer-Lautsprecher 2023-12-06 07:38:02.233 DEBUG (Thread-764 (process_request_thread)) [music_assistant.providers.sonos] Received AVTransport event for Player Wohnzimmer-Lautsprecher

Additional information

Home Assistant Core 2023.11.3 Supervisor 2023.11.6 Operating System 11.2 Frontend 20231030.2 CPU/RAM-Usage: Below 10%

Streaming-Service: Qobuz Played on: Sonos (Groups)

What version of Home Assistant Core are your running

2023.11.3

What type of installation are you running?

Home Assistant Core

On what type of hardware are you running?

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

OzGav commented 11 months ago

Please turn off debug logging and post again the log when this happens

BucciMobile commented 11 months ago

Good Morning.

No error is displayed when the Music stops. But this seems like a problem:

2023-12-13 09:47:10.233 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue Sonos Gruppen: 1
2023-12-13 09:47:11.258 WARNING (MainThread) [music_assistant.streams] Player RINCON_542A1B5D01D201400 is making multiple requests to the same stream, playback may be disturbed!
2023-12-13 09:49:47.829 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue Sonos Gruppen: 1
2023-12-13 09:49:48.811 WARNING (MainThread) [music_assistant.streams] Player RINCON_542A1B5D01D201400 is making multiple requests to the same stream, playback may be disturbed!

The starting Prozess:

[music_assistant.webserver] Starting server on  172.30.32.1:8095 - base url: http://172.30.32.1:8095
2023-12-13 09:46:55.788 INFO (MainThread) [music_assistant.music] Using a sync interval of 180 minutes.
2023-12-13 09:46:55.792 WARNING (MainThread) [music_assistant.webserver] [139668246846352] Invalid command: players/all
2023-12-13 09:46:56.072 INFO (MainThread) [music_assistant.streams] Detected ffmpeg version 5.1.4 with libsoxr support
2023-12-13 09:46:56.072 INFO (MainThread) [music_assistant.streams] Starting server on  0.0.0.0:8096 - base url: http://192.168.178.133:8096
2023-12-13 09:46:56.501 INFO (MainThread) [music_assistant.players] Player registered: ugp_1/Sonos Gruppen: 1
2023-12-13 09:46:56.502 INFO (MainThread) [music_assistant.players] Player registered: ugp_2/Sonos Gruppen: 2
2023-12-13 09:46:56.502 INFO (MainThread) [music_assistant.players] Player registered: ugp_3/Sonos Gruppen: 3
2023-12-13 09:46:56.502 INFO (MainThread) [music_assistant] Loaded player provider Sonos Gruppen
2023-12-13 09:46:56.503 INFO (MainThread) [music_assistant] Loaded player provider SONOS
2023-12-13 09:46:56.503 INFO (MainThread) [music_assistant] Loaded metadata provider TheAudioDB Metadata provider
2023-12-13 09:46:56.504 INFO (MainThread) [music_assistant] Loaded player provider UPnP/DLNA Player provider
2023-12-13 09:46:56.504 INFO (MainThread) [music_assistant] Loaded metadata provider fanart.tv Metadata provider
2023-12-13 09:46:56.521 INFO (MainThread) [music_assistant] Loaded music provider URL
2023-12-13 09:46:56.523 INFO (MainThread) [music_assistant] Loaded metadata provider MusicBrainz Metadata provider
2023-12-13 09:46:56.604 INFO (MainThread) [music_assistant] Loaded player provider Chromecast
2023-12-13 09:46:56.605 INFO (MainThread) [music_assistant.providers.slimproto] Started SLIMProto server on port 3483
2023-12-13 09:46:56.606 INFO (MainThread) [music_assistant.providers.slimproto.cli] Registering jsonrpc endpoints on the webserver
2023-12-13 09:46:56.609 INFO (MainThread) [music_assistant.music] Sync task for URL completed
2023-12-13 09:46:56.616 INFO (MainThread) [music_assistant.providers.slimproto.cli] Starting (telnet) CLI on port 9090
2023-12-13 09:46:56.623 INFO (MainThread) [music_assistant] Loaded player provider Slimproto
2023-12-13 09:46:56.787 INFO (MainThread) [music_assistant.providers.qobuz] Successfully logged in to Qobuz as Spotify
2023-12-13 09:46:56.787 INFO (MainThread) [music_assistant] Loaded music provider Qobuz
2023-12-13 09:46:56.852 INFO (MainThread) [music_assistant.players] Player registered: RINCON_542A1B892BFB01400/Wohnzimmer-Lautsprecher
2023-12-13 09:46:57.003 INFO (MainThread) [music_assistant.players] Player registered: RINCON_7828CAB45E5201400/Schlafzimmer-Sonos
2023-12-13 09:46:57.144 INFO (MainThread) [music_assistant.players] Player registered: RINCON_542A1B5D57F401400/Arbeitszimmer
2023-12-13 09:46:57.326 INFO (MainThread) [music_assistant.players] Player registered: RINCON_542A1B5D01D201400/Lautsprecher Flur
2023-12-13 09:46:57.511 INFO (MainThread) [music_assistant] Loaded player provider Airplay
2023-12-13 09:46:57.533 INFO (MainThread) [music_assistant.players] Player registered: aa:aa:8f:fa:1f:72/Schlafzimmer+
2023-12-13 09:46:57.713 INFO (MainThread) [music_assistant.music] Sync task for Qobuz completed
OzGav commented 11 months ago

Is that a DLNA player?

OzGav commented 11 months ago

If so please enable queue flow mode and see if that fixes it

nhadler commented 10 months ago

Also having this issue on 2.0.0b78 with a chromecast media player. 

2023-12-13 23:21:52.381 ERROR (MainThread) [asyncio] Task exception was never retrieved
future: <Task finished name='Task-302' coro=<TracksController.add_item_to_library() done, defined at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py:122> exception=AttributeError("'NoneType' object has no attribute 'get'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py", line 132, in add_item_to_library
    await self.mass.metadata.get_track_metadata(item)
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/metadata.py", line 169, in get_track_metadata
    if metadata := await provider.get_track_metadata(track):
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/theaudiodb/__init__.py", line 170, in get_track_metadata
    return self.__parse_track(adb_track)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/theaudiodb/__init__.py", line 242, in __parse_track
    metadata.lyrics = track_obj.get("strTrackLyrics")
                      ^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'get'
2023-12-13 23:21:52.538 ERROR (MainThread) [asyncio] Task exception was never retrieved
future: <Task finished name='Task-307' coro=<TracksController.add_item_to_library() done, defined at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py:122> exception=AttributeError("'NoneType' object has no attribute 'get'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py", line 132, in add_item_to_library
    await self.mass.metadata.get_track_metadata(item)
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/metadata.py", line 169, in get_track_metadata
    if metadata := await provider.get_track_metadata(track):
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/theaudiodb/__init__.py", line 170, in get_track_metadata
    return self.__parse_track(adb_track)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/theaudiodb/__init__.py", line 242, in __parse_track
    metadata.lyrics = track_obj.get("strTrackLyrics")
                      ^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'get'
2023-12-13 23:22:09.451 ERROR (MainThread) [asyncio] Task exception was never retrieved
future: <Task finished name='Task-345' coro=<TracksController.add_item_to_library() done, defined at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py:122> exception=AttributeError("'NoneType' object has no attribute 'get'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py", line 132, in add_item_to_library
    await self.mass.metadata.get_track_metadata(item)
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/metadata.py", line 169, in get_track_metadata
    if metadata := await provider.get_track_metadata(track):
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/theaudiodb/__init__.py", line 170, in get_track_metadata
    return self.__parse_track(adb_track)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/theaudiodb/__init__.py", line 242, in __parse_track
    metadata.lyrics = track_obj.get("strTrackLyrics")
                      ^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'get'
2023-12-13 23:22:15.596 INFO (ThreadPoolExecutor-0_5) [pychromecast.controllers] Receiver:Launching app CC1AD845
2023-12-13 23:22:15.877 ERROR (MainThread) [asyncio] Task exception was never retrieved
future: <Task finished name='Task-361' coro=<TracksController.add_item_to_library() done, defined at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py:122> exception=AttributeError("'NoneType' object has no attribute 'get'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py", line 132, in add_item_to_library
    await self.mass.metadata.get_track_metadata(item)
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/metadata.py", line 169, in get_track_metadata
    if metadata := await provider.get_track_metadata(track):
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/theaudiodb/__init__.py", line 170, in get_track_metadata
    return self.__parse_track(adb_track)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/theaudiodb/__init__.py", line 242, in __parse_track
    metadata.lyrics = track_obj.get("strTrackLyrics")
                      ^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'get'
2023-12-13 23:22:16.970 ERROR (MainThread) [asyncio] Task exception was never retrieved
future: <Task finished name='Task-367' coro=<TracksController.add_item_to_library() done, defined at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py:122> exception=AttributeError("'NoneType' object has no attribute 'get'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py", line 132, in add_item_to_library
    await self.mass.metadata.get_track_metadata(item)
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/metadata.py", line 169, in get_track_metadata
    if metadata := await provider.get_track_metadata(track):
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/theaudiodb/__init__.py", line 170, in get_track_metadata
    return self.__parse_track(adb_track)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/theaudiodb/__init__.py", line 242, in __parse_track
    metadata.lyrics = track_obj.get("strTrackLyrics")
                      ^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'get'
2023-12-13 23:22:52.305 ERROR (MainThread) [asyncio] Task exception was never retrieved
future: <Task finished name='Task-468' coro=<TracksController.add_item_to_library() done, defined at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py:122> exception=AttributeError("'NoneType' object has no attribute 'get'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py", line 132, in add_item_to_library
    await self.mass.metadata.get_track_metadata(item)
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/metadata.py", line 169, in get_track_metadata
    if metadata := await provider.get_track_metadata(track):
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/theaudiodb/__init__.py", line 170, in get_track_metadata
    return self.__parse_track(adb_track)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/theaudiodb/__init__.py", line 242, in __parse_track
    metadata.lyrics = track_obj.get("strTrackLyrics")
                      ^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'get'
OzGav commented 10 months ago

Is this playing then stopping or not starting at all?

nhadler commented 10 months ago

Is this playing then stopping or not starting at all?

Stops randomly while it's playing. Sometimes happens 30s in, or a minute or two

nhadler commented 10 months ago

I noticed this in my log when it occured:

2023-12-14 14:12:05.202 INFO (MainThread) [music_assistant.music] Sync task for Spotify completed
2023-12-14 14:49:53.877 WARNING (Thread-6) [pychromecast.socket_client] [Office clock(192.168.1.161):8009] Heartbeat timeout, resetting connection
2023-12-14 14:49:53.878 INFO (Thread-6) [pychromecast.controllers] Receiver:channel_disconnected
2023-12-14 14:50:23.908 ERROR (Thread-6) [pychromecast.socket_client] [Office clock(192.168.1.161):8009] Failed to connect to service ServiceInfo(type='host', data=('192.168.1.161', 8009)), retrying in 5.0s
OzGav commented 10 months ago

That is possibly a network error. Do you hear any poor quality audio before it stops?

nhadler commented 10 months ago

I don't, and the throughput of my network should be fairly good.

OzGav commented 10 months ago

Let’s experiment. Try changing the output codec to MP3 and see if that makes any difference. If that doesn’t help then try enabling queue flow mode

dbrand666 commented 10 months ago

I'm going to jump in here too. Let me know if I should open a separate issue. My player randomly stops playing a radio stream. I'm on Server version 2.0.0b78, player is piCorePlayer v8.2.0 Squeezelite v1.9.9-1392-pCP (I have 2 of them but this happens with only one online too). I have Tidal as well as local media over SMB but this happens often while I'm playing a radio stream at http://wfmu.org/wfmu.pls. What's weird is that if I check the logs right when it happens I often find an exception right when the music stops. Eg.

2023-12-23 14:27:48.939 INFO (MainThread) [music_assistant.music] Sync task for Filesystem (remote share) completed
2023-12-23 15:34:31.902 INFO (MainThread) [music_assistant.providers.tidal] Track 635892 has no available lyrics
2023-12-23 15:34:31.906 ERROR (MainThread) [asyncio] Task exception was never retrieved
future: <Task finished name='Task-441199' coro=<TracksController.add_item_to_library() done, defined at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py:122> exception=AttributeError("'ItemMapping' object has no attribute 'mbid'")>
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/media/tracks.py", line 132, in add_item_to_library
    await self.mass.metadata.get_track_metadata(item)
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/metadata.py", line 169, in get_track_metadata
    if metadata := await provider.get_track_metadata(track):
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/theaudiodb/__init__.py", line 165, in get_track_metadata
    if track.album.mbid and track.album.mbid != item["strMusicBrainzAlbumID"]:
       ^^^^^^^^^^^^^^^^
AttributeError: 'ItemMapping' object has no attribute 'mbid'

I realize this seems to be unrelated - I was listening to a radio stream, not Tidal, but maybe? I'll update this comment next time it happens.

melwinek commented 10 months ago

I confirm. On the radio stream and on the YT music playlist. After some time, playback stops. I have to press play again.

barrelltitor commented 10 months ago

I also have this issue on slimproto players. After some songs, the music unexpectedly stops until I play again.

Once I do hit play again, it starts the same song, it doesn't continue the next song in the playlist

BucciMobile commented 10 months ago

If so please enable queue flow mode and see if that fixes it

sorry for the late response. sadly queue flow mode did not fix the problem

Is that a DLNA player?

negativ.

joselao commented 10 months ago

Hi same problem here with ver: 2.0.0b81 the music stops after 1 or 2 mins, I have Sonos players (Cuina single player + Salon 2 units paired for stereo). All they works perfectly with the Sonos App, but with MA stops playing always. I got these logs (and I never got a Player RINCON_38420B971E5A01400 in my network):

2024-01-12 18:33:50.395 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue SONOS: SALON + CUINA 2024-01-12 18:33:51.148 WARNING (MainThread) [music_assistant.streams] Player RINCON_38420B975B4201400 is making multiple requests to the same stream, playback may be disturbed! 2024-01-12 18:37:02.742 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue SONOS: SALON + CUINA 2024-01-12 18:37:04.199 WARNING (MainThread) [music_assistant.streams] Detected existing (running) stream job for queue ugp_1 2024-01-12 18:37:04.202 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue SONOS: SALON + CUINA 2024-01-12 18:37:04.544 WARNING (MainThread) [music_assistant.streams] Player RINCON_38420B971E5A01400 is making multiple requests to the same stream, playback may be disturbed! 2024-01-12 18:37:35.884 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue SONOS: SALON + CUINA 2024-01-12 18:37:36.132 WARNING (MainThread) [music_assistant.streams] Player RINCON_38420B971E5A01400 is making multiple requests to the same stream, playback may be disturbed! 2024-01-12 18:37:42.664 WARNING (MainThread) [music_assistant.streams] Detected existing (running) stream job for queue ugp_1 2024-01-12 18:37:42.666 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue SONOS: SALON + CUINA 2024-01-12 18:37:42.787 WARNING (MainThread) [music_assistant.streams] Detected existing (running) stream job for queue ugp_1 2024-01-12 18:37:42.788 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue SONOS: SALON + CUINA 2024-01-12 18:37:45.028 WARNING (MainThread) [music_assistant.streams] Player RINCON_38420B971E5A01400 is making multiple requests to the same stream, playback may be disturbed! 2024-01-12 18:38:43.119 INFO (MainThread) [music_assistant.streams] Start Queue Flow stream for Queue SONOS: SALON + CUINA 2024-01-12 18:38:43.486 WARNING (MainThread) [music_assistant.streams] Player RINCON_38420B971E5A01400 is making multiple requests to the same stream, playback may be disturbed! 2024-01-12 18:42:18.897 WARNING (MainThread) [music_assistant.webserver] [139921940036816] Disconnected: Received non-Text message.

my config settings:

Screenshot 2024-01-12 at 20 28 33

Enabling for each one:

Thanks

Jose

BucciMobile commented 9 months ago

I was also wondering what "RINCON" is. Seems like it's a support/management function for Sonos:

https://bsteiner.info/articles/hidden-sonos-interface

joselao commented 9 months ago

yes!!! @BucciMobile, reading your link I can see that each Sonos in my network has a friendly name plus a LocalUID: "RINCON_xxxxxx" name... we only need check it here: http://<you_sonos_ip>:1400/support/review so my problem is related to: RINCON_38420B971E5A01400 that is: "SONOS salon (Left)" one of the Sonos that is paired for creating an stereo sound (Left+Right).... any clues?

mthxx commented 9 months ago

I came across this same issue earlier this week. I don't have a fix for the core issue, but I did find a temporary work around that so far seems to be working. If you use the Airplay protocol for your Sonos speakers, they seem to work correctly.

I tried both the Sonos Playerprovider for Music Assistant and the UPnP/DLNA Player Provider, and in both cases I got similar RINCON errors in my logs to what has been previously posted.

I did a bit of extra troubleshooting and I don't think this is a Music Assistant specific issue. I ran the same tests playing files directly out of Home Assistants media folder and encountered the same playback interruption issues. My media files are hosted on a Synology NAS on my local network and are connected to Home Assistant via the built in Network Storage connection. I've tested both mp3 and ogg with no apparent differences in behavior. I've also tested the same files directly from my Synology NAS via Synology's Audio Station and it worked as expected. So it appears to be a larger Home Assistant issue. Not a source file issue or a Music Assistant specific issue.

The speakers I am using are a Sonos Beam (ethernet), Sonos One (ethernet) and Sonos Roam (WiFi),

If there are any additional details I can provide that might be of help, please let me know.

OzGav commented 9 months ago

This should be fixed in beta 83 please advise if not