search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.13k stars 565 forks source link

No audio bug (fixed) + feature suggestion - set custom latency offsets for each type of stream #1404

Closed Gabi10017 closed 2 years ago

Gabi10017 commented 2 years ago

I am experiencing an issue with the latest dev build of shairport-sync (issue occurs while using airplay 2). If I play some music and then pause it for a little while (1-2 minutes) when I press play again, there is no sound. I would also like to add that this issue is present only on the apps that use REALTIME (eg. Spotify). I initially thought that the issue might lie in my configuration but I was wrong, as the unmodified config has the exact same issue. I can help with logs if you'll help me get them (I am a novice user). The only way to get the sound back is to restart the service.

mikebrady commented 2 years ago

Thanks for the report. This is not something I have encountered, but let me check to see if I can reproduce it.

handcc commented 2 years ago

I was about to report a bug with Soundcloud not working. After reading this post, Spotify also has the same no sound issue. Apple music works fine. My issue might be different though, because I never get any sound out of Soundcloud or Spotify even after i restart shairport-sync, but I can switch back to Apple Music and no problems. 

$ shairport-sync -vu --statistics
         0.000740444 "shairport.c:1892" Started in Airplay 2 mode with features 0x405c4a00,0x1c340 on device "dc:a6:32:a3:9c:1b"!
         0.000139871 "shairport.c:1934" software version: "4.1-dev-165-gb566d641-AirPlay2-alac-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
         0.000020333 "shairport.c:1940" log verbosity is 1.
         0.000043741 "audio_alsa.c:1018" alsa: alsa_maximum_stall_time of 0.200000 sec.
         0.000037574 "audio_alsa.c:1305" alsa: disable_standby_mode is "never".
         0.000045148 "audio_alsa.c:1307" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
         0.000042537 "audio_alsa.c:1309" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
         0.000048315 "audio_alsa.c:1348" alsa: output device name is "hw:CARD=XMC1,DEV=0".
         0.000240166 "shairport.c:1969" libsodium initialised.
         0.000062315 "shairport.c:2019" disable resend requests is off.
         0.000045259 "shairport.c:2023" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000042241 "shairport.c:2024" statistics_requester status is 1.
         0.000040315 "shairport.c:2029" rtsp listening port is 7000.
         0.000039667 "shairport.c:2030" udp base port is 6001.
         0.000039444 "shairport.c:2031" udp port range is 10.
         0.000038963 "shairport.c:2032" player name is "Raspberrypi".
         0.000039704 "shairport.c:2033" backend is "alsa".
         0.000038963 "shairport.c:2034" run_this_before_play_begins action is "(null)".
         0.000039315 "shairport.c:2035" run_this_after_play_ends action is "(null)".
         0.000039388 "shairport.c:2036" wait-cmd status is 0.
         0.000039334 "shairport.c:2037" run_this_before_play_begins may return output is 0.
         0.000039592 "shairport.c:2039" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000042686 "shairport.c:2041" run_this_before_entering_active_state action is  "(null)".
         0.000039666 "shairport.c:2043" run_this_after_exiting_active_state action is  "(null)".
         0.000039704 "shairport.c:2044" active_state_timeout is  10.000000 seconds.
         0.000064185 "shairport.c:2045" mdns backend "(null)".
         0.000045093 "shairport.c:2050" interpolation setting is "auto".
         0.000033889 "shairport.c:2051" interpolation soxr_delay_threshold is 30.
         0.000015518 "shairport.c:2052" resync time is 0.050000 seconds.
         0.000014704 "shairport.c:2053" allow a session to be interrupted: 0.
         0.000025426 "shairport.c:2054" busy timeout time is 0.
         0.000015296 "shairport.c:2055" drift tolerance is 0.001995 seconds.
         0.000014556 "shairport.c:2056" password is "(null)".
         0.000013426 "shairport.c:2057" ignore_volume_control is 1.
         0.000015185 "shairport.c:2061" volume_max_db is not set
         0.000013796 "shairport.c:2063" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000014407 "shairport.c:2067" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000014649 "shairport.c:2069" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000014574 "shairport.c:2070" disable_synchronization is 0.
         0.000013666 "shairport.c:2071" use_mmap_if_available is 1.
         0.000013519 "shairport.c:2073" output_format automatic selection is enabled.
         0.000014111 "shairport.c:2077" output_rate automatic selection is enabled.
         0.000014185 "shairport.c:2081" audio backend desired buffer length is 0.200000 seconds.
         0.000014778 "shairport.c:2083" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
         0.000028796 "shairport.c:2084" audio backend latency offset is 0.000000 seconds.
         0.000016519 "shairport.c:2086" audio backend silence lead-in time is "auto".
         0.000013815 "shairport.c:2090" zeroconf regtype is "_raop._tcp".
         0.000014000 "shairport.c:2091" decoders_supported field is 3.
         0.000013611 "shairport.c:2092" use_apple_decoder is 1.
         0.000013537 "shairport.c:2093" alsa_use_hardware_mute is 0.
         0.000013629 "shairport.c:2097" no special mdns service interface was requested.
         0.000034000 "shairport.c:2101" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000017297 "shairport.c:2130" loudness is 0.
         0.000013759 "shairport.c:2131" loudness reference level is -20.000000
         0.000828667 "rtsp.c:5067" unable to listen on IPv4 port 7000. The error is: "Address already in use".
         0.000092703 "rtsp.c:5067" unable to listen on IPv6 port 7000. The error is: "Address already in use".
         0.000026074 "rtsp.c:5214" *warning: could not establish a service on port 7000 -- program terminating. Is another instance of Shairport Sync running on this device?
         0.000017704 "rtsp.c:5216" Oops -- fell out of the RTSP select loop
         1.499280795 "shairport.c:224" "soxr" interpolation has been chosen.
         0.000226889 "shairport.c:1561" exit_function exit
Gabi10017 commented 2 years ago

I was about to report a bug with Soundcloud not working. After reading this post, Spotify also has the same no sound issue. Apple music works fine. My issue might be different though, because I never get any sound out of Soundcloud or Spotify even after i restart shairport-sync, but I can switch back to Apple Music and no problems.

$ shairport-sync -vu --statistics 0.000740444 "shairport.c:1892" Started in Airplay 2 mode with features 0x405c4a00,0x1c340 on device "dc:a6:32:a3:9c:1b"! 0.000139871 "shairport.c:1934" software version: "4.1-dev-165-gb566d641-AirPlay2-alac-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc" 0.000020333 "shairport.c:1940" log verbosity is 1. 0.000043741 "audio_alsa.c:1018" alsa: alsa_maximum_stall_time of 0.200000 sec. 0.000037574 "audio_alsa.c:1305" alsa: disable_standby_mode is "never". 0.000045148 "audio_alsa.c:1307" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds. 0.000042537 "audio_alsa.c:1309" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds. 0.000048315 "audio_alsa.c:1348" alsa: output device name is "hw:CARD=XMC1,DEV=0". 0.000240166 "shairport.c:1969" libsodium initialised. 0.000062315 "shairport.c:2019" disable resend requests is off. 0.000045259 "shairport.c:2023" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately. 0.000042241 "shairport.c:2024" statistics_requester status is 1. 0.000040315 "shairport.c:2029" rtsp listening port is 7000. 0.000039667 "shairport.c:2030" udp base port is 6001. 0.000039444 "shairport.c:2031" udp port range is 10. 0.000038963 "shairport.c:2032" player name is "Raspberrypi". 0.000039704 "shairport.c:2033" backend is "alsa". 0.000038963 "shairport.c:2034" run_this_before_play_begins action is "(null)". 0.000039315 "shairport.c:2035" run_this_after_play_ends action is "(null)". 0.000039388 "shairport.c:2036" wait-cmd status is 0. 0.000039334 "shairport.c:2037" run_this_before_play_begins may return output is 0. 0.000039592 "shairport.c:2039" run_this_if_an_unfixable_error_is_detected action is "(null)". 0.000042686 "shairport.c:2041" run_this_before_entering_active_state action is "(null)". 0.000039666 "shairport.c:2043" run_this_after_exiting_active_state action is "(null)". 0.000039704 "shairport.c:2044" active_state_timeout is 10.000000 seconds. 0.000064185 "shairport.c:2045" mdns backend "(null)". 0.000045093 "shairport.c:2050" interpolation setting is "auto". 0.000033889 "shairport.c:2051" interpolation soxr_delay_threshold is 30. 0.000015518 "shairport.c:2052" resync time is 0.050000 seconds. 0.000014704 "shairport.c:2053" allow a session to be interrupted: 0. 0.000025426 "shairport.c:2054" busy timeout time is 0. 0.000015296 "shairport.c:2055" drift tolerance is 0.001995 seconds. 0.000014556 "shairport.c:2056" password is "(null)". 0.000013426 "shairport.c:2057" ignore_volume_control is 1. 0.000015185 "shairport.c:2061" volume_max_db is not set 0.000013796 "shairport.c:2063" volume range in dB (zero means use the range specified by the mixer): 0. 0.000014407 "shairport.c:2067" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0. 0.000014649 "shairport.c:2069" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right). 0.000014574 "shairport.c:2070" disable_synchronization is 0. 0.000013666 "shairport.c:2071" use_mmap_if_available is 1. 0.000013519 "shairport.c:2073" output_format automatic selection is enabled. 0.000014111 "shairport.c:2077" output_rate automatic selection is enabled. 0.000014185 "shairport.c:2081" audio backend desired buffer length is 0.200000 seconds. 0.000014778 "shairport.c:2083" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds. 0.000028796 "shairport.c:2084" audio backend latency offset is 0.000000 seconds. 0.000016519 "shairport.c:2086" audio backend silence lead-in time is "auto". 0.000013815 "shairport.c:2090" zeroconf regtype is "_raop._tcp". 0.000014000 "shairport.c:2091" decoders_supported field is 3. 0.000013611 "shairport.c:2092" use_apple_decoder is 1. 0.000013537 "shairport.c:2093" alsa_use_hardware_mute is 0. 0.000013629 "shairport.c:2097" no special mdns service interface was requested. 0.000034000 "shairport.c:2101" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf". 0.000017297 "shairport.c:2130" loudness is 0. 0.000013759 "shairport.c:2131" loudness reference level is -20.000000 0.000828667 "rtsp.c:5067" unable to listen on IPv4 port 7000. The error is: "Address already in use". 0.000092703 "rtsp.c:5067" unable to listen on IPv6 port 7000. The error is: "Address already in use". 0.000026074 "rtsp.c:5214" *warning: could not establish a service on port 7000 -- program terminating. Is another instance of Shairport Sync running on this device? 0.000017704 "rtsp.c:5216" Oops -- fell out of the RTSP select loop 1.499280795 "shairport.c:224" "soxr" interpolation has been chosen. 0.000226889 "shairport.c:1561" exit_function exit

yeah.. apple music uses the BUFFERED mode that’s why it is not affected by this. Soundcloud and Spotify are using REALTIME (they stream directly from the source device, rather than from a server, like apple music).

mikebrady commented 2 years ago

Thanks for this report. It may take a few days to get to it, due to other IRL commitments.

Gabi10017 commented 2 years ago

Thanks for this report. It may take a few days to get to it, due to other IRL commitments.

Take your time. It's not a major issue.

mikebrady commented 2 years ago

Thanks for your reports. So, I just tried this with an installation running on a VM and it seemed to behave properly for me both with Spotify and SoundCloud -- both on an iPhone. Would it be possible for you to post your configuration settings please?

Running 4.1-dev-168-g18f45202 with everything else up to date.

And, does this definitely only happen with Realtime streams? Does it definitely not happen, in your experience, with Buffered streams?

Gabi10017 commented 2 years ago

Attached my config below. I am sure that it's only for Realtime, because playing back and forth Spotify and Apple Music right after I had the issue showed that Apple Music worked normally while Spotify played with no sound. The sender was also an iPhone in my case.

Running 4.1-dev-166-g55c111c with everything else up to date.

shairport-sync.conf.txt

Gabi10017 commented 2 years ago

$ shairport-sync -vu --statistics

     0.001526875 "shairport.c:1340" default metadata_pipename is "/tmp/shairport-sync-metadata".
     0.000093625 "shairport.c:1892" Started in Airplay 2 mode with features 0x405fca00,0x1c340 on device "d6:2b:98:e2:34:44"!
     0.000074375 "shairport.c:1934" software version: "4.1-dev-166-g55c111ca-AirPlay2-alac-OpenSSL-Avahi-pa-soxr-metadata-sysconfdir:/usr/local/etc"
     0.000013417 "shairport.c:1940" log verbosity is 1.
     0.000018375 "audio.c:149" The setting general.audio_backend_buffer_desired_length is deprecated. Use general.audio_backend_buffer_desired_length_in_seconds instead.
     0.002210542 "shairport.c:1969" libsodium initialised.
     0.000040250 "shairport.c:2019" disable resend requests is off.
     0.000014583 "shairport.c:2023" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
     0.000013417 "shairport.c:2024" statistics_requester status is 1.
     0.000011958 "shairport.c:2029" rtsp listening port is 7000.
     0.000010500 "shairport.c:2030" udp base port is 6001.
     0.000009333 "shairport.c:2031" udp port range is 10.
     0.000008750 "shairport.c:2032" player name is "Living Audio System".
     0.000010792 "shairport.c:2033" backend is "pa".
     0.000009333 "shairport.c:2034" run_this_before_play_begins action is "(null)".
     0.000009917 "shairport.c:2035" run_this_after_play_ends action is "(null)".
     0.000009333 "shairport.c:2036" wait-cmd status is 0.
     0.000008459 "shairport.c:2037" run_this_before_play_begins may return output is 0.
     0.000009333 "shairport.c:2039" run_this_if_an_unfixable_error_is_detected action is "(null)".
     0.000009333 "shairport.c:2041" run_this_before_entering_active_state action is  "(null)".
     0.000009042 "shairport.c:2043" run_this_after_exiting_active_state action is  "(null)".
     0.000009042 "shairport.c:2044" active_state_timeout is  10.000000 seconds.
     0.000010791 "shairport.c:2045" mdns backend "(null)".
     0.000009625 "shairport.c:2050" interpolation setting is "auto".
     0.000009042 "shairport.c:2051" interpolation soxr_delay_threshold is 30.
     0.000009042 "shairport.c:2052" resync time is 0.050000 seconds.
     0.000009625 "shairport.c:2053" allow a session to be interrupted: 0.
     0.000009041 "shairport.c:2054" busy timeout time is 0.
     0.000008750 "shairport.c:2055" drift tolerance is 0.001995 seconds.
     0.000009042 "shairport.c:2056" password is "(null)".
     0.000008458 "shairport.c:2057" ignore_volume_control is 0.
     0.000008750 "shairport.c:2061" volume_max_db is not set
     0.000008167 "shairport.c:2063" volume range in dB (zero means use the range specified by the mixer): 40.
     0.000009333 "shairport.c:2067" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
     0.000009917 "shairport.c:2069" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
     0.000009625 "shairport.c:2070" disable_synchronization is 0.
     0.000008750 "shairport.c:2071" use_mmap_if_available is 1.
     0.000009042 "shairport.c:2073" output_format automatic selection is enabled.
     0.000009041 "shairport.c:2077" output_rate automatic selection is enabled.
     0.000009042 "shairport.c:2081" audio backend desired buffer length is 1.100000 seconds.
     0.000009625 "shairport.c:2083" audio_backend_buffer_interpolation_threshold_in_seconds is 0.100000 seconds.
     0.000010208 "shairport.c:2084" audio backend latency offset is -1.750000 seconds.
     0.000009625 "shairport.c:2086" audio backend silence lead-in time is "auto".
     0.000009042 "shairport.c:2090" zeroconf regtype is "_raop._tcp".
     0.000008750 "shairport.c:2091" decoders_supported field is 3.
     0.000009333 "shairport.c:2092" use_apple_decoder is 1.
     0.000008459 "shairport.c:2093" alsa_use_hardware_mute is 0.
     0.000011375 "shairport.c:2097" no special mdns service interface was requested.
     0.000031208 "shairport.c:2101" configuration file name "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
     0.000014000 "shairport.c:2107" metadata enabled is 1.
     0.000009917 "shairport.c:2108" metadata pipename is "/tmp/shairport-sync-metadata".
     0.000009333 "shairport.c:2110" metadata socket address is "(null)" port 0.
     0.000009625 "shairport.c:2111" metadata socket packet size is "500".
     0.000009042 "shairport.c:2112" get-coverart is 1.
     0.000008458 "shairport.c:2130" loudness is 0.
     0.000008167 "shairport.c:2131" loudness reference level is -20.000000
     0.000135041 "rtsp.c:3823" metadata pipe name is "/tmp/shairport-sync-metadata".
     0.000956084 "rtsp.c:5067" unable to listen on IPv4 port 7000. The error is: "Address already in use".
     0.000285541 "rtsp.c:5067" unable to listen on IPv6 port 7000. The error is: "Address already in use".
     0.000157209 "rtsp.c:5214" *warning: could not establish a service on port 7000 -- program terminating. Is another instance of Shairport Sync running on this device?
     0.000269208 "rtsp.c:5216" Oops -- fell out of the RTSP select loop
     1.498847001 "shairport.c:224" "soxr" interpolation has been chosen.
     0.000221667 "shairport.c:1561" exit_function exit

Here are my logs.

L.E: Seems like a temporary fix would also be simply disconnecting and then reconnecting to the receiver.

mikebrady commented 2 years ago

Thanks. It looks like you are using the PulseAudio (pa) back end?

Gabi10017 commented 2 years ago

Thanks. It looks like you are using the PulseAudio (pa) back end?

Yes.

mikebrady commented 2 years ago

Thanks @Gabi10017 for the settings. There a number of features that need some discussion. They may not have any bearing on the problem, but here goes with the first one:

The log you have given is from an instance of Shairport Sync running from the command line. However, the log indicates that there is another instance of Shairport Sync running already. The following log entries suggest that the other instance already has control of port 7000:

     0.000956084 "rtsp.c:5067" unable to listen on IPv4 port 7000. The error is: "Address already in use".
     0.000285541 "rtsp.c:5067" unable to listen on IPv6 port 7000. The error is: "Address already in use".

You can see from the log that the instance your started from the command line then terminates:

0.000221667 "shairport.c:1561" exit_function exit

I am guessing that instance already running is the service that is started automatically when the machine boots up by the startup scripts you installed at the make install stage. Can I ask you if I have guessed right?

Gabi10017 commented 2 years ago

Thanks @Gabi10017 for the settings. There a number of features that need some discussion. They may not have any bearing on the problem, but here goes with the first one:

The log you have given is from an instance of Shairport Sync running from the command line. However, the log indicates that there is another instance of Shairport Sync running already. The following log entries suggest that the other instance already has control of port 7000:


     0.000956084 "rtsp.c:5067" unable to listen on IPv4 port 7000. The error is: "Address already in use".

     0.000285541 "rtsp.c:5067" unable to listen on IPv6 port 7000. The error is: "Address already in use".

You can see from the log that the instance your started from the command line then terminates:


0.000221667 "shairport.c:1561" exit_function exit

I am guessing that instance already running is the service that is started automatically when the machine boots up by the startup scripts you installed at the make install stage. Can I ask you if I have guessed right?

I honestly don't know.. A restart should fix this right? It should only start the daemon once.

Gabi10017 commented 2 years ago

