From 0afe8074f0885d8315bceaa54c5595c76c45ad67 Mon Sep 17 00:00:00 2001 From: David Schachter Date: Mon, 17 Aug 2026 21:56:45 -0700 Subject: [PATCH 1/6] ADFA-5172: Instrument the accept loop to locate the periodic 1 s stall The local WebServer stalls ~1.02 s about every 2 s under sustained load, and a client-side measurement cannot say whether the loop was waiting in accept() or busy elsewhere -- the ticket's first diagnostic. Time each accept-loop iteration in two parts, parked in accept() versus busy outside it, and time the per-request stat of the sdcard debug database, which is FUSE-backed emulated storage and is the leading suspect for a slow iteration delaying the next accept. One warn line is logged per iteration that crosses ServerConfig.stallThresholdMs (200 ms by default), carrying the previous iteration's split so a stall can be attributed to the loop or exonerated. Kept independent of the webserver.debug sentinel on purpose: its ~10 log lines per request perturb the timing being measured, and the ticket's next step is to re-run with the sentinel removed. A long park in accept() is normal on an idle server, so it is reported only when the previous park was short -- i.e. during the sustained load where the stall lives, not when a user simply stopped browsing. --- .../androidide/localWebServer/WebServer.kt | 65 +++++++++++++++++++ 1 file changed, 65 insertions(+) diff --git a/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt b/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt index 0b76b64d2d..503d632898 100644 --- a/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt +++ b/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt @@ -52,6 +52,8 @@ data class ServerConfig( "/Download/CodeOnTheGo.webserver.cs0", // Yes, this is hack code. val projectDatabasePath: String = "/data/data/com.itsaky.androidide/databases/RecentProject_database", + // ADFA-5172: accept-loop iterations slower than this get one diagnostic log line. + val stallThresholdMs: Long = 200, ) data class JavaExecutionResult( @@ -100,6 +102,12 @@ class WebServer( private val contentChunkSize = 1024 * 1024 + private val stallThresholdNanos = TimeUnit.MILLISECONDS.toNanos(config.stallThresholdMs) + + // How long handleClient()'s last stat of config.debugDatabasePath took. A plain var is safe: + // the accept loop is serial and single-threaded, and it is the only reader. + private var debugDbStatNanos = 0L + // function to obtain the last modified date of a documentation.db database // this is used to see if there is a newer version of the database on the sdcard fun getDatabaseTimestamp( @@ -187,12 +195,23 @@ class WebServer( } log.info("WebServer started successfully on '{}', port {}.", config.bindName, config.port) + // ADFA-5172: carried across iterations so a stall report can say whether the loop was + // even in accept() when the connection arrived. + var previousAcceptWaitNanos = 0L + var previousBusyNanos = 0L + while (true) { var clientSocket: Socket? = null + var acceptWaitNanos = 0L + var busyStartNanos = 0L + debugDbStatNanos = 0L try { try { if (debugEnabled) log.debug("About to call accept() on the server socket, {}.", serverSocket) + val acceptStartNanos = System.nanoTime() clientSocket = serverSocket.accept() + busyStartNanos = System.nanoTime() + acceptWaitNanos = busyStartNanos - acceptStartNanos if (debugEnabled) log.debug("Returned from socket accept(), clientSocket is {}.", clientSocket) } catch (e: java.net.SocketException) { @@ -232,6 +251,14 @@ class WebServer( // CodeRabbit objects to the following line because clientSocket may print out as "null." This is intentional. --DS if (debugEnabled) log.debug("clientSocket was {}.", clientSocket) + + // Zero when accept() threw, which leaves nothing to time. + if (busyStartNanos != 0L) { + val busyNanos = System.nanoTime() - busyStartNanos + reportStall(acceptWaitNanos, busyNanos, previousAcceptWaitNanos, previousBusyNanos) + previousAcceptWaitNanos = acceptWaitNanos + previousBusyNanos = busyNanos + } } } } catch (e: Exception) { @@ -255,6 +282,41 @@ class WebServer( } } + /** + * Logs one line per accept-loop iteration that crosses [ServerConfig.stallThresholdMs], for + * ADFA-5172's periodic ~1 s stall. Splits "parked in accept()" from "busy outside it" because + * that is what separates a stall the loop caused -- a slow iteration delays the next accept, + * so an arriving SYN can be dropped and retried ~1 s later -- from one it merely suffered. + * Deliberately independent of [debugEnabled], whose ~10 log lines per request perturb the + * timing being measured. + */ + private fun reportStall( + acceptWaitNanos: Long, + busyNanos: Long, + previousAcceptWaitNanos: Long, + previousBusyNanos: Long, + ) { + // A long wait in accept() is just an idle server, so report only the first one after a busy + // stretch: that is the periodic stall, not a user who stopped browsing the documentation. + val stalledBeforeAccept = + acceptWaitNanos >= stallThresholdNanos && previousAcceptWaitNanos < stallThresholdNanos + val stalledWhileBusy = busyNanos >= stallThresholdNanos || debugDbStatNanos >= stallThresholdNanos + if (!stalledBeforeAccept && !stalledWhileBusy) return + + log.warn( + "Accept-loop stall: {} ms parked in accept(), then {} ms busy outside it, of which {} ms " + + "stat'ing '{}'. Previous iteration: {} ms parked, {} ms busy.", + millis(acceptWaitNanos), + millis(busyNanos), + millis(debugDbStatNanos), + config.debugDatabasePath, + millis(previousAcceptWaitNanos), + millis(previousBusyNanos), + ) + } + + private fun millis(nanos: Long): Long = TimeUnit.NANOSECONDS.toMillis(nanos) + /** * Reads a single line from the stream (bytes until newline). Same stream is used for headers * and body so POST body bytes are not lost to a separate buffered reader. HTTP header lines are ASCII. @@ -331,7 +393,10 @@ class WebServer( // check to see if there is a newer version of the documentation.db database on the sdcard // if there is use that for our responses + // Timed for ADFA-5172: this stats FUSE-backed emulated storage on every request. + val statStartNanos = System.nanoTime() val debugDatabaseTimestamp = getDatabaseTimestamp(config.debugDatabasePath, true) + debugDbStatNanos = System.nanoTime() - statStartNanos if (debugDatabaseTimestamp > databaseTimestamp) { bookshelfTemplateId = -1 database.close() From 3968a4ba0dd074068090658b7194121c654caa8d Mon Sep 17 00:00:00 2001 From: David Schachter Date: Tue, 18 Aug 2026 05:11:17 -0700 Subject: [PATCH 2/6] ADFA-5172: Stop reporting an idle wait in accept() as a stall Review found two false positives in the accept-wait half of the report, and both were real: the carried previous-wait started at zero, which reads as an iteration that was served instantly, so the first request after startup was always reported -- on the device it logged "74552 ms parked in accept()" for exactly that reason -- and a long wait after any genuine pause looked the same. The wait now has to look like what ADFA-5172 is about: at least the threshold, no more than 10 s (Linux retransmits a SYN at 1 s, 3 s and 7 s, so past that it is nobody browsing), and preceded by an iteration that was served promptly. A sentinel distinguishes "no iteration has finished yet" from one that waited 0 ms. The decision moved into shouldReportAcceptWait() so it is testable, and it now has tests: the stall itself, each false positive that prompted this, the retransmission ladder, an ordinary wait, and the degenerate threshold. A negative stallThresholdMs is clamped to zero rather than reported as an error -- it is a diagnostic knob, and a nonsense value should not throw. Zero has a quirk worth knowing, so it is documented and tested rather than engineered around: it reports every iteration's serving time, but silences the accept-wait half, whose "the last iteration was served promptly" test cannot hold when the threshold is zero. --- .../androidide/localWebServer/WebServer.kt | 37 +++++++-- .../localWebServer/AcceptWaitReportingTest.kt | 78 +++++++++++++++++++ 2 files changed, 108 insertions(+), 7 deletions(-) create mode 100644 app/src/test/java/com/itsaky/androidide/localWebServer/AcceptWaitReportingTest.kt diff --git a/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt b/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt index 503d632898..2a3d3325f5 100644 --- a/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt +++ b/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt @@ -52,7 +52,9 @@ data class ServerConfig( "/Download/CodeOnTheGo.webserver.cs0", // Yes, this is hack code. val projectDatabasePath: String = "/data/data/com.itsaky.androidide/databases/RecentProject_database", - // ADFA-5172: accept-loop iterations slower than this get one diagnostic log line. + // ADFA-5172: accept-loop iterations slower than this get one diagnostic log line. Zero reports + // every iteration's serving time (and silences the accept-wait half, whose "the last iteration + // was served promptly" test cannot hold at zero); a negative value is clamped to zero. val stallThresholdMs: Long = 200, ) @@ -102,7 +104,14 @@ class WebServer( private val contentChunkSize = 1024 * 1024 - private val stallThresholdNanos = TimeUnit.MILLISECONDS.toNanos(config.stallThresholdMs) + // Sentinel for "no iteration has finished yet", distinct from an iteration that waited 0 ms. + private val noPreviousIteration = -1L + + private val stallThresholdNanos = TimeUnit.MILLISECONDS.toNanos(config.stallThresholdMs.coerceAtLeast(0)) + + // A park longer than this is an idle server, not a lost handshake: Linux's SYN retransmission + // ladder is 1 s, 3 s, 7 s, so anything past it is nobody browsing rather than ADFA-5172. + private val maxReportedAcceptWaitNanos = TimeUnit.SECONDS.toNanos(10) // How long handleClient()'s last stat of config.debugDatabasePath took. A plain var is safe: // the accept loop is serial and single-threaded, and it is the only reader. @@ -197,7 +206,7 @@ class WebServer( // ADFA-5172: carried across iterations so a stall report can say whether the loop was // even in accept() when the connection arrived. - var previousAcceptWaitNanos = 0L + var previousAcceptWaitNanos = noPreviousIteration var previousBusyNanos = 0L while (true) { @@ -296,10 +305,7 @@ class WebServer( previousAcceptWaitNanos: Long, previousBusyNanos: Long, ) { - // A long wait in accept() is just an idle server, so report only the first one after a busy - // stretch: that is the periodic stall, not a user who stopped browsing the documentation. - val stalledBeforeAccept = - acceptWaitNanos >= stallThresholdNanos && previousAcceptWaitNanos < stallThresholdNanos + val stalledBeforeAccept = shouldReportAcceptWait(acceptWaitNanos, previousAcceptWaitNanos) val stalledWhileBusy = busyNanos >= stallThresholdNanos || debugDbStatNanos >= stallThresholdNanos if (!stalledBeforeAccept && !stalledWhileBusy) return @@ -315,6 +321,23 @@ class WebServer( ) } + /** + * Whether a wait in accept() is worth a line. Waiting is normal, so this reports only a wait + * that looks like ADFA-5172's stall: long enough to be a retransmitted handshake, short enough + * not to be an idle server, and preceded by an iteration that was served promptly -- meaning + * requests were arriving steadily right up to the stall. + * + * [previousAcceptWaitNanos] is [noPreviousIteration] until one iteration has completed, so the + * very first request after startup is never reported. + */ + internal fun shouldReportAcceptWait( + acceptWaitNanos: Long, + previousAcceptWaitNanos: Long, + ): Boolean { + val loadWasSteady = previousAcceptWaitNanos in 0 until stallThresholdNanos + return loadWasSteady && acceptWaitNanos >= stallThresholdNanos && acceptWaitNanos <= maxReportedAcceptWaitNanos + } + private fun millis(nanos: Long): Long = TimeUnit.NANOSECONDS.toMillis(nanos) /** diff --git a/app/src/test/java/com/itsaky/androidide/localWebServer/AcceptWaitReportingTest.kt b/app/src/test/java/com/itsaky/androidide/localWebServer/AcceptWaitReportingTest.kt new file mode 100644 index 0000000000..13cadd0582 --- /dev/null +++ b/app/src/test/java/com/itsaky/androidide/localWebServer/AcceptWaitReportingTest.kt @@ -0,0 +1,78 @@ +package com.itsaky.androidide.localWebServer + +import com.google.common.truth.Truth.assertThat +import org.junit.Test +import java.util.concurrent.TimeUnit + +/** + * Covers when a wait in accept() is worth a log line (ADFA-5172). Waiting is the normal state of a + * server with nothing to do, so the interesting case is narrow: long enough to be a retransmitted + * handshake, short enough not to be an idle server, and arriving in the middle of steady traffic. + */ +class AcceptWaitReportingTest { + private val thresholdMs = 200L + + // Every path is given explicitly: ServerConfig's defaults reach for external storage, which a + // JVM test has no stub for. + private fun server(stallThresholdMs: Long = thresholdMs) = + WebServer( + ServerConfig( + port = 0, + databasePath = "/nonexistent/test.db", + fileDirPath = "/tmp", + debugDatabasePath = "/nonexistent/debug.db", + debugEnablePath = "/nonexistent/debug-flag", + experimentsEnablePath = "/nonexistent/exp-flag", + clearCacheEnablePath = "/nonexistent/cs0-flag", + projectDatabasePath = "/nonexistent/recent-projects.db", + stallThresholdMs = stallThresholdMs, + ), + ) + + private fun millis(value: Long) = TimeUnit.MILLISECONDS.toNanos(value) + + private val noPreviousIteration = -1L + + @Test + fun `a one second wait between promptly served requests is the stall being hunted`() { + assertThat(server().shouldReportAcceptWait(millis(1_020), previousAcceptWaitNanos = millis(0))).isTrue() + } + + @Test + fun `the first request after startup is never reported, however long the wait`() { + assertThat(server().shouldReportAcceptWait(millis(74_000), noPreviousIteration)).isFalse() + assertThat(server().shouldReportAcceptWait(millis(1_020), noPreviousIteration)).isFalse() + } + + @Test + fun `a wait after an already long wait is an idle server, not a stall`() { + assertThat(server().shouldReportAcceptWait(millis(1_020), previousAcceptWaitNanos = millis(30_000))).isFalse() + } + + @Test + fun `a wait far past the retransmission ladder is nobody browsing`() { + assertThat(server().shouldReportAcceptWait(millis(60_000), previousAcceptWaitNanos = millis(5))).isFalse() + } + + @Test + fun `a wait within the retransmission ladder is still reported`() { + // 1 s, 3 s and 7 s are Linux's first three SYN retransmissions. + assertThat(server().shouldReportAcceptWait(millis(3_100), previousAcceptWaitNanos = millis(5))).isTrue() + assertThat(server().shouldReportAcceptWait(millis(7_200), previousAcceptWaitNanos = millis(5))).isTrue() + } + + @Test + fun `an ordinary wait below the threshold is not reported`() { + assertThat(server().shouldReportAcceptWait(millis(30), previousAcceptWaitNanos = millis(5))).isFalse() + } + + @Test + fun `a zero or negative threshold silences the accept-wait report instead of flooding it`() { + // "The previous iteration waited less than the threshold" cannot hold when the threshold is + // zero, so this branch goes quiet rather than reporting every wait. A negative threshold is + // clamped to zero and behaves the same. The busy-phase report, which has no such + // precondition, does fire for every iteration at these settings. + assertThat(server(stallThresholdMs = 0).shouldReportAcceptWait(millis(1_020), previousAcceptWaitNanos = 0)).isFalse() + assertThat(server(stallThresholdMs = -5).shouldReportAcceptWait(millis(1_020), previousAcceptWaitNanos = 0)).isFalse() + } +} From df93f25adafe7fc105d72383b583632f02785819 Mon Sep 17 00:00:00 2001 From: David Schachter Date: Tue, 18 Aug 2026 08:35:15 -0700 Subject: [PATCH 3/6] ADFA-5172: Flatten the accept loop, and pin the report's boundaries Review asked for both. The loop was a try inside a try inside a while, with two catch blocks each nesting conditionals two deep, and a finally doing three unrelated jobs. It is now eight lines: accept, serve, close. The pieces became functions that each do one thing -- acceptNextClient() returns null only when the listening socket closed and retries any other accept failure, serveClient() serves one connection and answers a 500 if handling fails partway, sendInternalServerError(), closeQuietly(), and isSocketClosed() for the string test that a closed socket forces on us. Two side effects worth noting. The socket can no longer be null inside the loop, so the old comment defending a log line that could print "null" is gone with the line it defended; the replacement logs the socket it actually served. And the timings the loop carried in locals are now fields, which is honest about what they always were: state belonging to the single accept thread, not to one iteration. The report's filtering contract now has boundary tests, both ends inclusive: one millisecond under the threshold, exactly on it, one over; 9,999 / 10,000 / 10,001 ms against the ceiling; and the previous wait counting as steady load right up to the threshold. Round values well inside each range said nothing about whether the comparisons were inclusive, which is exactly what a later edit flips silently. --- .../androidide/localWebServer/WebServer.kt | 149 ++++++++++-------- .../localWebServer/AcceptWaitReportingTest.kt | 26 +++ 2 files changed, 112 insertions(+), 63 deletions(-) diff --git a/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt b/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt index 2a3d3325f5..7dfa15d4d5 100644 --- a/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt +++ b/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt @@ -113,9 +113,13 @@ class WebServer( // ladder is 1 s, 3 s, 7 s, so anything past it is nobody browsing rather than ADFA-5172. private val maxReportedAcceptWaitNanos = TimeUnit.SECONDS.toNanos(10) - // How long handleClient()'s last stat of config.debugDatabasePath took. A plain var is safe: - // the accept loop is serial and single-threaded, and it is the only reader. + // How long handleClient()'s last stat of config.debugDatabasePath took, and how long the last + // accept() waited. Plain vars are safe: the accept loop is serial and single-threaded, and it is + // the only reader and writer. private var debugDbStatNanos = 0L + private var acceptWaitNanos = 0L + private var previousAcceptWaitNanos = noPreviousIteration + private var previousBusyNanos = 0L // function to obtain the last modified date of a documentation.db database // this is used to see if there is a newer version of the database on the sdcard @@ -204,70 +208,14 @@ class WebServer( } log.info("WebServer started successfully on '{}', port {}.", config.bindName, config.port) - // ADFA-5172: carried across iterations so a stall report can say whether the loop was - // even in accept() when the connection arrived. - var previousAcceptWaitNanos = noPreviousIteration - var previousBusyNanos = 0L - while (true) { - var clientSocket: Socket? = null - var acceptWaitNanos = 0L - var busyStartNanos = 0L - debugDbStatNanos = 0L - try { - try { - if (debugEnabled) log.debug("About to call accept() on the server socket, {}.", serverSocket) - val acceptStartNanos = System.nanoTime() - clientSocket = serverSocket.accept() - busyStartNanos = System.nanoTime() - acceptWaitNanos = busyStartNanos - acceptStartNanos - - if (debugEnabled) log.debug("Returned from socket accept(), clientSocket is {}.", clientSocket) - } catch (e: java.net.SocketException) { - // SLF4J placeholders produce wrong formatting here. --DS, 23-Feb-2026 - if (debugEnabled) log.debug("Caught java.net.SocketException '$e'.") - - if (e.message?.contains("Closed", ignoreCase = true) == true) { - if (debugEnabled) log.debug("WebServer socket closed, shutting down.") - break - } - log.error("Accept() failed: {}", e.message) - continue - } - try { - clientSocket?.let { handleClient(it) } - } catch (e: Exception) { - // SLF4J placeholders produce wrong formatting here. --DS, 23-Feb-2026 - if (debugEnabled) log.debug("Caught exception '$e'.") + val clientSocket = acceptNextClient() ?: break - if (e is java.net.SocketException && e.message?.contains("Closed", ignoreCase = true) == true) { - if (debugEnabled) log.debug("Client disconnected: {}", e.message) - } else { - log.error("Error handling client: {}", e.message) - clientSocket?.let { socket -> - try { - val output = socket.outputStream - - sendError(PrintWriter(output, true), output, httpInternalServerError, "Internal Server Error 1") - } catch (e2: Exception) { - log.error("Error sending error response: {}", e2.message) - } - } - } - } + try { + serveClient(clientSocket) } finally { - clientSocket?.close() - - // CodeRabbit objects to the following line because clientSocket may print out as "null." This is intentional. --DS - if (debugEnabled) log.debug("clientSocket was {}.", clientSocket) - - // Zero when accept() threw, which leaves nothing to time. - if (busyStartNanos != 0L) { - val busyNanos = System.nanoTime() - busyStartNanos - reportStall(acceptWaitNanos, busyNanos, previousAcceptWaitNanos, previousBusyNanos) - previousAcceptWaitNanos = acceptWaitNanos - previousBusyNanos = busyNanos - } + closeQuietly(clientSocket) + if (debugEnabled) log.debug("Served and closed clientSocket {}.", clientSocket) } } } catch (e: Exception) { @@ -291,6 +239,81 @@ class WebServer( } } + /** + * Waits for the next connection. Null means the listening socket closed and the loop is done; + * an accept that failed for any other reason is logged and retried, since one bad accept is not + * a reason to stop serving. + */ + private fun acceptNextClient(): Socket? { + while (true) { + try { + if (debugEnabled) log.debug("About to call accept() on the server socket, {}.", serverSocket) + + val acceptStartNanos = System.nanoTime() + val clientSocket = serverSocket.accept() + acceptWaitNanos = System.nanoTime() - acceptStartNanos + + if (debugEnabled) log.debug("Returned from socket accept(), clientSocket is {}.", clientSocket) + return clientSocket + } catch (e: java.net.SocketException) { + // SLF4J placeholders produce wrong formatting here. --DS, 23-Feb-2026 + if (debugEnabled) log.debug("Caught java.net.SocketException '$e'.") + + if (isSocketClosed(e)) { + if (debugEnabled) log.debug("WebServer socket closed, shutting down.") + return null + } + log.error("Accept() failed: {}", e.message) + } + } + } + + /** Serves one connection, answering with a 500 if handling it fails partway. */ + private fun serveClient(clientSocket: Socket) { + val busyStartNanos = System.nanoTime() + debugDbStatNanos = 0L + + try { + handleClient(clientSocket) + } catch (e: Exception) { + // SLF4J placeholders produce wrong formatting here. --DS, 23-Feb-2026 + if (debugEnabled) log.debug("Caught exception '$e'.") + + if (e is java.net.SocketException && isSocketClosed(e)) { + if (debugEnabled) log.debug("Client disconnected: {}", e.message) + } else { + log.error("Error handling client: {}", e.message) + sendInternalServerError(clientSocket) + } + } finally { + val busyNanos = System.nanoTime() - busyStartNanos + reportStall(acceptWaitNanos, busyNanos, previousAcceptWaitNanos, previousBusyNanos) + previousAcceptWaitNanos = acceptWaitNanos + previousBusyNanos = busyNanos + } + } + + private fun sendInternalServerError(clientSocket: Socket) { + try { + val output = clientSocket.outputStream + + sendError(PrintWriter(output, true), output, httpInternalServerError, "Internal Server Error 1") + } catch (e: Exception) { + log.error("Error sending error response: {}", e.message) + } + } + + private fun closeQuietly(clientSocket: Socket) { + try { + clientSocket.close() + } catch (e: Exception) { + log.error("Cannot close client socket: {}", e.message) + } + } + + /** A closed socket reports itself only in the exception's message, hence the string test. */ + private fun isSocketClosed(e: java.net.SocketException): Boolean = e.message?.contains("Closed", ignoreCase = true) == true + /** * Logs one line per accept-loop iteration that crosses [ServerConfig.stallThresholdMs], for * ADFA-5172's periodic ~1 s stall. Splits "parked in accept()" from "busy outside it" because diff --git a/app/src/test/java/com/itsaky/androidide/localWebServer/AcceptWaitReportingTest.kt b/app/src/test/java/com/itsaky/androidide/localWebServer/AcceptWaitReportingTest.kt index 13cadd0582..ab2cfadc72 100644 --- a/app/src/test/java/com/itsaky/androidide/localWebServer/AcceptWaitReportingTest.kt +++ b/app/src/test/java/com/itsaky/androidide/localWebServer/AcceptWaitReportingTest.kt @@ -66,6 +66,32 @@ class AcceptWaitReportingTest { assertThat(server().shouldReportAcceptWait(millis(30), previousAcceptWaitNanos = millis(5))).isFalse() } + @Test + fun `the threshold itself is inclusive, and one millisecond under it is not reported`() { + val server = server() + + assertThat(server.shouldReportAcceptWait(millis(thresholdMs - 1), previousAcceptWaitNanos = millis(5))).isFalse() + assertThat(server.shouldReportAcceptWait(millis(thresholdMs), previousAcceptWaitNanos = millis(5))).isTrue() + assertThat(server.shouldReportAcceptWait(millis(thresholdMs + 1), previousAcceptWaitNanos = millis(5))).isTrue() + } + + @Test + fun `the ten second ceiling is inclusive, and one millisecond over it is an idle server`() { + val server = server() + + assertThat(server.shouldReportAcceptWait(millis(9_999), previousAcceptWaitNanos = millis(5))).isTrue() + assertThat(server.shouldReportAcceptWait(millis(10_000), previousAcceptWaitNanos = millis(5))).isTrue() + assertThat(server.shouldReportAcceptWait(millis(10_001), previousAcceptWaitNanos = millis(5))).isFalse() + } + + @Test + fun `the previous wait counts as steady load right up to the threshold`() { + val server = server() + + assertThat(server.shouldReportAcceptWait(millis(1_020), previousAcceptWaitNanos = millis(thresholdMs - 1))).isTrue() + assertThat(server.shouldReportAcceptWait(millis(1_020), previousAcceptWaitNanos = millis(thresholdMs))).isFalse() + } + @Test fun `a zero or negative threshold silences the accept-wait report instead of flooding it`() { // "The previous iteration waited less than the threshold" cannot hold when the threshold is From d3299e6dbafff2733bff7241cf78e8fecccfe1b2 Mon Sep 17 00:00:00 2001 From: David Schachter Date: Mon, 17 Aug 2026 22:45:19 -0700 Subject: [PATCH 4/6] ADFA-5175: Serve requests on a worker pool, not the accept loop Prerequisite for keep-alive: a connection that stays open must not stop the server from accepting the next one. The accept loop now hands each socket to a small on-demand pool (at most ServerConfig.maxWorkerThreads, SynchronousQueue so a burst grows the pool rather than queueing behind a busy worker) and goes straight back to accept(). That makes the shared database handle reachable from several threads at once, so swapping it -- which closes the old handle -- is now serialized against readers with a ReentrantReadWriteLock: requests hold the read lock across the query and the blob reads, the swap takes the write lock. The swap also opens the replacement before closing the old handle, so a failed open leaves the server serving the database it already had instead of a closed one. Shutdown drains the pool before closing the database, and closes live client sockets to do it: a worker parked in a socket read ignores shutdownNow()'s interrupt, and closing the database under it would crash the process. The per-request stat of the sdcard debug database is now rate-limited to once a second. It sits on FUSE-backed emulated storage and it is a developer-only override, so a stat per request bought nothing. ADFA-5172's instrumentation is retargeted to match: the accept thread still reports a long park in accept(), while time spent serving moves to the worker, where it now belongs. --- .../androidide/localWebServer/WebServer.kt | 274 +++++++++++++----- 1 file changed, 209 insertions(+), 65 deletions(-) diff --git a/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt b/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt index 7dfa15d4d5..e12de7e186 100644 --- a/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt +++ b/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt @@ -29,8 +29,15 @@ import java.sql.Date import java.text.SimpleDateFormat import java.util.Locale import java.util.concurrent.ConcurrentHashMap +import java.util.concurrent.RejectedExecutionException +import java.util.concurrent.SynchronousQueue +import java.util.concurrent.ThreadPoolExecutor import java.util.concurrent.TimeUnit +import java.util.concurrent.atomic.AtomicLong import java.util.concurrent.atomic.AtomicReference +import java.util.concurrent.locks.ReentrantReadWriteLock +import kotlin.concurrent.read +import kotlin.concurrent.write data class ServerConfig( val port: Int = 6174, @@ -56,6 +63,12 @@ data class ServerConfig( // every iteration's serving time (and silences the accept-wait half, whose "the last iteration // was served promptly" test cannot hold at zero); a negative value is clamped to zero. val stallThresholdMs: Long = 200, + // ADFA-5175: requests are served on a pool of at most this many threads. WebView opens up + // to 6 connections per host, so 16 leaves headroom for a second client. + val maxWorkerThreads: Int = 16, + // ADFA-5175: how often the sdcard debug database may be stat'ed. It lives on FUSE-backed + // emulated storage, and it is a developer-only override, so once a second is plenty. + val debugDatabaseCheckIntervalMs: Long = 1000, ) data class JavaExecutionResult( @@ -79,6 +92,9 @@ class WebServer( private var stopRequested = false private lateinit var serverSocket: ServerSocket private lateinit var database: SQLiteDatabase + + // Written under databaseLock's write lock, read without it in the fast path, hence volatile. + @Volatile private var databaseTimestamp: Long = -1 private val log = LoggerFactory.getLogger(WebServer::class.java) private val debugEnabled: Boolean = File(config.debugEnablePath).exists() @@ -98,6 +114,10 @@ class WebServer( .setObjectToNumberStrategy(ToNumberPolicy.LONG_OR_DOUBLE) .create() private val dbContextType = object : TypeToken>() {}.type + + // Read and written by any worker; -1 means "not fetched yet". Two workers racing to fetch it + // both write the same id, so a plain volatile is enough. + @Volatile private var bookshelfTemplateId: Int = -1 private val httpInternalServerError = 500 private val httpNotFound = 404 @@ -113,13 +133,34 @@ class WebServer( // ladder is 1 s, 3 s, 7 s, so anything past it is nobody browsing rather than ADFA-5172. private val maxReportedAcceptWaitNanos = TimeUnit.SECONDS.toNanos(10) - // How long handleClient()'s last stat of config.debugDatabasePath took, and how long the last - // accept() waited. Plain vars are safe: the accept loop is serial and single-threaded, and it is - // the only reader and writer. - private var debugDbStatNanos = 0L + // Accept-thread-only state for ADFA-5172's report: how long the last accept() waited, and the + // wait before it. Only that one thread reads or writes them, so plain vars are safe. private var acceptWaitNanos = 0L private var previousAcceptWaitNanos = noPreviousIteration - private var previousBusyNanos = 0L + + // Hal Eisen: required to fix StrictMode.VmPolicy.Builder.detectUntaggedSockets(). + private val socketStatsTag = 0xC0DE + + // Serializes swapping `database` (which closes the old handle) against the workers reading + // through it. Readers never block each other; only a swap waits. + private val databaseLock = ReentrantReadWriteLock() + + private val debugDatabaseCheckIntervalNanos = TimeUnit.MILLISECONDS.toNanos(config.debugDatabaseCheckIntervalMs) + + // Start one interval in the past so the first request still checks for a debug database. + private val lastDebugDatabaseCheckNanos = AtomicLong(System.nanoTime() - debugDatabaseCheckIntervalNanos) + + // Serves accepted connections, so a slow or idle client cannot delay the next accept(). + private var workers: ThreadPoolExecutor? = null + + // Live client sockets. Shutdown closes them, which is what unblocks a worker parked in a + // socket read -- shutdownNow()'s interrupt does not, since stream reads ignore it. + private val liveSockets: MutableSet = ConcurrentHashMap.newKeySet() + + private val workerShutdownTimeoutSeconds = 2L + + // How long an idle worker thread sticks around before the pool reclaims it. + private val workerIdleTimeoutSeconds = 30L // function to obtain the last modified date of a documentation.db database // this is used to see if there is a newer version of the database on the sdcard @@ -171,8 +212,7 @@ class WebServer( } fun start() { - // Hal Eisen: Required to fix StrictMode.VmPolicy.Builder.detectUntaggedSockets() - TrafficStats.setThreadStatsTag(0xC0DE) + TrafficStats.setThreadStatsTag(socketStatsTag) try { log.info( "Starting WebServer on {}, port {}, debugEnabled={}, debugEnablePath='{}', " + @@ -208,14 +248,18 @@ class WebServer( } log.info("WebServer started successfully on '{}', port {}.", config.bindName, config.port) + val pool = newWorkerPool() + workers = pool + while (true) { val clientSocket = acceptNextClient() ?: break + // The worker owns the socket from here, including closing it. try { - serveClient(clientSocket) - } finally { + pool.execute { handleConnection(clientSocket) } + } catch (e: RejectedExecutionException) { + log.warn("All {} workers are busy; dropping the connection {}.", config.maxWorkerThreads, clientSocket) closeQuietly(clientSocket) - if (debugEnabled) log.debug("Served and closed clientSocket {}.", clientSocket) } } } catch (e: Exception) { @@ -224,6 +268,23 @@ class WebServer( if (::serverSocket.isInitialized) { serverSocket.close() } + + // Workers have to finish before the database closes below, or one of them queries a + // handle this thread has already closed. Closing their sockets is what gets them out + // of a blocking read; the interrupt from shutdownNow() alone would not. + workers?.let { pool -> + pool.shutdownNow() + liveSockets.forEach { closeQuietly(it) } + try { + if (!pool.awaitTermination(workerShutdownTimeoutSeconds, TimeUnit.SECONDS)) { + log.warn("Workers still running {} s after shutdown; closing the database anyway.", workerShutdownTimeoutSeconds) + } + } catch (e: InterruptedException) { + Thread.currentThread().interrupt() + } + } + workers = null + // database is opened before the stopRequested check that can abort start() // early (and before the accept loop on every other exit path), so it must be // closed here too, not just serverSocket -- isInitialized guards the case @@ -240,9 +301,9 @@ class WebServer( } /** - * Waits for the next connection. Null means the listening socket closed and the loop is done; - * an accept that failed for any other reason is logged and retried, since one bad accept is not - * a reason to stop serving. + * Waits for the next connection, and reports the wait if it looks like ADFA-5172's stall. Null + * means the listening socket closed and the loop is done; an accept that failed for any other + * reason is logged and retried, since one bad accept is not a reason to stop serving. */ private fun acceptNextClient(): Socket? { while (true) { @@ -252,6 +313,8 @@ class WebServer( val acceptStartNanos = System.nanoTime() val clientSocket = serverSocket.accept() acceptWaitNanos = System.nanoTime() - acceptStartNanos + reportAcceptWait(acceptWaitNanos, previousAcceptWaitNanos) + previousAcceptWaitNanos = acceptWaitNanos if (debugEnabled) log.debug("Returned from socket accept(), clientSocket is {}.", clientSocket) return clientSocket @@ -268,10 +331,26 @@ class WebServer( } } - /** Serves one connection, answering with a 500 if handling it fails partway. */ - private fun serveClient(clientSocket: Socket) { - val busyStartNanos = System.nanoTime() - debugDbStatNanos = 0L + private fun sendInternalServerError(clientSocket: Socket) { + try { + val output = clientSocket.outputStream + + sendError(PrintWriter(output, true), output, httpInternalServerError, "Internal Server Error 1") + } catch (e: Exception) { + log.error("Error sending error response: {}", e.message) + } + } + + /** A closed socket reports itself only in the exception's message, hence the string test. */ + private fun isSocketClosed(e: java.net.SocketException): Boolean = e.message?.contains("Closed", ignoreCase = true) == true + + /** + * Serves one connection and closes it. Runs on a worker, so the accept loop is free to take + * the next connection while this one is still being answered. + */ + private fun handleConnection(clientSocket: Socket) { + liveSockets.add(clientSocket) + val startNanos = System.nanoTime() try { handleClient(clientSocket) @@ -286,61 +365,61 @@ class WebServer( sendInternalServerError(clientSocket) } } finally { - val busyNanos = System.nanoTime() - busyStartNanos - reportStall(acceptWaitNanos, busyNanos, previousAcceptWaitNanos, previousBusyNanos) - previousAcceptWaitNanos = acceptWaitNanos - previousBusyNanos = busyNanos + liveSockets.remove(clientSocket) + closeQuietly(clientSocket) + reportSlowRequest(System.nanoTime() - startNanos, clientSocket) + + if (debugEnabled) log.debug("Served and closed clientSocket {}.", clientSocket) } } - private fun sendInternalServerError(clientSocket: Socket) { - try { - val output = clientSocket.outputStream - - sendError(PrintWriter(output, true), output, httpInternalServerError, "Internal Server Error 1") - } catch (e: Exception) { - log.error("Error sending error response: {}", e.message) + /** + * Threads are created on demand up to [ServerConfig.maxWorkerThreads] and reused. The queue is + * a [SynchronousQueue] so a burst grows the pool instead of lining up behind a busy worker -- + * queueing would reintroduce the head-of-line delay this pool exists to remove. + */ + private fun newWorkerPool(): ThreadPoolExecutor { + val created = AtomicLong() + + return ThreadPoolExecutor( + 1, + config.maxWorkerThreads, + workerIdleTimeoutSeconds, + TimeUnit.SECONDS, + SynchronousQueue(), + ) { runnable -> + Thread({ + // Thread-local, so it has to be set on every worker, not just the accept thread. + TrafficStats.setThreadStatsTag(socketStatsTag) + runnable.run() + }, "WebServer-worker-${created.incrementAndGet()}").apply { isDaemon = true } } } - private fun closeQuietly(clientSocket: Socket) { + private fun closeQuietly(socket: Socket) { try { - clientSocket.close() + socket.close() } catch (e: Exception) { - log.error("Cannot close client socket: {}", e.message) + if (debugEnabled) log.debug("Cannot close client socket: {}", e.message) } } - /** A closed socket reports itself only in the exception's message, hence the string test. */ - private fun isSocketClosed(e: java.net.SocketException): Boolean = e.message?.contains("Closed", ignoreCase = true) == true - /** - * Logs one line per accept-loop iteration that crosses [ServerConfig.stallThresholdMs], for - * ADFA-5172's periodic ~1 s stall. Splits "parked in accept()" from "busy outside it" because - * that is what separates a stall the loop caused -- a slow iteration delays the next accept, - * so an arriving SYN can be dropped and retried ~1 s later -- from one it merely suffered. - * Deliberately independent of [debugEnabled], whose ~10 log lines per request perturb the - * timing being measured. + * Reports a long wait in accept(), for ADFA-5172's periodic ~1 s stall. A long wait is just an + * idle server, so only the first one after a busy stretch is reported: that is the stall under + * sustained load, not a user who stopped browsing the documentation. Deliberately independent + * of [debugEnabled], whose ~10 log lines per request perturb the timing being measured. */ - private fun reportStall( + private fun reportAcceptWait( acceptWaitNanos: Long, - busyNanos: Long, previousAcceptWaitNanos: Long, - previousBusyNanos: Long, ) { - val stalledBeforeAccept = shouldReportAcceptWait(acceptWaitNanos, previousAcceptWaitNanos) - val stalledWhileBusy = busyNanos >= stallThresholdNanos || debugDbStatNanos >= stallThresholdNanos - if (!stalledBeforeAccept && !stalledWhileBusy) return + if (!shouldReportAcceptWait(acceptWaitNanos, previousAcceptWaitNanos)) return log.warn( - "Accept-loop stall: {} ms parked in accept(), then {} ms busy outside it, of which {} ms " + - "stat'ing '{}'. Previous iteration: {} ms parked, {} ms busy.", + "Waited {} ms in accept() for a connection under load (ADFA-5172: the loop was ready, " + + "so the delay is the handshake, not this server).", millis(acceptWaitNanos), - millis(busyNanos), - millis(debugDbStatNanos), - config.debugDatabasePath, - millis(previousAcceptWaitNanos), - millis(previousBusyNanos), ) } @@ -361,8 +440,67 @@ class WebServer( return loadWasSteady && acceptWaitNanos >= stallThresholdNanos && acceptWaitNanos <= maxReportedAcceptWaitNanos } + /** The other half of ADFA-5172's instrumentation: time actually spent serving a connection. */ + private fun reportSlowRequest( + elapsedNanos: Long, + clientSocket: Socket, + ) { + if (elapsedNanos < stallThresholdNanos) return + + log.warn("Took {} ms to serve {} (ADFA-5172).", millis(elapsedNanos), clientSocket) + } + private fun millis(nanos: Long): Long = TimeUnit.NANOSECONDS.toMillis(nanos) + /** + * Swaps to the sdcard debug database once a newer one appears. Opens the replacement before + * closing the old handle, so a failed open leaves the server serving the database it had. + * Takes the write lock, so a caller must not already hold the read lock. + */ + private fun maybeSwapDebugDatabase() { + val debugDatabaseTimestamp = debugDatabaseTimestampIfDue() ?: return + if (debugDatabaseTimestamp <= databaseTimestamp) return + + databaseLock.write { + // Another worker may have swapped while this one waited for the lock. + if (debugDatabaseTimestamp <= databaseTimestamp) return@write + + val replacement = SQLiteDatabase.openDatabase(config.debugDatabasePath, null, SQLiteDatabase.OPEN_READONLY) + val previous = database + database = replacement + databaseTimestamp = debugDatabaseTimestamp + bookshelfTemplateId = -1 + previous.close() + log.info("Swapped to the debug database '{}'.", config.debugDatabasePath) + } + } + + /** + * The debug database's last-modified time, or null when the last check was too recent. The + * path is FUSE-backed emulated storage, so ADFA-5175 rate-limits what used to be a stat on + * every request; one thread wins each interval and the rest skip the check. + */ + private fun debugDatabaseTimestampIfDue(): Long? { + val now = System.nanoTime() + val last = lastDebugDatabaseCheckNanos.get() + if (now - last < debugDatabaseCheckIntervalNanos) return null + if (!lastDebugDatabaseCheckNanos.compareAndSet(last, now)) return null + + val startNanos = System.nanoTime() + val timestamp = getDatabaseTimestamp(config.debugDatabasePath, true) + val elapsedNanos = System.nanoTime() - startNanos + + if (elapsedNanos >= stallThresholdNanos) { + log.warn( + "Stat of '{}' took {} ms; it is on FUSE-backed emulated storage (ADFA-5172).", + config.debugDatabasePath, + millis(elapsedNanos), + ) + } + + return timestamp + } + /** * Reads a single line from the stream (bytes until newline). Same stream is used for headers * and body so POST body bytes are not lost to a separate buffered reader. HTTP header lines are ASCII. @@ -437,19 +575,25 @@ class WebServer( return sendError(writer, output, 501, "Not Implemented") } - // check to see if there is a newer version of the documentation.db database on the sdcard - // if there is use that for our responses - // Timed for ADFA-5172: this stats FUSE-backed emulated storage on every request. - val statStartNanos = System.nanoTime() - val debugDatabaseTimestamp = getDatabaseTimestamp(config.debugDatabasePath, true) - debugDbStatNanos = System.nanoTime() - statStartNanos - if (debugDatabaseTimestamp > databaseTimestamp) { - bookshelfTemplateId = -1 - database.close() - database = SQLiteDatabase.openDatabase(config.debugDatabasePath, null, SQLiteDatabase.OPEN_READONLY) - databaseTimestamp = debugDatabaseTimestamp - } + // Use a newer documentation.db from the sdcard if one has appeared. Outside the read lock + // below, because swapping takes the write lock and this lock does not upgrade. + maybeSwapDebugDatabase() + + // Everything that reads `database` runs under the read lock, so a swap cannot close the + // handle from under this request. Readers do not block each other. + databaseLock.read { serveRequest(writer, output, path, brotliSupported) } + } + /** + * Answers one parsed request. Called with [databaseLock]'s read lock held, which is what makes + * the shared [database] handle safe to use from a worker thread. + */ + private fun serveRequest( + writer: PrintWriter, + output: java.io.OutputStream, + path: String, + brotliSupported: Boolean, + ) { // Handle the special "pr" endpoint with highest priority if (path.startsWith("pr/", false)) { if (debugEnabled) log.debug("Found a pr/ path, '{}'.", path) From 29277c69706806c90a175ffa19ef7807b4884f81 Mon Sep 17 00:00:00 2001 From: David Schachter Date: Mon, 17 Aug 2026 23:15:48 -0700 Subject: [PATCH 5/6] ADFA-5175: Say in the docdb doc that requests are pooled and the stat is rate-limited --- docs/documentation-database.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/documentation-database.md b/docs/documentation-database.md index 566703ad1b..5125161498 100644 --- a/docs/documentation-database.md +++ b/docs/documentation-database.md @@ -8,7 +8,7 @@ This is a **read-only, prebuilt** database — CoGo never creates or migrates it - Installed path: `context.getDatabasePath("documentation.db")` (`Environment.DOC_DB` in `common/.../utils/Environment.java`), i.e. the app's private `databases/` dir. - Bundled as an asset and extracted on install/update by `BundledAssetsInstaller` / `SplitAssetsInstaller`. -- **Debug override:** if `/sdcard/Download/documentation.db` exists and is newer than the installed copy, `WebServer` and `ToolTipManager` swap to it at request time (timestamp-compared per request, not just at startup) — a fast way to test a new database on-device without reinstalling. `WebServer`'s debug logging and experiment flags are also file-flag-gated under `/sdcard/Download/` (`CodeOnTheGo.webserver.debug`, `CodeOnTheGo.exp`, `CodeOnTheGo.webserver.cs0`). +- **Debug override:** if `/sdcard/Download/documentation.db` exists and is newer than the installed copy, `WebServer` and `ToolTipManager` swap to it at request time (`WebServer` compares timestamps at most once a second, not per request, since the path is FUSE-backed emulated storage) — a fast way to test a new database on-device without reinstalling. `WebServer`'s debug logging and experiment flags are also file-flag-gated under `/sdcard/Download/` (`CodeOnTheGo.webserver.debug`, `CodeOnTheGo.exp`, `CodeOnTheGo.webserver.cs0`). - **Don't trust a local copy's on-disk schema or row content as ground truth without checking freshness first.** Any manually downloaded or debug-override copy is independent of git history — a stale one can have a different schema (e.g. missing `UNIQUE(path)` or `templateId`) or be missing rows that already exist in the current, maintained database. A stale copy caused a real near-miss in ADFA-5088: a SQL script validated against it would have silently overwritten curated production tooltip content for several tags. Diff or re-download before authoring SQL against a local copy's state, not just before shipping it. ## Schema @@ -71,7 +71,7 @@ CREATE TABLE Tooltips ( All three sites below open the file with `SQLiteDatabase.openDatabase(..., OPEN_READONLY)` — no writes, ever, from this app (see ADR 0001 for why raw SQLite is justified here instead of Room). -- **`app/.../localWebServer/WebServer.kt`** — serves Tier 3. On each `GET`, runs: +- **`app/.../localWebServer/WebServer.kt`** — serves Tier 3. Requests are handled on a small worker pool, not on the accept loop, so the shared handle is read under a `ReentrantReadWriteLock` (the debug-database swap takes the write lock). On each `GET`, runs: ```sql SELECT C.content, CT.value, CT.compression, C.templateId From d72defc5448e05b3b078687a2153db8d560a6762 Mon Sep 17 00:00:00 2001 From: David Schachter Date: Tue, 18 Aug 2026 05:13:53 -0700 Subject: [PATCH 6/6] ADFA-5175: Close review holes in the shutdown path and the debug swap Three real findings from review, all in code this PR added or moved. Shutdown could close the database under a live worker. The socket was registered from inside the worker task, so the sweep that closes sockets to unblock workers could run in the window before that registration and miss one; awaitTermination can also simply time out, and the code continued regardless. Sockets are now registered in the accept loop before the task starts, and the close takes the write lock, so a worker still holding the read lock finishes its query instead of having the handle pulled out from under it. A debug database that will not open failed the request that noticed it. The open sat in the write block with no handler, so a missing or truncated sdcard database turned into a 500 -- and contradicted the KDoc promising the previous database keeps serving. It is caught and logged now, and the rate limiter means a fixed file is picked up on its own an interval later. The swap left templateCache full of templates compiled from the previous database, keyed by an id the replacement can define differently. It is cleared with the rest of the per-database state. Pre-existing on stage, but this PR is where the swap became concurrent, so it belongs here. Rebased onto the ADFA-5172 branch to pick up its accept-wait fix, which this branch's rewritten reporter now calls. --- .../androidide/localWebServer/WebServer.kt | 33 ++++++++++++++++--- 1 file changed, 29 insertions(+), 4 deletions(-) diff --git a/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt b/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt index e12de7e186..a16d05f1c0 100644 --- a/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt +++ b/app/src/main/java/com/itsaky/androidide/localWebServer/WebServer.kt @@ -254,11 +254,15 @@ class WebServer( while (true) { val clientSocket = acceptNextClient() ?: break - // The worker owns the socket from here, including closing it. + // The worker owns the socket from here, including closing it. Registered before the + // task starts, not inside it: shutdown closes what is registered to unblock workers, + // and a socket registered by the worker itself can be missed in that window. + liveSockets.add(clientSocket) try { pool.execute { handleConnection(clientSocket) } } catch (e: RejectedExecutionException) { log.warn("All {} workers are busy; dropping the connection {}.", config.maxWorkerThreads, clientSocket) + liveSockets.remove(clientSocket) closeQuietly(clientSocket) } } @@ -289,9 +293,13 @@ class WebServer( // early (and before the accept loop on every other exit path), so it must be // closed here too, not just serverSocket -- isInitialized guards the case // where opening it above failed and this finally still runs. + // + // Under the write lock, because the drain above is not a guarantee: awaitTermination can + // time out, and a worker that outlived it holds the read lock across its query. Taking + // the write lock waits for that worker instead of closing the handle underneath it. if (::database.isInitialized) { try { - database.close() + databaseLock.write { database.close() } } catch (e: Exception) { log.error("Cannot close database: {}", e.message) } @@ -349,7 +357,6 @@ class WebServer( * the next connection while this one is still being answered. */ private fun handleConnection(clientSocket: Socket) { - liveSockets.add(clientSocket) val startNanos = System.nanoTime() try { @@ -465,11 +472,29 @@ class WebServer( // Another worker may have swapped while this one waited for the lock. if (debugDatabaseTimestamp <= databaseTimestamp) return@write - val replacement = SQLiteDatabase.openDatabase(config.debugDatabasePath, null, SQLiteDatabase.OPEN_READONLY) + // A missing, truncated or unreadable debug database must not fail the request that + // happened to notice it: log it and keep serving the database already open. The next + // check is one interval away, so a fixed file is picked up on its own. + val replacement = + try { + SQLiteDatabase.openDatabase(config.debugDatabasePath, null, SQLiteDatabase.OPEN_READONLY) + } catch (e: Exception) { + log.error( + "Cannot open the debug database '{}'; still serving '{}': {}", + config.debugDatabasePath, + config.databasePath, + e.message, + ) + return@write + } + val previous = database database = replacement databaseTimestamp = debugDatabaseTimestamp bookshelfTemplateId = -1 + // Templates are cached by id, and the replacement database can define the same ids with + // different content, so a stale compiled template would render for the new database. + templateCache.clear() previous.close() log.info("Swapped to the debug database '{}'.", config.debugDatabasePath) }