2.4.2 policy-handler - fixed race on step-timer

- fixed the bug of unpredictably stopping of the periodic catch-up
   step-timer due to thread race condition in policy-handler
  = added critical sections under the reentrant lock on every group
      of local var change in step-timer
- added more stats for healthcheck to track each type of
   job-operation separately
   = that helps narrowing down identifying the potential problems
- unit test coverage 76%

Change-Id: I92ddf6c92a3d225d9b87427e3edfb7f80669501a
Signed-off-by: Alex Shatov <alexs@att.com>
Issue-ID: DCAEGEN2-472

12 files changed, 162 insertions, 94 deletions

diff --git a/etc/config.json b/etc/config.json
index ea51ab9..35ed0b5 100644
--- a/etc/config.json
+++ b/etc/config.json
@@ -1,5 +1,5 @@
 {
-    "version" : "2.0.0",
+    "version" : "2.4.2",
     "wservice_port" : 25577,
     "policy_handler" : {
         "system" : "policy_handler"
diff --git a/policyhandler/onap/audit.py b/policyhandler/onap/audit.py
index c615d63..08dcd37 100644
--- a/policyhandler/onap/audit.py
+++ b/policyhandler/onap/audit.py
@@ -28,6 +28,7 @@
 import copy
 import json
 import os
+import re
 import subprocess
 import sys
 import time
@@ -48,6 +49,8 @@ AUDIT_REQUESTID = 'requestID'
 AUDIT_IPADDRESS = 'IPAddress'
 AUDIT_SERVER = 'server'
 AUDIT_TARGET_ENTITY = 'targetEntity'
+AUDIT_METRICS = 'metrics'
+AUDIT_TOTAL_STATS = 'audit_total_stats'
 
 HEADER_CLIENTAUTH = "clientauth"
 HEADER_AUTHORIZATION = "authorization"
@@ -119,6 +122,7 @@ class Audit(object):
     _service_version = ""
     _service_instance_uuid = str(uuid.uuid4())
     _started = datetime.now()
+    _key_format = re.compile(r"\W")
     _logger_debug = None
     _logger_error = None
     _logger_metrics = None
@@ -160,14 +164,16 @@ class Audit(object):
             "packages" : Audit._packages
         }
 
-    def __init__(self, request_id=None, req_message=None, aud_parent=None, **kwargs):
+    def __init__(self, job_name=None, request_id=None, req_message=None, aud_parent=None, **kwargs):
         """create audit object per each request in the system
 
+        :job_name: is the name of the audit job for health stats
         :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.job_name = Audit._key_format.sub('_', job_name or req_message or Audit._service_name)
         self.request_id = request_id
         self.req_message = req_message or ""
         self.aud_parent = aud_parent
@@ -178,6 +184,8 @@ class Audit(object):
         self._lock = Lock()
 
         if self.aud_parent:
+            self.job_name = Audit._key_format.sub(
+                '_', job_name or self.aud_parent.job_name or Audit._service_name)
             if not self.request_id:
                 self.request_id = self.aud_parent.request_id
             if not self.req_message:
@@ -330,17 +338,19 @@ class Audit(object):
             self._get_response_status()
         metrics_func = None
         timer = Audit.get_elapsed_time(self._metrics_started)
+        metrics_job = Audit._key_format.sub(
+            '_', all_kwargs.get(AUDIT_TARGET_ENTITY, AUDIT_METRICS + "_" + self.job_name))
         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)
+            Audit._health.success(metrics_job, 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)
+            Audit._health.error(metrics_job, timer)
 
         metrics_func(log_line, begTime=self._metrics_start_event, timer=timer,
                      statusCode=Audit.get_status_code(success), responseCode=response_code.value,
@@ -363,13 +373,15 @@ class Audit(object):
             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)
+            Audit._health.success(self.job_name, timer)
+            Audit._health.success(AUDIT_TOTAL_STATS, 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._health.error(self.job_name, timer)
+            Audit._health.error(AUDIT_TOTAL_STATS, timer)
 
         audit_func(log_line, begTime=self._start_event, timer=timer,
                    statusCode=Audit.get_status_code(success),
diff --git a/policyhandler/policy_receiver.py b/policyhandler/policy_receiver.py
index 843dbd8..751bea8 100644
--- a/policyhandler/policy_receiver.py
+++ b/policyhandler/policy_receiver.py
@@ -136,8 +136,9 @@ class _PolicyReceiver(Thread):
             )
             return
 
-        audit = Audit(req_message="policy-notification - updated[{0}], removed[{1}]" \
-                        .format(len(policies_updated), len(policies_removed)))
+        audit = Audit(job_name="policy_update",
+                      req_message="policy-notification - updated[{0}], removed[{1}]"
+                      .format(len(policies_updated), len(policies_removed)))
         audit.retry_get_config = True
         self._policy_updater.enqueue(audit, policies_updated, policies_removed)
 
diff --git a/policyhandler/policy_rest.py b/policyhandler/policy_rest.py
index 4eee154..0c8920a 100644
--- a/policyhandler/policy_rest.py
+++ b/policyhandler/policy_rest.py
@@ -406,18 +406,26 @@ class PolicyRest(object):
 
         result = {}
         aud_policy_filters = None
+        str_policy_filters = None
         str_metrics = None
-        str_policy_filters = json.dumps(policy_filter or PolicyRest._scope_prefixes)
+        target_entity = None
+
         if policy_filter is not None:
             aud_policy_filters = [(audit, policy_filter, None)]
+            str_policy_filters = json.dumps(policy_filter)
             str_metrics = "get_latest_policies for policy_filter {0}".format(
                 str_policy_filters)
+            target_entity = ("{0} total get_latest_policies by policy_filter"
+                             .format(PolicyRest._target_entity))
             result[POLICY_FILTER] = copy.deepcopy(policy_filter)
         else:
             aud_policy_filters = [(audit, {POLICY_NAME:scope_prefix + ".*"}, scope_prefix)
                                   for scope_prefix in PolicyRest._scope_prefixes]
+            str_policy_filters = json.dumps(PolicyRest._scope_prefixes)
             str_metrics = "get_latest_policies for scopes {0} {1}".format( \
                 len(PolicyRest._scope_prefixes), str_policy_filters)
+            target_entity = ("{0} total get_latest_policies by scope_prefixes"
+                             .format(PolicyRest._target_entity))
             result[SCOPE_PREFIXES] = copy.deepcopy(PolicyRest._scope_prefixes)
 
         PolicyRest._logger.debug("%s", str_policy_filters)
@@ -433,9 +441,10 @@ class PolicyRest(object):
             pool.close()
             pool.join()
 
-        audit.metrics("total result {0}: {1} {2}".format(
-            str_metrics, len(latest_policies), json.dumps(latest_policies)), \
-            targetEntity=PolicyRest._target_entity, targetServiceName=PolicyRest._url_get_config)
+        audit.metrics(
+            "total result {0}: {1} {2}".format(
+                str_metrics, len(latest_policies), json.dumps(latest_policies)),
+            targetEntity=target_entity, targetServiceName=PolicyRest._url_get_config)
 
         # latest_policies == [(valid_policies, errored_policies, errored_scope_prefix), ...]
         result[LATEST_POLICIES] = dict(
diff --git a/policyhandler/policy_updater.py b/policyhandler/policy_updater.py
index 0b9e227..70823fa 100644
--- a/policyhandler/policy_updater.py
+++ b/policyhandler/policy_updater.py
@@ -47,7 +47,7 @@ class PolicyUpdater(Thread):
         self._aud_shutdown = None
         self._aud_catch_up = None
 
-        catch_up_config = Config.config.get("catch_up", {})
+        catch_up_config = Config.config.get(CATCH_UP, {})
         self._catch_up_interval = catch_up_config.get("interval") or 15*60
         self._catch_up_max_skips = catch_up_config.get("max_skips") or 3
         self._catch_up_skips = 0
@@ -120,8 +120,10 @@ class PolicyUpdater(Thread):
         """need to bring the latest policies to DCAE-Controller"""
         with self._lock:
             self._aud_catch_up = audit or Audit(req_message=AUTO_CATCH_UP)
-            PolicyUpdater._logger.info("catch_up %s request_id %s",
-                self._aud_catch_up.req_message, self._aud_catch_up.request_id)
+            PolicyUpdater._logger.info(
+                "catch_up %s request_id %s",
+                self._aud_catch_up.req_message, self._aud_catch_up.request_id
+            )
 
         self.enqueue()
 
@@ -131,8 +133,8 @@ class PolicyUpdater(Thread):
             return
 
         if self._catch_up_timer:
-            self._catch_up_timer.next()
             self._logger.info("next step catch_up_timer in %s", self._catch_up_interval)
+            self._catch_up_timer.next()
             return
 
         self._catch_up_timer = StepTimer(
@@ -142,8 +144,8 @@ class PolicyUpdater(Thread):
             PolicyUpdater._logger,
             self
         )
-        self._catch_up_timer.start()
         self._logger.info("started catch_up_timer in %s", self._catch_up_interval)
+        self._catch_up_timer.start()
 
     def _pause_catch_up_timer(self):
         """pause catch_up_timer"""
diff --git a/policyhandler/step_timer.py b/policyhandler/step_timer.py
index ad77c85..3936107 100644
--- a/policyhandler/step_timer.py
+++ b/policyhandler/step_timer.py
@@ -19,7 +19,7 @@
 """periodically callback"""
 
 from datetime import datetime
-from threading import Event, Lock, Thread
+from threading import Event, RLock, Thread
 
 
 class StepTimer(Thread):
@@ -40,67 +40,75 @@ class StepTimer(Thread):
         self._args = args
         self._kwargs = kwargs
 
-        self._lock = Lock()
+        self._lock = RLock()
 
         self._timeout = Event()
-        self._paused = Event()
+        self._waiting_for_timeout = False
         self._next = Event()
-        self._finished = Event()
+        self._paused = False
+        self._finished = False
 
-        self._event = StepTimer.INIT
-        self._event_counter = 0
-        self._event_time = 0
-        self._event_ts = datetime.now()
+        self._request = StepTimer.INIT
+        self._req_count = 0
+        self._req_time = 0
+        self._req_ts = datetime.now()
 
         self._substep = None
         self._substep_time = 0
         self._substep_ts = datetime.now()
 
-    def get_status(self):
-        """returns status of events"""
+    def get_timer_status(self):
+        """returns timer status"""
         with self._lock:
             return "{0}[{1}] {2}: timeout({3}), paused({4}), next({5}), finished({6})".format(
-                self._event,
-                self._event_counter,
+                self._request,
+                self._req_count,
                 self._substep,
                 self._timeout.is_set(),
-                self._paused.is_set(),
+                self._paused,
                 self._next.is_set(),
-                self._finished.is_set(),
+                self._finished,
             )
 
     def next(self):
         """continue with the next timeout"""
-        self._paused.clear()
-        self._next.set()
-        self._timeout.set()
-        self._set_timer_event(StepTimer.NEXT)
+        with self._lock:
+            self._paused = False
+            if self._waiting_for_timeout:
+                self._next.set()
+                self._timeout.set()
+            else:
+                self._next.set()
+            self._request_to_timer(StepTimer.NEXT)
 
     def pause(self):
         """pause the timer"""
-        self._paused.set()
-        self._next.clear()
-        self._set_timer_event(StepTimer.PAUSED)
+        with self._lock:
+            self._paused = True
+            self._next.clear()
+            self._request_to_timer(StepTimer.PAUSED)
 
     def stop(self):
         """stop the timer if it hasn't finished yet"""
-        self._finished.set()
-        self._timeout.set()
-        self._next.set()
-        self._set_timer_event(StepTimer.STOPPING)
+        with self._lock:
+            self._finished = True
+            self._timeout.set()
+            self._next.set()
+            self._request_to_timer(StepTimer.STOPPING)
 
-    def _set_timer_event(self, event):
-        """set the event on the timer"""
+    def _request_to_timer(self, request):
+        """set the request on the timer"""
         with self._lock:
-            if event in [StepTimer.NEXT, StepTimer.STARTED]:
-                self._event_counter += 1
+            if request in [StepTimer.NEXT, StepTimer.STARTED]:
+                self._req_count += 1
 
-            self._event = event
+            prev_req = self._request
+            self._request = request
             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()))
