bluez / bluez

Main BlueZ tree
https://bluez.github.io/bluez/
GNU General Public License v2.0
754 stars 276 forks source link

Bluetooth Low Energy connection is terminated with connection timedout with isotest tool #860

Open SanaAnjaneyulu opened 5 months ago

SanaAnjaneyulu commented 5 months ago

I was using isotest utility to test ISO data transfer between two devices. With SDU interval 2500us, BLE connection is terminated with connection timedout error. This issue is inconsistent but observed few times.

I have attached bluez, btmon and wireshark logs from both source and sink. btd_sdu_2500us_sink.txt btd_sdu_2500us_src.txt btmon_logs_isotest_sdu_2500_sink.txt btmon_logs_isotest_sdu_2500_src.txt wireshark_logs.zip

Controller : Intel AX210 OS : Ubuntu 22.04 Bluez: 5.72

Could you please check the logs and let me know how can I fix this ?

Vudentz commented 5 months ago

I was using isotest utility to test ISO data transfer between two devices. With SDU interval 2500us, BLE connection is terminated with connection timedout error. This issue is inconsistent but observed few times.

I have attached bluez, btmon and wireshark logs from both source and sink. btd_sdu_2500us_sink.txt btd_sdu_2500us_src.txt btmon_logs_isotest_sdu_2500_sink.txt btmon_logs_isotest_sdu_2500_src.txt wireshark_logs.zip

Controller : Intel AX210 OS : Ubuntu 22.04 Bluez: 5.72

Could you please check the logs and let me know how can I fix this ?

Might need to double check but I don't think it is possible to have SDU interval of 2.5ms, in practice the minimal is 5ms if I recall correctly and even that is really going to be pushing the controller scheduler to the limit which I believe is what you are experiencing here.

SanaAnjaneyulu commented 5 months ago

Thanks for the quick response.

I experimented around rate control implemented in https://github.com/bluez/bluez/blob/master/tools/isotest.c here. If I commented out line numbers 901 and 902, connection works with SDU interval 2500us as well.

Is the restriction of 5ms SDU interval imposed by controllers?

Vudentz commented 5 months ago

Thanks for the quick response.

I experimented around rate control implemented in master/tools/isotest.c here. If I commented out line numbers 901 and 902, connection works with SDU interval 2500us as well.

Is the restriction of 5ms SDU interval imposed by controllers?

That is because the rate that the controller is using is not actually 2.5ms, the establish event comes around with a different interval so the rates don't really match.

Vudentz commented 5 months ago

@SanaAnjaneyulu what kernel version are you running btw?

SanaAnjaneyulu commented 5 months ago

On BLE source device: $ uname -r 6.5.0-17-generic

On BLE sink device: $ uname -r 6.5.0-35-generic

SanaAnjaneyulu commented 5 months ago

Hi @Vudentz ,

I went through the wireshark captures on source for both cases. I observed that in case where rate control is present, one ISO packet is sent per 10ms (ISO interval) even though SDU interval is 2.5ms. In case of no rate control, 4 ISO packets are sent per one ISO interval(10ms).

CIG parameters with rate control CIG_Params_1

CIG parameters without rate control CIG_Params_2

CIS parameters with rate control

CIS_Params_1

CIS parameters without rate control CIS_Params_2

ISO packet streaming with rate control ISO_Data_Streaming_1

ISO packet streaming without rate control

ISO_Data_Streaming_2

Wireshark captures without rate control.

wireshark_logs_no_ratecontrol.zip

Could you please check this?

Vudentz commented 5 months ago

@SanaAnjaneyulu not really sure I follow what do you mean by rate control? Perhaps you want to share if you have a diff or something, there seems to be a problem with how we do interpret the SDU interval since we are overwritting it with ISO Interval we got from CIS establish which is not quite right and will result in number of packets per interval to be 1.

Vudentz commented 5 months ago

@SanaAnjaneyulu https://github.com/bluez/bluez/issues/823#issuecomment-2069975826 so that might explain why this are not quite right with this sort of interval.

Vudentz commented 5 months ago
SDU_Interval = (CIG_Sync_Delay + (FT) x ISO_Interval) - Transport_Latency
SDU_Interval = (5480us + 1 x 10000us) - 12980
SDU_Interval = 2500us

Ok, so looks like we need to fix this in the kernel.

Vudentz commented 5 months ago

@SanaAnjaneyulu can you try with the following changes:

https://patchwork.kernel.org/project/bluetooth/patch/20240606162917.621031-1-luiz.dentz@gmail.com/

