2017-03-22 02:47:51

by Wong, Joshua Weng Onn

[permalink] [raw]
Subject: Unexpected SMP Command 0x17

SGkgYWxsLA0KDQpJIGFtIHNlZWluZyBhbiBlcnJvciBkdXJpbmcgdGhlIExFIHBhaXJpbmcgcHJv
Y2VzcyB3aGljaCBtYWtlcyB0aGUgcGFpcmluZyB0byBmYWlsLiBJIGhhdmUgdHdvIERVVHMgd2hp
Y2ggdXNlcyB0aGUgTWFydmVsbCA4OFc4ODk3Lg0KSGVyZSBhcmUgbXkgQlQgc2V0dGluZ3MgZm9y
IGJvdGggbWFzdGVyIGFuZCBzbGF2ZToNCg0KTWFzdGVyOg0KJCBidG1nbXQgaW5mbw0KY3VycmVu
dCBzZXR0aW5nczogcG93ZXJlZCBjb25uZWN0YWJsZSBkaXNjb3ZlcmFibGUgYm9uZGFibGUgc3Nw
IGJyL2VkciBsZSBzZWN1cmUtY29ubg0KDQpTbGF2ZToNCiQgYnRtZ210IGluZm8NCkN1cnJlbnQg
c2V0dGluZ3M6IHBvd2VyZWQgY29ubmVjdGFibGUgYm9uZGFibGUgbGUgYWR2ZXJ0aXNpbmcgc2Vj
dXJlLWNvbm4NCg0KV2hlbiBJIGluaXRpYXRlIHRoZSBwYWlyaW5nIHByb2Nlc3MgZnJvbSB0aGUg
bWFzdGVyLCBJIG9ic2VydmVkIHRoZSBtZXNzYWdlOg0KIkJsdWV0b290aDogaGNpMCB1bmV4cGVj
dGVkIFNNUCBjb21tYW5kIDB4MGEgZnJvbSA3NDpjNjozYjphYjo2ODplYSINCg0KV2hlcmUgNzQ6
YzY6M2I6YWI6Njg6ZWEgaXMgdGhlIGFkZHJlc3Mgb2YgdGhlIHNsYXZlIGRldmljZS4NCg0KSW4g
dGhlIGJ0bW9uIGxvZyBvZiB0aGUgbWFzdGVyIGRldmljZSwgaXQgaXMgb2JzZXJ2ZWQgdGhhdCBh
ZnRlciB0aGUgU2xhdmUgZGV2aWNlIGhhcyB0cmFuc21pdHRlZCB0aGUga2V5cywgdGhlIE1hc3Rl
ciBkb2VzIG5vdCB0cmFuc21pdCBpdC4gSGVuY2UsIHRoZSBTbGF2ZSBpcyBub3QgcmVjZWl2aW5n
IHRoZSBrZXlzIGFuZCB0aHVzIGRpc2Nvbm5lY3RzIHRoZSBsaW5rIGFuZCBwYWlyaW5nIGlzIGZh
aWxlZC4NCg0KPiBBQ0wgRGF0YSBSWDogSGFuZGxlIDEyOCBmbGFncyAweDAyIGRsZW4gMjEgICAg
ICAgICAgICAgICAgICAgICAgICAgICAgICAgW2hjaTBdIDEyNC44MDEwOTgNCiAgICAgIFNNUDog
RW5jcnlwdGlvbiBJbmZvcm1hdGlvbiAoMHgwNikgbGVuIDE2DQogICAgICAgIExvbmcgdGVybSBr
ZXk6IDlhYzY5MWU5NmU4NWU4MmNhNjhmNGI2ZDJhYmVjODBmDQo+IEhDSSBFdmVudDogRW5jcnlw
dGlvbiBDaGFuZ2UgKDB4MDgpIHBsZW4gNCAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICBb
aGNpMF0gMTI0LjgwMTI2MQ0KICAgICAgICBTdGF0dXM6IFN1Y2Nlc3MgKDB4MDApDQogICAgICAg
IEhhbmRsZTogMTI4DQogICAgICAgIEVuY3J5cHRpb246IEVuYWJsZWQgd2l0aCBBRVMtQ0NNICgw
eDAxKQ0KPiBBQ0wgRGF0YSBSWDogSGFuZGxlIDEyOCBmbGFncyAweDAyIGRsZW4gMTUgICAgICAg
ICAgICAgICAgICAgICAgICAgICAgICAgW2hjaTBdIDEyNC44MTI3NjENCiAgICAgIFNNUDogTWFz
dGVyIElkZW50aWZpY2F0aW9uICgweDA3KSBsZW4gMTANCiAgICAgICAgRURJVjogMHhlYTNmDQog
ICAgICAgIFJhbmQ6IDB4ODA2ZTU0MmE3OGY1NWQ3Yw0KPiBBQ0wgRGF0YSBSWDogSGFuZGxlIDEy
OCBmbGFncyAweDAyIGRsZW4gMjEgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgW2hjaTBd
IDEyNC44MTI3ODINCiAgICAgIFNNUDogU2lnbmluZyBJbmZvcm1hdGlvbiAoMHgwYSkgbGVuIDE2
DQogICAgICAgIFNpZ25hdHVyZSBrZXk6IDQ0NTFiOGFlMGVmZjkwZjBhNDdmYjk2YmU1MzQ3OWZi
DQo+IEhDSSBFdmVudDogRGlzY29ubmVjdCBDb21wbGV0ZSAoMHgwNSkgcGxlbiA0ICAgICAgICAg
ICAgICAgICAgICAgICAgICAgICBbaGNpMF0gMTU0LjgzOTU5MQ0KICAgICAgICBTdGF0dXM6IFN1
Y2Nlc3MgKDB4MDApDQogICAgICAgIEhhbmRsZTogMTI4DQogICAgICAgIFJlYXNvbjogUmVtb3Rl
IFVzZXIgVGVybWluYXRlZCBDb25uZWN0aW9uICgweDEzKQ0KDQo9PiBBdCB0aGlzIHBvaW50LCBN
YXN0ZXIgc2hvdWxkIHN0YXJ0IHNlbmRpbmcgTFRLIHRvIHNsYXZlLCBidXQgTWFzdGVyIGRvZXNu
J3Qgc2VuZCB0aGUgTFRLIHNvIFNsYXZlIGRpc2Nvbm5lY3RzIHRoZSBsaW5rIGFuZCBwYWlyaW5n
IGlzIGZhaWxlZC4NCg0KV2hhdCBjb3VsZCBwb3NzaWJseSBjYXVzZSB0aGUgbWFzdGVyIHRvIG5v
dCBzZW5kIHRoZSBMVEs/IE15IGtlcm5lbCB2ZXJzaW9uIGlzIHY0LjEuMjcgYW5kIGJsdWV6IHN0
YWNrIGlzIHY1LjQwLiBJIHdvdWxkIGFwcHJlY2lhdGUgYWR2aWNlIG9uIHRoaXMuDQoNClRoYW5r
IHlvdS4NCg0Kfkpvc2h1YQ0K


