oti/event-handler/otihandler/onap/audit.py

   1 # ================================================================================
   2 # Copyright (c) 2019-2020 AT&T Intellectual Property. All rights reserved.
   3 # ================================================================================
   4 # Licensed under the Apache License, Version 2.0 (the "License");
   5 # you may not use this file except in compliance with the License.
   6 # You may obtain a copy of the License at
   7 #
   8 #      http://www.apache.org/licenses/LICENSE-2.0
   9 #
  10 # Unless required by applicable law or agreed to in writing, software
  11 # distributed under the License is distributed on an "AS IS" BASIS,
  12 # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13 # See the License for the specific language governing permissions and
  14 # limitations under the License.
  15 # ============LICENSE_END=========================================================
  16
  17 """generic class to keep track of request handling
  18  from receiving it through reponse and log all the activities
  19
  20  call Audit.init("component-name", "path/to/config_file") to init the loggers before any requests
  21
  22  start each outside request with creation of the Audit object
  23  audit = Audit(request_id=None, headers=None, msg=None)
  24 """
  25
  26 import os
  27 import sys
  28 import json
  29 import uuid
  30 import time
  31 import copy
  32 from datetime import datetime
  33 from threading import Lock
  34 from enum import Enum
  35
  36 from .CommonLogger import CommonLogger
  37 from .health import Health
  38
  39 REQUEST_X_ECOMP_REQUESTID = "X-ECOMP-RequestID"
  40 REQUEST_REMOTE_ADDR = "Remote-Addr"
  41 REQUEST_HOST = "Host"
  42 HOSTNAME = "HOSTNAME"
  43
  44 AUDIT_REQUESTID = 'requestID'
  45 AUDIT_IPADDRESS = 'IPAddress'
  46 AUDIT_SERVER = 'server'
  47 AUDIT_TARGET_ENTITY = 'targetEntity'
  48
  49 HEADER_CLIENTAUTH = "clientauth"
  50 HEADER_AUTHORIZATION = "authorization"
  51
  52 class AuditHttpCode(Enum):
  53     """audit http codes"""
  54     HTTP_OK = 200
  55     PERMISSION_UNAUTHORIZED_ERROR = 401
  56     PERMISSION_FORBIDDEN_ERROR = 403
  57     RESPONSE_ERROR = 400
  58     DATA_NOT_FOUND_ERROR = 404
  59     SERVER_INTERNAL_ERROR = 500
  60     SERVICE_UNAVAILABLE_ERROR = 503
  61     DATA_ERROR = 1030
  62     SCHEMA_ERROR = 1040
  63
  64 class AuditResponseCode(Enum):
  65     """audit response codes"""
  66     SUCCESS = 0
  67     PERMISSION_ERROR = 100
  68     AVAILABILITY_ERROR = 200
  69     DATA_ERROR = 300
  70     SCHEMA_ERROR = 400
  71     BUSINESS_PROCESS_ERROR = 500
  72     UNKNOWN_ERROR = 900
  73
  74     @staticmethod
  75     def get_response_code(http_status_code):
  76         """calculates the response_code from max_http_status_code"""
  77         response_code = AuditResponseCode.UNKNOWN_ERROR
  78         if http_status_code <= AuditHttpCode.HTTP_OK.value:
  79             response_code = AuditResponseCode.SUCCESS
  80
  81         elif http_status_code in [AuditHttpCode.PERMISSION_UNAUTHORIZED_ERROR.value,
  82                                   AuditHttpCode.PERMISSION_FORBIDDEN_ERROR.value]:
  83             response_code = AuditResponseCode.PERMISSION_ERROR
  84         elif http_status_code == AuditHttpCode.SERVICE_UNAVAILABLE_ERROR.value:
  85             response_code = AuditResponseCode.AVAILABILITY_ERROR
  86         elif http_status_code == AuditHttpCode.SERVER_INTERNAL_ERROR.value:
  87             response_code = AuditResponseCode.BUSINESS_PROCESS_ERROR
  88         elif http_status_code in [AuditHttpCode.DATA_ERROR.value,
  89                                   AuditHttpCode.RESPONSE_ERROR.value,
  90                                   AuditHttpCode.DATA_NOT_FOUND_ERROR.value]:
  91             response_code = AuditResponseCode.DATA_ERROR
  92         elif http_status_code == AuditHttpCode.SCHEMA_ERROR.value:
  93             response_code = AuditResponseCode.SCHEMA_ERROR
  94
  95         return response_code
  96
  97     @staticmethod
  98     def get_human_text(response_code):
  99         """convert enum name into human readable text"""
 100         if not response_code:
 101             return "unknown"
 102         return response_code.name.lower().replace("_", " ")
 103
 104 class Audit(object):
 105     """put the audit object on stack per each initiating request in the system
 106
 107     :request_id: is the X-ECOMP-RequestID for tracing
 108
 109     :req_message: is the request message string for logging
 110
 111     :aud_parent: is the parent request - used for sub-query metrics to other systems
 112
 113     :kwargs: - put any request related params into kwargs
 114     """
 115     _service_name = ""
 116     _service_version = ""
 117     _service_instance_uuid = str(uuid.uuid4())
 118     _started = datetime.now()
 119     _logger_debug = None
 120     _logger_error = None
 121     _logger_metrics = None
 122     _logger_audit = None
 123     _health = Health()
 124     _py_ver = sys.version.replace("\n", "")
 125
 126     @staticmethod
 127     def init(service_name, service_version, config_file_path):
 128         """init static invariants and loggers"""
 129         Audit._service_name = service_name
 130         Audit._service_version = service_version
 131         Audit._logger_debug = CommonLogger(config_file_path, "debug", \
 132             instanceUUID=Audit._service_instance_uuid, serviceName=Audit._service_name)
 133         Audit._logger_error = CommonLogger(config_file_path, "error", \
 134             instanceUUID=Audit._service_instance_uuid, serviceName=Audit._service_name)
 135         Audit._logger_metrics = CommonLogger(config_file_path, "metrics", \
 136             instanceUUID=Audit._service_instance_uuid, serviceName=Audit._service_name)
 137         Audit._logger_audit = CommonLogger(config_file_path, "audit", \
 138             instanceUUID=Audit._service_instance_uuid, serviceName=Audit._service_name)
 139
 140     @staticmethod
 141     def health():
 142         """returns json for health check"""
 143         now = datetime.now()
 144         return {
 145             "service_name" : Audit._service_name,
 146             "service_version" : Audit._service_version,
 147             "service_instance_UUID" : Audit._service_instance_uuid,
 148             "python" : Audit._py_ver,
 149             "started" : str(Audit._started),
 150             "now" : str(now),
 151             "uptime" : str(now - Audit._started),
 152             "stats" : Audit._health.dump(),
 153             "packages" : "N/A"  # Audit._packages
 154         }
 155
 156     def __init__(self, request_id=None, req_message=None, aud_parent=None, **kwargs):
 157         """create audit object per each request in the system
 158
 159         :request_id: is the X-ECOMP-RequestID for tracing
 160         :req_message: is the request message string for logging
 161         :aud_parent: is the parent Audit - used for sub-query metrics to other systems
 162         :kwargs: - put any request related params into kwargs
 163         """
 164         self.request_id = request_id
 165         self.req_message = req_message or ""
 166         self.aud_parent = aud_parent
 167         self.kwargs = kwargs or {}
 168
 169         self.retry_get_config = False
 170         self.max_http_status_code = 0
 171         self._lock = Lock()
 172
 173         if self.aud_parent:
 174             if not self.request_id:
 175                 self.request_id = self.aud_parent.request_id
 176             if not self.req_message:
 177                 self.req_message = self.aud_parent.req_message
 178             self.kwargs = self.aud_parent.merge_all_kwargs(**self.kwargs)
 179         else:
 180             headers = self.kwargs.get("headers", {})
 181             if headers:
 182                 if not self.request_id:
 183                     self.request_id = headers.get(REQUEST_X_ECOMP_REQUESTID)
 184                 if AUDIT_IPADDRESS not in self.kwargs:
 185                     self.kwargs[AUDIT_IPADDRESS] = headers.get(REQUEST_REMOTE_ADDR)
 186                 if AUDIT_SERVER not in self.kwargs:
 187                     self.kwargs[AUDIT_SERVER] = headers.get(REQUEST_HOST)
 188
 189         if AUDIT_SERVER not in self.kwargs:
 190             self.kwargs[AUDIT_SERVER] = os.environ.get(HOSTNAME)
 191
 192         created_req = ""
 193         if not self.request_id:
 194             created_req = " with new"
 195             self.request_id = str(uuid.uuid4())
 196
 197         self.kwargs[AUDIT_REQUESTID] = self.request_id
 198
 199         self._started = time.time()
 200         self._start_event = Audit._logger_audit.getStartRecordEvent()
 201         self.metrics_start()
 202
 203         if not self.aud_parent:
 204             self.info("new audit{0} request_id {1}, msg({2}), kwargs({3})"\
 205                 .format(created_req, self.request_id, self.req_message, json.dumps(self.kwargs)))
 206
 207     def merge_all_kwargs(self, **kwargs):
 208         """returns the merge of copy of self.kwargs with the param kwargs"""
 209         all_kwargs = self.kwargs.copy()
 210         if kwargs:
 211             all_kwargs.update(kwargs)
 212         return all_kwargs
 213
 214     def set_http_status_code(self, http_status_code):
 215         """accumulate the highest(worst) http status code"""
 216         self._lock.acquire()
 217         if self.max_http_status_code < AuditHttpCode.SERVER_INTERNAL_ERROR.value:
 218             self.max_http_status_code = max(http_status_code, self.max_http_status_code)
 219         self._lock.release()
 220
 221     def get_max_http_status_code(self):
 222         """returns the highest(worst) http status code"""
 223         self._lock.acquire()
 224         max_http_status_code = self.max_http_status_code
 225         self._lock.release()
 226         return max_http_status_code
 227
 228     @staticmethod
 229     def get_status_code(success):
 230         """COMPLETE versus ERROR"""
 231         if success:
 232             return 'COMPLETE'
 233         return 'ERROR'
 234
 235     @staticmethod
 236     def hide_secrets(obj):
 237         """hides the known secret field values of the dictionary"""
 238         if not isinstance(obj, dict):
 239             return obj
 240
 241         for key in obj:
 242             if key.lower() in [HEADER_CLIENTAUTH, HEADER_AUTHORIZATION]:
 243                 obj[key] = "*"
 244             elif isinstance(obj[key], dict):
 245                 obj[key] = Audit.hide_secrets(obj[key])
 246
 247         return obj
 248
 249     @staticmethod
 250     def log_json_dumps(obj, **kwargs):
 251         """hide the known secret field values of the dictionary and return json.dumps"""
 252         if not isinstance(obj, dict):
 253             return json.dumps(obj, **kwargs)
 254
 255         return json.dumps(Audit.hide_secrets(copy.deepcopy(obj)), **kwargs)
 256
 257     def is_serious_error(self, status_code):
 258         """returns whether the response_code is success and a human text for response code"""
 259         return AuditResponseCode.PERMISSION_ERROR.value \
 260             == AuditResponseCode.get_response_code(status_code).value \
 261             or self.get_max_http_status_code() >= AuditHttpCode.SERVER_INTERNAL_ERROR.value
 262
 263     def _get_response_status(self):
 264         """calculates the response status fields from max_http_status_code"""
 265         max_http_status_code = self.get_max_http_status_code()
 266         response_code = AuditResponseCode.get_response_code(max_http_status_code)
 267         success = (response_code.value == AuditResponseCode.SUCCESS.value)
 268         response_description = AuditResponseCode.get_human_text(response_code)
 269         return success, max_http_status_code, response_code, response_description
 270
 271     def is_success(self):
 272         """returns whether the response_code is success and a human text for response code"""
 273         success, _, _, _ = self._get_response_status()
 274         return success
 275
 276     def debug(self, log_line, **kwargs):
 277         """debug - the debug=lowest level of logging"""
 278         Audit._logger_debug.debug(log_line, **self.merge_all_kwargs(**kwargs))
 279
 280     def info(self, log_line, **kwargs):
 281         """debug - the info level of logging"""
 282         Audit._logger_debug.info(log_line, **self.merge_all_kwargs(**kwargs))
 283
 284     def info_requested(self, result=None, **kwargs):
 285         """info "requested ..." - the info level of logging"""
 286         self.info("requested {0} {1}".format(self.req_message, result or ""), \
 287             **self.merge_all_kwargs(**kwargs))
 288
 289     def warn(self, log_line, **kwargs):
 290         """debug+error - the warn level of logging"""
 291         all_kwargs = self.merge_all_kwargs(**kwargs)
 292         Audit._logger_debug.warn(log_line, **all_kwargs)
 293         Audit._logger_error.warn(log_line, **all_kwargs)
 294
 295     def error(self, log_line, **kwargs):
 296         """debug+error - the error level of logging"""
 297         all_kwargs = self.merge_all_kwargs(**kwargs)
 298         Audit._logger_debug.error(log_line, **all_kwargs)
 299         Audit._logger_error.error(log_line, **all_kwargs)
 300
 301     def fatal(self, log_line, **kwargs):
 302         """debug+error - the fatal level of logging"""
 303         all_kwargs = self.merge_all_kwargs(**kwargs)
 304         Audit._logger_debug.fatal(log_line, **all_kwargs)
 305         Audit._logger_error.fatal(log_line, **all_kwargs)
 306
 307     @staticmethod
 308     def get_elapsed_time(started):
 309         """returns the elapsed time since started in milliseconds"""
 310         return int(round(1000 * (time.time() - started)))
 311
 312     def metrics_start(self, log_line=None, **kwargs):
 313         """reset metrics timing"""
 314         self._metrics_started = time.time()
 315         self._metrics_start_event = Audit._logger_metrics.getStartRecordEvent()
 316         if log_line:
 317             self.info(log_line, **self.merge_all_kwargs(**kwargs))
 318
 319     def metrics(self, log_line, **kwargs):
 320         """debug+metrics - the metrics=sub-audit level of logging"""
 321         all_kwargs = self.merge_all_kwargs(**kwargs)
 322         success, max_http_status_code, response_code, response_description = \
 323             self._get_response_status()
 324         metrics_func = None
 325         timer = Audit.get_elapsed_time(self._metrics_started)
 326         if success:
 327             log_line = "done: {0}".format(log_line)
 328             self.info(log_line, **all_kwargs)
 329             metrics_func = Audit._logger_metrics.info
 330             Audit._health.success(all_kwargs.get(AUDIT_TARGET_ENTITY, Audit._service_name), timer)
 331         else:
 332             log_line = "failed: {0}".format(log_line)
 333             self.error(log_line, errorCode=response_code.value, \
 334                 errorDescription=response_description, **all_kwargs)
 335             metrics_func = Audit._logger_metrics.error
 336             Audit._health.error(all_kwargs.get(AUDIT_TARGET_ENTITY, Audit._service_name), timer)
 337
 338         metrics_func(log_line, begTime=self._metrics_start_event, timer=timer,
 339                      statusCode=Audit.get_status_code(success), responseCode=response_code.value,
 340                      responseDescription=response_description,
 341                      **all_kwargs
 342                     )
 343
 344         self.metrics_start()
 345         return (success, max_http_status_code, response_description)
 346
 347     def audit_done(self, result=None, **kwargs):
 348         """debug+audit - the audit=top level of logging"""
 349         all_kwargs = self.merge_all_kwargs(**kwargs)
 350         success, max_http_status_code, response_code, response_description = \
 351             self._get_response_status()
 352         log_line = "{0} {1}".format(self.req_message, result or "").strip()
 353         audit_func = None
 354         timer = Audit.get_elapsed_time(self._started)
 355         if success:
 356             log_line = "done: {0}".format(log_line)
 357             self.info(log_line, **all_kwargs)
 358             audit_func = Audit._logger_audit.info
 359             Audit._health.success(all_kwargs.get(AUDIT_TARGET_ENTITY, Audit._service_name), timer)
 360         else:
 361             log_line = "failed: {0}".format(log_line)
 362             self.error(log_line, errorCode=response_code.value,
 363                        errorDescription=response_description, **all_kwargs)
 364             audit_func = Audit._logger_audit.error
 365             Audit._health.error(all_kwargs.get(AUDIT_TARGET_ENTITY, Audit._service_name), timer)
 366
 367         audit_func(log_line, begTime=self._start_event, timer=timer,
 368                    statusCode=Audit.get_status_code(success),
 369                    responseCode=response_code.value,
 370                    responseDescription=response_description,
 371                    **all_kwargs
 372                   )
 373
 374         return (success, max_http_status_code, response_description)
 375         # this line added to test