diff --git a/src/commonMain/kotlin/com/airthings/lib/logging/facility/FileLoggerFacility.kt b/src/commonMain/kotlin/com/airthings/lib/logging/facility/FileLoggerFacility.kt index 2d153bb..92a7f37 100644 --- a/src/commonMain/kotlin/com/airthings/lib/logging/facility/FileLoggerFacility.kt +++ b/src/commonMain/kotlin/com/airthings/lib/logging/facility/FileLoggerFacility.kt @@ -35,8 +35,10 @@ import com.airthings.lib.logging.platform.PlatformDirectoryListing import com.airthings.lib.logging.platform.PlatformFileInputOutput import com.airthings.lib.logging.platform.PlatformFileInputOutputImpl import com.airthings.lib.logging.platform.PlatformFileInputOutputNotifier +import kotlinx.coroutines.CoroutineDispatcher import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.Dispatchers +import kotlinx.coroutines.ExperimentalCoroutinesApi import kotlinx.coroutines.SupervisorJob import kotlinx.coroutines.launch @@ -255,6 +257,14 @@ class FileLoggerFacility( companion object { private const val LOG_TAG: String = "FileLoggerFacility" - internal fun loggerCoroutineScope(): CoroutineScope = CoroutineScope(Dispatchers.Main + SupervisorJob()) + /** + * Appending to a log file opens, seeks and writes, which is blocking work that does not + * belong on the main thread. One thread serves every facility built by the convenience + * constructors, so their writes to a shared file stay ordered. + */ + @OptIn(ExperimentalCoroutinesApi::class) + private val fileDispatcher: CoroutineDispatcher = Dispatchers.Default.limitedParallelism(1) + + internal fun loggerCoroutineScope(): CoroutineScope = CoroutineScope(fileDispatcher + SupervisorJob()) } } diff --git a/src/iosTest/kotlin/com/airthings/lib/logging/facility/FileLoggerFacilityCostTest.kt b/src/iosTest/kotlin/com/airthings/lib/logging/facility/FileLoggerFacilityCostTest.kt new file mode 100644 index 0000000..2df5c01 --- /dev/null +++ b/src/iosTest/kotlin/com/airthings/lib/logging/facility/FileLoggerFacilityCostTest.kt @@ -0,0 +1,153 @@ +package com.airthings.lib.logging.facility + +import com.airthings.lib.logging.LogLevel +import com.airthings.lib.logging.LogMessage +import com.airthings.lib.logging.platform.PlatformFileInputOutputImpl +import kotlin.test.AfterTest +import kotlin.test.BeforeTest +import kotlin.test.Test +import kotlin.test.assertEquals +import kotlin.test.assertTrue +import kotlin.time.Duration +import kotlin.time.TimeSource +import kotlinx.cinterop.ExperimentalForeignApi +import kotlinx.coroutines.CoroutineScope +import kotlinx.coroutines.Dispatchers +import kotlinx.coroutines.ExperimentalCoroutinesApi +import kotlinx.coroutines.Job +import kotlinx.coroutines.SupervisorJob +import kotlinx.coroutines.runBlocking +import platform.Foundation.NSFileManager +import platform.Foundation.NSString +import platform.Foundation.NSTemporaryDirectory +import platform.Foundation.NSUTF8StringEncoding +import platform.Foundation.stringWithContentsOfFile + +/** + * What a log line costs on the thread that writes it. + * + * Both measurements time the writes themselves and nothing else: the first calls the platform + * append directly, the second goes through the facility and waits on the jobs it launched rather + * than watching the file, so neither number carries polling latency. + */ +@OptIn(ExperimentalForeignApi::class, ExperimentalCoroutinesApi::class) +class FileLoggerFacilityCostTest { + + private lateinit var folder: String + + @BeforeTest + fun setUp() { + folder = NSTemporaryDirectory() + "kmplog-cost-" + TimeSource.Monotonic.markNow().hashCode() + NSFileManager.defaultManager.createDirectoryAtPath(folder, true, null, null) + } + + @AfterTest + fun tearDown() { + NSFileManager.defaultManager.removeItemAtPath(folder, null) + } + + @Test + fun `one append costs what it costs`() = runBlocking { + val io = PlatformFileInputOutputImpl() + val path = "$folder/raw.log" + io.ensure(path) + + repeat(WARMUP) { io.append(path, "warm-$it\n") } + + val elapsed = measure { index -> io.append(path, "$LINE-$index\n") } + report("append", elapsed) + + assertEquals(WARMUP + LINES, lineCount("raw.log"), "Every append has to produce one line") + assertUnder(elapsed) + } + + @Test + fun `the facility adds what the queue adds`() = runBlocking { + val job = SupervisorJob() + val facility = FileLoggerFacility( + minimumLogLevel = LogLevel.INFO, + baseFolder = folder, + // Mirrors what the convenience constructors build, so the queue being measured is the + // one that ships. The scope is held here only to wait on the writes it launches. + coroutineScope = CoroutineScope(Dispatchers.Default.limitedParallelism(1) + job), + notifier = null, + ) + + repeat(WARMUP) { facility.log("warmup", LogLevel.INFO, LogMessage("warm-$it")) } + job.drain() + + val elapsed = measure { index -> + facility.log("cost", LogLevel.INFO, LogMessage("$LINE-$index")) + job.drain() + } + report("facility", elapsed) + + val written = lines().filter { it.isNotBlank() } + assertEquals(WARMUP + LINES, written.size, "Every call has to produce one line") + repeat(LINES) { index -> + assertTrue(written.any { it.endsWith("$LINE-$index") }, "$LINE-$index is missing") + } + assertUnder(elapsed) + } + + // region helpers + + private suspend fun measure(write: suspend (Int) -> Unit): Duration { + val started = TimeSource.Monotonic.markNow() + repeat(LINES) { write(it) } + return started.elapsedNow() + } + + private fun report( + what: String, + elapsed: Duration, + ) { + println("$what: $LINES writes in $elapsed (${elapsed.inWholeMicroseconds / LINES} us each)") + } + + private fun assertUnder(elapsed: Duration) { + val perWrite = elapsed.inWholeMicroseconds / LINES + assertTrue( + perWrite < CEILING_MICROS, + "A write costs $perWrite us, over the $CEILING_MICROS us this test was written against", + ) + } + + private suspend fun Job.drain() { + while (true) { + val pending = children.toList() + if (pending.isEmpty()) return + pending.forEach { it.join() } + } + } + + private fun lines(name: String? = null): List { + val manager = NSFileManager.defaultManager + val file = name ?: manager.contentsOfDirectoryAtPath(folder, null) + .orEmpty() + .map { "$it" } + .firstOrNull { it.endsWith(".log") } + ?: return emptyList() + + val text = NSString.stringWithContentsOfFile("$folder/$file", NSUTF8StringEncoding, null) + ?: return emptyList() + + return "$text".lines() + } + + private fun lineCount(name: String): Int = lines(name).count { it.isNotBlank() } + + // endregion + + private companion object { + const val WARMUP = 20 + const val LINES = 500 + const val LINE = "line" + + /** + * Generous on purpose: this guards against an order-of-magnitude regression, not against + * the noise of a shared runner. + */ + const val CEILING_MICROS = 2_000L + } +} diff --git a/src/jvmTest/kotlin/com/airthings/lib/logging/facility/FileLoggerFacilitySharedFileTest.kt b/src/jvmTest/kotlin/com/airthings/lib/logging/facility/FileLoggerFacilitySharedFileTest.kt new file mode 100644 index 0000000..8fa6a2d --- /dev/null +++ b/src/jvmTest/kotlin/com/airthings/lib/logging/facility/FileLoggerFacilitySharedFileTest.kt @@ -0,0 +1,136 @@ +package com.airthings.lib.logging.facility + +import com.airthings.lib.logging.LogLevel +import com.airthings.lib.logging.LogMessage +import java.io.File +import java.nio.file.Files +import kotlin.test.AfterTest +import kotlin.test.BeforeTest +import kotlin.test.Test +import kotlin.test.assertEquals +import kotlin.test.assertTrue +import kotlinx.coroutines.delay +import kotlinx.coroutines.runBlocking +import kotlinx.coroutines.withTimeoutOrNull + +/** + * Two facilities built by the convenience constructors write one log file between them. + * + * What this covers is that the constructors work at all without a main dispatcher, and that the + * dispatcher they share keeps one facility's line off the end of the other's. It does not stand in + * for the arrangement on iOS, where the two facilities come from separate copies of this library + * and so hold separate dispatchers - nor can the JVM reproduce the hazard there, because it appends + * in append mode while Apple seeks and writes. + */ +class FileLoggerFacilitySharedFileTest { + + private lateinit var tempDir: File + + @BeforeTest + fun setUp() { + tempDir = Files.createTempDirectory("kmplog-shared-file-").toFile() + } + + @AfterTest + fun tearDown() { + tempDir.deleteRecursively() + } + + @Test + fun `the convenience constructor writes without a main dispatcher`() = runBlocking { + val facility = FileLoggerFacility( + minimumLogLevel = LogLevel.INFO, + baseFolder = tempDir.absolutePath, + ) + + facility.log(source = "test", level = LogLevel.INFO, message = LogMessage("only line")) + + val file = awaitLines(expected = 1) + assertTrue( + file.readText().contains("only line"), + "A facility built without an explicit scope has to be able to write", + ) + } + + @Test + fun `neither of two facilities loses a line to the other`() = runBlocking { + val first = FileLoggerFacility( + minimumLogLevel = LogLevel.INFO, + baseFolder = tempDir.absolutePath, + ) + val second = FileLoggerFacility( + minimumLogLevel = LogLevel.INFO, + baseFolder = tempDir.absolutePath, + ) + + repeat(LINES_EACH) { index -> + first.log(source = "first", level = LogLevel.INFO, message = LogMessage("first-$index")) + second.log(source = "second", level = LogLevel.INFO, message = LogMessage("second-$index")) + } + + val lines = awaitLines(expected = LINES_EACH * 2).readLines().filter { it.isNotBlank() } + repeat(LINES_EACH) { index -> + assertTrue(lines.any { it.endsWith("first-$index") }, "first-$index was overwritten") + assertTrue(lines.any { it.endsWith("second-$index") }, "second-$index was overwritten") + } + } + + @Test + fun `a line is never half written`() = runBlocking { + val first = FileLoggerFacility( + minimumLogLevel = LogLevel.INFO, + baseFolder = tempDir.absolutePath, + ) + val second = FileLoggerFacility( + minimumLogLevel = LogLevel.INFO, + baseFolder = tempDir.absolutePath, + ) + + repeat(LINES_EACH) { index -> + first.log(source = "first", level = LogLevel.INFO, message = LogMessage("aaaa-$index")) + second.log(source = "second", level = LogLevel.INFO, message = LogMessage("bbbb-$index")) + } + + val lines = awaitLines(expected = LINES_EACH * 2).readLines().filter { it.isNotBlank() } + + assertEquals(LINES_EACH * 2, lines.size, "Every call writes exactly one line") + + val whole = Regex("""(aaaa|bbbb)-\d+$""") + lines.forEach { line -> + assertTrue(whole.containsMatchIn(line), "A record was cut short or merged: $line") + assertTrue(line.contains("aaaa-") != line.contains("bbbb-"), "Two writes landed in one line: $line") + } + } + + // region helpers + + private suspend fun awaitLines(expected: Int): File { + val file = withTimeoutOrNull(DRAIN_TIMEOUT_MS) { + while (true) { + val candidate = logFiles().singleOrNull() + if (candidate != null && candidate.readLines().count { it.isNotBlank() } >= expected) { + return@withTimeoutOrNull candidate + } + delay(POLL_MS) + } + @Suppress("UNREACHABLE_CODE") + null + } + + return requireNotNull(file) { + val seen = logFiles().singleOrNull()?.readLines()?.count { it.isNotBlank() } ?: 0 + "Expected $expected lines within ${DRAIN_TIMEOUT_MS}ms, saw $seen" + } + } + + private fun logFiles(): List = + tempDir.listFiles { f -> f.isFile && f.name.endsWith(".log") }?.toList().orEmpty() + + // endregion + + private companion object { + const val LINES_EACH = 200 + const val DRAIN_TIMEOUT_MS = 10_000L + const val POLL_MS = 20L + } +}