Merge lp:~julian-edwards/launchpad/buildd-manager-better-logging-bug-530040 into lp:launchpad

[Julian Edwards]

= Summary =
improve the logging for the buildd-manager

== Proposed fix ==
https://bugs.edge.launchpad.net/bugs/530040

The logging for the buildd-manager *sucks*. It logs crap that it shouldn't
and doesn't log important stuff that it should. This branch takes care of
that!

== Pre-implementation notes ==
Chatted briefly with noodles about what to do with the logger name - in the
end a constant in the buildbase interface file appeared to be a reasonable
choice.

== Implementation details ==
Most of this stuff is changing log.debug into log.info and vice versa. I also
added the build.title to the info message when it fetches a build from the
slave, and it also now logs the files it retrieves.

== Tests ==
None exist - I really don't see the point of testing logging anyway.

== Demo and Q/A ==
I've tested this on dogfood already to make sure it logs what I need.

= Launchpad lint =

Checking for conflicts. and issues in doctests and templates.
Running jslint, xmllint, pyflakes, and pylint.
Using normal rules.

Linting changed files:
  lib/lp/buildmaster/model/builder.py
  lib/lp/buildmaster/model/buildbase.py
  lib/lp/buildmaster/master.py
  lib/lp/buildmaster/interfaces/buildbase.py
  lib/lp/buildmaster/manager.py

== Pylint notices ==

lib/lp/buildmaster/interfaces/buildbase.py
    14: [F0401] Unable to import 'lazr.enum' (No module named enum)
    15: [F0401] Unable to import 'lazr.restful.declarations' (No module named
restful)
    16: [F0401] Unable to import 'lazr.restful.fields' (No module named
restful)

[Abel Deuring (adeuring)]

review: Approve (code)

=== modified file 'lib/lp/buildmaster/interfaces/buildbase.py'
--- lib/lp/buildmaster/interfaces/buildbase.py	2010-02-16 03:52:28 +0000
+++ lib/lp/buildmaster/interfaces/buildbase.py	2010-03-08 11:14:30 +0000
@@ -7,7 +7,7 @@
 
 __metaclass__ = type
 
-__all__ = ['IBuildBase']
+__all__ = ['BUILDD_MANAGER_LOG_NAME', 'IBuildBase']
 
 from zope.interface import Attribute, Interface
 from zope.schema import Choice, Datetime, Object, TextLine, Timedelta
@@ -24,6 +24,9 @@
 from canonical.launchpad import _
 
 
+BUILDD_MANAGER_LOG_NAME = "slave-scanner"
+
+
 class IBuildBase(Interface):
     """Common interface shared by farm jobs that build a package."""
 

=== modified file 'lib/lp/buildmaster/manager.py'
--- lib/lp/buildmaster/manager.py	2010-02-02 16:39:10 +0000
+++ lib/lp/buildmaster/manager.py	2010-03-08 11:14:30 +0000
@@ -31,7 +31,7 @@
 from canonical.launchpad.webapp import urlappend
 from canonical.librarian.db import write_transaction
 from canonical.twistedsupport.processmonitor import run_process_with_timeout
-
+from lp.buildmaster.interfaces.buildbase import BUILDD_MANAGER_LOG_NAME
 
 buildd_success_result_map = {
     'ensurepresent': True,
@@ -222,7 +222,7 @@
         Make it less verbose to avoid messing too much with the old code.
         """
         level = logging.INFO
-        logger = logging.getLogger('slave-scanner')
+        logger = logging.getLogger(BUILDD_MANAGER_LOG_NAME)
 
         # Redirect the output to the twisted log module.
         channel = logging.StreamHandler(log.StdioOnnaStick())
@@ -283,7 +283,7 @@
 
             Perform the finishing-cycle tasks mentioned above.
             """
-            self.logger.info('Scanning cycle finished.')
+            self.logger.debug('Scanning cycle finished.')
             # We are only interested in returned objects of type
             # BaseDispatchResults, those are the ones that needs evaluation.
             # None, resulting from successful chains, are discarded.
@@ -304,7 +304,7 @@
             # Return the evaluated events for testing purpose.
             return deferred_results
 
-        self.logger.info('Finishing scanning cycle.')
+        self.logger.debug('Finishing scanning cycle.')
         dl = defer.DeferredList(self._deferreds, consumeErrors=True)
         dl.addBoth(done)
         return dl
@@ -415,7 +415,7 @@
 
         See `RecordingSlave.resumeSlaveHost` for more details.
         """
-        self.logger.info('Resuming slaves: %s' % recording_slaves)
+        self.logger.debug('Resuming slaves: %s' % recording_slaves)
         self.remaining_slaves = recording_slaves
         if len(self.remaining_slaves) == 0:
             self.finishCycle()

=== modified file 'lib/lp/buildmaster/master.py'
--- lib/lp/buildmaster/master.py	2010-01-20 01:23:38 +0000
+++ lib/lp/buildmaster/master.py	2010-03-08 11:14:30 +0000
@@ -138,7 +138,7 @@
         self._tm = tm
         self.librarian = getUtility(ILibrarianClient)
         self._archseries = {}
-        self._logger.info("Buildd Master has been initialised")
+        self._logger.debug("Buildd Master has been initialised")
 
     def commit(self):
         self._tm.commit()

=== modified file 'lib/lp/buildmaster/model/buildbase.py'
--- lib/lp/buildmaster/model/buildbase.py	2010-03-05 23:29:50 +0000
+++ lib/lp/buildmaster/model/buildbase.py	2010-03-08 11:14:30 +0000
@@ -29,6 +29,7 @@
 from canonical.launchpad.helpers import filenameToContentType
 from canonical.launchpad.interfaces.librarian import ILibraryFileAliasSet
 from canonical.librarian.utils import copy_and_close
+from lp.buildmaster.interfaces.buildbase import BUILDD_MANAGER_LOG_NAME
 from lp.registry.interfaces.pocket import pocketsuffix
 from lp.soyuz.interfaces.build import BuildStatus
 from lp.soyuz.model.buildqueue import BuildQueue
@@ -129,7 +130,7 @@
 
     def handleStatus(self, status, librarian, slave_status):
         """See `IBuildBase`."""
-        logger = logging.getLogger()
+        logger = logging.getLogger(BUILDD_MANAGER_LOG_NAME)
 
         method = getattr(self, '_handleStatus_' + status, None)
 
@@ -151,7 +152,8 @@
         buildid = slave_status['build_id']
         filemap = slave_status['filemap']
 
-        logger.debug("Processing successful build %s" % buildid)
+        logger.info("Processing successful build %s from builder %s" % (
+            buildid, self.buildqueue_record.builder.name))
         # Explode before collect a binary that is denied in this
         # distroseries/pocket
         if not self.archive.allowUpdatesToReleasePocket():
@@ -180,6 +182,7 @@
 
         slave = removeSecurityProxy(self.buildqueue_record.builder.slave)
         for filename in filemap:
+            logger.info("Grabbing file: %s" % filename)
             slave_file = slave.getFile(filemap[filename])
             out_file_name = os.path.join(upload_path, filename)
             out_file = open(out_file_name, "wb")
@@ -190,8 +193,8 @@
             upload_leaf, uploader_logfilename)
         logger.debug("Saving uploader log at '%s'" % uploader_logfilename)
 
-        logger.debug("Invoking uploader on %s" % root)
-        logger.debug("%s" % uploader_command)
+        logger.info("Invoking uploader on %s" % root)
+        logger.info("%s" % uploader_command)
 
         uploader_process = subprocess.Popen(
             uploader_command, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
@@ -204,11 +207,11 @@
         # when it failed HARD (there is a huge effort in process-upload
         # to not return error, it only happen when the code is broken).
         uploader_result_code = uploader_process.returncode
-        logger.debug("Uploader returned %d" % uploader_result_code)
+        logger.info("Uploader returned %d" % uploader_result_code)
 
         # Quick and dirty hack to carry on on process-upload failures
         if os.path.exists(upload_dir):
-            logger.debug("The upload directory did not get moved.")
+            logger.warning("The upload directory did not get moved.")
             failed_dir = os.path.join(root, "failed-to-move")
             if not os.path.exists(failed_dir):
                 os.mkdir(failed_dir)
@@ -261,7 +264,7 @@
         # binary upload when it was the case.
         if (self.buildstate != BuildStatus.FULLYBUILT or
             not self.verifySuccessfulUpload()):
-            logger.debug("Build %s upload failed." % self.id)
+            logger.warning("Build %s upload failed." % self.id)
             self.buildstate = BuildStatus.FAILEDTOUPLOAD
             uploader_log_content = self.getUploadLogContent(root,
                 upload_leaf)
@@ -271,7 +274,7 @@
             # Notify the build failure.
             self.notify(extra_info=uploader_log_content)
         else:
-            logger.debug(
+            logger.info(
                 "Gathered %s %d completely" % (
                 self.__class__.__name__, self.id))
 

=== modified file 'lib/lp/buildmaster/model/builder.py'
--- lib/lp/buildmaster/model/builder.py	2010-01-22 04:01:17 +0000
+++ lib/lp/buildmaster/model/builder.py	2010-03-08 11:14:30 +0000
@@ -636,17 +636,17 @@
 
     def pollBuilders(self, logger, txn):
         """See IBuilderSet."""
-        logger.info("Slave Scan Process Initiated.")
+        logger.debug("Slave Scan Process Initiated.")
 
         buildMaster = BuilddMaster(logger, txn)
 
-        logger.info("Setting Builders.")
+        logger.debug("Setting Builders.")
         # Put every distroarchseries we can find into the build master.
         for archseries in getUtility(IDistroArchSeriesSet):
             buildMaster.addDistroArchSeries(archseries)
             buildMaster.setupBuilders(archseries)
 
-        logger.info("Scanning Builders.")
+        logger.debug("Scanning Builders.")
         # Scan all the pending builds, update logtails and retrieve
         # builds where they are completed
         buildMaster.scanActiveBuilders()