Sporadic issues with npm

Hi,

I am experiencing issues when using the NPM feed, where it sometimes cannot find official packages from NPM. Example:
"npm install gulp"

npm ERR! No compatible version found: gulp
npm ERR! No valid targets found.

The specific package is different every time I attempt a "npm install [package]". If I run the "npm install" command a 2-3 times, it works.

If I disable ProGet and go directly to the official NPM registry, everything works fine.

Product: ProGet
Version: 4.0.10

That's strange; npm makes a tremendous amount of requests (1000's of simultaneous), especially when doing gulp installs. There are a lot of bugs related to this in the npm client (though they are fixed/regress with different versions). ProGet does not have these bugs so far as we're aware.

Because ProGet returns requests in a different order and at a different speed (sometimes faster, sometimes slower), and you said ""The specific package is different every time", I think its' related to npm client timing bugs.

The easiest way to diagnose this is to attach fidler or wireshark, and try to identify that pattern that's causing this.

I can sort of reproduce this without npm for our proget (I'm a coworker of Håkon, the orig. author).
I looked at the log npm creates and I can see that at some random point it fails getting a random feed.
Example from npm_debug.log

522 verbose get saving undefined to C:\Users\tn\AppData\Roaming\npm-cache\proget.hesehus.dk\npm\npm\gulp-cssnano.cache.json

That "undefined" is because proget doesn't returns the package data but instead the following:

{"time":{},"versions":{},"dist-tags":{}}

(Which is written to .cache.json)

Retrying the package will return the correct result.

For an outsider it looks like the Proget cache needs to be verified and with lots of request to the same package concurrently it returns "an empty" result.

I have written a LinqPad script to test this without npm and the below fails some times. throwing the error "throw new Exception("Empty result from Proget");"

Right now it is running fine - but it failed twice for me 10 min. ago, so I suspect the caches are warm now and that it will, if I'm correct, fail again tomorrow morning. I don't know how our Proget is setup, cache handling etc., but it doesn't look like a npm client problem to me at least.

`void Main()
{
const string BaseUrl = "https://<url_to_proget>/npm/npm";

int count = 0;
while (true)
{
    var tasks = new List<Task>();
    for (int i = 0; i < 4; ++i)
    {
        tasks.Add(Task.Run(() => Fetch(BaseUrl + "/gulp-cssnano", 10306)));
        ++count;
        tasks.Add(Task.Run(() => Fetch(BaseUrl + "/wiredep", 74494)));
        ++count;
        tasks.Add(Task.Run(() => Fetch(BaseUrl + "/gulp-babel", 18199)));
        ++count;
        tasks.Add(Task.Run(() => Fetch(BaseUrl + "/gulp-sourcemaps", 50822)));
        ++count;
        tasks.Add(Task.Run(() => Fetch(BaseUrl + "/run-sequence", 19978)));
        ++count;
        tasks.Add(Task.Run(() => Fetch(BaseUrl + "/require-all", 11591)));
        ++count;
        tasks.Add(Task.Run(() => Fetch(BaseUrl + "/babel-register", 19993)));
        ++count;
        tasks.Add(Task.Run(() => Fetch(BaseUrl + "/gulp-babel", 18199)));
        ++count;
        tasks.Add(Task.Run(() => Fetch(BaseUrl + "/gulp-uglify", 33667)));
        ++count;
    }
    
    var tasks2 = tasks.ToArray();
    Task.WaitAll(tasks2);
    Console.WriteLine("Loop done - " + count.ToString());
}

}

void Fetch(string url, int size)
{
try
{
var client = new HttpClient();
var result = client.GetAsync(url).Result;

    if (!result.IsSuccessStatusCode)
    {
        throw new Exception("StatusCode: " + result.StatusCode);
    }
    else
    {
        var content = result.Content.ReadAsStringAsync().Result;
        
        if (content == @"{""time"":{},""versions"":{},""dist-tags"":{}}")
        {
            throw new Exception("Empty result from Proget");
        }

// if (content.Length != size)
// {
// throw new Exception("content.Length != " + size);
// }
}

    result.Dispose();
    client.Dispose();
}
catch(Exception ex)
{
    throw;
}

}`

I tested this a few times today and I can pretty reliably make it fail by just doing (changed script from last post):

    [...]
    for (int i = 0; i < 32; ++i)
    {
        tasks.Add(Task.Run(() => Fetch(BaseUrl + "/ecstatic", 0)));
    }
    [...]

First time it will fail and work for subsequent runs - if I wait a few hours and try again, the script will fail again on the first run with lots of concurrent requests.

Thanks for the detailed reproduction information; I did a quick test in the lab, but it didn't fail (we also haven't had other reports of this)-- so that means we're going to have to investigate it a bit further on our end.

Unfortunately this might be a bit difficult to work, but we're definitely be looking into it more, especially as we look towards the next ProGet release (npm scoped packages).

Thanks for looking into it.

A quick note, it looks like it works on the first time I request a new resource, but after it has been cached the first time, it fails "randomly" after that. (Ie. if I wait a few hours without any requests, the first request after that will fail.)

Let us know if the is anything we can try on our side to help getting to the bottom of this!

We still haven't been able to reproduce this behavior, but I think just having ProGet return an HTTP error code instead of an empty package list will probably solve this, since npm shouldn't cache an error response. And I believe npm retries a few times by default in this case.

We've logged this as:

PG-550 - FIX: npm package metadata requests should return 404 instead of empty package list if package was not found

It will be included in ProGet 4.0.11, which should be available either today or tomorrow.

Thanks for all your help looking into this!

We have been running the update since it has been out and it does look like it has fixed our issues with random failing npm restores.

Running my LinqPad test script now (which makes 32 concurrent requests for the same resource), still makes it "fail", but now with a 404 as you described, instead of returning an empty package. (Which is still quite weird behavior IMO...)

Thanks for the quick response and help on solving this!