Error logging broken with next?

Error logging broken with next?

[Jan Kiszka]

Hi,

I vaguely recall that you, Baurzhan, told me that logs of failing tasks
are not always dumped, right? I'm on current next now, building breaking
kernels, and all I get now is our useless python backtrace, always. All
is fine with log.do_dpkg_build, though. Is that the issue? Very annoying
and a no-go for CI. No time to bisect ATM, unfortunately.

Jan

-- 
Siemens AG, Technology
Competence Center Embedded Linux

Re: Error logging broken with next?

[Baurzhan Ismagulov]

On Fri, May 13, 2022 at 06:49:37PM +0200, Jan Kiszka wrote:
> I vaguely recall that you, Baurzhan, told me that logs of failing tasks
> are not always dumped, right? I'm on current next now, building breaking
> kernels, and all I get now is our useless python backtrace, always. All
> is fine with log.do_dpkg_build, though. Is that the issue? Very annoying
> and a no-go for CI. No time to bisect ATM, unfortunately.

Can you provide some details for reproducing? Failure during make, or failure
in the recipe?

If you are running ci_build.sh -d, the complete bitbake output should be
visible in stdout.

If you are running ci_build.sh without -d, only a brief testcase list (1/23
repro pass) is shown for passing testcases. For failing testcases, stderr is
dumped. One issue here is that bitbake captures stderr of its children and
prints that to stdout, by design
(https://lists.openembedded.org/g/bitbake-devel/message/13640). We are
evaluating dumping bitbake stdout + stderr in this case.

With kind regards,
Baurzhan.

Re: Error logging broken with next?

[Jan Kiszka]

On 16.05.22 09:49, Baurzhan Ismagulov wrote:
> On Fri, May 13, 2022 at 06:49:37PM +0200, Jan Kiszka wrote:
>> I vaguely recall that you, Baurzhan, told me that logs of failing tasks
>> are not always dumped, right? I'm on current next now, building breaking
>> kernels, and all I get now is our useless python backtrace, always. All
>> is fine with log.do_dpkg_build, though. Is that the issue? Very annoying
>> and a no-go for CI. No time to bisect ATM, unfortunately.
> 
> Can you provide some details for reproducing? Failure during make, or failure
> in the recipe?

Build failure during a custom kernel build. Or a dependency error during
final image installation.

> 
> If you are running ci_build.sh -d, the complete bitbake output should be
> visible in stdout.
> 
> If you are running ci_build.sh without -d, only a brief testcase list (1/23
> repro pass) is shown for passing testcases. For failing testcases, stderr is
> dumped. One issue here is that bitbake captures stderr of its children and
> prints that to stdout, by design
> (https://lists.openembedded.org/g/bitbake-devel/message/13640). We are
> evaluating dumping bitbake stdout + stderr in this case.

This is not CI, it's a downstream layer consuming Isar.

I can look into reproducing cleanly the next days only. The layer I used
is unfortunately not yet public, but it was started from scratch,
standard kas-container setup, no bells or whistles. So I expect things
to be reproducible in Isar as well.

Jan

-- 
Siemens AG, Technology
Competence Center Embedded Linux

Re: Error logging broken with next?

[Anton Mikanovich]

13.05.2022 19:49, Jan Kiszka wrote:
> Hi,
>
> I vaguely recall that you, Baurzhan, told me that logs of failing tasks
> are not always dumped, right? I'm on current next now, building breaking
> kernels, and all I get now is our useless python backtrace, always. All
> is fine with log.do_dpkg_build, though. Is that the issue? Very annoying
> and a no-go for CI. No time to bisect ATM, unfortunately.
>
> Jan
>
Hello,

Thanks for reporting.
I've reproduced the issue on the latest next and also see the full log 
is still there on v0.8
Will try to bisect to find the reason (bitbake update?).

Re: Error logging broken with next?

[Anton Mikanovich]

17.05.2022 15:35, Anton Mikanovich wrote:
> 13.05.2022 19:49, Jan Kiszka wrote:
>> Hi,
>>
>> I vaguely recall that you, Baurzhan, told me that logs of failing tasks
>> are not always dumped, right? I'm on current next now, building breaking
>> kernels, and all I get now is our useless python backtrace, always. All
>> is fine with log.do_dpkg_build, though. Is that the issue? Very annoying
>> and a no-go for CI. No time to bisect ATM, unfortunately.
>>
>> Jan
>>
> Hello,
>
> Thanks for reporting.
> I've reproduced the issue on the latest next and also see the full log 
> is still there on v0.8
> Will try to bisect to find the reason (bitbake update?).
>
So, that's all about
https://github.com/openembedded/bitbake/commit/cf864cd84172f605b0e1777c3defc000fa3a7379
(included in bitbake 1.50.4)

Re: Error logging broken with next?

[Jan Kiszka]

On 17.05.22 15:42, Anton Mikanovich wrote:
> 17.05.2022 15:35, Anton Mikanovich wrote:
>> 13.05.2022 19:49, Jan Kiszka wrote:
>>> Hi,
>>>
>>> I vaguely recall that you, Baurzhan, told me that logs of failing tasks
>>> are not always dumped, right? I'm on current next now, building breaking
>>> kernels, and all I get now is our useless python backtrace, always. All
>>> is fine with log.do_dpkg_build, though. Is that the issue? Very annoying
>>> and a no-go for CI. No time to bisect ATM, unfortunately.
>>>
>>> Jan
>>>
>> Hello,
>>
>> Thanks for reporting.
>> I've reproduced the issue on the latest next and also see the full log
>> is still there on v0.8
>> Will try to bisect to find the reason (bitbake update?).
>>
> So, that's all about
> https://github.com/openembedded/bitbake/commit/cf864cd84172f605b0e1777c3defc000fa3a7379
> 
> (included in bitbake 1.50.4)
> 

So, already "bitbake ... | cat" causes this issue? Is there any command
line option that avoids this? I wonder what kas could do here without
breaking older versions. And why no one reported this so far from kas'
OE community.

Jan

-- 
Siemens AG, Technology
Competence Center Embedded Linux

Re: Error logging broken with next?

[Jan Kiszka]

On 19.05.22 08:01, Jan Kiszka wrote:
> On 17.05.22 15:42, Anton Mikanovich wrote:
>> 17.05.2022 15:35, Anton Mikanovich wrote:
>>> 13.05.2022 19:49, Jan Kiszka wrote:
>>>> Hi,
>>>>
>>>> I vaguely recall that you, Baurzhan, told me that logs of failing tasks
>>>> are not always dumped, right? I'm on current next now, building breaking
>>>> kernels, and all I get now is our useless python backtrace, always. All
>>>> is fine with log.do_dpkg_build, though. Is that the issue? Very annoying
>>>> and a no-go for CI. No time to bisect ATM, unfortunately.
>>>>
>>>> Jan
>>>>
>>> Hello,
>>>
>>> Thanks for reporting.
>>> I've reproduced the issue on the latest next and also see the full log
>>> is still there on v0.8
>>> Will try to bisect to find the reason (bitbake update?).
>>>
>> So, that's all about
>> https://github.com/openembedded/bitbake/commit/cf864cd84172f605b0e1777c3defc000fa3a7379
>>
>> (included in bitbake 1.50.4)
>>
> 
> So, already "bitbake ... | cat" causes this issue? Is there any command
> line option that avoids this? I wonder what kas could do here without
> breaking older versions. And why no one reported this so far from kas'
> OE community.
> 

It's actually much simpler: Just call "bitbake borken-target" on the 
shell, and you will only get the lengthy backtrace but not log report.

I'm not yet down to the core of the problem, but when you force such a 
failure in upstream poky (today's master), you also get no immediate 
output of bitbake - but then the knotty UI jumps in and does a

Log data follows:
| DEBUG: Executing python function extend_recipe_sysroot
...
| DEBUG: Python function patch_do_patch finished
| DEBUG: Executing shell function do_fix_readlib_c
| FAIL!
| WARNING: exit code 1 from a shell command.
| DEBUG: Python function do_patch finished
ERROR: Task (/poky/meta/recipes-core/glibc/glibc_2.35.bb:do_patch) failed with exit code '1'


I've done this to poky to trigger it:

diff --git a/meta/recipes-core/glibc/glibc_2.35.bb b/meta/recipes-core/glibc/glibc_2.35.bb
index 6ea5b1efb5..9500c8a128 100644
--- a/meta/recipes-core/glibc/glibc_2.35.bb
+++ b/meta/recipes-core/glibc/glibc_2.35.bb
@@ -91,6 +91,8 @@ do_patch:append() {
 }
 
 do_fix_readlib_c () {
+	echo "FAIL!"
+	false
 	sed -i -e 's#OECORE_KNOWN_INTERPRETER_NAMES#${EGLIBC_KNOWN_INTERPRETER_NAMES}#' ${S}/elf/readlib.c
 }
 
Analogous trigger for isar:

diff --git a/meta-isar/recipes-app/example-raw/files/rules b/meta-isar/recipes-app/example-raw/files/rules
index a1167375..ed63d364 100644
--- a/meta-isar/recipes-app/example-raw/files/rules
+++ b/meta-isar/recipes-app/example-raw/files/rules
@@ -5,4 +5,5 @@
 # we do violate debian quality rules here, but on purpose to demo how
 # to deal with it
 override_dh_usrlocal:
-	true
+	echo "FAIL!"
+	false

So, Isar has a bug here of not letting knotty (as default UI) do its 
job it seems to me. Didn't this work before? Didn't we also have those 
duplicate dumps in the past that upstream bitbake seem to have resolved 
now?


BTW, I've received first reports of this bug from the field today. We 
must fix this before the release, or our users will kill us.

Jan

-- 
Siemens AG, Technology
Competence Center Embedded Linux

Re: Error logging broken with next?

[Anton Mikanovich]

23.05.2022 22:06, Jan Kiszka wrote:
> It's actually much simpler: Just call "bitbake borken-target" on the
> shell, and you will only get the lengthy backtrace but not log report.
>
> I'm not yet down to the core of the problem, but when you force such a
> failure in upstream poky (today's master), you also get no immediate
> output of bitbake - but then the knotty UI jumps in and does a
>
> Log data follows:
> | DEBUG: Executing python function extend_recipe_sysroot
> ...
> | DEBUG: Python function patch_do_patch finished
> | DEBUG: Executing shell function do_fix_readlib_c
> | FAIL!
> | WARNING: exit code 1 from a shell command.
> | DEBUG: Python function do_patch finished
> ERROR: Task (/poky/meta/recipes-core/glibc/glibc_2.35.bb:do_patch) failed with exit code '1'
>
>
> I've done this to poky to trigger it:
>
> diff --git a/meta/recipes-core/glibc/glibc_2.35.bb b/meta/recipes-core/glibc/glibc_2.35.bb
> index 6ea5b1efb5..9500c8a128 100644
> --- a/meta/recipes-core/glibc/glibc_2.35.bb
> +++ b/meta/recipes-core/glibc/glibc_2.35.bb
> @@ -91,6 +91,8 @@ do_patch:append() {
>   }
>   
>   do_fix_readlib_c () {
> +	echo "FAIL!"
> +	false
>   	sed -i -e 's#OECORE_KNOWN_INTERPRETER_NAMES#${EGLIBC_KNOWN_INTERPRETER_NAMES}#' ${S}/elf/readlib.c
>   }
>   
> Analogous trigger for isar:
>
> diff --git a/meta-isar/recipes-app/example-raw/files/rules b/meta-isar/recipes-app/example-raw/files/rules
> index a1167375..ed63d364 100644
> --- a/meta-isar/recipes-app/example-raw/files/rules
> +++ b/meta-isar/recipes-app/example-raw/files/rules
> @@ -5,4 +5,5 @@
>   # we do violate debian quality rules here, but on purpose to demo how
>   # to deal with it
>   override_dh_usrlocal:
> -	true
> +	echo "FAIL!"
> +	false
>
> So, Isar has a bug here of not letting knotty (as default UI) do its
> job it seems to me. Didn't this work before? Didn't we also have those
> duplicate dumps in the past that upstream bitbake seem to have resolved
> now?
>
>
> BTW, I've received first reports of this bug from the field today. We
> must fix this before the release, or our users will kill us.
>
> Jan
>
Hello Jan,
Thanks for example.
The question is how the same bitbake version can work it different ways 
for Yocto and Isar.
I will try to dig in and let you know if found something.

Re: Error logging broken with next?

[Anton Mikanovich]

23.05.2022 22:06, Jan Kiszka wrote:
> It's actually much simpler: Just call "bitbake borken-target" on the
> shell, and you will only get the lengthy backtrace but not log report.
>
> I'm not yet down to the core of the problem, but when you force such a
> failure in upstream poky (today's master), you also get no immediate
> output of bitbake - but then the knotty UI jumps in and does a
>
> Log data follows:
> | DEBUG: Executing python function extend_recipe_sysroot
> ...
> | DEBUG: Python function patch_do_patch finished
> | DEBUG: Executing shell function do_fix_readlib_c
> | FAIL!
> | WARNING: exit code 1 from a shell command.
> | DEBUG: Python function do_patch finished
> ERROR: Task (/poky/meta/recipes-core/glibc/glibc_2.35.bb:do_patch) failed with exit code '1'
>
>
> I've done this to poky to trigger it:
>
> diff --git a/meta/recipes-core/glibc/glibc_2.35.bb b/meta/recipes-core/glibc/glibc_2.35.bb
> index 6ea5b1efb5..9500c8a128 100644
> --- a/meta/recipes-core/glibc/glibc_2.35.bb
> +++ b/meta/recipes-core/glibc/glibc_2.35.bb
> @@ -91,6 +91,8 @@ do_patch:append() {
>   }
>   
>   do_fix_readlib_c () {
> +	echo "FAIL!"
> +	false
>   	sed -i -e 's#OECORE_KNOWN_INTERPRETER_NAMES#${EGLIBC_KNOWN_INTERPRETER_NAMES}#' ${S}/elf/readlib.c
>   }
>   
> Analogous trigger for isar:
>
> diff --git a/meta-isar/recipes-app/example-raw/files/rules b/meta-isar/recipes-app/example-raw/files/rules
> index a1167375..ed63d364 100644
> --- a/meta-isar/recipes-app/example-raw/files/rules
> +++ b/meta-isar/recipes-app/example-raw/files/rules
> @@ -5,4 +5,5 @@
>   # we do violate debian quality rules here, but on purpose to demo how
>   # to deal with it
>   override_dh_usrlocal:
> -	true
> +	echo "FAIL!"
> +	false
>
> So, Isar has a bug here of not letting knotty (as default UI) do its
> job it seems to me. Didn't this work before? Didn't we also have those
> duplicate dumps in the past that upstream bitbake seem to have resolved
> now?
>
>
> BTW, I've received first reports of this bug from the field today. We
> must fix this before the release, or our users will kill us.
>
> Jan
>
I didn't find any differences between Yocto and Isar.
If putting glibc_2.35.bb change example into Isar it behaves in the same way
outputting full error log.
Otherwise if executing the second example in Yocto (running bash code from
python task with bb.build.exec_func) it will output only exception message
just like Isar.
So there are no issues in Isar itself, it behaves just like Yocto.
If we need to have full log printed Bitbake should be fixed.

Re: Error logging broken with next?

[Jan Kiszka]

On 24.05.22 16:23, Anton Mikanovich wrote:
> 23.05.2022 22:06, Jan Kiszka wrote:
>> It's actually much simpler: Just call "bitbake borken-target" on the
>> shell, and you will only get the lengthy backtrace but not log report.
>>
>> I'm not yet down to the core of the problem, but when you force such a
>> failure in upstream poky (today's master), you also get no immediate
>> output of bitbake - but then the knotty UI jumps in and does a
>>
>> Log data follows:
>> | DEBUG: Executing python function extend_recipe_sysroot
>> ...
>> | DEBUG: Python function patch_do_patch finished
>> | DEBUG: Executing shell function do_fix_readlib_c
>> | FAIL!
>> | WARNING: exit code 1 from a shell command.
>> | DEBUG: Python function do_patch finished
>> ERROR: Task (/poky/meta/recipes-core/glibc/glibc_2.35.bb:do_patch)
>> failed with exit code '1'
>>
>>
>> I've done this to poky to trigger it:
>>
>> diff --git a/meta/recipes-core/glibc/glibc_2.35.bb
>> b/meta/recipes-core/glibc/glibc_2.35.bb
>> index 6ea5b1efb5..9500c8a128 100644
>> --- a/meta/recipes-core/glibc/glibc_2.35.bb
>> +++ b/meta/recipes-core/glibc/glibc_2.35.bb
>> @@ -91,6 +91,8 @@ do_patch:append() {
>>   }
>>     do_fix_readlib_c () {
>> +    echo "FAIL!"
>> +    false
>>       sed -i -e
>> 's#OECORE_KNOWN_INTERPRETER_NAMES#${EGLIBC_KNOWN_INTERPRETER_NAMES}#'
>> ${S}/elf/readlib.c
>>   }
>>   Analogous trigger for isar:
>>
>> diff --git a/meta-isar/recipes-app/example-raw/files/rules
>> b/meta-isar/recipes-app/example-raw/files/rules
>> index a1167375..ed63d364 100644
>> --- a/meta-isar/recipes-app/example-raw/files/rules
>> +++ b/meta-isar/recipes-app/example-raw/files/rules
>> @@ -5,4 +5,5 @@
>>   # we do violate debian quality rules here, but on purpose to demo how
>>   # to deal with it
>>   override_dh_usrlocal:
>> -    true
>> +    echo "FAIL!"
>> +    false
>>
>> So, Isar has a bug here of not letting knotty (as default UI) do its
>> job it seems to me. Didn't this work before? Didn't we also have those
>> duplicate dumps in the past that upstream bitbake seem to have resolved
>> now?
>>
>>
>> BTW, I've received first reports of this bug from the field today. We
>> must fix this before the release, or our users will kill us.
>>
>> Jan
>>
> I didn't find any differences between Yocto and Isar.
> If putting glibc_2.35.bb change example into Isar it behaves in the same
> way
> outputting full error log.
> Otherwise if executing the second example in Yocto (running bash code from
> python task with bb.build.exec_func) it will output only exception message
> just like Isar.
> So there are no issues in Isar itself, it behaves just like Yocto.
> If we need to have full log printed Bitbake should be fixed.
> 

Ok, then the environment of the glibc case is not the same as our for
the dpkg_runbuild. The latter is broken, and we need to understand how
to restore its output in Isar - very likely not in bitbake.

Jan

-- 
Siemens AG, Technology
Competence Center Embedded Linux

Re: Error logging broken with next?

[Jan Kiszka]

On 24.05.22 17:54, Jan Kiszka wrote:
> On 24.05.22 16:23, Anton Mikanovich wrote:
>> 23.05.2022 22:06, Jan Kiszka wrote:
>>> It's actually much simpler: Just call "bitbake borken-target" on the
>>> shell, and you will only get the lengthy backtrace but not log report.
>>>
>>> I'm not yet down to the core of the problem, but when you force such a
>>> failure in upstream poky (today's master), you also get no immediate
>>> output of bitbake - but then the knotty UI jumps in and does a
>>>
>>> Log data follows:
>>> | DEBUG: Executing python function extend_recipe_sysroot
>>> ...
>>> | DEBUG: Python function patch_do_patch finished
>>> | DEBUG: Executing shell function do_fix_readlib_c
>>> | FAIL!
>>> | WARNING: exit code 1 from a shell command.
>>> | DEBUG: Python function do_patch finished
>>> ERROR: Task (/poky/meta/recipes-core/glibc/glibc_2.35.bb:do_patch)
>>> failed with exit code '1'
>>>
>>>
>>> I've done this to poky to trigger it:
>>>
>>> diff --git a/meta/recipes-core/glibc/glibc_2.35.bb
>>> b/meta/recipes-core/glibc/glibc_2.35.bb
>>> index 6ea5b1efb5..9500c8a128 100644
>>> --- a/meta/recipes-core/glibc/glibc_2.35.bb
>>> +++ b/meta/recipes-core/glibc/glibc_2.35.bb
>>> @@ -91,6 +91,8 @@ do_patch:append() {
>>>   }
>>>     do_fix_readlib_c () {
>>> +    echo "FAIL!"
>>> +    false
>>>       sed -i -e
>>> 's#OECORE_KNOWN_INTERPRETER_NAMES#${EGLIBC_KNOWN_INTERPRETER_NAMES}#'
>>> ${S}/elf/readlib.c
>>>   }
>>>   Analogous trigger for isar:
>>>
>>> diff --git a/meta-isar/recipes-app/example-raw/files/rules
>>> b/meta-isar/recipes-app/example-raw/files/rules
>>> index a1167375..ed63d364 100644
>>> --- a/meta-isar/recipes-app/example-raw/files/rules
>>> +++ b/meta-isar/recipes-app/example-raw/files/rules
>>> @@ -5,4 +5,5 @@
>>>   # we do violate debian quality rules here, but on purpose to demo how
>>>   # to deal with it
>>>   override_dh_usrlocal:
>>> -    true
>>> +    echo "FAIL!"
>>> +    false
>>>
>>> So, Isar has a bug here of not letting knotty (as default UI) do its
>>> job it seems to me. Didn't this work before? Didn't we also have those
>>> duplicate dumps in the past that upstream bitbake seem to have resolved
>>> now?
>>>
>>>
>>> BTW, I've received first reports of this bug from the field today. We
>>> must fix this before the release, or our users will kill us.
>>>
>>> Jan
>>>
>> I didn't find any differences between Yocto and Isar.
>> If putting glibc_2.35.bb change example into Isar it behaves in the same
>> way
>> outputting full error log.
>> Otherwise if executing the second example in Yocto (running bash code from
>> python task with bb.build.exec_func) it will output only exception message
>> just like Isar.
>> So there are no issues in Isar itself, it behaves just like Yocto.
>> If we need to have full log printed Bitbake should be fixed.
>>
> 
> Ok, then the environment of the glibc case is not the same as our for
> the dpkg_runbuild. The latter is broken, and we need to understand how
> to restore its output in Isar - very likely not in bitbake.
> 

Just thinking loudly: Is it our try-finally that changes the output
trigger for knotty?

    try:
        bb.build.exec_func("dpkg_runbuild", d)
    finally:
        bb.build.exec_func("dpkg_undo_mounts", d)
        bb.utils.unlockfile(lock)

Jan

-- 
Siemens AG, Technology
Competence Center Embedded Linux

Re: Error logging broken with next?

[Anton Mikanovich]

24.05.2022 18:54, Jan Kiszka wrote:
> Ok, then the environment of the glibc case is not the same as our for
> the dpkg_runbuild. The latter is broken, and we need to understand how
> to restore its output in Isar - very likely not in bitbake.
>
> Jan
>
This is not about the environment, but because the task is in python and 
bash
part is executed with bb.build.exec_func API. You can easily test it in 
Yocto
with the following example:

test_fun() {
     echo "FAIL!"
     false
}

python do_test() {
     bb.build.exec_func("test_fun", d)
}
addtask test

$ bitbake -c do_test recipename

Re: Error logging broken with next?

[Anton Mikanovich]

24.05.2022 18:57, Jan Kiszka wrote:
> Just thinking loudly: Is it our try-finally that changes the output
> trigger for knotty?
>
>      try:
>          bb.build.exec_func("dpkg_runbuild", d)
>      finally:
>          bb.build.exec_func("dpkg_undo_mounts", d)
>          bb.utils.unlockfile(lock)
>
> Jan
>
No, this is not because of try-finally itself, but because of exec_func API.
Look at my previous mail.

Re: Error logging broken with next?

[Jan Kiszka]

On 24.05.22 18:05, Anton Mikanovich wrote:
> 24.05.2022 18:57, Jan Kiszka wrote:
>> Just thinking loudly: Is it our try-finally that changes the output
>> trigger for knotty?
>>
>>      try:
>>          bb.build.exec_func("dpkg_runbuild", d)
>>      finally:
>>          bb.build.exec_func("dpkg_undo_mounts", d)
>>          bb.utils.unlockfile(lock)
>>
>> Jan
>>
> No, this is not because of try-finally itself, but because of exec_func
> API.
> Look at my previous mail.
> 

But that is just the same with glibc, and that worked fine in poky
during my test yesterday, ie. produced the correct dump.

Jan

-- 
Siemens AG, Technology
Competence Center Embedded Linux

Re: Error logging broken with next?

[Anton Mikanovich]

24.05.2022 19:07, Jan Kiszka wrote:
> On 24.05.22 18:05, Anton Mikanovich wrote:
>> 24.05.2022 18:57, Jan Kiszka wrote:
>>> Just thinking loudly: Is it our try-finally that changes the output
>>> trigger for knotty?
>>>
>>>       try:
>>>           bb.build.exec_func("dpkg_runbuild", d)
>>>       finally:
>>>           bb.build.exec_func("dpkg_undo_mounts", d)
>>>           bb.utils.unlockfile(lock)
>>>
>>> Jan
>>>
>> No, this is not because of try-finally itself, but because of exec_func
>> API.
>> Look at my previous mail.
>>
> But that is just the same with glibc, and that worked fine in poky
> during my test yesterday, ie. produced the correct dump.
>
> Jan
>
No, in "glibc" example failed code is executed from the bash task.
And bb.build.exec_func is python API called from python task.
This is not the same.

As I previously said, there is no difference between Yocto and Isar:
1) fail in bash task generates full log
2) fail in bash code called from python task generates masked log

Please try do_test example from one of the previous mails on Yocto.

Re: Error logging broken with next?

[Jan Kiszka]

On 24.05.22 18:14, Anton Mikanovich wrote:
> 24.05.2022 19:07, Jan Kiszka wrote:
>> On 24.05.22 18:05, Anton Mikanovich wrote:
>>> 24.05.2022 18:57, Jan Kiszka wrote:
>>>> Just thinking loudly: Is it our try-finally that changes the output
>>>> trigger for knotty?
>>>>
>>>>       try:
>>>>           bb.build.exec_func("dpkg_runbuild", d)
>>>>       finally:
>>>>           bb.build.exec_func("dpkg_undo_mounts", d)
>>>>           bb.utils.unlockfile(lock)
>>>>
>>>> Jan
>>>>
>>> No, this is not because of try-finally itself, but because of exec_func
>>> API.
>>> Look at my previous mail.
>>>
>> But that is just the same with glibc, and that worked fine in poky
>> during my test yesterday, ie. produced the correct dump.
>>
>> Jan
>>
> No, in "glibc" example failed code is executed from the bash task.
> And bb.build.exec_func is python API called from python task.
> This is not the same.
> 
> As I previously said, there is no difference between Yocto and Isar:
> 1) fail in bash task generates full log
> 2) fail in bash code called from python task generates masked log
> 
> Please try do_test example from one of the previous mails on Yocto.
> 

I'm afraid we are talking past each other. This is what I retried again:

$ . oe-init-build-env build

recipe.bb:
LICENSE = ""

test_fun() {
    echo "FAIL!"
    false
}

python do_test() {
    bb.build.exec_func("test_fun", d)
}
addtask test

conf/local.conf:
...

BBFILES += "recipe.bb"


$ bitbake -c test recipe
...
NOTE: No setscene tasks
NOTE: Executing Tasks
ERROR: recipe-1.0-r0 do_test: ExecutionError('/poky-build/tmp/work/core2-64-poky-linux/recipe/1.0-r0/temp/run.test_fun.260', 1, None, None)
ERROR: Logfile of failure stored in: /poky-build/tmp/work/core2-64-poky-linux/recipe/1.0-r0/temp/log.do_test.260
Log data follows:
| DEBUG: Executing python function do_test
| DEBUG: Executing shell function test_fun
| FAIL!
| WARNING: exit code 1 from a shell command.
| DEBUG: Python function do_test finished
ERROR: Task (recipe.bb:do_test) failed with exit code '1'
NOTE: Tasks Summary: Attempted 1 tasks of which 0 didn't need to be rerun and 1 failed.

Summary: 1 task failed:
  recipe.bb:do_test
Summary: There was 1 ERROR message, returning a non-zero exit code.

All fine for me.

Is this what you saw as well?


Now with Isar, using isar-init-build-env instead:
...
NOTE: No setscene tasks
NOTE: Executing Tasks
ERROR: recipe-1.0-r0 do_test: Error executing a python function in exec_python_func() autogenerated:

The stack trace of python calls that resulted in this exception/failure was:
File: 'exec_python_func() autogenerated', lineno: 2, function: <module>
     0001:
 *** 0002:do_test(d)
     0003:
File: 'recipe.bb', lineno: 9, function: do_test
  File "recipe.bb", line 9, in do_test
    bb.build.exec_func("test_fun", d)

File: '/isar/bitbake/lib/bb/build.py', lineno: 256, function: exec_func
     0252:    with bb.utils.fileslocked(lockfiles):
     0253:        if ispython:
     0254:            exec_func_python(func, d, runfile, cwd=adir)
     0255:        else:
 *** 0256:            exec_func_shell(func, d, runfile, cwd=adir)
     0257:
     0258:    try:
     0259:        curcwd = os.getcwd()
     0260:    except:
File: '/isar/bitbake/lib/bb/build.py', lineno: 507, function: exec_func_shell
     0503:    with open(fifopath, 'r+b', buffering=0) as fifo:
     0504:        try:
     0505:            bb.debug(2, "Executing shell function %s" % func)
     0506:            with open(os.devnull, 'r+') as stdin, logfile:
 *** 0507:                bb.process.run(cmd, shell=False, stdin=stdin, log=logfile, extrafiles=[(fifo,readfifo)])
     0508:        except bb.process.ExecutionError as exe:
     0509:            # Find the backtrace that the shell trap generated
     0510:            backtrace_marker_regex = re.compile(r"WARNING: Backtrace \(BB generated script\)")
     0511:            stdout_lines = (exe.stdout or "").split("\n")
File: '/isar/bitbake/lib/bb/process.py', lineno: 186, function: run
     0182:
     0183:    if pipe.returncode != 0:
     0184:        if log:
     0185:            # Don't duplicate the output in the exception if logging it
 *** 0186:            raise ExecutionError(cmd, pipe.returncode, None, None)
     0187:        raise ExecutionError(cmd, pipe.returncode, stdout, stderr)
     0188:    return stdout, stderr
Exception: bb.process.ExecutionError: Execution of '/isar-build/tmp/work/debian-bullseye-armhf/recipe/1.0-r0/temp/run.test_fun.1487' failed with exit code 1

ERROR: Logfile of failure stored in: /isar-build/tmp/work/debian-bullseye-armhf/recipe/1.0-r0/temp/log.do_test.1487
ERROR: Task (recipe.bb:do_test) failed with exit code '1'
NOTE: Tasks Summary: Attempted 1 tasks of which 0 didn't need to be rerun and 1 failed.

Summary: 1 task failed:
  recipe.bb:do_test
Summary: There was 1 ERROR message shown, returning a non-zero exit code.


This is NOT what we want to have. And this is an Isar bug at this level.

Jan

-- 
Siemens AG, Technology
Competence Center Embedded Linux

Re: Error logging broken with next?

[Anton Mikanovich]

24.05.2022 19:36, Jan Kiszka wrote:
> I'm afraid we are talking past each other. This is what I retried again:
> $ . oe-init-build-env build
>
> recipe.bb:
> LICENSE = ""
>
> test_fun() {
>      echo "FAIL!"
>      false
> }
>
> python do_test() {
>      bb.build.exec_func("test_fun", d)
> }
> addtask test
>
> conf/local.conf:
> ...
>
> BBFILES += "recipe.bb"
>
>
> $ bitbake -c test recipe
> ...
> NOTE: No setscene tasks
> NOTE: Executing Tasks
> ERROR: recipe-1.0-r0 do_test: ExecutionError('/poky-build/tmp/work/core2-64-poky-linux/recipe/1.0-r0/temp/run.test_fun.260', 1, None, None)
> ERROR: Logfile of failure stored in: /poky-build/tmp/work/core2-64-poky-linux/recipe/1.0-r0/temp/log.do_test.260
> Log data follows:
> | DEBUG: Executing python function do_test
> | DEBUG: Executing shell function test_fun
> | FAIL!
> | WARNING: exit code 1 from a shell command.
> | DEBUG: Python function do_test finished
> ERROR: Task (recipe.bb:do_test) failed with exit code '1'
> NOTE: Tasks Summary: Attempted 1 tasks of which 0 didn't need to be rerun and 1 failed.
>
> Summary: 1 task failed:
>    recipe.bb:do_test
> Summary: There was 1 ERROR message, returning a non-zero exit code.
>
> All fine for me.
>
> Is this what you saw as well?
Hmm... no.
What Yocto/Bitbake version did you use?
I'm using Yocto 3.4 based on Bitbake 1.52.0 as the most similar to the 
version we use in Isar (1.50.5).
And in Yocto 3.4 there is no log for that example.
> Now with Isar, using isar-init-build-env instead:
> ...
> NOTE: No setscene tasks
> NOTE: Executing Tasks
> ERROR: recipe-1.0-r0 do_test: Error executing a python function in exec_python_func() autogenerated:
>
> The stack trace of python calls that resulted in this exception/failure was:
> File: 'exec_python_func() autogenerated', lineno: 2, function: <module>
>       0001:
>   *** 0002:do_test(d)
>       0003:
> File: 'recipe.bb', lineno: 9, function: do_test
>    File "recipe.bb", line 9, in do_test
>      bb.build.exec_func("test_fun", d)
>
> File: '/isar/bitbake/lib/bb/build.py', lineno: 256, function: exec_func
>       0252:    with bb.utils.fileslocked(lockfiles):
>       0253:        if ispython:
>       0254:            exec_func_python(func, d, runfile, cwd=adir)
>       0255:        else:
>   *** 0256:            exec_func_shell(func, d, runfile, cwd=adir)
>       0257:
>       0258:    try:
>       0259:        curcwd = os.getcwd()
>       0260:    except:
> File: '/isar/bitbake/lib/bb/build.py', lineno: 507, function: exec_func_shell
>       0503:    with open(fifopath, 'r+b', buffering=0) as fifo:
>       0504:        try:
>       0505:            bb.debug(2, "Executing shell function %s" % func)
>       0506:            with open(os.devnull, 'r+') as stdin, logfile:
>   *** 0507:                bb.process.run(cmd, shell=False, stdin=stdin, log=logfile, extrafiles=[(fifo,readfifo)])
>       0508:        except bb.process.ExecutionError as exe:
>       0509:            # Find the backtrace that the shell trap generated
>       0510:            backtrace_marker_regex = re.compile(r"WARNING: Backtrace \(BB generated script\)")
>       0511:            stdout_lines = (exe.stdout or "").split("\n")
> File: '/isar/bitbake/lib/bb/process.py', lineno: 186, function: run
>       0182:
>       0183:    if pipe.returncode != 0:
>       0184:        if log:
>       0185:            # Don't duplicate the output in the exception if logging it
>   *** 0186:            raise ExecutionError(cmd, pipe.returncode, None, None)
>       0187:        raise ExecutionError(cmd, pipe.returncode, stdout, stderr)
>       0188:    return stdout, stderr
> Exception: bb.process.ExecutionError: Execution of '/isar-build/tmp/work/debian-bullseye-armhf/recipe/1.0-r0/temp/run.test_fun.1487' failed with exit code 1
>
> ERROR: Logfile of failure stored in: /isar-build/tmp/work/debian-bullseye-armhf/recipe/1.0-r0/temp/log.do_test.1487
> ERROR: Task (recipe.bb:do_test) failed with exit code '1'
> NOTE: Tasks Summary: Attempted 1 tasks of which 0 didn't need to be rerun and 1 failed.
>
> Summary: 1 task failed:
>    recipe.bb:do_test
> Summary: There was 1 ERROR message shown, returning a non-zero exit code.
>
>
> This is NOT what we want to have. And this is an Isar bug at this level.
>
> Jan
>

Re: Error logging broken with next?

[Anton Mikanovich]

24.05.2022 22:50, Anton Mikanovich wrote:
> 24.05.2022 19:36, Jan Kiszka wrote:
>> I'm afraid we are talking past each other. This is what I retried again:
>> $ . oe-init-build-env build
>>
>> recipe.bb:
>> LICENSE = ""
>>
>> test_fun() {
>>      echo "FAIL!"
>>      false
>> }
>>
>> python do_test() {
>>      bb.build.exec_func("test_fun", d)
>> }
>> addtask test
>>
>> conf/local.conf:
>> ...
>>
>> BBFILES += "recipe.bb"
>>
>>
>> $ bitbake -c test recipe
>> ...
>> NOTE: No setscene tasks
>> NOTE: Executing Tasks
>> ERROR: recipe-1.0-r0 do_test: 
>> ExecutionError('/poky-build/tmp/work/core2-64-poky-linux/recipe/1.0-r0/temp/run.test_fun.260', 
>> 1, None, None)
>> ERROR: Logfile of failure stored in: 
>> /poky-build/tmp/work/core2-64-poky-linux/recipe/1.0-r0/temp/log.do_test.260
>> Log data follows:
>> | DEBUG: Executing python function do_test
>> | DEBUG: Executing shell function test_fun
>> | FAIL!
>> | WARNING: exit code 1 from a shell command.
>> | DEBUG: Python function do_test finished
>> ERROR: Task (recipe.bb:do_test) failed with exit code '1'
>> NOTE: Tasks Summary: Attempted 1 tasks of which 0 didn't need to be 
>> rerun and 1 failed.
>>
>> Summary: 1 task failed:
>>    recipe.bb:do_test
>> Summary: There was 1 ERROR message, returning a non-zero exit code.
>>
>> All fine for me.
>>
>> Is this what you saw as well?
> Hmm... no.
> What Yocto/Bitbake version did you use?
> I'm using Yocto 3.4 based on Bitbake 1.52.0 as the most similar to the 
> version we use in Isar (1.50.5).
> And in Yocto 3.4 there is no log for that example.
>> Now with Isar, using isar-init-build-env instead:
>> ...
>> NOTE: No setscene tasks
>> NOTE: Executing Tasks
>> ERROR: recipe-1.0-r0 do_test: Error executing a python function in 
>> exec_python_func() autogenerated:
>>
>> The stack trace of python calls that resulted in this 
>> exception/failure was:
>> File: 'exec_python_func() autogenerated', lineno: 2, function: <module>
>>       0001:
>>   *** 0002:do_test(d)
>>       0003:
>> File: 'recipe.bb', lineno: 9, function: do_test
>>    File "recipe.bb", line 9, in do_test
>>      bb.build.exec_func("test_fun", d)
>>
>> File: '/isar/bitbake/lib/bb/build.py', lineno: 256, function: exec_func
>>       0252:    with bb.utils.fileslocked(lockfiles):
>>       0253:        if ispython:
>>       0254:            exec_func_python(func, d, runfile, cwd=adir)
>>       0255:        else:
>>   *** 0256:            exec_func_shell(func, d, runfile, cwd=adir)
>>       0257:
>>       0258:    try:
>>       0259:        curcwd = os.getcwd()
>>       0260:    except:
>> File: '/isar/bitbake/lib/bb/build.py', lineno: 507, function: 
>> exec_func_shell
>>       0503:    with open(fifopath, 'r+b', buffering=0) as fifo:
>>       0504:        try:
>>       0505:            bb.debug(2, "Executing shell function %s" % func)
>>       0506:            with open(os.devnull, 'r+') as stdin, logfile:
>>   *** 0507:                bb.process.run(cmd, shell=False, 
>> stdin=stdin, log=logfile, extrafiles=[(fifo,readfifo)])
>>       0508:        except bb.process.ExecutionError as exe:
>>       0509:            # Find the backtrace that the shell trap 
>> generated
>>       0510:            backtrace_marker_regex = re.compile(r"WARNING: 
>> Backtrace \(BB generated script\)")
>>       0511:            stdout_lines = (exe.stdout or "").split("\n")
>> File: '/isar/bitbake/lib/bb/process.py', lineno: 186, function: run
>>       0182:
>>       0183:    if pipe.returncode != 0:
>>       0184:        if log:
>>       0185:            # Don't duplicate the output in the exception 
>> if logging it
>>   *** 0186:            raise ExecutionError(cmd, pipe.returncode, 
>> None, None)
>>       0187:        raise ExecutionError(cmd, pipe.returncode, stdout, 
>> stderr)
>>       0188:    return stdout, stderr
>> Exception: bb.process.ExecutionError: Execution of 
>> '/isar-build/tmp/work/debian-bullseye-armhf/recipe/1.0-r0/temp/run.test_fun.1487' 
>> failed with exit code 1
>>
>> ERROR: Logfile of failure stored in: 
>> /isar-build/tmp/work/debian-bullseye-armhf/recipe/1.0-r0/temp/log.do_test.1487
>> ERROR: Task (recipe.bb:do_test) failed with exit code '1'
>> NOTE: Tasks Summary: Attempted 1 tasks of which 0 didn't need to be 
>> rerun and 1 failed.
>>
>> Summary: 1 task failed:
>>    recipe.bb:do_test
>> Summary: There was 1 ERROR message shown, returning a non-zero exit 
>> code.
>>
>>
>> This is NOT what we want to have. And this is an Isar bug at this level.
>>
>> Jan
>>
>
Ok, it looks like I've found it.
Did you use Yocto/Bitbake which already include this commit?
https://github.com/openembedded/bitbake/commit/23a6f11b089b14382c21d431edf34fa7224c66bf

Tried to apply on Isar's Bitbake and it works like it should be (error 
log is printed).
So we just need to update BItbake version to at least 1.52.3

Re: Error logging broken with next?

[Jan Kiszka]

On 25.05.22 07:30, Anton Mikanovich wrote:
> 24.05.2022 22:50, Anton Mikanovich wrote:
>> 24.05.2022 19:36, Jan Kiszka wrote:
>>> I'm afraid we are talking past each other. This is what I retried again:
>>> $ . oe-init-build-env build
>>>
>>> recipe.bb:
>>> LICENSE = ""
>>>
>>> test_fun() {
>>>      echo "FAIL!"
>>>      false
>>> }
>>>
>>> python do_test() {
>>>      bb.build.exec_func("test_fun", d)
>>> }
>>> addtask test
>>>
>>> conf/local.conf:
>>> ...
>>>
>>> BBFILES += "recipe.bb"
>>>
>>>
>>> $ bitbake -c test recipe
>>> ...
>>> NOTE: No setscene tasks
>>> NOTE: Executing Tasks
>>> ERROR: recipe-1.0-r0 do_test:
>>> ExecutionError('/poky-build/tmp/work/core2-64-poky-linux/recipe/1.0-r0/temp/run.test_fun.260',
>>> 1, None, None)
>>> ERROR: Logfile of failure stored in:
>>> /poky-build/tmp/work/core2-64-poky-linux/recipe/1.0-r0/temp/log.do_test.260
>>>
>>> Log data follows:
>>> | DEBUG: Executing python function do_test
>>> | DEBUG: Executing shell function test_fun
>>> | FAIL!
>>> | WARNING: exit code 1 from a shell command.
>>> | DEBUG: Python function do_test finished
>>> ERROR: Task (recipe.bb:do_test) failed with exit code '1'
>>> NOTE: Tasks Summary: Attempted 1 tasks of which 0 didn't need to be
>>> rerun and 1 failed.
>>>
>>> Summary: 1 task failed:
>>>    recipe.bb:do_test
>>> Summary: There was 1 ERROR message, returning a non-zero exit code.
>>>
>>> All fine for me.
>>>
>>> Is this what you saw as well?
>> Hmm... no.
>> What Yocto/Bitbake version did you use?
>> I'm using Yocto 3.4 based on Bitbake 1.52.0 as the most similar to the
>> version we use in Isar (1.50.5).
>> And in Yocto 3.4 there is no log for that example.
>>> Now with Isar, using isar-init-build-env instead:
>>> ...
>>> NOTE: No setscene tasks
>>> NOTE: Executing Tasks
>>> ERROR: recipe-1.0-r0 do_test: Error executing a python function in
>>> exec_python_func() autogenerated:
>>>
>>> The stack trace of python calls that resulted in this
>>> exception/failure was:
>>> File: 'exec_python_func() autogenerated', lineno: 2, function: <module>
>>>       0001:
>>>   *** 0002:do_test(d)
>>>       0003:
>>> File: 'recipe.bb', lineno: 9, function: do_test
>>>    File "recipe.bb", line 9, in do_test
>>>      bb.build.exec_func("test_fun", d)
>>>
>>> File: '/isar/bitbake/lib/bb/build.py', lineno: 256, function: exec_func
>>>       0252:    with bb.utils.fileslocked(lockfiles):
>>>       0253:        if ispython:
>>>       0254:            exec_func_python(func, d, runfile, cwd=adir)
>>>       0255:        else:
>>>   *** 0256:            exec_func_shell(func, d, runfile, cwd=adir)
>>>       0257:
>>>       0258:    try:
>>>       0259:        curcwd = os.getcwd()
>>>       0260:    except:
>>> File: '/isar/bitbake/lib/bb/build.py', lineno: 507, function:
>>> exec_func_shell
>>>       0503:    with open(fifopath, 'r+b', buffering=0) as fifo:
>>>       0504:        try:
>>>       0505:            bb.debug(2, "Executing shell function %s" % func)
>>>       0506:            with open(os.devnull, 'r+') as stdin, logfile:
>>>   *** 0507:                bb.process.run(cmd, shell=False,
>>> stdin=stdin, log=logfile, extrafiles=[(fifo,readfifo)])
>>>       0508:        except bb.process.ExecutionError as exe:
>>>       0509:            # Find the backtrace that the shell trap
>>> generated
>>>       0510:            backtrace_marker_regex = re.compile(r"WARNING:
>>> Backtrace \(BB generated script\)")
>>>       0511:            stdout_lines = (exe.stdout or "").split("\n")
>>> File: '/isar/bitbake/lib/bb/process.py', lineno: 186, function: run
>>>       0182:
>>>       0183:    if pipe.returncode != 0:
>>>       0184:        if log:
>>>       0185:            # Don't duplicate the output in the exception
>>> if logging it
>>>   *** 0186:            raise ExecutionError(cmd, pipe.returncode,
>>> None, None)
>>>       0187:        raise ExecutionError(cmd, pipe.returncode, stdout,
>>> stderr)
>>>       0188:    return stdout, stderr
>>> Exception: bb.process.ExecutionError: Execution of
>>> '/isar-build/tmp/work/debian-bullseye-armhf/recipe/1.0-r0/temp/run.test_fun.1487'
>>> failed with exit code 1
>>>
>>> ERROR: Logfile of failure stored in:
>>> /isar-build/tmp/work/debian-bullseye-armhf/recipe/1.0-r0/temp/log.do_test.1487
>>>
>>> ERROR: Task (recipe.bb:do_test) failed with exit code '1'
>>> NOTE: Tasks Summary: Attempted 1 tasks of which 0 didn't need to be
>>> rerun and 1 failed.
>>>
>>> Summary: 1 task failed:
>>>    recipe.bb:do_test
>>> Summary: There was 1 ERROR message shown, returning a non-zero exit
>>> code.
>>>
>>>
>>> This is NOT what we want to have. And this is an Isar bug at this level.
>>>
>>> Jan
>>>
>>
> Ok, it looks like I've found it.
> Did you use Yocto/Bitbake which already include this commit?
> https://github.com/openembedded/bitbake/commit/23a6f11b089b14382c21d431edf34fa7224c66bf
> 
> 
> Tried to apply on Isar's Bitbake and it works like it should be (error
> log is printed).
> So we just need to update BItbake version to at least 1.52.3
> 

Good catch! I was on poky master, and that included this fix.

1.52.x implies override syntax change, right? Then I would recommend to
temporarily fork bitbake here - or propose that commit for the 1.50.x
stable line if that is still maintained upstream.

Jan

-- 
Siemens AG, Technology
Competence Center Embedded Linux