2017-03-30 06:13:44

by Marcel Holtmann

[permalink] [raw]
Subject: Re: [EXT] Unexpected SMP Command 0x17

Hi Joshua,

>>>> Yes, for secure connection the LTK is generated locally.
>>>> But issue here is observed that after Pairing is complete the key
>>>> distribution is not completed from Master.
>>>>
>>>> i.e. After Slave sends the "Signature key:" but Master doesn't
>>>> share any key. Attached logs.
>>> I get that and that is clear from the logs. Something is stalling here
>>> and because of that, you run into the 30 seconds SMP timeout. We just
>>> need to know if the 4.9 kernel is doing this correctly. If so, then
>>> you can bi-sect that patch that fixes. Without proof that 4.9 is also
>>> broken, nobody will even bother to chase this down.
>>
>> I think the problem here is race between ACL data and HCI events on USB
>> dongle... We get initial slave keys but those get dropped due to encryption
>> changed event not being received yet. Since keys were silently dropped we later
>> on get unexpected SMP PDU and ignoring remaining keys as well which
>> eventually leads to SMP timeout.
>>
>> If this is USB dongle (using btusd) then only (AFAIK) solution would be to have a
>> workaround for this inside chip (it would delay ACL data received right after
>> encryption change giving host time to handle encpryption change event).
>> Bluetooth specification for USB transport is unfortunatelly kinda broken.
>>
>> --
>> pozdrawiam
>> Szymon Janc
>
> Thank you for your reply. Your inputs are valuable to us in helping to debug the issue. Yes, we are indeed using the btusb kernel module and it is using a USB interface (Bluetooth over USB).
>
> I noticed that when btmgmt settings are set to turn 'bredr off', the 'ssp' mode also turns off. Is this behavior expected to occur?
> My current settings are 'powered connectable discoverable bondable le secure-conn’

the SSP (Secure Simple Pairing) is a BR/EDR only feature. So when you disable BR/EDR, it will be disabled as well.

Regards

Marcel


2017-03-30 00:00:29

by Wong, Joshua Weng Onn

[permalink] [raw]
Subject: RE: [EXT] Re: Unexpected SMP Command 0x17

Hi Szymon,

> On Monday, 27 March 2017 16:55:05 CEST Marcel Holtmann wrote:
> > Hi Avinash,
> >
> > please also refrain from top posting.
> >
> > > Yes, for secure connection the LTK is generated locally.
> > > But issue here is observed that after Pairing is complete the key
> > > distribution is not completed from Master.
> > >
> > > i.e. After Slave sends the "Signature key:" but Master doesn't
> > > share any key. Attached logs.
> > I get that and that is clear from the logs. Something is stalling here
> > and because of that, you run into the 30 seconds SMP timeout. We just
> > need to know if the 4.9 kernel is doing this correctly. If so, then
> > you can bi-sect that patch that fixes. Without proof that 4.9 is also
> > broken, nobody will even bother to chase this down.
>=20
> I think the problem here is race between ACL data and HCI events on USB
> dongle... We get initial slave keys but those get dropped due to encrypt=
ion
> changed event not being received yet. Since keys were silently dropped we=
later
> on get unexpected SMP PDU and ignoring remaining keys as well which
> eventually leads to SMP timeout.
>=20
> If this is USB dongle (using btusd) then only (AFAIK) solution would be t=
o have a
> workaround for this inside chip (it would delay ACL data received right a=
fter
> encryption change giving host time to handle encpryption change event).
> Bluetooth specification for USB transport is unfortunatelly kinda broken.
>=20
> --
> pozdrawiam
> Szymon Janc

Thank you for your reply. Your inputs are valuable to us in helping to debu=
g the issue. Yes, we are indeed using the btusb kernel module and it is usi=
ng a USB interface (Bluetooth over USB).

I noticed that when btmgmt settings are set to turn 'bredr off', the 'ssp' =
mode also turns off. Is this behavior expected to occur?
My current settings are 'powered connectable discoverable bondable le secur=
e-conn'

Thank you.

Best regards,
Joshua



2017-03-27 15:08:17

by Szymon Janc

[permalink] [raw]
Subject: Re: [EXT] Re: Unexpected SMP Command 0x17

Hi,

On Monday, 27 March 2017 16:55:05 CEST Marcel Holtmann wrote:
> Hi Avinash,
>
> please also refrain from top posting.
>
> > Yes, for secure connection the LTK is generated locally.
> > But issue here is observed that after Pairing is complete the key
> > distribution is not completed from Master.
> >
> > i.e. After Slave sends the "Signature key:" but Master doesn't share any
> > key. Attached logs.
> I get that and that is clear from the logs. Something is stalling here and
> because of that, you run into the 30 seconds SMP timeout. We just need to
> know if the 4.9 kernel is doing this correctly. If so, then you can bi-sect
> that patch that fixes. Without proof that 4.9 is also broken, nobody will
> even bother to chase this down.

