mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.17k stars 569 forks source link

Stuttering and "Large negative sync error" when running in Docker #1255

Closed robcast closed 3 years ago

robcast commented 3 years ago

I try to run a recent version of shairport-sync in Docker (4.0-dev but even 3.3.5 doesn't work) on my ODROID-XU4 ARMV7 Linux board but the sound is stuttering and I get errors like:

   0.348221032 "player.c:2450" Large negative sync error of: -2563 frames (-0.058118 seconds), with frame: 247034922.
   0.153440926 "player.c:2450" Large negative sync error of: -2608 frames (-0.059138 seconds), with frame: 247041610.
   0.153105551 "player.c:2450" Large negative sync error of: -2607 frames (-0.059116 seconds), with frame: 247048298.

I use the Ubuntu docker.io (20.10.2) and the docker-compose file from https://github.com/mikebrady/shairport-sync/blob/development/docker/docker-compose.yaml

The standard Ubuntu package of shairport-sync 3.3.5 works fine (but I'd like to try out Airplay2).

Sound output is via the ODROID's HDMI and an AVR.

Log output from the working Ubuntu version and the broken Docker version looks very similar (see below).

Any ideas?

robcast commented 3 years ago

This is the log from the stuttering shairport-sync in Docker:

   0.001353125 "shairport.c:1821" Started!
   0.000038875 "shairport.c:1824" Started in Airplay 2 mode!
   0.000031959 "shairport.c:1866" software version: "4.0-dev-202-g8f54828-AirPlay2-alac-OpenSSL-Avahi-ALSA-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc"
   0.000035083 "shairport.c:1872" log verbosity is 1.
   0.000062417 "audio_alsa.c:1015" alsa: alsa_maximum_stall_time of 0.200000 sec.
   0.000065000 "audio_alsa.c:1299" alsa: disable_standby_mode is "never".
   0.000023458 "audio_alsa.c:1303" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
   0.000024792 "audio_alsa.c:1305" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
   0.000027041 "audio_alsa.c:1345" alsa: output device name is "hw:OdroidXU4".
   0.000303959 "shairport.c:1901" libsodium initialised.
   0.000023333 "shairport.c:1928" disable resend requests is off.
   0.000018459 "shairport.c:1929" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
   0.000028208 "shairport.c:1933" statistics_requester status is 1.
   0.000017167 "shairport.c:1938" rtsp listening port is 7000.
   0.000015333 "shairport.c:1939" udp base port is 6001.
   0.000016417 "shairport.c:1940" udp port range is 10.
   0.000015000 "shairport.c:1941" player name is "Rodroid".
   0.000018250 "shairport.c:1942" backend is "alsa".
   0.000016208 "shairport.c:1943" run_this_before_play_begins action is "(null)".
   0.000025958 "shairport.c:1944" run_this_after_play_ends action is "(null)".
   0.000023584 "shairport.c:1945" wait-cmd status is 0.
   0.000015708 "shairport.c:1946" run_this_before_play_begins may return output is 0.
   0.000022083 "shairport.c:1947" run_this_if_an_unfixable_error_is_detected action is "(null)".
   0.000020500 "shairport.c:1948" run_this_before_entering_active_state action is  "(null)".
   0.000020625 "shairport.c:1949" run_this_after_exiting_active_state action is  "(null)".
   0.000019417 "shairport.c:1950" active_state_timeout is  10.000000 seconds.
   0.000020833 "shairport.c:1951" mdns backend "(null)".
   0.000014875 "shairport.c:1953" interpolation setting is "auto".
   0.000015667 "shairport.c:1956" interpolation soxr_delay_threshold is 30.
   0.000025125 "shairport.c:1957" resync time is 0.050000 seconds.
   0.000015667 "shairport.c:1958" allow a session to be interrupted: 0.
   0.000012833 "shairport.c:1959" busy timeout time is 0.
   0.000012917 "shairport.c:1960" drift tolerance is 0.001995 seconds.
   0.000013625 "shairport.c:1961" password is "(null)".
   0.000012916 "shairport.c:1962" ignore_volume_control is 0.
   0.000064042 "shairport.c:1966" volume_max_db is not set
   0.000018958 "shairport.c:1967" volume range in dB (zero means use the range specified by the mixer): 0.
   0.000018792 "shairport.c:1969" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
   0.000018750 "shairport.c:1973" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
   0.000019083 "shairport.c:1975" disable_synchronization is 0.
   0.000014334 "shairport.c:1976" use_mmap_if_available is 1.
   0.000014000 "shairport.c:1977" output_format automatic selection is enabled.
   0.000019541 "shairport.c:1981" output_rate automatic selection is enabled.
   0.000017709 "shairport.c:1985" audio backend desired buffer length is 0.200000 seconds.
   0.000018625 "shairport.c:1987" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
   0.000018458 "shairport.c:1989" audio backend latency offset is 0.000000 seconds.
   0.000023000 "shairport.c:1991" audio backend silence lead-in time is "auto".
   0.000019833 "shairport.c:1995" zeroconf regtype is "_raop._tcp".
   0.000055792 "shairport.c:1996" decoders_supported field is 3.
   0.000013750 "shairport.c:1997" use_apple_decoder is 1.
   0.000013917 "shairport.c:1998" alsa_use_hardware_mute is 0.
   0.000013833 "shairport.c:2002" no special mdns service interface was requested.
   0.000102042 "shairport.c:2005" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
   0.000040583 "shairport.c:2012" metadata enabled is 1.
   0.000021834 "shairport.c:2013" metadata pipename is "/tmp/shairport-sync-metadata".
   0.000030041 "shairport.c:2014" metadata socket address is "(null)" port 0.
   0.000032834 "shairport.c:2016" metadata socket packet size is "500".
   0.000020500 "shairport.c:2017" get-coverart is 1.
   0.000020708 "shairport.c:2020" mqtt is disabled.
   0.000019333 "shairport.c:2021" mqtt hostname is (null), port is 1883.
   0.000021542 "shairport.c:2022" mqtt topic is /Rodroid.
   0.000018458 "shairport.c:2023" mqtt will not publish raw metadata.
   0.000019042 "shairport.c:2024" mqtt will not publish parsed metadata.
   0.000020167 "shairport.c:2025" mqtt will not publish cover Art.
   0.000017708 "shairport.c:2026" mqtt remote control is disabled.
   0.000015250 "shairport.c:2030" convolution is 0.
   0.000023083 "shairport.c:2031" convolution IR file is "(null)"
   0.000020459 "shairport.c:2032" convolution max length 8192
   0.000020291 "shairport.c:2033" convolution gain is 0.000000
   0.000022000 "shairport.c:2035" loudness is 0.
   0.000019000 "shairport.c:2036" loudness reference level is -20.000000
   0.000547959 "rtsp.c:3126" metadata pipe name is "/tmp/shairport-sync-metadata".
   0.013196088 "mdns_avahi.c:405" avahi_dacp_monitor_start Avahi DACP monitor successfully started
   0.005276293 "dbus-service.c:548" >> setting loudness threshold to -20.000000.
   0.000248459 "dbus-service.c:561" >> setting drift tolerance to 0.001995 seconds
   0.000114208 "dbus-service.c:905" >> ALACDecoder set to "apple"
   0.000091750 "dbus-service.c:914" >> Active set to "false"
   0.000110750 "dbus-service.c:919" >> disable standby mode set to "off"
   0.000119208 "dbus-service.c:940" >> interpolation set to "auto" (soxr support built in)
   0.000149209 "dbus-service.c:456" >> deactivating disable standby
   0.000075166 "dbus-service.c:538" >> deactivating loudness
   0.000063459 "dbus-service.c:472" >> deactivating convolution
   0.000206875 "dbus-service.c:441" >> log verbosity set to 1.
   0.000089208 "dbus-service.c:425" >> start logging statistics
   0.000066875 "dbus-service.c:390" >> stop including elapsed time in logs
   0.000098334 "dbus-service.c:400" >> start including delta time in logs
   0.000094375 "dbus-service.c:413" >> start including file and line in logs
   0.000249208 "dbus-service.c:1045" Shairport Sync native D-Bus service started at "org.gnome.ShairportSync" on the system bus.
   0.002410459 "mpris-service.c:341" MPRIS service started at "org.mpris.MediaPlayer2.ShairportSync" on the system bus.
   1.481970506 "shairport.c:211" "soxr" interpolation has been chosen.
  20.750682900 "rtsp.c:2234" Connection 5. Buffered Audio Stream Detected.
   0.006886419 "audio_alsa.c:528" alsa: output format chosen is "S24".
   0.000044875 "audio_alsa.c:569" alsa: output speed chosen is 44100.
   0.220705406 "rtp.c:1316" Connection 5: Clock 6d4d73cfa99e0005 is now the new anchor clock and master clock. History: 5822.398648 milliseconds.
   0.000037417 "rtp.c:1396" Connection 5: NQPTP new master clock 6d4d73cfa99e0005.
   0.014683338 "player.c:1059" Connection 5: Lead time for first frame 247024010: 0.299978 seconds.
   0.348221032 "player.c:2450" Large negative sync error of: -2563 frames (-0.058118 seconds), with frame: 247034922.
   0.153440926 "player.c:2450" Large negative sync error of: -2608 frames (-0.059138 seconds), with frame: 247041610.
   0.153105551 "player.c:2450" Large negative sync error of: -2607 frames (-0.059116 seconds), with frame: 247048298.
   0.159705303 "player.c:2450" Large negative sync error of: -2696 frames (-0.061134 seconds), with frame: 247055338.
   0.158978844 "player.c:2450" Large negative sync error of: -2690 frames (-0.060998 seconds), with frame: 247062378.

and this is the working Ubuntu version

   0.000778334 "shairport.c:1626" Started!
   0.000076875 "shairport.c:1638" software version: "3.3.5-libdaemon-OpenSSL-Avahi-ALSA-pa-dummy-stdout-pipe-soxr-convolution-metadata-mqtt-dbus-mpris-sysconfdir:/etc"
   0.000017792 "shairport.c:1644" log verbosity is 1.
   0.000061708 "audio_alsa.c:1018" alsa: alsa_maximum_stall_time of 0.200000 sec.
   0.000031709 "audio_alsa.c:1300" alsa: disable_standby_mode is "never".
   0.000015666 "audio_alsa.c:1304" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
   0.000015667 "audio_alsa.c:1306" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
   0.000017000 "audio_alsa.c:1346" alsa: output device name is "default".
   0.000251125 "shairport.c:1692" disable resend requests is off.
   0.000024625 "shairport.c:1693" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
   0.000018042 "shairport.c:1696" statistics_requester status is 1.
   0.000019166 "shairport.c:1698" daemon status is 0.
   0.000017000 "shairport.c:1699" daemon pid file path is "/run/shairport-sync/shairport-sync.pid".
   0.000015709 "shairport.c:1701" rtsp listening port is 5000.
   0.000020958 "shairport.c:1702" udp base port is 6001.
   0.000016125 "shairport.c:1703" udp port range is 10.
   0.000016125 "shairport.c:1704" player name is "Rodroid".
   0.000015833 "shairport.c:1705" backend is "(null)".
   0.000015251 "shairport.c:1706" run_this_before_play_begins action is "(null)".
   0.000015208 "shairport.c:1707" run_this_after_play_ends action is "(null)".
   0.000019667 "shairport.c:1708" wait-cmd status is 0.
   0.000015875 "shairport.c:1709" run_this_before_play_begins may return output is 0.
   0.000015291 "shairport.c:1710" run_this_if_an_unfixable_error_is_detected action is "(null)".
   0.000015500 "shairport.c:1711" run_this_before_entering_active_state action is  "(null)".
   0.000015459 "shairport.c:1712" run_this_after_exiting_active_state action is  "(null)".
   0.000018291 "shairport.c:1713" active_state_timeout is  10.000000 seconds.
   0.000018834 "shairport.c:1714" mdns backend "(null)".
   0.000015083 "shairport.c:1716" interpolation setting is "auto".
   0.000014750 "shairport.c:1719" interpolation soxr_delay_threshold is 30.
   0.000014958 "shairport.c:1720" resync time is 0.050000 seconds.
   0.000016084 "shairport.c:1721" allow a session to be interrupted: 0.
   0.000014750 "shairport.c:1722" busy timeout time is 120.
   0.000015875 "shairport.c:1723" drift tolerance is 0.001995 seconds.
   0.000016041 "shairport.c:1724" password is "(null)".
   0.000015334 "shairport.c:1725" ignore_volume_control is 0.
   0.000018291 "shairport.c:1729" volume_max_db is not set
   0.000022042 "shairport.c:1730" volume range in dB (zero means use the range specified by the mixer): 0.
   0.000016792 "shairport.c:1732" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
   0.000015791 "shairport.c:1735" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
   0.000016875 "shairport.c:1737" disable_synchronization is 0.
   0.000016750 "shairport.c:1738" use_mmap_if_available is 1.
   0.000017875 "shairport.c:1739" output_format automatic selection is enabled.
   0.000040375 "shairport.c:1743" output_rate automatic selection is enabled.
   0.000022959 "shairport.c:1747" audio backend desired buffer length is 0.200000 seconds.
   0.000020541 "shairport.c:1749" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
   0.000018417 "shairport.c:1751" audio backend latency offset is 0.000000 seconds.
   0.000021500 "shairport.c:1752" audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
   0.000016625 "shairport.c:1754" zeroconf regtype is "_raop._tcp".
   0.000015500 "shairport.c:1755" decoders_supported field is 1.
   0.000014792 "shairport.c:1756" use_apple_decoder is 0.
   0.000015083 "shairport.c:1757" alsa_use_hardware_mute is 0.
   0.000015375 "shairport.c:1761" no special mdns service interface was requested.
   0.000033792 "shairport.c:1764" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
   0.000018208 "shairport.c:1771" metadata enabled is 1.
   0.000015917 "shairport.c:1772" metadata pipename is "/tmp/shairport-sync-metadata".
   0.000015917 "shairport.c:1773" metadata socket address is "(null)" port 0.
   0.000018875 "shairport.c:1775" metadata socket packet size is "500".
   0.000016291 "shairport.c:1776" get-coverart is 1.
   0.000015459 "shairport.c:1779" mqtt is disabled.
   0.000016375 "shairport.c:1780" mqtt hostname is (null), port is 1883.
   0.000016666 "shairport.c:1781" mqtt topic is /Rodroid.
   0.000015834 "shairport.c:1782" mqtt will not publish raw metadata.
   0.000017875 "shairport.c:1783" mqtt will not publish parsed metadata.
   0.000016375 "shairport.c:1784" mqtt will not publish cover Art.
   0.000017125 "shairport.c:1785" mqtt remote control is disabled.
   0.000015208 "shairport.c:1789" convolution is 0.
   0.000015583 "shairport.c:1790" convolution IR file is "(null)"
   0.000018000 "shairport.c:1791" convolution max length 8192
   0.000019084 "shairport.c:1792" convolution gain is 0.000000
   0.000016166 "shairport.c:1794" loudness is 0.
   0.000015375 "shairport.c:1795" loudness reference level is -20.000000
   0.015823092 "dbus-service.c:985" *warning: Could not acquire a Shairport Sync native D-Bus interface "org.gnome.ShairportSync.i4142" on the system bus.
   0.000478875 "mpris-service.c:287" *warning: Could not acquire an MPRIS interface named "org.mpris.MediaPlayer2.ShairportSync.i4142" on the system bus.
   0.000804459 "mdns_avahi.c:371" avahi_dacp_monitor_start Avahi DACP monitor successfully started
   1.485394190 "shairport.c:198" "soxr" interpolation has been chosen.
  23.228995834 "rtsp.c:996" Connection 13: SETUP DACP-ID "66E2900835D3B527" from 2a02:8109:9280:104a:c900:ebb6:d0b0:86a9 to 2a02:8109:9280:104a:21e:6ff:fe30:b509 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
   0.014138507 "audio_alsa.c:529" alsa: output format chosen is "S32".
   0.000233917 "audio_alsa.c:570" alsa: output speed chosen is 44100.
   0.006526253 "player.c:1883" sync error in milliseconds, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy, source nominal frames per second, source actual frames per second, output frames per second, source clock drift in ppm, source clock drift sample count, rough calculated correction in ppm
  10.086859739 "player.c:2647"      -0.13,       0.0,       0.0,        1003,      0,      0,      0,      0,   8574,  234,  247,   44100.11,   44106.92,   44100.02,      0.00,     0,     -1.91
mikebrady commented 3 years ago

Thanks for the post. If I understand your post correctly, Shairport Sync 3.3.5 runs properly natively in your Ubuntu system but doesn't run inside a Docker container on the same system. Is that right?

robcast commented 3 years ago

Exactly, the non-Docker version 3.3.5 from Ubuntu runs fine while the Docker versions of 3.3.5 or 4.0-dev from Docker-hub produce the mentioned errors.

mikebrady commented 3 years ago

Thanks. So that would seem to indicate some kind of a problem associated with Docker. One possibility is how access is managed to the host's alsa subsystem, and to /proc/asound in particular. One way to explore that a little would be to tell the Docker version to output to the stdout or to a pipe and then to discard it by directing it to /dev/null. This would bypass the alsa system completely. IF the delays went away, that might mean that they are associated with the alsa system. IF they didn't go away, it would tend to indicate that the problem was elsewhere. Maybe... It's weak...

robcast commented 3 years ago

Thanks for the tip. The errors do not occur when I use output_backend = "pipe" and name = "/dev/null". So the problem lies in the container's access to the alsa subsystem.

After fiddling with docker options I could get it to work:

mikebrady commented 3 years ago

Good stuff. What output_device setting did you use, please?

robcast commented 3 years ago

I left the output_device setting commented out. I haven't checked what the default value is ;-)

mikebrady commented 3 years ago

Super, thanks.