diff mbox series

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

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

Commit Message

Mark Asselstine March 14, 2023, 7:20 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.

Special care is taken to save/restore the existing stdout and stderr
and preventing sending output directly to the logger when there are
"recursive" calls, for instance when a python function calls a shell
function, avoiding printing things potentially out of order and/or
multiple times.

The logging-test.bb in meta-selftest can be used to review this
change. This has been tested with the full bblogging oeqa tests.

[Yocto #14544]

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

v3:
 * returned the flush to always be run (see v2). After thinking about
   this there is a slim possibility that the try hits and exception
   before the first set of flush() calls which would result in no
   flush() calls. So it is better to keep them as they were.
 * fixed issues reported by oeqa bblogging tests, this required
   a bit more handling for "recursive" calls. See the commit log
   and code comments for details
 * return "<mem>" when there is no 'name' member, as is the case
   for io.StringIO, in StdoutNoopContextManager
 * ran oeqa bblogging tests to up the confidence in this change
   being in good shape
 * I will follow this change with an update to the bblogging tests
   to turn on the checks currently commented out due to lack of
   python functions supporting -v

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, 21 insertions(+), 2 deletions(-)
diff mbox series

Patch

diff --git a/lib/bb/build.py b/lib/bb/build.py
index 5a172711..44d08f5c 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')
@@ -177,7 +178,9 @@  class StdoutNoopContextManager:
 
     @property
     def name(self):
-        return sys.stdout.name
+        if "name" in dir(sys.stdout):
+            return sys.stdout.name
+        return "<mem>"
 
 
 def exec_func(func, d, dirs = None):
@@ -296,9 +299,21 @@  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:
+        if verboseStdoutLogging:
+            execio.flush()
+            logger.plain("%s" % execio.getvalue())
+            sys.stdout = currout
+            sys.stderr = currerr
+            execio.close()
         # 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()
@@ -441,7 +456,11 @@  exit $ret
         if fakerootcmd:
             cmd = [fakerootcmd, runfile]
 
-    if verboseStdoutLogging:
+    # We only want to output to logger via LogTee if stdout is sys.__stdout__ (which will either
+    # be real stdout or subprocess PIPE or similar). In other cases we are being run "recursively",
+    # ie. inside another function, in which case stdout is already being captured so we don't
+    # want to Tee here as output would be printed twice, and out of order.
+    if verboseStdoutLogging and sys.stdout == sys.__stdout__:
         logfile = LogTee(logger, StdoutNoopContextManager())
     else:
         logfile = StdoutNoopContextManager()