Compatibility issues with Android 4.3

[GoogleCodeExporter]

What steps will reproduce the problem?
1. Use MSP-EXP430F5438 and PAN1323ETU (TI CC2564)
2. Follow instructions to compile BTstack for MSP430 
(http://code.google.com/p/btstack/wiki/MSP430GettingStarted). This will require 
patching of MSP-EXP430F5438-CC256x\example\Makefile to compile & link against 
bluetooth_init_cc2564_2.10.c
3. run spp_counter example
4. Try to pair from Galaxy Nexus with Android 4.3 
5. Try to list services using BluetoothDevice.getUuids()

Expected result:
The pairing finishes successfully. BluetoothDevice.getUuids() returns one item 
in the list (SPP).

Tested and works with: Android 4.0.4 (Xperia Arc S) and Android 4.1.2 (Galaxy 
Note II)

Obtained result:
The pairing is slow and takes up to 10 seconds. BluetoothDevice.getUuids() 
returns an empty list.

BTstack version:
SVN rev. 1839

Host device:
Model: Galaxy Nexus
Android version: 4.3
Kernel: 3.0.72-gfb3c9ac android-build@vpbs1.mtv.corp.google.com #1 Fri Jun 7 
12:00:19 PDT 2013
Build: JWR66Y
Comm. module firmware: I9250XXLJ1

Original issue reported on code.google.com by muzaf...@mahkamov.com on 29 Aug 2013 at 8:12

[GoogleCodeExporter]

If you call BluetoothDevice.getUuids() during the pairing then it returns the 
expected result. However, after the pairing completes 
BluetoothDevice.getUuids() returns null.

Original comment by muzaf...@mahkamov.com on 29 Aug 2013 at 8:14

[GoogleCodeExporter]

Could it be that the bug for this is actually in Android 4.3? :)

I've recently tried to send files from an Nexus 7 (1st gen) 4.3 to my Mac and 
the pairing also took very long.

How can I reproduce this (the call to Bluetooth.getUuids() after the pairing 
completed) given that I know Java and  have an Nexus 7 4.3 but never wrote a 
single line of Android code (yet..)?

Original comment by matthias.ringwald@gmail.com on 29 Aug 2013 at 8:58

[GoogleCodeExporter]

> Could it be that the bug for this is actually in Android 4.3? :)

Well, it could be. I've seen a few bug reports on the Bluetooth stack of 
Android 4.3.

However, the Bluetopia stack v1.3 on the same test platform (MSP430 + CC2564) 
does not experience this issue. It might be that Bluetopia is handling this 
exception.

> How can I reproduce this (the call to Bluetooth.getUuids() after the pairing 
completed) given that I know Java and  have an Nexus 7 4.3 but never wrote a 
single line of Android code (yet..)?

Sorry, haven't thought about that.
I'll post a sample Android project within an hour.

Original comment by muzaf...@mahkamov.com on 29 Aug 2013 at 9:14

[GoogleCodeExporter]

That's a good bait: if Bluetopia can handle it, BTstack should be, too.
Thanks for posting a test project.

Original comment by matthias.ringwald@gmail.com on 29 Aug 2013 at 9:18

• Changed state: Accepted

[GoogleCodeExporter]

To quickly reproduce the issue on your side you can use BlueTerm app which is 
available on the Play Market: 
https://play.google.com/store/apps/details?id=es.pymasde.blueterm

The app connects to the device over SPP - so if it works, then 
BluetoothDevice.getUuids() is working. 

Original comment by muzaf...@mahkamov.com on 29 Aug 2013 at 9:26

[GoogleCodeExporter]

By the way, the issue could not be reproduced on Nexus 7 with Android 4.2.2.

Original comment by muzaf...@mahkamov.com on 29 Aug 2013 at 10:05

[GoogleCodeExporter]

Sorry, it took longer than expected to prepare a decent sample.

Please find attached the source code and the APK for the v1.0 of the sample.

It simply lists all the available Bluetooth devices and allows you to query the 
list of exported services by tapping on a paired device. If the device is 
unpaired you'll need to pair it in the Android OS settings first.

