Further consolidation of config file parsing, command line parsing,

and logging setup.  Most programs now use the unified mechanism,
although there are still a few holdouts: the GUI, which is a special
case because it has no command line, and the rpki-rtr program, which,
for historical reasons has its own implementation of the logging setup
infrastructure.

svn path=/branches/tk705/; revision=6390

9 files changed, 269 insertions, 253 deletions

diff --git a/rpki/adns.py b/rpki/adns.py
index 365e9803..4f8cf7ea 100644
--- a/rpki/adns.py
+++ b/rpki/adns.py
@@ -335,7 +335,6 @@ class getaddrinfo(object):
 
 if __name__ == "__main__":
 
-    rpki.log.init("test-adns")
     print "Some adns tests may take a minute or two, please be patient"
 
     class test_getaddrinfo(object):
diff --git a/rpki/config.py b/rpki/config.py
index 1aea0132..f1c43938 100644
--- a/rpki/config.py
+++ b/rpki/config.py
@@ -25,6 +25,10 @@ ConfigParser module.
 import ConfigParser
 import argparse
 import logging
+import logging.handlers
+import traceback
+import time
+import sys
 import os
 import re
 
@@ -44,6 +48,7 @@ except ImportError:
 
 rpki_conf_envname = "RPKI_CONF"
 
+
 class parser(object):
     """
     Extensions to stock Python ConfigParser:
@@ -90,6 +95,7 @@ class parser(object):
 
         self.filename = filename or os.getenv(rpki_conf_envname) or default_filename
         self.argparser = argparser
+        self.logging_defaults = None
 
         try:
             with open(self.filename, "r") as f:
@@ -132,7 +138,7 @@ class parser(object):
         if self.cfg.has_option(section, option):
             yield self.cfg.get(section, option)
         option += "."
-        matches = [o for o in self.cfg.options(section) 
+        matches = [o for o in self.cfg.options(section)
                    if o.startswith(option) and o[len(option):].isdigit()]
         matches.sort()
         for option in matches:
@@ -201,20 +207,7 @@ class parser(object):
         return long(self.get(option, default, section))
 
 
-    def add_argument(self, *names, **kwargs):
-        """
-        Combined command line and config file argument.  Takes
-        arguments mostly like ArgumentParser.add_argument(), but also
-        looks in config file for option of the same name.
-
-        The "section" and "default" arguments are used for the config file
-        lookup; the resulting value is used as the "default" parameter for 
-        the argument parser.
-
-        If a "type" argument is specified, it applies to both the value
-        parsed from the config file and the argument parser.
-        """
-
+    def _get_argument_default(self, names, kwargs):
         section = kwargs.pop("section", None)
         default = kwargs.pop("default", None)
 
@@ -225,15 +218,38 @@ class parser(object):
         else:
             raise ValueError
 
-        default = self.get(name, default = default, section = section)
+        if self.has_option(option = name, section = section):
+            default = self.get(option = name, section = section, default = default)
 
         if "type" in kwargs:
             default = kwargs["type"](default)
 
+        if "choices" in kwargs and default not in kwargs["choices"]:
+            raise ValueError
+
         kwargs["default"] = default
 
+        return name, default, kwargs
+
+
+    def add_argument(self, *names, **kwargs):
+        """
+        Combined command line and config file argument.  Takes
+        arguments mostly like ArgumentParser.add_argument(), but also
+        looks in config file for option of the same name.
+
+        The "section" and "default" arguments are used for the config file
+        lookup; the resulting value is used as the "default" parameter for
+        the argument parser.
+
+        If a "type" argument is specified, it applies to both the value
+        parsed from the config file and the argument parser.
+        """
+
+        name, default, kwargs = self._get_argument_default(names, kwargs)
         return self.argparser.add_argument(*names, **kwargs)
 
+
     def add_boolean_argument(self, name, **kwargs):
         """
         Combined command line and config file boolean argument.  Takes
@@ -241,7 +257,7 @@ class parser(object):
         looks in config file for option of the same name.
 
         The "section" and "default" arguments are used for the config file
-        lookup; the resulting value is used as the default value for 
+        lookup; the resulting value is used as the default value for
         the argument parser.
 
         Usage is a bit different from the normal ArgumentParser boolean
@@ -276,6 +292,146 @@ class parser(object):
 
         self.argparser.set_defaults(**{ kwargs["dest"] : default })
 
+
+    def _add_logging_argument(self, *names, **kwargs):
+        group = kwargs.pop("group", self.argparser)
+        name, default, kwargs = self._get_argument_default(names, kwargs)
+        setattr(self.logging_defaults, name.replace("-", "_"), default)
+        if group is not None:
+            group.add_argument(*names, **kwargs)
+
+
+    def add_logging_arguments(self, section = None):
+        """
+        Set up standard logging-related arguments.  This can be called
+        even when we're not going to parse the command line (eg,
+        because we're a WSGI app and therefore don't have a command
+        line), to handle whacking arguments from the config file into
+        the format that the logging setup code expects to see.
+        """
+
+        self.logging_defaults = argparse.Namespace()
+
+        class non_negative_integer(int):
+            def __init__(self, value):
+                if self < 0:
+                    raise ValueError
+
+        class positive_integer(int):
+            def __init__(self, value):
+                if self <= 0:
+                    raise ValueError
+
+        if self.argparser is None:
+            limit_group = None
+        else:
+            limit_group = self.argparser.add_mutually_exclusive_group()
+
+        self._add_logging_argument(
+            "--log-level",
+            default = "warning",
+            choices = ("debug", "info", "warning", "error", "critical"),
+            help    = "how verbosely to log")
+
+        self._add_logging_argument(
+            "--log-destination",
+            default = "stderr",
+            choices = ("syslog", "stdout", "stderr", "file"),
+            help    = "logging mechanism to use")
+
+        self._add_logging_argument(
+            "--log-filename",
+            help    = "where to log when log destination is \"file\"")
+
+        self._add_logging_argument(
+            "--log-facility",
+            default = "daemon",
+            choices = sorted(logging.handlers.SysLogHandler.facility_names.keys()),
+            help    = "syslog facility to use when log destination is \"syslog\"")
+
+        self._add_logging_argument(
+            "--log-count",
+            default = "7",
+            type    = positive_integer,
+            help    = "how many logs to keep when rotating for log destination \"file\""),
+
+        self._add_logging_argument(
+            "--log-size-limit",
+            group   = limit_group,
+            default = 0,
+            type    = non_negative_integer,
+            help    = "size in kbytes after which to rotate log for destination \"file\"")
+
+        self._add_logging_argument(
+            "--log-time-limit",
+            group   = limit_group,
+            default = 0,
+            type    = non_negative_integer,
+            help    = "hours after which to rotate log for destination \"file\"")
+
+
+    def configure_logging(self, args = None, ident = None):
+        """
+        Configure the logging system, using information from both the
+        config file and the command line; if this particular program
+        doesn't use the command line (eg, a WSGI app), we just use the
+        config file.
+        """
+
+        if self.logging_defaults is None:
+            self.add_logging_arguments()
+
+        if args is None:
+            args = self.logging_defaults
+
+        log_level = getattr(logging, args.log_level.upper())
+
+        if args.log_destination == "stderr":
+            log_handler = logging.StreamHandler(
+                stream = sys.stderr)
+
+        elif args.log_destination == "stdout":
+            log_handler = logging.StreamHandler(
+                stream = sys.stdout)
+
+        elif args.log_destination == "syslog":
+            log_handler = logging.handlers.SysLogHandler(
+                address = ("/dev/log" if os.path.exists("/dev/log")
+                           else ("localhost", logging.handlers.SYSLOG_UDP_PORT)),
+                facility = logging.handlers.SysLogHandler.facility_names[args.log_facility])
+
+        elif args.log_destination == "file" and (args.log_size_limit == 0 and 
+                                                 args.log_time_limit == 0):
+            log_handler = logging.handlers.WatchedFileHandler(
+                filename = args.log_filename)
+
+        elif args.log_destination == "file" and args.log_time_limit == 0:
+            log_handler = logging.handlers.RotatingFileHandler(
+                filename    = args.log_filename,
+                maxBytes    = args.log_size_limit * 1024,
+                backupCount = args.log_count)
+
+        elif args.log_destination == "file" and args.log_size_limit == 0:
+            log_handler = logging.handlers.TimedRotatingFileHandler(
+                filename    = args.log_filename,
+                interval    = args.log_time_limit,
+                backupCount = args.log_count,
+                when        = "H",
+                utc         = True)
+            
+        else:
+            raise ValueError
+
+        if ident is None:
+            ident = os.path.basename(sys.argv[0])
+
+        log_handler.setFormatter(Formatter(ident, log_handler, log_level))
+
+        root_logger = logging.getLogger()
+        root_logger.addHandler(log_handler)
+        root_logger.setLevel(log_level)
+
+
     def set_global_flags(self):
         """
         Consolidated control for all the little global control flags
@@ -287,7 +443,6 @@ class parser(object):
 
         # pylint: disable=W0621
         import rpki.x509
-        import rpki.log
         import rpki.daemonize
 
         for line in self.multiget("configure_logger"):
@@ -329,11 +484,6 @@ class parser(object):
             pass
 
         try:
-            rpki.log.enable_tracebacks = self.getboolean("enable_tracebacks")
-        except ConfigParser.NoOptionError:
-            pass
-
-        try:
             rpki.daemonize.default_pid_directory = self.get("pid_directory")
         except ConfigParser.NoOptionError:
             pass
@@ -412,3 +562,73 @@ def argparser(section = None, doc = None, cfg_optional = False):
                  allow_missing = cfg_optional or args.help)
 
     return cfg
+
+
+class Formatter(object):
+    """
+    Reimplementation (easier than subclassing in this case) of
+    logging.Formatter.
+
+    It turns out that the logging code only cares about this class's
+    .format(record) method, everything else is internal; so long as
+    .format() converts a record into a properly formatted string, the
+    logging code is happy.
+
+    So, rather than mess around with dynamically constructing and
+    deconstructing and tweaking format strings and ten zillion options
+    we don't use, we just provide our own implementation that supports
+    what we do need.
+    """
+
+    converter = time.gmtime
+
+    def __init__(self, ident, handler, level):
+        self.ident = ident
+        self.is_syslog = isinstance(handler, logging.handlers.SysLogHandler)
+        self.debugging = level == logging.DEBUG
+
+    def format(self, record):
+        return "".join(self.coformat(record)).rstrip("\n")
+
+    def coformat(self, record):
+
+        try:
+            if not self.is_syslog:
+                yield time.strftime("%Y-%m-%d %H:%M:%S ", time.gmtime(record.created))
+        except:
+            yield "[$!$Time format failed]"
+
+        try:
+            yield "{}[{:d}]: ".format(self.ident, record.process)
+        except:
+            yield "[$!$ident format failed]"
+
+        try:
+            if isinstance(record.context, (str, unicode)):
+                yield record.context + " "
+            else:
+                yield repr(record.context) + " "
+        except AttributeError:
+            pass
+        except:
+            yield "[$!$context format failed]"
+
+        try:
+            yield record.getMessage()
+        except:
+            yield "[$!$record.getMessage() failed]"
+
+        try:
+            if record.exc_info:
+                if self.is_syslog or not self.debugging:
+                    lines = traceback.format_exception_only(
+                        record.exc_info[0], record.exc_info[1])
+                    lines.insert(0, ": ")
+                else:
+                    lines = traceback.format_exception(
+                        record.exc_info[0], record.exc_info[1], record.exc_info[2])
+                    lines.insert(0, "\n")
+                for line in lines:
+                    yield line
+        except:
+            yield "[$!$exception formatting failed]"
diff --git a/rpki/irdbd.py b/rpki/irdbd.py
index adc24a00..7a2c4606 100644
--- a/rpki/irdbd.py
+++ b/rpki/irdbd.py
@@ -160,10 +160,10 @@ class main(object):
         self.cfg.add_argument("--profile",
                               default = "",
                               help = "enable profiling, saving data to PROFILE")
-        rpki.log.argparse_setup(self.cfg.argparser)
+        self.cfg.add_logging_arguments()
         args = self.cfg.argparser.parse_args()
 
-        rpki.log.init("irdbd", args)
+        self.cfg.configure_logging(args = args, ident = "irdbd")
 
         try:
             self.cfg.set_global_flags()
diff --git a/rpki/log.py b/rpki/log.py
index dd3923a7..14805fee 100644
--- a/rpki/log.py
+++ b/rpki/log.py
@@ -29,14 +29,6 @@ import logging.handlers
 import argparse
 import traceback as tb
 
-try:
-    have_setproctitle = False
-    if os.getenv("DISABLE_SETPROCTITLE") is None:
-        import setproctitle                 # pylint: disable=F0401
-        have_setproctitle = True
-except ImportError:
-    pass
-
 logger = logging.getLogger(__name__)
 
 ## @var show_python_ids
@@ -44,200 +36,6 @@ logger = logging.getLogger(__name__)
 
 show_python_ids = False
 
-## @var enable_tracebacks
-# Whether tracebacks are enabled globally.  Individual classes and
-# modules may choose to override this.
-
-enable_tracebacks = True
-
-## @var use_setproctitle
-# Whether to use setproctitle (if available) to change name shown for
-# this process in ps listings (etc).
-
-use_setproctitle = True
-
-## @var proctitle_extra
-
-# Extra text to include in proctitle display.  By default this is the
-# tail of the current directory name, as this is often useful, but you
-# can set it to something else if you like.  If None or the empty
-# string, the extra information field will be omitted from the proctitle.
-
-proctitle_extra = os.path.basename(os.getcwd())
-
-
-class Formatter(object):
-    """
-    Reimplementation (easier than subclassing in this case) of
-    logging.Formatter.
-
-    It turns out that the logging code only cares about this class's
-    .format(record) method, everything else is internal; so long as
-    .format() converts a record into a properly formatted string, the
-    logging code is happy.
-
-    So, rather than mess around with dynamically constructing and
-    deconstructing and tweaking format strings and ten zillion options
-    we don't use, we just provide our own implementation that supports
-    what we do need.
-    """
-
-    converter = time.gmtime
-
-    def __init__(self, ident, handler):
-        self.ident = ident
-        self.is_syslog = isinstance(handler, logging.handlers.SysLogHandler)
-
-    def format(self, record):
-        return "".join(self.coformat(record)).rstrip("\n")
-
-    def coformat(self, record):
-
-        try:
-            if not self.is_syslog:
-                yield time.strftime("%Y-%m-%d %H:%M:%S ", time.gmtime(record.created))
-        except:
-            yield "[$!$Time format failed]"
-
-        try:
-            yield "%s[%d]: " % (self.ident, record.process)
-        except:
-            yield "[$!$ident format failed]"
-
-        try:
-            if isinstance(record.context, (str, unicode)):
-                yield record.context + " "
-            else:
-                yield repr(record.context) + " "
-        except AttributeError:
-            pass
-        except:
-            yield "[$!$context format failed]"
-
-        try:
-            yield record.getMessage()
-        except:
-            yield "[$!$record.getMessage() failed]"
-
-        try:
-            if record.exc_info:
-                if self.is_syslog or not enable_tracebacks:
-                    lines = tb.format_exception_only(record.exc_info[0], record.exc_info[1])
-                    lines.insert(0, ": ")
-                else:
-                    lines = tb.format_exception(record.exc_info[0], record.exc_info[1], record.exc_info[2])
-                    lines.insert(0, "\n")
-                for line in lines:
-                    yield line
-        except:
-            yield "[$!$exception formatting failed]"
-
-
-def argparse_setup(parser, default_thunk = None):
-    """
-    Set up argparse stuff for functionality in this module.
-
-    Default logging destination is syslog, but you can change this
-    by setting default_thunk to a callable which takes no arguments
-    and which returns a instance of a logging.Handler subclass.
-
-    Also see rpki.log.init().
-    """
-
-    class LogLevelAction(argparse.Action):
-        def __call__(self, parser, namespace, values, option_string = None):
-            setattr(namespace, self.dest, getattr(logging, values.upper()))
-
-    parser.add_argument("--log-level", default = logging.WARNING, action = LogLevelAction,
-                        choices = ("debug", "info", "warning", "error", "critical"),
-                        help = "how verbosely to log")
-
-    group = parser.add_mutually_exclusive_group()
-
-    syslog_address = "/dev/log" if os.path.exists("/dev/log") else ("localhost", logging.handlers.SYSLOG_UDP_PORT)
-
-    class SyslogAction(argparse.Action):
-        def __call__(self, parser, namespace, values, option_string = None):
-            namespace.log_handler = lambda: logging.handlers.SysLogHandler(address = syslog_address, facility = values)
-
-    group.add_argument("--log-syslog", nargs = "?", const = "daemon", action = SyslogAction,
-                       choices = sorted(logging.handlers.SysLogHandler.facility_names.keys()),
-                       help = "send logging to syslog")
-
-    class StreamAction(argparse.Action):
-        def __call__(self, parser, namespace, values, option_string = None):
-            namespace.log_handler = lambda: logging.StreamHandler(stream = self.const)
-
-    group.add_argument("--log-stderr", nargs = 0, action = StreamAction, const = sys.stderr,
-                       help = "send logging to standard error")
-
-    group.add_argument("--log-stdout", nargs = 0, action = StreamAction, const = sys.stdout,
-                       help = "send logging to standard output")
-
-    class WatchedFileAction(argparse.Action):
-        def __call__(self, parser, namespace, values, option_string = None):
-            namespace.log_handler = lambda: logging.handlers.WatchedFileHandler(filename = values)
-
-    group.add_argument("--log-file", action = WatchedFileAction,
-                       help = "send logging to a file, reopening if rotated away")
-
-    class RotatingFileAction(argparse.Action):
-        def __call__(self, parser, namespace, values, option_string = None):
-            namespace.log_handler = lambda: logging.handlers.RotatingFileHandler(
-                filename    = values[0],
-                maxBytes    = int(values[1]) * 1024,
-                backupCount = int(values[2]))
-
-    group.add_argument("--log-rotating-file", action = RotatingFileAction,
-                       nargs = 3, metavar = ("FILENAME", "KBYTES", "COUNT"),
-                       help = "send logging to rotating file")
-
-    class TimedRotatingFileAction(argparse.Action):
-        def __call__(self, parser, namespace, values, option_string = None):
-            namespace.log_handler = lambda: logging.handlers.TimedRotatingFileHandler(
-                filename    = values[0],
-                interval    = int(values[1]),
-                backupCount = int(values[2]),
-                when        = "H",
-                utc         = True)
-
-    group.add_argument("--log-timed-rotating-file", action = TimedRotatingFileAction,
-                       nargs = 3, metavar = ("FILENAME", "HOURS", "COUNT"),
-                       help = "send logging to timed rotating file")
-
-    if default_thunk is None:
-        default_thunk = lambda: logging.handlers.SysLogHandler(address = syslog_address, facility = "daemon")
-
-    parser.set_defaults(log_handler = default_thunk)
-
-
-def init(ident = None, args = None):
-    """
-    Initialize logging system.
-
-    Default logging destination is stderr if "args" is not specified.
-    """
-
-    if ident is None:
-        ident = os.path.basename(sys.argv[0])
-
-    if args is None:
-        args = argparse.Namespace(log_level   = logging.WARNING,
-                                  log_handler = logging.StreamHandler)
-
-    handler = args.log_handler()        # pylint: disable=E1101
-    handler.setFormatter(Formatter(ident, handler))
-
-    root_logger = logging.getLogger()
-    root_logger.addHandler(handler)
-    root_logger.setLevel(args.log_level) # pylint: disable=E1101
-
-    if ident and have_setproctitle and use_setproctitle:
-        if proctitle_extra:
-            setproctitle.setproctitle("%s (%s)" % (ident, proctitle_extra))
-        else:
-            setproctitle.setproctitle(ident)
-
 
 def class_logger(module_logger, attribute = "logger"):
     """
