Yet another refactoring of the startup logging; this gets the startup and

debug handlers installed much earlier (before we have any configuration info)
so that very early log messages are not lost.  The debug handler is removed
as soon as we know whether debug mode is disabled, and the startup messages
are flushed to the real log as soon as we have it.

The Zope.Startup.ZopeStarter object makes more sense now as well.

lib/python/Zope/Startup/__init__.py

@@ -22,67 +22,99 @@ import socket
 
 import ZConfig
 
+from ZConfig.components.logger import loghandler
+
+
 logger = logging.getLogger("Zope")
 started = False
 
-def start_zope(cfg):
+def get_starter():
+    check_python_version()
+    if sys.platform[:3].lower() == "win":
+        return WindowsZopeStarter()
+    else:
+        return UnixZopeStarter()
+
+def start_zope(cfg, debug_handler):
     """The function called by run.py which starts a Zope appserver."""
     global started
     if started:
-        # dont allow any code to call start_zope twice.
+        # Don't allow any code to call start_zope() twice.
         return
 
-    check_python_version()
-    if sys.platform[:3].lower() == "win":
-        starter = WindowsZopeStarter(cfg)
-    else:
-        starter = UnixZopeStarter(cfg)
-    starter.setupLocale()
-    # we log events to the root logger, which is backed by a
-    # "StartupHandler" log handler.  The "StartupHandler" outputs to
-    # stderr but also buffers log messages.  When the "real" loggers
-    # are set up, we flush accumulated messages in StartupHandler's
-    # buffers to the real logger.
-    starter.setupInitialLogging()
-    starter.setupSecurityOptions()
-    # Start ZServer servers before we drop privileges so we can bind to
-    # "low" ports:
-    starter.setupZServerThreads()
-    starter.setupServers()
-    # drop privileges after setting up servers
-    starter.dropPrivileges()
-    starter.makeLockFile()
-    starter.makePidFile()
-    starter.startZope()
-    starter.registerSignals()
-    # emit a "ready" message in order to prevent the kinds of emails
-    # to the Zope maillist in which people claim that Zope has "frozen"
-    # after it has emitted ZServer messages.
-    logger.info('Ready to handle requests')
-    starter.setupFinalLogging()
+    starter = get_starter()
+    starter.setConfiguration(cfg)
+    starter.prepare()
 
     started = True
-
-    # the mainloop.
     try:
-        import ZServer
-        import Lifetime
-        Lifetime.loop()
-        sys.exit(ZServer.exit_code)
+        starter.run()
     finally:
-        starter.unlinkLockFile()
-        starter.unlinkPidFile()
         started = False
 
+
 class ZopeStarter:
     """This is a class which starts a Zope server.
 
     Making it a class makes it easier to test.
     """
-    def __init__(self, cfg):
-        self.cfg = cfg
+    def __init__(self):
         self.event_logger = logging.getLogger()
-        self.debug_handler = None
+        # set up our initial logging environment (log everything to stderr
+        # if we're not in debug mode).
+        formatter = logging.Formatter(
+            "%(asctime)s %(levelname)s %(name)s %(message)s",
+            "%Y-%m-%d %H:%M:%S")
+        self.debug_handler = loghandler.StreamHandler()
+        self.debug_handler.setFormatter(formatter)
+        self.debug_handler.setLevel(logging.WARN)
+
+        self.startup_handler = loghandler.StartupHandler()
+
+        self.event_logger.addHandler(self.debug_handler)
+        self.event_logger.addHandler(self.startup_handler)
+
+    def setConfiguration(self, cfg):
+        self.cfg = cfg
+
+    def prepare(self):
+        # we log events to the root logger, which is backed by a
+        # "StartupHandler" log handler.  The "StartupHandler" outputs to
+        # stderr but also buffers log messages.  When the "real" loggers
+        # are set up, we flush accumulated messages in StartupHandler's
+        # buffers to the real logger.
+        self.setupInitialLogging()
+        self.setupLocale()
+        self.setupSecurityOptions()
+        # Start ZServer servers before we drop privileges so we can bind to
+        # "low" ports:
+        self.setupZServerThreads()
+        self.setupServers()
+        # drop privileges after setting up servers
+        self.dropPrivileges()
+        self.makeLockFile()
+        self.makePidFile()
+        self.startZope()
+        self.registerSignals()
+        # emit a "ready" message in order to prevent the kinds of emails
+        # to the Zope maillist in which people claim that Zope has "frozen"
+        # after it has emitted ZServer messages.
+        logger.info('Ready to handle requests')
+        self.setupFinalLogging()
+
+    def run(self):
+        # the mainloop.
+        try:
+            import ZServer
+            import Lifetime
+            Lifetime.loop()
+            sys.exit(ZServer.exit_code)
+        finally:
+            self.shutdown()
+
+    def shutdown(self):
+        self.unlinkLockFile()
+        self.unlinkPidFile()
 
     # XXX does anyone actually use these three?
 
@@ -171,6 +203,8 @@ class ZopeStarter:
         return level
 
     def setupConfiguredLoggers(self):
+        # Must happen after ZopeStarter.setupInitialLogging()
+        self.event_logger.removeHandler(self.startup_handler)
         if self.cfg.zserver_read_only_mode:
             # no log files written in read only mode
             return
@@ -182,19 +216,20 @@ class ZopeStarter:
         if self.cfg.trace is not None:
             self.cfg.trace()
 
-    def setupDebugLogging(self):
-        from ZConfig.components.logger import loghandler
+        # flush buffered startup messages to event logger
+        if self.cfg.debug_mode:
+            self.event_logger.removeHandler(self.debug_handler)
+            self.startup_handler.flushBufferTo(self.event_logger)
+            self.event_logger.addHandler(self.debug_handler)
+        else:
+            self.startup_handler.flushBufferTo(self.event_logger)
+
+    def setupInitialLogging(self):
         if self.cfg.debug_mode:
-            formatter = logging.Formatter(
-                "%(asctime)s %(levelname)s %(name)s %(message)s",
-                "%Y-%m-%d %H:%M:%S")
-            self.debug_handler = loghandler.StreamHandler()
-            self.debug_handler.setFormatter(formatter)
             self.debug_handler.setLevel(self.getLoggingLevel())
-            root = self.event_logger
-            root.addHandler(self.debug_handler)
-            root.error("the lowest handler level is: %r",
-                       self.debug_handler.level)
+        else:
+            self.event_logger.removeHandler(self.debug_handler)
+            self.debug_handler = None
 
     def startZope(self):
         # Import Zope
@@ -260,7 +295,7 @@ class WindowsZopeStarter(ZopeStarter):
         pass
 
     def setupInitialLogging(self):
-        self.setupDebugLogging()
+        ZopeStarter.setupInitialLogging(self)
         self.setupConfiguredLoggers()
 
     def setupFinalLogging(self):
@@ -276,36 +311,17 @@ class UnixZopeStarter(ZopeStarter):
                                      self.cfg.trace])
 
     def setupInitialLogging(self):
-        self.setupDebugLogging()
-        # set up our initial logging environment (log everything to stderr
-        # if we're not in debug mode).
-        from ZConfig.components.logger.loghandler import StartupHandler
-
+        ZopeStarter.setupInitialLogging(self)
         level = self.getLoggingLevel()
 
-        formatter = logging.Formatter(
-            fmt='------\n%(asctime)s %(levelname)s %(name)s %(message)s',
-            datefmt='%Y-%m-%dT%H:%M:%S')
-        self.startup_handler = StartupHandler()
         self.startup_handler.setLevel(level)
-        self.startup_handler.setFormatter(formatter)
 
-        # set up our event logger temporarily with a startup handler only
-        self.event_logger.addHandler(self.startup_handler)
         # set the initial logging level (this will be changed by the
         # zconfig settings later)
         self.event_logger.setLevel(level)
 
     def setupFinalLogging(self):
-        if self.startup_handler in self.event_logger.handlers:
-            self.event_logger.removeHandler(self.startup_handler)
         self.setupConfiguredLoggers()
-        # flush buffered startup messages to event logger
-        if self.debug_handler is not None:
-            self.event_logger.removeHandler(self.debug_handler)
-        self.startup_handler.flushBufferTo(self.event_logger)
-        if self.debug_handler is not None:
-            self.event_logger.addHandler(self.debug_handler)
 
 
 def check_python_version():

