Tell me your build error message annoyances!

Hey folks,

I'd like to collect some feedback on error messages while building that you find confusing/annoying/unhelpful. I'm going to be working on trying to improve the situation and would like to hear from you about what could be more helpful.

I'm starting to track some of these situations with the following bugs:

http://bugzilla.pokylinux.org/show_bug.cgi?id=542

http://bugzilla.pokylinux.org/show_bug.cgi?id=1127

http://bugzilla.pokylinux.org/show_bug.cgi?id=1128

I can't promise to fix everything you come up with, but I'd like to try to make a dent in some of these issues and improve the usability of our build system.

Thanks,

Scott

Scott Garman
Embedded Linux Engineer - Yocto Project
Intel Open Source Technology Center

You can make SkipPackage print out what recipes is getting skipped! I blew a bunch of time trying to build qemu64 minimal target before I found that you need the meta-intel layer such that grub 2 would be provided. Recipes-bsp has grub 0.97 but, it raises a SkipPackage exception if the target is not 32 bit.

bitbake -DDD grub would report NoProvider: grub Yet show the grub_0.97.bb was indeed getting processed.

--mark

Funnily enough we were just having a discussion about this on irc. My personal top two least favourite diagnostics are:

a) "bitbake -b nonexistent-file" gives ten lines of so of python exception traceback and then prints "MultipleMatches".

b) "bitbake -b recipe.bb", with a recipe that skips (due to an inCOMPATIBLE_MACHINE or whatever) gives the traditional ten lines of traceback spew and then prints "TypeError: 'NoneType' object is not iterable".

This is with bitbake 1.13.0.

p.

Agreed, these are issues.

I'd like to highlight that there is an underlying design issue in bitbake which make these hard issues to fix. Its very hard for bitbake to work out when it needs to show the traceback and when it doesn't.

If the user has been given an explanation of the problem we shouldn't show the traceback but its hard to know that is the case.

Somehow we therefore need to improve the error infrastructure in bitbake to be able to tell the difference between an unexpected error where a traceback is useful and a known error which has been explained to the user and no traceback is required.

Cheers,

Richard

I think we have too many places where exceptions are responded to. If we pushed the handling up as far as we can, it'd reduce the duplication of error handling code a great deal.

Christopher Larson
clarson at kergoth dot com
Founder - BitBake, OpenEmbedded, OpenZaurus
Maintainer - Tslib
Senior Software Engineer, Mentor Graphics

Well perhaps it would be easier to build a list of packages that have been skipped? I think the cache knows about them. Perhaps they could be reported to a "skipped" file or something similar?

--mark

FYI there is a patch I submitted the other day to bitbake-devel which tracks these in their own internal list. The next step is that when a NoProvider event comes up we can look through this list to see if the requested target is in there, and if so report that it was skipped along with the reason why. I would think that this obviates the need to show the list of skipped packages at the start, although we could easily allow them to be reported via some other mechanism.

This is a separate exercise to sorting out the flow of exceptions within bitbake, but still very important for the overall task of improving error output.

Cheers,
Paul

Paul Eggleton
Intel Open Source Technology Centre

Another non-favourite: if you fail to specify the right protocol for the git fetcher then you end up with something like:

ERROR: Function 'Fetcher failure for URL: 'None'. Fetch command export
HOME="/home/pb"; export
GIT_CONFIG="/home/pb/oe/build/tmp-eglibc/sysroots/x86_64-linux/usr/etc/gitconfig"; export PATH="..."; git ls-remote rsync://gitolite@cam-git/pb/linux-2.6.35 master failed with signal 128, output:
fatal: Could not make temporary directory: No such file or directory
' failed

Usually the value of $PATH is about half a screenful so this error looks more monstrous in real life than it probably does above, and it isn't immediately apparent that the "no such file or directory" thing is a result of having tried to fetch with the wrong URI scheme.

This is made slightly more irritating by the fact that there isn't much consistency between the different fetchers about the URI structure; some of them want a "proto" attribute whereas others (including git) want "protocol", so it's harder than perhaps it ought to be to remember what the correct naming is.

p.

Hi,

I have
PATCHRESOLVE = "noop"
in my local.conf, because I prefer it to fail and continue building something else (with -k) instead of waiting for user to resolve it in another screen session

but simple message that patch_do_patch failed because patch wasn't found or didn't apply without python trace would be much better.

NOTE: Running task 345 of 353 (ID: 1, virtual:native:/OE/shr-core/openembedded-core/meta/recipes-gnome/gnome/gobject-introspection_git.bb, do_patch)
NOTE: package gobject-introspection-native-1.29.0+gitr2+8d64bc23d2b837421ecf9c7b0e4b8d5d95ca0d21-r4: task do_patch: Started
NOTE: Applying patch 'pathfix.patch' (openembedded-core/meta/recipes-gnome/gnome/gobject-introspection/pathfix.patch)
ERROR: Error executing a python function in /OE/shr-core/openembedded-core/meta/recipes-gnome/gnome/gobject-introspection_git.bb:
CmdError: Command Error: exit status: 1 Output:
Applying patch pathfix.patch
patching file giscanner/dumper.py
Hunk #1 FAILED at 82.
1 out of 1 hunk FAILED -- rejects in file giscanner/dumper.py
patching file giscanner/scannermain.py
Hunk #1 FAILED at 283.
1 out of 1 hunk FAILED -- rejects in file giscanner/scannermain.py
Patch pathfix.patch does not apply (enforce with -f)

ERROR: The stack trace of python calls that resulted in this exception/failure was:
ERROR: File "patch_do_patch", line 136, in <module>
ERROR:
ERROR: File "patch_do_patch", line 133, in patch_do_patch
ERROR:

ERROR:   File "/OE/shr-core/openembedded-core/meta/lib/oe/patch.py", line 338, in Resolve
ERROR:     raise sys.exc_value
ERROR:
ERROR: The code that was being executed was:
ERROR:      0132:                       raise bb.build.FuncFailed(str(sys.exc_value))
ERROR:      0133:               resolver.Resolve()
ERROR:      0134:
ERROR:      0135:
ERROR:  *** 0136:patch_do_patch(d)
ERROR:      0137:
ERROR: (file: 'patch_do_patch', lineno: 136, function: <module>)
ERROR:      0129:                       patchset.Import({"file":local, "remote":url, "strippath": striplevel}, True)
ERROR:      0130:               except Exception:
ERROR:      0131:                       import sys
ERROR:      0132:                       raise bb.build.FuncFailed(str(sys.exc_value))
ERROR:  *** 0133:               resolver.Resolve()
ERROR:      0134:
ERROR:      0135:
ERROR:      0136:patch_do_patch(d)
ERROR:      0137:
ERROR: (file: 'patch_do_patch', lineno: 133, function: patch_do_patch)
ERROR: Function 'patch_do_patch' failed
ERROR: Logfile of failure stored in: /OE/shr-core/tmp/work/x86_64-linux/gobject-introspection-native-1.29.0+gitr2+8d64bc23d2b837421ecf9c7b0e4b8d5d95ca0d21-r4/temp/log.do_patch.9995
Log data follows:
| NOTE: Applying patch 'pathfix.patch' (openembedded-core/meta/recipes-gnome/gnome/gobject-introspection/pathfix.patch)
| ERROR: Error executing a python function in /OE/shr-core/openembedded-core/meta/recipes-gnome/gnome/gobject-introspection_git.bb:
| CmdError: Command Error: exit status: 1  Output:
| Applying patch pathfix.patch
| patching file giscanner/dumper.py
| Hunk #1 FAILED at 82.
| 1 out of 1 hunk FAILED -- rejects in file giscanner/dumper.py
| patching file giscanner/scannermain.py
| Hunk #1 FAILED at 283.
| 1 out of 1 hunk FAILED -- rejects in file giscanner/scannermain.py
| Patch pathfix.patch does not apply (enforce with -f)
|
| ERROR: The stack trace of python calls that resulted in this exception/failure was:
| ERROR:   File "patch_do_patch", line 136, in <module>
| ERROR:
| ERROR:   File "patch_do_patch", line 133, in patch_do_patch
| ERROR:
| ERROR:   File "/OE/shr-core/openembedded-core/meta/lib/oe/patch.py", line 338, in Resolve
| ERROR:     raise sys.exc_value
| ERROR:
| ERROR: The code that was being executed was:
| ERROR:      0132:                     raise bb.build.FuncFailed(str(sys.exc_value))
| ERROR:      0133:             resolver.Resolve()
| ERROR:      0134:
| ERROR:      0135:
| ERROR:  *** 0136:patch_do_patch(d)
| ERROR:      0137:
| ERROR: (file: 'patch_do_patch', lineno: 136, function: <module>)
| ERROR:      0129:                     patchset.Import({"file":local, "remote":url, "strippath": striplevel}, True)
| ERROR:      0130:             except Exception:
| ERROR:      0131:                     import sys
| ERROR:      0132:                     raise bb.build.FuncFailed(str(sys.exc_value))
| ERROR:  *** 0133:             resolver.Resolve()
| ERROR:      0134:
| ERROR:      0135:
| ERROR:      0136:patch_do_patch(d)
| ERROR:      0137:
| ERROR: (file: 'patch_do_patch', lineno: 133, function: patch_do_patch)
| ERROR: Function 'patch_do_patch' failed

