`make check` cannot generate correct `out.pcm` after `rmmod`

Environment (Ubuntu 24.04 LTS)

➜  vsnd git:(master) ✗ uname -a
Linux vm 6.8.0-31-generic #31-Ubuntu SMP PREEMPT_DYNAMIC Sat Apr 20 00:40:06 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux

Problem Description

Overview

If we exeute the following commands:

$ ./scripts/pipewire-rmmod.sh vsnd
$ make check # first time
$ make check # second time

The content of out.pcm will be empty (size 0) after the first make check was executed. However, if we execute make check again, this time the out.pcm would be filled with correct date. Is this expected behaviour?

The sciprt pipewire-rmmod.sh is used to perform rmmod in pipewire-powered system for convenience:

➜  vsnd git:(master) ✗ cat scripts/pipewire-rmmod.sh
#!/bin/bash
systemctl --user stop pipewire.socket
systemctl --user stop pipewire
sudo rmmod $@
systemctl --user start pipewire
systemctl --user start pipewire.socket

Details

Setup

For the detailed output info, some pr_{info,warn,err} are inserted into vsnd.c:

$ PAGER=cat git diff vsnd.c
diff --git a/vsnd.c b/vsnd.c
index adb5841..9c14b38 100644
--- a/vsnd.c
+++ b/vsnd.c
@@ -7,6 +7,8 @@
 #include <sound/initval.h>
 #include <sound/pcm.h>

+#include <linux/errname.h>
+
 #define BITS_PER_BYTE 8

 #define DRIVER_NAME "vsnd"
@@ -206,6 +208,8 @@ static unsigned int vsnd_pos_update(struct vsnd_pcm *pcm_data)
     char *src_data = pcm_data->substream->runtime->dma_area;
     unsigned int src_off = pcm_data->buf_pos;
     unsigned int delta = 0, bytes_to_write, byte_left_to_write;
+    int ret;
+    // int retry_limit = 100;

     if (running) {
         delta = jiffies - pcm_data->last_jiffies;
@@ -222,7 +226,18 @@ static unsigned int vsnd_pos_update(struct vsnd_pcm *pcm_data)
         unsigned int size = byte_left_to_write;
         if (src_off + size > pcm_data->pcm_buffer_size)
             size = pcm_data->pcm_buffer_size - src_off;
-        kernel_write(vsnd->fifo_fp, src_data + src_off, size, NULL);
+    again:
+        ret = kernel_write(vsnd->fifo_fp, src_data + src_off, size, NULL);
+        if (ret < 0) {
+            // if (ret == -EAGAIN && retry_limit--) {
+            //     goto again;
+            // }
+            pr_err("kernel_write: failed: %s", errname(ret));
+        } else if (ret < size) {
+            pr_warn("kernel_write: expect write %d, but %d", size, ret);
+        } else {
+            pr_info("%d bytes written", ret);
+        }
         byte_left_to_write -= size;
         src_off = (src_off + size) % pcm_data->pcm_buffer_size;
     } while (byte_left_to_write > 0);
@@ -348,6 +363,8 @@ static int vsnd_open(struct snd_pcm_substream *substream)
         err = -EIO;
         goto finally;
     }
+    pr_info("FIFO file %s opened", out_fifo_name[dev_id]);
+    // dump_stack();
     vsnd->fifo_fp = fifo_fp;

     /* Set PCM data */
@@ -386,6 +403,8 @@ static int vsnd_close(struct snd_pcm_substream *substream)
     mutex_lock(&vsnd->lock);
     if (vsnd->fifo_fp) {
         filp_close(vsnd->fifo_fp, NULL);
+        pr_info("FIFO file closed");
+        // dump_stack();
         vsnd->fifo_fp = NULL;
     }
     mutex_unlock(&vsnd->lock);
@@ -436,6 +455,8 @@ static int vsnd_trigger(struct snd_pcm_substream *substream, int cmd)
     struct vsnd *vsnd = pcm_data->vsnd;
     int err = 0;

+    pr_info("Triggered");
+
     switch (cmd) {
     case SNDRV_PCM_TRIGGER_START:
         pr_info("START: channels %d rate %d", runtime->channels, runtime->rate);

And ls -l output is inserted into verify.sh:

$ PAGER=cat git diff scripts/verify.sh
diff --git a/scripts/verify.sh b/scripts/verify.sh
index 39a28af..5d6f8f9 100755
--- a/scripts/verify.sh
+++ b/scripts/verify.sh
@@ -14,4 +14,5 @@ sleep 1
 aplay -D plughw:CARD=vsnd,DEV=0 CantinaBand3.wav
 sudo rmmod vsnd

+ls -l out.pcm
 ffmpeg -f s16le -ar 22.05k -ac 1 -loglevel 8 -i out.pcm out.wav

Outputs

➜  vsnd git:(master) ✗ ./scripts/pipewire-rmmod.sh vsnd
[sudo] password for vm:

➜  vsnd git:(master) ✗ make check
make -C /lib/modules/6.8.0-31-generic/build M=/home/vm/mnt/vsnd modules
make[1]: Entering directory '/usr/src/linux-headers-6.8.0-31-generic'
warning: the compiler differs from the one used to build the kernel
  The kernel was built by: x86_64-linux-gnu-gcc-13 (Ubuntu 13.2.0-23ubuntu4) 13.2.0
  You are using:           gcc-13 (Ubuntu 13.2.0-23ubuntu4) 13.2.0
make[1]: Leaving directory '/usr/src/linux-headers-6.8.0-31-generic'
scripts/verify.sh
+ sudo modprobe snd_pcm
+ sudo rmmod vsnd
rmmod: ERROR: Module vsnd is not currently loaded
+ rm -f /tmp/audio.pcm
+ mkfifo /tmp/audio.pcm
+ sudo insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
+ sleep 1
+ tee out.pcm
+ tee out.pcm
+ aplay -D plughw:CARD=vsnd,DEV=0 CantinaBand3.wav
Playing WAVE 'CantinaBand3.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono
+ sudo rmmod vsnd
rmmod: ERROR: Module vsnd is in use
+ ls -l out.pcm
-rwxrwx--- 1 root vboxsf 0 May  9  2024 out.pcm
+ ffmpeg -f s16le -ar 22.05k -ac 1 -loglevel 8 -i out.pcm out.wav
File 'out.wav' already exists. Overwrite? [y/N]
Not overwriting - exiting

➜  vsnd git:(master) ✗ make check
make -C /lib/modules/6.8.0-31-generic/build M=/home/vm/mnt/vsnd modules
make[1]: Entering directory '/usr/src/linux-headers-6.8.0-31-generic'
warning: the compiler differs from the one used to build the kernel
  The kernel was built by: x86_64-linux-gnu-gcc-13 (Ubuntu 13.2.0-23ubuntu4) 13.2.0
  You are using:           gcc-13 (Ubuntu 13.2.0-23ubuntu4) 13.2.0
make[1]: Leaving directory '/usr/src/linux-headers-6.8.0-31-generic'
scripts/verify.sh
+ sudo modprobe snd_pcm
+ sudo rmmod vsnd
rmmod: ERROR: Module vsnd is in use
+ rm -f /tmp/audio.pcm
+ mkfifo /tmp/audio.pcm
+ sudo insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
insmod: ERROR: could not insert module vsnd.ko: File exists
+ sleep 1
+ tee out.pcm
+ aplay -D plughw:CARD=vsnd,DEV=0 CantinaBand3.wav
Playing WAVE 'CantinaBand3.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono
+ sudo rmmod vsnd
rmmod: ERROR: Module vsnd is in use
+ ls -l out.pcm
-rwxrwx--- 1 root vboxsf 138296 May  9  2024 out.pcm
+ ffmpeg -f s16le -ar 22.05k -ac 1 -loglevel 8 -i out.pcm out.wav
File 'out.wav' already exists. Overwrite? [y/N]
Not overwriting - exiting
➜  vsnd git:(master) ✗

Syslog (journalctl -f)

May 09 12:14:27 vm systemd[1]: Finished motd-news.service - Message of the Day.
May 09 12:15:01 vm CRON[345882]: pam_unix(cron:session): session opened for user root(uid=0) by root(uid=0)
May 09 12:15:01 vm CRON[345883]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
May 09 12:15:01 vm CRON[345882]: pam_unix(cron:session): session closed for user root
May 09 12:17:01 vm CRON[346588]: pam_unix(cron:session): session opened for user root(uid=0) by root(uid=0)
May 09 12:17:01 vm CRON[346589]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
May 09 12:17:02 vm CRON[346588]: pam_unix(cron:session): session closed for user root
May 09 12:18:15 vm systemd[2066]: tmux-spawn-2a333912-6bf4-43ca-be6e-7d6c2d23afa7.scope: Consumed 11.752s CPU time.
May 09 12:18:16 vm tracker-miner-fs-3[347026]: (tracker-extract-3:347026): GLib-GIO-WARNING **: 12:18:16.004: Error creating IO channel for /proc/self/mountinfo: Invalid argument (g-io-error-quark, 13)
May 09 12:18:31 vm tracker-miner-fs-3[347216]: (tracker-extract-3:347216): GLib-GIO-WARNING **: 12:18:31.143: Error creating IO channel for /proc/self/mountinfo: Invalid argument (g-io-error-quark, 13)
May 09 12:18:38 vm wireplumber[334476]: stopped by signal: Terminated
May 09 12:18:38 vm systemd[2066]: Stopping wireplumber.service - Multimedia Service Session Manager...
May 09 12:18:38 vm wireplumber[334476]: disconnected from pipewire
May 09 12:18:38 vm gsd-media-keys[2418]: Unable to get default sink
May 09 12:18:38 vm gsd-media-keys[2418]: Unable to get default source
May 09 12:18:38 vm systemd[2066]: Stopped wireplumber.service - Multimedia Service Session Manager.
May 09 12:18:38 vm systemd[2066]: Stopping pipewire.service - PipeWire Multimedia Service...
May 09 12:18:38 vm xdg-desktop-por[2951]: Caught PipeWire error: connection error
May 09 12:18:38 vm systemd[2066]: Stopped pipewire.service - PipeWire Multimedia Service.
May 09 12:18:38 vm systemd[2066]: Closed pipewire.socket - PipeWire Multimedia System Sockets.
May 09 12:18:38 vm xdg-desktop-por[2951]: Failed connect to PipeWire: Couldn't connect to PipeWire
May 09 12:18:40 vm sudo[347293]:       vm : TTY=pts/5 ; PWD=/home/vm/mnt/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 09 12:18:40 vm sudo[347293]: pam_unix(sudo:session): session opened for user root(uid=0) by vm(uid=1000)
May 09 12:18:40 vm sudo[347293]: pam_unix(sudo:session): session closed for user root
May 09 12:18:40 vm systemd[2066]: Listening on pipewire.socket - PipeWire Multimedia System Sockets.
May 09 12:18:40 vm systemd[2066]: Started pipewire.service - PipeWire Multimedia Service.
May 09 12:18:40 vm systemd[2066]: Started wireplumber.service - Multimedia Service Session Manager.
May 09 12:18:40 vm pipewire[347313]: mod.jackdbus-detect: Failed to receive jackdbus reply: org.freedesktop.DBus.Error.ServiceUnknown: The name org.jackaudio.service was not provided by any .service files
May 09 12:18:40 vm rtkit-daemon[1649]: Successfully made thread 347313 of process 347313 owned by '1000' high priority at nice level -11.
May 09 12:18:40 vm rtkit-daemon[1649]: Supervising 4 threads of 3 processes of 1 users.
May 09 12:18:40 vm rtkit-daemon[1649]: Successfully made thread 347328 of process 347315 owned by '1000' RT at priority 20.
May 09 12:18:40 vm rtkit-daemon[1649]: Supervising 5 threads of 4 processes of 1 users.
May 09 12:18:40 vm rtkit-daemon[1649]: Successfully made thread 347315 of process 347315 owned by '1000' high priority at nice level -11.
May 09 12:18:40 vm rtkit-daemon[1649]: Supervising 6 threads of 4 processes of 1 users.
May 09 12:18:40 vm rtkit-daemon[1649]: Successfully made thread 347330 of process 347313 owned by '1000' RT at priority 20.
May 09 12:18:40 vm rtkit-daemon[1649]: Supervising 7 threads of 4 processes of 1 users.
May 09 12:18:40 vm wireplumber[347315]: SPA handle 'api.libcamera.enum.manager' could not be loaded; is it installed?
May 09 12:18:40 vm wireplumber[347315]: PipeWire's libcamera SPA missing or broken. libcamera not supported.
May 09 12:18:40 vm wireplumber[347315]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
May 09 12:18:40 vm wireplumber[347315]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
May 09 12:18:40 vm wireplumber[347315]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
May 09 12:18:40 vm wireplumber[347315]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
May 09 12:18:40 vm wireplumber[347315]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
May 09 12:18:40 vm wireplumber[347315]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
May 09 12:18:40 vm wireplumber[347315]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
May 09 12:18:40 vm wireplumber[347315]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
May 09 12:18:40 vm wireplumber[347315]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
May 09 12:18:40 vm wireplumber[347315]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
May 09 12:18:40 vm wireplumber[347315]: BlueZ system service is not available
May 09 12:18:40 vm wireplumber[347315]: <WpPortalPermissionStorePlugin:0x64cb4f7e16d0> Failed to call Lookup: GDBus.Error:org.freedesktop.portal.Error.NotFound: No entry for camera
May 09 12:18:43 vm tracker-miner-fs-3[347375]: (tracker-extract-3:347375): GLib-GIO-WARNING **: 12:18:43.580: Error creating IO channel for /proc/self/mountinfo: Invalid argument (g-io-error-quark, 13)

------ I AM SEPARATE (the first time make check) ------

May 09 12:18:44 vm sudo[347621]:       vm : TTY=pts/5 ; PWD=/home/vm/mnt/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm
May 09 12:18:44 vm sudo[347621]: pam_unix(sudo:session): session opened for user root(uid=0) by vm(uid=1000)
May 09 12:18:44 vm sudo[347621]: pam_unix(sudo:session): session closed for user root
May 09 12:18:44 vm sudo[347624]:       vm : TTY=pts/5 ; PWD=/home/vm/mnt/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 09 12:18:44 vm sudo[347624]: pam_unix(sudo:session): session opened for user root(uid=0) by vm(uid=1000)
May 09 12:18:44 vm sudo[347624]: pam_unix(sudo:session): session closed for user root
May 09 12:18:44 vm sudo[347629]:       vm : TTY=pts/5 ; PWD=/home/vm/mnt/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
May 09 12:18:44 vm sudo[347629]: pam_unix(sudo:session): session opened for user root(uid=0) by vm(uid=1000)
May 09 12:18:44 vm sudo[347629]: pam_unix(sudo:session): session closed for user root
May 09 12:18:44 vm kernel: FIFO file /tmp/audio.pcm opened
May 09 12:18:44 vm kernel: FIFO file closed
May 09 12:18:44 vm kernel: FIFO file /tmp/audio.pcm opened
May 09 12:18:44 vm kernel: FIFO file closed
May 09 12:18:44 vm kernel: FIFO file /tmp/audio.pcm opened
May 09 12:18:44 vm kernel: FIFO file closed
May 09 12:18:44 vm kernel: FIFO file /tmp/audio.pcm opened
May 09 12:18:44 vm kernel: FIFO file closed
May 09 12:18:44 vm kernel: FIFO file /tmp/audio.pcm opened
May 09 12:18:44 vm kernel: FIFO file closed
May 09 12:18:44 vm kernel: FIFO file /tmp/audio.pcm opened
May 09 12:18:44 vm kernel: FIFO file closed
May 09 12:18:44 vm kernel: FIFO file /tmp/audio.pcm opened
May 09 12:18:44 vm kernel: FIFO file closed
May 09 12:18:44 vm kernel: FIFO file /tmp/audio.pcm opened
May 09 12:18:44 vm kernel: FIFO file closed
May 09 12:18:44 vm kernel: FIFO file /tmp/audio.pcm opened
May 09 12:18:45 vm kernel: FIFO file closed
May 09 12:18:45 vm kernel: FIFO file /tmp/audio.pcm opened
May 09 12:18:45 vm kernel: Triggered
May 09 12:18:45 vm kernel: START: channels 1 rate 22050
May 09 12:18:45 vm kernel: 5820 bytes written
May 09 12:18:46 vm kernel: 5468 bytes written
May 09 12:18:46 vm kernel: 5910 bytes written
May 09 12:18:46 vm kernel: 4850 bytes written
May 09 12:18:46 vm kernel: 662 bytes written
May 09 12:18:46 vm kernel: 5380 bytes written
May 09 12:18:46 vm kernel: 5514 bytes written
May 09 12:18:46 vm kernel: 5204 bytes written
May 09 12:18:46 vm kernel: 5288 bytes written
May 09 12:18:46 vm kernel: 356 bytes written
May 09 12:18:46 vm kernel: 5380 bytes written
May 09 12:18:47 vm kernel: 5556 bytes written
May 09 12:18:47 vm kernel: kernel_write: expect write 6262, but 2166
May 09 12:18:47 vm kernel: kernel_write: expect write 4494, but 398
May 09 12:18:47 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:47 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:47 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:47 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:47 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:47 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:47 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:48 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:48 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:48 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:48 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:48 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:48 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:48 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:48 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:48 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:48 vm kernel: kernel_write: failed: -EAGAIN
May 09 12:18:48 vm kernel: Triggered
May 09 12:18:48 vm kernel: STOP
May 09 12:18:48 vm sudo[347663]:       vm : TTY=pts/5 ; PWD=/home/vm/mnt/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 09 12:18:48 vm sudo[347663]: pam_unix(sudo:session): session opened for user root(uid=0) by vm(uid=1000)
May 09 12:18:48 vm sudo[347663]: pam_unix(sudo:session): session closed for user root

------ I AM SEPARATE (the second time make check) ------

May 09 12:18:52 vm sudo[347952]:       vm : TTY=pts/5 ; PWD=/home/vm/mnt/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm
May 09 12:18:52 vm sudo[347952]: pam_unix(sudo:session): session opened for user root(uid=0) by vm(uid=1000)
May 09 12:18:52 vm sudo[347952]: pam_unix(sudo:session): session closed for user root
May 09 12:18:52 vm sudo[347955]:       vm : TTY=pts/5 ; PWD=/home/vm/mnt/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 09 12:18:52 vm sudo[347955]: pam_unix(sudo:session): session opened for user root(uid=0) by vm(uid=1000)
May 09 12:18:52 vm sudo[347955]: pam_unix(sudo:session): session closed for user root
May 09 12:18:52 vm sudo[347960]:       vm : TTY=pts/5 ; PWD=/home/vm/mnt/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
May 09 12:18:52 vm sudo[347960]: pam_unix(sudo:session): session opened for user root(uid=0) by vm(uid=1000)
May 09 12:18:52 vm sudo[347960]: pam_unix(sudo:session): session closed for user root
May 09 12:18:53 vm kernel: FIFO file closed
May 09 12:18:53 vm kernel: FIFO file /tmp/audio.pcm opened
May 09 12:18:53 vm kernel: Triggered
May 09 12:18:53 vm kernel: START: channels 1 rate 22050
May 09 12:18:53 vm kernel: 6614 bytes written
May 09 12:18:53 vm kernel: 4718 bytes written
May 09 12:18:54 vm kernel: 5998 bytes written
May 09 12:18:54 vm kernel: 4718 bytes written
May 09 12:18:54 vm kernel: 442 bytes written
May 09 12:18:54 vm kernel: 7320 bytes written
May 09 12:18:54 vm kernel: 3484 bytes written
May 09 12:18:54 vm kernel: 5778 bytes written
May 09 12:18:54 vm kernel: 5024 bytes written
May 09 12:18:54 vm kernel: 796 bytes written
May 09 12:18:54 vm kernel: 8380 bytes written
May 09 12:18:55 vm kernel: 8202 bytes written
May 09 12:18:55 vm kernel: 4670 bytes written
May 09 12:18:55 vm kernel: 798 bytes written
May 09 12:18:55 vm kernel: 4808 bytes written
May 09 12:18:55 vm kernel: 5998 bytes written
May 09 12:18:55 vm kernel: 5292 bytes written
May 09 12:18:55 vm kernel: 5152 bytes written
May 09 12:18:55 vm kernel: 580 bytes written
May 09 12:18:55 vm kernel: 5468 bytes written
May 09 12:18:55 vm kernel: 5470 bytes written
May 09 12:18:56 vm kernel: 5292 bytes written
May 09 12:18:56 vm kernel: 5238 bytes written
May 09 12:18:56 vm kernel: 494 bytes written
May 09 12:18:56 vm kernel: 5998 bytes written
May 09 12:18:56 vm kernel: 5116 bytes written
May 09 12:18:56 vm kernel: 5380 bytes written
May 09 12:18:56 vm kernel: 5060 bytes written
May 09 12:18:56 vm kernel: 672 bytes written
May 09 12:18:56 vm kernel: 5336 bytes written
May 09 12:18:56 vm kernel: Triggered
May 09 12:18:56 vm kernel: STOP
May 09 12:18:56 vm sudo[347990]:       vm : TTY=pts/5 ; PWD=/home/vm/mnt/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 09 12:18:56 vm sudo[347990]: pam_unix(sudo:session): session opened for user root(uid=0) by vm(uid=1000)
May 09 12:18:56 vm sudo[347990]: pam_unix(sudo:session): session closed for user root

According to the output of journalctl during the first make check, the vsnd will first open/close the FIFO file many times.

And after the last open, vsnd did some kernel_write on the FIFO file but with many EAGAIN errors.

I have tried this several times, each time has similar result, and I have no idea why this happened.

I defer to @Cuda-Chen for confirmation.

Hi @freshLiver ,

Thanks for the reporting. While I am investigating whether this issue will appear on PulseAudio-enabled environment, I would like to share my finding if PulseAudio is enabled then execute make check:

out.pcm will be 0 size as the output is captured to other sound device (e.g., speakers).
out.pcm will contain the output with lagging if you set the sink to vsnd.

What's more, I am using Ubuntu 22.04 (Linux kernel version 5.15).

Hi @Cuda-Chen ,

Thanks for the information.

For the case that the output is captured by another sound device:

In the previously mentioned environment, the output is not captured by the default sound card, and it behaves similarly after I remove the driver of another sound card.

In my another environment which is a pulseaudio-powered system:

$ uname -a
Linux LabPC2 6.1.0-20-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.1.85-1 (2024-04-11) x86_64 GNU/Linux

This problem still exists and behaves similarly, according to the output of dmesg:

$ sudo dmesg -W
[2100141.020602] FIFO file closed
[2100177.038022] FIFO file /tmp/audio.pcm opened
[2100177.038120] FIFO file closed
[2100177.038176] FIFO file /tmp/audio.pcm opened
[2100177.038228] FIFO file closed
[2100177.038295] FIFO file /tmp/audio.pcm opened
[2100177.038387] FIFO file closed
[2100177.038456] FIFO file /tmp/audio.pcm opened
[2100177.038642] FIFO file closed
[2100177.038701] FIFO file /tmp/audio.pcm opened
[2100177.040714] FIFO file closed
[2100177.043919] FIFO file /tmp/audio.pcm opened
[2100177.057328] Triggered
[2100177.057334] START: channels 1 rate 22050
[2100179.072601] kernel_write: expect write 88200, but 65536
[2100179.072607] kernel_write: failed: -11
[2100181.084653] kernel_write: failed: -11
[2100181.084661] kernel_write: failed: -11
[2100182.061587] Triggered
[2100182.061594] STOP
----
[2100182.061687] FIFO file closed
[2100187.194256] FIFO file /tmp/audio.pcm opened
[2100187.195882] Triggered
[2100187.195891] START: channels 1 rate 22050
[2100187.324739] 5820 bytes written
[2100187.448735] 5468 bytes written
[2100187.572668] 5470 bytes written
[2100187.696681] 5290 bytes written
[2100187.696694] 178 bytes written
[2100187.824690] 5644 bytes written
[2100187.952685] 5646 bytes written
[2100188.072721] 5292 bytes written
[2100188.196716] 5288 bytes written
[2100188.196736] 180 bytes written
[2100188.324716] 5644 bytes written
[2100188.448719] 5468 bytes written
[2100188.572734] 5470 bytes written
[2100188.696730] 5286 bytes written
[2100188.696743] 182 bytes written
[2100188.824728] 5644 bytes written
[2100188.952695] 5646 bytes written
[2100189.072674] 5292 bytes written
[2100189.196738] 5284 bytes written
[2100189.196761] 184 bytes written
[2100189.324693] 5644 bytes written
[2100189.448726] 5468 bytes written
[2100189.572690] 5470 bytes written
[2100189.696727] 5282 bytes written
[2100189.696747] 186 bytes written
[2100189.824691] 5644 bytes written
[2100189.948731] 5468 bytes written
[2100190.072744] 5470 bytes written
[2100190.196734] 5280 bytes written
[2100190.196751] 188 bytes written
[2100190.324740] 5644 bytes written
[2100190.324747] Triggered
[2100190.324748] STOP

For the case that setting the sink to vsnd

I didn't encounter the lagging problem, the converted out.wav sounds as smooth as the original audio.

Hi @freshLiver ,

Thanks for you reply. I would like to conduct the steps these days to see the results of Linux Kernel 5.15.

HI @freshLiver ,

After using your patch, I do not encounter any write errors which you mention. For your information, I would like to write down the logs and the environments of mine.

Environment

$ uname -a
Linux jio-Aspire-V3-571G 5.15.0-106-generic #116-Ubuntu SMP Wed Apr 17 09:17:56 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux

Syslog

journalctl -f

May 11 10:33:26 jio-Aspire-V3-571G systemd[4640]: Stopping Sound Service...
May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSink/sbc
May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSource/sbc
May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSink/sbc_xq_453
May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSource/sbc_xq_453
May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSink/sbc_xq_512
May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSource/sbc_xq_512
May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSink/sbc_xq_552
May 11 10:33:26 jio-Aspire-V3-571G bluetoothd[1239]: Endpoint unregistered: sender=:1.107 path=/MediaEndpoint/A2DPSource/sbc_xq_552
May 11 10:33:26 jio-Aspire-V3-571G systemd[4640]: Stopped Sound Service.
May 11 10:33:26 jio-Aspire-V3-571G systemd[4640]: pulseaudio.service: Consumed 1min 27.017s CPU time.
May 11 10:33:26 jio-Aspire-V3-571G systemd[4640]: Closed Sound System.
May 11 10:33:31 jio-Aspire-V3-571G gsd-media-keys[5129]: Unable to get default sink
May 11 10:33:31 jio-Aspire-V3-571G gsd-media-keys[5129]: Unable to get default source

------ I AM SEPARATE (the first time make check) ------

May 11 10:35:35 jio-Aspire-V3-571G sudo[17662]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm
May 11 10:35:35 jio-Aspire-V3-571G sudo[17662]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 11 10:35:35 jio-Aspire-V3-571G sudo[17662]: pam_unix(sudo:session): session closed for user root
May 11 10:35:35 jio-Aspire-V3-571G sudo[17665]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 11 10:35:35 jio-Aspire-V3-571G sudo[17665]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 11 10:35:35 jio-Aspire-V3-571G sudo[17665]: pam_unix(sudo:session): session closed for user root
May 11 10:35:35 jio-Aspire-V3-571G sudo[17670]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
May 11 10:35:35 jio-Aspire-V3-571G sudo[17670]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 11 10:35:35 jio-Aspire-V3-571G sudo[17670]: pam_unix(sudo:session): session closed for user root
May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.062661:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.062817:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.065155:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.065252:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.081812:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.081913:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:35 jio-Aspire-V3-571G systemd[4640]: Reached target Sound Card.
May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.085029:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:35 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103535.085180:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:36 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 11 10:35:36 jio-Aspire-V3-571G kernel: Triggered
May 11 10:35:36 jio-Aspire-V3-571G kernel: START: channels 1 rate 22050
May 11 10:35:36 jio-Aspire-V3-571G kernel: 5996 bytes written
May 11 10:35:36 jio-Aspire-V3-571G kernel: 5292 bytes written
May 11 10:35:36 jio-Aspire-V3-571G kernel: 5470 bytes written
May 11 10:35:36 jio-Aspire-V3-571G kernel: 5290 bytes written
May 11 10:35:36 jio-Aspire-V3-571G kernel: 178 bytes written
May 11 10:35:36 jio-Aspire-V3-571G kernel: 5820 bytes written
May 11 10:35:36 jio-Aspire-V3-571G kernel: 5292 bytes written
May 11 10:35:37 jio-Aspire-V3-571G kernel: 5470 bytes written
May 11 10:35:37 jio-Aspire-V3-571G kernel: 5288 bytes written
May 11 10:35:37 jio-Aspire-V3-571G kernel: 180 bytes written
May 11 10:35:37 jio-Aspire-V3-571G kernel: 5644 bytes written
May 11 10:35:37 jio-Aspire-V3-571G kernel: 5468 bytes written
May 11 10:35:37 jio-Aspire-V3-571G kernel: 5646 bytes written
May 11 10:35:37 jio-Aspire-V3-571G kernel: 5110 bytes written
May 11 10:35:37 jio-Aspire-V3-571G kernel: 182 bytes written
May 11 10:35:37 jio-Aspire-V3-571G kernel: 5644 bytes written
May 11 10:35:37 jio-Aspire-V3-571G kernel: 5468 bytes written
May 11 10:35:38 jio-Aspire-V3-571G kernel: 5470 bytes written
May 11 10:35:38 jio-Aspire-V3-571G kernel: 5284 bytes written
May 11 10:35:38 jio-Aspire-V3-571G kernel: 184 bytes written
May 11 10:35:38 jio-Aspire-V3-571G kernel: 5644 bytes written
May 11 10:35:38 jio-Aspire-V3-571G kernel: 5468 bytes written
May 11 10:35:38 jio-Aspire-V3-571G kernel: 5646 bytes written
May 11 10:35:38 jio-Aspire-V3-571G kernel: 5106 bytes written
May 11 10:35:38 jio-Aspire-V3-571G kernel: 186 bytes written
May 11 10:35:38 jio-Aspire-V3-571G kernel: 5644 bytes written
May 11 10:35:38 jio-Aspire-V3-571G kernel: 5468 bytes written
May 11 10:35:39 jio-Aspire-V3-571G kernel: 5470 bytes written
May 11 10:35:39 jio-Aspire-V3-571G kernel: 5280 bytes written
May 11 10:35:39 jio-Aspire-V3-571G kernel: 188 bytes written
May 11 10:35:39 jio-Aspire-V3-571G kernel: 5644 bytes written
May 11 10:35:39 jio-Aspire-V3-571G kernel: Triggered
May 11 10:35:39 jio-Aspire-V3-571G kernel: STOP
May 11 10:35:39 jio-Aspire-V3-571G sudo[17681]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 11 10:35:39 jio-Aspire-V3-571G sudo[17681]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 11 10:35:39 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103539.232367:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:39 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103539.232444:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:39 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103539.233598:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:39 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103539.233671:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:39 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103539.234115:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:39 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103539.234176:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:35:39 jio-Aspire-V3-571G sudo[17681]: pam_unix(sudo:session): session closed for user root

------ I AM SEPARATE (the second time make check) ------

May 11 10:37:25 jio-Aspire-V3-571G sudo[17965]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm
May 11 10:37:25 jio-Aspire-V3-571G sudo[17965]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 11 10:37:25 jio-Aspire-V3-571G sudo[17965]: pam_unix(sudo:session): session closed for user root
May 11 10:37:25 jio-Aspire-V3-571G sudo[17968]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 11 10:37:25 jio-Aspire-V3-571G sudo[17968]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 11 10:37:25 jio-Aspire-V3-571G sudo[17968]: pam_unix(sudo:session): session closed for user root
May 11 10:37:25 jio-Aspire-V3-571G sudo[17973]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
May 11 10:37:25 jio-Aspire-V3-571G sudo[17973]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 11 10:37:25 jio-Aspire-V3-571G sudo[17973]: pam_unix(sudo:session): session closed for user root
May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.595563:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.595630:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.596466:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.596529:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.613430:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.613528:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.619225:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:37:25 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103725.619341:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:37:26 jio-Aspire-V3-571G kernel: FIFO file closed
May 11 10:37:26 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 11 10:37:26 jio-Aspire-V3-571G kernel: Triggered
May 11 10:37:26 jio-Aspire-V3-571G kernel: START: channels 1 rate 22050
May 11 10:37:26 jio-Aspire-V3-571G kernel: 5820 bytes written
May 11 10:37:26 jio-Aspire-V3-571G kernel: 5468 bytes written
May 11 10:37:27 jio-Aspire-V3-571G kernel: 5470 bytes written
May 11 10:37:27 jio-Aspire-V3-571G kernel: 5290 bytes written
May 11 10:37:27 jio-Aspire-V3-571G kernel: 178 bytes written
May 11 10:37:27 jio-Aspire-V3-571G kernel: 5644 bytes written
May 11 10:37:27 jio-Aspire-V3-571G kernel: 5468 bytes written
May 11 10:37:27 jio-Aspire-V3-571G kernel: 5470 bytes written
May 11 10:37:27 jio-Aspire-V3-571G kernel: 5288 bytes written
May 11 10:37:27 jio-Aspire-V3-571G kernel: 180 bytes written
May 11 10:37:27 jio-Aspire-V3-571G kernel: 5644 bytes written
May 11 10:37:27 jio-Aspire-V3-571G kernel: 5468 bytes written
May 11 10:37:28 jio-Aspire-V3-571G kernel: 5646 bytes written
May 11 10:37:28 jio-Aspire-V3-571G kernel: 5110 bytes written
May 11 10:37:28 jio-Aspire-V3-571G kernel: 182 bytes written
May 11 10:37:28 jio-Aspire-V3-571G kernel: 5644 bytes written
May 11 10:37:28 jio-Aspire-V3-571G kernel: 5468 bytes written
May 11 10:37:28 jio-Aspire-V3-571G kernel: 5470 bytes written
May 11 10:37:28 jio-Aspire-V3-571G kernel: 5284 bytes written
May 11 10:37:28 jio-Aspire-V3-571G kernel: 184 bytes written
May 11 10:37:28 jio-Aspire-V3-571G kernel: 5644 bytes written
May 11 10:37:28 jio-Aspire-V3-571G kernel: 5468 bytes written
May 11 10:37:29 jio-Aspire-V3-571G kernel: 5470 bytes written
May 11 10:37:29 jio-Aspire-V3-571G kernel: 5282 bytes written
May 11 10:37:29 jio-Aspire-V3-571G kernel: 186 bytes written
May 11 10:37:29 jio-Aspire-V3-571G kernel: 5644 bytes written
May 11 10:37:29 jio-Aspire-V3-571G kernel: 5468 bytes written
May 11 10:37:29 jio-Aspire-V3-571G kernel: 5470 bytes written
May 11 10:37:29 jio-Aspire-V3-571G kernel: 5280 bytes written
May 11 10:37:29 jio-Aspire-V3-571G kernel: 188 bytes written
May 11 10:37:29 jio-Aspire-V3-571G kernel: 5820 bytes written
May 11 10:37:29 jio-Aspire-V3-571G kernel: Triggered
May 11 10:37:29 jio-Aspire-V3-571G kernel: STOP
May 11 10:37:29 jio-Aspire-V3-571G sudo[17984]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 11 10:37:29 jio-Aspire-V3-571G sudo[17984]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 11 10:37:29 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103729.766703:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:37:29 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103729.766779:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:37:29 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103729.767124:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:37:29 jio-Aspire-V3-571G google-chrome.desktop[5704]: [6902:6902:0511/103729.767186:ERROR:pulse_util.cc(381)] pa_operation is nullptr.
May 11 10:37:29 jio-Aspire-V3-571G sudo[17984]: pam_unix(sudo:session): session closed for user root

Hi @Cuda-Chen ,

Could you provide the detailed version of your Ubuntu 22.04 env? I'd like to build a virtual env for testing.

I just tested in the fresh-installed Ubuntu 22.04.4, and the first make check still didn't generated the correct output (but with a slightly? different result).

Env info

Installed packages: build-essential git tmux meson bison linux-headers-uname -r curl ffmpeg gcc-12

Additional softwares: VirtualBox guest additions 6.1.44

vm@vm:~$ uname -a
Linux vm 6.5.0-28-generic #29~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Thu Apr  4 14:39:20 UTC 2 x86_64 x86_64 x86_64 GNU/Linux
vm@vm:~$ cat /etc/os-release 
PRETTY_NAME="Ubuntu 22.04.4 LTS"
NAME="Ubuntu"
VERSION_ID="22.04"
VERSION="22.04.4 LTS (Jammy Jellyfish)"
VERSION_CODENAME=jammy
ID=ubuntu
ID_LIKE=debian
...
UBUNTU_CODENAME=jammy

Default output device changed automatically after `insmod`

In this env, I found that the default output device will be automatically changed to vsnd (check the * symbol before the index):

vm@vm:~/vsnd$ pacmd list-sinks
1 sink(s) available.
  * index: 0
    name: <alsa_output.pci-0000_00_05.0.analog-stereo>
    driver: <module-alsa-card.c>
    flags: HARDWARE HW_MUTE_CTRL HW_VOLUME_CTRL DECIBEL_VOLUME LATENCY 
    state: SUSPENDED
    suspend cause: IDLE
    priority: 9039
    volume: front-left: 29274 /  45% / -21.00 dB,   front-right: 29274 /  45% / -21.00 dB
            balance 0.00
    base volume: 65536 / 100% / 0.00 dB
    volume steps: 65537
    muted: no
    current latency: 0.00 ms
    max request: 0 KiB
    max rewind: 0 KiB
    monitor source: 0
    sample spec: s16le 2ch 48000Hz
    channel map: front-left,front-right
                 Stereo
    used by: 0
    linked by: 0
    fixed latency: 99.94 ms
    card: 0 <alsa_card.pci-0000_00_05.0>
    module: 7
    properties:
        alsa.resolution_bits = "16"
        device.api = "alsa"
        device.class = "sound"
        alsa.class = "generic"
        alsa.subclass = "generic-mix"
        alsa.name = "Intel 82801AA-ICH"
        alsa.id = "Intel ICH"
        alsa.subdevice = "0"
        alsa.subdevice_name = "subdevice #0"
        alsa.device = "0"
        alsa.card = "0"
        alsa.card_name = "Intel 82801AA-ICH"
        alsa.long_card_name = "Intel 82801AA-ICH with AD1980 at irq 21"
        alsa.driver_name = "snd_intel8x0"
        device.bus_path = "pci-0000:00:05.0"
        sysfs.path = "/devices/pci0000:00/0000:00:05.0/sound/card0"
        device.bus = "pci"
        device.vendor.id = "8086"
        device.vendor.name = "Intel Corporation"
        device.product.id = "2415"
        device.product.name = "82801AA AC'97 Audio Controller"
        device.form_factor = "internal"
        device.string = "front:0"
        device.buffering.buffer_size = "19188"
        device.buffering.fragment_size = "6396"
        device.access_mode = "mmap"
        device.profile.name = "analog-stereo"
        device.profile.description = "Analog Stereo"
        device.description = "Built-in Audio Analog Stereo"
        module-udev-detect.discovered = "1"
        device.icon_name = "audio-card-pci"
    ports:
        analog-output;output-amplifier-on: Analog Output / Amplifier (priority 9910, latency offset 0 usec, available: unknown)
            properties:

        analog-output;output-amplifier-off: Analog Output / No Amplifier (priority 9900, latency offset 0 usec, available: unknown)
            properties:

    active port: <analog-output;output-amplifier-off>

vm@vm:~/vsnd$ sudo insmod vsnd.ko out_fifo_name=/tmp/audio.pcm

vm@vm:~/vsnd$ pacmd list-sinks
2 sink(s) available.
    index: 0
    name: <alsa_output.pci-0000_00_05.0.analog-stereo>
    driver: <module-alsa-card.c>
    flags: HARDWARE HW_MUTE_CTRL HW_VOLUME_CTRL DECIBEL_VOLUME LATENCY 
    state: SUSPENDED
    suspend cause: IDLE
    priority: 9039
    volume: front-left: 29274 /  45% / -21.00 dB,   front-right: 29274 /  45% / -21.00 dB
            balance 0.00
    base volume: 65536 / 100% / 0.00 dB
    volume steps: 65537
    muted: no
    current latency: 0.00 ms
    max request: 0 KiB
    max rewind: 0 KiB
    monitor source: 0
    sample spec: s16le 2ch 48000Hz
    channel map: front-left,front-right
                 Stereo
    used by: 0
    linked by: 0
    fixed latency: 99.94 ms
    card: 0 <alsa_card.pci-0000_00_05.0>
    module: 7
    properties:
        alsa.resolution_bits = "16"
        device.api = "alsa"
        device.class = "sound"
        alsa.class = "generic"
        alsa.subclass = "generic-mix"
        alsa.name = "Intel 82801AA-ICH"
        alsa.id = "Intel ICH"
        alsa.subdevice = "0"
        alsa.subdevice_name = "subdevice #0"
        alsa.device = "0"
        alsa.card = "0"
        alsa.card_name = "Intel 82801AA-ICH"
        alsa.long_card_name = "Intel 82801AA-ICH with AD1980 at irq 21"
        alsa.driver_name = "snd_intel8x0"
        device.bus_path = "pci-0000:00:05.0"
        sysfs.path = "/devices/pci0000:00/0000:00:05.0/sound/card0"
        device.bus = "pci"
        device.vendor.id = "8086"
        device.vendor.name = "Intel Corporation"
        device.product.id = "2415"
        device.product.name = "82801AA AC'97 Audio Controller"
        device.form_factor = "internal"
        device.string = "front:0"
        device.buffering.buffer_size = "19188"
        device.buffering.fragment_size = "6396"
        device.access_mode = "mmap"
        device.profile.name = "analog-stereo"
        device.profile.description = "Analog Stereo"
        device.description = "Built-in Audio Analog Stereo"
        module-udev-detect.discovered = "1"
        device.icon_name = "audio-card-pci"
    ports:
        analog-output;output-amplifier-on: Analog Output / Amplifier (priority 9910, latency offset 0 usec, available: unknown)
            properties:

        analog-output;output-amplifier-off: Analog Output / No Amplifier (priority 9900, latency offset 0 usec, available: unknown)
            properties:

    active port: <analog-output;output-amplifier-off>
  * index: 1
    name: <alsa_output.platform-vsnd.0.mono-fallback>
    driver: <module-alsa-card.c>
    flags: HARDWARE DECIBEL_VOLUME LATENCY 
    state: IDLE
    suspend cause: (none)
    priority: 9000
    volume: mono: 65536 / 100% / 0.00 dB
            balance 0.00
    base volume: 65536 / 100% / 0.00 dB
    volume steps: 65537
    muted: no
    current latency: 97.45 ms
    max request: 4 KiB
    max rewind: 4 KiB
    monitor source: 2
    sample spec: s16le 1ch 22050Hz
    channel map: mono
                 Mono
    used by: 0
    linked by: 0
    fixed latency: 99.95 ms
    card: 1 <alsa_card.platform-vsnd.0>
    module: 23
    properties:
        alsa.resolution_bits = "16"
        device.api = "alsa"
        device.class = "sound"
        alsa.class = "generic"
        alsa.subclass = "generic-mix"
        alsa.name = "vsnd PCM"
        alsa.id = "vsnd PCM"
        alsa.subdevice = "0"
        alsa.subdevice_name = "subdevice #0"
        alsa.device = "0"
        alsa.card = "1"
        alsa.card_name = "vsnd"
        alsa.long_card_name = "vsnd1"
        alsa.driver_name = "vsnd"
        device.bus_path = "platform-vsnd.0"
        sysfs.path = "/devices/platform/vsnd.0/sound/card1"
        device.form_factor = "internal"
        device.string = "hw:1"
        device.buffering.buffer_size = "4408"
        device.buffering.fragment_size = "4408"
        device.access_mode = "mmap"
        device.profile.name = "mono-fallback"
        device.profile.description = "Mono"
        device.description = "Built-in Audio Mono"
        module-udev-detect.discovered = "1"
        device.icon_name = "audio-card"
    ports:
        analog-output: Analog Output (priority 9900, latency offset 0 usec, available: unknown)
            properties:

    active port: <analog-output>

So a simple aplay CantinaBand3.wav is be handled by the vsnd module and still cause many kernel_write failed (return -11). But this time, the FIFO file was only opened and closed once:

$ sudo dmesg -W
[sudo] password for vm: 
[  803.186893] FIFO file closed
[  946.035333] FIFO file /tmp/audio.pcm opened
[  946.035514] Triggered
[  946.035516] START: channels 1 rate 22050
[  946.138769] 4408 bytes written
[  946.138783] 178 bytes written
[  946.238874] 4230 bytes written
[  946.238895] 180 bytes written
[  946.338694] 4228 bytes written
[  946.338717] 182 bytes written
[  946.438615] 4226 bytes written
[  946.438637] 184 bytes written
[  946.538608] 4224 bytes written
[  946.538631] 186 bytes written
[  946.638343] 4222 bytes written
[  946.638353] 188 bytes written
[  946.738296] 4220 bytes written
[  946.738305] 190 bytes written
[  946.838491] 4218 bytes written
[  946.838513] 192 bytes written
[  946.938280] kernel_write: expect write 4216, but 120
[  946.938293] 194 bytes written
[  947.038318] kernel_write: expect write 4214, but 118
[  947.038339] 196 bytes written
[  947.138098] kernel_write: expect write 4212, but 116
[  947.138107] 198 bytes written
[  947.238102] kernel_write: expect write 4210, but 114
[  947.238116] 200 bytes written
[  947.338098] kernel_write: expect write 4208, but 112
[  947.338107] 202 bytes written
[  947.440867] kernel_write: expect write 4206, but 110
[  947.440876] 204 bytes written
[  947.537959] kernel_write: expect write 4204, but 108
[  947.537975] 206 bytes written
[  947.637898] kernel_write: expect write 4202, but 106
[  947.637912] 208 bytes written
[  947.737886] kernel_write: expect write 4200, but 104
[  947.737906] 210 bytes written
[  947.841865] kernel_write: expect write 4198, but 102
[  947.841882] 388 bytes written
[  947.937698] kernel_write: failed: -11
[  947.937730] 214 bytes written
[  948.038658] kernel_write: expect write 4194, but 98
[  948.038668] 216 bytes written
[  948.137565] kernel_write: failed: -11
... # too many repeats
[  948.837265] kernel_write: failed: -11
[  949.836744] kernel_write: failed: -11
[  949.836753] kernel_write: failed: -11
[  949.936696] kernel_write: expect write 4156, but 60
[  949.936705] kernel_write: failed: -11
[  950.236577] kernel_write: failed: -11
... # too many repeats
[  955.030106] kernel_write: failed: -11
[  955.030114] kernel_write: failed: -11
[  955.038855] Triggered
[  955.038859] STOP

Changes on `verify.sh`

To prevent the default output device from being changed automatically after insmod, I added some commands in verify.sh to change and check the default output device:

...
sudo insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
+ pacmd list-sinks
+ pacmd set-default-sink alsa_output.pci-0000_00_05.0.analog-stereo
+ pacmd list-sinks
...

Output of `make check`

The second make check can still generate correct output. But in the first make check, the output pcm file size is no longer zero, but still has incorrect size apparently and has no sound.

vm@vm:~/vsnd$ ./scripts/pulseaudio-rmmod.sh vsnd

------ I AM SEPARATOR (the first time make check) ------

vm@vm:~/vsnd$ make check
make -C /lib/modules/6.5.0-28-generic/build M=/home/vm/vsnd modules
make[1]: Entering directory '/usr/src/linux-headers-6.5.0-28-generic'
warning: the compiler differs from the one used to build the kernel
  The kernel was built by: x86_64-linux-gnu-gcc-12 (Ubuntu 12.3.0-1ubuntu1~22.04) 12.3.0
  You are using:           gcc-12 (Ubuntu 12.3.0-1ubuntu1~22.04) 12.3.0
make[1]: Leaving directory '/usr/src/linux-headers-6.5.0-28-generic'
scripts/verify.sh
+ sudo modprobe snd_pcm
+ sudo rmmod vsnd
rmmod: ERROR: Module vsnd is not currently loaded
+ rm -f /tmp/audio.pcm
+ mkfifo /tmp/audio.pcm
+ sudo insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
+ pacmd list-sinks
2 sink(s) available.
    index: 0
    name: <alsa_output.pci-0000_00_05.0.analog-stereo>
    driver: <module-alsa-card.c>
    ...
  * index: 1
    name: <alsa_output.platform-vsnd.0.mono-fallback>
    driver: <module-alsa-card.c>
    flags: HARDWARE DECIBEL_VOLUME LATENCY 
    state: IDLE
    suspend cause: (none)
    priority: 9000
    volume: mono: 65536 / 100% / 0.00 dB
            balance 0.00
    base volume: 65536 / 100% / 0.00 dB
    volume steps: 65537
    muted: no
    current latency: 69.20 ms
    max request: 4 KiB
    max rewind: 4 KiB
    monitor source: 2
    sample spec: s16le 1ch 22050Hz
    channel map: mono
                 Mono
    used by: 0
    linked by: 0
    fixed latency: 99.95 ms
    card: 1 <alsa_card.platform-vsnd.0>
    module: 23
    properties:
        alsa.resolution_bits = "16"
        device.api = "alsa"
        device.class = "sound"
        alsa.class = "generic"
        alsa.subclass = "generic-mix"
        alsa.name = "vsnd PCM"
        alsa.id = "vsnd PCM"
        alsa.subdevice = "0"
        alsa.subdevice_name = "subdevice #0"
        alsa.device = "0"
        alsa.card = "1"
        alsa.card_name = "vsnd"
        alsa.long_card_name = "vsnd1"
        alsa.driver_name = "vsnd"
        device.bus_path = "platform-vsnd.0"
        sysfs.path = "/devices/platform/vsnd.0/sound/card1"
        device.form_factor = "internal"
        device.string = "hw:1"
        device.buffering.buffer_size = "4408"
        device.buffering.fragment_size = "4408"
        device.access_mode = "mmap"
        device.profile.name = "mono-fallback"
        device.profile.description = "Mono"
        device.description = "Built-in Audio Mono"
        module-udev-detect.discovered = "1"
        device.icon_name = "audio-card"
    ports:
        analog-output: Analog Output (priority 9900, latency offset 0 usec, available: unknown)
            properties:

    active port: <analog-output>
+ pacmd set-default-sink alsa_output.pci-0000_00_05.0.analog-stereo
+ pacmd list-sinks
2 sink(s) available.
  * index: 0
    name: <alsa_output.pci-0000_00_05.0.analog-stereo>
    driver: <module-alsa-card.c>
    ...
    index: 1
    name: <alsa_output.platform-vsnd.0.mono-fallback>
    driver: <module-alsa-card.c>
    flags: HARDWARE DECIBEL_VOLUME LATENCY 
    state: IDLE
    suspend cause: (none)
    priority: 9000
    volume: mono: 65536 / 100% / 0.00 dB
            balance 0.00
    base volume: 65536 / 100% / 0.00 dB
    volume steps: 65537
    muted: no
    current latency: 29.71 ms
    max request: 4 KiB
    max rewind: 4 KiB
    monitor source: 2
    sample spec: s16le 1ch 22050Hz
    channel map: mono
                 Mono
    used by: 0
    linked by: 0
    fixed latency: 99.95 ms
    card: 1 <alsa_card.platform-vsnd.0>
    module: 23
    properties:
        alsa.resolution_bits = "16"
        device.api = "alsa"
        device.class = "sound"
        alsa.class = "generic"
        alsa.subclass = "generic-mix"
        alsa.name = "vsnd PCM"
        alsa.id = "vsnd PCM"
        alsa.subdevice = "0"
        alsa.subdevice_name = "subdevice #0"
        alsa.device = "0"
        alsa.card = "1"
        alsa.card_name = "vsnd"
        alsa.long_card_name = "vsnd1"
        alsa.driver_name = "vsnd"
        device.bus_path = "platform-vsnd.0"
        sysfs.path = "/devices/platform/vsnd.0/sound/card1"
        device.form_factor = "internal"
        device.string = "hw:1"
        device.buffering.buffer_size = "4408"
        device.buffering.fragment_size = "4408"
        device.access_mode = "mmap"
        device.profile.name = "mono-fallback"
        device.profile.description = "Mono"
        device.description = "Built-in Audio Mono"
        module-udev-detect.discovered = "1"
        device.icon_name = "audio-card"
    ports:
        analog-output: Analog Output (priority 9900, latency offset 0 usec, available: unknown)
            properties:

    active port: <analog-output>
+ sleep 1
+ tee out.pcm
+ aplay -D plughw:CARD=vsnd,DEV=0 CantinaBand3.wav
aplay: main:831: audio open error: Device or resource busy
+ sudo rmmod vsnd
rmmod: ERROR: Module vsnd is in use
+ ls -l out.pcm
-rw-rw-r-- 1 vm vm 53096  五  11 19:58 out.pcm
+ ffmpeg -f s16le -ar 22.05k -ac 1 -loglevel 8 -i out.pcm out.wav
File 'out.wav' already exists. Overwrite? [y/N] y
vm@vm:~/vsnd$ aplay out.wav <------------------------------  no sound!!!
Playing WAVE 'out.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono

------ I AM SEPARATOR (the second time make check) ------

vm@vm:~/vsnd$ make check
make -C /lib/modules/6.5.0-28-generic/build M=/home/vm/vsnd modules
make[1]: Entering directory '/usr/src/linux-headers-6.5.0-28-generic'
warning: the compiler differs from the one used to build the kernel
  The kernel was built by: x86_64-linux-gnu-gcc-12 (Ubuntu 12.3.0-1ubuntu1~22.04) 12.3.0
  You are using:           gcc-12 (Ubuntu 12.3.0-1ubuntu1~22.04) 12.3.0
make[1]: Leaving directory '/usr/src/linux-headers-6.5.0-28-generic'
scripts/verify.sh
+ sudo modprobe snd_pcm
+ sudo rmmod vsnd
rmmod: ERROR: Module vsnd is in use
+ rm -f /tmp/audio.pcm
+ mkfifo /tmp/audio.pcm
+ sudo insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
insmod: ERROR: could not insert module vsnd.ko: File exists
+ pacmd list-sinks
2 sink(s) available.
  * index: 0
    name: <alsa_output.pci-0000_00_05.0.analog-stereo>
    driver: <module-alsa-card.c>
    ...
    index: 1
    name: <alsa_output.platform-vsnd.0.mono-fallback>
    driver: <module-alsa-card.c>
    flags: HARDWARE DECIBEL_VOLUME LATENCY 
    state: SUSPENDED
    suspend cause: IDLE
    priority: 9000
    volume: mono: 65536 / 100% / 0.00 dB
            balance 0.00
    base volume: 65536 / 100% / 0.00 dB
    volume steps: 65537
    muted: no
    current latency: 0.00 ms
    max request: 0 KiB
    max rewind: 0 KiB
    monitor source: 2
    sample spec: s16le 1ch 22050Hz
    channel map: mono
                 Mono
    used by: 0
    linked by: 0
    fixed latency: 99.95 ms
    card: 1 <alsa_card.platform-vsnd.0>
    module: 23
    properties:
        alsa.resolution_bits = "16"
        device.api = "alsa"
        device.class = "sound"
        alsa.class = "generic"
        alsa.subclass = "generic-mix"
        alsa.name = "vsnd PCM"
        alsa.id = "vsnd PCM"
        alsa.subdevice = "0"
        alsa.subdevice_name = "subdevice #0"
        alsa.device = "0"
        alsa.card = "1"
        alsa.card_name = "vsnd"
        alsa.long_card_name = "vsnd1"
        alsa.driver_name = "vsnd"
        device.bus_path = "platform-vsnd.0"
        sysfs.path = "/devices/platform/vsnd.0/sound/card1"
        device.form_factor = "internal"
        device.string = "hw:1"
        device.buffering.buffer_size = "4408"
        device.buffering.fragment_size = "4408"
        device.access_mode = "mmap"
        device.profile.name = "mono-fallback"
        device.profile.description = "Mono"
        device.description = "Built-in Audio Mono"
        module-udev-detect.discovered = "1"
        device.icon_name = "audio-card"
    ports:
        analog-output: Analog Output (priority 9900, latency offset 0 usec, available: unknown)
            properties:

    active port: <analog-output>
+ pacmd set-default-sink alsa_output.pci-0000_00_05.0.analog-stereo
+ pacmd list-sinks
2 sink(s) available.
  * index: 0
    name: <alsa_output.pci-0000_00_05.0.analog-stereo>
    driver: <module-alsa-card.c>
    ...
    index: 1
    name: <alsa_output.platform-vsnd.0.mono-fallback>
    driver: <module-alsa-card.c>
    flags: HARDWARE DECIBEL_VOLUME LATENCY 
    state: SUSPENDED
    suspend cause: IDLE
    priority: 9000
    volume: mono: 65536 / 100% / 0.00 dB
            balance 0.00
    base volume: 65536 / 100% / 0.00 dB
    volume steps: 65537
    muted: no
    current latency: 0.00 ms
    max request: 0 KiB
    max rewind: 0 KiB
    monitor source: 2
    sample spec: s16le 1ch 22050Hz
    channel map: mono
                 Mono
    used by: 0
    linked by: 0
    fixed latency: 99.95 ms
    card: 1 <alsa_card.platform-vsnd.0>
    module: 23
    properties:
        alsa.resolution_bits = "16"
        device.api = "alsa"
        device.class = "sound"
        alsa.class = "generic"
        alsa.subclass = "generic-mix"
        alsa.name = "vsnd PCM"
        alsa.id = "vsnd PCM"
        alsa.subdevice = "0"
        alsa.subdevice_name = "subdevice #0"
        alsa.device = "0"
        alsa.card = "1"
        alsa.card_name = "vsnd"
        alsa.long_card_name = "vsnd1"
        alsa.driver_name = "vsnd"
        device.bus_path = "platform-vsnd.0"
        sysfs.path = "/devices/platform/vsnd.0/sound/card1"
        device.form_factor = "internal"
        device.string = "hw:1"
        device.buffering.buffer_size = "4408"
        device.buffering.fragment_size = "4408"
        device.access_mode = "mmap"
        device.profile.name = "mono-fallback"
        device.profile.description = "Mono"
        device.description = "Built-in Audio Mono"
        module-udev-detect.discovered = "1"
        device.icon_name = "audio-card"
    ports:
        analog-output: Analog Output (priority 9900, latency offset 0 usec, available: unknown)
            properties:

    active port: <analog-output>
+ sleep 1
+ tee out.pcm
+ aplay -D plughw:CARD=vsnd,DEV=0 CantinaBand3.wav
Playing WAVE 'CantinaBand3.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono
+ sudo rmmod vsnd
rmmod: ERROR: Module vsnd is in use
+ ls -l out.pcm
-rw-rw-r-- 1 vm vm 138120  五  11 19:58 out.pcm
+ ffmpeg -f s16le -ar 22.05k -ac 1 -loglevel 8 -i out.pcm out.wav
File 'out.wav' already exists. Overwrite? [y/N] y
vm@vm:~/vsnd$ aplay out.wav    <------------------------------  correct result!!
Playing WAVE 'out.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono

Syslog

And from the syslog, there are several differences compared to the original result:

No write failure, but the FIFO file was still opened/closed many times.
There are many writes after the rmmod command which should indicate the end of aplay -D plughw:CARD=vsnd,DEV=0 CantinaBand3.wav
Error messages from pulseaudio

vm@vm:~/vsnd$ journalctl -f
 五  11 19:57:39 vm gnome-shell[1513]: Window manager warning: W2 appears to be one of the offending windows with a timestamp of 1210479.  Working around...
 五  11 19:58:03 vm systemd[1353]: Stopping Sound Service...
 五  11 19:58:03 vm systemd[1353]: Stopped Sound Service.
 五  11 19:58:03 vm systemd[1353]: Closed Sound System.
 五  11 19:58:03 vm sudo[4433]:       vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
 五  11 19:58:03 vm sudo[4433]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
 五  11 19:58:03 vm sudo[4433]: pam_unix(sudo:session): session closed for user root
 五  11 19:58:03 vm systemd[1353]: Listening on Sound System.
 五  11 19:58:03 vm systemd[1353]: Starting Sound Service...
 五  11 19:58:03 vm rtkit-daemon[1376]: Successfully made thread 4442 of process 4442 owned by '1000' high priority at nice level -11.
 五  11 19:58:03 vm rtkit-daemon[1376]: Supervising 4 threads of 3 processes of 1 users.
 五  11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
 五  11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
 五  11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
 五  11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
 五  11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
 五  11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
 五  11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
 五  11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
 五  11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'Center' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
 五  11 19:58:03 vm pulseaudio[4442]: The decibel volume range for element 'LFE' (-4650 dB - -2400 dB) has negative maximum. Disabling the decibel range.
 五  11 19:58:03 vm pulseaudio[4442]: Disabling timer-based scheduling because running inside a VM.
 五  11 19:58:03 vm rtkit-daemon[1376]: Supervising 4 threads of 3 processes of 1 users.
 五  11 19:58:03 vm rtkit-daemon[1376]: Successfully made thread 4443 of process 4442 owned by '1000' RT at priority 5.
 五  11 19:58:03 vm rtkit-daemon[1376]: Supervising 5 threads of 3 processes of 1 users.
 五  11 19:58:03 vm pulseaudio[4442]: Disabling timer-based scheduling because running inside a VM.
 五  11 19:58:03 vm rtkit-daemon[1376]: Supervising 5 threads of 3 processes of 1 users.
 五  11 19:58:03 vm rtkit-daemon[1376]: Successfully made thread 4444 of process 4442 owned by '1000' RT at priority 5.
 五  11 19:58:03 vm rtkit-daemon[1376]: Supervising 6 threads of 3 processes of 1 users.
 五  11 19:58:03 vm dbus-daemon[533]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.121' (uid=1000 pid=4442 comm="/usr/bin/pulseaudio --daemonize=no --log-target=jo" label="unconfined")
 五  11 19:58:03 vm systemd[1]: Condition check resulted in Bluetooth service being skipped.
 五  11 19:58:03 vm systemd[1353]: Started Sound Service.

------ I AM SEPARATOR (the first time make check) ------

 五  11 19:58:07 vm sudo[4679]:       vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm
 五  11 19:58:07 vm sudo[4679]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
 五  11 19:58:07 vm sudo[4679]: pam_unix(sudo:session): session closed for user root
 五  11 19:58:07 vm sudo[4682]:       vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
 五  11 19:58:07 vm sudo[4682]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
 五  11 19:58:07 vm sudo[4682]: pam_unix(sudo:session): session closed for user root
 五  11 19:58:07 vm sudo[4687]:       vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
 五  11 19:58:07 vm sudo[4687]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
 五  11 19:58:07 vm sudo[4687]: pam_unix(sudo:session): session closed for user root
 五  11 19:58:07 vm kernel: FIFO file closed
 五  11 19:58:07 vm kernel: FIFO file /tmp/audio.pcm opened
 五  11 19:58:07 vm kernel: FIFO file closed
 五  11 19:58:07 vm kernel: FIFO file /tmp/audio.pcm opened
 五  11 19:58:07 vm kernel: FIFO file closed
 五  11 19:58:07 vm kernel: FIFO file /tmp/audio.pcm opened
 五  11 19:58:07 vm kernel: FIFO file closed
 五  11 19:58:07 vm kernel: FIFO file /tmp/audio.pcm opened
 五  11 19:58:07 vm kernel: FIFO file closed
 五  11 19:58:07 vm kernel: FIFO file /tmp/audio.pcm opened
 五  11 19:58:07 vm pulseaudio[4442]: Disabling timer-based scheduling because running inside a VM.
 五  11 19:58:07 vm kernel: FIFO file closed
 五  11 19:58:07 vm rtkit-daemon[1376]: Supervising 6 threads of 3 processes of 1 users.
 五  11 19:58:07 vm rtkit-daemon[1376]: Successfully made thread 4695 of process 4442 owned by '1000' RT at priority 5.
 五  11 19:58:07 vm rtkit-daemon[1376]: Supervising 7 threads of 3 processes of 1 users.
 五  11 19:58:07 vm kernel: FIFO file /tmp/audio.pcm opened
 五  11 19:58:07 vm kernel: Triggered
 五  11 19:58:07 vm kernel: START: channels 1 rate 22050
 五  11 19:58:07 vm kernel: 4408 bytes written
 五  11 19:58:08 vm kernel: 178 bytes written
 五  11 19:58:08 vm kernel: 4230 bytes written
 五  11 19:58:08 vm kernel: 180 bytes written
 五  11 19:58:08 vm kernel: 4228 bytes written
 五  11 19:58:08 vm kernel: 182 bytes written
 五  11 19:58:08 vm kernel: 4226 bytes written
 五  11 19:58:08 vm kernel: 184 bytes written
 五  11 19:58:08 vm kernel: 4224 bytes written
 五  11 19:58:08 vm kernel: 186 bytes written
 五  11 19:58:08 vm kernel: 4222 bytes written
 五  11 19:58:08 vm kernel: 188 bytes written
 五  11 19:58:08 vm kernel: 4220 bytes written
 五  11 19:58:08 vm kernel: 190 bytes written
 五  11 19:58:08 vm kernel: 4218 bytes written
 五  11 19:58:08 vm kernel: 192 bytes written
 五  11 19:58:08 vm kernel: 4216 bytes written
 五  11 19:58:08 vm kernel: 194 bytes written
 五  11 19:58:08 vm kernel: 4214 bytes written
 五  11 19:58:08 vm kernel: 196 bytes written
 五  11 19:58:08 vm kernel: 4212 bytes written
 五  11 19:58:08 vm gsd-media-keys[1720]: Unable to get default sink
 五  11 19:58:08 vm gsd-media-keys[1720]: Unable to get default source
 五  11 19:58:09 vm kernel: 198 bytes written
 五  11 19:58:09 vm kernel: 4210 bytes written
 五  11 19:58:09 vm sudo[4701]:       vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
 五  11 19:58:09 vm sudo[4701]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
 五  11 19:58:09 vm sudo[4701]: pam_unix(sudo:session): session closed for user root

vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv writes after rmmod

 五  11 19:58:09 vm kernel: 200 bytes written
 五  11 19:58:09 vm kernel: 4208 bytes written
 五  11 19:58:09 vm kernel: 202 bytes written
 五  11 19:58:09 vm kernel: 4206 bytes written
 五  11 19:58:09 vm kernel: 204 bytes written
 五  11 19:58:09 vm kernel: 4204 bytes written
 五  11 19:58:09 vm kernel: 206 bytes written
 五  11 19:58:09 vm kernel: 4202 bytes written
 五  11 19:58:09 vm kernel: 208 bytes written
 五  11 19:58:09 vm kernel: 4200 bytes written
 五  11 19:58:09 vm kernel: 210 bytes written
 五  11 19:58:09 vm kernel: 4198 bytes written
 五  11 19:58:09 vm kernel: 212 bytes written
 五  11 19:58:09 vm kernel: 4196 bytes written
 五  11 19:58:09 vm kernel: 214 bytes written
 五  11 19:58:09 vm kernel: 4194 bytes written
 五  11 19:58:09 vm kernel: 216 bytes written
 五  11 19:58:09 vm kernel: 4192 bytes written
 五  11 19:58:10 vm kernel: 218 bytes written
 五  11 19:58:10 vm kernel: 4190 bytes written
 五  11 19:58:10 vm kernel: 220 bytes written
 五  11 19:58:10 vm kernel: 4188 bytes written
 五  11 19:58:10 vm kernel: 222 bytes written
 五  11 19:58:10 vm kernel: 4186 bytes written
 五  11 19:58:10 vm kernel: 224 bytes written
 五  11 19:58:10 vm kernel: 4184 bytes written
 五  11 19:58:10 vm kernel: 226 bytes written
 五  11 19:58:10 vm kernel: 4182 bytes written
 五  11 19:58:10 vm kernel: 228 bytes written
 五  11 19:58:10 vm kernel: 4180 bytes written
 五  11 19:58:10 vm kernel: 230 bytes written
 五  11 19:58:10 vm kernel: 4178 bytes written
 五  11 19:58:10 vm kernel: 232 bytes written
 五  11 19:58:10 vm kernel: 4176 bytes written
 五  11 19:58:10 vm kernel: 234 bytes written
 五  11 19:58:10 vm kernel: 4174 bytes written
 五  11 19:58:10 vm kernel: 236 bytes written
 五  11 19:58:10 vm kernel: 4172 bytes written
 五  11 19:58:11 vm kernel: 238 bytes written
 五  11 19:58:11 vm kernel: 4170 bytes written
 五  11 19:58:11 vm kernel: 240 bytes written
 五  11 19:58:11 vm kernel: 4168 bytes written
 五  11 19:58:11 vm kernel: 242 bytes written
 五  11 19:58:11 vm kernel: 4166 bytes written
 五  11 19:58:11 vm kernel: 244 bytes written
 五  11 19:58:11 vm kernel: 4164 bytes written
 五  11 19:58:11 vm kernel: 246 bytes written
 五  11 19:58:11 vm kernel: 4162 bytes written
 五  11 19:58:11 vm kernel: 248 bytes written
 五  11 19:58:11 vm kernel: 4160 bytes written
 五  11 19:58:11 vm kernel: 250 bytes written
 五  11 19:58:11 vm kernel: 4158 bytes written
 五  11 19:58:11 vm kernel: 252 bytes written
 五  11 19:58:11 vm kernel: 4156 bytes written
 五  11 19:58:11 vm kernel: 254 bytes written
 五  11 19:58:11 vm kernel: 4154 bytes written
 五  11 19:58:11 vm kernel: 256 bytes written
 五  11 19:58:11 vm kernel: 4152 bytes written
 五  11 19:58:12 vm kernel: 258 bytes written
 五  11 19:58:12 vm kernel: 4150 bytes written
 五  11 19:58:12 vm kernel: 260 bytes written
 五  11 19:58:12 vm kernel: 4148 bytes written
 五  11 19:58:12 vm kernel: 262 bytes written
 五  11 19:58:12 vm kernel: 4146 bytes written
 五  11 19:58:12 vm kernel: 264 bytes written
 五  11 19:58:12 vm kernel: 4144 bytes written
 五  11 19:58:12 vm kernel: 266 bytes written
 五  11 19:58:12 vm kernel: 4142 bytes written
 五  11 19:58:12 vm kernel: 268 bytes written
 五  11 19:58:12 vm kernel: 4140 bytes written
 五  11 19:58:12 vm kernel: 270 bytes written
 五  11 19:58:12 vm kernel: 4138 bytes written
 五  11 19:58:12 vm kernel: 272 bytes written
 五  11 19:58:12 vm kernel: 4136 bytes written
 五  11 19:58:12 vm kernel: 274 bytes written
 五  11 19:58:12 vm kernel: 4134 bytes written
 五  11 19:58:12 vm kernel: 276 bytes written
 五  11 19:58:12 vm kernel: Triggered
 五  11 19:58:12 vm kernel: STOP
 五  11 19:58:28 vm dbus-daemon[533]: [system] Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)
 五  11 19:58:28 vm pulseaudio[4442]: GetManagedObjects() failed: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

