Hi Kai,
On Tue, Apr 28, 2020 at 5:59 AM Kai Ruhnau <kai.ruhnau@xxxxxxxxxxxxx> 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
