feat: verbose logging and metrics (closes DELO-4898)

app.js

@@ -1,54 +1,53 @@
-const config = require('config');
-const express = require('express');
-const bodyParser = require('body-parser');
 const logger = require('./logger').logger;
-const app = express();
-app.use(bodyParser.json());
 
+const express = require('express');
+const app = express();
 
-//@for working with localhost
+// @for working with localhost
 app.use(function (req, res, next) {
-  res.header("Access-Control-Allow-Origin", "*");
-  res.header("Access-Control-Allow-Headers", "Origin, X-Requested-With, Content-Type, Accept");
-  res.header('Access-Control-Allow-Methods', 'GET, PUT, POST, DELETE, OPTIONS');
-  if ('OPTIONS' === req.method) {
-    //respond with 200
-    res.sendStatus(200);
-  }
-  else {
-    //move on
-    next();
-  }
+    res.header("Access-Control-Allow-Origin", "*");
+    res.header("Access-Control-Allow-Headers", "Origin, X-Requested-With, Content-Type, Accept");
+    res.header('Access-Control-Allow-Methods', 'GET, PUT, POST, DELETE, OPTIONS');
+    if ('OPTIONS' === req.method) {
+        // respond with 200
+        res.status(200).send();
+    } else {
+        // move on
+        next();
+    }
 });
 
-app.use(logger.errorHandler());
-
-//app.use(bodyParser.urlencoded({ extended: false }));
-
+app.use(express.json());
 
 const wpt = require('./routes/wpt');
 wpt(app);
 
-
 // catch 404 and forward to error handler
 app.all('*', function (req, res) {
-  res.status(404).send('what???');
+    res.status(404).send('what???');
 });
 
 app.use(function (req, res, next) {
-  let err = new Error('Not Found');
-  err.status = 404;
-  next(err);
+    let err = new Error('Not Found');
+    err.status = 404;
+    next(err);
 });
 
-// error handler
-app.use(function (err, req, res, next) {
-  // set locals, only providing error in development
-  res.locals.message = err.message;
-  res.locals.error = req.app.get('env') === 'development' ? err : {};
-
-  // render the error page
-  res.status(err.status || 500);
-});
+app.use((err, req, res, next) => {
+    // attributes from body-parser we don't want
+    delete err.body;
+    delete err.expose;
+
+    let statusCode = Number(err.statusCode);
+    if (!(statusCode >= 400 && statusCode < 600)) {
+        statusCode = 500;
+    }
+    res.status(statusCode).send();
+    logger.error(err, {
+        method: req.method,
+        url: req.url,
+        statusCode,
+    });
+})
 
 module.exports = app;

cloudinary/apiCaller.js

@@ -4,8 +4,8 @@
 
 'use strict';
 require('dotenv').config();
-const logger = require('../logger');
-const log = logger.logger;
+const logger = require('../logger').logger;
+const {LOG_LEVEL_INFO, LOG_LEVEL_WARNING, LOG_LEVEL_ERROR, LOG_LEVEL_CRITICAL, LOG_LEVEL_DEBUG} = require('../logger');
 const config = require('config');
 const _ = require('lodash');
 const cloudinaryParser = require('./cloudinaryResultParser');
@@ -32,7 +32,7 @@ const addServerInfo = (imageList, batchSize, dpr, metaData, quality, cb, rollBar
     });
   }, (err, res) => {
     if (err) {
-      log.warn('error getting head for image ', err, rollBarMsg);
+      logger.warn('error getting head for image ', err, rollBarMsg);
     } else {
       sendToCloudinary(list, bs, dpr, metaData, quality, cb, rollBarMsg);
     }
@@ -73,7 +73,6 @@ const sendToCloudinary = (imagesArray, batchSize, dpr, metaData, quality, cb, ro
           if (error) {
             analyzeResults.push({public_id: null});
             uploadErrors.push(error);
-            console.error('Error uploading to cloudinary', error);
             callback();
           } else {
             result.server = image.server;
@@ -83,14 +82,14 @@ const sendToCloudinary = (imagesArray, batchSize, dpr, metaData, quality, cb, ro
         });
   }, err => {
     if (uploadErrors.length > 0) {
-      log.error('cloudinary upload errors', uploadErrors, rollBarMsg);
+      logger.error('cloudinary upload errors', uploadErrors, rollBarMsg);
     }
     if (err) {
       cb({
         status: 'error',
         message: 'Error getting results from cloudinary',
         error: err,
-        logLevel: logger.LOG_LEVEL_ERROR,
+        logLevel: LOG_LEVEL_ERROR,
       }, null, null, rollBarMsg);
     }
     let parsed = cloudinaryParser.parseCloudinaryResults(analyzeResults, rollBarMsg);
@@ -109,6 +108,7 @@ const sendToCloudinary = (imagesArray, batchSize, dpr, metaData, quality, cb, ro
       delete (metaData.lcpEvent);
     }
     Object.assign(parsed.resultSumm, metaData);
+    logger.info("Finished upload to cloudinary");
     cb(null, {status: 'success', data: parsed});
   });
 

config/default.js

@@ -6,7 +6,7 @@ const CUSTOM_SCRIPT = fs.readFileSync('config/wpt/custom_metrics.min.js', 'utf8'
 
 const conf = {
   "rollbar": {
-    postToken: process.env.ROLLBAR_TOKEN || null
+    postToken: process.env.ROLLBAR_TOKEN || "dummy"
   },
   "images": {
     "maxNumberOfImages": process.env.MAX_IMGES || 50,
@@ -16,7 +16,7 @@ const conf = {
     "minImageRes": process.env.MIN_IMAGE_RES || 20,
   },
   "wtp": {
-    "apiKey": process.env.WTP_API_KEY,
+    "apiKey": process.env.WTP_API_KEY || "dummy",
     "imageScript": process.env.WTP_CUSTOM || CUSTOM_SCRIPT,
     "viewportWidth": 1366,
     "viewportHeight": 784,

instrumentation.js

@@ -1,10 +1,15 @@
 const opentelemetry = require('@opentelemetry/sdk-node');
 const {Resource} = require('@opentelemetry/resources');
+const {registerInstrumentations} = require('@opentelemetry/instrumentation');
+const {HttpInstrumentation} = require('@opentelemetry/instrumentation-http');
+const {ExpressInstrumentation} = require('@opentelemetry/instrumentation-express');
+const {PrometheusExporter} = require('@opentelemetry/exporter-prometheus');
+
 const {
     ATTR_SERVICE_NAME,
     ATTR_SERVICE_VERSION
 } = require('@opentelemetry/semantic-conventions');
-const {PrometheusExporter} = require('@opentelemetry/exporter-prometheus');
+
 const sdk = new opentelemetry.NodeSDK({
     resource: new Resource({
         [ATTR_SERVICE_NAME]: 'web-speed-test-server',
@@ -15,3 +20,21 @@ const sdk = new opentelemetry.NodeSDK({
     }),
 });
 sdk.start();
+
+registerInstrumentations({
+    instrumentations: [
+        // Express instrumentation expects HTTP layer to be instrumented
+        new HttpInstrumentation({
+            ignoreIncomingRequestHook: (req) => {
+                return req.connection.localPort === 6060;   // ignore incoming requests to prometheus
+            },
+            ignoreOutgoingRequestHook: (req) => {
+                return ![   // we care about performance of outgoing requests to those hosts only
+                    'www.webpagetest.org',
+                    'api.cloudinary.com'
+                ].includes(req.hostname);
+            },
+        }),
+        new ExpressInstrumentation()
+    ],
+});

logger/index.js

@@ -1,40 +1,85 @@
 require('dotenv').config();
 const config = require('config');
-const Rollbar = require('rollbar');
+
 const LOG_LEVEL_INFO = 'info';
 const LOG_LEVEL_WARNING = 'warning';
 const LOG_LEVEL_ERROR = 'error';
 const LOG_LEVEL_DEBUG = 'debug';
 const LOG_LEVEL_CRITICAL = 'critical';
 const packageJson = require('../package.json');
 const os = require('os');
-const logger = new Rollbar({
-  // enabled: false,  // silence rollbar as it takes too much quota.
-  accessToken: config.get('rollbar.postToken'),
-  verbose: true,
-  handleUncaughtExceptions: true,
-  handleUnhandledRejections: true,
-  environment: process.env.ENVIRONMENT || "development",
-  reportLevel: process.env.LOG_LEVEL || LOG_LEVEL_CRITICAL,
-  payload: {
-    system: {
-      appVersion: packageJson.version,
-      hostname: os.hostname(),
-      platform: os.platform(),
-      type: os.type(),
-    },
-  },
-});
 
-if ('development' === process.env.NODE_ENV || 'true' === process.env.PRINT_LOGS_CONSOLE) {
-  logger.configure({verbose: true});
-}
+const rollbarConfig = {
+    // enabled: false,  // silence rollbar as it takes too much quota.
+    accessToken: config.get('rollbar.postToken'),
+    verbose: false,
+    handleUncaughtExceptions: false,
+    handleUnhandledRejections: false,
+    environment: process.env.ENVIRONMENT || "development",
+    payload: {
+        system: {
+            appVersion: packageJson.version,
+            hostname: os.hostname(),
+            platform: os.platform(),
+            type: os.type(),
+        },
+    }
+};
+
+const winston = require('winston');
+const RollbarTransport = require('winston-transport-rollbar-3');
+const { context, trace } = require('@opentelemetry/api');
+
+const {combine, timestamp, prettyPrint, errors} = winston.format;
+const logger = winston.createLogger({
+    exitOnError: true,
+    level: process.env.LOG_LEVEL || LOG_LEVEL_INFO,
+    format: combine(
+        timestamp(),
+        errors({stack: true}),
+        winston.format((info, opts) => {
+            const span = trace.getSpan(context.active());
+            const traceId = span?.spanContext().traceId;
+            if (traceId) {
+                info.traceId = traceId;
+            }
+            const testId = span?.spanContext().testId;
+            if (testId) {
+                info.testId = testId;
+            }
+            return info;
+        })(),
+        winston.format.json(),
+        ...(process.env.NODE_ENV !== "production" ? [prettyPrint()] : [])
+    ),
+    transports: [
+        new winston.transports.Console(),
+        new RollbarTransport({
+            rollbarConfig,
+            level: process.env.ROLLBAR_LOG_LEVEL || LOG_LEVEL_ERROR,
+        })
+    ],
+    exceptionHandlers: [
+        new winston.transports.Console(),
+        new RollbarTransport({
+            rollbarConfig,
+            level: process.env.ROLLBAR_LOG_LEVEL || LOG_LEVEL_ERROR,
+        })
+    ],
+    rejectionHandlers: [
+        new winston.transports.Console(),
+        new RollbarTransport({
+            rollbarConfig,
+            level: process.env.ROLLBAR_LOG_LEVEL || LOG_LEVEL_ERROR,
+        })
+    ],
+});
 
 module.exports = {
-  logger: logger,
-  LOG_LEVEL_INFO: LOG_LEVEL_INFO,
-  LOG_LEVEL_WARNING: LOG_LEVEL_WARNING,
-  LOG_LEVEL_ERROR: LOG_LEVEL_ERROR,
-  LOG_LEVEL_CRITICAL: LOG_LEVEL_CRITICAL,
-  LOG_LEVEL_DEBUG: LOG_LEVEL_DEBUG
+    logger: logger,
+    LOG_LEVEL_INFO: LOG_LEVEL_INFO,
+    LOG_LEVEL_WARNING: LOG_LEVEL_WARNING,
+    LOG_LEVEL_ERROR: LOG_LEVEL_ERROR,
+    LOG_LEVEL_CRITICAL: LOG_LEVEL_CRITICAL,
+    LOG_LEVEL_DEBUG: LOG_LEVEL_DEBUG
 };

package.json

@@ -4,39 +4,41 @@
   "private": true,
   "scripts": {
     "test": "mocha",
-    "start": "node start.js",
-    "start-with-instrumentation": "node --require ./instrumentation.js start.js",
+    "start": "node --require ./instrumentation.js start.js",
     "postinstall": "patch-package"
   },
   "dependencies": {
     "@opentelemetry/api": "^1.9.0",
-    "@opentelemetry/exporter-prometheus": "^0.56.0",
-    "@opentelemetry/resources": "^1.29.0",
-    "@opentelemetry/sdk-node": "^0.56.0",
-    "@opentelemetry/semantic-conventions": "^1.28.0",
+    "@opentelemetry/exporter-prometheus": "^0.57.1",
+    "@opentelemetry/instrumentation-express": "^0.47.0",
+    "@opentelemetry/instrumentation-http": "^0.57.1",
+    "@opentelemetry/resources": "^1.30.1",
+    "@opentelemetry/sdk-node": "^0.57.1",
+    "@opentelemetry/sdk-trace-base": "^1.30.1",
+    "@opentelemetry/semantic-conventions": "^1.29.0",
     "async": "^3.2.6",
     "async-mutex": "^0.5.0",
-    "body-parser": "~1.20.3",
     "bytes": "^3.1.2",
     "cloudinary": "1.41.3",
     "config": "^3.3.12",
     "cookie-parser": "~1.4.7",
     "debug": "~4.4.0",
     "dotenv": "^16.4.7",
-    "express": "~4.21.2",
-    "got": "^14.4.5",
+    "express": "^4.21.2",
+    "got": "^14.4.6",
     "lodash": "^4.17.21",
     "rollbar": "^2.26.4",
-    "valid-url": "^1.0.9"
+    "winston": "^3.17.0",
+    "winston-transport-rollbar-3": "^3.2.6"
   },
   "devDependencies": {
     "chai": "^4.5.0",
     "chai-http": "^4.4.0",
-    "husky": "^8.0.3",
-    "mocha": "^10.8.2",
-    "nock": "^13.5.6",
+    "husky": "^9.1.7",
+    "mocha": "^11.1.0",
+    "nock": "^14.0.0",
     "patch-package": "^8.0.0",
-    "sinon": "^16.1.3",
+    "sinon": "^19.0.2",
     "sinon-chai": "^3.7.0"
   },
   "packageManager": "[email protected]+sha512.a6b2f7906b721bba3d67d4aff083df04dad64c399707841b7acf00f6b133b7ac24255f2652fa22ae3534329dc6180534e98d17432037ff6fd140556e2bb3137e"