Skip to content

Commit

Permalink
feat: full HTTP request logging
Browse files Browse the repository at this point in the history
  • Loading branch information
@n1ru4l
n1ru4l committed Jul 19, 2024
1 parent 918943c commit 9240b57
Show file tree
Hide file tree
Showing 4 changed files with 205 additions and 9 deletions.
7 changes: 5 additions & 2 deletions packages/libraries/core/src/client/agent.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -196,6 +196,7 @@ export function createAgent<TEvent>(
},
timeout: options.timeout,
fetchImplementation: pluginOptions.__testing?.fetch,
logger: options.logger,
})
.catch(error => {
debugLog(`Attempt ${attempt} failed: ${error.message}`);
Expand All @@ -218,7 +219,7 @@ export function createAgent<TEvent>(

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

Expand All @@ -237,7 +238,9 @@ export function createAgent<TEvent>(
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;
}
Expand Down
1 change: 1 addition & 0 deletions packages/libraries/core/src/client/client.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -113,6 +113,7 @@ export function createHive(options: HivePluginOptions): HiveClient {
},
timeout: 30_000,
fetchImplementation: options?.agent?.__testing?.fetch,
logger,
},
);

Expand Down
21 changes: 17 additions & 4 deletions packages/libraries/core/src/client/http-client.ts
View file
Original file line number Diff line number Diff line change
@@ -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<typeof asyncRetry>[1] & {
retryWhen(response: Response): boolean;
Expand All @@ -13,6 +14,7 @@ function get(
timeout?: number;
fetchImplementation?: typeof fetch;
retry?: RetryOptions;
logger?: Logger;
},
) {
return makeFetchCall(endpoint, {
Expand All @@ -21,6 +23,7 @@ function get(
timeout: config.timeout,
retry: config.retry,
fetchImplementation: config.fetchImplementation,
logger: config.logger ?? console,
});
}

Expand All @@ -32,6 +35,7 @@ function post(
timeout?: number;
retry?: RetryOptions;
fetchImplementation?: typeof fetch;
logger?: Logger;
},
) {
return makeFetchCall(endpoint, {
Expand All @@ -41,6 +45,7 @@ function post(
timeout: config.timeout,
retry: config.retry,
fetchImplementation: config.fetchImplementation,
logger: config.logger ?? console,
});
}

Expand All @@ -58,6 +63,7 @@ async function makeFetchCall(
timeout?: number;
retry?: RetryOptions;
fetchImplementation?: typeof fetch;
logger?: Logger;
},
) {
const controller = new AbortController();
Expand Down Expand Up @@ -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,
Expand All @@ -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) {
Expand Down
185 changes: 182 additions & 3 deletions packages/libraries/yoga/tests/yoga.spec.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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<void>(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;
});

0 comments on commit 9240b57

Please sign in to comment.