etherpad_mypads_ynh icon indicating copy to clipboard operation
etherpad_mypads_ynh copied to clipboard

Etherpad crash after last upgrade - loop restarting

Open tomdereub opened this issue 1 year ago • 11 comments

Describe the bug

After last upgrade, etherpad_mypads is starting and exiting continuously. Got the problem on 2 different servers.

Context

  • Hardware: Old laptop or computer
  • YunoHost version: 11.1.21.4
  • I have access to my server: Through SSH and through the webadmin and direct access via keyboard / screen | ...
  • Are you in a special context or did you perform some particular tweaking on your YunoHost instance?: no
  • Using, or trying to install package version/branch: upgrade to etherpad_mypads 1.9.1-ynh1

Steps to reproduce

Upgrade etherpad_mypas in the webadmin

Expected behavior

Etherpad_mypads working after upgrade

Logs

[2023-07-03 23:19:17.648] [ERROR] server - Error: Command exited with code 1: npm ls --long --json --depth=0 --no-production
    at exports (/var/www/etherpad_mypads/src/node/utils/run_cmd.js:119:25)
    at Object.exports.getPackages (/var/www/etherpad_mypads/src/static/js/pluginfw/plugins.js:115:48)
    at Object.exports.update (/var/www/etherpad_mypads/src/static/js/pluginfw/plugins.js:86:34)
    at Object.exports.start (/var/www/etherpad_mypads/src/node/server.js:143:19)
    at processTicksAndRejections (internal/process/task_queues.js:95:5)