NOTE: package gobject-introspection-native-1.29.0+gitr2+8d64bc23d2b837421ecf9c7b0e4b8d5d95ca0d21-r4: task do_patch: Failed
ERROR: Task 1 (virtual:native:/OE/shr-core/openembedded-core/meta/recipes-gnome/gnome/gobject-introspection_git.bb, do_patch) failed with exit code '1'
ERROR: 'virtual:native:/OE/shr-core/openembedded-core/meta/recipes-gnome/gnome/gobject-introspection_git.bb' failed

Martin 'JaMa' Jansa     jabber: [email protected]

These are maybe a bit off topic, but I'll leave it to you to decide if they meet the criteria for this effort.

o bb.debug messages are not logged anywhere nor do they appear on the console with -DDD during recipe parsing (while bb.note messages do make it to the console).

o I'm seeing duplicate messages lately - no examples handy, I'll post or open a bug next time.

o The bash logging facility (logging.bbclass) is still a second class citizen and probably needs a bitbake server hook so bbnote, bbplain, bbdebug, etc. can call into bitbake proper and use the python equivalents and therefor also make it to the proper destination (console or log).

o It's been mentioned, but I'd like to second that most of the time, getting a traceback is really not very helpful. Chris Larson mentioned moving the exception handling higher up the stack - I think that makes a lot of sense. I'd also suggest not printing a traceback unless running with at least -D. A catchall try block that only does:

print "Unhandled exception:", e

under normal conditions and prints a trace with -D enabled would clean things up a lot I think.

o In general I find the default UI to be exceedingly noisy. It feels very much like what I would write for something I was actively developing - ie, something I expect to break a lot! I don't think that's the sort of impression we want users to have while building a release (for example).

I'd prefer if what we currently get today was the output of -D. The current output could instead be something a lot more in the vein of what we see with recipe parsing. Perhaps one line per BB_NUMBER_TREADS (N), maybe something like:

Task 2300/4600 [#################### ]
0: linux-yocto: do_compile
1: matchbox: do_fetch
...
N: dbus: do_configure

It would of course update the current lines and not scroll. Most of the time, this would be plenty information. Upon failure we stop updating the "UI" and print something like:

ERROR: An unhandled exception occured while processing
linux-yocto: do_fetch

Exception: No such file or directory.

Run with -D for a more detailed error report or consult the appropriate log file:

$(pwd)/tmp/work/$machine/linux-yocto-$HASH-$HASH \
/temp/log.do_fetch.$PID

Or something along those lines.

Thanks for collecting these Scott, great idea!

Darren Hart
Intel Open Source Technology Center
Yocto Project - Linux Kernel

This isn't a priority for Scott's work at this point IMO.

This is a genuine bug that seems to have crept in recently which need to fix, not sure its Scott who needs to do it though.

This also isn't a priority for Scott's work at this point IMO.

I'm going to disagree here a little here. If something unexpected happens we always need the traceback so the pastebin'd error message means something to the developers. Currently it shows up even when the failure is a known error case and a message has been printed to the user and this is a bug though.

If we get exception handling right I think we solve this problem too.

You're describing the code in the ncurses UI. It is there and you can run it but its unfinished :(.

You should never be asked to rerun something, it should know when to print the right information.

Cheers,

Richard

...

I have heard similar comments from others as well.

Even if it did scroll, somehow limiting the messages being printed would be beneficial. It's been suggested to me simply one (or two) messages per step MAX.

Running linux-yocto do_compile
Running matchbox do_fetch
...

I believe currently we have around 3-5 messages per step, and it's still too noisy -- unless you need to debug something.

Correct. Right now, the output looks like:

NOTE: Running task 613 of 728 (ID: 190, virtual:native:/home/pb/oe/oe-core/meta/recipes-core/util-linux/util-linux_2.19.1.bb, do_install)
NOTE: package util-linux-native-2.19.1-r0: task do_install: Started
NOTE: package util-linux-native-2.19.1-r0: task do_install: Succeeded
NOTE: Running task 614 of 728 (ID: 191, virtual:native:/home/pb/oe/oe-core/meta/recipes-core/util-linux/util-linux_2.19.1.bb, do_populate_sysroot)
NOTE: package util-linux-native-2.19.1-r0: task do_populate_sysroot: Started
NOTE: package util-linux-native-2.19.1-r0: task do_populate_sysroot: Succeeded

It looks as though the "Started" and "Succeeded" lines could just be deleted without losing any real information.

p.

Heh, I used to have a personal branch where I dropped those, and also removed the unnecessary NOTE: prefix. I think its a given that something that doesn't indicate a warning or an error is simply informative :) The problem with dropping those messages is for postprocessing scripts, which may well want/need to know when a task completes, not just when it starts. Still, yet another case of something we could drop as long as we log it. We need to add a main bitbake execution log that captures everything, including debug messages, whether the user specifies -D or not.

Christopher Larson
clarson at kergoth dot com
Founder - BitBake, OpenEmbedded, OpenZaurus
Maintainer - Tslib
Senior Software Engineer, Mentor Graphics

In most systems, running with -D implies not only greater verbosity, but also reduced performance. I haven't checked, but I expect that is the case with bitbake as well. I don't think we want to enable all of -D and log it by default.

Thanks,

Darren Hart
Intel Open Source Technology Center
Yocto Project - Linux Kernel

I'm not sure the performance hit of this would be that great to be honest, particularly if we localised the output to the tasks and didn't hit the IPC mechanism for all the messages. It certainly could be valuable to have more robust logfiles on disk so that when things do break we can dive into them and get full debug info rather than the current partial info.

The main cost would be increased disk space but disks are cheap comparatively and the IO is minor compared to other things we do...

Cheers,

Richard

Hi Darren,

Before I can file a bug for this, I'll need more details/a reproducible test case.

Scott

Scott Garman
Embedded Linux Engineer - Yocto Project
Intel Open Source Technology Center

Op 1 jun 2011, om 00:26 heeft Scott Garman het volgende geschreven:

This one popped up recently, -b doesn't work anymore:

koen@dominion:/OE/tentacle/sources/meta-texasinstruments/recipes-kernel/linux$ ls | grep omap4
linux-omap4/
linux-omap4_2.6.35.3.bb
linux-omap4-2.6.35.7/
linux-omap4_2.6.35.7.bb
koen@dominion:/OE/tentacle/sources/meta-texasinstruments/recipes-kernel/linux$ MACHINE=omap4430-panda bitbake -b $PWD/linux-omap4_2.6.35.7.bb
ERROR: Command execution failed: Traceback (most recent call last):
  File "/OE/tentacle/sources/bitbake/lib/bb/command.py", line 102, in runAsyncCommand
    commandmethod(self.cmds_async, self, options)
  File "/OE/tentacle/sources/bitbake/lib/bb/command.py", line 190, in buildFile
    command.cooker.buildFile(bfile, task)
  File "/OE/tentacle/sources/bitbake/lib/bb/cooker.py", line 722, in buildFile
    fn = self.matchFile(fn)
  File "/OE/tentacle/sources/bitbake/lib/bb/cooker.py", line 700, in matchFile
    matches = self.matchFiles(buildfile)
  File "/OE/tentacle/sources/bitbake/lib/bb/cooker.py", line 683, in matchFiles
    filelist, masked = self.collect_bbfiles()
  File "/OE/tentacle/sources/bitbake/lib/bb/cooker.py", line 948, in collect_bbfiles
    files.sort( key=lambda fileitem: self.calc_bbfile_priority(fileitem) )
  File "/OE/tentacle/sources/bitbake/lib/bb/cooker.py", line 948, in <lambda>
    files.sort( key=lambda fileitem: self.calc_bbfile_priority(fileitem) )
  File "/OE/tentacle/sources/bitbake/lib/bb/cooker.py", line 411, in calc_bbfile_priority
    for _, _, regex, pri in self.status.bbfile_config_priorities:
AttributeError: 'NoneType' object has no attribute 'bbfile_config_priorities'

'bitbake linux-omap4-2.6.35.7' does work, though

Here's another one which, although perhaps slightly off-topic for your current effort, still seems to fall into all three of the categories you mentioned :-)

After I made a typo (mismatched quotes) in one of my recipes, my next bitbake run printed:

Loading cache: 100% |#####################################################################################################################################################| ETA: 00:00:00 Loaded 1323 entries from dependency cache.
NOTE: Error expanding variable do_configure | ETA: --:--:--
ERROR: Command execution failed: Traceback (most recent call last):############################# | ETA: 00:00:00
File "/home/pb/oe/bitbake/lib/bb/command.py", line 99, in runAsyncCommand
self.cooker.updateCache()
File "/home/pb/oe/bitbake/lib/bb/cooker.py", line 871, in updateCache
if not self.parser.parse_next():
File "/home/pb/oe/bitbake/lib/bb/cooker.py", line 1120, in parse_next
self.shutdown(clean=False)
File "/home/pb/oe/bitbake/lib/bb/cooker.py", line 1102, in shutdown
bb.codeparser.parser_cache_save(self.cfgdata)
File "/home/pb/oe/bitbake/lib/bb/codeparser.py", line 77, in parser_cache_save
data, version = p.load()
EOFError

So, this is (a) confusing, because "EOFError" doesn't yield much information about the actual cause of the problem; (b) unhelpful, since it doesn't mention which line of the file (or even which recipe) was to blame; and (c) annoying, for the usual reasons to do with python traceback.

Somewhat worse, even after I fixed the typo, any subsequent attempt to run bitbake would just result in:

Loading cache: 100% |#####################################################################################################################################################| ETA: 00:00:00 Loaded 1323 entries from dependency cache.
Traceback (most recent call last): | ETA: --:--:--
File "/usr/lib/python2.6/multiprocessing/util.py", line 235, in _run_finalizers
finalizer()
File "/usr/lib/python2.6/multiprocessing/util.py", line 174, in __call__

    res = self._callback(*self._args, **self._kwargs)

File "/home/pb/oe/bitbake/lib/bb/codeparser.py", line 77, in parser_cache_save
data, version = p.load()
EOFError

(repeated about 10 times)

I deleted tmp/cache/* and that seemed to fix the problem.

p.

FWIW, bitbake master has fixes for this specific issue and a number of other codeparser performance related issues. If it meets EOF while loading it will now just assume the cache file is corrupt and ignore/rebuild it.

Cheers,

Richard

Thanks everyone for your feedback. I have filed a number of bugs in Bugzilla and currently have a small list of them I'm working on currently. Here is the current list I created based on the replies to this thread:

Bug 542 - bitbake "NoProvider" message doesn't aid in resolving the problem
http://bugzilla.pokylinux.org/show_bug.cgi?id=542

Bug 1127 - Improve the error reporting when SkipPackage error is raised
http://bugzilla.pokylinux.org/show_bug.cgi?id=1127

Bug 1128 - Meaningless error message when quilt is not installed
http://bugzilla.pokylinux.org/show_bug.cgi?id=1128

Bug 1141 - bitbake -b prints meaningless error when given an invalid recipe name
http://bugzilla.pokylinux.org/show_bug.cgi?id=1141

Bug 1142 - git fetcher error when wrong protocol is specified is not helpful
http://bugzilla.pokylinux.org/show_bug.cgi?id=1142

Bug 1143 - Remove python stack trace when do_patch fails
http://bugzilla.pokylinux.org/show_bug.cgi?id=1143

Bug 1144 - bb.debug messages are not logged or displayed on the console with -DDD during recipe parsing
http://bugzilla.pokylinux.org/show_bug.cgi?id=1144

Bug 1145 - Make bitbake output less noisy for non-error cases
http://bugzilla.pokylinux.org/show_bug.cgi?id=1145

Again, not all of those are on my plate for M2/M3, but my goal is to make a dent in them soon.

Scott

Scott Garman
Embedded Linux Engineer - Yocto Project
Intel Open Source Technology Center