Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

smp_svr sample does not discover services #16735

Closed
mfiumara opened this issue Jun 11, 2019 · 21 comments
Closed

smp_svr sample does not discover services #16735

mfiumara opened this issue Jun 11, 2019 · 21 comments
Assignees
Labels
area: Bluetooth bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug

Comments

@mfiumara
Copy link
Contributor

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

@mfiumara mfiumara added the bug The issue is a bug, or the PR is fixing a bug label Jun 11, 2019
@aescolar
Copy link
Member

@jhedberg Could you triage?

@jhedberg
Copy link
Member

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 jhedberg added the priority: medium Medium impact/importance bug label Jun 11, 2019
@jhedberg
Copy link
Member

jhedberg commented Jun 11, 2019

@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
Copy link
Contributor Author

mfiumara commented Jun 11, 2019

@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
Copy link
Contributor Author

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
Copy link
Member

Can this issue be closed then?

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

@YuraCobain
Copy link

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

@aescolar aescolar reopened this Jul 12, 2019
@aescolar
Copy link
Member

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

@Vudentz
Copy link
Contributor

Vudentz commented Jul 17, 2019

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

Do you have any zephyr logs, does other samples services work or is this specific to smp_svr?

@YuraCobain
Copy link

Environment :

OS: Linux 4.18.0-25-generic #26~18.04.1-Ubuntu SMP x86_64 x86_64 x86_64 GNU/Linux
Bluez: 5.50
Zephyr SDK 0.10.0
Zephyr 1.14@743f3db
MCUBoot@853657c

hciconfig -a
hci1: Type: Primary Bus: USB
BD Address: 34:E1:2D:D2:C4:76 ACL MTU: 1021:4 SCO MTU: 96:6
UP RUNNING PSCAN
RX bytes:4992 acl:0 sco:0 events:183 errors:0
TX bytes:4757 acl:2 sco:0 commands:198 errors:0
Features: 0xff 0xfe 0x0f 0xfe 0xdb 0xff 0x7b 0x87
Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
Link policy: RSWITCH HOLD SNIFF
Link mode: SLAVE ACCEPT
Name: 'fendi #2'
Class: 0x0c010c
Service Classes: Rendering, Capturing
Device Class: Computer, Laptop
HCI Version: 4.2 (0x8) Revision: 0x100
LMP Version: 4.2 (0x8) Subversion: 0x100
Manufacturer: Intel Corp. (2)

hci0: Type: Primary Bus: USB
BD Address: 00:1A:7D:DA:71:05 ACL MTU: 310:10 SCO MTU: 64:8
UP RUNNING
RX bytes:6134 acl:0 sco:0 events:149 errors:0
TX bytes:4264 acl:12 sco:0 commands:164 errors:0
Features: 0xff 0xff 0x8f 0xfe 0xdb 0xff 0x5b 0x87
Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
Link policy: RSWITCH HOLD SNIFF PARK
Link mode: SLAVE ACCEPT
Name: 'fendi #1'
Class: 0x0c010c
Service Classes: Rendering, Capturing
Device Class: Computer, Laptop
HCI Version: 4.0 (0x6) Revision: 0x22bb
LMP Version: 4.0 (0x6) Subversion: 0x22bb
Manufacturer: Cambridge Silicon Radio (10)

Good scenario with hci0(Cambridge Silicon Radio):
sudo ~/go/bin/mcumgr --conntype ble -i 0 --connstring peer_name='Zephyr' echo test
test

Bad scenario with hci1(Intel):
sudo ~/go/bin/mcumgr --conntype ble -i 1 --connstring peer_name='Zephyr' echo test
Error: can't discover services: ATT request timeout: req timeout

btmon_cambridge_silicon_radio_hci_ok.log
btmon_intel_hci_nok.log
zephyr_cambridge_silic_ok.log
zephyr_intel_nok.log

@Vudentz
Copy link
Contributor

Vudentz commented Jul 18, 2019

So it doesn't work with Intel but works when connected with CSR? Does bluetoothctl produces the same results.

@YuraCobain
Copy link

