mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.2k stars 571 forks source link

No Clock Anchor. #1415

Closed handcc closed 2 years ago

handcc commented 2 years ago

Hello - I reported my troubles in https://github.com/mikebrady/shairport-sync/issues/1404. My problem appears to be unrelated.

I am unable to stream in AP2 mode from Spotify or SoundCloud. On the client side, it looks like the connection is successful and the music appears to be playing, but there is no audio. When it fails, sometimes I see something like 0.006229704 "rtp.c:1429" Connection 3: No Clock Anchor. See below.

shairport-sync -vu --statistics
         0.000720408 "shairport.c:1892" Started in Airplay 2 mode with features 0x405c4a00,0x1c340 on device "dc:a6:32:a3:9c:1b"!
         0.000137129 "shairport.c:1934" software version: "4.1-dev-174-g8bd31c14-AirPlay2-alac-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
         0.000020945 "shairport.c:1940" log verbosity is 1.
         0.000049426 "audio_alsa.c:1018" alsa: alsa_maximum_stall_time of 0.200000 sec.
         0.000040704 "audio_alsa.c:1310" alsa: disable_standby_mode is "never".
         0.000017037 "audio_alsa.c:1312" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
         0.000017092 "audio_alsa.c:1314" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
         0.000044537 "audio_alsa.c:1353" alsa: output device name is "hw:1".
         0.000217389 "shairport.c:1969" libsodium initialised.
         0.000032445 "shairport.c:2019" disable resend requests is off.
         0.000016925 "shairport.c:2023" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000018037 "shairport.c:2024" statistics_requester status is 1.
         0.000015889 "shairport.c:2029" rtsp listening port is 7000.
         0.000015760 "shairport.c:2030" udp base port is 6001.
         0.000015555 "shairport.c:2031" udp port range is 10.
         0.000015278 "shairport.c:2032" player name is "Raspberrypi".
         0.000015537 "shairport.c:2033" backend is "alsa".
         0.000015463 "shairport.c:2034" run_this_before_play_begins action is "(null)".
         0.000015537 "shairport.c:2035" run_this_after_play_ends action is "(null)".
         0.000015630 "shairport.c:2036" wait-cmd status is 0.
         0.000015481 "shairport.c:2037" run_this_before_play_begins may return output is 0.
         0.000016074 "shairport.c:2039" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000015889 "shairport.c:2041" run_this_before_entering_active_state action is  "(null)".
         0.000015574 "shairport.c:2043" run_this_after_exiting_active_state action is  "(null)".
         0.000015648 "shairport.c:2044" active_state_timeout is  10.000000 seconds.
         0.000018093 "shairport.c:2045" mdns backend "(null)".
         0.000015926 "shairport.c:2050" interpolation setting is "auto".
         0.000015555 "shairport.c:2051" interpolation soxr_delay_threshold is 30.
         0.000015500 "shairport.c:2052" resync time is 0.050000 seconds.
         0.000016241 "shairport.c:2053" allow a session to be interrupted: 0.
         0.000015741 "shairport.c:2054" busy timeout time is 0.
         0.000015407 "shairport.c:2055" drift tolerance is 0.001995 seconds.
         0.000016185 "shairport.c:2056" password is "(null)".
         0.000015445 "shairport.c:2057" ignore_volume_control is 0.
         0.000015241 "shairport.c:2061" volume_max_db is not set
         0.000015277 "shairport.c:2063" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000016204 "shairport.c:2067" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000019704 "shairport.c:2069" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000016129 "shairport.c:2070" disable_synchronization is 0.
         0.000016778 "shairport.c:2071" use_mmap_if_available is 1.
         0.000015500 "shairport.c:2073" output_format automatic selection is enabled.
         0.000015797 "shairport.c:2077" output_rate automatic selection is enabled.
         0.000015611 "shairport.c:2081" audio backend desired buffer length is 0.200000 seconds.
         0.000016481 "shairport.c:2083" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
         0.000016500 "shairport.c:2084" audio backend latency offset is 0.000000 seconds.
         0.000016222 "shairport.c:2086" audio backend silence lead-in time is "auto".
         0.000015445 "shairport.c:2090" zeroconf regtype is "_raop._tcp".
         0.000015426 "shairport.c:2091" decoders_supported field is 3.
         0.000015259 "shairport.c:2092" use_apple_decoder is 1.
         0.000015315 "shairport.c:2093" alsa_use_hardware_mute is 0.
         0.000015259 "shairport.c:2097" no special mdns service interface was requested.
         0.000033778 "shairport.c:2101" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000019129 "shairport.c:2130" loudness is 0.
         0.000015389 "shairport.c:2131" loudness reference level is -20.000000
         1.502142925 "shairport.c:224" "soxr" interpolation has been chosen.
        38.192015126 "rtsp.c:2646" Connection 1: AP2 PTP connection from 192.168.1.112:56747 to self at 192.168.1.223:7000.
         0.844150259 "rtsp.c:3030" Connection 1. AP2 Buffered Audio Stream.
         0.008604314 "audio_alsa.c:529" alsa: output format chosen is "S24_3LE".
         0.000494371 "audio_alsa.c:571" alsa: output speed chosen is 44100.
         0.199362259 "rtp.c:1216" Connection 1: Set Anchor Clock: d81c79ee45af0008.
         0.769777981 "rtp.c:1325" Connection 1: Clock d81c79ee45af0008 is now the new anchor clock and master clock. History: 1500.856610 milliseconds.
         0.000221092 "rtp.c:1408" Connection 1: NQPTP new master clock d81c79ee45af0008.
         7.952800551 "player.c:2460" sync error ms net sync ppm all sync ppm     packets min DAC queue min buffers max buffers output fps (r) output fps (c)
         0.000809519 "player.c:2460"          2.05        -14.3         14.3        1003          7273           1          63            N/A            N/A
         8.003080014 "player.c:2460"          1.43         -2.8          2.8        2006          8602          62          62       44099.67       44100.23
         8.007608569 "player.c:2460"          1.51        -11.3         11.3        3009          8605          62          63       44097.02       44097.57
         8.004782440 "player.c:2460"          1.32          0.0          0.0        4012          8583          62          63       44099.08       44099.62
         8.008563217 "player.c:2460"          1.36         -2.8          2.8        5015          8592          62          62       44098.51       44099.04
         8.002617569 "player.c:2460"          1.55         -8.5          8.5        6018          8599          62          63       44098.52       44099.04
         0.311693741 "player.c:1640" Connection 1: Playback Stopped. Total playing time 00:00:49. Input: 44099.08,  Output: 44098.52 (raw), 44099.04 (corrected) frames per second.
         0.562959537 "rtsp.c:2668" Connection 2: Remote Control connection from 192.168.1.112:56752 to self at 192.168.1.223:7000.
        19.510291562 "rtsp.c:2646" Connection 3: AP2 PTP connection from 192.168.1.112:56756 to self at 192.168.1.223:7000.
         0.375455852 "rtsp.c:3030" Connection 3. AP2 Buffered Audio Stream.
         0.000701722 "audio_alsa.c:529" alsa: output format chosen is "S24_3LE".
         0.000297981 "audio_alsa.c:571" alsa: output speed chosen is 44100.
         0.222228963 "rtp.c:1216" Connection 3: Set Anchor Clock: d81c79ee45af0008.
         1.063534370 "rtp.c:1325" Connection 3: Clock d81c79ee45af0008 is now the new anchor clock and master clock. History: 1500.441833 milliseconds.
         0.000174407 "rtp.c:1408" Connection 3: NQPTP new master clock d81c79ee45af0008.
         7.966381144 "player.c:2460" sync error ms net sync ppm all sync ppm     packets min DAC queue min buffers max buffers output fps (r) output fps (c)
         0.000192648 "player.c:2460"          2.64       -114.4        114.4        1003          7493           2          63            N/A            N/A
         6.514293533 "player.c:1644" Connection 3: Playback Stopped. Total playing time 00:00:16. Input: 44066.71 frames per second.
         0.082751130 "rtsp.c:3030" Connection 3. AP2 Buffered Audio Stream.
         0.000763055 "audio_alsa.c:529" alsa: output format chosen is "S24_3LE".
         0.000079889 "audio_alsa.c:571" alsa: output speed chosen is 44100.
         0.006229704 "rtp.c:1429" Connection 3: No Clock Anchor.
         0.167032555 "player.c:1644" Connection 3: Playback Stopped. Total playing time 00:00:00. Input: 0.00 frames per second.
        27.836803354 "rtsp.c:2668" Connection 4: Remote Control connection from 192.168.1.112:56762 to self at 192.168.1.223:7000.

Sometimes I see the initial connection, but nothing else until I disconnect (no errors):

shairport-sync -vu --statistics
         0.000730630 "shairport.c:1892" Started in Airplay 2 mode with features 0x405c4a00,0x1c340 on device "dc:a6:32:a3:9c:1b"!
         0.000139611 "shairport.c:1934" software version: "4.1-dev-174-g8bd31c14-AirPlay2-alac-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
         0.000021370 "shairport.c:1940" log verbosity is 1.
         0.000048037 "audio_alsa.c:1018" alsa: alsa_maximum_stall_time of 0.200000 sec.
         0.000039741 "audio_alsa.c:1310" alsa: disable_standby_mode is "never".
         0.000017167 "audio_alsa.c:1312" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
         0.000015259 "audio_alsa.c:1314" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
         0.000021259 "audio_alsa.c:1353" alsa: output device name is "hw:1".
         0.000219037 "shairport.c:1969" libsodium initialised.
         0.000034334 "shairport.c:2019" disable resend requests is off.
         0.000017148 "shairport.c:2023" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000016592 "shairport.c:2024" statistics_requester status is 1.
         0.000014334 "shairport.c:2029" rtsp listening port is 7000.
         0.000016018 "shairport.c:2030" udp base port is 6001.
         0.000015241 "shairport.c:2031" udp port range is 10.
         0.000013926 "shairport.c:2032" player name is "Raspberrypi".
         0.000013926 "shairport.c:2033" backend is "alsa".
         0.000013907 "shairport.c:2034" run_this_before_play_begins action is "(null)".
         0.000014204 "shairport.c:2035" run_this_after_play_ends action is "(null)".
         0.000014092 "shairport.c:2036" wait-cmd status is 0.
         0.000015130 "shairport.c:2037" run_this_before_play_begins may return output is 0.
         0.000014407 "shairport.c:2039" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000014130 "shairport.c:2041" run_this_before_entering_active_state action is  "(null)".
         0.000013963 "shairport.c:2043" run_this_after_exiting_active_state action is  "(null)".
         0.000014037 "shairport.c:2044" active_state_timeout is  10.000000 seconds.
         0.000017852 "shairport.c:2045" mdns backend "(null)".
         0.000015463 "shairport.c:2050" interpolation setting is "auto".
         0.000015426 "shairport.c:2051" interpolation soxr_delay_threshold is 30.
         0.000014129 "shairport.c:2052" resync time is 0.050000 seconds.
         0.000014482 "shairport.c:2053" allow a session to be interrupted: 0.
         0.000013593 "shairport.c:2054" busy timeout time is 0.
         0.000013703 "shairport.c:2055" drift tolerance is 0.001995 seconds.
         0.000014389 "shairport.c:2056" password is "(null)".
         0.000013519 "shairport.c:2057" ignore_volume_control is 0.
         0.000015259 "shairport.c:2061" volume_max_db is not set
         0.000015981 "shairport.c:2063" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000016408 "shairport.c:2067" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000014944 "shairport.c:2069" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000014556 "shairport.c:2070" disable_synchronization is 0.
         0.000013759 "shairport.c:2071" use_mmap_if_available is 1.
         0.000014333 "shairport.c:2073" output_format automatic selection is enabled.
         0.000014445 "shairport.c:2077" output_rate automatic selection is enabled.
         0.000016907 "shairport.c:2081" audio backend desired buffer length is 0.200000 seconds.
         0.000016574 "shairport.c:2083" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
         0.000015278 "shairport.c:2084" audio backend latency offset is 0.000000 seconds.
         0.000015056 "shairport.c:2086" audio backend silence lead-in time is "auto".
         0.000013740 "shairport.c:2090" zeroconf regtype is "_raop._tcp".
         0.000014000 "shairport.c:2091" decoders_supported field is 3.
         0.000013723 "shairport.c:2092" use_apple_decoder is 1.
         0.000015296 "shairport.c:2093" alsa_use_hardware_mute is 0.
         0.000015370 "shairport.c:2097" no special mdns service interface was requested.
         0.000033408 "shairport.c:2101" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000017055 "shairport.c:2130" loudness is 0.
         0.000013741 "shairport.c:2131" loudness reference level is -20.000000
         1.501978462 "shairport.c:224" "soxr" interpolation has been chosen.
         2.752021795 "rtsp.c:2646" Connection 1: AP2 PTP connection from 192.168.1.112:56795 to self at 192.168.1.223:7000.
        38.323951292 "rtsp.c:2668" Connection 2: Remote Control connection from 192.168.1.112:56799 to self at 192.168.1.223:7000.

