Unable to connect Squeezebox players (touch, boom, duet) to MAS

poerlemans commented 1 year ago

What version of Music Assistant has the issue?

2.0.0b32

The problem

When I try to connect squeezebox players with MAS, the players ate discovered by MAS but connection does not take place. I tried connection with Squeezebox Touch, Boom and Duet.

How to reproduce

As described in problem description: by trying to connect the player

Relevant log output

See descriptions below.

Additional information

See descriptions below

What version of Home Assistant Core are your running

2023.5.4

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)

poerlemans commented 1 year ago

I just tried to connect the squeezebox touch. The device is now visible in the list of players. Connection didn't succeed. I found the following log:

**2023-05-29 21:16:45 WARNING asyncio -- Executing <TimerHandle when=899038.402624412 SlimClient._send_heartbeat() created at /usr/local/lib/python3.11/site-packages/aioslimproto/client.py:643> took 0.235 seconds,

2023-05-29 21:17:13 WARNING asyncio -- Executing <TimerHandle when=899066.218535322 SlimClient._send_heartbeat() created at /usr/local/lib/python3.11/site-packages/aioslimproto/client.py:643> took 0.217 seconds

2023-05-29 21:17:41 WARNING asyncio -- Executing <Task pending name='Task-1205355' coro=<BaseSelectorEventLoop._accept_connection2() running at /usr/local/lib/python3.11/asyncio/selector_events.py:222> 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/selector_events.py:198> took 0.221 seconds,

2023-05-29 21:18:00 WARNING asyncio -- Executing <Task finished name='Task-1210075' coro=<SlimClient._process_helo() done, defined at /usr/local/lib/python3.11/site-packages/aioslimproto/client.py:504> result=None created at /usr/local/lib/python3.11/asyncio/tasks.py:374> took 0.207 seconds,

2023-05-29 21:18:09 WARNING asyncio -- Executing <Task finished name='Task-1212123' coro=<SlimprotoProvider._create_client() done, defined at /usr/local/lib/python3.11/site-packages/music_assistant/server/providers/slimproto/init.py:149> result=None created at /usr/local/lib/python3.11/asyncio/streams.py:249> took 0.218 seconds,

2023-05-29 21:21:15 WARNING asyncio -- Executing <Handle StreamReaderProtocol.connection_made(<_SelectorSoc...e, bufsize=0>>) created at /usr/local/lib/python3.11/asyncio/selector_events.py:915> took 0.206 seconds, 2023-05-29 21:19:20 INFO music_assistant.players -- Player registered: 00:04:20:22:7e:5b/controller: 00:04:20:22:7e:5b 2023-05-29 21:21:53 WARNING asyncio -- Executing <Handle StreamReaderProtocol.connection_made(<_SelectorSoc...e, bufsize=0>>) created at /usr/local/lib/python3.11/asyncio/selector_events.py:915> took 0.223 seconds**

poerlemans commented 1 year ago

Included a log of AVR-X2800 (thanks to the integration with Home Assistant):

The log in the last comment (start sleeping at 21:18:00) corresponds with the Home Assistant log:

2023-05-29 21:18:00 WARNING asyncio -- Executing <Task finished name='Task-1210075' coro=<SlimClient._process_helo() done, defined at /usr/local/lib/python3.11/site-packages/aioslimproto/client.py:504> result=None created at /usr/local/lib/python3.11/asyncio/tasks.py:374> took 0.207 seconds,

poerlemans commented 1 year ago

When I try to connect to the MAS music library, using the squeezebox duet controller, I get the following logs:

