Logging improvements

lib/api/apiUtils/object/abortMultipartUpload.js

@@ -100,7 +100,7 @@ function abortMultipartUpload(authInfo, bucketName, objectKey, uploadId, log,
             // In case there has been an error during cleanup after a complete MPU
             // (e.g. failure to delete MPU MD in shadow bucket),
             // we need to ensure that the MPU metadata is deleted.
-            log.info('Object has existing metadata, deleting them', {
+            log.debug('Object has existing metadata, deleting them', {
                 method: 'abortMultipartUpload',
                 bucketName,
                 objectKey,

lib/api/apiUtils/object/coldStorage.js

@@ -244,16 +244,26 @@ function _updateRestoreInfo(objectMD, restoreParam, log) {
  *
  */
 function startRestore(objectMD, restoreParam, log, cb) {
-    log.info('Validating if restore can be done or not.');
+    log.debug('Validating if restore can be done or not.');
     const checkResultError = _validateStartRestore(objectMD, log);
     if (checkResultError) {
+        log.debug('Restore cannot be done.', {
+            error: checkResultError,
+            method: 'startRestore'
+        });
         return cb(checkResultError);
     }
-    log.info('Updating restore information.');
     const updateResultError = _updateRestoreInfo(objectMD, restoreParam, log);
     if (updateResultError) {
+        log.debug('Failed to update restore information.', {
+            error: updateResultError,
+            method: 'startRestore'
+        });
         return cb(updateResultError);
     }
+    log.debug('Validated and updated restore information', {
+         method: 'startRestore'
+    });
     const isObjectAlreadyRestored = _updateObjectExpirationDate(objectMD, log);
     return cb(null, isObjectAlreadyRestored);
 }

lib/api/apiUtils/object/objectRestore.js

@@ -94,7 +94,7 @@ function objectRestore(metadata, mdUtils, userInfo, request, log, callback) {
                         log.trace('version is a delete marker', { method: METHOD, error: err });
                         return next(err, bucketMD, objectMD);
                     }
-                    log.info('it acquired the object metadata.', {
+                    log.debug('acquired the object metadata.', {
                         'method': METHOD,
                     });
                     return next(null, bucketMD, objectMD);
@@ -108,7 +108,7 @@ function objectRestore(metadata, mdUtils, userInfo, request, log, callback) {
                     if (err) {
                         return next(err, bucketMD, objectMD, restoreInfo);
                     }
-                    log.info('it parsed xml of the request body.', { method: METHOD, value: restoreInfo });
+                    log.debug('parsed xml of the request body.', { method: METHOD, value: restoreInfo });
                     const checkTierResult = checkTierSupported(restoreInfo);
                     if (checkTierResult instanceof Error) {
                         return next(checkTierResult);

lib/api/objectDelete.js

@@ -87,6 +87,21 @@ function objectDeleteInternal(authInfo, request, log, isExpiration, cb) {
                     // versioning has been configured
                     return next(null, bucketMD, objMD);
                 }
+
+                if (versioningCfg && versioningCfg.Status === 'Enabled' &&
+                    objMD.versionId === reqVersionId && isExpiration &&
+                    !objMD.isDeleteMarker) {
+                        log.warn('expiration is trying to delete a master version ' +
+                        'of an object with versioning enabled', {
+                            method: 'objectDeleteInternal',
+                            isExpiration,
+                            reqVersionId,
+                            versionId: objMD.versionId,
+                            replicationState: objMD.replicationInfo,
+                            location: objMD.location,
+                            originOp: objMD.originOp,
+                        });
+                    }
                 if (reqVersionId && objMD.location &&
                     Array.isArray(objMD.location) && objMD.location[0]) {
                     // we need this information for data deletes to AWS

lib/routes/routeBackbeat.js

@@ -1047,7 +1047,7 @@
     const reqUids = log.getSerializedUids();
     return dataClient.delete(objectGetInfo, reqUids, err => {
         if (err && err.code === 412) {
-            log.info('precondition for Azure deletion was not met', {
+            log.error('precondition for Azure deletion was not met', {
                 method: '_azureConditionalDelete',
                 key: request.objectKey,
                 bucket: request.bucketName,
@@ -1086,7 +1086,7 @@
         }
         const ifUnmodifiedSince = request.headers['if-unmodified-since'];
         if (new Date(ifUnmodifiedSince) < new Date(lastModified)) {
-            log.info('object has been modified, skipping tagging operation', {
+            log.debug('object has been modified, skipping tagging operation', {
                 method: '_conditionalTagging',
                 ifUnmodifiedSince,
                 lastModified,
@@ -1103,7 +1103,7 @@
     const { headers } = request;
     const location = locationConstraints[headers['x-scal-storage-class']];
     if (!request.headers['if-unmodified-since']) {
-        log.info('unknown last modified time, skipping conditional delete', {
+        log.debug('unknown last modified time, skipping conditional delete', {
             method: '_performConditionalDelete',
         });
         return _respond(response, null, log, cb);
@@ -1387,10 +1387,18 @@
     // Attach the apiMethod method to the request, so it can used by monitoring in the server
     // eslint-disable-next-line no-param-reassign
     request.apiMethod = 'routeBackbeat';
-    log.debug('routing request', {
-        method: 'routeBackbeat',
+    log.addDefaultFields({
+        clientIP,
         url: request.url,
+        method: 'routeBackbeat',
+        resourceType: request.resourceType,
+        bucketName: request.bucketName,
+        objectKey: request.objectKey,
+        bytesReceived: request.parsedContentLength || 0,
+        bodyLength: parseInt(request.headers['content-length'], 10) || 0,
     });
+
+    log.debug('routing request');
     _normalizeBackbeatRequest(request);
     const requestContexts = prepareRequestContexts('objectReplicate', request);
 
@@ -1429,9 +1437,6 @@
             if (err) {
                 log.debug('authentication error', {
                     error: err,
-                    method: request.method,
-                    bucketName: request.bucketName,
-                    objectKey: request.objectKey,
                 });
                 return responseJSONBody(err, null, response, log);
             }
@@ -1444,8 +1449,6 @@
             if (userInfo.getCanonicalID() === constants.publicId) {
                 log.debug('unauthenticated access to API routes', {
                     method: request.method,
-                    bucketName: request.bucketName,
-                    objectKey: request.objectKey,
                 });
                 return responseJSONBody(
                     errors.AccessDenied, null, response, log);
@@ -1473,18 +1476,8 @@
            (backbeatRoutes[request.method][request.resourceType]
             [request.query.operation] === undefined &&
             request.resourceType === 'multiplebackenddata'));
-    log.addDefaultFields({
-        bucketName: request.bucketName,
-        objectKey: request.objectKey,
-        bytesReceived: request.parsedContentLength || 0,
-        bodyLength: parseInt(request.headers['content-length'], 10) || 0,
-    });
     if (invalidRequest || invalidRoute) {
-        log.debug(invalidRequest ? 'invalid request' : 'no such route', {
-            method: request.method,
-            resourceType: request.resourceType,
-            query: request.query,
-        });
+        log.debug(invalidRequest ? 'invalid request' : 'no such route');
         return responseJSONBody(errors.MethodNotAllowed, null, response, log);
     }
 
@@ -1494,9 +1487,6 @@
             if (err) {
                 log.debug('authentication error', {
                     error: err,
-                    method: request.method,
-                    bucketName: request.bucketName,
-                    objectKey: request.objectKey,
                 });
             }
             // eslint-disable-next-line no-param-reassign
@@ -1507,11 +1497,7 @@
             // TODO: understand why non-object requests (batchdelete) were not authenticated
             if (!_isObjectRequest(request)) {
                 if (userInfo.getCanonicalID() === constants.publicId) {
-                    log.debug(`unauthenticated access to backbeat ${request.resourceType} routes`, {
-                        method: request.method,
-                        bucketName: request.bucketName,
-                        objectKey: request.objectKey,
-                    });
+                    log.debug(`unauthenticated access to backbeat ${request.resourceType} routes`);
                     return responseJSONBody(
                         errors.AccessDenied, null, response, log);
                 }
@@ -1559,12 +1545,7 @@
                 // target buckets with versioning enabled.
                 const isVersioningRequired = request.headers['x-scal-versioning-required'] === 'true';
                 if (isVersioningRequired && (!versioningConfig || versioningConfig.Status !== 'Enabled')) {
-                    log.debug('bucket versioning is not enabled', {
-                        method: request.method,
-                        bucketName: request.bucketName,
-                        objectKey: request.objectKey,
-                        resourceType: request.resourceType,
-                    });
+                    log.debug('bucket versioning is not enabled');
                     return next(errors.InvalidBucketState);
                 }
                 return backbeatRoutes[request.method][request.resourceType](
@@ -1586,12 +1567,12 @@
             (hook, done) => hook(err, done),
             () => {
                 if (err) {
+                    log.error('error processing backbeat request', {
+                        error: err,
+                    });
                     return responseJSONBody(err, null, response, log);
                 }
-                log.debug('backbeat route response sent successfully',
-                    { method: request.method,
-                        bucketName: request.bucketName,
-                        objectKey: request.objectKey });
+                log.debug('backbeat route response sent successfully');
                 return undefined;
             },
         ));

lib/routes/routeVeeam.js

@@ -188,7 +188,7 @@ function routeVeeam(clientIP, request, response, log) {
     request.apiMethod = 'routeVeeam';
     _normalizeVeeamRequest(request);
 
-    log.info('routing request', {
+    log.debug('routing request', {
         method: 'routeVeeam',
         url: request.url,
         clientIP,

lib/server.js

@@ -292,7 +292,7 @@
             next => clientCheck(true, log, next),
         ], (err, results) => {
             if (err) {
-                log.info('initial health check failed, delaying startup', {
+                log.warn('initial health check failed, delaying startup', {
                     error: err,
                     healthStatus: results,
                 });

package.json

@@ -1,6 +1,6 @@
 {
   "name": "@zenko/cloudserver",
-  "version": "8.8.43",
+  "version": "8.8.44",
   "description": "Zenko CloudServer, an open-source Node.js implementation of a server handling the Amazon S3 protocol",
   "main": "index.js",
   "engines": {
@@ -21,7 +21,7 @@
   "dependencies": {
     "@azure/storage-blob": "^12.12.0",
     "@hapi/joi": "^17.1.0",
-    "arsenal": "git+https://github.com/scality/arsenal#8.1.146",
+    "arsenal": "git+https://github.com/scality/arsenal#8.1.148",
     "async": "~2.5.0",
     "aws-sdk": "2.905.0",
     "bucketclient": "scality/bucketclient#8.1.9",

tests/unit/api/apiUtils/coldStorage.js

@@ -243,5 +243,16 @@ describe('cold storage', () => {
                 done();
             });
         });
+
+        it('should fail if _updateRestoreInfo fails', done => {
+            const objectMd = new ObjectMD().setDataStoreName(
+                'location-dmf-v1'
+            ).setArchive(false).getValue();
+
+            startRestore(objectMd, { days: 7 }, log, err => {
+                assert.deepStrictEqual(err, errors.InternalError);
+                done();
+            });
+        });
     });
 });

tests/unit/api/objectDelete.js

@@ -8,7 +8,7 @@ const bucketPutACL = require('../../../lib/api/bucketPutACL');
 const constants = require('../../../constants');
 const { cleanup, DummyRequestLogger, makeAuthInfo } = require('../helpers');
 const objectPut = require('../../../lib/api/objectPut');
-const { objectDelete } = require('../../../lib/api/objectDelete');
+const { objectDelete, objectDeleteInternal } = require('../../../lib/api/objectDelete');
 const objectGet = require('../../../lib/api/objectGet');
 const DummyRequest = require('../DummyRequest');
 const mpuUtils = require('../utils/mpuUtils');
@@ -210,6 +210,38 @@ describe('objectDelete API', () => {
         });
     });
 
+    it('should log when expiration is trying to delete a master version', done => {
+        const warnStub = sinon.stub(log, 'warn');
+        const testBucketPutVersionRequest = new DummyRequest({
+            bucketName,
+            namespace,
+            headers: { 'x-amz-bucket-object-lock-enabled': 'true' },
+            url: `/${bucketName}`,
+        });
+
+        bucketPut(authInfo, testBucketPutVersionRequest, log, () => {
+            objectPut(authInfo, testPutObjectRequest,
+                undefined, log, (err, data) => {
+                    const deleteObjectVersionRequest = new DummyRequest({
+                        bucketName,
+                        namespace,
+                        objectKey,
+                        headers: {},
+                        url: `/${bucketName}/${objectKey}?versionId=${data['x-amz-version-id']}`,
+                        query: {
+                            versionId: data['x-amz-version-id'],
+                        },
+                    });
+                    objectDeleteInternal(authInfo, deleteObjectVersionRequest, log, true, err => {
+                        assert.strictEqual(err, null);
+                        sinon.assert.calledWith(warnStub, 'expiration is trying to delete a master version ' +
+                            'of an object with versioning enabled');
+                        done();
+                    });
+                });
+        });
+    });
+
     describe('with \'modified\' headers', () => {
         beforeEach(done => {
             bucketPut(authInfo, testBucketPutRequest, log, () => {

tests/unit/internal/routeVeeam.js

@@ -1,6 +1,7 @@
 const assert = require('assert');
 const { DummyRequestLogger } = require('../helpers');
 const routeVeeam = require('../../../lib/routes/routeVeeam');
+const DummyRequest = require('../DummyRequest');
 
 const log = new DummyRequestLogger();
 
@@ -111,3 +112,25 @@ describe('RouteVeeam: _normalizeVeeamRequest', () => {
         assert.doesNotThrow(() => routeVeeam._normalizeVeeamRequest(request));
     });
 });
+
+describe('RouteVeeam: routeVeeam', () => {
+    it('should return error for unsupported routes', done => {
+        const req = new DummyRequest({
+            method: 'PATCH',
+            resourceType: 'bucket',
+            subresource: 'veeam',
+            apiMethod: 'routeVeeam',
+            url: '/bucket/veeam',
+        });
+        req.method = 'PATCH';
+        routeVeeam.routeVeeam('127.0.0.1', req, {
+            setHeader: () => {},
+            writeHead: () => {},
+            end: data => {
+                assert(data.includes('MethodNotAllowed'));
+                done();
+            },
+            headersSent: false,
+        }, log);
+    });
+});