self-compiled snapclient on OpenSuSE 64-Bit doesn't work

[hp4]

Describe the bug
I have a collection of snapserver/snapclients working fine on Raspberry
Pis. My self-compiled snapclient on an OpenSuSE 64-Bit produces stuttering sound.

Everything works fine with pulseaudio, local and remote.

Routing snapclient with "--player file | aplay -f cd" to ALSA also works fine

Only snapclient -> pulseaudio doesn't work, see log below : snd_pcm_avail_delay failed

Steps to Reproduce

1. build snapclient on OpenSuSE and start it (Server on remote Raspberry)

Environment details

• OS: OpenSuSE Tumbleweed 64-Bit
• Snapcast version : current cloned git-repository
• self compiled, ...

Attach logfile if applicable
Generate logs with snapclient --logfilter debug or snapserver --logging.filter debug if possible and paste them in the following codeblock

2020-11-23 16-31-58.364 [Info] (Connection) Resolving host IP for: vesta.planeten.hp4
2020-11-23 16-31-58.364 [Info] (Connection) Connecting
2020-11-23 16-31-58.369 [Notice] (Connection) Connected to 192.168.85.8
2020-11-23 16-31-58.369 [Info] (Connection) My MAC: "f4:6d:04:75:1d:05", socket: 8
2020-11-23 16-31-58.378 [Debug] (Connection) outstanding async_write
2020-11-23 16-31-58.384 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 87, muted: 0
metadata:{"STREAM":"Mopidy-Vesta"}
2020-11-23 16-31-58.385 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2
2020-11-23 16-31-58.385 [Info] (Player) Player name: alsa, device: default, description: Default ALSA Output (currently PulseAudio Sound Server), idx: 7, sharing mode: unspecified, parameters: <none>
2020-11-23 16-31-58.385 [Info] (Player) Mixer mode: software, parameters: <none>
2020-11-23 16-31-58.385 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2
2020-11-23 16-31-58.586 [Debug] (Alsa) PCM name: default
2020-11-23 16-31-58.586 [Debug] (Alsa) PCM state: PREPARED
2020-11-23 16-31-58.586 [Debug] (Alsa) channels: 2
2020-11-23 16-31-58.586 [Debug] (Alsa) rate: 48000 bps
2020-11-23 16-31-58.586 [Debug] (Alsa) frames: 720
2020-11-23 16-31-58.586 [Debug] (Alsa) period time: 15000
2020-11-23 16-31-58.586 [Warn] (Alsa) setVolume exp with base 10: 0.87 => 0.712567
2020-11-23 16-31-58.586 [Warn] (Alsa) snd_pcm_avail_delay failed: Input/output error, avail: 0, delay: 0, retrying.
2020-11-23 16-31-58.591 [Debug] (Alsa) Resizing buffer from 0 to 11520
2020-11-23 16-31-58.592 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe, avail: 2880, delay: 0, retrying.
2020-11-23 16-31-58.602 [Warn] (Alsa) snd_pcm_avail_delay failed again: Broken pipe, avail: 2880, delay: 0, using snd_pcm_avail and snd_pcm_delay.
2020-11-23 16-31-58.602 [Warn] (Alsa) snd_pcm_avail and snd_pcm_delay failed: Success, avail: -32, delay: 2879
2020-11-23 16-31-58.615 [Warn] (Alsa) snd_pcm_avail_delay failed: Input/output error, avail: -32, delay: 2879, retrying.
2020-11-23 16-31-58.621 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe, avail: 2880, delay: 0, retrying.
2020-11-23 16-31-58.631 [Warn] (Alsa) snd_pcm_avail_delay failed again: Broken pipe, avail: 2880, delay: 0, using snd_pcm_avail and snd_pcm_delay.
2020-11-23 16-31-58.631 [Warn] (Alsa) snd_pcm_avail and snd_pcm_delay failed: Success, avail: -32, delay: 2878
2020-11-23 16-31-58.644 [Warn] (Alsa) snd_pcm_avail_delay failed: Input/output error, avail: -32, delay: 2878, retrying.

[badaix]

Seems that the device "Default ALSA Output (currently PulseAudio Sound Server)" cannot properly report the current buffer size and latency.
Can you try another device, e.g. some with direct hardware access (without PulseAudio)? (Option -s <index>, available PCM devices are listed with -l).
Alternatively you can try the brand new PulseAudio backend in develop branch. It can be activated with --player pulse.

[hp4]

I'm wondering that I can play audio files locally with pulseaudio and I can stream files via pulseaudio over the network. As you said it's probably an interface problem locally between snapclient and pulseaudio, since snapclient works directly with alsa. And since all my Raspi-snapclients run fine, I think it might be a 64-Bit-(build?)-problem, e.g. if int or long-int or short-int variables are inconsistently used as parameters?