SanaAnjaneyulu commented 5 months ago

@SanaAnjaneyulu not really sure I follow what do you mean by rate control? Perhaps you want to share if you have a diff or something, there seems to be a problem with how we do interpret the SDU interval since we are overwritting it with ISO Interval we got from CIS establish which is not quite right and will result in number of packets per interval to be 1.

Here is the patch how i disabled rate control in isotest.c rate_control.patch

SanaAnjaneyulu commented 5 months ago

@SanaAnjaneyulu can you try with the following changes:

https://patchwork.kernel.org/project/bluetooth/patch/20240606162917.621031-1-luiz.dentz@gmail.com/

Thanks for the quick reply. I will test with this patch and let you know the outcome.

Vudentz commented 5 months ago

Fixed by https://github.com/bluez/bluetooth-next/commit/9b70755997d372a80928faf90fd5ea4a637b90ac

SanaAnjaneyulu commented 4 months ago

I was using isotest utility to test ISO data transfer between two devices. With SDU interval 2500us, BLE connection is terminated with connection timedout error. This issue is inconsistent but observed few times. I have attached bluez, btmon and wireshark logs from both source and sink. btd_sdu_2500us_sink.txt btd_sdu_2500us_src.txt btmon_logs_isotest_sdu_2500_sink.txt btmon_logs_isotest_sdu_2500_src.txt wireshark_logs.zip Controller : Intel AX210 OS : Ubuntu 22.04 Bluez: 5.72 Could you please check the logs and let me know how can I fix this ?

Might need to double check but I don't think it is possible to have SDU interval of 2.5ms, in practice the minimal is 5ms if I recall correctly and even that is really going to be pushing the controller scheduler to the limit which I believe is what you are experiencing here.

Hi @Vudentz ,

Just as a clarification, 2.5ms is the SDU interval I'm experimenting with. I am not testing this with LC3.

SanaAnjaneyulu commented 4 months ago

@SanaAnjaneyulu can you try with the following changes:

https://patchwork.kernel.org/project/bluetooth/patch/20240606162917.621031-1-luiz.dentz@gmail.com/

HI @Vudentz ,

Is there a way that I can confirm that the patch is applied to the linux kernel ? system logs or kernel logs?

I applied this patch with 6.5.0, I am still observing the same behaviour. When applied this patch to 6.5.1 and loaded, it didn't boot.

Any thoughts?

Thanks in advance.

Regards, Sana

Vudentz commented 4 months ago

@SanaAnjaneyulu can you try with the following changes: patchwork.kernel.org/project/bluetooth/patch/20240606162917.621031-1-luiz.dentz@gmail.com

HI @Vudentz ,

Is there a way that I can confirm that the patch is applied to the linux kernel ? system logs or kernel logs?

I applied this patch with 6.5.0, I am still observing the same behaviour. When applied this patch to 6.5.1 and loaded, it didn't boot.

Any thoughts?

Id really try with the latest bluetooth-next since ISO sockets are still experimental none of these changes are going to be backported until it is marked stable.

SanaAnjaneyulu commented 4 months ago

@SanaAnjaneyulu can you try with the following changes: patchwork.kernel.org/project/bluetooth/patch/20240606162917.621031-1-luiz.dentz@gmail.com

HI @Vudentz , Is there a way that I can confirm that the patch is applied to the linux kernel ? system logs or kernel logs? I applied this patch with 6.5.0, I am still observing the same behaviour. When applied this patch to 6.5.1 and loaded, it didn't boot. Any thoughts?

Id really try with the latest bluetooth-next since ISO sockets are still experimental none of these changes are going to be backported until it is marked stable.

Thanks for the quick reply.

I will try to test with latest bluetooth-next.

Were you able to reproduce this issue with your setup?

Regards, Sana

SanaAnjaneyulu commented 3 months ago

Hi @Vudentz ,

I was able to patch kernel and test it with isotest. I observed the issue again multiple times. However, once I was able to use SDU interval as 2500us and transmit the data.

I am attaching logs of both successful and connection timedout connections. I used Bluez 5.76, Ubuntu 24.04 (kernel 6.8.1 with patch applied). ConnectionTimedout.zip

Succesfull.zip

Note : As the file sizes of wireshark logs are too big, I did not upload these for successful case. Let me know if you need them.

Please check the logs and let me know if you need any additional details.

Thanks in advance, Sana

SanaAnjaneyulu commented 3 months ago

Hi @Vudentz ,

One update. This is issue is still observed with Intel AX210 controller but not with Intel BE200 controller.

Regards, Sana