BTW: Lukasz did have a really good suggestion for future debugging (why didnt I think of that?) :-)
A sniffer with wireshark is a really handy tool. I mentioned the debugger as it was something we could look at really quickly to see if it is an issue that I already know about with some controllers. And sure enough, I think this is the same issue we have seen before. The data length update procedure is not completing and the connection is timing out. A quick fix for now would be to disable the data length extension feature to see if this addresses the issue. In the syscfg.yml file in net/nimble/controller you should set BLE_LL_CFG_FEAT_DATA_LEN_EXT to 0. This should disable the controller automatically sending the data length update procedure. Hopefully this solves the problem. Will > On Mar 17, 2017, at 9:43 AM, Pritish Gandhi <[email protected]> wrote: > > Hi Will, > Sorry I was mistaken, I jumbled up the issues in my own head. You are > correct in that the blecent is running on the nrf52dk and the logs I > provided are from the blecent application. > > As you requested I put the breakpoint at ble_ll_ctrl_proc_rsp_timer_cb() > please > see the dump below: > > *console logs:* > > 92626:[ts=723640584ssb, mod=64 level=1] Connection established > > 92627:[ts=723648396ssb, mod=4 level=1] GATT procedure initiated: discover > all services > > 92703:[ts=724242172ssb, mod=4 level=1] GATT procedure initiated: discover > all characteristics; start_handle=1 end_handle=11 > > 92748:[ts=724593712ssb, mod=4 level=1] GATT procedure initiated: discover > all characteristics; start_handle=12 end_handle=15 > > 92786:[ts=724890568ssb, mod=4 level=1] GATT procedure initiated: discover > all characteristics; start_handle=16 end_handle=19 > > 92818:[ts=725140616ssb, mod=4 level=1] GATT procedure initiated: discover > all characteristics; start_handle=20 end_handle=32 > > 92863:[ts=725492156ssb, mod=4 level=1] GATT procedure initiated: discover > all characteristics; start_handle=33 end_handle=65535 > > 92927:[ts=725992124ssb, mod=4 level=1] GATT procedure initiated: discover > all descriptors; chr_val_handle=14 end_handle=15 > > 92940:[ts=726093744ssb, mod=4 level=1] GATT procedure initiated: discover > all descriptors; chr_val_handle=18 end_handle=19 > > 92953:[ts=726195300ssb, mod=4 level=1] GATT procedure initiated: discover > all descriptors; chr_val_handle=24 end_handle=25 > > 92978:[ts=726390600ssb, mod=4 level=1] GATT procedure initiated: discover > all descriptors; chr_val_handle=29 end_handle=30 > > 92991:[ts=726492156ssb, mod=4 level=1] GATT procedure initiated: discover > all descriptors; chr_val_handle=37 end_handle=65535 > > 93004:[ts=726593712ssb, mod=64 level=3] Service discovery complete; > status=0 conn_handle=1 > > 93006:[ts=726609336ssb, mod=4 level=1] GATT procedure initiated: read; > att_handle=22 > > 93008:[ts=726624960ssb, mod=4 level=1] GATT procedure initiated: write; > att_handle=32 len=2 > > 93011:[ts=726648396ssb, mod=4 level=1] GATT procedure initiated: write; > att_handle=30 len=2 > > 93036:[ts=726843696ssb, mod=64 level=1] Read complete; status=0 > conn_handle=1 attr_handle=22 value= > > 93042:[ts=726890568ssb, mod=64 level=1] Write complete; status=0 > conn_handle=1 attr_handle=32 > > 93049:[ts=726945252ssb, mod=64 level=1] Subscribe complete; status=0 > conn_handle=1 attr_handle=30 > > *gdb: (took a break point at ble_ll_ctrl_proc_rsp_timer_cb)* > > (gdb) p/x *(struct ble_ll_conn_sm *)ev->ev_arg > > $4 = { > > csmflags = { > > cfbit = { > > pkt_rxd = 0x0, > > terminate_ind_txd = 0x0, > > terminate_ind_rxd = 0x0, > > allow_slave_latency = 0x0, > > slave_set_last_anchor = 0x0, > > awaiting_host_reply = 0x0, > > send_conn_upd_event = 0x0, > > conn_update_sched = 0x0, > > host_expects_upd_event = 0x0, > > version_ind_sent = 0x1, > > rxd_version_ind = 0x1, > > chanmap_update_scheduled = 0x0, > > conn_empty_pdu_txd = 0x0, > > last_txd_md = 0x0, > > conn_req_txd = 0x1, > > send_ltk_req = 0x0, > > encrypted = 0x0, > > encrypt_chg_sent = 0x0, > > le_ping_supp = 0x1 > > }, > > conn_flags = 0x44600 > > }, > > conn_handle = 0x1, > > conn_state = 0x1, > > conn_role = 0x1, > > max_tx_octets = 0x1b, > > max_rx_octets = 0xfb, > > rem_max_tx_octets = 0x1b, > > rem_max_rx_octets = 0x1b, > > eff_max_tx_octets = 0x1b, > > eff_max_rx_octets = 0x1b, > > max_tx_time = 0x148, > > max_rx_time = 0x848, > > rem_max_tx_time = 0x148, > > rem_max_rx_time = 0x148, > > eff_max_tx_time = 0x148, > > eff_max_rx_time = 0x148, > > chanmap = {0xff, 0xff, 0xff, 0xff, 0x1f}, > > req_chanmap = {0x0, 0x0, 0x0, 0x0, 0x0}, > > chanmap_instant = 0x0, > > hop_inc = 0xb, > > data_chan_index = 0x5, > > unmapped_chan = 0x5, > > last_unmapped_chan = 0x1f, > > num_used_chans = 0x25, > > conn_rssi = 0xd0, > > tx_seqnum = 0x1, > > next_exp_seqnum = 0x1, > > cons_rxd_bad_crc = 0x0, > > last_rxd_sn = 0x0, > > last_rxd_hdr_byte = 0x5, > > rpa_index = 0xff, > > reject_reason = 0x0, > > host_reply_opcode = 0x0, > > master_sca = 0x4, > > tx_win_size = 0x1, > > cur_ctrl_proc = 0x8, > > disconnect_reason = 0x0, > > rxd_disconnect_reason = 0x0, > > common_features = 0x0, > > vers_nr = 0x7, > > pending_ctrl_procs = 0x100, > > event_cntr = 0x320, > > completed_pkts = 0x0, > > comp_id = 0xf, > > sub_vers_nr = 0x2209, > > auth_pyld_tmo = 0xbb8, > > access_addr = 0x14258862, > > crcinit = 0x742bf8, > > ce_end_time = 0x2d8b779d, > > terminate_timeout = 0x0, > > last_scheduled = 0x2d8aaaa6, > > conn_itvl_min = 0x18, > > conn_itvl_max = 0x28, > > conn_itvl = 0x28, > > slave_latency = 0x0, > > supervision_tmo = 0x100, > > min_ce_len = 0x10, > > max_ce_len = 0x50, > > tx_win_off = 0x0, > > anchor_point = 0x2d8b6e97, > > last_anchor_point = 0x2b290d01, > > slave_cur_tx_win_usecs = 0x0, > > slave_cur_window_widening = 0x0, > > own_addr_type = 0x0, > > peer_addr_type = 0x0, > > peer_addr = {0xaa, 0xaa, 0xaa, 0xaa, 0xaa, 0xaa}, > > conn_spvn_timer = { > > bsp_timer = 0x20002ee4, > > cb_func = 0x19865, > > cb_arg = 0x20003298, > > expiry = 0x2db1bca8, > > link = { > > tqe_next = 0x0, > > tqe_prev = 0x200036a4 > > } > > }, > > conn_spvn_ev = { > > ev_queued = 0x0, > > ev_cb = 0x1ac05, > > ev_arg = 0x20003298, > > ev_next = { > > stqe_next = 0x0 > > } > > }, > > conn_ev_end = { > > ev_queued = 0x0, > > ev_cb = 0x1a6a5, > > ev_arg = 0x20003298, > > ev_next = { > > stqe_next = 0x0 > > } > > }, > > cur_tx_pdu = 0x0, > > conn_txq = { > > stqh_first = 0x0, > > stqh_last = 0x20003358 > > }, > > { > > act_sle = { > > sle_next = 0x0 > > }, > > free_stqe = { > > stqe_next = 0x0 > > } > > }, > > ctrl_proc_rsp_timer = { > > c_ev = { > > ev_queued = 0x0, > > ev_cb = 0x1c1ed, > > ev_arg = 0x20003298, > > ev_next = { > > stqe_next = 0x0 > > } > > }, > > c_evq = 0x2000313c, > > c_ticks = 0x17dd2, > > c_next = { > > tqe_next = 0x200018e4, > > tqe_prev = 0x0 > > } > > }, > > conn_sch = { > > sched_type = 0x3, > > enqueued = 0x1, > > start_time = 0x2d8b6dd9, > > end_time = 0x2d8b779d, > > cb_arg = 0x20003298, > > sched_cb = 0x19d35, > > link = { > > tqe_next = 0x0, > > tqe_prev = 0x200036ac > > } > > }, > > auth_pyld_timer = { > > c_ev = { > > ev_queued = 0x0, > > ev_cb = 0x1a2d1, > > ev_arg = 0x20003298, > > ev_next = { > > stqe_next = 0x0 > > } > > }, > > c_evq = 0x2000313c, > > c_ticks = 0x0, > > c_next = { > > tqe_next = 0x0, > > tqe_prev = 0x0 > > } > > }, > > enc_data = { > > enc_state = 0x1, > > tx_encrypted = 0x0, > > enc_div = 0x0, > > tx_pkt_cntr = 0x0, > > rx_pkt_cntr = 0x0, > > host_rand_num = 0x0, > > iv = {0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, > > enc_block = { > > key = {0x0 <repeats 16 times>}, > > plain_text = {0x0 <repeats 16 times>}, > > cipher_text = {0x0 <repeats 16 times>} > > } > > }, > > conn_param_req = { > > handle = 0x0, > > conn_itvl_min = 0x0, > > conn_itvl_max = 0x0, > > conn_latency = 0x0, > > supervision_timeout = 0x0, > > min_ce_len = 0x0, > > max_ce_len = 0x0 > > }, > > conn_update_req = { > > winsize = 0x0, > > winoffset = 0x0, > > interval = 0x0, > > latency = 0x0, > > timeout = 0x0, > > instant = 0x0 > > }, > > conn_cp = { > > interval_min = 0x0, > > interval_max = 0x0, > > latency = 0x0, > > timeout = 0x0, > > pref_periodicity = 0x0, > > ref_conn_event_cnt = 0x0, > > offset0 = 0x0, > > offset1 = 0x0, > > offset2 = 0x0, > > offset3 = 0x0, > > offset4 = 0x0, > > offset5 = 0x0 > > } > > } > > > Thanks, > > Pritish > > On Thu, Mar 16, 2017 at 3:22 PM, will sanfilippo <[email protected]> wrote: > >> Maybe I read your email incorrectly, but I thought the error was coming >> from blecent on the nrf52dk? >> >>> On Mar 16, 2017, at 3:11 PM, Pritish Gandhi <[email protected]> >> wrote: >>> >>> Hi Will, >>> I'm not building the controller lib for the image that runs on the >>> stm32f4Discovery board. I'm building it as a Host Only. So I build the >>> host, HCI, and uart transport. Broadcom's Bluetooth core is really a >>> BlackBox to me, I don't have any way to debug what's going on there >> (except >>> maybe using a BLE sniffer and seeing packets going out on the interface) >>> Thanks, >>> Pritish >>> >>> On Thu, Mar 16, 2017 at 2:48 PM, will sanfilippo <[email protected]> >> wrote: >>> >>>> I do not think there is a simple way to debug this. As Chris points out, >>>> the first problem is a LL control procedure timeout. I think I can help >>>> figure some things out there. There is a function called >>>> ble_ll_ctrl_proc_rsp_timer_cb. If you set a breakpoint at this function >> in >>>> the debugger when you get the first error you can examine the connection >>>> state machine. The parameter passed in to that function is an event and >>>> ev->ev_arg is a pointer to the connection state machine. In the >> debugger, >>>> just dump ev_arg after typecasting it to a connection state machine: p/x >>>> (struct ble_ll_conn_sm *)ev->ev_arg >>>> >>>> I presume you are OK with using gdb? I would ‘set print pretty on’ >> before >>>> dumping the connection state machine. If you send me the output of that >> I >>>> might be able to help. >>>> >>>> Thanks >>>> >>>>> On Mar 16, 2017, at 2:30 PM, Christopher Collins <[email protected]> >>>> wrote: >>>>> >>>>> Hi Pritish, >>>>> >>>>> On Thu, Mar 16, 2017 at 01:50:12PM -0700, Pritish Gandhi wrote: >>>>>> Hi All, >>>>>> I'm trying to run blecent on an nrf52dk and am running the bleprph >>>>>> application on another BLE module (stm32f4discovery talking to a >>>> broadcom >>>>>> BLE core). Anyways, when try to run blecent it seems like I >> successfully >>>>>> connect to the peripheral and are able to discover it, however after >>>> that >>>>>> the connection seems to be timing out and then am never able to >> discover >>>>>> the peripheral again. >>>>> >>>>> [...] >>>>> >>>>> Hmm, that is odd, indeed. The disconnect reason codes you are seeing >>>>> are mapped as follows: >>>>> >>>>> 546 - LMP RESPONSE TIMEOUT / LL RESPONSE TIMEOUT >>>>> 520 - CONNECTION TIMEOUT >>>>> >>>>> I'm afraid I don't have any ideas at the moment. Could you please >>>>> clarify the setup you are using? Here is my understanding: >>>>> >>>>> Device A: blecent on nRF52dk (combined host-controller) >>>>> Device B: >>>>> * bleprph on stm32f4discovery (host-only) >>>>> * broadcom controller >>>>> >>>>> Is that correct? If so, I assume the host and controller on device B >>>>> communicate via UART? >>>>> >>>>> Thanks, >>>>> Chris >>>>> >>>>>> >>>>>> 1) Connected and Discovered the bleprph: >>>>>> >>>>>> 37493:[ts=292914004ssb, mod=4 level=1] GAP procedure initiated: >>>> discovery; >>>>>> own_addr_type=0 filter_policy=0 passive=1 limited=0 >> filter_duplicates=1 >>>>>> duration=forever >>>>>> >>>>>> 37503:[ts=292992124ssb, mod=4 level=1] GAP procedure initiated: >> connect; >>>>>> peer_addr_type=0 peer_addr=aa:aa:aa:aa:aa:aa scan_itvl=16 >> scan_window=16 >>>>>> itvl_min=24 itvl_max=40 latency=0 supervision_timeout=256 >> min_ce_len=16 >>>>>> max_ce_len=768 own_addr_ty >>>>>> >>>>>> 37517:[ts=293101556ssb, mod=64 level=1] Connection established >>>>>> >>>>>> 37519:[ts=293117180ssb, mod=4 level=1] GATT procedure initiated: >>>> discover >>>>>> all services >>>>>> >>>>>> 37588:[ts=293656208ssb, mod=4 level=1] GATT procedure initiated: >>>> discover >>>>>> all characteristics; start_handle=1 end_handle=11 >>>>>> >>>>>> 37627:[ts=293960876ssb, mod=4 level=1] GATT procedure initiated: >>>> discover >>>>>> all characteristics; start_handle=12 end_handle=15 >>>>>> >>>>>> 37658:[ts=294203112ssb, mod=4 level=1] GATT procedure initiated: >>>> discover >>>>>> all characteristics; start_handle=16 end_handle=19 >>>>>> >>>>>> 37684:[ts=294406224ssb, mod=4 level=1] GATT procedure initiated: >>>> discover >>>>>> all characteristics; start_handle=20 end_handle=32 >>>>>> >>>>>> 37722:[ts=294703080ssb, mod=4 level=1] GATT procedure initiated: >>>> discover >>>>>> all characteristics; start_handle=33 end_handle=65535 >>>>>> >>>>>> 37761:[ts=295007812ssb, mod=4 level=1] GATT procedure initiated: >>>> discover >>>>>> all descriptors; chr_val_handle=14 end_handle=15 >>>>>> >>>>>> 37774:[ts=295109368ssb, mod=4 level=1] GATT procedure initiated: >>>> discover >>>>>> all descriptors; chr_val_handle=18 end_handle=19 >>>>>> >>>>>> 37786:[ts=295203112ssb, mod=4 level=1] GATT procedure initiated: >>>> discover >>>>>> all descriptors; chr_val_handle=24 end_handle=25 >>>>>> >>>>>> 37799:[ts=295304668ssb, mod=4 level=1] GATT procedure initiated: >>>> discover >>>>>> all descriptors; chr_val_handle=29 end_handle=30 >>>>>> >>>>>> 37812:[ts=295406224ssb, mod=4 level=1] GATT procedure initiated: >>>> discover >>>>>> all descriptors; chr_val_handle=37 end_handle=65535 >>>>>> >>>>>> 37825:[ts=295507780ssb, mod=64 level=3] Service discovery complete; >>>>>> status=0 conn_handle=1 >>>>>> >>>>>> 2) Read/Write/Subscribe for notifications. Finally fails with >> reason=546 >>>>>> >>>>>> 37827:[ts=295523404ssb, mod=4 level=1] GATT procedure initiated: read; >>>>>> att_handle=22 >>>>>> >>>>>> 37829:[ts=295539028ssb, mod=4 level=1] GATT procedure initiated: >> write; >>>>>> att_handle=32 len=2 >>>>>> >>>>>> 37832:[ts=295562464ssb, mod=4 level=1] GATT procedure initiated: >> write; >>>>>> att_handle=30 len=2 >>>>>> >>>>>> 37851:[ts=295710892ssb, mod=64 level=1] Read complete; status=0 >>>>>> conn_handle=1 attr_handle=22 value= >>>>>> >>>>>> 37857:[ts=295757764ssb, mod=64 level=1] Write complete; status=0 >>>>>> conn_handle=1 attr_handle=32 >>>>>> >>>>>> 37863:[ts=295804636ssb, mod=64 level=1] Subscribe complete; status=0 >>>>>> conn_handle=1 attr_handle=30 >>>>>> >>>>>> 42637:[ts=333101556ssb, mod=64 level=1] disconnect; reason=546 >>>>>> >>>>>> >>>>>> 3) Once it disconnects, blecent gets stuck in this loop of trying to >>>>>> discover, but the discovery always fails: >>>>>> >>>>>> 42638:[ts=333109368ssb, mod=4 level=1] GAP procedure initiated: >>>> discovery; >>>>>> own_addr_type=0 filter_policy=0 passive=1 limited=0 >> filter_duplicates=1 >>>>>> duration=forever >>>>>> >>>>>> 42973:[ts=335726516ssb, mod=4 level=1] GAP procedure initiated: >> connect; >>>>>> peer_addr_type=0 peer_addr=aa:aa:aa:aa:aa:aa scan_itvl=16 >> scan_window=16 >>>>>> itvl_min=24 itvl_max=40 latency=0 supervision_timeout=256 >> min_ce_len=16 >>>>>> max_ce_len=768 own_addr_ty >>>>>> >>>>>> 42982:[ts=335796824ssb, mod=64 level=1] Connection established >>>>>> >>>>>> 42983:[ts=335804636ssb, mod=4 level=1] GATT procedure initiated: >>>> discover >>>>>> all services >>>>>> >>>>>> 43020:[ts=336093744ssb, mod=64 level=3] Error: Service discovery >> failed; >>>>>> status=7 conn_handle=1 >>>>>> >>>>>> 43022:[ts=336109368ssb, mod=4 level=1] GAP procedure initiated: >>>> terminate >>>>>> connection; conn_handle=1 hci_reason=19 >>>>>> >>>>>> 43025:[ts=336132804ssb, mod=64 level=1] disconnect; reason=520 >>>>>> >>>>>> 43027:[ts=336148428ssb, mod=4 level=1] GAP procedure initiated: >>>> discovery; >>>>>> own_addr_type=0 filter_policy=0 passive=1 limited=0 >> filter_duplicates=1 >>>>>> duration=forever >>>>>> >>>>>> 43038:[ts=336234360ssb, mod=4 level=1] GAP procedure initiated: >> connect; >>>>>> peer_addr_type=0 peer_addr=aa:aa:aa:aa:aa:aa scan_itvl=16 >> scan_window=16 >>>>>> itvl_min=24 itvl_max=40 latency=0 supervision_timeout=256 >> min_ce_len=16 >>>>>> max_ce_len=768 own_addr_ty >>>>>> >>>>>> 43046:[ts=336296856ssb, mod=64 level=1] Connection established >>>>>> >>>>>> 43047:[ts=336304668ssb, mod=4 level=1] GATT procedure initiated: >>>> discover >>>>>> all services >>>>>> >>>>>> 43084:[ts=336593712ssb, mod=64 level=3] Error: Service discovery >> failed; >>>>>> status=7 conn_handle=1 >>>>>> >>>>>> 43086:[ts=336609336ssb, mod=4 level=1] GAP procedure initiated: >>>> terminate >>>>>> connection; conn_handle=1 hci_reason=19 >>>>>> >>>>>> 43089:[ts=336632772ssb, mod=64 level=1] disconnect; reason=520 >>>>>> >>>>>> 43091:[ts=336648396ssb, mod=4 level=1] GAP procedure initiated: >>>> discovery; >>>>>> own_addr_type=0 filter_policy=0 passive=1 limited=0 >> filter_duplicates=1 >>>>>> duration=forever >>>>>> >>>>>> 43101:[ts=336726516ssb, mod=4 level=1] GAP procedure initiated: >> connect; >>>>>> peer_addr_type=0 peer_addr=aa:aa:aa:aa:aa:aa scan_itvl=16 >> scan_window=16 >>>>>> itvl_min=24 itvl_max=40 latency=0 supervision_timeout=256 >> min_ce_len=16 >>>>>> max_ce_len=768 own_addr_ty >>>>>> >>>>>> Any ideas whats going on and how to debug this further? >>>>>> The only way to recover seems to be to reset my bleprph device. >>>>>> Appreciate the help, >>>>>> Pritish >>>> >>>> >> >>
