[PATCH 0/8] Error message improvements

[PATCH 0/8] Error message improvements

[Paul Eggleton]

A number of fixes to improve the readability of error messages,
primarily for fetch errors, but will improve error output in other
situations as well.

(This supersedes the set of patches I sent a couple of days ago.)

The changes (against Poky, but apply cleanly with -p2 against bitbake
master) are available in the git repository at: 
  git://git.yoctoproject.org/poky-contrib paule/errorhandling
  http://git.yoctoproject.org/cgit.cgi/poky-contrib/log/?h=paule/errorhandling

Paul Eggleton (8):
  bitbake/knotty: don't count errors as warnings in summary
  bitbake/fetch2: improve error formatting for fetcher errors
  bitbake/runqueue: avoid "failed" in task summary if nothing did
  bitbake/fetch2: correctly decode exit signal/status
  bitbake/knotty: avoid printing full task log when error already
    printed
  bitbake/fetch2: reduce output for fetch failures
  bitbake/cooker: avoid printing stack trace for -b match error
  bitbake/knotty: print task failure summary

 bitbake/lib/bb/build.py           |   20 ++++++++++++++++----
 bitbake/lib/bb/cooker.py          |   21 +++++++++++----------
 bitbake/lib/bb/fetch2/__init__.py |   29 ++++++++++++++++++++---------
 bitbake/lib/bb/runqueue.py        |    6 +++++-
 bitbake/lib/bb/ui/knotty.py       |   28 ++++++++++++++++++++++++----
 5 files changed, 76 insertions(+), 28 deletions(-)

-- 
1.7.5.4

[PATCH 1/8] bitbake/knotty: don't count errors as warnings in summary

[Paul Eggleton]

The count of warnings being shown in the summary at the end was also
including the number of errors.

Signed-off-by: Paul Eggleton <paul.eggleton@linux.intel.com>
---
 bitbake/lib/bb/ui/knotty.py |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/bitbake/lib/bb/ui/knotty.py b/bitbake/lib/bb/ui/knotty.py
index 0340619..5366386 100644
--- a/bitbake/lib/bb/ui/knotty.py
+++ b/bitbake/lib/bb/ui/knotty.py
@@ -127,7 +127,7 @@ def main(server, eventHandler):
                 if event.levelno >= format.ERROR:
                     errors = errors + 1
                     return_value = 1
-                if event.levelno >= format.WARNING:
+                elif event.levelno == format.WARNING:
                     warnings = warnings + 1
                 # For "normal" logging conditions, don't show note logs from tasks
                 # but do show them if the user has changed the default log level to 
-- 
1.7.5.4

[PATCH 2/8] bitbake/fetch2: improve error formatting for fetcher errors

[Paul Eggleton]

* The "name" argument to FuncFailed is rarely used as a name in actual
  usage within bitbake, so don't treat it as one in the output.
* Don't print URL for FetchError if it was not specified (i.e. don't
  output "Fetcher failure for URL 'None'")
* Don't include URL in "unable to fetch from any source" message since
  we supply it to FetchError and it will be printed anyway.
* Don't include URL in "checksum failed" message for the same reason

Signed-off-by: Paul Eggleton <paul.eggleton@linux.intel.com>
---
 bitbake/lib/bb/build.py           |    2 +-
 bitbake/lib/bb/fetch2/__init__.py |   11 +++++++----
 2 files changed, 8 insertions(+), 5 deletions(-)

diff --git a/bitbake/lib/bb/build.py b/bitbake/lib/bb/build.py
index aabc1b6..30e5497 100644
--- a/bitbake/lib/bb/build.py
+++ b/bitbake/lib/bb/build.py
@@ -53,7 +53,7 @@ class FuncFailed(Exception):
         self.logfile = logfile
         self.name = name
         if name:
-            self.msg = "Function '%s' failed" % name
+            self.msg = 'Function failed: %s' % name
         else:
             self.msg = "Function failed"
 
