Fix #2177, change console.* server messages to use mozlog (#2858)

server/src/jobs.js

@@ -9,7 +9,7 @@ let checkDeletedInterval = config.checkDeletedInterval * 1000;
 
 exports.start = function() {
   if (config.disableControllerTasks) {
-    console.info("Note: not performing periodic tasks in this server");
+    mozlog.info("no-periodic-tasks", {msg: "Note: not performing periodic tasks in this server"});
     return;
   }
 

server/src/pages/leave-screenshots/server.js

@@ -2,6 +2,7 @@ const express = require("express");
 const csrf = require('csurf');
 const reactrender = require("../../reactrender");
 const { Shot } = require("../../servershot");
+const mozlog = require("mozlog")("leave-screenshots");
 
 const csrfProtection = csrf({cookie: true});
 let app = express();
@@ -24,7 +25,7 @@ app.post("/leave", csrfProtection, function(req, res) {
   Shot.deleteEverythingForDevice(req.backend, req.deviceId).then(() => {
     res.redirect("/leave-screenshots/?complete");
   }).catch((e) => {
-    console.error("An error occurred trying to delete:", e);
+    mozlog.error("delete-account-error", {msg: "An error occurred trying to delete account", error: e});
     res.status(500).send("An error occurred");
   });
 });

server/src/pages/metrics/server.js

@@ -3,6 +3,7 @@ const reactrender = require("../../reactrender");
 const { checkLastStoreQueriesTime, storeQueries } = require("./model");
 const config = require("../../config").getProperties();
 const { captureRavenException } = require("../../ravenclient");
+const mozlog = require("mozlog")("metrics");
 
 let app = exports.app = express();
 
@@ -20,11 +21,11 @@ function safeStoreQueries() {
   checkLastStoreQueriesTime().then((time) => {
     if ((!time) || Date.now() - time.getTime() > config.refreshMetricsTime * 1000) {
       return storeQueries().then(() => {
-        console.info("Updated metrics");
+        mozlog.info("updated-metrics", {msg: "Updated metrics"});
       });
     }
   }).catch((error) => {
-    console.error("Error running metrics queries:", error);
+    mozlog.error("metrics-update-error", {msg: "Error running metrics queries", error});
     captureRavenException(error);
   });
 }
@@ -37,7 +38,7 @@ if (config.refreshMetricsTime && !config.disableControllerTasks) {
   }
   setInterval(safeStoreQueries, interval);
 } else {
-  console.info("Not running periodic metrics updating");
+  mozlog.info("no-periodic-metrics", {msg: "Not running periodic metrics updating"});
 }
 
 if (!config.disableControllerTasks) {

server/src/pages/shotindex/server.js

@@ -2,6 +2,7 @@ const express = require("express");
 const csrf = require("csurf");
 const reactrender = require("../../reactrender");
 const { Shot } = require("../../servershot");
+const mozlog = require("mozlog")("shotindex");
 
 let app = express();
 
@@ -20,7 +21,7 @@ app.get("/", csrf({cookie: true}), function(req, res) {
   getShots.then(_render)
     .catch((err) => {
       res.type("txt").status(500).send("Error rendering page: " + err);
-      console.error("Error rendering page:", err);
+      mozlog.error("error-rendering", {msg: "Error rendering page", error: err});
     });
 
   function _render(shots) {

server/src/responses.js

@@ -1,5 +1,6 @@
 const config = require("./config").getProperties();
 const { captureRavenException } = require("./ravenclient");
+const mozlog = require("mozlog")("server");
 
 exports.simpleResponse = function(res, message, status) {
   status = status || 200;
@@ -27,6 +28,6 @@ exports.errorResponse = function(res, message, err) {
   } else {
     res.send("Server error");
   }
-  console.error(`Error: ${message}`, err + "", err);
+  mozlog.error("generic-error-response", {msg: message, error: err});
   captureRavenException(err);
 };

server/src/server.js

@@ -42,6 +42,7 @@ console.info = logFactory("info");
 console.warn = logFactory("warn");
 console.error = logFactory("error");
 
+const mozlog = require("mozlog")("server");
 const path = require('path');
 const { readFileSync, existsSync } = require('fs');
 const Cookies = require("cookies");
@@ -101,17 +102,17 @@ if (config.useS3) {
   // Test a PUT to s3 because configuring this requires using the aws web interface
   // If the permissions are not set up correctly, then we want to know that asap
   var s3bucket = new AWS.S3({params: {Bucket: config.s3BucketName}});
-  console.info(new Date(), `creating ${config.s3BucketName}`);
+  mozlog.info("creating-s3-bucket", {msg: `creating ${config.s3BucketName}`, bucketName: config.s3BucketName});
 
   // createBucket is a horribly named api; it creates a local object to access
   // an existing bucket
   s3bucket.createBucket(function() {
     var params = {Key: 'test', Body: 'Hello!'};
-    s3bucket.upload(params, function(err, data) {
-      if (err) {
-        console.warn("Error uploading data during test: ", err);
+    s3bucket.upload(params, function(error, data) {
+      if (error) {
+        mozlog.warn("test-upload-error", {msg: "Error uploading data during test", error, bucketName: config.s3BucketName});
       } else {
-        console.info(`Successfully uploaded data to ${config.s3BucketName}/test`);
+        mozlog.info("test-upload-success", {msg: `Successfully uploaded data to ${config.s3BucketName}/test`, bucketName: config.s3BucketName})
       }
     });
   });
@@ -126,16 +127,16 @@ function initDatabase() {
     },
     (e) => {
       hadError = true;
-      console.error("Error forcing database version:", forceDbVersion, e);
+      mozlog.error("database-version-update-error", {msg: "Error forcing database version:", dbVersion: forceDbVersion, error: e});
     }).then(() => {
-      console.info("Exiting after downgrade");
+      mozlog.info("database-version-update-exit", {msg: "Exiting after downgrade"});
       process.exit(hadError ? 2 : 0);
     });
     return;
   }
   let promise;
   if (config.disableControllerTasks) {
-    console.info("Note: this server will not perform database initialization");
+    mozlog.info("database-version-update-skipped", {msg: "Note: this server will not perform database initialization"});
     promise = dbschema.createKeygrip();
   } else {
     promise = dbschema.createTables().then(() => {
@@ -145,7 +146,7 @@ function initDatabase() {
     });
   }
   promise.catch((e) => {
-    console.error("Error initializing database:", e, e.stack);
+    mozlog.error("database-version-update-error", {msg: "Error initializing database:", error: e, stack: e.stack});
     captureRavenException(e);
     // Give Raven/etc a chance to work before exit:
     setTimeout(() => {
@@ -424,7 +425,7 @@ app.post("/error", function(req, res) {
     applicationVersion: bodyObj.version,
     exceptionDescription: desc
   }).send();
-  console.info("Error received:", desc);
+  mozlog.info("remote-error", {msg: "Error received:", description: desc});
   simpleResponse(res, "OK", 200);
 });
 
@@ -510,7 +511,7 @@ app.get("/redirect", function(req, res) {
     res.status(200);
     let redirectUrl = req.query.to;
     if (!validUrl.isUri(redirectUrl)) {
-      console_mozlog.warn("redirect-bad-url", {msg: "Redirect attempted to invalid URL", url: redirectUrl});
+      mozlog.warn("redirect-bad-url", {msg: "Redirect attempted to invalid URL", url: redirectUrl});
       sendRavenMessage(req, "Redirect attempted to invalid URL", {extra: {redirectUrl}});
       simpleResponse(res, "Bad Request", 400);
       return;
@@ -529,7 +530,7 @@ window.location = ${redirectUrlJs};
 </html>`;
     res.send(output);
   } else {
-    console_mozlog.warn("no-redirect-to", {"msg": "Bad Request, no ?to parameter"});
+    mozlog.warn("no-redirect-to", {"msg": "Bad Request, no ?to parameter"});
     sendRavenMessage(req, "Bad request, no ?to parameter");
     simpleResponse(res, "Bad Request", 400);
   }
@@ -539,7 +540,7 @@ app.post("/api/register", function(req, res) {
   let vars = req.body;
   let canUpdate = vars.deviceId === req.deviceId;
   if (!vars.deviceId) {
-    console.error("Bad register request:", JSON.stringify(vars, null, "  "));
+    mozlog.error("bad-api-register", {msg: "Bad register request", vars: JSON.stringify(vars, null, "  ")});
     sendRavenMessage(req, "Attempted to register without deviceId");
     simpleResponse(res, "Bad request, no deviceId", 400);
     return;
@@ -646,7 +647,7 @@ app.put("/data/:id/:domain", function(req, res) {
   let slowResponse = config.testing.slowResponse;
   let failSometimes = config.testing.failSometimes;
   if (failSometimes && Math.floor(Math.random() * failSometimes)) {
-    console.info("Artificially making request fail");
+    console.log("Artificially making request fail"); // eslint-disable-line no-console
     res.status(500);
     res.end();
     return;
@@ -657,7 +658,7 @@ app.put("/data/:id/:domain", function(req, res) {
   }
   let shotId = `${req.params.id}/${req.params.domain}`;
   if (!req.deviceId) {
-    console.warn("Attempted to PUT without logging in", req.url);
+    mozlog.warn("put-without-auth", {msg: "Attempted to PUT without logging in", url: req.url});
     sendRavenMessage(req, "Attempt PUT without authentication");
     simpleResponse(res, "Not logged in", 401);
     return;
@@ -1110,9 +1111,9 @@ linker.init().then(() => {
     scheme = "http";
   }
   server.listen(config.port);
-  console.info(`server listening on ${scheme}://localhost:${config.port}/`);
+  mozlog.info("server-started", {msg: `server listening on ${scheme}://localhost:${config.port}/`});
 }).catch((err) => {
-  console.error("Error getting git revision:", err, err.stack);
+  mozlog.error("git-revision-error", {msg: "Error getting git revision", error: err, stack: err.stack});
 });
 
 require("./jobs").start();

server/src/servershot.js

@@ -339,10 +339,10 @@ class ServerClip extends AbstractShot.prototype.Clip {
     let match = (/^data:([^;]*);base64,/).exec(url);
     if (!match) {
       if (!url) {
-        console.warn("Submitted with empty clip URL");
+        mozlog.warn("empty-clip-url", {msg: "Submitted with empty clip URL"});
         throw new Error("Empty clip URL");
       } else {
-        console.warn("Submitted with bad clip URL:", url.substr(0, 10) + "...");
+        mozlog.warn("bad-clip-url", {msg: "Submitted with bad clip URL", urlPrefix: url.substr(0, 10) + "..."});
         throw new Error("Bad clip URL");
       }
     }