search

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
12.87k stars 7.08k forks source link

esp-idf : ESP32_S3 nimble bleprph immediately disconnecting on windows after pairing, reason=531 (IDFGH-9270) #10653

Open JADELITANI opened 1 year ago

JADELITANI commented 1 year ago

Answers checklist.

General issue report

esp-idf version : release/V4.4 ( using esp-adf also so we can't jump to release V5.0) hardware: ESP32-S3-WROOM-1 ISSUE: Running the nimble bleperiph example, the BLE immediately disconnects on windows 11 after pairing, reason=531.

Steps to repeat the issue: Run nimble's bleprph example on an ESP32-S3 Using a windows device with a BLE5.0 compatible hardware , add the ble device, it will pair, connect for 5 seconds then immediately disconnects with reason = 531.

the logs are below: (460) NimBLE: GAP procedure initiated: advertise; I (470) NimBLE: disc_mode=2 I (470) NimBLE: adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0 I (480) NimBLE:

I (490) uart: queue free spaces: 8 I (14790) NimBLE: connection established; status=0 I (14790) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (14790) NimBLE: 7c:df:a1:e4:b0:fa I (14790) NimBLE: our_id_addr_type=0 our_id_addr= I (14800) NimBLE: 7c:df:a1:e4:b0:fa I (14800) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (14810) NimBLE: c8:b2:9b:f4:fe:b0 I (14810) NimBLE: peer_id_addr_type=0 peer_id_addr= I (14820) NimBLE: c8:b2:9b:f4:fe:b0 I (14820) NimBLE: conn_itvl=48 conn_latency=0 supervision_timeout=960 encrypted=0 authenticated=0 bonded=0

I (14830) NimBLE:

I (14840) NimBLE: mtu update event; conn_handle=1 cid=4 mtu=256

I (15530) NimBLE: encryption change event; status=0 I (15530) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (15530) NimBLE: 7c:df:a1:e4:b0:fa I (15530) NimBLE: our_id_addr_type=0 our_id_addr= I (15540) NimBLE: 7c:df:a1:e4:b0:fa I (15540) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (15550) NimBLE: c8:b2:9b:f4:fe:b0 I (15550) NimBLE: peer_id_addr_type=0 peer_id_addr= I (15560) NimBLE: c8:b2:9b:f4:fe:b0 I (15560) NimBLE: conn_itvl=48 conn_latency=0 supervision_timeout=960 encrypted=1 authenticated=0 bonded=1

I (15570) NimBLE:

I (15710) NimBLE: subscribe event; conn_handle=1 attr_handle=8 reason=1 prevn=0 curn=0 previ=0 curi=1

I (16370) NimBLE: connection updated; status=0 I (16370) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (16370) NimBLE: 7c:df:a1:e4:b0:fa I (16370) NimBLE: our_id_addr_type=0 our_id_addr= I (16380) NimBLE: 7c:df:a1:e4:b0:fa I (16380) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (16390) NimBLE: c8:b2:9b:f4:fe:b0 I (16390) NimBLE: peer_id_addr_type=0 peer_id_addr= I (16400) NimBLE: c8:b2:9b:f4:fe:b0 I (16400) NimBLE: conn_itvl=12 conn_latency=0 supervision_timeout=960 encrypted=1 authenticated=0 bonded=1

I (16410) NimBLE:

I (18350) NimBLE: connection updated; status=0 I (18350) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (18350) NimBLE: 7c:df:a1:e4:b0:fa I (18350) NimBLE: our_id_addr_type=0 our_id_addr= I (18360) NimBLE: 7c:df:a1:e4:b0:fa I (18360) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (18370) NimBLE: c8:b2:9b:f4:fe:b0 I (18370) NimBLE: peer_id_addr_type=0 peer_id_addr= I (18380) NimBLE: c8:b2:9b:f4:fe:b0 I (18380) NimBLE: conn_itvl=48 conn_latency=0 supervision_timeout=960 encrypted=1 authenticated=0 bonded=1

I (18390) NimBLE:

I (19730) NimBLE: subscribe event; conn_handle=1 attr_handle=8 reason=2 prevn=0 curn=0 previ=1 curi=0

I (19730) NimBLE: disconnect; reason=531 I (19730) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (19740) NimBLE: 7c:df:a1:e4:b0:fa I (19740) NimBLE: our_id_addr_type=0 our_id_addr= I (19750) NimBLE: 7c:df:a1:e4:b0:fa I (19750) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (19760) NimBLE: c8:b2:9b:f4:fe:b0 I (19760) NimBLE: peer_id_addr_type=0 peer_id_addr= I (19770) NimBLE: c8:b2:9b:f4:fe:b0 I (19770) NimBLE: conn_itvl=48 conn_latency=0 supervision_timeout=960 encrypted=1 authenticated=0 bonded=1

I (19780) NimBLE:

I (19790) NimBLE: GAP procedure initiated: advertise; I (19790) NimBLE: disc_mode=2 I (19790) NimBLE: adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0

IshaESP commented 1 year ago

Hi @JADELITANI , I tried reproducing this issue locally, but code is working properly. Can you share debug logs and application's sdkconfig here for us to debug the issue?

Thank You.

JADELITANI commented 1 year ago

Hi @IshaESP Thank you for your reply. I used the bleprph example as is. Attached is the sdkconfig file you requested and Below are the logs: I (102597) NimBLE: connection established; status=0 I (102607) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (102607) NimBLE: 7c:df:a1:e5:78:72 I (102607) NimBLE: our_id_addr_type=0 our_id_addr= I (102617) NimBLE: 7c:df:a1:e5:78:72 I (102617) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (102627) NimBLE: c8:b2:9b:f4:fe:b0 I (102627) NimBLE: peer_id_addr_type=0 peer_id_addr= I (102637) NimBLE: c8:b2:9b:f4:fe:b0 I (102637) NimBLE: conn_itvl=48 conn_latency=0 supervision_timeout=960 encrypted=0 authenticated=0 bonded=0

I (102647) NimBLE:

I (103007) NimBLE: mtu update event; conn_handle=1 cid=4 mtu=256

I (103187) NimBLE: encryption change event; status=1288 I (103187) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (103187) NimBLE: 7c:df:a1:e5:78:72 I (103187) NimBLE: our_id_addr_type=0 our_id_addr= I (103197) NimBLE: 7c:df:a1:e5:78:72 I (103197) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (103207) NimBLE: c8:b2:9b:f4:fe:b0 I (103207) NimBLE: peer_id_addr_type=0 peer_id_addr= I (103217) NimBLE: c8:b2:9b:f4:fe:b0 I (103217) NimBLE: conn_itvl=48 conn_latency=0 supervision_timeout=960 encrypted=0 authenticated=0 bonded=0

I (103237) NimBLE:

I (103307) NimBLE: disconnect; reason=531 I (103307) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (103307) NimBLE: 7c:df:a1:e5:78:72 I (103307) NimBLE: our_id_addr_type=0 our_id_addr= I (103317) NimBLE: 7c:df:a1:e5:78:72 I (103317) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (103327) NimBLE: c8:b2:9b:f4:fe:b0 I (103327) NimBLE: peer_id_addr_type=0 peer_id_addr= I (103337) NimBLE: c8:b2:9b:f4:fe:b0 I (103337) NimBLE: conn_itvl=48 conn_latency=0 supervision_timeout=960 encrypted=0 authenticated=0 bonded=0

I (103347) NimBLE:

I (103357) NimBLE: GAP procedure initiated: advertise; I (103357) NimBLE: disc_mode=2 I (103367) NimBLE: adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0 I (103377) NimBLE:

I (104547) NimBLE: connection established; status=0 I (104547) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (104547) NimBLE: 7c:df:a1:e5:78:72 I (104547) NimBLE: our_id_addr_type=0 our_id_addr= I (104557) NimBLE: 7c:df:a1:e5:78:72 I (104557) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (104567) NimBLE: c8:b2:9b:f4:fe:b0 I (104567) NimBLE: peer_id_addr_type=0 peer_id_addr= I (104577) NimBLE: c8:b2:9b:f4:fe:b0 I (104577) NimBLE: conn_itvl=48 conn_latency=0 supervision_timeout=960 encrypted=0 authenticated=0 bonded=0

I (104587) NimBLE:

I (104597) NimBLE: mtu update event; conn_handle=1 cid=4 mtu=256

I (105287) NimBLE: subscribe event; conn_handle=1 attr_handle=8 reason=1 prevn=0 curn=0 previ=0 curi=1

I (105947) NimBLE: connection updated; status=0 I (105947) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (105947) NimBLE: 7c:df:a1:e5:78:72 I (105947) NimBLE: our_id_addr_type=0 our_id_addr= I (105957) NimBLE: 7c:df:a1:e5:78:72 I (105957) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (105967) NimBLE: c8:b2:9b:f4:fe:b0 I (105967) NimBLE: peer_id_addr_type=0 peer_id_addr= I (105977) NimBLE: c8:b2:9b:f4:fe:b0 I (105977) NimBLE: conn_itvl=12 conn_latency=0 supervision_timeout=960 encrypted=0 authenticated=0 bonded=0

I (105987) NimBLE:

I (107927) NimBLE: connection updated; status=0 I (107927) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (107927) NimBLE: 7c:df:a1:e5:78:72 I (107927) NimBLE: our_id_addr_type=0 our_id_addr= I (107937) NimBLE: 7c:df:a1:e5:78:72 I (107937) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (107947) NimBLE: c8:b2:9b:f4:fe:b0 I (107947) NimBLE: peer_id_addr_type=0 peer_id_addr= I (107957) NimBLE: c8:b2:9b:f4:fe:b0 I (107957) NimBLE: conn_itvl=48 conn_latency=0 supervision_timeout=960 encrypted=0 authenticated=0 bonded=0

I (107967) NimBLE:

I (109307) NimBLE: subscribe event; conn_handle=1 attr_handle=8 reason=2 prevn=0 curn=0 previ=1 curi=0

I (109307) NimBLE: disconnect; reason=531 I (109307) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr= I (109317) NimBLE: 7c:df:a1:e5:78:72 I (109317) NimBLE: our_id_addr_type=0 our_id_addr= I (109327) NimBLE: 7c:df:a1:e5:78:72 I (109327) NimBLE: peer_ota_addr_type=0 peer_ota_addr= I (109337) NimBLE: c8:b2:9b:f4:fe:b0 I (109337) NimBLE: peer_id_addr_type=0 peer_id_addr= I (109347) NimBLE: c8:b2:9b:f4:fe:b0 I (109347) NimBLE: conn_itvl=48 conn_latency=0 supervision_timeout=960 encrypted=0 authenticated=0 bonded=0

I (109357) NimBLE:

I (109367) NimBLE: GAP procedure initiated: advertise; I (109367) NimBLE: disc_mode=2 I (109377) NimBLE: adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0 I (109387) NimBLE: sdkconfig.zip

IshaESP commented 1 year ago

Hi @JADELITANI , You can switch the debug logs on with the help of following steps:

  1. idf.py menuconfig
  2. Component config → Bluetooth → NimBLE Options → NimBLE Host log verbosity → Debug logs
  3. Component config → Log output → Default log verbosity → Debug

Can you try using this sdkconfig : sdkconfig.zip

Thank you!

JADELITANI commented 1 year ago

Hi @IshaESP

I tried your sdkconfig and it is still not working. Here are the logs with the debug active ble_logs.txt

IshaESP commented 1 year ago

Hi @JADELITANI , Can you get Ellisys OTA logs?  Is this issue seen with only one device or across all devices?

JADELITANI commented 1 year ago

It is happening on my windows 11 device. On my Android phone and Iphone it is not happening. It is a windows related issue for sure. But I can't seem to find the solution. Regarding Ellisys OTA logs can you guide me on how to get them ?

IshaESP commented 1 year ago

Observation from the logs shared :

So we wanted Over The Air(OTA) logs to check what remote(Windows 11 phone) is doing. As confirmed by you, issue is not seen on android phones, so this looks to be tied up with particular remote device.  I do not have a windows phone handy , but will try to get one and then can try.

JADELITANI commented 1 year ago

Hi IshaESP

Just to be clear the issue I'm facing is with a windows 11 laptop , with BLE 5.2 capable hardware.

Thank you

IshaESP commented 1 year ago

Hi Thanks for clarifying this. But we will still need Over The Air(OTA) logs to debug this issue.

JADELITANI commented 11 months ago

Hello Again, Sorry for the delay but I got caught up in other work. Update: I moved to esp-idf release/V5.0 and I tested the nimBLe periph example on my windows 11 laptop and the issue is still there. However I was able to get logs using windows Bluetooth virtual sniffer and Wireshark. Attached you can find the logs. I hope this can help pinpoint the issue. Thank you wireshark_events_ble_periph_example.txt

IshaESP commented 11 months ago

Hi @JADELITANI , Looking from the wireshark logs, host is sending a disconnect after receiving LE Connection Update Complete event from controller. To verify if the controller is sending an error in event or host is sending terminate due to different reason. Can you please apply this patch on nimble and give us the logs.

To apply patch:

  1. cd components/bt/host/nimble/nimble
  2. git apply nimble.patch

nimble.zip

JADELITANI commented 11 months ago

Hello @IshaESP

Here you go , I had to change the patch to be able to build. I changed ESP_LOGI( INFO .. to ESP_LOGI("BLE GAP INFO".. and ESP_LOGI("BLE HS HCI EVT INFO" , ... for some reason INFO was not defined.

Waiting for your reply wireshark_ble_periph_test_24_7_23.txt esp_ble_periph_logs_24_7_23.txt

JADELITANI commented 9 months ago

Hello @IshaESP

Do you have any updates , we are still having the same problem.

Waiting for your reply

rahult-github commented 9 months ago

Hi @JADELITANI ,

The issue here is that the disconnect is initiated from windows side. However, OTA log doesn't show anything where a response from nimble should result in this behaviour. All SMP / ATT requests from windows are responded as expected. Just before link termination, windows initiates LLCP updation, and that too is happening correctly when confirmed via the counters and Empty packets

So, since windows internal working is not known, it is taking time to understand and figure out what is going wrong. The same code works ok with other devices does imply that we adhere to BLE standards. I have a wild guess that may be windows is expecting some GATT service, which nimble is not exhibiting, leading to disconnect from windows side. But this is just a guess. Will try few more things to check more on this.

OTA for reference. windows_nimble_bleprph_2_good.zip

AhmadAmine998 commented 8 months ago

esp-idf version : release/V4.4 hardware: ESP32-S3-WROOM-1

Hello,

I had been facing the same issue with nimble BLE connection with Windows. After a lot of experimenting, I managed to get a stable connection with Windows using nimble. These are the steps that I took in debugging the problem:

  1. Looked for any Bluetooth example in ESP-IDF connected successfully to Windows. I found one example that worked: ble_hid_device_demo
  2. After a bit of experimentation, I found that the services and characteristics that were needed to get the connection to work were HID Service (Characteristics: Report, Report Map, HID Information, HID Control Point), Battery Service (Characteristic: Battery Value), and Device Information Service.
  3. This finding was confirmed after some investigation into windows documentation (here) and a nice reference that summarizes these requirements (here - see Table 3.1, 2.1).
  4. Accordingly, I implemented these services and characteristics in nimble, utilizing the UUIDs that I got from here.
  5. After implementing these services in nimble, I was able to connect successfully to the esp32-s3 without any disconnection.

With all that said, the connection is not yet perfect as I still have the following two issues:

  1. I am unable to disconnect from the device once a connection has been made. I suspect I need to add a characteristic or service to enable this behavior, but I am not sure which to add. For reference, see the photos below: These are the connection options that I get for my esp32: image And this is what I expect to get for my connection: image
  2. Since the device is paired, windows attempts to connect to the device once it has been detected via Bluetooth. However, I get stuck in a connect-disconnect loop where windows attempts to connect to the esp but then fails and disconnects. I get the following logs: I (6122) NimBLE: PHY updated rx 1, tx 1 I (6367) NimBLE: disconnect; reason=531

Can you please help me resolve these last two problems? Thank you

Nirklav commented 5 months ago

Have the same issue with ESP32 C3, host disconnects with 531 reason. esp-idf: v5.1 windows 11

cmorganBE commented 5 months ago

Seeing similar with esp32-s3, esp-idf 5.1, and lightblue on ios, this is using the bleprph example almost verbatim.

I (670) BLE_INIT: BT controller compile version [963cad4]
I (670) BLE_INIT: Bluetooth MAC: 7c:df:a1:e0:e9:be

I (680) ble: BLE Host Task Started
I (680) NimBLE: GAP procedure initiated: stop advertising.

I (680) NimBLE: Device Address: 
I (680) NimBLE: 7c:df:a1:e0:e9:be
I (680) NimBLE: 

I (680) NimBLE: GAP procedure initiated: advertise; 
I (680) NimBLE: disc_mode=2
I (680) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
I (680) NimBLE: 

I (680) uart: queue free spaces: 8
I (690) main_task: Returned from app_main()
esp> I (26130) NimBLE: connection established; status=0 
I (26130) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr=
I (26130) NimBLE: 7c:df:a1:e0:e9:be
I (26130) NimBLE:  our_id_addr_type=0 our_id_addr=
I (26130) NimBLE: 7c:df:a1:e0:e9:be
I (26130) NimBLE:  peer_ota_addr_type=1 peer_ota_addr=
I (26130) NimBLE: 7d:4c:e3:5e:5d:26
I (26130) NimBLE:  peer_id_addr_type=1 peer_id_addr=
I (26130) NimBLE: 7d:4c:e3:5e:5d:26
I (26130) NimBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

I (26130) NimBLE: 

I (26590) NimBLE: mtu update event; conn_handle=1 cid=4 mtu=256

I (26890) NimBLE: subscribe event; conn_handle=1 attr_handle=8 reason=1 prevn=0 curn=0 previ=0 curi=1

I (41020) NimBLE: subscribe event; conn_handle=1 attr_handle=8 reason=2 prevn=0 curn=0 previ=1 curi=0

I (41020) NimBLE: disconnect; reason=531 
I (41020) NimBLE: handle=1 our_ota_addr_type=0 our_ota_addr=
I (41020) NimBLE: 7c:df:a1:e0:e9:be
I (41020) NimBLE:  our_id_addr_type=0 our_id_addr=
I (41020) NimBLE: 7c:df:a1:e0:e9:be
I (41020) NimBLE:  peer_ota_addr_type=1 peer_ota_addr=
I (41020) NimBLE: 7d:4c:e3:5e:5d:26
I (41030) NimBLE:  peer_id_addr_type=1 peer_id_addr=
I (41030) NimBLE: 7d:4c:e3:5e:5d:26
I (41030) NimBLE:  conn_itvl=24 conn_latency=0 supervision_timeout=72 encrypted=0 authenticated=0 bonded=0

I (41030) NimBLE: 

I (41030) NimBLE: GAP procedure initiated: advertise; 
I (41030) NimBLE: disc_mode=2
I (41030) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
I (41030) NimBLE: