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..7dfa15d4d5 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,10 @@ 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. 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, ) data class JavaExecutionResult( @@ -100,6 +104,23 @@ class WebServer( private val contentChunkSize = 1024 * 1024 + // 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, 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 fun getDatabaseTimestamp( @@ -188,50 +209,13 @@ class WebServer( log.info("WebServer started successfully on '{}', port {}.", config.bindName, config.port) while (true) { - var clientSocket: Socket? = null - try { - try { - if (debugEnabled) log.debug("About to call accept() on the server socket, {}.", serverSocket) - clientSocket = serverSocket.accept() - - 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) + closeQuietly(clientSocket) + if (debugEnabled) log.debug("Served and closed clientSocket {}.", clientSocket) } } } catch (e: Exception) { @@ -255,6 +239,130 @@ 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 + * 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, + ) { + val stalledBeforeAccept = shouldReportAcceptWait(acceptWaitNanos, previousAcceptWaitNanos) + 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), + ) + } + + /** + * 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) + /** * 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 +439,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() 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..ab2cfadc72 --- /dev/null +++ b/app/src/test/java/com/itsaky/androidide/localWebServer/AcceptWaitReportingTest.kt @@ -0,0 +1,104 @@ +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 `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 + // 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() + } +}