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

Airplay to Shairport and Kodi at Ubuntu #1217

Closed gost4711 closed 1 year ago

gost4711 commented 1 year ago

What version of Music Assistant has the issue?

2.0.0b29

The problem

Hi, Airplay to Linux is not running.

How to reproduce

Play with Airport Player

Relevant log output

     7.448111326 "rtsp.c:747" mutex_lock "&conns_lock".
     0.000137445 "rtsp.c:750" found RTSP connection thread 1 in a non-running state.
     0.000047485 "rtsp.c:753" Connection 1: deleted in cleanup.
     0.000010232 "common.c:1565" mutex_unlock "&conns_lock" at "rtsp.c:758".
     0.000101871 "rtsp.c:5564" Connection 2: New connection from 10.0.0.90:54317 to self at 10.0.0.37:7000.
     0.000079996 "rtsp.c:5580" Successfully created RTSP receiver thread 2.
     0.000072179 "rtsp.c:687" mutex_lock "&conns_lock".
     0.000010657 "common.c:1565" mutex_unlock "&conns_lock" at "rtsp.c:709".
     0.100100713 "rtsp.c:808" msg_init message 3
     0.000250007 "rtsp.c:917" RTSP Message Received: "POST /auth-setup RTSP/1.0".
     0.000193793 "rtsp.c:948"     Content-Type: application/octet-stream.
     0.000029602 "rtsp.c:948"     Content-Length: 33.
     0.000012326 "rtsp.c:948"     CSeq: 1.
     0.000012495 "rtsp.c:948"     User-Agent: iTunes/7.6.2 (Windows; N;).
     0.000012089 "rtsp.c:948"     Client-Instance: b72528cb39f38ded.
     0.000073562 "rtsp.c:948"     DACP-ID: 1A2B3D4EA1B2C3D4.
     0.000020486 "rtsp.c:948"     Active-Remote: 2766559501.
     0.000027039 "rtsp.c:808" msg_init message 4
     0.000013259 "rtsp.c:5149" Connection 2: Received an RTSP Packet of type "POST":
     0.000071897 "rtsp.c:5151"   Type: "Content-Type", content: "application/octet-stream"
     0.000021767 "rtsp.c:5151"   Type: "Content-Length", content: "33"
     0.000014393 "rtsp.c:5151"   Type: "CSeq", content: "1"
     0.000012308 "rtsp.c:5151"   Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
     0.000012239 "rtsp.c:5151"   Type: "Client-Instance", content: "b72528cb39f38ded"
     0.000011821 "rtsp.c:5151"   Type: "DACP-ID", content: "1A2B3D4EA1B2C3D4"
     0.000094511 "rtsp.c:5151"   Type: "Active-Remote", content: "2766559501"
     0.000026504 "rtsp.c:5151"   No Content Plist. Content length: 33.
     0.000014835 "rtsp.c:2568" Connection 2: Unhandled POST /auth-setup Content-Length 33
     0.000012471 "rtsp.c:2570" POST request
     0.000012615 "rtsp.c:2570"   Type: "Content-Type", content: "application/octet-stream"
     0.000013547 "rtsp.c:2570"   Type: "Content-Length", content: "33"
     0.000011908 "rtsp.c:2570"   Type: "CSeq", content: "1"
     0.000087558 "rtsp.c:2570"   Type: "User-Agent", content: "iTunes/7.6.2 (Windows; N;)"
     0.000026447 "rtsp.c:2570"   Type: "Client-Instance", content: "b72528cb39f38ded"
     0.000012249 "rtsp.c:2570"   Type: "DACP-ID", content: "1A2B3D4EA1B2C3D4"
     0.000011906 "rtsp.c:2570"   Type: "Active-Remote", content: "2766559501"
     0.000011956 "rtsp.c:2570"   No Content Plist. Content length: 33.
     0.000011799 "rtsp.c:5210" Connection 2: RTSP Response:
     0.000011925 "rtsp.c:5211"   Response Code: 200.
     0.000094301 "rtsp.c:5211"   Type: "CSeq", content: "1"
     0.000013972 "rtsp.c:5211"   Type: "Server", content: "AirTunes/366.0"
     0.000012680 "rtsp.c:5211"   No Content Plist. Content length: 0.
     0.000046051 "rtsp.c:893" msg_free freed message 4
     0.000139018 "rtsp.c:893" msg_free freed message 3
     0.126688034 "rtsp.c:1353" Connection 2: Connection closed by client.
     0.000038136 "rtsp.c:5282" Connection 2: Terminate RTSP connection.
     0.000009544 "rtsp.c:4985" Connection 2: rtsp_conversation_thread_func_cleanup_function called.
     0.000008010 "rtsp.c:2657" Connection 2: TEARDOWN unspecified stream connection.
     0.000007860 "rtsp.c:4999" Connection 2: terminating  -- closing timing, control and audio sockets...
     0.000007496 "rtsp.c:5020" Connection 2: terminating -- closing RTSP connection socket 8: from 10.0.0.90:54317 to self at 10.0.0.37:7000.
     0.000043491 "rtsp.c:5073" Cancel watchdog thread.
     0.000029670 "rtsp.c:5075" Join watchdog thread.
     0.000122876 "rtsp.c:635" Connection 2: Watchdog Exit.
     0.000150348 "rtsp.c:5077" Delete watchdog mutex.
     0.000013115 "rtsp.c:5083" Connection 2: Closed.

