On Fri, 2018-03-23 at 00:06 +0100, Marcel Holtmann wrote:
> Hi Brennan,
>
> > > > I recently brought an Intel Edison board with a BCM43341B0 chip
> > > > up
> > > > from
> > > > 4.9 to 4.16.0-rc6 but I am having reliability issues when using
> > > > btattach instead of the previous brcm_patchram_plus utility to
> > > > attach
> > > > the device.
> > > >
> > > >
> > > > The hci communication with the bluetooth chip gets corrupted
> > > > almost
> > > > always when creating a GATT connection. Thowing "Bluetooth:
> > > > hci0:
> > > > Frame reassembly failed (-84)" and then requiring the device to
> > > > be
> > > > reset to communicate again.
> > > >
> > > > Kernel logs interleaved with attaching the device:
> > > > # /usr/bin/btattach --bredr /dev/ttyS0 -P bcm -S 3000000 &
> > > > # Attaching Primary controller to /dev/ttyS0
> > > > [ 53.148206] Bluetooth: HCI UART driver ver 2.3
> > > > [ 53.152758] Bluetooth: HCI UART protocol H4 registered
> > > > [ 53.157970] Bluetooth: HCI UART protocol Three-wire (H5)
> > > > registered
> > > > [ 53.164512] hci_bcm hci_bcm: hci_bcm device registered.
> > > > [ 53.170445] Bluetooth: HCI UART protocol Broadcom registered
> > > > Switched line discipline from 0 to 15
> > > > Device index 0 attached
> > > > [ 53.333220] Bluetooth: hci0: BCM: chip id 82
> > > > [ 53.340184] Bluetooth: hci0: BCM: features 0x2f
> > > > [ 53.368421] Bluetooth: hci0: BCM43341B0
> > > > [ 53.372338] Bluetooth: hci0: BCM43341B0 (002.001.014) build
> > > > 0000
> > > > [ 57.843684] Bluetooth: hci0: BCM (002.001.014) build 0166
> > >
> > > if you have a chance, I like to see the complete binary btmon -w
> > > trace.log.
> >
> > I have attached two traces starting the monitoring and then
> > attaching
> > the bluetooth device, first with btattach and second with the
> > patchram.
> >
> > btattach-trace.log patchram-trace.log
> >
> > The with btattach you can see the failure on connect, with patchram
> > the
> > full connection is successful as is the disconnect.
> >
> > >
> > > However I think we need to figure out what is causing the -EILSEQ
> > > error in the h4_recv_buf() in hci_h4.c. There are more than one
> > > in it
> > > and you have to do some printk debugging to figure out which one
> > > it
> > > is.
> > >
> > > So if you do something like this, then we might be able to debug
> > > what
> > > is going on in the H:4 stream.
> > >
> > > diff --git a/drivers/bluetooth/hci_h4.c
> > > b/drivers/bluetooth/hci_h4.c
> > > index fb97a3bf069b..ba9b293f4948 100644
> > > --- a/drivers/bluetooth/hci_h4.c
> > > +++ b/drivers/bluetooth/hci_h4.c
> > > @@ -201,8 +201,13 @@ struct sk_buff *h4_recv_buf(struct hci_dev
> > > *hdev, struct sk_buff *skb,
> > > }
> > >
> > > /* Check for invalid packet type */
> > > - if (!skb)
> > > + if (!skb) {
> > > + printk(KERN_INFO "H4: Invalid
> > > packet
> > > type\n");
> > > + print_hex_dump(KERN_INFO, " ",
> > > + DUMP_PREFIX_OFFSET
> > > ,
> > > 16, 1,
> > > + buffer, count,
> > > true);
> > > return ERR_PTR(-EILSEQ);
> > > + }
> > >
> > > count -= 1;
> > > buffer += 1;
> > > @@ -224,6 +229,9 @@ struct sk_buff *h4_recv_buf(struct hci_dev
> > > *hdev,
> > > struct sk_buff *skb,
> > > }
> > >
> > > if (i >= pkts_count) {
> > > + printk(KERN_INFO "H4: Corrupted packet
> > > type\n");
> > > + print_hex_dump(KERN_INFO, " ",
> > > DUMP_PREFIX_OFFSET,
> > > + 16, 1, skb->data, skb-
> > > >len,
> > > true);
> > > kfree_skb(skb);
> > > return ERR_PTR(-EILSEQ);
> > > }
> > > @@ -259,6 +267,10 @@ struct sk_buff *h4_recv_buf(struct hci_dev
> > > *hdev, struct sk_buff *skb,
> > > break;
> > > default:
> > > /* Unsupported variable length */
> > > + printk(KERN_INFO "H4: Invalid
> > > variable len\n");
> > > + print_hex_dump(KERN_INFO, " ",
> > > + DUMP_PREFIX_OFFSET
> > > ,
> > > 16, 1,
> > > + skb->data, skb-
> > > >len,
> > > true);
> > > kfree_skb(skb);
> > > return ERR_PTR(-EILSEQ);
> > > }
> > >
> > > If the H:4 stream fails for whatever reason, then that is pretty
> > > bad
> > > since there is no recovery.
> >
> >
> > Here are the results with the printk patch:
> > Kernel (btattach)
> >
> > [ 73.192554] Bluetooth: HCI UART driver ver 2.3
> > [ 73.197063] Bluetooth: HCI UART protocol H4 registered
> > [ 73.202268] Bluetooth: HCI UART protocol Three-wire (H5)
> > registered
> > [ 73.208744] hci_bcm hci_bcm: hci_bcm device registered.
> > [ 73.214382] Bluetooth: HCI UART protocol Broadcom registered
> > [ 73.393060] Bluetooth: hci0: BCM: chip id 82
> > [ 73.398965] Bluetooth: hci0: BCM: features 0x2f
> > [ 73.624991] Bluetooth: hci0: BCM43341B0
> > [ 73.747834] Bluetooth: hci0: BCM43341B0 (002.001.014) build 0000
> > [ 74.317254] random: crng init done
> > [ 78.234907] Bluetooth: hci0: BCM (002.001.014) build 0166
> > [ 124.797242] H4: Invalid packet type
> > [ 124.800808] 00000000: 90 9a 01 00 40 00 01 01 3e 54 00 18 45
> > 69 24
> > 00 ....@...>T..Ei$.
> > [ 124.809049] 00000010: 00 00 f4 01
> > 00 .....
> > [ 124.816332] Bluetooth: hci0: Frame reassembly failed (-84)
>
> so here is the problem, we detect a 0x90 packet type in the stream.
> If we detect that, we would need to re-synchronize to a H:4 valid
> packet type. Can you compare timestamps and see what the packet
> before and after of this is. btmon and dmesg can print absolute
> timestamps.
>
I am worried we are going to far away looking at this, since attaching
to the device differently seems to be triggering this. Maybe the serial
interface is being configured differently here:
https://github.com/01org/edison-firmware/blob/master/broadcom_cws/bluet
ooth/firmware/brcm_patchram_plus.c
I think this is what you are asking for though. I aligned the time-
stamps of the kernel and btmon messages:
< HCI Command: LE Set Adve.. (0x08|0x0006) plen 15 #312 [hci0]
23:35:24.170102
Min advertising interval: 1280.000 msec (0x0800)
Max advertising interval: 1280.000 msec (0x0800)
Type: Connectable undirected - ADV_IND (0x00)
Own address type: Public (0x00)
Direct address type: Public (0x00)
Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
Channel map: 37, 38, 39 (0x07)
Filter policy: Allow Scan Request from Any, Allow Connect
Request from Any (0x00)
> HCI Event: Command Complete (0x0e) plen 4 #313 [hci0]
23:35:24.173680
LE Set Advertising Parameters (0x08|0x0006) ncmd 1
Status: Success (0x00)
< HCI Command: LE Set Adver.. (0x08|0x000a) plen 1 #314 [hci0]
23:35:24.173990
Advertising: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4 #315 [hci0]
23:35:24.176283
LE Set Advertise Enable (0x08|0x000a) ncmd 1
Status: Success (0x00)
@ Control Event: 0xffff {0x0003} [hci0]
23:35:24.176434
01 00 3e 00 00 01
2018-03-22T23:35:34,770131+0000 H4: Invalid packet type
2018-03-22T23:35:34,773701+0000 00000000: 90 9a 01 00 40 00 01 01 0e
e7 86 49 6f 4d 24 00 ....@......IoM$.
2018-03-22T23:35:34,781939+0000 00000010: 00 00 f4 01
00 .....
2018-03-22T23:35:34,789248+0000 Bluetooth: hci0: Frame reassembly
failed (-84)
2018-03-22T23:35:35,025555+0000 Bluetooth: hci0: ACL packet for unknown
connection handle 64
> ACL Data RX: Handle 64 flags 0x02 dlen 11 #316 [hci0]
23:35:36.025425
ATT: Read By Group Type Request (0x10) len 6
Handle range: 0x0001-0xffff
Attribute group type: Primary Service (0x2800)
> HCI Event: LE Meta Event (0x3e) plen 10 #317 [hci0]
23:35:36.393267
LE Connection Update Complete (0x03)
Status: Success (0x00)
Handle: 64
Connection interval: 7.50 msec (0x0006)
Connection latency: 0 (0x0000)
Supervision timeout: 5000 msec (0x01f4)
2018-03-22T23:35:39,952909+0000 Bluetooth: hci0: ACL packet for unknown
connection handle 64
> ACL Data RX: Handle 64 flags 0x02 dlen 11 #318 [hci0]
23:35:40.952760
ATT: Read By Group Type Request (0x10) len 6
Handle range: 0x0001-0xffff
Attribute group type: Primary Service (0x2800)
2018-03-22T23:35:44,970395+0000 Bluetooth: hci0: ACL packet for unknown
connection handle 64
> ACL Data RX: Handle 64 flags 0x02 dlen 11 #319 [hci0]
23:35:45.970242
ATT: Read By Group Type Request (0x10) len 6
Handle range: 0x0001-0xffff
Attribute group type: Primary Service (0x2800)
> HCI Event: Disconnect Complete (0x05) plen 4 #320 [hci0]
23:35:50.995471
Status: Success (0x00)
Handle: 64
Reason: Remote User Terminated Connection (0x13)
--
To unsubscribe from this list: send the line "unsubscribe linux-bluetooth" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
