diff --git a/DevProxy.Tests/LogSinceFilterTests.cs b/DevProxy.Tests/LogSinceFilterTests.cs new file mode 100644 index 000000000..3ed266139 --- /dev/null +++ b/DevProxy.Tests/LogSinceFilterTests.cs @@ -0,0 +1,395 @@ +// 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.Abstractions.Proxy; +using DevProxy.Logging; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Options; +using System.Globalization; + +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(DateTimeOffset timestamp) => + $" time \u2502 {timestamp:O}"; + + private static string[] RequestBlock(string url, DateTimeOffset timestamp) => + [ + "", + $" req \u256d GET {url}", + TimeLine(timestamp), + " skip \u2502 RetryAfterPlugin: Request not throttled", + " pass \u2570 Passed through", + ]; + + private static string[] RequestBlockWithNormalTerminator(DateTimeOffset timestamp) + { + var formatter = new ProxyConsoleFormatter(Options.Create(new ProxyConsoleFormatterOptions { IncludeScopes = true })); + var scopeProvider = new LoggerExternalScopeProvider(); + using var scope = scopeProvider.Push(new Dictionary { ["requestId"] = 1 }); + using var writer = new StringWriter(CultureInfo.InvariantCulture); + + Write("GET https://example.com", MessageType.InterceptedRequest); + Write(timestamp.ToString("O", CultureInfo.InvariantCulture), MessageType.Timestamp); + Write("done", MessageType.Normal, "Plugin"); + Write(string.Empty, MessageType.FinishedProcessingRequest); + + return writer.ToString().Replace("\r", string.Empty, StringComparison.Ordinal).Split('\n')[..^1]; + + void Write(string message, MessageType type, string category = ProxyConsoleFormatter.DefaultCategoryName) + { + var log = new RequestLog(message, type, context: null); + var entry = new LogEntry(LogLevel.Information, category, new EventId(0), log, null, (state, _) => state.Message); + formatter.Write(entry, scopeProvider, writer); + } + } + + [Fact] + public void Filter_NormalMessageTerminator_DoesNotMisdateFollowingMessages() + { + var request = RequestBlockWithNormalTerminator(_start.AddMinutes(5)); + var laterTime = new DateTimeOffset(_start.AddHours(2)); + var laterMessage = $" info [{laterTime:O}] Later message"; + string[] lines = [.. request, laterMessage, "Continuation of later message"]; + + Assert.Equal(" \u2570 Plugin: done", request[^1]); + Assert.Equal([laterMessage, "Continuation of later message"], + LogSinceFilter.Filter(lines, _start, _start.AddHours(1))); + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public async Task ReadLinesAsync_NormalMessageTerminator_EmitsCompletedBlockImmediately(bool ansi) + { + var request = RequestBlockWithNormalTerminator(_start.AddMinutes(5)); + if (ansi) + { + request[^1] = "\u001b[39;49m \u001b[0m \u2570 Plugin: done"; + } + + var path = Path.GetTempFileName(); + try + { + using var reader = new LogFileReader(path, _start, _start.AddMinutes(1)); + await File.WriteAllTextAsync(path, string.Join('\n', request[..^1]) + "\n"); + Assert.Empty(await reader.ReadLinesAsync(CancellationToken.None)); + + await File.AppendAllTextAsync(path, request[^1] + "\n"); + Assert.Equal(request, await reader.ReadLinesAsync(CancellationToken.None)); + + var later = $" info [{new DateTimeOffset(_start.AddHours(2)):O}] Independent message"; + await File.AppendAllTextAsync(path, later + "\n"); + Assert.Equal([later], await reader.ReadLinesAsync(CancellationToken.None)); + } + finally + { + File.Delete(path); + } + } + + [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]); + } + + [Theory] + [InlineData("America/New_York", 11, 1, 1, 0)] + [InlineData("Europe/Berlin", 10, 25, 2, 0)] + [InlineData("Australia/Lord_Howe", 4, 5, 1, 30)] + public void ResolveTimeOfDay_DaylightSavingRollback_KeepsSameDate(string zoneId, int month, int day, int hour, int minute) + { + var timeZone = TimeZoneInfo.FindSystemTimeZoneById(zoneId); + var current = new DateTime(2026, month, day, hour, 59, 59); + var timeOfDay = new TimeSpan(hour, minute, 1); + + var beforeRollback = new DateTimeOffset(current, timeZone.GetAmbiguousTimeOffsets(current).Max()); + var timestamp = LogSinceFilter.ResolveTimeOfDay(timeOfDay, beforeRollback, timeZone); + + var expected = new DateTimeOffset(current.Date.Add(timeOfDay), timeZone.GetAmbiguousTimeOffsets(current).Min()); + Assert.Equal(expected, timestamp); + Assert.True(timestamp > beforeRollback); + } + + [Theory] + [InlineData("request")] + [InlineData("json")] + [InlineData("text")] + public async Task Filter_DaylightSavingRepeatedHour_UsesInstantsInSnapshotsAndFollowers(string format) + { + var beforeRollback = new DateTimeOffset(2026, 11, 1, 1, 50, 0, TimeSpan.FromHours(-4)); + var afterRollback = new DateTimeOffset(2026, 11, 1, 1, 20, 0, TimeSpan.FromHours(-5)); + var cutoff = LogSinceFilter.ParseSinceOption("2026-11-01T01:10:00-05:00")!.Value; + var start = beforeRollback.AddHours(-1); + var oldLines = FormatEntry(beforeRollback, "old"); + var newLines = FormatEntry(afterRollback, "new"); + string[] lines = [.. oldLines, .. newLines]; + + Assert.Equal(TimeSpan.FromHours(-5), cutoff.Offset); + Assert.Equal(newLines, LogSinceFilter.Filter(lines, start, cutoff)); + Assert.Equal(newLines, Commands.LogsCommand.FilterLines(lines, cutoff, start)); + + var path = Path.GetTempFileName(); + try + { + await File.WriteAllTextAsync(path, string.Join('\n', oldLines) + "\n"); + using var reader = new LogFileReader(path, start, cutoff); + Assert.Empty(await reader.ReadLinesAsync(CancellationToken.None)); + + await File.AppendAllTextAsync(path, string.Join('\n', newLines) + "\n"); + Assert.Equal(newLines, await reader.ReadLinesAsync(CancellationToken.None)); + } + finally + { + File.Delete(path); + } + + string[] FormatEntry(DateTimeOffset timestamp, string message) => format switch + { + "request" => RequestBlock($"https://example.com/{message}", timestamp), + "json" => [$$"""{"timestamp":"{{timestamp:O}}","message":"{{message}}"}"""], + _ => [$" warn [{timestamp:O}] {message}"] + }; + } + + [Theory] + [InlineData("2026-11-01T01:50:00-04:00", "2026-11-01T01:10:00-05:00", false)] + [InlineData("2026-11-01T01:10:00-05:00", "2026-11-01T01:50:00-04:00", true)] + public void Filter_ExplicitOffsetsAcrossRepeatedHour_OrdersByInstant(string eventTime, string since, bool included) + { + var cutoff = LogSinceFilter.ParseSinceOption(since)!.Value; + var line = $$"""{"timestamp":"{{eventTime}}"}"""; + var result = LogSinceFilter.Filter([line], cutoff.AddHours(-2), cutoff); + + Assert.Equal(included ? [line] : Array.Empty(), result); + } + + [Theory] + [InlineData("30s", 30)] + [InlineData("5m", 300)] + [InlineData("1h", 3600)] + [InlineData("2d", 172800)] + public void ParseSinceOption_Duration_UsesElapsedTime(string since, int seconds) + { + var earliest = DateTimeOffset.UtcNow.AddSeconds(-seconds); + var result = LogSinceFilter.ParseSinceOption(since); + var latest = DateTimeOffset.UtcNow.AddSeconds(-seconds); + + Assert.NotNull(result); + Assert.InRange(result.Value, earliest, latest); + } + + [Fact] + public async Task ReadLinesAsync_RequestFinishesAfterCutoff_FiltersByEventTimeAcrossReads() + { + var path = Path.GetTempFileName(); + try + { + var cutoff = _start.AddHours(1); + var oldRequest = RequestBlock("https://example.com/old", cutoff.AddSeconds(-1)); + var newRequest = RequestBlock("https://example.com/new", cutoff); + await File.WriteAllTextAsync(path, string.Join('\n', oldRequest[..2]) + "\n"); + using var reader = new LogFileReader(path, _start, cutoff); + + Assert.Empty(await reader.ReadLinesAsync(CancellationToken.None)); + + await File.AppendAllTextAsync(path, string.Join('\n', oldRequest[2..]) + "\n"); + Assert.Empty(await reader.ReadLinesAsync(CancellationToken.None)); + + await File.AppendAllTextAsync(path, string.Join('\n', newRequest[..3]) + "\n"); + Assert.Empty(await reader.ReadLinesAsync(CancellationToken.None)); + + await File.AppendAllTextAsync(path, string.Join('\n', newRequest[3..]) + "\n"); + Assert.Equal(newRequest, await reader.ReadLinesAsync(CancellationToken.None)); + } + finally + { + File.Delete(path); + } + } + + [Fact] + public async Task ReadLinesAsync_PartialLinesAndMidnight_RetainsReconstructionState() + { + var path = Path.GetTempFileName(); + try + { + var beforeMidnight = " dbug [23:59:59.0000000] before midnight"; + var afterMidnight = " dbug [00:00:01.0000000] after midnight"; + var cutoff = _start.Date.AddDays(1); + await File.WriteAllTextAsync(path, beforeMidnight + "\r\n"); + using var reader = new LogFileReader(path, _start, cutoff); + + Assert.Empty(await reader.ReadLinesAsync(CancellationToken.None)); + + await File.AppendAllTextAsync(path, afterMidnight[..20]); + Assert.Empty(await reader.ReadLinesAsync(CancellationToken.None)); + + await File.AppendAllTextAsync(path, afterMidnight[20..] + "\r\n"); + Assert.Equal([afterMidnight], await reader.ReadLinesAsync(CancellationToken.None)); + Assert.Empty(await reader.ReadLinesAsync(CancellationToken.None)); + } + finally + { + File.Delete(path); + } + } + + [Fact] + public async Task ReadLinesAsync_JsonLines_UsesEventTimeInsteadOfReadTime() + { + var path = Path.GetTempFileName(); + try + { + var cutoff = _start.AddHours(1); + var oldLine = $$"""{"timestamp":"{{new DateTimeOffset(_start):O}}","message":"old"}"""; + var newLine = $$"""{"timestamp":"{{new DateTimeOffset(cutoff):O}}","message":"new"}"""; + using var reader = new LogFileReader(path, _start, cutoff); + + await File.AppendAllTextAsync(path, oldLine + "\n" + newLine + "\n"); + + Assert.Equal([newLine], await reader.ReadLinesAsync(CancellationToken.None)); + } + finally + { + File.Delete(path); + } + } + + [Fact] + public async Task ReadLinesAsync_NoSince_EmitsLinesWithoutWaitingForRequestEnd() + { + var path = Path.GetTempFileName(); + try + { + string[] lines = ["", " req \u256d GET https://example.com", " info hello"]; + await File.WriteAllTextAsync(path, string.Join('\n', lines) + "\n"); + using var reader = new LogFileReader(path, _start, null); + + Assert.Equal(lines, await reader.ReadLinesAsync(CancellationToken.None)); + } + finally + { + File.Delete(path); + } + } + + [Fact] + public void FilterLines_NoSince_ReturnsAllLines() + { + string[] lines = ["a", "b"]; + + Assert.Equal(lines, Commands.LogsCommand.FilterLines(lines, null, _start)); + } +} diff --git a/DevProxy.Tests/LoggingConfigurationTests.cs b/DevProxy.Tests/LoggingConfigurationTests.cs new file mode 100644 index 000000000..f47bb11d2 --- /dev/null +++ b/DevProxy.Tests/LoggingConfigurationTests.cs @@ -0,0 +1,93 @@ +// 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.Commands; +using DevProxy.Logging; +using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Options; +using System.Globalization; + +using Xunit; + +namespace DevProxy.Tests; + +public class LoggingConfigurationTests +{ + [Theory] + [InlineData(false)] + [InlineData(true)] + public void ConfigureDevProxyLogging_Interactive_HonorsShowTimestamps(bool showTimestamps) + { + using var configuration = new ConfigurationManager(); + configuration["showTimestamps"] = showTimestamps.ToString(); + var services = new ServiceCollection(); + services.AddLogging(builder => builder.ConfigureDevProxyLogging(configuration, new DevProxyConfigOptions())); + using var provider = services.BuildServiceProvider(); + + var options = provider.GetRequiredService>().Value; + + Assert.Equal(showTimestamps, options.ShowTimestamps); + Assert.False(options.IncludeFullTimestamps); + } + + [Theory] + [InlineData(LogLevel.Warning)] + [InlineData(LogLevel.Error)] + [InlineData(LogLevel.Critical)] + [InlineData(LogLevel.Information)] + [InlineData(LogLevel.Debug)] + [InlineData(LogLevel.Trace)] + public async Task Formatter_DetachedSurvivingRecord_RetainsFullTimestampForSnapshotsAndFollowers(LogLevel level) + { + var formatter = new ProxyConsoleFormatter(Options.Create(new ProxyConsoleFormatterOptions + { + ShowTimestamps = false, + IncludeFullTimestamps = true + })); + using var writer = new StringWriter(CultureInfo.InvariantCulture); + var entry = new LogEntry(level, "Tests", new EventId(0), "surviving record", null, (state, _) => state); + var cutoff = DateTimeOffset.UtcNow; + + formatter.Write(entry, null, writer); + + var line = writer.ToString().TrimEnd('\r', '\n'); + var timestamp = Assert.Single(LogSinceFilter.GetLineTimes([line], cutoff.AddHours(-1))); + Assert.InRange(timestamp, cutoff, DateTimeOffset.UtcNow); + Assert.Equal([line], LogSinceFilter.Filter([line], cutoff.AddHours(-1), cutoff)); + Assert.Empty(LogSinceFilter.Filter([line], cutoff.AddHours(-1), cutoff.AddHours(1))); + + var path = Path.GetTempFileName(); + try + { + using var reader = new LogFileReader(path, cutoff.AddHours(-1), cutoff); + await File.AppendAllTextAsync(path, line + "\n"); + + Assert.Equal([line], await reader.ReadLinesAsync(CancellationToken.None)); + } + finally + { + File.Delete(path); + } + } + + [Theory] + [InlineData(false)] + [InlineData(true)] + public void Formatter_InteractiveWarning_DoesNotAddDetachedTimestampMetadata(bool showTimestamps) + { + var formatter = new ProxyConsoleFormatter(Options.Create(new ProxyConsoleFormatterOptions + { + ShowTimestamps = showTimestamps + })); + using var writer = new StringWriter(CultureInfo.InvariantCulture); + var entry = new LogEntry(LogLevel.Warning, "Tests", new EventId(0), "warning", null, (state, _) => state); + + formatter.Write(entry, null, writer); + + Assert.DoesNotMatch(@"\[\d{4}-\d{2}-\d{2}T", writer.ToString()); + } +} diff --git a/DevProxy.Tests/LogsCommandTests.cs b/DevProxy.Tests/LogsCommandTests.cs index 6f316b4ec..fcc946f39 100644 --- a/DevProxy.Tests/LogsCommandTests.cs +++ b/DevProxy.Tests/LogsCommandTests.cs @@ -11,6 +11,22 @@ namespace DevProxy.Tests; public class LogsCommandTests { + [Fact] + public void GetLogStartTime_AfterHotReload_UsesProcessStartRatherThanLatestState() + { + using var process = System.Diagnostics.Process.GetCurrentProcess(); + var state = new ProxyInstanceState + { + Pid = process.Id, + StartedAt = DateTimeOffset.Now.AddMinutes(5) + }; + + var logStartTime = LogsCommand.GetLogStartTime(state); + + Assert.Equal(process.StartTime, logStartTime); + Assert.Empty(Logging.LogSinceFilter.Filter([" info Original startup"], logStartTime, state.StartedAt.LocalDateTime)); + } + [Fact] public void GetMultipleInstancesNotice_SingleInstance_ReturnsNull() { diff --git a/DevProxy/ApiControllers/ProxyController.cs b/DevProxy/ApiControllers/ProxyController.cs index 3332dab6c..f85f5bf7e 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; @@ -190,37 +191,24 @@ private async Task WriteLogsAsync(string logFile, int lineCount, string? since, private async Task StreamLogsAsync(string logFile, int initialLines, string? since, bool useJson, CancellationToken cancellationToken) { - // Write initial lines - var allLines = await ReadAllLinesAsync(logFile, cancellationToken); - var filteredLines = FilterLines(allLines, since).TakeLast(initialLines).ToList(); + using var process = System.Diagnostics.Process.GetCurrentProcess(); + using var reader = new LogFileReader(logFile, process.StartTime, LogSinceFilter.ParseSinceOption(since)); + var filteredLines = (await reader.ReadLinesAsync(cancellationToken)).TakeLast(initialLines); foreach (var line in filteredLines) { await WriteSseEventAsync(line, useJson, cancellationToken); } - // Follow new lines - var lastPosition = new FileInfo(logFile).Length; - while (!cancellationToken.IsCancellationRequested) { await Task.Delay(500, cancellationToken); try { - using var fs = new FileStream(logFile, FileMode.Open, FileAccess.Read, FileShare.ReadWrite); - if (fs.Length > lastPosition) + foreach (var line in await reader.ReadLinesAsync(cancellationToken)) { - _ = fs.Seek(lastPosition, SeekOrigin.Begin); - using var reader = new StreamReader(fs); - - string? line; - while ((line = await reader.ReadLineAsync(cancellationToken)) != null) - { - await WriteSseEventAsync(line, useJson, cancellationToken); - } - - lastPosition = fs.Length; + await WriteSseEventAsync(line, useJson, cancellationToken); } } catch (IOException) @@ -246,76 +234,21 @@ 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)) { return lines; } - var sinceTime = ParseSinceOption(since); + var sinceTime = LogSinceFilter.ParseSinceOption(since); if (sinceTime == null) { return lines; } - return lines.Where(line => LineMatchesSince(line, sinceTime.Value)); - } - - private static DateTime? ParseSinceOption(string? since) - { - if (string.IsNullOrEmpty(since)) - { - return null; - } - - // Try parsing as a duration (e.g., "5m", "1h", "30s") - if (since.Length >= 2) - { - var unit = since[^1]; - if (int.TryParse(since[..^1], out var value)) - { - return unit switch - { - 's' => DateTime.Now.AddSeconds(-value), - 'm' => DateTime.Now.AddMinutes(-value), - 'h' => DateTime.Now.AddHours(-value), - 'd' => DateTime.Now.AddDays(-value), - _ => null - }; - } - } - - // Try parsing as a datetime - if (DateTime.TryParse(since, System.Globalization.CultureInfo.InvariantCulture, System.Globalization.DateTimeStyles.None, out var dateTime)) - { - return dateTime; - } - - 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; + using var process = System.Diagnostics.Process.GetCurrentProcess(); + return LogSinceFilter.Filter(lines, process.StartTime, sinceTime.Value); } private static LogEntryDto ParseLogLine(string line) diff --git a/DevProxy/Commands/LogsCommand.cs b/DevProxy/Commands/LogsCommand.cs index f61228ceb..f9367a87f 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; @@ -85,20 +86,27 @@ private async Task RunAsync(ParseResult parseResult, CancellationToken canc return 1; } - var sinceTime = ParseSinceOption(since); + var sinceTime = LogSinceFilter.ParseSinceOption(since); + var logStartTime = GetLogStartTime(state); if (follow) { - await FollowLogFileAsync(logFile, lines, sinceTime, cancellationToken); + await FollowLogFileAsync(logFile, lines, sinceTime, logStartTime, cancellationToken); } else { - await ShowLastLinesAsync(logFile, lines, sinceTime); + await ShowLastLinesAsync(logFile, lines, sinceTime, logStartTime); } return 0; } + internal static DateTimeOffset GetLogStartTime(ProxyInstanceState state) + { + using var process = System.Diagnostics.Process.GetProcessById(state.Pid); + return process.StartTime; + } + internal static string? GetMultipleInstancesNotice(ProxyInstanceState selected, IReadOnlyCollection states) { var otherPids = states @@ -115,40 +123,7 @@ private async Task RunAsync(ParseResult parseResult, CancellationToken canc $"Other instances: {string.Join(", ", otherPids)}. Use --pid to show logs from a specific instance."; } - private static DateTime? ParseSinceOption(string? since) - { - if (string.IsNullOrEmpty(since)) - { - return null; - } - - // Try parsing as a duration (e.g., "5m", "1h", "30s") - if (since.Length >= 2) - { - var unit = since[^1]; - if (int.TryParse(since[..^1], out var value)) - { - return unit switch - { - 's' => DateTime.Now.AddSeconds(-value), - 'm' => DateTime.Now.AddMinutes(-value), - 'h' => DateTime.Now.AddHours(-value), - 'd' => DateTime.Now.AddDays(-value), - _ => null - }; - } - } - - // Try parsing as a datetime - if (DateTime.TryParse(since, CultureInfo.InvariantCulture, DateTimeStyles.None, out var dateTime)) - { - return dateTime; - } - - return null; - } - - private static async Task ShowLastLinesAsync(string logFile, int lineCount, DateTime? sinceTime) + private static async Task ShowLastLinesAsync(string logFile, int lineCount, DateTimeOffset? sinceTime, DateTimeOffset logStartTime) { var lines = new List(); await foreach (var line in File.ReadLinesAsync(logFile)) @@ -156,7 +131,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,13 +140,13 @@ 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, DateTimeOffset? sinceTime, DateTimeOffset logStartTime, CancellationToken cancellationToken) { - // Show initial lines - await ShowLastLinesAsync(logFile, initialLines, sinceTime); - - // Follow new lines using FileSystemWatcher and reading from last position - var lastPosition = new FileInfo(logFile).Length; + using var reader = new LogFileReader(logFile, logStartTime, sinceTime); + foreach (var line in (await reader.ReadLinesAsync(cancellationToken)).TakeLast(initialLines)) + { + Console.WriteLine(line); + } using var watcher = new FileSystemWatcher(Path.GetDirectoryName(logFile)!, Path.GetFileName(logFile)) { @@ -204,23 +179,9 @@ private static async Task FollowLogFileAsync(string logFile, int initialLines, D // Timeout - check for new content anyway } - // Read new content - using var fs = new FileStream(logFile, FileMode.Open, FileAccess.Read, FileShare.ReadWrite); - if (fs.Length > lastPosition) + foreach (var line in await reader.ReadLinesAsync(cancellationToken)) { - _ = fs.Seek(lastPosition, SeekOrigin.Begin); - using var reader = new StreamReader(fs); - - string? line; - while ((line = await reader.ReadLineAsync(cancellationToken)) != null) - { - if (sinceTime == null || LineMatchesSince(line, sinceTime.Value)) - { - Console.WriteLine(line); - } - } - - lastPosition = fs.Length; + Console.WriteLine(line); } } catch (IOException) @@ -231,39 +192,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, DateTimeOffset? sinceTime, DateTimeOffset logStartTime) { if (sinceTime == null) { return lines; } - return lines.Where(line => LineMatchesSince(line, 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 + return LogSinceFilter.Filter(lines, logStartTime, sinceTime.Value); } -} \ No newline at end of file +} diff --git a/DevProxy/Extensions/ILoggingBuilderExtensions.cs b/DevProxy/Extensions/ILoggingBuilderExtensions.cs index 50ebafafc..28f6b0ab9 100644 --- a/DevProxy/Extensions/ILoggingBuilderExtensions.cs +++ b/DevProxy/Extensions/ILoggingBuilderExtensions.cs @@ -54,7 +54,8 @@ public static ILoggingBuilder ConfigureDevProxyLogging( } var showSkipMessages = configuration.GetValue("showSkipMessages", true); - var showTimestamps = configuration.GetValue("showTimestamps", true); + // Detached files need request timestamps even when interactive timestamps are hidden. + var showTimestamps = DevProxyCommand.IsInternalDaemon || configuration.GetValue("showTimestamps", true); // Select the appropriate formatter based on output setting var formatterName = configuredOutput == OutputFormat.Json @@ -84,6 +85,7 @@ public static ILoggingBuilder ConfigureDevProxyLogging( formatterOptions.IncludeScopes = true; formatterOptions.ShowSkipMessages = showSkipMessages; formatterOptions.ShowTimestamps = showTimestamps; + formatterOptions.IncludeFullTimestamps = DevProxyCommand.IsInternalDaemon; } ) .AddConsoleFormatter(formatterOptions => diff --git a/DevProxy/Logging/LogEntry.cs b/DevProxy/Logging/LogEntry.cs index 64e8c7ee6..74abdab8d 100644 --- a/DevProxy/Logging/LogEntry.cs +++ b/DevProxy/Logging/LogEntry.cs @@ -13,6 +13,7 @@ readonly struct LogEntry public EventId EventId { get; init; } public string? Message { get; init; } public Exception? Exception { get; init; } + public DateTimeOffset Timestamp { get; init; } public static LogEntry FromLogEntry(LogEntry logEntry) { @@ -22,7 +23,8 @@ public static LogEntry FromLogEntry(LogEntry logEntry) Category = logEntry.Category, EventId = logEntry.EventId, Message = logEntry.Formatter(logEntry.State, logEntry.Exception), - Exception = logEntry.Exception + Exception = logEntry.Exception, + Timestamp = DateTimeOffset.UtcNow }; } } \ No newline at end of file diff --git a/DevProxy/Logging/LogFileReader.cs b/DevProxy/Logging/LogFileReader.cs new file mode 100644 index 000000000..4384ac095 --- /dev/null +++ b/DevProxy/Logging/LogFileReader.cs @@ -0,0 +1,35 @@ +// 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. + +namespace DevProxy.Logging; + +internal sealed class LogFileReader : IDisposable +{ + private readonly StreamReader _reader; + private readonly LogSinceFilter _filter; + private string _partialLine = string.Empty; + + public LogFileReader(string path, DateTimeOffset logStartTime, DateTimeOffset? sinceTime) + { + _reader = new StreamReader(new FileStream(path, FileMode.Open, FileAccess.Read, FileShare.ReadWrite)); + _filter = new LogSinceFilter(logStartTime, sinceTime); + } + + public async Task> ReadLinesAsync(CancellationToken cancellationToken) + { + var content = _partialLine + await _reader.ReadToEndAsync(cancellationToken); + var lines = content.Split('\n'); + _partialLine = lines[^1]; + + List result = []; + for (var i = 0; i < lines.Length - 1; i++) + { + result.AddRange(_filter.AppendLine(lines[i].TrimEnd('\r'))); + } + + return result; + } + + public void Dispose() => _reader.Dispose(); +} diff --git a/DevProxy/Logging/LogSinceFilter.cs b/DevProxy/Logging/LogSinceFilter.cs new file mode 100644 index 000000000..83d0451e9 --- /dev/null +++ b/DevProxy/Logging/LogSinceFilter.cs @@ -0,0 +1,292 @@ +// 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 timestamp instant. Detached regular messages +/// carry full timestamps; legacy lines are reconstructed from the log start time +/// and the timestamps that the log contains: 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 sealed partial class LogSinceFilter(DateTimeOffset logStartTime, DateTimeOffset? sinceTime) +{ + private static readonly TimeSpan _outOfOrderTolerance = TimeSpan.FromMinutes(1); + private readonly List _pendingLines = []; + private DateTimeOffset _current = logStartTime; + private bool _inRequestBlock; + + internal IReadOnlyList AppendLine(string line) + { + if (sinceTime is null) + { + return [line]; + } + + List result = []; + var startsRequest = RequestStartRegex().IsMatch(line); + if (_inRequestBlock && startsRequest) + { + result.AddRange(ProcessPendingLines()); + _inRequestBlock = false; + } + + _pendingLines.Add(line); + _inRequestBlock |= startsRequest; + if (_inRequestBlock) + { + if (RequestEndRegex().IsMatch(line)) + { + result.AddRange(ProcessPendingLines()); + _inRequestBlock = false; + } + } + else if (!string.IsNullOrWhiteSpace(line)) + { + // Keep blank lines until the next entry identifies their timestamp. + result.AddRange(ProcessPendingLines()); + } + + return result; + } + + private List ProcessPendingLines() + { + var times = GetLineTimes(_pendingLines, _current); + List result = []; + for (var i = 0; i < _pendingLines.Count; i++) + { + if (times[i] >= sinceTime) + { + result.Add(_pendingLines[i]); + } + } + + _current = times[^1]; + _pendingLines.Clear(); + return result; + } + + public static IEnumerable Filter(IReadOnlyList lines, DateTimeOffset logStartTime, DateTimeOffset sinceTime) + { + var lineTimes = GetLineTimes(lines, logStartTime); + for (var i = 0; i < lines.Count; i++) + { + if (lineTimes[i] >= sinceTime) + { + yield return lines[i]; + } + } + } + + internal static DateTimeOffset[] GetLineTimes(IReadOnlyList lines, DateTimeOffset logStartTime) + { + var times = new DateTimeOffset[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, DateTimeOffset current, out DateTimeOffset timestamp) + { + timestamp = default; + + var match = FullTimestampRegex().Match(line); + if (!match.Success) + { + match = TimestampPrefixRegex().Match(line); + } + if (match.Success && + DateTimeOffset.TryParse(match.Groups["timestamp"].Value, CultureInfo.InvariantCulture, DateTimeStyles.None, out var dateTimeOffset)) + { + timestamp = dateTimeOffset; + 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); + } + + internal static DateTimeOffset ResolveTimeOfDay(TimeSpan timeOfDay, DateTimeOffset current, TimeZoneInfo? timeZone = null) + { + timeZone ??= TimeZoneInfo.Local; + var currentWallTime = TimeZoneInfo.ConvertTime(current, timeZone).DateTime; + var candidate = currentWallTime.Date.Add(timeOfDay); + + // Log lines are written in order, so a time of day earlier than the + // previous timestamp normally means midnight. During the repeated DST + // hour, however, the clock can move backwards on the same date. + if (candidate < currentWallTime - _outOfOrderTolerance) + { + if (!timeZone.IsAmbiguousTime(currentWallTime) || !timeZone.IsAmbiguousTime(candidate)) + { + candidate = candidate.AddDays(1); + } + } + else if (candidate - currentWallTime > TimeSpan.FromDays(1) - _outOfOrderTolerance) + { + candidate = candidate.AddDays(-1); + } + + if (timeZone.IsAmbiguousTime(candidate)) + { + var instants = timeZone.GetAmbiguousTimeOffsets(candidate) + .Select(offset => new DateTimeOffset(candidate, offset)) + .Order() + .ToArray(); + return instants.FirstOrDefault(instant => instant >= current - _outOfOrderTolerance, instants[^1]); + } + + return new DateTimeOffset(candidate, timeZone.GetUtcOffset(candidate)); + } + + private static bool TryGetJsonTimestamp(string line, out DateTimeOffset 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; + return true; + } + } + catch (JsonException) + { + } + + return false; + } + + internal static DateTimeOffset? ParseSinceOption(string? since) + { + if (string.IsNullOrEmpty(since)) + { + return null; + } + + if (since.Length >= 2 && int.TryParse(since[..^1], out var value)) + { + var now = DateTimeOffset.UtcNow; + return since[^1] switch + { + 's' => now.AddSeconds(-value), + 'm' => now.AddMinutes(-value), + 'h' => now.AddHours(-value), + 'd' => now.AddDays(-value), + _ => null + }; + } + + return DateTimeOffset.TryParse(since, CultureInfo.InvariantCulture, DateTimeStyles.None, out var timestamp) + ? timestamp + : null; + } + + // 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*(?:trce|dbug|info|warn|fail|crit)\s*" + Ansi + @"\s*(?:[\u2502\u2570]\s*)?)?\[(?\d{4}-\d{2}-\d{2}T[^\]]+)\]")] + private static partial Regex TimestampPrefixRegex(); + + [GeneratedRegex(@"^(?:\s*" + Ansi + @"\s*(?:dbug|trce)\s*" + Ansi + @"\s*)?\[(?