Running bluetooth examples using qemu


Primini
 

Hi everyone!

I am trying to run examples from samples using qemu_x86 board but I am facing with bluetooth init error -5 when executing examples that handle connection/disconnection callbacks.

I follow the steps available in zephyr doc page: http://docs.zephyrproject.org/subsystems/bluetooth/devel.html - "Testing with QEMU"

For exampĺe, running central sample I've got the following output:

$ make run
[  2%] Built target offsets
[  3%] Built target offsets_h
[ 27%] Built target kernel
[ 37%] Built target app
[ 38%] Built target linker_pass2_script
[ 39%] Built target linker_script
[ 70%] Built target zephyr
[ 72%] Built target subsys__bluetooth__common
[ 81%] Built target subsys__bluetooth__host
[ 82%] Built target subsys__net
[ 83%] Built target arch__x86__soc__ia32
[ 85%] Built target zephyr_prebuilt
[ 85%] Built target obj_list
[ 86%] Built target output_src_pre
[ 88%] Built target output_lib
[ 89%] Built target output_obj_renamed
[ 90%] Built target gen_idt_output
[ 91%] Built target staticIdt_o
[ 92%] Built target gdt_o
[ 94%] Built target irq_int_vector_map_o
[ 97%] Built target mmu_tables_o
[ 98%] Built target kernel_elf
[100%] 
To exit from QEMU enter: 'CTRL+a, x'
[QEMU] CPU: qemu32,+nx,+pae
qemu-system-i386: warning: Unknown firmware file in legacy mode: genroms/multiboot.bin

Bluetooth init failed (err -5)



I also have configured btproxy in my ubuntu host:

$ sudo ./btproxy -u
Listening on /tmp/bt-server-bredr
Opening user channel for hci0
New client connected


Is there anything missing in the configuration or maybe additional steps?


Regards!

Primini


Johan Hedberg
 

Hi Tiago,

On Tue, Nov 21, 2017, Tiago Primini wrote:
Bluetooth init failed (err -5)

I also have configured btproxy in my ubuntu host:

$ sudo ./btproxy -u
Listening on /tmp/bt-server-bredr
Opening user channel for hci0
New client connected

Is there anything missing in the configuration or maybe additional steps?
I can't really say for sure what's going wrong, but it would help if you
got some more logs for the situation. On the Linux side, you could run
btmon to see what HCI commands (if any) Zephyr manages to send. On the
Zephyr side, you could add at least the following to your app's prj.conf:

CONFIG_BT_DEBUG_LOG=y
CONFIG_BT_DEBUG_HCI_DRIVER=y
CONFIG_BT_DEBUG_HCI_CORE=y

With those you should be able to see a bit more of what's happening in
the Zephyr console.

Johan


Primini
 

Hi Johan,

from the host side I got btmon's log:

$ sudo btmon
Bluetooth monitor ver 5.47
= Note: Linux version 4.10.0-38-generic (x86_64)                                                          0.606132
= Note: Bluetooth subsystem version 2.22                                                                  0.606133
= New Index: 94:E9:79:F0:F7:AC (Primary,USB,hci0)                                                  [hci0] 0.606133
@ MGMT Open: bluetoothd (privileged) version 1.14                                                {0x0001} 0.606134
@ MGMT Open: btmon (privileged) version 1.14                                                     {0x0002} 0.606178
@ MGMT Event: Index Removed (0x0005) plen 0                                               {0x0002} [hci0] 4.637973
@ MGMT Event: Index Removed (0x0005) plen 0                                               {0x0001} [hci0] 4.637973
= Open Index: 94:E9:79:F0:F7:AC                                                                    [hci0] 4.637996
= Index Info: 94:E9:79:F0:F7:AC (Qualcomm)                                                         [hci0] 4.637996
@ USER Open: btproxy (privileged) version 2.22                                            {0x0003} [hci0] 4.638000
= bluetoothd: Endpoint unregistered: sender=:1.78 path=/MediaEndpoint/A2DPSource                          4.638071
= bluetoothd: Endpoint unregistered: sender=:1.78 path=/MediaEndpoint/A2DPSink                            4.638097
< HCI Command: Reset (0x03|0x0003) plen 0                                                       #1 [hci0] 4.926275
> HCI Event: Command Complete (0x0e) plen 4                                                     #2 [hci0] 4.981050
      Reset (0x03|0x0003) ncmd 1
        Status: Success (0x00)
< HCI Command: Read Local Supported Features (0x04|0x0003) plen 0                               #3 [hci0] 4.987188
> HCI Event: Command Complete (0x0e) plen 12                                                    #4 [hci0] 4.987983
      Read Local Supported Features (0x04|0x0003) ncmd 1
        Status: Success (0x00)
        Features: 0xff 0xfe 0x8f 0xfe 0xd8 0x3f 0x5b 0x87
          3 slot packets
          5 slot packets
          Encryption
          Slot offset
          Timing accuracy
          Role switch
          Hold mode
          Sniff mode
          Power control requests
          Channel quality driven data rate (CQDDR)
          SCO link
          HV2 packets
          HV3 packets
          u-law log synchronous data
          A-law log synchronous data
          CVSD synchronous data
          Paging parameter negotiation
          Power control
          Transparent synchronous data
          Broadcast Encryption
          Enhanced Data Rate ACL 2 Mbps mode
          Enhanced Data Rate ACL 3 Mbps mode
          Enhanced inquiry scan
          Interlaced inquiry scan
          Interlaced page scan
          RSSI with inquiry results
          Extended SCO link (EV3 packets)
          AFH capable slave
          AFH classification slave
          LE Supported (Controller)
          3-slot Enhanced Data Rate ACL packets
          5-slot Enhanced Data Rate ACL packets
          Sniff subrating
          Pause encryption
          AFH capable master
          AFH classification master
          Enhanced Data Rate eSCO 2 Mbps mode
          Extended Inquiry Response
          Simultaneous LE and BR/EDR (Controller)
          Secure Simple Pairing
          Encapsulated PDU
          Non-flushable Packet Boundary Flag
          Link Supervision Timeout Changed Event
          Inquiry TX Power Level
          Enhanced Power Control
          Extended features
< HCI Command: Read Local Version Information (0x04|0x0001) plen 0                              #5 [hci0] 4.992170
> HCI Event: Command Complete (0x0e) plen 12                                                    #6 [hci0] 4.992985
      Read Local Version Information (0x04|0x0001) ncmd 1
        Status: Success (0x00)
        HCI version: Bluetooth 4.1 (0x07) - Revision 0 (0x0000)
        LMP version: Bluetooth 4.1 (0x07) - Subversion 602 (0x025a)
        Manufacturer: Qualcomm (29)