------ I AM SEPARATOR (the second time make check) ------

 五  11 19:58:43 vm sudo[4944]:       vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm
 五  11 19:58:43 vm sudo[4944]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
 五  11 19:58:43 vm sudo[4944]: pam_unix(sudo:session): session closed for user root
 五  11 19:58:43 vm sudo[4947]:       vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
 五  11 19:58:43 vm sudo[4947]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
 五  11 19:58:43 vm sudo[4947]: pam_unix(sudo:session): session closed for user root
 五  11 19:58:43 vm sudo[4952]:       vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
 五  11 19:58:43 vm sudo[4952]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
 五  11 19:58:43 vm sudo[4952]: pam_unix(sudo:session): session closed for user root
 五  11 19:58:44 vm kernel: FIFO file closed
 五  11 19:58:44 vm kernel: FIFO file /tmp/audio.pcm opened
 五  11 19:58:44 vm kernel: Triggered
 五  11 19:58:44 vm kernel: START: channels 1 rate 22050
 五  11 19:58:44 vm kernel: 5820 bytes written
 五  11 19:58:44 vm kernel: 5468 bytes written
 五  11 19:58:45 vm kernel: 5470 bytes written
 五  11 19:58:45 vm kernel: 5290 bytes written
 五  11 19:58:45 vm kernel: 178 bytes written
 五  11 19:58:45 vm kernel: 5644 bytes written
 五  11 19:58:45 vm kernel: 5468 bytes written
 五  11 19:58:45 vm kernel: 5470 bytes written
 五  11 19:58:45 vm kernel: 5288 bytes written
 五  11 19:58:45 vm kernel: 180 bytes written
 五  11 19:58:45 vm kernel: 5644 bytes written
 五  11 19:58:45 vm kernel: 5468 bytes written
 五  11 19:58:46 vm kernel: 5470 bytes written
 五  11 19:58:46 vm kernel: 5286 bytes written
 五  11 19:58:46 vm kernel: 182 bytes written
 五  11 19:58:46 vm kernel: 5644 bytes written
 五  11 19:58:46 vm kernel: 5468 bytes written
 五  11 19:58:46 vm kernel: 5470 bytes written
 五  11 19:58:46 vm kernel: 5284 bytes written
 五  11 19:58:46 vm kernel: 184 bytes written
 五  11 19:58:46 vm kernel: 5644 bytes written
 五  11 19:58:46 vm kernel: 5468 bytes written
 五  11 19:58:47 vm kernel: 5470 bytes written
 五  11 19:58:47 vm kernel: 5282 bytes written
 五  11 19:58:47 vm kernel: 186 bytes written
 五  11 19:58:47 vm kernel: 5644 bytes written
 五  11 19:58:47 vm kernel: 5468 bytes written
 五  11 19:58:47 vm kernel: 5470 bytes written
 五  11 19:58:47 vm kernel: 5280 bytes written
 五  11 19:58:47 vm kernel: 188 bytes written
 五  11 19:58:47 vm kernel: 5644 bytes written
 五  11 19:58:47 vm kernel: Triggered
 五  11 19:58:47 vm kernel: STOP
 五  11 19:58:47 vm sudo[4961]:       vm : TTY=pts/0 ; PWD=/home/vm/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
 五  11 19:58:47 vm sudo[4961]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
 五  11 19:58:47 vm sudo[4961]: pam_unix(sudo:session): session closed for user root

 vvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvvv new error message?

 五  11 19:58:56 vm pulseaudio[4442]: ALSA woke us up to write new data to the device, but there was actually nothing to write.
 五  11 19:58:56 vm pulseaudio[4442]: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.
 五  11 19:58:56 vm pulseaudio[4442]: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.

