sound: WARNING in snd_rawmidi_transmit_ack

[Dmitry Vyukov]

Hello,

The following program triggers WARNING in snd_rawmidi_transmit_ack:

------------[ cut here ]------------
WARNING: CPU: 1 PID: 20739 at sound/core/rawmidi.c:1136
snd_rawmidi_transmit_ack+0x275/0x400()
Modules linked in:
CPU: 1 PID: 20739 Comm: syz-executor Tainted: G W 4.4.0+ #276
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
00000000ffffffff ffff8800346af8d8 ffffffff82999e2d 0000000000000000
ffff88002fea97c0 ffffffff86d3f920 ffff8800346af918 ffffffff81352089
ffffffff84f80bd5 ffffffff86d3f920 0000000000000470 ffff8800600b9b68
Call Trace:
[< inline >] __dump_stack lib/dump_stack.c:15
[<ffffffff82999e2d>] dump_stack+0x6f/0xa2 lib/dump_stack.c:50
[<ffffffff81352089>] warn_slowpath_common+0xd9/0x140 kernel/panic.c:482
[<ffffffff813522b9>] warn_slowpath_null+0x29/0x30 kernel/panic.c:515
[<ffffffff84f80bd5>] snd_rawmidi_transmit_ack+0x275/0x400
sound/core/rawmidi.c:1136
[<ffffffff84fdb3c1>] snd_virmidi_output_trigger+0x4b1/0x5a0
sound/core/seq/seq_virmidi.c:163
[< inline >] snd_rawmidi_output_trigger sound/core/rawmidi.c:150
[<ffffffff84f87ed9>] snd_rawmidi_kernel_write1+0x549/0x780
sound/core/rawmidi.c:1223
[<ffffffff84f89fd3>] snd_rawmidi_write+0x543/0xb30 sound/core/rawmidi.c:1273
[<ffffffff817b0323>] __vfs_write+0x113/0x480 fs/read_write.c:528
[<ffffffff817b1db7>] vfs_write+0x167/0x4a0 fs/read_write.c:577
[< inline >] SYSC_write fs/read_write.c:624
[<ffffffff817b50a1>] SyS_write+0x111/0x220 fs/read_write.c:616
[<ffffffff86336c36>] entry_SYSCALL_64_fastpath+0x16/0x7a
arch/x86/entry/entry_64.S:185
---[ end trace 93509ba74cc3e259 ]---


// autogenerated by syzkaller (http://github.com/google/syzkaller)
#include <pthread.h>
#include <stdint.h>
#include <string.h>
#include <sys/syscall.h>
#include <unistd.h>
#include <fcntl.h>

long r[11];

