Log retries

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)