I couldn't get snapclient running with one of the other devices, sorry I'm not an audio expert:

some of the devices with snapclient -l:

6: upmix
Plugin for channel upmix (4,6,8)

7: default
Default ALSA Output (currently PulseAudio Sound Server)

8: sysdefault:CARD=PCH
HDA Intel PCH, ALC887-VD Analog
Default Audio Device

9: front:CARD=PCH,DEV=0
HDA Intel PCH, ALC887-VD Analog
Front output / input

10: surround21:CARD=PCH,DEV=0
HDA Intel PCH, ALC887-VD Analog
2.1 Surround output to Front and Subwoofer speakers

11: surround40:CARD=PCH,DEV=0
HDA Intel PCH, ALC887-VD Analog
4.0 Surround output to Front and Rear speakers

12: surround41:CARD=PCH,DEV=0
HDA Intel PCH, ALC887-VD Analog
4.1 Surround output to Front, Rear and Subwoofer speakers

pulseaudio #7 gives stuttering sound,
card PCH #8 shows "ALSA lib pcm_dmix.c:1075:(snd_pcm_dmix_open) unable to open slave"
devices 9-12 produce no error but also no sound (may be I would have to install more speakers to the surround-outputs)

Since I've not very much experience with git: can you give me a hint how to clone your develop branch ?

[badaix]

Seems that all your devices are looped through PulseAudio.
You can play files with PulseAudio because this doesn't rely on snd_pcm_avail and snd_pcm_delay which is needed for synced playback.
cd into the cloned snapcast directory and git checkout develop

[badaix]

duplicate of #722

[hp4]

thanks for your quick responses.

Is it really a duplicate? My openSuSE-client is a remote client, not local on the snapcast-server. Everything works fine, when I simply use an Raspi-Archlinux/32Bit-Client instead of the openSuSE-x86-64Bit-client.

[badaix]

It looks like the same issue for me. It's not related to where the client is running, so it makes sense to link these two issues.

Issue #722 is having the same problem when playing through PulseAudio:

2020-11-17 21-44-58.997 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe, avail: 2646, delay: 0, retrying.
2020-11-17 21-44-59.008 [Warn] (Alsa) snd_pcm_avail_delay failed again: Broken pipe, avail: 2646, delay: 0, using snd_pcm_avail and snd_pcm_delay.
2020-11-17 21-44-59.008 [Warn] (Alsa) snd_pcm_avail and snd_pcm_delay failed: Success, avail: -32, delay: 2643
2020-11-17 21-44-59.019 [Warn] (Alsa) snd_pcm_avail_delay failed: Input/output error, avail: -32, delay: 2643, retrying.
2020-11-17 21-44-59.026 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe, avail: 2646, delay: 0, retrying.
2020-11-17 21-44-59.036 [Warn] (Alsa) snd_pcm_avail_delay failed again: Broken pipe, avail: 2646, delay: 0, using snd_pcm_avail and snd_pcm_delay.
2020-11-17 21-44-59.036 [Warn] (Alsa) snd_pcm_avail and snd_pcm_delay failed: Success, avail: -32, delay: 2643
2020-11-17 21-44-59.047 [Warn] (Alsa) snd_pcm_avail_delay failed: Input/output error, avail: -32, delay: 2643, retrying.
2020-11-17 21-44-59.055 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe, avail: 2646, delay: 0, retrying.
2020-11-17 21-44-59.065 [Warn] (Alsa) snd_pcm_avail_delay failed again: Broken pipe, avail: 2646, delay: 0, using snd_pcm_avail and snd_pcm_delay.
2020-11-17 21-44-59.065 [Warn] (Alsa) snd_pcm_avail and snd_pcm_delay failed: Success, avail: -32, delay: 2643
2020-11-17 21-44-59.077 [Warn] (Alsa) snd_pcm_avail_delay failed: Input/output error, avail: -32, delay: 2643, retrying.
2020-11-17 21-44-59.084 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe, avail: 2646, delay: 0, retrying.
2020-11-17 21-44-59.095 [Warn] (Alsa) snd_pcm_avail_delay failed again: Broken pipe, avail: 2646, delay: 0, using snd_pcm_avail and snd_pcm_delay.
2020-11-17 21-44-59.095 [Warn] (Alsa) snd_pcm_avail and snd_pcm_delay failed: Success, avail: -32, delay: 2644

Unfortunately there was no feedback yet, if the pulse backend is solving the problem or not, but the original poster managed to get audio running by using alsa directly:

But I did manage to switch to alsa and get rid of the abomination that is pulseaudio.

On all of my machines there are PulseAudio as well as direct alsa devices, e.g.:

0: default
Playback/recording through the PulseAudio sound server
...
32: hw:CARD=Intel,DEV=0
HDA Intel, CX20561 Analog
Direct hardware device without any conversions

BTW: What sound device are you using (vendor, model)?

[hp4]

Seems that the device "Default ALSA Output (currently PulseAudio Sound Server)" cannot properly report the current buffer size and latency.
Can you try another device, e.g. some with direct hardware access (without PulseAudio)? (Option -s <index>, available PCM devices are listed with -l).
Alternatively you can try the brand new PulseAudio backend in develop branch. It can be activated with --player pulse.

sorry for the delay: I've now compiled the develop-branch and replaced the binary snapclient.

Now everytyhing works fine with the option --player pulse !!!

So since all other audio functions with pulseaudio are ok locally and remote, I think, that the "release"-(non-develop)-snapclient doesn't work correctly with the pulseaudio-alsa-environment. Since the "release"-snapclient works fine with "--player file | aplay -f cd", it obviously is "pulseaudio-in-the-middle"-problem. And since all other applications work with "pulseaudio-in-the-middle", it's probably the snapclient interface, but only in X86-64Bit-architecture.

I've also seen that pulseaudio displays reasonable values for latency/buffer size in status-commands with pactl. So may be these values are corrupted on the way back to snapclient or misinterpreted?

[hp4]

additional info:
the snapclient-binary in the develop-branch references the following new libraries: libpulse.so.0 libpulsecommon-13.0.so libxcb.so.1 libsndfile.so.1 libXau.so.6 libvorbisenc.so.2 libspeex.so.1

Since the old binary didn't reference any pulseaudio-library I'm wondering, why the problem only occurs with pulseaudio in the middle. Are the failing calls to "snd_pcm_avail_delay" located in the libasound-library? And are they not used when playing directly to alsa or when using the new option "--player pulse"?

[hp4]

BTW: What sound device are you using (vendor, model)?

I'm working with an older Tower-PC with an NVIDIA-card, which is currently disabled. So the speakers are connected to the (mainboard?)-audio, which seems to be Intel.

As inexperienced audio-user I'm not sure how to retrieve the HW-information.

Pulseaudio reports:
alsa.card = "0"
alsa.card_name = "HDA Intel PCH"
alsa.long_card_name = "HDA Intel PCH at 0xf6300000 irq 41"
alsa.driver_name = "snd_hda_intel"

Alsa reports:
Karte 0: PCH [HDA Intel PCH], Gerät 0: ALC887-VD Analog [ALC887-VD Analog]
Sub-Geräte: 0/1
Sub-Gerät #0: subdevice #0
Karte 0: PCH [HDA Intel PCH], Gerät 1: ALC887-VD Digital [ALC887-VD Digital]
Sub-Geräte: 1/1
Sub-Gerät #0: subdevice #0

[badaix]