Thanks.

mikebrady commented 2 years ago

Thanks for the post. It does look like a separate issue alright. I edited your message for format. It's quite puzzling, because both SoundCloud on iOS uses a Realtime stream, not a Buffered Audio stream as in your logs. Here are examples from my system just now.

Source: SoundCloud on iOS.

        79.316401205 "rtsp.c:2644" Connection 1: AP2 PTP connection from 192.168.5.248:53237 to self at 192.168.5.53:7000.
        14.386785340 "rtsp.c:2976" Connection 1. AP2 Realtime Audio Stream.
         0.008242667 "audio_alsa.c:528" alsa: output format chosen is "S32".
         0.000041375 "audio_alsa.c:571" alsa: output speed chosen is 44100.
         0.085275208 "rtp.c:1216" Connection 1: Set Anchor Clock: 90e17b32a58b0008.
         0.001487125 "rtp.c:1322" Connection 1: Clock 90e17b32a58b0008 is now the new anchor clock and master clock. History: 14120.417048 milliseconds.
         0.000017750 "rtp.c:1407" Connection 1: NQPTP new master clock 90e17b32a58b0008.
         7.854345920 "player.c:2641" Large negative sync error of: -2340 frames (-0.053061 seconds), with frame: 71325351.
         1.986266210 "player.c:2460" sync error ms net sync ppm all sync ppm     packets missing   late too late resend reqs min DAC queue min buffers max buffers received fps output fps (r) output fps (c)
         8.005294921 "player.c:2460"         -1.85         34.0         34.0        9027       0    351        0          39          7694         208         232     44107.36       N/A.                N/A
         8.005100212 "player.c:2460"         -1.48          0.0          0.0       10030       0    368        0          39          7635         210         232     44104.15       44092.47       44093.33
         8.004806879 "player.c:2460"         -1.30          0.0          0.0       11033       0    388        0          39          7703         209         232     44106.04       44093.36       44094.18
         8.005008754 "player.c:2460"         -1.12          0.0          0.0       12036       0    396        0          40          7701         211         232     44103.08       44094.00       44094.78

