Task/improve logging of web fetch tool (#8365)

* Improve logging of web_fetch tool and validation of routes

* Update changelog

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`)

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();
+  });
+});

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

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');
 

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<WebFetchRoute[]>(
+    this.webFetchRoutes = this.getValidWebFetchRoutes(
+      await this.propertyService.getByKey<WebFetchRoute[]>(
         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<string, unknown>;
+
+    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, '*******');
         }
       }