Skip to content

CodeUseTelemetryBusyRecoverySmokeTest.kt

src/jvmMain/kotlin/afield/examples/CodeUseTelemetryBusyRecoverySmokeTest.kt · 168 lines

package afield.examples

import afield.app.diagnostics.CodeUseSummary
import afield.app.diagnostics.CodeUseTelemetryService
import java.nio.file.Files
import java.sql.DriverManager

FIELD_TEST id: examples.code-use.writer-busy-recovery runner: jvm-main entrypoint: afield.examples.CodeUseTelemetryBusyRecoverySmokeTest tags: [smoke, code-use, telemetry, sqlite] timeoutSec: 60 expect: exitCode: 0 stdoutContains: - "CodeUseTelemetryBusyRecoverySmokeTest ok"

object CodeUseTelemetryBusyRecoverySmokeTest

A second connection holds the telemetry database's write lock through two of the writer's 5 s busy timeouts. The writer must stay enabled, report the SQLITE_BUSY retries and the events it is holding, and commit every one of them once the lock is released. Analysis of a held compile event must wait for that commit.

object CodeUseTelemetryBusyRecoverySmokeTest {

fun main(args: Array<String>)

body — 140 lines, from line 28
    @JvmStatic
    fun main(args: Array<String>) {
        val tempDir = Files.createTempDirectory("afield-code-use-busy")
        val database = tempDir.resolve("field-code-use.sqlite").toString()
        System.setProperty("afield.codeUse.path", database)
        System.setProperty("afield.codeUse.semanticSidecar.url", "")

        val context = CodeUseTelemetryService.CodeUseContext(
            document = "code-use-busy",
            boxUid = "box-code-use-busy",
            boxName = "Code Use Busy",
            property = "code",
            mode = "execute",
            strand = "__main__"
        )

        // Let the writer create the schema and commit once before the lock is taken. A launch event
        // with no source queues no analysis, so no analyzer transaction competes for the lock.
        CodeUseTelemetryService.recordLaunchLifecycle(
            snippetId = CodeUseTelemetryService.newSnippetKey(),
            source = "",
            context = context,
            lifecycle = "execute-start"
        )
        waitForSummary("the primer event to commit") { it.launchEvents >= 1 }

        val blocker = DriverManager.getConnection("jdbc:sqlite:$database")
        blocker.autoCommit = false
        blocker.createStatement().use {
            it.executeUpdate("INSERT INTO classpath_entries(hash, path, mtime, size) VALUES('busy-smoke', 'write-lock', 0, 0)")
        }
        val lockTakenAt = System.currentTimeMillis()

        val launchIds = List(3) { CodeUseTelemetryService.newSnippetKey() }
        launchIds.forEach {
            CodeUseTelemetryService.recordLaunchLifecycle(snippetId = it, source = "", context = context, lifecycle = "execute-start")
        }
        val evalId = CodeUseTelemetryService.newSnippetKey()
        CodeUseTelemetryService.recordEvaluationResult(
            snippetId = evalId,
            context = context.copy(mode = "evaluate"),
            success = true,
            returnType = "kotlin.Unit",
            elapsedMs = 0.5
        )
        // `sin` matches several source definitions, so the analyzer records an ambiguity row.
        val compileId = CodeUseTelemetryService.newSnippetKey()
        CodeUseTelemetryService.recordCompileResult(
            snippetId = compileId,
            source = "sin(0.0)",
            sourceName = "CodeUseTelemetryBusyRecovery.kts",
            context = context.copy(mode = "compile:user-code"),
            success = true,
            diagnostics = emptyList(),
            elapsedMs = 0.25
        )
        val heldEvents = launchIds.size + 2

        val waiting = waitForSummary("two SQLITE_BUSY retries", timeoutMs = 30_000) { it.writerBusyRetries >= 2 }
        val heldForMs = System.currentTimeMillis() - lockTakenAt
        require(heldForMs > 5_000) { "Lock was held only $heldForMs ms, not past busy_timeout" }
        require(waiting.enabled) { "Writer disabled itself on SQLITE_BUSY: $waiting" }
        require("SQLITE_BUSY" in waiting.writerError) { "Summary does not name the busy error: $waiting" }
        require("write lock" in waiting.message) { "Summary message does not report the wait: $waiting" }
        require(waiting.queueSize >= heldEvents) { "Held events missing from queueSize: $waiting" }
        require(launchRows(database, launchIds) == 0) { "Held events were committed while the lock was held" }
        // Queued before the commit, the analysis job would have run, waited out the lock, and counted.
        require(waiting.analyzerCompletedJobs == 0L && waiting.analyzerQueueSize == 0) {
            "Analysis was queued before its compile event committed: $waiting"
        }

        blocker.rollback()
        blocker.close()

        waitFor("the held events to commit", timeoutMs = 30_000) {
            launchRows(database, launchIds) == launchIds.size &&
                rowCount(database, "eval_events", evalId) == 1 &&
                rowCount(database, "compile_events", compileId) == 1
        }
        val recovered = waitForSummary("the writer to report recovery") { it.writerError.isEmpty() && it.queueSize == 0 }
        require(recovered.enabled) { "Writer did not stay enabled: $recovered" }
        require(recovered.writerBusyRetries >= 2) { "Retry count was lost: $recovered" }
        require(recovered.droppedEvents == 0L) { "Events were dropped: $recovered" }
        require("write lock" !in recovered.message) { "Summary still reports a wait: $recovered" }
        require(recovered.launchEvents >= 1L + launchIds.size) { "Summary does not count the held launches: $recovered" }

        waitFor("analysis of the held compile event") { unresolvedRows(database, compileId) > 0 }
        val plan = DriverManager.getConnection("jdbc:sqlite:$database").use { conn ->
            conn.prepareStatement("EXPLAIN QUERY PLAN DELETE FROM unresolved_uses WHERE snippet_id = ?").use { ps ->
                ps.setString(1, compileId)
                ps.executeQuery().use { rs -> buildList { while (rs.next()) add(rs.getString("detail")) } }
            }
        }
        require(plan.any { "USING INDEX idx_unresolved_uses_snippet" in it }) {
            "Per-snippet unresolved_uses delete does not use its index: $plan"
        }

        println(
            "CodeUseTelemetryBusyRecoverySmokeTest ok (lock held ${heldForMs} ms, " +
                "${recovered.writerBusyRetries} busy retries, $heldEvents held events committed)"
        )
    }

