CP-48447+CA-390127: correct exception handling for func_output callba…

…cks, fix saving all log messages (#92)

* CP-48447: Fix Python3 handling Exceptions from func_output calls
* CA-390127: Fix adding even the last log() messages to the output archive (#93)

Signed-off-by: Bernhard Kaindl <bernhard.kaindl@cloud.com>

.vscode/ltex.dictionary.en-US.txt

@@ -8,6 +8,7 @@ authkey
 autoflake
 autouse
 backend
+backtrace
 basename
 basepath
 basestring
@@ -57,6 +58,7 @@ dir
 dircmp
 dirs
 docstrings
+dont
 dp
 dunder
 efi
@@ -127,6 +129,7 @@ networkd
 NEWNET
 NEWNS
 nonexisting
+NOSONAR
 NRPE
 nsswitch
 nvme

tests/unit/test_main.py

@@ -1,4 +1,5 @@
 """pytest module for unit-testing xen-bugtool's main() function"""
+
 import logging
 import os
 import sys
@@ -7,8 +8,9 @@
 
 import pytest
 
+# sourcery skip: dont-import-test-modules
 from . import test_xapidb_filter
-from .test_output import assert_valid_inventory_schema, parse
+from .test_output import MOCK_EXCEPTION_STRINGS, assert_valid_inventory_schema, mock_data_collector, parse
 
 
 yes_to_all_warning = """\
@@ -132,6 +134,7 @@ def return_no_for_proc_files(prompt):
         "xenserver-config",
         "xenserver-databases",
         "mock",
+        "xen-bugtool",
         "unknown",
     ]
     sys.argv.append("--entries=" + ",".join(entries))
@@ -177,6 +180,10 @@ def check_output(bugtool, captured, tmp_path, filename, filetype):
     # Provides a nicely formatted diff (unlike str.startswith()) on assertions:
     assert captured.out[: len(out_begin)] == out_begin
 
+    # Assert that the backtrace from the mock data collector is printed:
+    for backtrace_string in MOCK_EXCEPTION_STRINGS:
+        assert backtrace_string in captured.out
+
     if bugtool.ProcOutput.debug:
         assert p + "Starting '%s list'\n" % bugtool.BIN_STATIC_VDIS in captured.out
         for ls in ("/opt/xensource", "/etc/xensource/static-vdis"):
@@ -207,11 +214,42 @@ def check_output(bugtool, captured, tmp_path, filename, filetype):
         d = xenstore_ls_f.read()
     assert d == "/local/domain/1/data/set_clipboard = <filtered for security>\n"
 
+    #
+    # Given that --entries= includes `xen-bugtool`, the output should contain a log
+    # file with the backtrace from the Exception raised by the mock data collector:
+    #
+    with open(output_directory + "/xen-bugtool.log") as logfile:
+        assert_bugtool_logfile_data(logfile)
+
     # Assertion check of the output files is missing an inventory entry:
     # Do this check in a future test which runs
     assert_valid_inventory_schema(parse(output_directory + "inventory.xml"))
 
 
+def assert_bugtool_logfile_data(logfile):
+    """
+    Given that --entries= includes `xen-bugtool`, the output should contain a log
+    file with the backtrace from the Exception raised by the mock data collector:
+    """
+    log = logfile.read()
+    lines = log.splitlines()
+    assert len(lines) >= 2
+    assert lines[0].startswith(
+        "xen-bugtool --unlimited --entries=xenserver-config,"
+        "xenserver-databases,mock,xen-bugtool,unknown --out",
+    )
+    assert lines[1].startswith("PATH=")
+
+    #
+    # Given that the exception raised by the mock data collector function is
+    # caught and logged, the log file should contain the backtrace from the
+    # raised exception:
+    #
+    assert len(lines) == 9
+    for backtrace_string in MOCK_EXCEPTION_STRINGS:
+        assert backtrace_string in log
+
+
 def assert_valid_inventory(bugtool, args, cap, tmp_path, base_path, filetype):
     """Run the bugtool module object's main() function and check its output
 
@@ -229,6 +267,12 @@ def assert_valid_inventory(bugtool, args, cap, tmp_path, base_path, filetype):
     """
     sys.argv.extend(args)
 
+    # Given that we'd like to test handling of exceptions from func_output callbacks,
+    # we add a mock data collector function to a mock entry that raises an exception:
+    #
+    bugtool.entries = ["mock"]
+    bugtool.func_output("mock", "function_output.out", mock_data_collector)
+
     assert bugtool.main() == 0
     filename = base_path + "." + filetype
     with cap.disabled():

tests/unit/test_output.py

@@ -1,10 +1,31 @@
 """Unit tests for bugtool core functions creating minimal output archives"""
+
 import os
 import tarfile
 import zipfile
 
 from lxml.etree import XMLSchema, parse  # pytype: disable=import-error
 
+MOCK_EXCEPTION_STRINGS = (
+    "Traceback (most recent call last):",
+    ", in collect_data",
+    ", in mock_data_collector",
+    'raise Exception("mock data collector failed")',
+    "Exception: mock data collector failed",
+)
+
+
+def mock_data_collector(capability):
+    """Mock data collector for the mock plugin"""
+
+    # Assert that the mock data collector is called with the correct capability:
+    assert capability == "mock"
+
+    # Raise an exception to test the backtrace output in the bugtool log:
+    # sourcery skip: raise-specific-error
+    # pylint: disable-next=broad-exception-raised
+    raise Exception("mock data collector failed")
+
 
 def assert_valid_inventory_schema(inventory_tree):
     """Assert that the passed inventory validates against the inventory schema"""
@@ -20,6 +41,7 @@ def assert_mock_bugtool_plugin_output(temporary_directory, subdir, names):
     expected_names = [
         subdir + "/etc/group",
         subdir + "/etc/passwd.tar",
+        subdir + "/function_output.out",
         subdir + "/inventory.xml",
         subdir + "/ls-l-%etc.out",
         subdir + "/proc/self/status",
@@ -64,8 +86,17 @@ def minimal_bugtool(bugtool, dom0_template, archive, subdir, mocker):
     # For code coverage: This sub-archive will not be created as it has no file
     archive.declare_subarchive("/not/existing", subdir + "/not_created.tar")
     bugtool.load_plugins(just_capabilities=False)
+
+    # Add a mock data collector function to the mock plugin that raises an exception:
+    bugtool.func_output("mock", "function_output.out", mock_data_collector)
+
+    # Add collecting the xen-bugtool.log file (as CAP_XEN_BUGTOOL) to the archive:
+    bugtool.file_output(bugtool.CAP_XEN_BUGTOOL, [bugtool.XEN_BUGTOOL_LOG])
+
     # Mock the 2nd argument of the ls -l /etc to collect it using dom0_template:
     bugtool.data["ls -l /etc"]["cmd_args"][2] = dom0_template + "/etc"
+
+    # Collect the data from the mock plugin and write the output to the archive:
     bugtool.collect_data(subdir, archive)
     bugtool.include_inventory(archive, subdir)
     archive.close()
@@ -89,6 +120,10 @@ def assert_minimal_bugtool(bugtool, state_archive, dom0_template, cap):
         for msg in [version, etc_dir]:
             assert "[time.strftime]  Starting '%s'\n" % msg in captured_stdout
 
+    # Assert that the backtrace from the mock data collector is printed:
+    for backtrace_string in MOCK_EXCEPTION_STRINGS:
+        assert backtrace_string in captured_stdout
+
     filetype = "tarball" if ".tar" in state_archive.filename else "archive"
     written = "Writing %s %s successful.\n" % (filetype, state_archive.filename)
     assert captured_stdout[-len(written) :] == written

xen-bugtool

@@ -719,8 +719,9 @@ def collect_data(subdir, archive):
             try:
                 s = no_unicode(v["func"](cap))
             except Exception:
-                s = traceback.format_exc()
-                log(s)
+                backtrace = traceback.format_exc()  # type: str
+                log(backtrace)
+                s = backtrace.encode()
             if unlimited_data or caps[cap][MAX_SIZE] == -1 or \
                     cap_sizes[cap] < caps[cap][MAX_SIZE]:
                 v['output'] = StringIOmtime(s)
@@ -1272,8 +1273,6 @@ exclude those logs from the archive.
     cmd_output(CAP_YUM, [RPM, '-qa'])
     tree_output(CAP_YUM, SIGNING_KEY_INFO_DIR)
 
-    file_output(CAP_XEN_BUGTOOL, [XEN_BUGTOOL_LOG])
-
     # permit the user to filter out data
     for k in sorted(data.keys()):
         if not ANSWER_YES_TO_ALL and not yes("Include '%s'? [Y/n]: " % k):
@@ -1310,6 +1309,12 @@ exclude those logs from the archive.
     output_ts('Running commands to collect data')
     collect_data(subdir, archive)
 
+    # after all is done, include all log() entries from the XEN_BUGTOOL_LOG file
+    if CAP_XEN_BUGTOOL in entries:
+        archive.addRealFile(
+            construct_filename(subdir, XEN_BUGTOOL_LOG, {}), XEN_BUGTOOL_LOG
+        )
+
     # include inventory
     include_inventory(archive, subdir)