I think that this is not a general amd64 issue. I have Linux Mint 64 bit running on a core2-duo (Mint 18.3) and on a Ryzen 5 (Mint 20). On both machines snd_pcm_avail_delay returns successfully.
I don't now how Alsa over PulseAudio is working in detail, but I guess that PulseAudio provides some virtual PCM device driver that interfaces with Alsa and maybe this driver does not implement all features.
However: in your case the delay is reported, while avail (=free space in the PCM's ringbuffer) returns some negative number. Since the average buffer size is known to the Alsa player, it can be fed to the PCM device. If it's larger or smaller than the actual available PCM buffer then the next iteration will be earlier or later, but it shouldn't cause any buffer underruns and drops.
I've added this fallback to the develop branch. It might log some continuous warnings, but should work.
Would be great if you could test it.

[badaix]

@hp4 can you please test if the current develop branch fixes this issue?

2020-11-23 16-31-58.592 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe, avail: 2880, delay: 0, retrying.
2020-11-23 16-31-58.602 [Warn] (Alsa) snd_pcm_avail_delay failed again: Broken pipe, avail: 2880, delay: 0, using snd_pcm_avail and snd_pcm_delay.
2020-11-23 16-31-58.602 [Warn] (Alsa) snd_pcm_avail and snd_pcm_delay failed: Success, avail: -32, delay: 2879
2020-11-23 16-31-58.615 [Warn] (Alsa) snd_pcm_avail_delay failed: Input/output error, avail: -32, delay: 2879, retrying.
2020-11-23 16-31-58.621 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe, avail: 2880, delay: 0, retrying.
2020-11-23 16-31-58.631 [Warn] (Alsa) snd_pcm_avail_delay failed again: Broken pipe, avail: 2880, delay: 0, using snd_pcm_avail and snd_pcm_delay.
2020-11-23 16-31-58.631 [Warn] (Alsa) snd_pcm_avail and snd_pcm_delay failed: Success, avail: -32, delay: 2878
2020-11-23 16-31-58.644 [Warn] (Alsa) snd_pcm_avail_delay failed: Input/output error, avail: -32, delay: 2878, retrying.

[TurboGraphxBeige]

@hp4 can you please test if the current develop branch fixes this issue?

2020-11-23 16-31-58.592 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe, avail: 2880, delay: 0, retrying.
2020-11-23 16-31-58.602 [Warn] (Alsa) snd_pcm_avail_delay failed again: Broken pipe, avail: 2880, delay: 0, using snd_pcm_avail and snd_pcm_delay.
2020-11-23 16-31-58.602 [Warn] (Alsa) snd_pcm_avail and snd_pcm_delay failed: Success, avail: -32, delay: 2879
2020-11-23 16-31-58.615 [Warn] (Alsa) snd_pcm_avail_delay failed: Input/output error, avail: -32, delay: 2879, retrying.
2020-11-23 16-31-58.621 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe, avail: 2880, delay: 0, retrying.
2020-11-23 16-31-58.631 [Warn] (Alsa) snd_pcm_avail_delay failed again: Broken pipe, avail: 2880, delay: 0, using snd_pcm_avail and snd_pcm_delay.
2020-11-23 16-31-58.631 [Warn] (Alsa) snd_pcm_avail and snd_pcm_delay failed: Success, avail: -32, delay: 2878
2020-11-23 16-31-58.644 [Warn] (Alsa) snd_pcm_avail_delay failed: Input/output error, avail: -32, delay: 2878, retrying.

It does fix this issue for me.
This commit: 99f7626

I was running 0.22 (latest release) for ARM on a Raspberry Pi 3b+

[badaix]

thanks @TurboGraphxBeige for the feedback. I can see such snd_pcm_avail_* messages on one of my machines for two or maybe three times. From this I could guess what happens on @hp4 and @NDahlem clients, but I cannot really reproduce it, so I've implemented some workarounds and relaxed some constraints, googled around, checked the alsa lib source code and alsa lib sample client implementations. Adding snd_pcm_start ultimately fixed the two, three times occurrence of this message on my client, but broke it on other clients "in the field". This alsa player is a very sensitive and crucial part and I'm afraid to release it without indication of the original issue reporters that this bug (#727 and #722) is fixed for them.
It's really disappointing if you waste your spare time trying to fix bugs that you cannot reproduce and to beg for feedback from the issue reporter. Maybe I will revert the changes to the original state which is known to work for most users.

[TurboGraphxBeige]

That's why I felt the need to report back to you! So much time invested!

Strange thing is that I didn't have those errors before and I don't even know when this problem started to occur. Same machine, same hardware, etc. No change that I am aware of.

It only happens when I run snapclient on the same machine that snapserver runs. I get literally flooded with snd_pcm_avail* errors/warnings as soon as there's a pulseaudio stream going through snapcast's pipe-sink. All the other snapclients on other machines would playback the snapserver stream.

What I don't understand is that it looks like snapclient is trying to open an Alsa device but it's supposed to output to Pulseaudio.

Should I open another issue maybe? I didn't think it needed to open an issue at first because I thought it was a misconfiguration on my machine. What do you think?

[badaix]

@TurboGraphxBeige

Strange thing is that I didn't have those errors before and I don't even know when this problem started to occur. Same machine, same hardware, etc. No change that I am aware of.

It only happens when I run snapclient on the same machine that snapserver runs. I get literally flooded with snd_pcm_avail* errors/warnings as soon as there's a pulseaudio stream going through snapcast's pipe-sink. All the other snapclients on other machines would playback the snapserver stream.

Do you still get these messages? How do you start snapclient? Are you using the --player or -s option?

What I don't understand is that it looks like snapclient is trying to open an Alsa device but it's supposed to output to Pulseaudio.

Should I open another issue maybe? I didn't think it needed to open an issue at first because I thought it was a misconfiguration on my machine. What do you think?

I don't fully understand this. If you start snapclient with --player alsa or without the --player option, it will use alsa and if you use --player pulse, it will use pulse.

When using alsa with the default device, the audio will most probably be routed through pulse, because on most systems there will be a virtual alsa device set as default:

0: default
Playback/recording through the PulseAudio sound server

as you can read here:
https://www.freedesktop.org/wiki/Software/PulseAudio/Documentation/Users/Troubleshooting/
https://www.freedesktop.org/wiki/Software/PulseAudio/Documentation/User/PerfectSetup/

@hp4 can you check if the problem is solved with the latest develop version using alsa?

[TurboGraphxBeige]

I don't have these messages anymore (I removed the latest official release to install 99f7626). I start snapclient with a systemd service and the only client option is -s 0.

If I recall, I tried using --player pulse but still gave me errors.

I'll have to test everything again with the latest official release. I'll try changing ALSA configurations.

[badaix]

@TurboGraphxBeige sounds good. If you have problems with --player pulse (only available in develop snapshots), then please open an issue for this and add a debug log of the client.