fix(debug): Stop a failed start from erasing a resumed recording

Two rollback defects found reviewing the failed-start handling, both cases
where cleaning up after a start that could not finish damaged something it
did not own:

- FileLogger.start() deletes the log file only when that same call created
  it, and reports the failure instead of swallowing it. A resumed session
  appends to the previous recording's core.log, and a failed append used to
  erase it while telling the recorder the start had succeeded. The writer is
  published only once it is usable, so a failed attempt leaves nothing behind
  that would make a later start() a no-op (F3).
- The module's rollback skips self-suppression: a recorder broken in one way
  throws the same instance on the start line and again when the rollback
  stops it, and addSuppressed(self) raises IllegalArgumentException — which
  aborted the rollback before the failure state was committed and took the
  shared state collector with it (F4).

Recorder.start() is the only production caller of FileLogger.start(), and it
runs inside the module's whole-branch guard, so the new throw lands in the
rollback rather than escaping.

Fixes review findings F3, F4
This commit is contained in:
darken
2026-08-04 18:26:47 +02:00
committed by Matthias Urhahn
parent c696e523a9
commit ed940b3b3d
4 changed files with 180 additions and 11 deletions
@@ -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
@@ -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()) {
@@ -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<Context>().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<IOException> { 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<IOException> { 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<IOException> { 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)
}
}
}
@@ -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<Recorder>(relaxed = true)
coEvery { brokenRecorder.start(any()) } throws wedged
coEvery { brokenRecorder.stop() } throws wedged
withModules { modules ->
val module = modules.create(recorderFactory = { brokenRecorder })
shouldThrow<IOException> { 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