ARSN-479: Add details about kmip in logs

Log the host for multi ip
Log the latency for support to notice slow KMS problem
Log the operation and the success of kmip request to know latency and host

Author: BourgoisMickael

lib/network/kmip/Client.ts

@@ -54,6 +54,7 @@ const searchFilter = {
  * @param cb - The callback triggered after the negotiation.
  */
 function _negotiateProtocolVersion(client: any, logger: werelogs.Logger, cb: any) {
+    const startDate = Date.now();
     return client.kmip.request(logger, 'Discover Versions', [
         KMIP.Structure('Protocol Version', [
             KMIP.Integer('Protocol Version Major', 1),
@@ -68,10 +69,14 @@ function _negotiateProtocolVersion(client: any, logger: werelogs.Logger, cb: any
             KMIP.Integer('Protocol Version Minor', 2),
         ]),
     ], (err, response) => {
+        const kmipLog = {
+            host: client.host,
+            latencyMs: Date.now() - startDate
+        };
         if (err) {
             const error = arsenalErrorKMIP(err);
             logger.error('KMIP::negotiateProtocolVersion',
-                { error,
+                { error, kmip: kmipLog,
                     vendorIdentification: client.vendorIdentification });
             return cb(error);
         }
@@ -83,7 +88,7 @@ function _negotiateProtocolVersion(client: any, logger: werelogs.Logger, cb: any
             majorVersions.length !== minorVersions.length) {
             const error = arsenalErrorKMIP('No suitable protocol version');
             logger.error('KMIP::negotiateProtocolVersion',
-                { error,
+                { error, kmip: kmipLog,
                     vendorIdentification: client.vendorIdentification });
             return cb(error);
         }
@@ -100,13 +105,18 @@ function _negotiateProtocolVersion(client: any, logger: werelogs.Logger, cb: any
  * @param cb - The callback triggered after the extension mapping
  */
 function _mapExtensions(client: any, logger: werelogs.Logger, cb: any) {
+    const startDate = Date.now();
     return client.kmip.request(logger, 'Query', [
         KMIP.Enumeration('Query Function', 'Query Extension Map'),
     ], (err, response) => {
+        const kmipLog = {
+            host: client.host,
+            latencyMs: Date.now() - startDate
+        };
         if (err) {
             const error = arsenalErrorKMIP(err);
             logger.error('KMIP::mapExtensions',
-                { error,
+                { error, kmip: kmipLog,
                     vendorIdentification: client.vendorIdentification });
             return cb(error);
         }
@@ -115,7 +125,7 @@ function _mapExtensions(client: any, logger: werelogs.Logger, cb: any) {
         if (extensionNames.length !== extensionTags.length) {
             const error = arsenalErrorKMIP('Inconsistent extension list');
             logger.error('KMIP::mapExtensions',
-                { error,
+                { error, kmip: kmipLog,
                     vendorIdentification: client.vendorIdentification });
             return cb(error);
         }
@@ -133,13 +143,18 @@ function _mapExtensions(client: any, logger: werelogs.Logger, cb: any) {
  * @param cb - The callback triggered after the information discovery
  */
 function _queryServerInformation(client: any, logger: werelogs.Logger, cb: any) {
+    const startDate = Date.now();
     client.kmip.request(logger, 'Query', [
         KMIP.Enumeration('Query Function', 'Query Server Information'),
     ], (err, response) => {
+        const kmipLog = {
+            host: client.host,
+            latencyMs: Date.now() - startDate
+        };
         if (err) {
             const error = arsenalErrorKMIP(err);
             logger.warn('KMIP::queryServerInformation',
-                { error });
+                { error, kmip: kmipLog });
             /* no error returned, caller can keep going */
             return cb();
         }
@@ -151,7 +166,8 @@ function _queryServerInformation(client: any, logger: werelogs.Logger, cb: any)
         logger.info('KMIP Server identified',
             { vendorIdentification: client.vendorIdentification,
                 serverInformation: client.serverInformation,
-                negotiatedProtocolVersion: client.kmip.protocolVersion });
+                negotiatedProtocolVersion: client.kmip.protocolVersion,
+                kmip: kmipLog });
         return cb();
     });
 }
@@ -167,14 +183,19 @@ function _queryServerInformation(client: any, logger: werelogs.Logger, cb: any)
  * @param cb - The callback triggered after the information discovery
  */
 function _queryOperationsAndObjects(client: any, logger: werelogs.Logger, cb: any) {
+    const startDate = Date.now();
     return client.kmip.request(logger, 'Query', [
         KMIP.Enumeration('Query Function', 'Query Operations'),
         KMIP.Enumeration('Query Function', 'Query Objects'),
     ], (err, response) => {
+        const kmipLog = {
+            host: client.host,
+            latencyMs: Date.now() - startDate
+        };
         if (err) {
             const error = arsenalErrorKMIP(err);
             logger.error('KMIP::queryOperationsAndObjects',
-                { error,
+                { error, kmip: kmipLog,
                     vendorIdentification: client.vendorIdentification });
             return cb(error);
         }
@@ -205,10 +226,12 @@ function _queryOperationsAndObjects(client: any, logger: werelogs.Logger, cb: an
                 supportsEncrypt, supportsDecrypt,
                 supportsActivate, supportsRevoke,
                 supportsCreate, supportsDestroy,
-                supportsQuery, supportsSymmetricKeys });
+                supportsQuery, supportsSymmetricKeys,
+                kmip: kmipLog });
         } else {
             logger.info('KMIP Server provides the necessary feature set',
-                { vendorIdentification: client.vendorIdentification });
+                { vendorIdentification: client.vendorIdentification,
+                    kmip: kmipLog });
         }
         return cb();
     });
@@ -219,6 +242,7 @@ export default class Client implements KMSInterface {
     vendorIdentification: string;
     serverInformation: any[];
     kmip: KMIP;
+    host: string;
 
     /**
      * Construct a high level KMIP driver suitable for cloudserver
@@ -255,6 +279,7 @@ export default class Client implements KMSInterface {
         CodecClass: any,
         TransportClass: any,
     ) {
+        this.host = options.kmip.transport.tls.host;
         this.options = options.kmip.client || {};
         this.vendorIdentification = '';
         this.serverInformation = [];
@@ -567,20 +592,23 @@ export default class Client implements KMSInterface {
     }
 
     healthcheck(logger, cb) {
+        const kmipLog = { host: this.host };
         // the bucket does not have to exist, just passing a common bucket name here
         this.createBucketKey('kmip-healthcheck-test-bucket', logger, (err, bucketKeyId) => {
             if (err) {
                 logger.error('KMIP::healthcheck: failure to create a test bucket key', {
-                    error: err,
+                    error: err, kmip: kmipLog,
                 });
                 return cb(err);
             }
-            logger.debug('KMIP::healthcheck: success creating a test bucket key');
+            logger.debug('KMIP::healthcheck: success creating a test bucket key',
+                { kmip: kmipLog });
             this.destroyBucketKey(bucketKeyId, logger, err => {
                 if (err) {
                     logger.error('KMIP::healthcheck: failure to remove the test bucket key', {
                         bucketKeyId,
                         error: err,
+                        kmip: kmipLog,
                     });
                 }
             });

lib/network/kmip/index.ts

@@ -303,12 +303,18 @@ export default class KMIP {
                     KMIP.Structure('Request Payload', payload),
                 ])])]);
         const encodedMessage = this._encodeMessage(message);
+        const startDate = Date.now();
         this.transport.send(
             logger, encodedMessage,
             (err, conversation, rawResponse) => {
+                const kmipLog = {
+                    host: this.options.transport.tls.host,
+                    latencyMs: Date.now() - startDate,
+                    op: operation,
+                };
                 if (err) {
                     logger.error('KMIP::request: Failed to send message',
-                        { error: err });
+                        { error: err, kmip: kmipLog });
                     return cb(err);
                 }
                 const response = this._decodeMessage(logger, rawResponse);
@@ -327,7 +333,7 @@ export default class KMIP {
                     this.transport.abortPipeline(conversation);
                     const error = Error('Invalid batch item ID returned');
                     logger.error('KMIP::request: failed',
-                        { resultUniqueBatchItemID, uuid, error });
+                        { resultUniqueBatchItemID, uuid, error, kmip: kmipLog });
                     return cb(error);
                 }
                 if (performedOperation !== operation) {
@@ -338,7 +344,7 @@ export default class KMIP {
                         { got: performedOperation,
                             expected: operation });
                     logger.error('KMIP::request: Operation mismatch',
-                        { error });
+                        { error, kmip: kmipLog });
                     return cb(error);
                 }
                 if (resultStatus !== 'Success') {
@@ -356,9 +362,10 @@ export default class KMIP {
                             resultMessage });
                     logger.error('KMIP::request: request failed',
                         { error, resultStatus,
-                            resultReason, resultMessage });
+                            resultReason, resultMessage, kmip: kmipLog });
                     return cb(error);
                 }
+                logger.info('KMIP::success', { kmip: kmipLog });
                 return cb(null, response);
             });
     }