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

2 files changed, 40 insertions, 15 deletions

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 =========")