< HCI Command: Read BD ADDR (0x04|0x0009) plen 0                                                #7 [hci0] 4.998724
> HCI Event: Command Complete (0x0e) plen 10                                                    #8 [hci0] 4.998982
      Read BD ADDR (0x04|0x0009) ncmd 1
        Status: Success (0x00)
        Address: 94:E9:79:F0:F7:AC (OUI 94-E9-79)
< HCI Command: Read Local Supported Commands (0x04|0x0002) plen 0                               #9 [hci0] 5.003114
> HCI Event: Command Complete (0x0e) plen 68                                                   #10 [hci0] 5.007980
      Read Local Supported Commands (0x04|0x0002) ncmd 1
        Status: Success (0x00)
        Commands: 197 entries
          Inquiry (Octet 0 - Bit 0)
          Inquiry Cancel (Octet 0 - Bit 1)
          Periodic Inquiry Mode (Octet 0 - Bit 2)
          Exit Periodic Inquiry Mode (Octet 0 - Bit 3)
          Create Connection (Octet 0 - Bit 4)
          Disconnect (Octet 0 - Bit 5)
          Add SCO Connection (Octet 0 - Bit 6)
          Create Connection Cancel (Octet 0 - Bit 7)
          Accept Connection Request (Octet 1 - Bit 0)
          Reject Connection Request (Octet 1 - Bit 1)
          Link Key Request Reply (Octet 1 - Bit 2)
          Link Key Request Negative Reply (Octet 1 - Bit 3)
          PIN Code Request Reply (Octet 1 - Bit 4)
          PIN Code Request Negative Reply (Octet 1 - Bit 5)
          Change Connection Packet Type (Octet 1 - Bit 6)
          Authentication Requested (Octet 1 - Bit 7)
          Set Connection Encryption (Octet 2 - Bit 0)
          Change Connection Link Key (Octet 2 - Bit 1)
          Master Link Key (Octet 2 - Bit 2)
          Remote Name Request (Octet 2 - Bit 3)
          Remote Name Request Cancel (Octet 2 - Bit 4)
          Read Remote Supported Features (Octet 2 - Bit 5)
          Read Remote Extended Features (Octet 2 - Bit 6)
          Read Remote Version Information (Octet 2 - Bit 7)
          Read Clock Offset (Octet 3 - Bit 0)
          Read LMP Handle (Octet 3 - Bit 1)
          Hold Mode (Octet 4 - Bit 1)
          Sniff Mode (Octet 4 - Bit 2)
          Exit Sniff Mode (Octet 4 - Bit 3)
          QoS Setup (Octet 4 - Bit 6)
          Role Discovery (Octet 4 - Bit 7)
          Switch Role (Octet 5 - Bit 0)
          Read Link Policy Settings (Octet 5 - Bit 1)
          Write Link Policy Settings (Octet 5 - Bit 2)
          Read Default Link Policy Settings (Octet 5 - Bit 3)
          Write Default Link Policy Settings (Octet 5 - Bit 4)
          Flow Specification (Octet 5 - Bit 5)
          Set Event Mask (Octet 5 - Bit 6)
          Reset (Octet 5 - Bit 7)
          Set Event Filter (Octet 6 - Bit 0)
          Flush (Octet 6 - Bit 1)
          Read PIN Type (Octet 6 - Bit 2)
          Write PIN Type (Octet 6 - Bit 3)
          Read Stored Link Key (Octet 6 - Bit 5)
          Write Stored Link Key (Octet 6 - Bit 6)
          Delete Stored Link Key (Octet 6 - Bit 7)
          Write Local Name (Octet 7 - Bit 0)
          Read Local Name (Octet 7 - Bit 1)
          Read Connection Accept Timeout (Octet 7 - Bit 2)
          Write Connection Accept Timeout (Octet 7 - Bit 3)
          Read Page Timeout (Octet 7 - Bit 4)
          Write Page Timeout (Octet 7 - Bit 5)
          Read Scan Enable (Octet 7 - Bit 6)
          Write Scan Enable (Octet 7 - Bit 7)
          Read Page Scan Activity (Octet 8 - Bit 0)
          Write Page Scan Activity (Octet 8 - Bit 1)
          Read Inquiry Scan Activity (Octet 8 - Bit 2)
          Write Inquiry Scan Activity (Octet 8 - Bit 3)
          Read Authentication Enable (Octet 8 - Bit 4)
          Write Authentication Enable (Octet 8 - Bit 5)
          Read Encryption Mode (Octet 8 - Bit 6)
          Write Encryption Mode (Octet 8 - Bit 7)
          Read Class of Device (Octet 9 - Bit 0)
          Write Class of Device (Octet 9 - Bit 1)
          Read Voice Setting (Octet 9 - Bit 2)
          Write Voice Setting (Octet 9 - Bit 3)
          Read Automatic Flush Timeout (Octet 9 - Bit 4)
          Write Automatic Flush Timeout (Octet 9 - Bit 5)
          Read Num Broadcast Retransmissions (Octet 9 - Bit 6)
          Write Num Broadcast Retransmissions (Octet 9 - Bit 7)
          Read Hold Mode Activity (Octet 10 - Bit 0)
          Write Hold Mode Activity (Octet 10 - Bit 1)
          Read Transmit Power Level (Octet 10 - Bit 2)
          Read Sync Flow Control Enable (Octet 10 - Bit 3)
          Write Sync Flow Control Enable (Octet 10 - Bit 4)
          Set Controller To Host Flow Control (Octet 10 - Bit 5)
          Host Buffer Size (Octet 10 - Bit 6)
          Host Number of Completed Packets (Octet 10 - Bit 7)
          Read Link Supervision Timeout (Octet 11 - Bit 0)
          Write Link Supervision Timeout (Octet 11 - Bit 1)
          Read Number of Supported IAC (Octet 11 - Bit 2)
          Read Current IAC LAP (Octet 11 - Bit 3)
          Write Current IAC LAP (Octet 11 - Bit 4)
          Read Page Scan Period Mode (Octet 11 - Bit 5)
          Write Page Scan Period Mode (Octet 11 - Bit 6)
          Set AFH Host Channel Classification (Octet 12 - Bit 1)
          Read Inquiry Scan Type (Octet 12 - Bit 4)
          Write Inquiry Scan Type (Octet 12 - Bit 5)
          Read Inquiry Mode (Octet 12 - Bit 6)
          Write Inquiry Mode (Octet 12 - Bit 7)
          Read Page Scan Type (Octet 13 - Bit 0)
          Write Page Scan Type (Octet 13 - Bit 1)
          Read AFH Channel Assessment Mode (Octet 13 - Bit 2)
          Write AFH Channel Assessment Mode (Octet 13 - Bit 3)
          Read Local Version Information (Octet 14 - Bit 3)
          Read Local Supported Features (Octet 14 - Bit 5)
          Read Local Extended Features (Octet 14 - Bit 6)
          Read Buffer Size (Octet 14 - Bit 7)
          Read BD ADDR (Octet 15 - Bit 1)
          Read Failed Contact Counter (Octet 15 - Bit 2)
          Reset Failed Contact Counter (Octet 15 - Bit 3)
          Read Link Quality (Octet 15 - Bit 4)
          Read RSSI (Octet 15 - Bit 5)
          Read AFH Channel Map (Octet 15 - Bit 6)
          Read Clock (Octet 15 - Bit 7)
          Read Loopback Mode (Octet 16 - Bit 0)
          Write Loopback Mode (Octet 16 - Bit 1)
          Enable Device Under Test Mode (Octet 16 - Bit 2)
          Setup Synchronous Connection (Octet 16 - Bit 3)
          Accept Synchronous Connection Request (Octet 16 - Bit 4)
          Reject Synchronous Connection Request (Octet 16 - Bit 5)
          Read Extended Inquiry Response (Octet 17 - Bit 0)
          Write Extended Inquiry Response (Octet 17 - Bit 1)
          Refresh Encryption Key (Octet 17 - Bit 2)
          Sniff Subrating (Octet 17 - Bit 4)
          Read Simple Pairing Mode (Octet 17 - Bit 5)
          Write Simple Pairing Mode (Octet 17 - Bit 6)
          Read Local OOB Data (Octet 17 - Bit 7)
          Read Inquiry Response TX Power Level (Octet 18 - Bit 0)
          Write Inquiry Transmit Power Level (Octet 18 - Bit 1)
          IO Capability Request Reply (Octet 18 - Bit 7)
          User Confirmation Request Reply (Octet 19 - Bit 0)
          User Confirmation Request Neg Reply (Octet 19 - Bit 1)
          User Passkey Request Reply (Octet 19 - Bit 2)
          User Passkey Request Negative Reply (Octet 19 - Bit 3)
          Remote OOB Data Request Reply (Octet 19 - Bit 4)
          Write Simple Pairing Debug Mode (Octet 19 - Bit 5)
          Enhanced Flush (Octet 19 - Bit 6)
          Remote OOB Data Request Neg Reply (Octet 19 - Bit 7)
          Send Keypress Notification (Octet 20 - Bit 2)
          IO Capability Request Negative Reply (Octet 20 - Bit 3)
          Read Encryption Key Size (Octet 20 - Bit 4)
          Read Enhanced Transmit Power Level (Octet 24 - Bit 0)
          Read LE Host Supported (Octet 24 - Bit 5)
          Write LE Host Supported (Octet 24 - Bit 6)
          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)
          Octet 25 - Bit 3 
          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)
          Octet 29 - Bit 1 
          Octet 29 - Bit 2 
          Set External Frame Configuration (Octet 29 - Bit 7)
          Set Triggered Clock Capture (Octet 30 - Bit 5)
          Set Connectionless Slave Broadcast (Octet 31 - Bit 0)
          Start Synchronization Train (Octet 31 - Bit 2)
          Set Reserved LT_ADDR (Octet 31 - Bit 4)
          Delete Reserved LT_ADDR (Octet 31 - Bit 5)
          Set Connectionless Slave Broadcast Data (Octet 31 - Bit 6)
          Read Synchronization Train Parameters (Octet 31 - Bit 7)
          Write Synchronization Train Parameters (Octet 32 - Bit 0)
          Remote OOB Extended Data Request Reply (Octet 32 - Bit 1)
          Read Secure Connections Host Support (Octet 32 - Bit 2)
          Write Secure Connections Host Support (Octet 32 - Bit 3)
          Read Authenticated Payload Timeout (Octet 32 - Bit 4)
          Write Authenticated Payload Timeout (Octet 32 - Bit 5)
          Read Local OOB Extended Data (Octet 32 - Bit 6)
          Write Secure Connections Test Mode (Octet 32 - Bit 7)
          LE Remote Connection Parameter Request Reply (Octet 33 - Bit 4)
          LE Remote Connection Parameter Request Negative Reply (Octet 33 - Bit 5)
          LE Set Data Length (Octet 33 - Bit 6)
          LE Read Suggested Default Data Length (Octet 33 - Bit 7)
          LE Write Suggested Default Data Length (Octet 34 - Bit 0)
          LE Add Device To Resolving List (Octet 34 - Bit 3)
          LE Remove Device From Resolving List (Octet 34 - Bit 4)
          LE Clear Resolving List (Octet 34 - Bit 5)
          LE Read Resolving List Size (Octet 34 - Bit 6)
          LE Read Peer Resolvable Address (Octet 34 - Bit 7)
          LE Read Local Resolvable Address (Octet 35 - Bit 0)
          LE Set Address Resolution Enable (Octet 35 - Bit 1)
          LE Set Resolvable Private Address Timeout (Octet 35 - Bit 2)
