geo-rep: Logging improvements

- Redundant log messages removed.
- Worker and connected slave node details added in "starting worker" log
- Added log for Monitor state change
- Added log for Worker status change(Initializing/Active/Passive/Faulty)
- Added log for Crawl status Change
- Added log for config set and reset
- Added log for checkpoint set, reset and completion

BUG: 1359612
Change-Id: Icc7173ff3c93de4b862bdb1a61760db7eaf14271
Signed-off-by: Aravinda VK <avishwan@redhat.com>
Reviewed-on: http://review.gluster.org/15684
Smoke: Gluster Build System <jenkins@build.gluster.org>
NetBSD-regression: NetBSD Build System <jenkins@build.gluster.org>
CentOS-regression: Gluster Build System <jenkins@build.gluster.org>
Reviewed-by: Kotresh HR <khiremat@redhat.com>

4 files changed, 55 insertions, 29 deletions

diff --git a/geo-replication/syncdaemon/gsyncd.py b/geo-replication/syncdaemon/gsyncd.py
index 3718ba83141..68019be5549 100644
--- a/geo-replication/syncdaemon/gsyncd.py
+++ b/geo-replication/syncdaemon/gsyncd.py
@@ -36,7 +36,7 @@ import xml.etree.ElementTree as XET
 from subprocess import PIPE
 import subprocess
 from changelogagent import agent, Changelog
-from gsyncdstatus import set_monitor_status, GeorepStatus
+from gsyncdstatus import set_monitor_status, GeorepStatus, human_time_utc
 from libcxattr import Xattr
 import struct
 from syncdutils import get_master_and_slave_data_from_args
@@ -546,7 +546,7 @@ def main_i():
         rconf['config_file'], canon_peers, confdata,
         defaults.__dict__, opts.__dict__, namedict)
 
-    checkpoint_change = False
+    conf_change = False
     if confdata:
         opt_ok = norm(confdata.opt) in tunables + [None]
         if confdata.op == 'check':
@@ -565,10 +565,10 @@ def main_i():
         # when modifying checkpoint, it's important to make a log
         # of that, so in that case we go on to set up logging even
         # if its just config invocation
-        if confdata.opt == 'checkpoint' and confdata.op in ('set', 'del') and \
-           not confdata.rx:
-            checkpoint_change = True
-        if not checkpoint_change:
+        if confdata.op in ('set', 'del') and not confdata.rx:
+            conf_change = True
+
+        if not conf_change:
             return
 
     gconf.__dict__.update(defaults.__dict__)
@@ -666,13 +666,23 @@ def main_i():
     if not privileged() and gconf.log_file_mbr:
         gconf.log_file = gconf.log_file_mbr
 
-    if checkpoint_change:
+    if conf_change:
         try:
             GLogger._gsyncd_loginit(log_file=gconf.log_file, label='conf')
+            gconf.log_exit = False
+
             if confdata.op == 'set':
-                logging.info('checkpoint %s set' % confdata.val)
+                if confdata.opt == 'checkpoint':
+                    logging.info("Checkpoint Set: %s" % (
+                        human_time_utc(confdata.val)))
+                else:
+                    logging.info("Config Set: %s = %s" % (
+                        confdata.opt, confdata.val))
             elif confdata.op == 'del':
-                logging.info('checkpoint info was reset')
+                if confdata.opt == 'checkpoint':
+                    logging.info("Checkpoint Reset")
+                else:
+                    logging.info("Config Reset: %s" % confdata.opt)
         except IOError:
             if sys.exc_info()[1].errno == ENOENT:
                 # directory of log path is not present,
@@ -689,6 +699,17 @@ def main_i():
     if create:
         if getattr(gconf, 'state_file', None):
             set_monitor_status(gconf.state_file, create)
+
+        try:
+            GLogger._gsyncd_loginit(log_file=gconf.log_file, label='monitor')
+            gconf.log_exit = False
+            logging.info("Monitor Status: %s" % create)
+        except IOError:
+            if sys.exc_info()[1].errno == ENOENT:
+                # If log dir not present
+                pass
+            else:
+                raise
         return
 
     go_daemon = rconf['go_daemon']
