What is the reproducer?  Also can you make sure the problem without nvidia binary stuff?

I was able to reproduce it without the nvidia binaries loaded and notcied that there are two traces.

I have two different usb audio devices I use, the trace happens the only first time I use card 3 device 0.
When playing from card 2 device 0 it didn't underflow after a fresh boot, but afterwards using card 3 again would produce the underflow again.

The application I use is sndiod (http://www.sndio.org/), I wasn't able to reproduce it with mpv --ao=alsa, but using sndiod again after testing mpv --ao=alsa resulted in the traces.

**** List of PLAYBACK Hardware Devices ****
card 0: MID [HDA Intel MID], device 0: VT1705 Analog [VT1705 Analog]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: MID [HDA Intel MID], device 1: VT1705 Digital [VT1705 Digital]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: MID [HDA Intel MID], device 2: VT1705 Alt Analog [VT1705 Alt Analog]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: NVidia [HDA NVidia], device 3: HDMI 0 [HDMI 0]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: NVidia [HDA NVidia], device 7: HDMI 1 [HDMI 1]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: NVidia [HDA NVidia], device 8: HDMI 2 [HDMI 2]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 2: Speaker [USB Speaker], device 0: USB Audio [USB Audio]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 3: Headset [Logitech G430 Gaming Headset], device 0: USB Audio [USB Audio]
  Subdevices: 1/1
  Subdevice #0: subdevice #0


[   37.622693] ------------[ cut here ]------------
[   37.622695] refcount_t: increment on 0; use-after-free.
[   37.622716] WARNING: CPU: 2 PID: 768 at lib/refcount.c:156 refcount_inc_checked+0x26/0x30
[   37.622718] Modules linked in: cfg80211 8021q garp mrp stp llc nft_counter nft_ct nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nft_limit nf_tables_set nf_tables nfnetlink snd_hda_codec_hdmi snd_usb_audio coretemp intel_powerclamp snd_usbmidi_lib snd_rawmidi input_leds media kvm_intel snd_hda_codec_via snd_hda_codec_generic ledtrig_audio iTCO_wdt gpio_ich iTCO_vendor_support mei_wdt snd_hda_intel kvm irqbypass snd_hda_codec atl1c intel_cstate mei_me i2c_i801 snd_hda_core psmouse snd_hwdep mei lpc_ich snd_pcm evdev intel_agp intel_gtt mac_hid pcc_cpufreq acpi_cpufreq snd_seq snd_seq_device snd_timer snd soundcore vhost_vsock vmw_vsock_virtio_transport_common vsock vhost_net vhost tap uhid hci_vhci bluetooth ecdh_generic rfkill ecc vfio_iommu_type1 vfio dm_mod uinput userio ppp_generic slhc tun loop nvram btrfs xor raid6_pq libcrc32c cuse fuse ext4 crc32c_generic crc16 mbcache jbd2 usbmouse hid_generic usbkbd usbhid hid sd_mod nouveau ata_generic hwmon pata_acpi video mxm_wmi wmi i2c_algo_bit
[   37.622789]  drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm ata_piix ehci_pci ehci_hcd libata serio_raw drm crc32c_intel usbcore scsi_mod agpgart button
[   37.622803] CPU: 2 PID: 768 Comm: sndiod Not tainted 5.2.1_1 #1
[   37.622804] Hardware name: ECS H55H-M/H55H-M, BIOS 080016  11/26/2009
[   37.622807] RIP: 0010:refcount_inc_checked+0x26/0x30
[   37.622810] Code: 00 00 00 00 e8 9b ff ff ff 84 c0 74 01 c3 80 3d f2 c5 d2 00 00 75 f6 48 c7 c7 28 bc db aa c6 05 e2 c5 d2 00 01 e8 89 3b cb ff <0f> 0b c3 0f 1f 80 00 00 00 00 41 54 8b 06 83 f8 ff 74 1d 31 c9 39
[   37.622812] RSP: 0018:ffffb452815efcd8 EFLAGS: 00010086
[   37.622814] RAX: 0000000000000000 RBX: ffffa065756c8000 RCX: 0000000000000006
[   37.622816] RDX: 0000000000000007 RSI: 0000000000000086 RDI: ffffa06577a97450
[   37.622817] RBP: ffffa06575127318 R08: 00000000000002f8 R09: 0000000000000004
[   37.622819] R10: 0000000000000000 R11: 0000000000000001 R12: ffffa065756c8148
[   37.622820] R13: 0000000000000000 R14: 0000000000000003 R15: ffffa0656d58e4c8
[   37.622823] FS:  00007f58657f1740(0000) GS:ffffa06577a80000(0000) knlGS:0000000000000000
[   37.622825] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   37.622827] CR2: 000055c2ba492bf0 CR3: 000000022dc50000 CR4: 00000000000006e0
[   37.622829] Call Trace:
[   37.622848]  snd_pcm_stream_group_ref+0x7d/0xc0 [snd_pcm]
[   37.622856]  snd_pcm_action+0x1d/0x70 [snd_pcm]
[   37.622860]  __snd_pcm_lib_xfer+0x68b/0x920 [snd_pcm]
[   37.622865]  ? snd_pcm_hw_rule_step+0xf0/0xf0 [snd_pcm]
[   37.622869]  ? default_read_copy+0x70/0x70 [snd_pcm]
[   37.622874]  ? mem_cgroup_commit_charge+0x80/0x550
[   37.622876]  ? mem_cgroup_try_charge+0xa9/0x200
[   37.622880]  snd_pcm_common_ioctl+0x4f2/0xb90 [snd_pcm]
[   37.622885]  ? __handle_mm_fault+0xb31/0x1600
[   37.622889]  snd_pcm_ioctl+0x23/0x30 [snd_pcm]
[   37.622894]  do_vfs_ioctl+0x40c/0x670
[   37.622897]  ksys_ioctl+0x5e/0x90
[   37.622900]  __x64_sys_ioctl+0x16/0x20
[   37.622904]  do_syscall_64+0x4e/0x110
[   37.622907]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   37.622910] RIP: 0033:0x7f5865b54d97
[   37.622911] Code: 00 00 90 48 8b 05 f9 70 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d c9 70 0c 00 f7 d8 64 89 01 48
[   37.622912] RSP: 002b:00007fff109a84f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[   37.622914] RAX: ffffffffffffffda RBX: 000055c2ba47a7d0 RCX: 00007f5865b54d97
[   37.622915] RDX: 00007fff109a8500 RSI: 0000000040184150 RDI: 0000000000000006
[   37.622916] RBP: 000055c2ba47a850 R08: 0000000000000000 R09: 00007fff109b80b0
[   37.622918] R10: 00007fff109b8080 R11: 0000000000000246 R12: 000055c2ba478dd0
[   37.622919] R13: 000055c2ba491d00 R14: 0000000000000076 R15: 0000000000002b11
[   37.622921] ---[ end trace 999976d6ea591bcf ]---
[   37.622983] ------------[ cut here ]------------
[   37.622983] refcount_t: underflow; use-after-free.
[   37.622995] WARNING: CPU: 2 PID: 768 at lib/refcount.c:190 refcount_sub_and_test_checked+0x55/0x60
[   37.622996] Modules linked in: cfg80211 8021q garp mrp stp llc nft_counter nft_ct nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nft_limit nf_tables_set nf_tables nfnetlink snd_hda_codec_hdmi snd_usb_audio coretemp intel_powerclamp snd_usbmidi_lib snd_rawmidi input_leds media kvm_intel snd_hda_codec_via snd_hda_codec_generic ledtrig_audio iTCO_wdt gpio_ich iTCO_vendor_support mei_wdt snd_hda_intel kvm irqbypass snd_hda_codec atl1c intel_cstate mei_me i2c_i801 snd_hda_core psmouse snd_hwdep mei lpc_ich snd_pcm evdev intel_agp intel_gtt mac_hid pcc_cpufreq acpi_cpufreq snd_seq snd_seq_device snd_timer snd soundcore vhost_vsock vmw_vsock_virtio_transport_common vsock vhost_net vhost tap uhid hci_vhci bluetooth ecdh_generic rfkill ecc vfio_iommu_type1 vfio dm_mod uinput userio ppp_generic slhc tun loop nvram btrfs xor raid6_pq libcrc32c cuse fuse ext4 crc32c_generic crc16 mbcache jbd2 usbmouse hid_generic usbkbd usbhid hid sd_mod nouveau ata_generic hwmon pata_acpi video mxm_wmi wmi i2c_algo_bit
[   37.623043]  drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm ata_piix ehci_pci ehci_hcd libata serio_raw drm crc32c_intel usbcore scsi_mod agpgart button
[   37.623054] CPU: 2 PID: 768 Comm: sndiod Tainted: G        W         5.2.1_1 #1
[   37.623056] Hardware name: ECS H55H-M/H55H-M, BIOS 080016  11/26/2009
[   37.623059] RIP: 0010:refcount_sub_and_test_checked+0x55/0x60
[   37.623062] Code: e0 41 5c c3 44 89 e0 41 5c c3 44 0f b6 25 95 c5 d2 00 45 84 e4 75 e4 48 c7 c7 58 bc db aa c6 05 82 c5 d2 00 01 e8 2a 3b cb ff <0f> 0b eb d0 0f 1f 80 00 00 00 00 48 89 fe bf 01 00 00 00 eb 96 66
[   37.623063] RSP: 0018:ffffb452815efce0 EFLAGS: 00010082
[   37.623065] RAX: 0000000000000000 RBX: ffffa065756c8000 RCX: 0000000000000006
[   37.623067] RDX: 0000000000000007 RSI: 0000000000000092 RDI: ffffa06577a97450
[   37.623069] RBP: ffffa06575127318 R08: 0000000000000323 R09: 0000000000000004
[   37.623070] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000000
[   37.623071] R13: 0000000000000000 R14: 0000000000000003 R15: ffffa0656d58e4c8
[   37.623074] FS:  00007f58657f1740(0000) GS:ffffa06577a80000(0000) knlGS:0000000000000000
[   37.623076] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   37.623078] CR2: 000055c2ba492bf0 CR3: 000000022dc50000 CR4: 00000000000006e0
[   37.623079] Call Trace:
[   37.623086]  snd_pcm_group_unref.isra.0.part.0+0x1b/0x70 [snd_pcm]
[   37.623092]  snd_pcm_action+0x46/0x70 [snd_pcm]
[   37.623099]  __snd_pcm_lib_xfer+0x68b/0x920 [snd_pcm]
[   37.623105]  ? snd_pcm_hw_rule_step+0xf0/0xf0 [snd_pcm]
[   37.623111]  ? default_read_copy+0x70/0x70 [snd_pcm]
[   37.623115]  ? mem_cgroup_commit_charge+0x80/0x550
[   37.623119]  ? mem_cgroup_try_charge+0xa9/0x200
[   37.623125]  snd_pcm_common_ioctl+0x4f2/0xb90 [snd_pcm]
[   37.623129]  ? __handle_mm_fault+0xb31/0x1600
[   37.623135]  snd_pcm_ioctl+0x23/0x30 [snd_pcm]
[   37.623139]  do_vfs_ioctl+0x40c/0x670
[   37.623144]  ksys_ioctl+0x5e/0x90
[   37.623148]  __x64_sys_ioctl+0x16/0x20
[   37.623151]  do_syscall_64+0x4e/0x110
[   37.623153]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   37.623155] RIP: 0033:0x7f5865b54d97
[   37.623158] Code: 00 00 90 48 8b 05 f9 70 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d c9 70 0c 00 f7 d8 64 89 01 48
[   37.623159] RSP: 002b:00007fff109a84f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[   37.623162] RAX: ffffffffffffffda RBX: 000055c2ba47a7d0 RCX: 00007f5865b54d97
[   37.623164] RDX: 00007fff109a8500 RSI: 0000000040184150 RDI: 0000000000000006
[   37.623165] RBP: 000055c2ba47a850 R08: 0000000000000000 R09: 00007fff109b80b0
[   37.623167] R10: 00007fff109b8080 R11: 0000000000000246 R12: 000055c2ba478dd0
[   37.623169] R13: 000055c2ba491d00 R14: 0000000000000076 R15: 0000000000002b11
[   37.623172] ---[ end trace 999976d6ea591bd0 ]---
[   37.627572] retire_capture_urb: 18 callbacks suppressed

