Merge pull request #83 from telefonicaid/hardening/correlator_for_tra…

…ceability

Add correlator for traceability

apiary.apib

@@ -35,12 +35,32 @@ http://forge.fiware.org/plugins/mediawiki/wiki/fiware/index.php/FI-WARE_NGSI-10_
     + id (required, string, `myEntityId`) ... Identifier of the entity being monitored.
     + type (required, string, `myEntityType`) ... Type of entity being monitored.
 
+
 + Request (text/plain)
 
-        PROCS OK: 150 processes
+    + Body
+
+            PROCS OK: 150 processes
 
 + Response 200 (text/plain)
 
+    + Headers
+
+            Fiware-Correlator: 76e0b070-8c5e-11e6-80d8-f3aa1c3a2ceb
+
+
++ Request (text/plain)
 
+    + Headers
+
+            Fiware-Correlator: custom-txid-0001234
+
+    + Body
+
+            PROCS OK: 150 processes
+
++ Response 200 (text/plain)
 
+    + Headers
 
+            Fiware-Correlator: custom-txid-0001234

doc/manuals/admin/logs.rst

@@ -30,9 +30,9 @@ by the pipe character (``|``). Example:
 
 ::
 
-    time=2015-08-01T08:00:00.511Z | lvl=INFO | trans=ci2627bx00000b42g8m2pxw3z | op=POST | msg=Request on resource /check_xxx with params id=xxx&type=xxx
-    time=2015-08-01T08:00:00.675Z | lvl=INFO | trans=ci2627bx00000b42g8m2pxw3z | op=POST | msg=Response status 200 OK
-    time=2015-08-01T08:00:00.922Z | lvl=INFO | trans=ci2627bx00000b42g8m2pxw3z | op=UpdateContext | msg=Request to ContextBroker at http://host:1026/...
+    time=2015-08-01T08:00:00.511Z | lvl=INFO | corr=7af94c40-8f9b-11e6-ae0c-97fdb974345e | trans=ci2627bx00000b42g8m2pxw3z | op=POST | msg=Request on resource /check_xxx with params id=xxx&type=xxx
+    time=2015-08-01T08:00:00.675Z | lvl=INFO | corr=7af94c40-8f9b-11e6-ae0c-97fdb974345e | trans=ci2627bx00000b42g8m2pxw3z | op=POST | msg=Response status 200 OK
+    time=2015-08-01T08:00:00.922Z | lvl=INFO | corr=7af94c40-8f9b-11e6-ae0c-97fdb974345e | trans=ci2627bx00000b42g8m2pxw3z | op=UpdateContext | msg=Request to ContextBroker at http://host:1026/...
 
 
 These are the different fields found in each line:
@@ -53,8 +53,14 @@ These are the different fields found in each line:
   * DEBUG: This level designates fine-grained informational events that are
     most useful to debug an application.
 
-- **trans (transaction id)**. Can be either "N/A" (for log messages "out of
-  transaction", as the ones corresponding to startup) or a unique string id.
+- **corr (correlator)**. Can be either "N/A" (in startup messages, for instance)
+  or a global unique identifier of each processed request within the whole
+  end-to-end environment. In services scenario, when a request is done, it
+  will normally go through several elements in which will be necessary to
+  trace the request without losing sight of the end-to-end process.
+
+- **trans (transaction id)**. Can be either "N/A" or a unique identifier of each
+  request processed within a specific element.
 
 - **op (operation)**. The function in the source code that generated the log
   message. This information is useful for developers only.

ngsi_adapter/.bumpversion.cfg

@@ -1,5 +1,5 @@
 [bumpversion]
-current_version = 1.5.0
+current_version = 2.0.0
 commit = True
 tag = False
 

ngsi_adapter/lib/adapter.js

@@ -33,7 +33,8 @@ var http = require('http'),
     url = require('url'),
     retry = require('retry'),
     domain = require('domain'),
-    cuid = require('cuid'),
+    uuid = require('node-uuid').v1,
+    txid = require('cuid'),
     logger = require('./logger'),
     common = require('./common'),
     config = require('./config'),
@@ -77,6 +78,8 @@ function updateContext(reqdomain, callback) {
                     responseBody += chunk;
                 });
                 response.on('end', function () {
+                    var context = logger.getContext();
+                    context.corr = response.headers[common.correlatorHttpHeader.toLowerCase()] || context.corr;
                     callback(null, response.statusCode, responseBody, responseType);
                 });
             });
@@ -131,7 +134,7 @@ function updateContextCallback(err, responseStatus, responseBody, responseConten
  *
  * - Request query string MUST include arguments `id` and `type`
  * - Request path will denote the name of the originating probe
- * - Request headers may include a transaction identifier ({@link common#txIdHttpHeader})
+ * - Request headers may include a correlation identifier ({@link common#correlatorHttpHeader})
  *
  * @param {http.IncomingMessage} request    The HTTP request to this server.
  * @param {http.ServerResponse}  response   The HTTP response from this server.
@@ -141,12 +144,15 @@ function asyncRequestListener(request, response) {
     reqdomain.add(request);
     reqdomain.add(response);
     reqdomain.context = {
-        trans: request.headers[common.txIdHttpHeader.toLowerCase()] || cuid(),
+        trans: txid(),
+        corr: request.headers[common.correlatorHttpHeader.toLowerCase()] || uuid(),
         op: request.method
     };
+    var responseHeaders = {};
+    responseHeaders[common.correlatorHttpHeader] = reqdomain.context.corr;
     reqdomain.on('error', function (err) {
         logger.error(err.message);
-        response.writeHead(500);  // server error
+        response.writeHead(500, responseHeaders);  // server error
         response.end();
     });
     reqdomain.run(function () {
@@ -179,7 +185,7 @@ function asyncRequestListener(request, response) {
             }
         }
         logger.info('Response status %d %s', status, http.STATUS_CODES[status]);
-        response.writeHead(status);
+        response.writeHead(status, responseHeaders);
         response.end();
     });
 }
@@ -196,7 +202,7 @@ function udpRequestListener(socket, message, parserName) {
     var reqdomain = domain.create();
     reqdomain.add(socket);
     reqdomain.context = {
-        trans: cuid(),
+        trans: txid(),
         op: 'UDP'
     };
     reqdomain.on('error', function (err) {

ngsi_adapter/lib/common.js

@@ -1,5 +1,5 @@
 /*
- * Copyright 2013 Telefónica I+D
+ * Copyright 2013-2016 Telefónica I+D
  * All Rights Reserved.
  *
  * Licensed under the Apache License, Version 2.0 (the "License"); you may
@@ -33,9 +33,9 @@ exports.timestampAttrName = '_timestamp';
 
 
 /**
- * HTTP header for transaction id.
+ * HTTP header for correlation in end-to-end operations.
  */
-exports.txIdHttpHeader = 'txId';
+exports.correlatorHttpHeader = 'Fiware-Correlator';
 
 
 /**

ngsi_adapter/lib/logger.js

@@ -41,7 +41,7 @@ logger.setLevel(config.logLevel);
  *
  * @return {Object} The context object.
  */
-logger.getContext = function() {
+logger.getContext = function () {
     return (domain.active) ? domain.active.context : {};
 };
 
@@ -58,11 +58,12 @@ logger.getContext = function() {
  */
 logger.format = (process.env.NODE_ENV === 'development') ?
     logger.format :
-    function(level, context, message, args) {
+    function (level, context, message, args) {
         args.unshift(
-            'time=%s | lvl=%s | trans=%s | op=%s | msg=' + message,
+            'time=%s | lvl=%s | corr=%s | trans=%s | op=%s | msg=' + message,
             (new Date()).toISOString(),
             level,
+            context.corr || 'n/a',
             context.trans || 'n/a',
             context.op || 'n/a'
         );

ngsi_adapter/lib/parsers/common/base.js

@@ -96,8 +96,8 @@ baseParser.getUpdateRequest = function (reqdomain) {
             }
         };
 
-    // add transaction id
-    requestOptions.headers[common.txIdHttpHeader] = reqdomain.context.trans;
+    // add correlator
+    requestOptions.headers[common.correlatorHttpHeader] = reqdomain.context.corr;
 
     // add options to `reqdomain` and return request body
     reqdomain.options = requestOptions;

ngsi_adapter/package.json

@@ -1,5 +1,5 @@
 {
-  "version": "1.5.0",
+  "version": "2.0.0",
   "name": "ngsi_adapter",
   "description": "Generic NGSI Probe Adapter",
   "product": {
@@ -35,6 +35,7 @@
     "optimist": ">=0.6.0",
     "retry": ">=0.6.0",
     "cuid": "~1.2.4",
+    "node-uuid": "~1.4.7",
     "username": "~2.2.2"
   },
   "devDependencies": {

ngsi_adapter/test/acceptance/commons/constants.py

@@ -32,7 +32,7 @@
 HEADER_REPRESENTATION_TEXTPLAIN = u'text/plain'
 HEADER_AUTH_TOKEN = u'X-Auth-Token'
 HEADER_TENANT_ID = u'Tenant-Id'
-HEADER_TRANSACTION_ID = u'txid'
+HEADER_CORRELATOR = u'Fiware-Correlator'
 
 # HTTP VERBS
 HTTP_VERB_POST = 'post'
@@ -41,8 +41,8 @@
 HTTP_VERB_DELETE = 'delete'
 HTTP_VERB_UPDATE = 'update'
 
-# TRANSACTION ID
-TRANSACTION_ID_PATTERN = "qa/{uuid}"
+# CORRELATOR
+CORRELATOR_PATTERN = "qa/{uuid}"
 
 # NGSI CLIENT
 NGSI_ADAPTER_URI_BASE = "{api_root_url}"

ngsi_adapter/test/acceptance/commons/ngsi_adapter_api_utils/ngsi_adapter_client.py

@@ -25,9 +25,8 @@
 
 
 from commons.rest_client_utils import RestClient, API_ROOT_URL_ARG_NAME
-from commons.constants import HEADER_REPRESENTATION_TEXTPLAIN, HEADER_CONTENT_TYPE, HEADER_TRANSACTION_ID, \
-    HTTP_VERB_POST
-from commons.utils import generate_transaction_id
+from commons.constants import HEADER_REPRESENTATION_TEXTPLAIN, HEADER_CONTENT_TYPE, HEADER_CORRELATOR, HTTP_VERB_POST
+from commons.utils import generate_correlator
 from commons.logger_utils import get_logger
 
 NGSI_ADAPTER_URI_BASE = "{" + API_ROOT_URL_ARG_NAME + "}"
@@ -55,11 +54,11 @@ def __init__(self, protocol, host, port, base_resource=None):
         self.init_headers()
         self.rest_client = RestClient(protocol, host, port, base_resource)
 
-    def init_headers(self, content_type=HEADER_REPRESENTATION_TEXTPLAIN, transaction_id=generate_transaction_id()):
+    def init_headers(self, content_type=HEADER_REPRESENTATION_TEXTPLAIN, correlator=generate_correlator()):
         """
         Init header to values (or default values)
         :param content_type: Content-Type header value. By default text/plain
-        :param transaction_id: txId header value. By default, generated value by Utils.generate_transaction_id()
+        :param correlator: correlator header value. By default, generated value by utils.generate_correlator()
         :return: None
         """
 
@@ -69,11 +68,11 @@ def init_headers(self, content_type=HEADER_REPRESENTATION_TEXTPLAIN, transaction
         else:
             self.headers.update({HEADER_CONTENT_TYPE: content_type})
 
-        if transaction_id is None:
-            if HEADER_TRANSACTION_ID in self.headers:
-                del(self.headers[HEADER_TRANSACTION_ID])
+        if correlator is None:
+            if HEADER_CORRELATOR in self.headers:
+                del(self.headers[HEADER_CORRELATOR])
         else:
-            self.headers.update({HEADER_TRANSACTION_ID: transaction_id})
+            self.headers.update({HEADER_CORRELATOR: correlator})
 
     def set_headers(self, headers):
         """

ngsi_adapter/test/acceptance/commons/utils.py

@@ -27,25 +27,25 @@
 import uuid
 from pkg_resources import resource_string
 from logger_utils import get_logger
-from constants import TRANSACTION_ID_PATTERN, RESOURCES_SAMPLEDATA_MODULE, RESOURCES_PARAMETER_PATTERN
+from constants import CORRELATOR_PATTERN, RESOURCES_SAMPLEDATA_MODULE, RESOURCES_PARAMETER_PATTERN
 
 logger = get_logger("utils")
 
 
-def generate_transaction_id():
+def generate_correlator():
     """
-    Generate a transaction ID value following defined pattern.
-    :return: New transactionId
+    Generate a correlator value following defined pattern.
+    :return: New correlator
     """
 
-    return TRANSACTION_ID_PATTERN.format(uuid=uuid.uuid4())
+    return CORRELATOR_PATTERN.format(uuid=uuid.uuid4())
 
 
 def get_probe_data_from_resource_file(filename, replacement_values=None):
     """
     Get probe data from resource files. If replacement_values is not empty,
     :param filename: Resource filename to be used for loading probe data
-    :param param_values: (key, value) pairs. (list of dict)
+    :param replacement_values: (key, value) pairs. (list of dict)
     :return: File content with param value replacements
     """
 

ngsi_adapter/test/acceptance/features/component/send_data/send_data_api_resource.feature

@@ -2,7 +2,7 @@
 Feature: Sending probe data
   As a monitoring element (probe) user
   I want to be able to transform monitoring data from probes to NGSI context attributes
-  so that I can constantly check the status and performance of the cloud infrastructure using NGSI Context Broker.
+  so that I can constantly check the status and performance of the cloud infrastructure using Context Broker.
 
 
   @happy_path
@@ -130,16 +130,16 @@ Feature: Sending probe data
     | delete    |
 
 
-  Scenario Outline: NGSI-Adapter reuse the transaction-id header value given in the request
+  Scenario Outline: NGSI Adapter reuse the correlator header value given in the request
     Given the probe name "qa_probe"
     And   the monitored resource with id "qa:1234567890" and type "host"
-    And   the header Transaction-Id "<transaction_id>"
+    And   the header Correlator "<correlator>"
     When  I send raw data according to the selected probe
     Then  the response status code is "200"
-    And   the given Transaction-Id value is used in logs
+    And   the given Correlator value is used in logs
 
     Examples:
-    | transaction_id      |
+    | correlator          |
     | 1                   |
     | 1231asdfgasd        |
     | a/12345.qa          |

ngsi_adapter/test/acceptance/features/component/send_data/steps.py

@@ -93,15 +93,15 @@ def the_response_status_code_is(step, status_code):
     assert_equal(str(world.response.status_code), status_code)
 
 
-@step(u'the header Transaction-Id "(.*)"$')
-def the_header_transaction_id(step, transaction_id):
-    world.transaction_id = prepare_param(transaction_id)
-    world.ngsi_adapter_client.init_headers(transaction_id=world.transaction_id)
+@step(u'the header Correlator "(.*)"$')
+def the_header_correlator(step, correlator):
+    world.correlator = prepare_param(correlator)
+    world.ngsi_adapter_client.init_headers(correlator=world.correlator)
 
 
 @step(u'an auto-generated Transaction-Id value is used in logs')
-@step(u'the given Transaction-Id value is used in logs')
-def the_given_transaction_id_value_is_used_in_logs(step):
+@step(u'the given Correlator value is used in logs')
+def the_given_correlator_value_is_used_in_logs(step):
     log_utils = LogUtils()
 
     remote_log_local_path = world.config[PROPERTIES_CONFIG_ENV][PROPERTIES_CONFIG_ENV_LOCAL_PATH_REMOTE_LOGS]
@@ -110,14 +110,14 @@ def the_given_transaction_id_value_is_used_in_logs(step):
     # Wait for remote logging
     time.sleep(WAIT_FOR_REMOTE_LOGGING)
 
-    if world.transaction_id is not None and len(world.transaction_id) != 0:
-        log_value_transaction_id = {"TRANSACTION_ID": "trans={transaction_id}".format(
-            transaction_id=world.transaction_id)}
-        log_utils.search_in_log(remote_log_local_path, service_log_file_name, log_value_transaction_id)
+    if world.correlator is not None and len(world.correlator) != 0:
+        log_value_correlator = {"CORRELATOR": "corr={correlator}".format(
+            correlator=world.correlator)}
+        log_utils.search_in_log(remote_log_local_path, service_log_file_name, log_value_correlator)
     else:
         log_value_message = {"MESSAGE": "msg={probe}".format(probe=world.probe)}
         log_line = log_utils.search_in_log(remote_log_local_path, service_log_file_name, log_value_message)
 
-        transaction_id = log_line[log_utils.LOG_TAG["TRANSACTION_ID"].replace("=", "")]
-        assert_true(len(transaction_id) != 0,
-                    "Transaction-ID not found in logs. Expected value. Value in logs: " + transaction_id)
+        correlator = log_line[log_utils.LOG_TAG["CORRELATOR"].replace("=", "")]
+        assert_true(len(correlator) != 0,
+                    "Correlator not found in logs. Expected value. Value in logs: " + correlator)

ngsi_adapter/test/unit/common.js

@@ -26,7 +26,8 @@
 'use strict';
 
 
-var cuid = require('cuid'),
+var uuid = require('node-uuid').v1,
+    txid = require('cuid'),
     assert = require('assert'),
     timestampAttrName = require('../../lib/common').timestampAttrName;
 
@@ -81,10 +82,13 @@ function assertValidUpdateJSON(updateJSON, testSuite) {
  */
 function domain(testSuite) {
     return {
-        context: {trans: cuid()},
         timestamp: Date.now(),
         entityId: testSuite.entityId,
-        entityType: testSuite.entityType
+        entityType: testSuite.entityType,
+        context: {
+            corr: uuid(),
+            trans: txid()
+        }
     };
 }