< HCI Command: LE Rand (0x08|0x0018) plen 0                                                    #11 [hci0] 5.013827
> HCI Event: Command Complete (0x0e) plen 12                                                   #12 [hci0] 5.027016
      LE Rand (0x08|0x0018) ncmd 1
        Status: Success (0x00)
        Random number: 0xfee61e7ec62bf826
< HCI Command: LE Rand (0x08|0x0018) plen 0                                                    #13 [hci0] 5.031928
> HCI Event: Command Complete (0x0e) plen 12                                                   #14 [hci0] 5.045023
      LE Rand (0x08|0x0018) ncmd 1
        Status: Success (0x00)
        Random number: 0x1c276afe7740c4ff
< HCI Command: LE Rand (0x08|0x0018) plen 0                                                    #15 [hci0] 5.049313
> HCI Event: Command Complete (0x0e) plen 12                                                   #16 [hci0] 5.061988
      LE Rand (0x08|0x0018) ncmd 1
        Status: Success (0x00)
        Random number: 0xf621069453ac7a2d
< HCI Command: LE Rand (0x08|0x0018) plen 0                                                    #17 [hci0] 5.065359
> HCI Event: Command Complete (0x0e) plen 12                                                   #18 [hci0] 5.078030
      LE Rand (0x08|0x0018) ncmd 1
        Status: Success (0x00)
        Random number: 0xc6aa3953c9833a10
< HCI Command: LE Rand (0x08|0x0018) plen 0                                                    #19 [hci0] 5.081638
> HCI Event: Command Complete (0x0e) plen 12                                                   #20 [hci0] 5.095012
      LE Rand (0x08|0x0018) ncmd 1
        Status: Success (0x00)
        Random number: 0x88ac296b87c13816
< HCI Command: Host Buffer Size (0x03|0x0033) plen 7                                           #21 [hci0] 5.099430
        ACL MTU: 27   ACL max packet: 6
        SCO MTU: 0    SCO max packet: 0
> HCI Event: Command Complete (0x0e) plen 4                                                    #22 [hci0] 5.099979
      Host Buffer Size (0x03|0x0033) ncmd 1
        Status: Invalid HCI Command Parameters (0x12)


And on the bluetooth central example side the log is:

[bt] [DBG] hci_tx_thread: (0x00401380) Started
[bt] [DBG] hci_tx_thread: (0x00401380) Calling k_poll with 2 events
[bt] [DBG] h4_open: (0x00401920) 
[bt] [DBG] rx_thread: (0x00401020) started
[bt] [DBG] rx_thread: (0x00401020) rx.buf 0x00000000
[bt] [DBG] bt_hci_cmd_create: (0x00401920) opcode 0x0c03 param_len 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) buf 0x004022c0 opcode 0x0c03 len 3
[bt] [DBG] process_events: (0x00401380) count 2
[bt] [DBG] process_events: (0x00401380) ev->state 4
[bt] [DBG] send_cmd: (0x00401380) calling net_buf_get
[bt] [DBG] send_cmd: (0x00401380) calling sem_take_wait
[bt] [DBG] send_cmd: (0x00401380) Sending command 0x0c03 (buf 0x004022c0) to driver
[bt] [DBG] bt_send: (0x00401380) buf 0x004022c0 len 3 type 0
[bt] [DBG] h4_send: (0x00401380) buf 0x004022c0 type 0 len 3
[bt] [DBG] process_events: (0x00401380) ev->state 0
[bt] [DBG] hci_tx_thread: (0x00401380) Calling k_poll with 2 events
[bt] [DBG] process_rx: (0x004018c0) remaining 0 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] process_rx: (0x004018c0) remaining 2 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] get_evt_hdr: (0x004018c0) Got event header. Payload 4 bytes
[bt] [DBG] process_rx: (0x004018c0) remaining 4 discard 0 have_hdr 1 rx.buf 0x00000000 len 0
[bt] [DBG] get_rx: (0x004018c0) type 0x04, evt 0x0e
[bt] [DBG] bt_buf_get_cmd_complete: (0x004018c0) sent_cmd 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) Allocated rx.buf 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) got 4 bytes, remaining 0
[bt] [DBG] read_payload: (0x004018c0) Payload (len 6): 0e0401030c00
[bt] [DBG] read_payload: (0x004018c0) Calling bt_recv_prio(0x004022c0)
[bt] [DBG] hci_cmd_complete: (0x004018c0) opcode 0x0c03
[bt] [DBG] hci_cmd_done: (0x004018c0) opcode 0x0c03 status 0x00 buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) opcode 0x0c03 status 0x00
[bt] [DBG] hci_reset_complete: (0x00401920) status 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) opcode 0x1003 param_len 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) buf 0x004022c0 opcode 0x1003 len 3
[bt] [DBG] process_events: (0x00401380) count 2
[bt] [DBG] process_events: (0x00401380) ev->state 4
[bt] [DBG] send_cmd: (0x00401380) calling net_buf_get
[bt] [DBG] send_cmd: (0x00401380) calling sem_take_wait
[bt] [DBG] send_cmd: (0x00401380) Sending command 0x1003 (buf 0x004022c0) to driver
[bt] [DBG] bt_send: (0x00401380) buf 0x004022c0 len 3 type 0
[bt] [DBG] h4_send: (0x00401380) buf 0x004022c0 type 0 len 3
[bt] [DBG] process_events: (0x00401380) ev->state 0
[bt] [DBG] hci_tx_thread: (0x00401380) Calling k_poll with 2 events
[bt] [DBG] process_rx: (0x004018c0) remaining 0 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] process_rx: (0x004018c0) remaining 2 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] get_evt_hdr: (0x004018c0) Got event header. Payload 12 bytes
[bt] [DBG] process_rx: (0x004018c0) remaining 12 discard 0 have_hdr 1 rx.buf 0x00000000 len 0
[bt] [DBG] get_rx: (0x004018c0) type 0x04, evt 0x0e
[bt] [DBG] bt_buf_get_cmd_complete: (0x004018c0) sent_cmd 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) Allocated rx.buf 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) got 12 bytes, remaining 0
[bt] [DBG] read_payload: (0x004018c0) Payload (len 14): 0e0c01031000fffe8ffed83f5b87
[bt] [DBG] read_payload: (0x004018c0) Calling bt_recv_prio(0x004022c0)
[bt] [DBG] hci_cmd_complete: (0x004018c0) opcode 0x1003
[bt] [DBG] hci_cmd_done: (0x004018c0) opcode 0x1003 status 0x00 buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) opcode 0x1003 status 0x00
[bt] [DBG] read_local_features_complete: (0x00401920) status 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) opcode 0x1001 param_len 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) buf 0x004022c0 opcode 0x1001 len 3
[bt] [DBG] process_events: (0x00401380) count 2
[bt] [DBG] process_events: (0x00401380) ev->state 4
[bt] [DBG] send_cmd: (0x00401380) calling net_buf_get
[bt] [DBG] send_cmd: (0x00401380) calling sem_take_wait
[bt] [DBG] send_cmd: (0x00401380) Sending command 0x1001 (buf 0x004022c0) to driver
[bt] [DBG] bt_send: (0x00401380) buf 0x004022c0 len 3 type 0
[bt] [DBG] h4_send: (0x00401380) buf 0x004022c0 type 0 len 3
[bt] [DBG] process_events: (0x00401380) ev->state 0
[bt] [DBG] hci_tx_thread: (0x00401380) Calling k_poll with 2 events
[bt] [DBG] process_rx: (0x004018c0) remaining 0 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] process_rx: (0x004018c0) remaining 2 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] get_evt_hdr: (0x004018c0) Got event header. Payload 12 bytes
[bt] [DBG] process_rx: (0x004018c0) remaining 12 discard 0 have_hdr 1 rx.buf 0x00000000 len 0
[bt] [DBG] get_rx: (0x004018c0) type 0x04, evt 0x0e
[bt] [DBG] bt_buf_get_cmd_complete: (0x004018c0) sent_cmd 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) Allocated rx.buf 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) got 8 bytes, remaining 4
[bt] [DBG] read_payload: (0x004018c0) Payload (len 10): 0e0c0101100007000007
[bt] [DBG] process_rx: (0x004018c0) remaining 4 discard 0 have_hdr 1 rx.buf 0x004022c0 len 10
[bt] [DBG] read_payload: (0x004018c0) got 4 bytes, remaining 0
[bt] [DBG] read_payload: (0x004018c0) Payload (len 14): 0e0c01011000070000071d005a02
[bt] [DBG] read_payload: (0x004018c0) Calling bt_recv_prio(0x004022c0)
[bt] [DBG] hci_cmd_complete: (0x004018c0) opcode 0x1001
[bt] [DBG] hci_cmd_done: (0x004018c0) opcode 0x1001 status 0x00 buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) opcode 0x1001 status 0x00
[bt] [DBG] read_local_ver_complete: (0x00401920) status 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) opcode 0x1009 param_len 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) buf 0x004022c0 opcode 0x1009 len 3
[bt] [DBG] process_events: (0x00401380) count 2
[bt] [DBG] process_events: (0x00401380) ev->state 4
[bt] [DBG] send_cmd: (0x00401380) calling net_buf_get
[bt] [DBG] send_cmd: (0x00401380) calling sem_take_wait
[bt] [DBG] send_cmd: (0x00401380) Sending command 0x1009 (buf 0x004022c0) to driver
[bt] [DBG] bt_send: (0x00401380) buf 0x004022c0 len 3 type 0
[bt] [DBG] h4_send: (0x00401380) buf 0x004022c0 type 0 len 3
[bt] [DBG] process_events: (0x00401380) ev->state 0
[bt] [DBG] hci_tx_thread: (0x00401380) Calling k_poll with 2 events
[bt] [DBG] process_rx: (0x004018c0) remaining 0 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] process_rx: (0x004018c0) remaining 2 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] get_evt_hdr: (0x004018c0) Got event header. Payload 10 bytes
[bt] [DBG] process_rx: (0x004018c0) remaining 10 discard 0 have_hdr 1 rx.buf 0x00000000 len 0
[bt] [DBG] get_rx: (0x004018c0) type 0x04, evt 0x0e
[bt] [DBG] bt_buf_get_cmd_complete: (0x004018c0) sent_cmd 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) Allocated rx.buf 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) got 10 bytes, remaining 0
[bt] [DBG] read_payload: (0x004018c0) Payload (len 12): 0e0a01091000acf7f079e994
[bt] [DBG] read_payload: (0x004018c0) Calling bt_recv_prio(0x004022c0)
[bt] [DBG] hci_cmd_complete: (0x004018c0) opcode 0x1009
[bt] [DBG] hci_cmd_done: (0x004018c0) opcode 0x1009 status 0x00 buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) opcode 0x1009 status 0x00
[bt] [DBG] read_bdaddr_complete: (0x00401920) status 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) opcode 0x1002 param_len 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) buf 0x004022c0 opcode 0x1002 len 3
[bt] [DBG] process_events: (0x00401380) count 2
[bt] [DBG] process_events: (0x00401380) ev->state 4
[bt] [DBG] send_cmd: (0x00401380) calling net_buf_get
[bt] [DBG] send_cmd: (0x00401380) calling sem_take_wait
[bt] [DBG] send_cmd: (0x00401380) Sending command 0x1002 (buf 0x004022c0) to driver
[bt] [DBG] bt_send: (0x00401380) buf 0x004022c0 len 3 type 0
[bt] [DBG] h4_send: (0x00401380) buf 0x004022c0 type 0 len 3
[bt] [DBG] process_events: (0x00401380) ev->state 0
[bt] [DBG] hci_tx_thread: (0x00401380) Calling k_poll with 2 events
[bt] [DBG] process_rx: (0x004018c0) remaining 0 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] process_rx: (0x004018c0) remaining 2 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] get_evt_hdr: (0x004018c0) Got event header. Payload 68 bytes
[bt] [DBG] process_rx: (0x004018c0) remaining 68 discard 0 have_hdr 1 rx.buf 0x00000000 len 0
[bt] [DBG] get_rx: (0x004018c0) type 0x04, evt 0x0e
[bt] [DBG] bt_buf_get_cmd_complete: (0x004018c0) sent_cmd 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) Allocated rx.buf 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) got 8 bytes, remaining 60
[bt] [DBG] read_payload: (0x004018c0) Payload (len 10): 0e4401021000ffffff03
[bt] [DBG] process_rx: (0x004018c0) remaining 60 discard 0 have_hdr 1 rx.buf 0x004022c0 len 10
[bt] [DBG] read_payload: (0x004018c0) got 8 bytes, remaining 52
[bt] [DBG] read_payload: (0x004018c0) Payload (len 18): 0e4401021000ffffff03ceffefffffffff7f
[bt] [DBG] process_rx: (0x004018c0) remaining 52 discard 0 have_hdr 1 rx.buf 0x004022c0 len 18
[bt] [DBG] read_payload: (0x004018c0) got 8 bytes, remaining 44
[bt] [DBG] read_payload: (0x004018c0) Payload (len 26): 0e4401021000ffffff03ceffefffffffff7ff20fe8fe3ff783ff
[bt] [DBG] process_rx: (0x004018c0) remaining 44 discard 0 have_hdr 1 rx.buf 0x004022c0 len 26
[bt] [DBG] read_payload: (0x004018c0) got 44 bytes, remaining 0
[bt] [DBG] read_payload: (0x004018c0) Payload (len 70): 0e4401021000ffffff03ceffefffffffff7ff20fe8fe3ff783ff1c00000061ffffff7f8620f5fff0f90700000000000000000000000000000000000000000000
[bt] [DBG] read_payload: (0x004018c0) Calling bt_recv_prio(0x004022c0)
[bt] [DBG] hci_cmd_complete: (0x004018c0) opcode 0x1002
[bt] [DBG] hci_cmd_done: (0x004018c0) opcode 0x1002 status 0x00 buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) opcode 0x1002 status 0x00
[bt] [DBG] read_supported_commands_complete: (0x00401920) status 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) opcode 0x2018 param_len 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) buf 0x004022c0 opcode 0x2018 len 3
[bt] [DBG] process_events: (0x00401380) count 2
[bt] [DBG] process_events: (0x00401380) ev->state 4
[bt] [DBG] send_cmd: (0x00401380) calling net_buf_get
[bt] [DBG] send_cmd: (0x00401380) calling sem_take_wait
[bt] [DBG] send_cmd: (0x00401380) Sending command 0x2018 (buf 0x004022c0) to driver
[bt] [DBG] bt_send: (0x00401380) buf 0x004022c0 len 3 type 0
[bt] [DBG] h4_send: (0x00401380) buf 0x004022c0 type 0 len 3
[bt] [DBG] process_events: (0x00401380) ev->state 0
[bt] [DBG] hci_tx_thread: (0x00401380) Calling k_poll with 2 events
[bt] [DBG] process_rx: (0x004018c0) remaining 0 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] process_rx: (0x004018c0) remaining 2 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] get_evt_hdr: (0x004018c0) Got event header. Payload 12 bytes
[bt] [DBG] process_rx: (0x004018c0) remaining 12 discard 0 have_hdr 1 rx.buf 0x00000000 len 0
[bt] [DBG] get_rx: (0x004018c0) type 0x04, evt 0x0e
[bt] [DBG] bt_buf_get_cmd_complete: (0x004018c0) sent_cmd 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) Allocated rx.buf 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) got 8 bytes, remaining 4
[bt] [DBG] read_payload: (0x004018c0) Payload (len 10): 0e0c0118200094c5cddc
[bt] [DBG] process_rx: (0x004018c0) remaining 4 discard 0 have_hdr 1 rx.buf 0x004022c0 len 10
[bt] [DBG] read_payload: (0x004018c0) got 4 bytes, remaining 0
[bt] [DBG] read_payload: (0x004018c0) Payload (len 14): 0e0c0118200094c5cddc62b94c8c
[bt] [DBG] read_payload: (0x004018c0) Calling bt_recv_prio(0x004022c0)
[bt] [DBG] hci_cmd_complete: (0x004018c0) opcode 0x2018
[bt] [DBG] hci_cmd_done: (0x004018c0) opcode 0x2018 status 0x00 buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) opcode 0x2018 status 0x00
[bt] [DBG] bt_hci_cmd_create: (0x00401920) opcode 0x2018 param_len 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) buf 0x004022c0 opcode 0x2018 len 3
[bt] [DBG] process_events: (0x00401380) count 2
[bt] [DBG] process_events: (0x00401380) ev->state 4
[bt] [DBG] send_cmd: (0x00401380) calling net_buf_get
[bt] [DBG] send_cmd: (0x00401380) calling sem_take_wait
[bt] [DBG] send_cmd: (0x00401380) Sending command 0x2018 (buf 0x004022c0) to driver
[bt] [DBG] bt_send: (0x00401380) buf 0x004022c0 len 3 type 0
[bt] [DBG] h4_send: (0x00401380) buf 0x004022c0 type 0 len 3
[bt] [DBG] process_events: (0x00401380) ev->state 0
[bt] [DBG] hci_tx_thread: (0x00401380) Calling k_poll with 2 events
[bt] [DBG] process_rx: (0x004018c0) remaining 0 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] process_rx: (0x004018c0) remaining 2 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] get_evt_hdr: (0x004018c0) Got event header. Payload 12 bytes
[bt] [DBG] process_rx: (0x004018c0) remaining 12 discard 0 have_hdr 1 rx.buf 0x00000000 len 0
[bt] [DBG] get_rx: (0x004018c0) type 0x04, evt 0x0e
[bt] [DBG] bt_buf_get_cmd_complete: (0x004018c0) sent_cmd 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) Allocated rx.buf 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) got 8 bytes, remaining 4
[bt] [DBG] read_payload: (0x004018c0) Payload (len 10): 0e0c0118200044fc668a
[bt] [DBG] process_rx: (0x004018c0) remaining 4 discard 0 have_hdr 1 rx.buf 0x004022c0 len 10
[bt] [DBG] read_payload: (0x004018c0) got 4 bytes, remaining 0
[bt] [DBG] read_payload: (0x004018c0) Payload (len 14): 0e0c0118200044fc668ab71870bb
[bt] [DBG] read_payload: (0x004018c0) Calling bt_recv_prio(0x004022c0)
[bt] [DBG] hci_cmd_complete: (0x004018c0) opcode 0x2018
[bt] [DBG] hci_cmd_done: (0x004018c0) opcode 0x2018 status 0x00 buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) opcode 0x2018 status 0x00
[bt] [DBG] bt_hci_cmd_create: (0x00401920) opcode 0x2018 param_len 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) buf 0x004022c0 opcode 0x2018 len 3
[bt] [DBG] process_events: (0x00401380) count 2
[bt] [DBG] process_events: (0x00401380) ev->state 4
[bt] [DBG] send_cmd: (0x00401380) calling net_buf_get
[bt] [DBG] send_cmd: (0x00401380) calling sem_take_wait
[bt] [DBG] send_cmd: (0x00401380) Sending command 0x2018 (buf 0x004022c0) to driver
[bt] [DBG] bt_send: (0x00401380) buf 0x004022c0 len 3 type 0
[bt] [DBG] h4_send: (0x00401380) buf 0x004022c0 type 0 len 3
[bt] [DBG] process_events: (0x00401380) ev->state 0
[bt] [DBG] hci_tx_thread: (0x00401380) Calling k_poll with 2 events
[bt] [DBG] process_rx: (0x004018c0) remaining 0 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] process_rx: (0x004018c0) remaining 2 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] get_evt_hdr: (0x004018c0) Got event header. Payload 12 bytes
[bt] [DBG] process_rx: (0x004018c0) remaining 12 discard 0 have_hdr 1 rx.buf 0x00000000 len 0
[bt] [DBG] get_rx: (0x004018c0) type 0x04, evt 0x0e
[bt] [DBG] bt_buf_get_cmd_complete: (0x004018c0) sent_cmd 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) Allocated rx.buf 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) got 8 bytes, remaining 4
[bt] [DBG] read_payload: (0x004018c0) Payload (len 10): 0e0c01182000b519a7e7
[bt] [DBG] process_rx: (0x004018c0) remaining 4 discard 0 have_hdr 1 rx.buf 0x004022c0 len 10
[bt] [DBG] read_payload: (0x004018c0) got 4 bytes, remaining 0
[bt] [DBG] read_payload: (0x004018c0) Payload (len 14): 0e0c01182000b519a7e71b0ddfd8
[bt] [DBG] read_payload: (0x004018c0) Calling bt_recv_prio(0x004022c0)
[bt] [DBG] hci_cmd_complete: (0x004018c0) opcode 0x2018
[bt] [DBG] hci_cmd_done: (0x004018c0) opcode 0x2018 status 0x00 buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) opcode 0x2018 status 0x00
[bt] [DBG] bt_hci_cmd_create: (0x00401920) opcode 0x2018 param_len 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) buf 0x004022c0 opcode 0x2018 len 3
[bt] [DBG] process_events: (0x00401380) count 2
[bt] [DBG] process_events: (0x00401380) ev->state 4
[bt] [DBG] send_cmd: (0x00401380) calling net_buf_get
[bt] [DBG] send_cmd: (0x00401380) calling sem_take_wait
[bt] [DBG] send_cmd: (0x00401380) Sending command 0x2018 (buf 0x004022c0) to driver
[bt] [DBG] bt_send: (0x00401380) buf 0x004022c0 len 3 type 0
[bt] [DBG] h4_send: (0x00401380) buf 0x004022c0 type 0 len 3
[bt] [DBG] process_events: (0x00401380) ev->state 0
[bt] [DBG] hci_tx_thread: (0x00401380) Calling k_poll with 2 events
[bt] [DBG] process_rx: (0x004018c0) remaining 0 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] process_rx: (0x004018c0) remaining 2 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] get_evt_hdr: (0x004018c0) Got event header. Payload 12 bytes
[bt] [DBG] process_rx: (0x004018c0) remaining 12 discard 0 have_hdr 1 rx.buf 0x00000000 len 0
[bt] [DBG] get_rx: (0x004018c0) type 0x04, evt 0x0e
[bt] [DBG] bt_buf_get_cmd_complete: (0x004018c0) sent_cmd 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) Allocated rx.buf 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) got 8 bytes, remaining 4
[bt] [DBG] read_payload: (0x004018c0) Payload (len 10): 0e0c01182000765e4abf
[bt] [DBG] process_rx: (0x004018c0) remaining 4 discard 0 have_hdr 1 rx.buf 0x004022c0 len 10
[bt] [DBG] read_payload: (0x004018c0) got 4 bytes, remaining 0
[bt] [DBG] read_payload: (0x004018c0) Payload (len 14): 0e0c01182000765e4abfadd043f9
[bt] [DBG] read_payload: (0x004018c0) Calling bt_recv_prio(0x004022c0)
[bt] [DBG] hci_cmd_complete: (0x004018c0) opcode 0x2018
[bt] [DBG] hci_cmd_done: (0x004018c0) opcode 0x2018 status 0x00 buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) opcode 0x2018 status 0x00
[bt] [DBG] bt_hci_cmd_create: (0x00401920) opcode 0x2018 param_len 0
[bt] [DBG] bt_hci_cmd_create: (0x00401920) buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) buf 0x004022c0 opcode 0x2018 len 3
[bt] [DBG] process_events: (0x00401380) count 2
[bt] [DBG] process_events: (0x00401380) ev->state 4
[bt] [DBG] send_cmd: (0x00401380) calling net_buf_get
[bt] [DBG] send_cmd: (0x00401380) calling sem_take_wait
[bt] [DBG] send_cmd: (0x00401380) Sending command 0x2018 (buf 0x004022c0) to driver
[bt] [DBG] bt_send: (0x00401380) buf 0x004022c0 len 3 type 0
[bt] [DBG] h4_send: (0x00401380) buf 0x004022c0 type 0 len 3
[bt] [DBG] process_events: (0x00401380) ev->state 0
[bt] [DBG] hci_tx_thread: (0x00401380) Calling k_poll with 2 events
[bt] [DBG] process_rx: (0x004018c0) remaining 0 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] process_rx: (0x004018c0) remaining 2 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] get_evt_hdr: (0x004018c0) Got event header. Payload 12 bytes
[bt] [DBG] process_rx: (0x004018c0) remaining 12 discard 0 have_hdr 1 rx.buf 0x00000000 len 0
[bt] [DBG] get_rx: (0x004018c0) type 0x04, evt 0x0e
[bt] [DBG] bt_buf_get_cmd_complete: (0x004018c0) sent_cmd 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) Allocated rx.buf 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) got 8 bytes, remaining 4
[bt] [DBG] read_payload: (0x004018c0) Payload (len 10): 0e0c01182000dd758a93
[bt] [DBG] process_rx: (0x004018c0) remaining 4 discard 0 have_hdr 1 rx.buf 0x004022c0 len 10
[bt] [DBG] read_payload: (0x004018c0) got 4 bytes, remaining 0
[bt] [DBG] read_payload: (0x004018c0) Payload (len 14): 0e0c01182000dd758a930ddcc03d
[bt] [DBG] read_payload: (0x004018c0) Calling bt_recv_prio(0x004022c0)
[bt] [DBG] hci_cmd_complete: (0x004018c0) opcode 0x2018
[bt] [DBG] hci_cmd_done: (0x004018c0) opcode 0x2018 status 0x00 buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) opcode 0x2018 status 0x00
[bt] [DBG] bt_hci_cmd_create: (0x00401920) opcode 0x0c33 param_len 7
[bt] [DBG] bt_hci_cmd_create: (0x00401920) buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) buf 0x004022c0 opcode 0x0c33 len 10
[bt] [DBG] process_events: (0x00401380) count 2
[bt] [DBG] process_events: (0x00401380) ev->state 4
[bt] [DBG] send_cmd: (0x00401380) calling net_buf_get
[bt] [DBG] send_cmd: (0x00401380) calling sem_take_wait
[bt] [DBG] send_cmd: (0x00401380) Sending command 0x0c33 (buf 0x004022c0) to driver
[bt] [DBG] bt_send: (0x00401380) buf 0x004022c0 len 10 type 0
[bt] [DBG] h4_send: (0x00401380) buf 0x004022c0 type 0 len 10
[bt] [DBG] process_events: (0x00401380) ev->state 0
[bt] [DBG] hci_tx_thread: (0x00401380) Calling k_poll with 2 events
[bt] [DBG] process_rx: (0x004018c0) remaining 0 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] process_rx: (0x004018c0) remaining 2 discard 0 have_hdr 0 rx.buf 0x00000000 len 0
[bt] [DBG] get_evt_hdr: (0x004018c0) Got event header. Payload 4 bytes
[bt] [DBG] process_rx: (0x004018c0) remaining 4 discard 0 have_hdr 1 rx.buf 0x00000000 len 0
[bt] [DBG] get_rx: (0x004018c0) type 0x04, evt 0x0e
[bt] [DBG] bt_buf_get_cmd_complete: (0x004018c0) sent_cmd 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) Allocated rx.buf 0x004022c0
[bt] [DBG] read_payload: (0x004018c0) got 4 bytes, remaining 0
[bt] [DBG] read_payload: (0x004018c0) Payload (len 6): 0e0401330c12
[bt] [DBG] read_payload: (0x004018c0) Calling bt_recv_prio(0x004022c0)
[bt] [DBG] hci_cmd_complete: (0x004018c0) opcode 0x0c33
[bt] [DBG] hci_cmd_done: (0x004018c0) opcode 0x0c33 status 0x12 buf 0x004022c0
[bt] [DBG] bt_hci_cmd_send_sync: (0x00401920) opcode 0x0c33 status 0x12
Bluetooth init failed (err -5)


