philippe44 / AirConnect

Use AirPlay to stream to UPnP/Sonos & Chromecast devices
Other
3.43k stars 216 forks source link

Aircast sends 500 error when used with pipewire airplay sink #492

Closed sidevesh closed 8 months ago

sidevesh commented 8 months ago

Airconnect seems to be failing to play for more than 1 second when I try to play from my linux laptop with pipewire's built in airplay support, things are working well from MacBook, looks like airconnect can't handle some request and returns 500 breaking playback:

root@Home-Server-Pi-4:/# /bin/aircast-linux-arm -x /config/config.xml
[23:48:45.766846] main:923 Starting aircast version: v1.2.2 (Sep 29 2023 @ 15:45:45)
[23:48:45.767521] Start:689 Binding to 192.168.0.100 [eth0] with mask 0xffffff00
[23:48:45.783818] Start:715 Starting pico HTTP server on port 59369
[23:48:45.788057] AddCastDevice:653 [0x1e3f2c0]: adding renderer (Living Room TV - 192.168.0.111:8009) with mac CCCC2F4320CE
[23:48:45.804454] AddCastDevice:653 [0x1e3fc38]: adding renderer (Living Room display - 192.168.0.185:8009) with mac CCCC30DF715B
[23:48:45.808046] AddCastDevice:653 [0x1e405b0]: adding renderer (Bedroom speaker - 192.168.0.110:8009) with mac CCCC27398659
[23:49:04.613537] rtsp_thread:338 got RTSP connection 14
[23:49:04.620980] handle_rtsp:379 [0xf50604c8]: received ANNOUNCE
[23:49:04.621058] handle_rtsp:385 [0xf50604c8]: challenge Fh8FVhFxbu2LAeVZlSHaVw
[23:49:04.642203] handle_rtsp:592 [0xf50604c8]: responding:
RTSP/1.0 200 OK
Apple-Response: GdvPPuwKkekOszxTSC+cHgpy0T94NgAwA3xcJLRpXYbpzYlLyT4mYzrkuVs4egtat+/31y4GAtw5pnISnFWRGWfOFQGPcpgNkvZWeq4p78WsDBFcawJSMHoxssxhKaPFCgnWSKBAg0XMm/HDBRuFt8AftQ41o0Sd2bMP3blxVVZUZDNCbK2wdIktqdaePq0ZlbnT6IXYMI2eKaixojFPo+9o+vrz9X+yG6r2B0sxocdRMs+oIxlDjO+5gI7O+P8A0l+sj8ttZVjdxlUX7e/6zsL7r9QGecnpg0A+n4tbbvuMI4dJjoG4DMg7vj9DklOfMARprnkrV6PxpwsR5XfVWw
Audio-Jack-Status: connected; type=analog
CSeq: 2

[23:49:04.648573] handle_rtsp:379 [0xf50604c8]: received SETUP
[23:49:04.654522] raopst_init:378 [0xeee0df98]: UDP port-0 54792
[23:49:04.654651] raopst_init:378 [0xeee0df98]: UDP port-1 57776
[23:49:04.654816] raopst_init:378 [0xeee0df98]: UDP port-2 34377
[23:49:04.654960] raopst_init:396 [0xeee0df98]: HTTP listening port 57051
[23:49:04.655462] handle_rtsp:592 [0xf50604c8]: responding:
RTSP/1.0 200 OK
Transport: RTP/AVP/UDP;unicast;mode=record;control_port=57776;timing_port=34377;server_port=54792
Session: DEADBEEF
Audio-Jack-Status: connected; type=analog
CSeq: 3

[23:49:04.657932] rtp_thread_func:764 [0xeee0df98]: discarding NTP roundtrip of 2076865586 ms
[23:49:04.659764] handle_rtsp:379 [0xf50604c8]: received RECORD
[23:49:04.659835] raopst_record:502 [0xeee0df98]: record 48765 921190717
[23:49:04.659905] raop_cb:182 [0x1e3fc38]: Stream
[23:49:04.660030] handle_rtsp:592 [0xf50604c8]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 4

[23:49:04.663521] handle_rtsp:379 [0xf50604c8]: received SET_PARAMETER
[23:49:04.663601] handle_rtsp:546 [0xf50604c8]: SET PARAMETER volume -1.799927
[23:49:04.663689] CastSetDeviceVolume:373 [0x1e3fc38]: Queuing SET_VOLUME
[23:49:04.663711] raop_cb:232 [0x1e3fc38]: Volume[0..1] 0.9400
[23:49:04.663788] handle_rtsp:592 [0xf50604c8]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 5

[23:49:04.665354] rtp_thread_func:738 [0xeee0df98]: 1st sync packet received
[23:49:04.665462] rtp_thread_func:711 [0xeee0df98]: 1st audio packet received
[23:49:04.666482] mp3_init:238 [0xeee0df98]: Using shine MP3-320 (0xece00600)
[23:49:04.666525] buffer_put_packet:620 [0xeee0df98]: fill [level:1] [W:48765 R:48765]
[23:49:04.666573] raop_cb:205 [0x1e3fc38]: Play
[23:49:04.667461] handle_rtsp:379 [0xf50604c8]: received SET_PARAMETER
[23:49:04.667553] handle_rtsp:592 [0xf50604c8]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 6

[23:49:04.683433] handle_rtsp:379 [0xf50604c8]: received FLUSH
[23:49:04.683576] raopst_flush:470 [0xeee0df98]: FLUSH ignored as same as RECORD (48768 - 921191773)
[23:49:04.683617] raopst_flush:486 [0xeee0df98]: flush 48768 921191773
[23:49:04.683729] handle_rtsp:592 [0xf50604c8]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 7

[23:49:04.693156] CastConnect:239 [0x1e3fc38]: SSL connection opened [0xf505ee30]
[23:49:04.694041] CastLoad:177 [0x1e3fc38]: Queuing LOAD
[23:49:04.694120] CastPlay:262 [0x1e3fc38]: Queuing PLAY
[23:49:04.694148] CastSetDeviceVolume:373 [0x1e3fc38]: Queuing SET_VOLUME
[23:49:04.700142] CastSocketThread:628 [0x1e3fc38]: Launching receiver 1
[23:49:06.643031] CastSocketThread:656 [0x1e3fc38]: Receiver launched
[23:49:06.643265] ProcessQueue:448 [0x1e3fc38]: Processing VOLUME (id:3)
[23:49:06.664469] handle_rtsp:379 [0xf50604c8]: received POST
[23:49:06.664564] handle_rtsp:580 [0xf50604c8]: unknown/unhandled method POST
[23:49:06.664664] handle_rtsp:592 [0xf50604c8]: responding:
RTSP/1.0 500 ERROR

