fix(subagents): record spawn lifecycle in the session transcript

src/Netclaw.Actors.Tests/SubAgents/SubAgentSpawnObservabilityTests.cs

@@ -0,0 +1,118 @@
+// -----------------------------------------------------------------------
+// <copyright file="SubAgentSpawnObservabilityTests.cs" company="Petabridge, LLC">
+//      Copyright (C) 2026 - 2026 Petabridge, LLC <https://petabridge.com>
+// </copyright>
+// -----------------------------------------------------------------------
+using Microsoft.Extensions.Logging;
+using Netclaw.Actors.SubAgents;
+using Netclaw.Actors.Tools;
+using Netclaw.Configuration;
+using Netclaw.Tests.Utilities;
+using Netclaw.Tools;
+using Xunit;
+
+namespace Netclaw.Actors.Tests.SubAgents;
+
+/// <summary>
+/// Regression coverage for sub-agent spawn observability. A sub-agent's own actor
+/// logs go through Akka's async logger bridge, where the diagnostics AsyncLocal is
+/// gone, so they never reach the per-session <c>session.log</c>. The spawn lifecycle
+/// is instead recorded by parent-side breadcrumbs that must run while the parent
+/// session scope is active — otherwise a refused or failed spawn is invisible in the
+/// session transcript. These tests assert the scope is active at log time, which is
+/// exactly the condition <c>RollingFileLoggerProvider</c> uses to route a line to
+/// <c>session.log</c>.
+/// </summary>
+public sealed class SubAgentSpawnObservabilityTests : IDisposable
+{
+    private const string SessionId = "C123/167.42";
+
+    private readonly DisposableTempDir _dir = new();
+    private readonly NetclawPaths _paths;
+
+    public SubAgentSpawnObservabilityTests()
+    {
+        _paths = new NetclawPaths(_dir.Path);
+        _paths.EnsureDirectoriesExist();
+    }
+
+    public void Dispose() => _dir.Dispose();
+
+    [Fact]
+    public async Task Spawner_missing_session_context_records_breadcrumbs_under_session_scope()
+    {
+        var logger = new CapturingLogger<SubAgentSpawner>();
+        // Only the parent-side breadcrumb path runs before the early return, so the
+        // unused collaborators are never dereferenced.
+        var spawner = new SubAgentSpawner(
+            chatClientProvider: null!,
+            new ToolRegistry(),
+            toolAccessPolicy: null!,
+            approvalService: null,
+            promptProvider: null!,
+            logger);
+
+        // A context with a session id but no SpawnChildActor factory — the
+        // "subagent tried to spawn but never launched" failure shape.
+        var context = new ToolExecutionContext(SessionId, null) { Audience = TrustAudience.Personal };
+
+        var result = await spawner.SpawnAsync(
+            Profile("summarizer"), "do the work", null, context, TestContext.Current.CancellationToken);
+
+        Assert.False(result.Success);
+        // The spawn attempt and its failure are both visible in the session transcript.
+        Assert.Contains(logger.Entries, e => e.SessionScope == SessionId && e.Message.Contains("spawn requested"));
+        Assert.Contains(logger.Entries, e => e.SessionScope == SessionId && e.Message.Contains("no session context available"));
+    }
+
+    [Fact]
+    public async Task Tool_refusal_records_real_reason_under_session_scope()
+    {
+        var logger = new CapturingLogger<SpawnAgentTool>();
+        var registry = new SubAgentDefinitionRegistry();
+        var tool = new SpawnAgentTool(registry, spawner: null!, _paths, logger: logger);
+
+        // Public audience is refused with a deliberately opaque model-facing string;
+        // the operator-facing breadcrumb must still record the real reason.
+        var context = new ToolExecutionContext(SessionId, null) { Audience = TrustAudience.Public };
+
+        var result = await tool.ExecuteAsync(
+            new Dictionary<string, object?> { ["agent"] = "summarizer", ["task"] = "do the work" },
+            context,
+            TestContext.Current.CancellationToken);
+
+        Assert.Equal("Error: This tool is not available.", result);
+        Assert.Contains(
+            logger.Entries,
+            e => e.Level == LogLevel.Warning
+                 && e.SessionScope == SessionId
+                 && e.Message.Contains("refused")
+                 && e.Message.Contains("Public"));
+    }
+
+    private static SubAgentProfile Profile(string name) => new()
+    {
+        Name = name,
+        Description = "test agent",
+        SystemPrompt = "You are a test agent.",
+        ToolNames = ["file_read"],
+        Visibility = SubAgentVisibility.UserFacing
+    };
+
+    private sealed class CapturingLogger<T> : ILogger<T>
+    {
+        public readonly List<(LogLevel Level, string Message, string? SessionScope)> Entries = new();
+
+        public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
+
+        public bool IsEnabled(LogLevel logLevel) => true;
+
+        public void Log<TState>(
+            LogLevel logLevel,
+            EventId eventId,
+            TState state,
+            Exception? exception,
+            Func<TState, Exception?, string> formatter)
+            => Entries.Add((logLevel, formatter(state, exception), SessionDiagnosticsContext.SessionId));
+    }
+}

