Merge branch 'tristan/fix-logging-element-names' into 'master'

Restore task element name / element name distinction in UI

Closes #1393

See merge request BuildStream/buildstream!2070

20 files changed, 315 insertions, 107 deletions

diff --git a/src/buildstream/_artifactcache.py b/src/buildstream/_artifactcache.py
index 3cd34070d..5ccdf8fd8 100644
--- a/src/buildstream/_artifactcache.py
+++ b/src/buildstream/_artifactcache.py
@@ -121,7 +121,7 @@ class ArtifactCache(AssetCache):
     #
     def push(self, element, artifact):
         project = element._get_project()
-        display_key = element._get_brief_display_key()
+        display_key = element._get_display_key()
 
         index_remotes = [r for r in self._index_remotes[project] if r.push]
         storage_remotes = [r for r in self._storage_remotes[project] if r.push]
@@ -135,15 +135,13 @@ class ArtifactCache(AssetCache):
         # can perform file checks on their end
         for remote in storage_remotes:
             remote.init()
-            element.status("Pushing data from artifact {} -> {}".format(display_key, remote))
+            element.status("Pushing data from artifact {} -> {}".format(display_key.brief, remote))
 
             if self._push_artifact_blobs(artifact, artifact_digest, remote):
-                element.info("Pushed data from artifact {} -> {}".format(display_key, remote))
+                element.info("Pushed data from artifact {} -> {}".format(display_key.brief, remote))
             else:
                 element.info(
-                    "Remote ({}) already has all data of artifact {} cached".format(
-                        remote, element._get_brief_display_key()
-                    )
+                    "Remote ({}) already has all data of artifact {} cached".format(remote, display_key.brief)
                 )
 
         for remote in index_remotes:
@@ -154,9 +152,7 @@ class ArtifactCache(AssetCache):
                 element.info("Pushed artifact {} -> {}".format(display_key, remote))
                 pushed = True
             else:
-                element.info(
-                    "Remote ({}) already has artifact {} cached".format(remote, element._get_brief_display_key())
-                )
+                element.info("Remote ({}) already has artifact {} cached".format(remote, display_key.brief))
 
         return pushed
 
diff --git a/src/buildstream/_elementsources.py b/src/buildstream/_elementsources.py
index eed847e75..69051ee8a 100644
--- a/src/buildstream/_elementsources.py
+++ b/src/buildstream/_elementsources.py
@@ -279,7 +279,7 @@ class ElementSources:
     def get_cache_key(self):
         return self._cache_key
 
-    # _get_brief_display_key()
+    # get_brief_display_key()
     #
     # Returns an abbreviated cache key for display purposes
     #
diff --git a/src/buildstream/_frontend/app.py b/src/buildstream/_frontend/app.py
index 59bc3513b..2f4235733 100644
--- a/src/buildstream/_frontend/app.py
+++ b/src/buildstream/_frontend/app.py
@@ -454,13 +454,13 @@ class App:
     def shell_prompt(self, element):
 
         element_name = element._get_full_name()
-
-        _, key, dim = element._get_display_key()
+        display_key = element._get_display_key()
 
         if self.colors:
+            dim_key = not display_key.strict
             prompt = (
                 self._format_profile.fmt("[")
-                + self._content_profile.fmt(key, dim=dim)
+                + self._content_profile.fmt(display_key.brief, dim=dim_key)
                 + self._format_profile.fmt("@")
                 + self._content_profile.fmt(element_name)
                 + self._format_profile.fmt(":")
@@ -469,7 +469,7 @@ class App:
                 + " "
             )
         else:
-            prompt = "[{}@{}:${{PWD}}]$ ".format(key, element_name)
+            prompt = "[{}@{}:${{PWD}}]$ ".format(display_key.brief, element_name)
 
         return prompt
 
diff --git a/src/buildstream/_frontend/widget.py b/src/buildstream/_frontend/widget.py
index 65f74d475..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:
@@ -209,15 +210,17 @@ class CacheKey(Widget):
         if message.element_name is None:
             return " " * self._key_length
 
-        missing = False
+        dim = False
         key = " " * self._key_length
-        if message.element_key:
-            _, key, missing = message.element_key
+        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)
         else:
-            text = self.content_profile.fmt(key, dim=missing)
+            text = self.content_profile.fmt(key, dim=dim)
 
         return text
 
@@ -340,11 +343,12 @@ class LogLine(Widget):
         for element in dependencies:
             line = format_
 
