From fc3cd94770538638db9da4e19a4c9570d50fac2e Mon Sep 17 00:00:00 2001 From: Thomas Kaul <4159106+dtslvr@users.noreply.github.com> Date: Sat, 31 Oct 2026 17:31:49 +0100 Subject: [PATCH] Task/improve logging of web fetch tool (#8365) * Improve logging of web_fetch tool and validation of routes * Update changelog --- CHANGELOG.md | 2 + apps/api/src/helper/web-fetch.helper.spec.ts | 22 +- apps/api/src/helper/web-fetch.helper.ts | 16 + .../src/services/fetch/fetch.service.spec.ts | 274 ++++++++++++++++++ apps/api/src/services/fetch/fetch.service.ts | 185 ++++++++++-- 5 files changed, 473 insertions(+), 26 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 392d03c480..8200209ec6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Changed +- Improved the logging of the `web_fetch` tool in the `FetchService` +- Improved the validation of the `WEB_FETCH_ROUTES` setting in the `FetchService` - Improved the validation of the response of the `web_fetch` tool in the `FetchService` - Deprecated the `api/v1/admin/user`, `api/v1/user/:id` and `api/v1/user/:id/access-token` endpoints in favor of the `api/v1/users` endpoints - Improved the language localization for German (`de`) diff --git a/apps/api/src/helper/web-fetch.helper.spec.ts b/apps/api/src/helper/web-fetch.helper.spec.ts index 0759b65005..aa0f756897 100644 --- a/apps/api/src/helper/web-fetch.helper.spec.ts +++ b/apps/api/src/helper/web-fetch.helper.spec.ts @@ -1,4 +1,4 @@ -import { getWebFetchBody } from './web-fetch.helper'; +import { getWebFetchBody, getWebFetchError } from './web-fetch.helper'; const FAILURE_MESSAGE = '{"url":"https://www.example.com/data.json","status":"failed","error":"HTTP 405: Method Not Allowed","_failure_reason":"http_error","http_status":405}'; @@ -110,3 +110,23 @@ describe('getWebFetchBody', () => { }); }); }); + +describe('getWebFetchError', () => { + it.each([ + ['the raw message', FAILURE_MESSAGE], + ['a text around the message', `Failed:\n\n${FAILURE_MESSAGE}\n\nSorry.`] + ])('should get the error from %s', (_, candidate) => { + expect(getWebFetchError({ candidate })).toBe( + 'HTTP 405: Method Not Allowed' + ); + }); + + it.each([ + ['a body', BODY], + ['a text', 'The fetch did not succeed.'], + ['an empty text', ''], + ['broken JSON', '{"status":"failed",'] + ])('should get no error from %s', (_, candidate) => { + expect(getWebFetchError({ candidate })).toBeUndefined(); + }); +}); diff --git a/apps/api/src/helper/web-fetch.helper.ts b/apps/api/src/helper/web-fetch.helper.ts index 530c41a5d9..d54e185373 100644 --- a/apps/api/src/helper/web-fetch.helper.ts +++ b/apps/api/src/helper/web-fetch.helper.ts @@ -29,6 +29,22 @@ export function getWebFetchBody({ return json?.isWhole ? json.text : undefined; } +/** + * Gets the error of a failed fetch from a candidate of the `web_fetch` tool. + * Gives back `undefined` if the candidate has no failure message. + */ +export function getWebFetchError({ + candidate +}: { + candidate: string; +}): string | undefined { + const value = extractJson(candidate.trim())?.value; + + return isWebFetchFailureMessage(value) + ? (value as { error: string }).error + : undefined; +} + /** * Extracts the JSON object or array from a text. The JSON must start at the * beginning of a line and goes to the last matching closing bracket, so that a diff --git a/apps/api/src/services/fetch/fetch.service.spec.ts b/apps/api/src/services/fetch/fetch.service.spec.ts index 9659a038f0..e53fe4587b 100644 --- a/apps/api/src/services/fetch/fetch.service.spec.ts +++ b/apps/api/src/services/fetch/fetch.service.spec.ts @@ -2,6 +2,7 @@ import { PropertyService } from '@ghostfolio/api/services/property/property.serv import { PROPERTY_API_KEY_OPENROUTER, PROPERTY_OPENROUTER_ENGINE_WEB_FETCH, + PROPERTY_OPENROUTER_MODEL, PROPERTY_OPENROUTER_MODEL_WEB_FETCH, PROPERTY_WEB_FETCH_ROUTES } from '@ghostfolio/common/config'; @@ -250,6 +251,279 @@ describe('FetchService', () => { expect(directFetch).toHaveBeenCalledTimes(1); }); + describe('logging', () => { + let error: jest.SpyInstance; + let log: jest.SpyInstance; + let warn: jest.SpyInstance; + + beforeEach(() => { + error = jest.spyOn(Logger.prototype, 'error').mockImplementation(); + log = jest.spyOn(Logger.prototype, 'log').mockImplementation(); + warn = jest.spyOn(Logger.prototype, 'warn').mockImplementation(); + }); + + afterEach(() => { + error.mockRestore(); + log.mockRestore(); + warn.mockRestore(); + }); + + it('should log a successful web fetch', async () => { + mockGenerateText({ text: BODY }); + + await fetchService.fetch(URL_WITH_ROUTE); + + expect(log).toHaveBeenCalledTimes(1); + expect(log.mock.calls[0][0]).toMatch( + /\(engine=parallel finishReason=stop model=model duration=\d+ms\)$/ + ); + expect(warn).not.toHaveBeenCalled(); + }); + + it('should log the finish reason of a body from a source', async () => { + mockGenerateText({ + finishReason: 'length', + sources: [{ providerMetadata: { openrouter: { content: BODY } } }], + text: '{"items":[' + }); + + await fetchService.fetch(URL_WITH_ROUTE); + + expect(log.mock.calls[0][0]).toContain('finishReason=length'); + expect(warn).not.toHaveBeenCalled(); + }); + + it.each(['apikey', 'APIKEY', 'api_token', 'key', 'token'])( + 'should redact the query parameter %s in the log of a successful web fetch', + async (name) => { + mockGenerateText({ text: BODY }); + + await fetchService.fetch(`${URL_WITH_ROUTE}?${name}=secret&a=b`); + + expect(log.mock.calls[0][0]).toContain(`${name}=*******&a=b`); + expect(log.mock.calls[0][0]).not.toContain('secret'); + } + ); + + it.each([ + [ + 'a failure message', + { text: FAILURE_MESSAGE }, + 'reason=failure_message error="HTTP 405: Method Not Allowed"' + ], + [ + 'a failure message with an empty error', + { text: '{"url":"u","status":"failed","error":""}' }, + 'reason=failure_message error="(empty)"' + ], + [ + 'a failure message of a source before a text without JSON', + { + sources: [ + { providerMetadata: { openrouter: { content: FAILURE_MESSAGE } } } + ], + text: 'Sorry.' + }, + 'reason=failure_message error="HTTP 405: Method Not Allowed"' + ], + [ + 'a failure message after a source without JSON', + { + sources: [ + { providerMetadata: { openrouter: { content: 'Sorry.' } } } + ], + text: FAILURE_MESSAGE + }, + 'reason=failure_message error="HTTP 405: Method Not Allowed"' + ], + ['a text without JSON', { text: 'Sorry.' }, 'reason=invalid_body'], + ['an empty text', { text: '' }, 'reason=empty_body'], + [ + 'a truncated body', + { finishReason: 'length', text: BODY }, + 'finishReason=length model=model duration=' + ], + [ + 'the reason of a truncated body', + { finishReason: 'length', text: BODY }, + 'reason=finish_reason' + ] + ])('should log one warning on %s', async (_, result, expected) => { + mockGenerateText(result); + + await fetchService.fetch(URL_WITH_ROUTE); + + expect(warn).toHaveBeenCalledTimes(1); + expect(warn.mock.calls[0][0]).toContain(expected); + expect(log).not.toHaveBeenCalled(); + }); + + it.each([ + ['https://www.example.com?unknown=secret', 'No access to [url]'], + [ + 'https://www.example.com?u=https%3A%2F%2Fx%3Fapikey%3Dsecret', + 'No access to [url]' + ], + ['HTTPS://www.example.com?apikey=secret', 'No access to [url]'] + ])( + 'should replace the URL %s in the error of a failure message', + async (url, expected) => { + mockGenerateText({ + text: JSON.stringify({ + error: `No access to ${url}`, + status: 'failed', + url: 'https://www.example.com' + }) + }); + + await fetchService.fetch(URL_WITH_ROUTE); + + expect(warn.mock.calls[0][0]).toContain(`error="${expected}"`); + expect(warn.mock.calls[0][0]).not.toContain('secret'); + } + ); + + it('should redact the API keys outside of a URL in the error of a failure message', async () => { + mockGenerateText({ + text: '{"url":"https://www.example.com","status":"failed","error":"Invalid apikey=secret"}' + }); + + await fetchService.fetch(URL_WITH_ROUTE); + + expect(warn.mock.calls[0][0]).toContain('apikey=*******'); + expect(warn.mock.calls[0][0]).not.toContain('secret'); + }); + + it('should log an error of the model', async () => { + (generateText as jest.Mock).mockRejectedValue(new Error('Timeout')); + + await fetchService.fetch(URL_WITH_ROUTE); + + expect(error).toHaveBeenCalledTimes(1); + expect(error.mock.calls[0][0]).toMatch( + /\(engine=parallel model=model duration=\d+ms reason=request_error\): Timeout$/ + ); + }); + + it('should log the name of a missing model', async () => { + delete properties[PROPERTY_OPENROUTER_MODEL_WEB_FETCH]; + + await fetchService.fetch(URL_WITH_ROUTE); + + expect(warn).toHaveBeenCalledTimes(1); + expect(warn.mock.calls[0][0]).toContain( + `reason=missing_configuration missing=${PROPERTY_OPENROUTER_MODEL})` + ); + expect(warn.mock.calls[0][0]).not.toContain('api-key'); + }); + + it('should log the name of a missing API key', async () => { + delete properties[PROPERTY_API_KEY_OPENROUTER]; + + await fetchService.fetch(URL_WITH_ROUTE); + + expect(warn).toHaveBeenCalledTimes(1); + expect(warn.mock.calls[0][0]).toContain( + `reason=missing_configuration missing=${PROPERTY_API_KEY_OPENROUTER})` + ); + }); + + it('should log the names of a missing API key and model', async () => { + delete properties[PROPERTY_API_KEY_OPENROUTER]; + delete properties[PROPERTY_OPENROUTER_MODEL_WEB_FETCH]; + + await fetchService.fetch(URL_WITH_ROUTE); + + expect(warn.mock.calls[0][0]).toContain( + `missing=${PROPERTY_API_KEY_OPENROUTER},${PROPERTY_OPENROUTER_MODEL})` + ); + }); + + it('should log a missing configuration only one time', async () => { + delete properties[PROPERTY_API_KEY_OPENROUTER]; + + await fetchService.fetch(URL_WITH_ROUTE); + await fetchService.fetch(URL_WITH_ROUTE); + + expect(warn).toHaveBeenCalledTimes(1); + expect(directFetch).toHaveBeenCalledTimes(2); + }); + }); + + describe('validation of the routes', () => { + let warn: jest.SpyInstance; + + beforeEach(() => { + warn = jest.spyOn(Logger.prototype, 'warn').mockImplementation(); + }); + + afterEach(() => { + warn.mockRestore(); + }); + + it('should accept valid routes without a warning', async () => { + await fetchService.onModuleInit(); + + expect(warn).not.toHaveBeenCalled(); + }); + + it('should accept a missing property without a warning', async () => { + delete properties[PROPERTY_WEB_FETCH_ROUTES]; + + await fetchService.onModuleInit(); + + expect(warn).not.toHaveBeenCalled(); + }); + + it.each([ + ['an object', { domain: 'example.com' }], + ['a string', 'example.com'], + ['a number', 1] + ])('should ignore %s as the value of the property', async (_, value) => { + properties[PROPERTY_WEB_FETCH_ROUTES] = value; + + await fetchService.onModuleInit(); + + expect(warn).toHaveBeenCalledTimes(1); + expect(warn.mock.calls[0][0]).toContain('It must be an array'); + + await fetchService.fetch(URL_WITH_ROUTE); + + expect(generateText).not.toHaveBeenCalled(); + }); + + it.each([ + ['a route which is not an object', 'example.com'], + ['a route without a domain', {}], + ['a domain with a protocol', { domain: 'https://example.com' }], + ['a domain with a path', { domain: 'example.com/data' }], + [ + 'a content type which is not a string', + { domain: 'example.com', responseContentType: 1 } + ] + ])('should ignore %s and keep the valid routes', async (_, route) => { + mockGenerateText({ text: 'Plain text' }); + + properties[PROPERTY_WEB_FETCH_ROUTES] = [ + route, + { domain: 'example.org' } + ]; + + await fetchService.onModuleInit(); + + expect(warn).toHaveBeenCalledTimes(1); + expect(warn.mock.calls[0][0]).toContain('Ignoring an invalid route'); + + await fetchService.fetch(URL_WITH_ROUTE); + + expect(generateText).not.toHaveBeenCalled(); + + await fetchService.fetch('https://example.org/page'); + + expect(generateText).toHaveBeenCalledTimes(1); + }); + }); + it('should not use the model for a domain without a route', async () => { await fetchService.fetch('https://www.ghostfol.io'); diff --git a/apps/api/src/services/fetch/fetch.service.ts b/apps/api/src/services/fetch/fetch.service.ts index d8648154e5..9e1791cf3c 100644 --- a/apps/api/src/services/fetch/fetch.service.ts +++ b/apps/api/src/services/fetch/fetch.service.ts @@ -1,5 +1,7 @@ -import { redactPaths } from '@ghostfolio/api/helper/object.helper'; -import { getWebFetchBody } from '@ghostfolio/api/helper/web-fetch.helper'; +import { + getWebFetchBody, + getWebFetchError +} from '@ghostfolio/api/helper/web-fetch.helper'; import { PropertyService } from '@ghostfolio/api/services/property/property.service'; import { DEFAULT_OPENROUTER_ENGINE_WEB_FETCH, @@ -14,6 +16,8 @@ import { import { Injectable, Logger, OnModuleInit } from '@nestjs/common'; import { createOpenRouter } from '@openrouter/ai-sdk-provider'; import { generateText, jsonSchema, tool } from 'ai'; +import { isFQDN } from 'class-validator'; +import { isPlainObject } from 'lodash-es'; import ms from 'ms'; import { ProxyRoute } from './interfaces/proxy-route.interface'; @@ -24,9 +28,15 @@ export class FetchService implements OnModuleInit { private readonly logger = new Logger(FetchService.name); private static readonly BODY_PREVIEW_LENGTH = 500; - private static readonly REDACTED_QUERY_PARAM_NAMES = ['apikey', 'api_token']; + private static readonly REDACTED_QUERY_PARAM_NAMES = [ + 'apikey', + 'api_token', + 'key', + 'token' + ]; private static readonly WEB_FETCH_TIMEOUT = ms('30 seconds'); + private hasLoggedMissingConfiguration = false; private proxyRoutes: ProxyRoute[] = []; private webFetchRoutes: WebFetchRoute[] = []; @@ -38,10 +48,11 @@ export class FetchService implements OnModuleInit { PROPERTY_PROXY_ROUTES )) ?? []; - this.webFetchRoutes = - (await this.propertyService.getByKey( + this.webFetchRoutes = this.getValidWebFetchRoutes( + await this.propertyService.getByKey( PROPERTY_WEB_FETCH_ROUTES - )) ?? []; + ) + ); } public async fetch(input: RequestInfo | URL, init?: RequestInit) { @@ -114,9 +125,27 @@ export class FetchService implements OnModuleInit { const model = openRouterModelWebFetch || openRouterModel; if (!model || !openRouterApiKey) { + if (!this.hasLoggedMissingConfiguration) { + const missing = [ + ...(openRouterApiKey ? [] : [PROPERTY_API_KEY_OPENROUTER]), + ...(model ? [] : [PROPERTY_OPENROUTER_MODEL]) + ].join(','); + + this.logger.warn( + `Web fetch tool is not available (${this.getWebFetchLogDetails({ + engine, + reason: `missing_configuration missing=${missing}` + })})` + ); + + this.hasLoggedMissingConfiguration = true; + } + return undefined; } + const startTime = performance.now(); + try { const openRouterService = createOpenRouter({ apiKey: openRouterApiKey }); @@ -151,12 +180,6 @@ export class FetchService implements OnModuleInit { } }); - if (finishReason !== 'stop') { - this.logger.warn( - `Web fetch tool stopped with the reason "${finishReason}" for ${this.redactUrl(url)}` - ); - } - const candidates = [ ...(sources ?? []).map((source) => { return source.providerMetadata?.openrouter?.content; @@ -178,12 +201,22 @@ export class FetchService implements OnModuleInit { const body = getWebFetchBody({ candidate, isJson }); if (!body) { - rejectedBody = candidate.trim() || rejectedBody; + // A failure message tells more than the text of a later candidate + if ( + !rejectedBody || + getWebFetchError({ candidate: rejectedBody }) === undefined + ) { + rejectedBody = candidate.trim() || rejectedBody; + } continue; } - this.logger.debug(`Routed ${this.redactUrl(url)} via web fetch tool`); + this.logger.log( + `Routed ${this.redactUrl(url)} via web fetch tool (${this.getWebFetchLogDetails( + { engine, finishReason, model, startTime } + )})` + ); return new Response(body, { headers: webFetchRoute.responseContentType @@ -193,7 +226,15 @@ export class FetchService implements OnModuleInit { } this.logger.warn( - `Web fetch tool returned no usable body for ${this.redactUrl(url)}` + `Web fetch tool returned no usable body for ${this.redactUrl(url)} (${this.getWebFetchLogDetails( + { + engine, + finishReason, + model, + startTime, + reason: this.getRejectionReason({ finishReason, rejectedBody }) + } + )})` ); this.logger.debug( @@ -205,9 +246,9 @@ export class FetchService implements OnModuleInit { return undefined; } catch (error) { this.logger.error( - `Web fetch tool failed for ${this.redactUrl(url)}: ${ - error instanceof Error ? error.message : String(error) - }` + `Web fetch tool failed for ${this.redactUrl(url)} (${this.getWebFetchLogDetails( + { engine, model, startTime, reason: 'request_error' } + )}): ${error instanceof Error ? error.message : String(error)}` ); return undefined; @@ -296,6 +337,89 @@ export class FetchService implements OnModuleInit { } } + private getRejectionReason({ + finishReason, + rejectedBody + }: { + finishReason: string; + rejectedBody?: string; + }) { + if (!rejectedBody) { + return finishReason === 'stop' ? 'empty_body' : 'finish_reason'; + } + + const error = getWebFetchError({ candidate: rejectedBody }); + + // The model can repeat the URL of the prompt, which can contain a secret + return error !== undefined + ? `failure_message error="${this.getBodyPreview(error.replace(/https?:\/\/\S+/gi, '[url]'))}"` + : 'invalid_body'; + } + + /** + * Gives back the valid routes of the property. A route which is not valid + * would never match, so it gets a warning instead of a silent direct request. + */ + private getValidWebFetchRoutes(routes: unknown): WebFetchRoute[] { + if (routes === undefined || routes === null) { + return []; + } + + if (!Array.isArray(routes)) { + this.logger.warn( + `Ignoring the property ${PROPERTY_WEB_FETCH_ROUTES}: It must be an array` + ); + + return []; + } + + return routes.filter((route): route is WebFetchRoute => { + const isValid = this.isValidWebFetchRoute(route); + + if (!isValid) { + this.logger.warn( + `Ignoring an invalid route of the property ${PROPERTY_WEB_FETCH_ROUTES}: ${JSON.stringify(route)}` + ); + } + + return isValid; + }); + } + + private getWebFetchLogDetails({ + engine, + finishReason, + model, + reason, + startTime + }: { + engine: string; + finishReason?: string; + model?: string; + reason?: string; + startTime?: number; + }) { + const details = { + engine, + finishReason, + model, + duration: + startTime === undefined + ? undefined + : `${Math.round(performance.now() - startTime)}ms`, + reason + }; + + return Object.entries(details) + .filter(([, value]) => { + return value !== undefined; + }) + .map(([key, value]) => { + return `${key}=${value}`; + }) + .join(' '); + } + private hostnameMatchesDomain({ domain, hostname @@ -306,17 +430,28 @@ export class FetchService implements OnModuleInit { return hostname === domain || hostname.endsWith(`.${domain}`); } + private isValidWebFetchRoute(route: unknown) { + if (!isPlainObject(route)) { + return false; + } + + const { domain, responseContentType } = route as Record; + + return ( + isFQDN(domain) && + (responseContentType === undefined || + typeof responseContentType === 'string') + ); + } + private redactUrl(rawUrl: string): string { try { const url = new URL(rawUrl); - const redacted = redactPaths({ - object: Object.fromEntries(url.searchParams), - paths: FetchService.REDACTED_QUERY_PARAM_NAMES - }); - - for (const [key, value] of Object.entries(redacted)) { - if (value === null) { + for (const key of [...url.searchParams.keys()]) { + if ( + FetchService.REDACTED_QUERY_PARAM_NAMES.includes(key.toLowerCase()) + ) { url.searchParams.set(key, '*******'); } }