From 7318eaba8d8f1961366b05a231fd4631a7c6f05d Mon Sep 17 00:00:00 2001 From: Widthdom Date: Sun, 24 May 2026 22:18:24 +0900 Subject: [PATCH] Add query trace logging for #1901 --- README.md | 8 + changelog.d/unreleased/1901.added.md | 18 ++ src/CodeIndex/Cli/CliFlagSchema.cs | 2 + src/CodeIndex/Cli/ProgramRunner.cs | 294 ++++++++++++++++++++ tests/CodeIndex.Tests/ProgramRunnerTests.cs | 79 ++++++ 5 files changed, 401 insertions(+) create mode 100644 changelog.d/unreleased/1901.added.md diff --git a/README.md b/README.md index ab2e378ae8..762c33143a 100644 --- a/README.md +++ b/README.md @@ -131,6 +131,10 @@ file completion. - Read commands accept `--profile` to append SQL timing, row-count, and `EXPLAIN QUERY PLAN` JSON after the normal result; `--slow-query-ms ` logs profiled SQL statements that meet the threshold. +- Read commands also accept `--trace=stderr|file|none` (default `none`) to emit + one structured JSON trace line with sanitized parameters, elapsed time, + result count when available, exit code, and error status. `file` writes daily + `query-trace-YYYYMMDD.jsonl` files next to the persistent lifecycle log. - `cdidx diff ` compares two index databases for CI or drift debugging, reporting schema, file, symbol, and reference deltas with stable exit codes: `0` identical, `1` drift, `2` schema mismatch, `3` unreadable DB. @@ -340,6 +344,10 @@ POSIX 環境では、persistent global tool stderr log は開くたびに所有 - read 系コマンドは `--profile` で通常結果の後に SQL の時間、行数、 `EXPLAIN QUERY PLAN` の JSON を追加できます。`--slow-query-ms ` は 閾値以上の profiled SQL をログに記録します。 +- read 系コマンドは `--trace=stderr|file|none`（既定は `none`）も受け付け、 + sanitise 済みパラメータ、経過時間、取得可能な場合の result count、exit code、 + error 状態を含む構造化 JSON trace を 1 行出力できます。`file` は persistent + lifecycle log と同じ場所に日次 `query-trace-YYYYMMDD.jsonl` を書きます。 - `cdidx diff ` は CI や drift 調査向けに 2 つの index DB を比較し、 schema、file、symbol、reference の差分を報告します。exit code は `0` identical、 `1` drift、`2` schema mismatch、`3` unreadable DB です。 diff --git a/changelog.d/unreleased/1901.added.md b/changelog.d/unreleased/1901.added.md new file mode 100644 index 0000000000..c7ada070d1 --- /dev/null +++ b/changelog.d/unreleased/1901.added.md @@ -0,0 +1,18 @@ +--- +category: added +issues: + - 1901 +affected: + - src/CodeIndex/Cli/ProgramRunner.cs + - src/CodeIndex/Cli/CliFlagSchema.cs + - tests/CodeIndex.Tests/ProgramRunnerTests.cs + - README.md +--- + +## English + +- **CLI query commands can emit opt-in structured traces (#1901)** — read-side commands now accept `--trace=stderr|file|none` to write one sanitized JSON trace line with elapsed time, result-count field, exit code, and error status for CI and pipeline diagnostics. + +## 日本語 + +- **CLI query command が opt-in の構造化 trace を出力できるようになりました (#1901)** — read 系コマンドは `--trace=stderr|file|none` を受け付け、CI や pipeline 診断向けに sanitise 済み JSON trace を 1 行出力します。trace には経過時間、result count field、exit code、error 状態が含まれます。 diff --git a/src/CodeIndex/Cli/CliFlagSchema.cs b/src/CodeIndex/Cli/CliFlagSchema.cs index db167b5220..fa7ab96190 100644 --- a/src/CodeIndex/Cli/CliFlagSchema.cs +++ b/src/CodeIndex/Cli/CliFlagSchema.cs @@ -170,6 +170,7 @@ internal static class CliFlagSchema ]; private static readonly string[] VerboseQueryCommands = ProfileCommands; + private static readonly string[] TraceCommands = ProfileCommands; public static IReadOnlyList All { get; } = BuildAll(); @@ -183,6 +184,7 @@ private static IReadOnlyList BuildAll() new() { Name = "--profile", Description = "Emit SQL timing and EXPLAIN QUERY PLAN profile JSON after the normal result", Commands = Set(ProfileCommands) }, new() { Name = "--verbose", Description = "Emit query debug diagnostics to stderr, or _debug JSON when combined with --json", Commands = Set(VerboseQueryCommands.Concat(new[] { "index" }).ToArray()) }, new() { Name = "--slow-query-ms", ValuePlaceholder = "", Description = "Log profiled SQL statements at or above this millisecond threshold", Commands = Set(ProfileCommands) }, + new() { Name = "--trace", ValuePlaceholder = "", Description = "Emit one structured JSON query trace line to stderr or a daily log file", Commands = Set(TraceCommands) }, new() { Name = "--limit", ValuePlaceholder = "", Description = "Max results", Commands = Set(LimitCapableCommands) }, new() { Name = "--top", ValuePlaceholder = "", Description = "Max results", Commands = Set(LimitCapableCommands) }, new() { Name = "--lang", ValuePlaceholder = "", Description = "Filter by language", Commands = Set(LangCapableCommands) }, diff --git a/src/CodeIndex/Cli/ProgramRunner.cs b/src/CodeIndex/Cli/ProgramRunner.cs index bad92cfacb..af738ed894 100644 --- a/src/CodeIndex/Cli/ProgramRunner.cs +++ b/src/CodeIndex/Cli/ProgramRunner.cs @@ -1,7 +1,9 @@ using System.Diagnostics; using System.Globalization; using System.Net; +using System.Text; using System.Text.Json; +using System.Text.Json.Nodes; using System.Text.Json.Serialization; using CodeIndex.Database; using CodeIndex.Mcp; @@ -178,9 +180,19 @@ internal static int Run( int exitCode; if (queryRunner is not null) { + if (!TryConsumeQueryTraceFlag(ref subArgs, out var traceMode, out var traceError)) + { + CommandErrorWriter.Write(StripErrorPrefix(traceError), "use one of `none`, `stderr`, or `file`."); + GlobalToolLog.Info($"command_complete exit_code={CommandExitCodes.InvalidArgument} command={commandName} trace_flag_invalid=true"); + EmitCommandMetric(commandName, args, commandStartTimestamp, commandStopwatch, CommandExitCodes.InvalidArgument); + return CommandExitCodes.InvalidArgument; + } + + using var traceCapture = QueryTraceOutputCapture.TryStart(traceMode, subArgs); exitCode = JsonEnvelopeWrapper.ShouldWrap(commandName, subArgs) ? JsonEnvelopeWrapper.RunWrapped(commandName, subArgs, appVersion, jsonOptions, queryRunner) : queryRunner(subArgs); + EmitQueryTrace(traceMode, commandName, subArgs, commandStartTimestamp, commandStopwatch, exitCode, traceCapture?.ResultCount); } else { @@ -529,6 +541,288 @@ internal static bool TryConsumeMetricsFlag(ref string[] args, out string? path, return true; } + internal static bool TryConsumeQueryTraceFlag(ref string[] args, out string traceMode, out string error) + { + traceMode = "none"; + error = string.Empty; + if (args.Length == 0) + return true; + + var kept = new List(args.Length); + var passthrough = false; + for (var i = 0; i < args.Length; i++) + { + var arg = args[i]; + if (passthrough) + { + kept.Add(arg); + continue; + } + if (arg == "--") + { + passthrough = true; + kept.Add(arg); + continue; + } + + string? rawValue = null; + if (arg == "--trace") + { + if (i + 1 >= args.Length) + { + error = "Error: --trace requires a value (use `--trace stderr`, `--trace file`, `--trace none`, or `--trace=`)."; + return false; + } + rawValue = args[++i]; + } + else if (arg.StartsWith("--trace=", StringComparison.Ordinal)) + { + rawValue = arg.Substring("--trace=".Length); + } + else + { + kept.Add(arg); + continue; + } + + if (string.IsNullOrWhiteSpace(rawValue)) + { + error = "Error: --trace requires a non-empty value."; + return false; + } + if (rawValue is not ("none" or "stderr" or "file")) + { + error = $"Error: --trace must be one of `none`, `stderr`, or `file`, got `{rawValue}`."; + return false; + } + traceMode = rawValue; + } + + args = kept.ToArray(); + return true; + } + + private static void EmitQueryTrace(string mode, string commandName, string[] subArgs, DateTimeOffset startTimestamp, Stopwatch stopwatch, int exitCode, int? resultCount) + { + if (mode == "none") + return; + + try + { + var elapsedMs = stopwatch.Elapsed.TotalMilliseconds; + var payload = BuildQueryTraceJson(commandName, subArgs, startTimestamp, elapsedMs, exitCode, resultCount); + if (mode == "stderr") + { + Console.Error.WriteLine(payload); + return; + } + + var directory = GlobalToolLog.ResolveLogDirectoryForStatus(); + Directory.CreateDirectory(directory); + var path = Path.Combine(directory, $"query-trace-{DateTime.UtcNow:yyyyMMdd}.jsonl"); + File.AppendAllText(path, payload + Environment.NewLine); + } + catch + { + // Best-effort only: trace output must never change query command behavior. + } + } + + private static string BuildQueryTraceJson(string commandName, string[] subArgs, DateTimeOffset timestamp, double elapsedMs, int exitCode, int? resultCount) + { + var payload = new JsonObject + { + ["timestamp"] = timestamp.ToString("O", CultureInfo.InvariantCulture), + ["tool"] = commandName, + ["source"] = "cli_query", + ["parameters"] = BuildQueryTraceParameters(subArgs), + ["elapsed_ms"] = Math.Round(elapsedMs, 3), + ["result_count"] = resultCount, + ["exit_code"] = exitCode, + }; + if (exitCode != CommandExitCodes.Success) + payload["error"] = "command_failed"; + return payload.ToJsonString(CreateDefaultJsonOptions()); + } + + private static JsonObject BuildQueryTraceParameters(string[] args) + { + var parameters = new JsonObject + { + ["json"] = false, + ["count"] = false, + }; + var paths = new List(); + var excludePaths = new List(); + var passthrough = false; + for (var i = 0; i < args.Length; i++) + { + var arg = args[i]; + if (passthrough) + continue; + if (arg == "--") + { + passthrough = true; + continue; + } + + string? inlineValue = null; + var optionName = arg; + var equals = arg.IndexOf('='); + if (equals > 0) + { + optionName = arg[..equals]; + inlineValue = arg[(equals + 1)..]; + } + + string? value = inlineValue; + if (value == null && optionName is "--lang" or "--limit" or "--top" or "--path" or "--exclude-path") + { + if (i + 1 < args.Length) + value = args[++i]; + } + + switch (optionName) + { + case "--json": + parameters["json"] = true; + if (!string.IsNullOrWhiteSpace(value)) + parameters["json_format"] = value; + break; + case "--count": + parameters["count"] = true; + break; + case "--lang" when !string.IsNullOrWhiteSpace(value): + parameters["lang"] = value; + break; + case "--limit" when !string.IsNullOrWhiteSpace(value): + case "--top" when !string.IsNullOrWhiteSpace(value): + parameters["limit"] = value; + break; + case "--path" when !string.IsNullOrWhiteSpace(value): + paths.Add(value); + break; + case "--exclude-path" when !string.IsNullOrWhiteSpace(value): + excludePaths.Add(value); + break; + } + } + if (paths.Count > 0) + parameters["path"] = new JsonArray(paths.Select(path => JsonValue.Create(path)).ToArray()); + if (excludePaths.Count > 0) + parameters["exclude_path"] = new JsonArray(excludePaths.Select(path => JsonValue.Create(path)).ToArray()); + return parameters; + } + + private sealed class QueryTraceOutputCapture : TextWriter + { + private readonly TextWriter _inner; + private readonly bool _countNumericOutput; + private readonly bool _countJsonLines; + private bool _disposed; + + private QueryTraceOutputCapture(TextWriter inner, bool countNumericOutput, bool countJsonLines) + { + _inner = inner; + _countNumericOutput = countNumericOutput; + _countJsonLines = countJsonLines; + } + + public override Encoding Encoding => _inner.Encoding; + public int? ResultCount { get; private set; } + + public static QueryTraceOutputCapture? TryStart(string traceMode, string[] args) + { + if (traceMode == "none") + return null; + + var capture = new QueryTraceOutputCapture( + Console.Out, + HasFlag(args, "--count"), + HasFlag(args, "--json") && !HasInlineValue(args, "--json", "array")); + Console.SetOut(capture); + return capture; + } + + public override void Write(char value) => _inner.Write(value); + public override void Write(string? value) => _inner.Write(value); + + public override void WriteLine(string? value) + { + _inner.WriteLine(value); + ObserveLine(value); + } + + public override void WriteLine() + { + _inner.WriteLine(); + ObserveLine(string.Empty); + } + + protected override void Dispose(bool disposing) + { + if (!_disposed && disposing) + { + Console.SetOut(_inner); + _disposed = true; + } + base.Dispose(disposing); + } + + private void ObserveLine(string? value) + { + if (value == null) + return; + + var trimmed = value.Trim(); + if (_countNumericOutput && int.TryParse(trimmed, NumberStyles.Integer, CultureInfo.InvariantCulture, out var count) && count >= 0) + { + ResultCount = count; + return; + } + + if (_countJsonLines && trimmed.StartsWith('{')) + ResultCount = (ResultCount ?? 0) + 1; + } + + private static bool HasFlag(string[] args, string name) + { + var passthrough = false; + foreach (var arg in args) + { + if (passthrough) + continue; + if (arg == "--") + { + passthrough = true; + continue; + } + if (arg == name || arg.StartsWith(name + "=", StringComparison.Ordinal)) + return true; + } + return false; + } + + private static bool HasInlineValue(string[] args, string name, string value) + { + var expected = name + "=" + value; + var passthrough = false; + foreach (var arg in args) + { + if (passthrough) + continue; + if (arg == "--") + { + passthrough = true; + continue; + } + if (arg == expected) + return true; + } + return false; + } + } + internal static void EmitCommandMetric(string tool, string[] args, DateTimeOffset startTimestamp, Stopwatch stopwatch, int exitCode, string? error = null) { if (!MetricsSink.IsActive) diff --git a/tests/CodeIndex.Tests/ProgramRunnerTests.cs b/tests/CodeIndex.Tests/ProgramRunnerTests.cs index 8bc518dec6..509c967019 100644 --- a/tests/CodeIndex.Tests/ProgramRunnerTests.cs +++ b/tests/CodeIndex.Tests/ProgramRunnerTests.cs @@ -10,6 +10,85 @@ namespace CodeIndex.Tests; [Collection("SQLite pool sensitive")] public class ProgramRunnerTests { + [Fact] + public void TryConsumeQueryTraceFlag_StripsTraceAndPreservesEscapedQuery() + { + string[] args = ["needle", "--trace=stderr", "--lang", "csharp", "--", "--trace=file"]; + + var ok = ProgramRunner.TryConsumeQueryTraceFlag(ref args, out var mode, out var error); + + Assert.True(ok); + Assert.Empty(error); + Assert.Equal("stderr", mode); + Assert.Equal(["needle", "--lang", "csharp", "--", "--trace=file"], args); + } + + [Fact] + public void Run_QueryTraceStderr_EmitsStructuredSanitizedLine() + { + var projectRoot = TestProjectHelper.CreateTempProject("query-trace"); + try + { + var dbPath = TestProjectHelper.CreateProjectDb(projectRoot); + TestProjectHelper.InsertIndexedFile(dbPath, "src/app.cs", "csharp", "public class App { public void Needle() { } }"); + + var (exitCode, stdout, stderr) = CaptureConsole(() => ProgramRunner.Run( + ["search", "Needle", "--db", dbPath, "--trace=stderr", "--count", "--lang", "csharp", "--limit", "7", "--path", "src/**"], + appVersion: "1.10.0")); + + Assert.Equal(CommandExitCodes.Success, exitCode); + Assert.Equal("1", stdout.Trim()); + var traceLine = stderr.Split(Environment.NewLine, StringSplitOptions.RemoveEmptyEntries).Single(line => line.StartsWith('{')); + using var document = JsonDocument.Parse(traceLine); + var root = document.RootElement; + Assert.Equal("search", root.GetProperty("tool").GetString()); + Assert.Equal("cli_query", root.GetProperty("source").GetString()); + Assert.Equal(1, root.GetProperty("result_count").GetInt32()); + Assert.Equal(0, root.GetProperty("exit_code").GetInt32()); + Assert.Equal("csharp", root.GetProperty("parameters").GetProperty("lang").GetString()); + Assert.Equal("7", root.GetProperty("parameters").GetProperty("limit").GetString()); + Assert.Contains("src/**", root.GetProperty("parameters").GetProperty("path")[0].GetString()); + Assert.DoesNotContain("Needle", traceLine); + Assert.DoesNotContain(dbPath, traceLine); + } + finally + { + TestProjectHelper.DeleteDirectory(projectRoot); + } + } + + [Fact] + public void Run_QueryTraceFile_AppendsDailyJsonl() + { + var projectRoot = TestProjectHelper.CreateTempProject("query-trace-file"); + var logRoot = Path.Combine(Path.GetTempPath(), $"cdidx_query_trace_{Guid.NewGuid():N}"); + try + { + var dbPath = TestProjectHelper.CreateProjectDb(projectRoot); + TestProjectHelper.InsertIndexedFile(dbPath, "src/app.cs", "csharp", "public class App { public void Needle() { } }"); + using var env = EnvironmentVariableScope.Capture("CDIDX_GLOBAL_TOOL_LOG_DIR"); + env.Set("CDIDX_GLOBAL_TOOL_LOG_DIR", logRoot); + + var (exitCode, _, stderr) = CaptureConsole(() => ProgramRunner.Run( + ["search", "Needle", "--db", dbPath, "--trace=file"], + appVersion: "1.10.0")); + + Assert.Equal(CommandExitCodes.Success, exitCode); + Assert.DoesNotContain('{', stderr); + var tracePath = Path.Combine(logRoot, $"query-trace-{DateTime.UtcNow:yyyyMMdd}.jsonl"); + Assert.True(File.Exists(tracePath)); + var line = File.ReadAllLines(tracePath).Single(); + using var document = JsonDocument.Parse(line); + Assert.Equal("search", document.RootElement.GetProperty("tool").GetString()); + } + finally + { + TestProjectHelper.DeleteDirectory(projectRoot); + if (Directory.Exists(logRoot)) + Directory.Delete(logRoot, recursive: true); + } + } + [Fact] public void TryConsumeSuggestionDedupThresholdFlag_SetsEnvironmentAndRemovesFlag() {