Error with Artifactory

[kbirger]

Now that you have added the paging toggle, after disabling that on my settings, I get the following error pop up when using the extension:

Unexpected RIGHT_BRACE("}") in state VALUE

I have sniffed the response that the call makes:
Request: /artifactory/api
/npm/npm-local/-/v1/search?text=vscode&size=20&from=0&quality=0.65&popularity=0.98&maintenance=0
.5

{"objects":[{"package":{"name":"mypackage-vscode","description":"...","maintainers":[],"version":"0.1.0","date":null,"keywords":[],"author":null}}]}

While the error seems to suggest malformed JSON, the above seems to be valid.

[joelspadin-garmin]

It looks like this error is coming from jsonparse, which is used by minipass-json-stream, which is used by npm-registry-fetch. I'm not sure what could be causing the error, as passing in that text into jsonparse gives me valid output.

You may need to try building and debugging the extension yourself to get some more context for the error. If you break on uncaught exceptions and promise rejects like so...

...then the debugger should pause when it hits that error, and hopefully we can see what input it's failing on.

[kbirger]

Trying to build right now, but I'm getting a node_gyp error. Not sure what the cause is yet,but will keep digging....

npm ci

fsevents@1.2.12 install C:\Users\kbirger\Documents\git\vscode-private-extension-manager\extension\node_modules\watchpack\node_modules\fsevents
node-gyp rebuild