Additional information

No response

What version of Home Assistant Core are your running

2023.2.2

What type of installation are you running?

Home Assistant OS

On what type of hardware are you running?

Raspberry Pi

OzGav commented 1 year ago

Can you check that you have actually pasted in the MA log. That doesn’t look like what the MA log normally contains?

gost4711 commented 1 year ago

No this was the log from shairport. Here is the log from MA

2023-04-26 19:38:54 DEBUG music_assistant -- Loading provider TheAudioDB Metadata provider 2023-04-26 19:38:54 DEBUG music_assistant -- Loading provider LMS CLI 2023-04-26 19:38:54 DEBUG music_assistant -- Loading provider Tune-In Radio 2023-04-26 19:38:54 INFO music_assistant -- Loaded player provider SONOS 2023-04-26 19:38:54 DEBUG music_assistant.event -- providers_updated 2023-04-26 19:38:54 INFO music_assistant -- Loaded metadata provider MusicBrainz Metadata provider 2023-04-26 19:38:54 DEBUG music_assistant.event -- providers_updated 2023-04-26 19:38:54 INFO music_assistant -- Loaded plugin provider Websocket API 2023-04-26 19:38:54 DEBUG pychromecast.discovery -- HostBrowser thread started 2023-04-26 19:38:54 DEBUG music_assistant.event -- providers_updated 2023-04-26 19:38:54 INFO music_assistant -- Loaded music provider URL 2023-04-26 19:38:54 DEBUG music_assistant.event -- providers_updated 2023-04-26 19:38:54 DEBUG music_assistant.event -- sync_tasks_updated 2023-04-26 19:38:54 INFO music_assistant -- Loaded metadata provider fanart.tv Metadata provider 2023-04-26 19:38:54 DEBUG music_assistant.event -- providers_updated 2023-04-26 19:38:54 INFO music_assistant -- Loaded metadata provider TheAudioDB Metadata provider 2023-04-26 19:38:54 DEBUG music_assistant.event -- providers_updated 2023-04-26 19:38:54 INFO music_assistant.providers.lms_cli -- Registering jsonrpc endpoints on the webserver 2023-04-26 19:38:54 WARNING music_assistant.providers.tunein -- Emailadress detected instead of username, it is advised to use the tunein username instead of email. 2023-04-26 19:38:54 INFO music_assistant -- Loaded music provider Tune-In Radio 2023-04-26 19:38:54 DEBUG music_assistant.event -- providers_updated 2023-04-26 19:38:54 DEBUG music_assistant.event -- sync_tasks_updated 2023-04-26 19:38:54 DEBUG music_assistant.providers.sonos -- Sonos discovery started... 2023-04-26 19:38:54 DEBUG music_assistant.metadata -- Start scan for missing artist metadata 2023-04-26 19:38:54 DEBUG music_assistant.providers.tunein -- Start sync of radio items. 2023-04-26 19:38:54 INFO music_assistant -- Loaded player provider Chromecast 2023-04-26 19:38:54 DEBUG music_assistant.event -- providers_updated 2023-04-26 19:38:54 DEBUG music_assistant.event -- sync_tasks_updated 2023-04-26 19:38:54 INFO music_assistant.providers.lms_cli -- Starting (telnet) CLI on port 9090 2023-04-26 19:38:54 INFO music_assistant -- Loaded plugin provider LMS CLI 2023-04-26 19:38:54 DEBUG music_assistant.event -- providers_updated 2023-04-26 19:38:54 DEBUG music_assistant.metadata -- Finished scan for missing artist metadata 2023-04-26 19:38:55 DEBUG music_assistant -- Provider slimproto is not available 2023-04-26 19:38:55 INFO music_assistant.providers.slimproto -- Starting SLIMProto server on port 3483 2023-04-26 19:38:55 INFO music_assistant -- Loaded player provider Slimproto 2023-04-26 19:38:55 DEBUG music_assistant.event -- providers_updated 2023-04-26 19:38:56 INFO music_assistant -- Loaded player provider Airplay 2023-04-26 19:38:56 DEBUG music_assistant.event -- providers_updated 2023-04-26 19:38:56 DEBUG music_assistant.providers.airplay -- Starting Airplay bridge using config file /data/airplay_bridge.xml 2023-04-26 19:38:56 DEBUG music_assistant -- Starting Zeroconf broadcast... 2023-04-26 19:38:57 WARNING asyncio -- Executing <Task finished name='Task-2' coro=<run..new_coro() done, defined at /usr/local/lib/python3.11/site-packages/aiorun.py:227> result=None> took 0.808 seconds 2023-04-26 19:38:57 DEBUG music_assistant.providers.slimproto -- Socket client connected: ('127.0.0.1', 43452) 2023-04-26 19:38:57 DEBUG aioslimproto.client -- HELO received: b'\x0c\x00\xaa\xaa\rY\xe6\xa4\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00CanHTTPS=1,Model=squeezelite,ModelName=RaopBridge,AccuratePlayPoints=0,HasDigitalOut=1,MaxSampleRate=44100,pcm' 2023-04-26 19:38:57 DEBUG aioslimproto.client -- Player connected: aa:aa:0d:59:e6:a4 2023-04-26 19:38:57 INFO music_assistant.players -- Player registered: aa:aa:0d:59:e6:a4/squeezeplay: aa:aa:0d:59:e6:a4 2023-04-26 19:38:57 DEBUG music_assistant.event -- player_added aa:aa:0d:59:e6:a4 2023-04-26 19:38:57 DEBUG music_assistant.event -- player_updated aa:aa:0d:59:e6:a4 2023-04-26 19:38:57 DEBUG music_assistant.event -- player_updated aa:aa:0d:59:e6:a4 2023-04-26 19:38:57 DEBUG music_assistant.event -- player_updated aa:aa:0d:59:e6:a4 2023-04-26 19:38:57 DEBUG music_assistant.event -- player_updated aa:aa:0d:59:e6:a4 2023-04-26 19:38:57 DEBUG music_assistant.event -- queue_updated aa:aa:0d:59:e6:a4 2023-04-26 19:38:58 DEBUG music_assistant.websocket_api -- [140417102695376] Connection from 172.30.32.2 2023-04-26 19:38:58 DEBUG music_assistant.websocket_api -- [140417102695376] Handling command players/all 2023-04-26 19:38:58 DEBUG music_assistant.websocket_api -- [140417102695376] Handling command players/queue/all 2023-04-26 19:38:58 DEBUG music_assistant.websocket_api -- [140417102695376] Handling command music/albumartists 2023-04-26 19:38:58 DEBUG music_assistant.websocket_api -- [140417102695376] Handling command providers/available 2023-04-26 19:38:58 DEBUG music_assistant.websocket_api -- [140417102695376] Handling command providers 2023-04-26 19:38:58 DEBUG music_assistant.websocket_api -- [140417102695376] Handling command music/synctasks 2023-04-26 19:39:00 DEBUG music_assistant.websocket_api -- [140417102695376] Handling command config/providers 2023-04-26 19:39:00 DEBUG music_assistant.event -- sync_tasks_updated 2023-04-26 19:39:02 DEBUG music_assistant.server.controllers.config -- Saved data to persistent storage 2023-04-26 19:39:04 DEBUG music_assistant.websocket_api -- [140417102695376] Handling command config/players 2023-04-26 19:39:12 DEBUG music_assistant.websocket_api -- [140417102695376] Handling command config/providers 2023-04-26 19:39:15 DEBUG music_assistant.websocket_api -- [140417102695376] Handling command players/queue/play_pause 2023-04-26 19:39:15 DEBUG music_assistant.event -- queue_updated aa:aa:0d:59:e6:a4 2023-04-26 19:39:15 DEBUG music_assistant.event -- player_updated aa:aa:0d:59:e6:a4 2023-04-26 19:39:15 DEBUG aioslimproto.client.Test-ubuntu -- play url: http://10.0.0.90:8095/stream/aa:aa:0d:59:e6:a4/2910e364fa094f0f95a273578267a6e0/3BPFWnuanpdkr5ysUcYrAn.pcm 2023-04-26 19:39:15 DEBUG aioslimproto.client.Test-ubuntu -- STMf received - connection closed. 2023-04-26 19:39:15 DEBUG aioslimproto.client.Test-ubuntu -- STMf received - connection closed. 2023-04-26 19:39:15 DEBUG music_assistant.audio -- start media stream for: tunein://radio/s6634 2023-04-26 19:39:15 DEBUG music_assistant.audio -- writer started for tunein://radio/s6634 2023-04-26 19:39:15 DEBUG aioslimproto.client.Test-ubuntu -- STMc received - connected. 2023-04-26 19:39:15 DEBUG music_assistant.streams -- Got GET request to /stream/aa:aa:0d:59:e6:a4/2910e364fa094f0f95a273578267a6e0/3BPFWnuanpdkr5ysUcYrAn.pcm from 10.0.0.90 headers: <CIMultiDictProxy('Host': '10.0.0.90:8095', 'Connection': 'close', 'Accept': '/', 'Cache-Control': 'no-cache', 'User-Agent': 'VLC/3.0.9 LibVLC/3.0.9', 'Range': 'bytes=0-')> 2023-04-26 19:39:15 DEBUG music_assistant.streams -- Start serving audio stream 3BPFWnuanpdkr5ysUcYrAn to Test-ubuntu 2023-04-26 19:39:15 DEBUG aioslimproto.client.Test-ubuntu -- RESP received - Response received at player. 2023-04-26 19:39:15 DEBUG aioslimproto.client.Test-ubuntu -- send CODC for contenttype audio/x-wav;codec=pcm;rate=44100;bitrate=16;channels=2: b'p1321' 2023-04-26 19:39:15 DEBUG music_assistant.audio -- Start streaming radio with ICY metadata from url https://mdr-284320-0.sslcast.mdr.de/mdr/284320/0/mp3/high/stream.mp3?ar-distributor=f0a1 2023-04-26 19:39:15 DEBUG aioslimproto.client.Test-ubuntu -- Socket disconnected: ('127.0.0.1', 43452) 2023-04-26 19:39:15 DEBUG music_assistant.event -- queue_updated aa:aa:0d:59:e6:a4 2023-04-26 19:39:15 DEBUG music_assistant.event -- player_updated aa:aa:0d:59:e6:a4 2023-04-26 19:39:15 DEBUG music_assistant.providers.airplay -- Airplay Bridge process stopped Guessed Channel Layout for Input Stream #0.0 : stereo 2023-04-26 19:39:16 DEBUG music_assistant.providers.slimproto -- Socket client connected: ('127.0.0.1', 48234) 2023-04-26 19:39:16 DEBUG aioslimproto.client -- HELO received: b'\x0c\x00\xaa\xaa\rY\xe6\xa4\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00CanHTTPS=1,Model=squeezelite,ModelName=RaopBridge,AccuratePlayPoints=0,HasDigitalOut=1,MaxSampleRate=44100,pcm' 2023-04-26 19:39:16 DEBUG aioslimproto.client -- Player connected: aa:aa:0d:59:e6:a4 2023-04-26 19:39:16 DEBUG music_assistant.event -- queue_updated aa:aa:0d:59:e6:a4 2023-04-26 19:39:16 DEBUG music_assistant.event -- player_updated aa:aa:0d:59:e6:a4 2023-04-26 19:39:16 DEBUG music_assistant.event -- player_updated aa:aa:0d:59:e6:a4 2023-04-26 19:39:16 DEBUG music_assistant.event -- queue_updated aa:aa:0d:59:e6:a4 2023-04-26 19:39:16 DEBUG music_assistant.event -- player_updated aa:aa:0d:59:e6:a4 2023-04-26 19:39:17 DEBUG aioslimproto.client.Test-ubuntu -- Socket is disconnected. 2023-04-26 19:39:24 DEBUG music_assistant.websocket_api -- [140417102695376] Handling command config/players 2023-04-26 19:39:25 DEBUG music_assistant.websocket_api -- [140417102695376] Handling command config/providers 2023-04-26 19:39:26 DEBUG music_assistant.websocket_api -- [140417102695376] Handling command music/albumartists 2023-04-26 19:39:26 DEBUG aiohttp.server -- Ignored premature client disconnection. 2023-04-26 19:39:27 DEBUG music_assistant.websocket_api -- [140417102695376] Unsubscribed from events 2023-04-26 19:39:27 DEBUG music_assistant.websocket_api -- [140417102695376] Disconnected 2023-04-26 19:39:27 DEBUG aiohttp.server -- Ignored premature client disconnection.

OzGav commented 1 year ago

I don’t see any related errors there. What exactly is happening? Is the player detected at MA startup?

gost4711 commented 1 year ago

The player is recognized. I press the play button and nothing happens. Access can be seen in the Shaireport log (the first log). The Player is "Test-ubuntu".

erkr commented 1 year ago

I don't see obvious issues in the log either. Did you try other stations or music providers, like local files or Spotify as well? And please check your TuneIn config as I see this in the log:

2023-04-26 19:38:54 WARNING music_assistant.providers.tunein -- Emailadress detected instead of username, it is advised to use the tunein username instead of email.
gost4711 commented 1 year ago

Yes, I also tested other things. But now I have found a solution. I reconfigured shairport so that only Airplay 1 is used. Now it works. I can live with that. Thanks

OzGav commented 1 year ago

Indeed. Only Airplay 1 is supported in MA. Thanks for following this through. The docs have been updated.