r47084 - Merge tlogger-twistd-8235: Port twisted.application.app (and twistd) to use the new logging system.

hawkowl-TA+aISz0psMTMxyoc4vAAJOcrHinNvQL0E9HWUfgJXw@public.gmane.org Sat, 26 Mar 2016 04:47:01 -0600 (MDT)
Newsgroups gmane.comp.python.twisted.commits
Message-ID <[email protected]>
Author: hawkowl
Date: Sat Mar 26 04:46:49 2016
New Revision: 47084

Added:
   trunk/twisted/topfiles/8235.feature
   trunk/twisted/topfiles/8235.removal
Modified:
   trunk/twisted/application/app.py
   trunk/twisted/internet/protocol.py
   trunk/twisted/logger/__init__.py
   trunk/twisted/logger/_logger.py
   trunk/twisted/scripts/_twistd_unix.py
   trunk/twisted/test/test_twistd.py

Log:
Merge tlogger-twistd-8235: Port twisted.application.app (and twistd) to use the new logging system.

Author: hawkowl
Reviewer: wsanchez
Fixes: #8235

Modified: trunk/twisted/application/app.py
==============================================================================
--- trunk/twisted/application/app.py	(original)
+++ trunk/twisted/application/app.py	Sat Mar 26 04:46:49 2016
@@ -10,15 +10,15 @@
 import getpass
 import traceback
 import signal
+import warnings
 
 from operator import attrgetter
 
-from twisted import copyright, plugin
+from twisted import copyright, plugin, logger
 from twisted.application import service, reactors
 from twisted.internet import defer
 from twisted.persisted import sob
 from twisted.python import runtime, log, usage, failure, util, logfile
-from twisted.python.log import ILogObserver
 from twisted.python.reflect import qual, namedAny
 
 # Expose the new implementation of installReactor at the old location.
@@ -141,7 +141,8 @@
 class AppLogger(object):
     """
     An L{AppLogger} attaches the configured log observer specified on the
-    commandline to a L{ServerOptions} object or the custom L{ILogObserver}.
+    commandline to a L{ServerOptions} object, a custom L{logger.ILogObserver},
+    or a legacy custom {log.ILogObserver}.
 
     @ivar _logfilename: The name of the file to which to log, if other than the
         default.
@@ -151,7 +152,8 @@
         None.
 
     @ivar _observer: log observer added at C{start} and removed at C{stop}.
-    @type _observer: C{callable}
+    @type _observer: a callable that implements L{logger.ILogObserver} or
+        L{log.ILogObserver}.
     """
     _observer = None
 
@@ -168,24 +170,46 @@
         Initialize the global logging system for the given application.
 
         If a custom logger was specified on the command line it will be used.
-        If not, and an L{ILogObserver} component has been set on
-        C{application}, then it will be used as the log observer.  Otherwise a
-        log observer will be created based on the command-line options for
-        built-in loggers (e.g.  C{--logfile}).
+        If not, and an L{logger.ILogObserver} or legacy L{log.ILogObserver}
+        component has been set on C{application}, then it will be used as the
+        log observer. Otherwise a log observer will be created based on the
+        command line options for built-in loggers (e.g. C{--logfile}).
 
         @param application: The application on which to check for an
-            L{ILogObserver}.
+            L{logger.ILogObserver} or legacy L{log.ILogObserver}.
         @type application: L{twisted.python.components.Componentized}
         """
         if self._observerFactory is not None:
             observer = self._observerFactory()
         else:
-            observer = application.getComponent(ILogObserver, None)
+            observer = application.getComponent(logger.ILogObserver, None)
+            if observer is None:
+                # If there's no new ILogObserver, try the legacy one
+                observer = application.getComponent(log.ILogObserver, None)
 
         if observer is None:
             observer = self._getLogObserver()
         self._observer = observer
-        log.startLoggingWithObserver(self._observer)
+
+        if logger.ILogObserver.providedBy(self._observer):
+            observers = [self._observer]
+        elif log.ILogObserver.providedBy(self._observer):
+            observers = [logger.LegacyLogObserverWrapper(self._observer)]
+        else:
+            warnings.warn(
+                ("Passing a logger factory which makes log observers which do "
+                 "not implement twisted.logger.ILogObserver or "
+                 "twisted.python.log.ILogObserver to "
+                 "twisted.application.app.AppLogger was deprecated in "
+                 "Twisted 16.2. Please use a factory that produces "
+                 "twisted.logger.ILogObserver (or the legacy "
+                 "twisted.python.log.ILogObserver) implementing objects "
+                 "instead."),
+                DeprecationWarning,
+                stacklevel=2)
+            observers = [logger.LegacyLogObserverWrapper(self._observer)]
+
+        logger.globalLogBeginner.beginLoggingTo(observers)
         self._initialLog()
 
 
@@ -194,10 +218,12 @@
         Print twistd start log message.
         """
         from twisted.internet import reactor
