Skip to content

fix(streaming): thinking-only retry guard + 3-layer SSE/middleware/actor diagnostics + RollingFileLogger Debug fix #947

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
Aaronontheweb merged 3 commits into from
May 9, 2026
Merged

fix(streaming): thinking-only retry guard + 3-layer SSE/middleware/actor diagnostics + RollingFileLogger Debug fix #947

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
a64819c
fix: add response content diagnostics and thinking-only retry guard
Aaronontheweb May 7, 2026
3a86cf5
fix: inject ILoggerFactory so SSE-layer breakdown log actually fires
Aaronontheweb May 8, 2026
1bf8da3
fix(logging): drop hardcoded Information floor in RollingFileLogger (…
Aaronontheweb May 9, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
41 changes: 32 additions & 9 deletions src/Netclaw.Actors/Sessions/LlmSessionActor.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -363,6 +363,8 @@ private void Ready()
});

Command<ProcessingWatchdogExpired>(_ => { });
Command<LlmCallFailed>(_ => { }); // stale failure arriving after watchdog timeout
Copy link
Copy Markdown
Collaborator Author

@Aaronontheweb Aaronontheweb May 9, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

Command<LlmResponseReceived>(_ => { }); // stale response arriving after transition to Ready
Command<CompactionWorkCompleted>(_ => { });
Command<CompactionWorkFailed>(_ => { });
CommandDistillationAckNoOp();
Expand Down Expand Up @@ -443,8 +445,31 @@ private void Processing()
var response = msg.Response;
var lastMessage = response.Messages[^1];

// Check for tool calls
var toolCalls = lastMessage.Contents.OfType<FunctionCallContent>().ToList();
var toolCalls = new List<FunctionCallContent>();
bool hasText = false, hasThinking = false;
int textChars = 0, thinkingChars = 0;
foreach (var c in lastMessage.Contents)
{
switch (c)
{
case TextContent tc:
textChars += tc.Text?.Length ?? 0;
if (!string.IsNullOrWhiteSpace(tc.Text)) hasText = true;
break;
case TextReasoningContent rc:
thinkingChars += rc.Text?.Length ?? 0;
if (!string.IsNullOrWhiteSpace(rc.Text)) hasThinking = true;
break;
case FunctionCallContent fc:
toolCalls.Add(fc);
break;
}
}

_log.Debug(
"LLM response content breakdown: text={TextChars}ch thinking={ThinkingChars}ch toolCalls={ToolCallCount} finishReason={FinishReason}",
textChars, thinkingChars, toolCalls.Count, response.FinishReason?.ToString() ?? "null");

