What does one have to do to activate BT_DBG?

[jefffhaynes]

In the midst of SMP debug hell and I've been completely unable to get BT_DBG to trace anything out, at least in some modules (??)

Version is 2.7.99. It's a custom board running nrf52840.

prj.conf:

CONFIG_GPIO=y

# enable c++ support
CONFIG_CPLUSPLUS=y
CONFIG_LIB_CPLUSPLUS=y
CONFIG_NEWLIB_LIBC=y
CONFIG_NEWLIB_LIBC_FLOAT_PRINTF=y

CONFIG_HW_STACK_PROTECTION=y

# internal clock (TODO move to board def)
CONFIG_CLOCK_CONTROL_NRF_K32SRC_RC=y
CONFIG_BOARD_ENABLE_DCDC=n

# enable reboot from user space
CONFIG_REBOOT=y

CONFIG_FPU=y
CONFIG_MAIN_STACK_SIZE=16384
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=4096
CONFIG_MULTITHREADING=y

# serial console
CONFIG_PRINTK=y
CONFIG_CONSOLE=y
CONFIG_SERIAL=y
CONFIG_STDOUT_CONSOLE=y

# RTT
CONFIG_UART_CONSOLE=n
CONFIG_USE_SEGGER_RTT=y
CONFIG_RTT_CONSOLE=y
CONFIG_LOG_BACKEND_RTT=y

# i2c configuration for accelerometer
CONFIG_I2C=y

# enable PDM driver
CONFIG_NRFX_PDM=y

# enable PWM
CONFIG_PWM=y

# Bluetooth
CONFIG_BT=y

CONFIG_BT_SMP=y
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_ATT_PREPARE_COUNT=5
CONFIG_BT_PRIVACY=n
CONFIG_BT_CONN_TX_MAX=16
CONFIG_BT_DEVICE_NAME="Device"
CONFIG_BT_DEVICE_APPEARANCE=833

CONFIG_BT_SMP_SC_ONLY=y
CONFIG_BT_FIXED_PASSKEY=y
CONFIG_BT_MAX_PAIRED=3
CONFIG_BT_TINYCRYPT_ECC=y

CONFIG_BT_KEYS_OVERWRITE_OLDEST=y
CONFIG_BT_SETTINGS=y
CONFIG_FLASH_MAP=y
CONFIG_SETTINGS=y

# bluetooth debug
CONFIG_BT_DEBUG_LOG=y
CONFIG_BT_DEBUG_CONN=y
CONFIG_BT_DEBUG_ATT=y
CONFIG_BT_DEBUG_GATT=y
CONFIG_BT_LOG_LEVEL_DBG=y
CONFIG_BT_DEBUG_SMP=y

# debug settings
CONFIG_LOG_PROCESS_THREAD_STACK_SIZE=4096
CONFIG_BT_RX_STACK_SIZE=4096
CONFIG_BT_CTLR_RX_PRIO_STACK_SIZE=4096
CONFIG_DEBUG=y
CONFIG_LOG=y
CONFIG_ASSERT=y

# Allow for large Bluetooth data packets.
CONFIG_BT_L2CAP_TX_MTU=247

# Flash
CONFIG_FLASH=y
CONFIG_MPU_ALLOW_FLASH_WRITE=y
CONFIG_FLASH_PAGE_LAYOUT=y

# Internal Flash
CONFIG_NVS=y

# Accelerometer
CONFIG_SENSOR=y
CONFIG_LIS2DS12=y
CONFIG_LIS2DS12_TRIGGER_OWN_THREAD=y

CONFIG_I2S=y
CONFIG_NRFX_I2S=y

CONFIG_TEMP_NRF5=y

This is what I get out:

[00:00:00.000,000] <dbg> bt_hci_core.bt_hci_driver_register: Registered Controller
[00:00:00.000,915] <inf> LIS2DS12: LIS2DS12: int on GPIO_0.30
--- 447 messages dropped ---
[00:00:00.035,736] <dbg> bt_hci_core.hci_tx_thread: Calling k_poll with 2 events
[00:00:00.035,797] <dbg> bt_hci_core.bt_hci_cmd_send_sync: rsp 0x200257e8 opcode 0x2009 len 1
[00:00:00.035,888] <dbg> bt_conn.bt_conn_set_state: disconnected -> connect-adv
[00:00:00.035,919] <dbg> bt_conn.bt_conn_ref: handle 0 ref 1 -> 2
[00:00:00.035,919] <dbg> bt_hci_core.bt_hci_cmd_create: opcode 0x200a param_len 1
[00:00:00.035,949] <dbg> bt_hci_core.bt_hci_cmd_create: buf 0x200257e8
[00:00:00.036,010] <dbg> bt_hci_core.bt_hci_cmd_send_sync: buf 0x200257e8 opcode 0x200a len 4
[00:00:00.036,071] <dbg> bt_hci_core.process_events: count 2
[00:00:00.036,071] <dbg> bt_hci_core.process_events: ev->state 4
[00:00:00.036,102] <dbg> bt_uf_get
connected

OnPasskeyDisplay: 1234

OnSecurityChanged: 1

OnPairingFailed: 9

disconnected

There doesn't appear to be anything from the SMP module.

EDIT: This may have something to do with messages being silently dropped by the RTT backend, not sure

[nordic-krch]

you have a lot of dropped messages --- 447 messages dropped --- you can try to increase logging buffer (e.g.CONFIG_LOG_BUFFER_SIZE=8192). Another thing to increase is CONFIG_SEGGER_RTT_BUFFER_SIZE_UP.

[jefffhaynes]

That did the trick, thanks. Unfortunately this is starting to look like a sort of heisenbug where fixed key pairing works when logging is turned on and fails when it's turned off.

[jefffhaynes]

I very much believe this to be a legitimate bug. When logging is turned off, fixed key pairing fails every time. When turned on it succeeds every time. I'm having trouble rationalizing that as expected behavior.

[jefffhaynes]

I'm able to get it to reliably fail if I simply setup a callback to .pairing_confirm and have it always call bt_conn_auth_pairing_confirm from within the callback. This is with fixed key disabled. All my characteristics are marked as requiring authentication.

Here is the output:

connected

