Feature/logger plugin

README.md

@@ -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)

ilc/package.json

@@ -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",
@@ -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",

ilc/server/app.js

@@ -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'));

ilc/server/errorHandler/ErrorHandler.js

@@ -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) => {
@@ -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
             });
 
@@ -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.');

ilc/server/errorHandler/ErrorHandler.spec.js

@@ -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 () => {
@@ -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 () => {
@@ -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');
     });
 });

ilc/server/errorHandler/factory.js

@@ -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,
 );

ilc/server/logger/defaultLoggerConf.js

@@ -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;
+        }
+    }
+};

ilc/server/logger/fastify.js

@@ -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);

ilc/server/logger/index.js

@@ -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;