When you tap on a paired device a new activity with the cached list of services 
will be displayed. Those services are obtained using BluetoothDevice.getUuids() 
- the list is cached by Android. If you tap on the "Refresh" button then the 
app will query for the service list using SDP.

Let me know if you need more data.

Original comment by muzaf...@mahkamov.com on 29 Aug 2013 at 2:07

Attachments:

• BlueTest_1.0.7z
• BlueTest_1.0.apk

[GoogleCodeExporter]

Please find attached the signed version of the APK. You'll still need to enable 
the "Unknown sources" option.

Let me know if you still have problems installing it.

Original comment by muzaf...@mahkamov.com on 30 Aug 2013 at 8:44

Attachments:

• bluetest_1_0_signed.apk

[GoogleCodeExporter]

Thanks, that version installs and runs.

Original comment by matthias.ringwald@gmail.com on 30 Aug 2013 at 9:10

[GoogleCodeExporter]

Ok. It's working (I just had to figure out that it only works for paired 
devices).
I was still on 4.2.2, so I've updated the (old) Nexus 7 to 4.3

On 4.3, I first removed the pairing and paired again (which was reasonably fast)
Then, I ran bluetest again. I tap on "BlueMSP-Demo" and it shows a single 
serial port. Tapping on Refresh initiates a new SDP query which again returns a 
single serial port.

This was against example/libusb/spp_counter.c (I just added it to the SVN this 
morning)

I'll try withspp_counter on MSP430 next, but I don't expect any differences 
here.

Original comment by matthias.ringwald@gmail.com on 30 Aug 2013 at 9:47

[GoogleCodeExporter]

Same result with SPP Counter from SVN on MSP430 (compiled from SVN). After 
unpairing and pairing in Bluetooth Settings, I can start Bluetest and get the 
SerialPort both on entering the view as well as on "refresh".

Did you reboot the MSP430 before running the BlueTest? If yes, the link key 
will get lost (it's store in RAM as providing a generic persistent storage is 
not possible)

Original comment by matthias.ringwald@gmail.com on 30 Aug 2013 at 10:10

[GoogleCodeExporter]

>Same result with SPP Counter from SVN on MSP430 (compiled from SVN). After 
unpairing
>and pairing in Bluetooth Settings, I can start Bluetest and get the SerialPort 
both 
>on entering the view as well as on "refresh".

Let me update from the SVN and try again

> Did you reboot the MSP430 before running the BlueTest? If yes, the link key 
will 
> get lost (it's store in RAM as providing a generic persistent storage is not 
possible)

Yes, I did reboot. I also unpaired and paired the device several times with the 
same result, unfortunately.

I'm starting to think that there might be a problem with the init script of 
CC2564. I assume you're testing on CC2560.

Original comment by muzaf...@mahkamov.com on 30 Aug 2013 at 11:27

[GoogleCodeExporter]

[deleted comment]

[GoogleCodeExporter]

[deleted comment]

[GoogleCodeExporter]

Please try to unpair, reset MSP430, pair with Android, then start BlueTest 
without resetting the MSP430. If you do a reset, it will forget the link key as 
it is not stored in Flash memory.

The init scripts shouldn't be relevant for this. The libusb example was using a 
stock USB Bluetooth dongle, the MSP430 did use the CC2560 init script. You may 
try that too, but I really don't expect a difference in that (CC2560 = 
Bluetooth 2.1+EDR, CC2564 = Bluetooth 2.1 + EDR + LE). If it fails with CC2564 
init script but not CC2560 that would also be a very interesting detail. 

Original comment by matthias.ringwald@gmail.com on 30 Aug 2013 at 12:00

[GoogleCodeExporter]

> Please try to unpair, reset MSP430, pair with Android, then start BlueTest 
without 
> resetting the MSP430. If you do a reset, it will forget the link key as it is 
not 
> stored in Flash memory.

Tried again - didn't help :(

> The init scripts shouldn't be relevant for this

I've tried using bluetooth_init_cc2564_2.10.bts and 
bluetooth_init_cc2560A_2.8.bts - both with the same result.

I'll try to enable the BTstack logs and see if there's anything useful there.

