[PATCH 1/3] build: Ensure python stdout/stderr is logged correctly

[PATCH 1/3] build: Ensure python stdout/stderr is logged correctly

[Richard Purdie]

Currently we see things like:

Log data follows:
| DEBUG: Executing python function do_pythontest_exit
| DEBUG: Python function do_pythontest_exit finished
| ERROR: 1
| This is python stdout

Whilst after the change we see things like:

Log data follows:
| DEBUG: Executing python function do_pythontest_exit
| This is python stdout
| DEBUG: Python function do_pythontest_exit finished
| ERROR: 1

since the output is now correctly mixed with the log messages. In some cases the logging
tests indicate the output is being lost entirely which is bad for debugging and makes
things rather confusing.

Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
---
 lib/bb/build.py | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/lib/bb/build.py b/lib/bb/build.py
index c2479dd167..18586c276e 100644
--- a/lib/bb/build.py
+++ b/lib/bb/build.py
@@ -298,6 +298,10 @@ def exec_func_python(func, d, runfile, cwd=None):
         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()
         bb.debug(2, "Python function %s finished" % func)
 
         if cwd and olddir:
-- 
2.32.0

[PATCH 2/3] build: Make exception printing clearer

[Richard Purdie]

Shows:

ERROR: SystemExit(1)

instead of:

ERROR: 1

Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
---
 lib/bb/build.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/bb/build.py b/lib/bb/build.py
index 18586c276e..99954b0c26 100644
--- a/lib/bb/build.py
+++ b/lib/bb/build.py
@@ -707,7 +707,7 @@ def _exec_task(fn, task, d, quieterr):
                 # logs once already so don't duplicate
                 if verboseStdoutLogging:
                     errprinted = True
-                logger.error(str(exc))
+                logger.error(repr(exc))
                 event.fire(TaskFailed(task, fn, logfn, localdata, errprinted), localdata)
             return 1
     finally:
-- 
2.32.0

[PATCH 3/3] build: Fix log flushing race

[Richard Purdie]

There is a race between sending the TaskFailed event which could trigger
the UI to look at the logs and flushing and closing the log files.

Reverse the order of the finally clause and the exception handling
to ensure we've handled the logfiles before sending the task events.

This should fix a race seen in bblogging.BitBakeLogging.test_python_exit_logging

Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
---
 lib/bb/build.py | 76 ++++++++++++++++++++++++-------------------------
 1 file changed, 38 insertions(+), 38 deletions(-)

diff --git a/lib/bb/build.py b/lib/bb/build.py
index 99954b0c26..7e4ab9f64c 100644
--- a/lib/bb/build.py
+++ b/lib/bb/build.py
@@ -686,51 +686,51 @@ def _exec_task(fn, task, d, quieterr):
     try:
         try:
             event.fire(TaskStarted(task, fn, logfn, flags, localdata), localdata)
-        except (bb.BBHandledException, SystemExit):
-            return 1
 
-        try:
             for func in (prefuncs or '').split():
                 exec_func(func, localdata)
             exec_func(task, localdata)
             for func in (postfuncs or '').split():
                 exec_func(func, localdata)
-        except bb.BBHandledException:
-            event.fire(TaskFailed(task, fn, logfn, localdata, True), localdata)
-            return 1
-        except (Exception, SystemExit) as exc:
-            if quieterr:
-                event.fire(TaskFailedSilent(task, fn, logfn, localdata), localdata)
-            else:
-                errprinted = errchk.triggered
-                # If the output is already on stdout, we've printed the information in the
-                # logs once already so don't duplicate
-                if verboseStdoutLogging:
-                    errprinted = True
-                logger.error(repr(exc))
-                event.fire(TaskFailed(task, fn, logfn, localdata, errprinted), localdata)
-            return 1
-    finally:
-        sys.stdout.flush()
-        sys.stderr.flush()
-
-        bblogger.removeHandler(handler)
-
-        # Restore the backup fds
-        os.dup2(osi[0], osi[1])
-        os.dup2(oso[0], oso[1])
-        os.dup2(ose[0], ose[1])
-
-        # Close the backup fds
-        os.close(osi[0])
-        os.close(oso[0])
-        os.close(ose[0])
+        finally:
+            # Need to flush and close the logs before sending events where the
+            # UI may try to look at the logs.
+            sys.stdout.flush()
+            sys.stderr.flush()
+
+            bblogger.removeHandler(handler)
+
+            # Restore the backup fds
+            os.dup2(osi[0], osi[1])
+            os.dup2(oso[0], oso[1])
+            os.dup2(ose[0], ose[1])
+
+            # Close the backup fds
+            os.close(osi[0])
+            os.close(oso[0])
+            os.close(ose[0])
+
+            logfile.close()
+            if os.path.exists(logfn) and os.path.getsize(logfn) == 0:
+                logger.debug2("Zero size logfn %s, removing", logfn)
+                bb.utils.remove(logfn)
+                bb.utils.remove(loglink)
+    except bb.BBHandledException:
+        event.fire(TaskFailed(task, fn, logfn, localdata, True), localdata)
+        return 1
+    except (Exception, SystemExit) as exc:
+        if quieterr:
+            event.fire(TaskFailedSilent(task, fn, logfn, localdata), localdata)
+        else:
+            errprinted = errchk.triggered
+            # If the output is already on stdout, we've printed the information in the
+            # logs once already so don't duplicate
+            if verboseStdoutLogging:
+                errprinted = True
+            logger.error(repr(exc))
+            event.fire(TaskFailed(task, fn, logfn, localdata, errprinted), localdata)
+        return 1
 
-        logfile.close()
-        if os.path.exists(logfn) and os.path.getsize(logfn) == 0:
-            logger.debug2("Zero size logfn %s, removing", logfn)
-            bb.utils.remove(logfn)
-            bb.utils.remove(loglink)
     event.fire(TaskSucceeded(task, fn, logfn, localdata), localdata)
 
     if not localdata.getVarFlag(task, 'nostamp', False) and not localdata.getVarFlag(task, 'selfstamp', False):
-- 
2.32.0