src/Netclaw.Actors/SubAgents/SpawnAgentTool.cs

@@ -6,6 +6,7 @@
 using System.ComponentModel;
 using System.Runtime.CompilerServices;
 using System.Threading.Channels;
+using Microsoft.Extensions.Logging;
 using Netclaw.Configuration;
 using Netclaw.Tools;
 
@@ -29,6 +30,7 @@ public sealed partial class SpawnAgentTool : NetclawTool<SpawnAgentTool.Params>
     private readonly NetclawPaths _paths;
     private readonly SubAgentConfig _subAgentConfig;
     private readonly FileSubAgentDefinitionLoader? _loader;
+    private readonly ILogger<SpawnAgentTool>? _logger;
 
     public record Params(
         [property: Description("Name of the subagent to invoke (see available-subagents in context)")]
@@ -44,13 +46,15 @@ public record Params(
 
     public SpawnAgentTool(SubAgentDefinitionRegistry registry, SubAgentSpawner spawner, NetclawPaths paths,
         SubAgentConfig? subAgentConfig = null,
-        FileSubAgentDefinitionLoader? loader = null)
+        FileSubAgentDefinitionLoader? loader = null,
+        ILogger<SpawnAgentTool>? logger = null)
     {
         _registry = registry;
         _spawner = spawner;
         _paths = paths;
         _subAgentConfig = subAgentConfig ?? new SubAgentConfig();
         _loader = loader;
+        _logger = logger;
     }
 
     protected override Task<string> ExecuteAsync(Params args, CancellationToken ct)
@@ -116,10 +120,22 @@ private static string FormatResult(string agent, SubAgentResult result)
     /// </summary>
     private (string? Error, SubAgentProfile? Profile) Resolve(Params args, ToolExecutionContext context)
     {
+        // Rejections here return a (sometimes deliberately opaque) error string to
+        // the model. Mirror the real reason to the session transcript under the
+        // parent session scope so an operator can tell *why* a spawn was refused —
+        // the "This tool is not available." string hides the audience-vs-disabled
+        // distinction from the model on purpose.
+        using var diagnosticsScope = SessionDiagnosticsContext.Push(context.SessionId);
+
         // Defense-in-depth: block subagent spawning for Public audience or when
         // the subagent subsystem is disabled.
         if (context.Audience == TrustAudience.Public || !_subAgentConfig.Enabled)
+        {
+            _logger?.LogWarning(
+                "spawn_agent refused (agent={Agent}, audience={Audience}, subsystemEnabled={Enabled})",
+                args.Agent, context.Audience, _subAgentConfig.Enabled);
             return ("Error: This tool is not available.", null);
+        }
 
         if (string.IsNullOrWhiteSpace(args.Agent))
             return ("Error: 'agent' parameter is required.", null);
@@ -133,6 +149,9 @@ private static string FormatResult(string agent, SubAgentResult result)
         if (profile is null || profile.Visibility != SubAgentVisibility.UserFacing)
         {
             var available = _registry.GetUserFacing();
+            _logger?.LogWarning(
+                "spawn_agent refused: agent '{Agent}' not found or not user-facing (availableCount={Count})",
+                args.Agent, available.Count);
             if (available.Count == 0)
                 return ($"Error: No subagents are available. Agent '{args.Agent}' not found. Author one at {_paths.AgentsDirectory}/*.md or define a skill with metadata.subagent once #661 lands.", null);
 

src/Netclaw.Actors/SubAgents/SubAgentSpawner.cs

@@ -66,6 +66,16 @@ public async Task<SubAgentResult> SpawnAsync(
         string? systemPromptOverlay = null,
         ChannelWriter<ToolActivityUpdate>? activitySink = null)
     {
+        // Session-scoped breadcrumbs: the sub-agent's own actor logs go through
+        // Akka's async logger bridge, where the diagnostics AsyncLocal is gone, so
+        // they never reach session.log. These parent-side lines run synchronously
+        // under the parent session scope, so the spawn lifecycle (request → outcome,
+        // including every early rejection) is always visible in the session transcript.
+        using var diagnosticsScope = SessionDiagnosticsContext.Push(context.SessionId);
+        _logger.LogInformation(
+            "SubAgent [{AgentName}] spawn requested (taskChars={TaskChars})",
+            profile.Name, task.Length);
+
         if (context.SpawnChildActor is null)
         {
             _logger.LogWarning("SubAgent [{AgentName}] cannot spawn — no session context available", profile.Name);
@@ -131,7 +141,36 @@ public async Task<SubAgentResult> SpawnAsync(
             _approvalService,
             SubAgentMaxToolIterations);
         var actorName = $"subagent-{definition.Name}-{runId}";
-        var subAgent = (IActorRef)await context.SpawnChildActor(props, actorName, ct);
+        IActorRef subAgent;
+        try
+        {
+            subAgent = (IActorRef)await context.SpawnChildActor(props, actorName, ct);
+        }
+        catch (Exception ex)
+        {
+            // The child actor was never created (session actor ActorOf failed or the
+            // spawn ask timed out). Record it to the session transcript before the
+            // exception propagates to the tool pipeline.
+            _logger.LogError(
+                ex, "SubAgent [{AgentName}] failed to spawn child actor (runId={RunId})",
+                profile.Name, runId);
+            // Balance the IsStarted=true notification above: the non-streaming path
+            // (activitySink is null) relies solely on OnSubAgentActivity, so without
+            // a terminal event the session UI shows a sub-agent stuck in "Started".
+            context.OnSubAgentActivity?.Invoke(new SubAgentNotificationInfo
+            {
+                RunId = runId,
+                AgentName = definition.Name.Value,
+                IsStarted = false,
+                Success = false
+            });
+            activitySink?.TryComplete();
+            throw;
+        }
+
+        _logger.LogInformation(
+            "SubAgent [{AgentName}] child actor spawned (runId={RunId}); dispatching RunSubAgent",
+            profile.Name, runId);
 
         var sw = Stopwatch.StartNew();
         try
@@ -189,8 +228,8 @@ public async Task<SubAgentResult> SpawnAsync(
             });
 
             _logger.LogInformation(
-                "SubAgent [{AgentName}] completed (success={Success}, duration={Duration}ms)",
-                profile.Name, result.Success, sw.ElapsedMilliseconds);
+                "SubAgent [{AgentName}] completed (runId={RunId}, success={Success}, duration={Duration}ms)",
+                profile.Name, runId, result.Success, sw.ElapsedMilliseconds);
 
             return result;
         }
@@ -209,7 +248,7 @@ public async Task<SubAgentResult> SpawnAsync(
                 Duration = sw.Elapsed
             });
 
-            _logger.LogError(ex, "SubAgent [{AgentName}] spawn failed", profile.Name);
+            _logger.LogError(ex, "SubAgent [{AgentName}] run failed (runId={RunId})", profile.Name, runId);
             return new SubAgentResult
             {
                 Success = false,

src/Netclaw.Daemon.Tests/Mcp/ToolIndexUpdaterTests.cs

@@ -39,7 +39,7 @@ public async Task StartAsync_with_no_user_facing_agents_sets_actionable_discover
             loader,
             subAgentSpawner: null!,
             new SubAgentConfig(),
-            NullLogger<ToolIndexUpdater>.Instance);
+            NullLoggerFactory.Instance);
 
         await updater.StartAsync(TestContext.Current.CancellationToken);
 
