From a6616ada453446a076607c640cabe25fd0450426 Mon Sep 17 00:00:00 2001 From: Tommy Carpenter Date: Tue, 3 Apr 2018 11:13:01 -0400 Subject: Implement the EELF metrics format Change-Id: If7c10aad141f5e4600652e485dcd3851e364b1ac Issue-ID: DCAEGEN2-387 Signed-off-by: Tommy Carpenter --- Changelog.md | 3 +++ config_binding_service/controller.py | 38 +++++++++++++++++++++------ config_binding_service/logging.py | 50 +++++++++++++++++++++++++++++++----- pom.xml | 2 +- setup.py | 2 +- tests/test_binding.py | 21 +++++++++++++++ 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. org.onap.dcaegen2.platform configbinding dcaegen2-platform-configbinding - 2.1.3 + 2.1.4 http://maven.apache.org UTF-8 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) -- cgit 1.2.3-korg