865 update logs and metrics (#938)

* 865-update-logs-and-metrics.  Added the requestId to the server context.

Signed-off-by: ebadiere <[email protected]>

* Added missing formatters.ts file.

Signed-off-by: ebadiere <[email protected]>

* Updated year in copyright.

Signed-off-by: ebadiere <[email protected]>

* Added error logging to the koaJsonRpc.

Signed-off-by: ebadiere <[email protected]>

* Moved request error messages into constants.

Signed-off-by: ebadiere <[email protected]>

---------

Signed-off-by: ebadiere <[email protected]>

Author: ebadiere

packages/server/src/koaJsonRpc/index.ts

@@ -26,6 +26,7 @@ import parse from 'co-body';
 import dotenv from 'dotenv';
 import path from 'path';
 import { Logger } from 'pino';
+import { formatRequestIdMessage } from '../formatters';
 
 import {
   ParseError,
@@ -42,6 +43,13 @@ import { JsonRpcError } from '@hashgraph/json-rpc-relay';
 const hasOwnProperty = (obj, prop) => Object.prototype.hasOwnProperty.call(obj, prop);
 dotenv.config({ path: path.resolve(__dirname, '../../../../../.env') });
 
+const INTERNAL_ERROR = "INTERNAL ERROR";
+const INVALID_PARAMS_ERROR = "INVALID PARAMS ERROR";
+const INVALID_REQUEST = "INVALID REQUEST";
+const IP_RATE_LIMIT_EXCEEDED = "IP RATE LIMIT EXCEEDED";
+const JSON_RPC_ERROR = "JSON RPC ERROR"
+const METHOD_NOT_FOUND = "METHOD NOT FOUND";
+
 export default class KoaJsonRpc {
   private registry: any;
   private registryTotal: any;
@@ -52,6 +60,8 @@ export default class KoaJsonRpc {
   private rateLimit: RateLimit;
   private koaApp: Koa<Koa.DefaultState, Koa.DefaultContext>;
   private requestId: string;
+  private logger: Logger;
+  private startTimestamp!: number;
 
   constructor(logger: Logger, register: Registry, opts?) {
     this.koaApp = new Koa();
@@ -64,6 +74,7 @@ export default class KoaJsonRpc {
     if (opts) {
       this.limit = opts.limit || this.limit;
     }
+    this.logger = logger;
     this.rateLimit = new RateLimit(logger.child({ name: 'ip-rate-limit' }), register, this.duration);
   }
 
@@ -78,8 +89,12 @@ export default class KoaJsonRpc {
 
   rpcApp() {
     return async (ctx, next) => {
-      let body, result;
+      this.startTimestamp = ctx.state.start;
+      let body, ms, result;
 
+      this.requestId = ctx.state.reqId;
+      const requestIdPrefix =  formatRequestIdMessage(this.requestId);
+      
       if (this.token) {
         const headerToken = ctx.get('authorization').split(' ').pop();
         if (headerToken !== this.token) {
@@ -96,6 +111,9 @@ export default class KoaJsonRpc {
         return;
       }
 
+      const methodName = body.method;
+      const messagePrefix = `${requestIdPrefix} [POST] ${methodName}:`;
+
       if (
         body.jsonrpc !== '2.0' ||
         !hasOwnProperty(body, 'method') ||
@@ -104,21 +122,26 @@ export default class KoaJsonRpc {
       ) {
         ctx.body = jsonResp(body.id || null, new InvalidRequest(), undefined);
         ctx.status = 400;
+        ms = Date.now() - this.startTimestamp;
+        this.logger.error(`${messagePrefix} ${ctx.status} (${INVALID_REQUEST}) ${ms} ms`);
         return;
       }
 
       if (!this.registry[body.method]) {
         ctx.body = jsonResp(body.id, new MethodNotFound(), undefined);
         ctx.status = 400;
+        ms = Date.now() - this.startTimestamp;
+        this.logger.error(`${messagePrefix} ${ctx.status} (${METHOD_NOT_FOUND}) ${ms} ms`);
         return;
       }
 
-      this.requestId = ctx.state.reqId;
-      const methodName = body.method;
+ 
       const methodTotalLimit = this.registryTotal[methodName];
       if (this.rateLimit.shouldRateLimit(ctx.ip, methodName, methodTotalLimit, this.requestId)) {
         ctx.body = jsonResp(body.id, new IPRateLimitExceeded(methodName), undefined);
         ctx.status = 409;
+        ms = Date.now() - this.startTimestamp;
+        this.logger.warn(`${messagePrefix} ${ctx.status} (${IP_RATE_LIMIT_EXCEEDED}) ${ms} ms`);
         return;
       }
 
@@ -128,16 +151,22 @@ export default class KoaJsonRpc {
         if (e instanceof InvalidParamsError) {
           ctx.body = jsonResp(body.id, new InvalidParamsError(e.message), undefined);
           ctx.status = 400;
+          ms = Date.now() - this.startTimestamp;
+          this.logger.error(`${messagePrefix} ${ctx.status} (${INVALID_PARAMS_ERROR}) ${ms} ms`);
           return;
         }
         ctx.body = jsonResp(body.id, new InternalError(e.message), undefined);
         ctx.status = 500;
+        ms = Date.now() - this.startTimestamp;
+        this.logger.error(`${messagePrefix} ${ctx.status} (${INTERNAL_ERROR}) ${ms} ms`);
         return;
       }
 
       ctx.body = jsonResp(body.id, null, result);
       if (result instanceof JsonRpcError) {
         ctx.status = (result.code == -32603) ? 500 : 400;
+        ms = Date.now() - this.startTimestamp;
+        this.logger.error(`${messagePrefix} ${ctx.status} (${result.code}) (${JSON_RPC_ERROR}) ${ms} ms`);
       }
     };
   }
@@ -149,4 +178,8 @@ export default class KoaJsonRpc {
   getRequestId(): string {
     return this.requestId;
   }
+
+  getStartTimestamp(): number {
+    return this.startTimestamp;
+  }
 }

packages/server/src/server.ts

@@ -48,7 +48,6 @@ const app = new KoaJsonRpc(logger, register, {
   limit: process.env.INPUT_SIZE_LIMIT ? process.env.INPUT_SIZE_LIMIT + 'mb' : null
 });
 
-const REQUEST_ID_STRING = `Request ID: `;
 const responseSuccessStatusCode = '200';
 const responseInternalErrorCode = '-32603';
 collectDefaultMetrics({ register, prefix: 'rpc_relay_' });
@@ -166,13 +165,13 @@ app.getKoaApp().use(async (ctx, next) => {
     ctx.set(options.expose, id);
   }
 
+  ctx.state.start = Date.now();
   ctx.state.reqId = id;
 
   return next();
 });
 
 const logAndHandleResponse = async (methodName: any, methodParams: any, methodFunction: any) => {
-  const start = Date.now();
   let ms;
 
   const requestId = app.getRequestId();
@@ -189,7 +188,7 @@ const logAndHandleResponse = async (methodName: any, methodParams: any, methodFu
 
     const response = await methodFunction(requestId);
     const status = response instanceof JsonRpcError ? response.code.toString() : responseSuccessStatusCode;
-    ms = Date.now() - start;
+    ms = Date.now() - app.getStartTimestamp();
     methodResponseHistogram.labels(methodName, status).observe(ms);
     logger.info(`${messagePrefix} ${status} ${ms} ms `);
     if (response instanceof JsonRpcError) {
@@ -203,7 +202,7 @@ const logAndHandleResponse = async (methodName: any, methodParams: any, methodFu
     }
     return response;
   } catch (e: any) {
-    ms = Date.now() - start;
+    ms = Date.now() - app.getStartTimestamp();
     methodResponseHistogram.labels(methodName, responseInternalErrorCode).observe(ms);
     logger.error(e, `${messagePrefix} ${responseInternalErrorCode} ${ms} ms`);