-        log.msg("twistd %s (%s %s) starting up." % (
-            copyright.version, sys.executable, runtime.shortPythonVersion())
-        )
-        log.msg('reactor class: %s.' % (qual(reactor.__class__),))
+        logger._loggerFor(self).info(
+            "twistd {version} ({exe} {pyVersion}) starting up.",
+            version=copyright.version, exe=sys.executable,
+            pyVersion=runtime.shortPythonVersion())
+        logger._loggerFor(self).info('reactor class: {reactor}.',
+                                     reactor=qual(reactor.__class__))
 
 
     def _getLogObserver(self):
@@ -209,16 +235,16 @@
             logFile = sys.stdout
         else:
             logFile = logfile.LogFile.fromFullPath(self._logfilename)
-        return log.FileLogObserver(logFile).emit
+        return logger.textFileLogObserver(logFile)
 
 
     def stop(self):
         """
         Remove all log observers previously set up by L{AppLogger.start}.
         """
-        log.msg("Server Shut Down.")
+        logger._loggerFor(self).info("Server Shut Down.")
         if self._observer is not None:
-            log.removeObserver(self._observer)
+            logger.globalLogPublisher.removeObserver(self._observer)
             self._observer = None
 
 

Modified: trunk/twisted/internet/protocol.py
==============================================================================
--- trunk/twisted/internet/protocol.py	(original)
+++ trunk/twisted/internet/protocol.py	Sat Mar 26 04:46:49 2016
@@ -16,11 +16,7 @@
 
 from twisted.python import log, failure, components
 from twisted.internet import interfaces, error, defer
-from twisted.logger import Logger
-
-_log = Logger()
-_logFor = lambda _:_log.__get__(_, _.__class__)
-
+from twisted.logger import _loggerFor
 
 
 @implementer(interfaces.IProtocolFactory, interfaces.ILoggingContext)
@@ -73,8 +69,8 @@
         """
         if not self.numPorts:
             if self.noisy:
-                _logFor(self).info("Starting factory {factory!r}",
-                                   factory=self)
+                _loggerFor(self).info("Starting factory {factory!r}",
+                                      factory=self)
             self.startFactory()
         self.numPorts = self.numPorts + 1
 
@@ -90,8 +86,8 @@
         self.numPorts = self.numPorts - 1
         if not self.numPorts:
             if self.noisy:
-                _logFor(self).info("Stopping factory {factory!r}",
-                                   factory=self)
+                _loggerFor(self).info("Stopping factory {factory!r}",
+                                      factory=self)
             self.stopFactory()
 
     def startFactory(self):

Modified: trunk/twisted/logger/__init__.py
==============================================================================
--- trunk/twisted/logger/__init__.py	(original)
+++ trunk/twisted/logger/__init__.py	Sat Mar 26 04:46:49 2016
@@ -54,7 +54,7 @@
     "extractField",
 
     # From ._logger
-    "Logger",
+    "Logger", "_loggerFor",
 
     # From ._observer
     "ILogObserver", "LogPublisher",
@@ -94,7 +94,7 @@
     formatEvent, formatEventAsClassicLogText, formatTime, timeFormatRFC3339,
 )
 
-from ._logger import Logger
+from ._logger import Logger, _loggerFor
 
 from ._observer import ILogObserver, LogPublisher
 

Modified: trunk/twisted/logger/_logger.py
==============================================================================
--- trunk/twisted/logger/_logger.py	(original)
+++ trunk/twisted/logger/_logger.py	Sat Mar 26 04:46:49 2016
@@ -256,3 +256,8 @@
             later execution.
         """
         self.emit(LogLevel.critical, format, **kwargs)
