Bug 10785

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.

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).

Juro - I'm a bit stumped by this - could you take a look?

(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).

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

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.

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)

Spoke too soon.
A repeated test program still detects both missing log entries and entries in incorrect order. So back to the drawing board.

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()

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.

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.

(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.

Created attachment 3809 [details]
patch that passes all the tests....

merged:
http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=06e9b44f97a4ba5552d2b2ad1d10acd1871ac1ce