Cc: Thierry, Alan, Andrey,
The issue is reproducible immediately on QEMU instance with
USB_DUMMY_HCD and USB_RAW_GADGET. I don't know about real port100 NFC
device.
I spent some time looking into this and have no clue, except that it
looks like an effect of a race condition.
1. When using syskaller reproducer against one USB device (In the C
reproducer change the loop in main() to use procid=0) - issue does not
happen.
2. With two threads or more talking to separate Dummy USB devices, the
issue appears. The more of them, the better...
3. The reported problem is in missing complete. The correct flow is like:
port100_probe()
port100_get_command_type_mask()
port100_send_cmd_sync()
port100_send_cmd_async()
port100_submit_urb_for_ack()
port100_send_complete()
[ 63.363863] port100 2-1:0.0: NFC: Urb failure (status -71)
port100_recv_ack()
[ 63.369942] port100 2-1:0.0: NFC: Urb failure (status -71)
and schedule_work() which completes and unblocks port100_send_cmd_sync
However in the failing case (hung task) the port100_recv_ack() is never
called. It looks like USB core / HCD / gadget does not send the Ack/URB
complete.
I don't know why. The port100 NFC driver code looks OK, except it is not
prepared for missing ack/urb so it waits indefinitely. I could try to
convert it to wait_for_completion_timeout() but it won't be trivial and
more important - I am not sure if this is the problem. Somehow the ACK
with Urb failure is not sent back to the port100 device. Therefore I am
guessing that the race condition is somwhere in USB stack, not in
port100 driver.
The lockdep and other testing tools did not find anything here.
Anyone hints where the issue could be?
Best regards,
Krzysztof
Cc: Thierry, Alan, Andrey,
The issue is reproducible immediately on QEMU instance with
USB_DUMMY_HCD and USB_RAW_GADGET. I don't know about real port100 NFC
device.
I spent some time looking into this and have no clue, except that it
looks like an effect of a race condition.
1. When using syskaller reproducer against one USB device (In the C
reproducer change the loop in main() to use procid=0) - issue does not
happen.
2. With two threads or more talking to separate Dummy USB devices, the
issue appears. The more of them, the better...
3. The reported problem is in missing complete. The correct flow is like:
port100_probe()
port100_get_command_type_mask()
port100_send_cmd_sync()
port100_send_cmd_async()
port100_submit_urb_for_ack()
port100_send_complete()
[ 63.363863] port100 2-1:0.0: NFC: Urb failure (status -71)
port100_recv_ack()
[ 63.369942] port100 2-1:0.0: NFC: Urb failure (status -71)
and schedule_work() which completes and unblocks port100_send_cmd_sync
However in the failing case (hung task) the port100_recv_ack() is never
called. It looks like USB core / HCD / gadget does not send the Ack/URB
complete.
I don't know why. The port100 NFC driver code looks OK, except it is not
prepared for missing ack/urb so it waits indefinitely. I could try to
convert it to wait_for_completion_timeout() but it won't be trivial and
more important - I am not sure if this is the problem. Somehow the ACK
with Urb failure is not sent back to the port100 device. Therefore I am
guessing that the race condition is somwhere in USB stack, not in
port100 driver.
The lockdep and other testing tools did not find anything here.
Anyone hints where the issue could be?
From: Alan Stern <stern@rowland.harvard.edu> Date: 2021-07-22 14:47:26
On Thu, Jul 22, 2021 at 04:20:10PM +0200, Krzysztof Kozlowski wrote:
On 22/06/2021 17:43, syzbot wrote:
quoted
Hello,
syzbot found the following issue on:
HEAD commit: fd0aa1a4 Merge tag 'for-linus' of git://git.kernel.org/pub..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=13e1500c300000
kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
dashboard link: https://syzkaller.appspot.com/bug?extid=abd2e0dafb481b621869
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=1792e284300000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=13ad9d48300000
IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+abd2e0dafb481b621869@syzkaller.appspotmail.com
INFO: task kworker/0:1:7 blocked for more than 143 seconds.
Not tainted 5.13.0-rc6-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/0:1 state:D stack:25584 pid: 7 ppid: 2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
context_switch kernel/sched/core.c:4339 [inline]
__schedule+0x916/0x23e0 kernel/sched/core.c:5147
schedule+0xcf/0x270 kernel/sched/core.c:5226
schedule_timeout+0x1db/0x250 kernel/time/timer.c:1868
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common kernel/sched/completion.c:106 [inline]
wait_for_common kernel/sched/completion.c:117 [inline]
wait_for_completion+0x168/0x270 kernel/sched/completion.c:138
port100_send_cmd_sync drivers/nfc/port100.c:923 [inline]
port100_get_command_type_mask drivers/nfc/port100.c:1008 [inline]
port100_probe+0x9e4/0x1340 drivers/nfc/port100.c:1554
usb_probe_interface+0x315/0x7f0 drivers/usb/core/driver.c:396
...
Cc: Thierry, Alan, Andrey,
The issue is reproducible immediately on QEMU instance with
USB_DUMMY_HCD and USB_RAW_GADGET. I don't know about real port100 NFC
device.
I spent some time looking into this and have no clue, except that it
looks like an effect of a race condition.
1. When using syskaller reproducer against one USB device (In the C
reproducer change the loop in main() to use procid=0) - issue does not
happen.
2. With two threads or more talking to separate Dummy USB devices, the
issue appears. The more of them, the better...
3. The reported problem is in missing complete. The correct flow is like:
port100_probe()
port100_get_command_type_mask()
port100_send_cmd_sync()
port100_send_cmd_async()
port100_submit_urb_for_ack()
port100_send_complete()
[ 63.363863] port100 2-1:0.0: NFC: Urb failure (status -71)
port100_recv_ack()
[ 63.369942] port100 2-1:0.0: NFC: Urb failure (status -71)
and schedule_work() which completes and unblocks port100_send_cmd_sync
However in the failing case (hung task) the port100_recv_ack() is never
called. It looks like USB core / HCD / gadget does not send the Ack/URB
complete.
I don't know why. The port100 NFC driver code looks OK, except it is not
prepared for missing ack/urb so it waits indefinitely. I could try to
convert it to wait_for_completion_timeout() but it won't be trivial and
more important - I am not sure if this is the problem. Somehow the ACK
with Urb failure is not sent back to the port100 device. Therefore I am
guessing that the race condition is somwhere in USB stack, not in
port100 driver.
The lockdep and other testing tools did not find anything here.
Anyone hints where the issue could be?
Here's what I wrote earlier: "It looks like the problem stems from the fact
that port100_send_frame_async() submits two URBs, but
port100_send_cmd_sync() only waits for one of them to complete. The other
URB may then still be active when the driver tries to reuse it."
Of course, there may be more than one problem, so we may not be talking
about the same thing.
Does that help at all?
Alan Stern
From: Krzysztof Kozlowski <hidden> Date: 2021-07-23 09:05:21
On 22/07/2021 16:47, Alan Stern wrote:
On Thu, Jul 22, 2021 at 04:20:10PM +0200, Krzysztof Kozlowski wrote:
quoted
On 22/06/2021 17:43, syzbot wrote:
quoted
Hello,
syzbot found the following issue on:
HEAD commit: fd0aa1a4 Merge tag 'for-linus' of git://git.kernel.org/pub..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=13e1500c300000
kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
dashboard link: https://syzkaller.appspot.com/bug?extid=abd2e0dafb481b621869
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=1792e284300000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=13ad9d48300000
IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+abd2e0dafb481b621869@syzkaller.appspotmail.com
INFO: task kworker/0:1:7 blocked for more than 143 seconds.
Not tainted 5.13.0-rc6-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/0:1 state:D stack:25584 pid: 7 ppid: 2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
context_switch kernel/sched/core.c:4339 [inline]
__schedule+0x916/0x23e0 kernel/sched/core.c:5147
schedule+0xcf/0x270 kernel/sched/core.c:5226
schedule_timeout+0x1db/0x250 kernel/time/timer.c:1868
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common kernel/sched/completion.c:106 [inline]
wait_for_common kernel/sched/completion.c:117 [inline]
wait_for_completion+0x168/0x270 kernel/sched/completion.c:138
port100_send_cmd_sync drivers/nfc/port100.c:923 [inline]
port100_get_command_type_mask drivers/nfc/port100.c:1008 [inline]
port100_probe+0x9e4/0x1340 drivers/nfc/port100.c:1554
usb_probe_interface+0x315/0x7f0 drivers/usb/core/driver.c:396
...
quoted
Cc: Thierry, Alan, Andrey,
The issue is reproducible immediately on QEMU instance with
USB_DUMMY_HCD and USB_RAW_GADGET. I don't know about real port100 NFC
device.
I spent some time looking into this and have no clue, except that it
looks like an effect of a race condition.
1. When using syskaller reproducer against one USB device (In the C
reproducer change the loop in main() to use procid=0) - issue does not
happen.
2. With two threads or more talking to separate Dummy USB devices, the
issue appears. The more of them, the better...
3. The reported problem is in missing complete. The correct flow is like:
port100_probe()
port100_get_command_type_mask()
port100_send_cmd_sync()
port100_send_cmd_async()
port100_submit_urb_for_ack()
port100_send_complete()
[ 63.363863] port100 2-1:0.0: NFC: Urb failure (status -71)
port100_recv_ack()
[ 63.369942] port100 2-1:0.0: NFC: Urb failure (status -71)
and schedule_work() which completes and unblocks port100_send_cmd_sync
However in the failing case (hung task) the port100_recv_ack() is never
called. It looks like USB core / HCD / gadget does not send the Ack/URB
complete.
I don't know why. The port100 NFC driver code looks OK, except it is not
prepared for missing ack/urb so it waits indefinitely. I could try to
convert it to wait_for_completion_timeout() but it won't be trivial and
more important - I am not sure if this is the problem. Somehow the ACK
with Urb failure is not sent back to the port100 device. Therefore I am
guessing that the race condition is somwhere in USB stack, not in
port100 driver.
The lockdep and other testing tools did not find anything here.
Anyone hints where the issue could be?
Here's what I wrote earlier: "It looks like the problem stems from the fact
that port100_send_frame_async() submits two URBs, but
port100_send_cmd_sync() only waits for one of them to complete. The other
URB may then still be active when the driver tries to reuse it."
I see now you replied this to earlier syzbot report about "URB submitted
while active". Here is a slightly different issue - hung task on waiting
for completion coming from device ack.
However maybe these are both similar or at least come from similar root
cause in the driver.
Of course, there may be more than one problem, so we may not be talking
about the same thing.
Does that help at all?
Thanks, it gives me some ideas to look into although I spent already too
much time on this old driver. I doubt it has any users so maybe better
to mark it as BROKEN...
Best regards,
Krzysztof
From: Alan Stern <stern@rowland.harvard.edu> Date: 2021-07-23 13:07:50
On Fri, Jul 23, 2021 at 11:05:09AM +0200, Krzysztof Kozlowski wrote:
On 22/07/2021 16:47, Alan Stern wrote:
quoted
On Thu, Jul 22, 2021 at 04:20:10PM +0200, Krzysztof Kozlowski wrote:
quoted
Anyone hints where the issue could be?
Here's what I wrote earlier: "It looks like the problem stems from the fact
that port100_send_frame_async() submits two URBs, but
port100_send_cmd_sync() only waits for one of them to complete. The other
URB may then still be active when the driver tries to reuse it."
I see now you replied this to earlier syzbot report about "URB submitted
while active". Here is a slightly different issue - hung task on waiting
for completion coming from device ack.
However maybe these are both similar or at least come from similar root
cause in the driver.
Exactly what I was thinking. :-)
quoted
Of course, there may be more than one problem, so we may not be talking
about the same thing.
Does that help at all?
Thanks, it gives me some ideas to look into although I spent already too
much time on this old driver. I doubt it has any users so maybe better
to mark it as BROKEN...
Whatever you think is best. I know nothing about port100.
Alan Stern
From: Krzysztof Kozlowski <hidden> Date: 2021-10-20 20:56:49
On 22/07/2021 16:47, Alan Stern wrote:
On Thu, Jul 22, 2021 at 04:20:10PM +0200, Krzysztof Kozlowski wrote:
quoted
On 22/06/2021 17:43, syzbot wrote:
quoted
Hello,
syzbot found the following issue on:
HEAD commit: fd0aa1a4 Merge tag 'for-linus' of git://git.kernel.org/pub..
git tree: upstream
console output: https://syzkaller.appspot.com/x/log.txt?x=13e1500c300000
kernel config: https://syzkaller.appspot.com/x/.config?x=7ca96a2d153c74b0
dashboard link: https://syzkaller.appspot.com/bug?extid=abd2e0dafb481b621869
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=1792e284300000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=13ad9d48300000
IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+abd2e0dafb481b621869@syzkaller.appspotmail.com
INFO: task kworker/0:1:7 blocked for more than 143 seconds.
Not tainted 5.13.0-rc6-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:kworker/0:1 state:D stack:25584 pid: 7 ppid: 2 flags:0x00004000
Workqueue: usb_hub_wq hub_event
Call Trace:
context_switch kernel/sched/core.c:4339 [inline]
__schedule+0x916/0x23e0 kernel/sched/core.c:5147
schedule+0xcf/0x270 kernel/sched/core.c:5226
schedule_timeout+0x1db/0x250 kernel/time/timer.c:1868
do_wait_for_common kernel/sched/completion.c:85 [inline]
__wait_for_common kernel/sched/completion.c:106 [inline]
wait_for_common kernel/sched/completion.c:117 [inline]
wait_for_completion+0x168/0x270 kernel/sched/completion.c:138
port100_send_cmd_sync drivers/nfc/port100.c:923 [inline]
port100_get_command_type_mask drivers/nfc/port100.c:1008 [inline]
port100_probe+0x9e4/0x1340 drivers/nfc/port100.c:1554
usb_probe_interface+0x315/0x7f0 drivers/usb/core/driver.c:396
...
quoted
Cc: Thierry, Alan, Andrey,
The issue is reproducible immediately on QEMU instance with
USB_DUMMY_HCD and USB_RAW_GADGET. I don't know about real port100 NFC
device.
I spent some time looking into this and have no clue, except that it
looks like an effect of a race condition.
1. When using syskaller reproducer against one USB device (In the C
reproducer change the loop in main() to use procid=0) - issue does not
happen.
2. With two threads or more talking to separate Dummy USB devices, the
issue appears. The more of them, the better...
3. The reported problem is in missing complete. The correct flow is like:
port100_probe()
port100_get_command_type_mask()
port100_send_cmd_sync()
port100_send_cmd_async()
port100_submit_urb_for_ack()
port100_send_complete()
[ 63.363863] port100 2-1:0.0: NFC: Urb failure (status -71)
port100_recv_ack()
[ 63.369942] port100 2-1:0.0: NFC: Urb failure (status -71)
and schedule_work() which completes and unblocks port100_send_cmd_sync
However in the failing case (hung task) the port100_recv_ack() is never
called. It looks like USB core / HCD / gadget does not send the Ack/URB
complete.
I don't know why. The port100 NFC driver code looks OK, except it is not
prepared for missing ack/urb so it waits indefinitely. I could try to
convert it to wait_for_completion_timeout() but it won't be trivial and
more important - I am not sure if this is the problem. Somehow the ACK
with Urb failure is not sent back to the port100 device. Therefore I am
guessing that the race condition is somwhere in USB stack, not in
port100 driver.
The lockdep and other testing tools did not find anything here.
Anyone hints where the issue could be?
Here's what I wrote earlier: "It looks like the problem stems from the fact
that port100_send_frame_async() submits two URBs, but
port100_send_cmd_sync() only waits for one of them to complete. The other
URB may then still be active when the driver tries to reuse it."
Of course, there may be more than one problem, so we may not be talking
about the same thing.
Hi Alan, Felipe, Greg and others,
This is an old issue reported by syzkaller for NFC port100 driver [1].
There is something similar for pn533 [2].
I was looking at it some time ago, took a break and now I am trying to
fix it again. Without success.
The issue is reproducible via USB gadget on QEMU, not on real HW. I
looked and debugged the code and I think previously mentioned
double-URB-submit is not the reason here. Or I miss how the USB works
(which is quite probable...).
1. The port100 driver calls port100_send_cmd_sync() which eventually
goes to port100_send_frame_async(). After it, it waits for "sync"
completion.
2. In port100_send_frame_async(), driver indeed first submits "out_urb"
which quite fast is being processed by dummy_hcd with "no ep configured"
and -EPROTO.
3. Then (or sometimes before -EPROTO response from (2) above) the
port100_send_frame_async() submits "in_urb" via
port100_submit_urb_for_ack() and waits for its completion. Completion of
"in_urb" (or the "ack") in port100_recv_ack() would schedule work to
complete the (1) above - the sync completion.
4. Usually, when reproducer works fine (does not trigger issue), the
dummy_timer() from gadget responds with the same "no ep configured for
urb" for this "in_urb" (3). This completes "in_urb", which eventually
completes (1) and probe finishes with error. Error is expected, because
it's random junk-gadget...
The syzkaller reproducer fails if >1 of threads are running these usb
gadgets. When this happens, no "in_urb" completion happens. No this
"ack" port100_recv_ack().
I added some debugs and simply dummy_hcd dummy_timer() is woken up on
enqueuing in_urb and then is looping crazy on a previous URB (some older
URB, coming from before port100 driver probe started). The dummy_timer()
loop never reaches the second "in_urb" to process it, I think.
The pn533 NFC driver has similar design, but I have now really doubts it
is a NFC driver issue. Instead an issue in dummy gadget HCD is somehow
triggered by the reproducer.
Reproduction - just follow [1] or [2]. Eventually I slightly tweaked the
code and put here:
https://github.com/krzk/tools/tree/master/tests-var/nfc/port100_probe
$ make
$ sudo ./port100_probe
[1] https://syzkaller.appspot.com/bug?extid=abd2e0dafb481b621869
[2] https://syzkaller.appspot.com/bug?extid=1dc8b460d6d48d7ef9ca
Best regards,
Krzysztof
From: Alan Stern <stern@rowland.harvard.edu> Date: 2021-10-20 22:05:13
On Wed, Oct 20, 2021 at 10:56:42PM +0200, Krzysztof Kozlowski wrote:
Hi Alan, Felipe, Greg and others,
This is an old issue reported by syzkaller for NFC port100 driver [1].
There is something similar for pn533 [2].
I was looking at it some time ago, took a break and now I am trying to
fix it again. Without success.
The issue is reproducible via USB gadget on QEMU, not on real HW. I
looked and debugged the code and I think previously mentioned
double-URB-submit is not the reason here. Or I miss how the USB works
(which is quite probable...).
1. The port100 driver calls port100_send_cmd_sync() which eventually
goes to port100_send_frame_async(). After it, it waits for "sync"
completion.
2. In port100_send_frame_async(), driver indeed first submits "out_urb"
which quite fast is being processed by dummy_hcd with "no ep configured"
and -EPROTO.
3. Then (or sometimes before -EPROTO response from (2) above) the
port100_send_frame_async() submits "in_urb" via
port100_submit_urb_for_ack() and waits for its completion. Completion of
"in_urb" (or the "ack") in port100_recv_ack() would schedule work to
complete the (1) above - the sync completion.
4. Usually, when reproducer works fine (does not trigger issue), the
dummy_timer() from gadget responds with the same "no ep configured for
urb" for this "in_urb" (3). This completes "in_urb", which eventually
completes (1) and probe finishes with error. Error is expected, because
it's random junk-gadget...
The syzkaller reproducer fails if >1 of threads are running these usb
gadgets. When this happens, no "in_urb" completion happens. No this
"ack" port100_recv_ack().
I added some debugs and simply dummy_hcd dummy_timer() is woken up on
enqueuing in_urb and then is looping crazy on a previous URB (some older
URB, coming from before port100 driver probe started). The dummy_timer()
loop never reaches the second "in_urb" to process it, I think.
Is there any way you can track down what's happening in that crazy loop?
That is, what driver was responsible for the previous URB?
We have seen this sort of thing before, where a driver submits an URB
for a gadget which has disconnected. The URB fails with -EPROTO status
but the URB's completion handler does an automatic resubmit. That can
lead to a very tight loop with dummy-hcd, and it could easily prevent
some other important processing from occurring. The simple solution is
to prevent the driver from resubmitting when the completion status is
-EPROTO.
Alan Stern
From: Krzysztof Kozlowski <hidden> Date: 2021-10-25 14:57:33
On 21/10/2021 00:05, Alan Stern wrote:
quoted
The syzkaller reproducer fails if >1 of threads are running these usb
gadgets. When this happens, no "in_urb" completion happens. No this
"ack" port100_recv_ack().
I added some debugs and simply dummy_hcd dummy_timer() is woken up on
enqueuing in_urb and then is looping crazy on a previous URB (some older
URB, coming from before port100 driver probe started). The dummy_timer()
loop never reaches the second "in_urb" to process it, I think.
Is there any way you can track down what's happening in that crazy loop?
That is, what driver was responsible for the previous URB?
We have seen this sort of thing before, where a driver submits an URB
for a gadget which has disconnected. The URB fails with -EPROTO status
but the URB's completion handler does an automatic resubmit. That can
lead to a very tight loop with dummy-hcd, and it could easily prevent
some other important processing from occurring. The simple solution is
to prevent the driver from resubmitting when the completion status is
-EPROTO.
Hi Alan,
Thanks for the reply.
The URB which causes crazy loop is the port100 driver second URB, the
one called ack or in_urb.
The flow is:
1. probe()
2. port100_get_command_type_mask()
3. port100_send_cmd_async()
4. port100_send_frame_async()
5. usb_submit_urb(dev->out_urb)
The call succeeds, the dummy_hcd picks it up and immediately ends the
timer-loop with -EPROTO
The completion here does not resubmit another/same URB. I checked this
carefully and I hope I did not miss anything.
6. port100_submit_urb_for_ack() which sends the in_urb:
usb_submit_urb(dev->in_urb)
... wait for completion
... dummy_hcd loops on this URB around line 2000:
if (status == -EINPROGRESS)
continue
Best regards,
Krzysztof
From: Alan Stern <stern@rowland.harvard.edu> Date: 2021-10-25 16:22:10
On Mon, Oct 25, 2021 at 04:57:23PM +0200, Krzysztof Kozlowski wrote:
On 21/10/2021 00:05, Alan Stern wrote:
quoted
quoted
The syzkaller reproducer fails if >1 of threads are running these usb
gadgets. When this happens, no "in_urb" completion happens. No this
"ack" port100_recv_ack().
I added some debugs and simply dummy_hcd dummy_timer() is woken up on
enqueuing in_urb and then is looping crazy on a previous URB (some older
URB, coming from before port100 driver probe started). The dummy_timer()
loop never reaches the second "in_urb" to process it, I think.
Is there any way you can track down what's happening in that crazy loop?
That is, what driver was responsible for the previous URB?
We have seen this sort of thing before, where a driver submits an URB
for a gadget which has disconnected. The URB fails with -EPROTO status
but the URB's completion handler does an automatic resubmit. That can
lead to a very tight loop with dummy-hcd, and it could easily prevent
some other important processing from occurring. The simple solution is
to prevent the driver from resubmitting when the completion status is
-EPROTO.
Hi Alan,
Thanks for the reply.
The URB which causes crazy loop is the port100 driver second URB, the
one called ack or in_urb.
The flow is:
1. probe()
2. port100_get_command_type_mask()
3. port100_send_cmd_async()
4. port100_send_frame_async()
5. usb_submit_urb(dev->out_urb)
The call succeeds, the dummy_hcd picks it up and immediately ends the
timer-loop with -EPROTO
So that URB completes immediately.
The completion here does not resubmit another/same URB. I checked this
carefully and I hope I did not miss anything.
Yeah, I see the same thing.
6. port100_submit_urb_for_ack() which sends the in_urb:
usb_submit_urb(dev->in_urb)
... wait for completion
... dummy_hcd loops on this URB around line 2000:
if (status == -EINPROGRESS)
continue
Do I understand this correctly? You're saying that dummy-hcd executes
the following jump at line 1975:
/* incomplete transfer? */
if (status == -EINPROGRESS)
continue;
which goes back up to the loop head on line 1831:
list_for_each_entry_safe(urbp, tmp, &dum_hcd->urbp_list, urbp_list) {
Is that right? I don't see why this should cause any problem. It won't
loop back to the same URB; it will make its way through the list.
(Unless the list has somehow gotten corrupted...) dum_hcd->urbp_list
should be short (perhaps 32 entries at most), so the loop should reach
the end of the list fairly quickly.
Now, doing all this 1000 times per second could use up a significant
portion of the available time. Do you think that's the reason for the
problem? It seems pretty unlikely.
Alan Stern
From: Krzysztof Kozlowski <hidden> Date: 2021-10-25 17:14:11
On 25/10/2021 18:22, Alan Stern wrote:
On Mon, Oct 25, 2021 at 04:57:23PM +0200, Krzysztof Kozlowski wrote:
quoted
On 21/10/2021 00:05, Alan Stern wrote:
quoted
quoted
The syzkaller reproducer fails if >1 of threads are running these usb
gadgets. When this happens, no "in_urb" completion happens. No this
"ack" port100_recv_ack().
I added some debugs and simply dummy_hcd dummy_timer() is woken up on
enqueuing in_urb and then is looping crazy on a previous URB (some older
URB, coming from before port100 driver probe started). The dummy_timer()
loop never reaches the second "in_urb" to process it, I think.
Is there any way you can track down what's happening in that crazy loop?
That is, what driver was responsible for the previous URB?
We have seen this sort of thing before, where a driver submits an URB
for a gadget which has disconnected. The URB fails with -EPROTO status
but the URB's completion handler does an automatic resubmit. That can
lead to a very tight loop with dummy-hcd, and it could easily prevent
some other important processing from occurring. The simple solution is
to prevent the driver from resubmitting when the completion status is
-EPROTO.
Hi Alan,
Thanks for the reply.
The URB which causes crazy loop is the port100 driver second URB, the
one called ack or in_urb.
The flow is:
1. probe()
2. port100_get_command_type_mask()
3. port100_send_cmd_async()
4. port100_send_frame_async()
5. usb_submit_urb(dev->out_urb)
The call succeeds, the dummy_hcd picks it up and immediately ends the
timer-loop with -EPROTO
So that URB completes immediately.
quoted
The completion here does not resubmit another/same URB. I checked this
carefully and I hope I did not miss anything.
Yeah, I see the same thing.
quoted
6. port100_submit_urb_for_ack() which sends the in_urb:
usb_submit_urb(dev->in_urb)
... wait for completion
... dummy_hcd loops on this URB around line 2000:
if (status == -EINPROGRESS)
continue
Do I understand this correctly? You're saying that dummy-hcd executes
the following jump at line 1975:
/* incomplete transfer? */
if (status == -EINPROGRESS)
continue;
which goes back up to the loop head on line 1831:
list_for_each_entry_safe(urbp, tmp, &dum_hcd->urbp_list, urbp_list) {
Is that right?
Yes, exactly. The loop continues, iterating over list finishes thus the
loops and dummy timer function exits. Then immediately it is being
rescheduled by something (I don't know by what yet).
To remind - the syzbot reproducer must run at least two threads
(spawning USB gadgets so creating separate dummy devices) at the same
time. However only one of dummy HCD devices seems to timer-loop
endlessly... but this might not be important, e.g. maybe it's how syzbot
reproducer works.
I don't see why this should cause any problem. It won't
loop back to the same URB; it will make its way through the list.
(Unless the list has somehow gotten corrupted...) dum_hcd->urbp_list
should be short (perhaps 32 entries at most), so the loop should reach
the end of the list fairly quickly.
The list has actually only one element - only this one URB coming from
port100 device (which I was always calling second URB/ack, in_urb).
Now, doing all this 1000 times per second could use up a significant
portion of the available time. Do you think that's the reason for the
problem? It seems pretty unlikely.
No, this timer-looping itself is not a problem. Problem is that this URB
never reaches some final state, e.g. -EPROTO.
In normal operation, e.g. when reproducer did not hit the issue, both
URBs from port100 (the first out_urb and second in_urb) complete with
-EPROTO. In the case leading to hang ("task kworker/0:0:5 blocked for
more than 143 seconds"), the in_urb does not complete therefore the
port100 driver waits.
Whether this intensive timer-loop is important (processing the same URB
and continuing), I don't know.
Best regards,
Krzysztof
From: Alan Stern <stern@rowland.harvard.edu> Date: 2021-10-25 18:54:38
On Mon, Oct 25, 2021 at 07:13:59PM +0200, Krzysztof Kozlowski wrote:
On 25/10/2021 18:22, Alan Stern wrote:
quoted
On Mon, Oct 25, 2021 at 04:57:23PM +0200, Krzysztof Kozlowski wrote:
quoted
The URB which causes crazy loop is the port100 driver second URB, the
one called ack or in_urb.
The flow is:
1. probe()
2. port100_get_command_type_mask()
3. port100_send_cmd_async()
4. port100_send_frame_async()
5. usb_submit_urb(dev->out_urb)
The call succeeds, the dummy_hcd picks it up and immediately ends the
timer-loop with -EPROTO
So that URB completes immediately.
quoted
The completion here does not resubmit another/same URB. I checked this
carefully and I hope I did not miss anything.
Yeah, I see the same thing.
quoted
6. port100_submit_urb_for_ack() which sends the in_urb:
usb_submit_urb(dev->in_urb)
... wait for completion
... dummy_hcd loops on this URB around line 2000:
if (status == -EINPROGRESS)
continue
Do I understand this correctly? You're saying that dummy-hcd executes
the following jump at line 1975:
/* incomplete transfer? */
if (status == -EINPROGRESS)
continue;
which goes back up to the loop head on line 1831:
list_for_each_entry_safe(urbp, tmp, &dum_hcd->urbp_list, urbp_list) {
Is that right?
Yes, exactly. The loop continues, iterating over list finishes thus the
loops and dummy timer function exits. Then immediately it is being
rescheduled by something (I don't know by what yet).
There's a timer (dum_hcd->timer) which fires every millisecond. If
syzbot creates a lot of dummy-hcd instances then each instance will have
its own timer, which could use up a large part of the available CPU
time. But you say this isn't the real problem...
To remind - the syzbot reproducer must run at least two threads
(spawning USB gadgets so creating separate dummy devices) at the same
time. However only one of dummy HCD devices seems to timer-loop
endlessly... but this might not be important, e.g. maybe it's how syzbot
reproducer works.
quoted
I don't see why this should cause any problem. It won't
loop back to the same URB; it will make its way through the list.
(Unless the list has somehow gotten corrupted...) dum_hcd->urbp_list
should be short (perhaps 32 entries at most), so the loop should reach
the end of the list fairly quickly.
The list has actually only one element - only this one URB coming from
port100 device (which I was always calling second URB/ack, in_urb).
Okay, good.
quoted
Now, doing all this 1000 times per second could use up a significant
portion of the available time. Do you think that's the reason for the
problem? It seems pretty unlikely.
No, this timer-looping itself is not a problem. Problem is that this URB
never reaches some final state, e.g. -EPROTO.
The -EPROTO completion should happen very quickly once the gadget driver
unregisters or disconnects itself. This is because the call to
find_endpoint at line 1856 should return NULL:
ep = find_endpoint(dum, address);
if (!ep) {
/* set_configuration() disagreement */
dev_dbg(dummy_dev(dum_hcd),
"no ep configured for urb %p\n",
urb);
status = -EPROTO;
goto return_urb;
}
The NULL return should be caused by the !is_active test at the
beginning of find_endpoint:
static struct dummy_ep *find_endpoint(struct dummy *dum, u8 address)
{
int i;
if (!is_active((dum->gadget.speed == USB_SPEED_SUPER ?
dum->ss_hcd : dum->hs_hcd)))
return NULL;
is_active is defined as a macro:
#define is_active(dum_hcd) ((dum_hcd->port_status & \
(USB_PORT_STAT_CONNECTION | USB_PORT_STAT_ENABLE | \
USB_PORT_STAT_SUSPEND)) \
== (USB_PORT_STAT_CONNECTION | USB_PORT_STAT_ENABLE))
and a disconnection should turn off the USB_PORT_STAT_CONNECTION bit, as
follows:
usb_gadget_unregister_driver calls usb_gadget_remove_driver
(in drivers/usb/gadget/udc/core.c),
which calls usb_gadget_disconnect,
which calls dummy_pullup with value = 0,
which sets dum->pullup to 0 and calls set_link_state,
which calls set_link_state_by_speed,
which turns off the USB_PORT_STATE_CONNECTION bit in
dum_hcd->port_status because dum->pullup is 0.
You can try tracing through this sequence of events to see if they're
not taking place as intended.
In normal operation, e.g. when reproducer did not hit the issue, both
URBs from port100 (the first out_urb and second in_urb) complete with
-EPROTO. In the case leading to hang ("task kworker/0:0:5 blocked for
more than 143 seconds"), the in_urb does not complete therefore the
port100 driver waits.
Those "... blocked for more than 143 seconds" errors occur when some
task or interrupt loop is using up all the CPU time, preventing normal
processes from running. In this case the culprit has got to be the
timer routine and loop in dummy_hcd. However, the loop should terminate
once the gadget driver unregisters itself, as described above.
Whether this intensive timer-loop is important (processing the same URB
and continuing), I don't know.
Yes, that's how dummy_hcd gets its work done.
Alan Stern
Hm, I can't reproduce this issue on top of my tree. Let's test my latest
port100 patch
#syz test
git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
With regards,
Pavel Skripkin