Rework logging initialization code.

svn path=/trunk/; revision=5836

12 files changed, 114 insertions, 51 deletions

diff --git a/ca/rpki-start-servers b/ca/rpki-start-servers
index edaffb2e..ede47bec 100755
--- a/ca/rpki-start-servers
+++ b/ca/rpki-start-servers
@@ -48,9 +48,9 @@ cfg = rpki.config.parser(args.config, "myrpki")
 
 def run(name):
   # pylint: disable=E1103
-  cmd = (os.path.join(rpki.autoconf.libexecdir, name), "-c", cfg.filename)
+  cmd = (os.path.join(rpki.autoconf.libexecdir, name), "--config", cfg.filename)
   if args.debug:
-    proc = subprocess.Popen(cmd + ("-d",),
+    proc = subprocess.Popen(cmd + ("--foreground", "--log-stderr"),
                             stdout = open(os.path.join(args.logdir, name + ".log"), "a"),
                             stderr = subprocess.STDOUT)
   else:
diff --git a/ca/tests/smoketest.py b/ca/tests/smoketest.py
index 46182b52..1ff47aef 100644
--- a/ca/tests/smoketest.py
+++ b/ca/tests/smoketest.py
@@ -156,7 +156,7 @@ def main():
   Main program.
   """
 
-  rpki.log.init(smoketest_name, use_syslog = False)
+  rpki.log.init(smoketest_name)
   rpki.log.info("Starting")
 
   pubd_process = None
@@ -227,10 +227,10 @@ def main():
   try:
 
     rpki.log.info("Starting rootd")
-    rootd_process = subprocess.Popen((prog_python, prog_rootd, "-d", "-c", rootd_name + ".conf"))
+    rootd_process = subprocess.Popen((prog_python, prog_rootd, "--foreground", "--log-stderr", "--config", rootd_name + ".conf"))
 
     rpki.log.info("Starting pubd")
-    pubd_process = subprocess.Popen((prog_python, prog_pubd, "-d", "-c", pubd_name + ".conf") +
+    pubd_process = subprocess.Popen((prog_python, prog_pubd, "--foreground", "--log-stderr", "--config", pubd_name + ".conf") +
                                     (("-p", pubd_name + ".prof") if args.profile else ()))
 
     rpki.log.info("Starting rsyncd")
@@ -829,9 +829,9 @@ class allocation(object):
     Run daemons for this entity.
     """
     rpki.log.info("Running daemons for %s" % self.name)
-    self.rpkid_process = subprocess.Popen((prog_python, prog_rpkid, "-d", "-c", self.name + ".conf") +
-                                          (("-p", self.name + ".prof") if args.profile else ()))
-    self.irdbd_process = subprocess.Popen((prog_python, prog_irdbd, "-d", "-c", self.name + ".conf"))
+    self.rpkid_process = subprocess.Popen((prog_python, prog_rpkid, "--foreground", "--log-stderr", "--config", self.name + ".conf") +
+                                          (("--profile", self.name + ".prof") if args.profile else ()))
+    self.irdbd_process = subprocess.Popen((prog_python, prog_irdbd, "--foreground", "--log-stderr", "--config", self.name + ".conf"))
 
   def kill_daemons(self):
     """
diff --git a/ca/tests/yamlconf.py b/ca/tests/yamlconf.py
index 3c71d3cd..5a66fe8f 100644
--- a/ca/tests/yamlconf.py
+++ b/ca/tests/yamlconf.py
@@ -617,7 +617,7 @@ def main():
   quiet = args.quiet
   yaml_file = args.yaml_file
 
-  rpki.log.init("yamlconf", use_syslog = False)
+  rpki.log.init("yamlconf")
 
   # Allow optional config file for this tool to override default
   # passwords: this is mostly so that I can show a complete working
diff --git a/ca/tests/yamltest.py b/ca/tests/yamltest.py
index 5eb3bd2f..3716bd54 100644
--- a/ca/tests/yamltest.py
+++ b/ca/tests/yamltest.py
@@ -553,7 +553,7 @@ class allocation(object):
     representing the running daemon.
     """
     basename = os.path.splitext(os.path.basename(prog))[0]
-    cmd = [prog, "-d", "-c", self.path("rpki.conf")]
+    cmd = [prog, "--foreground", "--log-stderr", "--config", self.path("rpki.conf")]
     if args.profile and basename != "rootd":
       cmd.append("--profile")
       cmd.append(self.path(basename + ".prof"))
@@ -665,7 +665,7 @@ try:
   if args.pidfile is not None:
     open(args.pidfile, "w").write("%s\n" % os.getpid())
 
-  rpki.log.init("yamltest", use_syslog = False)
+  rpki.log.init("yamltest")
 
   # Allow optional config file for this tool to override default
   # passwords: this is mostly so that I can show a complete working
diff --git a/rpki/adns.py b/rpki/adns.py
index a6a900ed..50841f7f 100644
--- a/rpki/adns.py
+++ b/rpki/adns.py
@@ -317,7 +317,7 @@ class getaddrinfo(object):
 
 if __name__ == "__main__":
 
-  rpki.log.init("test-adns", use_syslog = False)
+  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/irdbd.py b/rpki/irdbd.py
index 41739dc4..850f8ac8 100644
--- a/rpki/irdbd.py
+++ b/rpki/irdbd.py
@@ -153,22 +153,21 @@ class main(object):
     parser = argparse.ArgumentParser(description = __doc__)
     parser.add_argument("-c", "--config",
                         help = "override default location of configuration file")
-    parser.add_argument("-d", "--debug", action = "store_true",
-                        help = "enable debugging mode")
     parser.add_argument("-f", "--foreground", action = "store_true",
                         help = "do not daemonize")
     parser.add_argument("--pidfile",
                         help = "override default location of pid file")
     parser.add_argument("--profile",
                         help = "enable profiling, saving data to PROFILE")
+    rpki.log.argparse_setup(parser)
     args = parser.parse_args()
 
-    rpki.log.init("irdbd", use_syslog = not args.debug)
+    rpki.log.init("irdbd", args)
 
     self.cfg = rpki.config.parser(args.config, "irdbd")
     self.cfg.set_global_flags()
 
-    if not args.foreground and not args.debug:
+    if not args.foreground:
       rpki.daemonize.daemon(pidfile = args.pidfile)
 
     if args.profile:
diff --git a/rpki/log.py b/rpki/log.py
index 9f59444f..4c4a444c 100644
--- a/rpki/log.py
+++ b/rpki/log.py
@@ -26,6 +26,7 @@ import sys
 import time
 import logging
 import logging.handlers
+import argparse
 import traceback as tb
 
 try:
@@ -67,36 +68,101 @@ use_setproctitle = True
 
 proctitle_extra = os.path.basename(os.getcwd())
 
-def init(ident = "rpki", use_syslog = True):
+def argparse_setup(parser):
+  """
+  Set up argparse stuff for functionality in this module.
+
+  Default logging destination is syslog, but also see rpki.log.init().
+  """
+
+  class RotatingFile(argparse.Action):
+    def __call__(self, parser, namespace, values, option_string = None):
+      setattr(namespace, self.dest, values[0])
+      setattr(namespace, self.dest + "_maxBytes",    int(values[1]))
+      setattr(namespace, self.dest + "_backupCount", int(values[2]))
+      if len(values) > 3:
+        raise ValueError
+
+  class TimedRotatingFile(argparse.Action):
+    def __call__(self, parser, namespace, values, option_string = None):
+      setattr(namespace, self.dest, values[0])
+      setattr(namespace, self.dest + "_interval",    int(values[1]))
+      setattr(namespace, self.dest + "_backupCount", int(values[2]))
+      if len(values) > 3:
+        raise ValueError
+
+  parser.add_argument("--log-level", default = logging.DEBUG,
+                      choices = ("debug", "info", "warning", "error", "critical"),
+                      type = lambda s: int(getattr(logging, s.upper())),
+                      help = "how verbosely to log")
+  group = parser.add_mutually_exclusive_group()
+  group.add_argument("--log-syslog", nargs = "?", default = "daemon",
+                     choices = sorted(logging.handlers.SysLogHandler.facility_names.keys()),
+                     help = "send logging to syslog")
+  group.add_argument("--log-stderr", dest = "log_stream", action = "store_const", const = sys.stderr,
+                     help = "send logging to standard error")
+  group.add_argument("--log-stdout", dest = "log_stream", action = "store_const", const = sys.stdout,
+                     help = "send logging to standard output")
+  group.add_argument("--log-file",
+                     help = "send logging to a plain old file")
+  group.add_argument("--log-rotating-file", action = RotatingFile,
+                     nargs = 3, metavar = ("FILENAME", "KBYTES", "COUNT"),
+                     help = "send logging to rotating file")
+  group.add_argument("--log-timed-rotating-file", action = TimedRotatingFile,
+                     nargs = 3, metavar = ("FILENAME", "HOURS", "COUNT"),
+                     help = "send logging to timed rotating file")
+
+
+def init(ident = "rpki", args = argparse.Namespace(log_level = logging.DEBUG, log_stream = sys.stderr)):
   """
   Initialize logging system.
+
+  Default logging destination is syslog if "args" is specified, stderr otherwise.
   """
 
-  # This will want tweaking after basic conversion to logging package
-  # is finished.  For now, keep it simple.
-  #
-  # Should also support LoggingAdapters, rotating log files,
-  # configurable log levels, and other forms of entertainment.
+  assert isinstance(args, argparse.Namespace)
 
-  format = ident + "[%(process)d] %(message)s"
-  if not use_syslog:
-    format = "%(asctime)s " + format
+  if args.log_stream:
+    handler = logging.StreamHandler(stream = args.log_stream)
 
-  formatter = logging.Formatter(format, "%Y-%m-%dT%H:%M:%SZ")
-  formatter.converter = time.gmtime
+  elif args.log_file:
+    handler = logging.FileHandler(filename = args.log_file)
+
+  elif args.log_rotating_file:
+    handler = logging.handlers.RotatingFileHandler(
+      filename = args.log_rotating_file,
+      maxBytes = args.log_rotating_file_maxBytes,
+      backupCount = args.log_rotating_file_backupCount)
+
+  elif args.log_timed_rotating_file:
+    handler = logging.handlers.TimedRotatingFileHandler(
+      filename = args.log_timed_rotating_file,
+      interval = args.log_timed_rotating_file_interval,
+      backupCount = args.log_timed_rotating_file_backupCount)
+
+  elif args.log_syslog:
+    handler = logging.handlers.SysLogHandler(
+      address = "/dev/log" if os.path.exists("/dev/log") else ("localhost", logging.handlers.SYSLOG_UDP_PORT),
+      facility = args.log_syslog)
 
-  if not use_syslog:
-    handler = logging.StreamHandler()
-  elif os.path.exists("/dev/log"):
-    handler = logging.handlers.SysLogHandler("/dev/log")
   else:
-    handler = logging.handlers.SysLogHandler()
+    raise ValueError
+  
+  format = ident + "[%(process)d]: %(message)s"
+  if not isinstance(handler, logging.handlers.SysLogHandler):
+    format = "%(asctime)s " + format
+
+  # At some point we will probably want our own subclass of
+  # logging.Formatter so we can support LoggingAdapters with extra
+  # fields, but this suffices for the moment.
 
+  formatter = logging.Formatter(format, "%Y-%m-%d %H:%M:%S")
+  formatter.converter = time.gmtime
   handler.setFormatter(formatter)
-  logging.root.addHandler(handler)
 
-  #logging.root.setLevel(args.log_level)
-  logging.root.setLevel(logging.DEBUG)
+  root_logger = logging.getLogger()
+  root_logger.addHandler(handler)
+  root_logger.setLevel(args.log_level)
 
   if ident and have_setproctitle and use_setproctitle:
     if proctitle_extra:
diff --git a/rpki/old_irdbd.py b/rpki/old_irdbd.py
index 41060344..eb901f5d 100644
--- a/rpki/old_irdbd.py
+++ b/rpki/old_irdbd.py
@@ -285,11 +285,12 @@ class main(object):
     parser = argparse.ArgumentParser(description = __doc__)
     parser.add_argument("-c", "--config",
                         help = "override default location of configuration file")
-    parser.add_argument("-d", "--debug", action = "store_true",
-                        help = "enable debugging mode")
+    parser.add_argument("-f", "--foreground", action = "store_true",
+                        help = "do not daemonize (ignored, old_irdbd never daemonizes)")
+    rpki.log.argparse_setup(parser)
     args = parser.parse_args()
 
-    rpki.log.init("irdbd", use_syslog = not args.debug)
+    rpki.log.init("irdbd", args)
 
     self.cfg = rpki.config.parser(args.config, "irdbd")
 
diff --git a/rpki/pubd.py b/rpki/pubd.py
index 31f22ed4..ec7be81e 100644
--- a/rpki/pubd.py
+++ b/rpki/pubd.py
@@ -53,24 +53,23 @@ class main(object):
     parser = argparse.ArgumentParser(description = __doc__)
     parser.add_argument("-c", "--config",
                         help = "override default location of configuration file")
-    parser.add_argument("-d", "--debug", action = "store_true",
-                        help = "enable debugging mode")
     parser.add_argument("-f", "--foreground", action = "store_true",
                         help = "do not daemonize")
     parser.add_argument("--pidfile",
                         help = "override default location of pid file")
     parser.add_argument("--profile",
                         help = "enable profiling, saving data to PROFILE")
+    rpki.log.argparse_setup(parser)
     args = parser.parse_args()
 
     self.profile = args.profile
 
-    rpki.log.init("pubd", use_syslog = not args.debug)
+    rpki.log.init("pubd", args)
 
     self.cfg = rpki.config.parser(args.config, "pubd")
     self.cfg.set_global_flags()
 
-    if not args.foreground and not args.debug:
+    if not args.foreground:
       rpki.daemonize.daemon(pidfile = args.pidfile)
 
     if self.profile:
diff --git a/rpki/rootd.py b/rpki/rootd.py
index 43e84873..1b6beb55 100644
--- a/rpki/rootd.py
+++ b/rpki/rootd.py
@@ -336,20 +336,19 @@ class main(object):
     parser = argparse.ArgumentParser(description = __doc__)
     parser.add_argument("-c", "--config",
                         help = "override default location of configuration file")
-    parser.add_argument("-d", "--debug", action = "store_true",
-                        help = "enable debugging mode")
     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)
     args = parser.parse_args()
 
