diff mbox series

[v2] build: Make python output print to stdout when running with -v (verbose)

Message ID 20230310145842.5412-1-mark.asselstine@windriver.com
State Accepted, archived
Commit 81a58647b2f4fc0a2589b2978fc9d81b2bfe6aec
Headers show
Series [v2] build: Make python output print to stdout when running with -v (verbose) | expand

Commit Message

Mark Asselstine March 10, 2023, 2:58 p.m. UTC
When tasks are run with -v (verbose) on the bitbake commandline, shell
tasks print their stdout, python tasks do not.

This change redirects the python task's print output to an in memory
buffer. After the task is executed the output is printed to stdout via
the logger. This makes the python task behavior match the shell task
behavior when running with -v. The contents of the task's log files
remain unchanged after this change.

This approach should keep the correct order in most cases, however, if
the python task accesses the logger directly, that content will appear
before other output. On the other hand, this change should negate the
need for python tasks to access the logger directly.

The following example will produce out-of-order output

--
python do_build() {
   import sys
   print("Start")
   print("Oops!", file=sys.stderr)
   bb.plain("********************");
   bb.plain("*                  *");
   bb.plain("*  Hello, World!   *");
   bb.plain("*                  *");
   bb.plain("********************");
   print("Finish")
}
--
will output
--
********************
*                  *
*  Hello, World!   *
*                  *
********************
Start
Oops!
Finish
--

The logging-test.bb in meta-selftest or the above 'hello world!' can
be used to review this change.

[Yocto #14544]

Signed-off-by: Mark Asselstine <mark.asselstine@windriver.com>
---

v2: Richard, per your suggestions, I have added capturing stderr and
also storing and restoring the previous stdout and stderr. Since we
are already flushing stdout and stderr when verboseStdoutLogging I
have skipped the second flushes.

 lib/bb/build.py | 23 +++++++++++++++++++----
 1 file changed, 19 insertions(+), 4 deletions(-)

Comments

Alexandre Belloni March 11, 2023, 11:20 p.m. UTC | #1
Hello,

This seems to break bitbake selftests:

https://autobuilder.yoctoproject.org/typhoon/#builders/127/builds/1082/steps/15/logs/stdio
https://autobuilder.yoctoproject.org/typhoon/#builders/80/builds/4859/steps/14/logs/stdio
https://autobuilder.yoctoproject.org/typhoon/#builders/87/builds/4938/steps/14/logs/stdio
https://autobuilder.yoctoproject.org/typhoon/#builders/79/builds/4912/steps/15/logs/stdio
https://autobuilder.yoctoproject.org/typhoon/#builders/86/builds/4903/steps/14/logs/stdio



On 10/03/2023 09:58:42-0500, Mark Asselstine wrote:
> When tasks are run with -v (verbose) on the bitbake commandline, shell
> tasks print their stdout, python tasks do not.
> 
> This change redirects the python task's print output to an in memory
> buffer. After the task is executed the output is printed to stdout via
> the logger. This makes the python task behavior match the shell task
> behavior when running with -v. The contents of the task's log files
> remain unchanged after this change.
> 
> This approach should keep the correct order in most cases, however, if
> the python task accesses the logger directly, that content will appear
> before other output. On the other hand, this change should negate the
> need for python tasks to access the logger directly.
> 
> The following example will produce out-of-order output
> 
> --
> python do_build() {
>    import sys
>    print("Start")
>    print("Oops!", file=sys.stderr)
>    bb.plain("********************");
>    bb.plain("*                  *");
>    bb.plain("*  Hello, World!   *");
>    bb.plain("*                  *");
>    bb.plain("********************");
>    print("Finish")
> }
> --
> will output
> --
> ********************
> *                  *
> *  Hello, World!   *
> *                  *
> ********************
> Start
> Oops!
> Finish
> --
> 
> The logging-test.bb in meta-selftest or the above 'hello world!' can
> be used to review this change.
> 
> [Yocto #14544]
> 
> Signed-off-by: Mark Asselstine <mark.asselstine@windriver.com>
> ---
> 
> v2: Richard, per your suggestions, I have added capturing stderr and
> also storing and restoring the previous stdout and stderr. Since we
> are already flushing stdout and stderr when verboseStdoutLogging I
> have skipped the second flushes.
> 
>  lib/bb/build.py | 23 +++++++++++++++++++----
>  1 file changed, 19 insertions(+), 4 deletions(-)
> 
> diff --git a/lib/bb/build.py b/lib/bb/build.py
> index 5a172711..786c215c 100644
> --- a/lib/bb/build.py
> +++ b/lib/bb/build.py
> @@ -25,6 +25,7 @@ import bb
>  import bb.msg
>  import bb.process
>  import bb.progress
> +from io import StringIO
>  from bb import data, event, utils
>  
>  bblogger = logging.getLogger('BitBake')
> @@ -296,13 +297,27 @@ def exec_func_python(func, d, runfile, cwd=None):
>          lineno = int(d.getVarFlag(func, "lineno", False))
>          bb.methodpool.insert_method(func, text, fn, lineno - 1)
>  
> +        if verboseStdoutLogging:
> +            sys.stdout.flush()
> +            sys.stderr.flush()
> +            currout = sys.stdout
> +            currerr = sys.stderr
> +            sys.stderr = sys.stdout = execio = StringIO()
>          comp = utils.better_compile(code, func, "exec_func_python() autogenerated")
>          utils.better_exec(comp, {"d": d}, code, "exec_func_python() autogenerated")
>      finally:
> -        # We want any stdout/stderr to be printed before any other log messages to make debugging
> -        # more accurate. In some cases we seem to lose stdout/stderr entirely in logging tests without this.
> -        sys.stdout.flush()
> -        sys.stderr.flush()
> +        if verboseStdoutLogging:
> +            execio.flush()
> +            logger.plain("%s" % execio.getvalue())
> +            sys.stdout = currout
> +            sys.stderr = currerr
> +            execio.close()
> +        else:
> +            # We want any stdout/stderr to be printed before any other log
> +            # messages to make debugging more accurate. In some cases we seem
> +            # to lose stdout/stderr entirely in logging tests without this.
> +            sys.stdout.flush()
> +            sys.stderr.flush()
>          bb.debug(2, "Python function %s finished" % func)
>  
>          if cwd and olddir:
> -- 
> 2.30.2
> 

> 
> -=-=-=-=-=-=-=-=-=-=-=-
> Links: You receive all messages sent to this group.
> View/Reply Online (#14538): https://lists.openembedded.org/g/bitbake-devel/message/14538
> Mute This Topic: https://lists.openembedded.org/mt/97520900/3617179
> Group Owner: bitbake-devel+owner@lists.openembedded.org
> Unsubscribe: https://lists.openembedded.org/g/bitbake-devel/unsub [alexandre.belloni@bootlin.com]
> -=-=-=-=-=-=-=-=-=-=-=-
>
diff mbox series

Patch

diff --git a/lib/bb/build.py b/lib/bb/build.py
index 5a172711..786c215c 100644
--- a/lib/bb/build.py
+++ b/lib/bb/build.py
@@ -25,6 +25,7 @@  import bb
 import bb.msg
 import bb.process
 import bb.progress
+from io import StringIO
 from bb import data, event, utils
 
 bblogger = logging.getLogger('BitBake')
@@ -296,13 +297,27 @@  def exec_func_python(func, d, runfile, cwd=None):
         lineno = int(d.getVarFlag(func, "lineno", False))
         bb.methodpool.insert_method(func, text, fn, lineno - 1)
 
+        if verboseStdoutLogging:
+            sys.stdout.flush()
+            sys.stderr.flush()
+            currout = sys.stdout
+            currerr = sys.stderr
+            sys.stderr = sys.stdout = execio = StringIO()
         comp = utils.better_compile(code, func, "exec_func_python() autogenerated")
         utils.better_exec(comp, {"d": d}, code, "exec_func_python() autogenerated")
     finally:
-        # We want any stdout/stderr to be printed before any other log messages to make debugging
-        # more accurate. In some cases we seem to lose stdout/stderr entirely in logging tests without this.
-        sys.stdout.flush()
-        sys.stderr.flush()
+        if verboseStdoutLogging:
+            execio.flush()
+            logger.plain("%s" % execio.getvalue())
+            sys.stdout = currout
+            sys.stderr = currerr
+            execio.close()
+        else:
+            # We want any stdout/stderr to be printed before any other log
+            # messages to make debugging more accurate. In some cases we seem
+            # to lose stdout/stderr entirely in logging tests without this.
+            sys.stdout.flush()
+            sys.stderr.flush()
         bb.debug(2, "Python function %s finished" % func)
 
         if cwd and olddir: