Regression in service discovery

[timokroeger]

WebBluetooth API cannot connect to devices running trouble from main branch.
I have tested this with different windows machines running edge browser.

Connection failed: NetworkError: Failed to execute 'getPrimaryService' on 'BluetoothRemoteGATTServer': GATT Server is disconnected. Cannot retrieve services. (Re)connect first with `device.gatt.connect`.

When I revert #446 the service discovery works again.

During debugging I also found that handle alignement logic is not required:

trouble/host/src/attribute.rs

Lines 625 to 626 in ed3e223

	// Jump to next 16-aligned
	self.table.handle = self.table.handle + (0x10 - (self.table.handle % 0x10));

Simply incrementing the handle works just aswell.
Is there a reason we do the 16-alignment? If not I’ll open a pull request for it.

[lulf]

@iwanders What do you think?

[iwanders]

Thanks for reporting this @timokroeger. I wonder if the new logic is incorrectly handling the case you encountered? If it was broken in all cases I'd expect we would've heard about it earlier and CI shouldn't have passed.

The primary service discovery is described here in the spec, we should verify that the output of the function matches that. I presume the actual problem is in handle_read_by_group_type_req (87fecaa) since the primary service is a group type? Any chance you could uncomment the debug! macro's in it and see if that leads to any immediate discoveries.

Ideally we'd somehow reproduce this in a unit test, could be something similar to this here, but I'm not sure how intricate your gattt server is @timokroeger.

[timokroeger]

My devices GATT server:

There is one custom service which contains 8 characteristics. All of them use a 128bit long UUID (truncated to a short UUID in the screenshot)

Log output:

