Cli: [BUG] npx fails to run some commands

[jsg2021]

Some background:
I'm trying to update a workflow where I had npx @scope/thing and it would happilly download the package and run it. I've added --yes to the workflow and many times this was enough. Some cases thing pre-existed and I needed to ignore the local version. So we added --ignore-existing in npm6. For that case... all of these are on a private registry.

Current Behavior:

With npm7's exec/npx, several packages are failing to run. Here is some log output...

Log npx --loglevel silly --yes -p @nti/clone -c 'clone'

npm verb cli [
npm verb cli   '/home/jonathan/.nvm/versions/node/v14.13.1/bin/node',
npm verb cli   '/home/jonathan/.nvm/versions/node/v14.13.1/lib/node_modules/npm/bin/npm-cli.js',
npm verb cli   'exec',
npm verb cli   '--loglevel',
npm verb cli   'silly',
npm verb cli   '--yes',
npm verb cli   '--package',
npm verb cli   '@nti/clone',
npm verb cli   '--call',
npm verb cli   'clone'
npm verb cli ]
npm info using [email protected]
npm info using [email protected]
npm timing config:load:defaults Completed in 1ms
npm timing config:load:file:/home/jonathan/.nvm/versions/node/v14.13.1/lib/node_modules/npm/npmrc Completed in 0ms
npm timing config:load:builtin Completed in 0ms
npm timing config:load:cli Completed in 1ms
npm timing config:load:env Completed in 1ms
npm timing config:load:project Completed in 0ms
npm timing config:load:file:/home/jonathan/.npmrc Completed in 1ms
npm timing config:load:user Completed in 1ms
npm timing config:load:file:/home/jonathan/.nvm/versions/node/v14.13.1/etc/npmrc Completed in 0ms
npm timing config:load:global Completed in 0ms
npm timing config:load:cafile Completed in 1ms
npm timing config:load:validate Completed in 0ms
npm timing config:load:setUserAgent Completed in 0ms
npm timing config:load:setEnvs Completed in 0ms
npm timing config:load Completed in 5ms
npm verb npm-session abf40e25096b1a17
npm timing npm:load Completed in 12ms
npm http fetch GET 200 https://npm.nextthought.com/@nti%2fclone 452ms
npm timing arborist:ctor Completed in 1ms
npm timing arborist:ctor Completed in 0ms
sh: clone: command not found
npm timing command:exec Completed in 514ms
npm verb stack Error: command failed
npm verb stack     at ChildProcess.<anonymous> (/home/jonathan/.nvm/versions/node/v14.13.1/lib/node_modules/npm/node_modules/@npmcli/promise-spawn/index.js:63:27)
npm verb stack     at ChildProcess.emit (events.js:314:20)
npm verb stack     at maybeClose (internal/child_process.js:1047:16)
npm verb stack     at Process.ChildProcess._handle.onexit (internal/child_process.js:287:5)
npm verb cwd /home/jonathan
npm verb Linux 5.8.14-200.fc32.x86_64
npm verb argv "/home/jonathan/.nvm/versions/node/v14.13.1/bin/node" "/home/jonathan/.nvm/versions/node/v14.13.1/lib/node_modules/npm/bin/npm-cli.js" "exec" "--loglevel" "silly" "--yes" "--package" "@nti/clone" "--call" "clone"
npm verb node v14.13.1
npm verb npm  v7.0.0
npm ERR! code 127
npm ERR! path /home/jonathan
npm ERR! command failed
npm ERR! command sh -c clone
npm verb exit 127
npm timing npm Completed in 634ms

Log npx --loglevel silly --yes -p @nti/clone@latest -c 'clone'

