search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.29k stars 574 forks source link

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

Open sberl opened 2 hours ago

sberl commented 2 hours ago

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?

How did you install Shairport Sync?

Built from source

Check previous issues

sberl commented 1 hour ago

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