YunoHost-Apps / etherpad_mypads_ynh

Etherpad MyPads package for YunoHost
http://etherpad.org/
GNU General Public License v3.0
16 stars 13 forks source link

Etherpad crash after last upgrade - loop restarting #186

Open tomdereub opened 1 year ago

tomdereub commented 1 year ago

Describe the bug

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

Context

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 eslint-plugin-import@2.27.5
[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)
Jaxom99 commented 1 year ago

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 autoetherpad 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:

rodinux commented 1 year ago

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 commented 1 year ago

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  };
ericgaspar commented 1 year ago

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

b01xy commented 1 year ago

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`

rodinux commented 1 year ago

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

tomdereub commented 1 year ago

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

fflorent commented 1 year ago

To workaround the issue:

# yunohost app shell etherpad_mypads
$ npm install eslint
Jaxom99 commented 1 year ago

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 !

lovingkindness commented 1 year ago

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/move-file@1.1.2: This functionality has been moved t o @npmcli/fs

sqlite3@5.1.6 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: sqlite3@5.1.6 (src/node_modules/ sqlite3): npm WARN optional SKIPPING OPTIONAL DEPENDENCY: sqlite3@5.1.6 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 commented 1 year ago

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!