Bugfixes, add EELF error log func

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

4 files changed, 95 insertions, 54 deletions

diff --git a/app/app/config_binding_service/controller.py b/app/app/config_binding_service/controller.py
index ec1fb86..acd9447 100644
--- a/app/app/config_binding_service/controller.py
+++ b/app/app/config_binding_service/controller.py
@@ -22,7 +22,7 @@ import connexion
 import uuid
 from flask import Response
 from config_binding_service import client, get_consul_uri
-from config_binding_service.logging import LOGGER, audit, utc
+from config_binding_service.logging import audit, utc, error
 
 
 def _get_helper(json_expecting_func, **kwargs):
@@ -37,46 +37,43 @@ def _get_helper(json_expecting_func, **kwargs):
     except client.CantGetConfig as exc:
         response, status_code, mimetype = exc.response, exc.code, "text/plain"
     except Exception as exc:
-        LOGGER.error(exc)
-        response, status_code, mimetype = "Unknown error, please report", 500, "text/plain"
+        response, status_code, mimetype = "Unknown error", 500, "text/plain"
     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:
+    xer = raw_request.headers.get("x-onap-requestid", None)
+    if xer is None:
         # some components are still using the old name
-        rid = raw_request.headers.get("x-ecomp-requestid", None)
-        if rid is None:
+        xer = raw_request.headers.get("x-ecomp-requestid", None)
+        if xer is None:
             # the user did NOT supply a request id, generate one
-            rid = str(uuid.uuid4())
-    return rid
+            xer = str(uuid.uuid4())
+    return xer
 
 
 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)
+    xer = _get_or_generate_xer(connexion.request)
     bts = utc()
     response, status_code, mimetype = _get_helper(client.resolve_all, service_component_name=service_component_name)
-    audit(connexion.request, bts, rid, status_code, __name__)
+    audit(connexion.request, bts, xer, status_code, __name__, "called for component {0}".format(service_component_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})
+    return Response(response=response, status=status_code, mimetype=mimetype, headers={"x-onap-requestid": xer})
 
 
 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)
+    xer = _get_or_generate_xer(connexion.request)
     bts = utc()
     response, status_code, mimetype = _get_helper(client.resolve, service_component_name=service_component_name)
-    audit(connexion.request, bts, rid, status_code, __name__)
-    return Response(response=response, status=status_code, mimetype=mimetype, headers={"x-onap-requestid": rid})
+    audit(connexion.request, bts, xer, status_code, __name__, "called for component {0}".format(service_component_name))
+    return Response(response=response, status=status_code, mimetype=mimetype, headers={"x-onap-requestid": xer})
 
 
 def get_key(key, service_component_name):
@@ -84,22 +81,26 @@ 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)
+    xer = _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)
-    audit(connexion.request, bts, rid, status_code, __name__)
-    return Response(response=response, status=status_code, mimetype=mimetype, headers={"x-onap-requestid": rid})
+    audit(connexion.request, bts, xer, status_code, __name__, "called for component {0}".format(service_component_name))
+    return Response(response=response, status=status_code, mimetype=mimetype, headers={"x-onap-requestid": xer})
 
 
 def healthcheck():
     """
     CBS Healthcheck
     """
-    LOGGER.info("healthcheck called")
-    res = requests.get(
-        "{0}/v1/catalog/service/config_binding_service".format(get_consul_uri()))
-    if res.status_code == 200:
-        return Response(response="CBS is alive and Consul connection OK",
-                        status=200)
-    return Response(response="CBS is alive but cannot reach Consul",
-                    status=503)
+    xer = _get_or_generate_xer(connexion.request)
+    bts = utc()
+    res = requests.get("{0}/v1/catalog/service/config_binding_service".format(get_consul_uri()))
+    status = res.status_code
+    if status == 200:
+        response = "CBS is alive and Consul connection OK"
+    else:
+        response = "CBS is alive but cannot reach Consul"
+        # treating this as a WARN because this could be a temporary network glitch. Also per EELF guidelines this is a 200 ecode (availability)
+        error(connexion.request, xer, "WARN", 200, tgt_entity="Consul", tgt_path="/v1/catalog/service/config_binding_service", msg=response)
+    audit(connexion.request, bts, xer, status, __name__, msg=response)
+    return Response(response=response, status=status)
diff --git a/app/app/config_binding_service/logging.py b/app/app/config_binding_service/logging.py
index f5cd6af..7966e2f 100644
--- a/app/app/config_binding_service/logging.py
+++ b/app/app/config_binding_service/logging.py
@@ -16,13 +16,15 @@
 #
 # ECOMP is a trademark and service mark of AT&T Intellectual Property.
 
