Repository: OSInside/kiwi

Issue:
Missing stderr output for logged command output
We apparently do not capture stderr output, which resulted in https://github.com/rpm-software-management/dnf5/issues/2116.

We should change this because having information hidden from us in logs can make diagnosing issues much more difficult.

Hints from issue comments:
@schaefi: Hmm, I might be missing some details here. Why are we not capturing stderr ? In case of an error of a kiwi command invocation all of stderr will be logged. We do not expect commands to log non error information to stderr. I admit I haven't read the dnf issue so far

@Conan-Kudo: The issue is that the DNF team has decided a lot of informational output should move from stdout to stderr. That results in our image-root logs missing a lot of debug information when `--debug` is passed in.

Solution patch:
diff --git a/kiwi/command_process.py b/kiwi/command_process.py
index b9b9e2ab..17cfd61e 100644
--- a/kiwi/command_process.py
+++ b/kiwi/command_process.py
@@ -18,6 +18,9 @@
 import logging
 from collections import namedtuple
 from kiwi.command import CommandCallT
+from typing import (
+    NamedTuple, List, Callable
+)
 
 # project
 from kiwi.utils.codec import Codec
@@ -28,6 +31,11 @@ from kiwi.exceptions import KiwiCommandError
 log = logging.getLogger('kiwi')
 
 
+class PollT(NamedTuple):
+    stdout_line: str
+    stderr_line: str
+
+
 class CommandProcess:
     """
     **Implements processing of non blocking Command calls**
@@ -47,7 +55,8 @@ class CommandProcess:
         """
         Iterate over process, raise on error and log output
         """
-        for line in self.command:
+        for lineT in self.command:
+            line = lineT.stdout_line
             if line:
                 log.debug('%s: %s', self.log_topic, line)
         if self.command.get_error_code() != 0:
@@ -55,7 +64,10 @@ class CommandProcess:
                 self.command.get_error_output()
             )
 
-    def poll_show_progress(self, items_to_complete, match_method):
+    def poll_show_progress(
+        self, items_to_complete: List[str], match_method: Callable,
+        with_stderr: bool = False
+    ):
         """
         Iterate over process and show progress in percent
         raise on error and log output
@@ -64,12 +76,16 @@ class CommandProcess:
         :param function match_method: method matching item
         """
         self._init_progress()
-        for line in self.command:
-            if line:
-                log.debug('%s: %s', self.log_topic, line)
-                self._update_progress(
-                    match_method, items_to_complete, line
-                )
+        for lineT in self.command:
+            lines = [lineT.stdout_line]
+            if with_stderr:
+                lines.append(lineT.stderr_line)
+            for line in lines:
+                if line:
+                    log.debug('%s: %s', self.log_topic, line)
+                    self._update_progress(
+                        match_method, items_to_complete, line
+                    )
         self._stop_progress()
         if self.command.get_error_code() != 0:
             raise KiwiCommandError(
@@ -83,7 +99,8 @@ class CommandProcess:
         """
         log.info(self.log_topic)
         log.debug('--------------out start-------------')
-        for line in self.command:
+        for lineT in self.command:
+            line = lineT.stdout_line
             if line:
                 log.debug(line)
         log.debug('--------------out stop--------------')
@@ -152,11 +169,13 @@ class CommandIterator:
         self.command = command
         self.command_error_output = bytes(b'')
         self.command_output_line = bytes(b'')
+        self.command_error_line = bytes(b'')
         self.output_eof_reached = False
         self.errors_eof_reached = False
 
-    def __next__(self):
-        line_read = None
+    def __next__(self) -> PollT:
+        line_stdout = ''
+        line_stderr = ''
         if self.command.process.poll() is not None:
             if self.output_eof_reached and self.errors_eof_reached:
                 raise StopIteration()
@@ -166,7 +185,7 @@ class CommandIterator:
             if not byte_read:
                 self.output_eof_reached = True
             elif byte_read == bytes(b'\n'):
-                line_read = Codec.decode(self.command_output_line)
+                line_stdout = Codec.decode(self.command_output_line)
                 self.command_output_line = bytes(b'')
             else:
                 self.command_output_line += byte_read
@@ -175,10 +194,17 @@ class CommandIterator:
             byte_read = self.command.error.read(1)
             if not byte_read:
                 self.errors_eof_reached = True
+            elif byte_read == bytes(b'\n'):
+                line_stderr = Codec.decode(self.command_error_line)
+                self.command_error_line = bytes(b'')
             else:
+                self.command_error_line += byte_read
                 self.command_error_output += byte_read
 
-        return line_read
+        return PollT(
+            stdout_line=line_stdout,
+            stderr_line=line_stderr
+        )
 
     def get_error_output(self):
         """
diff --git a/kiwi/package_manager/dnf5.py b/kiwi/package_manager/dnf5.py
index fe13e119..0b0e6ec8 100644
--- a/kiwi/package_manager/dnf5.py
+++ b/kiwi/package_manager/dnf5.py
@@ -308,7 +308,7 @@ class PackageManagerDnf5(PackageManagerBase):
         """
         return bool(
             re.match(
-                '.*Installing.*: {0}.*'.format(re.escape(package_name)),
+                '.*Installing.* {0}.*'.format(re.escape(package_name)),
                 package_manager_output
             )
         )
