Re: [bitbake-devel] Three copies of output from failing task

["Mike Crowe" <yocto@mac.mcrowe.com>]

On Tuesday 06 April 2021 at 15:26:02 +0100, Richard Purdie wrote:
> On Tue, 2021-03-30 at 15:30 +0100, Mike Crowe via lists.openembedded.org wrote:
> > After upgrading from oe-core Warrior (Bitbake 1.42) to Dunfell (Bitbake
> > 1.46), I'm seeing _three_ copies of the log output for every build failure.
> > I see similar when using the current state of oe-core master (along with
> > the new backtraces.)
> > 
> > To reproduce the problem, I hacked openssl_1.1.1k.bb:do_configure to insert:
> > 
> >  echo "an error"
> >  false
> > 
> > and ran bitbake openssl-native. The output was:
> > 
> > --8<--
> > NOTE: Executing Tasks
> > ERROR: openssl-native-1.1.1k-r0 do_configure: Execution of '/overflow/mac/nobackup/git/oe-core/build/tmp-glibc/work/x86_64-linux/openssl-native/1.1.1k-r0/temp/run.do_configure.32031' failed with exit code 1:
> > an error
> > WARNING: /overflow/mac/nobackup/git/oe-core/build/tmp-glibc/work/x86_64-linux/openssl-native/1.1.1k-r0/temp/run.do_configure.32031:143 exit 1 from 'false'
> > WARNING: Backtrace (BB generated script):
> >         #1: do_configure, /overflow/mac/nobackup/git/oe-core/build/tmp-glibc/work/x86_64-linux/openssl-native/1.1.1k-r0/temp/run.do_configure.32031, line 143
> >         #2: main, /overflow/mac/nobackup/git/oe-core/build/tmp-glibc/work/x86_64-linux/openssl-native/1.1.1k-r0/temp/run.do_configure.32031, line 221
> > 
> > Backtrace (metadata-relative locations):
> >         #1: do_configure, /overflow/mac/nobackup/git/oe-core/meta/recipes-connectivity/openssl/openssl_1.1.1k.bb, line 78
> > ERROR: Logfile of failure stored in: /overflow/mac/nobackup/git/oe-core/build/tmp-glibc/work/x86_64-linux/openssl-native/1.1.1k-r0/temp/log.do_configure.32031
> > Log data follows:
> > > DEBUG: Executing python function extend_recipe_sysroot
> > > NOTE: Direct dependencies are ['/overflow/mac/nobackup/git/oe-core/meta/recipes-devtools/quilt/quilt-native_0.66.bb:do_populate_sysroot']
> > > NOTE: Installed into sysroot: []
> > > NOTE: Skipping as already exists in sysroot: ['quilt-native']
> > > DEBUG: Python function extend_recipe_sysroot finished
> > > DEBUG: Executing shell function do_configure
> > > an error
> > > WARNING: /overflow/mac/nobackup/git/oe-core/build/tmp-glibc/work/x86_64-linux/openssl-native/1.1.1k-r0/temp/run.do_configure.32031:143 exit 1 from 'false'
> > > WARNING: Backtrace (BB generated script):
> > >       #1: do_configure, /overflow/mac/nobackup/git/oe-core/build/tmp-glibc/work/x86_64-linux/openssl-native/1.1.1k-r0/temp/run.do_configure.32031, line 143
> > >       #2: main, /overflow/mac/nobackup/git/oe-core/build/tmp-glibc/work/x86_64-linux/openssl-native/1.1.1k-r0/temp/run.do_configure.32031, line 221
> > > ERROR: Execution of '/overflow/mac/nobackup/git/oe-core/build/tmp-glibc/work/x86_64-linux/openssl-native/1.1.1k-r0/temp/run.do_configure.32031' failed with exit code 1:
> > > an error
> > > WARNING: /overflow/mac/nobackup/git/oe-core/build/tmp-glibc/work/x86_64-linux/openssl-native/1.1.1k-r0/temp/run.do_configure.32031:143 exit 1 from 'false'
> > > WARNING: Backtrace (BB generated script):
> > >       #1: do_configure, /overflow/mac/nobackup/git/oe-core/build/tmp-glibc/work/x86_64-linux/openssl-native/1.1.1k-r0/temp/run.do_configure.32031, line 143
> > >       #2: main, /overflow/mac/nobackup/git/oe-core/build/tmp-glibc/work/x86_64-linux/openssl-native/1.1.1k-r0/temp/run.do_configure.32031, line 221
> > > 
> > > Backtrace (metadata-relative locations):
> > >       #1: do_configure, /overflow/mac/nobackup/git/oe-core/meta/recipes-connectivity/openssl/openssl_1.1.1k.bb, line 78
> > ERROR: Task (virtual:native:/overflow/mac/nobackup/git/oe-core/meta/recipes-connectivity/openssl/openssl_1.1.1k.bb:do_configure) failed with exit code '1'
> > NOTE: Tasks Summary: Attempted 14 tasks of which 13 didn't need to be rerun and 1 failed.
> > -->8--
> > 
> > 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.
> > 
> > Does anyone know what the proper fix for this might be?
> 
> Thanks for the report and analysis. I think we should do something about it
> but having stared at the code a bit, I'm still not entirely sure what. I think
> the trouble is the error is being reported at mutliple levels in the code
> and we;re a bit paranoid about doing that as there is nothing worse than
> a failure where the traceback isn't shown.
> 
> I'll have to stare at it a bit more but wanted you to know I've at least
> looked at it and agree we should try and do something...

Thanks for looking at it. I did plan to try to dig further into it after
Ross's response, but haven't had a chance yet. If even you're not sure what
the right thing to do is then I don't have any great hopes that I'll be
able to solve it!

Thanks.

Mike.