On 6/17/14 4:04 PM, Lukasz Rymanowski wrote: > When pairing fails hci_conn refcnt drops below zero. This cause that > ACL link is not disconnected when disconnect timeout fires. > > Probably this is because l2cap_conn_del calls l2cap_chan_del for each > channel, and inside l2cap_chan_del conn is dropped. After that loop > hci_chan_del is called which also drops conn. > > Anyway, as it is desrcibed in hci_core.h, it is known that refcnt > drops below 0 sometimes and it should be fine. If so, let disconnect > link when hci_conn_timeout fires and refcnt is 0 or below. This patch > does it. > > This affects PTS test SM_TC_JW_BV_05_C > > Logs from scenario: > > [69713.706227] [6515] pair_device: > [69713.706230] [6515] hci_conn_add: hci0 dst 00:1b:dc:06:06:22 > [69713.706233] [6515] hci_dev_hold: hci0 orig refcnt 8 > [69713.706235] [6515] hci_conn_init_sysfs: conn ffff88021f65a000 > [69713.706239] [6515] hci_req_add_ev: hci0 opcode 0x200d plen 25 > [69713.706242] [6515] hci_prepare_cmd: skb len 28 > [69713.706243] [6515] hci_req_run: length 1 > [69713.706248] [6515] hci_conn_hold: hcon ffff88021f65a000 orig refcnt 0 > [69713.706251] [6515] hci_dev_put: hci0 orig refcnt 9 > [69713.706281] [8909] hci_cmd_work: hci0 cmd_cnt 1 cmd queued 1 > [69713.706288] [8909] hci_send_frame: hci0 type 1 len 28 > [69713.706290] [8909] hci_send_to_monitor: hdev ffff88021f0c7000 len 28 > [69713.706316] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69713.706382] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69713.711664] [8909] hci_rx_work: hci0 > [69713.711668] [8909] hci_send_to_monitor: hdev ffff88021f0c7000 len 6 > [69713.711680] [8909] hci_rx_work: hci0 Event packet > [69713.711683] [8909] hci_cs_le_create_conn: hci0 status 0x00 > [69713.711685] [8909] hci_sent_cmd_data: hci0 opcode 0x200d > [69713.711688] [8909] hci_req_cmd_complete: opcode 0x200d status 0x00 > [69713.711690] [8909] hci_sent_cmd_data: hci0 opcode 0x200d > [69713.711695] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69713.711744] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69713.818875] [8909] hci_rx_work: hci0 > [69713.818889] [8909] hci_send_to_monitor: hdev ffff88021f0c7000 len 21 > [69713.818913] [8909] hci_rx_work: hci0 Event packet > [69713.818917] [8909] hci_le_conn_complete_evt: hci0 status 0x00 > [69713.818922] [8909] hci_send_to_control: len 19 > [69713.818927] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69713.818938] [8909] hci_conn_add_sysfs: conn ffff88021f65a000 > [69713.818975] [6450] bt_sock_poll: sock ffff88005e758500, sk ffff88010323b800 > [69713.818981] [6515] hci_sock_recvmsg: sock ffff88005e75a080, sk ffff88010323ac00 > ... > [69713.819021] [8909] hci_dev_hold: hci0 orig refcnt 10 > [69713.819025] [8909] l2cap_connect_cfm: hcon ffff88021f65a000 bdaddr 00:1b:dc:06:06:22 status 0 > [69713.819028] [8909] hci_chan_create: hci0 hcon ffff88021f65a000 > [69713.819031] [8909] l2cap_conn_add: hcon ffff88021f65a000 conn ffff880221005c00 hchan ffff88020d60b1c0 > [69713.819034] [8909] l2cap_conn_ready: conn ffff880221005c00 > [69713.819036] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69713.819037] [8909] smp_conn_security: conn ffff880221005c00 hcon ffff88021f65a000 level 0x02 > [69713.819039] [8909] smp_chan_create: > [69713.819041] [8909] hci_conn_hold: hcon ffff88021f65a000 orig refcnt 1 > [69713.819043] [8909] smp_send_cmd: code 0x01 > [69713.819045] [8909] hci_send_acl: hci0 chan ffff88020d60b1c0 flags 0x0000 > [69713.819046] [5949] hci_sock_recvmsg: sock ffff8800941a9900, sk ffff88012bf4e800 > [69713.819049] [8909] hci_queue_acl: hci0 nonfrag skb ffff88005157c100 len 15 > [69713.819055] [5949] hci_sock_recvmsg: sock ffff8800941a9900, sk ffff88012bf4e800 > [69713.819057] [8909] l2cap_le_conn_ready: > [69713.819064] [8909] l2cap_chan_create: chan ffff88005ede2c00 > [69713.819066] [8909] l2cap_chan_hold: chan ffff88005ede2c00 orig refcnt 1 > [69713.819069] [8909] l2cap_sock_init: sk ffff88005ede5800 > [69713.819072] [8909] bt_accept_enqueue: parent ffff880160356000, sk ffff88005ede5800 > [69713.819074] [8909] __l2cap_chan_add: conn ffff880221005c00, psm 0x00, dcid 0x0004 > [69713.819076] [8909] l2cap_chan_hold: chan ffff88005ede2c00 orig refcnt 2 > [69713.819078] [8909] hci_conn_hold: hcon ffff88021f65a000 orig refcnt 2 > [69713.819080] [8909] smp_conn_security: conn ffff880221005c00 hcon ffff88021f65a000 level 0x01 > [69713.819082] [8909] l2cap_sock_ready_cb: sk ffff88005ede5800, parent ffff880160356000 > [69713.819086] [8909] le_pairing_complete_cb: status 0 > [69713.819091] [8909] hci_tx_work: hci0 acl 10 sco 8 le 0 > [69713.819093] [8909] hci_sched_acl: hci0 > [69713.819094] [8909] hci_sched_sco: hci0 > [69713.819096] [8909] hci_sched_esco: hci0 > [69713.819098] [8909] hci_sched_le: hci0 > [69713.819099] [8909] hci_chan_sent: hci0 > [69713.819101] [8909] hci_chan_sent: chan ffff88020d60b1c0 quote 10 > [69713.819104] [8909] hci_sched_le: chan ffff88020d60b1c0 skb ffff88005157c100 len 15 priority 7 > [69713.819106] [8909] hci_send_frame: hci0 type 2 len 15 > [69713.819108] [8909] hci_send_to_monitor: hdev ffff88021f0c7000 len 15 > [69713.819119] [8909] hci_chan_sent: hci0 > [69713.819121] [8909] hci_prio_recalculate: hci0 > [69713.819123] [8909] process_pending_rx: > [69713.819226] [6450] hci_sock_recvmsg: sock ffff88005e758780, sk ffff88010323d400 > ... > [69713.822022] [6450] l2cap_sock_accept: sk ffff880160356000 timeo 0 > [69713.822024] [6450] bt_accept_dequeue: parent ffff880160356000 > [69713.822026] [6450] bt_accept_unlink: sk ffff88005ede5800 state 1 > [69713.822028] [6450] l2cap_sock_accept: new socket ffff88005ede5800 > [69713.822368] [6450] l2cap_sock_getname: sock ffff8800941ab700, sk ffff88005ede5800 > [69713.822375] [6450] l2cap_sock_getsockopt: sk ffff88005ede5800 > [69713.822383] [6450] l2cap_sock_getname: sock ffff8800941ab700, sk ffff88005ede5800 > [69713.822414] [6450] bt_sock_poll: sock ffff8800941ab700, sk ffff88005ede5800 > ... > [69713.823255] [6450] l2cap_sock_getname: sock ffff8800941ab700, sk ffff88005ede5800 > [69713.823259] [6450] l2cap_sock_getsockopt: sk ffff88005ede5800 > [69713.824322] [6450] l2cap_sock_getname: sock ffff8800941ab700, sk ffff88005ede5800 > [69713.824330] [6450] l2cap_sock_getsockopt: sk ffff88005ede5800 > [69713.825029] [6450] bt_sock_poll: sock ffff88005e758500, sk ffff88010323b800 > ... > [69713.825187] [6450] l2cap_sock_sendmsg: sock ffff8800941ab700, sk ffff88005ede5800 > [69713.825189] [6450] bt_sock_wait_ready: sk ffff88005ede5800 > [69713.825192] [6450] l2cap_create_basic_pdu: chan ffff88005ede2c00 len 3 > [69713.825196] [6450] l2cap_do_send: chan ffff88005ede2c00, skb ffff880160b0b500 len 7 priority 0 > [69713.825199] [6450] hci_send_acl: hci0 chan ffff88020d60b1c0 flags 0x0000 > [69713.825201] [6450] hci_queue_acl: hci0 nonfrag skb ffff880160b0b500 len 11 > [69713.825210] [8909] hci_tx_work: hci0 acl 9 sco 8 le 0 > [69713.825213] [8909] hci_sched_acl: hci0 > [69713.825214] [8909] hci_sched_sco: hci0 > [69713.825216] [8909] hci_sched_esco: hci0 > [69713.825217] [8909] hci_sched_le: hci0 > [69713.825219] [8909] hci_chan_sent: hci0 > [69713.825221] [8909] hci_chan_sent: chan ffff88020d60b1c0 quote 9 > [69713.825223] [8909] hci_sched_le: chan ffff88020d60b1c0 skb ffff880160b0b500 len 11 priority 0 > [69713.825225] [8909] hci_send_frame: hci0 type 2 len 11 > [69713.825227] [8909] hci_send_to_monitor: hdev ffff88021f0c7000 len 11 > [69713.825242] [8909] hci_chan_sent: hci0 > [69713.825253] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69713.825253] [8909] hci_prio_recalculate: hci0 > [69713.825292] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69713.825768] [6450] bt_sock_poll: sock ffff88005e758500, sk ffff88010323b800 > ... > [69713.866902] [8909] hci_rx_work: hci0 > [69713.866921] [8909] hci_send_to_monitor: hdev ffff88021f0c7000 len 7 > [69713.866928] [8909] hci_rx_work: hci0 Event packet > [69713.866931] [8909] hci_num_comp_pkts_evt: hci0 num_hndl 1 > [69713.866937] [8909] hci_tx_work: hci0 acl 9 sco 8 le 0 > [69713.866939] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69713.866940] [8909] hci_sched_acl: hci0 > ... > [69713.866944] [8909] hci_sched_le: hci0 > [69713.866953] [8909] hci_chan_sent: hci0 > [69713.866997] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69713.867840] [28074] hci_rx_work: hci0 > [69713.867844] [28074] hci_send_to_monitor: hdev ffff88021f0c7000 len 7 > [69713.867850] [28074] hci_rx_work: hci0 Event packet > [69713.867853] [28074] hci_num_comp_pkts_evt: hci0 num_hndl 1 > [69713.867857] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69713.867858] [28074] hci_tx_work: hci0 acl 10 sco 8 le 0 > [69713.867860] [28074] hci_sched_acl: hci0 > [69713.867861] [28074] hci_sched_sco: hci0 > [69713.867862] [28074] hci_sched_esco: hci0 > [69713.867863] [28074] hci_sched_le: hci0 > [69713.867865] [28074] hci_chan_sent: hci0 > [69713.867888] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69714.145661] [8909] hci_rx_work: hci0 > [69714.145666] [8909] hci_send_to_monitor: hdev ffff88021f0c7000 len 10 > [69714.145676] [8909] hci_rx_work: hci0 ACL data packet > [69714.145679] [8909] hci_acldata_packet: hci0 len 6 handle 0x002d flags 0x0002 > [69714.145681] [8909] hci_conn_enter_active_mode: hcon ffff88021f65a000 mode 0 > [69714.145683] [8909] l2cap_recv_acldata: conn ffff880221005c00 len 6 flags 0x2 > [69714.145693] [8909] l2cap_recv_frame: len 2, cid 0x0006 > [69714.145696] [8909] hci_send_to_control: len 14 > [69714.145710] [8909] smp_chan_destroy: > [69714.145713] [8909] pairing_complete: status 3 > [69714.145714] [8909] cmd_complete: sock ffff88010323ac00 > [69714.145717] [8909] hci_conn_drop: hcon ffff88021f65a000 orig refcnt 3 > [69714.145719] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69714.145720] [6450] bt_sock_poll: sock ffff88005e758500, sk ffff88010323b800 > [69714.145722] [6515] hci_sock_recvmsg: sock ffff88005e75a080, sk ffff88010323ac00 > [69714.145724] [6450] bt_sock_poll: sock ffff8801db6b4f00, sk ffff880160351c00 > ... > [69714.145735] [6515] hci_sock_recvmsg: sock ffff88005e75a080, sk ffff88010323ac00 > [69714.145737] [8909] hci_conn_drop: hcon ffff88021f65a000 orig refcnt 2 > [69714.145739] [8909] l2cap_conn_del: hcon ffff88021f65a000 conn ffff880221005c00, err 13 > [69714.145740] [6450] bt_sock_poll: sock ffff8801db6b5400, sk ffff88021e775000 > [69714.145743] [6450] bt_sock_poll: sock ffff8801db6b5e00, sk ffff880160356000 > [69714.145744] [8909] l2cap_chan_hold: chan ffff88005ede2c00 orig refcnt 3 > [69714.145746] [6450] bt_sock_poll: sock ffff8800941ab700, sk ffff88005ede5800 > [69714.145748] [8909] l2cap_chan_del: chan ffff88005ede2c00, conn ffff880221005c00, err 13 > [69714.145749] [8909] l2cap_chan_put: chan ffff88005ede2c00 orig refcnt 4 > [69714.145751] [8909] hci_conn_drop: hcon ffff88021f65a000 orig refcnt 1 > [69714.145754] [6450] bt_sock_poll: sock ffff8800941ab700, sk ffff88005ede5800 > [69714.145756] [8909] l2cap_chan_put: chan ffff88005ede2c00 orig refcnt 3 > [69714.145759] [8909] hci_chan_del: hci0 hcon ffff88021f65a000 chan ffff88020d60b1c0 > [69714.145766] [5949] hci_sock_recvmsg: sock ffff8800941a9680, sk ffff88012bf4d000 > [69714.145787] [6515] hci_sock_release: sock ffff88005e75a080 sk ffff88010323ac00 > [69714.146002] [6450] hci_sock_recvmsg: sock ffff88005e758780, sk ffff88010323d400 > [69714.150795] [6450] l2cap_sock_release: sock ffff8800941ab700, sk ffff88005ede5800 > [69714.150799] [6450] l2cap_sock_shutdown: sock ffff8800941ab700, sk ffff88005ede5800 > [69714.150802] [6450] l2cap_chan_close: chan ffff88005ede2c00 state BT_CLOSED > [69714.150805] [6450] l2cap_sock_kill: sk ffff88005ede5800 state BT_CLOSED > [69714.150806] [6450] l2cap_chan_put: chan ffff88005ede2c00 orig refcnt 2 > [69714.150808] [6450] l2cap_sock_destruct: sk ffff88005ede5800 > [69714.150809] [6450] l2cap_chan_put: chan ffff88005ede2c00 orig refcnt 1 > [69714.150811] [6450] l2cap_chan_destroy: chan ffff88005ede2c00 > [69714.150970] [6450] bt_sock_poll: sock ffff88005e758500, sk ffff88010323b800 > ... > [69714.151991] [8909] hci_conn_drop: hcon ffff88021f65a000 orig refcnt 0 > [69716.150339] [8909] hci_conn_timeout: hcon ffff88021f65a000 state BT_CONNECTED, refcnt -1 > > Signed-off-by: Lukasz Rymanowski <lukasz.rymanowski@xxxxxxxxx> > --- > v4: fixed commit msg to looks nicer > > net/bluetooth/hci_conn.c | 12 +++++++++++- > 1 file changed, 11 insertions(+), 1 deletion(-) > > diff --git a/net/bluetooth/hci_conn.c b/net/bluetooth/hci_conn.c > index ca01d18..a7a27bc 100644 > --- a/net/bluetooth/hci_conn.c > +++ b/net/bluetooth/hci_conn.c > @@ -289,10 +289,20 @@ static void hci_conn_timeout(struct work_struct *work) > { > struct hci_conn *conn = container_of(work, struct hci_conn, > disc_work.work); > + int refcnt = atomic_read(&conn->refcnt); > > BT_DBG("hcon %p state %s", conn, state_to_string(conn->state)); > > - if (atomic_read(&conn->refcnt)) > + WARN_ON(refcnt < 0); As a fuzzer, syzbot hits this warning quite often. Thanks for adding this WARN_ON. It is indicating that the issue of refcount getting less than 0 is still present. It would be best if a bluetooth dev can have a look at the error paths to resolve this. > + > + /* FIXME: It was observed that in pairing failed scenario, refcnt > + * drops below 0. Probably this is because l2cap_conn_del calls > + * l2cap_chan_del for each channel, and inside l2cap_chan_del conn is > + * dropped. After that loop hci_chan_del is called which also drops > + * conn. For now make sure that ACL is alive if refcnt is higher then 0, > + * otherwise drop it. > + */ > + if (refcnt > 0) > return; > > switch (conn->state) { -- BR, Muhammad Usama Anjum _______________________________________________ devel mailing list devel@xxxxxxxxxxxxxxxxxxxxxx http://driverdev.linuxdriverproject.org/mailman/listinfo/driverdev-devel