[logging] Update logging format, gracefully handle errors (#57)

.github/workflows/CI.yaml

@@ -7,7 +7,7 @@ on:
 
 jobs:
   test:
-    runs-on: ubuntu-20.04
+    runs-on: ubuntu-22.04
     steps:
       - name: Cancel previous workflow runs
         uses: styfle/[email protected]

server/src/controllers/Controller.ts

@@ -1,7 +1,9 @@
+import camelCase from 'camelcase';
 import fs from 'fs';
 import path from 'path';
-import camelCase from 'camelcase';
 import config from '../config';
+import { ApiError, constructRosettaError, isRosettaError } from '../helpers/errors';
+import logger from '../logger';
 
 export default class Controller {
   static sendResponse(response, payload) {
@@ -10,7 +12,21 @@ export default class Controller {
      * payload will be an object consisting of a code and a payload. If not customized
      * send 200 and the payload as received in this method.
      */
-    response.status(payload.code || 200);
+    const statusCode = payload.code || 200;
+    response.status(statusCode);
+
+    const rosettaTraceId: string = response.getHeader('x-rosetta-trace-id');
+    response.removeHeader('x-rosetta-trace-id');
+
+    logger.info('server.response', {
+      request: {
+        method: response.req.method,
+        path: response.req.path
+      },
+      rosetta_trace_id: rosettaTraceId,
+      status: statusCode
+    });
+
     const responsePayload = payload.payload !== undefined ? payload.payload : payload;
     if (responsePayload instanceof Object) {
       response.json(responsePayload);
@@ -19,11 +35,31 @@ export default class Controller {
     }
   }
 
-  static sendError(response, error) {
-    response.status(500);
+  static sendError(response, error) {    
+    const statusCode = 500;
+    response.status(statusCode);
+
+    let rosettaError: Error = isRosettaError(error) ? error : constructRosettaError(ApiError.UNHANDLED_ERROR, {
+      error_type: error.constructor.name,
+      stack_trace: error.stack
+    });
+
+    const rosettaTraceId: string = response.getHeader('x-rosetta-trace-id');
+    response.removeHeader('x-rosetta-trace-id');
+
+    logger.error('server.response', {
+      error: rosettaError,
+      status: statusCode,
+      request: {
+        body: response.req.body,
+        method: response.req.method,
+        path: response.req.path
+      },
+      rosetta_trace_id: rosettaTraceId
+    });
 
-    if (error instanceof Object) {
-      response.json(error);
+    if (rosettaError instanceof Object) {
+      response.json(rosettaError);
     } else {
       response.end(error);
     }
@@ -107,7 +143,6 @@ export default class Controller {
       const serviceResponse = await serviceOperation(this.collectRequestParams(request));
       Controller.sendResponse(response, serviceResponse);
     } catch (error) {
-      console.log(error);
       Controller.sendError(response, error);
     }
   }

server/src/expressServer.ts

@@ -1,29 +1,34 @@
-import { middleware } from 'express-openapi-validator';
-import swaggerUI from 'swagger-ui-express';
-import express, { Express } from 'express';
-import cookieParser from 'cookie-parser';
 import bodyParser from 'body-parser';
-import jsYaml from 'js-yaml';
+import cookieParser from 'cookie-parser';
 import cors from 'cors';
+import { randomUUID } from 'crypto';
+import express, { Express } from 'express';
+import { middleware } from 'express-openapi-validator';
+import fs from 'fs';
 import http from 'http';
+import jsYaml from 'js-yaml';
 import path from 'path';
-import fs from 'fs';
-
-import logger from './logger';
+import swaggerUI from 'swagger-ui-express';
+import { Logger } from 'winston';
 import config from './config';
+import logger from './logger';
 
 export default class ExpressServer {
   schema: any;
   app: Express;
   server: http.Server;
+  logger: Logger
 
   constructor(private port: number, private openApiPath: string) {
     this.app = express();
+    this.logger = logger
+
     try {
       this.schema = jsYaml.load(fs.readFileSync(openApiPath));
     } catch (e) {
-      logger.error('failed to start Express Server', e.message);
+      this.logger.error('Failed to start Express Server', { error: e });
     }
+
     this.setupMiddleware();
   }
 
@@ -34,20 +39,43 @@ export default class ExpressServer {
     this.app.use(express.json());
     this.app.use(express.urlencoded({ extended: false }));
     this.app.use(cookieParser());
+
     // Simple test to see that the server is up and responding
     this.app.get('/hello', (req, res) => res.send(`Hello World. path: ${this.openApiPath}`));
+
     // Send the openapi document *AS GENERATED BY THE GENERATOR*
     this.app.get('/openapi', (req, res) => res.sendFile(path.join(__dirname, 'api', 'openapi.yaml')));
+
     // View the openapi document in a visual interface. Should be able to test from this page
     this.app.use('/api-docs', swaggerUI.serve, swaggerUI.setup(this.schema));
+
     this.app.get('/login-redirect', (req, res) => {
       res.status(200);
       res.json(req.query);
     });
+
     this.app.get('/oauth2-redirect.html', (req, res) => {
       res.status(200);
       res.json(req.query);
     });
+
+    this.app.use((req, res, next) => {
+      const rosettaTraceId: string = randomUUID();
+
+      if (req.path !== "/_health") {
+        this.logger.info('server.request', {
+          request: {
+            method: req.method,
+            path: req.path
+          },
+          rosetta_trace_id: rosettaTraceId
+        });
+      }
+
+      res.setHeader('x-rosetta-trace-id', rosettaTraceId);
+
+      next();
+    });
   }
 
   launch() {
@@ -61,21 +89,31 @@ export default class ExpressServer {
     );
 
     this.app.use((err, req, res, next) => {
-      console.log(err);
+      if (req.path !== "/_health") {
+        this.logger.error(null, {
+          request: {
+            body: res.req.body,
+            method: res.req.method,
+            path: res.req.path
+          },
+          error: err
+        });
+      }
+
       res.status(err.status || 500).json({
         message: err.message || err,
         errors: err.errors || '',
       });
     });
 
     this.server = http.createServer(this.app).listen(this.port);
-    logger.info(`Listening on port ${this.port}`);
+    this.logger.info(`Listening on port ${this.port}`);
   }
 
   async close() {
     if (this.server !== undefined) {
       await this.server.close();
-      logger.info(`Server on port ${this.port} shut down`);
+      this.logger.info(`Server on port ${this.port} shut down)`);
     }
   }
 }

server/src/helpers/construct-tx.ts

@@ -1,9 +1,10 @@
 import { methods, deriveAddress, decode } from '@substrate/txwrapper-polkadot';
 import { hexToString, hexToU8a, stringToHex, u8aConcat, u8aToHex } from '@polkadot/util';
 import { EXTRINSIC_VERSION } from '@polkadot/types/extrinsic/v4/Extrinsic';
-
 import { GearNetworkIdentifier } from '../networks';
 
+import logger from '../logger';
+
 export interface TxParams {
   dest: string;
   value: string;
@@ -76,6 +77,15 @@ export function parseTransaction(
   const tx = signed
     ? decode(transaction, { registry, metadataRpc })
     : decode(JSON.parse(hexToString(transaction)), { registry, metadataRpc });
+
+  tx.metadataRpc = "0x...truncated...";
+
+  logger.info(`Decoded ${signed ? 'signed' : 'unsigned'} transaction`, {
+    signed: signed,
+    encoded_tx: transaction,
+    decoded_tx: tx
+  });
+
   const source = tx.address;
   const dest = tx.method.args.dest['id'];
   const value = tx.method.args.value as string;

server/src/helpers/errors.ts

@@ -1,6 +1,6 @@
 import { Error } from 'rosetta-client';
 
-interface E {
+interface RosettaError {
   code: number;
   message: string;
   description?: string;
@@ -21,9 +21,15 @@ export enum ApiError {
   NOT_AVAILABLE_OFFLINE = 609,
   UNABLE_TO_GET_BLOCK = 610,
   INVALID_ACCOUNT_ADDRESS = 611,
+  UNHANDLED_ERROR = 99999
 }
 
-const errors: Record<number, E> = {
+const errors: Record<number, RosettaError> = {
+  [ApiError.UNHANDLED_ERROR]: {
+    code: ApiError.UNHANDLED_ERROR,
+    message: "Encountered an unhandled error",
+    retriable: false,
+  },
   [ApiError.NOT_SUPPORTED]: {
     code: ApiError.NOT_SUPPORTED,
     message: 'Endpoint is not supported',
@@ -90,14 +96,36 @@ const errors: Record<number, E> = {
     code: ApiError.INVALID_ACCOUNT_ADDRESS,
     message: 'Account address is invalid',
     retriable: false,
-  },
+  }
 };
 
-export function throwError(errorCode: ApiError, details?: object) {
+export function constructRosettaError(errorCode: ApiError, details?: object) {
   const { message, retriable, code } = errors[errorCode];
-  throw Error.constructFromObject({ code, message, retriable, details });
+  return Error.constructFromObject({ code, message, retriable, details });
+}
+
+export function throwError(errorCode: ApiError, details?: object) {
+  throw constructRosettaError(errorCode, details);
 }
 
 export const allErrors = Object.values(errors).map(
   ({ code, message, retriable }) => new Error(code, message, retriable),
 );
+
+export function isRosettaError(error: object): boolean {
+  if(error === undefined || error === null) {
+    return false;
+  }
+
+  if (!error.hasOwnProperty('code')) {
+    return false;
+  }
+  if (!error.hasOwnProperty('message')) {
+    return false;
+  }
+  if (!error.hasOwnProperty('retriable')) {
+    return false;
+  }
+
+  return true;
+}

server/src/helpers/gear.ts

@@ -55,8 +55,7 @@ export class GearApi {
 
       return { block, apiAt };
     } catch (err) {
-      logger.error(`Unable to get block ${at}`);
-      console.error(err);
+      logger.error(`Unable to get block ${at}`, { error: err });
       throwError(ApiError.UNABLE_TO_GET_BLOCK, typeof at === 'string' ? { hash: at } : { number: at });
     }
   }
@@ -102,8 +101,7 @@ export class GearApi {
     try {
       return await this.api.at(hash);
     } catch (err) {
-      logger.error(`Unable to get api instance at ${hash}`);
-      console.log(err);
+      logger.error(`Unable to get api instance at ${hash}`, { error: err });
       throwError(ApiError.UNABLE_TO_GET_BLOCK, { hash });
     }
   }

server/src/index.ts

@@ -18,14 +18,12 @@ const launchServer = async () => {
     expressServer.launch();
     logger.info('Express server running');
   } catch (error) {
-    console.log(error);
-    logger.error('Express Server failure', error.message);
+    logger.error('Express server failure', { error: error });
     await expressServer.close();
   }
 };
 
 launchServer().catch((e) => {
-  logger.error(e);
-  console.log(e);
+  logger.error(null, { error: e });
   process.exit(1);
 });

server/src/logger.ts

@@ -1,16 +1,44 @@
-import { transports, createLogger, format } from 'winston';
+import { createLogger, format, transports } from 'winston';
 
 export default createLogger({
   level: 'info',
-  format: format.combine(format.timestamp({ format: 'YY-MM-DD HH:mm:ss' }), format.json()),
-  defaultMeta: { service: 'rosetta' },
   transports: [
     new transports.Console({
       format: format.combine(
-        format.colorize(),
-        format.timestamp({ format: 'YY-MM-DD HH:mm:ss' }),
-        format.json(),
-        format.printf(({ level, message, timestamp }) => `${timestamp} [${level}]: ${message}`),
+        format.printf(({ level, message, ...meta }) => {
+          let logEvent: {[index: string]: any; } = {};
+
+          if (!message) {
+            if(!meta.error) {
+              return JSON.stringify({
+                message: 'Unexpected null log message with no error',
+                metadata: meta,
+                severity: 'ERROR'
+              }); 
+            }
+
+            // NOTE: Do to the use of throwError being used to generate a Rosetta-format
+            // response body for caught errors, any uncaught error that hits this flow will
+            // have meta.error = {}. This is doable as the log message will just contain the
+            // request data (method, path, body) and the status code, but ideally we can
+            // capture any error properly in the logs, even if it isn't an "expected" error
+            // code.
+            const err: object = meta.error;
+            delete meta.error;
+            logEvent = { ...err, ...meta };
+          } else if (typeof message === 'string') {
+            if (meta.length !== 0) {
+              logEvent = { message: message, ...meta };
+            } else {
+              logEvent = { message: message }
+            }
+          } else {
+            logEvent = { ...message, ...meta };
+          }
+
+          logEvent.severity = level.toUpperCase();
+          return JSON.stringify(logEvent);
+        }),
       ),
     }),
     new transports.File({ filename: 'error.log', level: 'error' }),