RFCOMM bug?
I'm having some trouble with the bluez implementation as distributed with fedora. I thought for a long time that this was a bug on the device (Ericsson P900 / Symbian 7.0) side of the connection, but it's now looking like a kernel issue on the linux box.
The app on the other side is a simple RFCOMM echoer. It reads a byte at a time and writes it back out to the socket. I'm connecting to it with a "cat /dev/rfcomm1", while I do a "echo a > /dev/rfcomm1" from another shell. What comes back is an unending spew of bytes, mostly (but oddly not entirely) derived from the "a\r\n" that went out the terminal initially.
FWIW, I see almost identical behavior when connecting to the "modem" device on the phone. The AT command work (in the sense that I can see the desired output appear on the socket), but come back as part of an infinite garbage stream.
Attached is the result of an hcidump -tx of such a session. Note that the local machine never stops sending data, despite the fact that I can verify with strace that only 3 bytes of data are ever written to the rfcomm device.
Can anyone shed some light on this?
Andy
HCIDump - HCI packet analyzer ver 1.5
device: hci0 snap_len: 1028 filter: 0xffffffff 1077057403.092894 < HCI Command: Create Connection(0x01|0x0005) plen 13
E3 58 E8 D9 0A 00 18 CC 01 00 00 00 01
1077057403.099367 > HCI Event: Command Status(0x0f) plen 4
00 01 05 04
1077057405.062120 > HCI Event: Connect Complete(0x03) plen 11
00 28 00 E3 58 E8 D9 0A 00 01 00
1077057405.062400 < ACL data: handle 0x0028 flags 0x02 dlen 12
L2CAP(s): Connect req: psm 3 scid 0x0040
1077057405.062413 < HCI Command: Write Link Policy Settings(0x02|0x000d) plen 4
28 00 0E 00
1077057405.070114 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057405.073116 > HCI Event: Command Complete(0x0e) plen 6
01 0D 08 00 28 00
1077057405.117115 > HCI Event: Max Slots Change(0x1b) plen 3
28 00 05
1077057406.027997 > ACL data: handle 0x0028 flags 0x02 dlen 16
L2CAP(s): Connect rsp: dcid 0x0048 scid 0x0040 result 1 status 2
1077057406.143983 > ACL data: handle 0x0028 flags 0x02 dlen 16
L2CAP(s): Connect rsp: dcid 0x0048 scid 0x0040 result 0 status 0
1077057406.144234 < ACL data: handle 0x0028 flags 0x02 dlen 16
L2CAP(s): Config req: dcid 0x0048 flags 0x0000 clen 4
MTU 1024
1077057406.151987 > ACL data: handle 0x0028 flags 0x02 dlen 12
L2CAP(s): Config req: dcid 0x0040 flags 0x0000 clen 0
1077057406.152978 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057406.152999 < ACL data: handle 0x0028 flags 0x02 dlen 14
L2CAP(s): Config rsp: scid 0x0048 flags 0x0000 result 0 clen 0
1077057406.159001 > ACL data: handle 0x0028 flags 0x02 dlen 18
L2CAP(s): Config rsp: scid 0x0040 flags 0x0000 result 0 clen 4
MTU 672
1077057406.159977 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057406.166292 < ACL data: handle 0x0028 flags 0x02 dlen 8
L2CAP(d): cid 0x48 len 4 [psm 3]
RFCOMM(s): SABM: cr 1 dlci 0 pf 1 ilen 0 fcs 0x1c
1077057406.174974 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057406.196974 > ACL data: handle 0x0028 flags 0x02 dlen 8
L2CAP(d): cid 0x40 len 4 [psm 3]
RFCOMM(s): UA: cr 1 dlci 0 pf 1 ilen 0 fcs 0xd7
1077057406.197056 < ACL data: handle 0x0028 flags 0x02 dlen 18
L2CAP(d): cid 0x48 len 14 [psm 3]
RFCOMM(s): PN CMD: cr 1 dlci 0 pf 0 ilen 10 fcs 0x70 mcc_len 8
dlci 10 frame_type 0 credit_flow 15 pri 7 ack_timer 0 frame_size 667 max_retrans 0 credits 71077057406.206978 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057406.234970 > ACL data: handle 0x0028 flags 0x02 dlen 17 1077057406.242968 > ACL data: handle 0x0028 flags 0x01 dlen 1
L2CAP(d): cid 0x40 len 14 [psm 3]
RFCOMM(s): PN RSP: cr 0 dlci 0 pf 0 ilen 10 fcs 0xaa mcc_len 8
dlci 10 frame_type 0 credit_flow 14 pri 7 ack_timer 0 frame_size 667 max_retrans 0 credits 3
1077057406.243029 < ACL data: handle 0x0028 flags 0x02 dlen 8
L2CAP(d): cid 0x48 len 4 [psm 3]
RFCOMM(s): SABM: cr 1 dlci 10 pf 1 ilen 0 fcs 0x8c
1077057406.247967 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057406.288964 > ACL data: handle 0x0028 flags 0x02 dlen 8
L2CAP(d): cid 0x40 len 4 [psm 3]
RFCOMM(s): UA: cr 1 dlci 10 pf 1 ilen 0 fcs 0x47
1077057406.289036 < ACL data: handle 0x0028 flags 0x02 dlen 12
L2CAP(d): cid 0x48 len 8 [psm 3]
RFCOMM(s): MSC CMD: cr 1 dlci 0 pf 0 ilen 4 fcs 0x70 mcc_len 2
dlci 10 fc 0 rtc 1 rtr 1 ic 0 dv 1 b1 1 b2 0 b3 0 len 0
1077057406.304962 > ACL data: handle 0x0028 flags 0x02 dlen 12
L2CAP(d): cid 0x40 len 8 [psm 3]
RFCOMM(s): MSC CMD: cr 0 dlci 0 pf 0 ilen 4 fcs 0xaa mcc_len 2
dlci 10 fc 0 rtc 1 rtr 1 ic 0 dv 1 b1 1 b2 0 b3 0 len 0
1077057406.305006 < ACL data: handle 0x0028 flags 0x02 dlen 12
L2CAP(d): cid 0x48 len 8 [psm 3]
RFCOMM(s): MSC RSP: cr 1 dlci 0 pf 0 ilen 4 fcs 0x70 mcc_len 2
dlci 10 fc 0 rtc 1 rtr 1 ic 0 dv 1 b1 1 b2 0 b3 0 len 0
1077057406.305958 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057406.310970 > ACL data: handle 0x0028 flags 0x02 dlen 12
L2CAP(d): cid 0x40 len 8 [psm 3]
RFCOMM(s): MSC RSP: cr 0 dlci 0 pf 0 ilen 4 fcs 0xaa mcc_len 2
dlci 10 fc 0 rtc 1 rtr 1 ic 0 dv 1 b1 1 b2 0 b3 0 len 0
1077057406.311016 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 1 ilen 0 fcs 0xac
21 1077057406.311957 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057406.316958 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
==========================================
= Connection is established, I now do a: =
= echo a > /dev/rfcomm1 =
==========================================
1077057417.282291 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
61
1077057417.282310 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
0D
1077057417.282315 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
0A 1077057417.291570 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057417.293572 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057417.295569 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057417.313579 > ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x40 len 5 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 10 pf 1 ilen 0 fcs 0x76
05
1077057417.320571 > ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x40 len 5 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 10 pf 0 ilen 1 fcs 0x6a
61
1077057417.320610 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
61
1077057417.324567 > ACL data: handle 0x0028 flags 0x02 dlen 10
L2CAP(d): cid 0x40 len 6 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 10 pf 1 ilen 1 fcs 0x76
01 0D
1077057417.324590 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
0D
1077057417.324595 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
0A
1077057417.327575 > ACL data: handle 0x0028 flags 0x02 dlen 10
L2CAP(d): cid 0x40 len 6 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 10 pf 1 ilen 1 fcs 0x76
01 0A 1077057417.328567 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057417.329579 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057417.331231 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
0D
1077057417.331245 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
0A 1077057417.331568 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057417.341570 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057417.341576 > ACL data: handle 0x0028 flags 0x02 dlen 10
L2CAP(d): cid 0x40 len 6 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 10 pf 1 ilen 1 fcs 0x76
02 61
1077057417.341623 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
61
1077057417.342566 > ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x40 len 5 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 10 pf 0 ilen 1 fcs 0x6a
0D
1077057417.342601 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
0D
1077057417.342607 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
0A 1077057417.346563 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057417.347567 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057417.349563 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057417.349583 > ACL data: handle 0x0028 flags 0x02 dlen 10
L2CAP(d): cid 0x40 len 6 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 10 pf 1 ilen 1 fcs 0x76
01 0A
1077057417.349616 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
0D
1077057417.349623 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
0A
1077057417.354561 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057417.354564 > ACL data: handle 0x0028 flags 0x02 dlen 10
L2CAP(d): cid 0x40 len 6 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 10 pf 1 ilen 1 fcs 0x76
01 0D
1077057417.354588 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
0D
1077057417.356562 > ACL data: handle 0x0028 flags 0x02 dlen 10
L2CAP(d): cid 0x40 len 6 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 10 pf 1 ilen 1 fcs 0x76
01 0A
1077057417.356585 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
0A 1077057417.357563 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057417.359562 > HCI Event: Number of Completed Packets(0x13) plen 5
01 28 00 01 00
1077057417.359565 > ACL data: handle 0x0028 flags 0x02 dlen 10
L2CAP(d): cid 0x40 len 6 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 10 pf 1 ilen 1 fcs 0x76
01 61
1077057417.359592 < ACL data: handle 0x0028 flags 0x02 dlen 9
L2CAP(d): cid 0x48 len 5 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 10 pf 0 ilen 1 fcs 0xb0
0D
===========================
= And so on, ad infinitum =
===========================Marcel Holtmann
maintainerHi Andy,
Quoted 12 lines
I'm having some trouble with the bluez implementation as distributed with fedora. I thought for a long time that this was a bug on the device (Ericsson P900 / Symbian 7.0) side of the connection, but it's now looking like a kernel issue on the linux box.
The app on the other side is a simple RFCOMM echoer. It reads a byte at a time and writes it back out to the socket. I'm connecting to it with a "cat
/dev/rfcomm1", while I do a "echo a >/dev/rfcomm1" from another shell. What comes back is an unending spew of bytes, mostly (but oddly not entirely) derived from the "a\r\n" that went out the terminal initially.
Quoted 4 lines
FWIW, I see almost identical behavior when connecting to the "modem" device on the phone. The AT command work (in the sense that I can see the desired output appear on the socket), but come back as part of an infinite garbage stream.
set the RFCOMM terminal device into raw mode and everything works fine.
Regards
Marcel
-------------------------------------------------------
SF.Net is sponsored by: Speed Start Your Linux Apps Now. Build and deploy apps & Web services for Linux with a free DVD software kit from IBM. Click Now!
http://ads.osdn.com/?ad_id=1356&alloc_id=3438&op=click
_______________________________________________
Bluez-devel mailing list [email protected]
https://lists.sourceforge.net/lists/listinfo/bluez-devel
Quoted 2 lines · Marcel Holtmann
set the RFCOMM terminal device into raw mode and everything works fine.
Duh, dunno why I didn't try that. A simple stty -cooked indeed fixes the problem.
That said: isn't this still a bug? Serial ports don't behave this way by default, and an rfcomm device is supposed to look like an RS232 device. Certainly a hardware tty *can* be made to echo to the remote device, but that's the job of programs like getty to set up properly. Something seems backwards here, is there a reason for making /dev/rfcomm* work differently from /dev/ttyS*?
Andy
-------------------------------------------------------
SF.Net is sponsored by: Speed Start Your Linux Apps Now. Build and deploy apps & Web services for Linux with a free DVD software kit from IBM. Click Now!
http://ads.osdn.com/?ad_id=1356&alloc_id=3438&op=click
_______________________________________________
Bluez-devel mailing list [email protected]
https://lists.sourceforge.net/lists/listinfo/bluez-devel
Marcel Holtmann
maintainerHi Andy,
Quoted 9 lines
Duh, dunno why I didn't try that. A simple stty -cooked indeed fixes the problem.
That said: isn't this still a bug? Serial ports don't behave this way by default, and an rfcomm device is supposed to look like an RS232 device. Certainly a hardware tty *can* be made to echo to the remote device, but that's the job of programs like getty to set up properly. Something seems backwards here, is there a reason for making
/dev/rfcomm*work differently from/dev/ttyS*?
the question is what should be default? This is application specific and so the kernel can't (and shouldn't) do anything about it.
Regards
Marcel
-------------------------------------------------------
SF.Net is sponsored by: Speed Start Your Linux Apps Now. Build and deploy apps & Web services for Linux with a free DVD software kit from IBM. Click Now!
http://ads.osdn.com/?ad_id=1356&alloc_id=3438&op=click
_______________________________________________
Bluez-devel mailing list [email protected]
https://lists.sourceforge.net/lists/listinfo/bluez-devel
Quoted 2 lines · Marcel Holtmann
the question is what should be default? This is application specific and so the kernel can't (and shouldn't) do anything about it.
I don't follow. The initialization state for a tty device is obviously set by the kernel, not an application. I'm simply saying that the kernel should initialize rfcomm devices to a state that matches RS232 devices, since that is what the user expects.
It's just a principle of least surprise argument. I mean, the rfcomm module *could* do anything by default. But some choices make more sense than others.
Andy
-------------------------------------------------------
SF.Net is sponsored by: Speed Start Your Linux Apps Now. Build and deploy apps & Web services for Linux with a free DVD software kit from IBM. Click Now!
http://ads.osdn.com/?ad_id=1356&alloc_id=3438&op=click
_______________________________________________
Bluez-devel mailing list [email protected]
https://lists.sourceforge.net/lists/listinfo/bluez-devel
Marcel Holtmann
maintainerHi Andy,
Quoted 8 lines
I don't follow. The initialization state for a tty device is obviously set by the kernel, not an application. I'm simply saying that the kernel should initialize rfcomm devices to a state that matches RS232 devices, since that is what the user expects.
It's just a principle of least surprise argument. I mean, the rfcomm module *could* do anything by default. But some choices make more sense than others.
the RFCOMM module inits the TTY the same as the serial driver does. You can compare it by yourself. Look at drivers/serial/serial_core.c and at net/bluetooth/rfcomm/tty.c and you will see that the init is the same.
If I missed anything I am happy to change it.
Regards
Marcel
-------------------------------------------------------
SF.Net is sponsored by: Speed Start Your Linux Apps Now. Build and deploy apps & Web services for Linux with a free DVD software kit from IBM. Click Now!
http://ads.osdn.com/?ad_id=1356&alloc_id=3438&op=click
_______________________________________________
Bluez-devel mailing list [email protected]
https://lists.sourceforge.net/lists/listinfo/bluez-devel