plugins: Improve logging of plugin events

This will make it easier to troubleshoot plugin and npm issues.

src/node/utils/run_npm.js

@@ -21,13 +21,8 @@ const stderrLogger = (line) => npmLogger.error(line);
  */
 module.exports = exports = (args, opts = {}) => {
   const cmd = ['npm', ...args];
-  logger.info(`Executing command: ${cmd.join(' ')}`);
-  const p = runCmd(cmd, {stdoutLogger, stderrLogger, ...opts});
-  p.then(
-      () => logger.info(`Successfully ran command: ${cmd.join(' ')}`),
-      () => logger.error(`npm command failed: ${cmd.join(' ')}`));
   // MUST return the original Promise returned from runCmd so that the caller can access stdout.
-  return p;
+  return runCmd(cmd, {stdoutLogger, stderrLogger, ...opts});
 };
 
 // Log the version of npm at startup.

src/static/js/pluginfw/installer.js

@@ -7,6 +7,8 @@ const npm = require('npm');
 const request = require('request');
 const util = require('util');
 
+const logger = log4js.getLogger('plugins');
+
 let npmIsLoaded = false;
 const loadNpm = async () => {
   if (npmIsLoaded) return;
@@ -33,13 +35,16 @@ const wrapTaskCb = (cb) => {
 
 exports.uninstall = async (pluginName, cb = null) => {
   cb = wrapTaskCb(cb);
+  logger.info(`Uninstalling plugin ${pluginName}...`);
   try {
     await loadNpm();
     await util.promisify(npm.commands.uninstall)([pluginName]);
   } catch (err) {
+    logger.error(`Failed to uninstall plugin ${pluginName}`);
     cb(err || new Error(err));
     throw err;
   }
+  logger.info(`Successfully uninstalled plugin ${pluginName}`);
   await hooks.aCallAll('pluginUninstall', {pluginName});
   await plugins.update();
   cb(null);
@@ -47,13 +52,16 @@ exports.uninstall = async (pluginName, cb = null) => {
 
 exports.install = async (pluginName, cb = null) => {
   cb = wrapTaskCb(cb);
+  logger.info(`Installing plugin ${pluginName}...`);
   try {
     await loadNpm();
     await util.promisify(npm.commands.install)([`${pluginName}@latest`]);
   } catch (err) {
+    logger.error(`Failed to install plugin ${pluginName}`);
     cb(err || new Error(err));
     throw err;
   }
+  logger.info(`Successfully installed plugin ${pluginName}`);
   await hooks.aCallAll('pluginInstall', {pluginName});
   await plugins.update();
   cb(null);
@@ -77,7 +85,7 @@ exports.getAvailablePlugins = (maxCacheAge) => {
       try {
         plugins = JSON.parse(plugins);
       } catch (err) {
-        console.error('error parsing plugins.json:', err);
+        logger.error(`error parsing plugins.json: ${err.stack || err}`);
         plugins = [];
       }
 
@@ -107,7 +115,7 @@ exports.search = (searchTerm, maxCacheAge) => exports.getAvailablePlugins(maxCac
               !~results[pluginName].description.toLowerCase().indexOf(searchTerm))
         ) {
           if (typeof results[pluginName].description === 'undefined') {
-            console.debug('plugin without Description: %s', results[pluginName].name);
+            logger.debug(`plugin without Description: ${results[pluginName].name}`);
           }
 
           continue;

src/static/js/pluginfw/plugins.js

@@ -2,12 +2,15 @@
 
 const fs = require('fs').promises;
 const hooks = require('./hooks');
+const log4js = require('log4js');
 const path = require('path');
 const runNpm = require('../../../node/utils/run_npm');
 const tsort = require('./tsort');
 const pluginUtils = require('./shared');
 const defs = require('./plugin_defs');
 
+const logger = log4js.getLogger('plugins');
+
 exports.prefix = 'ep_';
 
 exports.formatPlugins = () => Object.keys(defs.plugins).join(', ');
@@ -55,8 +58,11 @@ exports.update = async () => {
   const plugins = {};
 
   // Load plugin metadata ep.json
-  await Promise.all(Object.keys(packages).map(
+  await Promise.all(Object.keys(packages).map(async (pluginName) => {
-      async (pluginName) => await loadPlugin(packages, pluginName, plugins, parts)));
+    logger.info(`Loading plugin ${pluginName}...`);
+    await loadPlugin(packages, pluginName, plugins, parts);
+  }));
+  logger.info(`Loaded ${Object.keys(packages).length} plugins`);
 
   defs.plugins = plugins;
   defs.parts = sortParts(parts);
@@ -66,6 +72,7 @@ exports.update = async () => {
 };
 
 exports.getPackages = async () => {
+  logger.info('Running npm to get a list of installed plugins...');
   // Note: Do not pass `--prod` because it does not work if there is no package.json.
   const np = runNpm(['ls', '--long', '--json', '--depth=0'], {
     stdoutLogger: null, // We want to capture stdout, so don't attempt to log it.
@@ -104,11 +111,11 @@ const loadPlugin = async (packages, pluginName, plugins, parts) => {
         part.full_name = `${pluginName}/${part.name}`;
         parts[part.full_name] = part;
       }
-    } catch (ex) {
+    } catch (err) {
-      console.error(`Unable to parse plugin definition file ${pluginPath}: ${ex.toString()}`);
+      logger.error(`Unable to parse plugin definition file ${pluginPath}: ${err.stack || err}`);
     }
-  } catch (er) {
+  } catch (err) {
-    console.error(`Unable to load plugin definition file ${pluginPath}`);
+    logger.error(`Unable to load plugin definition file ${pluginPath}: ${err.stack || err}`);
   }
 };