Original comment by muzaf...@mahkamov.com on 30 Aug 2013 at 12:21

[GoogleCodeExporter]

Please find attached the BTstack logs.

L1. hci_transport_h4_dma.log - We tried to use the HCI transport without 
EHCILL. It doesn't work at all with CC2564.

L2. hci_transport_h4_ehcill_dma_Android_4.3.log - Logs with Android 4.3. 
Starting from line 30 there's pairing going on. After line 123 the 
communication stops completely. Pressing "refresh" in BlueTest (i.e. sending an 
SDP query) doesn't produce any further logs.

L3. hci_transport_h4_ehcill_dma_Android_4.0.4 - Logs with Android 4.0.4. 
Starting from line 30 there's pairing going on. We did not press "refresh" here 
so that you can compare with L2.

L4. hci_transport_h4_ehcill_dma_Android_4.0.4 - Logs with Android 4.0.4. 
Starting from line 30 there's pairing going on. After line 124 we pressed 
"Refresh" and the device received the SDP query.

If you diff L2 with L3 you can see some extra L2CAP events.

Original comment by muzaf...@mahkamov.com on 30 Aug 2013 at 1:04

Attachments:

• btstack_logs_2013-08-30.7z

[GoogleCodeExporter]

Thanks for the tests.

In l1. The eHCILL isn't disabled. The CC256x send a packet indentifier 0x30 to 
indicate that it went to sleep
What we don't see in the logs is the actual SDP communication. Is it possible 
to get complete logs on the Android side e.g. in hci_dump format? (it can be 
opened in Wireshark)?

And/or: could you try to compile example/libusb/spp_counter.c on a Mac or Linux 
system. It assumes that libusb v1.x is installed somewhere. The main benefit 
would be that it produces full packet logs.

Debugging Bluetooth on an embedded system, without a nice packet log, is very 
tedious. Full packet logs from Androidv side or from BTstack running on a PC 
would make it easier.

If that's really no option, you can add more debug output to src/sdp.c which 
handles SDP queries. 

Original comment by matthias.ringwald@gmail.com on 30 Aug 2013 at 1:22

[GoogleCodeExporter]

OK, I'll try to produce the packet logs and the debug logs on the SDP level.

Meanwhile, could you please send me the spp_counter.hex that you tested on the 
MSP430? I want to make sure that there are no configuration/build issues.

Original comment by muzaf...@mahkamov.com on 30 Aug 2013 at 2:08

[GoogleCodeExporter]

Here is the spp_counter.hex

Original comment by mila@ringwald.ch on 30 Aug 2013 at 2:27

Attachments:

• spp_counter.hex

[GoogleCodeExporter]

The issue can be replicated even with your version of spp_counter.hex...

Original comment by muzaf...@mahkamov.com on 30 Aug 2013 at 3:05

[GoogleCodeExporter]

Good test. In fact, I was expecting that. So, if we have almost the same 
hardware and the same software, maybe the Android device differs. I have the 
Nexus 7 which just updated today to 4.3. Do you have on of those, too? (Sorry, 
no better idea here)

Original comment by matthias.ringwald@gmail.com on 30 Aug 2013 at 3:17

[GoogleCodeExporter]

note.. while trying Secure Simple Pairing (which is mostly done), the 
spp_counter didn't work in the sense that I didn't receive data resp. RFCOMM is 
not working properly. (The BlueTest still shows the SerialPort). I'll look into 
that after finishing the SSP integration into the main stack (it's done in the 
app for testing)

Original comment by matthias.ringwald@gmail.com on 30 Aug 2013 at 3:20

[GoogleCodeExporter]

Please find attached the same logs with hci_dump to HCI_DUMP_STDOUT (serial 
port).

Some notable differences:
* There is a L2CAP_EVENT_TIMEOUT_CHECK entry in L2.
* There's only one L2CAP_EVENT_CHANNEL_OPENED in L3 - I think because there was 
no SDP refresh
* There are two L2CAP_EVENT_CHANNEL_OPENED events in L2 - note that there was 
no SDP refresh from BlueTest
* There are two L2CAP_EVENT_CHANNEL_OPENED events in L4 - because there was a 
SDP refresh from BlueTest