-    rpki.log.init("rootd", use_syslog = not args.debug)
+    rpki.log.init("rootd", args)
 
     self.cfg = rpki.config.parser(args.config, "rootd")
     self.cfg.set_global_flags()
 
-    if not args.foreground and not args.debug:
+    if not args.foreground:
       rpki.daemonize.daemon(pidfile = args.pidfile)
 
     self.bpki_ta                 = rpki.x509.X509(Auto_update = self.cfg.get("bpki-ta"))
diff --git a/rpki/rpkic.py b/rpki/rpkic.py
index d5339f5b..e01eeae2 100644
--- a/rpki/rpkic.py
+++ b/rpki/rpkic.py
@@ -111,7 +111,7 @@ class main(Cmd):
       self.main(args)
 
   def main(self, args):
-    rpki.log.init("rpkic", use_syslog = False)
+    rpki.log.init("rpkic")
     self.read_config()
     if self.interactive:
       Cmd.__init__(self)
diff --git a/rpki/rpkid.py b/rpki/rpkid.py
index 5546a02b..d0918b3c 100644
--- a/rpki/rpkid.py
+++ b/rpki/rpkid.py
@@ -60,24 +60,23 @@ class main(object):
     parser = argparse.ArgumentParser(description = __doc__)
     parser.add_argument("-c", "--config",
                         help = "override default location of configuration file")
-    parser.add_argument("-d", "--debug", action = "store_true",
-                        help = "enable debugging mode")
     parser.add_argument("-f", "--foreground", action = "store_true",
                         help = "do not daemonize")
     parser.add_argument("--pidfile",
                         help = "override default location of pid file")
     parser.add_argument("--profile",
                         help = "enable profiling, saving data to PROFILE")
+    rpki.log.argparse_setup(parser)
     args = parser.parse_args()
 
     self.profile = args.profile
 
-    rpki.log.init("rpkid", use_syslog = not args.debug)
+    rpki.log.init("rpkid", args)
 
     self.cfg = rpki.config.parser(args.config, "rpkid")
     self.cfg.set_global_flags()
 
-    if not args.foreground and not args.debug:
+    if not args.foreground:
       rpki.daemonize.daemon(pidfile = args.pidfile)
 
     if self.profile: