feat(hive-sdk): reduce http retry noise by introducing debug log level (#7264)

Author: n1ru4l

.changeset/odd-mammals-admire.md

@@ -0,0 +1,29 @@
+---
+'@graphql-hive/core': minor
+'@graphql-hive/apollo': minor
+'@graphql-hive/envelop': minor
+---
+
+Introduce debug log level. HTTP retry log pollute the error log. The retries are now logged to the debug level.
+In order to see debug logs set the `debug` option to true.
+
+```ts
+const hive = createHive({
+  debug: true,
+})
+```
+
+If you are using a custom logger, make sure to provide a `debug` logging method implementation.
+
+```ts
+const hive = createHive({
+  debug: true,
+  agent: {
+    logger: {
+      info() {},
+      error() {},
+      debug() {}
+    }
+  }
+})
+```

.changeset/proud-jobs-say.md

@@ -0,0 +1,5 @@
+---
+'@graphql-hive/cli': patch
+---
+
+Ensure http debug logs are printed properly.

packages/libraries/cli/src/base-command.ts

@@ -214,19 +214,19 @@ export default abstract class BaseCommand<T extends typeof Command> extends Comm
               variables: args.variables,
             }),
             {
-              logger: {
-                info: (...args) => {
-                  if (isDebug) {
-                    this.logInfo(...args);
+              logger: isDebug
+                ? {
+                    info: (...args) => {
+                      this.logInfo(...args);
+                    },
+                    error: (...args) => {
+                      this.logWarning(...args);
+                    },
+                    debug: (...args) => {
+                      this.logInfo(...args);
+                    },
                   }
-                },
-                error: (...args) => {
-                  // Allow retrying requests without noise
-                  if (isDebug) {
-                    this.logWarning(...args);
-                  }
-                },
-              },
+                : undefined,
               headers: requestHeaders,
               timeout: args.timeout,
             },

packages/libraries/core/src/client/agent.ts

@@ -100,11 +100,10 @@ export function createAgent<TEvent>(
     headers?(): Record<string, string>;
   },
 ) {
-  const options: Required<Omit<AgentOptions, 'fetch' | 'circuitBreaker'>> & {
+  const options: Required<Omit<AgentOptions, 'fetch' | 'circuitBreaker' | 'logger' | 'debug'>> & {
     circuitBreaker: null | AgentCircuitBreakerConfiguration;
   } = {
     timeout: 30_000,
-    debug: false,
     enabled: true,
     minTimeout: 200,
     maxRetries: 3,
@@ -119,9 +118,10 @@ export function createAgent<TEvent>(
         : pluginOptions.circuitBreaker === false
           ? null
           : pluginOptions.circuitBreaker,
-    logger: createHiveLogger(pluginOptions.logger ?? console, '[agent]'),
   };
 
+  const logger = createHiveLogger(pluginOptions.logger ?? console, '[agent]');
+
   const enabled = options.enabled !== false;
 
   let timeoutID: ReturnType<typeof setTimeout> | null = null;
@@ -134,16 +134,6 @@ export function createAgent<TEvent>(
     timeoutID = setTimeout(send, options.sendInterval);
   }
 
-  function debugLog(msg: string) {
-    if (options.debug) {
-      options.logger.info(msg);
-    }
-  }
-
-  function errorLog(msg: string) {
-    options.logger.error(msg);
-  }
-
   let scheduled = false;
   let inProgressCaptures: Promise<void>[] = [];
 
@@ -173,14 +163,14 @@ export function createAgent<TEvent>(
     data.set(event);
 
     if (data.size() >= options.maxSize) {
-      debugLog('Sending immediately');
+      logger.debug('Sending immediately');
       setImmediate(() => send({ throwOnError: false, skipSchedule: true }));
     }
   }
 
   function sendImmediately(event: TEvent): Promise<ReadOnlyResponse | null> {
     data.set(event);
-    debugLog('Sending immediately');
+    logger.debug('Sending immediately');
     return send({ throwOnError: true, skipSchedule: true });
   }
 
@@ -199,7 +189,7 @@ export function createAgent<TEvent>(
         retries: options.maxRetries,
         factor: 2,
       },
-      logger: options.logger,
+      logger,
       fetchImplementation: pluginOptions.fetch,
       signal,
     });
@@ -221,14 +211,14 @@ export function createAgent<TEvent>(
 
     data.clear();
 
-    debugLog(`Sending report (queue ${dataToSend})`);
+    logger.debug(`Sending report (queue ${dataToSend})`);
     const response = sendFromBreaker(buffer)
       .then(res => {
-        debugLog(`Report sent!`);
+        logger.debug(`Report sent!`);
         return res;
       })
       .catch(error => {
-        errorLog(`Failed to send report.`);
+        logger.debug(`Failed to send report.`);
 
         if (sendOptions?.throwOnError) {
           throw error;
@@ -246,7 +236,7 @@ export function createAgent<TEvent>(
   }
 
   async function dispose() {
-    debugLog('Disposing');
+    logger.debug('Disposing');
     if (timeoutID) {
       clearTimeout(timeoutID);
     }
@@ -266,7 +256,7 @@ export function createAgent<TEvent>(
     ReturnType<typeof sendHTTPCall>
   >;
   let loadCircuitBreakerPromise: Promise<void> | null = null;
-  const breakerLogger = createHiveLogger(options.logger, '[circuit breaker]');
+  const breakerLogger = createHiveLogger(logger, '[circuit breaker]');
 
   function noopBreaker(): typeof breaker {
     return {

packages/libraries/core/src/client/client.ts

@@ -8,31 +8,32 @@ import { version } from '../version.js';
 import { http } from './http-client.js';
 import { createPersistedDocuments } from './persisted-documents.js';
 import { createReporting } from './reporting.js';
-import type { HiveClient, HivePluginOptions } from './types.js';
+import type { HiveClient, HiveInternalPluginOptions, HivePluginOptions } from './types.js';
 import { createUsage } from './usage.js';
-import { createHiveLogger, isLegacyAccessToken, logIf } from './utils.js';
+import { createHiveLogger, isLegacyAccessToken } from './utils.js';
 
 export function createHive(options: HivePluginOptions): HiveClient {
-  const logger = createHiveLogger(options?.agent?.logger ?? console, '[hive]');
+  const logger = createHiveLogger(
+    options?.agent?.logger ?? console,
+    '[hive]',
+    options.debug ?? false,
+  );
   let enabled = options.enabled ?? true;
 
-  if (enabled === false) {
-    logIf(
-      options.debug === true &&
-        // hive client can be used only for persisted documents, without the cdn or usage reporting.
-        // hence, we dont want a misleading log message below saying that the plugin is disabled
-        !options.experimental__persistedDocuments,
-      'Plugin is not enabled.',
-      logger.info,
-    );
+  if (enabled === false && !options.experimental__persistedDocuments) {
+    logger.debug('Plugin is not enabled.');
   }
 
   if (!options.token && enabled) {
     enabled = false;
     logger.info('Missing token, disabling.');
   }
 
-  const mergedOptions: HivePluginOptions = { ...options, enabled } as HivePluginOptions;
+  const mergedOptions: HiveInternalPluginOptions = {
+    ...options,
+    enabled,
+    logger,
+  } as HiveInternalPluginOptions;
 
   const usage = createUsage(mergedOptions);
   const schemaReporter = createReporting(mergedOptions);

packages/libraries/core/src/client/gateways.ts

@@ -1,7 +1,7 @@
 import { version } from '../version.js';
 import { http } from './http-client.js';
 import type { SchemaFetcherOptions, ServicesFetcherOptions } from './types.js';
-import { createHash, joinUrl } from './utils.js';
+import { createHash, createHiveLogger, joinUrl } from './utils.js';
 
 interface Schema {
   sdl: string;
@@ -10,7 +10,7 @@ interface Schema {
 }
 
 function createFetcher(options: SchemaFetcherOptions & ServicesFetcherOptions) {
-  const logger = options.logger ?? console;
+  const logger = createHiveLogger(options.logger ?? console, '');
   let cacheETag: string | null = null;
   let cached: {
     id: string;

packages/libraries/core/src/client/http-client.ts

@@ -1,7 +1,7 @@
 import asyncRetry from 'async-retry';
 import { abortSignalAny } from '@graphql-hive/signal';
 import { crypto, fetch, URL } from '@whatwg-node/fetch';
-import type { Logger } from './types.js';
+import { Logger } from './types';
 
 interface SharedConfig {
   headers: Record<string, string>;
@@ -104,9 +104,10 @@ export async function makeFetchCall(
 
   return await asyncRetry(
     async (bail, attempt) => {
+      const isFinalAttempt = attempt > retries;
       const requestId = crypto.randomUUID();
 
-      logger?.info(
+      logger?.debug?.(
         `${config.method} ${endpoint} (x-request-id=${requestId})` +
           (retries > 0 ? ' ' + getAttemptMessagePart(attempt, retries + 1) : ''),
       );
@@ -125,15 +126,25 @@ export async function makeFetchCall(
         },
         signal,
       }).catch((error: unknown) => {
-        const logErrorMessage = () =>
-          logger?.error(
+        const logErrorMessage = () => {
+          const msg =
             `${config.method} ${endpoint} (x-request-id=${requestId}) failed ${getDuration()}. ` +
-              getErrorMessage(error),
-          );
+            getErrorMessage(error);
+
+          if (isFinalAttempt) {
+            logger?.error(msg);
+            return;
+          }
+          logger?.debug?.(msg);
+        };
 
         if (isAggregateError(error)) {
           for (const err of error.errors) {
-            logger?.error(err);
+            if (isFinalAttempt) {
+              logger?.error(err);
+              continue;
+            }
+            logger?.debug?.(String(err));
           }
 
           logErrorMessage();
@@ -152,21 +163,24 @@ export async function makeFetchCall(
       }
 
       if (isRequestOk(response)) {
-        logger?.info(
+        logger?.debug?.(
           `${config.method} ${endpoint} (x-request-id=${requestId}) succeeded with status ${response.status} ${getDuration()}.`,
         );
 
         return response;
       }
 
-      logger?.error(
-        `${config.method} ${endpoint} (x-request-id=${requestId}) failed with status ${response.status} ${getDuration()}: ${(await response.text()) || '<empty response body>'}`,
-      );
-
-      if (retries > 0 && attempt > retries) {
+      if (isFinalAttempt) {
+        logger?.error(
+          `${config.method} ${endpoint} (x-request-id=${requestId}) failed with status ${response.status} ${getDuration()}: ${(await response.text()) || '<empty response body>'}`,
+        );
         logger?.error(
           `${config.method} ${endpoint} (x-request-id=${requestId}) retry limit exceeded after ${attempt} attempts.`,
         );
+      } else {
+        logger?.debug?.(
+          `${config.method} ${endpoint} (x-request-id=${requestId}) failed with status ${response.status} ${getDuration()}: ${(await response.text()) || '<empty response body>'}`,
+        );
       }
 
       const error = new Error(

packages/libraries/core/src/client/persisted-documents.ts

@@ -1,15 +1,16 @@
 import type { PromiseOrValue } from 'graphql/jsutils/PromiseOrValue.js';
 import LRU from 'tiny-lru';
 import { http } from './http-client.js';
-import type { Logger, PersistedDocumentsConfiguration } from './types';
+import type { PersistedDocumentsConfiguration } from './types';
+import type { HiveLogger } from './utils.js';
 
 type HeadersObject = {
   get(name: string): string | null;
 };
 
 export function createPersistedDocuments(
   config: PersistedDocumentsConfiguration & {
-    logger: Logger;
+    logger: HiveLogger;
     fetch?: typeof fetch;
   },
 ): null | {

packages/libraries/core/src/client/reporting.ts

@@ -11,15 +11,15 @@ import { getDocumentNodeFromSchema } from '@graphql-tools/utils';
 import { version } from '../version.js';
 import type { SchemaPublishMutation } from './__generated__/types.js';
 import { http } from './http-client.js';
-import type { HivePluginOptions } from './types.js';
+import type { HiveInternalPluginOptions } from './types.js';
 import { createHiveLogger, logIf } from './utils.js';
 
 export interface SchemaReporter {
   report(args: { schema: GraphQLSchema }): void;
   dispose(): Promise<void>;
 }
 
-export function createReporting(pluginOptions: HivePluginOptions): SchemaReporter {
+export function createReporting(pluginOptions: HiveInternalPluginOptions): SchemaReporter {
   if (!pluginOptions.reporting || pluginOptions.enabled === false) {
     return {
       async report() {},
@@ -30,7 +30,7 @@ export function createReporting(pluginOptions: HivePluginOptions): SchemaReporte
   const token = pluginOptions.token;
   const selfHostingOptions = pluginOptions.selfHosting;
   const reportingOptions = pluginOptions.reporting;
-  const logger = createHiveLogger(pluginOptions.agent?.logger ?? console, '[hive][reporting]');
+  const logger = createHiveLogger(pluginOptions.logger, '[reporting]');
 
   logIf(
     typeof reportingOptions.author !== 'string' || reportingOptions.author.length === 0,

packages/libraries/core/src/client/types.ts

@@ -3,6 +3,7 @@ import type { PromiseOrValue } from 'graphql/jsutils/PromiseOrValue.js';
 import type { AgentOptions } from './agent.js';
 import type { autoDisposeSymbol, hiveClientSymbol } from './client.js';
 import type { SchemaReporter } from './reporting.js';
+import { HiveLogger } from './utils.js';
 
 type HeadersObject = {
   get(name: string): string | null;
@@ -70,6 +71,7 @@ export interface ClientInfo {
 export interface Logger {
   info(msg: string): void;
   error(error: any, ...data: any[]): void;
+  debug?(msg: string): void;
 }
 
 export interface HiveUsagePluginOptions {
@@ -237,6 +239,7 @@ export type HivePluginOptions = OptionalWhenFalse<
      *
      * **Note:** The new access tokens do not support printing the token info. For every access token starting with `hvo1/`
      * no information will be printed.
+     *
      * @deprecated This option will be removed in the future.
      */
     printTokenInfo?: boolean;
@@ -257,6 +260,10 @@ export type HivePluginOptions = OptionalWhenFalse<
   'token'
 >;
 
+export type HiveInternalPluginOptions = HivePluginOptions & {
+  logger: HiveLogger;
+};
+
 export type Maybe<T> = null | undefined | T;
 
 export interface GraphQLErrorsResult {