Meshtastic-Android/app/src/main/java/com/geeksville/mesh/service/RadioInterfaceService.kt

344 lines
12 KiB
Kotlin
Raw Normal View History

package com.geeksville.mesh.service
import android.annotation.SuppressLint
import android.app.Service
import android.content.Context
import android.content.Intent
import android.content.SharedPreferences
import android.os.IBinder
import androidx.core.content.edit
import com.geeksville.android.BinaryLogFile
2021-02-01 10:31:39 +08:00
import com.geeksville.android.BuildUtils.isEmulator
import com.geeksville.android.GeeksvilleApplication
import com.geeksville.android.Logging
import com.geeksville.concurrent.handledLaunch
import com.geeksville.mesh.IRadioInterfaceService
import com.geeksville.util.anonymize
import com.geeksville.util.ignoreException
import com.geeksville.util.toRemoteExceptions
import kotlinx.coroutines.CoroutineScope
import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.Job
import kotlinx.coroutines.cancel
open class RadioNotConnectedException(message: String = "Not connected to radio") :
BLEException(message)
2021-03-02 13:22:55 +08:00
/**
* Handles the bluetooth link with a mesh radio device. Does not cache any device state,
* just does bluetooth comms etc...
*
* This service is not exposed outside of this process.
*
* Note - this class intentionally dumb. It doesn't understand protobuf framing etc...
* It is designed to be simple so it can be stubbed out with a simulated version as needed.
*/
class RadioInterfaceService : Service(), Logging {
companion object : Logging {
/**
* The RECEIVED_FROMRADIO
* Payload will be the raw bytes which were contained within a MeshProtos.FromRadio protobuf
*/
const val RECEIVE_FROMRADIO_ACTION = "$prefix.RECEIVE_FROMRADIO"
/**
* This is broadcast when connection state changed
*/
const val RADIO_CONNECTED_ACTION = "$prefix.CONNECT_CHANGED"
const val DEVADDR_KEY_OLD = "devAddr"
const val DEVADDR_KEY = "devAddr2" // the new name for devaddr
/// This is public only so that SimRadio can bootstrap our message flow
fun broadcastReceivedFromRadio(context: Context, payload: ByteArray) {
val intent = Intent(RECEIVE_FROMRADIO_ACTION)
intent.putExtra(EXTRA_PAYLOAD, payload)
context.sendBroadcast(intent)
}
fun getPrefs(context: Context): SharedPreferences =
context.getSharedPreferences("radio-prefs", Context.MODE_PRIVATE)
/** Return the device we are configured to use, or null for none
* device address strings are of the form:
*
* at
*
* where a is either x for bluetooth or s for serial
* and t is an interface specific address (macaddr or a device path)
*/
@SuppressLint("NewApi")
fun getDeviceAddress(context: Context): String? {
// If the user has unpaired our device, treat things as if we don't have one
val prefs = getPrefs(context)
var address = prefs.getString(DEVADDR_KEY, null)
if (address == null) { /// Check for the old preferences name we used to use
var rest = prefs.getString(DEVADDR_KEY_OLD, null)
if(rest == "null")
rest = null
if (rest != null)
2021-02-01 10:31:39 +08:00
address = BluetoothInterface.toInterfaceName(rest) // Add the bluetooth prefix
}
2021-02-01 10:31:39 +08:00
// If we are running on the emulator we default to the mock interface, so we can have some data to show to the user
if(address == null && isMockInterfaceAvailable(context))
2021-02-01 10:31:39 +08:00
address = MockInterface.interfaceName
return address
}
/** return true if we should show the mock interface on this device
* (ie are we in an emulator or in testlab
*/
fun isMockInterfaceAvailable(context: Context) = isEmulator || ((context.applicationContext as GeeksvilleApplication).isInTestLab)
/** Like getDeviceAddress, but filtered to return only devices we are currently bonded with
*
* at
*
* where a is either x for bluetooth or s for serial
* and t is an interface specific address (macaddr or a device path)
*/
@SuppressLint("NewApi")
fun getBondedDeviceAddress(context: Context): String? {
// If the user has unpaired our device, treat things as if we don't have one
var address = getDeviceAddress(context)
/// Interfaces can filter addresses to indicate that address is no longer acceptable
if (address != null) {
val c = address[0]
val rest = address.substring(1)
val isValid = when (c) {
'x' -> BluetoothInterface.addressValid(context, rest)
2020-06-08 19:15:18 -07:00
's' -> SerialInterface.addressValid(context, rest)
'n' -> true
2021-02-01 10:31:39 +08:00
'm' -> true
2020-06-08 19:15:18 -07:00
else -> TODO("Unexpected interface type $c")
}
if (!isValid)
return null
}
return address
}
/// If our service is currently running, this pointer can be used to reach it (in case setBondedDeviceAddress is called)
private var runningService: RadioInterfaceService? = null
}
private val logSends = false
private val logReceives = false
private lateinit var sentPacketsLog: BinaryLogFile // inited in onCreate
private lateinit var receivedPacketsLog: BinaryLogFile
/**
* We recreate this scope each time we stop an interface
*/
var serviceScope = CoroutineScope(Dispatchers.IO + Job())
private val nopIf = NopInterface()
private var radioIf: IRadioInterface = nopIf
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
/** 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
*/
private val bluetoothStateReceiver = BluetoothStateReceiver { enabled ->
if (enabled)
startInterface() // If bluetooth just got turned on, try to restart our ble link (which might be bluetooth)
else if (radioIf is BluetoothInterface)
stopInterface() // Was using bluetooth, need to shutdown
}
2020-06-14 16:43:36 -07:00
private fun broadcastConnectionChanged(isConnected: Boolean, isPermanent: Boolean) {
debug("Broadcasting connection=$isConnected")
val intent = Intent(RADIO_CONNECTED_ACTION)
intent.putExtra(EXTRA_CONNECTED, isConnected)
intent.putExtra(EXTRA_PERMANENT, isPermanent)
sendBroadcast(intent)
}
/// Send a packet/command out the radio link, this routine can block if it needs to
private fun handleSendToRadio(p: ByteArray) {
radioIf.handleSendToRadio(p)
}
// Handle an incoming packet from the radio, broadcasts it as an android intent
fun handleFromRadio(p: ByteArray) {
if (logReceives) {
receivedPacketsLog.write(p)
receivedPacketsLog.flush()
}
// ignoreException { debug("FromRadio: ${MeshProtos.FromRadio.parseFrom(p)}") }
broadcastReceivedFromRadio(
this,
p
)
}
2020-06-14 16:43:36 -07:00
fun onConnect() {
if (!isConnected) {
isConnected = true
broadcastConnectionChanged(true, false)
}
}
fun onDisconnect(isPermanent: Boolean) {
2020-06-14 16:43:36 -07:00
if (isConnected) {
isConnected = false
broadcastConnectionChanged(false, isPermanent)
}
}
override fun onCreate() {
runningService = this
super.onCreate()
registerReceiver(bluetoothStateReceiver, bluetoothStateReceiver.intentFilter)
}
override fun onDestroy() {
unregisterReceiver(bluetoothStateReceiver)
stopInterface()
serviceScope.cancel("Destroying RadioInterface")
runningService = null
super.onDestroy()
}
override fun onBind(intent: Intent?): IBinder? {
return binder;
}
/** Start our configured interface (if it isn't already running) */
private fun startInterface() {
if (radioIf != nopIf)
warn("Can't start interface - $radioIf is already running")
else {
val address = getBondedDeviceAddress(this)
if (address == null)
warn("No bonded mesh radio, can't start interface")
else {
info("Starting radio ${address.anonymize}")
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
isStarted = true
if (logSends)
sentPacketsLog = BinaryLogFile(this, "sent_log.pb")
if (logReceives)
receivedPacketsLog = BinaryLogFile(this, "receive_log.pb")
val c = address[0]
val rest = address.substring(1)
radioIf = when (c) {
'x' -> BluetoothInterface(this, rest)
's' -> SerialInterface(this, rest)
2021-02-01 10:31:39 +08:00
'm' -> MockInterface(this)
'n' -> nopIf
else -> {
errormsg("Unexpected radio interface type")
nopIf
}
}
}
}
}
private fun stopInterface() {
val r = radioIf
info("stopping interface $r")
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
isStarted = false
radioIf = nopIf
r.close()
// cancel any old jobs and get ready for the new ones
serviceScope.cancel("stopping interface")
serviceScope = CoroutineScope(Dispatchers.IO + Job())
if (logSends)
sentPacketsLog.close()
if (logReceives)
receivedPacketsLog.close()
// Don't broadcast disconnects if we were just using the nop device
if (r != nopIf)
onDisconnect(isPermanent = true) // Tell any clients we are now offline
}
/**
* Change to a new device
*
* @return true if the device changed, false if no change
*/
@SuppressLint("NewApi")
private fun setBondedDeviceAddress(address: String?): Boolean {
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
return if (getBondedDeviceAddress(this) == address && isStarted) {
warn("Ignoring setBondedDevice $address, because we are already using that device")
false
} else {
// Record that this use has configured a new radio
GeeksvilleApplication.analytics.track(
"mesh_bond"
)
// Ignore any errors that happen while closing old device
ignoreException {
stopInterface()
}
// The device address "n" can be used to mean none
debug("Setting bonded device to ${address.anonymize}")
getPrefs(this).edit(commit = true) {
this.remove(DEVADDR_KEY_OLD) // remove any old version of the key
if (address == null)
this.remove(DEVADDR_KEY)
else
putString(DEVADDR_KEY, address)
}
// Force the service to reconnect
startInterface()
true
}
}
private val binder = object : IRadioInterfaceService.Stub() {
override fun setDeviceAddress(deviceAddr: String?): Boolean = toRemoteExceptions {
setBondedDeviceAddress(deviceAddr)
}
/** If the service is not currently connected to the radio, try to connect now. At boot the radio interface service will
* not connect to a radio until this call is received. */
override fun connect() = toRemoteExceptions {
// We don't start actually talking to our device until MeshService binds to us - this prevents
// broadcasting connection events before MeshService is ready to receive them
startInterface()
}
override fun sendToRadio(a: ByteArray) {
// Do this in the IO thread because it might take a while (and we don't care about the result code)
serviceScope.handledLaunch { handleSendToRadio(a) }
}
}
}