[REGRESSION] 3.2.0-rc3 Bluetooth L2CAP Linux to Linux rfcomm fails

[REGRESSION] 3.2.0-rc3 Bluetooth L2CAP Linux to Linux rfcomm fails

[David Fries]

On Mon, Oct 31, 2011 at 05:01:29PM -0200, Gustavo Padovan wrote:
> Hi Arek,
> 
> * Arek Lichwa <arkadiusz.lichwa@tieto.com> [2011-10-26 11:23:21 +0200]:
> 
> > Hi
> > 
> > We found during testing problem when setting rfcomm (SPP) channel between
> > two 2.1 devices. 
> > The test case always failed mostly saying security block on l2cap level 
> > but sometimes the fail root cause was 'Command not understood' on l2cap 
> > as well.
> > Analyzing security block issue, I found that there's unencrypted link when
> > l2cap command 'connection request' is sent to remote.
> > The second issue with 'command not understood' has turn out to be related to 
> > expiration of l2cap timer and its implications.
> > 
> > Solution that I found to fix the problem seems to be related to old commit 
> > 330605423ca6eafafb8dcc27502bce1c585d1b06 made by Ilia Kolomisnky. When there's
> > authentication ongoing, 'encryption pending' should be turn on, otherwise 
> > there're situations when link stays unencrypted. 
> > The issue with timer expiration is related to Andrzej Kaczmarek's patch 
> > sent to community a couple days ago (~ 2011/10/20). 
> > This patch actually recalculates (repairs) timer values on l2cap which were 
> > wrongly converted before. 
> > With this patch the expiration issue disappears during the test case 
> > I've made, otherwise just reverting 330605423ca6eafafb8dcc27502bce1c585d1b06
> > is not enough, since timer issue blocks very often passing the test case.
> 
> Are you saying that Andrzej's patch together with revert of 330605423 fixes
> the problem? and are you sure that we are not creating any new regression?
> 
> 	Gustavo

I just found that I can't connect rfcomm any more from Linux (desktop)
to Linux (N900) with bluetooth.  On the desktop side, 3.2.0-rc2 works,
but 3.2.0-rc3 (and on) fails, I even merged in
git://git.kernel.org/pub/scm/linux/kernel/git/padovan/bluetooth-next
master 5a13b09531420d230616bd524b68a5b0c23cd487 without any change.
Fortunately there were only three bluetooth patches between rc2 and rc3.
Reverting 4dff523a913197e3314c7b0d08734ab037709093 fixed the issue and
I can connect again.

Linux (desktop)
hci0:   Type: BR/EDR  Bus: USB
        BD Address: XX:XX:XX:XX:XX:XX  ACL MTU: 310:10  SCO MTU: 64:8
        UP RUNNING PSCAN ISCAN 
        RX bytes:1846 acl:16 sco:0 events:70 errors:0
        TX bytes:1223 acl:15 sco:0 commands:44 errors:0

Linux (N900)
hci0:   Type: UART
        BD Address: XX:XX:XX:XX:XX:XX ACL MTU: 1017:4 SCO MTU: 64:1
        UP RUNNING PSCAN 
        RX bytes:24972 acl:536 sco:0 events:784 errors:0
        TX bytes:32590 acl:520 sco:0 commands:217 errors:0

I'm trying to connect to N900 running Linux 2.6.28.10-power49+.  While
I can apply patches to the N900 kernel, and the community edition
power kernel is making bug releases, I have no expectation that the
stock Nokia kernel will have another release.  So I don't think this
can be fixed on the N900 side.

Here's a diff of a dump using both a working and not working kernel.
`rfcomm connect /dev/rfcomm0 XX:XX:XX:XX:XX:XX 1`
from the desktop side to the N900.  The connection is established with
3.2.0-rc2+ but not with 3.2.0-rc5+.

