From 535e0dc1340ce57c0bfeed8d1ce530111cf41063 Mon Sep 17 00:00:00 2001 From: Alex Shatov Date: Thu, 22 Mar 2018 15:52:14 -0400 Subject: 2.4.1 better step-timer + audit + unit-tests - improved step-timer due to unit tests -- fixed events -- better logging - audit - collect list of package thru subprocess pip freeze - unit tests coverage 76% Change-Id: Ib1cb5f687612ecf18aa7414b1ff7dbf5774345b4 Signed-off-by: Alex Shatov Issue-ID: DCAEGEN2-389 --- policyhandler/onap/audit.py | 20 +++++--- policyhandler/policy_updater.py | 5 +- policyhandler/step_timer.py | 105 ++++++++++++++++++++++++++++++++++++---- 3 files changed, 111 insertions(+), 19 deletions(-) (limited to 'policyhandler') diff --git a/policyhandler/onap/audit.py b/policyhandler/onap/audit.py index 109e3ff..c615d63 100644 --- a/policyhandler/onap/audit.py +++ b/policyhandler/onap/audit.py @@ -28,6 +28,7 @@ import copy import json import os +import subprocess import sys import time import uuid @@ -116,7 +117,7 @@ class Audit(object): """ _service_name = "" _service_version = "" - _service_instance_UUID = str(uuid.uuid4()) + _service_instance_uuid = str(uuid.uuid4()) _started = datetime.now() _logger_debug = None _logger_error = None @@ -124,6 +125,10 @@ class Audit(object): _logger_audit = None _health = Health() _py_ver = sys.version.replace("\n", "") + try: + _packages = filter(None, subprocess.check_output(["pip", "freeze"]).splitlines()) + except subprocess.CalledProcessError: + _packages = [] @staticmethod def init(service_name, service_version, config_file_path): @@ -131,13 +136,13 @@ class Audit(object): 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) + 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) + 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) + 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) + instanceUUID=Audit._service_instance_uuid, serviceName=Audit._service_name) @staticmethod def health(): @@ -146,12 +151,13 @@ class Audit(object): return { "service_name" : Audit._service_name, "service_version" : Audit._service_version, - "service_instance_UUID" : Audit._service_instance_UUID, + "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() + "stats" : Audit._health.dump(), + "packages" : Audit._packages } def __init__(self, request_id=None, req_message=None, aud_parent=None, **kwargs): diff --git a/policyhandler/policy_updater.py b/policyhandler/policy_updater.py index 2c2f729..0b9e227 100644 --- a/policyhandler/policy_updater.py +++ b/policyhandler/policy_updater.py @@ -139,19 +139,20 @@ class PolicyUpdater(Thread): "catch_up_timer", self._catch_up_interval, PolicyUpdater.catch_up, + PolicyUpdater._logger, self ) self._catch_up_timer.start() self._logger.info("started catch_up_timer in %s", self._catch_up_interval) def _pause_catch_up_timer(self): - """stop catch_up_timer""" + """pause catch_up_timer""" if self._catch_up_timer: self._logger.info("pause catch_up_timer") self._catch_up_timer.pause() def _stop_catch_up_timer(self): - """stop catch_up_timer""" + """stop and destroy the catch_up_timer""" if self._catch_up_timer: self._logger.info("stopping catch_up_timer") self._catch_up_timer.stop() diff --git a/policyhandler/step_timer.py b/policyhandler/step_timer.py index 6e2b3f6..ad77c85 100644 --- a/policyhandler/step_timer.py +++ b/policyhandler/step_timer.py @@ -18,46 +18,131 @@ """periodically callback""" -from threading import Event, Thread +from datetime import datetime +from threading import Event, Lock, Thread class StepTimer(Thread): """call on_time after interval number of seconds, then wait to continue""" - def __init__(self, name, interval, on_time, *args, **kwargs): + INIT = "init" + NEXT = "next" + STARTED = "started" + PAUSED = "paused" + STOPPING = "stopping" + STOPPED = "stopped" + + def __init__(self, name, interval, on_time, logger, *args, **kwargs): + """create step timer with controlled start. next step and pause""" Thread.__init__(self, name=name) self._interval = interval self._on_time = on_time + self._logger = logger self._args = args self._kwargs = kwargs + self._lock = Lock() + self._timeout = Event() self._paused = Event() - self._continue = Event() + self._next = Event() self._finished = Event() + self._event = StepTimer.INIT + self._event_counter = 0 + self._event_time = 0 + self._event_ts = datetime.now() + + self._substep = None + self._substep_time = 0 + self._substep_ts = datetime.now() + + def get_status(self): + """returns status of events""" + with self._lock: + return "{0}[{1}] {2}: timeout({3}), paused({4}), next({5}), finished({6})".format( + self._event, + self._event_counter, + self._substep, + self._timeout.is_set(), + self._paused.is_set(), + self._next.is_set(), + self._finished.is_set(), + ) + def next(self): """continue with the next timeout""" self._paused.clear() - self._continue.set() + self._next.set() + self._timeout.set() + self._set_timer_event(StepTimer.NEXT) def pause(self): """pause the timer""" self._paused.set() + self._next.clear() + self._set_timer_event(StepTimer.PAUSED) def stop(self): """stop the timer if it hasn't finished yet""" self._finished.set() self._timeout.set() - self._continue.set() + self._next.set() + self._set_timer_event(StepTimer.STOPPING) + + def _set_timer_event(self, event): + """set the event on the timer""" + with self._lock: + if event in [StepTimer.NEXT, StepTimer.STARTED]: + self._event_counter += 1 + + self._event = event + now = datetime.now() + self._event_time = (now - self._event_ts).total_seconds() + self._event_ts = now + self._logger.info("[{0}] {1} {2}".format( + self._event_time, self.name, self.get_status())) + + def _timer_substep(self, substep): + """log exe step""" + with self._lock: + self._substep = substep + now = datetime.now() + self._substep_time = (now - self._substep_ts).total_seconds() + self._substep_ts = now + self._logger.info("[{0}] {1}".format(self._substep_time, self.get_status())) def run(self): - """loop until stopped=finished""" + """loop one step a time until stopped=finished""" + self._set_timer_event(StepTimer.STARTED) while True: + self._timer_substep("waiting for timeout {0}...".format(self._interval)) self._timeout.wait(self._interval) + self._timer_substep("woke up after timeout") + if self._finished.is_set(): + self._timer_substep("finished") break - self._timeout.clear() - self._continue.clear() - if not self._paused.is_set(): + + if self._next.is_set(): + self._next.clear() + self._timeout.clear() + self._timer_substep("restart timer") + continue + + if self._paused.is_set(): + self._timer_substep("paused - skip on_time event") + else: + self._timer_substep("on_time event") self._on_time(*self._args, **self._kwargs) - self._continue.wait() + + self._timer_substep("waiting for next...") + self._next.wait() + self._next.clear() + self._timeout.clear() + self._timer_substep("woke up on next") + + if self._finished.is_set(): + self._timer_substep("finished") + break + + self._set_timer_event(StepTimer.STOPPED) -- cgit 1.2.3-korg