[00:00:21.975,738] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem taken
[00:00:21.975,769] <dbg> bt_ctlr_hci_driver.prio_recv_thread: RX node enqueue
[00:00:21.975,799] <dbg> bt_ctlr_hci_driver.prio_recv_thread: RX node enqueue
[00:00:21.975,799] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem take...
[00:00:21.975,830] <dbg> bt_ctlr_hci_driver.recv_thread: unblocked
[00:00:21.975,860] <dbg> bt_ctlr_hci_driver.recv_thread: Packet in: type:1 len:33
[00:00:21.975,860] <dbg> bt_hci_core.bt_recv: buf 0x20035cbc len 33
[00:00:21.975,891] <dbg> bt_hci_core.hci_event: event 0x3e
[00:00:21.975,891] <dbg> bt_hci_core.hci_le_meta_event: subevent 0x0a
[00:00:21.976,165] <dbg> bt_hci_core.bt_hci_le_enh_conn_complete: status 0x00 handle 0 role 1 peer 00:15:83:FD:58:0E (public) peer RPA 00:00:00:00:00:00
[00:00:21.976,287] <dbg> bt_hci_core.bt_hci_le_enh_conn_complete: local RPA 00:00:00:00:00:00
[00:00:21.976,440] <dbg> bt_keys.bt_keys_find_irk: 00:15:83:FD:58:0E (public)
[00:00:21.976,440] <dbg> bt_conn.bt_conn_ref: handle 0 ref 1 -> 2
[00:00:21.976,470] <dbg> bt_conn.bt_conn_unref: handle 0 ref 2 -> 1
[00:00:21.976,501] <dbg> bt_conn.bt_conn_ref: handle 0 ref 1 -> 2
[00:00:21.976,562] <dbg> bt_conn.bt_conn_set_state: disconnected -> connect-adv
[00:00:21.976,562] <dbg> bt_conn.bt_conn_ref: handle 0 ref 1 -> 2
[00:00:21.976,562] <dbg> bt_adv.bt_le_adv_resume: Resuming connectable advertising
[00:00:21.976,562] <dbg> bt_hci_core.bt_hci_cmd_create: opcode 0x200a param_len 1
[00:00:21.976,593] <dbg> bt_hci_core.bt_hci_cmd_create: buf 0x20035dec
[00:00:21.976,623] <dbg> bt_hci_core.bt_hci_cmd_send_sync: buf 0x20035dec opcode 0x200a len 4
[00:00:21.976,684] <dbg> bt_hci_core.process_events: count 2
[00:00:21.976,684] <dbg> bt_hci_core.process_events: ev->state 4
[00:00:21.976,684] <dbg> bt_hci_core.send_cmd: calling net_buf_get
[00:00:21.976,684] <dbg> bt_hci_core.send_cmd: calling sem_take_wait
[00:00:21.976,715] <dbg> bt_hci_core.send_cmd: Sending command 0x200a (buf 0x20035dec) to driver
[00:00:21.976,715] <dbg> bt_hci_core.bt_send: buf 0x20035dec len 4 type 0
[00:00:21.976,745] <dbg> bt_ctlr_hci_driver.hci_driver_send: enter
[00:00:21.976,806] <dbg> bt_ctlr_hci_driver.cmd_handle: Replying with event of 6 bytes
[00:00:21.976,806] <dbg> bt_hci_core.hci_cmd_complete: opcode 0x200a
[00:00:21.976,837] <dbg> bt_hci_core.hci_cmd_done: opcode 0x200a status 0x00 buf 0x20035dec
[00:00:21.976,989] <dbg> bt_ctlr_hci_driver.hci_driver_send: exit: 0
[00:00:21.977,020] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:21.977,020] <dbg> bt_conn.bt_conn_prepare_events: 
[00:00:21.977,050] <dbg> bt_hci_core.hci_tx_thread: Calling k_poll with 2 events
[00:00:21.977,081] <dbg> bt_hci_core.bt_hci_cmd_send_sync: rsp 0x20035dec opcode 0x200a len 1
[00:00:21.977,111] <dbg> bt_conn.bt_conn_unref: handle 0 ref 2 -> 1
[00:00:21.977,111] <dbg> bt_conn.bt_conn_set_state: connect-adv -> connected
[00:00:21.977,142] <dbg> bt_att.bt_att_accept: conn 0x20002758 handle 0
[00:00:21.977,233] <dbg> bt_l2cap.bt_l2cap_chan_add: conn 0x20002758 chan 0x20030810
[00:00:21.977,264] <dbg> bt_att.bt_att_connected: chan 0x20030810 cid 0x0004
[00:00:21.977,264] <dbg> bt_att.att_chan_attach: att 0x2003619c chan 0x20030808 flags 0
[00:00:21.977,294] <dbg> bt_att.bt_att_status: chan 0x20030810 status 0x20030878
[00:00:21.977,294] <dbg> bt_l2cap.l2cap_accept: conn 0x20002758 handle 0
[00:00:21.977,294] <dbg> bt_l2cap.bt_l2cap_chan_add: conn 0x20002758 chan 0x20002d98
[00:00:21.977,325] <dbg> bt_l2cap.l2cap_connected: ch 0x20002d98 cid 0x0005
[00:00:21.977,325] <dbg> bt_smp.bt_smp_accept: conn 0x20002758 handle 0
[00:00:21.977,355] <dbg> bt_l2cap.bt_l2cap_chan_add: conn 0x20002758 chan 0x200036d8
[00:00:21.977,355] <dbg> bt_smp.bt_smp_connected: chan 0x200036d8 cid 0x0006
[00:00:21.977,386] <dbg> bt_conn.bt_conn_ref: handle 0 ref 2 -> 3
[00:00:21.977,966] <dbg> bt_gatt.bt_gatt_connected: conn 0x20002758
[00:00:21.978,118] <dbg> bt_keys.bt_keys_find_addr: 00:15:83:FD:58:0E (public)
[00:00:21.978,118] <dbg> bt_hci_core.bt_hci_cmd_create: opcode 0x2016 param_len 2
[00:00:21.978,149] <dbg> bt_hci_core.bt_hci_cmd_create: buf 0x20035dec
[00:00:21.978,149] <dbg> bt_hci_core.bt_hci_cmd_send: opcode 0x2016 len 5
[00:00:21.978,179] <dbg> bt_conn.bt_conn_unref: handle 0 ref 3 -> 2
[00:00:21.978,210] <dbg> bt_hci_core.process_events: count 2
[00:00:21.978,240] <dbg> bt_hci_core.process_events: ev->state 4
[00:00:21.978,240] <dbg> bt_hci_core.send_cmd: calling net_buf_get
[00:00:21.978,240] <dbg> bt_hci_core.send_cmd: calling sem_take_wait
[00:00:21.978,240] <dbg> bt_hci_core.send_cmd: Sending command 0x2016 (buf 0x20035dec) to driver
[00:00:21.978,271] <dbg> bt_hci_core.bt_send: buf 0x20035dec len 5 type 0
[00:00:21.978,271] <dbg> bt_ctlr_hci_driver.hci_driver_send: enter
[00:00:21.978,302] <dbg> bt_ctlr_hci_driver.cmd_handle: Replying with event of 6 bytes
[00:00:21.978,302] <dbg> bt_hci_core.hci_cmd_status: opcode 0x2016
[00:00:21.978,332] <dbg> bt_hci_core.hci_cmd_done: opcode 0x2016 status 0x00 buf 0x20035dec
[00:00:21.978,332] <dbg> bt_ctlr_hci_driver.hci_driver_send: exit: 0
[00:00:21.978,363] <dbg> bt_hci_core.process_events: ev->state 1
[00:00:21.978,363] <dbg> bt_conn.bt_conn_prepare_events: 
[00:00:21.978,393] <dbg> bt_conn.conn_prepare_events: Adding conn 0x20002758 to poll list
[00:00:21.978,393] <dbg> bt_hci_core.hci_tx_thread: Calling k_poll with 3 events
[00:00:21.978,424] <dbg> bt_ctlr_hci_driver.recv_thread: blocking
[00:00:21.978,454] <dbg> bt_ctlr_hci_driver.recv_thread: unblocked
[00:00:21.978,454] <dbg> bt_ctlr_hci.le_chan_sel_algo: handle: 0x0000, CSA: 0.
[00:00:21.978,485] <dbg> bt_ctlr_hci_driver.recv_thread: blocking
[00:00:22.042,205] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem taken
[00:00:22.042,205] <dbg> bt_ctlr_hci_driver.prio_recv_thread: RX node enqueue
[00:00:22.042,236] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem take...
[00:00:22.042,236] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem taken
[00:00:22.042,266] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem take...
[00:00:22.042,297] <dbg> bt_ctlr_hci_driver.recv_thread: unblocked
[00:00:22.042,327] <dbg> bt_ctlr_hci_driver.recv_thread: Packet in: type:1 len:14
[00:00:22.042,327] <dbg> bt_hci_core.bt_recv: buf 0x20035cbc len 14
[00:00:22.042,327] <dbg> bt_hci_core.hci_event: event 0x3e
[00:00:22.042,327] <dbg> bt_hci_core.hci_le_meta_event: subevent 0x04
[00:00:22.042,388] <dbg> bt_conn.bt_conn_ref: handle 0 ref 2 -> 3
[00:00:22.042,388] <dbg> bt_hci_core.bt_hci_cmd_create: opcode 0x2032 param_len 7
[00:00:22.042,419] <dbg> bt_hci_core.bt_hci_cmd_create: buf 0x20035dec
[00:00:22.042,419] <dbg> bt_hci_core.bt_hci_cmd_send: opcode 0x2032 len 10
[00:00:22.042,449] <dbg> bt_conn.bt_conn_unref: handle 0 ref 3 -> 2
[00:00:22.042,510] <dbg> bt_hci_core.process_events: count 3
[00:00:22.042,510] <dbg> bt_hci_core.process_events: ev->state 4
[00:00:22.042,510] <dbg> bt_hci_core.send_cmd: calling net_buf_get
[00:00:22.042,541] <dbg> bt_hci_core.send_cmd: calling sem_take_wait
[00:00:22.042,541] <dbg> bt_hci_core.send_cmd: Sending command 0x2032 (buf 0x20035dec) to driver
[00:00:22.042,541] <dbg> bt_hci_core.bt_send: buf 0x20035dec len 10 type 0
[00:00:22.042,572] <dbg> bt_ctlr_hci_driver.hci_driver_send: enter
[00:00:22.042,572] <dbg> bt_ctlr_hci_driver.cmd_handle: Replying with event of 6 bytes
[00:00:22.042,602] <dbg> bt_hci_core.hci_cmd_status: opcode 0x2032
[00:00:22.042,602] <dbg> bt_hci_core.hci_cmd_done: opcode 0x2032 status 0x00 buf 0x20035dec
[00:00:22.042,633] <dbg> bt_ctlr_hci_driver.hci_driver_send: exit: 0
[00:00:22.042,694] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:22.042,694] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:22.042,724] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem taken
[00:00:22.042,724] <dbg> bt_ctlr_hci_driver.prio_recv_thread: RX node enqueue
[00:00:22.042,755] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem take...
[00:00:22.042,785] <dbg> bt_conn.bt_conn_prepare_events: 
[00:00:22.042,785] <dbg> bt_conn.conn_prepare_events: Adding conn 0x20002758 to poll list
[00:00:22.042,785] <dbg> bt_hci_core.hci_tx_thread: Calling k_poll with 3 events
[00:00:22.042,816] <dbg> bt_ctlr_hci_driver.recv_thread: blocking
[00:00:22.042,846] <dbg> bt_ctlr_hci_driver.recv_thread: unblocked
[00:00:22.042,938] <dbg> bt_ctlr_hci_driver.recv_thread: Packet in: type:3 len:11
[00:00:22.042,938] <dbg> bt_hci_core.bt_recv: buf 0x20035cbc len 11
[00:00:22.042,938] <dbg> bt_hci_core.hci_acl: buf 0x20035cbc
[00:00:22.042,968] <dbg> bt_hci_core.hci_acl: handle 0 len 7 flags 2
[00:00:22.042,968] <dbg> bt_conn.bt_conn_ref: handle 0 ref 2 -> 3
[00:00:22.042,968] <dbg> bt_conn.tx_notify: conn 0x20002758
[00:00:22.042,999] <dbg> bt_conn.bt_conn_recv: handle 0 len 7 flags 02
[00:00:22.042,999] <dbg> bt_conn.bt_acl_recv: First, len 7 final 3
[00:00:22.042,999] <dbg> bt_conn.bt_acl_recv: Successfully parsed 7 byte L2CAP packet
[00:00:22.043,029] <dbg> bt_l2cap.bt_l2cap_recv: Packet for CID 4 len 3
[00:00:22.043,029] <dbg> bt_l2cap.l2cap_chan_recv: chan 0x20030810 len 3
[00:00:22.043,029] <dbg> bt_att.bt_att_recv: Received ATT chan 0x20030808 code 0x02 len 2
[00:00:22.043,060] <dbg> bt_att.att_mtu_req: Client MTU 527
[00:00:22.043,060] <dbg> bt_att.att_mtu_req: Server MTU 65
[00:00:22.043,090] <dbg> bt_att.bt_att_chan_send: chan 0x20030808 flags 1 code 0x03
[00:00:22.043,090] <dbg> bt_att.chan_send: code 0x03
[00:00:22.043,121] <dbg> bt_l2cap.bt_l2cap_send_cb: conn 0x20002758 cid 4 len 3
[00:00:22.043,121] <dbg> bt_conn.bt_conn_send_cb: conn handle 0 buf len 7 cb 0x2120d user_data 0x20030810
[00:00:22.043,151] <dbg> bt_att.att_mtu_req: Negotiated MTU 65
[00:00:22.043,182] <dbg> bt_conn.bt_conn_unref: handle 0 ref 3 -> 2
[00:00:22.043,212] <dbg> bt_hci_core.process_events: count 3
[00:00:22.043,212] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:22.043,243] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:22.043,243] <dbg> bt_hci_core.process_events: ev->state 4
[00:00:22.043,243] <dbg> bt_conn.bt_conn_process_tx: conn 0x20002758
[00:00:22.043,273] <dbg> bt_conn.send_buf: conn 0x20002758 buf 0x20035eb0 len 7
[00:00:22.043,273] <dbg> bt_conn.send_frag: conn 0x20002758 buf 0x20035eb0 len 7 flags 0x02
[00:00:22.043,304] <dbg> bt_hci_core.bt_send: buf 0x20035eb0 len 11 type 2
[00:00:22.043,304] <dbg> bt_ctlr_hci_driver.hci_driver_send: enter
[00:00:22.043,334] <dbg> bt_ctlr_hci_driver.hci_driver_send: exit: 0
[00:00:22.043,334] <dbg> bt_conn.bt_conn_prepare_events: 
[00:00:22.043,365] <dbg> bt_conn.conn_prepare_events: Adding conn 0x20002758 to poll list
[00:00:22.043,365] <dbg> bt_hci_core.hci_tx_thread: Calling k_poll with 3 events
[00:00:22.043,395] <dbg> bt_ctlr_hci_driver.recv_thread: blocking
[00:00:22.092,254] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem taken
[00:00:22.092,285] <dbg> bt_ctlr_hci_driver.prio_recv_thread: RX node enqueue
OnSecurityChanged: 1

OnPairingFailed: 4

[00:00:22.092,285] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem take...
[00:00:22.092,315] <dbg> bt_ctlr_hci_driver.recv_thread: unblocked
[00:00:22.092,346] <dbg> bt_ctlr_hci_driver.recv_thread: Packet in: type:3 len:15
[00:00:22.092,346] <dbg> bt_hci_core.bt_recv: buf 0x20035cbc len 15
[00:00:22.092,376] <dbg> bt_hci_core.hci_acl: buf 0x20035cbc
[00:00:22.092,376] <dbg> bt_hci_core.hci_acl: handle 0 len 11 flags 2
[00:00:22.092,376] <dbg> bt_conn.bt_conn_ref: handle 0 ref 2 -> 3
[00:00:22.092,407] <dbg> bt_conn.tx_notify: conn 0x20002758
[00:00:22.092,437] <dbg> bt_conn.bt_conn_recv: handle 0 len 11 flags 02
[00:00:22.092,437] <dbg> bt_conn.bt_acl_recv: First, len 11 final 7
[00:00:22.092,437] <dbg> bt_conn.bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:22.092,468] <dbg> bt_l2cap.bt_l2cap_recv: Packet for CID 6 len 7
[00:00:22.092,468] <dbg> bt_l2cap.l2cap_chan_recv: chan 0x200036d8 len 7
[00:00:22.092,498] <dbg> bt_smp.bt_smp_recv: Received SMP code 0x01 len 6
[00:00:22.092,498] <dbg> bt_smp.smp_pairing_req: 
[00:00:22.092,651] <dbg> bt_keys.bt_keys_get_addr: 00:15:83:FD:58:0E (public)
[00:00:22.092,864] <dbg> bt_keys.bt_keys_get_addr: created 0x2000d130 for 00:15:83:FD:58:0E (public)
[00:00:22.094,360] <dbg> bt_smp.smp_init: prnd 7d3ac30062fd7879458e6b3cc2af38fe
[00:00:22.094,360] <dbg> bt_smp.smp_pairing_complete: status 0x3
[00:00:22.094,512] <dbg> bt_keys.bt_keys_clear: 00:15:83:FD:58:0E (public) (keys 0x0000)
[00:00:22.094,696] <dbg> bt_settings.bt_settings_encode_key: Encoded path bt/keys/001583fd580e0
[00:00:22.094,696] <dbg> bt_keys.bt_keys_clear: Deleting key bt/keys/001583fd580e0
[00:00:22.094,787] <dbg> bt_att.bt_att_encrypt_change: chan 0x20030810 conn 0x20002758 handle 0 sec_level 0x01 status 0x1f
[00:00:22.094,787] <dbg> bt_smp.bt_smp_encrypt_change: chan 0x200036d8 conn 0x20002758 handle 0 encrypt 0x00 hci status 0x1f
[00:00:22.096,893] <dbg> bt_hci_core.bt_hci_cmd_create: opcode 0x0406 param_len 3
[00:00:22.096,893] <dbg> bt_hci_core.bt_hci_cmd_create: buf 0x20035dec
[00:00:22.096,923] <dbg> bt_hci_core.bt_hci_cmd_send_sync: buf 0x20035dec opcode 0x0406 len 6
[00:00:22.096,984] <dbg> bt_hci_core.process_events: count 3
[00:00:22.096,984] <dbg> bt_hci_core.process_events: ev->state 4
[00:00:22.097,015] <dbg> bt_hci_core.send_cmd: calling net_buf_get
[00:00:22.097,015] <dbg> bt_hci_core.send_cmd: calling sem_take_wait
[00:00:22.097,015] <dbg> bt_hci_core.send_cmd: Sending command 0x0406 (buf 0x20035dec) to driver
[00:00:22.097,045] <dbg> bt_hci_core.bt_send: buf 0x20035dec len 6 type 0
[00:00:22.097,045] <dbg> bt_ctlr_hci_driver.hci_driver_send: enter
[00:00:22.097,045] <dbg> bt_ctlr_hci_driver.cmd_handle: Replying with event of 6 bytes
[00:00:22.097,076] <dbg> bt_hci_core.hci_cmd_status: opcode 0x0406
[00:00:22.097,076] <dbg> bt_hci_core.hci_cmd_done: opcode 0x0406 status 0x00 buf 0x20035dec
[00:00:22.097,106] <dbg> bt_ctlr_hci_driver.hci_driver_send: exit: 0
[00:00:22.097,137] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:22.097,137] <dbg> bt_hci_core.process_events: ev->state 0
[00:00:22.097,167] <dbg> bt_conn.bt_conn_prepare_events: 
[00:00:22.097,167] <dbg> bt_conn.conn_prepare_events: Adding conn 0x20002758 to poll list
[00:00:22.097,167] <dbg> bt_hci_core.hci_tx_thread: Calling k_poll with 3 events
[00:00:22.097,229] <dbg> bt_hci_core.bt_hci_cmd_send_sync: rsp 0x20035dec opcode 0x0406 len 0
[00:00:22.097,229] <dbg> bt_conn.bt_conn_set_state: connected -> disconnect
[00:00:22.097,290] <dbg> bt_l2cap.bt_l2cap_send_cb: conn 0x20002758 cid 6 len 2
[00:00:22.097,290] <dbg> bt_conn.bt_conn_send_cb: conn handle 0 buf len 6 cb (nil) user_data (nil)
[00:00:22.097,290] <err> bt_conn: not connected!
[00:00:22.097,320] <dbg> bt_conn.bt_conn_unref: handle 0 ref 3 -> 2
[00:00:22.097,351] <dbg> bt_ctlr_hci_driver.recv_thread: blocking
[00:00:22.142,272] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem taken
[00:00:22.142,303] <dbg> bt_ctlr_hci_driver.prio_recv_thread: Num Complete: 0x0000:1
[00:00:22.142,303] <dbg> bt_hci_core.hci_num_completed_packets: num_handles 1
[00:00:22.142,333] <dbg> bt_hci_core.hci_num_completed_packets: handle 0 count 1
[00:00:22.142,333] <dbg> bt_conn.bt_conn_ref: handle 0 ref 2 -> 3
[00:00:22.142,364] <dbg> bt_conn.bt_conn_unref: handle 0 ref 3 -> 2
[00:00:22.142,395] <dbg> bt_ctlr_hci_driver.prio_recv_thread: RX node enqueue
[00:00:22.142,425] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem take...
[00:00:22.142,456] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem taken
[00:00:22.142,456] <dbg> bt_ctlr_hci_driver.prio_recv_thread: sem take...
[00:00:22.142,517] <dbg> bt_ctlr_hci_driver.recv_thread: unblocked
[00:00:22.142,547] <dbg> bt_ctlr_hci_driver.recv_thread: Packet in: type:3 len:17
[00:00:22.142,547] <dbg> bt_hci_core.bt_recv: buf 0x20035cbc len 17
[00:00:22.142,547] <dbg> bt_hci_core.hci_acl: buf 0x20035cbc
[00:00:22.142,578] <dbg> bt_hci_core.hci_acl: handle 0 len 13 flags 2
[00:00:22.142,578] <dbg> bt_conn.bt_conn_ref: handle 0 ref 2 -> 3
[00:00:22.142,578] <dbg> bt_conn.tx_notify: conn 0x20002758
[00:00:22.142,608] <dbg> bt_conn.tx_notify: tx 0x2000ced8 cb 0x2120d user_data 0x20030810
[00:00:22.142,608] <dbg> bt_att.att_rsp_sent: conn 0x20002758 chan 0x20030808
[00:00:22.142,639] <dbg> bt_att.att_sent: conn 0x20002758 chan 0x20030810
[00:00:22.142,639] <dbg> bt_att.bt_att_sent: chan 0x20030808
[00:00:22.142,700] <dbg> bt_att.chan_rsp_sent: chan 0x20030808
[00:00:22.142,730] <dbg> bt_conn.bt_conn_recv: handle 0 len 13 flags 02
[00:00:22.142,730] <dbg> bt_conn.bt_acl_recv: First, len 13 final 9
[00:00:22.142,730] <dbg> bt_conn.bt_acl_recv: Successfully parsed 13 byte L2CAP packet
[00:00:22.142,761] <dbg> bt_l2cap.bt_l2cap_recv: Packet for CID 4 len 9
[00:00:22.142,761] <dbg> bt_l2cap.l2cap_chan_recv: chan 0x20030810 len 9
[00:00:22.142,791] <dbg> bt_att.bt_att_recv: Received ATT chan 0x20030808 code 0x06 len 8
[00:00:22.142,791] <dbg> bt_att.att_find_type_req: start_handle 0x0001 end_handle 0xffff type 10240
[00:00:22.142,791] <wrn> bt_att: Not connected
[00:00:22.142,822] <dbg> bt_att.bt_att_recv: ATT error 0x0e
[00:00:22.142,852] <dbg> bt_att.bt_att_chan_send: chan 0x20030808 flags 1 code 0x01
[00:00:22.142,852] <dbg> bt_att.chan_send: code 0x01
[00:00:22.142,852] <dbg> bt_l2cap.bt_l2cap_send_cb: conn 0x20002758 cid 4 len 5
[00:00:22.142,883] <dbg> bt_conn.bt_conn_send_cb: conn handle 0 buf len 9 cb 0x2120d user_data 0x20030810
[00:00:22.142,883] <err> bt_conn: not connected!
[00:00:22.142,913] <dbg> bt_conn.bt_conn_unref: handle 0 ref 3 -> 2
[00:00:22.142,944] <dbg> bt_ctlr_hci_driver.recv_thread: blocking
[00:00:22.142,974] <dbg> bt_conn.tx_complete_work: conn 0x20002758
[00:00:22.142,974] <dbg> bt_conn.tx_notify: conn 0x20002758
disconnected

[jefffhaynes]

Sorry, I realize this probably isn't the right place. I'll doublecheck my work and submit a bug for the pairing thing.