[Problem]: No Sound initially #2031
Description
What happened?
When airplaying music from my iPhone, The phone acts as if playback is proceeding without issue (I can pause and resume etc), however there is no sound for about a minute or two and then playback will begin. On the airplay reciever, I can see the metadata is recieved, but there is no audio.
Below is a verbose log where I did the following:
- Initiated shairport-sync with -vv
- Started playback from iphone
- Turned the volume up (to hear when playback starts)
- Waiting until playback began (after about a minute)
- Terminated shairport-sync with ctrl+c
Relevant log output
0.000492448 "shairport.c:579" looking for configuration file at full path "/etc/shairport-sync.conf"
0.001515833 "shairport.c:1474" default metadata_pipename is "/tmp/shairport-sync-metadata".
0.000431614 "shairport.c:2282" Startup in AirPlay 2 mode, with features 0x405fca00,0x1c340 on device "b8:27:eb:1a:e1:8c".
0.000080625 "shairport.c:2321" Version String: "4.3.6-AirPlay2-smi10-libdaemon-OpenSSL-Avahi-ALSA-jack-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc"
0.000050625 "shairport.c:2340" Command Line: "shairport-sync -vv -a AIRPLAY-TEST -- -d _audioout".
0.000068125 "shairport.c:2347" libsodium initialised.
0.000267292 "shairport.c:2372" libgcrypt initialised.
0.000014636 "shairport.c:2376" Log Verbosity is 2.
0.000015625 "audio_alsa.c:1065" alsa: init() -- alsa_backend_state => abm_disconnected.
0.000012552 "audio_alsa.c:1082" alsa: alsa_maximum_stall_time of 0.200000 sec.
0.000051979 "audio_alsa.c:1236" alsa output rate is 44100 frames per second
0.000024739 "audio_alsa.c:1371" alsa: disable_standby_mode is "auto".
0.000011355 "audio_alsa.c:1375" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
0.000012916 "audio_alsa.c:1377" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
0.000029531 "audio_alsa.c:1417" alsa: output device name is "_audioout".
0.000266094 "shairport.c:2411" The processor is running little-endian.
0.000018021 "shairport.c:2444" disable_resend_requests is off.
0.000001250 "shairport.c:2445" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
0.000014270 "shairport.c:2449" statistics_requester status is 0.
0.000012292 "shairport.c:2451" daemon status is 0.
0.000013438 "shairport.c:1571" PID file: "/run/shairport-sync/shairport-sync.pid".
0.000011198 "shairport.c:2452" daemon pid file path is "/run/shairport-sync/shairport-sync.pid".
0.000011770 "shairport.c:2454" rtsp listening port is 7000.
0.000011719 "shairport.c:2455" udp base port is 6001.
0.000010938 "shairport.c:2456" udp port range is 10.
0.000012135 "shairport.c:2457" player name is "AIRPLAY-TEST".
0.000010990 "audio_alsa.c:2110" keep_dac_busy is now "no"
0.000011042 "shairport.c:2458" backend is "alsa".
0.000017604 "shairport.c:2459" run_this_before_play_begins action is "(null)".
0.000011771 "shairport.c:2460" run_this_after_play_ends action is "(null)".
0.000011354 "shairport.c:2461" wait-cmd status is 1.
0.000063385 "shairport.c:2462" run_this_before_play_begins may return output is 0.
0.000019271 "shairport.c:2463" run_this_if_an_unfixable_error_is_detected action is "(null)".
0.000012761 "shairport.c:2465" run_this_before_entering_active_state action is "/var/local/www/commandw/spspre.sh".
0.000012395 "shairport.c:2467" run_this_after_exiting_active_state action is "/var/local/www/commandw/spspost.sh".
0.000012344 "shairport.c:2469" active_state_timeout is 10.000000 seconds.
0.000015052 "shairport.c:2470" mdns backend "(null)".
0.000010990 "shairport.c:2471" userSuppliedLatency is 0.
0.000016510 "shairport.c:2472" interpolation setting is "soxr".
0.000011771 "shairport.c:2476" interpolation soxr_delay_threshold is 30000000.
0.000011615 "shairport.c:2477" resync time is 0.050000 seconds.
0.000011875 "shairport.c:2478" resync recovery time is 0.100000 seconds.
0.000013385 "shairport.c:2479" allow a session to be interrupted: 0.
0.000055104 "shairport.c:2480" busy timeout time is 5.
0.000037500 "shairport.c:2481" drift tolerance is 0.002000 seconds.
0.000037865 "shairport.c:2482" password is not set.
0.000035312 "shairport.c:2483" default airplay volume is: -24.000000.
0.000038073 "shairport.c:2484" high threshold airplay volume is: -16.000000.
0.000037500 "shairport.c:2486" check for higher-than-threshold volume for new play session is disabled.
0.000035417 "shairport.c:2492" ignore_volume_control is 0.
0.000034948 "shairport.c:2496" volume_max_db is not set
0.000033854 "shairport.c:2497" volume range in dB (zero means use the range specified by the mixer): 0.
0.000049948 "shairport.c:2499" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
0.000037812 "shairport.c:2503" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
0.000036198 "shairport.c:2505" disable_synchronization is 0.
0.000027657 "shairport.c:2506" use_mmap_if_available is 1.
0.000013072 "shairport.c:2507" output_format automatic selection is disabled.
0.000012084 "shairport.c:2510" output_format is "S16".
0.000010989 "shairport.c:2511" output_rate automatic selection is disabled.
0.000011407 "shairport.c:2514" output_rate is 44100.
0.000010885 "shairport.c:2515" audio backend desired buffer length is 0.200000 seconds.
0.000015833 "shairport.c:2517" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
0.000013438 "shairport.c:2519" audio backend latency offset is 0.000000 seconds.
0.000012396 "shairport.c:2521" audio backend silence lead-in time is "auto".
0.000010937 "shairport.c:2525" zeroconf regtype is "_raop._tcp".
0.000011250 "shairport.c:2526" decoders_supported field is 1.
0.000010781 "shairport.c:2527" use_apple_decoder is 0.
0.000010886 "shairport.c:2528" alsa_use_hardware_mute is 0.
0.000010937 "shairport.c:2532" no special mdns service interface was requested.
0.000036823 "shairport.c:2535" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
0.000014011 "shairport.c:2542" metadata enabled is 1.
0.000011146 "shairport.c:2543" metadata pipename is "/tmp/shairport-sync-metadata".
0.000011666 "shairport.c:2544" metadata socket address is "(null)" port 0.
0.000011719 "shairport.c:2546" metadata socket packet size is "500".
0.000011510 "shairport.c:2547" get-coverart is 1.
0.000010834 "shairport.c:2550" mqtt is disabled.
0.000010781 "shairport.c:2551" mqtt hostname is (null), port is 1883.
0.000011615 "shairport.c:2552" mqtt topic is /AIRPLAY-TEST.
0.000010729 "shairport.c:2553" mqtt will not publish raw metadata.
0.000011198 "shairport.c:2554" mqtt will not publish parsed metadata.
0.000011041 "shairport.c:2555" mqtt will not publish cover Art.
0.000011459 "shairport.c:2556" mqtt remote control is disabled.
0.000011093 "shairport.c:2557" mqtt autodiscovery is disabled.
0.000010834 "shairport.c:2561" convolution is 0.
0.000010781 "shairport.c:2562" convolution IR file is "(null)"
0.000010781 "shairport.c:2563" convolution max length 8192
0.000010938 "shairport.c:2564" convolution gain is 0.000000
0.000011771 "shairport.c:2566" loudness is 0.
0.000010937 "shairport.c:2567" loudness reference level is -20.000000
0.000244635 "rtsp.c:4189" metadata pipe name is "/tmp/shairport-sync-metadata".
0.000060365 "rtsp.c:373" Creating metadata queue "pipe".
0.000189688 "rtsp.c:373" Creating metadata queue "multicast".
0.000120104 "rtsp.c:373" Creating metadata queue "hub".
0.000161666 "rtsp.c:373" Creating metadata queue "mqtt".
0.002412969 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp T"
0.001167761 "ptp-utilities.c:165" ptp_shm_interface_open with mapped_addr = 0
0.000210104 "ptp-utilities.c:196" ptp_shm_interface_open -- success!
0.000119427 "shairport.c:2694" NQPTP is online.
0.000812552 "activity_monitor.c:163" am_state: am_inactive
0.011574844 "dbus-service.c:610" >> setting loudness threshold to -20.000000.
0.001312500 "dbus-service.c:623" >> setting drift tolerance to 0.002000 seconds.
0.000080156 "dbus-service.c:636" >> setting volume to -24.0000.
0.000049687 "dbus-service.c:1025" >> ALACDecoder set to "hammerton"
0.000052865 "dbus-service.c:1030" >> Active set to "false"
0.000031875 "dbus-service.c:1043" >> disable standby mode set to "auto"
0.000029792 "dbus-service.c:1059" >> interpolation set to "soxr"
0.000037291 "dbus-service.c:518" >> deactivating disable standby
0.000026302 "dbus-service.c:600" >> deactivating loudness
0.000023698 "dbus-service.c:534" >> deactivating convolution
0.000117813 "dbus-service.c:503" >> log verbosity set to 2.
0.000027291 "dbus-service.c:488" >> stop logging statistics
0.000023334 "dbus-service.c:448" >> stop including elapsed time in logs
0.000031406 "dbus-service.c:458" >> start including delta time in logs
0.000027344 "dbus-service.c:471" >> start including file and line in logs
0.000074479 "dbus-service.c:1175" Shairport Sync native D-Bus service started at "org.gnome.ShairportSync" on the system bus.
0.002798906 "mpris-service.c:342" MPRIS service started at "org.mpris.MediaPlayer2.ShairportSync" on the system bus.
0.006742917 "mdns_avahi.c:220" avahi: service 'B827EB1AE18C@AIRPLAY-TEST' group is not yet committed.
0.005356406 "mdns_avahi.c:277" avahi: avahi_entry_group_commit 0
0.000485469 "mdns_avahi.c:477" avahi_dacp_monitor_start Avahi DACP monitor successfully started
0.000214583 "mdns_avahi.c:224" avahi: service 'B827EB1AE18C@AIRPLAY-TEST' group is registering.
0.917798177 "mdns_avahi.c:191" avahi: service 'B827EB1AE18C@AIRPLAY-TEST' successfully added.
0.552418541 "shairport.c:248" soxr_delay: 7097077 nanoseconds, soxr_delay_threshold: 30 milliseconds.
11.601151298 "rtsp.c:669" No active connections.
0.000226146 "rtsp.c:5647" can't set the keepAliveIdleTime wait time
0.000032760 "rtsp.c:5694" Connection 1: New connection from 2600:e001:1f6:7d00:e1ba:1bf7:d850:c112:53256 to self at 2600:e001:1f6:7d00:ae04:d498:43f8:a2a8:7000.
0.037371042 "rtsp.c:2259" Connection 1: handle_pair-setup Content-Length 9
0.062337969 "rtsp.c:2259" Connection 1: handle_pair-setup Content-Length 457
0.146293333 "rtsp.c:2880" Connection 1: SETUP (AirPlay 2)
0.000211146 "rtsp.c:2900" Connection 1 SETUP: No "streams" array has been found -- create an event thread and open a TCP port.
0.000051666 "rtsp.c:2913" Connection 1: AP2 PTP connection from 2600:e001:1f6:7d00:e1ba:1bf7:d850:c112:53256 ("Christopher’s iPhone 14") to self at 2600:e001:1f6:7d00:ae04:d498:43f8:a2a8:7000.
0.000044427 "rtsp.c:586" Connection 1: request to acquire principal_conn.
0.000087240 "ptp-utilities.c:165" ptp_shm_interface_open with mapped_addr = 547907297280
0.000040000 "ptp-utilities.c:200" ptp_shm_interface_open -- already open!
0.000040260 "rtsp.c:3001" Updated groupContainsGroupLeader to 0
0.000045625 "metadata_hub.c:570" MH Client IP set to: "2600:e001:1f6:7d00:e1ba:1bf7:d850:c112"
0.000005729 "dbus-service.c:226" Build metadata
0.000505677 "mpris-service.c:167" Build metadata
0.000333907 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp T 2600:e001:1f6:7d00:e1ba:1bf7:d850:c112"
0.000521927 "metadata_hub.c:622" MH Server IP set to: "2600:e001:1f6:7d00:ae04:d498:43f8:a2a8"
0.000313438 "dbus-service.c:226" Build metadata
0.000129583 "mpris-service.c:167" Build metadata
0.000420885 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp B"
0.000822344 "rtsp.c:3111" Connection 1: TCP PTP event port opened: 57843.
0.000411146 "rtp.c:1572" Connection 1: AP2 Event Receiver started
0.000208489 "rtsp.c:3138" Connection 1: SETUP mdns_update on PTP stream.
0.001771355 "metadata_hub.c:578" MH Client Name set to: "Christopher’s iPhone 14"
0.000294270 "dbus-service.c:226" Build metadata
0.000874063 "mpris-service.c:167" Build metadata
0.068685052 "rtp.c:1584" Connection 1: rtp_event_receiver accepted a connection on socket 13 and moved to a new socket 14.
0.012226094 "rtsp.c:4405" Connection 1: current volume (-24.000000) requested
0.006722135 "rtsp.c:1585" Connection 1: RECORD on PTP stream
0.010908386 "rtsp.c:2479" Connection 1: POST /command Content-Length 128
0.005338229 "rtsp.c:2479" Connection 1: POST /command Content-Length 939
2.570981405 "rtsp.c:2880" Connection 1: SETUP (AirPlay 2)
0.000107656 "rtsp.c:3223" Connection 1: SETUP on PTP stream. A "streams" array has been found
0.000020000 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp B"
0.000505625 "rtsp.c:3251" Connection 1: UDP control port opened: 40479.
0.000131823 "rtsp.c:3270" Connection 1: SETUP AP2 no Active-Remote information the SETUP Record.
0.000016823 "rtsp.c:3289" Connection 1: SETUP AP2 doesn't include DACP-ID string information.
0.000021511 "rtsp.c:3357" Connection 1. AP2 Buffered Audio Stream.
0.000012656 "rtsp.c:3358" Buffered Audio Stream SETUP incoming message
0.000011562 "rtsp.c:3358" Type: "Content-Length", content: "297"
0.000012136 "rtsp.c:3358" Type: "Content-Type", content: "application/x-apple-binary-plist"
0.000011927 "rtsp.c:3358" Type: "CSeq", content: "14"
0.000011146 "rtsp.c:3358" Type: "User-Agent", content: "AirPlay/860.7.1"
0.000083750 "rtsp.c:3358" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>streams</key>
<array>
<dict>
<key>type</key>
<integer>103</integer>
<key>audioMode</key>
<string>default</string>
<key>ct</key>
<integer>4</integer>
<key>streamConnectionID</key>
<integer>-4860984189103420511</integer>
<key>spf</key>
<integer>1024</integer>
<key>shk</key>
<data>
nkNAkYwsw8LOgaZwXCI8WY3MHnIuNPmtV3UQozvtLag=
</data>
<key>supportsDynamicStreamID</key>
<true/>
<key>audioFormat</key>
<integer>4194304</integer>
<key>audioFormatIndex</key>
<integer>22</integer>
<key>clientID</key>
<string>fr.radiooooo.app</string>
</dict>
</array>
</dict>
</plist>
--
0.000111145 "rtsp.c:3375" Connection 1: TCP Buffered Audio port opened: 35997.
0.456463646 "activity_monitor.c:64" abeg
0.000585469 "dbus-service.c:226" Build metadata
0.000753177 "mpris-service.c:167" Build metadata
0.000551719 "activity_monitor.c:167" am_state: am_active
0.004005573 "audio_alsa.c:2110" keep_dac_busy is now "yes"
0.052319218 "audio_alsa.c:1599" alsa: update timestamps available
0.002365052 "audio_alsa.c:257" alsa: precision delay timing is not available because it's not definitely a hardware device.
0.000086823 "audio_alsa.c:820" PCM handle name = '_audioout'
0.000015625 "audio_alsa.c:834" alsa device parameters:
0.000013855 "audio_alsa.c:837" access type = MMAP_INTERLEAVED
0.000016770 "audio_alsa.c:840" format = 'S16_LE' (Signed 16 bit Little Endian)
0.000015730 "audio_alsa.c:844" subformat = 'STD' (Standard)
0.000011822 "audio_alsa.c:848" number of channels = 2
0.000012969 "audio_alsa.c:851" number of significant bits = 16
0.000012500 "audio_alsa.c:859" rate = 44100 frames per second (precisely).
0.000013750 "audio_alsa.c:868" precise (rational) rate = 44100.000 frames per second (i.e. 44100/1).
0.000022761 "audio_alsa.c:882" period_time = 5011 us (>).
0.000013229 "audio_alsa.c:892" period_size = 221 frames (precisely).
0.000013437 "audio_alsa.c:905" buffer_time = 2000000 us (precisely).
0.000013177 "audio_alsa.c:918" buffer_size = 88200 frames (precisely).
0.000012188 "audio_alsa.c:934" periods_per_buffer = 399 (>).
0.000015677 "audio_alsa.c:1980" alsa: prepare() -- opened output device
0.000478594 "player.c:3632" Connection 1: player_play.
0.000848437 "dbus-service.c:226" Build metadata
0.005546979 "mpris-service.c:167" Build metadata
0.005936875 "rtp.c:1425" Connection 1: No NQPTP master clock.
0.001161094 "rtsp.c:2558" Connection 1: POST /audioMode Content-Length 64
0.001064792 "rtsp.c:2560" Type: "Content-Length", content: "64"
0.000067760 "rtsp.c:2560" Type: "Content-Type", content: "application/x-apple-binary-plist"
0.000044948 "rtsp.c:2560" Type: "CSeq", content: "15"
0.000037136 "rtsp.c:2560" Type: "User-Agent", content: "AirPlay/860.7.1"
0.000067343 "rtsp.c:2560" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>audioMode</key>
<string>default</string>
</dict>
</plist>
--
0.007962188 "dacp.c:411" set_dacp_server_information set IP to "2600:e001:1f6:7d00:e1ba:1bf7:d850:c112" and DACP id to "".
0.000194739 "player.c:2259" Set initial volume to -24.000000.
0.000105938 "player.c:3515" Software attenuation set to -5489.100000, i.e 118.013022 out of 65,536, for airplay volume of -24.000000
0.000622344 "loudness.c:47" Volume: -54.9 dB - Loudness gain @10Hz: 17.4 dB
0.000480781 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -24.00, software_attenuation dB: -54.89, hardware_attenuation dB: 0.00, muting is disabled.
0.000080729 "player.c:2262" Play begin
0.000673646 "dbus-service.c:226" Build metadata
0.001882656 "mpris-service.c:167" Build metadata
0.112774844 "rtsp.c:1970" networkTimeTimelineID "5c3e1b0347550008".
0.000139479 "rtsp.c:1975" anchor networkTimeSecs is 674607.
0.000056562 "rtsp.c:1980" anchor networkTimeFrac is 015462095469924057088.
0.000039167 "rtsp.c:1991" anchorTimeNanoseconds looks like 674607838201874.
0.000107969 "rtp.c:1274" set_ptp_anchor_info: clock: 5c3e1b0347550008, rtptime: 1257484265, networktime: 2658d608f0812.
0.000062812 "rtp.c:1277" Connection 1: Set Anchor Clock: 5c3e1b0347550008.
0.000048646 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp B"
0.000871354 "rtsp.c:2018" Connection 1: Start playing, with anchor clock 5c3e1b0347550008.
0.010540625 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: -24.000000.
0.000226146 "dbus-service.c:636" >> setting volume to -24.0000.
0.000069271 "player.c:3515" Software attenuation set to -5489.100000, i.e 118.013022 out of 65,536, for airplay volume of -24.000000
0.000052083 "loudness.c:47" Volume: -54.9 dB - Loudness gain @10Hz: 17.4 dB
0.000083177 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -24.00, software_attenuation dB: -54.89, hardware_attenuation dB: 0.00, muting is disabled.
0.020011094 "metadata_hub.c:542" MH Picture received, length 34001 bytes.
0.009174219 "dbus-service.c:226" Build metadata
0.000950260 "mpris-service.c:167" Build metadata
0.000717084 "metadata_hub.c:587" MH Progress String set to: "1251518525/1257486027/1268629325"
0.000669271 "dbus-service.c:226" Build metadata
0.000941770 "mpris-service.c:167" Build metadata
0.001572292 "metadata_hub.c:531" MH Metadata stream processing start.
0.000125625 "metadata_hub.c:376" MH Item ID seen: "74039ab14cfdc6d" of length 8.
0.000055052 "metadata_hub.c:381" MH Item ID set to: "74039ab14cfdc6d"
0.000043854 "metadata_hub.c:400" MH Album name set to: "Hidden Gem"
0.000048802 "metadata_hub.c:408" MH Artist name set to: "The Zenmenn & John Moods"
0.000295886 "metadata_hub.c:441" MH Track Name set to: "Out Of My Mind"
0.000050156 "metadata_hub.c:360" MH Song Data Kind seen: "0" of length 1.
0.000097917 "metadata_hub.c:366" MH Song Data Kind set to: "0"
0.000047500 "metadata_hub.c:387" MH Song Time seen: "388000" of length 4.
0.000139218 "metadata_hub.c:393" MH Song Time set to: "388000"
0.000050365 "metadata_hub.c:536" MH Metadata stream processing end with changes.
0.000336615 "dbus-service.c:226" Build metadata
0.000358489 "mpris-service.c:167" Build metadata
0.005315573 "rtsp.c:2479" Connection 1: POST /command Content-Length 939
56.420901749 "rtsp.c:671" One active connection.
54.243742323 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: -22.125000.
0.000163959 "dbus-service.c:636" >> setting volume to -22.1250.
0.000037812 "player.c:3515" Software attenuation set to -4947.412500, i.e 220.177877 out of 65,536, for airplay volume of -22.125000
0.000022188 "loudness.c:47" Volume: -49.5 dB - Loudness gain @10Hz: 14.7 dB
0.000054531 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -22.12, software_attenuation dB: -49.47, hardware_attenuation dB: 0.00, muting is disabled.
0.001704219 "dbus-service.c:226" Build metadata
0.000497604 "mpris-service.c:167" Build metadata
0.337271146 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: -20.250000.
0.000224843 "dbus-service.c:636" >> setting volume to -20.2500.
0.000665105 "player.c:3515" Software attenuation set to -4405.725000, i.e 410.787699 out of 65,536, for airplay volume of -20.250000
0.000063906 "loudness.c:47" Volume: -44.1 dB - Loudness gain @10Hz: 12.0 dB
0.000081927 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -20.25, software_attenuation dB: -44.06, hardware_attenuation dB: 0.00, muting is disabled.
0.039192969 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: -18.375000.
0.000222708 "dbus-service.c:636" >> setting volume to -18.3750.
0.000655781 "player.c:3515" Software attenuation set to -3864.037500, i.e 766.410032 out of 65,536, for airplay volume of -18.375000
0.000063542 "loudness.c:47" Volume: -38.6 dB - Loudness gain @10Hz: 9.3 dB
0.000106562 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -18.38, software_attenuation dB: -38.64, hardware_attenuation dB: 0.00, muting is disabled.
0.000214219 "dbus-service.c:226" Build metadata
0.000525625 "mpris-service.c:167" Build metadata
0.039560313 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: -16.500000.
0.000220885 "dbus-service.c:636" >> setting volume to -16.5000.
0.000630052 "player.c:3515" Software attenuation set to -3322.350000, i.e 1429.897578 out of 65,536, for airplay volume of -16.500000
0.000036302 "loudness.c:47" Volume: -33.2 dB - Loudness gain @10Hz: 6.6 dB
0.000084584 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -16.50, software_attenuation dB: -33.22, hardware_attenuation dB: 0.00, muting is disabled.
0.000216770 "dbus-service.c:226" Build metadata
0.000249011 "mpris-service.c:167" Build metadata
0.040962187 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: -14.625000.
0.000214740 "dbus-service.c:636" >> setting volume to -14.6250.
0.000641198 "player.c:3515" Software attenuation set to -2780.662500, i.e 2667.771819 out of 65,536, for airplay volume of -14.625000
0.000064166 "loudness.c:47" Volume: -27.8 dB - Loudness gain @10Hz: 3.9 dB
0.000284584 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -14.62, software_attenuation dB: -27.81, hardware_attenuation dB: 0.00, muting is disabled.
0.043033177 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: -12.750000.
0.000168594 "dbus-service.c:636" >> setting volume to -12.7500.
0.000028229 "player.c:3515" Software attenuation set to -2238.975000, i.e 4977.284099 out of 65,536, for airplay volume of -12.750000
0.000026250 "loudness.c:47" Volume: -22.4 dB - Loudness gain @10Hz: 1.2 dB
0.000050000 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -12.75, software_attenuation dB: -22.39, hardware_attenuation dB: 0.00, muting is disabled.
0.000182760 "dbus-service.c:226" Build metadata
0.000515000 "mpris-service.c:167" Build metadata
0.041028490 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: -10.875000.
0.000236823 "dbus-service.c:636" >> setting volume to -10.8750.
0.000704583 "player.c:3515" Software attenuation set to -1745.437500, i.e 8785.392735 out of 65,536, for airplay volume of -10.875000
0.000071823 "loudness.c:47" Volume: -17.5 dB - Loudness gain @10Hz: 0.0 dB
0.000122812 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -10.88, software_attenuation dB: -17.45, hardware_attenuation dB: 0.00, muting is disabled.
0.040558438 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: -9.000000.
0.000213750 "dbus-service.c:636" >> setting volume to -9.0000.
0.000651250 "player.c:3515" Software attenuation set to -1444.500000, i.e 12423.098556 out of 65,536, for airplay volume of -9.000000
0.000065573 "loudness.c:47" Volume: -14.4 dB - Loudness gain @10Hz: 0.0 dB
0.000193646 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -9.00, software_attenuation dB: -14.45, hardware_attenuation dB: 0.00, muting is disabled.
0.000204323 "dbus-service.c:226" Build metadata
0.001445625 "mpris-service.c:167" Build metadata
0.040877187 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: -7.125000.
0.000235573 "dbus-service.c:636" >> setting volume to -7.1250.
0.000622135 "player.c:3515" Software attenuation set to -1143.562500, i.e 17567.043658 out of 65,536, for airplay volume of -7.125000
0.000063490 "loudness.c:47" Volume: -11.4 dB - Loudness gain @10Hz: 0.0 dB
0.000052604 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -7.12, software_attenuation dB: -11.44, hardware_attenuation dB: 0.00, muting is disabled.
0.000187813 "dbus-service.c:226" Build metadata
0.000265260 "mpris-service.c:167" Build metadata
0.041219010 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: -5.250000.
0.000209584 "dbus-service.c:636" >> setting volume to -5.2500.
0.000697344 "player.c:3515" Software attenuation set to -842.625000, i.e 24840.905954 out of 65,536, for airplay volume of -5.250000
0.000077447 "loudness.c:47" Volume: -8.4 dB - Loudness gain @10Hz: 0.0 dB
0.000134271 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -5.25, software_attenuation dB: -8.43, hardware_attenuation dB: 0.00, muting is disabled.
0.088674063 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: -3.375000.
0.000165521 "dbus-service.c:636" >> setting volume to -3.3750.
0.000030833 "player.c:3515" Software attenuation set to -541.687500, i.e 35126.605286 out of 65,536, for airplay volume of -3.375000
0.000023125 "loudness.c:47" Volume: -5.4 dB - Loudness gain @10Hz: 0.0 dB
0.000048437 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -3.38, software_attenuation dB: -5.42, hardware_attenuation dB: 0.00, muting is disabled.
0.000298230 "dbus-service.c:226" Build metadata
0.000541718 "mpris-service.c:167" Build metadata
0.005570625 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: -1.500000.
0.000218177 "dbus-service.c:636" >> setting volume to -1.5000.
0.000400365 "player.c:3515" Software attenuation set to -240.750000, i.e 49671.231846 out of 65,536, for airplay volume of -1.500000
0.000060521 "loudness.c:47" Volume: -2.4 dB - Loudness gain @10Hz: 0.0 dB
0.000114739 "player.c:3538" player_volume_without_notification: volume mode is 0, airplay volume is -1.50, software_attenuation dB: -2.41, hardware_attenuation dB: 0.00, muting is disabled.
0.031935834 "rtsp.c:3629" Connection 1: request to set AirPlay Volume to: 0.000000.
0.000248854 "dbus-service.c:636" >> setting volume to 0.0000.
0.000630052 "player.c:3515" Software attenuation set to 0.000000, i.e 65536.000000 out of 65,536, for airplay volume of 0.000000
0.000097969 "loudness.c:47" Volume: 0.0 dB - Loudness gain @10Hz: 0.0 dB
0.000111094 "player.c:3538" 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.000355572 "dbus-service.c:226" Build metadata
0.000635261 "mpris-service.c:167" Build metadata
42.251573473 "metadata_hub.c:531" MH Metadata stream processing start.
0.000071667 "metadata_hub.c:376" MH Item ID seen: "3ca85a3e1574c07b" of length 8.
0.000017344 "metadata_hub.c:381" MH Item ID set to: "3ca85a3e1574c07b"
0.000016562 "metadata_hub.c:400" MH Album name set to: "Nebulous"
0.000019167 "metadata_hub.c:408" MH Artist name set to: "The Natural Yogurt Band"
0.000018125 "metadata_hub.c:441" MH Track Name set to: "Messages"
0.000014844 "metadata_hub.c:387" MH Song Time seen: "313000" of length 4.
0.000012239 "metadata_hub.c:393" MH Song Time set to: "313000"
0.000013125 "metadata_hub.c:536" MH Metadata stream processing end with changes.
0.000139115 "dbus-service.c:226" Build metadata
0.000221614 "mpris-service.c:167" Build metadata
0.006119427 "metadata_hub.c:542" MH Picture received, length 0 bytes.
0.000408073 "dbus-service.c:226" Build metadata
0.000320730 "mpris-service.c:167" Build metadata
0.004738281 "metadata_hub.c:531" MH Metadata stream processing start.
0.000403854 "metadata_hub.c:376" MH Item ID seen: "3ca85a3e1574c07b" of length 8.
0.000075156 "metadata_hub.c:538" MH Metadata stream processing end without changes.
0.009757136 "metadata_hub.c:542" MH Picture received, length 1949 bytes.
0.005275312 "dbus-service.c:226" Build metadata
0.000451250 "mpris-service.c:167" Build metadata
0.668012031 "metadata_hub.c:531" MH Metadata stream processing start.
0.000448177 "metadata_hub.c:376" MH Item ID seen: "3ca85a3e1574c07b" of length 8.
0.000162344 "metadata_hub.c:538" MH Metadata stream processing end without changes.
0.006991510 "metadata_hub.c:587" MH Progress String set to: "1264296349/1264296986/1278099649"
0.000359323 "dbus-service.c:226" Build metadata
0.000955261 "mpris-service.c:167" Build metadata
0.006743906 "metadata_hub.c:542" MH Picture received, length 0 bytes.
0.000431198 "dbus-service.c:226" Build metadata
0.000325677 "mpris-service.c:167" Build metadata
0.009148177 "metadata_hub.c:531" MH Metadata stream processing start.
0.000095885 "metadata_hub.c:376" MH Item ID seen: "3ca85a3e1574c07b" of length 8.
0.000074375 "metadata_hub.c:538" MH Metadata stream processing end without changes.
0.019369896 "metadata_hub.c:542" MH Picture received, length 45117 bytes.
0.001391511 "dbus-service.c:226" Build metadata
0.000471979 "mpris-service.c:167" Build metadata
0.051882604 "rtsp.c:2749" Connection 1: TEARDOWN 2 PTP stream.
0.000157656 "rtsp.c:2751" TEARDOWN:
0.000018698 "rtsp.c:2751" Type: "Content-Length", content: "84"
0.000013073 "rtsp.c:2751" Type: "Content-Type", content: "application/x-apple-binary-plist"
0.000012552 "rtsp.c:2751" Type: "CSeq", content: "121"
0.000011146 "rtsp.c:2751" Type: "User-Agent", content: "AirPlay/860.7.1"
0.000053646 "rtsp.c:2751" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>streams</key>
<array>
<dict>
<key>streamID</key>
<integer>0</integer>
<key>type</key>
<integer>103</integer>
</dict>
</array>
</dict>
</plist>
--
0.000045885 "rtsp.c:2760" Connection 1: TEARDOWN PTP stream -- close the stream.
0.000013854 "player.c:3655" Connection 1: player_stop.
0.000257240 "player.c:1827" Cancelling AP2 timing, control and audio threads...
0.000059063 "player.c:1836" Connection 1: Delete Buffered Audio Stream thread
0.000611145 "rtp.c:2010" Buffered TCP Reader Thread Exit via Cleanup.
0.002709427 "rtp.c:2183" Buffered Audio Receiver Cleanup Start.
0.000274532 "rtp.c:2186" Connection 1: TCP Buffered Audio port closed: 35997.
0.000048854 "rtp.c:2189" Buffered Audio Receiver Cleanup Done.
0.000149844 "player.c:1844" Connection 0: Delete AirPlay 2 Control thread
0.000206041 "rtp.c:1633" Connection 1: AP2 Control Receiver Cleanup.
0.000161927 "rtp.c:1635" Connection 1: UDP control port 40479 closed.
0.000168907 "rtp.c:1322" Connection 1: Clear anchor information.
0.000463333 "player.c:432" 1024 buffers allocated, 1024 buffers released.
0.000048958 "player.c:1897" Connection 1: player terminated.
0.000119323 "player.c:3670" Connection 1: player_stop successful.
0.000071146 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp E"
0.000683802 "rtsp.c:2765" Connection 1: TEARDOWN PTP stream -- close the stream complete
0.000283333 "dbus-service.c:226" Build metadata
0.001077969 "mpris-service.c:167" Build metadata
0.006381927 "rtsp.c:2880" Connection 1: SETUP (AirPlay 2)
0.000142240 "rtsp.c:3223" Connection 1: SETUP on PTP stream. A "streams" array has been found
0.000046354 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp B"
0.000681042 "rtsp.c:3251" Connection 1: UDP control port opened: 55536.
0.000197239 "rtsp.c:3270" Connection 1: SETUP AP2 no Active-Remote information the SETUP Record.
0.000050261 "rtsp.c:3289" Connection 1: SETUP AP2 doesn't include DACP-ID string information.
0.000041718 "rtsp.c:3357" Connection 1. AP2 Buffered Audio Stream.
0.000036459 "rtsp.c:3358" Buffered Audio Stream SETUP incoming message
0.000035573 "rtsp.c:3358" Type: "Content-Length", content: "297"
0.000035989 "rtsp.c:3358" Type: "Content-Type", content: "application/x-apple-binary-plist"
0.000035990 "rtsp.c:3358" Type: "CSeq", content: "122"
0.000037500 "rtsp.c:3358" Type: "User-Agent", content: "AirPlay/860.7.1"
0.000118281 "rtsp.c:3358" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>streams</key>
<array>
<dict>
<key>type</key>
<integer>103</integer>
<key>audioMode</key>
<string>default</string>
<key>ct</key>
<integer>4</integer>
<key>streamConnectionID</key>
<integer>-6762357807165781770</integer>
<key>spf</key>
<integer>1024</integer>
<key>shk</key>
<data>
Z8E4lfNfJNvbA4ANc6954Zq7E0tQWSlxcw+gfHJjBR8=
</data>
<key>supportsDynamicStreamID</key>
<true/>
<key>audioFormat</key>
<integer>4194304</integer>
<key>audioFormatIndex</key>
<integer>22</integer>
<key>clientID</key>
<string>fr.radiooooo.app</string>
</dict>
</array>
</dict>
</plist>
--
0.000366250 "rtsp.c:3375" Connection 1: TCP Buffered Audio port opened: 56633.
0.000119531 "player.c:3632" Connection 1: player_play.
0.000491094 "dbus-service.c:226" Build metadata
0.000313438 "mpris-service.c:167" Build metadata
0.007162656 "dacp.c:411" set_dacp_server_information set IP to "2600:e001:1f6:7d00:e1ba:1bf7:d850:c112" and DACP id to "".
0.000156823 "player.c:2259" Set initial volume to 0.000000.
0.000054896 "player.c:3515" Software attenuation set to 0.000000, i.e 65536.000000 out of 65,536, for airplay volume of 0.000000
0.000050572 "loudness.c:47" Volume: 0.0 dB - Loudness gain @10Hz: 0.0 dB
0.000107605 "player.c:3538" 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.000066406 "player.c:2262" Play begin
0.000949167 "dbus-service.c:226" Build metadata
0.000945885 "mpris-service.c:167" Build metadata
0.001034219 "rtsp.c:2558" Connection 1: POST /audioMode Content-Length 64
0.000082968 "rtsp.c:2560" Type: "Content-Length", content: "64"
0.000039271 "rtsp.c:2560" Type: "Content-Type", content: "application/x-apple-binary-plist"
0.000037240 "rtsp.c:2560" Type: "CSeq", content: "123"
0.000035521 "rtsp.c:2560" Type: "User-Agent", content: "AirPlay/860.7.1"
0.000063750 "rtsp.c:2560" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>audioMode</key>
<string>default</string>
</dict>
</plist>
--
0.090589791 "rtsp.c:1970" networkTimeTimelineID "5c3e1b0347550008".
0.000101823 "rtsp.c:1975" anchor networkTimeSecs is 674762.
0.000040938 "rtsp.c:1980" anchor networkTimeFrac is 09801382316721831936.
0.000037396 "rtsp.c:1991" anchorTimeNanoseconds looks like 674762531333999.
0.000061666 "rtp.c:1274" set_ptp_anchor_info: clock: 5c3e1b0347550008, rtptime: 1699414625, networktime: 265b164fce76f.
0.000045886 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp B"
0.000606823 "rtsp.c:2018" Connection 1: Start playing, with anchor clock 5c3e1b0347550008.
0.013485468 "metadata_hub.c:542" MH Picture received, length 45117 bytes.
0.008520886 "metadata_hub.c:587" MH Progress String set to: "1699404740/1699415680/1713208040"
0.000465260 "dbus-service.c:226" Build metadata
0.000890938 "mpris-service.c:167" Build metadata
0.007888854 "metadata_hub.c:531" MH Metadata stream processing start.
0.000285104 "metadata_hub.c:376" MH Item ID seen: "3ca85a3e1574c07b" of length 8.
0.000257813 "metadata_hub.c:360" MH Song Data Kind seen: "0" of length 1.
0.000111562 "metadata_hub.c:387" MH Song Time seen: "313000" of length 4.
0.000081927 "metadata_hub.c:538" MH Metadata stream processing end without changes.
0.006462865 "rtsp.c:2479" Connection 1: POST /command Content-Length 939
85.034407103 "rtp.c:1406" Connection 1: NQPTP master clock 5c3e1b0347550008.
0.000127239 "rtp.c:2494" Play started.
0.000025677 "rtp.c:2750" block sequence number changed from expected 1 to actual 7745801.
0.430937761 "rtp.c:2576" Connection 1: buffered audio starting frame: 1703185487, lead time: 0.003905 seconds.
0.000130364 "player.c:489" Connection 1: synced by first packet, seqno 0.
0.000083490 "player.c:1130" Dropping out of date packet 0 with timestamp 1703185487. Lead time is 0.003696 seconds.
0.000040573 "player.c:1130" Dropping out of date packet 1 with timestamp 1703185839. Lead time is 0.011678 seconds.
0.000029323 "player.c:1432" Connection 1: Buffer Empty
0.000409166 "player.c:1130" Dropping out of date packet 2 with timestamp 1703186191. Lead time is 0.019184 seconds.
0.000091042 "player.c:1130" Dropping out of date packet 3 with timestamp 1703186543. Lead time is 0.027166 seconds.
0.000074792 "player.c:1130" Dropping out of date packet 4 with timestamp 1703186895. Lead time is 0.035147 seconds.
0.000096250 "player.c:1130" Dropping out of date packet 5 with timestamp 1703187247. Lead time is 0.043129 seconds.
0.000043802 "player.c:1130" Dropping out of date packet 6 with timestamp 1703187599. Lead time is 0.051111 seconds.
0.000093750 "player.c:1130" Dropping out of date packet 7 with timestamp 1703187951. Lead time is 0.059093 seconds.
0.000107812 "player.c:1130" Dropping out of date packet 8 with timestamp 1703188303. Lead time is 0.066576 seconds.
0.000045886 "player.c:1130" Dropping out of date packet 9 with timestamp 1703188655. Lead time is 0.074558 seconds.
0.000072760 "player.c:1130" Dropping out of date packet 10 with timestamp 1703189007. Lead time is 0.082540 seconds.
0.000131458 "player.c:1130" Dropping out of date packet 11 with timestamp 1703189359. Lead time is 0.090272 seconds.
0.000047709 "player.c:1130" Dropping out of date packet 12 with timestamp 1703189711. Lead time is 0.098254 seconds.
0.000090781 "player.c:1130" Dropping out of date packet 13 with timestamp 1703190063. Lead time is 0.106236 seconds.
0.000108646 "player.c:1130" Dropping out of date packet 14 with timestamp 1703190415. Lead time is 0.113968 seconds.
0.000046562 "player.c:1136" Accepting packet 15 with timestamp 1703190767. Lead time is 0.121950 seconds.
0.000066198 "player.c:1214" Connection 1: Lead time for first frame 1703190767: 0.121937 seconds.
0.000073281 "audio_alsa.c:1949" alsa: play() -- alsa_backend_state => abm_playing
0.003285573 "player.c:2778" first frame sync error (positive --> late): 25 frames, 0.567 mS at 44100 frames per second output.
0.000281771 "metadata_hub.c:614" MH Stream Type set to: "Buffered"
0.000436563 "dbus-service.c:226" Build metadata
0.000865000 "mpris-service.c:167" Build metadata
6.716367810 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp P"
0.000563541 "rtsp.c:2028" Connection 1: Pause playing.
0.000048750 "rtp.c:1322" Connection 1: Clear anchor information.
0.000470469 "rtsp.c:2036" Connection 1: Stop the output backend.
0.000325834 "rtp.c:1428" Connection 1: Awaiting clock anchor information.
0.000243229 "dbus-service.c:226" Build metadata
0.000593593 "mpris-service.c:167" Build metadata
0.005870521 "rtp.c:2484" Play stopped.
9.996959475 "activity_monitor.c:84" aend
0.001282500 "activity_monitor.c:163" am_state: am_inactive
0.000001146 "dbus-service.c:226" Build metadata
0.001524063 "mpris-service.c:167" Build metadata
0.001068802 "audio_alsa.c:2110" keep_dac_busy is now "no"
0.000303437 "audio_alsa.c:2131" alsa: alsa_buffer_monitor_thread_code() -- closing the output device
0.000143802 "audio_alsa.c:1883" alsa: do_close()
0.011385261 "audio_alsa.c:1896" alsa: do_close() -- closing alsa handle
0.000363854 "audio_alsa.c:2134" alsa: alsa_buffer_monitor_thread_code() -- alsa_backend_state => abm_disconnected
0.122955417 "rtsp.c:1841" FLUSHBUFFERED request
0.000113802 "rtsp.c:1841" Type: "Content-Length", content: "87"
0.000081875 "rtsp.c:1841" Type: "Content-Type", content: "application/x-apple-binary-plist"
0.000040312 "rtsp.c:1841" Type: "CSeq", content: "181"
0.000053229 "rtsp.c:1841" Type: "User-Agent", content: "AirPlay/860.7.1"
0.000080625 "rtsp.c:1841" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>flushUntilSeq</key>
<integer>7755146</integer>
<key>flushUntilTS</key>
<integer>1709003823</integer>
</dict>
</plist>
--
0.000357240 "rtsp.c:1852" Can't find a flushFromSeq
0.000039792 "rtsp.c:1864" Can't find a flushFromTS
0.000037500 "rtsp.c:1877" flushUntilSeq is 7755146.
0.000035729 "rtsp.c:1885" flushUntilTS is 1709003823.
0.000048385 "rtsp.c:1932" Immediate Flush Requested
0.009644167 "rtp.c:2445" Flush requested.
0.000101354 "rtp.c:2451" untilTS: 1709003823
0.000013958 "rtp.c:2452" untilSeq: 7755146
0.000012136 "rtp.c:2453" --
0.000010573 "rtp.c:2454" currentTS_Start: 1703508015
0.000011302 "rtp.c:2456" framesInBuffer: 1024
0.000010989 "rtp.c:2458" currentTS_End: 1703509039
0.000011771 "rtp.c:2459" currentSeq: 7749779
0.000058698 "rtp.c:2523" Immediate Buffered Audio Flush Started.
0.009896406 "rtp.c:1966" buffered_read: waiting for 2 bytes (okay at start of a track).
0.075235990 "rtsp.c:2749" Connection 1: TEARDOWN 2 PTP stream.
0.000175208 "rtsp.c:2751" TEARDOWN:
0.000050886 "rtsp.c:2751" Type: "Content-Length", content: "84"
0.000039218 "rtsp.c:2751" Type: "Content-Type", content: "application/x-apple-binary-plist"
0.000038125 "rtsp.c:2751" Type: "CSeq", content: "182"
0.000036667 "rtsp.c:2751" Type: "User-Agent", content: "AirPlay/860.7.1"
0.000087813 "rtsp.c:2751" Content Plist (as XML):
--
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
<key>streams</key>
<array>
<dict>
<key>streamID</key>
<integer>0</integer>
<key>type</key>
<integer>103</integer>
</dict>
</array>
</dict>
</plist>
--
0.000644375 "rtsp.c:2760" Connection 1: TEARDOWN PTP stream -- close the stream.
0.000047916 "player.c:3655" Connection 1: player_stop.
0.000258282 "player.c:1827" Cancelling AP2 timing, control and audio threads...
0.000064843 "player.c:1836" Connection 1: Delete Buffered Audio Stream thread
0.000350677 "rtp.c:2010" Buffered TCP Reader Thread Exit via Cleanup.
0.000370209 "rtp.c:2183" Buffered Audio Receiver Cleanup Start.
0.000170312 "rtp.c:2186" Connection 1: TCP Buffered Audio port closed: 56633.
0.000144896 "rtp.c:2189" Buffered Audio Receiver Cleanup Done.
0.000251719 "player.c:1844" Connection 0: Delete AirPlay 2 Control thread
0.000158281 "rtp.c:1633" Connection 1: AP2 Control Receiver Cleanup.
0.001904427 "rtp.c:1635" Connection 1: UDP control port 55536 closed.
0.000297188 "rtp.c:1322" Connection 1: Clear anchor information.
0.001644375 "player.c:432" 2048 buffers allocated, 2048 buffers released.
0.000058229 "player.c:1897" Connection 1: player terminated.
0.000180469 "player.c:3670" Connection 1: player_stop successful.
0.000090781 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp E"
0.000969635 "rtsp.c:2765" Connection 1: TEARDOWN PTP stream -- close the stream complete
0.000358334 "dbus-service.c:226" Build metadata
0.000883854 "mpris-service.c:167" Build metadata
^C 4.739370258 "shairport.c:1753" exit on SIGINT
0.001375990 "rtsp.c:5420" rtsp_listen_loop_cleanup_handler called.
0.000121250 "rtsp.c:531" Connection 1: cancelled.
0.000102917 "rtsp.c:2675" Connection 1: TEARDOWN PTP stream connection.
0.000088593 "rtsp.c:2695" Connection 1: TEARDOWN PTP stream Delete Event Thread.
0.000421042 "rtp.c:1564" Connection 1: AP2 Event Receiver Cleanup.
0.000252969 "rtsp.c:2703" Connection 1: TEARDOWN PTP stream Close Event Socket.
0.000268073 "ptp-utilities.c:225" Send control message to NQPTP: "/nqptp T"
0.000751562 "rtsp.c:2735" Connection 1: TEARDOWN mdns_update on PTP stream.
0.001643229 "rtsp.c:2742" Connection 1: TEARDOWN PTP stream -- close the connection complete
0.000117240 "rtsp.c:5117" Connection 1: terminating -- closing RTSP connection socket 12: from 2600:e001:1f6:7d00:e1ba:1bf7:d850:c112:53256 to self at 2600:e001:1f6:7d00:ae04:d498:43f8:a2a8:7000.
0.000533854 "rtsp.c:542" Connection 1: joined.
0.000153073 "rtsp.c:5426" closing socket 5.
0.000085469 "rtsp.c:5426" closing socket 7.
0.000273333 "shairport.c:1596" exit function called...
0.000035313 "shairport.c:1606" Stopping the activity monitor.
0.000013541 "activity_monitor.c:243" activity_monitor_stop begin. state: 0, player_state: 0.
0.000263594 "activity_monitor.c:250" activity_monitor_stop complete
0.000024323 "shairport.c:1608" Stopping the activity monitor done.
0.000016198 "shairport.c:1611" Stopping DACP Monitor
0.000012239 "dacp.c:991" dacp_monitor_stop
0.000230052 "shairport.c:1613" Stopping DACP Monitor Done
0.000052188 "shairport.c:1624" Stopping D-Bus service
0.000040052 "dbus-service.c:1219" stopping dbus service
0.002300990 "shairport.c:1626" Stopping D-Bus service done
0.000100052 "shairport.c:1629" Stopping D-Bus Loop Thread
0.000171458 "shairport.c:1560" g_main_loop thread exit
0.000406615 "shairport.c:1637" Stopping D-Bus Loop Thread Done
0.000124010 "shairport.c:1642" Stopping metadata hub
0.000039740 "shairport.c:1644" Stopping metadata done
0.000036458 "shairport.c:1648" Stopping metadata
0.000042083 "rtsp.c:4240" metadata_stop called.
0.000366198 "rtsp.c:393" Deleting metadata queue "mqtt".
0.000742761 "rtsp.c:393" Deleting metadata queue "hub".
0.000314948 "rtsp.c:393" Deleting metadata queue "multicast".
0.000406406 "rtsp.c:393" Deleting metadata queue "pipe".
0.000093958 "shairport.c:1650" Stopping metadata done
0.000039636 "shairport.c:1654" Deinitialise the audio backend.
0.000040989 "audio_alsa.c:1442" Cancel buffer monitor thread.
0.000247865 "shairport.c:1656" Deinitialise the audio backend done.
0.000044531 "shairport.c:1662" Waiting for SoXr timecheck to terminate...
0.000104219 "shairport.c:1665" Waiting for SoXr timecheck to terminate done
0.000046354 "ptp-utilities.c:208" ptp_shm_interface_close
0.000083958 "shairport.c:1728" normal exitSystem Information.
-
This issue seems specific to iPhones airplaying to shairpoint-sync receiver.
-
The same iphones can airplay to other apple devices and a sonos without any issue.
-
The iPad and macbooks can airplay to all recievers without any issue.
-
All apple deviecs are up to date
-
The router is a dual stack ipv4 ipv6 with both 2.4ghz and 5ghz.
-
I have tried turning off LTE with airplane mode, but the issue persists.
Configuration Information.
$ shairport-sync --displayConfig
>> Display Config Start.
From "uname -a":
Linux kitchen 6.12.25+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.12.25-1+rpt1 (2025-04-30) aarch64 GNU/Linux
From /etc/os-release:
Debian GNU/Linux 12 (bookworm)
From /sys/firmware/devicetree/base/model:
Raspberry Pi 3 Model B Plus Rev 1.3
Shairport Sync Version String:
4.3.6-AirPlay2-smi10-libdaemon-OpenSSL-Avahi-ALSA-jack-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc
Command Line:
shairport-sync --displayConfig
Configuration File:
/etc/shairport-sync.conf
Configuration File Settings:
general :
{
interpolation = "soxr";
audio_backend_latency_offset_in_seconds = 0.0;
audio_backend_buffer_desired_length_in_seconds = 0.2;
};
sessioncontrol :
{
run_this_before_entering_active_state = "/var/local/www/commandw/spspre.sh";
run_this_after_exiting_active_state = "/var/local/www/commandw/spspost.sh";
active_state_timeout = 10.0;
wait_for_completion = "yes";
allow_session_interruption = "no";
session_timeout = 5;
};
alsa :
{
output_rate = 44100;
output_format = "S16";
disable_synchronization = "no";
disable_standby_mode = "auto";
};
pw :
{
};
metadata :
{
cover_art_cache_directory = "/var/local/www/imagesw/airplay-covers";
};PulseAudio or PipeWire installed?
- Check if your system uses a Sound Server.
How did you install Shairport Sync?
Homebrew for Mac
Check previous issues
- Confirm