[BUG] cache and registry in combination makes fetch unstable

[pgsandstrom]

What / Why

Whenever I have a cache and registry specified in the conf-object, some fetches fail. Its not 100%, but somewhere around 50% of the fetches fail. It only happens if I have both a cache and a registry. I have removed all other configurations.

How

My conf object:
{cache: '/tmp/new-cache', registry: 'my-company-internal-registry'}

My usage of npm-registry-fetch:
const json = (await npmRegistryFetch.json(dependencyName, conf))

Current Behavior

Sometimes I receive this response:
{"code":"FETCH_ERROR","errno":"FETCH_ERROR","type":"invalid-json"}

It never happens unless both registry and cache has been specified. In my testing I have done thousands of fetches and it is very reliable.

I'd be happy to supply more information if needed, or perform testing if it can help.

[isaacs]

That's really weird that specifying both would cause troubles, because the registry gets a default value anyway.

What's my-company-internal-registry? Maybe it's doing something unique that's messing with the cache in a way that the public registry doesn't?

[pgsandstrom]

Its a Nexus repository (https://www.sonatype.com/product-nexus-repository). The configuration of it seems to be quite standard. This is at a largish company and no one has detected anything weird with it. But as you mentioned the default repository, I did more testing.

This does produce errors:
conf = { cache: '/tmp/extra-new-cache', registry: 'my-company-internal-registry' }

But this does not produce errors:
conf = { cache: '/tmp/extra-new-cache', registry: 'https://registry.npmjs.org' }

So the registry is the source of the issue. But it still seems really strange that it bugs out so completely in this scenario, but works well otherwise. I mean, my npm cache seems to be working perfectly when using the npm client in my work. But I dont know enough about the npm cache to say in what way the registry could be buggy. Is there a sensible way to debug this?

[isaacs]

Can you please update your test to show the raw output?

Ie, instead of this:

const json = (await npmRegistryFetch.json(dependencyName, conf))

Do this:

const response = await npmRegistryFetch(dependencyName, conf)
const body = await response.text()
let json
try {
  json = JSON.parse(body)
} catch (er) {
  console.error('JSON failed', response.status, response.headers, body)
  throw er
}

And then share the output.

[pgsandstrom]

response.headers was an object and the body was too large to be logged to console. So the exact code I ran was like this:

console.error(
  'JSON failed',
  response.status,
  JSON.stringify(response.headers),
  body.substr(0, 1000),
)

All the responses I got was similar to this:

JSON failed 200 {} io.com","bugs":{"url":"https://github.com/Microsoft/vsce/issues"},"keywords":["vscode","vsce","extension"],"contributors":[{"name":"Microsoft Corporation"}],"author":{"name":"Microsoft Corporation"},"license":"MIT","main":"out/main.js","bin":{"vsce":"out/vsce"},"scripts":{"test":"mocha","prepublish":"gulp compile && mocha"},"engines":{"node":">= 0.12"},"dependencies":{"commander":"^2.8.1","denodeify":"^1.2.1","glob":"^5.0.14","lodash":"^3.10.1","mime":"^1.3.4","minimatch":"^2.0.10","osenv":"^0.1.3","read":"^1.0.7","tmp":"0.0.27","url-join":"0.0.1","vso-node-api":"^0.5.0","yazl":"^2.2.2"},"devDependencies":{"event-stream":"^3.3.1","gulp":"^3.9.0","gulp-filter":"^3.0.1","gulp-tsb":"^1.6.0","mocha":"^2.3.3","rimraf":"^2.4.3","source-map-support":"^0.3.2","xml2js":"^0.4.12"},"gitHead":"1af60269feede8d74fcd52fde591c9754781ec22","_id":"vsce@0.7.1","_shasum":"d2d430805a46e7693e0cd824a535e883920ab31d","_from":".","_npmVersion":"3.3.10","_nodeVersion":"0.12.7","_npmUser":{"name":"joaomoreno.ms"

It's really strange, it is as if they are cut of in the beginning. I guess that explains why the json cant be parsed.

I wrote some responses to file and inspected them, they all looked like this. Here is a pastebin of an entire response: https://pastebin.com/E7456cXz

[isaacs]

Ah, can you run it again, but don't JSON.stringify() the response.headers. Fetch headers is a Map object, so it'll JSON.stringify as just an empty object, but the headers might give us some indication if maybe we're incorrectly handling a chunked encoding or some other thing.

[isaacs]

Cutting down the body is fine. And yeah, it's definitely being cut off for some reason.

[pgsandstrom]

Maybe I'm missing something, but if I leave the headers as is then only [object Headers] is printed. However, I did manage to stringify it with an ugly hax. This is what I got:

{"cache-control":"public, max-age=300","cf-cache-status":"REVALIDATED","cf-ray":"5781460dbe9dd13b-GOT","connection":"keep-alive","content-encoding":"gzip","content-type":"application/json","date":"Sun, 22 Mar 2020 16:26:19 GMT","etag":"W/\"f217f19f947ba9ddec66a105b8085819\"","expect-ct":"max-age=604800, report-uri=\"https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct\"","last-modified":"Mon, 04 Feb 2019 10:34:16 GMT","server":"cloudflare","set-cookie":"__cfduid=<redacted>; expires=Tue, 21-Apr-20 16:26:19 GMT; path=/; domain=.npmjs.org; HttpOnly; SameSite=Lax","transfer-encoding":"chunked","vary":"accept-encoding, accept","x-fetch-attempts":"1"}

[isaacs]

Update on this! I was able to finally track down a way to reproduce this issue, and track it down to this bit of code in make-fetch-happen's cache.js, where we tee into the cache write stream if the response doesn't fit in memory:

      const tee = new Minipass()
      const cacheStream = cacache.put.stream(
        cachePath,
        ckey,
        cacheOpts
      )
      // XXX problem is right here:
      // if the cacheStream is slow, and there is more than one chunk
      // queued for consumption, then the first chunk is lost.  witaf?
      tee.pipe(cacheStream)
      // this works fine, though:
      // tee.on('data', d => cacheStream.write(d))
      // tee.on('end', () => cacheStream.end())
      // this fails in the same way (ie, not a cacache issue, just a minipass tee issue)
      // const cacheStream = new Minipass()
      // setTimeout(() => cacheStream.resume())
      cacheStream.promise().then(cacheWriteResolve, cacheWriteReject)
      newBody.unshift(tee)

I think this might be a bug in how Minipass handles multiple pipe destinations, so I'm going to dig into that. If so, it's a bug lurking for later anyway. If I can prove that minipass is behaving properly, then it means it's somewhere further up the stack, maybe in minipass-pipeline or minipass-flush (though those modules are super simple and just rely on the Minipass semantics, so I'm skeptical that they're to blame here).

[isaacs]

For posterity: the repro case is, in the npm v7 branch that uses arborist, doing npm i tap@14 --before=2020-01-01 with an empty cache, so that it has to fetch a large number of full-metadata packuments and cache them all. The fs streams get backed up, and the responses are large, so it hits this code path where the tee target is slower than the incoming or "main" pipeline of data.

Going to try to reduce it down to just a set of minipass streams in a synthetic environment today or tomorrow. In the meantime, I can float the "no backpressure pipe" patch on make-fetch-happen, since it's really not too much of a hazard to let the cache writes queue up in memory a bit anyway.

[isaacs]

Oh, wild! It's not just dropping the first chunk, it's getting the full data, but out of order!

 FAIL  test/cache.js
 ✖ should have same body

  --- expected
  +++ actual
  @@ -1,1 +1,1 @@
  -"hello, world!"
  +"ld!hello, wor"

  test: "test/cache.js put method stream (not in memory): caches correctly"

[isaacs]

Ok, update this to npm-registry-fetch 8.0.2, and it should not hit the problem any more. I'm leaving this issue open though, as the root cause still has to be determined and fixed properly either in cacache, minipass-pipeline, or minipass.