After a reboot:

     0.001503542 "shairport.c:1340" default metadata_pipename is "/tmp/shairport-sync-metadata".
     0.000262791 "shairport.c:1892" Started in Airplay 2 mode with features 0x405fca00,0x1c340 on device "76:24:2b:f0:c1:f4"!
     0.000150209 "shairport.c:1934" software version: "4.1-dev-166-g55c111ca-AirPlay2-alac-OpenSSL-Avahi-pa-soxr-metadata-sysconfdir:/usr/local/etc"
     0.000019250 "shairport.c:1940" log verbosity is 1.
     0.000131833 "audio.c:149" The setting general.audio_backend_buffer_desired_length is deprecated. Use general.audio_backend_buffer_desired_length_in_seconds instead.
     0.002094750 "shairport.c:1969" libsodium initialised.
     0.000036750 "shairport.c:2019" disable resend requests is off.
     0.000148750 "shairport.c:2023" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
     0.000074083 "shairport.c:2024" statistics_requester status is 1.
     0.000074667 "shairport.c:2029" rtsp listening port is 7000.
     0.000069125 "shairport.c:2030" udp base port is 6001.
     0.000067958 "shairport.c:2031" udp port range is 10.
     0.000137959 "shairport.c:2032" player name is "Living Audio System".
     0.000074958 "shairport.c:2033" backend is "pa".
     0.000069417 "shairport.c:2034" run_this_before_play_begins action is "(null)".
     0.000068250 "shairport.c:2035" run_this_after_play_ends action is "(null)".
     0.000068541 "shairport.c:2036" wait-cmd status is 0.
     0.000067084 "shairport.c:2037" run_this_before_play_begins may return output is 0.
     0.000068833 "shairport.c:2039" run_this_if_an_unfixable_error_is_detected action is "(null)".
     0.000097125 "shairport.c:2041" run_this_before_entering_active_state action is  "(null)".
     0.000076708 "shairport.c:2043" run_this_after_exiting_active_state action is  "(null)".
     0.000070584 "shairport.c:2044" active_state_timeout is  10.000000 seconds.
     0.000072041 "shairport.c:2045" mdns backend "(null)".
     0.000068834 "shairport.c:2050" interpolation setting is "auto".
     0.000009916 "shairport.c:2051" interpolation soxr_delay_threshold is 30.
     0.000007875 "shairport.c:2052" resync time is 0.050000 seconds.
     0.000008459 "shairport.c:2053" allow a session to be interrupted: 0.
     0.000007875 "shairport.c:2054" busy timeout time is 0.
     0.000007291 "shairport.c:2055" drift tolerance is 0.001995 seconds.
     0.000007875 "shairport.c:2056" password is "(null)".
     0.000087792 "shairport.c:2057" ignore_volume_control is 0.
     0.000067958 "shairport.c:2061" volume_max_db is not set
     0.000067667 "shairport.c:2063" volume range in dB (zero means use the range specified by the mixer): 38.
     0.000069125 "shairport.c:2067" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
     0.000071750 "shairport.c:2069" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
     0.000072625 "shairport.c:2070" disable_synchronization is 0.
     0.000071750 "shairport.c:2071" use_mmap_if_available is 1.
     0.000098000 "shairport.c:2073" output_format automatic selection is enabled.
     0.000071750 "shairport.c:2077" output_rate automatic selection is enabled.
     0.000068833 "shairport.c:2081" audio backend desired buffer length is 0.450000 seconds.
     0.000070000 "shairport.c:2083" audio_backend_buffer_interpolation_threshold_in_seconds is 0.100000 seconds.
     0.000071167 "shairport.c:2084" audio backend latency offset is -1.750000 seconds.
     0.000072917 "shairport.c:2086" audio backend silence lead-in time is "auto".
     0.000068541 "shairport.c:2090" zeroconf regtype is "_raop._tcp".
     0.000074667 "shairport.c:2091" decoders_supported field is 3.
     0.000069125 "shairport.c:2092" use_apple_decoder is 1.
     0.000067667 "shairport.c:2093" alsa_use_hardware_mute is 0.
     0.000067666 "shairport.c:2097" no special mdns service interface was requested.
     0.000153709 "shairport.c:2101" configuration file name "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
     0.000018666 "shairport.c:2107" metadata enabled is 1.
     0.000071167 "shairport.c:2108" metadata pipename is "/tmp/shairport-sync-metadata".
     0.000068833 "shairport.c:2110" metadata socket address is "(null)" port 0.
     0.000069125 "shairport.c:2111" metadata socket packet size is "500".
     0.000068542 "shairport.c:2112" get-coverart is 1.
     0.000067958 "shairport.c:2130" loudness is 0.
     0.000066792 "shairport.c:2131" loudness reference level is -20.000000
     0.000248792 "rtsp.c:3823" metadata pipe name is "/tmp/shairport-sync-metadata".
     0.000765625 "rtsp.c:5067" unable to listen on IPv4 port 7000. The error is: "Address already in use".
     0.000074666 "rtsp.c:5067" unable to listen on IPv6 port 7000. The error is: "Address already in use".
     0.000027125 "rtsp.c:5214" *warning: could not establish a service on port 7000 -- program terminating. Is another instance of Shairport Sync running on this device?
     0.000013709 "rtsp.c:5216" Oops -- fell out of the RTSP select loop
     1.500531375 "shairport.c:224" "soxr" interpolation has been chosen.
     0.000292834 "shairport.c:1561" exit_function exit

Seems like somehow it's still running twice?

handcc commented 2 years ago

That's because the daemon starts at boot and then is already running when you run the command. If you sudo systemctl stop shairport-sync and then run shairport-sync -vu --statistics you shouldn't see those messages.

I notice we are both running in Airplay2 mode with alac, which is not the default config. Maybe that will help @mikebrady .

Sorry to barge into your issue again. Let me know if I can help troubleshoot.

Gabi10017 commented 2 years ago

That's because the daemon starts at boot and then is already running when you run the command. If you sudo systemctl stop shairport-sync and then run shairport-sync -vu --statistics you shouldn't see those messages.

I notice we are both running in Airplay2 mode with alac, which is not the default config. Maybe that will help @mikebrady .

Sorry to barge into your issue again. Let me know if I can help troubleshoot.

You're right. I no longer see those last lines, and yes, I use alac too (might be relevant for @mikebrady in finding the cause of the issue)

It's alright, you can comment here whenever you want as long as you're helping in fixing the issue đŸ˜€

Gabi10017 commented 2 years ago

$ shairport-sync -vu --statistics

