fix: path metric labels (#6400) (#6518)

## About the changes
Some of our metrics are not labeled correctly, one example is
`<base-path>/api/frontend/client/metrics` is labeled as
`/client/metrics`. We can see that in internal-backstage/prometheus:


![image](https://github.com/Unleash/unleash/assets/455064/0d8f1f40-8b5b-49d4-8a88-70b523e9be09)

This issue affects all endpoints that fail to validate the request body.
Also, endpoints that are rejected by the authorization-middleware or the
api-token-middleware are reported as `(hidden)`.

To gain more insights on our api usage but being protective of metrics
cardinality we're prefixing `(hidden)` with some well known base urls:
https://github.com/Unleash/unleash/pull/6400/files#diff-1ed998ca46ffc97c9c0d5d400bfd982dbffdb3004b78a230a8a38e7644eee9b6R17-R33

## How to reproduce:
Make an invalid call to metrics (e.g. stop set to null), then check
/internal-backstage/prometheus and find the 400 error. Expected to be at
`path="/api/client/metrics"` but will have `path=""`:
```shell
curl -H"Authorization: *:development.unleash-insecure-client-api-token" -H'Content-type: application/json' localhost:4242/api/client/metrics -d '{
  "appName": "bash-test",
  "instanceId": "application-name-dacb1234",
  "environment": "development",
  "bucket": {
    "start": "2023-07-27T11:23:44Z",
    "stop": null,
    "toggles": {
      "myCoolToggle": {
        "yes": 25,
        "no": 42,
        "variants": {
          "blue": 6,
          "green": 15,
          "red": 46
        }
      },
      "myOtherToggle": {
        "yes": 0,
        "no": 100
      }
    }
  }
}'
```

<!-- Thanks for creating a PR! To make it easier for reviewers and
everyone else to understand what your changes relate to, please add some
relevant content to the headings below. Feel free to ignore or delete
sections that you don't think are relevant. Thank you! ❤️ -->

## About the changes
<!-- Describe the changes introduced. What are they and why are they
being introduced? Feel free to also add screenshots or steps to view the
changes if they're visual. -->

<!-- Does it close an issue? Multiple? -->
Closes #

<!-- (For internal contributors): Does it relate to an issue on public
roadmap? -->
<!--
Relates to [roadmap](https://github.com/orgs/Unleash/projects/10) item:
#
-->

### Important files
<!-- PRs can contain a lot of changes, but not all changes are equally
important. Where should a reviewer start looking to get an overview of
the changes? Are any files particularly important? -->


## Discussion points
<!-- Anything about the PR you'd like to discuss before it gets merged?
Got any questions or doubts? -->

src/lib/__snapshots__/create-config.test.ts.snap

@@ -132,6 +132,7 @@ exports[`should create default config 1`] = `
       "personalAccessTokensKillSwitch": false,
       "proPlanAutoCharge": false,
       "queryMissingTokens": false,
+      "responseTimeMetricsFix": false,
       "responseTimeWithAppNameKillSwitch": false,
       "scimApi": false,
       "sdkReporting": false,

src/lib/middleware/response-time-metrics.test.ts

@@ -0,0 +1,402 @@
+import { EventEmitter } from 'stream';
+import {
+    responseTimeMetrics,
+    storeRequestedRoute,
+} from './response-time-metrics';
+import { REQUEST_TIME } from '../metric-events';
+
+const fixedResponseTime = 100;
+// mock response-time library
+jest.mock('response-time', () => {
+    return (responseTimeMetricsFn) => {
+        return (req, res) => {
+            return responseTimeMetricsFn(req, res, fixedResponseTime);
+        };
+    };
+});
+
+const isDefined = async (timeInfo: any, limit = 10) => {
+    let counter = 0;
+    while (timeInfo === undefined) {
+        // Waiting for event to be triggered
+        await new Promise((resolve) => setTimeout(resolve, 10));
+        counter++;
+        if (counter > limit) {
+            throw new Error('Event was not triggered');
+        }
+    }
+};
+
+const flagResolver = {
+    isEnabled: jest.fn(),
+    getAll: jest.fn(),
+    getVariant: jest.fn(),
+};
+
+const flagResolverWithResponseTimeMetricsFix = {
+    ...flagResolver,
+    isEnabled: (name: string) => name === 'responseTimeMetricsFix',
+};
+
+// Make sure it's always cleaned up
+let res: any;
+beforeEach(() => {
+    res = {
+        statusCode: 200,
+        locals: {}, // res will always have locals (according to express RequestHandler type)
+    };
+});
+
+describe('responseTimeMetrics old behavior', () => {
+    const instanceStatsService = {
+        getAppCountSnapshot: jest.fn(),
+    };
+    const eventBus = new EventEmitter();
+
+    test('uses baseUrl and route path to report metrics', async () => {
+        let timeInfo: any;
+        // register a listener
+        eventBus.on(REQUEST_TIME, (data) => {
+            timeInfo = data;
+        });
+        const middleware = responseTimeMetrics(
+            eventBus,
+            flagResolver,
+            instanceStatsService,
+        );
+        const req = {
+            baseUrl: '/api/admin',
+            route: {
+                path: '/features',
+            },
+            method: 'GET',
+            path: 'should-not-be-used',
+        };
+
+        // @ts-expect-error req and res doesn't have all properties
+        middleware(req, res);
+
+        await isDefined(timeInfo);
+        expect(timeInfo).toMatchObject({
+            path: '/api/admin/features',
+            method: 'GET',
+            statusCode: 200,
+            time: 100,
+            appName: undefined,
+        });
+    });
+
+    test('uses baseUrl and route path to report metrics even with the new flag enabled', async () => {
+        let timeInfo: any;
+        // register a listener
+        eventBus.on(REQUEST_TIME, (data) => {
+            timeInfo = data;
+        });
+        const middleware = responseTimeMetrics(
+            eventBus,
+            flagResolverWithResponseTimeMetricsFix,
+            instanceStatsService,
+        );
+        const req = {
+            baseUrl: '/api/admin',
+            route: {
+                path: '/features',
+            },
+            method: 'GET',
+            path: 'should-not-be-used',
+        };
+
+        // @ts-expect-error req and res doesn't have all properties
+        middleware(req, res);
+
+        await isDefined(timeInfo);
+        expect(timeInfo).toMatchObject({
+            path: '/api/admin/features',
+        });
+    });
+
+    test('uses baseUrl and route path to report metrics even with res.locals.route but flag disabled', async () => {
+        let timeInfo: any;
+        // register a listener
+        eventBus.on(REQUEST_TIME, (data) => {
+            timeInfo = data;
+        });
+        const middleware = responseTimeMetrics(
+            eventBus,
+            flagResolver,
+            instanceStatsService,
+        );
+        const req = {
+            baseUrl: '/api/admin',
+            route: {
+                path: '/features',
+            },
+            method: 'GET',
+            path: 'should-not-be-used',
+        };
+
+        // @ts-expect-error req and res doesn't have all properties
+        middleware(req, {
+            statusCode: 200,
+            locals: { route: '/should-not-be-used-eiter' },
+        });
+
+        await isDefined(timeInfo);
+        expect(timeInfo).toMatchObject({
+            path: '/api/admin/features',
+        });
+    });
+
+    test('reports (hidden) when route is not present', async () => {
+        let timeInfo: any;
+        // register a listener
+        eventBus.on(REQUEST_TIME, (data) => {
+            timeInfo = data;
+        });
+        const middleware = responseTimeMetrics(
+            eventBus,
+            flagResolver,
+            instanceStatsService,
+        );
+        const req = {
+            baseUrl: '/api/admin',
+            method: 'GET',
+            path: 'should-not-be-used',
+        };
+
+        // @ts-expect-error req and res doesn't have all properties
+        middleware(req, res);
+
+        await isDefined(timeInfo);
+        expect(timeInfo).toMatchObject({
+            path: '(hidden)',
+        });
+    });
+
+    test.each([
+        ['/api/admin/features', '(hidden)'],
+        ['/api/admin/features/my-feature', '(hidden)'],
+        ['/api/frontend/client/metrics', '(hidden)'],
+        ['/api/client/metrics', '(hidden)'],
+        ['/edge/validate', '(hidden)'],
+        ['/whatever', '(hidden)'],
+        ['/healthz', '(hidden)'],
+        ['/internal-backstage/prometheus', '(hidden)'],
+    ])(
+        'when path is %s and route is undefined, reports %s',
+        async (path: string, expected: string) => {
+            let timeInfo: any;
+            // register a listener
+            eventBus.on(REQUEST_TIME, (data) => {
+                timeInfo = data;
+            });
+            const middleware = responseTimeMetrics(
+                eventBus,
+                flagResolver,
+                instanceStatsService,
+            );
+            const req = {
+                baseUrl: '/api/admin',
+                method: 'GET',
+                path: 'should-not-be-used',
+            };
+            const reqWithoutRoute = {
+                method: 'GET',
+                path,
+            };
+
+            // @ts-expect-error req and res doesn't have all properties
+            storeRequestedRoute(req, res, () => {});
+            // @ts-expect-error req and res doesn't have all properties
+            middleware(reqWithoutRoute, res);
+
+            await isDefined(timeInfo);
+            expect(timeInfo).toMatchObject({
+                path: expected,
+            });
+        },
+    );
+});
+
+describe('responseTimeMetrics new behavior', () => {
+    const instanceStatsService = {
+        getAppCountSnapshot: jest.fn(),
+    };
+    const eventBus = new EventEmitter();
+
+    test('uses baseUrl and route path to report metrics with flag enabled, but no res.locals.route', async () => {
+        let timeInfo: any;
+        // register a listener
+        eventBus.on(REQUEST_TIME, (data) => {
+            timeInfo = data;
+        });
+        const middleware = responseTimeMetrics(
+            eventBus,
+            flagResolverWithResponseTimeMetricsFix,
+            instanceStatsService,
+        );
+        const req = {
+            baseUrl: '/api/admin',
+            route: {
+                path: '/features',
+            },
+            method: 'GET',
+            path: 'should-not-be-used',
+        };
+
+        // @ts-expect-error req and res doesn't have all properties
+        middleware(req, res);
+
+        await isDefined(timeInfo);
+        expect(timeInfo).toMatchObject({
+            path: '/api/admin/features',
+        });
+    });
+
+    test('uses res.locals.route to report metrics when flag enabled', async () => {
+        let timeInfo: any;
+        // register a listener
+        eventBus.on(REQUEST_TIME, (data) => {
+            timeInfo = data;
+        });
+        const middleware = responseTimeMetrics(
+            eventBus,
+            flagResolverWithResponseTimeMetricsFix,
+            instanceStatsService,
+        );
+        const req = {
+            baseUrl: '/api/admin',
+            route: {
+                path: '/features',
+            },
+            method: 'GET',
+            path: 'should-not-be-used',
+        };
+        const reqWithoutRoute = {
+            method: 'GET',
+        };
+
+        // @ts-expect-error req and res doesn't have all properties
+        storeRequestedRoute(req, res, () => {});
+        // @ts-expect-error req and res doesn't have all properties
+        middleware(reqWithoutRoute, res);
+
+        await isDefined(timeInfo);
+        expect(timeInfo).toMatchObject({
+            path: '/api/admin/features',
+        });
+    });
+
+    test('uses res.locals.route to report metrics when flag enabled', async () => {
+        let timeInfo: any;
+        // register a listener
+        eventBus.on(REQUEST_TIME, (data) => {
+            timeInfo = data;
+        });
+        const middleware = responseTimeMetrics(
+            eventBus,
+            flagResolverWithResponseTimeMetricsFix,
+            instanceStatsService,
+        );
+        const req = {
+            baseUrl: '/api/admin',
+            route: {
+                path: '/features',
+            },
+            method: 'GET',
+            path: 'should-not-be-used',
+        };
+        const reqWithoutRoute = {
+            method: 'GET',
+        };
+
+        // @ts-expect-error req and res doesn't have all properties
+        storeRequestedRoute(req, res, () => {});
+        // @ts-expect-error req and res doesn't have all properties
+        middleware(reqWithoutRoute, res);
+
+        await isDefined(timeInfo);
+        expect(timeInfo).toMatchObject({
+            path: '/api/admin/features',
+        });
+    });
+
+    test.each([undefined, '/'])(
+        'reports (hidden) when route is undefined and path is %s',
+        async (path: string) => {
+            let timeInfo: any;
+            // register a listener
+            eventBus.on(REQUEST_TIME, (data) => {
+                timeInfo = data;
+            });
+            const middleware = responseTimeMetrics(
+                eventBus,
+                flagResolverWithResponseTimeMetricsFix,
+                instanceStatsService,
+            );
+            const req = {
+                baseUrl: '/api/admin',
+                method: 'GET',
+                path: 'should-not-be-used',
+            };
+            const reqWithoutRoute = {
+                method: 'GET',
+                path,
+            };
+
+            // @ts-expect-error req and res doesn't have all properties
+            storeRequestedRoute(req, res, () => {});
+            // @ts-expect-error req and res doesn't have all properties
+            middleware(reqWithoutRoute, res);
+
+            await isDefined(timeInfo);
+            expect(timeInfo).toMatchObject({
+                path: '(hidden)',
+            });
+        },
+    );
+
+    test.each([
+        ['/api/admin/features', '/api/admin/(hidden)'],
+        ['/api/admin/features/my-feature', '/api/admin/(hidden)'],
+        ['/api/frontend/client/metrics', '/api/frontend/(hidden)'],
+        ['/api/client/metrics', '/api/client/(hidden)'],
+        ['/edge/validate', '/edge/(hidden)'],
+        ['/whatever', '(hidden)'],
+        ['/healthz', '(hidden)'],
+        ['/internal-backstage/prometheus', '(hidden)'],
+    ])(
+        'when path is %s and route is undefined, reports %s',
+        async (path: string, expected: string) => {
+            let timeInfo: any;
+            // register a listener
+            eventBus.on(REQUEST_TIME, (data) => {
+                timeInfo = data;
+            });
+            const middleware = responseTimeMetrics(
+                eventBus,
+                flagResolverWithResponseTimeMetricsFix,
+                instanceStatsService,
+            );
+            const req = {
+                baseUrl: '/api/admin',
+                method: 'GET',
+                path: 'should-not-be-used',
+            };
+            const reqWithoutRoute = {
+                method: 'GET',
+                path,
+            };
+
+            // @ts-expect-error req and res doesn't have all properties
+            storeRequestedRoute(req, res, () => {});
+            // @ts-expect-error req and res doesn't have all properties
+            middleware(reqWithoutRoute, res);
+
+            await isDefined(timeInfo);
+            expect(timeInfo).toMatchObject({
+                path: expected,
+            });
+        },
+    );
+});

src/lib/middleware/response-time-metrics.ts

@@ -3,21 +3,62 @@ import EventEmitter from 'events';
 import { REQUEST_TIME } from '../metric-events';
 import { IFlagResolver } from '../types/experimental';
 import { InstanceStatsService } from '../services';
+import { RequestHandler } from 'express';
 
-// eslint-disable-next-line @typescript-eslint/naming-convention
 const _responseTime = responseTime.default;
-
 const appNameReportingThreshold = 1000;
 
+export const storeRequestedRoute: RequestHandler = (req, res, next) => {
+    if (req.route) {
+        res.locals = {
+            ...res.locals,
+            route: `${req.baseUrl}${req.route.path}`,
+        };
+    }
+    next();
+};
+
+function collapse(path: string): string {
+    let prefix = '';
+    if (path) {
+        if (path.startsWith('/api/admin')) {
+            prefix = '/api/admin/';
+        } else if (path.startsWith('/api/client')) {
+            prefix = '/api/client/';
+        } else if (path.startsWith('/api/frontend')) {
+            prefix = '/api/frontend/';
+        } else if (path.startsWith('/api')) {
+            prefix = '/api/';
+        } else if (path.startsWith('/edge')) {
+            prefix = '/edge/';
+        } else if (path.startsWith('/auth')) {
+            prefix = '/auth/';
+        }
+    }
+
+    return `${prefix}(hidden)`;
+}
+
 export function responseTimeMetrics(
     eventBus: EventEmitter,
     flagResolver: IFlagResolver,
     instanceStatsService: Pick<InstanceStatsService, 'getAppCountSnapshot'>,
-): any {
+): RequestHandler {
     return _responseTime((req, res, time) => {
         const { statusCode } = res;
-        const pathname = req.route ? req.baseUrl + req.route.path : '(hidden)';
-
+        const responseTimeMetricsFix = flagResolver.isEnabled(
+            'responseTimeMetricsFix',
+        );
+        let pathname: string | undefined = undefined;
+        if (responseTimeMetricsFix && res.locals.route) {
+            pathname = res.locals.route;
+        } else if (req.route) {
+            pathname = req.baseUrl + req.route.path;
+        }
+        // when pathname is undefined use a fallback
+        pathname =
+            pathname ??
+            (responseTimeMetricsFix ? collapse(req.path) : '(hidden)');
         let appName: string | undefined;
         if (
             !flagResolver.isEnabled('responseTimeWithAppNameKillSwitch') &&
@@ -34,6 +75,7 @@ export function responseTimeMetrics(
             time,
             appName,
         };
+
         eventBus.emit(REQUEST_TIME, timingInfo);
     });
 }

src/lib/routes/admin-api/index.ts

@@ -37,7 +37,7 @@ import FeatureSearchController from '../../features/feature-search/feature-searc
 import { InactiveUsersController } from '../../users/inactive/inactive-users-controller';
 import { UiObservabilityController } from '../../features/ui-observability-controller/ui-observability-controller';
 
-class AdminApi extends Controller {
+export class AdminApi extends Controller {
     constructor(config: IUnleashConfig, services: IUnleashServices, db: Db) {
         super(config);
 
@@ -171,5 +171,3 @@ class AdminApi extends Controller {
         );
     }
 }
-
-module.exports = AdminApi;

src/lib/routes/controller.ts

@@ -4,6 +4,7 @@ import { IUnleashConfig, NONE } from '../types';
 import { handleErrors } from './util';
 import requireContentType from '../middleware/content_type_checker';
 import { PermissionError } from '../error';
+import { storeRequestedRoute } from '../middleware/response-time-metrics';
 
 interface IRequestHandler<
     P = any,
@@ -108,6 +109,7 @@ export default class Controller {
     route(options: IRouteOptions): void {
         this.app[options.method](
             options.path,
+            storeRequestedRoute,
             checkPermission(options.permission),
             checkPrivateProjectPermissions(),
             this.useContentTypeMiddleware(options),
@@ -195,6 +197,7 @@ export default class Controller {
     ): void {
         this.app.post(
             path,
+            storeRequestedRoute,
             checkPermission(permission),
             checkPrivateProjectPermissions(),
             filehandler.bind(this),
@@ -206,12 +209,11 @@ export default class Controller {
         this.app.use(path, router);
     }
 
-    // eslint-disable-next-line @typescript-eslint/explicit-module-boundary-types
     useWithMiddleware(path: string, router: IRouter, middleware: any): void {
         this.app.use(path, middleware, router);
     }
 
-    get router(): any {
+    get router(): IRouter {
         return this.app;
     }
 }

src/lib/routes/index.ts

@@ -4,10 +4,10 @@ import { SimplePasswordProvider } from './auth/simple-password-provider';
 import { IUnleashConfig, IUnleashServices } from '../types';
 import LogoutController from './logout';
 import rateLimit from 'express-rate-limit';
+import Controller from './controller';
+import { AdminApi } from './admin-api';
+import ClientApi from './client-api';
 
-const AdminApi = require('./admin-api');
-const ClientApi = require('./client-api');
-const Controller = require('./controller');
 import { HealthCheckController } from './health-check';
 import FrontendAPIController from './proxy-api';
 import EdgeController from './edge-api';

src/lib/types/experimental.ts

@@ -51,6 +51,7 @@ export type IFlagKey =
     | 'disableUpdateMaxRevisionId'
     | 'disablePublishUnannouncedEvents'
     | 'sdkReporting'
+    | 'responseTimeMetricsFix'
     | 'scimApi'
     | 'displayEdgeBanner';
 
@@ -257,6 +258,10 @@ const flags: IFlags = {
         process.env.UNLEASH_EXPERIMENTAL_DISPLAY_EDGE_BANNER,
         false,
     ),
+    responseTimeMetricsFix: parseEnvVarBoolean(
+        process.env.UNLEASH_EXPERIMENTAL_RESPONSE_TIME_METRICS_FIX,
+        false,
+    ),
 };
 
 export const defaultExperimentalOptions: IExperimentalOptions = {

src/test/e2e/api/client/metrics.e2e.test.ts

@@ -1,14 +1,24 @@
-import { IUnleashTest, setupApp } from '../../helpers/test-helper';
+import {
+    IUnleashTest,
+    setupAppWithCustomConfig,
+} from '../../helpers/test-helper';
 import metricsExample from '../../../examples/client-metrics.json';
 import dbInit, { ITestDb } from '../../helpers/database-init';
 import getLogger from '../../../fixtures/no-logger';
+import { REQUEST_TIME } from '../../../../lib/metric-events';
 
 let app: IUnleashTest;
 let db: ITestDb;
 
 beforeAll(async () => {
     db = await dbInit('metrics_api_client', getLogger);
-    app = await setupApp(db.stores);
+    app = await setupAppWithCustomConfig(db.stores, {
+        experimental: {
+            flags: {
+                responseTimeMetricsFix: true,
+            },
+        },
+    });
 });
 
 afterEach(async () => {
@@ -64,3 +74,31 @@ test('should create instance if does not exist', async () => {
     const finalInstances = await db.stores.clientInstanceStore.getAll();
     expect(finalInstances.length).toBe(1);
 });
+
+test('should emit response time metrics data in the correct path', async () => {
+    const badMetrics = {
+        ...metricsExample,
+        bucket: { ...metricsExample.bucket, stop: null },
+    };
+
+    let timeInfo = undefined;
+    app.config.eventBus.on(REQUEST_TIME, (data) => {
+        timeInfo = data;
+    });
+
+    await app.request.post('/api/client/metrics').send(badMetrics).expect(400);
+
+    // wait in a loop of 10 milliseconds step while triggered is false
+    // or until 1000 milliseconds have passed
+    while (timeInfo === undefined) {
+        console.log('Waiting for event to be triggered');
+        await new Promise((resolve) => setTimeout(resolve, 10));
+    }
+
+    expect(timeInfo).toMatchObject({
+        method: 'POST',
+        statusCode: 400,
+        path: '/api/client/metrics',
+    });
+    app.config.eventBus.removeAllListeners();
+});

src/test/e2e/helpers/test-helper.ts

@@ -1,6 +1,5 @@
 import supertest from 'supertest';
 
-import EventEmitter from 'events';
 import getApp from '../../../lib/app';
 import { createTestConfig } from '../../config/test-config';
 import { IAuthType, IUnleashConfig } from '../../../lib/types/option';
@@ -321,8 +320,6 @@ async function createApp(
     });
     const services = createServices(stores, config, db);
     const unleashSession = sessionDb(config, undefined);
-    const emitter = new EventEmitter();
-    emitter.setMaxListeners(0);
     const app = await getApp(config, stores, services, unleashSession, db);
     const request = supertest.agent(app);