search

michelcandido / btstack

Automatically exported from code.google.com/p/btstack
0 stars 0 forks source link

H4 - SDP discover fails when record >=277 bytes #197

Closed GoogleCodeExporter closed 8 years ago

GoogleCodeExporter commented 8 years ago 
Looks like the discovery process fails if the SPD record is larger than 277 
bytes.

Log below show a 'used size 310' which might be significant. This was working 
back in may, when I created the octopud example, but if failing now with same 
code base.
--
simon@womble:~/btstack-git-svn$ sudo src/BTdaemon 
BTdaemon started
config.h: HAVE_RFCOMM
Socket created at /tmp/BTstack
Server up and running ...
socket_connection_accept new connection 5
Nr Connections changed, new 1
hci_power_control: 1, current mode 0
New state: 1
Bluetooth status: 1
hci_read_buffer_size: used size 310, count 10, packet types 7f18
New state: 2
Bluetooth status: 2
SDP_REGISTER_SERVICE_RECORD size 277
Connection_incoming: 00:26:e2:ed:91:01, type 1
sending hci_accept_connection_request
Connection_complete (status=0) 00:26:e2:ed:91:01
New connection: handle 42, 00:26:e2:ed:91:01
New nr connections: 1
Bluetooth status: 3
signaling handler code 4, state 6
signaling handler code 5, state 6
signaling handler code 6, state 7
Connection closed: handle 42, 00:26:e2:ed:91:01
New nr connections: 0
Bluetooth status: 2
--

Original issue reported on code.google.com by mungew...@gmail.com on 29 Sep 2011 at 5:10

GoogleCodeExporter commented 8 years ago 
hi. if possible, please use the hci_dump facitlity to create hcidump or 
packetlogger logs. They contain all information.

I've recently rewritten (also) the SDP part to use 52 Bytes ACL packets in a 
minimal configuration. SDP can serve snippets of large records. 

If I remember correctly the SDP record for WeBe++ is on a similar size, I can 
double check that.

Original comment by matthias.ringwald@gmail.com on 29 Sep 2011 at 7:10

GoogleCodeExporter commented 8 years ago 
running my code as
--
simon@womble:~/btstack-git-svn$ sudo ./example/octopud 
HCI_STATE_WORKING
RFCOMM channel 1 was assigned to OctoPud1 by BTdaemon
RFCOMM_EVENT_SERVICE_REGISTERED
RFCOMM channel 2 was assigned to OctoPud2 by BTdaemon
RFCOMM_EVENT_SERVICE_REGISTERED
RFCOMM channel 3 was assigned to OctoPud3 by BTdaemon
RFCOMM_EVENT_SERVICE_REGISTERED
RFCOMM channel 4 was assigned to OctoPud4 by BTdaemon
RFCOMM_EVENT_SERVICE_REGISTERED
Using PIN 0000
^Csimon@womble:~/btstack-git-svn$
--

BTstack fails as
--
simon@womble:~/btstack-git-svn$ sudo ./src/BTdaemon 
BTdaemon started
config.h: HAVE_RFCOMM
Socket created at /tmp/BTstack
Server up and running ...
socket_connection_accept new connection 5
Nr Connections changed, new 1
hci_power_control: 1, current mode 0
New state: 1
Bluetooth status: 1
hci_read_buffer_size: used size 310, count 10, packet types 7f18
New state: 2
Bluetooth status: 2
SDP_REGISTER_SERVICE_RECORD size 290
SDP_REGISTER_SERVICE_RECORD size 290
SDP_REGISTER_SERVICE_RECORD size 290
SDP_REGISTER_SERVICE_RECORD size 290
Connection_incoming: 00:26:e2:ed:91:01, type 1
sending hci_accept_connection_request
Connection_complete (status=0) 00:26:e2:ed:91:01
New connection: handle 42, 00:26:e2:ed:91:01
New nr connections: 1
Bluetooth status: 3
signaling handler code 4, state 6
signaling handler code 5, state 6
signaling handler code 6, state 7
simon@womble:~/btstack-git-svn$
--

Client device (LG Expo) hangs/timeouts when probing for services.

Original comment by mungew...@gmail.com on 30 Sep 2011 at 2:42

Attachments:

GoogleCodeExporter commented 8 years ago 
working example with only 1 rfcomm port enabled and a smaller SDP record.
--
simon@womble:~/btstack-git-svn$ sudo ./src/BTdaemon 
BTdaemon started
config.h: HAVE_RFCOMM
Socket created at /tmp/BTstack
Server up and running ...
socket_connection_accept new connection 5
Nr Connections changed, new 1
hci_power_control: 1, current mode 0
New state: 1
Bluetooth status: 1
hci_read_buffer_size: used size 310, count 10, packet types 7f18
New state: 2
Bluetooth status: 2
SDP_REGISTER_SERVICE_RECORD size 147
Connection_incoming: 00:26:e2:ed:91:01, type 1
sending hci_accept_connection_request
Connection_complete (status=0) 00:26:e2:ed:91:01
New connection: handle 42, 00:26:e2:ed:91:01
New nr connections: 1
Bluetooth status: 3
signaling handler code 4, state 6
signaling handler code 5, state 6
signaling handler code 6, state 7
Connection closed: handle 42, 00:26:e2:ed:91:01
New nr connections: 0
Bluetooth status: 2
Connection_incoming: 00:26:e2:ed:91:01, type 1
sending hci_accept_connection_request
Connection_complete (status=0) 00:26:e2:ed:91:01
New connection: handle 43, 00:26:e2:ed:91:01
New nr connections: 1
Bluetooth status: 3
signaling handler code 4, state 6
signaling handler code 5, state 6
signaling handler code 6, state 7
rfcomm_max_frame_size_for_l2cap_mtu:  306 -> 300
L2CAP_EVENT_INCOMING_CONNECTION (l2cap_cid 0x42) for PSM_RFCOMM => 
acceptsignaling handler code 4, state 6
signaling handler code 5, state 6
L2CAP_EVENT_CHANNEL_OPENED for PSM_RFCOMM
rfcomm_max_frame_size_for_l2cap_mtu:  306 -> 300
Received SABM #0
Sending UA #0
Multiplexer up and running
Received UIH Parameter Negotiation Command for #2
rfcomm_channel_create for service 0x855b508, channel 1 --- begin
-> Inform app
Received Accept Connction
Sending UIH Parameter Negotiation Respond for #2
Received SABM #2
Sending UA #2
Received MSC CMD for #2, 
Sending MSC CMD for #2
Sending MSC RSP for #2
Providing credits for #2
Received MSC RSP for #2
rfcomm_channel_opened!
Sending UA after DISC for #2
Received DISC #0, (ougoing = 0)
Sending UA #0
Closing down multiplexer
signaling handler code 6, state 8
Connection closed: handle 43, 00:26:e2:ed:91:01
New nr connections: 0
Bluetooth status: 2
Nr Connections changed, new 0
No active client connection for 10 seconds -> POWER OFF
hci_power_control: 0, current mode 2
New state: 3
Bluetooth status: 1
HCI_STATE_HALTING
HCI_STATE_HALTING, calling off
hci_power_control_off
hci_power_control_off - hci_transport closed
hci_power_control_off - control closed
HCI_STATE_HALTING, emitting state
New state: 0
Bluetooth status: 1
HCI_STATE_HALTING, done
--

Original comment by mungew...@gmail.com on 30 Sep 2011 at 2:56

Attachments:

GoogleCodeExporter commented 8 years ago 
hi. thanks for the logs. I don't see an error here, so far. The SDP record 
itself seems to be complete. With ACL Buffer size of 310 the 303 bytes packet 
should be fine.

Could you run hcidump on the linux side, too, and rerun the version with the 
large SDP record. I'm wondering if somehow the record doesn't get received in 
full. (and attach the logs from both sides)

Original comment by matthias.ringwald@gmail.com on 8 Oct 2011 at 5:14

GoogleCodeExporter commented 8 years ago 
I seem to be seeing a segfault at present when doing a SDP browse from a remote 
machine to BTstack running my octopud example.

This occurs immediately if I have a large SDP record, or multiple records 
(rfcomm ports). This can also occur with a single/small record on the second 
browse, providing BTstack enters 'idle' - as indicated with "Bluetooth status: 
2".

The segfault appears to be corrupt pointer being processed by the HCI layer.
--
Starting program: /home/simon/btstack-git-svn/src/BTdaemon 
BTdaemon started
config.h: HAVE_RFCOMM
Socket created at /tmp/BTstack
Server up and running ...
socket_connection_accept new connection 7
Nr Connections changed, new 1
hci_power_control: 1, current mode 0
New state: 1
Bluetooth status: 1
hci_read_buffer_size: used size 310, count 10, packet types 7f18
New state: 2
Bluetooth status: 2
SDP_REGISTER_SERVICE_RECORD size 147
Connection_incoming: 00:0f:b3:99:6b:cc, type 1
sending hci_accept_connection_request
Connection_complete (status=0) 00:0f:b3:99:6b:cc
New connection: handle 42, 00:0f:b3:99:6b:cc
New nr connections: 1
Bluetooth status: 3
signaling handler code 4, state 6
signaling handler code 5, state 6
signaling handler code 6, state 7
Connection closed: handle 42, 00:0f:b3:99:6b:cc
New nr connections: 0
Bluetooth status: 2
Connection_incoming: 00:0f:b3:99:6b:cc, type 1
sending hci_accept_connection_request
Connection_complete (status=0) 00:0f:b3:99:6b:cc
New connection: handle 43, 00:0f:b3:99:6b:cc
New nr connections: 1
Bluetooth status: 3
signaling handler code 4, state 6
signaling handler code 5, state 6
signaling handler code 6, state 7