lib/python/Zope/Startup/run.py

@@ -14,18 +14,22 @@
 
 def run():
     """ Start a Zope instance """
-    from Zope.Startup import start_zope
+    import Zope.Startup
+    starter = Zope.Startup.get_starter()
     opts = _setconfig()
-    start_zope(opts.configroot)
+    starter.setConfiguration(opts.configroot)
+    starter.prepare()
+    starter.run()
 
 def configure(configfile):
     """ Provide an API which allows scripts like zopectl to configure
     Zope before attempting to do 'app = Zope.app(). Should be used as
     follows:  from Zope.Startup.run import configure;
     configure('/path/to/configfile'); import Zope; app = Zope.app() """
-    from Zope.Startup import ZopeStarter
+    import Zope.Startup
+    starter = Zope.Startup.get_starter()
     opts = _setconfig(configfile)
-    starter = ZopeStarter(opts.configroot)
+    starter.setConfiguration(opts.configroot)
     starter.setupSecurityOptions()
     starter.dropPrivileges()
 

lib/python/Zope/Startup/tests/testStarter.py

@@ -14,6 +14,7 @@
 """ Tests of the ZopeStarter class """
 
 import cStringIO
+import errno
 import logging
 import os
 import sys
@@ -22,10 +23,9 @@ import unittest
 
 import ZConfig
 from ZConfig.components.logger.tests import test_logger
+from ZConfig.components.logger.loghandler import NullHandler
 
 import Zope.Startup
-from Zope.Startup import handlers
-from Zope.Startup import ZopeStarter, UnixZopeStarter
 
 from App.config import getConfiguration, setConfiguration
 
@@ -33,7 +33,7 @@ TEMPNAME = tempfile.mktemp()
 TEMPPRODUCTS = os.path.join(TEMPNAME, "Products")
 
 def getSchema():
-    startup = os.path.dirname(os.path.realpath(Zope.Startup.__file__))
+    startup = os.path.dirname(Zope.Startup.__file__)
     schemafile = os.path.join(startup, 'zopeschema.xml')
     return ZConfig.loadSchema(schemafile)
 
@@ -50,8 +50,11 @@ for name in (None, 'trace', 'access'):
 
 class ZopeStarterTestCase(test_logger.LoggingTestBase):
 
+    schema = None
+
     def setUp(self):
-        self.schema = getSchema()
+        if self.schema is None:
+            ZopeStarterTestCase.schema = getSchema()
         test_logger.LoggingTestBase.setUp(self)
 
     def tearDown(self):
@@ -66,6 +69,11 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
             logger = logging.getLogger(name)
             logger.__dict__.update(logger_states[name])
 
+    def get_starter(self, conf):
+        starter = Zope.Startup.get_starter()
+        starter.setConfiguration(conf)
+        return starter
+
     def load_config_text(self, text):
         # We have to create a directory of our own since the existence
         # of the directory is checked.  This handles this in a
@@ -98,7 +106,7 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
                     'The specified locale "en_GB" is not supported'):
                     return
                 raise
-            starter = ZopeStarter(conf)
+            starter = self.get_starter(conf)
             starter.setupLocale()
             self.assertEqual(locale.getlocale(), ['en_GB', 'ISO8859-1'])
         finally:
@@ -122,12 +130,12 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
               level blather
              </logfile>
            </eventlog>""")
-        starter = UnixZopeStarter(conf)
+        starter = self.get_starter(conf)
         starter.setupInitialLogging()
 
         # startup handler should take on the level of the event log handler
         # with the lowest level
-        logger = logging.getLogger()
+        logger = starter.event_logger
         self.assertEqual(starter.startup_handler.level, 15) # 15 is BLATHER
         self.assert_(starter.startup_handler in logger.handlers)
         self.assertEqual(logger.level, 15)
@@ -147,7 +155,7 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
               level info
              </logfile>
            </eventlog>""")
-        starter = UnixZopeStarter(conf)
+        starter = self.get_starter(conf)
         starter.setupInitialLogging()
         # XXX need to check that log messages get written to
         # sys.stderr, not that the stream identity for the startup
