smp_svr sample does not discover services

[mfiumara]

Describe the bug
When following steps in the smp_svr example (https://docs.zephyrproject.org/latest/samples/subsys/mgmt/mcumgr/smp_svr/README.html#smp-svr-sample) and try to perform a ping to the target device, I get the following error:

mcumgr --conntype ble --connstring peer_name=Zephyr echo hello
Error: can't discover services: ATT request timeout: req timeout

To Reproduce

1. Follow guide at https://docs.zephyrproject.org/latest/samples/subsys/mgmt/mcumgr/smp_svr/README.html#smp-svr-sample using a nrf52_pca10040 dev kit to flash bootloader and application

Expected behavior
Expected output:

sudo mcumgr --conntype ble --connstring ctlr_name=hci0,peer_name='Zephyr' echo hello
hello

Impact
showstopper, I cannot DFU the smp_svr example.

Screenshots or console output
The MCU bootloader and application are correctly flashed as I get expected output from the UART terminal on the device:

***** Booting Zephyr OS zephyr-v1.14.0-1297-g5a2c6d33e490 *****
[00:00:00.005,065] <inf> mcuboot: Starting bootloader
[00:00:00.011,596] <inf> mcuboot: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=03
[00:00:00.022,155] <inf> mcuboot: Scratch: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
[00:00:00.032,165] <inf> mcuboot: Boot source: primary slot
[00:00:00.041,534] <inf> mcuboot: Swap type: none
[00:00:00.265,563] <inf> mcuboot: Bootloader chainload address offset: 0xc000
[00:00:00.273,193] <inf> mcuboot: Jumping to the first image slot
***** Booting Zephyr OS zephyr-v1.14.0-1297-g5a2c6d33e490 *****
Bluetooth initialized
Advertising successfully started

Output from BTmon when issuing mcumgr --conntype ble --connstring peer_name=Zephyr echo hello:

< HCI Command: LE Create Connection (0x08|0x000d) plen 25                    #16048 [hci0] 3112.172454
        Scan interval: 10.000 msec (0x0010)
        Scan window: 10.000 msec (0x0010)
        Filter policy: White list is not used (0x00)
        Peer address type: Random (0x01)
        Peer address: C3:6A:41:0F:21:66 (Static)
        Own address type: Public (0x00)
        Min connection interval: 7.50 msec (0x0006)
        Max connection interval: 7.50 msec (0x0006)
        Connection latency: 0 (0x0000)
        Supervision timeout: 720 msec (0x0048)
        Min connection length: 0.000 msec (0x0000)
        Max connection length: 0.000 msec (0x0000)
> HCI Event: Command Status (0x0f) plen 4                                    #16049 [hci0] 3112.177446
      LE Create Connection (0x08|0x000d) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19                                    #16050 [hci0] 3112.231279
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 77
        Role: Master (0x00)
        Peer address type: Random (0x01)
        Peer address: C3:6A:41:0F:21:66 (Static)
        Connection interval: 7.50 msec (0x0006)
        Connection latency: 0 (0x0000)
        Supervision timeout: 720 msec (0x0048)
        Master clock accuracy: 0x00
< ACL Data TX: Handle 77 flags 0x00 dlen 7                                   #16051 [hci0] 3112.231448
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 512
> HCI Event: Number of Completed Packets (0x13) plen 5                       #16052 [hci0] 3112.242665
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 7                                   #16053 [hci0] 3112.246759
      ATT: Exchange MTU Response (0x03) len 2
        Server RX MTU: 252
< ACL Data TX: Handle 77 flags 0x00 dlen 11                                  #16054 [hci0] 3112.246875
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0001-0xffff
        Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5                       #16055 [hci0] 3112.255309
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 16                                  #16056 [hci0] 3117.234379
      LE L2CAP: Connection Parameter Update Request (0x12) ident 1 len 8
        Min interval: 24
        Max interval: 40
        Slave latency: 0
        Timeout multiplier: 42
< HCI Command: LE Connection Update (0x08|0x0013) plen 14                    #16057 [hci0] 3117.234625
        Handle: 77
        Min connection interval: 30.00 msec (0x0018)
        Max connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Min connection length: 0.000 msec (0x0000)
        Max connection length: 0.000 msec (0x0000)
> HCI Event: Command Status (0x0f) plen 4                                    #16058 [hci0] 3117.249303
      LE Connection Update (0x08|0x0013) ncmd 1
        Status: Success (0x00)
< ACL Data TX: Handle 77 flags 0x00 dlen 10                                  #16059 [hci0] 3117.249501
      LE L2CAP: Connection Parameter Update Response (0x13) ident 1 len 2
        Result: Connection Parameters accepted (0x0000)
> HCI Event: Number of Completed Packets (0x13) plen 5                       #16060 [hci0] 3117.258296
        Num handles: 1
        Handle: 77
        Count: 1
> HCI Event: LE Meta Event (0x3e) plen 10                                    #16061 [hci0] 3117.339382
      LE Connection Update Complete (0x03)
        Status: Success (0x00)
        Handle: 77
        Connection interval: 50.00 msec (0x0028)
        Connection latency: 0 (0x0000)
        Supervision timeout: 420 msec (0x002a)
< HCI Command: Disconnect (0x01|0x0006) plen 3                               #16062 [hci0] 3142.247160
        Handle: 77
        Reason: Remote User Terminated Connection (0x13)
> HCI Event: Command Status (0x0f) plen 4                                    #16063 [hci0] 3142.263293
      Disconnect (0x01|0x0006) ncmd 1
        Status: Success (0x00)
< HCI Command: Read BD ADDR (0x04|0x0009) plen 0                             #16064 [hci0] 3142.263617
> HCI Event: Command Complete (0x0e) plen 10                                 #16065 [hci0] 3142.268320
      Read BD ADDR (0x04|0x0009) ncmd 1
        Status: Success (0x00)
        Address: 00:01:95:48:41:2C (Sena Technologies, Inc.)
@ USER Close: mcumgr                                                       {0x0004} [hci0] 3142.268438
= Close Index: 00:01:95:48:41:2C                                                    [hci0] 3142.269352

I have also tried connecting directly using bluetoothctl, it seems the smp_svr service is available so I don't know what is causing the problem:

[bluetooth]# connect C3:6A:41:0F:21:66 
Attempting to connect to C3:6A:41:0F:21:66
[CHG] Device C3:6A:41:0F:21:66 Connected: yes
Connection successful
[Zephyr]# info
Device C3:6A:41:0F:21:66 (random)
	Name: Zephyr
	Alias: Zephyr
	Paired: no
	Trusted: yes
	Blocked: no
	Connected: yes
	LegacyPairing: no
	UUID: Vendor specific           (8d53dc1d-1db7-4cd3-868b-8a527460aa84)

Environment (please complete the following information):

• OS: Manjaro Linux 64 bit. bluez 5.50
• Zephyr SDK 0.10.0
• Zephyr 1.14, MCUBoot @ fc07eab

Additional context

[aescolar]

@jhedberg Could you triage?

[jhedberg]

Looks like this PDU is not getting a response from Zephyr:

< ACL Data TX: Handle 77 flags 0x00 dlen 11                                  #16054 [hci0] 3112.246875
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0001-0xffff
        Attribute group type: Primary Service (0x2800)

[jhedberg]

@Vudentz this could be the ATT flow control thing on the Zephyr side. @mfiumara could you try with latest master branch? If the issue persists, could you enable CONFIG_BT_DEBUG_LOG=y so we get more info from the Bluetooth stack.

[mfiumara]

@jhedberg I checked out the latest master @ 23a6de5 and repeated steps above: this seems to solve the issue. Output is now as expected:

sudo mcumgr --conntype ble --connstring peer_name=Zephyr echo hello
hello

Output from btmon now:

> HCI Event: Command Complete (0x0e) plen 4                                  #17019 [hci0] 6603.772563
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
< HCI Command: LE Create Connection (0x08|0x000d) plen 25                    #17020 [hci0] 6603.772776
        Scan interval: 10.000 msec (0x0010)
        Scan window: 10.000 msec (0x0010)
        Filter policy: White list is not used (0x00)
        Peer address type: Random (0x01)
        Peer address: C3:6A:41:0F:21:66 (Static)
        Own address type: Public (0x00)
        Min connection interval: 7.50 msec (0x0006)
        Max connection interval: 7.50 msec (0x0006)
        Connection latency: 0 (0x0000)
        Supervision timeout: 720 msec (0x0048)
        Min connection length: 0.000 msec (0x0000)
        Max connection length: 0.000 msec (0x0000)
> HCI Event: Command Status (0x0f) plen 4                                    #17021 [hci0] 6603.779281
      LE Create Connection (0x08|0x000d) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19                                    #17022 [hci0] 6603.838623
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 77
        Role: Master (0x00)
        Peer address type: Random (0x01)
        Peer address: C3:6A:41:0F:21:66 (Static)
        Connection interval: 7.50 msec (0x0006)
        Connection latency: 0 (0x0000)
        Supervision timeout: 720 msec (0x0048)
        Master clock accuracy: 0x00
< ACL Data TX: Handle 77 flags 0x00 dlen 7                                   #17023 [hci0] 6603.838901
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 512
> HCI Event: Number of Completed Packets (0x13) plen 5                       #17024 [hci0] 6603.843613
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 7                                   #17025 [hci0] 6603.851533
      ATT: Exchange MTU Response (0x03) len 2
        Server RX MTU: 252
< ACL Data TX: Handle 77 flags 0x00 dlen 11                                  #17026 [hci0] 6603.851761
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0001-0xffff
        Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5                       #17027 [hci0] 6603.858382
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 18                                  #17028 [hci0] 6603.865204
      ATT: Read By Group Type Response (0x11) len 13
        Attribute data length: 6
        Attribute group list: 2 entries
        Handle range: 0x0001-0x0008
        UUID: Generic Attribute Profile (0x1801)
        Handle range: 0x0009-0x000f
        UUID: Generic Access Profile (0x1800)
< ACL Data TX: Handle 77 flags 0x00 dlen 11                                  #17029 [hci0] 6603.865348
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0010-0xffff
        Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5                       #17030 [hci0] 6603.872583
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 26                                  #17031 [hci0] 6603.879944
      ATT: Read By Group Type Response (0x11) len 21
        Attribute data length: 20
        Attribute group list: 1 entry
        Handle range: 0x0010-0x0013
        UUID: Vendor specific (8d53dc1d-1db7-4cd3-868b-8a527460aa84)
< ACL Data TX: Handle 77 flags 0x00 dlen 11                                  #17032 [hci0] 6603.880128
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0014-0xffff
        Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5                       #17033 [hci0] 6603.887586
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 9                                   #17034 [hci0] 6603.896396
      ATT: Error Response (0x01) len 4
        Read By Group Type Request (0x10)
        Handle: 0x0014
        Error: Attribute Not Found (0x0a)
< ACL Data TX: Handle 77 flags 0x00 dlen 11                                  #17035 [hci0] 6603.896530
      ATT: Read By Type Request (0x08) len 6
        Handle range: 0x0001-0x0008
        Attribute type: Characteristic (0x2803)
> HCI Event: Number of Completed Packets (0x13) plen 5                       #17036 [hci0] 6603.902598
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 27                                  #17037 [hci0] 6603.909922
      ATT: Read By Type Response (0x09) len 22
        Attribute data length: 7
        Attribute data list: 3 entries
        Handle: 0x0002
        Value: 200300052a
        Handle: 0x0005
        Value: 0a0600292b
        Handle: 0x0007
        Value: 0208002a2b
< ACL Data TX: Handle 77 flags 0x00 dlen 9                                   #17038 [hci0] 6603.910088
      ATT: Find Information Request (0x04) len 4
        Handle range: 0x0004-0x0004
> HCI Event: Number of Completed Packets (0x13) plen 5                       #17039 [hci0] 6603.917608
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 10                                  #17040 [hci0] 6603.926660
      ATT: Find Information Response (0x05) len 5
        Format: UUID-16 (0x01)
        Handle: 0x0004
        UUID: Client Characteristic Configuration (0x2902)
< ACL Data TX: Handle 77 flags 0x00 dlen 11                                  #17041 [hci0] 6603.926769
      ATT: Read By Type Request (0x08) len 6
        Handle range: 0x0009-0x000f
        Attribute type: Characteristic (0x2803)
> HCI Event: Number of Completed Packets (0x13) plen 5                       #17042 [hci0] 6603.940635
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 27                                  #17043 [hci0] 6603.949121
      ATT: Read By Type Response (0x09) len 22
        Attribute data length: 7
        Attribute data list: 3 entries
        Handle: 0x000a
        Value: 020b00002a
        Handle: 0x000c
        Value: 020d00012a
        Handle: 0x000e
        Value: 020f00042a
< ACL Data TX: Handle 77 flags 0x00 dlen 11                                  #17044 [hci0] 6603.949271
      ATT: Read By Type Request (0x08) len 6
        Handle range: 0x0010-0x0013
        Attribute type: Characteristic (0x2803)
> HCI Event: Number of Completed Packets (0x13) plen 5                       #17045 [hci0] 6603.956898
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 27                                  #17046 [hci0] 6603.962433
      ATT: Read By Type Response (0x09) len 22
        Attribute data length: 21
        Attribute data list: 1 entry
        Handle: 0x0011
        Value: 141200487c997411269eae014ecefb28782eda
< ACL Data TX: Handle 77 flags 0x00 dlen 11                                  #17047 [hci0] 6603.962586
      ATT: Read By Type Request (0x08) len 6
        Handle range: 0x0013-0x0013
        Attribute type: Characteristic (0x2803)
> HCI Event: Number of Completed Packets (0x13) plen 5                       #17048 [hci0] 6603.973492
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 9                                   #17049 [hci0] 6603.977241
      ATT: Error Response (0x01) len 4
        Read By Type Request (0x08)
        Handle: 0x0013
        Error: Attribute Not Found (0x0a)
< ACL Data TX: Handle 77 flags 0x00 dlen 9                                   #17050 [hci0] 6603.977349
      ATT: Find Information Request (0x04) len 4
        Handle range: 0x0013-0x0013
> HCI Event: Number of Completed Packets (0x13) plen 5                       #17051 [hci0] 6603.985577
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 10                                  #17052 [hci0] 6603.992260
      ATT: Find Information Response (0x05) len 5
        Format: UUID-16 (0x01)
        Handle: 0x0013
        UUID: Client Characteristic Configuration (0x2902)
< ACL Data TX: Handle 77 flags 0x00 dlen 9                                   #17053 [hci0] 6603.992501
      ATT: Write Request (0x12) len 4
        Handle: 0x0013
          Data: 0100
> HCI Event: Number of Completed Packets (0x13) plen 5                       #17054 [hci0] 6604.000611
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 5                                   #17055 [hci0] 6604.008631
      ATT: Write Response (0x13) len 0
< ACL Data TX: Handle 77 flags 0x00 dlen 24                                  #17056 [hci0] 6604.008844
      ATT: Write Command (0x52) len 19
        Handle: 0x0012
          Data: 0200000900004200a161646568656c6c6f
> HCI Event: Number of Completed Packets (0x13) plen 5                       #17057 [hci0] 6604.017410
        Num handles: 1
        Handle: 77
        Count: 1
> ACL Data RX: Handle 77 flags 0x02 dlen 25                                  #17058 [hci0] 6604.022432
      ATT: Handle Value Notification (0x1b) len 20
        Handle: 0x0012
          Data: 0300000a00004200bf61726568656c6c6fff
< HCI Command: Disconnect (0x01|0x0006) plen 3                               #17059 [hci0] 6604.023034
        Handle: 77
        Reason: Remote User Terminated Connection (0x13)
> HCI Event: Command Status (0x0f) plen 4                                    #17060 [hci0] 6604.025203
      Disconnect (0x01|0x0006) ncmd 1
        Status: Success (0x00)
< HCI Command: Read BD ADDR (0x04|0x0009) plen 0                             #17061 [hci0] 6604.025298
> HCI Event: Command Complete (0x0e) plen 10                                 #17062 [hci0] 6604.031048
      Read BD ADDR (0x04|0x0009) ncmd 1
        Status: Success (0x00)
        Address: 00:01:95:48:41:2C (Sena Technologies, Inc.)
@ USER Close: mcumgr                                                       {0x0004} [hci0] 6604.031446

[mfiumara]

Also services now get discovered correctly:

[bluetooth]# connect C3:6A:41:0F:21:66 
Attempting to connect to C3:6A:41:0F:21:66
[CHG] Device C3:6A:41:0F:21:66 Connected: yes
Connection successful
[NEW] Primary Service (Handle 0x0000)
	/org/bluez/hci0/dev_C3_6A_41_0F_21_66/service0001
	00001801-0000-1000-8000-00805f9b34fb
	Generic Attribute Profile
[NEW] Characteristic (Handle 0x4e68)
	/org/bluez/hci0/dev_C3_6A_41_0F_21_66/service0001/char0002
	00002a05-0000-1000-8000-00805f9b34fb
	Service Changed
[NEW] Descriptor (Handle 0x54d0)
	/org/bluez/hci0/dev_C3_6A_41_0F_21_66/service0001/char0002/desc0004
	00002902-0000-1000-8000-00805f9b34fb
	Client Characteristic Configuration
[NEW] Characteristic (Handle 0x97e8)
	/org/bluez/hci0/dev_C3_6A_41_0F_21_66/service0001/char0005
	00002b29-0000-1000-8000-00805f9b34fb
	Unknown
[NEW] Characteristic (Handle 0x6e08)
	/org/bluez/hci0/dev_C3_6A_41_0F_21_66/service0001/char0007
	00002b2a-0000-1000-8000-00805f9b34fb
	Unknown
[NEW] Primary Service (Handle 0x20c0)
	/org/bluez/hci0/dev_C3_6A_41_0F_21_66/service0010
	8d53dc1d-1db7-4cd3-868b-8a527460aa84
	Vendor specific
[NEW] Characteristic (Handle 0x7df8)
	/org/bluez/hci0/dev_C3_6A_41_0F_21_66/service0010/char0011
	da2e7828-fbce-4e01-ae9e-261174997c48
	Vendor specific
[NEW] Descriptor (Handle 0x54d0)
	/org/bluez/hci0/dev_C3_6A_41_0F_21_66/service0010/char0011/desc0013
	00002902-0000-1000-8000-00805f9b34fb
	Client Characteristic Configuration
[CHG] Device C3:6A:41:0F:21:66 UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Device C3:6A:41:0F:21:66 UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Device C3:6A:41:0F:21:66 UUIDs: 8d53dc1d-1db7-4cd3-868b-8a527460aa84
[CHG] Device C3:6A:41:0F:21:66 ServicesResolved: yes

Can this issue be closed then?

[jhedberg]

Can this issue be closed then?

Yes, I'd say so. I.e. my suspicion of this getting solved by #16612 was correct.

[YuraCobain]

The issue still exists on the latest master @ ab69044 with the same symptoms as described in Bug description.

[aescolar]

@Vudentz (as @jhedberg is on holiday) can you take a look at this one?