From 66018e300fe39f3d3485d444a0c1fd80984c5d7d Mon Sep 17 00:00:00 2001 From: Gar Date: Tue, 30 Apr 2024 07:40:23 -0700 Subject: [PATCH] fix: log errors on retry Closes https://github.com/npm/cli/issues/7371 --- lib/remote.js | 4 ++++ package.json | 1 + test/cache.js | 2 +- test/fetch.js | 28 +++++++++++++++++++++++++++- test/options.js | 18 +++++++++--------- 5 files changed, 42 insertions(+), 11 deletions(-) diff --git a/lib/remote.js b/lib/remote.js index 2aef9f8..8554564 100644 --- a/lib/remote.js +++ b/lib/remote.js @@ -2,6 +2,7 @@ const { Minipass } = require('minipass') const fetch = require('minipass-fetch') const promiseRetry = require('promise-retry') const ssri = require('ssri') +const { log } = require('proc-log') const CachingMinipassPipeline = require('./pipeline.js') const { getAgent } = require('@npmcli/agent') @@ -89,6 +90,8 @@ const remoteFetch = (request, options) => { options.onRetry(res) } + /* eslint-disable-next-line max-len */ + log.http('fetch', `${req.method} ${req.url} attempt ${attemptNum} failed with ${res.status}`) return retryHandler(res) } @@ -112,6 +115,7 @@ const remoteFetch = (request, options) => { options.onRetry(err) } + log.http('fetch', `${req.method} ${req.url} attempt ${attemptNum} failed with ${err.code}`) return retryHandler(err) } }, options.retry).catch((err) => { diff --git a/package.json b/package.json index 859c201..017d23f 100644 --- a/package.json +++ b/package.json @@ -42,6 +42,7 @@ "minipass-flush": "^1.0.5", "minipass-pipeline": "^1.2.4", "negotiator": "^0.6.3", + "proc-log": "^4.2.0", "promise-retry": "^2.0.1", "ssri": "^10.0.0" }, diff --git a/test/cache.js b/test/cache.js index f4023da..c459e67 100644 --- a/test/cache.js +++ b/test/cache.js @@ -1548,7 +1548,7 @@ t.test('generic errors streaming from cache propagate to response body', async ( t.teardown(() => { cacache.get.stream.byDigest = realGet }) - cacache.get.stream.byDigest = (cachePath, integrity) => { + cacache.get.stream.byDigest = () => { const stream = new Readable({ read: () => {} }) setImmediate(() => { stream.emit('error', new Error('broken stream')) diff --git a/test/fetch.js b/test/fetch.js index 51b25e2..c50c952 100644 --- a/test/fetch.js +++ b/test/fetch.js @@ -74,6 +74,14 @@ t.test('500-level responses not thrown', async t => { t.test('calls opts.onRetry', async t => { t.test('when request is retriable', async (t) => { + const logs = [] + const logHandler = (...logparams) => { + logs.push(...logparams) + } + process.on('log', logHandler) + t.teardown(() => { + process.off('log', logHandler) + }) const srv = nock(HOST) .get('/test-onretry') .reply(500) @@ -95,10 +103,23 @@ t.test('calls opts.onRetry', async t => { t.same(res.headers.get('x-fetch-attempts'), '2', 'set the appropriate header') t.equal(calledOnRetry, true, 'should have called onRetry') t.equal(retryNotification, 1, 'should have called method once') + t.strictSame(logs, [ + 'http', + 'fetch', + 'GET https://make-fetch-happen.npm/test-onretry attempt 1 failed with 500', + ]) t.ok(srv.isDone()) }) t.test('when request is retriable; and caught', async (t) => { + const logs = [] + const logHandler = (...logparams) => { + logs.push(...logparams) + } + process.on('log', logHandler) + t.teardown(() => { + process.off('log', logHandler) + }) const srv = nock(HOST) .get('/catch-retry') .replyWithError({ @@ -128,6 +149,11 @@ t.test('calls opts.onRetry', async t => { t.equal(calledOnRetry, true, 'should have called onRetry') const buf = await res.buffer() t.same(buf, CONTENT, 'request succeeded') + t.strictSame(logs, [ + 'http', + 'fetch', + 'GET https://make-fetch-happen.npm/catch-retry attempt 1 failed with ECONNRESET', + ]) t.ok(srv.isDone()) }) @@ -356,7 +382,7 @@ t.test('supports passthrough of options on redirect', async (t) => { .get('/test') .matchHeader('x-test', 'test') .reply(200, CONTENT, { - 'test-header': (req, res, body) => { + 'test-header': (req) => { t.ok(req.headers['x-test'].length) t.equal(req.headers['x-test'][0], 'test', 'headers from redriect') return 'truthy' diff --git a/test/options.js b/test/options.js index 0434729..b81110d 100644 --- a/test/options.js +++ b/test/options.js @@ -1,12 +1,12 @@ 'use strict' const dns = require('dns') const configureOptions = require('../lib/options.js') -const { test } = require('tap') +const t = require('tap') const defaultDns = { ttl: 5 * 60 * 1000, lookup: dns.lookup } -test('configure options', async (t) => { - test('supplied with no value', async (t) => { +t.test('configure options', async (t) => { + t.test('supplied with no value', async (t) => { const opts = configureOptions() const expectedObject = { method: 'GET', @@ -19,7 +19,7 @@ test('configure options', async (t) => { t.same(opts, expectedObject, 'should return default opts') }) - test('supplied with empty object', async (t) => { + t.test('supplied with empty object', async (t) => { const opts = configureOptions({}) const expectedObject = { method: 'GET', @@ -32,7 +32,7 @@ test('configure options', async (t) => { t.same(opts, expectedObject, 'should return default opts') }) - test('changes method to upper case', async (t) => { + t.test('changes method to upper case', async (t) => { const actualOpts = { method: 'post' } const opts = configureOptions(actualOpts) const expectedObject = { @@ -46,7 +46,7 @@ test('configure options', async (t) => { t.same(opts, expectedObject, 'should return upper cased method') }) - test('copies strictSSL to rejectUnauthorized', async (t) => { + t.test('copies strictSSL to rejectUnauthorized', async (t) => { const trueOpts = configureOptions({ strictSSL: true }) const trueExpectedObject = { method: 'GET', @@ -82,7 +82,7 @@ test('configure options', async (t) => { 'should treat strictSSL: null as true just like tls.connect') }) - test('should set dns property correctly', async (t) => { + t.test('should set dns property correctly', async (t) => { t.test('no property given', async (t) => { const actualOpts = { method: 'GET' } const opts = configureOptions(actualOpts) @@ -127,7 +127,7 @@ test('configure options', async (t) => { }) }) - test('should set retry property correctly', async (t) => { + t.test('should set retry property correctly', async (t) => { t.test('no property given', async (t) => { const actualOpts = { method: 'GET' } const opts = configureOptions(actualOpts) @@ -199,7 +199,7 @@ test('configure options', async (t) => { }) }) - test('configures cache correctly', async (t) => { + t.test('configures cache correctly', async (t) => { t.test('supplied with no values', async (t) => { const actualOpts = {} const opts = configureOptions(actualOpts)