[O2B-1644] Reuse the API logger in gRPC as well to log all requests via its endpoints

docs/backend-architecture.md

@@ -36,19 +36,24 @@ Because the services might have inter-dependencies that can lead to cyclic depen
 
 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
+### 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:
+Every request handled by the `HTTP` API (`/api`, not the static files) and every `gRPC` call is logged once handled, by `ApiRequestLogger` (`HTTP`: `accessLogMiddleware`, `gRPC`: `bindGRPCController`). The entry is a single-line `JSON`, logged by the `API` logger **to the local log only** (it is not forwarded to InfoLogger). `HTTP` and `gRPC` entries share the same structure, so that they can be stored and aggregated together 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"}}}
+{"type":"api_request","protocol":"http","method":"GET","route":"/api/runs","status":200,"durationMs":42,"userId":7,"bytes":18234,"params":"{\"filter\":{\"runNumbers\":\"1,2\"},\"page\":{\"limit\":\"50\"}}"}
+{"type":"api_request","protocol":"grpc","method":null,"route":"/o2.bookkeeping.RunService/Get","status":0,"durationMs":12,"userId":null,"bytes":null,"params":"{\"runNumber\":12}"}
 ```
 
-- `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
+- `type`: always `api_request`
+- `protocol`: `http` or `grpc`
+- `method`: the `HTTP` method, `null` for `gRPC`
+- `route`: for `HTTP` 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). For `gRPC` the method path
+- `status`: the `HTTP` status or the `gRPC` status code (`0` for success), which are not comparable: filter on `protocol` first
+- `durationMs`: time between the reception of the request by the middleware (`HTTP`) or the call (`gRPC`) and the end of the response, so it includes the authentication
+- `userId`: the id of the user, `null` if not authenticated
+- `bytes`: the `content-length` of the `HTTP` response, `null` if not provided and for `gRPC`
+- `params`: the `HTTP` query string (the `token` parameter is removed and the body is never logged) or the `gRPC` request message, as a `JSON` **string** (not an object, because the structure varies from one endpoint to another and the types are not the same between protocols, which would lead to conflicts in OpenSearch mappings). It is omitted when empty and truncated (with a trailing `…`) when it exceeds 1000 characters
+- `aborted`: `true` only if the connection was closed before the response was completely sent (`HTTP` only)
 
 Nothing is logged in test mode.

docs/grpc.md

@@ -46,6 +46,11 @@ The system will then automate the extraction of the request object, convert enum
 handling), pass it to the implementation function and return the result to the gRPC client (converting enums the other
 way around). The implementation may or may not be asynchronous by returning a Promise.
 