librga:RGA_GET_VERSION:2.00,2.000000
ctx=0x81472b90,ctx->rgaFd=3
Rga built version:version:+2017-09-28 10:12:42
         0.001473500 "shairport.c:1340" default metadata_pipename is "/tmp/shair                                                                                                                                                             port-sync-metadata".
         0.000258417 "shairport.c:1892" Started in Airplay 2 mode with features                                                                                                                                                              0x405fca00,0x1c340 on device "2a:8b:b4:4e:f5:4f"!
         0.000152833 "shairport.c:1934" software version: "4.1-dev-166-g55c111ca                                                                                                                                                             -AirPlay2-alac-OpenSSL-Avahi-pa-soxr-metadata-sysconfdir:/usr/local/etc"
         0.000019250 "shairport.c:1940" log verbosity is 1.
         0.000132708 "audio.c:149" The setting general.audio_backend_buffer_desi                                                                                                                                                             red_length is deprecated. Use general.audio_backend_buffer_desired_length_in_sec                                                                                                                                                             onds instead.
         0.002314084 "shairport.c:1969" libsodium initialised.
         0.000037333 "shairport.c:2019" disable resend requests is off.
         0.000202417 "shairport.c:2023" diagnostic_drop_packet_fraction is 0.000                                                                                                                                                             000. A value of 0.0 means no packets will be dropped deliberately.
         0.000020708 "shairport.c:2024" statistics_requester status is 1.
         0.000074375 "shairport.c:2029" rtsp listening port is 7000.
         0.000068833 "shairport.c:2030" udp base port is 6001.
         0.000069125 "shairport.c:2031" udp port range is 10.
         0.000134167 "shairport.c:2032" player name is "Living Audio System".
         0.000076417 "shairport.c:2033" backend is "pa".
         0.000070000 "shairport.c:2034" run_this_before_play_begins action is "(                                                                                                                                                             null)".
         0.000068833 "shairport.c:2035" run_this_after_play_ends action is "(nul                                                                                                                                                             l)".
         0.000069125 "shairport.c:2036" wait-cmd status is 0.
         0.000068250 "shairport.c:2037" run_this_before_play_begins may return o                                                                                                                                                             utput is 0.
         0.000067958 "shairport.c:2039" run_this_if_an_unfixable_error_is_detect                                                                                                                                                             ed action is "(null)".
         0.000069125 "shairport.c:2041" run_this_before_entering_active_state ac                                                                                                                                                             tion is  "(null)".
         0.000070584 "shairport.c:2043" run_this_after_exiting_active_state acti                                                                                                                                                             on is  "(null)".
         0.000084875 "shairport.c:2044" active_state_timeout is  10.000000 secon                                                                                                                                                             ds.
         0.000075541 "shairport.c:2045" mdns backend "(null)".
         0.000068542 "shairport.c:2050" interpolation setting is "auto".
         0.000068250 "shairport.c:2051" interpolation soxr_delay_threshold is 30                                                                                                                                                             .
         0.000068250 "shairport.c:2052" resync time is 0.050000 seconds.
         0.000069417 "shairport.c:2053" allow a session to be interrupted: 0.
         0.000097125 "shairport.c:2054" busy timeout time is 0.
         0.000071166 "shairport.c:2055" drift tolerance is 0.001995 seconds.
         0.000080500 "shairport.c:2056" password is "(null)".
         0.000067667 "shairport.c:2057" ignore_volume_control is 0.
         0.000068542 "shairport.c:2061" volume_max_db is not set
         0.000069125 "shairport.c:2063" volume range in dB (zero means use the r                                                                                                                                                             ange specified by the mixer): 38.
         0.000072625 "shairport.c:2067" volume_range_combined_hardware_priority                                                                                                                                                              (1 means hardware mixer attenuation is used first) is 0.
         0.000072041 "shairport.c:2069" playback_mode is 0 (0-stereo, 1-mono, 1-                                                                                                                                                             reverse_stereo, 2-both_left, 3-both_right).
         0.000072334 "shairport.c:2070" disable_synchronization is 0.
         0.000070875 "shairport.c:2071" use_mmap_if_available is 1.
         0.000068250 "shairport.c:2073" output_format automatic selection is ena                                                                                                                                                             bled.
         0.000068250 "shairport.c:2077" output_rate automatic selection is enabl                                                                                                                                                             ed.
         0.000068833 "shairport.c:2081" audio backend desired buffer length is 0                                                                                                                                                             .450000 seconds.
         0.000070000 "shairport.c:2083" audio_backend_buffer_interpolation_thres                                                                                                                                                             hold_in_seconds is 0.100000 seconds.
         0.000071458 "shairport.c:2084" audio backend latency offset is -1.75000                                                                                                                                                             0 seconds.
         0.000071750 "shairport.c:2086" audio backend silence lead-in time is "a                                                                                                                                                             uto".
         0.000096834 "shairport.c:2090" zeroconf regtype is "_raop._tcp".
         0.000072333 "shairport.c:2091" decoders_supported field is 3.
         0.000072917 "shairport.c:2092" use_apple_decoder is 1.
         0.000067666 "shairport.c:2093" alsa_use_hardware_mute is 0.
         0.000067959 "shairport.c:2097" no special mdns service interface was re                                                                                                                                                             quested.
         0.000144666 "shairport.c:2101" configuration file name "/usr/local/etc/                                                                                                                                                             shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
         0.000017792 "shairport.c:2107" metadata enabled is 1.
         0.000095958 "shairport.c:2108" metadata pipename is "/tmp/shairport-syn                                                                                                                                                             c-metadata".
         0.000072625 "shairport.c:2110" metadata socket address is "(null)" port                                                                                                                                                              0.
         0.000069417 "shairport.c:2111" metadata socket packet size is "500".
         0.000069417 "shairport.c:2112" get-coverart is 1.
         0.000067666 "shairport.c:2130" loudness is 0.
         0.000070584 "shairport.c:2131" loudness reference level is -20.000000
         0.000254625 "rtsp.c:3823" metadata pipe name is "/tmp/shairport-sync-me                                                                                                                                                             tadata".
         1.500966542 "shairport.c:224" "soxr" interpolation has been chosen.
         2.615251585 "rtsp.c:2646" Connection 1: AP2 PTP connection from 192.168                                                                                                                                                             .1.2:54962 to self at 192.168.1.97:7000.
         1.683191750 "rtsp.c:2976" Connection 1. AP2 Realtime Audio Stream.
         0.252727709 "rtp.c:1325" Connection 1: Clock 84ab1a7eeeee0008 is now th                                                                                                                                                             e new anchor clock and master clock. History: 1688.730209 milliseconds.
         0.000616583 "rtp.c:1408" Connection 1: NQPTP new master clock 84ab1a7ee                                                                                                                                                             eee0008.
         0.001136625 "player.c:1070" Connection 1: Short lead time for first fra                                                                                                                                                             me 2575196619: 0.057789 seconds. Flushing 0.5 seconds
         0.549929042 "player.c:2628" Large positive sync error of: 2230 frames (                                                                                                                                                             0.050567 seconds), with frame: 2575230411.
         0.117623042 "player.c:2628" Large positive sync error of: 2308 frames (                                                                                                                                                             0.052336 seconds), with frame: 2575235339.
         0.526067792 "player.c:2628" Large positive sync error of: 2213 frames (                                                                                                                                                             0.050181 seconds), with frame: 2575255755.
         6.948668711 "player.c:2457"     packets missing   late too late resend reqs min buffers max buffers received fps
         0.000072917 "player.c:2457"        1003       1      0        0           0           0          14     44042.25
         7.988714754 "player.c:2457"        2006      16      0        0           0           0          10     44128.91
         7.385910128 "player.c:1644" Connection 1: Playback Stopped. Total playing time 00:00:23. Input: 44128.91 frames per second.
        69.721236909 "rtsp.c:2976" Connection 1. AP2 Realtime Audio Stream.
         0.217115791 "player.c:1070" Connection 1: Short lead time for first frame 3237316490: -31.690765 seconds. Flushing 0.5 seconds
         0.000524125 "player.c:1119" Gone past starting time for 3237316490 by 31690765333 nanoseconds.
         0.026299875 "player.c:1070" Connection 1: Short lead time for first frame 3237325642: -31.510128 seconds. Flushing 0.5 seconds
         0.000393750 "player.c:1119" Gone past starting time for 3237325642 by 31510127780 nanoseconds.
         0.021055709 "player.c:1070" Connection 1: Short lead time for first frame 3237326698: -31.507623 seconds. Flushing 0.5 seconds
         0.000375083 "player.c:1119" Gone past starting time for 3237326698 by 31507623494 nanoseconds.
         0.023907917 "player.c:1070" Connection 1: Short lead time for first frame 3237327754: -31.507975 seconds. Flushing 0.5 seconds
         0.000361083 "player.c:1119" Gone past starting time for 3237327754 by 31507974916 nanoseconds.
         0.022981000 "player.c:1070" Connection 1: Short lead time for first frame 3237328458: -31.515336 seconds. Flushing 0.5 seconds
         0.000370417 "player.c:1119" Gone past starting time for 3237328458 by 31515336072 nanoseconds.
         0.023367458 "player.c:1070" Connection 1: Short lead time for first frame 3237329514: -31.515140 seconds. Flushing 0.5 seconds
         0.000383833 "player.c:1119" Gone past starting time for 3237329514 by 31515140326 nanoseconds.
         0.022073334 "player.c:1070" Connection 1: Short lead time for first frame 3237330570: -31.513651 seconds. Flushing 0.5 seconds
         0.000371875 "player.c:1119" Gone past starting time for 3237330570 by 31513651331 nanoseconds.
         0.037439791 "player.c:1070" Connection 1: Short lead time for first frame 3237331626: -31.527531 seconds. Flushing 0.5 seconds
         0.000375667 "player.c:1119" Gone past starting time for 3237331626 by 31527531128 nanoseconds.
         0.031587208 "player.c:1070" Connection 1: Short lead time for first frame 3237333738: -31.511604 seconds. Flushing 0.5 seconds
         0.000361959 "player.c:1119" Gone past starting time for 3237333738 by 31511603722 nanoseconds.
         0.022973708 "player.c:1070" Connection 1: Short lead time for first frame 3237334794: -31.510987 seconds. Flushing 0.5 seconds
         0.000364000 "player.c:1119" Gone past starting time for 3237334794 by 31510987393 nanoseconds.
         0.022863167 "player.c:1070" Connection 1: Short lead time for first frame 3237335850: -31.510268 seconds. Flushing 0.5 seconds
         0.000357583 "player.c:1119" Gone past starting time for 3237335850 by 31510268399 nanoseconds.
         0.022857333 "player.c:1070" Connection 1: Short lead time for first frame 3237336906: -31.509547 seconds. Flushing 0.5 seconds
         0.000363709 "player.c:1119" Gone past starting time for 3237336906 by 31509547362 nanoseconds.
         0.023012500 "player.c:1070" Connection 1: Short lead time for first frame 3237337962: -31.508959 seconds. Flushing 0.5 seconds
         0.000362833 "player.c:1119" Gone past starting time for 3237337962 by 31508958743 nanoseconds.
         0.021757167 "player.c:1070" Connection 1: Short lead time for first frame 3237339018: -31.507143 seconds. Flushing 0.5 seconds
         0.000371292 "player.c:1119" Gone past starting time for 3237339018 by 31507143372 nanoseconds.
         0.023388750 "player.c:1070" Connection 1: Short lead time for first frame 3237339722: -31.514938 seconds. Flushing 0.5 seconds
         0.000359333 "player.c:1119" Gone past starting time for 3237339722 by 31514937946 nanoseconds.
         0.023335958 "player.c:1070" Connection 1: Short lead time for first frame 3237340778: -31.514690 seconds. Flushing 0.5 seconds
         0.000363125 "player.c:1119" Gone past starting time for 3237340778 by 31514690284 nanoseconds.
         0.022771292 "player.c:1070" Connection 1: Short lead time for first frame 3237341834: -31.513875 seconds. Flushing 0.5 seconds
         0.000380042 "player.c:1119" Gone past starting time for 3237341834 by 31513874747 nanoseconds.
         0.022701583 "player.c:1070" Connection 1: Short lead time for first frame 3237342890: -31.513011 seconds. Flushing 0.5 seconds
         0.000367500 "player.c:1119" Gone past starting time for 3237342890 by 31513011086 nanoseconds.
         0.023164750 "player.c:1070" Connection 1: Short lead time for first frame 3237343946: -31.512474 seconds. Flushing 0.5 seconds
         0.000362542 "player.c:1119" Gone past starting time for 3237343946 by 31512473508 nanoseconds.
         0.022767500 "player.c:1070" Connection 1: Short lead time for first frame 3237345002: -31.511787 seconds. Flushing 0.5 seconds
         0.000360500 "player.c:1119" Gone past starting time for 3237345002 by 31511787471 nanoseconds.
         0.022096375 "player.c:1070" Connection 1: Short lead time for first frame 3237346058: -31.510314 seconds. Flushing 0.5 seconds
         0.000359333 "player.c:1119" Gone past starting time for 3237346058 by 31510313643 nanoseconds.
         0.022804250 "player.c:1070" Connection 1: Short lead time for first frame 3237347114: -31.509525 seconds. Flushing 0.5 seconds
         0.000363417 "player.c:1119" Gone past starting time for 3237347114 by 31509524940 nanoseconds.
         0.023075208 "player.c:1070" Connection 1: Short lead time for first frame 3237348170: -31.509011 seconds. Flushing 0.5 seconds
         0.000363125 "player.c:1119" Gone past starting time for 3237348170 by 31509010987 nanoseconds.
         0.024003000 "player.c:1070" Connection 1: Short lead time for first frame 3237349226: -31.509430 seconds. Flushing 0.5 seconds
         0.000355833 "player.c:1119" Gone past starting time for 3237349226 by 31509430074 nanoseconds.
         0.022326209 "player.c:1070" Connection 1: Short lead time for first frame 3237350282: -31.508165 seconds. Flushing 0.5 seconds
         0.000428458 "player.c:1119" Gone past starting time for 3237350282 by 31508164788 nanoseconds.
         0.022524250 "player.c:1070" Connection 1: Short lead time for first frame 3237350986: -31.515154 seconds. Flushing 0.5 seconds
         0.000359625 "player.c:1119" Gone past starting time for 3237350986 by 31515154069 nanoseconds.
         0.023390792 "player.c:1070" Connection 1: Short lead time for first frame 3237352042: -31.514958 seconds. Flushing 0.5 seconds
         0.000358458 "player.c:1119" Gone past starting time for 3237352042 by 31514958033 nanoseconds.
         0.022196708 "player.c:1070" Connection 1: Short lead time for first frame 3237353098: -31.513566 seconds. Flushing 0.5 seconds
         0.000361084 "player.c:1119" Gone past starting time for 3237353098 by 31513566163 nanoseconds.
         0.023176416 "player.c:1070" Connection 1: Short lead time for first frame 3237354154: -31.513155 seconds. Flushing 0.5 seconds
         0.000358459 "player.c:1119" Gone past starting time for 3237354154 by 31513155168 nanoseconds.
         0.023268583 "player.c:1070" Connection 1: Short lead time for first frame 3237355210: -31.512853 seconds. Flushing 0.5 seconds
         0.000360500 "player.c:1119" Gone past starting time for 3237355210 by 31512853257 nanoseconds.
         0.022774208 "player.c:1070" Connection 1: Short lead time for first frame 3237356266: -31.512032 seconds. Flushing 0.5 seconds
         0.000361084 "player.c:1119" Gone past starting time for 3237356266 by 31512032178 nanoseconds.
         0.022016166 "player.c:1070" Connection 1: Short lead time for first frame 3237357322: -31.510453 seconds. Flushing 0.5 seconds
         0.000365750 "player.c:1119" Gone past starting time for 3237357322 by 31510452767 nanoseconds.
         0.023826834 "player.c:1070" Connection 1: Short lead time for first frame 3237358378: -31.510718 seconds. Flushing 0.5 seconds
         0.000359041 "player.c:1119" Gone past starting time for 3237358378 by 31510718147 nanoseconds.
         0.021603750 "player.c:1070" Connection 1: Short lead time for first frame 3237359434: -31.508726 seconds. Flushing 0.5 seconds
         0.000370417 "player.c:1119" Gone past starting time for 3237359434 by 31508726027 nanoseconds.
         0.022779458 "player.c:1070" Connection 1: Short lead time for first frame 3237360490: -31.507925 seconds. Flushing 0.5 seconds
         0.000380917 "player.c:1119" Gone past starting time for 3237360490 by 31507925365 nanoseconds.
         0.022321833 "player.c:1070" Connection 1: Short lead time for first frame 3237361546: -31.506686 seconds. Flushing 0.5 seconds
         0.000355834 "player.c:1119" Gone past starting time for 3237361546 by 31506686030 nanoseconds.
         0.023671083 "player.c:1070" Connection 1: Short lead time for first frame 3237362250: -31.514716 seconds. Flushing 0.5 seconds
         0.000373625 "player.c:1119" Gone past starting time for 3237362250 by 31514716269 nanoseconds.
         0.022659875 "player.c:1070" Connection 1: Short lead time for first frame 3237363306: -31.513823 seconds. Flushing 0.5 seconds
         0.000363417 "player.c:1119" Gone past starting time for 3237363306 by 31513823150 nanoseconds.
         0.024203375 "player.c:1070" Connection 1: Short lead time for first frame 3237364362: -31.514020 seconds. Flushing 0.5 seconds
         0.000687750 "player.c:1119" Gone past starting time for 3237364362 by 31514019987 nanoseconds.
         0.022510250 "player.c:1070" Connection 1: Short lead time for first frame 3237365418: -31.513692 seconds. Flushing 0.5 seconds
         0.000372750 "player.c:1119" Gone past starting time for 3237365418 by 31513692409 nanoseconds.
         0.022877750 "player.c:1070" Connection 1: Short lead time for first frame 3237366474: -31.513001 seconds. Flushing 0.5 seconds
         0.000365458 "player.c:1119" Gone past starting time for 3237366474 by 31513000540 nanoseconds.
         0.021950250 "player.c:1070" Connection 1: Short lead time for first frame 3237367530: -31.511384 seconds. Flushing 0.5 seconds
         0.000749875 "player.c:1119" Gone past starting time for 3237367530 by 31511384378 nanoseconds.
         0.023404208 "player.c:1070" Connection 1: Short lead time for first frame 3237368586: -31.511572 seconds. Flushing 0.5 seconds
         0.000374209 "player.c:1119" Gone past starting time for 3237368586 by 31511571884 nanoseconds.
         0.022605042 "player.c:1070" Connection 1: Short lead time for first frame 3237369642: -31.510615 seconds. Flushing 0.5 seconds
         0.000369541 "player.c:1119" Gone past starting time for 3237369642 by 31510615472 nanoseconds.
         0.023510084 "player.c:1070" Connection 1: Short lead time for first frame 3237370698: -31.510528 seconds. Flushing 0.5 seconds
         0.000373625 "player.c:1119" Gone past starting time for 3237370698 by 31510527935 nanoseconds.
         0.022364708 "player.c:1070" Connection 1: Short lead time for first frame 3237371754: -31.509321 seconds. Flushing 0.5 seconds
         0.000372458 "player.c:1119" Gone past starting time for 3237371754 by 31509320982 nanoseconds.
         0.022477292 "player.c:1070" Connection 1: Short lead time for first frame 3237372810: -31.508213 seconds. Flushing 0.5 seconds
         0.000366333 "player.c:1119" Gone past starting time for 3237372810 by 31508213196 nanoseconds.
         0.023156584 "player.c:1070" Connection 1: Short lead time for first frame 3237373514: -31.515788 seconds. Flushing 0.5 seconds
         0.000372750 "player.c:1119" Gone past starting time for 3237373514 by 31515788144 nanoseconds.
         0.022957083 "player.c:1070" Connection 1: Short lead time for first frame 3237374570: -31.515165 seconds. Flushing 0.5 seconds
         0.000984375 "player.c:1119" Gone past starting time for 3237374570 by 31515165107 nanoseconds.
         0.022233167 "player.c:1070" Connection 1: Short lead time for first frame 3237375626: -31.514442 seconds. Flushing 0.5 seconds
         0.000366916 "player.c:1119" Gone past starting time for 3237375626 by 31514441737 nanoseconds.
         0.022880959 "player.c:1070" Connection 1: Short lead time for first frame 3237376682: -31.513738 seconds. Flushing 0.5 seconds
         0.000398125 "player.c:1119" Gone past starting time for 3237376682 by 31513738200 nanoseconds.
         0.022259125 "player.c:1070" Connection 1: Short lead time for first frame 3237377738: -31.512484 seconds. Flushing 0.5 seconds
         0.000374208 "player.c:1119" Gone past starting time for 3237377738 by 31512483997 nanoseconds.
         0.024526542 "player.c:1070" Connection 1: Short lead time for first frame 3237378794: -31.512119 seconds. Flushing 0.5 seconds
         0.000379750 "player.c:1119" Gone past starting time for 3237378794 by 31512119086 nanoseconds.
         0.021602875 "player.c:1070" Connection 1: Short lead time for first frame 3237379850: -31.511443 seconds. Flushing 0.5 seconds
         0.000370125 "player.c:1119" Gone past starting time for 3237379850 by 31511442965 nanoseconds.
         0.022023458 "player.c:1070" Connection 1: Short lead time for first frame 3237380906: -31.510015 seconds. Flushing 0.5 seconds
         0.000252875 "player.c:1119" Gone past starting time for 3237380906 by 31510014637 nanoseconds.
         0.023475958 "player.c:1070" Connection 1: Short lead time for first frame 3237381962: -31.509810 seconds. Flushing 0.5 seconds
         0.000246459 "player.c:1119" Gone past starting time for 3237381962 by 31509809559 nanoseconds.
         0.022931708 "player.c:1070" Connection 1: Short lead time for first frame 3237383018: -31.509040 seconds. Flushing 0.5 seconds
         0.000349125 "player.c:1119" Gone past starting time for 3237383018 by 31509039815 nanoseconds.
         0.022404958 "player.c:1070" Connection 1: Short lead time for first frame 3237384074: -31.507828 seconds. Flushing 0.5 seconds
         0.000256084 "player.c:1119" Gone past starting time for 3237384074 by 31507827611 nanoseconds.
         0.023466333 "player.c:1070" Connection 1: Short lead time for first frame 3237384778: -31.515613 seconds. Flushing 0.5 seconds
         0.000252875 "player.c:1119" Gone past starting time for 3237384778 by 31515613434 nanoseconds.
         0.026689833 "player.c:1070" Connection 1: Short lead time for first frame 3237385834: -31.518229 seconds. Flushing 0.5 seconds
         0.000682792 "player.c:1119" Gone past starting time for 3237385834 by 31518228772 nanoseconds.
         0.020222708 "player.c:1070" Connection 1: Short lead time for first frame 3237386890: -31.515192 seconds. Flushing 0.5 seconds
         0.000685125 "player.c:1119" Gone past starting time for 3237386890 by 31515192194 nanoseconds.
         0.022106875 "player.c:1070" Connection 1: Short lead time for first frame 3237387946: -31.514005 seconds. Flushing 0.5 seconds
         0.000882292 "player.c:1119" Gone past starting time for 3237387946 by 31514005366 nanoseconds.
         0.022426833 "player.c:1070" Connection 1: Short lead time for first frame 3237389002: -31.513397 seconds. Flushing 0.5 seconds
         0.000678417 "player.c:1119" Gone past starting time for 3237389002 by 31513396913 nanoseconds.
         0.022472625 "player.c:1070" Connection 1: Short lead time for first frame 3237390058: -31.512624 seconds. Flushing 0.5 seconds
         0.000679000 "player.c:1119" Gone past starting time for 3237390058 by 31512623960 nanoseconds.
         0.022053500 "player.c:1070" Connection 1: Short lead time for first frame 3237391114: -31.511778 seconds. Flushing 0.5 seconds
         0.000252292 "player.c:1119" Gone past starting time for 3237391114 by 31511778089 nanoseconds.
         0.022437625 "player.c:1070" Connection 1: Short lead time for first frame 3237392170: -31.510521 seconds. Flushing 0.5 seconds
         0.000246166 "player.c:1119" Gone past starting time for 3237392170 by 31510521261 nanoseconds.
         0.022616417 "player.c:1070" Connection 1: Short lead time for first frame 3237393226: -31.509429 seconds. Flushing 0.5 seconds
         0.000252292 "player.c:1119" Gone past starting time for 3237393226 by 31509428933 nanoseconds.
         0.022856750 "player.c:1070" Connection 1: Short lead time for first frame 3237394282: -31.508603 seconds. Flushing 0.5 seconds
         0.000246166 "player.c:1119" Gone past starting time for 3237394282 by 31508602605 nanoseconds.
         0.022655500 "player.c:1070" Connection 1: Short lead time for first frame 3237395338: -31.507560 seconds. Flushing 0.5 seconds
         0.000249375 "player.c:1119" Gone past starting time for 3237395338 by 31507559568 nanoseconds.
         0.024896084 "player.c:1070" Connection 1: Short lead time for first frame 3237396042: -31.516350 seconds. Flushing 0.5 seconds
         0.000693875 "player.c:1119" Gone past starting time for 3237396042 by 31516350475 nanoseconds.
         0.022343125 "player.c:1070" Connection 1: Short lead time for first frame 3237397098: -31.515462 seconds. Flushing 0.5 seconds
         0.000669375 "player.c:1119" Gone past starting time for 3237397098 by 31515462313 nanoseconds.
         0.092290958 "player.c:2628" Large positive sync error of: 1404644 frames (31.851338 seconds), with frame: 3237401322.
         0.000238875 "player.c:931" flush request: sanity check -- flush frame 3238810376 is too far into the future from the first frame 3237401674 -- discarded.
         0.093795042 "player.c:2628" Large positive sync error of: 1404277 frames (31.843016 seconds), with frame: 3237405898.
         0.000363708 "player.c:931" flush request: sanity check -- flush frame 3238814585 is too far into the future from the first frame 3237406250 -- discarded.
         0.114617125 "player.c:2628" Large positive sync error of: 1395875 frames (31.652494 seconds), with frame: 3237410474.
         0.000523834 "player.c:931" flush request: sanity check -- flush frame 3238810759 is too far into the future from the first frame 3237410826 -- discarded.
         0.096489458 "player.c:2628" Large positive sync error of: 1395930 frames (31.653741 seconds), with frame: 3237415050.
         0.000393167 "player.c:931" flush request: sanity check -- flush frame 3238815390 is too far into the future from the first frame 3237415402 -- discarded.
         0.111981625 "player.c:2628" Large positive sync error of: 1396311 frames (31.662381 seconds), with frame: 3237419626.
         0.000365458 "player.c:931" flush request: sanity check -- flush frame 3238820347 is too far into the future from the first frame 3237419978 -- discarded.
         0.105589458 "player.c:2628" Large positive sync error of: 1396401 frames (31.664422 seconds), with frame: 3237424202.
         0.000316459 "player.c:931" flush request: sanity check -- flush frame 3238825013 is too far into the future from the first frame 3237424554 -- discarded.
         0.084403375 "player.c:2628" Large positive sync error of: 1395568 frames (31.645533 seconds), with frame: 3237428778.
         0.114826250 "player.c:2628" Large positive sync error of: 1396054 frames (31.656553 seconds), with frame: 3237433354.
         0.000391125 "player.c:931" flush request: sanity check -- flush frame 3238833818 is too far into the future from the first frame 3237433706 -- discarded.
         0.097834625 "player.c:2628" Large positive sync error of: 1400031 frames (31.746735 seconds), with frame: 3237437930.
         0.109138458 "player.c:2628" Large positive sync error of: 1396049 frames (31.656440 seconds), with frame: 3237442506.
         0.000271834 "player.c:931" flush request: sanity check -- flush frame 3238842965 is too far into the future from the first frame 3237442858 -- discarded.
         0.103028041 "player.c:2628" Large positive sync error of: 1400247 frames (31.751633 seconds), with frame: 3237447082.
         0.100916084 "player.c:2628" Large positive sync error of: 1395903 frames (31.653129 seconds), with frame: 3237451658.
         0.000321708 "player.c:931" flush request: sanity check -- flush frame 3238851971 is too far into the future from the first frame 3237452010 -- discarded.
         0.104965875 "player.c:2628" Large positive sync error of: 1400189 frames (31.750317 seconds), with frame: 3237456234.
         0.104902583 "player.c:2628" Large positive sync error of: 1396020 frames (31.655782 seconds), with frame: 3237460810.
         0.000648375 "player.c:931" flush request: sanity check -- flush frame 3238861240 is too far into the future from the first frame 3237461162 -- discarded.
         0.101367292 "player.c:2628" Large positive sync error of: 1400162 frames (31.749705 seconds), with frame: 3237465386.
         0.107296292 "player.c:2628" Large positive sync error of: 1396095 frames (31.657483 seconds), with frame: 3237469962.
         0.000510125 "player.c:931" flush request: sanity check -- flush frame 3238870467 is too far into the future from the first frame 3237470314 -- discarded.
         0.093821292 "player.c:2628" Large positive sync error of: 1399904 frames (31.743855 seconds), with frame: 3237474538.
         0.114631708 "player.c:2628" Large positive sync error of: 1396159 frames (31.658934 seconds), with frame: 3237479114.
         0.000513042 "player.c:931" flush request: sanity check -- flush frame 3238879683 is too far into the future from the first frame 3237479466 -- discarded.
         0.103038250 "player.c:2628" Large positive sync error of: 1400373 frames (31.754490 seconds), with frame: 3237483690.
         0.000261333 "player.c:931" flush request: sanity check -- flush frame 3238888473 is too far into the future from the first frame 3237484042 -- discarded.
         0.104173417 "player.c:2628" Large positive sync error of: 1396185 frames (31.659524 seconds), with frame: 3237488266.
         0.000273583 "player.c:931" flush request: sanity check -- flush frame 3238888861 is too far into the future from the first frame 3237488618 -- discarded.
         0.103299292 "player.c:2628" Large positive sync error of: 1396163 frames (31.659025 seconds), with frame: 3237492842.
         0.000729458 "player.c:931" flush request: sanity check -- flush frame 3238893415 is too far into the future from the first frame 3237493194 -- discarded.
         0.104731750 "player.c:2628" Large positive sync error of: 1396251 frames (31.661020 seconds), with frame: 3237497418.
         0.000224292 "player.c:931" flush request: sanity check -- flush frame 3238898079 is too far into the future from the first frame 3237497770 -- discarded.
         0.094299917 "player.c:2628" Large positive sync error of: 1395844 frames (31.651791 seconds), with frame: 3237501994.
         0.000121333 "player.c:931" flush request: sanity check -- flush frame 3238902248 is too far into the future from the first frame 3237502346 -- discarded.
         0.101093417 "player.c:2628" Large positive sync error of: 1395726 frames (31.649116 seconds), with frame: 3237506570.
         0.109355750 "player.c:2628" Large positive sync error of: 1395976 frames (31.654785 seconds), with frame: 3237511146.
         0.000184333 "player.c:931" flush request: sanity check -- flush frame 3238911532 is too far into the future from the first frame 3237511498 -- discarded.
         0.099930250 "player.c:2628" Large positive sync error of: 1400033 frames (31.746780 seconds), with frame: 3237515722.
         0.108973083 "player.c:2628" Large positive sync error of: 1396045 frames (31.656349 seconds), with frame: 3237520298.
         0.000184917 "player.c:931" flush request: sanity check -- flush frame 3238920753 is too far into the future from the first frame 3237520650 -- discarded.
         0.099278667 "player.c:2628" Large positive sync error of: 1400072 frames (31.747664 seconds), with frame: 3237524874.
         0.107004333 "player.c:2628" Large positive sync error of: 1395997 frames (31.655261 seconds), with frame: 3237529450.
         0.000361084 "player.c:931" flush request: sanity check -- flush frame 3238929857 is too far into the future from the first frame 3237529802 -- discarded.
         0.097888000 "player.c:2628" Large positive sync error of: 1399975 frames (31.745465 seconds), with frame: 3237534026.
         0.110438416 "player.c:2628" Large positive sync error of: 1396048 frames (31.656417 seconds), with frame: 3237538602.
         0.000360209 "player.c:931" flush request: sanity check -- flush frame 3238939060 is too far into the future from the first frame 3237538954 -- discarded.
         0.101701541 "player.c:2628" Large positive sync error of: 1400192 frames (31.750385 seconds), with frame: 3237543178.
         0.106819417 "player.c:2628" Large positive sync error of: 1396108 frames (31.657778 seconds), with frame: 3237547754.
         0.000536667 "player.c:931" flush request: sanity check -- flush frame 3238948272 is too far into the future from the first frame 3237548106 -- discarded.
         0.098151666 "player.c:2628" Large positive sync error of: 1400102 frames (31.748345 seconds), with frame: 3237552330.
         0.000283792 "player.c:931" flush request: sanity check -- flush frame 3238956842 is too far into the future from the first frame 3237552682 -- discarded.
         0.112567875 "player.c:2628" Large positive sync error of: 1396280 frames (31.661678 seconds), with frame: 3237556906.
         0.000202709 "player.c:931" flush request: sanity check -- flush frame 3238957596 is too far into the future from the first frame 3237557258 -- discarded.
         0.095448791 "player.c:2628" Large positive sync error of: 1395925 frames (31.653628 seconds), with frame: 3237561482.
         0.000271834 "player.c:931" flush request: sanity check -- flush frame 3238961817 is too far into the future from the first frame 3237561834 -- discarded.
         0.110557416 "player.c:2628" Large positive sync error of: 1396238 frames (31.660726 seconds), with frame: 3237566058.
         0.000355250 "player.c:931" flush request: sanity check -- flush frame 3238966706 is too far into the future from the first frame 3237566410 -- discarded.
         0.095987792 "player.c:2628" Large positive sync error of: 1395911 frames (31.653311 seconds), with frame: 3237570634.
         0.000192208 "player.c:931" flush request: sanity check -- flush frame 3238970955 is too far into the future from the first frame 3237570986 -- discarded.
         0.095807542 "player.c:2628" Large positive sync error of: 1395569 frames (31.645556 seconds), with frame: 3237575210.
         0.114806708 "player.c:2628" Large positive sync error of: 1396053 frames (31.656531 seconds), with frame: 3237579786.
         0.000269209 "player.c:931" flush request: sanity check -- flush frame 3238980249 is too far into the future from the first frame 3237580138 -- discarded.
         0.093719500 "player.c:2628" Large positive sync error of: 1399845 frames (31.742517 seconds), with frame: 3237584362.
         0.115168667 "player.c:2628" Large positive sync error of: 1396124 frames (31.658141 seconds), with frame: 3237588938.
         0.000266000 "player.c:931" flush request: sanity check -- flush frame 3238989472 is too far into the future from the first frame 3237589290 -- discarded.
         0.093282291 "player.c:2628" Large positive sync error of: 1399899 frames (31.743741 seconds), with frame: 3237593514.
         0.110287042 "player.c:2628" Large positive sync error of: 1395962 frames (31.654467 seconds), with frame: 3237598090.
         0.000513625 "player.c:931" flush request: sanity check -- flush frame 3238998462 is too far into the future from the first frame 3237598442 -- discarded.
         0.101553667 "player.c:2628" Large positive sync error of: 1400111 frames (31.748549 seconds), with frame: 3237602666.
         0.106950375 "player.c:2628" Large positive sync error of: 1396030 frames (31.656009 seconds), with frame: 3237607242.
         0.000350875 "player.c:931" flush request: sanity check -- flush frame 3239007682 is too far into the future from the first frame 3237607594 -- discarded.
         0.101992333 "player.c:2628" Large positive sync error of: 1400186 frames (31.750249 seconds), with frame: 3237611818.
         0.106843334 "player.c:2628" Large positive sync error of: 1396101 frames (31.657619 seconds), with frame: 3237616394.
         0.000524708 "player.c:931" flush request: sanity check -- flush frame 3239016905 is too far into the future from the first frame 3237616746 -- discarded.
         0.094749667 "player.c:2628" Large positive sync error of: 1399950 frames (31.744898 seconds), with frame: 3237620970.
         0.112711666 "player.c:2628" Large positive sync error of: 1396122 frames (31.658095 seconds), with frame: 3237625546.
         0.000528792 "player.c:931" flush request: sanity check -- flush frame 3239026078 is too far into the future from the first frame 3237625898 -- discarded.
         0.096195750 "player.c:2628" Large positive sync error of: 1400035 frames (31.746825 seconds), with frame: 3237630122.
         0.000194542 "player.c:931" flush request: sanity check -- flush frame 3239034567 is too far into the future from the first frame 3237630474 -- discarded.
         0.112607541 "player.c:2628" Large positive sync error of: 1396210 frames (31.660091 seconds), with frame: 3237634698.
         0.000530250 "player.c:931" flush request: sanity check -- flush frame 3239035318 is too far into the future from the first frame 3237635050 -- discarded.
         0.097399750 "player.c:2628" Large positive sync error of: 1395953 frames (31.654263 seconds), with frame: 3237639274.
         0.000273000 "player.c:931" flush request: sanity check -- flush frame 3239039637 is too far into the future from the first frame 3237639626 -- discarded.
         0.110685750 "player.c:2628" Large positive sync error of: 1396272 frames (31.661497 seconds), with frame: 3237643850.
         0.000341834 "player.c:931" flush request: sanity check -- flush frame 3239044532 is too far into the future from the first frame 3237644202 -- discarded.
         0.097756458 "player.c:2628" Large positive sync error of: 1396019 frames (31.655760 seconds), with frame: 3237648426.
         0.000267459 "player.c:931" flush request: sanity check -- flush frame 3239048855 is too far into the future from the first frame 3237648778 -- discarded.
         0.093600791 "player.c:2628" Large positive sync error of: 1395586 frames (31.645941 seconds), with frame: 3237653002.
         0.115262875 "player.c:2628" Large positive sync error of: 1396091 frames (31.657392 seconds), with frame: 3237657578.
         0.000253167 "player.c:931" flush request: sanity check -- flush frame 3239058079 is too far into the future from the first frame 3237657930 -- discarded.
         0.094268125 "player.c:2628" Large positive sync error of: 1399907 frames (31.743923 seconds), with frame: 3237662154.
         0.114745167 "player.c:2628" Large positive sync error of: 1396160 frames (31.658957 seconds), with frame: 3237666730.
         0.000261041 "player.c:931" flush request: sanity check -- flush frame 3239067300 is too far into the future from the first frame 3237667082 -- discarded.
         0.096527667 "player.c:2628" Large positive sync error of: 1400081 frames (31.747868 seconds), with frame: 3237671306.
         0.107035833 "player.c:2628" Large positive sync error of: 1396003 frames (31.655397 seconds), with frame: 3237675882.
         0.000461417 "player.c:931" flush request: sanity check -- flush frame 3239076295 is too far into the future from the first frame 3237676234 -- discarded.
         0.098240334 "player.c:2628" Large positive sync error of: 1400003 frames (31.746100 seconds), with frame: 3237680458.
         0.109622041 "player.c:2628" Large positive sync error of: 1396038 frames (31.656190 seconds), with frame: 3237685034.
         0.000478042 "player.c:931" flush request: sanity check -- flush frame 3239085482 is too far into the future from the first frame 3237685386 -- discarded.
         0.099253875 "player.c:2628" Large positive sync error of: 1400084 frames (31.747937 seconds), with frame: 3237689610.
         0.115397042 "player.c:2628" Large positive sync error of: 1396358 frames (31.663447 seconds), with frame: 3237694186.
         0.000708458 "player.c:931" flush request: sanity check -- flush frame 3239094954 is too far into the future from the first frame 3237694538 -- discarded.
         0.088081583 "player.c:2628" Large positive sync error of: 1399939 frames (31.744649 seconds), with frame: 3237698762.
         0.000214375 "player.c:931" flush request: sanity check -- flush frame 3239103111 is too far into the future from the first frame 3237699114 -- discarded.
         0.113501500 "player.c:2628" Large positive sync error of: 1396149 frames (31.658707 seconds), with frame: 3237703338.
         0.000528209 "player.c:931" flush request: sanity check -- flush frame 3239103897 is too far into the future from the first frame 3237703690 -- discarded.
         0.097594000 "player.c:2628" Large positive sync error of: 1395904 frames (31.653152 seconds), with frame: 3237707914.
         0.000393750 "player.c:931" flush request: sanity check -- flush frame 3239108228 is too far into the future from the first frame 3237708266 -- discarded.
         0.109804625 "player.c:2628" Large positive sync error of: 1396188 frames (31.659592 seconds), with frame: 3237712490.
         0.000493500 "player.c:931" flush request: sanity check -- flush frame 3239113088 is too far into the future from the first frame 3237712842 -- discarded.
         0.096977125 "player.c:2628" Large positive sync error of: 1395910 frames (31.653288 seconds), with frame: 3237717066.
         0.000384708 "player.c:931" flush request: sanity check -- flush frame 3239117386 is too far into the future from the first frame 3237717418 -- discarded.
         0.094948292 "player.c:2628" Large positive sync error of: 1395541 frames (31.644921 seconds), with frame: 3237721642.
         0.087504958 "player.c:2457"     packets missing   late too late resend reqs min buffers max buffers received fps
         0.000214667 "player.c:2457"        1003       0      0        0           0           0           2         0.00
         0.027362708 "player.c:2628" Large positive sync error of: 1396038 frames (31.656190 seconds), with frame: 3237726218.
         0.000374500 "player.c:931" flush request: sanity check -- flush frame 3239126666 is too far into the future from the first frame 3237726570 -- discarded.
         0.093629084 "player.c:2628" Large positive sync error of: 1399831 frames (31.742200 seconds), with frame: 3237730794.
         0.115206000 "player.c:2628" Large positive sync error of: 1396112 frames (31.657868 seconds), with frame: 3237735370.
         0.000377708 "player.c:931" flush request: sanity check -- flush frame 3239135892 is too far into the future from the first frame 3237735722 -- discarded.
         0.098303042 "player.c:2628" Large positive sync error of: 1400109 frames (31.748503 seconds), with frame: 3237739946.
         0.104445542 "player.c:2628" Large positive sync error of: 1395920 frames (31.653515 seconds), with frame: 3237744522.
         0.000262208 "player.c:931" flush request: sanity check -- flush frame 3239144852 is too far into the future from the first frame 3237744874 -- discarded.
         0.102494875 "player.c:2628" Large positive sync error of: 1400094 frames (31.748163 seconds), with frame: 3237749098.
         0.108087000 "player.c:2628" Large positive sync error of: 1396066 frames (31.656825 seconds), with frame: 3237753674.
         0.000332500 "player.c:931" flush request: sanity check -- flush frame 3239154150 is too far into the future from the first frame 3237754026 -- discarded.
         0.100086292 "player.c:2628" Large positive sync error of: 1400138 frames (31.749161 seconds), with frame: 3237758250.
         0.108022541 "player.c:2628" Large positive sync error of: 1396104 frames (31.657687 seconds), with frame: 3237762826.
         0.000491750 "player.c:931" flush request: sanity check -- flush frame 3239163340 is too far into the future from the first frame 3237763178 -- discarded.
         0.093688000 "player.c:2628" Large positive sync error of: 1399905 frames (31.743878 seconds), with frame: 3237767402.
         0.114502209 "player.c:2628" Large positive sync error of: 1396155 frames (31.658844 seconds), with frame: 3237771978.
         0.000487083 "player.c:931" flush request: sanity check -- flush frame 3239172543 is too far into the future from the first frame 3237772330 -- discarded.
         0.096702667 "player.c:2628" Large positive sync error of: 1400087 frames (31.748005 seconds), with frame: 3237776554.
         0.000382667 "player.c:931" flush request: sanity check -- flush frame 3239181051 is too far into the future from the first frame 3237776906 -- discarded.
         0.110729791 "player.c:2628" Large positive sync error of: 1396192 frames (31.659683 seconds), with frame: 3237781130.
         0.000339500 "player.c:931" flush request: sanity check -- flush frame 3239181732 is too far into the future from the first frame 3237781482 -- discarded.
         0.096705000 "player.c:2628" Large positive sync error of: 1395893 frames (31.652902 seconds), with frame: 3237785706.
         0.000385000 "player.c:931" flush request: sanity check -- flush frame 3239186009 is too far into the future from the first frame 3237786058 -- discarded.
         0.111888584 "player.c:2628" Large positive sync error of: 1396268 frames (31.661406 seconds), with frame: 3237790282.
         0.000492625 "player.c:931" flush request: sanity check -- flush frame 3239190960 is too far into the future from the first frame 3237790634 -- discarded.
         0.097108958 "player.c:2628" Large positive sync error of: 1395997 frames (31.655261 seconds), with frame: 3237794858.
         0.000383250 "player.c:931" flush request: sanity check -- flush frame 3239195265 is too far into the future from the first frame 3237795210 -- discarded.
         0.096747875 "player.c:2628" Large positive sync error of: 1395707 frames (31.648685 seconds), with frame: 3237799434.
         0.110813792 "player.c:2628" Large positive sync error of: 1396015 frames (31.655669 seconds), with frame: 3237804010.
         0.000480375 "player.c:931" flush request: sanity check -- flush frame 3239204435 is too far into the future from the first frame 3237804362 -- discarded.
         0.098014292 "player.c:2628" Large positive sync error of: 1400004 frames (31.746122 seconds), with frame: 3237808586.
         0.109425750 "player.c:2628" Large positive sync error of: 1396035 frames (31.656122 seconds), with frame: 3237813162.
         0.000262500 "player.c:931" flush request: sanity check -- flush frame 3239213607 is too far into the future from the first frame 3237813514 -- discarded.
         0.098744625 "player.c:2628" Large positive sync error of: 1400043 frames (31.747007 seconds), with frame: 3237817738.
         0.105872666 "player.c:2628" Large positive sync error of: 1395918 frames (31.653469 seconds), with frame: 3237822314.
         0.000301292 "player.c:931" flush request: sanity check -- flush frame 3239222642 is too far into the future from the first frame 3237822666 -- discarded.
         0.103361708 "player.c:2628" Large positive sync error of: 1400132 frames (31.749025 seconds), with frame: 3237826890.
         0.106810959 "player.c:2628" Large positive sync error of: 1396048 frames (31.656417 seconds), with frame: 3237831466.
         0.000306250 "player.c:931" flush request: sanity check -- flush frame 3239231924 is too far into the future from the first frame 3237831818 -- discarded.
         0.101258500 "player.c:2628" Large positive sync error of: 1400169 frames (31.749864 seconds), with frame: 3237836042.
         0.107603708 "player.c:2628" Large positive sync error of: 1396119 frames (31.658027 seconds), with frame: 3237840618.
         0.000287584 "player.c:931" flush request: sanity check -- flush frame 3239241147 is too far into the future from the first frame 3237840970 -- discarded.
         0.096382125 "player.c:2628" Large positive sync error of: 1400028 frames (31.746667 seconds), with frame: 3237845194.
         0.000186083 "player.c:931" flush request: sanity check -- flush frame 3239249632 is too far into the future from the first frame 3237845546 -- discarded.
         0.112335125 "player.c:2628" Large positive sync error of: 1396191 frames (31.659660 seconds), with frame: 3237849770.
         0.000468708 "player.c:931" flush request: sanity check -- flush frame 3239250371 is too far into the future from the first frame 3237850122 -- discarded.
         0.096670000 "player.c:2628" Large positive sync error of: 1395899 frames (31.653039 seconds), with frame: 3237854346.
         0.000257542 "player.c:931" flush request: sanity check -- flush frame 3239254655 is too far into the future from the first frame 3237854698 -- discarded.
         0.111028458 "player.c:2628" Large positive sync error of: 1396232 frames (31.660590 seconds), with frame: 3237858922.
         0.000340959 "player.c:931" flush request: sanity check -- flush frame 3239259564 is too far into the future from the first frame 3237859274 -- discarded.
         0.097286875 "player.c:2628" Large positive sync error of: 1395959 frames (31.654399 seconds), with frame: 3237863498.
         0.000261333 "player.c:931" flush request: sanity check -- flush frame 3239263867 is too far into the future from the first frame 3237863850 -- discarded.
         0.094257625 "player.c:2628" Large positive sync error of: 1395555 frames (31.645238 seconds), with frame: 3237868074.
         0.114543625 "player.c:2628" Large positive sync error of: 1396028 frames (31.655964 seconds), with frame: 3237872650.
         0.000252000 "player.c:931" flush request: sanity check -- flush frame 3239273088 is too far into the future from the first frame 3237873002 -- discarded.
         0.097891500 "player.c:2628" Large positive sync error of: 1400001 frames (31.746054 seconds), with frame: 3237877226.
         0.109024125 "player.c:2628" Large positive sync error of: 1396014 frames (31.655646 seconds), with frame: 3237881802.
         0.000179959 "player.c:931" flush request: sanity check -- flush frame 3239282226 is too far into the future from the first frame 3237882154 -- discarded.
         0.098586250 "player.c:2628" Large positive sync error of: 1400012 frames (31.746304 seconds), with frame: 3237886378.
         0.105605208 "player.c:2628" Large positive sync error of: 1395874 frames (31.652472 seconds), with frame: 3237890954.
         0.000275333 "player.c:931" flush request: sanity check -- flush frame 3239291238 is too far into the future from the first frame 3237891306 -- discarded.
         0.103728042 "player.c:2628" Large positive sync error of: 1400104 frames (31.748390 seconds), with frame: 3237895530.
         0.106468542 "player.c:2628" Large positive sync error of: 1396002 frames (31.655374 seconds), with frame: 3237900106.
         0.000441292 "player.c:931" flush request: sanity check -- flush frame 3239300518 is too far into the future from the first frame 3237900458 -- discarded.
         0.097542375 "player.c:2628" Large positive sync error of: 1399971 frames (31.745374 seconds), with frame: 3237904682.
         0.111045958 "player.c:2628" Large positive sync error of: 1396071 frames (31.656939 seconds), with frame: 3237909258.
         0.000308292 "player.c:931" flush request: sanity check -- flush frame 3239309739 is too far into the future from the first frame 3237909610 -- discarded.
         0.095708958 "player.c:2628" Large positive sync error of: 1399947 frames (31.744830 seconds), with frame: 3237913834.
         0.111911625 "player.c:2628" Large positive sync error of: 1396086 frames (31.657279 seconds), with frame: 3237918410.
         0.000249958 "player.c:931" flush request: sanity check -- flush frame 3239318906 is too far into the future from the first frame 3237918762 -- discarded.
         0.096754292 "player.c:2628" Large positive sync error of: 1400009 frames (31.746236 seconds), with frame: 3237922986.
         0.000263083 "player.c:931" flush request: sanity check -- flush frame 3239327405 is too far into the future from the first frame 3237923338 -- discarded.
         0.110925209 "player.c:2628" Large positive sync error of: 1396118 frames (31.658005 seconds), with frame: 3237927562.
         0.000184042 "player.c:931" flush request: sanity check -- flush frame 3239328090 is too far into the future from the first frame 3237927914 -- discarded.
         0.097549958 "player.c:2628" Large positive sync error of: 1395849 frames (31.651905 seconds), with frame: 3237932138.
         0.000262792 "player.c:931" flush request: sanity check -- flush frame 3239332397 is too far into the future from the first frame 3237932490 -- discarded.
         0.110937458 "player.c:2628" Large positive sync error of: 1396179 frames (31.659388 seconds), with frame: 3237936714.
         0.000182875 "player.c:931" flush request: sanity check -- flush frame 3239337303 is too far into the future from the first frame 3237937066 -- discarded.
         0.095718000 "player.c:2628" Large positive sync error of: 1395833 frames (31.651542 seconds), with frame: 3237941290.
         0.000181417 "player.c:931" flush request: sanity check -- flush frame 3239341533 is too far into the future from the first frame 3237941642 -- discarded.
         0.098988750 "player.c:2628" Large positive sync error of: 1395628 frames (31.646893 seconds), with frame: 3237945866.
         0.111417833 "player.c:2628" Large positive sync error of: 1395966 frames (31.654558 seconds), with frame: 3237950442.
         0.000256083 "player.c:931" flush request: sanity check -- flush frame 3239350818 is too far into the future from the first frame 3237950794 -- discarded.
         0.097208709 "player.c:2628" Large positive sync error of: 1399909 frames (31.743968 seconds), with frame: 3237955018.
         0.111587875 "player.c:2628" Large positive sync error of: 1396033 frames (31.656077 seconds), with frame: 3237959594.
         0.000253750 "player.c:931" flush request: sanity check -- flush frame 3239360037 is too far into the future from the first frame 3237959946 -- discarded.
         0.097136667 "player.c:2628" Large positive sync error of: 1399973 frames (31.745420 seconds), with frame: 3237964170.
         0.107624125 "player.c:2628" Large positive sync error of: 1395921 frames (31.653537 seconds), with frame: 3237968746.
         0.000257833 "player.c:931" flush request: sanity check -- flush frame 3239369077 is too far into the future from the first frame 3237969098 -- discarded.
         0.099816500 "player.c:2628" Large positive sync error of: 1399982 frames (31.745624 seconds), with frame: 3237973322.
         0.107671667 "player.c:2628" Large positive sync error of: 1395934 frames (31.653832 seconds), with frame: 3237977898.
         0.000177041 "player.c:931" flush request: sanity check -- flush frame 3239378242 is too far into the future from the first frame 3237978250 -- discarded.
         0.102365084 "player.c:2628" Large positive sync error of: 1400099 frames (31.748277 seconds), with frame: 3237982474.
         0.107346750 "player.c:2628" Large positive sync error of: 1396035 frames (31.656122 seconds), with frame: 3237987050.
         0.000252292 "player.c:931" flush request: sanity check -- flush frame 3239387495 is too far into the future from the first frame 3237987402 -- discarded.
         0.096797750 "player.c:2628" Large positive sync error of: 1399961 frames (31.745147 seconds), with frame: 3237991626.
         0.000265708 "player.c:931" flush request: sanity check -- flush frame 3239395997 is too far into the future from the first frame 3237991978 -- discarded.
         0.111503875 "player.c:2628" Large positive sync error of: 1396092 frames (31.657415 seconds), with frame: 3237996202.
         0.000353208 "player.c:931" flush request: sanity check -- flush frame 3239396704 is too far into the future from the first frame 3237996554 -- discarded.
         0.097162334 "player.c:2628" Large positive sync error of: 1395820 frames (31.651247 seconds), with frame: 3238000778.
         0.000190166 "player.c:931" flush request: sanity check -- flush frame 3239401008 is too far into the future from the first frame 3238001130 -- discarded.
         0.095521417 "player.c:1644" Connection 1: Playback Stopped. Total playing time 00:00:16. Input: 0.00 frames per second.
         7.443155420 "rtsp.c:2976" Connection 1. AP2 Realtime Audio Stream.
         0.224295167 "player.c:1070" Connection 1: Short lead time for first frame 1909985740: -31.692890 seconds. Flushing 0.5 seconds
         0.000380917 "player.c:1119" Gone past starting time for 1909985740 by 31692889641 nanoseconds.
         0.024122000 "player.c:1070" Connection 1: Short lead time for first frame 1909994892: -31.510204 seconds. Flushing 0.5 seconds
         0.000261333 "player.c:1119" Gone past starting time for 1909994892 by 31510204004 nanoseconds.
         0.023025917 "player.c:1070" Connection 1: Short lead time for first frame 1909995948: -31.509644 seconds. Flushing 0.5 seconds
         0.000254041 "player.c:1119" Gone past starting time for 1909995948 by 31509643968 nanoseconds.
         0.022219459 "player.c:1070" Connection 1: Short lead time for first frame 1909997004: -31.508164 seconds. Flushing 0.5 seconds
         0.000251125 "player.c:1119" Gone past starting time for 1909997004 by 31508164015 nanoseconds.
         0.023660875 "player.c:1070" Connection 1: Short lead time for first frame 1909997708: -31.516120 seconds. Flushing 0.5 seconds
         0.000247041 "player.c:1119" Gone past starting time for 1909997708 by 31516119587 nanoseconds.
         0.022417209 "player.c:1070" Connection 1: Short lead time for first frame 1909998764: -31.514861 seconds. Flushing 0.5 seconds
         0.000265708 "player.c:1119" Gone past starting time for 1909998764 by 31514861301 nanoseconds.
         0.023303875 "player.c:1070" Connection 1: Short lead time for first frame 1909999820: -31.514218 seconds. Flushing 0.5 seconds
         0.000367208 "player.c:1119" Gone past starting time for 1909999820 by 31514217555 nanoseconds.
         0.021678125 "player.c:1070" Connection 1: Short lead time for first frame 1910000876: -31.512330 seconds. Flushing 0.5 seconds
         0.000365167 "player.c:1119" Gone past starting time for 1910000876 by 31512330436 nanoseconds.
         0.022894958 "player.c:1070" Connection 1: Short lead time for first frame 1910001932: -31.511667 seconds. Flushing 0.5 seconds
         0.000362250 "player.c:1119" Gone past starting time for 1910001932 by 31511667441 nanoseconds.
         0.022820000 "player.c:1070" Connection 1: Short lead time for first frame 1910002988: -31.510901 seconds. Flushing 0.5 seconds
         0.000359625 "player.c:1119" Gone past starting time for 1910002988 by 31510901488 nanoseconds.
         0.023743125 "player.c:1070" Connection 1: Short lead time for first frame 1910004044: -31.511031 seconds. Flushing 0.5 seconds
         0.000363709 "player.c:1119" Gone past starting time for 1910004044 by 31511031242 nanoseconds.
         0.021938291 "player.c:1070" Connection 1: Short lead time for first frame 1910005100: -31.509401 seconds. Flushing 0.5 seconds
         0.000355250 "player.c:1119" Gone past starting time for 1910005100 by 31509401373 nanoseconds.
         0.023465459 "player.c:1070" Connection 1: Short lead time for first frame 1910006156: -31.509298 seconds. Flushing 0.5 seconds
         0.000523833 "player.c:1119" Gone past starting time for 1910006156 by 31509297503 nanoseconds.
         0.022668042 "player.c:1070" Connection 1: Short lead time for first frame 1910007212: -31.508518 seconds. Flushing 0.5 seconds
         0.000367500 "player.c:1119" Gone past starting time for 1910007212 by 31508517842 nanoseconds.
         0.023496667 "player.c:1070" Connection 1: Short lead time for first frame 1910008268: -31.508448 seconds. Flushing 0.5 seconds
         0.000372750 "player.c:1119" Gone past starting time for 1910008268 by 31508448097 nanoseconds.
         0.022071875 "player.c:1070" Connection 1: Short lead time for first frame 1910008972: -31.514921 seconds. Flushing 0.5 seconds
         0.000361958 "player.c:1119" Gone past starting time for 1910008972 by 31514920545 nanoseconds.
         0.022939583 "player.c:1070" Connection 1: Short lead time for first frame 1910010028: -31.514274 seconds. Flushing 0.5 seconds
         0.000358459 "player.c:1119" Gone past starting time for 1910010028 by 31514274466 nanoseconds.
         0.022846250 "player.c:1070" Connection 1: Short lead time for first frame 1910011084: -31.513542 seconds. Flushing 0.5 seconds
         0.000243541 "player.c:1119" Gone past starting time for 1910011084 by 31513542055 nanoseconds.
         0.022933167 "player.c:1070" Connection 1: Short lead time for first frame 1910012140: -31.512785 seconds. Flushing 0.5 seconds
         0.000247042 "player.c:1119" Gone past starting time for 1910012140 by 31512784560 nanoseconds.
         0.022934916 "player.c:1070" Connection 1: Short lead time for first frame 1910013196: -31.512012 seconds. Flushing 0.5 seconds
         0.000240334 "player.c:1119" Gone past starting time for 1910013196 by 31512012190 nanoseconds.
         0.023093583 "player.c:1070" Connection 1: Short lead time for first frame 1910014252: -31.511393 seconds. Flushing 0.5 seconds
         0.000243250 "player.c:1119" Gone past starting time for 1910014252 by 31511393237 nanoseconds.
         0.022543208 "player.c:1070" Connection 1: Short lead time for first frame 1910015308: -31.510247 seconds. Flushing 0.5 seconds
         0.000246459 "player.c:1119" Gone past starting time for 1910015308 by 31510246658 nanoseconds.
         0.022933750 "player.c:1070" Connection 1: Short lead time for first frame 1910016364: -31.509473 seconds. Flushing 0.5 seconds
         0.000246458 "player.c:1119" Gone past starting time for 1910016364 by 31509472539 nanoseconds.
         0.023022125 "player.c:1070" Connection 1: Short lead time for first frame 1910017420: -31.508810 seconds. Flushing 0.5 seconds
         0.000242083 "player.c:1119" Gone past starting time for 1910017420 by 31508810127 nanoseconds.
         0.023466625 "player.c:1070" Connection 1: Short lead time for first frame 1910018476: -31.508574 seconds. Flushing 0.5 seconds
         0.000244125 "player.c:1119" Gone past starting time for 1910018476 by 31508574133 nanoseconds.
         0.022575584 "player.c:1070" Connection 1: Short lead time for first frame 1910019532: -31.507419 seconds. Flushing 0.5 seconds
         0.000244708 "player.c:1119" Gone past starting time for 1910019532 by 31507419387 nanoseconds.
         0.023352875 "player.c:1070" Connection 1: Short lead time for first frame 1910020236: -31.515062 seconds. Flushing 0.5 seconds
         0.000245292 "player.c:1119" Gone past starting time for 1910020236 by 31515062294 nanoseconds.
         0.022796666 "player.c:1070" Connection 1: Short lead time for first frame 1910021292: -31.514163 seconds. Flushing 0.5 seconds
         0.000251417 "player.c:1119" Gone past starting time for 1910021292 by 31514162757 nanoseconds.
         0.023081625 "player.c:1070" Connection 1: Short lead time for first frame 1910022348: -31.513518 seconds. Flushing 0.5 seconds
         0.000252000 "player.c:1119" Gone past starting time for 1910022348 by 31513517554 nanoseconds.
         0.022987125 "player.c:1070" Connection 1: Short lead time for first frame 1910023404: -31.512850 seconds. Flushing 0.5 seconds
         0.000246167 "player.c:1119" Gone past starting time for 1910023404 by 31512849601 nanoseconds.
         0.022926166 "player.c:1070" Connection 1: Short lead time for first frame 1910024460: -31.512065 seconds. Flushing 0.5 seconds
         0.000249084 "player.c:1119" Gone past starting time for 1910024460 by 31512065273 nanoseconds.
         0.023050416 "player.c:1070" Connection 1: Short lead time for first frame 1910025516: -31.511422 seconds. Flushing 0.5 seconds
         0.000244125 "player.c:1119" Gone past starting time for 1910025516 by 31511422110 nanoseconds.
         0.023002875 "player.c:1070" Connection 1: Short lead time for first frame 1910026572: -31.510681 seconds. Flushing 0.5 seconds
         0.000254334 "player.c:1119" Gone past starting time for 1910026572 by 31510680657 nanoseconds.
         0.022514041 "player.c:1070" Connection 1: Short lead time for first frame 1910027628: -31.509540 seconds. Flushing 0.5 seconds
         0.000254625 "player.c:1119" Gone past starting time for 1910027628 by 31509539621 nanoseconds.
         0.023494625 "player.c:1070" Connection 1: Short lead time for first frame 1910028684: -31.509202 seconds. Flushing 0.5 seconds
         0.000251125 "player.c:1119" Gone past starting time for 1910028684 by 31509202126 nanoseconds.
         0.022439667 "player.c:1070" Connection 1: Short lead time for first frame 1910029740: -31.508075 seconds. Flushing 0.5 seconds
         0.000247042 "player.c:1119" Gone past starting time for 1910029740 by 31508075146 nanoseconds.
         0.047496750 "player.c:1070" Connection 1: Short lead time for first frame 1910031500: -31.515876 seconds. Flushing 0.5 seconds
         0.000261333 "player.c:1119" Gone past starting time for 1910031500 by 31515875808 nanoseconds.
         0.022015292 "player.c:1070" Connection 1: Short lead time for first frame 1910032556: -31.514226 seconds. Flushing 0.5 seconds
         0.000251416 "player.c:1119" Gone past starting time for 1910032556 by 31514226396 nanoseconds.
         0.022943959 "player.c:1070" Connection 1: Short lead time for first frame 1910033612: -31.513482 seconds. Flushing 0.5 seconds
         0.000249666 "player.c:1119" Gone past starting time for 1910033612 by 31513482027 nanoseconds.
         0.022885334 "player.c:1070" Connection 1: Short lead time for first frame 1910034668: -31.512687 seconds. Flushing 0.5 seconds
         0.000248791 "player.c:1119" Gone past starting time for 1910034668 by 31512686614 nanoseconds.
         0.023762375 "player.c:1070" Connection 1: Short lead time for first frame 1910035724: -31.512121 seconds. Flushing 0.5 seconds
         0.000374500 "player.c:1119" Gone past starting time for 1910035724 by 31512121328 nanoseconds.
         0.022887667 "player.c:1070" Connection 1: Short lead time for first frame 1910036780: -31.512048 seconds. Flushing 0.5 seconds
         0.000246167 "player.c:1119" Gone past starting time for 1910036780 by 31512048083 nanoseconds.
         0.023395167 "player.c:1070" Connection 1: Short lead time for first frame 1910037836: -31.511573 seconds. Flushing 0.5 seconds
         0.000252583 "player.c:1119" Gone past starting time for 1910037836 by 31511572922 nanoseconds.
         0.023081042 "player.c:1070" Connection 1: Short lead time for first frame 1910038892: -31.511130 seconds. Flushing 0.5 seconds
         0.000254625 "player.c:1119" Gone past starting time for 1910038892 by 31511129843 nanoseconds.
         0.022991208 "player.c:1070" Connection 1: Short lead time for first frame 1910039948: -31.510168 seconds. Flushing 0.5 seconds
         0.000260750 "player.c:1119" Gone past starting time for 1910039948 by 31510167599 nanoseconds.
         0.022870167 "player.c:1070" Connection 1: Short lead time for first frame 1910041004: -31.509416 seconds. Flushing 0.5 seconds
         0.000251125 "player.c:1119" Gone past starting time for 1910041004 by 31509416229 nanoseconds.
         0.020822083 "player.c:1070" Connection 1: Short lead time for first frame 1910042060: -31.506936 seconds. Flushing 0.5 seconds
         0.000172958 "player.c:1119" Gone past starting time for 1910042060 by 31506936443 nanoseconds.
         0.023126250 "player.c:1070" Connection 1: Short lead time for first frame 1910042764: -31.514275 seconds. Flushing 0.5 seconds
         0.000172375 "player.c:1119" Gone past starting time for 1910042764 by 31514274849 nanoseconds.
         0.023191000 "player.c:1070" Connection 1: Short lead time for first frame 1910043820: -31.513427 seconds. Flushing 0.5 seconds
         0.000181417 "player.c:1119" Gone past starting time for 1910043820 by 31513426937 nanoseconds.
         0.023661750 "player.c:1070" Connection 1: Short lead time for first frame 1910044876: -31.513587 seconds. Flushing 0.5 seconds
         0.000173833 "player.c:1119" Gone past starting time for 1910044876 by 31513587317 nanoseconds.
         0.023396042 "player.c:1070" Connection 1: Short lead time for first frame 1910045932: -31.513218 seconds. Flushing 0.5 seconds
         0.000170042 "player.c:1119" Gone past starting time for 1910045932 by 31513218322 nanoseconds.
         0.021984083 "player.c:1070" Connection 1: Short lead time for first frame 1910046988: -31.511432 seconds. Flushing 0.5 seconds
         0.000168875 "player.c:1119" Gone past starting time for 1910046988 by 31511431536 nanoseconds.
         0.024235167 "player.c:1070" Connection 1: Short lead time for first frame 1910048044: -31.511679 seconds. Flushing 0.5 seconds
         0.000247625 "player.c:1119" Gone past starting time for 1910048044 by 31511678541 nanoseconds.
         0.023386125 "player.c:1070" Connection 1: Short lead time for first frame 1910049100: -31.511379 seconds. Flushing 0.5 seconds
         0.000249666 "player.c:1119" Gone past starting time for 1910049100 by 31511378963 nanoseconds.
         0.023080167 "player.c:1070" Connection 1: Short lead time for first frame 1910050156: -31.510777 seconds. Flushing 0.5 seconds
         0.000249667 "player.c:1119" Gone past starting time for 1910050156 by 31510776634 nanoseconds.
         0.023271500 "player.c:1070" Connection 1: Short lead time for first frame 1910051212: -31.510328 seconds. Flushing 0.5 seconds
         0.000249958 "player.c:1119" Gone past starting time for 1910051212 by 31510327723 nanoseconds.
         0.022546708 "player.c:1070" Connection 1: Short lead time for first frame 1910052268: -31.509198 seconds. Flushing 0.5 seconds
         0.000244709 "player.c:1119" Gone past starting time for 1910052268 by 31509197770 nanoseconds.
         0.022217416 "player.c:1070" Connection 1: Short lead time for first frame 1910053324: -31.507729 seconds. Flushing 0.5 seconds
         0.000249084 "player.c:1119" Gone past starting time for 1910053324 by 31507728608 nanoseconds.
         0.023249916 "player.c:1070" Connection 1: Short lead time for first frame 1910054028: -31.514953 seconds. Flushing 0.5 seconds
         0.000257542 "player.c:1119" Gone past starting time for 1910054028 by 31514952973 nanoseconds.
         0.020836083 "player.c:1070" Connection 1: Short lead time for first frame 1910055084: -31.512375 seconds. Flushing 0.5 seconds
         0.000245584 "player.c:1119" Gone past starting time for 1910055084 by 31512375478 nanoseconds.
         0.023382916 "player.c:1070" Connection 1: Short lead time for first frame 1910056140: -31.512066 seconds. Flushing 0.5 seconds
         0.000245000 "player.c:1119" Gone past starting time for 1910056140 by 31512066274 nanoseconds.
         0.022593084 "player.c:1070" Connection 1: Short lead time for first frame 1910057196: -31.510977 seconds. Flushing 0.5 seconds
         0.000247625 "player.c:1119" Gone past starting time for 1910057196 by 31510976863 nanoseconds.
         0.023513875 "player.c:1070" Connection 1: Short lead time for first frame 1910058252: -31.510777 seconds. Flushing 0.5 seconds
         0.000247916 "player.c:1119" Gone past starting time for 1910058252 by 31510777326 nanoseconds.
         0.022920625 "player.c:1070" Connection 1: Short lead time for first frame 1910059308: -31.509993 seconds. Flushing 0.5 seconds
         0.000245000 "player.c:1119" Gone past starting time for 1910059308 by 31509992707 nanoseconds.
         0.022849459 "player.c:1070" Connection 1: Short lead time for first frame 1910060364: -31.509143 seconds. Flushing 0.5 seconds
         0.000248500 "player.c:1119" Gone past starting time for 1910060364 by 31509142753 nanoseconds.
         0.022907208 "player.c:1070" Connection 1: Short lead time for first frame 1910061420: -31.508361 seconds. Flushing 0.5 seconds
         0.000248500 "player.c:1119" Gone past starting time for 1910061420 by 31508361050 nanoseconds.
         0.023464583 "player.c:1070" Connection 1: Short lead time for first frame 1910062476: -31.507843 seconds. Flushing 0.5 seconds
         0.000252875 "player.c:1119" Gone past starting time for 1910062476 by 31507842722 nanoseconds.
         0.022548167 "player.c:1070" Connection 1: Short lead time for first frame 1910063532: -31.506980 seconds. Flushing 0.5 seconds
         0.000256667 "player.c:1119" Gone past starting time for 1910063532 by 31506979644 nanoseconds.
         0.022918291 "player.c:1070" Connection 1: Short lead time for first frame 1910064588: -31.506224 seconds. Flushing 0.5 seconds
         0.000252292 "player.c:1119" Gone past starting time for 1910064588 by 31506224191 nanoseconds.
         0.022591917 "player.c:1070" Connection 1: Short lead time for first frame 1910065292: -31.513370 seconds. Flushing 0.5 seconds
         0.000249666 "player.c:1119" Gone past starting time for 1910065292 by 31513370388 nanoseconds.
         0.023590292 "player.c:1070" Connection 1: Short lead time for first frame 1910066348: -31.513279 seconds. Flushing 0.5 seconds
         0.000242375 "player.c:1119" Gone past starting time for 1910066348 by 31513279351 nanoseconds.
         0.022144792 "player.c:1070" Connection 1: Short lead time for first frame 1910067404: -31.511680 seconds. Flushing 0.5 seconds
         0.000248500 "player.c:1119" Gone past starting time for 1910067404 by 31511680398 nanoseconds.
         0.023765583 "player.c:1070" Connection 1: Short lead time for first frame 1910068460: -31.511619 seconds. Flushing 0.5 seconds
         0.000252875 "player.c:1119" Gone past starting time for 1910068460 by 31511619112 nanoseconds.
         0.022619917 "player.c:1070" Connection 1: Short lead time for first frame 1910069516: -31.510561 seconds. Flushing 0.5 seconds
         0.000248792 "player.c:1119" Gone past starting time for 1910069516 by 31510561492 nanoseconds.
         0.022604166 "player.c:1070" Connection 1: Short lead time for first frame 1910070572: -31.509478 seconds. Flushing 0.5 seconds
         0.000251709 "player.c:1119" Gone past starting time for 1910070572 by 31509478498 nanoseconds.
         0.023430750 "player.c:1070" Connection 1: Short lead time for first frame 1910071628: -31.509061 seconds. Flushing 0.5 seconds
         0.000253166 "player.c:1119" Gone past starting time for 1910071628 by 31509061085 nanoseconds.
         0.022549334 "player.c:1070" Connection 1: Short lead time for first frame 1910072684: -31.508059 seconds. Flushing 0.5 seconds
         0.000254625 "player.c:1119" Gone past starting time for 1910072684 by 31508058882 nanoseconds.
         0.022654333 "player.c:1070" Connection 1: Short lead time for first frame 1910073740: -31.507040 seconds. Flushing 0.5 seconds
         0.000452958 "player.c:1119" Gone past starting time for 1910073740 by 31507039578 nanoseconds.
         0.023551792 "player.c:1070" Connection 1: Short lead time for first frame 1910074796: -31.507089 seconds. Flushing 0.5 seconds
         0.000260458 "player.c:1119" Gone past starting time for 1910074796 by 31507089417 nanoseconds.
         0.023160084 "player.c:1070" Connection 1: Short lead time for first frame 1910075852: -31.506585 seconds. Flushing 0.5 seconds
         0.000252000 "player.c:1119" Gone past starting time for 1910075852 by 31506585381 nanoseconds.
         0.022576166 "player.c:1070" Connection 1: Short lead time for first frame 1910076556: -31.513338 seconds. Flushing 0.5 seconds
         0.000250834 "player.c:1119" Gone past starting time for 1910076556 by 31513338120 nanoseconds.
         0.022975458 "player.c:1070" Connection 1: Short lead time for first frame 1910077612: -31.512738 seconds. Flushing 0.5 seconds
         0.000248208 "player.c:1119" Gone past starting time for 1910077612 by 31512737834 nanoseconds.
         0.023020667 "player.c:1070" Connection 1: Short lead time for first frame 1910078668: -31.512139 seconds. Flushing 0.5 seconds
         0.001213625 "player.c:1119" Gone past starting time for 1910078668 by 31512139296 nanoseconds.
         0.021963667 "player.c:1070" Connection 1: Short lead time for first frame 1910079724: -31.511243 seconds. Flushing 0.5 seconds
         0.001018500 "player.c:1119" Gone past starting time for 1910079724 by 31511243260 nanoseconds.
         0.022158791 "player.c:1070" Connection 1: Short lead time for first frame 1910080780: -31.510488 seconds. Flushing 0.5 seconds
         0.000930417 "player.c:1119" Gone past starting time for 1910080780 by 31510487807 nanoseconds.
         0.025301208 "player.c:1070" Connection 1: Short lead time for first frame 1910081836: -31.512706 seconds. Flushing 0.5 seconds
         0.001016459 "player.c:1119" Gone past starting time for 1910081836 by 31512706187 nanoseconds.
         0.019269541 "player.c:1070" Connection 1: Short lead time for first frame 1910082892: -31.509119 seconds. Flushing 0.5 seconds
         0.001021417 "player.c:1119" Gone past starting time for 1910082892 by 31509118943 nanoseconds.
         0.021712833 "player.c:1070" Connection 1: Short lead time for first frame 1910083948: -31.508046 seconds. Flushing 0.5 seconds
         0.000959292 "player.c:1119" Gone past starting time for 1910083948 by 31508046447 nanoseconds.
         0.022911000 "player.c:1070" Connection 1: Short lead time for first frame 1910085004: -31.507663 seconds. Flushing 0.5 seconds
         0.000949083 "player.c:1119" Gone past starting time for 1910085004 by 31507663452 nanoseconds.
         0.022032500 "player.c:1070" Connection 1: Short lead time for first frame 1910086060: -31.506855 seconds. Flushing 0.5 seconds
         0.001124667 "player.c:1119" Gone past starting time for 1910086060 by 31506854916 nanoseconds.
         0.021848750 "player.c:1070" Connection 1: Short lead time for first frame 1910087116: -31.505782 seconds. Flushing 0.5 seconds
         0.000253750 "player.c:1119" Gone past starting time for 1910087116 by 31505782130 nanoseconds.
         0.023327500 "player.c:1070" Connection 1: Short lead time for first frame 1910087820: -31.513478 seconds. Flushing 0.5 seconds
         0.000250833 "player.c:1119" Gone past starting time for 1910087820 by 31513477827 nanoseconds.
         0.022953875 "player.c:1070" Connection 1: Short lead time for first frame 1910088876: -31.512733 seconds. Flushing 0.5 seconds
         0.000253167 "player.c:1119" Gone past starting time for 1910088876 by 31512733166 nanoseconds.
         0.022927625 "player.c:1070" Connection 1: Short lead time for first frame 1910089932: -31.511960 seconds. Flushing 0.5 seconds
         0.000247333 "player.c:1119" Gone past starting time for 1910089932 by 31511959629 nanoseconds.
         0.025418750 "player.c:1070" Connection 1: Short lead time for first frame 1910090988: -31.513693 seconds. Flushing 0.5 seconds
         0.000248500 "player.c:1119" Gone past starting time for 1910090988 by 31513692676 nanoseconds.
         0.022737750 "player.c:1070" Connection 1: Short lead time for first frame 1910092044: -31.512769 seconds. Flushing 0.5 seconds
         0.000245584 "player.c:1119" Gone past starting time for 1910092044 by 31512769223 nanoseconds.
         0.020520208 "player.c:1070" Connection 1: Short lead time for first frame 1910093100: -31.509615 seconds. Flushing 0.5 seconds
         0.000245000 "player.c:1119" Gone past starting time for 1910093100 by 31509615103 nanoseconds.
         0.024234875 "player.c:1070" Connection 1: Short lead time for first frame 1910094156: -31.510172 seconds. Flushing 0.5 seconds
         0.000245875 "player.c:1119" Gone past starting time for 1910094156 by 31510172149 nanoseconds.
         0.023163875 "player.c:1070" Connection 1: Short lead time for first frame 1910095212: -31.509600 seconds. Flushing 0.5 seconds
         0.000250542 "player.c:1119" Gone past starting time for 1910095212 by 31509599863 nanoseconds.
         0.021429625 "player.c:1070" Connection 1: Short lead time for first frame 1910096268: -31.507361 seconds. Flushing 0.5 seconds
         0.000245291 "player.c:1119" Gone past starting time for 1910096268 by 31507360701 nanoseconds.
         0.022957084 "player.c:1070" Connection 1: Short lead time for first frame 1910097324: -31.506590 seconds. Flushing 0.5 seconds
         0.000245291 "player.c:1119" Gone past starting time for 1910097324 by 31506589790 nanoseconds.
         0.022872209 "player.c:1070" Connection 1: Short lead time for first frame 1910098380: -31.505770 seconds. Flushing 0.5 seconds
         0.000408041 "player.c:1119" Gone past starting time for 1910098380 by 31505769586 nanoseconds.
         0.023110500 "player.c:1070" Connection 1: Short lead time for first frame 1910099084: -31.513319 seconds. Flushing 0.5 seconds
         0.000245292 "player.c:1119" Gone past starting time for 1910099084 by 31513319160 nanoseconds.
         0.023549750 "player.c:1070" Connection 1: Short lead time for first frame 1910100140: -31.513188 seconds. Flushing 0.5 seconds
         0.000246167 "player.c:1119" Gone past starting time for 1910100140 by 31513187873 nanoseconds.
         0.022004792 "player.c:1070" Connection 1: Short lead time for first frame 1910101196: -31.511476 seconds. Flushing 0.5 seconds
         0.000249666 "player.c:1119" Gone past starting time for 1910101196 by 31511475753 nanoseconds.
         0.023655625 "player.c:1070" Connection 1: Short lead time for first frame 1910102252: -31.511450 seconds. Flushing 0.5 seconds
         0.000247334 "player.c:1119" Gone past starting time for 1910102252 by 31511450050 nanoseconds.
         0.022515208 "player.c:1070" Connection 1: Short lead time for first frame 1910103308: -31.510117 seconds. Flushing 0.5 seconds
         0.000244417 "player.c:1119" Gone past starting time for 1910103308 by 31510117389 nanoseconds.
         0.023908791 "player.c:1070" Connection 1: Short lead time for first frame 1910104364: -31.510465 seconds. Flushing 0.5 seconds
         0.000245875 "player.c:1119" Gone past starting time for 1910104364 by 31510465019 nanoseconds.
         0.022757584 "player.c:1070" Connection 1: Short lead time for first frame 1910105420: -31.509441 seconds. Flushing 0.5 seconds
         0.000251416 "player.c:1119" Gone past starting time for 1910105420 by 31509441232 nanoseconds.
         0.023636084 "player.c:1070" Connection 1: Short lead time for first frame 1910106476: -31.509424 seconds. Flushing 0.5 seconds
         0.000247333 "player.c:1119" Gone past starting time for 1910106476 by 31509423987 nanoseconds.
         0.021585958 "player.c:1070" Connection 1: Short lead time for first frame 1910107532: -31.507320 seconds. Flushing 0.5 seconds
         0.000250834 "player.c:1119" Gone past starting time for 1910107532 by 31507319576 nanoseconds.
         0.023196541 "player.c:1070" Connection 1: Short lead time for first frame 1910108588: -31.506815 seconds. Flushing 0.5 seconds
         0.000400750 "player.c:1119" Gone past starting time for 1910108588 by 31506814956 nanoseconds.
         0.022887375 "player.c:1070" Connection 1: Short lead time for first frame 1910109644: -31.506156 seconds. Flushing 0.5 seconds
         0.000244417 "player.c:1119" Gone past starting time for 1910109644 by 31506155752 nanoseconds.
         0.022346625 "player.c:1070" Connection 1: Short lead time for first frame 1910110348: -31.512773 seconds. Flushing 0.5 seconds
         0.000245000 "player.c:1119" Gone past starting time for 1910110348 by 31512773159 nanoseconds.
         0.023777250 "player.c:1070" Connection 1: Short lead time for first frame 1910111404: -31.512854 seconds. Flushing 0.5 seconds
         0.000431083 "player.c:1119" Gone past starting time for 1910111404 by 31512853622 nanoseconds.
         0.022731917 "player.c:1070" Connection 1: Short lead time for first frame 1910112460: -31.512070 seconds. Flushing 0.5 seconds
         0.000247917 "player.c:1119" Gone past starting time for 1910112460 by 31512070460 nanoseconds.
         0.022687583 "player.c:1070" Connection 1: Short lead time for first frame 1910113516: -31.511071 seconds. Flushing 0.5 seconds
         0.000248208 "player.c:1119" Gone past starting time for 1910113516 by 31511071174 nanoseconds.
         0.022728417 "player.c:1070" Connection 1: Short lead time for first frame 1910114572: -31.510108 seconds. Flushing 0.5 seconds
         0.000243542 "player.c:1119" Gone past starting time for 1910114572 by 31510107763 nanoseconds.
         0.023336833 "player.c:1070" Connection 1: Short lead time for first frame 1910115628: -31.509725 seconds. Flushing 0.5 seconds
         0.000252875 "player.c:1119" Gone past starting time for 1910115628 by 31509724767 nanoseconds.
         0.023009000 "player.c:1070" Connection 1: Short lead time for first frame 1910116684: -31.509039 seconds. Flushing 0.5 seconds
         0.000247917 "player.c:1119" Gone past starting time for 1910116684 by 31509038731 nanoseconds.
         0.022452791 "player.c:1070" Connection 1: Short lead time for first frame 1910117740: -31.507775 seconds. Flushing 0.5 seconds
         0.000249959 "player.c:1119" Gone past starting time for 1910117740 by 31507774971 nanoseconds.
         0.023496958 "player.c:1070" Connection 1: Short lead time for first frame 1910118796: -31.507593 seconds. Flushing 0.5 seconds
         0.000244708 "player.c:1119" Gone past starting time for 1910118796 by 31507592643 nanoseconds.
         0.022898750 "player.c:1070" Connection 1: Short lead time for first frame 1910119852: -31.506792 seconds. Flushing 0.5 seconds
         0.000250250 "player.c:1119" Gone past starting time for 1910119852 by 31506791982 nanoseconds.
         0.022682917 "player.c:1070" Connection 1: Short lead time for first frame 1910120908: -31.505922 seconds. Flushing 0.5 seconds
         0.001155583 "player.c:1119" Gone past starting time for 1910120908 by 31505921903 nanoseconds.
         0.021663542 "player.c:1070" Connection 1: Short lead time for first frame 1910121612: -31.512779 seconds. Flushing 0.5 seconds
         0.001056125 "player.c:1119" Gone past starting time for 1910121612 by 31512779060 nanoseconds.
         0.022617292 "player.c:1070" Connection 1: Short lead time for first frame 1910122668: -31.512530 seconds. Flushing 0.5 seconds
         0.000926041 "player.c:1119" Gone past starting time for 1910122668 by 31512530231 nanoseconds.
         0.021883459 "player.c:1070" Connection 1: Short lead time for first frame 1910123724: -31.511394 seconds. Flushing 0.5 seconds
         0.001054958 "player.c:1119" Gone past starting time for 1910123724 by 31511393570 nanoseconds.
         0.022983917 "player.c:1070" Connection 1: Short lead time for first frame 1910124780: -31.511265 seconds. Flushing 0.5 seconds
         0.000255500 "player.c:1119" Gone past starting time for 1910124780 by 31511265492 nanoseconds.
         0.022883583 "player.c:1070" Connection 1: Short lead time for first frame 1910125836: -31.510497 seconds. Flushing 0.5 seconds
         0.000246750 "player.c:1119" Gone past starting time for 1910125836 by 31510497497 nanoseconds.
         0.022956792 "player.c:1070" Connection 1: Short lead time for first frame 1910126892: -31.509759 seconds. Flushing 0.5 seconds
         0.000245875 "player.c:1119" Gone past starting time for 1910126892 by 31509758668 nanoseconds.
         0.023113416 "player.c:1070" Connection 1: Short lead time for first frame 1910127948: -31.509174 seconds. Flushing 0.5 seconds
         0.000251417 "player.c:1119" Gone past starting time for 1910127948 by 31509173840 nanoseconds.
         0.022899917 "player.c:1070" Connection 1: Short lead time for first frame 1910129004: -31.508390 seconds. Flushing 0.5 seconds
         0.000245875 "player.c:1119" Gone past starting time for 1910129004 by 31508389512 nanoseconds.
         0.022855875 "player.c:1070" Connection 1: Short lead time for first frame 1910130060: -31.507540 seconds. Flushing 0.5 seconds
         0.000248500 "player.c:1119" Gone past starting time for 1910130060 by 31507540142 nanoseconds.
         0.023243792 "player.c:1070" Connection 1: Short lead time for first frame 1910131116: -31.506978 seconds. Flushing 0.5 seconds
         0.001357125 "player.c:1119" Gone past starting time for 1910131116 by 31506978356 nanoseconds.
         0.021593833 "player.c:1070" Connection 1: Short lead time for first frame 1910132172: -31.505898 seconds. Flushing 0.5 seconds
         0.000254333 "player.c:1119" Gone past starting time for 1910132172 by 31505898277 nanoseconds.
         0.023283459 "player.c:1070" Connection 1: Short lead time for first frame 1910132876: -31.513729 seconds. Flushing 0.5 seconds
         0.000249958 "player.c:1119" Gone past starting time for 1910132876 by 31513728725 nanoseconds.
         0.022884750 "player.c:1070" Connection 1: Short lead time for first frame 1910133932: -31.512585 seconds. Flushing 0.5 seconds
         0.000257250 "player.c:1119" Gone past starting time for 1910133932 by 31512584772 nanoseconds.
         0.022375500 "player.c:1070" Connection 1: Short lead time for first frame 1910134988: -31.511550 seconds. Flushing 0.5 seconds
         0.000259583 "player.c:1119" Gone past starting time for 1910134988 by 31511549902 nanoseconds.
         0.022866084 "player.c:1070" Connection 1: Short lead time for first frame 1910136044: -31.510757 seconds. Flushing 0.5 seconds
         0.000255500 "player.c:1119" Gone past starting time for 1910136044 by 31510756824 nanoseconds.
         0.022913625 "player.c:1070" Connection 1: Short lead time for first frame 1910137100: -31.510008 seconds. Flushing 0.5 seconds
         0.000251416 "player.c:1119" Gone past starting time for 1910137100 by 31510008371 nanoseconds.
         0.023403625 "player.c:1070" Connection 1: Short lead time for first frame 1910138156: -31.509699 seconds. Flushing 0.5 seconds
         0.000256667 "player.c:1119" Gone past starting time for 1910138156 by 31509698584 nanoseconds.
         0.023621208 "player.c:1070" Connection 1: Short lead time for first frame 1910139212: -31.509189 seconds. Flushing 0.5 seconds
         0.000252000 "player.c:1119" Gone past starting time for 1910139212 by 31509189006 nanoseconds.
         0.022346625 "player.c:1070" Connection 1: Short lead time for first frame 1910140268: -31.508285 seconds. Flushing 0.5 seconds
         0.000343875 "player.c:1119" Gone past starting time for 1910140268 by 31508285386 nanoseconds.
         0.022824667 "player.c:1070" Connection 1: Short lead time for first frame 1910141324: -31.507522 seconds. Flushing 0.5 seconds
         0.000254625 "player.c:1119" Gone past starting time for 1910141324 by 31507522350 nanoseconds.
         0.022863458 "player.c:1070" Connection 1: Short lead time for first frame 1910142380: -31.506700 seconds. Flushing 0.5 seconds
         0.000249667 "player.c:1119" Gone past starting time for 1910142380 by 31506699521 nanoseconds.
         0.022819417 "player.c:1070" Connection 1: Short lead time for first frame 1910143436: -31.505802 seconds. Flushing 0.5 seconds
         0.000244708 "player.c:1119" Gone past starting time for 1910143436 by 31505802026 nanoseconds.
         0.023116625 "player.c:1070" Connection 1: Short lead time for first frame 1910144140: -31.513192 seconds. Flushing 0.5 seconds
         0.000254042 "player.c:1119" Gone past starting time for 1910144140 by 31513192349 nanoseconds.
         0.023102333 "player.c:1070" Connection 1: Short lead time for first frame 1910145196: -31.512620 seconds. Flushing 0.5 seconds
         0.000249083 "player.c:1119" Gone past starting time for 1910145196 by 31512620354 nanoseconds.
         0.022817959 "player.c:1070" Connection 1: Short lead time for first frame 1910146252: -31.511735 seconds. Flushing 0.5 seconds
         0.000247625 "player.c:1119" Gone past starting time for 1910146252 by 31511735401 nanoseconds.
         0.022871041 "player.c:1070" Connection 1: Short lead time for first frame 1910147308: -31.510903 seconds. Flushing 0.5 seconds
         0.000421167 "player.c:1119" Gone past starting time for 1910147308 by 31510903240 nanoseconds.
         0.007812875 "player.c:1644" Connection 1: Playback Stopped. Total playing time 00:00:04. Input: 0.00 frames per second.
        10.696182297 "rtsp.c:2976" Connection 1. AP2 Realtime Audio Stream.
         0.225265583 "player.c:1070" Connection 1: Short lead time for first frame 3668270509: -31.691677 seconds. Flushing 0.5 seconds
         0.000751625 "player.c:1119" Gone past starting time for 3668270509 by 31691676648 nanoseconds.
         0.021660625 "player.c:1070" Connection 1: Short lead time for first frame 3668279661: -31.507911 seconds. Flushing 0.5 seconds
         0.000480084 "player.c:1119" Gone past starting time for 3668279661 by 31507911261 nanoseconds.
         0.023762666 "player.c:1070" Connection 1: Short lead time for first frame 3668280717: -31.508238 seconds. Flushing 0.5 seconds
         0.000487959 "player.c:1119" Gone past starting time for 3668280717 by 31508237600 nanoseconds.
         0.022879500 "player.c:1070" Connection 1: Short lead time for first frame 3668281773: -31.507649 seconds. Flushing 0.5 seconds
         0.000460833 "player.c:1119" Gone past starting time for 3668281773 by 31507648980 nanoseconds.
         0.023158042 "player.c:1070" Connection 1: Short lead time for first frame 3668282477: -31.515316 seconds. Flushing 0.5 seconds
         0.000462000 "player.c:1119" Gone past starting time for 3668282477 by 31515316094 nanoseconds.
         0.021573416 "player.c:1070" Connection 1: Short lead time for first frame 3668283533: -31.513394 seconds. Flushing 0.5 seconds
         0.000456459 "player.c:1119" Gone past starting time for 3668283533 by 31513394266 nanoseconds.
         0.020368000 "player.c:1070" Connection 1: Short lead time for first frame 3668284589: -31.510982 seconds. Flushing 0.5 seconds
         0.000168583 "player.c:1119" Gone past starting time for 3668284589 by 31510981604 nanoseconds.
         0.024538792 "player.c:1070" Connection 1: Short lead time for first frame 3668285645: -31.511748 seconds. Flushing 0.5 seconds
         0.000169458 "player.c:1119" Gone past starting time for 3668285645 by 31511748068 nanoseconds.
         0.022175417 "player.c:1070" Connection 1: Short lead time for first frame 3668286701: -31.510150 seconds. Flushing 0.5 seconds
         0.000167125 "player.c:1119" Gone past starting time for 3668286701 by 31510150281 nanoseconds.
         0.023282583 "player.c:1070" Connection 1: Short lead time for first frame 3668287757: -31.509645 seconds. Flushing 0.5 seconds
         0.000172375 "player.c:1119" Gone past starting time for 3668287757 by 31509645370 nanoseconds.
         0.097984250 "player.c:2628" Large positive sync error of: 1396720 frames (31.671655 seconds), with frame: 3668291981.
         0.000564667 "player.c:931" flush request: sanity check -- flush frame 3669693111 is too far into the future from the first frame 3668292333 -- discarded.
         0.092445791 "player.c:2628" Large positive sync error of: 1400474 frames (31.756780 seconds), with frame: 3668296557.
         0.112056000 "player.c:2628" Large positive sync error of: 1395030 frames (31.633333 seconds), with frame: 3668301133.
         0.000636709 "player.c:931" flush request: sanity check -- flush frame 3669700573 is too far into the future from the first frame 3668301485 -- discarded.
         0.097531292 "player.c:2628" Large positive sync error of: 1399007 frames (31.723515 seconds), with frame: 3668305709.
         0.110196625 "player.c:2628" Large positive sync error of: 1395051 frames (31.633810 seconds), with frame: 3668310285.
         0.000497000 "player.c:931" flush request: sanity check -- flush frame 3669709746 is too far into the future from the first frame 3668310637 -- discarded.
         0.097668375 "player.c:2628" Large positive sync error of: 1399042 frames (31.724308 seconds), with frame: 3668314861.
         0.000270083 "player.c:931" flush request: sanity check -- flush frame 3669718313 is too far into the future from the first frame 3668315213 -- discarded.
         0.110054583 "player.c:2628" Large positive sync error of: 1395112 frames (31.635193 seconds), with frame: 3668319437.
         0.000297500 "player.c:931" flush request: sanity check -- flush frame 3669718959 is too far into the future from the first frame 3668319789 -- discarded.
         0.098213792 "player.c:2628" Large positive sync error of: 1394879 frames (31.629909 seconds), with frame: 3668324013.
         0.000272708 "player.c:931" flush request: sanity check -- flush frame 3669723302 is too far into the future from the first frame 3668324365 -- discarded.
         0.110525334 "player.c:2628" Large positive sync error of: 1395188 frames (31.636916 seconds), with frame: 3668328589.
         0.000473958 "player.c:931" flush request: sanity check -- flush frame 3669728187 is too far into the future from the first frame 3668328941 -- discarded.
         0.097765500 "player.c:2628" Large positive sync error of: 1394945 frames (31.631406 seconds), with frame: 3668333165.
         0.000275333 "player.c:931" flush request: sanity check -- flush frame 3669732520 is too far into the future from the first frame 3668333517 -- discarded.
         0.097269667 "player.c:2628" Large positive sync error of: 1394671 frames (31.625193 seconds), with frame: 3668337741.
         0.110030375 "player.c:2628" Large positive sync error of: 1394950 frames (31.631519 seconds), with frame: 3668342317.
         0.000187250 "player.c:931" flush request: sanity check -- flush frame 3669741677 is too far into the future from the first frame 3668342669 -- discarded.
         0.095127375 "player.c:2628" Large positive sync error of: 1398798 frames (31.718776 seconds), with frame: 3668346893.
         0.114445625 "player.c:2628" Large positive sync error of: 1395046 frames (31.633696 seconds), with frame: 3668351469.
         0.000260750 "player.c:931" flush request: sanity check -- flush frame 3669750925 is too far into the future from the first frame 3668351821 -- discarded.
         0.097446709 "player.c:2628" Large positive sync error of: 1398999 frames (31.723333 seconds), with frame: 3668356045.
         0.106549625 "player.c:2628" Large positive sync error of: 1394903 frames (31.630454 seconds), with frame: 3668360621.
         0.000293416 "player.c:931" flush request: sanity check -- flush frame 3669759934 is too far into the future from the first frame 3668360973 -- discarded.
         0.101951792 "player.c:2628" Large positive sync error of: 1399055 frames (31.724603 seconds), with frame: 3668365197.
         0.110020459 "player.c:2628" Large positive sync error of: 1395113 frames (31.635215 seconds), with frame: 3668369773.
         0.000310041 "player.c:931" flush request: sanity check -- flush frame 3669769296 is too far into the future from the first frame 3668370125 -- discarded.
         0.101012334 "player.c:2628" Large positive sync error of: 1399224 frames (31.728435 seconds), with frame: 3668374349.
         0.105230125 "player.c:2628" Large positive sync error of: 1395067 frames (31.634172 seconds), with frame: 3668378925.
         0.000451500 "player.c:931" flush request: sanity check -- flush frame 3669778402 is too far into the future from the first frame 3668379277 -- discarded.
         0.094415708 "player.c:2628" Large positive sync error of: 1398899 frames (31.721066 seconds), with frame: 3668383501.
         0.113994708 "player.c:2628" Large positive sync error of: 1395126 frames (31.635510 seconds), with frame: 3668388077.
         0.000438959 "player.c:931" flush request: sanity check -- flush frame 3669787613 is too far into the future from the first frame 3668388429 -- discarded.
         0.096839166 "player.c:2628" Large positive sync error of: 1399061 frames (31.724739 seconds), with frame: 3668392653.
         0.000267750 "player.c:931" flush request: sanity check -- flush frame 3669796124 is too far into the future from the first frame 3668393005 -- discarded.
         0.111417542 "player.c:2628" Large positive sync error of: 1395188 frames (31.636916 seconds), with frame: 3668397229.
         0.000438667 "player.c:931" flush request: sanity check -- flush frame 3669796827 is too far into the future from the first frame 3668397581 -- discarded.
         0.097921833 "player.c:2628" Large positive sync error of: 1394951 frames (31.631542 seconds), with frame: 3668401805.
         0.000274167 "player.c:931" flush request: sanity check -- flush frame 3669801166 is too far into the future from the first frame 3668402157 -- discarded.
         0.110406625 "player.c:2628" Large positive sync error of: 1395257 frames (31.638481 seconds), with frame: 3668406381.
         0.000304792 "player.c:931" flush request: sanity check -- flush frame 3669806048 is too far into the future from the first frame 3668406733 -- discarded.
         0.094737125 "player.c:2628" Large positive sync error of: 1394873 frames (31.629773 seconds), with frame: 3668410957.
         0.000198333 "player.c:931" flush request: sanity check -- flush frame 3669810240 is too far into the future from the first frame 3668411309 -- discarded.
         0.095958333 "player.c:2628" Large positive sync error of: 1394537 frames (31.622154 seconds), with frame: 3668415533.
         0.114815167 "player.c:2628" Large positive sync error of: 1395021 frames (31.633129 seconds), with frame: 3668420109.
         0.000375667 "player.c:931" flush request: sanity check -- flush frame 3669819540 is too far into the future from the first frame 3668420461 -- discarded.
         0.096588333 "player.c:2628" Large positive sync error of: 1398944 frames (31.722086 seconds), with frame: 3668424685.
         0.109916042 "player.c:2628" Large positive sync error of: 1394997 frames (31.632585 seconds), with frame: 3668429261.
         0.000187250 "player.c:931" flush request: sanity check -- flush frame 3669828668 is too far into the future from the first frame 3668429613 -- discarded.
         0.099429750 "player.c:2628" Large positive sync error of: 1399032 frames (31.724082 seconds), with frame: 3668433837.
         0.106434708 "player.c:2628" Large positive sync error of: 1394930 frames (31.631066 seconds), with frame: 3668438413.
         0.000300125 "player.c:931" flush request: sanity check -- flush frame 3669837753 is too far into the future from the first frame 3668438765 -- discarded.
         0.100059750 "player.c:2628" Large positive sync error of: 1399000 frames (31.723356 seconds), with frame: 3668442989.
         0.108934292 "player.c:2628" Large positive sync error of: 1395006 frames (31.632789 seconds), with frame: 3668447565.
         0.000435458 "player.c:931" flush request: sanity check -- flush frame 3669846981 is too far into the future from the first frame 3668447917 -- discarded.
         0.098623875 "player.c:2628" Large positive sync error of: 1399023 frames (31.723878 seconds), with frame: 3668452141.
         0.110036792 "player.c:2628" Large positive sync error of: 1395075 frames (31.634354 seconds), with frame: 3668456717.
         0.000433417 "player.c:931" flush request: sanity check -- flush frame 3669856202 is too far into the future from the first frame 3668457069 -- discarded.
         0.094709417 "player.c:2628" Large positive sync error of: 1398919 frames (31.721519 seconds), with frame: 3668461293.
         0.000191916 "player.c:931" flush request: sanity check -- flush frame 3669864622 is too far into the future from the first frame 3668461645 -- discarded.
         0.113820875 "player.c:2628" Large positive sync error of: 1395147 frames (31.635986 seconds), with frame: 3668465869.
         0.000571959 "player.c:931" flush request: sanity check -- flush frame 3669865426 is too far into the future from the first frame 3668466221 -- discarded.
         0.094647875 "player.c:2628" Large positive sync error of: 1394774 frames (31.627528 seconds), with frame: 3668470445.
         0.000191916 "player.c:931" flush request: sanity check -- flush frame 3669869629 is too far into the future from the first frame 3668470797 -- discarded.
         0.112429334 "player.c:2628" Large positive sync error of: 1395161 frames (31.636304 seconds), with frame: 3668475021.
         0.000275916 "player.c:931" flush request: sanity check -- flush frame 3669874592 is too far into the future from the first frame 3668475373 -- discarded.
         0.097344334 "player.c:2628" Large positive sync error of: 1394890 frames (31.630159 seconds), with frame: 3668479597.
         0.000274458 "player.c:931" flush request: sanity check -- flush frame 3669878897 is too far into the future from the first frame 3668479949 -- discarded.
         0.093131500 "player.c:2628" Large positive sync error of: 1394436 frames (31.619864 seconds), with frame: 3668484173.
         0.115333459 "player.c:2628" Large positive sync error of: 1394945 frames (31.631406 seconds), with frame: 3668488749.
         0.000263666 "player.c:931" flush request: sanity check -- flush frame 3669888104 is too far into the future from the first frame 3668489101 -- discarded.
         0.096817584 "player.c:2628" Large positive sync error of: 1398870 frames (31.720408 seconds), with frame: 3668493325.
         0.109398625 "player.c:2628" Large positive sync error of: 1394900 frames (31.630385 seconds), with frame: 3668497901.
         0.000183458 "player.c:931" flush request: sanity check -- flush frame 3669897211 is too far into the future from the first frame 3668498253 -- discarded.
         0.099927042 "player.c:2628" Large positive sync error of: 1398957 frames (31.722381 seconds), with frame: 3668502477.
         0.106037750 "player.c:2628" Large positive sync error of: 1394839 frames (31.629002 seconds), with frame: 3668507053.
         0.000181416 "player.c:931" flush request: sanity check -- flush frame 3669906302 is too far into the future from the first frame 3668507405 -- discarded.
         0.098588584 "player.c:2628" Large positive sync error of: 1398841 frames (31.719751 seconds), with frame: 3668511629.
         0.110858416 "player.c:2628" Large positive sync error of: 1394930 frames (31.631066 seconds), with frame: 3668516205.
         0.000266584 "player.c:931" flush request: sanity check -- flush frame 3669915545 is too far into the future from the first frame 3668516557 -- discarded.
         0.098133000 "player.c:2628" Large positive sync error of: 1398917 frames (31.721474 seconds), with frame: 3668520781.
         0.110007333 "player.c:2628" Large positive sync error of: 1394968 frames (31.631927 seconds), with frame: 3668525357.
         0.000259292 "player.c:931" flush request: sanity check -- flush frame 3669924735 is too far into the future from the first frame 3668525709 -- discarded.
         0.096985583 "player.c:2628" Large positive sync error of: 1398902 frames (31.721134 seconds), with frame: 3668529933.
         0.112253167 "player.c:2628" Large positive sync error of: 1395058 frames (31.633968 seconds), with frame: 3668534509.
         0.000179667 "player.c:931" flush request: sanity check -- flush frame 3669933977 is too far into the future from the first frame 3668534861 -- discarded.
         0.096641416 "player.c:2628" Large positive sync error of: 1398970 frames (31.722676 seconds), with frame: 3668539085.
         0.000269500 "player.c:931" flush request: sanity check -- flush frame 3669942465 is too far into the future from the first frame 3668539437 -- discarded.
         0.111696084 "player.c:2628" Large positive sync error of: 1395109 frames (31.635125 seconds), with frame: 3668543661.
         0.000262500 "player.c:931" flush request: sanity check -- flush frame 3669943180 is too far into the future from the first frame 3668544013 -- discarded.
         0.096980916 "player.c:2628" Large positive sync error of: 1394822 frames (31.628617 seconds), with frame: 3668548237.
         0.000263959 "player.c:931" flush request: sanity check -- flush frame 3669947469 is too far into the future from the first frame 3668548589 -- discarded.
         0.112386167 "player.c:2628" Large positive sync error of: 1395214 frames (31.637506 seconds), with frame: 3668552813.
         0.000264833 "player.c:931" flush request: sanity check -- flush frame 3669952437 is too far into the future from the first frame 3668553165 -- discarded.
         0.096639375 "player.c:2628" Large positive sync error of: 1394912 frames (31.630658 seconds), with frame: 3668557389.
         0.000265417 "player.c:931" flush request: sanity check -- flush frame 3669956711 is too far into the future from the first frame 3668557741 -- discarded.
         0.096488000 "player.c:2628" Large positive sync error of: 1394604 frames (31.623673 seconds), with frame: 3668561965.
         0.064980125 "player.c:1644" Connection 1: Playback Stopped. Total playing time 00:00:06. Input: 0.00 frames per second.