BR, Primini

On Tue, Nov 21, 2017 at 5:15 PM, Johan Hedberg <johan.hedberg@...> wrote:
Hi Tiago,

On Tue, Nov 21, 2017, Tiago Primini wrote:
> Bluetooth init failed (err -5)
>
> I also have configured btproxy in my ubuntu host:
>
> $ sudo ./btproxy -u
> Listening on /tmp/bt-server-bredr
> Opening user channel for hci0
> New client connected
>
> Is there anything missing in the configuration or maybe additional steps?

I can't really say for sure what's going wrong, but it would help if you
got some more logs for the situation. On the Linux side, you could run
btmon to see what HCI commands (if any) Zephyr manages to send. On the
Zephyr side, you could add at least the following to your app's prj.conf:

CONFIG_BT_DEBUG_LOG=y
CONFIG_BT_DEBUG_HCI_DRIVER=y
CONFIG_BT_DEBUG_HCI_CORE=y

With those you should be able to see a bit more of what's happening in
the Zephyr console.

Johan


Johan Hedberg
 

Hi Tiago,

On Wed, Nov 22, 2017, Tiago Primini wrote:
< HCI Command: Host Buffer Size (0x03|0x0033) plen 7
ACL MTU: 27 ACL max packet: 6
SCO MTU: 0 SCO max packet: 0
HCI Event: Command Complete (0x0e) plen 4
Host Buffer Size (0x03|0x0033) ncmd 1
Status: Invalid HCI Command Parameters (0x12)
This looks like the reason for the failure. I.e. your PC's Broadcom
controller doesn't like the Host Buffer Size HCI command that Zephyr
sends, causing the Zephyr Bluetooth initialization to fail.

