Unable to find packages.json on Windows Manual Install

Describe the bug

I grabbed the latest changeset, d7ed71e, on the develop branch. I think issue #4787 has been resolved, but I'm getting an error that packages.json cannot be found.

Relevant snippet:

[ERROR] npm - npm ERR! error in C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\node_modules\ep_etherpad-lite: ENOENT: no such file or directory, open 'C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\node_modules\ep_etherpad-lite\package.json'

The file ep_etherpad-lite exists and the contents are "../src". If use a file explorer to navigate up one level and into /src, I find packages.json. I don't think Windows supports using a file for path redirection this way. I tried replacing ep_etherpad-lite with a shortcut, but that didn't work. I deleted ep_etherpad-lite, created a folder in its place and copied packages.json into this folder: that caused this issue to go away and start.bat seems to run successfully.

However, start.bat auto exits and returns to the command line and there doesn't appear to be a server running in the background. I don't know if that is a side effect of the change I described above. I then tried using node src/node/server.js to start the server instead, but auto-quits in the same way.

1) Here's the complete log from before I started playing with the ep_etherpad-lite file.

C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop>start.bat

C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop>node src\node\server.js
[2021-02-16 19:00:20.780] [DEBUG] console - Running on Node v14.15.5 (minimum required Node version: 10.17.0)
[2021-02-16 19:00:20.793] [INFO] console - All relative paths will be interpreted relative to the identified Etherpad base dir: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop
[2021-02-16 19:00:20.794] [INFO] console - Random string used for versioning assets: 04155d40
[2021-02-16 19:00:20.795] [DEBUG] AbsolutePaths - Relative path "settings.json" can be rewritten to "C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\settings.json"
[2021-02-16 19:00:20.796] [DEBUG] AbsolutePaths - Relative path "credentials.json" can be rewritten to "C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\credentials.json"
[2021-02-16 19:00:20.797] [WARN] console - No settings file found in C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\settings.json. Continuing using defaults!
[2021-02-16 19:00:20.797] [INFO] console - No credentials file found in C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\credentials.json. Ignoring.
[2021-02-16 19:00:20.798] [WARN] console - No "skinName" parameter found. Please check out settings.json.template and update your settings.json. Falling back to the default "colibris".
[2021-02-16 19:00:20.799] [INFO] console - Using skin "colibris" in dir: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\src\static\skins\colibris
[2021-02-16 19:00:20.799] [INFO] console - Session key file "C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\SESSIONKEY.txt" not found. Creating with random contents.
[2021-02-16 19:00:20.800] [WARN] console - DirtyDB is used. This is not recommended for production. File location: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\var\dirty.db
[2021-02-16 19:00:21.142] [INFO] server - Starting Etherpad...
[2021-02-16 19:00:21.180] [INFO] runNpm - Executing command: npm ls --long --json --depth=0
[2021-02-16 19:00:21.330] [INFO] runNpm - npm --version: 6.14.11
[2021-02-16 19:00:21.615] [ERROR] npm - npm ERR! error in C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\node_modules\ep_etherpad-lite: ENOENT: no such file or directory, open 'C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\node_modules\ep_etherpad-lite\package.json'
[2021-02-16 19:00:21.623] [ERROR] runNpm - npm command failed: npm ls --long --json --depth=0
[2021-02-16 19:00:21.624] [ERROR] server - Error occurred while starting Etherpad
[2021-02-16 19:00:21.625] [ERROR] server - Error: Command exited non-zero: npm ls --long --json --depth=0
    at exports (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\src\node\utils\run_cmd.js:71:25)
    at exports (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\src\node\utils\run_npm.js:25:13)
    at Object.exports.getPackages (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\src\static\js\pluginfw\plugins.js:73:14)
    at Object.exports.update (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\src\static\js\pluginfw\plugins.js:56:34)
    at Object.exports.start (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\src\node\server.js:137:19)
[2021-02-16 19:00:21.625] [INFO] server - Exiting...
[2021-02-16 19:00:21.626] [INFO] server - Waiting for Node.js to exit...

2) Log from after I deleted the ep_etherpad-lite file and copied packages.json into a new folder in its place.

C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop>node ./src/node/server.js
[2021-02-16 19:34:11.334] [DEBUG] console - Running on Node v12.20.2 (minimum required Node version: 10.17.0)
[2021-02-16 19:34:11.348] [INFO] console - All relative paths will be interpreted relative to the identified Etherpad base dir: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop
[2021-02-16 19:34:11.349] [INFO] console - Random string used for versioning assets: 5a4d5cee
[2021-02-16 19:34:11.349] [DEBUG] AbsolutePaths - Relative path "settings.json" can be rewritten to "C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\settings.json"
[2021-02-16 19:34:11.350] [DEBUG] AbsolutePaths - Relative path "credentials.json" can be rewritten to "C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\credentials.json"
[2021-02-16 19:34:11.350] [WARN] console - No settings file found in C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\settings.json. Continuing using defaults!
[2021-02-16 19:34:11.351] [INFO] console - No credentials file found in C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\credentials.json. Ignoring.
[2021-02-16 19:34:11.351] [WARN] console - No "skinName" parameter found. Please check out settings.json.template and update your settings.json. Falling back to the default "colibris".
[2021-02-16 19:34:11.352] [INFO] console - Using skin "colibris" in dir: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\src\static\skins\colibris
[2021-02-16 19:34:11.352] [INFO] console - Session key loaded from: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\SESSIONKEY.txt
[2021-02-16 19:34:11.352] [WARN] console - DirtyDB is used. This is not recommended for production. File location: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e\etherpad-lite-develop\var\dirty.db
[2021-02-16 19:34:11.694] [INFO] server - Starting Etherpad...
[2021-02-16 19:34:11.731] [INFO] runNpm - Executing command: npm ls --long --json --depth=0
[2021-02-16 19:34:11.875] [INFO] runNpm - npm --version: 6.14.11
[2021-02-16 19:34:12.178] [INFO] runNpm - Successfully ran command: npm ls --long --json --depth=0
[2021-02-16 19:34:12.178] [INFO] server - Installed plugins:
[2021-02-16 19:34:12.179] [INFO] server - Etherpad is running

To Reproduce

I downloaded changeset d7ed71e from the develop branch.
Executed InstallOnWindows.bat (no reported errors).
Executed start.bat and the above error was reported.

All of the above was on:

Node v14.15.5
NPM 6.14.11

I downgraded back to Node v12.20.2 and the same problem occurs.

The file ep_etherpad-lite exists and the contents are "../src". If use a file explorer to navigate up one level and into /src, I find packages.json. I don't think Windows supports using a file for path redirection this way.

Correct. node_modules\ep_etherpad-lite is supposed to be a symbolic link that points to the src directory. You can tell that it is supposed to be a symlink by running git cat-file -p HEAD:node_modules—the 120000 for the file's mode means it's stored in Git as a symlink (regular files are either 100644 or 100755 depending on whether they're executable or not). Unfortunately, Windows doesn't handle symbolic links well: https://github.com/git-for-windows/git/wiki/Symbolic-Links

I haven't used Windows in ages, so I don't know what the "right" fix is. The quick-and-dirty fix would be to replace node_modules\ep_etherpad-lite with a directory and copy everything in src (recursively) into node_modules\ep_etherpad-lite. Or you can try to figure out how to replace node_modules\ep_etherpad-lite with something resembling a symlink, perhaps by enabling Git for Windows's core.symlinks setting.

Thanks @rhansen!

Here's a summary list of the current issues that I ran into and the actions that I took to resolve them, in case this is helpful for the EP-lite team or anyone else trying to set up Windows in the short term.

Extracted a fresh copy of changeset d7ed71e.
Deleted node_modules\ep_etherpad-lite
Created a new folder at node_modules\ep_etherpad-lite
Moved the contents (recursively) of src into node_modules\ep_etherpad-lite. Delete src.
Ran InstallOnWindows.bat.
Modified start.bat to be node node_modules\ep_etherpad-lite\node\server.js.
Ran start.bat.

This error was reported.

Error: ENOENT: no such file or directory, open 'C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\src\node\utils\tar.json'

There was a hardcoded reference to the src folder and this one seems to come from line 20 of static.js. I adjusted this path manually, as such:

const tarJson = await fs.readFile(path.join(settings.root, 'node_modules/ep_etherpad-lite/node/utils/tar.json'), 'utf8');

Re-ran the server and it's running locally on my machine!

Addition:

I noticed that the skin directory wasn't found. Also adjusted node\utils\Settings.js line 712 to the following:

const skinBasePath = path.join(exports.root, 'node_modules', 'ep_etherpad-lite', 'static', 'skins');

Nice spot, I will try to send a PR containing these fixes today :)

Ah, most of these changes would break linux deployments so I'm not sure it's the right fix ;/

Yeah, I completely agree that this would break the linux deployments. I'm not at all familiar with Node development, so I'm just trying to keep notes of what I needed to adjust to get it to work on Windows. Is that helpful?

I tried installing a plugin, ep_copy_paste_images, via the admin plugin manager web page, and it crashed the server.

