Better error logging (#1521)

* DO not use arrow functions for cases not binding this

* Add logging framework to Thimble

* Add error display/reporting framework

* Use error framework to log meaningful error messages

* Fix JSHint errors

* Review fixes

env.dist

@@ -30,6 +30,10 @@ export L10N_SUPPORTED_LANGUAGES="[ "*" ]"
 export L10N_LOCALE_SRC="locales"
 export L10N_LOCALE_DEST="dist/locales"
 
+# Logging level
+# Can be "info" (all logs), "warn" (warning and error logs) or "error" (only error logs)
+export LOG_LEVEL="info"
+
 ##
 # Bramble config, including grunt tasks (see gruntfile.js)
 #

locales/en-US/messages.properties

@@ -224,6 +224,32 @@ prjListDeleteProjectBtnTitle=Delete this Project
 ## Shared ##
 ############
 
+# Errors
+errorDetailsHeader=Error Details
+errorSomethingWentWrong=Oops, something went wrong!
+errorPageNotFound=Oh no, page not found!
+errorPageNotFoundDetails=If you think this page should be here, <br/> let us know.
+errorSomethingWentWrongDetails=Please try what you did again. If you keep seeing this error, let us know.
+errorHttpServiceUnavailable=Service Unavailable ({{ httpStatusCode }})
+errorHttpAuthenticationFailed=Authentication Failed ({{ httpStatusCode }})
+errorHttpClientError=Thimble Application Error ({{ httpStatusCode }})
+errorHttpNotFound=Not Found ({{ httpStatusCode }})
+errorLoadingThimble=Failed to load Thimble!
+errorAuthenticating=Failed to login!
+errorMigratingProject=Failed to recover the project you were working on!
+errorCreatingProject=Failed to create the project!
+errorGettingProjectList=Failed to get the list of your projects!
+errorUpdatingProject=Failed to update the project's details!
+errorRenamingProject=Failed to rename the project!
+errorRenamingProjectFolder=Failed to rename folder for project!
+errorDeletingProject=Failed to delete the project!
+errorPublishingProject=Failed to publish the project!
+errorUnpublishingProject=Failed to unpublish the project!
+errorRemixingProject=Failed to remix the requested project!
+errorGettingProjectFiles=Failed to get the project's files!
+errorCreatingFile=Failed to create new file!
+errorUpdatingFile=Failed to update the file!
+errorDeletingFile=Failed to delete the file!
 
 
 #######################

package.json

@@ -58,7 +58,7 @@
     "less-middleware": "2.0.1",
     "memorystream": "^0.3.1",
     "moment": "^2.11.2",
-    "morgan": "^1.6.1",
+    "morgan": "^1.7.0",
     "multer": "^1.0.1",
     "npm-run-all": "^1.5.1",
     "nunjucks": "^2.3.0",

server/index.js

@@ -13,19 +13,20 @@ let templatize = require("./templatize");
 let Request = require("./request");
 let Security = require("./security");
 let localize = require("./localize");
-let errorhandling = require("./lib/errorhandling");
+let HttpError = require("./lib/http-error.js");
 let middleware = require("./lib/middleware")();
 let routes = require("./routes")();
-let getFileList = require("./lib/utils").getFileList;
+let Utils = require("./lib/utils");
 
 let server = express();
-let isDevelopment = env.get("NODE_ENV") === "development";
+let environment = env.get("NODE_ENV");
+let isDevelopment = environment === "development";
 let root = path.dirname(__dirname);
 let client = path.join(root, isDevelopment ? "client" : "dist");
 let cssAssets = path.join(require("os").tmpDir(), "mozilla.webmaker.org");
 let editor = url.parse(env.get("BRAMBLE_URI"));
 let editorHost = `${editor.protocol}//${editor.host}`;
-const maxCacheAge = { maxAge: "1d" };
+let maxCacheAge = { maxAge: "1d" };
 
 /*
  * Local server variables
@@ -60,10 +61,6 @@ requests.disableHeaders([ "x-powered-by" ])
   },
   proxy: true
 });
-// Logging
-if(isDevelopment) {
-  requests.log("dev");
-}
 
 
 /**
@@ -94,15 +91,17 @@ if(!!env.get("FORCE_SSL")) {
 /**
  * Static assets
  */
-getFileList(path.join(root, "public"), "!(*.js)")
+Utils.getFileList(path.join(root, "public"), "!(*.js)")
 .forEach(file => server.use(express.static(file, maxCacheAge)));
-server.use(express.static(client, maxCacheAge));
 server.use(express.static(cssAssets, maxCacheAge));
 server.use(express.static(path.join(root, "public/resources"), maxCacheAge));
+server.use("/bower", express.static(path.join(root, server.locals.bower_path), maxCacheAge));
+// Start logging requests for routes that serve JS
+requests.enableLogging(environment);
+server.use(express.static(client, maxCacheAge));
 // So that we don't break compatibility with existing published projects,
 // we serve the remix resources through this route as well
 server.use("/resources/remix", express.static(path.join(root, "public/resources/remix"), maxCacheAge));
-server.use("/bower", express.static(path.join(root, server.locals.bower_path), maxCacheAge));
 
 
 /**
@@ -122,8 +121,8 @@ routes.init(server, middleware);
 /*
  * Error handlers
  */
-server.use(errorhandling.errorHandler);
-server.use(errorhandling.pageNotFoundHandler);
+server.use(HttpError.generic);
+server.use(HttpError.notFound);
 
 /*
  * export the server object

server/lib/http-error.js

@@ -0,0 +1,71 @@
+"use strict";
+
+const Nunjucks = require("nunjucks");
+
+class HttpError {
+  static generic(error, request, response, next) {
+    //jshint unused:vars
+    const localeInfo = request.localeInfo;
+    const locale = (localeInfo && localeInfo.locale) || "en-US";
+    const statusCode = response.statusCode || 500;
+    let statusMessage = statusCode;
+    const statusMessageKey = HttpError.getStatusMessageKey(statusCode);
+
+    if(statusMessageKey) {
+      statusMessage = Nunjucks.renderString(
+        request.gettext(statusMessageKey, locale),
+        { httpStatusCode: statusCode }
+      );
+    }
+
+    const userFriendlyError = {
+      statusMessage,
+      status: statusCode,
+      message: error.userMessage || error
+    };
+
+    response.format({
+      text() {
+        response.send(`${userFriendlyError.statusMessage}: ${userFriendlyError.message}`);
+      },
+      html() {
+        response.render("error.html", userFriendlyError);
+      },
+      json() {
+        response.send(userFriendlyError);
+      },
+      default() {
+        response.send(userFriendlyError);
+      }
+    });
+
+    request.log.error(error);
+  }
+
+  static notFound(request, response, next) {
+    //jshint unused:vars
+    response.status(404);
+    response.render("error.html", { status: 404 });
+  }
+
+  static getStatusMessageKey(statusCode) {
+    return statusCode >= 500 ? "errorHttpServiceUnavailable"
+      : (statusCode >= 405 || statusCode === 400) ? "errorHttpClientError"
+      : statusCode === 404 ? "errorHttpNotFound"
+      : statusCode >= 401 ? "errorHttpAuthenticationFailed"
+      : null;
+  }
+
+  static format(error, request) {
+    const localeInfo = request.localeInfo;
+    const locale = (localeInfo && localeInfo.locale) || "en-US";
+    const userMessageKey = request.errorMessageKey;
+
+    error.userMessage = request.gettext(userMessageKey, locale);
+    error.locale = localeInfo && localeInfo.lang;
+
+    return error;
+  }
+}
+
+module.exports = HttpError;

server/lib/middleware.js

@@ -8,7 +8,7 @@ let cors = require("cors");
 let Cryptr = require("cryptr");
 
 let env = require("./environment");
-let utils = require("./utils");
+let HttpError = require("./http-error");
 
 let upload = multer({
   dest: require("os").tmpdir(),
@@ -37,6 +37,18 @@ module.exports = function middlewareConstructor() {
       });
     },
 
+    /**
+     * On the request, set the key to use for user error messages
+     * Takes a function or a string. If it is a function,
+     * it is called with the request to get the error message's key.
+     */
+    setErrorMessage(errorMessageKey) {
+      return function(req, res, next) {
+        req.errorMessageKey = typeof errorMessageKey === "function" ? errorMessageKey(req) : errorMessageKey;
+        next();
+       };
+     },
+
     /**
      * Check whether the requesting user has been authenticated.
      */
@@ -85,13 +97,24 @@ module.exports = function middlewareConstructor() {
     validateRequest(properties) {
       return function(req, res, next) {
         let valid = !!req.body &&
-          properties.every(prop => req.body[prop] !== null && req.body[prop] !== undefined);
+          properties.every(function(prop) {
+            return req.body[prop] !== null && req.body[prop] !== undefined;
+          });
 
-        if(!valid) {
-          next(utils.error(400, "Request body missing data"));
-        } else {
-          next();
+        if(valid) {
+          return next();
         }
+
+        res.status(400);
+        next(
+          HttpError.format({
+            message: `Data validation in middleware failed for ${req.originalUrl}`,
+            context: {
+              expected: properties,
+              actual: req.body
+            }
+          }, req)
+        );
       };
     },
 
@@ -106,23 +129,37 @@ module.exports = function middlewareConstructor() {
         return next();
       }
 
+      let userUrl = `${publishHost}/users/login`;
+
       request({
         method: "POST",
-        url: `${publishHost}/users/login`,
+        url: userUrl,
         headers: {
           "Authorization": `token ${user.token}`
         },
         body: {
           name: user.username
         },
         json: true
-      }, (err, response, body) => {
+      }, function(err, response, body) {
         if(err) {
-          return next(utils.error(500));
+          res.status(500);
+          return next(
+            HttpError.format({
+              message: `Failed to send request to ${userUrl}`,
+              context: err
+            }, req)
+          );
         }
 
-        if(response.statusCode !== 200 &&  response.statusCode !== 201) {
-          return next(utils.error(response.statusCode, response.body));
+        if(response.statusCode !== 200 && response.statusCode !== 201) {
+          res.status(response.statusCode);
+          return next(
+            HttpError.format({
+              message: `Request to ${userUrl} returned a status of ${response.statusCode}`,
+              context: response.body
+            }, req)
+          );
         }
 
         req.user.publishId = body.id;
@@ -141,26 +178,46 @@ module.exports = function middlewareConstructor() {
         return next();
       }
 
+      let projectUrl = `${publishHost}/projects/${projectId}`;
+
       // Get project data from publish.wm.org
       request.get({
-        url: `${publishHost}/projects/${projectId}`,
+        url: projectUrl,
         headers: {
           "Authorization": `token ${req.user.token}`
         }
-      }, (err, response, body) => {
+      }, function(err, response, body) {
         if(err) {
-          return next(utils.error(500));
+          res.status(500);
+          return next(
+            HttpError.format({
+              message: `Failed to send request to ${projectUrl}`,
+              context: err
+            }, req)
+          );
         }
 
         if(response.statusCode !== 200) {
-          return next(utils.error(response.statusCode, response.body));
+          res.status(response.statusCode);
+          return next(
+            HttpError.format({
+              message: `Request to ${projectUrl} returned a status of ${response.statusCode}`,
+              context: response.body
+            }, req)
+          );
         }
 
         try {
           req.project = JSON.parse(body);
         } catch(e) {
-          console.error("Failed to parse project sent by the publish server in `setProject` middleware with ", e);
-          return next(utils.error(500));
+          res.status(500);
+          return next(
+            HttpError.format({
+              message: "Project data received from the publish server was in an invalid format. Failed to run `JSON.parse`",
+              context: e.message,
+              stack: e.stack
+            }, req)
+          );
         }
 
         next();