ADFA-5172: Instrument the accept loop to locate the periodic 1 s stall

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

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