From fcb4b3fd816e1ab2f75f12f1e13d7971cdfdf5a5 Mon Sep 17 00:00:00 2001 From: Waldek Mastykarz Date: Wed, 21 Oct 2026 16:03:59 +0200 Subject: [PATCH 1/4] Fix logs --since and /proxy/logs?since= to filter by date and time. Closes #1961 Detached log lines don't start with a [hh:mm:ss.fff] timestamp, so the previous filter matched no lines, included all of them and ignored the date. Reconstruct each line's full date and time from the instance start time, request blocks' 'time' lines, debug/trace time-of-day prefixes (with midnight rollover) and JSON 'timestamp' properties, and filter on that. The log line format is unchanged. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: 3b2ff54c-c6ab-4c98-a477-c522a6c02ac2 --- DevProxy.Tests/LogSinceFilterTests.cs | 143 +++++++++++++++ DevProxy/ApiControllers/ProxyController.cs | 29 +--- DevProxy/Commands/LogsCommand.cs | 48 ++---- DevProxy/Logging/LogSinceFilter.cs | 192 +++++++++++++++++++++ 4 files changed, 351 insertions(+), 61 deletions(-) create mode 100644 DevProxy.Tests/LogSinceFilterTests.cs create mode 100644 DevProxy/Logging/LogSinceFilter.cs diff --git a/DevProxy.Tests/LogSinceFilterTests.cs b/DevProxy.Tests/LogSinceFilterTests.cs new file mode 100644 index 000000000..a82be854e --- /dev/null +++ b/DevProxy.Tests/LogSinceFilterTests.cs @@ -0,0 +1,143 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using DevProxy.Logging; + +using Xunit; + +namespace DevProxy.Tests; + +public class LogSinceFilterTests +{ + private static readonly DateTime _start = new(2026, 10, 19, 22, 0, 0, DateTimeKind.Local); + + private static string TimeLine(DateTime localTime) => + $" time \u2502 {new DateTimeOffset(localTime).ToUniversalTime():O}"; + + private static string[] RequestBlock(string url, DateTime localTime) => + [ + "", + $" req \u256d GET {url}", + TimeLine(localTime), + " skip \u2502 RetryAfterPlugin: Request not throttled", + " pass \u2570 Passed through", + ]; + + [Fact] + public void Filter_RequestsOnPreviousDays_ExcludedBySinceDuration() + { + string[] lines = + [ + " info Dev Proxy listening on 127.0.0.1:8000", + .. RequestBlock("https://example.com/day1", _start.AddMinutes(30)), + .. RequestBlock("https://example.com/day2", _start.AddDays(1).AddHours(1)), + .. RequestBlock("https://example.com/day3", _start.AddDays(2).AddHours(1)), + ]; + + var result = LogSinceFilter.Filter(lines, _start, _start.AddDays(2)).ToList(); + + Assert.DoesNotContain(result, l => l.Contains("listening", StringComparison.Ordinal)); + Assert.DoesNotContain(result, l => l.Contains("day1", StringComparison.Ordinal)); + Assert.DoesNotContain(result, l => l.Contains("day2", StringComparison.Ordinal)); + Assert.Equal(RequestBlock("https://example.com/day3", _start.AddDays(2).AddHours(1)), result); + } + + [Fact] + public void Filter_SinceInFuture_ReturnsNoLines() + { + string[] lines = + [ + " info Dev Proxy listening on 127.0.0.1:8000", + .. RequestBlock("https://example.com", _start.AddMinutes(5)), + ]; + + Assert.Empty(LogSinceFilter.Filter(lines, _start, _start.AddYears(1))); + } + + [Fact] + public void Filter_SinceBeforeLogStart_ReturnsAllLines() + { + string[] lines = + [ + " info Dev Proxy listening on 127.0.0.1:8000", + .. RequestBlock("https://example.com", _start.AddMinutes(5)), + ]; + + Assert.Equal(lines, LogSinceFilter.Filter(lines, _start, _start.AddDays(-1))); + } + + [Fact] + public void GetLineTimes_LinesWithoutTimestamp_UseLogStartOrPrecedingTimestamp() + { + string[] lines = + [ + " info Dev Proxy listening on 127.0.0.1:8000", + .. RequestBlock("https://example.com", _start.AddHours(1)), + " info Configuration changed. Restarting...", + ]; + + var times = LogSinceFilter.GetLineTimes(lines, _start); + + Assert.Equal(_start, times[0]); + Assert.All(times[1..], t => Assert.Equal(_start.AddHours(1), t)); + } + + [Fact] + public void GetLineTimes_DebugTimeOfDayAcrossMidnight_RollsOverToNextDay() + { + string[] lines = + [ + " dbug [23:59:59.0000000] ProxyEngine: before midnight", + " dbug [00:00:01.0000000] ProxyEngine: after midnight", + " dbug [00:00:00.9990000] ProxyEngine: written slightly out of order", + " dbug [23:00:00.0000000] ProxyEngine: next evening", + ]; + + var times = LogSinceFilter.GetLineTimes(lines, _start); + + Assert.Equal(_start.Date.AddHours(23).AddMinutes(59).AddSeconds(59), times[0]); + Assert.Equal(_start.Date.AddDays(1).AddSeconds(1), times[1]); + Assert.Equal(_start.Date.AddDays(1).AddMilliseconds(999), times[2]); + Assert.Equal(_start.Date.AddDays(1).AddHours(23), times[3]); + } + + [Fact] + public void GetLineTimes_RequestTimestampJustBeforeMidnight_KeepsPreviousDay() + { + var afterMidnight = _start.Date.AddDays(1).AddMilliseconds(1); + string[] lines = + [ + .. RequestBlock("https://example.com", afterMidnight), + " trce [23:59:59.9990000] ProxyEngine: written slightly out of order", + ]; + + var times = LogSinceFilter.GetLineTimes(lines, _start); + + Assert.Equal(_start.Date.AddDays(1).AddMilliseconds(-1), times[^1]); + } + + [Fact] + public void GetLineTimes_JsonLines_UseTimestampProperty() + { + var timestamp = _start.AddDays(3); + string[] lines = + [ + $$"""{"type":"log","level":"info","message":"hello","timestamp":"{{new DateTimeOffset(timestamp).ToUniversalTime():O}}"}""", + "{not json", + ]; + + var times = LogSinceFilter.GetLineTimes(lines, _start); + + Assert.Equal(timestamp, times[0]); + Assert.Equal(timestamp, times[1]); + } + + [Fact] + public void FilterLines_NoSince_ReturnsAllLines() + { + string[] lines = ["a", "b"]; + + Assert.Equal(lines, Commands.LogsCommand.FilterLines(lines, null, _start)); + } +} diff --git a/DevProxy/ApiControllers/ProxyController.cs b/DevProxy/ApiControllers/ProxyController.cs index 31b55b0c9..3d6504d78 100644 --- a/DevProxy/ApiControllers/ProxyController.cs +++ b/DevProxy/ApiControllers/ProxyController.cs @@ -5,6 +5,7 @@ using DevProxy.Abstractions.Proxy; using DevProxy.Commands; using DevProxy.Jwt; +using DevProxy.Logging; using DevProxy.Proxy; using Microsoft.AspNetCore.Mvc; using System.ComponentModel.DataAnnotations; @@ -246,7 +247,7 @@ private async Task WriteSseEventAsync(string line, bool useJson, CancellationTok await Response.Body.FlushAsync(cancellationToken); } - private static IEnumerable FilterLines(IList lines, string? since) + private static IEnumerable FilterLines(List lines, string? since) { if (string.IsNullOrEmpty(since)) { @@ -259,7 +260,8 @@ private static IEnumerable FilterLines(IList lines, string? sinc return lines; } - return lines.Where(line => LineMatchesSince(line, sinceTime.Value)); + using var process = System.Diagnostics.Process.GetCurrentProcess(); + return LogSinceFilter.Filter(lines, process.StartTime, sinceTime.Value); } private static DateTime? ParseSinceOption(string? since) @@ -295,29 +297,6 @@ private static IEnumerable FilterLines(IList lines, string? sinc return null; } - private static bool LineMatchesSince(string line, DateTime sinceTime) - { - // Parse timestamp from line format: [HH:mm:ss.fff] ... - if (line.Length < 14 || line[0] != '[' || line[13] != ']') - { - return true; - } - - var timestampStr = line[1..13]; - if (TimeSpan.TryParseExact(timestampStr, "hh\\:mm\\:ss\\.fff", System.Globalization.CultureInfo.InvariantCulture, out var timeOfDay)) - { - var lineTime = DateTime.Today.Add(timeOfDay); - if (lineTime > DateTime.Now) - { - lineTime = lineTime.AddDays(-1); - } - - return lineTime >= sinceTime; - } - - return true; - } - private static LogEntryDto ParseLogLine(string line) { // Parse: [HH:mm:ss.fff] level: category: message diff --git a/DevProxy/Commands/LogsCommand.cs b/DevProxy/Commands/LogsCommand.cs index f61228ceb..07111a82a 100644 --- a/DevProxy/Commands/LogsCommand.cs +++ b/DevProxy/Commands/LogsCommand.cs @@ -2,6 +2,7 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. +using DevProxy.Logging; using DevProxy.State; using System.CommandLine; using System.Globalization; @@ -89,11 +90,11 @@ private async Task RunAsync(ParseResult parseResult, CancellationToken canc if (follow) { - await FollowLogFileAsync(logFile, lines, sinceTime, cancellationToken); + await FollowLogFileAsync(logFile, lines, sinceTime, state.StartedAt.LocalDateTime, cancellationToken); } else { - await ShowLastLinesAsync(logFile, lines, sinceTime); + await ShowLastLinesAsync(logFile, lines, sinceTime, state.StartedAt.LocalDateTime); } return 0; @@ -148,7 +149,7 @@ private async Task RunAsync(ParseResult parseResult, CancellationToken canc return null; } - private static async Task ShowLastLinesAsync(string logFile, int lineCount, DateTime? sinceTime) + private static async Task ShowLastLinesAsync(string logFile, int lineCount, DateTime? sinceTime, DateTime logStartTime) { var lines = new List(); await foreach (var line in File.ReadLinesAsync(logFile)) @@ -156,7 +157,7 @@ private static async Task ShowLastLinesAsync(string logFile, int lineCount, Date lines.Add(line); } - var filteredLines = FilterLines(lines, sinceTime); + var filteredLines = FilterLines(lines, sinceTime, logStartTime); var linesToShow = filteredLines.TakeLast(lineCount); foreach (var line in linesToShow) @@ -165,10 +166,10 @@ private static async Task ShowLastLinesAsync(string logFile, int lineCount, Date } } - private static async Task FollowLogFileAsync(string logFile, int initialLines, DateTime? sinceTime, CancellationToken cancellationToken) + private static async Task FollowLogFileAsync(string logFile, int initialLines, DateTime? sinceTime, DateTime logStartTime, CancellationToken cancellationToken) { // Show initial lines - await ShowLastLinesAsync(logFile, initialLines, sinceTime); + await ShowLastLinesAsync(logFile, initialLines, sinceTime, logStartTime); // Follow new lines using FileSystemWatcher and reading from last position var lastPosition = new FileInfo(logFile).Length; @@ -214,7 +215,8 @@ private static async Task FollowLogFileAsync(string logFile, int initialLines, D string? line; while ((line = await reader.ReadLineAsync(cancellationToken)) != null) { - if (sinceTime == null || LineMatchesSince(line, sinceTime.Value)) + // New lines are written now + if (sinceTime == null || DateTime.Now >= sinceTime.Value) { Console.WriteLine(line); } @@ -231,39 +233,13 @@ private static async Task FollowLogFileAsync(string logFile, int initialLines, D } } - private static IEnumerable FilterLines(IEnumerable lines, DateTime? sinceTime) + internal static IEnumerable FilterLines(IReadOnlyList lines, DateTime? sinceTime, DateTime logStartTime) { if (sinceTime == null) { return lines; } - return lines.Where(line => LineMatchesSince(line, sinceTime.Value)); + return LogSinceFilter.Filter(lines, logStartTime, sinceTime.Value); } - - private static bool LineMatchesSince(string line, DateTime sinceTime) - { - // Parse timestamp from line format: [HH:mm:ss.fff] ... - if (line.Length < 14 || line[0] != '[' || line[13] != ']') - { - return true; // Include lines that don't match the expected format - } - - var timestampStr = line[1..13]; // "HH:mm:ss.fff" - if (TimeSpan.TryParseExact(timestampStr, "hh\\:mm\\:ss\\.fff", CultureInfo.InvariantCulture, out var timeOfDay)) - { - // Assume the log is from today - var lineTime = DateTime.Today.Add(timeOfDay); - - // If line time is in the future, assume it's from yesterday - if (lineTime > DateTime.Now) - { - lineTime = lineTime.AddDays(-1); - } - - return lineTime >= sinceTime; - } - - return true; // Include lines with unparseable timestamps - } -} \ No newline at end of file +} diff --git a/DevProxy/Logging/LogSinceFilter.cs b/DevProxy/Logging/LogSinceFilter.cs new file mode 100644 index 000000000..d5e150809 --- /dev/null +++ b/DevProxy/Logging/LogSinceFilter.cs @@ -0,0 +1,192 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System.Globalization; +using System.Text.Json; +using System.Text.RegularExpressions; + +namespace DevProxy.Logging; + +/// +/// Filters Dev Proxy log lines by date and time. Most log lines don't carry +/// a timestamp, so each line's time is reconstructed from the log start time +/// and the timestamps that the log does contain: request blocks' +/// time lines (full ISO date), time-of-day prefixes on debug/trace +/// messages and the timestamp property of JSON log lines. A line +/// without a timestamp is assigned the most recent preceding timestamp. +/// +internal static partial class LogSinceFilter +{ + private static readonly TimeSpan _outOfOrderTolerance = TimeSpan.FromMinutes(1); + + public static IEnumerable Filter(IReadOnlyList lines, DateTime logStartTime, DateTime sinceTime) + { + var lineTimes = GetLineTimes(lines, logStartTime); + for (var i = 0; i < lines.Count; i++) + { + if (lineTimes[i] >= sinceTime) + { + yield return lines[i]; + } + } + } + + internal static DateTime[] GetLineTimes(IReadOnlyList lines, DateTime logStartTime) + { + var times = new DateTime[lines.Count]; + var current = logStartTime; + + var i = 0; + while (i < lines.Count) + { + if (RequestStartRegex().IsMatch(lines[i])) + { + // Request blocks are written at once and their timestamp is on + // the 'time' line inside the block, so apply it to the whole block + var blockEnd = FindRequestBlockEnd(lines, i); + for (var j = i; j <= blockEnd; j++) + { + if (TryGetTimestamp(lines[j], current, out var blockTime)) + { + current = blockTime; + break; + } + } + + // The empty line preceding a request block belongs to it + if (i > 0 && string.IsNullOrWhiteSpace(lines[i - 1])) + { + times[i - 1] = current; + } + + for (var j = i; j <= blockEnd; j++) + { + times[j] = current; + } + + i = blockEnd + 1; + continue; + } + + if (TryGetTimestamp(lines[i], current, out var lineTime)) + { + current = lineTime; + } + + times[i] = current; + i++; + } + + return times; + } + + private static int FindRequestBlockEnd(IReadOnlyList lines, int start) + { + if (RequestEndRegex().IsMatch(lines[start])) + { + return start; + } + + for (var i = start + 1; i < lines.Count; i++) + { + if (RequestStartRegex().IsMatch(lines[i])) + { + return i - 1; + } + + if (RequestEndRegex().IsMatch(lines[i])) + { + return i; + } + } + + return lines.Count - 1; + } + + private static bool TryGetTimestamp(string line, DateTime current, out DateTime timestamp) + { + timestamp = default; + + var match = FullTimestampRegex().Match(line); + if (match.Success && + DateTimeOffset.TryParse(match.Groups["timestamp"].Value, CultureInfo.InvariantCulture, DateTimeStyles.None, out var dateTimeOffset)) + { + timestamp = dateTimeOffset.LocalDateTime; + return true; + } + + match = TimeOfDayRegex().Match(line); + if (match.Success && + TimeSpan.TryParseExact(match.Groups["time"].Value, ["hh\\:mm\\:ss\\.fffffff", "hh\\:mm\\:ss\\.fff"], CultureInfo.InvariantCulture, out var timeOfDay)) + { + timestamp = ResolveTimeOfDay(timeOfDay, current); + return true; + } + + return TryGetJsonTimestamp(line, out timestamp); + } + + private static DateTime ResolveTimeOfDay(TimeSpan timeOfDay, DateTime current) + { + var candidate = current.Date.Add(timeOfDay); + + // Log lines are written in order, so a time of day earlier than the + // previous timestamp means the log crossed midnight. Allow for small + // differences caused by concurrent writes. + if (candidate < current - _outOfOrderTolerance) + { + candidate = candidate.AddDays(1); + } + else if (candidate - current > TimeSpan.FromDays(1) - _outOfOrderTolerance) + { + candidate = candidate.AddDays(-1); + } + + return candidate; + } + + private static bool TryGetJsonTimestamp(string line, out DateTime timestamp) + { + timestamp = default; + + var trimmed = line.AsSpan().TrimStart(); + if (trimmed.IsEmpty || trimmed[0] != '{') + { + return false; + } + + try + { + using var document = JsonDocument.Parse(line); + if (document.RootElement.ValueKind == JsonValueKind.Object && + document.RootElement.TryGetProperty("timestamp", out var property) && + property.ValueKind == JsonValueKind.String && + DateTimeOffset.TryParse(property.GetString(), CultureInfo.InvariantCulture, DateTimeStyles.None, out var dateTimeOffset)) + { + timestamp = dateTimeOffset.LocalDateTime; + return true; + } + } + catch (JsonException) + { + } + + return false; + } + + // Optional ANSI escape sequences around labels, in case colored output was captured + private const string Ansi = @"(?:\x1b\[[0-9;]*m)*"; + + [GeneratedRegex(@"^\s*" + Ansi + @"\s*req\s*" + Ansi + @"\s*\u256d")] + private static partial Regex RequestStartRegex(); + + [GeneratedRegex(@"^\s*" + Ansi + @"\s*\S+\s*" + Ansi + @"\s*\u2570")] + private static partial Regex RequestEndRegex(); + + [GeneratedRegex(@"^\s*" + Ansi + @"\s*time\s*" + Ansi + @"\s*[\u2502\u2570]\s*(?\d{4}-\d{2}-\d{2}T\S+)\s*$")] + private static partial Regex FullTimestampRegex(); + + [GeneratedRegex(@"^(?:\s*" + Ansi + @"\s*(?:dbug|trce)\s*" + Ansi + @"\s*)?\[(?