Hi,
I'm running Linux 5.4.32 and Bluez 5.54 on my embedded platform and use from my
application the DBus interface to set up the local GATT database and work with
remote services.
In one scenario, I have an agent registered and call as peripheral the
ReadValue method of a central's encrypted characteristic before pairing has
been done. This results in my agent implementation receiving a
RequestConfirmation call for pairing. I complete that agent's method call with
an org.bluez.Error.Rejected error and unregister my agent. The initial
ReadValue method call, though, is never completed - my application neither
receives a DBus method return or an error for that method call.
Instead, using btmon, I can see that internally, the read request is
continuously retried every ~1.2 seconds. Each time, there is an Insufficient
Authentication error, a Pairing Request, an immediate Authentication Failed,
and a Pairing Failed response.
I would have expected that after rejecting the first pairing request, the
ReadValue method call is completed with for example a
org.bluez.Error.NotAuthorized error, and not an uninterruptible loop.
These are the bluetoothd debug messages while in the loop:
bluetoothd[2370]: ../bluez-5.54/src/device.c:gatt_debug() Read By Type - start: 0x0001 end: 0x0005
bluetoothd[2370]: ../bluez-5.54/src/gatt-database.c:gap_device_name_read_cb() GAP Device Name read request
bluetoothd[2370]: ../bluez-5.54/src/adapter.c:bonding_attempt_complete() hci0 bdaddr 5A:2A:C3:75:E8:BB type 2 status 0x5
bluetoothd[2370]: ../bluez-5.54/src/device.c:device_bonding_complete() bonding (nil) status 0x05
bluetoothd[2370]: ../bluez-5.54/src/device.c:device_bonding_failed() status 5
bluetoothd[2370]: ../bluez-5.54/src/adapter.c:resume_discovery()
[pause, then repeat]
Here's an excerpt from the btmon log starting at the reject and showing the loop
@ MGMT Command: User Confirmation... (0x001d) plen 7 {0x0001} [hci0] 44.045329
LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
< ACL Data TX: Handle 1025 flags 0x00 dlen 6 #322 [hci0] 44.045373
SMP: Pairing Failed (0x05) len 1
Reason: Numeric comparison failed (0x0c)
@ MGMT Event: Authentication Failed (0x0011) plen 8 {0x0002} [hci0] 44.045400
LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
Status: Authentication Failed (0x05)
@ MGMT Event: Authentication Failed (0x0011) plen 8 {0x0001} [hci0] 44.045400
LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
Status: Authentication Failed (0x05)
@ MGMT Event: Command Complete (0x0001) plen 10 {0x0001} [hci0] 44.045426
User Confirmation Negative Reply (0x001d) plen 7
Status: Success (0x00)
LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
@ MGMT Command: Remove Advertising (0x003f) plen 1 {0x0001} [hci0] 44.052011
Instance: 2
@ MGMT Event: Advertising Removed (0x0024) plen 1 {0x0002} [hci0] 44.052029
Instance: 2
@ MGMT Event: Command Complete (0x0001) plen 4 {0x0001} [hci0] 44.052041
Remove Advertising (0x003f) plen 1
Status: Success (0x00)
Instance: 2
> HCI Event: Number of Completed Packets (0x13) plen 5 #323 [hci0] 44.190618
Num handles: 1
Handle: 1025
Count: 1
> ACL Data RX: Handle 1025 flags 0x02 dlen 11 #324 [hci0] 45.082137
ATT: Read By Type Request (0x08) len 6
Handle range: 0x0001-0x0005
Attribute type: Device Name (0x2a00)
< ACL Data TX: Handle 1025 flags 0x00 dlen 14 #325 [hci0] 45.084191
ATT: Read By Type Response (0x09) len 9
Attribute data length: 8
Attribute data list: 1 entry
Handle: 0x0003
Value: 663930307378
< ACL Data TX: Handle 1025 flags 0x00 dlen 7 #326 [hci0] 45.086693
ATT: Read Request (0x0a) len 2
Handle: 0x003b
> ACL Data RX: Handle 1025 flags 0x02 dlen 9 #327 [hci0] 45.141328
ATT: Error Response (0x01) len 4
Read Request (0x0a)
Handle: 0x003b
Error: Insufficient Authentication (0x05)
> HCI Event: Number of Completed Packets (0x13) plen 5 #328 [hci0] 45.141350
Num handles: 1
Handle: 1025
Count: 2
< ACL Data TX: Handle 1025 flags 0x00 dlen 6 #329 [hci0] 45.142787
SMP: Security Request (0x0b) len 1
Authentication requirement: Bonding, MITM, SC, No Keypresses, CT2 (0x2d)
> ACL Data RX: Handle 1025 flags 0x02 dlen 11 #330 [hci0] 45.201290
SMP: Pairing Request (0x01) len 6
IO capability: KeyboardDisplay (0x04)
OOB data: Authentication data not present (0x00)
Authentication requirement: Bonding, MITM, SC, No Keypresses, CT2 (0x2d)
Max encryption key size: 16
Initiator key distribution: EncKey IdKey LinkKey (0x0b)
Responder key distribution: EncKey IdKey LinkKey (0x0b)
@ MGMT Event: Authentication Failed (0x0011) plen 8 {0x0002} [hci0] 45.201455
LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
Status: Authentication Failed (0x05)
@ MGMT Event: Authentication Failed (0x0011) plen 8 {0x0001} [hci0] 45.201455
LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
Status: Authentication Failed (0x05)
< ACL Data TX: Handle 1025 flags 0x00 dlen 6 #331 [hci0] 45.201551
SMP: Pairing Failed (0x05) len 1
Reason: Pairing not supported (0x05)
> HCI Event: Number of Completed Packets (0x13) plen 5 #332 [hci0] 45.261239
Num handles: 1
Handle: 1025
Count: 2
[pause, then goto 45.082137]
Hi Kai,
On Tue, Apr 28, 2020 at 5:59 AM Kai Ruhnau <[email protected]> wrote:
>
> Hi,
>
> I'm running Linux 5.4.32 and Bluez 5.54 on my embedded platform and use from my
> application the DBus interface to set up the local GATT database and work with
> remote services.
>
> In one scenario, I have an agent registered and call as peripheral the
> ReadValue method of a central's encrypted characteristic before pairing has
> been done. This results in my agent implementation receiving a
> RequestConfirmation call for pairing. I complete that agent's method call with
> an org.bluez.Error.Rejected error and unregister my agent. The initial
> ReadValue method call, though, is never completed - my application neither
> receives a DBus method return or an error for that method call.
>
> Instead, using btmon, I can see that internally, the read request is
> continuously retried every ~1.2 seconds. Each time, there is an Insufficient
> Authentication error, a Pairing Request, an immediate Authentication Failed,
> and a Pairing Failed response.
>
> I would have expected that after rejecting the first pairing request, the
> ReadValue method call is completed with for example a
> org.bluez.Error.NotAuthorized error, and not an uninterruptible loop.
>
> These are the bluetoothd debug messages while in the loop:
> bluetoothd[2370]: ../bluez-5.54/src/device.c:gatt_debug() Read By Type - start: 0x0001 end: 0x0005
> bluetoothd[2370]: ../bluez-5.54/src/gatt-database.c:gap_device_name_read_cb() GAP Device Name read request
> bluetoothd[2370]: ../bluez-5.54/src/adapter.c:bonding_attempt_complete() hci0 bdaddr 5A:2A:C3:75:E8:BB type 2 status 0x5
> bluetoothd[2370]: ../bluez-5.54/src/device.c:device_bonding_complete() bonding (nil) status 0x05
> bluetoothd[2370]: ../bluez-5.54/src/device.c:device_bonding_failed() status 5
> bluetoothd[2370]: ../bluez-5.54/src/adapter.c:resume_discovery()
> [pause, then repeat]
>
>
> Here's an excerpt from the btmon log starting at the reject and showing the loop
>
> @ MGMT Command: User Confirmation... (0x001d) plen 7 {0x0001} [hci0] 44.045329
> LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
> < ACL Data TX: Handle 1025 flags 0x00 dlen 6 #322 [hci0] 44.045373
> SMP: Pairing Failed (0x05) len 1
> Reason: Numeric comparison failed (0x0c)
> @ MGMT Event: Authentication Failed (0x0011) plen 8 {0x0002} [hci0] 44.045400
> LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
> Status: Authentication Failed (0x05)
> @ MGMT Event: Authentication Failed (0x0011) plen 8 {0x0001} [hci0] 44.045400
> LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
> Status: Authentication Failed (0x05)
> @ MGMT Event: Command Complete (0x0001) plen 10 {0x0001} [hci0] 44.045426
> User Confirmation Negative Reply (0x001d) plen 7
> Status: Success (0x00)
> LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
> @ MGMT Command: Remove Advertising (0x003f) plen 1 {0x0001} [hci0] 44.052011
> Instance: 2
> @ MGMT Event: Advertising Removed (0x0024) plen 1 {0x0002} [hci0] 44.052029
> Instance: 2
> @ MGMT Event: Command Complete (0x0001) plen 4 {0x0001} [hci0] 44.052041
> Remove Advertising (0x003f) plen 1
> Status: Success (0x00)
> Instance: 2
> > HCI Event: Number of Completed Packets (0x13) plen 5 #323 [hci0] 44.190618
> Num handles: 1
> Handle: 1025
> Count: 1
> > ACL Data RX: Handle 1025 flags 0x02 dlen 11 #324 [hci0] 45.082137
> ATT: Read By Type Request (0x08) len 6
> Handle range: 0x0001-0x0005
> Attribute type: Device Name (0x2a00)
> < ACL Data TX: Handle 1025 flags 0x00 dlen 14 #325 [hci0] 45.084191
> ATT: Read By Type Response (0x09) len 9
> Attribute data length: 8
> Attribute data list: 1 entry
> Handle: 0x0003
> Value: 663930307378
> < ACL Data TX: Handle 1025 flags 0x00 dlen 7 #326 [hci0] 45.086693
> ATT: Read Request (0x0a) len 2
> Handle: 0x003b
> > ACL Data RX: Handle 1025 flags 0x02 dlen 9 #327 [hci0] 45.141328
> ATT: Error Response (0x01) len 4
> Read Request (0x0a)
> Handle: 0x003b
> Error: Insufficient Authentication (0x05)
> > HCI Event: Number of Completed Packets (0x13) plen 5 #328 [hci0] 45.141350
> Num handles: 1
> Handle: 1025
> Count: 2
> < ACL Data TX: Handle 1025 flags 0x00 dlen 6 #329 [hci0] 45.142787
> SMP: Security Request (0x0b) len 1
> Authentication requirement: Bonding, MITM, SC, No Keypresses, CT2 (0x2d)
> > ACL Data RX: Handle 1025 flags 0x02 dlen 11 #330 [hci0] 45.201290
> SMP: Pairing Request (0x01) len 6
> IO capability: KeyboardDisplay (0x04)
> OOB data: Authentication data not present (0x00)
> Authentication requirement: Bonding, MITM, SC, No Keypresses, CT2 (0x2d)
> Max encryption key size: 16
> Initiator key distribution: EncKey IdKey LinkKey (0x0b)
> Responder key distribution: EncKey IdKey LinkKey (0x0b)
> @ MGMT Event: Authentication Failed (0x0011) plen 8 {0x0002} [hci0] 45.201455
> LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
> Status: Authentication Failed (0x05)
> @ MGMT Event: Authentication Failed (0x0011) plen 8 {0x0001} [hci0] 45.201455
> LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
> Status: Authentication Failed (0x05)
> < ACL Data TX: Handle 1025 flags 0x00 dlen 6 #331 [hci0] 45.201551
> SMP: Pairing Failed (0x05) len 1
> Reason: Pairing not supported (0x05)
> > HCI Event: Number of Completed Packets (0x13) plen 5 #332 [hci0] 45.261239
> Num handles: 1
> Handle: 1025
> Count: 2
> [pause, then goto 45.082137]
Interresting, I think originally the kernel would disconnect if the
pairing fails but perhaps that is no longer the case so we keep
retrying, will have a look what can be done regarding this.
--
Luiz Augusto von Dentz
Hi,
Luiz Augusto von Dentz wrote:
> Hi Kai,
>
> On Tue, Apr 28, 2020 at 5:59 AM Kai Ruhnau <[email protected]> wrote:
>>
>> Hi,
>>
>> I'm running Linux 5.4.32 and Bluez 5.54 on my embedded platform and use from my
>> application the DBus interface to set up the local GATT database and work with
>> remote services.
>>
>> In one scenario, I have an agent registered and call as peripheral the
>> ReadValue method of a central's encrypted characteristic before pairing has
>> been done. This results in my agent implementation receiving a
>> RequestConfirmation call for pairing. I complete that agent's method call with
>> an org.bluez.Error.Rejected error and unregister my agent. The initial
>> ReadValue method call, though, is never completed - my application neither
>> receives a DBus method return or an error for that method call.
>>
>> Instead, using btmon, I can see that internally, the read request is
>> continuously retried every ~1.2 seconds. Each time, there is an Insufficient
>> Authentication error, a Pairing Request, an immediate Authentication Failed,
>> and a Pairing Failed response.
>>
>> I would have expected that after rejecting the first pairing request, the
>> ReadValue method call is completed with for example a
>> org.bluez.Error.NotAuthorized error, and not an uninterruptible loop.
>>
>> These are the bluetoothd debug messages while in the loop:
>> bluetoothd[2370]: ../bluez-5.54/src/device.c:gatt_debug() Read By Type - start: 0x0001 end: 0x0005
>> bluetoothd[2370]: ../bluez-5.54/src/gatt-database.c:gap_device_name_read_cb() GAP Device Name read request
>> bluetoothd[2370]: ../bluez-5.54/src/adapter.c:bonding_attempt_complete() hci0 bdaddr 5A:2A:C3:75:E8:BB type 2 status 0x5
>> bluetoothd[2370]: ../bluez-5.54/src/device.c:device_bonding_complete() bonding (nil) status 0x05
>> bluetoothd[2370]: ../bluez-5.54/src/device.c:device_bonding_failed() status 5
>> bluetoothd[2370]: ../bluez-5.54/src/adapter.c:resume_discovery()
>> [pause, then repeat]
>>
>>
>> Here's an excerpt from the btmon log starting at the reject and showing the loop
>>
>> @ MGMT Command: User Confirmation... (0x001d) plen 7 {0x0001} [hci0] 44.045329
>> LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
>> < ACL Data TX: Handle 1025 flags 0x00 dlen 6 #322 [hci0] 44.045373
>> SMP: Pairing Failed (0x05) len 1
>> Reason: Numeric comparison failed (0x0c)
>> @ MGMT Event: Authentication Failed (0x0011) plen 8 {0x0002} [hci0] 44.045400
>> LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
>> Status: Authentication Failed (0x05)
>> @ MGMT Event: Authentication Failed (0x0011) plen 8 {0x0001} [hci0] 44.045400
>> LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
>> Status: Authentication Failed (0x05)
>> @ MGMT Event: Command Complete (0x0001) plen 10 {0x0001} [hci0] 44.045426
>> User Confirmation Negative Reply (0x001d) plen 7
>> Status: Success (0x00)
>> LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
>> @ MGMT Command: Remove Advertising (0x003f) plen 1 {0x0001} [hci0] 44.052011
>> Instance: 2
>> @ MGMT Event: Advertising Removed (0x0024) plen 1 {0x0002} [hci0] 44.052029
>> Instance: 2
>> @ MGMT Event: Command Complete (0x0001) plen 4 {0x0001} [hci0] 44.052041
>> Remove Advertising (0x003f) plen 1
>> Status: Success (0x00)
>> Instance: 2
>> > HCI Event: Number of Completed Packets (0x13) plen 5 #323 [hci0] 44.190618
>> Num handles: 1
>> Handle: 1025
>> Count: 1
>> > ACL Data RX: Handle 1025 flags 0x02 dlen 11 #324 [hci0] 45.082137
>> ATT: Read By Type Request (0x08) len 6
>> Handle range: 0x0001-0x0005
>> Attribute type: Device Name (0x2a00)
>> < ACL Data TX: Handle 1025 flags 0x00 dlen 14 #325 [hci0] 45.084191
>> ATT: Read By Type Response (0x09) len 9
>> Attribute data length: 8
>> Attribute data list: 1 entry
>> Handle: 0x0003
>> Value: 663930307378
>> < ACL Data TX: Handle 1025 flags 0x00 dlen 7 #326 [hci0] 45.086693
>> ATT: Read Request (0x0a) len 2
>> Handle: 0x003b
>> > ACL Data RX: Handle 1025 flags 0x02 dlen 9 #327 [hci0] 45.141328
>> ATT: Error Response (0x01) len 4
>> Read Request (0x0a)
>> Handle: 0x003b
>> Error: Insufficient Authentication (0x05)
>> > HCI Event: Number of Completed Packets (0x13) plen 5 #328 [hci0] 45.141350
>> Num handles: 1
>> Handle: 1025
>> Count: 2
>> < ACL Data TX: Handle 1025 flags 0x00 dlen 6 #329 [hci0] 45.142787
>> SMP: Security Request (0x0b) len 1
>> Authentication requirement: Bonding, MITM, SC, No Keypresses, CT2 (0x2d)
>> > ACL Data RX: Handle 1025 flags 0x02 dlen 11 #330 [hci0] 45.201290
>> SMP: Pairing Request (0x01) len 6
>> IO capability: KeyboardDisplay (0x04)
>> OOB data: Authentication data not present (0x00)
>> Authentication requirement: Bonding, MITM, SC, No Keypresses, CT2 (0x2d)
>> Max encryption key size: 16
>> Initiator key distribution: EncKey IdKey LinkKey (0x0b)
>> Responder key distribution: EncKey IdKey LinkKey (0x0b)
>> @ MGMT Event: Authentication Failed (0x0011) plen 8 {0x0002} [hci0] 45.201455
>> LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
>> Status: Authentication Failed (0x05)
>> @ MGMT Event: Authentication Failed (0x0011) plen 8 {0x0001} [hci0] 45.201455
>> LE Address: 4E:FE:AC:7A:F8:93 (Resolvable)
>> Status: Authentication Failed (0x05)
>> < ACL Data TX: Handle 1025 flags 0x00 dlen 6 #331 [hci0] 45.201551
>> SMP: Pairing Failed (0x05) len 1
>> Reason: Pairing not supported (0x05)
>> > HCI Event: Number of Completed Packets (0x13) plen 5 #332 [hci0] 45.261239
>> Num handles: 1
>> Handle: 1025
>> Count: 2
>> [pause, then goto 45.082137]
>
> Interresting, I think originally the kernel would disconnect if the
> pairing fails but perhaps that is no longer the case so we keep
> retrying, will have a look what can be done regarding this.
I have added Disconnect'ing the device after sending the rejection to my
application. This does stop all the HCI traffic, but still the method call
does not return. Currently I'm just piling up the small allocations for
the code expecting the method return and I don't see that this could
become an issue further down. Would be nice if Bluez followed the DBus
rules, though :)
Cheers,
Kai