Restore task element name / element name distinction in UI

This behavior has regressed a while back when introducing the messenger
object in 0026e379 from merge request !1500.

Main behavior change:

  - Messages in the master log always appear with the task element's
    element name and cache key, even if the element or plugin issuing
    the log line is not the primary task element.

  - Messages logged in the task specific log, retain the context of the
    element names and cache keys which are issuing the log lines.

Changes include:

  * _message.py: Added the task element name & key members

  * _messenger.py: Log the element key as well if it is provided

  * _widget.py: Prefer the task name & key when logging, we fallback
    to the element name & key in case messages are being logged outside
    of any ongoing task (main process/context)

  * job.py: Unconditionally stamp messages with the task name & key

    Also removed some unused parameters here, clearing up an XXX comment

  * plugin.py: Add new `_message_kwargs` instance property, it is the responsibility
               of the core base class to maintain the base keyword arguments which
	       are to be used as kwargs for Message() instances created on behalf
	       of the issuing plugin.

    Use this method to construct messages in Plugin.__message() and to
    pass kwargs along to Messenger.timed_activity().

  * element.py: Update the `_message_kwargs` when the cache key is updated

  * tests/frontend/logging.py: Fix test to expect the cache key in the logline

  * tests/frontend/artifact_log.py: Fix test to expect the cache key in the logline

Fixes #1393

6 files changed, 71 insertions, 37 deletions

diff --git a/src/buildstream/_frontend/widget.py b/src/buildstream/_frontend/widget.py
index 7b2ff2688..0f2b07ed3 100644
--- a/src/buildstream/_frontend/widget.py
+++ b/src/buildstream/_frontend/widget.py
@@ -170,7 +170,8 @@ class TypeName(Widget):
 class ElementName(Widget):
     def render(self, message):
         action_name = message.action_name
-        element_name = message.element_name
+        element_name = message.task_element_name or message.element_name
+
         if element_name is not None:
             name = "{: <30}".format(element_name)
         else:
@@ -211,9 +212,10 @@ class CacheKey(Widget):
 
         dim = False
         key = " " * self._key_length
-        if message.element_key:
-            key = message.element_key.brief
-            dim = not message.element_key.strict
+        element_key = message.task_element_key or message.element_key
+        if element_key:
+            key = element_key.brief
+            dim = not element_key.strict
 
         if message.message_type in ERROR_MESSAGES:
             text = self._err_profile.fmt(key)
diff --git a/src/buildstream/_message.py b/src/buildstream/_message.py
index a2844ddce..675cc7b85 100644
--- a/src/buildstream/_message.py
+++ b/src/buildstream/_message.py
@@ -52,6 +52,8 @@ class Message:
         message_type,
         message,
         *,
+        task_element_name=None,
+        task_element_key=None,
         element_name=None,
         element_key=None,
         detail=None,
@@ -63,8 +65,10 @@ class Message:
     ):
         self.message_type = message_type  # Message type
         self.message = message  # The message string
-        self.element_name = element_name  # The instance element name of the issuing plugin
-        self.element_key = element_key  # The display key of the issuing plugin element
+        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
diff --git a/src/buildstream/_messenger.py b/src/buildstream/_messenger.py
index 43904b470..c37eca8bc 100644
--- a/src/buildstream/_messenger.py
+++ b/src/buildstream/_messenger.py
@@ -370,7 +370,12 @@ class Messenger:
         template = "[{timecode: <8}] {type: <7}"
 
         # If this message is associated with an element or source plugin, print the
-        # full element name of the instance.
+        # full element name and key for the instance.
+        element_key = ""
+        if message.element_key:
+            template += " [{element_key}]"
+            element_key = message.element_key.brief
+
         element_name = ""
         if message.element_name:
             template += " {element_name}"
