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 <alexs@att.com>
Issue-ID: DCAEGEN2-389

3 files changed, 111 insertions, 19 deletions

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)