I'll add SDP logs next time.

Original comment by muzaf...@mahkamov.com on 30 Aug 2013 at 3:22

Attachments:

• btstack_logs_2013-08-30_hcidump.7z

[GoogleCodeExporter]

>  I have the Nexus 7 which just updated today to 4.3. Do you have on of those, 
too? (Sorry, no better idea here)

Yep, tested on Nexus 7 with Android 4.3 - the issue is there.

Original comment by muzaf...@mahkamov.com on 30 Aug 2013 at 3:27

[GoogleCodeExporter]

There's one more difference between L2 and L3:

* In L2 the "Pin code request" event happens before the "Connection_complete" 
and BTSTACK_EVENT_NR_CONNECTIONS_CHANGED events
* In L3 the "Pin code request" event happens after the "Connection_complete" 
and BTSTACK_EVENT_NR_CONNECTIONS_CHANGED events

Original comment by muzaf...@mahkamov.com on 30 Aug 2013 at 3:31

[GoogleCodeExporter]

Hi again.In the last log (hci_transport_h4_ehcill_dma_Android_4.3), the SDP 
channel is opened and closed three times. That's rather odd. Maybe Android is 
unhappy with what it gets and just tries again?

Could you a) disable eHCILL (to reduce log output), b) also log DATA packets to 
see the acutal queries for these test cases. I'll have a closer look at my 
local setup where ssp_counter doesn't work (pairing and SDP are correct, 
there's just no data received)

Original comment by matthias.ringwald@gmail.com on 1 Sep 2013 at 8:29

[GoogleCodeExporter]

> a) disable eHCILL (to reduce log output)

Could you please tell me how to do that? Simply undefining HAVE_EHCILL doesn't 
seem to disable it. Linking against hci_transport_h4_dma.c instead of 
hci_transport_h4_ehcill_dma.c produces the unhandled 0x30 event log.

> b) also log DATA packets to see the acutal queries for these test cases

OK, will do.

By the way, starting from SVN rev. 1841 we cannot build the MSP430 samples 
because the .data and .rodata sections do not fit into the firmware. Hence 
we're testing with rev. 1839.

Original comment by muzaf...@mahkamov.com on 2 Sep 2013 at 7:10

[GoogleCodeExporter]

Please find attached more detailed logs.

Compiled with:
#define ENABLE_LOG_DEBUG
#define ENABLE_LOG_INFO 
#define DUMP
#define ENABLE_LOG_ERROR

I also enabled some logs in sdp.c, you can see SDP packet dumps under "SDP 
Request" lines.

Original comment by muzaf...@mahkamov.com on 2 Sep 2013 at 10:54

Attachments:

• btstack_logs_2013-09-02_hcidump.7z

[GoogleCodeExporter]

eHCILL: to disable, use 0 in bt_control_cc256x_enable_ehcill(1) of spp_counter.c

Original comment by matthias.ringwald@gmail.com on 2 Sep 2013 at 11:36

[GoogleCodeExporter]

Attached are the logs with eHCILL disabled.

The bug cannot be reproduced in this case.

It looks like there's a timing issue.

Original comment by muzaf...@mahkamov.com on 2 Sep 2013 at 11:53

Attachments:

• btstack_logs_2013-09-02_hcidump_nohci.7z

[GoogleCodeExporter]

In L2 of btstack_logs_2013-09-02_hcidump.7z you can find the following lines:

RX: EHCILL_GO_TO_SLEEP_IND

L2CAP_EVENT_TIMEOUT_CHECK
EVT <= 73 02 01 00
L2CAP_EVENT_TIMEOUT_CHECK
EVT <= 73 02 01 00
Re-activate rx

RX: EHCILL_GO_TO_SLEEP_IND

There's a few second hiccup after the first EHCILL_GO_TO_SLEEP_IND and the 
"Re-activate rx" event. That happens during the pairing procedure after the PIN 
entry.

Original comment by muzaf...@mahkamov.com on 2 Sep 2013 at 12:01

[GoogleCodeExporter]

