chore: enhance bluetooth and wifi connection logging (#3960)

This commit is contained in:
Mac DeCourcy 2025-12-13 12:44:23 -08:00 committed by GitHub
parent 3a74389eaa
commit f51b7fb0f2
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
6 changed files with 279 additions and 37 deletions

View file

@ -95,6 +95,11 @@ constructor(
private val writeMutex = Mutex()
private var peripheral: Peripheral? = null
private var connectionStartTime: Long = 0
private var packetsReceived: Int = 0
private var packetsSent: Int = 0
private var bytesReceived: Long = 0
private var bytesSent: Long = 0
private var toRadioCharacteristic: RemoteCharacteristic? = null
private var fromNumCharacteristic: RemoteCharacteristic? = null
@ -121,7 +126,12 @@ constructor(
}
private fun dispatchPacket(packet: ByteArray) {
Timber.d("[$address] Dispatching packet to service.handleFromRadio()")
packetsReceived++
bytesReceived += packet.size
Timber.d(
"[$address] Dispatching packet to service.handleFromRadio() - " +
"Packet #$packetsReceived, ${packet.size} bytes (Total: $bytesReceived bytes)",
)
try {
service.handleFromRadio(p = packet)
} catch (t: Throwable) {
@ -157,14 +167,20 @@ constructor(
private fun connect() {
connectionScope.launch {
try {
connectionStartTime = System.currentTimeMillis()
Timber.i("[$address] BLE connection attempt started at $connectionStartTime")
peripheral = retryCall { findAndConnectPeripheral() }
peripheral?.let {
val connectionTime = System.currentTimeMillis() - connectionStartTime
Timber.i("[$address] BLE peripheral connected in ${connectionTime}ms")
onConnected()
observePeripheralChanges()
discoverServicesAndSetupCharacteristics(it)
}
} catch (e: Exception) {
Timber.e(e, "[$address] Failed to connect to peripheral")
val failureTime = System.currentTimeMillis() - connectionStartTime
Timber.e(e, "[$address] Failed to connect to peripheral after ${failureTime}ms")
service.onDisconnect(BleError.from(e))
}
}
@ -196,21 +212,35 @@ constructor(
private fun observePeripheralChanges() {
peripheral?.let { p ->
p.phy.onEach { phy -> Timber.d("[$address] PHY changed to $phy") }.launchIn(connectionScope)
p.phy.onEach { phy -> Timber.i("[$address] BLE PHY changed to $phy") }.launchIn(connectionScope)
p.connectionParameters
.onEach { Timber.d("[$address] Connection parameters changed to $it") }
.onEach { params -> Timber.i("[$address] BLE connection parameters changed to $params") }
.launchIn(connectionScope)
p.state
.onEach { state ->
Timber.d("[$address] State changed to $state")
Timber.i("[$address] BLE connection state changed to $state")
if (state is ConnectionState.Disconnected) {
val uptime =
if (connectionStartTime > 0) {
System.currentTimeMillis() - connectionStartTime
} else {
0
}
Timber.w(
"[$address] BLE disconnected - Reason: ${state.reason}, " +
"Uptime: ${uptime}ms, " +
"Packets RX: $packetsReceived ($bytesReceived bytes), " +
"Packets TX: $packetsSent ($bytesSent bytes)",
)
service.onDisconnect(BleError.Disconnected(reason = state.reason))
}
}
.launchIn(connectionScope)
}
centralManager.state
.onEach { state -> Timber.d("CentralManager state changed to $state") }
.onEach { state -> Timber.i("[$address] CentralManager state changed to $state") }
.launchIn(connectionScope)
}
@ -314,8 +344,15 @@ constructor(
throw e
} catch (e: Exception) {
currentAttempt++
if (currentAttempt >= RETRY_COUNT) throw e
Timber.w(e, "[$address] Operation failed, retrying ($currentAttempt/$RETRY_COUNT)...")
if (currentAttempt >= RETRY_COUNT) {
Timber.e(e, "[$address] BLE operation failed after $RETRY_COUNT attempts, giving up")
throw e
}
Timber.w(
e,
"[$address] BLE operation failed (attempt $currentAttempt/$RETRY_COUNT), " +
"retrying in ${RETRY_DELAY_MS}ms...",
)
delay(RETRY_DELAY_MS)
}
}
@ -330,7 +367,10 @@ constructor(
*/
override fun handleSendToRadio(p: ByteArray) {
toRadioCharacteristic?.let { characteristic ->
if (peripheral == null) return@let
if (peripheral == null) {
Timber.w("[$address] BLE peripheral is null, cannot send packet")
return@let
}
connectionScope.launch {
writeMutex.withLock {
try {
@ -341,22 +381,43 @@ constructor(
WriteType.WITH_RESPONSE
}
retryCall {
Timber.d("[$address] Writing packet to toRadioCharacteristic with $writeType")
packetsSent++
bytesSent += p.size
Timber.d(
"[$address] Writing packet #$packetsSent to toRadioCharacteristic with $writeType - " +
"${p.size} bytes (Total TX: $bytesSent bytes)",
)
characteristic.write(p, writeType = writeType)
}
drainPacketQueueAndDispatch()
} catch (e: Exception) {
Timber.e(e, "[$address] Failed to write packet to toRadioCharacteristic")
Timber.e(
e,
"[$address] Failed to write packet to toRadioCharacteristic after " +
"$packetsSent successful writes",
)
service.onDisconnect(BleError.from(e))
}
}
}
} ?: Timber.w("[$address] toRadio unavailable, can't send data")
} ?: Timber.w("[$address] toRadio characteristic unavailable, can't send data")
}
/** Closes the connection to the device. */
override fun close() {
runBlocking {
val uptime =
if (connectionStartTime > 0) {
System.currentTimeMillis() - connectionStartTime
} else {
0
}
Timber.i(
"[$address] BLE close() called - " +
"Uptime: ${uptime}ms, " +
"Packets RX: $packetsReceived ($bytesReceived bytes), " +
"Packets TX: $packetsSent ($bytesSent bytes)",
)
connectionScope.cancel()
peripheral?.disconnect()
service.onDisconnect(true)

View file

@ -48,16 +48,30 @@ constructor(
override fun connect() {
val device = serialInterfaceSpec.findSerial(address)
if (device == null) {
Timber.e("Can't find device")
Timber.e("[$address] Serial device not found at address")
} else {
Timber.i("Opening $device")
val onConnect: () -> Unit = { super.connect() }
val connectStart = System.currentTimeMillis()
Timber.i("[$address] Opening serial device: $device")
var packetsReceived = 0
var bytesReceived = 0L
var connectionStartTime = 0L
val onConnect: () -> Unit = {
connectionStartTime = System.currentTimeMillis()
val connectionTime = connectionStartTime - connectStart
Timber.i("[$address] Serial device connected in ${connectionTime}ms")
super.connect()
}
usbRepository
.createSerialConnection(
device,
object : SerialConnectionListener {
override fun onMissingPermission() {
Timber.e("Need permissions for port")
Timber.e(
"[$address] Serial connection failed - missing USB permissions for device: $device",
)
}
override fun onConnected() {
@ -65,13 +79,29 @@ constructor(
}
override fun onDataReceived(bytes: ByteArray) {
Timber.d("Received ${bytes.size} byte(s)")
packetsReceived++
bytesReceived += bytes.size
Timber.d(
"[$address] Serial received packet #$packetsReceived - " +
"${bytes.size} byte(s) (Total RX: $bytesReceived bytes)",
)
bytes.forEach(::readChar)
}
override fun onDisconnected(thrown: Exception?) {
thrown?.let { e -> Timber.e("Serial error: $e") }
Timber.d("$device disconnected")
val uptime =
if (connectionStartTime > 0) {
System.currentTimeMillis() - connectionStartTime
} else {
0
}
thrown?.let { e -> Timber.e(e, "[$address] Serial error after ${uptime}ms: ${e.message}") }
Timber.w(
"[$address] Serial device disconnected - " +
"Device: $device, " +
"Uptime: ${uptime}ms, " +
"Packets RX: $packetsReceived ($bytesReceived bytes)",
)
onDeviceDisconnect(false)
}
},
@ -84,6 +114,12 @@ constructor(
}
override fun sendBytes(p: ByteArray) {
connRef.get()?.sendBytes(p)
val conn = connRef.get()
if (conn != null) {
Timber.d("[$address] Serial sending ${p.size} bytes")
conn.sendBytes(p)
} else {
Timber.w("[$address] Serial connection not available, cannot send ${p.size} bytes")
}
}
}

View file

@ -44,6 +44,7 @@ class TCPInterface @AssistedInject constructor(service: RadioInterfaceService, @
const val SOCKET_TIMEOUT = 5000
const val SOCKET_RETRIES = 18
const val SERVICE_PORT = NetworkRepository.SERVICE_PORT
const val TIMEOUT_LOG_INTERVAL = 5 // Log every Nth timeout
}
private var retryCount = 1
@ -52,22 +53,45 @@ class TCPInterface @AssistedInject constructor(service: RadioInterfaceService, @
private var socket: Socket? = null
private lateinit var outStream: OutputStream
private var connectionStartTime: Long = 0
private var packetsReceived: Int = 0
private var packetsSent: Int = 0
private var bytesReceived: Long = 0
private var bytesSent: Long = 0
private var timeoutEvents: Int = 0
init {
connect()
}
override fun sendBytes(p: ByteArray) {
packetsSent++
bytesSent += p.size
Timber.d("[$address] TCP sending packet #$packetsSent - ${p.size} bytes (Total TX: $bytesSent bytes)")
outStream.write(p)
}
override fun flushBytes() {
Timber.d("[$address] TCP flushing output stream")
outStream.flush()
}
override fun onDeviceDisconnect(waitForStopped: Boolean) {
val s = socket
if (s != null) {
Timber.d("Closing TCP socket")
val uptime =
if (connectionStartTime > 0) {
System.currentTimeMillis() - connectionStartTime
} else {
0
}
Timber.w(
"[$address] TCP disconnecting - " +
"Uptime: ${uptime}ms, " +
"Packets RX: $packetsReceived ($bytesReceived bytes), " +
"Packets TX: $packetsSent ($bytesSent bytes), " +
"Timeout events: $timeoutEvents",
)
s.close()
socket = null
}
@ -80,37 +104,66 @@ class TCPInterface @AssistedInject constructor(service: RadioInterfaceService, @
try {
startConnect()
} catch (ex: IOException) {
Timber.e("IOException in TCP reader: $ex")
val uptime =
if (connectionStartTime > 0) {
System.currentTimeMillis() - connectionStartTime
} else {
0
}
Timber.e(ex, "[$address] TCP IOException after ${uptime}ms - ${ex.message}")
onDeviceDisconnect(false)
} catch (ex: Throwable) {
val uptime =
if (connectionStartTime > 0) {
System.currentTimeMillis() - connectionStartTime
} else {
0
}
Timber.e(ex, "[$address] TCP exception after ${uptime}ms - ${ex.message}")
Exceptions.report(ex, "Exception in TCP reader")
onDeviceDisconnect(false)
}
if (retryCount > MAX_RETRIES_ALLOWED) break
if (retryCount > MAX_RETRIES_ALLOWED) {
Timber.e("[$address] TCP max retries ($MAX_RETRIES_ALLOWED) exceeded, giving up")
break
}
Timber.d("Reconnect attempt $retryCount in ${backoffDelay / 1000}s")
Timber.i(
"[$address] TCP reconnect attempt #$retryCount in ${backoffDelay / 1000}s " +
"(backoff: ${backoffDelay}ms)",
)
delay(backoffDelay)
retryCount++
backoffDelay = minOf(backoffDelay * 2, MAX_BACKOFF_MILLIS)
}
Timber.d("Exiting TCP reader")
Timber.i("[$address] TCP reader exiting")
}
}
// Create a socket to make the connection with the server
private suspend fun startConnect() = withContext(Dispatchers.IO) {
Timber.d("TCP connecting to $address")
val attemptStart = System.currentTimeMillis()
Timber.i("[$address] TCP connection attempt starting...")
val (host, port) =
address.split(":", limit = 2).let { it[0] to (it.getOrNull(1)?.toIntOrNull() ?: SERVICE_PORT) }
Timber.d("[$address] Resolving host '$host' and connecting to port $port...")
Socket(InetAddress.getByName(host), port).use { socket ->
socket.tcpNoDelay = true
socket.soTimeout = SOCKET_TIMEOUT
this@TCPInterface.socket = socket
val connectTime = System.currentTimeMillis() - attemptStart
connectionStartTime = System.currentTimeMillis()
Timber.i(
"[$address] TCP socket connected in ${connectTime}ms - " +
"Local: ${socket.localSocketAddress}, Remote: ${socket.remoteSocketAddress}",
)
BufferedOutputStream(socket.getOutputStream()).use { outputStream ->
outStream = outputStream
@ -125,17 +178,33 @@ class TCPInterface @AssistedInject constructor(service: RadioInterfaceService, @
try { // close after 90s of inactivity
val c = inputStream.read()
if (c == -1) {
Timber.w("Got EOF on TCP stream")
Timber.w("[$address] TCP got EOF on stream after $packetsReceived packets received")
break
} else {
timeoutCount = 0
packetsReceived++
bytesReceived++
readChar(c.toByte())
}
} catch (ex: SocketTimeoutException) {
timeoutCount++
timeoutEvents++
if (timeoutCount % TIMEOUT_LOG_INTERVAL == 0) {
Timber.d(
"[$address] TCP socket timeout count: $timeoutCount/$SOCKET_RETRIES " +
"(total timeouts: $timeoutEvents)",
)
}
// Ignore and start another read
}
}
if (timeoutCount >= SOCKET_RETRIES) {
val inactivityMs = SOCKET_RETRIES * SOCKET_TIMEOUT
Timber.w(
"[$address] TCP closing connection due to $SOCKET_RETRIES consecutive timeouts " +
"(${inactivityMs}ms of inactivity)",
)
}
}
}
onDeviceDisconnect(false)

View file

@ -1855,10 +1855,19 @@ class MeshService : Service() {
/**
* Regenerate the myNodeInfo model. We call this twice. Once after we receive myNodeInfo from the device and again
* after we have the node DB (which might allow us a better notion of our HwModel.
* after we have the node DB (which might allow us a better notion of our HwModel).
*/
private fun regenMyNodeInfo(metadata: MeshProtos.DeviceMetadata? = MeshProtos.DeviceMetadata.getDefaultInstance()) {
val myInfo = rawMyNodeInfo
val hasMetadata = metadata != null && metadata != MeshProtos.DeviceMetadata.getDefaultInstance()
Timber.i(
"[MYNODE_REGEN] Called - " +
"rawMyNodeInfo: ${if (myInfo != null) "present" else "null"}, " +
"metadata: ${if (hasMetadata) "present" else "null/default"}, " +
"firmwareVersion: ${metadata?.firmwareVersion ?: "null"}, " +
"hasWifi: ${metadata?.hasWifi}",
)
if (myInfo != null) {
val mi =
with(myInfo) {
@ -1883,10 +1892,22 @@ class MeshService : Service() {
deviceId = deviceId.toStringUtf8(),
)
}
Timber.i(
"[MYNODE_REGEN] Created MyNodeEntity - " +
"nodeNum: ${mi.myNodeNum}, " +
"model: ${mi.model}, " +
"firmwareVersion: ${mi.firmwareVersion}, " +
"hasWifi: ${mi.hasWifi}",
)
if (metadata != null && metadata != MeshProtos.DeviceMetadata.getDefaultInstance()) {
serviceScope.handledLaunch { nodeRepository.insertMetadata(MetadataEntity(mi.myNodeNum, metadata)) }
}
newMyNodeInfo = mi
Timber.i("[MYNODE_REGEN] Set newMyNodeInfo (will be committed on configComplete)")
} else {
Timber.w("[MYNODE_REGEN] rawMyNodeInfo is null, cannot regenerate")
}
}
@ -1901,7 +1922,12 @@ class MeshService : Service() {
/** Update MyNodeInfo (called from either new API version or the old one) */
private fun handleMyInfo(myInfo: MeshProtos.MyNodeInfo) {
Timber.d("[myInfo] ${myInfo.toPIIString()}")
Timber.i(
"[MYINFO_RECEIVED] MyNodeInfo received - " +
"nodeNum: ${myInfo.myNodeNum}, " +
"minAppVersion: ${myInfo.minAppVersion}, " +
"PII data: ${myInfo.toPIIString()}",
)
val packetToSave =
MeshLog(
uuid = UUID.randomUUID().toString(),
@ -1913,6 +1939,7 @@ class MeshService : Service() {
insertMeshLog(packetToSave)
rawMyNodeInfo = myInfo
Timber.i("[MYINFO_RECEIVED] Set rawMyNodeInfo, calling regenMyNodeInfo()")
regenMyNodeInfo()
// We'll need to get a new set of channels and settings now
@ -1925,7 +1952,14 @@ class MeshService : Service() {
/** Update our DeviceMetadata */
private fun handleMetadata(metadata: MeshProtos.DeviceMetadata) {
Timber.d("[deviceMetadata] ${metadata.toPIIString()}")
Timber.i(
"[METADATA_RECEIVED] DeviceMetadata received - " +
"firmwareVersion: ${metadata.firmwareVersion}, " +
"hwModel: ${metadata.hwModel}, " +
"hasWifi: ${metadata.hasWifi}, " +
"hasBluetooth: ${metadata.hasBluetooth}, " +
"PII data: ${metadata.toPIIString()}",
)
val packetToSave =
MeshLog(
uuid = UUID.randomUUID().toString(),
@ -1936,6 +1970,10 @@ class MeshService : Service() {
)
insertMeshLog(packetToSave)
Timber.i(
"[METADATA_RECEIVED] Calling regenMyNodeInfo with metadata - " +
"This will update newMyNodeInfo with firmwareVersion: ${metadata.firmwareVersion}",
)
regenMyNodeInfo(metadata)
}
@ -2089,7 +2127,7 @@ class MeshService : Service() {
}
private fun handleConfigOnlyComplete() {
Timber.d("Config-only complete for nonce $configOnlyNonce")
Timber.i("[CONFIG_COMPLETE] Config-only complete for nonce $configOnlyNonce")
val packetToSave =
MeshLog(
uuid = UUID.randomUUID().toString(),
@ -2101,9 +2139,16 @@ class MeshService : Service() {
insertMeshLog(packetToSave)
if (newMyNodeInfo == null) {
Timber.e("Did not receive a valid config")
Timber.e("[CONFIG_COMPLETE] Did not receive a valid config - newMyNodeInfo is null")
} else {
Timber.i(
"[CONFIG_COMPLETE] Committing newMyNodeInfo to myNodeInfo - " +
"firmwareVersion: ${newMyNodeInfo?.firmwareVersion}, " +
"hasWifi: ${newMyNodeInfo?.hasWifi}, " +
"model: ${newMyNodeInfo?.model}",
)
myNodeInfo = newMyNodeInfo
Timber.i("[CONFIG_COMPLETE] myNodeInfo committed successfully")
}
// Keep BLE awake and allow the firmware to settle before the node-info stage.
serviceScope.handledLaunch {

View file

@ -485,9 +485,21 @@ private fun VersionChecks(viewModel: UIViewModel) {
// Check if the device is running an old app version or firmware version
LaunchedEffect(connectionState, myNodeInfo) {
if (connectionState == ConnectionState.Connected) {
Timber.i(
"[FW_CHECK] Connection state: $connectionState, " +
"myNodeInfo: ${if (myNodeInfo != null) "present" else "null"}, " +
"firmwareVersion: ${myFirmwareVersion ?: "null"}",
)
myNodeInfo?.let { info ->
val isOld = info.minAppVersion > BuildConfig.VERSION_CODE && BuildConfig.DEBUG.not()
Timber.d(
"[FW_CHECK] App version check - minAppVersion: ${info.minAppVersion}, " +
"currentVersion: ${BuildConfig.VERSION_CODE}, isOld: $isOld",
)
if (isOld) {
Timber.w("[FW_CHECK] App too old - showing update prompt")
viewModel.showAlert(
getString(Res.string.app_too_old),
getString(Res.string.must_update),
@ -498,9 +510,20 @@ private fun VersionChecks(viewModel: UIViewModel) {
},
)
} else {
myFirmwareVersion?.let {
val curVer = DeviceVersion(it)
myFirmwareVersion?.let { fwVersion ->
val curVer = DeviceVersion(fwVersion)
Timber.i(
"[FW_CHECK] Firmware version comparison - " +
"device: $curVer (raw: $fwVersion), " +
"absoluteMin: ${MeshService.absoluteMinDeviceVersion}, " +
"min: ${MeshService.minDeviceVersion}",
)
if (curVer < MeshService.absoluteMinDeviceVersion) {
Timber.w(
"[FW_CHECK] Firmware too old - " +
"device: $curVer < absoluteMin: ${MeshService.absoluteMinDeviceVersion}",
)
val title = getString(Res.string.firmware_too_old)
val message = getString(Res.string.firmware_old)
viewModel.showAlert(
@ -513,13 +536,21 @@ private fun VersionChecks(viewModel: UIViewModel) {
},
)
} else if (curVer < MeshService.minDeviceVersion) {
Timber.w(
"[FW_CHECK] Firmware should update - " +
"device: $curVer < min: ${MeshService.minDeviceVersion}",
)
val title = getString(Res.string.should_update_firmware)
val message = getString(Res.string.should_update, latestStableFirmwareRelease.asString)
viewModel.showAlert(title = title, message = message, dismissable = false, onConfirm = {})
} else {
Timber.i("[FW_CHECK] Firmware version OK - device: $curVer meets requirements")
}
}
} ?: run { Timber.w("[FW_CHECK] Firmware version is null despite myNodeInfo being present") }
}
}
} ?: run { Timber.d("[FW_CHECK] myNodeInfo is null, skipping firmware check") }
} else {
Timber.d("[FW_CHECK] Not connected (state: $connectionState), skipping firmware check")
}
}
}

@ -1 +1 @@
Subproject commit 4095e598902b4cd893dbcb62842514704d0f64e0
Subproject commit 52fa252f1e01be87ad2f7ab17ceef7882b2a4a93