[23:49:06.666452] rtsp_thread:353 RTSP close 14
[23:49:06.694108] MRThread:328 [0x1e3fc38]: Volume local change 1.0000
[23:49:06.719835] MRThread:328 [0x1e3fc38]: Volume local change 1.0000
[23:49:06.749630] ProcessQueue:483 [0x1e3fc38]: Processing LOAD (id:4)
[23:49:07.926152] http_thread_func:1060 [0xeee0df98]: got HTTP connection 14 (silent frames 0)
[23:49:08.147381] handle_http:1237 [0xeee0df98]: received GET HTTP/1.1
Host: 192.168.0.100:57051
Connection: keep-alive
User-Agent: Mozilla/5.0 (Fuchsia) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36 CrKey/1.56.500000
Accept-Encoding: identity;q=1, *;q=0
Accept: */*
CAST-DEVICE-CAPABILITIES: {"bluetooth_supported":true,"display_supported":true,"hi_res_audio_supported":false,"remote_control_input_supported":false,"touch_input_supported":true}
Accept-Language: en-US,en;q=0.9
Range: bytes=0-

[23:49:08.147617] handle_http:1293 [0xeee0df98]: responding: HTTP/1.0 200 OK
Server: HairTunes
Content-Type: audio/mpeg
Connection: close

[23:49:08.147843] _buffer_get_frame:959 [0xeee0df98]: drain [level:2 gap:-1985] [W:48767 R:48765] [R:0 S:0 F:0]
[23:49:35.766501] rtsp_thread:338 got RTSP connection 21
[23:49:35.773137] handle_rtsp:379 [0xf50604c8]: received ANNOUNCE
[23:49:35.773204] handle_rtsp:385 [0xf50604c8]: challenge WTAI5QXQEVpzuq6Hp33PnA
[23:49:35.797645] handle_rtsp:592 [0xf50604c8]: responding:
RTSP/1.0 200 OK
Apple-Response: 2j+QnvfTE0LYUpGvqBBgy7EALhVFovg5YS/DBkbGlcrzGNGLnUMKArxgeN+NK1/L8XVPj8iMnYMsBaxYR5sZiq6PjFh1Cg8NPcvDF/fLpB4mXvHLH4p/RAx3ztI6eRSmsT0Eif0u2NALsKLmqmuii1S8waskaFs6sq589LrjpTQwTOC4u5mtbfA/cS54erMRPRLgetqQCYUfdXFDxw/+ovnP8M0sICsGBRSdzb9jWPi4wlENP0J+OLRgG4YQ2+2Ad4ICGkK7QaHKLQR5c8gFr4FqBFY2ipx8jDY/vY/FJeSZXwYVB7pYzaAx+8pAw8WDZV4f0q4czMxgl1sMBG8iKA
Audio-Jack-Status: connected; type=analog
CSeq: 2

[23:49:35.804642] handle_rtsp:379 [0xf50604c8]: received SETUP
[23:49:35.812608] raopst_init:378 [0xee07afc8]: UDP port-0 49289
[23:49:35.813870] raopst_init:378 [0xee07afc8]: UDP port-1 42766
[23:49:35.814578] raopst_init:378 [0xee07afc8]: UDP port-2 45486
[23:49:35.815119] raopst_init:396 [0xee07afc8]: HTTP listening port 46161
[23:49:35.815929] handle_rtsp:592 [0xf50604c8]: responding:
RTSP/1.0 200 OK
Transport: RTP/AVP/UDP;unicast;mode=record;control_port=42766;timing_port=45486;server_port=49289
Session: DEADBEEF
Audio-Jack-Status: connected; type=analog
CSeq: 3

[23:49:35.818020] rtp_thread_func:764 [0xee07afc8]: discarding NTP roundtrip of 1386512455 ms
[23:49:35.822084] handle_rtsp:379 [0xf50604c8]: received RECORD
[23:49:35.822150] raopst_record:502 [0xee07afc8]: record 61346 3926925354
[23:49:35.822172] raop_cb:182 [0x1e3fc38]: Stream
[23:49:35.822369] handle_rtsp:592 [0xf50604c8]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 4

[23:49:35.825320] rtp_thread_func:738 [0xee07afc8]: 1st sync packet received
[23:49:35.826322] rtp_thread_func:711 [0xee07afc8]: 1st audio packet received
[23:49:35.827255] mp3_init:238 [0xee07afc8]: Using shine MP3-320 (0xee408990)
[23:49:35.827329] buffer_put_packet:620 [0xee07afc8]: fill [level:1] [W:61346 R:61346]
[23:49:35.827400] raop_cb:205 [0x1e3fc38]: Play
[23:49:35.827698] CastLoad:166 [0x1e3fc38]: Immediate LOAD (id:5)
[23:49:35.827761] CastPlay:262 [0x1e3fc38]: Queuing PLAY
[23:49:35.827800] CastSetDeviceVolume:373 [0x1e3fc38]: Queuing SET_VOLUME
[23:49:35.828130] handle_rtsp:379 [0xf50604c8]: received SET_PARAMETER
[23:49:35.828180] handle_rtsp:546 [0xf50604c8]: SET PARAMETER volume -1.799927
[23:49:35.828381] raop_cb:232 [0x1e3fc38]: Volume[0..1] 0.9400
[23:49:35.828654] handle_rtsp:592 [0xf50604c8]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 5

[23:49:35.832629] handle_rtsp:379 [0xf50604c8]: received SET_PARAMETER
[23:49:35.832819] handle_rtsp:592 [0xf50604c8]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 6

[23:49:35.994740] http_thread_func:1079 HTTP close 14
[23:49:35.994851] http_thread_func:1060 [0xeee0df98]: got HTTP connection 14 (silent frames 0)
[23:49:35.998258] handle_http:1237 [0xeee0df98]: received OPTIONS HTTP/1.1
Host: 192.168.0.100:57051
Connection: keep-alive
Accept: */*
Access-Control-Request-Method: GET
Access-Control-Request-Private-Network: true
Origin: https://philippe44.github.io
User-Agent: Mozilla/5.0 (Fuchsia) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36 CrKey/1.56.500000
Sec-Fetch-Mode: cors
Accept-Encoding: gzip, deflate
Accept-Language: en-US,en;q=0.9

