diff --git a/src/Netclaw.Actors.Tests/SubAgents/SubAgentSpawnObservabilityTests.cs b/src/Netclaw.Actors.Tests/SubAgents/SubAgentSpawnObservabilityTests.cs new file mode 100644 index 000000000..2bedfcb23 --- /dev/null +++ b/src/Netclaw.Actors.Tests/SubAgents/SubAgentSpawnObservabilityTests.cs @@ -0,0 +1,118 @@ +// ----------------------------------------------------------------------- +// +// Copyright (C) 2026 - 2026 Petabridge, LLC +// +// ----------------------------------------------------------------------- +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; + +/// +/// 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 session.log. 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 RollingFileLoggerProvider uses to route a line to +/// session.log. +/// +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(); + // 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(); + 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 { ["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 : ILogger + { + public readonly List<(LogLevel Level, string Message, string? SessionScope)> Entries = new(); + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + => Entries.Add((logLevel, formatter(state, exception), SessionDiagnosticsContext.SessionId)); + } +} diff --git a/src/Netclaw.Actors/SubAgents/SpawnAgentTool.cs b/src/Netclaw.Actors/SubAgents/SpawnAgentTool.cs index ddc4980e1..1da3cabd8 100644 --- a/src/Netclaw.Actors/SubAgents/SpawnAgentTool.cs +++ b/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 private readonly NetclawPaths _paths; private readonly SubAgentConfig _subAgentConfig; private readonly FileSubAgentDefinitionLoader? _loader; + private readonly ILogger? _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? logger = null) { _registry = registry; _spawner = spawner; _paths = paths; _subAgentConfig = subAgentConfig ?? new SubAgentConfig(); _loader = loader; + _logger = logger; } protected override Task ExecuteAsync(Params args, CancellationToken ct) @@ -116,10 +120,22 @@ private static string FormatResult(string agent, SubAgentResult result) /// 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); diff --git a/src/Netclaw.Actors/SubAgents/SubAgentSpawner.cs b/src/Netclaw.Actors/SubAgents/SubAgentSpawner.cs index 8a6ed52e6..7e8c793de 100644 --- a/src/Netclaw.Actors/SubAgents/SubAgentSpawner.cs +++ b/src/Netclaw.Actors/SubAgents/SubAgentSpawner.cs @@ -66,6 +66,16 @@ public async Task SpawnAsync( string? systemPromptOverlay = null, ChannelWriter? 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 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 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 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, diff --git a/src/Netclaw.Daemon.Tests/Mcp/ToolIndexUpdaterTests.cs b/src/Netclaw.Daemon.Tests/Mcp/ToolIndexUpdaterTests.cs index 0f40b0772..08843852e 100644 --- a/src/Netclaw.Daemon.Tests/Mcp/ToolIndexUpdaterTests.cs +++ b/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.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.Instance); + NullLoggerFactory.Instance); await updater.StartAsync(TestContext.Current.CancellationToken); diff --git a/src/Netclaw.Daemon/Mcp/ToolIndexUpdater.cs b/src/Netclaw.Daemon/Mcp/ToolIndexUpdater.cs index eec4c03f3..aceb81739 100644 --- a/src/Netclaw.Daemon/Mcp/ToolIndexUpdater.cs +++ b/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 _logger; public ToolIndexUpdater( @@ -38,7 +39,7 @@ public ToolIndexUpdater( FileSubAgentDefinitionLoader agentLoader, SubAgentSpawner subAgentSpawner, SubAgentConfig subAgentConfig, - ILogger 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(); } 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())); _shadowCatalogWriter.WriteCatalogs(); _logger.LogInformation("Tool index updated ({ToolCount} registrations)", _toolRegistry.GetAllRegistrations().Count);