Added more comprehensive logging to FlowControl ops and added '>' prefix to all ChefWorker logs to improve clarity

package-lock.json

@@ -2436,12 +2436,31 @@
         "event-emitter": "0.3.5"
       }
     },
+    "es6-object-assign": {
+      "version": "1.1.0",
+      "resolved": "https://registry.npmjs.org/es6-object-assign/-/es6-object-assign-1.1.0.tgz",
+      "integrity": "sha1-wsNYJlYkfDnqEHyx5mUrb58kUjw="
+    },
+    "es6-polyfills": {
+      "version": "2.0.0",
+      "resolved": "https://registry.npmjs.org/es6-polyfills/-/es6-polyfills-2.0.0.tgz",
+      "integrity": "sha1-fzWP04jYyIjQDPyaHuqJ+XFoOTE=",
+      "requires": {
+        "es6-object-assign": "1.1.0",
+        "es6-promise-polyfill": "1.2.0"
+      }
+    },
     "es6-promise": {
       "version": "4.0.5",
       "resolved": "https://registry.npmjs.org/es6-promise/-/es6-promise-4.0.5.tgz",
       "integrity": "sha1-eILzCt3lskDM+n99eMVIMwlRrkI=",
       "dev": true
     },
+    "es6-promise-polyfill": {
+      "version": "1.2.0",
+      "resolved": "https://registry.npmjs.org/es6-promise-polyfill/-/es6-promise-polyfill-1.2.0.tgz",
+      "integrity": "sha1-84kl8jyz4+jObNqP93T867sJDN4="
+    },
     "es6-set": {
       "version": "0.1.5",
       "resolved": "https://registry.npmjs.org/es6-set/-/es6-set-0.1.5.tgz",
@@ -6134,6 +6153,15 @@
       "resolved": "https://registry.npmjs.org/loglevel/-/loglevel-1.6.0.tgz",
       "integrity": "sha1-rgyqVhERSYxboTcj1vtjHSQAOTQ="
     },
