CLDSRV-821: add backbeat calls to logs

lib/routes/routeBackbeat.js

@@ -114,6 +114,10 @@ function _respondWithHeaders(response, payload, extraHeaders, log, callback) {
         'content-type': 'application/json',
         'content-length': Buffer.byteLength(body),
     }, extraHeaders);
+    if (response.serverAccessLog) {
+        // eslint-disable-next-line no-param-reassign
+        response.serverAccessLog.bytesSent = Buffer.byteLength(body);
+    }
     response.writeHead(200, httpHeaders);
     response.end(body, 'utf8', () => {
         log.end().info('responded with payload', {
@@ -1572,6 +1576,10 @@ function routeBackbeat(clientIP, request, response, log) {
     const contentLength = request.headers['x-amz-decoded-content-length'] || request.headers['content-length'];
     // eslint-disable-next-line no-param-reassign
     request.parsedContentLength = Number.parseInt(contentLength?.toString() ?? '', 10);
+
+    log.debug('routing request');
+    _normalizeBackbeatRequest(request);
+
     log.addDefaultFields({
         clientIP,
         url: request.url,
@@ -1582,9 +1590,17 @@ function routeBackbeat(clientIP, request, response, log) {
         bytesReceived: request.parsedContentLength || 0,
         bodyLength: parseInt(request.headers['content-length'], 10) || 0,
     });
+    if (request.serverAccessLog) {
+        // eslint-disable-next-line no-param-reassign
+        request.serverAccessLog.bucketName = request.bucketName;
+        // eslint-disable-next-line no-param-reassign
+        request.serverAccessLog.objectKey = request.objectKey;
+        // eslint-disable-next-line no-param-reassign
+        request.serverAccessLog.backbeat = true;
+        // eslint-disable-next-line no-param-reassign
+        request.serverAccessLog.analyticsAction = 'BACKBEAT_INVALID';
+    }
 
-    log.debug('routing request');
-    _normalizeBackbeatRequest(request);
     const requestContexts = prepareRequestContexts('objectReplicate', request);
 
     if (request.resourceType === 'expiration' || request.resourceType === 'batchdelete') {
@@ -1642,6 +1658,16 @@ function routeBackbeat(clientIP, request, response, log) {
 
     const isObjectRequest = _isObjectRequest(request);
 
+    if (request.serverAccessLog) {
+        let route = backbeatRoutes[request.method][request.resourceType];
+        if (useMultipleBackend && request.resourceType !== 'multiplebackendmetadata') {
+            route = backbeatRoutes[request.method][request.resourceType][request.query.operation];
+        }
+
+        // eslint-disable-next-line no-param-reassign
+        request.serverAccessLog.analyticsAction = route?.name ?? 'BACKBEAT_INVALID';
+    }
+
     return async.waterfall([
         next => auth.server.doAuth(
             request, log, (err, userInfo, authorizationResults, streamingV4Params, infos) => {
@@ -1652,6 +1678,14 @@ function routeBackbeat(clientIP, request, response, log) {
                         objectKey: request.objectKey,
                     });
                 }
+                if (request.serverAccessLog && userInfo) {
+                    // eslint-disable-next-line no-param-reassign
+                    request.serverAccessLog.authInfo = userInfo;
+                    // eslint-disable-next-line no-param-reassign
+                    request.serverAccessLog.analyticsAccountName = userInfo.getAccountDisplayName();
+                    // eslint-disable-next-line no-param-reassign
+                    request.serverAccessLog.analyticsUserName = userInfo.getIAMdisplayName();
+                }
                 // eslint-disable-next-line no-param-reassign
                 request.accountQuotas = infos?.accountQuota;
                 return next(err, userInfo, authorizationResults);

lib/server.js

@@ -126,11 +126,13 @@ class S3Server {
         monitoringClient.httpActiveRequests.inc();
         const requestStartTime = process.hrtime.bigint();
 
-        // Skip server access logs for heartbeat and backbeat.
+        // Skip server access logs for heartbeat.
         const isLoggingEnabled = _config.serverAccessLogs
             && (_config.serverAccessLogs.mode === serverAccessLogsModes.LOG_ONLY
                 || _config.serverAccessLogs.mode === serverAccessLogsModes.ENABLED);
-        if (isLoggingEnabled && !req.url.startsWith('/_/')) {
+        const isInternalRoute = req.url.startsWith('/_');
+        const isBackbeatRoute = req.url.startsWith('/_/backbeat/');
+        if (isLoggingEnabled && (!isInternalRoute || isBackbeatRoute)) {
             // eslint-disable-next-line no-param-reassign
             req.serverAccessLog = {
                 enabled: false,

lib/utilities/serverAccessLogger.js

@@ -257,6 +257,10 @@ const methodToResType = Object.freeze({
 
 function getOperation(req) {
     const resourceType = methodToResType[req.apiMethod];
+
+    if (req.serverAccessLog && req.serverAccessLog.backbeat) {
+        return `REST.${req.method}.BACKBEAT`;
+    }
     if (!resourceType) {
         process.emitWarning('Unknown apiMethod for server access log', {
             type: 'ServerAccessLogWarning',
@@ -457,7 +461,9 @@ function logServerAccess(req, res) {
 
         // Scality server access logs extra fields
         logFormatVersion: SERVER_ACCESS_LOG_FORMAT_VERSION,
-        loggingEnabled: params.enabled ?? undefined,
+        // If backbeat is enabled, we set loggingEnabled to false
+        // to prevent backbeat requests from getting to log courier.
+        loggingEnabled: params.backbeat ? false : (params.enabled ?? undefined),
         loggingTargetBucket: params.loggingEnabled?.TargetBucket ?? undefined,
         loggingTargetPrefix: params.loggingEnabled?.TargetPrefix ?? undefined,
         awsAccessKeyID: authInfo?.getAccessKey() ?? undefined,

package.json

@@ -1,6 +1,6 @@
 {
   "name": "@zenko/cloudserver",
-  "version": "9.2.17",
+  "version": "9.2.18",
   "description": "Zenko CloudServer, an open-source Node.js implementation of a server handling the Amazon S3 protocol",
   "main": "index.js",
   "engines": {

schema/server_access_log.schema.json

@@ -20,7 +20,7 @@
             "minimum": 0
         },
         "action": {
-            "description": "S3 API action name.",
+            "description": "S3 API action name or the Backbeat route.",
             "type": "string"
         },
         "accountName": {

tests/unit/utils/serverAccessLogger.js

@@ -196,6 +196,68 @@ describe('serverAccessLogger utility functions', () => {
             const result = getOperation(req);
             assert.strictEqual(result, 'REST.GET.UNKNOWN');
         });
+
+        it('should return REST.GET.BACKBEAT when backbeat is enabled for GET', () => {
+            const req = {
+                method: 'GET',
+                apiMethod: 'objectGet',
+                serverAccessLog: { backbeat: true },
+            };
+            const result = getOperation(req);
+            assert.strictEqual(result, 'REST.GET.BACKBEAT');
+        });
+
+        it('should return REST.PUT.BACKBEAT when backbeat is enabled for PUT', () => {
+            const req = {
+                method: 'PUT',
+                apiMethod: 'objectPut',
+                serverAccessLog: { backbeat: true },
+            };
+            const result = getOperation(req);
+            assert.strictEqual(result, 'REST.PUT.BACKBEAT');
+        });
+
+        it('should return REST.DELETE.BACKBEAT when backbeat is enabled for DELETE', () => {
+            const req = {
+                method: 'DELETE',
+                apiMethod: 'objectDelete',
+                serverAccessLog: { backbeat: true },
+            };
+            const result = getOperation(req);
+            assert.strictEqual(result, 'REST.DELETE.BACKBEAT');
+        });
+
+        it('should return REST.POST.BACKBEAT when backbeat is enabled for POST', () => {
+            const req = {
+                method: 'POST',
+                apiMethod: 'completeMultipartUpload',
+                serverAccessLog: { backbeat: true },
+            };
+            const result = getOperation(req);
+            assert.strictEqual(result, 'REST.POST.BACKBEAT');
+        });
+
+        it('should prioritize backbeat over normal apiMethod mapping', () => {
+            const req = {
+                method: 'GET',
+                apiMethod: 'bucketGetVersioning',
+                serverAccessLog: { backbeat: true },
+            };
+            const result = getOperation(req);
+            // Should return BACKBEAT instead of normal REST.GET.VERSIONING
+            assert.strictEqual(result, 'REST.GET.BACKBEAT');
+        });
+
+        it('should return REST.method.BACKBEAT even with unknown apiMethod', () => {
+            const req = {
+                method: 'GET',
+                apiMethod: 'unknownMethod',
+                serverAccessLog: { backbeat: true },
+            };
+            const result = getOperation(req);
+            // Should return BACKBEAT instead of UNKNOWN
+            assert.strictEqual(result, 'REST.GET.BACKBEAT');
+        });
     });
 
     describe('getRequester', () => {
@@ -1146,6 +1208,90 @@ describe('serverAccessLogger utility functions', () => {
             assert.strictEqual('bytesReceived' in loggedData, false);
             assert.strictEqual('contentLength' in loggedData, false);
         });
+
+        it('should log with loggingEnabled false when backbeat is enabled', () => {
+            setServerAccessLogger(mockLogger);
+            const req = {
+                serverAccessLog: {
+                    backbeat: true,
+                    enabled: true,
+                },
+                method: 'GET',
+                apiMethod: 'objectGet',
+                headers: {},
+                socket: {},
+            };
+            const res = {
+                serverAccessLog: {},
+                getHeader: () => null,
+            };
+
+            logServerAccess(req, res);
+
+            assert.strictEqual(mockLogger.write.callCount, 1);
+            const loggedData = JSON.parse(mockLogger.write.firstCall.args[0].trim());
+
+            // Verify loggingEnabled is false in the logged data
+            assert.strictEqual(loggedData.loggingEnabled, false);
+        });
+
+        it('should log REST.GET.BACKBEAT operation when backbeat is enabled', () => {
+            setServerAccessLogger(mockLogger);
+            const req = {
+                serverAccessLog: {
+                    backbeat: true,
+                },
+                method: 'GET',
+                apiMethod: 'objectGet',
+                headers: {},
+                socket: {},
+            };
+            const res = {
+                serverAccessLog: {},
+                getHeader: () => null,
+            };
+
+            logServerAccess(req, res);
+
+            assert.strictEqual(mockLogger.write.callCount, 1);
+            const loggedData = JSON.parse(mockLogger.write.firstCall.args[0].trim());
+
+            // Verify operation is REST.GET.BACKBEAT
+            assert.strictEqual(loggedData.operation, 'REST.GET.BACKBEAT');
+        });
+
+        it('should override loggingEnabled when backbeat is enabled with logging config', () => {
+            setServerAccessLogger(mockLogger);
+            const req = {
+                serverAccessLog: {
+                    backbeat: true,
+                    enabled: true,
+                    loggingEnabled: {
+                        TargetBucket: 'log-bucket',
+                        TargetPrefix: 'logs/',
+                    },
+                },
+                method: 'PUT',
+                apiMethod: 'objectPut',
+                headers: {},
+                socket: {},
+            };
+            const res = {
+                serverAccessLog: {},
+                getHeader: () => null,
+            };
+
+            logServerAccess(req, res);
+
+            assert.strictEqual(mockLogger.write.callCount, 1);
+            const loggedData = JSON.parse(mockLogger.write.firstCall.args[0].trim());
+
+            // Verify loggingEnabled is false (overridden by backbeat)
+            assert.strictEqual(loggedData.loggingEnabled, false);
+            // But TargetBucket and TargetPrefix should still be logged
+            assert.strictEqual(loggedData.loggingTargetBucket, 'log-bucket');
+            assert.strictEqual(loggedData.loggingTargetPrefix, 'logs/');
+        });
     });
 });