On Tue, 2018-06-12 at 17:58 +0800, Sean Wang wrote:

On Wed, 2018-05-30 at 08:26 +0200, Marcel Holtmann wrote:

quoted

Hi Sean,

quoted

quoted

quoted

quoted

quoted

quoted

[ ... ]

quoted

quoted

quoted

quoted

* Unknown packet (code 14 len 30)                                      0.641509
      01 00 00 00 02 00 01 0e 00 01 00 00 00 10 62 6c  ..............bl
      75 65 74 6f 6f 74 68 64 00 00 00 00 00 00        uetoothd......  
* Unknown packet (code 14 len 30)                                      0.641592
      02 00 00 00 02 00 01 0e 00 01 00 00 00 10 62 74  ..............bt
      6d 6f 6e 00 00 00 00 00 00 00 00 00 00 00        mon...........  
* Unknown packet (code 16 len 7)                                [hci0] 6.536771
      01 00 00 00 05 00 01                             .......         
= Open Index: 00:00:46:76:22:01                                 [hci0] 6.717019
= Index Info: 00:00:46:76:22:01 (MediaTek, Inc.)                [hci0] 6.717030

can you try with the latest BlueZ 5.49 or git version. Seems it actually stumbles over the extra packet here. Fun fact is that I can not get a backtrace to pin-point the issue in btmon and why it crashes.

I had less experience updating user land BlueZ, but I can try it as possible and see whether Unknown packets still are present at newest version BlueZ. Hopefully I don't misunderstand your point here. 

please use the latest btmon and check if it can read your trace.

sure, I'll have a try with the latest btmon.

I use the btmon version 5.50 and it can read the trace

quoted

quoted

quoted

quoted

quoted

HCI Event: Unknown (0xe4) plen 5                              [hci0] 6.741093

      02 01 01 00 00                                   .....           

quoted

HCI Event: Unknown (0xe4) plen 5                              [hci0] 6.742088

      02 01 01 00 00                                   .....           

quoted

HCI Event: Unknown (0xe4) plen 5                              [hci0] 6.743102

      02 01 01 00 00                                   .....           

[ ... ]

quoted

quoted

quoted

quoted

quoted

HCI Event: Unknown (0xe4) plen 5                              [hci0] 6.814708

      02 01 01 00 00                                   .....           

quoted

HCI Event: Unknown (0xe4) plen 5                              [hci0] 6.815705

      02 01 01 00 00                                   .....           

quoted

HCI Event: Unknown (0xe4) plen 5                              [hci0] 6.816378

      02 01 01 00 00                                   .....           

Why do I see only HCI events here? Is this event conveying any useful information. It is kinda complicated that this is 0xe4 event code which is actually reserved for future use by the Bluetooth SIG. Are there any accompanying HCI commands for this and they just not make it into btmon?

I have made all vendor HCI commands go through BlueZ core in v2 patch. 

And for these HCI events, they are all corresponding to vendor ACL data, applied only to firmware setup packets, but they're not being sent via BlueZ core, so they are not being logged in btmon.

As for its event, where heading 0xe4 refers to a vendor event and is used on notification of that either vendor ACL data or vendor HCI command have been done.

I would prefer if everything goes via the Bluetooth core since then we have it all properly scheduled. Sending things down the ACL data path however if kinda funky. Does your hardware accept sending command both via ACL data and as HCI command? If so, then I would prefer sending them as HCI commands since the speed improvement you think you are getting is neglectable on Linux (I have been down that path). This seems to be a pure optimization when Windows is driving the device.

firmware people said the device can support firmware download as HCI commands. According to my test, this way indeed works so I will improve the part in the next version.

quoted

And the vendor event 0xe4 is really only received during firmware download? It is not ever received during normal operation?

0xe4 is only received during chip initialization.

I also thought 0xe4 is a poor definition for vendor event and already have notified firmware people should pick 0xff as its vendor event id in the future.

but for now, unfortunately, 0xe4 cannot be changed on the device, the only way is to add a workaround in RX path as below to allow btmon can recognize these bad events properly. 

int mtk_btuart_hci_frame(struct hci_dev *hdev, struct sk_buff *skb)
{
        struct hci_event_hdr *hdr = (void *)skb->data;

        /* Fix up the vendor event id with HCI_VENDOR_PKT instead of
         * 0xe4 so that btmon can parse the kind of vendor event properly.
         */
        if (hdr->evt == 0xe4)
                hdr->evt = HCI_VENDOR_PKT;

        /* Each HCI event would go through the core. */
        return hci_recv_frame(hdev, skb);
}