npm verb cli [
npm verb cli   '/home/jonathan/.nvm/versions/node/v14.13.1/bin/node',
npm verb cli   '/home/jonathan/.nvm/versions/node/v14.13.1/lib/node_modules/npm/bin/npm-cli.js',
npm verb cli   'exec',
npm verb cli   '--loglevel',
npm verb cli   'silly',
npm verb cli   '--yes',
npm verb cli   '--package',
npm verb cli   '@nti/clone@latest',
npm verb cli   '--call',
npm verb cli   'clone'
npm verb cli ]
npm info using [email protected]
npm info using [email protected]
npm timing config:load:defaults Completed in 1ms
npm timing config:load:file:/home/jonathan/.nvm/versions/node/v14.13.1/lib/node_modules/npm/npmrc Completed in 1ms
npm timing config:load:builtin Completed in 1ms
npm timing config:load:cli Completed in 1ms
npm timing config:load:env Completed in 0ms
npm timing config:load:project Completed in 1ms
npm timing config:load:file:/home/jonathan/.npmrc Completed in 0ms
npm timing config:load:user Completed in 0ms
npm timing config:load:file:/home/jonathan/.nvm/versions/node/v14.13.1/etc/npmrc Completed in 0ms
npm timing config:load:global Completed in 0ms
npm timing config:load:cafile Completed in 0ms
npm timing config:load:validate Completed in 0ms
npm timing config:load:setUserAgent Completed in 1ms
npm timing config:load:setEnvs Completed in 0ms
npm timing config:load Completed in 5ms
npm verb npm-session 291a9cc0edb721dd
npm timing npm:load Completed in 11ms
npm http fetch GET 200 https://npm.nextthought.com/@nti%2fclone 207ms
npm timing arborist:ctor Completed in 0ms
npm timing arborist:ctor Completed in 0ms
npm timing arborist:ctor Completed in 0ms
npm timing idealTree:init Completed in 41ms
npm http fetch GET 200 https://npm.nextthought.com/@nti%2fclone 85ms
npm timing idealTree:userRequests Completed in 86ms
npm sill idealTree buildDeps
npm sill fetch manifest @nti/[email protected]
npm http fetch GET 200 https://npm.nextthought.com/@nti%2fclone 86ms
npm sill placeDep ROOT @nti/[email protected] REPLACE for:  want: 2.28.1
npm timing idealTree:#root Completed in 92ms
npm timing idealTree:node_modules/@nti/clone Completed in 0ms
npm timing idealTree:buildDeps Completed in 93ms
npm timing idealTree:fixDepFlags Completed in 1ms
npm timing idealTree Completed in 222ms
npm timing reify:loadTrees Completed in 222ms
npm timing reify:diffTrees Completed in 1ms
npm sill reify mark retired [ '/home/jonathan/.npm/_npx/2d462251b07b0764/node_modules/@nti/clone' ]
npm sill reify moves {
npm sill reify   '/home/jonathan/.npm/_npx/2d462251b07b0764/node_modules/@nti/clone': '/home/jonathan/.npm/_npx/2d462251b07b0764/node_modules/@nti/.clone-Ujz7Huvv'
npm sill reify }
npm timing reify:retireShallow Completed in 1ms
npm timing reify:createSparse Completed in 0ms
npm timing reify:loadBundles Completed in 0ms
npm sill tarball no local data for https://npm.nextthought.com/@nti%2fclone/-/clone-2.28.1.tgz. Extracting by manifest.
npm http fetch GET 403 https://npm.nextthought.com/@nti%2fclone/-/clone-2.28.1.tgz 21ms
npm timing reify:rollback:createSparse Completed in 1ms
npm timing reify:rollback:retireShallow Completed in 0ms
npm timing command:exec Completed in 513ms
npm verb stack Error: 403 Forbidden - GET https://npm.nextthought.com/@nti%2fclone/-/clone-2.28.1.tgz - unregistered users are not allowed to access package @nti/clone
npm verb stack     at /home/jonathan/.nvm/versions/node/v14.13.1/lib/node_modules/npm/node_modules/npm-registry-fetch/check-response.js:123:15
npm verb stack     at processTicksAndRejections (internal/process/task_queues.js:93:5)
npm verb statusCode 403
npm verb pkgid https://npm.nextthought.com/@nti%2fclone/-/clone-2.28.1.tgz
npm verb cwd /home/jonathan
npm verb Linux 5.8.14-200.fc32.x86_64
npm verb argv "/home/jonathan/.nvm/versions/node/v14.13.1/bin/node" "/home/jonathan/.nvm/versions/node/v14.13.1/lib/node_modules/npm/bin/npm-cli.js" "exec" "--loglevel" "silly" "--yes" "--package" "@nti/clone@latest" "--call" "clone"
npm verb node v14.13.1
npm verb npm  v7.0.0
npm ERR! code E403
npm ERR! 403 403 Forbidden - GET https://npm.nextthought.com/@nti%2fclone/-/clone-2.28.1.tgz - unregistered users are not allowed to access package @nti/clone
npm ERR! 403 In most cases, you or one of your dependencies are requesting
npm ERR! 403 a package version that is forbidden by your security policy, or
npm ERR! 403 on a server you do not have access to.
npm verb exit 1
npm http fetch POST 200 https://registry.npmjs.org/-/npm/v1/security/advisories/bulk 434ms
npm timing auditReport:getReport Completed in 435ms
npm timing auditReport:init Completed in 0ms
npm timing reify:audit Completed in 436ms
npm timing npm Completed in 1035ms

Expected Behavior:

The package downloads/runs.

Steps To Reproduce:

Run npx on a simple package in a private scope. Mine was @nti/clone and @nti/fix. These are command-line tools that automate things...

Environment:

System:
    OS: Linux 5.8 Fedora 32 (Workstation Edition) 32 (Workstation Edition)
    CPU: (32) x64 AMD Ryzen 9 3950X 16-Core Processor
    Memory: 25.93 GB / 31.32 GB
    Container: Yes
    Shell: 5.8 - /usr/bin/zsh
  Binaries:
    Node: 14.13.1 - ~/.nvm/versions/node/v14.13.1/bin/node
    npm: 7.0.0 - ~/.nvm/versions/node/v14.13.1/bin/npm

[jsg2021]

There might be an install bug here. Trying to npm install @nti/clone gets me a 403 downloading the tarball from our private registry... but it was able to authenticate to get package info.

[jsg2021]

npm6 this works fine. both install and exec.

[jsg2021]

Its seems like its only failing on packages that have type: module in the package.json :thinking:

[t-fritsch]

same here with npx 7.0.2. I'm also using nvm on linux (debian) but with node 15

npx serve

sh: 1: serve: not found
npm ERR! code 127
npm ERR! path /home/xxxxxxxxx/tmp
npm ERR! command failed
npm ERR! command sh -c serve

npm ERR! A complete log of this run can be found in:
npm ERR!     /home/xxxxxxxxx/.npm/_logs/2020-10-21T16_02_33_043Z-debug.log