-Linux Pulsar 3.2.0-rc2+ #12 SMP Mon Nov 21 18:30:39 CST 2011 x86_64 GNU/Linux
+Linux Pulsar 3.2.0-rc5+ #16 SMP Sat Dec 10 20:09:18 CST 2011 x86_64 GNU/Linux

 hcidump -X

 HCI sniffer - Bluetooth packet analyzer ver 2.1
 device: hci0 snap_len: 1028 filter: 0xffffffffffffffff
 < HCI Command: Create Connection (0x01|0x0005) plen 13
     bdaddr XX:XX:XX:XX:XX:XX ptype 0xcc18 rswitch 0x01 clkoffset 0x0000
     Packet type: DM1 DM3 DM5 DH1 DH3 DH5 
 > HCI Event: Command Status (0x0f) plen 4
     Create Connection (0x01|0x0005) status 0x00 ncmd 1
 > HCI Event: Role Change (0x12) plen 8
     status 0x00 bdaddr XX:XX:XX:XX:XX:XX role 0x01
     Role: Slave
 > HCI Event: Connect Complete (0x03) plen 11
     status 0x00 handle 38 bdaddr XX:XX:XX:XX:XX:XX type ACL encrypt 0x00
 < HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2
     handle 38
 > HCI Event: Page Scan Repetition Mode Change (0x20) plen 7
     bdaddr XX:XX:XX:XX:XX:XX mode 0
 > HCI Event: Max Slots Change (0x1b) plen 3
     handle 38 slots 5
 > HCI Event: Command Status (0x0f) plen 4
     Read Remote Supported Features (0x01|0x001b) status 0x00 ncmd 1
 > HCI Event: Read Remote Supported Features (0x0b) plen 11
     status 0x00 handle 38
     Features: 0xbf 0xee 0x0f 0xc6 0x98 0x3d 0x59 0x82
 < HCI Command: Read Remote Extended Features (0x01|0x001c) plen 3
     handle 38 page 1
 > HCI Event: Command Status (0x0f) plen 4
     Read Remote Extended Features (0x01|0x001c) status 0x00 ncmd 1
 > HCI Event: Read Remote Extended Features (0x23) plen 13
     status 0x00 handle 38 page 1 max 1
     Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
 < HCI Command: Remote Name Request (0x01|0x0019) plen 10
     bdaddr XX:XX:XX:XX:XX:XX mode 2 clkoffset 0x0000
 > HCI Event: Command Status (0x0f) plen 4
     Remote Name Request (0x01|0x0019) status 0x00 ncmd 1
 > HCI Event: Remote Name Req Complete (0x07) plen 255
     status 0x00 bdaddr XX:XX:XX:XX:XX:XX name 'XXXXXXXXXXXXXX_900'
 < HCI Command: Authentication Requested (0x01|0x0011) plen 2
     handle 38
 > HCI Event: Command Status (0x0f) plen 4
     Authentication Requested (0x01|0x0011) status 0x00 ncmd 1
 > HCI Event: Link Key Request (0x17) plen 6
     bdaddr XX:XX:XX:XX:XX:XX
 < HCI Command: Link Key Request Reply (0x01|0x000b) plen 22
     bdaddr XX:XX:XX:XX:XX:XX key XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
 > HCI Event: Command Complete (0x0e) plen 10
     Link Key Request Reply (0x01|0x000b) ncmd 1
     status 0x00 bdaddr XX:XX:XX:XX:XX:XX
 > HCI Event: Auth Complete (0x06) plen 3
     status 0x00 handle 38
 < HCI Command: Set Connection Encryption (0x01|0x0013) plen 3
     handle 38 encrypt 0x01
 > HCI Event: Command Status (0x0f) plen 4
     Set Connection Encryption (0x01|0x0013) status 0x00 ncmd 1
 > HCI Event: Encrypt Change (0x08) plen 4
     status 0x00 handle 38 encrypt 0x01
 < ACL data: handle 38 flags 0x00 dlen 10
     L2CAP(s): Info req: type 2
 > HCI Event: Number of Completed Packets (0x13) plen 5
     handle 38 packets 1
 > ACL data: handle 38 flags 0x02 dlen 16
     L2CAP(s): Info rsp: type 2 result 0
       Extended feature mask 0x0000
 < ACL data: handle 38 flags 0x00 dlen 12
     L2CAP(s): Connect req: psm 3 scid 0x0040
 > HCI Event: Number of Completed Packets (0x13) plen 5
     handle 38 packets 1
 > ACL data: handle 38 flags 0x02 dlen 16
     L2CAP(s): Connect rsp: dcid 0x0040 scid 0x0040 result 1 status 0
       Connection pending - No futher information available
 > ACL data: handle 38 flags 0x02 dlen 10
     L2CAP(s): Info req: type 2
 < ACL data: handle 38 flags 0x00 dlen 16
     L2CAP(s): Info rsp: type 2 result 0
       Extended feature mask 0x00b8
 > HCI Event: Number of Completed Packets (0x13) plen 5
     handle 38 packets 1
 > ACL data: handle 38 flags 0x02 dlen 10
     L2CAP(s): Info req: type 3
 < ACL data: handle 38 flags 0x00 dlen 20
     L2CAP(s): Info rsp: type 3 result 0
       Fixed channel list
 > HCI Event: Number of Completed Packets (0x13) plen 5
     handle 38 packets 1
 > ACL data: handle 38 flags 0x02 dlen 16
     L2CAP(s): Connect rsp: dcid 0x0040 scid 0x0040 result 0 status 0
       Connection successful
 < ACL data: handle 38 flags 0x00 dlen 16
     L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4
       MTU 1013 
 > HCI Event: Number of Completed Packets (0x13) plen 5
     handle 38 packets 1
 > ACL data: handle 38 flags 0x02 dlen 18
     L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 4
       MTU 1013 
 > ACL data: handle 38 flags 0x02 dlen 16
     L2CAP(s): Config req: dcid 0x0040 flags 0x00 clen 4
       MTU 1013 
 < ACL data: handle 38 flags 0x00 dlen 18
     L2CAP(s): Config rsp: scid 0x0040 flags 0x00 result 0 clen 4
       MTU 1013 
 < ACL data: handle 38 flags 0x00 dlen 8
     L2CAP(d): cid 0x0040 len 4 [psm 3]
       RFCOMM(s): SABM: cr 1 dlci 0 pf 1 ilen 0 fcs 0x1c 
 > HCI Event: Number of Completed Packets (0x13) plen 5
     handle 38 packets 1
 > HCI Event: Number of Completed Packets (0x13) plen 5
     handle 38 packets 1
 > ACL data: handle 38 flags 0x02 dlen 8
     L2CAP(d): cid 0x0040 len 4 [psm 3]
       RFCOMM(s): UA: cr 1 dlci 0 pf 1 ilen 0 fcs 0xd7 
-< ACL data: handle 38 flags 0x00 dlen 18
-    L2CAP(d): cid 0x0040 len 14 [psm 3]
-      RFCOMM(s): PN CMD: cr 1 dlci 0 pf 0 ilen 10 fcs 0x70 mcc_len 8
-      dlci 2 frame_type 0 credit_flow 15 pri 7 ack_timer 0
-      frame_size 1008 max_retrans 0 credits 7
-> HCI Event: Number of Completed Packets (0x13) plen 5
-    handle 38 packets 1
-> ACL data: handle 38 flags 0x02 dlen 18
-    L2CAP(d): cid 0x0040 len 14 [psm 3]
-      RFCOMM(s): PN RSP: cr 0 dlci 0 pf 0 ilen 10 fcs 0xaa mcc_len 8
-      dlci 2 frame_type 0 credit_flow 14 pri 7 ack_timer 0
-      frame_size 1008 max_retrans 0 credits 7
-< ACL data: handle 38 flags 0x00 dlen 8
-    L2CAP(d): cid 0x0040 len 4 [psm 3]
-      RFCOMM(s): SABM: cr 1 dlci 2 pf 1 ilen 0 fcs 0x59 
-> HCI Event: Number of Completed Packets (0x13) plen 5
-    handle 38 packets 1
-> ACL data: handle 38 flags 0x02 dlen 8
-    L2CAP(d): cid 0x0040 len 4 [psm 3]
-      RFCOMM(s): UA: cr 1 dlci 2 pf 1 ilen 0 fcs 0x92 
-< ACL data: handle 38 flags 0x00 dlen 12
-    L2CAP(d): cid 0x0040 len 8 [psm 3]
-      RFCOMM(s): MSC CMD: cr 1 dlci 0 pf 0 ilen 4 fcs 0x70 mcc_len 2
-      dlci 2 fc 0 rtc 1 rtr 1 ic 0 dv 1 b1 1 b2 1 b3 0 len 0
-> ACL data: handle 38 flags 0x02 dlen 12
-    L2CAP(d): cid 0x0040 len 8 [psm 3]
-      RFCOMM(s): MSC CMD: cr 0 dlci 0 pf 0 ilen 4 fcs 0xaa mcc_len 2
-      dlci 2 fc 0 rtc 1 rtr 1 ic 0 dv 1 b1 1 b2 1 b3 0 len 0
-< ACL data: handle 38 flags 0x00 dlen 12
-    L2CAP(d): cid 0x0040 len 8 [psm 3]
-      RFCOMM(s): MSC RSP: cr 1 dlci 0 pf 0 ilen 4 fcs 0x70 mcc_len 2
-      dlci 2 fc 0 rtc 1 rtr 1 ic 0 dv 1 b1 1 b2 1 b3 0 len 0
-> HCI Event: Number of Completed Packets (0x13) plen 5
-    handle 38 packets 1
-> ACL data: handle 38 flags 0x02 dlen 12
-    L2CAP(d): cid 0x0040 len 8 [psm 3]
-      RFCOMM(s): MSC RSP: cr 0 dlci 0 pf 0 ilen 4 fcs 0xaa mcc_len 2
-      dlci 2 fc 0 rtc 1 rtr 1 ic 0 dv 1 b1 1 b2 1 b3 0 len 0
-< ACL data: handle 38 flags 0x00 dlen 9
-    L2CAP(d): cid 0x0040 len 5 [psm 3]
-      RFCOMM(d): UIH: cr 1 dlci 2 pf 1 ilen 0 fcs 0x86 credits 33
-> HCI Event: Number of Completed Packets (0x13) plen 5
-    handle 38 packets 1
-> HCI Event: Number of Completed Packets (0x13) plen 5
-    handle 38 packets 1
-> ACL data: handle 38 flags 0x02 dlen 9
-    L2CAP(d): cid 0x0040 len 5 [psm 3]
-      RFCOMM(d): UIH: cr 0 dlci 2 pf 1 ilen 0 fcs 0x5c credits 33
-
 
 < ACL data: handle 38 flags 0x00 dlen 8
     L2CAP(d): cid 0x0040 len 4 [psm 3]
       RFCOMM(s): DISC: cr 1 dlci 2 pf 1 ilen 0 fcs 0xb8 
 > HCI Event: Number of Completed Packets (0x13) plen 5
     handle 38 packets 1
 > ACL data: handle 38 flags 0x02 dlen 8
     L2CAP(d): cid 0x0040 len 4 [psm 3]
