I do not think this is really an answer but it is the best I can do without more information.
When a device initially “connects” the state of the connection is not considered established until a data frame is received from the other device in the connection. The initial supervision timeout is 6 connection intervals and is not based on the supervision timeout. That is why you see the disconnect in 6 connection intervals. So either the connect request from the master to the peripheral was not received by the peripheral or it was received but no further data packets were transferred and that is why the connection dropped. What version of code are you using? When I did the anchor point/last rxd cputime math I see the difference between the two is 301889. This implies to me that cputime is counting at 1 MHz and not at 32.768kHz. Which also implies that you are not using the latest code. NOTE: I would expect this to happen occasionally, and more occasionally if there are alot of devices transmitting in close proximity or if the two devices connecting dont have a great RF link. > On Sep 4, 2017, at 5:50 PM, Simon Ratner <[email protected]> wrote: > > Hi devs, > > I am tracking a nimble issue (on nrf52) that seems to surface > intermittently - a supervision timeout when i am not expecting one. Below > is a section of the log, nimble is the master here and as you can see, the > time between connection being established and the tmo error is ~260ms: > > 007734 [ts=60421848ssb, mod=4 level=1] GAP procedure initiated: connect; > peer_addr_type=1 peer_addr=73:a0:1a:2e:b1:df scan_itvl=16 scan_window=16 > itvl_min=24 itvl_max=40 latency=1 supervision_timeout=512 min_ce_len=16 > max_ce_len=768 own_addr_ty > 007760 [ts=60624960ssb, mod=64 level=1] peer: connected; conn_handle=14 > status=0 addr=73:a0:1a:2e:b1:df > 007763 [ts=60648396ssb, mod=4 level=1] GATT procedure initiated: exchange > mtu > 007765 [ts=60664020ssb, mod=4 level=1] GATT procedure initiated: discover > service by uuid; uuid=.. > 007793 *** ble_ll_conn.c:2160 *** cputime=61336489 anchor_point=61386140 > last_rxd_pdu_cputime=61084251 tmo=300000 > 007795 [ts=60898380ssb, mod=64 level=1] peer: updated; conn_handle=14 > status=520 itvl=40 latency=1 tmo=512 > 007800 [ts=60937440ssb, mod=64 level=1] peer: disconnected; conn_handle=14 > reason=520 > > > The line marked with *** is in `ble_ll_conn_event_end`, just before it > reports `BLE_ERR_CONN_SPVN_TMO`. The time of last PDU seems to match the > time when I see the "connected" host event (line #7760), and the anchor > point is presumably the time of the next scheduled conn event. What I > thought was interesting is that the tmo value is 300ms, i.e. > conn_itvl(50ms) * 6 rather than the supervision timeout. The connection sm > is in `BLE_LL_CONN_STATE_CREATED` state, and not > `BLE_LL_CONN_STATE_ESTABLISHED` as I would've expected, having already > received the "connected" event from the host. > > Any ideas what could be going on here? > > cheers, > simon
