gsyncd: do some basic sanitization on logs

- exceptions raised by us will be logged as single-line error messages
  (full stack strace is shown only at DEBUG loglevel)
- common/well understood exceptions are mapped to "user-parsable" error logs

Change-Id: I75f1fb848483372364b2093878d9cfed576c9739
BUG: 2778
Reviewed-on: http://review.gluster.com/125
Tested-by: Gluster Build System <jenkins@build.gluster.com>
Reviewed-by: Anand Avati <avati@gluster.com>

5 files changed, 60 insertions, 24 deletions

diff --git a/xlators/features/marker/utils/syncdaemon/configinterface.py b/xlators/features/marker/utils/syncdaemon/configinterface.py
index dff6c111d..cc8f7063a 100644
--- a/xlators/features/marker/utils/syncdaemon/configinterface.py
+++ b/xlators/features/marker/utils/syncdaemon/configinterface.py
@@ -6,7 +6,7 @@ except ImportError:
 import re
 from string import Template
 
-from syncdutils import escape, unescape, norm, update_file
+from syncdutils import escape, unescape, norm, update_file, GsyncdError
 
 SECT_ORD = '__section_order__'
 SECT_META = '__meta__'
@@ -109,7 +109,7 @@ class GConffile(object):
 
     def update_to(self, dct, allow_unresolved=False):
         if not self.peers:
-            raise RuntimeError('no peers given, cannot select matching options')
+            raise GsyncdError('no peers given, cannot select matching options')
         def update_from_sect(sect, mud):
             for k, v in self.config._sections[sect].items():
                 if k == '__name__':
diff --git a/xlators/features/marker/utils/syncdaemon/gsyncd.py b/xlators/features/marker/utils/syncdaemon/gsyncd.py
index 313bfdb0a..fb1dc1b9c 100644
--- a/xlators/features/marker/utils/syncdaemon/gsyncd.py
+++ b/xlators/features/marker/utils/syncdaemon/gsyncd.py
@@ -15,6 +15,7 @@ from errno import EEXIST, ENOENT
 
 from gconf import gconf
 from syncdutils import FreeObject, norm, grabpidfile, finalize, log_raise_exception
+from syncdutils import GsyncdError
 from configinterface import GConffile
 import resource
 from monitor import monitor
@@ -72,7 +73,7 @@ def startup(**kw):
             os.dup2(dn, f.fileno())
         if getattr(gconf, 'pid_file', None):
             if not grabpidfile(gconf.pid_file + '.tmp'):
-                raise RuntimeError("cannot grap temporary pidfile")
+                raise GsyncdError("cannot grab temporary pidfile")
             os.rename(gconf.pid_file + '.tmp', gconf.pid_file)
         # wait for parent to terminate
         # so we can start up with
@@ -203,7 +204,7 @@ def main_i():
             if len(rscs) > 1:
                 remote = rscs[1]
             if not local.can_connect_to(remote):
-                raise RuntimeError("%s cannot work with %s" % (local.path, remote and remote.path))
+                raise GsyncdError("%s cannot work with %s" % (local.path, remote and remote.path))
         pa = ([], [], [])
         urlprms = ({}, {'canonical': True}, {'canonical': True, 'escaped': True})
         for x in rscs:
@@ -237,7 +238,7 @@ def main_i():
             else:
                 sys.exit(1)
         elif not opt_ok:
-            raise RuntimeError("not a valid option: " + confdata.opt)
+            raise GsyncdError("not a valid option: " + confdata.opt)
         if confdata.op == 'get':
             gcnf.get(confdata.opt)
         elif confdata.op == 'set':
@@ -263,7 +264,7 @@ def main_i():
         # I have _never_ _ever_ seen such an utterly braindead
         # error condition
         if lvl2 == "Level " + lvl1:
-            raise RuntimeError('cannot recognize log level "%s"' % lvl0)
+            raise GsyncdError('cannot recognize log level "%s"' % lvl0)
         gconf.log_level = lvl2
 
     go_daemon = rconf['go_daemon']
diff --git a/xlators/features/marker/utils/syncdaemon/master.py b/xlators/features/marker/utils/syncdaemon/master.py
index f0a5b5dc1..495634b06 100644
--- a/xlators/features/marker/utils/syncdaemon/master.py
+++ b/xlators/features/marker/utils/syncdaemon/master.py
@@ -9,7 +9,7 @@ from errno import ENOENT, ENODATA
 from threading import currentThread, Condition, Lock
 
 from gconf import gconf
-from syncdutils import FreeObject, Thread
+from syncdutils import FreeObject, Thread, GsyncdError
 
 URXTIME = (-1, 0)
 
@@ -24,7 +24,7 @@ class GMaster(object):
         fgn_vi = None
         if fgn_vis:
             if len(fgn_vis) > 1:
-                raise RuntimeError("cannot work with multiple foreign masters")
+                raise GsyncdError("cannot work with multiple foreign masters")
             fgn_vi = fgn_vis[0]
         return fgn_vi, nat_vi
 
@@ -165,7 +165,7 @@ class GMaster(object):
                 return vi
             if vi0 and vi and vi0['uuid'] != vi['uuid'] and not param.relax_mismatch:
                 # uuid mismatch for master candidate, bail out
-                raise RuntimeError("aborting on uuid change from %s to %s" % \
+                raise GsyncdError("aborting on uuid change from %s to %s" % \
                                    (vi0['uuid'], vi['uuid']))
             # fall back to old
             return vi0
@@ -208,7 +208,7 @@ class GMaster(object):
                gconf.configinterface.set('volume_id', self.uuid)
             if self.volinfo:
                 if self.volinfo['retval']:
-                    raise RuntimeError ("master is corrupt")
+                    raise GsyncdError ("master is corrupt")
             else:
                 if should_display_info or self.crawls == 0:
                     if self.inter_master:
@@ -236,7 +236,7 @@ class GMaster(object):
         else:
             xtr = xtr0
             if xtr > xtl:
-                raise RuntimeError("timestamp corruption for " + path)
+                raise GsyncdError("timestamp corruption for " + path)
             if xtl == xtr:
                 if path == '.' and self.change_seen:
                     self.turns += 1
diff --git a/xlators/features/marker/utils/syncdaemon/resource.py b/xlators/features/marker/utils/syncdaemon/resource.py
index 09839f09e..30011b3d3 100644
--- a/xlators/features/marker/utils/syncdaemon/resource.py
+++ b/xlators/features/marker/utils/syncdaemon/resource.py
@@ -17,6 +17,7 @@ import repce
 from repce import RepceServer, RepceClient
 from master import GMaster
 import syncdutils
+from syncdutils import GsyncdError
 
 UrlRX  = re.compile('\A(\w+)://(.*)')
 HostRX = re.compile('[a-z\d](?:[a-z\d.-]*[a-z\d])?', re.I)
@@ -36,23 +37,31 @@ def desugar(ustr):
             return "gluster://" + ustr
     else:
         if ustr[0] != '/':
-            raise RuntimeError("cannot resolve sugared url '%s'" % ustr)
+            raise GsyncdError("cannot resolve sugared url '%s'" % ustr)
         ap = os.path.normpath(ustr)
         if ap.startswith('//'):
             ap = ap[1:]
         return "file://" + ap
 
+def gethostbyname(hnam):
+    try:
+        return socket.gethostbyname(hnam)
+    except socket.gaierror:
+        ex = sys.exc_info()[1]
+        raise GsyncdError("failed to resolve %s: %s" % \
+                          (hnam, ex.strerror))
+
 def parse_url(ustr):
     m = UrlRX.match(ustr)
     if not m:
         ustr = desugar(ustr)
     m = UrlRX.match(ustr)
     if not m:
-        raise RuntimeError("malformed url")
+        raise GsyncdError("malformed url")
     sch, path = m.groups()
     this = sys.modules[__name__]
     if not hasattr(this, sch.upper()):
-        raise RuntimeError("unknown url scheme " + sch)
+        raise GsyncdError("unknown url scheme " + sch)
     return getattr(this, sch.upper())(path)
 
 
@@ -243,11 +252,11 @@ class SlaveRemote(object):
             for k, v in da0[i].iteritems():
                 da1[i][k] = int(v)
         if da1[0] != da1[1]:
-            raise RuntimeError("RePCe major version mismatch: local %s, remote %s" % (exrv, rv))
+            raise GsyncdError("RePCe major version mismatch: local %s, remote %s" % (exrv, rv))
 
     def rsync(self, files, *args):
         if not files:
-            raise RuntimeError("no files to sync")
+            raise GsyncdError("no files to sync")
         logging.debug("files: " + ", ".join(files))
         argv = gconf.rsync_command.split() + gconf.rsync_extra.split() + ['-aR'] + files + list(args)
         return os.spawnvp(os.P_WAIT, argv[0], argv) == 0
@@ -258,7 +267,7 @@ class AbstractUrl(object):
     def __init__(self, path, pattern):
         m = re.search(pattern, path)
         if not m:
-            raise RuntimeError("malformed path")
+            raise GsyncdError("malformed path")
         self.path = path
         return m.groups()
 
@@ -359,7 +368,7 @@ class GLUSTER(AbstractUrl, SlaveLocal, SlaveRemote):
         self.host, self.volume = sup(self, path, '^(%s):(.+)' % HostRX.pattern)
 
     def canonical_path(self):
-        return ':'.join([socket.gethostbyname(self.host), self.volume])
+        return ':'.join([gethostbyname(self.host), self.volume])
 
     def can_connect_to(self, remote):
         return True
@@ -376,12 +385,12 @@ class GLUSTER(AbstractUrl, SlaveLocal, SlaveRemote):
                     ['-l', gconf.gluster_log_file, '-s', self.host,
                      '--volfile-id', self.volume, '--client-pid=-1', d]
             if os.spawnvp(os.P_WAIT, argv[0], argv):
-                raise RuntimeError("command failed: " + " ".join(argv))
+                raise GsyncdError("command failed: " + " ".join(argv))
             mounted = True
             logging.debug('auxiliary glusterfs mount in place')
             os.chdir(d)
             if umount_l(d) != 0:
-                raise RuntimeError("umounting %s failed" % d)
+                raise GsyncdError("umounting %s failed" % d)
             mounted = False
         finally:
             try:
@@ -419,7 +428,7 @@ class SSH(AbstractUrl, SlaveRemote):
             u, h = m.groups()
         else:
             u, h = pwd.getpwuid(os.geteuid()).pw_name, self.remote_addr
-        remote_addr = '@'.join([u, socket.gethostbyname(h)])
+        remote_addr = '@'.join([u, gethostbyname(h)])
         return ':'.join([remote_addr, self.inner_rsc.get_url(canonical=True)])
 
     def can_connect_to(self, remote):
diff --git a/xlators/features/marker/utils/syncdaemon/syncdutils.py b/xlators/features/marker/utils/syncdaemon/syncdutils.py
index 49ef1662e..a905745f1 100644
--- a/xlators/features/marker/utils/syncdaemon/syncdutils.py
+++ b/xlators/features/marker/utils/syncdaemon/syncdutils.py
@@ -5,9 +5,10 @@ import fcntl
 import shutil
 import logging
 from threading import Lock, Thread as baseThread
-from errno import EACCES, EAGAIN
+from errno import EACCES, EAGAIN, EPIPE, ENOTCONN
 from signal import SIGTERM, SIGKILL
 from time import sleep
+from cPickle import PickleError
 
 from gconf import gconf
 
@@ -125,13 +126,35 @@ def finalize(*a, **kw):
     os._exit(kw.get('exval', 0))
 
 def log_raise_exception(excont):
+    is_filelog = False
+    for h in logging.getLogger().handlers:
+        fno = getattr(getattr(h, 'stream', None), 'fileno', None)
+        if fno and not os.isatty(fno()):
+            is_filelog = True
+
     exc = sys.exc_info()[1]
     if isinstance(exc, SystemExit):
         excont.exval = exc.code or 0
         raise
     else:
-        logging.exception("FAIL: ")
-        sys.stderr.write("failed with %s.\n" % type(exc).__name__)
+        logtag = None
+        if isinstance(exc, GsyncdError):
+            if is_filelog:
+                logging.error(exc.message)
+            sys.stderr.write('failure: ' + exc.message + "\n")
+        elif isinstance(exc, PickleError) or isinstance(exc, EOFError) or \
+             ((isinstance(exc, OSError) or isinstance(exc, IOError)) and \
+              exc.errno == EPIPE):
+            logging.error('connection to peer is broken')
+        elif isinstance(exc, OSError) and exc.errno == ENOTCONN:
+            logging.error('glusterfs session went down')
+        else:
+            logtag = "FAIL"
+        if not logtag and logging.getLogger().isEnabledFor(logging.DEBUG):
+            logtag = "FULL EXCEPTION TRACE"
+        if logtag:
+            logging.exception(logtag + ": ")
+            sys.stderr.write("failed with %s.\n" % type(exc).__name__)
         excont.exval = 1
         sys.exit(excont.exval)
 
@@ -160,3 +183,6 @@ class Thread(baseThread):
             kw['target'] = twrap
         baseThread.__init__(self, *a, **kw)
         self.setDaemon(True)
+
+class GsyncdError(StandardError):
+    pass