Interesting. The logs still lack the full ACL packets. Could you remove "if 
(len>5) len=8" in hci_transport_h4_ehcill_dma.c?

I've looked at both logs. In the 4.0, Android does a search for services with 
UUID 0100 - that's all services that built upon L2CAP incl. RFCOMM. In 4.3, 
there's first a request for services with UUID 1200 - that Device Information 
also called PnP Information. BTstack returns an empty response for that, and 
then Android asks for 0100 services. The response is 95 bytes, but that doesn't 
fit into the 52 byte packets, so Android should ask for the rest of it. This 
happens on 4.0, but not in the 4.3 logs, where Android just closes the 
connection.

L2CAP_EVENT_TIMEOUT_CHECK are basically irrelevant internal events, however 
they appear every 5 seconds (I think). If you get two in a row, the other side 
might as well face some timeouts. Could you also log the time in 
ehcill_send_packet and h4_process where the RX and TX dumps are please?

Original comment by matthias.ringwald@gmail.com on 2 Sep 2013 at 1:09

[GoogleCodeExporter]

I added the timestamps (using MSP430's RTC) - works OK

I removed "if (len>5) len=8" - it takes more time to dump the logs and the 
phone simply times out. I'll increase the USB serial port speed and see if it 
helps.

By the way, add the following to the example Makefile to avoid code size issues:
* add "-fdata-sections -ffunction-sections" to CFLAGS
* add "--no-keep-memory -Wl,-gc-sections" to LDFLAGS

I'll attach the logs as soon as I resolve the serial port speed issue.

Original comment by muzaf...@mahkamov.com on 2 Sep 2013 at 2:45

[GoogleCodeExporter]

Does it get stuck with timestamp, eHCILL and the short packet dump too? That 
might help already.
(I debugged and found the problem with Android 4.3, RFCOMM and libusb, but it 
was a detail in the libusb implementation which isn't present in your setup)

Original comment by matthias.ringwald@gmail.com on 2 Sep 2013 at 8:31

[GoogleCodeExporter]

> Does it get stuck with timestamp, eHCILL and the short packet dump too?

Yes, it gets stuck with Android 4.3

I'm attaching the logs with the timestamp, eHCILL and the short packet dump.
I'm sorry, but the LOG_INFO is disabled because BTstack doesn't work with it 
enabled anymore. It looks like the CC2564 initialization phase is very time 
sensitive.

The timestamp is recorded within [] and starts from 00:00:00.

The pairing is initiated at 00:01:00. From 00:01:01 to 00:01:30 you can see a 
29 second delay.

Original comment by muzaf...@mahkamov.com on 3 Sep 2013 at 8:38

Attachments:

• hci_transport_h4_ehcill_dma_Android_4.3.7z

[GoogleCodeExporter]

Thanks for the new logs. Is "sdp_try_respond" always logged or only when 
sep_response_size = 0 == no sdp response pending. I only see "sdp_try_respond: 
sdp_response_size is 0" but I also see two SDP responses. 

Again, we have a SDP request for 1201 which is answered on channel 0x040, then 
SDP is closed and opened again. Now the request for 0100 which contains the SPP 
record. Here I see in line 400 that the first part is sent, and then we have 
the long break. After the break, we get an L2CAP control message which is 
probably the channel close message.

so.. after sending the first part of the SDP result, I would expect a "Number 
Of Completed Packets Event", but that's not what's blocking here. The next step 
should be a Android asking for the next chunk of the SDP result.

hm. if you want to give it another try: could you dump the sdp_response in 
sdp_try_respond if the preconditions for sending are met? 

In general, the communication with the Bluetooth module should not be very time 
sensitive. The only critical part is that BTstack raises the RTS to stop the 
module from sending in the IRQ handler to not loose a byte. Everything else 
just happens at whatever speed. Bluetooth timeouts are in the order of seconds 
(Android gives up after 30 seconds and the Bluetooth spec doesn't even have 
timeouts listed for higher layer stuff)

If we can't sort that out, maybe you can borrow me your complete setup for a 
day or so. :)

Original comment by matthias.ringwald@gmail.com on 4 Sep 2013 at 6:37