-from logging import getLogger, StreamHandler, Formatter
+from logging import getLogger, Formatter
 from logging.handlers import RotatingFileHandler
 from os import makedirs
 import datetime
 
 
 LOGGER = getLogger("defaultlogger")
+_AUDIT_LOGGER = getLogger("defaultlogger")
+_ERROR_LOGGER = getLogger("defaultlogger")
 
 
 def _create_logger(name, logfile):
@@ -36,23 +38,28 @@ def _create_logger(name, logfile):
                                        maxBytes=10000000, backupCount=2)  # 10 meg with one backup..
     formatter = Formatter('%(message)s')
     file_handler.setFormatter(formatter)
-    stream_handler = StreamHandler()
-    stream_handler.setFormatter(formatter)
     logger.setLevel("DEBUG")
     logger.addHandler(file_handler)
-    logger.addHandler(stream_handler)
     return logger
 
 
-def create_logger():
+def create_loggers():
     """
     Public method to set the global logger, launched from Run
     """
-    LOGFILE = "/opt/logs/log.log"
     makedirs("/opt/logs", exist_ok=True)
-    open(LOGFILE, 'a').close()  # this is like "touch"
-    global LOGGER
-    LOGGER = _create_logger("config_binding_service", LOGFILE)
+
+    # create the audit log
+    aud_file = "/opt/logs/audit.log"
+    open(aud_file, 'a').close()  # this is like "touch"
+    global _AUDIT_LOGGER
+    _AUDIT_LOGGER = _create_logger("config_binding_service_audit", aud_file)
+
+    # create the error log
+    err_file = "/opt/logs/error.log"
+    open(err_file, 'a').close()  # this is like "touch"
+    global _ERROR_LOGGER
+    _ERROR_LOGGER = _create_logger("config_binding_service_error", err_file)
 
 
 def utc():
@@ -65,23 +72,23 @@ 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)
+    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(
+    _AUDIT_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,
@@ -92,3 +99,36 @@ def audit(raw_request, bts, xer, rcode, calling_mod, msg="n/a"):
         clientip=raw_request.remote_addr,
         calling_mod=calling_mod, msg=msg
     ))
+
+
+def error(raw_request, xer, severity, ecode, tgt_entity="n/a", tgt_path="n/a", msg="n/a", adv_msg="n/a"):
+    """
+    write an EELF error record per
+    the error fields implemented:
+
+    1 Timestamp          Auto Injected when this is called
+    2 RequestID          Implemented (xer)
+    4 ServiceName        Implemented (from Req)
+    6 TargetEntity       Implemented (tgt_entity)
+    7 TargetServiceName Implemented (tgt_path)/
+    8 ErrorCategory      Implemented (severity)
+    9. ErrorCode         Implemented (ecode)
+    10 ErrorDescription  Implemented (msg)
+    11. detailMessage    Implemented (adv_msg)
+
+    Not implemented:
+    3 ThreadID - n/a
+    5 PartnerName - nothing in the request tells me this
+    """
+    ets = utc()
+
+    _ERROR_LOGGER.error("{ets}|{xer}||{path}||{tge}|{tgp}|{sev}|{ecode}|{msg}|{amsg}".format(
+        ets=ets,
+        xer=xer,
+        path=raw_request.path.split("/")[1],
+        tge=tgt_entity,
+        tgp=tgt_path,
+        sev=severity,
+        ecode=ecode,
+        msg=msg,
+        amsg=adv_msg))
diff --git a/app/app/main.py b/app/app/main.py
index 6cedc4d..dd71ccf 100755
--- a/app/app/main.py
+++ b/app/app/main.py
@@ -19,11 +19,11 @@
 # ECOMP is a trademark and service mark of AT&T Intellectual Property.
 
 import connexion
-from config_binding_service.logging import create_logger
+from config_binding_service.logging import create_loggers
 
 # Entrypoint When in uwsgi
 # This create logger call used to be in the main block, but when moving to NGINX+uwsgi, this had to change. See https://hub.docker.com/r/tiangolo/uwsgi-nginx-flask/
-create_logger()
+create_loggers()
 app = connexion.App(__name__, specification_dir='.')
 app.add_api('swagger.yaml', arguments={'title': 'Config Binding Service'})
 
diff --git a/app/app/setup.py b/app/app/setup.py
index df59069..7b8c7ca 100644
--- a/app/app/setup.py
+++ b/app/app/setup.py
@@ -20,7 +20,7 @@ from setuptools import setup, find_packages
 
 setup(
     name='config_binding_service',
-    version='2.2.0',
+    version='2.2.1',
     packages=find_packages(exclude=["tests.*", "tests"]),
     author="Tommy Carpenter",
     author_email="tommy@research.att.com",