Add runtime diagnostic logging for level setup, native Git calls, inspection, validation, and UI command flow

2026-06-25 13:53:51 -05:00
parent 035851ac05
commit 60dd3c82f7
8 changed files with 215 additions and 53 deletions
--- a/app/build.gradle.kts
+++ b/app/build.gradle.kts
@@ -20,8 +20,8 @@ android {
        applicationId = "solutions.tretter.githugandroid"
        minSdk = 26
        targetSdk = 35
-        versionCode = 176
-        versionName = "0.1.175"
+        versionCode = 177
+        versionName = "0.1.176"

        testInstrumentationRunner = "androidx.test.runner.AndroidJUnitRunner"
        vectorDrawables.useSupportLibrary = true
--- a/app/src/main/java/solutions/tretter/githugandroid/AppLog.kt
+++ b/app/src/main/java/solutions/tretter/githugandroid/AppLog.kt
@@ -12,4 +12,46 @@ object AppLog {
    fun e(area: String, message: String, error: Throwable? = null) {
        Log.e(TAG, "[$area] $message", error)
    }
-}
+}
+
+internal fun elapsedMillisSince(startNanos: Long): Long =
+    (System.nanoTime() - startNanos) / 1_000_000L
+
+internal fun RepoState.diagnosticSnapshot(): String = buildString {
+    append("initialized=")
+    append(initialized)
+    append(", headBranch=")
+    append(headBranch)
+    append(", currentDir=")
+    append(currentDir)
+    append(", branches=")
+    append(branches.keys.sorted())
+    append(", tags=")
+    append(tags.sorted())
+    append(", remotes=")
+    append(remotes.toSortedMap())
+    append(", fetchedBranches=")
+    append(fetchedBranches.sorted())
+    append(", fetchHeadCount=")
+    append(fetchHeadCount)
+    append(", pushedBranches=")
+    append(pushedBranches.sorted())
+    append(", pushedTags=")
+    append(pushedTags.sorted())
+    append(", stashes=")
+    append(stashes)
+    append(", submodules=")
+    append(submodules.toSortedMap())
+    append(", maintenanceActions=")
+    append(maintenanceActions.sorted())
+    append(", config=")
+    append(config.toSortedMap())
+    append(", files=")
+    append(files.map { file ->
+        "${file.name}(staged=${file.staged},tracked=${file.tracked},deleted=${file.deleted})"
+    }.sorted())
+    append(", commits=")
+    append(commits.map { commit ->
+        "(${commit.id}, parents=${commit.parentCount}, message=${commit.message})"
+    })
+}
--- a/app/src/main/java/solutions/tretter/githugandroid/GitHugApp.kt
+++ b/app/src/main/java/solutions/tretter/githugandroid/GitHugApp.kt
@@ -111,8 +111,10 @@ fun GitHugApp() {
        }

        LaunchedEffect(currentLevelIndex) {
+            AppLog.d("GitHugApp", "Current level index changed to $currentLevelIndex id=${levels[currentLevelIndex].id}")
            delay(100)
            screenScrollState.animateScrollTo(0)
+            AppLog.d("GitHugApp", "Scrolled to top for level index=$currentLevelIndex id=${levels[currentLevelIndex].id}")
        }

        fun updatePaneLayout(transform: (PaneLayout) -> PaneLayout, persist: Boolean = true) {
@@ -214,7 +216,9 @@ fun GitHugApp() {
        }

        fun resetCurrentLevel(message: String = "Level reset.") {
+            val startedAt = System.nanoTime()
            val resetLevelId = currentLevel.id
+            AppLog.d("GitHugApp", "Reset requested level=$resetLevelId")
            val updatedCompletedLevels = completedLevels - resetLevelId
            completedLevels = updatedCompletedLevels
            scope.launch { persistProgress(updatedCompletedLevels, resetLevelId) }
@@ -231,6 +235,10 @@ fun GitHugApp() {
            gitMessageEditorState = null
            manPageState = null
            applyRecommendedPaneWeights(persist = false, outputLineCount = terminalOutputLineCount(listOf(message)))
+            AppLog.d(
+                "GitHugApp",
+                "Reset finished level=$resetLevelId durationMs=${elapsedMillisSince(startedAt)} repo=${repo.diagnosticSnapshot()}",
+            )
        }

        fun loadLevel(
@@ -239,6 +247,7 @@ fun GitHugApp() {
            keepSuppressedImeEcho: Boolean = false,
            prepareInBackground: Boolean = false,
        ) {
+            val startedAt = System.nanoTime()
            val level = levels[index]
            val requestId = levelLoadRequestId + 1
            levelLoadRequestId = requestId
@@ -260,21 +269,46 @@ fun GitHugApp() {
            if (prepareInBackground) {
                isPreparingLevel = true
                repo = RepoState()
+                AppLog.d(
+                    "GitHugApp",
+                    "Level load state updated index=$index id=${level.id} requestId=$requestId durationMs=${elapsedMillisSince(startedAt)} preparing=true",
+                )
                scope.launch {
+                    val prepareStartedAt = System.nanoTime()
+                    AppLog.d("GitHugApp", "Background prepare started index=$index id=${level.id} requestId=$requestId")
                    val preparedRepo = withContext(Dispatchers.Default) {
                        runtime.prepareLevel(level)
                    }
+                    val prepareMs = elapsedMillisSince(prepareStartedAt)
                    if (levelLoadRequestId == requestId) {
-                        AppLog.d("GitHugApp", "Prepared level index=$index id=${level.id}")
+                        AppLog.d(
+                            "GitHugApp",
+                            "Background prepare applying index=$index id=${level.id} requestId=$requestId prepareMs=$prepareMs " +
+                                "repo=${preparedRepo.diagnosticSnapshot()}",
+                        )
                        repo = preparedRepo
                        output = message
                        isPreparingLevel = false
                        clearCommandInput(recreateField = true)
+                        AppLog.d(
+                            "GitHugApp",
+                            "Background prepare applied index=$index id=${level.id} requestId=$requestId totalMs=${elapsedMillisSince(startedAt)}",
+                        )
+                    } else {
+                        AppLog.d(
+                            "GitHugApp",
+                            "Background prepare discarded index=$index id=${level.id} requestId=$requestId activeRequestId=$levelLoadRequestId prepareMs=$prepareMs",
+                        )
                    }
                }
            } else {
                isPreparingLevel = false
+                val prepareStartedAt = System.nanoTime()
                repo = runtime.prepareLevel(level)
+                AppLog.d(
+                    "GitHugApp",
+                    "Synchronous prepare applied index=$index id=${level.id} prepareMs=${elapsedMillisSince(prepareStartedAt)}",
+                )
            }
            paneLayout = paneLayout.copy(
                weights = paneLayout.weights + recommendedPaneWeights(
@@ -288,6 +322,10 @@ fun GitHugApp() {
                    ),
                )
            )
+            AppLog.d(
+                "GitHugApp",
+                "Level load returned index=$index id=${level.id} requestId=$requestId durationMs=${elapsedMillisSince(startedAt)} preparing=$isPreparingLevel",
+            )
        }

        fun setCommandText(text: String) {
@@ -348,12 +386,14 @@ fun GitHugApp() {
        }

        fun applyCommandResult(raw: String, newRepo: RepoState, lines: List<String>, echoCommand: Boolean) {
+            val startedAt = System.nanoTime()
            val levelForResult = currentLevel
            val solvedAfterCommand = levelForResult.validator(newRepo, raw)
            val wasAlreadyCompleted = currentLevel.id in completedLevels
            AppLog.d(
                "GitHugApp",
-                "Command='$raw' level=${levelForResult.id} solved=$solvedAfterCommand alreadyCompleted=$wasAlreadyCompleted completedBefore=${completedLevels.sorted()}",
+                "Command='$raw' level=${levelForResult.id} solved=$solvedAfterCommand alreadyCompleted=$wasAlreadyCompleted " +
+                    "completedBefore=${completedLevels.sorted()} outputLineCount=${lines.size} repo=${newRepo.diagnosticSnapshot()}",
            )
            val newOutput = buildList {
                addAll(output)
@@ -396,6 +436,10 @@ fun GitHugApp() {
                output = newOutput
                applyRecommendedPaneWeights(persist = false, outputLineCount = terminalOutputLineCount(newOutput))
            }
+            AppLog.d(
+                "GitHugApp",
+                "Command result applied level=${levelForResult.id} solved=$solvedAfterCommand durationMs=${elapsedMillisSince(startedAt)}",
+            )
        }

        fun openEditor(invocation: VisualEditorInvocation) {
@@ -480,16 +524,23 @@ fun GitHugApp() {
        }

        fun runCommand() {
+            val startedAt = System.nanoTime()
            val submittedText = commandInput.text
            val raw = submittedText.trim()
            if (raw.isBlank()) return
            if (isPreparingLevel) {
+                AppLog.d("GitHugApp", "Command blocked while preparing level=${currentLevel.id} raw='$raw'")
                output = output + "Still preparing ${currentLevel.title}. Try again in a moment."
                clearCommandInput(recreateField = true)
                applyRecommendedPaneWeights(persist = false, outputLineCount = terminalOutputLineCount(output))
                return
            }
+            val submittedLevelId = currentLevel.id
            val isInteractiveInput = repo.interactiveAddSession != null
+            AppLog.d(
+                "GitHugApp",
+                "Command submitted level=$submittedLevelId raw='$raw' interactive=$isInteractiveInput repo=${repo.diagnosticSnapshot()}",
+            )

            showHelpOverlay = false
            showTerminalInputHint = false
@@ -529,6 +580,7 @@ fun GitHugApp() {

            val (newRepo, lines) = runtime.execute(currentLevel, repo, raw)
            applyCommandResult(raw, newRepo, lines, echoCommand = !isInteractiveInput)
+            AppLog.d("GitHugApp", "Command handling finished level=$submittedLevelId raw='$raw' durationMs=${elapsedMillisSince(startedAt)}")
        }

        fun showCommandHelp() {
--- a/app/src/main/java/solutions/tretter/githugandroid/GitProcessRunner.kt
+++ b/app/src/main/java/solutions/tretter/githugandroid/GitProcessRunner.kt
@@ -54,11 +54,27 @@ internal class GitProcessRunner(
        arguments: List<String>,
        environment: Map<String, String> = emptyMap(),
    ): ProcessExecutionResult {
-        if (context != null) {
-            gitExecDirectory(binary)
-            return NativeGitBridge.runGitMain(binary, workingDir, arguments, gitEnvironment(binary, workingDir, environment))
+        val startedAt = System.nanoTime()
+        val execStartedAt = System.nanoTime()
+        val gitExecPath = gitExecDirectory(binary)
+        val execDirectoryMs = elapsedMillisSince(execStartedAt)
+        val fullEnvironment = gitEnvironment(binary, workingDir, environment, gitExecPath)
+        AppLog.d(
+            "GitProcess",
+            "runGit start cwd=${workingDir.absolutePath} argv=${formatGitArgv(arguments)} " +
+                "extraEnvKeys=${environment.keys.sorted()} execDirectoryMs=$execDirectoryMs",
+        )
+        val result = if (context != null) {
+            NativeGitBridge.runGitMain(binary, workingDir, arguments, fullEnvironment)
+        } else {
+            runProcess(binary, workingDir, arguments, fullEnvironment)
        }
-        return runProcess(binary, workingDir, arguments, environment)
+        AppLog.d(
+            "GitProcess",
+            "runGit finish exit=${result.exitCode} durationMs=${elapsedMillisSince(startedAt)} " +
+                "output=${formatOutputPreview(result.outputLines)}",
+        )
+        return result
    }

    fun runShellProcess(binary: File, workingDir: File, arguments: List<String>): ProcessExecutionResult {
@@ -84,15 +100,14 @@ internal class GitProcessRunner(
        binary: File,
        workingDir: File,
        arguments: List<String>,
-        extraEnvironment: Map<String, String> = emptyMap(),
+        environment: Map<String, String>,
    ): ProcessExecutionResult {
        return try {
-            val gitExecPath = gitExecDirectory(binary)
            val process = ProcessBuilder(listOf(binary.absolutePath) + arguments)
                .directory(workingDir)
                .redirectErrorStream(true)
                .apply {
-                    environment().putAll(gitEnvironment(binary, workingDir, extraEnvironment, gitExecPath))
+                    environment().putAll(environment)
                }
                .start()

@@ -192,6 +207,25 @@ internal class GitProcessRunner(
        }
        alias.setExecutable(true, false)
    }
+
+    private fun formatGitArgv(arguments: List<String>): String =
+        (listOf("git") + arguments).joinToString(" ") { argument ->
+            if (argument.any { it.isWhitespace() || it == '"' || it == '\'' }) {
+                "'" + argument.replace("'", "'\\''") + "'"
+            } else {
+                argument
+            }
+        }
+
+    private fun formatOutputPreview(lines: List<String>): String {
+        if (lines.isEmpty()) return "[]"
+        val preview = lines
+            .take(8)
+            .joinToString(" | ")
+            .take(1_000)
+        val suffix = if (lines.size > 8) " ... (${lines.size} lines)" else " (${lines.size} lines)"
+        return "[$preview]$suffix"
+    }
 }

 internal data class ProcessExecutionResult(
--- a/app/src/main/java/solutions/tretter/githugandroid/GitRepositoryInspector.kt
+++ b/app/src/main/java/solutions/tretter/githugandroid/GitRepositoryInspector.kt
@@ -7,33 +7,50 @@ internal class GitRepositoryInspector(
    private val runGit: (File, File, List<String>, Map<String, String>) -> ProcessExecutionResult,
 ) {
    fun inspectConfig(sandbox: File, currentDir: String = "."): Map<String, String> {
+        val startedAt = System.nanoTime()
        val git = nativeGit()
        val workingDir = File(sandbox, currentDir).canonicalFile
            .takeIf { it.path == sandbox.canonicalPath || it.path.startsWith(sandbox.canonicalPath + File.separator) }
            ?: sandbox
        val repositoryRoot = repositoryRoot(sandbox, workingDir) ?: sandbox
-        return readConfig(git, repositoryRoot)
+        val config = readConfig(git, repositoryRoot)
+        AppLog.d(
+            "GitInspector",
+            "inspectConfig sandbox=${sandbox.name} currentDir=$currentDir durationMs=${elapsedMillisSince(startedAt)} config=${config.toSortedMap()}",
+        )
+        return config
    }

    fun inspect(sandbox: File, currentDir: String = "."): RepoState {
+        val startedAt = System.nanoTime()
        val git = nativeGit()
        val workingDir = File(sandbox, currentDir).canonicalFile
            .takeIf { it.path == sandbox.canonicalPath || it.path.startsWith(sandbox.canonicalPath + File.separator) }
            ?: sandbox
        val repositoryRoot = repositoryRoot(sandbox, workingDir)
        val inspectionRoot = repositoryRoot ?: sandbox
+        AppLog.d(
+            "GitInspector",
+            "inspect start sandbox=${sandbox.name} currentDir=$currentDir workingDir=${workingDir.absolutePath} " +
+                "repositoryRoot=${repositoryRoot?.absolutePath ?: "<none>"}",
+        )
        val filesOnDisk = inspectionRoot.walkTopDown()
            .filter { it.isFile && !it.relativeTo(inspectionRoot).path.startsWith(".git/") }
            .orEmpty()
            .toList()

        if (repositoryRoot == null) {
-            return RepoState(
+            val repo = RepoState(
                initialized = false,
                files = filesOnDisk.map {
                    GitFile(name = it.relativeTo(inspectionRoot).path, content = it.readText())
                },
            )
+            AppLog.d(
+                "GitInspector",
+                "inspect finish sandbox=${sandbox.name} durationMs=${elapsedMillisSince(startedAt)} repo=${repo.diagnosticSnapshot()}",
+            )
+            return repo
        }

        val statusResult = run(git, inspectionRoot, listOf("status", "--porcelain"))
@@ -124,7 +141,7 @@ internal class GitRepositoryInspector(
                ?.let { "tags/$it" }
            ?: "DETACHED"

-        return RepoState(
+        val repo = RepoState(
            initialized = true,
            files = filesOnDisk.map { file ->
                val relativePath = file.relativeTo(inspectionRoot).path
@@ -172,6 +189,11 @@ internal class GitRepositoryInspector(
            submodules = submodules,
            maintenanceActions = maintenanceActions,
        )
+        AppLog.d(
+            "GitInspector",
+            "inspect finish sandbox=${sandbox.name} durationMs=${elapsedMillisSince(startedAt)} repo=${repo.diagnosticSnapshot()}",
+        )
+        return repo
    }

    private fun run(
--- a/app/src/main/java/solutions/tretter/githugandroid/GitRuntime.kt
+++ b/app/src/main/java/solutions/tretter/githugandroid/GitRuntime.kt
@@ -68,14 +68,19 @@ class GitRepositoryRuntime private constructor(
    }

    fun prepareLevel(level: Level): RepoState {
+        val startedAt = System.nanoTime()
        AppLog.d("GitRuntime", "Preparing level id=${level.id} title=${level.title}")
        val nativeGit = requireNativeGit()

        val sandbox = sandboxDir(level)
+        val resetStartedAt = System.nanoTime()
        sandbox.deleteRecursively()
        sandbox.mkdirs()
+        val resetMs = elapsedMillisSince(resetStartedAt)

        val desired = level.setup()
+        AppLog.d("GitRuntime", "Level setup desired id=${level.id} repo=${desired.diagnosticSnapshot()}")
+        val filesStartedAt = System.nanoTime()
        desired.files.forEach { file ->
            File(sandbox, file.name).apply {
                parentFile?.mkdirs()
@@ -83,8 +88,10 @@ class GitRepositoryRuntime private constructor(
            }
        }
        File(sandbox, desired.currentDir).mkdirs()
+        val filesMs = elapsedMillisSince(filesStartedAt)

        val needsGit = desired.initialized || desired.files.any { it.staged || it.tracked } || desired.commits.isNotEmpty()
+        val materializeStartedAt = System.nanoTime()
        if (needsGit) {
            val initResult = runGit(nativeGit, sandbox, listOf("init", "-b", desired.headBranch))
            if (initResult.exitCode != 0) {
@@ -94,12 +101,22 @@ class GitRepositoryRuntime private constructor(

            levelMaterializer.materialize(nativeGit, sandbox, desired, level)
        }
+        val materializeMs = elapsedMillisSince(materializeStartedAt)

-        return inspectSandbox(level, desired.currentDir).copy(currentDir = desired.currentDir)
+        val inspectStartedAt = System.nanoTime()
+        val preparedRepo = inspectSandbox(level, desired.currentDir).copy(currentDir = desired.currentDir)
+        val inspectMs = elapsedMillisSince(inspectStartedAt)
+        AppLog.d(
+            "GitRuntime",
+            "Prepared level id=${level.id} durationMs=${elapsedMillisSince(startedAt)} resetMs=$resetMs " +
+                "filesMs=$filesMs materializeMs=$materializeMs inspectMs=$inspectMs repo=${preparedRepo.diagnosticSnapshot()}",
+        )
+        return preparedRepo
    }

    fun execute(level: Level, currentRepo: RepoState, command: String): Pair<RepoState, List<String>> {
-        AppLog.d("GitRuntime", "Executing command for level=${level.id}: $command")
+        val startedAt = System.nanoTime()
+        AppLog.d("GitRuntime", "Executing command for level=${level.id}: $command currentRepo=${currentRepo.diagnosticSnapshot()}")
        val nativeGit = requireNativeGit()

        val sandbox = sandboxDir(level)
@@ -120,15 +137,33 @@ class GitRepositoryRuntime private constructor(
        } else {
            expandShellPathspecs(currentRepo, invocation.command)
        }
+        AppLog.d(
+            "GitRuntime",
+            "Command parsed level=${level.id} raw='$command' tokens=$tokens expanded=$expandedTokens cwd=${workingDir.absolutePath}",
+        )

        val result = when (expandedTokens.first()) {
-            "git" -> currentRepo to runGit(nativeGit, workingDir, expandedTokens.drop(1), invocation.environment).outputLines
+            "git" -> {
+                val gitResult = runGit(nativeGit, workingDir, expandedTokens.drop(1), invocation.environment)
+                AppLog.d(
+                    "GitRuntime",
+                    "Git command result level=${level.id} exit=${gitResult.exitCode} output=${gitResult.outputLines}",
+                )
+                currentRepo to gitResult.outputLines
+            }
            "help", "?" -> currentRepo to commandReferenceLines()
            else -> helperCommands.executeExecutableShortcut(sandboxRoot, workingDir, currentRepo, expandedTokens)
                ?: helperCommands.execute(sandboxRoot, workingDir, currentRepo, expandedTokens)
        }

+        val refreshStartedAt = System.nanoTime()
        val refreshedRepo = refreshRepoAfterCommand(level, currentRepo, result.first, expandedTokens)
+        val refreshMs = elapsedMillisSince(refreshStartedAt)
+        AppLog.d(
+            "GitRuntime",
+            "Command finished level=${level.id} durationMs=${elapsedMillisSince(startedAt)} refreshMs=$refreshMs " +
+                "repo=${refreshedRepo.diagnosticSnapshot()}",
+        )
        return refreshedRepo to result.second
    }

--- a/app/src/main/java/solutions/tretter/githugandroid/levels/LevelCatalog.kt
+++ b/app/src/main/java/solutions/tretter/githugandroid/levels/LevelCatalog.kt
@@ -131,6 +131,7 @@ private fun loggingValidator(
    levelTitle: String,
    validator: (RepoState, String) -> Boolean,
 ): (RepoState, String) -> Boolean = { repo, command ->
+    val startedAt = System.nanoTime()
    AppLog.d(
        "Validation",
        buildString {
@@ -141,43 +142,10 @@ private fun loggingValidator(
            append(" command='")
            append(command)
            append("' repo=")
-            append(repo.validationSnapshot())
+            append(repo.diagnosticSnapshot())
        },
    )
    val result = validator(repo, command)
-    AppLog.d("Validation", "Result level=$levelId passed=$result")
+    AppLog.d("Validation", "Result level=$levelId passed=$result durationMs=${elapsedMillisSince(startedAt)}")
    result
 }
-
-private fun RepoState.validationSnapshot(): String = buildString {
-    append("initialized=")
-    append(initialized)
-    append(", headBranch=")
-    append(headBranch)
-    append(", branches=")
-    append(branches.keys.sorted())
-    append(", tags=")
-    append(tags.sorted())
-    append(", remotes=")
-    append(remotes.toSortedMap())
-    append(", fetchedBranches=")
-    append(fetchedBranches.sorted())
-    append(", fetchHeadCount=")
-    append(fetchHeadCount)
-    append(", pushedBranches=")
-    append(pushedBranches.sorted())
-    append(", pushedTags=")
-    append(pushedTags.sorted())
-    append(", stashes=")
-    append(stashes)
-    append(", submodules=")
-    append(submodules.toSortedMap())
-    append(", maintenanceActions=")
-    append(maintenanceActions.sorted())
-    append(", config=")
-    append(config.toSortedMap())
-    append(", files=")
-    append(files.map { file -> "${file.name}(staged=${file.staged},tracked=${file.tracked})" }.sorted())
-    append(", commits=")
-    append(commits.map { it.id to it.message })
-}