As per the Bluetooth Core Specification, there's nothing inherently
invalid about the parameters Zephyr gives your controller, despite it
claiming otherwise. It could simply be that this less often used feature
is either missing or incorrectly implemented in your controller.

There are two options from here:

1. Use another controller.

2. Disable the Host flow control feature in Zephyr, i.e. set
CONFIG_BT_HCI_ACL_FLOW_CONTROL=n in your configuration.

The second option may have some unwanted side effects, and possibly
require you to increase the Zephyr host buffer count to compensate for
the lack of flow control (CONFIG_BT_RX_BUF_COUNT option). However it may
be the most practical one in the short term.

Johan


Primini
 

Hi Johan,

Disabling host flow control using the option that you mentioned the sample works fine.
I will take care some side effects because of this configuration, thanks for the advice.

Have a nice day,

Primini



On Wed, Nov 22, 2017 at 8:40 AM, Johan Hedberg <johan.hedberg@...> wrote:
Hi Tiago,

On Wed, Nov 22, 2017, Tiago Primini wrote:
> < HCI Command: Host Buffer Size (0x03|0x0033) plen 7
>         ACL MTU: 27   ACL max packet: 6
>         SCO MTU: 0    SCO max packet: 0
> > HCI Event: Command Complete (0x0e) plen 4
>       Host Buffer Size (0x03|0x0033) ncmd 1
>         Status: Invalid HCI Command Parameters (0x12)

