Re: [syzbot] INFO: rcu detected stall in tx

[guido@kiener-muenchen.de]

Zitat von Alan Stern <stern@rowland.harvard.edu>:

> On Thu, May 20, 2021 at 09:25:53PM +0000, Guido Kiener wrote:
>> I've tested to pull the cable and I can easy produce the -EPROTO  
>> (-71) error in the usbtmc.c driver.
>> The error also happens when I have no traffic and just switch off  
>> the USBTMC device (which I can do from home office).
>> When there is traffic, the IN/OUT pipe will also show some -EPROTO  
>> errors from the flying urbs.
>>
>> On my test PC the amount of error messages vary from 1 to ca. 10  
>> error message issued by the INT pipe (see below).
>> Nevertheless I do not see the endless loop, since the USB  
>> disconnect stops the loop.
>> (Tested with USB 2.0, older kernel 4.15, but latest modified  
>> usbtmc.c driver using ehci-pci)
>> So I can test fixes (of course with latest kernel) and also setup a  
>> machine with USB 3.0.
>>
>> 1. Example
>> [1616527.017863] usbtmc 1-1.4:1.0: usbtmc_write_bulk_cb - nonzero  
>> write bulk status received: -71
>> [1616527.032489] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1616527.053998] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1616527.076145] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1616527.098143] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1616527.120244] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1616527.142244] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1616527.164440] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1616527.186517] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1616527.208175] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1616527.230272] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1616527.241982] usb 1-1.4: USB disconnect, device number 3
>>
>> 2. Example
>> [1622454.299131] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1622454.305815] usbtmc 1-1.4:1.0: usbtmc_write_bulk_cb - nonzero  
>> write bulk status received: -71
>> [1622454.309921] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -71
>> [1622454.319121] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1622454.341199] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1622454.363336] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1622454.385466] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1622454.407576] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1622454.422870] usb 1-1.4: USB disconnect, device number 7
>>
>> 3. Example
>> [1623429.713784] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -71
>> [1623429.714037] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.714279] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.714528] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.714778] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.715029] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.715278] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.715528] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.715777] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.716028] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.716277] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.718916] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.719168] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.722404] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.725666] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.725918] usbtmc 1-1.4:1.0: usbtmc_read_bulk_cb - nonzero  
>> read bulk status received: -2
>> [1623429.727837] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1623429.749949] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1623429.772094] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1623429.794184] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1623429.816297] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1623429.838479] usbtmc 1-1.4:1.0: unknown status received: -71
>> [1623429.838795] usb 1-1.4: USB disconnect, device number 8
>
> Try running this test on a system with only one CPU (and no
> hyperthreading).  I think that's the environment syzbot emulates.
>

I looked at the original console output again:
https://syzkaller.appspot.com/x/log.txt?x=1065c5fcd00000
I'm not very familiar yet in reading rcu files, but I would say:
1. I assume there are 2 CPUs running (C0,C1).
2. There are 5 USBTMC devices running concurrenlty which seems to be  
disconnected together at once.
You will find all disconnect messages "usb x-1: USB disconnect, device  
number y" at the end within 5 seconds (418.4-423.7 sec).
3. Each USBTMC device issues every 20 msec the typical INT pipe  
message "X-1:0.0: unknown status received: -71" when the connection is  
disconnected.
All USBTMC device messages are alternating. Round robin works.

Does someone have an idea for the following questions:
1. Why does it take about 96 seconds from the beginning of the first  
INT pipe message (322.1) until the first disconnect message (418.4)?
2. What is blocking the "disconnect" event for such a long time?
3. Is it possible to provoke this behavior when I disconnect the cable  
in slow motion?
4. Is the self-detected stall just caused by another driver and the  
USBTMC driver is innocent, but only chatty?

Next Thursday I can check recommendations again.

-Guido