Skip to content

Commit 47057cf

Browse files
lukaszczerpak-cloudinarylukaszczerpak-cloudinary
authored
feat: verbose logging and metrics (closes DELO-4898) (#110)
Winston is used as main logger now. Rollbar gets messages from Winston. All logs are printed out to console. There are two environment variables now: - LOG_LEVEL: minimal log level for the console - ROLLBAR_LOG_LEVEL: minimal log level for Rollbar The app uses Opentelemetry for better insight into server as well as WPT client metrics.
1 parent 190e48d commit 47057cf

File tree

11 files changed

+1024
-483
lines changed

11 files changed

+1024
-483
lines changed

‎app.js‎

Lines changed: 34 additions & 35 deletions
Original file line numberDiff line numberDiff line change
@@ -1,54 +1,53 @@
1-
const config = require('config');
2-
const express = require('express');
3-
const bodyParser = require('body-parser');
41
const logger = require('./logger').logger;
5-
const app = express();
6-
app.use(bodyParser.json());
72

3+
const express = require('express');
4+
const app = express();
85

9-
//@for working with localhost
6+
// @for working with localhost
107
app.use(function (req, res, next) {
11-
res.header("Access-Control-Allow-Origin", "*");
12-
res.header("Access-Control-Allow-Headers", "Origin, X-Requested-With, Content-Type, Accept");
13-
res.header('Access-Control-Allow-Methods', 'GET, PUT, POST, DELETE, OPTIONS');
14-
if ('OPTIONS' === req.method) {
15-
//respond with 200
16-
res.sendStatus(200);
17-
}
18-
else {
19-
//move on
20-
next();
21-
}
8+
res.header("Access-Control-Allow-Origin", "*");
9+
res.header("Access-Control-Allow-Headers", "Origin, X-Requested-With, Content-Type, Accept");
10+
res.header('Access-Control-Allow-Methods', 'GET, PUT, POST, DELETE, OPTIONS');
11+
if ('OPTIONS' === req.method) {
12+
// respond with 200
13+
res.status(200).send();
14+
} else {
15+
// move on
16+
next();
17+
}
2218
});
2319

24-
app.use(logger.errorHandler());
25-
26-
//app.use(bodyParser.urlencoded({ extended: false }));
27-
20+
app.use(express.json());
2821

2922
const wpt = require('./routes/wpt');
3023
wpt(app);
3124

32-
3325
// catch 404 and forward to error handler
3426
app.all('*', function (req, res) {
35-
res.status(404).send('what???');
27+
res.status(404).send('what???');
3628
});
3729

3830
app.use(function (req, res, next) {
39-
let err = new Error('Not Found');
40-
err.status = 404;
41-
next(err);
31+
let err = new Error('Not Found');
32+
err.status = 404;
33+
next(err);
4234
});
4335

44-
// error handler
45-
app.use(function (err, req, res, next) {
46-
// set locals, only providing error in development
47-
res.locals.message = err.message;
48-
res.locals.error = req.app.get('env') === 'development' ? err : {};
49-
50-
// render the error page
51-
res.status(err.status || 500);
52-
});
36+
app.use((err, req, res, next) => {
37+
// attributes from body-parser we don't want
38+
delete err.body;
39+
delete err.expose;
40+
41+
let statusCode = Number(err.statusCode);
42+
if (!(statusCode >= 400 && statusCode < 600)) {
43+
statusCode = 500;
44+
}
45+
res.status(statusCode).send();
46+
logger.error(err, {
47+
method: req.method,
48+
url: req.url,
49+
statusCode,
50+
});
51+
})
5352

5453
module.exports = app;

‎cloudinary/apiCaller.js‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -4,8 +4,8 @@
44

55
'use strict';
66
require('dotenv').config();
7-
const logger = require('../logger');
8-
const log = logger.logger;
7+
const logger = require('../logger').logger;
8+
const {LOG_LEVEL_INFO, LOG_LEVEL_WARNING, LOG_LEVEL_ERROR, LOG_LEVEL_CRITICAL, LOG_LEVEL_DEBUG} = require('../logger');
99
const config = require('config');
1010
const _ = require('lodash');
1111
const cloudinaryParser = require('./cloudinaryResultParser');
@@ -32,7 +32,7 @@ const addServerInfo = (imageList, batchSize, dpr, metaData, quality, cb, rollBar
3232
});
3333
}, (err, res) => {
3434
if (err) {
35-
log.warn('error getting head for image ', err, rollBarMsg);
35+
logger.warn('error getting head for image ', err, rollBarMsg);
3636
} else {
3737
sendToCloudinary(list, bs, dpr, metaData, quality, cb, rollBarMsg);
3838
}
@@ -73,7 +73,6 @@ const sendToCloudinary = (imagesArray, batchSize, dpr, metaData, quality, cb, ro
7373
if (error) {
7474
analyzeResults.push({public_id: null});
7575
uploadErrors.push(error);
76-
console.error('Error uploading to cloudinary', error);
7776
callback();
7877
} else {
7978
result.server = image.server;
@@ -83,14 +82,14 @@ const sendToCloudinary = (imagesArray, batchSize, dpr, metaData, quality, cb, ro
8382
});
8483
}, err => {
8584
if (uploadErrors.length > 0) {
86-
log.error('cloudinary upload errors', uploadErrors, rollBarMsg);
85+
logger.error('cloudinary upload errors', uploadErrors, rollBarMsg);
8786
}
8887
if (err) {
8988
cb({
9089
status: 'error',
9190
message: 'Error getting results from cloudinary',
9291
error: err,
93-
logLevel: logger.LOG_LEVEL_ERROR,
92+
logLevel: LOG_LEVEL_ERROR,
9493
}, null, null, rollBarMsg);
9594
}
9695
let parsed = cloudinaryParser.parseCloudinaryResults(analyzeResults, rollBarMsg);
@@ -109,6 +108,7 @@ const sendToCloudinary = (imagesArray, batchSize, dpr, metaData, quality, cb, ro
109108
delete (metaData.lcpEvent);
110109
}
111110
Object.assign(parsed.resultSumm, metaData);
111+
logger.info("Finished upload to cloudinary");
112112
cb(null, {status: 'success', data: parsed});
113113
});
114114

‎config/default.js‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,7 @@ const CUSTOM_SCRIPT = fs.readFileSync('config/wpt/custom_metrics.min.js', 'utf8'
66

77
const conf = {
88
"rollbar": {
9-
postToken: process.env.ROLLBAR_TOKEN || null
9+
postToken: process.env.ROLLBAR_TOKEN || "dummy"
1010
},
1111
"images": {
1212
"maxNumberOfImages": process.env.MAX_IMGES || 50,
@@ -16,7 +16,7 @@ const conf = {
1616
"minImageRes": process.env.MIN_IMAGE_RES || 20,
1717
},
1818
"wtp": {
19-
"apiKey": process.env.WTP_API_KEY,
19+
"apiKey": process.env.WTP_API_KEY || "dummy",
2020
"imageScript": process.env.WTP_CUSTOM || CUSTOM_SCRIPT,
2121
"viewportWidth": 1366,
2222
"viewportHeight": 784,

‎instrumentation.js‎

Lines changed: 24 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,10 +1,15 @@
11
const opentelemetry = require('@opentelemetry/sdk-node');
22
const {Resource} = require('@opentelemetry/resources');
3+
const {registerInstrumentations} = require('@opentelemetry/instrumentation');
4+
const {HttpInstrumentation} = require('@opentelemetry/instrumentation-http');
5+
const {ExpressInstrumentation} = require('@opentelemetry/instrumentation-express');
6+
const {PrometheusExporter} = require('@opentelemetry/exporter-prometheus');
7+
38
const {
49
ATTR_SERVICE_NAME,
510
ATTR_SERVICE_VERSION
611
} = require('@opentelemetry/semantic-conventions');
7-
const {PrometheusExporter} = require('@opentelemetry/exporter-prometheus');
12+
813
const sdk = new opentelemetry.NodeSDK({
914
resource: new Resource({
1015
[ATTR_SERVICE_NAME]: 'web-speed-test-server',
@@ -15,3 +20,21 @@ const sdk = new opentelemetry.NodeSDK({
1520
}),
1621
});
1722
sdk.start();
23+
24+
registerInstrumentations({
25+
instrumentations: [
26+
// Express instrumentation expects HTTP layer to be instrumented
27+
new HttpInstrumentation({
28+
ignoreIncomingRequestHook: (req) => {
29+
return req.connection.localPort === 6060; // ignore incoming requests to prometheus
30+
},
31+
ignoreOutgoingRequestHook: (req) => {
32+
return ![ // we care about performance of outgoing requests to those hosts only
33+
'www.webpagetest.org',
34+
'api.cloudinary.com'
35+
].includes(req.hostname);
36+
},
37+
}),
38+
new ExpressInstrumentation()
39+
],
40+
});

‎logger/index.js‎

Lines changed: 72 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -1,40 +1,85 @@
11
require('dotenv').config();
22
const config = require('config');
3-
const Rollbar = require('rollbar');
3+
44
const LOG_LEVEL_INFO = 'info';
55
const LOG_LEVEL_WARNING = 'warning';
66
const LOG_LEVEL_ERROR = 'error';
77
const LOG_LEVEL_DEBUG = 'debug';
88
const LOG_LEVEL_CRITICAL = 'critical';
99
const packageJson = require('../package.json');
1010
const os = require('os');
11-
const logger = new Rollbar({
12-
// enabled: false, // silence rollbar as it takes too much quota.
13-
accessToken: config.get('rollbar.postToken'),
14-
verbose: true,
15-
handleUncaughtExceptions: true,
16-
handleUnhandledRejections: true,
17-
environment: process.env.ENVIRONMENT || "development",
18-
reportLevel: process.env.LOG_LEVEL || LOG_LEVEL_CRITICAL,
19-
payload: {
20-
system: {
21-
appVersion: packageJson.version,
22-
hostname: os.hostname(),
23-
platform: os.platform(),
24-
type: os.type(),
25-
},
26-
},
27-
});
2811

29-
if ('development' === process.env.NODE_ENV || 'true' === process.env.PRINT_LOGS_CONSOLE) {
30-
logger.configure({verbose: true});
31-
}
12+
const rollbarConfig = {
13+
// enabled: false, // silence rollbar as it takes too much quota.
14+
accessToken: config.get('rollbar.postToken'),
15+
verbose: false,
16+
handleUncaughtExceptions: false,
17+
handleUnhandledRejections: false,
18+
environment: process.env.ENVIRONMENT || "development",
19+
payload: {
20+
system: {
21+
appVersion: packageJson.version,
22+
hostname: os.hostname(),
23+
platform: os.platform(),
24+
type: os.type(),
25+
},
26+
}
27+
};
28+
29+
const winston = require('winston');
30+
const RollbarTransport = require('winston-transport-rollbar-3');
31+
const { context, trace } = require('@opentelemetry/api');
32+
33+
const {combine, timestamp, prettyPrint, errors} = winston.format;
34+
const logger = winston.createLogger({
35+
exitOnError: true,
36+
level: process.env.LOG_LEVEL || LOG_LEVEL_INFO,
37+
format: combine(
38+
timestamp(),
39+
errors({stack: true}),
40+
winston.format((info, opts) => {
41+
const span = trace.getSpan(context.active());
42+
const traceId = span?.spanContext().traceId;
43+
if (traceId) {
44+
info.traceId = traceId;
45+
}
46+
const testId = span?.spanContext().testId;
47+
if (testId) {
48+
info.testId = testId;
49+
}
50+
return info;
51+
})(),
52+
winston.format.json(),
53+
...(process.env.NODE_ENV !== "production" ? [prettyPrint()] : [])
54+
),
55+
transports: [
56+
new winston.transports.Console(),
57+
new RollbarTransport({
58+
rollbarConfig,
59+
level: process.env.ROLLBAR_LOG_LEVEL || LOG_LEVEL_ERROR,
60+
})
61+
],
62+
exceptionHandlers: [
63+
new winston.transports.Console(),
64+
new RollbarTransport({
65+
rollbarConfig,
66+
level: process.env.ROLLBAR_LOG_LEVEL || LOG_LEVEL_ERROR,
67+
})
68+
],
69+
rejectionHandlers: [
70+
new winston.transports.Console(),
71+
new RollbarTransport({
72+
rollbarConfig,
73+
level: process.env.ROLLBAR_LOG_LEVEL || LOG_LEVEL_ERROR,
74+
})
75+
],
76+
});
3277

3378
module.exports = {
34-
logger: logger,
35-
LOG_LEVEL_INFO: LOG_LEVEL_INFO,
36-
LOG_LEVEL_WARNING: LOG_LEVEL_WARNING,
37-
LOG_LEVEL_ERROR: LOG_LEVEL_ERROR,
38-
LOG_LEVEL_CRITICAL: LOG_LEVEL_CRITICAL,
39-
LOG_LEVEL_DEBUG: LOG_LEVEL_DEBUG
79+
logger: logger,
80+
LOG_LEVEL_INFO: LOG_LEVEL_INFO,
81+
LOG_LEVEL_WARNING: LOG_LEVEL_WARNING,
82+
LOG_LEVEL_ERROR: LOG_LEVEL_ERROR,
83+
LOG_LEVEL_CRITICAL: LOG_LEVEL_CRITICAL,
84+
LOG_LEVEL_DEBUG: LOG_LEVEL_DEBUG
4085
};

‎package.json‎

Lines changed: 16 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -4,39 +4,41 @@
44
"private": true,
55
"scripts": {
66
"test": "mocha",
7-
"start": "node start.js",
8-
"start-with-instrumentation": "node --require ./instrumentation.js start.js",
7+
"start": "node --require ./instrumentation.js start.js",
98
"postinstall": "patch-package"
109
},
1110
"dependencies": {
1211
"@opentelemetry/api": "^1.9.0",
13-
"@opentelemetry/exporter-prometheus": "^0.56.0",
14-
"@opentelemetry/resources": "^1.29.0",
15-
"@opentelemetry/sdk-node": "^0.56.0",
16-
"@opentelemetry/semantic-conventions": "^1.28.0",
12+
"@opentelemetry/exporter-prometheus": "^0.57.1",
13+
"@opentelemetry/instrumentation-express": "^0.47.0",
14+
"@opentelemetry/instrumentation-http": "^0.57.1",
15+
"@opentelemetry/resources": "^1.30.1",
16+
"@opentelemetry/sdk-node": "^0.57.1",
17+
"@opentelemetry/sdk-trace-base": "^1.30.1",
18+
"@opentelemetry/semantic-conventions": "^1.29.0",
1719
"async": "^3.2.6",
1820
"async-mutex": "^0.5.0",
19-
"body-parser": "~1.20.3",
2021
"bytes": "^3.1.2",
2122
"cloudinary": "1.41.3",
2223
"config": "^3.3.12",
2324
"cookie-parser": "~1.4.7",
2425
"debug": "~4.4.0",
2526
"dotenv": "^16.4.7",
26-
"express": "~4.21.2",
27-
"got": "^14.4.5",
27+
"express": "^4.21.2",
28+
"got": "^14.4.6",
2829
"lodash": "^4.17.21",
2930
"rollbar": "^2.26.4",
30-
"valid-url": "^1.0.9"
31+
"winston": "^3.17.0",
32+
"winston-transport-rollbar-3": "^3.2.6"
3133
},
3234
"devDependencies": {
3335
"chai": "^4.5.0",
3436
"chai-http": "^4.4.0",
35-
"husky": "^8.0.3",
36-
"mocha": "^10.8.2",
37-
"nock": "^13.5.6",
37+
"husky": "^9.1.7",
38+
"mocha": "^11.1.0",
39+
"nock": "^14.0.0",
3840
"patch-package": "^8.0.0",
39-
"sinon": "^16.1.3",
41+
"sinon": "^19.0.2",
4042
"sinon-chai": "^3.7.0"
4143
},
4244
"packageManager": "[email protected]+sha512.a6b2f7906b721bba3d67d4aff083df04dad64c399707841b7acf00f6b133b7ac24255f2652fa22ae3534329dc6180534e98d17432037ff6fd140556e2bb3137e"

0 commit comments

Comments
 (0)