• State Verified Answer
  • Replies 5 replies
  • Subscribers 74 subscribers
  • Views 1262 views
  • Users 0 members are here
Attachments (1) Download All
Nordic Case Info
  • Case ID: 305486
Options

ATT Timeout

DSmartboxAT

Hi,

I've been trying to find the cause of this ATT timeout for quite a few days, and my brain is toasted to a crisp now.

do you have any useful suggestions on how to debug?

I can share full source code in private, it runs on a NRF52840DK

Fullscreen 6646.message.txt Download 
[00:00:24.556,854] <dbg> eriskay_bluetooth: eir_found_cb: BT_DATA_UUID128_ALL
[00:00:24.556,915] <dbg> eriskay_bluetooth: rpb2_user_pairing_stop: rpb2_user_pairing_stop
[00:00:24.556,915] <dbg> eriskay_bluetooth: rpb2_user_pairing_stop: user-initiated pairing stopped or timed-out
[00:00:24.557,220] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:24.557,281] <dbg> eriskay_bluetooth: rpb2_pairing_blink_stop_cb: rpb2_pairing_blink_stop_cb
[00:00:24.557,312] <dbg> eriskay_led: led_update: led_update
[00:00:24.558,227] <dbg> bt_conn: bt_conn_set_state: disconnected -> connecting
[00:00:24.558,227] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
[00:00:24.558,441] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:24.558,837] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:24.558,898] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:24.558,898] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:24.558,929] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:24.599,517] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:24.599,548] <dbg> bt_conn: bt_conn_set_state: connecting -> connected
[00:00:24.599,609] <dbg> bt_att: bt_att_accept: conn 0x20004e80 handle 0
[00:00:24.599,639] <dbg> bt_att: att_chan_attach: att 0x20013bc0 chan 0x20011bc0 flags 0
[00:00:24.599,639] <dbg> bt_att: bt_att_connected: chan 0x20011bc4 cid 0x0004
[00:00:24.599,670] <dbg> bt_gatt: bt_gatt_connected: conn 0x20004e80
[00:00:24.599,731] <dbg> bt_att: bt_att_status: chan 0x20011bc4 status 0x20011bd4
[00:00:24.599,761] <dbg> eriskay_bluetooth: connected_cb: connected_cb
[00:00:24.599,945] <inf> eriskay_bluetooth: connected_cb: Connected to RPB2: 00:A0:50:E1:E0:19 (public)
[00:00:24.599,975] <dbg> eriskay_bluetooth: rpb2_auth: rpb2_auth
[00:00:24.599,975] <dbg> eriskay_bluetooth: rpb2_auth: RPB2 auth payload 70
[00:00:24.600,006] <dbg> bt_gatt: bt_gatt_write: handle 0x0012 length 1
[00:00:24.600,006] <dbg> bt_att: bt_att_req_alloc: req 0x20013c24
[00:00:24.600,067] <dbg> bt_att: bt_att_req_send: conn 0x20004e80 req 0x20013c24
[00:00:24.600,067] <dbg> bt_att: bt_att_chan_req_send: req 0x20013c24
[00:00:24.600,097] <dbg> bt_att: chan_req_send: chan 0x20011bc0 req 0x20013c24 len 4
[00:00:24.600,097] <dbg> bt_att: bt_att_chan_send: chan 0x20011bc0 flags 4 code 0x12
[00:00:24.600,128] <dbg> bt_att: chan_send: code 0x12
[00:00:24.600,128] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 8 cb 0x68fd5 user_data 0x2000710c
[00:00:24.600,433] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:24.600,463] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004e80 to poll list
[00:00:24.600,494] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004e80
[00:00:24.600,494] <dbg> bt_conn: send_buf: conn 0x20004e80 buf 0x20013b78 len 8
[00:00:24.600,524] <dbg> bt_conn: send_frag: conn 0x20004e80 buf 0x20013b78 len 8 flags 0x02
[00:00:24.600,616] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:24.600,616] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004e80 to poll list
[00:00:24.600,982] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:24.600,982] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004e80 to poll list
[00:00:24.601,043] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:24.601,043] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:24.601,074] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:24.601,104] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:24.601,104] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:24.801,177] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:24.801,239] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:24.801,391] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:24.801,391] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:24.801,452] <dbg> bt_conn: tx_complete_work: conn 0x20004e80
[00:00:24.801,452] <dbg> bt_conn: tx_notify: conn 0x20004e80
[00:00:24.801,483] <dbg> bt_conn: tx_notify: tx 0x20007040 cb 0x68fd5 user_data 0x2000710c
[00:00:24.801,513] <dbg> bt_att: att_sent: conn 0x20004e80 chan 0x20011bc4
[00:00:24.801,513] <dbg> bt_att: bt_att_sent: chan 0x20011bc0
[00:00:24.801,544] <dbg> bt_att: chan_req_sent: chan 0x20011bc0 chan->req 0x20013c24
[00:00:24.901,153] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:24.901,184] <dbg> bt_conn: tx_notify: conn 0x20004e80
[00:00:24.901,184] <dbg> bt_conn: bt_conn_recv: handle 0 len 5 flags 02
[00:00:24.901,214] <dbg> bt_conn: bt_acl_recv: First, len 5 final 1
[00:00:24.901,214] <dbg> bt_conn: bt_acl_recv: Successfully parsed 5 byte L2CAP packet
[00:00:24.901,245] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20011bc0 code 0x13 len 0
[00:00:24.901,275] <dbg> bt_att: att_handle_write_rsp: 
[00:00:24.901,306] <dbg> bt_att: att_handle_rsp: chan 0x20011bc0 err 0x00 len 0: 
[00:00:24.901,336] <dbg> bt_att: bt_att_req_free: req 0x20013c24
[00:00:24.901,336] <dbg> bt_gatt: gatt_write_rsp: err 0x00
[00:00:24.901,367] <dbg> eriskay_bluetooth: on_rpb2_auth_write_cb: on_rpb2_auth_write_cb
[00:00:24.901,855] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 11 cb (nil) user_data (nil)
[00:00:24.901,947] <dbg> bt_gatt: gatt_write_ccc: handle 0x0013 value 0x0001
[00:00:24.901,947] <dbg> bt_att: bt_att_req_alloc: req 0x20013c24
[00:00:24.902,008] <dbg> bt_att: bt_att_req_send: conn 0x20004e80 req 0x20013c24
[00:00:24.902,038] <dbg> bt_att: bt_att_chan_req_send: req 0x20013c24
[00:00:24.902,038] <dbg> bt_att: chan_req_send: chan 0x20011bc0 req 0x20013c24 len 5
[00:00:24.902,069] <dbg> bt_att: bt_att_chan_send: chan 0x20011bc0 flags 4 code 0x12
[00:00:24.902,099] <dbg> bt_att: chan_send: code 0x12
[00:00:24.902,099] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0x68fd5 user_data 0x20007120
[00:00:24.902,130] <inf> eriskay_bluetooth: on_rpb2_auth_write_cb: Subscribed to RPB2
[00:00:24.902,160] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:24.902,191] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004e80
[00:00:24.902,221] <dbg> bt_conn: send_buf: conn 0x20004e80 buf 0x20013b78 len 11
[00:00:24.902,221] <dbg> bt_conn: send_frag: conn 0x20004e80 buf 0x20013b78 len 11 flags 0x02
[00:00:24.902,282] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:24.902,313] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004e80 to poll list
[00:00:24.902,343] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004e80
[00:00:24.902,343] <dbg> bt_conn: send_buf: conn 0x20004e80 buf 0x20013b90 len 9
[00:00:24.902,374] <dbg> bt_conn: send_frag: conn 0x20004e80 buf 0x20013b90 len 9 flags 0x02
[00:00:24.902,404] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:24.902,435] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004e80 to poll list
[00:00:25.001,159] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:25.001,190] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:25.001,342] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:25.001,373] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:25.101,196] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:25.101,226] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:25.101,379] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:25.101,409] <dbg> bt_conn: tx_notify: conn 0x20004e80
[00:00:25.101,409] <dbg> bt_conn: tx_notify: tx 0x20007050 cb 0x68fd5 user_data 0x20007120
[00:00:25.101,440] <dbg> bt_att: att_sent: conn 0x20004e80 chan 0x20011bc4
[00:00:25.101,470] <dbg> bt_att: bt_att_sent: chan 0x20011bc0
[00:00:25.101,470] <dbg> bt_att: chan_req_sent: chan 0x20011bc0 chan->req 0x20013c24
[00:00:25.101,501] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
[00:00:25.101,531] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:00:25.101,531] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:25.101,654] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 21 cb (nil) user_data (nil)
[00:00:25.101,715] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:25.101,745] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004e80
[00:00:25.101,745] <dbg> bt_conn: send_buf: conn 0x20004e80 buf 0x20013b90 len 21
[00:00:25.101,776] <dbg> bt_conn: send_frag: conn 0x20004e80 buf 0x20013b90 len 21 flags 0x02
[00:00:25.101,806] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:25.101,837] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004e80 to poll list
[00:00:25.101,898] <dbg> bt_conn: tx_complete_work: conn 0x20004e80
[00:00:25.101,898] <dbg> bt_conn: tx_notify: conn 0x20004e80
[00:00:25.201,324] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:25.201,354] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:25.201,507] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:25.201,507] <dbg> bt_conn: tx_notify: conn 0x20004e80
[00:00:25.201,538] <dbg> bt_conn: bt_conn_recv: handle 0 len 16 flags 02
[00:00:25.201,538] <dbg> bt_conn: bt_acl_recv: First, len 16 final 12
[00:00:25.201,568] <dbg> bt_conn: bt_acl_recv: Successfully parsed 16 byte L2CAP packet
[00:00:25.201,599] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 10 cb (nil) user_data (nil)
[00:00:25.201,721] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004e80
[00:00:25.201,721] <dbg> bt_conn: send_buf: conn 0x20004e80 buf 0x20013b90 len 10
[00:00:25.201,751] <dbg> bt_conn: send_frag: conn 0x20004e80 buf 0x20013b90 len 10 flags 0x02
[00:00:25.201,873] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:25.201,904] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004e80 to poll list
[00:00:25.201,965] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:25.301,300] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:25.301,330] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:25.301,483] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:25.301,513] <dbg> bt_conn: tx_notify: conn 0x20004e80
[00:00:25.301,513] <dbg> bt_conn: bt_conn_recv: handle 0 len 21 flags 02
[00:00:25.301,544] <dbg> bt_conn: bt_acl_recv: First, len 21 final 17
[00:00:25.301,544] <dbg> bt_conn: bt_acl_recv: Successfully parsed 21 byte L2CAP packet
[00:00:25.301,635] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 21 cb (nil) user_data (nil)
[00:00:25.301,666] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:25.301,696] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004e80
[00:00:25.301,727] <dbg> bt_conn: send_buf: conn 0x20004e80 buf 0x20013b90 len 21
[00:00:25.301,727] <dbg> bt_conn: send_frag: conn 0x20004e80 buf 0x20013b90 len 21 flags 0x02
[00:00:25.301,788] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:25.301,818] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004e80 to poll list
[00:00:25.501,190] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:25.501,220] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:25.701,293] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:25.701,293] <dbg> bt_conn: tx_notify: conn 0x20004e80
[00:00:25.701,324] <dbg> bt_conn: bt_conn_recv: handle 0 len 21 flags 02
[00:00:25.701,324] <dbg> bt_conn: bt_acl_recv: First, len 21 final 17
[00:00:25.701,354] <dbg> bt_conn: bt_acl_recv: Successfully parsed 21 byte L2CAP packet
[00:00:25.701,660] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:25.701,660] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004e80 to poll list
[00:00:25.701,721] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:26.901,123] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:26.901,153] <dbg> eriskay_bluetooth: le_param_updated: le_param_updated
[00:00:26.901,367] <inf> eriskay_bluetooth: le_param_updated: LE param updated 00:A0:50:E1:E0:19 (public): interval 48 latency 0 timeout 200
[00:00:26.901,397] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:27.301,147] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:27.301,361] <dbg> bt_att: bt_att_encrypt_change: chan 0x20011bc4 conn 0x20004e80 handle 0 sec_level 0x02 status 0x00
[00:00:27.301,361] <dbg> bt_gatt: bt_gatt_encrypt_change: conn 0x20004e80
[00:00:27.301,422] <dbg> eriskay_bluetooth: security_changed_cb: security_changed_cb
[00:00:27.301,605] <inf> eriskay_bluetooth: security_changed_cb: Security changed: 00:A0:50:E1:E0:19 (public) level 2
[00:00:27.301,635] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:27.421,264] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:27.421,295] <dbg> bt_conn: tx_notify: conn 0x20004e80
[00:00:27.421,295] <dbg> bt_conn: bt_conn_recv: handle 0 len 21 flags 02
[00:00:27.421,325] <dbg> bt_conn: bt_acl_recv: First, len 21 final 17
[00:00:27.421,325] <dbg> bt_conn: bt_acl_recv: Successfully parsed 21 byte L2CAP packet
[00:00:27.421,386] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:27.421,905] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:27.421,936] <dbg> bt_conn: tx_notify: conn 0x20004e80
[00:00:27.421,936] <dbg> bt_conn: bt_conn_recv: handle 0 len 15 flags 02
[00:00:27.421,966] <dbg> bt_conn: bt_acl_recv: First, len 15 final 11
[00:00:27.421,966] <dbg> bt_conn: bt_acl_recv: Successfully parsed 15 byte L2CAP packet
[00:00:27.422,027] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:27.422,546] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:27.422,546] <dbg> bt_conn: tx_notify: conn 0x20004e80
[00:00:27.422,576] <dbg> bt_conn: bt_conn_recv: handle 0 len 21 flags 02
[00:00:27.422,576] <dbg> bt_conn: bt_acl_recv: First, len 21 final 17
[00:00:27.422,607] <dbg> bt_conn: bt_acl_recv: Successfully parsed 21 byte L2CAP packet
[00:00:27.422,637] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:27.423,156] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:27.423,187] <dbg> bt_conn: tx_notify: conn 0x20004e80
[00:00:27.423,217] <dbg> bt_conn: bt_conn_recv: handle 0 len 12 flags 02
[00:00:27.423,217] <dbg> bt_conn: bt_acl_recv: First, len 12 final 8
[00:00:27.423,248] <dbg> bt_conn: bt_acl_recv: Successfully parsed 12 byte L2CAP packet
[00:00:27.424,041] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 21 cb (nil) user_data (nil)
[00:00:27.424,133] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 15 cb 0x6ae2b user_data (nil)
[00:00:27.424,194] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:27.424,255] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004e80
[00:00:27.424,255] <dbg> bt_conn: send_buf: conn 0x20004e80 buf 0x20013b90 len 21
[00:00:27.424,285] <dbg> bt_conn: send_frag: conn 0x20004e80 buf 0x20013b90 len 21 flags 0x02
[00:00:27.424,346] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:27.424,346] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004e80 to poll list
[00:00:27.424,377] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004e80
[00:00:27.424,407] <dbg> bt_conn: send_buf: conn 0x20004e80 buf 0x20013b78 len 15
[00:00:27.424,407] <dbg> bt_conn: send_frag: conn 0x20004e80 buf 0x20013b78 len 15 flags 0x02
[00:00:27.424,468] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:27.424,499] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004e80 to poll list
[00:00:27.481,140] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:27.481,170] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:27.481,842] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:27.481,872] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:27.481,964] <dbg> bt_conn: tx_complete_work: conn 0x20004e80
[00:00:27.481,964] <dbg> bt_conn: tx_notify: conn 0x20004e80
[00:00:27.481,994] <dbg> bt_conn: tx_notify: tx 0x20007060 cb 0x6ae2b user_data (nil)
[00:00:27.487,274] <dbg> eriskay_bluetooth: auth_pairing_complete_cb: auth_pairing_complete_cb
[00:00:27.487,487] <inf> eriskay_bluetooth: auth_pairing_complete_cb: Bonded with RPB2 00:A0:50:E1:E0:19 (public)
[00:00:40.771,636] <dbg> eriskay_bluetooth: rpb2_user_pairing_timeout_cb: rpb2_user_pairing_timeout_cb
[00:00:40.771,697] <dbg> eriskay_bluetooth: rpb2_user_pairing_stop_work_handler: rpb2_user_pairing_stop_work_handler
[00:00:40.771,728] <dbg> eriskay_bluetooth: rpb2_user_pairing_stop: rpb2_user_pairing_stop
[00:00:40.771,728] <dbg> eriskay_bluetooth: rpb2_user_pairing_stop: user-initiated pairing stopped or timed-out
[00:00:55.101,562] <err> bt_att: att_timeout: ATT Timeout
[00:00:55.101,593] <dbg> bt_att: bt_att_disconnected: chan 0x20011bc4 cid 0x0004
[00:00:55.101,623] <dbg> bt_att: att_chan_detach: chan 0x20011bc0
[00:00:55.101,654] <dbg> bt_att: att_handle_rsp: chan 0x20011bc0 err 0x0e len 0: 
[00:00:55.101,684] <dbg> bt_att: bt_att_req_free: req 0x20013c24
[00:00:55.101,684] <dbg> bt_gatt: gatt_write_ccc_rsp: err 0x0e
[00:00:55.101,715] <inf> eriskay_bluetooth: notify_cb: Unsubscribed from RPB2
[00:00:55.101,745] <dbg> bt_gatt: bt_gatt_disconnected: conn 0x20004e80
[00:00:55.102,203] <dbg> bt_gatt: bt_gatt_store_ccc: Stored CCCs for 00:A0:50:E1:E0:19 (public) (bt/ccc/00a050e1e0190)
[00:00:55.102,233] <dbg> bt_gatt: bt_gatt_store_ccc:   CCC: NULL
[00:00:55.102,233] <dbg> bt_gatt: bt_gatt_store_cf: No config for CF
[00:00:55.102,661] <dbg> bt_gatt: bt_gatt_store_cf: Stored CF for 00:A0:50:E1:E0:19 (public) (bt/cf/00a050e1e0190)