diff --git a/rpki/old_irdbd.py b/rpki/old_irdbd.py
index b2dd42bd..c08ce362 100644
--- a/rpki/old_irdbd.py
+++ b/rpki/old_irdbd.py
@@ -273,17 +273,13 @@ class main(object):
         os.environ["TZ"] = "UTC"
         time.tzset()
 
-        parser = argparse.ArgumentParser(description = __doc__)
-        parser.add_argument("-c", "--config",
-                            help = "override default location of configuration file")
-        parser.add_argument("-f", "--foreground", action = "store_true",
-                            help = "do not daemonize (ignored, old_irdbd never daemonizes)")
-        rpki.log.argparse_setup(parser)
+        self.cfg = rpki.config.argparser(section = "irdbd", doc = __doc__)
+        self.cfg.add_boolean_argument("--foreground", default = False,
+                                      help = "do not daemonize (ignored, old_irdbd never daemonizes)")
+        self.cfg.add_logging_arguments()
         args = parser.parse_args()
 
-        rpki.log.init("irdbd", args)
-
-        self.cfg = rpki.config.parser(set_filename = args.config, section = "irdbd")
+        cfg.configure_logging(args = args, ident = "irdbd")
 
         startup_msg = self.cfg.get("startup-message", "")
         if startup_msg:
diff --git a/rpki/pubd.py b/rpki/pubd.py
index 4d8962a7..389936bb 100644
--- a/rpki/pubd.py
+++ b/rpki/pubd.py
@@ -68,12 +68,12 @@ class main(object):
         self.cfg.add_argument("--profile",
                               default = "",
                               help = "enable profiling, saving data to PROFILE")
-        rpki.log.argparse_setup(self.cfg.argparser)
+        self.cfg.add_logging_arguments()
         args = self.cfg.argparser.parse_args()
 
         self.profile = args.profile
 
-        rpki.log.init("pubd", args)
+        self.cfg.configure_logging(args = args, ident = "pubd")
 
         try:
             self.cfg.set_global_flags()
diff --git a/rpki/rootd.py b/rpki/rootd.py
index 70669345..dca60956 100644
--- a/rpki/rootd.py
+++ b/rpki/rootd.py
@@ -399,19 +399,18 @@ class main(object):
         os.environ["TZ"] = "UTC"
         time.tzset()
 
-        parser = argparse.ArgumentParser(description = __doc__)
-        parser.add_argument("-c", "--config",
-                            help = "override default location of configuration file")
-        parser.add_argument("-f", "--foreground", action = "store_true",
-                            help = "do not daemonize")
-        parser.add_argument("--pidfile",
-                            help = "override default location of pid file")
-        rpki.log.argparse_setup(parser)
+        self.cfg = rpki.config.argparser(section = "rootd", doc = __doc__)
+        self.cfg.add_boolean_argument("--foreground", default = False,
+                                      help = "do not daemonize")
+        self.cfg.add_argument("--pidfile",
+                              default = os.pat.join(rpki.daemonize.default_pid_directory,
+                                                    "rootd.pid"),
+                              help = "override default location of pid file")
+        self.cfg.add_logging_arguments()
         args = parser.parse_args()
 