diff --git a/bitbake/lib/bb/fetch2/__init__.py b/bitbake/lib/bb/fetch2/__init__.py
index 3af56e5..21abb13 100644
--- a/bitbake/lib/bb/fetch2/__init__.py
+++ b/bitbake/lib/bb/fetch2/__init__.py
@@ -55,7 +55,10 @@ class MalformedUrl(BBFetchException):
 class FetchError(BBFetchException):
     """General fetcher exception when something happens incorrectly"""
     def __init__(self, message, url = None):
-         msg = "Fetcher failure for URL: '%s'. %s" % (url, message)
+         if url:
+            msg = "Fetcher failure for URL: '%s'. %s" % (url, message)
+         else:
+            msg = "Fetcher failure: %s" % message
          self.url = url
          BBFetchException.__init__(self, msg)
          self.args = (message, url)
@@ -302,10 +305,10 @@ def verify_checksum(u, ud, d):
     # it does not match.
     msg = ""
     if md5mismatch and ud.md5_expected:
-        msg = msg + "\nFile: '%s' has %s checksum %s when %s was expected (from URL: '%s')" % (ud.localpath, 'md5', md5data, ud.md5_expected, u)
+        msg = msg + "\nFile: '%s' has %s checksum %s when %s was expected" % (ud.localpath, 'md5', md5data, ud.md5_expected)
 
     if sha256mismatch and ud.sha256_expected:
-        msg = msg + "\nFile: '%s' has %s checksum %s when %s was expected (from URL: '%s')" % (ud.localpath, 'sha256', sha256data, ud.sha256_expected, u)
+        msg = msg + "\nFile: '%s' has %s checksum %s when %s was expected" % (ud.localpath, 'sha256', sha256data, ud.sha256_expected)
 
     if len(msg):
         raise FetchError('Checksum mismatch!%s' % msg, u)
@@ -983,7 +986,7 @@ class Fetch(object):
                         localpath = try_mirrors (self.d, ud, mirrors)
 
                 if not localpath or ((not os.path.exists(localpath)) and localpath.find("*") == -1):
-                    raise FetchError("Unable to fetch URL %s from any source." % u, u)
+                    raise FetchError("Unable to fetch URL from any source.", u)
 
                 update_stamp(u, ud, self.d)
 
-- 
1.7.5.4

[PATCH 3/8] bitbake/runqueue: avoid "failed" in task summary if nothing did

[Paul Eggleton]

Seeing the word "failed" alone without reading the whole context has
occasionally triggered an automatic assumption on the part of some users
(myself included) that something has gone wrong, even when this message
is telling you that "0 [tasks] failed". To avoid this let's just say
"all succeeded" in this case instead.

As a bonus this means you can now search the output for "fail" and not
find anything if all went well.

Signed-off-by: Paul Eggleton <paul.eggleton@linux.intel.com>
---
 bitbake/lib/bb/runqueue.py |    6 +++++-
 1 files changed, 5 insertions(+), 1 deletions(-)

diff --git a/bitbake/lib/bb/runqueue.py b/bitbake/lib/bb/runqueue.py
index 86744fb..054d36c 100644
--- a/bitbake/lib/bb/runqueue.py
+++ b/bitbake/lib/bb/runqueue.py
@@ -968,7 +968,11 @@ class RunQueue:
 
         if self.state is runQueueComplete:
             # All done
-            logger.info("Tasks Summary: Attempted %d tasks of which %d didn't need to be rerun and %d failed.", self.rqexe.stats.completed, self.rqexe.stats.skipped, self.rqexe.stats.failed)
+            if self.rqexe.stats.failed:
+                logger.info("Tasks Summary: Attempted %d tasks of which %d didn't need to be rerun and %d failed.", self.rqexe.stats.completed, self.rqexe.stats.skipped, self.rqexe.stats.failed)
+            else:
+                # Let's avoid the word "failed" if nothing actually did
+                logger.info("Tasks Summary: Attempted %d tasks of which %d didn't need to be rerun and all succeeded.", self.rqexe.stats.completed, self.rqexe.stats.skipped)
             return False
 
         if self.state is runQueueChildProcess:
-- 
1.7.5.4

[PATCH 4/8] bitbake/fetch2: correctly decode exit signal/status

[Paul Eggleton]

The termination signal and exit code of the fetch process were not being
decoded correctly, resulting in bitbake reporting that the process
terminated with a signal of the exit code (if it was under 255). There
are functions in the Python os module to do this decoding correctly (for
Unix at least), so let's use them.

Signed-off-by: Paul Eggleton <paul.eggleton@linux.intel.com>
---
 bitbake/lib/bb/fetch2/__init__.py |   11 +++++++----
 1 files changed, 7 insertions(+), 4 deletions(-)

diff --git a/bitbake/lib/bb/fetch2/__init__.py b/bitbake/lib/bb/fetch2/__init__.py
index 21abb13..771f72e 100644
--- a/bitbake/lib/bb/fetch2/__init__.py
+++ b/bitbake/lib/bb/fetch2/__init__.py
@@ -422,8 +422,11 @@ def runfetchcmd(cmd, d, quiet = False, cleanup = []):
         output += line
 
     status = stdout_handle.close() or 0
-    signal = status >> 8
-    exitstatus = status & 0xff
+    signal = os.WTERMSIG(status)
+    if os.WIFEXITED(status):
+        exitstatus = os.WEXITSTATUS(status)
+    else:
+        exitstatus = 0
 
     if (signal or status != 0):
         for f in cleanup:
@@ -434,8 +437,8 @@ def runfetchcmd(cmd, d, quiet = False, cleanup = []):
 
         if signal:
             raise FetchError("Fetch command %s failed with signal %s, output:\n%s" % (cmd, signal, output))
-        elif status != 0:
-            raise FetchError("Fetch command %s failed with exit code %s, output:\n%s" % (cmd, status, output))
+        elif exitstatus:
+            raise FetchError("Fetch command %s failed with exit code %s, output:\n%s" % (cmd, exitstatus, output))
 
     return output
 
-- 
1.7.5.4

[PATCH 5/8] bitbake/knotty: avoid printing full task log when error already printed

[Paul Eggleton]

If a task has logged an ERROR then don't print the contents of the
task's log file in knotty (the default terminal UI).

As a side-effect we now also respect BBINCLUDELOGS in knotty; if it is
false we never print the log (but the pointer to the log file is always
printed).

Signed-off-by: Paul Eggleton <paul.eggleton@linux.intel.com>
---
 bitbake/lib/bb/build.py     |   18 +++++++++++++++---
 bitbake/lib/bb/ui/knotty.py |    2 +-
 2 files changed, 16 insertions(+), 4 deletions(-)

diff --git a/bitbake/lib/bb/build.py b/bitbake/lib/bb/build.py
index 30e5497..1e041a2 100644
--- a/bitbake/lib/bb/build.py
+++ b/bitbake/lib/bb/build.py
@@ -91,8 +91,9 @@ class TaskSucceeded(TaskBase):
 class TaskFailed(TaskBase):
     """Task execution failed"""
 
-    def __init__(self, task, logfile, metadata):
+    def __init__(self, task, logfile, metadata, errprinted = False):
         self.logfile = logfile
+        self.errprinted = errprinted
         super(TaskFailed, self).__init__(task, metadata)
 
 class TaskInvalid(TaskBase):
@@ -286,6 +287,13 @@ def _exec_task(fn, task, d, quieterr):
     prefuncs = localdata.getVarFlag(task, 'prefuncs', expand=True)
     postfuncs = localdata.getVarFlag(task, 'postfuncs', expand=True)
 
+    class ErrorCheckHandler(logging.Handler):
+        def __init__(self):
+            self.triggered = False
+            logging.Handler.__init__(self, logging.ERROR)
+        def emit(self, record):
+            self.triggered = True
+
     # Handle logfiles
     si = file('/dev/null', 'r')
     try:
@@ -311,6 +319,9 @@ def _exec_task(fn, task, d, quieterr):
     handler.setLevel(logging.DEBUG - 2)
     bblogger.addHandler(handler)
 
+    errchk = ErrorCheckHandler()
+    bblogger.addHandler(errchk)
+
     localdata.setVar('BB_LOGFILE', logfn)
 
     event.fire(TaskStarted(task, localdata), localdata)
@@ -322,8 +333,9 @@ def _exec_task(fn, task, d, quieterr):
             exec_func(func, localdata)
     except FuncFailed as exc:
         if not quieterr:
+            errprinted = errchk.triggered
             logger.error(str(exc))
-            event.fire(TaskFailed(task, logfn, localdata), localdata)
+            event.fire(TaskFailed(task, logfn, localdata, errprinted), localdata)
         return 1
     finally:
         sys.stdout.flush()
@@ -366,7 +378,7 @@ def exec_task(fn, task, d):
         if not quieterr:
             logger.error("Build of %s failed" % (task))
             logger.error(format_exc())
-            failedevent = TaskFailed(task, None, d)
+            failedevent = TaskFailed(task, None, d, True)
             event.fire(failedevent, d)
         return 1
 
diff --git a/bitbake/lib/bb/ui/knotty.py b/bitbake/lib/bb/ui/knotty.py
index 5366386..205a8d8 100644
--- a/bitbake/lib/bb/ui/knotty.py
+++ b/bitbake/lib/bb/ui/knotty.py
@@ -142,7 +142,7 @@ def main(server, eventHandler):
                 logfile = event.logfile
                 if logfile and os.path.exists(logfile):
                     print("ERROR: Logfile of failure stored in: %s" % logfile)
-                    if 1 or includelogs:
+                    if includelogs and not event.errprinted:
                         print("Log data follows:")
                         f = open(logfile, "r")
                         lines = []
-- 
1.7.5.4

[PATCH 6/8] bitbake/fetch2: reduce output for fetch failures

[Paul Eggleton]

Make the warning for the initial fetch failure a single line - we don't
need the full command and output here yet, but write it into the log in
full as a debug message. However, if fetching from mirrors fails as well
then print out the full details for the first error that occurred as an
ERROR rather than a WARNING.

Since this is logged as an ERROR, combined with an earlier patch it
suppresses the full log which does make the output much more readable
for any fetch error.

Fixes [YOCTO #1832].

Signed-off-by: Paul Eggleton <paul.eggleton@linux.intel.com>
---
 bitbake/lib/bb/fetch2/__init__.py |    7 ++++++-
 1 files changed, 6 insertions(+), 1 deletions(-)

diff --git a/bitbake/lib/bb/fetch2/__init__.py b/bitbake/lib/bb/fetch2/__init__.py
index 771f72e..fe4f4b1 100644
--- a/bitbake/lib/bb/fetch2/__init__.py
+++ b/bitbake/lib/bb/fetch2/__init__.py
@@ -965,6 +965,7 @@ class Fetch(object):
                 if premirroronly:
                     self.d.setVar("BB_NO_NETWORK", "1")
 
+                firsterr = None
                 if not localpath and m.need_update(u, ud, self.d):
                     try:
                         logger.debug(1, "Trying Upstream")
@@ -980,7 +981,9 @@ class Fetch(object):
                         raise
 
                     except BBFetchException as e:
-                        logger.warn(str(e))
+                        logger.warn('Failed to fetch URL %s' % u)
+                        logger.debug(1, str(e))
+                        firsterr = e
                         # Remove any incomplete fetch
                         if os.path.isfile(ud.localpath):
                             bb.utils.remove(ud.localpath)
@@ -989,6 +992,8 @@ class Fetch(object):
                         localpath = try_mirrors (self.d, ud, mirrors)
 
                 if not localpath or ((not os.path.exists(localpath)) and localpath.find("*") == -1):
+                    if firsterr:
+                        logger.error(str(firsterr))
                     raise FetchError("Unable to fetch URL from any source.", u)
 
                 update_stamp(u, ud, self.d)
-- 
1.7.5.4

[PATCH 7/8] bitbake/cooker: avoid printing stack trace for -b match error

[Paul Eggleton]

Improves error output for matching problems when the -b / --buildfile
command line option is used.

Rename MultipleMatches exception to NoSpecificMatch (as it is also
raised when there are no matching recipes) and make it inherit from
BBHandledException so that it doesn't print a stack trace (we always log
an ERROR prior to raising it.)

In addition, improve the formatting of the error message - only call the
log function once rather than once for every match, and use a more
appropriate message if there are no matches.

Fixes [YOCTO #1141]

Signed-off-by: Paul Eggleton <paul.eggleton@linux.intel.com>
---
 bitbake/lib/bb/cooker.py |   17 +++++++++++------
 1 files changed, 11 insertions(+), 6 deletions(-)

diff --git a/bitbake/lib/bb/cooker.py b/bitbake/lib/bb/cooker.py
index 194046e..6041410 100644
--- a/bitbake/lib/bb/cooker.py
+++ b/bitbake/lib/bb/cooker.py
@@ -44,9 +44,9 @@ buildlog    = logging.getLogger("BitBake.Build")
 parselog    = logging.getLogger("BitBake.Parsing")
 providerlog = logging.getLogger("BitBake.Provider")
 
-class MultipleMatches(Exception):
+class NoSpecificMatch(bb.BBHandledException):
     """
-    Exception raised when multiple file matches are found
+    Exception raised when no or multiple file matches are found
     """
 
 class NothingToBuild(Exception):
@@ -979,10 +979,15 @@ class BBCooker:
         """
         matches = self.matchFiles(buildfile)
         if len(matches) != 1:
-            parselog.error("Unable to match %s (%s matches found):" % (buildfile, len(matches)))
-            for f in matches:
-                parselog.error("    %s" % f)
-            raise MultipleMatches
+            if matches:
+                msg = "Unable to match '%s' to a specific recipe file - %s matches found:" % (buildfile, len(matches))
+                if matches:
+                    for f in matches:
+                        msg += "\n    %s" % f
+                parselog.error(msg)
+            else:
+                parselog.error("Unable to find any recipe file matching '%s'" % buildfile)
+            raise NoSpecificMatch
         return matches[0]
 
     def buildFile(self, buildfile, task):
-- 
1.7.5.4

[PATCH 8/8] bitbake/knotty: print task failure summary

[Paul Eggleton]

Remove the error logged within cooker summarising the list of failed
tasks, and instead print this in the UI (knotty) where it belongs. This
also adds the actual name of the task that failed as well as the
corresponding recipe file that was being shown previously.

In addition, reformat the summary messages more tidily - no extra breaks
between lines and use correct English singular/plurals, with some
allowance for future translation.

Signed-off-by: Paul Eggleton <paul.eggleton@linux.intel.com>
---
 bitbake/lib/bb/cooker.py    |    4 ----
 bitbake/lib/bb/ui/knotty.py |   24 ++++++++++++++++++++++--
 2 files changed, 22 insertions(+), 6 deletions(-)

diff --git a/bitbake/lib/bb/cooker.py b/bitbake/lib/bb/cooker.py
index 6041410..4197a02 100644
--- a/bitbake/lib/bb/cooker.py
+++ b/bitbake/lib/bb/cooker.py
@@ -1065,8 +1065,6 @@ class BBCooker:
             try:
                 retval = rq.execute_runqueue()
             except runqueue.TaskFailure as exc:
-                for fnid in exc.args:
-                    buildlog.error("'%s' failed" % taskdata.fn_index[fnid])
                 failures += len(exc.args)
                 retval = False
             except SystemExit as exc:
@@ -1106,8 +1104,6 @@ class BBCooker:
             try:
                 retval = rq.execute_runqueue()
             except runqueue.TaskFailure as exc:
-                for fnid in exc.args:
-                    buildlog.error("'%s' failed" % taskdata.fn_index[fnid])
                 failures += len(exc.args)
                 retval = False
             except SystemExit as exc:
diff --git a/bitbake/lib/bb/ui/knotty.py b/bitbake/lib/bb/ui/knotty.py
index 205a8d8..e1d42f7 100644
--- a/bitbake/lib/bb/ui/knotty.py
+++ b/bitbake/lib/bb/ui/knotty.py
@@ -64,6 +64,12 @@ def new_progress(msg, maxval):
     else:
         return NonInteractiveProgress(msg, maxval)
 
+def pluralise(singular, plural, qty):
+    if(qty == 1):
+        return singular % qty
+    else:
+        return plural % qty
+
 def main(server, eventHandler):
 
     # Get values of variables which control our output
@@ -107,6 +113,7 @@ def main(server, eventHandler):
     return_value = 0
     errors = 0
     warnings = 0
+    taskfailures = []
     while True:
         try:
             event = eventHandler.waitEvent(0.25)
@@ -240,6 +247,7 @@ def main(server, eventHandler):
                 continue
 
             if isinstance(event, bb.runqueue.runQueueTaskFailed):
+                taskfailures.append(event.taskstring)
                 logger.error("Task %s (%s) failed with exit code '%s'",
                              event.taskid, event.taskstring, event.exitcode)
                 continue
@@ -272,8 +280,20 @@ def main(server, eventHandler):
                 server.runCommand(["stateShutdown"])
             shutdown = shutdown + 1
             pass
+
+    summary = ""
+    if taskfailures:
+        summary += pluralise("\nSummary: %s task failed:",
+                             "\nSummary: %s tasks failed:", len(taskfailures))
+        for failure in taskfailures:
+            summary += "\n  %s" % failure
     if warnings:
-        print("Summary: There were %s WARNING messages shown.\n" % warnings)
+        summary += pluralise("\nSummary: There was %s WARNING message shown.",
+                             "\nSummary: There were %s WARNING messages shown.", warnings)
     if return_value:
-        print("Summary: There were %s ERROR messages shown, returning a non-zero exit code.\n" % errors)
+        summary += pluralise("\nSummary: There was %s ERROR message shown, returning a non-zero exit code.",
+                             "\nSummary: There were %s ERROR messages shown, returning a non-zero exit code.", errors)
+    if summary:
+        print(summary)
+
     return return_value
-- 
1.7.5.4

Re: [PATCH 0/8] Error message improvements

[Richard Purdie]

On Fri, 2012-01-13 at 17:01 +0000, Paul Eggleton wrote:
> A number of fixes to improve the readability of error messages,
> primarily for fetch errors, but will improve error output in other
> situations as well.
> 
> (This supersedes the set of patches I sent a couple of days ago.)
> 
> The changes (against Poky, but apply cleanly with -p2 against bitbake
> master) are available in the git repository at: 
>   git://git.yoctoproject.org/poky-contrib paule/errorhandling
>   http://git.yoctoproject.org/cgit.cgi/poky-contrib/log/?h=paule/errorhandling
> 
> Paul Eggleton (8):
>   bitbake/knotty: don't count errors as warnings in summary
>   bitbake/fetch2: improve error formatting for fetcher errors
>   bitbake/runqueue: avoid "failed" in task summary if nothing did
>   bitbake/fetch2: correctly decode exit signal/status
>   bitbake/knotty: avoid printing full task log when error already
>     printed
>   bitbake/fetch2: reduce output for fetch failures
>   bitbake/cooker: avoid printing stack trace for -b match error
>   bitbake/knotty: print task failure summary

Merged to master, thanks. Some good improvements in there.

Cheers,

Richard