C:\Users\kbirger\Documents\git\vscode-private-extension-manager\extension\node_modules\watchpack\node_modules\fsevents>if not defined npm_config_node_gyp (node "C:\Users\kbirger\AppData\Roaming\nvm\v12.14.0\node_modules\npm\node_modules\npm-lifecycle\node-gyp-bin\....\node_modules\node-gyp\bin\node-gyp.js" rebuild ) else (node "C:\Users\kbirger\AppData\Roaming\nvm\v12.14.0\node_modules\npm\node_modules\node-gyp\bin\node-gyp.js" rebuild )
Traceback (most recent call last):
File "C:\Users\kbirger\AppData\Roaming\nvm\v12.14.0\node_modules\npm\node_modules\node-gyp\gyp\gyp_main.py", line 50, in
sys.exit(gyp.script_main())
File "C:\Users\kbirger\AppData\Roaming\nvm\v12.14.0\node_modules\npm\node_modules\node-gyp\gyp\pylib\gyp_init_.py", line 554, in script_main
return main(sys.argv[1:])
File "C:\Users\kbirger\AppData\Roaming\nvm\v12.14.0\node_modules\npm\node_modules\node-gyp\gyp\pylib\gyp_init_.py", line 547, in main
return gyp_main(args)
File "C:\Users\kbirger\AppData\Roaming\nvm\v12.14.0\node_modules\npm\node_modules\node-gyp\gyp\pylib\gyp_init_.py", line 532, in gyp_main
generator.GenerateOutput(flat_list, targets, data, params)
File "C:\Users\kbirger\AppData\Roaming\nvm\v12.14.0\node_modules\npm\node_modules\node-gyp\gyp\pylib\gyp\generator\msvs.py", line 2033, in GenerateOutput
root_entries = _GatherSolutionFolders(
File "C:\Users\kbirger\AppData\Roaming\nvm\v12.14.0\node_modules\npm\node_modules\node-gyp\gyp\pylib\gyp\generator\msvs.py", line 1791, in _GatherSolutionFolders
return _DictsToFolders('', root, flat)
File "C:\Users\kbirger\AppData\Roaming\nvm\v12.14.0\node_modules\npm\node_modules\node-gyp\gyp\pylib\gyp\generator\msvs.py", line 1744, in _DictsToFolders
for folder, contents in bucket.items():
AttributeError: 'MSVSProject' object has no attribute 'items'
gyp ERR! configure error
gyp ERR! stack Error: gyp failed with exit code: 1
gyp ERR! stack at ChildProcess.onCpExit (C:\Users\kbirger\AppData\Roaming\nvm\v12.14.0\node_modules\npm\node_modules\node-gyp\lib\configure.js
:351:16)
gyp ERR! stack at ChildProcess.emit (events.js:210:5)
gyp ERR! stack at Process.ChildProcess._handle.onexit (internal/child_process.js:272:12)
gyp ERR! System Windows_NT 10.0.18363
gyp ERR! command "C:\Program Files\nodejs\node.exe" "C:\Users\kbirger\AppData\Roaming\nvm\v12.14.0\node_modules\npm\node_modules\nodenode
-gyp\bin\node-gyp.js" "rebuild"
gyp ERR! cwd C:\Users\kbirger\Documents\git\vscode-private-extension-manager\extension\node_modules\watchpack\node_modules\fsevents
gyp ERR! node -v v12.14.0
gyp ERR! node-gyp -v v5.0.5
gyp ERR! not ok
added 804 packages in 37.63s

It seems like this package has dependencies on some Visual Studio components. I have installed the C++ dev package, and I've got the latest VS 2019 update installed. I'm on Python 3.8 (where regards node-gyp).
node version is 12.14 as evidenced from the log above

[joelspadin-garmin]

Try deleting node_modules and using npm install instead of npm ci. I've seen weird issues like that before where NPM thinks it needs to install fsevents even though that's an optional dependency which I think is only for OSX.

[kbirger]

Yeah, I managed to get it working with npm install. The error is mysterious though. It seems to throw the error after the very end of parsing the string. I also noticed that for some reason the fetch http call gets called two times, followed by a call to the info for the specific package (the only one I have matching the query in place). Not really sure what to make of all of it because the JSON is valid.

[joelspadin-garmin]

It's possible the search request is happening twice because I was lazy and didn't have the tree view and auto update check share a source of data. I figured the caching the NPM libraries do would prevent that, but it probably only applies to package info and not to the search calls.

Do you know exactly which request it was trying to parse when it failed? If Private Extension Manager makes a call for the info for a specific package, then that seems to indicate that it succeeded in parsing the result of the search call since it needs that to know which packages exist.

I did upgrade npm-registry-fetch to the latest version, and it looks like it switched which JSON parsing library it's using to minipass-json-stream, but the source for that library no longer seems to exist? I'm not entirely sure what happened there.

[kbirger]

The exception is thrown from jsonparse:

proto.parseError = function (token, value) {
  this.tState = STOP;
  this.onError(new Error("Unexpected " + Parser.toknam(token) + (value ? ("(" + JSON.stringify(value) + ")") : "") + " in state " + Parser.toknam(this.state)));
};

I can catch it in Registry.ts:

await npmsearch(query, {
          ...this.options,
          from,
        });

Which tells me that the error does come from that search call, unless I'm wrong.

Incidentally, tried to roll back the version of npm-registry-fetch, but the version of jsonparse stays the same I think.

[joelspadin-garmin]

Hmm. Since it's running the npmsearch() call twice, is one succeeding and the other failing, or do both fail?

[kbirger]

Here are my observations. Upon initial load, I see 3 calls to the search. All three fail. Subsequently, when I press the refresh button at the top of the panel, two calls are made. Only the second one fails here.

The second call for me is:

getChildren => getRootChildren => getRecommendedExtensions => getUniquePackages => getPackages => findMatchingPackages

[joelspadin-garmin]

Okay. I think those search calls on first load are:

1. Main extensions view
2. Recommended extensions view
3. Auto update check

And then on refresh just 1-2 get run again. The one that succeeds the second time is for the recommended extensions view. I cannot explain why this would fail the first time but succeed the second.

You mentioned you tried backdating npm-registry-fetch, but I don't think that would actually affect those checks because those are run through libnpmsearch, which still depends on the newer version of npm-registry-fetch. Can you try backdating both npm-registry-fetch and libnpmsearch?

One more idea that doesn't seem very likely to me but is worth trying: try commenting out everything inside

vscode-private-extension-manager/extension/src/extension.ts

Line 90 in eef3d4c

async function verifyCache() {

to stop the extension from cleaning up its cache when it starts. The fact that you're seeing this issue at startup but then it works some time later makes me think it might be caused by something else that only happens at startup.

[kbirger]

Backdating the two libraries seems to have corrected the issue.

[joelspadin-garmin]

It sounds like this is an issue with the latest version of npm-registry-fetch. We'd need to provide the maintainers of that project with a way to reproduce the issue though. "I found an issue that only happens with my private server you can't access" is probably not too helpful.

It looks like Artifactory does have a free version, so if you can provide steps for setting up Artifactory and code to query it that works in an older version of npm-registry-fetch but not the current version, then we can report this to npm-registry-fetch.

You could try using the Node REPL (just run node with no arguments) to find a minimal code example that causes the issue, like:

const search = require('libnpmsearch');
search('*', { registry: 'https://localhost:1234' });

I would also be interested to know if the issue still happens with the latest versions of libnpmsearch and npm-registry-fetch but with verifyCache() commented out, just to rule out some weird interaction between the cache cleaning code and the newer versions of the libraries.

[joelspadin-garmin]

Possibly related? npm/npm-registry-fetch#23

[kbirger]

Commenting verifyCache doesn't seem to make a difference. I tried your suggestion in terms of making a minimal reproduction by setting up a wiremock to handle the relevant endpoint and to reply with the exact json I received. Unfortunately, it seems to work perfectly :).

Not sure if that issue is related, because the main characteristic of this seems to be a parsing error from the library. I didn't have a chance to look at it in depth, but it seems like a slightly different error.

There is one other thing that has been bothering me. When I look in fiddler, the result looks like this:

HTTP/1.1 200 OK
Server: Artifactory/6.10.3
X-Artifactory-Id: ae576ca938320186:1deb3309:16c8cc9321d:-8000
Content-Type: application/json
Transfer-Encoding: chunked
Date: Fri, 03 Apr 2020 20:50:15 GMT

c7
{"objects":[{"package":{"name":"mypackage-vscode","description":"...","maintainers":[],"version":"0.1.0","date":null,"keywords":[],"author":null}
3
}]}
0

I'm not sure what those numbered characters are. I mostly think they are an artifact of how Fiddler renders responses, and indeed when stepping through the parser, I didn't see any tokens that I didn't expect. Also, when I run the request through curl, I see nothing odd about the response, but then again I didn't correct for headers.

[joelspadin-garmin]

I'm not familiar with how chunked transfer encoding works, but "3" followed by 3 characters and "0" at the end seems to indicate those are the sizes of the following chunks. Maybe the code that receives the response isn't properly putting the chunks back together and garbage data is getting fed into the JSON parser?

[kbirger]

I was thinking something along those lines, but I don't see how that would work if all the tokens seem correct. I was debugging with breakpoints however, so maybe I missed something.

Tomorrow I will try to comment out one of the calls and see if I can spot anything else.

Incidentally, what application do you use for your private registry?

[joelspadin-garmin]

I believe we're using Sonatype Nexus. Someone else manages that though, so I don't know a whole lot about how we've set it up.

[kbirger]

I've noticed that if I return an empty array from getUniquePackages() instead of doing work that after the initial attempt to load the extensions (there's only one call now) which still fails, the remaining calls to findMatchingPackages() generally succeed - I would say over 80% of the time.

Regarding that issue you posted: npm/npm-registry-fetch#23

npm-registry-fetch is only used to get the details about specific packages. The happens when doing the search. In other words, the code discussed in this issue is never triggered during the error scenario.

[joelspadin]

Another idea that might help track this down: If you run the request in fiddler multiple times, does it always get chunked the same way? If you do 2-3 of the same request back to back quickly does it change?

I wonder if something about the encoding or chunking is changing and only sometimes cause the problem. For example, if a multi-byte Unicode character got split across two chunks and it wasn't recombined properly, that could confuse the parser.

[joelspadin-garmin]

Whoops. Was signed into the wrong account. The above comment is also me.

[kbirger]

That was a great thought, unfortunately today I tried what you suggested and it didn't reveal anything interesting.
I had to try 6 requests in order to get one that worked, and all 6 had the same positioning of the chunks.

Was there any objective gain in updating the version of the library? Could we perhaps revert to the stable version while they investigate the issue as it seems they are doing? (Assuming this is the same issue as you linked above). I do believe in helping folks get their packages stable (as we are doing here), but it seems like a dead end so far :(

[joelspadin-garmin]

I remember NPM saying there were some potential security vulnerabilities so I updated everything, but I didn't check whether any of those were related to npm-registry-fetch. I'll try backdating and see if any warnings come back.

[joelspadin-garmin]

No vulnerabilities in the old versions. I still need to test that everything still works though.

[joelspadin-garmin]

@kbirger 4a590aa reverts to the older versions of NPM libraries. Could you test if that works for you?

[kbirger]

@joelspadin-garmin It seems to be working just fine for me from source on that commit. You haven't released this new version to the marketplace, right? (I still see 1.1.0 as latest there).

Thank you!

[joelspadin-garmin]

Not yet, but I will do it soon. I want to see if I can quickly make use of the new welcome views API added in the latest release first.

[kbirger]

Thanks for the info. Do you have any idea of when you think you'll have the new build available?

[joelspadin-garmin]

I just published it. It should show up as an update in a few minutes.

[kbirger]

Awesome, thank you! I just got the update, and it worked right away from the first try!

[joelspadin-garmin]

Great! I'll start watching npm-registry-fetch to see if they fix any JSON parsing issues.

[joelspadin-garmin]

Also, I forgot to respond to this part:

Regarding that issue you posted: npm/npm-registry-fetch#23

npm-registry-fetch is only used to get the details about specific packages. The happens when doing the search. In other words, the code discussed in this issue is never triggered during the error scenario.

Searches use libnpmsearch, which uses npm-registry-fetch (https://github.com/npm/libnpmsearch/blob/latest/index.js#L47), so everything does end up going through npm-registry-fetch.

[joelspadin]

It looks like npm/make-fetch-happen@7f896be might fix the issue with invalid JSON.

[kbirger]

That's great! Give me a shout if you want me to test another build at some point.

Edit: yeah, sounds like the issue I was seeing. Impressive they found it, and amusing that it baffled them a bit too :)

[joelspadin-garmin]

@kbirger I had some free time to update things. Here's a new build if you'd like to test it. https://github.com/joelspadin-garmin/vscode-private-extension-manager/releases/tag/v1.3.0-beta.0

[kbirger]

Thank you @joelspadin-garmin - It seems to work without a problem! I know it says you have only updated the fetch, but I ran it through the end-to-end lifecycle anyway to make sure I can report anything that comes up. I did as below (for records):

• Uninstalled current version
• Installed the beta version through the menu item by pointing to the vsix file
• Reloaded
• Verified that my private repo extension shows up
• Uninstalled the extension
• Reloaded
• Verified that my extension shows up in search results
• Installed it
• Reloaded
• Verified extension functionality to make sure install was right.

Thanks again!

[joelspadin-garmin]

Great! I'll include that in the next version then, (whenever I get time to add something to justify a new version).