Spotify on iOS:

        27.835662763 "rtsp.c:2976" Connection 1. AP2 Realtime Audio Stream.
         0.001931625 "audio_alsa.c:528" alsa: output format chosen is "S32".
         0.000024333 "audio_alsa.c:571" alsa: output speed chosen is 44100.
         0.050042000 "rtp.c:1429" Connection 1: No Clock Anchor.
         0.022079792 "rtp.c:1407" Connection 1: NQPTP new master clock 90e17b32a58b0008.
         9.861896005 "player.c:2460" sync error ms net sync ppm all sync ppm     packets missing   late too late resend reqs min DAC queue min buffers max buffers received fps output fps (r) output fps (c)
         0.000063750 "player.c:2460"        -22.91       1001.3       1001.3        1003       0     16        0           0          6680         208         232     44109.45            N/A            N/A
         8.005238337 "player.c:2460"        -44.22       2840.9       2840.9        2006       0     20        0           0          6336         192         231     44097.99       44159.81       44158.85
         8.019034420 "player.c:2460"        -16.30       2430.2       2430.2        3009       0     56        0           1          6971         168         232     44094.74       44092.41       44091.44
         8.005967338 "player.c:2460"          3.24      -1940.2       1940.2        4012       0     86        0           1          7678         208         233     44097.78       44060.68       44059.70
         8.008574045 "player.c:2460"          2.93      -1373.7       1373.7        5015       0    107        0           1          7678         210         233     44102.16       44057.71       44056.72
         7.998392921 "player.c:2460"          1.85       -153.0        153.0        6018       0    130        0           1          7700         210         233     44097.94       44067.15       44066.15

(The timings are very poor because Shairport Sync is running here in a virtual machine.)

The "No Clock Anchor" in this example is harmless -- it simply means that SPS is waiting for clock information which arrives 22 milliseconds later.

So, overall, the mystery is to try to determine why you are not seeing Realtime streams. Is it correct that you are sending from an iOS device, or is it something else?

handcc commented 2 years ago

Yes, I am streaming from an iPhone XR running iOS 15.2.1.

handcc commented 2 years ago

I upgraded to iOS 15.3 and everything appears to be working now. Perhaps an iOS bug. I'll wait a day or 2 before closing this to be sure, but so far so good.