[Problem]: Possible confusion between "pipe" and "PipeWire" backends?

[neddey]

What happened?

Can stream to shairport fine but there is no volume output when using pipewire. when output_backend is set to alsa I can't even stream to shairport.

Relevant log output

0.000132240 "shairport.c:579" looking for configuration file at full path "/etc/shairport-sync.conf"
0.000218920 "shairport.c:1470" default metadata_pipename is "/tmp/shairport-sync-metadata".
0.000004170 "shairport.c:2255" Startup in classic Airplay (aka "AirPlay 1") mode.
0.000002550 "shairport.c:2291" Version String: "4.3.2-OpenSSL-Avahi-dns_sd-ALSA-jack-pa-stdout-pipe-soxr-metadata-mqtt-sysconfdir:/etc"
0.000002650 "shairport.c:2310" Command Line: "shairport-sync -vv".
0.000001480 "shairport.c:2346" Log Verbosity is 2.
0.000009020 "audio_pipe.c:134" audio pipe name is "/tmp/shairport-sync-audio"
0.000001810 "shairport.c:2361" The processor is running little-endian.
0.000001120 "shairport.c:2394" disable_resend_requests is off.
0.000001310 "shairport.c:2395" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
0.000002260 "shairport.c:2399" statistics_requester status is 0.
0.000002860 "shairport.c:2404" rtsp listening port is 5000.
0.000001550 "shairport.c:2405" udp base port is 6001.
0.000001500 "shairport.c:2406" udp port range is 10.
0.000001140 "shairport.c:2407" player name is "pc".
0.000001320 "shairport.c:2408" backend is "pipe".
0.000002120 "shairport.c:2409" run_this_before_play_begins action is "(null)".
0.000001220 "shairport.c:2410" run_this_after_play_ends action is "(null)".
0.000001500 "shairport.c:2411" wait-cmd status is 0.
0.000001090 "shairport.c:2412" run_this_before_play_begins may return output is 0.
0.000001590 "shairport.c:2413" run_this_if_an_unfixable_error_is_detected action is "(null)".
0.000001460 "shairport.c:2415" run_this_before_entering_active_state action is  "(null)".
0.000001140 "shairport.c:2417" run_this_after_exiting_active_state action is  "(null)".
0.000002020 "shairport.c:2419" active_state_timeout is  10.000000 seconds.
0.000001810 "shairport.c:2420" mdns backend "(null)".
0.000001970 "shairport.c:2421" userSuppliedLatency is 0.
0.000001450 "shairport.c:2422" interpolation setting is "auto".
0.000001340 "shairport.c:2426" interpolation soxr_delay_threshold is 30000000.
0.000001070 "shairport.c:2427" resync time is 0.050000 seconds.
0.000001630 "shairport.c:2428" resync recovery time is 0.100000 seconds.
0.000001540 "shairport.c:2429" allow a session to be interrupted: 0.
0.000001430 "shairport.c:2430" busy timeout time is 120.
0.000001610 "shairport.c:2431" drift tolerance is 0.002000 seconds.
0.000001510 "shairport.c:2432" password is "(null)".
0.000001710 "shairport.c:2433" default airplay volume is: -24.000000.
0.000001860 "shairport.c:2434" high threshold airplay volume is: -16.000000.
0.000001750 "shairport.c:2436" check for higher-than-threshold volume for new play session is disabled.
0.000001610 "shairport.c:2442" ignore_volume_control is 0.
0.000001550 "shairport.c:2446" volume_max_db is not set
0.000001520 "shairport.c:2447" volume range in dB (zero means use the range specified by the mixer): 0.
0.000001280 "shairport.c:2449" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
0.000001670 "shairport.c:2453" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
0.000001110 "shairport.c:2455" disable_synchronization is 0.
0.000001530 "shairport.c:2456" use_mmap_if_available is 1.
0.000001990 "shairport.c:2457" output_format automatic selection is enabled.
0.000002070 "shairport.c:2461" output_rate automatic selection is enabled.
0.000001090 "shairport.c:2465" audio backend desired buffer length is 1.000000 seconds.
0.000002040 "shairport.c:2467" audio_backend_buffer_interpolation_threshold_in_seconds is 0.000000 seconds.
0.000001660 "shairport.c:2469" audio backend latency offset is 0.000000 seconds.
0.000001550 "shairport.c:2471" audio backend silence lead-in time is "auto".
0.000002370 "shairport.c:2475" zeroconf regtype is "_raop._tcp".
0.000002000 "shairport.c:2476" decoders_supported field is 1.
0.000001450 "shairport.c:2477" use_apple_decoder is 0.
0.000001570 "shairport.c:2478" alsa_use_hardware_mute is 0.
0.000001040 "shairport.c:2482" no special mdns service interface was requested.
0.000002830 "shairport.c:2485" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
0.000002180 "shairport.c:2492" metadata enabled is 1.
0.000001600 "shairport.c:2493" metadata pipename is "/tmp/shairport-sync-metadata".
0.000001490 "shairport.c:2494" metadata socket address is "(null)" port 0.
0.000001390 "shairport.c:2496" metadata socket packet size is "500".
0.000001510 "shairport.c:2497" get-coverart is 1.
0.000001070 "shairport.c:2500" mqtt is disabled.
0.000001440 "shairport.c:2501" mqtt hostname is (null), port is 1883.
0.000001460 "shairport.c:2502" mqtt topic is /pc.
0.000001390 "shairport.c:2503" mqtt will not publish raw metadata.
0.000001160 "shairport.c:2504" mqtt will not publish parsed metadata.
0.000002160 "shairport.c:2505" mqtt will not publish cover Art.
0.000001020 "shairport.c:2506" mqtt remote control is disabled.
0.000001560 "shairport.c:2515" loudness is 0.
0.000001410 "shairport.c:2516" loudness reference level is -20.000000
0.000589030 "rtsp.c:4193" metadata pipe name is "/tmp/shairport-sync-metadata".
0.000091589 "rtsp.c:374" Creating metadata queue "pipe".
0.000077140 "rtsp.c:374" Creating metadata queue "multicast".
0.000078520 "rtsp.c:374" Creating metadata queue "hub".
0.000076560 "rtsp.c:374" Creating metadata queue "mqtt".
0.000101530 "metadata_hub.c:145" Metadata_hub write lock is already taken by unknown -- must wait.
0.000018610 "metadata_hub.c:148" Okay -- acquired the metadata_hub write lock at "metadata_hub.c:350".
0.000076270 "activity_monitor.c:163" am_state: am_inactive
0.000780070 "mdns_avahi.c:220" avahi: service '2ED659802FC9@pc' group is not yet committed.
0.000220460 "mdns_avahi.c:277" avahi: avahi_entry_group_commit 0
0.000118929 "mdns_avahi.c:477" avahi_dacp_monitor_start Avahi DACP monitor successfully started
0.000041290 "mdns_avahi.c:224" avahi: service '2ED659802FC9@pc' group is registering.
0.754421235 "mdns_avahi.c:191" avahi: service '2ED659802FC9@pc' successfully added.
0.743415321 "shairport.c:248" soxr_delay: 365946 nanoseconds, soxr_delay_threshold: 30 milliseconds.
0.000006860 "shairport.c:255" "soxr" interpolation has been chosen.
6.120063881 "rtsp.c:719" No active connections.
0.000012860 "rtsp.c:726" Airplay Volume for new connections is -24.000000.
0.000028120 "rtsp.c:5588" Connection 1 is at: 0x76e948006370.
0.000015000 "rtsp.c:5670" Connection 1: New connection from 192.168.20.10:58026 to self at 192.168.20.14:5000.
0.000233049 "rtsp.c:5251" Connection 1: Received an RTSP Packet of type "OPTIONS":
0.000004640 "rtsp.c:5253"   Type: "CSeq", content: "1"
0.000001790 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000002090 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000001290 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000001240 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000001110 "rtsp.c:5253"   No Content Plist. Content length: 0.
0.000001890 "rtsp.c:2624" OPTIONS request
0.000001780 "rtsp.c:2624"   Type: "CSeq", content: "1"
0.000002290 "rtsp.c:2624"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000002560 "rtsp.c:2624"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000001900 "rtsp.c:2624"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000001880 "rtsp.c:2624"   Type: "Active-Remote", content: "2843644481"
0.000001540 "rtsp.c:2624"   No Content Plist. Content length: 0.
0.000002810 "rtsp.c:5312" Connection 1: RTSP Response:
0.000001860 "rtsp.c:5313"   Response Code: 200.
0.000001640 "rtsp.c:5313"   Type: "CSeq", content: "1"
0.000001140 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000001610 "rtsp.c:5313"   Type: "Public", content: "ANNOUNCE, SETUP, RECORD, PAUSE, FLUSH, TEARDOWN, OPTIONS, GET_PARAMETER, SET_PARAMETER"
0.000002610 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.307448402 "rtsp.c:1334" Connection 1: Connection closed by client.
0.000014910 "rtsp.c:5068" Connection 1: unspecified stream rtsp_conversation_thread_func_cleanup_function called.
0.000003380 "rtsp.c:2775" Connection 1: TEARDOWN (Classic AirPlay).
0.000002140 "player.c:3645" Connection 1: player_stop.
0.000003080 "player.c:3665" Connection 1: no player thread.
0.000004380 "rtsp.c:5100" Connection 1: terminating -- closing RTSP connection socket 8: from 192.168.20.10:58026 to self at 192.168.20.14:5000.
0.000158400 "rtsp.c:5167" Connection 1: Closed.
0.000003940 "rtsp.c:5389" Connection 1: RTSP thread exit.
7.069316160 "rtsp.c:702" Found RTSP connection thread 1 in a non-running state.
0.000016190 "rtsp.c:705" Connection 1: deleted.
0.000005040 "rtsp.c:726" Airplay Volume for new connections is -24.000000.
0.000005680 "rtsp.c:5588" Connection 2 is at: 0x76e948006370.
0.000020090 "rtsp.c:5670" Connection 2: New connection from 192.168.20.10:58028 to self at 192.168.20.14:5000.
0.000114049 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "ANNOUNCE":
0.000014130 "rtsp.c:5253"   Type: "CSeq", content: "1"
0.000003370 "rtsp.c:5253"   Type: "Content-Type", content: "application/sdp"
0.000002660 "rtsp.c:5253"   Type: "Content-Length", content: "572"
0.000002220 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000003410 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000002480 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000002350 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000003050 "rtsp.c:5253"   No Content Plist. Content length: 572.
0.000003290 "rtsp.c:4497" Connection 2: ANNOUNCE
0.000002950 "rtsp.c:586" Connection 2: request to acquire principal_conn.
0.000002490 "rtsp.c:4501" Connection 2: ANNOUNCE has acquired play lock.
0.001010870 "rtsp.c:4719" Play connection from user agent "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7" on RTSP conversation thread 2.
0.000009880 "rtsp.c:4751" Connection 2: ANNOUNCE has completed.
0.000002370 "rtsp.c:5312" Connection 2: RTSP Response:
0.000001340 "rtsp.c:5313"   Response Code: 200.
0.000001210 "rtsp.c:5313"   Type: "CSeq", content: "1"
0.000001140 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000001140 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.004517557 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "SETUP":
0.000005330 "rtsp.c:5253"   Type: "CSeq", content: "2"
0.000002880 "rtsp.c:5253"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002"
0.000003080 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000002690 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000001950 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000001690 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000001540 "rtsp.c:5253"   No Content Plist. Content length: 0.
0.000002250 "rtsp.c:3458" Connection 2: SETUP
0.000001700 "rtsp.c:3465" Connection 2: SETUP: Active-Remote string seen: "2843644481".
0.000004560 "rtsp.c:3485" Connection 2: SETUP: DACP-ID string seen: "8EA9D2F8A68F597E".
0.000004650 "rtp.c:1033" Connection 2: SETUP -- Connection from 192.168.20.10 to self at 192.168.20.14.
0.000017740 "rtsp.c:3547" Connection 2: SETUP DACP-ID "8EA9D2F8A68F597E" from 192.168.20.10 to 192.168.20.14 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
0.000005050 "rtsp.c:5312" Connection 2: RTSP Response:
0.000000090 "rtsp.c:5313"   Response Code: 200.
0.000001700 "metadata_hub.c:570" MH Client IP set to: "192.168.20.10"
0.000004000 "metadata_hub.c:622" MH Server IP set to: "192.168.20.14"
0.000001920 "rtsp.c:5313"   Type: "CSeq", content: "2"
0.000004160 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000001800 "rtsp.c:5313"   Type: "Transport", content: "RTP/AVP/UDP;unicast;interleaved=0-1;mode=record;control_port=6001;timing_port=6002;server_port=6003"
0.000002870 "rtsp.c:5313"   Type: "Session", content: "1"
0.000001930 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.094485819 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "RECORD":
0.000015010 "rtsp.c:5253"   Type: "CSeq", content: "3"
0.000003240 "rtsp.c:5253"   Type: "Session", content: "1"
0.000002610 "rtsp.c:5253"   Type: "Range", content: "npt=0-"
0.000002400 "rtsp.c:5253"   Type: "RTP-Info", content: "seq=52673;rtptime=2337665016"
0.000002250 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000003980 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000002220 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000002870 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000002200 "rtsp.c:5253"   No Content Plist. Content length: 0.
0.000004050 "rtsp.c:1622" Connection 2: RECORD
0.000002610 "rtsp.c:1628" Connection 2: Classic AirPlay connection from 192.168.20.10:58028 to self at 192.168.20.14:5000.
0.000003930 "activity_monitor.c:64" abeg
0.000010340 "player.c:3622" Connection 2: player_play.
0.000005040 "activity_monitor.c:167" am_state: am_active
0.000139000 "rtsp.c:5312" Connection 2: RTSP Response:
0.000003510 "rtsp.c:5313"   Response Code: 200.
0.000001800 "rtsp.c:5313"   Type: "CSeq", content: "3"
0.000002420 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000001730 "rtsp.c:5313"   Type: "Audio-Latency", content: "11025"
0.000001790 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.001533579 "rtp.c:321" rtp_control_receiver start
0.000071350 "dacp.c:411" set_dacp_server_information set IP to "192.168.20.10" and DACP id to "8EA9D2F8A68F597E".
0.000007290 "player.c:2255" Set initial volume to -24.000000.
0.000004550 "player.c:3487" Software attenuation set to -5489.100000, i.e 118.013022 out of 65,536, for airplay volume of -24.000000
0.000004620 "loudness.c:47" Volume: -54.9 dB - Loudness gain @10Hz: 17.4 dB
0.000007070 "player.c:3528" player_volume_without_notification: volume mode is 0, airplay volume is -24.00, software_attenuationdB: -54.89, hardware_attenuation dB: 0.00, muting is disabled.
0.000003860 "player.c:2258" Play begin
0.000094720 "rtp.c:583" rtp_timing_sender start
0.000021430 "rtp.c:609" AP1 clock sender thread: initialised.
0.002132128 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
0.000004960 "rtsp.c:5253"   Type: "CSeq", content: "4"
0.000002240 "rtsp.c:5253"   Type: "Session", content: "1"
0.000001900 "rtsp.c:5253"   Type: "Content-Type", content: "text/parameters"
0.000002370 "rtsp.c:5253"   Type: "Content-Length", content: "20"
0.000001800 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000002720 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000001360 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000001660 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000001460 "rtsp.c:5253"   No Content Plist. Content length: 20.
0.000004380 "rtsp.c:3617" Connection 2: request to set AirPlay Volume to: -20.000797.
0.000002900 "player.c:3487" Software attenuation set to -4333.730332, i.e 446.287543 out of 65,536, for airplay volume of -20.000797
0.000003630 "loudness.c:47" Volume: -43.3 dB - Loudness gain @10Hz: 11.7 dB
0.000005690 "player.c:3528" player_volume_without_notification: volume mode is 0, airplay volume is -20.00, software_attenuationdB: -43.34, hardware_attenuation dB: 0.00, muting is disabled.
0.000003000 "rtsp.c:5312" Connection 2: RTSP Response:
0.000001790 "rtsp.c:5313"   Response Code: 200.
0.000001560 "rtsp.c:5313"   Type: "CSeq", content: "4"
0.000001480 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000001190 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.004947217 "rtp.c:750" AP1 clock receiver thread: initialised.
0.000005160 "rtp.c:771" clock synchronisation request: return time is    7.128 milliseconds.
0.001322029 "rtp.c:468" New latency: 99225, sync latency: 88200, minimum latency: 0, maximum latency: 0, fixed offset: 11025, audio_backend_latency_offset: 0.000000.
0.000006260 "rtp.c:515" AP1 control thread: set_ntp_anchor_info: rtptime: 2337565791, networktime: 1ea80737ece417b1.
0.000161860 "player.c:490" Connection 2: synced by first packet, seqno 52673.
0.000039430 "player.c:174" Hammerton Decoder used on encrypted audio.
0.000028000 "player.c:1137" Accepting packet 52673 with timestamp 2337665016. Lead time is 2.244966 seconds.
0.000003790 "player.c:1211" Connection 2: Lead time for first frame 2337665016: 2.244957 seconds.
0.001188469 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
0.000005200 "rtsp.c:5253"   Type: "CSeq", content: "5"
0.000002600 "rtsp.c:5253"   Type: "Session", content: "1"
0.000002400 "rtsp.c:5253"   Type: "Content-Type", content: "text/parameters"
0.000002520 "rtsp.c:5253"   Type: "Content-Length", content: "20"
0.000002120 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000003390 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000002170 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000001630 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000001830 "rtsp.c:5253"   No Content Plist. Content length: 20.
0.000003650 "rtsp.c:3617" Connection 2: request to set AirPlay Volume to: -20.000797.
0.000003280 "player.c:3487" Software attenuation set to -4333.730332, i.e 446.287543 out of 65,536, for airplay volume of -20.000797
0.000004440 "loudness.c:47" Volume: -43.3 dB - Loudness gain @10Hz: 11.7 dB
0.000006480 "player.c:3528" player_volume_without_notification: volume mode is 0, airplay volume is -20.00, software_attenuationdB: -43.34, hardware_attenuation dB: 0.00, muting is disabled.
0.000003440 "rtsp.c:5312" Connection 2: RTSP Response:
0.000002250 "rtsp.c:5313"   Response Code: 200.
0.000001970 "rtsp.c:5313"   Type: "CSeq", content: "5"
0.000002080 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000002410 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.192859086 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
0.000016500 "rtsp.c:5253"   Type: "CSeq", content: "6"
0.000004030 "rtsp.c:5253"   Type: "Session", content: "1"
0.000002800 "rtsp.c:5253"   Type: "Content-Type", content: "application/x-dmap-tagged"
0.000002980 "rtsp.c:5253"   Type: "Content-Length", content: "1202"
0.000003060 "rtsp.c:5253"   Type: "RTP-Info", content: "rtptime=2337665016"
0.000004340 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000015670 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000002630 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000002370 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000002650 "rtsp.c:5253"   No Content Plist. Content length: 1202.
0.000032980 "metadata_hub.c:531" MH Metadata stream processing start.
0.000011310 "metadata_hub.c:400" MH Album name set to: "Crab Rave - Single"
0.000004480 "metadata_hub.c:408" MH Artist name set to: "Noisestorm"
0.000004420 "metadata_hub.c:433" MH Genre set to: "Dance"
0.000005480 "metadata_hub.c:387" MH Song Time seen: "161280" of length 4.
0.000002610 "metadata_hub.c:393" MH Song Time set to: "161280"
0.000004280 "metadata_hub.c:441" MH Track Name set to: "Crab Rave"
0.000002640 "metadata_hub.c:376" MH Item ID seen: "54512961a0656a4d" of length 8.
0.000002660 "metadata_hub.c:381" MH Item ID set to: "54512961a0656a4d"
0.000002660 "metadata_hub.c:360" MH Song Data Kind seen: "1" of length 1.
0.000000540 "metadata_hub.c:366" MH Song Data Kind set to: "1"
0.000001860 "rtsp.c:5312" Connection 2: RTSP Response:
0.000004370 "rtsp.c:5313"   Response Code: 200.
0.000004660 "rtsp.c:5313"   Type: "CSeq", content: "6"
0.000003780 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000003490 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.000009720 "metadata_hub.c:536" MH Metadata stream processing end with changes.
0.115630736 "rtp.c:771" clock synchronisation request: return time is   18.505 milliseconds.
0.234175949 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
0.000005340 "rtsp.c:5253"   Type: "CSeq", content: "7"
0.000002670 "rtsp.c:5253"   Type: "Session", content: "1"
0.000002330 "rtsp.c:5253"   Type: "Content-Type", content: "image/png"
0.000002280 "rtsp.c:5253"   Type: "Content-Length", content: "1075480"
0.000002560 "rtsp.c:5253"   Type: "RTP-Info", content: "rtptime=2337665016"
0.000001810 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000003420 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000002230 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000002280 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000002200 "rtsp.c:5253"   No Content Plist. Content length: 1075480.
0.000014600 "rtsp.c:5312" Connection 2: RTSP Response:
0.000002150 "rtsp.c:5313"   Response Code: 200.
0.000001770 "rtsp.c:5313"   Type: "CSeq", content: "7"
0.000001980 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000002780 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.000000460 "metadata_hub.c:542" MH Picture received, length 1075480 bytes.
0.158899568 "rtp.c:771" clock synchronisation request: return time is  111.520 milliseconds.
0.003872637 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
0.000007010 "rtsp.c:5253"   Type: "CSeq", content: "8"
0.000001900 "rtsp.c:5253"   Type: "Session", content: "1"
0.000001420 "rtsp.c:5253"   Type: "Content-Type", content: "text/parameters"
0.000001260 "rtsp.c:5253"   Type: "Content-Length", content: "44"
0.000001110 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000002010 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000001180 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000001200 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000001150 "rtsp.c:5253"   No Content Plist. Content length: 44.
0.000012600 "rtsp.c:5312" Connection 2: RTSP Response:
0.000002580 "rtsp.c:5313"   Response Code: 200.
0.000002010 "rtsp.c:5313"   Type: "CSeq", content: "8"
0.000002500 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000002080 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.000010710 "metadata_hub.c:587" MH Progress String set to: "2336956472/2337665016/2344068920"
0.187206940 "mdns_avahi.c:510" dacp_monitor for "8EA9D2F8A68F597E"
0.007598465 "rtp.c:771" clock synchronisation request: return time is    9.934 milliseconds.
0.012973221 "dacp.c:464" dacp_monitor_port_update_callback with Remote ID "8EA9D2F8A68F597E", target ID "8EA9D2F8A68F597E" and port number 58027.
0.024230955 "dacp.c:623" metadata_store.dacp_server_active set to 1.
0.000004880 "dacp.c:631" metadata_store.advanced_dacp_server_active set to 1.
0.000077230 "dacp.c:464" dacp_monitor_port_update_callback with Remote ID "8EA9D2F8A68F597E", target ID "8EA9D2F8A68F597E" and port number 58027.
0.011005443 "dacp.c:714" Play status changed to "playing".
0.000003900 "dacp.c:729" Shuffle status is "off".
0.000002000 "dacp.c:750" Repeat status is "none".
0.000001790 "dacp.c:803" DACP Composite ID seen
0.000002240 "dacp.c:817" Item composite ID changed to 0x00000047000000000000000000003EA0.
0.000001730 "dacp.c:771" DACP Track Name seen
0.000002100 "dacp.c:779" DACP Artist Name seen
0.000002260 "dacp.c:787" DACP Album Name seen
0.000002170 "dacp.c:795" DACP Genre seen
0.000002430 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.057178853 "rtp.c:468" New latency: 99578, sync latency: 88553, minimum latency: 0, maximum latency: 0, fixed offset: 11025, audio_backend_latency_offset: 0.000000.
0.000021620 "rtp.c:513" AP1 control thread: set_ntp_anchor_info: rtptime: 2337610142, networktime: 1ea8073828d749b1, frame adjustment:  -4.506.
1.002744124 "rtp.c:513" AP1 control thread: set_ntp_anchor_info: rtptime: 2337654494, networktime: 1ea8073864ca7bb1, frame adjustment:  -3.506.
0.011816223 "dacp.c:803" DACP Composite ID seen
0.000005090 "dacp.c:771" DACP Track Name seen
0.000003940 "dacp.c:779" DACP Artist Name seen
0.000001900 "dacp.c:787" DACP Album Name seen
0.000002470 "dacp.c:795" DACP Genre seen
0.000002170 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.994685819 "rtp.c:513" AP1 control thread: set_ntp_anchor_info: rtptime: 2337698846, networktime: 1ea80738a0bdadb0, frame adjustment:  -3.506.
0.062529680 "dacp.c:803" DACP Composite ID seen
0.000004710 "dacp.c:771" DACP Track Name seen
0.000002000 "dacp.c:779" DACP Artist Name seen
0.000001520 "dacp.c:787" DACP Album Name seen
0.000001470 "dacp.c:795" DACP Genre seen
0.000001740 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.905402457 "rtp.c:771" clock synchronisation request: return time is   92.553 milliseconds.
0.037082186 "rtp.c:513" AP1 control thread: set_ntp_anchor_info: rtptime: 2337743198, networktime: 1ea80738dcb0dfb0, frame adjustment:  -3.506.
0.093922710 "dacp.c:803" DACP Composite ID seen
0.000005480 "dacp.c:771" DACP Track Name seen
0.000003930 "dacp.c:779" DACP Artist Name seen
0.000002860 "dacp.c:787" DACP Album Name seen
0.000002250 "dacp.c:795" DACP Genre seen
0.000003260 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
1.005629713 "rtp.c:513" AP1 control thread: set_ntp_anchor_info: rtptime: 2337787550, networktime: 1ea8073918a411b0, frame adjustment:  -3.506.
0.035449917 "dacp.c:803" DACP Composite ID seen
0.000006850 "dacp.c:771" DACP Track Name seen
0.000003260 "dacp.c:779" DACP Artist Name seen
0.000002240 "dacp.c:787" DACP Album Name seen
0.000002770 "dacp.c:795" DACP Genre seen
0.000001960 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.975434582 "rtp.c:513" AP1 control thread: set_ntp_anchor_info: rtptime: 2337831902, networktime: 1ea80739549743af, frame adjustment:  -3.506.
0.113488287 "dacp.c:803" DACP Composite ID seen
0.000010160 "dacp.c:771" DACP Track Name seen
0.000002770 "dacp.c:779" DACP Artist Name seen
0.000002360 "dacp.c:787" DACP Album Name seen
0.000002280 "dacp.c:795" DACP Genre seen
0.000002190 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.704069706 "rtp.c:771" clock synchronisation request: return time is   57.596 milliseconds.
0.204910409 "rtp.c:513" AP1 control thread: set_ntp_anchor_info: rtptime: 2337876254, networktime: 1ea80739908a75af, frame adjustment:  -3.506.
0.126219848 "dacp.c:803" DACP Composite ID seen
0.000008790 "dacp.c:771" DACP Track Name seen
0.000002880 "dacp.c:779" DACP Artist Name seen
0.000001750 "dacp.c:787" DACP Album Name seen
0.000001560 "dacp.c:795" DACP Genre seen
0.000001820 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.387988291 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "FLUSH":
0.000013800 "rtsp.c:5253"   Type: "CSeq", content: "9"
0.000004510 "rtsp.c:5253"   Type: "Session", content: "1"
0.000003230 "rtsp.c:5253"   Type: "RTP-Info", content: "seq=53630;rtptime=2338001880"
0.000002470 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000005760 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000003060 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000002900 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000002420 "rtsp.c:5253"   No Content Plist. Content length: 0.
0.000004000 "rtsp.c:2814" FLUSH request
0.000003310 "rtsp.c:2814"   Type: "CSeq", content: "9"
0.000003780 "rtsp.c:2814"   Type: "Session", content: "1"
0.000003670 "rtsp.c:2814"   Type: "RTP-Info", content: "seq=53630;rtptime=2338001880"
0.000002980 "rtsp.c:2814"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000004509 "rtsp.c:2814"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000003030 "rtsp.c:2814"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000003100 "rtsp.c:2814"   Type: "Active-Remote", content: "2843644481"
0.000003090 "rtsp.c:2814"   No Content Plist. Content length: 0.
0.000003890 "rtsp.c:2830" RTSP Flush Requested: 2338001880.
0.000012050 "rtsp.c:5312" Connection 2: RTSP Response:
0.000002870 "rtsp.c:5313"   Response Code: 200.
0.000002570 "rtsp.c:5313"   Type: "CSeq", content: "9"
0.000003200 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000003110 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.031784820 "player.c:1057" flush request: flush frame 2338001880 completed -- buffer contained 53504 frames, from 2337948376 to2338001879
0.000021140 "player.c:1100" flush request: flush done.
0.614325235 "dacp.c:708" Play status is "paused".
0.000011170 "dacp.c:803" DACP Composite ID seen
0.000002260 "dacp.c:771" DACP Track Name seen
0.000002490 "dacp.c:779" DACP Artist Name seen
0.000001750 "dacp.c:787" DACP Album Name seen
0.000001840 "dacp.c:795" DACP Genre seen
0.000001580 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
1.035113383 "dacp.c:803" DACP Composite ID seen
0.000010510 "dacp.c:771" DACP Track Name seen
0.000003560 "dacp.c:779" DACP Artist Name seen
0.000002330 "dacp.c:787" DACP Album Name seen
0.000001920 "dacp.c:795" DACP Genre seen
0.000001890 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.546817898 "rtp.c:771" clock synchronisation request: return time is    4.505 milliseconds.
0.842632378 "dacp.c:803" DACP Composite ID seen
0.000012210 "dacp.c:771" DACP Track Name seen
0.000003440 "dacp.c:779" DACP Artist Name seen
0.000002450 "dacp.c:787" DACP Album Name seen
0.000002460 "dacp.c:795" DACP Genre seen
0.000002010 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
1.448602437 "dacp.c:803" DACP Composite ID seen
0.000009120 "dacp.c:771" DACP Track Name seen
0.000003160 "dacp.c:779" DACP Artist Name seen
0.000002300 "dacp.c:787" DACP Album Name seen
0.000002310 "dacp.c:795" DACP Genre seen
0.000003490 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.710279603 "rtp.c:771" clock synchronisation request: return time is    5.795 milliseconds.
0.426692945 "dacp.c:803" DACP Composite ID seen
0.000010810 "dacp.c:771" DACP Track Name seen
0.000002640 "dacp.c:779" DACP Artist Name seen
0.000001830 "dacp.c:787" DACP Album Name seen
0.000001800 "dacp.c:795" DACP Genre seen
0.000002220 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
1.510962798 "dacp.c:803" DACP Composite ID seen
0.000013200 "dacp.c:771" DACP Track Name seen
0.000002360 "dacp.c:779" DACP Artist Name seen
0.000002920 "dacp.c:787" DACP Album Name seen
0.000002590 "dacp.c:795" DACP Genre seen
0.000001960 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.817982413 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
0.000016280 "rtsp.c:5253"   Type: "CSeq", content: "10"
0.000005810 "rtsp.c:5253"   Type: "Session", content: "1"
0.000003250 "rtsp.c:5253"   Type: "Content-Type", content: "text/parameters"
0.000004250 "rtsp.c:5253"   Type: "Content-Length", content: "18"
0.000003760 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000002970 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000001990 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000001910 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000002140 "rtsp.c:5253"   No Content Plist. Content length: 18.
0.000004100 "rtsp.c:3617" Connection 2: request to set AirPlay Volume to: 0.000000.
0.000004900 "player.c:3487" Software attenuation set to 0.000000, i.e 65536.000000 out of 65,536, for airplay volume of 0.000000
0.000004940 "loudness.c:47" Volume: 0.0 dB - Loudness gain @10Hz: 0.0 dB
0.000010710 "player.c:3528" player_volume_without_notification: volume mode is 0, airplay volume is 0.00, software_attenuation dB: 0.00, hardware_attenuation dB: 0.00, muting is disabled.
0.000003310 "rtsp.c:5312" Connection 2: RTSP Response:
0.000002230 "rtsp.c:5313"   Response Code: 200.
0.000002040 "rtsp.c:5313"   Type: "CSeq", content: "10"
0.000002530 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000001950 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.185108941 "rtp.c:468" New latency: 99225, sync latency: 88200, minimum latency: 0, maximum latency: 0, fixed offset: 11025, audio_backend_latency_offset: 0.000000.
0.000011520 "rtp.c:513" AP1 control thread: set_ntp_anchor_info: rtptime: 2337902655, networktime: 1ea8073b91b1a0cd, frame adjustment: -353268.193.
0.000004050 "player.c:490" Connection 2: synced by first packet, seqno 53630.
0.000128820 "player.c:1137" Accepting packet 53630 with timestamp 2338001880. Lead time is 2.056122 seconds.
0.000009530 "player.c:1211" Connection 2: Lead time for first frame 2338001880: 2.056120 seconds.
0.052779146 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
0.000015020 "rtsp.c:5253"   Type: "CSeq", content: "11"
0.000003390 "rtsp.c:5253"   Type: "Session", content: "1"
0.000002310 "rtsp.c:5253"   Type: "Content-Type", content: "application/x-dmap-tagged"
0.000001960 "rtsp.c:5253"   Type: "Content-Length", content: "1202"
0.000004300 "rtsp.c:5253"   Type: "RTP-Info", content: "rtptime=2338001880"
0.000002390 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000005730 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000003240 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000003490 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000002710 "rtsp.c:5253"   No Content Plist. Content length: 1202.
0.000016890 "metadata_hub.c:531" MH Metadata stream processing start.
0.000016220 "metadata_hub.c:387" MH Song Time seen: "161280" of length 4.
0.000005870 "metadata_hub.c:376" MH Item ID seen: "54512961a0656a4d" of length 8.
0.000005070 "metadata_hub.c:360" MH Song Data Kind seen: "1" of length 1.
0.000061090 "rtsp.c:5312" Connection 2: RTSP Response:
0.000002290 "rtsp.c:5313"   Response Code: 200.
0.000001320 "metadata_hub.c:538" MH Metadata stream processing end without changes.
0.000002640 "rtsp.c:5313"   Type: "CSeq", content: "11"
0.000007190 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000002470 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.011684662 "rtp.c:771" clock synchronisation request: return time is   11.370 milliseconds.
0.304874074 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
0.000014900 "rtsp.c:5253"   Type: "CSeq", content: "12"
0.000002890 "rtsp.c:5253"   Type: "Session", content: "1"
0.000002660 "rtsp.c:5253"   Type: "Content-Type", content: "image/png"
0.000002350 "rtsp.c:5253"   Type: "Content-Length", content: "1075480"
0.000002220 "rtsp.c:5253"   Type: "RTP-Info", content: "rtptime=2338001880"
0.000001930 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000004090 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000001560 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000001580 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000004310 "rtsp.c:5253"   No Content Plist. Content length: 1075480.
0.000010820 "rtsp.c:5312" Connection 2: RTSP Response:
0.000002580 "rtsp.c:5313"   Response Code: 200.
0.000000100 "rtsp.c:5313"   Type: "CSeq", content: "12"
0.000004980 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000004310 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.000001730 "metadata_hub.c:542" MH Picture received, length 1075480 bytes.
0.160587276 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "SET_PARAMETER":
0.000013440 "rtsp.c:5253"   Type: "CSeq", content: "13"
0.000003230 "rtsp.c:5253"   Type: "Session", content: "1"
0.000002290 "rtsp.c:5253"   Type: "Content-Type", content: "text/parameters"
0.000002130 "rtsp.c:5253"   Type: "Content-Length", content: "44"
0.000001630 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000004610 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000002480 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000002280 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000003100 "rtsp.c:5253"   No Content Plist. Content length: 44.
0.000009930 "rtsp.c:5312" Connection 2: RTSP Response:
0.000002850 "rtsp.c:5313"   Response Code: 200.
0.000001760 "rtsp.c:5313"   Type: "CSeq", content: "13"
0.000001630 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000001640 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.000005640 "metadata_hub.c:587" MH Progress String set to: "2337057816/2338001880/2344170264"
0.000012780 "dacp.c:714" Play status changed to "playing".
0.000005650 "dacp.c:803" DACP Composite ID seen
0.000001940 "dacp.c:771" DACP Track Name seen
0.000001640 "dacp.c:779" DACP Artist Name seen
0.000001260 "dacp.c:787" DACP Album Name seen
0.000001240 "dacp.c:795" DACP Genre seen
0.000001500 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.284483997 "rtp.c:468" New latency: 99578, sync latency: 88553, minimum latency: 0, maximum latency: 0, fixed offset: 11025, audio_backend_latency_offset: 0.000000.
0.000023800 "rtp.c:513" AP1 control thread: set_ntp_anchor_info: rtptime: 2337947006, networktime: 1ea8073bcda4d2cd, frame adjustment:  -4.506.
0.794067889 "dacp.c:803" DACP Composite ID seen
0.000009180 "dacp.c:771" DACP Track Name seen
0.000002760 "dacp.c:779" DACP Artist Name seen
0.000001710 "dacp.c:787" DACP Album Name seen
0.000002250 "dacp.c:795" DACP Genre seen
0.000002050 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.211880914 "rtp.c:513" AP1 control thread: set_ntp_anchor_info: rtptime: 2337991358, networktime: 1ea8073c099804cc, frame adjustment:  -3.506.
0.839282359 "player.c:2579" number_of_statistics is zero!
0.040783204 "dacp.c:803" DACP Composite ID seen
0.000010530 "dacp.c:771" DACP Track Name seen
0.000003880 "dacp.c:779" DACP Artist Name seen
0.000002450 "dacp.c:787" DACP Album Name seen
0.000001810 "dacp.c:795" DACP Genre seen
0.000002100 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.125704509 "rtp.c:513" AP1 control thread: set_ntp_anchor_info: rtptime: 2338035710, networktime: 1ea8073c458b36cc, frame adjustment:  -3.506.
0.369085143 "rtp.c:771" clock synchronisation request: return time is  142.246 milliseconds.
0.540772382 "dacp.c:803" DACP Composite ID seen
0.000009390 "dacp.c:771" DACP Track Name seen
0.000002720 "dacp.c:779" DACP Artist Name seen
0.000001760 "dacp.c:787" DACP Album Name seen
0.000002610 "dacp.c:795" DACP Genre seen
0.000002620 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.095488788 "rtp.c:513" AP1 control thread: set_ntp_anchor_info: rtptime: 2338080062, networktime: 1ea8073c817e68cc, frame adjustment:  -3.506.
1.002629255 "dacp.c:803" DACP Composite ID seen
0.000011920 "dacp.c:771" DACP Track Name seen
0.000003230 "dacp.c:779" DACP Artist Name seen
0.000001740 "dacp.c:787" DACP Album Name seen
0.000001790 "dacp.c:795" DACP Genre seen
0.000002100 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.003980877 "rtp.c:513" AP1 control thread: set_ntp_anchor_info: rtptime: 2338124414, networktime: 1ea8073cbd719acb, frame adjustment:  -3.506.
0.508091303 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "FLUSH":
0.000015090 "rtsp.c:5253"   Type: "CSeq", content: "14"
0.000004840 "rtsp.c:5253"   Type: "Session", content: "1"
0.000002560 "rtsp.c:5253"   Type: "RTP-Info", content: "seq=54302;rtptime=2338238424"
0.000002530 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000007800 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000014900 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000002480 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000001870 "rtsp.c:5253"   No Content Plist. Content length: 0.
0.000003310 "rtsp.c:2814" FLUSH request
0.000002600 "rtsp.c:2814"   Type: "CSeq", content: "14"
0.000002150 "rtsp.c:2814"   Type: "Session", content: "1"
0.000002050 "rtsp.c:2814"   Type: "RTP-Info", content: "seq=54302;rtptime=2338238424"
0.000002150 "rtsp.c:2814"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000004500 "rtsp.c:2814"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000002630 "rtsp.c:2814"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000003130 "rtsp.c:2814"   Type: "Active-Remote", content: "2843644481"
0.000003030 "rtsp.c:2814"   No Content Plist. Content length: 0.
0.000003450 "rtsp.c:2830" RTSP Flush Requested: 2338238424.
0.000011610 "rtsp.c:5312" Connection 2: RTSP Response:
0.000003310 "rtsp.c:5313"   Response Code: 200.
0.000002900 "rtsp.c:5313"   Type: "CSeq", content: "14"
0.000003150 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000003160 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.031491630 "player.c:1057" flush request: flush frame 2338238424 completed -- buffer contained 47168 frames, from 2338191256 to2338238423
0.000010660 "player.c:1100" flush request: flush done.
0.497785149 "dacp.c:708" Play status is "paused".
0.000010260 "dacp.c:803" DACP Composite ID seen
0.000003730 "dacp.c:771" DACP Track Name seen
0.000003070 "dacp.c:779" DACP Artist Name seen
0.000002280 "dacp.c:787" DACP Album Name seen
0.000002700 "dacp.c:795" DACP Genre seen
0.000001390 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.182335323 "rtp.c:771" clock synchronisation request: return time is    4.893 milliseconds.
0.849178533 "dacp.c:803" DACP Composite ID seen
0.000010100 "dacp.c:771" DACP Track Name seen
0.000003360 "dacp.c:779" DACP Artist Name seen
0.000002480 "dacp.c:787" DACP Album Name seen
0.000001960 "dacp.c:795" DACP Genre seen
0.000002210 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
1.133568640 "dacp.c:803" DACP Composite ID seen
0.000009210 "dacp.c:771" DACP Track Name seen
0.000003380 "dacp.c:779" DACP Artist Name seen
0.000002470 "dacp.c:787" DACP Album Name seen
0.000002100 "dacp.c:795" DACP Genre seen
0.000002230 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
1.194692271 "rtp.c:771" clock synchronisation request: return time is  182.276 milliseconds.
0.927837463 "dacp.c:803" DACP Composite ID seen
0.000011500 "dacp.c:771" DACP Track Name seen
0.000003330 "dacp.c:779" DACP Artist Name seen
0.000002450 "dacp.c:787" DACP Album Name seen
0.000001910 "dacp.c:795" DACP Genre seen
0.000002040 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
0.710185733 "rtsp.c:5251" Connection 2: Received an RTSP Packet of type "TEARDOWN":
0.000013590 "rtsp.c:5253"   Type: "CSeq", content: "15"
0.000003630 "rtsp.c:5253"   Type: "Session", content: "1"
0.000001880 "rtsp.c:5253"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000002620 "rtsp.c:5253"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000001180 "rtsp.c:5253"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000001120 "rtsp.c:5253"   Type: "Active-Remote", content: "2843644481"
0.000001290 "rtsp.c:5253"   No Content Plist. Content length: 0.
0.000002220 "rtsp.c:2799" TEARDOWN request
0.000001750 "rtsp.c:2799"   Type: "CSeq", content: "15"
0.000002100 "rtsp.c:2799"   Type: "Session", content: "1"
0.000001770 "rtsp.c:2799"   Type: "User-Agent", content: "Music/1.4.1 (Macintosh; OS X 14.1.1) AppleWebKit/616.2.9.11.7"
0.000002220 "rtsp.c:2799"   Type: "Client-Instance", content: "8EA9D2F8A68F597E"
0.000001140 "rtsp.c:2799"   Type: "DACP-ID", content: "8EA9D2F8A68F597E"
0.000001090 "rtsp.c:2799"   Type: "Active-Remote", content: "2843644481"
0.000001970 "rtsp.c:2799"   No Content Plist. Content length: 0.
0.000001820 "rtsp.c:2800" Connection 2: TEARDOWN
0.000001740 "rtsp.c:2775" Connection 2: TEARDOWN (Classic AirPlay).
0.000001740 "player.c:3645" Connection 2: player_stop.
0.000028570 "player.c:1848" Cancelling AP1 timing, control and audio threads...
0.000347730 "rtp.c:317" Control Receiver Cleanup Done.
0.000260939 "player.c:433" 1024 buffers allocated, 1024 buffers released.
0.000009240 "player.c:1894" Connection 2: player terminated.
0.000134140 "player.c:3660" Connection 2: player_stop successful.
0.000013550 "rtsp.c:5312" Connection 2: RTSP Response:
0.000003080 "rtsp.c:5313"   Response Code: 200.
0.000002010 "rtsp.c:5313"   Type: "CSeq", content: "15"
0.000002400 "rtsp.c:5313"   Type: "Server", content: "AirTunes/105.1"
0.000002440 "rtsp.c:5313"   Type: "Connection", content: "close"
0.000002640 "rtsp.c:5313"   No Content Plist. Content length: 0.
0.921382507 "dacp.c:803" DACP Composite ID seen
0.000014950 "dacp.c:771" DACP Track Name seen
0.000004010 "dacp.c:779" DACP Artist Name seen
0.000002720 "dacp.c:787" DACP Album Name seen
0.000001770 "dacp.c:795" DACP Genre seen
0.000001710 "dacp.c:825" DACP Song Time seen: "161280" of length 4.
1.229632009 "rtsp.c:1334" Connection 2: Connection closed by client.
0.000016500 "rtsp.c:5068" Connection 2: Classic AirPlay stream rtsp_conversation_thread_func_cleanup_function called.
0.000004940 "rtsp.c:2775" Connection 2: TEARDOWN (Classic AirPlay).
0.000003110 "player.c:3645" Connection 2: player_stop.
0.000002780 "player.c:3665" Connection 2: no player thread.
0.000016410 "rtsp.c:5100" Connection 2: terminating -- closing RTSP connection socket 8: from 192.168.20.10:58028 to self at 192.168.20.14:5000.
0.000100780 "rtsp.c:5167" Connection 2: Closed.
0.000004810 "rtsp.c:5389" Connection 2: RTSP thread exit.
0.102610144 "dacp.c:1196" Freeing response memory.
0.000014270 "dacp.c:1253" Unexpected return code 501 from dacp_get_speaker_list.
1.204337514 "mdns_avahi.c:160" (Browser) REMOVE: service 'iTunes_Ctrl_8EA9D2F8A68F597E' of type '_dacp._tcp' in domain 'local'.
0.303701635 "dacp.c:464" dacp_monitor_port_update_callback with Remote ID "8EA9D2F8A68F597E", target ID "8EA9D2F8A68F597E" and port number 0.
0.000011860 "mdns_avahi.c:160" (Browser) REMOVE: service 'iTunes_Ctrl_8EA9D2F8A68F597E' of type '_dacp._tcp' in domain 'local'.
0.000002800 "dacp.c:464" dacp_monitor_port_update_callback with Remote ID "8EA9D2F8A68F597E", target ID "8EA9D2F8A68F597E" and port number 0.
6.238200144 "activity_monitor.c:84" aend
0.000027320 "activity_monitor.c:163" am_state: am_inactive
13.343366760 "shairport.c:1745" exit on SIGINT
0.000034760 "rtsp.c:5415" rtsp_listen_loop_cleanup_handler called.
0.000006850 "rtsp.c:533" Connection 2: not cancelled.
0.000002830 "rtsp.c:5421" closing socket 3.
0.000007150 "rtsp.c:5421" closing socket 4.
0.000298440 "shairport.c:1588" exit function called...
0.000005440 "shairport.c:1598" Stopping the activity monitor.
0.000002380 "activity_monitor.c:243" activity_monitor_stop begin. state: 0, player_state: 0.
0.000098640 "activity_monitor.c:250" activity_monitor_stop complete
0.000002360 "shairport.c:1600" Stopping the activity monitor done.
0.000001340 "shairport.c:1603" Stopping DACP Monitor
0.000001240 "dacp.c:991" dacp_monitor_stop
0.000082780 "shairport.c:1605" Stopping DACP Monitor Done
0.000002010 "shairport.c:1634" Stopping metadata hub
0.000001190 "shairport.c:1636" Stopping metadata done
0.000001490 "shairport.c:1640" Stopping metadata
0.000001370 "rtsp.c:4229" metadata_stop called.
0.000015510 "rtsp.c:394" Deleting metadata queue "mqtt".
0.000094650 "rtsp.c:394" Deleting metadata queue "hub".
0.000094410 "rtsp.c:394" Deleting metadata queue "multicast".
0.000082230 "rtsp.c:394" Deleting metadata queue "pipe".
0.000071350 "shairport.c:1642" Stopping metadata done
0.000002120 "shairport.c:1646" Deinitialise the audio backend.
0.000001750 "shairport.c:1648" Deinitialise the audio backend done.
0.000001550 "shairport.c:1654" Waiting for SoXr timecheck to terminate...
0.000012290 "shairport.c:1657" Waiting for SoXr timecheck to terminate done
0.000139340 "mdns_avahi.c:531" avahi_dacp_monitor_stop Avahi DACP monitor successfully stopped
0.000002300 "mdns_avahi.c:428" avahi_unregister.
0.000001340 "mdns_avahi.c:430" avahi: stop the threaded poll.
0.000076830 "mdns_avahi.c:434" avahi: free the client.
0.000011480 "mdns_avahi.c:440" avahi: free the threaded poll.
0.000005270 "mdns_avahi.c:448" avahi: free the service name.
0.000001720 "mdns_avahi.c:455" avahi: free the ap2 service_name.
0.000001200 "mdns_avahi.c:461" avahi free text_record_string_list
0.000002200 "shairport.c:1725" normal ex

