Bug 14542

Summary:	Three copies of output from failing task
Product:	[Build System, Metadata & Runtime] BitBake	Reporter:	Martin Jansa <Martin.Jansa>
Component:	bitbake	Assignee:	Richard Purdie <richard.purdie>
Status:	RESOLVED FIXED	QA Contact:
Severity:	normal
Priority:	Medium+	CC:	poky.bs.watcher, poky.watcher, randy.macleod, ross.burton, yocto
Version:	unspecified
Target Milestone:	3.4 M4
Hardware:	x86
OS:	Multiple
Whiteboard:
OS type for building Yocto:	---	Type of Regression:	---
Verified:		Documentation change:	Don't know

Description Martin Jansa 2021-09-03 11:46:48 UTC

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'

Comment 1 Martin Jansa 2021-09-03 11:56:35 UTC

RFC work around sent to ML: https://lists.openembedded.org/g/openembedded-core/message/155650

Comment 2 Richard Purdie 2021-09-07 21:21:38 UTC

I can't help wondering if we should remove that variable entirely...

Comment 3 Richard Purdie 2021-09-10 08:46:18 UTC

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 :(

Comment 4 Richard Purdie 2021-09-10 09:18:26 UTC

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.

Comment 5 Richard Purdie 2021-09-10 09:30:33 UTC

I've also sent a further patch to make -v not include a further copy of the info.

Comment 6 Martin Jansa 2021-09-10 10:03:33 UTC

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

Comment 7 Richard Purdie 2021-09-11 21:41:24 UTC

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