I think the problem here is race between ACL data and HCI events on USB
dongle... We get initial slave keys but those get dropped due to encryption
changed event not being received yet. Since keys were silently dropped we
later on get unexpected SMP PDU and ignoring remaining keys as well which
eventually leads to SMP timeout.

If this is USB dongle (using btusd) then only (AFAIK) solution would be to
have a workaround for this inside chip (it would delay ACL data received right
after encryption change giving host time to handle encpryption change event).
Bluetooth specification for USB transport is unfortunatelly kinda broken.

--
pozdrawiam
Szymon Janc

2017-03-27 14:55:05

by Marcel Holtmann

[permalink] [raw]
Subject: Re: [EXT] Re: Unexpected SMP Command 0x17

Hi Avinash,

please also refrain from top posting.

> Yes, for secure connection the LTK is generated locally.
> But issue here is observed that after Pairing is complete the key distribution is not completed from Master.
>
> i.e. After Slave sends the "Signature key:" but Master doesn't share any key. Attached logs.

I get that and that is clear from the logs. Something is stalling here and because of that, you run into the 30 seconds SMP timeout. We just need to know if the 4.9 kernel is doing this correctly. If so, then you can bi-sect that patch that fixes. Without proof that 4.9 is also broken, nobody will even bother to chase this down.

Regards

Marcel


2017-03-27 14:50:12

by Avinash Kadam

[permalink] [raw]
Subject: RE: [EXT] Re: Unexpected SMP Command 0x17

Thanks Marcel.
Yes, for secure connection the LTK is generated locally.
But issue here is observed that after Pairing is complete the key distribution is not completed from Master.

i.e. After Slave sends the "Signature key:" but Master doesn't share any key. Attached logs.

HI Joshua,

Please help to check with latest kernel and update.

--
Thanks,
Avinash K


-----Original Message-----
From: Marcel Holtmann [mailto:[email protected]]
Sent: 22 March 2017 13:06
To: Wong, Joshua Weng Onn <[email protected]>
Cc: Bluez mailing list <[email protected]>; Wong, Mun choy <[email protected]>; Zulqarnain, Adam <[email protected]>; Avinash Kadam <[email protected]>
Subject: [EXT] Re: Unexpected SMP Command 0x17

External Email

----------------------------------------------------------------------
Hi Joshua,

> I am seeing an error during the LE pairing process which makes the pairing to fail. I have two DUTs which uses the Marvell 88W8897.
> Here are my BT settings for both master and slave:
>
> Master:
> $ btmgmt info
> current settings: powered connectable discoverable bondable ssp br/edr le secure-conn
>
> Slave:
> $ btmgmt info
> Current settings: powered connectable bondable le advertising secure-conn
>
> When I initiate the pairing process from the master, I observed the message:
> "Bluetooth: hci0 unexpected SMP command 0x0a from 74:c6:3b:ab:68:ea"
>
> Where 74:c6:3b:ab:68:ea is the address of the slave device.
>
> In the btmon log of the master device, it is observed that after the Slave device has transmitted the keys, the Master does not transmit it. Hence, the Slave is not receiving the keys and thus disconnects the link and pairing is failed.
>
>> ACL Data RX: Handle 128 flags 0x02 dlen 21 [hci0] 124.801098
> SMP: Encryption Information (0x06) len 16
> Long term key: 9ac691e96e85e82ca68f4b6d2abec80f
>> HCI Event: Encryption Change (0x08) plen 4 [hci0] 124.801261
> Status: Success (0x00)
> Handle: 128
> Encryption: Enabled with AES-CCM (0x01)
>> ACL Data RX: Handle 128 flags 0x02 dlen 15 [hci0] 124.812761
> SMP: Master Identification (0x07) len 10
> EDIV: 0xea3f
> Rand: 0x806e542a78f55d7c
>> ACL Data RX: Handle 128 flags 0x02 dlen 21 [hci0] 124.812782
> SMP: Signing Information (0x0a) len 16
> Signature key: 4451b8ae0eff90f0a47fb96be53479fb
>> HCI Event: Disconnect Complete (0x05) plen 4 [hci0] 154.839591
> Status: Success (0x00)
> Handle: 128
> Reason: Remote User Terminated Connection (0x13)
>
> => At this point, Master should start sending LTK to slave, but Master doesn't send the LTK so Slave disconnects the link and pairing is failed.
>
> What could possibly cause the master to not send the LTK? My kernel version is v4.1.27 and bluez stack is v5.40. I would appreciate advice on this.

