[Problem]: "player.c:2708" Delay error -524 when checking running latency. #1930 #1931

sberl · 2024-11-15T23:14:34Z

What happened?

I just installed shairport-sync on a fresh install of Raspberry OS on a RPi 4.
Version String: "4.3.4-1-g910264e5-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"

It works fine when started on the command line. Can play music from phone or laptop and it comes out the headphone jack of the Pi just fine.

When running as a service, the log shows the normal startup messages (same as what I see on command line start), but as soon as my phone attaches, it starts to spew out lots of these messages.

"player.c:2708" Delay error -524 when checking running latency.

No sound comes from the Pi headphone jack in this case.

Mike suggested this is related to HDMI ports. I have nothing connected to the HDMI ports on my machine. Only power, Ethernet, USB SDD, and headphone jack output to an audio amp (Sonos speaker line input).
I do have the GUI installed and am sometimes accessing the machine via VNC.

Included the log from running as a service below with some comments noting what I was doing.

Steve

Relevant log output

// Shutting down the shairport-sync service

Nov 15 15:04:33 berl-music-pi sudo[2659]:    admin : TTY=pts/3 ; PWD=/home/admin ; USER=root ; COMMAND=/usr/bin/systemctl status shairport-sync.service
Nov 15 15:04:33 berl-music-pi sudo[2659]: pam_unix(sudo:session): session opened for user root(uid=0) by admin(uid=1000)
Nov 15 15:04:43 berl-music-pi sudo[2659]: pam_unix(sudo:session): session closed for user root
Nov 15 15:04:55 berl-music-pi sudo[2663]:    admin : TTY=pts/3 ; PWD=/home/admin ; USER=root ; COMMAND=/usr/bin/systemctl stop shairport-sync.service
Nov 15 15:04:55 berl-music-pi sudo[2663]: pam_unix(sudo:session): session opened for user root(uid=0) by admin(uid=1000)
Nov 15 15:04:55 berl-music-pi systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Nov 15 15:04:55 berl-music-pi shairport-sync[2584]:        242.678624041 "shairport.c:1729" normal exit
Nov 15 15:04:55 berl-music-pi systemd[1]: shairport-sync.service: Deactivated successfully.
Nov 15 15:04:55 berl-music-pi systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Nov 15 15:04:55 berl-music-pi systemd[1]: shairport-sync.service: Consumed 2.544s CPU time.
Nov 15 15:04:55 berl-music-pi sudo[2663]: pam_unix(sudo:session): session closed for user root


// Starting up the shairport-sync service

