diff --git a/app/src/main/java/com/geeksville/mesh/repository/radio/NordicBleInterface.kt b/app/src/main/java/com/geeksville/mesh/repository/radio/NordicBleInterface.kt index cfb67ef87..9ceed32c7 100644 --- a/app/src/main/java/com/geeksville/mesh/repository/radio/NordicBleInterface.kt +++ b/app/src/main/java/com/geeksville/mesh/repository/radio/NordicBleInterface.kt @@ -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) diff --git a/app/src/main/java/com/geeksville/mesh/repository/radio/SerialInterface.kt b/app/src/main/java/com/geeksville/mesh/repository/radio/SerialInterface.kt index 90ecfa946..264d0cab3 100644 --- a/app/src/main/java/com/geeksville/mesh/repository/radio/SerialInterface.kt +++ b/app/src/main/java/com/geeksville/mesh/repository/radio/SerialInterface.kt @@ -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") + } } } diff --git a/app/src/main/java/com/geeksville/mesh/repository/radio/TCPInterface.kt b/app/src/main/java/com/geeksville/mesh/repository/radio/TCPInterface.kt index 4bb6d8ff7..5bc3442b8 100644 --- a/app/src/main/java/com/geeksville/mesh/repository/radio/TCPInterface.kt +++ b/app/src/main/java/com/geeksville/mesh/repository/radio/TCPInterface.kt @@ -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) diff --git a/app/src/main/java/com/geeksville/mesh/service/MeshService.kt b/app/src/main/java/com/geeksville/mesh/service/MeshService.kt index c0e923994..f221cfea2 100644 --- a/app/src/main/java/com/geeksville/mesh/service/MeshService.kt +++ b/app/src/main/java/com/geeksville/mesh/service/MeshService.kt @@ -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 { diff --git a/app/src/main/java/com/geeksville/mesh/ui/Main.kt b/app/src/main/java/com/geeksville/mesh/ui/Main.kt index bf1235d79..8c3121155 100644 --- a/app/src/main/java/com/geeksville/mesh/ui/Main.kt +++ b/app/src/main/java/com/geeksville/mesh/ui/Main.kt @@ -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") } } } diff --git a/core/proto/src/main/proto b/core/proto/src/main/proto index 4095e5989..52fa252f1 160000 --- a/core/proto/src/main/proto +++ b/core/proto/src/main/proto @@ -1 +1 @@ -Subproject commit 4095e598902b4cd893dbcb62842514704d0f64e0 +Subproject commit 52fa252f1e01be87ad2f7ab17ceef7882b2a4a93