Strange qemu6 regression cauing disabled usb controller.

[Remy Noel]

Hello,

I'm encountering a nagging issue with usbredir and a windows guest, but 
although I did pinpoint the commit that caused the issue, I have a hard time 
understanding it.

The issue occurs when a two usbredir devices are added to a guest windows vm. 
When the second device is added, the UHCI usb controller is disabled by windows 
with an error code 43 (can be seen with in the usb adapters section of the 
device manager).

The commit causing the issue (everything works well when reverting it) is 
7bed89958bfbf40df9ca681cefbdca63abdde39d : device_core: use drain_call_rcu in 
in qmp_device_add.

I narrowed the problem to the unlock of the iothread: the minimum 
drain_call_rcu code that still reproduce the issue is:

void drain_call_rcu(void)
{
    bool locked = qemu_mutex_iothread_locked();
    if (locked) {
        qemu_mutex_unlock_iothread();
    }
    usleep(50000); // time spent draining the rcu on a few slow cases.

    if (locked) {
        qemu_mutex_lock_iothread();
    }
}

The issue can be reproduced from a basic windows home instalation and the 
following qemu command line:

qemu-system-x86_64 -M pc -cpu host,hv_time,hv_synic,hv_stimer,hv_vpindex -enable-kvm 
-m 4096 -device piix3-usb-uhci,id=uhci -qmp 
tcp:127.0.0.1:4444,server=on,wait=off,ipv4 -drive <disk-parameters> -snapshot

Note that the hv parameters are needed to trigger the issue I do not know why.

Two usbredir devices are then added to the vm (qmp client script added at the 
end of the mail) in order to trigger the issue.

The second device can be added right after or much later than the first and the 
bug still triggers.

I tried to find what was able to take avantage of the free iothread lock, but 
the only thing I got so far is that the iothread lock is not taken during the 
first drain (from the first device add), but is taken many times during the 
second drain by physmem's IOs (from kvm-accel, but at this point, I'm a bit 
lost).

I'm looking for pointers as to what could trigger the issue in order to narrow 
it down, as, so far, I do not understand exactly what causes the regression.
I am unsure of how this would even transcribe in a linux vm so i didn't try to 
reproduce the issue with one.

Below is the reproduction script (python):

import asyncio
import json
import socket
import sys
import time

char1 = {
    "execute": "chardev-add",
    "arguments": {
        "id": "r-usb0",
        "backend": {
            "type": "socket",
            "data": {
                "nodelay": True,
                "addr": {
                    "type": "inet",
                    "data": {
                        "host": "::",
                        "port": "10100"
                    }
                }
            }
        }
    }
}
dev1 = {
    "execute": "device_add",
    "arguments": {
        "driver": "usb-redir",
        "id": "r-usb0",
        "chardev": "r-usb0",
        "bus": "uhci.0"
    }
}
char2 = {
    "execute": "chardev-add",
    "arguments": {
        "id": "r-usb1",
        "backend": {
            "type": "socket",
            "data": {
                "nodelay": True,
                "addr": {
                    "type": "inet",
                    "data": {
                        "host": "::",
                        "port": "10101"
                    }
                }
            }
        }
    }
}
dev2 = {
    "execute": "device_add",
    "arguments": {
        "driver": "usb-redir",
        "id": "r-usb1",
        "chardev": "r-usb1",
        "bus": "uhci.0"
    }
}


cond = None
ids = {}

async def pull_answers(reader):
    while True:
        data = await reader.read(1024)
        if not data:
            sys.exit(0)
        data = data.decode('ascii')
        while data:
            try:
                msg, remain = json.JSONDecoder().raw_decode(data)
            except ValueError as vae:
                break
            if not msg:
                break
            msg_id = msg.get('id')
            if msg_id:
                async with cond:
                    ids[msg_id] = msg
                    cond.notify_all()
            else:
                print("QMP:", msg)
            data = data[remain:]


async def wait_answer(async_msg_id):
    async with cond:
        msg_id = await async_msg_id
        await cond.wait_for(lambda : msg_id in ids)
        return ids[msg_id]


ID = 0

async def send_message(writer, obj):
    global ID
    obj['id'] = ID
    ID += 1
    writer.write(json.dumps(obj).encode())
    await writer.drain()
    return obj['id']


async def main():
    global cond
    cond = asyncio.Condition()
    with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as sock:
        sock.connect(('127.0.0.1', 4444))
        reader, writer = await asyncio.open_connection(sock=sock)
        waiter = asyncio.create_task(pull_answers(reader))
        await send_message(writer, {'execute': 'qmp_capabilities'})
        sender = asyncio.create_task(send_message(writer, char1))
        resp = await wait_answer(sender)
        sender = asyncio.create_task(send_message(writer, dev1))
        resp = await wait_answer(sender)
        time.sleep(.01)
        sender = send_message(writer, char2)
        resp = await wait_answer(sender)
        sender = send_message(writer, dev2)
        resp = await wait_answer(sender)
        print("Added. Awaiting disconnect ...")
        await waiter
        return 0


asyncio.run(main())