Nov 15 15:05:15 berl-music-pi sudo[2668]:    admin : TTY=pts/3 ; PWD=/home/admin ; USER=root ; COMMAND=/usr/bin/systemctl start shairport-sync.service
Nov 15 15:05:15 berl-music-pi sudo[2668]: pam_unix(sudo:session): session opened for user root(uid=0) by admin(uid=1000)
Nov 15 15:05:15 berl-music-pi systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Nov 15 15:05:15 berl-music-pi sudo[2668]: pam_unix(sudo:session): session closed for user root
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000965315 "shairport.c:2278" Startup in AirPlay 2 mode, with features 0x405c4a00,0x1c340 on device "d8:3a:dd:ed:74:7a".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000137111 "shairport.c:2317" Version String: "4.3.4-1-g910264e5-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000013926 "shairport.c:2336" Command Line: "/usr/local/bin/shairport-sync --log-to-syslog".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000229870 "shairport.c:2372" Log Verbosity is 1.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000021833 "audio_alsa.c:1082" alsa: alsa_maximum_stall_time of 0.200000 sec.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000026704 "audio_alsa.c:1371" alsa: disable_standby_mode is "never".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000008908 "audio_alsa.c:1375" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000008148 "audio_alsa.c:1377" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000021722 "audio_alsa.c:1417" alsa: output device name is "default".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000152481 "shairport.c:2440" disable_resend_requests is off.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000016945 "shairport.c:2441" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000008926 "shairport.c:2445" statistics_requester status is 0.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007981 "shairport.c:2450" rtsp listening port is 7000.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007260 "shairport.c:2451" udp base port is 6001.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007148 "shairport.c:2452" udp port range is 10.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007000 "shairport.c:2453" player name is "Berl-music-pi".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000006889 "shairport.c:2454" backend is "alsa".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000008222 "shairport.c:2455" run_this_before_play_begins action is "(null)".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007926 "shairport.c:2456" run_this_after_play_ends action is "(null)".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007778 "shairport.c:2457" wait-cmd status is 0.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007185 "shairport.c:2458" run_this_before_play_begins may return output is 0.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007092 "shairport.c:2459" run_this_if_an_unfixable_error_is_detected action is "(null)".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007130 "shairport.c:2461" run_this_before_entering_active_state action is  "(null)".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007630 "shairport.c:2463" run_this_after_exiting_active_state action is  "(null)".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007166 "shairport.c:2465" active_state_timeout is  10.000000 seconds.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000009889 "shairport.c:2466" mdns backend "(null)".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007370 "shairport.c:2468" interpolation setting is "auto".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007408 "shairport.c:2472" interpolation soxr_delay_threshold is 30000000.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007092 "shairport.c:2473" resync time is 0.050000 seconds.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007371 "shairport.c:2474" resync recovery time is 0.100000 seconds.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007389 "shairport.c:2475" allow a session to be interrupted: 0.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000006833 "shairport.c:2476" busy timeout time is 120.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007482 "shairport.c:2477" drift tolerance is 0.002000 seconds.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007444 "shairport.c:2478" password is not set.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000006981 "shairport.c:2479" default airplay volume is: -24.000000.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000008500 "shairport.c:2480" high threshold airplay volume is: -16.000000.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000008519 "shairport.c:2482" check for higher-than-threshold volume for new play session is disabled.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007074 "shairport.c:2488" ignore_volume_control is 0.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007593 "shairport.c:2492" volume_max_db is not set
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000006796 "shairport.c:2493" volume range in dB (zero means use the range specified by the mixer): 0.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007370 "shairport.c:2495" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007260 "shairport.c:2499" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007648 "shairport.c:2501" disable_synchronization is 0.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000006796 "shairport.c:2502" use_mmap_if_available is 1.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007148 "shairport.c:2503" output_format automatic selection is enabled.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007408 "shairport.c:2507" output_rate automatic selection is enabled.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007351 "shairport.c:2511" audio backend desired buffer length is 0.200000 seconds.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007797 "shairport.c:2513" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007870 "shairport.c:2515" audio backend latency offset is 0.000000 seconds.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000011019 "shairport.c:2517" audio backend silence lead-in time is "auto".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007203 "shairport.c:2521" zeroconf regtype is "_raop._tcp".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007204 "shairport.c:2522" decoders_supported field is 1.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000006815 "shairport.c:2523" use_apple_decoder is 0.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007148 "shairport.c:2524" alsa_use_hardware_mute is 0.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000006759 "shairport.c:2528" no special mdns service interface was requested.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000014648 "shairport.c:2531" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000009074 "shairport.c:2561" loudness is 0.
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000007112 "shairport.c:2562" loudness reference level is -20.000000
Nov 15 15:05:15 berl-music-pi shairport-sync[2672]:          0.000684814 "shairport.c:2689" NQPTP is online.
Nov 15 15:05:17 berl-music-pi shairport-sync[2672]:          1.501465055 "shairport.c:255" "soxr" interpolation has been chosen.

// This is when my Macbook attempts to connect to the service

Nov 15 15:05:46 berl-music-pi shairport-sync[2672]:         29.485403890 "rtsp.c:2896" Connection 1: AP2 PTP connection from 2601:643:8d81:2100:10ad:bfca:8854:484a:50137 ("Steve-MacBook-Air") to self at 2601:643:8d81:2100:c93b:d2b3:c7c7:b021:7000.

// Some suspicious error messages

Nov 15 15:05:55 berl-music-pi kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd022 fail, reason -52
Nov 15 15:05:55 berl-music-pi kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd026 fail, reason -52
Nov 15 15:05:55 berl-music-pi kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02a fail, reason -52
Nov 15 15:05:55 berl-music-pi kernel: brcmfmac: brcmf_set_channel: set chanspec 0xd02e fail, reason -52
Nov 15 15:06:04 berl-music-pi shairport-sync[2672]:         18.001692860 "rtsp.c:3253" Connection 1: SETUP AP2 no Active-Remote information  the SETUP Record.
Nov 15 15:06:04 berl-music-pi shairport-sync[2672]:          0.000091833 "rtsp.c:3272" Connection 1: SETUP AP2 doesn't include DACP-ID string information.
Nov 15 15:06:04 berl-music-pi shairport-sync[2672]:          0.000042018 "rtsp.c:3287" Connection 1. AP2 Realtime Audio Stream.
Nov 15 15:06:04 berl-music-pi shairport-sync[2672]:          0.046093926 "rtp.c:1738" AP2 Realtime Clock receiver initialised.
Nov 15 15:06:05 berl-music-pi shairport-sync[2672]:          0.575942574 "rtsp.c:2896" Connection 2: AP2 PTP connection from 2601:643:8d81:2100:10ad:bfca:8854:484a:50143 ("Steve-MacBook-Air") to self at 2601:643:8d81:2100:c93b:d2b3:c7c7:b021:7000.
Nov 15 15:06:05 berl-music-pi shairport-sync[2672]:          0.210175833 "rtsp.c:3253" Connection 2: SETUP AP2 no Active-Remote information  the SETUP Record.
Nov 15 15:06:05 berl-music-pi shairport-sync[2672]:          0.000039463 "rtsp.c:3272" Connection 2: SETUP AP2 doesn't include DACP-ID string information.
Nov 15 15:06:07 berl-music-pi shairport-sync[2672]:          1.627299999 "player.c:1252" Gone past starting time for 351486788 by 10959357 nanoseconds.
Nov 15 15:06:07 berl-music-pi shairport-sync[2672]:          0.004206889 "player.c:2708" Delay error -524 when checking running latency.
Nov 15 15:06:07 berl-music-pi shairport-sync[2672]:          0.000439907 "player.c:2708" Delay error -524 when checking running latency.
Nov 15 15:06:07 berl-music-pi shairport-sync[2672]:          0.000447593 "player.c:2708" Delay error -524 when checking running latency.
Nov 15 15:06:07 berl-music-pi shairport-sync[2672]:          0.000443019 "player.c:2708" Delay error -524 when checking running latency.
Nov 15 15:06:07 berl-music-pi shairport-sync[2672]:          0.000411851 "player.c:2708" Delay error -524 when checking running latency.

// Many more of the same

System Information.

Raspberry Pi 4B+ upgraded to latest on Nov 15, 2024
admin@berl-music-pi:~ $ cat /etc/os-release
PRETTY_NAME="Debian GNU/Linux 12 (bookworm)"
NAME="Debian GNU/Linux"
VERSION_ID="12"
VERSION="12 (bookworm)"
VERSION_CODENAME=bookworm
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"
admin@berl-music-pi:~ $

Configuration Information.

dmin@berl-music-pi:~ $ shairport-sync --displayConfig
         0.000860649 "shairport.c:2129" >> Display Config Start.
         0.002193314 "shairport.c:2129" 
         0.000042704 "shairport.c:2129" From "uname -a":
         0.000008185 "shairport.c:2129"  Linux berl-music-pi 6.6.51+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.6.51-1+rpt3 (2024-10-08) aarch64 GNU/Linux
         0.004496630 "shairport.c:2129" 
         0.000276685 "shairport.c:2129" From /etc/os-release:
         0.000044500 "shairport.c:2129"  Debian GNU/Linux 12 (bookworm)
         0.002592333 "shairport.c:2129" 
         0.000220186 "shairport.c:2129" From /sys/firmware/devicetree/base/model:
         0.000030685 "shairport.c:2129"  Raspberry Pi 4 Model B Rev 1.5
         0.000051629 "shairport.c:2129" 
         0.000018223 "shairport.c:2129" Shairport Sync Version String:
         0.000007814 "shairport.c:2129"  4.3.4-1-g910264e5-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc
         0.000007778 "shairport.c:2129" 
         0.000005611 "shairport.c:2129" Command Line:
         0.000005815 "shairport.c:2129"  shairport-sync --displayConfig
         0.000035426 "shairport.c:2129" 
         0.000006963 "shairport.c:2129" Configuration File:
         0.000005907 "shairport.c:2129"  /etc/shairport-sync.conf
         0.000005797 "shairport.c:2129" 
         0.000090685 "shairport.c:2129" Configuration File Settings:
         0.000009148 "shairport.c:2129"  diagnostics : 
         0.000006074 "shairport.c:2129"  {
         0.000005537 "shairport.c:2129"    log_verbosity = 1;
         0.000006019 "shairport.c:2129"  };
         0.000005481 "shairport.c:2129" 
         0.000005259 "shairport.c:2129" >> Display Config End.
         0.000012130 "shairport.c:2131" >> Goodbye!
         0.000020704 "shairport.c:1729" normal exit

PulseAudio or PipeWire installed?

Check if your system uses a Sound Server.

How did you install Shairport Sync?

Built from source

Check previous issues

Confirm

sberl · 2024-11-15T23:41:25Z

I just tried it out with the "Boot to GUI" disabled. Didn't seem to make a difference.

sberl · 2024-11-16T01:52:59Z

It's starting to smell like a permission problem. When I start shairport-sync from the command like, the process runs with my user and group privileges. When I start the service it runs with user admin group admin (who I logged in as).
When I start the service it runs as user shairport-sync and group shairport-sync.
Coul there be some files that admin has permissions for that shairport-sync does not?

sberl · 2024-11-16T02:03:32Z

A cleaner version of the startup syslog when starting the service:

Nov 15 17:59:37 berl-music-pi sudo[1464]:    admin : TTY=pts/1 ; PWD=/home/admin ; USER=root ; COMMAND=/usr/bin/systemctl start shairport-sync.service
Nov 15 17:59:37 berl-music-pi sudo[1464]: pam_unix(sudo:session): session opened for user root(uid=0) by admin(uid=1000)
Nov 15 17:59:37 berl-music-pi systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Nov 15 17:59:37 berl-music-pi sudo[1464]: pam_unix(sudo:session): session closed for user root
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.002786000 "shairport.c:2278" Startup in AirPlay 2 mode, with features 0x405c4a00,0x1c340 on device "d8:3a:dd:ed:74:7a".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000146759 "shairport.c:2317" Version String: "4.3.4-1-g910264e5-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000012574 "shairport.c:2336" Command Line: "/usr/local/bin/shairport-sync --log-to-syslog".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000217741 "shairport.c:2372" Log Verbosity is 1.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000021352 "audio_alsa.c:1082" alsa: alsa_maximum_stall_time of 0.200000 sec.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000022203 "audio_alsa.c:1371" alsa: disable_standby_mode is "never".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000008111 "audio_alsa.c:1375" alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007741 "audio_alsa.c:1377" alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000021333 "audio_alsa.c:1417" alsa: output device name is "default".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000142352 "shairport.c:2440" disable_resend_requests is off.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000016648 "shairport.c:2441" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000008797 "shairport.c:2445" statistics_requester status is 0.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007981 "shairport.c:2450" rtsp listening port is 7000.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007537 "shairport.c:2451" udp base port is 6001.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007130 "shairport.c:2452" udp port range is 10.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007167 "shairport.c:2453" player name is "Berl-music-pi".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000011277 "shairport.c:2454" backend is "alsa".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000014667 "shairport.c:2455" run_this_before_play_begins action is "(null)".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000008981 "shairport.c:2456" run_this_after_play_ends action is "(null)".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007278 "shairport.c:2457" wait-cmd status is 0.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007037 "shairport.c:2458" run_this_before_play_begins may return output is 0.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000006889 "shairport.c:2459" run_this_if_an_unfixable_error_is_detected action is "(null)".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007037 "shairport.c:2461" run_this_before_entering_active_state action is  "(null)".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007130 "shairport.c:2463" run_this_after_exiting_active_state action is  "(null)".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007333 "shairport.c:2465" active_state_timeout is  10.000000 seconds.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000010704 "shairport.c:2466" mdns backend "(null)".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007389 "shairport.c:2468" interpolation setting is "auto".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007222 "shairport.c:2472" interpolation soxr_delay_threshold is 30000000.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007074 "shairport.c:2473" resync time is 0.050000 seconds.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007907 "shairport.c:2474" resync recovery time is 0.100000 seconds.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007612 "shairport.c:2475" allow a session to be interrupted: 0.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000006740 "shairport.c:2476" busy timeout time is 120.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000008834 "shairport.c:2477" drift tolerance is 0.002000 seconds.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007777 "shairport.c:2478" password is not set.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000006797 "shairport.c:2479" default airplay volume is: -24.000000.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007944 "shairport.c:2480" high threshold airplay volume is: -16.000000.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000009630 "shairport.c:2482" check for higher-than-threshold volume for new play session is disabled.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007537 "shairport.c:2488" ignore_volume_control is 0.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007185 "shairport.c:2492" volume_max_db is not set
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000006889 "shairport.c:2493" volume range in dB (zero means use the range specified by the mixer): 0.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007278 "shairport.c:2495" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007240 "shairport.c:2499" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007426 "shairport.c:2501" disable_synchronization is 0.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000006926 "shairport.c:2502" use_mmap_if_available is 1.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000006963 "shairport.c:2503" output_format automatic selection is enabled.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000006834 "shairport.c:2507" output_rate automatic selection is enabled.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007481 "shairport.c:2511" audio backend desired buffer length is 0.200000 seconds.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007889 "shairport.c:2513" audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000009204 "shairport.c:2515" audio backend latency offset is 0.000000 seconds.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000008055 "shairport.c:2517" audio backend silence lead-in time is "auto".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000006908 "shairport.c:2521" zeroconf regtype is "_raop._tcp".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007092 "shairport.c:2522" decoders_supported field is 1.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007185 "shairport.c:2523" use_apple_decoder is 0.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007037 "shairport.c:2524" alsa_use_hardware_mute is 0.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000006908 "shairport.c:2528" no special mdns service interface was requested.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000016648 "shairport.c:2531" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000008852 "shairport.c:2561" loudness is 0.
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000007185 "shairport.c:2562" loudness reference level is -20.000000
Nov 15 17:59:37 berl-music-pi shairport-sync[1468]:          0.000798352 "shairport.c:2689" NQPTP is online.
Nov 15 17:59:39 berl-music-pi shairport-sync[1468]:          1.499743888 "shairport.c:255" "soxr" interpolation has been chosen.