if this is LE Secure Connections, then the LTK is no longer distributed. It is being calculated from ECDH. Please include the complete SMP exchanges. Only then we can see what is going on.

Also keep in mind that 4.1.x kernels are actually rather old. The latest one is 4.10.x and if there is a bug, you should verify that it also happens with the latest kernel.

Regards

Marcel


Attachments:
secure-conn-on-master-log.txt (12.75 kB)
secure-conn-on-master-log.txt
secure-conn-on-slave-log.txt (12.90 kB)
secure-conn-on-slave-log.txt
Download all attachments

2017-03-22 07:36:22

by Marcel Holtmann

[permalink] [raw]
Subject: Re: Unexpected SMP Command 0x17

Hi Joshua,

> I am seeing an error during the LE pairing process which makes the pairing to fail. I have two DUTs which uses the Marvell 88W8897.
> Here are my BT settings for both master and slave:
>
> Master:
> $ btmgmt info
> current settings: powered connectable discoverable bondable ssp br/edr le secure-conn
>
> Slave:
> $ btmgmt info
> Current settings: powered connectable bondable le advertising secure-conn
>
> When I initiate the pairing process from the master, I observed the message:
> "Bluetooth: hci0 unexpected SMP command 0x0a from 74:c6:3b:ab:68:ea"
>
> Where 74:c6:3b:ab:68:ea is the address of the slave device.
>
> In the btmon log of the master device, it is observed that after the Slave device has transmitted the keys, the Master does not transmit it. Hence, the Slave is not receiving the keys and thus disconnects the link and pairing is failed.
>
>> ACL Data RX: Handle 128 flags 0x02 dlen 21 [hci0] 124.801098
> SMP: Encryption Information (0x06) len 16
> Long term key: 9ac691e96e85e82ca68f4b6d2abec80f
>> HCI Event: Encryption Change (0x08) plen 4 [hci0] 124.801261
> Status: Success (0x00)
> Handle: 128
> Encryption: Enabled with AES-CCM (0x01)
>> ACL Data RX: Handle 128 flags 0x02 dlen 15 [hci0] 124.812761
> SMP: Master Identification (0x07) len 10
> EDIV: 0xea3f
> Rand: 0x806e542a78f55d7c
>> ACL Data RX: Handle 128 flags 0x02 dlen 21 [hci0] 124.812782
> SMP: Signing Information (0x0a) len 16
> Signature key: 4451b8ae0eff90f0a47fb96be53479fb
>> HCI Event: Disconnect Complete (0x05) plen 4 [hci0] 154.839591
> Status: Success (0x00)
> Handle: 128
> Reason: Remote User Terminated Connection (0x13)
>
> => At this point, Master should start sending LTK to slave, but Master doesn't send the LTK so Slave disconnects the link and pairing is failed.
>
> What could possibly cause the master to not send the LTK? My kernel version is v4.1.27 and bluez stack is v5.40. I would appreciate advice on this.

if this is LE Secure Connections, then the LTK is no longer distributed. It is being calculated from ECDH. Please include the complete SMP exchanges. Only then we can see what is going on.

Also keep in mind that 4.1.x kernels are actually rather old. The latest one is 4.10.x and if there is a bug, you should verify that it also happens with the latest kernel.

Regards

Marcel