RE: [PATCH] btusb: fix zero BD address problem during stress test

[Amitkumar Karwar]

Hi Marcel,

> From: Amitkumar Karwar
> Sent: Wednesday, November 23, 2016 3:14 PM
> To: 'Marcel Holtmann'
> Cc: linux-bluetooth@xxxxxxxxxxxxxxx; linux-kernel@xxxxxxxxxxxxxxx;
> Cathy Luo; Nishant Sarmukadam; Ganapathi Bhat
> Subject: RE: [PATCH] btusb: fix zero BD address problem during stress
> test
> 
> Hi Marcel,
> 
> > From: Marcel Holtmann [mailto:marcel@xxxxxxxxxxxx]
> > Sent: Wednesday, November 23, 2016 1:46 PM
> > To: Amitkumar Karwar
> > Cc: linux-bluetooth@xxxxxxxxxxxxxxx; linux-kernel@xxxxxxxxxxxxxxx;
> > Cathy Luo; Nishant Sarmukadam; Ganapathi Bhat
> > Subject: Re: [PATCH] btusb: fix zero BD address problem during stress
> > test
> >
> > Hi Amitkumar,
> >
> > >>>> From: Amitkumar Karwar [mailto:akarwar@xxxxxxxxxxx]
> > >>>> Sent: Tuesday, October 18, 2016 6:27 PM
> > >>>> To: linux-bluetooth@xxxxxxxxxxxxxxx
> > >>>> Cc: marcel@xxxxxxxxxxxx; linux-kernel@xxxxxxxxxxxxxxx; Cathy
> Luo;
> > >>>> Nishant Sarmukadam; Ganapathi Bhat; Amitkumar Karwar
> > >>>> Subject: [PATCH] btusb: fix zero BD address problem during
> stress
> > >>>> test
> > >>>>
> > >>>> From: Ganapathi Bhat <gbhat@xxxxxxxxxxx>
> > >>>>
> > >>>> We came across a corner case issue during reboot stress test in
> > >> which
> > >>>> hciconfig shows BD address is all zero. Reason is we don't get
> > >>>> response for HCI RESET command during initialization
> > >>>>
> > >>>> The issue is tracked to a race where USB subsystem calls
> > >>>> btusb_intr_complete() to deliver a data(NOOP frame) received on
> > >>>> interrupt endpoint. HCI_RUNNING flag is not yet set by bluetooth
> > >>>> subsystem. So we ignore that frame and return.
> > >>>>
> > >>>> As we missed to resubmit the buffer to interrupt endpoint in
> this
> > >>>> case, we don't get response for BT reset command downloaded
> after
> > >> this.
> > >>>>
> > >>>> This patch handles the corner case to resolve zero BD address
> > >> problem.
> > >>>>
> > >>>> Signed-off-by: Ganapathi Bhat <gbhat@xxxxxxxxxxx>
> > >>>> Signed-off-by: Amitkumar Karwar <akarwar@xxxxxxxxxxx>
> > >>>> ---
> > >>>> drivers/bluetooth/btusb.c | 5 +----
> > >>>> 1 file changed, 1 insertion(+), 4 deletions(-)
> > >>>>
> > >>>> diff --git a/drivers/bluetooth/btusb.c
> > >>>> b/drivers/bluetooth/btusb.c index 811f9b9..b5596ac 100644
> > >>>> --- a/drivers/bluetooth/btusb.c
> > >>>> +++ b/drivers/bluetooth/btusb.c
> > >>>> @@ -607,10 +607,7 @@ static void btusb_intr_complete(struct urb
> > >> *urb)
> > >>>> 	BT_DBG("%s urb %p status %d count %d", hdev->name, urb,
> urb-
> > >>>>> status,
> > >>>> 	       urb->actual_length);
> > >>>>
> > >>>> -	if (!test_bit(HCI_RUNNING, &hdev->flags))
> > >>>> -		return;
> > >>>> -
> > >>>> -	if (urb->status == 0) {
> > >>>> +	if (urb->status == 0 && test_bit(HCI_RUNNING, &hdev-
> > >flags)) {
> > >>>> 		hdev->stat.byte_rx += urb->actual_length;
> > >>>>
> > >>>> 		if (btusb_recv_intr(data, urb->transfer_buffer,
> > >>>
> > >>> Did you get a chance to check this?
> > >>> Please let us know if you have any review comments.
> > >>
> > >> can you explain how this is correct and show me the HCI traces for
> > >> this.
> > >>
> > >
> > > I suppose HCI trace means hcidump logs here. As device hasn't yet
> > initialized, hcidump won't show anything.
> > > We had added debug info in btusb driver to trace the data received
> > > on
> > all USB endpoints and also checked usbmon logs.
> >
> > use btmon and it will show it.
> >
> > > Here is the sequence of events we observed in a corner case while
> > running stress test.
> > > 1) Inside btusb_open() call ------ Thread 1
> > > 2) btusb_submit_intr_urb() submits the URB for receiving data on
> > > interrupt endpoint ---- Thread 1
> > > 3) btusb_intr_complete() gets called to deliver NOP frame from HCI
> > > controller ---- Thread 2
> > > 4) HCI_RUNNING isn't set yet. So we return from
> > > btusb_intr_complete() without resubmitting the buffer --- Thread 2
> > > 5) Exit btusb_open() ---- Thread 1
> > > 6) "set_bit(HCI_RUNNING, &hdev->flags)" done by bluetooth core ----
> > > Thread 1
> > >
> > > Later HCI_RESET command gets timedout, as we haven't re-submitted
> > buffer for interrupt endpoint in step (4) above.
> > >
> > > Please find attached logs. usbmon log shows first frame received on
> > interrupt endpoint is NOP(Search for Marvell in log).
> > >
> > > Here is what bluetooth spec says about NOP frame.
> > >
> > > "To indicate to the Host that the Controller is ready to receive
> HCI
> > > command packets, the Controller generates a Command Status event
> > > with Status 0x00 and Command_Opcode 0x0000, and the
> > Num_HCI_Command_Packets
> > > event parameter is set to 1 or more. Command_Opcode, 0x0000 is a
> NOP
> > (No Operation)â
> >
> > So I wonder if we need to remove the HCI_RUNNING logic from the
> > drivers. It is only left in a few USB drivers and I removed the rest
> > and moved it into the core. I am not in favour of papering over this
> > issue. I need to understand what is wrong. And actually HCI_RUNNING
> > needs to be taken away from the drivers. So the question is if
> btusb.c
> > still needs it or if that is just a leftover. Meaning is it
> protecting
> > anything?
> >
> 
> I can see HCI_RUNNING check being used at below places in btusb.c
> 
> 1) btusb_intr_complete
> 2) btusb_bulk_complete
> 3) btusb_isoc_complete
> 4) btusb_tx_complete
> 5) btusb_isoc_tx_complete
> 6) btusb_bcm_set_diag
> 7) btusb_resume
> 
> I think, it can be removed from (1), (2) and (3), as we already have
> below check inside hci_recv_frame()
> 
>         if (!hdev || (!test_bit(HCI_UP, &hdev->flags)
>                       && !test_bit(HCI_INIT, &hdev->flags))) {
>                 kfree_skb(skb);
>                 return -ENXIO;
>         }
> 
> For (4) and (5), it's just used to decide if we should update "hdev-
> >stat" or not.
> 

Please guide on how should we fix this issue. We observe timeout for HCI_RESET command sometimes when system is booted. This happens due to missing urb_submitt() when first frame(NOP) received on INT endpoint is ignored. Below change would also help.

--- a/net/bluetooth/hci_core.c
+++ b/net/bluetooth/hci_core.c
@@ -1318,12 +1318,13 @@ static int hci_dev_do_open(struct hci_dev *hdev)
                goto done;
        }

+       set_bit(HCI_RUNNING, &hdev->flags);
        if (hdev->open(hdev)) {
+               clear_bit(HCI_RUNNING, &hdev->flags);
                ret = -EIO;
                goto done;
        }

-       set_bit(HCI_RUNNING, &hdev->flags);
        hci_sock_dev_event(hdev, HCI_DEV_OPEN);

Regards,
Amitkumar