14542 2021-09-03 11:46:48 +0000 Three copies of output from failing task 2021-09-11 21:41:24 +0000 1 1 7 Build System, Metadata & Runtime BitBake bitbake unspecified x86 Multiple RESOLVED FIXED Medium+ normal 3.4 M4 1 Martin.Jansa richard.purdie poky.bs.watcher poky.watcher randy.macleod ross.burton yocto --- --- Don't know oldest_to_newest 91337 0 Martin.Jansa 2021-09-03 11:46:48 +0000 It was originally reported by Mike Crowe on bitbake-devel in: https://lists.openembedded.org/g/bitbake-devel/message/12144 His analysis: Even if I set BBINCLUDELOGS="no", I still get these three copies. The first one (without the leading "|" characters) appears to come from _build.py:_exec_task (around line 702) executing logger.error(str(exc)). This line dates from 2011. The second and third ones (with the leading "|") come from knotty.py around line 767. They are both in log.do_configure.32031. It looks like the third copy is coming from the same place as the first copy, but has been written to both the console and the log file. If I comment out the previously-mentioned call to logger.error(str(exc)) in _build.py:_exec_task then I get the single copy of the task output as I would expect. With simple test recipe: $ cat openembedded-core/meta/recipes-core/failing/one.bb SUMMARY = "Destined to fail" LICENSE = "CLOSED" deltask do_patch INHIBIT_DEFAULT_DEPS = "1" do_configure() { echo "This is stdout" echo "This is stderr" >&2 exit 1 } $ bitbake one -c configure ... NOTE: Executing Tasks ERROR: one-1.0-r0 do_configure: Execution of '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/temp/run.do_configure.1956426' failed with exit code 1: This is stdout This is stderr WARNING: exit code 1 from a shell command. ERROR: Logfile of failure stored in: /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/temp/log.do_configure.1956426 Log data follows: | DEBUG: Executing python function extend_recipe_sysroot | NOTE: Direct dependencies are ['virtual:native:/OE/build/oe-core/openembedded-core/meta/recipes-devtools/pseudo/pseudo_git.bb:do_populate_sysroot'] | NOTE: Installed into sysroot: [] | NOTE: Skipping as already exists in sysroot: ['pseudo-native'] | DEBUG: Python function extend_recipe_sysroot finished | DEBUG: Executing shell function do_configure | This is stdout | This is stderr | WARNING: exit code 1 from a shell command. | ERROR: Execution of '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/temp/run.do_configure.1956426' failed with exit code 1: | This is stdout | This is stderr | WARNING: exit code 1 from a shell command. | ERROR: Task (/OE/build/oe-core/openembedded-core/meta/recipes-core/failing/one.bb:do_configure) failed with exit code '1' NOTE: Tasks Summary: Attempted 107 tasks of which 106 didn't need to be rerun and 1 failed. with -v it gets even worse and the output is shown 5 times: NOTE: one-1.0-r0 do_configure: Direct dependencies are ['virtual:native:/OE/build/oe-core/openembedded-core/meta/recipes-devtools/pseudo/pseudo_git.bb:do_populate_sysroot'] NOTE: one-1.0-r0 do_configure: Installed into sysroot: [] NOTE: one-1.0-r0 do_configure: Skipping as already exists in sysroot: ['pseudo-native'] + cd /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/one-1.0 + do_configure + echo This is stdout This is stdout + echo This is stderr This is stderr + exit 1 + bb_sh_exit_handler + ret=1 + [ 1 != 0 ] + echo WARNING: exit code 1 from a shell command. WARNING: exit code 1 from a shell command. + exit 1 ERROR: one-1.0-r0 do_configure: Execution of '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/temp/run.do_configure.1956968' failed with exit code 1: + cd /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/one-1.0 + do_configure + echo This is stdout This is stdout + echo This is stderr This is stderr + exit 1 + bb_sh_exit_handler + ret=1 + [ 1 != 0 ] + echo WARNING: exit code 1 from a shell command. WARNING: exit code 1 from a shell command. + exit 1 ERROR: Logfile of failure stored in: /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/temp/log.do_configure.1956968 Log data follows: | DEBUG: Executing python function extend_recipe_sysroot | NOTE: Direct dependencies are ['virtual:native:/OE/build/oe-core/openembedded-core/meta/recipes-devtools/pseudo/pseudo_git.bb:do_populate_sysroot'] | NOTE: Installed into sysroot: [] | NOTE: Skipping as already exists in sysroot: ['pseudo-native'] | DEBUG: Python function extend_recipe_sysroot finished | DEBUG: Executing shell function do_configure | + cd /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/one-1.0 | + do_configure | + echo This is stdout | This is stdout | + echo This is stderr | This is stderr | + exit 1 | + bb_sh_exit_handler | + ret=1 | + [ 1 != 0 ] | + echo WARNING: exit code 1 from a shell command. | WARNING: exit code 1 from a shell command. | + exit 1 | | + cd /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/one-1.0 | + do_configure | + echo This is stdout | This is stdout | + echo This is stderr | This is stderr | + exit 1 | + bb_sh_exit_handler | + ret=1 | + [ 1 != 0 ] | + echo WARNING: exit code 1 from a shell command. | WARNING: exit code 1 from a shell command. | + exit 1 | ERROR: Execution of '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/temp/run.do_configure.1956968' failed with exit code 1: | + cd /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/one-1.0 | + do_configure | + echo This is stdout | This is stdout | + echo This is stderr | This is stderr | + exit 1 | + bb_sh_exit_handler | + ret=1 | + [ 1 != 0 ] | + echo WARNING: exit code 1 from a shell command. | WARNING: exit code 1 from a shell command. | + exit 1 | ERROR: Task (/OE/build/oe-core/openembedded-core/meta/recipes-core/failing/one.bb:do_configure) failed with exit code '1' This was with default BBINCLUDELOGS("yes"), BBINCLUDELOGS_LINES(unset), BB_LOGCONFIG(unset), BB_CONSOLELOG("${LOG_DIR}/cooker/${MACHINE}/${DATETIME}.log" This gets worse when the failed tasks log file is huge (like 50MB log.do_compile file from chromium-x11 build when it gets tripped in cooker output). It's also a bit unfortunate that setting BBINCLUDELOGS to "no" doesn't work, because any non-empty value will work as enabled in lib/bb/ui/knotty.py: "if includelogs and not event.errprinted" With BBINCLUDELOGS set to empty the output is reasonable: $ bitbake one -c configure NOTE: Executing Tasks ERROR: one-1.0-r0 do_configure: Execution of '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/temp/run.do_configure.1960559' failed with exit code 1: This is stdout This is stderr WARNING: exit code 1 from a shell command. ERROR: Logfile of failure stored in: /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/temp/log.do_configure.1960559 ERROR: Task (/OE/build/oe-core/openembedded-core/meta/recipes-core/failing/one.bb:do_configure) failed with exit code '1' And with -v it's only doubled (2nd one is printed on stderr) $ bitbake one -c configure -v ... NOTE: one-1.0-r0 do_configure: Direct dependencies are ['virtual:native:/OE/build/oe-core/openembedded-core/meta/recipes-devtools/pseudo/pseudo_git.bb:do_populate_sysroot'] NOTE: one-1.0-r0 do_configure: Installed into sysroot: [] NOTE: one-1.0-r0 do_configure: Skipping as already exists in sysroot: ['pseudo-native'] + cd /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/one-1.0 + do_configure + echo This is stdout This is stdout + echo This is stderr This is stderr + exit 1 + bb_sh_exit_handler + ret=1 + [ 1 != 0 ] + echo WARNING: exit code 1 from a shell command. WARNING: exit code 1 from a shell command. + exit 1 ERROR: one-1.0-r0 do_configure: Execution of '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/temp/run.do_configure.1960937' failed with exit code 1: + cd /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/one-1.0 + do_configure + echo This is stdout This is stdout + echo This is stderr This is stderr + exit 1 + bb_sh_exit_handler + ret=1 + [ 1 != 0 ] + echo WARNING: exit code 1 from a shell command. WARNING: exit code 1 from a shell command. + exit 1 ERROR: Logfile of failure stored in: /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/temp/log.do_configure.1960937 ERROR: Task (/OE/build/oe-core/openembedded-core/meta/recipes-core/failing/one.bb:do_configure) failed with exit code '1' If only stdout or stderr is shown, then the output looks a bit strange in both cases: $ bitbake one -c configure 2>/dev/null ... NOTE: Executing Tasks NOTE: Tasks Summary: Attempted 107 tasks of which 106 didn't need to be rerun and 1 failed. NOTE: Writing buildhistory NOTE: Writing buildhistory took: 2 seconds NOTE: Uploading the report /OE/build/oe-core/tmp-glibc/log/error-report/error_report_20210903114242.txt to errors.yoctoproject.org:80 NOTE: Report submitted: 200 Your entry can be found here: http://errors.yoctoproject.org/Errors/Build/129779/ Summary: 1 task failed: /OE/build/oe-core/openembedded-core/meta/recipes-core/failing/one.bb:do_configure $ bitbake one -c configure 1>/dev/null ERROR: one-1.0-r0 do_configure: Execution of '/OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/temp/run.do_configure.1961690' failed with exit code 1: This is stdout This is stderr WARNING: exit code 1 from a shell command. ERROR: Logfile of failure stored in: /OE/build/oe-core/tmp-glibc/work/core2-64-oe-linux/one/1.0-r0/temp/log.do_configure.1961690 ERROR: Task (/OE/build/oe-core/openembedded-core/meta/recipes-core/failing/one.bb:do_configure) failed with exit code '1' 91338 1 Martin.Jansa 2021-09-03 11:56:35 +0000 RFC work around sent to ML: https://lists.openembedded.org/g/openembedded-core/message/155650 91354 2 richard.purdie 2021-09-07 21:21:38 +0000 I can't help wondering if we should remove that variable entirely... 91373 3 richard.purdie 2021-09-10 08:46:18 +0000 It is interesting to compare/contrast this with a python function like: python do_configure () { print("Some output") sys.exit(1) } or python do_configure () { print("Some output") bb.fatal("Fatal error") } I had thought this change would stop showing task output for the python case but it seems that isn't shown regardless of what BBINCLUDELOGS is set to. So it looks like shell task logs are printed regardless and python tasks aren't at all. What a mess :( 91374 4 richard.purdie 2021-09-10 09:18:26 +0000 I dug into this a bit further. I have a couple of patches, one to fix python logging, the other to hide bb.process.run() output if piped logging is in use. I think with those two fixes, we can turn BBINCLUDELOGS back on and things will work as expected with a single backtrace of the logs for both shell and python tasks. This means with those two applied, I'd revert the BBINCLUDELOGS default change as I think this is the better set of fixes. Testing/feedback welcome. 91375 5 richard.purdie 2021-09-10 09:30:33 +0000 I've also sent a further patch to make -v not include a further copy of the info. 91376 6 Martin.Jansa 2021-09-10 10:03:33 +0000 I've repeated my test with one.bb with the BBINCLUDELOGS patch reverted and replaced with top 3 patches from your contrib/rpurdie/t222 and it seems to work fine. Thanks 91390 7 richard.purdie 2021-09-11 21:41:24 +0000 http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=ba4a61e69cd4035b5cdaa6cdf6be538af5ddaabb http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=f49854c1f7b7ab72c803864ab7f4c782fc503ca0 http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=c2b40b0f6d062c5061b11b038fac3b7b1539c688