twister: setup logging per process

Setup logging per process to fix issue on both mac and windows where
handlers are not available to the processes.

Fixes #86237

Signed-off-by: Anas Nashif <anas.nashif@intel.com>

scripts/pylib/twister/twisterlib/log_helper.py

@@ -5,11 +5,17 @@
 Common code used when logging that is needed by multiple modules.
 '''
 
+import logging
+import os
 import platform
 import shlex
 
 _WINDOWS = (platform.system() == 'Windows')
 
+
+logger = logging.getLogger("twister")
+logger.setLevel(logging.DEBUG)
+
 def log_command(logger, msg, args):
     '''Platform-independent helper for logging subprocess invocations.
     Will log a command string that can be copy/pasted into a POSIX
@@ -25,3 +31,34 @@ def log_command(logger, msg, args):
         logger.debug(msg, str(args))
     else:
         logger.debug(msg, shlex.join(args))
+
+
+
+def setup_logging(outdir, log_file, log_level, timestamps):
+    # create file handler which logs even debug messages
+    if log_file:
+        fh = logging.FileHandler(log_file)
+    else:
+        fh = logging.FileHandler(os.path.join(outdir, "twister.log"))
+
+    fh.setLevel(logging.DEBUG)
+
+    # create console handler with a higher log level
+    ch = logging.StreamHandler()
+    ch.setLevel(getattr(logging, log_level))
+
+    # create formatter and add it to the handlers
+    if timestamps:
+        formatter = logging.Formatter("%(asctime)s - %(levelname)s - %(message)s")
+    else:
+        formatter = logging.Formatter("%(levelname)-7s - %(message)s")
+
+    formatter_file = logging.Formatter(
+        "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
+    )
+    ch.setFormatter(formatter)
+    fh.setFormatter(formatter_file)
+
+    # add the handlers to logger
+    logger.addHandler(ch)
+    logger.addHandler(fh)

scripts/pylib/twister/twisterlib/runner.py

@@ -29,6 +29,7 @@
 from twisterlib.cmakecache import CMakeCache
 from twisterlib.environment import canonical_zephyr_base
 from twisterlib.error import BuildError, ConfigurationError, StatusAttributeError
+from twisterlib.log_helper import setup_logging
 from twisterlib.statuses import TwisterStatus
 
 if version.parse(elftools.__version__) < version.parse('0.24'):
@@ -978,7 +979,9 @@ def process(self, pipeline, done, message, lock, results):
         additionals = {}
 
         op = message.get('op')
-
+        options = self.options
+        if not logger.handlers:
+            setup_logging(options.outdir, options.log_file, options.log_level, options.timestamps)
         self.instance.setup_handler(self.env)
 
         if op == "filter":

scripts/pylib/twister/twisterlib/twister_main.py

@@ -15,6 +15,7 @@
 from twisterlib.coverage import run_coverage
 from twisterlib.environment import TwisterEnv
 from twisterlib.hardwaremap import HardwareMap
+from twisterlib.log_helper import setup_logging
 from twisterlib.package import Artifacts
 from twisterlib.reports import Reporting
 from twisterlib.runner import TwisterRunner
@@ -25,35 +26,6 @@
 logger.setLevel(logging.DEBUG)
 
 
-def setup_logging(outdir, log_file, log_level, timestamps):
-    # create file handler which logs even debug messages
-    if log_file:
-        fh = logging.FileHandler(log_file)
-    else:
-        fh = logging.FileHandler(os.path.join(outdir, "twister.log"))
-
-    fh.setLevel(logging.DEBUG)
-
-    # create console handler with a higher log level
-    ch = logging.StreamHandler()
-    ch.setLevel(getattr(logging, log_level))
-
-    # create formatter and add it to the handlers
-    if timestamps:
-        formatter = logging.Formatter("%(asctime)s - %(levelname)s - %(message)s")
-    else:
-        formatter = logging.Formatter("%(levelname)-7s - %(message)s")
-
-    formatter_file = logging.Formatter(
-        "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
-    )
-    ch.setFormatter(formatter)
-    fh.setFormatter(formatter_file)
-
-    # add the handlers to logger
-    logger.addHandler(ch)
-    logger.addHandler(fh)
-
 
 def init_color(colorama_strip):
     colorama.init(strip=colorama_strip)

scripts/tests/twister/test_runner.py

@@ -1482,6 +1482,7 @@ def mock_getsize(filename, *args, **kwargs):
 def test_projectbuilder_process(
     caplog,
     mocked_jobserver,
+    tmp_path,
     message,
     instance_status,
     instance_reason,
@@ -1529,6 +1530,9 @@ def mock_determine_testcases(res):
     pb.options.prep_artifacts_for_testing = options_prep_artifacts
     pb.options.runtime_artifact_cleanup = options_runtime_artifacts
     pb.options.cmake_only = options_cmake_only
+    pb.options.outdir = tmp_path
+    pb.options.log_file = None
+    pb.options.log_level = "DEBUG"
 
     pb.cmake = mock.Mock(return_value=cmake_res)
     pb.build = mock.Mock(return_value=build_res)