+
+
+
+_log = Logger()
+_loggerFor = lambda obj:_log.__get__(obj, obj.__class__)

Modified: trunk/twisted/scripts/_twistd_unix.py
==============================================================================
--- trunk/twisted/scripts/_twistd_unix.py	(original)
+++ trunk/twisted/scripts/_twistd_unix.py	Sat Mar 26 04:46:49 2016
@@ -14,7 +14,7 @@
     switchUID, uidFromString, gidFromString, untilConcludes)
 from twisted.application import app, service
 from twisted.internet.interfaces import IReactorDaemonize
-from twisted import copyright
+from twisted import copyright, logger
 from twisted.python.runtime import platformType
 
 
@@ -167,7 +167,7 @@
                         from twisted.internet import reactor
                         reactor.callFromThread(logFile.rotate)
                     signal.signal(signal.SIGUSR1, rotateLog)
-        return log.FileLogObserver(logFile).emit
+        return logger.textFileLogObserver(logFile)
 
 
 

Modified: trunk/twisted/test/test_twistd.py
==============================================================================
--- trunk/twisted/test/test_twistd.py	(original)
+++ trunk/twisted/test/test_twistd.py	Sat Mar 26 04:46:49 2016
@@ -30,19 +30,21 @@
 from twisted.trial import unittest
 from twisted.test.test_process import MockOS
 
-from twisted import plugin
+from twisted import plugin, logger
 from twisted.application.service import IServiceMaker
 from twisted.application import service, app, reactors
 from twisted.scripts import twistd
-from twisted.python import log
 from twisted.python.compat import NativeStringIO
 from twisted.python.usage import UsageError
-from twisted.python.log import ILogObserver
+from twisted.python.log import (ILogObserver as LegacyILogObserver,
+                                textFromEventDict)
 from twisted.python.components import Componentized
 from twisted.internet.defer import Deferred
 from twisted.internet.interfaces import IReactorDaemonize
 from twisted.internet.test.modulehelpers import AlternateReactor
 from twisted.python.fakepwd import UserDatabase
+from twisted.logger import globalLogBeginner, globalLogPublisher, ILogObserver
+
 try:
     from twisted.scripts import _twistd_unix
 except ImportError:
@@ -1091,10 +1093,10 @@
 
 
 
-def _patchFileLogObserver(patch):
+def _patchTextFileLogObserver(patch):
     """
-    Patch L{log.FileLogObserver} to record every call and keep a reference to
-    the passed log file for tests.
+    Patch L{logger.textFileLogObserver} to record every call and keep a
+    reference to the passed log file for tests.
 
     @param patch: a callback for patching (usually L{unittest.TestCase.patch}).
 
@@ -1102,13 +1104,13 @@
     @rtype: C{list}
     """
     logFiles = []
-    oldFileLobObserver = log.FileLogObserver
+    oldFileLogObserver = logger.textFileLogObserver
 
-    def FileLogObserver(logFile):
+    def observer(logFile, *args, **kwargs):
         logFiles.append(logFile)
-        return oldFileLobObserver(logFile)
+        return oldFileLogObserver(logFile, *args, **kwargs)
 
-    patch(log, 'FileLogObserver', FileLogObserver)
+    patch(logger, 'textFileLogObserver', observer)
     return logFiles
 
 
@@ -1142,16 +1144,17 @@
 
     def setUp(self):
         """
-        Override L{log.addObserver} so that we can trace the observers
-        installed in C{self.observers}.
+        Override L{globaLogBeginner.beginLoggingTo} so that we can trace the
+        observers installed in C{self.observers}.
         """
         self.observers = []
 
-        def startLoggingWithObserver(observer):
-            self.observers.append(observer)
-            log.addObserver(observer)
+        def beginLoggingTo(observers):
+            for observer in observers:
+                self.observers.append(observer)
+                globalLogPublisher.addObserver(observer)
 
-        self.patch(log, 'startLoggingWithObserver', startLoggingWithObserver)
+        self.patch(globalLogBeginner, 'beginLoggingTo', beginLoggingTo)
 
 
     def tearDown(self):
