From 9cba42d730689f778a246c524ba6d14c766f44c8 Mon Sep 17 00:00:00 2001 From: George Raduta Date: Mon, 26 Oct 2026 14:50:10 +0100 Subject: [PATCH 1/3] Extract the HTTP middleware to be used by gRPC as well --- docs/backend-architecture.md | 23 ++-- docs/grpc.md | 5 + lib/domain/enums/ApiProtocols.js | 20 +++ lib/server/gRPC/bindGRPCController.js | 36 +++++- lib/server/middleware/accessLog.middleware.js | 90 +++++++------ lib/server/utilities/ApiRequestLogger.js | 118 ++++++++++++++++++ 6 files changed, 232 insertions(+), 60 deletions(-) create mode 100644 lib/domain/enums/ApiProtocols.js create mode 100644 lib/server/utilities/ApiRequestLogger.js diff --git a/docs/backend-architecture.md b/docs/backend-architecture.md index f7df1f1dd0..32e705fcea 100644 --- a/docs/backend-architecture.md +++ b/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. diff --git a/docs/grpc.md b/docs/grpc.md index 10e070114d..5060d33c3a 100644 --- a/docs/grpc.md +++ b/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 diff --git a/lib/domain/enums/ApiProtocols.js b/lib/domain/enums/ApiProtocols.js new file mode 100644 index 0000000000..c8ead170ff --- /dev/null +++ b/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', +}); diff --git a/lib/server/gRPC/bindGRPCController.js b/lib/server/gRPC/bindGRPCController.js index 27a68f3665..250ed743b1 100644 --- a/lib/server/gRPC/bindGRPCController.js +++ b/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,9 +118,16 @@ const adaptGrpcServiceMethodToControllerHandler = ( * @param {Array} preProcessors a list of functions (or class containing a `process` function) that need to be run * against the call before the implementation * @param {Map} 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)) { @@ -122,6 +135,9 @@ const bindGRPCController = (serviceDefinition, implementation, preProcessors, ab const responseFieldsConverters = extractFieldsConverters(responseType.type, absoluteMessagesDefinitions); serviceImplementations[methodName] = async (call, callback) => { + const stopTimer = apiRequestLogger.startTimer(); + let status = GRPC_STATUS_OK; + const adapter = adaptGrpcServiceMethodToControllerHandler( implementation[methodName].bind(implementation), requestFieldsConverters, @@ -136,12 +152,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 { + // The request has been converted in place by the adapter, so it is logged the way it has been received by the controller + apiRequestLogger.log({ + protocol: ApiProtocols.GRPC, + route: path, + status, + durationMs: stopTimer(), + userId: call.identity?.id ?? null, + params: call.request, + }); } }; } diff --git a/lib/server/middleware/accessLog.middleware.js b/lib/server/middleware/accessLog.middleware.js index e10a7b34fe..4e60246423 100644 --- a/lib/server/middleware/accessLog.middleware.js +++ b/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(); + }; }; diff --git a/lib/server/utilities/ApiRequestLogger.js b/lib/server/utilities/ApiRequestLogger.js new file mode 100644 index 0000000000..9bd2e3831d --- /dev/null +++ b/lib/server/utilities/ApiRequestLogger.js @@ -0,0 +1,118 @@ +/** + * @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} [request.params] the HTTP query or gRPC request message, 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} [params] the params to stringify + * @return {string|null} the stringified params, null if there is nothing to log + */ + static stringifyParams(params) { + if (!params || Object.keys(params).length === 0) { + return null; + } + + // Bigints can not be natively stringified + const stringified = JSON.stringify(params, (_key, value) => typeof value === 'bigint' ? value.toString() : value); + + return stringified.length > MAX_PARAMS_LENGTH ? `${stringified.slice(0, MAX_PARAMS_LENGTH)}…` : stringified; + } +} + +exports.ApiRequestLogger = ApiRequestLogger; + +exports.MAX_PARAMS_LENGTH = MAX_PARAMS_LENGTH; From 06f17fd69d480b6a1ee63ceecbc47f6915e6b21e Mon Sep 17 00:00:00 2001 From: George Raduta Date: Mon, 26 Oct 2026 14:50:36 +0100 Subject: [PATCH 2/3] Update tests for API logging --- test/gRPC/serviceImplementation.test.js | 55 ++++++++++++++ .../middleware/accessLog.middleware.test.js | 13 ++-- .../server/utilities/ApiRequestLogger.test.js | 75 +++++++++++++++++++ test/lib/server/utilities/index.js | 2 + 4 files changed, 139 insertions(+), 6 deletions(-) create mode 100644 test/lib/server/utilities/ApiRequestLogger.test.js diff --git a/test/gRPC/serviceImplementation.test.js b/test/gRPC/serviceImplementation.test.js index 44a5e31160..c21906d0f8 100644 --- a/test/gRPC/serviceImplementation.test.js +++ b/test/gRPC/serviceImplementation.test.js @@ -20,6 +20,9 @@ const { extractAbsoluteMessageDefinitions } = require('../../lib/server/gRPC/ser const sinon = require('sinon'); const { bindGRPCController } = require('../../lib/server/gRPC/bindGRPCController.js'); const { Long } = require('@grpc/proto-loader'); +const { ApiRequestLogger } = require('../../lib/server/utilities/ApiRequestLogger.js'); +const { ConflictError } = require('../../lib/server/errors/ConflictError.js'); +const { AuthenticatedOnly } = require('../../lib/server/errors/AuthenticatedOnly.js'); const PROTO_DIR = `${__dirname}/proto`; @@ -154,4 +157,56 @@ module.exports = () => { message: 'Controller for /test.Service/TestEnums returned an invalid response', })).to.be.true; }); + + describe('Calls logging', () => { + const getAdapter = (controller, preProcessors = []) => { + const logger = { infoMessage: sinon.fake() }; + const apiRequestLogger = new ApiRequestLogger({ logger, silent: false }); + const adapter = bindGRPCController(proto.Service.service, controller, preProcessors, absoluteMessagesDefinitions, apiRequestLogger); + return { adapter, logger }; + }; + + it('should log successful calls with the user, the method and the request', async () => { + const { adapter, logger } = getAdapter({ TestEnums: () => ({}), TestBigInts: () => ({ ui: 1n, i: 2n }), TestRepeated: () => ({}) }); + + await adapter.TestBigInts({ identity: { id: 9 }, request: { ui: Long.fromString('12', true), i: Long.fromString('-5') } }, sinon.fake()); + + expect(logger.infoMessage.calledOnce).to.be.true; + const { durationMs, ...entry } = JSON.parse(logger.infoMessage.firstCall.args[0]); + expect(durationMs).to.be.a('number').and.to.be.at.least(0); + expect(entry).to.eql({ + type: 'api_request', + protocol: 'grpc', + method: null, + route: '/test.Service/TestBigInts', + status: 0, + userId: 9, + bytes: null, + params: '{"ui":"12","i":"-5"}', + }); + }); + + it('should log the gRPC status of failing calls, including failed pre-processors', async () => { + const throwingController = { + TestEnums: () => { + throw new ConflictError('conflict'); + }, + TestBigInts: () => null, + TestRepeated: () => ({}), + }; + const { adapter, logger } = getAdapter(throwingController, [() => { + throw new AuthenticatedOnly('not authenticated'); + }]); + await adapter.TestEnums({ request: {} }, sinon.fake()); + expect(JSON.parse(logger.infoMessage.lastCall.args[0])).to.include({ status: 16, userId: null }); + + const { adapter: adapterWithoutPreProcessor, logger: otherLogger } = getAdapter(throwingController); + await adapterWithoutPreProcessor.TestEnums({ request: {} }, sinon.fake()); + expect(JSON.parse(otherLogger.infoMessage.lastCall.args[0])).to.include({ status: 6 }); + + await adapterWithoutPreProcessor.TestBigInts({ request: {} }, sinon.fake()); + expect(JSON.parse(otherLogger.infoMessage.lastCall.args[0])).to.include({ status: 2 }); + expect(otherLogger.infoMessage.callCount).to.equal(2); + }); + }); }; diff --git a/test/lib/server/middleware/accessLog.middleware.test.js b/test/lib/server/middleware/accessLog.middleware.test.js index 1458c3dbfa..a34ea0e69c 100644 --- a/test/lib/server/middleware/accessLog.middleware.test.js +++ b/test/lib/server/middleware/accessLog.middleware.test.js @@ -38,7 +38,7 @@ const handle = (request, responseFields = {}, configuration = {}) => { }; module.exports = () => { - it('should log a single line JSON entry with route pattern, status, duration, user, size and query once the response is sent', () => { + it('should log a single line JSON entry with route pattern, status, duration, user, size and params once the response is sent', () => { const query = { filter: { runNumbers: '1,2' }, page: { limit: '10' } }; const { logger, next, response } = handle( { method: 'GET', baseUrl: '/api', originalUrl: '/api/runs/12?a=1', route: { path: '/runs/:runNumber' }, session: { id: 7 }, query }, @@ -59,22 +59,23 @@ module.exports = () => { expect(durationMs).to.be.a('number').and.to.be.at.least(0); expect(entry).to.eql({ type: 'api_request', + protocol: 'http', method: 'GET', route: '/api/runs/:runNumber', status: 201, userId: 7, bytes: 123, - query, + params: JSON.stringify(query), }); }); - it('should log null user and size, no query, and the path when the request is anonymous and no route matched', () => { + it('should log null user and size, no params, and the path when the request is anonymous and no route matched', () => { const { logger, response } = handle({ method: 'GET', baseUrl: '/api', originalUrl: '/api/unknown?x=1', query: {} }); response.emit('finish'); const entry = JSON.parse(logger.infoMessage.firstCall.args[0]); expect(entry).to.include({ route: '/api/unknown', userId: null, bytes: null }); - expect(entry).to.not.have.property('query'); + expect(entry).to.not.have.property('params'); expect(entry).to.not.have.property('aborted'); }); @@ -90,7 +91,7 @@ module.exports = () => { const [message] = logger.infoMessage.firstCall.args; expect(message).to.not.include('secret'); - expect(JSON.parse(message).query).to.eql({ page: { limit: '5' } }); + expect(JSON.parse(message).params).to.equal(JSON.stringify({ page: { limit: '5' } })); }); it('should not log a query containing only the token parameter', () => { @@ -103,7 +104,7 @@ module.exports = () => { }); response.emit('finish'); - expect(JSON.parse(logger.infoMessage.firstCall.args[0])).to.not.have.property('query'); + expect(JSON.parse(logger.infoMessage.firstCall.args[0])).to.not.have.property('params'); }); it('should flag as aborted a request whose connection is closed before the response is sent', () => { diff --git a/test/lib/server/utilities/ApiRequestLogger.test.js b/test/lib/server/utilities/ApiRequestLogger.test.js new file mode 100644 index 0000000000..1ce64cc05b --- /dev/null +++ b/test/lib/server/utilities/ApiRequestLogger.test.js @@ -0,0 +1,75 @@ +/** + * @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 sinon = require('sinon'); +const { expect } = require('chai'); +const { ApiRequestLogger, MAX_PARAMS_LENGTH } = require('../../../../lib/server/utilities/ApiRequestLogger.js'); + +module.exports = () => { + const request = { protocol: 'grpc', route: '/o2.bookkeeping.RunService/Get', status: 0, durationMs: 3 }; + + it('should log a single line JSON entry with the same structure for every protocol', () => { + const logger = { infoMessage: sinon.fake() }; + const apiRequestLogger = new ApiRequestLogger({ logger, silent: false }); + + apiRequestLogger.log({ ...request, userId: 4, params: { runNumber: 12 } }); + apiRequestLogger.log({ protocol: 'http', method: 'GET', route: '/api/runs', status: 200, durationMs: 5, bytes: 10 }); + + expect(logger.infoMessage.callCount).to.equal(2); + const [grpcEntry, httpEntry] = logger.infoMessage.getCalls().map(({ args: [message] }) => { + expect(message).to.not.include('\n'); + return JSON.parse(message); + }); + + expect(grpcEntry).to.eql({ + type: 'api_request', + protocol: 'grpc', + method: null, + route: '/o2.bookkeeping.RunService/Get', + status: 0, + durationMs: 3, + userId: 4, + bytes: null, + params: '{"runNumber":12}', + }); + expect(Object.keys(httpEntry)).to.eql(Object.keys(grpcEntry).filter((key) => key !== 'params')); + }); + + it('should stringify bigints, omit empty params and truncate too long ones', () => { + expect(ApiRequestLogger.stringifyParams({ id: 12n })).to.equal('{"id":"12"}'); + expect(ApiRequestLogger.stringifyParams({})).to.be.null; + expect(ApiRequestLogger.stringifyParams(undefined)).to.be.null; + + const truncated = ApiRequestLogger.stringifyParams({ text: 'a'.repeat(MAX_PARAMS_LENGTH * 2) }); + expect(truncated).to.have.lengthOf(MAX_PARAMS_LENGTH + 1); + expect(truncated.endsWith('…')).to.be.true; + }); + + it('should not log anything when silent, and never throw', () => { + const logger = { infoMessage: sinon.fake() }; + new ApiRequestLogger({ logger, silent: true }).log(request); + expect(logger.infoMessage.called).to.be.false; + + const circular = {}; + circular.self = circular; + expect(() => new ApiRequestLogger({ logger, silent: false }).log({ ...request, params: circular })).to.not.throw(); + expect(() => new ApiRequestLogger({ logger: { infoMessage: () => { + throw new Error('failing logger'); + } }, silent: false }).log(request)).to.not.throw(); + }); + + it('should measure elapsed milliseconds', () => { + const stopTimer = new ApiRequestLogger({ silent: true }).startTimer(); + expect(stopTimer()).to.be.a('number').and.to.be.at.least(0); + }); +}; diff --git a/test/lib/server/utilities/index.js b/test/lib/server/utilities/index.js index 52f7704ea3..01e62f0c9f 100644 --- a/test/lib/server/utilities/index.js +++ b/test/lib/server/utilities/index.js @@ -14,8 +14,10 @@ const appendPathTest = require('./appendPath.test.js'); const isAnEmptyShellTest = require('./isAnEmptyShell.test.js'); const bigIntConverter = require('./bigIntConverter.test.js'); +const apiRequestLoggerTest = require('./ApiRequestLogger.test.js'); module.exports = () => { + describe('ApiRequestLogger', apiRequestLoggerTest); describe('appendPath', appendPathTest); describe('bigIntConverter', bigIntConverter); describe('isAnEmptyShell', isAnEmptyShellTest); From 20e506b223c26c856564f66cec678f990e94f417 Mon Sep 17 00:00:00 2001 From: George Raduta Date: Mon, 26 Oct 2026 15:06:00 +0100 Subject: [PATCH 3/3] Fix recommended snapshot issue --- lib/server/gRPC/bindGRPCController.js | 18 ++++++++++--- lib/server/utilities/ApiRequestLogger.js | 20 ++++++++++---- test/gRPC/serviceImplementation.test.js | 33 ++++++++++++++++++++++++ 3 files changed, 63 insertions(+), 8 deletions(-) diff --git a/lib/server/gRPC/bindGRPCController.js b/lib/server/gRPC/bindGRPCController.js index 250ed743b1..2af76100bb 100644 --- a/lib/server/gRPC/bindGRPCController.js +++ b/lib/server/gRPC/bindGRPCController.js @@ -138,8 +138,20 @@ const bindGRPCController = ( 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, ); @@ -163,14 +175,14 @@ const bindGRPCController = ( status = grpcError.code; callback(grpcError); } finally { - // The request has been converted in place by the adapter, so it is logged the way it has been received by the controller apiRequestLogger.log({ protocol: ApiProtocols.GRPC, route: path, status, durationMs: stopTimer(), userId: call.identity?.id ?? null, - params: call.request, + // The controller has not been reached (for example, a pre-processor failed): the request is still untouched + params: requestSnapshot === undefined ? call.request : requestSnapshot, }); } }; diff --git a/lib/server/utilities/ApiRequestLogger.js b/lib/server/utilities/ApiRequestLogger.js index 9bd2e3831d..090e90cac6 100644 --- a/lib/server/utilities/ApiRequestLogger.js +++ b/lib/server/utilities/ApiRequestLogger.js @@ -69,7 +69,8 @@ class ApiRequestLogger { * @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} [request.params] the HTTP query or gRPC request message, logged as a (truncated) JSON string, omitted if empty + * @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} */ @@ -98,16 +99,25 @@ class ApiRequestLogger { /** * Stringifies the params to a size limited JSON string * - * @param {object} [params] the params to stringify - * @return {string|null} the stringified params, null if there is nothing to log + * @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; } - // Bigints can not be natively stringified - const stringified = JSON.stringify(params, (_key, value) => typeof value === 'bigint' ? value.toString() : value); + 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; } diff --git a/test/gRPC/serviceImplementation.test.js b/test/gRPC/serviceImplementation.test.js index c21906d0f8..14f8ef172d 100644 --- a/test/gRPC/serviceImplementation.test.js +++ b/test/gRPC/serviceImplementation.test.js @@ -186,6 +186,39 @@ module.exports = () => { }); }); + it('should log the request as received by the controller even if the controller mutates it', async () => { + const { adapter, logger } = getAdapter({ + TestEnums: () => ({}), + TestBigInts: (request) => { + // Controllers consume the fields of the request they handle + delete request.ui; + request.i = 0n; + request.added = true; + return { ui: 1n, i: 2n }; + }, + TestRepeated: () => ({}), + }); + + await adapter.TestBigInts({ request: { ui: Long.fromString('12', true), i: Long.fromString('-5') } }, sinon.fake()); + + expect(JSON.parse(logger.infoMessage.firstCall.args[0]).params).to.equal('{"ui":"12","i":"-5"}'); + }); + + it('should log the untouched request when a pre-processor fails before the controller is reached', async () => { + const controller = sinon.fake(); + const { adapter, logger } = getAdapter( + { TestEnums: controller, TestBigInts: controller, TestRepeated: controller }, + [() => { + throw new AuthenticatedOnly('not authenticated'); + }], + ); + + await adapter.TestBigInts({ request: { ui: 'raw' } }, sinon.fake()); + + expect(controller.called).to.be.false; + expect(JSON.parse(logger.infoMessage.firstCall.args[0])).to.include({ status: 16, params: '{"ui":"raw"}' }); + }); + it('should log the gRPC status of failing calls, including failed pre-processors', async () => { const throwingController = { TestEnums: () => {