I have a custom piece of hardware with a bluetooth low energy chip. I have set it up with an array with 500 u32s such that array[n] == n. I'm working on an android app that can connect to the device, request the length of the array, and then request the datapoints in the array one at a time.
The android app appears to be mostly working fine. It connects to the device, requests the length, and continues to request the next piece of data AFTER the previous piece was received. However, partway through the array(anywhere from 2 to 450 elements in - appears to be inconsistent), it will write another command, and it will make it all the way to onCharacteristicWrite(), but it never receives a response. I have my BLE peripheral hooked up to CoolTerm, and it never even receives the command. Here are snippets from my code and logs:
BLEService:
private final BluetoothGattCallback bleGattCallback = new BluetoothGattCallback() {
@Override
public void onCharacteristicRead(BluetoothGatt gatt, BluetoothGattCharacteristic characteristic, int status) {
super.onCharacteristicRead(gatt, characteristic, status);
Log.d("onCharacteristicRead", byteArrToHex(characteristic.getValue()));
}
@Override
public void onCharacteristicWrite(BluetoothGatt gatt, BluetoothGattCharacteristic characteristic, int status) {
if(status != BluetoothGatt.GATT_SUCCESS){
Log.d("onCharacteristicWrite", "Failed write, retrying");
gatt.writeCharacteristic(characteristic);
}
Log.d("onCharacteristicWrite", byteArrToHex(characteristic.getValue()));
super.onCharacteristicWrite(gatt, characteristic, status);
}
@Override
public void onCharacteristicChanged(BluetoothGatt gatt, BluetoothGattCharacteristic characteristic) {
super.onCharacteristicChanged(gatt, characteristic);
Log.d("onCharacteristicChanged", byteArrToHex(characteristic.getValue()));
broadcastUpdate(ACTION_DATA_AVAILABLE, characteristic);
}
};
I have omitted unnecessary parts of the callback related to descriptor writes, connection state changes, etc. When data is broadcasted, it is received in this portion of MainActivity:
private BroadcastReceiver messageReceiver = new BroadcastReceiver() {
@Override
public void onReceive(Context context, Intent intent) {
String receivedUUID = intent.getStringExtra("uuid");
byte[] data = intent.getByteArrayExtra("data");
Log.d("messageReceiver", "received intent in mainActivity with uuid " + receivedUUID.toString());
if(receivedUUID.equals(READ_LEN_UUID.toString()) && currentlyReading) {
datapoints = new ArrayList<Long>();
numberOfDatapoints = 0;
numberOfDatapoints |= (data[0] & 0xff);
numberOfDatapoints |= (data[1] & 0xff) << 8;
numberOfDatapoints |= (data[2] & 0xff) << 16;
numberOfDatapoints |= (data[3] & 0xff) << 24;
Log.d("RECEIVER TEST:", "number of datapoints = " + numberOfDatapoints);
if(numberOfDatapoints > 0) {
bleService.requestDatapoint(0);
}
} else if (receivedUUID.equals(READ_DATAPOINT_UUID.toString()) && currentlyReading){
long message = 0;
message |= (data[0] & 0xff);
message |= (data[1] & 0xff) << 8;
message |= (data[2] & 0xff) << 16;
message |= (data[3] & 0xff) << 24;
Log.d("Datapoint Recieved", "Index " + datapoints.size() + " = " + message);
datapoints.add(message);
if(datapoints.size() < numberOfDatapoints){
bleService.requestDatapoint(datapoints.size());
}
}
}
};
The code that calls writeCharacteristic:
public void requestDatapoint(int index){
Log.d("requestDatapoint", "Requested datapoint at " + index);
BluetoothGattCharacteristic commandChar = this.gattService.getCharacteristic(WRITE_UUID);
byte[] request = new byte[3];
// command - 2 = get index
request[0] = (byte) (2 & 0xff);
// index
request[1] = (byte) ((index) & 0xff);
request[2] = (byte) ((index >> 8) & 0xff);
commandChar.setValue(request);
bleGatt.writeCharacteristic(commandChar);
}
I'm fairly certain there isn't an issue with sending commands too quickly. It's actually incredibly slow, which I did on purpose so I could more easily test things before moving on to the next portion of my project.
An snippet from one of my debug logs:
08-23 12:08:18.470 16753-16753/sethp.datalogcollector D/requestDatapoint: Requested datapoint at 49
08-23 12:08:18.570 16753-16765/sethp.datalogcollector D/onCharacteristicWrite: 02 31 00
08-23 12:08:18.570 16753-16765/sethp.datalogcollector D/onCharacteristicChanged: 31 00 00 00
08-23 12:08:18.570 16753-16765/sethp.datalogcollector D/BLEService: Characteristic found. UUID: 00020000-5f5f-4a49-4847-464544434241
08-23 12:08:18.575 16753-16753/sethp.datalogcollector D/messageReceiver: received intent in mainActivity with uuid 00020000-5f5f-4a49-4847-464544434241
08-23 12:08:18.575 16753-16753/sethp.datalogcollector D/Datapoint Recieved: Index 49 = 49
08-23 12:08:18.575 16753-16753/sethp.datalogcollector D/requestDatapoint: Requested datapoint at 50
08-23 12:05:55.585 16753-16765/sethp.datalogcollector D/onCharacteristicWrite: 02 32 00
08-23 12:05:55.585 16753-16765/sethp.datalogcollector D/onCharacteristicChanged: 32 00 00 00
08-23 12:05:55.585 16753-16765/sethp.datalogcollector D/BLEService: Characteristic found. UUID: 00020000-5f5f-4a49-4847-464544434241
08-23 12:05:55.585 16753-16753/sethp.datalogcollector D/messageReceiver: received intent in mainActivity with uuid 00020000-5f5f-4a49-4847-464544434241
08-23 12:05:55.590 16753-16753/sethp.datalogcollector D/Datapoint Recieved: Index 50 = 50
08-23 12:05:55.590 16753-16753/sethp.datalogcollector D/requestDatapoint: Requested datapoint at 51
08-23 12:05:55.680 16753-16845/sethp.datalogcollector D/onCharacteristicWrite: 02 33 00
08-23 12:05:55.685 16753-16764/sethp.datalogcollector D/onCharacteristicChanged: 33 00 00 00
08-23 12:05:55.685 16753-16764/sethp.datalogcollector D/BLEService: Characteristic found. UUID: 00020000-5f5f-4a49-4847-464544434241
08-23 12:05:55.685 16753-16753/sethp.datalogcollector D/messageReceiver: received intent in mainActivity with uuid 00020000-5f5f-4a49-4847-464544434241
08-23 12:05:55.685 16753-16753/sethp.datalogcollector D/Datapoint Recieved: Index 51 = 51
08-23 12:05:55.685 16753-16753/sethp.datalogcollector D/requestDatapoint: Requested datapoint at 52
08-23 12:05:55.785 16753-16765/sethp.datalogcollector D/onCharacteristicChanged: 34 00 00 00
08-23 12:05:55.785 16753-16765/sethp.datalogcollector D/BLEService: Characteristic found. UUID: 00020000-5f5f-4a49-4847-464544434241
08-23 12:05:55.785 16753-16753/sethp.datalogcollector D/messageReceiver: received intent in mainActivity with uuid 00020000-5f5f-4a49-4847-464544434241
08-23 12:05:55.785 16753-16753/sethp.datalogcollector D/Datapoint Recieved: Index 52 = 52
08-23 12:05:55.785 16753-16753/sethp.datalogcollector D/requestDatapoint: Requested datapoint at 53
08-23 12:05:55.790 16753-16765/sethp.datalogcollector D/onCharacteristicWrite: 02 35 00
and my corresponding CoolTerm log snippet:
command: 02
index: 0031
command = 2
datapoint at 49 = 49
attempting to send 49
command: 02
index: 0032
command = 2
datapoint at 50 = 50
attempting to send 50
command: 02
index: 0033
command = 2
datapoint at 51 = 51
attempting to send 51
command: 02
index: 0034
command = 2
datapoint at 52 = 52
attempting to send 52
Note that in my peripheral log, it doesn't appear to receive the request for datapoint 53. For reference, the first hex byte in the onCharacteristicWrite debug is the command. The command 02 just means that I am requesting a datapoint at the index of whatever the next 2 bytes contain.
I have noticed that in the Android log, there isn't an onCharacteristicWrite log for requesting datapoint 51. That does seem to happens every time right before it stops getting data, but I'm not sure if this is significant or if it's just an issue with the Log buffer.
I have run quite a few tests trying to notice any patterns, and I have noticed that it seems to get more datapoints when the device is not connected to the debug cable. My only thought at this point is that maybe I have an issue with something asynchronous interrupting the callback, but I don't know what would be doing that. Does anybody have any thoughts about why it doesn't seem to actually write data after onCharacteristicWrite is called?
Thanks
EDIT:
I followed Emil's suggestion and turned on bluetooth logging. I played around with wireshark and figured out what was going on. I tried out my app again, and it ran up to index 102 until it stopped, at which point I disconnected the device. I dug through the packets in Wireshark, and found that my device DID receive the data about 102, but it did not send a request for 103. I double checked my android log, and a Log statement from inside onCharacteristicWrite said that it sent the command 02 67 00, which is a request for 103. So, it appears that onCharacteristicWrite is being called, but the characteristic is not actually being written.
After some more staring and thinking, I am quite certain that either 1) onCharacteristicWrite is being called improperly, because the data is never being written, or 2) somehow, something asynchronous is interrupting it and stopping it from transmitting. I have no idea what would be doing this.
FINAL EDIT:
Even though, as far as I understand from the spec, onCharacteristicWrite is only supposed to be called when a reliable, successful write is in progress, I decided to check the return value from writeCharacteristic. Which I should have checked hours ago. And what do you know, it was returning false on the last request.
I think the fact that onCharacteristicWrite was called even though the return was false is a bug. I've read that it is safe to use the onCharacteristicWrite call to write the next chunk of data. Either they were wrong, or something screwy is going on here. Either way, I guess it's a pretty good idea to check those function call return values.
