From 777e0f67757f4568309f8a9661f1f072431f000e Mon Sep 17 00:00:00 2001 From: geeksville Date: Tue, 7 Jul 2020 10:39:26 -0700 Subject: [PATCH] fix autobug on a "redmi 5 plus" phone. This phone repeatedly (and rapidly) tells the phone the BLE device is bonded... which was cause the RadioInterfaceService to screate two instances of of the BluetoothInterface (ouch). So now rather than checking for isConnected when changing device addresses, we check for 'isStarted' which is a new state we've added. Interfaces progress from !started to started to started+connected. When an interface disconnects it goes !connected. When the user stops an interface it goes !started. annotated crashlytics log follows 419 | Mon Jul 06 2020 18:21:34 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.ui.BTScanModel: BTScan component active 420 | Mon Jul 06 2020 18:21:34 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.ui.BTScanModel: starting scan 421 | Mon Jul 06 2020 18:21:35 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.ui.BTScanModel: onScanResult DeviceListEntry(name=...a14, addr=...:16) 422 | Mon Jul 06 2020 18:21:35 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.ui.BTScanModel: onScanResult DeviceListEntry(name=...ad8, addr=...:DA) 423 | Mon Jul 06 2020 18:21:35 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.ui.SettingsFragment: We have location access 424 | Mon Jul 06 2020 18:21:36 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.ui.SLogging: Received bond state changed 12 425 | Mon Jul 06 2020 18:21:36 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.ui.SLogging: Bonding completed, state=12 426 | Mon Jul 06 2020 18:21:36 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.ui.BTScanModel: Changing device to ...:16 *** bond complete occurred so we started service and tried to connect 427 | Mon Jul 06 2020 18:21:36 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.MeshService: Passing through device change to radio service: xCC:50:E3:B6:0A:16 428 | Mon Jul 06 2020 18:21:36 GMT-0700 (Pacific Daylight Time) | com.geeksville.analytics.GoogleAnalytics: Analytics: track mesh_bond 429 | Mon Jul 06 2020 18:21:36 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.RadioInterfaceService: stopping interface com.geeksville.mesh.service.BluetoothInterface@b3a5506 430 | Mon Jul 06 2020 18:21:36 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Closing BluetoothInterface 431 | Mon Jul 06 2020 18:21:36 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Closing our GATT connection 432 | Mon Jul 06 2020 18:21:36 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: new bluetooth connection state 0, status 0 433 | Mon Jul 06 2020 18:21:36 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Got disconnect because we are shutting down, closing gatt 434 | Mon Jul 06 2020 18:21:36 GMT-0700 (Pacific Daylight Time) | mesh_bond 435 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Failing 0 works, because Connection closing 436 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.RadioInterfaceService: Broadcasting connection=false 437 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.RadioInterfaceService: Setting bonded device to xCC:50:E3:B6:0A:16 438 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.RadioInterfaceService: Starting radio xCC:50:E3:B6:0A:16 439 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Creating radio interface service. device=...:16 440 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: connect 441 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: connect 442 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.MeshService: Discarding NodeDB 443 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.MeshService$Companion: Trying to start service 444 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: new bluetooth connection state 2, status 0 445 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.ui.SLogging: Received bond state changed 12 ** BONDED 446 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: work connect is completed, resuming status=0, res=kotlin.Unit 447 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Connected to radio! *** in connect callback 448 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.ui.SLogging: Bonding completed, state=12 449 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.ui.BTScanModel: Changing device to ...:16 *** bond complete occurred so we started service and tried to connect SECOND TIME 450 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.MeshService: Passing through device change to radio service: xCC:50:E3:B6:0A:16 451 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.analytics.GoogleAnalytics: Analytics: track mesh_bond 452 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.RadioInterfaceService: stopping interface com.geeksville.mesh.service.BluetoothInterface@fe0fede 453 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Closing BluetoothInterface 454 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Closing our GATT connection 455 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: new bluetooth connection state 0, status 0 456 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Got disconnect because we are shutting down, closing gatt 457 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | mesh_bond 458 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Failing 0 works, because Connection closing 459 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.RadioInterfaceService: Setting bonded device to xCC:50:E3:B6:0A:16 460 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.RadioInterfaceService: Starting radio xCC:50:E3:B6:0A:16 461 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Creating radio interface service. device=...:16 462 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: connect 463 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: connect 464 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.MeshService: Discarding NodeDB 465 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.MeshService$Companion: Trying to start service 466 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: new bluetooth connection state 2, status 0 467 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: work connect is completed, resuming status=0, res=kotlin.Unit 468 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Connected to radio! 469 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.MeshService: Received broadcast com.geeksville.mesh.CONNECT_CHANGED 470 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.MeshService: onConnectionChanged=DISCONNECTED 471 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.analytics.GoogleAnalytics: Analytics: track mesh_disconnect 472 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.analytics.GoogleAnalytics: Analytics: track num_nodes 473 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.MeshService: Requesting foreground service=true *** TWO REQUEST FOREGROUND 474 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.ui.BTScanModel: onScanResult DeviceListEntry(name=...a14, addr=...:16) 475 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.MeshService: Requesting foreground service=true 476 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.MainActivity: Received from mesh service Intent { act=com.geeksville.mesh.MESH_CONNECTED flg=0x10 (has extras) } 477 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: reqMtu 478 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: reqMtu 479 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Starting failsafe timer 10000 480 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.MainActivity: connchange DISCONNECTED 481 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | mesh_disconnect 482 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | num_nodes 483 | Mon Jul 06 2020 18:21:37 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: reqMtu 484 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: reqMtu 485 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Starting failsafe timer 10000 486 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: work reqMtu is completed, resuming status=0, res=kotlin.Unit *** TWO MTU RUNNIGN!!! 487 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: MTU change attempted 488 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: discover 489 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: discover 490 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: work reqMtu is completed, resuming status=0, res=kotlin.Unit 491 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: MTU change attempted 492 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: discover 493 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: discover *** we have TWO DISOVERS RUNNING!!!! 494 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: work discover is completed, resuming status=0, res=kotlin.Unit 495 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Discovered services! 496 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: work discover is completed, resuming status=0, res=kotlin.Unit 497 | Mon Jul 06 2020 18:21:38 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Discovered services! 498 | Mon Jul 06 2020 18:21:39 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Scheduling reconnect because Unexpected error in initial device enumeration, forcing disconnect com.geeksville.mesh.service.RadioNotConnectedException: BLE service not found 499 | Mon Jul 06 2020 18:21:39 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Forcing disconnect and hopefully device will comeback (disabling forced refresh) 500 | Mon Jul 06 2020 18:21:39 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Closing our GATT connection 501 | Mon Jul 06 2020 18:21:39 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Scheduling reconnect because Unexpected error in initial device enumeration, forcing disconnect com.geeksville.mesh.service.RadioNotConnectedException: BLE service not found 502 | Mon Jul 06 2020 18:21:39 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Forcing disconnect and hopefully device will comeback (disabling forced refresh) 503 | Mon Jul 06 2020 18:21:39 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Closing our GATT connection 504 | Mon Jul 06 2020 18:21:39 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: new bluetooth connection state 0, status 0 505 | Mon Jul 06 2020 18:21:39 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Got disconnect because we are shutting down, closing gatt 506 | Mon Jul 06 2020 18:21:39 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Failing 0 works, because Connection closing 507 | Mon Jul 06 2020 18:21:39 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Failing 0 works, because Connection closing 508 | Mon Jul 06 2020 18:21:40 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Attempting reconnect 509 | Mon Jul 06 2020 18:21:40 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth: Enqueuing work: connect 510 | Mon Jul 06 2020 18:21:40 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.SafeBluetooth$BluetoothContinuation: Starting work: connect 511 | Mon Jul 06 2020 18:21:40 GMT-0700 (Pacific Daylight Time) | com.geeksville.mesh.service.BluetoothInterface: Attempting reconnect 512 | Mon Jul 06 2020 18:21:40 GMT-0700 (Pacific Daylight Time) | com.geeksville.util.Exceptions: MeshService-coroutine coroutine-exception (exception currentWork was not null: Work:connect) Non-fatal Exception: java.lang.AssertionError: currentWork was not null: Work:connect at com.geeksville.mesh.service.SafeBluetooth.asyncConnect(SafeBluetooth.java:531) at com.geeksville.mesh.service.BluetoothInterface.startConnect(BluetoothInterface.java:464) at com.geeksville.mesh.service.BluetoothInterface.retryDueToException(BluetoothInterface.java:342) at com.geeksville.mesh.service.BluetoothInterface$retryDueToException$1.invokeSuspend(BluetoothInterface.java:11) at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(BaseContinuationImpl.java:33) at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.java:56) at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.java:571) at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.java:738) at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.java:678) at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.java:665) 0.7.90 --- .../mesh/service/RadioInterfaceService.kt | 14 +++++++++++--- 1 file changed, 11 insertions(+), 3 deletions(-) diff --git a/app/src/main/java/com/geeksville/mesh/service/RadioInterfaceService.kt b/app/src/main/java/com/geeksville/mesh/service/RadioInterfaceService.kt index c9bb06521..7b674d9bb 100644 --- a/app/src/main/java/com/geeksville/mesh/service/RadioInterfaceService.kt +++ b/app/src/main/java/com/geeksville/mesh/service/RadioInterfaceService.kt @@ -126,6 +126,14 @@ class RadioInterfaceService : Service(), Logging { private val nopIf = NopInterface() private var radioIf: IRadioInterface = nopIf + /** true if we have started our interface + * + * Note: an interface may be started without necessarily yet having a connection + */ + private var isStarted = false + + /// true if our interface is currently connected to a device + private var isConnected = false /** * If the user turns on bluetooth after we start, make sure to try and reconnected then @@ -165,8 +173,6 @@ class RadioInterfaceService : Service(), Logging { ) } - private var isConnected = false - fun onConnect() { if (!isConnected) { isConnected = true @@ -211,6 +217,7 @@ class RadioInterfaceService : Service(), Logging { warn("No bonded mesh radio, can't start interface") else { info("Starting radio $address") + isStarted = true if (logSends) sentPacketsLog = BinaryLogFile(this, "sent_log.pb") @@ -236,6 +243,7 @@ class RadioInterfaceService : Service(), Logging { private fun stopInterface() { val r = radioIf info("stopping interface $r") + isStarted = false radioIf = nopIf r.close() @@ -257,7 +265,7 @@ class RadioInterfaceService : Service(), Logging { */ @SuppressLint("NewApi") private fun setBondedDeviceAddress(address: String?): Boolean { - return if (getBondedDeviceAddress(this) == address && isConnected) { + return if (getBondedDeviceAddress(this) == address && isStarted) { warn("Ignoring setBondedDevice $address, because we are already using that device") false } else {