diff --git a/AGENTS.md b/AGENTS.md index d3f6b9d227..a08b5f78ed 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -187,6 +187,7 @@ suspend fun getData(): Result = withContext(Dispatchers.IO) { - NEVER manually append the `Throwable`'s message or any other props to the string passed as the 1st param of `Logger.*` calls, its internals are already enriching the final log message with the details of the `Throwable` passed via the `e` arg - ALWAYS wrap parameter values in log messages with single quotes, e.g. `Logger.info("Received event '$eventName'", context = TAG)` - ALWAYS start log messages with a verb, e.g. `Logger.info("Received payment for '$hash'", context = TAG)` +- ALWAYS keep log names, tags, labels, and references mechanically traceable to the caller. Do not rewrite them into long descriptions. - ALWAYS log errors at the final handling layer where the error is acted upon, not in intermediate layers that just propagate it - ALWAYS use the Result API instead of try-catch - NEVER wrap methods returning `Result` in try-catch diff --git a/app/src/main/java/to/bitkit/async/ServiceQueue.kt b/app/src/main/java/to/bitkit/async/ServiceQueue.kt index b359cd73a0..68d339b7f4 100644 --- a/app/src/main/java/to/bitkit/async/ServiceQueue.kt +++ b/app/src/main/java/to/bitkit/async/ServiceQueue.kt @@ -6,9 +6,7 @@ import kotlinx.coroutines.SupervisorJob import kotlinx.coroutines.asCoroutineDispatcher import kotlinx.coroutines.runBlocking import kotlinx.coroutines.withContext -import to.bitkit.ext.callerName import to.bitkit.utils.AppError -import to.bitkit.utils.measured import java.util.concurrent.Executors import java.util.concurrent.ThreadFactory import kotlin.coroutines.CoroutineContext @@ -20,30 +18,16 @@ enum class ServiceQueue { fun blocking( coroutineContext: CoroutineContext = scope.coroutineContext, - functionName: String = Thread.currentThread().callerName, block: suspend CoroutineScope.() -> T, ): T = runBlocking(coroutineContext) { - runCatching { - measured(label = functionName, context = TAG) { - block() - } - }.getOrElse { throw AppError(it) } + runCatching { block() }.getOrElse { throw AppError(it) } } suspend fun background( coroutineContext: CoroutineContext = scope.coroutineContext, - functionName: String = Thread.currentThread().callerName, block: suspend CoroutineScope.() -> T, ): T = withContext(coroutineContext) { - runCatching { - measured(label = functionName, context = TAG) { - block() - } - }.getOrElse { throw AppError(it) } - } - - companion object { - private const val TAG = "ServiceQueue" + runCatching { block() }.getOrElse { throw AppError(it) } } } diff --git a/app/src/main/java/to/bitkit/fcm/WakeNodeWorker.kt b/app/src/main/java/to/bitkit/fcm/WakeNodeWorker.kt index 6572848a8d..555da1bc45 100644 --- a/app/src/main/java/to/bitkit/fcm/WakeNodeWorker.kt +++ b/app/src/main/java/to/bitkit/fcm/WakeNodeWorker.kt @@ -62,6 +62,7 @@ class WakeNodeWorker @AssistedInject constructor( private var notificationPayload: JsonObject? = null private val timeout = 2.minutes + private val slowWakeNodeThreshold = 10.seconds private val deliverSignal = CompletableDeferred() override suspend fun doWork(): Result { @@ -80,7 +81,7 @@ class WakeNodeWorker @AssistedInject constructor( } return runCatching { - measured(label = "doWork", context = TAG) { + measured(label = "doWork", context = TAG, slowThreshold = slowWakeNodeThreshold) { lightningRepo.start( walletIndex = 0, timeout = timeout, diff --git a/app/src/main/java/to/bitkit/repositories/LightningRepo.kt b/app/src/main/java/to/bitkit/repositories/LightningRepo.kt index 2eb6a1ebd1..dda3c3154c 100644 --- a/app/src/main/java/to/bitkit/repositories/LightningRepo.kt +++ b/app/src/main/java/to/bitkit/repositories/LightningRepo.kt @@ -350,6 +350,7 @@ class LightningRepo @Inject constructor( // Initial state sync syncState() + logNodeSupportSummary("node started") updateGeoBlockState() refreshChannelCache() @@ -376,6 +377,7 @@ class LightningRepo @Inject constructor( connectToTrustedPeers().onFailure { Logger.error("Failed to connect to trusted peers", it, context = TAG) } + logNodeSupportSummary("trusted peers connected") sync().onFailure { e -> Logger.warn("Initial sync failed, event-driven sync will retry", e, context = TAG) @@ -1294,6 +1296,52 @@ class LightningRepo @Inject constructor( } } + private fun logNodeSupportSummary(reason: String) { + val state = _lightningState.value + val connectedPeers = state.peers.count { it.isConnected } + val persistedPeers = state.peers.count { it.isPersisted } + val readyChannels = state.channels.count { it.isChannelReady } + val usableChannels = state.channels.count { it.isUsable } + + Logger.info( + "Collected node support summary for '$reason': " + + "nodeId='${state.nodeId}', " + + "lifecycle='${state.nodeLifecycleState}', " + + "peers='${state.peers.size}', " + + "connectedPeers='$connectedPeers', " + + "persistedPeers='$persistedPeers', " + + "channels='${state.channels.size}', " + + "readyChannels='$readyChannels', " + + "usableChannels='$usableChannels'", + context = TAG, + ) + + state.peers.forEach { + Logger.info( + "Collected peer support summary for '$reason': " + + "nodeId='${it.nodeId}', " + + "address='${it.address}', " + + "connected='${it.isConnected}', " + + "persisted='${it.isPersisted}'", + context = TAG, + ) + } + + state.channels.forEach { + Logger.info( + "Collected channel support summary for '$reason': " + + "channelId='${it.channelId}', " + + "counterparty='${it.counterpartyNodeId}', " + + "ready='${it.isChannelReady}', " + + "usable='${it.isUsable}', " + + "announced='${it.isAnnounced}', " + + "outboundMsat='${it.outboundCapacityMsat}', " + + "inboundMsat='${it.inboundCapacityMsat}'", + context = TAG, + ) + } + } + suspend fun awaitPeerConnected(timeout: Duration = 30.seconds) = withContext(bgDispatcher) { if (lightningService.peers?.any { it.isConnected } == true) return@withContext Logger.debug("Waiting for peer to reconnect (timeout='$timeout')...", context = TAG) diff --git a/app/src/main/java/to/bitkit/repositories/LogsRepo.kt b/app/src/main/java/to/bitkit/repositories/LogsRepo.kt index fcf6412dfb..621ee9bd40 100644 --- a/app/src/main/java/to/bitkit/repositories/LogsRepo.kt +++ b/app/src/main/java/to/bitkit/repositories/LogsRepo.kt @@ -6,14 +6,19 @@ import androidx.core.content.FileProvider import dagger.hilt.android.qualifiers.ApplicationContext import kotlinx.coroutines.CoroutineDispatcher import kotlinx.coroutines.withContext +import kotlinx.serialization.Serializable +import kotlinx.serialization.encodeToString import to.bitkit.data.ChatwootHttpClient import to.bitkit.di.BgDispatcher import to.bitkit.di.IoDispatcher import to.bitkit.env.Env +import to.bitkit.ext.DatePattern import to.bitkit.ext.fromBase64 import to.bitkit.ext.getEnumValueOf import to.bitkit.ext.toBase64 +import to.bitkit.ext.utcDateFormatterOf import to.bitkit.models.ChatwootMessage +import to.bitkit.models.NodeLifecycleState import to.bitkit.utils.LogSource import to.bitkit.utils.Logger import java.io.BufferedReader @@ -21,10 +26,12 @@ import java.io.ByteArrayOutputStream import java.io.File import java.io.FileInputStream import java.io.FileReader +import java.util.Date import java.util.zip.ZipEntry import java.util.zip.ZipOutputStream import javax.inject.Inject import javax.inject.Singleton +import to.bitkit.di.json as appJson @Singleton class LogsRepo @Inject constructor( @@ -32,11 +39,12 @@ class LogsRepo @Inject constructor( @BgDispatcher private val bgDispatcher: CoroutineDispatcher, @IoDispatcher private val ioDispatcher: CoroutineDispatcher, private val chatwootHttpClient: ChatwootHttpClient, + private val lightningRepo: LightningRepo, ) { suspend fun postQuestion(email: String, message: String): Result = withContext(bgDispatcher) { runCatching { - val logsBase64 = zipLogs().getOrDefault("") - val logsFileName = "bitkit_logs_${System.currentTimeMillis()}.zip" + val logsBase64 = zipLogs(maxEncodedBytes = MAX_SUPPORT_UPLOAD_BASE64_BYTES).getOrDefault("") + val logsFileName = createLogsArchiveFileName(SUPPORT_LOGS_ARCHIVE_PREFIX) chatwootHttpClient.postQuestion( message = ChatwootMessage( @@ -49,7 +57,7 @@ class LogsRepo @Inject constructor( ) ) }.onFailure { - Logger.error(it.message, e = it, context = TAG) + Logger.error("Failed to post support question", it, context = TAG) } } @@ -61,22 +69,7 @@ class LogsRepo @Inject constructor( val logFiles = logDir .listFiles { file -> file.extension == "log" } - ?.map { file -> - val fileName = file.name - val components = fileName.split("_") - - val serviceName = components.firstOrNull() - ?.let { c -> c.replaceFirstChar { if (it.isLowerCase()) it.titlecase() else it.toString() } } - ?: LogSource.Unknown.name - val timestamp = if (components.size >= 3) components[components.size - 2] else "" - val displayName = "$serviceName Log: $timestamp" - - LogFile( - displayName = displayName, - file = file, - source = getEnumValueOf(serviceName).getOrDefault(LogSource.Unknown), - ) - } + ?.map { it.toLogFile() } ?.sortedByDescending { it.file.lastModified() } ?: emptyList() @@ -115,7 +108,7 @@ class LogsRepo @Inject constructor( val file = withContext(ioDispatcher) { val tempDir = context.cacheDir.resolve("logs").apply { mkdirs() } - val zipFileName = "bitkit_logs_${System.currentTimeMillis()}.zip" + val zipFileName = createLogsArchiveFileName() val tempFile = File(tempDir, zipFileName) // Convert base64 back to bytes and write to file @@ -128,7 +121,7 @@ class LogsRepo @Inject constructor( return@mapCatching contentUri }.onFailure { - Logger.error("Error preparing logs for sharing", it) + Logger.error("Failed to prepare logs for sharing", it, context = TAG) } } @@ -136,6 +129,7 @@ class LogsRepo @Inject constructor( suspend fun zipLogs( limit: Int = 20, source: LogSource? = null, + maxEncodedBytes: Int? = null, ): Result = withContext(bgDispatcher) { runCatching { val logsResult = getLogs().onFailure { @@ -146,30 +140,38 @@ class LogsRepo @Inject constructor( val logsToZip = if (source != null) { allLogs.filter { it.source == source }.take(limit) } else { - // Group by source and take most recent from each - allLogs.groupBy { it.source } - .values - .flatMap { logs -> - val sourcesCount = LogSource.entries.filter { it != LogSource.Unknown }.size - logs.take(limit / sourcesCount.coerceAtLeast(1)) - } - .take(limit) - } - - if (logsToZip.isEmpty()) { - return@withContext Result.failure(Exception("No log files found")) + allLogs.take(limit) } - return@runCatching createZipBase64(logsToZip) + return@runCatching createZipBase64(logsToZip, maxEncodedBytes) }.onFailure { Logger.error("Failed to zip logs", it, context = TAG) } } @Suppress("NestedBlockDepth") - private fun createZipBase64(logFiles: List): String { - val zipBytes = ByteArrayOutputStream().use { byteArrayOut -> + private fun createZipBase64(logFiles: List, maxEncodedBytes: Int?): String { + val selectedLogFiles = logFiles.toMutableList() + + while (true) { + val encoded = createZipBytes(selectedLogFiles).toBase64() + if (maxEncodedBytes == null || encoded.length <= maxEncodedBytes || selectedLogFiles.isEmpty()) { + Logger.info("Created support logs archive with '${selectedLogFiles.size}' log file(s)", context = TAG) + return encoded + } + + selectedLogFiles.removeAt(selectedLogFiles.lastIndex) + } + } + + @Suppress("NestedBlockDepth") + private fun createZipBytes(logFiles: List): ByteArray { + return ByteArrayOutputStream().use { byteArrayOut -> ZipOutputStream(byteArrayOut).use { zipOut -> + zipOut.putNextEntry(ZipEntry(SUPPORT_SNAPSHOT_FILE_NAME)) + zipOut.write(createSupportSnapshot().toByteArray()) + zipOut.closeEntry() + logFiles.forEach { logFile -> if (logFile.file.exists()) { val zipEntry = ZipEntry("${logFile.source.name.lowercase()}/${logFile.fileName}") @@ -184,12 +186,99 @@ class LogsRepo @Inject constructor( } byteArrayOut.toByteArray() } + } + + private fun File.toLogFile(): LogFile { + val match = LOG_FILE_NAME_REGEX.matchEntire(name) + val serviceName = match + ?.groupValues + ?.getOrNull(1) + ?.replaceFirstChar { if (it.isLowerCase()) it.titlecase() else it.toString() } + ?: LogSource.Unknown.name + val timestamp = match?.groupValues?.getOrNull(2)?.replace("_", " ") + val part = match?.groupValues?.getOrNull(3)?.ifBlank { null } + val partSuffix = part?.let { " part $it" }.orEmpty() + val displayName = if (timestamp != null) { + "$serviceName Log: $timestamp$partSuffix" + } else { + "$serviceName Log: $name" + } - return zipBytes.toBase64() + return LogFile( + displayName = displayName, + file = this, + source = getEnumValueOf(serviceName).getOrDefault(LogSource.Unknown), + ) + } + + private fun createSupportSnapshot(): String { + val state = lightningRepo.lightningState.value + val snapshot = SupportSnapshot( + generatedAt = currentLogTimestamp(), + platform = Env.platform, + version = Env.version, + network = Env.network.name, + nodeId = state.nodeId, + lifecycle = state.nodeLifecycleState.supportName(), + isSyncingWallet = state.isSyncingWallet, + isGeoBlocked = state.isGeoBlocked, + lastSuccessfulSyncAt = state.lastSuccessfulSyncAt?.toString(), + lastSyncError = state.lastSyncError?.javaClass?.simpleName, + blockHeight = state.nodeStatus?.currentBestBlock?.height?.toString(), + blockHash = state.nodeStatus?.currentBestBlock?.blockHash, + latestRgsSnapshotTimestamp = state.nodeStatus?.latestRgsSnapshotTimestamp?.toString(), + peers = state.peers.map { + SupportPeerSnapshot( + nodeId = it.nodeId, + address = it.address, + isConnected = it.isConnected, + isPersisted = it.isPersisted, + ) + }, + channels = state.channels.map { + SupportChannelSnapshot( + channelId = it.channelId, + counterpartyNodeId = it.counterpartyNodeId, + isChannelReady = it.isChannelReady, + isUsable = it.isUsable, + isAnnounced = it.isAnnounced, + channelValueSats = it.channelValueSats.toString(), + outboundCapacityMsat = it.outboundCapacityMsat.toString(), + inboundCapacityMsat = it.inboundCapacityMsat.toString(), + ) + }, + balances = state.balances?.let { + SupportBalanceSnapshot( + totalOnchainBalanceSats = it.totalOnchainBalanceSats.toString(), + spendableOnchainBalanceSats = it.spendableOnchainBalanceSats.toString(), + totalAnchorChannelsReserveSats = it.totalAnchorChannelsReserveSats.toString(), + totalLightningBalanceSats = it.totalLightningBalanceSats.toString(), + lightningBalancesCount = it.lightningBalances.size, + pendingChannelClosureBalancesCount = it.pendingBalancesFromChannelClosures.size, + ) + }, + ) + + return appJson.encodeToString(snapshot) + } + + private fun createLogsArchiveFileName(prefix: String = LOGS_ARCHIVE_PREFIX): String { + return "${prefix}_${currentLogTimestamp()}.zip" + } + + private fun currentLogTimestamp(): String { + return utcDateFormatterOf(DatePattern.LOG_FILE).format(Date()) } private companion object { const val TAG = "SupportRepo" + const val LOGS_ARCHIVE_PREFIX = "bitkit_logs" + const val MAX_SUPPORT_UPLOAD_BASE64_BYTES = 900 * 1024 + const val SUPPORT_LOGS_ARCHIVE_PREFIX = "bitkit_support_logs" + const val SUPPORT_SNAPSHOT_FILE_NAME = "support_snapshot.json" + val LOG_FILE_NAME_REGEX = Regex( + "^([A-Za-z]+)_(\\d{4}-\\d{2}-\\d{2}_\\d{2}-\\d{2}-\\d{2})(?:\\.part_(\\d{3}))?\\.log$" + ) } } @@ -200,3 +289,62 @@ data class LogFile( ) { val fileName: String get() = file.name } + +private fun NodeLifecycleState.supportName(): String = when (this) { + is NodeLifecycleState.Stopped -> "Stopped" + is NodeLifecycleState.Starting -> "Starting" + is NodeLifecycleState.Running -> "Running" + is NodeLifecycleState.Stopping -> "Stopping" + is NodeLifecycleState.Initializing -> "Initializing" + is NodeLifecycleState.ErrorStarting -> "ErrorStarting" +} + +@Serializable +private data class SupportSnapshot( + val generatedAt: String, + val platform: String, + val version: String, + val network: String, + val nodeId: String, + val lifecycle: String, + val isSyncingWallet: Boolean, + val isGeoBlocked: Boolean, + val lastSuccessfulSyncAt: String?, + val lastSyncError: String?, + val blockHeight: String?, + val blockHash: String?, + val latestRgsSnapshotTimestamp: String?, + val peers: List, + val channels: List, + val balances: SupportBalanceSnapshot?, +) + +@Serializable +private data class SupportPeerSnapshot( + val nodeId: String, + val address: String, + val isConnected: Boolean, + val isPersisted: Boolean, +) + +@Serializable +private data class SupportChannelSnapshot( + val channelId: String, + val counterpartyNodeId: String, + val isChannelReady: Boolean, + val isUsable: Boolean, + val isAnnounced: Boolean, + val channelValueSats: String, + val outboundCapacityMsat: String, + val inboundCapacityMsat: String, +) + +@Serializable +private data class SupportBalanceSnapshot( + val totalOnchainBalanceSats: String, + val spendableOnchainBalanceSats: String, + val totalAnchorChannelsReserveSats: String, + val totalLightningBalanceSats: String, + val lightningBalancesCount: Int, + val pendingChannelClosureBalancesCount: Int, +) diff --git a/app/src/main/java/to/bitkit/repositories/WalletRepo.kt b/app/src/main/java/to/bitkit/repositories/WalletRepo.kt index dde2ee0a44..bc47c5e746 100644 --- a/app/src/main/java/to/bitkit/repositories/WalletRepo.kt +++ b/app/src/main/java/to/bitkit/repositories/WalletRepo.kt @@ -45,6 +45,7 @@ import to.bitkit.utils.measured import javax.inject.Inject import javax.inject.Singleton import kotlin.coroutines.cancellation.CancellationException +import kotlin.time.Duration.Companion.seconds @Suppress("LongParameterList", "TooManyFunctions") @Singleton @@ -177,7 +178,7 @@ class WalletRepo @Inject constructor( val startHeight = lightningRepo.lightningState.value.block()?.height Logger.debug("Sync $sourceLabel started at block height=$startHeight", context = TAG) - val result = measured(label = "Sync $sourceLabel", context = TAG) { + val result = measured(label = "Sync $sourceLabel", context = TAG, slowThreshold = SLOW_SYNC_THRESHOLD) { syncBalances() lightningRepo.sync().onSuccess { syncBalances() @@ -590,6 +591,7 @@ class WalletRepo @Inject constructor( private companion object { const val TAG = "WalletRepo" const val EVENT_SYNC_DEBOUNCE_MS = 500L + val SLOW_SYNC_THRESHOLD = 5.seconds } } diff --git a/app/src/main/java/to/bitkit/services/LightningService.kt b/app/src/main/java/to/bitkit/services/LightningService.kt index 979bb64592..f8c267a1f5 100644 --- a/app/src/main/java/to/bitkit/services/LightningService.kt +++ b/app/src/main/java/to/bitkit/services/LightningService.kt @@ -570,10 +570,28 @@ class LightningService @Inject constructor( Logger.info("Channel close initiated (force=$force): '$channelId'", context = TAG) } catch (e: NodeException) { val error = LdkError(e) - Logger.error("Error initiating channel close (force=$force): '$channelId'", error, context = TAG) + Logger.error("Failed to initiate channel close for '$channelId' with force '$force'", error, context = TAG) + logCloseChannelPeerState(node, channel) throw LdkError(e) } } + + private fun logCloseChannelPeerState(node: Node, channel: ChannelDetails) { + runCatching { + val peer = node.listPeers().firstOrNull { it.nodeId == channel.counterpartyNodeId } + Logger.info( + "Collected close peer state for channel '${channel.channelId}': " + + "counterparty='${channel.counterpartyNodeId}', " + + "peerFound='${peer != null}', " + + "peerAddress='${peer?.address}', " + + "peerConnected='${peer?.isConnected}', " + + "peerPersisted='${peer?.isPersisted}'", + context = TAG, + ) + }.onFailure { + Logger.warn("Failed to collect close peer state for channel '${channel.channelId}'", it, context = TAG) + } + } // endregion // region payments diff --git a/app/src/main/java/to/bitkit/ui/screens/transfer/external/LnurlChannelViewModel.kt b/app/src/main/java/to/bitkit/ui/screens/transfer/external/LnurlChannelViewModel.kt index 53dec2fe45..966ca73d6b 100644 --- a/app/src/main/java/to/bitkit/ui/screens/transfer/external/LnurlChannelViewModel.kt +++ b/app/src/main/java/to/bitkit/ui/screens/transfer/external/LnurlChannelViewModel.kt @@ -12,10 +12,12 @@ import kotlinx.coroutines.launch import org.lightningdevkit.ldknode.PeerDetails import to.bitkit.R import to.bitkit.ext.of +import to.bitkit.ext.uri import to.bitkit.models.Toast import to.bitkit.repositories.LightningRepo import to.bitkit.ui.Routes import to.bitkit.ui.shared.toast.ToastEventBus +import to.bitkit.utils.Logger import javax.inject.Inject @HiltViewModel @@ -57,6 +59,15 @@ class LnurlChannelViewModel @Inject constructor( // Connect to peer if not connected lightningRepo.connectPeer(peer) + .onSuccess { + Logger.info("Connected LNURL channel peer '${peer.uri}'", context = TAG) + }.onFailure { + Logger.warn( + "Failed to connect LNURL channel peer '${peer.uri}' before channel request", + it, + context = TAG, + ) + } lightningRepo.requestLnurlChannel(callback = params.callback, k1 = params.k1, nodeId = nodeId) .onSuccess { @@ -81,6 +92,10 @@ class LnurlChannelViewModel @Inject constructor( description = error.message ?: "Unknown error", ) } + + private companion object { + const val TAG = "LnurlChannelViewModel" + } } data class LnurlChannelUiState( diff --git a/app/src/main/java/to/bitkit/usecases/WipeWalletUseCase.kt b/app/src/main/java/to/bitkit/usecases/WipeWalletUseCase.kt index ca1f462ec5..58a744c15f 100644 --- a/app/src/main/java/to/bitkit/usecases/WipeWalletUseCase.kt +++ b/app/src/main/java/to/bitkit/usecases/WipeWalletUseCase.kt @@ -6,7 +6,6 @@ import to.bitkit.data.CacheStore import to.bitkit.data.SettingsStore import to.bitkit.data.WidgetsStore import to.bitkit.data.keychain.Keychain -import to.bitkit.env.Env import to.bitkit.repositories.ActivityRepo import to.bitkit.repositories.BackupRepo import to.bitkit.repositories.BlocktankRepo @@ -64,10 +63,7 @@ class WipeWalletUseCase @Inject constructor( migrationService.markMigrationChecked() lightningRepo.wipeStorage(walletIndex) - .onSuccess { - onSuccess() - if (Env.isDebug) Logger.reset() - } + .onSuccess { onSuccess() } .getOrThrow() }.onFailure { Logger.error("Wipe wallet error", it, context = TAG) diff --git a/app/src/main/java/to/bitkit/utils/Logger.kt b/app/src/main/java/to/bitkit/utils/Logger.kt index 3b8aeb8965..f117942b02 100644 --- a/app/src/main/java/to/bitkit/utils/Logger.kt +++ b/app/src/main/java/to/bitkit/utils/Logger.kt @@ -21,10 +21,18 @@ import java.io.FileOutputStream import java.util.Date import java.util.Locale import java.util.concurrent.atomic.AtomicReference -import kotlin.time.measureTime +import kotlin.time.Duration +import kotlin.time.Duration.Companion.seconds +import kotlin.time.measureTimedValue private const val APP = "APP" private const val COMPACT = false +private const val LOG_FILE_EXTENSION = "log" +private const val MAX_LOG_FILE_BYTES = 1L * 1024L * 1024L +private const val MAX_LOG_RETENTION_BYTES = 500L * 1024L * 1024L +private const val MAX_LOG_RETENTION_DAYS = 60L +private const val MILLIS_IN_DAY = 24L * 60L * 60L * 1000L +private val DEFAULT_SLOW_OPERATION_THRESHOLD = 1.seconds enum class LogSource { Ldk, Bitkit, Unknown } enum class LogLevel { PERF, VERBOSE, GOSSIP, TRACE, DEBUG, INFO, WARN, ERROR } @@ -208,14 +216,18 @@ class LogSaverImpl( private val queue: CoroutineScope by lazy { CoroutineScope(newSingleThreadDispatcher(ServiceQueue.LOG.name) + SupervisorJob()) } + private var currentLogFilePath: String? = null init { if (sessionFilePath.isNotEmpty()) { + val sessionFile = File(sessionFilePath) + currentLogFilePath = sessionFile.absolutePath + sessionFile.parentFile?.mkdirs() log("Log session initialized with file path: '$sessionFilePath'") - // Clean all old log files in background + // Apply retention in background without wiping useful startup context. CoroutineScope(Dispatchers.IO).launch { - cleanupOldLogFiles() + enforceLogRetentionLimits(activeLogFile = sessionFile) } } } @@ -226,8 +238,19 @@ class LogSaverImpl( queue.launch { runCatching { val sanitized = message.replace("\n", " ") - FileOutputStream(File(sessionFilePath), true).use { stream -> - stream.write("$sanitized\n".toByteArray()) + val bytes = "$sanitized\n".toByteArray() + val file = getWritableLogFile(bytes.size) + val previousLogFilePath = currentLogFilePath + currentLogFilePath = file.absolutePath + + FileOutputStream(file, true).use { stream -> + stream.write(bytes) + } + + if (previousLogFilePath != file.absolutePath) { + CoroutineScope(Dispatchers.IO).launch { + enforceLogRetentionLimits(activeLogFile = file) + } } }.onFailure { Log.e(APP, "Error writing to log file: '$sessionFilePath'", it) @@ -235,6 +258,43 @@ class LogSaverImpl( } } + private fun getWritableLogFile(nextWriteBytes: Int): File { + val sessionFile = File(sessionFilePath) + val sessionDir = sessionFile.parentFile ?: Env.logDir + val sessionName = sessionFile.nameWithoutExtension + + sessionDir.mkdirs() + + val currentFile = currentLogFilePath + ?.let(::File) + ?.takeIf { + it.parentFile?.absolutePath == sessionDir.absolutePath && + it.nameWithoutExtension.startsWith(sessionName) + } + + if (currentFile != null && currentFile.hasRoomFor(nextWriteBytes)) { + return currentFile + } + + var file = currentFile ?: sessionFile + var part = file.logPartNumber(sessionFile) + while (file.exists() && file.length() + nextWriteBytes > MAX_LOG_FILE_BYTES) { + part += 1 + file = sessionDir.resolve("$sessionName.part_${part.toString().padStart(3, '0')}.$LOG_FILE_EXTENSION") + } + + return file + } + + private fun File.hasRoomFor(nextWriteBytes: Int): Boolean { + return !exists() || length() + nextWriteBytes <= MAX_LOG_FILE_BYTES + } + + private fun File.logPartNumber(sessionFile: File): Int { + if (absolutePath == sessionFile.absolutePath) return 1 + return nameWithoutExtension.substringAfter(".part_", "1").toIntOrNull() ?: 1 + } + private fun log( message: String, level: LogLevel = LogLevel.INFO, @@ -245,33 +305,58 @@ class LogSaverImpl( save(formatted) } - private fun cleanupOldLogFiles(maxTotalSizeMB: Int = 20) { - log("Deleting old log files…", LogLevel.VERBOSE, Log::v) + private fun enforceLogRetentionLimits( + maxTotalSizeBytes: Long = MAX_LOG_RETENTION_BYTES, + maxAgeDays: Long = MAX_LOG_RETENTION_DAYS, + activeLogFile: File? = null, + ) { + log("Enforcing log retention limits…", LogLevel.VERBOSE, Log::v) val logDir = runCatching { Env.logDir }.getOrNull() ?: return val logFiles = logDir - .listFiles { file -> file.extension == "log" } + .listFiles { file -> file.extension == LOG_FILE_EXTENSION } ?: return - var totalSize = logFiles.sumOf { it.length() } - val maxSizeBytes = maxTotalSizeMB * 1024L * 1024L + val activeLogFilePath = activeLogFile?.absolutePath + val removableFiles = logFiles.filterNot { it.absolutePath == activeLogFilePath } + val oldestAllowedModifiedAt = System.currentTimeMillis() - maxAgeDays * MILLIS_IN_DAY - // Sort by creation date (oldest first) - logFiles + removableFiles .sortedBy { it.lastModified() } .forEach { file -> - if (totalSize <= maxSizeBytes) return + if (file.lastModified() < oldestAllowedModifiedAt) { + deleteLogFile(file) + } + } - runCatching { - log("Deleting old log file: '${file.name}'", LogLevel.DEBUG, Log::d) - if (file.delete()) { - totalSize -= file.length() - } - }.onFailure { - log("Failed to delete old log file: '${file.name}'", LogLevel.WARN, Log::w) + var totalSize = logDir + .listFiles { file -> file.extension == LOG_FILE_EXTENSION } + ?.sumOf { it.length() } + ?: return + + logDir + .listFiles { file -> file.extension == LOG_FILE_EXTENSION } + ?.filterNot { it.absolutePath == activeLogFilePath } + ?.sortedBy { it.lastModified() } + ?.forEach { file -> + if (totalSize <= maxTotalSizeBytes) return@forEach + + val fileSize = file.length() + if (deleteLogFile(file)) { + totalSize -= fileSize } } - log("Deleted all old log files.", LogLevel.VERBOSE, Log::v) + + log("Enforced log retention limits.", LogLevel.VERBOSE, Log::v) + } + + private fun deleteLogFile(file: File): Boolean { + return runCatching { + log("Deleting old log file: '${file.name}'", LogLevel.DEBUG, Log::d) + file.delete() + }.onFailure { + log("Failed to delete old log file: '${file.name}'", LogLevel.WARN, Log::w) + }.getOrDefault(false) } companion object { @@ -344,12 +429,12 @@ fun errorLogOf(e: Throwable): String = "[${e::class.simpleName}='${e.message}']" internal inline fun measured( label: String, context: String, + slowThreshold: Duration = DEFAULT_SLOW_OPERATION_THRESHOLD, block: () -> T, ): T { - var result: T - val elapsed = measureTime { - result = block() + val timedValue = measureTimedValue(block) + if (timedValue.duration >= slowThreshold) { + Logger.perf("Measured '$label' in '${timedValue.duration}'", context = context) } - Logger.perf("$label took $elapsed", context = context) - return result + return timedValue.value } diff --git a/changelog.d/next/support-logs.fixed.md b/changelog.d/next/support-logs.fixed.md new file mode 100644 index 0000000000..6284c60158 --- /dev/null +++ b/changelog.d/next/support-logs.fixed.md @@ -0,0 +1 @@ +Improved support log handling so diagnostics stay smaller and include more useful Lightning connection details. diff --git a/gradle/libs.versions.toml b/gradle/libs.versions.toml index 58fdeeb050..884e903834 100644 --- a/gradle/libs.versions.toml +++ b/gradle/libs.versions.toml @@ -64,7 +64,7 @@ ktor-client-core = { module = "io.ktor:ktor-client-core", version.ref = "ktor" } ktor-client-logging = { module = "io.ktor:ktor-client-logging", version.ref = "ktor" } ktor-client-okhttp = { module = "io.ktor:ktor-client-okhttp", version.ref = "ktor" } ktor-serialization-kotlinx-json = { module = "io.ktor:ktor-serialization-kotlinx-json", version.ref = "ktor" } -ldk-node-android = { module = "com.synonym:ldk-node-android", version = "0.7.0-rc.37" } +ldk-node-android = { module = "com.synonym:ldk-node-android", version = "0.7.0-rc.42" } lifecycle-process = { group = "androidx.lifecycle", name = "lifecycle-process", version.ref = "lifecycle" } lifecycle-runtime-compose = { module = "androidx.lifecycle:lifecycle-runtime-compose", version.ref = "lifecycle" } lifecycle-runtime-ktx = { module = "androidx.lifecycle:lifecycle-runtime-ktx", version.ref = "lifecycle" }