This looks like the reason for the failure. I.e. your PC's Broadcom
controller doesn't like the Host Buffer Size HCI command that Zephyr
sends, causing the Zephyr Bluetooth initialization to fail.

As per the Bluetooth Core Specification, there's nothing inherently
invalid about the parameters Zephyr gives your controller, despite it
claiming otherwise. It could simply be that this less often used feature
is either missing or incorrectly implemented in your controller.

There are two options from here:

 1. Use another controller.

 2. Disable the Host flow control feature in Zephyr, i.e. set
 CONFIG_BT_HCI_ACL_FLOW_CONTROL=n in your configuration.

The second option may have some unwanted side effects, and possibly
require you to increase the Zephyr host buffer count to compensate for
the lack of flow control (CONFIG_BT_RX_BUF_COUNT option). However it may
be the most practical one in the short term.

Johan


Primini
 

Hi Johan, another issue:

Every time my application stay connected for a period it receives a disconnection with the following code:

[bt] [DBG] bt_smp_recv: (0x20002048) Received SMP code 0x06 len 17
[bt] [DBG] smp_encrypt_info: (0x20002048) 
[bt] [DBG] bt_smp_recv: (0x20002048) Received SMP code 0x07 len 11
[bt] [DBG] smp_master_ident: (0x20002048) 
[bt] [DBG] bt_smp_recv: (0x20002048) Received SMP code 0x08 len 17
[bt] [DBG] smp_ident_info: (0x20002048) 
[bt] [DBG] bt_smp_recv: (0x20002048) Received SMP code 0x09 len 8
[bt] [DBG] smp_ident_addr_info: (0x20002048) identity 40:88:05:79:66:96 (public)
Identity resolved 5e:ea:ae:c4:8f:c9 (random) -> 40:88:05:79:66:96 (public)
[bt] [DBG] smp_pairing_complete: (0x20002048) status 0x0
[bt] [DBG] bt_smp_disconnected: (0x20002048) chan 0x20000b4c cid 0x0006
Disconnected (reason 19)

