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

14 files changed, 421 insertions, 205 deletions

diff --git a/etc/config.json b/etc/config.json
index 774142f..e54569b 100644
--- a/etc/config.json
+++ b/etc/config.json
@@ -1,5 +1,4 @@
 {
-    "version" : "2.4.3",
     "wservice_port" : 25577,
     "policy_handler" : {
         "system" : "policy_handler"
diff --git a/policyhandler/onap/audit.py b/policyhandler/onap/audit.py
index 48988fe..0aa1c50 100644
--- a/policyhandler/onap/audit.py
+++ b/policyhandler/onap/audit.py
@@ -26,7 +26,6 @@
 """
 
 import copy
-import gc
 import json
 import os
 import re
@@ -38,10 +37,9 @@ import uuid
 from datetime import datetime
 from enum import Enum
 
-import psutil
-
 from .CommonLogger import CommonLogger
 from .health import Health
+from .process_info import ProcessInfo
 
 REQUEST_X_ECOMP_REQUESTID = "X-ECOMP-RequestID"
 REQUEST_REMOTE_ADDR = "Remote-Addr"
@@ -117,58 +115,6 @@ class AuditResponseCode(Enum):
         return response_code.name.lower().replace("_", " ")
 
 
-class ProcessInfo(object):
-    """static class to calculate process info"""
-    _KILO_SYMBOLS = ('KB', 'MB', 'GB', 'TB', 'PB', 'EB', 'ZB', 'YB')
-    _KILO_POWERS = {}
-
-    @staticmethod
-    def init():
-        """init static constants"""
-        for i, kilo_symbol in enumerate(ProcessInfo._KILO_SYMBOLS):
-            ProcessInfo._KILO_POWERS[kilo_symbol] = 1 << (i + 1) * 10
-        ProcessInfo._KILO_SYMBOLS = list(reversed(ProcessInfo._KILO_SYMBOLS))
-
-    @staticmethod
-    def bytes_to_human(byte_count):
-        """converts byte count to human value in kilo-powers"""
-        for kilo_symbol in ProcessInfo._KILO_SYMBOLS:
-            kilo_power = ProcessInfo._KILO_POWERS[kilo_symbol]
-            if byte_count >= kilo_power:
-                value = float(byte_count) / kilo_power
-                return '%.1f%s' % (value, kilo_symbol)
-        return "%sB" % byte_count
-
-    @staticmethod
-    def mem_info():
-        """calculates the memory usage of the current process"""
-        process = psutil.Process()
-        with process.oneshot():
-            mem = process.memory_full_info()
-            return {
-                "uss" : ProcessInfo.bytes_to_human(mem.uss),
-                "rss" : ProcessInfo.bytes_to_human(mem.rss),
-                "swap" : ProcessInfo.bytes_to_human(getattr(mem, "swap", 0)),
-                "pss" : ProcessInfo.bytes_to_human(getattr(mem, "pss", 0))
-            }
-
-
-    @staticmethod
-    def gc_info(full=False):
-        """gets info from garbage collector"""
-        gc_info = {
-            "gc_count" : str(gc.get_count()),
-            "gc_threshold" : str(gc.get_threshold())
-        }
-        try:
-            if gc.garbage:
-                gc_info["gc_garbage"] = ([repr(stuck) for stuck in gc.garbage]
-                                         if full else len(gc.garbage))
-        except Exception:
-            pass
-        return gc_info
-
-
 class _Audit(object):
     """put the audit object on stack per each initiating request in the system
 
@@ -226,17 +172,22 @@ class _Audit(object):
                 "started" : str(_Audit._started),
                 "utcnow" : str(utcnow),
                 "uptime" : str(utcnow - _Audit._started),
-                "active_threads" : sorted([thr.name for thr in threading.enumerate()]),
+                "active_threads" : ProcessInfo.active_threads(),
                 "gc" : ProcessInfo.gc_info(full),
-                "mem_info" : ProcessInfo.mem_info()
+                "virtual_memory" : ProcessInfo.virtual_memory(),
+                "process_memory" : ProcessInfo.process_memory()
             },
             "stats" : _Audit._health.dump(),
             "soft" : {"python" : _Audit._py_ver, "packages" : _Audit._packages}
         }
-        health_txt = "{} health: {}".format(_Audit._service_name, json.dumps(health))
-        self.info(health_txt)
+        self.info("{} health: {}".format(_Audit._service_name, json.dumps(health)))
         return health
 
