| Message ID | 20230309192138.991-1-mark.asselstine@windriver.com |
|---|---|
| State | Accepted, archived |
| Commit | 81a58647b2f4fc0a2589b2978fc9d81b2bfe6aec |
| Headers | show |
| Series | build: Make python output print to stdout when running with -v (verbose) | expand |
On Thu, 2023-03-09 at 14:21 -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() { > print("Start") > bb.plain("********************"); > bb.plain("* *"); > bb.plain("* Hello, World! *"); > bb.plain("* *"); > bb.plain("********************"); > print("Finish") > } > -- > will output > -- > ******************** > * * > * Hello, World! * > * * > ******************** > Start > 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> > --- > lib/bb/build.py | 9 +++++++++ > 1 file changed, 9 insertions(+) > > diff --git a/lib/bb/build.py b/lib/bb/build.py > index 5a172711..eb2d5b59 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,9 +297,17 @@ 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.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 = sys.__stdout__ > + 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() From memory, I think exec_func_python can get called recursively so I suspect this is going to corrupt sys.stdout. You could save it's value, then restore it? Also, what about stderr? Cheers, Richard
On 3/9/2023 4:49 PM, Richard Purdie wrote: > On Thu, 2023-03-09 at 14:21 -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() { >> print("Start") >> bb.plain("********************"); >> bb.plain("* *"); >> bb.plain("* Hello, World! *"); >> bb.plain("* *"); >> bb.plain("********************"); >> print("Finish") >> } >> -- >> will output >> -- >> ******************** >> * * >> * Hello, World! * >> * * >> ******************** >> Start >> 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> >> --- >> lib/bb/build.py | 9 +++++++++ >> 1 file changed, 9 insertions(+) >> >> diff --git a/lib/bb/build.py b/lib/bb/build.py >> index 5a172711..eb2d5b59 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,9 +297,17 @@ 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.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 = sys.__stdout__ >> + 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() > > From memory, I think exec_func_python can get called recursively so I > suspect this is going to corrupt sys.stdout. You could save it's value, > then restore it? > I was actually dithering on this and was saving and restoring it in my first iteration. I opted for simplicity when I believed that it was allways going to be __stdout__. Regardless if it every changes it would be safer to save and restore. I will return to that approach in V2. > Also, what about stderr? Tunnel vision at play, I was only focused on stdout :). It should be simple to add stderr and I will do so in V2. MarkA > > Cheers, > > Richard >
diff --git a/lib/bb/build.py b/lib/bb/build.py index 5a172711..eb2d5b59 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,9 +297,17 @@ 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.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 = sys.__stdout__ + 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()
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() { print("Start") bb.plain("********************"); bb.plain("* *"); bb.plain("* Hello, World! *"); bb.plain("* *"); bb.plain("********************"); print("Finish") } -- will output -- ******************** * * * Hello, World! * * * ******************** Start 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> --- lib/bb/build.py | 9 +++++++++ 1 file changed, 9 insertions(+)