Do you have any insight?

BR, Primini

On Wed, Nov 22, 2017 at 8:59 AM, Tiago Primini <primini@...> wrote:
Hi Johan,

Disabling host flow control using the option that you mentioned the sample works fine.
I will take care some side effects because of this configuration, thanks for the advice.

Have a nice day,

Primini



On Wed, Nov 22, 2017 at 8:40 AM, Johan Hedberg <johan.hedberg@...> wrote:
Hi Tiago,

On Wed, Nov 22, 2017, Tiago Primini wrote:
> < HCI Command: Host Buffer Size (0x03|0x0033) plen 7
>         ACL MTU: 27   ACL max packet: 6
>         SCO MTU: 0    SCO max packet: 0
> > HCI Event: Command Complete (0x0e) plen 4
>       Host Buffer Size (0x03|0x0033) ncmd 1
>         Status: Invalid HCI Command Parameters (0x12)

This looks like the reason for the failure. I.e. your PC's Broadcom
controller doesn't like the Host Buffer Size HCI command that Zephyr
sends, causing the Zephyr Bluetooth initialization to fail.

As per the Bluetooth Core Specification, there's nothing inherently
invalid about the parameters Zephyr gives your controller, despite it
claiming otherwise. It could simply be that this less often used feature
is either missing or incorrectly implemented in your controller.

There are two options from here:

 1. Use another controller.

 2. Disable the Host flow control feature in Zephyr, i.e. set
 CONFIG_BT_HCI_ACL_FLOW_CONTROL=n in your configuration.

The second option may have some unwanted side effects, and possibly
require you to increase the Zephyr host buffer count to compensate for
the lack of flow control (CONFIG_BT_RX_BUF_COUNT option). However it may
be the most practical one in the short term.

Johan