+    def process_info(self):
+        """get the debug info on all the threads and memory"""
+        process_info = ProcessInfo.get_all()
+        self.info("{} process_info: {}".format(_Audit._service_name, json.dumps(process_info)))
+        return process_info
 
     def __init__(self, job_name=None, request_id=None, req_message=None, **kwargs):
         """create audit object per each request in the system
diff --git a/policyhandler/onap/process_info.py b/policyhandler/onap/process_info.py
new file mode 100644
index 0000000..9fb6334
--- /dev/null
+++ b/policyhandler/onap/process_info.py
@@ -0,0 +1,152 @@
+# ================================================================================
+# 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.
+
+"""generic class to keep get real time info about the current process"""
+
+import gc
+import sys
+import threading
+import traceback
+from functools import wraps
+
+import psutil
+
+
+def safe_operation(func):
+    """safequard the function against any exception"""
+    if not func:
+        return
+
+    @wraps(func)
+    def wrapper(*args, **kwargs):
+        """wrapper around the function"""
+        try:
+            return func(*args, **kwargs)
+        except Exception as ex:
+            return "%s: %s" % (type(ex).__name__, str(ex))
+    return wrapper
+
+
+class ProcessInfo(object):
+    """static class to calculate process info"""
+    _BIBYTES_SYMBOLS = ('KiB', 'MiB', 'GiB', 'TiB', 'PiB', 'EiB', 'ZiB', 'YiB')
+    _BIBYTES_VALS = {}
+    _inited = False
+    _lock = threading.Lock()
+
+    @staticmethod
+    def init():
+        """init static constants"""
+        if ProcessInfo._inited:
+            return
+        with ProcessInfo._lock:
+            if ProcessInfo._inited:
+                return
+
+            for i, bibytes_symbol in enumerate(ProcessInfo._BIBYTES_SYMBOLS):
+                ProcessInfo._BIBYTES_VALS[bibytes_symbol] = 1 << (i + 1) * 10
+            ProcessInfo._BIBYTES_SYMBOLS = list(reversed(ProcessInfo._BIBYTES_SYMBOLS))
+            ProcessInfo._inited = True
+
+    @staticmethod
+    def bytes_to_bibytes(byte_count):
+        """converts byte count to human value in kibi-mebi-gibi-...-bytes"""
+        if byte_count is None:
+            return "unknown"
+        if not byte_count or not isinstance(byte_count, int):
+            return byte_count
+        ProcessInfo.init()
+
+        for bibytes_symbol in ProcessInfo._BIBYTES_SYMBOLS:
+            bibytes_value = ProcessInfo._BIBYTES_VALS[bibytes_symbol]
+            if byte_count >= bibytes_value:
+                value = float(byte_count) / bibytes_value
+                return '%.2f %s' % (value, bibytes_symbol)
+        return "%s B" % byte_count
+
+    @staticmethod
+    @safe_operation
+    def process_memory():
+        """calculates the memory usage of the current process"""
+        process = psutil.Process()
+        with process.oneshot():
+            return dict((k, ProcessInfo.bytes_to_bibytes(v))
+                        for k, v in process.memory_full_info()._asdict().iteritems())
+
+
+    @staticmethod
+    @safe_operation
+    def virtual_memory():
+        """calculates the virtual memory usage of the whole vm"""
+        return dict((k, ProcessInfo.bytes_to_bibytes(v))
+                    for k, v in psutil.virtual_memory()._asdict().iteritems())
+
+
+    @staticmethod
+    @safe_operation
+    def active_threads():
+        """list of active threads"""
+        return sorted([thr.name + "(" + str(thr.ident) + ")" for thr in threading.enumerate()])
+
+
+    @staticmethod
+    @safe_operation
+    def thread_stacks():
+        """returns the current threads with their stack"""
+        thread_names = dict((thr.ident, thr.name) for thr in threading.enumerate())
+        return [
+            {
+                "thread_id" : thread_id,
+                "thread_name" : thread_names.get(thread_id),
+                "thread_stack" : [
+                    {
+                        "filename" : filename,
+                        "lineno" : lineno,
+                        "function" : function_name,
+                        "line" : line.strip() if line else None
+                    }
+                    for filename, lineno, function_name, line in traceback.extract_stack(stack)
+                ]
+            }
+            for thread_id, stack in sys._current_frames().items()
+        ]
+
+
+    @staticmethod
+    @safe_operation
+    def gc_info(full=False):
+        """gets info from garbage collector"""
+        gc_info = {
+            "gc_count" : str(gc.get_count()),
+            "gc_threshold" : str(gc.get_threshold())
+        }
+        if gc.garbage:
+            gc_info["gc_garbage"] = ([repr(stuck) for stuck in gc.garbage]
+                                     if full else len(gc.garbage))
+        return gc_info
+
+    @staticmethod
+    def get_all():
+        """all info"""
+        return {
+            "active_threads" : ProcessInfo.active_threads(),
+            "gc" : ProcessInfo.gc_info(full=True),
+            "process_memory" : ProcessInfo.process_memory(),
+            "virtual_memory" : ProcessInfo.virtual_memory(),
+            "thread_stacks" : ProcessInfo.thread_stacks()
+        }
diff --git a/policyhandler/policy_updater.py b/policyhandler/policy_updater.py
index 38ce93a..9f24d3d 100644
--- a/policyhandler/policy_updater.py
+++ b/policyhandler/policy_updater.py
@@ -236,6 +236,7 @@ class PolicyUpdater(Thread):
 
         PolicyUpdater._logger.info("policy_handler health: %s",
                                    json.dumps(aud_catch_up.health(full=True)))
+        PolicyUpdater._logger.info("process_info: %s", json.dumps(aud_catch_up.process_info()))
         return success
 
 
diff --git a/policyhandler/policy_utils.py b/policyhandler/policy_utils.py
index 69978b6..c96d4f6 100644
--- a/policyhandler/policy_utils.py
+++ b/policyhandler/policy_utils.py
@@ -134,7 +134,8 @@ class Utils(object):
         try:
             return json.loads(json_str)
         except (ValueError, TypeError) as err:
-            Utils._logger.warn("unexpected json %s: %s", str(json_str), str(err))
+            Utils._logger.warn("unexpected json error(%s): len(%s) str[:100]: (%s)",
+                               str(err), len(json_str), str(json_str)[:100])
         return json_str
 
     @staticmethod
diff --git a/policyhandler/web_server.py b/policyhandler/web_server.py
index 5314791..041a442 100644
--- a/policyhandler/web_server.py
+++ b/policyhandler/web_server.py
@@ -198,6 +198,7 @@ class _PolicyWeb(object):
         PolicyWeb.logger.info("%s: --------- the end -----------", req_info)
         res = str(datetime.utcnow())
         audit.info_requested(res)
+        PolicyWeb.logger.info("process_info: %s", json.dumps(audit.process_info()))
         return "goodbye! shutdown requested {0}".format(res)
 
     @cherrypy.expose
diff --git a/pom.xml b/pom.xml
index 592beb2..0484790 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.3-SNAPSHOT</version>
+  <version>2.4.4-SNAPSHOT</version>
   <url>http://maven.apache.org</url>
   <properties>
     <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
diff --git a/run_policy.sh b/run_policy.sh
index a95aee9..28b5bf8 100644
--- a/run_policy.sh
+++ b/run_policy.sh
@@ -29,7 +29,6 @@ cat /etc/hosts | tee -a ${LOG_FILE}
 python -m policyhandler/policy_handler >> ${LOG_FILE} 2>&1 &
 PID=$!
 
-echo "running policy_handler as" ${PID} "log" ${LOG_FILE} | tee -a ${LOG_FILE}
 function finish {
   echo "killing policy_handler ${PID}" $(date +%Y_%m%d-%H:%M:%S.%N) | tee -a ${LOG_FILE}
   kill -9 ${PID}
@@ -37,6 +36,13 @@ function finish {
 }
 trap finish SIGHUP SIGINT SIGTERM
 
+echo "running policy_handler as" ${PID} "log" ${LOG_FILE} | tee -a ${LOG_FILE}
+uname -a  | tee -a ${LOG_FILE}
+free -h  | tee -a ${LOG_FILE}
+df -h    | tee -a ${LOG_FILE}
+ps afxvw | tee -a ${LOG_FILE}
+ss -aepi | tee -a ${LOG_FILE}
+
 wait ${PID}
 echo "---------------------------------------------" >> ${LOG_FILE} 2>&1
 mv ${LOG_FILE} ${LOG_FILE}.$(date +%Y-%m-%d_%H%M%S)
diff --git a/setup.py b/setup.py
index 5556814..33011e9 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.3",

+    version="2.4.4",

     author='Alex Shatov',

     packages=['policyhandler'],

     zip_safe=False,

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)))
diff --git a/version.properties b/version.properties
index b3509ec..9282bc9 100644
--- a/version.properties
+++ b/version.properties
@@ -1,6 +1,6 @@
 major=2

 minor=4

-patch=3

+patch=4

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

 release_version=${base_version}

 snapshot_version=${base_version}-SNAPSHOT