launchpad-reviewers team mailing list archive
-
launchpad-reviewers team
-
Mailing list archive
-
Message #00303
[Merge] lp:~henninge/launchpad/buildd-manager-logging into lp:launchpad/devel
Henning Eggers has proposed merging lp:~henninge/launchpad/buildd-manager-logging into lp:launchpad/devel.
Requested reviews:
Launchpad code reviewers (launchpad-reviewers)
Related bugs:
#589604 buildd-manager should be more rsync-friendly with log syncing
https://bugs.launchpad.net/bugs/589604
= Bug 589604 =
Twistd does it's own log rotation by default but we don't want that. This branch changes it's behavior for buildd manager to be like e.g. apache's: keep logging until SIGUSR1 is received, then re-open log file.
== Pre-imp ==
I chatted this out with Julian, Tom and even busy Jono and all are very happy about this solution.
== Proposed solution ==
The solution was to add a component to the Buildd-Manager application that implements ILogObserver. Twistd looks for such a component during startup and uses it for logging instead of setting up it's own log observer. This component is implemented as RotatableFileLogObserver and added to the application in the the tac file.
== Implementation details ==
The other addition to the tac file is accessing the command line options to get a hold of the requested log file name.
== Tests ==
bin/test -vvm lp.buildmaster.tests -t TestBuilddManagerScript
I implemented a high-level test for the script that made it easy to check for log files and also to send a signal to the script. I added some code to the test harness in tachandler.py and harness.py to be able to send a signal (not just kill the process) and to pre-create a log file to check (the absence of) log rotation.
The testBuilddManagerLoggingNoRotation test works because the twistd log rotation works synchronously, meaning that it will rotate logs right after performing the write operation that exceeded the limit. For the test a log file is pre-created that is just under the limit so that the next write operation would trigger the log rotation.
== Demo/QA ==
Run "bin/twistd -n -y daemons/buildd-manager.tac -l buildd-manager.log" and tail the log file in the current directory. You will see it grow. Rename the log file and twistd will continue to log to it. Send the process a "SIGUSR1" using "kill" and a new buildd-manager.log will appear and grow while the old one won't be touched any more.
To verify that log rotation does not occur, fill the logfile with arbitrary content up to just under 1000000 bytes and run twistd again. Watch for "buildd-manager.log*" files but you should only see the one which keeps growing beyond 1000000 bytes.
--
https://code.launchpad.net/~henninge/launchpad/buildd-manager-logging/+merge/31057
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~henninge/launchpad/buildd-manager-logging into lp:launchpad/devel.
=== modified file 'daemons/buildd-manager.tac'
--- daemons/buildd-manager.tac 2009-06-24 20:55:31 +0000
+++ daemons/buildd-manager.tac 2010-07-27 15:41:56 +0000
@@ -5,9 +5,11 @@
# Use with "twistd2.4 -y <file.tac>", e.g. "twistd -noy server.tac"
from twisted.application import service
+from twisted.scripts.twistd import ServerOptions
from twisted.web import server
from lp.buildmaster.manager import BuilddManager
+from lp.services.twistedsupport.loggingsupport import RotatableFileLogObserver
from canonical.config import config
from canonical.launchpad.daemons import tachandler
from canonical.launchpad.scripts import execute_zcml_for_scripts
@@ -16,7 +18,12 @@
execute_zcml_for_scripts()
initZopeless(dbuser=config.builddmaster.dbuser)
+options = ServerOptions()
+options.parseOptions()
+
application = service.Application('BuilddManager')
+application.addComponent(
+ RotatableFileLogObserver(options.get('logfile')), ignoreClass=1)
# Service that announces when the daemon is ready.
tachandler.ReadyService().setServiceParent(application)
=== modified file 'lib/canonical/launchpad/daemons/tachandler.py'
--- lib/canonical/launchpad/daemons/tachandler.py 2010-05-27 07:07:24 +0000
+++ lib/canonical/launchpad/daemons/tachandler.py 2010-07-27 15:41:56 +0000
@@ -30,7 +30,6 @@
# This file is used by launchpad-buildd, so it cannot import any
# Launchpad code!
-
def two_stage_kill(pid, poll_interval=0.1, num_polls=50):
"""Kill process 'pid' with SIGTERM. If it doesn't die, SIGKILL it.
@@ -70,23 +69,30 @@
pass
+def get_pid_from_file(pidfile_path):
+ """Retrieve the PID from the given file, if it exists, None otherwise."""
+ if not os.path.exists(pidfile_path):
+ return None
+ # Get the pid.
+ pid = open(pidfile_path, 'r').read().split()[0]
+ try:
+ pid = int(pid)
+ except ValueError:
+ # pidfile contains rubbish
+ return None
+ return pid
+
+
def kill_by_pidfile(pidfile_path, poll_interval=0.1, num_polls=50):
"""Kill a process identified by the pid stored in a file.
The pid file is removed from disk.
"""
- if not os.path.exists(pidfile_path):
- return
try:
- # Get the pid.
- pid = open(pidfile_path, 'r').read().split()[0]
- try:
- pid = int(pid)
- except ValueError:
- # pidfile contains rubbish
+ pid = get_pid_from_file(pidfile_path)
+ if pid is None:
return
-
- two_stage_kill(pid)
+ two_stage_kill(pid, poll_interval, num_polls)
finally:
remove_if_exists(pidfile_path)
@@ -106,6 +112,7 @@
LOG_MAGIC = 'daemon ready!'
+
class TacException(Exception):
"""Error raised by TacTestSetup."""
@@ -115,6 +122,7 @@
You can override setUpRoot to set up a root directory for the daemon.
"""
+
def setUp(self, spew=False, umask=None):
# Before we run, we want to make sure that we have cleaned up any
# previous runs. Although tearDown() should have been called already,
@@ -197,6 +205,13 @@
pidfile = self.pidfile
kill_by_pidfile(pidfile)
+ def sendSignal(self, sig):
+ """Send the given signal to the tac process."""
+ pid = get_pid_from_file(self.pidfile)
+ if pid is None:
+ return
+ os.kill(pid, sig)
+
def setUpRoot(self):
"""Override this.
@@ -225,8 +240,8 @@
class ReadyService(service.Service):
"""Service that logs a 'ready!' message once the reactor has started."""
+
def startService(self):
from twisted.internet import reactor
reactor.addSystemEventTrigger('after', 'startup', log.msg, LOG_MAGIC)
service.Service.startService(self)
-
=== modified file 'lib/lp/buildmaster/tests/harness.py'
--- lib/lp/buildmaster/tests/harness.py 2010-02-19 12:11:56 +0000
+++ lib/lp/buildmaster/tests/harness.py 2010-07-27 15:41:56 +0000
@@ -21,6 +21,12 @@
class BuilddManagerTestSetup(TacTestSetup):
"""Setup BuilddManager for use by functional tests."""
+ logfilecontent = None
+
+ def precreateLogfile(self, content, repeat=1):
+ """Precreate a logfile in the root."""
+ self.logfilecontent = content*repeat
+
def setUpRoot(self):
"""Create `TacTestSetup.root` for storing the log and pid files.
@@ -28,6 +34,8 @@
"""
remove_tree(self.root)
os.makedirs(self.root)
+ if self.logfilecontent is not None:
+ open(self.logfile, "w").write(self.logfilecontent)
@property
def root(self):
=== modified file 'lib/lp/buildmaster/tests/test_manager.py'
--- lib/lp/buildmaster/tests/test_manager.py 2010-07-18 17:43:23 +0000
+++ lib/lp/buildmaster/tests/test_manager.py 2010-07-27 15:41:56 +0000
@@ -5,6 +5,7 @@
import os
import signal
+import time
import transaction
import unittest
@@ -867,11 +868,78 @@
self.assertEqual('does not work!', builder.failnotes)
+def is_file_growing(filename, poll_interval=1, poll_repeat=10):
+ """Poll the file size to see if it grows."""
+ last_size = None
+ for poll in range(poll_repeat+1):
+ try:
+ statinfo = os.stat(filename)
+ if last_size is None:
+ last_size = statinfo.st_size
+ elif statinfo.st_size > last_size:
+ return True
+ else:
+ # The file should not be shrinking.
+ assert statinfo.st_size == last_size
+ except OSError:
+ if poll == poll_repeat:
+ # Propagate only on the last loop, i.e. give up.
+ raise
+ time.sleep(poll_interval)
+ return False
+
+
class TestBuilddManagerScript(unittest.TestCase):
layer = LaunchpadScriptLayer
def testBuilddManagerRuns(self):
- # Ensure `buildd-manager.tac` starts and stops correctly.
+ # The `buildd-manager.tac` starts and stops correctly.
BuilddManagerTestSetup().setUp()
BuilddManagerTestSetup().tearDown()
+<<<<<<< TREE
+=======
+
+ def testBuilddManagerLogging(self):
+ # The twistd process loggs as execpected.
+ test_setup = BuilddManagerTestSetup()
+ logfilepath = test_setup.logfile
+ test_setup.setUp()
+ # The process loggs to its logfile.
+ self.assertTrue(is_file_growing(logfilepath))
+ # After rotating the log, the process keeps using the old file, no
+ # new file is created.
+ rotated_logfilepath = logfilepath+'.1'
+ os.rename(logfilepath, rotated_logfilepath)
+ self.assertTrue(is_file_growing(rotated_logfilepath))
+ self.assertFalse(os.access(logfilepath, os.F_OK))
+ # Upon receiving the USR1 signal, the process will re-open its log
+ # file at the old location.
+ test_setup.sendSignal(signal.SIGUSR1)
+ self.assertTrue(is_file_growing(logfilepath))
+ self.assertTrue(os.access(rotated_logfilepath, os.F_OK))
+ test_setup.tearDown()
+
+ def testBuilddManagerLoggingNoRotation(self):
+ # The twistd process does not perform its own rotation.
+ # By default twistd will rotate log files that grow beyond
+ # 1000000 bytes but this is deactivated for the buildd manager.
+ test_setup = BuilddManagerTestSetup()
+ logfilepath = test_setup.logfile
+ rotated_logfilepath = logfilepath+'.1'
+ # Prefill the log file to just under 1000000 bytes.
+ test_setup.precreateLogfile(
+ "2010-07-27 12:36:54+0200 [-] Starting scanning cycle.\n", 18518)
+ test_setup.setUp()
+ # The process loggs to the logfile.
+ self.assertTrue(is_file_growing(logfilepath))
+ # No rotation occured.
+ self.assertFalse(
+ os.access(rotated_logfilepath, os.F_OK),
+ "Twistd's log file was rotated by twistd.")
+ test_setup.tearDown()
+
+
+def test_suite():
+ return unittest.TestLoader().loadTestsFromName(__name__)
+>>>>>>> MERGE-SOURCE
=== modified file 'lib/lp/services/twistedsupport/loggingsupport.py'
--- lib/lp/services/twistedsupport/loggingsupport.py 2010-05-27 07:02:09 +0000
+++ lib/lp/services/twistedsupport/loggingsupport.py 2010-07-27 15:41:56 +0000
@@ -19,10 +19,13 @@
import glob
import logging
import os
+import signal
+import sys
-from twisted.python import log
+from twisted.python import log, logfile
from twisted.python.logfile import DailyLogFile
from twisted.web import xmlrpc
+from zope.interface import implements
from canonical.launchpad.scripts import logger
from canonical.launchpad.webapp import errorlog
@@ -31,7 +34,6 @@
class OOPSLoggingObserver(log.PythonLoggingObserver):
"""A version of `PythonLoggingObserver` that logs OOPSes for errors."""
-
# XXX: JonathanLange 2008-12-23 bug=314959: As best as I can tell, this
# ought to be a log *handler*, not a feature of the bridge from
# Twisted->Python logging. Ask Michael about this.
@@ -189,3 +191,26 @@
return result
deferred = xmlrpc.Proxy.callRemote(self, method, *args)
return deferred.addBoth(_logResult)
+
+
+class RotatableFileLogObserver(object):
+ """A log observer that uses a log file and reopens it on SIGUSR1."""
+
+ implements(log.ILogObserver)
+
+ def __init__(self, logfilename):
+ if logfilename is None:
+ logFile = sys.stdout
+ else:
+ logFile = logfile.LogFile.fromFullPath(
+ logfilename, rotateLength=None)
+ # Override if signal is set to None or SIG_DFL (0)
+ if not signal.getsignal(signal.SIGUSR1):
+ def signalHandler(signal, frame):
+ from twisted.internet import reactor
+ reactor.callFromThread(logFile.reopen)
+ signal.signal(signal.SIGUSR1, signalHandler)
+ self.observer = log.FileLogObserver(logFile)
+
+ def __call__(self, eventDict):
+ self.observer.emit(eventDict)
