diff --git a/app/src/main/java/eu/darken/capod/common/debug/logging/FileLogger.kt b/app/src/main/java/eu/darken/capod/common/debug/logging/FileLogger.kt index 70e659ae..edbf2805 100644 --- a/app/src/main/java/eu/darken/capod/common/debug/logging/FileLogger.kt +++ b/app/src/main/java/eu/darken/capod/common/debug/logging/FileLogger.kt @@ -17,32 +17,47 @@ class FileLogger( ) : Logging.Logger { private var logWriter: OutputStreamWriter? = null + /** + * A failure here belongs to the caller: swallowing it left an installed logger writing nowhere, + * so a recording looked like it had started and produced an empty log. + */ @SuppressLint("SetWorldReadable") @Synchronized fun start() { if (logWriter != null) return logFile.parentFile!!.mkdirs() - if (logFile.createNewFile()) { + // Whether THIS attempt created the file decides what a failure below may delete: a resumed + // session appends to a log file that already holds the previous recording, and failing to + // open it must not erase that. + val createdNow = logFile.createNewFile() + if (createdNow) { Log.i(TAG, "File logger writing to " + logFile.path) } if (logFile.setReadable(true, false)) { Log.i(TAG, "Debug run log read permission set") } + var writer: OutputStreamWriter? = null try { - logWriter = OutputStreamWriter(FileOutputStream(logFile, true)) - logWriter!!.write("=== BEGIN ===\n") - logWriter!!.write("Logfile: $logFile\n") - logWriter!!.flush() - Log.i(TAG, "File logger started.") + writer = OutputStreamWriter(FileOutputStream(logFile, true)) + writer.write("=== BEGIN ===\n") + writer.write("Logfile: $logFile\n") + writer.flush() } catch (e: IOException) { - e.printStackTrace() - - logFile.delete() - if (logWriter != null) logWriter!!.close() + Log.e(TAG, "File logger failed to start.", e) + try { + writer?.close() + } catch (ignore: IOException) { + } + if (createdNow) logFile.delete() + throw e } + // Published only once it is usable, so a failed attempt leaves nothing behind that would + // make a later start() a no-op. + logWriter = writer + Log.i(TAG, "File logger started.") } @Synchronized diff --git a/app/src/main/java/eu/darken/capod/common/debug/recording/core/RecorderModule.kt b/app/src/main/java/eu/darken/capod/common/debug/recording/core/RecorderModule.kt index 1f5fb75c..837cb529 100644 --- a/app/src/main/java/eu/darken/capod/common/debug/recording/core/RecorderModule.kt +++ b/app/src/main/java/eu/darken/capod/common/debug/recording/core/RecorderModule.kt @@ -137,7 +137,7 @@ class RecorderModule @Inject constructor( try { it.stop() } catch (stopError: Exception) { - e.addSuppressed(stopError) + e.recordSuppressed(stopError) } } this@RecorderModule.currentLogDir = null @@ -259,6 +259,22 @@ class RecorderModule @Inject constructor( else -> error } + /** + * Attaches a rollback failure to the failure being reported. The very same throwable can come + * back out of the rollback — a recorder broken in one way throws it on the start line and again + * on the teardown line — and [Throwable.addSuppressed] rejects self-suppression with an + * [IllegalArgumentException], which would abort the rollback before the failure is ever + * published. + */ + private fun Throwable.recordSuppressed(other: Throwable) { + if (other === this) return + try { + addSuppressed(other) + } catch (e: Exception) { + // Bookkeeping only: nothing about reporting the failure may replace the failure itself. + } + } + private fun deleteTriggerFile() { try { if (triggerFile.exists() && !triggerFile.delete()) { diff --git a/app/src/test/java/eu/darken/capod/common/debug/logging/FileLoggerTest.kt b/app/src/test/java/eu/darken/capod/common/debug/logging/FileLoggerTest.kt new file mode 100644 index 00000000..9bf9cdd3 --- /dev/null +++ b/app/src/test/java/eu/darken/capod/common/debug/logging/FileLoggerTest.kt @@ -0,0 +1,106 @@ +package eu.darken.capod.common.debug.logging + +import android.content.Context +import androidx.test.core.app.ApplicationProvider +import io.kotest.assertions.throwables.shouldThrow +import io.kotest.matchers.shouldBe +import io.kotest.matchers.string.shouldContain +import org.junit.After +import org.junit.Assume.assumeTrue +import org.junit.Before +import org.junit.Test +import org.junit.runner.RunWith +import org.robolectric.RobolectricTestRunner +import org.robolectric.annotation.Config +import testhelpers.BaseTest +import testhelpers.TestApplication +import testhelpers.TestTimeSource +import java.io.File +import java.io.IOException + +/** + * A file logger that cannot open its writer used to swallow the failure and wipe the log file on + * the way out: the recorder was told the recording had started while nothing could be written to + * it, and a resumed session lost the recording it was continuing. + * + * Robolectric because [FileLogger] logs through [android.util.Log] directly, which is not mocked in + * plain unit tests here. + */ +@RunWith(RobolectricTestRunner::class) +@Config(sdk = [33], application = TestApplication::class) +class FileLoggerTest : BaseTest() { + + private val timeSource = TestTimeSource() + + private val sessionDir: File + get() = File(ApplicationProvider.getApplicationContext().cacheDir, "filelogger-test") + + @Before + fun cleanSessionDir() { + sessionDir.deleteRecursively() + sessionDir.mkdirs() + } + + @After + fun removeSessionDir() { + sessionDir.deleteRecursively() + } + + @Test + fun `a log file that cannot be opened fails the start`() { + // core.log occupied by a directory: the writer cannot be opened. + val logFile = File(sessionDir, "core.log").also { it.mkdirs() } + + val logger = FileLogger(logFile, timeSource) + + shouldThrow { logger.start() } + + // Inert rather than half-started: nothing was published, so neither writing nor stopping + // does anything. + logger.log(Logging.Priority.INFO, "tag", "dropped", null) + logger.stop() + } + + @Test + fun `a failed start leaves the logger startable`() { + val logFile = File(sessionDir, "core.log").also { it.mkdirs() } + val logger = FileLogger(logFile, timeSource) + shouldThrow { logger.start() } + + // With the obstruction gone the same logger has to start for real: the failed attempt must + // not have left a writer reference behind that makes the retry a no-op. + logFile.deleteRecursively() + logger.start() + logger.log(Logging.Priority.INFO, "tag", "recorded", null) + logger.stop() + + logFile.readText() shouldContain "recorded" + } + + /** + * A resumed session appends to the log file of the recording it continues. Cleaning up after a + * failed open deleted that file unconditionally, so a resume that could not append (a full + * disk) destroyed the recording the user was about to send. + */ + @Test + fun `a failed start keeps a log file it did not create`() { + val logFile = File(sessionDir, "core.log") + logFile.writeText("=== BEGIN ===\nprevious recording\n") + // Read-only: the append cannot be opened, but the file itself is perfectly deletable. + logFile.setWritable(false, false) + assumeTrue("The read-only bit is not enforced for this user", !logFile.canWrite()) + + try { + val logger = FileLogger(logFile, timeSource) + + // The failure has to surface: the module's rollback only runs if it does. + shouldThrow { logger.start() } + + // Only a file THIS attempt created may be cleaned up. + logFile.exists() shouldBe true + logFile.readText() shouldContain "previous recording" + } finally { + logFile.setWritable(true, true) + } + } +} diff --git a/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleStartFailureTest.kt b/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleStartFailureTest.kt index 1eb477c2..4bf9ae32 100644 --- a/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleStartFailureTest.kt +++ b/app/src/test/java/eu/darken/capod/common/debug/recording/core/RecorderModuleStartFailureTest.kt @@ -301,6 +301,38 @@ class RecorderModuleStartFailureTest : BaseTest() { } } + /** + * A recorder that is broken in one way throws the SAME exception instance on the start line and + * again when the rollback stops it — and [Throwable.addSuppressed] rejects self-suppression with + * an [IllegalArgumentException]. Raised inside the rollback, that would escape before the + * failure is ever committed: the collector dies and the module wedges, which is the very thing + * the rollback exists to prevent. + */ + @Test + fun `a rollback that throws the start's own error still publishes the failure`() { + val wedged = IOException("log writer wedged") + val brokenRecorder = mockk(relaxed = true) + coEvery { brokenRecorder.start(any()) } throws wedged + coEvery { brokenRecorder.stop() } throws wedged + + withModules { modules -> + val module = modules.create(recorderFactory = { brokenRecorder }) + + shouldThrow { module.startRecorder() } shouldBe wedged + + val state = module.state.first() + state.isRecording shouldBe false + state.shouldRecord shouldBe false + state.startFailure shouldBe wedged + state.currentLogDir.shouldBeNull() + module.currentLogDir.shouldBeNull() + triggerFile.exists() shouldBe false + // The rollback ran to its end rather than aborting at the suppression: the dir it + // created for this attempt is gone too. + externalLogsDir.listFiles()?.toList().orEmpty().shouldBeEmpty() + } + } + /** * The start is only committed into the state once the recorder is live, so for the whole window * before that the session dir sits on disk with nothing pointing at it: a scan sees a directory