_2023-05-30 11:36:36 WARNING asyncio -- Executing <Task pending name='Task-39' coro=<MusicController._start_provider_sync..run_sync() running at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/music.py:544> 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=[MusicAssistant.create_task..task_done_callback() at /usr/local/lib/python3.11/site-packages/music_assistant/server/server.py:293, MusicController._start_provider_sync..on_sync_task_done() at /usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/music.py:558] created at /usr/local/lib/python3.11/site-packages/music_assistant/server/server.py:286> took 0.150 seconds, future: <Task finished name='Task-724' coro=<SlimClient.volume_set() done, defined at /usr/local/lib/python3.11/site-packages/aioslimproto/client.py:301> exception=OSError(107, 'Transport endpoint is not connected') created at /usr/local/lib/python3.11/site-packages/music_assistant/server/server.py:286>, 2023-05-30 11:40:26 ERROR asyncio -- Task exception was never retrieved, File "/usr/local/bin/mass", line 8, in , source_traceback: Object created at (most recent call last):, sys.exit(main()), File "/usr/local/lib/python3.11/asyncio/events.py", line 80, in _run, handle._run(), File "/usr/local/lib/python3.11/asyncio/base_events.py", line 1914, in _run_once, File "/usr/local/lib/python3.11/asyncio/base_events.py", line 607, in run_forever, self._run_once(), loop.run_forever(), run(, File "/usr/local/lib/python3.11/site-packages/music_assistant/main.py", line 108, in main, File "/usr/local/lib/python3.11/site-packages/aiorun.py", line 273, in run, self._context.run(self._callback, *self._args), File "/usr/local/lib/python3.11/site-packages/aioslimproto/client.py", line 526, in _process_helo, self.callback(EventType.PLAYER_CONNECTED, self), File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/slimproto/init.py", line 166, in client_callback, self._handle_connected(client), File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/slimproto/init.py", line 523, in _handle_connected, self.mass.create_task(client.volume_set(init_volume)), File "/usr/local/lib/python3.11/site-packages/music_assistant/server/server.py", line 286, in create_task, task = self.loop.create_task(target), Traceback (most recent call last):, File "/usr/local/lib/python3.11/site-packages/aioslimproto/client.py", line 306, in volume_set, await self._send_frame(, File "/usr/local/lib/python3.11/site-packages/aioslimproto/client.py", line 424, in _send_frame, self.disconnect(), File "/usr/local/lib/python3.11/site-packages/aioslimproto/client.py", line 182, in disconnect, self._writer.write_eof(), File "/usr/local/lib/python3.11/asyncio/streams.py", line 338, in write_eof, return self._transport.write_eof(), ^^^^^^^^^^^^^^^^^^^^^^^^^^^, File "/usr/local/lib/python3.11/asyncio/selector_events.py", line 1111, in write_eof, self.sock.shutdown(socket.SHUT_WR), OSError: [Errno 107] Transport endpoint is not connected

poerlemans commented 1 year ago

Trying to discover Squeezebox Boom by MAS, I get the following logs:

2023-05-30 11:48:46 ERROR aioslimproto.discovery -- Error occured while trying to parse a datagram from ('192.168.1.25', 3483) - data: b'd\x00\n9\x00\x00\x00\x00\x00\x00\x00\x00\x00\x04 \x1en\x7f' Traceback (most recent call last): File "/usr/local/lib/python3.11/site-packages/aioslimproto/discovery.py", line 205, in datagram_received dgram = Datagram.decode(data) ^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/aioslimproto/discovery.py", line 42, in decode return ClientDiscoveryDatagram(data) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/aioslimproto/discovery.py", line 63, in init assert msg[0] == "d" ^^^^^^^^^^^^^ AssertionError

Discovery has not been taken place.

poerlemans commented 1 year ago

Boom player was connected with mysqueezebox.com. After disconnecting the Boom player is discovered by MAS. But after discovery same kind of logs:

2023-05-30 12:10:37 INFO music_assistant.players -- Player registered: 00:04:20:1e:6e:7f/boom: 00:04:20:1e:6e:7f

2023-05-30 12:12:11 ERROR aioslimproto.discovery -- Error occured while trying to parse a datagram from ('192.168.1.25', 3483) - data: b'd\x00\n9\x00\x00\x00\x00\x00\x00\x00\x00\x00\x04 \x1en\x7f' Traceback (most recent call last): File "/usr/local/lib/python3.11/site-packages/aioslimproto/discovery.py", line 205, in datagram_received dgram = Datagram.decode(data) ^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/aioslimproto/discovery.py", line 42, in decode return ClientDiscoveryDatagram(data) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/aioslimproto/discovery.py", line 63, in init assert msg[0] == "d" ^^^^^^^^^^^^^ AssertionError

erkr commented 1 year ago

@poerlemans just to rule out the obvious; do you have the slimproto integration installed in HA? Or some LMS server? If so that interferes with the slimproto provider in MA

poerlemans commented 1 year ago

I have not installed the slimproto integration in HA. For controlling the squeezeboxes in HA I use the Squeezebox integration. But, because of the fact that the LMS server is not running anymore (because I use now MAS), this Squeezebox integration is useless. The connection problems of my squeezebox devices as described above were already present before HA integration of MAS was realized.

marcelveldt commented 1 year ago

Yeah I guess @erkr missed the conversation we already had about this in that other issue report. I have squashed a lot of slimproto bugs last couple of days so maybe I have fixed this one too but I do not have any old style squeezebox hardware here like the Boom or Duet, only the "Radio".

poerlemans commented 1 year ago

I'm very curious to see the effect of elimination of several slimproto bugs. I will test the improvements on real squeezebox hardware.

erkr commented 1 year ago

Yeah I guess @erkr missed the conversation we already had about this

Yep sorry

OzGav commented 1 year ago

Please try with beta 36

poerlemans commented 1 year ago

I tested beta 35 with Squeezebox Touch, Boom and Duet. Connection was possible with all three players. Connection very stable with Squeezebox Touch (ethernet network connection). Connection with Squeezebox Boom and Duet (both Wifi connection) sometimes interrupted and restored after some time. Control of the players via Music Assistant web interface went smoothly. Conclusion: very impressive improvements!

But very frequently the following log:

2023-06-10 12:15:54 ERROR asyncio -- Task exception was never retrieved future: <Task finished name='Task-15731' coro=<LmsCli._handle_cometd_request.._handle() done, defined at /usr/local/lib/python3.11/site-packages/music_assistant/server/providers/slimproto/cli.py:549> exception=ValueError('too many values to unpack (expected 2)') created at /usr/local/lib/python3.11/site-packages/music_assistant/server/server.py:284> source_traceback: Object created at (most recent call last): File "/usr/local/bin/mass", line 8, in sys.exit(main()) File "/usr/local/lib/python3.11/site-packages/music_assistant/main.py", line 108, in main run( File "/usr/local/lib/python3.11/site-packages/aiorun.py", line 273, in run loop.run_forever() File "/usr/local/lib/python3.11/asyncio/base_events.py", line 607, in run_forever self._run_once() File "/usr/local/lib/python3.11/asyncio/base_events.py", line 1914, in _run_once handle._run() File "/usr/local/lib/python3.11/asyncio/events.py", line 80, in _run self._context.run(self._callback, *self._args) File "/usr/local/lib/python3.11/site-packages/aiohttp/web_protocol.py", line 433, in _handle_request resp = await request_handler(request) File "/usr/local/lib/python3.11/site-packages/aiohttp/web_app.py", line 504, in _handle resp = await handler(request) File "/usr/local/lib/python3.11/site-packages/music_assistant/server/controllers/webserver.py", line 115, in _handle_catch_all return await handler(request) File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/slimproto/cli.py", line 485, in _handle_cometd self._handle_cometd_request(cometd_client, cometd_msg) File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/slimproto/cli.py", line 560, in _handle_cometd_request self.mass.create_task(_handle()) File "/usr/local/lib/python3.11/site-packages/music_assistant/server/server.py", line 284, in create_task task = self.loop.create_task(target) Traceback (most recent call last): File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/slimproto/cli.py", line 550, in _handle result = await self._handle_request(cometd_request["data"]["request"]) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/slimproto/cli.py", line 579, in _handle_request cmd_result = await cmd_result ^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/slimproto/cli.py", line 632, in _handle_status return player_status_from_mass( ^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/slimproto/models.py", line 348, in player_status_from_mass cur_item = playlist_item_from_mass(mass, queue.current_item, queue.current_index, True) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.11/site-packages/music_assistant/server/providers/slimproto/models.py", line 179, in playlist_item_from_mass artist, track = queue_item.streamdetails.stream_title.split(" - ") ^^^^^^^^^^^^^ ValueError: too many values to unpack (expected 2)

poerlemans commented 1 year ago

I have the strong impression that the connection interruptions with the Squeezebox Boom and Duet are not related to a bad Wifi connection. In my router I see upload and download activities during the time the player is not available in Music Assistant.

OzGav commented 1 year ago

There can be uploads and downloads happening but if the bitrate can’t be supported then interruptions will occur. You can try lower quality streams such as mp3 in the advanced settings

marcelveldt commented 1 year ago

Cool to hear this progress and that it now works for like 90% already. I'll fix that last error you spotted in the logs. I also think that is what causes the interruptions as I noticed that all the "jive" based squeezebox players are really sensitive to errors in the cli. I had to reverse engineer Logitech Media Server in order to get it working but thats parts of the challenge.

poerlemans commented 1 year ago

Connection problems between Music Assistant and the players (Duet or Boom) also occur when nothing is playing. But I will try what lowering the quality stream will bring. @marcelveldt I'm also very positive about what is realized already. For some reason interruptions were much less present this evening than some hours ago. So I hope that further improvement of the cli will result in good news.

poerlemans commented 1 year ago

@marcelveldt , @OzGav : I was talking about connection problems here above (https://github.com/music-assistant/hass-music-assistant/issues/1273#issuecomment-1585818104). I found these problems had to do with my internal network. After some adjustments, connection problems removed!

OzGav commented 1 year ago

@poerlemans Ok so confirming all your squeeze box players are working fine now. If so I will close this

poerlemans commented 1 year ago

There are some things left that are not functioning well (but maybe there is already worked on):

On the squeezebox controller (belonging to Duet) and Squeezeplay in the "My Music"-tab the in Music Assistant choosen presets are shown. So the music library as scanned in Music Assistant is not shown. Consequently the controller (Duet and Squeezeplay) cannot be applied for selecting music from the music library.
The power on/power off button of the Boom isn't activated. Also the control-light on the Duet-player keeps on blinking when power off the device in Music Assistant.
The preset-tabs on the Boom are not corresponding with the presets in the corresponding player in Music Assistant. I have the impression that the preset-tabs on the Boom are not functioning at all.

But on the whole a lot of progress has been made the last month concerning the application of the squeezebox hardware in Music Assistant. Thank you for all your effort!

OzGav commented 1 year ago

Ok I am going to spawn a new issue with the above feature requests to tidy things up. Likely this will be low priority but will be addressed at some point.

music-assistant / hass-music-assistant