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

From: David Fries
Date: Sun Dec 11 2011 - 00:16:45 EST

Next message: ANNIE LI: "Re: [PATCH V3 1/2] xen/granttable: Support sub-page grants"
Previous message: Rusty Russell: "Re: [PATCH 21/21] MODSIGN: Apply signature checking to modules on module load [ver #3]"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Mon, Oct 31, 2011 at 05:01:29PM -0200, Gustavo Padovan wrote:
> Hi Arek,
>
> * Arek Lichwa <arkadiusz.lichwa@xxxxxxxxx> [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@xxxxxxxxx> PGP pub CB1EE8F0
http://fries.net/~david/
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: ANNIE LI: "Re: [PATCH V3 1/2] xen/granttable: Support sub-page grants"
Previous message: Rusty Russell: "Re: [PATCH 21/21] MODSIGN: Apply signature checking to modules on module load [ver #3]"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]