diff options
author | Tommy Carpenter <tommy@research.att.com> | 2018-07-09 15:11:14 -0400 |
---|---|---|
committer | Tommy Carpenter <tommy@research.att.com> | 2018-07-10 09:31:45 -0400 |
commit | 46ef692d3c1c9d57ad61bcc34bdac48eabf240b7 (patch) | |
tree | 52972cd3c311d66f69805a91df7aad86a7d81595 /app/app/config_binding_service | |
parent | e98e967740e58cf429b76b187828e3e0625215a5 (diff) |
Finish EELF compliance.
Issue-ID: DCAEGEN2-581
Change-Id: I22651dbe775b0165612c507df99b5a0e8e2ee22c
Signed-off-by: Tommy Carpenter <tommy@research.att.com>
Diffstat (limited to 'app/app/config_binding_service')
-rw-r--r-- | app/app/config_binding_service/client.py | 60 | ||||
-rw-r--r-- | app/app/config_binding_service/controller.py | 22 | ||||
-rw-r--r-- | app/app/config_binding_service/logging.py | 80 |
3 files changed, 126 insertions, 36 deletions
diff --git a/app/app/config_binding_service/client.py b/app/app/config_binding_service/client.py index a87c3bc..93f4d69 100644 --- a/app/app/config_binding_service/client.py +++ b/app/app/config_binding_service/client.py @@ -24,7 +24,7 @@ import json import requests import six from config_binding_service import get_consul_uri -from config_binding_service.logging import LOGGER +from config_binding_service.logging import utc, metrics CONSUL = get_consul_uri() @@ -62,7 +62,7 @@ class BadRequest(Exception): ### -def _consul_get_all_as_transaction(service_component_name): +def _consul_get_all_as_transaction(service_component_name, raw_request, xer): """ Use Consul's transaction API to get all keys of the form service_component_name:* Return a dict with all the values decoded @@ -75,7 +75,9 @@ def _consul_get_all_as_transaction(service_component_name): } }] + bts = utc() response = requests.put("{0}/v1/txn".format(CONSUL), json=payload) + metrics(raw_request, bts, xer, "Consul", "/v1/txn".format(service_component_name), response.status_code, __name__, msg="Retrieving Consul transaction for all keys for {0}".format(service_component_name)) try: response.raise_for_status() @@ -99,8 +101,8 @@ def _consul_get_all_as_transaction(service_component_name): return new_res -def _get_config_rels_dmaap(service_component_name): - allk = _consul_get_all_as_transaction(service_component_name) +def _get_config_rels_dmaap(service_component_name, raw_request, xer): + allk = _consul_get_all_as_transaction(service_component_name, raw_request, xer) config = allk[service_component_name] rels = allk.get(service_component_name + ":rels", []) dmaap = allk.get(service_component_name + ":dmaap", {}) @@ -112,23 +114,27 @@ def _get_connection_info_from_consul(service_component_name): Call consul's catalog TODO: currently assumes there is only one service - 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. + DEPRECATION NOTE: + This function existed when DCAE was using Consul to resolve service component's connection information. + This relied on a "rels" key and a Cloudify relationship plugin to set up the magic. + The consensous is that this feature is no longer used. + This functionality is very likely deprecated by Kubernetes service discovery mechanism, and DMaaP. + + This function also includes logic related to CDAP, which is also likely deprecated. + + This code shall remain here for now but is at risk of being deleted in a future release. """ - LOGGER.info("Retrieving connection information for %s", service_component_name) - res = requests.get( - "{0}/v1/catalog/service/{1}".format(CONSUL, service_component_name)) + # Note: there should be a metrics log here, but see the deprecation note above; this function is due to be deleted. + 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 %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 %s", redirectish_url) + redirectish_url = "http://{0}:{1}/application/{2}".format(ip_addr, port, service_component_name) res = requests.get(redirectish_url) res.raise_for_status() details = res.json() @@ -214,11 +220,13 @@ def _recurse(config, rels, dmaap): ######### -def resolve(service_component_name): +def resolve(service_component_name, raw_request, xer): """ Return the bound config of service_component_name + + raw_request and xer are needed to form the correct metrics log """ - config, rels, dmaap = _get_config_rels_dmaap(service_component_name) + config, rels, dmaap = _get_config_rels_dmaap(service_component_name, raw_request, xer) return _recurse(config, rels, dmaap) @@ -231,15 +239,19 @@ def resolve_override(config, rels=[], dmaap={}): return _recurse(copy.deepcopy(config), rels, dmaap) -def resolve_all(service_component_name): +def resolve_all(service_component_name, raw_request, xer): """ Return config, policies, and any other k such that service_component_name:k exists (other than :dmaap and :rels) + + raw_request and xer are needed to form the correct metrics log """ - allk = _consul_get_all_as_transaction(service_component_name) + allk = _consul_get_all_as_transaction(service_component_name, raw_request, xer) returnk = {} # replace the config with the resolved config - returnk["config"] = resolve(service_component_name) + returnk["config"] = resolve_override(allk[service_component_name], + allk.get("{0}:rels".format(service_component_name), []), + allk.get("{0}:dmaap".format(service_component_name), {})) # concatenate the items for k in allk: @@ -262,15 +274,21 @@ def resolve_all(service_component_name): return returnk -def get_key(key, service_component_name): +def get_key(key, service_component_name, raw_request, xer): """ Try to fetch a key k from Consul of the form service_component_name:k + + raw_request and xer are needed to form the correct metrics log """ if key == "policies": raise BadRequest( ":policies is a complex folder and should be retrieved using the service_component_all API") - response = requests.get( - "{0}/v1/kv/{1}:{2}".format(CONSUL, service_component_name, key)) + + bts = utc() + path = "v1/kv/{0}:{1}".format(service_component_name, key) + response = requests.get("{0}/{1}".format(CONSUL, path)) + metrics(raw_request, bts, xer, "Consul", path, response.status_code, __name__, msg="Retrieving single Consul key {0} for {1}".format(key, service_component_name)) + try: response.raise_for_status() except requests.exceptions.HTTPError as exc: diff --git a/app/app/config_binding_service/controller.py b/app/app/config_binding_service/controller.py index acd9447..943837c 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 audit, utc, error +from config_binding_service.logging import audit, utc, error, metrics def _get_helper(json_expecting_func, **kwargs): @@ -59,7 +59,7 @@ def bind_all(service_component_name): """ xer = _get_or_generate_xer(connexion.request) bts = utc() - response, status_code, mimetype = _get_helper(client.resolve_all, service_component_name=service_component_name) + response, status_code, mimetype = _get_helper(client.resolve_all, service_component_name=service_component_name, raw_request=connexion.request, xer=xer) 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": xer}) @@ -71,7 +71,7 @@ def bind_config_for_scn(service_component_name): """ xer = _get_or_generate_xer(connexion.request) bts = utc() - response, status_code, mimetype = _get_helper(client.resolve, service_component_name=service_component_name) + response, status_code, mimetype = _get_helper(client.resolve, service_component_name=service_component_name, raw_request=connexion.request, xer=xer) 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}) @@ -83,7 +83,7 @@ def get_key(key, service_component_name): """ 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) + response, status_code, mimetype = _get_helper(client.get_key, key=key, service_component_name=service_component_name, raw_request=connexion.request, xer=xer) 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}) @@ -93,14 +93,16 @@ def healthcheck(): CBS Healthcheck """ xer = _get_or_generate_xer(connexion.request) + path = "v1/catalog/service/config_binding_service" bts = utc() - res = requests.get("{0}/v1/catalog/service/config_binding_service".format(get_consul_uri())) + res = requests.get("{0}/{1}".format(get_consul_uri(), path)) status = res.status_code if status == 200: - response = "CBS is alive and Consul connection OK" + msg = "CBS is alive and Consul connection OK" else: - response = "CBS is alive but cannot reach Consul" + msg = "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) + error(connexion.request, xer, "WARN", 200, tgt_entity="Consul", tgt_path="/v1/catalog/service/config_binding_service", msg=msg) + metrics(connexion.request, bts, xer, "Consul", path, res.status_code, __name__, msg="Checking Consul connectivity during CBS healthcheck, {0}".format(msg)) + audit(connexion.request, bts, xer, status, __name__, msg=msg) + return Response(response=msg, status=status) diff --git a/app/app/config_binding_service/logging.py b/app/app/config_binding_service/logging.py index 7966e2f..b6275a7 100644 --- a/app/app/config_binding_service/logging.py +++ b/app/app/config_binding_service/logging.py @@ -22,9 +22,9 @@ from os import makedirs import datetime -LOGGER = getLogger("defaultlogger") _AUDIT_LOGGER = getLogger("defaultlogger") _ERROR_LOGGER = getLogger("defaultlogger") +_METRICS_LOGGER = getLogger("defaultlogger") def _create_logger(name, logfile): @@ -46,6 +46,7 @@ def _create_logger(name, logfile): def create_loggers(): """ Public method to set the global logger, launched from Run + This is *not* launched during unit testing, so unit tests do not create/write log files """ makedirs("/opt/logs", exist_ok=True) @@ -61,6 +62,12 @@ def create_loggers(): global _ERROR_LOGGER _ERROR_LOGGER = _create_logger("config_binding_service_error", err_file) + # create the metrics log + met_file = "/opt/logs/metrics.log" + open(met_file, 'a').close() # this is like "touch" + global _METRICS_LOGGER + _METRICS_LOGGER = _create_logger("config_binding_service_metrics", met_file) + def utc(): """gets current time in utc""" @@ -75,25 +82,36 @@ def audit(raw_request, bts, xer, rcode, calling_mod, msg="n/a"): 1 BeginTimestamp Implemented (bts) 2 EndTimestamp Auto Injected when this is called 3 RequestID Implemented (xer) + 5 threadId n/a 7 serviceName Implemented (from Req) 9 StatusCode Auto injected based on rcode 10 ResponseCode Implemented (rcode) + 13 Category log level - all audit records are INFO. 15 Server IP address Implemented (from Req) 16 ElapsedTime Auto Injected (milliseconds) + 17 Server This is running in a Docker container so this is not applicable, my HOSTNAME is always "config_binding_service" 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) + + Not implemented + 4 serviceInstanceID - ? + 6 physical/virtual server name (Optional) + 8 PartnerName - nothing in the request tells me this + 11 Response Description - the CBS follows standard HTTP error codes so look them up + 12 instanceUUID - Optional + 14 Severity (Optional) """ ets = utc() - _AUDIT_LOGGER.info("{bts}|{ets}|{xer}||||{path}||{status}|{rcode}|||||{servip}|{et}||{clientip}|{calling_mod}|||||||{msg}".format( + _AUDIT_LOGGER.info("{bts}|{ets}|{xer}||n/a||{path}||{status}|{rcode}|||INFO||{servip}|{et}|config_binding_service|{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", + status="COMPLETE" if rcode < 400 else "ERROR", servip=raw_request.host.split(":")[0], et=int((ets - bts).microseconds / 1000), # supposed to be in milleseconds clientip=raw_request.remote_addr, @@ -108,6 +126,7 @@ def error(raw_request, xer, severity, ecode, tgt_entity="n/a", tgt_path="n/a", m 1 Timestamp Auto Injected when this is called 2 RequestID Implemented (xer) + 3 ThreadID n/a 4 ServiceName Implemented (from Req) 6 TargetEntity Implemented (tgt_entity) 7 TargetServiceName Implemented (tgt_path)/ @@ -117,12 +136,11 @@ def error(raw_request, xer, severity, ecode, tgt_entity="n/a", tgt_path="n/a", m 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( + _ERROR_LOGGER.error("{ets}|{xer}|n/a|{path}||{tge}|{tgp}|{sev}|{ecode}|{msg}|{amsg}".format( ets=ets, xer=xer, path=raw_request.path.split("/")[1], @@ -132,3 +150,55 @@ def error(raw_request, xer, severity, ecode, tgt_entity="n/a", tgt_path="n/a", m ecode=ecode, msg=msg, amsg=adv_msg)) + + +def metrics(raw_request, bts, xer, target, target_path, rcode, calling_mod, msg="n/a"): + """ + write an EELF metrics record per https://wiki.onap.org/download/attachments/1015849/ONAP%20application%20logging%20guidelines.pdf?api=v2 + %The metrics fields implemented: + + 1 BeginTimestamp Implemented (bts) + 2 EndTimestamp Auto Injected when this is called + 3 RequestID Implemented (xer) + 5 threadId n/a + 7 serviceName Implemented (from Req) + 9 TargetEntity Implemented (target) + 10 TargetServiceName Implemented (target_path) + 11 StatusCode Implemented (based on rcode) + 12 Response Code Implemented (rcode) + 15 Category log level all metrics records are INFO. + 17 Server IP address Implemented (from Req) + 18 ElapsedTime Auto Injected (milliseconds) + 19 Server This is running in a Docker container so this is not applicable, my HOSTNAME is always "config_binding_service" + 20 ClientIPaddress Implemented (from Req) + 21 class name Implemented (mod), though docs say OOP, I am using the python module here + 22 Unused ...implemented.... + 24 TargetVirtualEntity n/a + 25-28 Custom n/a + 29 detailMessage Implemented (msg) + + Not implemented + 4 serviceInstanceID - ? + 6 physical/virtual server name (Optional) + 8 PartnerName - nothing in the request tells me this + 13 Response Description - the CBS follows standard HTTP error codes so look them up + 14 instanceUUID - Optional + 16 Severity (Optional) + 23 ProcessKey - optional + """ + ets = utc() + + _METRICS_LOGGER.info("{bts}|{ets}|{xer}||n/a||{path}||{tge}|{tgp}|{status}|{rcode}|||INFO||{servip}|{et}|config_binding_service|{clientip}|{calling_mod}|||n/a|||||{msg}".format( + bts=bts.isoformat(), + ets=ets.isoformat(), + xer=xer, + path=raw_request.path.split("/")[1], + tge=target, + tgp=target_path, + status="COMPLETE" if rcode < 400 else "ERROR", + rcode=rcode, + 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 + )) |