mikebrady / shairport-sync

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

[Problem]: Audio distortion at the beginning of every song [Bluetooth] #1698

Closed teoavv94 closed 1 year ago

teoavv94 commented 1 year ago

What happened?

Hi, I've an issue with my installation on Raspberry Pi 3 with a Bluetooth speaker as output, that I don't know how to resolve. The problem is that when the player (mainly Apple Music on iPhone 12 Pro Max, but it happens with every player and on every device) the audio is distorted when a new track starts. In my opinion it seems to be a buffer problem, so I've tried to increase the buffer size of alsa but the error persist. Thanks!

PS: as you can see from the log output I've this error but it seems not to be a problem:

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

For this reason I include the result of the command "ps aux | grep shairp":

shairpo+ 541 2.1 2.5 210880 24124 ? Ssl Jun23 79:52 /usr/local/bin/shairport-sync --log-to-syslog matteo 22949 0.0 0.0 7452 572 pts/0 S+ 09:36 0:00 grep --color=auto shairp

Relevant log output - shairport-sync -v

0.000032240 "shairport.c:2420" no special mdns service interface was requested.
         0.000069843 "shairport.c:2423" configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
         0.000041407 "shairport.c:2453" loudness is 0.
         0.000033229 "shairport.c:2454" loudness reference level is -20.000000
         0.000228073 "shairport.c:2464" size of hw_addr is 8.
         0.005750364 "shairport.c:2547" NQPTP is online.
         0.001851875 "rtsp.c:5403" unable to listen on IPv4 port 7000. The error is: "Address already in use".
         0.000200625 "rtsp.c:5403" unable to listen on IPv6 port 7000. The error is: "Address already in use".
         0.000058906 "rtsp.c:5587" *warning: could not establish a service on port 7000 -- program terminating. Is another instance of Shairport Sync running on this device?
         0.000045000 "rtsp.c:5591" Oops -- fell out of the RTSP select loop
         1.495887812 "shairport.c:254" "soxr" interpolation has been chosen.
         0.000616563 "shairport.c:1674" normal exit

Relevant log output - syslog

May 29 19:48:29 raspberrypi kernel: [393678.733475] input: JBL Go 3 (AVRCP) as /devices/virtual/input/input8
May 29 19:48:29 raspberrypi bluetoothd[1268]: /org/bluez/hci0/dev_40_C1_F6_50_3E_B2/fd7: fd(38) ready
May 29 19:48:30 raspberrypi systemd-udevd[30347]: event1: Process '/usr/sbin/th-cmd --socket /var/run/thd.socket --passfd --udev' failed with exit code 1.
May 29 19:52:47 raspberrypi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver...
May 29 19:52:48 raspberrypi systemd[1]: shairport-sync.service: Succeeded.
May 29 19:52:48 raspberrypi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver.
May 29 19:52:48 raspberrypi systemd[1]: shairport-sync.service: Consumed 1h 44min 25.804s CPU time.
May 29 19:52:48 raspberrypi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
May 29 19:52:49 raspberrypi shairport-sync: warning: could not establish a service on port 7000 -- program terminating. Is another instance of Shairport Sync running on this device?
May 29 19:52:50 raspberrypi shairport-sync[30906]: Failed to load cookie file from cookie: No such file or directory
May 29 19:52:50 raspberrypi shairport-sync[30906]: Failed to load cookie file from cookie: No such file or directory
May 29 19:52:50 raspberrypi systemd[1]: shairport-sync.service: Succeeded.
May 29 19:52:50 raspberrypi systemd[1]: shairport-sync.service: Consumed 1.732s CPU time.
May 29 19:53:00 raspberrypi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
May 29 19:53:00 raspberrypi shairport-sync[31096]: Failed to load cookie file from cookie: No such file or directory
May 29 19:53:00 raspberrypi shairport-sync[31096]: Failed to load cookie file from cookie: No such file or directory
May 29 19:58:20 raspberrypi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver...
May 29 19:58:20 raspberrypi systemd[1]: shairport-sync.service: Succeeded.
May 29 19:58:20 raspberrypi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver.
May 29 19:58:20 raspberrypi systemd[1]: shairport-sync.service: Consumed 22.317s CPU time.
May 29 19:58:21 raspberrypi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
May 29 19:58:21 raspberrypi shairport-sync[31371]: Failed to load cookie file from cookie: No such file or directory
May 29 19:58:21 raspberrypi shairport-sync[31371]: Failed to load cookie file from cookie: No such file or directory
May 29 20:00:09 raspberrypi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver...
May 29 20:00:09 raspberrypi systemd[1]: shairport-sync.service: Succeeded.
May 29 20:00:09 raspberrypi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver.
May 29 20:00:09 raspberrypi systemd[1]: shairport-sync.service: Consumed 8.069s CPU time.
May 29 20:00:09 raspberrypi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
May 29 20:00:10 raspberrypi shairport-sync[31475]: Failed to load cookie file from cookie: No such file or directory
May 29 20:00:10 raspberrypi shairport-sync[31475]: Failed to load cookie file from cookie: No such file or directory

Configuration Information.

>> Display Config Start.

From "uname -a":
 Linux raspberrypi 6.1.21-v7+ #1642 SMP Mon Apr  3 17:20:52 BST 2023 armv7l GNU/Linux

From /etc/os-release:
 Raspbian GNU/Linux 11 (bullseye)

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

Shairport Sync Version String:
 4.1.1-5-g69d3b02a-AirPlay2-alac-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc

Command Line:
 shairport-sync --displayConfig

Configuration File:
 /etc/shairport-sync.conf

Configuration File Settings:
 general : 
 {
   name = "JBL GO 3";
   interpolation = "auto";
   alac_decoder = "apple";
   audio_backend_latency_offset_in_seconds = -0.125;
   regtype = "_airplay._tcp";
 };
 sessioncontrol : 
 {
   allow_session_interruption = "yes";
 };
 alsa : 
 {
   output_device = "default";
   output_rate = 44100;
   output_format = "S16";
   disable_standby_mode = "auto";
   buffer_size = 2048;
 };

>> Display Config End.
>> Goodbye!

How did you install Shairport Sync?

A package manager (apt, apt install, yum, pkg, etc.)

Check previous issues

mikebrady commented 1 year ago

Thanks for the post. There are quite a few things to tease out here.

First, the syslog above is not informative. To get debug log from Shairport Sync ("SPS"), set the log_verbosity to 1 and set --statistics to "yes" in the configuration file and restart.

Second, a lot is happening to the audio when it leaves SPS. I imagine that the path is something like:

SPS → alsa `default` device → PulseAudio → (44.1k to 48k transcode) → Bluetooth Audio

Third, I guess that the buffer_size = 2048; is probably not needed. Also, it might be worth (temporarily at least) setting the audio_backend_latency_offset_in_seconds to 0.

If you could run SPS through a track and a track-to-next-track transition and post the log, that would be useful.

teoavv94 commented 1 year ago

Hi Mike thank you. I've made the log by changing the configuration file as you suggested (I've left only the negative delay of 125 ms, as in my previous tests the problem persisted even with 0 delay), you can read the output it in the attached text file.

Log SPS.txt

mikebrady commented 1 year ago

Thanks -- that's interesting. It seems that at the start SPS was running twice. Really, only one copy should be running at a time. You can see that the second instance of it stopped after a while.

Anyway, a quick way to check if SPS is introducing distortion is to disable synchronisation. In the alsa stanza of the configuration file:

    disable_synchronization = "yes"; // Set to "yes" to disable synchronization. Default is "no" 

Make the change and restart, and listen to hear if the distortion is still there. Also, please post the log, and let's see what's happening.

teoavv94 commented 1 year ago

With a quick test seems to be almost resolved, some minor random delay still present during some song (no more at the beginning, even with a very quick track change!) but it is very less annoying, even my HomePod Mini have a similar behavior sometimes... So I consider it an airplay flaw. Anyway I paste the new log.

Log SPS no_sync.txt

mikebrady commented 1 year ago

Thanks for the update. Another setting to try would be to increase the size of the buffer SPS tries to maintain in the output device from the default of 0.2 to, maybe, 0.5 seconds. The setting is in the general stanza:

    audio_backend_buffer_desired_length_in_seconds = 0.5;

Does that makes a difference?

teoavv94 commented 1 year ago

Hi Mike, this issue has been resolved. I tested the audio for about 2 hours and didn't hear any distortion. But another issue occurred, I think is not directly related to SPS... As you can see at the end of the new log bluetooth disconnect automatically for saving energy even if SPS is playing something. I hope that you can help me even with this issue.

SPS_backend_buffer.txt

mikebrady commented 1 year ago

Thanks for the update!

I'm afraid I don't have any suggestions to offer on the Bluetooth issue; perhaps some other contributors might have some ideas.

github-actions[bot] commented 1 year ago

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