[bitbake-devel] [PATCH] server/process: Various server startup logging fixes

[Joshua Watt]

Looks good to me. I have a few (optional) suggestions.

On Wed, 2018-09-05 at 18:01 +0100, Richard Purdie wrote:
> There were various problems in the server startup loggin:
> 
> a) stdout/stderr were not being flushed before forking which could
> potentially
>    duplicate output
> 
> b) there were separate buffers for stdout/stderr leading to confusing
> logs
>    where the entries could be reordered. This was particularly
> confusing
>    due to the separator the logs use to idendify new messages
> 
> c) an fd wasn't being closed during server startup meaning if the
>    server failed to start, the closed fd wasn't detected as it was
> held
>    open by the other reference
> 
> d) If the pipe was detected as being closed, the code incorrectly
> retried
>    server startup
> 
> e) The event code would remap stdout/stderr without flushing them,
> leading
>    to lose log messages
> 
> Signed-off-by: Richard Purdie <richard.purdie at linuxfoundation.org>
> ---
>  lib/bb/daemonize.py      | 12 +++++++++---
>  lib/bb/event.py          |  3 +++
>  lib/bb/server/process.py | 20 ++++++++++----------
>  3 files changed, 22 insertions(+), 13 deletions(-)
> 
> diff --git a/lib/bb/daemonize.py b/lib/bb/daemonize.py
> index bf16793468..613fb35536 100644
> --- a/lib/bb/daemonize.py
> +++ b/lib/bb/daemonize.py
> @@ -16,6 +16,10 @@ def createDaemon(function, logfile):
>      background as a daemon, returning control to the caller.
>      """
>  
> +    # Ensure stdout/stderror are flushed before forking to avoid
> duplicate output
> +    sys.stdout.flush()
> +    sys.stderr.flush()
> +
>      try:
>          # Fork a child process so the parent can exit.  This returns
> control to
>          # the command-line or shell.  It also guarantees that the
> child will not
> @@ -66,12 +70,14 @@ def createDaemon(function, logfile):
>  
>      try:
>          so = open(logfile, 'a+')
> -        se = so
>          os.dup2(so.fileno(), sys.stdout.fileno())
> -        os.dup2(se.fileno(), sys.stderr.fileno())
> +        os.dup2(so.fileno(), sys.stderr.fileno())

I think so "leaks" here. Granted, it was doing that before so perhaps
it could be saved for a separate patch:

 with open(logfile, 'a+') as so:
     os.dup2(so.fileno(), sys.stdout.fileno())
     os.dup2(so.fileno(), sys.stderr.fileno())


>      except io.UnsupportedOperation:
>          sys.stdout = open(logfile, 'a+')
> -        sys.stderr = sys.stdout
> +
> +    # Have stdout and stderr be the same so log output matches
> chronologically
> +    # and there aren't two seperate buffers
> +    sys.stderr = sys.stdout
>  
>      try:
>          function()
> diff --git a/lib/bb/event.py b/lib/bb/event.py
> index c0ec605209..5b1b094a80 100644
> --- a/lib/bb/event.py
> +++ b/lib/bb/event.py
> @@ -141,6 +141,9 @@ def print_ui_queue():
>      logger = logging.getLogger("BitBake")
>      if not _uiready:
>          from bb.msg import BBLogFormatter
> +        # Flush any existing buffered content
> +        sys.stdout.flush()
> +        sys.stderr.flush()
>          stdout = logging.StreamHandler(sys.stdout)
>          stderr = logging.StreamHandler(sys.stderr)
>          formatter = BBLogFormatter("%(levelname)s: %(message)s")
> diff --git a/lib/bb/server/process.py b/lib/bb/server/process.py
> index 9e5e709f04..38b923fe2d 100644
> --- a/lib/bb/server/process.py
> +++ b/lib/bb/server/process.py
> @@ -395,11 +395,16 @@ class BitBakeServer(object):
>          bb.daemonize.createDaemon(self._startServer, logfile)
>          self.sock.close()
>          self.bitbake_lock.close()
> +        os.close(self.readypipein)
>  
>          ready = ConnectionReader(self.readypipe)
>          r = ready.poll(30)
>          if r:
> -            r = ready.get()
> +            try:
> +                r = ready.get()
> +            except EOFError:
> +                # Trap the child exitting/closing the pipe and error
> out
> +                r = None
>          if not r or r != "ready":
>              ready.close()
>              bb.error("Unable to start bitbake server")
> @@ -425,21 +430,16 @@ class BitBakeServer(object):
>                          bb.error("Server log for this session
> (%s):\n%s" % (logfile, "".join(lines)))
>              raise SystemExit(1)
>          ready.close()
> -        os.close(self.readypipein)
>  
>      def _startServer(self):
>          print(self.start_log_format % (os.getpid(),
> datetime.datetime.now().strftime(self.start_log_datetime_format)))
>          server = ProcessServer(self.bitbake_lock, self.sock,
> self.sockname)
>          self.configuration.setServerRegIdleCallback(server.register_
> idle_function)
> +        os.close(self.readypipe)
>          writer = ConnectionWriter(self.readypipein)
> -        try:
> -            self.cooker = bb.cooker.BBCooker(self.configuration,
> self.featureset)
> -            writer.send("ready")
> -        except:
> -            writer.send("fail")
> -            raise
> -        finally:
> -            os.close(self.readypipein)
> +        self.cooker = bb.cooker.BBCooker(self.configuration,
> self.featureset)
> +        writer.send("ready")
> +        writer.close()

If we want to ensure that writer is always explicitly closed, would
this be better?

 import contextlib

 with contextlib.closing(ConnectionWriter(self.readypipein)) as writer:
     self.cooker = bb.cooker.BBCooker(...)
     writer.send("ready")

>          server.cooker = self.cooker
>          server.server_timeout = self.configuration.server_timeout
>          server.xmlrpcinterface = self.configuration.xmlrpcinterface
> -- 
> 2.17.1
> 
-- 
Joshua Watt <JPEWhacker at gmail.com>