@mikebrady this is the most relevant log I got regarding this issue, I think.

mikebrady commented 2 years ago

Many thanks.

Gabi10017 commented 2 years ago

I've got a workaround, until this gets fixed.

Set

resync_threshold_in_seconds=0;

In your configuration file. It also should fix stuttering on some networks.

L.E: Unrelated but, I also set

drift_tolerance_in_seconds=10;

to fix stuttering.

mikebrady commented 2 years ago

Thanks for these reports. I have pushed an update to the development branch which may address part of this problem, and if you got a chance tor try it, that would be great.

I think there may be some other issues with some of your setups, but let's see if this helps.

handcc commented 2 years ago

No luck for me. I tried connecting three times and this is what I see

 shairport-sync -vu --statistics
         0.000713481 "shairport.c:1892" Started in Airplay 2 mode with features 0x405c4a00,0x1c340 on device "dc:a6:32:a3:9c:1b"!
         0.000178296 "shairport.c:1934" software version: "4.1-dev-172-g16f5c7b7-AirPlay2-alac-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
         0.000045630 "shairport.c:1940" log verbosity is 1.
         0.000050685 "audio_alsa.c:1018" alsa: alsa_maximum_stall_time of 0.200000 sec.
         0.000062389 "audio_alsa.c:1310" alsa: disable_standby_mode is "never".
         0.000041407 "audio_alsa.c:1312" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
         0.000041297 "audio_alsa.c:1314" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
         0.000046852 "audio_alsa.c:1353" alsa: output device name is "hw:1".
         0.000238074 "shairport.c:1969" libsodium initialised.
         0.000062314 "shairport.c:2019" disable resend requests is off.
         0.000045426 "shairport.c:2023" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000042482 "shairport.c:2024" statistics_requester status is 1.
         0.000039389 "shairport.c:2029" rtsp listening port is 7000.
         0.000039333 "shairport.c:2030" udp base port is 6001.
         0.000038889 "shairport.c:2031" udp port range is 10.
         0.000038667 "shairport.c:2032" player name is "Raspberrypi".
         0.000038666 "shairport.c:2033" backend is "alsa".
         0.000042037 "shairport.c:2034" run_this_before_play_begins action is "(null)".
         0.000033537 "shairport.c:2035" run_this_after_play_ends action is "(null)".
         0.000015074 "shairport.c:2036" wait-cmd status is 0.
         0.000014112 "shairport.c:2037" run_this_before_play_begins may return output is 0.
         0.000037351 "shairport.c:2039" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000015797 "shairport.c:2041" run_this_before_entering_active_state action is  "(null)".
         0.000014389 "shairport.c:2043" run_this_after_exiting_active_state action is  "(null)".
         0.000014444 "shairport.c:2044" active_state_timeout is  10.000000 seconds.
         0.000053130 "shairport.c:2045" mdns backend "(null)".
         0.000017407 "shairport.c:2050" interpolation setting is "auto".
         0.000035333 "shairport.c:2051" interpolation soxr_delay_threshold is 30.
         0.000042075 "shairport.c:2052" resync time is 0.050000 seconds.
         0.000035259 "shairport.c:2053" allow a session to be interrupted: 0.
         0.000016463 "shairport.c:2054" busy timeout time is 0.
         0.000014963 "shairport.c:2055" drift tolerance is 0.001995 seconds.
         0.000015703 "shairport.c:2056" password is "(null)".
         0.000014926 "shairport.c:2057" ignore_volume_control is 0.
         0.000015352 "shairport.c:2061" volume_max_db is not set
         0.000023722 "shairport.c:2063" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000016130 "shairport.c:2067" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000035889 "shairport.c:2069" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000039889 "shairport.c:2070" disable_synchronization is 0.
         0.000038426 "shairport.c:2071" use_mmap_if_available is 1.
         0.000038740 "shairport.c:2073" output_format automatic selection is enabled.
         0.000043834 "shairport.c:2077" output_rate automatic selection is enabled.
         0.000042778 "shairport.c:2081" audio backend desired buffer length is 0.200000 seconds.
         0.000039851 "shairport.c:2083" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
         0.000040093 "shairport.c:2084" audio backend latency offset is 0.000000 seconds.
         0.000039815 "shairport.c:2086" audio backend silence lead-in time is "auto".
         0.000038648 "shairport.c:2090" zeroconf regtype is "_raop._tcp".
         0.000038481 "shairport.c:2091" decoders_supported field is 3.
         0.000038389 "shairport.c:2092" use_apple_decoder is 1.
         0.000038463 "shairport.c:2093" alsa_use_hardware_mute is 0.
         0.000038482 "shairport.c:2097" no special mdns service interface was requested.
         0.000062926 "shairport.c:2101" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000044889 "shairport.c:2130" loudness is 0.
         0.000038703 "shairport.c:2131" loudness reference level is -20.000000
         1.500475111 "shairport.c:224" "soxr" interpolation has been chosen.
        40.115664050 "rtsp.c:2646" Connection 1: AP2 PTP connection from fe80::47a:ef24:a10a:b87:49571 to self at fe80::132a:3d2b:f9a0:3f9b:7000.
        15.323887824 "rtsp.c:2668" Connection 2: Remote Control connection from fe80::47a:ef24:a10a:b87:49573 to self at fe80::132a:3d2b:f9a0:3f9b:7000.
        18.900754766 "rtsp.c:2646" Connection 3: AP2 PTP connection from fe80::47a:ef24:a10a:b87:49576 to self at fe80::132a:3d2b:f9a0:3f9b:7000.
        11.895159956 "rtsp.c:2668" Connection 4: Remote Control connection from fe80::47a:ef24:a10a:b87:49578 to self at fe80::132a:3d2b:f9a0:3f9b:7000.
         4.490474183 "rtsp.c:2646" Connection 5: AP2 PTP connection from fe80::47a:ef24:a10a:b87:49581 to self at fe80::132a:3d2b:f9a0:3f9b:7000.
        12.683318696 "rtsp.c:2668" Connection 6: Remote Control connection from fe80::47a:ef24:a10a:b87:49584 to self at fe80::132a:3d2b:f9a0:3f9b:7000.