void* thr(void* arg)
{
switch ((long)arg) {
case 0:
r[0] = syscall(SYS_mmap, 0x20000000ul, 0x10000ul, 0x3ul, 0x32ul,
0xfffffffffffffffful, 0x0ul);
break;
case 1:
r[1] = syscall(SYS_open, "/dev/dmmidi2", O_RDWR, 0);
break;
case 2:
*(uint32_t*)0x20006fda = (uint32_t)0x28;
*(uint32_t*)0x20006fde = (uint32_t)0x7;
*(uint64_t*)0x20006fe2 = (uint64_t)0x0;
*(uint64_t*)0x20006fea = (uint64_t)0x7;
*(uint64_t*)0x20006ff2 = (uint64_t)0x8;
*(uint16_t*)0x20006ffa = (uint16_t)0xfffffffffffffff8;
r[8] = syscall(SYS_write, r[1], 0x20006fdaul, 0x28ul, 0, 0, 0);
break;
case 3:
memcpy((void*)0x20007000,
"\x3c\x3f\xbc\xd7\x07\xee\x01\x21\x84\x26\x11\x6d\xc6\xc3"
"\xac\x7f\x14\xa3\x15\xda\xa1\x34\x67\xe9\xb6\xf8\xa8\xdd"
"\xb5\xe0\x2a\x64\x6e\x04\x7c\x40\xdb\x64\x4f\x53\x41\x90"
"\x02\x3b\x48\xba\xf6\xd7\x32\xe5\x11\x3f\xe5\xc5\xf2\x5f"
"\x4e\x6f\x5b\xe9\x0e\x76\x1a\x72\x77\x68\xad\xd3\x1b\x8d"
"\x8f\x71\x2f\x40\xde\xf4\xbf\x78\x48\xc2\xc3\xe5\xe9\x11"
"\x11\xd2\x9a\x91\x94\x81\x57\x22\xef\x2a\x5b\xe2\x9e\xce"
"\x3f\xa6\x07\x54\xd4\xb6\x1f\x30\xfd\x09\x35\x54\xcc\x78"
"\x12\x37\x59\xf7\x5c\x51\xd2\x47\xb8\x40\x98\x2b\xb4\x8d"
"\xbf\xd5\x34\x26\xcd\xb5\xe4\x98\x2d\x0e\xb1\x71\x0f\x12"
"\x06\xb0\x2c\x78\x74\xba\x3d\x32\x9c\x72\x96\x0d\x91\x50"
"\x9a\xe3\xbc\x4f\x1e\x26\xb2\xe3\xb2\xa2\x68\x6f\x10\xb5"
"\xc1\x7f\xfc\xfd\xf0\xe6\xd9\x0c\xa0\xa7\x54\x2c\x62\x0d"
"\xee\x04\x5b\x9d\x73\xf4\xcc\x29\x37\x01\xc2\x35\x8d\x3c"
"\x8a\x2f\xe3\xf5\x55\x42\x77\x55\x2d\x49\x6f\x46\xf7\x34"
"\xb1\x5f\xe7\x98\x55\xb5\x7c\x4e\xd7\x47\x18\xd1\xf9\xf2"
"\xd2\xfe\x47\xff\x22\x04\xa9\x32\xe9\xd6\x28\xda\xe1\x85"
"\xcb\xc5\xe6\xc1\xca\x9e\x3f\x1f\x80\xe6",
248);
r[10] = syscall(SYS_write, r[1], 0x20007000ul, 0xf8ul, 0, 0, 0);
break;
}
return 0;
}

int main()
{
long i;
pthread_t th[4];

memset(r, -1, sizeof(r));
for (i = 0; i < 4; i++) {
pthread_create(&th[i], 0, thr, (void*)i);
usleep(10000);
}
for (i = 0; i < 4; i++) {
pthread_create(&th[i], 0, thr, (void*)i);
if (i % 2 == 0)
usleep(10000);
}
usleep(100000);
return 0;
}

On commit 30f05309bde49295e02e45c7e615f73aa4e0ccc2.

[Takashi Iwai]

Could you check the patch below? It's untested yet in my side due to
other bugs...


thanks,

Takashi

