Snapcast: Snapclient breaks when disconnecting usb output

Created on 25 May 2016  路  25Comments  路  Source: badaix/snapcast

I stream my mpd music with snapcast from one raspberry to itself and to another raspberry that is connected over wifi.
The main raspberry is connected over usb to a sound system with integrated usb-sound card.
If I run snapclient connected directly to alsa it works without too much time corrections.
But if I shutdown my sound-system snapclient is breaking. It runs on full cpu consumption until I kill it and after killing it is staying as zombie. 

2016-05-25 22-09-53 [err] ERROR. Can't write to PCM device: Input/output error
2016-05-25 22-11-27 [err] Controller::onException: read_some: End of file

So to get the snapclient running again I have to reboot the raspberry.

2016-05-25 22-24-55 [err] Controller::onException: Can't open default PCM device: File descriptor in bad state

As workaround I send the output of the snapclient to pulseaudio.
This is working because if the usb-soundcard is disconnected pulseaudio is still running, so the snapclient is still running too.
But pulseaudio causes a lot of time corrections.
The Snapserver looks like this:

2016-05-25 21-20-27 [out] onResync (default): 8ms
2016-05-25 21-20-32 [out] onResync (default): 3ms
2016-05-25 21-20-35 [out] onResync (default): 7ms
2016-05-25 21-20-36 [out] onResync (default): 5ms
2016-05-25 21-20-36 [out] onResync (default): 11ms
2016-05-25 21-20-41 [out] onResync (default): 3ms
2016-05-25 21-20-41 [out] onResync (default): 2ms
2016-05-25 21-20-43 [out] onResync (default): 3ms
2016-05-25 21-20-53 [out] onResync (default): 4ms
2016-05-25 21-20-53 [out] onResync (default): 2ms
2016-05-25 21-20-55 [out] onResync (default): 1ms
2016-05-25 21-21-02 [out] onResync (default): 9ms
2016-05-25 21-21-08 [out] onResync (default): 2ms
2016-05-25 21-21-10 [out] onResync (default): 2ms
2016-05-25 21-21-13 [out] onResync (default): 3ms
2016-05-25 21-21-16 [out] onResync (default): 3ms
2016-05-25 21-21-26 [out] onResync (default): 1ms
2016-05-25 21-21-30 [out] onResync (default): 1ms
2016-05-25 21-21-33 [out] onResync (default): 2ms
2016-05-25 21-21-43 [out] onResync (default): 3ms
2016-05-25 21-21-45 [out] onResync (default): 1ms
2016-05-25 21-21-46 [out] onResync (default): 1ms
2016-05-25 21-21-48 [out] onResync (default): 2ms
2016-05-25 21-21-48 [out] onStateChanged (default): 1
2016-05-25 21-21-48 [out] onResync (default): 98ms
2016-05-25 21-21-48 [out] onStateChanged (default): 2
2016-05-25 21-21-48 [out] onResync (default): 1ms
2016-05-25 21-21-50 [out] onResync (default): 1ms
2016-05-25 21-21-50 [out] onResync (default): 2ms
2016-05-25 21-21-54 [out] onResync (default): 3ms
2016-05-25 21-21-55 [out] onResync (default): 8ms
2016-05-25 21-21-57 [out] onResync (default): 4ms
2016-05-25 21-21-59 [out] onResync (default): 3ms
2016-05-25 21-21-59 [out] onResync (default): 1ms
2016-05-25 21-22-01 [out] onResync (default): 1ms
2016-05-25 21-22-01 [out] onResync (default): 1ms
2016-05-25 21-22-03 [out] onResync (default): 1ms
2016-05-25 21-22-06 [out] onResync (default): 7ms
2016-05-25 21-22-10 [out] onResync (default): 2ms
2016-05-25 21-22-16 [out] onResync (default): 5ms
2016-05-25 21-22-16 [out] onResync (default): 2ms
2016-05-25 21-22-18 [out] onResync (default): 1ms
2016-05-25 21-22-22 [out] onResync (default): 1ms
2016-05-25 21-22-26 [out] onResync (default): 5ms
2016-05-25 21-22-28 [out] onResync (default): 2ms
2016-05-25 21-22-30 [out] onResync (default): 2ms
2016-05-25 21-22-32 [out] onResync (default): 1ms
2016-05-25 21-22-32 [out] onResync (default): 4ms
2016-05-25 21-22-40 [out] onResync (default): 1ms
2016-05-25 21-22-42 [out] onResync (default): 1ms
2016-05-25 21-22-46 [out] onResync (default): 2ms
2016-05-25 21-22-46 [out] onResync (default): 3ms
2016-05-25 21-22-47 [out] onResync (default): 2ms
2016-05-25 21-22-50 [out] onResync (default): 1ms
2016-05-25 21-22-52 [out] onResync (default): 2ms
2016-05-25 21-22-52 [out] onResync (default): 3ms
2016-05-25 21-22-52 [out] onStateChanged (default): 1
2016-05-25 21-22-52 [out] onResync (default): 103ms
2016-05-25 21-22-52 [out] onStateChanged (default): 2
2016-05-25 21-22-56 [out] onResync (default): 1ms
2016-05-25 21-22-58 [out] onResync (default): 2ms
2016-05-25 21-22-58 [out] onResync (default): 4ms
2016-05-25 21-23-04 [out] onResync (default): 2ms
2016-05-25 21-23-04 [out] onResync (default): 2ms
2016-05-25 21-23-06 [out] onResync (default): 4ms
2016-05-25 21-23-06 [out] onResync (default): 1ms
2016-05-25 21-23-11 [out] onResync (default): 1ms
2016-05-25 21-23-11 [out] onResync (default): 8ms
2016-05-25 21-23-11 [out] onResync (default): 2ms
2016-05-25 21-23-13 [out] onResync (default): 2ms
2016-05-25 21-23-13 [out] onResync (default): 5ms
2016-05-25 21-23-18 [out] onResync (default): 1ms
2016-05-25 21-23-18 [out] onResync (default): 1ms
2016-05-25 21-23-18 [out] onResync (default): 1ms
2016-05-25 21-23-22 [out] onResync (default): 3ms
2016-05-25 21-23-22 [out] onResync (default): 9ms
2016-05-25 21-23-31 [out] onResync (default): 3ms
2016-05-25 21-23-35 [out] onResync (default): 6ms
2016-05-25 21-23-41 [out] onResync (default): 1ms
2016-05-25 21-23-43 [out] onResync (default): 1ms
2016-05-25 21-23-45 [out] onResync (default): 2ms
2016-05-25 21-23-47 [out] onResync (default): 1ms
2016-05-25 21-23-53 [out] onStateChanged (default): 1
2016-05-25 21-23-53 [out] onResync (default): 88ms
2016-05-25 21-23-53 [out] onStateChanged (default): 2
2016-05-25 21-23-53 [out] onResync (default): 3ms
2016-05-25 21-23-53 [out] onResync (default): 3ms
2016-05-25 21-23-59 [out] onResync (default): 9ms
2016-05-25 21-24-01 [out] onResync (default): 2ms
2016-05-25 21-24-03 [out] onResync (default): 5ms
2016-05-25 21-24-03 [out] onResync (default): 3ms
2016-05-25 21-24-03 [out] onResync (default): 4ms
2016-05-25 21-24-03 [out] onResync (default): 3ms
2016-05-25 21-24-03 [out] onResync (default): 2ms

(What do onStateChanged mean?)

I tried to adjust the buffer size, the pipe read buffer size and the codec but it didn't help.
By the way it would be nice if it is documented how the buffers effect the sound quality.

In the end the best would be to use alsa directly.

So maybe someone can fix the bug that breaks snapclient when it is disconnected from a usb audio output.

bug next release
Source
picture Mo-M
👍1

All 25 comments

This bugs the OpenWrt very well, as the PulseAudio is not a viable workaround.

xabolcs picture xabolcs on 1 Nov 2019

Building snapclient from v0.16.0 (at f79455042ddfe2fe997ad86e31c79da1a5ab0ad5) on x86_64 I'm unable to reproduce the issue, as it aborts on disconnect:

2019-11-01 16-01-45 [Info] Sleep 0, age: -8, bufferDuration: 21
2019-11-01 16-01-45 [Info] Sleep 0
2019-11-01 16-01-46 [Info] Chunk: -88   -88 -88 -88 13  82
2019-11-01 16-01-47 [Info] Chunk: -91   -91 -91 -91 60  81
2019-11-01 16-01-47 [Err] ERROR. Can't write to PCM device: No such device
ALSA lib confmisc.c:767:(parse_card) cannot find card 'DAC'
ALSA lib conf.c:4528:(_snd_config_evaluate) function snd_func_card_driver returned error: No such device
ALSA lib confmisc.c:392:(snd_func_concat) error evaluating strings
ALSA lib conf.c:4528:(_snd_config_evaluate) function snd_func_concat returned error: No such device
ALSA lib confmisc.c:1246:(snd_func_refer) error evaluating name
ALSA lib conf.c:4528:(_snd_config_evaluate) function snd_func_refer returned error: No such device
ALSA lib conf.c:5007:(snd_config_expand) Evaluate error: No such device
ALSA lib pcm.c:2495:(snd_pcm_open_noupdate) Unknown PCM sysdefault:CARD=DAC
2019-11-01 16-01-47 [Err] Exception in initAlsa: Can't open sysdefault:CARD=DAC PCM device: No such device
snapclient: pcm.c:1062: snd_pcm_delay: Assertion `pcm' failed.
Aborted

Where sysdefault:CARD=DAC is the USB sound card selected with the -s command line parameter.

I'm going to test it on mips_24kc.

xabolcs picture xabolcs on 1 Nov 2019

With 86c416add3be448c59ac8a64b95b259f7700533c the log says that snd_pcm_drain doesn't return:

2019-11-02 11-44-25 [Info] Sleep 0
2019-11-02 11-44-26 [Info] Chunk: -32   -32 -32 -32 19  64
2019-11-02 11-44-27 [Info] Chunk: -32   -32 -32 -32 66  64
2019-11-02 11-44-27 [Err] ERROR. Can't write to PCM device: I/O error
2019-11-02 11-44-27 [Info] uninitAlsa: entered
2019-11-02 11-44-27 [Info] uninitAlsa: if handle_ != nullptr entered
2019-11-02 11-44-27 [Info] uninitAlsa: snd_pcm_drain entering
^Csignal: 2
2019-11-02 11-44-48 [Info] Received signal 2: Interrupt
2019-11-02 11-44-48 [Err] Controller::onException: read_some: End of file
^Csignal: 2
terminate called after throwing an instance of 'std::future_error'
  what():  std::future_error: Promise already satisfied
^C^C^C^C
xabolcs picture xabolcs on 2 Nov 2019

With commit 158b363da8b36c73d2788d5a9d0a9a340178207b it segfaults instead abort :upside_down_face: 

2019-11-02 12-06-54 [Info] Chunk: -62   -63 -42 -2  421 79
2019-11-02 12-06-55 [Info] Chunk: 9 2   -62 -2  468 80
2019-11-02 12-06-55 [Info] pShortBuffer->full() && (abs(shortMedian_) > 5): -6236
2019-11-02 12-06-55 [Info] Sleep -6, age: 0, bufferDuration: 21
2019-11-02 12-06-55 [Info] Sleep -5, age: 1, bufferDuration: 21
2019-11-02 12-06-55 [Info] Sleep -4, age: 2, bufferDuration: 21
2019-11-02 12-06-55 [Info] Sleep -3, age: 5, bufferDuration: 21
2019-11-02 12-06-55 [Info] Sleep -3, age: 2, bufferDuration: 21
2019-11-02 12-06-55 [Info] Sleep -2, age: 3, bufferDuration: 21
2019-11-02 12-06-56 [Info] Sleep -1, age: 4, bufferDuration: 21
2019-11-02 12-06-56 [Info] Chunk: 40    40  40  40  1   79
2019-11-02 12-06-56 [Err] ERROR. Can't write to PCM device: I/O error
2019-11-02 12-06-56 [Info] uninitAlsa: entered
2019-11-02 12-06-56 [Info] uninitAlsa: if handle_ != nullptr entered
2019-11-02 12-06-56 [Info] uninitAlsa: snd_pcm_drop entering
2019-11-02 12-06-56 [Info] uninitAlsa: snd_pcm_drop exited
2019-11-02 12-06-56 [Info] uninitAlsa: snd_pcm_close entering
2019-11-02 12-06-56 [Info] uninitAlsa: snd_pcm_close exited
2019-11-02 12-06-56 [Info] uninitAlsa: handle_ = nullptr done
2019-11-02 12-06-56 [Info] uninitAlsa: if buff_ != nullptr entered
2019-11-02 12-06-56 [Info] uninitAlsa: free(buff_); started
2019-11-02 12-06-56 [Info] uninitAlsa: free(buff_); done
2019-11-02 12-06-56 [Info] uninitAlsa: buff_ = nullptr; done
ALSA lib confmisc.c:767:(parse_card) cannot find card 'DAC'
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_card_driver returned error: No such device
ALSA lib confmisc.c:392:(snd_func_concat) error evaluating strings
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_concat returned error: No such device
ALSA lib confmisc.c:1246:(snd_func_refer) error evaluating name
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_refer returned error: No such device
ALSA lib conf.c:5047:(snd_config_expand) Evaluate error: No such device
ALSA lib pcm.c:2564:(snd_pcm_open_noupdate) Unknown PCM default:CARD=DAC
2019-11-02 12-06-56 [Err] Exception in initAlsa: Can't open default:CARD=DAC PCM device: No such device
Segmentation fault
xabolcs picture xabolcs on 2 Nov 2019

On OpenWrt 19.07.2 example assert program aborts, while snd_pcm_drain doesn't. Interesting.

root@OpenWrt:~# cat assert.c 
#include <stdio.h>
#include <assert.h>

int main() {
    int a, b;

    printf("Input two integers to divide!\n");
    scanf("%d%d", &a, &b);

    assert(b != 0);

    printf("%d/%d = %.2f\n", a, b, a/(float)b);

    return 0;
}

root@OpenWrt:~# gcc assert.c -o assert
root@OpenWrt:~# ./assert
Input two integers to divide!
1
2
1/2 = 0.50
root@OpenWrt:~# ./assert
Input two integers to divide!
2 0
Assertion failed: b != 0 (assert.c: main: 10)
Aborted
xabolcs picture xabolcs on 12 Mar 2020

How does aplay handle USB disconnects? If it handles them gracefully, it could be a minor Snapclient issue. Otherwise a bug should be reported to the alsa project.

badaix picture badaix on 14 Mar 2020
👍1

Will test, thanks for the hint!

xabolcs picture xabolcs on 14 Mar 2020

Looks like it's a minor Snapclient issue:

$ logread -f
aplay: pcm_write:2057: write error: I/O error
Mon Mar 16 02:01:28 2020 kern.info kernel: [950730.882507] usb 1-1: USB disconnect, device number 2
Mon Mar 16 02:01:28 2020 kern.err kernel: [950730.887821] usb 1-1: cannot submit urb (err = -19)
Mon Mar 16 02:01:38 2020 kern.info kernel: [950740.994938] usb 1-1: new full-speed USB device number 3 using ehci-platform

^C[1]+  Done(1)                    aplay -t raw /dev/urandom

Software: OpenWrt SNAPSHOT, r12455-633c5137df, aplay: version 1.1.9 by Jaroslav Kysela <[email protected]>
Hardware: TP-Link TL-WR1043ND v1

xabolcs picture xabolcs on 16 Mar 2020

Should be fixed in develop branch: 9aa2f33

badaix picture badaix on 7 May 2020
🎉1

Works nicely! Thanks!

2020-05-07 09-11-56.374 [Notice] (Connection) Connected to 192.168.20.3
2020-05-07 09-11-56.375 [Info] (Controller) Connected!
2020-05-07 09-11-56.377 [Info] (Connection) My MAC: "74:ea:3a:c2:57:dc", socket: 7
2020-05-07 09-11-56.544 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"default"}
2020-05-07 09-11-56.549 [Info] (Controller) Codec: flac
2020-05-07 09-11-56.551 [Notice] (state) sampleformat: 48000:16:2
2020-05-07 09-11-56.592 [Info] (Alsa) frames: 1440
2020-05-07 09-11-56.836 [Info] (Controller) diff to server [ms]: -3.54685e+08
2020-05-07 09-11-57.438 [Debug] (Stats) Chunk: 0    0   0   0   1   96  0
2020-05-07 09-11-58.008 [Debug] (Stats) Chunk: 0    0   0   0   20  96  0
2020-05-07 09-11-59.028 [Debug] (Stats) Chunk: 0    0   0   0   53  96  0
2020-05-07 09-12-00.018 [Debug] (Stats) Chunk: 4    0   0   0   86  96  0
2020-05-07 09-12-01.008 [Debug] (Stats) Chunk: 1    1   0   0   119 96  0
2020-05-07 09-12-02.028 [Debug] (Stats) Chunk: 1    1   0   0   153 96  0
2020-05-07 09-12-03.019 [Debug] (Stats) Chunk: 2    1   1   0   186 96  0
2020-05-07 09-12-04.009 [Debug] (Stats) Chunk: 1    1   1   1   219 96  -2
2020-05-07 09-12-05.029 [Debug] (Stats) Chunk: 1    1   1   1   253 96  -2
2020-05-07 09-12-06.019 [Debug] (Stats) Chunk: 1    0   1   1   286 96  -3
2020-05-07 09-12-06.874 [Error] (Alsa) ERROR. Can't wait for PCM to become ready: I/O error
Segmentation fault

Software: OpenWrt SNAPSHOT, r12455-633c5137df, Snapclient: snapclient v0.19.0 on commit 9aa2f334ebb222aa11a95092a8e20fea3bbda52a
Hardware: TP-Link TL-WR1043ND v1

xabolcs picture xabolcs on 7 May 2020

Does it really work? I can see a Segmentation fault in your log.

On my machine it looks like this:

2020-05-07 12-54-14.017 [Debug] (Stats) Chunk: 0    0   0   0   500 96  0
2020-05-07 12-54-15.007 [Debug] (Stats) Chunk: 0    0   0   0   500 96  0
2020-05-07 12-54-16.027 [Debug] (Stats) Chunk: 0    0   0   0   500 96  0
2020-05-07 12-54-17.017 [Debug] (Stats) Chunk: 0    0   0   0   500 96  0
2020-05-07 12-54-18.007 [Debug] (Stats) Chunk: 0    0   0   0   500 96  0
2020-05-07 12-54-18.939 [Error] (Alsa) ERROR. Can't wait for PCM to become ready: No such device
ALSA lib pcm_hw.c:1700:(_snd_pcm_hw_open) Invalid value for card
2020-05-07 12-54-18.948 [Error] (Alsa) Exception in initAlsa: Can't open hw:CARD=CODEC,DEV=0, error: No such device
ALSA lib pcm_hw.c:1700:(_snd_pcm_hw_open) Invalid value for card
2020-05-07 12-54-19.049 [Error] (Alsa) Exception in initAlsa: Can't open hw:CARD=CODEC,DEV=0, error: No such device
ALSA lib pcm_hw.c:1700:(_snd_pcm_hw_open) Invalid value for card
...
2020-05-07 12-54-20.865 [Error] (Alsa) Exception in initAlsa: Can't open hw:CARD=CODEC,DEV=0, error: No such device
ALSA lib pcm_hw.c:1700:(_snd_pcm_hw_open) Invalid value for card
2020-05-07 12-54-20.966 [Error] (Alsa) Exception in initAlsa: Can't open hw:CARD=CODEC,DEV=0, error: No such device
2020-05-07 12-54-21.069 [Debug] (Alsa) PCM name: hw:CARD=CODEC,DEV=0
2020-05-07 12-54-21.069 [Debug] (Alsa) PCM state: PREPARED
2020-05-07 12-54-21.069 [Debug] (Alsa) channels: 2
2020-05-07 12-54-21.069 [Debug] (Alsa) rate: 48000 bps
2020-05-07 12-54-21.070 [Debug] (Alsa) frames: 1440
2020-05-07 12-54-21.070 [Debug] (Alsa) period time: 30000
2020-05-07 12-54-21.070 [Info] (Stream) abs(age > 500): 2037146
2020-05-07 12-54-21.070 [Debug] (Stats) Chunk: 20371    0   0   0   500 0   0
badaix picture badaix on 7 May 2020

The syslog has a little more detail:

Thu May  7 10:55:33 2020 daemon.info snapclient-sed[9283]: [Debug] (Stats) Chunk: 1 0   1   0   500 96  -2
Thu May  7 10:55:34 2020 daemon.info snapclient-sed[9283]: [Debug] (Stats) Chunk: 1 0   1   0   500 96  -3
Thu May  7 10:55:34 2020 kern.info kernel: [484584.750727] usb 1-1: USB disconnect, device number 3
Thu May  7 10:55:34 2020 kern.err kernel: [484584.755918] usb 1-1: cannot submit urb (err = -19)
Thu May  7 10:55:34 2020 kern.info kernel: [484584.772069] do_page_fault(): sending SIGSEGV to snapclient for invalid read access from 0000012c
Thu May  7 10:55:34 2020 kern.info kernel: [484584.781713] epc = 77e563fc in libasound.so.2.0.0[77e14000+cb000]
Thu May  7 10:55:34 2020 kern.info kernel: [484584.787999] ra  = 77e58870 in libasound.so.2.0.0[77e14000+cb000]
Thu May  7 10:55:34 2020 daemon.info snapclient-sed[9283]: [Debug] (Stats) Chunk: 1 0   0   0   500 96  -1
Thu May  7 10:55:34 2020 daemon.info snapclient-sed[9283]: [Error] (Alsa) ERROR. Can't wait for PCM to become ready: I/O error
Thu May  7 10:55:34 2020 daemon.err snapclient-sed[9283]: Segmentation fault

Does it really work? I can see a Segmentation fault in your log.

I saw that too.
The segfault is acceptable to me.
The original description says:

But if I shutdown my sound-system snapclient is breaking. It runs on full cpu consumption until I kill it and after killing it is staying as zombie.

Your commit solves the above.

Sure, it would be nice if it will be able to survive without segfault and could continue to wait for sound device. :+1:

xabolcs picture xabolcs on 7 May 2020

I checked the aplay sources, they are cheating and simply exit when they get an I/O error.
Can you please try in void AlsaPlayer::uninitAlsa() to:

  1. replace snd_pcm_drain(handle_); with snd_pcm_drop(handle_);
  2. if still segfaulting: comment/remove the line
  3. if still segfaulting: comment/remove the next line snd_pcm_close(handle_);

(3) will not be an option, just for curiosity

badaix picture badaix on 7 May 2020

Something is wrong here. Commit d6752844ab00f49334c79343ea347bfa716e4802 produces hang, 100% cpu, and oom:

2020-05-07 14-17-58.032 [Debug] (Stats) Chunk: 1    1   1   0   276 43  -2
2020-05-07 14-17-59.014 [Debug] (Stats) Chunk: 1    1   1   1   307 63  -3
2020-05-07 14-18-00.016 [Debug] (Stats) Chunk: 2    1   1   1   338 43  -2
2020-05-07 14-18-00.166 [Error] (Alsa) ERROR. Can't wait for PCM to become ready: I/O error
Killed

Thu May  7 14:18:36 2020 kern.info kernel: [  839.302104] [   2184]     0  2184      293       26    16384        0             0 dropbear
Thu May  7 14:18:36 2020 kern.info kernel: [  839.310605] [   2185]     0  2185      304       13    16384        0             0 ash
Thu May  7 14:18:36 2020 kern.info kernel: [  839.318722] [   2272]     0  2272      403      102    16384        0             0 htop
Thu May  7 14:18:36 2020 kern.info kernel: [  839.326887] [   2280]     0  2280     3163     1783    28672        0             0 snapclient
Thu May  7 14:18:36 2020 kern.err kernel: [  839.335544] Out of memory: Kill process 2280 (snapclient) score 275 or sacrifice child
Thu May  7 14:18:36 2020 kern.err kernel: [  839.343538] Killed process 2280 (snapclient) total-vm:12652kB, anon-rss:6928kB, file-rss:68kB, shmem-rss:136kB
Thu May  7 14:18:36 2020 kern.info kernel: [  839.361020] oom_reaper: reaped process 2280 (snapclient), now anon-rss:0kB, file-rss:64kB, shmem-rss:132kB

Will try the other steps later, and maybe I'll add extra logging to uninitAlsa() like I did previously in commit 86c416a

xabolcs picture xabolcs on 7 May 2020

Something is wrong here.

snapclient -l says about my UCA202:

0: null
Discard all samples (playback) or generate zero samples (capture)

1: default:CARD=CODEC
USB Audio CODEC, USB Audio
Default Audio Device

2: sysdefault:CARD=CODEC
USB Audio CODEC, USB Audio
Default Audio Device

3: front:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
Front speakers

4: surround21:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
2.1 Surround output to Front and Subwoofer speakers

5: surround40:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
4.0 Surround output to Front and Rear speakers

6: surround41:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
4.1 Surround output to Front, Rear and Subwoofer speakers

7: surround50:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
5.0 Surround output to Front, Center and Rear speakers

8: surround51:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
5.1 Surround output to Front, Center, Rear and Subwoofer speakers

9: surround71:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
7.1 Surround output to Front, Center, Side, Rear and Woofer speakers

10: iec958:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
IEC958 (S/PDIF) Digital Audio Output

  • commit 57aa683f93212c0645176d148c1a36040ae0300d

    • hangs, ooms with CARD=CODEC cards (1 and 2) :exclamation:
    • segfaults with CARD=CODEC,DEV=0 cards (3 and up) :heavy_check_mark:

  • commit d6752844ab00f49334c79343ea347bfa716e4802

    • hangs, ooms with CARD=CODEC cards (1 and 2) :exclamation:
    • segfaults with CARD=CODEC,DEV=0 cards (3 and up) :heavy_check_mark:

  • commit 93aa7e385442aaf591f4ac750221306cd6599fc3

    • hangs, ooms with CARD=CODEC cards (1 and 2) :exclamation:
    • segfaults with CARD=CODEC,DEV=0 cards (3 and up) :heavy_check_mark:

  • commit e02f993750140b8af7f09212540fe14f0a7481f9

    • hangs, ooms with CARD=CODEC cards (1 and 2) :exclamation:
    • segfaults with CARD=CODEC,DEV=0 cards (3 and up) :heavy_check_mark:
xabolcs picture xabolcs on 7 May 2020

Hmm, thanks for testing. I tested on a x86 with the UCA202, but just with 1: default:CARD=CODEC which is working fine and recovers when USB is plugged back again. I will also test with 3: front:CARD=CODEC,DEV=0, no idea what the difference is.
But in general I guess that the issues depend on the alsa driver/version.

badaix picture badaix on 9 May 2020

Hmm, thanks for testing.

Should I testing futher, like polluting every lines of alsa_player.cpp to localize where the infinite loop and memory leak happens?

But in general I guess that the issues depend on the alsa driver/version.

I thinks the same, but not just for the alsa driver but the libc. See my comment from 03.12:

On OpenWrt 19.07.2 example assert program aborts, while snd_pcm_drain doesn't. Interesting.

xabolcs picture xabolcs on 9 May 2020

I will not stop you from further investigating this issue :)
But I think that this is not a show stopper and it's slightly improved now (at least survives on my X86).

badaix picture badaix on 9 May 2020

Yes, the disconnection handling on those exotic platforms like raspi and mips is now acceptable.

systemd and procd is able to automatically restart on crash so segfault are not a big problem for me.

OK, will continue debugging.

xabolcs picture xabolcs on 9 May 2020

OK, will continue debugging.

My build environment wasn't clean enough!
A new test with commit 2a6360a832f99bf4c7f472e3aca9f73e2ea1a8be shows the following:

  • with sound cards CARD=CODEC,DEV=0 (3 and up) it logs a lot of error on disconnect, but recovers on connect:
2020-05-10 14-42-12.766 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-42-13.005 [Debug] (Stats) Chunk: 0    1   1   1   500 96  -3
2020-05-10 14-42-13.771 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-42-14.025 [Debug] (Stats) Chunk: 0    0   0   1   500 96  -1
2020-05-10 14-42-14.775 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-42-14.915 [Error] (Alsa) ERROR. Can't wait for PCM to become ready: I/O error
ALSA lib confmisc.c:767:(parse_card) cannot find card 'CODEC'
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_card_driver returned error: No such device
ALSA lib confmisc.c:392:(snd_func_concat) error evaluating strings
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_concat returned error: No such device
ALSA lib confmisc.c:1246:(snd_func_refer) error evaluating name
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_refer returned error: No such device
ALSA lib conf.c:5047:(snd_config_expand) Evaluate error: No such device
ALSA lib pcm.c:2564:(snd_pcm_open_noupdate) Unknown PCM iec958:CARD=CODEC,DEV=0
.
.
.
2020-05-10 14-42-25.254 [Error] (Alsa) Exception in initAlsa: Can't open iec958:CARD=CODEC,DEV=0, error: No such device
ALSA lib confmisc.c:767:(parse_card) cannot find card 'CODEC'
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_card_driver returned error: No such device
ALSA lib confmisc.c:392:(snd_func_concat) error evaluating strings
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_concat returned error: No such device
ALSA lib confmisc.c:1246:(snd_func_refer) error evaluating name
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_refer returned error: No such device
ALSA lib conf.c:5047:(snd_config_expand) Evaluate error: No such device
ALSA lib pcm.c:2564:(snd_pcm_open_noupdate) Unknown PCM iec958:CARD=CODEC,DEV=0
2020-05-10 14-42-25.369 [Error] (Alsa) Exception in initAlsa: Can't open iec958:CARD=CODEC,DEV=0, error: No such device
ALSA lib confmisc.c:767:(parse_card) cannot find card 'CODEC'
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_card_driver returned error: No such device
ALSA lib confmisc.c:392:(snd_func_concat) error evaluating strings
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_concat returned error: No such device
ALSA lib confmisc.c:1246:(snd_func_refer) error evaluating name
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_refer returned error: No such device
ALSA lib conf.c:5047:(snd_config_expand) Evaluate error: No such device
ALSA lib pcm.c:2564:(snd_pcm_open_noupdate) Unknown PCM iec958:CARD=CODEC,DEV=0
2020-05-10 14-42-25.488 [Error] (Alsa) Exception in initAlsa: Can't open iec958:CARD=CODEC,DEV=0, error: No such device
2020-05-10 14-42-25.600 [Debug] (Alsa) PCM name: iec958:CARD=CODEC,DEV=0
2020-05-10 14-42-25.602 [Debug] (Alsa) PCM state: PREPARED
2020-05-10 14-42-25.606 [Debug] (Alsa) channels: 2
2020-05-10 14-42-25.608 [Debug] (Alsa) rate: 48000 bps
2020-05-10 14-42-25.609 [Debug] (Alsa) frames: 1440
2020-05-10 14-42-25.611 [Debug] (Alsa) period time: 30000
2020-05-10 14-42-25.613 [Info] (Stream) abs(age > 500): 10593245
2020-05-10 14-42-25.616 [Debug] (Stats) Chunk: 105932   0   0   1   500 0   0
2020-05-10 14-42-25.618 [Info] (Alsa) Failed to get chunk
2020-05-10 14-42-25.620 [Debug] (Stream) age > 0: 10480ms
2020-05-10 14-42-25.624 [Debug] (Stream) age: 10464, requested chunk_duration: 120, duration: 24
2020-05-10 14-42-25.626 [Debug] (Stream) age: 10442, requested chunk_duration: 120, duration: 24
2020-05-10 14-42-25.628 [Debug] (Stream) age: 10420, requested chunk_duration: 120, duration: 24
2020-05-10 14-42-25.630 [Debug] (Stream) age: 10398, requested chunk_duration: 120, duration: 24
2020-05-10 14-42-25.631 [Debug] (Stream) age: 10376, requested chunk_duration: 120, duration: 24
2020-05-10 14-42-25.633 [Debug] (Stream) age: 10353, requested chunk_duration: 120, duration: 24
2020-05-10 14-42-25.635 [Debug] (Stream) age: 10331, requested chunk_duration: 120, duration: 24
2020-05-10 14-42-25.636 [Debug] (Stream) age: 10308, requested chunk_duration: 120, duration: 24
2020-05-10 14-42-25.638 [Debug] (Stream) age: 10286, requested chunk_duration: 120, duration: 24
  • with CARD=CODEC cards (1 and 2), it enters infinite loop and OOMs - it doesn't detect the reconnected soundcard:
2020-05-10 14-49-10.495 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-10.506 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-10.511 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-10.514 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-10.517 [Info] (Controller) diff to server [ms]: 1.41248e+08
2020-05-10 14-49-10.520 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-10.979 [Debug] (Stream) Silent frames: 626, frames: 1056, age: -13.053
2020-05-10 14-49-11.021 [Debug] (Stats) Chunk: 2    2   2   2   1   43  0
2020-05-10 14-49-11.524 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-12.003 [Debug] (Stats) Chunk: 1    0   0   0   32  63  0
2020-05-10 14-49-12.530 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-13.006 [Debug] (Stats) Chunk: 0    0   0   0   63  43  0
2020-05-10 14-49-13.536 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-14.030 [Debug] (Stats) Chunk: 0    0   0   0   95  43  0
2020-05-10 14-49-14.544 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-15.012 [Debug] (Stats) Chunk: 0    0   0   0   126 63  0
2020-05-10 14-49-15.549 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-16.014 [Debug] (Stats) Chunk: 0    0   0   0   157 43  0
2020-05-10 14-49-16.555 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-17.038 [Debug] (Stats) Chunk: 1    0   0   0   189 43  0
2020-05-10 14-49-17.566 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-18.021 [Debug] (Stats) Chunk: 1    1   0   0   220 63  0
2020-05-10 14-49-18.474 [Error] (Alsa) ERROR. Can't wait for PCM to become ready: I/O error
2020-05-10 14-49-18.571 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-19.577 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-20.582 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-21.589 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-22.600 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-23.614 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-24.627 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-25.634 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-26.640 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-27.655 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-28.660 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-29.674 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-30.682 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-31.686 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-32.692 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-33.697 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-34.704 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-35.710 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-36.715 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-37.723 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-38.729 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-39.733 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-40.737 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-41.745 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-42.757 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-43.762 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-44.767 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-45.771 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-46.778 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-47.792 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-48.798 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-49.802 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-50.815 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-51.823 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-52.835 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 14-49-53.840 [Trace] (Connection) Wrote 34 bytes to socket
Killed
xabolcs picture xabolcs on 10 May 2020

I tested further.

snd_pcm_drain does work for ....,DEV=0 cards, and snapclient survives the disconnect:

2020-05-10 11-46-41.176 [Trace] (Alsa) Before snd_pcm_wait
2020-05-10 11-46-41.196 [Trace] (Alsa) After snd_pcm_wait, result: -5, I/O error
2020-05-10 11-46-41.204 [Error] (Alsa) ERROR. Can't wait for PCM to become ready: I/O error
2020-05-10 11-46-41.206 [Trace] (Alsa) uninitAlsa - handle is null
2020-05-10 11-46-41.209 [Trace] (Alsa) uninitAlsa - before snd_pcm_drain
2020-05-10 11-46-41.211 [Trace] (Alsa) uninitAlsa - after snd_pcm_drain
2020-05-10 11-46-41.213 [Trace] (Alsa) uninitAlsa - before snd_pcm_close
2020-05-10 11-46-41.215 [Trace] (Alsa) uninitAlsa - after snd_pcm_close
2020-05-10 11-46-41.226 [Trace] (Alsa) uninitAlsa - done
2020-05-10 11-46-41.327 [Error] (Alsa) Exception in initAlsa: Can't open iec958:CARD=CODEC,DEV=0, error: No such device
2020-05-10 11-46-41.429 [Warn] (Alsa) Handler is null after init!
2020-05-10 11-46-41.442 [Error] (Alsa) Exception in initAlsa: Can't open iec958:CARD=CODEC,DEV=0, error: No such device

But it doesn't work for simple named cards, like CARD=CODEC:

2020-05-10 11-48-27.614 [Trace] (Alsa) Before snd_pcm_wait
2020-05-10 11-48-27.616 [Trace] (Alsa) After snd_pcm_wait, result: -5, I/O error
2020-05-10 11-48-27.619 [Error] (Alsa) ERROR. Can't wait for PCM to become ready: I/O error
2020-05-10 11-48-27.623 [Trace] (Alsa) uninitAlsa - handle is null
2020-05-10 11-48-27.631 [Trace] (Alsa) uninitAlsa - before snd_pcm_drain
2020-05-10 11-48-27.910 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 11-48-28.915 [Trace] (Connection) Wrote 34 bytes to socket
.
.
.
2020-05-10 11-49-01.175 [Trace] (Connection) Wrote 34 bytes to socket
2020-05-10 11-49-02.183 [Trace] (Connection) Wrote 34 bytes to socket
Killed

So I retested (4955982baa846e62955a175ad2aaf4904767889b) your proposed change:

replace snd_pcm_drain(handle_); with snd_pcm_drop(handle_);

And it works! :+1:
With CARD=CODEC:

2020-05-10 18-28-42.371 [Trace] (Alsa) Before snd_pcm_wait
2020-05-10 18-28-42.408 [Trace] (Alsa) After snd_pcm_wait, result: -5, I/O error
2020-05-10 18-28-42.409 [Error] (Alsa) ERROR. Can't wait for PCM to become ready: I/O error
2020-05-10 18-28-42.415 [Trace] (Alsa) uninitAlsa - handle is null
2020-05-10 18-28-42.417 [Trace] (Alsa) uninitAlsa - before snd_pcm_drop
2020-05-10 18-28-42.418 [Trace] (Alsa) uninitAlsa - after snd_pcm_drop
2020-05-10 18-28-42.420 [Trace] (Alsa) uninitAlsa - before snd_pcm_close
2020-05-10 18-28-42.424 [Trace] (Alsa) uninitAlsa - after snd_pcm_close
2020-05-10 18-28-42.432 [Trace] (Alsa) uninitAlsa - done
ALSA lib confmisc.c:767:(parse_card) cannot find card 'CODEC'
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_card_driver returned error: No such device
ALSA lib confmisc.c:392:(snd_func_concat) error evaluating strings
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_concat returned error: No such device
ALSA lib confmisc.c:1246:(snd_func_refer) error evaluating name
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_refer returned error: No such device
ALSA lib conf.c:5047:(snd_config_expand) Evaluate error: No such device
ALSA lib pcm.c:2564:(snd_pcm_open_noupdate) Unknown PCM default:CARD=CODEC
2020-05-10 18-28-42.448 [Error] (Alsa) Exception in initAlsa: Can't open default:CARD=CODEC, error: No such device
2020-05-10 18-28-42.551 [Warn] (Alsa) Handler is null after init!

And with CARD=CODEC,DEV=0 too:

2020-05-10 18-45-18.362 [Trace] (Alsa) Before snd_pcm_wait
2020-05-10 18-45-18.378 [Trace] (Alsa) After snd_pcm_wait, result: -5, I/O error
2020-05-10 18-45-18.379 [Error] (Alsa) ERROR. Can't wait for PCM to become ready: I/O error
2020-05-10 18-45-18.380 [Trace] (Alsa) uninitAlsa - handle is null
2020-05-10 18-45-18.381 [Trace] (Alsa) uninitAlsa - before snd_pcm_drop
2020-05-10 18-45-18.381 [Trace] (Alsa) uninitAlsa - after snd_pcm_drop
2020-05-10 18-45-18.382 [Trace] (Alsa) uninitAlsa - before snd_pcm_close
2020-05-10 18-45-18.393 [Trace] (Alsa) uninitAlsa - after snd_pcm_close
2020-05-10 18-45-18.395 [Trace] (Alsa) uninitAlsa - done
ALSA lib confmisc.c:767:(parse_card) cannot find card 'CODEC'
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_card_driver returned error: No such device
ALSA lib confmisc.c:392:(snd_func_concat) error evaluating strings
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_concat returned error: No such device
ALSA lib confmisc.c:1246:(snd_func_refer) error evaluating name
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_refer returned error: No such device
ALSA lib conf.c:5047:(snd_config_expand) Evaluate error: No such device
ALSA lib pcm.c:2564:(snd_pcm_open_noupdate) Unknown PCM iec958:CARD=CODEC,DEV=0
2020-05-10 18-45-18.500 [Error] (Alsa) Exception in initAlsa: Can't open iec958:CARD=CODEC,DEV=0, error: No such device
2020-05-10 18-45-18.602 [Warn] (Alsa) Handler is null after init!
ALSA lib confmisc.c:767:(parse_card) cannot find card 'CODEC'
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_card_driver returned error: No such device
ALSA lib confmisc.c:392:(snd_func_concat) error evaluating strings
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_concat returned error: No such device
ALSA lib confmisc.c:1246:(snd_func_refer) error evaluating name
ALSA lib conf.c:4568:(_snd_config_evaluate) function snd_func_refer returned error: No such device
ALSA lib conf.c:5047:(snd_config_expand) Evaluate error: No such device
ALSA lib pcm.c:2564:(snd_pcm_open_noupdate) Unknown PCM iec958:CARD=CODEC,DEV=0
xabolcs picture xabolcs on 10 May 2020

About the DEV=0 thing...

I have another USB soundcard: SMSL X4. It's snapclient -l is exactly the same as UCA202:

0: null
Discard all samples (playback) or generate zero samples (capture)

1: default:CARD=DAC
SMSL X4 DAC, USB Audio
Default Audio Device

2: sysdefault:CARD=DAC
SMSL X4 DAC, USB Audio
Default Audio Device

3: front:CARD=DAC,DEV=0
SMSL X4 DAC, USB Audio
Front speakers

4: surround21:CARD=DAC,DEV=0
SMSL X4 DAC, USB Audio
2.1 Surround output to Front and Subwoofer speakers

5: surround40:CARD=DAC,DEV=0
SMSL X4 DAC, USB Audio
4.0 Surround output to Front and Rear speakers

6: surround41:CARD=DAC,DEV=0
SMSL X4 DAC, USB Audio
4.1 Surround output to Front, Rear and Subwoofer speakers

7: surround50:CARD=DAC,DEV=0
SMSL X4 DAC, USB Audio
5.0 Surround output to Front, Center and Rear speakers

8: surround51:CARD=DAC,DEV=0
SMSL X4 DAC, USB Audio
5.1 Surround output to Front, Center, Rear and Subwoofer speakers

9: surround71:CARD=DAC,DEV=0
SMSL X4 DAC, USB Audio
7.1 Surround output to Front, Center, Side, Rear and Woofer speakers

10: iec958:CARD=DAC,DEV=0
SMSL X4 DAC, USB Audio
IEC958 (S/PDIF) Digital Audio Output

But checkink its hw params with aplay --dump-hw-params it reveals interesting details.
CARD=DAC:

Playing raw data '/dev/zero' : Unsigned 8 bit, Rate 8000 Hz, Mono
HW Params of device "sysdefault":
--------------------
ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
SUBFORMAT:  STD
SAMPLE_BITS: [4 64]
FRAME_BITS: [4 640000]
CHANNELS: [1 10000]
RATE: [4000 4294967295)
PERIOD_TIME: (21333 21334)
PERIOD_SIZE: (85 91628833)
PERIOD_BYTES: (42 4294967295)
PERIODS: (0 17247242)
BUFFER_TIME: [1 4294967295]
BUFFER_SIZE: [170 1466015503]
BUFFER_BYTES: [85 4294967295]
TICK_TIME: ALL
--------------------

With CARD=DAC,DEV=0, e.g. front or iec958:

Playing raw data '/dev/zero' : Unsigned 8 bit, Rate 8000 Hz, Mono
HW Params of device "front":
--------------------
ACCESS:  MMAP_INTERLEAVED RW_INTERLEAVED
FORMAT:  S24_3LE
SUBFORMAT:  STD
SAMPLE_BITS: 24
FRAME_BITS: 48
CHANNELS: 2
RATE: [44100 96000]
PERIOD_TIME: [1000 1981429)
PERIOD_SIZE: [45 87381]
PERIOD_BYTES: [270 524286]
PERIODS: [2 1024]
BUFFER_TIME: (937 3962858)
BUFFER_SIZE: [90 174762]
BUFFER_BYTES: [540 1048572]
TICK_TIME: ALL
--------------------
aplay: set_params:1339: Sample format non available
Available formats:
- S24_3LE

And the same is true for UCA202. default:CARD=CODEC has all the formats:

Playing raw data '/dev/zero' : Unsigned 8 bit, Rate 8000 Hz, Mono
HW Params of device "default":
--------------------
ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
SUBFORMAT:  STD
SAMPLE_BITS: [4 64]
FRAME_BITS: [4 640000]
CHANNELS: [1 10000]
RATE: [4000 4294967295)
PERIOD_TIME: (21333 21334)
PERIOD_SIZE: (85 91628833)
PERIOD_BYTES: (42 4294967295)
PERIODS: (0 17247242)
BUFFER_TIME: [1 4294967295]
BUFFER_SIZE: [170 1466015503]
BUFFER_BYTES: [85 4294967295]
TICK_TIME: ALL
--------------------

But the CARD=CODEC,DEV=0 cards, e.g. iec958 has just a few:

Playing raw data '/dev/zero' : Unsigned 8 bit, Rate 8000 Hz, Mono
HW Params of device "iec958":
--------------------
ACCESS:  MMAP_INTERLEAVED RW_INTERLEAVED
FORMAT:  S8 U8 S16_LE
SUBFORMAT:  STD
SAMPLE_BITS: [8 16]
FRAME_BITS: [8 32]
CHANNELS: [1 2]
RATE: [32000 48000]
PERIOD_TIME: [1000 16384000]
PERIOD_SIZE: [32 524288]
PERIOD_BYTES: [64 524288]
PERIODS: [2 1024]
BUFFER_TIME: (1333 32768000]
BUFFER_SIZE: [64 1048576]
BUFFER_BYTES: [64 1048576]
TICK_TIME: ALL
--------------------
Warning: rate is not accurate (requested = 8000Hz, got = 32000Hz)
         please, try the plug plugin (-Dplug:iec958)

... and with that plug plugin it gains all the formats:

Playing raw data '/dev/zero' : Unsigned 8 bit, Rate 8000 Hz, Mono
HW Params of device "plug:iec958":
--------------------
ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
SUBFORMAT:  STD
SAMPLE_BITS: [4 64]
FRAME_BITS: [4 640000]
CHANNELS: [1 10000]
RATE: [4000 4294967295]
PERIOD_TIME: [1000 16384000]
PERIOD_SIZE: [4 4294967295]
PERIOD_BYTES: [2 4294967295]
PERIODS: (0 1073741824)
BUFFER_TIME: [1 4294967295]
BUFFER_SIZE: [5 4294967294]
BUFFER_BYTES: [3 4294967295]
TICK_TIME: ALL
--------------------

It looks like the DEV=0 suffix forces the Alsa to "use real sound card", without that Alsa use some "enhancements" like the plug plugin above.

xabolcs picture xabolcs on 10 May 2020

Thanks for the insightful testing!
So can we summarize that snd_pcm_drain(handle_) should be replaced with snd_pcm_drop(handle_)?

From the docs:

Stop a PCM preserving pending frames.

Parameters
pcm PCM handle
Returns
0 on success otherwise a negative error code
Return values
-ESTRPIPE a suspend event occurred
For playback wait for all pending frames to be played and then stop the PCM. For capture stop PCM permitting to retrieve residual frames.

For stopping the PCM stream immediately, use ::snd_pcm_drop() instead.

It doesn't make sense to try playing the frames that might be buffered when the device is disconnected, dropping is the only meaningful thing we can do. And in normal operation no one will miss the buffered frames when shutting down alsa (which happens either during 5s of silence or when Snapclient is terminated).

badaix picture badaix on 13 May 2020
👍1

So can we summarize ...

Exactly! The fix would be commit cadca894c539806a06640c08db4400d3f759d22b, but with better summary and with a nice description ... like your comment above.

xabolcs picture xabolcs on 13 May 2020

I've cherry-picked it from your repo, so you're listed as the author 91f392f483819dd298df75148dfb6d3ae609d2e7

badaix picture badaix on 13 May 2020
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

trommegutten picture trommegutten  路  5Comments
jreusch picture jreusch  路  5Comments
renne picture renne  路  4Comments
artmg picture artmg  路  3Comments
quantenschaum picture quantenschaum  路  7Comments