+            self._req_time = (now - self._req_ts).total_seconds()
+            self._req_ts = now
+            self._logger.info("{0}[{1}] {2}->{3}".format(
+                self.name, self._req_time, prev_req, self.get_timer_status()))
 
     def _timer_substep(self, substep):
         """log exe step"""
@@ -109,27 +117,34 @@ class StepTimer(Thread):
             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()))
+            self._logger.info("[{0}] {1}".format(self._substep_time, self.get_timer_status()))
 
     def run(self):
         """loop one step a time until stopped=finished"""
-        self._set_timer_event(StepTimer.STARTED)
+        self._request_to_timer(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")
+            with self._lock:
+                self._timeout.clear()
+                self._waiting_for_timeout = True
+                self._timer_substep("waiting for timeout {0}...".format(self._interval))
 
-            if self._finished.is_set():
-                self._timer_substep("finished")
-                break
+            interrupted = self._timeout.wait(self._interval)
 
-            if self._next.is_set():
-                self._next.clear()
-                self._timeout.clear()
-                self._timer_substep("restart timer")
-                continue
+            with self._lock:
+                self._waiting_for_timeout = False
+                self._timer_substep("woke up after {0}timeout"
+                                    .format((interrupted and "interrupted ") or ""))
+
+                if self._finished:
+                    self._timer_substep("finished")
+                    break
 
-            if self._paused.is_set():
+                if self._next.is_set() and interrupted:
+                    self._next.clear()
+                    self._timer_substep("restart timer")
+                    continue
+
+            if self._paused:
                 self._timer_substep("paused - skip on_time event")
             else:
                 self._timer_substep("on_time event")
@@ -137,12 +152,12 @@ class StepTimer(Thread):
 
             self._timer_substep("waiting for next...")
             self._next.wait()
-            self._next.clear()
-            self._timeout.clear()
-            self._timer_substep("woke up on next")
+            with self._lock:
+                self._next.clear()
+                self._timer_substep("woke up on next")
 
-            if self._finished.is_set():
+            if self._finished:
                 self._timer_substep("finished")
                 break
 
-        self._set_timer_event(StepTimer.STOPPED)
+        self._request_to_timer(StepTimer.STOPPED)
diff --git a/policyhandler/web_server.py b/policyhandler/web_server.py
index 20e74e3..e9cc9cc 100644
--- a/policyhandler/web_server.py
+++ b/policyhandler/web_server.py
@@ -56,7 +56,8 @@ class _PolicyWeb(object):
     def policy_latest(self, policy_id):
         """retireves the latest policy identified by policy_id"""
         req_info = _PolicyWeb._get_request_info(cherrypy.request)
-        audit = Audit(req_message=req_info, headers=cherrypy.request.headers)
+        audit = Audit(job_name="get_latest_policy",
+                      req_message=req_info, headers=cherrypy.request.headers)
         PolicyWeb.logger.info("%s policy_id=%s headers=%s", \
             req_info, policy_id, json.dumps(cherrypy.request.headers))
 
@@ -74,7 +75,8 @@ class _PolicyWeb(object):
     def _get_all_policies_latest(self):
         """retireves all the latest policies on GET /policies_latest"""
         req_info = _PolicyWeb._get_request_info(cherrypy.request)
-        audit = Audit(req_message=req_info, headers=cherrypy.request.headers)
+        audit = Audit(job_name="get_all_policies_latest",
+                      req_message=req_info, headers=cherrypy.request.headers)
 
         PolicyWeb.logger.info("%s", req_info)
 
@@ -146,7 +148,8 @@ class _PolicyWeb(object):
         str_policy_filter = json.dumps(policy_filter)
 
         req_info = _PolicyWeb._get_request_info(cherrypy.request)
-        audit = Audit(req_message="{0}: {1}".format(req_info, str_policy_filter), \
+        audit = Audit(job_name="get_latest_policies",
+                      req_message="{0}: {1}".format(req_info, str_policy_filter), \
             headers=cherrypy.request.headers)
         PolicyWeb.logger.info("%s: policy_filter=%s headers=%s", \
             req_info, str_policy_filter, json.dumps(cherrypy.request.headers))
@@ -168,7 +171,7 @@ class _PolicyWeb(object):
         """catch up with all DCAE policies"""
         started = str(datetime.now())
         req_info = _PolicyWeb._get_request_info(cherrypy.request)
-        audit = Audit(req_message=req_info, headers=cherrypy.request.headers)
+        audit = Audit(job_name="catch_up", req_message=req_info, headers=cherrypy.request.headers)
 
         PolicyWeb.logger.info("%s", req_info)
         PolicyReceiver.catch_up(audit)
@@ -182,7 +185,7 @@ class _PolicyWeb(object):
     def shutdown(self):
         """Shutdown the policy-handler"""
         req_info = _PolicyWeb._get_request_info(cherrypy.request)
-        audit = Audit(req_message=req_info, headers=cherrypy.request.headers)
+        audit = Audit(job_name="shutdown", req_message=req_info, headers=cherrypy.request.headers)
 
         PolicyWeb.logger.info("%s: --- stopping REST API of policy-handler ---", req_info)
 
@@ -203,7 +206,8 @@ class _PolicyWeb(object):
     def healthcheck(self):
         """returns the healthcheck results"""
         req_info = _PolicyWeb._get_request_info(cherrypy.request)
-        audit = Audit(req_message=req_info, headers=cherrypy.request.headers)
+        audit = Audit(job_name="healthcheck",
+                      req_message=req_info, headers=cherrypy.request.headers)
 
         PolicyWeb.logger.info("%s", req_info)
 
diff --git a/pom.xml b/pom.xml
index 65e8ec1..aca0cdd 100644
--- a/pom.xml
+++ b/pom.xml
@@ -30,7 +30,7 @@ ECOMP is a trademark and service mark of AT&T Intellectual Property.
   <groupId>org.onap.dcaegen2.platform</groupId>
   <artifactId>policy-handler</artifactId>
   <name>dcaegen2-platform-policy-handler</name>
-  <version>2.4.1-SNAPSHOT</version>
+  <version>2.4.2-SNAPSHOT</version>
   <url>http://maven.apache.org</url>
   <properties>
     <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
diff --git a/setup.py b/setup.py
index 386e578..f6de927 100644
--- a/setup.py
+++ b/setup.py
@@ -23,7 +23,7 @@ from setuptools import setup
 setup(

     name='policyhandler',

     description='DCAE-Controller policy-handler to communicate with policy-engine',

-    version="2.4.1",

+    version="2.4.2",

     author='Alex Shatov',

     packages=['policyhandler'],

     zip_safe=False,

diff --git a/tests/test_policyhandler.py b/tests/test_policyhandler.py
index 72cb857..4a5fdf6 100644
--- a/tests/test_policyhandler.py
+++ b/tests/test_policyhandler.py
@@ -53,11 +53,13 @@ try:
 except subprocess.CalledProcessError:
     POLICY_HANDLER_VERSION = "2.4.1"
 
+
 class MonkeyHttpResponse(object):
     """Monkey http reposne"""
     def __init__(self, headers):
         self.headers = headers or {}
 
+
 class MonkeyedResponse(object):
     """Monkey response"""
     def __init__(self, full_path, res_json, json_body=None, headers=None):
@@ -76,6 +78,7 @@ class MonkeyedResponse(object):
         """ignoring"""
         pass
 
+
 def monkeyed_discovery(full_path):
     """monkeypatch for get from consul"""
     res_json = {}
@@ -88,6 +91,7 @@ def monkeyed_discovery(full_path):
         res_json = copy.deepcopy(Settings.dicovered_config)
     return MonkeyedResponse(full_path, res_json)
 
+
 @pytest.fixture()
 def fix_discovery(monkeypatch):
     """monkeyed discovery request.get"""
@@ -96,6 +100,7 @@ def fix_discovery(monkeypatch):
     yield fix_discovery  # provide the fixture value
     Settings.logger.info("teardown fix_discovery")
 
+
 class Settings(object):
     """init all locals"""
     logger = None
@@ -113,7 +118,7 @@ class Settings(object):
 
         Config.load_from_file("etc_upload/config.json")
 
-        Config.config["catch_up"] = {"interval" : 10, "max_skips" : 2}
+        Config.config["catch_up"] = {"interval": 10, "max_skips": 2}
 
         Settings.logger = logging.getLogger("policy_handler.unit_test")
         sys.stdout = LogWriter(Settings.logger.info)
@@ -126,8 +131,10 @@ class Settings(object):
         Settings.logger.info("starting policy_handler with config:")
         Settings.logger.info(Audit.log_json_dumps(Config.config))
 
+
 Settings.init()
 
+
 class MonkeyPolicyBody(object):
     """policy body that policy-engine returns"""
     @staticmethod
@@ -157,6 +164,7 @@ class MonkeyPolicyBody(object):
             "property": None
         }
 
+
 class MonkeyPolicyEngine(object):
     """pretend this is the policy-engine"""
     _scope_prefix = Config.config["scope_prefixes"][0]
@@ -194,8 +202,8 @@ class MonkeyPolicyEngine(object):
         """generate the policy response by policy_index = version - 1"""
         policy_id = MonkeyPolicyEngine.get_policy_id(policy_index)
         expected_policy = {
-            POLICY_ID : policy_id,
-            POLICY_BODY : MonkeyPolicyBody.create_policy_body(policy_id, policy_index + 1)
+            POLICY_ID: policy_id,
+            POLICY_BODY: MonkeyPolicyBody.create_policy_body(policy_id, policy_index + 1)
         }
         return policy_id, PolicyUtils.parse_policy_config(expected_policy)
 
@@ -226,11 +234,13 @@ class MonkeyPolicyEngine(object):
 
 MonkeyPolicyEngine.init()
 
+
 def monkeyed_policy_rest_post(full_path, json=None, headers=None):
     """monkeypatch for the POST to policy-engine"""
     res_json = MonkeyPolicyEngine.get_config(json.get(POLICY_NAME))
     return MonkeyedResponse(full_path, res_json, json, headers)
 
+
 @pytest.fixture()
 def fix_pdp_post(monkeypatch):
     """monkeyed request /getConfig to PDP"""
@@ -241,6 +251,7 @@ def fix_pdp_post(monkeypatch):
     yield fix_pdp_post  # provide the fixture value
     Settings.logger.info("teardown fix_pdp_post")
 
+
 def monkeyed_deploy_handler(full_path, json=None, headers=None):
     """monkeypatch for deploy_handler"""
     return MonkeyedResponse(full_path,
@@ -248,6 +259,7 @@ def monkeyed_deploy_handler(full_path, json=None, headers=None):
         json, headers
     )
 
+
 @pytest.fixture()
 def fix_deploy_handler(monkeypatch, fix_discovery):
     """monkeyed discovery request.get"""
@@ -259,10 +271,12 @@ def fix_deploy_handler(monkeypatch, fix_discovery):
     yield fix_deploy_handler  # provide the fixture value
     Settings.logger.info("teardown fix_deploy_handler")
 
+
 def monkeyed_cherrypy_engine_exit():
     """monkeypatch for deploy_handler"""
     Settings.logger.info("cherrypy_engine_exit()")
 
+
 @pytest.fixture()
 def fix_cherrypy_engine_exit(monkeypatch):
     """monkeyed cherrypy.engine.exit()"""
@@ -272,6 +286,7 @@ def fix_cherrypy_engine_exit(monkeypatch):
     yield fix_cherrypy_engine_exit  # provide the fixture value
     Settings.logger.info("teardown fix_cherrypy_engine_exit")
 
+
 class MonkeyedWebSocket(object):
     """Monkey websocket"""
     on_message = None
@@ -282,7 +297,7 @@ class MonkeyedWebSocket(object):
         if not MonkeyedWebSocket.on_message:
             return
         message = {
-            LOADED_POLICIES : [
+            LOADED_POLICIES: [
                 {POLICY_NAME: "{0}.{1}.xml".format(
                     MonkeyPolicyEngine.get_policy_id(policy_index), policy_index + 1),
                  POLICY_VER: str(policy_index + 1)}
@@ -327,6 +342,7 @@ class MonkeyedWebSocket(object):
             """close socket"""
             self.sock.connected = False
 
+
 @pytest.fixture()
 def fix_policy_receiver_websocket(monkeypatch):
     """monkeyed websocket for policy_receiver"""
@@ -335,11 +351,13 @@ def fix_policy_receiver_websocket(monkeypatch):
     yield fix_policy_receiver_websocket  # provide the fixture value
     Settings.logger.info("teardown fix_policy_receiver_websocket")
 
+
 def test_get_policy_latest(fix_pdp_post):
     """test /policy_latest/<policy-id>"""
     policy_id, expected_policy = MonkeyPolicyEngine.gen_policy_latest(3)
 
-    audit = Audit(req_message="get /policy_latest/{0}".format(policy_id or ""))
+    audit = Audit(job_name="test_get_policy_latest",
+                  req_message="get /policy_latest/{0}".format(policy_id or ""))
     policy_latest = PolicyRest.get_latest_policy((audit, policy_id, None, None)) or {}
     audit.audit_done(result=json.dumps(policy_latest))
 
@@ -347,22 +365,24 @@ def test_get_policy_latest(fix_pdp_post):
     Settings.logger.info("policy_latest: %s", json.dumps(policy_latest))
     assert Utils.are_the_same(policy_latest, expected_policy)
 
+
 def test_healthcheck():
     """test /healthcheck"""
-    audit = Audit(req_message="get /healthcheck")
+    audit = Audit(job_name="test_healthcheck", req_message="get /healthcheck")
     audit.metrics_start("test /healthcheck")
     time.sleep(0.1)
 
-    audit.metrics("test /healthcheck")
+    audit.metrics("test /healthcheck", targetEntity="test_healthcheck")
     health = Audit.health()
     audit.audit_done(result=json.dumps(health))
 
     Settings.logger.info("healthcheck: %s", json.dumps(health))
     assert bool(health)
 
+
 def test_healthcheck_with_error():
     """test /healthcheck"""
-    audit = Audit(req_message="get /healthcheck")
+    audit = Audit(job_name="test_healthcheck_with_error", req_message="get /healthcheck")
     audit.metrics_start("test /healthcheck")
     time.sleep(0.2)
     audit.error("error from test_healthcheck_with_error")
@@ -373,7 +393,7 @@ def test_healthcheck_with_error():
     if audit.is_success():
         audit.set_http_status_code(AuditHttpCode.DATA_NOT_FOUND_ERROR.value)
     audit.set_http_status_code(AuditHttpCode.SERVER_INTERNAL_ERROR.value)
-    audit.metrics("test /healthcheck")
+    audit.metrics("test /healthcheck", targetEntity="test_healthcheck_with_error")
 
     health = Audit.health()
     audit.audit_done(result=json.dumps(health))
@@ -381,6 +401,7 @@ def test_healthcheck_with_error():
     Settings.logger.info("healthcheck: %s", json.dumps(health))
     assert bool(health)
 
+
 @pytest.mark.usefixtures("fix_pdp_post")
 class WebServerTest(CPWebCase):
     """testing the web-server - runs tests in alphabetical order of method names"""
@@ -456,7 +477,8 @@ class WebServerTest(CPWebCase):
     def test_zzz_policy_updates_and_catch_ups(self):
         """test run policy handler with policy updates and catchups"""
         Settings.logger.info("start policy_updates_and_catch_ups")
-        audit = Audit(req_message="start policy_updates_and_catch_ups")
+        audit = Audit(job_name="test_zzz_policy_updates_and_catch_ups",
+                      req_message="start policy_updates_and_catch_ups")
         PolicyReceiver.run(audit)
 
         Settings.logger.info("sleep before send_notification...")
@@ -476,7 +498,8 @@ class WebServerTest(CPWebCase):
     def test_zzz_catch_up_on_deploy_handler_changed(self):
         """test run policy handler with deployment-handler changed underneath"""
         Settings.logger.info("start zzz_catch_up_on_deploy_handler_changed")
-        audit = Audit(req_message="start zzz_catch_up_on_deploy_handler_changed")
+        audit = Audit(job_name="test_zzz_catch_up_on_deploy_handler_changed",
+                      req_message="start zzz_catch_up_on_deploy_handler_changed")
         PolicyReceiver.run(audit)
 
         Settings.logger.info("sleep before send_notification...")
@@ -503,7 +526,7 @@ class WebServerTest(CPWebCase):
     def test_zzz_get_catch_up(self):
         """test /catch_up"""
         Settings.logger.info("start /catch_up")
-        audit = Audit(req_message="start /catch_up")
+        audit = Audit(job_name="test_zzz_get_catch_up", req_message="start /catch_up")
         PolicyReceiver.run(audit)
         time.sleep(5)
         result = self.getPage("/catch_up")
@@ -524,7 +547,7 @@ class WebServerTest(CPWebCase):
     def test_zzzzz_shutdown(self):
         """test shutdown"""
         Settings.logger.info("start shutdown")
-        audit = Audit(req_message="start shutdown")
+        audit = Audit(job_name="test_zzzzz_shutdown", req_message="start shutdown")
         PolicyReceiver.run(audit)
 
         Settings.logger.info("sleep before send_notification...")
diff --git a/tests/test_step_timer.py b/tests/test_step_timer.py
index fe2d1c1..a116f8c 100644
--- a/tests/test_step_timer.py
+++ b/tests/test_step_timer.py
@@ -20,7 +20,6 @@
 
 import json
 import logging
-import sys
 import time
 from datetime import datetime
 
@@ -29,6 +28,7 @@ from policyhandler.step_timer import StepTimer
 
 Config.load_from_file()
 
+
 class MockTimer(object):
     """testing step_timer"""
     logger = logging.getLogger("policy_handler.unit_test.step_timer")
@@ -131,9 +131,10 @@ class MockTimer(object):
             str(self.status_ts), str(self.exe_ts)
         )
         if self.step_timer:
-            return "{0}: {1}".format(status, self.step_timer.get_status())
+            return "{0}: {1}".format(status, self.step_timer.get_timer_status())
         return status
 
+
 def test_step_timer():
     """test step_timer"""
     MockTimer.logger.info("============ test_step_timer =========")
@@ -161,6 +162,7 @@ def test_step_timer():
         time.sleep(3 * step_timer.interval)
         step_timer.verify_last_event()
 
+
 def test_interrupt_step_timer():
     """test step_timer"""
     MockTimer.logger.info("============ test_interrupt_step_timer =========")
diff --git a/version.properties b/version.properties
index 0f14334..9ba4cb9 100644
--- a/version.properties
+++ b/version.properties
@@ -1,6 +1,6 @@
 major=2

 minor=4

-patch=1

+patch=2

 base_version=${major}.${minor}.${patch}

 release_version=${base_version}

 snapshot_version=${base_version}-SNAPSHOT