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

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

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..)?

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.

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

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.

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

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.

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.

Thanks, that version installs and runs.

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.

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)

Comment deleted

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.

Comment deleted

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.

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.

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.

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.

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.

Here is the spp_counter.hex

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

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)

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)

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.

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.

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

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)

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.

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.

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

Attached are the logs with eHCILL disabled.

The bug cannot be reproduced in this case.

It looks like there's a timing issue.

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.

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?

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.

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)

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.

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. :)