fix: log tarball retrieval from cache

[mbtools]

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.

[wraithgar]

npm currently signals where the http request ended up coming from.

$ npm view npm --loglevel http
npm http fetch GET 200 https://registry.npmjs.org/npm 284ms (cache revalidated)

~/D/s/install $ npm i abbrev --loglevel http
npm http fetch GET 200 https://registry.npmjs.org/abbrev 216ms (cache revalidated)
npm http fetch GET 200 https://registry.npmjs.org/abbrev/-/abbrev-3.0.0.tgz 123ms (cache miss)

It does seem like it does not log the tgz requests if there is a cache hit. This is a bug. Adding a discrete logging statement here is not the fix, however.

~/D/s/install $ npm i abbrev --loglevel http
npm http fetch GET 200 https://registry.npmjs.org/abbrev 17ms (cache hit)
npm http fetch GET 200 https://registry.npmjs.org/semver 159ms (cache revalidated)
npm http fetch GET 200 https://registry.npmjs.org/typescript 201ms (cache updated)
npm http fetch GET 200 https://registry.npmjs.org/typescript/-/typescript-5.6.3.tgz 413ms (cache miss)

[wraithgar]

Ohh I see what's going on. We're bypassing the caching being done in our fetch library and doing it directly. This logging statement may be the right place then. I wonder if this is "technically" an http level logging, since that's typically the log level folks set when debugging http/caching issues.

Also, as much as I usually try to avoid "bike shedding" I think the output of this should maybe be closer to that of the http/fetch log lines.

[mbtools]

Yes, something http entry for tarball cache hits is missing.

npm http fetch GET 200 https://registry.npmjs.org/typescript/-/typescript-5.6.3.tgz 413ms (cache hit)

In general, the mix of HTTP and local caching details in one log entry is confusing. If the cache is involved, no HTTP GET requests are sent (an HTTP cache hit would typically result in a 304).

It might be better to separate cache from fetch in the log:

npm http cache hit https://registry.npmjs.org/abbrev 
npm http fetch GET 200 https://registry.npmjs.org/semver (cache revalidated)
npm http fetch GET 200 https://registry.npmjs.org/typescript (cache updated)
npm http cache hit https://registry.npmjs.org/abbrev/-/abbrev-3.0.0.tgz 
npm http fetch GET 200 https://registry.npmjs.org/typescript/-/typescript-5.6.3.tgz 413ms (cache miss)

[wraithgar]

In general, the mix of HTTP and local caching details in one log entry is confusing.

100%

It might be better to separate cache from fetch in the log:

This is a great suggestion.

[mbtools]

i will give it a try

[mbtools]

Part 2 is here npm/npm-registry-fetch#273

The pacote tests don't run on my Windows machine so I'm not sure if any tests need to be adjusted.

It should look like this:

npm http cache https://registry.npmjs.org/abbrev 111ms (cache hit)
npm http fetch GET 200 https://registry.npmjs.org/semver 111ms (cache revalidated)
npm http fetch GET 200 https://registry.npmjs.org/typescript 111ms (cache updated)
npm http cache https://registry.npmjs.org/abbrev/-/abbrev-3.0.0.tgz 111ms  (cache hit)
npm http fetch GET 200 https://registry.npmjs.org/typescript/-/typescript-5.6.3.tgz 111ms (cache miss)

[wraithgar]

This will get tests passing. Not sure why they're not running in CI right now.

/D/n/p/b/pr (tarball_cache_log|✚1) $ git diff
diff --git a/test/fetcher.js b/test/fetcher.js
index 8b2adb3..765266b 100644
--- a/test/fetcher.js
+++ b/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',

[wraithgar]

@mbtools if you apply that patch I can land this PR. If you can't get to it soon I'll make a new PR and get another npm cli team member to approve it so I can land it.

[mbtools]

I was traveling on Canadian Thanksgiving. Changed it