Implement logging that can get to ELK

This adds more logging into the front end, and also logs to a file so
ELK can get them.
All public calls to the CBS are logged with the return code.
This is not to say logging is completed in the CBS, more may come later
and under a more structured format.

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

4 files changed, 108 insertions, 73 deletions

diff --git a/config_binding_service/__init__.py b/config_binding_service/__init__.py
index 2835511..5a6b081 100644
--- a/config_binding_service/__init__.py
+++ b/config_binding_service/__init__.py
@@ -17,17 +17,6 @@
 # ECOMP is a trademark and service mark of AT&T Intellectual Property.
 
 import os
-import logging
-
-# Configures the module root logger
-root = logging.getLogger()
-if root.handlers:
-    root.handlers.clear()
-formatter = logging.Formatter('%(asctime)s | %(name)s | %(module)s | %(funcName)s | %(lineno)d |  %(levelname)s | %(message)s')
-handler = logging.StreamHandler()
-handler.setFormatter(formatter)
-root.addHandler(handler)
-root.setLevel("DEBUG")
 
 
 class BadEnviornmentENVNotFound(Exception):
@@ -37,11 +26,6 @@ class BadEnviornmentENVNotFound(Exception):
     pass
 
 
-def get_logger(module=None):
-    '''Returns a module-specific logger or global logger if the module is None'''
-    return root if module is None else root.getChild(module)
-
-
 def get_consul_uri():
     """
     This method waterfalls reads an envioronmental variable called CONSUL_HOST
diff --git a/config_binding_service/client.py b/config_binding_service/client.py
index 2c04684..51ce3b1 100644
--- a/config_binding_service/client.py
+++ b/config_binding_service/client.py
@@ -23,9 +23,10 @@ import copy
 import json
 import requests
 import six
-from config_binding_service import get_consul_uri, get_logger
+from config_binding_service import get_consul_uri
+from config_binding_service.logging import LOGGER
+
 
-_logger = get_logger(__name__)
 CONSUL = get_consul_uri()
 
 template_match_rels = re.compile("\{{2}([^\}\{]*)\}{2}")
@@ -111,23 +112,20 @@ def _get_connection_info_from_consul(service_component_name):
     TODO: WARNING: FIXTHIS: CALLINTHENATIONALARMY:
     This tries to determine that a service_component_name is a cdap application by inspecting service_component_name and name munging. However, this would force all CDAP applications to have cdap_app in their name. A much better way to do this is to do some kind of catalog_lookup here, OR MAYBE change this API so that the component_type is passed in somehow. THis is a gaping TODO.
     """
-    _logger.info("Retrieving connection information for {0}".format(
-        service_component_name))
+    LOGGER.info("Retrieving connection information for %s", service_component_name)
     res = requests.get(
         "{0}/v1/catalog/service/{1}".format(CONSUL, service_component_name))
     res.raise_for_status()
     services = res.json()
     if services == []:
-        _logger.info("Warning: config and rels keys were both valid, but there is no component named {0} registered in Consul!".format(
-            service_component_name))
+        LOGGER.info("Warning: config and rels keys were both valid, but there is no component named %s registered in Consul!", service_component_name)
         return None  # later will get filtered out
     ip_addr = services[0]["ServiceAddress"]
     port = services[0]["ServicePort"]
     if "cdap_app" in service_component_name:
         redirectish_url = "http://{0}:{1}/application/{2}".format(
             ip_addr, port, service_component_name)
-        _logger.info("component is a CDAP application; trying the broker redirect on {0}".format(
-            redirectish_url))
+        LOGGER.info("component is a CDAP application; trying the broker redirect on %s", redirectish_url)
         res = requests.get(redirectish_url)
         res.raise_for_status()
         details = res.json()
diff --git a/config_binding_service/controller.py b/config_binding_service/controller.py
index 7bb5f51..68ac1ac 100644
--- a/config_binding_service/controller.py
+++ b/config_binding_service/controller.py
@@ -16,71 +16,68 @@
 #
 # ECOMP is a trademark and service mark of AT&T Intellectual Property.
 
+import json
 import requests
 from flask import Response
-import json
-from config_binding_service import client, get_consul_uri, get_logger
+from config_binding_service import client, get_consul_uri
+from config_binding_service.logging import LOGGER
+
 
-_logger = get_logger(__name__)
+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"
+    except client.BadRequest as exc:
+        response, status_code, mimetype = exc.response, exc.code, "text/plain"
+    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"
+    return response, status_code, mimetype
 
 
 def bind_all(service_component_name):
-    try:
-        allk = client.resolve_all(service_component_name)
-        return Response(response=json.dumps(allk),
-                        status=200,
-                        mimetype="application/json")
-    except client.CantGetConfig as e:
-        return Response(status=e.code,
-                        response=e.response)
-    except Exception as e:
-        _logger.error(e)
-        return Response(response="Unknown error:  please report",
-                        status=500)
+    """
+    Get all the keys in Consul for this SCN, and bind the config
+    """
+    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)
 
 
 def bind_config_for_scn(service_component_name):
-    try:
-        bound = client.resolve(service_component_name)
-        return Response(response=json.dumps(bound),
-                        status=200,
-                        mimetype="application/json")
-    except client.CantGetConfig as e:
-        return Response(status=e.code,
-                        response=e.response)
-    except Exception as e:  # should never happen...
-        _logger.error(e)
-        return Response(response="Please report this error",
-                        status=500)
+    """
+    Bind just the config for this SCN
+    """
+    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)
 
 
 def get_key(key, service_component_name):
-    try:
-        bound = client.get_key(key, service_component_name)
-        return Response(response=json.dumps(bound),
-                        status=200,
-                        mimetype="application/json")
-    except client.CantGetConfig as e:
-        return Response(status=e.code,
-                        response=e.response)
-    except client.BadRequest as exc:
-        return Response(status=exc.code,
-                        response=exc.response,
-                        mimetype="text/plain")
-    except Exception as e:  # should never happen...
-        _logger.error(e)
-        return Response(response="Please report this error",
-                        status=500)
+    """
+    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
+    """
+    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)
 
 
 def healthcheck():
-    # got this far, I must be alive... check my connection to Consul by checking myself
-    CONSUL = get_consul_uri()
+    """
+    CBS Healthcheck
+    """
+    LOGGER.info("healthcheck called")
     res = requests.get(
-        "{0}/v1/catalog/service/config_binding_service".format(CONSUL))
+        "{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)
-    else:
-        return Response(response="CBS is alive but cannot reach Consul",
-                        status=503)
+    return Response(response="CBS is alive but cannot reach Consul",
+                    status=503)
diff --git a/config_binding_service/logging.py b/config_binding_service/logging.py
new file mode 100644
index 0000000..e66851d
--- /dev/null
+++ b/config_binding_service/logging.py
@@ -0,0 +1,56 @@
+# ============LICENSE_START=======================================================
+# Copyright (c) 2017-2018 AT&T Intellectual Property. All rights reserved.
+# ================================================================================
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+# ============LICENSE_END=========================================================
+#
+# ECOMP is a trademark and service mark of AT&T Intellectual Property.
+
+from logging import getLogger, StreamHandler, Formatter
+from logging.handlers import RotatingFileHandler
+from os import makedirs
+
+
+LOGGER = getLogger("defaultlogger")
+
+
+def _create_logger(name, logfile):
+    """
+    Create a RotatingFileHandker
+    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)
+
+    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)
+    logger.setLevel("DEBUG")  # a function is going to wrap this anyway
+    logger.addHandler(file_handler)
+    logger.addHandler(stream_handler)
+    return logger
+
+
+def create_logger():
+    """
+    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)