for #55: convert console to mozlog

.env-dist

@@ -4,6 +4,9 @@ SERVER_URL=http://localhost:6060
 PORT=6060
 COOKIE_SECRET=3895d33b5f9730f5eb2a2067fe0a690e298f55f5e382c032fd3656863412
 
+# see https://www.npmjs.com/package/mozlog
+MOZLOG_LEVEL=debug
+
 # 1: disables the dockerflow endpoints
 # see: https://github.com/mozilla-services/Dockerflow#containerized-app-requirements
 DISABLE_DOCKERFLOW=

app-constants.js

@@ -19,6 +19,7 @@ const kEnvironmentVariables = [
   "BASKET_API_KEY",
   "BASKET_NEWSLETTER",
   "FXA_ENABLED",
+  "MOZLOG_LEVEL",
   "OAUTH_AUTHORIZATION_URI",
   "OAUTH_TOKEN_URI",
   "OAUTH_PROFILE_URI",

controllers/dockerflow.js

@@ -5,18 +5,21 @@ const path = require("path");
 
 const {version, homepage} = require("../package.json");
 
+const mozlog = require("../log");
 
+
+const log = mozlog("dockerflow");
 const versionJsonPath = path.join(__dirname, "..", "version.json");
 
 // If the version.json file already exists (e.g., created by circle + docker),
 // don't need to generate it
 if (!fs.existsSync(versionJsonPath)) {
-  console.log("Could not find version.json, generating ...");
+  log.info("generating");
   let commit;
   try {
     commit = require("git-rev-sync").short();
   } catch (err) {
-    console.error("Error in git-rev-sync: ", err);
+    log.error("generating", {err: err});
   }
 
   const versionJson = {

controllers/hibp.js

@@ -6,6 +6,11 @@ const EmailUtils = require("../email-utils");
 const HIBP = require("../hibp");
 const sha1 = require("../sha1-utils");
 const HBSHelpers = require("../hbs-helpers");
+const mozlog = require("../log");
+
+
+const log = mozlog("controllers.hibp");
+
 
 async function notify (req, res) {
   if(!["breachName", "hashPrefix", "hashSuffixes"].every(req.body.hasOwnProperty, req.body)) {
@@ -29,7 +34,7 @@ async function notify (req, res) {
   const hashes = req.body.hashSuffixes.map(suffix=>reqHashPrefix + suffix.toLowerCase());
   const subscribers = await DB.getSubscribersByHashes(hashes);
 
-  console.log(`Found ${subscribers.length} subscribers in ${breachAlert.Name}. Notifying ...`);
+  log.info("notification", { length: subscribers.length, breachAlertName: breachAlert.Name });
 
   const notifiedSubscribers = [];
 
@@ -57,7 +62,7 @@ async function notify (req, res) {
       notifiedSubscribers.push(email);
     }
   }
-  console.log(`Notified ${notifiedSubscribers.length} unique subscribers.`);
+  log.info("notified", { length: notifiedSubscribers.length });
   res.status(200);
   res.json(
     {info: "Notified subscribers of breach."}

controllers/ses.js

@@ -4,8 +4,11 @@ const MessageValidator = require("sns-validator");
 
 const DB = require("../db/DB");
 
+const mozlog = require("../log");
+
 
 const validator = new MessageValidator();
+const log = mozlog("controllers.ses");
 
 
 async function notification(req, res) {
@@ -13,7 +16,7 @@ async function notification(req, res) {
   return new Promise((resolve, reject) => {
     validator.validate(message, async (err, message) => {
       if (err) {
-        console.error(err);
+        log.error(err);
         const body = "Access denied. " + err.message;
         res.status(401).send(body);
         return reject(body);
@@ -31,7 +34,7 @@ async function notification(req, res) {
 
 
 async function handleNotification(notification) {
-  console.log("Received SES message, ID: ", notification.MessageId);
+  log.info("received-SES", { id: notification.MessageId });
   const message = JSON.parse(notification.Message);
   switch (message.eventType) {
     case "Bounce":
@@ -41,7 +44,7 @@ async function handleNotification(notification) {
       await handleComplaintMessage(message);
       break;
     default:
-      console.log("Unhandled eventType: ", message.eventType);
+      log.info("unhandled-eventType", { type: message.eventType });
   }
 }
 

db/DB.js

@@ -9,9 +9,12 @@ const AppConstants = require("../app-constants");
 const HIBP = require("../hibp");
 const Basket = require("../basket");
 const getSha1 = require("../sha1-utils");
+const mozlog = require("../log");
 
 const knexConfig = require("./knexfile");
+
 let knex = Knex(knexConfig);
+const log = mozlog("DB");
 
 
 const DB = {
@@ -131,10 +134,10 @@ const DB = {
       await knex("subscribers")
         .where("id", "=", aEntry.id)
         .del();
-      console.log("Removed subscriber ID: ", aEntry.id);
+      log.info("removed-subscriber", { id: aEntry.id });
       return aEntry;
     }, async () => {
-      console.warn("removeSubscriber called with email not found in database.");
+      log.warn("removed-subscriber-not-found");
       return;
     });
   },

email-utils.js

@@ -6,8 +6,11 @@ const nodemailer = require("nodemailer");
 const hbs = require("nodemailer-express-handlebars");
 
 const HBSHelpers = require("./hbs-helpers");
+const mozlog = require("./log");
 
 
+const log = mozlog("email-utils");
+
 const hbsOptions = {
   viewEngine: {
     extname: ".hbs",
@@ -29,7 +32,7 @@ const EmailUtils = {
 
     // Allow a debug mode that will log JSON instead of sending emails.
     if (!smtpUrl) {
-      console.info("smtpUrl is empty, EmailUtils will log a JSON response instead of sending emails.");
+      log.info("smtpUrl-empty", { message: "EmailUtils will log a JSON response instead of sending emails." });
       gTransporter = nodemailer.createTransport({jsonTransport: true});
       return Promise.resolve(true);
     }
@@ -67,7 +70,7 @@ const EmailUtils = {
           return;
         }
         if (gTransporter.transporter.name === "JSONTransport") {
-          console.log(info.message.toString());
+          log.info("JSONTransport", { message: info.message.toString() });
         }
         resolve(info);
       });

hbs-helpers.js

@@ -1,5 +1,10 @@
 "use strict";
 
+const mozlog = require("./log");
+
+
+const log = mozlog("hbs-helpers");
+
 function breachDataClasses(dataClasses) {
   if (dataClasses.constructor === Array) {
     return dataClasses.join(", ");
@@ -49,7 +54,8 @@ function ifCompare(v1, operator, v2, options) {
     }
     return options.inverse(this);
   }
-  return console.error(`Error: ${operator} not found`);
+  log.error("ifCompare", {message: `${operator} not found`});
+  return;
 }
 
 

hibp.js

@@ -5,11 +5,13 @@ const createDOMPurify = require("dompurify");
 const { JSDOM } = require("jsdom");
 
 const AppConstants = require("./app-constants");
+const mozlog = require("./log");
 const pkg = require("./package.json");
 
 
 const DOMPurify = createDOMPurify((new JSDOM("")).window);
 const HIBP_USER_AGENT = `${pkg.name}/${pkg.version}`;
+const log = mozlog("hibp");
 
 
 const HIBP = {
@@ -29,14 +31,14 @@ const HIBP = {
       response = await got(url, reqOptions);
       return response;
     } catch (err) {
-      console.error("got an error: " + err);
+      log.error("_throttledGot", {err: err});
       if (err.statusCode === 404) {
         // 404 can mean "no results", return undefined response; sorry calling code
         return response;
       } else if (err.statusCode === 429) {
-        console.log("got a 429, tryCount: ", tryCount);
+        log.info("_throttledGot", {err: "got a 429, tryCount: " + tryCount});
         if (tryCount >= AppConstants.HIBP_THROTTLE_MAX_TRIES) {
-          console.error(err.message);
+          log.error("_throttledGot", {err: err});
           throw new Error("Too many connections to HIBP.");
         } else {
           tryCount++;
@@ -63,7 +65,7 @@ const HIBP = {
   },
 
   async loadBreachesIntoApp(app) {
-    console.log("Loading breaches from HIBP into app.locals");
+    log.info("loadBreachesIntoApp", {});
     try {
       const breachesResponse = await this.req("/breaches");
       const breaches = [];
@@ -80,7 +82,7 @@ const HIBP = {
     } catch (error) {
       throw new Error("Could not load breaches: " + error);
     }
-    console.log("Done loading breaches.");
+    log.info("Done loading breaches");
   },
 
   async getUnsafeBreachesForEmail(sha1, allBreaches) {

log.js

@@ -0,0 +1,14 @@
+"use strict";
+
+const mozlog = require("mozlog");
+
+const AppConstants = require("./app-constants");
+
+
+const log = mozlog({
+  app: "fx-monitor",
+  level: AppConstants.MOZLOG_LEVEL,
+});
+
+
+module.exports = log;

middleware.js

@@ -1,6 +1,9 @@
 "use strict";
 
+const mozlog = require("./log");
 
+
+const log = mozlog("middleware");
 // Helps handle errors for all async route controllers
 // See https://medium.com/@Abazhenov/using-async-await-in-express-with-node-8-b8af872c0016
 function asyncMiddleware (fn) {
@@ -11,7 +14,7 @@ function asyncMiddleware (fn) {
 
 
 function logErrors (err, req, res, next) {
-  console.error(err.stack);
+  log.error("error", {stack: err.stack});
   next(err);
 }
 

package.json

@@ -24,6 +24,7 @@
     "isemail": "^3.1.3",
     "jsdom": "^11.11.0",
     "knex": "^0.14.6",
+    "mozlog": "^2.2.0",
     "nodemailer": "^4.6.4",
     "nodemailer-express-handlebars": "^3.0.0",
     "pg": "^7.4.3",

routes/ses.js

@@ -4,15 +4,17 @@ const bodyParser = require("body-parser");
 const express = require("express");
 
 const AppConstants = require("../app-constants");
+const mozlog = require("../log");
 const {notification} = require("../controllers/ses");
 
 
+const log = mozlog("routes.ses");
 const router = express.Router();
 const textParser = bodyParser.text();
 
 if (AppConstants.SES_NOTIFICATION_LOG_ONLY) {
   router.post("/notification", textParser, (req, res, next) => {
-    console.log("SES Notification request body: ", req.body);
+    log.info("ses-notification-body", { body: req.body });
   });
 } else {
   router.post("/notification", textParser, notification);

scripts/notify-subscribers-of-breach.js

@@ -1,46 +0,0 @@
-"use strict";
-
-const DBUtils = require("../db/DB");
-const EmailUtils = require("../email-utils");
-
-
-const breachName = process.argv[2];
-if (!breachName) {
-  throw("Usage: node notify-subscribers-of-breach.js \"breach-name\"");
-}
-
-EmailUtils.init();
-
-
-async function notifySubscribersOfNewBreach(breachName) {
-  // FIXME: TODO: change to load breaches from HIBP
-  const breach = await DBUtils.getBreachByName(breachName);
-  console.log("Found breach: ", breach);
-  // FIXME: TODO: change to updated DB module code
-  const breachedSubscribers = await DBUtils.getSubscribersForBreach(breach);
-  console.log(`Found ${breachedSubscribers.length} un-notified subscribers in the breach`);
-  for (const subscriber of breachedSubscribers) {
-    console.log(`Sending email to subscriber ID: ${subscriber.id} ...`);
-    const subject = `${subscriber.email} was involved in the ${breach.name} breach.`;
-    try {
-      await EmailUtils.sendEmail(
-        subscriber.email,
-        subject,
-        "breach_notification",
-        { email: subscriber.email, breach: breach }
-      );
-      console.log("DONE sending email.");
-      console.log("Setting notified=true ...");
-      // FIXME: TODO: change to updated DB module code
-      await DBUtils.setBreachedHashNotified(breach, subscriber.email);
-      console.log("DONE setting notified=true");
-    } catch (e) {
-      console.log(e);
-    }
-  }
-}
-
-(async () => {
-  await notifySubscribersOfNewBreach(breachName);
-  process.exit();
-})();

server.js

@@ -12,6 +12,7 @@ const EmailUtils = require("./email-utils");
 const HBSHelpers = require("./hbs-helpers");
 const HIBP = require("./hibp");
 const {logErrors, clientErrorHandler, errorHandler} = require("./middleware");
+const mozlog = require("./log");
 
 const HibpRoutes = require("./routes/hibp");
 const HomeRoutes = require("./routes/home");
@@ -21,6 +22,7 @@ const OAuthRoutes = require("./routes/oauth");
 const UserRoutes = require("./routes/user");
 
 
+const log = mozlog("server");
 const app = express();
 
 // Redirect non-dev environments to HTTPS
@@ -40,7 +42,7 @@ if (app.get("env") !== "dev") {
   try {
     await HIBP.loadBreachesIntoApp(app);
   } catch (error) {
-    console.error(error);
+    log.error(error);
   }
 })();
 
@@ -114,8 +116,8 @@ app.use(errorHandler);
 
 EmailUtils.init().then(() => {
   const listener = app.listen(AppConstants.PORT, () => {
-    console.info(`Listening on ${listener.address().port}`);
+    log.info("Listening", {port: listener.address().port});
   });
 }).catch(error => {
-  console.error(error);
+  log.error(error);
 });