From 50bed534083c96cbf1f8fa4e220cb2b00dff9621 Mon Sep 17 00:00:00 2001 From: Alex Shatov Date: Fri, 27 Apr 2018 11:53:55 -0400 Subject: 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 Issue-ID: DCAEGEN2-472 --- etc/config.json | 2 +- policyhandler/onap/audit.py | 22 +++++-- policyhandler/policy_receiver.py | 5 +- policyhandler/policy_rest.py | 17 ++++-- policyhandler/policy_updater.py | 12 ++-- policyhandler/step_timer.py | 121 ++++++++++++++++++++++----------------- policyhandler/web_server.py | 16 ++++-- pom.xml | 2 +- setup.py | 2 +- tests/test_policyhandler.py | 49 +++++++++++----- tests/test_step_timer.py | 6 +- version.properties | 2 +- 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. org.onap.dcaegen2.platform policy-handler dcaegen2-platform-policy-handler - 2.4.1-SNAPSHOT + 2.4.2-SNAPSHOT http://maven.apache.org UTF-8 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, 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 -- cgit 1.2.3-korg