if (toolCalls.Count > 0 && _turnState.ForceNoToolsActive)
{
TurnLog().Warning(
Expand All @@ -465,21 +490,19 @@ private void Processing()
return;
}

// Guard: empty response (no text, no thinking, no tool calls) — delegate decision to tracker
var hasContent = lastMessage.Contents.Any(c =>
(c is TextContent tc && !string.IsNullOrWhiteSpace(tc.Text)) ||
(c is TextReasoningContent rc && !string.IsNullOrWhiteSpace(rc.Text)));
if (!hasContent)
if (!hasText && toolCalls.Count == 0)
Comment thread
Aaronontheweb marked this conversation as resolved.
{
var label = hasThinking ? "thinking-only" : "empty";
switch (_turnState.EvaluateEmptyResponse())
{
case EmptyResponseAction.Retry retry:
_log.Warning("LLM produced empty response — retrying with nudge");
_log.Warning("LLM produced {Label} response ({ThinkingChars} chars) — retrying with nudge",
label, thinkingChars);
_state = _state.AddSystemNudge(retry.NudgeText);
FireLlmCall();
return;
case EmptyResponseAction.Fail fail:
_log.Warning("LLM produced empty response — failing turn");
_log.Warning("LLM produced {Label} response — failing turn", label);
FailCurrentTurn(fail.ErrorMessage, fail.Cause, ErrorCategory.ProviderFailure);
return;
}
Expand Down
37 changes: 34 additions & 3 deletions src/Netclaw.Daemon/Configuration/LoggingChatClient.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -72,6 +72,12 @@ public override async IAsyncEnumerable<ChatResponseUpdate> GetStreamingResponseA
var start = _timeProvider.GetTimestamp();
long inputTokens = 0;
long outputTokens = 0;
int textDeltaCount = 0;
int textDeltaChars = 0;
int thinkingDeltaCount = 0;
int thinkingDeltaChars = 0;
int toolCallDeltaCount = 0;
ChatFinishReason? lastFinishReason = null;

IAsyncEnumerable<ChatResponseUpdate> stream;
try
Expand All @@ -87,16 +93,41 @@ public override async IAsyncEnumerable<ChatResponseUpdate> GetStreamingResponseA

await foreach (var update in stream)
{
if (update.Contents?.OfType<UsageContent>().FirstOrDefault() is { } usage)
foreach (var item in update.Contents)
{
inputTokens += usage.Details?.InputTokenCount ?? 0;
outputTokens += usage.Details?.OutputTokenCount ?? 0;
switch (item)
{
case TextContent tc:
textDeltaCount++;
textDeltaChars += tc.Text?.Length ?? 0;
break;
case TextReasoningContent rc:
thinkingDeltaCount++;
thinkingDeltaChars += rc.Text?.Length ?? 0;
break;
case FunctionCallContent:
toolCallDeltaCount++;
break;
case UsageContent usage:
inputTokens += usage.Details?.InputTokenCount ?? 0;
outputTokens += usage.Details?.OutputTokenCount ?? 0;
break;
}
}

if (update.FinishReason is not null)
lastFinishReason = update.FinishReason;

yield return update;
}

var totalElapsed = _timeProvider.GetElapsedTime(start);

_logger.LogDebug(
"LLM streaming response content breakdown: textDeltas={TextDeltaCount} textChars={TextChars} thinkingDeltas={ThinkingDeltaCount} thinkingChars={ThinkingChars} toolCallDeltas={ToolCallDeltaCount} finishReason={FinishReason}",
textDeltaCount, textDeltaChars, thinkingDeltaCount, thinkingDeltaChars, toolCallDeltaCount,
lastFinishReason?.ToString() ?? "null");

if (inputTokens > 0 || outputTokens > 0)
{
var delta = RecordInputTokens(inputTokens);
Expand Down
2 changes: 1 addition & 1 deletion src/Netclaw.Daemon/Configuration/RollingFileLoggerProvider.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -212,7 +212,7 @@ public RollingFileLogger(string category, RollingFileLoggerProvider provider)

public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;

public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel.Information;
public bool IsEnabled(LogLevel logLevel) => logLevel != LogLevel.None;
Copy link
Copy Markdown
Collaborator Author

@Aaronontheweb Aaronontheweb May 9, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ensures that debug logs can actually show up now


public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{
Expand Down
24 changes: 23 additions & 1 deletion src/Netclaw.Providers/SelfHosted/OpenAiCompatibleChatClient.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,8 @@
using System.Text.Json;
using System.Text.Json.Nodes;
using Microsoft.Extensions.AI;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;

namespace Netclaw.Providers.SelfHosted;

Expand All @@ -22,11 +24,15 @@ public sealed class OpenAiCompatibleChatClient : IChatClient
private readonly HttpClient _httpClient;
private readonly OpenAiCompatibleEndpoint _endpoint;
private readonly string _modelId;
public OpenAiCompatibleChatClient(HttpClient httpClient, OpenAiCompatibleEndpoint endpoint, string modelId)
private readonly ILogger _logger;

public OpenAiCompatibleChatClient(HttpClient httpClient, OpenAiCompatibleEndpoint endpoint, string modelId,
ILogger? logger = null)
{
_httpClient = httpClient;
_endpoint = endpoint;
_modelId = modelId;
_logger = logger ?? NullLogger.Instance;
}

public async Task<ChatResponse> GetResponseAsync(
Expand Down Expand Up @@ -67,6 +73,9 @@ public async IAsyncEnumerable<ChatResponseUpdate> GetStreamingResponseAsync(
var hadStructuredToolCalls = false;
ChatResponseUpdate? finalUpdate = null;
var filter = new ToolCallTextFilter();
int textDeltaCount = 0, textDeltaChars = 0;
int thinkingDeltaCount = 0, thinkingDeltaChars = 0;
int toolCallDeltaCount = 0, suppressedDeltaCount = 0;

while (!cancellationToken.IsCancellationRequested)
{
Expand Down Expand Up @@ -99,11 +108,18 @@ public async IAsyncEnumerable<ChatResponseUpdate> GetStreamingResponseAsync(
{
case TextContent tc:
accumulatedText.Append(tc.Text);
textDeltaCount++;
textDeltaChars += tc.Text?.Length ?? 0;
if (filter.ShouldSuppress(tc.Text))
suppressThisUpdate = true;
break;
case TextReasoningContent rc:
thinkingDeltaCount++;
thinkingDeltaChars += rc.Text?.Length ?? 0;
break;
case FunctionCallContent:
hadStructuredToolCalls = true;
toolCallDeltaCount++;
break;
}
}
Expand All @@ -115,6 +131,7 @@ public async IAsyncEnumerable<ChatResponseUpdate> GetStreamingResponseAsync(
// content-free keepalive so the caller knows the stream is alive.
if (suppressThisUpdate)
{
suppressedDeltaCount++;
yield return KeepaliveUpdate;
continue;
}
Expand All @@ -123,6 +140,11 @@ public async IAsyncEnumerable<ChatResponseUpdate> GetStreamingResponseAsync(
}
}

_logger.LogDebug(
"SSE stream content breakdown: textDeltas={TextDeltas} textChars={TextChars} thinkingDeltas={ThinkingDeltas} thinkingChars={ThinkingChars} toolCallDeltas={ToolCallDeltas} suppressedDeltas={SuppressedDeltas} finishReason={FinishReason}",
textDeltaCount, textDeltaChars, thinkingDeltaCount, thinkingDeltaChars, toolCallDeltaCount,
suppressedDeltaCount, finalUpdate?.FinishReason?.ToString() ?? "null");

// Fallback: if the model stopped without structured tool calls but the text
// contains XML-like tool call blocks, emit a synthetic tool call update.
if (!hadStructuredToolCalls
Expand Down
12 changes: 10 additions & 2 deletions src/Netclaw.Providers/SelfHosted/OpenAiCompatibleProviderPlugin.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@
// </copyright>
// -----------------------------------------------------------------------
using Microsoft.Extensions.AI;
using Microsoft.Extensions.Logging;
using Netclaw.Configuration;
using Netclaw.Providers;

Expand All @@ -14,7 +15,13 @@ namespace Netclaw.Providers.SelfHosted;
/// </summary>
public sealed class OpenAiCompatibleProviderPlugin : ProviderPluginBase<OpenAiCompatibleDescriptor>
{
public OpenAiCompatibleProviderPlugin(OpenAiCompatibleDescriptor descriptor) : base(descriptor) { }
private readonly ILoggerFactory _loggerFactory;

public OpenAiCompatibleProviderPlugin(OpenAiCompatibleDescriptor descriptor, ILoggerFactory loggerFactory)
: base(descriptor)
{
_loggerFactory = loggerFactory;
}

public override IChatClient CreateChatClient(ProviderEntry entry, ModelReference model)
{
Expand All @@ -25,6 +32,7 @@ public override IChatClient CreateChatClient(ProviderEntry entry, ModelReference
return new OpenAiCompatibleChatClient(
CreateLlmHttpClient(endpoint.BaseUri),
endpoint,
model.ModelId);
model.ModelId,
_loggerFactory.CreateLogger<OpenAiCompatibleChatClient>());
}
}
Loading