search

jlinear / DispatchApp

Off-the-grid communication app based on BlueNet.
MIT License
0 stars 0 forks source link

unstable connection and failed to get neighbors #5

Open jlinear opened 6 years ago

jlinear commented 6 years ago

Two devices are able to find each other and initiate a connection, but the connection is cut off soon after the establishment according to the logcat. The getNeighbors() / getConnectedDevices didn't return expected values in such a short connected interval.

screen shot 2018-06-12 at 1 13 57 am
jtsiva commented 6 years ago

I made a change that might work, but I haven't tested it yet. Check out this and this for other possible solutions.

jtsiva commented 6 years ago

Latest commit appears to take care of the status 133 issues.

jtsiva commented 6 years ago

We still have an issue with disconnecting and difficulty connecting multiple devices.

Here is what a common connection log between two devices looks like. Notice the multiple connections of the GATT server. I believe one is due to the GATT client on the same device creating a connection while the other is due to the GATT client on the other device starting a connection.

Device A:

06-21 09:25:12.506  1550  1829 I ActivityManager: Start proc 20229:com.example.marco.bluenet_01/u0a134 for activity com.example.marco.bluenet_01/.MainActivity
06-21 09:25:12.509 20229 20229 I art     : Late-enabling -Xcheck:jni
06-21 09:25:12.548 20229 20229 W System  : ClassLoader referenced unknown path: /data/app/com.example.marco.bluenet_01-1/lib/arm
06-21 09:25:12.653 20229 20245 I Adreno  : QUALCOMM build                   : 15c6858, Id9e7eae3da
06-21 09:25:12.653 20229 20245 I Adreno  : Build Date                       : 12/22/16
06-21 09:25:12.653 20229 20245 I Adreno  : OpenGL ES Shader Compiler Version: XE031.09.00.03
06-21 09:25:12.653 20229 20245 I Adreno  : Local Branch                     : 
06-21 09:25:12.653 20229 20245 I Adreno  : Remote Branch                    : refs/tags/AU_LINUX_ANDROID_LA.UM.5.5.R1.07.00.00.269.019
06-21 09:25:12.653 20229 20245 I Adreno  : Remote Branch                    : NONE
06-21 09:25:12.653 20229 20245 I Adreno  : Reconstruct Branch               : NOTHING
06-21 09:25:12.658 20229 20245 I OpenGLRenderer: Initialized EGL, version 1.4
06-21 09:25:19.265 20229 20229 W art     : Before Android 4.1, method android.graphics.PorterDuffColorFilter android.support.graphics.drawable.VectorDrawableCompat.updateTintFilter(android.graphics.PorterDuffColorFilter, android.content.res.ColorStateList, android.graphics.PorterDuff$Mode) would have incorrectly overridden the package-private method in android.graphics.drawable.Drawable
06-21 09:25:19.420 20229 20229 I APP_INFO: BLE SCAN STARTED
06-21 09:25:19.430 20229 20229 I zzbz    : Making Creator dynamically
06-21 09:25:19.437 20229 20229 I DynamiteModule: Considering local module com.google.android.gms.maps_dynamite:0 and remote module com.google.android.gms.maps_dynamite:220
06-21 09:25:19.437 20229 20229 I DynamiteModule: Selected remote version of com.google.android.gms.maps_dynamite, version >= 220
06-21 09:25:19.444 20229 20229 W System  : ClassLoader referenced unknown path: 
06-21 09:25:19.459 20229 20229 W System  : ClassLoader referenced unknown path: /data/user_de/0/com.google.android.gms/app_chimera/m/00000011/n/armeabi
06-21 09:25:19.483 20229 20229 I Google Maps Android API: Google Play services client version: 12451000
06-21 09:25:19.487 20229 20229 I Google Maps Android API: Google Play services package version: 12685022
06-21 09:25:19.583 20229 20229 E art     : The String#value field is not present on Android versions >= 6.0
06-21 09:25:19.794 20229 20229 I Choreographer: Skipped 31 frames!  The application may be doing too much work on its main thread.
06-21 09:25:19.882 20229 20229 I APP_INFO: LE Advertise Started
06-21 09:25:20.534 20229 20265 I BlueNet : trying to connect!
06-21 09:25:20.951 20229 20264 I APP_INFO: Gatt Server connected to 6D:CB:FA:3E:D3:DC
06-21 09:25:20.956 20229 20265 I APP_INFO: Connected to GATT server at 6D:CB:FA:3E:D3:DC
06-21 09:25:20.957 20229 20265 I APP_INFO: Starting service discoverytrue
06-21 09:25:21.191 20229 20229 I MapsActivity: Location: 41.6813291 -86.2290033
06-21 09:25:21.193 20229 20229 I BlueNet : Hit RoutingManager
06-21 09:25:21.786 20229 20299 W DynamiteModule: Local module descriptor class for com.google.android.gms.googlecertificates not found.
06-21 09:25:21.791 20229 20299 I DynamiteModule: Considering local module com.google.android.gms.googlecertificates:0 and remote module com.google.android.gms.googlecertificates:4
06-21 09:25:21.791 20229 20299 I DynamiteModule: Selected remote version of com.google.android.gms.googlecertificates, version >= 4
06-21 09:25:21.795 20229 20299 W System  : ClassLoader referenced unknown path: /data/user_de/0/com.google.android.gms/app_chimera/m/00000014/n/armeabi-v7a
06-21 09:25:21.795 20229 20299 W System  : ClassLoader referenced unknown path: /data/user_de/0/com.google.android.gms/app_chimera/m/00000014/n/armeabi
06-21 09:25:22.656 20229 20264 I APP_INFO: Gatt Server connected to 4D:F6:18:38:0E:0E
06-21 09:25:23.787 20229 20265 I BlueNet : Enable characteristic notifications
06-21 09:25:25.677 20229 20264 I APP_INFO: Subscribe device to notifications: 4D:F6:18:38:0E:0E
06-21 09:25:27.388 20229 20265 I BlueNet : Characteristic change from: 6D:CB:FA:3E:D3:DC
06-21 09:25:27.389 20229 20229 I BlueNet : Received a packet!
06-21 09:25:27.390 20229 20229 I BlueNet : MessageRetriever starting read request
06-21 09:25:27.484 20229 20270 W BluetoothGatt: onCharacteristicRead() - Device=6D:CB:FA:3E:D3:DC handle=57 Status=0
06-21 09:25:27.485 20229 20265 I BlueNet : read complete!
06-21 09:25:27.486 20229 20229 I BlueNet : Hit RoutingManager
06-21 09:25:31.287 20229 20229 I MapsActivity: Location: 41.6813291 -86.2290033
06-21 09:25:31.289 20229 20229 I BlueNet : Hit RoutingManager
06-21 09:25:31.290 20229 20229 I BlueNet : Sending a packet!
06-21 09:25:31.290 20229 20229 I BlueNet : Hit BLEWriter
06-21 09:25:31.290 20229 20264 I BlueNet : notifying 4D:F6:18:38:0E:0E
06-21 09:25:31.292 20229 20264 I BlueNet : Notification sent!
06-21 09:25:32.795 20229 20264 I BlueNet : sending read response of length 10 of payload of length 10

