diff --git a/packages/kilo-jetbrains/CHANGELOG.md b/packages/kilo-jetbrains/CHANGELOG.md index 7ecd10534fd..ab2f215be36 100644 --- a/packages/kilo-jetbrains/CHANGELOG.md +++ b/packages/kilo-jetbrains/CHANGELOG.md @@ -4,7 +4,7 @@ ### Fixed -- Surface a clear error when the Kilo backend fails to start instead of hanging on loading, write the `kilo-dev.log` diagnostic log in release builds, and add CLI install path diagnostics for relocated JetBrains system folders. +- Surface a clear error when the Kilo backend fails to start instead of hanging on loading, write rotated `kilo-dev.log.*` diagnostic logs in release builds, and add CLI install path diagnostics for relocated JetBrains system folders. ## 7.4.2 diff --git a/packages/kilo-jetbrains/README.md b/packages/kilo-jetbrains/README.md index d35a08a8065..e5452e7ddd0 100644 --- a/packages/kilo-jetbrains/README.md +++ b/packages/kilo-jetbrains/README.md @@ -109,7 +109,7 @@ All properties below are passed with `-P` on the Gradle command line or in the r | `kilo.dev.worktree.root` | monorepo root | Worktree root used to resolve `.kilo-dev/`. Auto-detected from the Gradle project directory; override only when the auto-detection is wrong. | The checked-in IDE run configurations pass `--no-configuration-cache` because the IntelliJ Platform Gradle Plugin run-IDE tasks are not configuration-cache compatible in this setup. -They also pass `--purge-old-log-directories` so stale sandbox logs do not hide the current backend and frontend `kilo-dev.log` files. +They also pass `--purge-old-log-directories` so stale sandbox logs do not hide the current backend and frontend `kilo-dev.log.*` files. Example with a fixed split-mode port: @@ -141,7 +141,7 @@ The checked-in `Run IDE (Backend)`, `Run IDE (Frontend)`, and `Run IDE (Split Mo ### Debug logging properties -The plugin supports a few JVM system properties for local debugging. These are most useful with sandbox runs because the logs are mirrored to `kilo-dev.log` files for frontend and backend. +The plugin supports a few JVM system properties for local debugging. These are most useful with sandbox runs because the logs are mirrored to `kilo-dev.log.*` files for frontend and backend. `kilo.dev.log.level` @@ -167,8 +167,8 @@ The plugin supports a few JVM system properties for local debugging. These are m Where to find the log files: - In sandbox runs, Kilo writes separate dev log files for each side under the IDE sandbox log directory reported by `PathManager.getLogDir()`. -- Frontend log file: `/kilo-frontend/kilo-dev.log` -- Backend log file: `/kilo-backend/kilo-dev.log` +- Frontend log file: `/kilo-frontend/kilo-dev.log.0` +- Backend log file: `/kilo-backend/kilo-dev.log.0` - In practice these sit under the current `log_run*` sandbox logs for the active run. - If you are unsure of the exact sandbox root, open the IDE log directory from the running sandbox instance and then look for the `kilo-frontend/` and `kilo-backend/` subdirectories. diff --git a/packages/kilo-jetbrains/backend/src/main/kotlin/ai/kilocode/backend/app/KiloBackendAppService.kt b/packages/kilo-jetbrains/backend/src/main/kotlin/ai/kilocode/backend/app/KiloBackendAppService.kt index 5033b312c0c..77aee949b6b 100644 --- a/packages/kilo-jetbrains/backend/src/main/kotlin/ai/kilocode/backend/app/KiloBackendAppService.kt +++ b/packages/kilo-jetbrains/backend/src/main/kotlin/ai/kilocode/backend/app/KiloBackendAppService.kt @@ -162,6 +162,8 @@ class KiloBackendAppService private constructor( clear() connection.restart() log.info("restart: complete") + } catch (e: CancellationException) { + throw e } catch (e: Exception) { log.warn("restart: failed", e) throw e @@ -177,6 +179,8 @@ class KiloBackendAppService private constructor( clear() connection.reinstall() log.info("reinstall: complete") + } catch (e: CancellationException) { + throw e } catch (e: Exception) { log.warn("reinstall: failed", e) throw e diff --git a/packages/kilo-jetbrains/backend/src/main/kotlin/ai/kilocode/backend/cli/KiloBackendCliManager.kt b/packages/kilo-jetbrains/backend/src/main/kotlin/ai/kilocode/backend/cli/KiloBackendCliManager.kt index 3fd3ce8355b..6a6b0cd9251 100644 --- a/packages/kilo-jetbrains/backend/src/main/kotlin/ai/kilocode/backend/cli/KiloBackendCliManager.kt +++ b/packages/kilo-jetbrains/backend/src/main/kotlin/ai/kilocode/backend/cli/KiloBackendCliManager.kt @@ -8,6 +8,7 @@ import com.intellij.openapi.application.PathManager import com.intellij.openapi.util.SystemInfo import com.intellij.util.EnvironmentUtil import kotlinx.coroutines.CompletableDeferred +import kotlinx.coroutines.CancellationException import kotlinx.coroutines.Dispatchers import kotlinx.coroutines.TimeoutCancellationException import kotlinx.coroutines.withContext @@ -43,6 +44,7 @@ class KiloBackendCliManager( companion object { private const val STARTUP_TIMEOUT_MS = 30_000L + private const val STARTUP_TIMEOUT_GRACE_MS = 8_000L private const val KILL_TIMEOUT_SECONDS = 5L } @@ -64,7 +66,21 @@ class KiloBackendCliManager( val path = resolveCli(onProgress) onResolved() log.info("CLI binary path: ${path.absolutePath} (size=${path.length()} bytes)") - spawn(path) + withTimeout(timeoutMs + STARTUP_TIMEOUT_GRACE_MS) { spawn(path) } + } catch (e: TimeoutCancellationException) { + val msg = "CLI startup timed out after ${timeoutMs}ms" + log.warn(msg, e) + process?.let { proc -> + log.info("Cleaning up orphaned CLI process (pid=${proc.pid()})") + process = null + cleanup(proc, "startup timeout cleanup") + } + CliServer.State.Error( + message = msg, + details = e.stackTraceToString(), + ) + } catch (e: CancellationException) { + throw e } catch (e: Exception) { log.warn("CLI startup failed", e) process?.let { proc -> @@ -106,6 +122,7 @@ class KiloBackendCliManager( private suspend fun spawn(cli: File): CliServer.State = withContext(Dispatchers.IO) { val pwd = generatePassword() + val start = System.nanoTime() val env = buildEnv(pwd) val diag = startupDiagnostics(cli, env, log) @@ -148,20 +165,21 @@ class KiloBackendCliManager( stdout = proc.inputStream, stderr = stderr, pwd = pwd, - timeoutMs = timeoutMs, + timeoutMs = (timeoutMs - elapsed(start)).coerceAtLeast(1L), alive = { proc.isAlive }, pid = { proc.pid() }, code = { proc.waitFor() }, - onTimeout = { cleanup(proc, "startup timeout") }, + onTimeout = { + if (process == proc) process = null + cleanup(proc, "startup timeout") + }, diagnostics = { diag }, log = log, onThread = { stdout = it }, ) - if (state is CliServer.State.Error) { + if (state is CliServer.State.Error && process == proc) { process = null - uninstall() - this@KiloBackendCliManager.stderr = null - this@KiloBackendCliManager.stdout = null + cleanup(proc, "startup error") } state } @@ -242,6 +260,8 @@ class KiloBackendCliManager( SecureRandom().nextBytes(bytes) return bytes.joinToString("") { "%02x".format(it) } } + + private fun elapsed(start: Long): Long = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start) } internal fun startupDiagnostics(cli: File, env: Map, log: KiloLog): String { diff --git a/packages/kilo-jetbrains/backend/src/main/kotlin/ai/kilocode/backend/cli/KiloCliDownloader.kt b/packages/kilo-jetbrains/backend/src/main/kotlin/ai/kilocode/backend/cli/KiloCliDownloader.kt index e664c97dd88..3c436e3a32c 100644 --- a/packages/kilo-jetbrains/backend/src/main/kotlin/ai/kilocode/backend/cli/KiloCliDownloader.kt +++ b/packages/kilo-jetbrains/backend/src/main/kotlin/ai/kilocode/backend/cli/KiloCliDownloader.kt @@ -131,11 +131,11 @@ class KiloCliDownloader( val mutex = LOCKS.computeIfAbsent(file.absolutePath) { Any() } return synchronized(mutex) { RandomAccessFile(file, "rw").channel.use { channel -> - val start = System.currentTimeMillis() + val start = System.nanoTime() log.info("Waiting for Kilo CLI cache lock: ${file.absolutePath}") val lock = acquire(file, channel::tryLock, start) lock.use { - log.info("Acquired Kilo CLI cache lock after ${System.currentTimeMillis() - start}ms: ${file.absolutePath}") + log.info("Acquired Kilo CLI cache lock after ${elapsed(start)}ms: ${file.absolutePath}") block() } } @@ -150,7 +150,7 @@ class KiloCliDownloader( null } if (lock != null) return lock - val waited = System.currentTimeMillis() - start + val waited = elapsed(start) if (waited >= lockTimeoutMs) { val msg = "Timed out waiting for Kilo CLI cache lock after ${waited}ms: ${file.absolutePath}" log.warn(msg) @@ -160,6 +160,8 @@ class KiloCliDownloader( } } + private fun elapsed(start: Long): Long = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start) + private fun stage(version: String, platform: String): File { val tmp = File(root, ".tmp") val dir = File(tmp, "$version-$platform-${System.nanoTime()}") @@ -377,16 +379,16 @@ class KiloCliDownloader( add("pluginsPath=${safe { PathManager.getPluginsPath() }}") add("logPath=${safe { PathManager.getLogPath() }}") add("logDir=${safe { PathManager.getLogDir().toString() }}") - add("idea.config.path=${System.getProperty("idea.config.path") ?: ""}") - add("idea.system.path=${System.getProperty("idea.system.path") ?: ""}") - add("idea.plugins.path=${System.getProperty("idea.plugins.path") ?: ""}") - add("idea.log.path=${System.getProperty("idea.log.path") ?: ""}") - add("idea.properties.file=${System.getProperty("idea.properties.file") ?: ""}") - add("user.home=${System.getProperty("user.home") ?: ""}") - add("USERPROFILE=${EnvironmentUtil.getValue("USERPROFILE") ?: ""}") - add("TEMP=${EnvironmentUtil.getValue("TEMP") ?: ""}") - add("TMP=${EnvironmentUtil.getValue("TMP") ?: ""}") - add("cacheRoot=${root.absolutePath}${info(root)}") + add("idea.config.path=${safe { System.getProperty("idea.config.path") ?: "" }}") + add("idea.system.path=${safe { System.getProperty("idea.system.path") ?: "" }}") + add("idea.plugins.path=${safe { System.getProperty("idea.plugins.path") ?: "" }}") + add("idea.log.path=${safe { System.getProperty("idea.log.path") ?: "" }}") + add("idea.properties.file=${safe { System.getProperty("idea.properties.file") ?: "" }}") + add("user.home=${safe { System.getProperty("user.home") ?: "" }}") + add("USERPROFILE=${safe { EnvironmentUtil.getValue("USERPROFILE") ?: "" }}") + add("TEMP=${safe { EnvironmentUtil.getValue("TEMP") ?: "" }}") + add("TMP=${safe { EnvironmentUtil.getValue("TMP") ?: "" }}") + add("cacheRoot=${safe { root.absolutePath + info(root) }}") }.joinToString(" ") log.info("Kilo CLI path diagnostics: $text") } diff --git a/packages/kilo-jetbrains/backend/src/test/kotlin/ai/kilocode/backend/cli/KiloBackendCliManagerReadyTest.kt b/packages/kilo-jetbrains/backend/src/test/kotlin/ai/kilocode/backend/cli/KiloBackendCliManagerReadyTest.kt index 8f981b3de5e..eebcc96eb4d 100644 --- a/packages/kilo-jetbrains/backend/src/test/kotlin/ai/kilocode/backend/cli/KiloBackendCliManagerReadyTest.kt +++ b/packages/kilo-jetbrains/backend/src/test/kotlin/ai/kilocode/backend/cli/KiloBackendCliManagerReadyTest.kt @@ -44,7 +44,7 @@ class KiloBackendCliManagerReadyTest { stdout = input, stderr = StringBuilder("stderr line"), pwd = "pwd123", - timeoutMs = 50, + timeoutMs = WATCHDOG_TIMEOUT_MS, alive = { true }, pid = { 456L }, code = { 0 }, @@ -57,7 +57,7 @@ class KiloBackendCliManagerReadyTest { val err = assertIs(state) assertEquals(1, calls.get()) - assertContains(err.message, "within 50ms") + assertContains(err.message, "within ${WATCHDOG_TIMEOUT_MS}ms") assertContains(err.message, "process alive=true") assertContains(err.message, "pid=456") assertContains(err.details.orEmpty(), "stderr line") @@ -107,5 +107,6 @@ class KiloBackendCliManagerReadyTest { companion object { private const val TIMEOUT_MS = 1_000L + private const val WATCHDOG_TIMEOUT_MS = 50L } } diff --git a/packages/kilo-jetbrains/backend/src/test/kotlin/ai/kilocode/backend/cli/KiloCliDownloaderTest.kt b/packages/kilo-jetbrains/backend/src/test/kotlin/ai/kilocode/backend/cli/KiloCliDownloaderTest.kt index 12d71855d97..f1971c8d981 100644 --- a/packages/kilo-jetbrains/backend/src/test/kotlin/ai/kilocode/backend/cli/KiloCliDownloaderTest.kt +++ b/packages/kilo-jetbrains/backend/src/test/kotlin/ai/kilocode/backend/cli/KiloCliDownloaderTest.kt @@ -274,7 +274,7 @@ class KiloCliDownloaderTest { } @Test - fun `cache lock times out clearly when held by another process`() = runBlocking { + fun `cache lock times out clearly when already held in this process`() = runBlocking { assertTrue(dir.mkdirs() || dir.isDirectory) val file = File(dir, ".lock") val log = TestLog() diff --git a/packages/kilo-jetbrains/shared/src/main/kotlin/ai/kilocode/log/KiloLog.kt b/packages/kilo-jetbrains/shared/src/main/kotlin/ai/kilocode/log/KiloLog.kt index b448343a5b9..a14ed12f0e4 100644 --- a/packages/kilo-jetbrains/shared/src/main/kotlin/ai/kilocode/log/KiloLog.kt +++ b/packages/kilo-jetbrains/shared/src/main/kotlin/ai/kilocode/log/KiloLog.kt @@ -21,10 +21,10 @@ import java.util.logging.LogRecord * Logging interface for the Kilo JetBrains plugin. * * In normal (non-sandbox) mode, output goes through IntelliJ's own [com.intellij.openapi.diagnostic.Logger], - * which writes to the standard IDE log file, and to a rotated `kilo-dev.log` file inside the IDE log directory. + * which writes to the standard IDE log file, and to rotated `kilo-dev.log.*` files inside the IDE log directory. * * In sandbox mode (i.e. when running via `./gradlew runIde`, detected via the `idea.plugin.in.sandbox.mode` - * system property), output is written only to `kilo-dev.log`. + * system property), output is written only to `kilo-dev.log.*`. * * Usage: * ```kotlin @@ -119,7 +119,7 @@ internal class FileLog(cls: Class<*>) : KiloLog { private val handler: FileHandler by lazy { val dir = resolveLogDir() - val path = dir.resolve("kilo-dev.log") + val path = dir.resolve("kilo-dev.log.%g") IntellijLog(FileLog::class.java).info("Kilo diagnostic log directory: $dir") val h = FileHandler(path.toString(), LIMIT, COUNT, true) h.formatter = KiloFormatter()