Yes, works with CSR and doesn't with Intel.
bluetoothctl produces the following results:
zephyr_intel_bluetoothhctl_manually.log
btmon_intel_bluetoothhctl_manually.log

@lawrencek52
Copy link
Contributor

lawrencek52 commented Aug 9, 2019

I am seeing the same thing, unfortunately I only have Intel, hence I can't connect.

On a related note the Zephyr app I am developing has developed a bug between an older build and the current tip. Doing a git bisect the bug shows up when a change to the timers was made. I am using tickless kernel (hence the timer rate is 32kHz which counts as high). When the bug hits the timer interrupts disappear (my LEDs also stop blinking), I think the bluetooth stack is taking too long to do something while the timer is trying to setup the next interrupt, and the compare register gets set too late, hence missing the interrupt and stalling the system for 512 seconds. But I haven't got to the bottom of it yet...

Here is the output of git bisect identifying the change:

# bad: [0ec0c84808c07b01ba418d4a3afa1cb0289a4d6a] dts: bindings: Remove unused 'version' field
git bisect bad 0ec0c84808c07b01ba418d4a3afa1cb0289a4d6a
# good: [6746470d1d7b58462236d70fe051ba8820d60c41] drivers: ieee802154: nrf5: Support when LOG is off
git bisect good 6746470d1d7b58462236d70fe051ba8820d60c41
# good: [6020a50092125d257bbdeb82948abc62ea69c0e0] tests: schedule_api: skip test assert if COVERAGE
git bisect good 6020a50092125d257bbdeb82948abc62ea69c0e0
# bad: [e809b95c5146c53e4ca695eae8c7c0c79103e9b3] net: Collect network packet TX send time
git bisect bad e809b95c5146c53e4ca695eae8c7c0c79103e9b3
# good: [171272cf312cde3011f212d495fcca4c683f6327] arch: arm: update thread options flag and CONTROL atomically
git bisect good 171272cf312cde3011f212d495fcca4c683f6327
# good: [a744501a7d2df4a556ee9f35eb1ca40137c27930] kernel: test coverage for sflist
git bisect good a744501a7d2df4a556ee9f35eb1ca40137c27930
# good: [fc23fd1989d9d7e85af17e5d367b8354d96ebed3] drivers: can: stm32: Update enable driver help message
git bisect good fc23fd1989d9d7e85af17e5d367b8354d96ebed3
# good: [ace11bbefde384af7e0bf7c2f7b9fc6a1c9c88ca] mempool: make sure max block size isn't smaller than minimum allowed
git bisect good ace11bbefde384af7e0bf7c2f7b9fc6a1c9c88ca
# bad: [17051e42d6c41ecb735dd93df8bcf60644c1bf49] drivers/sensor/hp206c: Clarify tick rate warning
git bisect bad 17051e42d6c41ecb735dd93df8bcf60644c1bf49
# bad: [7044ce746f3ba42ce03546fc32679a6a2d6bb314] boards/arm: Remove 1000 Hz tick rate on STM32 boards
git bisect bad 7044ce746f3ba42ce03546fc32679a6a2d6bb314
# bad: [0baf72e1c795abf7279018588cb033255b70f011] drivers/timer/nrf_rtc_timer: Fix round-up for rapid tick rates
git bisect bad 0baf72e1c795abf7279018588cb033255b70f011
# good: [9f4f57eed3a36fb2f84f828f9bebe14d730cba44] sanitycheck: don't multiply CPU count
git bisect good 9f4f57eed3a36fb2f84f828f9bebe14d730cba44
# first bad commit: [0baf72e1c795abf7279018588cb033255b70f011] drivers/timer/nrf_rtc_timer: Fix round-up for rapid tick rates

@carlescufi
Copy link
Member

@lawrencek52 your timer bug might be fixed now, there was a comparator register fix posted: 9f34d17#diff-57dfbf11ae1437d7b0a30d68d709d8d6

@carlescufi
Copy link
Member

@YuraCobain @lawrencek52 can you please retest on the latest master, since there have been multiple fixes to GATT?

@YuraCobain
Copy link

