[Bluez-devel] racing condition in accepting incoming RFCOMM connection

[Bluez-devel] racing condition in accepting incoming RFCOMM connection

[Dmitri Khokhlov]

[-- Attachment #1: Type: text/plain, Size: 1059 bytes --]

Hi

It looks like there is a racing condition in accepting incoming RFCOMM
connection. It happens to me in 90% cases when a headset originates
connection to a voice gateway. If RFCOMM SAMB command frame comes in L2CAP
data packet right after L2CAP Configuration Request packet and there is no
active RFCOMM sessions yet then the kernel RFCOMM thread wakes up only one
time and creates new session but does not process SAMB frame from second
L2CAP data packet waiting in queue. Connection setup hangs. Headset is
waiting for UA frame response but the kernel RFCOMM thread keeps sleeping.
The kernel log for bad case is attached. I use the following environment:
Kernel: Linux 2.4.21 + patch-2.4.21-mh6, PowerPC.
Headsets: Motorola Model 98405H, BlueTrek-G2.
Voice gateway: Murata BlueModule, CSR BlueCore: BC02 (Hardware ID 8a)
firmware version 526
A possible solution could be to force additional thread wakeup right after
successful creation of new session in rfcomm_accept_connection(). The patch
is attached.

Regards.
Dmitri
mailto: dkhokhlov@hotmail.com

[-- Attachment #2: patch --]
[-- Type: application/octet-stream, Size: 475 bytes --]

diff -Naur  linux.org/net/bluetooth/rfcomm/core.c.old  linux/net/bluetooth/rfcomm/core.c
--- linux.org/net/bluetooth/rfcomm/core.c	Mon Feb  2 10:45:56 2004
+++ linux/net/bluetooth/rfcomm/core.c	Wed Feb  4 13:23:38 2004
@@ -1654,8 +1654,10 @@
 	nsock->sk->state_change = rfcomm_l2state_change;
 
 	s = rfcomm_session_add(nsock, BT_OPEN);
-	if (s)
+	if (s) {
 		rfcomm_session_hold(s);
+		rfcomm_schedule(RFCOMM_SCHED_RX);
+	}	
 	else
 		sock_release(nsock);
 }

[-- Attachment #3: log --]
[-- Type: application/octet-stream, Size: 6094 bytes --]

...incoming RFCOMM connection setup, DLC config negotiation...

Feb 3 16:24:49 10 kernel: hci_rx_task: hci0 ACL data packet
Feb 3 16:24:49 10 kernel: hci_acldata_packet: hci0 len 16 handle 0x29 flags 0x2
Feb 3 16:24:49 10 kernel: l2cap_recv_acldata: conn c02f0d20 len 16 flags 0x2
Feb 3 16:24:49 10 kernel: l2cap_recv_frame: len 12, cid 0x0001
Feb 3 16:24:49 10 kernel: l2cap_sig_channel: code 0x04 len 8 id 0x04

>>>>>>>>>Feb 3 16:24:49 10 kernel: l2cap_config_req: dcid 0x0041 flags 0x00

Feb 3 16:24:49 10 kernel: l2cap_parse_conf_req: sk c158aac0 len 4
Feb 3 16:24:49 10 kernel: l2cap_get_conf_opt: type 0x01 len 2 val 0x84
Feb 3 16:24:49 10 kernel: l2cap_build_conf_rsp: sk c158aac0 complete 1
Feb 3 16:24:49 10 kernel: l2cap_conf_output: sk c158aac0 result 0
Feb 3 16:24:49 10 kernel: l2cap_build_cmd: conn c02f0d20, code 0x05, ident 0x04, len 6
Feb 3 16:24:49 10 kernel: l2cap_send_rsp: code 0x05
Feb 3 16:24:49 10 kernel: hci_send_acl: hci0 conn c1cc7aa0 flags 0x0
Feb 3 16:24:49 10 kernel: hci_send_acl: hci0 nonfrag skb c03fef20 len 18
Feb 3 16:24:49 10 kernel: l2cap_build_conf_req: sk c158aac0
Feb 3 16:24:49 10 kernel: l2cap_add_conf_opt: type 0x01 len 2 val 0x400
Feb 3 16:24:49 10 kernel: l2cap_build_cmd: conn c02f0d20, code 0x04, ident 0x02, len 8
Feb 3 16:24:49 10 kernel: l2cap_send_req: code 0x04
Feb 3 16:24:49 10 kernel: hci_send_acl: hci0 conn c1cc7aa0 flags 0x0
Feb 3 16:24:49 10 kernel: hci_send_acl: hci0 nonfrag skb c0289480 len 20
Feb 3 16:24:49 10 kernel: hci_tx_task: hci0 acl 8 sco 8
Feb 3 16:24:49 10 kernel: hci_sched_acl: hci0
Feb 3 16:24:49 10 kernel: hci_low_sent: conn c1cc7aa0 quote 8
Feb 3 16:24:49 10 kernel: hci_sched_acl: skb c03fef20 len 18
Feb 3 16:24:49 10 kernel: hci_send_frame: hci0 type 2 len 18
Feb 3 16:24:49 10 kernel: hci_send_to_sock: hdev c02a9804 len 18
Feb 3 16:24:49 10 kernel: hci_uart_send_frame: hci0: type 2 len 18
Feb 3 16:24:49 10 kernel: hci_uart_tx_wakeup:
Feb 3 16:24:49 10 kernel: hci_sched_acl: skb c0289480 len 20
Feb 3 16:24:49 10 kernel: hci_send_frame: hci0 type 2 len 20
Feb 3 16:24:49 10 kernel: hci_send_to_sock: hdev c02a9804 len 20
Feb 3 16:24:49 10 kernel: hci_uart_send_frame: hci0: type 2 len 20
Feb 3 16:24:49 10 kernel: hci_uart_tx_wakeup:
Feb 3 16:24:49 10 kernel: hci_low_sent: conn 00000000 quote 0
Feb 3 16:24:49 10 kernel: hci_sched_sco: hci0
Feb 3 16:24:49 10 kernel: hci_low_sent: conn 00000000 quote 0
Feb 3 16:24:49 10 kernel: hci_uart_tty_wakeup:
Feb 3 16:24:49 10 kernel: hci_uart_tx_wakeup:
Feb 3 16:24:49 10 kernel: hci_recv_frame: hci0 type 4 len 7
Feb 3 16:24:49 10 kernel: hci_rx_task: hci0
Feb 3 16:24:49 10 kernel: hci_send_to_sock: hdev c02a9804 len 7
Feb 3 16:24:49 10 kernel: hci_event_packet: hci0 evt 0x13
Feb 3 16:24:49 10 kernel: hci_num_comp_pkts_evt: hci0 num_hndl 1
Feb 3 16:24:49 10 kernel: hci_tx_task: hci0 acl 7 sco 8
Feb 3 16:24:49 10 kernel: hci_sched_acl: hci0
Feb 3 16:24:49 10 kernel: hci_low_sent: conn 00000000 quote 0
Feb 3 16:24:49 10 kernel: hci_sched_sco: hci0
Feb 3 16:24:49 10 kernel: hci_low_sent: conn 00000000 quote 0
Feb 3 16:24:49 10 kernel: hci_recv_frame: hci0 type 4 len 7
Feb 3 16:24:49 10 kernel: hci_rx_task: hci0
Feb 3 16:24:49 10 kernel: hci_send_to_sock: hdev c02a9804 len 7
Feb 3 16:24:49 10 kernel: hci_event_packet: hci0 evt 0x13
Feb 3 16:24:49 10 kernel: hci_num_comp_pkts_evt: hci0 num_hndl 1
Feb 3 16:24:49 10 kernel: hci_tx_task: hci0 acl 8 sco 8
Feb 3 16:24:49 10 kernel: hci_sched_acl: hci0
Feb 3 16:24:49 10 kernel: hci_low_sent: conn 00000000 quote 0
Feb 3 16:24:49 10 kernel: hci_sched_sco: hci0
Feb 3 16:24:49 10 kernel: hci_low_sent: conn 00000000 quote 0
Feb 3 16:24:49 10 kernel: hci_recv_frame: hci0 type 2 len 21
Feb 3 16:24:49 10 kernel: hci_rx_task: hci0
Feb 3 16:24:49 10 kernel: hci_send_to_sock: hdev c02a9804 len 21
Feb 3 16:24:49 10 kernel: hci_rx_task: hci0 ACL data packet
Feb 3 16:24:49 10 kernel: hci_acldata_packet: hci0 len 17 handle 0x29 flags 0x2
Feb 3 16:24:49 10 kernel: l2cap_recv_acldata: conn c02f0d20 len 17 flags 0x2

>>>>>>Feb 3 16:24:49 10 kernel: l2cap_recv_acldata: Start: total len 18, frag len 17

Feb 3 16:24:49 10 kernel: hci_recv_frame: hci0 type 2 len 5
Feb 3 16:24:49 10 kernel: hci_rx_task: hci0
Feb 3 16:24:49 10 kernel: hci_send_to_sock: hdev c02a9804 len 5
Feb 3 16:24:49 10 kernel: hci_rx_task: hci0 ACL data packet
Feb 3 16:24:49 10 kernel: hci_acldata_packet: hci0 len 1 handle 0x29 flags 0x1
Feb 3 16:24:49 10 kernel: l2cap_recv_acldata: conn c02f0d20 len 1 flags 0x1
Feb 3 16:24:49 10 kernel: l2cap_recv_acldata: Cont: frag len 1 (expecting 1)
Feb 3 16:24:49 10 kernel: l2cap_recv_frame: len 14, cid 0x0001
Feb 3 16:24:49 10 kernel: l2cap_sig_channel: code 0x05 len 10 id 0x02

>>>>>>Feb 3 16:24:49 10 kernel: l2cap_config_rsp: scid 0x0041 flags 0x00 result 0x00

Feb 3 16:24:49 10 kernel: l2cap_chan_ready: sk c158aac0, parent c02c3080
Feb 3 16:24:49 10 kernel: l2cap_sock_clear_timer: sock c158aac0 state 1
Feb 3 16:24:49 10 kernel: rfcomm_l2data_ready: c02c3080 bytes 0
Feb 3 16:24:49 10 kernel: hci_recv_frame: hci0 type 2 len 12
Feb 3 16:24:49 10 kernel: hci_rx_task: hci0
Feb 3 16:24:49 10 kernel: hci_send_to_sock: hdev c02a9804 len 12
Feb 3 16:24:49 10 kernel: hci_rx_task: hci0 ACL data packet
Feb 3 16:24:49 10 kernel: hci_acldata_packet: hci0 len 8 handle 0x29 flags 0x2
Feb 3 16:24:49 10 kernel: l2cap_recv_acldata: conn c02f0d20 len 8 flags 0x2

>>>>>>Feb 3 16:24:49 10 kernel: l2cap_recv_frame: len 4, cid 0x0041 >>>>>>>>>SABM

Feb 3 16:24:49 10 kernel: l2cap_data_channel: sk c158aac0, len 4
Feb 3 16:24:49 10 kernel: hci_acldata_packet: hci0 len 4 handle 0x29 flags 0x2 @@@@@@ after recv_acldata

>>>>>>Feb 3 16:24:49 10 kernel: rfcomm_accept_connection: session c02f05a0

Feb 3 16:24:49 10 kernel: l2cap_sock_accept: sk c02c3080 timeo 0
Feb 3 16:24:49 10 kernel: l2cap_sock_accept: new socket c158aac0
Feb 3 16:24:49 10 kernel: rfcomm_session_add: session c02f0ae0 sock c155a560
Feb 3 16:24:49 10 kernel: rfcomm_worker: worker loop event 0x0

.. nothing happens here. 

Re: [Bluez-devel] racing condition in accepting incoming RFCOMM connection

[Marcel Holtmann]

Hi Dmitri,

> It looks like there is a racing condition in accepting incoming RFCOMM
> connection. It happens to me in 90% cases when a headset originates
> connection to a voice gateway. If RFCOMM SAMB command frame comes in L2CAP
> data packet right after L2CAP Configuration Request packet and there is no
> active RFCOMM sessions yet then the kernel RFCOMM thread wakes up only one
> time and creates new session but does not process SAMB frame from second
> L2CAP data packet waiting in queue. Connection setup hangs. Headset is
> waiting for UA frame response but the kernel RFCOMM thread keeps sleeping.
> The kernel log for bad case is attached. I use the following environment:
> Kernel: Linux 2.4.21 + patch-2.4.21-mh6, PowerPC.
> Headsets: Motorola Model 98405H, BlueTrek-G2.
> Voice gateway: Murata BlueModule, CSR BlueCore: BC02 (Hardware ID 8a)
> firmware version 526
> A possible solution could be to force additional thread wakeup right after
> successful creation of new session in rfcomm_accept_connection(). The patch
> is attached.

sounds reasonable to me. Anyone else noticed this behaviour?

Regards

Marcel




-------------------------------------------------------
The SF.Net email is sponsored by EclipseCon 2004
Premiere Conference on Open Tools Development and Integration
See the breadth of Eclipse activity. February 3-5 in Anaheim, CA.
http://www.eclipsecon.org/osdn
_______________________________________________
Bluez-devel mailing list
Bluez-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bluez-devel