+    "loglevel-message-prefix": {
+      "version": "3.0.0",
+      "resolved": "https://registry.npmjs.org/loglevel-message-prefix/-/loglevel-message-prefix-3.0.0.tgz",
+      "integrity": "sha1-ER/bltlPlh2PyLiqv7ZrBqw+dq0=",
+      "requires": {
+        "es6-polyfills": "2.0.0",
+        "loglevel": "1.6.0"
+      }
+    },
     "longest": {
       "version": "1.0.1",
       "resolved": "https://registry.npmjs.org/longest/-/longest-1.0.1.tgz",

package.json

@@ -88,6 +88,7 @@
     "jsrsasign": "8.0.4",
     "lodash": "^4.17.4",
     "loglevel": "^1.6.0",
+    "loglevel-message-prefix": "^3.0.0",
     "moment": "^2.20.1",
     "moment-timezone": "^0.5.14",
     "node-md6": "^0.1.0",

src/core/ChefWorker.js

@@ -11,6 +11,15 @@ import Chef from "./Chef.js";
 import OperationConfig from "./config/MetaConfig.js";
 import OpModules from "./config/modules/Default.js";
 
+// Add ">" to the start of all log messages in the Chef Worker
+import loglevelMessagePrefix from "loglevel-message-prefix";
+
+loglevelMessagePrefix(log, {
+    prefixes: [],
+    staticPrefixes: [">"],
+    prefixFormat: "%p"
+});
+
 
 // Set up Chef instance
 self.chef = new Chef();
@@ -91,7 +100,7 @@ async function bake(data) {
         );
 
         self.postMessage({
-            action: "bakeSuccess",
+            action: "bakeComplete",
             data: response
         });
     } catch (err) {

src/core/FlowControl.js

@@ -56,6 +56,7 @@ const FlowControl = {
 
         // Run recipe over each tranche
         for (i = 0; i < inputs.length; i++) {
+            log.debug(`Entering tranche ${i + 1} of ${inputs.length}`);
             const dish = new Dish(inputs[i], inputType);
             try {
                 progress = await recipe.execute(dish, 0);
@@ -169,16 +170,19 @@ const FlowControl = {
      * @returns {Object} The updated state of the recipe.
      */
     runJump: function(state) {
-        let ings     = state.opList[state.progress].getIngValues(),
+        const ings     = state.opList[state.progress].getIngValues(),
-            jmpIndex = FlowControl._getLabelIndex(ings[0], state),
+            label = ings[0],
-            maxJumps = ings[1];
+            maxJumps = ings[1],
+            jmpIndex = FlowControl._getLabelIndex(label, state);
 
         if (state.numJumps >= maxJumps || jmpIndex === -1) {
+            log.debug("Maximum jumps reached or label cannot be found");
             return state;
         }
 
         state.progress = jmpIndex;
         state.numJumps++;
+        log.debug(`Jumping to label '${label}' at position ${jmpIndex} (jumps = ${state.numJumps})`);
         return state;
     },
 
@@ -194,14 +198,16 @@ const FlowControl = {
      * @returns {Object} The updated state of the recipe.
      */
     runCondJump: function(state) {
-        let ings     = state.opList[state.progress].getIngValues(),
+        const ings     = state.opList[state.progress].getIngValues(),
             dish     = state.dish,
             regexStr = ings[0],
             invert   = ings[1],
-            jmpIndex = FlowControl._getLabelIndex(ings[2], state),
+            label    = ings[2],
-            maxJumps = ings[3];
+            maxJumps = ings[3],
+            jmpIndex = FlowControl._getLabelIndex(label, state);
 
         if (state.numJumps >= maxJumps || jmpIndex === -1) {
+            log.debug("Maximum jumps reached or label cannot be found");
             return state;
         }
 
@@ -210,6 +216,7 @@ const FlowControl = {
             if (!invert && strMatch || invert && !strMatch) {
                 state.progress = jmpIndex;
                 state.numJumps++;
+                log.debug(`Jumping to label '${label}' at position ${jmpIndex} (jumps = ${state.numJumps})`);
             }
         }
 
@@ -249,6 +256,7 @@ const FlowControl = {
     /**
      * Returns the index of a label.
      *
+     * @private
      * @param {Object} state
      * @param {string} name
      * @returns {number}

src/core/Recipe.js

@@ -146,10 +146,11 @@ Recipe.prototype.lastOpIndex = function(startIndex) {
 Recipe.prototype.execute = async function(dish, startFrom) {
     startFrom = startFrom || 0;
     let op, input, output, numJumps = 0, numRegisters = 0;
+    log.debug(`[*] Executing recipe of ${this.opList.length} operations, starting at ${startFrom}`);
 
     for (let i = startFrom; i < this.opList.length; i++) {
         op = this.opList[i];
-        log.debug(`[${i}] ${op.name}`);
+        log.debug(`[${i}] ${op.name} ${JSON.stringify(op.getIngValues())}`);
         if (op.isDisabled()) {
             log.debug("Operation is disabled, skipping");
             continue;

src/web/App.js

@@ -49,9 +49,11 @@ App.prototype.setup = function() {
     this.manager.setup();
     this.resetLayout();
     this.setCompileMessage();
-    this.loadURIParams();
 
+    log.debug("App loaded");
     this.appLoaded = true;
+
+    this.loadURIParams();
     this.loaded();
 };
 

src/web/Manager.js

@@ -119,7 +119,7 @@ Manager.prototype.initialiseEventListeners = function() {
     this.addDynamicListener(".op-list .op-icon", "mouseover", this.ops.opIconMouseover, this.ops);
     this.addDynamicListener(".op-list .op-icon", "mouseleave", this.ops.opIconMouseleave, this.ops);
     this.addDynamicListener(".op-list", "oplistcreate", this.ops.opListCreate, this.ops);
-    this.addDynamicListener("li.operation", "operationadd", this.recipe.opAdd.bind(this.recipe));
+    this.addDynamicListener("li.operation", "operationadd", this.recipe.opAdd, this.recipe);
 
     // Recipe
     this.addDynamicListener(".arg:not(select)", "input", this.recipe.ingChange, this.recipe);

src/web/RecipeWaiter.js

@@ -253,7 +253,7 @@ RecipeWaiter.prototype.breakpointClick = function(e) {
  */
 RecipeWaiter.prototype.operationDblclick = function(e) {
     e.target.remove();
-    window.dispatchEvent(this.manager.statechange);
+    this.opRemove(e);
 };
 
 
@@ -266,7 +266,7 @@ RecipeWaiter.prototype.operationDblclick = function(e) {
  */
 RecipeWaiter.prototype.operationChildDblclick = function(e) {
     e.target.parentNode.remove();
-    window.dispatchEvent(this.manager.statechange);
+    this.opRemove(e);
 };
 
 
@@ -421,6 +421,7 @@ RecipeWaiter.prototype.dropdownToggleClick = function(e) {
  * @param {event} e
  */
 RecipeWaiter.prototype.opAdd = function(e) {
+    log.debug(`'${e.target.querySelector(".arg-title").textContent}' added to recipe`);
     window.dispatchEvent(this.manager.statechange);
 };
 
@@ -433,6 +434,7 @@ RecipeWaiter.prototype.opAdd = function(e) {
  * @param {event} e
  */
 RecipeWaiter.prototype.opRemove = function(e) {
+    log.debug("Operation removed from recipe");
     window.dispatchEvent(this.manager.statechange);
 };
 

src/web/WorkerWaiter.js

@@ -45,7 +45,7 @@ WorkerWaiter.prototype.handleChefMessage = function(e) {
     log.debug("Receiving '" + r.action + "' from ChefWorker");
 
     switch (r.action) {
-        case "bakeSuccess":
+        case "bakeComplete":
             this.bakingComplete(r.data);
             break;
         case "bakeError":
@@ -56,6 +56,7 @@ WorkerWaiter.prototype.handleChefMessage = function(e) {
             break;
         case "workerLoaded":
             this.app.workerLoaded = true;
+            log.debug("ChefWorker loaded");
             this.app.loaded();
             break;
         case "statusMessage":
@@ -118,6 +119,7 @@ WorkerWaiter.prototype.bakingComplete = function(response) {
     this.app.progress = response.progress;
     this.manager.recipe.updateBreakpointIndicator(response.progress);
     this.manager.output.set(response.result, response.type, response.duration);
+    log.debug("--- Bake complete ---");
 };