Hi @freshLiver , I would like to provide my detail env and my experiment result.

Env info

My env is running on a bare metal x86 machine. Installed packages: build-essential git tmux meson bison linux-headers-uname -r curl ffmpeg gcc-11

$ uname -a
Linux jio-Aspire-V3-571G 5.15.0-106-generic #116-Ubuntu SMP Wed Apr 17 09:17:56 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux
$ cat /etc/os-release 
PRETTY_NAME="Ubuntu 22.04.4 LTS"
NAME="Ubuntu"
VERSION_ID="22.04"
VERSION="22.04.4 LTS (Jammy Jellyfish)"
VERSION_CODENAME=jammy
ID=ubuntu
ID_LIKE=debian
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
UBUNTU_CODENAME=jammy

Output of `make check`

I apply your changes on verify.sh. What's more, I do not disable PulseAudio, then get the same situation of yours (first make check out.wav does not contain any sound). If I disable PulseAudio then run make check, out.wav always produces sound.

Syslog

I get the alike result if I do not disable PluseAudio first.

$ journalctl -f

------ I AM SEPARATOR (the first time make check) ------

May 12 10:55:03 jio-Aspire-V3-571G sudo[5481]: pam_unix(sudo:auth): authentication failure; logname=jio uid=1000 euid=0 tty=/dev/pts/4 ruser=jio rhost=  user=jio
May 12 10:55:07 jio-Aspire-V3-571G sudo[5481]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm
May 12 10:55:07 jio-Aspire-V3-571G sudo[5481]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 12 10:55:07 jio-Aspire-V3-571G sudo[5481]: pam_unix(sudo:session): session closed for user root
May 12 10:55:07 jio-Aspire-V3-571G sudo[5484]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 12 10:55:07 jio-Aspire-V3-571G sudo[5484]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 12 10:55:07 jio-Aspire-V3-571G sudo[5484]: pam_unix(sudo:session): session closed for user root
May 12 10:55:07 jio-Aspire-V3-571G sudo[5489]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
May 12 10:55:07 jio-Aspire-V3-571G sudo[5489]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 12 10:55:07 jio-Aspire-V3-571G sudo[5489]: pam_unix(sudo:session): session closed for user root
May 12 10:55:07 jio-Aspire-V3-571G systemd[2899]: Reached target Sound Card.
May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file closed
May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file closed
May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file closed
May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file closed
May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file closed
May 12 10:55:07 jio-Aspire-V3-571G rtkit-daemon[1350]: Supervising 6 threads of 3 processes of 1 users.
May 12 10:55:07 jio-Aspire-V3-571G rtkit-daemon[1350]: Successfully made thread 5497 of process 2908 owned by '1000' RT at priority 5.
May 12 10:55:07 jio-Aspire-V3-571G rtkit-daemon[1350]: Supervising 7 threads of 3 processes of 1 users.
May 12 10:55:07 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 12 10:55:07 jio-Aspire-V3-571G kernel: Triggered
May 12 10:55:08 jio-Aspire-V3-571G sudo[5504]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 12 10:55:08 jio-Aspire-V3-571G sudo[5504]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 12 10:55:08 jio-Aspire-V3-571G sudo[5504]: pam_unix(sudo:session): session closed for user root
May 12 10:55:09 jio-Aspire-V3-571G kernel: START: channels 1 rate 22050
May 12 10:55:09 jio-Aspire-V3-571G kernel: kernel_write: expect write 88200, but 65536
May 12 10:55:11 jio-Aspire-V3-571G kernel: 882 bytes written
May 12 10:55:11 jio-Aspire-V3-571G kernel: kernel_write: expect write 87318, but 65536
May 12 10:55:12 jio-Aspire-V3-571G kernel: 176 bytes written
May 12 10:55:12 jio-Aspire-V3-571G kernel: Triggered
May 12 10:55:12 jio-Aspire-V3-571G kernel: STOP