    private fun waitForSummary(
        what: String,
        timeoutMs: Long = 10_000,
        predicate: (CodeUseSummary) -> Boolean
    ): CodeUseSummary {
        val deadline = System.currentTimeMillis() + timeoutMs
        var latest = CodeUseTelemetryService.summary()
        while (!predicate(latest)) {
            require(System.currentTimeMillis() < deadline) { "Timed out waiting for $what: $latest" }
            Thread.sleep(100)
            latest = CodeUseTelemetryService.summary()
        }
        return latest
    }

    private fun waitFor(what: String, timeoutMs: Long = 10_000, condition: () -> Boolean) {
        val deadline = System.currentTimeMillis() + timeoutMs
        while (!condition()) {
            require(System.currentTimeMillis() < deadline) { "Timed out waiting for $what" }
            Thread.sleep(100)
        }
    }

    private fun launchRows(database: String, snippetIds: List<String>): Int =
        snippetIds.sumOf { rowCount(database, "launch_events", it) }

    private fun unresolvedRows(database: String, snippetId: String): Int =
        rowCount(database, "unresolved_uses", snippetId)

    private fun rowCount(database: String, table: String, snippetId: String): Int =
        DriverManager.getConnection("jdbc:sqlite:$database").use { conn ->
            conn.prepareStatement("SELECT COUNT(*) FROM $table WHERE snippet_id = ?").use { ps ->
                ps.setString(1, snippetId)
                ps.executeQuery().use { rs -> if (rs.next()) rs.getInt(1) else 0 }
            }
        }
}