From 5105258de50958e3b060f961dd0ddc88d71b7560 Mon Sep 17 00:00:00 2001 From: Alex Shatov Date: Fri, 18 May 2018 15:13:40 -0400 Subject: 2.4.4 policy-handler - log process memory - in search of the memory leak that is falsely reported by docker stats, the following runtime logging was added = process_memory - rss and other memory of the current process = virtual_memory - the memory info of the whole system = thread_stacks - the active threads with the full stack on each Change-Id: I5f5ab3a477bfba3aecc5963547aa82da6269670b Signed-off-by: Alex Shatov Issue-ID: DCAEGEN2-514 --- tests/mock_settings.py | 64 ++++++++++++++ tests/test_policyhandler.py | 197 +++++++++++++++++++++++--------------------- tests/test_step_timer.py | 49 +++++------ tests/test_zzz_memory.py | 75 +++++++++++------ 4 files changed, 245 insertions(+), 140 deletions(-) create mode 100644 tests/mock_settings.py (limited to 'tests') diff --git a/tests/mock_settings.py b/tests/mock_settings.py new file mode 100644 index 0000000..f211dde --- /dev/null +++ b/tests/mock_settings.py @@ -0,0 +1,64 @@ +# ============LICENSE_START======================================================= +# Copyright (c) 2018 AT&T Intellectual Property. All rights reserved. +# ================================================================================ +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# ============LICENSE_END========================================================= +# +# ECOMP is a trademark and service mark of AT&T Intellectual Property. + +import json +import logging +import subprocess +import sys +import uuid +from datetime import datetime + +from policyhandler.config import Config +from policyhandler.onap.audit import Audit +from policyhandler.policy_handler import LogWriter + +try: + POLICY_HANDLER_VERSION = subprocess.check_output(["python", "setup.py", "--version"]).strip() +except subprocess.CalledProcessError: + POLICY_HANDLER_VERSION = "2.4.1" + + +class Settings(object): + """init all locals""" + logger = None + RUN_TS = datetime.utcnow().isoformat()[:-3] + 'Z' + dicovered_config = None + deploy_handler_instance_uuid = str(uuid.uuid4()) + + @staticmethod + def init(): + """init configs""" + Config.load_from_file() + + with open("etc_upload/config.json", 'r') as config_json: + Settings.dicovered_config = json.load(config_json) + + Config.load_from_file("etc_upload/config.json") + + Config.config["catch_up"] = {"interval": 10, "max_skips": 2} + + Settings.logger = logging.getLogger("policy_handler.unit_test") + sys.stdout = LogWriter(Settings.logger.info) + sys.stderr = LogWriter(Settings.logger.error) + + print "print ========== run_policy_handler ==========" + Settings.logger.info("========== run_policy_handler ==========") + Audit.init(Config.get_system_name(), POLICY_HANDLER_VERSION, Config.LOGGER_CONFIG_FILE_PATH) + + Settings.logger.info("starting policy_handler with config:") + Settings.logger.info(Audit.log_json_dumps(Config.config)) diff --git a/tests/test_policyhandler.py b/tests/test_policyhandler.py index c1176a9..f2dd9eb 100644 --- a/tests/test_policyhandler.py +++ b/tests/test_policyhandler.py @@ -20,15 +20,12 @@ import copy import json -import logging import re -import subprocess -import sys import time import uuid -from datetime import datetime import pytest + import cherrypy from cherrypy.test.helper import CPWebCase @@ -36,23 +33,21 @@ from policyhandler.config import Config from policyhandler.deploy_handler import DeployHandler from policyhandler.discovery import DiscoveryClient from policyhandler.onap.audit import (REQUEST_X_ECOMP_REQUESTID, Audit, - AuditHttpCode, Metrics) + AuditHttpCode) from policyhandler.policy_consts import (ERRORED_POLICIES, ERRORED_SCOPES, LATEST_POLICIES, POLICY_BODY, POLICY_CONFIG, POLICY_ID, POLICY_NAME, POLICY_VERSION, SCOPE_PREFIXES) -from policyhandler.policy_handler import LogWriter from policyhandler.policy_receiver import (LOADED_POLICIES, POLICY_VER, REMOVED_POLICIES, PolicyReceiver) from policyhandler.policy_rest import PolicyRest from policyhandler.policy_utils import PolicyUtils, Utils from policyhandler.web_server import _PolicyWeb -try: - POLICY_HANDLER_VERSION = subprocess.check_output(["python", "setup.py", "--version"]).strip() -except subprocess.CalledProcessError: - POLICY_HANDLER_VERSION = "2.4.1" +from .mock_settings import Settings + +Settings.init() class MonkeyHttpResponse(object): """Monkey http reposne""" @@ -101,40 +96,6 @@ def fix_discovery(monkeypatch): Settings.logger.info("teardown fix_discovery") -class Settings(object): - """init all locals""" - logger = None - RUN_TS = datetime.utcnow().isoformat()[:-3] + 'Z' - dicovered_config = None - deploy_handler_instance_uuid = str(uuid.uuid4()) - - @staticmethod - def init(): - """init configs""" - Config.load_from_file() - - with open("etc_upload/config.json", 'r') as config_json: - Settings.dicovered_config = json.load(config_json) - - Config.load_from_file("etc_upload/config.json") - - Config.config["catch_up"] = {"interval": 10, "max_skips": 2} - - Settings.logger = logging.getLogger("policy_handler.unit_test") - sys.stdout = LogWriter(Settings.logger.info) - sys.stderr = LogWriter(Settings.logger.error) - - print "print ========== run_policy_handler ==========" - Settings.logger.info("========== run_policy_handler ==========") - Audit.init(Config.get_system_name(), POLICY_HANDLER_VERSION, Config.LOGGER_CONFIG_FILE_PATH) - - 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 @@ -169,6 +130,7 @@ class MonkeyPolicyEngine(object): """pretend this is the policy-engine""" _scope_prefix = Config.config["scope_prefixes"][0] LOREM_IPSUM = """Lorem ipsum dolor sit amet consectetur ametist""".split() + LONG_TEXT = "0123456789" * 100 _policies = [] @staticmethod @@ -191,11 +153,21 @@ class MonkeyPolicyEngine(object): for policy in MonkeyPolicyEngine._policies if re.match(policy_name, policy[POLICY_NAME])] + @staticmethod + def get_configs_all(): + """get all policies the way the policy-engine finds""" + policies = [copy.deepcopy(policy) + for policy in MonkeyPolicyEngine._policies] + for policy in policies: + policy["config"] = MonkeyPolicyEngine.LONG_TEXT + return policies + @staticmethod def get_policy_id(policy_index): """get the policy_id by index""" - return MonkeyPolicyEngine._scope_prefix \ - + MonkeyPolicyEngine.LOREM_IPSUM[policy_index % len(MonkeyPolicyEngine.LOREM_IPSUM)] + return (MonkeyPolicyEngine._scope_prefix + + MonkeyPolicyEngine.LOREM_IPSUM[ + policy_index % len(MonkeyPolicyEngine.LOREM_IPSUM)]) @staticmethod def gen_policy_latest(policy_index): @@ -250,6 +222,23 @@ def fix_pdp_post(monkeypatch): yield fix_pdp_post # provide the fixture value Settings.logger.info("teardown fix_pdp_post") + +@pytest.fixture() +def fix_pdp_post_big(monkeypatch): + """monkeyed request /getConfig to PDP""" + def monkeyed_policy_rest_post(full_path, json=None, headers=None): + """monkeypatch for the POST to policy-engine""" + res_json = MonkeyPolicyEngine.get_configs_all() + return MonkeyedResponse(full_path, res_json, json, headers) + + Settings.logger.info("setup fix_pdp_post_big") + PolicyRest._lazy_init() + monkeypatch.setattr('policyhandler.policy_rest.PolicyRest._requests_session.post', + monkeyed_policy_rest_post) + yield fix_pdp_post_big # provide the fixture value + Settings.logger.info("teardown fix_pdp_post_big") + + class MockException(Exception): """mock exception""" pass @@ -289,18 +278,18 @@ def fix_select_latest_policies_boom(monkeypatch): yield fix_select_latest_policies_boom Settings.logger.info("teardown fix_select_latest_policies_boom") -def monkeyed_deploy_handler(full_path, json=None, headers=None): - """monkeypatch for deploy_handler""" - return MonkeyedResponse( - full_path, - {"server_instance_uuid": Settings.deploy_handler_instance_uuid}, - json, headers - ) - @pytest.fixture() def fix_deploy_handler(monkeypatch, fix_discovery): """monkeyed discovery request.get""" + def monkeyed_deploy_handler(full_path, json=None, headers=None): + """monkeypatch for deploy_handler""" + return MonkeyedResponse( + full_path, + {"server_instance_uuid": Settings.deploy_handler_instance_uuid}, + json, headers + ) + Settings.logger.info("setup fix_deploy_handler") audit = Audit(req_message="fix_deploy_handler") DeployHandler._lazy_init(audit) @@ -310,6 +299,39 @@ def fix_deploy_handler(monkeypatch, fix_discovery): Settings.logger.info("teardown fix_deploy_handler") +@pytest.fixture() +def fix_deploy_handler_fail(monkeypatch, fix_discovery): + """monkeyed failed discovery request.get""" + def monkeyed_deploy_handler(full_path, json=None, headers=None): + """monkeypatch for deploy_handler""" + res = MonkeyedResponse( + full_path, + {"server_instance_uuid": Settings.deploy_handler_instance_uuid}, + json, headers + ) + res.status_code = 413 + return res + + @staticmethod + def monkeyed_deploy_handler_init(audit_ignore, rediscover=False): + """monkeypatch for deploy_handler init""" + DeployHandler._url = None + + Settings.logger.info("setup fix_deploy_handler_fail") + config_catch_up = Config.config["catch_up"] + Config.config["catch_up"] = {"interval": 1, "max_skips": 0} + + audit = Audit(req_message="fix_deploy_handler_fail") + DeployHandler._lazy_init(audit, rediscover=True) + monkeypatch.setattr('policyhandler.deploy_handler.DeployHandler._requests_session.post', + monkeyed_deploy_handler) + monkeypatch.setattr('policyhandler.deploy_handler.DeployHandler._lazy_init', + monkeyed_deploy_handler_init) + yield fix_deploy_handler_fail + Settings.logger.info("teardown fix_deploy_handler_fail") + Config.config["catch_up"] = config_catch_up + + def monkeyed_cherrypy_engine_exit(): """monkeypatch for deploy_handler""" Settings.logger.info("cherrypy_engine_exit()") @@ -404,45 +426,6 @@ def test_get_policy_latest(fix_pdp_post): assert Utils.are_the_same(policy_latest, expected_policy) -def test_healthcheck(): - """test /healthcheck""" - audit = Audit(job_name="test_healthcheck", - req_message="get /healthcheck") - metrics = Metrics(aud_parent=audit, targetEntity="test_healthcheck") - metrics.metrics_start("test /healthcheck") - time.sleep(0.1) - - metrics.metrics("test /healthcheck") - health = audit.health(full=True) - 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(job_name="test_healthcheck_with_error", - req_message="get /healthcheck") - metrics = Metrics(aud_parent=audit, targetEntity="test_healthcheck_with_error") - metrics.metrics_start("test /healthcheck") - time.sleep(0.2) - audit.error("error from test_healthcheck_with_error") - audit.fatal("fatal from test_healthcheck_with_error") - audit.debug("debug from test_healthcheck_with_error") - audit.warn("debug from test_healthcheck_with_error") - audit.info_requested("debug from 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) - metrics.metrics("test /healthcheck") - - health = audit.health(full=True) - audit.audit_done(result=json.dumps(health)) - - Settings.logger.info("healthcheck: %s", json.dumps(health)) - assert bool(health) - @pytest.mark.usefixtures("fix_pdp_post") class WebServerTest(CPWebCase): @@ -943,3 +926,31 @@ class WebServerInternalBoomTest(CPWebCase): self.assertStatus('200 OK') Settings.logger.info("got shutdown: %s", self.body) time.sleep(1) + + +@pytest.mark.usefixtures( + "fix_pdp_post_big", + "fix_deploy_handler_fail", + "fix_policy_receiver_websocket" +) +def test_catch_ups_failed_dh(): + """test run policy handler with catchups and failed deployment-handler""" + Settings.logger.info("start test_catch_ups_failed_dh") + audit = Audit(job_name="test_catch_ups_failed_dh", + req_message="start test_catch_ups_failed_dh") + PolicyReceiver.run(audit) + + Settings.logger.info("sleep 50 before shutdown...") + time.sleep(50) + + health = audit.health(full=True) + audit.audit_done(result=json.dumps(health)) + + Settings.logger.info("healthcheck: %s", json.dumps(health)) + assert bool(health) + + PolicyReceiver.shutdown(audit) + time.sleep(1) + + health = audit.health(full=True) + Settings.logger.info("healthcheck: %s", json.dumps(health)) diff --git a/tests/test_step_timer.py b/tests/test_step_timer.py index 631a44f..808f99e 100644 --- a/tests/test_step_timer.py +++ b/tests/test_step_timer.py @@ -29,7 +29,7 @@ from policyhandler.step_timer import StepTimer Config.load_from_file() -class MockTimer(object): +class MockTimerController(object): """testing step_timer""" logger = logging.getLogger("policy_handler.unit_test.step_timer") @@ -50,7 +50,7 @@ class MockTimer(object): self.status_ts = datetime.utcnow() self.exe_ts = None self.exe_interval = None - self.set_status(MockTimer.INIT) + self.set_status(MockTimerController.INIT) def __enter__(self): """constructor""" @@ -64,65 +64,66 @@ class MockTimer(object): """timer event""" self.exe_ts = datetime.utcnow() self.exe_interval = (self.exe_ts - self.status_ts).total_seconds() - MockTimer.logger.info("run on_time[%s] (%s, %s) in %s for %s", - self.run_counter, json.dumps(args), json.dumps(kwargs), - self.exe_interval, self.get_status()) + MockTimerController.logger.info("run on_time[%s] (%s, %s) in %s for %s", + self.run_counter, json.dumps(args), json.dumps(kwargs), + self.exe_interval, self.get_status()) time.sleep(3) - MockTimer.logger.info("done on_time[%s] (%s, %s) in %s for %s", - self.run_counter, json.dumps(args), json.dumps(kwargs), - self.exe_interval, self.get_status()) + MockTimerController.logger.info("done on_time[%s] (%s, %s) in %s for %s", + self.run_counter, json.dumps(args), json.dumps(kwargs), + self.exe_interval, self.get_status()) def verify_last_event(self): """assertions needs to be in the main thread""" if self.exe_interval is None: - MockTimer.logger.info("not executed: %s", self.get_status()) + MockTimerController.logger.info("not executed: %s", self.get_status()) return - MockTimer.logger.info("verify exe %s for %s", self.exe_interval, self.get_status()) + MockTimerController.logger.info("verify exe %s for %s", + self.exe_interval, self.get_status()) assert self.exe_interval >= self.interval assert self.exe_interval < 2 * self.interval - MockTimer.logger.info("success %s", self.get_status()) + MockTimerController.logger.info("success %s", self.get_status()) def run_timer(self): """create and start the step_timer""" if self.step_timer: self.step_timer.next() - self.set_status(MockTimer.NEXT) + self.set_status(MockTimerController.NEXT) return self.step_timer = StepTimer( - self.name, self.interval, MockTimer.on_time, - MockTimer.logger, + self.name, self.interval, MockTimerController.on_time, + MockTimerController.logger, self ) self.step_timer.start() - self.set_status(MockTimer.STARTED) + self.set_status(MockTimerController.STARTED) def pause_timer(self): """pause step_timer""" if self.step_timer: self.step_timer.pause() - self.set_status(MockTimer.PAUSED) + self.set_status(MockTimerController.PAUSED) def stop_timer(self): """stop step_timer""" if self.step_timer: - self.set_status(MockTimer.STOPPING) + self.set_status(MockTimerController.STOPPING) self.step_timer.stop() self.step_timer.join() self.step_timer = None - self.set_status(MockTimer.STOPPED) + self.set_status(MockTimerController.STOPPED) def set_status(self, status): """set the status of the timer""" - if status in [MockTimer.NEXT, MockTimer.STARTED]: + if status in [MockTimerController.NEXT, MockTimerController.STARTED]: self.run_counter += 1 self.status = status utcnow = datetime.utcnow() time_step = (utcnow - self.status_ts).total_seconds() self.status_ts = utcnow - MockTimer.logger.info("%s: %s", time_step, self.get_status()) + MockTimerController.logger.info("[%s]: %s", time_step, self.get_status()) def get_status(self): """string representation""" @@ -137,8 +138,8 @@ class MockTimer(object): def test_step_timer(): """test step_timer""" - MockTimer.logger.info("============ test_step_timer =========") - with MockTimer("step_timer", 5) as step_timer: + MockTimerController.logger.info("============ test_step_timer =========") + with MockTimerController("step_timer", 5) as step_timer: step_timer.run_timer() time.sleep(1) step_timer.verify_last_event() @@ -165,8 +166,8 @@ def test_step_timer(): def test_interrupt_step_timer(): """test step_timer""" - MockTimer.logger.info("============ test_interrupt_step_timer =========") - with MockTimer("step_timer", 5) as step_timer: + MockTimerController.logger.info("============ test_interrupt_step_timer =========") + with MockTimerController("step_timer", 5) as step_timer: step_timer.run_timer() time.sleep(1) step_timer.verify_last_event() diff --git a/tests/test_zzz_memory.py b/tests/test_zzz_memory.py index 31a8dea..e70cf59 100644 --- a/tests/test_zzz_memory.py +++ b/tests/test_zzz_memory.py @@ -20,20 +20,13 @@ import gc import json -import logging -import subprocess -import sys +import time -from policyhandler.config import Config -from policyhandler.onap.audit import Audit -from policyhandler.policy_handler import LogWriter +from policyhandler.onap.audit import Audit, AuditHttpCode, Metrics -Config.load_from_file() +from .mock_settings import Settings -try: - POLICY_HANDLER_VERSION = subprocess.check_output(["python", "setup.py", "--version"]).strip() -except subprocess.CalledProcessError: - POLICY_HANDLER_VERSION = "2.4.1" +Settings.init() class Node(object): """making the cycled objects""" @@ -44,16 +37,49 @@ class Node(object): return '%s(%s)' % (self.__class__.__name__, self.name) -def test_healthcheck_with_garbage(): +def test_healthcheck(): """test /healthcheck""" + audit = Audit(job_name="test_healthcheck", + req_message="get /healthcheck") + metrics = Metrics(aud_parent=audit, targetEntity="test_healthcheck") + metrics.metrics_start("test /healthcheck") + time.sleep(0.1) + + metrics.metrics("test /healthcheck") + health = audit.health(full=True) + audit.audit_done(result=json.dumps(health)) + + Settings.logger.info("healthcheck: %s", json.dumps(health)) + assert bool(health) - Audit.init(Config.get_system_name(), POLICY_HANDLER_VERSION, Config.LOGGER_CONFIG_FILE_PATH) +def test_healthcheck_with_error(): + """test /healthcheck""" + audit = Audit(job_name="test_healthcheck_with_error", + req_message="get /healthcheck") + metrics = Metrics(aud_parent=audit, targetEntity="test_healthcheck_with_error") + metrics.metrics_start("test /healthcheck") + time.sleep(0.2) + audit.error("error from test_healthcheck_with_error") + audit.fatal("fatal from test_healthcheck_with_error") + audit.debug("debug from test_healthcheck_with_error") + audit.warn("debug from test_healthcheck_with_error") + audit.info_requested("debug from 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) + metrics.metrics("test /healthcheck") - logger = logging.getLogger("policy_handler.unit_test_memory") - sys.stdout = LogWriter(logger.info) - sys.stderr = LogWriter(logger.error) + health = audit.health(full=True) + audit.audit_done(result=json.dumps(health)) + Settings.logger.info("healthcheck: %s", json.dumps(health)) + assert bool(health) + + +def test_healthcheck_with_garbage(): + """test /healthcheck""" + gc_found = gc.collect() gc.set_debug(gc.DEBUG_LEAK) node1 = Node("one") @@ -70,19 +96,22 @@ def test_healthcheck_with_garbage(): health = audit.health(full=True) audit.audit_done(result=json.dumps(health)) - logger.info("test_healthcheck_with_garbage[%s]: %s", gc_found, json.dumps(health)) + Settings.logger.info("test_healthcheck_with_garbage[%s]: %s", gc_found, json.dumps(health)) assert bool(health) assert bool(health.get("runtime", {}).get("gc", {}).get("gc_garbage")) - logger.info("clearing up garbage...") + Settings.logger.info("clearing up garbage...") for obj in gc.garbage: if isinstance(obj, Node): - logger.info("in garbage: %s 0x%x", obj, id(obj)) + Settings.logger.info("in garbage: %s 0x%x", obj, id(obj)) obj.next = None gc_found = gc.collect() - health = audit.health(full=True) - logger.info("after clear test_healthcheck_with_garbage[%s]: %s", gc_found, json.dumps(health)) - assert bool(health) + Settings.logger.info("after clear test_healthcheck_with_garbage[%s]: %s", + gc_found, json.dumps(audit.health(full=True))) - gc.set_debug(not gc.DEBUG_LEAK) + gc.set_debug(False) + + gc_found = gc.collect() + Settings.logger.info("after turned off gc debug test_healthcheck_with_garbage[%s]: %s", + gc_found, json.dumps(audit.health(full=True))) -- cgit 1.2.3-korg