Repository: apache/buildstream
Issue: Build failure message is not printed before user prompt in interactive mode

[See original issue on GitLab](https://gitlab.com/BuildStream/buildstream/-/issues/1394)
In GitLab by [[Gitlab user @tristanvb]](https://gitlab.com/tristanvb) on Sep 20, 2020, 08:02

Today while testing fdsdk ports against BuildStream master, I encountered the following in the UI:


```
[--:--:--][14a1ca15][   build:bootstrap/glibc.bst           ] START   freedesktop-sdk/bootstrap-glibc/14a1ca15-build.4192016.log
[--:--:--][14a1ca15][   build:bootstrap/linux-headers.bst   ] STATUS  Staging bootstrap/linux-headers.bst/47a8467e

Build failure on element: bootstrap/glibc.bst

Choose one of the following options:
  (c)ontinue  - Continue queueing jobs as much as possible
  (q)uit      - Exit after all ongoing jobs complete
  (t)erminate - Terminate any ongoing jobs and exit
  (r)etry     - Retry this job
  (l)og       - View the full log file

Pressing ^C will terminate jobs and exit


Choice: [continue]: 

Continuing with other non failing elements
```

After dismissing the prompt, I got the following:

```
[--:--:--][14a1ca15][   build:bootstrap/gnu-config.bst      ] STATUS  Staging bootstrap/gnu-config.bst/41de65c5
[--:--:--][14a1ca15][   build:bootstrap/build/dwz-build.bst ] STATUS  Staging bootstrap/build/dwz-build.bst/54b3b542
[--:--:--][14a1ca15][   build:bootstrap/build/tools-lib-path.bst] STATUS  Staging bootstrap/build/tools-lib-path.bst/06cd15ad
[--:--:--][14a1ca15][   build:bootstrap/build/elfutils-build.bst] STATUS  Staging bootstrap/build/elfutils-build.bst/3ba8bb0e
[--:--:--][14a1ca15][   build:bootstrap/build/file-stage1.bst] STATUS  Staging bootstrap/build/file-stage1.bst/81d9ec9f
[--:--:--][14a1ca15][   build:bootstrap/build/debugedit-build.bst] STATUS  Staging bootstrap/build/debugedit-build.bst/d28b84db
[--:--:--][14a1ca15][   build:bootstrap/build/stripper.bst  ] STATUS  Staging bootstrap/build/stripper.bst/39725ba1
[--:--:--][14a1ca15][   build:bootstrap/build/debug-utils.bst] STATUS  Staging bootstrap/build/debug-utils.bst/9c869295
[--:--:--][14a1ca15][   build:bootstrap/build/base-sdk/filtered.bst] STATUS  Staging bootstrap/build/base-sdk/filtered.bst/5747e62f
[--:--:--][14a1ca15][   build:bootstrap/build/base-sdk/symlinks.bst] STATUS  Staging bootstrap/build/base-sdk/symlinks.bst/b4e168e0
[--:--:--][14a1ca15][   build:bootstrap/build/base-sdk.bst  ] STATUS  Staging bootstrap/build/base-sdk.bst/36b8498b
[--:--:--][14a1ca15][   build:bootstrap/build/binutils-stage1.bst] STATUS  Staging bootstrap/build/binutils-stage1.bst/8f278972
[--:--:--][14a1ca15][   build:bootstrap/build/gcc-stage1.bst] STATUS  Staging bootstrap/build/gcc-stage1.bst/f7ebac9b
[00:00:00][14a1ca15][   build:bootstrap/glibc.bst           ] FAILURE [overlaps]: Non-whitelisted overlaps detected
Staged files overwrite existing files in staging area: /
/usr/bin/dwz: bootstrap/build/base-sdk/filtered.bst is not permitted to overlap other elements, order bootstrap/build/base-sdk/filtered.bst above bootstrap/build/dwz-build.bst 
/usr/share/man/man1/dwz.1: bootstrap/build/base-sdk/filtered.bst is not permitted to overlap other elements, order bootstrap/build/base-sdk/filtered.bst above bootstrap/build/dwz-build.bst 


    Printing the last 20 lines from log file:
    /home/tristan/.cache/buildstream/logs/freedesktop-sdk/bootstrap-glibc/14a1ca15-build.4192016.log
    ======================================================================
        V: '1'
    [--:--:--] STATUS  bootstrap/linux-headers.bst: Staging bootstrap/linux-headers.bst/47a8467e
    [--:--:--] STATUS  bootstrap/gnu-config.bst: Staging bootstrap/gnu-config.bst/41de65c5
    [--:--:--] STATUS  bootstrap/build/dwz-build.bst: Staging bootstrap/build/dwz-build.bst/54b3b542
    [--:--:--] STATUS  bootstrap/build/tools-lib-path.bst: Staging bootstrap/build/tools-lib-path.bst/06cd15ad
    [--:--:--] STATUS  bootstrap/build/elfutils-build.bst: Staging bootstrap/build/elfutils-build.bst/3ba8bb0e
    [--:--:--] STATUS  bootstrap/build/file-stage1.bst: Staging bootstrap/build/file-stage1.bst/81d9ec9f
    [--:--:--] STATUS  bootstrap/build/debugedit-build.bst: Staging bootstrap/build/debugedit-build.bst/d28b84db
    [--:--:--] STATUS  bootstrap/build/stripper.bst: Staging bootstrap/build/stripper.bst/39725ba1
    [--:--:--] STATUS  bootstrap/build/debug-utils.bst: Staging bootstrap/build/debug-utils.bst/9c869295
    [--:--:--] STATUS  bootstrap/build/base-sdk/filtered.bst: Staging bootstrap/build/base-sdk/filtered.bst/5747e62f
    [--:--:--] STATUS  bootstrap/build/base-sdk/symlinks.bst: Staging bootstrap/build/base-sdk/symlinks.bst/b4e168e0
    [--:--:--] STATUS  bootstrap/build/base-sdk.bst: Staging bootstrap/build/base-sdk.bst/36b8498b
    [--:--:--] STATUS  bootstrap/build/binutils-stage1.bst: Staging bootstrap/build/binutils-stage1.bst/8f278972
    [--:--:--] STATUS  bootstrap/build/gcc-stage1.bst: Staging bootstrap/build/gcc-stage1.bst/f7ebac9b
    [00:00:00] FAILURE bootstrap/glibc.bst: [overlaps]: Non-whitelisted overlaps detected
    Staged files overwrite existing files in staging area: /
    /usr/bin/dwz: bootstrap/build/base-sdk/filtered.bst is not permitted to overlap other elements, order bootstrap/build/base-sdk/filtered.bst above bootstrap/build/dwz-build.bst 
    /usr/share/man/man1/dwz.1: bootstrap/build/base-sdk/filtered.bst is not permitted to overlap other elements, order bootstrap/build/base-sdk/filtered.bst above bootstrap/build/dwz-build.bst
    ======================================================================

[00:21:14][        ][    main:core activity                 ] FAILURE Build


Failure Summary
    bootstrap/glibc.bst:
    [00:00:00][14a1ca15][   build:bootstrap/glibc.bst           ] FAILURE [overlaps]: Non-whitelisted overlaps detected
    Staged files overwrite existing files in staging area: /
    /usr/bin/dwz: bootstrap/build/base-sdk/filtered.bst is not permitted to overlap other elements, order bootstrap/build/base-sdk/filtered.bst above bootstrap/build/dwz-build.bst 
    /usr/share/man/man1/dwz.1: bootstrap/build/base-sdk/filtered.bst is not permitted to overlap other elements, order bootstrap/build/base-sdk/filtered.bst above bootstrap/build/dwz-build.bst 


        Printing the last 20 lines from log file:
        /home/tristan/.cache/buildstream/logs/freedesktop-sdk/bootstrap-glibc/14a1ca15-build.4192016.log
        ======================================================================
            V: '1'
        [--:--:--] STATUS  bootstrap/linux-headers.bst: Staging bootstrap/linux-headers.bst/47a8467e
        [--:--:--] STATUS  bootstrap/gnu-config.bst: Staging bootstrap/gnu-config.bst/41de65c5
        [--:--:--] STATUS  bootstrap/build/dwz-build.bst: Staging bootstrap/build/dwz-build.bst/54b3b542
        [--:--:--] STATUS  bootstrap/build/tools-lib-path.bst: Staging bootstrap/build/tools-lib-path.bst/06cd15ad
        [--:--:--] STATUS  bootstrap/build/elfutils-build.bst: Staging bootstrap/build/elfutils-build.bst/3ba8bb0e
        [--:--:--] STATUS  bootstrap/build/file-stage1.bst: Staging bootstrap/build/file-stage1.bst/81d9ec9f
        [--:--:--] STATUS  bootstrap/build/debugedit-build.bst: Staging bootstrap/build/debugedit-build.bst/d28b84db
        [--:--:--] STATUS  bootstrap/build/stripper.bst: Staging bootstrap/build/stripper.bst/39725ba1
        [--:--:--] STATUS  bootstrap/build/debug-utils.bst: Staging bootstrap/build/debug-utils.bst/9c869295
        [--:--:--] STATUS  bootstrap/build/base-sdk/filtered.bst: Staging bootstrap/build/base-sdk/filtered.bst/5747e62f
        [--:--:--] STATUS  bootstrap/build/base-sdk/symlinks.bst: Staging bootstrap/build/base-sdk/symlinks.bst/b4e168e0
        [--:--:--] STATUS  bootstrap/build/base-sdk.bst: Staging bootstrap/build/base-sdk.bst/36b8498b
        [--:--:--] STATUS  bootstrap/build/binutils-stage1.bst: Staging bootstrap/build/binutils-stage1.bst/8f278972
        [--:--:--] STATUS  bootstrap/build/gcc-stage1.bst: Staging bootstrap/build/gcc-stage1.bst/f7ebac9b
        [00:00:00] FAILURE bootstrap/glibc.bst: [overlaps]: Non-whitelisted overlaps detected
        Staged files overwrite existing files in staging area: /
        /usr/bin/dwz: bootstrap/build/base-sdk/filtered.bst is not permitted to overlap other elements, order bootstrap/build/base-sdk/filtered.bst above bootstrap/build/dwz-build.bst 
        /usr/share/man/man1/dwz.1: bootstrap/build/base-sdk/filtered.bst is not permitted to overlap other elements, order bootstrap/build/base-sdk/filtered.bst above bootstrap/build/dwz-build.bst
        ======================================================================

Pipeline Summary
    Total:       17
    Session:     3
    Fetch Queue: processed 1, skipped 2, failed 0 
    Build Queue: processed 2, skipped 0, failed 1 


[--:--:--][        ][    main:core activity                 ] START   Terminating buildbox-casd
[00:00:02][        ][    main:core activity                 ] SUCCESS Terminating buildbox-casd

```

The `FAILURE` message is somehow pushed back to the end of the message queue, instead of being printed directly before the user prompt.

It did not work like this before, I expect to see the `FAILURE` message *before* the interactive prompt, giving me some context about what failed immediately before asking me what I want to do about it.

At the end of the session, of course the collection of `FAILURE` messages are summarized again, in the above case, they same message is printed twice at the end; first the message which should have come before the prompt is printed, and then it is printed again as a part of the failure summary a couple of lines further down.

Changed files:
src/buildstream/_message.py, src/buildstream/_frontend/app.py, src/buildstream/_messenger.py

diff --git a/src/buildstream/_frontend/app.py b/src/buildstream/_frontend/app.py
index 8d6cdb064..303c9636a 100644
--- a/src/buildstream/_frontend/app.py
+++ b/src/buildstream/_frontend/app.py
@@ -624,6 +624,9 @@ class App:
     def _job_failed(self, task_id, element=None):
         task = self._state.tasks[task_id]
 
+        # Flush any pending messages when handling a failure
+        self._render(message_text=self._message_text)
+
         # Dont attempt to handle a failure if the user has already opted to
         # terminate
         if not self.stream.terminated:
diff --git a/src/buildstream/_message.py b/src/buildstream/_message.py
index 538d385d7..c54398c39 100644
--- a/src/buildstream/_message.py
+++ b/src/buildstream/_message.py
@@ -1,5 +1,5 @@
 #
-#  Copyright (C) 2017 Codethink Limited
+#  Copyright (C) 2022 Codethink Limited
 #
 #  Licensed under the Apache License, Version 2.0 (the "License");
 #  you may not use this file except in compliance with the License.
@@ -18,6 +18,9 @@
 
 import datetime
 import os
+from typing import Optional
+
+from .types import _DisplayKey
 
 
 # Types of status messages.
@@ -48,33 +51,33 @@ unconditional_messages = [MessageType.INFO, MessageType.WARN, MessageType.FAIL,
 class Message:
     def __init__(
         self,
-        message_type,
-        message,
+        message_type: str,
+        message: str,
         *,
-        task_element_name=None,
-        task_element_key=None,
-        element_name=None,
-        element_key=None,
-        detail=None,
-        action_name=None,
-        elapsed=None,
-        logfile=None,
-        sandbox=False,
-        scheduler=False
+        task_element_name: Optional[str] = None,
+        task_element_key: Optional[_DisplayKey] = None,
+        element_name: Optional[str] = None,
+        element_key: Optional[_DisplayKey] = None,
+        detail: str = None,
+        action_name: str = None,
+        elapsed: Optional[datetime.timedelta] = None,
+        logfile: str = None,
+        sandbox: bool = False,
+        scheduler: bool = False
     ):
-        self.message_type = message_type  # Message type
-        self.message = message  # The message string
-        self.task_element_name = task_element_name  # The name of the issuing task element
-        self.task_element_key = task_element_key  # The DisplayKey of the issuing task element
-        self.element_name = element_name  # The name of the issuing element
-        self.element_key = element_key  # The DisplayKey of the issuing element
-        self.detail = detail  # An additional detail string
-        self.action_name = action_name  # Name of the task queue (fetch, refresh, build, etc)
-        self.elapsed = elapsed  # The elapsed time, in timed messages
-        self.logfile = logfile  # The log file path where commands took place
-        self.sandbox = sandbox  # Whether the error that caused this message used a sandbox
-        self.pid = os.getpid()  # The process pid
-        self.scheduler = scheduler  # Whether this is a scheduler level message
-        self.creation_time = datetime.datetime.now()
+        self.message_type: str = message_type  # Message type
+        self.message: str = message  # The message string
+        self.task_element_name: Optional[str] = task_element_name  # The name of the issuing task element
+        self.task_element_key: Optional[_DisplayKey] = task_element_key  # The DisplayKey of the issuing task element
+        self.element_name: Optional[str] = element_name  # The name of the issuing element
+        self.element_key: Optional[_DisplayKey] = element_key  # The DisplayKey of the issuing element
+        self.detail: Optional[str] = detail  # An additional detail string
+        self.action_name: Optional[str] = action_name  # Name of the task queue (fetch, refresh, build, etc)
+        self.elapsed: Optional[datetime.timedelta] = elapsed  # The elapsed time, in timed messages
+        self.logfile: Optional[str] = logfile  # The log file path where commands took place
+        self.sandbox: bool = sandbox  # Whether the error that caused this message used a sandbox
+        self.pid: int = os.getpid()  # The process pid
+        self.scheduler: bool = scheduler  # Whether this is a scheduler level message
+        self.creation_time: datetime.datetime = datetime.datetime.now()
         if message_type in (MessageType.SUCCESS, MessageType.FAIL):
             assert elapsed is not None
diff --git a/src/buildstream/_messenger.py b/src/buildstream/_messenger.py
index 6baacc9ab..93b1db927 100644
--- a/src/buildstream/_messenger.py
+++ b/src/buildstream/_messenger.py
@@ -22,6 +22,7 @@ import threading
 from contextlib import contextmanager
 from typing import Optional, Callable, Iterator, TextIO
 
+from .types import _DisplayKey
 from . import _signals
 from ._exceptions import BstError
 from ._message import Message, MessageType, unconditional_messages
@@ -48,8 +49,13 @@ class _TimeData:
         self.start_time: datetime.datetime = start_time
 
 
+# _JobInfo
+#
+# Information about a job, used as a part of thread local storage
+# in order to fill in some Message parameters automatically.
+#
 class _JobInfo:
-    def __init__(self, action_name: str, element_name: str, element_key: str) -> None:
+    def __init__(self, action_name: str, element_name: str, element_key: _DisplayKey) -> None:
         self.action_name = action_name
         self.element_name = element_name
         self.element_key = element_key
@@ -111,7 +117,17 @@ class Messenger:
         #
         self._bst_version = get_versions()["version"]
 
-    def setup_new_action_context(self, action_name: str, element_name: str, element_key: str) -> None:
+    # setup_new_action_context()
+    #
+    # Setup the thread local context for a new task, some message
+    # components are filled in automatically based on the action context.
+    #
+    # Args:
+    #    action_name: The action name
+    #    element_name: The element name
+    #    element_key: The element's DisplayKey
+    #
+    def setup_new_action_context(self, action_name: str, element_name: str, element_key: _DisplayKey) -> None:
         self._locals.silence_scope_depth = 0
         self._locals.job = _JobInfo(action_name, element_name, element_key)
 
@@ -529,6 +545,7 @@ class Messenger:
 
         timecode = EMPTYTIME
         if message.message_type in (MessageType.SUCCESS, MessageType.FAIL):
+            assert message.elapsed is not None
             hours, remainder = divmod(int(message.elapsed.total_seconds()), 60**2)
             minutes, seconds = divmod(remainder, 60)
             timecode = "{0:02d}:{1:02d}:{2:02d}".format(hours, minutes, seconds)