Program received signal SIGSEGV, Segmentation fault.
0x0804fe28 in l2cap_run () at l2cap.c:342
342         switch (channel->state){
(gdb) p *channel
Cannot access memory at address 0x480
(gdb)
--

Original comment by mungew...@gmail.com on 11 Oct 2011 at 4:25

Attachments:

GoogleCodeExporter commented 8 years ago 
I might have a lead on this... browsing from my phone onto BlueGiga WT41 on 
serial port it reports a 'remote_mtu' of 512 and this functions up to (maximum) 
8 records.

However when browsing with PC the 'remote_mtu' is 1024. If I have more that 2 
records I'm getting segfaults, caused by memory corruption.

Where does BTstack determine the MTU of the local hardware, and specify it for 
it's local buffers?
Simon

Original comment by mungew...@gmail.com on 14 Oct 2011 at 1:18

GoogleCodeExporter commented 8 years ago 
yes, SDP server is writing out of scope of the SDP record and corrupting other 
variables which it should not touch.

This is triggered by browsing from a Win7 PC, but not from phone.

'defered_list' is the linked list I am using for storing delay packets. It is 
nominally NULL.

--
Breakpoint 2, spd_append_range (context=0xbfffefbc, len=2, data=0x805b3a1 
"\b\377\t") at sdp_util.c:362
362     memcpy(context->buffer, &data[context->startOffset], remainder_len);
(gdb) p *context
$11 = {buffer = 0x805a7f3 "", startOffset = 0, maxBytes = 93, usedBytes = 86, 
attributeIDList = 0x805a595 "5\005\n", 
  complete = 1}
(gdb) c
Continuing.

Breakpoint 2, spd_append_range (context=0xbfffefbc, len=3, data=0xbfffef2d 
"\t") at sdp_util.c:362
362     memcpy(context->buffer, &data[context->startOffset], remainder_len);
(gdb) c
Continuing.

Breakpoint 2, spd_append_range (context=0xbfffefbc, len=12, data=0x805b3a6 "6") 
at sdp_util.c:362
362     memcpy(context->buffer, &data[context->startOffset], remainder_len);
(gdb) p *context
$12 = {buffer = 0x805a7f8 "\001", startOffset = 0, maxBytes = 88, usedBytes = 
91, attributeIDList = 0x805a595 "5\005\n", 
  complete = 1}
(gdb) c
Continuing.
Hardware watchpoint 1: defered_list

Old value = (linked_list_t) 0x0
New value = (linked_list_t) 0x10901
0xb7ee25e3 in ?? () from /lib/i386-linux-gnu/libc.so.6
(gdb) p *defered_list
Cannot access memory at address 0x10901
(gdb) p &defered_list
$13 = (linked_list_t *) 0x805a800
(gdb) bt
#0  0xb7ee25e3 in ?? () from /lib/i386-linux-gnu/libc.so.6
#1  0x0804a585 in spd_append_range (context=0xbfffefbc, len=12, data=0x805b3a6 
"6") at sdp_util.c:362
#2  0x0804a6e0 in sdp_traversal_filter_attributes (attributeID=9, 
attributeValue=0x805b3a6 "6", type=DE_DES, 
    size=DE_SIZE_VAR_16, my_context=0xbfffefbc) at sdp_util.c:399
#3  0x0804a273 in sdp_attribute_list_traverse_sequence (element=0x805b348 "6", 
    handler=0x804a5cb <sdp_traversal_filter_attributes>, context=0xbfffefbc) at sdp_util.c:259
#4  0x0804a758 in sdp_filter_attributes_in_attributeIDList (record=0x805b348 
"6", attributeIDList=0x805a595 "5\005\n", 
    startOffset=0, maxBytes=179, usedBytes=0xbffff036, buffer=0x805a79d "\t") at sdp_util.c:417
#5  0x08055d60 in sdp_handle_service_search_attribute_request (packet=0x805a589 
"\006", remote_mtu=200) at sdp.c:522
#6  0x08055fd0 in sdp_packet_handler (packet_type=6 '\006', channel=64, 
packet=0x805a589 "\006", size=20) at sdp.c:600
#7  0x0804f384 in l2cap_dispatch (channel=0x805d420, type=6 '\006', 
data=0x805a589 "\006", size=20) at l2cap.c:106
#8  0x080510b1 in l2cap_acl_handler (packet=0x805a581 "* \030", size=28) at 
l2cap.c:917
#9  0x080510fc in l2cap_packet_handler (packet_type=2 '\002', packet=0x805a581 
"* \030", size=28) at l2cap.c:927
#10 0x0804cbe4 in acl_handler (packet=0x805a581 "* \030", size=28) at hci.c:317
#11 0x0804d5fa in packet_handler (packet_type=2 '\002', packet=0x805a581 "* 
\030", size=28) at hci.c:616
#12 0x0804efc6 in h4_deliver_packet () at hci_transport_h4.c:228
#13 0x0804f0d9 in h4_statemachine () at hci_transport_h4.c:263
#14 0x0804f160 in h4_process (ds=0x805d060) at hci_transport_h4.c:293
#15 0x08049844 in posix_execute () at run_loop_posix.c:166
#16 0x080494ed in run_loop_execute () at run_loop.c:114
#17 0x08056e5b in main (argc=1, argv=0xbffff3e4) at ../example/octopud.c:570

Original comment by mungew...@gmail.com on 14 Oct 2011 at 4:03

GoogleCodeExporter commented 8 years ago

Original comment by matthias.ringwald@gmail.com on 16 Mar 2012 at 11:24