Device B:

06-21 09:25:14.199  3473  3473 I art     : Late-enabling -Xcheck:jni
06-21 09:25:14.242  3473  3473 W System  : ClassLoader referenced unknown path: /data/app/com.example.marco.bluenet_01-1/lib/arm
06-21 09:25:14.348  3473  3489 I Adreno  : QUALCOMM build                   : 15c6858, Id9e7eae3da
06-21 09:25:14.348  3473  3489 I Adreno  : Build Date                       : 12/22/16
06-21 09:25:14.348  3473  3489 I Adreno  : OpenGL ES Shader Compiler Version: XE031.09.00.03
06-21 09:25:14.348  3473  3489 I Adreno  : Local Branch                     : 
06-21 09:25:14.348  3473  3489 I Adreno  : Remote Branch                    : refs/tags/AU_LINUX_ANDROID_LA.UM.5.5.R1.07.00.00.269.019
06-21 09:25:14.348  3473  3489 I Adreno  : Remote Branch                    : NONE
06-21 09:25:14.348  3473  3489 I Adreno  : Reconstruct Branch               : NOTHING
06-21 09:25:14.352  3473  3489 I OpenGLRenderer: Initialized EGL, version 1.4
06-21 09:25:21.433  3473  3473 W art     : Before Android 4.1, method android.graphics.PorterDuffColorFilter android.support.graphics.drawable.VectorDrawableCompat.updateTintFilter(android.graphics.PorterDuffColorFilter, android.content.res.ColorStateList, android.graphics.PorterDuff$Mode) would have incorrectly overridden the package-private method in android.graphics.drawable.Drawable
06-21 09:25:21.594  3473  3473 I APP_INFO: BLE SCAN STARTED
06-21 09:25:21.604  3473  3473 I zzbz    : Making Creator dynamically
06-21 09:25:21.611  3473  3473 I DynamiteModule: Considering local module com.google.android.gms.maps_dynamite:0 and remote module com.google.android.gms.maps_dynamite:220
06-21 09:25:21.611  3473  3473 I DynamiteModule: Selected remote version of com.google.android.gms.maps_dynamite, version >= 220
06-21 09:25:21.617  3473  3473 W System  : ClassLoader referenced unknown path: 
06-21 09:25:21.632  3473  3473 W System  : ClassLoader referenced unknown path: /data/user_de/0/com.google.android.gms/app_chimera/m/00000005/n/armeabi
06-21 09:25:21.657  3473  3473 I Google Maps Android API: Google Play services client version: 12451000
06-21 09:25:21.662  3473  3473 I Google Maps Android API: Google Play services package version: 12685022
06-21 09:25:21.757  3473  3473 E art     : The String#value field is not present on Android versions >= 6.0
06-21 09:25:21.953  3473  3473 I Choreographer: Skipped 31 frames!  The application may be doing too much work on its main thread.
06-21 09:25:22.045  3473  3473 I APP_INFO: LE Advertise Started
06-21 09:25:22.186  3473  3509 I APP_INFO: Gatt Server connected to 42:A1:91:56:B2:B2
06-21 09:25:23.322  3473  3473 I MapsActivity: Location: 41.6813291 -86.2290033
06-21 09:25:23.324  3473  3473 I BlueNet : Hit RoutingManager
06-21 09:25:23.410  3473  3510 I BlueNet : trying to connect!
06-21 09:25:23.887  3473  3509 I APP_INFO: Gatt Server connected to 4A:FD:1B:00:06:C7
06-21 09:25:23.891  3473  3510 I APP_INFO: Connected to GATT server at 4A:FD:1B:00:06:C7
06-21 09:25:23.893  3473  3510 I APP_INFO: Starting service discoverytrue
06-21 09:25:23.945  3473  3544 W DynamiteModule: Local module descriptor class for com.google.android.gms.googlecertificates not found.
06-21 09:25:23.949  3473  3544 I DynamiteModule: Considering local module com.google.android.gms.googlecertificates:0 and remote module com.google.android.gms.googlecertificates:4
06-21 09:25:23.949  3473  3544 I DynamiteModule: Selected remote version of com.google.android.gms.googlecertificates, version >= 4
06-21 09:25:23.952  3473  3544 W System  : ClassLoader referenced unknown path: /data/user_de/0/com.google.android.gms/app_chimera/m/00000008/n/armeabi-v7a
06-21 09:25:23.952  3473  3544 W System  : ClassLoader referenced unknown path: /data/user_de/0/com.google.android.gms/app_chimera/m/00000008/n/armeabi
06-21 09:25:25.060  3473  3509 I APP_INFO: Subscribe device to notifications: 42:A1:91:56:B2:B2
06-21 09:25:26.869  3473  3510 I BlueNet : Enable characteristic notifications
06-21 09:25:28.570  3473  3473 I MapsActivity: Location: 41.6813291 -86.2290033
06-21 09:25:28.571  3473  3473 I BlueNet : Hit RoutingManager
06-21 09:25:28.573  3473  3473 I BlueNet : Sending a packet!
06-21 09:25:28.573  3473  3473 I BlueNet : Hit BLEWriter
06-21 09:25:28.573  3473  3509 I BlueNet : notifying 42:A1:91:56:B2:B2
06-21 09:25:28.576  3473  3509 I BlueNet : Notification sent!
06-21 09:25:28.669  3473  3509 I BlueNet : sending read response of length 10 of payload of length 10
06-21 09:25:32.567  3473  3510 I BlueNet : Characteristic change from: 4A:FD:1B:00:06:C7
06-21 09:25:32.569  3473  3473 I BlueNet : Received a packet!
06-21 09:25:32.569  3473  3473 I BlueNet : MessageRetriever starting read request
06-21 09:25:34.125  3473  3512 W BluetoothGatt: onCharacteristicRead() - Device=4A:FD:1B:00:06:C7 handle=57 Status=0
06-21 09:25:34.126  3473  3510 I BlueNet : read complete!

Eventually, we will get an unexpected disconnect after some amount of time ranging from 30 seconds to 10 minutes. The disconnection looks like this:

Device A:

06-21 09:27:43.546 20229 20242 W BluetoothGatt: onCharacteristicRead() - Device=6D:CB:FA:3E:D3:DC handle=57 Status=0
06-21 09:27:43.547 20229 20265 I BlueNet : read complete!
06-21 09:27:43.547 20229 20229 I BlueNet : Hit RoutingManager
06-21 09:27:43.548 20229 20229 I BlueNet : Sending a packet!
06-21 09:27:43.548 20229 20229 I BlueNet : Hit BLEWriter
06-21 09:27:43.847 20229 20264 I APP_INFO: Gatt Server disconnected from 4D:F6:18:38:0E:0E
06-21 09:27:44.162 20229 20229 I MapsActivity: Location: 41.6813291 -86.2290033
06-21 09:27:44.163 20229 20229 I BlueNet : Hit RoutingManager
06-21 09:27:44.164 20229 20229 I BlueNet : Sending a packet!
06-21 09:27:44.165 20229 20229 I BlueNet : Hit BLEWriter
06-21 09:27:44.471 20229 20264 I APP_INFO: Gatt Server connected to 4D:F6:18:38:0E:0E
06-21 09:27:45.070 20229 20270 E BlueNet : Error in onConnectionStatechange -- status: 19, state: 0
06-21 09:27:45.070 20229 20264 I APP_INFO: Gatt Server disconnected from 6D:CB:FA:3E:D3:DC
06-21 09:27:45.071 20229 20265 I APP_INFO: Disconnected from GATT server at 6D:CB:FA:3E:D3:DC
06-21 09:27:45.074 20229 20265 I BlueNet : Attempting to reconnect...
06-21 09:27:45.079 20229 20265 I BlueNet : trying to connect!
06-21 09:27:45.938 20229 20264 I APP_INFO: Gatt Server connected to 6D:CB:FA:3E:D3:DC
06-21 09:27:45.952 20229 20265 I APP_INFO: Connected to GATT server at 6D:CB:FA:3E:D3:DC
06-21 09:27:45.954 20229 20265 I APP_INFO: Starting service discoverytrue
06-21 09:27:47.346 20229 20264 I APP_INFO: Subscribe device to notifications: 4D:F6:18:38:0E:0E
06-21 09:27:48.428 20229 20264 I APP_INFO: Gatt Server disconnected from 4D:F6:18:38:0E:0E

