From ad5d0f8b683d2e1871c9587bf62fa1005dc0d722 Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Tue, 16 Jul 2024 15:30:55 +0200 Subject: [PATCH 01/16] feat: full HTTP request logging --- packages/libraries/core/src/client/agent.ts | 7 +- packages/libraries/core/src/client/client.ts | 1 + .../libraries/core/src/client/http-client.ts | 21 +- packages/libraries/yoga/tests/yoga.spec.ts | 185 +++++++++++++++++- 4 files changed, 205 insertions(+), 9 deletions(-) diff --git a/packages/libraries/core/src/client/agent.ts b/packages/libraries/core/src/client/agent.ts index d1c1692551..be515c70cc 100644 --- a/packages/libraries/core/src/client/agent.ts +++ b/packages/libraries/core/src/client/agent.ts @@ -196,6 +196,7 @@ export function createAgent( }, timeout: options.timeout, fetchImplementation: pluginOptions.__testing?.fetch, + logger: options.logger, }) .catch(error => { debugLog(`Attempt ${attempt} failed: ${error.message}`); @@ -218,7 +219,7 @@ export function createAgent( if (response.status < 200 || response.status >= 300) { throw new Error( - `[hive][${prefix}] Failed to send data (HTTP status ${response.status}): ${await response.text()}`, + `[hive][${prefix}] POST ${options.endpoint} failed with status code ${response.status}. ${await response.text()}`, ); } @@ -237,7 +238,9 @@ export function createAgent( throw error; } - options.logger.error(`[hive][${prefix}] Failed to send data: ${error.message}`); + options.logger.error( + `[hive][${prefix}] POST ${options.endpoint} failed with status ${error.message}`, + ); return null; } diff --git a/packages/libraries/core/src/client/client.ts b/packages/libraries/core/src/client/client.ts index d2015935c8..ca40613214 100644 --- a/packages/libraries/core/src/client/client.ts +++ b/packages/libraries/core/src/client/client.ts @@ -113,6 +113,7 @@ export function createHive(options: HivePluginOptions): HiveClient { }, timeout: 30_000, fetchImplementation: options?.agent?.__testing?.fetch, + logger, }, ); diff --git a/packages/libraries/core/src/client/http-client.ts b/packages/libraries/core/src/client/http-client.ts index 0cd72f7644..e1b9283274 100644 --- a/packages/libraries/core/src/client/http-client.ts +++ b/packages/libraries/core/src/client/http-client.ts @@ -1,5 +1,6 @@ import asyncRetry from 'async-retry'; import { fetch, URL } from '@whatwg-node/fetch'; +import type { Logger } from './types.js'; type RetryOptions = Parameters[1] & { retryWhen(response: Response): boolean; @@ -13,6 +14,7 @@ function get( timeout?: number; fetchImplementation?: typeof fetch; retry?: RetryOptions; + logger?: Logger; }, ) { return makeFetchCall(endpoint, { @@ -21,6 +23,7 @@ function get( timeout: config.timeout, retry: config.retry, fetchImplementation: config.fetchImplementation, + logger: config.logger ?? console, }); } @@ -32,6 +35,7 @@ function post( timeout?: number; retry?: RetryOptions; fetchImplementation?: typeof fetch; + logger?: Logger; }, ) { return makeFetchCall(endpoint, { @@ -41,6 +45,7 @@ function post( timeout: config.timeout, retry: config.retry, fetchImplementation: config.fetchImplementation, + logger: config.logger ?? console, }); } @@ -58,6 +63,7 @@ async function makeFetchCall( timeout?: number; retry?: RetryOptions; fetchImplementation?: typeof fetch; + logger?: Logger; }, ) { const controller = new AbortController(); @@ -92,17 +98,20 @@ async function makeFetchCall( } if (!retryOptions.retryWhen(res)) { + config.logger?.error( + `${config.method} ${endpoint} failed with status ${res.status}. ${res.statusText ?? 'Internal Server Error'}`, + ); bail( new Error( - `Failed to fetch ${endpoint}, received: ${res.status} ${res.statusText ?? 'Internal Server Error'}`, + `${config.method} ${endpoint} failed with status ${res.status}. ${res.statusText ?? 'Internal Server Error'}`, ), ); return; } - throw new Error( - `Failed to fetch ${endpoint}, received: ${res.status} ${res.statusText ?? 'Internal Server Error'}`, - ); + const errorMessage = `${config.method} ${endpoint} failed with status ${res.status}. ${res.statusText ?? 'Internal Server Error'}`; + config.logger?.error(errorMessage); + throw new Error(errorMessage); }, { ...retryOptions, @@ -124,6 +133,10 @@ async function makeFetchCall( cause: error, }); } + + config.logger?.error(error); + config.logger?.error(`${config.method} ${endpoint} failed.`); + throw error; } finally { if (timeoutId !== undefined) { diff --git a/packages/libraries/yoga/tests/yoga.spec.ts b/packages/libraries/yoga/tests/yoga.spec.ts index fa3b4fcedd..b72271e016 100644 --- a/packages/libraries/yoga/tests/yoga.spec.ts +++ b/packages/libraries/yoga/tests/yoga.spec.ts @@ -104,9 +104,38 @@ test('should not interrupt the process', async () => { await waitFor(50); - expect(logger.error).toHaveBeenCalledWith(expect.stringContaining('[hive][info] Error')); - expect(logger.error).toHaveBeenCalledWith(expect.stringContaining('[hive][reporting] Failed')); - expect(logger.error).toHaveBeenCalledWith(expect.stringContaining('[hive][usage] Failed')); + expect(logger.error.mock.calls).toMatchInlineSnapshot(` + [ + [ + [Error: getaddrinfo ENOTFOUND 404.localhost], + ], + [ + POST http://404.localhost/registry failed., + ], + [ + [hive][info] Error getaddrinfo ENOTFOUND 404.localhost, + ], + [ + [Error: getaddrinfo ENOTFOUND 404.localhost], + ], + [ + POST http://404.localhost/registry failed., + ], + [ + [hive][reporting] Failed to report schema: getaddrinfo ENOTFOUND 404.localhost, + ], + [ + [Error: getaddrinfo ENOTFOUND 404.localhost], + ], + [ + POST http://404.localhost/usage failed., + ], + [ + [hive][usage] POST http://404.localhost/usage failed with status getaddrinfo ENOTFOUND 404.localhost, + ], + ] + `); + await hive.dispose(); clean(); }, 1_000); @@ -1488,3 +1517,153 @@ describe('incremental delivery usage reporting', () => { graphqlScope.done(); }); }); + +test('useful log information in case usage/registry endpoint sends unexpected status code', async () => { + const graphqlScope = nock('http://localhost') + .post('/registry', () => { + return true; + }) + .reply(500); + + const logger = createLogger('silent'); + const d = createDeferred(); + const yoga = createYoga({ + schema: createSchema({ + typeDefs: /* GraphQL */ ` + type Query { + hi: String + } + `, + }), + plugins: [ + useHive({ + enabled: true, + debug: false, + token: 'brrrt', + selfHosting: { + applicationUrl: 'http://localhost/foo', + graphqlEndpoint: 'http://localhost/registry', + usageEndpoint: 'http://localhost/registry', + }, + usage: { + endpoint: 'http://localhost/usage', + }, + agent: { + maxSize: 1, + logger, + maxRetries: 0, + }, + }), + ], + }); + + logger.error = err => { + expect(err).toEqual( + '[hive][usage] POST http://localhost/registry failed with status 500: Internal Server Error', + ); + d.resolve(); + }; + + const response = await yoga.fetch('http://localhost/graphql', { + body: JSON.stringify({ + query: `{hi}`, + }), + method: 'POST', + headers: { + 'content-type': 'application/json', + }, + }); + expect(response.status).toEqual(200); + expect(await response.json()).toMatchInlineSnapshot(` + { + data: { + hi: null, + }, + } + `); + + await d.promise; + + graphqlScope.done(); +}); + +const createDeferred = () => { + let resolve: () => void; + const promise = new Promise(r => { + resolve = r; + }); + + return { + resolve: () => resolve(), + promise, + }; +}; + +test('useful log information in case registry is not reachable', async () => { + const d = createDeferred(); + const logger = createLogger('silent'); + + const yoga = createYoga({ + schema: createSchema({ + typeDefs: /* GraphQL */ ` + type Query { + hi: String + } + `, + }), + plugins: [ + useHive({ + enabled: true, + debug: false, + token: 'brrrt', + selfHosting: { + applicationUrl: 'http://localhost/foo', + graphqlEndpoint: 'http://nope.localhost:1313', + usageEndpoint: 'http://nope.localhost:1313', + }, + usage: { + endpoint: 'http://localhost/usage', + }, + agent: { + maxSize: 1, + logger, + }, + }), + ], + }); + + let logCounter = 0; + logger.error = err => { + console.log(err); + if (logCounter === 0) { + expect(err.code).toEqual('ENOTFOUND'); + logCounter++; + return; + } + if (logCounter === 1) { + expect(err).toMatchInlineSnapshot(`POST http://nope.localhost:1313 failed.`); + d.resolve(); + return; + } + }; + + const response = await yoga.fetch('http://localhost/graphql', { + body: JSON.stringify({ + query: `{hi}`, + }), + method: 'POST', + headers: { + 'content-type': 'application/json', + }, + }); + expect(response.status).toEqual(200); + expect(await response.json()).toMatchInlineSnapshot(` + { + data: { + hi: null, + }, + } + `); + + await d.promise; +}); From b8e027e4fec3317c2f9feb9bb85558b59d865ced Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Fri, 19 Jul 2024 16:48:04 +0200 Subject: [PATCH 02/16] wip --- packages/libraries/core/src/client/agent.ts | 147 +++------- packages/libraries/core/src/client/client.ts | 35 +-- .../libraries/core/src/client/gateways.ts | 11 +- .../libraries/core/src/client/http-client.ts | 263 +++++++++++------- .../libraries/core/src/client/reporting.ts | 99 +++---- packages/libraries/core/src/client/types.ts | 1 + packages/libraries/core/src/client/usage.ts | 17 +- packages/libraries/core/src/client/utils.ts | 41 ++- packages/libraries/core/src/index.ts | 1 + .../libraries/core/tests/gateways.spec.ts | 2 +- .../libraries/core/tests/http-client.spec.ts | 146 ++++++++++ .../libraries/core/tests/reporting.spec.ts | 217 ++++++++------- packages/libraries/core/tests/test-utils.ts | 28 ++ packages/libraries/core/tests/usage.spec.ts | 147 +++++----- packages/libraries/yoga/tests/yoga.spec.ts | 203 ++------------ 15 files changed, 707 insertions(+), 651 deletions(-) create mode 100644 packages/libraries/core/tests/http-client.spec.ts diff --git a/packages/libraries/core/src/client/agent.ts b/packages/libraries/core/src/client/agent.ts index be515c70cc..2afb3c23d5 100644 --- a/packages/libraries/core/src/client/agent.ts +++ b/packages/libraries/core/src/client/agent.ts @@ -1,9 +1,8 @@ -import retry from 'async-retry'; import { version } from '../version.js'; import { http } from './http-client.js'; import type { Logger } from './types.js'; -type ReadOnlyResponse = Pick; +type ReadOnlyResponse = Pick; export interface AgentOptions { enabled?: boolean; @@ -55,12 +54,10 @@ export interface AgentOptions { export function createAgent( pluginOptions: AgentOptions, { - prefix, data, body, headers = () => ({}), }: { - prefix: string; data: { clear(): void; set(data: TEvent): void; @@ -97,10 +94,14 @@ export function createAgent( function debugLog(msg: string) { if (options.debug) { - options.logger.info(`[hive][${prefix}]${enabled ? '' : '[DISABLED]'} ${msg}`); + options.logger.info(msg); } } + function errorLog(msg: string) { + options.logger.error(msg); + } + let scheduled = false; let inProgressCaptures: Promise[] = []; @@ -132,118 +133,59 @@ export function createAgent( if (data.size() >= options.maxSize) { debugLog('Sending immediately'); - setImmediate(() => send({ runOnce: true, throwOnError: false })); + setImmediate(() => send({ throwOnError: false })); } } function sendImmediately(event: TEvent): Promise { data.set(event); - debugLog('Sending immediately'); - return send({ runOnce: true, throwOnError: true }); + return send({ throwOnError: true }); } - async function send(sendOptions: { - runOnce?: boolean; - throwOnError: true; - }): Promise; - async function send(sendOptions: { - runOnce?: boolean; - throwOnError: false; - }): Promise; - async function send(sendOptions?: { - runOnce?: boolean; - throwOnError: boolean; - }): Promise { - const runOnce = sendOptions?.runOnce ?? false; - - if (!data.size()) { - if (!runOnce) { - schedule(); - } + async function send(sendOptions?: { throwOnError?: boolean }): Promise { + if (!data.size() || !enabled) { return null; } - try { - const buffer = await body(); - const dataToSend = data.size(); - - data.clear(); - - const sendReport: retry.RetryFunction<{ - status: number; - text(): Promise; - json(): Promise; - }> = async (_bail, attempt) => { - debugLog(`Sending (queue ${dataToSend}) (attempt ${attempt})`); - - if (!enabled) { - return { - status: 200, - text: async () => 'OK', - json: async () => ({}), - }; - } - - const response = await http - .post(options.endpoint, buffer, { - headers: { - accept: 'application/json', - 'content-type': 'application/json', - Authorization: `Bearer ${options.token}`, - 'User-Agent': `${options.name}/${version}`, - ...headers(), - }, - timeout: options.timeout, - fetchImplementation: pluginOptions.__testing?.fetch, - logger: options.logger, - }) - .catch(error => { - debugLog(`Attempt ${attempt} failed: ${error.message}`); - return Promise.reject(error); - }); - - if (response.status >= 200 && response.status < 300) { - return response; + const buffer = await body(); + const dataToSend = data.size(); + + data.clear(); + + debugLog(`Sending report (queue ${dataToSend})`); + const response = await http + .post(options.endpoint, buffer, { + headers: { + accept: 'application/json', + 'content-type': 'application/json', + Authorization: `Bearer ${options.token}`, + 'User-Agent': `${options.name}/${version}`, + ...headers(), + }, + timeout: options.timeout, + retry: { + retries: options.maxRetries, + factor: 2, + }, + logger: options.logger, + fetchImplementation: pluginOptions.__testing?.fetch, + }) + .then(res => { + debugLog(`Report sent!`); + return res; + }) + .catch(error => { + errorLog(`Failed to send report.`); + + if (sendOptions?.throwOnError) { + throw error; } - debugLog(`Attempt ${attempt} failed: ${response.status}`); - throw new Error(`${response.status}: ${response.statusText} ${await response.text()}`); - }; - - const response = await retry(sendReport, { - retries: options.maxRetries, - minTimeout: options.minTimeout, - factor: 2, + return null; }); - if (response.status < 200 || response.status >= 300) { - throw new Error( - `[hive][${prefix}] POST ${options.endpoint} failed with status code ${response.status}. ${await response.text()}`, - ); - } - - debugLog(`Sent!`); - - if (!runOnce) { - schedule(); - } - return response; - } catch (error: any) { - if (!runOnce) { - schedule(); - } - - if (sendOptions?.throwOnError) { - throw error; - } - - options.logger.error( - `[hive][${prefix}] POST ${options.endpoint} failed with status ${error.message}`, - ); - - return null; - } + return response; } async function dispose() { @@ -257,7 +199,6 @@ export function createAgent( } await send({ - runOnce: true, throwOnError: false, }); } diff --git a/packages/libraries/core/src/client/client.ts b/packages/libraries/core/src/client/client.ts index ca40613214..b07acea0ce 100644 --- a/packages/libraries/core/src/client/client.ts +++ b/packages/libraries/core/src/client/client.ts @@ -10,19 +10,19 @@ import { createPersistedDocuments } from './persisted-documents.js'; import { createReporting } from './reporting.js'; import type { HiveClient, HivePluginOptions } from './types.js'; import { createUsage } from './usage.js'; -import { logIf } from './utils.js'; +import { createHiveLogger, logIf } from './utils.js'; export function createHive(options: HivePluginOptions): HiveClient { - const logger = options?.agent?.logger ?? console; + const logger = createHiveLogger(options?.agent?.logger ?? console, '[hive]'); let enabled = options.enabled ?? true; if (enabled === false) { - logIf(options.debug === true, '[hive] is not enabled.', logger.info); + logIf(options.debug === true, 'plugin is not enabled.', logger.info); } if (!options.token && enabled) { enabled = false; - logger.info('[hive] Missing token, disabling.'); + logger.info('Missing token, disabling.'); } const mergedOptions: HivePluginOptions = { ...options, enabled } as HivePluginOptions; @@ -50,6 +50,7 @@ export function createHive(options: HivePluginOptions): HiveClient { const printTokenInfo = enabled ? options.printTokenInfo === true || (!!options.debug && options.printTokenInfo !== false) : false; + const infoLogger = createHiveLogger(logger, '[info]'); const info = printTokenInfo ? async () => { @@ -97,6 +98,8 @@ export function createHive(options: HivePluginOptions): HiveClient { } `; + infoLogger.info('Fetching token details...'); + const response = await http.post( endpoint, JSON.stringify({ @@ -113,7 +116,7 @@ export function createHive(options: HivePluginOptions): HiveClient { }, timeout: 30_000, fetchImplementation: options?.agent?.__testing?.fetch, - logger, + logger: infoLogger, }, ); @@ -145,9 +148,9 @@ export function createHive(options: HivePluginOptions): HiveClient { const projectUrl = `${organizationUrl}/${project.cleanId}`; const targetUrl = `${projectUrl}/${target.cleanId}`; - logger.info( + infoLogger.info( [ - '[hive][info] Token details', + 'Token details', '', `Token name: ${print(tokenInfo.token.name)}`, `Organization: ${print(organization.name, organizationUrl)}`, @@ -161,23 +164,21 @@ export function createHive(options: HivePluginOptions): HiveClient { ].join('\n'), ); } else if (result.data?.tokenInfo.message) { - logger.error( - `[hive][info] Token not found. Reason: ${result.data?.tokenInfo.message}`, - ); - logger.info( - `[hive][info] How to create a token? https://docs.graphql-hive.com/features/tokens`, + infoLogger.error(`Token not found. Reason: ${result.data?.tokenInfo.message}`); + infoLogger.info( + `How to create a token? https://docs.graphql-hive.com/features/tokens`, ); } else { - logger.error(`[hive][info] ${result.errors![0].message}`); - logger.info( - `[hive][info] How to create a token? https://docs.graphql-hive.com/features/tokens`, + infoLogger.error(`${result.errors![0].message}`); + infoLogger.info( + `How to create a token? https://docs.graphql-hive.com/features/tokens`, ); } } else { - logger.error(`[hive][info] Error ${response.status}: ${response.statusText}`); + infoLogger.error(`Error ${response.status}: ${response.statusText}`); } } catch (error) { - logger.error(`[hive][info] Error ${(error as Error)?.message ?? error}`); + infoLogger.error(`Error ${(error as Error)?.message ?? error}`); } } : () => {}; diff --git a/packages/libraries/core/src/client/gateways.ts b/packages/libraries/core/src/client/gateways.ts index 763692336d..69560ee6d2 100644 --- a/packages/libraries/core/src/client/gateways.ts +++ b/packages/libraries/core/src/client/gateways.ts @@ -1,6 +1,6 @@ import { version } from '../version.js'; import { http } from './http-client.js'; -import type { SchemaFetcherOptions, ServicesFetcherOptions } from './types.js'; +import type { Logger, SchemaFetcherOptions, ServicesFetcherOptions } from './types.js'; import { createHash, joinUrl } from './utils.js'; interface Schema { @@ -10,6 +10,7 @@ interface Schema { } function createFetcher(options: SchemaFetcherOptions & ServicesFetcherOptions) { + const logger = options.logger ?? console; let cacheETag: string | null = null; let cached: { id: string; @@ -37,12 +38,12 @@ function createFetcher(options: SchemaFetcherOptions & ServicesFetcherOptions) { .get(endpoint, { headers, retry: { - retryWhen: response => response.status >= 500, - okWhen: response => response.status === 304, retries: 10, maxTimeout: 200, minTimeout: 1, }, + isRequestOk: response => response.ok || response.status === 304, + logger, }) .then(async response => { if (response.ok) { @@ -61,9 +62,7 @@ function createFetcher(options: SchemaFetcherOptions & ServicesFetcherOptions) { return cached; } - throw new Error( - `Failed to GET ${endpoint}, received: ${response.status} ${response.statusText ?? 'Internal Server Error'}`, - ); + throw new Error(`Unexpected error.`); }); }; } diff --git a/packages/libraries/core/src/client/http-client.ts b/packages/libraries/core/src/client/http-client.ts index e1b9283274..7ed55c5756 100644 --- a/packages/libraries/core/src/client/http-client.ts +++ b/packages/libraries/core/src/client/http-client.ts @@ -2,21 +2,35 @@ import asyncRetry from 'async-retry'; import { fetch, URL } from '@whatwg-node/fetch'; import type { Logger } from './types.js'; -type RetryOptions = Parameters[1] & { - retryWhen(response: Response): boolean; - okWhen?(response: Response): boolean; -}; +interface SharedConfig { + headers: Record; + /** + * timeout in milliseconds (for each single fetch call) + * @default 20_000 + */ + timeout?: number; + /** Retry configuration. Set to `false` for having no retries. */ + retry?: RetryOptions | false; + /** custom fetch implementation. */ + fetchImplementation?: typeof fetch; + /** Logger for HTTP info and request errors. Uses `console` by default. */ + logger?: Logger; + /** + * Function for determining whether the request response is okay. + * You can override it if you want to accept other status codes as well. + * @default {response => response.ok} + **/ + isRequestOk?: ResponseAssertFunction; +} -function get( - endpoint: string, - config: { - headers: Record; - timeout?: number; - fetchImplementation?: typeof fetch; - retry?: RetryOptions; - logger?: Logger; - }, -) { +/** + * Return a string that contains the reason on why the request should be retried. + */ +type ResponseAssertFunction = (response: Response) => boolean; + +type RetryOptions = Parameters[1]; + +function get(endpoint: string, config: SharedConfig) { return makeFetchCall(endpoint, { method: 'GET', headers: config.headers, @@ -27,25 +41,11 @@ function get( }); } -function post( - endpoint: string, - data: string | Buffer, - config: { - headers: Record; - timeout?: number; - retry?: RetryOptions; - fetchImplementation?: typeof fetch; - logger?: Logger; - }, -) { +function post(endpoint: string, data: string | Buffer, config: SharedConfig) { return makeFetchCall(endpoint, { body: data, method: 'POST', - headers: config.headers, - timeout: config.timeout, - retry: config.retry, - fetchImplementation: config.fetchImplementation, - logger: config.logger ?? console, + ...config, }); } @@ -54,95 +54,160 @@ export const http = { post, }; -async function makeFetchCall( - endpoint: string, +export async function makeFetchCall( + endpoint: URL | string, config: { body?: string | Buffer; method: 'GET' | 'POST'; headers: Record; + /** + * timeout in milliseconds (for each single fetch call) + * @default 20_000 + */ timeout?: number; - retry?: RetryOptions; + /** Retry configuration. Set to `false` for having no retries. */ + retry?: RetryOptions | false; + /** custom fetch implementation. */ fetchImplementation?: typeof fetch; + /** Logger for HTTP info and request errors. Uses `console` by default. */ logger?: Logger; + /** + * Function for determining whether the request response is okay. + * You can override it if you want to accept other status codes as well. + * @default {response => response.ok} + **/ + isRequestOk?: ResponseAssertFunction; }, -) { - const controller = new AbortController(); - let timeoutId: ReturnType | undefined = undefined; - - if (config.timeout) { - timeoutId = setTimeout(() => controller.abort(), config.timeout); +): Promise { + const logger = config.logger ?? console; + const isRequestOk: ResponseAssertFunction = config.isRequestOk ?? (response => response.ok); + let retries = 0; + let minTimeout = 200; + let maxTimeout = 2000; + let factor = 1.2; + + if (config.retry !== false) { + retries = config.retry?.retries ?? 5; + minTimeout = config.retry?.minTimeout ?? 200; + maxTimeout = config.retry?.maxTimeout ?? 2000; + factor = config.retry?.factor ?? 1.2; } - try { - const retryOptions = config.retry; - if (!retryOptions) { - return await (config.fetchImplementation ?? fetch)(endpoint, { + return await asyncRetry( + async (bail, attempt) => { + logger.info( + `${config.method} ${endpoint}` + + (retries > 0 ? ' ' + getAttemptMessagePart(attempt, retries + 1) : ''), + ); + + const getDuration = measureTime(); + const signal = AbortSignal.timeout(config.timeout ?? 20_000); + + const response = await (config.fetchImplementation ?? fetch)(endpoint, { method: config.method, body: config.body, headers: config.headers, - signal: controller.signal, - }); - } - - const result = await asyncRetry( - async bail => { - const res = await (config.fetchImplementation ?? fetch)(endpoint, { - method: config.method, - body: config.body, - headers: config.headers, - signal: controller.signal, - }); - - if (res.ok || retryOptions.okWhen?.(res)) { - return res; - } - - if (!retryOptions.retryWhen(res)) { - config.logger?.error( - `${config.method} ${endpoint} failed with status ${res.status}. ${res.statusText ?? 'Internal Server Error'}`, - ); - bail( - new Error( - `${config.method} ${endpoint} failed with status ${res.status}. ${res.statusText ?? 'Internal Server Error'}`, - ), + signal, + }).catch((error: unknown) => { + const logErrorMessage = () => + logger.error( + `${config.method} ${endpoint} failed ${getDuration()}. ` + getErrorMessage(error), ); - return; + + if (isAggregateError(error)) { + for (const err of error.errors) { + logger.error(err); + } + + logErrorMessage(); + throw new Error('Unexpected HTTP error.', { cause: error }); } - const errorMessage = `${config.method} ${endpoint} failed with status ${res.status}. ${res.statusText ?? 'Internal Server Error'}`; - config.logger?.error(errorMessage); - throw new Error(errorMessage); - }, - { - ...retryOptions, - retries: retryOptions?.retries ?? 5, - minTimeout: retryOptions?.minTimeout ?? 200, - maxTimeout: retryOptions?.maxTimeout ?? 2000, - factor: retryOptions?.factor ?? 1.2, - }, - ); - - if (result === undefined) { - throw new Error('Failed to bail out of retry.'); - } - - return result; - } catch (error) { - if (isAggregateError(error)) { - throw new Error(error.errors.map(e => e.message).join(', '), { - cause: error, + logger.error(error); + logErrorMessage(); + throw new Error('Unexpected HTTP error.', { cause: error }); }); - } - config.logger?.error(error); - config.logger?.error(`${config.method} ${endpoint} failed.`); + if (isRequestOk(response)) { + logger.info( + `${config.method} ${endpoint} succeeded with status ${response.status} ${getDuration()}.`, + ); + + return response; + } + + logger.error( + `${config.method} ${endpoint} failed with status ${response.status} ${getDuration()}: ${(await response.text()) || ''}`, + ); + + if (retries > 0 && attempt > retries) { + logger.error( + `${config.method} ${endpoint} retry limit exceeded after ${attempt} attempts.`, + ); + } + + const error = new Error( + `${config.method} ${endpoint} failed with status ${response.status}.`, + ); + + if (response.status >= 400 && response.status < 500) { + if (retries > 0) { + logger.error(`Abort retry because of status code ${response.status}.`); + } + bail(error); + } + + throw error; + }, + { + retries, + minTimeout, + maxTimeout, + factor, + }, + ); +} + +function getErrorMessage(error: unknown): string { + if (error && typeof error === 'object' && 'message' in error) { + return String(error.message); + } + return ''; +} + +function getAttemptMessagePart(attempt: number, retry: number): string { + return `Attempt (${attempt}/${retry})`; +} + +function measureTime() { + const start = Date.now(); + return () => '(' + formatTimestamp(Date.now() - start) + ')'; +} + +function formatTimestamp(timestamp: number): string { + const milliseconds = timestamp % 1000; + const seconds = Math.floor((timestamp / 1000) % 60); + const minutes = Math.floor((timestamp / (1000 * 60)) % 60); + const hours = Math.floor(timestamp / (1000 * 60 * 60)); + + const parts: string[] = []; - throw error; - } finally { - if (timeoutId !== undefined) { - clearTimeout(timeoutId); - } + if (hours > 0) { + parts.push(`${hours}h`); } + + if (minutes > 0 || hours > 0) { + // Include minutes if hours exist, even if minutes are 0 + parts.push(`${minutes}m`); + } + + if (seconds > 0 || minutes > 0 || hours > 0) { + parts.push(`${seconds}s`); + } + + parts.push(`${milliseconds}ms`); + + return parts.join(':'); } interface AggregateError extends Error { diff --git a/packages/libraries/core/src/client/reporting.ts b/packages/libraries/core/src/client/reporting.ts index 6f2c446e1c..ed2ed8f8fe 100644 --- a/packages/libraries/core/src/client/reporting.ts +++ b/packages/libraries/core/src/client/reporting.ts @@ -10,9 +10,9 @@ import { import { getDocumentNodeFromSchema } from '@graphql-tools/utils'; import { version } from '../version.js'; import type { SchemaPublishMutation } from './__generated__/types.js'; -import { createAgent } from './agent.js'; +import { http } from './http-client.js'; import type { HivePluginOptions } from './types.js'; -import { logIf } from './utils.js'; +import { createHiveLogger, logIf } from './utils.js'; export interface SchemaReporter { report(args: { schema: GraphQLSchema }): void; @@ -30,7 +30,7 @@ export function createReporting(pluginOptions: HivePluginOptions): SchemaReporte const token = pluginOptions.token; const selfHostingOptions = pluginOptions.selfHosting; const reportingOptions = pluginOptions.reporting; - const logger = pluginOptions.agent?.logger ?? console; + const logger = createHiveLogger(pluginOptions.agent?.logger ?? console, '[hive][reporting]'); logIf( typeof reportingOptions.author !== 'string' || reportingOptions.author.length === 0, @@ -48,62 +48,39 @@ export function createReporting(pluginOptions: HivePluginOptions): SchemaReporte logger.error, ); - let currentSchema: GraphQLSchema | null = null; - const agent = createAgent( - { - logger, - ...pluginOptions.agent, - endpoint: - selfHostingOptions?.graphqlEndpoint ?? - reportingOptions.endpoint ?? - 'https://app.graphql-hive.com/graphql', - token, - enabled: pluginOptions.enabled, - debug: pluginOptions.debug, - __testing: pluginOptions.agent?.__testing, - }, - { - prefix: 'reporting', - data: { - set(incomingSchema) { - currentSchema = incomingSchema; - }, - size() { - return currentSchema ? 1 : 0; - }, - clear() { - currentSchema = null; - }, - }, - headers() { - return { - 'graphql-client-name': 'Hive Client', - 'graphql-client-version': version, - }; - }, - async body() { - return JSON.stringify({ - query, - operationName: 'schemaPublish', - variables: { - input: { - sdl: await printToSDL(currentSchema!), - author: reportingOptions.author, - commit: reportingOptions.commit, - service: reportingOptions.serviceName ?? null, - url: reportingOptions.serviceUrl ?? null, - force: true, - }, - }, - }); - }, - }, - ); + const endpoint = + selfHostingOptions?.graphqlEndpoint ?? + reportingOptions.endpoint ?? + 'https://app.graphql-hive.com/graphql'; return { async report({ schema }) { + logger.info(`Publish schema`); try { - const response = await agent.sendImmediately(schema); + const response = await http.post( + endpoint, + JSON.stringify({ + query, + operationName: 'schemaPublish', + variables: { + input: { + sdl: await printToSDL(schema), + author: reportingOptions.author, + commit: reportingOptions.commit, + service: reportingOptions.serviceName ?? null, + url: reportingOptions.serviceUrl ?? null, + force: true, + }, + }, + }), + { + headers: { + 'graphql-client-name': 'Hive Client', + 'graphql-client-version': version, + }, + logger, + }, + ); if (response === null) { throw new Error('Empty response'); @@ -119,7 +96,7 @@ export function createReporting(pluginOptions: HivePluginOptions): SchemaReporte switch (data.__typename) { case 'SchemaPublishSuccess': { - logger.info(`[hive][reporting] ${data.successMessage ?? 'Published schema'}`); + logger.info(`${data.successMessage ?? 'Published schema'}`); return; } case 'SchemaPublishMissingServiceError': { @@ -129,9 +106,7 @@ export function createReporting(pluginOptions: HivePluginOptions): SchemaReporte throw new Error('Service url is not defined'); } case 'SchemaPublishError': { - logger.info( - `[hive][reporting] Published schema (forced with ${data.errors.total} errors)`, - ); + logger.info(`Published schema (forced with ${data.errors.total} errors)`); data.errors.nodes.slice(0, 5).forEach(error => { logger.info(` - ${error.message}`); }); @@ -140,13 +115,15 @@ export function createReporting(pluginOptions: HivePluginOptions): SchemaReporte } } catch (error) { logger.error( - `[hive][reporting] Failed to report schema: ${ + `Failed to report schema: ${ error instanceof Error && 'message' in error ? error.message : error }`, ); } }, - dispose: agent.dispose, + dispose() { + return Promise.resolve(); + }, }; } diff --git a/packages/libraries/core/src/client/types.ts b/packages/libraries/core/src/client/types.ts index 429bb6b3d5..5ff252f62e 100644 --- a/packages/libraries/core/src/client/types.ts +++ b/packages/libraries/core/src/client/types.ts @@ -259,6 +259,7 @@ export interface GraphQLErrorsResult { export interface SchemaFetcherOptions { endpoint: string; key: string; + logger?: Logger; } export interface ServicesFetcherOptions { diff --git a/packages/libraries/core/src/client/usage.ts b/packages/libraries/core/src/client/usage.ts index cdafeeafc4..8dd482cf9f 100644 --- a/packages/libraries/core/src/client/usage.ts +++ b/packages/libraries/core/src/client/usage.ts @@ -20,7 +20,14 @@ import type { HivePluginOptions, HiveUsagePluginOptions, } from './types.js'; -import { cache, cacheDocumentKey, logIf, measureDuration, memo } from './utils.js'; +import { + cache, + cacheDocumentKey, + createHiveLogger, + logIf, + measureDuration, + memo, +} from './utils.js'; interface UsageCollector { collect(): CollectUsageCallback; @@ -64,15 +71,16 @@ export function createUsage(pluginOptions: HivePluginOptions): UsageCollector { const options = typeof pluginOptions.usage === 'boolean' ? ({} as HiveUsagePluginOptions) : pluginOptions.usage; const selfHostingOptions = pluginOptions.selfHosting; - const logger = pluginOptions.agent?.logger ?? console; + const logger = createHiveLogger(pluginOptions.agent?.logger ?? console, '[hive][usage]'); const collector = memo(createCollector, arg => arg.schema); const excludeSet = new Set(options.exclude ?? []); + const agent = createAgent( { - logger, ...(pluginOptions.agent ?? { maxSize: 1500, }), + logger, endpoint: selfHostingOptions?.usageEndpoint ?? options.endpoint ?? @@ -83,7 +91,6 @@ export function createUsage(pluginOptions: HivePluginOptions): UsageCollector { __testing: pluginOptions.agent?.__testing, }, { - prefix: 'usage', data: { set(action) { if (action.type === 'request') { @@ -156,7 +163,7 @@ export function createUsage(pluginOptions: HivePluginOptions): UsageCollector { logIf( typeof pluginOptions.token !== 'string' || pluginOptions.token.length === 0, - '[hive][usage] token is missing', + 'token is missing', logger.error, ); diff --git a/packages/libraries/core/src/client/utils.ts b/packages/libraries/core/src/client/utils.ts index d08358f7a7..ec453285ab 100644 --- a/packages/libraries/core/src/client/utils.ts +++ b/packages/libraries/core/src/client/utils.ts @@ -1,6 +1,6 @@ import { crypto, TextEncoder } from '@whatwg-node/fetch'; import { hiveClientSymbol } from './client.js'; -import type { HiveClient, HivePluginOptions } from './types.js'; +import type { HiveClient, HivePluginOptions, Logger } from './types.js'; export const isCloudflareWorker = typeof caches !== 'undefined' && 'default' in caches && !!caches.default; @@ -178,3 +178,42 @@ export function joinUrl(url: string, subdirectory: string) { return normalizedUrl + '/' + normalizedSubdirectory; } + +const hiveSymbol = Symbol('hive-logger'); + +type HiveLogger = { + info(message: string): void; + error(error: any, ...data: any[]): void; + [hiveSymbol]: { + path: string; + logger: Logger; + }; +}; + +export function createHiveLogger(baseLogger: Logger, prefix: string): HiveLogger { + const context: HiveLogger[typeof hiveSymbol] = { + path: '', + logger: baseLogger, + // @ts-ignore + ...baseLogger?.[hiveSymbol], + }; + context.path = context.path + prefix; + + const { logger, path } = context; + + return { + [hiveSymbol]: context, + info: (message: string) => { + logger.info(`${path} ${message}`); + }, + error: (error: any, ...data: any[]) => { + if (error.stack) { + for (const stack of error.stack?.split('\n')) { + logger.error(`${path} ${stack}`); + } + } else { + logger.error(`${path} ${String(error)}`, ...data); + } + }, + }; +} diff --git a/packages/libraries/core/src/index.ts b/packages/libraries/core/src/index.ts index 594a6d51d1..a87e198b78 100644 --- a/packages/libraries/core/src/index.ts +++ b/packages/libraries/core/src/index.ts @@ -5,3 +5,4 @@ export { createHive, autoDisposeSymbol } from './client/client.js'; export { atLeastOnceSampler } from './client/samplers.js'; export { isHiveClient, isAsyncIterable, createHash, joinUrl } from './client/utils.js'; export { http, URL } from './client/http-client.js'; +export type { Logger } from './client/types.js'; diff --git a/packages/libraries/core/tests/gateways.spec.ts b/packages/libraries/core/tests/gateways.spec.ts index bc61ba8316..9a7ef5ab65 100644 --- a/packages/libraries/core/tests/gateways.spec.ts +++ b/packages/libraries/core/tests/gateways.spec.ts @@ -290,7 +290,7 @@ test('fail in case of unexpected CDN status code (nRetryCount=11)', async () => await fetcher(); } catch (e) { expect(e).toMatchInlineSnapshot( - `[Error: Failed to fetch http://localhost/services, received: 500 Internal Server Error]`, + `[Error: GET http://localhost/services failed with status 500.]`, ); } }); diff --git a/packages/libraries/core/tests/http-client.spec.ts b/packages/libraries/core/tests/http-client.spec.ts new file mode 100644 index 0000000000..824d0effb4 --- /dev/null +++ b/packages/libraries/core/tests/http-client.spec.ts @@ -0,0 +1,146 @@ +import { createHiveTestingLogger } from 'test-utils'; +import { makeFetchCall } from '../src/client/http-client'; + +test('HTTP call without retries and system level error', async () => { + const logger = createHiveTestingLogger(); + const response = await makeFetchCall('https://ap.localhost', { + method: 'GET', + retry: false, + headers: {}, + logger, + }).catch(_ => {}); + + if (response) { + throw new Error('Should have rejected.'); + } + + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] GET https://ap.localhost + [ERR] Error: getaddrinfo ENOTFOUND ap.localhost + [ERR] GET https://ap.localhost failed (666ms). getaddrinfo ENOTFOUND ap.localhost + `); +}); + +test('HTTP with retries and system', async () => { + const logger = createHiveTestingLogger(); + await makeFetchCall('https://ap.localhost', { + method: 'GET', + retry: { + retries: 1, + }, + headers: {}, + logger, + }).catch(_ => {}); + + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] GET https://ap.localhost Attempt (1/2) + [ERR] Error: getaddrinfo ENOTFOUND ap.localhost + [ERR] GET https://ap.localhost failed (666ms). getaddrinfo ENOTFOUND ap.localhost + [INF] GET https://ap.localhost Attempt (2/2) + [ERR] Error: getaddrinfo ENOTFOUND ap.localhost + [ERR] GET https://ap.localhost failed (666ms). getaddrinfo ENOTFOUND ap.localhost + `); +}); + +test('HTTP with 4xx status code will not be retried', async () => { + const logger = createHiveTestingLogger(); + await makeFetchCall('https://ap.localhost', { + method: 'GET', + retry: { + retries: 1, + }, + headers: {}, + logger, + fetchImplementation: async () => { + return new Response('Bubatzbieber', { + status: 404, + statusText: 'Not Found', + }); + }, + }).catch(_ => {}); + + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] GET https://ap.localhost Attempt (1/2) + [ERR] GET https://ap.localhost failed with status 404 (666ms): Bubatzbieber + [ERR] Abort retry because of status code 404. + `); +}); + +test('HTTP with 5xx status code will be retried', async () => { + const logger = createHiveTestingLogger(); + + await makeFetchCall('https://ap.localhost', { + method: 'GET', + retry: { + retries: 1, + }, + headers: {}, + logger, + fetchImplementation: async () => { + return new Response('Bubatzbieber', { + status: 500, + statusText: 'Internal Server Error', + }); + }, + }).catch(_ => {}); + + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] GET https://ap.localhost Attempt (1/2) + [ERR] GET https://ap.localhost failed with status 500 (666ms): Bubatzbieber + [INF] GET https://ap.localhost Attempt (2/2) + [ERR] GET https://ap.localhost failed with status 500 (666ms): Bubatzbieber + [ERR] GET https://ap.localhost retry limit exceeded after 2 attempts. + `); +}); + +test('HTTP with status 3xx will be retried', async () => { + const logger = createHiveTestingLogger(); + + await makeFetchCall('https://ap.localhost', { + method: 'GET', + retry: { + retries: 1, + }, + headers: {}, + logger, + fetchImplementation: async () => { + return new Response('Bubatzbieber', { + status: 302, + statusText: 'Found', + }); + }, + }).catch(_ => {}); + + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] GET https://ap.localhost Attempt (1/2) + [ERR] GET https://ap.localhost failed with status 302 (666ms): Bubatzbieber + [INF] GET https://ap.localhost Attempt (2/2) + [ERR] GET https://ap.localhost failed with status 302 (666ms): Bubatzbieber + [ERR] GET https://ap.localhost retry limit exceeded after 2 attempts. + `); +}); + +test('HTTP with status 3xx will not be retried with custom "isRequestOk" implementation', async () => { + const logger = createHiveTestingLogger(); + + await makeFetchCall('https://ap.localhost', { + method: 'GET', + retry: { + retries: 1, + }, + headers: {}, + logger, + fetchImplementation: async () => { + return new Response('Bubatzbieber', { + status: 302, + statusText: 'Found', + }); + }, + isRequestOk: response => response.status === 302, + }).catch(_ => {}); + + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] GET https://ap.localhost Attempt (1/2) + [INF] GET https://ap.localhost succeeded with status 302 (666ms). + `); +}); diff --git a/packages/libraries/core/tests/reporting.spec.ts b/packages/libraries/core/tests/reporting.spec.ts index e64c7f7751..ea8a06705f 100644 --- a/packages/libraries/core/tests/reporting.spec.ts +++ b/packages/libraries/core/tests/reporting.spec.ts @@ -4,7 +4,7 @@ import { buildSubgraphSchema as buildSubgraphSchemaV1 } from '@apollo/federation import { buildSubgraphSchema as buildSubgraphSchemaV2 } from '@apollo/subgraph'; import { createHive } from '../src/client/client'; import { version } from '../src/version'; -import { waitFor } from './test-utils'; +import { createHiveTestingLogger, waitFor } from './test-utils'; afterEach(() => { nock.cleanAll(); @@ -17,10 +17,7 @@ const headers = { }; test('should not leak the exception', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const hive = createHive({ enabled: true, @@ -51,24 +48,17 @@ test('should not leak the exception', async () => { await waitFor(50); await hive.dispose(); - expect(logger.info).toHaveBeenCalledWith('[hive][reporting] Sending (queue 1) (attempt 1)'); - expect(logger.info).toHaveBeenCalledWith( - expect.stringContaining('[hive][reporting] Attempt 1 failed:'), - ); - expect(logger.info).toHaveBeenCalledWith('[hive][reporting] Sending (queue 1) (attempt 2)'); - expect(logger.error).toHaveBeenCalledTimes(1); - expect(logger.error).toHaveBeenCalledWith( - expect.stringContaining( - `[hive][reporting] Failed to report schema: connect ECONNREFUSED 127.0.0.1:55404`, - ), - ); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][reporting] Publish schema + [INF] [hive][reporting] POST http://127.0.0.1:55404 Attempt (1/6) + [ERR] [hive][reporting] Error: connect ECONNREFUSED 127.0.0.1:55404 + [ERR] [hive][reporting] at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1607:16) + [ERR] [hive][reporting] POST http://127.0.0.1:55404 failed (666ms). connect ECONNREFUSED 127.0.0.1:55404 + `); }); test('should send data to Hive', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const author = 'Test'; const commit = 'Commit'; @@ -135,23 +125,19 @@ test('should send data to Hive', async () => { await hive.dispose(); http.done(); - expect(logger.error).not.toHaveBeenCalled(); - expect(logger.info).toHaveBeenCalledWith('[hive][reporting] Sending (queue 1) (attempt 1)'); - expect(logger.info).toHaveBeenCalledWith(`[hive][reporting] Sent!`); - - expect(body.variables.input.sdl).toBe(`type Query{foo:String}`); - expect(body.variables.input.author).toBe(author); - expect(body.variables.input.commit).toBe(commit); - expect(body.variables.input.service).toBe(serviceName); - expect(body.variables.input.url).toBe(serviceUrl); - expect(body.variables.input.force).toBe(true); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][reporting] Sending immediately + [INF] [hive][reporting] Sending report (queue 1) + [INF] POST http://localhost/200 + [INF] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][reporting] Report sent! + [INF] [hive][reporting] Published schema + [INF] [hive][reporting] Disposing + `); }); test('should send data to Hive (deprecated endpoint)', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const author = 'Test'; const commit = 'Commit'; @@ -215,9 +201,15 @@ test('should send data to Hive (deprecated endpoint)', async () => { await hive.dispose(); http.done(); - expect(logger.error).not.toHaveBeenCalled(); - expect(logger.info).toHaveBeenCalledWith('[hive][reporting] Sending (queue 1) (attempt 1)'); - expect(logger.info).toHaveBeenCalledWith(`[hive][reporting] Sent!`); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][reporting] Sending immediately + [INF] [hive][reporting] Sending report (queue 1) + [INF] POST http://localhost/200 + [INF] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][reporting] Report sent! + [INF] [hive][reporting] Published schema + [INF] [hive][reporting] Disposing + `); expect(body.variables.input.sdl).toBe(`type Query{foo:String}`); expect(body.variables.input.author).toBe(author); @@ -228,10 +220,7 @@ test('should send data to Hive (deprecated endpoint)', async () => { }); test('should send data to app.graphql-hive.com/graphql by default', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const author = 'Test'; const commit = 'Commit'; @@ -290,9 +279,15 @@ test('should send data to app.graphql-hive.com/graphql by default', async () => await hive.dispose(); http.done(); - expect(logger.error).not.toHaveBeenCalled(); - expect(logger.info).toHaveBeenCalledWith('[hive][reporting] Sending (queue 1) (attempt 1)'); - expect(logger.info).toHaveBeenCalledWith(`[hive][reporting] Sent!`); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][reporting] Sending immediately + [INF] [hive][reporting] Sending report (queue 1) + [INF] POST https://app.graphql-hive.com/graphql + [INF] POST https://app.graphql-hive.com/graphql succeeded with status 200 (666ms). + [INF] [hive][reporting] Report sent! + [INF] [hive][reporting] Published schema + [INF] [hive][reporting] Disposing + `); expect(body.variables.input.sdl).toBe(`type Query{foo:String}`); expect(body.variables.input.author).toBe(author); @@ -301,10 +296,7 @@ test('should send data to app.graphql-hive.com/graphql by default', async () => }); test('should send data to Hive immediately', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const author = 'Test'; const commit = 'Commit'; @@ -364,16 +356,43 @@ test('should send data to Hive immediately', async () => { `), }); - expect(logger.error).not.toHaveBeenCalled(); - expect(logger.info).toHaveBeenCalledWith('[hive][reporting] Sending immediately'); - expect(logger.info).toHaveBeenCalledTimes(1); + expect(logger.getLogs()).toMatchInlineSnapshot(`[INF] [hive][reporting] Publish schema`); + logger.clear(); await waitFor(50); - expect(logger.info).toHaveBeenCalledWith('[hive][reporting] Sending (queue 1) (attempt 1)'); - expect(logger.error).not.toHaveBeenCalled(); - expect(logger.info).toHaveBeenCalledWith(`[hive][reporting] Sent!`); - expect(logger.info).toHaveBeenCalledWith(`[hive][reporting] Successfully published schema`); - expect(logger.info).toHaveBeenCalledTimes(4); - + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][reporting] POST http://localhost/200 Attempt (1/6) + [ERR] [hive][reporting] Error: Nock: No match for request { + [ERR] [hive][reporting] "method": "POST", + [ERR] [hive][reporting] "url": "http://localhost/200", + [ERR] [hive][reporting] "headers": { + [ERR] [hive][reporting] "graphql-client-name": "Hive Client", + [ERR] [hive][reporting] "graphql-client-version": "0.5.0", + [ERR] [hive][reporting] "content-type": "text/plain;charset=UTF-8", + [ERR] [hive][reporting] "content-length": "530" + [ERR] [hive][reporting] }, + [ERR] [hive][reporting] "body": "{\\"query\\":\\"mutation schemaPublish($input:SchemaPublishInput!){schemaPublish(input:$input){__typename ...on SchemaPublishSuccess{initial valid successMessage:message}...on SchemaPublishError{valid errors{nodes{message}total}}...on SchemaPublishMissingServiceError{missingServiceError:message}...on SchemaPublishMissingUrlError{missingUrlError:message}}}\\",\\"operationName\\":\\"schemaPublish\\",\\"variables\\":{\\"input\\":{\\"sdl\\":\\"type Query{foo:String}\\",\\"author\\":\\"Test\\",\\"commit\\":\\"Commit\\",\\"service\\":\\"my-api\\",\\"url\\":\\"https://api.com\\",\\"force\\":true}}}" + [ERR] [hive][reporting] } + [ERR] [hive][reporting] at InterceptedRequestRouter.startPlayback (/Users/laurinquast/Projects/graphql-hive-3/node_modules/.pnpm/nock@14.0.0-beta.7/node_modules/nock/lib/intercepted_request_router.js:346:21) + [ERR] [hive][reporting] at InterceptedRequestRouter.maybeStartPlayback (/Users/laurinquast/Projects/graphql-hive-3/node_modules/.pnpm/nock@14.0.0-beta.7/node_modules/nock/lib/intercepted_request_router.js:268:12) + [ERR] [hive][reporting] at InterceptedRequestRouter.handleEnd (/Users/laurinquast/Projects/graphql-hive-3/node_modules/.pnpm/nock@14.0.0-beta.7/node_modules/nock/lib/intercepted_request_router.js:216:10) + [ERR] [hive][reporting] at OverriddenClientRequest.req.end (/Users/laurinquast/Projects/graphql-hive-3/node_modules/.pnpm/nock@14.0.0-beta.7/node_modules/nock/lib/intercepted_request_router.js:100:33) + [ERR] [hive][reporting] at Readable.onend (node:internal/streams/readable:946:10) + [ERR] [hive][reporting] at Object.onceWrapper (node:events:634:28) + [ERR] [hive][reporting] at Readable.emit (node:events:520:28) + [ERR] [hive][reporting] at endReadableNT (node:internal/streams/readable:1696:12) + [ERR] [hive][reporting] at processTicksAndRejections (node:internal/process/task_queues:82:21) + [ERR] [hive][reporting] POST http://localhost/200 failed (666ms). Nock: No match for request { + "method": "POST", + "url": "http://localhost/200", + "headers": { + "graphql-client-name": "Hive Client", + "graphql-client-version": "0.5.0", + "content-type": "text/plain;charset=UTF-8", + "content-length": "530" + }, + "body": "{\\"query\\":\\"mutation schemaPublish($input:SchemaPublishInput!){schemaPublish(input:$input){__typename ...on SchemaPublishSuccess{initial valid successMessage:message}...on SchemaPublishError{valid errors{nodes{message}total}}...on SchemaPublishMissingServiceError{missingServiceError:message}...on SchemaPublishMissingUrlError{missingUrlError:message}}}\\",\\"operationName\\":\\"schemaPublish\\",\\"variables\\":{\\"input\\":{\\"sdl\\":\\"type Query{foo:String}\\",\\"author\\":\\"Test\\",\\"commit\\":\\"Commit\\",\\"service\\":\\"my-api\\",\\"url\\":\\"https://api.com\\",\\"force\\":true}}}" + } + `); expect(body.variables.input.sdl).toBe(`type Query{foo:String}`); expect(body.variables.input.author).toBe(author); expect(body.variables.input.commit).toBe(commit); @@ -382,17 +401,20 @@ test('should send data to Hive immediately', async () => { expect(body.variables.input.force).toBe(true); await waitFor(100); - expect(logger.info).toHaveBeenCalledTimes(4); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][reporting] Sending report (queue 1) + [INF] POST http://localhost/200 + [INF] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][reporting] Report sent! + [INF] [hive][reporting] Successfully published schema + `); await hive.dispose(); http.done(); }); test('should send original schema of a federated (v1) service', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const author = 'Test'; const commit = 'Commit'; @@ -452,10 +474,7 @@ test('should send original schema of a federated (v1) service', async () => { }); test('should send original schema of a federated (v2) service', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const author = 'Test'; const commit = 'Commit'; @@ -515,11 +534,7 @@ test('should send original schema of a federated (v2) service', async () => { }); test('should display SchemaPublishMissingServiceError', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; - + const logger = createHiveTestingLogger(); const token = 'Token'; const http = nock('http://localhost') .post('/200') @@ -570,17 +585,19 @@ test('should display SchemaPublishMissingServiceError', async () => { await hive.dispose(); http.done(); - expect(logger.info).toHaveBeenCalledWith('[hive][reporting] Sending (queue 1) (attempt 1)'); - expect(logger.error).toHaveBeenCalledWith( - `[hive][reporting] Failed to report schema: Service name is not defined`, - ); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][reporting] Sending immediately + [INF] [hive][reporting] Sending report (queue 1) + [INF] POST http://localhost/200 Attempt (1/2) + [INF] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][reporting] Report sent! + [ERR] [hive][reporting] Failed to report schema: Service name is not defined + [INF] [hive][reporting] Disposing + `); }); test('should display SchemaPublishMissingUrlError', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const token = 'Token'; const http = nock('http://localhost') @@ -632,18 +649,22 @@ test('should display SchemaPublishMissingUrlError', async () => { await hive.dispose(); http.done(); - expect(logger.info).toHaveBeenCalledWith('[hive][reporting] Sending (queue 1) (attempt 1)'); - expect(logger.error).toHaveBeenCalledWith( - `[hive][reporting] Failed to report schema: Service url is not defined`, - ); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][reporting] Sending immediately + [INF] [hive][reporting] Sending report (queue 1) + [INF] POST http://localhost/200 Attempt (1/2) + [INF] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][reporting] Report sent! + [ERR] [hive][reporting] Failed to report schema: Service url is not defined + [INF] [hive][reporting] Disposing + `); + + expect(logger.getLogs()).toContain('[hive][reporting] Sending report (queue 1)'); + expect(logger.getLogs()).toContain('Service url is not defined'); }); test('retry on non-200', async () => { - const logSpy = vi.fn(); - const logger = { - error: logSpy, - info: logSpy, - }; + const logger = createHiveTestingLogger(); const token = 'Token'; @@ -684,13 +705,15 @@ test('retry on non-200', async () => { await waitFor(50); await hive.dispose(); - expect(logSpy).toHaveBeenCalledWith('[hive][reporting] Sending (queue 1) (attempt 1)'); - expect(logSpy).toHaveBeenCalledWith( - expect.stringContaining(`[hive][reporting] Attempt 1 failed`), - ); - expect(logSpy).toHaveBeenCalledWith('[hive][reporting] Sending (queue 1) (attempt 2)'); - expect(logSpy).toHaveBeenCalledWith( - expect.stringContaining(`[hive][reporting] Attempt 2 failed`), - ); - expect(logSpy).not.toHaveBeenCalledWith('[hive][reporting] Sending (queue 1) (attempt 3)'); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][reporting] Publish schema + [INF] [hive][reporting] POST http://localhost/registry Attempt (1/6) + [ERR] [hive][reporting] Error: connect ECONNREFUSED ::1:80 + [ERR] [hive][reporting] at createConnectionError (node:net:1648:14) + [ERR] [hive][reporting] at afterConnectMultiple (node:net:1678:16) + [ERR] [hive][reporting] Error: connect ECONNREFUSED 127.0.0.1:80 + [ERR] [hive][reporting] at createConnectionError (node:net:1648:14) + [ERR] [hive][reporting] at afterConnectMultiple (node:net:1678:16) + [ERR] [hive][reporting] POST http://localhost/registry failed (666ms). + `); }); diff --git a/packages/libraries/core/tests/test-utils.ts b/packages/libraries/core/tests/test-utils.ts index 507f8cac55..8bd7d854ae 100644 --- a/packages/libraries/core/tests/test-utils.ts +++ b/packages/libraries/core/tests/test-utils.ts @@ -3,3 +3,31 @@ export function waitFor(ms: number) { setTimeout(resolve, ms); }); } + +/** helper function to get log lines and replace milliseconds with static value. */ +function getLogLines(calls: Array>) { + return calls.map(log => { + let msg: string; + if (typeof log[1] === 'string') { + msg = log[1].replace(/\(\d{1,3}ms\)/, '(666ms)'); + } else { + msg = String(log[1]); + } + + return '[' + log[0] + ']' + ' ' + msg; + }); +} + +export function createHiveTestingLogger() { + let fn = vi.fn(); + return { + error: (message: unknown) => fn('ERR', message), + info: (message: unknown) => fn('INF', message), + getLogs() { + return getLogLines(fn.mock.calls).join('\n'); + }, + clear() { + fn = vi.fn(); + }, + }; +} diff --git a/packages/libraries/core/tests/usage.spec.ts b/packages/libraries/core/tests/usage.spec.ts index ae5994f68f..95295a64a7 100644 --- a/packages/libraries/core/tests/usage.spec.ts +++ b/packages/libraries/core/tests/usage.spec.ts @@ -4,7 +4,7 @@ import { createHive } from '../src/client/client'; import { atLeastOnceSampler } from '../src/client/samplers'; import type { Report } from '../src/client/usage'; import { version } from '../src/version'; -import { waitFor } from './test-utils'; +import { createHiveTestingLogger, waitFor } from './test-utils'; const headers = { 'Content-Type': 'application/json', @@ -110,10 +110,7 @@ afterEach(() => { }); test('should send data to Hive', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const token = 'Token'; @@ -167,9 +164,13 @@ test('should send data to Hive', async () => { await waitFor(30); http.done(); - expect(logger.error).not.toHaveBeenCalled(); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sending (queue 1) (attempt 1)`); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sent!`); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][usage] Disposing + [INF] [hive][usage] Sending report (queue 1) + [INF] [hive][usage] POST http://localhost/200 + [INF] [hive][usage] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][usage] Report sent! + `); // Map expect(report.size).toEqual(1); @@ -219,11 +220,7 @@ test('should send data to Hive', async () => { }); test('should send data to Hive (deprecated endpoint)', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; - + const logger = createHiveTestingLogger(); const token = 'Token'; let report: Report = { @@ -273,9 +270,13 @@ test('should send data to Hive (deprecated endpoint)', async () => { await waitFor(50); http.done(); - expect(logger.error).not.toHaveBeenCalled(); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sending (queue 1) (attempt 1)`); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sent!`); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][usage] Disposing + [INF] [hive][usage] Sending report (queue 1) + [INF] [hive][usage] POST http://localhost/200 + [INF] [hive][usage] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][usage] Report sent! + `); // Map expect(report.size).toEqual(1); @@ -325,10 +326,7 @@ test('should send data to Hive (deprecated endpoint)', async () => { }); test('should not leak the exception', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const hive = createHive({ enabled: true, @@ -358,22 +356,18 @@ test('should not leak the exception', async () => { await waitFor(50); await hive.dispose(); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sending (queue 1) (attempt 1)`); - expect(logger.info).toHaveBeenCalledWith( - expect.stringContaining(`[hive][usage] Attempt 1 failed:`), - ); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sending (queue 1) (attempt 2)`); - expect(logger.error).toHaveBeenCalledTimes(1); - expect(logger.error).toHaveBeenCalledWith( - expect.stringContaining(`[hive][usage] Failed to send data`), - ); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][usage] Sending report (queue 1) + [INF] [hive][usage] POST http://404.localhost Attempt (1/2) + [ERR] [hive][usage] Error: getaddrinfo ENOTFOUND 404.localhost + [ERR] [hive][usage] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:120:26) + [ERR] [hive][usage] POST http://404.localhost failed (666ms). getaddrinfo ENOTFOUND 404.localhost + [INF] [hive][usage] Disposing + `); }); test('sendImmediately should not stop the schedule', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const token = 'Token'; @@ -414,8 +408,6 @@ test('sendImmediately should not stop the schedule', async () => { const collect = hive.collectUsage(); - expect(logger.info).toHaveBeenCalledTimes(0); - await collect( { schema, @@ -427,44 +419,43 @@ test('sendImmediately should not stop the schedule', async () => { await waitFor(120); // Because maxSize is 2 and sendInterval is 50ms (+120ms buffer) // the scheduled send task should be done by now - expect(logger.error).not.toHaveBeenCalled(); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sending (queue 1) (attempt 1)`); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sent!`); + // since we sent only 1 element, the buffer was not full, - // so we should not see the following log: - expect(logger.info).not.toHaveBeenCalledWith(`[hive][usage] Sending immediately`); - expect(logger.info).toHaveBeenCalledTimes(2); + // so we should not see "Sending immediately" + + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][usage] Sending report (queue 1) + [INF] [hive][usage] POST http://localhost/200 + [INF] [hive][usage] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][usage] Report sent! + `); + logger.clear(); // Now we will hit the maxSize // We run collect two times await Promise.all([collect(args, {}), collect(args, {})]); await waitFor(1); - expect(logger.error).not.toHaveBeenCalled(); - expect(logger.info).toHaveBeenCalledTimes(4); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sending (queue 2) (attempt 1)`); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sending immediately`); - // we run setImmediate under the hood - // It should be sent already - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sent!`); - expect(logger.info).toHaveBeenCalledTimes(4); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][usage] Sending immediately + [INF] [hive][usage] Sending report (queue 2) + [INF] [hive][usage] POST http://localhost/200 + `); + logger.clear(); await waitFor(100); - expect(logger.info).toHaveBeenCalledTimes(5); // Let's check if the scheduled send task is still running await collect(args, {}); await waitFor(30); - expect(logger.error).not.toHaveBeenCalled(); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sending (queue 1) (attempt 1)`); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sent!`); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][usage] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][usage] Report sent! + `); await hive.dispose(); http.done(); }); test('should send data to Hive at least once when using atLeastOnceSampler', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const token = 'Token'; @@ -548,9 +539,13 @@ test('should send data to Hive at least once when using atLeastOnceSampler', asy await waitFor(50); http.done(); - expect(logger.error).not.toHaveBeenCalled(); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sending (queue 2) (attempt 1)`); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sent!`); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][usage] Disposing + [INF] [hive][usage] Sending report (queue 2) + [INF] [hive][usage] POST http://localhost/200 + [INF] [hive][usage] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][usage] Report sent! + `); // Map expect(report.size).toEqual(2); @@ -571,10 +566,7 @@ test('should send data to Hive at least once when using atLeastOnceSampler', asy }); test('should not send excluded operation name data to Hive', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const token = 'Token'; @@ -651,9 +643,13 @@ test('should not send excluded operation name data to Hive', async () => { await waitFor(50); http.done(); - expect(logger.error).not.toHaveBeenCalled(); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sending (queue 2) (attempt 1)`); - expect(logger.info).toHaveBeenCalledWith(`[hive][usage] Sent!`); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][usage] Disposing + [INF] [hive][usage] Sending report (queue 2) + [INF] [hive][usage] POST http://localhost/200 + [INF] [hive][usage] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][usage] Report sent! + `); // Map expect(report.size).toEqual(2); @@ -703,11 +699,7 @@ test('should not send excluded operation name data to Hive', async () => { }); test('retry on non-200', async () => { - const logSpy = vi.fn(); - const logger = { - error: logSpy, - info: logSpy, - }; + const logger = createHiveTestingLogger(); const token = 'Token'; @@ -750,9 +742,10 @@ test('retry on non-200', async () => { await waitFor(50); await hive.dispose(); - expect(logSpy).toHaveBeenCalledWith('[hive][usage] Sending (queue 1) (attempt 1)'); - expect(logSpy).toHaveBeenCalledWith(expect.stringContaining(`[hive][usage] Attempt 1 failed`)); - expect(logSpy).toHaveBeenCalledWith('[hive][usage] Sending (queue 1) (attempt 2)'); - expect(logSpy).toHaveBeenCalledWith(expect.stringContaining(`[hive][usage] Attempt 2 failed`)); - expect(logSpy).not.toHaveBeenCalledWith('[hive][usage] Sending (queue 1) (attempt 3)'); + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][usage] Sending report (queue 1) + [INF] [hive][usage] POST http://localhost/200 Attempt (1/2) + [ERR] [hive][usage] POST http://localhost/200 failed with status 500 (666ms): No no no + [INF] [hive][usage] Disposing + `); }); diff --git a/packages/libraries/yoga/tests/yoga.spec.ts b/packages/libraries/yoga/tests/yoga.spec.ts index b72271e016..72d0f5a2ae 100644 --- a/packages/libraries/yoga/tests/yoga.spec.ts +++ b/packages/libraries/yoga/tests/yoga.spec.ts @@ -11,6 +11,7 @@ import { useDisableIntrospection } from '@graphql-yoga/plugin-disable-introspect import { useGraphQLSSE } from '@graphql-yoga/plugin-graphql-sse'; import { useResponseCache } from '@graphql-yoga/plugin-response-cache'; import { Response } from '@whatwg-node/fetch'; +import { createLogger as createHiveTestingLogger } from '../../core/tests/test-utils'; import { createHive, useHive } from '../src/index.js'; beforeAll(() => { @@ -52,10 +53,7 @@ function handleProcess() { } test('should not interrupt the process', async () => { - const logger = { - error: vi.fn(), - info: vi.fn(), - }; + const logger = createHiveTestingLogger(); const clean = handleProcess(); const hive = createHive({ enabled: true, @@ -104,36 +102,23 @@ test('should not interrupt the process', async () => { await waitFor(50); - expect(logger.error.mock.calls).toMatchInlineSnapshot(` - [ - [ - [Error: getaddrinfo ENOTFOUND 404.localhost], - ], - [ - POST http://404.localhost/registry failed., - ], - [ - [hive][info] Error getaddrinfo ENOTFOUND 404.localhost, - ], - [ - [Error: getaddrinfo ENOTFOUND 404.localhost], - ], - [ - POST http://404.localhost/registry failed., - ], - [ - [hive][reporting] Failed to report schema: getaddrinfo ENOTFOUND 404.localhost, - ], - [ - [Error: getaddrinfo ENOTFOUND 404.localhost], - ], - [ - POST http://404.localhost/usage failed., - ], - [ - [hive][usage] POST http://404.localhost/usage failed with status getaddrinfo ENOTFOUND 404.localhost, - ], - ] + expect(logger.getLogs()).toMatchInlineSnapshot(` + [INF] [hive][info] Fetching token details... + [INF] [hive][info] POST http://404.localhost/registry Attempt (1/6) + [INF] [hive][reporting] Publish schema + [INF] [hive][reporting] POST http://404.localhost/registry Attempt (1/6) + [ERR] [hive][info] Error: getaddrinfo ENOTFOUND 404.localhost + [ERR] [hive][info] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:120:26) + [ERR] [hive][info] POST http://404.localhost/registry failed (666ms). getaddrinfo ENOTFOUND 404.localhost + [ERR] [hive][reporting] Error: getaddrinfo ENOTFOUND 404.localhost + [ERR] [hive][reporting] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:120:26) + [ERR] [hive][reporting] POST http://404.localhost/registry failed (666ms). getaddrinfo ENOTFOUND 404.localhost + [INF] [hive][usage] Sending report (queue 1) + [INF] [hive][usage] POST http://404.localhost/usage + [ERR] [hive][usage] Error: getaddrinfo ENOTFOUND 404.localhost + [ERR] [hive][usage] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:120:26) + [ERR] [hive][usage] POST http://404.localhost/usage failed (666ms). getaddrinfo ENOTFOUND 404.localhost + [ERR] [hive][usage] Failed to send report. `); await hive.dispose(); @@ -1517,153 +1502,3 @@ describe('incremental delivery usage reporting', () => { graphqlScope.done(); }); }); - -test('useful log information in case usage/registry endpoint sends unexpected status code', async () => { - const graphqlScope = nock('http://localhost') - .post('/registry', () => { - return true; - }) - .reply(500); - - const logger = createLogger('silent'); - const d = createDeferred(); - const yoga = createYoga({ - schema: createSchema({ - typeDefs: /* GraphQL */ ` - type Query { - hi: String - } - `, - }), - plugins: [ - useHive({ - enabled: true, - debug: false, - token: 'brrrt', - selfHosting: { - applicationUrl: 'http://localhost/foo', - graphqlEndpoint: 'http://localhost/registry', - usageEndpoint: 'http://localhost/registry', - }, - usage: { - endpoint: 'http://localhost/usage', - }, - agent: { - maxSize: 1, - logger, - maxRetries: 0, - }, - }), - ], - }); - - logger.error = err => { - expect(err).toEqual( - '[hive][usage] POST http://localhost/registry failed with status 500: Internal Server Error', - ); - d.resolve(); - }; - - const response = await yoga.fetch('http://localhost/graphql', { - body: JSON.stringify({ - query: `{hi}`, - }), - method: 'POST', - headers: { - 'content-type': 'application/json', - }, - }); - expect(response.status).toEqual(200); - expect(await response.json()).toMatchInlineSnapshot(` - { - data: { - hi: null, - }, - } - `); - - await d.promise; - - graphqlScope.done(); -}); - -const createDeferred = () => { - let resolve: () => void; - const promise = new Promise(r => { - resolve = r; - }); - - return { - resolve: () => resolve(), - promise, - }; -}; - -test('useful log information in case registry is not reachable', async () => { - const d = createDeferred(); - const logger = createLogger('silent'); - - const yoga = createYoga({ - schema: createSchema({ - typeDefs: /* GraphQL */ ` - type Query { - hi: String - } - `, - }), - plugins: [ - useHive({ - enabled: true, - debug: false, - token: 'brrrt', - selfHosting: { - applicationUrl: 'http://localhost/foo', - graphqlEndpoint: 'http://nope.localhost:1313', - usageEndpoint: 'http://nope.localhost:1313', - }, - usage: { - endpoint: 'http://localhost/usage', - }, - agent: { - maxSize: 1, - logger, - }, - }), - ], - }); - - let logCounter = 0; - logger.error = err => { - console.log(err); - if (logCounter === 0) { - expect(err.code).toEqual('ENOTFOUND'); - logCounter++; - return; - } - if (logCounter === 1) { - expect(err).toMatchInlineSnapshot(`POST http://nope.localhost:1313 failed.`); - d.resolve(); - return; - } - }; - - const response = await yoga.fetch('http://localhost/graphql', { - body: JSON.stringify({ - query: `{hi}`, - }), - method: 'POST', - headers: { - 'content-type': 'application/json', - }, - }); - expect(response.status).toEqual(200); - expect(await response.json()).toMatchInlineSnapshot(` - { - data: { - hi: null, - }, - } - `); - - await d.promise; -}); From edcd95cbb3d77a21f5ab46ab941f3da61a829d7d Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 10:44:46 +0200 Subject: [PATCH 03/16] pls --- packages/libraries/apollo/src/index.ts | 3 +- .../libraries/apollo/tests/apollo.spec.ts | 4 +- .../cli/src/commands/artifact/fetch.ts | 3 - .../libraries/core/src/client/http-client.ts | 1 + .../libraries/core/src/client/reporting.ts | 2 + packages/libraries/core/tests/enabled.spec.ts | 4 +- .../libraries/core/tests/reporting.spec.ts | 108 +++++++----------- packages/libraries/yoga/tests/yoga.spec.ts | 2 +- 8 files changed, 49 insertions(+), 78 deletions(-) diff --git a/packages/libraries/apollo/src/index.ts b/packages/libraries/apollo/src/index.ts index 899bf90430..8e0f258260 100644 --- a/packages/libraries/apollo/src/index.ts +++ b/packages/libraries/apollo/src/index.ts @@ -44,9 +44,8 @@ export function createSupergraphSDLFetcher(options: SupergraphSDLFetcherOptions) return http .get(endpoint, { headers, + isRequestOk: response => response.status === 304 || response.ok, retry: { - retryWhen: response => response.status >= 500, - okWhen: response => response.status === 304, retries: 10, maxTimeout: 200, minTimeout: 1, diff --git a/packages/libraries/apollo/tests/apollo.spec.ts b/packages/libraries/apollo/tests/apollo.spec.ts index 18c92132de..0fa6dc0c3d 100644 --- a/packages/libraries/apollo/tests/apollo.spec.ts +++ b/packages/libraries/apollo/tests/apollo.spec.ts @@ -298,9 +298,7 @@ describe('supergraph SDL fetcher', async () => { try { await fetcher(); } catch (err) { - expect(err).toMatchInlineSnapshot( - `[Error: Failed to fetch http://localhost/supergraph, received: 500 Internal Server Error]`, - ); + expect(err).toMatchInlineSnapshot(`[Error: GET http://localhost/supergraph failed with status 500.]`); } }); }); diff --git a/packages/libraries/cli/src/commands/artifact/fetch.ts b/packages/libraries/cli/src/commands/artifact/fetch.ts index fa898445d4..56ebae12c0 100644 --- a/packages/libraries/cli/src/commands/artifact/fetch.ts +++ b/packages/libraries/cli/src/commands/artifact/fetch.ts @@ -47,9 +47,6 @@ export default class ArtifactsFetch extends Command { }, retry: { retries: 3, - retryWhen(response) { - return response.status >= 500; - }, }, }); diff --git a/packages/libraries/core/src/client/http-client.ts b/packages/libraries/core/src/client/http-client.ts index 7ed55c5756..88093c3799 100644 --- a/packages/libraries/core/src/client/http-client.ts +++ b/packages/libraries/core/src/client/http-client.ts @@ -38,6 +38,7 @@ function get(endpoint: string, config: SharedConfig) { retry: config.retry, fetchImplementation: config.fetchImplementation, logger: config.logger ?? console, + isRequestOk: config.isRequestOk, }); } diff --git a/packages/libraries/core/src/client/reporting.ts b/packages/libraries/core/src/client/reporting.ts index ed2ed8f8fe..d06a4fd1e5 100644 --- a/packages/libraries/core/src/client/reporting.ts +++ b/packages/libraries/core/src/client/reporting.ts @@ -77,6 +77,8 @@ export function createReporting(pluginOptions: HivePluginOptions): SchemaReporte headers: { 'graphql-client-name': 'Hive Client', 'graphql-client-version': version, + authorization: `Bearer ${token}`, + 'content-type': 'application/json', }, logger, }, diff --git a/packages/libraries/core/tests/enabled.spec.ts b/packages/libraries/core/tests/enabled.spec.ts index ba4f21e8e1..ba72fde08e 100644 --- a/packages/libraries/core/tests/enabled.spec.ts +++ b/packages/libraries/core/tests/enabled.spec.ts @@ -19,7 +19,9 @@ test("should log that it's not enabled", async () => { .then(() => 'OK') .catch(() => 'ERROR'); - expect(logger.info).toHaveBeenCalledWith(expect.stringContaining(`[hive] is not enabled.`)); + expect(logger.info).toHaveBeenCalledWith( + expect.stringContaining(`[hive] plugin is not enabled.`), + ); expect(result).toBe('OK'); }); diff --git a/packages/libraries/core/tests/reporting.spec.ts b/packages/libraries/core/tests/reporting.spec.ts index ea8a06705f..aa58cda5fa 100644 --- a/packages/libraries/core/tests/reporting.spec.ts +++ b/packages/libraries/core/tests/reporting.spec.ts @@ -126,13 +126,10 @@ test('should send data to Hive', async () => { http.done(); expect(logger.getLogs()).toMatchInlineSnapshot(` - [INF] [hive][reporting] Sending immediately - [INF] [hive][reporting] Sending report (queue 1) - [INF] POST http://localhost/200 - [INF] POST http://localhost/200 succeeded with status 200 (666ms). - [INF] [hive][reporting] Report sent! + [INF] [hive][reporting] Publish schema + [INF] [hive][reporting] POST http://localhost/200 Attempt (1/6) + [INF] [hive][reporting] POST http://localhost/200 succeeded with status 200 (666ms). [INF] [hive][reporting] Published schema - [INF] [hive][reporting] Disposing `); }); @@ -202,13 +199,10 @@ test('should send data to Hive (deprecated endpoint)', async () => { http.done(); expect(logger.getLogs()).toMatchInlineSnapshot(` - [INF] [hive][reporting] Sending immediately - [INF] [hive][reporting] Sending report (queue 1) - [INF] POST http://localhost/200 - [INF] POST http://localhost/200 succeeded with status 200 (666ms). - [INF] [hive][reporting] Report sent! + [INF] [hive][reporting] Publish schema + [INF] [hive][reporting] POST http://localhost/200 Attempt (1/6) + [INF] [hive][reporting] POST http://localhost/200 succeeded with status 200 (666ms). [INF] [hive][reporting] Published schema - [INF] [hive][reporting] Disposing `); expect(body.variables.input.sdl).toBe(`type Query{foo:String}`); @@ -280,13 +274,10 @@ test('should send data to app.graphql-hive.com/graphql by default', async () => http.done(); expect(logger.getLogs()).toMatchInlineSnapshot(` - [INF] [hive][reporting] Sending immediately - [INF] [hive][reporting] Sending report (queue 1) - [INF] POST https://app.graphql-hive.com/graphql - [INF] POST https://app.graphql-hive.com/graphql succeeded with status 200 (666ms). - [INF] [hive][reporting] Report sent! + [INF] [hive][reporting] Publish schema + [INF] [hive][reporting] POST https://app.graphql-hive.com/graphql Attempt (1/6) + [INF] [hive][reporting] POST https://app.graphql-hive.com/graphql succeeded with status 200 (666ms). [INF] [hive][reporting] Published schema - [INF] [hive][reporting] Disposing `); expect(body.variables.input.sdl).toBe(`type Query{foo:String}`); @@ -361,37 +352,8 @@ test('should send data to Hive immediately', async () => { await waitFor(50); expect(logger.getLogs()).toMatchInlineSnapshot(` [INF] [hive][reporting] POST http://localhost/200 Attempt (1/6) - [ERR] [hive][reporting] Error: Nock: No match for request { - [ERR] [hive][reporting] "method": "POST", - [ERR] [hive][reporting] "url": "http://localhost/200", - [ERR] [hive][reporting] "headers": { - [ERR] [hive][reporting] "graphql-client-name": "Hive Client", - [ERR] [hive][reporting] "graphql-client-version": "0.5.0", - [ERR] [hive][reporting] "content-type": "text/plain;charset=UTF-8", - [ERR] [hive][reporting] "content-length": "530" - [ERR] [hive][reporting] }, - [ERR] [hive][reporting] "body": "{\\"query\\":\\"mutation schemaPublish($input:SchemaPublishInput!){schemaPublish(input:$input){__typename ...on SchemaPublishSuccess{initial valid successMessage:message}...on SchemaPublishError{valid errors{nodes{message}total}}...on SchemaPublishMissingServiceError{missingServiceError:message}...on SchemaPublishMissingUrlError{missingUrlError:message}}}\\",\\"operationName\\":\\"schemaPublish\\",\\"variables\\":{\\"input\\":{\\"sdl\\":\\"type Query{foo:String}\\",\\"author\\":\\"Test\\",\\"commit\\":\\"Commit\\",\\"service\\":\\"my-api\\",\\"url\\":\\"https://api.com\\",\\"force\\":true}}}" - [ERR] [hive][reporting] } - [ERR] [hive][reporting] at InterceptedRequestRouter.startPlayback (/Users/laurinquast/Projects/graphql-hive-3/node_modules/.pnpm/nock@14.0.0-beta.7/node_modules/nock/lib/intercepted_request_router.js:346:21) - [ERR] [hive][reporting] at InterceptedRequestRouter.maybeStartPlayback (/Users/laurinquast/Projects/graphql-hive-3/node_modules/.pnpm/nock@14.0.0-beta.7/node_modules/nock/lib/intercepted_request_router.js:268:12) - [ERR] [hive][reporting] at InterceptedRequestRouter.handleEnd (/Users/laurinquast/Projects/graphql-hive-3/node_modules/.pnpm/nock@14.0.0-beta.7/node_modules/nock/lib/intercepted_request_router.js:216:10) - [ERR] [hive][reporting] at OverriddenClientRequest.req.end (/Users/laurinquast/Projects/graphql-hive-3/node_modules/.pnpm/nock@14.0.0-beta.7/node_modules/nock/lib/intercepted_request_router.js:100:33) - [ERR] [hive][reporting] at Readable.onend (node:internal/streams/readable:946:10) - [ERR] [hive][reporting] at Object.onceWrapper (node:events:634:28) - [ERR] [hive][reporting] at Readable.emit (node:events:520:28) - [ERR] [hive][reporting] at endReadableNT (node:internal/streams/readable:1696:12) - [ERR] [hive][reporting] at processTicksAndRejections (node:internal/process/task_queues:82:21) - [ERR] [hive][reporting] POST http://localhost/200 failed (666ms). Nock: No match for request { - "method": "POST", - "url": "http://localhost/200", - "headers": { - "graphql-client-name": "Hive Client", - "graphql-client-version": "0.5.0", - "content-type": "text/plain;charset=UTF-8", - "content-length": "530" - }, - "body": "{\\"query\\":\\"mutation schemaPublish($input:SchemaPublishInput!){schemaPublish(input:$input){__typename ...on SchemaPublishSuccess{initial valid successMessage:message}...on SchemaPublishError{valid errors{nodes{message}total}}...on SchemaPublishMissingServiceError{missingServiceError:message}...on SchemaPublishMissingUrlError{missingUrlError:message}}}\\",\\"operationName\\":\\"schemaPublish\\",\\"variables\\":{\\"input\\":{\\"sdl\\":\\"type Query{foo:String}\\",\\"author\\":\\"Test\\",\\"commit\\":\\"Commit\\",\\"service\\":\\"my-api\\",\\"url\\":\\"https://api.com\\",\\"force\\":true}}}" - } + [INF] [hive][reporting] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][reporting] Successfully published schema `); expect(body.variables.input.sdl).toBe(`type Query{foo:String}`); expect(body.variables.input.author).toBe(author); @@ -402,10 +364,8 @@ test('should send data to Hive immediately', async () => { await waitFor(100); expect(logger.getLogs()).toMatchInlineSnapshot(` - [INF] [hive][reporting] Sending report (queue 1) - [INF] POST http://localhost/200 - [INF] POST http://localhost/200 succeeded with status 200 (666ms). - [INF] [hive][reporting] Report sent! + [INF] [hive][reporting] POST http://localhost/200 Attempt (1/6) + [INF] [hive][reporting] POST http://localhost/200 succeeded with status 200 (666ms). [INF] [hive][reporting] Successfully published schema `); @@ -456,7 +416,7 @@ test('should send original schema of a federated (v1) service', async () => { expect(body.variables.input.service).toBe(serviceName); expect(body.variables.input.url).toBe(serviceUrl); expect(body.variables.input.force).toBe(true); - return [200]; + return [200, '{"data":{"schemaPublish":{"__typename":"SchemaPublishSuccess"}}}']; }); hive.reportSchema({ @@ -469,7 +429,16 @@ test('should send original schema of a federated (v1) service', async () => { ), }); + await waitFor(50); + await hive.dispose(); + const logs = logger.getLogs(); + expect(logs).toMatchInlineSnapshot(` + [INF] [hive][reporting] Publish schema + [INF] [hive][reporting] POST http://localhost/200 Attempt (1/6) + [INF] [hive][reporting] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][reporting] Published schema + `); http.done(); }); @@ -516,7 +485,7 @@ test('should send original schema of a federated (v2) service', async () => { expect(body.variables.input.service).toBe(serviceName); expect(body.variables.input.url).toBe(serviceUrl); expect(body.variables.input.force).toBe(true); - return [200]; + return [200, '{"data":{"schemaPublish":{"__typename":"SchemaPublishSuccess"}}}']; }); hive.reportSchema({ @@ -529,7 +498,16 @@ test('should send original schema of a federated (v2) service', async () => { ), }); + await waitFor(50); + await hive.dispose(); + const logs = logger.getLogs(); + expect(logs).toMatchInlineSnapshot(` + [INF] [hive][reporting] Publish schema + [INF] [hive][reporting] POST http://localhost/200 Attempt (1/6) + [INF] [hive][reporting] POST http://localhost/200 succeeded with status 200 (666ms). + [INF] [hive][reporting] Published schema + `); http.done(); }); @@ -586,13 +564,10 @@ test('should display SchemaPublishMissingServiceError', async () => { http.done(); expect(logger.getLogs()).toMatchInlineSnapshot(` - [INF] [hive][reporting] Sending immediately - [INF] [hive][reporting] Sending report (queue 1) - [INF] POST http://localhost/200 Attempt (1/2) - [INF] POST http://localhost/200 succeeded with status 200 (666ms). - [INF] [hive][reporting] Report sent! + [INF] [hive][reporting] Publish schema + [INF] [hive][reporting] POST http://localhost/200 Attempt (1/6) + [INF] [hive][reporting] POST http://localhost/200 succeeded with status 200 (666ms). [ERR] [hive][reporting] Failed to report schema: Service name is not defined - [INF] [hive][reporting] Disposing `); }); @@ -650,16 +625,13 @@ test('should display SchemaPublishMissingUrlError', async () => { http.done(); expect(logger.getLogs()).toMatchInlineSnapshot(` - [INF] [hive][reporting] Sending immediately - [INF] [hive][reporting] Sending report (queue 1) - [INF] POST http://localhost/200 Attempt (1/2) - [INF] POST http://localhost/200 succeeded with status 200 (666ms). - [INF] [hive][reporting] Report sent! + [INF] [hive][reporting] Publish schema + [INF] [hive][reporting] POST http://localhost/200 Attempt (1/6) + [INF] [hive][reporting] POST http://localhost/200 succeeded with status 200 (666ms). [ERR] [hive][reporting] Failed to report schema: Service url is not defined - [INF] [hive][reporting] Disposing `); - expect(logger.getLogs()).toContain('[hive][reporting] Sending report (queue 1)'); + expect(logger.getLogs()).toContain('POST http://localhost/200 Attempt (1/6)'); expect(logger.getLogs()).toContain('Service url is not defined'); }); diff --git a/packages/libraries/yoga/tests/yoga.spec.ts b/packages/libraries/yoga/tests/yoga.spec.ts index 72d0f5a2ae..cff512e5a4 100644 --- a/packages/libraries/yoga/tests/yoga.spec.ts +++ b/packages/libraries/yoga/tests/yoga.spec.ts @@ -11,7 +11,7 @@ import { useDisableIntrospection } from '@graphql-yoga/plugin-disable-introspect import { useGraphQLSSE } from '@graphql-yoga/plugin-graphql-sse'; import { useResponseCache } from '@graphql-yoga/plugin-response-cache'; import { Response } from '@whatwg-node/fetch'; -import { createLogger as createHiveTestingLogger } from '../../core/tests/test-utils'; +import { createHiveTestingLogger } from '../../core/tests/test-utils'; import { createHive, useHive } from '../src/index.js'; beforeAll(() => { From 25c71fec9c4746e121488f421875c5e6045d6167 Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 11:19:25 +0200 Subject: [PATCH 04/16] fixtures --- .../libraries/apollo/tests/apollo.spec.ts | 4 ++- .../libraries/core/tests/reporting.spec.ts | 10 +++---- packages/libraries/core/tests/test-utils.ts | 6 +++- packages/libraries/yoga/tests/yoga.spec.ts | 29 ++++++++++++++++--- 4 files changed, 38 insertions(+), 11 deletions(-) diff --git a/packages/libraries/apollo/tests/apollo.spec.ts b/packages/libraries/apollo/tests/apollo.spec.ts index 0fa6dc0c3d..d36cabb1d2 100644 --- a/packages/libraries/apollo/tests/apollo.spec.ts +++ b/packages/libraries/apollo/tests/apollo.spec.ts @@ -298,7 +298,9 @@ describe('supergraph SDL fetcher', async () => { try { await fetcher(); } catch (err) { - expect(err).toMatchInlineSnapshot(`[Error: GET http://localhost/supergraph failed with status 500.]`); + expect(err).toMatchInlineSnapshot( + `[Error: GET http://localhost/supergraph failed with status 500.]`, + ); } }); }); diff --git a/packages/libraries/core/tests/reporting.spec.ts b/packages/libraries/core/tests/reporting.spec.ts index aa58cda5fa..0ef2634fd4 100644 --- a/packages/libraries/core/tests/reporting.spec.ts +++ b/packages/libraries/core/tests/reporting.spec.ts @@ -52,7 +52,7 @@ test('should not leak the exception', async () => { [INF] [hive][reporting] Publish schema [INF] [hive][reporting] POST http://127.0.0.1:55404 Attempt (1/6) [ERR] [hive][reporting] Error: connect ECONNREFUSED 127.0.0.1:55404 - [ERR] [hive][reporting] at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1607:16) + [ERR] [hive][reporting] at TCPConnectWrap.afterConnect [as oncomplete] (node:net:666:666) [ERR] [hive][reporting] POST http://127.0.0.1:55404 failed (666ms). connect ECONNREFUSED 127.0.0.1:55404 `); }); @@ -681,11 +681,11 @@ test('retry on non-200', async () => { [INF] [hive][reporting] Publish schema [INF] [hive][reporting] POST http://localhost/registry Attempt (1/6) [ERR] [hive][reporting] Error: connect ECONNREFUSED ::1:80 - [ERR] [hive][reporting] at createConnectionError (node:net:1648:14) - [ERR] [hive][reporting] at afterConnectMultiple (node:net:1678:16) + [ERR] [hive][reporting] at createConnectionError (node:net:666:666) + [ERR] [hive][reporting] at afterConnectMultiple (node:net:666:666) [ERR] [hive][reporting] Error: connect ECONNREFUSED 127.0.0.1:80 - [ERR] [hive][reporting] at createConnectionError (node:net:1648:14) - [ERR] [hive][reporting] at afterConnectMultiple (node:net:1678:16) + [ERR] [hive][reporting] at createConnectionError (node:net:666:666) + [ERR] [hive][reporting] at afterConnectMultiple (node:net:666:666) [ERR] [hive][reporting] POST http://localhost/registry failed (666ms). `); }); diff --git a/packages/libraries/core/tests/test-utils.ts b/packages/libraries/core/tests/test-utils.ts index 8bd7d854ae..7157351076 100644 --- a/packages/libraries/core/tests/test-utils.ts +++ b/packages/libraries/core/tests/test-utils.ts @@ -9,7 +9,11 @@ function getLogLines(calls: Array>) { return calls.map(log => { let msg: string; if (typeof log[1] === 'string') { - msg = log[1].replace(/\(\d{1,3}ms\)/, '(666ms)'); + msg = log[1] + // Replace milliseconds with static value + .replace(/\(\d{1,3}ms\)/, '(666ms)') + // Replace stack trace line numbers with static value + .replace(/\(node:net:\d+:\d+\)/, '(node:net:666:666)'); } else { msg = String(log[1]); } diff --git a/packages/libraries/yoga/tests/yoga.spec.ts b/packages/libraries/yoga/tests/yoga.spec.ts index cff512e5a4..886644735f 100644 --- a/packages/libraries/yoga/tests/yoga.spec.ts +++ b/packages/libraries/yoga/tests/yoga.spec.ts @@ -101,18 +101,39 @@ test('should not interrupt the process', async () => { ); await waitFor(50); - - expect(logger.getLogs()).toMatchInlineSnapshot(` + expect( + logger + .getLogs() + .split(`\n`) + .filter(item => item.includes(`[hive][info]`)) + .join(`\n`), + ).toMatchInlineSnapshot(` [INF] [hive][info] Fetching token details... [INF] [hive][info] POST http://404.localhost/registry Attempt (1/6) - [INF] [hive][reporting] Publish schema - [INF] [hive][reporting] POST http://404.localhost/registry Attempt (1/6) [ERR] [hive][info] Error: getaddrinfo ENOTFOUND 404.localhost [ERR] [hive][info] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:120:26) [ERR] [hive][info] POST http://404.localhost/registry failed (666ms). getaddrinfo ENOTFOUND 404.localhost + `); + expect( + logger + .getLogs() + .split(`\n`) + .filter(item => item.includes(`[hive][reporting]`)) + .join(`\n`), + ).toMatchInlineSnapshot(` + [INF] [hive][reporting] Publish schema + [INF] [hive][reporting] POST http://404.localhost/registry Attempt (1/6) [ERR] [hive][reporting] Error: getaddrinfo ENOTFOUND 404.localhost [ERR] [hive][reporting] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:120:26) [ERR] [hive][reporting] POST http://404.localhost/registry failed (666ms). getaddrinfo ENOTFOUND 404.localhost + `); + expect( + logger + .getLogs() + .split(`\n`) + .filter(item => item.includes(`[hive][usage]`)) + .join(`\n`), + ).toMatchInlineSnapshot(` [INF] [hive][usage] Sending report (queue 1) [INF] [hive][usage] POST http://404.localhost/usage [ERR] [hive][usage] Error: getaddrinfo ENOTFOUND 404.localhost From a870b52a2c8e971a3137e0c79e7c5d627a35d735 Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 11:46:13 +0200 Subject: [PATCH 05/16] lint lint --- .eslintrc.cjs | 2 +- packages/libraries/core/src/client/gateways.ts | 2 +- packages/libraries/core/src/client/utils.ts | 4 ++-- packages/libraries/core/tests/reporting.spec.ts | 2 -- 4 files changed, 4 insertions(+), 6 deletions(-) diff --git a/.eslintrc.cjs b/.eslintrc.cjs index 8bac953d0f..215da93ecd 100644 --- a/.eslintrc.cjs +++ b/.eslintrc.cjs @@ -14,7 +14,6 @@ const OPERATIONS_PATHS = [ const rulesToExtends = Object.fromEntries( Object.entries(guildConfig.rules).filter(([key]) => [ - 'no-implicit-coercion', 'import/first', 'no-restricted-globals', '@typescript-eslint/no-unused-vars', @@ -189,6 +188,7 @@ module.exports = { 'jsx-a11y/no-static-element-interactions': 'off', '@next/next/no-html-link-for-pages': 'off', 'unicorn/no-negated-condition': 'off', + 'no-implicit-coercion': 'off', }, }, { diff --git a/packages/libraries/core/src/client/gateways.ts b/packages/libraries/core/src/client/gateways.ts index 69560ee6d2..dabb8c7939 100644 --- a/packages/libraries/core/src/client/gateways.ts +++ b/packages/libraries/core/src/client/gateways.ts @@ -1,6 +1,6 @@ import { version } from '../version.js'; import { http } from './http-client.js'; -import type { Logger, SchemaFetcherOptions, ServicesFetcherOptions } from './types.js'; +import type { SchemaFetcherOptions, ServicesFetcherOptions } from './types.js'; import { createHash, joinUrl } from './utils.js'; interface Schema { diff --git a/packages/libraries/core/src/client/utils.ts b/packages/libraries/core/src/client/utils.ts index ec453285ab..46d0ddb43e 100644 --- a/packages/libraries/core/src/client/utils.ts +++ b/packages/libraries/core/src/client/utils.ts @@ -194,7 +194,7 @@ export function createHiveLogger(baseLogger: Logger, prefix: string): HiveLogger const context: HiveLogger[typeof hiveSymbol] = { path: '', logger: baseLogger, - // @ts-ignore + // @ts-expect-error internal stuff ...baseLogger?.[hiveSymbol], }; context.path = context.path + prefix; @@ -208,7 +208,7 @@ export function createHiveLogger(baseLogger: Logger, prefix: string): HiveLogger }, error: (error: any, ...data: any[]) => { if (error.stack) { - for (const stack of error.stack?.split('\n')) { + for (const stack of error.stack.split('\n')) { logger.error(`${path} ${stack}`); } } else { diff --git a/packages/libraries/core/tests/reporting.spec.ts b/packages/libraries/core/tests/reporting.spec.ts index 0ef2634fd4..ab85229ed5 100644 --- a/packages/libraries/core/tests/reporting.spec.ts +++ b/packages/libraries/core/tests/reporting.spec.ts @@ -66,7 +66,6 @@ test('should send data to Hive', async () => { const serviceUrl = 'https://api.com'; const serviceName = 'my-api'; - let body: any = {}; const http = nock('http://localhost') .post('/200') .matchHeader('Authorization', `Bearer ${token}`) @@ -75,7 +74,6 @@ test('should send data to Hive', async () => { .matchHeader('graphql-client-version', headers['graphql-client-version']) .once() .reply((_, _body) => { - body = _body; return [ 200, { From 6b4ac02ec9b9424fce999a756508ebb4fa80de3d Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 11:54:22 +0200 Subject: [PATCH 06/16] host --- .../libraries/apollo/tests/apollo.spec.ts | 4 +- .../libraries/core/tests/http-client.spec.ts | 58 +++++++++---------- packages/libraries/core/tests/test-utils.ts | 3 +- packages/libraries/core/tests/usage.spec.ts | 10 ++-- packages/libraries/yoga/tests/yoga.spec.ts | 28 ++++----- 5 files changed, 52 insertions(+), 51 deletions(-) diff --git a/packages/libraries/apollo/tests/apollo.spec.ts b/packages/libraries/apollo/tests/apollo.spec.ts index d36cabb1d2..d29f306f63 100644 --- a/packages/libraries/apollo/tests/apollo.spec.ts +++ b/packages/libraries/apollo/tests/apollo.spec.ts @@ -82,12 +82,12 @@ test('should not interrupt the process', async () => { logger, }, reporting: { - endpoint: 'http://404.localhost/registry', + endpoint: 'http://404.localhost.noop/registry', author: 'jest', commit: 'js', }, usage: { - endpoint: 'http://404.localhost/usage', + endpoint: 'http://404.localhost.noop/usage', }, }), ], diff --git a/packages/libraries/core/tests/http-client.spec.ts b/packages/libraries/core/tests/http-client.spec.ts index 824d0effb4..e1ab0d578f 100644 --- a/packages/libraries/core/tests/http-client.spec.ts +++ b/packages/libraries/core/tests/http-client.spec.ts @@ -3,7 +3,7 @@ import { makeFetchCall } from '../src/client/http-client'; test('HTTP call without retries and system level error', async () => { const logger = createHiveTestingLogger(); - const response = await makeFetchCall('https://ap.localhost', { + const response = await makeFetchCall('https://ap.localhost.noop', { method: 'GET', retry: false, headers: {}, @@ -15,15 +15,15 @@ test('HTTP call without retries and system level error', async () => { } expect(logger.getLogs()).toMatchInlineSnapshot(` - [INF] GET https://ap.localhost - [ERR] Error: getaddrinfo ENOTFOUND ap.localhost - [ERR] GET https://ap.localhost failed (666ms). getaddrinfo ENOTFOUND ap.localhost + [INF] GET https://ap.localhost.noop + [ERR] Error: getaddrinfo ENOTFOUND ap.localhost.noop + [ERR] GET https://ap.localhost.noop failed (666ms). getaddrinfo ENOTFOUND ap.localhost.noop `); }); test('HTTP with retries and system', async () => { const logger = createHiveTestingLogger(); - await makeFetchCall('https://ap.localhost', { + await makeFetchCall('https://ap.localhost.noop', { method: 'GET', retry: { retries: 1, @@ -33,18 +33,18 @@ test('HTTP with retries and system', async () => { }).catch(_ => {}); expect(logger.getLogs()).toMatchInlineSnapshot(` - [INF] GET https://ap.localhost Attempt (1/2) - [ERR] Error: getaddrinfo ENOTFOUND ap.localhost - [ERR] GET https://ap.localhost failed (666ms). getaddrinfo ENOTFOUND ap.localhost - [INF] GET https://ap.localhost Attempt (2/2) - [ERR] Error: getaddrinfo ENOTFOUND ap.localhost - [ERR] GET https://ap.localhost failed (666ms). getaddrinfo ENOTFOUND ap.localhost + [INF] GET https://ap.localhost.noop Attempt (1/2) + [ERR] Error: getaddrinfo ENOTFOUND ap.localhost.noop + [ERR] GET https://ap.localhost.noop failed (666ms). getaddrinfo ENOTFOUND ap.localhost.noop + [INF] GET https://ap.localhost.noop Attempt (2/2) + [ERR] Error: getaddrinfo ENOTFOUND ap.localhost.noop + [ERR] GET https://ap.localhost.noop failed (666ms). getaddrinfo ENOTFOUND ap.localhost.noop `); }); test('HTTP with 4xx status code will not be retried', async () => { const logger = createHiveTestingLogger(); - await makeFetchCall('https://ap.localhost', { + await makeFetchCall('https://ap.localhost.noop', { method: 'GET', retry: { retries: 1, @@ -60,8 +60,8 @@ test('HTTP with 4xx status code will not be retried', async () => { }).catch(_ => {}); expect(logger.getLogs()).toMatchInlineSnapshot(` - [INF] GET https://ap.localhost Attempt (1/2) - [ERR] GET https://ap.localhost failed with status 404 (666ms): Bubatzbieber + [INF] GET https://ap.localhost.noop Attempt (1/2) + [ERR] GET https://ap.localhost.noop failed with status 404 (666ms): Bubatzbieber [ERR] Abort retry because of status code 404. `); }); @@ -69,7 +69,7 @@ test('HTTP with 4xx status code will not be retried', async () => { test('HTTP with 5xx status code will be retried', async () => { const logger = createHiveTestingLogger(); - await makeFetchCall('https://ap.localhost', { + await makeFetchCall('https://ap.localhost.noop', { method: 'GET', retry: { retries: 1, @@ -85,18 +85,18 @@ test('HTTP with 5xx status code will be retried', async () => { }).catch(_ => {}); expect(logger.getLogs()).toMatchInlineSnapshot(` - [INF] GET https://ap.localhost Attempt (1/2) - [ERR] GET https://ap.localhost failed with status 500 (666ms): Bubatzbieber - [INF] GET https://ap.localhost Attempt (2/2) - [ERR] GET https://ap.localhost failed with status 500 (666ms): Bubatzbieber - [ERR] GET https://ap.localhost retry limit exceeded after 2 attempts. + [INF] GET https://ap.localhost.noop Attempt (1/2) + [ERR] GET https://ap.localhost.noop failed with status 500 (666ms): Bubatzbieber + [INF] GET https://ap.localhost.noop Attempt (2/2) + [ERR] GET https://ap.localhost.noop failed with status 500 (666ms): Bubatzbieber + [ERR] GET https://ap.localhost.noop retry limit exceeded after 2 attempts. `); }); test('HTTP with status 3xx will be retried', async () => { const logger = createHiveTestingLogger(); - await makeFetchCall('https://ap.localhost', { + await makeFetchCall('https://ap.localhost.noop', { method: 'GET', retry: { retries: 1, @@ -112,18 +112,18 @@ test('HTTP with status 3xx will be retried', async () => { }).catch(_ => {}); expect(logger.getLogs()).toMatchInlineSnapshot(` - [INF] GET https://ap.localhost Attempt (1/2) - [ERR] GET https://ap.localhost failed with status 302 (666ms): Bubatzbieber - [INF] GET https://ap.localhost Attempt (2/2) - [ERR] GET https://ap.localhost failed with status 302 (666ms): Bubatzbieber - [ERR] GET https://ap.localhost retry limit exceeded after 2 attempts. + [INF] GET https://ap.localhost.noop Attempt (1/2) + [ERR] GET https://ap.localhost.noop failed with status 302 (666ms): Bubatzbieber + [INF] GET https://ap.localhost.noop Attempt (2/2) + [ERR] GET https://ap.localhost.noop failed with status 302 (666ms): Bubatzbieber + [ERR] GET https://ap.localhost.noop retry limit exceeded after 2 attempts. `); }); test('HTTP with status 3xx will not be retried with custom "isRequestOk" implementation', async () => { const logger = createHiveTestingLogger(); - await makeFetchCall('https://ap.localhost', { + await makeFetchCall('https://ap.localhost.noop', { method: 'GET', retry: { retries: 1, @@ -140,7 +140,7 @@ test('HTTP with status 3xx will not be retried with custom "isRequestOk" impleme }).catch(_ => {}); expect(logger.getLogs()).toMatchInlineSnapshot(` - [INF] GET https://ap.localhost Attempt (1/2) - [INF] GET https://ap.localhost succeeded with status 302 (666ms). + [INF] GET https://ap.localhost.noop Attempt (1/2) + [INF] GET https://ap.localhost.noop succeeded with status 302 (666ms). `); }); diff --git a/packages/libraries/core/tests/test-utils.ts b/packages/libraries/core/tests/test-utils.ts index 7157351076..4ab2b5d4f4 100644 --- a/packages/libraries/core/tests/test-utils.ts +++ b/packages/libraries/core/tests/test-utils.ts @@ -13,7 +13,8 @@ function getLogLines(calls: Array>) { // Replace milliseconds with static value .replace(/\(\d{1,3}ms\)/, '(666ms)') // Replace stack trace line numbers with static value - .replace(/\(node:net:\d+:\d+\)/, '(node:net:666:666)'); + .replace(/\(node:net:\d+:\d+\)/, '(node:net:666:666)') + .replace(/\(node:dns:\d+:\d+\)/, '(node:dns:666:666)'); } else { msg = String(log[1]); } diff --git a/packages/libraries/core/tests/usage.spec.ts b/packages/libraries/core/tests/usage.spec.ts index 95295a64a7..0da0884b79 100644 --- a/packages/libraries/core/tests/usage.spec.ts +++ b/packages/libraries/core/tests/usage.spec.ts @@ -340,7 +340,7 @@ test('should not leak the exception', async () => { }, token: 'Token', usage: { - endpoint: 'http://404.localhost', + endpoint: 'http://404.localhost.noop', }, }); @@ -358,10 +358,10 @@ test('should not leak the exception', async () => { expect(logger.getLogs()).toMatchInlineSnapshot(` [INF] [hive][usage] Sending report (queue 1) - [INF] [hive][usage] POST http://404.localhost Attempt (1/2) - [ERR] [hive][usage] Error: getaddrinfo ENOTFOUND 404.localhost - [ERR] [hive][usage] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:120:26) - [ERR] [hive][usage] POST http://404.localhost failed (666ms). getaddrinfo ENOTFOUND 404.localhost + [INF] [hive][usage] POST http://404.localhost.noop Attempt (1/2) + [ERR] [hive][usage] Error: getaddrinfo ENOTFOUND 404.localhost.noop + [ERR] [hive][usage] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:666:666) + [ERR] [hive][usage] POST http://404.localhost.noop failed (666ms). getaddrinfo ENOTFOUND 404.localhost.noop [INF] [hive][usage] Disposing `); }); diff --git a/packages/libraries/yoga/tests/yoga.spec.ts b/packages/libraries/yoga/tests/yoga.spec.ts index 886644735f..558cf61d0b 100644 --- a/packages/libraries/yoga/tests/yoga.spec.ts +++ b/packages/libraries/yoga/tests/yoga.spec.ts @@ -66,12 +66,12 @@ test('should not interrupt the process', async () => { logger, }, reporting: { - endpoint: 'http://404.localhost/registry', + endpoint: 'http://404.localhost.noop/registry', author: 'jest', commit: 'js', }, usage: { - endpoint: 'http://404.localhost/usage', + endpoint: 'http://404.localhost.noop/usage', }, }); @@ -109,10 +109,10 @@ test('should not interrupt the process', async () => { .join(`\n`), ).toMatchInlineSnapshot(` [INF] [hive][info] Fetching token details... - [INF] [hive][info] POST http://404.localhost/registry Attempt (1/6) - [ERR] [hive][info] Error: getaddrinfo ENOTFOUND 404.localhost - [ERR] [hive][info] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:120:26) - [ERR] [hive][info] POST http://404.localhost/registry failed (666ms). getaddrinfo ENOTFOUND 404.localhost + [INF] [hive][info] POST http://404.localhost.noop/registry Attempt (1/6) + [ERR] [hive][info] Error: getaddrinfo ENOTFOUND 404.localhost.noop + [ERR] [hive][info] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:666:666) + [ERR] [hive][info] POST http://404.localhost.noop/registry failed (666ms). getaddrinfo ENOTFOUND 404.localhost.noop `); expect( logger @@ -122,10 +122,10 @@ test('should not interrupt the process', async () => { .join(`\n`), ).toMatchInlineSnapshot(` [INF] [hive][reporting] Publish schema - [INF] [hive][reporting] POST http://404.localhost/registry Attempt (1/6) - [ERR] [hive][reporting] Error: getaddrinfo ENOTFOUND 404.localhost - [ERR] [hive][reporting] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:120:26) - [ERR] [hive][reporting] POST http://404.localhost/registry failed (666ms). getaddrinfo ENOTFOUND 404.localhost + [INF] [hive][reporting] POST http://404.localhost.noop/registry Attempt (1/6) + [ERR] [hive][reporting] Error: getaddrinfo ENOTFOUND 404.localhost.noop + [ERR] [hive][reporting] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:666:666) + [ERR] [hive][reporting] POST http://404.localhost.noop/registry failed (666ms). getaddrinfo ENOTFOUND 404.localhost.noop `); expect( logger @@ -135,10 +135,10 @@ test('should not interrupt the process', async () => { .join(`\n`), ).toMatchInlineSnapshot(` [INF] [hive][usage] Sending report (queue 1) - [INF] [hive][usage] POST http://404.localhost/usage - [ERR] [hive][usage] Error: getaddrinfo ENOTFOUND 404.localhost - [ERR] [hive][usage] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:120:26) - [ERR] [hive][usage] POST http://404.localhost/usage failed (666ms). getaddrinfo ENOTFOUND 404.localhost + [INF] [hive][usage] POST http://404.localhost.noop/usage + [ERR] [hive][usage] Error: getaddrinfo ENOTFOUND 404.localhost.noop + [ERR] [hive][usage] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:666:666) + [ERR] [hive][usage] POST http://404.localhost.noop/usage failed (666ms). getaddrinfo ENOTFOUND 404.localhost.noop [ERR] [hive][usage] Failed to send report. `); From 9393f939db3bbd639bcff8500bfbc2ca500b4b2f Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 12:21:32 +0200 Subject: [PATCH 07/16] changesets --- .changeset/chilly-balloons-cover.md | 27 ++++++++++++++++++++++++++ .changeset/fuzzy-readers-melt.md | 7 +++++++ .changeset/stupid-rabbits-swim.md | 5 +++++ packages/libraries/apollo/src/index.ts | 4 ++++ 4 files changed, 43 insertions(+) create mode 100644 .changeset/chilly-balloons-cover.md create mode 100644 .changeset/fuzzy-readers-melt.md create mode 100644 .changeset/stupid-rabbits-swim.md diff --git a/.changeset/chilly-balloons-cover.md b/.changeset/chilly-balloons-cover.md new file mode 100644 index 0000000000..3be205fb4b --- /dev/null +++ b/.changeset/chilly-balloons-cover.md @@ -0,0 +1,27 @@ +--- +'@graphql-hive/apollo': minor +--- + +Better HTTP info, error and debug logging. + +For the supergraph manager, pass a `console` instance as the `logger` property. + +```ts +import { createSupergraphManager } from '@graphql-hive/apollo'; + +const manager = createSupergraphManager({ + ...otherOptions, + logger: console, +}) +``` + +For the supergraph SDL fetcher pass a `console` instance as the `logger` property. + +```ts +import { createSupergraphSDLFetcher } from '@graphql-hive/apollo'; + +const manager = createSupergraphSDLFetcher({ + ...otherOptions, + logger: console, +}) +``` \ No newline at end of file diff --git a/.changeset/fuzzy-readers-melt.md b/.changeset/fuzzy-readers-melt.md new file mode 100644 index 0000000000..692311edd5 --- /dev/null +++ b/.changeset/fuzzy-readers-melt.md @@ -0,0 +1,7 @@ +--- +'@graphql-hive/core': minor +'@graphql-hive/yoga': minor +'@graphql-hive/apollo': minor +--- + +Improved logging output of HTTP requests and retires. diff --git a/.changeset/stupid-rabbits-swim.md b/.changeset/stupid-rabbits-swim.md new file mode 100644 index 0000000000..0820f6c4f5 --- /dev/null +++ b/.changeset/stupid-rabbits-swim.md @@ -0,0 +1,5 @@ +--- +'@graphql-hive/cli': minor +--- + +Provide debug logging for HTTP requests when setting environment variable `NODE_ENV` to `development`. diff --git a/packages/libraries/apollo/src/index.ts b/packages/libraries/apollo/src/index.ts index 8e0f258260..233798b53c 100644 --- a/packages/libraries/apollo/src/index.ts +++ b/packages/libraries/apollo/src/index.ts @@ -9,6 +9,7 @@ import { http, isHiveClient, joinUrl, + Logger, } from '@graphql-hive/core'; import { version } from './version.js'; @@ -17,6 +18,7 @@ export { atLeastOnceSampler, createSchemaFetcher, createServicesFetcher } from ' export interface SupergraphSDLFetcherOptions { endpoint: string; key: string; + logger?: Logger; } export function createSupergraphSDLFetcher(options: SupergraphSDLFetcherOptions) { @@ -50,6 +52,7 @@ export function createSupergraphSDLFetcher(options: SupergraphSDLFetcherOptions) maxTimeout: 200, minTimeout: 1, }, + logger: options.logger, }) .then(async response => { if (response.ok) { @@ -86,6 +89,7 @@ export function createSupergraphManager( const fetchSupergraph = createSupergraphSDLFetcher({ endpoint: options.endpoint, key: options.key, + logger: options.logger, }); let timer: ReturnType | null = null; From a458bfb0c66070c0a67f7bc3c69dcc3924675682 Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 12:27:26 +0200 Subject: [PATCH 08/16] ok --- packages/libraries/yoga/tests/yoga.spec.ts | 13 ------------- 1 file changed, 13 deletions(-) diff --git a/packages/libraries/yoga/tests/yoga.spec.ts b/packages/libraries/yoga/tests/yoga.spec.ts index 558cf61d0b..6bd6b17792 100644 --- a/packages/libraries/yoga/tests/yoga.spec.ts +++ b/packages/libraries/yoga/tests/yoga.spec.ts @@ -101,19 +101,6 @@ test('should not interrupt the process', async () => { ); await waitFor(50); - expect( - logger - .getLogs() - .split(`\n`) - .filter(item => item.includes(`[hive][info]`)) - .join(`\n`), - ).toMatchInlineSnapshot(` - [INF] [hive][info] Fetching token details... - [INF] [hive][info] POST http://404.localhost.noop/registry Attempt (1/6) - [ERR] [hive][info] Error: getaddrinfo ENOTFOUND 404.localhost.noop - [ERR] [hive][info] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:666:666) - [ERR] [hive][info] POST http://404.localhost.noop/registry failed (666ms). getaddrinfo ENOTFOUND 404.localhost.noop - `); expect( logger .getLogs() From 664c5528177e9d5154aeebe1a73b06848656c6cc Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 12:41:48 +0200 Subject: [PATCH 09/16] fix --- packages/libraries/yoga/tests/yoga.spec.ts | 45 ++++++++-------------- 1 file changed, 17 insertions(+), 28 deletions(-) diff --git a/packages/libraries/yoga/tests/yoga.spec.ts b/packages/libraries/yoga/tests/yoga.spec.ts index 6bd6b17792..c9d1ce0eb6 100644 --- a/packages/libraries/yoga/tests/yoga.spec.ts +++ b/packages/libraries/yoga/tests/yoga.spec.ts @@ -99,35 +99,24 @@ test('should not interrupt the process', async () => { }, }), ); - await waitFor(50); - expect( - logger - .getLogs() - .split(`\n`) - .filter(item => item.includes(`[hive][reporting]`)) - .join(`\n`), - ).toMatchInlineSnapshot(` - [INF] [hive][reporting] Publish schema - [INF] [hive][reporting] POST http://404.localhost.noop/registry Attempt (1/6) - [ERR] [hive][reporting] Error: getaddrinfo ENOTFOUND 404.localhost.noop - [ERR] [hive][reporting] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:666:666) - [ERR] [hive][reporting] POST http://404.localhost.noop/registry failed (666ms). getaddrinfo ENOTFOUND 404.localhost.noop - `); - expect( - logger - .getLogs() - .split(`\n`) - .filter(item => item.includes(`[hive][usage]`)) - .join(`\n`), - ).toMatchInlineSnapshot(` - [INF] [hive][usage] Sending report (queue 1) - [INF] [hive][usage] POST http://404.localhost.noop/usage - [ERR] [hive][usage] Error: getaddrinfo ENOTFOUND 404.localhost.noop - [ERR] [hive][usage] at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:666:666) - [ERR] [hive][usage] POST http://404.localhost.noop/usage failed (666ms). getaddrinfo ENOTFOUND 404.localhost.noop - [ERR] [hive][usage] Failed to send report. - `); + + const reportingLogs = logger + .getLogs() + .split(`\n`) + .filter(item => item.includes(`[hive][reporting]`)) + .join(`\n`); + + expect(reportingLogs).includes('Publish schema'); + expect(reportingLogs).includes('POST http://404.localhost.noop/registry'); + + const usageLogs = logger + .getLogs() + .split(`\n`) + .filter(item => item.includes(`[hive][usage]`)) + .join(`\n`); + + expect(usageLogs).includes('POST http://404.localhost.noop/usage'); await hive.dispose(); clean(); From 405651bde44427bebcb6d1029ba86305d102bde8 Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 13:08:25 +0200 Subject: [PATCH 10/16] ok --- packages/libraries/apollo/tests/apollo.spec.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/libraries/apollo/tests/apollo.spec.ts b/packages/libraries/apollo/tests/apollo.spec.ts index d29f306f63..d41d109753 100644 --- a/packages/libraries/apollo/tests/apollo.spec.ts +++ b/packages/libraries/apollo/tests/apollo.spec.ts @@ -100,7 +100,7 @@ test('should not interrupt the process', async () => { } `, }); - await waitFor(50); + await waitFor(200); await apollo.stop(); clean(); expect(logger.error).toHaveBeenCalledWith(expect.stringContaining('[hive][info]')); From a7ef642ff00d6556b368de0cd50c8d0ec34a722a Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 13:12:12 +0200 Subject: [PATCH 11/16] fix --- packages/libraries/core/tests/http-client.spec.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/libraries/core/tests/http-client.spec.ts b/packages/libraries/core/tests/http-client.spec.ts index e1ab0d578f..0248cd4bb7 100644 --- a/packages/libraries/core/tests/http-client.spec.ts +++ b/packages/libraries/core/tests/http-client.spec.ts @@ -1,5 +1,5 @@ -import { createHiveTestingLogger } from 'test-utils'; import { makeFetchCall } from '../src/client/http-client'; +import { createHiveTestingLogger } from './test-utils'; test('HTTP call without retries and system level error', async () => { const logger = createHiveTestingLogger(); From ff780ac320fb89edc4d63ab119d1e15f93d17e75 Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 13:33:21 +0200 Subject: [PATCH 12/16] infor opt-in --- packages/libraries/cli/src/base-command.ts | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/packages/libraries/cli/src/base-command.ts b/packages/libraries/cli/src/base-command.ts index ab5fbcb9ce..dea3980086 100644 --- a/packages/libraries/cli/src/base-command.ts +++ b/packages/libraries/cli/src/base-command.ts @@ -173,6 +173,16 @@ export default abstract class extends Command { variables, }), { + logger: { + info: (...args) => { + if (process.env.NODE_ENV === 'development') { + console.info(...args); + } + }, + error: (...args) => { + console.error(...args); + }, + }, headers: requestHeaders, }, ); From c8845399fb0f9087c2e3a10a0ad05ed942d80f58 Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 13:46:55 +0200 Subject: [PATCH 13/16] ok --- packages/libraries/cli/src/base-command.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/packages/libraries/cli/src/base-command.ts b/packages/libraries/cli/src/base-command.ts index dea3980086..262788b05a 100644 --- a/packages/libraries/cli/src/base-command.ts +++ b/packages/libraries/cli/src/base-command.ts @@ -175,6 +175,7 @@ export default abstract class extends Command { { logger: { info: (...args) => { + // eslint-disable-next-line no-process-env if (process.env.NODE_ENV === 'development') { console.info(...args); } From 0a7580d9a97ee52d9bf9b238c6869ca21103298c Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 15:34:44 +0200 Subject: [PATCH 14/16] base command --- packages/libraries/cli/src/base-command.ts | 48 +++++++++++++++---- .../cli/src/commands/artifact/fetch.ts | 2 +- .../cli/src/commands/config/delete.ts | 4 +- .../libraries/cli/src/commands/config/get.ts | 4 +- .../cli/src/commands/config/reset.ts | 4 +- .../libraries/cli/src/commands/config/set.ts | 4 +- packages/libraries/cli/src/commands/dev.ts | 2 +- .../libraries/cli/src/commands/introspect.ts | 2 +- .../cli/src/commands/operations/check.ts | 2 +- .../cli/src/commands/schema/check.ts | 2 +- .../cli/src/commands/schema/delete.ts | 2 +- .../cli/src/commands/schema/fetch.ts | 2 +- .../cli/src/commands/schema/publish.ts | 2 +- packages/libraries/cli/src/commands/whoami.ts | 2 +- 14 files changed, 57 insertions(+), 25 deletions(-) diff --git a/packages/libraries/cli/src/base-command.ts b/packages/libraries/cli/src/base-command.ts index 262788b05a..728f1f9979 100644 --- a/packages/libraries/cli/src/base-command.ts +++ b/packages/libraries/cli/src/base-command.ts @@ -3,22 +3,53 @@ import { print, type GraphQLError } from 'graphql'; import type { ExecutionResult } from 'graphql'; import { http } from '@graphql-hive/core'; import type { TypedDocumentNode } from '@graphql-typed-document-node/core'; -import { Command, Errors, Config as OclifConfig } from '@oclif/core'; +import { Command, Errors, Flags, Interfaces, Config as OclifConfig } from '@oclif/core'; import { Config, GetConfigurationValueType, ValidConfigurationKeys } from './helpers/config'; +export type Flags = Interfaces.InferredFlags< + (typeof BaseCommand)['baseFlags'] & T['flags'] +>; +export type Args = Interfaces.InferredArgs; + type OmitNever = { [K in keyof T as T[K] extends never ? never : K]: T[K] }; -export default abstract class extends Command { - protected _userConfig: Config; +export default abstract class BaseCommand extends Command { + protected _userConfig: Config | undefined; + + static baseFlags = { + debug: Flags.boolean({ + default: false, + summary: 'Whether debug output for HTTP calls and similar should be enabled.', + }), + }; + + protected flags!: Flags; + protected args!: Args; - protected constructor(argv: string[], config: OclifConfig) { - super(argv, config); + protected get userConfig(): Config { + if (!this._userConfig) { + throw new Error('User config is not initialized'); + } + return this._userConfig!; + } + + public async init(): Promise { + await super.init(); this._userConfig = new Config({ // eslint-disable-next-line no-process-env filepath: process.env.HIVE_CONFIG, rootDir: process.cwd(), }); + + const { args, flags } = await this.parse({ + flags: this.ctor.flags, + baseFlags: (super.ctor as typeof BaseCommand).baseFlags, + args: this.ctor.args, + strict: this.ctor.strict, + }); + this.flags = flags as Flags; + this.args = args as Args; } success(...args: any[]) { @@ -122,7 +153,7 @@ export default abstract class extends Command { return process.env[env] as TArgs[keyof TArgs] as NonNullable>; } - const userConfigValue = this._userConfig.get(key); + const userConfigValue = this._userConfig!.get(key); if (userConfigValue != null) { return userConfigValue; @@ -161,6 +192,8 @@ export default abstract class extends Command { ...additionalHeaders, }; + const isDebug = this.flags.debug; + return { async request( operation: TypedDocumentNode, @@ -175,8 +208,7 @@ export default abstract class extends Command { { logger: { info: (...args) => { - // eslint-disable-next-line no-process-env - if (process.env.NODE_ENV === 'development') { + if (isDebug) { console.info(...args); } }, diff --git a/packages/libraries/cli/src/commands/artifact/fetch.ts b/packages/libraries/cli/src/commands/artifact/fetch.ts index 56ebae12c0..7ab8769143 100644 --- a/packages/libraries/cli/src/commands/artifact/fetch.ts +++ b/packages/libraries/cli/src/commands/artifact/fetch.ts @@ -2,7 +2,7 @@ import { http, URL } from '@graphql-hive/core'; import { Flags } from '@oclif/core'; import Command from '../../base-command'; -export default class ArtifactsFetch extends Command { +export default class ArtifactsFetch extends Command { static description = 'fetch artifacts from the CDN'; static flags = { 'cdn.endpoint': Flags.string({ diff --git a/packages/libraries/cli/src/commands/config/delete.ts b/packages/libraries/cli/src/commands/config/delete.ts index 4d4b18396d..a3922da099 100644 --- a/packages/libraries/cli/src/commands/config/delete.ts +++ b/packages/libraries/cli/src/commands/config/delete.ts @@ -1,7 +1,7 @@ import { Args } from '@oclif/core'; import Command from '../../base-command'; -export default class DeleteConfig extends Command { +export default class DeleteConfig extends Command { static description = 'deletes specific cli configuration'; static args = { key: Args.string({ @@ -13,7 +13,7 @@ export default class DeleteConfig extends Command { async run() { const { args } = await this.parse(DeleteConfig); - this._userConfig.delete(args.key); + this._userConfig!.delete(args.key); this.success(this.bolderize(`Config flag "${args.key}" was deleted`)); } } diff --git a/packages/libraries/cli/src/commands/config/get.ts b/packages/libraries/cli/src/commands/config/get.ts index a5fa67f520..893a4991e1 100644 --- a/packages/libraries/cli/src/commands/config/get.ts +++ b/packages/libraries/cli/src/commands/config/get.ts @@ -2,7 +2,7 @@ import { Args } from '@oclif/core'; import Command from '../../base-command'; import { allowedKeys, ValidConfigurationKeys } from '../../helpers/config'; -export default class GetConfig extends Command { +export default class GetConfig extends Command { static description = 'prints specific cli configuration'; static args = { key: Args.string({ @@ -15,6 +15,6 @@ export default class GetConfig extends Command { async run() { const { args } = await this.parse(GetConfig); - console.dir(this._userConfig.get(args.key as ValidConfigurationKeys)); + console.dir(this.userConfig.get(args.key as ValidConfigurationKeys)); } } diff --git a/packages/libraries/cli/src/commands/config/reset.ts b/packages/libraries/cli/src/commands/config/reset.ts index 19ceb3d8c6..7800fea672 100644 --- a/packages/libraries/cli/src/commands/config/reset.ts +++ b/packages/libraries/cli/src/commands/config/reset.ts @@ -1,10 +1,10 @@ import Command from '../../base-command'; -export default class ResetConfig extends Command { +export default class ResetConfig extends Command { static description = 'resets local cli configuration'; async run() { - this._userConfig.clear(); + this.userConfig.clear(); this.success('Config cleared.'); } } diff --git a/packages/libraries/cli/src/commands/config/set.ts b/packages/libraries/cli/src/commands/config/set.ts index bd3b57516c..bcbc5d9ac4 100644 --- a/packages/libraries/cli/src/commands/config/set.ts +++ b/packages/libraries/cli/src/commands/config/set.ts @@ -2,7 +2,7 @@ import { Args } from '@oclif/core'; import Command from '../../base-command'; import { allowedKeys, ValidConfigurationKeys } from '../../helpers/config'; -export default class SetConfig extends Command { +export default class SetConfig extends Command { static description = 'updates specific cli configuration'; static args = { key: Args.string({ @@ -20,7 +20,7 @@ export default class SetConfig extends Command { async run() { const { args } = await this.parse(SetConfig); - this._userConfig.set(args.key as ValidConfigurationKeys, args.value); + this.userConfig.set(args.key as ValidConfigurationKeys, args.value); this.success(this.bolderize(`Config flag "${args.key}" was set to "${args.value}"`)); } } diff --git a/packages/libraries/cli/src/commands/dev.ts b/packages/libraries/cli/src/commands/dev.ts index 349c16e606..26f5886248 100644 --- a/packages/libraries/cli/src/commands/dev.ts +++ b/packages/libraries/cli/src/commands/dev.ts @@ -83,7 +83,7 @@ type ServiceWithSource = { }; }; -export default class Dev extends Command { +export default class Dev extends Command { static description = [ 'Develop and compose Supergraph with your local services.', 'Only available for Federation projects.', diff --git a/packages/libraries/cli/src/commands/introspect.ts b/packages/libraries/cli/src/commands/introspect.ts index 0aa4a30f5c..a29b731b9b 100644 --- a/packages/libraries/cli/src/commands/introspect.ts +++ b/packages/libraries/cli/src/commands/introspect.ts @@ -5,7 +5,7 @@ import { Args, Flags } from '@oclif/core'; import Command from '../base-command'; import { loadSchema } from '../helpers/schema'; -export default class Introspect extends Command { +export default class Introspect extends Command { static description = 'introspects a GraphQL Schema'; static flags = { write: Flags.string({ diff --git a/packages/libraries/cli/src/commands/operations/check.ts b/packages/libraries/cli/src/commands/operations/check.ts index fcb74a8ae8..4dd2c95793 100644 --- a/packages/libraries/cli/src/commands/operations/check.ts +++ b/packages/libraries/cli/src/commands/operations/check.ts @@ -14,7 +14,7 @@ const fetchLatestVersionQuery = graphql(/* GraphQL */ ` } `); -export default class OperationsCheck extends Command { +export default class OperationsCheck extends Command { static description = 'checks operations against a published schema'; static flags = { 'registry.endpoint': Flags.string({ diff --git a/packages/libraries/cli/src/commands/schema/check.ts b/packages/libraries/cli/src/commands/schema/check.ts index 8050e4539f..bdfad3c73c 100644 --- a/packages/libraries/cli/src/commands/schema/check.ts +++ b/packages/libraries/cli/src/commands/schema/check.ts @@ -86,7 +86,7 @@ const schemaCheckMutation = graphql(/* GraphQL */ ` } `); -export default class SchemaCheck extends Command { +export default class SchemaCheck extends Command { static description = 'checks schema'; static flags = { service: Flags.string({ diff --git a/packages/libraries/cli/src/commands/schema/delete.ts b/packages/libraries/cli/src/commands/schema/delete.ts index 0058d0f43b..ada5db2543 100644 --- a/packages/libraries/cli/src/commands/schema/delete.ts +++ b/packages/libraries/cli/src/commands/schema/delete.ts @@ -37,7 +37,7 @@ const schemaDeleteMutation = graphql(/* GraphQL */ ` } `); -export default class SchemaDelete extends Command { +export default class SchemaDelete extends Command { static description = 'deletes a schema'; static flags = { 'registry.endpoint': Flags.string({ diff --git a/packages/libraries/cli/src/commands/schema/fetch.ts b/packages/libraries/cli/src/commands/schema/fetch.ts index b4fc2b5ee0..3498c4877c 100644 --- a/packages/libraries/cli/src/commands/schema/fetch.ts +++ b/packages/libraries/cli/src/commands/schema/fetch.ts @@ -20,7 +20,7 @@ const SchemaVersionForActionIdQuery = graphql(/* GraphQL */ ` } `); -export default class SchemaFetch extends Command { +export default class SchemaFetch extends Command { static description = 'fetch schema or supergraph from the Hive API'; static flags = { /** @deprecated */ diff --git a/packages/libraries/cli/src/commands/schema/publish.ts b/packages/libraries/cli/src/commands/schema/publish.ts index d65d2ce4b4..a12ccf28f7 100644 --- a/packages/libraries/cli/src/commands/schema/publish.ts +++ b/packages/libraries/cli/src/commands/schema/publish.ts @@ -63,7 +63,7 @@ const schemaPublishMutation = graphql(/* GraphQL */ ` } `); -export default class SchemaPublish extends Command { +export default class SchemaPublish extends Command { static description = 'publishes schema'; static flags = { service: Flags.string({ diff --git a/packages/libraries/cli/src/commands/whoami.ts b/packages/libraries/cli/src/commands/whoami.ts index d986d2d8bf..a30c005e0c 100644 --- a/packages/libraries/cli/src/commands/whoami.ts +++ b/packages/libraries/cli/src/commands/whoami.ts @@ -35,7 +35,7 @@ const myTokenInfoQuery = graphql(/* GraphQL */ ` } `); -export default class WhoAmI extends Command { +export default class WhoAmI extends Command { static description = 'shows information about the current token'; static flags = { 'registry.endpoint': Flags.string({ From 62b15d42142ccaa1ed4f804c0c8289e34c4597e3 Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 15:40:09 +0200 Subject: [PATCH 15/16] update changeset --- .changeset/stupid-rabbits-swim.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.changeset/stupid-rabbits-swim.md b/.changeset/stupid-rabbits-swim.md index 0820f6c4f5..d6279108df 100644 --- a/.changeset/stupid-rabbits-swim.md +++ b/.changeset/stupid-rabbits-swim.md @@ -2,4 +2,4 @@ '@graphql-hive/cli': minor --- -Provide debug logging for HTTP requests when setting environment variable `NODE_ENV` to `development`. +Provide debug logging for HTTP requests when providing the `--debug` flag. From c5ccdc35b9d636f64e5ce5500066da28a937a75c Mon Sep 17 00:00:00 2001 From: Laurin Quast Date: Thu, 1 Aug 2024 16:52:20 +0200 Subject: [PATCH 16/16] fix --- packages/libraries/cli/src/base-command.ts | 2 +- packages/libraries/cli/src/helpers/schema.ts | 8 ++++---- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/packages/libraries/cli/src/base-command.ts b/packages/libraries/cli/src/base-command.ts index 728f1f9979..f29fc5942c 100644 --- a/packages/libraries/cli/src/base-command.ts +++ b/packages/libraries/cli/src/base-command.ts @@ -3,7 +3,7 @@ import { print, type GraphQLError } from 'graphql'; import type { ExecutionResult } from 'graphql'; import { http } from '@graphql-hive/core'; import type { TypedDocumentNode } from '@graphql-typed-document-node/core'; -import { Command, Errors, Flags, Interfaces, Config as OclifConfig } from '@oclif/core'; +import { Command, Errors, Flags, Interfaces } from '@oclif/core'; import { Config, GetConfigurationValueType, ValidConfigurationKeys } from './helpers/config'; export type Flags = Interfaces.InferredFlags< diff --git a/packages/libraries/cli/src/helpers/schema.ts b/packages/libraries/cli/src/helpers/schema.ts index 5bf2babe65..41f4d9fc09 100644 --- a/packages/libraries/cli/src/helpers/schema.ts +++ b/packages/libraries/cli/src/helpers/schema.ts @@ -5,7 +5,7 @@ import { GraphQLFileLoader } from '@graphql-tools/graphql-file-loader'; import { JsonFileLoader } from '@graphql-tools/json-file-loader'; import { loadTypedefs } from '@graphql-tools/load'; import { UrlLoader } from '@graphql-tools/url-loader'; -import baseCommand from '../base-command'; +import BaseCommand from '../base-command'; import { FragmentType, graphql, useFragment as unmaskFragment } from '../gql'; import { CriticalityLevel, SchemaErrorConnection, SchemaWarningConnection } from '../gql/graphql'; @@ -17,7 +17,7 @@ const criticalityMap: Record = { [CriticalityLevel.Dangerous]: colors.green('-'), }; -export function renderErrors(this: baseCommand, errors: SchemaErrorConnection) { +export function renderErrors(this: BaseCommand, errors: SchemaErrorConnection) { this.fail(`Detected ${errors.total} error${errors.total > 1 ? 's' : ''}`); this.log(''); @@ -43,7 +43,7 @@ const RenderChanges_SchemaChanges = graphql(` `); export function renderChanges( - this: baseCommand, + this: BaseCommand, maskedChanges: FragmentType, ) { const changes = unmaskFragment(RenderChanges_SchemaChanges, maskedChanges); @@ -91,7 +91,7 @@ export function renderChanges( } } -export function renderWarnings(this: baseCommand, warnings: SchemaWarningConnection) { +export function renderWarnings(this: BaseCommand, warnings: SchemaWarningConnection) { this.log(''); this.infoWarning(`Detected ${warnings.total} warning${warnings.total > 1 ? 's' : ''}`); this.log('');