From 60dd3c82f71b99622e9da7006ed0bdf6025c978a Mon Sep 17 00:00:00 2001 From: Joe Tretter Date: Thu, 25 Jun 2026 13:53:51 -0500 Subject: [PATCH] Add runtime diagnostic logging for level setup, native Git calls, inspection, validation, and UI command flow --- README.md | 9 +++ app/build.gradle.kts | 4 +- .../solutions/tretter/githugandroid/AppLog.kt | 44 ++++++++++++++- .../tretter/githugandroid/GitHugApp.kt | 56 ++++++++++++++++++- .../tretter/githugandroid/GitProcessRunner.kt | 48 +++++++++++++--- .../githugandroid/GitRepositoryInspector.kt | 28 +++++++++- .../tretter/githugandroid/GitRuntime.kt | 41 +++++++++++++- .../githugandroid/levels/LevelCatalog.kt | 38 +------------ 8 files changed, 215 insertions(+), 53 deletions(-) diff --git a/README.md b/README.md index c0d3dd8..6f1f482 100644 --- a/README.md +++ b/README.md @@ -81,6 +81,15 @@ Test outputs and logs are written under project-local build directories: - Per-test emulator logcat files: `app/build/outputs/androidTest-results/connected/debug//logcat-*.txt` - Emulator startup log: `build/reports/android-emulator.log` +Runtime diagnostics are emitted to Android logcat with the `GitHugAndroid` tag. To capture a focused trace from a device or emulator: + +```bash +android-sdk/platform-tools/adb logcat -c +android-sdk/platform-tools/adb logcat -v time -s GitHugAndroid:D '*:S' +``` + +The trace includes level loading and preparation timings, native Git argv/cwd/exit/output previews, repository inspection timings, validation snapshots, and the final app decision for each submitted command. For level-resolution issues, compare the `GitRuntime`, `GitProcess`, `GitInspector`, `Validation`, and `GitHugApp` lines around the submitted command. + To build installable/debuggable artifacts: ```bash diff --git a/app/build.gradle.kts b/app/build.gradle.kts index 6a8a27d..ef4dd2f 100644 --- 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 diff --git a/app/src/main/java/solutions/tretter/githugandroid/AppLog.kt b/app/src/main/java/solutions/tretter/githugandroid/AppLog.kt index a38ed0a..66deea5 100644 --- 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) } -} \ No newline at end of file +} + +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})" + }) +} diff --git a/app/src/main/java/solutions/tretter/githugandroid/GitHugApp.kt b/app/src/main/java/solutions/tretter/githugandroid/GitHugApp.kt index ceabecb..05b2715 100644 --- 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, 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() { diff --git a/app/src/main/java/solutions/tretter/githugandroid/GitProcessRunner.kt b/app/src/main/java/solutions/tretter/githugandroid/GitProcessRunner.kt index dce7d89..653722b 100644 --- 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, environment: Map = 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): ProcessExecutionResult { @@ -84,15 +100,14 @@ internal class GitProcessRunner( binary: File, workingDir: File, arguments: List, - extraEnvironment: Map = emptyMap(), + environment: Map, ): 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 = + (listOf("git") + arguments).joinToString(" ") { argument -> + if (argument.any { it.isWhitespace() || it == '"' || it == '\'' }) { + "'" + argument.replace("'", "'\\''") + "'" + } else { + argument + } + } + + private fun formatOutputPreview(lines: List): 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( diff --git a/app/src/main/java/solutions/tretter/githugandroid/GitRepositoryInspector.kt b/app/src/main/java/solutions/tretter/githugandroid/GitRepositoryInspector.kt index e8d3372..951873d 100644 --- 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, Map) -> ProcessExecutionResult, ) { fun inspectConfig(sandbox: File, currentDir: String = "."): Map { + 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 ?: ""}", + ) 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( diff --git a/app/src/main/java/solutions/tretter/githugandroid/GitRuntime.kt b/app/src/main/java/solutions/tretter/githugandroid/GitRuntime.kt index dd21424..e564bf2 100644 --- 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> { - 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 } diff --git a/app/src/main/java/solutions/tretter/githugandroid/levels/LevelCatalog.kt b/app/src/main/java/solutions/tretter/githugandroid/levels/LevelCatalog.kt index 0ac6d20..42158e4 100644 --- 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 }) -}