Device B:

06-21 09:27:44.439  3473  3473 I MapsActivity: Location: 41.6813291 -86.2290033
06-21 09:27:44.441  3473  3473 I BlueNet : Hit RoutingManager
06-21 09:27:44.443  3473  3473 I BlueNet : Sending a packet!
06-21 09:27:44.443  3473  3473 I BlueNet : Hit BLEWriter
06-21 09:27:44.552  3473  3509 I BlueNet : notifying 42:A1:91:56:B2:B2
06-21 09:27:44.553  3473  3509 I BlueNet : Notification sent!
06-21 09:27:44.732  3473  3509 I BlueNet : sending read response of length 10 of payload of length 10
06-21 09:27:45.081  3473  3509 I APP_INFO: Gatt Server disconnected from 4A:FD:1B:00:06:C7
06-21 09:27:45.083  3473  3517 E BlueNet : Error in onConnectionStatechange -- status: 19, state: 0
06-21 09:27:45.084  3473  3510 I APP_INFO: Disconnected from GATT server at 4A:FD:1B:00:06:C7
06-21 09:27:45.087  3473  3510 I BlueNet : Attempting to reconnect...
06-21 09:27:45.093  3473  3510 I BlueNet : trying to connect!
06-21 09:27:45.707  3473  3509 I APP_INFO: Gatt Server connected to 4A:FD:1B:00:06:C7
06-21 09:27:45.720  3473  3510 I APP_INFO: Connected to GATT server at 4A:FD:1B:00:06:C7
06-21 09:27:45.722  3473  3510 I APP_INFO: Starting service discoverytrue
06-21 09:27:46.301  3473  3509 I APP_INFO: Gatt Server disconnected from 42:A1:91:56:B2:B2
06-21 09:27:47.074  3473  3509 I APP_INFO: Gatt Server connected to 42:A1:91:56:B2:B2
06-21 09:27:48.538  3473  3510 I BlueNet : Enable characteristic notifications
06-21 09:27:49.662  3473  3509 I APP_INFO: Gatt Server disconnected from 4A:FD:1B:00:06:C7

Additionally, the hci logs show that only one connection is actually created:

Device A: image

Device B: image

Eventually, an HCI_CMD to disconnect comes along on both sides and ruins everything...