diff --git a/src/server/lib/github/__tests__/cacheRequest.test.ts b/src/server/lib/github/__tests__/cacheRequest.test.ts index 247834c8..63636007 100644 --- a/src/server/lib/github/__tests__/cacheRequest.test.ts +++ b/src/server/lib/github/__tests__/cacheRequest.test.ts @@ -44,6 +44,7 @@ describe('cacheRequest', () => { let logger: { debug: jest.Mock; info: jest.Mock; + warn: jest.Mock; error: jest.Mock; }; @@ -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); @@ -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'); + }); + }); }); diff --git a/src/server/lib/github/cacheRequest.ts b/src/server/lib/github/cacheRequest.ts index 733678fe..f96940f6 100644 --- a/src/server/lib/github/cacheRequest.ts +++ b/src/server/lib/github/cacheRequest.ts @@ -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; @@ -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({