Gabi10017 commented 2 years ago

Hi! If I still raised this issue, I thought why not come and present you a similar one also. The issue basically is that playing YouTube videos while connected to the AP Receiver (had this issue on both AP1 and AP2) results in a 'Something went bad, Please try again' message. Also, after getting this you'll be unable to play anything else as the Receiver hangs. I'll also attach a video from my iPhone down there. The logs have a tag, so that you can distinguish between the errors caused by YouTube, and the others that occur when trying to play anything afterwards.

The video from my iPhone: https://drive.google.com/file/d/1etC7L4ICFHoAhxvJeRbg5UG2d_rHpQiI/view?usp=sharing (was too big, so I couldn't upload it directly). IMG_1158 Screenshot from the YouTube app (this is what it shows if you connect to a shairport receiver and try to play something)

     0.001486917 "shairport.c:1340" default metadata_pipename is "/tmp/shairport-sync-metadata".
     0.000141750 "shairport.c:1892" Started in Airplay 2 mode with features 0x405fca00,0x1c340 on device "2a:8b:b4:4e:f5:4f"!
     0.000102667 "shairport.c:1934" software version: "4.1-dev-172-g16f5c7b7-AirPlay2-alac-OpenSSL-Avahi-pa-soxr-metadata-sysconfdir:/usr/local/etc"
     0.000063875 "shairport.c:1940" log verbosity is 1.
     0.002096500 "shairport.c:1969" libsodium initialised.
     0.000069125 "shairport.c:2019" disable resend requests is off.
     0.000033833 "shairport.c:2023" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
     0.000031792 "shairport.c:2024" statistics_requester status is 1.
     0.000028291 "shairport.c:2029" rtsp listening port is 7000.
     0.000028292 "shairport.c:2030" udp base port is 6001.
     0.000027417 "shairport.c:2031" udp port range is 10.
     0.000027125 "shairport.c:2032" player name is "Living Audio System".
     0.000035583 "shairport.c:2033" backend is "pa".
     0.000028583 "shairport.c:2034" run_this_before_play_begins action is "(null)".
     0.000030334 "shairport.c:2035" run_this_after_play_ends action is "(null)".
     0.000030333 "shairport.c:2036" wait-cmd status is 0.
     0.000027417 "shairport.c:2037" run_this_before_play_begins may return output is 0.
     0.000034708 "shairport.c:2039" run_this_if_an_unfixable_error_is_detected action is "(null)".
     0.000028875 "shairport.c:2041" run_this_before_entering_active_state action is  "(null)".
     0.000027708 "shairport.c:2043" run_this_after_exiting_active_state action is  "(null)".
     0.000028292 "shairport.c:2044" active_state_timeout is  10.000000 seconds.
     0.000030042 "shairport.c:2045" mdns backend "(null)".
     0.000032958 "shairport.c:2050" interpolation setting is "soxr".
     0.000048708 "shairport.c:2051" interpolation soxr_delay_threshold is 30.
     0.000022459 "shairport.c:2052" resync time is 0.000000 seconds.
     0.000012250 "shairport.c:2053" allow a session to be interrupted: 0.
     0.000009916 "shairport.c:2054" busy timeout time is 0.
     0.000009625 "shairport.c:2055" drift tolerance is 10.000000 seconds.
     0.000010209 "shairport.c:2056" password is "(null)".
     0.000009041 "shairport.c:2057" ignore_volume_control is 0.
     0.000009042 "shairport.c:2061" volume_max_db is not set
     0.000008458 "shairport.c:2063" volume range in dB (zero means use the range specified by the mixer): 38.
     0.000009917 "shairport.c:2067" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
     0.000009917 "shairport.c:2069" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
     0.000009625 "shairport.c:2070" disable_synchronization is 0.
     0.000008750 "shairport.c:2071" use_mmap_if_available is 1.
     0.000008750 "shairport.c:2073" output_format automatic selection is enabled.
     0.000009041 "shairport.c:2077" output_rate automatic selection is enabled.
     0.000009334 "shairport.c:2081" audio backend desired buffer length is 0.350000 seconds.
     0.000010500 "shairport.c:2083" audio_backend_buffer_interpolation_threshold_in_seconds is 0.020000 seconds.
     0.000010208 "shairport.c:2084" audio backend latency offset is -1.750000 seconds.
     0.000010208 "shairport.c:2086" audio backend silence lead-in time is "auto".
     0.000009042 "shairport.c:2090" zeroconf regtype is "_raop._tcp".
     0.000009625 "shairport.c:2091" decoders_supported field is 3.
     0.000008750 "shairport.c:2092" use_apple_decoder is 1.
     0.000008750 "shairport.c:2093" alsa_use_hardware_mute is 0.
     0.000009042 "shairport.c:2097" no special mdns service interface was requested.
     0.000031791 "shairport.c:2101" configuration file name "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
     0.000014292 "shairport.c:2107" metadata enabled is 1.
     0.000011667 "shairport.c:2108" metadata pipename is "/tmp/shairport-sync-metadata".
     0.000011083 "shairport.c:2110" metadata socket address is "(null)" port 0.
     0.000010500 "shairport.c:2111" metadata socket packet size is "500".
     0.000009625 "shairport.c:2112" get-coverart is 1.
     0.000009333 "shairport.c:2130" loudness is 0.
     0.000008750 "shairport.c:2131" loudness reference level is -20.000000
     0.000134167 "rtsp.c:3823" metadata pipe name is "/tmp/shairport-sync-metadata".
    25.693100846 "rtsp.c:2646" Connection 1: AP2 PTP connection from 192.168.1.2:54133 to self at 192.168.1.97:7000.
     0.251204041 "rtsp.c:3030" Connection 1. AP2 Buffered Audio Stream.
     0.101311751 "rtsp.c:2976" Connection 1. AP2 Realtime Audio Stream.
     0.004869375 "rtp.c:1668" Discarding early timing packet.
     0.000071750 "rtp.c:1765" AP2 Control Receiver -- error 0 receiving a packet. --YouTube error (from this line, above)
     1.728945459 "rtp.c:1678" First packet is a not a sentinel packet!
     0.000067666 "rtp.c:1216" Connection 1: Set Anchor Clock: 84ab1a7eeeee0008.
     0.000712834 "rtp.c:1325" Connection 1: Clock 84ab1a7eeeee0008 is now the new anchor clock and master clock. History: 1865.906751 milliseconds.
     0.000183750 "rtp.c:1408" Connection 1: NQPTP new master clock 84ab1a7eeeee0008.
     5.737961252 "rtsp.c:2668" Connection 2: Remote Control connection from 192.168.1.2:54136 to self at 192.168.1.97:7000.
    10.370036505 "rtsp.c:2646" Connection 3: AP2 PTP connection from 192.168.1.2:54146 to self at 192.168.1.97:7000.
     3.004902627 "rtsp.c:598" Connection 3: failed to get player lock after waiting. --Trying to stream something (Spotify in this case, but its the same issue with Apple Music) afterwards (errors are from this line, until the YT error tag).