@@ -92,7 +92,7 @@ public async Task StartAsync_keeps_public_tool_index_filtered_from_hidden_capabi
             loader,
             subAgentSpawner: null!,
             new SubAgentConfig { Enabled = false },
-            NullLogger<ToolIndexUpdater>.Instance);
+            NullLoggerFactory.Instance);
 
         await updater.StartAsync(TestContext.Current.CancellationToken);
 

src/Netclaw.Daemon/Mcp/ToolIndexUpdater.cs

@@ -27,6 +27,7 @@ internal sealed class ToolIndexUpdater : IHostedService
     private readonly FileSubAgentDefinitionLoader _agentLoader;
     private readonly SubAgentSpawner _subAgentSpawner;
     private readonly SubAgentConfig _subAgentConfig;
+    private readonly ILoggerFactory _loggerFactory;
     private readonly ILogger<ToolIndexUpdater> _logger;
 
     public ToolIndexUpdater(
@@ -38,7 +39,7 @@ public ToolIndexUpdater(
         FileSubAgentDefinitionLoader agentLoader,
         SubAgentSpawner subAgentSpawner,
         SubAgentConfig subAgentConfig,
-        ILogger<ToolIndexUpdater> logger)
+        ILoggerFactory loggerFactory)
     {
         _paths = paths;
         _shadowCatalogWriter = shadowCatalogWriter;
@@ -48,14 +49,17 @@ public ToolIndexUpdater(
         _agentLoader = agentLoader;
         _subAgentSpawner = subAgentSpawner;
         _subAgentConfig = subAgentConfig;
-        _logger = logger;
+        _loggerFactory = loggerFactory;
+        _logger = loggerFactory.CreateLogger<ToolIndexUpdater>();
     }
 
     public Task StartAsync(CancellationToken cancellationToken)
     {
         LoadFileBasedAgents();
 
-        _toolRegistry.Register(new SpawnAgentTool(_subAgentRegistry, _subAgentSpawner, _paths, _subAgentConfig, _agentLoader));
+        _toolRegistry.Register(new SpawnAgentTool(
+            _subAgentRegistry, _subAgentSpawner, _paths, _subAgentConfig, _agentLoader,
+            _loggerFactory.CreateLogger<SpawnAgentTool>()));
 
         _shadowCatalogWriter.WriteCatalogs();
         _logger.LogInformation("Tool index updated ({ToolCount} registrations)", _toolRegistry.GetAllRegistrations().Count);