@@ -1159,30 +1162,45 @@
         Remove all installed observers.
         """
         for observer in self.observers:
-            log.removeObserver(observer)
+            globalLogPublisher.removeObserver(observer)
+
+
+    def _makeObserver(self):
+        """
+        Make a new observer which captures all logs sent to it.
+
+        @return: An observer that stores all logs sent to it.
+        @rtype: Callable that implements L{ILogObserver}.
+        """
+        @implementer(ILogObserver)
+        class TestObserver(object):
+            _logs = []
 
+            def __call__(self, event):
+                self._logs.append(event)
 
-    def _checkObserver(self, logs):
+        return TestObserver()
+
+
+    def _checkObserver(self, observer):
         """
-        Ensure that initial C{twistd} logs are written to the given list.
+        Ensure that initial C{twistd} logs are written to logs.
 
-        @type logs: C{list}
-        @param logs: The list whose C{append} method was specified as the
-            initial log observer.
+        @param observer: The observer made by L{self._makeObserver).
         """
-        self.assertEqual(self.observers, [logs.append])
-        self.assertIn("starting up", logs[0]["message"][0])
-        self.assertIn("reactor class", logs[1]["message"][0])
+        self.assertEqual(self.observers, [observer])
+        self.assertIn("starting up", observer._logs[0]["log_format"])
+        self.assertIn("reactor class", observer._logs[1]["log_format"])
 
 
     def test_start(self):
         """
-        L{app.AppLogger.start} calls L{log.addObserver}, and then writes some
-        messages about twistd and the reactor.
+        L{app.AppLogger.start} calls L{globalLogBeginner.addObserver}, and then
+        writes some messages about twistd and the reactor.
         """
         logger = app.AppLogger({})
-        observer = []
-        logger._getLogObserver = lambda: observer.append
+        observer = self._makeObserver()
+        logger._getLogObserver = lambda: observer
         logger.start(Componentized())
         self._checkObserver(observer)
 
@@ -1194,11 +1212,11 @@
         new one.
         """
         application = Componentized()
-        logs = []
-        application.setComponent(ILogObserver, logs.append)
+        observer = self._makeObserver()
+        application.setComponent(ILogObserver, observer)
         logger = app.AppLogger({})
         logger.start(application)