Parents
  • 0

    To give you some context, the NRF52840 IC is trying to connect with another bluetooth device (A remote with a custom BT service), writes to a characteristic to do a custom authentication protocol, changes security to L2, subscribes to a characteristic, then received a notification.

    it seems something goes wrong around the subscription, which triggers the ATT timeout and disconnection after 30 seconds (even if the other device is not as fussy and will happily continue sending notifications).

    I'm in NRF SDK V2.2

    I've tried switching all code that interact with the bluetooth to use a custom workqueue, since i've read there are some issues associated with calling the BT stack from the system workqueue that can cause this ATT timeout and are not fixed yet, but to no avail.

  • 0 in reply to DSmartboxAT

    Have a feeling that this is related to [00:00:40.771,728] <dbg> eriskay_bluetooth: rpb2_user_pairing_stop: user-initiated pairing stopped or timed-out

    Where (which context) are you trying to change the security? Is it possible that there was some handling expected in the callback which was not handled?
    Have you implemented all the security callbacks in your application?

Reply Children
  • 0 in reply to Susheel Nuguru

    The call to bt_conn_set_security() is within the callback of bt_gatt_write().

    after bt_conn_set_security() (also inside within the callback of bt_gatt_write()) I call bt_gatt_subscribe()

    bt_gatt_write() is called by the connected callback.

    This should answer the question regarding the context.

    ---

    The only security callback I have is the security_changed cb, is there anything else I should implement?

    ---

    From the uploaded log (the timing, 30sec or so before the error), as well as trying shuffling stuff around, it seems the culprit is somewhere here:

    static void on_rpb2_auth_write_cb(struct bt_conn *conn, uint8_t err,
				  struct bt_gatt_write_params *params)
{
	LOG_DBG("%s", __func__);

	int ret = bt_conn_set_security(conn, BT_SECURITY_L2);
	if (ret) {
		LOG_ERR("Failed to set security level, err (%d)", ret);
	}

	subscribe_params.notify = notify_cb;
	subscribe_params.value = BT_GATT_CCC_NOTIFY;
	subscribe_params.value_handle = RBP2_BUTTON_SERVICE_BUTTON_CHARACTERISTIC_CHAR_HANDLE;
	subscribe_params.ccc_handle =
		RBP2_BUTTON_SERVICE_BUTTON_CHARACTERISTIC_CLIENT_CHARACTERISTIC_CONFIGURATION_DESC_HANDLE;

	err = bt_gatt_subscribe(conn, &subscribe_params);
	if (err && err != -EALREADY) {
		LOG_ERR("Subscribe failed (err %d)", err);
	} else {
		LOG_INF("Subscribed to RPB2");
	}
}

    Note this is called by the write cb because the periferial has a weird authentication procedure, where you have to write a value on an unencrypted characteristic before being able to upgrade the security to L2. 

    Al I doing something wrong in the code above? 

Related
Terms of service