mirror of
https://github.com/MindWorkAI/AI-Studio.git
synced 2026-08-11 17:32:11 +00:00
Improved logging for tool execution
This commit is contained in:
Peer Schütt
parent
c13255fe77
commit
f24e40b99f
@ -15,6 +15,7 @@ public sealed class ReadWebPageTool(WebPageRetrievalService webPageRetrievalServ
|
||||
private const int MAX_TIMEOUT_SECONDS = 60;
|
||||
private const int MAX_CONTENT_CHARACTERS = 50000;
|
||||
private const int MAX_TRACE_LENGTH = 12000;
|
||||
private const int MAX_LOG_URL_LENGTH = 2000;
|
||||
private const string ALLOWED_PRIVATE_HOSTS_SETTING = "allowedPrivateHosts";
|
||||
|
||||
public string ImplementationKey => ToolSelectionRules.READ_WEB_PAGE_TOOL_ID;
|
||||
@ -96,6 +97,14 @@ public sealed class ReadWebPageTool(WebPageRetrievalService webPageRetrievalServ
|
||||
var maxContentCharacters = Math.Min(ToolSettingsValueParser.ReadOptionalPositiveInt(context.SettingsValues, "maxContentCharacters") ?? DEFAULT_MAX_CONTENT_CHARACTERS, MAX_CONTENT_CHARACTERS);
|
||||
if (!TryReadAllowedPrivateHostPatterns(context.SettingsValues.GetValueOrDefault(ALLOWED_PRIVATE_HOSTS_SETTING), out var allowedPrivateHosts, out var allowlistError))
|
||||
throw new InvalidOperationException(allowlistError);
|
||||
|
||||
logger.LogInformation(
|
||||
"Starting web page retrieval. ToolCallId={ToolCallId}, Url={Url}, TimeoutSeconds={TimeoutSeconds}, MaxContentCharacters={MaxContentCharacters}",
|
||||
context.ToolCallId,
|
||||
FormatUrlForLog(url),
|
||||
timeoutSeconds,
|
||||
maxContentCharacters);
|
||||
|
||||
RetrievedWebPage retrievedPage;
|
||||
try
|
||||
{
|
||||
@ -134,6 +143,18 @@ public sealed class ReadWebPageTool(WebPageRetrievalService webPageRetrievalServ
|
||||
warnings.Add($"The extracted page content was truncated from {originalContentCharacters} to {markdown.Length} characters.");
|
||||
}
|
||||
|
||||
logger.LogInformation(
|
||||
"Completed web page retrieval. ToolCallId={ToolCallId}, RequestedUrl={RequestedUrl}, FinalUrl={FinalUrl}, WasRedirected={WasRedirected}, ContentType={ContentType}, OriginalContentCharacters={OriginalContentCharacters}, ReturnedContentCharacters={ReturnedContentCharacters}, ContentTruncated={ContentTruncated}, RequiredProviderConfidence={RequiredProviderConfidence}",
|
||||
context.ToolCallId,
|
||||
FormatUrlForLog(page.RequestedUrl),
|
||||
FormatUrlForLog(page.FinalUrl),
|
||||
!page.RequestedUrl.Equals(page.FinalUrl),
|
||||
page.ContentType,
|
||||
originalContentCharacters,
|
||||
markdown.Length,
|
||||
contentTruncated,
|
||||
retrievedPage.RequiredProviderConfidence);
|
||||
|
||||
return new ToolExecutionResult
|
||||
{
|
||||
JsonContent = BuildModelContent(page, extractedPage, retrievedPage.RetrievedAtUtc, markdown, originalContentCharacters, contentTruncated, warnings),
|
||||
@ -289,6 +310,29 @@ public sealed class ReadWebPageTool(WebPageRetrievalService webPageRetrievalServ
|
||||
return text;
|
||||
}
|
||||
|
||||
private static string FormatUrlForLog(Uri url)
|
||||
{
|
||||
var builder = new UriBuilder(url)
|
||||
{
|
||||
UserName = string.Empty,
|
||||
Password = string.Empty,
|
||||
Fragment = string.Empty,
|
||||
Query = string.Join("&", url.Query
|
||||
.TrimStart('?')
|
||||
.Split('&', StringSplitOptions.RemoveEmptyEntries)
|
||||
.Select(parameter =>
|
||||
{
|
||||
var separatorIndex = parameter.IndexOf('=');
|
||||
var name = separatorIndex >= 0 ? parameter[..separatorIndex] : parameter;
|
||||
return string.IsNullOrWhiteSpace(name) ? "*****" : $"{name}=*****";
|
||||
})),
|
||||
};
|
||||
var formattedUrl = builder.Uri.AbsoluteUri;
|
||||
return formattedUrl.Length <= MAX_LOG_URL_LENGTH
|
||||
? formattedUrl
|
||||
: $"{formattedUrl[..MAX_LOG_URL_LENGTH]}...";
|
||||
}
|
||||
|
||||
private readonly record struct AllowedPrivateHostPattern(string Host, bool IsWildcard)
|
||||
{
|
||||
public bool IsMatch(string normalizedHost) =>
|
||||
|
||||
@ -11,6 +11,7 @@ public sealed class SearXNGWebSearchTool : IToolImplementation
|
||||
|
||||
private readonly SearXNGSearchClient searchClient = new();
|
||||
private readonly SearXNGPageRetrievalService pageRetrievalService;
|
||||
private readonly ILogger<SearXNGWebSearchTool> logger;
|
||||
|
||||
private const int DEFAULT_MAX_RESULTS = 5;
|
||||
private const int DEFAULT_TIMEOUT_SECONDS = 20;
|
||||
@ -26,10 +27,12 @@ public sealed class SearXNGWebSearchTool : IToolImplementation
|
||||
private const int MAX_MIN_CONTENT_CHARACTERS_PER_RESULT = 3000;
|
||||
private const int MAX_PAGE_TIMEOUT_SECONDS = 30;
|
||||
private const int MAX_RETRIEVAL_TIMEOUT_SECONDS = 90;
|
||||
private const int MAX_LOG_QUERY_LENGTH = 1000;
|
||||
|
||||
public SearXNGWebSearchTool(WebPageRetrievalService webPageRetrievalService)
|
||||
public SearXNGWebSearchTool(WebPageRetrievalService webPageRetrievalService, ILogger<SearXNGWebSearchTool> logger)
|
||||
{
|
||||
this.pageRetrievalService = new SearXNGPageRetrievalService(webPageRetrievalService);
|
||||
this.logger = logger;
|
||||
}
|
||||
|
||||
public string ImplementationKey => ToolSelectionRules.WEB_SEARCH_TOOL_ID;
|
||||
@ -232,6 +235,17 @@ public sealed class SearXNGWebSearchTool : IToolImplementation
|
||||
if (page is > MAX_PAGE)
|
||||
throw new ArgumentException($"Argument 'page' must be less than or equal to {MAX_PAGE}.");
|
||||
|
||||
this.logger.LogInformation(
|
||||
"Starting web search. ToolCallId={ToolCallId}, Query={Query}, Categories=[{Categories}], Engines=[{Engines}], Language={Language}, TimeRange={TimeRange}, Page={Page}, Limit={Limit}",
|
||||
context.ToolCallId,
|
||||
FormatQueryForLog(query),
|
||||
string.Join(", ", categories),
|
||||
string.Join(", ", engines),
|
||||
language,
|
||||
timeRange,
|
||||
page,
|
||||
effectiveLimit);
|
||||
|
||||
var searchResponse = await this.searchClient.SearchAsync(
|
||||
new SearXNGSearchRequest(
|
||||
searchUri,
|
||||
@ -267,6 +281,20 @@ public sealed class SearXNGWebSearchTool : IToolImplementation
|
||||
if (retrievalResult.Results.Count == 0)
|
||||
resultObject["diagnostic"] = "No result page could be retrieved as readable public HTML. Pages may have failed, timed out, been blocked by network safety checks, used an unsupported content type, or contained no readable static content.";
|
||||
|
||||
var retrievalStatistics = retrievalResult.ErrorStatistics;
|
||||
this.logger.LogInformation(
|
||||
"Completed web search. ToolCallId={ToolCallId}, CandidateCount={CandidateCount}, ResultCount={ResultCount}, BlockedPageCount={BlockedPageCount}, PageTimeoutCount={PageTimeoutCount}, FailedPageCount={FailedPageCount}, EmptyContentCount={EmptyContentCount}, RetrievalTimedOut={RetrievalTimedOut}, ReturnedContentCharacters={ReturnedContentCharacters}, TruncatedResultCount={TruncatedResultCount}",
|
||||
context.ToolCallId,
|
||||
searchResponse.CandidateCount,
|
||||
retrievalResult.Results.Count,
|
||||
retrievalStatistics.BlockedCount,
|
||||
retrievalStatistics.PageTimedOutCount,
|
||||
retrievalStatistics.FailedCount,
|
||||
retrievalStatistics.EmptyContentCount,
|
||||
retrievalResult.RetrievalTimedOut,
|
||||
retrievalResult.Results.Sum(result => result.ReturnedMarkdown.Length),
|
||||
retrievalResult.Results.Count(result => result.ContentTruncated));
|
||||
|
||||
return new ToolExecutionResult
|
||||
{
|
||||
JsonContent = resultObject
|
||||
@ -382,6 +410,18 @@ public sealed class SearXNGWebSearchTool : IToolImplementation
|
||||
.Distinct(StringComparer.Ordinal)
|
||||
.ToList() ?? [];
|
||||
|
||||
private static string FormatQueryForLog(string query)
|
||||
{
|
||||
var singleLineQuery = query
|
||||
.Replace('\r', ' ')
|
||||
.Replace('\n', ' ')
|
||||
.Replace('\t', ' ')
|
||||
.Trim();
|
||||
return singleLineQuery.Length <= MAX_LOG_QUERY_LENGTH
|
||||
? singleLineQuery
|
||||
: $"{singleLineQuery[..MAX_LOG_QUERY_LENGTH]}...";
|
||||
}
|
||||
|
||||
private static bool TryNormalizeSearchUri(string rawUrl, out Uri searchUri, out string error) =>
|
||||
SearXNGSearchClient.TryNormalizeSearchUri(
|
||||
rawUrl,
|
||||
|
||||
@ -11,6 +11,8 @@ public sealed class ToolExecutionContext
|
||||
{
|
||||
public required ToolDefinition Definition { get; init; }
|
||||
|
||||
public string ToolCallId { get; init; } = string.Empty;
|
||||
|
||||
public required SettingsManager SettingsManager { get; init; }
|
||||
|
||||
public required IReadOnlyDictionary<string, string> SettingsValues { get; init; }
|
||||
|
||||
@ -30,10 +30,9 @@ public sealed class ToolExecutor(ToolSettingsService toolSettingsService, ILogge
|
||||
}
|
||||
|
||||
logger.LogInformation(
|
||||
"Starting tool execution. ToolName={ToolName}, ToolCallId={ToolCallId}, ArgumentNames={ArgumentNames}",
|
||||
"Starting tool execution. ToolName={ToolName}, ToolCallId={ToolCallId}",
|
||||
toolName,
|
||||
toolCallId,
|
||||
formattedArguments.Keys.OrderBy(x => x, StringComparer.Ordinal).ToList());
|
||||
toolCallId);
|
||||
var stopwatch = Stopwatch.StartNew();
|
||||
if (runnableTool.Definition is null || runnableTool.Implementation is null)
|
||||
{
|
||||
@ -61,6 +60,7 @@ public sealed class ToolExecutor(ToolSettingsService toolSettingsService, ILogge
|
||||
var result = await implementation.ExecuteAsync(document.RootElement, new ToolExecutionContext
|
||||
{
|
||||
Definition = definition,
|
||||
ToolCallId = toolCallId,
|
||||
SettingsManager = Program.SERVICE_PROVIDER.GetRequiredService<Settings.SettingsManager>(),
|
||||
SettingsValues = settingsValues,
|
||||
ProviderConfidence = providerConfidence,
|
||||
@ -87,11 +87,12 @@ public sealed class ToolExecutor(ToolSettingsService toolSettingsService, ILogge
|
||||
}
|
||||
catch (OperationCanceledException) when (token.IsCancellationRequested)
|
||||
{
|
||||
logger.LogInformation("Completed tool execution. ToolName={ToolName}, ToolCallId={ToolCallId}, DurationMs={DurationMs}, Status={Status}", toolName, toolCallId, stopwatch.ElapsedMilliseconds, "CANCELED");
|
||||
throw;
|
||||
}
|
||||
catch (ToolExecutionBlockedException exception)
|
||||
{
|
||||
logger.LogWarning(exception, "Tool execution was blocked. ToolName={ToolName}, ToolCallId={ToolCallId}, DurationMs={DurationMs}, Status={Status}, ErrorMessage={ErrorMessage}", toolName, toolCallId, stopwatch.ElapsedMilliseconds, ToolInvocationTraceStatus.BLOCKED, exception.Message);
|
||||
logger.LogWarning("Tool execution was blocked. ToolName={ToolName}, ToolCallId={ToolCallId}, DurationMs={DurationMs}, Status={Status}, Reason={Reason}", toolName, toolCallId, stopwatch.ElapsedMilliseconds, ToolInvocationTraceStatus.BLOCKED, exception.Message);
|
||||
|
||||
var toolInvocationTrace = new ToolInvocationTrace
|
||||
{
|
||||
@ -111,7 +112,7 @@ public sealed class ToolExecutor(ToolSettingsService toolSettingsService, ILogge
|
||||
catch (Exception exception)
|
||||
{
|
||||
var error = $"Tool execution failed: {exception.Message}";
|
||||
logger.LogError(exception, "Tool execution failed. ToolName={ToolName}, ToolCallId={ToolCallId}, DurationMs={DurationMs}, Status={Status}, ErrorMessage={ErrorMessage}", toolName, toolCallId, stopwatch.ElapsedMilliseconds, ToolInvocationTraceStatus.ERROR, exception.Message);
|
||||
logger.LogError(exception, "Tool execution failed. ToolName={ToolName}, ToolCallId={ToolCallId}, DurationMs={DurationMs}, Status={Status}", toolName, toolCallId, stopwatch.ElapsedMilliseconds, ToolInvocationTraceStatus.ERROR);
|
||||
|
||||
var toolInvocationTrace = new ToolInvocationTrace
|
||||
{
|
||||
|
||||
@ -226,32 +226,32 @@ public sealed class ToolRegistry
|
||||
{
|
||||
if (!this.settingsManager.AreToolsEnabled())
|
||||
{
|
||||
this.logger.LogInformation("Tool calling is skipped because tools are disabled by managed configuration.");
|
||||
this.logger.LogDebug("Tool calling is skipped because tools are disabled by managed configuration.");
|
||||
return [];
|
||||
}
|
||||
|
||||
if (!isToolSelectionVisible)
|
||||
{
|
||||
this.logger.LogInformation("Tool calling is skipped for component '{Component}' because tool selection is not visible.", component);
|
||||
this.logger.LogDebug("Tool calling is skipped for component '{Component}' because tool selection is not visible.", component);
|
||||
return [];
|
||||
}
|
||||
|
||||
var toolCallingAvailability = provider.GetToolCallingAvailability();
|
||||
if (!toolCallingAvailability.IsAvailable)
|
||||
{
|
||||
this.logger.LogInformation("Tool calling is unavailable for provider '{Provider}' with model '{ModelId}': {Reason}", provider.InstanceName, provider.Model.Id, toolCallingAvailability.Message);
|
||||
this.logger.LogDebug("Tool calling is unavailable for provider '{Provider}' with model '{ModelId}': {Reason}", provider.InstanceName, provider.Model.Id, toolCallingAvailability.Message);
|
||||
return [];
|
||||
}
|
||||
|
||||
if (!modelCapabilities.Contains(Capability.FUNCTION_CALLING) ||
|
||||
(!modelCapabilities.Contains(Capability.CHAT_COMPLETION_API) && !modelCapabilities.Contains(Capability.RESPONSES_API)))
|
||||
{
|
||||
this.logger.LogInformation("Tool calling is unavailable for provider '{Provider}' with model '{ModelId}' because the model lacks the required API or function-calling capability.", provider.InstanceName, provider.Model.Id);
|
||||
this.logger.LogDebug("Tool calling is unavailable for provider '{Provider}' with model '{ModelId}' because the model lacks the required API or function-calling capability.", provider.InstanceName, provider.Model.Id);
|
||||
return [];
|
||||
}
|
||||
|
||||
var selectedToolIdSet = ToolSelectionRules.NormalizeSelection(selectedToolIds);
|
||||
this.logger.LogInformation("Resolving runnable tools for provider '{Provider}' with model '{ModelId}'. Selected tool IDs: [{ToolIds}].", provider.InstanceName, provider.Model.Id, string.Join(", ", selectedToolIdSet.OrderBy(x => x, StringComparer.Ordinal)));
|
||||
this.logger.LogDebug("Resolving runnable tools for provider '{Provider}' with model '{ModelId}'. Selected tool IDs: [{ToolIds}].", provider.InstanceName, provider.Model.Id, string.Join(", ", selectedToolIdSet.OrderBy(x => x, StringComparer.Ordinal)));
|
||||
|
||||
var definitions = this.GetDefinitionsForComponent(component).Where(x => selectedToolIdSet.Contains(x.Id)).ToList();
|
||||
var result = new List<(ToolDefinition, IToolImplementation)>(definitions.Count);
|
||||
@ -259,26 +259,26 @@ public sealed class ToolRegistry
|
||||
{
|
||||
if (!this.settingsManager.IsToolActive(definition.Id))
|
||||
{
|
||||
this.logger.LogInformation("Skipping tool '{ToolId}' because it is disabled by managed configuration.", definition.Id);
|
||||
this.logger.LogDebug("Skipping tool '{ToolId}' because it is disabled by managed configuration.", definition.Id);
|
||||
continue;
|
||||
}
|
||||
|
||||
if (!this.implementationsByKey.TryGetValue(definition.ImplementationKey, out var implementation))
|
||||
{
|
||||
this.logger.LogInformation("Skipping tool '{ToolId}' because no implementation is registered.", definition.Id);
|
||||
this.logger.LogWarning("Skipping tool '{ToolId}' because no implementation is registered.", definition.Id);
|
||||
continue;
|
||||
}
|
||||
|
||||
var configurationState = await this.toolSettingsService.GetConfigurationStateAsync(definition, implementation);
|
||||
if (!configurationState.IsConfigured)
|
||||
{
|
||||
this.logger.LogInformation("Skipping tool '{ToolId}' because it is not configured.", definition.Id);
|
||||
this.logger.LogDebug("Skipping tool '{ToolId}' because it is not configured.", definition.Id);
|
||||
continue;
|
||||
}
|
||||
|
||||
var resolution = this.settingsManager.GetMinimumProviderConfidenceResolutionForTool(definition.Id);
|
||||
var minimumToolConfidence = resolution.ConfidenceLevel;
|
||||
this.logger.LogInformation("Tool '{ToolId}' uses minimum provider confidence '{ConfidenceLevel}' from {Source}.", definition.Id, minimumToolConfidence, resolution.Source);
|
||||
this.logger.LogDebug("Tool '{ToolId}' uses minimum provider confidence '{ConfidenceLevel}' from {Source}.", definition.Id, minimumToolConfidence, resolution.Source);
|
||||
|
||||
if (!ToolSelectionRules.IsProviderConfidenceAllowed(providerConfidence, minimumToolConfidence))
|
||||
{
|
||||
@ -290,7 +290,7 @@ public sealed class ToolRegistry
|
||||
}
|
||||
|
||||
foreach (var selectedToolId in selectedToolIdSet.Where(selectedToolId => definitions.All(definition => !definition.Id.Equals(selectedToolId, StringComparison.Ordinal))))
|
||||
this.logger.LogInformation("Skipping tool '{ToolId}' because it is not selected in this component or not available in this context.", selectedToolId);
|
||||
this.logger.LogDebug("Skipping tool '{ToolId}' because it is not selected in this component or not available in this context.", selectedToolId);
|
||||
|
||||
return result;
|
||||
}
|
||||
|
||||
Loading…
Reference in New Issue
Block a user