Closed mikebrady closed 7 months ago
mikebrady
commented
9 months ago Thanks for the post. Could you provide a bit more information please?
Specifically the result of:
$ shairport-sync --displayConfigand if you could set the logging verbosity of Shairport Sync to 1 and post the log when Shairport Sync starts up and also when attempt to play to it, it would be very useful.
LorbusChris
commented
9 months ago The POST /feedback was added to PipeWire recently, it is a sort of hearbeat that some devices seem to require. At least Apple HomePods do, otherwise they go mute after ~30sec.
A RTSP/1.0 200 OK response would certainly be best, but I wonder are there any devices that similarlu to shairport-sync would barf on this? Maybe we can be smarter on the Pipewire side as to when to enable the hearbeat.
mikebrady
commented
9 months ago Very interesting, thanks. A 200 response can easily be added to Shairport Sync — not a problem at all. But I’d be very interested in the format and payload of the HomePod response.
LorbusChris
commented
9 months ago Pipewire doesn't log the payload contents, but the headers are (reply from HomePod Mini):
RTSP/1.0 200 OK
Date: Sat, 07 Oct 2023 17:25:41 GMT
Content-Length: 55
Content-Type: application/x-apple-binary-plist
Server: AirTunes/710.79.1
CSeq: 11
alexbramford
commented
9 months ago @mikebrady
As requested:
Logfile when Shairport Sync starts up, and when playing to shairport.
shairport-sync --displayConfig
0.001645648 "shairport.c:2113" >> Display Config Start.
0.004744982 "shairport.c:2113"
0.000069889 "shairport.c:2113" From "uname -a":
0.000027203 "shairport.c:2113" Linux shairportserver 6.1.21-v8+ #1642 SMP PREEMPT Mon Apr 3 17:24:16 BST 2023 aarch64 GNU/Linux
0.009552630 "shairport.c:2113"
0.000078463 "shairport.c:2113" From /etc/os-release:
0.000063074 "shairport.c:2113" Debian GNU/Linux 11 (bullseye)
0.006480018 "shairport.c:2113"
0.000121260 "shairport.c:2113" From /sys/firmware/devicetree/base/model:
0.000058370 "shairport.c:2113" Raspberry Pi 4 Model B Rev 1.5
0.000116037 "shairport.c:2113"
0.000059833 "shairport.c:2113" Shairport Sync Version String:
0.000056167 "shairport.c:2113" 4.3.1-24-g7e0e3af6-OpenSSL-Avahi-ALSA-soxr-metadata-mqtt-sysconfdir:/etc
0.000059130 "shairport.c:2113"
0.000053518 "shairport.c:2113" Command Line:
0.000055389 "shairport.c:2113" shairport-sync --displayConfig
0.000099445 "shairport.c:2113"
0.000059592 "shairport.c:2113" Configuration File:
0.000057871 "shairport.c:2113" /etc/shairport-sync.conf
0.000056777 "shairport.c:2113"
0.000328500 "shairport.c:2113" Configuration File Settings:
0.000067704 "shairport.c:2113" general :
0.000057278 "shairport.c:2113" {
0.000054666 "shairport.c:2113" interpolation = "soxr";
0.000055426 "shairport.c:2113" udp_port_base = 6001;
0.000054982 "shairport.c:2113" udp_port_range = 10;
0.000054926 "shairport.c:2113" drift_tolerance_in_seconds = 0.002;
0.000055129 "shairport.c:2113" ignore_volume_control = "no";
0.000055297 "shairport.c:2113" volume_range_db = 90;
0.000054796 "shairport.c:2113" playback_mode = "stereo";
0.000054982 "shairport.c:2113" audio_backend_latency_offset_in_seconds = 0.6;
0.000056074 "shairport.c:2113" audio_backend_buffer_desired_length_in_seconds = 2.0;
0.000054926 "shairport.c:2113" audio_backend_buffer_interpolation_threshold_in_seconds = 0.075;
0.000054962 "shairport.c:2113" };
0.000054612 "shairport.c:2113" sessioncontrol :
0.000054370 "shairport.c:2113" {
0.000053574 "shairport.c:2113" active_state_timeout = 10.0;
0.000055648 "shairport.c:2113" wait_for_completion = "yes";
0.000054722 "shairport.c:2113" allow_session_interruption = "no";
0.000055500 "shairport.c:2113" session_timeout = 120;
0.000054889 "shairport.c:2113" };
0.000054389 "shairport.c:2113" alsa :
0.000054185 "shairport.c:2113" {
0.000054241 "shairport.c:2113" output_device = "hw:0";
0.000054685 "shairport.c:2113" mixer_control_name = "DAC";
0.000054463 "shairport.c:2113" output_rate = 44100;
0.000054741 "shairport.c:2113" output_format = "S32_LE";
0.000056037 "shairport.c:2113" use_precision_timing = "auto";
0.000055000 "shairport.c:2113" disable_standby_mode = "yes";
0.000054593 "shairport.c:2113" };
0.000054148 "shairport.c:2113" metadata :
0.000054148 "shairport.c:2113" {
0.000054315 "shairport.c:2113" enabled = "yes";
0.000054592 "shairport.c:2113" include_cover_art = "yes";
0.000054611 "shairport.c:2113" };
0.000053630 "shairport.c:2113" mqtt :
0.000053593 "shairport.c:2113" {
0.000054259 "shairport.c:2113" enabled = "yes";
0.000054537 "shairport.c:2113" hostname = "rpiadafruit.spaceodyssey.2001.com";
0.000054796 "shairport.c:2113" port = 1883;
0.000054019 "shairport.c:2113" topic = "shairport-sync/rpih1";
0.000054703 "shairport.c:2113" publish_raw = "yes";
0.000054704 "shairport.c:2113" publish_parsed = "yes";
0.000054500 "shairport.c:2113" publish_cover = "yes";
0.000054148 "shairport.c:2113" enable_remote = "yes";
0.000054241 "shairport.c:2113" };
0.000087019 "shairport.c:2113" diagnostics :
0.000057722 "shairport.c:2113" {
0.000053926 "shairport.c:2113" statistics = "no";
0.000055129 "shairport.c:2113" log_verbosity = 1;
0.000054315 "shairport.c:2113" };
0.000054445 "shairport.c:2113"
0.000054000 "shairport.c:2113" >> Display Config End.
0.000067259 "shairport.c:2115" >> Goodbye!
0.000088870 "shairport.c:1725" normal exit@mikebrady
Also attaching logs from sender (Fedora 38)
mikebrady
commented
9 months ago Hi there. An update has been pushed into the development branch that returns a 200 response to a POST /feedback message instead of the 500 response hitherto . It contains no payload, but maybe it will help. Any feedback would be appreciated.
alexbramford
commented
9 months ago The issue appears to be resolved.
I pulled your changes and rebuilt shairport-sync from the 'development' branch. Shairpoint-sync server is now returning 200 in response to pipewire's "POST /feedback" request.
Here is a snippet from the pipewire log entries , showing the response, before, and after the fix with reboot:
Oct 08 15:12:56 pipewire[116219]: default: sent: POST /feedback RTSP/1.0
CSeq: 9596
Client-Instance: 2B22903C0AE8499E
DACP-ID: 2B22903C0AE8499E
User-Agent: PipeWire/0.3.81
Session: 1
Oct 08 15:12:56 pipewire[116219]: spa.loop: 0x5645957968c0: update 0000001d -> 00000019
Oct 08 15:12:56 pipewire[116219]: default: received line: RTSP/1.0 500 Internal Server Error
Oct 08 15:12:56 pipewire[116219]: default: status: RTSP/1.0 500 Internal Server Error
--
Oct 08 15:37:25 pipewire[128994]: default: sent: POST /feedback RTSP/1.0
CSeq: 7
Client-Instance: DE60C77B64993EEF
DACP-ID: DE60C77B64993EEF
User-Agent: PipeWire/0.3.81
Session: 1
Oct 08 15:37:25 pipewire[128994]: default: status: RTSP/1.0 200 OK
Oct 08 15:37:25 pipewire[128994]: default: CSeq: 7
Oct 08 15:37:25 pipewire[128994]: default: Server: AirTunes/105.1Have also attached relevant logs for reference:
alexbramford
commented
9 months ago @mikebrady
Thank you, as always, for this excellent project which makes my home sound system possible.
philippe44
commented
9 months ago I have the same error with AirConnect but I disagree to add a 200. This is a matter of principle to not bastardize standards and always adapts to the buggy actor (UPnP is the best example of that). The POST is anAP2 feature and AP1 clients are right to answer with a 501 (not implemented). This change is on pipewire, not on the others
mikebrady
commented
9 months ago I have the same error with AirConnect but I disagree to add a 200. This is a matter of principle to not bastardize standards and always adapts to the buggy actor (UPnP is the best example of that). The POST is anAP2 feature and AP1 clients are right to answer with a 501 (not implemented). This change is on pipewire, not on the others
I see your point. So you’re suggesting PipeWire should not complain if a 501 is returned to it?
LorbusChris
commented
9 months ago PipeWire does not care what is replied to the POST /feedback
LorbusChris
commented
9 months ago philippe44
commented
9 months ago PipeWire does not care what is replied to the POST /feedback
That makes sense. The issue was on my side with a wrong format when sending a 500 or 501. I still thing that a /feedback should not be sent to an AP1 device, but that's less important.
alexbramford
commented
9 months ago Pipewire may not care what is replied to the POST /feedback, but it's not clear that Shairport returning [500 Internal Server Error] is helpful when there's nothing wrong at the Shairport server.
LorbusChris
commented
9 months ago Right, it should reply either say 200 OK or 501 Not Implemented
philippe44
commented
9 months ago Agreed, and I think 501 is the most logical, to my previous point of rewarding non-compliance (and believe me, I've been more than often on the other side of this problem and did correct my stuff, even if it was not fun).
mikebrady
commented
9 months ago Thanks for all the information. I've just pushed an update in the development branch to return 501 Not Implemented. Does it work just as well?
alexbramford
commented
9 months ago Confirming the"501" fix is working in the developement branch:
Shairport (receiver)
Oct 13 12:04:56 rpiiqaudio shairport-sync[6638]: 0.016277611 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "POST":
Oct 13 12:04:56 rpiiqaudio shairport-sync[6638]: 0.000056667 "rtsp.c:5253" Type: "CSeq", content: "36"
Oct 13 12:04:56 rpiiqaudio shairport-sync[6638]: 0.000032555 "rtsp.c:5253" Type: "Client-Instance", content: "A0715D67DCFE1A94"
Oct 13 12:04:56 rpiiqaudio shairport-sync[6638]: 0.000026778 "rtsp.c:5253" Type: "DACP-ID", content: "A0715D67DCFE1A94"
Oct 13 12:04:56 rpiiqaudio shairport-sync[6638]: 0.000034593 "rtsp.c:5253" Type: "User-Agent", content: "PipeWire/0.3.81"
--
Oct 13 12:04:56 rpiiqaudio shairport-sync[6638]: 0.000027870 "rtsp.c:5312" Connection 2: RTSP Response:
Oct 13 12:04:56 rpiiqaudio shairport-sync[6638]: 0.000025130 "rtsp.c:5313" Response Code: 501.
Oct 13 12:04:56 rpiiqaudio shairport-sync[6638]: 0.000025630 "rtsp.c:5313" Type: "CSeq", content: "36"
Oct 13 12:04:56 rpiiqaudio shairport-sync[6638]: 0.000025759 "rtsp.c:5313" Type: "Server", content: "AirTunes/105.1"
Oct 13 12:04:56 rpiiqaudio shairport-sync[6638]: 0.000030000 "rtsp.c:5313" No Content Plist. Content length: 0.Pipewire (sender)
Oct 13 12:04:56 pipewire[9806]: default: sent: POST /feedback RTSP/1.0
CSeq: 36
Client-Instance: A0715D67DCFE1A94
DACP-ID: A0715D67DCFE1A94
User-Agent: PipeWire/0.3.81
Session: 1
--
Oct 13 12:04:56 pipewire[9806]: default: received line: RTSP/1.0 501 Not Implemented
Oct 13 12:04:56 pipewire[9806]: default: status: RTSP/1.0 501 Not Implemented
Oct 13 12:04:56 pipewire[9806]: default: received line: CSeq: 36
Oct 13 12:04:56 pipewire[9806]: default: received line: Server: AirTunes/105.1
Oct 13 12:04:56 pipewire[9806]: default: received line:
Oct 13 12:04:56 pipewire[9806]: default: CSeq: 36
Oct 13 12:04:56 pipewire[9806]: default: Server: AirTunes/105.1
github-actions[bot]
commented
7 months ago This issue has been inactive for 28 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.
Discussed in https://github.com/mikebrady/shairport-sync/discussions/1744