diff --git a/src/Netclaw.Actors.Tests/SubAgents/SubAgentObservabilityTests.cs b/src/Netclaw.Actors.Tests/SubAgents/SubAgentObservabilityTests.cs new file mode 100644 index 000000000..304667b2e --- /dev/null +++ b/src/Netclaw.Actors.Tests/SubAgents/SubAgentObservabilityTests.cs @@ -0,0 +1,109 @@ +// ----------------------------------------------------------------------- +// +// Copyright (C) 2026 - 2026 Petabridge, LLC +// +// ----------------------------------------------------------------------- +using Akka.Actor; +using Akka.Hosting; +using Akka.Hosting.TestKit; +using Microsoft.Extensions.AI; +using Netclaw.Actors.SubAgents; +using Netclaw.Actors.Tests.Memory; +using Netclaw.Configuration; +using Netclaw.Tools; +using Xunit; + +namespace Netclaw.Actors.Tests.SubAgents; + +/// +/// Observability coverage for : progress phases and +/// lifecycle events must surface in the logs (and therefore Seq) even on the +/// non-streaming spawn path, where the actor has no activity sink to write to. +/// Before the observability work these phases only reached a parent-owned channel +/// (or, with no sink, nothing at all). Regression coverage for issues #1429/#1431. +/// +public sealed class SubAgentObservabilityTests : TestKit +{ + public SubAgentObservabilityTests(ITestOutputHelper output) : base(output: output) { } + + protected override void ConfigureAkka(AkkaConfigurationBuilder builder, IServiceProvider provider) + { + // INFO so the EventFilter assertions on the sub-agent's progress and + // lifecycle logs are deterministic. + builder.AddHocon("akka.loglevel = INFO", HoconAddMode.Prepend); + } + + private static SubAgentDefinition CreateDefinition(IReadOnlyList? tools = null) + => new() + { + Name = new AgentName("test-agent"), + SystemPrompt = "You are a test agent.", + Tools = tools ?? [], + EmitStructuredFindings = false + }; + + private static RunSubAgent NewRun(string task, string? scopeId = null) + => new() + { + Task = task, + Timeout = TimeSpan.FromSeconds(5), + Audience = TrustAudience.Personal, + SessionScopeId = scopeId + }; + + [Fact] + public async Task Progress_phase_is_logged_on_the_non_streaming_path() + { + // No ActivitySink is supplied (the non-streaming spawn_agent path). Before + // the fix EmitActivity was a no-op here, so a long run emitted almost nothing + // between start and completion. Now the phase is logged, so it is visible and + // diagnosable in Seq. The scope id mirrors a real spawn so the SessionId/ + // SubSessionId enrichment branch is exercised too. + var agent = Sys.ActorOf(SubAgentActor.CreateProps(CreateDefinition(), new FakeChatClient())); + + await EventFilter.Info(contains: "calling the model").ExpectAsync(1, async () => + { + await agent.Ask( + NewRun("Say hello", "console/C123/subagent/test-agent/run-abc"), + TimeSpan.FromSeconds(5), + TestContext.Current.CancellationToken); + }, cancellationToken: TestContext.Current.CancellationToken); + } + + [Fact] + public async Task Completion_emits_summary_with_cumulative_stats() + { + var agent = Sys.ActorOf(SubAgentActor.CreateProps(CreateDefinition(), new FakeChatClient())); + + // The summary line carries the cumulative tool/iteration/duration stats used + // for sub-agent run analysis. + await EventFilter.Info(contains: "summary:").ExpectAsync(1, async () => + { + await agent.Ask( + NewRun("Say hello"), TimeSpan.FromSeconds(5), TestContext.Current.CancellationToken); + }, cancellationToken: TestContext.Current.CancellationToken); + } + + [Fact] + public async Task Tool_dispatch_logs_a_tool_start_event_with_call_id() + { + var fakeTool = new FakeNetclawTool("greet", "Hello from tool!"); + var fakeClient = new FakeChatClient + { + ToolCallsOnFirstCall = + [ + new FunctionCallContent("call-1", "greet", + new Dictionary { ["name"] = "World" }) + ] + }; + var agent = Sys.ActorOf(SubAgentActor.CreateProps(CreateDefinition([fakeTool]), fakeClient)); + + // A tool start event (distinct from the existing tool-result log) lets an + // operator see when a slow tool began, not just when it finished. + await EventFilter.Info(contains: "tool start callId=call-1 name=greet").ExpectAsync(1, async () => + { + await agent.Ask( + NewRun("Greet the user"), TimeSpan.FromSeconds(5), TestContext.Current.CancellationToken); + }, cancellationToken: TestContext.Current.CancellationToken); + } +} diff --git a/src/Netclaw.Actors/SubAgents/SubAgentActor.cs b/src/Netclaw.Actors/SubAgents/SubAgentActor.cs index af2fc8417..83f1b7fdc 100644 --- a/src/Netclaw.Actors/SubAgents/SubAgentActor.cs +++ b/src/Netclaw.Actors/SubAgents/SubAgentActor.cs @@ -1,4 +1,4 @@ -// ----------------------------------------------------------------------- +// ----------------------------------------------------------------------- // // Copyright (C) 2026 - 2026 Petabridge, LLC // @@ -64,10 +64,15 @@ [Subagent Execution Contract] private readonly int _maxToolIterations; private readonly ToolRegistry _toolRegistry; private IReadOnlyList _aiTools = []; - private readonly ILoggingAdapter _log; + private ILoggingAdapter _log; private readonly MemoryPolicyEvaluator _policyEvaluator = new(); private readonly TurnStateTracker _turnState = new(); + // Stopwatch tracking the total wall-clock duration of the sub-agent run. + // Used for the summary log on completion (ProcessingWatchdog is only a + // timer scheduler — it doesn't track elapsed time itself). + private readonly Stopwatch _runStopwatch = Stopwatch.StartNew(); + // Conversation state (not persisted — ephemeral) private readonly List _history = []; private long _llmCallId; @@ -247,6 +252,22 @@ private void Idle() var self = Self; // Capture before callback — Self requires active actor context _externalCancellationRegistration = msg.Cancellation.Register(() => self.Tell(SubAgentCancelled.Instance)); + // Enrich the logger so every sub-agent log line correlates back to the + // parent session (SessionId) and to this specific sub-agent run + // (SubSessionId), and is plainly attributable to the sub-agent. scopeId is + // "{parentSessionId}/subagent/{name}/{runId}"; NormalizeSessionId strips the + // "/subagent/..." suffix to recover the parent. SessionId matches the key the + // session/channel actors already use (see SessionLoggingScope), so sub-agent + // and parent logs share one filterable attribute; SubSessionId isolates a + // single run within that session. + var parentSessionId = SessionDiagnosticsContext.NormalizeSessionId(scopeId); + var enrichedLog = Context.GetLogger(); + if (!string.IsNullOrWhiteSpace(parentSessionId)) + enrichedLog = enrichedLog.WithContext("SessionId", parentSessionId); + if (!string.IsNullOrWhiteSpace(scopeId)) + enrichedLog = enrichedLog.WithContext("SubSessionId", scopeId); + _log = enrichedLog; + // The run is bounded by a two-phase inactivity watchdog re-armed on // every progress event (LLM response, tool batch, streaming delta, // keepalive) plus a keepalive-immune no-progress deadline. A sub-agent @@ -578,7 +599,9 @@ private void Processing() _interDeltaBudget, Timers); - EmitActivity("the model is responding"); + // log: false — the SubAgentStreamPing handler above already logs this + // liveness at Debug; an Info line per streamed delta would flood Seq. + EmitActivity("the model is responding", log: false); }); } @@ -595,6 +618,12 @@ private void HandleToolCalls(AiChatMessage assistantMessage, List tc.Name)); @@ -689,6 +718,15 @@ private void Complete(bool success, string output) _log.Info("SubAgent [{AgentName}] completed (success={Success}, output={OutputLength} chars, iterations={Iterations})", _definition.Name, success, output.Length, _turnState.ToolIterationCount); + // Log cumulative stats for observability — total LLM calls, tool usage, etc. + // This gives operators a single summary line for sub-agent duration analysis. + _log.Info( + "SubAgent [{AgentName}] summary: success={Success}, totalToolCalls={TotalToolCalls}, " + + "iterations={Iterations}, duration={Duration}s", + _definition.Name, success, _turnState.ToolCallCount, + _turnState.ToolIterationCount, + _runStopwatch.Elapsed.TotalSeconds); + var findings = success && _definition.EmitStructuredFindings ? BuildFindings(output, _toolExecutionContext.SessionId) : []; @@ -721,12 +759,24 @@ private void StartLlmCallWatchdog() private void RestartWatchdog(TimeSpan budget) => _watchdog.Start(ProcessingWatchdog.LlmCall, budget, Timers); - /// Emit a liveness/progress item to the spawning tool's stream, if any. - private void EmitActivity(string phase, bool suspendsInactivityWatchdog = false) - => _activitySink?.TryWrite(new ToolActivityUpdate(phase) + /// + /// Emit a liveness/progress item to the spawning tool's stream (if any) and log + /// the phase so it is visible in Seq even on non-streaming spawn paths (where + /// is null), correlated by SessionId/SubSessionId. + /// The per-delta streaming ping passes = false because the + /// handler already logs that liveness at Debug — + /// logging it here too would emit one Info line per streamed delta. + /// + private void EmitActivity(string phase, bool suspendsInactivityWatchdog = false, bool log = true) + { + if (log) + _log.Info("SubAgent [{AgentName}] {Phase}", _definition.Name, phase); + + _activitySink?.TryWrite(new ToolActivityUpdate(phase) { SuspendsInactivityWatchdog = suspendsInactivityWatchdog }); + } /// /// Record forward progress in the tool loop / post-approval: re-baseline the diff --git a/src/Netclaw.Actors/SubAgents/SubAgentSpawner.cs b/src/Netclaw.Actors/SubAgents/SubAgentSpawner.cs index 46b1381a5..6fc1add45 100644 --- a/src/Netclaw.Actors/SubAgents/SubAgentSpawner.cs +++ b/src/Netclaw.Actors/SubAgents/SubAgentSpawner.cs @@ -1,4 +1,4 @@ -// ----------------------------------------------------------------------- +// ----------------------------------------------------------------------- // // Copyright (C) 2026 - 2026 Petabridge, LLC // @@ -156,9 +156,11 @@ public async Task SpawnAsync( ParentCwd = context.ResolveShellCwd(null), Cancellation = ct, ApprovalBridge = context.ApprovalBridge, - // Null for non-streaming callers such as routed skills and - // the legacy ExecuteAsync path. Streaming spawn_agent calls - // pass a real sink so parent tool liveness sees progress. + // Null for non-streaming callers such as routed skills and the + // legacy ExecuteAsync path; the sub-agent surfaces its progress + // through its own session-correlated logs regardless. Streaming + // spawn_agent calls pass a real sink so the parent tool's + // liveness watchdog sees progress. ActivitySink = activitySink }, // No Ask timeout: a healthy run is bounded by the sub-agent's own @@ -237,7 +239,10 @@ private IReadOnlyList ResolveTools(SubAgentProfile profile, ToolEx } else { - _logger.LogDebug( + // Log at INFO so tool denials are visible in production logs. + // Sub-agents without certain tools may be unable to complete + // their tasks, and this information is important for debugging. + _logger.LogInformation( "SubAgent [{AgentName}] tool '{ToolName}' denied by SubAgentToolPolicy", profile.Name, tool.Name); }