From 59a9444556136d04c497d0449052b68beeb1922d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A5le=20Stor=C3=B8=20Hauknes?= Date: Thu, 23 Apr 2026 01:05:08 +0200 Subject: [PATCH 1/6] Fix bug --- .../logging/facility/JsonLoggerFacility.kt | 17 +- .../platform/PlatformFileInputOutputImpl.kt | 13 +- .../facility/JsonLoggerFacilityTest.kt | 253 ++++++++++++++++++ 3 files changed, 272 insertions(+), 11 deletions(-) create mode 100644 src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt diff --git a/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt b/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt index 6414c18..8794a40 100644 --- a/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt +++ b/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt @@ -239,23 +239,26 @@ class JsonLoggerFacility( val logFile = "$baseFolder${io.pathSeparator}${dateStamp(null)}.json" val currentLogFileLocked = currentLogFile.value - // New JSON log files always contain an empty array ("[]") which is 2 bytes long. - val isEmpty = io.size(logFile) > 2L - if (currentLogFileLocked != logFile) { if (currentLogFileLocked != null) { notifier?.onLogFileClosed(currentLogFileLocked) } io.ensure(logFile) - // New JSON log files start their life as an empty array ("[]"). - io.append(logFile, "$ARRAY_OPEN$ARRAY_CLOSE") + // A fresh JSON log file starts its life as an empty array ("[]"). Don't + // overwrite one that already exists from a previous session. + if (io.size(logFile) == 0L) { + io.append(logFile, "$ARRAY_OPEN$ARRAY_CLOSE") + } currentLogFile.set(logFile) notifier?.onLogFileOpened(logFile) } - action(logFile, if (isEmpty) "" else ",") + // A file that's just "[]" is 2 bytes. Anything longer means there's already at + // least one entry, so the new entry needs to be preceded by a comma separator. + val hasPriorEntries = io.size(logFile) > 2L + action(logFile, if (hasPriorEntries) "," else "") } } @@ -335,6 +338,8 @@ class JsonLoggerFacility( if (!args.isNullOrEmpty()) { append(COMMA) + append(ARGS_KEY.jsonQuote()) + append(':') append(args.jsonEntry()) } diff --git a/src/jvmMain/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImpl.kt b/src/jvmMain/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImpl.kt index 82771bd..acfa1a3 100644 --- a/src/jvmMain/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImpl.kt +++ b/src/jvmMain/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImpl.kt @@ -25,6 +25,7 @@ import com.airthings.lib.logging.PLATFORM_JVM import com.airthings.lib.logging.ifAfter import java.io.File import java.io.FileOutputStream +import java.io.RandomAccessFile internal actual class PlatformFileInputOutputImpl : PlatformFileInputOutput { private val writeLock = Any() @@ -47,13 +48,15 @@ internal actual class PlatformFileInputOutputImpl : PlatformFileInputOutput { contents: String, ) { synchronized(writeLock) { - FileOutputStream(File(path), true).use { - val channel = it.channel - val size = channel.size() + // `FileOutputStream(file, append=true)` silently ignores `channel.position(...)` + // because append mode forces every write to the end of the file. Use + // `RandomAccessFile` so `position` is honored. + RandomAccessFile(File(path), "rw").use { raf -> + val size = raf.length() val relativePosition = position.relativeToSize(size) - channel.position(relativePosition) - it.write(contents.toByteArray()) + raf.seek(relativePosition) + raf.write(contents.toByteArray()) } } } diff --git a/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt b/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt new file mode 100644 index 0000000..1561048 --- /dev/null +++ b/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt @@ -0,0 +1,253 @@ +package com.airthings.lib.logging.facility + +import com.airthings.lib.logging.LogArg +import com.airthings.lib.logging.LogLevel +import com.airthings.lib.logging.LogMessage +import com.airthings.lib.logging.platform.PlatformFileInputOutputNotifier +import java.io.File +import java.nio.file.Files +import kotlin.test.AfterTest +import kotlin.test.BeforeTest +import kotlin.test.Test +import kotlin.test.assertContains +import kotlin.test.assertEquals +import kotlin.test.assertFalse +import kotlin.test.assertTrue +import kotlinx.coroutines.CoroutineScope +import kotlinx.coroutines.Dispatchers + +class JsonLoggerFacilityTest { + + private lateinit var tempDir: File + private val scope = CoroutineScope(Dispatchers.Unconfined) + + @BeforeTest + fun setUp() { + tempDir = Files.createTempDirectory("kmplog-json-facility-").toFile() + } + + @AfterTest + fun tearDown() { + tempDir.deleteRecursively() + } + + @Test + fun `log writes a valid single-entry JSON array`() { + val facility = newFacility() + + facility.log(source = "src", level = LogLevel.WARNING, message = LogMessage("caution")) + + val contents = soleJsonFile().readText() + assertValidJsonArrayShape(contents, expectedEntries = 1) + assertContains(contents, "\"source\":\"src\"") + assertContains(contents, "\"level\":\"WARNING\"") + assertContains(contents, "\"message\":\"caution\"") + } + + @Test + fun `log appends entries with a comma separator`() { + val facility = newFacility() + + facility.log(source = "src", level = LogLevel.INFO, message = LogMessage("first")) + facility.log(source = "src", level = LogLevel.INFO, message = LogMessage("second")) + facility.log(source = "src", level = LogLevel.INFO, message = LogMessage("third")) + + val contents = soleJsonFile().readText() + assertValidJsonArrayShape(contents, expectedEntries = 3) + assertContains(contents, "\"message\":\"first\"") + assertContains(contents, "\"message\":\"second\"") + assertContains(contents, "\"message\":\"third\"") + } + + @Test + fun `log drops entries below the minimum level`() { + val facility = newFacility(minimumLogLevel = LogLevel.WARNING) + + facility.log(source = "src", level = LogLevel.INFO, message = LogMessage("quiet")) + + assertEquals(0, jsonFiles().size) + } + + @Test + fun `log with error writes the stack trace under an error key`() { + val facility = newFacility() + val boom = IllegalStateException("oops") + + facility.log(source = "src", level = LogLevel.ERROR, error = boom) + + val contents = soleJsonFile().readText() + assertValidJsonArrayShape(contents, expectedEntries = 1) + assertContains(contents, "\"error\":\"") + assertContains(contents, "IllegalStateException") + } + + @Test + fun `log with message and error writes a single entry with both fields`() { + val facility = newFacility() + val boom = IllegalStateException("oops") + + facility.log( + source = "src", + level = LogLevel.ERROR, + message = LogMessage("hello"), + error = boom, + ) + + val contents = soleJsonFile().readText() + assertValidJsonArrayShape(contents, expectedEntries = 1) + assertContains(contents, "\"message\":\"hello\"") + assertContains(contents, "\"error\":\"") + } + + @Test + fun `log includes args under the args key`() { + val facility = newFacility() + val message = LogMessage( + "request", + args = listOf(LogArg("status", 200), LogArg("path", "/x")), + ) + + facility.log(source = "src", level = LogLevel.INFO, message = message) + + val contents = soleJsonFile().readText() + assertValidJsonArrayShape(contents, expectedEntries = 1) + assertContains(contents, "\"args\":{") + assertContains(contents, "\"status\":\"200\"") + assertContains(contents, "\"path\":\"\\/x\"") + } + + @Test + fun `log escapes JSON-special characters in the message`() { + val facility = newFacility() + + facility.log( + source = "src", + level = LogLevel.INFO, + message = LogMessage("line1\nline2\twith \"quotes\""), + ) + + val contents = soleJsonFile().readText() + assertValidJsonArrayShape(contents, expectedEntries = 1) + assertContains(contents, "line1\\nline2\\twith \\\"quotes\\\"") + assertFalse( + contents.contains("line1\nline2"), + "Raw newline should not appear inside a JSON value: $contents", + ) + } + + @Test + fun `a second facility appends to the same file instead of overwriting it`() { + // Simulate an app restart: one facility writes an entry, then a fresh facility + // targeting the same folder should add a second entry rather than re-init the file. + newFacility().log(source = "src", level = LogLevel.INFO, message = LogMessage("prior")) + val fileAfterFirst = soleJsonFile() + val sizeAfterFirst = fileAfterFirst.length() + + newFacility().log(source = "src", level = LogLevel.INFO, message = LogMessage("new")) + + val contents = soleJsonFile().readText() + assertValidJsonArrayShape(contents, expectedEntries = 2) + assertContains(contents, "\"message\":\"prior\"") + assertContains(contents, "\"message\":\"new\"") + assertTrue(soleJsonFile().length() > sizeAfterFirst) + } + + @Test + fun `isEnabled is true and toString identifies the facility`() { + val facility = newFacility() + assertTrue(facility.isEnabled()) + assertContains(facility.toString(), "JsonLoggerFacility(") + } + + @Test + fun `notifier is invoked when a JSON log file is first opened`() { + val opened = mutableListOf() + val notifier = object : PlatformFileInputOutputNotifier { + override fun onLogFolderInvalid(folder: String) = Unit + override fun onLogFileOpened(path: String) { + opened += path + } + override fun onLogFileClosed(path: String) = Unit + } + val facility = newFacility(notifier = notifier) + + facility.log(source = "src", level = LogLevel.INFO, message = LogMessage("first")) + + assertEquals(1, opened.size) + assertTrue(opened.first().endsWith(".json")) + } + + // region helpers + + private fun newFacility( + minimumLogLevel: LogLevel = LogLevel.INFO, + notifier: PlatformFileInputOutputNotifier? = null, + ): JsonLoggerFacility = JsonLoggerFacility( + minimumLogLevel = minimumLogLevel, + baseFolder = tempDir.absolutePath, + coroutineScope = scope, + notifier = notifier, + ) + + private fun jsonFiles(): List = + tempDir.listFiles { f -> f.isFile && f.name.endsWith(".json") }?.toList().orEmpty() + + private fun soleJsonFile(): File { + val files = jsonFiles() + check(files.size == 1) { "Expected exactly one .json file, got ${files.map { it.name }}" } + return files.single() + } + + /** + * Verifies the file contents look like a well-formed JSON array of `expectedEntries` + * top-level objects, without pulling in a full JSON parser. + * + * Structural invariants checked: + * - Starts with `[` and ends with `]`. + * - Brace count matches (balanced `{` and `}`). + * - Exactly `expectedEntries - 1` top-level `,` separators at brace-depth 1. + */ + private fun assertValidJsonArrayShape( + contents: String, + expectedEntries: Int, + ) { + assertTrue(contents.startsWith("["), "Must start with '[': $contents") + assertTrue(contents.endsWith("]"), "Must end with ']': $contents") + + var depth = 0 + var topLevelSeparators = 0 + var objectCount = 0 + var inString = false + var escaped = false + contents.substring(1, contents.length - 1).forEach { ch -> + if (escaped) { + escaped = false + return@forEach + } + when { + ch == '\\' && inString -> escaped = true + ch == '"' -> inString = !inString + inString -> Unit + ch == '{' -> { + if (depth == 0) objectCount++ + depth++ + } + ch == '}' -> depth-- + ch == ',' && depth == 0 -> topLevelSeparators++ + } + } + assertEquals(0, depth, "Unbalanced braces: $contents") + assertEquals( + expectedEntries, + objectCount, + "Expected $expectedEntries top-level objects: $contents", + ) + assertEquals( + (expectedEntries - 1).coerceAtLeast(0), + topLevelSeparators, + "Expected ${expectedEntries - 1} top-level commas: $contents", + ) + } + + // endregion +} From 143ff7652bf6a88b62c754db8f3a94991bfc8eb5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A5le=20Stor=C3=B8=20Hauknes?= Date: Fri, 24 Apr 2026 08:59:58 +0200 Subject: [PATCH 2/6] Address PR comments --- .../platform/PlatformFileInputOutputImpl.kt | 10 ++--- .../logging/facility/JsonLoggerFacility.kt | 44 +++++++++++-------- 2 files changed, 31 insertions(+), 23 deletions(-) diff --git a/src/androidMain/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImpl.kt b/src/androidMain/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImpl.kt index 8ca382b..f062093 100644 --- a/src/androidMain/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImpl.kt +++ b/src/androidMain/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImpl.kt @@ -25,6 +25,7 @@ import com.airthings.lib.logging.PLATFORM_ANDROID import com.airthings.lib.logging.ifAfter import java.io.File import java.io.FileOutputStream +import java.io.RandomAccessFile internal actual class PlatformFileInputOutputImpl : PlatformFileInputOutput { private val writeLock = Any() @@ -47,13 +48,12 @@ internal actual class PlatformFileInputOutputImpl : PlatformFileInputOutput { contents: String, ) { synchronized(writeLock) { - FileOutputStream(File(path), true).use { - val channel = it.channel - val size = channel.size() + RandomAccessFile(File(path), "rw").use { raf -> + val size = raf.length() val relativePosition = position.relativeToSize(size) - channel.position(relativePosition) - it.write(contents.toByteArray()) + raf.seek(relativePosition) + raf.write(contents.toByteArray()) } } } diff --git a/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt b/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt index 8794a40..e1062bf 100644 --- a/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt +++ b/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt @@ -37,6 +37,8 @@ import com.airthings.lib.logging.platform.PlatformFileInputOutputNotifier import com.airthings.lib.logging.utc import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.launch +import kotlinx.coroutines.sync.Mutex +import kotlinx.coroutines.sync.withLock import kotlinx.datetime.LocalDateTime /** @@ -137,6 +139,7 @@ class JsonLoggerFacility( }, ) private val currentLogFile = AtomicReference(null) + private val writeMutex = Mutex() /** * Returns the platform-dependent [PlatformDirectoryListing] instance. @@ -236,29 +239,34 @@ class JsonLoggerFacility( } coroutineScope.launch { - val logFile = "$baseFolder${io.pathSeparator}${dateStamp(null)}.json" - val currentLogFileLocked = currentLogFile.value + // Serialize size-check and write: two concurrent launches can otherwise both + // read the same pre-write size and both skip the comma separator. + writeMutex.withLock { + val logFile = "$baseFolder${io.pathSeparator}${dateStamp(null)}.json" + val currentLogFileLocked = currentLogFile.value + + if (currentLogFileLocked != logFile) { + if (currentLogFileLocked != null) { + notifier?.onLogFileClosed(currentLogFileLocked) + } + io.ensure(logFile) - if (currentLogFileLocked != logFile) { - if (currentLogFileLocked != null) { - notifier?.onLogFileClosed(currentLogFileLocked) - } - io.ensure(logFile) + // A fresh JSON log file starts its life as an empty array ("[]"). Don't + // overwrite one that already exists from a previous session. + if (io.size(logFile) == 0L) { + io.append(logFile, "$ARRAY_OPEN$ARRAY_CLOSE") + } - // A fresh JSON log file starts its life as an empty array ("[]"). Don't - // overwrite one that already exists from a previous session. - if (io.size(logFile) == 0L) { - io.append(logFile, "$ARRAY_OPEN$ARRAY_CLOSE") + currentLogFile.set(logFile) + notifier?.onLogFileOpened(logFile) } - currentLogFile.set(logFile) - notifier?.onLogFileOpened(logFile) + // A file that's just "[]" is 2 bytes. Anything longer means there's already + // at least one entry, so the new entry needs to be preceded by a comma + // separator. + val hasPriorEntries = io.size(logFile) > 2L + action(logFile, if (hasPriorEntries) "," else "") } - - // A file that's just "[]" is 2 bytes. Anything longer means there's already at - // least one entry, so the new entry needs to be preceded by a comma separator. - val hasPriorEntries = io.size(logFile) > 2L - action(logFile, if (hasPriorEntries) "," else "") } } From c389f97c085751ac73004a8781bf071796cd1ef2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A5le=20Stor=C3=B8=20Hauknes?= Date: Fri, 24 Apr 2026 09:43:12 +0200 Subject: [PATCH 3/6] Address more PR comments --- .../logging/facility/JsonLoggerFacility.kt | 20 ++++++++----------- .../facility/JsonLoggerFacilityTest.kt | 3 ++- 2 files changed, 10 insertions(+), 13 deletions(-) diff --git a/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt b/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt index e1062bf..0056686 100644 --- a/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt +++ b/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt @@ -250,22 +250,18 @@ class JsonLoggerFacility( notifier?.onLogFileClosed(currentLogFileLocked) } io.ensure(logFile) - - // A fresh JSON log file starts its life as an empty array ("[]"). Don't - // overwrite one that already exists from a previous session. - if (io.size(logFile) == 0L) { - io.append(logFile, "$ARRAY_OPEN$ARRAY_CLOSE") - } - currentLogFile.set(logFile) notifier?.onLogFileOpened(logFile) } - // A file that's just "[]" is 2 bytes. Anything longer means there's already - // at least one entry, so the new entry needs to be preceded by a comma - // separator. - val hasPriorEntries = io.size(logFile) > 2L - action(logFile, if (hasPriorEntries) "," else "") + // A fresh JSON log file starts its life as an empty array ("[]") — 2 bytes. + // Anything longer means there's already at least one entry, so the new entry + // needs to be preceded by a comma separator. + val size = io.size(logFile) + if (size == 0L) { + io.append(logFile, "$ARRAY_OPEN$ARRAY_CLOSE") + } + action(logFile, if (size > 2L) "," else "") } } } diff --git a/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt b/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt index 1561048..27faf6a 100644 --- a/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt +++ b/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt @@ -205,7 +205,8 @@ class JsonLoggerFacilityTest { * Structural invariants checked: * - Starts with `[` and ends with `]`. * - Brace count matches (balanced `{` and `}`). - * - Exactly `expectedEntries - 1` top-level `,` separators at brace-depth 1. + * - Exactly `expectedEntries - 1` top-level `,` separators at depth 0 + * (after stripping the outer `[...]`). */ private fun assertValidJsonArrayShape( contents: String, From 97f77971894a322d3a8e9aecb8c46d2db121fb19 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A5le=20Stor=C3=B8=20Hauknes?= Date: Mon, 27 Apr 2026 11:22:58 +0200 Subject: [PATCH 4/6] Fix bug --- .../lib/logging/facility/JsonLoggerFacility.kt | 16 +++++++++++----- 1 file changed, 11 insertions(+), 5 deletions(-) diff --git a/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt b/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt index 0056686..fab945a 100644 --- a/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt +++ b/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt @@ -239,19 +239,22 @@ class JsonLoggerFacility( } coroutineScope.launch { + var closedPath: String? = null + var openedPath: String? = null + // Serialize size-check and write: two concurrent launches can otherwise both - // read the same pre-write size and both skip the comma separator. + // read the same pre-write size and both skip the comma separator. Notifier + // callbacks are user code and must run outside the lock — invoking them under + // a non-reentrant `Mutex` would deadlock if a notifier triggers another log(). writeMutex.withLock { val logFile = "$baseFolder${io.pathSeparator}${dateStamp(null)}.json" val currentLogFileLocked = currentLogFile.value if (currentLogFileLocked != logFile) { - if (currentLogFileLocked != null) { - notifier?.onLogFileClosed(currentLogFileLocked) - } + closedPath = currentLogFileLocked io.ensure(logFile) currentLogFile.set(logFile) - notifier?.onLogFileOpened(logFile) + openedPath = logFile } // A fresh JSON log file starts its life as an empty array ("[]") — 2 bytes. @@ -263,6 +266,9 @@ class JsonLoggerFacility( } action(logFile, if (size > 2L) "," else "") } + + closedPath?.let { notifier?.onLogFileClosed(it) } + openedPath?.let { notifier?.onLogFileOpened(it) } } } From 6241bde627ac1da0e8a16a5131df785a772c592e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A5le=20Stor=C3=B8=20Hauknes?= Date: Mon, 27 Apr 2026 14:47:39 +0200 Subject: [PATCH 5/6] Add more tests --- .../facility/JsonLoggerFacilityTest.kt | 47 +++++++++++++++++++ 1 file changed, 47 insertions(+) diff --git a/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt b/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt index 27faf6a..22103f9 100644 --- a/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt +++ b/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt @@ -1,6 +1,7 @@ package com.airthings.lib.logging.facility import com.airthings.lib.logging.LogArg +import com.airthings.lib.logging.LogDate import com.airthings.lib.logging.LogLevel import com.airthings.lib.logging.LogMessage import com.airthings.lib.logging.platform.PlatformFileInputOutputNotifier @@ -15,6 +16,7 @@ import kotlin.test.assertFalse import kotlin.test.assertTrue import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.Dispatchers +import kotlinx.coroutines.test.runTest class JsonLoggerFacilityTest { @@ -177,6 +179,51 @@ class JsonLoggerFacilityTest { assertTrue(opened.first().endsWith(".json")) } + @Test + fun `secondary constructor with baseFolder+scope+notifier defaults to WARNING`() { + val facility = JsonLoggerFacility( + baseFolder = tempDir.absolutePath, + scope = scope, + notifier = null, + ) + facility.log(source = "src", level = LogLevel.INFO, message = LogMessage("filtered out")) + assertEquals(0, jsonFiles().size) + } + + @Test + fun `secondary constructor with minimumLogLevel+baseFolder+notifier uses default scope`() { + // The default scope uses Dispatchers.Main which isn't available in plain JUnit; verify + // construction succeeds without invoking log() on this instance. + JsonLoggerFacility( + minimumLogLevel = LogLevel.INFO, + baseFolder = tempDir.absolutePath, + notifier = null, + ) + } + + @Test + fun `files() returns the JSON log files in the folder`() = runTest { + val facility = newFacility() + File(tempDir, "2024-03-05.json").createNewFile() + File(tempDir, "2024-03-06.json").createNewFile() + + val files = facility.files() + + assertEquals(2, files.size) + } + + @Test + fun `files(date) returns only JSON log files newer than the cutoff`() = runTest { + val facility = newFacility() + File(tempDir, "2024-03-05.json").createNewFile() + File(tempDir, "2024-03-07.json").createNewFile() + + val files = facility.files(LogDate(2024, 3, 6)) + + assertEquals(1, files.size) + assertTrue(files.first().endsWith("2024-03-07.json")) + } + // region helpers private fun newFacility( From fd2e4d45c75f1c11ef15a24b2504ccf8263ee25e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?St=C3=A5le=20Stor=C3=B8=20Hauknes?= <270292+LaStrada@users.noreply.github.com> Date: Fri, 12 Jun 2026 13:24:46 +0200 Subject: [PATCH 6/6] Fix JsonLoggerFacility producing invalid JSON Three bugs made the JSON log array malformed, plus the JVM/Android file writes weren't seekable: - Inverted comma-separator flag: the first entry got a leading comma, later entries got none. - Args were emitted as a bare {k:v} block with no "args": key, which is invalid inside the entry object. - write(path, position, contents) used FileOutputStream in append mode, which ignores channel.position(...), so the trailing "]" was never overwritten. Switched to RandomAccessFile for true seekable writes. Serialize the size-check + write under a Mutex so concurrent log calls can't both skip the separator, and run notifier callbacks outside the lock to avoid re-entrant deadlocks. Escape all control characters per RFC 8259. Co-Authored-By: Claude Opus 4.8 (1M context) --- .../platform/PlatformFileInputOutputImpl.kt | 8 +- .../logging/facility/JsonLoggerFacility.kt | 50 +++++++--- .../facility/JsonLoggerFacilityTest.kt | 96 ++++++++++++++++++- .../PlatformFileInputOutputImplTest.kt | 49 ++++++++++ 4 files changed, 184 insertions(+), 19 deletions(-) create mode 100644 src/jvmTest/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImplTest.kt diff --git a/src/androidMain/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImpl.kt b/src/androidMain/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImpl.kt index f062093..037b382 100644 --- a/src/androidMain/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImpl.kt +++ b/src/androidMain/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImpl.kt @@ -70,8 +70,12 @@ internal actual class PlatformFileInputOutputImpl : PlatformFileInputOutput { } actual override suspend fun ensure(path: String) { - synchronized(writeLock) { - File(path).createNewFile() + val parentPath = File(path).parentFile.canonicalPath + + if (mkdirs(parentPath)) { + synchronized(writeLock) { + File(path).createNewFile() + } } } diff --git a/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt b/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt index fab945a..2f0cfdb 100644 --- a/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt +++ b/src/commonMain/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacility.kt @@ -251,24 +251,30 @@ class JsonLoggerFacility( val currentLogFileLocked = currentLogFile.value if (currentLogFileLocked != logFile) { - closedPath = currentLogFileLocked + // ensure() can throw; mutate state only after it succeeds so a retry + // on the next log() sees the same `currentLogFile` and re-attempts. io.ensure(logFile) + closedPath = currentLogFileLocked currentLogFile.set(logFile) openedPath = logFile } - // A fresh JSON log file starts its life as an empty array ("[]") — 2 bytes. - // Anything longer means there's already at least one entry, so the new entry - // needs to be preceded by a comma separator. + // A fresh JSON log file is "[]" (2 bytes). Anything longer means at least + // one entry already, so the new entry needs a comma separator. A file + // shorter than 2 bytes (size 0, or a stray "[" from a partial write or + // external truncation) is reseeded via write-at-position-0 — `append` + // would leave the stray byte in place and produce "[[]". val size = io.size(logFile) - if (size == 0L) { - io.append(logFile, "$ARRAY_OPEN$ARRAY_CLOSE") + if (size < 2L) { + io.write(logFile, position = 0L, contents = "$ARRAY_OPEN$ARRAY_CLOSE") } action(logFile, if (size > 2L) "," else "") } - closedPath?.let { notifier?.onLogFileClosed(it) } - openedPath?.let { notifier?.onLogFileOpened(it) } + // Notifier callbacks are user code; isolate failures so a misbehaving observer + // can't tear down the log coroutine after the write has already succeeded. + closedPath?.let { path -> runCatching { notifier?.onLogFileClosed(path) } } + openedPath?.let { path -> runCatching { notifier?.onLogFileOpened(path) } } } } @@ -286,13 +292,27 @@ class JsonLoggerFacility( private const val CURLY_OPEN: Char = '{' private const val CURLY_CLOSE: Char = '}' - private fun String.jsonEscape(): String = replace("\\", "\\\\") - .replace("/", "\\/") - .replace("\"", "\\\"") - .replace("\b", "\\b") - .replace("\r", "\\r") - .replace("\n", "\\n") - .replace("\t", "\\t") + private fun String.jsonEscape(): String = buildString(length) { + this@jsonEscape.forEach { c -> + when (c) { + '\\' -> append("\\\\") + '"' -> append("\\\"") + '/' -> append("\\/") + '\b' -> append("\\b") + '\u000C' -> append("\\f") + '\n' -> append("\\n") + '\r' -> append("\\r") + '\t' -> append("\\t") + else -> if (c < '\u0020') { + // RFC 8259: every control character U+0000..U+001F must be escaped. + append("\\u") + append(c.code.toString(16).padStart(4, '0')) + } else { + append(c) + } + } + } + } private fun String.jsonQuote(): String = "\"${jsonEscape()}\"" diff --git a/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt b/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt index 22103f9..e0bfd4b 100644 --- a/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt +++ b/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt @@ -16,6 +16,11 @@ import kotlin.test.assertFalse import kotlin.test.assertTrue import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.Dispatchers +import kotlinx.coroutines.Job +import kotlinx.coroutines.coroutineScope +import kotlinx.coroutines.joinAll +import kotlinx.coroutines.launch +import kotlinx.coroutines.runBlocking import kotlinx.coroutines.test.runTest class JsonLoggerFacilityTest { @@ -193,12 +198,99 @@ class JsonLoggerFacilityTest { @Test fun `secondary constructor with minimumLogLevel+baseFolder+notifier uses default scope`() { // The default scope uses Dispatchers.Main which isn't available in plain JUnit; verify - // construction succeeds without invoking log() on this instance. - JsonLoggerFacility( + // construction succeeds and the basic surface is wired up without invoking log(). + val facility = JsonLoggerFacility( + minimumLogLevel = LogLevel.INFO, + baseFolder = tempDir.absolutePath, + notifier = null, + ) + + assertTrue(facility.isEnabled()) + assertContains(facility.toString(), "JsonLoggerFacility(") + } + + @Test + fun `log escapes control characters as backslash-u sequences`() { + val facility = newFacility() + + facility.log( + source = "src", + level = LogLevel.INFO, + message = LogMessage("\u0000-\u000c-\u001f"), + ) + + val contents = soleJsonFile().readText() + assertValidJsonArrayShape(contents, expectedEntries = 1) + assertContains(contents, "\\u0000-\\f-\\u001f") + assertFalse( + contents.contains("\u000c"), + "Raw form-feed should not appear in the output: $contents", + ) + } + + @Test + fun `concurrent log calls produce a valid JSON array`() { + // The writeMutex serializes the size-check + write that would otherwise interleave + // and cause two concurrent launches to both omit the comma. Drive real concurrency + // (Dispatchers.Unconfined runs every launch synchronously on the caller, which can't + // exercise the bug). + val facilityJob = Job() + val facilityScope = CoroutineScope(Dispatchers.IO + facilityJob) + val facility = JsonLoggerFacility( minimumLogLevel = LogLevel.INFO, baseFolder = tempDir.absolutePath, + coroutineScope = facilityScope, notifier = null, ) + + runBlocking { + val n = 50 + coroutineScope { + repeat(n) { i -> + launch(Dispatchers.IO) { + facility.log( + source = "src", + level = LogLevel.INFO, + message = LogMessage("entry-$i"), + ) + } + } + } + // facility.log is fire-and-forget; wait for all spawned writes to drain. + facilityJob.children.toList().joinAll() + } + + val contents = soleJsonFile().readText() + assertValidJsonArrayShape(contents, expectedEntries = 50) + + facilityScope.coroutineContext[Job]?.cancel() + } + + @Test + fun `notifier callback can call log without deadlocking`() { + // The mutex/notifier ordering invariant is that callbacks run outside writeMutex — + // a notifier that itself calls log() would otherwise deadlock on a non-reentrant + // Mutex. If this test ever hangs, that invariant has regressed. + lateinit var facility: JsonLoggerFacility + val notifier = object : PlatformFileInputOutputNotifier { + override fun onLogFolderInvalid(folder: String) = Unit + override fun onLogFileOpened(path: String) { + facility.log( + source = "src", + level = LogLevel.INFO, + message = LogMessage("from-notifier"), + ) + } + override fun onLogFileClosed(path: String) = Unit + } + facility = newFacility(notifier = notifier) + + facility.log(source = "src", level = LogLevel.INFO, message = LogMessage("first")) + + val contents = soleJsonFile().readText() + assertValidJsonArrayShape(contents, expectedEntries = 2) + assertContains(contents, "\"message\":\"first\"") + assertContains(contents, "\"message\":\"from-notifier\"") } @Test diff --git a/src/jvmTest/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImplTest.kt b/src/jvmTest/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImplTest.kt new file mode 100644 index 0000000..e171c7f --- /dev/null +++ b/src/jvmTest/kotlin/com/airthings/lib/logging/platform/PlatformFileInputOutputImplTest.kt @@ -0,0 +1,49 @@ +package com.airthings.lib.logging.platform + +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 kotlinx.coroutines.test.runTest + +class PlatformFileInputOutputImplTest { + + private lateinit var tempDir: File + private val io = PlatformFileInputOutputImpl() + + @BeforeTest + fun setUp() { + tempDir = Files.createTempDirectory("kmplog-platform-io-").toFile() + } + + @AfterTest + fun tearDown() { + tempDir.deleteRecursively() + } + + @Test + fun `write at position -1 overwrites the trailing byte`() = runTest { + // FileOutputStream(append=true) silently ignores channel.position(...) — the previous + // implementation always wrote at EOF, so a write at position=-1 (intended to overwrite + // the trailing "]" of a JSON array) was concatenated instead. RandomAccessFile honors + // seek(), which is what JsonLoggerFacility relies on. + val file = File(tempDir, "trail.json").apply { writeText("[{\"a\":1}]") } + + io.write(path = file.absolutePath, position = -1L, contents = ",{\"b\":2}]") + + assertEquals("[{\"a\":1},{\"b\":2}]", file.readText()) + } + + @Test + fun `write at position 0 overwrites in place and extends a shorter file`() = runTest { + // Used by JsonLoggerFacility to reseed a corrupted/short file (size 0 or 1) back to + // a clean "[]". A 1-byte file is extended to 2 bytes by writing 2 bytes from position 0. + val file = File(tempDir, "stub.json").apply { writeText("[") } + + io.write(path = file.absolutePath, position = 0L, contents = "[]") + + assertEquals("[]", file.readText()) + } +}