diff --git a/.github/workflows/tests.yaml b/.github/workflows/tests.yaml index 4dc5bc1c..73a8beb7 100644 --- a/.github/workflows/tests.yaml +++ b/.github/workflows/tests.yaml @@ -112,7 +112,8 @@ jobs: test: - name: run unit tests command: yarn test - env: {} + env: + UTAPI_METRICS_ENABLED: 'true' - name: run client tests command: bash ./.github/scripts/run_ft_tests.bash false ft_test:client env: {} diff --git a/libV2/models/RequestContext.js b/libV2/models/RequestContext.js index 283383a4..be89df75 100644 --- a/libV2/models/RequestContext.js +++ b/libV2/models/RequestContext.js @@ -3,6 +3,7 @@ const Joi = require('@hapi/joi'); const { buildModel } = require('./Base'); const { apiOperations } = require('../server/spec'); const ResponseContainer = require('./ResponseContainer'); +const { httpRequestDurationSeconds } = require('../server/metrics'); const apiTags = Object.keys(apiOperations); const apiOperationIds = Object.values(apiOperations) @@ -21,6 +22,7 @@ const contextSchema = { logger: Joi.any(), request: Joi.any(), results: Joi.any(), + requestTimer: Joi.any(), }; const RequestContextModel = buildModel('RequestContext', contextSchema); @@ -34,6 +36,10 @@ class RequestContext extends RequestContextModel { const tag = request.swagger.operation['x-router-controller']; const { operationId } = request.swagger.operation; + const requestTimer = tag !== 'internal' + ? httpRequestDurationSeconds.startTimer({ action: operationId }) + : null; + request.logger.logger.addDefaultFields({ tag, operationId, @@ -50,6 +56,7 @@ class RequestContext extends RequestContextModel { encrypted, results: new ResponseContainer(), logger: request.logger, + requestTimer, }); } diff --git a/libV2/server/index.js b/libV2/server/index.js index f8e90789..440198ca 100644 --- a/libV2/server/index.js +++ b/libV2/server/index.js @@ -28,6 +28,7 @@ class UtapiServer extends Process { app.use(middleware.loggerMiddleware); await initializeOasTools(spec, app); app.use(middleware.errorMiddleware); + app.use(middleware.httpMetricsMiddleware); app.use(middleware.responseLoggerMiddleware); return app; } diff --git a/libV2/server/metrics.js b/libV2/server/metrics.js new file mode 100644 index 00000000..6ddba276 --- /dev/null +++ b/libV2/server/metrics.js @@ -0,0 +1,20 @@ +const promClient = require('prom-client'); + +const httpRequestsTotal = new promClient.Counter({ + name: 'utapi_http_requests_total', + help: 'Total number of HTTP requests', + labelNames: ['action', 'code'], +}); + +const httpRequestDurationSeconds = new promClient.Histogram({ + name: 'utapi_http_request_duration_seconds', + help: 'Duration of HTTP requests in seconds', + labelNames: ['action', 'code'], + // buckets for response time from 0.1ms to 60s + buckets: [0.0001, 0.005, 0.015, 0.05, 0.1, 0.2, 0.3, 0.4, 0.5, 1.0, 5.0, 15.0, 30.0, 60.0], +}); + +module.exports = { + httpRequestDurationSeconds, + httpRequestsTotal, +}; diff --git a/libV2/server/middleware.js b/libV2/server/middleware.js index 1a5a4bc5..d20e3734 100644 --- a/libV2/server/middleware.js +++ b/libV2/server/middleware.js @@ -6,6 +6,7 @@ const config = require('../config'); const { logger, buildRequestLogger } = require('../utils'); const errors = require('../errors'); const { translateAndAuthorize } = require('../vault'); +const metricHandlers = require('./metrics'); const oasOptions = { controllers: path.join(__dirname, './API/'), @@ -55,6 +56,23 @@ function responseLoggerMiddleware(req, res, next) { } } +function httpMetricsMiddleware(request, response, next) { + // If the request.ctx is undefined then this is an internal oasTools request (/_/docs) + // No metrics should be pushed + if (config.metrics.enabled && request.ctx && request.ctx.tag !== 'internal') { + metricHandlers.httpRequestsTotal + .labels({ + action: request.ctx.operationId, + code: response.statusCode, + }).inc(1); + request.ctx.requestTimer({ code: response.statusCode }); + } + + if (next) { + next(); + } +} + // next is purposely not called as all error responses are handled here // eslint-disable-next-line no-unused-vars function errorMiddleware(err, req, res, next) { @@ -82,7 +100,7 @@ function errorMiddleware(err, req, res, next) { code, message, }); - responseLoggerMiddleware(req, res); + responseLoggerMiddleware(req, res, () => httpMetricsMiddleware(req, res)); } // eslint-disable-next-line no-unused-vars @@ -158,5 +176,6 @@ module.exports = { responseLoggerMiddleware, authV4Middleware, clientIpLimitMiddleware, + httpMetricsMiddleware, }, }; diff --git a/tests/unit/v2/models/testRequestContext.js b/tests/unit/v2/models/testRequestContext.js index b381d6e0..6e048ce4 100644 --- a/tests/unit/v2/models/testRequestContext.js +++ b/tests/unit/v2/models/testRequestContext.js @@ -10,6 +10,7 @@ const templateExpected = opts => ({ operationId: 'healthcheck', tag: 'internal', encrypted: false, + requestTimer: null, ...(opts || {}), }); diff --git a/tests/unit/v2/server/testMiddleware.js b/tests/unit/v2/server/testMiddleware.js index 2c6bf6d0..a6d6d52b 100644 --- a/tests/unit/v2/server/testMiddleware.js +++ b/tests/unit/v2/server/testMiddleware.js @@ -1,8 +1,11 @@ const assert = require('assert'); const sinon = require('sinon'); +const promClient = require('prom-client'); const { middleware } = require('../../../../libV2/server/middleware'); const { templateRequest, ExpressResponseStub } = require('../../../utils/v2Data'); +const RequestContext = require('../../../../libV2/models/RequestContext'); +const { getMetricValues, assertMetricValue } = require('../../../utils/prom'); describe('Test middleware', () => { it('should build a request logger', next => { @@ -86,4 +89,55 @@ describe('Test middleware', () => { })); }); }); + + describe('test httpMetricsMiddleware', () => { + let resp; + + beforeEach(() => { + resp = new ExpressResponseStub(); + resp.status(200); + }); + + afterEach(() => { + promClient.register.clear(); + }); + + it('should increment the counter if not an internal route', async () => { + const req = templateRequest({ + swagger: { + operation: { + 'x-router-controller': 'metrics', + 'operationId': 'listMetrics', + }, + }, + }); + + req.ctx = new RequestContext(req); + middleware.httpMetricsMiddleware(req, resp); + await assertMetricValue('utapi_http_requests_total', 1); + const duration = await getMetricValues('utapi_http_request_duration_seconds'); + // 14 defined buckets + 1 for Infinity + assert.strictEqual( + duration.filter(metric => metric.metricName === 'utapi_http_request_duration_seconds_bucket').length, + 15, + ); + const count = duration.filter(metric => metric.metricName === 'utapi_http_request_duration_seconds_count'); + assert.deepStrictEqual(count, [{ + labels: { + action: 'listMetrics', + code: 200, + }, + metricName: 'utapi_http_request_duration_seconds_count', + value: 1, + }]); + assert.strictEqual(count[0].value, 1); + }); + + it('should not increment the counter if an internal route', async () => { + const req = templateRequest(); + req.ctx = new RequestContext(req); + middleware.httpMetricsMiddleware(req, resp); + assert.rejects(() => getMetricValues('utapi_http_requests_total')); + }); + }); });