-      RFCOMM(s): UA: cr 1 dlci 2 pf 1 ilen 0 fcs 0x92 
+      RFCOMM(s): DM: cr 1 dlci 2 pf 1 ilen 0 fcs 0x73 

-- 
David Fries <david@fries.net>    PGP pub CB1EE8F0
http://fries.net/~david/

Re: [REGRESSION] 3.2.0-rc3 Bluetooth L2CAP Linux to Linux rfcomm fails

[Gustavo Padovan]

Hi David,

* David Fries <david@fries.net> [2011-12-10 23:16:24 -0600]:

> On Mon, Oct 31, 2011 at 05:01:29PM -0200, Gustavo Padovan wrote:
> > Hi Arek,
> > 
> > * Arek Lichwa <arkadiusz.lichwa@tieto.com> [2011-10-26 11:23:21 +0200]:
> > 
> > > Hi
> > > 
> > > We found during testing problem when setting rfcomm (SPP) channel between
> > > two 2.1 devices. 
> > > The test case always failed mostly saying security block on l2cap level 
> > > but sometimes the fail root cause was 'Command not understood' on l2cap 
> > > as well.
> > > Analyzing security block issue, I found that there's unencrypted link when
> > > l2cap command 'connection request' is sent to remote.
> > > The second issue with 'command not understood' has turn out to be related to 
> > > expiration of l2cap timer and its implications.
> > > 
> > > Solution that I found to fix the problem seems to be related to old commit 
> > > 330605423ca6eafafb8dcc27502bce1c585d1b06 made by Ilia Kolomisnky. When there's
> > > authentication ongoing, 'encryption pending' should be turn on, otherwise 
> > > there're situations when link stays unencrypted. 
> > > The issue with timer expiration is related to Andrzej Kaczmarek's patch 
> > > sent to community a couple days ago (~ 2011/10/20). 
> > > This patch actually recalculates (repairs) timer values on l2cap which were 
> > > wrongly converted before. 
> > > With this patch the expiration issue disappears during the test case 
> > > I've made, otherwise just reverting 330605423ca6eafafb8dcc27502bce1c585d1b06
> > > is not enough, since timer issue blocks very often passing the test case.
> > 
> > Are you saying that Andrzej's patch together with revert of 330605423 fixes
> > the problem? and are you sure that we are not creating any new regression?
> > 
> > 	Gustavo
> 
> I just found that I can't connect rfcomm any more from Linux (desktop)
> to Linux (N900) with bluetooth.  On the desktop side, 3.2.0-rc2 works,
> but 3.2.0-rc3 (and on) fails, I even merged in
> git://git.kernel.org/pub/scm/linux/kernel/git/padovan/bluetooth-next
> master 5a13b09531420d230616bd524b68a5b0c23cd487 without any change.
> Fortunately there were only three bluetooth patches between rc2 and rc3.
> Reverting 4dff523a913197e3314c7b0d08734ab037709093 fixed the issue and
> I can connect again.

I wen ahead and reverted this one.

	Gustavo

Re: [REGRESSION] 3.2.0-rc3 Bluetooth L2CAP Linux to Linux rfcomm fails

[David Fries]

On Sun, Dec 18, 2011 at 10:36:52PM -0200, Gustavo Padovan wrote:
> Hi David,
> 
> * David Fries <david@fries.net> [2011-12-10 23:16:24 -0600]:
> 
> > On Mon, Oct 31, 2011 at 05:01:29PM -0200, Gustavo Padovan wrote:
> > > Hi Arek,
> > > 
> > > * Arek Lichwa <arkadiusz.lichwa@tieto.com> [2011-10-26 11:23:21 +0200]:
> > > 
> > > > Hi
> > > > 
> > > > We found during testing problem when setting rfcomm (SPP) channel between
> > > > two 2.1 devices. 
> > > > The test case always failed mostly saying security block on l2cap level 
> > > > but sometimes the fail root cause was 'Command not understood' on l2cap 
> > > > as well.
> > > > Analyzing security block issue, I found that there's unencrypted link when
> > > > l2cap command 'connection request' is sent to remote.
> > > > The second issue with 'command not understood' has turn out to be related to 
> > > > expiration of l2cap timer and its implications.
> > > > 
> > > > Solution that I found to fix the problem seems to be related to old commit 
> > > > 330605423ca6eafafb8dcc27502bce1c585d1b06 made by Ilia Kolomisnky. When there's
> > > > authentication ongoing, 'encryption pending' should be turn on, otherwise 
> > > > there're situations when link stays unencrypted. 
> > > > The issue with timer expiration is related to Andrzej Kaczmarek's patch 
> > > > sent to community a couple days ago (~ 2011/10/20). 
> > > > This patch actually recalculates (repairs) timer values on l2cap which were 
> > > > wrongly converted before. 
> > > > With this patch the expiration issue disappears during the test case 
> > > > I've made, otherwise just reverting 330605423ca6eafafb8dcc27502bce1c585d1b06
> > > > is not enough, since timer issue blocks very often passing the test case.
> > > 
> > > Are you saying that Andrzej's patch together with revert of 330605423 fixes
> > > the problem? and are you sure that we are not creating any new regression?
> > > 
> > > 	Gustavo
> > 
> > I just found that I can't connect rfcomm any more from Linux (desktop)
> > to Linux (N900) with bluetooth.  On the desktop side, 3.2.0-rc2 works,
> > but 3.2.0-rc3 (and on) fails, I even merged in
> > git://git.kernel.org/pub/scm/linux/kernel/git/padovan/bluetooth-next
> > master 5a13b09531420d230616bd524b68a5b0c23cd487 without any change.
> > Fortunately there were only three bluetooth patches between rc2 and rc3.
> > Reverting 4dff523a913197e3314c7b0d08734ab037709093 fixed the issue and
> > I can connect again.
> 
> I wen ahead and reverted this one.
> 
> 	Gustavo

Thanks.  It's unfortunate that it seems some devices seem to have
mutually incompatible options.  I'll volunteer to test against the
N900 if there are any patches in the future that try to make both
types work if I'm made aware of the change.

Here's the N900 kernel-power's net/bluetooth/hci_conn.c
at least it was interesting to me that it does the test_and_set_bit
that causes my desktop to be unable to connect with it.  N900 is based
on 2.6.28 though the N900 version of that file is almost a match with
2.6.31.

/* Enable security */
int hci_conn_security(struct hci_conn *conn, __u8 sec_level, __u8 auth_type)
{
	BT_DBG("conn %p", conn);

	if (sec_level == BT_SECURITY_SDP)
		return 1;

	if (sec_level == BT_SECURITY_LOW &&
				(!conn->ssp_mode || !conn->hdev->ssp_mode))
		return 1;

	if (conn->link_mode & HCI_LM_ENCRYPT)
		return hci_conn_auth(conn, sec_level, auth_type);

	if (test_and_set_bit(HCI_CONN_ENCRYPT_PEND, &conn->pend))
		return 0;

	if (hci_conn_auth(conn, sec_level, auth_type)) {
		struct hci_cp_set_conn_encrypt cp;
		cp.handle  = cpu_to_le16(conn->handle);
		cp.encrypt = 1;
		hci_send_cmd(conn->hdev, HCI_OP_SET_CONN_ENCRYPT,
							sizeof(cp), &cp);
	}

	return 0;
}

After failing to connect to the N900 both with and without it reverted
I rebooted the N900, and double checked.  I could connect with
4dff523a913197e33 reverted, but I still got the 'Connection reset by
peer' without the patch reverted, not sure what went wrong on the N900
for a bit to cause both to fail and yet connect to bluetooth audio
devices, but it does need it reverted to work.

-- 
David Fries <david@fries.net>    PGP pub CB1EE8F0
http://fries.net/~david/