Meshtastic-Android/app/src/main/java/com
geeksville 777e0f6775 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
2020-07-07 10:39:26 -07:00
..
geeksville/mesh fix autobug on a "redmi 5 plus" phone. This phone repeatedly (and rapidly) tells the phone the BLE device is bonded... 2020-07-07 10:39:26 -07:00