---
diff --git a/sound/core/seq/seq_virmidi.c b/sound/core/seq/seq_virmidi.c
index 3da2d48610b3..1d13057c84cf 100644
--- a/sound/core/seq/seq_virmidi.c
+++ b/sound/core/seq/seq_virmidi.c
@@ -160,8 +160,11 @@ static void snd_virmidi_output_trigger(struct snd_rawmidi_substream *substream,
vmidi->trigger = 1;
if (vmidi->seq_mode == SNDRV_VIRMIDI_SEQ_DISPATCH &&
!(vmidi->rdev->flags & SNDRV_VIRMIDI_SUBSCRIBE)) {
- snd_rawmidi_transmit_ack(substream, substream->runtime->buffer_size - substream->runtime->avail);
- return; /* ignored */
+ while (snd_rawmidi_transmit(substream, buf,
+ sizeof(buf)) > 0) {
+ /* ignored */
+ }
+ return;
}
if (vmidi->event.type != SNDRV_SEQ_EVENT_NONE) {
if (snd_seq_kernel_client_dispatch(vmidi->client, &vmidi->event, in_atomic(), 0) < 0)

[Dmitry Vyukov]

No, I still see the same warning.
Please try to reproduce it locally and test. I've attached my config.


[ 163.406601] ------------[ cut here ]------------
[ 163.407223] WARNING: CPU: 0 PID: 7812 at sound/core/rawmidi.c:1136
snd_rawmidi_transmit_ack+0x275/0x400()
[ 163.407552] Modules linked in:
[ 163.407552] CPU: 0 PID: 7812 Comm: a.out Not tainted 4.5.0-rc1+ #294
[ 163.407552] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS Bochs 01/01/2011
[ 163.407552] 00000000ffffffff ffff88005de5f8a8 ffffffff829e79ad
0000000000000000
[ 163.407552] ffff88005f848000 ffffffff86ef3060 ffff88005de5f8e8
ffffffff813536d9
[ 163.407552] ffffffff8507a085 ffffffff86ef3060 0000000000000470
ffff88005e9e8fa8
[ 163.407552] Call Trace:
[ 163.407552] [<ffffffff829e79ad>] dump_stack+0x6f/0xa2
[ 163.432954] [<ffffffff813536d9>] warn_slowpath_common+0xd9/0x140
[ 163.432954] [<ffffffff8507a085>] ? snd_rawmidi_transmit_ack+0x275/0x400
[ 163.432954] [<ffffffff81353909>] warn_slowpath_null+0x29/0x30
[ 163.432954] [<ffffffff8507a085>] snd_rawmidi_transmit_ack+0x275/0x400
[ 163.432954] [<ffffffff8507a5d0>] snd_rawmidi_transmit+0x70/0x90
[ 163.432954] [<ffffffff850d48a0>] snd_virmidi_output_trigger+0x480/0x570
[ 163.432954] [<ffffffff850d4420>] ? snd_virmidi_input_trigger+0x100/0x100
[ 163.432954] [<ffffffff85081389>] snd_rawmidi_kernel_write1+0x549/0x780
[ 163.432954] [<ffffffff85083483>] snd_rawmidi_write+0x543/0xb30
[ 163.432954] [<ffffffff85082f40>] ? snd_rawmidi_release+0xf0/0xf0
[ 163.432954] [<ffffffff81455c49>] ? __lock_acquire+0xea9/0x4700
[ 163.432954] [<ffffffff81453e78>] ? mark_held_locks+0xc8/0x120
[ 163.432954] [<ffffffff817a5e67>] ? mem_cgroup_commit_charge+0x187/0x2e0
[ 163.432954] [<ffffffff81454da0>] ? debug_check_no_locks_freed+0x3c0/0x3c0
[ 163.432954] [<ffffffff817b9013>] __vfs_write+0x113/0x480
[ 163.432954] [<ffffffff85082f40>] ? snd_rawmidi_release+0xf0/0xf0
[ 163.432954] [<ffffffff817b8f00>] ? vfs_iter_write+0x320/0x320
[ 163.432954] [<ffffffff814926e7>] ? debug_lockdep_rcu_enabled+0x77/0x90
[ 163.432954] [<ffffffff827eade5>] ? common_file_perm+0x155/0x3a0
[ 163.432954] [<ffffffff827eb242>] ? apparmor_file_permission+0x22/0x30
[ 163.432954] [<ffffffff82721a9c>] ? security_file_permission+0x8c/0x1f0
[ 163.432954] [<ffffffff817ba472>] ? rw_verify_area+0x102/0x2c0
[ 163.432954] [<ffffffff817baaa7>] vfs_write+0x167/0x4a0
[ 163.432954] [<ffffffff817bdd91>] SyS_write+0x111/0x220
[ 163.432954] [<ffffffff817bdc80>] ? SyS_read+0x220/0x220
[ 163.432954] [<ffffffff81005017>] ? trace_hardirqs_on_thunk+0x17/0x19
[ 163.432954] [<ffffffff864599b6>] entry_SYSCALL_64_fastpath+0x16/0x7a
[ 163.432954] ---[ end trace d6645f646c593dae ]---

[Takashi Iwai]

This wasn't triggered on my machine. How did you start the test
program?

Meanwhile below is another patch to be applied in addition to the
previous fix. There is a possible race in calling
snd_rawmidi_transmit(), and this may result in such a warning.


Takashi

---
From: Takashi Iwai <ti...@suse.de>
Subject: [PATCH] ALSA: rawmidi: Make snd_rawmidi_transmit() race-free

Signed-off-by: Takashi Iwai <ti...@suse.de>
---
sound/core/rawmidi.c | 95 ++++++++++++++++++++++++++++++++++------------------
1 file changed, 62 insertions(+), 33 deletions(-)

diff --git a/sound/core/rawmidi.c b/sound/core/rawmidi.c
index a7759846fbaa..3a27944c821c 100644
--- a/sound/core/rawmidi.c
+++ b/sound/core/rawmidi.c
@@ -1054,24 +1054,9 @@ int snd_rawmidi_transmit_empty(struct snd_rawmidi_substream *substream)
}
EXPORT_SYMBOL(snd_rawmidi_transmit_empty);

-/**
- * snd_rawmidi_transmit_peek - copy data from the internal buffer
- * @substream: the rawmidi substream
- * @buffer: the buffer pointer
- * @count: data size to transfer
- *
- * Copies data from the internal output buffer to the given buffer.
- *
- * Call this in the interrupt handler when the midi output is ready,
- * and call snd_rawmidi_transmit_ack() after the transmission is
- * finished.
- *
- * Return: The size of copied data, or a negative error code on failure.
- */
-int snd_rawmidi_transmit_peek(struct snd_rawmidi_substream *substream,
+static int rawmidi_transmit_peek(struct snd_rawmidi_substream *substream,
unsigned char *buffer, int count)
{
- unsigned long flags;
int result, count1;
struct snd_rawmidi_runtime *runtime = substream->runtime;

@@ -1081,7 +1066,6 @@ int snd_rawmidi_transmit_peek(struct snd_rawmidi_substream *substream,
return -EINVAL;
}
result = 0;
- spin_lock_irqsave(&runtime->lock, flags);
if (runtime->avail >= runtime->buffer_size) {
/* warning: lowlevel layer MUST trigger down the hardware */
goto __skip;
@@ -1106,25 +1090,39 @@ int snd_rawmidi_transmit_peek(struct snd_rawmidi_substream *substream,
}
}
__skip:
- spin_unlock_irqrestore(&runtime->lock, flags);
return result;
}
-EXPORT_SYMBOL(snd_rawmidi_transmit_peek);

/**
- * snd_rawmidi_transmit_ack - acknowledge the transmission
+ * snd_rawmidi_transmit_peek - copy data from the internal buffer
* @substream: the rawmidi substream
- * @count: the transferred count
+ * @buffer: the buffer pointer
+ * @count: data size to transfer
*
- * Advances the hardware pointer for the internal output buffer with
- * the given size and updates the condition.
- * Call after the transmission is finished.
+ * Copies data from the internal output buffer to the given buffer.
*
- * Return: The advanced size if successful, or a negative error code on failure.
+ * Call this in the interrupt handler when the midi output is ready,
+ * and call snd_rawmidi_transmit_ack() after the transmission is
+ * finished.
+ *
+ * Return: The size of copied data, or a negative error code on failure.
*/
-int snd_rawmidi_transmit_ack(struct snd_rawmidi_substream *substream, int count)
+int snd_rawmidi_transmit_peek(struct snd_rawmidi_substream *substream,
+ unsigned char *buffer, int count)
{
+ struct snd_rawmidi_runtime *runtime = substream->runtime;
+ int result;
unsigned long flags;
+
+ spin_lock_irqsave(&runtime->lock, flags);
+ result = rawmidi_transmit_peek(substream, buffer, count);
+ spin_unlock_irqrestore(&runtime->lock, flags);
+ return result;
+}
+EXPORT_SYMBOL(snd_rawmidi_transmit_peek);
+
+static int rawmidi_transmit_ack(struct snd_rawmidi_substream *substream, int count)
+{
struct snd_rawmidi_runtime *runtime = substream->runtime;

if (runtime->buffer == NULL) {
@@ -1132,7 +1130,6 @@ int snd_rawmidi_transmit_ack(struct snd_rawmidi_substream *substream, int count)
"snd_rawmidi_transmit_ack: output is not active!!!\n");
return -EINVAL;
}
- spin_lock_irqsave(&runtime->lock, flags);
snd_BUG_ON(runtime->avail + count > runtime->buffer_size);
runtime->hw_ptr += count;
runtime->hw_ptr %= runtime->buffer_size;
@@ -1142,9 +1139,31 @@ int snd_rawmidi_transmit_ack(struct snd_rawmidi_substream *substream, int count)
if (runtime->drain || snd_rawmidi_ready(substream))
wake_up(&runtime->sleep);
}
- spin_unlock_irqrestore(&runtime->lock, flags);
return count;
}
+
+/**
+ * snd_rawmidi_transmit_ack - acknowledge the transmission
+ * @substream: the rawmidi substream
+ * @count: the transferred count
+ *
+ * Advances the hardware pointer for the internal output buffer with
+ * the given size and updates the condition.
+ * Call after the transmission is finished.
+ *
+ * Return: The advanced size if successful, or a negative error code on failure.
+ */
+int snd_rawmidi_transmit_ack(struct snd_rawmidi_substream *substream, int count)
+{
+ struct snd_rawmidi_runtime *runtime = substream->runtime;
+ int result;
+ unsigned long flags;
+
+ spin_lock_irqsave(&runtime->lock, flags);
+ result = rawmidi_transmit_ack(substream, count);
+ spin_unlock_irqrestore(&runtime->lock, flags);
+ return result;
+}
EXPORT_SYMBOL(snd_rawmidi_transmit_ack);

