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.

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 active = false
-    private var reported = 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
+        if (!active) return
-        reported = true
+        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
+        active = true
-        reported = false
     }
 }
 

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)
+}

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 ->

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,