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..037b382 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()) } } } @@ -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 6414c18..2f0cfdb 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,26 +239,42 @@ class JsonLoggerFacility( } coroutineScope.launch { - 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) + 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. 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) { + // 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 } - io.ensure(logFile) - // New JSON log files start their life as an empty array ("[]"). - io.append(logFile, "$ARRAY_OPEN$ARRAY_CLOSE") - - currentLogFile.set(logFile) - notifier?.onLogFileOpened(logFile) + // 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 < 2L) { + io.write(logFile, position = 0L, contents = "$ARRAY_OPEN$ARRAY_CLOSE") + } + action(logFile, if (size > 2L) "," else "") } - action(logFile, if (isEmpty) "" else ",") + // 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) } } } } @@ -273,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()}\"" @@ -335,6 +368,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..e0bfd4b --- /dev/null +++ b/src/jvmTest/kotlin/com/airthings/lib/logging/facility/JsonLoggerFacilityTest.kt @@ -0,0 +1,393 @@ +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 +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 +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 { + + 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")) + } + + @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 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 + 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( + 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 depth 0 + * (after stripping the outer `[...]`). + */ + 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 +} 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()) + } +}