BTLE Fundamentals - Lesson 6, Exercise 2 - LL_PHY_REQ response is 2 LL_REJECT_EXT_IND and then nothing, however COM logging on the app indicates success

[robbsadler]

I am working through BTLE Fundamentals, Lesson 6, Exercise 2, and running the code from blefund_less3_exer2 per the instructions and it all looks good on the app COM log:

*** Booting nRF Connect SDK v3.5.99-ncs1-1 ***
[00:00:00.000,274] <inf> Lesson3_Exercise2: Starting Lesson 3 - Exercise 2

[00:00:00.000,671] <inf> bt_sdc_hci_driver: SoftDevice Controller build revision:
36 f0 e5 0e 87 68 48 fb 02 fd 9f 82 cc 32 e5 7b |6....hH. .....2.{
91 b1 5c ed |..\.
[00:00:00.002,593] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.002,624] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
[00:00:00.002,655] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 54.58864 Build 1214809870
[00:00:00.003,540] <inf> bt_hci_core: Identity: EA:F7:95:23:3C:04 (random)
[00:00:00.003,570] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x118f, manufacturer 0x0059
[00:00:00.003,601] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0x118f
[00:00:00.003,601] <inf> Lesson3_Exercise2: Bluetooth initialized
[00:00:00.004,486] <inf> Lesson3_Exercise2: Advertising successfully started
[00:00:15.846,984] <inf> Lesson3_Exercise2: Connected
[00:00:15.847,015] <inf> Lesson3_Exercise2: Connection parameters: interval 45.00 ms, latency 0 intervals, timeout 5000 ms
[00:00:15.915,740] <inf> Lesson3_Exercise2: MTU exchange successful
[00:00:15.915,771] <inf> Lesson3_Exercise2: New MTU: 244 bytes
[00:00:16.050,872] <inf> Lesson3_Exercise2: Data length updated. Length 251/27 bytes, time 2120/328 us
[00:00:16.275,756] <inf> Lesson3_Exercise2: PHY updated. New PHY: 1M
[00:00:16.501,007] <inf> Lesson3_Exercise2: Connection parameters updated: interval 7.50 ms, latency 0 intervals, timeout 5000 ms
[00:00:16.755,737] <inf> Lesson3_Exercise2: Connection parameters updated: interval 45.00 ms, latency 0 intervals, timeout 5000 ms
[00:00:21.270,660] <inf> Lesson3_Exercise2: Connection parameters updated: interval 1000.00 ms, latency 0 intervals, timeout 4000 ms

But in the sniffer output, I'm getting an error in response to the LL_PHY_REQ, and I have retried it many times:

Time	Source	Protocol	Length	Flags	Channel Index	Delta time (start to start)	RSSI	Info
1472.562202	Slave_0xd2f6322c	LE LL	29	0x01	31	326µs	-26 dBm	Control Opcode: LL_PHY_REQ
1472.607106	Slave_0xd2f6322c	ATT	52	0x01	26	230µs	-23 dBm	Rcvd Read By Group Type Response, Attribute List Length: 1, Unknown
1472.607544	Master_0xd2f6322c	LE LL	29	0x03	26	438µs	-45 dBm	Control Opcode: LL_REJECT_EXT_IND
1472.651875	Master_0xd2f6322c	LE LL	29	0x03	30	44331µs	-42 dBm	Control Opcode: LL_REJECT_EXT_IND

I was trying to see if there was something I was missing, and ran into the definition of the 0x2a Different Transaction Collision error. It looks like you should wait for a response before sending out another request, and the exercise code doesn't do that. One comment I found mentioned that starting another request while one is in process is a spec violation. So I'm wondering if this is generally true for all requests, and for guidance on how best to accomplish this.

I modified the code as follows add a 1 sec sleep before the next request, and it eliminated the collision:

	/* STEP 7.2 - Update the PHY mode */
	update_phy(my_conn);

	// wait for a second - RLS
	k_sleep(K_MSEC(1000));

	/* STEP 13.5 - Update the data length and MTU */
	update_data_length(my_conn);
	update_mtu(my_conn);

So it looks like that may be something missing in the exercise, and I might want to send these async requests out awaiting the previous one to complete. 

Can anyone comment on best practices for doing this?

I am not new to async programming or to C, but this is my first time around BTLE programming.

[Edvin]

Hello,

Is it possible to upload the sniffer trace that you pasted some snippets from? 

Best regards,

Edvin

[robbsadler]

I can probably repro - it was a very consistent situation for my setup. I'll get you the trace when I get set up (on the road currently).

[Edvin]

That would be great. You see, I am not able to reproduce it, but I also see that my phone also requests some of these updates before the nRF has had the chance to do so, and therefore, the request is not physically sent, and hence no collission.

I could of course write a central sample that doesn't actively request any of these updates, but if you already have a setup that can replicate the issue, that would be great. To be honest, I am surprised that the BT stack didn't throw an error if it is doing an illegal operation. Since this is the case, it would be nice to have a sniffer trace to point to.

Can you please also specify what version of NCS you are using? And you didn't specifically choose the Zephyr Bluetooth controller? (if you don't know what I am talking about, then you probably didn't. The default controller is the SoftDevice Controller from Nordic).

Best regards,

Edvin

[robbsadler]

Okay, that took me a bit cause of some non-related interruptions. Here you go...BTLE_L6E2_Getting_LL_REJECT_EXT_IND_CollisionError.pcapng

Hopefully that is the format you need.

[Edvin]

Hello,

Sorry for the late reply.

What are you using as your BLE central? A phone? Computer? Another nRF? 

Have you tried another central, to see if the issue persists?

I find it strange that the central/master replies with "Different Transaction Collision", because it doesn't look like this is actually the case. Each device can have one Link Layer operation ongoing at once, but the previous LL transaction initiated from the peripheral is done (initiated in packet 6524 and response in packet 6528).

Therefore, without knowing more, I would say that it looks like it is the central that is misbehaving with an incorrect "Different Transaction Collision" reply. 

Best regards,

Edvin

[robbsadler]

I was running the device under test and the sniffer were both running on nRF52840-DK boards. I have moved on, so maybe we can just leave it be. I did think it strange that the request seemed successful while an error was reported. I'm not overly concerned, but just wanted to let you know it happened.

Thanks for taking a look!

[Gmrck]

Just to inform, that I experience exactly the same behaviour, as the original author of this post. The LL_PHY_REQ never gets its UPDATE in the wireshark, I see the same collision errors and LL_REJECT_EXT_IND and the peripheral outputs, that the selected PHY is 1M.

The setup:
Peripheral - 52840DK v3
Sniffer - 52840 Dongle v3
Central - Android phone with nrf Connect Mobile application