[2021-02-17 13:25:09.001] [WARN] console - Can't get git version for server header
ENOENT: no such file or directory, lstat 'C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop/.git'
npm WARN saveError ENOENT: no such file or directory, open 'C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\package.json'
npm notice created a lockfile as package-lock.json. You should commit this file.
npm WARN enoent ENOENT: no such file or directory, open 'C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\package.json'
npm WARN etherpad-lite-develop No description
npm WARN etherpad-lite-develop No repository field.
npm WARN etherpad-lite-develop No README data
npm WARN etherpad-lite-develop No license field.
[2021-02-17 13:25:28.249] [ERROR] console -
[2021-02-17 13:25:28.256] [INFO] console - + ep_copy_paste_images@0.0.28
added 1 package from 1 contributor and audited 919 packages in 5.205s
[2021-02-17 13:25:28.505] [INFO] console -
73 packages are looking for funding
  run `npm fund` for details

[2021-02-17 13:25:28.506] [INFO] console - found 0 vulnerabilities

[2021-02-17 13:25:28.510] [INFO] runNpm - Executing command: npm ls --long --json --depth=0
[2021-02-17 13:25:30.562] [ERROR] npm - npm ERR! peer dep missing: ep_etherpad-lite@>=1.8.6, required by ep_copy_paste_images@0.0.28
[2021-02-17 13:25:30.576] [ERROR] runNpm - npm command failed: npm ls --long --json --depth=0
[2021-02-17 13:25:30.576] [WARN] console - Error: Command exited non-zero: npm ls --long --json --depth=0
    at exports (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\node\utils\run_cmd.js:71:25)
    at exports (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\node\utils\run_npm.js:25:13)
    at Object.exports.getPackages (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\static\js\pluginfw\plugins.js:73:14)
    at Object.exports.update (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\static\js\pluginfw\plugins.js:56:34)
    at Object.exports.install (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\static\js\pluginfw\installer.js:54:19)
[2021-02-17 13:25:30.577] [INFO] http - Closing HTTP server...

Restarting the server now fails due to dependency issues.

[2021-02-17 13:47:59.253] [DEBUG] console - Running on Node v12.20.2 (minimum required Node version: 10.17.0)
[2021-02-17 13:47:59.265] [DEBUG] AbsolutePaths - C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite does not end with "src"
[2021-02-17 13:47:59.266] [INFO] console - All relative paths will be interpreted relative to the identified Etherpad base dir: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop
[2021-02-17 13:47:59.267] [INFO] console - Random string used for versioning assets: cd9d940b
[2021-02-17 13:47:59.267] [DEBUG] AbsolutePaths - Relative path "settings.json" can be rewritten to "C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\settings.json"
[2021-02-17 13:47:59.267] [DEBUG] AbsolutePaths - Relative path "credentials.json" can be rewritten to "C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\credentials.json"
[2021-02-17 13:47:59.273] [INFO] console - settings loaded from: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\settings.json
[2021-02-17 13:47:59.275] [INFO] console - No credentials file found in C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\credentials.json. Ignoring.
[2021-02-17 13:47:59.278] [INFO] console - Using skin "colibris" in dir: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\static\skins\colibris
[2021-02-17 13:47:59.278] [INFO] console - Session key loaded from: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\SESSIONKEY.txt
[2021-02-17 13:47:59.815] [INFO] server - Starting Etherpad...
tedious deprecated The default value for "config.options.validateBulkLoadParameters" will change from `false` to `true` in the next major version of `tedious`. Set the value to `true` or `false` explicitly to silence this message. node_modules\ep_etherpad-lite\node_modules\mssql\lib\tedious\connection-pool.js:62:23
[2021-02-17 13:47:59.905] [INFO] runNpm - Executing command: npm ls --long --json --depth=0
[2021-02-17 13:48:00.192] [INFO] runNpm - npm --version: 6.14.11
[2021-02-17 13:48:01.969] [ERROR] npm - npm ERR! peer dep missing: ep_etherpad-lite@>=1.8.6, required by ep_copy_paste_images@0.0.28
[2021-02-17 13:48:01.983] [ERROR] runNpm - npm command failed: npm ls --long --json --depth=0
[2021-02-17 13:48:01.983] [ERROR] server - Error occurred while starting Etherpad
[2021-02-17 13:48:01.983] [ERROR] server - Error: Command exited non-zero: npm ls --long --json --depth=0
    at exports (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\node\utils\run_cmd.js:71:25)
    at exports (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\node\utils\run_npm.js:25:13)
    at Object.exports.getPackages (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\static\js\pluginfw\plugins.js:73:14)
    at Object.exports.update (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\static\js\pluginfw\plugins.js:56:34)
    at Object.exports.start (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\node\server.js:137:19)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)
[2021-02-17 13:48:01.984] [INFO] server - Exiting...
[2021-02-17 13:48:01.984] [INFO] server - Waiting for Node.js to exit...
[2021-02-17 13:48:06.989] [ERROR] server - Something that should have been cleaned up during the shutdown hook (such as a timer, worker thread, or open connection) is preventing Node.js from exiting
[2021-02-17 13:48:06.990] [INFO] console - [WTF Node?] open handles:
[2021-02-17 13:48:06.992] [INFO] console - - File descriptors: (note: stdio always exists)
[2021-02-17 13:48:06.992] [INFO] console -   - fd 1 (tty) (stdio)
[2021-02-17 13:48:06.992] [INFO] console -   - fd 2 (tty) (stdio)
[2021-02-17 13:48:06.992] [INFO] console - - Sockets:
[2021-02-17 13:48:06.993] [INFO] console -   - 127.0.0.1:59718 -> 127.0.0.1:1433
[2021-02-17 13:48:06.993] [INFO] console - - Intervals:
[2021-02-17 13:48:06.994] [INFO] console -   - (1000 ~ 1000 ms) (anonymous) @ C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\node_modules\tarn\dist\Pool.js:451
[2021-02-17 13:48:06.994] [ERROR] server - Forcing an unclean exit...

I assume this is probably related to moving the src folder. After installing the addon, I now have a package-log.json1 file in the site root (I can't remember if this was here before). node_modules has a folder for ep_copy_paste_images. I tried moving this folder into `node_modules/ep_etherpad-lite/node_moduels', but that causes this crash.

[2021-02-17 13:57:25.568] [DEBUG] console - Running on Node v12.20.2 (minimum required Node version: 10.17.0)
[2021-02-17 13:57:25.583] [DEBUG] AbsolutePaths - C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite does not end with "src"
[2021-02-17 13:57:25.583] [INFO] console - All relative paths will be interpreted relative to the identified Etherpad base dir: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop
[2021-02-17 13:57:25.584] [INFO] console - Random string used for versioning assets: f95d1d38
[2021-02-17 13:57:25.585] [DEBUG] AbsolutePaths - Relative path "settings.json" can be rewritten to "C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\settings.json"
[2021-02-17 13:57:25.585] [DEBUG] AbsolutePaths - Relative path "credentials.json" can be rewritten to "C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\credentials.json"
[2021-02-17 13:57:25.591] [INFO] console - settings loaded from: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\settings.json
[2021-02-17 13:57:25.592] [INFO] console - No credentials file found in C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\credentials.json. Ignoring.
[2021-02-17 13:57:25.594] [INFO] console - Using skin "colibris" in dir: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\static\skins\colibris
[2021-02-17 13:57:25.594] [INFO] console - Session key loaded from: C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\SESSIONKEY.txt
[2021-02-17 13:57:26.111] [INFO] server - Starting Etherpad...
tedious deprecated The default value for "config.options.validateBulkLoadParameters" will change from `false` to `true` in the next major version of `tedious`. Set the value to `true` or `false` explicitly to silence this message. node_modules\ep_etherpad-lite\node_modules\mssql\lib\tedious\connection-pool.js:62:23
[2021-02-17 13:57:26.197] [INFO] runNpm - Executing command: npm ls --long --json --depth=0
[2021-02-17 13:57:26.482] [INFO] runNpm - npm --version: 6.14.11
[2021-02-17 13:57:27.928] [ERROR] npm - npm ERR! missing: ep_copy_paste_images@0.0.28, required by etherpad-lite-develop
[2021-02-17 13:57:27.942] [ERROR] runNpm - npm command failed: npm ls --long --json --depth=0
[2021-02-17 13:57:27.943] [ERROR] server - Error occurred while starting Etherpad
[2021-02-17 13:57:27.943] [ERROR] server - Error: Command exited non-zero: npm ls --long --json --depth=0
    at exports (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\node\utils\run_cmd.js:71:25)
    at exports (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\node\utils\run_npm.js:25:13)
    at Object.exports.getPackages (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\static\js\pluginfw\plugins.js:73:14)
    at Object.exports.update (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\static\js\pluginfw\plugins.js:56:34)
    at Object.exports.start (C:\Users\alexe\Downloads\etherpad-lite-develop-d7ed71e-2\etherpad-lite-develop\node_modules\ep_etherpad-lite\node\server.js:137:19)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)
[2021-02-17 13:57:27.943] [INFO] server - Exiting...

node_modules\ep_etherpad-lite\package.json was not modified by installing this plugin.

I'm just working out of a folder right now, no change control, so I can't see the entire delta of this action. Any ideas? I have to run to a meeting, but I can debug later this afternoon if the answer isn't obvious.

Yea this is due to the changes you made, 100%. I should be able to get @rhansen able to know the PR that broke the windows build.

For a clean windows build you can just use...

Enable developer options in Windows. < <<< < < < This is the temporary hack to get symlinks

then:

cd c:\
cd \
git clone https://github.com/ether/etherpad-lite.git
cd etherpad-lite
cd src
npm i --no-optionals
cd..
start.bat

I got symbolic links working on Windows 10 Pro, so those steps above work like a dream now. I've been fighting with an Azure deployment most of the afternoon and evening. I reached out to Microsoft for support (using the support hours that my employer has available) and I'll consolidate those notes for the wiki too. The conversation should be happening here: https://docs.microsoft.com/en-us/answers/questions/277739/deployment-of-etherpad-lite-an-open-source-nodejs.html

The patch for 1.8.8 is in and I'm going to be fixing import then releasing 1.8.9 tonight.

I'm making progress with Azure. It's now starting a workflow in Github to do a deployment. I'm running into an issue with the package.json file. I think it's looking for this file in the site root, but it's located in src.

Is it normal to have the packages.json in a non-root folder? Is this related to the bug fix you're working on?

Here's the relevant output of the workflow.

Run npm install
  npm install
  npm run build --if-present
  npm run test --if-present
  shell: C:\Program Files\PowerShell\7\pwsh.EXE -command ". '{0}'"
npm WARN saveError ENOENT: no such file or directory, open 'D:\a\accountname\webappname\package.json'
npm notice created a lockfile as package-lock.json. You should commit this file.
npm WARN enoent ENOENT: no such file or directory, open 'D:\a\accountname\webappname\package.json'

npm ERR! code ENOENT
npm ERR! syscall open
npm ERR! path D:\a\accountname\webappname\package.json
npm ERR! errno -4058
npm ERR! enoent ENOENT: no such file or directory, open 'D:\a\accountname\webappname\package.json'
npm ERR! enoent This is related to npm not being able to find a file.
npm ERR! enoent

Peep the windows ci branch. I'm working on it today

Awesome! I'll hit pause on my efforts until you give me the thumbs up. I'm probably running into issues that you're addressing now. Thank you so much for your help!

git clone
cd src && npm i && cd ..
node src/node/server.js <-- this is what you would set as the run script (whatever azure uses)

gimme a shout if that doesn't work

btw it's not normal to have the package.json in src/, It's due to how we use npm to install plugins etc. Can azure not handle that? :\

There is a wealth of conflicting information online about Node.js on Azure. I haven't found anything in the official documentation, but there are many stackoverflow and Q&A pages that mention that package.json has to be in the root. Let me give it a try this afternoon and I'll report the outcome.

Which branch should I be in at this point? Do you want me to stay in develop, main or switch to windows-server-ci?

develop

You can see the tests runner working fine on Microsoft Server there but IDK what Azure does different ;/ Myself and @rhansen just made it work on Microsoft infrastructure but from the sounds of things Azure does some specific things w/ NodeJS apps and sets certain expectations that we might not provide config for.. Do you wnat to jump on discord and we can see if we can figure it out in real time? Links on https://etherpad.org

Awesome! Up and running locally with a new folder using these commands:

mkdir etherpad-dev
cd etherpad-dev\etherpad-lite
git clone https://github.com/ether/etherpad-lite.git
cd src && npm i && cd ..
node src\node\server.js

At this point, I could load the site on localhost:9001.

Then I created a new repository in my personal Github, set the remote url, and checked in the latest.

git remote -v -- Confirm that it points to the official Etherpad-Lite repo
git remote set-url origin https://github.com/username/repo.git -- Update to point to my repo
git remote -v -- Confirm that it points to my repo
git add --all
git commit -m "initial"
git push

I have an Azure App Service set up with a Windows server. I'm using the Deployment Center to create a Github integration for CI/CD. It creates the connection to the Github repo fine and creates a .yml file in .github\workflows. The contents are below. This workflow is failing on the Github side.

# Docs for the Azure Web Apps Deploy action: https://github.com/Azure/webapps-deploy
# More GitHub Actions for Azure: https://github.com/Azure/actions

name: Build and deploy Node.js app to Azure Web App - mysite-etherpad

on:
  push:
    branches:
      - develop
  workflow_dispatch:

jobs:
  build-and-deploy:
    runs-on: windows-latest

    steps:
    - uses: actions/checkout@master

    - name: Set up Node.js version
      uses: actions/setup-node@v1
      with:
        node-version: '12.13.0'

    - name: npm install, build, and test
      run: |
        npm install
        npm run build --if-present
        npm run test --if-present

    - name: 'Deploy to Azure Web App'
      uses: azure/webapps-deploy@v2
      with:
        app-name: 'mysite-etherpad'
        slot-name: 'production'
        publish-profile: ${{ secrets.AzureAppService_PublishProfile_4fc8dd232ce24a5d9179defc7ba3fca6 }}
        package: .

This was failing because it couldn't find package.json. I modified three lines under name: npm install, build and test:

npm --prefix src install
npm --prefix src run build --if-present
# npm --prefix src run test --if-present

This still failed in Github workflow, but it wasn't a fatal error and the code was deployed to Azure.

Once in Azure, I had some web.config issues that I think I resolved by deleting the web.config. There were issues caused by duplicated iisnode nodes.

Now it appears to start running the server, but it stops without an error code and I'm returned an HTTP 500.1001 error: iisnode was unable to establish named pipe connection to the node.exe process. Below are the best logs I can find on the server. Any suggestions? I'm trying to get support from Azure again.