@@ -158,7 +166,7 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
         conf = self.load_config_text("""
             instancehome <<INSTANCE_HOME>>
            zserver-threads 10""")
-        starter = ZopeStarter(conf)
+        starter = self.get_starter(conf)
         starter.setupZServerThreads()
         from ZServer.PubCore import _n
         self.assertEqual(_n, 10)
@@ -172,7 +180,7 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
             <ftp-server>
                address 18093
             </ftp-server>""")
-        starter = ZopeStarter(conf)
+        starter = self.get_starter(conf)
         # do the job the 'handler' would have done (call prepare)
         for server in conf.servers:
             server.prepare('', None, 'Zope', {}, None)
@@ -202,7 +210,7 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
         ##        # conflict
         ##        address 18092
         ##     </ftp-server>""")
-        ## starter = ZopeStarter(conf)
+        ## starter = self.get_starter(conf)
         ## # do the job the 'handler' would have done (call prepare)
         ## for server in conf.servers:
         ##     server.prepare('', None, 'Zope', {}, None)
@@ -219,26 +227,32 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
         _old_getuid = os.getuid
         def _return0():
             return 0
+        def make_starter(conf):
+            # remove the debug handler, since we don't want junk on
+            # stderr for the tests
+            starter = self.get_starter(conf)
+            starter.event_logger.removeHandler(starter.debug_handler)
+            return starter
         try:
             os.getuid = _return0
             # no effective user
             conf = self.load_config_text("""
                 instancehome <<INSTANCE_HOME>>""")
-            starter = ZopeStarter(conf)
+            starter = make_starter(conf)
             self.assertRaises(ZConfig.ConfigurationError,
                               starter.dropPrivileges)
             # cant find user in passwd database
             conf = self.load_config_text("""
                 instancehome <<INSTANCE_HOME>>
                 effective-user n0sucHuS3r""")
-            starter = ZopeStarter(conf)
+            starter = make_starter(conf)
             self.assertRaises(ZConfig.ConfigurationError,
                               starter.dropPrivileges)
             # can't specify '0' as effective user
             conf = self.load_config_text("""
                 instancehome <<INSTANCE_HOME>>
                 effective-user 0""")
-            starter = ZopeStarter(conf)
+            starter = make_starter(conf)
             self.assertRaises(ZConfig.ConfigurationError,
                               starter.dropPrivileges)
             # setuid to test runner's uid XXX will this work cross-platform?
@@ -246,7 +260,7 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
             conf = self.load_config_text("""
                 instancehome <<INSTANCE_HOME>>
                 effective-user %s""" % runnerid)
-            starter = ZopeStarter(conf)
+            starter = make_starter(conf)
             finished = starter.dropPrivileges()
             self.failUnless(finished)
         finally:
@@ -279,7 +293,7 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
            </logger>
            """)
         try:
-            starter = UnixZopeStarter(conf)
+            starter = self.get_starter(conf)
             starter.setupInitialLogging()
             starter.info('hello')
             starter.setupFinalLogging()
@@ -313,7 +327,7 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
         f.write(' hello')
         f.close()
         try:
-            starter = ZopeStarter(conf)
+            starter = self.get_starter(conf)
             starter.makeLockFile()
             f = open(name, 'rb')
             f.seek(1)   # skip over the locked byte
@@ -335,7 +349,7 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
         f.write('hello')
         f.close()
         try:
-            starter = ZopeStarter(conf)
+            starter = self.get_starter(conf)
             starter.makePidFile()
             self.failIf(open(name).read().find('hello') > -1)
         finally:
@@ -348,9 +362,11 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
             os.mkdir(TEMPNAME)
             os.mkdir(TEMPPRODUCTS)
         except OSError, why:
-            if why == 17:
+            if why == errno.EEXIST:
                 # already exists
                 pass
+        old_argv = sys.argv
+        sys.argv = [sys.argv[0]]
         try:
             fname = os.path.join(TEMPNAME, 'zope.conf')
             from Zope import configure
@@ -362,6 +378,7 @@ class ZopeStarterTestCase(test_logger.LoggingTestBase):
             new_config = getConfiguration()
             self.failUnlessEqual(new_config.zserver_threads, 100)
         finally:
+            sys.argv = old_argv
             try:
                 os.unlink(fname)
             except: