CLDSRV-890: Log lifecycle expiration events in server access logs

lib/routes/routeBackbeat.js

@@ -117,6 +117,8 @@ function _respondWithHeaders(response, payload, extraHeaders, log, callback) {
     if (response.serverAccessLog) {
         // eslint-disable-next-line no-param-reassign
         response.serverAccessLog.bytesSent = Buffer.byteLength(body);
+        // eslint-disable-next-line no-param-reassign
+        response.serverAccessLog.endTurnAroundTime = process.hrtime.bigint();
     }
     response.writeHead(200, httpHeaders);
     response.end(body, 'utf8', () => {
@@ -843,6 +845,10 @@ function putObject(request, response, log, callback) {
 }
 
 function deleteObjectFromExpiration(request, response, userInfo, log, callback) {
+    if (request.serverAccessLog) {
+        // eslint-disable-next-line no-param-reassign
+        request.serverAccessLog.expiration = true;
+    }
     return objectDeleteInternal(userInfo, request, log, true, err => {
         if (err) {
             log.error('error deleting object from expiration', {
@@ -1693,6 +1699,10 @@ function routeBackbeat(clientIP, request, response, log) {
         (userInfo, authorizationResults, next) => handleAuthorizationResults(
                 request, authorizationResults, apiMethods[0], undefined, log, err => next(err, userInfo)),
         (userInfo, next) => {
+            if (request.serverAccessLog) {
+                // eslint-disable-next-line no-param-reassign
+                request.serverAccessLog.startTurnAroundTime = process.hrtime.bigint();
+            }
             // TODO: understand why non-object requests (batchdelete) were not authenticated
             if (!isObjectRequest) {
                 return routeNonObjectRequest(request, response, userInfo, log, next);

lib/utilities/serverAccessLogger.js

@@ -288,6 +288,9 @@ function getOperation(req) {
     const resourceType = methodToResType[req.apiMethod];
 
     if (req.serverAccessLog && req.serverAccessLog.backbeat) {
+        if (req.serverAccessLog.expiration) {
+            return 'S3.EXPIRE.OBJECT';
+        }
         return `REST.${req.method}.BACKBEAT`;
     }
 
@@ -516,9 +519,9 @@ function buildLogEntry(req, params, options) {
 
         // Scality server access logs extra fields
         logFormatVersion: SERVER_ACCESS_LOG_FORMAT_VERSION,
-        // 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),
+        // For non-expiration backbeat requests, force loggingEnabled
+        // to false to prevent delivery to log courier.
+        loggingEnabled: (params.backbeat && !params.expiration) ? false : (params.enabled ?? undefined),
         loggingTargetBucket: params.loggingEnabled?.TargetBucket ?? undefined,
         loggingTargetPrefix: params.loggingEnabled?.TargetPrefix ?? undefined,
         awsAccessKeyID: authInfo?.getAccessKey() ?? undefined,
@@ -604,6 +607,26 @@ function logServerAccess(req, res) {
         objectKey: params.objectKey,
     });
 
+    // Lifecycle expiration is an internal operation.
+    // Null out HTTP-layer fields to match AWS access log format.
+    if (params.expiration) {
+        logEntry.requester = 'ScalityS3LifecycleService';
+        logEntry.clientIP = undefined;
+        logEntry.requestURI = undefined;
+        logEntry.httpCode = undefined;
+        logEntry.bytesSent = undefined;
+        logEntry.totalTime = undefined;
+        logEntry.turnAroundTime = undefined;
+        logEntry.signatureVersion = undefined;
+        logEntry.cipherSuite = undefined;
+        logEntry.authenticationType = undefined;
+        logEntry.hostHeader = undefined;
+        logEntry.tlsVersion = undefined;
+        logEntry.referer = undefined;
+        logEntry.userAgent = undefined;
+        logEntry.versionId = undefined;
+        logEntry.awsAccessKeyID = undefined;
+    }
 
     if (params.internalLogRequestQueue && params.internalLogRequestQueue.length > 0) {
         if (logEntry.operation === 'REST.POST.MULTI_OBJECT_DELETE') {

package.json

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

tests/unit/utils/serverAccessLogger.js

@@ -276,6 +276,16 @@ describe('serverAccessLogger utility functions', () => {
             // Should return BACKBEAT instead of UNKNOWN
             assert.strictEqual(result, 'REST.GET.BACKBEAT');
         });
+
+        it('should return S3.EXPIRE.OBJECT for lifecycle expiration requests', () => {
+            const req = {
+                method: 'DELETE',
+                apiMethod: 'objectDelete',
+                serverAccessLog: { backbeat: true, expiration: true },
+            };
+            const result = getOperation(req);
+            assert.strictEqual(result, 'S3.EXPIRE.OBJECT');
+        });
     });
 
     describe('getRequester', () => {
@@ -1412,6 +1422,224 @@ describe('serverAccessLogger utility functions', () => {
             assert.strictEqual(loggedData.loggingTargetBucket, 'log-bucket');
             assert.strictEqual(loggedData.loggingTargetPrefix, 'logs/');
         });
+
+        it('should pass through loggingEnabled for lifecycle expiration', () => {
+            setServerAccessLogger(mockLogger);
+            const req = {
+                serverAccessLog: {
+                    backbeat: true,
+                    expiration: true,
+                    enabled: true,
+                    loggingEnabled: {
+                        TargetBucket: 'log-bucket',
+                        TargetPrefix: 'logs/',
+                    },
+                },
+                method: 'DELETE',
+                apiMethod: 'objectDelete',
+                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());
+            assert.strictEqual(loggedData.loggingEnabled, true);
+            assert.strictEqual(loggedData.loggingTargetBucket, 'log-bucket');
+            assert.strictEqual(loggedData.loggingTargetPrefix, 'logs/');
+            assert.strictEqual(loggedData.operation, 'S3.EXPIRE.OBJECT');
+        });
+
+        it('should force loggingEnabled false for non-expiration backbeat', () => {
+            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());
+            assert.strictEqual(loggedData.loggingEnabled, false);
+        });
+
+        it('should not deliver lifecycle expiration log when bucket has no logging config', () => {
+            setServerAccessLogger(mockLogger);
+            const req = {
+                serverAccessLog: {
+                    backbeat: true,
+                    expiration: true,
+                    enabled: false,
+                },
+                method: 'DELETE',
+                apiMethod: 'objectDelete',
+                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());
+            assert.strictEqual(loggedData.loggingEnabled, false);
+        });
+
+        it('should produce a complete log entry for lifecycle expiration', () => {
+            setServerAccessLogger(mockLogger);
+            const authInfo = {
+                getAccountDisplayName: () => 'lifecycleAccount',
+                getCanonicalID: () => 'lifecycle-canonical-id',
+                isRequesterPublicUser: () => false,
+                isRequesterAnIAMUser: () => false,
+                getAuthVersion: () => 'AWS4-HMAC-SHA256',
+                getAuthType: () => 'REST-HEADER',
+                getAccessKey: () => 'lifecycle-access-key',
+            };
+            const startTime = process.hrtime.bigint();
+            const startTurnAroundTime = startTime + 1_000_000n;
+            const endTurnAroundTime = startTurnAroundTime + 50_000_000n;
+            const onFinishEndTime = startTime + 100_000_000n;
+            const onCloseEndTime = startTime + 110_000_000n;
+
+            const req = {
+                serverAccessLog: {
+                    backbeat: true,
+                    expiration: true,
+                    enabled: true,
+                    loggingEnabled: {
+                        TargetBucket: 'log-bucket',
+                        TargetPrefix: 'access-logs/',
+                    },
+                    bucketOwner: 'bucket-owner-id',
+                    bucketName: 'source-bucket',
+                    objectKey: 'expired-object.txt',
+                    authInfo,
+                    analyticsAction: 'deleteObjectFromExpiration',
+                    analyticsAccountName: 'lifecycleAccount',
+                    analyticsUserName: '',
+                    startTime,
+                    startTimeUnixMS: Date.now(),
+                    startTurnAroundTime,
+                    onFinishEndTime,
+                    onCloseEndTime,
+                    objectSize: 1024,
+                    analyticsBytesDeleted: 1024,
+                },
+                method: 'DELETE',
+                apiMethod: 'objectDelete',
+                headers: { host: 'source-bucket.s3.amazonaws.com' },
+                socket: {},
+            };
+            const res = {
+                serverAccessLog: {
+                    endTurnAroundTime,
+                },
+                statusCode: 200,
+                getHeader: () => null,
+            };
+
+            logServerAccess(req, res);
+
+            assert.strictEqual(mockLogger.write.callCount, 1);
+            const loggedData = JSON.parse(mockLogger.write.firstCall.args[0].trim());
+
+            // Core expiration fields
+            assert.strictEqual(loggedData.operation, 'S3.EXPIRE.OBJECT');
+            assert.strictEqual(loggedData.loggingEnabled, true);
+            assert.strictEqual(loggedData.loggingTargetBucket, 'log-bucket');
+            assert.strictEqual(loggedData.loggingTargetPrefix, 'access-logs/');
+
+            // Bucket and object info
+            assert.strictEqual(loggedData.bucketOwner, 'bucket-owner-id');
+            assert.strictEqual(loggedData.bucketName, 'source-bucket');
+            assert.strictEqual(loggedData.objectKey, 'expired-object.txt');
+
+            // Requester is the lifecycle service, not the auth identity
+            assert.strictEqual(loggedData.requester, 'ScalityS3LifecycleService');
+
+            // Object size
+            assert.strictEqual(loggedData.objectSize, 1024);
+            assert.strictEqual(loggedData.bytesDeleted, 1024);
+
+            // HTTP-layer fields are null (internal operation, not an HTTP request)
+            assert.strictEqual(loggedData.clientIP, undefined);
+            assert.strictEqual(loggedData.requestURI, undefined);
+            assert.strictEqual(loggedData.httpCode, undefined);
+            assert.strictEqual(loggedData.bytesSent, undefined);
+            assert.strictEqual(loggedData.totalTime, undefined);
+            assert.strictEqual(loggedData.turnAroundTime, undefined);
+            assert.strictEqual(loggedData.signatureVersion, undefined);
+            assert.strictEqual(loggedData.authenticationType, undefined);
+            assert.strictEqual(loggedData.hostHeader, undefined);
+            assert.strictEqual(loggedData.awsAccessKeyID, undefined);
+        });
+
+        it('should log lifecycle expiration with error code on failure', () => {
+            setServerAccessLogger(mockLogger);
+            const req = {
+                serverAccessLog: {
+                    backbeat: true,
+                    expiration: true,
+                    enabled: true,
+                    loggingEnabled: {
+                        TargetBucket: 'log-bucket',
+                        TargetPrefix: 'logs/',
+                    },
+                    bucketOwner: 'bucket-owner-id',
+                    bucketName: 'source-bucket',
+                    objectKey: 'expired-object.txt',
+                    startTime: process.hrtime.bigint(),
+                    startTimeUnixMS: Date.now(),
+                },
+                method: 'DELETE',
+                apiMethod: 'objectDelete',
+                headers: {},
+                socket: {},
+            };
+            const res = {
+                serverAccessLog: {
+                    errorCode: 'NoSuchKey',
+                    endTurnAroundTime: process.hrtime.bigint(),
+                },
+                statusCode: 404,
+                getHeader: () => null,
+            };
+
+            logServerAccess(req, res);
+
+            assert.strictEqual(mockLogger.write.callCount, 1);
+            const loggedData = JSON.parse(mockLogger.write.firstCall.args[0].trim());
+            assert.strictEqual(loggedData.operation, 'S3.EXPIRE.OBJECT');
+            assert.strictEqual(loggedData.loggingEnabled, true);
+            assert.strictEqual(loggedData.requester, 'ScalityS3LifecycleService');
+            assert.strictEqual(loggedData.errorCode, 'NoSuchKey');
+            assert.strictEqual(loggedData.httpCode, undefined);
+        });
+
     });
 });