Skip to content

Commit 5a985e8

Browse files
Fix #1294: Log startup connect exceptions to the rolling file sink
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
1 parent ccc7a09 commit 5a985e8

3 files changed

Lines changed: 140 additions & 4 deletions

File tree

Phantom.Workspaces.Tests/MainWindowIntegrationTests.cs

Lines changed: 118 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6107,6 +6107,7 @@ public async Task App_Startup_DefaultWorkspaceWithRestorableSubAgents_DismissesL
61076107
await using var viewModel = CreateTestMainWindowViewModel();
61086108

61096109
var succeeded = await StartupSplashRunner.RunWithSplashDismissAsync(
6110+
loggerFactory: Microsoft.Extensions.Logging.Abstractions.NullLoggerFactory.Instance,
61106111
initializeAsync: () => viewModel.InitializeAsync(),
61116112
setStatus: _ => { },
61126113
onFaultDelay: () => Task.CompletedTask,
@@ -6127,6 +6128,7 @@ public async Task App_Startup_ViewModelInitializeAsyncFaults_LoadingWindowIsClos
61276128
var postInitializeRan = false;
61286129

61296130
var succeeded = await StartupSplashRunner.RunWithSplashDismissAsync(
6131+
loggerFactory: Microsoft.Extensions.Logging.Abstractions.NullLoggerFactory.Instance,
61306132
initializeAsync: () => Task.FromException(new InvalidOperationException("boom")),
61316133
setStatus: _ => { },
61326134
onFaultDelay: () => Task.CompletedTask,
@@ -6150,6 +6152,7 @@ public async Task App_Startup_SubAgentRestoreThrows_DoesNotHangSplash()
61506152
var statusMessages = new List<string>();
61516153

61526154
var succeeded = await StartupSplashRunner.RunWithSplashDismissAsync(
6155+
loggerFactory: Microsoft.Extensions.Logging.Abstractions.NullLoggerFactory.Instance,
61536156
initializeAsync: () => Task.FromException(
61546157
new InvalidOperationException("Agent definition does not specify a model.")),
61556158
setStatus: msg => statusMessages.Add(msg),
@@ -6163,6 +6166,121 @@ public async Task App_Startup_SubAgentRestoreThrows_DoesNotHangSplash()
61636166
Assert.Contains(statusMessages, m => m.Contains("Agent definition does not specify a model.", StringComparison.Ordinal));
61646167
}
61656168

6169+
// ── Issue #1294: startup connect failures must be written to the rolling log file ──
6170+
6171+
private sealed class RecordingStartupLoggerFactory : Microsoft.Extensions.Logging.ILoggerFactory
6172+
{
6173+
public List<TestLogger<StartupSplashRunner>.LogEntry> Entries { get; } = [];
6174+
private readonly TestLogger<StartupSplashRunner> logger;
6175+
6176+
public RecordingStartupLoggerFactory()
6177+
{
6178+
this.logger = new TestLogger<StartupSplashRunner>();
6179+
}
6180+
6181+
public void AddProvider(Microsoft.Extensions.Logging.ILoggerProvider provider) { }
6182+
public Microsoft.Extensions.Logging.ILogger CreateLogger(string categoryName) => this.logger;
6183+
public void Dispose() { }
6184+
6185+
public IReadOnlyList<TestLogger<StartupSplashRunner>.LogEntry> Snapshot() => this.logger.Entries;
6186+
}
6187+
6188+
[AvaloniaFact(Timeout = 15_000)]
6189+
public async Task StartupSplashRunner_WhenInitializeThrows_LogsError()
6190+
{
6191+
var factory = new RecordingStartupLoggerFactory();
6192+
var boom = new InvalidOperationException("boom-1294");
6193+
6194+
await StartupSplashRunner.RunWithSplashDismissAsync(
6195+
loggerFactory: factory,
6196+
initializeAsync: () => Task.FromException(boom),
6197+
setStatus: _ => { },
6198+
onFaultDelay: () => Task.CompletedTask,
6199+
shutdown: () => { },
6200+
postInitialize: () => { },
6201+
closeSplash: () => { });
6202+
6203+
var errors = factory.Snapshot()
6204+
.Where(e => e.Level == Microsoft.Extensions.Logging.LogLevel.Error)
6205+
.ToList();
6206+
Assert.Single(errors);
6207+
Assert.Same(boom, errors[0].Exception);
6208+
Assert.Contains("Startup connect failed", errors[0].Message, StringComparison.Ordinal);
6209+
}
6210+
6211+
[AvaloniaFact(Timeout = 15_000)]
6212+
public async Task StartupSplashRunner_WhenInitializeThrows_SetsSplashStatus()
6213+
{
6214+
var factory = new RecordingStartupLoggerFactory();
6215+
var statusMessages = new List<string>();
6216+
6217+
await StartupSplashRunner.RunWithSplashDismissAsync(
6218+
loggerFactory: factory,
6219+
initializeAsync: () => Task.FromException(new InvalidOperationException("boom-status")),
6220+
setStatus: msg => statusMessages.Add(msg),
6221+
onFaultDelay: () => Task.CompletedTask,
6222+
shutdown: () => { },
6223+
postInitialize: () => { },
6224+
closeSplash: () => { });
6225+
6226+
Assert.Contains("Failed to connect: boom-status", statusMessages);
6227+
}
6228+
6229+
[AvaloniaFact(Timeout = 15_000)]
6230+
public async Task StartupSplashRunner_WhenInitializeSucceeds_DoesNotLogError()
6231+
{
6232+
var factory = new RecordingStartupLoggerFactory();
6233+
6234+
await StartupSplashRunner.RunWithSplashDismissAsync(
6235+
loggerFactory: factory,
6236+
initializeAsync: () => Task.CompletedTask,
6237+
setStatus: _ => { },
6238+
onFaultDelay: () => Task.CompletedTask,
6239+
shutdown: () => { },
6240+
postInitialize: () => { },
6241+
closeSplash: () => { });
6242+
6243+
Assert.DoesNotContain(factory.Snapshot(), e => e.Level == Microsoft.Extensions.Logging.LogLevel.Error);
6244+
}
6245+
6246+
[AvaloniaFact(Timeout = 15_000)]
6247+
public async Task StartupSplashRunner_WhenInitializeThrows_LogsBeforeShutdown()
6248+
{
6249+
var factory = new RecordingStartupLoggerFactory();
6250+
var events = new List<string>();
6251+
6252+
// TestLogger records to factory.Snapshot() synchronously; we also snapshot ordering
6253+
// via events for the shutdown/onFaultDelay callbacks so we can assert LogError fired
6254+
// strictly before either.
6255+
await StartupSplashRunner.RunWithSplashDismissAsync(
6256+
loggerFactory: factory,
6257+
initializeAsync: () => Task.FromException(new InvalidOperationException("order-check")),
6258+
setStatus: _ => events.Add("setStatus"),
6259+
onFaultDelay: () =>
6260+
{
6261+
events.Add("onFaultDelay");
6262+
return Task.CompletedTask;
6263+
},
6264+
shutdown: () => events.Add("shutdown"),
6265+
postInitialize: () => events.Add("postInitialize"),
6266+
closeSplash: () => events.Add("closeSplash"));
6267+
6268+
// Snapshot the error entry — the RecordingStartupLoggerFactory records synchronously
6269+
// inside LogError, so its presence at snapshot time means LogError has returned.
6270+
var errorEntry = factory.Snapshot()
6271+
.Single(e => e.Level == Microsoft.Extensions.Logging.LogLevel.Error);
6272+
Assert.Contains("Startup connect failed", errorEntry.Message, StringComparison.Ordinal);
6273+
6274+
// Ordering: shutdown and onFaultDelay both follow the LogError call, which happens
6275+
// before setStatus in the catch block. shutdown must not precede either.
6276+
var shutdownIndex = events.IndexOf("shutdown");
6277+
var onFaultDelayIndex = events.IndexOf("onFaultDelay");
6278+
var setStatusIndex = events.IndexOf("setStatus");
6279+
Assert.True(setStatusIndex >= 0);
6280+
Assert.True(onFaultDelayIndex > setStatusIndex, "onFaultDelay must run after setStatus (and after LogError).");
6281+
Assert.True(shutdownIndex > onFaultDelayIndex, "shutdown must run after onFaultDelay (and after LogError).");
6282+
}
6283+
61666284
private static RepositorySource CreateInMemoryRepositorySource()
61676285
{
61686286
return new UnknownRepositorySource();

Phantom.Workspaces/App.axaml.cs

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -331,6 +331,7 @@ public override async void OnFrameworkInitializationCompleted()
331331
// RestoreSubAgentsAsync (the reported #1186 cause) left it stuck in
332332
// front indefinitely.
333333
var succeeded = await StartupSplashRunner.RunWithSplashDismissAsync(
334+
loggerFactory: loggerFactory,
334335
initializeAsync: () => viewModel.InitializeAsync(),
335336
setStatus: msg => loadingViewModel.StatusText = msg,
336337
onFaultDelay: () => Task.Delay(5000), // Give user time to read the error

Phantom.Workspaces/StartupSplashRunner.cs

Lines changed: 21 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,7 @@
11
namespace Phantom.Workspaces;
22

3+
using Microsoft.Extensions.Logging;
4+
35
/// <summary>
46
/// Issue #1186: Centralises the "initialize the view-model behind the splash" run so
57
/// that the loading window is ALWAYS dismissed via <see langword="finally"/>, no matter
@@ -8,34 +10,49 @@ namespace Phantom.Workspaces;
810
/// a fault inside <c>viewModel.InitializeAsync()</c> — or, per the diagnosed bug, an
911
/// unobserved fault buried inside <c>RestoreSubAgentsAsync</c> — could leave the
1012
/// splash stuck in front of every other window indefinitely.
13+
/// Issue #1294: The runner now also owns startup-connect logging so exceptions that would
14+
/// otherwise be shown only in the splash <c>StatusText</c> are written to the rolling
15+
/// file sink via the injected <see cref="ILoggerFactory"/>.
1116
/// </summary>
12-
internal static class StartupSplashRunner
17+
internal sealed class StartupSplashRunner
1318
{
19+
private StartupSplashRunner() { }
20+
1421
/// <summary>
1522
/// Runs <paramref name="initializeAsync"/>. On success invokes
1623
/// <paramref name="postInitialize"/> and returns <see langword="true"/>. On
17-
/// exception invokes <paramref name="setStatus"/> with the failure message,
18-
/// awaits <paramref name="onFaultDelay"/>, invokes <paramref name="shutdown"/>
19-
/// and returns <see langword="false"/>. In every case, <paramref name="closeSplash"/>
24+
/// exception logs the exception via <paramref name="loggerFactory"/> BEFORE invoking
25+
/// <paramref name="setStatus"/> with the failure message, awaiting
26+
/// <paramref name="onFaultDelay"/>, invoking <paramref name="shutdown"/>
27+
/// and returning <see langword="false"/>. In every case, <paramref name="closeSplash"/>
2028
/// runs from a <see langword="finally"/> block so the loading window is always
2129
/// dismissed.
2230
/// </summary>
2331
internal static async Task<bool> RunWithSplashDismissAsync(
32+
ILoggerFactory loggerFactory,
2433
Func<Task> initializeAsync,
2534
Action<string> setStatus,
2635
Func<Task> onFaultDelay,
2736
Action shutdown,
2837
Action postInitialize,
2938
Action closeSplash)
3039
{
40+
ArgumentNullException.ThrowIfNull(loggerFactory);
41+
var logger = loggerFactory.CreateLogger<StartupSplashRunner>();
3142
try
3243
{
3344
try
3445
{
46+
logger.LogInformation("Startup connect: beginning initialize.");
3547
await initializeAsync().ConfigureAwait(true);
3648
}
3749
catch (Exception ex)
3850
{
51+
// Issue #1294: Log the full exception (type + message + stack) to the rolling
52+
// file sink BEFORE showing the splash message, awaiting the fault delay, or
53+
// shutting down. Doing it first keeps the entry flushable even if shutdown
54+
// races the file sink and gives users a diagnostic trail beyond ex.Message.
55+
logger.LogError(ex, "Startup connect failed.");
3956
setStatus($"Failed to connect: {ex.Message}");
4057
await onFaultDelay().ConfigureAwait(true);
4158
shutdown();

0 commit comments

Comments
 (0)