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

4 files changed, 245 insertions, 140 deletions

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
@@ -192,10 +154,20 @@ class MonkeyPolicyEngine(object):
                 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)))