From c262e58a96d22020cc8994eff1f7aa2fd89b7f2d Mon Sep 17 00:00:00 2001
From: austinried <4966622+austinried@users.noreply.github.com>
Date: Thu, 8 Oct 2026 20:17:09 +0000
Subject: [PATCH] logging: fix SQL timing and upsert-conflict false alarms

Room's statement cache resets a statement when returning it to the cache, so starting the timer at reset counted idle time in the cache and reported normal queries as tens of seconds. Start timing on the first step instead, and finish on the completing step. Also downgrade Room @Upsert uniqueness-conflict errors (its insert-then-catch-then-update control flow) from ERROR to DEBUG, and log successful HTTP requests at VERBOSE so debug logs aren't flooded by cover-art requests.
---
 .../kotlin/com/subtracks/data/db/DbLogging.kt | 19 ++++++-------
 app/src/main/kotlin/com/subtracks/log/Log.kt  | 27 +++++++++++++++++--
 .../com/subtracks/data/db/DbLoggingTest.kt    | 19 +++++++++++++
 .../com/subtracks/log/LogFileStoreTest.kt     |  8 ++++++
 4 files changed, 62 insertions(+), 11 deletions(-)

diff --git a/app/src/main/kotlin/com/subtracks/data/db/DbLogging.kt b/app/src/main/kotlin/com/subtracks/data/db/DbLogging.kt
index 558be462..93babc79 100644
--- a/app/src/main/kotlin/com/subtracks/data/db/DbLogging.kt
+++ b/app/src/main/kotlin/com/subtracks/data/db/DbLogging.kt
@@ -47,14 +47,13 @@ private class LoggingStatement(
     private val sql: String,
     private val onExecution: (SqlExecution) -> Unit,
 ) : SQLiteStatement by delegate {
-    private var startNanos = System.nanoTime()
+    private var startNanos = 0L
     private var rows = 0L
     private var failure: Throwable? = null
-    private var started = false
-    private var reported = false
+    private var active = false
 
     override fun step(): Boolean {
-        started = true
+        begin()
         val result =
             try {
                 delegate.step()
@@ -71,7 +70,6 @@ private class LoggingStatement(
     override fun reset() {
         report()
         delegate.reset()
-        begin()
     }
 
     override fun close() {
@@ -80,17 +78,20 @@ private class LoggingStatement(
     }
 
     private fun report() {
-        if (!started || reported) return
-        reported = true
+        if (!active) return
+        active = false
         onExecution(SqlExecution(sql, System.nanoTime() - startNanos, rows, failure))
     }
 
+    // Started on the first step, not on reset: Room's statement cache resets a statement when it is
+    // returned to the cache (BasePreparedStatementCache.CachedStatement.close), so timing from reset
+    // would count however long the statement idled there before its next use.
     private fun begin() {
+        if (active) return
         startNanos = System.nanoTime()
         rows = 0
         failure = null
-        started = false
-        reported = false
+        active = true
     }
 }
 
diff --git a/app/src/main/kotlin/com/subtracks/log/Log.kt b/app/src/main/kotlin/com/subtracks/log/Log.kt
index a63ab126..bf9204c6 100644
--- a/app/src/main/kotlin/com/subtracks/log/Log.kt
+++ b/app/src/main/kotlin/com/subtracks/log/Log.kt
@@ -34,6 +34,11 @@ object Log {
         i("app", "started ${BuildConfig.VERSION_NAME} (${BuildConfig.VERSION_CODE}) on Android ${Build.VERSION.SDK_INT} ${Build.MODEL}")
     }
 
+    fun v(
+        tag: String,
+        message: String,
+    ) = log(LogLevel.VERBOSE, tag, message, null)
+
     fun d(
         tag: String,
         message: String,
@@ -83,7 +88,7 @@ object Log {
     fun interceptor(): Interceptor =
         Interceptor { chain ->
             val request = chain.request()
-            d("http", "${request.method} ${request.url}")
+            v("http", "${request.method} ${request.url}")
             try {
                 val response = chain.proceed(request)
                 if (response.code >= 400) {
@@ -99,7 +104,11 @@ object Log {
     fun sql(execution: SqlExecution) {
         val failure = execution.error
         if (failure != null) {
-            e("sql", "failed: ${shortSql(execution.sql)}", failure)
+            if (isUpsertConflict(failure)) {
+                d("sql", "upsert fallback conflict: ${shortSql(execution.sql)}")
+            } else {
+                e("sql", "failed: ${shortSql(execution.sql)}", failure)
+            }
             return
         }
         if (!isSlowQuery(execution, SLOW_QUERY_MS)) return
@@ -166,3 +175,17 @@ internal fun isSlowQuery(
     execution: SqlExecution,
     thresholdMs: Double,
 ): Boolean = execution.error == null && execution.durationMillis >= thresholdMs && isDataStatement(execution.sql)
+
+// Room's EntityUpsertAdapter implements @Upsert as an INSERT and, on a uniqueness conflict, catches
+// the error and runs an UPDATE instead (EntityUpsertAdapter.checkUniquenessException). That failure
+// is expected control flow, not an error worth alarming about.
+private const val CONSTRAINT_UNIQUE_MESSAGE = "unique constraint failed"
+private const val SQLITE_CONSTRAINT_PRIMARYKEY = "1555"
+private const val SQLITE_CONSTRAINT_UNIQUE = "2067"
+
+internal fun isUpsertConflict(error: Throwable): Boolean {
+    val message = error.message?.lowercase() ?: return false
+    return message.contains(CONSTRAINT_UNIQUE_MESSAGE) ||
+        message.contains(SQLITE_CONSTRAINT_PRIMARYKEY) ||
+        message.contains(SQLITE_CONSTRAINT_UNIQUE)
+}
diff --git a/app/src/test/kotlin/com/subtracks/data/db/DbLoggingTest.kt b/app/src/test/kotlin/com/subtracks/data/db/DbLoggingTest.kt
index c6ea39f3..1da27991 100644
--- a/app/src/test/kotlin/com/subtracks/data/db/DbLoggingTest.kt
+++ b/app/src/test/kotlin/com/subtracks/data/db/DbLoggingTest.kt
@@ -62,6 +62,25 @@ class DbLoggingTest {
         assertTrue(select.durationNanos > 0)
     }
 
+    @Test
+    fun doesNotCountIdleTimeBetweenReuses() {
+        driver().open(":memory:").use { connection ->
+            connection.prepare("CREATE TABLE t (id INTEGER PRIMARY KEY, name TEXT)").use { it.step() }
+            connection.prepare("INSERT INTO t (name) VALUES (?)").use { statement ->
+                statement.bindText(1, "a")
+                statement.step()
+                statement.reset()
+                Thread.sleep(250)
+                statement.bindText(1, "b")
+                statement.step()
+                statement.reset()
+            }
+        }
+        val inserts = executions.filter { it.sql.startsWith("INSERT") }
+        assertEquals(2, inserts.size)
+        inserts.forEach { assertTrue("${it.durationMillis}ms", it.durationNanos < 100_000_000) }
+    }
+
     @Test
     fun recordsPrepareError() {
         driver().open(":memory:").use { connection ->
diff --git a/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt b/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt
index 238466f8..a07722b1 100644
--- a/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt
+++ b/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt
@@ -150,6 +150,14 @@ class LogFileStoreTest {
         assertFalse(isReadStatement("INSERT INTO t VALUES (1)"))
     }
 
+    @Test
+    fun detectsUpsertConflictErrors() {
+        assertTrue(isUpsertConflict(IllegalStateException("UNIQUE constraint failed: playback_cursor.id")))
+        assertTrue(isUpsertConflict(IllegalStateException("Error code: 1555, message: UNIQUE constraint failed")))
+        assertTrue(isUpsertConflict(IllegalStateException("SQLITE_CONSTRAINT_UNIQUE 2067")))
+        assertFalse(isUpsertConflict(IllegalStateException("no such table: songs")))
+    }
+
     private fun execution(
         milliseconds: Double,
         sql: String,