-            full_key, cache_key, dim_keys = element._get_display_key()
+            key = element._get_display_key()
+            dim_keys = not key.strict
 
             line = p.fmt_subst(line, "name", element._get_full_name(), fg="blue", bold=True)
-            line = p.fmt_subst(line, "key", cache_key, fg="yellow", dim=dim_keys)
-            line = p.fmt_subst(line, "full-key", full_key, fg="yellow", dim=dim_keys)
+            line = p.fmt_subst(line, "key", key.brief, fg="yellow", dim=dim_keys)
+            line = p.fmt_subst(line, "full-key", key.full, fg="yellow", dim=dim_keys)
 
             try:
                 if not element._has_all_sources_resolved():
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 b9ceb2107..c37eca8bc 100644
--- a/src/buildstream/_messenger.py
+++ b/src/buildstream/_messenger.py
@@ -154,16 +154,16 @@ class Messenger:
     #
     # Args:
     #    activity_name (str): The name of the activity
-    #    element_name (str): Optionally, the element full name of the plugin related to the message
     #    detail (str): An optional detailed message, can be multiline output
-    #    silent_nested (bool): If True, all but _message.unconditional_messages are silenced
+    #    silent_nested (bool): If True, all nested messages are silenced except for unconditionaly ones
+    #    kwargs: Remaining Message() constructor keyword arguments.
     #
     @contextmanager
-    def timed_activity(self, activity_name, *, element_name=None, detail=None, silent_nested=False):
+    def timed_activity(self, activity_name, *, detail=None, silent_nested=False, **kwargs):
         with self.timed_suspendable() as timedata:
             try:
                 # Push activity depth for status messages
-                message = Message(MessageType.START, activity_name, detail=detail, element_name=element_name)
+                message = Message(MessageType.START, activity_name, detail=detail, **kwargs)
                 self.message(message)
                 with self.silence(actually_silence=silent_nested):
                     yield
@@ -172,12 +172,12 @@ class Messenger:
                 # Note the failure in status messages and reraise, the scheduler
                 # expects an error when there is an error.
                 elapsed = datetime.datetime.now() - timedata.start_time
-                message = Message(MessageType.FAIL, activity_name, elapsed=elapsed, element_name=element_name)
+                message = Message(MessageType.FAIL, activity_name, elapsed=elapsed, **kwargs)
                 self.message(message)
                 raise
 
             elapsed = datetime.datetime.now() - timedata.start_time
-            message = Message(MessageType.SUCCESS, activity_name, elapsed=elapsed, element_name=element_name)
+            message = Message(MessageType.SUCCESS, activity_name, elapsed=elapsed, **kwargs)
             self.message(message)
 
     # simple_task()
@@ -186,30 +186,31 @@ class Messenger:
     #
     # Args:
     #    activity_name (str): The name of the activity
-    #    element_name (str): Optionally, the element full name of the plugin related to the message
-    #    full_name (str): Optionally, the distinguishing name of the activity, e.g. element name
-    #    silent_nested (bool): If True, all but _message.unconditional_messages are silenced
+    #    task_name (str): Optionally, the task name for the frontend during this task
+    #    detail (str): An optional detailed message, can be multiline output
+    #    silent_nested (bool): If True, all nested messages are silenced except for unconditionaly ones
+    #    kwargs: Remaining Message() constructor keyword arguments.
     #
     # Yields:
     #    Task: A Task object that represents this activity, principally used to report progress
     #
     @contextmanager
-    def simple_task(self, activity_name, *, element_name=None, full_name=None, silent_nested=False):
+    def simple_task(self, activity_name, *, task_name=None, detail=None, silent_nested=False, **kwargs):
         # Bypass use of State when none exists (e.g. tests)
         if not self._state:
-            with self.timed_activity(activity_name, element_name=element_name, silent_nested=silent_nested):
+            with self.timed_activity(activity_name, detail=detail, silent_nested=silent_nested, **kwargs):
                 yield
             return
 
-        if not full_name:
-            full_name = activity_name
+        if not task_name:
+            task_name = activity_name
 
         with self.timed_suspendable() as timedata:
             try:
-                message = Message(MessageType.START, activity_name, element_name=element_name)
+                message = Message(MessageType.START, activity_name, detail=detail, **kwargs)
                 self.message(message)
 
-                task = self._state.add_task(full_name, activity_name, full_name)
+                task = self._state.add_task(task_name, activity_name, task_name)
                 task.set_render_cb(self._render_status)
                 self._active_simple_tasks += 1
                 if not self._next_render:
@@ -220,11 +221,11 @@ class Messenger:
 
             except BstError:
                 elapsed = datetime.datetime.now() - timedata.start_time
-                message = Message(MessageType.FAIL, activity_name, elapsed=elapsed, element_name=element_name)
+                message = Message(MessageType.FAIL, activity_name, elapsed=elapsed, **kwargs)
                 self.message(message)
                 raise
             finally:
-                self._state.remove_task(full_name)
+                self._state.remove_task(task_name)
                 self._active_simple_tasks -= 1
                 if self._active_simple_tasks == 0:
                     self._next_render = None
@@ -237,9 +238,7 @@ class Messenger:
                     detail = "{} of {} subtasks processed".format(task.current_progress, task.maximum_progress)
                 else:
                     detail = "{} subtasks processed".format(task.current_progress)
-            message = Message(
-                MessageType.SUCCESS, activity_name, elapsed=elapsed, detail=detail, element_name=element_name
-            )
+            message = Message(MessageType.SUCCESS, activity_name, elapsed=elapsed, detail=detail, **kwargs)
             self.message(message)
 
     # recorded_messages()
@@ -371,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}"
@@ -393,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 c8ff853ed..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()
@@ -289,7 +289,7 @@ class Job:
     # key for for the issuing message (if an element is related to the Job).
     #
     # Args:
-    #     element_key (tuple): The element_key tuple to be supplied to the Message() constructor
+    #     element_key (_DisplayKey): The element_key tuple to be supplied to the Message() constructor
     #
     def set_message_element_key(self, element_key):
         self._message_element_key = element_key
@@ -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/_scheduler/queues/queue.py b/src/buildstream/_scheduler/queues/queue.py
index 9e444b393..f5aa2ca4c 100644
--- a/src/buildstream/_scheduler/queues/queue.py
+++ b/src/buildstream/_scheduler/queues/queue.py
@@ -356,9 +356,9 @@ class Queue:
 
     def _element_log_path(self, element):
         project = element._get_project()
-        key = element._get_display_key()[1]
+        key = element._get_display_key()
         action = self.action_name.lower()
-        logfile = "{key}-{action}".format(key=key, action=action)
+        logfile = "{key}-{action}".format(key=key.brief, action=action)
 
         return os.path.join(project.name, element.normal_name, logfile)
 
diff --git a/src/buildstream/element.py b/src/buildstream/element.py
index c9480d4fc..7f80d08f6 100644
--- a/src/buildstream/element.py
+++ b/src/buildstream/element.py
@@ -102,7 +102,7 @@ from .plugin import Plugin
 from .sandbox import SandboxFlags, SandboxCommandError
 from .sandbox._config import SandboxConfig
 from .sandbox._sandboxremote import SandboxRemote
-from .types import _Scope, _CacheBuildTrees, _KeyStrength, OverlapAction
+from .types import _Scope, _CacheBuildTrees, _KeyStrength, OverlapAction, _DisplayKey
 from ._artifact import Artifact
 from ._elementproxy import ElementProxy
 from ._elementsources import ElementSources
@@ -1021,7 +1021,7 @@ class Element(Plugin):
         # Time to use the artifact, check once more that it's there
         self.__assert_cached()
 
-        self.status("Staging {}/{}".format(self.name, self._get_brief_display_key()))
+        self.status("Staging {}/{}".format(self.name, self._get_display_key().brief))
         # Disable type checking since we can't easily tell mypy that
         # `self.__artifact` can't be None at this stage.
         files_vdir = self.__artifact.get_files()  # type: ignore
@@ -1398,15 +1398,13 @@ class Element(Plugin):
     # Returns cache keys for display purposes
     #
     # Returns:
-    #    (str): A full hex digest cache key for this Element
-    #    (str): An abbreviated hex digest cache key for this Element
-    #    (bool): True if key should be shown as dim, False otherwise
+    #    (_DisplayKey): The display key
     #
     # Question marks are returned if information for the cache key is missing.
     #
     def _get_display_key(self):
         context = self._get_context()
-        dim_key = True
+        strict = False
 
         cache_key = self._get_cache_key()
 
@@ -1415,23 +1413,10 @@ class Element(Plugin):
         elif cache_key == self.__strict_cache_key:
             # Strong cache key used in this session matches cache key
             # that would be used in strict build mode
-            dim_key = False
+            strict = True
 
         length = min(len(cache_key), context.log_key_length)
-        return (cache_key, cache_key[0:length], dim_key)
-
-    # _get_brief_display_key()
-    #
-    # Returns an abbreviated cache key for display purposes
-    #
-    # Returns:
-    #    (str): An abbreviated hex digest cache key for this Element
-    #
-    # Question marks are returned if information for the cache key is missing.
-    #
-    def _get_brief_display_key(self):
-        _, display_key, _ = self._get_display_key()
-        return display_key
+        return _DisplayKey(cache_key, cache_key[0:length], strict)
 
     # _tracking_done():
     #
@@ -2704,7 +2689,7 @@ class Element(Plugin):
     # Raises an error if the artifact is not cached.
     #
     def __assert_cached(self):
-        assert self._cached(), "{}: Missing artifact {}".format(self, self._get_brief_display_key())
+        assert self._cached(), "{}: Missing artifact {}".format(self, self._get_display_key().brief)
 
     # __get_tainted():
     #
@@ -3209,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
@@ -3285,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):
diff --git a/src/buildstream/types.py b/src/buildstream/types.py
index a5cf7afb8..67383f86a 100644
--- a/src/buildstream/types.py
+++ b/src/buildstream/types.py
@@ -208,6 +208,24 @@ class _KeyStrength(FastEnum):
     WEAK = 2
 
 
+# _DisplayKey():
+#
+# The components of a cache key which need to be displayed
+#
+# This is a part of Message() so it needs to be a simple serializable object.
+#
+# Args:
+#    full: A full hex digest cache key for an Element
+#    brief: An abbreviated hex digest cache key for an Element
+#    strict: Whether the key matches the key which would be used in strict mode
+#
+class _DisplayKey:
+    def __init__(self, full: str, brief: str, strict: bool):
+        self.full = full  # type: str
+        self.brief = brief  # type: str
+        self.strict = strict  # type: bool
+
+
 # _SchedulerErrorAction()
 #
 # Actions the scheduler can take on error
diff --git a/tests/frontend/artifact_log.py b/tests/frontend/artifact_log.py
index 6ea610a25..8fd51ea2a 100644
--- a/tests/frontend/artifact_log.py
+++ b/tests/frontend/artifact_log.py
@@ -19,6 +19,7 @@
 # pylint: disable=redefined-outer-name
 
 import os
+import re
 import pytest
 
 from buildstream.testing import cli  # pylint: disable=unused-import
@@ -88,9 +89,12 @@ def test_artifact_log_files(cli, datafiles):
     assert os.path.exists(import_bin)
 
     # Ensure the file contains the logs by checking for the LOG line
+    pattern = r"\[..:..:..\] LOG     \[.*\] target.bst"
     with open(target, "r") as f:
         data = f.read()
-        assert "LOG     target.bst" in data
+        assert len(re.findall(pattern, data, re.MULTILINE)) > 0
+
+    pattern = r"\[..:..:..\] LOG     \[.*\] import-bin.bst"
     with open(import_bin, "r") as f:
         data = f.read()
-        assert "LOG     import-bin.bst" in data
+        assert len(re.findall(pattern, data, re.MULTILINE)) > 0
diff --git a/tests/frontend/logging.py b/tests/frontend/logging.py
index 6eb058990..f2be66e99 100644
--- a/tests/frontend/logging.py
+++ b/tests/frontend/logging.py
@@ -13,10 +13,10 @@ from buildstream.exceptions import ErrorDomain
 from buildstream.testing import cli  # pylint: disable=unused-import
 
 # Project directory
-DATA_DIR = os.path.join(os.path.dirname(os.path.realpath(__file__)), "project",)
+DATA_DIR = os.path.dirname(os.path.realpath(__file__))
 
 
-@pytest.mark.datafiles(DATA_DIR)
+@pytest.mark.datafiles(os.path.join(DATA_DIR, "project"))
 def test_default_logging(cli, tmpdir, datafiles):
     project = str(datafiles)
     bin_files_path = os.path.join(project, "files", "bin-files")
@@ -41,7 +41,7 @@ def test_default_logging(cli, tmpdir, datafiles):
     assert m is not None
 
 
