Implement the EELF metrics format

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

2 files changed, 74 insertions, 14 deletions

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
+    ))