@carlescufi the issue still exists on Intel controller.

@carlescufi
Copy link
Member

@Vudentz or @jhedberg any chance you could try to reproduce this using an Intel controller and see if this is indeed a Zephyr issue or else a BlueZ/Intel issue?

@carlescufi
Copy link
Member

@YuraCobain I just tested this with an Intel controller:

[bluetooth]# connect C8:7A:F3:8D:12:7B
Attempting to connect to C8:7A:F3:8D:12:7B
[CHG] Device 55:73:F0:06:B5:6F RSSI: -88
[CHG] Device 55:73:F0:06:B5:6F ServiceData Key: 0000feaf-0000-1000-8000-00805f9b34fb
[CHG] Device 55:73:F0:06:B5:6F ServiceData Value:
  10 01 00 02 5a 23 12 00 36 f5 8c 00 00 30 b4 18  ....Z#..6....0..
  00                                               .
[CHG] Device 1D:7A:B0:05:5D:D2 RSSI: -80
[CHG] Device C8:7A:F3:8D:12:7B Connected: yes
Connection successful
[NEW] Primary Service
        /org/bluez/hci0/dev_C8_7A_F3_8D_12_7B/service0001
        00001801-0000-1000-8000-00805f9b34fb
        Generic Attribute Profile
[NEW] Characteristic
        /org/bluez/hci0/dev_C8_7A_F3_8D_12_7B/service0001/char0002
        00002a05-0000-1000-8000-00805f9b34fb
        Service Changed
[NEW] Descriptor
        /org/bluez/hci0/dev_C8_7A_F3_8D_12_7B/service0001/char0002/desc0004
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[NEW] Characteristic
        /org/bluez/hci0/dev_C8_7A_F3_8D_12_7B/service0001/char0005
        00002b29-0000-1000-8000-00805f9b34fb
        Unknown
[NEW] Characteristic
        /org/bluez/hci0/dev_C8_7A_F3_8D_12_7B/service0001/char0007
        00002b2a-0000-1000-8000-00805f9b34fb
        Unknown
[NEW] Primary Service
        /org/bluez/hci0/dev_C8_7A_F3_8D_12_7B/service0010
        8d53dc1d-1db7-4cd3-868b-8a527460aa84
        Vendor specific
[NEW] Characteristic
        /org/bluez/hci0/dev_C8_7A_F3_8D_12_7B/service0010/char0011
        da2e7828-fbce-4e01-ae9e-261174997c48
        Vendor specific
[NEW] Descriptor
        /org/bluez/hci0/dev_C8_7A_F3_8D_12_7B/service0010/char0011/desc0013
        00002902-0000-1000-8000-00805f9b34fb
        Client Characteristic Configuration
[CHG] Device C8:7A:F3:8D:12:7B UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Device C8:7A:F3:8D:12:7B UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Device C8:7A:F3:8D:12:7B UUIDs: 8d53dc1d-1db7-4cd3-868b-8a527460aa84
[CHG] Device C8:7A:F3:8D:12:7B ServicesResolved: yes

This is my device:

$ hciconfig hci0 version
hci0:   Type: Primary  Bus: USB
        BD Address: 00:28:F8:B3:4D:08  ACL MTU: 1021:4  SCO MTU: 96:6
        HCI Version: 4.2 (0x8)  Revision: 0x100
        LMP Version: 4.2 (0x8)  Subversion: 0x100
        Manufacturer: Intel Corp. (2)

@carlescufi
Copy link
Member

@YuraCobain can you please use bluetoothctl and not mcumgr to test this? Because this might be a bug in mcumgr instead.

@carlescufi carlescufi added priority: low Low impact/importance bug and removed priority: medium Medium impact/importance bug labels Aug 27, 2019
@carlescufi
Copy link
Member

Lowering priority to low since this is not a blocker nor it is easily reproducible.

@nvlsianpu
Copy link
Collaborator

As recently I have been using smp_svr a loot on nRF52 SoC's I can tell that it works fine, re-open if found it buggy again.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area: Bluetooth bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug
Projects
None yet
Development

No branches or pull requests

10 participants