System Information.

Artix Linux OpenRC

Configuration Information.

>> Display Config Start.

From "uname -a":
 Linux pc 6.7.4-zen1-1-zen #1 ZEN SMP PREEMPT_DYNAMIC Wed, 07 Feb 2024 08:00:08 +0000 x86_64 GNU/Linux

From /etc/os-release:
 Artix Linux

Shairport Sync Version String:
 4.3.2-OpenSSL-Avahi-dns_sd-ALSA-jack-pa-stdout-pipe-soxr-metadata-mqtt-sysconfdir:/etc

Command Line:
 shairport-sync --displayConfig

Configuration File:
 /etc/shairport-sync.conf

Configuration File Settings:
 general :
 {
   interpolation = "auto";
   output_backend = "pipe";
 };
 pw :
 {
   application_name = "Shairport Sync";
   node_name = "Shairport Sync";
 };

>> Display Config End.
>> Goodbye!

PulseAudio or PipeWire installed?

• [X] Check if your system uses a Sound Server.

How did you install Shairport Sync?

A package manager (apt, apt install, yum, pkg, etc.)

Check previous issues

• [X] Confirm

[mikebrady]

Thanks for the post. I notice that the backend you have chosen is "pipe", but that is not for PipeWire -- instead it is for output to a Unix pipe.

The PipeWire backend is abbreviated "pw". So try building with the PipeWire backend: include --with-pw at the ./configure... step. You'll be told if you have to add a PipeWire library. Then, specify the pw backend as the output_backend in the configuration file:

...
output_backend = "pw";
...

Regarding the alsa problems, you might wish to review this discussion about using sound servers like PipeWire.

[github-actions[bot]]

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.