10785 2016-12-12 02:34:16 +0000 shell logging function appears to break task output 2017-07-19 17:01:19 +0000 1 1 7 Build System, Metadata & Runtime BitBake bitbake 2.2 x86 Multiple RESOLVED FIXED Medium+ normal 2.4 M2 1 bluelightning juro.bystricky poky.bs.watcher poky.watcher randy.macleod ross.burton sgw --- --- No (bug/feature does not impact docs) oldest_to_newest 69025 0 bluelightning 2016-12-12 02:34:16 +0000 I've just noticed some bizarre behaviour with the shell logging functions i.e. bbwarn/bbdebug/bberror. If you add the following to a recipe: --------------- snip --------------- addtask test1 do_test1[nostamp] = "1" do_test1() { bbdebug 1 "breakage" echo "this will not be printed" printf "nor this\n" } --------------- snip --------------- Then run bitbake -c test1 recipename, the task log contains this: --------------- snip --------------- DEBUG: Executing shell function do_test1 DEBUG: breakage DEBUG: Shell function do_test1 finished --------------- snip --------------- i.e. for some reason the echo and printf lines don't make it to the log. If you try one of: commenting out the bbdebug line, adding "ls -l" or even "ls -l > /dev/null" at the end, or commenting out the bb.debug() call in readfifo() in lib/bb/build.py then the echo/printf lines do get printed. However no amount of additional echo lines appear to make a difference. An "echo something > /tmp/testfile" added to the end does actually create a /tmp/testfile with "something" in it, so the subsequent commands are being executed, it's just that the console output is apparently broken. (I found this issue on master, but krogoth seems similarly afflicted.) 69026 1 bluelightning 2016-12-12 02:50:08 +0000 In fact it looks like this has been broken since jethro, which probably means since the fix to pipe shell logging messages to the console was implemented. 69305 2 bluelightning 2016-12-22 03:42:48 +0000 Perhaps this is output not being flushed before the task log is closed - though why using the python output function would trigger that I'm not sure. (When I tried bitbake -v I saw the same sort of behaviour, so it's not just the log file). 73733 3 bluelightning 2017-06-06 11:15:08 +0000 Juro - I'm a bit stumped by this - could you take a look? 73753 4 juro.bystricky 2017-06-06 15:44:52 +0000 (In reply to comment #3) > Juro - I'm a bit stumped by this - could you take a look? Hi Paul, nice mystery. Good thing it is reproducible (unlike some other log-related bugs). 73769 5 juro.bystricky 2017-06-06 17:43:27 +0000 This is my observation with the master: meta-yocto-bsp = "HEAD:02417b149623c3042c257d1c1074f915dc02b7c7" $ bitbake <recipe> -cdo_test1 sometimes I get the log busted as advertised: DEBUG: SITE files ['endian-little', 'bit-32', 'ix86-common', 'common-linux', 'common-glibc', 'i586-linux', 'common'] DEBUG: Executing shell function do_test1 DEBUG: breakage DEBUG: Shell function do_test1 finished but most of the time the log is correct: DEBUG: SITE files ['endian-little', 'bit-32', 'ix86-common', 'common-linux', 'common-glibc', 'i586-linux', 'common'] DEBUG: Executing shell function do_test1 DEBUG: breakage this will not be printed nor this DEBUG: Shell function do_test1 finished 73772 6 juro.bystricky 2017-06-06 20:07:13 +0000 More observations: The following task: do_test3() { bbdebug 1 "breakage1" echo "this will not be printed" printf "nor this\n" bbdebug 1 "breakage2" } Generates the output: ... DEBUG: Executing shell function do_test3 DEBUG: breakage1 DEBUG: breakage2 this will not be printed nor this DEBUG: Shell function do_test3 finished Note the messages are all there but in wrong order. This, I believe is 100% reproducible. 73777 7 juro.bystricky 2017-06-06 23:39:38 +0000 So this patch fixes the out-of-order-messages and possibly the original bug as well. (I guess I will need to write/run some kind of test program) diff --git a/bitbake/lib/bb/build.py b/bitbake/lib/bb/build.py index 0d0100a..d3bf2d5 100644 --- a/bitbake/lib/bb/build.py +++ b/bitbake/lib/bb/build.py @@ -426,6 +426,7 @@ exit $ret bb.debug(level, value) else: bb.warn("Unrecognised command '%s' on FIFO" % cmd) + logfile.flush() fifobuffer = nextmsg else: break @@ -435,13 +436,14 @@ exit $ret if os.path.exists(fifopath): os.unlink(fifopath) os.mkfifo(fifopath) + from subprocess import PIPE with open(fifopath, 'r+b', buffering=0) as fifo: try: bb.debug(2, "Executing shell function %s" % func) try: with open(os.devnull, 'r+') as stdin: - bb.process.run(cmd, shell=False, stdin=stdin, log=logfile, extrafiles=[(fifo,readfifo)]) + bb.process.run(cmd, shell=False, stdin=stdin, stdout=PIPE, log=logfile, extrafiles=[(fifo,readfifo)]) except bb.process.CmdError: logfn = d.getVar('BB_LOGFILE') raise FuncFailed(func, logfn) 73830 8 juro.bystricky 2017-06-07 17:24:59 +0000 Spoke too soon. A repeated test program still detects both missing log entries and entries in incorrect order. So back to the drawing board. 73853 9 juro.bystricky 2017-06-08 01:11:25 +0000 OK, so I think I got it right this time. I will test it overnight, testing various combinations of shell outputs/fifo log writes for completeness and correct order. So far so good. diff --git a/bitbake/lib/bb/process.py b/bitbake/lib/bb/process.py index a4a5599..138f908 100644 --- a/bitbake/lib/bb/process.py +++ b/bitbake/lib/bb/process.py @@ -81,7 +81,6 @@ def _logged_communicate(pipe, log, input, extrafiles): rin.append(pipe.stderr) for fobj, _ in extrafiles: bb.utils.nonblockingfd(fobj.fileno()) - rin.append(fobj) def readextras(selected): for fobj, func in extrafiles: @@ -105,6 +104,8 @@ def _logged_communicate(pipe, log, input, extrafiles): if e.errno != errno.EINTR: raise + readextras([fobj for fobj, _ in extrafiles]) + if pipe.stdout in r: data = stdoutbuf + pipe.stdout.read() if data is not None and len(data) > 0: @@ -126,13 +127,9 @@ def _logged_communicate(pipe, log, input, extrafiles): stderrbuf = b"" except UnicodeDecodeError: stderrbuf = data - - readextras(r) - + log.flush() finally: - log.flush() - - readextras([fobj for fobj, _ in extrafiles]) + pass if pipe.stdout is not None: pipe.stdout.close() 73907 10 juro.bystricky 2017-06-08 15:40:42 +0000 Extended testing passed. I tested these cases: do_test1() { bbdebug 1 "breakage" echo "this will not be printed" printf "nor this\n" } do_test2() { echo "this will not be printed" bbdebug 1 "breakage" printf "nor this\n" } do_test3() { echo "line1" bbdebug 1 "breakage1 line2" echo "this will not be printed (line3)" printf "nor this (line4)\n" bbdebug 1 "breakage2 line5" } do_test4() { bbdebug 1 "breakage1 line2" bbdebug 1 "breakage2 line2" } Although all the tests passed, by looking a the logging code, I am not sure we can guarantee a "correct" order of log entries. There is a round-robin loop for merging stdout, fifo (bbdebug uses fifo) and stderr messages into the log file. 73909 11 bluelightning 2017-06-08 15:44:24 +0000 Great work! Personally potential ordering anomalies don't bother me nearly as much as losing entire messages, so if that's the only remaining issue I'd say it's good enough. 73929 12 juro.bystricky 2017-06-08 23:37:41 +0000 (In reply to comment #11) > Great work! Personally potential ordering anomalies don't bother me nearly > as much as losing entire messages, so if that's the only remaining issue I'd > say it's good enough. Well, apparently third time is the charm. I can actually explain what went wrong. Basically we have this code (proccess.py): def _logged_communicate(pipe, log, input, extrafiles): <do_some_stuff> while ProcessOpen log fifo(s) log stdout log stderr log_fifo(s) (Note after Process is closed we make effort to drain/log fifos but not stdout/stderr) What can happen is that Process is closed before the code reaches the "while" loop and hence the pipes do not get a chance to be logged/drained. Or (most likely) the process is closed somewhere in the loop and some of the pipes may have still data in them. So the fix is this: while ProcessOpen log fifo(s) log stdout log stderr # Drain ALL pipes after process closed log_fifo() log stdout log stderr Which can be reformatted as: def read_all_pipes: log fifo(s) log stdout log stderr while ProcessOpen read_all_pipes # Drain ALL pipes after process closed read_all_pipes The previous patch worked very well in tests, but did not address the root cause of the problem. So I am testing the v3 of the patch, with additional tests. I'll let it run overnight and if there are no problems I'll send the patch to the mailing list. 73967 13 3809 juro.bystricky 2017-06-09 23:16:32 +0000 Created attachment 3809 patch that passes all the tests.... 75141 14 juro.bystricky 2017-07-19 17:01:19 +0000 merged: http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=06e9b44f97a4ba5552d2b2ad1d10acd1871ac1ce 3809 2017-06-09 23:16:32 +0000 2017-06-09 23:16:32 +0000 patch that passes all the tests.... bug-10785.diff text/plain 3120 juro.bystricky ZGlmZiAtLWdpdCBhL2JpdGJha2UvbGliL2JiL3Byb2Nlc3MucHkgYi9iaXRiYWtlL2xpYi9iYi9w cm9jZXNzLnB5CmluZGV4IGE0YTU1OTkuLjkzMTQ5YzAgMTAwNjQ0Ci0tLSBhL2JpdGJha2UvbGli L2JiL3Byb2Nlc3MucHkKKysrIGIvYml0YmFrZS9saWIvYmIvcHJvY2Vzcy5weQpAQCAtOTQsNDUg Kzk0LDUyIEBAIGRlZiBfbG9nZ2VkX2NvbW11bmljYXRlKHBpcGUsIGxvZywgaW5wdXQsIGV4dHJh ZmlsZXMpOgogICAgICAgICAgICAgICAgIGlmIGRhdGEgaXMgbm90IE5vbmU6CiAgICAgICAgICAg ICAgICAgICAgIGZ1bmMoZGF0YSkKIAorICAgIGRlZiByZWFkX2FsbF9waXBlcyhsb2csIHJpbiwg b3V0ZGF0YSwgZXJyZGF0YSk6CisgICAgICAgIHJsaXN0ID0gcmluCisgICAgICAgIHN0ZG91dGJ1 ZiA9IGIiIgorICAgICAgICBzdGRlcnJidWYgPSBiIiIKKworICAgICAgICB0cnk6CisgICAgICAg ICAgICByLHcsZSA9IHNlbGVjdC5zZWxlY3QgKHJsaXN0LCBbXSwgW10sIDEpCisgICAgICAgIGV4 Y2VwdCBPU0Vycm9yIGFzIGU6CisgICAgICAgICAgICBpZiBlLmVycm5vICE9IGVycm5vLkVJTlRS OgorICAgICAgICAgICAgICAgIHJhaXNlCisKKyAgICAgICAgcmVhZGV4dHJhcyhyKQorCisgICAg ICAgIGlmIHBpcGUuc3Rkb3V0IGluIHI6CisgICAgICAgICAgICBkYXRhID0gc3Rkb3V0YnVmICsg cGlwZS5zdGRvdXQucmVhZCgpCisgICAgICAgICAgICBpZiBkYXRhIGlzIG5vdCBOb25lIGFuZCBs ZW4oZGF0YSkgPiAwOgorICAgICAgICAgICAgICAgIHRyeToKKyAgICAgICAgICAgICAgICAgICAg ZGF0YSA9IGRhdGEuZGVjb2RlKCJ1dGYtOCIpCisgICAgICAgICAgICAgICAgICAgIG91dGRhdGEu YXBwZW5kKGRhdGEpCisgICAgICAgICAgICAgICAgICAgIGxvZy53cml0ZShkYXRhKQorICAgICAg ICAgICAgICAgICAgICBsb2cuZmx1c2goKQorICAgICAgICAgICAgICAgICAgICBzdGRvdXRidWYg PSBiIiIKKyAgICAgICAgICAgICAgICBleGNlcHQgVW5pY29kZURlY29kZUVycm9yOgorICAgICAg ICAgICAgICAgICAgICBzdGRvdXRidWYgPSBkYXRhCisKKyAgICAgICAgaWYgcGlwZS5zdGRlcnIg aW4gcjoKKyAgICAgICAgICAgIGRhdGEgPSBzdGRlcnJidWYgKyBwaXBlLnN0ZGVyci5yZWFkKCkK KyAgICAgICAgICAgIGlmIGRhdGEgaXMgbm90IE5vbmUgYW5kIGxlbihkYXRhKSA+IDA6CisgICAg ICAgICAgICAgICAgdHJ5OgorICAgICAgICAgICAgICAgICAgICBkYXRhID0gZGF0YS5kZWNvZGUo InV0Zi04IikKKyAgICAgICAgICAgICAgICAgICAgZXJyZGF0YS5hcHBlbmQoZGF0YSkKKyAgICAg ICAgICAgICAgICAgICAgbG9nLndyaXRlKGRhdGEpCisgICAgICAgICAgICAgICAgICAgIGxvZy5m bHVzaCgpCisgICAgICAgICAgICAgICAgICAgIHN0ZGVycmJ1ZiA9IGIiIgorICAgICAgICAgICAg ICAgIGV4Y2VwdCBVbmljb2RlRGVjb2RlRXJyb3I6CisgICAgICAgICAgICAgICAgICAgIHN0ZGVy cmJ1ZiA9IGRhdGEKKwogICAgIHRyeToKKyAgICAgICAgIyBSZWFkIGFsbCBwaXBlcyB3aGlsZSB0 aGUgcHJvY2VzcyBpcyBvcGVuCiAgICAgICAgIHdoaWxlIHBpcGUucG9sbCgpIGlzIE5vbmU6Ci0g ICAgICAgICAgICBybGlzdCA9IHJpbgotICAgICAgICAgICAgc3Rkb3V0YnVmID0gYiIiCi0gICAg ICAgICAgICBzdGRlcnJidWYgPSBiIiIKLSAgICAgICAgICAgIHRyeToKLSAgICAgICAgICAgICAg ICByLHcsZSA9IHNlbGVjdC5zZWxlY3QgKHJsaXN0LCBbXSwgW10sIDEpCi0gICAgICAgICAgICBl eGNlcHQgT1NFcnJvciBhcyBlOgotICAgICAgICAgICAgICAgIGlmIGUuZXJybm8gIT0gZXJybm8u RUlOVFI6Ci0gICAgICAgICAgICAgICAgICAgIHJhaXNlCi0KLSAgICAgICAgICAgIGlmIHBpcGUu c3Rkb3V0IGluIHI6Ci0gICAgICAgICAgICAgICAgZGF0YSA9IHN0ZG91dGJ1ZiArIHBpcGUuc3Rk b3V0LnJlYWQoKQotICAgICAgICAgICAgICAgIGlmIGRhdGEgaXMgbm90IE5vbmUgYW5kIGxlbihk YXRhKSA+IDA6Ci0gICAgICAgICAgICAgICAgICAgIHRyeToKLSAgICAgICAgICAgICAgICAgICAg ICAgIGRhdGEgPSBkYXRhLmRlY29kZSgidXRmLTgiKQotICAgICAgICAgICAgICAgICAgICAgICAg b3V0ZGF0YS5hcHBlbmQoZGF0YSkKLSAgICAgICAgICAgICAgICAgICAgICAgIGxvZy53cml0ZShk YXRhKQotICAgICAgICAgICAgICAgICAgICAgICAgc3Rkb3V0YnVmID0gYiIiCi0gICAgICAgICAg ICAgICAgICAgIGV4Y2VwdCBVbmljb2RlRGVjb2RlRXJyb3I6Ci0gICAgICAgICAgICAgICAgICAg ICAgICBzdGRvdXRidWYgPSBkYXRhCi0KLSAgICAgICAgICAgIGlmIHBpcGUuc3RkZXJyIGluIHI6 Ci0gICAgICAgICAgICAgICAgZGF0YSA9IHN0ZGVycmJ1ZiArIHBpcGUuc3RkZXJyLnJlYWQoKQot ICAgICAgICAgICAgICAgIGlmIGRhdGEgaXMgbm90IE5vbmUgYW5kIGxlbihkYXRhKSA+IDA6Ci0g ICAgICAgICAgICAgICAgICAgIHRyeToKLSAgICAgICAgICAgICAgICAgICAgICAgIGRhdGEgPSBk YXRhLmRlY29kZSgidXRmLTgiKQotICAgICAgICAgICAgICAgICAgICAgICAgZXJyZGF0YS5hcHBl bmQoZGF0YSkKLSAgICAgICAgICAgICAgICAgICAgICAgIGxvZy53cml0ZShkYXRhKQotICAgICAg ICAgICAgICAgICAgICAgICAgc3RkZXJyYnVmID0gYiIiCi0gICAgICAgICAgICAgICAgICAgIGV4 Y2VwdCBVbmljb2RlRGVjb2RlRXJyb3I6Ci0gICAgICAgICAgICAgICAgICAgICAgICBzdGRlcnJi dWYgPSBkYXRhCi0KLSAgICAgICAgICAgIHJlYWRleHRyYXMocikKLQotICAgIGZpbmFsbHk6ICAg IAotICAgICAgICBsb2cuZmx1c2goKQotCi0gICAgcmVhZGV4dHJhcyhbZm9iaiBmb3IgZm9iaiwg XyBpbiBleHRyYWZpbGVzXSkKKyAgICAgICAgICAgIHJlYWRfYWxsX3BpcGVzKGxvZywgcmluLCBv dXRkYXRhLCBlcnJkYXRhKQorCisgICAgICAgICMgUG9jZXNzIGNsb3NlZCwgZHJhaW4gYWxsIHBp cGVzLi4uCisgICAgICAgIHJlYWRfYWxsX3BpcGVzKGxvZywgcmluLCBvdXRkYXRhLCBlcnJkYXRh KQorICAgIGZpbmFsbHk6CisgICAgICAgIGxvZy5mbHVzaAogCiAgICAgaWYgcGlwZS5zdGRvdXQg aXMgbm90IE5vbmU6CiAgICAgICAgIHBpcGUuc3Rkb3V0LmNsb3NlKCkK