OK, thanks, such a detailed information is much appreciated!

Can you try with strace and see the syscall patterns to trigger the bug?
My wild guess is that it's either some racy scenario the driver still overlooked, or a code path that forgot the refcount properly.  strace might show something.

Meanwhile I'm going to test sndio with a USB device in my side, too.

BTW, what are the command line parameters passed to sndiod in your case?

Created attachment 283817 [details]
sndiod syscall log

execve("/usr/bin/sndiod", ["sndiod", "-d", "-f", "rsnd/Headset", "-s", "default", "-f", "rsnd/Headset", "-s", "gaming", "-f", "rsnd/Speaker", "-d"], 0x7ffdc711e2a0 /* 2 vars */) = 0


so snd/0 is device 3,0 (Headset) and snd/1 is 2,0 (Speaker).

The attached strace log is from a fresh booted system, while it produced the trace.

I did test aucat -f rsnd/Speaker -i /usr/share/sounds/alsa/Noise.wav to see if I could get a smaller syscall trace, by using sndios alsa code but without the daemon in between, but I couldn't get it to produce the trace.

Thanks.  One more detail: are you using PulseAudio?  Or this "default" points to ALSA dmix/dsnoop?

I'm not using PulseAudio, only sndiod which opens the alsa "hwplug" devices directly, so no dmix or any other ioplug as far as I can tell.