+## Calls logging
+
+Each call is logged once handled (with its status, duration, user and request), using the same structure as the `HTTP` requests. See
+[the API access log](backend-architecture.md#api-access-log).
+
 ## Enums handling
 
 Because gRPC enums must have unique values across all the proto files, the gRPC convention to prefix enum values by the

lib/domain/enums/ApiProtocols.js

@@ -0,0 +1,20 @@
+/**
+ *  @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.
+ */
+
+/**
+ * Protocols of the API, shared by every component logging API requests (HTTP middleware, gRPC binding...) so that their entries are consistent
+ */
+exports.ApiProtocols = Object.freeze({
+    HTTP: 'http',
+    GRPC: 'grpc',
+});

lib/server/gRPC/bindGRPCController.js

@@ -13,6 +13,12 @@
 
 const { nativeToGRPCError } = require('./nativeToGRPCError.js');
 const { extractFieldsConverters } = require('./services/protoParsing/extractFieldsConverters.js');
+const { ApiRequestLogger } = require('../utilities/ApiRequestLogger.js');
+const { ApiProtocols } = require('../../domain/enums/ApiProtocols.js');
+
+const GRPC_STATUS_OK = 0;
+
+const defaultApiRequestLogger = new ApiRequestLogger();
 
 /**
  * Adapt gRPC service method to controller handler
@@ -112,18 +118,40 @@ const adaptGrpcServiceMethodToControllerHandler = (
  * @param {Array<Function|{process:Function}>} preProcessors a list of functions (or class containing a `process` function) that need to be run
  *     against the call before the implementation
  * @param {Map<string, Object>} absoluteMessagesDefinitions the absolute messages definitions
+ * @param {ApiRequestLogger} [apiRequestLogger] the logger of the calls
  * @return {Object} the adapter to provide as gRPC service implementation
  */
-const bindGRPCController = (serviceDefinition, implementation, preProcessors, absoluteMessagesDefinitions) => {
+const bindGRPCController = (
+    serviceDefinition,
+    implementation,
+    preProcessors,
+    absoluteMessagesDefinitions,
+    apiRequestLogger = defaultApiRequestLogger,
+) => {
     const serviceImplementations = {};
 
     for (const [methodName, { requestType, responseType, path }] of Object.entries(serviceDefinition)) {
         const requestFieldsConverters = extractFieldsConverters(requestType.type, absoluteMessagesDefinitions);
         const responseFieldsConverters = extractFieldsConverters(responseType.type, absoluteMessagesDefinitions);
 
         serviceImplementations[methodName] = async (call, callback) => {
+            const stopTimer = apiRequestLogger.startTimer();
+            let status = GRPC_STATUS_OK;
+
+            /*
+             * The request is converted in place then handed to the controller, which is free to mutate it (for example by removing the fields it
+             * consumed). It is then snapshotted right before the controller call, to be logged the way it has been received by the controller
+             */
+            let requestSnapshot;
+            const controllerHandler = implementation[methodName].bind(implementation);
+
             const adapter = adaptGrpcServiceMethodToControllerHandler(
-                implementation[methodName].bind(implementation),
+                (request) => {
+                    if (!apiRequestLogger.silent) {
+                        requestSnapshot = ApiRequestLogger.stringifyParams(request);
+                    }
+                    return controllerHandler(request);
+                },
                 requestFieldsConverters,
                 responseFieldsConverters,
             );
@@ -136,12 +164,26 @@ const bindGRPCController = (serviceDefinition, implementation, preProcessors, ab
                 const response = await adapter(call);
 
                 if (response === null) {
-                    callback(nativeToGRPCError(new Error(`Controller for ${path} returned an invalid response`)));
+                    const error = nativeToGRPCError(new Error(`Controller for ${path} returned an invalid response`));
+                    status = error.code;
+                    callback(error);
                 } else {
                     callback(null, response);
                 }
             } catch (error) {
-                callback(nativeToGRPCError(error));
+                const grpcError = nativeToGRPCError(error);
+                status = grpcError.code;
+                callback(grpcError);
+            } finally {
+                apiRequestLogger.log({
+                    protocol: ApiProtocols.GRPC,
+                    route: path,
+                    status,
+                    durationMs: stopTimer(),
+                    userId: call.identity?.id ?? null,
+                    // The controller has not been reached (for example, a pre-processor failed): the request is still untouched
+                    params: requestSnapshot === undefined ? call.request : requestSnapshot,
+                });
             }
         };
     }

lib/server/middleware/accessLog.middleware.js

@@ -11,67 +11,61 @@
  * or submit itself to any jurisdiction.
  */
 
-const { LogManager } = require('@aliceo2/web-ui');
-const { isInTestMode } = require('../../utilities/env-utils');
-
-const NANOSECONDS_PER_MILLISECOND = 1000000n;
+const { ApiRequestLogger } = require('../utilities/ApiRequestLogger.js');
+const { ApiProtocols } = require('../../domain/enums/ApiProtocols.js');
 
 /**
  * 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
+ * The entry is built by {@see ApiRequestLogger}, so it has the same structure as the gRPC ones. 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 (as params)
  *
- * @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)
+ * @param {object} [configuration] the middleware configuration, see {@see ApiRequestLogger}
  * @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;
+exports.accessLogMiddleware = (configuration) => {
+    const apiRequestLogger = new ApiRequestLogger(configuration);
 
-    const log = () => {
-        if (logged) {
+    return (request, response, next) => {
+        if (apiRequestLogger.silent) {
+            next();
             return;
         }
-        logged = true;
 
-        const { method, query, session, route, originalUrl } = request;
-        const contentLength = Number(response.getHeader('content-length'));
+        const stopTimer = apiRequestLogger.startTimer();
+        // 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 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,
-        };
+        const log = () => {
+            if (logged) {
+                return;
+            }
+            logged = true;
 
-        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;
-        }
+            const { method, query, session, route, originalUrl } = request;
+            const contentLength = Number(response.getHeader('content-length'));
 
-        logger.infoMessage(JSON.stringify(entry));
-    };
+            // The token is a credential and must never be logged
+            const params = { ...query };
+            delete params.token;
+
+            apiRequestLogger.log({
+                protocol: ApiProtocols.HTTP,
+                method,
+                route: route ? `${baseUrl}${route.path}` : originalUrl.split('?')[0],
+                status: response.statusCode,
+                durationMs: stopTimer(),
+                userId: session?.id ?? null,
+                bytes: Number.isNaN(contentLength) ? null : contentLength,
+                params,
+                aborted: !response.writableFinished,
+            });
+        };
 
-    response.once('finish', log);
-    response.once('close', log);
-    next();
+        response.once('finish', log);
+        response.once('close', log);
+        next();
+    };
 };

lib/server/utilities/ApiRequestLogger.js

@@ -0,0 +1,128 @@
+/**
+ * @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;
+
+/**
+ * Maximum length of the stringified params in the log entry, to keep the entries small
+ */
+const MAX_PARAMS_LENGTH = 500;
+
+/**
+ * Logs one single-line JSON entry for each API request, whatever the protocol (HTTP or gRPC), so that they share the same structure
+ *
+ * Entries are sent to the local logger only (no log level is provided, so they are NOT forwarded to InfoLogger)
+ */
+class ApiRequestLogger {
+    /**
+     * Constructor
+     *
+     * @param {object} [configuration] the logger 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)
+     */
+    constructor({ logger = LogManager.getLogger('API'), silent = isInTestMode() } = {}) {
+        this._logger = logger;
+        this._silent = silent;
+    }
+
+    /**
+     * States if the logger is silent
+     *
+     * @return {boolean} true if nothing will be logged
+     */
+    get silent() {
+        return this._silent;
+    }
+
+    /**
+     * Starts a timer
+     *
+     * @return {function(): number} function returning the number of milliseconds elapsed since the timer was started
+     */
+    startTimer() {
+        const startTime = process.hrtime.bigint();
+        return () => Number((process.hrtime.bigint() - startTime) / NANOSECONDS_PER_MILLISECOND);
+    }
+
+    /**
+     * Logs an API request. This function never throws: logging must not impact the request
+     *
+     * @param {object} request the request to log
+     * @param {ApiProtocols} request.protocol the protocol of the request
+     * @param {string|null} [request.method] the HTTP method (not applicable to gRPC)
+     * @param {string} request.route the HTTP route pattern or the gRPC method path
+     * @param {number} request.status the HTTP status or gRPC status code
+     * @param {number} request.durationMs the duration of the request
+     * @param {number|null} [request.userId] the id of the user
+     * @param {number|null} [request.bytes] the size of the response
+     * @param {object|string|null} [request.params] the HTTP query or gRPC request message (or its already stringified snapshot), logged as a
+     *     (truncated) JSON string, omitted if empty
+     * @param {boolean} [request.aborted] true if the request has been interrupted before the end of the response
+     * @return {void}
+     */
+    log({ protocol, method = null, route, status, durationMs, userId = null, bytes = null, params, aborted }) {
+        if (this._silent) {
+            return;
+        }
+
+        try {
+            const entry = { type: 'api_request', protocol, method, route, status, durationMs, userId, bytes };
+
+            const stringifiedParams = ApiRequestLogger.stringifyParams(params);
+            if (stringifiedParams !== null) {
+                entry.params = stringifiedParams;
+            }
+            if (aborted) {
+                entry.aborted = true;
+            }
+
+            this._logger.infoMessage(JSON.stringify(entry));
+        } catch {
+            // Ignored: a failure to log must never impact the request
+        }
+    }
+
+    /**
+     * Stringifies the params to a size limited JSON string
+     *
+     * @param {object|string|null} [params] the params to stringify. A string is considered as already stringified and is returned as is
+     * @return {string|null} the stringified params, null if there is nothing to log or if they can not be stringified
+     */
+    static stringifyParams(params) {
+        if (typeof params === 'string') {
+            return params;
+        }
+
+        if (!params || Object.keys(params).length === 0) {
+            return null;
+        }
+
+        let stringified;
+        try {
+            // Bigints can not be natively stringified
+            stringified = JSON.stringify(params, (_key, value) => typeof value === 'bigint' ? value.toString() : value);
+        } catch {
+            return null;
+        }
+
+        return stringified.length > MAX_PARAMS_LENGTH ? `${stringified.slice(0, MAX_PARAMS_LENGTH)}…` : stringified;
+    }
+}
+
+exports.ApiRequestLogger = ApiRequestLogger;
+
+exports.MAX_PARAMS_LENGTH = MAX_PARAMS_LENGTH;