Gabi10017 commented 2 years ago

No luck for me. I tried connecting three times and this is what I see

shairport-sync -vu --statistics 0.000713481 "shairport.c:1892" Started in Airplay 2 mode with features 0x405c4a00,0x1c340 on device "dc:a6:32:a3:9c:1b"! 0.000178296 "shairport.c:1934" software version: "4.1-dev-172-g16f5c7b7-AirPlay2-alac-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc" 0.000045630 "shairport.c:1940" log verbosity is 1. 0.000050685 "audio_alsa.c:1018" alsa: alsa_maximum_stall_time of 0.200000 sec. 0.000062389 "audio_alsa.c:1310" alsa: disable_standby_mode is "never". 0.000041407 "audio_alsa.c:1312" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds. 0.000041297 "audio_alsa.c:1314" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds. 0.000046852 "audio_alsa.c:1353" alsa: output device name is "hw:1". 0.000238074 "shairport.c:1969" libsodium initialised. 0.000062314 "shairport.c:2019" disable resend requests is off. 0.000045426 "shairport.c:2023" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately. 0.000042482 "shairport.c:2024" statistics_requester status is 1. 0.000039389 "shairport.c:2029" rtsp listening port is 7000. 0.000039333 "shairport.c:2030" udp base port is 6001. 0.000038889 "shairport.c:2031" udp port range is 10. 0.000038667 "shairport.c:2032" player name is "Raspberrypi". 0.000038666 "shairport.c:2033" backend is "alsa". 0.000042037 "shairport.c:2034" run_this_before_play_begins action is "(null)". 0.000033537 "shairport.c:2035" run_this_after_play_ends action is "(null)". 0.000015074 "shairport.c:2036" wait-cmd status is 0. 0.000014112 "shairport.c:2037" run_this_before_play_begins may return output is 0. 0.000037351 "shairport.c:2039" run_this_if_an_unfixable_error_is_detected action is "(null)". 0.000015797 "shairport.c:2041" run_this_before_entering_active_state action is "(null)". 0.000014389 "shairport.c:2043" run_this_after_exiting_active_state action is "(null)". 0.000014444 "shairport.c:2044" active_state_timeout is 10.000000 seconds. 0.000053130 "shairport.c:2045" mdns backend "(null)". 0.000017407 "shairport.c:2050" interpolation setting is "auto". 0.000035333 "shairport.c:2051" interpolation soxr_delay_threshold is 30. 0.000042075 "shairport.c:2052" resync time is 0.050000 seconds. 0.000035259 "shairport.c:2053" allow a session to be interrupted: 0. 0.000016463 "shairport.c:2054" busy timeout time is 0. 0.000014963 "shairport.c:2055" drift tolerance is 0.001995 seconds. 0.000015703 "shairport.c:2056" password is "(null)". 0.000014926 "shairport.c:2057" ignore_volume_control is 0. 0.000015352 "shairport.c:2061" volume_max_db is not set 0.000023722 "shairport.c:2063" volume range in dB (zero means use the range specified by the mixer): 0. 0.000016130 "shairport.c:2067" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0. 0.000035889 "shairport.c:2069" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right). 0.000039889 "shairport.c:2070" disable_synchronization is 0. 0.000038426 "shairport.c:2071" use_mmap_if_available is 1. 0.000038740 "shairport.c:2073" output_format automatic selection is enabled. 0.000043834 "shairport.c:2077" output_rate automatic selection is enabled. 0.000042778 "shairport.c:2081" audio backend desired buffer length is 0.200000 seconds. 0.000039851 "shairport.c:2083" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds. 0.000040093 "shairport.c:2084" audio backend latency offset is 0.000000 seconds. 0.000039815 "shairport.c:2086" audio backend silence lead-in time is "auto". 0.000038648 "shairport.c:2090" zeroconf regtype is "_raop._tcp". 0.000038481 "shairport.c:2091" decoders_supported field is 3. 0.000038389 "shairport.c:2092" use_apple_decoder is 1. 0.000038463 "shairport.c:2093" alsa_use_hardware_mute is 0. 0.000038482 "shairport.c:2097" no special mdns service interface was requested. 0.000062926 "shairport.c:2101" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf". 0.000044889 "shairport.c:2130" loudness is 0. 0.000038703 "shairport.c:2131" loudness reference level is -20.000000 1.500475111 "shairport.c:224" "soxr" interpolation has been chosen. 40.115664050 "rtsp.c:2646" Connection 1: AP2 PTP connection from fe80::47a:ef24:a10a:b87:49571 to self at fe80::132a:3d2b:f9a0:3f9b:7000. 15.323887824 "rtsp.c:2668" Connection 2: Remote Control connection from fe80::47a:ef24:a10a:b87:49573 to self at fe80::132a:3d2b:f9a0:3f9b:7000. 18.900754766 "rtsp.c:2646" Connection 3: AP2 PTP connection from fe80::47a:ef24:a10a:b87:49576 to self at fe80::132a:3d2b:f9a0:3f9b:7000. 11.895159956 "rtsp.c:2668" Connection 4: Remote Control connection from fe80::47a:ef24:a10a:b87:49578 to self at fe80::132a:3d2b:f9a0:3f9b:7000. 4.490474183 "rtsp.c:2646" Connection 5: AP2 PTP connection from fe80::47a:ef24:a10a:b87:49581 to self at fe80::132a:3d2b:f9a0:3f9b:7000. 12.683318696 "rtsp.c:2668" Connection 6: Remote Control connection from fe80::47a:ef24:a10a:b87:49584 to self at fe80::132a:3d2b:f9a0:3f9b:7000.