50.930786 [INFO ] [ble] connected (ioutble firmware/src/ble.rs:193)
51.038513 [DEBUG] exchange_att_mtu: 527, current default: 247 (trouble_host host/src/connection_manager.rs:520)
51.038604 [INFO ] [host] agreed att MTU of 247 (trouble_host host/src/host.rs:454)
51.338806 [DEBUG] [read_by_group] found! Uuid16([0, 28]) handle: 1 (trouble_host host/src/attribute_server.rs:528)
51.338897 [DEBUG] [read_by_group] found first entry Uuid16([0, 28]), handle 1 (trouble_host host/src/attribute_server.rs:537)
51.339019 [DEBUG] [read_by_group] found! Uuid16([0, 28]) handle: 16 (trouble_host host/src/attribute_server.rs:528)
51.339111 [DEBUG] [read_by_group] found equal length 2, handle 16 (trouble_host host/src/attribute_server.rs:544)
51.339202 [DEBUG] [read_by_group] found! Uuid16([0, 28]) handle: 32 (trouble_host host/src/attribute_server.rs:528)
51.339294 [DEBUG] [read_by_group] different length: 16, old: 2 (trouble_host host/src/attribute_server.rs:548)
51.458831 [DEBUG] [read_by_group] found! Uuid16([0, 28]) handle: 32 (trouble_host host/src/attribute_server.rs:528)
51.458953 [DEBUG] [read_by_group] found first entry Uuid16([0, 28]), handle 32 (trouble_host host/src/attribute_server.rs:537)
51.699066 [DEBUG] [ble] connection params updated: conn_interval=Duration { ticks: 451 }, peripheral_latency=0, supervision_timeout=Duration { ticks: 314573 } (ioutble firmware/src/ble.rs:341)
51.785095 [DEBUG] [read_by_type] found first entry Uuid16([3, 28]), handle 2 (trouble_host host/src/attribute_server.rs:457)
51.785217 [DEBUG] [read_by_type] found equal length 5, handle 4 (trouble_host host/src/attribute_server.rs:464)
51.936340 [DEBUG] [read_by_group] found! Uuid16([0, 28]) handle: 1 (trouble_host host/src/attribute_server.rs:528)
51.936462 [DEBUG] [read_by_group] found first entry Uuid16([0, 28]), handle 1 (trouble_host host/src/attribute_server.rs:537)
51.936553 [DEBUG] [read_by_group] found! Uuid16([0, 28]) handle: 16 (trouble_host host/src/attribute_server.rs:528)
51.936676 [DEBUG] [read_by_group] found equal length 2, handle 16 (trouble_host host/src/attribute_server.rs:544)
51.936737 [DEBUG] [read_by_group] found! Uuid16([0, 28]) handle: 32 (trouble_host host/src/attribute_server.rs:528)
51.936859 [DEBUG] [read_by_group] different length: 16, old: 2 (trouble_host host/src/attribute_server.rs:548)
51.963867 [DEBUG] [read_by_group] found! Uuid16([0, 28]) handle: 32 (trouble_host host/src/attribute_server.rs:528)
51.963958 [DEBUG] [read_by_group] found first entry Uuid16([0, 28]), handle 32 (trouble_host host/src/attribute_server.rs:537)
52.087585 [DEBUG] [read_by_type] found first entry Uuid16([3, 28]), handle 17 (trouble_host host/src/attribute_server.rs:457)
52.087707 [DEBUG] [read_by_type] found equal length 5, handle 19 (trouble_host host/src/attribute_server.rs:464)
52.156372 [DEBUG] [read_by_type] found first entry Uuid16([3, 28]), handle 33 (trouble_host host/src/attribute_server.rs:457)
52.156494 [DEBUG] [read_by_type] found equal length 19, handle 36 (trouble_host host/src/attribute_server.rs:464)
52.156585 [DEBUG] [read_by_type] found equal length 19, handle 39 (trouble_host host/src/attribute_server.rs:464)
52.156677 [DEBUG] [read_by_type] found equal length 19, handle 42 (trouble_host host/src/attribute_server.rs:464)
52.156768 [DEBUG] [read_by_type] found equal length 19, handle 45 (trouble_host host/src/attribute_server.rs:464)
52.156860 [DEBUG] [read_by_type] found equal length 19, handle 48 (trouble_host host/src/attribute_server.rs:464)
52.156951 [DEBUG] [read_by_type] found equal length 19, handle 51 (trouble_host host/src/attribute_server.rs:464)
52.157012 [DEBUG] [read_by_type] found equal length 19, handle 54 (trouble_host host/src/attribute_server.rs:464)
52.157104 [DEBUG] [read_by_type] found equal length 19, handle 57 (trouble_host host/src/attribute_server.rs:464)
52.157196 [DEBUG] [read_by_type] found equal length 19, handle 60 (trouble_host host/src/attribute_server.rs:464)

I tested some more and handle_read_by_group_type_req() appears to be working.
The changes to handle_read_by_type_req() are what breaks the discovery process.

[timokroeger]

Found the issue, my softdevice controllers transmit buffers were configured to 27bytes size.
The improved implementation (which is working correctly) produces responses larger than that.
I still have to figure out the exact interaction between the controllers buffer sizes, hosts package pool MTU and ATT_MTU.

[timokroeger]

Another update:
On the controlled side I had configured 3 tx buffers of size 27bytes.
trouble as host requests 216 bytes (the size of the reply for my service configuration).
We get stuck because the controller never gives back the requested number of buffers.

Solution: Increase the total controller buffer size to be larger than the biggest reply. In my case I bumbed the x buffer count to 10 (for a total of 270 bytes).

Closing this issue as the problem was in an unrelated code path. The improvements just made my improprely configured buffer sizes visible.

[iwanders]

Whew, okay, that's good news. Hopefully the increased buffer size can be accommodated in your usecase, it should be a small price to pay for the reduction in roundtrip messages during the service discovery.

Unfortunate the failure mode did not immediately indicate the problem. I'm not too sure how all the buffers are handled in trouble so I can't really comment on how to improve the handling of this particular failure.