[36m[2021-02-17 20:38:22.572] [DEBUG] console - [39mRunning on Node v12.13.0 (minimum required Node version: 10.17.0)
[32m[2021-02-17 20:38:22.759] [INFO] console - [39mAll relative paths will be interpreted relative to the identified Etherpad base dir: C:\home\site\wwwroot
[32m[2021-02-17 20:38:22.759] [INFO] console - [39mRandom string used for versioning assets: b1e64664
[36m[2021-02-17 20:38:22.775] [DEBUG] AbsolutePaths - [39mRelative path "settings.json" can be rewritten to "C:\home\site\wwwroot\settings.json"
[36m[2021-02-17 20:38:22.791] [DEBUG] AbsolutePaths - [39mRelative path "credentials.json" can be rewritten to "C:\home\site\wwwroot\credentials.json"
[32m[2021-02-17 20:38:22.827] [INFO] console - [39msettings loaded from: C:\home\site\wwwroot\settings.json
[32m[2021-02-17 20:38:22.838] [INFO] console - [39mNo credentials file found in C:\home\site\wwwroot\credentials.json. Ignoring.
[32m[2021-02-17 20:38:22.838] [INFO] console - [39mUsing skin "colibris" in dir: C:\home\site\wwwroot\src\static\skins\colibris
[32m[2021-02-17 20:38:22.853] [INFO] console - [39mSession key loaded from: C:\home\site\wwwroot\SESSIONKEY.txt
[31m[2021-02-17 20:38:37.541] [ERROR] console - [39m(node:14704) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead.
[32m[2021-02-17 20:38:39.855] [INFO] runNpm - [39mnpm --version: 6.14.11

Oh wow you are getting far in! Good job.. So it looks like if it's stopped after version, it's not fully starting Etherpad..

after the line containing version after a few seconds you should get

[2021-02-18 21:38:07.061] [INFO] plugins - npm --version: 6.14.11
[2021-02-18 21:38:09.580] [INFO] plugins - Loading plugin ep_etherpad-lite...
[2021-02-18 21:38:09.583] [INFO] plugins - Loaded 1 plugins
[2021-02-18 21:38:10.027] [INFO] APIHandler - Api key file "C:\etherpad-lite\APIKEY.txt" not found.  Creating with random contents.
[2021-02-18 21:38:10.172] [INFO] server - Installed plugins:
[2021-02-18 21:38:10.189] [INFO] console - Report bugs at https://github.com/ether/etherpad-lite/issues
[2021-02-18 21:38:10.191] [INFO] console - Your Etherpad version is 1.8.9 (d5997dd)
[2021-02-18 21:38:11.944] [INFO] http - HTTP server listening for connections
[2021-02-18 21:38:11.945] [INFO] console - You can access your Etherpad instance at http://0.0.0.0:9001/
[2021-02-18 21:38:11.947] [WARN] console - Admin username and password not set in settings.json. To access admin please uncomment and edit "users" in settings.json
[2021-02-18 21:38:11.953] [WARN] console - Etherpad is running in Development mode. This mode is slower for users and less secure than production mode. You should set the NODE_ENV environment variable to production by using: export NODE_ENV=production
[2021-02-18 21:38:11.953] [INFO] server - Etherpad is running

Etherpad doesn't respect

npm --prefix src run build --if-present
npm --prefix src run test --if-present

remove these.. Unless you need to test before deployment, which would be weird??

This was failing because it couldn't find package.json.

Try this instead:

    - name: npm install, build, and test
      run: |
        cd src
        npm ci
        npm run build --if-present
        npm run test --if-present

it stops without an error code

Are you sure that it stops? The line in the log that says "runNpm - npm --version: 6.14.11" is printed just as Etherpad runs npm to discover installed plugins. The npm CLI is slow, so maybe it's just taking a while? It should take less than 60s to return.

If it is indeed stopping but the logs don't show anything, I wonder if it's a Windows-specific log buffering issue. Maybe the process is dying and Windows isn't flushing buffered writes so you can't see the printed error message.

Progress! Azure does not support symlinks. I copied src/bin to bin.

There is a development console available for the App Service via the Azure Portal. I used this console to manually run the server and I got the actual error logs:

[36m[2021-02-19 16:15:06.540] [DEBUG] console - [39mRunning on Node v12.13.0 (minimum required Node version: 10.17.0)
[32m[2021-02-19 16:15:06.697] [INFO] console - [39mAll relative paths will be interpreted relative to the identified Etherpad base dir: C:\home\site\wwwroot
[32m[2021-02-19 16:15:06.712] [INFO] console - [39mRandom string used for versioning assets: 43551526
[36m[2021-02-19 16:15:06.712] [DEBUG] AbsolutePaths - [39mRelative path "settings.json" can be rewritten to "C:\home\site\wwwroot\settings.json"
[36m[2021-02-19 16:15:06.712] [DEBUG] AbsolutePaths - [39mRelative path "credentials.json" can be rewritten to "C:\home\site\wwwroot\credentials.json"
[32m[2021-02-19 16:15:06.743] [INFO] console - [39msettings loaded from: C:\home\site\wwwroot\settings.json
[32m[2021-02-19 16:15:06.743] [INFO] console - [39mNo credentials file found in C:\home\site\wwwroot\credentials.json. Ignoring.
[32m[2021-02-19 16:15:06.762] [INFO] console - [39mUsing skin "colibris" in dir: C:\home\site\wwwroot\src\static\skins\colibris
[32m[2021-02-19 16:15:06.775] [INFO] console - [39mSession key loaded from: C:\home\site\wwwroot\SESSIONKEY.txt
[33m[2021-02-19 16:15:06.775] [WARN] console - [39mDirtyDB is used. This is not recommended for production. File location: C:\home\site\wwwroot\var\dirty.db
[33m[2021-02-19 16:15:06.775] [WARN] console - [39mThe settings file contains an empty string ("") for the "ip" parameter. The "port" parameter will be interpreted as the path to a Unix socket to bind at.
[32m[2021-02-19 16:15:13.275] [INFO] server - [39mStarting Etherpad...
[32m[2021-02-19 16:15:13.666] [INFO] plugins - [39mRunning npm to get a list of installed plugins...
[32m[2021-02-19 16:15:18.651] [INFO] plugins - [39mnpm --version: 6.14.11
[31m[2021-02-19 16:15:51.792] [ERROR] runCmd|npm - [39mnpm ERR! missing: ep_etherpad-lite@file:src, required by wwwroot
[31m[2021-02-19 16:15:51.792] [ERROR] runCmd|npm - [39mnpm ERR! missing: eslint@7.18.0, required by ep_etherpad-lite@file:src
[... Error logs trimmed by Alex ...]
[31m[2021-02-19 16:15:51.932] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: underscore@1.12.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\underscore
[31m[2021-02-19 16:15:51.932] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: unorm@1.4.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\unorm
[31m[2021-02-19 16:15:51.932] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: wtfnode@0.8.4 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\wtfnode
[31m[2021-02-19 16:15:51.948] [ERROR] server - [39mError occurred while starting Etherpad
[31m[2021-02-19 16:15:51.948] [ERROR] server - [39mError: Command exited with code 1: npm ls --long --json --depth=0 --no-production
    at exports (C:\home\site\wwwroot\src\node\utils\run_cmd.js:119:25)
    at Object.exports.getPackages (C:\home\site\wwwroot\src\static\js\pluginfw\plugins.js:93:48)
    at Object.exports.update (C:\home\site\wwwroot\src\static\js\pluginfw\plugins.js:67:34)
    at Object.exports.start (C:\home\site\wwwroot\src\node\server.js:140:19)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
[32m[2021-02-19 16:15:51.948] [INFO] server - [39mExiting...
[32m[2021-02-19 16:15:51.948] [INFO] server - [39mWaiting for Node.js to exit...

I tried to install the dependencies with npm i

cd src
npm i

Output:

npm WARN optional SKIPPING OPTIONAL DEPENDENCY: fsevents@2.1.3 (node_modules\fsevents):
npm WARN notsup SKIPPING OPTIONAL DEPENDENCY: Unsupported platform for fsevents@2.1.3: wanted {"os":"darwin","arch":"any"} (current: {"os":"win32","arch":"ia32"})

I ran server.js again. Same log entries: all modules are missing and then all modules are extraneous.

Browsing the folder structure via FTP, it looks like node_modules and src/node_modules are downloaded and available.

@alexeisenhart in your CI build, you can set src as the working folder and deploy that Azure along with the artifacts.

# File: .github/workflows/workflow.yml
name: JavaScript CI

on: [push]

env:
  AZURE_WEBAPP_NAME: my-app-name   # set this to your application's name
  AZURE_WEBAPP_PACKAGE_PATH: 'my-app-path'      # set this to the path to your web app project, defaults to the repository root
  NODE_VERSION: '14.x'                # set this to the node version to use

jobs:
  build-and-deploy:
    name: Build and Deploy
    runs-on: ubuntu-latest
    steps:
    - uses: actions/checkout@main
    - name: Use Node.js ${{ env.NODE_VERSION }}
      uses: actions/setup-node@v1
      with:
        node-version: ${{ env.NODE_VERSION }}
    - name: npm install, build, and test
      run: |
        # Build and test the project, then
        # deploy to Azure Web App.
        npm install
        npm run build --if-present
        npm run test --if-present
      working-directory: my-app-path
    - name: 'Deploy to Azure WebApp'
      uses: azure/webapps-deploy@v2
      with: 
        app-name: ${{ env.AZURE_WEBAPP_NAME }}
        publish-profile: ${{ secrets.AZURE_WEBAPP_PUBLISH_PROFILE }}
        package: ${{ env.AZURE_WEBAPP_PACKAGE_PATH }}

When your app is deployed, there should be a web.config generated for you. You don't want to delete this file because for Windows hosting environments, it uses this file to run iisnode to host your node app. Azure will do it's best to determine how to run your application through package.json but you can configure command this in the Configuration Settings blade or by running

The error you posted points to

500	1001	- Win32Error 0x2 - App is not responding to the URL. Check the URL rewrite rules or check if your express app has the correct routes defined. - Win32Error 0x6d – named pipe is busy – Node.exe is not accepting requests because the pipe is busy. Check high cpu usage. - Other errors – check if node.exe crashed.

If you removed the web.config, that could be the reason why. See https://docs.microsoft.com/en-us/azure/app-service/app-service-web-nodejs-best-practices-and-troubleshoot-guide#iisnode-http-status-and-substatus.

Hey @RyanHill-MSFT. Thanks for the info. The Node.JS best practices link is new to me, and that looks very useful. At this point I'm running into application issues that I think are related to the symlinks. I think setting src as the working folder won't work because NPM is used to manage plugins for this project as well.

@JohnMcLear, I mentioned in my last post that I has copied src/bin to bin, but I forgot about the symlink at node_moduels/ep_etherpad-lite. Since my last poste, I performed the following actions and I'm getting the same issue: all of the modules required by ep_etherpad-lite are both missing and extraneous. I'll paste the full log below.

Deleted `node_modules\ep_etherpad-lite`
Created a new folder at `node_modules\ep_etherpad-lite`
Copied the contents (recursively) of `src` into `node_modules\ep_etherpad-lite`
node src\node\server.js

Output of starting the server:

[36m[2021-02-19 18:01:06.186] [DEBUG] console - [39mRunning on Node v12.13.0 (minimum required Node version: 10.17.0)
[32m[2021-02-19 18:01:06.842] [INFO] console - [39mAll relative paths will be interpreted relative to the identified Etherpad base dir: C:\home\site\wwwroot
[32m[2021-02-19 18:01:06.842] [INFO] console - [39mRandom string used for versioning assets: aadf2fba
[36m[2021-02-19 18:01:06.858] [DEBUG] AbsolutePaths - [39mRelative path "settings.json" can be rewritten to "C:\home\site\wwwroot\settings.json"
[36m[2021-02-19 18:01:06.858] [DEBUG] AbsolutePaths - [39mRelative path "credentials.json" can be rewritten to "C:\home\site\wwwroot\credentials.json"
[32m[2021-02-19 18:01:06.889] [INFO] console - [39msettings loaded from: C:\home\site\wwwroot\settings.json
[32m[2021-02-19 18:01:06.889] [INFO] console - [39mNo credentials file found in C:\home\site\wwwroot\credentials.json. Ignoring.
[32m[2021-02-19 18:01:06.905] [INFO] console - [39mUsing skin "colibris" in dir: C:\home\site\wwwroot\src\static\skins\colibris
[32m[2021-02-19 18:01:06.924] [INFO] console - [39mSession key loaded from: C:\home\site\wwwroot\SESSIONKEY.txt
[33m[2021-02-19 18:01:06.924] [WARN] console - [39mDirtyDB is used. This is not recommended for production. File location: C:\home\site\wwwroot\var\dirty.db
[33m[2021-02-19 18:01:06.924] [WARN] console - [39mThe settings file contains an empty string ("") for the "ip" parameter. The "port" parameter will be interpreted as the path to a Unix socket to bind at.
[32m[2021-02-19 18:01:16.826] [INFO] server - [39mStarting Etherpad...
[32m[2021-02-19 18:01:16.967] [INFO] plugins - [39mRunning npm to get a list of installed plugins...
[32m[2021-02-19 18:01:26.144] [INFO] plugins - [39mnpm --version: 6.14.11
[31m[2021-02-19 18:01:51.439] [ERROR] runCmd|npm - [39mnpm ERR! missing: ep_etherpad-lite@file:src, required by wwwroot
[31m[2021-02-19 18:01:51.439] [ERROR] runCmd|npm - [39mnpm ERR! missing: eslint@7.18.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.439] [ERROR] runCmd|npm - [39mnpm ERR! missing: eslint-config-etherpad@1.0.24, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.439] [ERROR] runCmd|npm - [39mnpm ERR! missing: eslint-plugin-eslint-comments@3.2.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.439] [ERROR] runCmd|npm - [39mnpm ERR! missing: eslint-plugin-mocha@8.0.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: eslint-plugin-node@11.1.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: eslint-plugin-prefer-arrow@1.2.3, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: eslint-plugin-promise@4.2.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: eslint-plugin-you-dont-need-lodash-underscore@6.10.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: etherpad-cli-client@0.0.9, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: mocha@7.1.2, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: mocha-froth@0.2.10, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: set-cookie-parser@2.4.7, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: sinon@9.2.4, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: supertest@4.0.2, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: wd@1.12.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: async@3.2.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: async-stacktrace@0.0.2, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: channels@0.0.4, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: cheerio@0.22.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: clean-css@4.2.3, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: cookie-parser@1.4.5, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: cross-spawn@7.0.3, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: ejs@3.1.6, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: etherpad-require-kernel@1.0.9, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.453] [ERROR] runCmd|npm - [39mnpm ERR! missing: etherpad-yajsml@0.0.2, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: express@4.17.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: express-rate-limit@5.2.3, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: express-session@1.17.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: find-root@1.1.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: formidable@1.2.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: http-errors@1.8.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: js-cookie@2.2.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: jsonminify@0.4.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: languages4translatewiki@0.1.3, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: lodash.clonedeep@4.5.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: log4js@0.6.35, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: measured-core@1.51.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: mime-types@2.1.28, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: nodeify@1.0.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: npm@6.14.11, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: openapi-backend@2.4.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.472] [ERROR] runCmd|npm - [39mnpm ERR! missing: proxy-addr@2.0.6, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: rate-limiter-flexible@2.2.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: rehype@10.0.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: rehype-minify-whitespace@4.0.5, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: request@2.88.2, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: resolve@1.19.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: security@1.0.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: semver@5.7.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: socket.io@2.4.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: terser@4.8.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: threads@1.6.3, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: tiny-worker@2.3.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: tinycon@0.0.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: ueberdb2@1.2.5, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: underscore@1.12.0, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: unorm@1.4.1, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! missing: wtfnode@0.8.4, required by ep_etherpad-lite@file:src
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: eslint@7.18.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\eslint
[31m[2021-02-19 18:01:51.485] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: eslint-config-etherpad@1.0.24 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\eslint-config-etherpad
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: eslint-plugin-eslint-comments@3.2.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\eslint-plugin-eslint-comments
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: eslint-plugin-mocha@8.0.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\eslint-plugin-mocha
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: eslint-plugin-node@11.1.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\eslint-plugin-node
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: eslint-plugin-prefer-arrow@1.2.3 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\eslint-plugin-prefer-arrow
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: eslint-plugin-promise@4.2.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\eslint-plugin-promise
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: eslint-plugin-you-dont-need-lodash-underscore@6.10.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\eslint-plugin-you-dont-need-lodash-underscore
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: etherpad-cli-client@0.0.9 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\etherpad-cli-client
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: mocha@7.1.2 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\mocha
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: mocha-froth@0.2.10 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\mocha-froth
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: set-cookie-parser@2.4.7 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\set-cookie-parser
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: sinon@9.2.4 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\sinon
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: supertest@4.0.2 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\supertest
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: wd@1.12.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\wd
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: async@3.2.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\async
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: async-stacktrace@0.0.2 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\async-stacktrace
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: channels@0.0.4 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\channels
[31m[2021-02-19 18:01:51.503] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: cheerio@0.22.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\cheerio
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: clean-css@4.2.3 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\clean-css
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: cookie-parser@1.4.5 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\cookie-parser
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: cross-spawn@7.0.3 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\cross-spawn
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: ejs@3.1.6 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\ejs
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: etherpad-require-kernel@1.0.9 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\etherpad-require-kernel
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: etherpad-yajsml@0.0.2 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\etherpad-yajsml
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: express@4.17.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\express
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: express-rate-limit@5.2.3 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\express-rate-limit
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: express-session@1.17.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\express-session
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: find-root@1.1.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\find-root
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: formidable@1.2.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\formidable
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: http-errors@1.8.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\http-errors
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: js-cookie@2.2.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\js-cookie
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: jsonminify@0.4.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\jsonminify
[31m[2021-02-19 18:01:51.516] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: languages4translatewiki@0.1.3 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\languages4translatewiki
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: lodash.clonedeep@4.5.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\lodash.clonedeep
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: log4js@0.6.35 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\log4js
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: measured-core@1.51.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\measured-core
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: mime-types@2.1.28 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\mime-types
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: nodeify@1.0.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\nodeify
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: npm@6.14.11 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\npm
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: openapi-backend@2.4.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\openapi-backend
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: proxy-addr@2.0.6 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\proxy-addr
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: rate-limiter-flexible@2.2.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\rate-limiter-flexible
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: rehype@10.0.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\rehype
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: rehype-minify-whitespace@4.0.5 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\rehype-minify-whitespace
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: request@2.88.2 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\request
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: resolve@1.19.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\resolve
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: security@1.0.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\security
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: semver@5.7.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\semver
[31m[2021-02-19 18:01:51.532] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: socket.io@2.4.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\socket.io
[31m[2021-02-19 18:01:51.547] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: terser@4.8.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\terser
[31m[2021-02-19 18:01:51.547] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: threads@1.6.3 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\threads
[31m[2021-02-19 18:01:51.547] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: tiny-worker@2.3.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\tiny-worker
[31m[2021-02-19 18:01:51.547] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: tinycon@0.0.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\tinycon
[31m[2021-02-19 18:01:51.547] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: ueberdb2@1.2.5 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\ueberdb2
[31m[2021-02-19 18:01:51.547] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: underscore@1.12.0 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\underscore
[31m[2021-02-19 18:01:51.547] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: unorm@1.4.1 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\unorm
[31m[2021-02-19 18:01:51.547] [ERROR] runCmd|npm - [39mnpm ERR! extraneous: wtfnode@0.8.4 C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node_modules\wtfnode
[31m[2021-02-19 18:01:51.578] [ERROR] server - [39mError occurred while starting Etherpad
[31m[2021-02-19 18:01:51.578] [ERROR] server - [39mError: Command exited with code 1: npm ls --long --json --depth=0 --no-production
    at exports (C:\home\site\wwwroot\src\node\utils\run_cmd.js:119:25)
    at Object.exports.getPackages (C:\home\site\wwwroot\src\static\js\pluginfw\plugins.js:93:48)
    at Object.exports.update (C:\home\site\wwwroot\src\static\js\pluginfw\plugins.js:67:34)
    at Object.exports.start (C:\home\site\wwwroot\src\node\server.js:140:19)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
[32m[2021-02-19 18:01:51.578] [INFO] server - [39mExiting...
[32m[2021-02-19 18:01:51.578] [INFO] server - [39mWaiting for Node.js to exit...

@JohnMcLear made adjustments that resolve the symlink issues on Windows.

At this point, I trashed this deployment, emptied the file storage and started fresh with download of https://github.com/ether/etherpad-lite/releases/download/1.8.9/etherpad-lite-win.zip, which has adjustments to deal with the symlink issue.

curl https://github.com/ether/etherpad-lite/releases/download/1.8.9/etherpad-lite-win.zip -o etherpad.zip

I tried to issue this command via the Azure Console and the Kudu CMD Console, but it repeatedly downloaded only 625 bytes. I downloaded this zip file locally, transferred it to the server via SFTP and then tried to extract it with unzip etherpad.zip but this command seemed to timeout and the console reported "Failed to execute the command." So I had to extracted the zip locally and SFTP'd the entire deployment (some 22,000 files).

I had to play with the web.configs a bit, and I don't have that working yet. But, in the Development Console (in the Azure App Service Portal), I can start node server.js, and it loads successfully until it gets to ip / port binding errors, but I think the errors I'm running into are on the Azure side now.

@RyanHill-MSFT, below is the web.config that I have in the root of the site. The server file is located at wwwroot/node_modules/ep_etherpad-lite/node/server.js. Do you see any errors here? When I browse the site, the response from the server is The page cannot be displayed because an internal server error has occurred.

<configuration>
  <system.webServer>

    <handlers>
      <add name="iisnode" path="node_modules/ep_etherpad-lite/node/server.js" verb="*" modules="iisnode" />
    </handlers>

    <rewrite>
        <rules>
            <rule name="LogFile" patternSyntax="ECMAScript" stopProcessing="true">
                <match url="iisnode"/>
                <action type="Rewrite" url="node_modules/ep_etherpad-lite/node/iisnode" />
            </rule>
            <rule name="NodeInspector" patternSyntax="ECMAScript" stopProcessing="true">                    
                <match url="^server.js\/debug[\/]?" />
            </rule>

            <rule name="StaticContent">
                 <action type="Rewrite" url="public{{REQUEST_URI}}"/>
            </rule>
            <rule name="DynamicContent">
                 <conditions>
                      <add input="{{REQUEST_FILENAME}}" matchType="IsFile" negate="True"/>
                 </conditions>
                <action type="Rewrite" url="node_modules/ep_etherpad-lite/node/server.js" />
            </rule>
        </rules>
    </rewrite>

  </system.webServer>
</configuration>

I monitor the log using Kudo and HTTP 500.1001 is now returned. The requested url is https://sitename:80/node_modules/ep_etherpad-lite/node/server.js, so that's good. When I run the server manually with a node command on Kudo, it takes about 45 seconds to start up (with no binding issues). It might be timing out on the Azure server? I'm not sure because I don't see any other more detailed log errors.

This application seems to require the port to be configured in a settings.json file. How can I determine which port I need to bind to? Is the port fixed?

@RyanHill-MSFT, I think port binding is possibly the issue. From the best practices article that you shared, it recommends using process.env.PORT to find the port. I am not familiar with the code base, but it looks like this property is used correctly.

/**
 * The IP ep-lite should listen to
 */
exports.ip = '0.0.0.0';

/**
 * The Port ep-lite should listen to
 */
exports.port = process.env.PORT || 9001;

It looks like it's trying to bind to whatever value I have in the settings file, which I assume means that process.env.PORT is returning null?

Here are some sample log files. Default port of 9001.

[32m[2021-02-19 22:07:08.535] [INFO] console - [39mYour Etherpad version is 1.8.9 ()
[31m[2021-02-19 22:07:14.083] [ERROR] server - [39mError: listen EADDRINUSE: address already in use 0.0.0.0:9001
    at Server.setupListenHandle [as _listen2] (net.js:1316:16)
    at listenInCluster (net.js:1364:12)
    at doListen (net.js:1501:7)
    at processTicksAndRejections (internal/process/task_queues.js:85:21)
[31m[2021-02-19 22:07:14.191] [ERROR] server - [39mTypeError: Promise resolve or reject function is not callable
    at Promise.then (<anonymous>)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)
[31m[2021-02-19 22:07:14.191] [ERROR] server - [39mError occurred while waiting to exit. Forcing an immediate unclean     exit...

And I tried binding to 80, just in case there was some sort of port redirection happening.

[32m[2021-02-19 22:08:46.175] [INFO] console - [39mYour Etherpad version is 1.8.9 ()
[31m[2021-02-19 22:08:51.113] [ERROR] server - [39mError: listen EACCES: permission denied 0.0.0.0:80
    at Server.setupListenHandle [as _listen2] (net.js:1299:21)
    at listenInCluster (net.js:1364:12)
    at doListen (net.js:1501:7)
    at processTicksAndRejections (internal/process/task_queues.js:85:21)
[31m[2021-02-19 22:08:51.113] [ERROR] server - [39mTypeError: Promise resolve or reject function is not callable
    at Promise.then (<anonymous>)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)
[31m[2021-02-19 22:08:51.113] [ERROR] server - [39mError occurred while waiting to exit. Forcing an immediate unclean exit...

exports.port = process.env.PORT || 9001;
It looks like it's trying to bind to whatever value I have in the settings file, which I assume means that process.env.PORT is returning null?

That line sets the default value. The default is overridden by whatever you have in your settings.json file. To use the PORT environment variable, comment out port in your settings.json.

@rhansen Thanks for the idea. I thought I tried that already, but I just retested. I commented out the port line from settings.json. Trying to load the site via a web browser gives me the same HTTP 500.1001 error. Running the sever with node via the console shows that it's trying to bind to 9001.

Running the sever with node via the console shows that it's trying to bind to 9001.

What is the value of the PORT environment variable? I'm not familiar with Windows shells, but on POSIX systems you can run echo $PORT to check.

runCmd|npm - [39mnpm ERR! missing: ep_etherpad-lite@file:src, required by wwwroot

This indicates that you somehow ended up with a package.json and/or package-lock.json in the top level of your Etherpad directory. What version of npm are you using (npm --version)? If npm v7, please try npm v6 (which comes with node v14).

exports.port = process.env.PORT || 9001;

You'll still want this line for local development. When you deploy your app to Azure, the worker will set the environment variable which your app can access from process.env.PORT which will bind to 80. If you elect to remove || 9001, make sure you've added PORT as a local environment variable. I personally never seen settings.json used in node apps, are you reading it in like https://codeburst.io/node-js-best-practices-smarter-ways-to-manage-config-files-and-variables-893eef56cbef?

I would also delete that package-lock.json from your git repo if that file is causing that 39mnpm ERR. Normally, that file isn't included in source control.

Thanks @RyanHill-MSFT and @rhansen!

I deleted node_modules\ep_etherpad-lite\package-lock.json. No change. I don't see a package.json nor a package-lock.json in the wwwroot, wwwroot/node_modules, nor wwwroot/node_modules/ep_etherpad-lite.

It looks like env can be used to print all environment variables, but I don't see a value for port.

I don't see any other environment variables that contain the phrase port, but variables related to Jetty and Tomcat both reference %HTTP_PLATFORM_PORT%, though I don't see that assigned in the list.

AZURE_JETTY93_CMDLINE=-Djava.net.preferIPv4Stack=true -Djetty.port=%HTTP_PLATFORM_PORT% -Djetty.base="D:\Program Files (x86)\jetty-distribution-9.3.25.v20180904" -Djetty.webapps="d:\home\site\wwwroot\webapps" -jar "D:\Program Files (x86)\jetty-distribution-9.3.25.v20180904\start.jar" etc\jetty-logging.xml

I tried modifying Settings.js, so that the line reads as follows, just in case Azure adds the port environment variable at runtime, but no change.

exports.port = process.env.PORT; // || 9001;`

I'm using npm version 6.12.0.

@RyanHill-MSFT, I'm accessing logs in 3 different ways. Are they all valid?

Load the site in a web browser, and watch the logs in the Azure Admin Portal -> Log Stream.
Load the site in a web browser, and watch the logs in the Kudu log stream https://sitename.scm.azurewebsites.net/api/logstream
Open the Console in the Azure Admin Portal and manually execute the server node server.js.

I think 1 and 2 are identical, but they do not display the full runtime logging from server.js. It hits a point in execution and then the HTTP 500.1001 is returned and the remaining logs are lost... perhaps the buffer isn't being flushed?

I've used method 3 to get more complete logging, but I'm concerned that when it comes to port binding that this might not be a valid test case, since some other hosting process might be listening on the port already?

EDIT: Ah, I had my streams crossed a bit. The error message that implies the existing of an extra package.json or package-lock.json is from a previous installation. I replaced that deployment with a fresh extraction of etherpad-lite-win.zip a few messages back, before we started talking about the port binding. So, I just redeployed the package-lock.json that I mentioned deleting earlier in this message.

@RyanHill-MSFT Would you recommend that I delete the App Service and start with a fresh one?

@RyanHill-MSFT, I'm accessing logs in 3 different ways. Are they all valid?

Load the site in a web browser, and watch the logs in the Azure Admin Portal -> Log Stream.

Load the site in a web browser, and watch the logs in the Kudu log stream https://sitename.scm.azurewebsites.net/api/logstream .

Open the Console in the Azure Admin Portal and manually execute the server node server.js.

I think 1 and 2 are identical, but they do not display the full runtime logging from server.js. It hits a point in execution and then the HTTP 500.1001 is returned and the remaining logs are lost... perhaps the buffer isn't being flushed?

All sources are valid @alexeisenhart and you are correct in that 1 and 2 are the same logging sources.

I've used method 3 to get more complete logging, but I'm concerned that when it comes to port binding that this might not be a valid test case, since some other hosting process might be listening on the port already?

I recommend accessing your log files via https://<>.scm.azurewebsites.net/api/vfs/LogFiles/. This where output from the log stream as well as worker related log files are stored. Depending on your hosting environment though, available log files will be different.

@RyanHill-MSFT Would you recommend that I delete the App Service and start with a fresh one?

Redeploying your application will overwrite your app code. If package.json isn't there, double check your artifacts from your CI/CD. Just to verify, your app is hosted in Windows right?

@RyanHill-MSFT, thanks, that's good to hear! How would you recommend that I proceed? I personally don't have any customizations other than settings changes, btw. package.json and package-lock.json both appear to be in the correct place. At this point I don't have any deployment issues; I'm struggling to get the site to load.

I have two issues:

HTTP 500.1001 when I load the site in a web browser. There are no errors logged in the Log Stream. I don't know why this error is happening and everything works locally with the same code and configuration.
When I manually run server.js in the Console, it fails with port binding errors. How should I tackle this?

EDIT: Yes, I'm using a Windows server. EDIT: I could do a screenshare or we could use an IM platform if that would be easier than commenting here.

Don't run server.js manually in the Console. I don't think that will get your anywhere. Enable all your logging, no need to hook Azure Monitor right now, and redeploy everything starting fresh. Add loggingeEnabled=true to <iisnode ... /> in web.config. Check your deployment logs for any errors or warnings. If all is good there, then check application logs for any errors during app startup.

Thanks @RyanHill-MSFT! Quick question: the application logs which version of NPM is being used. It logs version 1.1.37 (you can see this in the logs below). When I check the version via the Console, it reports version 6.12.0. Do you have any insight here? Where would NPM 1.1.37 be coming from? I've recorded my actions, the logs, and the web.config below.

I redeployed the site. The application ships a web.config in a subfolder: I deleted node_modules/ep_etherpad-lite/web.config.

Here's the web.config in the site root:

<configuration>
  <system.webServer>

    <handlers>
      <add name="iisnode" path="node_modules/ep_etherpad-lite/node/server.js" verb="*" modules="iisnode" />
    </handlers>

    <rewrite>
        <rules>
            <rule name="LogFile" patternSyntax="ECMAScript" stopProcessing="true">
                <match url="iisnode"/>
                <action type="Rewrite" url="node_modules/ep_etherpad-lite/node/iisnode" />
            </rule>
            <rule name="NodeInspector" patternSyntax="ECMAScript" stopProcessing="true">                    
                <match url="^server.js\/debug[\/]?" />
            </rule>

            <rule name="StaticContent">
                 <action type="Rewrite" url="public{{REQUEST_URI}}"/>
            </rule>
            <rule name="DynamicContent">
                 <conditions>
                      <add input="{{REQUEST_FILENAME}}" matchType="IsFile" negate="True"/>
                 </conditions>
                <action type="Rewrite" url="node_modules/ep_etherpad-lite/node/server.js" />
            </rule>
        </rules>
    </rewrite>

    <iisnode node_env="%node_env%"
        nodeProcessCountPerApplication="1"
        maxConcurrentRequestsPerProcess="1024"
        maxNamedPipeConnectionRetry="100"
        namedPipeConnectionRetryDelay="250"
        maxNamedPipeConnectionPoolSize="512"
        maxNamedPipePooledConnectionAge="30000"
        asyncCompletionThreadCount="0"
        initialRequestBufferSize="4096"
        maxRequestBufferSize="65536"
        uncFileChangesPollingInterval="5000"
        gracefulShutdownTimeout="60000"
        loggingEnabled="true"
        logDirectory="iisnode"
        debuggingEnabled="true"
        debugHeaderEnabled="false"
        debuggerPortRange="5058-6058"
        debuggerPathSegment="debug"
        maxLogFileSizeInKB="128"
        maxTotalLogFileSizeInKB="1024"
        maxLogFiles="20"
        devErrorsEnabled="true"
        flushResponse="false"
        enableXFF="false"
        promoteServerVars=""
        configOverrides="iisnode.yml"
        watchedFiles="web.config;*.js"
        nodeProcessCommandLine="C:\home\site\wwwroot\node.exe"
        />

  </system.webServer>
</configuration>

I didn't understand the purpose of <iisnode> before, so this has definitely helped! I used the above configuration and got these results:

[36m[2021-02-22 16:46:13.395] [DEBUG] console - [39mRunning on Node v12.20.2 (minimum required Node version: 10.17.0)
[36m[2021-02-22 16:46:13.613] [DEBUG] AbsolutePaths - [39mC:\home\site\wwwroot\node_modules\ep_etherpad-lite does not end with "src"
[32m[2021-02-22 16:46:13.613] [INFO] console - [39mAll relative paths will be interpreted relative to the identified Etherpad base dir: C:\home\site\wwwroot
[32m[2021-02-22 16:46:13.629] [INFO] console - [39mRandom string used for versioning assets: c3a38752
[36m[2021-02-22 16:46:13.645] [DEBUG] AbsolutePaths - [39mRelative path "settings.json" can be rewritten to "C:\home\site\wwwroot\settings.json"
[36m[2021-02-22 16:46:13.645] [DEBUG] AbsolutePaths - [39mRelative path "credentials.json" can be rewritten to "C:\home\site\wwwroot\credentials.json"
[32m[2021-02-22 16:46:13.676] [INFO] console - [39msettings loaded from: C:\home\site\wwwroot\settings.json
[32m[2021-02-22 16:46:13.692] [INFO] console - [39mNo credentials file found in C:\home\site\wwwroot\credentials.json. Ignoring.
[32m[2021-02-22 16:46:13.707] [INFO] console - [39mUsing skin "colibris" in dir: C:\home\site\wwwroot\src\static\skins\colibris
[32m[2021-02-22 16:46:13.723] [INFO] console - [39mSession key loaded from: C:\home\site\wwwroot\SESSIONKEY.txt
[33m[2021-02-22 16:46:13.738] [WARN] console - [39mDirtyDB is used. This is not recommended for production. File location: C:\home\site\wwwroot\var\dirty.db
[31m[2021-02-22 16:46:23.754] [ERROR] console - [39m(node:34760) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead.
[32m[2021-02-22 16:46:25.004] [INFO] runNpm - [39mnpm --version: 1.1.37

In the browser, this was returned:

iisnode encountered an error when processing the request.

HRESULT: 0x2
HTTP status: 500
HTTP subStatus: 1001
HTTP reason: Internal Server Error

You are receiving this HTTP 200 response because system.webServer/iisnode/@devErrorsEnabled configuration setting is 'true'.

In addition to the log of stdout and stderr of the node.exe process, consider using debugging and ETW traces to further diagnose the problem.

The node.exe process has not written any information to stderr or iisnode was unable to capture this information. Frequent reason is that the iisnode module is unable to create a log file to capture stdout and stderr output from node.exe. Please check that the identity of the IIS application pool running the node.js application has read and write access permissions to the directory on the server where the node.js application is located. Alternatively you can disable logging by setting system.webServer/iisnode/@loggingEnabled element of web.config to 'false'.

I increased the maxNamedPipeConnectionRetry to 1000 and refreshed the browser. The browser returned a 500 error this time.

500 - The request timed out. The web server failed to respond within the specified time.

Server side, I have the same application logs that stop at the same entry.

[36m[2021-02-22 16:37:39.663] [DEBUG] console - [39mRunning on Node v12.20.2 (minimum required Node version: 10.17.0)
[36m[2021-02-22 16:37:39.851] [DEBUG] AbsolutePaths - [39mC:\home\site\wwwroot\node_modules\ep_etherpad-lite does not end with "src"
[32m[2021-02-22 16:37:39.866] [INFO] console - [39mAll relative paths will be interpreted relative to the identified Etherpad base dir: C:\home\site\wwwroot
[32m[2021-02-22 16:37:39.882] [INFO] console - [39mRandom string used for versioning assets: 0adb147c
[36m[2021-02-22 16:37:39.898] [DEBUG] AbsolutePaths - [39mRelative path "settings.json" can be rewritten to "C:\home\site\wwwroot\settings.json"
[36m[2021-02-22 16:37:39.913] [DEBUG] AbsolutePaths - [39mRelative path "credentials.json" can be rewritten to "C:\home\site\wwwroot\credentials.json"
[32m[2021-02-22 16:37:39.960] [INFO] console - [39msettings loaded from: C:\home\site\wwwroot\settings.json
[32m[2021-02-22 16:37:39.976] [INFO] console - [39mNo credentials file found in C:\home\site\wwwroot\credentials.json. Ignoring.
[32m[2021-02-22 16:37:39.992] [INFO] console - [39mUsing skin "colibris" in dir: C:\home\site\wwwroot\src\static\skins\colibris
[32m[2021-02-22 16:37:40.007] [INFO] console - [39mSession key loaded from: C:\home\site\wwwroot\SESSIONKEY.txt
[33m[2021-02-22 16:37:40.023] [WARN] console - [39mDirtyDB is used. This is not recommended for production. File location: C:\home\site\wwwroot\var\dirty.db
[31m[2021-02-22 16:37:50.304] [ERROR] console - [39m(node:37536) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead.
[32m[2021-02-22 16:37:51.570] [INFO] runNpm - [39mnpm --version: 1.1.37

@JohnMcLear It seems like it's still hanging up with trying to load the ep_etherpad-lite plugin. As you mentioned above, the logs should look like the following, but it's hanging after logging the npm version. I mentioned to Ryan above that the logs indicate NPM version 1.1.37, but when I check the version via the Console, it reports version 6.12.0. Do you think that if the application is really using version 1.1.37 that this could cause a timeout or silent crash or something in Etherpad?

**SAMPLE LOGS** -- not from the server
[2021-02-18 21:38:07.061] [INFO] plugins - npm --version: 6.14.11
[2021-02-18 21:38:09.580] [INFO] plugins - Loading plugin ep_etherpad-lite...
[2021-02-18 21:38:09.583] [INFO] plugins - Loaded 1 plugins

The environment variables indicate that the NPM path is 6.12.0

@JohnMcLear Is there any chance that Etherpad doesn't work well if multiple NPM versions are installed? It looks like the runtime is maybe grabbing the first version found?

@alexeisenhart, just set your node version to whatever your app need.

Hey @RyanHill-MSFT and @JohnMcLear

Long story short, I think Etherpad is grabbing the wrong NPM version in Azure.

I was deploying the node.exe that was shipped in the Etherpad Windows zip release. The web.config was directing Etherpad uses this node.exe (nodeProcessCommandLine="C:\home\site\wwwroot\node.exe") so the version reported at start up is correct (Node v12.20.2). However I noticed in the logs that it's loading NPM 1.1.37.

Now, I deleted node.exe from the site root and removed the nodeProcessCommandLine attribute from the web.config.

Which version of Node is being used? v12.13.0

Etherpad is reporting Running on Node v12.13.0.
node -- version reports v12.13.0
env shows WEBSITE_NODE_DEFAULT_VERSION=12.13.0

Which version of NPM is being used? MIXED

Etherpad is reporting npm --version: 1.1.37.
npm --version reports 6.12.0
package.json indicates 6.14.11 (if that is relevant)

Node seems to be good, but NPM is not. Ryan, how is the NPM version in Azure assigned?

Sorry, haven't had time to respond to this tomorrow my time but will reply tomorrow early GMT :)

Okay, so having such an old version of npm being used is never going to work, that needs resolving. Thankfully Etherpad has a way of specifying which version of npm to use.

https://github.com/ether/etherpad-lite/blob/develop/src/package.json#L57

So is it the case that azure is disregarding this setting? If so, why? Does your package.json line 57 read the same?

Are symlinks / mklink 100% out of the options for azure? It feels like something that would be sort of important for most deployments but what do I know..

Hey @JohnMcLear. Yeah, I was confused too. My package.json indicates the same version. My only thought was that having multiple node installations in program files would introduce an error at runtime with resolving the NPM version.

@RyanHill-MSFT what are your thoughts to John’s questions?

@JohnMcLear To directly answer your question, I tried to give an outline of the versions in my previous post, but here it is again (this is a long thread!).

Configuration: package.json indicates npm version 6.14.11
NPM in Console: npm --version reports 6.12.0
Runtime: Etherpad is reporting via logs: "npm --version: 1.1.37."

I don't know why the runtime is using this old version. This version is available in Program Files (x86). It is the first version when sorted alphanumerically, so I wondered if there might be a bug in Etherpad that would cause Etherpad to select the wrong version in some way?

Here's someone who's had a similar issue but there was no resolution: https://stackoverflow.com/questions/64571262/azure-appservice-not-using-correct-version-of-npm-when-using-child-process

I updated npm npm install -g npm and now npm --version reports 7.5.6. Earlier in this conversation, there was some concern that there might be issues running Etherpad on 7.x versions, but putting that aside, runtime is still reporting npm version 1.1.37.

I'm going to delete this Azure App Service, create a new one and document exactly what what I'm configuring. Maybe I'm missing something.

Uh oh, so I bet npm ls is using the incorrect npm package.. Yea, npm install -g npm wont change anything btw, you will need to update the npm package within package.json..

I have an idea, do you know the absolute path to the correct npm executable that you want to target in azure? To prove my theory we could manually modify the npm -ls calls to use an absolute executable path. It wont solve the problem but if we can show that azure's process.exec is spawning old versions of npm then there is every likelihood that the infosec community are gonna be interested in that 👯‍♀️

Wait.. https://github.com/ether/etherpad-lite/blob/develop/src/static/js/pluginfw/plugins.js#L17 - is where it's showing version..

replace npm with an absolute path IE \program files x86\npm\6.9.0\npm or whatever is the correct path.

This post is multi-purpose: it documents for support purposes for the Microsoft team supporting my debugging, it details reproduction steps for the Etherpad team, and it's here for posterity for future implementers in my shoes.

I deleted my App Service and I'm starting with a clean and fresh slate, so all above posts by me are not relevant to the contents detailed below.

Create Azure Windows App Service

Set up Etherpad Lite on Local Machine

Download the latest Windows Prebuilt Package of Etherpad Lite from https://github.com/ether/etherpad-lite/releases/download/1.8.9/etherpad-lite-win.zip.
Extracted this zip.
Run cmd with admin credentials then run start.bat. Confirm that it starts without issues and navigate to localhost:9001 in a web browser to confirm that the site loads locally (it works on my Windows 10 Pro desktop).

Prepare for Azure Deployment using SFTP.

Remove:

node_modules\ep_etherpad-lite\web.config
src\web.config
node.exe from the site root.

Create a new web.config in the site root. Contents:

<configuration>
  <system.webServer>

    <handlers>
      <add name="iisnode" path="node_modules/ep_etherpad-lite/node/server.js" verb="*" modules="iisnode" />
    </handlers>

    <rewrite>
        <rules>
            <rule name="LogFile" patternSyntax="ECMAScript" stopProcessing="true">
                <match url="iisnode"/>
                <action type="Rewrite" url="node_modules/ep_etherpad-lite/node/iisnode" />
            </rule>
            <rule name="NodeInspector" patternSyntax="ECMAScript" stopProcessing="true">                    
                <match url="^server.js\/debug[\/]?" />
            </rule>

            <rule name="StaticContent">
                 <action type="Rewrite" url="public{{REQUEST_URI}}"/>
            </rule>
            <rule name="DynamicContent">
                 <conditions>
                      <add input="{{REQUEST_FILENAME}}" matchType="IsFile" negate="True"/>
                 </conditions>
                <action type="Rewrite" url="node_modules/ep_etherpad-lite/node/server.js" />
            </rule>
        </rules>
    </rewrite>

    <iisnode node_env="%node_env%"
        nodeProcessCountPerApplication="1"
        maxConcurrentRequestsPerProcess="1024"
        maxNamedPipeConnectionRetry="100"
        namedPipeConnectionRetryDelay="250"
        maxNamedPipeConnectionPoolSize="512"
        maxNamedPipePooledConnectionAge="30000"
        asyncCompletionThreadCount="10"
        initialRequestBufferSize="4096"
        maxRequestBufferSize="65536"
        uncFileChangesPollingInterval="5000"
        gracefulShutdownTimeout="60000"
        loggingEnabled="true"
        logDirectory="iisnode"
        debuggingEnabled="true"
        debugHeaderEnabled="false"
        debuggerPortRange="5058-6058"
        debuggerPathSegment="debug"
        maxLogFileSizeInKB="128"
        maxTotalLogFileSizeInKB="1024"
        maxLogFiles="20"
        devErrorsEnabled="true"
        flushResponse="true"
        enableXFF="false"
        promoteServerVars=""
        configOverrides="iisnode.yml"
        watchedFiles="web.config;*.js"

        />

  </system.webServer>
</configuration>

Deploy the site to the new Azure App Service. I used SFTP. Get the credentials from the Deployment Center.

...wait for all 24,000 files to upload. There are faster ways to deploy the site, and you should set that up in the future, but this has fewer moving parts.

Attempt to Load the Azure site

Navigate to the public URL of the Azure App Service (https://yoursite.azurewebsites.net/) and try to load the site. In my case it does not load and this error is reported:

The page cannot be displayed because an internal server error has occurred.

To see more detailed error messages, enable the Application Service Logs.

Load https://yoursite.scm.azurewebsites.net/api/logstream to view the application service logs. This is a live stream, so reload your site after loading this page.

My issue was that there was a 2nd web.config in a child folder that I forgot to delete. I amended the notes above, so you didn't forget to delete it =)

My log was HTTP Error 500.19 - Internal Server Error and Cannot add duplicate collection entry of type 'add' with unique key attribute 'name' set to 'iisnode'. Deleting the extra web.config fixed that issue for me.

At this point refreshing the site gives me this error:

iisnode encountered an error when processing the request.

HRESULT: 0x2
HTTP status: 500
HTTP subStatus: 1001
HTTP reason: Internal Server Error

You are receiving this HTTP 200 response because system.webServer/iisnode/@devErrorsEnabled configuration setting is 'true'.

In addition to the log of stdout and stderr of the node.exe process, consider using debugging and ETW traces to further diagnose the problem.

The node.exe process has not written any information to stderr or iisnode was unable to capture this information. Frequent reason is that the iisnode module is unable to create a log file to capture stdout and stderr output from node.exe. Please check that the identity of the IIS application pool running the node.js application has read and write access permissions to the directory on the server where the node.js application is located. Alternatively you can disable logging by setting system.webServer/iisnode/@loggingEnabled element of web.config to 'false'.

And the logs indicate a silent failure after this log entry:

[INFO] runNpm - [39 npm --version: 1.1.37

The correct version of NPM is not being used.

What Version of Node is configured for Azure?

Use the Configuration page in the Azure portal to view the version of Node that is configured. Look for the WEBSITE_NODE_DEFAULT_VERSION key. If it doesn't exist, add it. Do not include a v at the start of the version string.

Following the above steps gives me version 12.13.0.

What Version of Node and NPM is Azure Using?

Use the Console page in the Azure portal to get access to a console.

node --version will tell you which version of node Azure is currently using. I have v12.13.0.
npm --version will tell you which version of npm Azure is currently using. I have 6.12.0.

What Version of Node and NPM is Etherpad Using?

Load https://yoursite.scm.azurewebsites.net/api/logstream to view the logs created by Etherpad. This is a live stream, so reload your site after loading this page.

In these logs you should find two entries. Here's what I get:

[DEBUG] console - [39mRunning on Node v12.13.0 (minimum required Node version: 10.17.0)
[...]
[INFO] runNpm - [39mnpm --version: 1.1.37

ether / etherpad-lite