@@ -392,6 +397,7 @@ class Messenger:
 
         text = template.format(
             timecode=timecode,
+            element_key=element_key,
             element_name=element_name,
             type=message.message_type.upper(),
             message=message.message,
diff --git a/src/buildstream/_scheduler/jobs/job.py b/src/buildstream/_scheduler/jobs/job.py
index 388fe0f5d..08e40694e 100644
--- a/src/buildstream/_scheduler/jobs/job.py
+++ b/src/buildstream/_scheduler/jobs/job.py
@@ -140,8 +140,8 @@ class Job:
         self._terminated = False  # Whether this job has been explicitly terminated
 
         self._logfile = logfile
-        self._message_element_name = None  # The plugin instance element name for messaging
-        self._message_element_key = None  # The element key for messaging
+        self._message_element_name = None  # The task-wide element name
+        self._message_element_key = None  # The task-wide element cache key
         self._element = None  # The Element() passed to the Job() constructor, if applicable
 
     # set_name()
@@ -299,23 +299,21 @@ class Job:
     # Logs a message, this will be logged in the task's logfile and
     # conditionally also be sent to the frontend.
     #
-    # XXX: Note no calls to message() currently override the default
-    #      name & key (previously unique_id), potential to be removed.
-    #
     # Args:
     #    message_type (MessageType): The type of message to send
     #    message (str): The message
     #    kwargs: Remaining Message() constructor arguments, note that you can
     #            override 'element_name' and 'element_key' this way.
     #
-    def message(self, message_type, message, element_name=None, element_key=None, **kwargs):
+    def message(self, message_type, message, **kwargs):
         kwargs["scheduler"] = True
-        # If default name & key values not provided, set as given job attributes
-        if element_name is None:
-            element_name = self._message_element_name
-        if element_key is None:
-            element_key = self._message_element_key
-        message = Message(message_type, message, element_name=element_name, element_key=element_key, **kwargs)
+        message = Message(
+            message_type,
+            message,
+            element_name=self._message_element_name,
+            element_key=self._message_element_key,
+            **kwargs
+        )
         self._messenger.message(message)
 
     # get_element()
@@ -557,9 +555,6 @@ class ChildJob:
     # Logs a message, this will be logged in the task's logfile and
     # conditionally also be sent to the frontend.
     #
-    # XXX: Note no calls to message() currently override the default
-    #      name & key (previously unique_id), potential to be removed.
-    #
     # Args:
     #    message_type (MessageType): The type of message to send
     #    message (str): The message
@@ -568,15 +563,16 @@ class ChildJob:
     #            for front end display if not already set or explicitly
     #            overriden here.
     #
-    def message(self, message_type, message, element_name=None, element_key=None, **kwargs):
+    def message(self, message_type, message, **kwargs):
         kwargs["scheduler"] = True
-        # If default name & key values not provided, set as given job attributes
-        if element_name is None:
-            element_name = self._message_element_name
-        if element_key is None:
-            element_key = self._message_element_key
         self._messenger.message(
-            Message(message_type, message, element_name=element_name, element_key=element_key, **kwargs)
+            Message(
+                message_type,
+                message,
+                element_name=self._message_element_name,
+                element_key=self._message_element_key,
+                **kwargs
+            )
         )
 
     #######################################################
@@ -790,17 +786,14 @@ class ChildJob:
     def _child_message_handler(self, message, is_silenced):
 
         message.action_name = self.action_name
-
-        # If no key has been set at this point, and the element job has
-        # a related key, set it. This is needed for messages going
-        # straight to the message handler from the child process.
-        if message.element_key is None and self._message_element_key:
-            message.element_key = self._message_element_key
+        message.task_element_name = self._message_element_name
+        message.task_element_key = self._message_element_key
 
         # Send to frontend if appropriate
         if is_silenced and (message.message_type not in unconditional_messages):
             return
 
+        # Don't bother propagating these to the frontend
         if message.message_type == MessageType.LOG:
             return
 
diff --git a/src/buildstream/element.py b/src/buildstream/element.py
index 9570ad487..7f80d08f6 100644
--- a/src/buildstream/element.py
+++ b/src/buildstream/element.py
@@ -3194,6 +3194,10 @@ class Element(Plugin):
         # a potential existing artifact.
         self.__update_artifact_state()
 
+        # Update the message kwargs in use for this plugin to dispatch messages with
+        #
+        self._message_kwargs["element_key"] = self._get_display_key()
+
     # __update_artifact_state()
     #
     # Updates the data involved in knowing about the artifact corresponding
@@ -3270,6 +3274,9 @@ class Element(Plugin):
             # Now we have the strong cache key, update the Artifact
             self.__artifact._cache_key = self.__cache_key
 
+            # Update the message kwargs in use for this plugin to dispatch messages with
+            self._message_kwargs["element_key"] = self._get_display_key()
+
 
 # _get_normal_name():
 #
diff --git a/src/buildstream/plugin.py b/src/buildstream/plugin.py
index 84165c706..2b2382eb7 100644
--- a/src/buildstream/plugin.py
+++ b/src/buildstream/plugin.py
@@ -265,6 +265,9 @@ class Plugin:
         # Get the full_name as project & type_tag are resolved
         self.__full_name = self.__get_full_name()
 
+        # Our message kwargs
+        self._message_kwargs = {"element_name": self._get_full_name()}
+
         # Infer the kind identifier
         modulename = type(self).__module__
         self.__kind = modulename.split(".")[-1]
@@ -498,8 +501,11 @@ class Plugin:
               # This will raise SourceError on its own
               self.call(... command which takes time ...)
         """
+
+        # Get the plugin kwargs and pass them along
+        plugin_kwargs = self._message_kwargs
         with self.__context.messenger.timed_activity(
-            activity_name, element_name=self._get_full_name(), detail=detail, silent_nested=silent_nested
+            activity_name, detail=detail, silent_nested=silent_nested, **plugin_kwargs
         ):
             yield
 
@@ -718,8 +724,24 @@ class Plugin:
 
         return (exit_code, output)
 
+    # __message():
+    #
+    # The plugin level focal point for issuing messages.
+    #
+    # Args:
+    #    message_type (MessageType): The message type
+    #    brief (str): The brief message
+    #    kwargs: The remaining Message attributes
+    #
     def __message(self, message_type, brief, **kwargs):
-        message = Message(message_type, brief, element_name=self._get_full_name(), **kwargs)
+        #
+        # Merge the plugin kwargs with the explicitly passed kwargs, give
+        # precedence to the explicitly passed kwargs.
+        #
+        plugin_kwargs = self._message_kwargs.copy()
+        plugin_kwargs.update(kwargs)
+
+        message = Message(message_type, brief, **plugin_kwargs)
         self.__context.messenger.message(message)
 
     def __note_command(self, output, *popenargs, **kwargs):