// Startup complete. Now I connect my Mac

Nov 15 18:00:53 berl-music-pi shairport-sync[1468]:         74.144901437 "rtsp.c:2896" Connection 1: AP2 PTP connection from 2601:643:8200:d201:10ad:bfca:8854:484a:62168 ("Steve-MacBook-Air") to self at 2601:643:8200:d201:5cea:1576:d405:30de:7000.

// Now I start to play some music

Nov 15 18:01:19 berl-music-pi shairport-sync[1468]:         26.146910299 "rtsp.c:3253" Connection 1: SETUP AP2 no Active-Remote information  the SETUP Record.
Nov 15 18:01:19 berl-music-pi shairport-sync[1468]:          0.000090204 "rtsp.c:3272" Connection 1: SETUP AP2 doesn't include DACP-ID string information.
Nov 15 18:01:19 berl-music-pi shairport-sync[1468]:          0.000042352 "rtsp.c:3287" Connection 1. AP2 Realtime Audio Stream.
Nov 15 18:01:19 berl-music-pi shairport-sync[1468]:          0.046625444 "rtp.c:1738" AP2 Realtime Clock receiver initialised.
Nov 15 18:01:20 berl-music-pi shairport-sync[1468]:          0.701724815 "rtsp.c:2896" Connection 2: AP2 PTP connection from 2601:643:8200:d201:10ad:bfca:8854:484a:62207 ("Steve-MacBook-Air") to self at 2601:643:8200:d201:5cea:1576:d405:30de:7000.
Nov 15 18:01:20 berl-music-pi shairport-sync[1468]:          0.269681981 "rtsp.c:3253" Connection 2: SETUP AP2 no Active-Remote information  the SETUP Record.
Nov 15 18:01:20 berl-music-pi shairport-sync[1468]:          0.000081315 "rtsp.c:3272" Connection 2: SETUP AP2 doesn't include DACP-ID string information.
Nov 15 18:01:21 berl-music-pi shairport-sync[1468]:          1.499595518 "player.c:1252" Gone past starting time for 1696916512 by 12065723 nanoseconds.
Nov 15 18:01:21 berl-music-pi shairport-sync[1468]:          0.008865962 "player.c:2708" Delay error -524 when checking running latency.
Nov 15 18:01:21 berl-music-pi shairport-sync[1468]:          0.001125167 "player.c:2708" Delay error -524 when checking running latency.
Nov 15 18:01:21 berl-music-pi shairport-sync[1468]:          0.001055093 "player.c:2708" Delay error -524 when checking running latency.
Nov 15 18:01:21 berl-music-pi shairport-sync[1468]:          0.001072666 "player.c:2708" Delay error -524 when checking running latency.
Nov 15 18:01:21 berl-music-pi shairport-sync[1468]:          0.001109630 "player.c:2708" Delay error -524 when checking running latency.
Nov 15 18:01:21 berl-music-pi shairport-sync[1468]:          0.001085315 "player.c:2708" Delay error -524 when checking running latency.

mikebrady · 2024-11-16T09:58:58Z

Thanks. This is indeed an interesting problem, and I haven't come across it before. Just a few thoughts here:

It really does seem that error 524 is associated with HDMI. I have not been able to find an alsa error code (or any error code) with this value, so I suspect if might actually not be an error code but a kind of status code. If I'm right, then somehow the Shairport Sync service is trying to access an inactive HDMI port. I have no idea why that might be.
You don't explicitly specify the output device, so it'll be the default. However, the default will be different for different users.
Since your setup has a GUI, it is probably using PipeWire, both for video and audio. If you were connected up to a HDMI monitor, video and audio would be handled by PipeWire and directed to the HDMI device. In that case, for a user that has logged in via the GUI, the alsa default output device, used by Shairport Sync, is in fact a fake device that actually routes the audio to PipeWire. As a service, Shairport Sync runs under the user shairport-sync, which does not log in via the GUI, so has no defined default audio output device.
To get around this, you could explicitly configure the output device, which I recommend. To help find out what real output devices there are, there's dacquery.
There's more about issues using a sound server like PipeWire or PulseAudio here.
Unfortunately, your problems may not end there. If PipeWire is running, it will occupy an audio output device, which will not be available, or may not be available all the time.
I don't know if disabling the GUI disables PipeWire.
There is certainly the possibility of a permissions issue, though the shairport-sync user is made part of the audio group by the installer. If you could contrive to run dacquery under the shairport-sync user and log the output to a file or the log, that would help you to see what the shairport-sync user can see.
One way to do that would be to modify the shairport startup script to calldacquery (with appropriate output redirection) instead of shairport-sync. That's a bit tricky, but might be worth trying out.

sberl · 2024-11-16T17:48:38Z

Okay. Will check out dacquery.
I do see pipewire processes running, though I never knew wha they do.
Using the headphone jack is just a temporary setup for testing. Eventually, I plan to use a usb connected DAC of some kind. So specifying the output device explicitly is probably needed anyway. I have no particular reason to use the default.
Will let you know what happens.

sberl · 2024-11-16T19:06:35Z

Output from dacquery when logged in as "admin":

admin@berl-music-pi:~ $ dacquery
  --- Alsa Version: 1.2.8.
  --- Sound Cards: 3.
  --- Card 0:
        --- Name: "vc4-hdmi-0".
        --- No mixers found.
        --- Interfaces and Supported Formats:
              >>> Interface "hw:vc4hdmi0":
                  This interface appears to be for a disconnected or uninitialized HDMI port. To test it, perform the following steps:
                     (1) connect it to the HDMI device,
                     (2) turn the HDMI device on and select this device as source,
                     (3) reboot and try again.
              >>> Interface "hdmi:vc4hdmi0":
                  This interface appears to be for a disconnected or uninitialized HDMI port. To test it, perform the following steps:
                     (1) connect it to the HDMI device,
                     (2) turn the HDMI device on and select this device as source,
                     (3) reboot and try again.
  --- Card 1:
        --- Name: "vc4-hdmi-1".
        --- No mixers found.
        --- Interfaces and Supported Formats:
              >>> Interface "hw:vc4hdmi1":
                  This interface appears to be for a disconnected or uninitialized HDMI port. To test it, perform the following steps:
                     (1) connect it to the HDMI device,
                     (2) turn the HDMI device on and select this device as source,
                     (3) reboot and try again.
              >>> Interface "hdmi:vc4hdmi1":
                  This interface appears to be for a disconnected or uninitialized HDMI port. To test it, perform the following steps:
                     (1) connect it to the HDMI device,
                     (2) turn the HDMI device on and select this device as source,
                     (3) reboot and try again.
  --- Card 2:
        --- Name: "bcm2835 Headphones".
        --- Mixer:
               --------------------------------------------------------------------------------------------------------
              |  Name                              |  Index  |     Min  |     Max  |  Mute dB  |   Min dB  |   Max dB  |
               --------------------------------------------------------------------------------------------------------
              |  PCM                               |      0  |  -10239  |     400  |      Yes  |  -102.38  |     4.00  |
               --------------------------------------------------------------------------------------------------------
        --- Interfaces and Supported Formats:
              >>> Interface "hw:Headphones":
              >>> Interface "hw:CARD=Headphones,DEV=0,SUBDEV=1":
              >>> Interface "hw:CARD=Headphones,DEV=0,SUBDEV=2":
              >>> Interface "hw:CARD=Headphones,DEV=0,SUBDEV=3":
              >>> Interface "hw:CARD=Headphones,DEV=0,SUBDEV=4":
              >>> Interface "hw:CARD=Headphones,DEV=0,SUBDEV=5":
              >>> Interface "hw:CARD=Headphones,DEV=0,SUBDEV=6":
              >>> Interface "hw:CARD=Headphones,DEV=0,SUBDEV=7":
                  These interfaces support any rate, format and channel combination from the following table:
                       -------------------------------------------------------------------------------------------------------------
                      |    Rate |              Format |  Channels | Channel Map                                                     |
                       -------------------------------------------------------------------------------------------------------------
                      |    8000 |                  U8 |         1 |                                                                 |
                      |   11025 |              S16_LE |         2 |                                                                 |
                      |   16000 |                     |         3 |                                                                 |
                      |   22050 |                     |         4 |                                                                 |
                      |   32000 |                     |         5 |                                                                 |
                      |   44100 |                     |         6 |                                                                 |
                      |   48000 |                     |         7 |                                                                 |
                      |   64000 |                     |         8 |                                                                 |
                      |   88200 |                     |           |                                                                 |
                      |   96000 |                     |           |                                                                 |
                      |  176400 |                     |           |                                                                 |
                      |  192000 |                     |           |                                                                 |
                       -------------------------------------------------------------------------------------------------------------

I tried setting the interface in /etc/shairport-sync.conf to interface = "hw:Headphones" but still the same result.
I also tried "hw:CARD=Headphones,DEV=0,SUBDEV=1" but that gave a "not found" error.

mikebrady · 2024-11-16T19:54:01Z

Thanks. That dacquery result looks like what I'd expect. Could you just post the result of

$ shairport-sync --displayConfig

please?

sberl · 2024-11-18T21:55:45Z

I tried a few things with explicitly specifying the interface name, plugging in a USB sound dongle, and neither changed the problem with error 524.
I then completely rebuilt the system with Raspberry Pi OS Lite, installed nqptp and shairport-sync per the README instructions. Now it work from the command line, but fails starting as a service, but in a completely different way.
Now I see the error

Failed to create secure directory (/home/shairport-sync/.config/pulse): No such file or directory

It seems that the user and group were set up correctly, but the home directory was not created during the installation. Weird.

admin@berl-music-pi:~ $ shairport-sync --displayConfig
>> Display Config Start.

From "uname -a":
 Linux berl-music-pi 6.6.51+rpt-rpi-v8 #1 SMP PREEMPT Debian 1:6.6.51-1+rpt3 (2024-10-08) aarch64 GNU/Linux

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

From /sys/firmware/devicetree/base/model:
 Raspberry Pi 4 Model B Rev 1.5

Shairport Sync Version String:
 4.3.4-1-g910264e5-AirPlay2-smi10-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc

Command Line:
 shairport-sync --displayConfig

Configuration File:
 /etc/shairport-sync.conf

Configuration File Settings:
 pw : 
 {
 };

>> Display Config End.
>> Goodbye!

sberl · 2024-11-18T21:59:05Z

Here's the output from the "sudo make install" command in case that helps:

admin@berl-music-pi:~/shairport-sync $ sudo make install
make  install-am
make[1]: Entering directory '/home/admin/shairport-sync'
make[2]: Entering directory '/home/admin/shairport-sync'
 /usr/bin/mkdir -p '/usr/local/bin'
  /usr/bin/install -c shairport-sync '/usr/local/bin'
make  install-exec-hook
make[3]: Entering directory '/home/admin/shairport-sync'
install -d /etc
install -m 0644 ./scripts/shairport-sync.conf /etc/shairport-sync.conf.sample
[ -f /etc/shairport-sync.conf ] || cp ./scripts/shairport-sync.conf /etc/shairport-sync.conf
getent group shairport-sync &>/dev/null || groupadd -r shairport-sync &>/dev/null
getent passwd shairport-sync &>/dev/null || useradd -r -M -g shairport-sync -s /usr/sbin/nologin -G audio shairport-sync &>/dev/null
install -d /lib/systemd/system
[ -e /lib/systemd/system/shairport-sync.service ] || install -m 0644 scripts/shairport-sync.service-avahi /lib/systemd/system/shairport-sync.service
make[3]: Leaving directory '/home/admin/shairport-sync'
 /usr/bin/mkdir -p '/usr/local/share/man/man1'
 /usr/bin/install -c -m 644 ./man/shairport-sync.1 '/usr/local/share/man/man1'
make[2]: Leaving directory '/home/admin/shairport-sync'
make[1]: Leaving directory '/home/admin/shairport-sync'

