Log retries (#294)

Three commits:
- **deps: add [email protected]**
- **fix: log errors on retry**
- **chore: fix linting in test files**

Closes npm/cli#7371

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) => {

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"
  },

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'))

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'

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)