All the mail mirrored from lore.kernel.org
 help / color / mirror / Atom feed

* [review-request][PATCH][v2] toasterui: Create per-build logs
@ 2015-10-28 13:44 Elliot Smith
  2015-10-28 13:47 ` Smith, Elliot
  2015-11-02  1:15 ` Brian Avery
  0 siblings, 2 replies; 6+ messages in thread
From: Elliot Smith @ 2015-10-28 13:44 UTC (permalink / raw
  To: toaster

v2:

* Toaster doesn't get a ParseStarted event for command-line builds,
so revert to using BuildStarted (for cli builds only). This means we lose
the "Build configuration" for command-line builds (not for Toaster builds);
but as the user is building on the command-line, they can see the
build configuration anyway.

* Changed getSetVariable for BB_CONSOLELOG to getVariable, as we have
a read-only bitbake server, which means variable writes fail;
and we don't need to set that variable anyway (we only read it so we
know which directory to put our logs into).

---

Rather than relying on bug 8411, which is conveniently creating
separate log files for each of our builds, create our own
log file for each build.

The log files are created in the same tmp directories that
bitbake uses, but are timestamped to the millisecond to avoid
name collisions.

Each log file is opened on a ParseStarted event (for builds
triggered by Toaster) or BuildStarted event (for builds on the
command line: Toaster doesn't get the ParseStarted event
for command-line builds).

The log file is closed on the BuildCompleted event, or if the
build fails.

Because we start logging on ParseStarted for Toaster builds,
we're able to capture the "Build Configuration" section which
bitbake writes to output. We lose this section for cli builds.