My .asoundrc contains 'pcm.!default "hw:Headset"' so the test where I used mpv --ao=alsa was also without dmix. I do have a 'pcm.dmixer' in my users .asoundrc but this is just a leftover and is using a hw:MID as slave pcm.
The sndiod daemon runs as separate user without any asounrc, no alsa configurations in /etc, only the default/upstream configurations from alsa-lib in /usr.

I did have a apparmor profile in complain mode loaded for sndiod, but just to be sure I removed the rule completely and restarted again and it still produced the trace.

If there is any other way I can help like a more verbose kernel log would be possible.
I think I'm going to install PulseAudio later or tomorrow to see if I can reproduce it there.

Is this just a false alarm? The refcount is initialized with 0, my kernel is build with CONFIG_REFCOUNT_FULL=y which makes `refcount_inc` be `refcount_inc_checked` and it will not increase the refcount if its 0, resulting in the other trace when there is actually an underflow happening because it was never incremented.

This only happens to the the Headset PCM, because of the second subdevice in sndiod, in sndiod it creates snd/0(.default) and snd/0.gaming, sndiod then captures the "Headset" stream and links it to the playback stream.
The "Speaker" pcm never creates a capture stream and will not use pcm_link.

(In reply to Duncan Overbruck from comment #9)
> Is this just a false alarm? The refcount is initialized with 0, my kernel is
> build with CONFIG_REFCOUNT_FULL=y which makes `refcount_inc` be
> `refcount_inc_checked` and it will not increase the refcount if its 0,
> resulting in the other trace when there is actually an underflow happening
> because it was never incremented.

Yes, I came to the same conclusion: the whole problem is due to the design of refcount_t that surfaces only with CONFIG_REFCOUNT_FULL=y.  I completely overlooked that nature of the API :-<

The reason why the warning appears only once is just because it's WARN_ONCE().  Two different warnings, once for inc and once for dec.

Below is a quick fix patch.  This slightly modifies the way to handle refcount and termination condition so that it won't hit refcount_inc() on zero.

Created attachment 283819 [details]
Test fix patch

Great thanks. The patch seems to work as expected as far as I can see. The traces are gone and audio still works.
Is there any way I can help to verify if the groups are freed as expected?

Putting a printk at assigning and freeing would reveal it.  I already checked with sndio and it seems working, so I'm going to submit and merge this fix patch.

May I put you as reported-and-tested-by tag?

(In reply to Takashi Iwai from comment #14)
> Putting a printk at assigning and freeing would reveal it.  I already
> checked with sndio and it seems working, so I'm going to submit and merge
> this fix patch.

Nice, thank you very much for the fast response and patch.

> May I put you as reported-and-tested-by tag?

Yes sure.

Fix merged in upstream.