@@ -328,7 +328,7 @@ class PackageManagerDnf5(PackageManagerBase):
         """
         return bool(
             re.match(
-                '.*Removing.*: {0}.*'.format(re.escape(package_name)),
+                '.*Removing.* {0}.*'.format(re.escape(package_name)),
                 package_manager_output
             )
         )
diff --git a/kiwi/system/prepare.py b/kiwi/system/prepare.py
index 7416150c..97ad7e54 100644
--- a/kiwi/system/prepare.py
+++ b/kiwi/system/prepare.py
@@ -254,6 +254,7 @@ class SystemPrepare:
         bootstrap_archives = self.xml_state.get_bootstrap_archives()
         bootstrap_archives_target_dirs = self.xml_state.get_bootstrap_archives_target_dirs()
         bootstrap_packages_ignored = self.xml_state.get_bootstrap_ignore_packages()
+        package_manager = self.xml_state.get_package_manager()
         # process package installations
         if collection_type == 'onlyRequired':
             manager.process_only_required()
@@ -279,7 +280,8 @@ class SystemPrepare:
                 items_to_complete=all_install_items,
                 match_method=process.create_match_method(
                     manager.match_package_installed
-                )
+                ),
+                with_stderr=True if package_manager == 'dnf5' else False
             )
         except Exception as issue:
             if manager.has_failed(process.returncode()):
@@ -331,6 +333,7 @@ class SystemPrepare:
         system_archives = self.xml_state.get_system_archives()
         system_archives_target_dirs = self.xml_state.get_system_archives_target_dirs()
         system_packages_ignored = self.xml_state.get_system_ignore_packages()
+        package_manager = self.xml_state.get_package_manager()
         # process package installations
         if collection_type == 'onlyRequired':
             manager.process_only_required()
@@ -352,7 +355,8 @@ class SystemPrepare:
                     items_to_complete=all_install_items,
                     match_method=process.create_match_method(
                         manager.match_package_installed
-                    )
+                    ),
+                    with_stderr=True if package_manager == 'dnf5' else False
                 )
             except Exception as issue:
                 if manager.has_failed(process.returncode()):
@@ -447,6 +451,7 @@ class SystemPrepare:
         :raises KiwiSystemInstallPackagesFailed: if installation process fails
         """
         log.info('Installing system packages (chroot)')
+        package_manager = self.xml_state.get_package_manager()
         all_install_items = self._setup_requests(
             manager, packages
         )
@@ -459,7 +464,8 @@ class SystemPrepare:
                     items_to_complete=all_install_items,
                     match_method=process.create_match_method(
                         manager.match_package_installed
-                    )
+                    ),
+                    with_stderr=True if package_manager == 'dnf5' else False
                 )
             except Exception as issue:
                 raise KiwiSystemInstallPackagesFailed(
@@ -484,6 +490,7 @@ class SystemPrepare:
 
         :raises KiwiSystemDeletePackagesFailed: if installation process fails
         """
+        package_manager = self.xml_state.get_package_manager()
         all_delete_items = self._setup_requests(
             manager, packages
         )
@@ -502,7 +509,8 @@ class SystemPrepare:
                     items_to_complete=all_delete_items,
                     match_method=process.create_match_method(
                         manager.match_package_deleted
-                    )
+                    ),
+                    with_stderr=True if package_manager == 'dnf5' else False
                 )
                 manager.post_process_delete_requests(self.root_bind)
             except Exception as issue:


Test patch:
diff --git a/test/unit/command_process_test.py b/test/unit/command_process_test.py
index d553b298..2b5134e5 100644
--- a/test/unit/command_process_test.py
+++ b/test/unit/command_process_test.py
@@ -7,8 +7,10 @@ from pytest import (
 )
 from builtins import bytes
 
-from kiwi.command_process import CommandProcess
-from kiwi.command_process import CommandIterator
+from kiwi.command_process import (
+    CommandProcess,
+    CommandIterator
+)
 
 from kiwi.exceptions import KiwiCommandError
 
@@ -42,13 +44,13 @@ class TestCommandProcess:
         return create_method
 
     def setup(self):
-        self.data_flow = [True, None, None, None, None, None, None]
+        self.data_flow = [True, None, None, None, None, None, None, None]
         self.data_out = [
-            bytes(b''), bytes(b'\n'), bytes(b'a'),
+            bytes(b''), bytes(b''), bytes(b'\n'), bytes(b'a'),
             bytes(b't'), bytes(b'a'), bytes(b'd')
         ]
         self.data_err = [
-            bytes(b''), bytes(b'r'), bytes(b'o'),
+            bytes(b''), bytes(b'\n'), bytes(b'r'), bytes(b'o'),
             bytes(b'r'), bytes(b'r'), bytes(b'e')
         ]
         self.flow = self.create_flow_method(self.poll)
@@ -80,7 +82,7 @@ class TestCommandProcess:
         process.command.command.error.read = self.flow_err
         process.command.command.process.returncode = 0
         with self._caplog.at_level(logging.DEBUG):
-            process.poll_show_progress(['a', 'b'], match_method)
+            process.poll_show_progress(['a', 'b'], match_method, True)
             assert 'system: data' in self._caplog.text
 
     @patch('kiwi.command.Command')