I am extending the Glucose sensor app in nRF Toolbox (Develop thread). I had logic error which I have corrected, but while debugging I encountered a strange effect that could suggest a problem with the Android Library: incoming Indications might corrupt outgoing characteristic writes. Nordic might want to look into this.
My code sends a sequence of commands to my device using writeCharacteristic() calls to the RACP characteristic. The device carries out the command then responds with an Indication, with the result of the command. My logic error was not to wait for the the Indication before sending the subsequent writeCharacteristic(). So the second writeCharacteristic() would have been happening very close to the time at which the first Indication was arriving.
What I saw was that the payload of the subsequent writeCharacteristic() call was sometimes replaced with the payload of the incoming Indication.
Below are two extracts captured by nRF Logger. The first shows the correct sequence (the phone asks the device how many stored records it has, then asks it to send all stored records). The sequence shows a first writeCharacteristic(), the resulting incoming Indication, then a second writeCharacteristic() and a second Indication. Note the correct payload for the second write at 11:58:54.276 is (0x) 01-01. Lines starting with "APP_MedManager " come from my code and include parsed messages or responses; other lines are from the library.
I 11:58:54.130 Data written to 55feb603-0030-11e7-93ae-92361f002671, value: (0x) 04-01
A 11:58:54.149 APP_MedManager "Report number of stored records Operator: All records" sent
V 11:58:54.166 Writing characteristic 55feb603-0030-11e7-93ae-92361f002671 (WRITE REQUEST)
D 11:58:54.184 gatt.writeCharacteristic(55feb603-0030-11e7-93ae-92361f002671)
I 11:58:54.201 Indication received from 55feb603-0030-11e7-93ae-92361f002671, value: (0x) 05-00-03-00
A 11:58:54.216 APP_MedManager "Number of stored records response: 3" received
I 11:58:54.276 Data written to 55feb603-0030-11e7-93ae-92361f002671, value: (0x) 01-01
A 11:58:54.289 APP_MedManager "Report stored records Operator: All records" sent
<snip: the device sends the 3 records as 3 Notifications. then:>
I 11:58:54.592 Indication received from 55feb603-0030-11e7-93ae-92361f002671, value: (0x) 06-00-01-01
A 11:58:54.608 APP_MedManager "Response for Report stored records: Success" received
The second sequence shown below shows the fault condition.
I 11:57:49.125 Data written to 55feb603-0030-11e7-93ae-92361f002671, value: (0x) 04-01
A 11:57:49.140 APP_MedManager Command "Report number of stored records. Operator: All records" sent
V 11:57:49.154 Writing characteristic 55feb603-0030-11e7-93ae-92361f002671 (WRITE REQUEST)
D 11:57:49.168 gatt.writeCharacteristic(55feb603-0030-11e7-93ae-92361f002671)
I 11:57:49.186 Indication received from 55feb603-0030-11e7-93ae-92361f002671, value: (0x) 05-00-03-00
A 11:57:49.203 APP_MedManager "Number of stored records response: 3" received
I 11:57:49.376 Data written to 55feb603-0030-11e7-93ae-92361f002671, value: (0x) 05-00-03-00
A 11:57:49.391 APP_MedManager Command "Report stored records Operator: All records" sent
I 11:57:49.626 Indication received from 55feb603-0030-11e7-93ae-92361f002671, value: (0x) 06-00-05-02
A 11:57:49.641 APP_MedManager "Response for Number of stored records response: Operation not supported" received
The first writeCharacteristic() carrying the command "Report number of stored records" is logged at 11:57:49.125
The resulting Indication is logged at 11:57.49.186 and contains the expected payload: (0x) 05-00-03-00 (showing the device has 3 stored records). The 0x05 means "Number of stored records response"
The second writeCharacteristic() is logged at 11:57:49.376 and should have carried the payload (0x) 01-01 but instead carries the incorrect payload (0x) 05-00-03-00, which is the response just received in the previous Indication.
Note that at 11:57:49.391 the app prints the correct (parsed) command that it has sent in the second writeCharacteristic() call. This shows that my app has sent the correct command to the writeCharacteristic() call. The second incoming Indication at 11:57:49.626 shows that the device has rejected that command as illegal: the parsed response at 11:57:49.641 shows that the device has received an illegal command 0x05 ("Number of stored records response") and so responds with status 0x02 ("Operation not supported")
Summary:
I hypothesise that the writeCharacteristic() and the incoming Indication share the same buffer, and that if an Indication comes in while a writeCharacteristic() is about to go out, the incoming Indication payload overwrites the queued writeCharacteristic() payload, and so the writeCharacteristic() sends the wrong data. By chance my logic error meant that the first Indication arrives at about the same time as the second writeCharacteristic is about to leave, and so greatly increases the chance of this bug occurring. But it could happen at random to anyone.