-        rpki.log.init("rootd", args)
+        self.cfg.configure_logging(args = args, ident = "rootd")
 
-        self.cfg = rpki.config.parser(set_filename = args.config, section = "rootd")
         self.cfg.set_global_flags()
 
         if not args.foreground:
diff --git a/rpki/rpkic.py b/rpki/rpkic.py
index 755e9102..e297c4d8 100644
--- a/rpki/rpkic.py
+++ b/rpki/rpkic.py
@@ -128,7 +128,6 @@ class main(Cmd):
             self.main(args)
 
     def main(self, args):
-        rpki.log.init("rpkic")
         self.read_config()
         if self.interactive:
             self.cmdloop_with_history()
@@ -159,6 +158,11 @@ class main(Cmd):
 
         try:
             cfg = rpki.config.parser(set_filename = self.cfg_file, section = "myrpki")
+            cfg.configure_logging(
+                args  = argparse.Namespace(
+                    log_destination = "stderr", 
+                    log_level       = "warning"),
+                ident = "rpkic")
             cfg.set_global_flags()
         except IOError, e:
             sys.exit("%s: %s" % (e.strerror, e.filename))
diff --git a/rpki/rpkid.py b/rpki/rpkid.py
index 119de8ec..e647fe12 100644
--- a/rpki/rpkid.py
+++ b/rpki/rpkid.py
@@ -86,12 +86,12 @@ class main(object):
         self.cfg.add_argument("--profile",
                               default = "",
                               help = "enable profiling, saving data to PROFILE")
-        rpki.log.argparse_setup(self.cfg.argparser)
+        self.cfg.add_logging_arguments()
         args = self.cfg.argparser.parse_args()
 
-        self.profile = args.profile
+        self.cfg.configure_logging(args = args, ident = "rpkid")
 
-        rpki.log.init("rpkid", args)
+        self.profile = args.profile
 
         try:
             self.cfg.set_global_flags()