-        self._checkObserver(logs)
+        self._checkObserver(observer)
 
 
     def _setupConfiguredLogger(self, application, extraLogArgs={},
@@ -1217,12 +1235,12 @@
         @rtype: C{list}
         @return: The logs accumulated by the log observer.
         """
-        logs = []
-        logArgs = {"logger": lambda: logs.append}
+        observer = self._makeObserver()
+        logArgs = {"logger": lambda: observer}
         logArgs.update(extraLogArgs)
         logger = appLogger(logArgs)
         logger.start(application)
-        return logs
+        return observer
 
 
     def test_startUsesConfiguredLogObserver(self):
@@ -1238,16 +1256,46 @@
 
     def test_configuredLogObserverBeatsComponent(self):
         """
-        C{--logger} takes precedence over a ILogObserver component set on
+        C{--logger} takes precedence over a L{ILogObserver} component set on
         Application.
         """
+        observer = self._makeObserver()
+        application = Componentized()
+        application.setComponent(ILogObserver, observer)
+        self._checkObserver(self._setupConfiguredLogger(application))
+        self.assertEqual(observer._logs, [])
+
+
+    def test_configuredLogObserverBeatsLegacyComponent(self):
+        """
+        C{--logger} takes precedence over a L{LegacyILogObserver} component
+        set on Application.
+        """
         nonlogs = []
         application = Componentized()
-        application.setComponent(ILogObserver, nonlogs.append)
+        application.setComponent(LegacyILogObserver, nonlogs.append)
         self._checkObserver(self._setupConfiguredLogger(application))
         self.assertEqual(nonlogs, [])
 
 
+    def test_loggerComponentBeatsLegacyLoggerComponent(self):
+        """
+        A L{ILogObserver} takes precedence over a L{LegacyILogObserver}
+        component set on Application.
+        """
+        nonlogs = []
+        observer = self._makeObserver()
+        application = Componentized()
+        application.setComponent(ILogObserver, observer)
+        application.setComponent(LegacyILogObserver, nonlogs.append)
+
+        logger = app.AppLogger({})
+        logger.start(application)
+
+        self._checkObserver(observer)
+        self.assertEqual(nonlogs, [])
+
+
     def test_configuredLogObserverBeatsSyslog(self):
         """
         C{--logger} takes precedence over a C{--syslog} command line
@@ -1284,7 +1332,7 @@
         returns a log observer pointing at C{sys.stdout}.
         """
         logger = app.AppLogger({"logfile": "-"})
-        logFiles = _patchFileLogObserver(self.patch)
+        logFiles = _patchTextFileLogObserver(self.patch)
 
         logger._getLogObserver()
 
@@ -1303,7 +1351,7 @@
         When passing the C{logfile} option, L{app.AppLogger._getLogObserver}
         returns a log observer pointing at the specified path.
         """
-        logFiles = _patchFileLogObserver(self.patch)
+        logFiles = _patchTextFileLogObserver(self.patch)
         filename = self.mktemp()
         logger = app.AppLogger({"logfile": filename})
 
@@ -1326,7 +1374,7 @@
         def remove(observer):
             removed.append(observer)
 
-        self.patch(log, 'removeObserver', remove)
+        self.patch(globalLogPublisher, 'removeObserver', remove)
         logger = app.AppLogger({})
         logger._observer = observer
         logger.stop()
@@ -1336,6 +1384,61 @@
         self.assertIdentical(logger._observer, None)
 
 
+    def test_legacyObservers(self):
+        """
+        L{app.AppLogger} using a legacy logger observer still works, wrapping
+        it in a compat shim.
+        """
+        logs = []
+        logger = app.AppLogger({})
+
+        @implementer(LegacyILogObserver)
+        class LoggerObserver(object):
+            """
+            An observer which implements the legacy L{LegacyILogObserver}.
+            """
+            def __call__(self, x):
+                """
+                Add C{x} to the logs list.
+                """
+                logs.append(x)
+
+        logger._observerFactory = lambda: LoggerObserver()
+        logger.start(Componentized())
+
+        self.assertIn("starting up", textFromEventDict(logs[0]))
+        warnings = self.flushWarnings(
+            [self.test_legacyObservers])
+        self.assertEqual(len(warnings), 0)
+
+
+    def test_unmarkedObserversDeprecated(self):
+        """
+        L{app.AppLogger} using a logger observer which does not implement
+        L{ILogObserver} or L{LegacyILogObserver} will be wrapped in a compat
+        shim and raise a L{DeprecationWarning}.
+        """
+        logs = []
+        logger = app.AppLogger({})
+        logger._getLogObserver = lambda: logs.append
+        logger.start(Componentized())
+
+        self.assertIn("starting up", textFromEventDict(logs[0]))
+
+        warnings = self.flushWarnings(
+            [self.test_unmarkedObserversDeprecated])
+        self.assertEqual(len(warnings), 1)
+        self.assertEqual(warnings[0]["message"],
+                         ("Passing a logger factory which makes log observers "
+                          "which do not implement twisted.logger.ILogObserver "
+                          "or twisted.python.log.ILogObserver to "
+                          "twisted.application.app.AppLogger was deprecated "
+                          "in Twisted 16.2. Please use a factory that "
+                          "produces twisted.logger.ILogObserver (or the "
+                          "legacy twisted.python.log.ILogObserver) "
+                          "implementing objects instead."))
+
+
 
 class UnixAppLoggerTests(unittest.TestCase):
     """
@@ -1367,7 +1470,7 @@
         L{UnixAppLogger._getLogObserver} returns a log observer pointing at
         C{sys.stdout}.
         """
-        logFiles = _patchFileLogObserver(self.patch)
+        logFiles = _patchTextFileLogObserver(self.patch)
 
         logger = UnixAppLogger({"logfile": "-", "nodaemon": True})
         logger._getLogObserver()
@@ -1396,7 +1499,7 @@
         returns a log observer pointing at the specified path, and a signal
         handler rotating the log is installed.
         """
-        logFiles = _patchFileLogObserver(self.patch)
+        logFiles = _patchTextFileLogObserver(self.patch)
         filename = self.mktemp()
         logger = UnixAppLogger({"logfile": filename})
         logger._getLogObserver()
@@ -1441,7 +1544,7 @@
         L{UnixAppLogger._getLogObserver} points at C{twistd.log} in the current
         directory.
         """
-        logFiles = _patchFileLogObserver(self.patch)
+        logFiles = _patchTextFileLogObserver(self.patch)
         logger = UnixAppLogger({"logfile": "", "nodaemon": False})
         logger._getLogObserver()