fix(subagents): session-correlated sub-agent log observability

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

@@ -0,0 +1,109 @@
+// -----------------------------------------------------------------------
+// <copyright file="SubAgentObservabilityTests.cs" company="Petabridge, LLC">
+//      Copyright (C) 2026 - 2026 Petabridge, LLC <https://petabridge.com>
+// </copyright>
+// -----------------------------------------------------------------------
+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;
+
+/// <summary>
+/// Observability coverage for <see cref="SubAgentActor"/>: 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.
+/// </summary>
+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<INetclawTool>? 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<SubAgentResult>(
+                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<SubAgentResult>(
+                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<string, object?> { ["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<SubAgentResult>(
+                NewRun("Greet the user"), TimeSpan.FromSeconds(5), TestContext.Current.CancellationToken);
+        }, cancellationToken: TestContext.Current.CancellationToken);
+    }
+}

src/Netclaw.Actors/SubAgents/SubAgentActor.cs

@@ -1,4 +1,4 @@
-// -----------------------------------------------------------------------
+// -----------------------------------------------------------------------
 // <copyright file="SubAgentActor.cs" company="Petabridge, LLC">
 //      Copyright (C) 2026 - 2026 Petabridge, LLC <https://petabridge.com>
 // </copyright>
@@ -64,10 +64,15 @@ [Subagent Execution Contract]
     private readonly int _maxToolIterations;
     private readonly ToolRegistry _toolRegistry;
     private IReadOnlyList<AITool> _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<AiChatMessage> _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<FunctionCallCo
                 ? JsonSerializer.Serialize(toolCall.Arguments)
                 : null;
             _turnState.TrackToolCall(toolCall.Name, argsJson);
+
+            // Log tool START event so tool execution spans are visible in Seq
+            // (previously only tool results were logged, making it impossible to
+            // correlate tool start with tool end when tools take a long time).
+            _log.Info("SubAgent [{AgentName}] tool start callId={ToolCallId} name={ToolName}",
+                _definition.Name, toolCall.CallId ?? "unknown", toolCall.Name);
         }
 
         var toolNames = string.Join(", ", toolCalls.Select(tc => 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);
 
-    /// <summary>Emit a liveness/progress item to the spawning tool's stream, if any.</summary>
-    private void EmitActivity(string phase, bool suspendsInactivityWatchdog = false)
-        => _activitySink?.TryWrite(new ToolActivityUpdate(phase)
+    /// <summary>
+    /// 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
+    /// <see cref="_activitySink"/> is null), correlated by SessionId/SubSessionId.
+    /// The per-delta streaming ping passes <paramref name="log"/> = false because the
+    /// <see cref="SubAgentStreamPing"/> handler already logs that liveness at Debug —
+    /// logging it here too would emit one Info line per streamed delta.
+    /// </summary>
+    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
         });
+    }
 
     /// <summary>
     /// Record forward progress in the tool loop / post-approval: re-baseline the

src/Netclaw.Actors/SubAgents/SubAgentSpawner.cs

@@ -1,4 +1,4 @@
-// -----------------------------------------------------------------------
+// -----------------------------------------------------------------------
 // <copyright file="SubAgentSpawner.cs" company="Petabridge, LLC">
 //      Copyright (C) 2026 - 2026 Petabridge, LLC <https://petabridge.com>
 // </copyright>
@@ -156,9 +156,11 @@ public async Task<SubAgentResult> 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<INetclawTool> 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);
             }