search

zephyrproject-rtos / zephyr

Primary Git Repository for the Zephyr Project. Zephyr is a new generation, scalable, optimized, secure RTOS for multiple hardware architectures.
https://docs.zephyrproject.org
Apache License 2.0
10.83k stars 6.6k forks source link

STM32WB55 Failed read remote feature, remote version and LE set PHY #49584

Closed Aljohcomb closed 2 years ago

Aljohcomb commented 2 years ago

Describe the bug Running Bluetooth application with SMP in peripheral mode. When connected to from remote device errors codes are received indicating that connection procedure failed. However the device still connects. Following pairing attempts succeeds.

When using the device for communication it is unreliable and will connect/disconnect immediately.

Please also mention any information which could help others to understand the problem you're facing: Platform: STM32WB55CG

I have tried to enable configuration for ctlr phy in prj.conf: ``` CONFIG_BT_CTLR=y CONFIG_BT_LL_SW_SPLIT=y CONFIG_BT_PHY_UPDATE=y CONFIG_BT_HCI=y CONFIG_BT_DRIVERS=y ```

The prj.conf for the test application used to replicate this: ``` CONFIG_LOG=y CONFIG_APP_LOG_LEVEL_DBG=n

CONFIG_BT=y CONFIG_BT_BAS=y CONFIG_BT_PERIPHERAL=y CONFIG_BT_DEBUG_LOG=y CONFIG_BT_DEBUG_SMP=y CONFIG_BT_DEBUG_HCI_CORE=n CONFIG_BT_DEVICE_NAME="LE PHY TEST" CONFIG_BT_DEVICE_NAME_DYNAMIC=y CONFIG_BT_DIS=y CONFIG_BT_LOG_LEVEL_INF=y CONFIG_BT_LOG_LEVEL_WRN=n CONFIG_BT_LOG_LEVEL_ERR=n CONFIG_BT_REMOTE_VERSION=y CONFIG_BT_SMP=y

CONFIG_CONSOLE=y CONFIG_DEBUG_OPTIMIZATIONS=y CONFIG_LOG=y CONFIG_LOG_DEFAULT_LEVEL=4 CONFIG_SERIAL=y CONFIG_UART_CONSOLE=y ```

I have also tested different stack from ST, HCI, HCI-extended, FULL, etc. However, from another issue 46400 and zephyr documentation _stm32wb5x_BLE_HCILayer_extendedfw.bin 13.3 seems to be the correct one.

I have also tried with using extended advertising, improvement.

I have also build and run the peripheral_gatt_write sample and have the same issue there with the exception of Failed to read remote version.

To Reproduce Steps to reproduce the behavior:

  1. build application
  2. cmake -DBOARD=board_xyz
  3. make
  4. Connect to device from remote.
  5. Pair to device.
  6. See error

Expected behavior Connection successful without errors.

Impact Breaks connectability to especially with certain chipsets on remote device, e.g. intel AX201. Crashes upon pairing.

Logs and console output

Our test application: ``` Booting Zephyr OS build zephyr-v3.1.0-4239-g88aa873fbc54 [00:00:00.008,000] main: LE PHY Test Application 0.0.0 [00:00:00.028,000] bt_smp: bt_smp_init: LE SC enabled [00:00:00.029,000] bt_hci_core: Identity: 02:80:E1:00:00:00 (public) [00:00:00.029,000] bt_hci_core: HCI: version 5.2 (0x0b) revision 0xa06a, manufacturer 0x0030 [00:00:00.029,000] bt_hci_core: LMP: version 5.2 (0x0b) subver 0x216a [00:00:00.029,000] main: Bluetooth initialized [00:00:00.031,000] main: Advertising successfully started [00:00:00.182,000] bt_smp: bt_smp_pkey_ready: [00:00:09.754,000] hci_ipm: Invalid peer addr FF:FF:FF:FF:FF:FF (random) [00:00:09.754,000] bt_smp: bt_smp_accept: conn 0x20000dd0 handle 2049 [00:00:09.754,000] bt_smp: bt_smp_connected: chan 0x20001044 cid 0x0006 [00:00:09.754,000] main: Updated MTU: TX: 23 RX: 23 bytes [00:00:09.754,000] main: Connected [00:00:09.755,000] bt_hci_core: opcode 0x2016 status 0x3a [00:00:09.755,000] bt_hci_core: Failed read remote features (-5) [00:00:09.755,000] bt_hci_core: opcode 0x041d status 0x0c [00:00:09.755,000] bt_hci_core: Failed read remote version (-5) [00:00:09.756,000] bt_hci_core: opcode 0x2032 status 0x0c [00:00:09.756,000] bt_hci_core: Failed LE Set PHY (-5) [00:00:18.770,000] bt_smp: bt_smp_recv: Received SMP code 0x01 len 6 [00:00:18.770,000] bt_smp: smp_pairing_req: [00:00:18.773,000] bt_smp: smp_init: prnd fbb0a6d14e9cf40c2b4f6674bee80f99 [00:00:18.861,000] bt_smp: bt_smp_recv: Received SMP code 0x0c len 64 [00:00:18.861,000] bt_smp: smp_public_key: [00:00:18.864,000] main: auth_passkey_display: Passkey display [00:00:18.864,000] main: Passkey for 65:FC:D7:6B:84:F4 (random): 524824 [00:00:19.019,000] bt_smp: bt_smp_dhkey_ready: 0x20003f89 [00:00:29.029,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:29.029,000] bt_smp: smp_pairing_confirm: [00:00:29.029,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:29.029,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:29.029,000] bt_smp: smp_f4: x fbb0a6d14e9cf40c2b4f6674bee80f99 z 0x80 [00:00:29.031,000] bt_smp: smp_f4: res 879d6b653d5bfdd081dcb7f1e755bb77 [00:00:29.119,000] bt_smp: bt_smp_recv: Received SMP code 0x04 len 16 [00:00:29.119,000] bt_smp: smp_pairing_random: [00:00:29.119,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:29.119,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:29.119,000] bt_smp: smp_f4: x 0a83efb9571b73b3ed59ce97a53e0c48 z 0x80 [00:00:29.122,000] bt_smp: smp_f4: res 1834aeff7d4b42d7d5a61c73dc9549c4 [00:00:29.122,000] bt_smp: sc_smp_check_confirm: pcnf 1834aeff7d4b42d7d5a61c73dc9549c4 [00:00:29.122,000] bt_smp: sc_smp_check_confirm: cfm 1834aeff7d4b42d7d5a61c73dc9549c4 [00:00:29.209,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:29.209,000] bt_smp: smp_pairing_confirm: [00:00:29.209,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:29.209,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:29.209,000] bt_smp: smp_f4: x e195c107fd4238f5fd8d5d5425033ce8 z 0x80 [00:00:29.212,000] bt_smp: smp_f4: res 132d537fb4d27224d25bc53a0851488a [00:00:29.299,000] bt_smp: smp_pairing_random: --- 1 messages dropped --- [00:00:29.299,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:29.299,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:29.299,000] bt_smp: smp_f4: x d47536d81884417bfcf3fe8495d5d9e3 z 0x80 [00:00:29.302,000] bt_smp: smp_f4: res 9e5af248394e30ecff0c4891e160cebc [00:00:29.302,000] bt_smp: sc_smp_check_confirm: pcnf 9e5af248394e30ecff0c4891e160cebc [00:00:29.302,000] bt_smp: sc_smp_check_confirm: cfm 9e5af248394e30ecff0c4891e160cebc [00:00:29.389,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:29.389,000] bt_smp: smp_pairing_confirm: [00:00:29.389,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:29.389,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:29.389,000] bt_smp: smp_f4: x 4097c66d4d02ec0c0a311b5fbc6a5a90 z 0x80 [00:00:29.392,000] bt_smp: smp_f4: res 902b709a6b1131542fe610b024b46cde [00:00:29.479,000] bt_smp: bt_smp_recv: Received SMP code 0x04 len 16 [00:00:29.479,000] bt_smp: smp_pairing_random: [00:00:29.479,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:29.479,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:29.479,000] bt_smp: smp_f4: x 8dd9f1d82844e98d99cb7456f5eb2325 z 0x80 [00:00:29.482,000] bt_smp: smp_f4: res 214c80e3bd745cf713e1315c03717f78 [00:00:29.482,000] bt_smp: sc_smp_check_confirm: pcnf 214c80e3bd745cf713e1315c03717f78 [00:00:29.482,000] bt_smp: sc_smp_check_confirm: cfm 214c80e3bd745cf713e1315c03717f78 [00:00:29.569,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:29.569,000] bt_smp: smp_pairing_confirm: [00:00:29.569,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:29.569,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:29.569,000] bt_smp: smp_f4: x ee0df8e03781156c28a40e26e74b4881 z 0x81 [00:00:29.572,000] bt_smp: smp_f4: res 2ccd58f26082fa01a0145d68e072647d [00:00:29.659,000] bt_smp: smp_pairing_random: --- 1 messages dropped --- [00:00:29.659,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:29.659,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:29.659,000] bt_smp: smp_f4: x 03aab1b0075091eaa5f0c590c44d7dc9 z 0x81 [00:00:29.662,000] bt_smp: smp_f4: res 6043e9268c8b36a881515daabe2d217f [00:00:29.662,000] bt_smp: sc_smp_check_confirm: pcnf 6043e9268c8b36a881515daabe2d217f [00:00:29.662,000] bt_smp: sc_smp_check_confirm: cfm 6043e9268c8b36a881515daabe2d217f [00:00:29.749,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:29.749,000] bt_smp: smp_pairing_confirm: [00:00:29.749,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:29.749,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:29.749,000] bt_smp: smp_f4: x eb267e51b366cf20a6d54beb3e5f8ae7 z 0x81 [00:00:29.752,000] bt_smp: smp_f4: res 152e0ade8ce51efd7d776ac9f88fd8ac [00:00:29.839,000] bt_smp: bt_smp_recv: Received SMP code 0x04 len 16 [00:00:29.839,000] bt_smp: smp_pairing_random: [00:00:29.839,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:29.839,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:29.839,000] bt_smp: smp_f4: x 27af45b5c24854c3419c02b5ba45d4c4 z 0x81 [00:00:29.842,000] bt_smp: smp_f4: res 7143010078a6289f038e6b9a8690a464 [00:00:29.842,000] bt_smp: sc_smp_check_confirm: pcnf 7143010078a6289f038e6b9a8690a464 [00:00:29.842,000] bt_smp: sc_smp_check_confirm: cfm 7143010078a6289f038e6b9a8690a464 [00:00:29.929,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:29.929,000] bt_smp: smp_pairing_confirm: [00:00:29.929,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:29.929,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:29.929,000] bt_smp: smp_f4: x 615329fdfa90b68bd20f082a6c85cdbf z 0x80 [00:00:29.932,000] bt_smp: smp_f4: res 413ed21ed055c4eea9dc449d0d763188 [00:00:30.019,000] bt_smp: smp_pairing_random: --- 1 messages dropped --- [00:00:30.019,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:30.019,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:30.019,000] bt_smp: smp_f4: x 1ac533805c181d0b3a1285626840477f z 0x80 [00:00:30.022,000] bt_smp: smp_f4: res 6490e8e17ce49d5b081ff604692f531b [00:00:30.022,000] bt_smp: sc_smp_check_confirm: pcnf 6490e8e17ce49d5b081ff604692f531b [00:00:30.022,000] bt_smp: sc_smp_check_confirm: cfm 6490e8e17ce49d5b081ff604692f531b [00:00:30.109,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:30.109,000] bt_smp: smp_pairing_confirm: [00:00:30.109,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:30.109,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:30.109,000] bt_smp: smp_f4: x 44bc58823534b76fa74463a1d18835fb z 0x80 [00:00:30.112,000] bt_smp: smp_f4: res 05f868767610d24cfd84c6047eede964 [00:00:30.199,000] bt_smp: bt_smp_recv: Received SMP code 0x04 len 16 [00:00:30.199,000] bt_smp: smp_pairing_random: [00:00:30.199,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:30.199,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:30.199,000] bt_smp: smp_f4: x be8b28cb00c0466793221c80f1ceaac9 z 0x80 [00:00:30.202,000] bt_smp: smp_f4: res 9f2a20e5b5a1755de184c66051a3d6ed [00:00:30.202,000] bt_smp: sc_smp_check_confirm: pcnf 9f2a20e5b5a1755de184c66051a3d6ed [00:00:30.202,000] bt_smp: sc_smp_check_confirm: cfm 9f2a20e5b5a1755de184c66051a3d6ed [00:00:30.289,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:30.289,000] bt_smp: smp_pairing_confirm: [00:00:30.289,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:30.289,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:30.289,000] bt_smp: smp_f4: x aa6d7a5b1a3ba35d1b869ab9c91f96c9 z 0x80 [00:00:30.292,000] bt_smp: smp_f4: res d706c44759ac3001fae24393fb2caa44 [00:00:30.379,000] bt_smp: smp_pairing_random: --- 1 messages dropped --- [00:00:30.379,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:30.379,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:30.379,000] bt_smp: smp_f4: x 17d9baca69f1d8113f8bceaabd61959d z 0x80 [00:00:30.382,000] bt_smp: smp_f4: res ac8f49ce40a102cb3599fcc8dac95360 [00:00:30.382,000] bt_smp: sc_smp_check_confirm: pcnf ac8f49ce40a102cb3599fcc8dac95360 [00:00:30.382,000] bt_smp: sc_smp_check_confirm: cfm ac8f49ce40a102cb3599fcc8dac95360 [00:00:30.469,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:30.469,000] bt_smp: smp_pairing_confirm: [00:00:30.469,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:30.469,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:30.469,000] bt_smp: smp_f4: x 2f4eb3135025a2cb3f68279ea42a5c0e z 0x80 [00:00:30.472,000] bt_smp: smp_f4: res d40f8ce6b9df1278bc4ebdfbe4445561 [00:00:30.559,000] bt_smp: bt_smp_recv: Received SMP code 0x04 len 16 [00:00:30.559,000] bt_smp: smp_pairing_random: [00:00:30.559,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:30.559,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:30.559,000] bt_smp: smp_f4: x 92d82b074d646e99aee4d753f3674f8d z 0x80 [00:00:30.561,000] bt_smp: smp_f4: res 4e6162a1ab3d04cb85afb6383b63858e [00:00:30.562,000] bt_smp: sc_smp_check_confirm: pcnf 4e6162a1ab3d04cb85afb6383b63858e [00:00:30.562,000] bt_smp: sc_smp_check_confirm: cfm 4e6162a1ab3d04cb85afb6383b63858e [00:00:30.649,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:30.649,000] bt_smp: smp_pairing_confirm: [00:00:30.649,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:30.649,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:30.649,000] bt_smp: smp_f4: x d22db839c966945270c67ff8921efcf1 z 0x81 [00:00:30.652,000] bt_smp: smp_f4: res 337edd11f4eb0ac9dfc607901118ece1 [00:00:30.739,000] bt_smp: smp_pairing_random: --- 1 messages dropped --- [00:00:30.739,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:30.739,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:30.739,000] bt_smp: smp_f4: x 8ae5758346292f0cafba4ce0ca5813ca z 0x81 [00:00:30.741,000] bt_smp: smp_f4: res 41908c27d0aeff787717eac1c3e5bc76 [00:00:30.742,000] bt_smp: sc_smp_check_confirm: pcnf 41908c27d0aeff787717eac1c3e5bc76 [00:00:30.742,000] bt_smp: sc_smp_check_confirm: cfm 41908c27d0aeff787717eac1c3e5bc76 [00:00:30.829,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:30.829,000] bt_smp: smp_pairing_confirm: [00:00:30.829,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:30.829,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:30.829,000] bt_smp: smp_f4: x 36c4e7e669c7ec686882fdaf8be5cb05 z 0x80 [00:00:30.832,000] bt_smp: smp_f4: res ae4888bdb8b8f58353b2d101ca890b87 [00:00:30.919,000] bt_smp: bt_smp_recv: Received SMP code 0x04 len 16 [00:00:30.919,000] bt_smp: smp_pairing_random: [00:00:30.919,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:30.919,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:30.919,000] bt_smp: smp_f4: x c7fbbb4f4c61385036b3596fcb59e2ed z 0x80 [00:00:30.921,000] bt_smp: smp_f4: res 535ef491ac28d2f5a2f6b27de59cc59c [00:00:30.922,000] bt_smp: sc_smp_check_confirm: pcnf 535ef491ac28d2f5a2f6b27de59cc59c [00:00:30.922,000] bt_smp: sc_smp_check_confirm: cfm 535ef491ac28d2f5a2f6b27de59cc59c [00:00:31.009,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:31.009,000] bt_smp: smp_pairing_confirm: [00:00:31.009,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:31.009,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:31.009,000] bt_smp: smp_f4: x daedb153446cde3e246ee8f51b6cfd34 z 0x80 [00:00:31.011,000] bt_smp: smp_f4: res 1f6f167e48b6faa7adc39dff40dd277b [00:00:31.099,000] bt_smp: smp_pairing_random: --- 1 messages dropped --- [00:00:31.099,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:31.099,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:31.099,000] bt_smp: smp_f4: x f3652f9b55f495e7f03ceb46b442b7e6 z 0x80 [00:00:31.101,000] bt_smp: smp_f4: res ebaa76b349f842edd6f01774d6166e3e [00:00:31.102,000] bt_smp: sc_smp_check_confirm: pcnf ebaa76b349f842edd6f01774d6166e3e [00:00:31.102,000] bt_smp: sc_smp_check_confirm: cfm ebaa76b349f842edd6f01774d6166e3e [00:00:31.189,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:31.189,000] bt_smp: smp_pairing_confirm: [00:00:31.189,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:31.189,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:31.189,000] bt_smp: smp_f4: x 86e17a75b9978c1d3ac23a193b262d72 z 0x80 [00:00:31.191,000] bt_smp: smp_f4: res 00bd0a2e45b76d01f9ae40499e77c9c2 [00:00:31.279,000] bt_smp: bt_smp_recv: Received SMP code 0x04 len 16 [00:00:31.279,000] bt_smp: smp_pairing_random: [00:00:31.279,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:31.279,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:31.279,000] bt_smp: smp_f4: x 1d3d0ca2813b65ffa935bb57a4b58589 z 0x80 [00:00:31.281,000] bt_smp: smp_f4: res c85864a9f20ebbe605ef31d80dade4ca [00:00:31.281,000] bt_smp: sc_smp_check_confirm: pcnf c85864a9f20ebbe605ef31d80dade4ca [00:00:31.282,000] bt_smp: sc_smp_check_confirm: cfm c85864a9f20ebbe605ef31d80dade4ca [00:00:31.369,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:31.369,000] bt_smp: smp_pairing_confirm: [00:00:31.369,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:31.369,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:31.369,000] bt_smp: smp_f4: x 657d097fcbe48babddcbe3f328f7fc88 z 0x80 [00:00:31.371,000] bt_smp: smp_f4: res c3f5f5fa2786cde39b901915e740f6a9 [00:00:31.459,000] bt_smp: smp_pairing_random: --- 1 messages dropped --- [00:00:31.459,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:31.459,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:31.459,000] bt_smp: smp_f4: x c8e910a0181f550f9420c31a92ad5872 z 0x80 [00:00:31.461,000] bt_smp: smp_f4: res c1c5faa27189cedaa91451a78b20e95a [00:00:31.461,000] bt_smp: sc_smp_check_confirm: pcnf c1c5faa27189cedaa91451a78b20e95a [00:00:31.462,000] bt_smp: sc_smp_check_confirm: cfm c1c5faa27189cedaa91451a78b20e95a [00:00:31.549,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:31.549,000] bt_smp: smp_pairing_confirm: [00:00:31.549,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:31.549,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:31.549,000] bt_smp: smp_f4: x cd198373afef33ecad35fd9291d0c960 z 0x80 [00:00:31.551,000] bt_smp: smp_f4: res 663f5e29cce22b38a2ff57fb3f466cca [00:00:31.639,000] bt_smp: bt_smp_recv: Received SMP code 0x04 len 16 [00:00:31.639,000] bt_smp: smp_pairing_random: [00:00:31.639,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:31.639,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:31.639,000] bt_smp: smp_f4: x cdbba64a21856e149ef35e12ee08666e z 0x80 [00:00:31.641,000] bt_smp: smp_f4: res 589a4b3a1bf1dc261553d9a51f32ece6 [00:00:31.641,000] bt_smp: sc_smp_check_confirm: pcnf 589a4b3a1bf1dc261553d9a51f32ece6 [00:00:31.642,000] bt_smp: sc_smp_check_confirm: cfm 589a4b3a1bf1dc261553d9a51f32ece6 [00:00:31.729,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:31.729,000] bt_smp: smp_pairing_confirm: [00:00:31.729,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:31.729,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:31.729,000] bt_smp: smp_f4: x 61b1c206962ceae1148b8445596f0bf1 z 0x80 [00:00:31.731,000] bt_smp: smp_f4: res 64535a6f863de37ba4b54b7a53feb06e [00:00:31.819,000] bt_smp: smp_pairing_random: --- 1 messages dropped --- [00:00:31.819,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:31.819,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:31.819,000] bt_smp: smp_f4: x 09add2fcc195bbea3b9b51b977874438 z 0x80 [00:00:31.821,000] bt_smp: smp_f4: res 669ea3911ad9d5553b445328eb882c66 [00:00:31.821,000] bt_smp: sc_smp_check_confirm: pcnf 669ea3911ad9d5553b445328eb882c66 [00:00:31.822,000] bt_smp: sc_smp_check_confirm: cfm 669ea3911ad9d5553b445328eb882c66 [00:00:31.909,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:31.909,000] bt_smp: smp_pairing_confirm: [00:00:31.909,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:31.909,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:31.909,000] bt_smp: smp_f4: x 48c035027fc3b7116db9d43a1b8e4622 z 0x80 [00:00:31.911,000] bt_smp: smp_f4: res 91e32317130ae3b31eb50cef5b2873cc [00:00:31.999,000] bt_smp: bt_smp_recv: Received SMP code 0x04 len 16 [00:00:31.999,000] bt_smp: smp_pairing_random: [00:00:31.999,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:31.999,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:31.999,000] bt_smp: smp_f4: x e2710db70d49ef43c1785798bc44cb8c z 0x80 [00:00:32.001,000] bt_smp: smp_f4: res 41681be0fb840bbdab2066c3afba58ee [00:00:32.001,000] bt_smp: sc_smp_check_confirm: pcnf 41681be0fb840bbdab2066c3afba58ee [00:00:32.002,000] bt_smp: sc_smp_check_confirm: cfm 41681be0fb840bbdab2066c3afba58ee [00:00:32.134,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:32.134,000] bt_smp: smp_pairing_confirm: [00:00:32.134,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:32.134,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:32.134,000] bt_smp: smp_f4: x be0687e2cbf5539d2ca25c6f17c44c6e z 0x80 [00:00:32.136,000] bt_smp: smp_f4: res 38c585e06486e03f1cc5417d40a46ae9 [00:00:32.224,000] bt_smp: bt_smp_recv: Received SMP code 0x04 len 16 [00:00:32.224,000] bt_smp: smp_pairing_random: [00:00:32.224,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:32.224,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:32.224,000] bt_smp: smp_f4: x ea027c25881f08e2d5fb634cbd02ba75 z 0x80 [00:00:32.226,000] bt_smp: smp_f4: res d48d19be4edb85c15430617a3f1c19b2 [00:00:32.226,000] bt_smp: sc_smp_check_confirm: pcnf d48d19be4edb85c15430617a3f1c19b2 [00:00:32.226,000] bt_smp: sc_smp_check_confirm: cfm d48d19be4edb85c15430617a3f1c19b2 [00:00:32.314,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:32.314,000] bt_smp: smp_pairing_confirm: [00:00:32.314,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:32.314,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:32.314,000] bt_smp: smp_f4: x 1865002e2a1df5576a6b37ff51105e59 z 0x80 [00:00:32.316,000] bt_smp: smp_f4: res 1e728640db39fe459b1cfe81495b1483 [00:00:32.404,000] bt_smp: smp_pairing_random: --- 1 messages dropped --- [00:00:32.404,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:32.404,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:32.404,000] bt_smp: smp_f4: x 6b1ff5bd7e815ee6995a0154742e4c2f z 0x80 [00:00:32.406,000] bt_smp: smp_f4: res 68438aa2001444a7f2b18c4aa1f6c265 [00:00:32.406,000] bt_smp: sc_smp_check_confirm: pcnf 68438aa2001444a7f2b18c4aa1f6c265 [00:00:32.406,000] bt_smp: sc_smp_check_confirm: cfm 68438aa2001444a7f2b18c4aa1f6c265 [00:00:32.494,000] bt_smp: bt_smp_recv: Received SMP code 0x03 len 16 [00:00:32.494,000] bt_smp: smp_pairing_confirm: [00:00:32.494,000] bt_smp: smp_f4: u eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:32.494,000] bt_smp: smp_f4: v b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:32.494,000] bt_smp: smp_f4: x a165f11516e7535038f88a138e10526d z 0x81 [00:00:32.496,000] bt_smp: smp_f4: res b88799a5d90dd1089dd8920bf6024cb8 [00:00:32.584,000] bt_smp: bt_smp_recv: Received SMP code 0x04 len 16 [00:00:32.584,000] bt_smp: smp_pairing_random: [00:00:32.584,000] bt_smp: smp_f4: u b0fb9a24ac1318c66229cb9e3249feb9acb6d4f366fbdecd237dfa4301f11ca5 [00:00:32.584,000] bt_smp: smp_f4: v eaace4962a5eda345eb0bbd6a74882da8717745783f5c74f0fa7195b1100b224 [00:00:32.584,000] bt_smp: smp_f4: x 95fdc5d0227a1fc8018764cc728bf334 z 0x81 [00:00:32.586,000] bt_smp: smp_f4: res 943763a708e2b637c9d8f94d41466ffc [00:00:32.586,000] bt_smp: sc_smp_check_confirm: pcnf 943763a708e2b637c9d8f94d41466ffc [00:00:32.586,000] bt_smp: sc_smp_check_confirm: cf[00:00:32.674,000] bt_smp: bt_smp_recv: Received SMP code 0x0d len 16 [00:00:32.674,000] bt_smp: smp_dhkey_check: [00:00:32.674,000] bt_smp: smp_f5: w dc3f5712ffd443cfc600b3717aed571f7678c9d480db29bda7176fb3d0397997 [00:00:32.674,000] bt_smp: smp_f5: n1 95fdc5d0227a1fc8018764cc728bf334 [00:00:32.674,000] bt_smp: smp_f5: n2 a165f11516e7535038f88a138e10526d [00:00:32.674,000] os: MPU FAULT [00:00:32.674,000] os: Stacking error (context area might be not valid) [00:00:32.674,000] os: Data Access Violation [00:00:32.674,000] os: MMFAR Address: 0x2000213c [00:00:32.674,000] os: r0/a1: 0x93069305 r1/a2: 0x93089307 r2/a3: 0x46499309 [00:00:32.674,000] os: r3/a4: 0xf7ffa806 r12/ip: 0x9002fe53 r14/lr: 0x3019f89d [00:00:32.674,000] os: xpsr: 0x61000000 [00:00:32.674,000] os: Faulting instruction address (r15/pc): 0x08002d48 [00:00:32.674,000] os: >>> ZEPHYR FATAL ERROR 2: Stack overflow on CPU 0 [00:00:32.674,000] os: Current thread: 0x20000b78 (unknown) [00:00:32.782,000] os: Halting system ```

Peripheral_gatt_write sample logs: ``` Booting Zephyr OS build zephyr-v3.1.0-4239-g88aa873fbc54 Bluetooth initialized Advertising successfully started [00:00:00.030,000] bt_hci_core: Identity: 02:80:E1:00:00:00 (public) [00:00:00.030,000] bt_hci_core: HCI: version 5.2 (0x0b) revision 0xa06a, manufacturer 0x0030 [00:00:00.030,000] bt_hci_core: LMP: version 5.2 (0x0b) subver 0x216a Updated MTU: TX: 23 RX: 23 bytes connected: 7B:AB:1A:CF:81:89 (random) role 1 mtu_exchange: Current MTU = 23 mtu_exchange: Exchange MTU... Updated MTU: TX: 247 RX: 247 bytes mtu_exchange_cb: MTU exchange successful (247) le_param_updated: int 0x0006 lat 0 to 500 le_param_updated: int 0x0024 lat 0 to 500 write_cmd_cb: count= 0, len= 0, rate= 0 bps. [00:00:12.223,000] hci_ipm: Invalid peer addr FF:FF:FF:FF:FF:FF (random) [00:00:12.236,000] bt_hci_core: opcode 0x2016 status 0x3a [00:00:12.236,000] bt_hci_core: Failed read remote features (-5) [00:00:12.237,000] bt_hci_core: opcode 0x2032 status 0x0c [00:00:12.237,000] bt_hci_core: Failed LE Set PHY (-5) ```

Environment (please complete the following information):

Additional Context When looking up the line from the crash with: addr2line -e zephyr.elf 0x08002d48

It leads here: modules/crypto/tinycrypt/lib/source/aes_encrypt.c:71

erwango commented 2 years ago

@Aljohcomb Thanks for raising this point. We'll try to investigate based on the trace provided.

Note, following Kconfig flags are not compatible with STM32WB. I think they are discarded in the build, but it would be cleaner not to disable them:

CONFIG_BT_CTLR=y
CONFIG_BT_LL_SW_SPLIT=y
Aljohcomb commented 2 years ago

@Aljohcomb Thanks for raising this point. We'll try to investigate based on the trace provided.

Note, following Kconfig flags are not compatible with STM32WB. I think they are discarded in the build, but it would be cleaner not to disable them:

CONFIG_BT_CTLR=y
CONFIG_BT_LL_SW_SPLIT=y

Thank you for the response! Those configuration options are not in the actual project, only given as examples of somethings I've tried. But you are correct of course.

The issue is very problematic for our use of the STM32 since the bluetooth does not work at all. I would be very happy to provide more logs or testing if there are any ideas.

erwango commented 2 years ago

I have also tested different stack from ST, HCI, HCI-extended, FULL, etc. However, from another issue https://github.com/zephyrproject-rtos/zephyr/issues/46400 and zephyr documentation stm32wb5x_BLE_HCILayer_extended_fw.bin 13.3 seems to be the correct one.

Note that for general usage, stm32wb5x_BLE_HCILayer_fw.bin is the one to be used.

Aljohcomb commented 2 years ago

I have also tested different stack from ST, HCI, HCI-extended, FULL, etc. However, from another issue #46400 and zephyr documentation stm32wb5x_BLE_HCILayer_extended_fw.bin 13.3 seems to be the correct one.

Note that for general usage, stm32wb5x_BLE_HCILayer_fw.bin is the one to be used.

I have also tried older versions of that stack with no major difference.

erwango commented 2 years ago

@Aljohcomb I'm not able to reproduce this issue on my side (I'm testing current main with V13.2.0, stm32wb5x_BLE_HCILayer_fw.bin). But maybe I'm lacking a remote device that allows to reproduce the issue. In order to help on investigation, would you be able to try to reproduce the issue using full STM32Cube application ?

Aljohcomb commented 2 years ago

@Aljohcomb I'm not able to reproduce this issue on my side (I'm testing current main with V13.2.0, stm32wb5x_BLE_HCILayer_fw.bin). But maybe I'm lacking a remote device that allows to reproduce the issue. In order to help on investigation, would you be able to try to reproduce the issue using full STM32Cube application ?

The issue is mainly prevalent when remote is using Intels AX201 chipset. However I get the faults no matter remote device. I did manage just now to get the set phy working with: CONFIG_BT_AUTO_PHY_UPDATE=n I this makes the remote decide on PHY instead of the STM32 in this case. Also fixed the crash. The error of failed to read remote features still remains.

Connection towards the AX201 chipset is still not possible.

I could run a cube application for testing for sure, might take some time to setup unless there is something ready to go.

@erwango Another theory I have is regarding clocks. Is your STM32 board running BT with LSE clock? We don't have one and are using HSE currently. I'm speculating that this could cause syncronisation issues.

erwango commented 2 years ago

I did manage just now to get the set phy working with: CONFIG_BT_AUTO_PHY_UPDATE=n I this makes the remote decide on PHY instead of the STM32 in this case. Also fixed the crash.

Agreed. I'm checking with our BLE experts on the consequence on deactivating this option. Note that I don't get crash even when this is on.

The error of failed to read remote features still remains.

Ok, I can see this error as well. We need to investigate that also, but I don't think this is related with your issue.

I could run a cube application for testing for sure, might take some time to setup unless there is something ready to go.

Here is the equivalent Cube Application https://github.com/STMicroelectronics/STM32CubeWB/tree/master/Projects/P-NUCLEO-WB55.Nucleo/Applications/BLE/BLE_HeartRate

@erwango Another theory I have is regarding clocks. Is your STM32 board running BT with LSE clock? We don't have one and are using HSE currently. I'm speculating that this could cause synchronization issues.

You might be interested by https://github.com/zephyrproject-rtos/zephyr/issues/31959. This is on my TODO list for long time If this is helping in your case, I'll try to speed things up.

Aljohcomb commented 2 years ago

Here is the equivalent Cube Application https://github.com/STMicroelectronics/STM32CubeWB/tree/master/Projects/P-NUCLEO-WB55.Nucleo/Applications/BLE/BLE_HeartRate

I will take a look at this and get it running on our HW.

You might be interested by #31959. This is on my TODO list for long time If this is helping in your case, I'll try to speed things up.

Thanks, will read through this.

Will try to get back on this asap.

Aljohcomb commented 2 years ago

Regarding #31959 we have made following patch to _ipmstm32wb.c.

Subject: [PATCH] drivers: hci: stm32_ipm: Add HSE as BLE RF wake up source

LSI is not a valid RF wake up clock source anymore.
For more info see, STM32WB55 errata chap. 2.2.1.
---
 drivers/bluetooth/hci/ipm_stm32wb.c | 14 ++++++++++----
 1 file changed, 10 insertions(+), 4 deletions(-)

diff --git a/drivers/bluetooth/hci/ipm_stm32wb.c b/drivers/bluetooth/hci/ipm_stm32wb.c
index a487b8b019..13bb8a6e58 100644
--- a/drivers/bluetooth/hci/ipm_stm32wb.c
+++ b/drivers/bluetooth/hci/ipm_stm32wb.c
@@ -69,6 +69,8 @@ struct aci_set_ble_addr {
 #define HCI_CONFIG_DATA_PUBADDR_OFFSET     0
 #define HCI_CONFIG_DATA_RANDOM_ADDRESS_OFFSET  0x2E

+#define CFG_BLE_HSE_SOURCE 1
+
 static bt_addr_t bd_addr_udn;

 /* Rx thread definitions */
@@ -92,7 +94,11 @@ static void stm32wb_start_ble(void)
        CFG_BLE_MAX_ATT_MTU,
        CFG_BLE_SLAVE_SCA,
        CFG_BLE_MASTER_SCA,
+       #if STM32_LSE_CLOCK
        CFG_BLE_LSE_SOURCE,
+       #else
+       CFG_BLE_HSE_SOURCE,
+       #endif
        CFG_BLE_MAX_CONN_EVENT_LENGTH,
        CFG_BLE_HSE_STARTUP_TIME,
        CFG_BLE_VITERBI_MODE,
@@ -406,13 +412,13 @@ static void start_ble_rf(void)
    /* Switch OFF LSI */
    LL_RCC_LSI2_Disable();
 #else
-   LL_RCC_LSI2_Enable();
-   while (!LL_RCC_LSI2_IsReady()) {
+   LL_RCC_HSE_Enable();
+   while (!LL_RCC_HSE_IsReady()) {
    }

    /* Select wakeup source of BLE RF */
-   LL_RCC_SetRFWKPClockSource(LL_RCC_RFWKP_CLKSOURCE_LSI);
-   LL_RCC_SetRTCClockSource(LL_RCC_RTC_CLKSOURCE_LSI);
+   LL_RCC_SetRFWKPClockSource(LL_RCC_RFWKP_CLKSOURCE_HSE_DIV1024);
+   LL_RCC_SetRTCClockSource(LL_RCC_RTC_CLKSOURCE_HSE_DIV32);
 #endif

    /* Set RNG on HSI48 */
--

To get HSE working as clock. Due to an errata from ST we found out that the LSI clock does not work.

erwango commented 2 years ago

Regarding https://github.com/zephyrproject-rtos/zephyr/issues/31959 we have made following patch to ipm_stm32wb.c.

Did it helped in fixing your issue ?

Aljohcomb commented 2 years ago

Regarding #31959 we have made following patch to ipm_stm32wb.c.

Did it helped in fixing your issue ?

It did fix the issue, we have used this patch for a while. Might be important to point out that this issue is mostly towards a specific inter chip, AX201.

I'm attaching a log file from a wireshark session were the issue is observer. Can provide longer recordings if necessary. STM32_read_remote_features_fail.json.txt

Have not done the cube project yet.

erwango commented 2 years ago

@Aljohcomb Sorry but I'm lost. Which issue did it fixed ? As I understand this is not current issue.

Aljohcomb commented 2 years ago

@Aljohcomb Sorry but I'm lost. Which issue did it fixed ? As I understand this is not current issue.

Sorry that was unclear from my side. It is not the current issue. It was only in regards to the issue you linked yesterday. I thought that maybe our use of HSE instead of LSE could have an effect on the syncronisation which was a longshot theory for the read remote features fail.

KenthJohan commented 2 years ago

I have the same problem when connecting then disconnecting then connecting then disconnecting then connecting:

CONFIG_BT_AUTO_PHY_UPDATE=y
*** Booting Zephyr OS build v3.2.0-rc3-24-g8364715998c9  ***
Bluetooth initialized        
Advertising successfully started
[00:00:00.346,000] <inf> bt_hci_core: Identity: 02:80:E1:00:00:00 (public)
[00:00:00.346,000] <inf> bt_hci_core: HCI: version 5.0 (0x09) revision 0x0026, manufacturer 0x00
30
[00:00:00.346,000] <inf> bt_hci_core: LMP: version 5.0 (0x09) subver 0x2126
Connected
[00:00:04.258,000] <wrn> bt_hci_core: opcode 0x2016 status 0x3a
[00:00:04.258,000] <err> bt_hci_core: Failed read remote features (-5)
[00:00:04.258,000] <wrn> bt_hci_core: opcode 0x2032 status 0x0c
[00:00:04.258,000] <err> bt_hci_core: Failed LE Set PHY (-5)
Disconnected (reason 0x13)
Connected
[00:00:09.668,000] <wrn> bt_hci_core: opcode 0x2016 status 0x3a
[00:00:09.668,000] <err> bt_hci_core: Failed read remote features (-5)
[00:00:09.669,000] <wrn> bt_hci_core: opcode 0x2032 status 0x0c
[00:00:09.669,000] <err> bt_hci_core: Failed LE Set PHY (-5)
Disconnected (reason 0x13)              
Connected                                                                              
[00:00:14.150,000] <wrn> bt_hci_core: opcode 0x2016 status 0x3a
[00:00:14.150,000] <err> bt_hci_core: Failed read remote features (-5)
[00:00:14.151,000] <wrn> bt_hci_core: opcode 0x2032 status 0x0c
[00:00:14.151,000] <err> bt_hci_core: Failed LE Set PHY (-5)

After the last Connected using nRF Connect for Mobile it fails to connect and there is no error printing from zephyr log.

CONFIG_BT_AUTO_PHY_UPDATE=n
*** Booting Zephyr OS build v3.2.0-rc3-24-g8364715998c9  ***
Bluetooth initialized
Advertising successfully started
[00:00:00.346,000] <inf> bt_hci_core: Identity: 02:80:E1:00:00:00 (public)
[00:00:00.346,000] <inf> bt_hci_core: HCI: version 5.0 (0x09) revision 0x0026, manufacturer 0x00
30
[00:00:00.346,000] <inf> bt_hci_core: LMP: version 5.0 (0x09) subver 0x2126
Connected
[00:00:07.251,000] <wrn> bt_hci_core: opcode 0x2016 status 0x3a
[00:00:07.251,000] <err> bt_hci_core: Failed read remote features (-5)
Disconnected (reason 0x13)
Connected                        
[00:00:15.788,000] <wrn> bt_hci_core: opcode 0x2016 status 0x3a
[00:00:15.788,000] <err> bt_hci_core: Failed read remote features (-5)
Disconnected (reason 0x13)                    
Connected
[00:00:19.577,000] <wrn> bt_hci_core: opcode 0x2016 status 0x3a
[00:00:19.577,000] <err> bt_hci_core: Failed read remote features (-5)
[00:00:20.166,000] <err> os: ***** BUS FAULT *****
[00:00:20.166,000] <err> os:   Imprecise data bus error
[00:00:20.166,000] <err> os: r0/a1:  0x200018e0  r1/a2:  0x200300d8  r2/a3:  0x2003d238
[00:00:20.166,000] <err> os: r3/a4:  0x00000000 r12/ip:  0x00000000 r14/lr:  0x08001ce7
[00:00:20.166,000] <err> os:  xpsr:  0x61000000
[00:00:20.166,000] <err> os: Faulting instruction address (r15/pc): 0x08001ce6
[00:00:20.166,000] <err> os: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0
[00:00:20.166,000] <err> os: Current thread: 0x200012b8 (unknown)
[00:00:20.237,000] <err> os: Halting system

After the last Connected using nRF Connect for Mobile it fails to connect but now zephyr log prints some error at least.

erwango commented 2 years ago

I have the same problem when connecting then disconnecting then connecting then disconnecting then connecting:

This is likely a different error. Would you mind raising a new issue and provide all information on the SW you're using ? Also note that AUTO_PHY_UPDATE is not supported by STM32WB BLE Controller. Config should be CONFIG_BT_AUTO_PHY_UPDATE=n.

KenthJohan commented 2 years ago

I have the same problem when connecting then disconnecting then connecting then disconnecting then connecting:

This is likely a different error. Would you mind raising a new issue and provide all information on the SW you're using ? Also note that AUTO_PHY_UPDATE is not supported by STM32WB BLE Controller. Config should be CONFIG_BT_AUTO_PHY_UPDATE=n.

https://github.com/zephyrproject-rtos/zephyr/issues/50655

erwango commented 2 years ago

btmon extract:

< HCI Command: LE Read Remote Used Features (0x08|0x0016) plen 2                    #55 11.132100
        Handle: 2049
> HCI Event: Command Status (0x0f) plen 4                                           #56 11.133800
      LE Read Remote Used Features (0x08|0x0016) ncmd 1
        Status: Controller Busy (0x3a)
< HCI Command: LE Set PHY (0x08|0x0032) plen 7                                      #57 11.135300
        Handle: 2049
        All PHYs preference: 0x00
        TX PHYs preference: 0x02
          LE 2M
        RX PHYs preference: 0x02
          LE 2M
        PHY options preference: Reserved (0x0000)
> HCI Event: Command Status (0x0f) plen 4                                           #58 11.137400
      LE Set PHY (0x08|0x0032) ncmd 1
        Status: Command Disallowed (0x0c)
....
* Drops: cmd 0 evt 1 acl_tx 1 acl_rx 1 sco_tx 0 sco_rx 0 other 0
= bt: bt_hci_core: opcode 0x2016 status 0x3a                                            11.135200
= bt: bt_hci_core: Failed read remote features (-5)                                     11.135200
= bt: bt_hci_core: opcode 0x2032 status 0x0c                                            11.138800
* Drops: cmd 0 evt 1 acl_tx 1 acl_rx 1 sco_tx 0 sco_rx 0 other 0
= bt: bt_hci_core: Failed LE Set PHY (-5)                                               11.138800
erwango commented 2 years ago

@jhedberg question for you on 2 specific errors we're facing here (see btmon extract above):

First issue: "LE Read Remote Used Features": Controller Busy I wonder what is the expected behavior in that case. Is host supposed to renew the request some time later ? I haven't found anything in the specification.

In any case, there is nothing controller can do for that ...

Second issue: "LE Set PHY" command disallowed: Actually controller perform the PHY update on his own and doesn't expect host to trigger the procedure. I can perform the following configuration for STM32WB (either in_deconfig or .deconfig file):

CONFIG_BT_PHY_UPDATE=y
CONFIG_BT_USER_PHY_UPDATE=n
CONFIG_BT_AUTO_PHY_UPDATE=n

But this won't prevent any wrong configuration happening later by the user. Is it the best option I have?

jhedberg commented 2 years ago

@cvinayak any thoughts on the questions @erwango raises in the comment above?

cvinayak commented 2 years ago

@erwango The device is a peripheral and the controller does not support both the peripheral initiated feature request and PHY update control procedures.

Zephyr Host will not initiate a remote feature request if the controller does not support it, see the code:

https://github.com/zephyrproject-rtos/zephyr/blob/07de2ffbb01a4633cdec7e48190ae369ecc37c9b/subsys/bluetooth/host/hci_core.c#L1010-L1017

The same with PHY update procedure:

https://github.com/zephyrproject-rtos/zephyr/blob/07de2ffbb01a4633cdec7e48190ae369ecc37c9b/subsys/bluetooth/host/hci_core.c#L1027-L1036

It appear the controller is at fault as it returns the features as supported when host asks the local supported features:

https://github.com/zephyrproject-rtos/zephyr/blob/07de2ffbb01a4633cdec7e48190ae369ecc37c9b/subsys/bluetooth/host/hci_core.c#L2922-L2930

Users using this controller has to use CONFIG_BT_PHY_UPDATE=n and live with error with the remote feature request failure as there is no Kconfig to disable (as Host trusts a Conformant Controller to return correct local supported features).

jhedberg commented 2 years ago

@cvinayak @erwango btw, we have the concept of "quirks" (special flags) that HCI drivers can set, in case it's known that a controller misbehaves in a specific way and it can't be properly fixed worked around in any other reasonable way.

Just as I wrote the above, I realized that the quirks are not implemented in an ideal way for Zephyr. The design is inherited from Linux, where controllers can come and go dynamically. With Zephyr a more optimal solution would be promptless Kconfig symbols that the HCI driver would select, and the host would then have if (IS_ENABLED(...)) { branches for them. The only case where Zephyr might need runtime quirks is if discovering the need for one would require doing e.g. some HCI communication first.

Anyway, considering the "add a new quirk" option should really be the last resort. If you can get the controller firmware fixed, or work around the issue in some other clean way, then that would be better.

erwango commented 2 years ago

@jhedberg, @cvinayak Thanks for your inputs.

About the remote feature request point, the fact is that the controller actually supports it. Problem is that the request is received at a point where it is not able to process it and hence returns "Controller Busy". "Controller Busy" is an allowed response distinct from "Command Disallowed", so one can expect a specific treatment on host side. This being said, I haven't found anything in the specification about the behavior expected in this case, but I would have expected the host to have a new try later. Are we in a grey area here ?

About the phy update request, indeed CONFIG_BT_PHY_UPDATE=n should be used, but there is no way to prevent user to set it otherwise. As mentioned, it would be nice to have promptless Kconfig symbols which would prevent this possibility. Anyway, I'm not in position to implement this atm.

cvinayak commented 2 years ago

When the Controller receives the HCI_LE_Read_Remote_Features command, the Controller shall send the HCI_Command_Status event to the Host. When the Controller has completed the procedure to determine the remote features or has determined that it will be using a cached copy, the Controller shall send an HCI_LE_Read_Remote_Features_Complete event to the Host. The HCI_LE_Read_Remote_Features_Complete event contains the status of this command and the parameter describing the features used on the connection and the features supported by the remote device. Note: An HCI_Command_Complete event is not sent by the Controller to indicate that this command has been completed. Instead, the HCI_LERead- Remote_Features_Complete event indicates that this command has been completed.

"Controller Busy" return seems Controller implementation specific, and there is nothing Host can do to retry. Retries can loop forever unless the Controller would let the Host know when to retry.

hlukasz commented 2 years ago

I am facing the same issue in my STM32WB board - reading remote features returns "controller busy" error. I did a quick workaround to retry this command with 100ms delay, after around 5 tries it finally passes. The only concern is if adding about 0,5s delay in conn_auto_initiate() does not affect something else in negative way.

Here is the patch

diff --git a/subsys/bluetooth/host/hci_core.c b/subsys/bluetooth/host/hci_core.c
index b53f091099..4f3fda80fd 100644
--- a/subsys/bluetooth/host/hci_core.c
+++ b/subsys/bluetooth/host/hci_core.c
@@ -334,6 +334,8 @@ int bt_hci_cmd_send_sync(uint16_t opcode, struct net_buf *buf,
                switch (status) {
                case BT_HCI_ERR_CONN_LIMIT_EXCEEDED:
                        return -ECONNREFUSED;
+               case BT_HCI_ERR_CONTROLLER_BUSY:
+                       return -EBUSY;
                default:
                        return -EIO;
                }
@@ -997,7 +999,7 @@ static bool skip_auto_phy_update_on_conn_establishment(struct bt_conn *conn)

 static void conn_auto_initiate(struct bt_conn *conn)
 {
-       int err;
+       int err, retries;

        if (conn->state != BT_CONN_CONNECTED) {
                /* It is possible that connection was disconnected directly from
@@ -1010,7 +1012,14 @@ static void conn_auto_initiate(struct bt_conn *conn)
        if (!atomic_test_bit(conn->flags, BT_CONN_AUTO_FEATURE_EXCH) &&
            ((conn->role == BT_HCI_ROLE_CENTRAL) ||
             BT_FEAT_LE_PER_INIT_FEAT_XCHG(bt_dev.le.features))) {
-               err = hci_le_read_remote_features(conn);
+               retries = 10;
+               do {
+                       err = hci_le_read_remote_features(conn);
+                       if (err != -EBUSY) {
+                               break;
+                       }
+                       k_sleep(K_MSEC(100));
+               } while (--retries > 0);
                if (err) {
                        BT_ERR("Failed read remote features (%d)", err);
                }
erwango commented 2 years ago

I am facing the same issue in my STM32WB board - reading remote features returns "controller busy" error. I did a quick workaround to retry this command with 100ms delay, after around 5 tries it finally passes. The only concern is if adding about 0,5s delay in conn_auto_initiate() does not affect something else in negative way.

Thanks @hlukasz for the head's up. Though I'm not sure if/how this can be fitted into tree.

About phy update request, sending the message at a different time works (see below). So I'll go with something like:

config BT_USER_PHY_UPDATE
    default y if BT
< HCI Command: LE Set PHY (0x08|0x0032) plen 7                                                                                                 #58 10.267600
        Handle: 2049
        All PHYs preference: 0x00
        TX PHYs preference: 0x02
          LE 2M
        RX PHYs preference: 0x02
          LE 2M
        PHY options preference: Reserved (0x0000)
> HCI Event: Command Status (0x0f) plen 4                                                                                                      #59 10.269400
      LE Set PHY (0x08|0x0032) ncmd 1
        Status: Success (0x00)