[2023-07-03 23:19:17.648] [INFO] server - Exiting...
[2023-07-03 23:19:17.648] [INFO] server - Waiting for Node.js to exit...
[2023-07-03 23:19:22.649] [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
[2023-07-03 23:19:22.649] [ERROR] server - Enable `dumpOnUncleanExit` setting to get a dump of objects preventing a clean exit
[2023-07-03 23:19:22.650] [ERROR] server - Forcing an unclean exit...
[2023-07-03 23:19:23.104] [INFO] settings - All relative paths will be interpreted relative to the identified Etherpad base dir: /var/www/etherpad_mypads
[2023-07-03 23:19:23.122] [INFO] settings - settings loaded from: /var/www/etherpad_mypads/settings.json
[2023-07-03 23:19:23.123] [INFO] settings - credentials loaded from: /var/www/etherpad_mypads/credentials.json
[2023-07-03 23:19:23.124] [INFO] settings - Using skin "colibris" in dir: /var/www/etherpad_mypads/src/static/skins/colibris
[2023-07-03 23:19:23.124] [INFO] settings - Session key loaded from: /var/www/etherpad_mypads/SESSIONKEY.txt
[2023-07-03 23:19:23.125] [INFO] settings - Random string used for versioning assets: aa1e719a
[2023-07-03 23:19:23.371] [INFO] server - Starting Etherpad...
[2023-07-03 23:19:23.471] [INFO] plugins - Running npm to get a list of installed plugins...
[2023-07-03 23:19:23.577] [INFO] plugins - npm --version: 6.14.16
[2023-07-03 23:19:27.959] [ERROR] runCmd|npm - npm ERR! peer dep missing: eslint@^2 || ^3 || ^4 || ^5 || ^6 || ^7.2.0 || ^8, required by [email protected]
[2023-07-03 23:19:27.979] [ERROR] server - Error occurred while starting Etherpad
[2023-07-03 23:19:27.980] [ERROR] server - Metrics at time of fatal error:
{
  "httpStartTime": 0,
  "memoryUsage": 68923392,
  "memoryUsageHeap": 13537056,
  "ueberdb_lockAwaits": 0,
  "ueberdb_lockAcquires": 0,
  "ueberdb_lockReleases": 0,
  "ueberdb_reads": 0,
  "ueberdb_readsFailed": 0,
  "ueberdb_readsFinished": 0,
  "ueberdb_readsFromCache": 0,
  "ueberdb_readsFromDb": 0,
  "ueberdb_readsFromDbFailed": 0,
  "ueberdb_readsFromDbFinished": 0,
  "ueberdb_writes": 0,
  "ueberdb_writesFailed": 0,
  "ueberdb_writesFinished": 0,
  "ueberdb_writesObsoleted": 0,
  "ueberdb_writesToDb": 0,
  "ueberdb_writesToDbFailed": 0,
  "ueberdb_writesToDbFinished": 0,
  "ueberdb_writesToDbRetried": 0
}
[2023-07-03 23:19:27.980] [ERROR] server - Error: Command exited with code 1: npm ls --long --json --depth=0 --no-production
    at exports (/var/www/etherpad_mypads/src/node/utils/run_cmd.js:119:25)
    at Object.exports.getPackages (/var/www/etherpad_mypads/src/static/js/pluginfw/plugins.js:115:48)
    at Object.exports.update (/var/www/etherpad_mypads/src/static/js/pluginfw/plugins.js:86:34)
    at Object.exports.start (/var/www/etherpad_mypads/src/node/server.js:143:19)
    at processTicksAndRejections (internal/process/task_queues.js:95:5)

tomdereub avatar Jul 03 '23 21:07 tomdereub

same here, on same versions. I'll keep an eye on this issue, hope it's easy to fix. I can provide logs and tests if needed.

+ I mistakenly removed the auto_etherpad backup that is made by the upgrade script from previous version (by forcing a reinstall of same app version) soooo... anyone know how to reinstall a previous version AND back-up the data ? :grin:

Jaxom99 avatar Jul 07 '23 15:07 Jaxom99

same here, only on a raspberry Pi 4. On another server I have done the upgrade without issues, but perhaps it was with a system yunohost a bit older than the last stable...

rodinux avatar Jul 17 '23 14:07 rodinux

we have a problem on this file

cat -n /var/www/etherpad_mypads/src/static/js/pluginfw/plugins.js
     1	'use strict';
     2	
     3	const fs = require('fs').promises;
     4	const hooks = require('./hooks');
     5	const log4js = require('log4js');
     6	const path = require('path');
     7	const runCmd = require('../../../node/utils/run_cmd');
     8	const tsort = require('./tsort');
     9	const pluginUtils = require('./shared');
    10	const defs = require('./plugin_defs');
    11	
    12	const logger = log4js.getLogger('plugins');
    13	
    14	// Log the version of npm at startup.
    15	(async () => {
    16	  try {
    17	    const version = await runCmd(['npm', '--version'], {stdio: [null, 'string']});
    18	    logger.info(`npm --version: ${version}`);
    19	  } catch (err) {
    20	    logger.error(`Failed to get npm version: ${err.stack || err}`);
    21	    // This isn't a fatal error so don't re-throw.
    22	  }
    23	})();
    24	
    25	exports.prefix = 'ep_';
    26	
    27	exports.formatPlugins = () => Object.keys(defs.plugins).join(', ');
    28	
    29	exports.formatParts = () => defs.parts.map((part) => part.full_name).join('\n');
    30	
    31	exports.formatHooks = (hookSetName, html) => {
    32	  let hooks = new Map();
    33	  for (const [pluginName, def] of Object.entries(defs.plugins)) {
    34	    for (const part of def.parts) {
    35	      for (const [hookName, hookFnName] of Object.entries(part[hookSetName] || {})) {
    36	        let hookEntry = hooks.get(hookName);
    37	        if (!hookEntry) {
    38	          hookEntry = new Map();
    39	          hooks.set(hookName, hookEntry);
    40	        }
    41	        let pluginEntry = hookEntry.get(pluginName);
    42	        if (!pluginEntry) {
    43	          pluginEntry = new Map();
    44	          hookEntry.set(pluginName, pluginEntry);
    45	        }
    46	        pluginEntry.set(part.name, hookFnName);
    47	      }
    48	    }
    49	  }
    50	  const lines = [];
    51	  const sortStringKeys = (a, b) => String(a[0]).localeCompare(b[0]);
    52	  if (html) lines.push('<dl>');
    53	  hooks = new Map([...hooks].sort(sortStringKeys));
    54	  for (const [hookName, hookEntry] of hooks) {
    55	    lines.push(html ? `  <dt>${hookName}:</dt><dd><dl>` : `  ${hookName}:`);
    56	    const sortedHookEntry = new Map([...hookEntry].sort(sortStringKeys));
    57	    hooks.set(hookName, sortedHookEntry);
    58	    for (const [pluginName, pluginEntry] of sortedHookEntry) {
    59	      lines.push(html ? `    <dt>${pluginName}:</dt><dd><dl>` : `    ${pluginName}:`);
    60	      const sortedPluginEntry = new Map([...pluginEntry].sort(sortStringKeys));
    61	      sortedHookEntry.set(pluginName, sortedPluginEntry);
    62	      for (const [partName, hookFnName] of sortedPluginEntry) {
    63	        lines.push(html
    64	          ? `      <dt>${partName}:</dt><dd>${hookFnName}</dd>`
    65	          : `      ${partName}: ${hookFnName}`);
    66	      }
    67	      if (html) lines.push('    </dl></dd>');
    68	    }
    69	    if (html) lines.push('  </dl></dd>');
    70	  }
    71	  if (html) lines.push('</dl>');
    72	  return lines.join('\n');
    73	};
    74	
    75	exports.pathNormalization = (part, hookFnName, hookName) => {
    76	  const tmp = hookFnName.split(':'); // hookFnName might be something like 'C:\\foo.js:myFunc'.
    77	  // If there is a single colon assume it's 'filename:funcname' not 'C:\\filename'.
    78	  const functionName = (tmp.length > 1 ? tmp.pop() : null) || hookName;
    79	  const moduleName = tmp.join(':') || part.plugin;
    80	  const packageDir = path.dirname(defs.plugins[part.plugin].package.path);
    81	  const fileName = path.join(packageDir, moduleName);
    82	  return `${fileName}:${functionName}`;
    83	};
    84	
    85	exports.update = async () => {
    86	  const packages = await exports.getPackages();
    87	  const parts = {}; // Key is full name. sortParts converts this into a topologically sorted array.
    88	  const plugins = {};
    89	
    90	  // Load plugin metadata ep.json
    91	  await Promise.all(Object.keys(packages).map(async (pluginName) => {
    92	    logger.info(`Loading plugin ${pluginName}...`);
    93	    await loadPlugin(packages, pluginName, plugins, parts);
    94	  }));
    95	  logger.info(`Loaded ${Object.keys(packages).length} plugins`);
    96	
    97	  defs.plugins = plugins;
    98	  defs.parts = sortParts(parts);
    99	  defs.hooks = pluginUtils.extractHooks(defs.parts, 'hooks', exports.pathNormalization);
   100	  defs.loaded = true;
   101	  await Promise.all(Object.keys(defs.plugins).map(async (p) => {
   102	    const logger = log4js.getLogger(`plugin:${p}`);
   103	    await hooks.aCallAll(`init_${p}`, {logger});
   104	  }));
   105	};
   106	
   107	exports.getPackages = async () => {
   108	  logger.info('Running npm to get a list of installed plugins...');
   109	  // Notes:
   110	  //   * Do not pass `--prod` otherwise `npm ls` will fail if there is no `package.json`.
   111	  //   * The `--no-production` flag is required (or the `NODE_ENV` environment variable must be
   112	  //     unset or set to `development`) because otherwise `npm ls` will not mention any packages
   113	  //     that are not included in `package.json` (which is expected to not exist).
   114	  const cmd = ['npm', 'ls', '--long', '--json', '--depth=0', '--no-production'];
   115	  const {dependencies = {}} = JSON.parse(await runCmd(cmd, {stdio: [null, 'string']}));
   116	  await Promise.all(Object.entries(dependencies).map(async ([pkg, info]) => {
   117	    if (!pkg.startsWith(exports.prefix)) {
   118	      delete dependencies[pkg];
   119	      return;
   120	    }
   121	    info.realPath = await fs.realpath(info.path);
   122	  }));
   123	  return dependencies;
   124	};
   125	
   126	const loadPlugin = async (packages, pluginName, plugins, parts) => {
   127	  const pluginPath = path.resolve(packages[pluginName].path, 'ep.json');
   128	  try {
   129	    const data = await fs.readFile(pluginPath);
   130	    try {
   131	      const plugin = JSON.parse(data);
   132	      plugin.package = packages[pluginName];
   133	      plugins[pluginName] = plugin;
   134	      for (const part of plugin.parts) {
   135	        part.plugin = pluginName;
   136	        part.full_name = `${pluginName}/${part.name}`;
   137	        parts[part.full_name] = part;
   138	      }
   139	    } catch (err) {
   140	      logger.error(`Unable to parse plugin definition file ${pluginPath}: ${err.stack || err}`);
   141	    }
   142	  } catch (err) {
   143	    logger.error(`Unable to load plugin definition file ${pluginPath}: ${err.stack || err}`);
   144	  }
   145	};
   146	
   147	const partsToParentChildList = (parts) => {
   148	  const res = [];
   149	  for (const name of Object.keys(parts)) {
   150	    for (const childName of parts[name].post || []) {
   151	      res.push([name, childName]);
   152	    }
   153	    for (const parentName of parts[name].pre || []) {
   154	      res.push([parentName, name]);
   155	    }
   156	    if (!parts[name].pre && !parts[name].post) {
   157	      res.push([name, `:${name}`]); // Include apps with no dependency info
   158	    }
   159	  }
   160	  return res;
   161	};
   162	
   163	// Used only in Node, so no need for _
   164	const sortParts = (parts) => tsort(partsToParentChildList(parts))
   165	    .filter((name) => parts[name] !== undefined)
   166	    .map((name) => parts[name]);

Perhaps one of the plugins is no more supported ??

It seems breaking here

107	exports.getPackages = async () => {
   108	  logger.info('Running npm to get a list of installed plugins...');
   109	  // Notes:
   110	  //   * Do not pass `--prod` otherwise `npm ls` will fail if there is no `package.json`.
   111	  //   * The `--no-production` flag is required (or the `NODE_ENV` environment variable must be
   112	  //     unset or set to `development`) because otherwise `npm ls` will not mention any packages
   113	  //     that are not included in `package.json` (which is expected to not exist).
   114	  const cmd = ['npm', 'ls', '--long', '--json', '--depth=0', '--no-production'];
   115	  const {dependencies = {}} = JSON.parse(await runCmd(cmd, {stdio: [null, 'string']}));
   116	  await Promise.all(Object.entries(dependencies).map(async ([pkg, info]) => {
   117	    if (!pkg.startsWith(exports.prefix)) {
   118	      delete dependencies[pkg];
   119	      return;
   120	    }
   121	    info.realPath = await fs.realpath(info.path);
   122	  }));
   123	  return dependencies;
   124	};

rodinux avatar Jul 17 '23 15:07 rodinux

Do you have an extra plugins installed? (plugins not installed with the app)

ericgaspar avatar Jul 17 '23 20:07 ericgaspar

Same problem for me, I don't think I have installed extra plug-in : `

Greffons installés

align Etherpad plugin to set left, center, right, or full justification for a paragraph 0.3.53 author_hover Adds author names to span titles (shows on hover), works as authors change their name. Hover includes author color and fast switching between author spans. Hat tip to Martyn York for the initial work on this. 0.3.37 comments_page Adds comments on sidebar and link it to the text. For no-skin use ep_page_view. 1.0.5 countable Displays paragraphs, sentences, words and characters counts. 0.0.13 delete_empty_pads Delete pads which were never edited [DO NOT UPGRADE IF Etherpad < 1.8.0] 0.0.9 font_color Apply colors to fonts 0.0.63 font_size Apply sizes to fonts 0.4.44 headings2 Adds heading support to Etherpad Lite. Includes improved suppot for export, i18n etc. 0.2.44 markdown Edit and Export as Markdown in Etherpad 0.1.50 mypads Groups and private pads for etherpad 1.7.24 spellcheck Add support to do 'Spell checking', with a toggle on/off option in Settings 0.0.43 subscript_and_superscript Add support for different Fonts 0.2.47 table_of_contents View a table of contents for your pad 0.3.42`

b01xy avatar Jul 18 '23 10:07 b01xy

It happens again also on another server... here the last logs of the upgrade

Info: [#################+..] > Starting a systemd service...
Warning: (this may take some time)
Warning: The service etherpad_mypads didn't fully executed the action restart before the timeout.
Warning: Please find here an extract of the end of the log of the service etherpad_mypads:
Warning: Jul 25 23:49:49 systemd[1]: etherpad_mypads.service: Failed with result 'exit-code'.
Warning: Jul 25 23:49:49 systemd[1]: etherpad_mypads.service: Consumed 13.316s CPU time.
Warning: Jul 25 23:49:50 systemd[1]: etherpad_mypads.service: Scheduled restart job, restart counter is at 3.
Warning: Jul 25 23:49:50 systemd[1]: Stopped Etherpad-lite: the collaborative editor..
Warning: Jul 25 23:49:50 systemd[1]: etherpad_mypads.service: Consumed 13.316s CPU time.
Warning: Jul 25 23:49:50 systemd[1]: Started Etherpad-lite: the collaborative editor..
Warning: Jul 25 23:50:05 systemd[1]: etherpad_mypads.service: Main process exited, code=exited, status=1/FAILURE
Warning: Jul 25 23:50:05 systemd[1]: etherpad_mypads.service: Failed with result 'exit-code'.
Warning: Jul 25 23:50:05 systemd[1]: etherpad_mypads.service: Consumed 14.133s CPU time.
Warning: Jul 25 23:50:06 systemd[1]: etherpad_mypads.service: Scheduled restart job, restart counter is at 4.
Warning: Jul 25 23:50:06 systemd[1]: Stopped Etherpad-lite: the collaborative editor..
Warning: Jul 25 23:50:06 systemd[1]: etherpad_mypads.service: Consumed 14.133s CPU time.
Warning: Jul 25 23:50:06 systemd[1]: Started Etherpad-lite: the collaborative editor..
Warning: Jul 25 23:50:21 systemd[1]: etherpad_mypads.service: Main process exited, code=exited, status=1/FAILURE
Warning: Jul 25 23:50:21 systemd[1]: etherpad_mypads.service: Failed with result 'exit-code'.
Warning: Jul 25 23:50:21 systemd[1]: etherpad_mypads.service: Consumed 13.304s CPU time.
Warning: Jul 25 23:50:21 systemd[1]: etherpad_mypads.service: Scheduled restart job, restart counter is at 5.
Warning: Jul 25 23:50:21 systemd[1]: Stopped Etherpad-lite: the collaborative editor..
Warning: Jul 25 23:50:21 systemd[1]: etherpad_mypads.service: Consumed 13.304s CPU time.
Warning: Jul 25 23:50:21 systemd[1]: Started Etherpad-lite: the collaborative editor
Warning: \-\-\-
Warning:   "ueberdb_readsFromDb": 0,
Warning:   "ueberdb_readsFromDbFailed": 0,
Warning:   "ueberdb_readsFromDbFinished": 0,
Warning:   "ueberdb_writes": 0,
Warning:   "ueberdb_writesFailed": 0,
Warning:   "ueberdb_writesFinished": 0,
Warning:   "ueberdb_writesObsoleted": 0,
Warning:   "ueberdb_writesToDb": 0,
Warning:   "ueberdb_writesToDbFailed": 0,
Warning:   "ueberdb_writesToDbFinished": 0,
Warning:   "ueberdb_writesToDbRetried": 0
Warning: }   
Warning: [2023-07-25 23:50:32.429] [ERROR] server - Error: Command exited with code 1: npm ls --long --json --depth=0 --no-production
Warning:     at exports (/var/www/etherpad_mypads/src/node/utils/run_cmd.js:119:25)
Warning:     at Object.exports.getPackages (/var/www/etherpad_mypads/src/static/js/pluginfw/plugins.js:115:48)
Warning:     at Object.exports.update (/var/www/etherpad_mypads/src/static/js/pluginfw/plugins.js:86:34)
Warning:     at Object.exports.start (/var/www/etherpad_mypads/src/node/server.js:143:19)
Warning:     at processTicksAndRejections (internal/process/task_queues.js:95:5)
Warning: [2023-07-25 23:50:32.429] [INFO] server - Exiting...
Warning: [2023-07-25 23:50:32.429] [INFO] server - Waiting for Node.js to exit...
Info: [##################+.] > Reconfiguring Fail2Ban...
Info: The service fail2ban has correctly executed the action reload-or-restart.
Info: [###################.] > Disabling maintenance mode...
Info: [####################] > Upgrade of etherpad_mypads completed
Success! etherpad_mypads upgraded
Success! Upgrade complet

but it is broken and just give me a page with nginx. I come back to the older version...

rodinux avatar Jul 25 '23 22:07 rodinux

Do you have an extra plugins installed? (plugins not installed with the app)

No extra plugins installed in my case, but in etherpad's admin interface updates are proposed for 2 plugins : image

tomdereub avatar Jul 27 '23 05:07 tomdereub

To workaround the issue:

# yunohost app shell etherpad_mypads
$ npm install eslint

fflorent avatar Jul 31 '23 09:07 fflorent

To workaround the issue:

# yunohost app shell etherpad_mypads
$ npm install eslint

Interesting, how did you work that out ? I'm not able to test it right now, but I'll do it soon !

Jaxom99 avatar Jul 31 '23 11:07 Jaxom99

Hi all. My Etherpad has been working healthy for past year. But my Etherpad didn't launch any more after the last upgrade, same versions too.

I remember that I saw "fatal error" message on my log during the upgrade and upgrade never ended on the "System update" web interface, so I just closed the page after 1 hour.

Then I rebooted my yunohost and tried to start Etherpad from the https://domain/yunohost/sso/ app launcher. The app launcher didn't launch the up at all, doesn't do anything after clicking the "Et Etherpad". I went to check if others are encountering same issue on yunohost forum, tag/etherpad_mypads. There are reports but there was no solution given. So I came here on github and found the @fflorent's workaround command.

I couldn't be patient to wait for someone to test the @fflorent's command. Considering the fact that my machine also showed "npm ERR! peer dep missing: eslint" in the error message, I decided to run the suggested command on my machine to see what happens.

This is what my screen showed when I run the command.


etherpad_mypads@xxx:~$ npm install eslint npm WARN deprecated @npmcli/[email protected]: This functionality has been moved t o @npmcli/fs

[email protected] install /var/www/etherpad_mypads/src/node_modules/sqlite3 node-pre-gyp install --fallback-to-build

sh: 1: node-pre-gyp: not found npm WARN saveError ENOENT: no such file or directory, open '/var/www/etherpad_my pads/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 '/var/www/etherpad_mypad s/package.json' npm WARN etherpad_mypads No description npm WARN etherpad_mypads No repository field. npm WARN etherpad_mypads No README data npm WARN etherpad_mypads No license field. npm WARN optional SKIPPING OPTIONAL DEPENDENCY: [email protected] (src/node_modules/ sqlite3): npm WARN optional SKIPPING OPTIONAL DEPENDENCY: [email protected] install: node-pre -gyp install --fallback-to-build npm WARN optional SKIPPING OPTIONAL DEPENDENCY: spawn ENOENT

248 packages are looking for funding run npm fund for details

etherpad_mypads@xxx:~$


After installing the npm eslint, Etherpad works normally again on my yunohost!!!

Thanks to @fflorent for sharing his knowledge and experience when people needs the solution!!!

lovingkindness avatar Aug 04 '23 05:08 lovingkindness

Update:

I spent past 6 hours to test Etherpad with multiple users while working on a single pad after I made my report that my Etherpad worked again.

After 6 hours of test drving of Etherpad, I have to add info here that it seems that my Etherpad is not functioning fully well to me on my machine comparing with before upgrading.

Immediately after installing the npm eslint, my Etherpad was launched successfully. Then I saw myPad screen and I typed my own preferred link for a new pad and the new pad was generated.

After working on a single pad with multiple users, I closed the pad.

After I closed the pad, new session of my Etherpad doesn’t launch anymore.

I haven’t rebooted yunohost yet to see if Etherpad runs or not since I am hurrying to write this up and share as an update.

By clicking “Et Etherpad” on the app menu, https://domain/yunohost/sso/, rather than Etherpad being launched, it comes back to https://domain/yunohost/sso/.

I can’t tell if Etherpad is working fully fine or not in my capacity. So in the meantime, I will be watching this issue #186 for others to come up with comments.

Thanks!

lovingkindness avatar Aug 04 '23 12:08 lovingkindness