Merge lp:~jaypipes/glance/bug720816 into lp:~glance-coresec/glance/cactus-trunk

[Jay Pipes]

Adds documentation on configuring logging and a unit test for checking simple log output

Adds documentation on configuring logging and a test that log_file works. It didn't, so this also inludes fixes for setting up log handling :)

[Devin Carlen (devcamcar)]

good stuff!

review: Approve

[Rick Harris (rconradharris)]

Thanks Jay, this is a definite improvement.

review: Approve

[Cory Wright (corywright)]

You may want to merge trunk in once more. I just tried it and got a conflict.

[Jay Pipes (jaypipes)]

Merged and fixed.

[lp:~jaypipes/glance/bug720816]

87. By Jay Pipes on 2011-03-16

Fixed run_tests.py addError() method since I noted it was faulty in another branch...

[Jay Pipes (jaypipes)]

pushing to trunk...

review: Approve

=== modified file 'bin/glance-api'
--- bin/glance-api	2011-02-21 22:11:27 +0000
+++ bin/glance-api	2011-03-16 16:32:09 +0000
@@ -47,7 +47,7 @@
     :param parser: The option parser
     """
     config.add_common_options(parser)
-    config.add_log_options('glance-api', parser)
+    config.add_log_options(parser)
 
 
 if __name__ == '__main__':
@@ -57,7 +57,6 @@
     (options, args) = config.parse_options(oparser)
 
     try:
-        config.setup_logging(options)
         conf, app = config.load_paste_app('glance-api', options, args)
 
         server = wsgi.Server()

=== modified file 'bin/glance-registry'
--- bin/glance-registry	2011-02-21 22:11:27 +0000
+++ bin/glance-registry	2011-03-16 16:32:09 +0000
@@ -47,7 +47,7 @@
     :param parser: The option parser
     """
     config.add_common_options(parser)
-    config.add_log_options('glance-registry', parser)
+    config.add_log_options(parser)
 
 
 if __name__ == '__main__':
@@ -57,7 +57,6 @@
     (options, args) = config.parse_options(oparser)
 
     try:
-        config.setup_logging(options)
         conf, app = config.load_paste_app('glance-registry', options, args)
 
         server = wsgi.Server()

=== modified file 'doc/source/configuring.rst'
--- doc/source/configuring.rst	2011-02-04 23:59:52 +0000
+++ doc/source/configuring.rst	2011-03-16 16:32:09 +0000
@@ -18,3 +18,49 @@
 ==================
 
 .. todo:: Complete details of configuration with paste.deploy config files
+
+Configuring Logging in Glance
+-----------------------------
+
+There are a number of configuration options in Glance that control how Glance
+servers log messages. The configuration options are specified in the
+``glance.conf`` config file.
+
+* ``--log-config=PATH``
+
+Optional. Default: ``None``
+
+Specified on the command line only.
+
+Takes a path to a configuration file to use for configuring logging.
+
+* ``--log-format``
+
+*Because of a bug in the PasteDeploy package, this option is only available
+on the command line.*
+
+Optional. Default: ``%(asctime)s %(levelname)8s [%(name)s] %(message)s``
+
+The format of the log records. See the
+`logging module <http://docs.python.org/library/logging.html>`_ documentation for
+more information on setting this format string.
+
+* ``log_file`` (``--log-file`` when specified on the command line)
+
+The filepath of the file to use for logging messages from Glance's servers. If
+missing, the default is to output messages to ``stdout``, so if you are running
+Glance servers in a daemon mode (using ``glance-control``) you should make
+sure that the ``log_file`` option is set appropriately.
+
+* ``log_dir`` (``--log-dir`` when specified on the command line)
+
+The filepath of the directory to use for log files. If not specified (the default)
+the ``log_file`` is used as an absolute filepath.
+
+* ``log_date_format`` (``--log-date-format`` when specified from the command line)
+
+The format string for timestamps in the log output.
+
+Defaults to ``%Y-%m-%d %H:%M:%S``. See the
+`logging module <http://docs.python.org/library/logging.html>`_ documentation for
+more information on setting this format string.

