Implement the EELF metrics format

Change-Id: If7c10aad141f5e4600652e485dcd3851e364b1ac
Issue-ID: DCAEGEN2-387
Signed-off-by: Tommy Carpenter <tommy@research.att.com>

6 files changed, 100 insertions, 16 deletions

diff --git a/Changelog.md b/Changelog.md
index eae83cc..ac2ea37 100644
--- a/Changelog.md
+++ b/Changelog.md
@@ -4,6 +4,9 @@ All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](http://keepachangelog.com/)
 and this project adheres to [Semantic Versioning](http://semver.org/).
 
+## [2.1.4] - 4/3/2018
+* Adhere to EELF metrics log for the log file
+
 ## [2.1.3]
 * Small cleanups; move swagger, remove bin, do proper install in Dockerfile
 
diff --git a/config_binding_service/controller.py b/config_binding_service/controller.py
index 68ac1ac..ec1fb86 100644
--- a/config_binding_service/controller.py
+++ b/config_binding_service/controller.py
@@ -18,16 +18,17 @@
 
 import json
 import requests
+import connexion
+import uuid
 from flask import Response
 from config_binding_service import client, get_consul_uri
-from config_binding_service.logging import LOGGER
+from config_binding_service.logging import LOGGER, audit, utc
 
 
 def _get_helper(json_expecting_func, **kwargs):
     """
     Helper function used by several functions below
     """
-    print(kwargs)
     try:
         payload = json_expecting_func(**kwargs)
         response, status_code, mimetype = json.dumps(payload), 200, "application/json"
@@ -41,22 +42,41 @@ def _get_helper(json_expecting_func, **kwargs):
     return response, status_code, mimetype
 
 
+def _get_or_generate_xer(raw_request):
+    """get or generate the transaction id"""
+    rid = raw_request.headers.get("x-onap-requestid", None)
+    if rid is None:
+        # some components are still using the old name
+        rid = raw_request.headers.get("x-ecomp-requestid", None)
+        if rid is None:
+            # the user did NOT supply a request id, generate one
+            rid = str(uuid.uuid4())
+    return rid
+
+
 def bind_all(service_component_name):
     """
     Get all the keys in Consul for this SCN, and bind the config
     """
+    rid = _get_or_generate_xer(connexion.request)
+    bts = utc()
     response, status_code, mimetype = _get_helper(client.resolve_all, service_component_name=service_component_name)
-    LOGGER.info("bind_all called for %s, returned code %d", service_component_name, status_code)
-    return Response(response=response, status=status_code, mimetype=mimetype)
+    audit(connexion.request, bts, rid, status_code, __name__)
+    # Even though some older components might be using the ecomp name, we return the proper one
+    return Response(response=response, status=status_code, mimetype=mimetype, headers={"x-onap-requestid": rid})
 
 
 def bind_config_for_scn(service_component_name):
     """
     Bind just the config for this SCN
     """
+    print(connexion)
+    print(connexion.request)
+    rid = _get_or_generate_xer(connexion.request)
+    bts = utc()
     response, status_code, mimetype = _get_helper(client.resolve, service_component_name=service_component_name)
-    LOGGER.info("bind_config_for_scn called for %s, returned code %d", service_component_name, status_code)
-    return Response(response=response, status=status_code, mimetype=mimetype)
+    audit(connexion.request, bts, rid, status_code, __name__)
+    return Response(response=response, status=status_code, mimetype=mimetype, headers={"x-onap-requestid": rid})
 
 
 def get_key(key, service_component_name):
@@ -64,9 +84,11 @@ def get_key(key, service_component_name):
     Get a single key k of the form service_component_name:k from Consul.
     Should not be used and will return a BAD REQUEST for k=policies because it's a complex object
     """
+    rid = _get_or_generate_xer(connexion.request)
+    bts = utc()
     response, status_code, mimetype = _get_helper(client.get_key, key=key, service_component_name=service_component_name)
-    LOGGER.info("get_key called for %s, returned code %d", service_component_name, status_code)
-    return Response(response=response, status=status_code, mimetype=mimetype)
+    audit(connexion.request, bts, rid, status_code, __name__)
+    return Response(response=response, status=status_code, mimetype=mimetype, headers={"x-onap-requestid": rid})
 
 
 def healthcheck():
diff --git a/config_binding_service/logging.py b/config_binding_service/logging.py
index e66851d..edd8c1f 100644
--- a/config_binding_service/logging.py
+++ b/config_binding_service/logging.py
@@ -19,6 +19,7 @@
 from logging import getLogger, StreamHandler, Formatter
 from logging.handlers import RotatingFileHandler
 from os import makedirs
+import datetime
 
 
 LOGGER = getLogger("defaultlogger")
@@ -26,19 +27,17 @@ LOGGER = getLogger("defaultlogger")
 
 def _create_logger(name, logfile):
     """
-    Create a RotatingFileHandker
+    Create a RotatingFileHandler and a streamhandler for stdout
     https://docs.python.org/3/library/logging.handlers.html
     what's with the non-pythonic naming in these stdlib methods? Shameful.
     """
     logger = getLogger(name)
     file_handler = RotatingFileHandler(logfile,
                                        maxBytes=10000000, backupCount=2)  # 10 meg with one backup..
-    file_formatter = Formatter('%(asctime)s | %(name)s | %(module)s | %(funcName)s | %(lineno)d |  %(levelname)s | %(message)s')  # right now the same, but intending to change
-    file_handler.setFormatter(file_formatter)
-
+    formatter = Formatter('%(message)s')
+    file_handler.setFormatter(formatter)
     stream_handler = StreamHandler()
-    stream_formatter = Formatter('%(asctime)s | %(name)s | %(module)s | %(funcName)s | %(lineno)d |  %(levelname)s | %(message)s')
-    stream_handler.setFormatter(stream_formatter)
+    stream_handler.setFormatter(formatter)
     logger.setLevel("DEBUG")  # a function is going to wrap this anyway
     logger.addHandler(file_handler)
     logger.addHandler(stream_handler)
@@ -54,3 +53,42 @@ def create_logger():
     open(LOGFILE, 'a').close()  # this is like "touch"
     global LOGGER
     LOGGER = _create_logger("config_binding_service", LOGFILE)
+
+
+def utc():
+    """gets current time in utc"""
+    return datetime.datetime.utcnow()
+
+
+def audit(raw_request, bts, xer, rcode, calling_mod, msg="n/a"):
+    """
+    write an EELF audit record per https://wiki.onap.org/download/attachments/1015849/ONAP%20application%20logging%20guidelines.pdf?api=v2
+    %The audit fields implemented:
+
+    1 BeginTimestamp                    Implemented (bts)
+    2 EndTimestamp                      Auto Injected when this is called
+    3 RequestID                         Implemented (xer)
+    7 serviceName                       Implemented (from Req)
+    9 StatusCode                        Auto injected based on rcode
+    10 ResponseCode                     Implemented (rcode)
+    15 Server IP address                Implemented (from Req)
+    16 ElapsedTime                      Auto Injected (milliseconds)
+    18 ClientIPaddress                  Implemented (from Req)
+    19 class name                       Implemented (mod), though docs say OOP, I am using the python  module here
+    20 Unused                           ...implemented....
+    21-25 Custom                        n/a
+    26 detailMessage                    Implemented (msg)
+    """
+    ets = utc()
+
+    LOGGER.info("{bts}|{ets}|{xer}||||{path}||{status}|{rcode}|||||{servip}|{et}||{clientip}|{calling_mod}|||||||{msg}".format(
+        bts=bts.isoformat(),
+        ets=ets.isoformat(),
+        xer=xer, rcode=rcode,
+        path=raw_request.path.split("/")[1],
+        status="COMPLETE" if rcode == 200 else "ERROR",
+        servip=raw_request.host.split(":")[0],
+        et=int((ets - bts).microseconds / 1000),  # supposed to be in milleseconds
+        clientip=raw_request.remote_addr,
+        calling_mod=calling_mod, msg=msg
+    ))
diff --git a/pom.xml b/pom.xml
index 43ea442..f4f63e3 100644
--- a/pom.xml
+++ b/pom.xml
@@ -29,7 +29,7 @@ ECOMP is a trademark and service mark of AT&T Intellectual Property.
   <groupId>org.onap.dcaegen2.platform</groupId>
   <artifactId>configbinding</artifactId>
   <name>dcaegen2-platform-configbinding</name>
-  <version>2.1.3</version>
+  <version>2.1.4</version>
   <url>http://maven.apache.org</url>
   <properties>
     <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
diff --git a/setup.py b/setup.py
index 35aed26..5e7d49c 100644
--- a/setup.py
+++ b/setup.py
@@ -20,7 +20,7 @@ from setuptools import setup, find_packages
 
 setup(
     name='config_binding_service',
-    version='2.1.3',
+    version='2.1.4',
     packages=find_packages(exclude=["tests.*", "tests"]),
     author="Tommy Carpenter",
     author_email="tommy@research.att.com",
diff --git a/tests/test_binding.py b/tests/test_binding.py
index 94ee1cb..27d4c1b 100644
--- a/tests/test_binding.py
+++ b/tests/test_binding.py
@@ -27,6 +27,14 @@ from config_binding_service import client, controller
 #####
 
 
+class FakeConnexion(object):
+    def __init__(self, headers, path, host, remote_addr):
+        self.headers = headers
+        self.path = path
+        self.host = host
+        self.remote_addr = remote_addr
+
+
 def monkeyed_get_connection_info_from_consul(service_component_name):
     # shared monkeypatch. probably somewhat lazy because the function htis patches can be broken up.
     if service_component_name == "cdap":
@@ -107,6 +115,7 @@ def test_get_config_rels_dmaap(monkeypatch):
 
 def test_bind_config_for_scn(monkeypatch):
     monkeypatch.setattr('requests.put', monkeyed_requests_put)
+    monkeypatch.setattr('connexion.request', FakeConnexion({"x-onap-requestid": 123456789}, "/service_component", "mytestingmachine", "myremoteclient"))
 
     assert(client.resolve("scn_exists") == {"foo3": "bar3"})
     with pytest.raises(client.CantGetConfig):
@@ -115,12 +124,15 @@ def test_bind_config_for_scn(monkeypatch):
     R = controller.bind_config_for_scn("scn_exists")
     assert(json.loads(R.data) == {"foo3": "bar3"})
     assert(R.status_code == 200)
+    assert(R.headers["x-onap-requestid"] == "123456789")
 
     R = controller.bind_config_for_scn("scn_NOTexists")
     assert(R.status_code == 404)
+    assert(R.headers["x-onap-requestid"] == "123456789")
 
     R = controller.bind_config_for_scn("asdfasdf")
     assert(R.status_code == 500)
+    assert(R.headers["x-onap-requestid"] == "123456789")
 
 
 def test_generic(monkeypatch):
@@ -132,18 +144,23 @@ def test_generic(monkeypatch):
         client.get_key(
             "nokeyforyou", "test_service_component_name.unknown.unknown.unknown.dcae.onap.org")
 
+    monkeypatch.setattr('connexion.request', FakeConnexion({}, "/get_key", "mytestingmachine", "myremoteclient"))
+
     R = controller.get_key(
         "dti", "test_service_component_name.unknown.unknown.unknown.dcae.onap.org")
     assert(json.loads(R.data) == {"my": "dti"})
     assert(R.status_code == 200)
+    assert "x-onap-requestid" in R.headers
 
     R = controller.get_key(
         "nokeyforyou", "test_service_component_name.unknown.unknown.unknown.dcae.onap.org")
     assert(R.status_code == 404)
+    assert "x-onap-requestid" in R.headers
 
     R = controller.get_key(
         "policies", "test_service_component_name.unknown.unknown.unknown.dcae.onap.org")
     assert(R.status_code == 400)
+    assert "x-onap-requestid" in R.headers
 
 
 def test_bad_config_http():
@@ -300,10 +317,13 @@ def test_resolve_all(monkeypatch):
     allk = client.resolve_all("test_resolve_scn")
     assert allk == {"config": expected_config}
 
+    monkeypatch.setattr('connexion.request', FakeConnexion({}, "/service_component_all", "mytestingmachine", "myremoteclient"))
+
     R = controller.bind_all(
         "test_service_component_name.unknown.unknown.unknown.dcae.onap.org")
     assert(json.loads(R.data) == withstuff)
     assert(R.status_code == 200)
+    assert "x-onap-requestid" in R.headers
 
     R = controller.bind_all("test_resolve_scn")
     assert(json.loads(R.data) == {"config": expected_config})
@@ -311,6 +331,7 @@ def test_resolve_all(monkeypatch):
 
     R = controller.bind_all("scn_NOTexists")
     assert(R.status_code == 404)
+    assert "x-onap-requestid" in R.headers
 
     R = controller.bind_all("asdfasdf")
     assert(R.status_code == 500)