Hi all,
While debugging an application that concurrently pushes files to
close remote devices, hcidump (git HEAD - v1.42) erroneously
parses obex packets sent to and received from certain mobiles.
Details and a verbose backtrace using "-ggdb" follows.
At first, hcidump rightfully parses the OBEX "connect" packet and
its response:
2009-07-01 13:46:10.016580 < ACL data: handle 42 flags 0x02 dlen 15
L2CAP(d): cid 0x0040 len 11 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 12 pf 0 ilen 7 fcs 0x4f
OBEX: Connect cmd(f): len 7 version 1.0 flags 0 mtu 32767
...
2009-07-01 13:46:10.075331 > ACL data: handle 42 flags 0x02 dlen 16
L2CAP(d): cid 0x0041 len 12 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 12 pf 1 ilen 7 fcs 0x89 credits 1
OBEX: Connect rsp(f): status 200 len 7 version 1.0 flags 0 mtu 4096
Status 200 = Success
It also parses the first PUT packet (final bit not set) and its
headers nicely:
2009-07-01 13:46:10.204197 < ACL data: handle 42 flags 0x02 dlen 76
L2CAP(d): cid 0x0040 len 72 [psm 3]
RFCOMM(d): UIH: cr 1 dlci 12 pf 0 ilen 68 fcs 0x4f
OBEX: Put cmd(c): len 4096
Name (0x01) = Unicode length 12
0000: 00 31 00 2e 00 6a 00 70 00 67 00 00 .1...j.p.g..
Length (0xc3) = 863062
Body (0x48) = Sequence length 4070
0000: ff d8 ff e0 00 10 4a 46 49 46 00 01 02 01 00 48 ......JFIF.....H
....
After this packet, it seems hcidump didn't recognize that subsequent
packets are normal OBEX packets passing through RFCOMM:
2009-07-01 13:46:27.759807 > ACL data: handle 42 flags 0x02 dlen 12
L2CAP(d): cid 0x0041 len 8 [psm 0]
0000: 31 ff 07 05 90 00 03 89 1.......
As you see "90 00 03" is the OBEX response packet of "Continue"/0x90
with a size of 0x0003 bytes. the rest is possibly related to rfcomm
which I'm not familiar with yet.
In subsequent PUT packets, similar erroneous behaviour occurs:
2009-07-01 13:46:27.808222 < ACL data: handle 42 flags 0x01 dlen 86
L2CAP(d): cid 0x0040 len 1012 [psm 0]
0000: 33 ef de 07 02 10 00 48 0f fd 0d c4 a6 c7 6e 05 3......H......n.
0010: e6 41 2e 6e d2 c2 df 4a bf 76 cf d2 26 95 e3 62 .A.n...J.v..&..b
....
Above data "02 10 00 48 0f fd .." was an OBEX "Put"/0x02 with a size
of 0x1000 and a "Body"/0x48 header followed by body contents of size
0x0fffd. "0x0d c4 .." is a part of the pushed file content.
I've noticed that in all cases of unrecognized OBEX PUT packets _sent_
to the remote device, the packet get encapsulated by the four bytes
"33 ef (de|89) (07|71)" at the start and "4f" at the end. Sometimes
the _single_ OBEX packet get sent in several smaller chunks encapsulated
inside those bytes. I'm quite positive those are related to rfcomm.
In the other cases of OBEX responses _received_ from the remote device,
the packet always get encapsulated between the sequence
"31 ff 07 05" and the byte "89". So I constantly see the sequence
0000: 31 ff 07 05 90 00 03 89 1.......
due to the several OBEX "Continue" responses to the non-final PUT
requests packets.
At first I thought this behaviour might be related to the bug I'm
tracing, but the sent file was nicely received by the remote device
and the transfer continued till the last OBEX packet.
Ironically, hcidump recognized the last OBEX packet received from
the device which was a response to a "Disconnect" request sent
following the successful PUT operation:
/* Not recognized OBEX Disconnect (0x81) of size 3 bytes (0x0003) */
2009-07-01 13:47:12.250213 < ACL data: handle 42 flags 0x02 dlen 11
L2CAP(d): cid 0x0040 len 7 [psm 0]
0000: 33 ef 07 81 00 03 4f 3.....O
/* The response is perceived as a response to the first _recognized_
* OBEX "Put". It's actually for the above "Disconnect" request. */
2009-07-01 13:47:12.296699 > ACL data: handle 42 flags 0x02 dlen 12
L2CAP(d): cid 0x0041 len 8 [psm 3]
RFCOMM(d): UIH: cr 0 dlci 12 pf 1 ilen 3 fcs 0x89 credits 1
OBEX: Put rsp(f): status 200 len 3
Given above details, we can say that hcidump only recognized the
first and the last OBEX packet. It's also clear that hcidump didn't
recognize the rfcomm overhead itself where the obex packets are
encapsulated.
Any ideas about the possible cause? I'm not comfortable yet with l2cap
and rfcomm binary dumps to be able to judge. Thanks
----
On a possibly related behaviour, while reading ("-r") the same binary
dump, hcidump crashed by below segfault. The binary dump can be sent
privately if requested. It's 15 MB in size and the fault is reproducable:
$ gdb /usr/local/sbin/hcidump -c core
...
Core was generated by `/usr/local/sbin/hcidump -XV --timestamp -r binary-dump'.
Program terminated with signal 11, Segmentation fault.
[New process 11962]
#0 0xb8088b23 in ext_dump (level=3, frm=0xb80ae0a8, num=30716) at parser.c:309
309 printf("%02x%s", buf[i], (i + 1) % 8 ? " " : " ");
(gdb) bt
#0 0xb8088b23 in ext_dump (level=3, frm=0xb80ae0a8, num=30716) at parser.c:309
#1 0xb8088cbc in raw_ndump (level=3, frm=0xb80ae0a8, num=63740) at parser.c:338
#2 0xb8099c70 in parse_headers (level=3, frm=0xb80ae0a8) at obex.c:213
#3 0xb809a2c8 in obex_dump (level=3, frm=0xb80ae0a8) at obex.c:307
#4 0xb809523d in uih_frame (level=2, frm=0xb80ae4f4, head=0xbfe94898) at rfcomm.c:278
#5 0xb8094f8d in rfcomm_dump (level=2, frm=0xb80ae4f4) at rfcomm.c:325
#6 0xb8092596 in l2cap_parse (level=2, frm=0xb80ae4f4) at l2cap.c:828
#7 0xb8093282 in l2cap_dump (level=1, frm=0xbfe949e4) at l2cap.c:960
#8 0xb8090888 in acl_dump (level=1, frm=0xbfe949e4) at hci.c:3226
#9 0xb808924b in hci_dump (level=0, frm=0xbfe949e4) at hci.c:3302
#10 0xb8085c09 in parse (frm=0xbfe949e4) at ../parser/parser.h:248
#11 0xb808619c in read_dump (fd=3) at hcidump.c:465
#12 0xb8087b1a in main (argc=0, argv=0xbfe94b78) at hcidump.c:1152
(gdb)
Regards
--
Ahmed S. Darwish
Homepage: http://darwish.07.googlepages.com