(NB: serve does not have type: module in its package.json https://github.com/vercel/serve/blob/master/package.json)

[nlf]

@jsg2021 i don't suppose you've seen this happen with a public module? also, we did release some fixes related to auth of private registries, does this still happen for you in 7.0.5?

@t-fritsch i'm not able to reproduce that one in 7.0.5 either, can you try updating and let me know if it fixes it?

[t-fritsch]

thank you @nlf, unfortunately I just tried with 7.0.5 and still get the same error message

[nlf]

thank you @nlf, unfortunately I just tried with 7.0.5 and still get the same error message

can you share more details? are you running npx serve from a directory that has a package.json? is serve a local dependency, or globally installed? the debug log mentioned in the error output may also be helpful

[t-fritsch]

yes of course :

• running from a directory with or without a package.json file results in the same error message.
• installing the package as a local dependency with npm i serve before running npx serve works
• using npx@6 works fine in every situation (with or without package.json, with or without locally installed package)
• here is the log output :
  
  
  

  cat /home/xxxxxxxxx/.npm/_logs/2020-10-27T15_25_12_235Z-debug.log

0 verbose cli [
0 verbose cli   '/home/xxxxxxxxxx/.nvm/versions/node/v15.0.1/bin/node',
0 verbose cli   '/home/xxxxxxxxxx/.nvm/versions/node/v15.0.1/lib/node_modules/npm/bin/npm-cli.js',
0 verbose cli   'exec',
0 verbose cli   '--',
0 verbose cli   'serve'
0 verbose cli ]
1 info using [email protected]
2 info using [email protected]
3 timing config:load:defaults Completed in 2ms
4 timing config:load:file:/home/xxxxxxxxxx/.nvm/versions/node/v15.0.1/lib/node_modules/npm/npmrc Completed in 2ms
5 timing config:load:builtin Completed in 2ms
6 timing config:load:cli Completed in 2ms
7 timing config:load:env Completed in 0ms
8 timing config:load:file:/home/xxxxxxxxxx/tmp/.npmrc Completed in 0ms
9 timing config:load:project Completed in 2ms
10 timing config:load:file:/home/xxxxxxxxxx/.npmrc Completed in 1ms
11 timing config:load:user Completed in 1ms
12 timing config:load:file:/home/xxxxxxxxxx/.nvm/versions/node/v15.0.1/etc/npmrc Completed in 1ms
13 timing config:load:global Completed in 1ms
14 timing config:load:cafile Completed in 0ms
15 timing config:load:validate Completed in 2ms
16 timing config:load:setUserAgent Completed in 1ms
17 timing config:load:setEnvs Completed in 1ms
18 timing config:load Completed in 15ms
19 verbose npm-session bc119059f77a1875
20 timing npm:load Completed in 26ms
21 http fetch GET 304 http://registry.npmjs.org/serve 97ms (from cache)
22 timing arborist:ctor Completed in 0ms
23 timing arborist:ctor Completed in 0ms
24 timing command:exec Completed in 173ms
25 verbose stack Error: command failed
25 verbose stack     at ChildProcess. (/home/xxxxxxxxxx/.nvm/versions/node/v15.0.1/lib/node_modules/npm/node_modules/@npmcli/promise-spawn/index.js:63:27)
25 verbose stack     at ChildProcess.emit (node:events:327:20)
25 verbose stack     at maybeClose (node:internal/child_process:1048:16)
25 verbose stack     at Process.ChildProcess._handle.onexit (node:internal/child_process:288:5)
26 verbose cwd /home/xxxxxxxxxx/tmp
27 verbose Linux 4.19.0-12-amd64
28 verbose argv "/home/xxxxxxxxxx/.nvm/versions/node/v15.0.1/bin/node" "/home/xxxxxxxxxx/.nvm/versions/node/v15.0.1/lib/node_modules/npm/bin/npm-cli.js" "exec" "--" "serve"
29 verbose node v15.0.1
30 verbose npm  v7.0.5
31 error code 127
32 error path /home/xxxxxxxxxx/tmp
33 error command failed
34 error command sh -c serve
35 verbose exit 127

[JakeChampion]

We are seeing the same issue for two other packages as well:

• oax
• @financial-times/sass

I don't think this is to do with multiple different registries being used as I can replicate the issue when using only the public npmjs registry.

Here is the github workflow build which fails when using npmjs public registry directly

Here is the github workflow build which fails when using a proxy npm registry

The issue looks to be a failure in linking the binary file to the node_modules/.bin directory.

Here is the commands and out I used to get to that conclusion, they should be reproducible for anyone to run: npm -v && npm init -y && npm i --save-dev scrumple && npm ls && tree && ls ./node_modules/.bin && npx scrumple

❯ npm -v
7.0.6

❯ npm init -y
Wrote to /private/tmp/a/package.json:
{
  "name": "a",
  "version": "1.0.0",
  "description": "",
  "main": "index.js",
  "scripts": {
    "test": "echo \"Error: no test specified\" && exit 1"
  },
  "keywords": [],
  "author": "",
  "license": "ISC"
}

❯ npm i --save-dev scrumple
added 2 packages, and audited 2 packages in 4s
found 0 vulnerabilities

❯ npm ls
[email protected] /private/tmp/a
└── [email protected]

❯ tree
.
├── node_modules
│   ├── .bin
│   ├── .package-lock.json
│   ├── @financial-times
│   │   └── scrumple-darwin
│   │       ├── index.js
│   │       ├── package.json
│   │       ├── postinstall.js
│   │       └── scrumple
│   └── scrumple
│       ├── index.js
│       ├── package.json
│       ├── postinstall.js
│       ├── readme.md
│       └── scrumple -> ../@financial-times/scrumple-darwin/scrumple
├── package-lock.json
└── package.json
5 directories, 12 files

❯ ls ./node_modules/.bin

❯ npx scrumple
sh: scrumple: command not found
npm ERR! code 127
npm ERR! path /private/tmp/a
npm ERR! command failed
npm ERR! command sh -c scrumple

npm ERR! A complete log of this run can be found in:
npm ERR!     /Users/jake.champion/.npm/_logs/2020-10-29T11_15_13_075Z-debug.log

[jsg2021]

@nlf I tried to recreate my private packages on the public registry gutted... but I couldn't get any I publish to fail. But, my existing (internal registry) packages still fail with command not found. So this made me try just publishing a new version... and the new published packages on the internal registry work. (I've done all this on 7.0.8 today)

I tested npx serve and it works for me.

[nlf]

oax and scrumple have bin entries that refer to a symlink within the published code, symlinks in windows however are.. strange, and so it is unsurprising that this doesn't work. with the current npm (7.0.9) i can install scrumple and i see that the bin file is in place, if i attempt to run it i get a Cannot find module 'node_modules/scrumple/scrumple from the common JS loader telling me that it's node itself that is unable to resolve this type of symlink.

given that, as well as the confirmation that other packages seem to be working correctly, i'm going to close this issue

[JakeChampion]

Previous versions of npm worked fine with the same oax and scrumple version, do you know why that would be?