diff --git a/lib/routes/routeBackbeat.js b/lib/routes/routeBackbeat.js index 1d25dff0b2..cc65cce354 100644 --- a/lib/routes/routeBackbeat.js +++ b/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); diff --git a/lib/utilities/serverAccessLogger.js b/lib/utilities/serverAccessLogger.js index 9dc5531dfc..25639c59ae 100644 --- a/lib/utilities/serverAccessLogger.js +++ b/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') { diff --git a/package.json b/package.json index 2633ee786d..b4ae39b20d 100644 --- a/package.json +++ b/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": { diff --git a/tests/unit/utils/serverAccessLogger.js b/tests/unit/utils/serverAccessLogger.js index 967a1d52bb..e9fbb307f9 100644 --- a/tests/unit/utils/serverAccessLogger.js +++ b/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); + }); + }); });