[23:49:35.998401] handle_http:1293 [0xeee0df98]: responding: HTTP/1.0 200 OK
Server: HairTunes
Content-Type: audio/mpeg
Connection: close

[23:49:35.998550] http_thread_func:1079 HTTP close 14
[23:49:36.101503] http_thread_func:1060 [0xee07afc8]: got HTTP connection 14 (silent frames 0)
[23:49:36.329842] handle_http:1237 [0xee07afc8]: received GET HTTP/1.1
Host: 192.168.0.100:46161
Connection: keep-alive
User-Agent: Mozilla/5.0 (Fuchsia) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/116.0.0.0 Safari/537.36 CrKey/1.56.500000
Accept-Encoding: identity;q=1, *;q=0
Accept: */*
CAST-DEVICE-CAPABILITIES: {"bluetooth_supported":true,"display_supported":true,"hi_res_audio_supported":false,"remote_control_input_supported":false,"touch_input_supported":true}
Accept-Language: en-US,en;q=0.9
Range: bytes=0-

[23:49:36.329985] handle_http:1293 [0xee07afc8]: responding: HTTP/1.0 200 OK
Server: HairTunes
Content-Type: audio/mpeg
Connection: close

[23:49:36.330031] _buffer_get_frame:959 [0xee07afc8]: drain [level:62 gap:992] [W:61408 R:61346] [R:0 S:0 F:0]
[23:49:37.602719] CastSocketThread:670 [0x1e3fc38]: Media session id 2
[23:49:37.707685] ProcessQueue:455 [0x1e3fc38]: Processing PLAY (id:9)
[23:49:37.824933] handle_rtsp:379 [0xf50604c8]: received POST
[23:49:37.824993] handle_rtsp:580 [0xf50604c8]: unknown/unhandled method POST
[23:49:37.825118] handle_rtsp:592 [0xf50604c8]: responding:
RTSP/1.0 500 ERROR

[23:49:37.826392] rtsp_thread:353 RTSP close 21
[23:49:37.847281] ProcessQueue:448 [0x1e3fc38]: Processing VOLUME (id:11)
[23:49:37.847768] MRThread:292 [0x1e3fc38]: Cast playing
sidevesh commented 8 months ago

Its the POST request to /feedback endpoint that seems to return 500 and break playback, this seems to be something that some of these airplay implementations do to maybe keep alive connection: https://gitlab.freedesktop.org/pipewire/pipewire/-/issues/3279#note_2056968

If this endpoint is of no use for AirConnect then can it be added just so we don't send a 500 causing the playback to stop ?

philippe44 commented 8 months ago

I'll do a 501

philippe44 commented 8 months ago

Can you tell me if this works aircast-linux-arm.zip

sidevesh commented 8 months ago

I think you will to return a 200 here so that the server does not fail https://openairplay.github.io/airplay-spec/audio/rtsp_requests/post_feedback.html https://emanuelecozzi.net/docs/airplay2/rtsp/

It seems to be just a heartbeat check to see if client is still alive

philippe44 commented 8 months ago

AFAIK it's an AP2 feature, so responding "not implemented" seems appropriate where 500 was not, I agree. If a server fails on a 501 on hearbeat, knowing this is an AP2 command, then that server should be corrected

sidevesh commented 8 months ago

still breaks, can you give me a binary that responds with 200 just so I can test it and then raise the issue with pipewire maintainers regarding /feedback being AP2 feature. Seems like this /feedback endpoint usage is something other tools like atv for python also do, so this is not limited to just pipewire.

progress: 0/0/0

[I][09280.470364] default      | [   rtsp-client.c:  246 process_status()] status: RTSP/1.0 200 OK
[I][09280.470540] default      | [   rtsp-client.c:  322 process_header()]  Audio-Jack-Status: connected; type=analog
[I][09280.470565] default      | [   rtsp-client.c:  322 process_header()]  CSeq: 5
[I][09280.470583] default      | [   rtsp-client.c:  279 dispatch_handler()] received reply to request with cseq:5
[I][09280.470600] mod.raop-sink | [module-raop-sink:  952 rtsp_log_reply_status()] reply status: 200
[I][09280.512285] default      | [   rtsp-client.c:  246 process_status()] status: RTSP/1.0 200 OK
[I][09280.512398] default      | [   rtsp-client.c:  322 process_header()]  Audio-Jack-Status: connected; type=analog
[I][09280.512410] default      | [   rtsp-client.c:  322 process_header()]  CSeq: 6
[I][09280.512419] default      | [   rtsp-client.c:  279 dispatch_handler()] received reply to request with cseq:6
[I][09280.512432] mod.raop-sink | [module-raop-sink:  952 rtsp_log_reply_status()] reply status: 200
[I][09282.423358] default      | [   rtsp-client.c:  414 flush_output()] sent: POST /feedback RTSP/1.0
CSeq: 7
Client-Instance: F22F7C8FB283E6B8
DACP-ID: F22F7C8FB283E6B8
User-Agent: PipeWire/0.3.81
Session: DEADBEEF

[I][09282.439237] default      | [   rtsp-client.c:  246 process_status()] status: RTSP/1.0 501 Not Implemented
[I][09282.439273] default      | [   rtsp-client.c:  246 process_status()] status: 
[E][09282.439338] default      | [   rtsp-client.c:  470 on_source_io()] 0x55b5538db210: got connection error -71 (Protocol error)
[E][09282.439351] mod.raop-sink | [module-raop-sink: 1620 rtsp_error()] error -71
[I][09282.439390] mod.raop-sink | [module-raop-sink: 1613 rtsp_disconnected()] disconnected
[W][09282.444938] mod.raop-sink | [module-raop-sink:  506 flush_to_udp_packet()] error streaming packet: -9
[W][09282.450226] mod.raop-sink | [module-raop-sink:  506 flush_to_udp_packet()] error streaming packet: -9
[W][09282.460890] mod.raop-sink | [module-raop-sink:  506 flush_to_udp_packet()] error streaming packet: -9
[W][09282.466242] mod.raop-sink | [module-raop-sink:  506 flush_to_udp_packet()] error streaming packet: -9
sidevesh commented 8 months ago

https://github.com/mikebrady/shairport-sync/issues/1745

sidevesh commented 8 months ago

Can you give me a binary that returns 200 OK please ? Looks like that solved the issue for shairport-sync

philippe44 commented 8 months ago

We know for sure that a 200 will work but I will not do that. I put a note on https://github.com/mikebrady/shairport-sync/issues/1745 expressing my position. The heartbeat has been a known issue for a long while and I, like others, used an existing feature like requesting an "OPTIONS" to deal with it. A controller that sends AP2 request when it knows it is AP1 player shall not expect a 200.

sidevesh commented 8 months ago

@philippe44 looks like the 500 error is not the cause of my issue but something else, I have shared the logs and info related to it at https://gitlab.freedesktop.org/pipewire/pipewire/-/issues/3566

sidevesh commented 8 months ago

@philippe44 https://gitlab.freedesktop.org/pipewire/pipewire/-/issues/3566#note_2125636 Does this seem to be something that could be happening with AirConnect ?

philippe44 commented 8 months ago

Yes, this one is probably on me, an error when sending no header. Can you try 1.2.4?

sidevesh commented 8 months ago

Sure, I dont see it in Releases though, where do I get it from ?

philippe44 commented 8 months ago

https://github.com/philippe44/AirConnect/tree/master/bin

sidevesh commented 8 months ago

that fixed the issue!

sidevesh commented 8 months ago

I guess this issue can be closed as 500 error is anyways not an issue, thanks for all the help!