Received-SPF: pass (google.com: domain of linux-bluetooth-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
MIME-Version: 1.0
References: <AM0PR02MB3841479A0B2378DF0B0109AAC5AC0@AM0PR02MB3841.eurprd02.prod.outlook.com>
In-Reply-To: <AM0PR02MB3841479A0B2378DF0B0109AAC5AC0@AM0PR02MB3841.eurprd02.prod.outlook.com>
From:   Luiz Augusto von Dentz <luiz.dentz@gmail.com>
Date:   Wed, 29 Apr 2020 11:59:51 -0700
Message-ID: <CABBYNZ+7_N27=2_t1ZjVtmTvoqAv_PB67A+Or_hp_XrS4tqnNw@mail.gmail.com>
Subject: Re: Characteristic ReadValue / WriteValue never finish
To:     Kai Ruhnau <kai.ruhnau@target-sg.com>
Cc:     "linux-bluetooth@vger.kernel.org" <linux-bluetooth@vger.kernel.org>
Content-Type: text/plain; charset="UTF-8"
Sender: linux-bluetooth-owner@vger.kernel.org
Precedence: bulk

Hi Kai,

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