Bluetooth BLE support for Adafruit Feather Bluefruit LE

@BlynkAndroidDev

I also have another failure case where Blynk stops responding to the board altogether!

3:17:53 DEBUG BLE - onDataChanged: characteristic=6e400003-b5a3-f393-e0a9-e50e24dcca9e value=[20, 0, 25, 0, 6, 118, 119, 0, 51, 0, 54]
23:17:53 DEBUG BLE - parseAndSend: actionId=20 messageId=25 codeOrLength=6 message=
23:17:53 DEBUG CommunicationService - onPacketReceived messageId = 25, actionId = 20, value = 1972193027
[...]
23:17:53 DEBUG CommunicationService - onPacketReceived forward projectId=1972193027 actionId=20 value=1972193027
23:17:53 DEBUG CommunicationService - sendAction action=ForwardHardwareAction{actiondId=65, body=1972193027-0
23:17:53 DEBUG SocketTransport - add action=ForwardHardwareAction{actiondId=65, body=1972193027-0
23:17:53 DEBUG SocketWriter - write as id=24 action=ForwardHardwareAction{actiondId=65, body=1972193027-0
23:17:56 DEBUG BLE - onDataChanged: characteristic=6e400003-b5a3-f393-e0a9-e50e24dcca9e value=[20, 0, 26, 0]
23:17:56 DEBUG BLE - onDataChanged: characteristic=6e400003-b5a3-f393-e0a9-e50e24dcca9e value=[6, 118, 119, 0, 48, 0, 55]
23:17:56 DEBUG BLE - onDataChanged: characteristic=6e400003-b5a3-f393-e0a9-e50e24dcca9e value=[20, 0, 27, 0, 6, 118, 119, 0, 49, 0, 55]
23:17:56 DEBUG BLE - onDataChanged: characteristic=6e400003-b5a3-f393-e0a9-e50e24dcca9e value=[20, 0, 28, 0, 6, 118, 119, 0, 50, 0, 55]
23:17:56 DEBUG BLE - onDataChanged: characteristic=6e400003-b5a3-f393-e0a9-e50e24dcca9e value=[20, 0, 29, 0, 6, 118, 119, 0, 51, 0, 55]

You can see at the end the board sends lots of messages back to blynk, but blynk does nothing.

Have sent a second logfile to cover this.

That’s probably some bugged data received, as I see this 4 bytes data:

23:17:56 DEBUG BLE - onDataChanged: characteristic=6e400003-b5a3-f393-e0a9-e50e24dcca9e value=[20, 0, 26, 0]

When app expect surely smth like - [20, 0, 27, 0, 6, 118, 119, 0, 49, 0, 55]

  1. Debug app is 2.17.3, why it should have other version?
  2. onPacketResponse is called async, so it could be in the log not near the onDataChanged and parseAndSend elems.

Thanks, I’ll check your logs.

So you can see it’s written it over 2 writes:

23:17:56 DEBUG BLE - onDataChanged: characteristic=6e400003-b5a3-f393-e0a9-e50e24dcca9e value=[20, 0, 26, 0]
23:17:56 DEBUG BLE - onDataChanged: characteristic=6e400003-b5a3-f393-e0a9-e50e24dcca9e value=[6, 118, 119, 0, 48, 0, 55]

I’m not sure about the BLE protocols exactly (@vshymanskyy might know) - can the message be broken down into two? I don’t see why not.

If you are going to disallow this the app should either disconnect and reconnect, or it should gracefully recover when it receives a correct message.

Yep, I see now, that’s correct. I’ve thought next one was the new message.

Right. Indeed the corresponding 5th onPacketResponse call is 10 seconds later (22:36:42) - which suspiciously happens to be after the next time the board sends another message.

So yeah it’s async, but at the same time there’s very strong evidence that a message is being buffered somewhere.

1 Like

Yep, I’ve seen in your logs that app is receiving 2 times ‘login OK’, now I see that it is possibly a buffering issue.

Please check this build, it seems that buffering issue is fixed on it (I’ve tested on ESP32 BLE sketch with pings and several virtual writes every 5 seconds).
If you will reproduce the board’s disconnection issue, or that not parsing of the received data issue - please send logs again.

Thanks!!
My initial test suggests that the buffering issue is indeed fixed.

However I can still get the split-message issue:

04:59:12 DEBUG c.b.a.communication.transport.a.a.a - onDataChanged: onDataChanged=[20, 0, 13]
04:59:12 DEBUG c.b.a.communication.transport.a.a.a - onDataChanged: onDataChanged=[0, 6, 118, 119, 0, 48, 0, 52]
04:59:12 DEBUG c.b.a.communication.transport.a.a.a - parseAndSend: actionId=0 messageId=1654 codeOrLength=30464
04:59:12 DEBUG c.b.a.communication.transport.a.a.a - parseAndSend: wrap
04:59:12 DEBUG CommunicationService - onPacketResponse messageId=1654 responseCode=null
04:59:12 DEBUG CommunicationService - onPacketResponse serverAction=null
04:59:12 DEBUG CommunicationService - onPacketResponse postResponse=ServerResponse{code=30464, messageId=1654, projectId=-1, body='null'}
04:59:12 DEBUG c.b.a.communication.transport.a.a.a - onDataChanged: onDataChanged=[20, 0, 14, 0, 6, 118, 119, 0, 49, 0, 52]
04:59:12 DEBUG c.b.a.communication.transport.a.a.a - parseAndSend: not wrap
04:59:12 DEBUG c.b.a.communication.transport.a.a.a - onDataChanged: onDataChanged=[20, 0, 15, 0, 6, 118, 119, 0, 50, 0, 52]
04:59:12 DEBUG c.b.a.communication.transport.a.a.a - parseAndSend: not wrap

Logs in the mail.

I’m also seeing a third issue to do with disconnects.

If my phone goes to sleep it disconnects from the bluetooth, if I wake it up ~30 seconds later my phone will reconnect to the board.

However if I wake it up immediately my phone fails to reconnect.

(A 3rd failure mode is when I start the app from cold. It sometimes fails to connect to the board)

Here’s a good reconnect:

05:09:02 DEBUG CommunicationService - removeOnServerResponseListener: clazz=ProjectActivity
05:09:02 DEBUG CommunicationService - onUnbind
05:09:02 DEBUG CommunicationService - onDestroy
05:09:02 DEBUG c.b.a.communication.transport.a.a.a - onDisconnect: forced=true
[...]
05:09:15 DEBUG CommunicationService - onBind
05:09:15 DEBUG SocketTransport - connect: relogin
05:09:15 DEBUG SocketReader - connect to 139.59.206.133
05:09:15 DEBUG CommunicationService - onReceive activeNetwork = 
[REDACTED]
05:09:21 DEBUG c.b.a.communication.transport.a.a.a - onDisconnect: forced=true
[...]
05:09:23 DEBUG c.b.a.communication.transport.a.a.b - to write: BluetoothLoginAction{actiondId=2, body=570529042ad34219a964929e2a483f40}
05:09:23 DEBUG c.b.a.communication.transport.a.a.b - write: [2, 0, 1, 0, 32, 53, 55, 48, 53, 50, 57, 48, 52, 50, 97, 100, 51, 52, 50, 49]
05:09:23 DEBUG c.b.a.communication.transport.a.a.b - write: [57, 97, 57, 54, 52, 57, 50, 57, 101, 50, 97, 52, 56, 51, 102, 52, 48]
05:09:23 DEBUG c.b.a.communication.transport.a.a.a - onDataChanged: onDataChanged=[0, 0, 1, 0, -56]
05:09:23 DEBUG c.b.a.communication.transport.a.a.a - parseAndSend: actionId=0 messageId=1 codeOrLength=200
05:09:23 DEBUG CommunicationService - onEventMainThread serverResponse=ServerResponse{code=200, messageId=-200, projectId=-1, body='null'} paused=false
05:09:23 DEBUG c.b.a.communication.transport.a.a.a - parseAndSend: wrap
[...]
05:09:24 DEBUG CommunicationService - onPacketReceived messageId = 1111, actionId = 25, value = 1972193027-0
05:09:24 DEBUG CommunicationService - onPacketReceived actionId=25 serverAction=null
05:09:24 DEBUG CommunicationService - onPacketReceived messageId = 1111, actionId = 25, value = 1972193027-0
05:09:24 DEBUG CommunicationService - onPacketReceived actionId=25 serverAction=null
[...5 more...]
05:09:25 DEBUG c.b.a.communication.transport.a.a.a - onDataChanged: onDataChanged=[20, 0, 109, 0, 7, 118, 119, 0, 48, 0, 50, 57]
05:09:25 DEBUG c.b.a.communication.transport.a.a.a - parseAndSend: actionId=20 messageId=109 codeOrLength=7 message=
05:09:25 DEBUG c.b.a.communication.transport.a.a.a - parseAndSend: wrap
05:09:25 DEBUG CommunicationService - onPacketReceived messageId = 109, actionId = 20, value = 1972193027-0

Notice the ~12 second gap from when my phone went to standby at 05:09:03 and when it woke up at 05:09:15. It then takes another 8 seconds before it reconnects the bluetooth (but hey I can live with that). I see a bunch of synthetic onPackedReceived messages after it reconnects that contain the values from before the disconnect - is this by design?

Now here is a bad reconnect:

05:09:45 DEBUG CommunicationService - removeOnServerResponseListener: clazz=ProjectActivity
05:09:45 DEBUG CommunicationService - onUnbind
05:09:45 DEBUG CommunicationService - onDestroy
05:09:45 DEBUG c.b.a.communication.transport.a.a.a - onDisconnect: forced=true
[...]
05:09:47 DEBUG CommunicationService - onBind
05:09:47 DEBUG SocketTransport - connect: relogin
05:09:47 DEBUG SocketReader - connect to 139.59.206.133
05:09:47 DEBUG CommunicationService - onReceive activeNetwork = 
[...]
05:09:52 DEBUG c.b.a.communication.transport.a.a.a - onDisconnect: forced=true
05:09:53 DEBUG c.b.a.communication.transport.a.a.a - onDisconnect: forced=true
05:09:53 DEBUG CommunicationService - onPacketResponse messageId=4 responseCode=OK
05:09:53 DEBUG CommunicationService - onPacketResponse serverAction=SyncAction{actiondId=25, body=1972193027}
05:09:53 DEBUG CommunicationService - onPacketResponse postResponse=ServerResponse{code=200, messageId=4, projectId=1972193027, body='null'}
[A whole bunch of synthetic onPacketRecieved messages]

Here there are only 2 seconds from the disconnect (05:09:45) to the reconnect (05:09:47).

In the bad case the app fails to reconnect the BLE connection. I know this because the BLE-connected light on my board is off.

My theory here is that in the good case, both the BLE connection is broken and the Blynk heartbeat timeout has passed. In the bad case the Blynk heartbeat timeout has not passed. For some reason in this situation the app does not fix the bluetooth connection.

I’ve found some possible causes of the failed reconnection and messaging processing fail after some bad data received (not your case with sending message in several parts, but it should also be fixed)

Thanks! The re-connection is SO MUCH FASTER, oh my!

I’m still getting the short-term issue - i.e. if I put my phone into standby for a second and then switch it back on immediately the Blynk app will fail to reconnect the bluetooth:

23:04:29 DEBUG CommunicationService - removeOnServerResponseListener: clazz=ProjectActivity
23:04:29 DEBUG CommunicationService - onUnbind
23:04:29 DEBUG CommunicationService - onDestroy
23:04:29 DEBUG c.b.a.communication.transport.a.a.a - onDisconnect: forced=true
23:04:29 DEBUG SocketTransport - add action=PingAction{actiondId=6, body=null}
23:04:29 DEBUG SocketWriter - write as id=39 action=PingAction{actiondId=6, body=null}
23:04:30 DEBUG SocketTransport - disconnect
23:04:30 ERROR SocketTransport - stopThreadPool clear socketReader
23:04:30 ERROR SocketReader - SSLSocket reading exception.
java.net.SocketException: socket is closed
[...]
23:04:31 DEBUG CommunicationService - onBind
23:04:31 DEBUG SocketTransport - connect: relogin
23:04:31 DEBUG SocketReader - connect to 139.59.206.133
[... blah blah blah, but no BLE connection or data ...]

I haven’t been able to reproduce the other issues. I’ll give it a crack if I have the energy, but this is so much better - thank you so much!!

1 Like

Hmm, strange, I’ve thought the reconnection issue is fixed. What do you mean by standby for a second? When the display goes darker?

@BlynkAndroidDev

Ah - I was able to reproduce the split message issue again too:

23:30:46 DEBUG c.b.a.communication.transport.a.a.a - onDataChanged: onDataChanged=[20, 2, -99, 0]
23:30:46 DEBUG c.b.a.communication.transport.a.a.a - onDataChanged: onDataChanged=[8, 118, 119, 0, 48, 0, 53, 56, 48]
23:30:46 DEBUG c.b.a.communication.transport.a.a.a - parseAndSend: actionId=8 messageId=30327 codeOrLength=48
23:30:46 DEBUG c.b.a.communication.transport.a.a.a - parseAndSend: not wrap
23:30:47 DEBUG c.b.a.communication.transport.a.a.a - onDataChanged: onDataChanged=[20, 2, -98, 0, 8, 118, 119, 0, 49, 0, 53, 56, 48]
23:30:47 DEBUG c.b.a.communication.transport.a.a.a - parseAndSend: actionId=8 messageId=30327 codeOrLength=48
23:30:47 DEBUG c.b.a.communication.transport.a.a.a - parseAndSend: not wrap

Logs in the mail.

No not when it goes darker.

When I push the power button on my phone it locks the phone (and the BLE light on the board goes off). If I push it again it takes me to the lock screen. I then (quickly) enter my pin to take me back to the blynk app. If I do this quickly blynk does not reconnect the bluetooth.

Oddly it seems to work some of the time (maybe even most of the time?). I’ll see if I can figure it out - The re connection appears to fail maybe ~20% of the time.

1 Like

I’ll provide a new build with some additional logging and reconnection/message_concating fixes in an hour or two, probably. In any case, all the fixes will be released in 2.18.0 tomorrow.

App’s build is updated by the same link. Split messages issues should be fixed. This fast reconnect issue would need more time, maybe in some next releases we’ll fix it, first we need to reproduce it on our devices.

@BlynkAndroidDev - Thanks.

The brief-disconnect issue isn’t readily reproducible, I had to disconnect and reconnect ~10 times to get it to happen. I have a BLE-connected light on my board so I can just switch on and off my phone until the phone is on but the BLE connected light is off.

07:14:59 DEBUG CommunicationService - removeOnServerResponseListener: clazz=ProjectActivity
07:14:59 DEBUG CommunicationService - onUnbind
07:14:59 DEBUG CommunicationService - onDestroy
07:14:59 DEBUG c.b.a.communication.transport.a.a.a - onDisconnect: forced=true
07:14:59 DEBUG SocketTransport - disconnect
07:14:59 ERROR SocketTransport - stopThreadPool clear socketReader
07:14:59 ERROR SocketReader - SSLSocket reading exception.
[...]
07:15:00 DEBUG CommunicationService - onEventMainThread serverResponse=ServerResponse{code=1002, messageId=-100, projectId=-1, body='null'} paused=true
07:15:00 DEBUG CommunicationService - onBind
07:15:00 DEBUG SocketTransport - connect: relogin
07:15:00 DEBUG SocketReader - connect to 139.59.206.133
[... no more BLE messages ...]

I also got a “Board is diconnected” message, I think it’s this:

07:13:56 DEBUG CommunicationService - custom transport f: isProcessed=true isTransportIndependent=true
07:13:56 DEBUG SocketTransport - add action=ActivateAction{actiondId=7, body=1972193027}
07:13:56 DEBUG SocketWriter - write as id=6 action=ActivateAction{actiondId=7, body=1972193027}
07:13:56 DEBUG CommunicationService - onPacketResponse messageId=6 responseCode=DEVICE_NOT_IN_NETWORK

Which is a bit weird. It’s rare enough not to be an issue - though I’ve seen it once or twice before. The slightly frustrating thing is that there’s no way to force Blynk to retry connection - other than going into design mode, or putting the phone into standby and out.

Here’s a suggestion: Could you make the bluetooth widget reflect the BLE connected status? And in run mode if you touch it while it’s disconnected it could force a retry?

2 Likes

If the board was disconnected - it would be requested to reconnect in the background, usually, it takes some time. Thanks, we’ll think about such feature.

Hi,

I am currently also doing BLE tests using the Android store version 2.18.0 of 26th of Jan 2018 in combination with HM10.

I don’t know if it is related or not, but

  • when i leave the app and return to the Blynk app
  • or, when I switch off and on the screen (standby for some seconds)

the reconnection sometimes (10%-20%) doesn’t work.

When I debug the Arduino code, I notice that only the 15 first bytes of the authentication code are being received.
a) In case some button is pressed in the app, it sends that command after the 15 authentication code bytes, and this results in “invalid token”
b) if no button is pressed, this results in “Can’t read body”: in that case only 15 bytes have been received (followed by a time-out) instead of the expected 32 bytes.