=== modified file 'glance/common/config.py'
--- glance/common/config.py	2011-02-11 00:12:51 +0000
+++ glance/common/config.py	2011-03-16 16:32:09 +0000
@@ -35,8 +35,6 @@
 
 DEFAULT_LOG_FORMAT = "%(asctime)s %(levelname)8s [%(name)s] %(message)s"
 DEFAULT_LOG_DATE_FORMAT = "%Y-%m-%d %H:%M:%S"
-DEFAULT_LOG_HANDLER = 'stream'
-LOGGING_HANDLER_CHOICES = ['syslog', 'file', 'stream']
 
 
 def parse_options(parser, cli_args=None):
@@ -82,38 +80,7 @@
     parser.add_option_group(group)
 
 
-def add_daemon_options(parser):
-    """
-    Given a supplied optparse.OptionParser, adds an OptionGroup that
-    represents all the configuration options around daemonization.
-
-    :param parser: optparse.OptionParser
-    """
-    help_text = "The following configuration options are specific to "\
-                "the daemonizing of this program."
-
-    group = optparse.OptionGroup(parser, "Daemon Options", help_text)
-    group.add_option('--config', default=None,
-                     help="Configuration file to read when loading "
-                          "application. If missing, the first argument is "
-                          "used. If no arguments are found, then a set of "
-                          "standard directories are searched for a config "
-                          "file.")
-    group.add_option("--pid-file", default=None, metavar="PATH",
-                     help="(Optional) Name of pid file for the server. "
-                          "If not specified, the pid file will be named "
-                          "/var/run/glance/<SERVER>.pid.")
-    group.add_option("--uid", type=int, default=os.getuid(),
-                     help="uid under which to run. Default: %default")
-    group.add_option("--gid", type=int, default=os.getgid(),
-                     help="gid under which to run. Default: %default")
-    group.add_option('--working-directory', '--working-dir',
-                     default=os.path.abspath(os.getcwd()),
-                     help="The working directory. Default: %default")
-    parser.add_option_group(group)
-
-
-def add_log_options(prog_name, parser):
+def add_log_options(parser):
     """
     Given a supplied optparse.OptionParser, adds an OptionGroup that
     represents all the configuration options around logging.
@@ -130,29 +97,25 @@
                           "any other logging options specified. Please see "
                           "the Python logging module documentation for "
                           "details on logging configuration files.")
-    group.add_option('--log-handler', default=DEFAULT_LOG_HANDLER,
-                     metavar="HANDLER",
-                     choices=LOGGING_HANDLER_CHOICES,
-                     help="What logging handler to use? "
-                           "Default: %default")
     group.add_option('--log-date-format', metavar="FORMAT",
                       default=DEFAULT_LOG_DATE_FORMAT,
                       help="Format string for %(asctime)s in log records. "
                            "Default: %default")
-    group.add_option('--log-file', default="%s.log" % prog_name,
-                      metavar="PATH",
-                      help="(Optional) Name of log file to output to.")
+    group.add_option('--log-file', default=None, metavar="PATH",
+                      help="(Optional) Name of log file to output to. "
+                           "If not set, logging will go to stdout.")
     group.add_option("--log-dir", default=None,
                       help="(Optional) The directory to keep log files in "
                            "(will be prepended to --logfile)")
     parser.add_option_group(group)
 
 
-def setup_logging(options):
+def setup_logging(options, conf):
     """
     Sets up the logging options for a log with supplied name
 
     :param options: Mapping of typed option key/values
+    :param conf: Mapping of untyped key/values from config file
     """
 
     if options.get('log_config', None):
@@ -182,27 +145,24 @@
     log_date_format = options.get('log_date_format', DEFAULT_LOG_DATE_FORMAT)
     formatter = logging.Formatter(log_format, log_date_format)
 
-    log_handler = options.get('log_handler', DEFAULT_LOG_HANDLER)
-    if log_handler == 'syslog':
-        syslog = logging.handlers.SysLogHandler(address='/dev/log')
-        syslog.setFormatter(formatter)
-        root_logger.addHandler(syslog)
-    elif log_handler == 'file':
-        logfile = options['log_file']
-        logdir = options['log_dir']
+    logfile = options.get('log_file')
+    if not logfile:
+        logfile = conf.get('log_file')
+
+    if logfile:
+        logdir = options.get('log_dir')
+        if not logdir:
+            logdir = conf.get('log_dir')
         if logdir:
             logfile = os.path.join(logdir, logfile)
         logfile = logging.FileHandler(logfile)
         logfile.setFormatter(formatter)
         logfile.setFormatter(formatter)
         root_logger.addHandler(logfile)
-    elif log_handler == 'stream':
+    else:
         handler = logging.StreamHandler(sys.stdout)
         handler.setFormatter(formatter)
         root_logger.addHandler(handler)
-    else:
-        raise exception.BadInputError(
-            "unrecognized log handler '%(log_handler)s'" % locals())
 
 
 def find_config_file(options, args):
@@ -270,6 +230,11 @@
                             "Cannot load application %s" % app_name)
     try:
         conf = deploy.appconfig("config:%s" % conf_file, name=app_name)
+
+        # Setup logging early, supplying both the CLI options and the
+        # configuration mapping from the config file
+        setup_logging(options, conf)
+
         # We only update the conf dict for the verbose and debug
         # flags. Everything else must be set up in the conf file...
         conf['verbose'] = options['verbose']

=== modified file 'run_tests.py'
--- run_tests.py	2011-03-16 06:43:16 +0000
+++ run_tests.py	2011-03-16 16:32:09 +0000
@@ -129,8 +129,7 @@
             'yellow': red | green | bold,
             'magenta': red | blue | bold,
             'cyan': green | blue | bold,
-            'white': red | green | blue | bold
-            }
+            'white': red | green | blue | bold}
 
     def supported(cls, stream=sys.stdout):
         try:
@@ -238,15 +237,15 @@
                     elif self.dots:
                         stream.write(label[:1])
                 return
-            self.errors.append((test, exc_info))
-            test.passed = False
-            if stream is not None:
-                if self.showAll:
-                    self.colorizer.write("ERROR", 'red')
-                    self.stream.writeln()
-                elif self.dots:
-                    stream.write('E')
-    
+        self.errors.append((test, exc_info))
+        test.passed = False
+        if stream is not None:
+            if self.showAll:
+                self.colorizer.write("ERROR", 'red')
+                self.stream.writeln()
+            elif self.dots:
+                stream.write('E')
+
     def startTest(self, test):
         unittest.TestResult.startTest(self, test)
         current_case = test.test.__class__.__name__

=== modified file 'tests/unit/test_migrations.py'
--- tests/unit/test_migrations.py	2011-03-08 17:53:25 +0000
+++ tests/unit/test_migrations.py	2011-03-16 16:32:09 +0000
@@ -33,8 +33,7 @@
 
         self.options = dict(sql_connection=sql_connection,
                             verbose=False)
-
-        config.setup_logging(self.options)
+        config.setup_logging(self.options, {})
 
     def tearDown(self):
         api.configure_db(self.options)

=== modified file 'tests/unit/test_misc.py'
--- tests/unit/test_misc.py	2011-03-14 19:10:24 +0000
+++ tests/unit/test_misc.py	2011-03-16 16:32:09 +0000
@@ -207,3 +207,146 @@
             cmd = "./bin/glance-control registry stop "\
                   "%s --pid-file=glance-registry.pid" % conf_file_name
             ignored, out, err = execute(cmd)
+
+
+# TODO(jaypipes): Move this to separate test file once
+# LP Bug#731304 moves execute() out to a common file, etc
+class TestLogging(unittest.TestCase):
+
+    """Tests that logging can be configured correctly"""
+
+    def setUp(self):
+        self.logfiles = []
+
+    def tearDown(self):
+        self._cleanup_test_servers()
+        self._cleanup_log_files()
+
+    def _cleanup_test_servers(self):
+        # Clean up any leftover test servers...
+        pid_files = ('glance-api.pid', 'glance-registry.pid')
+        for pid_file in pid_files:
+            if os.path.exists(pid_file):
+                pid = int(open(pid_file).read().strip())
+                try:
+                    os.killpg(pid, signal.SIGTERM)
+                except:
+                    pass  # Ignore if the process group is dead
+                os.unlink(pid_file)
+
+    def _cleanup_log_files(self):
+        for f in self.logfiles:
+            if os.path.exists(f):
+                os.unlink(f)
+
+    def test_logfile(self):
+        """
+        A test that logging can be configured properly from the
+        glance.conf file with the log_file option.
+
+        We start both servers daemonized with a temporary config
+        file that has some logging options in it.
+
+        We then use curl to issue a few requests and verify that each server's
+        logging statements were logged to the one log file
+        """
+        logfile = "/tmp/test_logfile.log"
+        self.logfiles.append(logfile)
+
+        if os.path.exists(logfile):
+            os.unlink(logfile)
+
+        self._cleanup_test_servers()
+
+        # Port numbers hopefully not used by anything...
+        api_port = 32001
+        reg_port = 32000
+        image_dir = "/tmp/test.images.%d" % api_port
+        if os.path.exists(image_dir):
+            shutil.rmtree(image_dir)
+
+        # A config file to use just for this test...we don't want
+        # to trample on currently-running Glance servers, now do we?
+        with tempfile.NamedTemporaryFile() as conf_file:
+            conf_contents = """[DEFAULT]
+verbose = True
+debug = True
+log_file = %(logfile)s
+
+[app:glance-api]
+paste.app_factory = glance.server:app_factory
+filesystem_store_datadir=%(image_dir)s
+default_store = file
+bind_host = 0.0.0.0
+bind_port = %(api_port)s
+registry_host = 0.0.0.0
+registry_port = %(reg_port)s
+
+[app:glance-registry]
+paste.app_factory = glance.registry.server:app_factory
+bind_host = 0.0.0.0
+bind_port = %(reg_port)s
+sql_connection = sqlite://
+sql_idle_timeout = 3600
+""" % locals()
+            conf_file.write(conf_contents)
+            conf_file.flush()
+            conf_file_name = conf_file.name
+
+            venv = ""
+            if 'VIRTUAL_ENV' in os.environ:
+                venv = "tools/with_venv.sh "
+
+            # Start up the API and default registry server
+            cmd = venv + "./bin/glance-control api start "\
+                         "%s --pid-file=glance-api.pid" % conf_file_name
+            exitcode, out, err = execute(cmd)
+
+            self.assertEquals(0, exitcode)
+            self.assertTrue("Starting glance-api with" in out)
+
+            cmd = venv + "./bin/glance-control registry start "\
+                         "%s --pid-file=glance-registry.pid" % conf_file_name
+            exitcode, out, err = execute(cmd)
+
+            self.assertEquals(0, exitcode)
+            self.assertTrue("Starting glance-registry with" in out)
+
+            time.sleep(2)  # Gotta give some time for spin up...
+
+            cmd = "curl -X POST -H 'Content-Type: application/octet-stream' "\
+                  "-H 'X-Image-Meta-Name: ImageName' "\
+                  "-H 'X-Image-Meta-Disk-Format: Invalid' "\
+                  "http://0.0.0.0:%d/images" % api_port
+            ignored, out, err = execute(cmd)
+
+            self.assertTrue('Invalid disk format' in out,
+                            "Could not find 'Invalid disk format' "
+                            "in output: %s" % out)
+
+            self.assertTrue(os.path.exists(logfile),
+                            "Logfile %s does not exist!" % logfile)
+
+            logfile_contents = open(logfile, 'rb').read()
+
+            # Check that BOTH the glance API and registry server
+            # modules are logged to the file.
+            self.assertTrue('[glance.server]' in logfile_contents,
+                            "Could not find '[glance.server]' "
+                            "in logfile: %s" % logfile_contents)
+            self.assertTrue('[glance.registry.server]' in logfile_contents,
+                            "Could not find '[glance.registry.server]' "
+                            "in logfile: %s" % logfile_contents)
+
+            # Test that the error we caused above is in the log
+            self.assertTrue('Invalid disk format' in logfile_contents,
+                            "Could not find 'Invalid disk format' "
+                            "in logfile: %s" % logfile_contents)
+
+            # Spin down the API and default registry server
+            cmd = "./bin/glance-control api stop "\
+                  "%s --pid-file=glance-api.pid" % conf_file_name
+            ignored, out, err = execute(cmd)
+            cmd = "./bin/glance-control registry stop "\
+                  "%s --pid-file=glance-registry.pid" % conf_file_name
+            ignored, out, err = execute(cmd)