quoted

quoted

quoted

quoted

< HCI Command: Vendor (0x3f|0x006f) plen 5                      [hci0] 6.816413
      01 07 01 00 04                                   .....           

quoted

HCI Event: Unknown (0xe4) plen 5                              [hci0] 6.816536

      02 07 01 00 00                                   .....           

[ ... ]

quoted

quoted

quoted

quoted

        Encapsulated PDU
        Erroneous Data Reporting
        Non-flushable Packet Boundary Flag
        Link Supervision Timeout Changed Event
        Inquiry TX Power Level
        Enhanced Power Control
        Extended features
< HCI Command: Read Local Version Info.. (0x04|0x0001) plen 0  [hci0] 10.865987

quoted

HCI Event: Vendor (0xff) plen 9                              [hci0] 10.866259

      29 19 09 17 20 48 07 11 00                       )... H…       

Is this meant to happen here?

If event received is not expected as the specification defines, I think it's probably incorrect.

But it requires more discussion with firmware people to make it clearer.

Please check and let them decode what this event means.

it's just debugging purpose information listing built-time something
like that and will be removed in the firmware.

quoted

quoted

quoted

quoted

quoted

HCI Event: Command Complete (0x0e) plen 12                   [hci0] 10.866372

    Read Local Version Information (0x04|0x0001) ncmd 1
      Status: Success (0x00)
      HCI version: Bluetooth 4.2 (0x08) - Revision 4359 (0x1107)
      LMP version: Bluetooth 4.2 (0x08) - Subversion 2329 (0x0919)
      Manufacturer: MediaTek, Inc. (70)
< HCI Command: Read BD ADDR (0x04|0x0009) plen 0               [hci0] 10.866391

quoted

HCI Event: Command Complete (0x0e) plen 10                   [hci0] 10.866539

[ ... ]

quoted

quoted

quoted

quoted

        LE Add Device To Resolving List (Octet 34 - Bit 3)
        LE Remove Device From Resolving List (Octet 34 - Bit 4)
        LE Clear Resolving List (Octet 34 - Bit 5)
        LE Read Resolving List Size (Octet 34 - Bit 6)
        LE Read Peer Resolvable Address (Octet 34 - Bit 7)
        LE Read Local Resolvable Address (Octet 35 - Bit 0)
        LE Set Address Resolution Enable (Octet 35 - Bit 1)
        LE Set Resolvable Private Address Timeout (Octet 35 - Bit 2)
        LE Read Maximum Data Length (Octet 35 - Bit 3)
        Octet 35 - Bit 4 
        Octet 35 - Bit 5 
        Octet 35 - Bit 6 
        Octet 35 - Bit 7 
        Octet 36 - Bit 0 

So you support the PHY commands, but do not indicate support LE 2M or LE Coded? Also these are Bluetooth 5.0 commands.

To be honest. When I ported the device into Bluez core, a unexpected event for LE read local feature would cause a fail at Bluez core, so I made a hack on Bluez core  

to allow that I can keeping bring up the device without be blocked by the issue most probably from firmware.

Below code snippet is the only thing I added to avoid a fail at Bluez core to bring upbtsnoop the device.

@@ -927,6 +927,8 @@ static void hci_cc_le_read_local_features(struct hci_dev *hdev,
               return;

       memcpy(hdev->le_features, rp->features, 8);
+       hdev->le_features[0] = 0;
+       hdev->le_features[1] = 0;

}

Send me the trace where you didn’t clear the feature bits and I check what is going on. I doubt that we have a bug, but maybe some of the commands are optional and we should add an appropriate check. Or you guys need to fix your firmware. A new btmon should decode all bits properly.

okay, I'll have a follow-up.where

. 
It's a fault from the device and can be simply fixed up in the firmware.
The fault is the device reporting to host told it can support "LE Read
Maximum Data Length", but actually it can't. so it's just a fail at the
command.


The attached here is the fail log I captured with btmon 5.50 where I
already turned the patch setup in HCI command from ACL data and turned
event id 0xe4 to 0xff every vendor should use. And, finally, it can be
seen that btmon already can record and parse all traffic between host
and device well.

quoted

Regards

Marcel