feat: improve logging (quite a bit) (#73)

* Improve logging

* Bump package ver. Improve README slightly.

* Package versions, vuln fixes

* Some minor fixes

README.md

@@ -6,6 +6,11 @@
 
 The backend service to support the admin portal web ui. Essentially a thin wrapper around SQL queries.
 
+Run in development with `npm run dev`.
+
+You can filter logs through `pino-pretty`, or another ndjson viewer such as `jq` to obtain
+pretty-printed output. This also works with `kubectl log`.
+
 ## TODO
 * Make sure app.env is 'production' in production.  See: https://koajs.com/ 'Settings' section.
 * In development mode check for divergence between .env.template and .env and warn the user
@@ -16,18 +21,6 @@ The backend service to support the admin portal web ui. Essentially a thin wrapp
 * Check all mandatory environment and secrets are present before beginning operation. Print a
     useful error message informing that operation cannot continue if they are not.
 
-## Deploying to DEV environment
-* Make a PR to this repo and have it merged
-* Make a release on the repo with the release version of the form vX.Y.Z where X is the product
-    increment, Y is the sprint number, Z is an zero-based incrementing integer that is reset each
-    time Y is changed.
-
-## Installing
-```bash
-cd ./src
-npm install
-```
-
 ## External dependencies
 This service relies on external APIs in order to perform some operations regarding Forex transactions and delegation of the "commit settlement window" action.
 
@@ -36,18 +29,6 @@ Their endpoints are defined by these configuration values:
 * FXP_ENDPOINT
 * EXTERNAL_SETTLEMENTS_ENDPOINT
 
-## Push to the repo
-Follow the instructions from the Building section above, then:
-```bash
-make push
-```
-
-## Running containerised
-Follow the instructions from the Building section above, then:
-```bash
-make run
-```
-
 ## Running locally
 You'll need access to a mysql instance containing some central_ledger data, and a mojaloop deployment.
 

src/handlers/emailAddress.js

@@ -1,12 +1,9 @@
-const casaLib = require('@mojaloop/finance-portal-lib');
-
-const { getParticipantEmailAddresses, updateEmailAddress } = casaLib.admin.api;
+const { getParticipantEmailAddresses, updateEmailAddress } = require('@mojaloop/finance-portal-lib').admin.api;
 
 const handler = (router, routesContext) => {
     router.get('/emailAddress/:participantName', async (ctx, next) => {
         const emailAddresses = await getParticipantEmailAddresses(
             routesContext.config.centralLedgerEndpoint, ctx.params.participantName,
-            routesContext.log,
         );
         ctx.response.body = emailAddresses;
         ctx.response.status = 200;
@@ -21,10 +18,9 @@ const handler = (router, routesContext) => {
             participantName,
             emailType,
             ctx.request.body.newValue,
-            routesContext.log,
         );
         const emailAddresses = await getParticipantEmailAddresses(
-            routesContext.config.centralLedgerEndpoint, participantName, routesContext.log,
+            routesContext.config.centralLedgerEndpoint, participantName,
         );
         const emailAddress = emailAddresses.filter((a) => a.type === emailType);
         [ctx.response.body] = emailAddress;

src/handlers/forex.js

@@ -1,5 +1,4 @@
 const casaLib = require('@mojaloop/finance-portal-lib');
-const util = require('util');
 
 const { getFxpRatesPerCurrencyChannel, createFxpRateForCurrencyChannel } = casaLib.admin.api;
 
@@ -15,7 +14,7 @@ const handler = (router, routesContext) => {
 
             await next();
         } catch (error) {
-            routesContext.log('Error', util.inspect(error, { depth: 10 }));
+            ctx.log.error(error);
             ctx.response.body = { msg: 'FXP API Error' };
             ctx.response.status = 502;
 
@@ -35,7 +34,7 @@ const handler = (router, routesContext) => {
 
             await next();
         } catch (error) {
-            routesContext.log('Error', util.inspect(error, { depth: 10 }));
+            ctx.log.error(error);
             ctx.response.body = { msg: 'FXP API Error' };
             ctx.response.status = 502;
 

src/handlers/funds-out.js

@@ -13,7 +13,6 @@ const handler = (router, routesContext) => {
                 ctx.request.body.amount,
                 ctx.request.body.currency,
                 'Admin portal funds out request',
-                routesContext.log,
             );
             ctx.response.status = 200;
         } catch (err) {

src/handlers/login.js

@@ -16,7 +16,7 @@ const handler = (router, routesContext) => {
 
     router.post('/login', async (ctx, next) => {
         if (routesContext.config.auth.bypass) {
-            routesContext.log('authentication bypassed');
+            ctx.log.warn('authentication bypassed');
             ctx.response.body = {
                 expiresIn: '3600',
             };

src/handlers/logout.js

@@ -9,7 +9,7 @@ const selfSignedAgent = new https.Agent({ rejectUnauthorized: false });
 const handler = (router, routesContext) => {
     router.put('/logout', async (ctx, next) => {
         const accessToken = ctx.request.get('Cookie').split('=').splice(1).join('');
-        routesContext.log(`revoking token - ${accessToken}- onlogout`);
+        ctx.log.info(`revoking token - ${accessToken}- onlogout`);
         const opts = {
             method: 'POST',
             headers: {

src/handlers/netdebitcap.js

@@ -14,7 +14,6 @@ const handler = (router, routesContext) => {
                 routesContext.config.centralLedgerEndpoint,
                 ctx.params.participantName,
                 acc.currency,
-                routesContext.log,
             );
             acc.netDebitCap = limit.limit.value;
             return acc;
@@ -30,7 +29,6 @@ const handler = (router, routesContext) => {
             ctx.params.participantName,
             ctx.request.body.currency,
             ctx.request.body.newValue,
-            routesContext.log,
         );
         const accounts = await getParticipantAccounts(
             routesContext.config.centralLedgerEndpoint, ctx.params.participantName,
@@ -42,7 +40,6 @@ const handler = (router, routesContext) => {
                 routesContext.config.centralLedgerEndpoint,
                 ctx.params.participantName,
                 acc.currency,
-                routesContext.log,
             );
             acc.netDebitCap = limit.limit.value;
             return acc;

src/handlers/participants.js

@@ -4,8 +4,7 @@ const { getParticipants, setParticipantIsActiveFlag } = casaLib.admin.api;
 
 const handler = (router, routesContext) => {
     router.get('/participants', async (ctx, next) => {
-        ctx.response.body = await getParticipants(routesContext.config.centralLedgerEndpoint,
-            routesContext.log);
+        ctx.response.body = await getParticipants(routesContext.config.centralLedgerEndpoint);
         ctx.response.status = 200;
         await next();
     });
@@ -23,7 +22,6 @@ const handler = (router, routesContext) => {
                 routesContext.config.centralLedgerEndpoint,
                 ctx.request.body.participantName,
                 ctx.request.body.isActive !== 0,
-                routesContext.log,
             );
         } catch (err) {
             ctx.response.body = await routesContext.db

src/handlers/report.js

@@ -25,9 +25,9 @@ const handler = (router, routesContext) => {
         };
 
         const reportUrl = new URL(routesContext.config.reportUrls[reportId]);
-        routesContext.log(`Found report URL: ${reportUrl}`);
+        ctx.log.info(`Found report URL: ${reportUrl}`);
         const completeUrl = await generateReportUrl(ctx.request, reportUrl, reportId);
-        routesContext.log(`Generated report request: ${completeUrl}`);
+        ctx.log.info(`Generated report request: ${completeUrl}`);
 
         try {
             const response = await fetch(completeUrl, opts);

src/handlers/settlement-window-commit.js

@@ -1,5 +1,4 @@
 const portalLib = require('@mojaloop/finance-portal-lib');
-const util = require('util');
 const sleep = require('sleep-promise');
 
 const { commitSettlementWindow } = portalLib.admin.api;
@@ -16,7 +15,7 @@ const handler = (router, routesContext) => {
                 Number(settlementId),
             );
         } catch (error) {
-            routesContext.log('Settlement API Error', util.inspect(error, { depth: 10 }));
+            ctx.log.child({ error }).error('Settlement API Error');
             ctx.response.body = { msg: 'Settlement API Error' };
             ctx.response.status = 502;
 
@@ -41,7 +40,7 @@ const handler = (router, routesContext) => {
 
             [mostRecentSettlementWindow] = settlementWindows;
         } catch (error) {
-            routesContext.log(`An error occurred during getSettlementWindow: ${error.message}`);
+            ctx.log.child({ error }).error('An error occurred during getSettlementWindow');
         }
 
         ctx.response.body = mostRecentSettlementWindow || {};

src/handlers/settlement-windows.js

@@ -29,7 +29,7 @@ const handler = (router, routesContext) => {
             });
             settlementWindow.settlement = (settlement.length === 1 ? settlement[0] : {});
         } catch (error) {
-            routesContext.log(error);
+            ctx.log.error(error);
             settlementWindow.settlement = {};
         }
         ctx.response.body = settlementWindow;

src/handlers/validate-transfer.js

@@ -16,7 +16,7 @@ const handler = (router, routesContext) => {
         const validMessage = await AzureLog
             .getTransferMessageWithJWSSignature(routesContext.config.azureLog,
                 ctx.params.transferId,
-                routesContext.log);
+                ctx.log);
         let isValidTransfer = false;
 
         if (validMessage != null) {
@@ -32,7 +32,7 @@ const handler = (router, routesContext) => {
             try {
                 isValidTransfer = pubKeys.some((pubKey) => JWT.verify(token, pubKey));
             } catch (err) {
-                routesContext.log(`Error validating JWS token: ${err.stack || util.inspect(err)}`);
+                ctx.log.error(`Error validating JWS token: ${err.stack || util.inspect(err)}`);
             }
         }
 

src/index.js

@@ -1,43 +1,58 @@
+const pino = require('pino');
 const createServer = require('./server');
 const Database = require('./db');
 const config = require('./config/config');
-const log = require('./lib/log');
 const { version } = require('./package.json');
 
 // /////////////////////////////////////////////////////////////////////////////
 // Config
 // /////////////////////////////////////////////////////////////////////////////
 
+const logger = pino({
+    serializers: {
+        // return the body for any HTTPResponseError types we receive from finance-portal-lib
+        err: pino.stdSerializers.wrapErrorSerializer((e) => {
+            if (e.type !== 'HTTPResponseError') {
+                return e;
+            }
+            return {
+                ...e,
+                body: e.raw.getData().resp,
+                request: e.raw.getData().request,
+            };
+        }),
+    },
+});
+
 // Log development/production status
-log('Running portal version ', version);
-log('Running in ', process.env.NODE_ENV);
+logger.child({ version, env: process.env.NODE_ENV }).info('Running portal backend service');
 
 // Set up the db
 const db = new Database(config.db);
 
 // Warnings for certain environment var settings
 if (config.cors.reflectOrigin && process.env.NODE_ENV !== 'development') {
-    log('WARNING: NODE_ENV != \'development\' and CORS origin being reflected in Access-Control-Allow-Origin header. '
+    logger.warn('WARNING: NODE_ENV != \'development\' and CORS origin being reflected in Access-Control-Allow-Origin header. '
         + 'Changing CORS_ACCESS_CONTROL_REFLECT_ORIGIN to false is important for preventing CSRF.');
 }
 if (config.auth.bypass) {
-    log('WARNING: auth bypass enabled- all login requests will be approved');
+    logger.warn('WARNING: auth bypass enabled- all login requests will be approved');
 }
 
 // /////////////////////////////////////////////////////////////////////////////
 // Start app
 // /////////////////////////////////////////////////////////////////////////////
 
-log('Config:', config);
-const server = createServer(config, db, log, Database);
+logger.child({ config }).info('Config:');
+const server = createServer(config, db, logger, Database);
 const listener = server.listen(config.server.listenPort);
 
 const handle = async (signal) => {
-    log(`Received signal ${signal}. Shutting down..`);
+    logger.info(`Received signal ${signal}. Shutting down..`);
     listener.close();
     process.exit();
 };
 process.on('SIGINT', handle);
 process.on('SIGTERM', handle);
 
-log(`Listening on port ${config.server.listenPort}`);
+logger.info(`Listening on port ${config.server.listenPort}`);