Hi! The last update completely fixed the issue for me. Might be related with the use of ipv6 in your case? 

     0.001533000 "shairport.c:1340" default metadata_pipename is "/tmp/shairport-sync-metadata".
     0.000093334 "shairport.c:1892" Started in Airplay 2 mode with features 0x405fca00,0x1c340 on device "2a:8b:b4:4e:f5:4f"!
     0.000082541 "shairport.c:1934" software version: "4.1-dev-172-g16f5c7b7-AirPlay2-alac-OpenSSL-Avahi-pa-soxr-metadata-sysconfdir:/usr/local/etc"
     0.000015459 "shairport.c:1940" log verbosity is 1.
     0.002410333 "shairport.c:1969" libsodium initialised.
     0.000037333 "shairport.c:2019" disable resend requests is off.
     0.000012834 "shairport.c:2023" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
     0.000013708 "shairport.c:2024" statistics_requester status is 1.
     0.000009625 "shairport.c:2029" rtsp listening port is 7000.
     0.000009333 "shairport.c:2030" udp base port is 6001.
     0.000009042 "shairport.c:2031" udp port range is 10.
     0.000008750 "shairport.c:2032" player name is "Living Audio System".
     0.000009042 "shairport.c:2033" backend is "pa".
     0.000008750 "shairport.c:2034" run_this_before_play_begins action is "(null)".
     0.000009041 "shairport.c:2035" run_this_after_play_ends action is "(null)".
     0.000008750 "shairport.c:2036" wait-cmd status is 0.
     0.000008750 "shairport.c:2037" run_this_before_play_begins may return output is 0.
     0.000009334 "shairport.c:2039" run_this_if_an_unfixable_error_is_detected action is "(null)".
     0.000009041 "shairport.c:2041" run_this_before_entering_active_state action is  "(null)".
     0.000009334 "shairport.c:2043" run_this_after_exiting_active_state action is  "(null)".
     0.000009041 "shairport.c:2044" active_state_timeout is  10.000000 seconds.
     0.000010209 "shairport.c:2045" mdns backend "(null)".
     0.000009333 "shairport.c:2050" interpolation setting is "soxr".
     0.000009042 "shairport.c:2051" interpolation soxr_delay_threshold is 30.
     0.000008750 "shairport.c:2052" resync time is 0.000000 seconds.
     0.000009625 "shairport.c:2053" allow a session to be interrupted: 0.
     0.000009041 "shairport.c:2054" busy timeout time is 0.
     0.000009042 "shairport.c:2055" drift tolerance is 10.000000 seconds.
     0.000010208 "shairport.c:2056" password is "(null)".
     0.000009042 "shairport.c:2057" ignore_volume_control is 0.
     0.000009917 "shairport.c:2061" volume_max_db is not set
     0.000008458 "shairport.c:2063" volume range in dB (zero means use the range specified by the mixer): 38.
     0.000009917 "shairport.c:2067" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
     0.000010208 "shairport.c:2069" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
     0.000009333 "shairport.c:2070" disable_synchronization is 0.
     0.000008750 "shairport.c:2071" use_mmap_if_available is 1.
     0.000008750 "shairport.c:2073" output_format automatic selection is enabled.
     0.000008750 "shairport.c:2077" output_rate automatic selection is enabled.
     0.000008750 "shairport.c:2081" audio backend desired buffer length is 0.350000 seconds.
     0.000009625 "shairport.c:2083" audio_backend_buffer_interpolation_threshold_in_seconds is 0.020000 seconds.
     0.000009917 "shairport.c:2084" audio backend latency offset is -1.750000 seconds.
     0.000009917 "shairport.c:2086" audio backend silence lead-in time is "auto".
     0.000008750 "shairport.c:2090" zeroconf regtype is "_raop._tcp".
     0.000009625 "shairport.c:2091" decoders_supported field is 3.
     0.000008750 "shairport.c:2092" use_apple_decoder is 1.
     0.000008458 "shairport.c:2093" alsa_use_hardware_mute is 0.
     0.000008750 "shairport.c:2097" no special mdns service interface was requested.
     0.000031208 "shairport.c:2101" configuration file name "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
     0.000014000 "shairport.c:2107" metadata enabled is 1.
     0.000009334 "shairport.c:2108" metadata pipename is "/tmp/shairport-sync-metadata".
     0.000007583 "shairport.c:2110" metadata socket address is "(null)" port 0.
     0.000008167 "shairport.c:2111" metadata socket packet size is "500".
     0.000010208 "shairport.c:2112" get-coverart is 1.
     0.000009333 "shairport.c:2130" loudness is 0.
     0.000008750 "shairport.c:2131" loudness reference level is -20.000000
     0.000132709 "rtsp.c:3823" metadata pipe name is "/tmp/shairport-sync-metadata".
     5.663685169 "rtsp.c:2646" Connection 1: AP2 PTP connection from 192.168.1.2:54242 to self at 192.168.1.97:7000.
     1.463690376 "rtsp.c:2976" Connection 1. AP2 Realtime Audio Stream.
     0.008928500 "rtp.c:1668" Discarding early timing packet.
     0.000525292 "rtp.c:1765" AP2 Control Receiver -- error 0 receiving a packet.
     1.034674500 "rtp.c:1678" First packet is a not a sentinel packet!
     0.000147583 "rtp.c:1216" Connection 1: Set Anchor Clock: 84ab1a7eeeee0008.
     0.002445042 "rtp.c:1325" Connection 1: Clock 84ab1a7eeeee0008 is now the new anchor clock and master clock. History: 2252.257418 milliseconds.
     0.000347375 "rtp.c:1408" Connection 1: NQPTP new master clock 84ab1a7eeeee0008.
     0.001223833 "player.c:1070" Connection 1: Short lead time for first frame 3833060204: -0.736936 seconds. Flushing 0.5 seconds
     0.000475125 "player.c:1119" Gone past starting time for 3833060204 by 736935699 nanoseconds.
     7.998245463 "player.c:2458"     packets missing   late too late resend reqs min buffers max buffers received fps
     0.000161875 "player.c:2458"        1003       3      0        0           0           0           4     44586.51
     1.885861875 "player.c:1644" Connection 1: Playback Stopped. Total playing time 00:00:11. Input: 44586.51 frames per second.
    83.876828707 "rtsp.c:2976" Connection 1. AP2 Realtime Audio Stream.
     0.008285375 "rtp.c:1668" Discarding early timing packet.
     0.000887833 "rtp.c:1765" AP2 Control Receiver -- error 0 receiving a packet.
     0.221373542 "rtp.c:1429" Connection 1: No Clock Anchor.
     0.778077209 "rtp.c:1678" First packet is a not a sentinel packet!
     0.002208208 "rtp.c:1408" Connection 1: NQPTP new master clock 84ab1a7eeeee0008.
     0.000662959 "player.c:1070" Connection 1: Short lead time for first frame 450435060: -40.194208 seconds. Flushing 0.5 seconds
     0.000789250 "player.c:1119" Gone past starting time for 450435060 by 40194208126 nanoseconds.
     0.002225125 "player.c:1070" Connection 1: Short lead time for first frame 450478708: -39.207995 seconds. Flushing 0.5 seconds
     0.000566125 "player.c:1119" Gone past starting time for 450478708 by 39207995185 nanoseconds.
     8.007338212 "player.c:2458"     packets missing   late too late resend reqs min buffers max buffers received fps
     0.000112291 "player.c:2458"        1003       0      0        0           0           0           2     43909.57
     7.997176254 "player.c:2458"        2006       0      0        0           0           0           2     44098.39
     8.002526587 "player.c:2458"        3009       0      0        0           0           0           2     44108.30
     8.010935046 "player.c:2458"        4012       0      0        0           0           0           2     44097.83
     8.008065337 "player.c:2458"        5015       0      0        0           0           0           2     44084.06
     7.993718254 "player.c:2458"        6018       0      0        0           0           0           2     44104.10
     8.009902837 "player.c:2458"        7021       0      0        0           0           0           2     44099.41
     8.007069295 "player.c:2458"        8024       0      0        0           0           0           2     44102.53
     8.009775671 "player.c:2458"        9027       0      0        0           0           0           2     44093.29
     8.008314420 "player.c:2458"       10030       0      0        0           0           0           2     44096.88
     7.111093795 "player.c:1644" Connection 1: Playback Stopped. Total playing time 00:01:28. Input: 44096.88 frames per second.
    85.717678166 "rtsp.c:2976" Connection 1. AP2 Realtime Audio Stream.
     0.005767709 "rtp.c:1668" Discarding early timing packet.
     0.000223416 "rtp.c:1765" AP2 Control Receiver -- error 0 receiving a packet.
     0.215332542 "rtp.c:1429" Connection 1: No Clock Anchor.
     0.786333917 "rtp.c:1678" First packet is a not a sentinel packet!
     0.001938417 "rtp.c:1408" Connection 1: NQPTP new master clock 84ab1a7eeeee0008.
     0.000560875 "player.c:1070" Connection 1: Short lead time for first frame 1452208045: -78.593057 seconds. Flushing 0.5 seconds
     0.000465208 "player.c:1119" Gone past starting time for 1452208045 by 78593057236 nanoseconds.
     0.003806833 "player.c:1070" Connection 1: Short lead time for first frame 1452251693: -77.607828 seconds. Flushing 0.5 seconds
     0.000457334 "player.c:1119" Gone past starting time for 1452251693 by 77607828088 nanoseconds.
     8.004068629 "player.c:2458"     packets missing   late too late resend reqs min buffers max buffers received fps
     0.000099458 "player.c:2458"        1003       0      0        0           0           0           2     43944.79
     7.992345962 "player.c:2458"        2006       0      0        0           0           0           2     44113.81
     8.008582754 "player.c:2458"        3009       0      0        0           0           0           2     44113.99
     8.009934920 "player.c:2458"        4012       0      0        0           0           0           2     44103.49
     8.008585671 "player.c:2458"        5015       0      0        0           0           0           2     44096.48
     7.992604087 "player.c:2458"        6018       0      0        0           0           0           2     44107.64
     8.010151046 "player.c:2458"        7021       0      0        0           0           0           2     44102.50
     8.008879670 "player.c:2458"        8024       0      0        0           0           0           2     44104.58
     8.652187254 "rtp.c:1408" Connection 1: NQPTP new master clock 84ab1a7eeeee0008.
     0.210262209 "player.c:2458"        9027       0      0        0           0           0         187     44102.25
     7.156026795 "player.c:2458"       10030       0      0        0           0           0         105     44093.59
     7.989325753 "player.c:2458"       11033       0      0        0           0           0           2     44102.82
     8.009887671 "player.c:2458"       12036       0      0        0           0           0           2     44100.88
     8.010039045 "player.c:2458"       13039       0      0        0           0           0           2     44098.70
     8.009694338 "player.c:2458"       14042       0      0        0           0           0           2     44097.24
     7.989050128 "player.c:2458"       15045       0      0        0           0           0           2     44103.77
     8.010856379 "player.c:2458"       16048       0      0        0           0           0           2     44101.74
     8.010082504 "player.c:2458"       17051       0      0        0           0           0           2     44100.21
     8.008837171 "player.c:2458"       18054       0      0        0           0           0           2     44099.26
     8.010224545 "player.c:2458"       19057       0      0        0           0           0           2     44097.97
     7.990687254 "player.c:2458"       20060       0      0        0           0           0           2     44102.33
     8.007808962 "player.c:2458"       21063       0      0        0           0           0           2     44101.64
     8.012456379 "player.c:2458"       22066       0      0        0           0           0           2     44100.13
     8.009472045 "player.c:2458"       23069       0      0        0           0           0           2     44102.98
     7.942748337 "player.c:1644" Connection 1: Playback Stopped. Total playing time 00:03:14. Input: 44102.98 frames per second.
mikebrady commented 2 years ago

Thanks for these reports. @Gabi10017, can I just clarify if the problem has been resolved for you?

I've pushed some more changes to the development branch, including a sanity check of settings which @Gabi10017's settings will fail -- the combination of buffer size and offset is too long to accommodate in the stream's two second latency. My suggestion is to allow those settings to go to their defaults, and to see what happens.

The fact that there are problems with YouTube on AP1 as well as AP2 strongly suggests to me that there are network quality issues. @Gabi10017, if you could run in AP1 mode with the log_verbosity set to 2, you will get some figures that relate to the variation in timing packet times, which would be useful to know.

Gabi10017 commented 2 years ago

Thanks for these reports. @Gabi10017, can I just clarify if the problem has been resolved for you?

I've pushed some more changes to the development branch, including a sanity check of settings which @Gabi10017's settings will fail -- the combination of buffer size and offset is too long to accommodate in the stream's two second latency. My suggestion is to allow those settings to go to their defaults, and to see what happens.

The fact that there are problems with YouTube on AP1 as well as AP2 strongly suggests to me that there are network quality issues. @Gabi10017, if you could run in AP1 mode with the log_verbosity set to 2, you will get some figures that relate to the variation in timing packet times, which would be useful to know.

Hi! I would like to clarify a few things. I combined those settings because I want low to no latency when streaming a Realtime stream! Those 2 seconds delays when starting or pausing the stream are extremely annyoing. For me this combination worked very well. Also, the no audio issue was fixed for me with your last commit, thanks.

Regarding the YouTube issue, I'm extremely sure it's not a network quality issue, as everything is connected on cable excepting my phone which is connected on a Wifi 6 AP. There are no packets lost when streaming as you can see from my logs above.. Could you please try streaming from the YouTube app and see if it works for you? Safari worked fine in my case though, only the app has this issue..

An interesting fact I saw is that, YouTube music works partially, and through that I mean that when streaming audio only, it works, but as soon as you tap on the video option, it immediately hangs (maybe it also tries to send the video to the Receiver?)

mikebrady commented 2 years ago

Hi! I would like to clarify a few things. I combined those settings because I want low to no latency when streaming a Realtime stream! Those 2 seconds delays when starting or pausing the stream are extremely annyoing. For me this combination worked very well. Also, the no audio issue was fixed for me with your last commit, thanks.

Thanks for the clarification. AirPlay 1 and the Realtime stream of AirPlay 2 seem to be designed to have a two second delay and apps like YouTube will be aware of that. If you want a very short delay, the offset of -1.75 would give a nominal delay of 0.25 seconds. The default pa backend buffer is 0.35 seconds, so you are over the time budget. So, if you set the backend buffer to 0.25 (or 0.2) seconds, you should get the short delay you want.

Regarding the YouTube issue, I'm extremely sure it's not a network quality issue, as everything is connected on cable excepting my phone which is connected on a Wifi 6 AP. There are no packets lost when streaming as you can see from my logs above.. Could you please try streaming from the YouTube app and see if it works for you? Safari worked fine in my case though, only the app has this issue..

Okay, so I tried to do this with the settings above (with audio_backend_buffer_interpolation_threshold left at its default) and could not make YouTube or Shairport Sync misbehave. However, I am not using the premium version of YouTube. Note that YouTube uses a Buffered Audio stream rather than Realtime Audio stream.

Could you set the log verbosity to 1 and log whatever happens when you do what you did in the video please?

An interesting fact I saw is that, YouTube music works partially, and through that I mean that when streaming audio only, it works, but as soon as you tap on the video option, it immediately hangs (maybe it also tries to send the video to the Receiver?)

Yes, Shairport Sync is audio only and should not be offered as a video service. I think this is a bug in YouTube, or maybe in the AirPlay subsystem.

mikebrady commented 2 years ago

Just looking at the logs again, and this:

     8.008879670 "player.c:2458"        8024       0      0        0           0           0           2     44104.58
     8.652187254 "rtp.c:1408" Connection 1: NQPTP new master clock 84ab1a7eeeee0008.
     0.210262209 "player.c:2458"        9027       0      0        0           0           0         187     44102.25

looks a bit strange. Something odd happened here. If you were to switch over to an AirPlay 1 build and run at log verbosity 2, you might pick up some indication of network errors, particularly occasional long delays. Unfortunately, connecting with cable does not eliminate network errors caused, say, by a faulty router (see the troubleshooting page for more).

Gabi10017 commented 2 years ago

Hi! I would like to clarify a few things. I combined those settings because I want low to no latency when streaming a Realtime stream! Those 2 seconds delays when starting or pausing the stream are extremely annyoing. For me this combination worked very well. Also, the no audio issue was fixed for me with your last commit, thanks.

Thanks for the clarification. AirPlay 1 and the Realtime stream of AirPlay 2 seem to be designed to have a two second delay and apps like YouTube will be aware of that. If you want a very short delay, the offset of -1.75 would give a nominal delay of 0.25 seconds. The default pa backend buffer is 0.35 seconds, so you are over the time budget. So, if you set the backend buffer to 0.25 (or 0.2) seconds, you should get the short delay you want.

Regarding the YouTube issue, I'm extremely sure it's not a network quality issue, as everything is connected on cable excepting my phone which is connected on a Wifi 6 AP. There are no packets lost when streaming as you can see from my logs above.. Could you please try streaming from the YouTube app and see if it works for you? Safari worked fine in my case though, only the app has this issue..

Okay, so I tried to do this with the settings above (with audio_backend_buffer_interpolation_threshold left at its default) and could not make YouTube or Shairport Sync misbehave. However, I am not using the premium version of YouTube. Note that YouTube uses a Buffered Audio stream rather than Realtime Audio stream.

Could you set the log verbosity to 1 and log whatever happens when you do what you did in the video please?

An interesting fact I saw is that, YouTube music works partially, and through that I mean that when streaming audio only, it works, but as soon as you tap on the video option, it immediately hangs (maybe it also tries to send the video to the Receiver?)

Yes, Shairport Sync is audio only and should not be offered as a video service. I think this is a bug in YouTube, or maybe in the AirPlay subsystem.

I forgot to tell you but the log attached with the video was taken exactly when the video was made, and the log verbose is set to 1 in that case.

I tweaked the settings for a shorter delay, I tried to run with the default latency offset, with the suggested buffer desired length, also switched the account to a non-premium one, and it still wouldn't work. It shouldn't be caused by the network though, as other buffered streams work just fine.. I really don't want to build shairport again, and I also don't know how to set the log verbose.

I don't know if it helps or not but my main router is running OpenWRT with all devices getting local IPs from one address pool (192.168.1.x).

Gabi10017 commented 2 years ago

UPDATE: YouTube issue seems to be related to my phone or the network, because YouTube gives the same error when I try to stream to my TV (Native Airplay 2).

mikebrady commented 2 years ago

This is interesting. Looks like a bug from the source. But we might still be able to do something about it…

    25.693100846 "rtsp.c:2646" Connection 1: AP2 PTP connection from 192.168.1.2:54133 to self at 192.168.1.97:7000.
     0.251204041 "rtsp.c:3030" Connection 1. AP2 Buffered Audio Stream.
     0.101311751 "rtsp.c:2976" Connection 1. AP2 Realtime Audio Stream.
Gabi10017 commented 2 years ago

UPDATE 2: Seems like my shitty Pi-Hole was blocking some of YouTube's domains, which were causing these weird issues, it's all fixed now, works like a charm. The 'bug' you saw is actually YouTube trying to switch to a 'legacy' Realtime stream as a last resort to get the connection going, which also fails for obvious reasons. Thank you very much for all your help and support!

Gabi10017 commented 2 years ago

This is interesting. Looks like a bug from the source. But we might still be able to do something about it…


    25.693100846 "rtsp.c:2646" Connection 1: AP2 PTP connection from 192.168.1.2:54133 to self at 192.168.1.97:7000.

     0.251204041 "rtsp.c:3030" Connection 1. AP2 Buffered Audio Stream.

     0.101311751 "rtsp.c:2976" Connection 1. AP2 Realtime Audio Stream.

Also, I discovered that, the message you saw causes YouTube to panic, but it's actually caused by the negative latency offset that I put for realtime streams (it makes nqptp not to set an anchor clock). When using the default latency offset it works fine.

@mikebrady An extremely good idea, if you can implement it.. would be to have the ability to set custom latency offsets only for a type of stream (e.g set -1.75 seconds for realtime streams and none for buffered streams). That would be an extremely nice feature.