Skip to content

Commit

Permalink
Use a rolling file logwriter (#152)
Browse files Browse the repository at this point in the history
Initially the goal was to use Kermit's `RollingFileLogWriter`, but an issue was found during testing (see touchlab/Kermit#433) so we are using a local patched version in the meantime.

Logging can be configured with these two new config parameters:
- `--log-rotate-size` Log rotate size in MB (default 10 MB)
- `--log-rotate-max-files`: Maximum number of log files kept (default 5)
  • Loading branch information
pm47 authored Feb 25, 2025
1 parent d9732ab commit 4f1ddd6
Show file tree
Hide file tree
Showing 6 changed files with 185 additions and 39 deletions.
1 change: 1 addition & 0 deletions build.gradle.kts
Original file line number Diff line number Diff line change
Expand Up @@ -111,6 +111,7 @@ kotlin {

implementation("org.jetbrains.kotlinx:kotlinx-io-core:${libs.versions.kotlinx.io.get()}")
implementation("com.github.ajalt.clikt:clikt:${libs.versions.clikt.get()}")
implementation("co.touchlab:kermit-io:${libs.versions.kermit.io.get()}")
}
}
commonTest {
Expand Down
1 change: 1 addition & 0 deletions gradle/libs.versions.toml
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@ clikt = "4.4.0"
ktor = "3.1.0"
sqldelight = "2.0.2" # TODO: remove 'addEnclosingTransaction' hack in AfterVersionX files when upgrading
lightningkmp = "1.8.5-SNAPSHOT"
kermit-io = "2.0.5"

# test dependencies
test-logback = "1.5.16"
Expand Down
13 changes: 11 additions & 2 deletions src/commonMain/kotlin/fr/acinq/phoenixd/Phoenixd.kt
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ package fr.acinq.phoenixd
import co.touchlab.kermit.CommonWriter
import co.touchlab.kermit.Severity
import co.touchlab.kermit.StaticConfig
import co.touchlab.kermit.io.RollingFileLogWriterConfig
import com.github.ajalt.clikt.core.CliktCommand
import com.github.ajalt.clikt.core.UsageError
import com.github.ajalt.clikt.core.context
Expand All @@ -13,6 +14,7 @@ import com.github.ajalt.clikt.parameters.groups.provideDelegate
import com.github.ajalt.clikt.parameters.options.*
import com.github.ajalt.clikt.parameters.types.choice
import com.github.ajalt.clikt.parameters.types.int
import com.github.ajalt.clikt.parameters.types.long
import com.github.ajalt.clikt.parameters.types.restrictTo
import com.github.ajalt.mordant.rendering.TextColors.*
import com.github.ajalt.mordant.rendering.TextStyles.bold
Expand Down Expand Up @@ -40,7 +42,7 @@ import fr.acinq.phoenixd.db.SqliteChannelsDb
import fr.acinq.phoenixd.db.SqlitePaymentsDb
import fr.acinq.phoenixd.db.createPhoenixDb
import fr.acinq.phoenixd.json.ApiType
import fr.acinq.phoenixd.logs.FileLogWriter
import fr.acinq.phoenixd.logs.RollingFileLogWriter
import fr.acinq.phoenixd.logs.TimestampFormatter
import fr.acinq.phoenixd.logs.stringTimestamp
import io.ktor.http.*
Expand Down Expand Up @@ -157,6 +159,13 @@ class Phoenixd : CliktCommand() {

private val liquidityOptions by LiquidityOptions()

private val logRotateSize by option("--log-rotate-size", help = "Log rotate size in MB.")
.long().convert { it * 1024 * 1024 }
.default(10 * 1024 * 1024, "10")
private val logRotateMaxFiles by option("--log-rotate-max-files", help = "Maximum number of log files kept.")
.int()
.default(5, "5")

sealed class Verbosity {
data object Default : Verbosity()
data object Silent : Verbosity()
Expand Down Expand Up @@ -230,7 +239,7 @@ class Phoenixd : CliktCommand() {
val loggerFactory = LoggerFactory(
StaticConfig(minSeverity = Severity.Info, logWriterList = buildList {
// always log to file
add(FileLogWriter(Path(datadir, "phoenix.log"), scope))
add(RollingFileLogWriter(RollingFileLogWriterConfig(logFileName = "phoenix", logFilePath = Path(datadir.toString()), rollOnSize = logRotateSize, maxLogFiles = logRotateMaxFiles)))
// only log to console if verbose mode is enabled
if (verbosity == Verbosity.Verbose) add(CommonWriter(TimestampFormatter))
})
Expand Down
33 changes: 0 additions & 33 deletions src/commonMain/kotlin/fr/acinq/phoenixd/logs/FileLogWriter.kt

This file was deleted.

170 changes: 170 additions & 0 deletions src/commonMain/kotlin/fr/acinq/phoenixd/logs/RollingFileLogWriter.kt
Original file line number Diff line number Diff line change
@@ -0,0 +1,170 @@
package fr.acinq.phoenixd.logs

// TODO: remove when https://github.com/touchlab/Kermit/pull/433 is merged and released

/*
* Copyright (c) 2024 Touchlab
* Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License.
*/

import co.touchlab.kermit.*
import co.touchlab.kermit.io.RollingFileLogWriterConfig
import kotlinx.coroutines.*
import kotlinx.coroutines.channels.Channel
import kotlinx.coroutines.channels.trySendBlocking
import kotlinx.datetime.Clock
import kotlinx.datetime.format
import kotlinx.datetime.format.DateTimeComponents
import kotlinx.io.*
import kotlinx.io.files.FileSystem
import kotlinx.io.files.Path
import kotlinx.io.files.SystemFileSystem

/**
* Implements a log writer that writes log messages to a rolling file.
*
* It also deletes old log files when the maximum number of log files is reached. We simply keep
* approximately [RollingFileLogWriterConfig.rollOnSize] bytes in each log file,
* and delete the oldest file when we have more than [RollingFileLogWriterConfig.maxLogFiles].
*
* Formatting is governed by the passed [MessageStringFormatter], but we do prepend a timestamp by default.
* Turn this off via [RollingFileLogWriterConfig.prependTimestamp]
*
* Writes to the file are done by a different coroutine. The main reason for this is to make writes to the
* log file sink thread-safe, and so that file rolling can be performed without additional synchronization
* or locking. The channel that buffers log messages is currently unbuffered, so logging threads will block
* until the I/O is complete. However, buffering could easily be introduced to potentially increase logging
* throughput. The envisioned usage scenarios for this class probably do not warrant this.
*
* The recommended way to obtain the logPath on Android is:
*
* ```kotlin
* Path(context.filesDir.path)
* ```
*
* and on iOS this wil return the application's sandboxed document directory:
*
* ```kotlin
* (NSFileManager.defaultManager.URLsForDirectory(NSDocumentDirectory, NSUserDomainMask).last() as NSURL).path!!
* ```
*
* However, you can use any path that is writable by the application. This would generally be implemented by
* platform-specific code.
*/
open class RollingFileLogWriter(
private val config: RollingFileLogWriterConfig,
private val messageStringFormatter: MessageStringFormatter = DefaultFormatter,
private val clock: Clock = Clock.System,
private val fileSystem: FileSystem = SystemFileSystem,
) : LogWriter() {
@OptIn(DelicateCoroutinesApi::class, ExperimentalCoroutinesApi::class)
private val coroutineScope = CoroutineScope(
newSingleThreadContext("RollingFileLogWriter") +
SupervisorJob() +
CoroutineName("RollingFileLogWriter") +
CoroutineExceptionHandler { _, throwable ->
// can't log it, we're the logger -- print to standard error
println("RollingFileLogWriter: Uncaught exception in writer coroutine")
throwable.printStackTrace()
}
)

private val loggingChannel: Channel<Buffer> = Channel()

init {
coroutineScope.launch {
writer()
}
}

override fun log(severity: Severity, message: String, tag: String, throwable: Throwable?) {
bufferLog(
formatMessage(
severity = severity,
tag = Tag(tag),
message = Message(message)
), throwable
)
}

private fun bufferLog(message: String, throwable: Throwable?) {
val log = buildString {
append(clock.now().format(DateTimeComponents.Formats.ISO_DATE_TIME_OFFSET))
append(" ")
appendLine(message)
if (throwable != null) {
appendLine(throwable.stackTraceToString())
}
}
loggingChannel.trySendBlocking(Buffer().apply { writeString(log) })
}

private fun formatMessage(severity: Severity, tag: Tag?, message: Message): String =
messageStringFormatter.formatMessage(severity, if (config.logTag) tag else null, message)

private fun shouldRollLogs(logFilePath: Path): Boolean {
val size = fileSizeOrZero(logFilePath)
return size > config.rollOnSize
}

private fun rollLogs() {
if (fileSystem.exists(pathForLogIndex(config.maxLogFiles - 1))) {
fileSystem.delete(pathForLogIndex(config.maxLogFiles - 1))
}
(0..<(config.maxLogFiles - 1)).reversed().forEach {
val sourcePath = pathForLogIndex(it)
val targetPath = pathForLogIndex(it + 1)
if (fileSystem.exists(sourcePath)) {
try {
fileSystem.atomicMove(sourcePath, targetPath)
} catch (e: IOException) {
// we can't log it, we're the logger -- print to standard error
println("RollingFileLogWriter: Failed to roll log file $sourcePath to $targetPath (sourcePath exists=${fileSystem.exists(sourcePath)})")
e.printStackTrace()
}
}
}
}

private fun pathForLogIndex(index: Int): Path =
Path(config.logFilePath, if (index == 0) "${config.logFileName}.log" else "${config.logFileName}-$index.log")

private suspend fun writer() {
val logFilePath = pathForLogIndex(0)

if (fileSystem.exists(logFilePath) && shouldRollLogs(logFilePath)) {
rollLogs()
}

fun createNewLogSink(): Sink = fileSystem
.sink(logFilePath, append = true)
.buffered()

var currentLogSink: Sink = createNewLogSink()

while (currentCoroutineContext().isActive) {
// wait for data to be available, flush periodically
val result = loggingChannel.receiveCatching()

// check if logs need rolling
if (shouldRollLogs(logFilePath)) {
currentLogSink.close()
rollLogs()
currentLogSink = createNewLogSink()
}

result.getOrNull()?.transferTo(currentLogSink)

// we could improve performance by flushing less frequently at the cost of potential data loss,
// but this is a safe default
currentLogSink.flush()
}
}

private fun fileSizeOrZero(path: Path) = fileSystem.metadataOrNull(path)?.size ?: 0
}
Original file line number Diff line number Diff line change
Expand Up @@ -4,11 +4,9 @@ import co.touchlab.kermit.Message
import co.touchlab.kermit.MessageStringFormatter
import co.touchlab.kermit.Severity
import co.touchlab.kermit.Tag
import kotlinx.datetime.Clock
import kotlinx.datetime.LocalDateTime
import kotlinx.datetime.TimeZone
import kotlinx.datetime.*
import kotlinx.datetime.format.DateTimeComponents
import kotlinx.datetime.format.char
import kotlinx.datetime.toLocalDateTime

object TimestampFormatter : MessageStringFormatter {
override fun formatMessage(severity: Severity?, tag: Tag?, message: Message): String {
Expand Down

0 comments on commit 4f1ddd6

Please # to comment.