Pass Delay as a Parameter to LogcatServiceImpl

Logcat format is not well-defined. A log entry is terminated by a "\n\n" but it can also contain a "\n\n" inside a single log entry. So there is no way to tell when an entry ends. This means that we cannot consume the last log entry immediately, we need to allow for the possibility that another batch is arriving from the socket. If another batch doesn't arrive within a certain time period, we consume the entry.

By definition, this is flaky but there is no other alternative that I am aware of. I have plans to switch to the binary format which is more robust, but it's also more fragile, so I'm not sure when that will happen.

The test is failing because LogcatMessageAssembler is consuming the last message from the server too early, before the server terminates.

By passing a large delay value to the assembler, we can prevent that from happening.

http://sponge/ed5c43dc-1862-4996-bd2e-377b590fa4be

Fixes: 240555493
Test: Self
Change-Id: Id4be6052aee6a9f137d3279ef34623cfa414b6b2

4 files changed, 35 insertions, 13 deletions

diff --git a/logcat/src/com/android/tools/idea/logcat/service/LogcatMessageAssembler.kt b/logcat/src/com/android/tools/idea/logcat/service/LogcatMessageAssembler.kt
index bf78ace2a4b..363dc60248b 100644
--- a/logcat/src/com/android/tools/idea/logcat/service/LogcatMessageAssembler.kt
+++ b/logcat/src/com/android/tools/idea/logcat/service/LogcatMessageAssembler.kt
@@ -33,11 +33,6 @@ import kotlin.coroutines.CoroutineContext
 private const val SYSTEM_LINE_PREFIX = "--------- beginning of "
 
 /**
- * Last message in batch will be posted after a delay, to allow for more log lines if another batch is pending.
- */
-private const val DELAY_MILLIS = 100L
-
-/**
  * Receives batches of lines from an `adb logcat -v long` process and assembles them into complete [LogcatMessage]'s.
  *
  * A logcat entry starts with a header:
@@ -53,6 +48,9 @@ private const val DELAY_MILLIS = 100L
  * To avoid this delay, after finishing precessing a batch of lines, we schedule a delayed task to flush the last message if nothing arrives
  * in time.
  *
+ * Note:
+ * This is flaky by definition but given the Logcat ambiguous format, it's the best we can do.
+ *
  * This class is derived from [com.android.tools.idea.logcat.AndroidLogcatReceiver]
  */
 internal class LogcatMessageAssembler(
@@ -62,6 +60,7 @@ internal class LogcatMessageAssembler(
   private val channel: SendChannel<List<LogcatMessage>>,
   processNameMonitor: ProcessNameMonitor,
   coroutineContext: CoroutineContext,
+  private val lastMessageDelayMs: Long,
 ) : Disposable {
   private val coroutineScope = AndroidCoroutineScope(this, coroutineContext)
 
@@ -113,7 +112,8 @@ internal class LogcatMessageAssembler(
     // If there is a valid last message in the batch, queue it for sending in case there is no imminent next batch coming
     if (batch.lastHeader != null && batch.lastLines.isNotEmpty()) {
       coroutineScope.launch {
-        delay(DELAY_MILLIS)
+        // This is flaky by definition but given the Logcat ambiguous format, it's the best we can do. See class KDoc
+        delay(lastMessageDelayMs)
         val message = getAndResetPendingMessage(partialMessage)
         if (message != null) {
           channel.send(listOf(message))
diff --git a/logcat/src/com/android/tools/idea/logcat/service/LogcatServiceImpl.kt b/logcat/src/com/android/tools/idea/logcat/service/LogcatServiceImpl.kt
index e826f4be40c..b92d369502e 100644
--- a/logcat/src/com/android/tools/idea/logcat/service/LogcatServiceImpl.kt
+++ b/logcat/src/com/android/tools/idea/logcat/service/LogcatServiceImpl.kt
@@ -16,16 +16,28 @@ import com.intellij.openapi.Disposable
 import kotlinx.coroutines.flow.Flow
 import kotlinx.coroutines.flow.channelFlow
 import kotlinx.coroutines.flow.collect
+import org.jetbrains.annotations.VisibleForTesting
 import java.time.Duration
 
 /**
+ * Last message in batch will be posted after a delay, to allow for more log lines if another batch is pending.
+ */
+private const val LOGCAT_IDLE_TIMEOUT_MILLIS = 100L
+
+/**
  * Implementation of a [LogcatService]
  */
-internal class LogcatServiceImpl(
+internal class LogcatServiceImpl @VisibleForTesting constructor (
   private val disposableParent: Disposable,
   private val deviceServicesFactory: () -> AdbDeviceServices,
   private val processNameMonitor: ProcessNameMonitor,
+  private val lastMessageDelayMs: Long,
 ) : LogcatService {
+  constructor(
+    disposableParent: Disposable,
+    deviceServicesFactory: () -> AdbDeviceServices,
+    processNameMonitor: ProcessNameMonitor,
+  ): this(disposableParent, deviceServicesFactory, processNameMonitor, LOGCAT_IDLE_TIMEOUT_MILLIS)
 
   override suspend fun readLogcat(device: Device): Flow<List<LogcatMessage>> {
     val deviceSelector = DeviceSelector.fromSerialNumber(device.serialNumber)
@@ -38,7 +50,8 @@ internal class LogcatServiceImpl(
         logcatFormat,
         channel,
         processNameMonitor,
-        coroutineContext)
+        coroutineContext,
+        lastMessageDelayMs)
       deviceServicesFactory().shell(deviceSelector, buildLogcatCommand(logcatFormat), LineBatchShellCollector()).collect {
         messageAssembler.processNewLines(it)
       }
diff --git a/logcat/testSrc/com/android/tools/idea/logcat/service/LogcatMessageAssemblerTest.kt b/logcat/testSrc/com/android/tools/idea/logcat/service/LogcatMessageAssemblerTest.kt
index c03b776001f..c96e50d0ce8 100644
--- a/logcat/testSrc/com/android/tools/idea/logcat/service/LogcatMessageAssemblerTest.kt
+++ b/logcat/testSrc/com/android/tools/idea/logcat/service/LogcatMessageAssemblerTest.kt
@@ -441,7 +441,8 @@ class LogcatMessageAssemblerTest {
       EPOCH_FORMAT,
       channel,
       processNameMonitor,
-      coroutineContext)
+      coroutineContext,
+      lastMessageDelayMs = 100)
 }
 
 private fun logcatMessage(
diff --git a/logcat/testSrc/com/android/tools/idea/logcat/service/LogcatServiceImplTest.kt b/logcat/testSrc/com/android/tools/idea/logcat/service/LogcatServiceImplTest.kt
index 15e1072241f..5fe39d23d95 100644
--- a/logcat/testSrc/com/android/tools/idea/logcat/service/LogcatServiceImplTest.kt
+++ b/logcat/testSrc/com/android/tools/idea/logcat/service/LogcatServiceImplTest.kt
@@ -49,7 +49,7 @@ import java.net.Socket
 import java.time.Duration
 import java.time.Instant
 import java.util.concurrent.TimeUnit.MILLISECONDS
-
+import java.util.concurrent.TimeUnit.SECONDS
 
 /**
  * A Logcat message that's sent as the last message to a device so that we can wait for it before terminating FakeAdbRule
@@ -113,7 +113,8 @@ class LogcatServiceImplTest {
     val job = launch {
       try {
         service.readLogcat(device.device).collect {}
-      } catch (e: EOFException) {
+      }
+      catch (e: EOFException) {
         // We sometimes (~1%) get an EOFException when the ADB Server terminates
       }
     }
@@ -210,9 +211,16 @@ class LogcatServiceImplTest {
 
       More error information
     """.trimIndent()
-    val service = logcatServiceImpl(
+    // This test is flaky because the underlying code has a 100ms delay before consuming the last log entry from the server. If the server
+    // takes a bit too long to terminate, the delay expires and the error message is consumed as a normal message rather than an error
+    // message. We pass a longer delay to LogcatServiceImpl to prevent LogcatMessageAssembler from consuming the last message before the
+    // server terminates.
+    val service = LogcatServiceImpl(
+      projectRule.project,
       deviceServicesFactory = { fakeAdb.createAdbSession(closeables).deviceServices },
-      processNameMonitor = fakeProcessNameMonitor)
+      processNameMonitor = fakeProcessNameMonitor,
+      lastMessageDelayMs = SECONDS.toMillis(10),
+    )
     val deviceState = fakeAdb.attachDevice(device30)
     deviceState.addLogcatMessage(logcat)