fix: write log files off the main thread

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())
     }
 }

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<String> {
+        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
+    }
+}

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<File> =
+        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
+    }
+}