[O2B-1644] Add general logging middleware for improved statistics

docs/backend-architecture.md

@@ -35,3 +35,20 @@ Because the services might have inter-dependencies that can lead to cyclic depen
 ### Error management
 
 Currently, `usecases` returns `HTTP` oriented objects when an exception occurs, with `HTTP` error code and message. This is not viable anymore because those errors makes no sense in `gRPC`. To solve these issues, if an error occur in the service layer, an instance of a specific instance must be thrown and it must be converted to API-specific error in controllers or at an even higher level (for example `AuthenticatedOnly` error will be converted to error code `16` in `gRPC` and `401` in `HTTP`).
+
+### HTTP API access log
+
+Every request handled by the `HTTP` API (`/api`, not the static files) is logged by `accessLogMiddleware` once its response has been sent. The entry is a single-line `JSON`, logged by the `API` logger **to the local log only** (it is not forwarded to InfoLogger), so that it can be parsed and aggregated in OpenSearch:
+
+```json
+{"type":"api_request","method":"GET","route":"/api/runs","status":200,"durationMs":42,"userId":7,"bytes":18234,"query":{"filter":{"runNumbers":"1,2"},"page":{"limit":"50"}}}
+```
+
+- `route`: the route pattern (for example `/api/runs/:runNumber`) and not the raw url, so that requests can be grouped per endpoint. When no route matched, it is the requested path
+- `durationMs`: time between the reception of the request by the middleware and the end of the response
+- `userId`: the id of the user, `null` if the request is not authenticated
+- `bytes`: the `content-length` of the response, `null` if not provided
+- `query`: the parsed query string (filters, pagination, sorting...), omitted when empty. The `token` parameter is removed and the body is never logged
+- `aborted`: `true` only if the connection was closed before the response was completely sent
+
+Nothing is logged in test mode.

lib/server/WebUiServer.js

@@ -19,6 +19,7 @@ const { isInTestMode, isInDevMode } = require('../utilities/env-utils');
 const { createOrUpdateUser } = require('./services/user/createOrUpdateUser.js');
 const { LogManager } = require('@aliceo2/web-ui');
 const { BkpRoles } = require('../domain/enums/BkpRoles.js');
