tests/frontend/logging.py: Test log lines for correct element names/keystristan/fix-logging-element-names

When printing log lines to the master log, we ensure that log lines are
printed with the element name and cache key which are related to the task
from which the messages are being issued.

When printing log lines to task specific log lines, we prefer to print
the element names and cache keys which pertain to the element from which
the log line was actually issued.

This new tests asserts this behavior.

8 files changed, 174 insertions, 4 deletions

diff --git a/tests/frontend/logging.py b/tests/frontend/logging.py
index a86bda577..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 = []
@@ -108,3 +108,106 @@ def test_failed_build_listing(cli, datafiles):
     # they have the name as expected.
     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