search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.15k stars 568 forks source link

[Problem]: USB Audio: "player.c:2906" Large negative (i.e. early) sync error" #1845

Closed alistairgn closed 1 month ago

alistairgn commented 4 months ago

What happened?

I'm trying to output audio from a Raspberry Pi 3 Model B Rev 1.2 to a Bose SoundLink Revolve+ II Speaker via USB Input. I'm currently able to get shairport to work via Aux Input only. I'm hoping that I can connect these Bose speakers with a single cable for power and audio.

Also adding that I can get test audio to play to the speaker using the speaker-test command.

This is the logs that I get:

$ shairport-sync -v
         0.002174583 "shairport.c:2252" Startup in AirPlay 2 mode, with features 0x405c4a00,0x1c340 on device “xx:xx:xx:xx:xx:xx”.
         0.000217083 "shairport.c:2291" Version String: "4.3.2-4-g45767ef9-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
         0.000029167 "shairport.c:2310" Command Line: "shairport-sync -v".
         0.000454948 "shairport.c:2346" Log Verbosity is 1.
         0.000057917 "audio_alsa.c:1021" alsa: alsa_maximum_stall_time of 0.200000 sec.
         0.000051145 "audio_alsa.c:1310" alsa: disable_standby_mode is "never".
         0.000013803 "audio_alsa.c:1314" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
         0.000014375 "audio_alsa.c:1316" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
         0.000022083 "audio_alsa.c:1356" alsa: output device name is "hw:1".
         0.000219479 "shairport.c:2394" disable_resend_requests is off.
         0.000018906 "shairport.c:2395" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000017292 "shairport.c:2399" statistics_requester status is 0.
         0.000012917 "shairport.c:2404" rtsp listening port is 7000.
         0.000013020 "shairport.c:2405" udp base port is 6001.
         0.000012500 "shairport.c:2406" udp port range is 10.
         0.000012188 "shairport.c:2407" player name is "Living Room".
         0.000012812 "shairport.c:2408" backend is "alsa".
         0.000049428 "shairport.c:2409" run_this_before_play_begins action is "(null)".
         0.000045468 "shairport.c:2410" run_this_after_play_ends action is "(null)".
         0.000040209 "shairport.c:2411" wait-cmd status is 0.
         0.000038698 "shairport.c:2412" run_this_before_play_begins may return output is 0.
         0.000038958 "shairport.c:2413" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000038854 "shairport.c:2415" run_this_before_entering_active_state action is  "(null)".
         0.000039479 "shairport.c:2417" run_this_after_exiting_active_state action is  "(null)".
         0.000039167 "shairport.c:2419" active_state_timeout is  10.000000 seconds.
         0.000028646 "shairport.c:2420" mdns backend "(null)".
         0.000013541 "shairport.c:2422" interpolation setting is "auto".
         0.000012657 "shairport.c:2426" interpolation soxr_delay_threshold is 30000000.
         0.000012916 "shairport.c:2427" resync time is 0.050000 seconds.
         0.000013542 "shairport.c:2428" resync recovery time is 0.100000 seconds.
         0.000013906 "shairport.c:2429" allow a session to be interrupted: 0.
         0.000012448 "shairport.c:2430" busy timeout time is 0.
         0.000012136 "shairport.c:2431" drift tolerance is 0.002000 seconds.
         0.000014166 "shairport.c:2432" password is "(null)".
         0.000011771 "shairport.c:2433" default airplay volume is: -24.000000.
         0.000014792 "shairport.c:2434" high threshold airplay volume is: -16.000000.
         0.000014531 "shairport.c:2436" check for higher-than-threshold volume for new play session is disabled.
         0.000013333 "shairport.c:2442" ignore_volume_control is 0.
         0.000012136 "shairport.c:2446" volume_max_db is not set
         0.000012135 "shairport.c:2447" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000016719 "shairport.c:2449" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000014427 "shairport.c:2453" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000014062 "shairport.c:2455" disable_synchronization is 0.
         0.000012188 "shairport.c:2456" use_mmap_if_available is 1.
         0.000012135 "shairport.c:2457" output_format automatic selection is enabled.
         0.000012657 "shairport.c:2461" output_rate automatic selection is enabled.
         0.000012500 "shairport.c:2465" audio backend desired buffer length is 0.200000 seconds.
         0.000014531 "shairport.c:2467" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
         0.000014687 "shairport.c:2469" audio backend latency offset is 0.000000 seconds.
         0.000014063 "shairport.c:2471" audio backend silence lead-in time is "auto".
         0.000012448 "shairport.c:2475" zeroconf regtype is "_raop._tcp".
         0.000012708 "shairport.c:2476" decoders_supported field is 1.
         0.000012500 "shairport.c:2477" use_apple_decoder is 0.
         0.000011823 "shairport.c:2478" alsa_use_hardware_mute is 0.
         0.000012448 "shairport.c:2482" no special mdns service interface was requested.
         0.000038646 "shairport.c:2485" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000015729 "shairport.c:2515" loudness is 0.
         0.000012292 "shairport.c:2516" loudness reference level is -20.000000
         0.000467187 "shairport.c:2643" NQPTP is online.
         1.502752239 "shairport.c:255" "soxr" interpolation has been chosen.
         7.961620205 "rtsp.c:2902" Connection 2: AP2 PTP connection from xxxx::xxxx:xxxx:xxxx:xxxx:xxxx ("xxxx’s iPhone") to self at xxxx::xxxx:xx:xxxx:xxx:xxxx.
         9.412920726 "rtsp.c:3258" Connection 2: SETUP AP2 no Active-Remote information  the SETUP Record.
         0.000115885 "rtsp.c:3277" Connection 2: SETUP AP2 doesn't include DACP-ID string information.
         1.148340052 "player.c:2906" Large negative (i.e. early) sync error of -2216 frames (-0.050249 seconds), at frame: 1233457123.
         0.527690417 "player.c:2906" Large negative (i.e. early) sync error of -2330 frames (-0.052834 seconds), at frame: 1233480355.
         0.486725572 "player.c:2906" Large negative (i.e. early) sync error of -2364 frames (-0.053605 seconds), at frame: 1233501475.
         0.486759271 "player.c:2906" Large negative (i.e. early) sync error of -2211 frames (-0.050136 seconds), at frame: 1233523299.
         0.526747708 "player.c:2906" Large negative (i.e. early) sync error of -2283 frames (-0.051769 seconds), at frame: 1233546179.
         0.445378281 "player.c:2906" Large negative (i.e. early) sync error of -2208 frames (-0.050068 seconds), at frame: 1233566243.
         0.465653229 "player.c:2906" Large negative (i.e. early) sync error of -2211 frames (-0.050136 seconds), at frame: 1233586659.
         0.526970833 "player.c:2906" Large negative (i.e. early) sync error of -2328 frames (-0.052789 seconds), at frame: 1233609891.
         0.526863958 "player.c:2906" Large negative (i.e. early) sync error of -2486 frames (-0.056372 seconds), at frame: 1233632771.
         0.526250104 "player.c:2906" Large negative (i.e. early) sync error of -2246 frames (-0.050930 seconds), at frame: 1233656003.
         0.514936459 "player.c:2906" Large negative (i.e. early) sync error of -2306 frames (-0.052290 seconds), at frame: 1233679235.
         0.514022187 "player.c:2906" Large negative (i.e. early) sync error of -2386 frames (-0.054104 seconds), at frame: 1233701059.
         0.524266198 "player.c:2906" Large negative (i.e. early) sync error of -2340 frames (-0.053061 seconds), at frame: 1233724995.
         0.501393281 "player.c:2906" Large negative (i.e. early) sync error of -2260 frames (-0.051247 seconds), at frame: 1233746467.
         0.511875885 "player.c:2906" Large negative (i.e. early) sync error of -2335 frames (-0.052948 seconds), at frame: 1233769699.

Speaker shows up fine on my iPhone or Mac and connects, but as soon as I play audio the "player.c:2906" Large negative (i.e. early) sync error of -2216 frames' error begins appearing until I pause or exit shairport-sync.

Using sps-alsa-explore command shows the following audio devices:

$ ./sps-alsa-explore 
> Device Full Name:    "hw:Headphones"
  Short Name:          "hw:0"
  This device seems suitable for use with Shairport Sync.
  Possible mixers:     "PCM",0                 Range: 106.38 dB
  The following rate and format would be chosen by Shairport Sync in "auto" mode:
     Rate              Format
     44100             S16_LE

> Device Full Name:    "hw:SoundLink"
  Short Name:          "hw:1"
  This device seems suitable for use with Shairport Sync.
  Possible mixers:     "PCM",0                 Range:  82.00 dB
  The following rate and format would be chosen by Shairport Sync in "auto" mode:
     Rate              Format
     44100             S16_LE`

I've tried different variants of "output_device" / "mixer_control_name" / latency offsets / output rates and formats but always have the same sync error with ~-0.05 seconds.

Is there something I am missing? Everything else I have used with shairport-sync has worked perfectly and I am so thankful for this player!

Relevant log output

No response

System Information.

Raspberry Pi 3 Model B Rev 1.2 Bose SoundLink Revolve+ II Bluetooth Speaker

Configuration Information.

$ shairport-sync --displayConfig
>> Display Config Start.

From "uname -a":
 Linux airplay-pi 6.6.28+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.6.28-1+rpt1 (2024-04-22) aarch64 GNU/Linux

From /etc/os-release:
 Debian GNU/Linux 12 (bookworm)

From /sys/firmware/devicetree/base/model:
 Raspberry Pi 3 Model B Rev 1.2

Shairport Sync Version String:
 4.3.2-4-g45767ef9-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc

Command Line:
 shairport-sync --displayConfig

Configuration File:
 /etc/shairport-sync.conf

Configuration File Settings:
 general : 
 {
   name = "Living Room";
 };
 alsa : 
 {
   output_device = "hw:1"; //have also tried “hw:SoundLink”
   mixer_control_name = "PCM"; //have also tried “USB Audio”

 };
 pw : 
 {
 };

>> Display Config End.
>> Goodbye!

PulseAudio or PipeWire installed?

How did you install Shairport Sync?

Built from source

Check previous issues

mikebrady commented 4 months ago

Thanks for the post, and it was a very good idea to run sps-alsa-explore.

It's a peculiar situation, to be sure. Those messages, like:

         1.148340052 "player.c:2906" Large negative (i.e. early) sync error of -2216 frames (-0.050249 seconds), at frame: 1233457123.

are coming from Shairport Sync trying to resynchronise, having calculated an error or more than ± 50 milliseconds. Let me suggest that you disable resynchronisation by setting resync_threshold_in_seconds to 0 (don't forget to uncomment that line and restart Shairport Sync). It would be very interesting to see the resulting log!

alistairgn commented 4 months ago

Thank you for your response Mike. Setting resync_theshold_in_senconds = 0 results in the following:

shairport-sync -v
         0.002191354 "shairport.c:2252" Startup in AirPlay 2 mode, with features 0x405c4a00,0x1c340 on device "b8:27:eb:b0:52:00".
         0.000140469 "shairport.c:2291" Version String: "4.3.2-4-g45767ef9-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
         0.000018646 "shairport.c:2310" Command Line: "shairport-sync -v".
         0.000342812 "shairport.c:2346" Log Verbosity is 1.
         0.000030886 "audio_alsa.c:1021" alsa: alsa_maximum_stall_time of 0.200000 sec.
         0.000051458 "audio_alsa.c:1310" alsa: disable_standby_mode is "never".
         0.000013490 "audio_alsa.c:1314" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
         0.000014322 "audio_alsa.c:1316" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
         0.000025730 "audio_alsa.c:1356" alsa: output device name is "hw:SoundLink".
         0.000223073 "shairport.c:2394" disable_resend_requests is off.
         0.000018802 "shairport.c:2395" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
         0.000017291 "shairport.c:2399" statistics_requester status is 0.
         0.000013125 "shairport.c:2404" rtsp listening port is 7000.
         0.000012136 "shairport.c:2405" udp base port is 6001.
         0.000012291 "shairport.c:2406" udp port range is 10.
         0.000012500 "shairport.c:2407" player name is "Living Room Bose".
         0.000013177 "shairport.c:2408" backend is "alsa".
         0.000012188 "shairport.c:2409" run_this_before_play_begins action is "(null)".
         0.000020677 "shairport.c:2410" run_this_after_play_ends action is "(null)".
         0.000056406 "shairport.c:2411" wait-cmd status is 0.
         0.000040834 "shairport.c:2412" run_this_before_play_begins may return output is 0.
         0.000039843 "shairport.c:2413" run_this_if_an_unfixable_error_is_detected action is "(null)".
         0.000039584 "shairport.c:2415" run_this_before_entering_active_state action is  "(null)".
         0.000018698 "shairport.c:2417" run_this_after_exiting_active_state action is  "(null)".
         0.000014375 "shairport.c:2419" active_state_timeout is  10.000000 seconds.
         0.000017291 "shairport.c:2420" mdns backend "(null)".
         0.000012032 "shairport.c:2422" interpolation setting is "auto".
         0.000012864 "shairport.c:2426" interpolation soxr_delay_threshold is 30000000.
         0.000012969 "shairport.c:2427" resync time is 0.000000 seconds.
         0.000013333 "shairport.c:2428" resync recovery time is 0.100000 seconds.
         0.000013906 "shairport.c:2429" allow a session to be interrupted: 0.
         0.000012292 "shairport.c:2430" busy timeout time is 0.
         0.000012240 "shairport.c:2431" drift tolerance is 0.002000 seconds.
         0.000014271 "shairport.c:2432" password is "(null)".
         0.000011822 "shairport.c:2433" default airplay volume is: -24.000000.
         0.000014688 "shairport.c:2434" high threshold airplay volume is: -16.000000.
         0.000014531 "shairport.c:2436" check for higher-than-threshold volume for new play session is disabled.
         0.000017604 "shairport.c:2442" ignore_volume_control is 0.
         0.000013021 "shairport.c:2446" volume_max_db is not set
         0.000012136 "shairport.c:2447" volume range in dB (zero means use the range specified by the mixer): 0.
         0.000013333 "shairport.c:2449" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
         0.000013594 "shairport.c:2453" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
         0.000013229 "shairport.c:2455" disable_synchronization is 0.
         0.000012500 "shairport.c:2456" use_mmap_if_available is 1.
         0.000011927 "shairport.c:2457" output_format automatic selection is enabled.
         0.000012500 "shairport.c:2461" output_rate automatic selection is enabled.
         0.000012500 "shairport.c:2465" audio backend desired buffer length is 0.200000 seconds.
         0.000013750 "shairport.c:2467" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
         0.000014792 "shairport.c:2469" audio backend latency offset is 0.000000 seconds.
         0.000014010 "shairport.c:2471" audio backend silence lead-in time is "auto".
         0.000012344 "shairport.c:2475" zeroconf regtype is "_raop._tcp".
         0.000012396 "shairport.c:2476" decoders_supported field is 1.
         0.000012031 "shairport.c:2477" use_apple_decoder is 0.
         0.000011667 "shairport.c:2478" alsa_use_hardware_mute is 0.
         0.000012291 "shairport.c:2482" no special mdns service interface was requested.
         0.000042813 "shairport.c:2485" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000015885 "shairport.c:2515" loudness is 0.
         0.000012292 "shairport.c:2516" loudness reference level is -20.000000
         0.000508125 "shairport.c:2643" NQPTP is online.
         1.502434166 "shairport.c:255" "soxr" interpolation has been chosen.
// Airplay speaker is then selected on device
         2.755037395 "rtsp.c:2902" Connection 1: AP2 PTP connection from xxxx::xxxx:xxxx:xxxx:xxxx:xxxxx ("iPhone") to self at xxxx::xxxx:xx:axxxx:xx:xxxx.
         6.777910362 "rtsp.c:3258" Connection 1: SETUP AP2 no Active-Remote information  the SETUP Record.
         0.000118958 "rtsp.c:3277" Connection 1: SETUP AP2 doesn't include DACP-ID string information.
// Press play on device
         2.479292759 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.000299063 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.008127292 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.032327708 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.000187135 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.040256771 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.000220209 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.007962291 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.032634479 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.000194844 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.040098333 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.000569219 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.007620677 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.032633438 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.000229479 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.040174739 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.000271459 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.000164427 "audio_alsa.c:1752" alsa: recovering from a previous underrun.

I also tried audio_backend_buffer_desired_length_in_seconds = 1.0 which produces the same log as above.

With this alsa error - would you have any other suggestions. I assume it is related to the alsa buffer size but not sure where to begin? If this is speaker specific I can revert to using the aux cable, however would happily keep troubleshooting if there is a way to make this work via USB audio.

mikebrady commented 4 months ago

Thanks. This is a real puzzle, and it's good that you have the AUX input solution as a backup.

If you could do $ shairport-sync -vv and start a play session, Shairport Sync will give some information about the DAC, something like this:

         0.007103385 "audio_alsa.c:548" alsa: output format chosen is "S16".
         0.000236511 "audio_alsa.c:591" alsa: output speed chosen is 44100.
         0.004730781 "audio_alsa.c:1529" alsa: update timestamps available
         0.000196562 "audio_alsa.c:253" alsa: precision delay timing is available.
         0.000091198 "audio_alsa.c:743" alsa: precision timing selected for "auto" mode
         0.000083490 "audio_alsa.c:760" PCM handle name = 'hw:2'
         0.000078385 "audio_alsa.c:774" alsa device parameters:
         0.000109375 "audio_alsa.c:777"   access type = MMAP_INTERLEAVED
         0.000105417 "audio_alsa.c:780"   format = 'S16_LE' (Signed 16 bit Little Endian)
         0.000105052 "audio_alsa.c:784"   subformat = 'STD' (Standard)
         0.000107240 "audio_alsa.c:788"   number of channels = 2
         0.000101406 "audio_alsa.c:791"   number of significant bits = 16
         0.000095364 "audio_alsa.c:799"   rate = 44100 frames per second (precisely).
         0.000088698 "audio_alsa.c:808"   precise (rational) rate = 44100.000 frames per second (i.e. 44100/1).
         0.000101042 "audio_alsa.c:822"   period_time = 5011 us (>).
         0.000106771 "audio_alsa.c:832"   period_size = 221 frames (precisely).
         0.000089427 "audio_alsa.c:845"   buffer_time = 2000000 us (precisely).
         0.000100417 "audio_alsa.c:858"   buffer_size = 88200 frames (precisely).
         0.000200468 "audio_alsa.c:874"   periods_per_buffer = 399 (>).

It might show some anomaly...

alistairgn commented 4 months ago

This returns the following info about the DAC:

         0.000489531 "rtsp.c:3363" Connection 1: TCP Buffered Audio port opened: 39809.
         0.000073021 "audio_alsa.c:900" alsa: hardware mixer prepare
         0.000027657 "activity_monitor.c:167" am_state: am_active
         0.003494427 "audio_alsa.c:923" Lowest dB value is a mute
         0.000667812 "audio_alsa.c:548" alsa: output format chosen is "S16".
         0.000098698 "audio_alsa.c:591" alsa: output speed chosen is 44100.
         0.005742396 "audio_alsa.c:1528" alsa: update timestamps available
         0.000073333 "audio_alsa.c:253" alsa: precision delay timing is available.
         0.000016042 "audio_alsa.c:743" alsa: precision timing selected for "auto" mode
         0.000014375 "audio_alsa.c:760" PCM handle name = 'hw:1'
         0.000012552 "audio_alsa.c:774" alsa device parameters:
         0.000018229 "audio_alsa.c:777"   access type = MMAP_INTERLEAVED
         0.000022344 "audio_alsa.c:780"   format = 'S16_LE' (Signed 16 bit Little Endian)
         0.000023177 "audio_alsa.c:784"   subformat = 'STD' (Standard)
         0.000017396 "audio_alsa.c:788"   number of channels = 2
         0.000015416 "audio_alsa.c:791"   number of significant bits = 16
         0.000016094 "audio_alsa.c:799"   rate = 44100 frames per second (precisely).
         0.000015938 "audio_alsa.c:808"   precise (rational) rate = 44100.000 frames per second (i.e. 44100/1).
         0.000023021 "audio_alsa.c:822"   period_time = 5011 us (>).
         0.000016197 "audio_alsa.c:832"   period_size = 221 frames (precisely).
         0.000020365 "audio_alsa.c:845"   buffer_time = 2000000 us (precisely).
         0.000014375 "audio_alsa.c:858"   buffer_size = 88200 frames (precisely).
         0.000016875 "audio_alsa.c:874"   periods_per_buffer = 399 (>).
         0.000017396 "audio_alsa.c:1792" do_open() set_mute_state
         0.000014167 "audio_alsa.c:1909" alsa: prepare() -- opened output device
         0.000379322 "player.c:3622" Connection 1: player_play.
         0.000634636 "rtsp.c:3453"  SETUP response
         0.000120885 "rtsp.c:3453"   Response Code: 200.
         0.000021927 "rtsp.c:3453"   Type: "CSeq", content: "13"
         0.000013802 "rtsp.c:3453"   Type: "Server", content: "AirTunes/366.0"
         0.000013438 "rtsp.c:3453"   Type: "Content-Type", content: "application/x-apple-binary-plist"
         0.000084219 "rtsp.c:3453"   Content Plist (as XML):

Anything that stands out?

This is also now showing that the underrun is is -1 frames:

         0.000105364 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.000292188 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.040221562 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.000432604 "player.c:2681" Underrun of -1 frames reported, but ignored.
         0.000177813 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.007601719 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.033039635 "player.c:2681" Underrun of -1 frames reported, but ignored.
         0.000153646 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.000282291 "audio_alsa.c:1752" alsa: recovering from a previous underrun.
         0.040152396 "audio_alsa.c:1752" alsa: recovering from a previous underrun.

I tried with all of this with Raspberry Pi4 Model B and still get the same errors.

mikebrady commented 4 months ago

Thanks. That all looks completely fine, unfortunately.

I have occasionally heard of problems with the so-called precision timing, so it might be worth disabling it. To do that, set use_precision_timing to "no" in the alsa stanza of the configuration file. It's really a long shot in the dark, just to mangle a few metaphors...

alistairgn commented 4 months ago

Tried the above and still nothing.

I've just done some more testing and it has come to my attention that this is likely an issue with the DAC/Speak not actually able to play rates of 44100.

Audio plays from the speaker via USB-Audio using the following command:

$ aplay /usr/share/sounds/alsa/Front_Left.wav
Playing WAVE '/usr/share/sounds/alsa/Front_Left.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Mono

I noted this was at a Rate of 48000 that shairport does not support.

I then tested:

speaker-test -r44100 --device=hw:1 -c2

Which provided no audio.

However - 

speaker-test -r48000 --device=hw:1 -c2

Plays through the pink noise.

I should have picked up on this earlier but although the speaker showed in sps-alsa-explore, it didn't necessarily mean that it could playback at a rate of 44100.

I would assume this is now a speaker limitation (using USB Audio) and there is nothing further to troubleshoot?

Thank you for your help with this Mike - I appreciate your time, and thank you for all your work on this player.

mikebrady commented 4 months ago

Thanks for all your investigations. I think your conclusions are spot on.

It does seems as if the SoundLink has a bug in it. Even though it can not play at 44,100 frames per second, when asked by Shairport Sync, the player advertises that it can do so. The lines following:

0.000012552 "audio_alsa.c:774" alsa device parameters:
...
...

in the log listed above show the response from the DAC.

As you've discovered, the device can only work at 48,000. Shairport Sync requires a playback rate of 44,100 or an integer multiple of it.

Maybe this will help someone in the future.

github-actions[bot] commented 2 months ago

This issue has been inactive for 28 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.