/**
@@ -1160,12 +1179,22 @@ EXPORT_SYMBOL(snd_rawmidi_transmit_ack);
int snd_rawmidi_transmit(struct snd_rawmidi_substream *substream,
unsigned char *buffer, int count)
{
+ struct snd_rawmidi_runtime *runtime = substream->runtime;
+ int result;
+ unsigned long flags;
+
+ spin_lock_irqsave(&runtime->lock, flags);
if (!substream->opened)
- return -EBADFD;
- count = snd_rawmidi_transmit_peek(substream, buffer, count);
- if (count < 0)
- return count;
- return snd_rawmidi_transmit_ack(substream, count);
+ result = -EBADFD;
+ else {
+ count = rawmidi_transmit_peek(substream, buffer, count);
+ if (count <= 0)
+ result = count;
+ else
+ result = rawmidi_transmit_ack(substream, count);
+ }
+ spin_unlock_irqrestore(&runtime->lock, flags);
+ return result;
}
EXPORT_SYMBOL(snd_rawmidi_transmit);

--
2.7.0

[Dmitry Vyukov]

I've attached my config.

Then I start qemu as:

$ qemu-system-x86_64 -hda
/usr/local/google/home/dvyukov/bin/wheezy.img -net
user,host=10.0.2.10,hostfwd=tcp::10022-:22 -net nic -nographic -kernel
arch/x86/boot/bzImage -append "console=ttyS0 root=/dev/sda debug
earlyprintk=serial slub_debug=UZ" -enable-kvm -pidfile vm_pid -m 2G
-numa node,nodeid=0,cpus=0-1 -numa node,nodeid=1,cpus=2-3 -smp
sockets=2,cores=2,threads=1 -usb -usbdevice mouse -usbdevice tablet
-soundhw all

Then I start programs using stress utility, if you have Go toolchain
installed you can get it with:
$ go get golang.org/x/tools/cmd/stress
$ ./stress -p 32 -failure=foobar ./a.out
This will run a.out constantly keeping 32 parallel processes and
ignoring any failures a.out itself.