Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
alexeisenhart opened this issue Feb 17, 2021 · 83 comments · Fixed by #4901
Closed

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

alexeisenhart opened this issue Feb 17, 2021 · 83 comments · Fixed by #4901

Comments

@alexeisenhart
Copy link

alexeisenhart commented Feb 17, 2021

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...
  1. 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

  1. I downloaded changeset d7ed71e from the develop branch.
  2. Executed InstallOnWindows.bat (no reported errors).
  3. Executed start.bat and the above error was reported.
@alexeisenhart
Copy link
Author

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.

@rhansen
Copy link
Member

rhansen commented Feb 17, 2021

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.

@alexeisenhart
Copy link
Author

alexeisenhart commented Feb 17, 2021

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.

  1. Extracted a fresh copy of changeset d7ed71e.
  2. Deleted node_modules\ep_etherpad-lite
  3. Created a new folder at node_modules\ep_etherpad-lite
  4. Moved the contents (recursively) of src into node_modules\ep_etherpad-lite. Delete src.
  5. Ran InstallOnWindows.bat.
  6. Modified start.bat to be node node_modules\ep_etherpad-lite\node\server.js.
  7. 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!

@alexeisenhart
Copy link
Author

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');

@JohnMcLear
Copy link
Member

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

@JohnMcLear
Copy link
Member

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

@alexeisenhart
Copy link
Author

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?

@JohnMcLear
Copy link
Member

yep, ty :)

@alexeisenhart
Copy link
Author

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.

@JohnMcLear
Copy link
Member

JohnMcLear commented Feb 17, 2021

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

@alexeisenhart
Copy link
Author

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

@JohnMcLear
Copy link
Member

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

@alexeisenhart
Copy link
Author

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 

@JohnMcLear
Copy link
Member

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

@alexeisenhart
Copy link
Author

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!

@JohnMcLear
Copy link
Member

JohnMcLear commented Feb 18, 2021

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? :\

@alexeisenhart
Copy link
Author

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?

@JohnMcLear
Copy link
Member

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

@alexeisenhart
Copy link
Author

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

@JohnMcLear
Copy link
Member

JohnMcLear commented Feb 18, 2021

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??

@rhansen
Copy link
Member

rhansen commented Feb 18, 2021

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.

@alexeisenhart
Copy link
Author

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.

@alexeisenhart
Copy link
Author

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

@RyanHill-MSFT
Copy link

@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.

@alexeisenhart
Copy link
Author

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...

@alexeisenhart
Copy link
Author

@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?

@alexeisenhart
Copy link
Author

alexeisenhart commented Feb 19, 2021

@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...

@rhansen
Copy link
Member

rhansen commented Feb 19, 2021

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.

@alexeisenhart
Copy link
Author

@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.

@alexeisenhart
Copy link
Author

I just realized that npm version 1.1.37 is in the c:\program files (x86)\nodejs! I don't have access to rename it. That might be related.

@alexeisenhart
Copy link
Author

Hey @RyanHill-MSFT. Can you help here? I'm not getting the right NPM version at runtime. Where is NPM

NPM Versions:

  1. env shows NPM_JS_PATH=C:\Program Files (x86)\npm\6.12.0\node_modules\npm\bin\npm-cli.js
  2. npm --version shows 6.12.0.
  3. "C:\Program Files (x86)\npm\6.12.0\node_modules\npm\bin\npm-cli.js" --version gives no output.
  4. "c:\program files (x86)\nodejs\npm" --version is 1.1.37.

Where is NPM 6.12.0 located?

@rhansen
Copy link
Member

rhansen commented Feb 24, 2021

Please enable DEBUG logging in your settings.json and paste the PATH that it logs (and surrounding lines). Edit: I just found and fixed a bug in that line; see PR #4854. You will have to manually apply the fix to your node_modules\ep_etherpad-lite\node\utils\run_cmd.js file. Edit 2: See the next post for a link to a new etherpad-lite-win.zip.

Etherpad attempts to run the npm executable that should be in the .zip file at src\node_modules\.bin\npm. It does that by adding that .bin directory to the front of the PATH environment variable. That is failing for reasons that are not yet understood; Windows is instead finding and running npm from a bizarrely different directory (1.1.37).

@rhansen
Copy link
Member

rhansen commented Feb 24, 2021

@JohnMcLear I just realized that there might be a problem with the way we build the Windows zip. We run src/bin/buildForWindows.sh on a Linux or MacOS system, which means that the npm script at src\node_modules\.bin\npm is OK for Linux and MacOS systems but probably not for Windows.

I updated our CI to build a Windows zip on Windows. @alexeisenhart Try downloading the etherpad-lite-win.zip artifact from this page: https://github.com/ether/etherpad-lite/actions/runs/594903463 (Unfortunately it's a zip within a zip due to the way GitHub artifacts work.)

@alexeisenhart
Copy link
Author

alexeisenhart commented Feb 24, 2021

@JohnMcLear Progress on the Azure side. I'm loading the correct version of NPM at runtime now (6.12.0), but Etherpad is still silently failing after it logs the npm version. I turned on debug logging, but nothing significant showed up in the log files.

What happens after the npm version is printed? I don't have any plugins installed. Could it be a permissions issue? Does it create folder if it doesn't exist or something like that?

When I run locally, the order of the log entries is different. For example, locally I have "Starting Etherpad..." logged before "npm --version: 6.14.11", however on Azure I see the npm version log, but I do not see "Starting Etherpad...". Similarly, locally I see "Running npm to get a list of installed plugins..." after "Starting Etherpad..." and before "npm --version" is logged, but I don't see "Running npm to get a list of installed plugins..." on the server either.

I assume this is due to asynchronous threads, but is there a clue in this? I'm trying to trace through the code while adding new log entries to find where it's breaking down. I know you're out today, but I'd be open to any tips or hints when you get home! =)

Here's the complete log from a fresh run from Azure this morning.

[36m[2021-02-24 14:34:49.871] [DEBUG] console - [39mRunning on Node v12.13.0 (minimum required Node version: 10.17.0)
[36m[2021-02-24 14:34:50.074] [DEBUG] AbsolutePaths - [39mC:\home\site\wwwroot\node_modules\ep_etherpad-lite does not end with "src"
[32m[2021-02-24 14:34:50.089] [INFO] console - [39mAll relative paths will be interpreted relative to the identified Etherpad base dir: C:\home\site\wwwroot
[36m[2021-02-24 14:34:50.105] [DEBUG] AbsolutePaths - [39mRelative path "settings.json" can be rewritten to "C:\home\site\wwwroot\settings.json"
[36m[2021-02-24 14:34:50.105] [DEBUG] AbsolutePaths - [39mRelative path "credentials.json" can be rewritten to "C:\home\site\wwwroot\credentials.json"
[32m[2021-02-24 14:34:50.136] [INFO] console - [39msettings loaded from: C:\home\site\wwwroot\settings.json
[32m[2021-02-24 14:34:50.168] [INFO] console - [39mNo credentials file found in C:\home\site\wwwroot\credentials.json. Ignoring.
[32m[2021-02-24 14:34:50.183] [INFO] console - [39mUsing skin "colibris" in dir: C:\home\site\wwwroot\src\static\skins\colibris
[36m[2021-02-24 14:34:50.183] [DEBUG] AbsolutePaths - [39mRelative path "./SESSIONKEY.txt" can be rewritten to "C:\home\site\wwwroot\SESSIONKEY.txt"
[32m[2021-02-24 14:34:50.199] [INFO] console - [39mSession key loaded from: C:\home\site\wwwroot\SESSIONKEY.txt
[36m[2021-02-24 14:34:50.215] [DEBUG] AbsolutePaths - [39mRelative path "var/dirty.db" can be rewritten to "C:\home\site\wwwroot\var\dirty.db"
[33m[2021-02-24 14:34:50.230] [WARN] console - [39mDirtyDB is used. This is not recommended for production. File location: C:\home\site\wwwroot\var\dirty.db
[32m[2021-02-24 14:34:50.246] [INFO] console - [39mRandom string used for versioning assets: 0f458912
[36m[2021-02-24 14:34:57.184] [DEBUG] runCmd - [39mExecuting command: "C:\Program Files (x86)\npm\6.12.0\npm" --version
[36m[2021-02-24 14:34:57.200] [DEBUG] runCmd - [39mcwd: C:\home\site\wwwroot
[36m[2021-02-24 14:34:57.216] [DEBUG] runCmd - [39mPath=C:\Python27;C:\Program Files (x86)\nodejs\12.13.0;C:\windows\system32;C:\windows;C:\windows\System32\Wbem;C:\windows\System32\WindowsPowerShell\v1.0\;C:\Program Files\Microsoft Network Monitor 3\;C:\Program Files\Git\cmd;C:\Users\imgadmin\AppData\Roaming\npm;C:\Program Files (x86)\nodejs\;C:\Program Files (x86)\Mercurial\;c:\Program Files (x86)\Microsoft ASP.NET\ASP.NET Web Pages\v1.0\;C:\Users\imgadmin\AppData\Local\Microsoft\WindowsApps;;C:\Program Files (x86)\dotnet;C:\Program Files\dotnet;C:\windows\system32\config\systemprofile\AppData\Local\Microsoft\WindowsApps;C:\Program Files\Java\zulu8.46.0.19-jre8.0.252-win_x64\bin;
[31m[2021-02-24 14:34:57.263] [ERROR] console - [39m(node:3464) [DEP0005] DeprecationWarning: Buffer() is deprecated due to security and usability issues. Please use the Buffer.alloc(), Buffer.allocUnsafe(), or Buffer.from() methods instead.
[36m[2021-02-24 14:34:59.481] [DEBUG] runCmd - [39mCommand returned successfully: "C:\Program Files (x86)\npm\6.12.0\npm" --version
[32m[2021-02-24 14:34:59.497] [INFO] plugins - [39mnpm --version: 6.12.0

@alexeisenhart
Copy link
Author

Progress so far.

server.js -> in Azure, this test at the bottom is failing. I commented it out and just directly run start and it seems to get further.

/* 
if (require.main === module){ 
  logger.warn("Calling server.start()")
  exports.start();
}
else{
  logger.warn("Failed test to call server.start()")
}*/

exports.start();

It's breaking on interpreting the results of npm ls --long --json --depth=0 --no-production

[36m[2021-02-24 15:51:34.567] [DEBUG] runCmd - [39mAttempting: npm ls --long --json --depth=0 --no-production
[36m[2021-02-24 15:51:34.567] [DEBUG] runCmd - [39mCommand returned successfully: npm ls --long --json --depth=0 --no-production
[31m[2021-02-24 15:51:34.599] [ERROR] server - [39mError occurred while starting Etherpad
[31m[2021-02-24 15:51:34.616] [ERROR] server - [39mTypeError [ERR_INVALID_ARG_TYPE]: The "path" argument must be one of type string, Buffer, or URL. Received type undefined
    at Object.realpath (internal/fs/promises.js:457:10)
    at C:\home\site\wwwroot\node_modules\ep_etherpad-lite\static\js\pluginfw\plugins.js:99:30
    at Array.map (<anonymous>)
    at Object.exports.getPackages (C:\home\site\wwwroot\node_modules\ep_etherpad-lite\static\js\pluginfw\plugins.js:94:50)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
    at async Object.exports.update (C:\home\site\wwwroot\node_modules\ep_etherpad-lite\static\js\pluginfw\plugins.js:67:20)
    at async Object.exports.start (C:\home\site\wwwroot\node_modules\ep_etherpad-lite\node\server.js:146:5)

Jumping into a meeting, but that's my morning progress.

@alexeisenhart
Copy link
Author

YES!

image

@JohnMcLear
Copy link
Member

Wow well done mate

@alexeisenhart
Copy link
Author

alexeisenhart commented Feb 24, 2021

Current issue: I can not load pads. Tried with Dirty.db and SQL Server databases. The page loads with HTTP 200 and displays the "Loading..." message, but the page never comes up.

Lunch time, then I'll dig back into it.

Client side loaded resources:

image

Client side Javascript console errors:

image

No reported errors server side. Server logs:

[36m[2021-02-24 17:36:30.739] [DEBUG] http - [39m304, GET /p/test
[36m[2021-02-24 17:36:30.833] [DEBUG] SessionStore - [39mGET 9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb
[36m[2021-02-24 17:36:30.848] [DEBUG] SessionStore - [39mGET 9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb
[36m[2021-02-24 17:36:30.864] [DEBUG] ueberDB - [39mGET    - sessionstorage:9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb - {"cookie":{"path":"/","_expires":null,"originalMaxAge":null,"httpOnly":true,"sameSite":"Lax","secure":true}} - from database 
[36m[2021-02-24 17:36:30.880] [DEBUG] SessionStore - [39mGET 9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb
[36m[2021-02-24 17:36:30.895] [DEBUG] http - [39m304, GET /static/js/require-kernel.js?v=2f04f5f0
[36m[2021-02-24 17:36:30.895] [DEBUG] ueberDB - [39mGET    - sessionstorage:9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb - {"cookie":{"path":"/","_expires":null,"originalMaxAge":null,"httpOnly":true,"sameSite":"Lax","secure":true}} - from database 
[36m[2021-02-24 17:36:30.911] [DEBUG] SessionStore - [39mGET 9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb
[36m[2021-02-24 17:36:30.942] [DEBUG] ueberDB - [39mGET    - sessionstorage:9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb - {"cookie":{"path":"/","_expires":null,"originalMaxAge":null,"httpOnly":true,"sameSite":"Lax","secure":true}} - from database 
[36m[2021-02-24 17:36:30.958] [DEBUG] SessionStore - [39mGET 9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb
[36m[2021-02-24 17:36:30.973] [DEBUG] SessionStore - [39mGET 9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb
[36m[2021-02-24 17:36:30.973] [DEBUG] http - [39m304, GET /static/js/l10n.js?v=2f04f5f0
[36m[2021-02-24 17:36:30.989] [DEBUG] SessionStore - [39mGET 9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb
[36m[2021-02-24 17:36:31.005] [DEBUG] http - [39m304, GET /static/js/vendors/html10n.js?v=2f04f5f0
[36m[2021-02-24 17:36:31.005] [DEBUG] ueberDB - [39mGET    - sessionstorage:9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb - {"cookie":{"path":"/","_expires":null,"originalMaxAge":null,"httpOnly":true,"sameSite":"Lax","secure":true}} - from database 
[36m[2021-02-24 17:36:31.036] [DEBUG] SessionStore - [39mGET 9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb
[36m[2021-02-24 17:36:31.052] [DEBUG] ueberDB - [39mGET    - sessionstorage:9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb - {"cookie":{"path":"/","_expires":null,"originalMaxAge":null,"httpOnly":true,"sameSite":"Lax","secure":true}} - from database 
[36m[2021-02-24 17:36:31.052] [DEBUG] http - [39m307, GET /javascripts/lib/ep_etherpad-lite/static/js/pad_utils.js?callback=require.define&v=2f04f5f0
[36m[2021-02-24 17:36:31.067] [DEBUG] http - [39m304, GET /javascripts/lib/ep_etherpad-lite/static/js/ace2_common.js?callback=require.define&v=2f04f5f0
[36m[2021-02-24 17:36:31.083] [DEBUG] ueberDB - [39mGET    - sessionstorage:9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb - {"cookie":{"path":"/","_expires":null,"originalMaxAge":null,"httpOnly":true,"sameSite":"Lax","secure":true}} - from database 
[36m[2021-02-24 17:36:31.083] [DEBUG] http - [39m304, GET /javascripts/lib/ep_etherpad-lite/static/js/pad.js?callback=require.define&v=2f04f5f0
[36m[2021-02-24 17:36:31.098] [DEBUG] ueberDB - [39mGET    - sessionstorage:9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb - {"cookie":{"path":"/","_expires":null,"originalMaxAge":null,"httpOnly":true,"sameSite":"Lax","secure":true}} - from database 
[36m[2021-02-24 17:36:31.114] [DEBUG] SessionStore - [39mGET 9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb
[36m[2021-02-24 17:36:31.130] [DEBUG] http - [39m304, GET /static/skins/colibris/pad.js?v=2f04f5f0
[36m[2021-02-24 17:36:31.130] [DEBUG] ueberDB - [39mGET    - sessionstorage:9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb - {"cookie":{"path":"/","_expires":null,"originalMaxAge":null,"httpOnly":true,"sameSite":"Lax","secure":true}} - from database 
[36m[2021-02-24 17:36:31.145] [DEBUG] http - [39m304, GET /static/img/brand.svg
[36m[2021-02-24 17:36:31.161] [DEBUG] ueberDB - [39mGET    - sessionstorage:9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb - {"cookie":{"path":"/","_expires":null,"originalMaxAge":null,"httpOnly":true,"sameSite":"Lax","secure":true}} - from database 
[36m[2021-02-24 17:36:31.270] [DEBUG] http - [39m200, GET /javascripts/lib/ep_etherpad-lite/static/js/timeslider.js?callback=require.define&v=2f04f5f0
[36m[2021-02-24 17:36:31.317] [DEBUG] SessionStore - [39mGET 9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb
[36m[2021-02-24 17:36:31.333] [DEBUG] ueberDB - [39mGET    - sessionstorage:9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb - {"cookie":{"path":"/","_expires":null,"originalMaxAge":null,"httpOnly":true,"sameSite":"Lax","secure":true}} - from database 
[36m[2021-02-24 17:36:31.348] [DEBUG] http - [39m200, GET /locales.json
[36m[2021-02-24 17:36:31.395] [DEBUG] SessionStore - [39mGET 9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb
[36m[2021-02-24 17:36:31.411] [DEBUG] ueberDB - [39mGET    - sessionstorage:9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb - {"cookie":{"path":"/","_expires":null,"originalMaxAge":null,"httpOnly":true,"sameSite":"Lax","secure":true}} - from database 
[32m[2021-02-24 17:36:31.442] [INFO] Minify - [39mCompress CSS file css/pad.css.
[36m[2021-02-24 17:36:31.458] [DEBUG] SessionStore - [39mGET 9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb
[36m[2021-02-24 17:36:31.473] [DEBUG] ueberDB - [39mGET    - sessionstorage:9qEoyayOvBW4YkNnP43ZdFdHKLlrmswb - {"cookie":{"path":"/","_expires":null,"originalMaxAge":null,"httpOnly":true,"sameSite":"Lax","secure":true}} - from database 
[32m[2021-02-24 17:36:31.505] [INFO] Minify - [39mCompress CSS file skins/colibris/pad.css.
[36m[2021-02-24 17:36:31.817] [DEBUG] http - [39m200, GET /static/css/pad.css?v=2f04f5f0
[36m[2021-02-24 17:36:31.864] [DEBUG] http - [39m200, GET /static/skins/colibris/pad.css?v=2f04f5f0

@JohnMcLear
Copy link
Member

Try disable minify in settings.json

@alexeisenhart
Copy link
Author

Fast answer, in case you're still around and know the answer. If not, I'll debug after lunch. Two issues:

  1. padutils is undefined:

image

  1. rjquery does not exist. -- I checked the path indicated, and there is an rjquery.js file.

image

@alexeisenhart
Copy link
Author

alexeisenhart commented Feb 24, 2021

@JohnMcLear Where can I learn more about require-kernel.js? It looks like it's a dynamically created file, because it's accessed at http://site.com/static/js/require-kernel.js, but it's not in the static folder on the server. It looks like the issue is that require isn't able to load modules.

    $ = jQuery = require('ep_etherpad-lite/static/js/rjquery').jQuery; // Expose jQuery #HACK

If I navigate to https://site.azurewebsites.net/static/js/rjquery.js then the file is returned. I tried modifying the above line to remove ep_etherpad-lite but that didn't correct the issue.

Any suggestions?

Edit: It looks like https://site.azurewebsites.net/javascripts/lib/static/js/rjquery.js?callback=require.define is loaded (HTTP 200) when I try to load the pad. I think there are some fancy client-side things going on that I'll need help with, when you have time.

@alexeisenhart
Copy link
Author

It looks like Etherpad is connected to a pipe. Might that introduce this issue?

[32m[2021-02-24 19:15:11.545] [INFO] console - [39mYou can access your Etherpad instance at http://localhost:\.\pipe\9d4e4b8c-d103-49fc-890f-0d39f8af6eb9/

@rhansen
Copy link
Member

rhansen commented Feb 25, 2021

I'm loading the correct version of NPM at runtime now (6.12.0)

@alexeisenhart It should log 6.14.11, so something is still not working. Did you try the .zip I linked? Please paste debug logs during startup.

Where can I learn more about require-kernel.js?

src/node/utils/Minify.js line 325. It's also mentioned elsewhere in that same file. The following paths should all give you the contents of require-kernel.js:

  • /static/js/require-kernel.js
  • /static/plugins/ep_etherpad-lite/static/js/require-kernel.js
  • /javascripts/lib/ep_etherpad-lite/static/js/require-kernel.js?callback=require.define

It looks like Etherpad is connected to a pipe.

It's apparently trying to use a named pipe, but I don't think that's the right way to do it:

  • When your settings.json port setting is a named pipe then the ip setting must be the empty string (or maybe null?). In your case it is "localhost", which is wrong.
  • If you are using a named pipe then according to the Node.js documentation the port setting must start with \\?\pipe\ or \\.\pipe\. In your case it starts with a single backslash when it should start with two backslashes.

Any suggestions?

Would you please visit /static/js/ace.js, scroll down, and see if you have lines that look like this:

Ace2Editor.EMBEDED = Ace2Editor.EMBEDED || {};
Ace2Editor.EMBEDED["../static/js/require-kernel.js"] = "... really really long string with lots of code ...";

If not then I think there's a problem with pathname processing in Minify.js. I sent out PR #4867 to try to improve that code. Please try the etherpad-lite-win.zip in that PR's build artifacts.

@JohnMcLear
Copy link
Member

JohnMcLear commented Feb 25, 2021

#4867 artifact has the same issue

Uncaught Error: Require kernel could not be found.
at http://127.0.0.1:9001/javascripts/lib/ep_etherpad-lite/static/js/pad.js?callback=require.define&v=22c85ed0 at line 35

static/js/ace.js

"use strict";const KERNEL_SOURCE="../static/js/require-kernel.js",hooks=require("./pluginfw/hooks"),pluginUtils=require("./pluginfw/shared"),scriptTag=t=>`<script type="text/javascript">\n${t.replace(/<\//g,"<\\/")}<\/script>`,Ace2Editor=function(){const t=Ace2Editor;let e={editor:this,id:t.registry.nextId++},n=!1,r=[];const i=t=>function(...e){const i=()=>t.apply(this,e);if(n)return i();r.push(i)};t.registry[e.id]=e;const o=["importText","importAText","focus","setEditable","getFormattedCode","setOnKeyPress","...

/static/js/ace.js looking for embeds

;if(Ace2Editor.EMBEDED)for(let r=0,i=t.length;r<i;r++){const i=t[r];Object.prototype.hasOwnProperty.call(Ace2Editor.EMBEDED,i)?e.push(i):n.push(i)}else n=t;return{embeded:e,remote:n}})(e),r=n.embeded,i=n.remote;if(r.length>0){t.push('<style type="text/css">');for(const e of r)t.push((Ace2Editor.EMBEDED[e]||"").replace(/<\//g,"<\\/"));t.push("</style>")}for(const e of i)t.push(`<link rel="stylesheet" type="text/css" href="${encodeURI(e)}"/>`)};this.destroy=i(()=>{e.ace_dispose(),e.frame.parentNode.removeChild(e.frame),delete t.registry[e.id],e=null}),this.init=function(t,i,o){this.importText(i),e.onEditorReady=()=>{n=!0,(()=>{for(const t of r)t();r=[]})(),o()},(()=>{const n=[];n.push("<!doctype html>"),n.push(`<html class='inner-editor ${clientVars.skinVariants}'><head>`);let r=[],i=t=>{r.push(t)};i("../static/css/iframe_editor.css"),clientVars.disableCustomScriptsAndStyles||i("../static/css/pad.css?v="+clientVars.randomVersionString);let o=hooks.callAll("aceEditorCSS").map(t=>t.match(/\/\//)?t:"../static/plugins/"+t);if(r=r.concat(o),i(`../static/skins/${clientVars.skinName}/pad.css?v=${clientVars.randomVersionString}`),l(n,r),!Ace2Editor.EMBEDED||!Ace2Editor.EMBEDED[KERNEL_SOURCE])throw new Error("Require kernel could not be found.");n.push(scriptTag(Ace2Editor.EMBEDED[KERNEL_SOURCE]+'\nrequire.setRootURI("../javascripts/src");\nrequire.setLibraryURI("../javascripts/lib");\nrequire.setGlobalKeyPath("require");\n\nvar plugins = require("ep_etherpad-lite/static/js/pluginfw/client_plugins");\nplugins.adoptPluginsFromAncestorsOf(window);\n\n$ = jQuery = require("ep_etherpad-lite/static/js/rjquery").jQuery; // Expose jQuery #HACK\nvar Ace2Inner = require("ep_etherpad-lite/static/js/ace2_inner");\n\nplugins.ensure(function () {\n  Ace2Inner.init();\n});\n')),n.push('<style type="text/css" title="dynamicsyntax"></style>'),hooks.callAll("aceInitInnerdocbodyHead",{iframeHTML:n}),n.push('</head><body id="innerdocbody" class="innerdocbody" role="application" class="syntax" spellcheck="false">&nbsp;</body></html>');("object"==typeof globalThis?globalThis:window).ChildAccessibleAce2Editor=Ace2Editor;const u=`e

/static/js/require-kernel.js

var require=function(){
/*!

  require-kernel

  Created by Chad Weider on 01/04/11.
  Released to the Public Domain on 17/01/12.

*/
var t=null,e={},n={},r=

Ace2Editor.EMBEDED || {};

is NOT present in pad.js but nor is it present on linux based deployments ;/

@JohnMcLear
Copy link
Member

[2021-02-25 08:22:08.506] [INFO] plugins - Running npm to get a list of installed plugins...
[2021-02-25 08:22:14.830] [INFO] plugins - npm --version: 6.14.11
[2021-02-25 08:22:37.353] [INFO] plugins - Loading plugin ep_etherpad-lite...
[2021-02-25 08:22:37.364] [INFO] plugins - Loaded 1 plugins

@JohnMcLear
Copy link
Member

JohnMcLear commented Feb 25, 2021

I set minify to false and maxAge to 0 and the same error persists : This points at the issue not necessarily being the minify logic IMHO.

[2021-02-25 08:33:24.507] [INFO] access - [CREATE] pad:foo socket:qtzpHnbrftP8S4stAAAA IP:127.0.0.1 authorID:a.nof5kX9UkLNvq7ww
[2021-02-25 08:33:24.561] [WARN] client - Uncaught Error: Require kernel could not be found. -- {
  errorId: '41SbuA3jCZXZAb8tg31M',
  type: 'Uncaught exception',
  msg: 'Uncaught Error: Require kernel could not be found.',
  url: 'http://127.0.0.1:9001/p/foo',
  source: 'http://127.0.0.1:9001/javascripts/lib/ep_etherpad-lite/static/js/pad.js?callback=require.define&v=4af58bdc',
  linenumber: 2923,
  userAgent: 'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.182 Safari/537.36',
  stack: 'Error: Require kernel could not be found.\n' +
    '    at http://127.0.0.1:9001/javascripts/lib/ep_etherpad-lite/static/js/pad.js?callback=require.define&v=4af58bdc:2923:15\n' +
    '    at Ace2Editor.init (http://127.0.0.1:9001/javascripts/lib/ep_etherpad-lite/static/js/pad.js?callback=require.define&v=4af58bdc:3030:7)\n' +
    '    at Object.init (http://127.0.0.1:9001/javascripts/lib/ep_etherpad-lite/static/js/pad_utils.js?callback=require.define&v=4af58bdc:1129:16)\n' +
    '    at Object._afterHandshake (http://127.0.0.1:9001/javascripts/lib/ep_etherpad-lite/static/js/pad.js?callback=require.define&v=4af58bdc:506:15)\n' +
    '    at r.<anonymous> (http://127.0.0.1:9001/javascripts/lib/ep_etherpad-lite/static/js/pad.js?callback=require.define&v=4af58bdc:302:11)\n' +
    '    at r.emit (http://127.0.0.1:9001/socket.io/socket.io.js?v=4af58bdc:6:13957)\n' +
    '    at r.onevent (http://127.0.0.1:9001/socket.io/socket.io.js?v=4af58bdc:8:10372)\n' +
    '    at r.onpacket (http://127.0.0.1:9001/socket.io/socket.io.js?v=4af58bdc:8:9994)\n' +
    '    at r.<anonymous> (http://127.0.0.1:9001/socket.io/socket.io.js?v=4af58bdc:8:12155)\n' +
    '    at r.emit (http://127.0.0.1:9001/socket.io/socket.io.js?v=4af58bdc:6:13957)'

@webzwo0i
Copy link
Member

webzwo0i commented Feb 25, 2021

You probably did this, but if not ensure cache is disabled in develop console. The thing is, if we require a file via require-kernel that is not a package, but that is part of a package (like pad_utils.js), then yajsml will send a 307 redirect to that package. However, that redirect location does not include the version string, so that file can and will be served from the cache. That's the main reason elimination of 307s is important besides performance.

This is probably worth fixing even though we're gonna drop yajsml/require-kernel in the future? It's probably not related to this bug though, as I see all version strings are included in the error trace you got.

@JohnMcLear
Copy link
Member

Yep browser cache is perma disabled for me obviously

@webzwo0i
Copy link
Member

Interesting. The error from @alexeisenhart with rjquery is thrown from pad.html (before ace.js runs) while your error seems to be thrown later when initializing Ace2Editor.

@alexeisenhart
Copy link
Author

alexeisenhart commented Feb 25, 2021

I'm loading the correct version of NPM at runtime now (6.12.0)

@alexeisenhart It should log 6.14.11, so something is still not working. Did you try the .zip I linked? Please paste debug logs during startup.

Hey @rhansen. I think I missed your previous comment requesting me to deploy your zip. The one that I'm currently running was sent to me two days ago by @JohnMcLear. I did not deploy the node.exe that came with that zip, so by saying that it's running the "correct" version of NPM I mean that it's using the version that I configured Azure to use. Do you expect issues with node 6.12.0?

It's apparently trying to use a named pipe, but I don't think that's the right way to do it:

  • When your settings.json port setting is a named pipe then the ip setting must be the empty string (or maybe null?). In your case it is "localhost", which is wrong.
  • If you are using a named pipe then according to the Node.js documentation the port setting must start with \\?\pipe\ or \\.\pipe\. In your case it starts with a single backslash when it should start with two backslashes.

I have my IP address configured as localhost and I commented out the port line. In settings.js, I modified the port line to read as follows, to ensure that the environment port is used. This seemed to be the right thing to do for Azure.

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

Would you please visit /static/js/ace.js, scroll down, and see if you have lines that look like this:

Ace2Editor.EMBEDED = Ace2Editor.EMBEDED || {};
Ace2Editor.EMBEDED["../static/js/require-kernel.js"] = "... really really long string with lots of code ...";

If not then I think there's a problem with pathname processing in Minify.js. I sent out PR #4867 to try to improve that code. Please try the etherpad-lite-win.zip in that PR's build artifacts.

Do you still need me to do these things, or is the information that John supplied sufficient?

@RyanHill-MSFT
Copy link

Hey @RyanHill-MSFT. Can you help here? I'm not getting the right NPM version at runtime. Where is NPM

NPM Versions:

  1. env shows NPM_JS_PATH=C:\Program Files (x86)\npm\6.12.0\node_modules\npm\bin\npm-cli.js
  2. npm --version shows 6.12.0.
  3. "C:\Program Files (x86)\npm\6.12.0\node_modules\npm\bin\npm-cli.js" --version gives no output.
  4. "c:\program files (x86)\nodejs\npm" --version is 1.1.37.

Where is NPM 6.12.0 located?

@alexeisenhart, See https://github.com/projectkudu/kudu/wiki/Node-versioning. Use WEBSITE_NODE_DEFAULT_VERSION to set your default node version. For available runtimes, go to https://{your-app-name}.scm.azurewebsites.net/api/diagnostics/runtime.

@rhansen
Copy link
Member

rhansen commented Feb 28, 2021

@alexeisenhart What's the status? Were you able to get it working?

@alexeisenhart
Copy link
Author

Hey @rhansen. Not yet, but I haven't tried since Friday. I have to focus on personal things this weekend, but I'll be diving back in tomorrow morning.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants