Add logging and metrics to rate limit logic (#622)

Add logging and metrics to rate limit logic

- Add log to user method limit
- Add log to budget limit
- Add metric to method limit
- Capture methodName in user method limit

Signed-off-by: Nana Essilfie-Conduah <[email protected]>

packages/relay/src/lib/clients/sdkClient.ts

@@ -133,7 +133,7 @@ export class SDKClient {
 
         const duration = parseInt(process.env.HBAR_RATE_LIMIT_DURATION!);
         const total = parseInt(process.env.HBAR_RATE_LIMIT_TINYBAR!);
-        this.hbarLimiter = new HbarLimit(Date.now(), total, duration);
+        this.hbarLimiter = new HbarLimit(logger.child({ name: 'hbar-rate-limit' }), Date.now(), total, duration);
     }
 
     async getAccountBalance(account: string, callerName: string, requestId?: string): Promise<AccountBalance> {

packages/relay/src/lib/hbarlimiter/index.ts

@@ -18,14 +18,18 @@
  *
  */
 
+import { Logger } from 'pino';
+
 export default class HbarLimit {
     private enabled: boolean = false;
     private remainingBudget: number;
     private duration: number = 0;
     private total: number = 0;
     private reset: number;
+    private logger: Logger;
 
-    constructor(currentDateNow: number, total: number, duration: number) {
+    constructor(logger: Logger, currentDateNow: number, total: number, duration: number) {
+        this.logger = logger;
         this.enabled = false;
 
         if (total && duration) {
@@ -48,7 +52,13 @@ export default class HbarLimit {
         if (this.shouldResetLimiter(currentDateNow)){
             this.resetLimiter(currentDateNow);
         }
-        return this.remainingBudget <= 0 ? true : false;
+
+        if (this.remainingBudget <= 0) {
+            this.logger.warn(`Rate limit incoming calls, ${this.remainingBudget} out of ${this.total} tℏ left in relay budget until ${this.reset}`);
+            return true;
+        }
+
+        return false;
     }
 
     /**

packages/relay/tests/lib/hbarLimiter.spec.ts

@@ -19,8 +19,11 @@
  */
 
 import { expect } from 'chai';
+import pino from 'pino';
 import HbarLimit from '../../src/lib/hbarlimiter';
 
+const logger = pino();
+
 describe('HBAR Rate Limiter', async function () {
     this.timeout(20000);
     let rateLimiter: HbarLimit;
@@ -35,7 +38,7 @@ describe('HBAR Rate Limiter', async function () {
     });
 
     it('should be disabled, if we pass invalid total', async function () {
-        rateLimiter = new HbarLimit(currentDateNow, invalidTotal, validDuration);
+        rateLimiter = new HbarLimit(logger, currentDateNow, invalidTotal, validDuration);
 
         const isEnabled = rateLimiter.isEnabled();
         const limiterResetTime = rateLimiter.getResetTime();
@@ -50,7 +53,7 @@ describe('HBAR Rate Limiter', async function () {
     });
 
     it('should be disabled, if we pass invalid duration', async function () {
-        rateLimiter = new HbarLimit(currentDateNow, validTotal, invalidDuration);
+        rateLimiter = new HbarLimit(logger, currentDateNow, validTotal, invalidDuration);
 
         const isEnabled = rateLimiter.isEnabled();
         const limiterResetTime = rateLimiter.getResetTime();
@@ -65,7 +68,7 @@ describe('HBAR Rate Limiter', async function () {
     });
 
     it('should be disabled, if we pass both invalid duration and total', async function () {
-        rateLimiter = new HbarLimit(currentDateNow, invalidTotal, invalidDuration);
+        rateLimiter = new HbarLimit(logger, currentDateNow, invalidTotal, invalidDuration);
 
         const isEnabled = rateLimiter.isEnabled();
         const limiterResetTime = rateLimiter.getResetTime();
@@ -80,7 +83,7 @@ describe('HBAR Rate Limiter', async function () {
     });
 
     it('should be enabled, if we pass valid duration and total', async function () {
-        rateLimiter = new HbarLimit(currentDateNow, validTotal, validDuration);
+        rateLimiter = new HbarLimit(logger, currentDateNow, validTotal, validDuration);
 
         const isEnabled = rateLimiter.isEnabled();
         const limiterResetTime = rateLimiter.getResetTime();
@@ -95,7 +98,7 @@ describe('HBAR Rate Limiter', async function () {
 
     it('should not rate limit', async function () {
         const cost = 10000000;
-        rateLimiter = new HbarLimit(currentDateNow, validTotal, validDuration);
+        rateLimiter = new HbarLimit(logger, currentDateNow, validTotal, validDuration);
         rateLimiter.addExpense(cost, currentDateNow);
 
         const isEnabled = rateLimiter.isEnabled();
@@ -111,7 +114,7 @@ describe('HBAR Rate Limiter', async function () {
 
     it('should rate limit', async function () {
         const cost = 1000000000;
-        rateLimiter = new HbarLimit(currentDateNow, validTotal, validDuration);
+        rateLimiter = new HbarLimit(logger, currentDateNow, validTotal, validDuration);
         rateLimiter.addExpense(cost, currentDateNow);
 
         const isEnabled = rateLimiter.isEnabled();
@@ -127,7 +130,7 @@ describe('HBAR Rate Limiter', async function () {
 
     it('should reset budget, while checking if we should rate limit', async function () {
         const cost = 1000000000;
-        rateLimiter = new HbarLimit(currentDateNow, validTotal, validDuration);
+        rateLimiter = new HbarLimit(logger, currentDateNow, validTotal, validDuration);
         rateLimiter.addExpense(cost, currentDateNow);
 
         const isEnabled = rateLimiter.isEnabled();
@@ -144,7 +147,7 @@ describe('HBAR Rate Limiter', async function () {
 
     it('should reset budget, while adding expense', async function () {
         const cost = 1000000000;
-        rateLimiter = new HbarLimit(currentDateNow, validTotal, validDuration);
+        rateLimiter = new HbarLimit(logger, currentDateNow, validTotal, validDuration);
 
         rateLimiter.addExpense(cost, currentDateNow);
         const shouldRateLimitBefore = rateLimiter.shouldLimit(currentDateNow);

packages/server/src/koaJsonRpc/index.ts

@@ -25,6 +25,7 @@ import RateLimit from '../ratelimit';
 import parse from 'co-body';
 import dotenv from 'dotenv';
 import path from 'path';
+import { Logger } from 'pino';
 import {
   ParseError,
   InvalidRequest,
@@ -34,6 +35,7 @@ import {
   Unauthorized
 } from './lib/RpcError';
 import Koa from 'koa';
+import { Registry } from 'prom-client';
 
 const hasOwnProperty = (obj, prop) => Object.prototype.hasOwnProperty.call(obj, prop);
 dotenv.config({ path: path.resolve(__dirname, '../../../../../.env') });
@@ -48,7 +50,7 @@ export default class KoaJsonRpc {
   private ratelimit: RateLimit;
   private koaApp: Koa<Koa.DefaultState, Koa.DefaultContext>;
 
-  constructor(opts?) {
+  constructor(logger: Logger, register: Registry, opts?) {
     this.koaApp = new Koa();
     this.limit = '1mb';
     this.duration = parseInt(process.env.LIMIT_DURATION!);
@@ -59,7 +61,7 @@ export default class KoaJsonRpc {
       this.limit = opts.limit || this.limit;
       this.duration = opts.limit || this.limit;
     }
-    this.ratelimit = new RateLimit(this.duration);
+    this.ratelimit = new RateLimit(logger.child({ name: 'ip-rate-limit' }), register, this.duration);
   }
 
   useRpc(name, func) {
@@ -109,7 +111,7 @@ export default class KoaJsonRpc {
       const methodName = body.method;
       const methodTotalLimit = this.registryTotal[methodName];
       if (this.ratelimit.shouldRateLimit(ctx.ip, methodName, methodTotalLimit)) {
-        ctx.body = jsonResp(body.id, new IPRateLimitExceeded(), undefined);
+        ctx.body = jsonResp(body.id, new IPRateLimitExceeded(methodName), undefined);
         return;
       }
 

packages/server/src/koaJsonRpc/lib/RpcError.ts

@@ -85,8 +85,8 @@ export class ServerError extends JsonRpcError {
 }
 
 export class IPRateLimitExceeded extends JsonRpcError {
-  constructor() {
-    super('IP Rate limit exceeded', -32605, undefined);
+  constructor(methodName) {
+    super(`IP Rate limit exceeded on ${methodName}`, -32605, undefined);
   }
 }
 

packages/server/src/ratelimit/index.ts

@@ -18,13 +18,28 @@
  *
  */
 
+import { Logger } from 'pino';
+import { Gauge, Registry } from 'prom-client';
+
 export default class RateLimit {
-  duration: number;
-  database: any;
+  private duration: number;
+  private database: any;
+  private logger: Logger;
+  private ipRateLimitGauge: Gauge;
 
-  constructor(duration) {
+  constructor(logger: Logger, register: Registry, duration) {
+    this.logger = logger;
     this.duration = duration;
     this.database = Object.create(null);
+
+    const metricGaugeName = 'rpc_relay_ip_rate_limit';
+    register.removeSingleMetric(metricGaugeName);
+    this.ipRateLimitGauge = new Gauge({
+        name: metricGaugeName,
+        help: 'Relay ip rate limit gauge',
+        labelNames: ['methodName'],
+        registers: [register],
+    });
   }
 
   shouldRateLimit(ip: string, methodName: string, total: number): boolean {
@@ -34,6 +49,9 @@ export default class RateLimit {
         this.decreaseRemaining(ip, methodName);
         return false;
       }
+
+      this.ipRateLimitGauge.labels(methodName).inc(1);
+      this.logger.warn(`Rate limit call to ${methodName}, ${this.database[ip].methodInfo[methodName].remaining} out of ${total} calls remaining`);
       return true;
     } else {
       this.reset(ip, methodName, total);

packages/server/src/server.ts

@@ -42,7 +42,7 @@ const cors = require('koa-cors');
 const logger = mainLogger.child({ name: 'rpc-server' });
 const register = new Registry();
 const relay: Relay = new RelayImpl(logger, register);
-const app = new KoaJsonRpc();
+const app = new KoaJsonRpc(logger, register);
 
 const REQUEST_ID_STRING = `Request ID: `;
 const responseSuccessStatusCode = '200';
@@ -144,7 +144,7 @@ const logAndHandleResponse = async (methodName, methodFunction) => {
     methodResponseHistogram.labels(methodName, status).observe(ms);
     logger.info(`${messagePrefix} ${status} ${ms} ms `);
     if (response instanceof JsonRpcError) {
-      logger.error(`returning error to sender: ${requestIdPrefix} ${response.message}`)
+      logger.error(`returning error to sender: ${requestIdPrefix} ${response.message}`);
       return new JsonRpcError({
         name: response.name,
         code: response.code,