fix: log tarball retrieval from cache (#403)

If tarballs are cached, the npm install log contains no information on
where it got the tarball from. This helps troubleshoot issues with
caching and `preferOnline/preferOffline`, for example.

---------

Co-authored-by: Gar <wraithgar@github.com>

lib/fetcher.js

@@ -188,7 +188,15 @@ class FetcherBase {
   // private
   // Note: cacache will raise a EINTEGRITY error if the integrity doesn't match
   #tarballFromCache () {
-    return cacache.get.stream.byDigest(this.cache, this.integrity, this.opts)
+    const startTime = Date.now()
+    const stream = cacache.get.stream.byDigest(this.cache, this.integrity, this.opts)
+    const elapsedTime = Date.now() - startTime
+    // cache is good, so log it as a hit in particular since there was no fetch logged
+    log.http(
+      'cache',
+      `${this.spec} ${elapsedTime}ms (cache hit)`
+    )
+    return stream
   }
 
   get [_.cacheFetches] () {

test/fetcher.js

@@ -207,6 +207,10 @@ t.test('extract', t => {
       }).extract(target + '/badcache')
         .then(({ resolved, integrity }) => {
           t.match(logs, [
+            ['http',
+              'cache',
+              /file:test\/fixtures\/abbrev-1.1.1.tgz.*(cache hit)/,
+            ],
             ['warn', 'tar', 'zlib: incorrect header check'],
             [
               'silly',
@@ -298,7 +302,11 @@ t.test('extract', t => {
             algorithm: 'sha512',
             sri: Object,
           }, 'got expected error')
-          t.same(logs, [
+          t.match(logs, [
+            ['http',
+              'cache',
+              /file:test\/fixtures\/abbrev-1.1.1.tgz.*(cache hit)/,
+            ],
             [
               'silly',
               'tarball',