NPM issue with a fresh Windows Prebuilt Package? #4787

alexeisenhart · 2021-02-15T15:25:33Z

Describe the bug

I first followed the "Manually install on Windows" directions to set up Etherpad on Windows for development then I ran into the issue that I'll describe below. I assumed that I set something up wrong, so I trashed that and started from scratch with the "Prebuilt Windows package" steps and the error happened again.

Below you'll find the command line output from running start.bat as an administrator, using an installation that was freshly extracted from etherpad-lite-win.zip and unmodified. Is there any other information that I can supply that would be helpful to debug this issue?

C:\Windows\system32>cd c:\dev\W\VisualStudio.com\Etherpad

c:\dev\W\VisualStudio.com\Etherpad>start.bat

c:\dev\W\VisualStudio.com\Etherpad>node node_modules\ep_etherpad-lite\node\server.js
[2021-02-15 10:18:12.137] [DEBUG] console - Running on Node v12.20.2 (minimum required Node version: 10.17.0)
[2021-02-15 10:18:12.149] [DEBUG] AbsolutePaths - c:\dev\W\VisualStudio.com\Etherpad\node_modules\ep_etherpad-lite does not end with "src"
[2021-02-15 10:18:12.150] [INFO] console - All relative paths will be interpreted relative to the identified Etherpad base dir: c:\dev\W\VisualStudio.com\Etherpad
[2021-02-15 10:18:12.150] [INFO] console - Random string used for versioning assets: 3d78ab94
[2021-02-15 10:18:12.151] [DEBUG] AbsolutePaths - Relative path "settings.json" can be rewritten to "c:\dev\W\VisualStudio.com\Etherpad\settings.json"
[2021-02-15 10:18:12.151] [DEBUG] AbsolutePaths - Relative path "credentials.json" can be rewritten to "c:\dev\W\VisualStudio.com\Etherpad\credentials.json"
[2021-02-15 10:18:12.157] [INFO] console - settings loaded from: c:\dev\W\VisualStudio.com\Etherpad\settings.json
[2021-02-15 10:18:12.158] [INFO] console - No credentials file found in c:\dev\W\VisualStudio.com\Etherpad\credentials.json. Ignoring.
[2021-02-15 10:18:12.159] [INFO] console - Using skin "colibris" in dir: c:\dev\W\VisualStudio.com\Etherpad\src\static\skins\colibris
[2021-02-15 10:18:12.159] [INFO] console - Session key loaded from: c:\dev\W\VisualStudio.com\Etherpad\SESSIONKEY.txt
[2021-02-15 10:18:12.159] [WARN] console - DirtyDB is used. This is not recommended for production. File location: c:\dev\W\VisualStudio.com\Etherpad\var\dirty.db
[2021-02-15 10:18:12.483] [INFO] server - Starting Etherpad...
[2021-02-15 10:18:12.489] [ERROR] server - Error: spawn npm ENOENT
    at Process.ChildProcess._handle.onexit (internal/child_process.js:268:19)
    at onErrorNT (internal/child_process.js:470:16)
    at processTicksAndRejections (internal/process/task_queues.js:84:21)
[2021-02-15 10:18:12.490] [ERROR] server - TypeError: Promise resolve or reject function is not callable
    at Promise.then (<anonymous>)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)
[2021-02-15 10:18:12.490] [ERROR] server - Error occurred while waiting to exit. Forcing an immediate unclean exit...

To Reproduce
Follow the steps to set up the Windows Prebuilt Package. The above error occurs when the start.bat script is executed in a command prompt with Administrator permissions.

https://github.com/ether/etherpad-lite#prebuilt-windows-package

The text was updated successfully, but these errors were encountered:

JohnMcLear · 2021-02-15T15:42:07Z

If you do node -v what do you get?

alexeisenhart · 2021-02-15T16:36:46Z

Thanks for your fast response! v12.20.2

JohnMcLear · 2021-02-15T16:52:59Z

Confirmed with 12.20.2. Gimme 15 mins will try compile a fresh zip and up it

JohnMcLear · 2021-02-15T17:03:10Z

Good news is I can replicate, bad news is it has nothing to do with the built / compiled version, it's broken when running from source ;\ Weird this one sneaked through, we sort of expect node to be mature enough to work the same on windows and linux nowadays but I guess we're learning how fragile the npm/node ecosystem is a little bit more every day ;(

Tested on 14.15.0

JohnMcLear · 2021-02-15T17:07:35Z

etherpad-lite/src/node/server.js

Line 135 in 269c6d0

await util.promisify(npm.load)();

is offending line.

JohnMcLear · 2021-02-15T17:10:12Z

@rhansen any ideas on this? I think it's related to npm version but it looks like it's failing on 6.14.11 when I thought this functionality wouldn't fail until 7.*

alexeisenhart · 2021-02-15T19:42:13Z

@JohnMcLear, do you think if I downgraded to an older version of Node then I'd be able to continue with my set up and testing? If so, which version would you recommend?

rhansen · 2021-02-16T05:42:09Z

I don't have access to a Windows machine so I have no idea what's going wrong (other than the fact that it's executing npm when it should be executing npm.cmd on Windows), or why it started happening now. We can try upgrading npm to a newer 6.x (see #4788) but looking at the changelog I'm not optimistic.

Line 135 is offending line.

Are you sure it's line 135 that's causing the problem? Can you get any more information about where inside npm.load() it is failing?

rhansen · 2021-02-16T05:44:39Z

We can try upgrading npm to a newer 6.x (see #4788)

I merged that PR. Please check out the latest develop branch and see if you can reproduce.

JohnMcLear · 2021-02-16T09:22:08Z

No dice w/ that PR. Any tips for how to dive into npm.load? Afaik that's an npm internal thing?

I can try create a MVP crash, that might be useful.

JohnMcLear · 2021-02-16T09:26:25Z

'use strict';

const util = require('util');
const npm = require('npm/lib/npm.js');
(async () => {
  console.log('does this crash?');
  await util.promisify(npm.load)();
  console.log('this works!');
})();

This does not crash...

JohnMcLear · 2021-02-16T09:30:04Z

'use strict';

const util = require('util');
const npm = require('npm/lib/npm.js');
const pluginDefs = require('../static/js/pluginfw/plugin_defs');
const plugins = require('../static/js/pluginfw/plugins');

(async () => {
  console.log('does this crash?');
  await util.promisify(npm.load)();
  console.log('this works!');
})();

crashes with

[2021-02-16 09:29:24.753] [INFO] console - does this crash?
events.js:292
      throw er; // Unhandled 'error' event
      ^

Error: spawn npm ENOENT
    at Process.ChildProcess._handle.onexit (internal/child_process.js:269:19)
    at onErrorNT (internal/child_process.js:465:16)
    at processTicksAndRejections (internal/process/task_queues.js:80:21)
Emitted 'error' event on ChildProcess instance at:
    at Process.ChildProcess._handle.onexit (internal/child_process.js:275:12)
    at onErrorNT (internal/child_process.js:465:16)
    at processTicksAndRejections (internal/process/task_queues.js:80:21) {
  errno: -4058,
  code: 'ENOENT',
  syscall: 'spawn npm',
  path: 'npm',
  spawnargs: [ '--version' ]

JohnMcLear · 2021-02-16T09:30:45Z

So the problem is in pluginfw/plugins.js

JohnMcLear · 2021-02-16T09:37:08Z

await Promise.all([
    (async () => { for await (const chunk of p.stdout) chunks.push(chunk); })(),
    p, // Await in parallel to avoid unhandled rejection if np rejects during chunk read.
  ]);

is the offending line.

JohnMcLear · 2021-02-16T09:47:24Z

That's as far as I can get today, the contents of p.stdout is

[2021-02-16 09:46:23.494] [WARN] console - <ref *1> Socket {
  connecting: false,
  _hadError: false,
  _parent: null,
  _host: null,
  _readableState: ReadableState {
    objectMode: false,
    highWaterMark: 16384,
    buffer: BufferList { head: null, tail: null, length: 0 },
    length: 0,
    pipes: [],
    flowing: true,
    ended: false,
    endEmitted: false,
    reading: true,
    sync: false,
    needReadable: true,
    emittedReadable: false,
    readableListening: false,
    resumeScheduled: true,
    errorEmitted: false,
    emitClose: false,
    autoDestroy: false,
    destroyed: false,
    errored: null,
    closed: false,
    closeEmitted: false,
    defaultEncoding: 'utf8',
    awaitDrainWriters: null,
    multiAwaitDrain: false,
    readingMore: false,
    decoder: StringDecoder {
      encoding: 'utf8',
      [Symbol(kNativeDecoder)]: <Buffer 00 00 00 00 00 00 01>
    },
    encoding: 'utf8',
    [Symbol(kPaused)]: false
  },
  _events: [Object: null prototype] {
    end: [ [Function: onReadableStreamEnd], [Function (anonymous)] ],
    close: [Function (anonymous)],
    data: [Function (anonymous)]
  },
  _eventsCount: 3,
  _maxListeners: undefined,
  _writableState: WritableState {
    objectMode: false,
    highWaterMark: 16384,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: false,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function: bound onwrite],
    writecb: null,
    writelen: 0,
    afterWriteTickInfo: null,
    buffered: [],
    bufferedIndex: 0,
    allBuffers: true,
    allNoop: true,
    pendingcb: 0,
    prefinished: false,
    errorEmitted: false,
    emitClose: false,
    autoDestroy: false,
    errored: null,
    closed: false,
    writable: false,
    closeEmitted: false
  },
  allowHalfOpen: false,
  _sockname: null,
  _pendingData: null,
  _pendingEncoding: '',
  server: null,
  _server: null,
  [Symbol(async_id_symbol)]: 9,
  [Symbol(kHandle)]: Pipe { reading: true, [Symbol(owner_symbol)]: [Circular *1] },
  [Symbol(kSetNoDelay)]: false,
  [Symbol(lastWriteQueueSize)]: 0,
  [Symbol(timeout)]: null,
  [Symbol(kBuffer)]: null,
  [Symbol(kBufferCb)]: null,
  [Symbol(kBufferGen)]: null,
  [Symbol(kCapture)]: false,
  [Symbol(kBytesRead)]: 0,
  [Symbol(kBytesWritten)]: 0
}

JohnMcLear · 2021-02-16T09:52:43Z

On linux p.stdout is

<ref *1> Socket {
  connecting: false,
  _hadError: false,
  _parent: null,
  _host: null,
  _readableState: ReadableState {
    objectMode: false,
    highWaterMark: 16384,
    buffer: BufferList { head: null, tail: null, length: 0 },
    length: 0,
    pipes: [],
    flowing: null,
    ended: false,
    endEmitted: false,
    reading: true,
    sync: false,
    needReadable: true,
    emittedReadable: false,
    readableListening: false,
    resumeScheduled: false,
    errorEmitted: false,
    emitClose: false,
    autoDestroy: false,
    destroyed: false,
    errored: null,
    closed: false,
    closeEmitted: false,
    defaultEncoding: 'utf8',
    awaitDrainWriters: null,
    multiAwaitDrain: false,
    readingMore: false,
    decoder: null,
    encoding: null,
    [Symbol(kPaused)]: null
  },
  _events: [Object: null prototype] {
    end: [Function: onReadableStreamEnd],
    close: [Function (anonymous)]
  },
  _eventsCount: 2,
  _maxListeners: undefined,
  _writableState: WritableState {
    objectMode: false,
    highWaterMark: 16384,
    finalCalled: false,
    needDrain: false,
    ending: false,
    ended: false,
    finished: false,
    destroyed: false,
    decodeStrings: false,
    defaultEncoding: 'utf8',
    length: 0,
    writing: false,
    corked: 0,
    sync: true,
    bufferProcessing: false,
    onwrite: [Function: bound onwrite],
    writecb: null,
    writelen: 0,
    afterWriteTickInfo: null,
    buffered: [],
    bufferedIndex: 0,
    allBuffers: true,
    allNoop: true,
    pendingcb: 0,
    prefinished: false,
    errorEmitted: false,
    emitClose: false,
    autoDestroy: false,
    errored: null,
    closed: false,
    writable: false,
    closeEmitted: false
  },
  allowHalfOpen: false,
  _sockname: null,
  _pendingData: null,
  _pendingEncoding: '',
  server: null,
  _server: null,
  [Symbol(async_id_symbol)]: 8,
  [Symbol(kHandle)]: Pipe { reading: true, [Symbol(owner_symbol)]: [Circular *1]                                                                         },
  [Symbol(kSetNoDelay)]: false,
  [Symbol(lastWriteQueueSize)]: 0,
  [Symbol(timeout)]: null,
  [Symbol(kBuffer)]: null,
  [Symbol(kBufferCb)]: null,
  [Symbol(kBufferGen)]: null,
  [Symbol(kCapture)]: false,
  [Symbol(kBytesRead)]: 0,
  [Symbol(kBytesWritten)]: 0
}

JohnMcLear · 2021-02-16T10:04:55Z

The notable values that change are

resumeScheduled
decoder
The end event

I'd hazard a guess here the windows nodejs stdout is behaving different to linux, there are some docs on this but I'm not sure which part is useful to us: https://nodejs.org/api/child_process.html

rhansen · 2021-02-16T22:15:43Z

Fixed by PR #4799. Please try the latest commit on the develop branch.

@JohnMcLear Should we cut a new release? It'll give us an excuse to test out the release.js changes. 🙂

alexeisenhart changed the title ~~NPM issue with a fresh Manual Install on Windows?~~ NPM issue with a fresh Windows Prebuilt Package? Feb 15, 2021

JohnMcLear mentioned this issue Feb 16, 2021

WIP: Windows Server CI #4791

Merged

6 tasks

rhansen mentioned this issue Feb 16, 2021

plugins: Fix "Error: spawn npm ENOENT" error on Windows #4799

Merged

rhansen linked a pull request Feb 16, 2021 that will close this issue

plugins: Fix "Error: spawn npm ENOENT" error on Windows #4799

Merged

rhansen closed this as completed Feb 16, 2021

alexeisenhart mentioned this issue Feb 17, 2021

Unable to find packages.json on Windows Manual Install #4800

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

NPM issue with a fresh Windows Prebuilt Package? #4787

NPM issue with a fresh Windows Prebuilt Package? #4787

alexeisenhart commented Feb 15, 2021 •

edited by rhansen

Loading

JohnMcLear commented Feb 15, 2021

alexeisenhart commented Feb 15, 2021

JohnMcLear commented Feb 15, 2021 •

edited

Loading

JohnMcLear commented Feb 15, 2021 •

edited

Loading

JohnMcLear commented Feb 15, 2021 •

edited by rhansen

Loading

JohnMcLear commented Feb 15, 2021

alexeisenhart commented Feb 15, 2021

rhansen commented Feb 16, 2021 •

edited

Loading

rhansen commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021 •

edited

Loading

JohnMcLear commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021

rhansen commented Feb 16, 2021

NPM issue with a fresh Windows Prebuilt Package? #4787

NPM issue with a fresh Windows Prebuilt Package? #4787

Comments

alexeisenhart commented Feb 15, 2021 • edited by rhansen Loading

JohnMcLear commented Feb 15, 2021

alexeisenhart commented Feb 15, 2021

JohnMcLear commented Feb 15, 2021 • edited Loading

JohnMcLear commented Feb 15, 2021 • edited Loading

JohnMcLear commented Feb 15, 2021 • edited by rhansen Loading

JohnMcLear commented Feb 15, 2021

alexeisenhart commented Feb 15, 2021

rhansen commented Feb 16, 2021 • edited Loading

rhansen commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021 • edited Loading

JohnMcLear commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021

JohnMcLear commented Feb 16, 2021

rhansen commented Feb 16, 2021

alexeisenhart commented Feb 15, 2021 •

edited by rhansen

Loading

JohnMcLear commented Feb 15, 2021 •

edited

Loading

JohnMcLear commented Feb 15, 2021 •

edited

Loading

JohnMcLear commented Feb 15, 2021 •

edited by rhansen

Loading

rhansen commented Feb 16, 2021 •

edited

Loading

JohnMcLear commented Feb 16, 2021 •

edited

Loading