Switch logging to WatchedFileHandler

Now that pull runs as a daemon, we need to be able to logrotate, so
switch to using WatchedFileHandlers that offers native support for this.

Signed-off-by: Konstantin Ryabitsev <konstantin@linuxfoundation.org>

6 files changed, 64 insertions, 123 deletions

diff --git a/contrib/logrotate b/contrib/logrotate
new file mode 100644
index 0000000..5b15992
--- /dev/null
+++ b/contrib/logrotate
@@ -0,0 +1,5 @@
+/var/log/grokmirror/*.log {
+    missingok
+    notifempty
+    delaycompress
+}
diff --git a/grokmirror/__init__.py b/grokmirror/__init__.py
index cb66b2a..d5286ae 100644
--- a/grokmirror/__init__.py
+++ b/grokmirror/__init__.py
@@ -23,6 +23,7 @@ import fnmatch
 import subprocess
 import requests
 import logging
+import logging.handlers
 import hashlib
 import pathlib
 import uuid
@@ -42,7 +43,7 @@ MANIFEST_LOCKH = None
 REPO_LOCKH = {}
 GITBIN = '/usr/bin/git'
 
-# default logger. Will probably be overridden.
+# default logger. Will be overridden.
 logger = logging.getLogger(__name__)
 
 _alt_repo_map = None
@@ -948,3 +949,29 @@ def get_repack_level(obj_info, max_loose_objects=1200, max_packs=20, pc_loose_ob
             needs_repack = 1
 
     return needs_repack
+
+
+def init_logger(subcommand, logfile, loglevel, verbose):
+    global logger
+
+    logger = logging.getLogger('grokmirror')
+    logger.setLevel(logging.DEBUG)
+
+    if logfile:
+        ch = logging.handlers.WatchedFileHandler(logfile)
+        formatter = logging.Formatter(subcommand + '[%(process)d] %(asctime)s - %(levelname)s - %(message)s')
+        ch.setFormatter(formatter)
+        ch.setLevel(loglevel)
+        logger.addHandler(ch)
+
+    ch = logging.StreamHandler()
+    formatter = logging.Formatter('%(message)s')
+    ch.setFormatter(formatter)
+
+    if verbose:
+        ch.setLevel(logging.INFO)
+    else:
+        ch.setLevel(logging.CRITICAL)
+
+    logger.addHandler(ch)
+    return logger
diff --git a/grokmirror/dumb_pull.py b/grokmirror/dumb_pull.py
index ac096ed..4fec94b 100755
--- a/grokmirror/dumb_pull.py
+++ b/grokmirror/dumb_pull.py
@@ -180,36 +180,15 @@ def parse_args():
     return opts, args
 
 
-def dumb_pull(args, verbose=False, svn=False, remotes=None, posthook='',
-              logfile=None):
+def dumb_pull(args, verbose=False, svn=False, remotes=None, posthook='', logfile=None):
+    global logger
+
+    loglevel = logging.INFO
+    logger = grokmirror.init_logger('dumb-pull', logfile, loglevel, verbose)
 
     if remotes is None:
         remotes = ['*']
 
-    logger.setLevel(logging.DEBUG)
-
-    ch = logging.StreamHandler()
-    formatter = logging.Formatter('%(message)s')
-    ch.setFormatter(formatter)
-
-    if verbose:
-        ch.setLevel(logging.INFO)
-    else:
-        ch.setLevel(logging.CRITICAL)
-
-    logger.addHandler(ch)
-
-    if logfile is not None:
-        ch = logging.FileHandler(logfile)
-        formatter = logging.Formatter("dumb-pull[%(process)d] %(asctime)s - %(levelname)s - %(message)s")
-        ch.setFormatter(formatter)
-
-        ch.setLevel(logging.DEBUG)
-        logger.addHandler(ch)
-
-    # push our logger into grokmirror to override the default
-    grokmirror.logger = logger
-
     # Find all repositories we are to pull
     for entry in args:
         if entry[-4:] == '.git':
@@ -231,7 +210,6 @@ def dumb_pull(args, verbose=False, svn=False, remotes=None, posthook='',
 
 
 def command():
-
     opts, args = parse_args()
 
     return dumb_pull(
diff --git a/grokmirror/fsck.py b/grokmirror/fsck.py
index 5714a3e..21d3f2b 100755
--- a/grokmirror/fsck.py
+++ b/grokmirror/fsck.py
@@ -376,38 +376,8 @@ def get_repack_level(obj_info, max_loose_objects=1200, max_packs=20, pc_loose_ob
     return needs_repack
 
 
-def fsck_mirror(config, verbose=False, force=False, repack_only=False,
-                conn_only=False, repack_all_quick=False, repack_all_full=False):
-    global logger
-    logger = logging.getLogger('fsck')
-    logger.setLevel(logging.DEBUG)
-
-    logfile = config['core'].get('log', None)
-    if logfile:
-        ch = logging.FileHandler(logfile)
-        formatter = logging.Formatter("fsck[%(process)d] %(asctime)s - %(levelname)s - %(message)s")
-        ch.setFormatter(formatter)
-        loglevel = logging.INFO
-
-        if config['core'].get('loglevel', 'info') == 'debug':
-            loglevel = logging.DEBUG
-
-        ch.setLevel(loglevel)
-        logger.addHandler(ch)
-
-    ch = logging.StreamHandler()
-    formatter = logging.Formatter('%(message)s')
-    ch.setFormatter(formatter)
-
-    if verbose:
-        ch.setLevel(logging.INFO)
-    else:
-        ch.setLevel(logging.CRITICAL)
-
-    logger.addHandler(ch)
-
-    # push it into grokmirror to override the default logger
-    grokmirror.logger = logger
+def fsck_mirror(config, force=False, repack_only=False, conn_only=False,
+                repack_all_quick=False, repack_all_full=False):
 
     if conn_only or repack_all_quick or repack_all_full:
         force = True
@@ -1063,6 +1033,7 @@ def parse_args():
 
 def grok_fsck(cfgfile, verbose=False, force=False, repack_only=False, conn_only=False,
               repack_all_quick=False, repack_all_full=False):
+    global logger
 
     config = grokmirror.load_config_file(cfgfile)
 
@@ -1071,8 +1042,15 @@ def grok_fsck(cfgfile, verbose=False, force=False, repack_only=False, conn_only=
         obstdir = os.path.join(config['core'].get('toplevel'), '_alternates')
         config['core']['objstore'] = obstdir
 
-    fsck_mirror(config, verbose, force, repack_only, conn_only,
-                repack_all_quick, repack_all_full)
+    logfile = config['core'].get('log', None)
+    if config['core'].get('loglevel', 'info') == 'debug':
+        loglevel = logging.DEBUG
+    else:
+        loglevel = logging.INFO
+
+    logger = grokmirror.init_logger('pull', logfile, loglevel, verbose)
+
+    fsck_mirror(config, force, repack_only, conn_only, repack_all_quick, repack_all_full)
 
 
 def command():
diff --git a/grokmirror/manifest.py b/grokmirror/manifest.py
index 1186ba6..6ca759e 100755
--- a/grokmirror/manifest.py
+++ b/grokmirror/manifest.py
@@ -171,6 +171,9 @@ def parse_args():
 def grok_manifest(manifile, toplevel, args=None, logfile=None, usenow=False,
                   check_export_ok=False, purge=False, remove=False,
                   pretty=False, ignore=None, wait=False, verbose=False, fetchobst=False):
+    global logger
+    loglevel = logging.INFO
+    logger = grokmirror.init_logger('manifest', logfile, loglevel, verbose)
 
     startt = datetime.datetime.now()
     if args is None:
@@ -178,31 +181,6 @@ def grok_manifest(manifile, toplevel, args=None, logfile=None, usenow=False,
     if ignore is None:
         ignore = list()
 
-    logger.setLevel(logging.DEBUG)
-    # noinspection PyTypeChecker
-
-    ch = logging.StreamHandler()
-    formatter = logging.Formatter('%(message)s')
-    ch.setFormatter(formatter)
-
-    if verbose:
-        ch.setLevel(logging.INFO)
-    else:
-        ch.setLevel(logging.CRITICAL)
-
-    logger.addHandler(ch)
-
-    if logfile is not None:
-        ch = logging.FileHandler(logfile)
-        formatter = logging.Formatter("manifest[%(process)d] %(asctime)s - %(levelname)s - %(message)s")
-        ch.setFormatter(formatter)
-
-        ch.setLevel(logging.DEBUG)
-        logger.addHandler(ch)
-
-    # push our logger into grokmirror to override the default
-    grokmirror.logger = logger
-
     grokmirror.manifest_lock(manifile)
     manifest = grokmirror.read_manifest(manifile, wait=wait)
 
diff --git a/grokmirror/pull.py b/grokmirror/pull.py
index 2af635e..ea6dd50 100755
--- a/grokmirror/pull.py
+++ b/grokmirror/pull.py
@@ -956,39 +956,7 @@ def showstats(q_todo, q_pull, q_spa, good, bad, pws, dws):
     logger.info('      ---:  %s', ', '.join(stats))
 
 
-def pull_mirror(config, verbose=False, nomtime=False, forcepurge=False, runonce=False):
-    global logger
-
-    logger = logging.getLogger('pull')
-    logger.setLevel(logging.DEBUG)
-
-    logfile = config['core'].get('log', None)
-    if logfile:
-        ch = logging.FileHandler(logfile)
-        formatter = logging.Formatter("pull[%(process)d] %(asctime)s - %(levelname)s - %(message)s")
-        ch.setFormatter(formatter)
-        loglevel = logging.INFO
-
-        if config['core'].get('loglevel', 'info') == 'debug':
-            loglevel = logging.DEBUG
-
-        ch.setLevel(loglevel)
-        logger.addHandler(ch)
-
-    ch = logging.StreamHandler()
-    formatter = logging.Formatter('%(message)s')
-    ch.setFormatter(formatter)
-
-    if verbose:
-        ch.setLevel(logging.INFO)
-    else:
-        ch.setLevel(logging.CRITICAL)
-
-    logger.addHandler(ch)
-
-    # push it into grokmirror to override the default logger
-    grokmirror.logger = logger
-
+def pull_mirror(config, nomtime=False, forcepurge=False, runonce=False):
     toplevel = os.path.realpath(config['core'].get('toplevel'))
     obstdir = os.path.realpath(config['core'].get('objstore'))
     refresh = config['pull'].getint('refresh', 300)
@@ -1042,13 +1010,11 @@ def pull_mirror(config, verbose=False, nomtime=False, forcepurge=False, runonce=
                     pws.remove(pw)
                     logger.info('   worker: terminated (%s remaining)', len(pws))
                     showstats(q_todo, q_pull, q_spa, good, bad, pws, dws)
-                    continue
 
             for dw in dws:
                 if dw and not dw.is_alive():
                     dws.remove(dw)
                     showstats(q_todo, q_pull, q_spa, good, bad, pws, dws)
-                    continue
 
             if not q_spa.empty() and not len(dws):
                 if runonce:
@@ -1225,12 +1191,21 @@ def parse_args():
 
 
 def grok_pull(cfgfile, verbose=False, nomtime=False, forcepurge=False, runonce=False):
+    global logger
 
     config = grokmirror.load_config_file(cfgfile)
     if config['pull'].get('refresh', None) is None:
         runonce = True
 
-    return pull_mirror(config, verbose, nomtime, forcepurge, runonce)
+    logfile = config['core'].get('log', None)
+    if config['core'].get('loglevel', 'info') == 'debug':
+        loglevel = logging.DEBUG
+    else:
+        loglevel = logging.INFO
+
+    logger = grokmirror.init_logger('pull', logfile, loglevel, verbose)
+
+    return pull_mirror(config, nomtime, forcepurge, runonce)
 
 
 def command():