Merge pull request #331 from symposion/develop

fix(logging): Improve logging output to track down odd bugs

lib/command-parser.js

@@ -198,7 +198,7 @@ class Command {
       });
     }
 
-    this.handler(finalOptions);
+    return this.handler(finalOptions);
   }
 
   withSelection(selectionSpec) {
@@ -260,7 +260,7 @@ function processSelection(selection, constraints, roll20) {
   }, {});
 }
 
-module.exports = function commandParser(rootCommand, roll20) {
+module.exports = function commandParser(rootCommand, roll20, errorHandler) {
   const commands = {};
   return {
     addCommand(cmds, handler, gmOnly) {
@@ -286,7 +286,11 @@ module.exports = function commandParser(rootCommand, roll20) {
         if (!cmd) {
           throw new UserError(`Unrecognised command ${prefix}${cmdName}`);
         }
-        cmd.handle(parts, msg.selected, `${prefix}${cmdName}`, roll20.playerIsGM(msg.playerid), msg.playerid);
+        const returnVal =
+          cmd.handle(parts, msg.selected, `${prefix}${cmdName}`, roll20.playerIsGM(msg.playerid), msg.playerid);
+        if (returnVal instanceof Promise) {
+          returnVal.catch(errorHandler);
+        }
       }
     },
 

lib/importer.js

@@ -5,6 +5,7 @@ const ShapedConfig = require('./shaped-config');
 const _ = require('underscore');
 const sanitise = require('./sanitise');
 const utils = require('./utils');
+const Logger = require('roll20-logger');
 
 class Importer extends ShapedModule {
   constructor(entityLookup, parser, abilityMaker, srdConverter) {
@@ -169,27 +170,26 @@ class Importer extends ShapedModule {
 
     if (_.isEmpty(options.monsters)) {
       this.showEntityPicker('monster', 'monsters');
+      return null;
     }
-    else {
-      this.importMonsters(options.monsters, options, options.selected.graphic, [])
-        .then((results) => {
-          if (!_.isEmpty(results.importedList)) {
-            const monsterList = results.importedList.map(char => char.get('name')).join('</li><li>');
-            this.reportPlayer('Import Success', `Added the following monsters: <ul><li>${monsterList}</li></ul>`);
-          }
-          if (!_.isEmpty(results.errors)) {
-            const errorList = results.errors.join('</li><li>');
-            this.reportError(`The following errors occurred on import:  <ul><li>${errorList}</li></ul>`);
-          }
-        });
-    }
+    return this.importMonsters(options.monsters, options, options.selected.graphic, [])
+      .then((results) => {
+        if (!_.isEmpty(results.importedList)) {
+          const monsterList = results.importedList.map(char => char.get('name')).join('</li><li>');
+          this.reportPlayer('Import Success', `Added the following monsters: <ul><li>${monsterList}</li></ul>`);
+        }
+        if (!_.isEmpty(results.errors)) {
+          const errorList = results.errors.join('</li><li>');
+          this.reportError(`The following errors occurred on import:  <ul><li>${errorList}</li></ul>`);
+        }
+      });
   }
 
   importByToken(options) {
     const notFound = [];
     const imported = [];
     const errors = [];
-    options.selected.graphic
+    return options.selected.graphic
       .reduce((promise, token) =>
         promise.then((prevImported) => {
           if (prevImported) {
@@ -224,8 +224,7 @@ class Importer extends ShapedModule {
             `${errors.join('</li><li>')}</li></ul>`;
         }
         this.reportPlayer('Monster Import Complete', message);
-      })
-      .catch(this.errorHandler);
+      });
   }
 
   importMonsters(monsters, options, token, characterProcessors) {
@@ -278,8 +277,7 @@ class Importer extends ShapedModule {
             .then((finishedChar) => {
               this.fixRoll20Brokenness(finishedChar);
               importedList.push(finishedChar);
-            })
-            .catch(this.errorHandler);
+            });
         }), Promise.resolve())
       .then(() => {
         this.logger.debug('All monsters imported $$$', importedList);
@@ -293,21 +291,21 @@ class Importer extends ShapedModule {
   importSpellsFromJson(options) {
     if (_.isEmpty(options.spells)) {
       this.showEntityPicker('spell', 'spells');
+      return null;
     }
-    else {
-      this.importData(options.selected.character, _.pick(options, 'spells'))
-        .then(() => {
-          this.reportPlayer('Import Success', 'Added the following spells:  <ul><li>' +
-            `${_.map(options.spells, spell => spell.name).join('</li><li>')}</li></ul>`);
-        });
-    }
+
+    return this.importData(options.selected.character, _.pick(options, 'spells'))
+      .then(() => {
+        this.reportPlayer('Import Success', 'Added the following spells:  <ul><li>' +
+          `${_.map(options.spells, spell => spell.name).join('</li><li>')}</li></ul>`);
+      });
   }
 
   importSpellListFromJson(options) {
     const spells = this.entityLookup.searchEntities('spells', _.pick(options, _.keys(ShapedConfig.spellSearchOptions)));
     const newOpts = _.omit(options, _.keys(ShapedConfig.spellSearchOptions));
     newOpts.spells = spells;
-    this.importSpellsFromJson(newOpts);
+    return this.importSpellsFromJson(newOpts);
   }
 
   fixRoll20Brokenness(character) {
@@ -389,8 +387,7 @@ class Importer extends ShapedModule {
       .then((newChar) => {
         msg.finish();
         return newChar;
-      })
-      .catch(this.errorHandler);
+      });
   }
 
   getSpellAttributesForCharacter(char) {
@@ -470,6 +467,10 @@ class Importer extends ShapedModule {
       this.logger.debug('Importing attributes for stage $$$: $$$', name, attributes);
       msgStreamer.stream(name);
       this.logger.debug(`${name} start`);
+      if (this.logger.getLogLevel() >= Logger.levels.DEBUG) {
+        this.logger.debug('Character attributes at start: $$$',
+          this.roll20.findObjs({ type: 'attribute', characterid: character.id }));
+      }
 
       return _.chain(attributes)
         .reduce((executionGroups, attrVal, attrName) => {
@@ -727,8 +728,7 @@ class Importer extends ShapedModule {
       .then(() => {
         msg.finish();
         this.reportPlayer('Update Complete', `${count} characters checked/updated`);
-      })
-      .catch(this.errorHandler);
+      });
   }
 
   expandSpells(options) {

lib/shaped-module.js

@@ -1,12 +1,11 @@
 'use strict';
 
 module.exports = class ShapedModule {
-  configure(roll20, reporter, logger, myState, errorHandler, commandProcessor) {
+  configure(roll20, reporter, logger, myState, commandProcessor) {
     this.roll20 = roll20;
     this.reporter = reporter;
     this.logger = logger;
     this.myState = myState;
-    this.errorHandler = errorHandler;
     logger.wrapModule(this);
     this.addCommands(commandProcessor);
   }

lib/shaped-script.js

@@ -37,13 +37,6 @@ function ShapedScripts(logger, myState, roll20, parser, entityLookup, reporter)
   let addedTokenIds = [];
   const reportPublic = reporter.reportPublic.bind(reporter);
   const reportError = reporter.reportError.bind(reporter);
-  const commandProc = makeCommandProc('shaped', roll20);
-  const chatWatchers = [];
-  const advantageTracker = new AdvantageTracker();
-  const usesManager = new UsesManager();
-  const ammoManager = new AmmoManager();
-  const abilityMaker = new AbilityMaker();
-  const importer = new Importer(entityLookup, parser, abilityMaker, srdConverter);
   const errorHandler = function errorHandler(e) {
     if (typeof e === 'string' || e instanceof parseModule.ParserError || e instanceof UserError) {
       reportError(e);
@@ -55,6 +48,13 @@ function ShapedScripts(logger, myState, roll20, parser, entityLookup, reporter)
       reportError('An error occurred. Please see the log for more details.');
     }
   };
+  const commandProc = makeCommandProc('shaped', roll20, errorHandler);
+  const chatWatchers = [];
+  const advantageTracker = new AdvantageTracker();
+  const usesManager = new UsesManager();
+  const ammoManager = new AmmoManager();
+  const abilityMaker = new AbilityMaker();
+  const importer = new Importer(entityLookup, parser, abilityMaker, srdConverter);
   const modules = [
     abilityMaker,
     new ConfigUI(),
@@ -65,7 +65,7 @@ function ShapedScripts(logger, myState, roll20, parser, entityLookup, reporter)
     importer,
   ];
 
-  modules.forEach(module => module.configure(roll20, reporter, logger, myState, errorHandler, commandProc));
+  modules.forEach(module => module.configure(roll20, reporter, logger, myState, commandProc));
 
   /**
    *

test/dummy-logger.js

@@ -10,4 +10,6 @@ module.exports = {
   trace: _.noop,
   wrapModule: _.noop,
   wrapFunction: _.noop,
+  getLogLevel: _.constant(1),
+  levels: {},
 };

test/test-importer.js

@@ -48,10 +48,6 @@ const spellAttributes = [
   new Roll20Object('attribute', { name: 'repeating_spell3_6_name', current: 'Counterspell' }),
 ];
 
-function errorHandler(err) {
-  throw err;
-}
-
 describe('importer', function () {
   let roll20;
 
@@ -163,7 +159,7 @@ describe('importer', function () {
       const attributes = {};
       const streamer = { stream: _.noop };
       const importer = new Importer(el.entityLookup, null, null);
-      importer.configure(roll20, new Reporter(), logger, {}, errorHandler, cp);
+      importer.configure(roll20, new Reporter(), logger, {}, cp);
       _.times(100, index => (attributes[`attr${index}`] = index));
       roll20Mock.expects('onSheetWorkerCompleted').twice().yieldsAsync();
       roll20Mock.expects('setAttrWithWorker').exactly(100);
@@ -176,7 +172,7 @@ describe('importer', function () {
       const char = new Roll20Object('character', { name: 'character' });
       const roll20Mock = sinon.mock(roll20);
       const importer = new Importer(el.entityLookup, null, null);
-      importer.configure(roll20, new Reporter(), logger, {}, errorHandler, cp);
+      importer.configure(roll20, new Reporter(), logger, {}, cp);
 
       roll20Mock.expects('findObjs').returns(spellAttributes);
       const spells = importer.getSpellAttributesForCharacter(char);
@@ -193,7 +189,7 @@ describe('importer', function () {
         convertSpells: _.identity,
       };
       const importer = new Importer(el.entityLookup, null, null, srdConverterStub);
-      importer.configure(roll20, new Reporter(), logger, {}, errorHandler, cp);
+      importer.configure(roll20, new Reporter(), logger, {}, cp);
       roll20Mock.expects('findObjs').returns(spellAttributes);
 
       const attributes = importer.getSpellAttributesForImport(char, {},
@@ -215,7 +211,7 @@ describe('importer', function () {
         convertSpells: _.identity,
       };
       const importer = new Importer(el.entityLookup, null, null, srdConverterStub);
-      importer.configure(roll20, new Reporter(), logger, {}, errorHandler, cp);
+      importer.configure(roll20, new Reporter(), logger, {}, cp);
       roll20Mock.expects('findObjs').returns(spellAttributes);
 
       const attributes = importer.getSpellAttributesForImport(char, {},
@@ -236,7 +232,7 @@ describe('importer', function () {
     let importer;
     before(function () {
       importer = new Importer(el.entityLookup, null, null);
-      importer.configure(roll20, new Reporter(), logger, {}, errorHandler, cp);
+      importer.configure(roll20, new Reporter(), logger, {}, cp);
     });
 
     it('should configure senses correctly', function () {
@@ -282,7 +278,7 @@ describe('importer', function () {
     it('debrokens', function () {
       const importer = new Importer(el.entityLookup, null, null);
       sinon.stub(roll20);
-      importer.configure(roll20, new Reporter(), logger, {}, errorHandler, cp);
+      importer.configure(roll20, new Reporter(), logger, {}, cp);
       const attributes = [
         new Roll20Object('attribute', { name: 'foo', current: 1 }),
         new Roll20Object('attribute', { name: 'foo', max: 2 }),
@@ -312,7 +308,7 @@ function runImportMonsterTest(roll20, monsters, options, preConfigure, expectati
   sinon.stub(roll20, 'getObj');
   sinon.stub(roll20, 'setDefaultTokenForCharacter');
   const importer = new Importer(el.entityLookup, null, null, { convertMonster: _.identity });
-  importer.configure(roll20, new Reporter(), logger, { config: { tokenSettings: { light: {} } } }, errorHandler, cp);
+  importer.configure(roll20, new Reporter(), logger, { config: { tokenSettings: { light: {} } } }, cp);
 
   const token = new Roll20Object('graphic');
   token.set('imgsrc', 'imgsrc');

test/test-rest-manager.js

@@ -67,7 +67,7 @@ describe('rest-manager', function () {
     restManager = new RestManager();
     sinon.stub(roll20);
     char = new Roll20Object('character', { name: 'character' });
-    restManager.configure(roll20, null, logger, null, null, cp);
+    restManager.configure(roll20, null, logger, null, cp);
     restManager.rests = testRests;
     restManager.displayTemplates = testTemplates;
   });