------ I AM SEPARATOR (the second time make check) ------

May 12 10:56:07 jio-Aspire-V3-571G sudo[5788]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm
May 12 10:56:07 jio-Aspire-V3-571G sudo[5788]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 12 10:56:07 jio-Aspire-V3-571G sudo[5788]: pam_unix(sudo:session): session closed for user root
May 12 10:56:07 jio-Aspire-V3-571G sudo[5791]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 12 10:56:07 jio-Aspire-V3-571G sudo[5791]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 12 10:56:07 jio-Aspire-V3-571G sudo[5791]: pam_unix(sudo:session): session closed for user root
May 12 10:56:07 jio-Aspire-V3-571G sudo[5796]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
May 12 10:56:07 jio-Aspire-V3-571G sudo[5796]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 12 10:56:07 jio-Aspire-V3-571G sudo[5796]: pam_unix(sudo:session): session closed for user root
May 12 10:56:08 jio-Aspire-V3-571G kernel: FIFO file closed
May 12 10:56:08 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 12 10:56:08 jio-Aspire-V3-571G kernel: Triggered
May 12 10:56:08 jio-Aspire-V3-571G kernel: START: channels 1 rate 22050
May 12 10:56:09 jio-Aspire-V3-571G kernel: 5820 bytes written
May 12 10:56:09 jio-Aspire-V3-571G kernel: 5468 bytes written
May 12 10:56:09 jio-Aspire-V3-571G kernel: 5470 bytes written
May 12 10:56:09 jio-Aspire-V3-571G kernel: 5290 bytes written
May 12 10:56:09 jio-Aspire-V3-571G kernel: 178 bytes written
May 12 10:56:09 jio-Aspire-V3-571G kernel: 5644 bytes written
May 12 10:56:09 jio-Aspire-V3-571G kernel: 5468 bytes written
May 12 10:56:09 jio-Aspire-V3-571G kernel: 5470 bytes written
May 12 10:56:09 jio-Aspire-V3-571G kernel: 5288 bytes written
May 12 10:56:09 jio-Aspire-V3-571G kernel: 180 bytes written
May 12 10:56:10 jio-Aspire-V3-571G kernel: 5644 bytes written
May 12 10:56:10 jio-Aspire-V3-571G kernel: 5468 bytes written
May 12 10:56:10 jio-Aspire-V3-571G kernel: 5470 bytes written
May 12 10:56:10 jio-Aspire-V3-571G kernel: 5286 bytes written
May 12 10:56:10 jio-Aspire-V3-571G kernel: 182 bytes written
May 12 10:56:10 jio-Aspire-V3-571G kernel: 5644 bytes written
May 12 10:56:10 jio-Aspire-V3-571G kernel: 5468 bytes written
May 12 10:56:10 jio-Aspire-V3-571G kernel: 5470 bytes written
May 12 10:56:10 jio-Aspire-V3-571G kernel: 5284 bytes written
May 12 10:56:10 jio-Aspire-V3-571G kernel: 184 bytes written
May 12 10:56:11 jio-Aspire-V3-571G kernel: 5644 bytes written
May 12 10:56:11 jio-Aspire-V3-571G kernel: 5468 bytes written
May 12 10:56:11 jio-Aspire-V3-571G kernel: 5470 bytes written
May 12 10:56:11 jio-Aspire-V3-571G kernel: 5282 bytes written
May 12 10:56:11 jio-Aspire-V3-571G kernel: 186 bytes written
May 12 10:56:11 jio-Aspire-V3-571G kernel: 5644 bytes written
May 12 10:56:11 jio-Aspire-V3-571G kernel: 5468 bytes written
May 12 10:56:11 jio-Aspire-V3-571G kernel: 5470 bytes written
May 12 10:56:11 jio-Aspire-V3-571G kernel: 5280 bytes written
May 12 10:56:11 jio-Aspire-V3-571G kernel: 188 bytes written
May 12 10:56:11 jio-Aspire-V3-571G kernel: 5644 bytes written
May 12 10:56:11 jio-Aspire-V3-571G kernel: Triggered
May 12 10:56:11 jio-Aspire-V3-571G kernel: STOP
May 12 10:56:11 jio-Aspire-V3-571G sudo[5805]:      jio : TTY=pts/4 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 12 10:56:11 jio-Aspire-V3-571G sudo[5805]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 12 10:56:11 jio-Aspire-V3-571G sudo[5805]: pam_unix(sudo:session): session closed for user root
May 12 10:56:30 jio-Aspire-V3-571G kernel: FIFO file closed

Thanks for the system info, @Cuda-Chen !

And I just found that the repeated FIFO open/close seems caused by the insmod instead of aplay.

Therefore, I suspect that this might be due to the module not being fully initialized yet. I tried simply adding sleep 1 before the insmod, and after running a few simple tests, the issue did not reoccur.

Could you please try this in your environment as well?

Hi @freshLiver ,

Sorry for the late reply. I will conduct the "sleep 1 before the insmod test in these days.

I tried simply adding sleep 1 before the insmod, and after running a ...

Sorry, I made a mistake. The sleep command should be added after insmod.

Hi @freshLiver ,

I tried simply adding sleep 1 before the insmod, and after running a ...

Sorry, I made a mistake. The sleep command should be added after insmod.

It seems that the sleep after insmod does not solve the repeated FIFO open/close scene:

$ journalctl -f

------ I AM SEPARATOR (the first time make check) ------

May 19 09:14:28 jio-Aspire-V3-571G systemd[4649]: Reached target Sound Card.
May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file closed
May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file closed
May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file closed
May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file closed
May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file closed
May 19 09:14:28 jio-Aspire-V3-571G rtkit-daemon[1456]: Supervising 6 threads of 3 processes of 1 users.
May 19 09:14:28 jio-Aspire-V3-571G rtkit-daemon[1456]: Successfully made thread 9338 of process 4658 owned by '1000' RT at priority 5.
May 19 09:14:28 jio-Aspire-V3-571G rtkit-daemon[1456]: Supervising 7 threads of 3 processes of 1 users.
May 19 09:14:28 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 19 09:14:28 jio-Aspire-V3-571G kernel: Triggered
May 19 09:14:30 jio-Aspire-V3-571G kernel: START: channels 1 rate 22050
May 19 09:14:30 jio-Aspire-V3-571G kernel: kernel_write: expect write 88200, but 65536
May 19 09:14:30 jio-Aspire-V3-571G sudo[9346]:      jio : TTY=pts/5 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 19 09:14:30 jio-Aspire-V3-571G sudo[9346]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 19 09:14:30 jio-Aspire-V3-571G sudo[9346]: pam_unix(sudo:session): session closed for user root
May 19 09:14:32 jio-Aspire-V3-571G kernel: 882 bytes written
May 19 09:14:32 jio-Aspire-V3-571G kernel: kernel_write: expect write 87318, but 65536
May 19 09:14:33 jio-Aspire-V3-571G kernel: kernel_write failed
May 19 09:14:33 jio-Aspire-V3-571G kernel: Triggered
May 19 09:14:33 jio-Aspire-V3-571G kernel: STOP

------ I AM SEPARATOR (the second time make check) ------

May 19 09:16:00 jio-Aspire-V3-571G sudo[9626]:      jio : TTY=pts/5 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/modprobe snd_pcm
May 19 09:16:00 jio-Aspire-V3-571G sudo[9626]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 19 09:16:00 jio-Aspire-V3-571G sudo[9626]: pam_unix(sudo:session): session closed for user root
May 19 09:16:00 jio-Aspire-V3-571G sudo[9629]:      jio : TTY=pts/5 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 19 09:16:00 jio-Aspire-V3-571G sudo[9629]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 19 09:16:00 jio-Aspire-V3-571G sudo[9629]: pam_unix(sudo:session): session closed for user root
May 19 09:16:00 jio-Aspire-V3-571G sudo[9634]:      jio : TTY=pts/5 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
May 19 09:16:00 jio-Aspire-V3-571G sudo[9634]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 19 09:16:00 jio-Aspire-V3-571G sudo[9634]: pam_unix(sudo:session): session closed for user root
May 19 09:16:02 jio-Aspire-V3-571G kernel: FIFO file closed
May 19 09:16:02 jio-Aspire-V3-571G kernel: FIFO file /tmp/audio.pcm opened
May 19 09:16:02 jio-Aspire-V3-571G kernel: Triggered
May 19 09:16:02 jio-Aspire-V3-571G kernel: START: channels 1 rate 22050
May 19 09:16:03 jio-Aspire-V3-571G kernel: 5820 bytes written
May 19 09:16:03 jio-Aspire-V3-571G kernel: 5468 bytes written
May 19 09:16:03 jio-Aspire-V3-571G kernel: 5470 bytes written
May 19 09:16:03 jio-Aspire-V3-571G kernel: 5290 bytes written
May 19 09:16:03 jio-Aspire-V3-571G kernel: 178 bytes written
May 19 09:16:03 jio-Aspire-V3-571G kernel: 5644 bytes written
May 19 09:16:03 jio-Aspire-V3-571G kernel: 5468 bytes written
May 19 09:16:03 jio-Aspire-V3-571G kernel: 5470 bytes written
May 19 09:16:03 jio-Aspire-V3-571G kernel: 5288 bytes written
May 19 09:16:03 jio-Aspire-V3-571G kernel: 180 bytes written
May 19 09:16:04 jio-Aspire-V3-571G kernel: 5644 bytes written
May 19 09:16:04 jio-Aspire-V3-571G kernel: 5468 bytes written
May 19 09:16:04 jio-Aspire-V3-571G kernel: 5470 bytes written
May 19 09:16:04 jio-Aspire-V3-571G kernel: 5286 bytes written
May 19 09:16:04 jio-Aspire-V3-571G kernel: 182 bytes written
May 19 09:16:04 jio-Aspire-V3-571G kernel: 5644 bytes written
May 19 09:16:04 jio-Aspire-V3-571G kernel: 5468 bytes written
May 19 09:16:04 jio-Aspire-V3-571G kernel: 5470 bytes written
May 19 09:16:04 jio-Aspire-V3-571G kernel: 5284 bytes written
May 19 09:16:04 jio-Aspire-V3-571G kernel: 184 bytes written
May 19 09:16:05 jio-Aspire-V3-571G kernel: 5644 bytes written
May 19 09:16:05 jio-Aspire-V3-571G kernel: 5468 bytes written
May 19 09:16:05 jio-Aspire-V3-571G kernel: 5470 bytes written
May 19 09:16:05 jio-Aspire-V3-571G kernel: 5282 bytes written
May 19 09:16:05 jio-Aspire-V3-571G kernel: 186 bytes written
May 19 09:16:05 jio-Aspire-V3-571G kernel: 5644 bytes written
May 19 09:16:05 jio-Aspire-V3-571G kernel: 5468 bytes written
May 19 09:16:05 jio-Aspire-V3-571G kernel: 5470 bytes written
May 19 09:16:05 jio-Aspire-V3-571G kernel: 5280 bytes written
May 19 09:16:05 jio-Aspire-V3-571G kernel: 188 bytes written
May 19 09:16:05 jio-Aspire-V3-571G kernel: 5644 bytes written
May 19 09:16:05 jio-Aspire-V3-571G kernel: Triggered
May 19 09:16:05 jio-Aspire-V3-571G kernel: STOP
May 19 09:16:05 jio-Aspire-V3-571G sudo[9644]:      jio : TTY=pts/5 ; PWD=/home/jio/c_code/vsnd ; USER=root ; COMMAND=/usr/sbin/rmmod vsnd
May 19 09:16:05 jio-Aspire-V3-571G sudo[9644]: pam_unix(sudo:session): session opened for user root(uid=0) by jio(uid=1000)
May 19 09:16:05 jio-Aspire-V3-571G sudo[9644]: pam_unix(sudo:session): session closed for user root

$ dmesg -W

------ I AM SEPARATOR (the first time make check) ------

[  314.697972] FIFO file /tmp/audio.pcm opened
[  314.698094] FIFO file closed
[  314.698197] FIFO file /tmp/audio.pcm opened
[  314.698251] FIFO file closed
[  314.698339] FIFO file /tmp/audio.pcm opened
[  314.698413] FIFO file closed
[  314.698500] FIFO file /tmp/audio.pcm opened
[  314.698674] FIFO file closed
[  314.698781] FIFO file /tmp/audio.pcm opened
[  314.702722] FIFO file closed
[  314.704888] FIFO file /tmp/audio.pcm opened
[  314.711622] Triggered
[  314.711627] START: channels 1 rate 22050
[  316.731118] kernel_write: expect write 88200, but 65536
[  316.731193] 882 bytes written
[  318.715116] kernel_write: expect write 87318, but 65536
[  318.715147] kernel_write failed
[  319.717213] Triggered
[  319.717237] STOP
[  319.717305] FIFO file closed

------ I AM SEPARATOR (the second time make check) ------

[  409.397916] FIFO file /tmp/audio.pcm opened
[  409.401056] Triggered
[  409.401061] START: channels 1 rate 22050
[  409.530983] 5820 bytes written
[  409.654960] 5468 bytes written
[  409.778954] 5470 bytes written
[  409.902960] 5290 bytes written
[  409.903001] 178 bytes written
[  410.030961] 5644 bytes written
[  410.154964] 5468 bytes written
[  410.278966] 5470 bytes written
[  410.402963] 5288 bytes written
[  410.403010] 180 bytes written
[  410.530957] 5644 bytes written
[  410.654959] 5468 bytes written
[  410.778956] 5470 bytes written
[  410.902964] 5286 bytes written
[  410.903005] 182 bytes written
[  411.030957] 5644 bytes written
[  411.154950] 5468 bytes written
[  411.278950] 5470 bytes written
[  411.402949] 5284 bytes written
[  411.403016] 184 bytes written
[  411.530954] 5644 bytes written
[  411.654952] 5468 bytes written
[  411.778955] 5470 bytes written
[  411.902952] 5282 bytes written
[  411.903017] 186 bytes written
[  412.030952] 5644 bytes written
[  412.154904] 5468 bytes written
[  412.278954] 5470 bytes written
[  412.402954] 5280 bytes written
[  412.403024] 188 bytes written
[  412.530953] 5644 bytes written
[  412.531017] Triggered
[  412.531030] STOP

What's more, my environment is complaining about cannot find errname, so I change your patch in vsnd.c as follows:

diff --git a/vsnd.c b/vsnd.c
index adb5841..22f10fe 100644
--- a/vsnd.c
+++ b/vsnd.c
@@ -222,7 +226,19 @@ static unsigned int vsnd_pos_update(struct vsnd_pcm *pcm_data)
         unsigned int size = byte_left_to_write;
         if (src_off + size > pcm_data->pcm_buffer_size)
             size = pcm_data->pcm_buffer_size - src_off;
-        kernel_write(vsnd->fifo_fp, src_data + src_off, size, NULL);
+    again:
+        ret = kernel_write(vsnd->fifo_fp, src_data + src_off, size, NULL);
+        if (ret < 0) {
+            // if (ret == -EAGAIN && retry_limit--) {
+            //     goto again;
+            // }
+            //pr_err("kernel_write: failed: %s", errname(ret));
+            pr_err("kernel_write failed");
+        } else if (ret < size) {
+            pr_warn("kernel_write: expect write %d, but %d", size, ret);
+        } else {
+            pr_info("%d bytes written", ret);
+        }
         byte_left_to_write -= size;
         src_off = (src_off + size) % pcm_data->pcm_buffer_size;
     } while (byte_left_to_write > 0);

@Cuda-Chen , thanks for testing and sharing the result,

I might try to enable some configs (e.g., CONFIG_SND_DEBUG) on the 5.15 kernel to check whether there will have some debug messages reported by the kernel.

And, for the errname symbol, since this option CONFIG_SYMBOLIC_ERRNAME is enabled in all my testing environments, I assumed it was enabled by default in Ubuntu. Sorry for not handling it.

Hi @freshLiver ,

I might try to enable some configs (e.g., CONFIG_SND_DEBUG) on the 5.15 kernel to check whether there will have some debug messages reported by the kernel.

You can share the configs here as we have gotten the same result yet different environment.

And, for the errname symbol, since this option CONFIG_SYMBOLIC_ERRNAME is enabled in all my testing environments, I assumed it was enabled by default in Ubuntu. Sorry for not handling it.

That's okey, as there are zillion of options, and some of the options require re-compilation.

@Cuda-Chen ,

No problem, I will post my kernel config (maybe using the gist to avoid making this page too long) once I have reproduced the problem on the custom kernels.

For configs of the testing environments above, I think they should be available via the apt?

I prepared an environment with a configuration based on 5.15.0-106-generic for testing. However, this time adding sleep after insmod did not completely resolve the issue, and unfortunately, there is no new debug messages generated by ALSA after enabling additional debug configs.

Further tests might needed to be conducted for checking whether it's related to kernel version.

The output messages along with kernel logs:

user@localhost:/mnt$ ./scripts/verify.sh
+ sudo modprobe snd_pcm
+ sudo rmmod vsnd
rmmod: ERROR: Module vsnd is not currently loaded
+ rm -f /tmp/audio.pcm
+ mkfifo /tmp/audio.pcm
+ sudo insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
+ sleep 1                                 <------- sleep after insmod
[  485.647657] FIFO file closed
[  517.606441] FIFO file /tmp/audio.pcm opened
...                                       <------- repeated open/close
[  517.612729] FIFO file closed
[  517.613972] FIFO file /tmp/audio.pcm opened

[  517.614927] vsnd_hw_params called
[  517.616064] vsnd_prepare called
[  517.618359] vsnd_hw_free called
[  517.619281] FIFO file closed
[  517.621212] FIFO file /tmp/audio.pcm opened
[  517.622204] vsnd_hw_params called
[  517.623357] vsnd_prepare called
[  517.629391] Triggered
[  517.630324] START: channels 1 rate 22050
[  517.733149] 4408 bytes written
...                                       <------- writes without error
[  518.436974] 192 bytes written
[  518.533135] kernel_write: expect write 4216, but 120
+ tee out.pcm
+ sleep 1
[  518.536736] 194 bytes written
... writes without error
[  519.533158] 4020 bytes written
+ aplay -D plughw:CARD=vsnd,DEV=0 CantinaBand3.wav
aplay: main:831: audio open error: Device or resource busy
+ sudo rmmod vsnd
rmmod: ERROR: Module vsnd is in use
[  519.537201] 214 bytes written

[  519.641091] 4194 bytes written
-rw-r--r-- 1 user user 84456 May 26  2024 out.pcm  <------- weird output size
+ ffmpeg -f s16le -ar 22.05k -ac 1 -loglevel 8 -i out.pcm out.wav
File 'out.wav' already exists. Overwrite? [y/N] 
[  519.642957] 392 bytes written
...                                       <------- delayed(?) writes without error
[  522.541071] 450 bytes written
[  522.634363] Triggered
[  522.637864] STOP
[  522.640649] vsnd_hw_free called

Not overwriting - exiting

I prepared an environment with a configuration based on 5.15.0-106-generic for testing. However, this time adding sleep after insmod did not completely resolve the issue, and unfortunately, there is no new debug messages generated by ALSA after enabling additional debug configs.

Hi @freshLiver , thanks for sharing, I will compile the 5.15 kernel with your configuration for testing.

What's more, can you help me to confirm the "weird output size output.pcm" contains crappy/lagged sound?

@Cuda-Chen ,

Sure, and when I was trying to reproduce the problem, I found that the writes after rmmod don't appear to be merely delayed. If we check the size after all writes have completed, we will find that the output file is much larger than the expected size and its content is entirely zeros:

+ ls -l out.pcm
-rw-r--r-- 1 user user 84456 May 27  2024 out.pcm  <------- size before all writes done
+ ffmpeg -f s16le -ar 22.05k -ac 1 -loglevel 8 -i out.pcm out.wav
[  238.170629] 392 bytes written
[  238.267125] 4016 bytes written
user@localhost:/mnt$
[  238.267845] 394 bytes written
[  238.363233] 4014 bytes written
...
[  241.166242] 276 bytes written
[  241.169218] Triggered
[  241.169741] STOP
[  241.170160] vsnd_hw_free called

user@localhost:/mnt$ ls -l out*
-rw-r--r-- 1 user user 216580 May 27 00:07 out.pcm <------- size after all writes done

user@localhost:/mnt$ diff out.pcm <(head -c 216580 /dev/zero) && echo zero
zero

Additionally, it is worth noting that if I disable the pulseaudio service, the previously mentioned issues do not occur during the process, and the resulting audio file also sounds no problem as expected:

user@localhost:/mnt$ systemctl --user stop pulseaudio{.socket,}
user@localhost:/mnt$ ./scripts/verify.sh 
+ sudo modprobe snd_pcm
+ sudo rmmod vsnd
rmmod: ERROR: Module vsnd is not currently loaded
+ rm -f /tmp/audio.pcm
+ mkfifo /tmp/audio.pcm
+ sudo insmod vsnd.ko out_fifo_name=/tmp/audio.pcm
+ tee out.pcm
+ sleep 1
+ aplay -D plughw:CARD=vsnd,DEV=0 CantinaBand3.wav
[ 1726.186125] FIFO file closed
Playing WAVE 'CantinaBand3.wav' : Signed 16 bit Little Endian, R[ 1794.967182] FIFO file /tmp/audio.pcm opened
ate 22050 Hz, Mo[ 1794.970675] vsnd_hw_params called
no
[ 1794.971712] vsnd_prepare called
[ 1794.972949] Triggered
[ 1794.973686] START: channels 1 rate 22050
[ 1795.103143] 5820 bytes written
...
[ 1798.107200] 5820 bytes written
[ 1798.108196] Triggered
[ 1798.108991] STOP
[ 1798.109993] vsnd_hw_free called
+ sudo rmmod vsnd
+ ls -l out.pcm
-rw-r--r-- 1 user user 138296 May 27  2024 out.pcm
+ ffmpeg -f s16le -ar 22.05k -ac 1 -loglevel 8 -i out.pcm out.wav
File 'out.wav' already exists. Overwrite? [y/N] y
-rw-r--r-- 1 user user 138296 May 27 00:33 out.pcm
-rw-r--r-- 1 user user 138374 May 27 00:33 out.wav <----- sounds no problem

Hi @freshLiver ,

For my knowledge, both PulseAudio and PipeWire are downstream of ALSA. So I suspect there is something funny happens when these downstream components receive the data sent from ALSA.

I suspect there is something funny happens ...

Agree, I have similar opinion as the problems above didn't occur when neither PulseAudio nor PipeWire was enabled.

But I also think it will be good that if there is a workaround for this issue, since most distributions use one of them the by default.

Hi @freshLiver ,

For debugging the PulseAudio, you can first disable PulseAudio then launch pluseaudio -vvvvv to check the status of PulseAudio. I put the reference here: https://fedoraproject.org/wiki/How_to_debug_PulseAudio_problems

I'm currently tracing the problem with gdb, and there are some new findings:

The write errors occurred during the execution of the PA module module-udev-detect
The problem will not happen if you comment out the load-module module-udev-detect in PA config. And if you load the module manually by using pactl load-module module-udev-detect, it will write data to the FIFO and cause write errors.
the EAGAIN is returned from pipe.c (updated: fix wrong line number)

Hi @freshLiver ,

Thanks for your report! For PulseAudio, I found that the reference count of vsnd cannot be decreased if PulseAudio is enabled.

As I have little knowledge of debugging the kernel module, I would like to ask that may you leave the steps? I have read the kernel document (https://docs.kernel.org/dev-tools/gdb-kernel-debugging.html), it seems that I have to launch a VM, and I am curious are there any alternatives for debugging.

@Cuda-Chen ,

I found that the reference count of vsnd cannot be decreased

Thanks for the information! Could you provide the detailed information about the reference count?

I am curious are there any alternatives for debugging.

Maybe you can try user-mode linux, but I'm using qemu as I'm more familiar with it.

Here are the brief steps for building my testing environment:

prepare a rootfs with needed packages (I use systemd/mkosi to generate the rootfs image)
defconfig + debug configs mentioned in the kernel doc + sound card configs (make sure the needed modules are built into the kernel, so that you don't need to copy the modules to rootfs)
add the path of vmlinux-gdb.py script to the gdb config file and make sure your gdb has python supported
run qemu with options mentioned in the doc, and attach gdb to it
use lx-symbols /path/to/vsnd/dir to load the vsnd symbol after the module is inserted to the kernel

@freshLiver ,

Thanks for the information! Could you provide the detailed information about the reference count?

For the reference count observation, it is mentioned in https://github.com/sysprog21/vsnd/issues/1#issuecomment-1949903668, and for you ease I re-post here:

$ lsmod | grep vsnd
vsnd                   16384  1
snd_pcm               143360  7 snd_hda_codec_hdmi,snd_hda_intel,snd_hda_codec,vsnd,snd_hda_core
snd                   106496  24 snd_hda_codec_generic,snd_seq,snd_seq_device,snd_hda_codec_hdmi,snd_hwdep,snd_hda_intel,snd_hda_codec,snd_hda_codec_realtek,snd_timer,vsnd,snd_pcm,snd_rawmidi

Here are the brief steps for building my testing environment: omitted as it is lengthy

I will try on it as well as user-mode linux. Once I have any findings or some setting problems, I will leave comments here.

I found that this problem may be relative to the open flag in vsnd_open.

According to the description of open() from The Open Group Base Specifications, open a FIFO with flag O_RDWR is undefined:

O_RDWR

Open for reading and writing. The result is undefined if this flag is applied to a FIFO.

And if I change the open flag to O_WRONLY, vsnd_open() will encounter an ENXIO error while executing the udev-detect module (manually load it via pactl load-module after the vsnd is inserted into kernel). According to the man page of open(2):

ENXIO O_NONBLOCK | O_WRONLY is set, the named file is a FIFO, and no process has the FIFO open for reading.

As for scripts/verify.sh, since it opens the read end through tee out.pcm < /tmp/audio.pcm >/dev/null & before writing data, I didn't encounter any open error when running this script.

To address the problem and eliminate the undefined behavior, a simple workaround might be to add a buffer and write data to the buffer when vsnd fails to open the FIFO, indicating that no read end exists.

To address the problem and eliminate the undefined behavior, a simple workaround might be to add a buffer and write data to the buffer when vsnd fails to open the FIFO, indicating that no read end exists.

It is reasonably fair to forbid non-blocking mode for this FIFO based driver model.

Do you mean that the vsnd_open should fall back to blocking mode when there is no reader, instead of writing to a buffer?

Do you mean that the vsnd_open should fall back to blocking mode when there is no reader, instead of writing to a buffer?

Yes, keep it simple and stupid.

I made some changes to implement the fallback mechanism:

diff --git a/vsnd.c b/vsnd.c
old mode 100644
new mode 100755
index adb5841..45f890f
--- a/vsnd.c
+++ b/vsnd.c
@@ -328,7 +328,7 @@ static int vsnd_open(struct snd_pcm_substream *substream)
     struct vsnd_pcm *pcm_data;
     int dev_id = substream->pcm->device;
     void *fifo_fp;
-    int err = 0;
+    int err = 0, oflags = O_WRONLY | O_NONBLOCK;

     /* Create and configure PCM data structures */
     pcm_data = kzalloc(sizeof(*pcm_data), GFP_KERNEL);
@@ -342,9 +342,15 @@ static int vsnd_open(struct snd_pcm_substream *substream)
     /* CAUTION: We need to open this FIFO pipe as for both read-write as opening
      * for write-only will cause 'flip_close()' to crash.
      */
-    fifo_fp = filp_open(out_fifo_name[dev_id], O_RDWR | O_NONBLOCK, 0);
+retry:
+    fifo_fp = filp_open(out_fifo_name[dev_id], oflags, 0);
     if (IS_ERR(fifo_fp)) {
-        pr_err("Failed to open FIFO file.");
+        if (PTR_ERR(fifo_fp) == -ENXIO && (oflags & O_NONBLOCK)) {
+            pr_warn("no read end exists, fallback to blocking mode");
+            oflags &= ~O_NONBLOCK;
+            goto retry;
+        }
+        pr_err("Failed to open FIFO file with 0x%x, err:%ld.", oflags, PTR_ERR(fifo_fp));
         err = -EIO;
         goto finally;
     }

But during the execution of verify.sh script, it stuck at the aplay command. And after checking the logs of PA, I found that it's because the PA (with module-udev-detect enabled) stuck at the initialization step as there is no reader exists. And in order to finish the PA initialization, I had to manually read the FIFO file several times. (updated: pulseaudio log, not system journal)

update 2: I have also tried fall back to O_RDWR instead of O_WRONLY, but result in kernel errors and system stuck:

[  128.279827] no read end exists, fallback to O_RDWR
[  128.287839] START: channels 1 rate 22050
[  129.189331] BUG: scheduling while atomic: swapper/0/0/0x00000100
[  129.190127] STOP
[  129.190784] Modules linked in: vsnd(O-) [last unloaded: vsnd]
[  129.193035] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G           O      5.15.149 #8
[  129.193039] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[  129.193044] Call Trace:
[  129.193058]  <IRQ>
[  129.193063]  dump_stack_lvl+0x33/0x46
[  129.193073]  __schedule_bug.cold+0x3e/0x4a
[  129.193080]  __schedule+0x5c7/0x6c0
[  129.193091]  schedule+0x53/0xa0
[  129.193094]  pipe_write+0x449/0x620
[  129.193101]  ? wait_woken+0x70/0x70
[  129.193105]  __kernel_write+0x28b/0x310
[  129.193107]  kernel_write+0x6e/0x150
[  129.193110]  vsnd_timer_elapsed+0x162/0x1c0 [vsnd]
[  129.193114]  ? vsnd_runtime_free+0x10/0x10 [vsnd]
[  129.193116]  call_timer_fn+0x22/0xf0
[  129.193123]  __run_timers+0x204/0x270
[  129.193126]  run_timer_softirq+0x14/0x30
[  129.193128]  __do_softirq+0xbb/0x26a
[  129.193149]  irq_exit_rcu+0x7e/0xa0
[  129.193162]  sysvec_apic_timer_interrupt+0x66/0x80
[  129.193170]  </IRQ>
[  129.193170]  <TASK>
[  129.193171]  asm_sysvec_apic_timer_interrupt+0x16/0x20
[  129.193179] RIP: 0010:default_idle+0xb/0x10
[  129.193183] Code: fb 65 48 8b 04 25 00 ad 01 00 f0 80 60 02 df c3 cc cc cc cc 0f ae f0 0f ae 38 0f ae f0 eb b5 eb 07 0f 00 2d 27 42 55 00 fb f4 <c3> cc cc cc cc 65 8b 15 59 32 36 7e 89 d2 48 8b 05 70 00 52 01 48
[  129.193185] RSP: 0018:ffffffff82803eb0 EFLAGS: 00000206
[  129.193187] RAX: ffffffff81cb2300 RBX: ffffffff82814940 RCX: ffff888003a57370
[  129.193188] RDX: 0000000000007655 RSI: ffffffff82803e40 RDI: 0000000000007656
[  129.193190] RBP: 0000000000000000 R08: 0000000000007655 R09: 0000000000000324
[  129.193191] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000000
[  129.193192] R13: 0000000000000000 R14: ffffffff82814118 R15: 0000000000000000
[  129.193194]  ? mwait_idle+0x70/0x70
[  129.193199]  default_idle_call+0x2e/0xb0
[  129.193201]  do_idle+0x1ee/0x260
[  129.193208]  cpu_startup_entry+0x14/0x20
[  129.193211]  start_kernel+0x63c/0x665
[  129.193218]  secondary_startup_64_no_verify+0xc2/0xcb
[  129.193224]  </TASK>
[  129.193226] bad: scheduling from the idle thread!

And about the usage of O_RDWR flag mentioned before, I notice that fifo(7) says that it's not undefined behavior under linux, sorry for the misunderstanding.

Under Linux, opening a FIFO for read and write will succeed both in blocking and nonblocking mode. POSIX leaves this behavior undefined. This can be used to open a FIFO for writing while there are no readers available.

To avoid the issue where vsnd gets stuck waiting for a reader during PulseAudio initialization, I tried several different methods to handle the situation when no reader exists during the open call:

Fallback to O_RDWR | O_NONBLOCK mode (#700350f)

This approach is similar to the current implementation. Since verify.sh adds a sleep between tee and aplay, the tee becomes the reader during PulseAudio initialization, and aplay encounters an EBUSY error when attempting to open the PCM device because vsnd is already occupied by PulseAudio.

In my test environment, although removing the sleep allows aplay to occupy vsnd first (due to some delay between module-udev-detect and insmod), this approach is obviously unreliable. Any delay between insmod and tee might result in PulseAudio getting vsnd first, causing aplay to encounter the EBUSY error.
Directly fail vsnd_open and return ENXIO (#792cd33)

With a sleep between tee and aplay, PulseAudio seems to attempt multiple open calls. As a result, sometimes PulseAudio successfully opens due to the presence of tee, causing aplay's reader to disappear and leading to an open failure (ENXIO).

Moving the sleep before the tee can solve this, but it will cause PulseAudio initialization fail and fail to recognize vsnd.
Make vsnd_open succeed but without actually opening and writing to the FIFO (#f97e367)

With a sleep between tee and aplay, the situation is similar to situation 1.
Based on method 3, add substreams to avoid competition between PulseAudio and aplay (#2b2dd19)

With a sleep between tee and aplay, PulseAudio makes multiple open calls, and tee might be treated as a reader in one of those attempts, causing subsequent aplay to be judged as open without a reader.

In several of my test environments, this issue can be resolved by adding a sleep before tee, as PulseAudio's initialization process seems to involve only one open that performs a write, and other open calls are immediately closed.

After these tests, I think the previously encountered issue of out.wav sounds lagged is due to PulseAudio (or PipeWire) initialization and aplay write data interleaved to the FIFO.

Hi @freshLiver ,

Thanks for your thorough examinations! For the user-mode Linux environment, though I am quite busy these weeks (for my working and supporting other project), I think I can create a document of how to debugging the vsnd with user-mode Linux environment once I figure out the compilation settings and the installation of with PulseAudio and PipeWire.

sysprog21 / vsnd