Re: [PATCH 1/1] process.py, build.py: Fix log truncation problems with flush()

[Richard Purdie <richard.purdie@linuxfoundation.org>]

On Thu, 2012-06-14 at 09:58 -0500, Jason Wessel wrote:
> There are two problems with the _logged_communicate that are both
> caused as a result of buffering I/O, instead of flushing it out to the
> log files as it arrives.
> 
> 1) log truncation when python dumps
>    I have seen the task logs missing data that was not flushed when
>    bitbake crashes.
> 
> 2) While a bitbake task is running it is impossible to see what is
>    going on if it is only writing a small incremental log that is
>    smaller than the buffer, or you get only a partial log, up until
>    the task exists.  It is worse in the case that stderr and stdout
>    are separate file handles, because previous code blocks on the read
>    of stdout and then stderr, serially.
> 
> The right approach is simply to use select() to determine if there is
> data available and then to flush the log buffers as they arrive.  This
> still makes use of buffering in the cases where there is more than 1
> byte of data, but the buffers are much more dynamic.
> 
> Signed-off-by: Jason Wessel <jason.wessel@windriver.com>
> ---
>  lib/bb/build.py   |    3 ++-
>  lib/bb/process.py |   29 +++++++++++++++++++++++++++--
>  2 files changed, 29 insertions(+), 3 deletions(-)

For what its worth I'm seeing a small but consistent increase in real,
sys and user times with this patch which is why I'm pausing to look at
it a little further :(

Cheers,

Richard



> diff --git a/lib/bb/build.py b/lib/bb/build.py
> index a9ba02d..7e9bb23 100644
> --- a/lib/bb/build.py
> +++ b/lib/bb/build.py
> @@ -135,7 +135,8 @@ class LogTee(object):
>  
>      def __repr__(self):
>          return '<LogTee {0}>'.format(self.name)
> -
> +    def flush(self):
> +        self.outfile.flush()
>  
>  def exec_func(func, d, dirs = None):
>      """Execute an BB 'function'"""
> diff --git a/lib/bb/process.py b/lib/bb/process.py
> index b74cb18..9848fc3 100644
> --- a/lib/bb/process.py
> +++ b/lib/bb/process.py
> @@ -1,6 +1,9 @@
>  import logging
>  import signal
>  import subprocess
> +import fcntl
> +import errno
> +import select
>  
>  logger = logging.getLogger('BitBake.Process')
>  
> @@ -70,18 +73,40 @@ def _logged_communicate(pipe, log, input):
>  
>      bufsize = 512
>      outdata, errdata = [], []
> +    rin = []
> +
> +    if pipe.stdout is not None:
> +        fd = pipe.stdout.fileno()
> +        fl = fcntl.fcntl(fd, fcntl.F_GETFL)
> +        fcntl.fcntl(fd, fcntl.F_SETFL, fl | os.O_NONBLOCK)
> +        rin.append(pipe.stdout)
> +    if pipe.stderr is not None:
> +        fd = pipe.stderr.fileno()
> +        fl = fcntl.fcntl(fd, fcntl.F_GETFL)
> +        fcntl.fcntl(fd, fcntl.F_SETFL, fl | os.O_NONBLOCK)
> +        rin.append(pipe.stderr)
> +
>      while pipe.poll() is None:
> -        if pipe.stdout is not None:
> +        rlist = rin
> +        try:
> +            r,w,e = select.select (rlist, [], [])
> +        except OSError, e:
> +            if e.errno != errno.EINTR:
> +                raise
> +
> +        if pipe.stdout in r:
>              data = pipe.stdout.read(bufsize)
>              if data is not None:
>                  outdata.append(data)
>                  log.write(data)
> +                log.flush()
>  
> -        if pipe.stderr is not None:
> +        if pipe.stderr in r:
>              data = pipe.stderr.read(bufsize)
>              if data is not None:
>                  errdata.append(data)
>                  log.write(data)
> +                log.flush()
>      return ''.join(outdata), ''.join(errdata)
>  
>  def run(cmd, input=None, log=None, **options):