mikebrady · 2024-11-18T22:19:40Z

Thanks for the update.

That line:

Failed to create secure directory (/home/shairport-sync/.config/pulse): No such file or directory

is a diagnostic from PulseAudio. But PulseAudio should not be present in a Lite version of Raspberry Pi OS.

Is it possible, somehow, that PulseAudio is installed?

sberl · 2024-11-18T22:42:48Z

I did not install it explicitly, it must have become part of the "lite" version of the os?

I do have good news though. It turns out I was specifying my output audio device with the "interface" parameter up near the top of the shairport-sync.conf file. But it seems what I really needed to do was to set it in the alsa section with the output_device parameter. If I do that it seems to be working.

mikebrady · 2024-11-19T08:44:10Z

I did not install it explicitly, it must have become part of the "lite" version of the os?

No, it shouldn't be there. It's a mystery. I'll have to try to replicate your actions to see what's happening. But I haven't seen it anywhere in the logs of a Raspberry Pi OS installation I'm running now.

I do have good news though. It turns out I was specifying my output audio device with the "interface" parameter up near the top of the shairport-sync.conf file. But it seems what I really needed to do was to set it in the alsa section with the output_device parameter. If I do that it seems to be working.

Super stuff.

mikebrady · 2024-11-28T14:27:03Z

Is it okay to close this issue now?

sberl · 2024-11-29T19:55:01Z

Yes. I think so. Thanks for the help.

…

-steve

On Thu, Nov 28, 2024 at 06:27 Mike Brady ***@***.***> wrote: Is it okay to close this issue now? — Reply to this email directly, view it on GitHub <#1931 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAHXLEJ63FKC2RORBEV76HL2C4R4ZAVCNFSM6AAAAABR4EKBP6VHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDKMBWGI2DQMRYGA> . You are receiving this because you authored the thread.Message ID: ***@***.***>

sberl added the new issue label Nov 15, 2024

mikebrady added troubleshooting and removed new issue labels Nov 16, 2024

mikebrady closed this as completed Dec 6, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Problem]: "player.c:2708" Delay error -524 when checking running latency. #1930 #1931

[Problem]: "player.c:2708" Delay error -524 when checking running latency. #1930 #1931

sberl commented Nov 15, 2024

sberl commented Nov 15, 2024

sberl commented Nov 16, 2024

sberl commented Nov 16, 2024 •

edited by mikebrady

Loading

mikebrady commented Nov 16, 2024

sberl commented Nov 16, 2024

sberl commented Nov 16, 2024 •

edited by mikebrady

Loading

mikebrady commented Nov 16, 2024 •

edited

Loading

sberl commented Nov 18, 2024 •

edited by mikebrady

Loading

sberl commented Nov 18, 2024 •

edited by mikebrady

Loading

mikebrady commented Nov 18, 2024

sberl commented Nov 18, 2024

mikebrady commented Nov 19, 2024

mikebrady commented Nov 28, 2024

sberl commented Nov 29, 2024 via email

[Problem]: "player.c:2708" Delay error -524 when checking running latency. #1930 #1931

[Problem]: "player.c:2708" Delay error -524 when checking running latency. #1930 #1931

Comments

sberl commented Nov 15, 2024

What happened?

Relevant log output

System Information.

Configuration Information.

PulseAudio or PipeWire installed?

How did you install Shairport Sync?

Check previous issues

sberl commented Nov 15, 2024

sberl commented Nov 16, 2024

sberl commented Nov 16, 2024 • edited by mikebrady Loading

mikebrady commented Nov 16, 2024

sberl commented Nov 16, 2024

sberl commented Nov 16, 2024 • edited by mikebrady Loading

mikebrady commented Nov 16, 2024 • edited Loading

sberl commented Nov 18, 2024 • edited by mikebrady Loading

sberl commented Nov 18, 2024 • edited by mikebrady Loading

mikebrady commented Nov 18, 2024

sberl commented Nov 18, 2024

mikebrady commented Nov 19, 2024

mikebrady commented Nov 28, 2024

sberl commented Nov 29, 2024 via email

sberl commented Nov 16, 2024 •

edited by mikebrady

Loading

sberl commented Nov 16, 2024 •

edited by mikebrady

Loading

mikebrady commented Nov 16, 2024 •

edited

Loading

sberl commented Nov 18, 2024 •

edited by mikebrady

Loading

sberl commented Nov 18, 2024 •

edited by mikebrady

Loading