[YOCTO #8373]

Signed-off-by: Elliot Smith <elliot.smith@intel.com>
---
 bitbake/lib/bb/ui/buildinfohelper.py |   8 +--
 bitbake/lib/bb/ui/toasterui.py       | 116 +++++++++++++++++++++++++++--------
 2 files changed, 94 insertions(+), 30 deletions(-)

diff --git a/bitbake/lib/bb/ui/buildinfohelper.py b/bitbake/lib/bb/ui/buildinfohelper.py
index 2fc1a43..78f1e92 100644
--- a/bitbake/lib/bb/ui/buildinfohelper.py
+++ b/bitbake/lib/bb/ui/buildinfohelper.py
@@ -784,7 +784,7 @@ class BuildInfoHelper(object):
     ## methods to convert event/external info into objects that the ORM layer uses


-    def _get_build_information(self, consolelogfile):
+    def _get_build_information(self, build_log_path):
         build_info = {}
         # Generate an identifier for each new build

@@ -793,7 +793,7 @@ class BuildInfoHelper(object):
         build_info['distro_version'] = self.server.runCommand(["getVariable", "DISTRO_VERSION"])[0]
         build_info['started_on'] = timezone.now()
         build_info['completed_on'] = timezone.now()
-        build_info['cooker_log_path'] = consolelogfile
+        build_info['cooker_log_path'] = build_log_path
         build_info['build_name'] = self.server.runCommand(["getVariable", "BUILDNAME"])[0]
         build_info['bitbake_version'] = self.server.runCommand(["getVariable", "BB_VERSION"])[0]

@@ -934,9 +934,9 @@ class BuildInfoHelper(object):
                 logger.warn("buildinfohelper: cannot identify layer exception:%s ", nee)


-    def store_started_build(self, event, consolelogfile):
+    def store_started_build(self, event, build_log_path):
         assert '_pkgs' in vars(event)
-        build_information = self._get_build_information(consolelogfile)
+        build_information = self._get_build_information(build_log_path)

         build_obj = self.orm_wrapper.create_build_object(build_information, self.brbe, self.project)

diff --git a/bitbake/lib/bb/ui/toasterui.py b/bitbake/lib/bb/ui/toasterui.py
index 2b3bc3f..3d26150 100644
--- a/bitbake/lib/bb/ui/toasterui.py
+++ b/bitbake/lib/bb/ui/toasterui.py
@@ -21,6 +21,7 @@
 # 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.

 from __future__ import division
+import time
 import sys
 try:
     import bb
@@ -43,8 +44,6 @@ featureSet = [bb.cooker.CookerFeatures.HOB_EXTRA_CACHES, bb.cooker.CookerFeature
 logger = logging.getLogger("ToasterLogger")
 interactive = sys.stdout.isatty()

-
-
 def _log_settings_from_server(server):
     # Get values of variables which control our output
     includelogs, error = server.runCommand(["getVariable", "BBINCLUDELOGS"])
@@ -55,16 +54,60 @@ def _log_settings_from_server(server):
     if error:
         logger.error("Unable to get the value of BBINCLUDELOGS_LINES variable: %s", error)
         raise BaseException(error)
-    consolelogfile, error = server.runCommand(["getSetVariable", "BB_CONSOLELOG"])
+    consolelogfile, error = server.runCommand(["getVariable", "BB_CONSOLELOG"])
     if error:
         logger.error("Unable to get the value of BB_CONSOLELOG variable: %s", error)
         raise BaseException(error)
-    return includelogs, loglines, consolelogfile
+    return consolelogfile
+
+# create a log file for a single build and direct the logger at it;
+# log file name is timestamped to the millisecond (depending
+# on system clock accuracy) to ensure it doesn't overlap with
+# other log file names
+#
+# returns (log file, path to log file) for a build
+def _open_build_log(log_dir):
+    format_str = "%(levelname)s: %(message)s"
+
+    now = time.time()
+    now_ms = int((now - int(now)) * 1000)
+    time_str = time.strftime('build_%Y%m%d_%H%M%S', time.localtime(now))
+    log_file_name = time_str + ('.%d.log' % now_ms)
+    build_log_file_path = os.path.join(log_dir, log_file_name)
+
+    build_log = logging.FileHandler(build_log_file_path)
+
+    logformat = bb.msg.BBLogFormatter(format_str)
+    build_log.setFormatter(logformat)

+    bb.msg.addDefaultlogFilter(build_log)
+    logger.addHandler(build_log)
+
+    return (build_log, build_log_file_path)
+
+# stop logging to the build log if it exists
+def _close_build_log(build_log):
+    if build_log:
+        build_log.flush()
+        build_log.close()
+        logger.removeHandler(build_log)
+
+def main(server, eventHandler, params):
+    # set to a logging.FileHandler instance when a build starts;
+    # see _open_build_log()
+    build_log = None
+
+    # set to the log path when a build starts
+    build_log_file_path = None

-def main(server, eventHandler, params ):
     helper = uihelper.BBUIHelper()

+    # TODO don't use log output to determine when bitbake has started
+    #
+    # WARNING: this log handler cannot be removed, as localhostbecontroller
+    # relies on output in the toaster_ui.log file to determine whether
+    # the bitbake server has started, which only happens if
+    # this logger is setup here (see the TODO in the loop below)
     console = logging.StreamHandler(sys.stdout)
     format_str = "%(levelname)s: %(message)s"
     formatter = bb.msg.BBLogFormatter(format_str)
@@ -73,8 +116,6 @@ def main(server, eventHandler, params ):
     logger.addHandler(console)
     logger.setLevel(logging.INFO)

-    _, _, consolelogfile = _log_settings_from_server(server)
-
     # verify and warn
     build_history_enabled = True
     inheritlist, _ = server.runCommand(["getVariable", "INHERIT"])
@@ -87,8 +128,9 @@ def main(server, eventHandler, params ):
         logger.error("ToasterUI can only work in observer mode")
         return 1

-
+    # set to 1 when toasterui needs to shut down
     main.shutdown = 0
+
     interrupted = False
     return_value = 0
     errors = 0
@@ -98,25 +140,31 @@ def main(server, eventHandler, params ):

     buildinfohelper = BuildInfoHelper(server, build_history_enabled)

-    if buildinfohelper.brbe is not None and consolelogfile:
-        # if we are under managed mode we have no other UI and we need to write our own file
-        bb.utils.mkdirhier(os.path.dirname(consolelogfile))
-        conlogformat = bb.msg.BBLogFormatter(format_str)
-        consolelog = logging.FileHandler(consolelogfile)
-        bb.msg.addDefaultlogFilter(consolelog)
-        consolelog.setFormatter(conlogformat)
-        logger.addHandler(consolelog)
-
+    # write our own log files into bitbake's log directory;
+    # we're only interested in the path to the parent directory of
+    # this file, as we're writing our own logs into the same directory
+    consolelogfile = _log_settings_from_server(server)
+    log_dir = os.path.dirname(consolelogfile)
+    bb.utils.mkdirhier(log_dir)

     while True:
         try:
             event = eventHandler.waitEvent(0.25)
             if first:
                 first = False
+
+                # TODO don't use log output to determine when bitbake has started
+                #
+                # this is the line localhostbecontroller needs to
+                # see in toaster_ui.log which it uses to decide whether
+                # the bitbake server has started...
                 logger.info("ToasterUI waiting for events")

             if event is None:
                 if main.shutdown > 0:
+                    # if shutting down, close any open build log first
+                    _close_build_log(build_log)
+
                     break
                 continue

@@ -125,8 +173,21 @@ def main(server, eventHandler, params ):
             # pylint: disable=protected-access
             # the code will look into the protected variables of the event; no easy way around this

+            # we treat ParseStarted as the first event of toaster-triggered
+            # builds; that way we get the Build Configuration included in the log
+            # and any errors that occur before BuildStarted is fired
+            if isinstance(event, bb.event.ParseStarted):
+                if not (build_log and build_log_file_path):
+                    build_log, build_log_file_path = _open_build_log(log_dir)
+                continue
+
             if isinstance(event, bb.event.BuildStarted):
-                buildinfohelper.store_started_build(event, consolelogfile)
+                # command-line builds don't fire a ParseStarted event,
+                # so we have to start the log file for those on BuildStarted instead
+                if not (build_log and build_log_file_path):
+                    build_log, build_log_file_path = _open_build_log(log_dir)
+
+                buildinfohelper.store_started_build(event, build_log_file_path)

             if isinstance(event, (bb.build.TaskStarted, bb.build.TaskSucceeded, bb.build.TaskFailedSilent)):
                 buildinfohelper.update_and_store_task(event)
@@ -171,8 +232,6 @@ def main(server, eventHandler, params ):
             # timing and error informations from the parsing phase in Toaster
             if isinstance(event, (bb.event.SanityCheckPassed, bb.event.SanityCheck)):
                 continue
-            if isinstance(event, bb.event.ParseStarted):
-                continue
             if isinstance(event, bb.event.ParseProgress):
                 continue
             if isinstance(event, bb.event.ParseCompleted):
@@ -248,6 +307,12 @@ def main(server, eventHandler, params ):
                     errorcode = 1
                     logger.error("Command execution failed: %s", event.error)

+                # turn off logging to the current build log
+                _close_build_log(build_log)
+
+                # reset ready for next BuildStarted
+                build_log = None
+
                 # update the build info helper on BuildCompleted, not on CommandXXX
                 buildinfohelper.update_build_information(event, errors, warnings, taskfailures)
                 buildinfohelper.close(errorcode)
@@ -256,7 +321,6 @@ def main(server, eventHandler, params ):

                 # we start a new build info
                 if buildinfohelper.brbe is not None:
-
                     logger.debug("ToasterUI under BuildEnvironment management - exiting after the build")
                     server.terminateServer()
                 else:
@@ -298,8 +362,9 @@ def main(server, eventHandler, params ):
                 continue

             if isinstance(event, bb.cooker.CookerExit):
-                # exit when the server exits
-                break
+                # shutdown when bitbake server shuts down
+                main.shutdown = 1
+                continue

             # ignore
             if isinstance(event, (bb.event.BuildBase,
@@ -350,9 +415,8 @@ def main(server, eventHandler, params ):
             # make sure we return with an error
             return_value += 1

-    if interrupted:
-        if return_value == 0:
-            return_value += 1
+    if interrupted and return_value == 0:
+        return_value += 1

     logger.warn("Return value is %d", return_value)
     return return_value
--
Elliot Smith
Software Engineer
Intel OTC

---------------------------------------------------------------------
Intel Corporation (UK) Limited
Registered No. 1134945 (England)
Registered Office: Pipers Way, Swindon SN3 1RJ
VAT No: 860 2173 47

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.



^ permalink raw reply related	[flat|nested] 6+ messages in thread

* Re: [review-request][PATCH][v2] toasterui: Create per-build logs
  2015-10-28 13:44 [review-request][PATCH][v2] toasterui: Create per-build logs Elliot Smith
@ 2015-10-28 13:47 ` Smith, Elliot
  2015-10-29 12:03   ` Ed Bartosh
  2015-11-02  1:15 ` Brian Avery
  1 sibling, 1 reply; 6+ messages in thread
From: Smith, Elliot @ 2015-10-28 13:47 UTC (permalink / raw
  To: toaster

[-- Attachment #1: Type: text/plain, Size: 13999 bytes --]

Note: I think this is actually v3, but I lost track.

Elliot

On 28 October 2015 at 13:44, Elliot Smith <elliot.smith@intel.com> wrote:

> v2:
>
> * Toaster doesn't get a ParseStarted event for command-line builds,
> so revert to using BuildStarted (for cli builds only). This means we lose
> the "Build configuration" for command-line builds (not for Toaster builds);
> but as the user is building on the command-line, they can see the
> build configuration anyway.
>
> * Changed getSetVariable for BB_CONSOLELOG to getVariable, as we have
> a read-only bitbake server, which means variable writes fail;
> and we don't need to set that variable anyway (we only read it so we
> know which directory to put our logs into).
>
> ---
>
> Rather than relying on bug 8411, which is conveniently creating
> separate log files for each of our builds, create our own
> log file for each build.
>
> The log files are created in the same tmp directories that
> bitbake uses, but are timestamped to the millisecond to avoid
> name collisions.
>
> Each log file is opened on a ParseStarted event (for builds
> triggered by Toaster) or BuildStarted event (for builds on the
> command line: Toaster doesn't get the ParseStarted event
> for command-line builds).
>
> The log file is closed on the BuildCompleted event, or if the
> build fails.
>
> Because we start logging on ParseStarted for Toaster builds,
> we're able to capture the "Build Configuration" section which
> bitbake writes to output. We lose this section for cli builds.
>
> [YOCTO #8373]
>
> Signed-off-by: Elliot Smith <elliot.smith@intel.com>
> ---
>  bitbake/lib/bb/ui/buildinfohelper.py |   8 +--
>  bitbake/lib/bb/ui/toasterui.py       | 116
> +++++++++++++++++++++++++++--------
>  2 files changed, 94 insertions(+), 30 deletions(-)
>
> diff --git a/bitbake/lib/bb/ui/buildinfohelper.py
> b/bitbake/lib/bb/ui/buildinfohelper.py
> index 2fc1a43..78f1e92 100644
> --- a/bitbake/lib/bb/ui/buildinfohelper.py
> +++ b/bitbake/lib/bb/ui/buildinfohelper.py
> @@ -784,7 +784,7 @@ class BuildInfoHelper(object):
>      ## methods to convert event/external info into objects that the ORM
> layer uses
>
>
> -    def _get_build_information(self, consolelogfile):
> +    def _get_build_information(self, build_log_path):
>          build_info = {}
>          # Generate an identifier for each new build
>
> @@ -793,7 +793,7 @@ class BuildInfoHelper(object):
>          build_info['distro_version'] =
> self.server.runCommand(["getVariable", "DISTRO_VERSION"])[0]
>          build_info['started_on'] = timezone.now()
>          build_info['completed_on'] = timezone.now()
> -        build_info['cooker_log_path'] = consolelogfile
> +        build_info['cooker_log_path'] = build_log_path
>          build_info['build_name'] = self.server.runCommand(["getVariable",
> "BUILDNAME"])[0]
>          build_info['bitbake_version'] =
> self.server.runCommand(["getVariable", "BB_VERSION"])[0]
>
> @@ -934,9 +934,9 @@ class BuildInfoHelper(object):
>                  logger.warn("buildinfohelper: cannot identify layer
> exception:%s ", nee)
>
>
> -    def store_started_build(self, event, consolelogfile):
> +    def store_started_build(self, event, build_log_path):
>          assert '_pkgs' in vars(event)
> -        build_information = self._get_build_information(consolelogfile)
> +        build_information = self._get_build_information(build_log_path)
>
>          build_obj =
> self.orm_wrapper.create_build_object(build_information, self.brbe,
> self.project)
>
> diff --git a/bitbake/lib/bb/ui/toasterui.py
> b/bitbake/lib/bb/ui/toasterui.py
> index 2b3bc3f..3d26150 100644
> --- a/bitbake/lib/bb/ui/toasterui.py
> +++ b/bitbake/lib/bb/ui/toasterui.py
> @@ -21,6 +21,7 @@
>  # 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
>
>  from __future__ import division
> +import time
>  import sys
>  try:
>      import bb
> @@ -43,8 +44,6 @@ featureSet = [bb.cooker.CookerFeatures.HOB_EXTRA_CACHES,
> bb.cooker.CookerFeature
>  logger = logging.getLogger("ToasterLogger")
>  interactive = sys.stdout.isatty()
>
> -
> -
>  def _log_settings_from_server(server):
>      # Get values of variables which control our output
>      includelogs, error = server.runCommand(["getVariable",
> "BBINCLUDELOGS"])
> @@ -55,16 +54,60 @@ def _log_settings_from_server(server):
>      if error:
>          logger.error("Unable to get the value of BBINCLUDELOGS_LINES
> variable: %s", error)
>          raise BaseException(error)
> -    consolelogfile, error = server.runCommand(["getSetVariable",
> "BB_CONSOLELOG"])
> +    consolelogfile, error = server.runCommand(["getVariable",
> "BB_CONSOLELOG"])
>      if error:
>          logger.error("Unable to get the value of BB_CONSOLELOG variable:
> %s", error)
>          raise BaseException(error)
> -    return includelogs, loglines, consolelogfile
> +    return consolelogfile
> +
> +# create a log file for a single build and direct the logger at it;
> +# log file name is timestamped to the millisecond (depending
> +# on system clock accuracy) to ensure it doesn't overlap with
> +# other log file names
> +#
> +# returns (log file, path to log file) for a build
> +def _open_build_log(log_dir):
> +    format_str = "%(levelname)s: %(message)s"
> +
> +    now = time.time()
> +    now_ms = int((now - int(now)) * 1000)
> +    time_str = time.strftime('build_%Y%m%d_%H%M%S', time.localtime(now))
> +    log_file_name = time_str + ('.%d.log' % now_ms)
> +    build_log_file_path = os.path.join(log_dir, log_file_name)
> +
> +    build_log = logging.FileHandler(build_log_file_path)
> +
> +    logformat = bb.msg.BBLogFormatter(format_str)
> +    build_log.setFormatter(logformat)
>
> +    bb.msg.addDefaultlogFilter(build_log)
> +    logger.addHandler(build_log)
> +
> +    return (build_log, build_log_file_path)
> +
> +# stop logging to the build log if it exists
> +def _close_build_log(build_log):
> +    if build_log:
> +        build_log.flush()
> +        build_log.close()
> +        logger.removeHandler(build_log)
> +
> +def main(server, eventHandler, params):
> +    # set to a logging.FileHandler instance when a build starts;
> +    # see _open_build_log()
> +    build_log = None
> +
> +    # set to the log path when a build starts
> +    build_log_file_path = None
>
> -def main(server, eventHandler, params ):
>      helper = uihelper.BBUIHelper()
>
> +    # TODO don't use log output to determine when bitbake has started
> +    #
> +    # WARNING: this log handler cannot be removed, as
> localhostbecontroller
> +    # relies on output in the toaster_ui.log file to determine whether
> +    # the bitbake server has started, which only happens if
> +    # this logger is setup here (see the TODO in the loop below)
>      console = logging.StreamHandler(sys.stdout)
>      format_str = "%(levelname)s: %(message)s"
>      formatter = bb.msg.BBLogFormatter(format_str)
> @@ -73,8 +116,6 @@ def main(server, eventHandler, params ):
>      logger.addHandler(console)
>      logger.setLevel(logging.INFO)
>
> -    _, _, consolelogfile = _log_settings_from_server(server)
> -
>      # verify and warn
>      build_history_enabled = True
>      inheritlist, _ = server.runCommand(["getVariable", "INHERIT"])
> @@ -87,8 +128,9 @@ def main(server, eventHandler, params ):
>          logger.error("ToasterUI can only work in observer mode")
>          return 1
>
> -
> +    # set to 1 when toasterui needs to shut down
>      main.shutdown = 0
> +
>      interrupted = False
>      return_value = 0
>      errors = 0
> @@ -98,25 +140,31 @@ def main(server, eventHandler, params ):
>
>      buildinfohelper = BuildInfoHelper(server, build_history_enabled)
>
> -    if buildinfohelper.brbe is not None and consolelogfile:
> -        # if we are under managed mode we have no other UI and we need to
> write our own file
> -        bb.utils.mkdirhier(os.path.dirname(consolelogfile))
> -        conlogformat = bb.msg.BBLogFormatter(format_str)
> -        consolelog = logging.FileHandler(consolelogfile)
> -        bb.msg.addDefaultlogFilter(consolelog)
> -        consolelog.setFormatter(conlogformat)
> -        logger.addHandler(consolelog)
> -
> +    # write our own log files into bitbake's log directory;
> +    # we're only interested in the path to the parent directory of
> +    # this file, as we're writing our own logs into the same directory
> +    consolelogfile = _log_settings_from_server(server)
> +    log_dir = os.path.dirname(consolelogfile)
> +    bb.utils.mkdirhier(log_dir)
>
>      while True:
>          try:
>              event = eventHandler.waitEvent(0.25)
>              if first:
>                  first = False
> +
> +                # TODO don't use log output to determine when bitbake has
> started
> +                #
> +                # this is the line localhostbecontroller needs to
> +                # see in toaster_ui.log which it uses to decide whether
> +                # the bitbake server has started...
>                  logger.info("ToasterUI waiting for events")
>
>              if event is None:
>                  if main.shutdown > 0:
> +                    # if shutting down, close any open build log first
> +                    _close_build_log(build_log)
> +
>                      break
>                  continue
>
> @@ -125,8 +173,21 @@ def main(server, eventHandler, params ):
>              # pylint: disable=protected-access
>              # the code will look into the protected variables of the
> event; no easy way around this
>
> +            # we treat ParseStarted as the first event of
> toaster-triggered
> +            # builds; that way we get the Build Configuration included in
> the log
> +            # and any errors that occur before BuildStarted is fired
> +            if isinstance(event, bb.event.ParseStarted):
> +                if not (build_log and build_log_file_path):
> +                    build_log, build_log_file_path =
> _open_build_log(log_dir)
> +                continue
> +
>              if isinstance(event, bb.event.BuildStarted):
> -                buildinfohelper.store_started_build(event, consolelogfile)
> +                # command-line builds don't fire a ParseStarted event,
> +                # so we have to start the log file for those on
> BuildStarted instead
> +                if not (build_log and build_log_file_path):
> +                    build_log, build_log_file_path =
> _open_build_log(log_dir)
> +
> +                buildinfohelper.store_started_build(event,
> build_log_file_path)
>
>              if isinstance(event, (bb.build.TaskStarted,
> bb.build.TaskSucceeded, bb.build.TaskFailedSilent)):
>                  buildinfohelper.update_and_store_task(event)
> @@ -171,8 +232,6 @@ def main(server, eventHandler, params ):
>              # timing and error informations from the parsing phase in
> Toaster
>              if isinstance(event, (bb.event.SanityCheckPassed,
> bb.event.SanityCheck)):
>                  continue
> -            if isinstance(event, bb.event.ParseStarted):
> -                continue
>              if isinstance(event, bb.event.ParseProgress):
>                  continue
>              if isinstance(event, bb.event.ParseCompleted):
> @@ -248,6 +307,12 @@ def main(server, eventHandler, params ):
>                      errorcode = 1
>                      logger.error("Command execution failed: %s",
> event.error)
>
> +                # turn off logging to the current build log
> +                _close_build_log(build_log)
> +
> +                # reset ready for next BuildStarted
> +                build_log = None
> +
>                  # update the build info helper on BuildCompleted, not on
> CommandXXX
>                  buildinfohelper.update_build_information(event, errors,
> warnings, taskfailures)
>                  buildinfohelper.close(errorcode)
> @@ -256,7 +321,6 @@ def main(server, eventHandler, params ):
>
>                  # we start a new build info
>                  if buildinfohelper.brbe is not None:
> -
>                      logger.debug("ToasterUI under BuildEnvironment
> management - exiting after the build")
>                      server.terminateServer()
>                  else:
> @@ -298,8 +362,9 @@ def main(server, eventHandler, params ):
>                  continue
>
>              if isinstance(event, bb.cooker.CookerExit):
> -                # exit when the server exits
> -                break
> +                # shutdown when bitbake server shuts down
> +                main.shutdown = 1
> +                continue
>
>              # ignore
>              if isinstance(event, (bb.event.BuildBase,
> @@ -350,9 +415,8 @@ def main(server, eventHandler, params ):
>              # make sure we return with an error
>              return_value += 1
>
> -    if interrupted:
> -        if return_value == 0:
> -            return_value += 1
> +    if interrupted and return_value == 0:
> +        return_value += 1
>
>      logger.warn("Return value is %d", return_value)
>      return return_value
> --
> Elliot Smith
> Software Engineer
> Intel OTC
>
> ---------------------------------------------------------------------
> Intel Corporation (UK) Limited
> Registered No. 1134945 (England)
> Registered Office: Pipers Way, Swindon SN3 1RJ
> VAT No: 860 2173 47
>
> This e-mail and any attachments may contain confidential material for
> the sole use of the intended recipient(s). Any review or distribution
> by others is strictly prohibited. If you are not the intended
> recipient, please contact the sender and delete all copies.
>
>


-- 
Elliot Smith
Software Engineer
Intel Open Source Technology Centre

[-- Attachment #2: Type: text/html, Size: 16368 bytes --]

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [review-request][PATCH][v2] toasterui: Create per-build logs
  2015-10-28 13:47 ` Smith, Elliot
@ 2015-10-29 12:03   ` Ed Bartosh
  0 siblings, 0 replies; 6+ messages in thread
From: Ed Bartosh @ 2015-10-29 12:03 UTC (permalink / raw
  To: Smith, Elliot; +Cc: toaster

Hi,

sent to bitbake-devel and pushed to toaster-next

Regards,
Ed

On Wed, Oct 28, 2015 at 01:47:08PM +0000, Smith, Elliot wrote:
> Note: I think this is actually v3, but I lost track.
> 
> Elliot
> 
> On 28 October 2015 at 13:44, Elliot Smith <elliot.smith@intel.com> wrote:
> 
> > v2:
> >
> > * Toaster doesn't get a ParseStarted event for command-line builds,
> > so revert to using BuildStarted (for cli builds only). This means we lose
> > the "Build configuration" for command-line builds (not for Toaster builds);
> > but as the user is building on the command-line, they can see the
> > build configuration anyway.
> >
> > * Changed getSetVariable for BB_CONSOLELOG to getVariable, as we have
> > a read-only bitbake server, which means variable writes fail;
> > and we don't need to set that variable anyway (we only read it so we
> > know which directory to put our logs into).
> >
> > ---
> >
> > Rather than relying on bug 8411, which is conveniently creating
> > separate log files for each of our builds, create our own
> > log file for each build.
> >
> > The log files are created in the same tmp directories that
> > bitbake uses, but are timestamped to the millisecond to avoid
> > name collisions.
> >
> > Each log file is opened on a ParseStarted event (for builds
> > triggered by Toaster) or BuildStarted event (for builds on the
> > command line: Toaster doesn't get the ParseStarted event
> > for command-line builds).
> >
> > The log file is closed on the BuildCompleted event, or if the
> > build fails.
> >
> > Because we start logging on ParseStarted for Toaster builds,
> > we're able to capture the "Build Configuration" section which
> > bitbake writes to output. We lose this section for cli builds.
> >
> > [YOCTO #8373]
> >
> > Signed-off-by: Elliot Smith <elliot.smith@intel.com>
> > ---
> >  bitbake/lib/bb/ui/buildinfohelper.py |   8 +--
> >  bitbake/lib/bb/ui/toasterui.py       | 116
> > +++++++++++++++++++++++++++--------
> >  2 files changed, 94 insertions(+), 30 deletions(-)
> >
> > diff --git a/bitbake/lib/bb/ui/buildinfohelper.py
> > b/bitbake/lib/bb/ui/buildinfohelper.py
> > index 2fc1a43..78f1e92 100644
> > --- a/bitbake/lib/bb/ui/buildinfohelper.py
> > +++ b/bitbake/lib/bb/ui/buildinfohelper.py
> > @@ -784,7 +784,7 @@ class BuildInfoHelper(object):
> >      ## methods to convert event/external info into objects that the ORM
> > layer uses
> >
> >
> > -    def _get_build_information(self, consolelogfile):
> > +    def _get_build_information(self, build_log_path):
> >          build_info = {}
> >          # Generate an identifier for each new build
> >
> > @@ -793,7 +793,7 @@ class BuildInfoHelper(object):
> >          build_info['distro_version'] =
> > self.server.runCommand(["getVariable", "DISTRO_VERSION"])[0]
> >          build_info['started_on'] = timezone.now()
> >          build_info['completed_on'] = timezone.now()
> > -        build_info['cooker_log_path'] = consolelogfile
> > +        build_info['cooker_log_path'] = build_log_path
> >          build_info['build_name'] = self.server.runCommand(["getVariable",
> > "BUILDNAME"])[0]
> >          build_info['bitbake_version'] =
> > self.server.runCommand(["getVariable", "BB_VERSION"])[0]
> >
> > @@ -934,9 +934,9 @@ class BuildInfoHelper(object):
> >                  logger.warn("buildinfohelper: cannot identify layer
> > exception:%s ", nee)
> >
> >
> > -    def store_started_build(self, event, consolelogfile):
> > +    def store_started_build(self, event, build_log_path):
> >          assert '_pkgs' in vars(event)
> > -        build_information = self._get_build_information(consolelogfile)
> > +        build_information = self._get_build_information(build_log_path)
> >
> >          build_obj =
> > self.orm_wrapper.create_build_object(build_information, self.brbe,
> > self.project)
> >
> > diff --git a/bitbake/lib/bb/ui/toasterui.py
> > b/bitbake/lib/bb/ui/toasterui.py
> > index 2b3bc3f..3d26150 100644
> > --- a/bitbake/lib/bb/ui/toasterui.py
> > +++ b/bitbake/lib/bb/ui/toasterui.py
> > @@ -21,6 +21,7 @@
> >  # 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
> >
> >  from __future__ import division
> > +import time
> >  import sys
> >  try:
> >      import bb
> > @@ -43,8 +44,6 @@ featureSet = [bb.cooker.CookerFeatures.HOB_EXTRA_CACHES,
> > bb.cooker.CookerFeature
> >  logger = logging.getLogger("ToasterLogger")
> >  interactive = sys.stdout.isatty()
> >
> > -
> > -
> >  def _log_settings_from_server(server):
> >      # Get values of variables which control our output
> >      includelogs, error = server.runCommand(["getVariable",
> > "BBINCLUDELOGS"])
> > @@ -55,16 +54,60 @@ def _log_settings_from_server(server):
> >      if error:
> >          logger.error("Unable to get the value of BBINCLUDELOGS_LINES
> > variable: %s", error)
> >          raise BaseException(error)
> > -    consolelogfile, error = server.runCommand(["getSetVariable",
> > "BB_CONSOLELOG"])
> > +    consolelogfile, error = server.runCommand(["getVariable",
> > "BB_CONSOLELOG"])
> >      if error:
> >          logger.error("Unable to get the value of BB_CONSOLELOG variable:
> > %s", error)
> >          raise BaseException(error)
> > -    return includelogs, loglines, consolelogfile
> > +    return consolelogfile
> > +
> > +# create a log file for a single build and direct the logger at it;
> > +# log file name is timestamped to the millisecond (depending
> > +# on system clock accuracy) to ensure it doesn't overlap with
> > +# other log file names
> > +#
> > +# returns (log file, path to log file) for a build
> > +def _open_build_log(log_dir):
> > +    format_str = "%(levelname)s: %(message)s"
> > +
> > +    now = time.time()
> > +    now_ms = int((now - int(now)) * 1000)
> > +    time_str = time.strftime('build_%Y%m%d_%H%M%S', time.localtime(now))
> > +    log_file_name = time_str + ('.%d.log' % now_ms)
> > +    build_log_file_path = os.path.join(log_dir, log_file_name)
> > +
> > +    build_log = logging.FileHandler(build_log_file_path)
> > +
> > +    logformat = bb.msg.BBLogFormatter(format_str)
> > +    build_log.setFormatter(logformat)
> >
> > +    bb.msg.addDefaultlogFilter(build_log)
> > +    logger.addHandler(build_log)
> > +
> > +    return (build_log, build_log_file_path)
> > +
> > +# stop logging to the build log if it exists
> > +def _close_build_log(build_log):
> > +    if build_log:
> > +        build_log.flush()
> > +        build_log.close()
> > +        logger.removeHandler(build_log)
> > +
> > +def main(server, eventHandler, params):
> > +    # set to a logging.FileHandler instance when a build starts;
> > +    # see _open_build_log()
> > +    build_log = None
> > +
> > +    # set to the log path when a build starts
> > +    build_log_file_path = None
> >
> > -def main(server, eventHandler, params ):
> >      helper = uihelper.BBUIHelper()
> >
> > +    # TODO don't use log output to determine when bitbake has started
> > +    #
> > +    # WARNING: this log handler cannot be removed, as
> > localhostbecontroller
> > +    # relies on output in the toaster_ui.log file to determine whether
> > +    # the bitbake server has started, which only happens if
> > +    # this logger is setup here (see the TODO in the loop below)
> >      console = logging.StreamHandler(sys.stdout)
> >      format_str = "%(levelname)s: %(message)s"
> >      formatter = bb.msg.BBLogFormatter(format_str)
> > @@ -73,8 +116,6 @@ def main(server, eventHandler, params ):
> >      logger.addHandler(console)
> >      logger.setLevel(logging.INFO)
> >
> > -    _, _, consolelogfile = _log_settings_from_server(server)
> > -
> >      # verify and warn
> >      build_history_enabled = True
> >      inheritlist, _ = server.runCommand(["getVariable", "INHERIT"])
> > @@ -87,8 +128,9 @@ def main(server, eventHandler, params ):
> >          logger.error("ToasterUI can only work in observer mode")
> >          return 1
> >
> > -
> > +    # set to 1 when toasterui needs to shut down
> >      main.shutdown = 0
> > +
> >      interrupted = False
> >      return_value = 0
> >      errors = 0
> > @@ -98,25 +140,31 @@ def main(server, eventHandler, params ):
> >
> >      buildinfohelper = BuildInfoHelper(server, build_history_enabled)
> >
> > -    if buildinfohelper.brbe is not None and consolelogfile:
> > -        # if we are under managed mode we have no other UI and we need to
> > write our own file
> > -        bb.utils.mkdirhier(os.path.dirname(consolelogfile))
> > -        conlogformat = bb.msg.BBLogFormatter(format_str)
> > -        consolelog = logging.FileHandler(consolelogfile)
> > -        bb.msg.addDefaultlogFilter(consolelog)
> > -        consolelog.setFormatter(conlogformat)
> > -        logger.addHandler(consolelog)
> > -
> > +    # write our own log files into bitbake's log directory;
> > +    # we're only interested in the path to the parent directory of
> > +    # this file, as we're writing our own logs into the same directory
> > +    consolelogfile = _log_settings_from_server(server)
> > +    log_dir = os.path.dirname(consolelogfile)
> > +    bb.utils.mkdirhier(log_dir)
> >
> >      while True:
> >          try:
> >              event = eventHandler.waitEvent(0.25)
> >              if first:
> >                  first = False
> > +
> > +                # TODO don't use log output to determine when bitbake has
> > started
> > +                #
> > +                # this is the line localhostbecontroller needs to
> > +                # see in toaster_ui.log which it uses to decide whether
> > +                # the bitbake server has started...
> >                  logger.info("ToasterUI waiting for events")
> >
> >              if event is None:
> >                  if main.shutdown > 0:
> > +                    # if shutting down, close any open build log first
> > +                    _close_build_log(build_log)
> > +
> >                      break
> >                  continue
> >
> > @@ -125,8 +173,21 @@ def main(server, eventHandler, params ):
> >              # pylint: disable=protected-access
> >              # the code will look into the protected variables of the
> > event; no easy way around this
> >
> > +            # we treat ParseStarted as the first event of
> > toaster-triggered
> > +            # builds; that way we get the Build Configuration included in
> > the log
> > +            # and any errors that occur before BuildStarted is fired
> > +            if isinstance(event, bb.event.ParseStarted):
> > +                if not (build_log and build_log_file_path):
> > +                    build_log, build_log_file_path =
> > _open_build_log(log_dir)
> > +                continue
> > +
> >              if isinstance(event, bb.event.BuildStarted):
> > -                buildinfohelper.store_started_build(event, consolelogfile)
> > +                # command-line builds don't fire a ParseStarted event,
> > +                # so we have to start the log file for those on
> > BuildStarted instead
> > +                if not (build_log and build_log_file_path):
> > +                    build_log, build_log_file_path =
> > _open_build_log(log_dir)
> > +
> > +                buildinfohelper.store_started_build(event,
> > build_log_file_path)
> >
> >              if isinstance(event, (bb.build.TaskStarted,
> > bb.build.TaskSucceeded, bb.build.TaskFailedSilent)):
> >                  buildinfohelper.update_and_store_task(event)
> > @@ -171,8 +232,6 @@ def main(server, eventHandler, params ):
> >              # timing and error informations from the parsing phase in
> > Toaster
> >              if isinstance(event, (bb.event.SanityCheckPassed,
> > bb.event.SanityCheck)):
> >                  continue
> > -            if isinstance(event, bb.event.ParseStarted):
> > -                continue
> >              if isinstance(event, bb.event.ParseProgress):
> >                  continue
> >              if isinstance(event, bb.event.ParseCompleted):
> > @@ -248,6 +307,12 @@ def main(server, eventHandler, params ):
> >                      errorcode = 1
> >                      logger.error("Command execution failed: %s",
> > event.error)
> >
> > +                # turn off logging to the current build log
> > +                _close_build_log(build_log)
> > +
> > +                # reset ready for next BuildStarted
> > +                build_log = None
> > +
> >                  # update the build info helper on BuildCompleted, not on
> > CommandXXX
> >                  buildinfohelper.update_build_information(event, errors,
> > warnings, taskfailures)
> >                  buildinfohelper.close(errorcode)
> > @@ -256,7 +321,6 @@ def main(server, eventHandler, params ):
> >
> >                  # we start a new build info
> >                  if buildinfohelper.brbe is not None:
> > -
> >                      logger.debug("ToasterUI under BuildEnvironment
> > management - exiting after the build")
> >                      server.terminateServer()
> >                  else:
> > @@ -298,8 +362,9 @@ def main(server, eventHandler, params ):
> >                  continue
> >
> >              if isinstance(event, bb.cooker.CookerExit):
> > -                # exit when the server exits
> > -                break
> > +                # shutdown when bitbake server shuts down
> > +                main.shutdown = 1
> > +                continue
> >
> >              # ignore
> >              if isinstance(event, (bb.event.BuildBase,
> > @@ -350,9 +415,8 @@ def main(server, eventHandler, params ):
> >              # make sure we return with an error
> >              return_value += 1
> >
> > -    if interrupted:
> > -        if return_value == 0:
> > -            return_value += 1
> > +    if interrupted and return_value == 0:
> > +        return_value += 1
> >
> >      logger.warn("Return value is %d", return_value)
> >      return return_value
> > --
> > Elliot Smith
> > Software Engineer
> > Intel OTC
> >
> > ---------------------------------------------------------------------
> > Intel Corporation (UK) Limited
> > Registered No. 1134945 (England)
> > Registered Office: Pipers Way, Swindon SN3 1RJ
> > VAT No: 860 2173 47
> >
> > This e-mail and any attachments may contain confidential material for
> > the sole use of the intended recipient(s). Any review or distribution
> > by others is strictly prohibited. If you are not the intended
> > recipient, please contact the sender and delete all copies.
> >
> >
> 
> 
> -- 
> Elliot Smith
> Software Engineer
> Intel Open Source Technology Centre

> -- 
> _______________________________________________
> toaster mailing list
> toaster@yoctoproject.org
> https://lists.yoctoproject.org/listinfo/toaster


^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [review-request][PATCH][v2] toasterui: Create per-build logs
  2015-10-28 13:44 [review-request][PATCH][v2] toasterui: Create per-build logs Elliot Smith
  2015-10-28 13:47 ` Smith, Elliot
@ 2015-11-02  1:15 ` Brian Avery
  2015-11-02 10:04   ` Smith, Elliot
  1 sibling, 1 reply; 6+ messages in thread
From: Brian Avery @ 2015-11-02  1:15 UTC (permalink / raw
  To: Elliot Smith; +Cc: toaster

Hi Elliot,

Umm,

Sorry, I've been sick. I am just catching up (slowly).


So I looked at the lack of a parse started event for the cli builds
and it's pretty ez to get one in cli mode too.  I'm pretty sure it's
just the fact that we weren't passing in a event mask and so got the
default one.  BTW, whenever an event issue comes up I find it easiest
to instrument knotty.py (the ncurses command line ui) as it is the
most complete.

With the following diff:

diff --git a/bitbake/lib/bb/ui/toasterui.py b/bitbake/lib/bb/ui/toasterui.py
index 3d26150..3b8f689 100644
--- a/bitbake/lib/bb/ui/toasterui.py
+++ b/bitbake/lib/bb/ui/toasterui.py
@@ -138,6 +138,20 @@ def main(server, eventHandler, params):
     taskfailures = []
     first = True
+
+    _evt_list = [ "bb.runqueue.runQueueExitWait",
"bb.event.LogExecTTY", "logging.LogRecord",
+              "bb.build.TaskFailed", "bb.build.TaskBase",
"bb.event.ParseStarted",
+              "bb.event.ParseProgress", "bb.event.ParseCompleted",
"bb.event.CacheLoadStarted",
+              "bb.event.CacheLoadProgress",
"bb.event.CacheLoadCompleted", "bb.command.CommandFailed",
+              "bb.command.CommandExit",
"bb.command.CommandCompleted",  "bb.cooker.CookerExit",
+              "bb.event.MultipleProviders", "bb.event.NoProvider",
"bb.runqueue.sceneQueueTaskStarted",
+              "bb.runqueue.runQueueTaskStarted",
"bb.runqueue.runQueueTaskFailed", "bb.runqueue.sceneQueueTaskFailed",
+              "bb.event.BuildBase", "bb.build.TaskStarted",
"bb.build.TaskSucceeded", "bb.build.TaskFailedSilent"]
+
+    llevel, debug_domains = bb.msg.constructLogOptions()
+    logger.warn("BAVERY: setting event mask")
+    server.runCommand(["setEventMask", server.getEventHandle(),
llevel, debug_domains, _evt_list])
+
     buildinfohelper = BuildInfoHelper(server, build_history_enabled)


     # write our own log files into bitbake's log directory;

@@ -150,6 +164,14 @@ def main(server, eventHandler, params):
     while True:
         try:
             event = eventHandler.waitEvent(0.25)
+            if isinstance(event, bb.event.ParseStarted):
+                logger.warn("BAVERY: parse started")
+            if isinstance(event, bb.event.ParseProgress):
+                logger.warn("BAVERY: parse progress")
+            if isinstance(event, bb.event.ParseCompleted):
+                logger.warn("BAVERY: parse completed")
+
+
             if first:
                 first = False


Gives the following output: (many parse progress events...):


toaster_ui.log:WARNING: BAVERY: setting event mask
toaster_ui.log:WARNING: BAVERY: parse started
toaster_ui.log:WARNING: BAVERY: parse progress
toaster_ui.log:WARNING: BAVERY: parse progress
....
toaster_ui.log:WARNING: BAVERY: parse completed

On Wed, Oct 28, 2015 at 6:44 AM, Elliot Smith <elliot.smith@intel.com> wrote:
> v2:
>
> * Toaster doesn't get a ParseStarted event for command-line builds,
> so revert to using BuildStarted (for cli builds only). This means we lose
> the "Build configuration" for command-line builds (not for Toaster builds);
> but as the user is building on the command-line, they can see the
> build configuration anyway.
>
> * Changed getSetVariable for BB_CONSOLELOG to getVariable, as we have
> a read-only bitbake server, which means variable writes fail;
> and we don't need to set that variable anyway (we only read it so we
> know which directory to put our logs into).
>
> ---
>
> Rather than relying on bug 8411, which is conveniently creating
> separate log files for each of our builds, create our own
> log file for each build.
>
> The log files are created in the same tmp directories that
> bitbake uses, but are timestamped to the millisecond to avoid
> name collisions.
>
> Each log file is opened on a ParseStarted event (for builds
> triggered by Toaster) or BuildStarted event (for builds on the
> command line: Toaster doesn't get the ParseStarted event
> for command-line builds).
>
> The log file is closed on the BuildCompleted event, or if the
> build fails.
>
> Because we start logging on ParseStarted for Toaster builds,
> we're able to capture the "Build Configuration" section which
> bitbake writes to output. We lose this section for cli builds.
>
> [YOCTO #8373]
>
> Signed-off-by: Elliot Smith <elliot.smith@intel.com>
> ---
>  bitbake/lib/bb/ui/buildinfohelper.py |   8 +--
>  bitbake/lib/bb/ui/toasterui.py       | 116 +++++++++++++++++++++++++++--------
>  2 files changed, 94 insertions(+), 30 deletions(-)
>
> diff --git a/bitbake/lib/bb/ui/buildinfohelper.py b/bitbake/lib/bb/ui/buildinfohelper.py
> index 2fc1a43..78f1e92 100644
> --- a/bitbake/lib/bb/ui/buildinfohelper.py
> +++ b/bitbake/lib/bb/ui/buildinfohelper.py
> @@ -784,7 +784,7 @@ class BuildInfoHelper(object):
>      ## methods to convert event/external info into objects that the ORM layer uses
>
>
> -    def _get_build_information(self, consolelogfile):
> +    def _get_build_information(self, build_log_path):
>          build_info = {}
>          # Generate an identifier for each new build
>
> @@ -793,7 +793,7 @@ class BuildInfoHelper(object):
>          build_info['distro_version'] = self.server.runCommand(["getVariable", "DISTRO_VERSION"])[0]
>          build_info['started_on'] = timezone.now()
>          build_info['completed_on'] = timezone.now()
> -        build_info['cooker_log_path'] = consolelogfile
> +        build_info['cooker_log_path'] = build_log_path
>          build_info['build_name'] = self.server.runCommand(["getVariable", "BUILDNAME"])[0]
>          build_info['bitbake_version'] = self.server.runCommand(["getVariable", "BB_VERSION"])[0]
>
> @@ -934,9 +934,9 @@ class BuildInfoHelper(object):
>                  logger.warn("buildinfohelper: cannot identify layer exception:%s ", nee)
>
>
> -    def store_started_build(self, event, consolelogfile):
> +    def store_started_build(self, event, build_log_path):
>          assert '_pkgs' in vars(event)
> -        build_information = self._get_build_information(consolelogfile)
> +        build_information = self._get_build_information(build_log_path)
>
>          build_obj = self.orm_wrapper.create_build_object(build_information, self.brbe, self.project)
>
> diff --git a/bitbake/lib/bb/ui/toasterui.py b/bitbake/lib/bb/ui/toasterui.py
> index 2b3bc3f..3d26150 100644
> --- a/bitbake/lib/bb/ui/toasterui.py
> +++ b/bitbake/lib/bb/ui/toasterui.py
> @@ -21,6 +21,7 @@
>  # 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
>
>  from __future__ import division
> +import time
>  import sys
>  try:
>      import bb
> @@ -43,8 +44,6 @@ featureSet = [bb.cooker.CookerFeatures.HOB_EXTRA_CACHES, bb.cooker.CookerFeature
>  logger = logging.getLogger("ToasterLogger")
>  interactive = sys.stdout.isatty()
>
> -
> -
>  def _log_settings_from_server(server):
>      # Get values of variables which control our output
>      includelogs, error = server.runCommand(["getVariable", "BBINCLUDELOGS"])
> @@ -55,16 +54,60 @@ def _log_settings_from_server(server):
>      if error:
>          logger.error("Unable to get the value of BBINCLUDELOGS_LINES variable: %s", error)
>          raise BaseException(error)
> -    consolelogfile, error = server.runCommand(["getSetVariable", "BB_CONSOLELOG"])
> +    consolelogfile, error = server.runCommand(["getVariable", "BB_CONSOLELOG"])
>      if error:
>          logger.error("Unable to get the value of BB_CONSOLELOG variable: %s", error)
>          raise BaseException(error)
> -    return includelogs, loglines, consolelogfile
> +    return consolelogfile
> +
> +# create a log file for a single build and direct the logger at it;
> +# log file name is timestamped to the millisecond (depending
> +# on system clock accuracy) to ensure it doesn't overlap with
> +# other log file names
> +#
> +# returns (log file, path to log file) for a build
> +def _open_build_log(log_dir):
> +    format_str = "%(levelname)s: %(message)s"
> +
> +    now = time.time()
> +    now_ms = int((now - int(now)) * 1000)
> +    time_str = time.strftime('build_%Y%m%d_%H%M%S', time.localtime(now))
> +    log_file_name = time_str + ('.%d.log' % now_ms)
> +    build_log_file_path = os.path.join(log_dir, log_file_name)
> +
> +    build_log = logging.FileHandler(build_log_file_path)
> +
> +    logformat = bb.msg.BBLogFormatter(format_str)
> +    build_log.setFormatter(logformat)
>
> +    bb.msg.addDefaultlogFilter(build_log)
> +    logger.addHandler(build_log)
> +
> +    return (build_log, build_log_file_path)
> +
> +# stop logging to the build log if it exists
> +def _close_build_log(build_log):
> +    if build_log:
> +        build_log.flush()
> +        build_log.close()
> +        logger.removeHandler(build_log)
> +
> +def main(server, eventHandler, params):
> +    # set to a logging.FileHandler instance when a build starts;
> +    # see _open_build_log()
> +    build_log = None
> +
> +    # set to the log path when a build starts
> +    build_log_file_path = None
>
> -def main(server, eventHandler, params ):
>      helper = uihelper.BBUIHelper()
>
> +    # TODO don't use log output to determine when bitbake has started
> +    #
> +    # WARNING: this log handler cannot be removed, as localhostbecontroller
> +    # relies on output in the toaster_ui.log file to determine whether
> +    # the bitbake server has started, which only happens if
> +    # this logger is setup here (see the TODO in the loop below)
>      console = logging.StreamHandler(sys.stdout)
>      format_str = "%(levelname)s: %(message)s"
>      formatter = bb.msg.BBLogFormatter(format_str)
> @@ -73,8 +116,6 @@ def main(server, eventHandler, params ):
>      logger.addHandler(console)
>      logger.setLevel(logging.INFO)
>
> -    _, _, consolelogfile = _log_settings_from_server(server)
> -
>      # verify and warn
>      build_history_enabled = True
>      inheritlist, _ = server.runCommand(["getVariable", "INHERIT"])
> @@ -87,8 +128,9 @@ def main(server, eventHandler, params ):
>          logger.error("ToasterUI can only work in observer mode")
>          return 1
>
> -
> +    # set to 1 when toasterui needs to shut down
>      main.shutdown = 0
> +
>      interrupted = False
>      return_value = 0
>      errors = 0
> @@ -98,25 +140,31 @@ def main(server, eventHandler, params ):
>
>      buildinfohelper = BuildInfoHelper(server, build_history_enabled)
>
> -    if buildinfohelper.brbe is not None and consolelogfile:
> -        # if we are under managed mode we have no other UI and we need to write our own file
> -        bb.utils.mkdirhier(os.path.dirname(consolelogfile))
> -        conlogformat = bb.msg.BBLogFormatter(format_str)
> -        consolelog = logging.FileHandler(consolelogfile)
> -        bb.msg.addDefaultlogFilter(consolelog)
> -        consolelog.setFormatter(conlogformat)
> -        logger.addHandler(consolelog)
> -
> +    # write our own log files into bitbake's log directory;
> +    # we're only interested in the path to the parent directory of
> +    # this file, as we're writing our own logs into the same directory
> +    consolelogfile = _log_settings_from_server(server)
> +    log_dir = os.path.dirname(consolelogfile)
> +    bb.utils.mkdirhier(log_dir)
>
>      while True:
>          try:
>              event = eventHandler.waitEvent(0.25)
>              if first:
>                  first = False
> +
> +                # TODO don't use log output to determine when bitbake has started
> +                #
> +                # this is the line localhostbecontroller needs to
> +                # see in toaster_ui.log which it uses to decide whether
> +                # the bitbake server has started...
>                  logger.info("ToasterUI waiting for events")
>
>              if event is None:
>                  if main.shutdown > 0:
> +                    # if shutting down, close any open build log first
> +                    _close_build_log(build_log)
> +
>                      break
>                  continue
>
> @@ -125,8 +173,21 @@ def main(server, eventHandler, params ):
>              # pylint: disable=protected-access
>              # the code will look into the protected variables of the event; no easy way around this
>
> +            # we treat ParseStarted as the first event of toaster-triggered
> +            # builds; that way we get the Build Configuration included in the log
> +            # and any errors that occur before BuildStarted is fired
> +            if isinstance(event, bb.event.ParseStarted):
> +                if not (build_log and build_log_file_path):
> +                    build_log, build_log_file_path = _open_build_log(log_dir)
> +                continue
> +
>              if isinstance(event, bb.event.BuildStarted):
> -                buildinfohelper.store_started_build(event, consolelogfile)
> +                # command-line builds don't fire a ParseStarted event,
> +                # so we have to start the log file for those on BuildStarted instead
> +                if not (build_log and build_log_file_path):
> +                    build_log, build_log_file_path = _open_build_log(log_dir)
> +
> +                buildinfohelper.store_started_build(event, build_log_file_path)
>
>              if isinstance(event, (bb.build.TaskStarted, bb.build.TaskSucceeded, bb.build.TaskFailedSilent)):
>                  buildinfohelper.update_and_store_task(event)
> @@ -171,8 +232,6 @@ def main(server, eventHandler, params ):
>              # timing and error informations from the parsing phase in Toaster
>              if isinstance(event, (bb.event.SanityCheckPassed, bb.event.SanityCheck)):
>                  continue
> -            if isinstance(event, bb.event.ParseStarted):
> -                continue
>              if isinstance(event, bb.event.ParseProgress):
>                  continue
>              if isinstance(event, bb.event.ParseCompleted):
> @@ -248,6 +307,12 @@ def main(server, eventHandler, params ):
>                      errorcode = 1
>                      logger.error("Command execution failed: %s", event.error)
>
> +                # turn off logging to the current build log
> +                _close_build_log(build_log)
> +
> +                # reset ready for next BuildStarted
> +                build_log = None
> +
>                  # update the build info helper on BuildCompleted, not on CommandXXX
>                  buildinfohelper.update_build_information(event, errors, warnings, taskfailures)
>                  buildinfohelper.close(errorcode)
> @@ -256,7 +321,6 @@ def main(server, eventHandler, params ):
>
>                  # we start a new build info
>                  if buildinfohelper.brbe is not None:
> -
>                      logger.debug("ToasterUI under BuildEnvironment management - exiting after the build")
>                      server.terminateServer()
>                  else:
> @@ -298,8 +362,9 @@ def main(server, eventHandler, params ):
>                  continue
>
>              if isinstance(event, bb.cooker.CookerExit):
> -                # exit when the server exits
> -                break
> +                # shutdown when bitbake server shuts down
> +                main.shutdown = 1
> +                continue
>
>              # ignore
>              if isinstance(event, (bb.event.BuildBase,
> @@ -350,9 +415,8 @@ def main(server, eventHandler, params ):
>              # make sure we return with an error
>              return_value += 1
>
> -    if interrupted:
> -        if return_value == 0:
> -            return_value += 1
> +    if interrupted and return_value == 0:
> +        return_value += 1
>
>      logger.warn("Return value is %d", return_value)
>      return return_value
> --
> Elliot Smith
> Software Engineer
> Intel OTC
>
> ---------------------------------------------------------------------
> Intel Corporation (UK) Limited
> Registered No. 1134945 (England)
> Registered Office: Pipers Way, Swindon SN3 1RJ
> VAT No: 860 2173 47
>
> This e-mail and any attachments may contain confidential material for
> the sole use of the intended recipient(s). Any review or distribution
> by others is strictly prohibited. If you are not the intended
> recipient, please contact the sender and delete all copies.
>
> --
> _______________________________________________
> toaster mailing list
> toaster@yoctoproject.org
> https://lists.yoctoproject.org/listinfo/toaster


^ permalink raw reply related	[flat|nested] 6+ messages in thread

* Re: [review-request][PATCH][v2] toasterui: Create per-build logs
  2015-11-02  1:15 ` Brian Avery
@ 2015-11-02 10:04   ` Smith, Elliot
  2015-11-02 15:55     ` Brian Avery
  0 siblings, 1 reply; 6+ messages in thread
From: Smith, Elliot @ 2015-11-02 10:04 UTC (permalink / raw
  To: Brian Avery; +Cc: toaster

[-- Attachment #1: Type: text/plain, Size: 17972 bytes --]

On 2 November 2015 at 01:15, Brian Avery <avery.brian@gmail.com> wrote:

> So I looked at the lack of a parse started event for the cli builds
> and it's pretty ez to get one in cli mode too.  I'm pretty sure it's
> just the fact that we weren't passing in a event mask and so got the
> default one.  BTW, whenever an event issue comes up I find it easiest
> to instrument knotty.py (the ncurses command line ui) as it is the
> most complete.
>

Thanks Brian.

Would it be worth you making a formal patch for this? I think my code will
already cope correctly, as it either looks for ParseStarted or
BuildStarted. We could probably even remove the check for BuildStarted
altogether.

Elliot


>
> With the following diff:
>
> diff --git a/bitbake/lib/bb/ui/toasterui.py
> b/bitbake/lib/bb/ui/toasterui.py
> index 3d26150..3b8f689 100644
> --- a/bitbake/lib/bb/ui/toasterui.py
> +++ b/bitbake/lib/bb/ui/toasterui.py
> @@ -138,6 +138,20 @@ def main(server, eventHandler, params):
>      taskfailures = []
>      first = True
> +
> +    _evt_list = [ "bb.runqueue.runQueueExitWait",
> "bb.event.LogExecTTY", "logging.LogRecord",
> +              "bb.build.TaskFailed", "bb.build.TaskBase",
> "bb.event.ParseStarted",
> +              "bb.event.ParseProgress", "bb.event.ParseCompleted",
> "bb.event.CacheLoadStarted",
> +              "bb.event.CacheLoadProgress",
> "bb.event.CacheLoadCompleted", "bb.command.CommandFailed",
> +              "bb.command.CommandExit",
> "bb.command.CommandCompleted",  "bb.cooker.CookerExit",
> +              "bb.event.MultipleProviders", "bb.event.NoProvider",
> "bb.runqueue.sceneQueueTaskStarted",
> +              "bb.runqueue.runQueueTaskStarted",
> "bb.runqueue.runQueueTaskFailed", "bb.runqueue.sceneQueueTaskFailed",
> +              "bb.event.BuildBase", "bb.build.TaskStarted",
> "bb.build.TaskSucceeded", "bb.build.TaskFailedSilent"]
> +
> +    llevel, debug_domains = bb.msg.constructLogOptions()
> +    logger.warn("BAVERY: setting event mask")
> +    server.runCommand(["setEventMask", server.getEventHandle(),
> llevel, debug_domains, _evt_list])
> +
>      buildinfohelper = BuildInfoHelper(server, build_history_enabled)
>
>
>      # write our own log files into bitbake's log directory;
>
> @@ -150,6 +164,14 @@ def main(server, eventHandler, params):
>      while True:
>          try:
>              event = eventHandler.waitEvent(0.25)
> +            if isinstance(event, bb.event.ParseStarted):
> +                logger.warn("BAVERY: parse started")
> +            if isinstance(event, bb.event.ParseProgress):
> +                logger.warn("BAVERY: parse progress")
> +            if isinstance(event, bb.event.ParseCompleted):
> +                logger.warn("BAVERY: parse completed")
> +
> +
>              if first:
>                  first = False
>
>
> Gives the following output: (many parse progress events...):
>
>
> toaster_ui.log:WARNING: BAVERY: setting event mask
> toaster_ui.log:WARNING: BAVERY: parse started
> toaster_ui.log:WARNING: BAVERY: parse progress
> toaster_ui.log:WARNING: BAVERY: parse progress
> ....
> toaster_ui.log:WARNING: BAVERY: parse completed
>
> On Wed, Oct 28, 2015 at 6:44 AM, Elliot Smith <elliot.smith@intel.com>
> wrote:
> > v2:
> >
> > * Toaster doesn't get a ParseStarted event for command-line builds,
> > so revert to using BuildStarted (for cli builds only). This means we lose
> > the "Build configuration" for command-line builds (not for Toaster
> builds);
> > but as the user is building on the command-line, they can see the
> > build configuration anyway.
> >
> > * Changed getSetVariable for BB_CONSOLELOG to getVariable, as we have
> > a read-only bitbake server, which means variable writes fail;
> > and we don't need to set that variable anyway (we only read it so we
> > know which directory to put our logs into).
> >
> > ---
> >
> > Rather than relying on bug 8411, which is conveniently creating
> > separate log files for each of our builds, create our own
> > log file for each build.
> >
> > The log files are created in the same tmp directories that
> > bitbake uses, but are timestamped to the millisecond to avoid
> > name collisions.
> >
> > Each log file is opened on a ParseStarted event (for builds
> > triggered by Toaster) or BuildStarted event (for builds on the
> > command line: Toaster doesn't get the ParseStarted event
> > for command-line builds).
> >
> > The log file is closed on the BuildCompleted event, or if the
> > build fails.
> >
> > Because we start logging on ParseStarted for Toaster builds,
> > we're able to capture the "Build Configuration" section which
> > bitbake writes to output. We lose this section for cli builds.
> >
> > [YOCTO #8373]
> >
> > Signed-off-by: Elliot Smith <elliot.smith@intel.com>
> > ---
> >  bitbake/lib/bb/ui/buildinfohelper.py |   8 +--
> >  bitbake/lib/bb/ui/toasterui.py       | 116
> +++++++++++++++++++++++++++--------
> >  2 files changed, 94 insertions(+), 30 deletions(-)
> >
> > diff --git a/bitbake/lib/bb/ui/buildinfohelper.py
> b/bitbake/lib/bb/ui/buildinfohelper.py
> > index 2fc1a43..78f1e92 100644
> > --- a/bitbake/lib/bb/ui/buildinfohelper.py
> > +++ b/bitbake/lib/bb/ui/buildinfohelper.py
> > @@ -784,7 +784,7 @@ class BuildInfoHelper(object):
> >      ## methods to convert event/external info into objects that the ORM
> layer uses
> >
> >
> > -    def _get_build_information(self, consolelogfile):
> > +    def _get_build_information(self, build_log_path):
> >          build_info = {}
> >          # Generate an identifier for each new build
> >
> > @@ -793,7 +793,7 @@ class BuildInfoHelper(object):
> >          build_info['distro_version'] =
> self.server.runCommand(["getVariable", "DISTRO_VERSION"])[0]
> >          build_info['started_on'] = timezone.now()
> >          build_info['completed_on'] = timezone.now()
> > -        build_info['cooker_log_path'] = consolelogfile
> > +        build_info['cooker_log_path'] = build_log_path
> >          build_info['build_name'] =
> self.server.runCommand(["getVariable", "BUILDNAME"])[0]
> >          build_info['bitbake_version'] =
> self.server.runCommand(["getVariable", "BB_VERSION"])[0]
> >
> > @@ -934,9 +934,9 @@ class BuildInfoHelper(object):
> >                  logger.warn("buildinfohelper: cannot identify layer
> exception:%s ", nee)
> >
> >
> > -    def store_started_build(self, event, consolelogfile):
> > +    def store_started_build(self, event, build_log_path):
> >          assert '_pkgs' in vars(event)
> > -        build_information = self._get_build_information(consolelogfile)
> > +        build_information = self._get_build_information(build_log_path)
> >
> >          build_obj =
> self.orm_wrapper.create_build_object(build_information, self.brbe,
> self.project)
> >
> > diff --git a/bitbake/lib/bb/ui/toasterui.py
> b/bitbake/lib/bb/ui/toasterui.py
> > index 2b3bc3f..3d26150 100644
> > --- a/bitbake/lib/bb/ui/toasterui.py
> > +++ b/bitbake/lib/bb/ui/toasterui.py
> > @@ -21,6 +21,7 @@
> >  # 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
> >
> >  from __future__ import division
> > +import time
> >  import sys
> >  try:
> >      import bb
> > @@ -43,8 +44,6 @@ featureSet =
> [bb.cooker.CookerFeatures.HOB_EXTRA_CACHES, bb.cooker.CookerFeature
> >  logger = logging.getLogger("ToasterLogger")
> >  interactive = sys.stdout.isatty()
> >
> > -
> > -
> >  def _log_settings_from_server(server):
> >      # Get values of variables which control our output
> >      includelogs, error = server.runCommand(["getVariable",
> "BBINCLUDELOGS"])
> > @@ -55,16 +54,60 @@ def _log_settings_from_server(server):
> >      if error:
> >          logger.error("Unable to get the value of BBINCLUDELOGS_LINES
> variable: %s", error)
> >          raise BaseException(error)
> > -    consolelogfile, error = server.runCommand(["getSetVariable",
> "BB_CONSOLELOG"])
> > +    consolelogfile, error = server.runCommand(["getVariable",
> "BB_CONSOLELOG"])
> >      if error:
> >          logger.error("Unable to get the value of BB_CONSOLELOG
> variable: %s", error)
> >          raise BaseException(error)
> > -    return includelogs, loglines, consolelogfile
> > +    return consolelogfile
> > +
> > +# create a log file for a single build and direct the logger at it;
> > +# log file name is timestamped to the millisecond (depending
> > +# on system clock accuracy) to ensure it doesn't overlap with
> > +# other log file names
> > +#
> > +# returns (log file, path to log file) for a build
> > +def _open_build_log(log_dir):
> > +    format_str = "%(levelname)s: %(message)s"
> > +
> > +    now = time.time()
> > +    now_ms = int((now - int(now)) * 1000)
> > +    time_str = time.strftime('build_%Y%m%d_%H%M%S', time.localtime(now))
> > +    log_file_name = time_str + ('.%d.log' % now_ms)
> > +    build_log_file_path = os.path.join(log_dir, log_file_name)
> > +
> > +    build_log = logging.FileHandler(build_log_file_path)
> > +
> > +    logformat = bb.msg.BBLogFormatter(format_str)
> > +    build_log.setFormatter(logformat)
> >
> > +    bb.msg.addDefaultlogFilter(build_log)
> > +    logger.addHandler(build_log)
> > +
> > +    return (build_log, build_log_file_path)
> > +
> > +# stop logging to the build log if it exists
> > +def _close_build_log(build_log):
> > +    if build_log:
> > +        build_log.flush()
> > +        build_log.close()
> > +        logger.removeHandler(build_log)
> > +
> > +def main(server, eventHandler, params):
> > +    # set to a logging.FileHandler instance when a build starts;
> > +    # see _open_build_log()
> > +    build_log = None
> > +
> > +    # set to the log path when a build starts
> > +    build_log_file_path = None
> >
> > -def main(server, eventHandler, params ):
> >      helper = uihelper.BBUIHelper()
> >
> > +    # TODO don't use log output to determine when bitbake has started
> > +    #
> > +    # WARNING: this log handler cannot be removed, as
> localhostbecontroller
> > +    # relies on output in the toaster_ui.log file to determine whether
> > +    # the bitbake server has started, which only happens if
> > +    # this logger is setup here (see the TODO in the loop below)
> >      console = logging.StreamHandler(sys.stdout)
> >      format_str = "%(levelname)s: %(message)s"
> >      formatter = bb.msg.BBLogFormatter(format_str)
> > @@ -73,8 +116,6 @@ def main(server, eventHandler, params ):
> >      logger.addHandler(console)
> >      logger.setLevel(logging.INFO)
> >
> > -    _, _, consolelogfile = _log_settings_from_server(server)
> > -
> >      # verify and warn
> >      build_history_enabled = True
> >      inheritlist, _ = server.runCommand(["getVariable", "INHERIT"])
> > @@ -87,8 +128,9 @@ def main(server, eventHandler, params ):
> >          logger.error("ToasterUI can only work in observer mode")
> >          return 1
> >
> > -
> > +    # set to 1 when toasterui needs to shut down
> >      main.shutdown = 0
> > +
> >      interrupted = False
> >      return_value = 0
> >      errors = 0
> > @@ -98,25 +140,31 @@ def main(server, eventHandler, params ):
> >
> >      buildinfohelper = BuildInfoHelper(server, build_history_enabled)
> >
> > -    if buildinfohelper.brbe is not None and consolelogfile:
> > -        # if we are under managed mode we have no other UI and we need
> to write our own file
> > -        bb.utils.mkdirhier(os.path.dirname(consolelogfile))
> > -        conlogformat = bb.msg.BBLogFormatter(format_str)
> > -        consolelog = logging.FileHandler(consolelogfile)
> > -        bb.msg.addDefaultlogFilter(consolelog)
> > -        consolelog.setFormatter(conlogformat)
> > -        logger.addHandler(consolelog)
> > -
> > +    # write our own log files into bitbake's log directory;
> > +    # we're only interested in the path to the parent directory of
> > +    # this file, as we're writing our own logs into the same directory
> > +    consolelogfile = _log_settings_from_server(server)
> > +    log_dir = os.path.dirname(consolelogfile)
> > +    bb.utils.mkdirhier(log_dir)
> >
> >      while True:
> >          try:
> >              event = eventHandler.waitEvent(0.25)
> >              if first:
> >                  first = False
> > +
> > +                # TODO don't use log output to determine when bitbake
> has started
> > +                #
> > +                # this is the line localhostbecontroller needs to
> > +                # see in toaster_ui.log which it uses to decide whether
> > +                # the bitbake server has started...
> >                  logger.info("ToasterUI waiting for events")
> >
> >              if event is None:
> >                  if main.shutdown > 0:
> > +                    # if shutting down, close any open build log first
> > +                    _close_build_log(build_log)
> > +
> >                      break
> >                  continue
> >
> > @@ -125,8 +173,21 @@ def main(server, eventHandler, params ):
> >              # pylint: disable=protected-access
> >              # the code will look into the protected variables of the
> event; no easy way around this
> >
> > +            # we treat ParseStarted as the first event of
> toaster-triggered
> > +            # builds; that way we get the Build Configuration included
> in the log
> > +            # and any errors that occur before BuildStarted is fired
> > +            if isinstance(event, bb.event.ParseStarted):
> > +                if not (build_log and build_log_file_path):
> > +                    build_log, build_log_file_path =
> _open_build_log(log_dir)
> > +                continue
> > +
> >              if isinstance(event, bb.event.BuildStarted):
> > -                buildinfohelper.store_started_build(event,
> consolelogfile)
> > +                # command-line builds don't fire a ParseStarted event,
> > +                # so we have to start the log file for those on
> BuildStarted instead
> > +                if not (build_log and build_log_file_path):
> > +                    build_log, build_log_file_path =
> _open_build_log(log_dir)
> > +
> > +                buildinfohelper.store_started_build(event,
> build_log_file_path)
> >
> >              if isinstance(event, (bb.build.TaskStarted,
> bb.build.TaskSucceeded, bb.build.TaskFailedSilent)):
> >                  buildinfohelper.update_and_store_task(event)
> > @@ -171,8 +232,6 @@ def main(server, eventHandler, params ):
> >              # timing and error informations from the parsing phase in
> Toaster
> >              if isinstance(event, (bb.event.SanityCheckPassed,
> bb.event.SanityCheck)):
> >                  continue
> > -            if isinstance(event, bb.event.ParseStarted):
> > -                continue
> >              if isinstance(event, bb.event.ParseProgress):
> >                  continue
> >              if isinstance(event, bb.event.ParseCompleted):
> > @@ -248,6 +307,12 @@ def main(server, eventHandler, params ):
> >                      errorcode = 1
> >                      logger.error("Command execution failed: %s",
> event.error)
> >
> > +                # turn off logging to the current build log
> > +                _close_build_log(build_log)
> > +
> > +                # reset ready for next BuildStarted
> > +                build_log = None
> > +
> >                  # update the build info helper on BuildCompleted, not
> on CommandXXX
> >                  buildinfohelper.update_build_information(event, errors,
> warnings, taskfailures)
> >                  buildinfohelper.close(errorcode)
> > @@ -256,7 +321,6 @@ def main(server, eventHandler, params ):
> >
> >                  # we start a new build info
> >                  if buildinfohelper.brbe is not None:
> > -
> >                      logger.debug("ToasterUI under BuildEnvironment
> management - exiting after the build")
> >                      server.terminateServer()
> >                  else:
> > @@ -298,8 +362,9 @@ def main(server, eventHandler, params ):
> >                  continue
> >
> >              if isinstance(event, bb.cooker.CookerExit):
> > -                # exit when the server exits
> > -                break
> > +                # shutdown when bitbake server shuts down
> > +                main.shutdown = 1
> > +                continue
> >
> >              # ignore
> >              if isinstance(event, (bb.event.BuildBase,
> > @@ -350,9 +415,8 @@ def main(server, eventHandler, params ):
> >              # make sure we return with an error
> >              return_value += 1
> >
> > -    if interrupted:
> > -        if return_value == 0:
> > -            return_value += 1
> > +    if interrupted and return_value == 0:
> > +        return_value += 1
> >
> >      logger.warn("Return value is %d", return_value)
> >      return return_value
> > --
> > Elliot Smith
> > Software Engineer
> > Intel OTC
> >
> > ---------------------------------------------------------------------
> > Intel Corporation (UK) Limited
> > Registered No. 1134945 (England)
> > Registered Office: Pipers Way, Swindon SN3 1RJ
> > VAT No: 860 2173 47
> >
> > This e-mail and any attachments may contain confidential material for
> > the sole use of the intended recipient(s). Any review or distribution
> > by others is strictly prohibited. If you are not the intended
> > recipient, please contact the sender and delete all copies.
> >
> > --
> > _______________________________________________
> > toaster mailing list
> > toaster@yoctoproject.org
> > https://lists.yoctoproject.org/listinfo/toaster
>



-- 
Elliot Smith
Software Engineer
Intel Open Source Technology Centre

[-- Attachment #2: Type: text/html, Size: 22389 bytes --]

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: [review-request][PATCH][v2] toasterui: Create per-build logs
  2015-11-02 10:04   ` Smith, Elliot
@ 2015-11-02 15:55     ` Brian Avery
  0 siblings, 0 replies; 6+ messages in thread
From: Brian Avery @ 2015-11-02 15:55 UTC (permalink / raw
  To: Smith, Elliot; +Cc: toaster

well,

this works in cli mode as well as managed mode, which as I understand
it, your current patch does not. Is that correct?

also, this would allow the UI to show the (fairly long) parsing
section and the progress events would even allow us to do a progress
bar. furthermore, alot of times, bitbake dies in the parse section if
it is missing a dependency (say when you are designing a new layer for
instance) and this way we could capture that error and report it.

So, yes, I'd say doing a real patch for this makes sense as well as
handling/relying on the parsing as well as the building events.

-b


On Mon, Nov 2, 2015 at 2:04 AM, Smith, Elliot <elliot.smith@intel.com> wrote:
> On 2 November 2015 at 01:15, Brian Avery <avery.brian@gmail.com> wrote:
>>
>> So I looked at the lack of a parse started event for the cli builds
>> and it's pretty ez to get one in cli mode too.  I'm pretty sure it's
>> just the fact that we weren't passing in a event mask and so got the
>> default one.  BTW, whenever an event issue comes up I find it easiest
>> to instrument knotty.py (the ncurses command line ui) as it is the
>> most complete.
>
>
> Thanks Brian.
>
> Would it be worth you making a formal patch for this? I think my code will
> already cope correctly, as it either looks for ParseStarted or BuildStarted.
> We could probably even remove the check for BuildStarted altogether.
>
> Elliot
>
>>
>>
>> With the following diff:
>>
>> diff --git a/bitbake/lib/bb/ui/toasterui.py
>> b/bitbake/lib/bb/ui/toasterui.py
>> index 3d26150..3b8f689 100644
>> --- a/bitbake/lib/bb/ui/toasterui.py
>> +++ b/bitbake/lib/bb/ui/toasterui.py
>> @@ -138,6 +138,20 @@ def main(server, eventHandler, params):
>>      taskfailures = []
>>      first = True
>> +
>> +    _evt_list = [ "bb.runqueue.runQueueExitWait",
>> "bb.event.LogExecTTY", "logging.LogRecord",
>> +              "bb.build.TaskFailed", "bb.build.TaskBase",
>> "bb.event.ParseStarted",
>> +              "bb.event.ParseProgress", "bb.event.ParseCompleted",
>> "bb.event.CacheLoadStarted",
>> +              "bb.event.CacheLoadProgress",
>> "bb.event.CacheLoadCompleted", "bb.command.CommandFailed",
>> +              "bb.command.CommandExit",
>> "bb.command.CommandCompleted",  "bb.cooker.CookerExit",
>> +              "bb.event.MultipleProviders", "bb.event.NoProvider",
>> "bb.runqueue.sceneQueueTaskStarted",
>> +              "bb.runqueue.runQueueTaskStarted",
>> "bb.runqueue.runQueueTaskFailed", "bb.runqueue.sceneQueueTaskFailed",
>> +              "bb.event.BuildBase", "bb.build.TaskStarted",
>> "bb.build.TaskSucceeded", "bb.build.TaskFailedSilent"]
>> +
>> +    llevel, debug_domains = bb.msg.constructLogOptions()
>> +    logger.warn("BAVERY: setting event mask")
>> +    server.runCommand(["setEventMask", server.getEventHandle(),
>> llevel, debug_domains, _evt_list])
>> +
>>      buildinfohelper = BuildInfoHelper(server, build_history_enabled)
>>
>>
>>      # write our own log files into bitbake's log directory;
>>
>> @@ -150,6 +164,14 @@ def main(server, eventHandler, params):
>>      while True:
>>          try:
>>              event = eventHandler.waitEvent(0.25)
>> +            if isinstance(event, bb.event.ParseStarted):
>> +                logger.warn("BAVERY: parse started")
>> +            if isinstance(event, bb.event.ParseProgress):
>> +                logger.warn("BAVERY: parse progress")
>> +            if isinstance(event, bb.event.ParseCompleted):
>> +                logger.warn("BAVERY: parse completed")
>> +
>> +
>>              if first:
>>                  first = False
>>
>>
>> Gives the following output: (many parse progress events...):
>>
>>
>> toaster_ui.log:WARNING: BAVERY: setting event mask
>> toaster_ui.log:WARNING: BAVERY: parse started
>> toaster_ui.log:WARNING: BAVERY: parse progress
>> toaster_ui.log:WARNING: BAVERY: parse progress
>> ....
>> toaster_ui.log:WARNING: BAVERY: parse completed
>>
>> On Wed, Oct 28, 2015 at 6:44 AM, Elliot Smith <elliot.smith@intel.com>
>> wrote:
>> > v2:
>> >
>> > * Toaster doesn't get a ParseStarted event for command-line builds,
>> > so revert to using BuildStarted (for cli builds only). This means we
>> > lose
>> > the "Build configuration" for command-line builds (not for Toaster
>> > builds);
>> > but as the user is building on the command-line, they can see the
>> > build configuration anyway.
>> >
>> > * Changed getSetVariable for BB_CONSOLELOG to getVariable, as we have
>> > a read-only bitbake server, which means variable writes fail;
>> > and we don't need to set that variable anyway (we only read it so we
>> > know which directory to put our logs into).
>> >
>> > ---
>> >
>> > Rather than relying on bug 8411, which is conveniently creating
>> > separate log files for each of our builds, create our own
>> > log file for each build.
>> >
>> > The log files are created in the same tmp directories that
>> > bitbake uses, but are timestamped to the millisecond to avoid
>> > name collisions.
>> >
>> > Each log file is opened on a ParseStarted event (for builds
>> > triggered by Toaster) or BuildStarted event (for builds on the
>> > command line: Toaster doesn't get the ParseStarted event
>> > for command-line builds).
>> >
>> > The log file is closed on the BuildCompleted event, or if the
>> > build fails.
>> >
>> > Because we start logging on ParseStarted for Toaster builds,
>> > we're able to capture the "Build Configuration" section which
>> > bitbake writes to output. We lose this section for cli builds.
>> >
>> > [YOCTO #8373]
>> >
>> > Signed-off-by: Elliot Smith <elliot.smith@intel.com>
>> > ---
>> >  bitbake/lib/bb/ui/buildinfohelper.py |   8 +--
>> >  bitbake/lib/bb/ui/toasterui.py       | 116
>> > +++++++++++++++++++++++++++--------
>> >  2 files changed, 94 insertions(+), 30 deletions(-)
>> >
>> > diff --git a/bitbake/lib/bb/ui/buildinfohelper.py
>> > b/bitbake/lib/bb/ui/buildinfohelper.py
>> > index 2fc1a43..78f1e92 100644
>> > --- a/bitbake/lib/bb/ui/buildinfohelper.py
>> > +++ b/bitbake/lib/bb/ui/buildinfohelper.py
>> > @@ -784,7 +784,7 @@ class BuildInfoHelper(object):
>> >      ## methods to convert event/external info into objects that the ORM
>> > layer uses
>> >
>> >
>> > -    def _get_build_information(self, consolelogfile):
>> > +    def _get_build_information(self, build_log_path):
>> >          build_info = {}
>> >          # Generate an identifier for each new build
>> >
>> > @@ -793,7 +793,7 @@ class BuildInfoHelper(object):
>> >          build_info['distro_version'] =
>> > self.server.runCommand(["getVariable", "DISTRO_VERSION"])[0]
>> >          build_info['started_on'] = timezone.now()
>> >          build_info['completed_on'] = timezone.now()
>> > -        build_info['cooker_log_path'] = consolelogfile
>> > +        build_info['cooker_log_path'] = build_log_path
>> >          build_info['build_name'] =
>> > self.server.runCommand(["getVariable", "BUILDNAME"])[0]
>> >          build_info['bitbake_version'] =
>> > self.server.runCommand(["getVariable", "BB_VERSION"])[0]
>> >
>> > @@ -934,9 +934,9 @@ class BuildInfoHelper(object):
>> >                  logger.warn("buildinfohelper: cannot identify layer
>> > exception:%s ", nee)
>> >
>> >
>> > -    def store_started_build(self, event, consolelogfile):
>> > +    def store_started_build(self, event, build_log_path):
>> >          assert '_pkgs' in vars(event)
>> > -        build_information = self._get_build_information(consolelogfile)
>> > +        build_information = self._get_build_information(build_log_path)
>> >
>> >          build_obj =
>> > self.orm_wrapper.create_build_object(build_information, self.brbe,
>> > self.project)
>> >
>> > diff --git a/bitbake/lib/bb/ui/toasterui.py
>> > b/bitbake/lib/bb/ui/toasterui.py
>> > index 2b3bc3f..3d26150 100644
>> > --- a/bitbake/lib/bb/ui/toasterui.py
>> > +++ b/bitbake/lib/bb/ui/toasterui.py
>> > @@ -21,6 +21,7 @@
>> >  # 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
>> >
>> >  from __future__ import division
>> > +import time
>> >  import sys
>> >  try:
>> >      import bb
>> > @@ -43,8 +44,6 @@ featureSet =
>> > [bb.cooker.CookerFeatures.HOB_EXTRA_CACHES, bb.cooker.CookerFeature
>> >  logger = logging.getLogger("ToasterLogger")
>> >  interactive = sys.stdout.isatty()
>> >
>> > -
>> > -
>> >  def _log_settings_from_server(server):
>> >      # Get values of variables which control our output
>> >      includelogs, error = server.runCommand(["getVariable",
>> > "BBINCLUDELOGS"])
>> > @@ -55,16 +54,60 @@ def _log_settings_from_server(server):
>> >      if error:
>> >          logger.error("Unable to get the value of BBINCLUDELOGS_LINES
>> > variable: %s", error)
>> >          raise BaseException(error)
>> > -    consolelogfile, error = server.runCommand(["getSetVariable",
>> > "BB_CONSOLELOG"])
>> > +    consolelogfile, error = server.runCommand(["getVariable",
>> > "BB_CONSOLELOG"])
>> >      if error:
>> >          logger.error("Unable to get the value of BB_CONSOLELOG
>> > variable: %s", error)
>> >          raise BaseException(error)
>> > -    return includelogs, loglines, consolelogfile
>> > +    return consolelogfile
>> > +
>> > +# create a log file for a single build and direct the logger at it;
>> > +# log file name is timestamped to the millisecond (depending
>> > +# on system clock accuracy) to ensure it doesn't overlap with
>> > +# other log file names
>> > +#
>> > +# returns (log file, path to log file) for a build
>> > +def _open_build_log(log_dir):
>> > +    format_str = "%(levelname)s: %(message)s"
>> > +
>> > +    now = time.time()
>> > +    now_ms = int((now - int(now)) * 1000)
>> > +    time_str = time.strftime('build_%Y%m%d_%H%M%S',
>> > time.localtime(now))
>> > +    log_file_name = time_str + ('.%d.log' % now_ms)
>> > +    build_log_file_path = os.path.join(log_dir, log_file_name)
>> > +
>> > +    build_log = logging.FileHandler(build_log_file_path)
>> > +
>> > +    logformat = bb.msg.BBLogFormatter(format_str)
>> > +    build_log.setFormatter(logformat)
>> >
>> > +    bb.msg.addDefaultlogFilter(build_log)
>> > +    logger.addHandler(build_log)
>> > +
>> > +    return (build_log, build_log_file_path)
>> > +
>> > +# stop logging to the build log if it exists
>> > +def _close_build_log(build_log):
>> > +    if build_log:
>> > +        build_log.flush()
>> > +        build_log.close()
>> > +        logger.removeHandler(build_log)
>> > +
>> > +def main(server, eventHandler, params):
>> > +    # set to a logging.FileHandler instance when a build starts;
>> > +    # see _open_build_log()
>> > +    build_log = None
>> > +
>> > +    # set to the log path when a build starts
>> > +    build_log_file_path = None
>> >
>> > -def main(server, eventHandler, params ):
>> >      helper = uihelper.BBUIHelper()
>> >
>> > +    # TODO don't use log output to determine when bitbake has started
>> > +    #
>> > +    # WARNING: this log handler cannot be removed, as
>> > localhostbecontroller
>> > +    # relies on output in the toaster_ui.log file to determine whether
>> > +    # the bitbake server has started, which only happens if
>> > +    # this logger is setup here (see the TODO in the loop below)
>> >      console = logging.StreamHandler(sys.stdout)
>> >      format_str = "%(levelname)s: %(message)s"
>> >      formatter = bb.msg.BBLogFormatter(format_str)
>> > @@ -73,8 +116,6 @@ def main(server, eventHandler, params ):
>> >      logger.addHandler(console)
>> >      logger.setLevel(logging.INFO)
>> >
>> > -    _, _, consolelogfile = _log_settings_from_server(server)
>> > -
>> >      # verify and warn
>> >      build_history_enabled = True
>> >      inheritlist, _ = server.runCommand(["getVariable", "INHERIT"])
>> > @@ -87,8 +128,9 @@ def main(server, eventHandler, params ):
>> >          logger.error("ToasterUI can only work in observer mode")
>> >          return 1
>> >
>> > -
>> > +    # set to 1 when toasterui needs to shut down
>> >      main.shutdown = 0
>> > +
>> >      interrupted = False
>> >      return_value = 0
>> >      errors = 0
>> > @@ -98,25 +140,31 @@ def main(server, eventHandler, params ):
>> >
>> >      buildinfohelper = BuildInfoHelper(server, build_history_enabled)
>> >
>> > -    if buildinfohelper.brbe is not None and consolelogfile:
>> > -        # if we are under managed mode we have no other UI and we need
>> > to write our own file
>> > -        bb.utils.mkdirhier(os.path.dirname(consolelogfile))
>> > -        conlogformat = bb.msg.BBLogFormatter(format_str)
>> > -        consolelog = logging.FileHandler(consolelogfile)
>> > -        bb.msg.addDefaultlogFilter(consolelog)
>> > -        consolelog.setFormatter(conlogformat)
>> > -        logger.addHandler(consolelog)
>> > -
>> > +    # write our own log files into bitbake's log directory;
>> > +    # we're only interested in the path to the parent directory of
>> > +    # this file, as we're writing our own logs into the same directory
>> > +    consolelogfile = _log_settings_from_server(server)
>> > +    log_dir = os.path.dirname(consolelogfile)
>> > +    bb.utils.mkdirhier(log_dir)
>> >
>> >      while True:
>> >          try:
>> >              event = eventHandler.waitEvent(0.25)
>> >              if first:
>> >                  first = False
>> > +
>> > +                # TODO don't use log output to determine when bitbake
>> > has started
>> > +                #
>> > +                # this is the line localhostbecontroller needs to
>> > +                # see in toaster_ui.log which it uses to decide whether
>> > +                # the bitbake server has started...
>> >                  logger.info("ToasterUI waiting for events")
>> >
>> >              if event is None:
>> >                  if main.shutdown > 0:
>> > +                    # if shutting down, close any open build log first
>> > +                    _close_build_log(build_log)
>> > +
>> >                      break
>> >                  continue
>> >
>> > @@ -125,8 +173,21 @@ def main(server, eventHandler, params ):
>> >              # pylint: disable=protected-access
>> >              # the code will look into the protected variables of the
>> > event; no easy way around this
>> >
>> > +            # we treat ParseStarted as the first event of
>> > toaster-triggered
>> > +            # builds; that way we get the Build Configuration included
>> > in the log
>> > +            # and any errors that occur before BuildStarted is fired
>> > +            if isinstance(event, bb.event.ParseStarted):
>> > +                if not (build_log and build_log_file_path):
>> > +                    build_log, build_log_file_path =
>> > _open_build_log(log_dir)
>> > +                continue
>> > +
>> >              if isinstance(event, bb.event.BuildStarted):
>> > -                buildinfohelper.store_started_build(event,
>> > consolelogfile)
>> > +                # command-line builds don't fire a ParseStarted event,
>> > +                # so we have to start the log file for those on
>> > BuildStarted instead
>> > +                if not (build_log and build_log_file_path):
>> > +                    build_log, build_log_file_path =
>> > _open_build_log(log_dir)
>> > +
>> > +                buildinfohelper.store_started_build(event,
>> > build_log_file_path)
>> >
>> >              if isinstance(event, (bb.build.TaskStarted,
>> > bb.build.TaskSucceeded, bb.build.TaskFailedSilent)):
>> >                  buildinfohelper.update_and_store_task(event)
>> > @@ -171,8 +232,6 @@ def main(server, eventHandler, params ):
>> >              # timing and error informations from the parsing phase in
>> > Toaster
>> >              if isinstance(event, (bb.event.SanityCheckPassed,
>> > bb.event.SanityCheck)):
>> >                  continue
>> > -            if isinstance(event, bb.event.ParseStarted):
>> > -                continue
>> >              if isinstance(event, bb.event.ParseProgress):
>> >                  continue
>> >              if isinstance(event, bb.event.ParseCompleted):
>> > @@ -248,6 +307,12 @@ def main(server, eventHandler, params ):
>> >                      errorcode = 1
>> >                      logger.error("Command execution failed: %s",
>> > event.error)
>> >
>> > +                # turn off logging to the current build log
>> > +                _close_build_log(build_log)
>> > +
>> > +                # reset ready for next BuildStarted
>> > +                build_log = None
>> > +
>> >                  # update the build info helper on BuildCompleted, not
>> > on CommandXXX
>> >                  buildinfohelper.update_build_information(event, errors,
>> > warnings, taskfailures)
>> >                  buildinfohelper.close(errorcode)
>> > @@ -256,7 +321,6 @@ def main(server, eventHandler, params ):
>> >
>> >                  # we start a new build info
>> >                  if buildinfohelper.brbe is not None:
>> > -
>> >                      logger.debug("ToasterUI under BuildEnvironment
>> > management - exiting after the build")
>> >                      server.terminateServer()
>> >                  else:
>> > @@ -298,8 +362,9 @@ def main(server, eventHandler, params ):
>> >                  continue
>> >
>> >              if isinstance(event, bb.cooker.CookerExit):
>> > -                # exit when the server exits
>> > -                break
>> > +                # shutdown when bitbake server shuts down
>> > +                main.shutdown = 1
>> > +                continue
>> >
>> >              # ignore
>> >              if isinstance(event, (bb.event.BuildBase,
>> > @@ -350,9 +415,8 @@ def main(server, eventHandler, params ):
>> >              # make sure we return with an error
>> >              return_value += 1
>> >
>> > -    if interrupted:
>> > -        if return_value == 0:
>> > -            return_value += 1
>> > +    if interrupted and return_value == 0:
>> > +        return_value += 1
>> >
>> >      logger.warn("Return value is %d", return_value)
>> >      return return_value
>> > --
>> > Elliot Smith
>> > Software Engineer
>> > Intel OTC
>> >
>> > ---------------------------------------------------------------------
>> > Intel Corporation (UK) Limited
>> > Registered No. 1134945 (England)
>> > Registered Office: Pipers Way, Swindon SN3 1RJ
>> > VAT No: 860 2173 47
>> >
>> > This e-mail and any attachments may contain confidential material for
>> > the sole use of the intended recipient(s). Any review or distribution
>> > by others is strictly prohibited. If you are not the intended
>> > recipient, please contact the sender and delete all copies.
>> >
>> > --
>> > _______________________________________________
>> > toaster mailing list
>> > toaster@yoctoproject.org
>> > https://lists.yoctoproject.org/listinfo/toaster
>
>
>
>
> --
> Elliot Smith
> Software Engineer
> Intel Open Source Technology Centre


^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2015-11-02 15:55 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2015-10-28 13:44 [review-request][PATCH][v2] toasterui: Create per-build logs Elliot Smith
2015-10-28 13:47 ` Smith, Elliot
2015-10-29 12:03   ` Ed Bartosh
2015-11-02  1:15 ` Brian Avery
2015-11-02 10:04   ` Smith, Elliot
2015-11-02 15:55     ` Brian Avery

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.