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.66k stars 6.53k forks source link

samples/bluetooth/peripheral: could not connect with disco_l475_iot1 board #15714

Closed parthitce closed 5 years ago

parthitce commented 5 years ago

Describe the bug When I tried to run samples/bluetooth/peripheral/ in disco_l475_iot1 board and unable to connect with Bluez. The sample application crashes with exception.

To Reproduce Steps to reproduce the behavior:

  1. cd samples/bluetooth/peripheral; mkdir build; cd build
  2. cmake -GNinja -DBOARD=disco_l475_iot1 ..
  3. ninja; ninja flash
  4. Run bluetoothctl: trust the zephyr device and pair it.

Expected behavior Zephyr and Bluetoothctl should ideally pair and connect.

Impact This blocks the basic bluetooth functional testing and smp_svr use case on top of mcuboot.

Screenshots or console output

***** Booting Zephyr OS v1.14.0-rc1-2148-g3ce677092d36 *****
[00:00:00.005,000] <inf> mcuboot: Starting bootloader
[00:00:00.012,000] <inf> mcuboot: Primary image: magic=unset, copy_done=0x3, image_ok=0x3
[00:00:00.020,000] <inf> mcuboot: Scratch: magic=unset, copy_done=0x0, image_ok=0x3
[00:00:00.028,000] <inf> mcuboot: Boot source: primary slot
[00:00:00.049,000] <inf> mcuboot: Swap type: none
[00:00:00.251,000] <inf> mcuboot: Bootloader chainload address offset: 0x20000
[00:00:00.258,000] <inf> mcuboot: Jumping to the first image slot
***** Booting Zephyr OS v1.14.0-rc1-2150-g0dd3b421c4c4 *****
[00:00:00.024,000] <dbg> bt_gatt.sc_process: sBluetooth initialized
tart 0Advertising successfully started
x0010 end 0x0016
--- 528 messages dropped ---
[00:00:00.259,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0018 offset 0 length 5
[00:00:00.259,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x001b offset 0 length 5
[00:00:00.260,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x001d offset 0 length 5
[00:00:00.261,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x001f offset 0 length 2
[00:00:00.261,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0020 offset 0 length 5
[00:00:00.262,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0023 offset 0 length 2
[00:00:00.262,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0024 offset 0 length 5
[00:00:00.263,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0027 offset 0 length 16
[00:00:00.264,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0028 offset 0 length 16
[00:00:00.265,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x002b offset 0 length 16
[00:00:00.266,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x002d offset 0 length 16
[00:00:00.267,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x002f offset 0 length 2
[00:00:00.267,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0030 offset 0 length 16
[00:00:00.268,000] <dbg> bt_gatt.bt_gatt_attr_read: handle 0x0032 offset 0 length 16
[00:00:00.270,000] <dbg> bt_gatt: Hash: 
9d b0 23 d1 d5 24 27 e2 |..#..$'.
a9 36 0b 9b 5c 3b f5 78 |.6..\;.x
[00:00:00.321,000] <dbg> bt_gatt.db_hash_store: Database Hash stored
Connected
[00:00:20.661,000] <dbg> bt_hci_core.bt_recv: buf 0x200030c0 len 21
[00:00:20.661,000] <dbg> bt_hci_core.hci_event: event 0x3e
[00:00:20.661,000] <dbg> bt_hci_core.hci_le_meta_event: subevent 0x01
[00:00:20.661,000] <dbg> bt_hci_core.le_legacy_conn_complete: status 0 role 1 b8:27:eb:93:88:8c (public)
[00:00:20.662,000] <dbg> bt_hci_core.enh_conn_complete: status 0 handle 2049 role 1 b8:27:eb:93:88:8c (public)
[00:00:20.662,000] <dbg> bt_conn.bt_conn_set_state: disconnected -> connected
[00:00:20.662,000] <dbg> bt_conn.bt_conn_ref: handle 2049 ref 2
[00:00:20.662,000] <dbg> bt_att.bt_att_accept: conn 0x200005ec handle 2049
[00:00:20.662,000] <dbg> bt_l2cap.bt_l2cap_chan_add: conn 0x200005ec chan 0x20000720
[00:00:20.662,000] <dbg> bt_att.bt_att_connected: chan 0x20000720 cid 0x0004
[00:00:20.662,000] <dbg> bt_l2cap.bt_l2cap_chan_add: conn 0x200005ec chan 0x200008c0
[00:00:20.662,000] <dbg> bt_l2cap.l2cap_accept: conn 0x200005ec handle 2049
[00:00:20.662,000] <dbg> bt_l2cap.bt_l2cap_chan_add: conn 0x200005ec chan 0x2000068c
[00:00:20.662,000] <dbg> bt_l2cap.l2cap_connected: ch 0x2000068c cid 0x0005
[00:00:20.663,000] <dbg> bt_gatt.bt_gatt_connected: conn 0x200005ec
[00:00:20.663,000] <dbg> bt_conn.bt_conn_unref: handle 2049 ref 1
[00:00:20.664,000] <dbg> bt_hci_core.process_events: count 2
[00:00:20.664,000] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:20.664,0Called legacy_request_tk
Passkey for b8:27:eb:93:88:8c (public): 207703
0[00:00:20.819,000] <dbg> bt_conn.bt_conn_send_cb: conn handle 2049 buf len 7 cb 0x080292b5
--- 30 messages dropped ---
[00:00:20.819,000] <dbg> bt_att.att_mtu_req: Negotiated MTU 65
[00:00:20.819,000] <dbg> bt_conn.bt_conn_unref: handle 2049 ref 1
[00:00:20.819,000] <dbg> bt_hci_core.process_events: count 4
[00:00:20.819,000] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:20.819,000] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:20.819,000] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:20.819,000] <dbg> bt_hci_core.process_events: ev->state 4
[00:00:20.819,000] <dbg> bt_conn.bt_conn_process_tx: conn 0x200005ec
[00:00:20.819,000] <dbg> bt_conn.send_buf: conn 0x200005ec buf 0x20003108 len 11
[00:00:20.819,000] <dbg> bt_conn.send_frag: conn 0x200005ec buf 0x20003108 len 11 flags 0x00
[00:00:20.819,000] <dbg> bt_conn.bt_conn_notify_tx: conn 0x200005ec
[00:00:20.819,000] <dbg> bt_conn.add_pending_tx: conn 0x200005ec cb 0x00000000
[00:00:20.820,000] <dbg> bt_hci_core.bt_send: buf 0x20003108 len 15 type 2
[00:00:20.820,000] <dbg> bt_conn.bt_conn_prepare_events: 
[00:00:20.820,000] <dbg> bt_conn.bt_conn_prepare_events: Adding conn 0x200005ec to poll list
[00:00:20.820,000] <dbg> bt_hci_core.hci_tx_thread: Calling k_poll with 4 events
[00:00:20.820,000] <dbg> bt_hci_core.process_events: count 4
[00:00:20.820,000] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:20.820,000] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:20.820,000] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:20.821,000] <dbg> bt_hci_core.process_events: ev->state 4
[00:00:20.821,000] <dbg> bt_conn.bt_conn_process_tx: conn 0x200005ec
[00:00:20.821,000] <dbg> bt_conn.send_buf: conn 0x200005ec buf 0x20003120 len 7
[00:00:20.821,000] <dbg> bt_conn.send_frag: conn 0x200005ec buf 0x20003120 len 7 flags 0x00
***** USAGE FAULT *****
  Illegal load of EXC_RETURN into PC
***** Hardware exception *****
Current thread ID = 0x2000021c
Faulting instruction address = 0x3c6ef372
Fatal fault in thread 0x2000021c! Aborting.
[00:00:21.020,000] <dbg> bt_hci_core.hci_num_completed_packets: num_handles 1
[00:00:21.027,000] <dbg> bt_hci_core.hci_num_completed_packets: handle 2049 count 1
[00:00:21.035,000] <dbg> bt_conn.bt_conn_ref: handle 2049 ref 2
[00:00:21.042,000] <dbg> bt_conn.bt_conn_unref: handle 2049 ref 1
[00:00:21.048,000] <dbg> bt_conn.bt_conn_notify_tx: conn 0x200005ec
[00:00:21.055,000] <dbg> bt_conn.add_pending_tx: conn 0x200005ec cb 0x080292b5
[00:00:21.062,000] <dbg> bt_hci_core.bt_send: buf 0x20003120 len 11 type 2
[00:00:21.070,000] <dbg> bt_conn.bt_conn_prepare_events: 
[00:00:21.076,000] <dbg> bt_conn.bt_conn_prepare_events: Adding conn 0x200005ec to poll list
[00:00:21.085,000] <dbg> bt_hci_core.hci_tx_thread: Calling k_poll with 4 events
***** USAGE FAULT *****
  Illegal load of EXC_RETURN into PC
***** Hardware exception *****
Current thread ID = 0x20000494
Faulting instruction address = 0x20004080
Fatal fault in thread 0x20000494! Aborting.
[00:00:25.664,000] <dbg> bt_conn.conn_le_update_timeout: conn 0x200005ec
[00:00:25.671,000] <dbg> bt_conn.send_conn_le_param_update: conn 0x200005ec features 0x00 params (24-40 0 42)
[00:00:25.681,000] <dbg> bt_l2cap.bt_l2cap_send_cb: conn 0x200005ec cid 5 len 12
[00:00:25.689,000] <dbg> bt_conn.bt_conn_send_cb: conn handle 2049 buf len 16 cb 0x00000000
[00:00:25.698,000] <dbg> bt_hci_core.process_events: count 4
[00:00:25.704,000] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:25.710,000] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:25.717,000] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:25.723,000] <dbg> bt_hci_core.process_events: ev->state 4
[00:00:25.729,000] <dbg> bt_conn.bt_conn_process_tx: conn 0x200005ec
[00:00:25.736,000] <dbg> bt_conn.send_buf: conn 0x200005ec buf 0x20003120 len 16
[00:00:25.744,000] <dbg> bt_conn.send_frag: conn 0x200005ec buf 0x20003120 len 16 flags 0x00
[00:00:50.806,000] <err> bt_smp: SMP Timeout

Environment (please complete the following information):

Additional context Raspberrpi bluetoothctl pairing info:

[bluetooth]# pair 4C:5E:AA:B4:67:EC 
Attempting to pair with 4C:5E:AA:B4:67:EC
[CHG] Device 4C:5E:AA:B4:67:EC Connected: yes
Request passkey
[agent] Enter passkey (number in 0-999999): 207703
[Zephyr Peripheral Sample Long]# info 
Device 4C:5E:AA:B4:67:EC (random)
    Name: Zephyr Peripheral Sample Long
    Alias: Zephyr Peripheral Sample Long
    Paired: no
    Trusted: yes
    Blocked: no
    Connected: yes
    LegacyPairing: no
    UUID: Heart Rate                (0000180d-0000-1000-8000-00805f9b34fb)
    UUID: Battery Service           (0000180f-0000-1000-8000-00805f9b34fb)
    UUID: Current Time Service      (00001805-0000-1000-8000-00805f9b34fb)
    UUID: Vendor specific           (12345678-1234-5678-1234-56789abcdef0)
    RSSI: -51
    AdvertisingFlags:
  06                                               .               
[CHG] Device 4C:5E:AA:B4:67:EC Connected: no
Failed to pair: org.bluez.Error.ConnectionAttemptFailed
[DEL] Device 4C:5E:AA:B4:67:EC Zephyr Peripheral Sample Long
jhedberg commented 5 years ago

I don't have this board, so I can't really do much about this with the given information. Do the instruction pointers resolve to some meaningful place in the code? Which threads are the ones that are faulting? Have you double-checked that this isn't a thread stack overflow?

parthitce commented 5 years ago

@jhedberg I haven't checked the addr2line, will do it tomorrow. I am not sure about the stack size, I have also tried with increased *STACK_SIZE's, still no luck.

jhedberg commented 5 years ago

@erwango do you know anything about Bluetooth support on this board?

erwango commented 5 years ago

@jhedberg, BLE module on this board is 4.1. We've used it to perform IPSP demos.

parthitce commented 5 years ago

@erwango Thanks, yes it got 4.1 based on ST's SPBTLE-RF module. It has the LE protocol stack built into the module and access is provided over SPI.

Is 4.1 a restriction for this use case?

erwango commented 5 years ago

Is 4.1 a restriction for this use case?

I don't think so, I was hoping it could help @jhedberg for his analysis.

erwango commented 5 years ago

@parthitce, fixed on my side by https://github.com/erwango/zephyr/commit/17108ad2f23eb218cc784d730785c9541a16b5e2

parthitce commented 5 years ago

@erwango Thank you very much for that. I will check the same in my end today evening CEST.

jhedberg commented 5 years ago

@erwango what's the reason to disable enforcing ATT flow control? Is this bug in the controller?

erwango commented 5 years ago

@jhedberg, I'm not quite sure. Use case was not working, and a bt_att warning message was generated "Ignoring unexpected request", linked to flow control enforcement. I don't have controller source code so, I can't comment much more.

parthitce commented 5 years ago

@erwango I still see the same problem with some additional errors after applying the patches.

***** Booting Zephyr OS v1.14.0-rc1-2651-g78790c4f8b96 *****
Bluetooth initialized
[00:00:00.110,000]Advertising successfully started
 <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
--- 86 messages dropped ---
[00:00:00.111,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.111,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.112,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.112,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.113,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.114,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.114,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.115,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.115,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.116,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.116,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.117,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.117,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.118,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.119,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.119,000] <err> settings: set-value failure. key: bt error(-2)
[00:00:00.120,000] <err> settings: set-value failure. key: bt error(-2)
[00:00:00.120,000] <err> settings: set-value failure. key: bt error(-2)
[00:00:00.121,000] <err> settings: set-value failure. key: bt error(-2)
[00:00:00.121,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.122,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.123,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.123,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.124,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.124,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.125,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.125,000] <err> settings: set-value failure. key: <log_strdup alloc failed> error(-2)
[00:00:00.137,000] <inf> bt_hci_core: Identity: <log_strdup alloc failed>
[00:00:00.137,000] <inf> bt_hci_core: HCI: version 4.1 (0x07) revision 0x3107, manufacturer 0x0030
[00:00:00.137,000] <inf> bt_hci_core: LMP: version 4.1 (0x07) subver 0x0023
Connected
Passkey for b8:27:eb:93:88:8c (public): 147633
***** USAGE FAULT *****
  Illegal use of the EPSR
***** Hardware exception *****
Current thread ID = 0x2000021c
Faulting instruction address = 0x0
Fatal fault in thread 0x2000021c! Aborting.
[00:00:46.141,000] <err> bt_smp: SMP Timeout
[00:00:54.299,000] <wrn> bt_smp: SMP command (code 0x03) received after timeout
Disconnected (reason 19)
***** USAGE FAULT *****
  Unaligned memory access
***** Hardware exception *****
Current thread ID = 0x20000494
Faulting instruction address = 0x800b32e
Fatal fault in thread 0x20000494! Aborting.

RPI end:

pi@raspberrypi:~ $ systemctl status bluetooth
● bluetooth.service - Bluetooth service
   Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2019-05-15 18:29:16 BST; 2s ago
     Docs: man:bluetoothd(8)
 Main PID: 655 (bluetoothd)
   Status: "Running"
   CGroup: /system.slice/bluetooth.service
           └─655 /usr/libexec/bluetooth/bluetoothd -E

May 15 18:29:16 raspberrypi systemd[1]: Starting Bluetooth service...
May 15 18:29:16 raspberrypi bluetoothd[655]: Bluetooth daemon 5.50
May 15 18:29:16 raspberrypi systemd[1]: Started Bluetooth service.
May 15 18:29:16 raspberrypi bluetoothd[655]: Starting SDP server
May 15 18:29:16 raspberrypi bluetoothd[655]: Bluetooth management interface 1.14 initialized
pi@raspberrypi:~ $ 
pi@raspberrypi:~ $ 
pi@raspberrypi:~ $ 
pi@raspberrypi:~ $ sudo bluetoothctl 
Agent registered
[bluetooth]# power on
Changing power on succeeded
[bluetooth]# discoverable on 
Changing discoverable on succeeded
[CHG] Controller B8:27:EB:93:88:8C Discoverable: yes
[bluetooth]# pairable on
Changing pairable on succeeded
[bluetooth]# scan on
Discovery started
[CHG] Controller B8:27:EB:93:88:8C Discovering: yes
[NEW] Device 7E:6F:27:53:0C:B4 Zephyr Peripheral Sample Long
[NEW] Device 5A:FB:B1:EC:2A:30 5A-FB-B1-EC-2A-30
[NEW] Device 4A:45:A1:50:43:1D 4A-45-A1-50-43-1D
[NEW] Device 7B:3F:5F:A3:CD:96 7B-3F-5F-A3-CD-96
[CHG] Device 5A:FB:B1:EC:2A:30 RSSI: -89
[CHG] Device 5A:FB:B1:EC:2A:30 AdvertisingFlags:
  00                                               .               
[CHG] Device 7B:3F:5F:A3:CD:96 RSSI: -95
[CHG] Device 7B:3F:5F:A3:CD:96 AdvertisingFlags:
  00                                               .               
[bluetooth]# scan off
Discovery stopped
[CHG] Controller B8:27:EB:93:88:8C Discovering: no
[CHG] Device 7B:3F:5F:A3:CD:96 RSSI is nil
[CHG] Device 4A:45:A1:50:43:1D RSSI is nil
[CHG] Device 5A:FB:B1:EC:2A:30 RSSI is nil
[CHG] Device 7E:6F:27:53:0C:B4 RSSI is nil
[bluetooth]# trust 7E:6F:27:53:0C:B4 
[CHG] Device 7E:6F:27:53:0C:B4 Trusted: yes
Changing 7E:6F:27:53:0C:B4 trust succeeded
[bluetooth]# pair 7E:6F:27:53:0C:B4 
[bluetooth]# pair 7E:6F:27:53:0C:B4 
Attempting to pair with 7E:6F:27:53:0C:B4
[CHG] Device 7E:6F:27:53:0C:B4 Connected: yes
Request passkey
[agent] Enter passkey (number in 0-999999): [NEW] Primary Service
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0001
    00001801-0000-1000-8000-00805f9b34fb
    Generic Attribute Profile
[NEW] Primary Service
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service000d
    00001805-0000-1000-8000-00805f9b34fb
    Current Time Service
[NEW] Characteristic
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service000d/char000e
    00002a2b-0000-1000-8000-00805f9b34fb
    Current Time
[NEW] Descriptor
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service000d/char000e/desc0010
    00002902-0000-1000-8000-00805f9b34fb
    Client Characteristic Configuration
[NEW] Primary Service
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0011
    0000180a-0000-1000-8000-00805f9b34fb
    Device Information
[NEW] Characteristic
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0011/char0012
    00002a24-0000-1000-8000-00805f9b34fb
    Model Number String
[NEW] Characteristic
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0011/char0014
    00002a29-0000-1000-8000-00805f9b34fb
    Manufacturer Name String
[NEW] Characteristic
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0011/char0016
    00002a50-0000-1000-8000-00805f9b34fb
    PnP ID
[NEW] Primary Service
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0018
    0000180d-0000-1000-8000-00805f9b34fb
    Heart Rate
[NEW] Characteristic
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0018/char0019
    00002a37-0000-1000-8000-00805f9b34fb
    Heart Rate Measurement
[NEW] Descriptor
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0018/char0019/desc001b
    00002902-0000-1000-8000-00805f9b34fb
    Client Characteristic Configuration
[NEW] Characteristic
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0018/char001c
    00002a38-0000-1000-8000-00805f9b34fb
    Body Sensor Location
[NEW] Characteristic
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0018/char001e
    00002a39-0000-1000-8000-00805f9b34fb
    Heart Rate Control Point
[NEW] Primary Service
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0020
    12345678-1234-5678-1234-56789abcdef0
    Vendor specific
[NEW] Characteristic
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0020/char0021
    12345678-1234-5678-1234-56789abcdef1
    Vendor specific
[NEW] Descriptor
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0020/char0021/desc0023
    00002902-0000-1000-8000-00805f9b34fb
    Client Characteristic Configuration
[NEW] Characteristic
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0020/char0024
    12345678-1234-5678-1234-56789abcdef2
    Vendor specific
[NEW] Characteristic
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0020/char0026
    12345678-1234-5678-1234-56789abcdef3
    Vendor specific
[NEW] Descriptor
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0020/char0026/desc0028
    00002900-0000-1000-8000-00805f9b34fb
    Characteristic Extended Properties
[NEW] Characteristic
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0020/char0029
    13345678-1234-5678-1334-56789abcdef3
    Vendor specific
[NEW] Characteristic
    /org/bluez/hci0/dev_7E_6F_27_53_0C_B4/service0020/char002b
    12345678-1234-5678-1234-56789abcdef4
    Vendor specific
[CHG] Device 7E:6F:27:53:0C:B4 UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Device 7E:6F:27:53:0C:B4 UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Device 7E:6F:27:53:0C:B4 UUIDs: 00001805-0000-1000-8000-00805f9b34fb
[CHG] Device 7E:6F:27:53:0C:B4 UUIDs: 0000180a-0000-1000-8000-00805f9b34fb
[CHG] Device 7E:6F:27:53:0C:B4 UUIDs: 0000180d-0000-1000-8000-00805f9b34fb
[CHG] Device 7E:6F:27:53:0C:B4 UUIDs: 0000180f-0000-1000-8000-00805f9b34fb
[CHG] Device 7E:6F:27:53:0C:B4 UUIDs: 12345678-1234-5678-1234-56789abcdef0
[CHG] Device 7E:6F:27:53:0C:B4 ServicesResolved: yes
[CHG] Device 7E:6F:27:53:0C:B4 Name: Zephyr Peripheral Sample Long Name
[CHG] Device 7E:6F:27:53:0C:B4 Alias: Zephyr Peripheral Sample Long Name
[CHG] Device 7E:6F:27:53:0C:B4 Appearance: 0x0341
[CHG] Device 7E:6F:27:53:0C:B4 Modalias: bluetooth:v0000p0000d0001
147633
[Zephyr Peripheral Sample Long]# info 
Device 7E:6F:27:53:0C:B4 (random)
    Name: Zephyr Peripheral Sample Long Name
    Alias: Zephyr Peripheral Sample Long Name
    Appearance: 0x0341
    Paired: no
    Trusted: yes
    Blocked: no
    Connected: yes
    LegacyPairing: no
    UUID: Generic Access Profile    (00001800-0000-1000-8000-00805f9b34fb)
    UUID: Generic Attribute Profile (00001801-0000-1000-8000-00805f9b34fb)
    UUID: Current Time Service      (00001805-0000-1000-8000-00805f9b34fb)
    UUID: Device Information        (0000180a-0000-1000-8000-00805f9b34fb)
    UUID: Heart Rate                (0000180d-0000-1000-8000-00805f9b34fb)
    UUID: Battery Service           (0000180f-0000-1000-8000-00805f9b34fb)
    UUID: Vendor specific           (12345678-1234-5678-1234-56789abcdef0)
    Modalias: bluetooth:v0000p0000d0001
    AdvertisingFlags:
  06                                               .

Thanks for your help.

jhedberg commented 5 years ago

@erwango what's the reason to disable enforcing ATT flow control? Is this bug in the controller?

@jhedberg, I'm not quite sure. Use case was not working, and a bt_att warning message was generated "Ignoring unexpected request", linked to flow control enforcement. I don't have controller source code so, I can't comment much more.

@erwango the other HCI driver exceptions where the ATT flow control is disabled have well understood technical reasons: they're cases where USB HCI transport is used, and due to USB having ACL data and HCI events in different endpoints this creates a potential race condition where these get received in the wrong order, making the host think that a request wasn't yet sent when it already receives the response to it.

Could you at least check from the HCI logs if some similar issue is happening with your controller? I.e. look at how the HCI Number of Completed Packets events are reported wrt. corresponding outgoing ACL data packets.

erwango commented 5 years ago

@jhedberg: Node of the issue should lie in the following messages, but seems too much subtle to my eyes.

> HCI Event: LE Meta Event (0x3e) plen 19                                #40 37.599300
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 2049
        Role: Slave (0x01)
        Peer address type: Random (0x01)
        Peer address: 47:94:61:B5:8E:35 (Resolvable)
        Connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 5000 msec (0x01f4)
        Master clock accuracy: 0x01
= Note: Connected: ACL starts now                                    37.602200
> ACL Data RX: Handle 2049 flags 0x02 dlen 11                           #41 37.837600
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0001-0xffff
        Attribute group type: Primary Service (0x2800)
< ACL Data TX: Handle 2049 flags 0x00 dlen 24                           #42 37.840200
      ATT: Read By Group Type Response (0x11) len 19
        Attribute data length: 6
        Attribute group list: 3 entries
        Handle range: 0x0001-0x0001
        UUID: Generic Attribute Profile (0x1801)
        Handle range: 0x0002-0x0008
        UUID: Generic Access Profile (0x1800)
        Handle range: 0x0009-0x000c
        UUID: Battery Service (0x180f)
> HCI Event: Number of Completed Packets (0x13) plen 5              #43 37.937100
        Num handles: 1
        Handle: 2049
        Count: 1
> ACL Data RX: Handle 2049 flags 0x02 dlen 11                             #44 37.939200
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x000d-0xffff
        Attribute group type: Primary Service (0x2800)
= bt: bt_att: Ignoring unexpected request                                         37.941300
erwango commented 5 years ago

@parthitce, peripheral sample requires some flash configuration which is not yet available on disco. Use of BT settings could be deactivated with:

CONFIG_BT_SETTINGS=n
CONFIG_FLASH=n
CONFIG_FLASH_PAGE_LAYOUT=n
CONFIG_FLASH_MAP=n
CONFIG_FCB=n
CONFIG_SETTINGS=n
CONFIG_SETTINGS_FCB=n

Then, on my side, I've been testing using Android apps like NRF Connect or ST BLE Profile. I don't have RPI to test with.

Also, this is not the case for this test case for me right now, but I know following option has enabled to avoid some issues like 'Illegal Use of ESPR' in specific conditions:

CONFIG_LINKER_SORT_BY_ALIGNMENT=n
parthitce commented 5 years ago

@erwango Thanks for feedback. Will check again with the disabled BT settings today.

jhedberg commented 5 years ago

@jhedberg: Node of the issue should lie in the following messages, but seems too much subtle to my eyes.

@erwango I don't see anything wrong with that. @Vudentz do you?

Vudentz commented 5 years ago

= bt: bt_att: Ignoring unexpected request 37.941300

Weird, that shouldn't happen as there should not be anything pending or perhaps it still waiting att_rsp_sent? I can see the packet completed update though, perhaps we need more debug to log exactly why this is happening.

erwango commented 5 years ago

@erwango I don't see anything wrong with that. @Vudentz do you?

Great to see my eyes are not the problem here :-)

@Vudentz, I can provide log from the beginning, if github allows

erwango commented 5 years ago

So here it the log, from the boot:

= New Index: 00:00:00:00:00:00 (Primary,SPI,SPBTLE-)                                                              0.000300
= Note: ***** Booting Zephyr OS zephyr-v1.14.0-774-g408172533b45 *****                                            0.002900
< HCI Command: Vendor (0x3f|0x000c) plen 3                                                                     #1 0.014700
        2c 01 01                                         ,..             
= Open Index: 00:00:00:00:00:00                                                                                   0.016700
* Drops: cmd 0 evt 1 acl_tx 0 acl_rx 0 sco_tx 0 sco_rx 0 other 0
< HCI Command: Read Local Supported Features (0x04|0x0003) plen 0                                              #2 0.018500
> HCI Event: Command Complete (0x0e) plen 12                                                                   #3 0.021100
      Read Local Supported Features (0x04|0x0003) ncmd 1
        Status: Success (0x00)
        Features: 0x00 0x00 0x00 0x00 0x60 0x00 0x00 0x00
          BR/EDR Not Supported
          LE Supported (Controller)
< HCI Command: Read Local Version Information (0x04|0x0001) plen 0                                             #4 0.023400
> HCI Event: Command Complete (0x0e) plen 12                                                                   #5 0.025800
      Read Local Version Information (0x04|0x0001) ncmd 1
        Status: Success (0x00)
        HCI version: Bluetooth 4.1 (0x07) - Revision 12551 (0x3107)
        LMP version: Bluetooth 4.1 (0x07) - Subversion 35 (0x0023)
        Manufacturer: ST Microelectronics (48)
< HCI Command: Read BD ADDR (0x04|0x0009) plen 0                                                               #6 0.028100
> HCI Event: Command Complete (0x0e) plen 10                                                                   #7 0.030400
      Read BD ADDR (0x04|0x0009) ncmd 1
        Status: Success (0x00)
        Address: FF:FF:FF:FF:FF:FF (OUI FF-FF-FF)
< HCI Command: Read Local Supported Commands (0x04|0x0002) plen 0                                              #8 0.032600
> HCI Event: Command Complete (0x0e) plen 68                                                                   #9 0.036100
      Read Local Supported Commands (0x04|0x0002) ncmd 1
        Status: Success (0x00)
        Commands: 39 entries
          Disconnect (Octet 0 - Bit 5)
          Read Remote Version Information (Octet 2 - Bit 7)
          Set Event Mask (Octet 5 - Bit 6)
          Reset (Octet 5 - Bit 7)
          Read Transmit Power Level (Octet 10 - Bit 2)
          Read Local Version Information (Octet 14 - Bit 3)
          Read Local Supported Features (Octet 14 - Bit 5)
          Read BD ADDR (Octet 15 - Bit 1)
          Read RSSI (Octet 15 - Bit 5)
          LE Set Event Mask (Octet 25 - Bit 0)
          LE Read Buffer Size (Octet 25 - Bit 1)
          LE Read Local Supported Features (Octet 25 - Bit 2)
          LE Set Random Address (Octet 25 - Bit 4)
          LE Set Advertising Parameters (Octet 25 - Bit 5)
          LE Read Advertising Channel TX Power (Octet 25 - Bit 6)
          LE Set Advertising Data (Octet 25 - Bit 7)
          LE Set Scan Response Data (Octet 26 - Bit 0)
          LE Set Advertise Enable (Octet 26 - Bit 1)
          LE Set Scan Parameters (Octet 26 - Bit 2)
          LE Set Scan Enable (Octet 26 - Bit 3)
          LE Create Connection (Octet 26 - Bit 4)
          LE Create Connection Cancel (Octet 26 - Bit 5)
          LE Read White List Size (Octet 26 - Bit 6)
          LE Clear White List (Octet 26 - Bit 7)
          LE Add Device To White List (Octet 27 - Bit 0)
          LE Remove Device From White List (Octet 27 - Bit 1)
          LE Connection Update (Octet 27 - Bit 2)
          LE Set Host Channel Classification (Octet 27 - Bit 3)
          LE Read Channel Map (Octet 27 - Bit 4)
          LE Read Remote Used Features (Octet 27 - Bit 5)
          LE Encrypt (Octet 27 - Bit 6)
          LE Rand (Octet 27 - Bit 7)
          LE Start Encryption (Octet 28 - Bit 0)
          LE Long Term Key Request Reply (Octet 28 - Bit 1)
          LE Long Term Key Request Neg Reply (Octet 28 - Bit 2)
          LE Read Supported States (Octet 28 - Bit 3)
          LE Receiver Test (Octet 28 - Bit 4)
          LE Transmitter Test (Octet 28 - Bit 5)
          LE Test End (Octet 28 - Bit 6)
< HCI Command: LE Rand (0x08|0x0018) plen 0                                                                   #10 0.043300
> HCI Event: Command Complete (0x0e) plen 12                                                                  #11 0.045800
      LE Rand (0x08|0x0018) ncmd 1
        Status: Success (0x00)
        Random number: 0xa71b73949f2bd0a8
< HCI Command: LE Rand (0x08|0x0018) plen 0                                                                   #12 0.055400
> HCI Event: Command Complete (0x0e) plen 12                                                                  #13 0.057800
      LE Rand (0x08|0x0018) ncmd 1
        Status: Success (0x00)
        Random number: 0x87e73ac33ca55ac4
< HCI Command: LE Rand (0x08|0x0018) plen 0                                                                   #14 0.060200
> HCI Event: Command Complete (0x0e) plen 12                                                                  #15 0.062600
      LE Rand (0x08|0x0018) ncmd 1
        Status: Success (0x00)
        Random number: 0x2c809f3476edd993
< HCI Command: LE Rand (0x08|0x0018) plen 0                                                                   #16 0.065000
> HCI Event: Command Complete (0x0e) plen 12                                                                  #17 0.067400
      LE Rand (0x08|0x0018) ncmd 1
        Status: Success (0x00)
        Random number: 0x384d45ecb20854c9
< HCI Command: LE Rand (0x08|0x0018) plen 0                                                                   #18 0.069800
> HCI Event: Command Complete (0x0e) plen 12                                                                  #19 0.072300
      LE Rand (0x08|0x0018) ncmd 1
        Status: Success (0x00)
        Random number: 0x550c949d6d183fbe
< HCI Command: LE Read Local Supported Features (0x08|0x0003) plen 0                                          #20 0.082500
> HCI Event: Command Complete (0x0e) plen 12                                                                  #21 0.085000
      LE Read Local Supported Features (0x08|0x0003) ncmd 1
        Status: Success (0x00)
        Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
          LE Encryption
< HCI Command: LE Read Buffer Size (0x08|0x0002) plen 0                                                       #22 0.087300
> HCI Event: Command Complete (0x0e) plen 7                                                                   #23 0.090700
      LE Read Buffer Size (0x08|0x0002) ncmd 1
        Status: Success (0x00)
        Data packet length: 27
        Num data packets: 1
< HCI Command: LE Read Supported States (0x08|0x001c) plen 0                                                  #24 0.092600
> HCI Event: Command Complete (0x0e) plen 12                                                                  #25 0.095100
      LE Read Supported States (0x08|0x001c) ncmd 1
        Status: Success (0x00)
        States: 0x00000000330000ff
          Non-connectable Advertising State
          Scannable Advertising State
          Connectable Advertising State
          High Duty Cycle Directed Advertising State
          Passive Scanning State
          Active Scanning State
          Initiating State
            and Connection State (Master Role)
          Connection State (Slave Role)
          Passive Scanning State
            and Connection State (Master Role)
          Active Scanning State
            and Connection State (Master Role)
          Initiating State
            and Connection State (Master Role)
            and Master Role & Master Role
          Low Duty Cycle Directed Advertising State
< HCI Command: LE Set Event Mask (0x08|0x0001) plen 8                                                         #26 0.097400
        Mask: 0x000000000000001f
          LE Connection Complete
          LE Advertising Report
          LE Connection Update Complete
          LE Read Remote Used Features Complete
          LE Long Term Key Request
> HCI Event: Command Complete (0x0e) plen 4                                                                   #27 0.100500
      LE Set Event Mask (0x08|0x0001) ncmd 1
        Status: Success (0x00)
< HCI Command: Set Event Mask (0x03|0x0001) plen 8                                                            #28 0.102200
        Mask: 0x2000800002008890
          Disconnection Complete
          Encryption Change
          Read Remote Version Information Complete
          Hardware Error
          Data Buffer Overflow
          Encryption Key Refresh Complete
          LE Meta
> HCI Event: Command Complete (0x0e) plen 4                                                                   #29 0.105300
      Set Event Mask (0x03|0x0001) ncmd 1
        Status: Success (0x00)
= Note: Bluetooth initialized                                                                                     0.124000
< HCI Command: LE Set Advertising Data (0x08|0x0008) plen 32                                                  #30 0.126900
        Length: 29
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (complete): 3 entries
          Heart Rate (0x180d)
          Battery Service (0x180f)
          Current Time Service (0x1805)
        128-bit Service UUIDs (complete): 1 entry
          Vendor specific (12345678-1234-5678-1234-56789abcdef0)
> HCI Event: Command Complete (0x0e) plen 4                                                                   #31 0.132600
      LE Set Advertising Data (0x08|0x0008) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Scan Response Data (0x08|0x0009) plen 32                                                #32 0.134300
        Length: 31
        Name (short): Zephyr Peripheral Sample Long
> HCI Event: Command Complete (0x0e) plen 4                                                                   #33 0.140000
      LE Set Scan Response Data (0x08|0x0009) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Random Address (0x08|0x0005) plen 6                                                     #34 0.147900
        Address: 4E:AB:90:98:CA:CF (Resolvable)
> HCI Event: Command Complete (0x0e) plen 4                                                                   #35 0.150800
      LE Set Random Address (0x08|0x0005) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Advertising Parameters (0x08|0x0006) plen 15                                            #36 0.152500
        Min advertising interval: 100.000 msec (0x00a0)
        Max advertising interval: 150.000 msec (0x00f0)
        Type: Connectable undirected - ADV_IND (0x00)
        Own address type: Random (0x01)
        Direct address type: Public (0x00)
        Direct address: 00:00:00:00:00:00 (OUI 00-00-00)
        Channel map: 37, 38, 39 (0x07)
        Filter policy: Allow Scan Request from Any, Allow Connect Request from Any (0x00)
> HCI Event: Command Complete (0x0e) plen 4                                                                   #37 0.156500
      LE Set Advertising Parameters (0x08|0x0006) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Set Advertise Enable (0x08|0x000a) plen 1                                                   #38 0.158200
        Advertising: Enabled (0x01)
> HCI Event: Command Complete (0x0e) plen 4                                                                   #39 0.160700
      LE Set Advertise Enable (0x08|0x000a) ncmd 1
        Status: Success (0x00)
= Note: Advertising successfully started                                                                          0.162400
= bt: spi_ll_stm32: CS control inhibited (no GPIO device)                                                         0.013800
= bt: bt_hci_core: ECC HCI commands not available                                                                 0.117900
= bt: bt_hci_core: Using temporary IRK                                                                            0.123400
= bt: bt_hci_core: Identity: d5:59:99:18:5c:99 (random)                                                           0.123800
= bt: bt_hci_core: HCI: version 4.1 (0x07) revision 0x3107, manufacturer 0x0030                                   0.123800
= bt: bt_hci_core: LMP: version 4.1 (0x07) subver 0x0023                                                          0.123900
> HCI Event: LE Meta Event (0x3e) plen 19                                                                    #40 37.599300
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 2049
        Role: Slave (0x01)
        Peer address type: Random (0x01)
        Peer address: 47:94:61:B5:8E:35 (Resolvable)
        Connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 5000 msec (0x01f4)
        Master clock accuracy: 0x01
= Note: Connected                                                                                                37.602200
> ACL Data RX: Handle 2049 flags 0x02 dlen 11                                                                #41 37.837600
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0001-0xffff
        Attribute group type: Primary Service (0x2800)
< ACL Data TX: Handle 2049 flags 0x00 dlen 24                                                                #42 37.840200
      ATT: Read By Group Type Response (0x11) len 19
        Attribute data length: 6
        Attribute group list: 3 entries
        Handle range: 0x0001-0x0001
        UUID: Generic Attribute Profile (0x1801)
        Handle range: 0x0002-0x0008
        UUID: Generic Access Profile (0x1800)
        Handle range: 0x0009-0x000c
        UUID: Battery Service (0x180f)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                       #43 37.937100
        Num handles: 1
        Handle: 2049
        Count: 1
> ACL Data RX: Handle 2049 flags 0x02 dlen 11                                                                #44 37.939200
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x000d-0xffff
        Attribute group type: Primary Service (0x2800)
= bt: bt_att: Ignoring unexpected request                                                                        37.941300
Vudentz commented 5 years ago

I guess you are missing CONFIG_BT_DEBUG_ATT so we can see the effect of things like Number of Completed Packets, that usually clears the pending flag which causes the error on the last line.

erwango commented 5 years ago

@Vudentz , I just had a try enabling CONFIG_BT_DEBUG_ATT? Though, for some reason, this does display more traces.

Using following config, I don't get more debug traces:

CONFIG_BT_DEBUG_ATT=y
CONFIG_BT_ATT_ENFORCE_FLOW=y

Using following config, I do see the traces, but at a later step, not reached in with the first config

CONFIG_BT_DEBUG_ATT=y
CONFIG_BT_ATT_ENFORCE_FLOW=n

Trace:

= Note: Connected                                                                                                11.409100
> ACL Data RX: Handle 2049 flags 0x02 dlen 11                                                                #41 11.642100
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0001-0xffff
        Attribute group type: Primary Service (0x2800)
< ACL Data TX: Handle 2049 flags 0x00 dlen 24                                                                #42 11.644900
      ATT: Read By Group Type Response (0x11) len 19
        Attribute data length: 6
        Attribute group list: 3 entries
        Handle range: 0x0001-0x0001
        UUID: Generic Attribute Profile (0x1801)
        Handle range: 0x0002-0x0008
        UUID: Generic Access Profile (0x1800)
        Handle range: 0x0009-0x000c
        UUID: Battery Service (0x180f)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                       #43 11.741500
        Num handles: 1
        Handle: 2049
        Count: 1
> ACL Data RX: Handle 2049 flags 0x02 dlen 11                                                                #44 11.743600
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x000d-0xffff
        Attribute group type: Primary Service (0x2800)
< ACL Data TX: Handle 2049 flags 0x00 dlen 24                                                                #45 11.746500
      ATT: Read By Group Type Response (0x11) len 19
        Attribute data length: 6
        Attribute group list: 3 entries
        Handle range: 0x000d-0x0010
        UUID: Current Time Service (0x1805)
        Handle range: 0x0011-0x0017
        UUID: Device Information (0x180a)
        Handle range: 0x0018-0x001f
        UUID: Heart Rate (0x180d)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                       #46 11.841700
        Num handles: 1
        Handle: 2049
        Count: 1
> ACL Data RX: Handle 2049 flags 0x02 dlen 11                                                                #47 11.843800
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0020-0xffff
        Attribute group type: Primary Service (0x2800)
< ACL Data TX: Handle 2049 flags 0x00 dlen 26                                                                #48 11.846700
      ATT: Read By Group Type Response (0x11) len 21
        Attribute data length: 20
        Attribute group list: 1 entry
        Handle range: 0x0020-0x002c
        UUID: Vendor specific (12345678-1234-5678-1234-56789abcdef0)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                       #49 11.942200
        Num handles: 1
        Handle: 2049
        Count: 1
> ACL Data RX: Handle 2049 flags 0x02 dlen 11                                                                #50 11.944300
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x002d-0xffff
        Attribute group type: Primary Service (0x2800)
> HCI Event: LE Meta Event (0x3e) plen 10                                                                    #51 11.947200
      LE Connection Update Complete (0x03)
        Status: Success (0x00)
        Handle: 2049
        Connection interval: 7.50 msec (0x0006)
        Connection latency: 0 (0x0000)
        Supervision timeout: 5000 msec (0x01f4)
< ACL Data TX: Handle 2049 flags 0x00 dlen 9                                                                 #52 11.949200
      ATT: Error Response (0x01) len 4
        Read By Group Type Request (0x10)
        Handle: 0x002d
        Error: Attribute Not Found (0x0a)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                       #53 12.003500
        Num handles: 1
        Handle: 2049
        Count: 1
> ACL Data RX: Handle 2049 flags 0x02 dlen 11                                                                #54 12.005600
      ATT: Read By Type Request (0x08) len 6
        Handle range: 0x0001-0x0001
        Attribute type: Include (0x2802)
< ACL Data TX: Handle 2049 flags 0x00 dlen 9                                                                 #55 12.008200
      ATT: Error Response (0x01) len 4
        Read By Type Request (0x08)
        Handle: 0x0001
        Error: Attribute Not Found (0x0a)
* Drops: cmd 0 evt 1 acl_tx 1 acl_rx 1 sco_tx 0 sco_rx 0 other 0
* Drops: cmd 0 evt 1 acl_tx 1 acl_rx 1 sco_tx 0 sco_rx 0 other 0
* Drops: cmd 0 evt 1 acl_tx 1 acl_rx 1 sco_tx 0 sco_rx 0 other 0
* Drops: cmd 0 evt 1 acl_tx 1 acl_rx 1 sco_tx 0 sco_rx 0 other 0
* Drops: cmd 0 evt 1 acl_tx 1 acl_rx 1 sco_tx 0 sco_rx 0 other 0
* Drops: cmd 0 evt 1 acl_tx 1 acl_rx 1 sco_tx 0 sco_rx 0 other 0
erwango commented 5 years ago

@parthitce, I've been able to use bluetoothctl (not on RPI though), I can connect with instruction 'connect'. But I don't think that pair command could work with current peripheral sample.

parthitce commented 5 years ago

@erwango Should I need to enable any specific defconfig option apart from PR 16146 ?

erwango commented 5 years ago

@parthitce, I've tested with:

CONFIG_BT_ATT_ENFORCE_FLOW=n
CONFIG_LINKER_SORT_BY_ALIGNMENT=n

But maybe CONFIG_LINKER_SORT_BY_ALIGNMENT=n is not needed

parthitce commented 5 years ago

@erwango Thanks. I will check it now.

parthitce commented 5 years ago

@erwango Thanks. The sample worked fine. I am able to find the GATT UUIDS and there isn't any crash.

***** Booting Zephyr OS zephyr-v1.14.0-838-gfbac5745c814 *****
Bluetooth initialized
Advertising successfully started
[00:00:00.010,000] <inf> spi_ll_stm32: CS control inhibited (no GPIO device)
[00:00:00.064,000] <wrn> bt_hci_core: ECC HCI commands not available
[00:00:00.069,000] <wrn> bt_hci_core: Using temporary IRK
[00:00:00.070,000] <inf> bt_hci_core: Identity: ce:88:bc:3a:54:71 (random)
[00:00:00.070,000] <inf> bt_hci_core: HCI: version 4.1 (0x07) revision 0x3107, manufacturer 0x0030
[00:00:00.070,000] <inf> bt_hci_core: LMP: version 4.1 (0x07) subver 0x0023
Connected
parthitce commented 5 years ago

@erwango I also tried mcuboot + smp_svr. I am able to start the application without any problem. But when I try communicate with the target over bluetooth 2nd time, I am facing another exception.

Still I am managed to upload the new image by reset + re-do i.e. the first time it always works, but fails running the 2nd time.

Can you share any clues to fix this? If not in this bug, can I open a another one?

RPI end:

pi@raspberrypi:~/fota/bin $ sudo ./mcumgr --conntype ble --connstring 'peer_name=Zephyr' image confirm
Images:
 slot=0
    version: 1.0.0
    bootable: true
    flags: active confirmed
    hash: d7707fd16c935d75f4984a30ebc57b7c869c53212fe48cb296b331840bf4b573
 slot=1
    version: 1.0.0
    bootable: true
    flags: 
    hash: 00b1ae3c7fbcdfc3f6cb4d4cba82e00d9b52f554a691d215b2a8032250eacbe7
Split status: N/A (0)
pi@raspberrypi:~/fota/bin $ sudo ./mcumgr --conntype ble --connstring 'peer_name=Zephyr' image list

Error: Failed to connect to peer after 10s

Zephyr end:

***** Booting Zephyr OS zephyr-v1.14.0-838-gfbac5745c814 *****
[00:00:00.005,000] <inf> mcuboot: Starting bootloader
[00:00:00.012,000] <inf> mcuboot: Primary image: magic=bad, copy_done=0x2, image_ok=0x2
[00:00:00.020,000] <inf> mcuboot: Scratch: magic=unset, copy_done=0x0, image_ok=0x3
[00:00:00.028,000] <inf> mcuboot: Boot source: none
[00:00:00.034,000] <inf> mcuboot: Swap type: test
[00:00:06.790,000] <inf> mcuboot: Bootloader chainload address offset: 0x20000
[00:00:06.798,000] <inf> mcuboot: Jumping to the first image slot
***** Booting Zephyr OS zephyr-v1.14.0-838-gfbac5745c814 *****
Error getting NFFS flash device binding
New image

uart:~$ Bluetooth initialized
Advertising successfully started
uart:~$ Connected
uart:~$ Disconnected (reason 8)
uart:~$ ***** USAGE FAULT *****
  Illegal use of the EPSR
***** Hardware exception *****
Current thread ID = 0x2000043c
Faulting instruction address = 0x10
Fatal fault in thread 0x2000043c! Aborting.
parthitce commented 5 years ago

@erwango Additional information about the new problem. I am missed enabling CONFIG_MCUMGR_SMP_UART=y for smp_svr example. Now after enabling this defconfig, there is no crash observed.

To observe it, I have opened bluetoothctl in one shell and tried running mcumgr in another. Now after running the mcumgr, the RPI bluetooth controller itself going down. Not sure why. I have captured the btmon output as well. As the log is huge, just copied it here : https://pastebin.com/kMQUGvbm

RPI shell 1:

pi@raspberrypi:~/fota/bin $ sudo ./mcumgr --conntype ble --connstring 'peer_name=Zephyr' image list
Images:
 slot=0
    version: 1.0.0
    bootable: true
    flags: active confirmed
    hash: 3e1d942586087b899c45a2393159d9a33f086083836898af6dfd1e10b238e9f6
 slot=1
    version: 1.0.0
    bootable: true
    flags: 
    hash: 00b1ae3c7fbcdfc3f6cb4d4cba82e00d9b52f554a691d215b2a8032250eacbe7
Split status: N/A (0)

RPI shell 2:

pi@raspberrypi:~ $ sudo bluetoothctl 
Agent registered
[bluetooth]# power on
Changing power on succeeded
[bluetooth]# discoverable on
Changing discoverable on succeeded
[CHG] Controller B8:27:EB:93:88:8C Discoverable: yes
[bluetooth]# pairable on
Changing pairable on succeeded
[bluetooth]# menu scan

[bluetooth]# clear
SetDiscoveryFilter success
[bluetooth]# back

[bluetooth]# scan on
Discovery started
[CHG] Controller B8:27:EB:93:88:8C Discovering: yes
[NEW] Device E3:7D:F8:7F:AC:21 Zephyr
[bluetooth]# info E3:7D:F8:7F:AC:21 
Device E3:7D:F8:7F:AC:21 (random)
    Name: Zephyr
    Alias: Zephyr
    Paired: no
    Trusted: no
    Blocked: no
    Connected: no
    LegacyPairing: no
    UUID: Vendor specific           (8d53dc1d-1db7-4cd3-868b-8a527460aa84)
    RSSI: -66
    AdvertisingFlags:
  06                                               .               
[CHG] Device E3:7D:F8:7F:AC:21 RSSI: -69
[CHG] Device E3:7D:F8:7F:AC:21 RSSI is nil
[CHG] Controller B8:27:EB:93:88:8C Powered: no
[CHG] Controller B8:27:EB:93:88:8C Discovering: no
[CHG] Controller B8:27:EB:93:88:8C Discoverable: no
[CHG] Controller B8:27:EB:93:88:8C Powered: yes
[CHG] Controller B8:27:EB:93:88:8C Powered: no
[CHG] Controller B8:27:EB:93:88:8C Discovering: no
[DEL] Device E3:7D:F8:7F:AC:21 Zephyr
[DEL] Controller B8:27:EB:93:88:8C raspberrypi [default]
[NEW] Controller B8:27:EB:93:88:8C raspberrypi [default]
[CHG] Controller B8:27:EB:93:88:8C Powered: yes
[CHG] Controller B8:27:EB:93:88:8C UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Controller B8:27:EB:93:88:8C UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
[CHG] Controller B8:27:EB:93:88:8C UUIDs: 00001200-0000-1000-8000-00805f9b34fb
[CHG] Controller B8:27:EB:93:88:8C UUIDs: 0000110c-0000-1000-8000-00805f9b34fb
[CHG] Controller B8:27:EB:93:88:8C UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Controller B8:27:EB:93:88:8C UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Controller B8:27:EB:93:88:8C UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
[CHG] Controller B8:27:EB:93:88:8C UUIDs: 00001200-0000-1000-8000-00805f9b34fb
[CHG] Controller B8:27:EB:93:88:8C UUIDs: 0000110c-0000-1000-8000-00805f9b34fb
[CHG] Controller B8:27:EB:93:88:8C UUIDs: 00001800-0000-1000-8000-00805f9b34fb
erwango commented 5 years ago

@erwango I also tried mcuboot + smp_svr. I am able to start the application without any problem. But when I try communicate with the target over bluetooth 2nd time, I am facing another exception.

Can you open a new issue for this exception? Resolution generally goes faster if we're able to clearly separate issues.

To observe it, I have opened bluetoothctl in one shell and tried running mcumgr in another. Now after running the mcumgr, the RPI bluetooth controller itself going down.

Maybe this should be raised to https://github.com/apache/mynewt-mcumgr, then.

parthitce commented 5 years ago

@erwango I also tried mcuboot + smp_svr. I am able to start the application without any problem. But when I try communicate with the target over bluetooth 2nd time, I am facing another exception.

Can you open a new issue for this exception? Resolution generally goes faster if we're able to clearly separate issues.

Sure, I understand.

To observe it, I have opened bluetoothctl in one shell and tried running mcumgr in another. Now after running the mcumgr, the RPI bluetooth controller itself going down.

Maybe this should be raised to https://github.com/apache/mynewt-mcumgr, then.

Am not sure. The same use case works fine with nrf52840_pca0056 target. So I am not sure whether the problem is with mcumgr.

Thanks for you help. I will close this issue now and open a new one for mcumgr related.

erwango commented 5 years ago

@parthitce , thanks for your understanding.

Though, I'm reopening the issue since according to @jhedberg and @Vudentz current proposed solution might not be the most appropriate.

jhedberg commented 5 years ago

Could you re-test this with latest master? I suspect #16612 may have fixed it.

erwango commented 5 years ago

@jhedberg, just tested and unfortunately, it doesn't... Still requires CONFIG_BT_ATT_ENFORCE_FLOW=n

jhedberg commented 5 years ago

This board uses drivers/bluetooth/hci/spi.c right? I just took a look at it and saw that it has a bug in the way bt_recv() and bt_recv_prio() are called. We have those two distinct APIs specifically so that bt_recv_prio() will be called from a higher priority context (either an ISR or a higher-priority thread), however looking at the SPI HCI driver they are both called from the same RX thread. That could explain the symptoms described in this issue.

jhedberg commented 5 years ago

Just a follow-up on my previous comment, one way to fix this would be to stop selecting BT_RECV_IS_RX_THREAD in drivers/bluetooth/hci/Kconfig and instead define the spi.c-internal thread with some lower priority than CONFIG_BT_RX_PRIO

jhedberg commented 5 years ago

Completely untested, but the fix I suggested would look something like this (in its simplest form):

--- a/drivers/bluetooth/hci/Kconfig
+++ b/drivers/bluetooth/hci/Kconfig
@@ -35,7 +35,6 @@ config BT_H5

 config BT_SPI
        bool "SPI HCI"
-       select BT_RECV_IS_RX_THREAD
        depends on SPI
        help
          Supports Bluetooth ICs using SPI as the communication protocol.
diff --git a/drivers/bluetooth/hci/spi.c b/drivers/bluetooth/hci/spi.c
index b83e288872..b513502182 100644
--- a/drivers/bluetooth/hci/spi.c
+++ b/drivers/bluetooth/hci/spi.c
@@ -507,7 +507,7 @@ static int bt_spi_open(void)
        k_thread_create(&rx_thread_data, rx_stack,
                        K_THREAD_STACK_SIZEOF(rx_stack),
                        (k_thread_entry_t)bt_spi_rx_thread, NULL, NULL, NULL,
-                       K_PRIO_COOP(CONFIG_BT_RX_PRIO),
+                       K_PRIO_COOP(CONFIG_BT_RX_PRIO - 1),
                        0, K_NO_WAIT);

        /* Take BLE out of reset */
erwango commented 5 years ago

@yboutreux, Can you test this patch?

jhedberg commented 5 years ago

Btw, if my patch works you'll probably want to substantially reduce the spi.c-internal rx_stack size since its consumption will be considerably lower. You might also want to add a spi prefix to it since it's no longer "the" RX stack, rather just an HCI driver-internal one.

yboutreux commented 5 years ago

Seems like "fresh" merged commits have introduced more errors with peripheral and the disco_l475_iot1... I'll need to see this with you @erwango (FYI I was troubleshooting BLE HCI-SPI from commit 3ce677092d3636785ea1398efee93489614f05f7, which was more stable at this time)

erwango commented 5 years ago

@jhedberg , tested and working on my side. Will try to push a PR soon, txs!