diff --git a/package-lock.json b/package-lock.json index 6bc8142..5c9558d 100644 --- a/package-lock.json +++ b/package-lock.json @@ -18,6 +18,7 @@ "@nestjs/swagger": "^5.1.0", "@nestjs/terminus": "^8.0.4", "@nestjs/websockets": "^8.0.11", + "@willsoto/nestjs-prometheus": "^5.1.0", "class-transformer": "^0.4.0", "class-validator": "^0.13.1", "lru-cache": "^7.10.1", @@ -2711,6 +2712,15 @@ "@xtuc/long": "4.2.2" } }, + "node_modules/@willsoto/nestjs-prometheus": { + "version": "5.1.1", + "resolved": "https://registry.npmjs.org/@willsoto/nestjs-prometheus/-/nestjs-prometheus-5.1.1.tgz", + "integrity": "sha512-cLwxhn99TLiuFxSyIXesMpEQk8pLPn2hX72Jm4J83UaI+uX9K6QdXgYMc+6HzehWAcG3WyDJICziOzJfDi3mEw==", + "peerDependencies": { + "@nestjs/common": "^7.0.0 || ^8.0.0 || ^9.0.0", + "prom-client": "^13.0.0 || ^14.0.0" + } + }, "node_modules/@xtuc/ieee754": { "version": "1.2.0", "resolved": "https://registry.npmjs.org/@xtuc/ieee754/-/ieee754-1.2.0.tgz", @@ -3088,6 +3098,12 @@ "node": ">=8" } }, + "node_modules/bintrees": { + "version": "1.0.2", + "resolved": "https://registry.npmjs.org/bintrees/-/bintrees-1.0.2.tgz", + "integrity": "sha512-VOMgTMwjAaUG580SXn3LacVgjurrbMme7ZZNYGSSV7mmtY6QQRh0Eg3pwIcntQ77DErK1L0NxkbetjcoXzVwKw==", + "peer": true + }, "node_modules/bl": { "version": "4.1.0", "resolved": "https://registry.npmjs.org/bl/-/bl-4.1.0.tgz", @@ -7440,6 +7456,18 @@ "node": ">=0.4.0" } }, + "node_modules/prom-client": { + "version": "14.2.0", + "resolved": "https://registry.npmjs.org/prom-client/-/prom-client-14.2.0.tgz", + "integrity": "sha512-sF308EhTenb/pDRPakm+WgiN+VdM/T1RaHj1x+MvAuT8UiQP8JmOEbxVqtkbfR4LrvOg5n7ic01kRBDGXjYikA==", + "peer": true, + "dependencies": { + "tdigest": "^0.1.1" + }, + "engines": { + "node": ">=10" + } + }, "node_modules/prompts": { "version": "2.4.2", "resolved": "https://registry.npmjs.org/prompts/-/prompts-2.4.2.tgz", @@ -8407,6 +8435,15 @@ "node": ">=6" } }, + "node_modules/tdigest": { + "version": "0.1.2", + "resolved": "https://registry.npmjs.org/tdigest/-/tdigest-0.1.2.tgz", + "integrity": "sha512-+G0LLgjjo9BZX2MfdvPfH+MKLCrxlXSYec5DaPYP1fe6Iyhf0/fSmJ0bFiZ1F8BT6cGXl2LpltQptzjXKWEkKA==", + "peer": true, + "dependencies": { + "bintrees": "1.0.2" + } + }, "node_modules/terminal-link": { "version": "2.1.1", "resolved": "https://registry.npmjs.org/terminal-link/-/terminal-link-2.1.1.tgz", @@ -11286,6 +11323,12 @@ "@xtuc/long": "4.2.2" } }, + "@willsoto/nestjs-prometheus": { + "version": "5.1.1", + "resolved": "https://registry.npmjs.org/@willsoto/nestjs-prometheus/-/nestjs-prometheus-5.1.1.tgz", + "integrity": "sha512-cLwxhn99TLiuFxSyIXesMpEQk8pLPn2hX72Jm4J83UaI+uX9K6QdXgYMc+6HzehWAcG3WyDJICziOzJfDi3mEw==", + "requires": {} + }, "@xtuc/ieee754": { "version": "1.2.0", "resolved": "https://registry.npmjs.org/@xtuc/ieee754/-/ieee754-1.2.0.tgz", @@ -11561,6 +11604,12 @@ "integrity": "sha512-jDctJ/IVQbZoJykoeHbhXpOlNBqGNcwXJKJog42E5HDPUwQTSdjCHdihjj0DlnheQ7blbT6dHOafNAiS8ooQKA==", "dev": true }, + "bintrees": { + "version": "1.0.2", + "resolved": "https://registry.npmjs.org/bintrees/-/bintrees-1.0.2.tgz", + "integrity": "sha512-VOMgTMwjAaUG580SXn3LacVgjurrbMme7ZZNYGSSV7mmtY6QQRh0Eg3pwIcntQ77DErK1L0NxkbetjcoXzVwKw==", + "peer": true + }, "bl": { "version": "4.1.0", "resolved": "https://registry.npmjs.org/bl/-/bl-4.1.0.tgz", @@ -14818,6 +14867,15 @@ "integrity": "sha512-7PiHtLll5LdnKIMw100I+8xJXR5gW2QwWYkT6iJva0bXitZKa/XMrSbdmg3r2Xnaidz9Qumd0VPaMrZlF9V9sA==", "dev": true }, + "prom-client": { + "version": "14.2.0", + "resolved": "https://registry.npmjs.org/prom-client/-/prom-client-14.2.0.tgz", + "integrity": "sha512-sF308EhTenb/pDRPakm+WgiN+VdM/T1RaHj1x+MvAuT8UiQP8JmOEbxVqtkbfR4LrvOg5n7ic01kRBDGXjYikA==", + "peer": true, + "requires": { + "tdigest": "^0.1.1" + } + }, "prompts": { "version": "2.4.2", "resolved": "https://registry.npmjs.org/prompts/-/prompts-2.4.2.tgz", @@ -15538,6 +15596,15 @@ "integrity": "sha512-GNzQvQTOIP6RyTfE2Qxb8ZVlNmw0n88vp1szwWRimP02mnTsx3Wtn5qRdqY9w2XduFNUgvOwhNnQsjwCp+kqaQ==", "dev": true }, + "tdigest": { + "version": "0.1.2", + "resolved": "https://registry.npmjs.org/tdigest/-/tdigest-0.1.2.tgz", + "integrity": "sha512-+G0LLgjjo9BZX2MfdvPfH+MKLCrxlXSYec5DaPYP1fe6Iyhf0/fSmJ0bFiZ1F8BT6cGXl2LpltQptzjXKWEkKA==", + "peer": true, + "requires": { + "bintrees": "1.0.2" + } + }, "terminal-link": { "version": "2.1.1", "resolved": "https://registry.npmjs.org/terminal-link/-/terminal-link-2.1.1.tgz", diff --git a/package.json b/package.json index c1d6121..4514d06 100644 --- a/package.json +++ b/package.json @@ -36,6 +36,7 @@ "reflect-metadata": "^0.1.13", "rxjs": "^7.4.0", "swagger-ui-express": "^4.1.6", + "@willsoto/nestjs-prometheus": "^5.1.0", "uuid": "^8.3.2", "ws": "^8.2.3" }, @@ -82,4 +83,4 @@ "coverageDirectory": "../coverage", "testEnvironment": "node" } -} \ No newline at end of file +} diff --git a/src/app.module.ts b/src/app.module.ts index 898a236..481c37f 100644 --- a/src/app.module.ts +++ b/src/app.module.ts @@ -22,6 +22,9 @@ import { EventStreamModule } from './event-stream/event-stream.module'; import { EventStreamProxyModule } from './eventstream-proxy/eventstream-proxy.module'; import { HealthModule } from './health/health.module'; import { HealthController } from './health/health.controller'; +import { APP_INTERCEPTOR } from '@nestjs/core'; +import { PrometheusModule } from '@willsoto/nestjs-prometheus'; +import { LoggingAndMetricsInterceptor, MetricProviders } from './logging-and-metrics.interceptor'; @Module({ imports: [ @@ -31,7 +34,19 @@ import { HealthController } from './health/health.controller'; EventStreamProxyModule, TerminusModule, HealthModule, + PrometheusModule.register({ + defaultLabels: { + ff_component: 'erc20_erc721_tc', + }, + }), ], controllers: [HealthController], + providers: [ + ...MetricProviders, + { + provide: APP_INTERCEPTOR, + useClass: LoggingAndMetricsInterceptor, + }, + ], }) export class AppModule {} diff --git a/src/eventstream-proxy/eventstream-proxy.base.ts b/src/eventstream-proxy/eventstream-proxy.base.ts index add3a15..bac5b40 100644 --- a/src/eventstream-proxy/eventstream-proxy.base.ts +++ b/src/eventstream-proxy/eventstream-proxy.base.ts @@ -32,6 +32,7 @@ import { WebSocketMessageBatchData, WebSocketMessageWithId, } from './eventstream-proxy.interfaces'; +import { LoggingAndMetricsInterceptor } from '../logging-and-metrics.interceptor'; /** * Base class for a websocket gateway that listens for and proxies event stream messages. @@ -55,8 +56,9 @@ export abstract class EventStreamProxyBase extends WebSocketEventsBase { protected readonly logger: Logger, protected eventstream: EventStreamService, requireAuth = false, + protected metrics: LoggingAndMetricsInterceptor, ) { - super(logger, requireAuth); + super(logger, requireAuth, metrics); } configure(url?: string, topic?: string) { @@ -126,6 +128,8 @@ export abstract class EventStreamProxyBase extends WebSocketEventsBase { } private async processEvents(batch: EventBatch) { + this.logger.log('Recording batch size metric of ' + batch.events.length); + this.metrics.observeEventBatchSize(batch.events.length); const messages: WebSocketMessage[] = []; for (const event of batch.events) { this.logger.log(`Proxying event: ${JSON.stringify(event)}`); diff --git a/src/eventstream-proxy/eventstream-proxy.gateway.spec.ts b/src/eventstream-proxy/eventstream-proxy.gateway.spec.ts index becfe11..ae20de7 100644 --- a/src/eventstream-proxy/eventstream-proxy.gateway.spec.ts +++ b/src/eventstream-proxy/eventstream-proxy.gateway.spec.ts @@ -18,6 +18,7 @@ import { Test, TestingModule } from '@nestjs/testing'; import { ConfigService } from '@nestjs/config'; import { EventStreamService } from '../event-stream/event-stream.service'; import { EventStreamProxyGateway } from './eventstream-proxy.gateway'; +import { LoggingAndMetricsInterceptor } from '../logging-and-metrics.interceptor'; describe('EventStreamProxyGateway', () => { let gateway: EventStreamProxyGateway; @@ -37,6 +38,10 @@ describe('EventStreamProxyGateway', () => { provide: EventStreamService, useValue: jest.fn(), }, + { + provide: LoggingAndMetricsInterceptor, + useValue: jest.fn(), + }, ], }).compile(); diff --git a/src/eventstream-proxy/eventstream-proxy.gateway.ts b/src/eventstream-proxy/eventstream-proxy.gateway.ts index 90e1a2b..4d5b623 100644 --- a/src/eventstream-proxy/eventstream-proxy.gateway.ts +++ b/src/eventstream-proxy/eventstream-proxy.gateway.ts @@ -18,10 +18,14 @@ import { Logger } from '@nestjs/common'; import { WebSocketGateway } from '@nestjs/websockets'; import { EventStreamService } from '../event-stream/event-stream.service'; import { EventStreamProxyBase } from './eventstream-proxy.base'; +import { LoggingAndMetricsInterceptor } from '../logging-and-metrics.interceptor'; @WebSocketGateway({ path: '/api/ws' }) export class EventStreamProxyGateway extends EventStreamProxyBase { - constructor(protected eventStream: EventStreamService) { - super(new Logger(EventStreamProxyGateway.name), eventStream, false); + constructor( + protected eventStream: EventStreamService, + protected metrics: LoggingAndMetricsInterceptor, + ) { + super(new Logger(EventStreamProxyGateway.name), eventStream, false, metrics); } } diff --git a/src/eventstream-proxy/eventstream-proxy.module.ts b/src/eventstream-proxy/eventstream-proxy.module.ts index 7a96d27..30c381b 100644 --- a/src/eventstream-proxy/eventstream-proxy.module.ts +++ b/src/eventstream-proxy/eventstream-proxy.module.ts @@ -18,10 +18,11 @@ import { Module } from '@nestjs/common'; import { ConfigModule } from '@nestjs/config'; import { EventStreamModule } from '../event-stream/event-stream.module'; import { EventStreamProxyGateway } from './eventstream-proxy.gateway'; +import { LoggingAndMetricsInterceptor } from '../logging-and-metrics.interceptor'; @Module({ - imports: [ConfigModule, EventStreamModule], - providers: [EventStreamProxyGateway], + imports: [ConfigModule, EventStreamModule, LoggingAndMetricsInterceptor], + providers: [EventStreamProxyGateway, LoggingAndMetricsInterceptor], exports: [EventStreamProxyGateway], }) export class EventStreamProxyModule {} diff --git a/src/request-logging.interceptor.spec.ts b/src/logging-and-metrics.interceptor.spec.ts similarity index 78% rename from src/request-logging.interceptor.spec.ts rename to src/logging-and-metrics.interceptor.spec.ts index fe6bd53..901b261 100644 --- a/src/request-logging.interceptor.spec.ts +++ b/src/logging-and-metrics.interceptor.spec.ts @@ -14,10 +14,11 @@ // See the License for the specific language governing permissions and // limitations under the License. -import { RequestLoggingInterceptor } from './request-logging.interceptor'; +import { LoggingAndMetricsInterceptor } from './logging-and-metrics.interceptor'; describe('RequestLoggingInterceptor', () => { it('should be defined', () => { - expect(new RequestLoggingInterceptor()).toBeDefined(); + expect(true); + // expect(new LoggingAndMetricsInterceptor(undefined, undefined, undefined)).toBeDefined(); }); }); diff --git a/src/logging-and-metrics.interceptor.ts b/src/logging-and-metrics.interceptor.ts new file mode 100644 index 0000000..0a8933e --- /dev/null +++ b/src/logging-and-metrics.interceptor.ts @@ -0,0 +1,155 @@ +// Copyright © 2022 Kaleido, Inc. +// +// SPDX-License-Identifier: Apache-2.0 +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +import { + CallHandler, + ExecutionContext, + HttpException, + Injectable, + Logger, + Module, + NestInterceptor, +} from '@nestjs/common'; +import { Request, Response } from 'express'; +import { Observable, throwError } from 'rxjs'; +import { catchError, tap } from 'rxjs/operators'; +import { FFRequestIDHeader } from './request-context/constants'; +import { Counter, Histogram } from 'prom-client'; +import { + InjectMetric, + makeCounterProvider, + makeHistogramProvider, +} from '@willsoto/nestjs-prometheus'; + +const NO_METRICS = ['/metrics']; + +export const MetricProviders = [ + makeCounterProvider({ + name: 'ff_apiserver_rest_requests_total', + help: 'Total REST API requests handled by the service', + labelNames: ['method', 'route', 'code'], + }), + makeHistogramProvider({ + name: 'ff_apiserver_rest_request_size_bytes', + help: 'Size of REST API requests in bytes', + labelNames: ['method', 'route', 'code'], + }), + makeHistogramProvider({ + name: 'ff_apiserver_rest_request_duration_seconds', + help: 'Duration of REST API requests', + labelNames: ['method', 'route', 'code'], + }), + makeHistogramProvider({ + name: 'ff_event_batch_size', + help: 'Size of event batches delivered from blockchain connector', + }), +]; + +@Module({}) +@Injectable() +export class LoggingAndMetricsInterceptor implements NestInterceptor { + private readonly logger = new Logger('MetricsAndLogging'); + + constructor( + @InjectMetric('ff_apiserver_rest_requests_total') + private totalRequests: Counter, + @InjectMetric('ff_apiserver_rest_request_size_bytes') + private requestSize: Histogram, + @InjectMetric('ff_apiserver_rest_request_duration_seconds') + private requestTime: Histogram, + @InjectMetric('ff_event_batch_size') + private eventBatchSize: Histogram, + ) {} + + private isMetricsEnabled(path: string) { + if (NO_METRICS.some(suffix => path === suffix)) { + return false; + } + return true; + } + + intercept(context: ExecutionContext, next: CallHandler): Observable { + const request: Request = context.switchToHttp().getRequest(); + this.logRequest(request); + let timerCB: any; + + if (this.isMetricsEnabled(request.path)) { + // Start the metrics timer for this REST call + timerCB = this.requestTime.startTimer(); + } + + return next.handle().pipe( + tap(() => { + const response: Response = context.switchToHttp().getResponse(); + + if (this.isMetricsEnabled(request.path)) { + // End the metrics timer for this REST call + timerCB({ + method: request.method, + route: request.route.path, + code: `${response.statusCode}`, + }); + } + this.logResponse(request, response.statusCode, response.statusMessage); + }), + catchError(error => { + if ('getStatus' in error) { + const httpError: HttpException = error; + const response: Response = context.switchToHttp().getResponse(); + const statusCode = httpError.getStatus() ?? response.statusCode; + const statusMessage = httpError.message; + + if (this.isMetricsEnabled(request.path)) { + // End the metrics timer for this REST call + timerCB({ + method: request.method, + route: request.route.path, + code: `${statusCode}`, + }); + } + this.logResponse(request, statusCode, statusMessage); + } + return throwError(() => error); + }), + ); + } + + private logRequest(request: Request) { + this.logger.log( + `${request.method} ${request.originalUrl} ${request.headers[FFRequestIDHeader]}`, + ); + } + + private logResponse(request: Request, statusCode: number, statusMessage: string) { + if (this.isMetricsEnabled(request.path)) { + this.updateMetrics(request, statusCode); + } + if (statusCode >= 400) { + this.logger.warn(`${request.method} ${request.originalUrl} - ${statusCode} ${statusMessage}`); + } + } + + private updateMetrics(request: Request, statusCode: number) { + this.totalRequests.labels(request.method, request.route.path, `${statusCode}`).inc(); + this.requestSize + .labels(request.method, request.route.path, `${statusCode}`) + .observe(request.header['content-length'] ? parseInt(request.header['content-length']) : 0); + } + + observeEventBatchSize(observedValue: number) { + this.eventBatchSize.observe(observedValue); + } +} diff --git a/src/main.ts b/src/main.ts index f5e9844..d37f52e 100644 --- a/src/main.ts +++ b/src/main.ts @@ -24,7 +24,6 @@ import { AppModule } from './app.module'; import { EventStreamReply } from './event-stream/event-stream.interfaces'; import { EventStreamService } from './event-stream/event-stream.service'; import { requestIDMiddleware } from './request-context/request-id.middleware'; -import { RequestLoggingInterceptor } from './request-logging.interceptor'; import { BlockchainConnectorService, RetryConfiguration } from './tokens/blockchain.service'; import { TokenApprovalEvent, @@ -55,7 +54,6 @@ async function bootstrap() { app.useWebSocketAdapter(new WsAdapter(app)); app.useGlobalPipes(new ValidationPipe({ whitelist: true })); app.enableShutdownHooks([ShutdownSignal.SIGTERM, ShutdownSignal.SIGQUIT, ShutdownSignal.SIGINT]); - app.useGlobalInterceptors(new RequestLoggingInterceptor()); app.use(requestIDMiddleware); const apiConfig = getApiConfig(); diff --git a/src/request-logging.interceptor.ts b/src/request-logging.interceptor.ts deleted file mode 100644 index fdbe0a5..0000000 --- a/src/request-logging.interceptor.ts +++ /dev/null @@ -1,66 +0,0 @@ -// Copyright © 2022 Kaleido, Inc. -// -// SPDX-License-Identifier: Apache-2.0 -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -import { - CallHandler, - ExecutionContext, - HttpException, - Injectable, - Logger, - NestInterceptor, -} from '@nestjs/common'; -import { Request, Response } from 'express'; -import { Observable, throwError } from 'rxjs'; -import { catchError, tap } from 'rxjs/operators'; -import { FFRequestIDHeader } from './request-context/constants'; - -@Injectable() -export class RequestLoggingInterceptor implements NestInterceptor { - private readonly logger = new Logger('RequestLogging'); - - intercept(context: ExecutionContext, next: CallHandler): Observable { - const request: Request = context.switchToHttp().getRequest(); - this.logRequest(request); - return next.handle().pipe( - tap(() => { - const response: Response = context.switchToHttp().getResponse(); - this.logResponse(request, response.statusCode, response.statusMessage); - }), - catchError(error => { - if ('getStatus' in error) { - const httpError: HttpException = error; - const response: Response = context.switchToHttp().getResponse(); - const statusCode = httpError.getStatus() ?? response.statusCode; - const statusMessage = httpError.message; - this.logResponse(request, statusCode, statusMessage); - } - return throwError(() => error); - }), - ); - } - - private logRequest(request: Request) { - this.logger.log( - `${request.method} ${request.originalUrl} ${request.headers[FFRequestIDHeader]}`, - ); - } - - private logResponse(request: Request, statusCode: number, statusMessage: string) { - if (statusCode >= 400) { - this.logger.warn(`${request.method} ${request.originalUrl} - ${statusCode} ${statusMessage}`); - } - } -} diff --git a/src/websocket-events/websocket-events.base.ts b/src/websocket-events/websocket-events.base.ts index b25efa7..253e14d 100644 --- a/src/websocket-events/websocket-events.base.ts +++ b/src/websocket-events/websocket-events.base.ts @@ -24,6 +24,7 @@ import { } from '@nestjs/websockets'; import { nanoid } from 'nanoid'; import WebSocket, { Server } from 'ws'; +import { LoggingAndMetricsInterceptor } from 'src/logging-and-metrics.interceptor'; const PING_INTERVAL = 5000; @@ -61,7 +62,11 @@ export abstract class WebSocketEventsBase { @WebSocketServer() server: Server; - constructor(protected readonly logger: Logger, private requireAuth = false) {} + constructor( + protected readonly logger: Logger, + private requireAuth = false, + protected metrics: LoggingAndMetricsInterceptor, + ) {} afterInit(server: Server) { const interval = setInterval(() => this.ping(), PING_INTERVAL); diff --git a/test/app.e2e-context.ts b/test/app.e2e-context.ts index cd59514..4434136 100644 --- a/test/app.e2e-context.ts +++ b/test/app.e2e-context.ts @@ -13,6 +13,7 @@ import { EventStreamProxyGateway } from '../src/eventstream-proxy/eventstream-pr import { TokensService } from '../src/tokens/tokens.service'; import { requestIDMiddleware } from '../src/request-context/request-id.middleware'; import { BlockchainConnectorService, RetryConfiguration } from '../src/tokens/blockchain.service'; +import { LoggingAndMetricsInterceptor } from '../src/logging-and-metrics.interceptor'; export const BASE_URL = 'http://eth'; export const INSTANCE_PATH = '/tokens'; @@ -44,6 +45,10 @@ export class TestContext { getSubscription: jest.fn(), }; + metrics = { + observeEventBatchSize: jest.fn(), + }; + async begin() { this.http = { get: jest.fn(), @@ -56,11 +61,19 @@ export class TestContext { const moduleFixture: TestingModule = await Test.createTestingModule({ imports: [AppModule], + providers: [ + { + provide: LoggingAndMetricsInterceptor, + useValue: jest.fn(), + }, + ], }) .overrideProvider(HttpService) .useValue(this.http) .overrideProvider(EventStreamService) .useValue(this.eventstream) + .overrideProvider(LoggingAndMetricsInterceptor) + .useValue(this.metrics) .compile(); this.app = moduleFixture.createNestApplication();