Merge lp:~mabac/svammel/extra-verbose-option into lp:svammel

[Mattias Backman]

Hi,

This branch adds an --extra-verbose option which makes the script print out detailed information about steps taken. This was requested by Matthias Klose to make troubleshooting easier.

Thanks,

Mattias

[Guilherme Salgado (salgado)]

I think it would make sense to use python's logging module with its various types of messages (e.g. info, debug, warning, etc) instead. Has that been considered?

[Mattias Backman (mabac)]

> I think it would make sense to use python's logging module with its various
> types of messages (e.g. info, debug, warning, etc) instead. Has that been
> considered?

Actually, no I didn't spend enough time on this to consider looking for that module. But you're right it makes sense, a lot for free with little effort to change to logging.

[Mattias Backman (mabac)]

Perhaps there also should be a nice formatter, or is a format like the example below ok?

   INFO:Svammel:There's already a bug report for qtiplot version 0.9.8.2-1ubuntu4.

[James Westby (james-w)]

202 parser.add_argument(
203 + '-v2', '--debug', action='store_true', dest='verbose2',
204 + help='Enable debug messages.')

I think I would prefer just having -v be an option that you can specify
multiple times. -vv would then be the debug option.

I think there is an example of doing this in the documentation.

Otherwise this looks good.

Thanks,

James

review: Approve

[lp:~mabac/svammel/extra-verbose-option]

97. By Mattias Backman on 2011-04-15

Remove -v2 option and change -v to count how many times it was passed.

98. By Mattias Backman on 2011-04-15

Remove Error: substring from .error logs.

=== modified file 'bug_logging.py'
--- bug_logging.py	2011-04-08 14:04:36 +0000
+++ bug_logging.py	2011-04-15 07:02:24 +0000
@@ -17,12 +17,14 @@
 # You should have received a copy of the GNU General Public License
 # along with Linaro Svammel.  If not, see <http://www.gnu.org/licenses/>.
 
+import logging
 from config import (
-    print_message,
+    LOGGER_NAME,
     )
 
 
 LOG_ITEM_SEPARATOR = ';'
+logger = logging.getLogger(LOGGER_NAME)
 
 
 class Log(object):
@@ -36,7 +38,7 @@
             try:
                 self.log_file = open(self.log_file_name, 'a')
             except IOError:
-                print 'Error: Could not open log file for writing.'
+                logger.error('Could not open log file for writing.')
                 raise
 
     def __del__(self):
@@ -57,7 +59,7 @@
                                          log_items[2], log_items[3])
                     self.add_entry(log_entry)
             except IOError:
-                print_message("Log file '%s' does not exist." % \
+                logger.warning("Log file '%s' does not exist." % \
                                   self.log_file_name)
             finally:
                 if log_file is not None:
@@ -77,7 +79,7 @@
             try:
                 self.log_file.write(log_string + '\n')
             except IOError:
-                print 'Error: Could not write log to file.'
+                logger.error('Could not write log to file.')
                 self.log_file.close()
                 raise
 

=== modified file 'bug_reporting.py'
--- bug_reporting.py	2011-04-08 14:04:36 +0000
+++ bug_reporting.py	2011-04-15 07:02:24 +0000
@@ -17,14 +17,16 @@
 # You should have received a copy of the GNU General Public License
 # along with Linaro Svammel.  If not, see <http://www.gnu.org/licenses/>.
 
+import logging
 from config import (
-    print_message,
+    LOGGER_NAME,
     continue_on_error,
     )
 
 
 BUG_INVALID_STATUS = 'Invalid'
 BUG_FIXED_STATUS = 'Fix Released'
+logger = logging.getLogger(LOGGER_NAME)
 
 
 def get_project_url(package_name, lp):
@@ -44,11 +46,11 @@
                             target=target_url,
                             tags=tags)
     if bug is not None:
-        print 'Filed bug %i: %s' % (bug.id, bug.web_link)
+        logger.info('Filed bug %i: %s' % (bug.id, bug.web_link))
         if importance is not None:
             set_bugtask_importance(bug, importance)
     else:
-        print "Error: unable to file bug '%s'." % title
+        logger.error("Unable to file bug '%s'." % title)
 
     return bug
 
@@ -60,7 +62,8 @@
             bug_task.lp_save()
     except:
         if continue_on_error():
-            print "Error: unable to set bug importance to '%s' but will proceed." % importance
+            logger.error("Unable to set bug importance to '%s' but " \
+                "will proceed." % importance)
         else:
             raise
 
@@ -81,7 +84,7 @@
     """ Close the bugtask by setting status to Invalid."""
 
     bug_task = lp.load(url)
-    print_message("  Changing status for %s [%s ==> %s]" % \
-                      (bug_task.title, bug_task.status, close_status))
+    logger.info("Changing status for %s [%s ==> %s]" % \
+                    (bug_task.title, bug_task.status, close_status))
     bug_task.status = close_status
     bug_task.lp_save()

=== modified file 'build_log.py'
--- build_log.py	2011-04-08 14:04:36 +0000
+++ build_log.py	2011-04-15 07:02:24 +0000
@@ -21,9 +21,13 @@
 import io
 import gzip
 import urllib
+import logging
 from StringIO import StringIO
 from collections import deque
-from config import print_message
+from config import LOGGER_NAME
+
+
+logger = logging.getLogger(LOGGER_NAME)
 
 
 class MatcherError(Exception):
@@ -37,6 +41,7 @@
 def get_file_contents(gz_url):
     """Return the contents of gzip file at url."""
 
+    logger.debug('Downloading contents of %s', gz_url)
     file = ''
     if gz_url is not None:
         file_handle = urllib.urlopen(gz_url)
@@ -52,6 +57,8 @@
                 except:
                     # Log is not compressed, might be 404 error.
                     # TODO: should this be analyzed or just thrown away?
+                    logger.warning(
+                        'Log is not compressed, might be 404 error.')
                     file = ''
                 file_io.close()
             file_handle.close()
@@ -102,6 +109,7 @@
                       '^Source-dependencies not satisfied'),
         ]
 
+    logger.debug('Applying log file matchers.')
     history = deque([])
     history_max = 20
     skipped_lines = 0
@@ -114,6 +122,9 @@
         for matcher in matchers:
             if isinstance(matcher, AbstractMatcher):
                 if matcher.match(line):
+                    logger.debug("Matcher '%s' triggered on line %d.",
+                                 matcher.get_name(), skipped_lines +
+                                 len(history))
                     return """This log snippet might be of interest, since it \
 triggered the matcher '%s'.\nExcerpt %d lines into the build log:\n\n%s""" % \
                         (matcher.get_name(), skipped_lines, "".join(history))

=== modified file 'config.py'
--- config.py	2011-04-12 07:59:04 +0000
+++ config.py	2011-04-15 07:02:24 +0000
@@ -17,6 +17,7 @@
 # You should have received a copy of the GNU General Public License
 # along with Linaro Svammel.  If not, see <http://www.gnu.org/licenses/>.
 
+import logging
 from launchpadlib.launchpad import Launchpad
 import argparse
 
@@ -44,6 +45,7 @@
 lp = None
 verbose = False
 ignore_errors = False
+LOGGER_NAME = 'Svammel'
 
 
 def verify_inited():
@@ -51,11 +53,6 @@
         raise ConfigInitError('Global configuration is not initialized.')
 
 
-def set_verbose_messages(state):
-    global verbose
-    verbose = state
-
-
 def set_ignore_errors(state):
     global ignore_errors
     ignore_errors = state
@@ -112,6 +109,9 @@
     else:
         raise ConfigInitError('Unsupported service_root: %s' % root)
 
+    logging.getLogger(LOGGER_NAME).debug(
+        "Logging in to Launchpad environment '%s' as application '%s' " \
+            "using local cachedir '%s'.", service_root, appid, cachedir)
     set_launchpad(service_root, appid, cachedir)
     inited = True
 
@@ -120,8 +120,9 @@
     """Get the ArgumentParser for the arguments given on the command line."""
     parser = argparse.ArgumentParser()
     parser.add_argument(
-        '-v', '--verbose', action='store_true', dest='verbose',
-        help='Enable verbose messages.')
+        '-v', '--verbose', action='count', dest='verbose',
+        help='Enable verbose messages. Passing -v more than once increases ' \
+            'verbosity.')
     parser.add_argument(
         '--dryrun', action='store_true', dest='dryrun',
         help='Disable bug filing and enable verbose messages.')
@@ -169,8 +170,3 @@
             'failure to set bug attributes.')
 
     return parser
-
-
-def print_message(message):
-    if verbose is True:
-        print message

=== modified file 'data_parsing.py'
--- data_parsing.py	2011-04-11 10:17:35 +0000
+++ data_parsing.py	2011-04-15 07:02:24 +0000
@@ -22,12 +22,13 @@
 
 from launchpadlib.uris import *
 import apt_pkg
+import logging
 
 from config import (
     get_base_url,
     get_base_api_url,
     get_launchpad,
-    print_message,
+    LOGGER_NAME,
     )
 
 apt_pkg.InitSystem()
@@ -40,6 +41,7 @@
 PRIMARY_ARCHIVE_NAME = 'primary'
 FAILED_BUILD_STATE = 'Failed to build'
 SUCCESS_BUILD_STATE = 'Successfully built'
+logger = logging.getLogger(LOGGER_NAME)
 
 
 class InvalidArchiveError(Exception):
@@ -93,6 +95,8 @@
 
 def get_build_list(archive, state, source=None):
 
+    logger.debug("Getting '%s' builds for source '%s' from archive " \
+                            "'%s'" % (state, source, archive.name))
     buildlist = archive.getBuildRecords(build_state=state, source_name=source)
 
     # XXX mabac 2011-03-16: getBuildRecords filters on substrings
@@ -104,6 +108,8 @@
             csp = build.current_source_publication
             if csp is not None and csp.source_package_name == source:
                 filter_list.append(build)
+        logger.debug("Done getting '%s' builds for source '%s'" % \
+                         (state, source))
         return filter_list
 
     return buildlist
@@ -129,7 +135,7 @@
 def fetch_pkg_list(archives):
     all_spph = dict()
     for archive, archive_name in archives:
-        print_message("The following packages have failed to build " \
+        logger.info("The following packages have failed to build " \
                       "in '%s'." % archive_name)
 
         buildlist = get_build_list(archive, FAILED_BUILD_STATE)
@@ -139,15 +145,20 @@
                 # Build record for an older version
                 continue
 
-            print_message("  Found build '%s'" % build.title)
+            logger.info("Found build '%s'" % build.title)
 
             stored_spph = all_spph.get(csp.source_package_name)
             new_spph = SPPH(csp.source_package_name,
                             csp.source_package_version)
             if new_spph.is_higher_version_than(stored_spph):
+                logger.debug("Keeping new build record.")
                 all_spph[csp.source_package_name] = new_spph
                 new_spph.add_build_record(build)
             else:
+                logger.debug(
+                    "Newly found build is not higher version than " \
+                        "previously found build. Will store new build " \
+                        "record for same version.")
                 stored_spph.add_build_record(build)
 
     return all_spph
@@ -205,32 +216,34 @@
     A subset of all_spph_list which represents the interesting packages.
     """
     filtered_list = []
-    print_message('Determining which build failures to file bugs for.')
+    logger.info('Determining which build failures to file bugs for.')
     for spph in all_spph_list.values():
+        logger.debug(' - checking %s' % spph.package_name)
         if not spph.is_ftbfs(fail_arch):
-            print_message("  Ignoring package '%s' version '%s' since it " \
-                              "did not fail on architecture '%s'." % \
-                              (spph.package_name, spph.version, fail_arch))
+            logger.info("Ignoring package '%s' version '%s' since it " \
+                            "did not fail on architecture '%s'." % \
+                            (spph.package_name, spph.version, fail_arch))
             continue
         also_failed = next((arch for arch in ok_archs
                                  if spph.is_ftbfs(arch)), None)
         if also_failed is not None:
-            print_message("  Ignoring package '%s' version '%s' since it " \
-                              "also failed to build on architecture '%s'." % \
-                              (spph.package_name, spph.version, also_failed))
+            logger.info("Ignoring package '%s' version '%s' since it " \
+                            "also failed to build on architecture '%s'." % \
+                            (spph.package_name, spph.version, also_failed))
             continue
 
         success_version = exists_successful_later_build(spph, archives,
                                                         fail_arch)
         if success_version is not None:
-            print_message("  Ignoring package '%s' version '%s' since build " \
-                              "of version '%s' succeded." % (spph.package_name,
-                                                             spph.version,
-                                                             success_version))
+            logger.info("Ignoring package '%s' version '%s' since build " \
+                            "of version '%s' succeded." % (spph.package_name,
+                                                           spph.version,
+                                                           success_version))
             continue
 
         filtered_list.append(spph)
 
+    logger.debug(' done filtering packages.')
     return filtered_list
 
 
@@ -246,8 +259,10 @@
     """
     archives = []
     series = None
+    logger.debug('Getting ubuntu distribution.')
     ubuntu = get_launchpad().distributions['ubuntu']
     for archive_name in archive_names:
+        logger.debug('Getting archive %s.', archive_name)
         try:
             archive = None
             archive_display_name = ''
@@ -264,9 +279,10 @@
                 raise InvalidArchiveError(
                     'Error: %s is not a valid archive.' % archive_name)
             archive_display_name = archive_display_name + archive.name
+            logger.debug('Got archive %s.', archive_display_name)
             archives.append((archive, archive_display_name))
         except HTTPError:
-            print 'Error: %s is not a valid archive.' % archive_name
+            logger.critical('Error: %s is not a valid archive.' % archive_name)
             raise
     return archives
 
@@ -284,9 +300,10 @@
     A list of SPPH objects representing source packages to file bugs against.
     """
 
+    logger.info('Getting archives.')
     archives = get_archives(archive_names, series_name)
 
-    print_message("Will be getting builds from archives " + ", ".join(
+    logger.info("Will be getting builds from archives " + ", ".join(
             name for (archive, name) in archives))
     spph_list = fetch_pkg_list(archives)
     return filter_spph(spph_list, fail_platform, ok_platforms, archives)

=== modified file 'file-failures.py'
--- file-failures.py	2011-04-11 08:40:06 +0000
+++ file-failures.py	2011-04-15 07:02:24 +0000
@@ -18,6 +18,7 @@
 # You should have received a copy of the GNU General Public License
 # along with Linaro Svammel.  If not, see <http://www.gnu.org/licenses/>.
 
+import logging
 from data_parsing import (
     get_tags_for_fail,
     get_build_status,
@@ -36,9 +37,8 @@
     init,
     get_launchpad,
     get_args_parser,
-    print_message,
-    set_verbose_messages,
     set_ignore_errors,
+    LOGGER_NAME,
 )
 from build_log import (
     get_file_contents,
@@ -60,10 +60,15 @@
 
 LP_APP_NAME = 'Svammel bug filer'
 
-
+logging.basicConfig()
+logger = logging.getLogger(LOGGER_NAME)
 parser = get_args_parser()
 args = parser.parse_args()
-set_verbose_messages(args.verbose or args.dryrun)
+if args.verbose == 1 or args.dryrun:
+    logger.setLevel(logging.INFO)
+if args.verbose > 1:
+    logger.setLevel(logging.DEBUG)
+logger.debug('Options: %s', args)
 set_ignore_errors(args.ignoreerrors)
 standard_bug_tags = ['ftbfs', 'arm-porting-queue']
 if args.bugtag is not None:
@@ -84,32 +89,35 @@
     interesting_spph = get_build_status(args.archive, args.series,
                                         fail_platform, ok_platforms)
 except:
-    print 'Error: Could not get build status'
+    logger.critical('Could not get build status.')
     raise
 
 bug_log = Log(args.logfile)
 for spph in interesting_spph:
 
     if bug_already_filed_by_url(spph.url, standard_bug_tags, get_launchpad()):
-        print_message("There's already a bug report for %s version %s." % \
+        logger.info("There's already a bug report for %s version %s." % \
             (spph.package_name, spph.version))
         continue
 
     if bug_log.get_entry(spph.package_name, spph.version,
                          fail_platform) is not None:
-        print_message("Bug already reported for %s version %s. Perhaps it " \
+        logger.info("Bug already reported for %s version %s. Perhaps it " \
                           "has been closed or retargeted." % \
                           (spph.package_name, spph.version))
         continue
 
+    logger.debug("Getting build record for %s." % spph.package_name)
     build_record = spph.get_arch(fail_platform)
     if build_record is not None:
+        logger.debug("Getting build log for %s." % spph.package_name)
         build_log = get_file_contents(build_record.build_log_url)
     else:
-        print "%s build record not available for %s version %s." % \
-            (fail_platform, spph.package_name, spph.version)
+        logger.warning("%s build record not available for %s version %s.",
+                       fail_platform, spph.package_name, spph.version)
         build_log = ''
     bug_tags = standard_bug_tags[:]
+    logger.debug("Processing build log for %s." % spph.package_name)
     bug_tags.extend(get_tags_for_fail(build_log))
     interesting_log_part = get_interesting_part(build_log)
 
@@ -124,7 +132,7 @@
 """ % (bug_title, build_record.web_link, build_record.build_log_url,
        interesting_log_part)
 
-    print_message("Will file bug for %s version %s with tags: %s" % \
+    logger.info("Will file bug for %s version %s with tags: %s" % \
                   (spph.package_name, spph.version, bug_tags))
     if not args.dryrun:
         bug = file_bug_by_url(spph.url, bug_description, bug_title,
@@ -134,11 +142,11 @@
                 LogEntry(spph.package_name, spph.version, fail_platform,
                          bug.bug_tasks[0].self_link).to_string())
     else:
-        print_message("  ... but didn't since dryrun is specified.")
+        logger.info("  ... but didn't since dryrun is specified.")
 
 archives = get_archives(args.archive, args.series)
 for log_entry in bug_log.get_arch(fail_platform):
-    print_message("Checking for successful builds for package " \
+    logger.info("Checking for successful builds for package " \
                       "%s version >= %s" % \
                       (log_entry.package_name, log_entry.package_version))
     success_version = exists_successful_later_build(
@@ -154,6 +162,6 @@
         else:
             bug = get_launchpad().load(log_entry.bugtask_url)
             for bug_task in bug.bug_tasks:
-                print_message("  Had reason to close the bugtask %s but " \
-                                  "didn't since dryrun is specified." % \
-                                  bug_task.web_link)
+                logger.info("Had reason to close the bugtask %s but " \
+                                "didn't since dryrun is specified." % \
+                                bug_task.web_link)

=== modified file 'tests/test_fail_filer.py'
--- tests/test_fail_filer.py	2011-04-12 10:43:36 +0000
+++ tests/test_fail_filer.py	2011-04-15 07:02:24 +0000
@@ -52,7 +52,6 @@
     ConfigInitError,
     LaunchpadError,
     set_ignore_errors,
-    set_verbose_messages,
     )