+const { accessLogMiddleware } = require('./middleware/accessLog.middleware.js');
 
 /**
  * WebUI implementation of the Server.
@@ -42,6 +43,12 @@ class WebUiServer {
             autoListen: false,
         }, JwtConfig, OpenIdConfig.isValid() ? OpenIdConfig : null);
 
+        /**
+         * Logs every API request once handled, not the statics
+         * (public router only: it is mounted first and registering both would log twice)
+         */
+        this.http.routerPublic.use(accessLogMiddleware());
+
         [this.http.router, this.http.routerPublic, this.http.routerStatics].forEach((router) => {
             router.use(async (request, response, next) => {
                 if (isInTestMode()) {

lib/server/middleware/accessLog.middleware.js

@@ -0,0 +1,77 @@
+/**
+ * @license
+ * Copyright CERN and copyright holders of ALICE O2. This software is
+ * distributed under the terms of the GNU General Public License v3 (GPL
+ * Version 3), copied verbatim in the file "COPYING".
+ *
+ * See http://alice-o2.web.cern.ch/license for full licensing information.
+ *
+ * In applying this license CERN does not waive the privileges and immunities
+ * granted to it by virtue of its status as an Intergovernmental Organization
+ * or submit itself to any jurisdiction.
+ */
+
+const { LogManager } = require('@aliceo2/web-ui');
+const { isInTestMode } = require('../../utilities/env-utils');
+
+const NANOSECONDS_PER_MILLISECOND = 1000000n;
+
+/**
+ * Express middleware logging one single-line JSON entry for each handled API request, once its response has been sent.
+ *
+ * The entry is sent to the local logger only (no log level is provided, so it is NOT forwarded to InfoLogger). It contains the method, the route
+ * pattern (not the raw url, to keep it aggregable), the status, the duration, the id of the user, the size of the response and the query
+ *
+ * @param {object} [configuration] the middleware configuration
+ * @param {{infoMessage: function(string): void}} [configuration.logger] the logger to use
+ * @param {boolean} [configuration.silent] if true, nothing is logged (defaults to true in test mode)
+ * @return {function(object, object, function): void} the access log middleware
+ */
+exports.accessLogMiddleware = ({ logger = LogManager.getLogger('API'), silent = isInTestMode() } = {}) => (request, response, next) => {
+    if (silent) {
+        next();
+        return;
+    }
+
+    const startTime = process.hrtime.bigint();
+    // The base url (i.e. the router mount path) must be read now, as express restores it when leaving the router
+    const { baseUrl } = request;
+    // Needed as to not duplicate logging in case of both close and finish events triggering the log function
+    let logged = false;
+
+    const log = () => {
+        if (logged) {
+            return;
+        }
+        logged = true;
+
+        const { method, query, session, route, originalUrl } = request;
+        const contentLength = Number(response.getHeader('content-length'));
+
+        const entry = {
+            type: 'api_request',
+            method,
+            route: route ? `${baseUrl}${route.path}` : originalUrl.split('?')[0],
+            status: response.statusCode,
+            durationMs: Number((process.hrtime.bigint() - startTime) / NANOSECONDS_PER_MILLISECOND),
+            userId: session?.id ?? null,
+            bytes: Number.isNaN(contentLength) ? null : contentLength,
+        };
+
+        if (!response.writableFinished) {
+            entry.aborted = true;
+        }
+        // The token is a credential and must never be logged
+        const loggableQuery = { ...query };
+        delete loggableQuery.token;
+        if (Object.keys(loggableQuery).length > 0) {
+            entry.query = loggableQuery;
+        }
+
+        logger.infoMessage(JSON.stringify(entry));
+    };
+
+    response.once('finish', log);
+    response.once('close', log);
+    next();
+};

lib/server/middleware/index.js

@@ -12,7 +12,9 @@
  */
 
 const multerMiddleware = require('./multer.middleware');
+const { accessLogMiddleware } = require('./accessLog.middleware.js');
 
 module.exports = {
     multerMiddleware,
+    accessLogMiddleware,
 };

lib/server/routers/dataPasses.router.js

@@ -14,13 +14,11 @@
 const { DataPassesController } = require('../controllers/dataPasses.controller.js');
 const { rbacMiddleware } = require('../middleware/rbac.middleware.js');
 const { BkpRoles } = require('../../domain/enums/BkpRoles.js');
-const FilterLogger = require('../Loggers/FilterLogger.js');
-const { infoLoggerListenerMiddleware } = require('../middleware/InfoLoggerListener.middleware.js');
 
 exports.dataPassesRouter = {
     path: '/dataPasses',
     method: 'get',
-    controller: [infoLoggerListenerMiddleware(FilterLogger), DataPassesController.listDataPassesHandler],
+    controller: DataPassesController.listDataPassesHandler,
 
     children: [
         {

lib/server/routers/environments.router.js

@@ -12,13 +12,11 @@
  */
 
 const { EnvironmentsController } = require('../controllers');
-const FilterLogger = require('../Loggers/FilterLogger');
-const { infoLoggerListenerMiddleware } = require('../middleware/InfoLoggerListener.middleware');
 
 module.exports = {
     method: 'get',
     path: '/environments',
-    controller: [infoLoggerListenerMiddleware(FilterLogger), EnvironmentsController.getAllEnvironments],
+    controller: EnvironmentsController.getAllEnvironments,
     children: [
         {
             method: 'post',

lib/server/routers/lhcFills.router.js

@@ -12,15 +12,13 @@
  */
 
 const { LhcFillsController } = require('../controllers');
-const FilterLogger = require('../Loggers/FilterLogger');
-const { infoLoggerListenerMiddleware } = require('../middleware/InfoLoggerListener.middleware');
 
 module.exports = {
     path: '/lhcFills',
     children: [
         {
             method: 'get',
-            controller: [infoLoggerListenerMiddleware(FilterLogger), LhcFillsController.listLhcFills],
+            controller: LhcFillsController.listLhcFills,
         },
         {
             method: 'post',

lib/server/routers/lhcPeriodsStatistics.router.js

@@ -12,15 +12,13 @@
  */
 
 const { LhcPeriodStatisticsController } = require('../controllers/lhcPeriodStatistics.controller.js');
-const FilterLogger = require('../Loggers/FilterLogger.js');
-const { infoLoggerListenerMiddleware } = require('../middleware/InfoLoggerListener.middleware.js');
 
 exports.lhcPeriodsRouter = {
     path: '/lhcPeriodsStatistics',
     children: [
         {
             method: 'get',
-            controller: [infoLoggerListenerMiddleware(FilterLogger), LhcPeriodStatisticsController.listLhcPeriodStatisticsHandler],
+            controller: LhcPeriodStatisticsController.listLhcPeriodStatisticsHandler,
         },
         {
             method: 'get',

lib/server/routers/logs.router.js

@@ -12,14 +12,12 @@
  */
 
 const { LogsController } = require('../controllers');
-const FilterLogger = require('../Loggers/FilterLogger');
 const { multerMiddleware: { attachmentMiddleware } } = require('../middleware');
-const { infoLoggerListenerMiddleware } = require('../middleware/InfoLoggerListener.middleware');
 
 module.exports = {
     method: 'get',
     path: '/logs',
-    controller: [infoLoggerListenerMiddleware(FilterLogger), LogsController.listLogs],
+    controller: LogsController.listLogs,
     children: [
         {
             method: 'get',

lib/server/routers/qcFlag.router.js

@@ -13,8 +13,6 @@
 
 const { BkpRoles } = require('../../domain/enums/BkpRoles.js');
 const { QcFlagController } = require('../controllers/qcFlag.controller.js');
-const FilterLogger = require('../Loggers/FilterLogger.js');
-const { infoLoggerListenerMiddleware } = require('../middleware/InfoLoggerListener.middleware.js');
 const { rbacMiddleware } = require('../middleware/rbac.middleware.js');
 
 exports.qcFlagsRouter = {
@@ -23,7 +21,7 @@ exports.qcFlagsRouter = {
         {
             path: 'gaq',
             method: 'get',
-            controller: [infoLoggerListenerMiddleware(FilterLogger), QcFlagController.getGaqQcFlagsHandler],
+            controller: QcFlagController.getGaqQcFlagsHandler,
         },
         {
             path: 'summary',

lib/server/routers/runs.router.js

@@ -12,8 +12,6 @@
  */
 
 const { RunsController } = require('../controllers');
-const FilterLogger = require('../Loggers/FilterLogger');
-const { infoLoggerListenerMiddleware } = require('../middleware/InfoLoggerListener.middleware');
 
 module.exports = {
     children: [
@@ -37,7 +35,7 @@ module.exports = {
                 },
                 {
                     method: 'get',
-                    controller: [infoLoggerListenerMiddleware(FilterLogger), RunsController.listRuns],
+                    controller: RunsController.listRuns,
                 },
                 {
                     method: 'get',

lib/server/routers/simulationPasses.router.js

@@ -12,8 +12,6 @@
  */
 
 const { SimulationPassesController } = require('../controllers/simulationPasses.controller.js');
-const FilterLogger = require('../Loggers/FilterLogger.js');
-const { infoLoggerListenerMiddleware } = require('../middleware/InfoLoggerListener.middleware.js');
 
 exports.simulationPassesRouter = {
     path: '/simulationPasses',
@@ -25,7 +23,7 @@ exports.simulationPassesRouter = {
         },
         {
             method: 'get',
-            controller: [infoLoggerListenerMiddleware(FilterLogger), SimulationPassesController.listSimulationPassesHandler],
+            controller: SimulationPassesController.listSimulationPassesHandler,
         },
     ],
 };