@@ -718,7 +739,7 @@ def main_i():
     if be_monitor:
         label = 'monitor'
     elif be_agent:
-        label = 'agent'
+        label = gconf.local_path
     elif remote:
         # master
         label = gconf.local_path
@@ -735,7 +756,6 @@ def main_i():
     if be_monitor:
         return monitor(*rscs)
 
-    logging.info("syncing: %s" % " -> ".join(r.url for r in rscs))
     if remote:
         go_daemon = remote.connect_remote(go_daemon=go_daemon)
         if go_daemon:
diff --git a/geo-replication/syncdaemon/gsyncdstatus.py b/geo-replication/syncdaemon/gsyncdstatus.py
index f0836edbb26..c9938b5116f 100644
--- a/geo-replication/syncdaemon/gsyncdstatus.py
+++ b/geo-replication/syncdaemon/gsyncdstatus.py
@@ -17,6 +17,8 @@ import json
 import time
 from datetime import datetime
 from errno import EACCES, EAGAIN, ENOENT
+import logging
+
 from syncdutils import EVENT_GEOREP_ACTIVE, EVENT_GEOREP_PASSIVE, gf_event
 from syncdutils import EVENT_GEOREP_CHECKPOINT_COMPLETED
 
@@ -215,6 +217,10 @@ class GeorepStatus(object):
                     data["checkpoint_time"] = checkpoint_time
                     data["checkpoint_completion_time"] = curr_time
                     data["checkpoint_completed"] = "Yes"
+                    logging.info("Checkpoint completed. Checkpoint "
+                                 "Time: %s, Completion Time: %s" % (
+                                     human_time_utc(checkpoint_time),
+                                     human_time_utc(curr_time)))
                     self.trigger_gf_event_checkpoint_completion(
                         checkpoint_time, curr_time)
 
@@ -223,10 +229,12 @@ class GeorepStatus(object):
         self._update(merger)
 
     def set_worker_status(self, status):
-        self.set_field("worker_status", status)
+        if self.set_field("worker_status", status):
+            logging.info("Worker Status: %s" % status)
 
     def set_worker_crawl_status(self, status):
-        self.set_field("crawl_status", status)
+        if self.set_field("crawl_status", status):
+            logging.info("Crawl Status: %s" % status)
 
     def set_slave_node(self, slave_node):
         def merger(data):
@@ -253,6 +261,7 @@ class GeorepStatus(object):
 
     def set_active(self):
         if self.set_field("worker_status", "Active"):
