# ================================================================================ # Copyright (c) 2019-2020 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========================================================= """generic class to keep track of request handling from receiving it through reponse and log all the activities call Audit.init("component-name", "path/to/config_file") to init the loggers before any requests start each outside request with creation of the Audit object audit = Audit(request_id=None, headers=None, msg=None) """ import os import sys import json import uuid import time import copy from datetime import datetime from threading import Lock from enum import Enum from .CommonLogger import CommonLogger from .health import Health REQUEST_X_ECOMP_REQUESTID = "X-ECOMP-RequestID" REQUEST_REMOTE_ADDR = "Remote-Addr" REQUEST_HOST = "Host" HOSTNAME = "HOSTNAME" AUDIT_REQUESTID = 'requestID' AUDIT_IPADDRESS = 'IPAddress' AUDIT_SERVER = 'server' AUDIT_TARGET_ENTITY = 'targetEntity' HEADER_CLIENTAUTH = "clientauth" HEADER_AUTHORIZATION = "authorization" class AuditHttpCode(Enum): """audit http codes""" HTTP_OK = 200 PERMISSION_UNAUTHORIZED_ERROR = 401 PERMISSION_FORBIDDEN_ERROR = 403 RESPONSE_ERROR = 400 DATA_NOT_FOUND_ERROR = 404 SERVER_INTERNAL_ERROR = 500 SERVICE_UNAVAILABLE_ERROR = 503 DATA_ERROR = 1030 SCHEMA_ERROR = 1040 class AuditResponseCode(Enum): """audit response codes""" SUCCESS = 0 PERMISSION_ERROR = 100 AVAILABILITY_ERROR = 200 DATA_ERROR = 300 SCHEMA_ERROR = 400 BUSINESS_PROCESS_ERROR = 500 UNKNOWN_ERROR = 900 @staticmethod def get_response_code(http_status_code): """calculates the response_code from max_http_status_code""" response_code = AuditResponseCode.UNKNOWN_ERROR if http_status_code <= AuditHttpCode.HTTP_OK.value: response_code = AuditResponseCode.SUCCESS elif http_status_code in [AuditHttpCode.PERMISSION_UNAUTHORIZED_ERROR.value, AuditHttpCode.PERMISSION_FORBIDDEN_ERROR.value]: response_code = AuditResponseCode.PERMISSION_ERROR elif http_status_code == AuditHttpCode.SERVICE_UNAVAILABLE_ERROR.value: response_code = AuditResponseCode.AVAILABILITY_ERROR elif http_status_code == AuditHttpCode.SERVER_INTERNAL_ERROR.value: response_code = AuditResponseCode.BUSINESS_PROCESS_ERROR elif http_status_code in [AuditHttpCode.DATA_ERROR.value, AuditHttpCode.RESPONSE_ERROR.value, AuditHttpCode.DATA_NOT_FOUND_ERROR.value]: response_code = AuditResponseCode.DATA_ERROR elif http_status_code == AuditHttpCode.SCHEMA_ERROR.value: response_code = AuditResponseCode.SCHEMA_ERROR return response_code @staticmethod def get_human_text(response_code): """convert enum name into human readable text""" if not response_code: return "unknown" return response_code.name.lower().replace("_", " ") class Audit(object): """put the audit object on stack per each initiating request in the system :request_id: is the X-ECOMP-RequestID for tracing :req_message: is the request message string for logging :aud_parent: is the parent request - used for sub-query metrics to other systems :kwargs: - put any request related params into kwargs """ _service_name = "" _service_version = "" _service_instance_uuid = str(uuid.uuid4()) _started = datetime.now() _logger_debug = None _logger_error = None _logger_metrics = None _logger_audit = None _health = Health() _py_ver = sys.version.replace("\n", "") @staticmethod def init(service_name, service_version, config_file_path): """init static invariants and loggers""" Audit._service_name = service_name Audit._service_version = service_version Audit._logger_debug = CommonLogger(config_file_path, "debug", \ instanceUUID=Audit._service_instance_uuid, serviceName=Audit._service_name) Audit._logger_error = CommonLogger(config_file_path, "error", \ instanceUUID=Audit._service_instance_uuid, serviceName=Audit._service_name) Audit._logger_metrics = CommonLogger(config_file_path, "metrics", \ instanceUUID=Audit._service_instance_uuid, serviceName=Audit._service_name) Audit._logger_audit = CommonLogger(config_file_path, "audit", \ instanceUUID=Audit._service_instance_uuid, serviceName=Audit._service_name) @staticmethod def health(): """returns json for health check""" now = datetime.now() return { "service_name" : Audit._service_name, "service_version" : Audit._service_version, "service_instance_UUID" : Audit._service_instance_uuid, "python" : Audit._py_ver, "started" : str(Audit._started), "now" : str(now), "uptime" : str(now - Audit._started), "stats" : Audit._health.dump(), "packages" : "N/A" # Audit._packages } def __init__(self, request_id=None, req_message=None, aud_parent=None, **kwargs): """create audit object per each request in the system :request_id: is the X-ECOMP-RequestID for tracing :req_message: is the request message string for logging :aud_parent: is the parent Audit - used for sub-query metrics to other systems :kwargs: - put any request related params into kwargs """ self.request_id = request_id self.req_message = req_message or "" self.aud_parent = aud_parent self.kwargs = kwargs or {} self.retry_get_config = False self.max_http_status_code = 0 self._lock = Lock() if self.aud_parent: if not self.request_id: self.request_id = self.aud_parent.request_id if not self.req_message: self.req_message = self.aud_parent.req_message self.kwargs = self.aud_parent.merge_all_kwargs(**self.kwargs) else: headers = self.kwargs.get("headers", {}) if headers: if not self.request_id: self.request_id = headers.get(REQUEST_X_ECOMP_REQUESTID) if AUDIT_IPADDRESS not in self.kwargs: self.kwargs[AUDIT_IPADDRESS] = headers.get(REQUEST_REMOTE_ADDR) if AUDIT_SERVER not in self.kwargs: self.kwargs[AUDIT_SERVER] = headers.get(REQUEST_HOST) if AUDIT_SERVER not in self.kwargs: self.kwargs[AUDIT_SERVER] = os.environ.get(HOSTNAME) created_req = "" if not self.request_id: created_req = " with new" self.request_id = str(uuid.uuid4()) self.kwargs[AUDIT_REQUESTID] = self.request_id self._started = time.time() self._start_event = Audit._logger_audit.getStartRecordEvent() self.metrics_start() if not self.aud_parent: self.info("new audit{0} request_id {1}, msg({2}), kwargs({3})"\ .format(created_req, self.request_id, self.req_message, json.dumps(self.kwargs))) def merge_all_kwargs(self, **kwargs): """returns the merge of copy of self.kwargs with the param kwargs""" all_kwargs = self.kwargs.copy() if kwargs: all_kwargs.update(kwargs) return all_kwargs def set_http_status_code(self, http_status_code): """accumulate the highest(worst) http status code""" self._lock.acquire() if self.max_http_status_code < AuditHttpCode.SERVER_INTERNAL_ERROR.value: self.max_http_status_code = max(http_status_code, self.max_http_status_code) self._lock.release() def get_max_http_status_code(self): """returns the highest(worst) http status code""" self._lock.acquire() max_http_status_code = self.max_http_status_code self._lock.release() return max_http_status_code @staticmethod def get_status_code(success): """COMPLETE versus ERROR""" if success: return 'COMPLETE' return 'ERROR' @staticmethod def hide_secrets(obj): """hides the known secret field values of the dictionary""" if not isinstance(obj, dict): return obj for key in obj: if key.lower() in [HEADER_CLIENTAUTH, HEADER_AUTHORIZATION]: obj[key] = "*" elif isinstance(obj[key], dict): obj[key] = Audit.hide_secrets(obj[key]) return obj @staticmethod def log_json_dumps(obj, **kwargs): """hide the known secret field values of the dictionary and return json.dumps""" if not isinstance(obj, dict): return json.dumps(obj, **kwargs) return json.dumps(Audit.hide_secrets(copy.deepcopy(obj)), **kwargs) def is_serious_error(self, status_code): """returns whether the response_code is success and a human text for response code""" return AuditResponseCode.PERMISSION_ERROR.value \ == AuditResponseCode.get_response_code(status_code).value \ or self.get_max_http_status_code() >= AuditHttpCode.SERVER_INTERNAL_ERROR.value def _get_response_status(self): """calculates the response status fields from max_http_status_code""" max_http_status_code = self.get_max_http_status_code() response_code = AuditResponseCode.get_response_code(max_http_status_code) success = (response_code.value == AuditResponseCode.SUCCESS.value) response_description = AuditResponseCode.get_human_text(response_code) return success, max_http_status_code, response_code, response_description def is_success(self): """returns whether the response_code is success and a human text for response code""" success, _, _, _ = self._get_response_status() return success def debug(self, log_line, **kwargs): """debug - the debug=lowest level of logging""" Audit._logger_debug.debug(log_line, **self.merge_all_kwargs(**kwargs)) def info(self, log_line, **kwargs): """debug - the info level of logging""" Audit._logger_debug.info(log_line, **self.merge_all_kwargs(**kwargs)) def info_requested(self, result=None, **kwargs): """info "requested ..." - the info level of logging""" self.info("requested {0} {1}".format(self.req_message, result or ""), \ **self.merge_all_kwargs(**kwargs)) def warn(self, log_line, **kwargs): """debug+error - the warn level of logging""" all_kwargs = self.merge_all_kwargs(**kwargs) Audit._logger_debug.warn(log_line, **all_kwargs) Audit._logger_error.warn(log_line, **all_kwargs) def error(self, log_line, **kwargs): """debug+error - the error level of logging""" all_kwargs = self.merge_all_kwargs(**kwargs) Audit._logger_debug.error(log_line, **all_kwargs) Audit._logger_error.error(log_line, **all_kwargs) def fatal(self, log_line, **kwargs): """debug+error - the fatal level of logging""" all_kwargs = self.merge_all_kwargs(**kwargs) Audit._logger_debug.fatal(log_line, **all_kwargs) Audit._logger_error.fatal(log_line, **all_kwargs) @staticmethod def get_elapsed_time(started): """returns the elapsed time since started in milliseconds""" return int(round(1000 * (time.time() - started))) def metrics_start(self, log_line=None, **kwargs): """reset metrics timing""" self._metrics_started = time.time() self._metrics_start_event = Audit._logger_metrics.getStartRecordEvent() if log_line: self.info(log_line, **self.merge_all_kwargs(**kwargs)) def metrics(self, log_line, **kwargs): """debug+metrics - the metrics=sub-audit level of logging""" all_kwargs = self.merge_all_kwargs(**kwargs) success, max_http_status_code, response_code, response_description = \ self._get_response_status() metrics_func = None timer = Audit.get_elapsed_time(self._metrics_started) if success: log_line = "done: {0}".format(log_line) self.info(log_line, **all_kwargs) metrics_func = Audit._logger_metrics.info Audit._health.success(all_kwargs.get(AUDIT_TARGET_ENTITY, Audit._service_name), timer) else: log_line = "failed: {0}".format(log_line) self.error(log_line, errorCode=response_code.value, \ errorDescription=response_description, **all_kwargs) metrics_func = Audit._logger_metrics.error Audit._health.error(all_kwargs.get(AUDIT_TARGET_ENTITY, Audit._service_name), timer) metrics_func(log_line, begTime=self._metrics_start_event, timer=timer, statusCode=Audit.get_status_code(success), responseCode=response_code.value, responseDescription=response_description, **all_kwargs ) self.metrics_start() return (success, max_http_status_code, response_description) def audit_done(self, result=None, **kwargs): """debug+audit - the audit=top level of logging""" all_kwargs = self.merge_all_kwargs(**kwargs) success, max_http_status_code, response_code, response_description = \ self._get_response_status() log_line = "{0} {1}".format(self.req_message, result or "").strip() audit_func = None timer = Audit.get_elapsed_time(self._started) if success: log_line = "done: {0}".format(log_line) self.info(log_line, **all_kwargs) audit_func = Audit._logger_audit.info Audit._health.success(all_kwargs.get(AUDIT_TARGET_ENTITY, Audit._service_name), timer) else: log_line = "failed: {0}".format(log_line) self.error(log_line, errorCode=response_code.value, errorDescription=response_description, **all_kwargs) audit_func = Audit._logger_audit.error Audit._health.error(all_kwargs.get(AUDIT_TARGET_ENTITY, Audit._service_name), timer) audit_func(log_line, begTime=self._start_event, timer=timer, statusCode=Audit.get_status_code(success), responseCode=response_code.value, responseDescription=response_description, **all_kwargs ) return (success, max_http_status_code, response_description) # this line added to test