Greg Padgett has uploaded a new change for review.

Change subject: agent, broker, lib: less logging at INFO level
......................................................................

agent, broker, lib: less logging at INFO level

Decrease the amount of output going to the logs at INFO level.
Accomplished via:
 - moving some logging calls from INFO to DEBUG
 - log agent metadata only occasionally or when changed
 - fix the log filter which assists intermittent logging
 - apply said filter to additional log statements to silence some
   redundant updates

Change-Id: I8b4614a6ea23c2813c0341e03171328e24f148c8
Bug-Url: https://bugzilla.redhat.com/1019471
Signed-off-by: Greg Padgett <gpadg...@redhat.com>
---
M ovirt_hosted_engine_ha/agent/constants.py.in
M ovirt_hosted_engine_ha/agent/hosted_engine.py
M ovirt_hosted_engine_ha/broker/storage_broker.py
M ovirt_hosted_engine_ha/broker/submonitors/engine_health.py
M ovirt_hosted_engine_ha/broker/submonitors/mem_free.py
M ovirt_hosted_engine_ha/broker/submonitors/mem_load.py
M ovirt_hosted_engine_ha/broker/submonitors/mgmt_bridge.py
M ovirt_hosted_engine_ha/broker/submonitors/ping.py
M ovirt_hosted_engine_ha/lib/brokerlink.py
M ovirt_hosted_engine_ha/lib/log_filter.py
10 files changed, 122 insertions(+), 72 deletions(-)


  git pull ssh://gerrit.ovirt.org:29418/ovirt-hosted-engine-ha 
refs/changes/18/21318/1

diff --git a/ovirt_hosted_engine_ha/agent/constants.py.in 
b/ovirt_hosted_engine_ha/agent/constants.py.in
index e6830d0..fc689e6 100644
--- a/ovirt_hosted_engine_ha/agent/constants.py.in
+++ b/ovirt_hosted_engine_ha/agent/constants.py.in
@@ -40,9 +40,9 @@
 ENGINE_BAD_HEALTH_TIMEOUT_SECS = 300
 ENGINE_BAD_HEALTH_EXPIRATION_SECS = 600
 VM_UNEXPECTED_SHUTDOWN_EXPIRATION_SECS = 600
-INTERMITTENT_LOG_INTERVAL_SECS = 900
 MAX_VDSM_WAIT_SECS = 15
 MAX_DOMAIN_MONITOR_WAIT_SECS = 240
+METADATA_LOG_PERIOD_SECS = 600
 
 VDSM_USER = '@VDSM_USER@'
 VDSM_GROUP = '@VDSM_GROUP@'
diff --git a/ovirt_hosted_engine_ha/agent/hosted_engine.py 
b/ovirt_hosted_engine_ha/agent/hosted_engine.py
index f547315..1303c0c 100644
--- a/ovirt_hosted_engine_ha/agent/hosted_engine.py
+++ b/ovirt_hosted_engine_ha/agent/hosted_engine.py
@@ -53,12 +53,13 @@
 
 class HostedEngine(object):
     LF_MD_ERROR = 'LF_MD_ERROR'
-    LF_HOST_UPDATE = 'LF_HOST_UPDATE'
-    LF_HOST_UPDATE_DETAIL = 'LF_HOST_UPDATE_DETAIL'
+    LF_MD_ERROR_INT = 900
     LF_ENGINE_HEALTH = 'LF_ENGINE_HEALTH'
+    LF_ENGINE_HEALTH_INT = 60
     LF_GLOBAL_MD_ERROR = 'LF_GLOBAL_MD_ERROR'
-    LF_GLOBAL_MD_UPDATE_DETAIL = 'LF_GLOBAL_MD_UPDATE_DETAIL'
+    LF_GLOBAL_MD_ERROR_INT = 900
     LF_MAINTENANCE = 'LF_MAINTENANCE'
+    LF_MAINTENANCE_INT = 900
 
     MIGRATION_THRESHOLD_SCORE = 800
 
@@ -113,6 +114,7 @@
         self._rinfo = {}
         self._init_runtime_info()
         self._all_host_stats = {}
+        self._prior_host_stats = {}
         self._global_stats = {}
 
         self._sd_path = None
@@ -205,6 +207,9 @@
         # Local timestamp when vm was unexpectedly shut down
         self._rinfo['unexpected-shutdown-time'] = None
 
+        # Local timestamp of last metadata logging
+        self._rinfo['last-metadata-log-time'] = 0
+
         # Host id of local host
         self._rinfo['host-id'] = int(self._config.get(config.ENGINE,
                                                       config.HOST_ID))
@@ -215,31 +220,27 @@
         # The following are initialized when needed to process engine actions
 
         # Used to denote best-ranked engine status of all live hosts
-        # 'best-engine-status'
-        # 'best-engine-status-host-id'
+        # self._rinfo['best-engine-status']
+        # self._rinfo['best-engine-status-host-id']
 
         # Highest score of all hosts, and host-id with that score
-        # 'best-score'
-        # 'best-score-host-id'
+        # self._rinfo['best-score']
+        # self._rinfo['best-score-host-id']
 
         # Current state machine state, member of self.States
-        # 'current-state'
+        # self._rinfo['current-state']
 
         # State of maintenance bit, True/False
-        # 'maintenance'
+        # self._rinfo['maintenance']
 
         # Used by ON state; tracks time when bad status first seen, cleanred
         # on either state change due to healthy state or timeout
-        # 'first-bad-status-time'
+        # self._rinfo['first-bad-status-time']
 
         # Used by ON and MIGRATE state, tracks status of migration (element of
         # self.MigrationStatus) and host id to which migration is occurring
-        # 'migration-host-id'
-        # 'migration-status'
-
-    def _get_lf_args(self, lf_class):
-        return {'lf_class': lf_class,
-                'interval': constants.INTERMITTENT_LOG_INTERVAL_SECS}
+        # self._rinfo['migration-host-id']
+        # self._rinfo['migration-status']
 
     def start_monitoring(self):
         error_count = 0
@@ -336,8 +337,8 @@
             self._log.debug("stdout: %s", output[0])
             self._log.debug("stderr: %s", output[1])
             if p.returncode == 0:
-                self._log.info("Successfully verified that VDSM"
-                               " is attached to storage")
+                self._log.debug("Successfully verified that VDSM"
+                                " is attached to storage")
                 break
         if tries == constants.MAX_VDSM_WAIT_SECS:
             self._log.error("Failed trying to connect storage: %s", output[1])
@@ -354,9 +355,9 @@
                                   'service', service_name, 'status'],
                                  stdout=devnull, stderr=devnull)
             if p.wait() == 0:
-                self._log.info("%s running", service_name)
+                self._log.debug("%s running", service_name)
             else:
-                self._log.error("Starting %s", service_name)
+                self._log.info("Starting %s", service_name)
                 with open(os.devnull, "w") as devnull:
                     p = subprocess.Popen(['sudo',
                                           'service', service_name, 'start'],
@@ -449,7 +450,7 @@
             status = self._get_domain_monitor_status()
 
         if status == self.DomainMonitorStatus.ACQUIRED:
-            self._log.info("VDSM is monitoring domain %s", sd_uuid)
+            self._log.debug("VDSM is monitoring domain %s", sd_uuid)
         else:
             msg = ("Failed to start monitoring domain"
                    " (sd_uuid={0}, host_id={1}): {2}"
@@ -477,12 +478,15 @@
 
         if sd_uuid not in repo_stats:
             status = self.DomainMonitorStatus.NONE
+            log_level = logging.INFO
         elif repo_stats[sd_uuid]['acquired']:
             status = self.DomainMonitorStatus.ACQUIRED
+            log_level = logging.DEBUG
         else:
             status = self.DomainMonitorStatus.PENDING
+            log_level = logging.INFO
 
-        self._log.info("VDSM domain monitor status: %s", status)
+        self._log.log(log_level, "VDSM domain monitor status: %s", status)
         return status
 
     def _collect_local_stats(self):
@@ -632,8 +636,8 @@
 
         info_count = int((len(info) + constants.METADATA_BLOCK_BYTES - 1)
                          / constants.METADATA_BLOCK_BYTES)
-        self._log.info("Generated %d blocks:\n%s\n<\\0 padding>\n%s",
-                       info_count + 1, data, info)
+        self._log.debug("Generated %d blocks:\n%s\n<\\0 padding>\n%s",
+                        info_count + 1, data, info)
         data = data.ljust(constants.METADATA_BLOCK_BYTES, '\0')
         info = info.ljust(constants.METADATA_BLOCK_BYTES * info_count, '\0')
         out = data + info
@@ -650,7 +654,7 @@
         all_stats = self._broker.get_stats_from_storage(
             self._metadata_dir,
             constants.SERVICE_TYPE)
-        local_ts = time.time()
+        local_ts = int(time.time())
 
         # host_id 0 is a special case, representing global metadata
         data = all_stats.pop(0, None)
@@ -658,15 +662,15 @@
         if data is not None:
             try:
                 md = metadata.parse_global_metadata_to_dict(self._log, data)
-                self._log.info(
-                    'Global metadata: {0}'.format(md),
-                    extra=self._get_lf_args(self.LF_GLOBAL_MD_UPDATE_DETAIL))
             except ex.MetadataError as e:
                 self._log.error(
                     str(e),
-                    extra=self._get_lf_args(self.LF_GLOBAL_MD_ERROR))
+                    extra=log_filter.lf_args(self.LF_GLOBAL_MD_ERROR,
+                                             self.LF_GLOBAL_MD_ERROR_INT))
                 # Continue agent processing, ignoring the bad global metadata
-        self._global_stats = md
+        if self._global_stats != md:
+            self._log.info('Global metadata changed: {0}'.format(md))
+            self._global_stats = md
 
         for host_id, data in all_stats.iteritems():
             try:
@@ -674,7 +678,8 @@
             except ex.MetadataError as e:
                 self._log.error(
                     str(e),
-                    extra=self._get_lf_args(self.LF_MD_ERROR))
+                    extra=log_filter.lf_args(self.LF_MD_ERROR + str(host_id),
+                                             self.LF_MD_ERROR_INT))
                 continue
 
             if md['host-id'] not in self._all_host_stats:
@@ -689,6 +694,8 @@
 
             if self._all_host_stats[md['host-id']]['last-update-host-ts'] \
                     != md['host-ts']:
+                self._prior_host_stats[md['host-id']] = \
+                    self._all_host_stats[md['host-id']]
                 # Track first update in order to accurately judge liveness.
                 # If last-update-host-ts is 0, then first-update stays True
                 # which indicates that we cannot use this last-update-local-ts
@@ -715,24 +722,34 @@
                 # a timeout in this case means we read stale data, but still
                 # must mark the host as dead.
                 # TODO newer sanlocks can report this through get_hosts()
-                self._log.error("Host %s (id %d) is no longer updating its"
-                                " metadata", attr['hostname'], host_id,
-                                extra=self._get_lf_args(self.LF_HOST_UPDATE))
-                self._all_host_stats[host_id]['alive'] = False
+                if self._all_host_stats[host_id]['alive']:
+                    self._log.error("Host %s (id %d) is no longer updating its"
+                                    " metadata", attr['hostname'], host_id)
+                    self._all_host_stats[host_id]['alive'] = False
             elif attr['first-update']:
                 self._log.info("Waiting for first update from host %s (id %d)",
-                               attr['hostname'], host_id,
-                               extra=self._get_lf_args(self.LF_HOST_UPDATE))
+                               attr['hostname'], host_id)
             else:
-                self._log.info("Host %s (id %d) metadata updated",
-                               attr['hostname'], host_id,
-                               extra=self._get_lf_args(self.LF_HOST_UPDATE))
+                self._log.debug("Host %s (id %d) metadata updated",
+                                attr['hostname'], host_id)
+                self._all_host_stats[host_id]['alive'] = True
+
+            # Log any changed stats
+            if (any((self._all_host_stats[host_id][k]
+                     != self._prior_host_stats[host_id][k]
+                     for k in ['alive', 'engine-status', 'score']))):
+                info_str = "{0}".format(attr)
+                self._log.info("Host %s (id %d) changed: %s",
+                               attr['hostname'], host_id, info_str)
+
+        if util.has_elapsed(self._rinfo['last-metadata-log-time'],
+                            constants.METADATA_LOG_PERIOD_SECS):
+            self._rinfo['last-metadata-log-time'] = int(time.time())
+            self._log.info('Global metadata: {0}'.format(self._global_stats))
+            for host_id, attr in self._all_host_stats.iteritems():
                 info_str = "{0}".format(attr)
                 self._log.info("Host %s (id %d): %s",
-                               attr['hostname'], host_id, info_str,
-                               extra=self._get_lf_args(
-                                   self.LF_HOST_UPDATE_DETAIL))
-                self._all_host_stats[host_id]['alive'] = True
+                               attr['hostname'], host_id, info_str)
 
     def _perform_engine_actions(self):
         """
@@ -852,7 +869,8 @@
                     "Engine vm is running on host %s (id %d)",
                     self._all_host_stats[engine_host_id]['hostname'],
                     engine_host_id,
-                    extra=self._get_lf_args(self.LF_ENGINE_HEALTH)
+                    extra=log_filter.lf_args(self.LF_ENGINE_HEALTH,
+                                             self.LF_ENGINE_HEALTH_INT)
                 )
                 return self.States.OFF, True
 
@@ -867,13 +885,15 @@
 
         if self._rinfo['best-score-host-id'] != local_host_id:
             self._log.info("Engine down, local host does not have best score",
-                           extra=self._get_lf_args(self.LF_ENGINE_HEALTH))
+                           extra=log_filter.lf_args(self.LF_ENGINE_HEALTH,
+                                                    self.LF_ENGINE_HEALTH_INT))
             return self.States.OFF, True
 
         self._log.error("Engine down and local host has best score (%d),"
                         " attempting to start engine VM",
                         self._rinfo['best-score'],
-                        extra=self._get_lf_args(self.LF_ENGINE_HEALTH))
+                        extra=log_filter.lf_args(self.LF_ENGINE_HEALTH,
+                                                 self.LF_ENGINE_HEALTH_INT))
         return self.States.START, False
 
     def _handle_start(self):
@@ -972,12 +992,12 @@
         local_host_id = self._rinfo['host-id']
         if self._rinfo['best-engine-status'][:5] != 'vm-up':
             self._log.error("Engine vm died unexpectedly")
-            self._rinfo['unexpected-shutdown-time'] = time.time()
+            self._rinfo['unexpected-shutdown-time'] = int(time.time())
             # Switch to OFF after yielding so score can adjust to 0
             return self.States.OFF, True
         elif self._rinfo['best-engine-status-host-id'] != local_host_id:
             self._log.error("Engine vm unexpectedly running on other host")
-            self._rinfo['unexpected-shutdown-time'] = time.time()
+            self._rinfo['unexpected-shutdown-time'] = int(time.time())
             return self.States.OFF, True
 
         if self._rinfo['maintenance'] == self.MaintenanceMode.GLOBAL:
@@ -1018,7 +1038,9 @@
                 # FIXME how do we avoid this for cases like vm running fsck?
                 return self.States.STOP, False
 
-        self._log.info("Engine vm running on localhost")
+        self._log.info("Engine vm running on localhost",
+                       extra=log_filter.lf_args(self.LF_ENGINE_HEALTH,
+                                                self.LF_ENGINE_HEALTH_INT))
         return self.States.ON, True
 
     def _handle_on_cleanup(self):
@@ -1163,7 +1185,8 @@
         """
         if self._rinfo['maintenance'] == self.MaintenanceMode.GLOBAL:
             self._log.info("Global HA maintenance enabled",
-                           extra=self._get_lf_args(self.LF_MAINTENANCE))
+                           extra=log_filter.lf_args(self.LF_MAINTENANCE,
+                                                    self.LF_MAINTENANCE_INT))
             return self.States.MAINTENANCE, True
         else:
             return self.States.ENTRY, False
diff --git a/ovirt_hosted_engine_ha/broker/storage_broker.py 
b/ovirt_hosted_engine_ha/broker/storage_broker.py
index 7a79c3c..0f75017 100644
--- a/ovirt_hosted_engine_ha/broker/storage_broker.py
+++ b/ovirt_hosted_engine_ha/broker/storage_broker.py
@@ -55,8 +55,8 @@
         Note: this method is called from the client as well as from
         self.get_all_stats_for_service_type().
         """
-        self._log.info("Getting stats for service %s from %s",
-                       service_type, storage_dir)
+        self._log.debug("Getting stats for service %s from %s",
+                        service_type, storage_dir)
         path = os.path.join(storage_dir, self._get_filename(service_type))
 
         # Use direct I/O if possible, to avoid the local filesystem cache
@@ -98,9 +98,9 @@
         host_id = int(host_id)
         path = os.path.join(storage_dir, self._get_filename(service_type))
         offset = host_id * constants.HOST_SEGMENT_BYTES
-        self._log.info("Writing stats for service %s, host id %d"
-                       " to file %s, offset %d",
-                       service_type, host_id, path, offset)
+        self._log.debug("Writing stats for service %s, host id %d"
+                        " to file %s, offset %d",
+                        service_type, host_id, path, offset)
 
         byte_data = base64.b16decode(data)
         byte_data = byte_data.ljust(constants.HOST_SEGMENT_BYTES, '\0')
diff --git a/ovirt_hosted_engine_ha/broker/submonitors/engine_health.py 
b/ovirt_hosted_engine_ha/broker/submonitors/engine_health.py
index dd1dbe8..c0e714e 100644
--- a/ovirt_hosted_engine_ha/broker/submonitors/engine_health.py
+++ b/ovirt_hosted_engine_ha/broker/submonitors/engine_health.py
@@ -23,6 +23,7 @@
 from ovirt_hosted_engine_ha.broker import constants
 from ovirt_hosted_engine_ha.broker import submonitor_base
 from ovirt_hosted_engine_ha.lib import exceptions as exceptions
+from ovirt_hosted_engine_ha.lib import log_filter
 from ovirt_hosted_engine_ha.lib import util as util
 from ovirt_hosted_engine_ha.lib import vds_client as vdsc
 
@@ -34,6 +35,7 @@
 class Submonitor(submonitor_base.SubmonitorBase):
     def setup(self, options):
         self._log = logging.getLogger("EngineHealth")
+        self._log.addFilter(log_filter.IntermittentFilter())
 
         self._address = options.get('address')
         self._use_ssl = util.to_bool(options.get('use_ssl'))
@@ -55,7 +57,8 @@
             if isinstance(e, exceptions.DetailedError) \
                     and e.detail == "Virtual machine does not exist":
                 # Not on this host
-                self._log.info("VM not on this host")
+                self._log.info("VM not on this host",
+                               extra=log_filter.lf_args('status', 60))
                 self.update_result('vm-down')
                 return
             else:
@@ -71,11 +74,13 @@
                          'restoringstate',
                          'savingstate',
                          'paused'):
-            self._log.info("VM status: %s", vm_status)
+            self._log.info("VM status: %s", vm_status,
+                           extra=log_filter.lf_args('status', 60))
             self.update_result('vm-up bad-health-status')
             return
         if vm_status != 'up':
-            self._log.info("VM not running on this host, status %s", vm_status)
+            self._log.info("VM not running on this host, status %s", vm_status,
+                           extra=log_filter.lf_args('status', 60))
             self.update_result('vm-down')
             return
 
@@ -85,7 +90,8 @@
                              stdout=subprocess.PIPE, stderr=subprocess.PIPE)
         output = p.communicate()
         if p.returncode == 0:
-            self._log.info("VM is up on this host with healthy engine")
+            self._log.info("VM is up on this host with healthy engine",
+                           extra=log_filter.lf_args('status', 60))
             self.update_result("vm-up good-health-status")
             return
         self._log.warning("bad health status: %s", output[0])
diff --git a/ovirt_hosted_engine_ha/broker/submonitors/mem_free.py 
b/ovirt_hosted_engine_ha/broker/submonitors/mem_free.py
index 34b0bcc..141f0b0 100644
--- a/ovirt_hosted_engine_ha/broker/submonitors/mem_free.py
+++ b/ovirt_hosted_engine_ha/broker/submonitors/mem_free.py
@@ -20,6 +20,7 @@
 import logging
 
 from ovirt_hosted_engine_ha.broker import submonitor_base
+from ovirt_hosted_engine_ha.lib import log_filter
 from ovirt_hosted_engine_ha.lib import util as util
 from ovirt_hosted_engine_ha.lib import vds_client as vdsc
 
@@ -31,6 +32,7 @@
 class Submonitor(submonitor_base.SubmonitorBase):
     def setup(self, options):
         self._log = logging.getLogger("MemFree")
+        self._log.addFilter(log_filter.IntermittentFilter())
         self._address = options.get('address')
         self._use_ssl = util.to_bool(options.get('use_ssl'))
         if self._address is None or self._use_ssl is None:
@@ -47,5 +49,6 @@
             return
 
         mem_free = str(response['info']['memFree'])
-        self._log.info("memFree: %s", mem_free)
+        self._log.info("memFree: %s", mem_free,
+                       extra=log_filter.lf_args('status', 60))
         self.update_result(mem_free)
diff --git a/ovirt_hosted_engine_ha/broker/submonitors/mem_load.py 
b/ovirt_hosted_engine_ha/broker/submonitors/mem_load.py
index dcc769a..be4fcd5 100644
--- a/ovirt_hosted_engine_ha/broker/submonitors/mem_load.py
+++ b/ovirt_hosted_engine_ha/broker/submonitors/mem_load.py
@@ -20,6 +20,7 @@
 import logging
 
 from ovirt_hosted_engine_ha.broker import submonitor_base
+from ovirt_hosted_engine_ha.lib import log_filter
 from ovirt_hosted_engine_ha.lib import util as util
 from ovirt_hosted_engine_ha.lib import vds_client as vdsc
 
@@ -31,6 +32,7 @@
 class Submonitor(submonitor_base.SubmonitorBase):
     def setup(self, options):
         self._log = logging.getLogger("MemLoad")
+        self._log.addFilter(log_filter.IntermittentFilter())
         self._address = options.get('address')
         self._use_ssl = util.to_bool(options.get('use_ssl'))
         if self._address is None or self._use_ssl is None:
@@ -52,5 +54,6 @@
         mem_used = int(stats['info']['memUsed'])
         mem_load = float(mem_used) / mem_size
         self._log.info("memSize: %d, memUsed: %d, Load: %f",
-                       mem_size, mem_used, mem_load)
+                       mem_size, mem_used, mem_load,
+                       extra=log_filter.lf_args('status', 60))
         self.update_result(str(mem_load))
diff --git a/ovirt_hosted_engine_ha/broker/submonitors/mgmt_bridge.py 
b/ovirt_hosted_engine_ha/broker/submonitors/mgmt_bridge.py
index 7490dc2..bbb29b0 100644
--- a/ovirt_hosted_engine_ha/broker/submonitors/mgmt_bridge.py
+++ b/ovirt_hosted_engine_ha/broker/submonitors/mgmt_bridge.py
@@ -20,6 +20,7 @@
 import logging
 
 from ovirt_hosted_engine_ha.broker import submonitor_base
+from ovirt_hosted_engine_ha.lib import log_filter
 from ovirt_hosted_engine_ha.lib import util as util
 from ovirt_hosted_engine_ha.lib import vds_client as vdsc
 
@@ -31,6 +32,7 @@
 class Submonitor(submonitor_base.SubmonitorBase):
     def setup(self, options):
         self._log = logging.getLogger("MgmtBridge")
+        self._log.addFilter(log_filter.IntermittentFilter())
         self._address = options.get('address')
         self._use_ssl = util.to_bool(options.get('use_ssl'))
         self._bridge = options.get('bridge_name')
@@ -53,8 +55,10 @@
         if ('bridges' in response['info']
                 and self._bridge in response['info']['bridges']):
             # FIXME check status of bridge?
-            self._log.info("Found bridge %s", self._bridge)
+            self._log.info("Found bridge %s", self._bridge,
+                           extra=log_filter.lf_args('status', 60))
             self.update_result(True)
         else:
-            self._log.info("Bridge %s not found", self._bridge)
+            self._log.info("Bridge %s not found", self._bridge,
+                           extra=log_filter.lf_args('status', 60))
             self.update_result(False)
diff --git a/ovirt_hosted_engine_ha/broker/submonitors/ping.py 
b/ovirt_hosted_engine_ha/broker/submonitors/ping.py
index 0f4f08b..3b9f140 100644
--- a/ovirt_hosted_engine_ha/broker/submonitors/ping.py
+++ b/ovirt_hosted_engine_ha/broker/submonitors/ping.py
@@ -22,6 +22,7 @@
 import subprocess
 
 from ovirt_hosted_engine_ha.broker import submonitor_base
+from ovirt_hosted_engine_ha.lib import log_filter
 
 
 def register():
@@ -31,6 +32,7 @@
 class Submonitor(submonitor_base.SubmonitorBase):
     def setup(self, options):
         self._log = logging.getLogger("Ping")
+        self._log.addFilter(log_filter.IntermittentFilter())
         self._addr = options.get('addr')
         self._timeout = str(options.get('timeout', 10))
         if self._addr is None:
@@ -46,5 +48,6 @@
                 self._log.warning("Failed to ping %s", self._addr)
                 self.update_result(False)
             else:
-                self._log.info("Successfully pinged %s", self._addr)
+                self._log.info("Successfully pinged %s", self._addr,
+                               extra=log_filter.lf_args('status', 60))
                 self.update_result(True)
diff --git a/ovirt_hosted_engine_ha/lib/brokerlink.py 
b/ovirt_hosted_engine_ha/lib/brokerlink.py
index f53371b..b00e0d4 100644
--- a/ovirt_hosted_engine_ha/lib/brokerlink.py
+++ b/ovirt_hosted_engine_ha/lib/brokerlink.py
@@ -43,7 +43,7 @@
         """
         if self.is_connected():
             return
-        self._log.info("Connecting to ha-broker")
+        self._log.debug("Connecting to ha-broker")
 
         try:
             self._socket = socket.socket(socket.AF_UNIX, socket.SOCK_STREAM)
@@ -76,7 +76,7 @@
         return self._socket is not None
 
     def disconnect(self):
-        self._log.info("Closing connection to ha-broker")
+        self._log.debug("Closing connection to ha-broker")
         try:
             if self._socket:
                 self._socket.close()
@@ -122,7 +122,7 @@
             self._log.error("Exception getting monitor status: %s", str(e))
             raise RequestError("Failed to get monitor status: {0}"
                                .format(str(e)))
-        self._log.info("Success, status %s", response)
+        self._log.debug("Success, status %s", response)
         return response
 
     def put_stats_on_storage(self, storage_dir, service_type, host_id, data):
@@ -130,7 +130,7 @@
         Puts data on the shared storage according to the parameters.
         Data should be passed in as a string.
         """
-        self._log.info("Storing blocks on storage at %s", storage_dir)
+        self._log.debug("Storing blocks on storage at %s", storage_dir)
         # broker expects blocks in hex format
         hex_data = base64.b16encode(data)
         request = ("put-stats"
diff --git a/ovirt_hosted_engine_ha/lib/log_filter.py 
b/ovirt_hosted_engine_ha/lib/log_filter.py
index b43f2e6..8b703f7 100644
--- a/ovirt_hosted_engine_ha/lib/log_filter.py
+++ b/ovirt_hosted_engine_ha/lib/log_filter.py
@@ -22,6 +22,9 @@
 
 
 class IntermittentFilter(logging.Filter):
+    def __init__(self):
+        self._classes = {}
+
     """
     Makes sure a messages in each message class are only logged every
     lf_interval seconds or when the message text changes.
@@ -40,9 +43,14 @@
                 or (self._classes[record.lf_class]['time']
                     + record.lf_interval < now)
                 or (self._classes[record.lf_class]['message']
-                    != record.get_message())):
+                    != record.getMessage())):
             self._classes[record.lf_class]['time'] = now
-            self._classes[record.lf_class]['message'] = record.get_message()
+            self._classes[record.lf_class]['message'] = record.getMessage()
             return True
         else:
             return False
+
+
+def lf_args(lf_class, lf_interval):
+    return {'lf_class': lf_class,
+            'lf_interval': lf_interval}


-- 
To view, visit http://gerrit.ovirt.org/21318
To unsubscribe, visit http://gerrit.ovirt.org/settings

Gerrit-MessageType: newchange
Gerrit-Change-Id: I8b4614a6ea23c2813c0341e03171328e24f148c8
Gerrit-PatchSet: 1
Gerrit-Project: ovirt-hosted-engine-ha
Gerrit-Branch: master
Gerrit-Owner: Greg Padgett <gpadg...@redhat.com>
_______________________________________________
Engine-patches mailing list
Engine-patches@ovirt.org
http://lists.ovirt.org/mailman/listinfo/engine-patches

Reply via email to