Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
76 changes: 76 additions & 0 deletions src/server/lib/github/__tests__/cacheRequest.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -44,6 +44,7 @@ describe('cacheRequest', () => {
let logger: {
debug: jest.Mock;
info: jest.Mock;
warn: jest.Mock;
error: jest.Mock;
};

Expand All @@ -54,6 +55,7 @@ describe('cacheRequest', () => {
logger = {
debug: jest.fn(),
info: jest.fn(),
warn: jest.fn(),
error: jest.fn(),
};
(redisClient.getRedis as jest.Mock).mockReturnValue(cache);
Expand Down Expand Up @@ -328,4 +330,78 @@ describe('cacheRequest', () => {
expect(cache.hset).toHaveBeenCalledTimes(1);
expect(cache.expire).not.toHaveBeenCalled();
});

describe('transient failures', () => {
beforeEach(() => {
jest.useFakeTimers();
});

afterEach(() => {
jest.useRealTimers();
});

it('retries a GET that fails with a server error and returns the eventual response', async () => {
const endpoint = 'GET /repos/acme/widget/git/trees/abc123';
const response = { status: 200, headers: {}, data: { tree: [] } };
request
.mockRejectedValueOnce(Object.assign(new Error('other side closed'), { status: 500 }))
.mockResolvedValueOnce(response);

const pending = cacheRequest(endpoint, {}, { cache });
await jest.advanceTimersByTimeAsync(10_000);
const result = await pending;

expect(result).toBe(response);
expect(request).toHaveBeenCalledTimes(2);
expect(logger.warn).toHaveBeenCalledWith('GitHub: cache request retrying');
expect(getLogger).toHaveBeenCalledWith({ endpoint, status: 500 });
expect(cache.hset).toHaveBeenCalledTimes(1);
});

it('does not retry a non-GET endpoint, so a write is never duplicated', async () => {
const endpoint = 'POST /repos/acme/widget/deployments';
request.mockRejectedValue(Object.assign(new Error('other side closed'), { status: 500 }));

const assertion = expect(cacheRequest(endpoint, { data: { ref: 'main' } }, { cache })).rejects.toMatchObject({
message: 'GitHub API request failed',
});
await jest.advanceTimersByTimeAsync(10_000);
await assertion;

expect(request).toHaveBeenCalledTimes(1);
expect(logger.warn).not.toHaveBeenCalled();
});

it('still retries when a 304 refetch is what hits the server error', async () => {
const endpoint = 'GET /repos/acme/widget';
const response = { status: 200, headers: {}, data: { id: 17 } };
cache.hgetall.mockResolvedValue({ etag: '"stale-etag"', lastModified: '', data: 'not-json' });
request
.mockRejectedValueOnce(Object.assign(new Error('Not Modified'), { status: 304 }))
.mockRejectedValueOnce(Object.assign(new Error('other side closed'), { status: 500 }))
.mockResolvedValueOnce(response);

const pending = cacheRequest(endpoint, {}, { cache });
await jest.advanceTimersByTimeAsync(10_000);

expect(await pending).toBe(response);
expect(request).toHaveBeenCalledTimes(3);
expect(logger.warn).toHaveBeenCalledTimes(1);
});

it('retries only once, then gives up', async () => {
const endpoint = 'GET /repos/acme/widget';
request.mockRejectedValue(Object.assign(new Error('other side closed'), { status: 500 }));

const assertion = expect(cacheRequest(endpoint, {}, { cache })).rejects.toMatchObject({
message: 'GitHub API request failed',
});
await jest.advanceTimersByTimeAsync(10_000);
await assertion;

expect(request).toHaveBeenCalledTimes(2);
expect(logger.warn).toHaveBeenCalledTimes(1);
expect(logger.error).toHaveBeenCalledWith('GitHub: cache request failed');
});
});
});
13 changes: 11 additions & 2 deletions src/server/lib/github/cacheRequest.ts
Original file line number Diff line number Diff line change
Expand Up @@ -22,10 +22,12 @@ import { CacheRequestData } from 'server/lib/github/types';

import { redisClient } from 'server/lib/dependencies';

const TRANSIENT_RETRY_DELAY_MS = 10_000;

export async function cacheRequest(
endpoint: string,
requestData = {} as CacheRequestData,
{ cache = redisClient.getRedis(), ignoreCache = false } = {}
{ cache = redisClient.getRedis(), ignoreCache = false, retried = false } = {}
) {
const cacheKey = `github:req_cache:${endpoint}`;
let cached;
Expand Down Expand Up @@ -73,11 +75,18 @@ export async function cacheRequest(
getLogger({ endpoint, cacheHit: true }).debug('GitHub: cache request hit');
return { data, cacheHit: true };
} catch (error) {
return cacheRequest(endpoint, requestData, { cache, ignoreCache: true });
return cacheRequest(endpoint, requestData, { cache, ignoreCache: true, retried });
}
} else if (error?.status === 404) {
getLogger().info(`GitHub: cache request not found endpoint=${endpoint}`);
throw new Error('Resource not found');
} else if (!retried && endpoint.startsWith('GET ') && error?.status >= 500) {
// Octokit reports a dropped keep-alive socket as status 500, indistinguishable from a real 5xx.
// The wait is long enough to miss the same dead socket, and short enough that a sleeping
// retry does not outlive a worker's shutdown grace and leave its job to stall recovery.
getLogger({ endpoint, status: error.status }).warn('GitHub: cache request retrying');
await new Promise((resolve) => setTimeout(resolve, TRANSIENT_RETRY_DELAY_MS));
return cacheRequest(endpoint, requestData, { cache, ignoreCache, retried: true });
} else {
const errorHeaders = error?.response?.headers || error?.headers;
getLogger({
Expand Down
Loading