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
> >>
> >>
>
>
