diff --git a/CHANGELOG.md b/CHANGELOG.md index 39beab85..2bd450e6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,17 @@ and a release's notes are its section. The procedure is in [`docs/RELEASING.md`] ## [Unreleased] +### Added + +- A crash now leaves its stack in `logs/client-diagnostics-*.log`, in the window and the terminal alike, + along with errors the UI framework used to swallow without a trace. + +### Changed + +- An MXP picture is downloaded and decoded once per session. A room picture shown on every look used + to be fetched again whenever the pane's width had changed, and once per look that arrived while it was + still loading. + ## [0.1.5] - 2026-10-25 ### Added diff --git a/src/SharpMUTerm.Tui/ClientDiagnostics.cs b/src/SharpMUTerm.Tui/ClientDiagnostics.cs index c67d442d..4a792139 100644 --- a/src/SharpMUTerm.Tui/ClientDiagnostics.cs +++ b/src/SharpMUTerm.Tui/ClientDiagnostics.cs @@ -120,12 +120,83 @@ public static ClientDiagnostics Create(string folder, LogLevel minimum = LogLeve } } + /// + /// Routes the framework's own log into this pipeline, from Warning up, for as long as the result is held. + /// + /// The framework catches what it runs and logs it to a of its + /// own that writes nowhere unless an environment variable names a file: every exception thrown by an + /// EnqueueOnUIThread action (which is most of this app's cross-thread work, through OnUiThread), and + /// the one that ends the main loop. That last one returns 1 from Run and prints its stack to the console + /// once the console is restored, which a terminal shows and a window has nowhere to put: the window just closed, + /// and no file on the machine said why. + /// + /// + public IDisposable Forward(SharpConsoleUI.Logging.ILogService framework) + { + var logger = For("SharpConsoleUI"); + void OnEntry(object? sender, SharpConsoleUI.Logging.LogEntry entry) + { + var level = entry.Level switch + { + SharpConsoleUI.Logging.LogLevel.Critical => LogLevel.Critical, + SharpConsoleUI.Logging.LogLevel.Error => LogLevel.Error, + SharpConsoleUI.Logging.LogLevel.Warning => LogLevel.Warning, + _ => LogLevel.None, + }; + if (level != LogLevel.None) + { + logger.Log(level, entry.Exception, "{Message}", entry.Message); + } + } + + framework.LogAdded += OnEntry; + return new Subscription(() => framework.LogAdded -= OnEntry); + } + + /// + /// Records what would otherwise end the process without a word, for as long as the result is held: an exception + /// no thread caught (, which also sees one escaping the window's own + /// UI thread) and a faulted task nobody awaited (, which does + /// not end the process and is logged as an error). Neither is handled here: the process ends as it would have, + /// with the stack in the file first. The file sink is unbuffered, so the line is on disk when the handler returns. + /// + public IDisposable RecordUnhandled() + { + var logger = For("SharpMUTerm.Crash"); + void OnUnhandled(object? sender, UnhandledExceptionEventArgs e) + { + logger.LogCritical( + e.ExceptionObject as Exception, + "Unhandled exception on thread {Thread} (terminating: {Terminating})", + Thread.CurrentThread.Name ?? Environment.CurrentManagedThreadId.ToString(), + e.IsTerminating); + } + + void OnUnobserved(object? sender, UnobservedTaskExceptionEventArgs e) => + logger.LogError(e.Exception, "A task failed and nothing awaited it"); + + AppDomain.CurrentDomain.UnhandledException += OnUnhandled; + TaskScheduler.UnobservedTaskException += OnUnobserved; + return new Subscription(() => + { + AppDomain.CurrentDomain.UnhandledException -= OnUnhandled; + TaskScheduler.UnobservedTaskException -= OnUnobserved; + }); + } + public void Dispose() { _factory.Dispose(); _serilog.Dispose(); } + private sealed class Subscription(Action undo) : IDisposable + { + private Action? _undo = undo; + + public void Dispose() => Interlocked.Exchange(ref _undo, null)?.Invoke(); + } + private static LogEventLevel ToSerilog(LogLevel level) => level switch { LogLevel.Trace => LogEventLevel.Verbose, diff --git a/src/SharpMUTerm.Tui/InlineImageHost.cs b/src/SharpMUTerm.Tui/InlineImageHost.cs index 1964f1b8..bdfae50c 100644 --- a/src/SharpMUTerm.Tui/InlineImageHost.cs +++ b/src/SharpMUTerm.Tui/InlineImageHost.cs @@ -12,10 +12,17 @@ namespace SharpMUTerm.Tui; /// Conservative in the ways a world could abuse it. Fetching goes through 's /// rules (http(s) and data:, an image content type, a byte cap, a timeout). At most /// run at once and at most lines wait, -/// so a server spamming tags gets placeholders rather than a client with a hundred sockets open. A -/// result is kept per URL, presentation and box, so the room map a game re-sends on every look -/// is fetched once and, under Kitty, transmitted once — later copies are placeholder cells pointing at -/// the image the terminal already holds. +/// so a server spamming tags gets placeholders rather than a client with a hundred sockets open. +/// +/// +/// Two caches, because a picture is used at more than one size. The decoded picture is kept per URL +/// (), and a fetch already running is shared, so the room picture a game +/// re-sends on every look is fetched and decoded once for the session, whatever width the pane is +/// when it arrives and however many looks land before the first fetch is back. Decoding is the costly +/// half: a WebP the size of a desktop background is tens of milliseconds of SIMD work each time. The rows +/// are kept as well, per URL, presentation and box, so a repeat at the same size is not even re-scaled +/// and, under Kitty, not re-transmitted — later copies are placeholder cells pointing at the image the +/// terminal already holds. /// /// internal sealed class InlineImageHost : IDisposable @@ -29,6 +36,13 @@ internal sealed class InlineImageHost : IDisposable /// Finished results kept for reuse. public const int CacheSize = 32; + /// + /// Decoded pictures kept for reuse, in bytes of pixels. A 1942×809 room picture is about 6 MB, so this + /// holds a session's worth of rooms; the least recently used goes first, and one larger than the whole + /// budget is used once and not kept. + /// + public const long SourceCacheBytes = 64L * 1024 * 1024; + /// /// First Kitty image id this host hands out. The framework numbers its own images (the web view's) /// from 1; starting high keeps the two apart, and every id still fits the 24 bits a placeholder's @@ -41,14 +55,23 @@ internal sealed class InlineImageHost : IDisposable private readonly SemaphoreSlim _fetches = new(MaxConcurrentFetches); private readonly CancellationTokenSource _cts = new(); private readonly LinkedList<(string Key, IReadOnlyList Rows)> _cache = new(); + private readonly Dictionary> _sources = new(StringComparer.Ordinal); + private readonly LinkedList _sourceOrder = new(); + private readonly long _sourceBudget; + private long _sourceBytes; private readonly object _gate = new(); private int _queued; private int _nextKittyId = FirstKittyId; /// Fetches an image's bytes, or null. /// Marshals onto the UI thread. - public InlineImageHost(Func> fetch, Action onUi) + /// The decoded-picture budget; unless a test says otherwise. + public InlineImageHost( + Func> fetch, + Action onUi, + long sourceCacheBytes = SourceCacheBytes) { + _sourceBudget = sourceCacheBytes; _fetch = fetch ?? throw new ArgumentNullException(nameof(fetch)); _onUi = onUi ?? throw new ArgumentNullException(nameof(onUi)); } @@ -176,22 +199,8 @@ presentation is not (InlineImagePresentation.Kitty or InlineImagePresentation.Ha return hit; } - byte[]? bytes; - await _fetches.WaitAsync(_cts.Token).ConfigureAwait(false); - try - { - bytes = await _fetch(request.Url, _cts.Token).ConfigureAwait(false); - } - catch (OperationCanceledException) - { - return null; - } - finally - { - _fetches.Release(); - } - - var picture = bytes is null ? null : Decode(bytes, request, availableColumns, maxRows); + var source = await SourceFor(request.Url).ConfigureAwait(false); + var picture = source is null ? null : Fit(source, request, availableColumns, maxRows); if (picture is null) { return null; @@ -221,6 +230,125 @@ presentation is not (InlineImagePresentation.Kitty or InlineImagePresentation.Ha return rows; } + /// + /// The decoded picture at : from the cache, from a fetch already under way, or + /// fetched and decoded now. Null when it cannot be had, and a failure is not remembered, so the next + /// mention tries again. + /// + private Task SourceFor(string url) + { + lock (_gate) + { + if (_sources.TryGetValue(url, out var node)) + { + _sourceOrder.Remove(node); + _sourceOrder.AddFirst(node); + return node.Value.Picture; + } + + // In the cache before it starts, so a fetch that finishes at once still finds itself there to + // settle; and off this thread, so a fetch that completes at once does not decode under the lock. + var source = new Source(url); + _sources[url] = _sourceOrder.AddFirst(source); + source.Picture = Task.Run(async () => + { + PixelBuffer? picture = null; + try + { + picture = await FetchAndDecodeAsync(url).ConfigureAwait(false); + return picture; + } + finally + { + Settle(source, picture); + } + }); + return source.Picture; + } + } + + private async Task FetchAndDecodeAsync(string url) + { + byte[]? bytes; + await _fetches.WaitAsync(_cts.Token).ConfigureAwait(false); + try + { + bytes = await _fetch(url, _cts.Token).ConfigureAwait(false); + } + catch (OperationCanceledException) + { + return null; + } + finally + { + _fetches.Release(); + } + + if (bytes is null) + { + return null; + } + + try + { + return ImageDecoder.Decode(bytes); + } + catch (Exception ex) when (ex is not OutOfMemoryException) + { + return null; + } + } + + /// Accounts for a finished fetch: forgets a failure, and trims the cache to its budget. + private void Settle(Source source, PixelBuffer? picture) + { + lock (_gate) + { + if (!_sources.TryGetValue(source.Url, out var node) || !ReferenceEquals(node.Value, source)) + { + return; + } + + if (picture is null) + { + Forget(node); + return; + } + + source.Bytes = (long)picture.Width * picture.Height * 4; + _sourceBytes += source.Bytes; + for (var last = _sourceOrder.Last; _sourceBytes > _sourceBudget && last is not null;) + { + var previous = last.Previous; + if (last.Value.Bytes > 0) + { + Forget(last); + } + + last = previous; + } + } + } + + private void Forget(LinkedListNode node) + { + _sourceOrder.Remove(node); + _sources.Remove(node.Value.Url); + _sourceBytes -= node.Value.Bytes; + } + + /// Decoded pictures held, and fetches under way — for tests. + internal int SourcesHeld + { + get + { + lock (_gate) + { + return _sources.Count; + } + } + } + /// /// Decodes and sizes a picture. The pixels kept are the most either presentation needs: under /// Kitty the terminal scales into the box, so anything past @@ -242,6 +370,16 @@ presentation is not (InlineImagePresentation.Kitty or InlineImagePresentation.Ha return null; } + return Fit(source, request, availableColumns, maxRows); + } + + /// Sizes a decoded picture to its cell box, keeping the pixels either presentation needs. + internal static DecodedPicture? Fit( + PixelBuffer source, + InlineImageRequest request, + int availableColumns, + int maxRows = InlineImageLayout.MaxRows) + { var box = InlineImageLayout.Fit(source.Width, source.Height, request.Width, request.Height, availableColumns, maxRows); if (box.Columns <= 0 || box.Rows <= 0) { @@ -364,6 +502,17 @@ private void Remember(string key, IReadOnlyList rows) } } + /// A decoded picture held by the cache, or the fetch that will produce it. + private sealed class Source(string url) + { + public string Url { get; } = url; + + public Task Picture { get; set; } = Task.FromResult(null); + + /// Its size in the cache's budget; zero while the fetch is under way. + public long Bytes { get; set; } + } + public void Dispose() { _cts.Cancel(); diff --git a/src/SharpMUTerm.Tui/Program.cs b/src/SharpMUTerm.Tui/Program.cs index 7345e37d..34964bae 100644 --- a/src/SharpMUTerm.Tui/Program.cs +++ b/src/SharpMUTerm.Tui/Program.cs @@ -127,6 +127,10 @@ internal static int RunLive( // the World.Character-*.log transcripts). Never a console sink — this app owns the screen. using var diagnostics = ClientDiagnostics.Create(logRoot); + // A crash leaves its stack in that file. Without this an exception nothing caught ended the process with + // nothing written anywhere a user could find, which in the window (no console) meant it simply vanished. + using var crashes = diagnostics.RecordUnhandled(); + // Drain what the configuration load had to say now that there is somewhere to say it. A secrets file // that could not be read means characters start with no password — worth one line in the client // message log (⌃P), and never more than that: the client still runs, still connects, and the password @@ -173,7 +177,23 @@ internal static int RunLive( logRoot: logRoot, restore: restore, mssp: mssp); - var exitCode = liveApp.Run(startup); // blocks on the SharpConsoleUI main loop until exit + int exitCode; + try + { + exitCode = liveApp.Run(startup); // blocks on the SharpConsoleUI main loop until exit + } + catch (Exception ex) + { + // Run itself catches what its loop throws; this is what escapes it (startup, shutdown). The window's + // client thread catches it next, and has nowhere but a console that does not exist to write it. + diagnostics.Logger.LogCritical(ex, "The client stopped on an exception"); + throw; + } + + if (exitCode != 0) + { + diagnostics.Logger.LogWarning("The client loop ended with exit code {ExitCode}", exitCode); + } // Persist the workspace so the next launch resumes where this one left off. try diff --git a/src/SharpMUTerm.Tui/SharpMUTermApp.cs b/src/SharpMUTerm.Tui/SharpMUTermApp.cs index 79f50ebf..e223cc4c 100644 --- a/src/SharpMUTerm.Tui/SharpMUTermApp.cs +++ b/src/SharpMUTerm.Tui/SharpMUTermApp.cs @@ -347,6 +347,9 @@ private sealed class SizeReport /// The client diagnostics pipeline: the message log, the rolling file, the level switch. private readonly ClientDiagnostics _diagnostics; + /// The framework's own log, routed into ; see . + private readonly IDisposable _frameworkLog; + /// Whether this app built its own pipeline (and so must dispose it) or was handed one. private readonly bool _ownsDiagnostics; @@ -722,6 +725,7 @@ public SharpMUTermApp( // erased it and the overlay drew it back, every frame. Changed cells only, then. DirtyTrackingMode: _sixel is null ? DirtyTrackingMode.Smart : DirtyTrackingMode.Cell); _system = new ConsoleWindowSystem(host.Driver, options); + _frameworkLog = _diagnostics.Forward(_system.LogService); // Built here so the app always has one to ask, and inert unless something turns it on. Nothing // reaches the terminal until Run() starts it, which is the same shape as the save/logRoot/restore @@ -9177,6 +9181,9 @@ internal static (int Width, int Height) SixelCellSize(string? value) /// How the driver decides which cells to write; Cell while the Sixel overlay is on. internal DirtyTrackingMode DirtyTracking => _system.Options.DirtyTrackingMode; + /// The framework's own log, which routes into this app's. + internal SharpConsoleUI.Logging.ILogService FrameworkLog => _system.LogService; + /// /// Finds the pictures on the frame just painted and, once it is on the terminal, draws them again as /// Sixel over their half-blocks (). The Sixel is queued, not written here: @@ -12312,6 +12319,7 @@ public async ValueTask DisposeAsync() _imageLoader.Dispose(); _fetcher.Dispose(); await _sessions.DisposeAsync().ConfigureAwait(false); + _frameworkLog.Dispose(); if (_ownsDiagnostics) { _diagnostics.Dispose(); // only the pipeline this app built; a supplied one outlives it diff --git a/tests/SharpMUTerm.Tui.Tests/CrashLoggingTests.cs b/tests/SharpMUTerm.Tui.Tests/CrashLoggingTests.cs new file mode 100644 index 00000000..6fee9602 --- /dev/null +++ b/tests/SharpMUTerm.Tui.Tests/CrashLoggingTests.cs @@ -0,0 +1,73 @@ +using SharpConsoleUI.Drivers; +using SharpMUTerm.Core.Configuration; +using SharpMUTerm.Core.Diagnostics; +using SharpMUTerm.Graphics; +using FrameworkLogService = SharpConsoleUI.Logging.LogService; + +namespace SharpMUTerm.Tui.Tests; + +/// +/// A failure has to reach the diagnostics file. The framework catches what its loop and its queued UI actions +/// throw and logs it to a log service of its own that writes nowhere, so the window closed with no record of why. +/// +[NotInParallel] +public class CrashLoggingTests +{ + [Test] + public async Task TheFrameworksErrorsReachTheClientLog() + { + using var diagnostics = ClientDiagnostics.InMemory(); + var framework = new FrameworkLogService(); + using (diagnostics.Forward(framework)) + { + framework.LogCritical("Unhandled exception in main loop: boom", new InvalidOperationException("boom"), "System"); + } + + var entry = diagnostics.Messages.Entries.Single(); + await Assert.That(entry.Severity).IsEqualTo(MessageSeverity.Error); + await Assert.That(entry.Text).Contains("Unhandled exception in main loop"); + await Assert.That(entry.Text).Contains("boom"); + await Assert.That(entry.Source).IsEqualTo("SharpConsoleUI"); + } + + [Test] + public async Task TheFrameworksChatterStaysOut() + { + using var diagnostics = ClientDiagnostics.InMemory(); + var framework = new FrameworkLogService { MinimumLevel = SharpConsoleUI.Logging.LogLevel.Trace }; + using (diagnostics.Forward(framework)) + { + framework.LogDebug("Console window system shutting down"); + framework.LogInfo("started"); + } + + await Assert.That(diagnostics.Messages.Entries.Count).IsEqualTo(0); + } + + [Test] + public async Task NothingIsForwardedOnceTheSubscriptionIsDisposed() + { + using var diagnostics = ClientDiagnostics.InMemory(); + var framework = new FrameworkLogService(); + diagnostics.Forward(framework).Dispose(); + framework.LogError("late"); + + await Assert.That(diagnostics.Messages.Entries.Count).IsEqualTo(0); + } + + [Test] + public async Task TheAppForwardsItsFrameworksLog() + { + using var diagnostics = ClientDiagnostics.InMemory(); + var config = new AppConfiguration(); + var caps = new TerminalCapabilities(GraphicsProtocol.None, supportsTrueColor: true, supportsKittyGraphics: false, supportsSixel: false); + await using var app = new SharpMUTermApp( + config, + ClientHost.Headless(new HeadlessConsoleDriver(80, 24), caps), + diagnostics: diagnostics); + + app.FrameworkLog.LogError("Error in EnqueueOnUIThread action: boom", new InvalidOperationException("boom"), "System"); + + await Assert.That(diagnostics.Messages.Entries.Any(e => e.Text.Contains("EnqueueOnUIThread"))).IsTrue(); + } +} diff --git a/tests/SharpMUTerm.Tui.Tests/InlineImageCacheTests.cs b/tests/SharpMUTerm.Tui.Tests/InlineImageCacheTests.cs new file mode 100644 index 00000000..28526f93 --- /dev/null +++ b/tests/SharpMUTerm.Tui.Tests/InlineImageCacheTests.cs @@ -0,0 +1,115 @@ +using SharpMUTerm.Core.Text; +using SharpMUTerm.Graphics; + +namespace SharpMUTerm.Tui.Tests; + +/// +/// A room picture a game re-sends on every look is fetched and decoded once a session — at any pane +/// width, and however many looks land before the first fetch is back. +/// +public class InlineImageCacheTests +{ + private const string Url = "https://mud.example/room.png"; + + private static readonly InlineImageRequest Room = new(Url, "room.png"); + + private sealed class Counting + { + public int Fetches; + + public Func> Fetch(Task bytes) => (_, _) => + { + Interlocked.Increment(ref Fetches); + return bytes; + }; + } + + private static async Task>> Show(InlineImageHost host, params int[] widths) + { + var drawn = new List>(); + foreach (var width in widths) + { + host.Load([Room], InlineImagePresentation.HalfBlock, width, () => null, (_, rows) => drawn.Add(rows)); + } + + await host.Pending; + return drawn; + } + + [Test] + public async Task APictureShownAtAnotherWidthIsNotFetchedAgain() + { + var count = new Counting(); + using var host = new InlineImageHost(count.Fetch(Task.FromResult(TestImages.RgbaPng(320, 160))), run => run()); + + var first = await Show(host, 40); + var second = await Show(host, 20); + + await Assert.That(count.Fetches).IsEqualTo(1); + await Assert.That(first.Single()[0].Count(c => c == '▀')).IsEqualTo(40); + await Assert.That(second.Single()[0].Count(c => c == '▀')).IsEqualTo(20); + } + + [Test] + public async Task LooksThatArriveBeforeTheFetchIsBackShareIt() + { + var count = new Counting(); + var gate = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + using var host = new InlineImageHost(count.Fetch(gate.Task), run => run()); + + var drawn = new List>(); + for (var look = 0; look < 3; look++) + { + host.Load([Room], InlineImagePresentation.HalfBlock, 40, () => null, (_, rows) => { lock (drawn) { drawn.Add(rows); } }); + } + + gate.SetResult(TestImages.RgbaPng(64, 32)); + await host.Pending; + + await Assert.That(count.Fetches).IsEqualTo(1); + await Assert.That(drawn.Count).IsEqualTo(3); + } + + [Test] + public async Task AFailedFetchIsTriedAgainNextTime() + { + var calls = 0; + using var host = new InlineImageHost( + (_, _) => Task.FromResult(Interlocked.Increment(ref calls) == 1 ? null : TestImages.RgbaPng(64, 32)), + run => run()); + + var first = await Show(host, 40); + var second = await Show(host, 40); + + await Assert.That(calls).IsEqualTo(2); + await Assert.That(first.Count).IsEqualTo(0); + await Assert.That(second.Count).IsEqualTo(1); + } + + [Test] + public async Task APictureWithinTheBudgetIsKept() + { + using var host = new InlineImageHost( + (_, _) => Task.FromResult(TestImages.RgbaPng(64, 32)), + run => run(), + sourceCacheBytes: 64 * 32 * 4); + + await Show(host, 40); + + await Assert.That(host.SourcesHeld).IsEqualTo(1); + } + + [Test] + public async Task APictureLargerThanTheWholeBudgetIsNotKept() + { + using var host = new InlineImageHost( + (_, _) => Task.FromResult(TestImages.RgbaPng(64, 32)), + run => run(), + sourceCacheBytes: 64 * 32 * 4 - 1); + + var drawn = await Show(host, 40); + + await Assert.That(drawn.Count).IsEqualTo(1); + await Assert.That(host.SourcesHeld).IsEqualTo(0); + } +}