+            logging.info("Worker Status: Active")
             gf_event(EVENT_GEOREP_ACTIVE,
                      master_volume=self.master,
                      slave_host=self.slave_host,
@@ -261,6 +270,7 @@ class GeorepStatus(object):
 
     def set_passive(self):
         if self.set_field("worker_status", "Passive"):
+            logging.info("Worker Status: Passive")
             gf_event(EVENT_GEOREP_PASSIVE,
                      master_volume=self.master,
                      slave_host=self.slave_host,
diff --git a/geo-replication/syncdaemon/master.py b/geo-replication/syncdaemon/master.py
index b5ddac05c29..2c4d8c581a4 100644
--- a/geo-replication/syncdaemon/master.py
+++ b/geo-replication/syncdaemon/master.py
@@ -98,7 +98,7 @@ def gmaster_builder(excrawl=None):
         modemixin = 'normal'
     changemixin = 'xsync' if gconf.change_detector == 'xsync' \
                   else excrawl or gconf.change_detector
-    logging.info('setting up %s change detection mode' % changemixin)
+    logging.debug('setting up %s change detection mode' % changemixin)
     modemixin = getattr(this, modemixin.capitalize() + 'Mixin')
     crawlmixin = getattr(this, 'GMaster' + changemixin.capitalize() + 'Mixin')
     sendmarkmixin = boolify(
@@ -391,10 +391,8 @@ class GMasterCommon(object):
         self.slave = slave
         self.jobtab = {}
         if boolify(gconf.use_tarssh):
-            logging.info("using 'tar over ssh' as the sync engine")
             self.syncer = Syncer(slave, self.slave.tarssh, [2])
         else:
-            logging.info("using 'rsync' as the sync engine")
             # partial transfer (cf. rsync(1)), that's normal
             self.syncer = Syncer(slave, self.slave.rsync, [23, 24])
         # crawls vs. turns:
@@ -535,9 +533,9 @@ class GMasterCommon(object):
         volinfo_sys = self.volinfo_hook()
         self.volinfo = volinfo_sys[self.KNAT]
         inter_master = volinfo_sys[self.KFGN]
-        logging.info("%s master with volume id %s ..." %
-                     (inter_master and "intermediate" or "primary",
-                      self.uuid))
+        logging.debug("%s master with volume id %s ..." %
+                      (inter_master and "intermediate" or "primary",
+                       self.uuid))
         gconf.configinterface.set('volume_id', self.uuid)
         if self.volinfo:
             if self.volinfo['retval']:
@@ -546,7 +544,6 @@ class GMasterCommon(object):
         else:
             raise GsyncdError("master volinfo unavailable")
         self.lastreport['time'] = time.time()
-        logging.info('crawl interval: %d seconds' % self.sleep_interval)
 
         t0 = time.time()
         crawl = self.should_crawl()
@@ -557,9 +554,9 @@ class GMasterCommon(object):
             self.start = time.time()
             should_display_info = self.start - self.lastreport['time'] >= 60
             if should_display_info:
-                logging.info("%d crawls, %d turns",
-                             self.crawls - self.lastreport['crawls'],
-                             self.turns - self.lastreport['turns'])
+                logging.debug("%d crawls, %d turns",
+                              self.crawls - self.lastreport['crawls'],
+                              self.turns - self.lastreport['turns'])
                 self.lastreport.update(crawls=self.crawls,
                                        turns=self.turns,
                                        time=self.start)
@@ -1240,7 +1237,6 @@ class GMasterChangeloghistoryMixin(GMasterChangelogMixin):
                         repr(end_time), self.get_entry_stime()))
 
         if not data_stime or data_stime == URXTIME:
-            logging.info("stime not available, abandoning history crawl")
             raise NoStimeAvailable()
 
         # Changelogs backend path is hardcoded as
@@ -1322,10 +1318,10 @@ class GMasterXsyncMixin(GMasterChangelogMixin):
         self.stimes = []
         self.sleep_interval = 60
         self.tempdir = self.setup_working_dir()
+        logging.info('Working dir: %s' % self.tempdir)
         self.tempdir = os.path.join(self.tempdir, 'xsync')
         self.processed_changelogs_dir = self.tempdir
         self.name = "xsync"
-        logging.info('xsync temp directory: %s' % self.tempdir)
         try:
             os.makedirs(self.tempdir)
         except OSError:
diff --git a/geo-replication/syncdaemon/monitor.py b/geo-replication/syncdaemon/monitor.py
index 7eddd26d5ea..f13e5e79eab 100644
--- a/geo-replication/syncdaemon/monitor.py
+++ b/geo-replication/syncdaemon/monitor.py
@@ -269,8 +269,8 @@ class Monitor(object):
             # Spawn the worker and agent in lock to avoid fd leak
             self.lock.acquire()
 
-            logging.info('-' * conn_timeout)
-            logging.info('starting gsyncd worker')
+            logging.info('starting gsyncd worker(%s). Slave node: %s' %
+                         (w[0]['dir'], remote_host))
 
             # Couple of pipe pairs for RPC communication b/w
             # worker and changelog agent.
@@ -452,7 +452,7 @@ def distribute(*resources):
                                       new_stime_xattr_name)
     else:
         raise GsyncdError("unknown slave type " + slave.url)
-    logging.info('slave bricks: ' + repr(sbricks))
+    logging.debug('slave bricks: ' + repr(sbricks))
     if isinstance(si, FILE):
         slaves = [slave.url]
     else:
@@ -477,7 +477,7 @@ def distribute(*resources):
                                slaves[idx % len(slaves)],
                                get_subvol_num(idx, mvol, is_hot),
                                is_hot))
-    logging.info('worker specs: ' + repr(workerspex))
+    logging.debug('worker specs: ' + repr(workerspex))
     return workerspex, suuid, slave_vol, slave_host, master