Skip to content

Commit

Permalink
Feature/logger plugin (#193)
Browse files Browse the repository at this point in the history
* fix: fixed error handling

* feat: Plugin system added

* chore: Registry & server router now switched to the internal logger

* wrapFetchWithCache now switched to the internal logger

* chore: More verbose tests for error logging

* chore: README update
  • Loading branch information
StyleT authored Sep 1, 2020
1 parent 1024707 commit 1e7bd0b
Show file tree
Hide file tree
Showing 15 changed files with 220 additions and 58 deletions.
1 change: 1 addition & 0 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -80,6 +80,7 @@ And don't miss the **[Step-By-Step lessons about apps development with ILC](./do
* [Animation during reroute](./docs/animation_during_reroute.md)
* [Global error handling](./docs/global_errors_handling.md)
* [Demo applications used in quick start](https://github.com/namecheap/ilc-demo-apps)
* [SDK for ILC plugins development](https://github.com/namecheap/ilc-plugins-sdk)

## 🔌 Adapters
To conveniently connect various frameworks to ILC we rely on the [ecosystem of the single-spa](https://single-spa.js.org/docs/ecosystem)
Expand Down
4 changes: 4 additions & 0 deletions ilc/package.json
Original file line number Diff line number Diff line change
Expand Up @@ -26,11 +26,14 @@
"config": "^3.3.1",
"cross-env": "^6.0.3",
"deepmerge": "4.2.2",
"fast-glob": "^3.2.4",
"fastify": "^2.15.2",
"http-headers": "^3.0.2",
"hyperid": "^2.0.5",
"is-url": "^1.2.4",
"lodash": "^4.17.19",
"newrelic": "^6.11.0",
"pino": "^6.5.0",
"serve-static": "^1.14.1",
"single-spa": "5.4.0",
"systemjs": "^6.4.2",
Expand Down Expand Up @@ -66,6 +69,7 @@
"raw-loader": "^3.1.0",
"sinon": "^8.1.1",
"supertest": "^4.0.2",
"test-console": "^1.1.0",
"webpack": "^4.44.1",
"webpack-cli": "^3.3.12",
"webpack-dev-middleware": "^3.7.2",
Expand Down
6 changes: 3 additions & 3 deletions ilc/server/app.js
Original file line number Diff line number Diff line change
Expand Up @@ -6,9 +6,9 @@ const registryService = require('./registry/factory');
const errorHandlingService = require('./errorHandler/factory');

module.exports = () => {
const app = fastify({
logger: require('./fastifyLoggerConf'),
});
const app = fastify(Object.assign({
trustProxy: false, //TODO: should be configurable via Registry
}, require('./logger/fastify')));
const tailor = tailorFactory(config.get('cdnUrl'), config.get('newrelic.customClientJsWrapper'));

app.register(require('./ping'));
Expand Down
23 changes: 14 additions & 9 deletions ilc/server/errorHandler/ErrorHandler.js
Original file line number Diff line number Diff line change
Expand Up @@ -14,20 +14,20 @@ module.exports = class ErrorHandler {
this.#logger = logger;
}

/**
*
* @param {Error} err
* @param {{}} errInfo
*/
noticeError(err, errInfo = {}) {
const infoData = Object.assign({}, errInfo);
if (err.data) {
//TODO: fetch data from parent errors
Object.assign(infoData, err.data);
}

this.#errorsService.noticeError(err, infoData);
this.#logger.error(JSON.stringify({
type: err.name,
message: err.message,
stack: err.stack.split("\n"),
additionalInfo: infoData,
}));
err.data = infoData;
this.#logger.error(err);
}

handleError = async (err, req, res) => {
Expand All @@ -37,9 +37,14 @@ module.exports = class ErrorHandler {
// While Fastify will pass it's own Reply object
// Tailor passes http.ServerResponse from Node core
let nres = res.res ? res.res : res;
// Claim full responsibility of the low-level response from Fastify
if (res.res) {
res.sent = true;
}

try {
this.noticeError(err, {
reqId: req.id,
errorId
});

Expand All @@ -52,13 +57,13 @@ module.exports = class ErrorHandler {
nres.write(data);
nres.end();
} catch (causeErr) {
const err = new ErrorHandlingError({
const e = new ErrorHandlingError({
cause: causeErr,
d: {
errorId,
}
});
this.#logger.error(err);
this.#logger.error(e);

nres.statusCode = 500;
nres.write('Oops! Something went wrong. Pls try to refresh page or contact support.');
Expand Down
54 changes: 37 additions & 17 deletions ilc/server/errorHandler/ErrorHandler.spec.js
Original file line number Diff line number Diff line change
@@ -1,35 +1,46 @@
const chai = require('chai');
const sinon = require('sinon');
const supertest = require('supertest');
const nock = require('nock');
const stdoutInterceptor = require("test-console").stdout;
const config = require('config');
const localStorage = require('../../common/localStorage');

const createApp = require('../app');
const ErrorHandlingError = require('./ErrorHandler').ErrorHandlingError;

const parseOutput = capturedOutput => capturedOutput.map(v => {
v = Buffer.from(v).toString('utf-8');
try {
return JSON.parse(v);
} catch (e) {
return v;
}

});

describe('error handler', () => {
const errorIdRegExp = /(?<errorId>[\d\w]{8}-[\d\w]{4}-[\d\w]{4}-[\d\w]{4}-[\d\w]{12})/;

let app;
let server;
let stdoutInspect;

before(async () => {
app = createApp();
await app.ready();
server = supertest(app.server);
});

sinon.spy(global.console, 'error');
beforeEach(() => {
stdoutInspect = stdoutInterceptor.inspect();
});

afterEach(() => {
localStorage.clear();
global.console.error.resetHistory();
stdoutInspect.restore();
});

after(() => {
app.close();
global.console.error.restore();
});

it('should show 500 error page with an error id', async () => {
Expand Down Expand Up @@ -60,13 +71,24 @@ describe('error handler', () => {
'</body>' +
'</html>'
);
chai.expect(JSON.parse(global.console.error.getCall(0).args[0])).to.deep.include({

const output = parseOutput(stdoutInspect.output);

chai.expect(output[1]).to.deep.include({
level: 50,
type: 'Error',
message: '500 page test error',
additionalInfo: {
errorId,
reqId: output[1].additionalInfo.reqId || 'some value should be here',
},
});

chai.expect(output[1].stack[0]).to.eql('Error: 500 page test error');
chai.expect(output[1].stack[1]).to.contain(' at Object.');
chai.expect(output[1]).to.have.property('time');
chai.expect(output[1]).to.have.property('pid');
chai.expect(output[1]).to.have.property('hostname');
});

it('should send an error message when showing 500 error page throws an error', async () => {
Expand All @@ -75,21 +97,19 @@ describe('error handler', () => {
nock(config.get('registry').address).get(`/api/v1/template/500/rendered`).replyWithError(replyingError.message);

const response = await server.get('/_ilc/500').expect(500);
const {errorId} = global.console.error.getCall(0).args[0].match(errorIdRegExp).groups;
const output = parseOutput(stdoutInspect.output);

chai.expect(response.text).to.be.eql('Oops! Something went wrong. Pls try to refresh page or contact support.');
chai.expect(JSON.parse(global.console.error.getCall(0).args[0])).to.deep.include({
chai.expect(output[1]).to.deep.include({
level: 50,
type: 'Error',
message: '500 page test error',
additionalInfo: {
errorId,
},
});
chai.expect(global.console.error.getCall(1).args[0]).to.eql(new ErrorHandlingError({
cause: replyingError,
d: {
errorId,
},
}));
chai.expect(output[1]).to.have.nested.property('additionalInfo.errorId');
chai.expect(output[2].stack.join("\n")).to.have.string("ErrorHandlingError: \n");
chai.expect(output[2].stack.join("\n")).to.have.string("Caused by: Error: Something awful happened.\n");
chai.expect(output[2]).to.have.property('time');
chai.expect(output[2]).to.have.property('pid');
chai.expect(output[2]).to.have.property('hostname');
});
});
3 changes: 2 additions & 1 deletion ilc/server/errorHandler/factory.js
Original file line number Diff line number Diff line change
Expand Up @@ -2,9 +2,10 @@ const newrelic = require('newrelic');

const registryService = require('../registry/factory');
const ErrorHandler = require('./ErrorHandler');
const logger = require('../logger');

module.exports = new ErrorHandler(
registryService,
newrelic,
global.console,
logger,
);
23 changes: 0 additions & 23 deletions ilc/server/fastifyLoggerConf.js

This file was deleted.

57 changes: 57 additions & 0 deletions ilc/server/logger/defaultLoggerConf.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,57 @@
const httpHeaders = require('http-headers');

module.exports = {
level: 'info',
//nestedKey: 'payload', TODO: blocked by https://github.com/pinojs/pino/issues/883
hooks: {
logMethod(inputArgs, method) {
if (inputArgs[0] instanceof Error) {
const err = inputArgs[0];

const causeData = [];
let rawErr = err.cause;
while (rawErr) {
if (rawErr.data) {
causeData.push(rawErr.data);
} else {
causeData.push({});
}
rawErr = rawErr.cause;
}

const logObj = {
type: err.name,
message: err.message,
stack: err.stack.split("\n"),
};
if (err.data) {
logObj.additionalInfo = err.data;
}
if (causeData.length) {
logObj.causeData = causeData;
}
inputArgs[0] = logObj;
}

return method.apply(this, inputArgs)
}
},
serializers: {
res(res) {
const r = {
statusCode: res.statusCode,
};

if (r.statusCode >= 300 && r.statusCode < 400) {
const headers = httpHeaders(res, true);
if (headers['location']) {
r.headers = {
location: headers['location']
};
}
}

return r;
}
}
};
18 changes: 18 additions & 0 deletions ilc/server/logger/fastify.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,18 @@
'use strict';

const _ = require('lodash');
const pluginManager = require('../pluginManager/factory');


let fastifyConf = pluginManager.getReportingPlugin();
if (fastifyConf === null) {
const hyperid = require('hyperid')
const instance = hyperid({urlSafe: true, fixedLength: true});

fastifyConf = {
logger: require('./index'),
genReqId: instance,
}
}

module.exports = _.omit(_.pick(fastifyConf, ['logger', 'requestIdLogLabel', 'genReqId']), _.isEmpty);
22 changes: 22 additions & 0 deletions ilc/server/logger/index.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,22 @@
'use strict';

const {PassThrough} = require('stream');
const pluginManager = require('../pluginManager/factory');
const pino = require('pino');

let logger = pluginManager.getReportingPlugin();
if (logger === null) {
let destStream = process.stdout;
// We need this to being able to capture stdout of the app.
// As for pure "process.stdout" uses faster logs output via sonic-boom
// which is hard to intercept
if (process.env.NODE_ENV === 'test') {
destStream = new PassThrough();
destStream.pipe(process.stdout);
}
logger = pino(require('./defaultLoggerConf'), destStream);
} else {
logger = logger.logger;
}

module.exports = logger;
Loading

0 comments on commit 1e7bd0b

Please sign in to comment.