-@pytest.mark.datafiles(DATA_DIR)
+@pytest.mark.datafiles(os.path.join(DATA_DIR, "project"))
 def test_custom_logging(cli, tmpdir, datafiles):
     project = str(datafiles)
     bin_files_path = os.path.join(project, "files", "bin-files")
@@ -73,7 +73,7 @@ def test_custom_logging(cli, tmpdir, datafiles):
     assert m is not None
 
 
-@pytest.mark.datafiles(DATA_DIR)
+@pytest.mark.datafiles(os.path.join(DATA_DIR, "project"))
 def test_failed_build_listing(cli, datafiles):
     project = str(datafiles)
     element_names = []
@@ -106,5 +106,108 @@ def test_failed_build_listing(cli, datafiles):
     # Note that if we mess up the 'element_name' of Messages, they won't be printed
     # with the name of the relevant element, e.g. 'testfail-1.bst'. Check that
     # they have the name as expected.
-    pattern = r"\[..:..:..\] FAILURE testfail-.\.bst: Staged artifacts do not provide command 'sh'"
+    pattern = r"\[..:..:..\] FAILURE \[.*\] testfail-.\.bst: Staged artifacts do not provide command 'sh'"
     assert len(re.findall(pattern, result.stderr, re.MULTILINE)) == 6  # each element should be matched twice.
+
+
+# This test ensures that we get the expected element name and cache key in log lines.
+#
+#   * The master build log should show the element name and cache key
+#     of the task element, i.e. the element currently being built, not
+#     the element issuing the message.
+#
+#   * In the individual task log, we expect to see the name and cache
+#     key of the element issuing messages, since the entire log file
+#     is contextual to the task, it makes more sense to provide the
+#     full context of the element issuing the log in this case.
+#
+# The order and format of log lines are UI and as such might change
+# in which case this test needs to be adapted, the important part of
+# this test is only that we see task elements reported in the aggregated
+# master log file, and that we see message originating elements in
+# a task specific log file.
+#
+@pytest.mark.datafiles(os.path.join(DATA_DIR, "logging"))
+def test_log_line_element_names(cli, datafiles):
+
+    project = str(datafiles)
+
+    # First discover the cache keys, this will give us a dictionary
+    # where we can look up the brief cache key (as displayed in the logs)
+    # by the element name.
+    #
+    keys = {}
+    result = cli.run(project=project, args=["show", "--deps", "all", "--format", "%{name}||%{key}", "logtest.bst"])
+    result.assert_success()
+    lines = result.output.splitlines()
+    for line in lines:
+        split = line.split(sep="||")
+        keys[split[0]] = split[1]
+
+    # Run a build of the import elements, so that we can observe only the build of the logtest.bst element
+    # at the end.
+    #
+    result = cli.run(project=project, args=["build", "foo.bst", "bar.bst"])
+
+    # Now run the build
+    #
+    result = cli.run(project=project, args=["build", "logtest.bst"])
+    result.assert_success()
+    master_log = result.stderr
+
+    # Now run `bst artifact log` to conveniently collect the build log so we can compare it.
+    logfiles = os.path.join(project, "logfiles")
+    logfile = os.path.join(project, "logfiles", "logtest.log")
+    result = cli.run(project=project, args=["artifact", "log", "--out", logfiles, "logtest.bst"])
+    result.assert_success()
+
+    with open(logfile, "r") as f:
+        task_log = f.read()
+
+    #########################################################
+    #              Parse and assert master log              #
+    #########################################################
+
+    # In the master log, we're looking for lines like this:
+    #
+    # [--:--:--][10dc28c5][   build:logtest.bst                   ] STATUS  Staging bar.bst/40ff1c5a
+    # [--:--:--][10dc28c5][   build:logtest.bst                   ] STATUS  Staging foo.bst/e5ab75a1
+
+    # Capture (log key, element name, staged element name, staged element key)
+    pattern = r"\[--:--:--\]\[(\S*)\]\[\s*build:(\S*)\s*] STATUS  Staging\s*(\S*)/(\S*)"
+    lines = re.findall(pattern, master_log, re.MULTILINE)
+
+    # We staged 2 elements
+    assert len(lines) == 2
+
+    # Assert that the logtest.bst element name and it's cache key is used in the master log
+    for line in lines:
+        log_key, log_name, staged_name, staged_key = line
+
+        assert log_name == "logtest.bst"
+        assert log_key == keys["logtest.bst"]
+
+    #########################################################
+    #              Parse and assert artifact log            #
+    #########################################################
+
+    # In the task specific build log, we're looking for lines like this:
+    #
+    # [--:--:--] STATUS  [40ff1c5a] bar.bst: Staging bar.bst/40ff1c5a
+    # [--:--:--] STATUS  [e5ab75a1] foo.bst: Staging foo.bst/e5ab75a1
+
+    # Capture (log key, element name, staged element name, staged element key)
+    pattern = r"\[--:--:--\] STATUS  \[(\S*)\] (\S*): Staging\s*(\S*)/(\S*)"
+    lines = re.findall(pattern, task_log, re.MULTILINE)
+
+    # We staged 2 elements
+    assert len(lines) == 2
+
+    # Assert that the originating element names and cache keys are used in
+    # log lines when recorded to the task specific log file
+    for line in lines:
+        log_key, log_name, staged_name, staged_key = line
+
+        assert log_name == staged_name
+        assert log_key == staged_key
+        assert log_key == keys[log_name]
diff --git a/tests/frontend/logging/elements/bar.bst b/tests/frontend/logging/elements/bar.bst
new file mode 100644
index 000000000..db6f66526
--- /dev/null
+++ b/tests/frontend/logging/elements/bar.bst
@@ -0,0 +1,4 @@
+kind: import
+sources:
+- kind: local
+  path: files/bar
diff --git a/tests/frontend/logging/elements/foo.bst b/tests/frontend/logging/elements/foo.bst
new file mode 100644
index 000000000..487b8e2a5
--- /dev/null
+++ b/tests/frontend/logging/elements/foo.bst
@@ -0,0 +1,4 @@
+kind: import
+sources:
+- kind: local
+  path: files/foo
diff --git a/tests/frontend/logging/elements/logtest.bst b/tests/frontend/logging/elements/logtest.bst
new file mode 100644
index 000000000..cbfbaf86f
--- /dev/null
+++ b/tests/frontend/logging/elements/logtest.bst
@@ -0,0 +1,5 @@
+kind: logtest
+
+depends:
+- foo.bst
+- bar.bst
diff --git a/tests/frontend/logging/files/bar b/tests/frontend/logging/files/bar
new file mode 100644
index 000000000..e69de29bb
--- /dev/null
+++ b/tests/frontend/logging/files/bar
diff --git a/tests/frontend/logging/files/foo b/tests/frontend/logging/files/foo
new file mode 100644
index 000000000..e69de29bb
--- /dev/null
+++ b/tests/frontend/logging/files/foo
diff --git a/tests/frontend/logging/plugins/logtest.py b/tests/frontend/logging/plugins/logtest.py
new file mode 100644
index 000000000..0817a92d8
--- /dev/null
+++ b/tests/frontend/logging/plugins/logtest.py
@@ -0,0 +1,44 @@
+from buildstream import Element
+
+
+class LogTest(Element):
+    BST_MIN_VERSION = "2.0"
+
+    def configure(self, node):
+        pass
+
+    def preflight(self):
+        pass
+
+    def get_unique_key(self):
+        return {}
+
+    def configure_sandbox(self, sandbox):
+        pass
+
+    def stage(self, sandbox):
+        # Here we stage the artifacts of dependencies individually without
+        # using a timed activity or suppressing the logging.
+        #
+        # This allows us to test the logging behavior when log lines are
+        # triggered by an element which is not the element being processed.
+        #
+        #   * The master build log should show the element name and cache key
+        #     of the task element, i.e. the element currently being built, not
+        #     the element issuing the message.
+        #
+        #   * In the individual task log, we expect to see the name and cache
+        #     key of the element issuing messages, since the entire log file
+        #     is contextual to the task, it makes more sense to provide the
+        #     full context of the element issuing the log in this case.
+        #
+        for dep in self.dependencies():
+            dep.stage_artifact(sandbox)
+
+    def assemble(self, sandbox):
+        return "/"
+
+
+# Plugin entry point
+def setup():
+    return LogTest
diff --git a/tests/frontend/logging/project.conf b/tests/frontend/logging/project.conf
new file mode 100644
index 000000000..151b0cd1a
--- /dev/null
+++ b/tests/frontend/logging/project.conf
@@ -0,0 +1,10 @@
+# Project config for frontend build test
+name: test
+min-version: 2.0
+element-path: elements
+
+plugins:
+- origin: local
+  path: plugins
+  elements:
+  - logtest