Merge remote-tracking branch 'richtja/logging_fix'

Signed-off-by: Cleber Rosa <[email protected]>

avocado/core/job.py

@@ -209,7 +209,9 @@ def __exit__(self, _exc_type, _exc_value, _traceback):
     def __start_job_logging(self):
         # Enable test logger
         full_log = os.path.join(self.logdir, "full.log")
-        fmt = "%(asctime)s %(name)s %(levelname)-5.5s| %(message)s"
+        fmt = (
+            "%(asctime)s %(module)-16.16s L%(lineno)-.4d %(levelname)-5.5s| %(message)s"
+        )
         output.add_log_handler(
             LOG_JOB,
             logging.FileHandler,
@@ -219,7 +221,20 @@ def __start_job_logging(self):
             handler_filter=output.FilterTestMessage(),
         )
         output.add_log_handler(
-            logging.getLogger(""), logging.FileHandler, full_log, self.loglevel, fmt
+            logging.getLogger(""),
+            logging.FileHandler,
+            full_log,
+            self.loglevel,
+            fmt,
+            handler_filter=output.FilterTestMessage(),
+        )
+        output.add_log_handler(
+            logging.getLogger(""),
+            logging.FileHandler,
+            full_log,
+            self.loglevel,
+            "",
+            handler_filter=output.FilterTestMessageOnly(),
         )
 
         # --store-logging-stream files
@@ -233,7 +248,20 @@ def __start_job_logging(self):
                 level = logging.DEBUG
                 logfile = os.path.join(self.logdir, f"{enabled_logger}.log")
             output.add_log_handler(
-                enabled_logger, logging.FileHandler, logfile, level, fmt
+                enabled_logger,
+                logging.FileHandler,
+                logfile,
+                level,
+                fmt,
+                handler_filter=output.FilterTestMessage(),
+            )
+            output.add_log_handler(
+                enabled_logger,
+                logging.FileHandler,
+                logfile,
+                level,
+                "",
+                handler_filter=output.FilterTestMessageOnly(),
             )
 
     def __stop_job_logging(self):

avocado/core/messages.py

@@ -337,9 +337,6 @@ class LogMessageHandler(BaseRunningMessageHandler):
     :param log_levelname: level of the logger, such as "INFO", required
                           if "log_name" is set
     :type log_levelname: string
-    :param log_message: message formatted as message only (no name, level
-                        or timestamp), require if "log_name" is set
-    :type log_message: string
 
     example: {'status': 'running', 'type': 'log', 'log': 'log message',
               'time': 18405.55351474}
@@ -348,7 +345,7 @@ class LogMessageHandler(BaseRunningMessageHandler):
 
     example: {'status': 'running', 'type': 'log', 'log': 'log message',
               'time': 18405.55351474, 'log_name': 'avocado.test.foo',
-              'log_levelname': 'INFO', 'log_message': 'foo content'}
+              'log_levelname': 'INFO'}
     """
 
     _tag = b"[stdlog] "
@@ -372,7 +369,7 @@ def handle(self, message, task, job):
         if log_name is not None and log_name != "avocado.app":
             logger = logging.getLogger(log_name)
             level = logging.getLevelName(message.get("log_levelname"))
-            log_message = f"{task.identifier}: {message.get('log_message')}"
+            log_message = f"{task.identifier}: {message.get('log').decode(message.get('encoding'))}"
             logger_level = logger.level
             logger.setLevel(level)
             logger.log(level, log_message)

avocado/core/output.py

@@ -567,6 +567,11 @@ def filter(self, record):
         return record.module != "messages" and record.funcName != "handle"
 
 
+class FilterTestMessageOnly(logging.Filter):
+    def filter(self, record):
+        return record.module == "messages" and record.funcName == "handle"
+
+
 class ProgressStreamHandler(logging.StreamHandler):
 
     """

avocado/core/utils/messages.py

@@ -198,11 +198,9 @@ def message_only_formatter(self):
     def emit(self, record):
         msg = self.format(record)
         if self.message is LogMessage:
-            formatted_msg = self.message_only_formatter.format(record)
             kwargs = {
                 "log_name": record.name,
                 "log_levelname": record.levelname,
-                "log_message": formatted_msg,
             }
             kwargs.update(**self.kwargs)
         else:
@@ -249,7 +247,7 @@ def start_logging(config, queue):
 
     log_level = config.get("job.output.loglevel", logging.DEBUG)
     log_handler = RunnerLogHandler(queue, "log")
-    fmt = "%(asctime)s %(name)s %(levelname)-5.5s| %(message)s"
+    fmt = "%(asctime)s %(module)-16.16s L%(lineno)-.4d %(levelname)-5.5s| %(message)s"
     formatter = logging.Formatter(fmt=fmt)
     log_handler.setFormatter(formatter)
 

selftests/functional/output.py

@@ -462,23 +462,22 @@ def test_show_custom_log(self):
             expected_rc,
             (f"Avocado did not return rc {expected_rc}:" f"\n{result}"),
         )
-        self.assertEqual(
-            result.stdout_text,
-            (
-                "avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: preparing soil on row 0\n"
-                "avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: preparing soil on row 1\n"
-                "avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: preparing soil on row 2\n"
-                "avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: letting soil rest before throwing seeds\n"
-                "avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: throwing seeds on row 0\n"
-                "avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: throwing seeds on row 1\n"
-                "avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: throwing seeds on row 2\n"
-                "avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: waiting for Avocados to grow\n"
-                "avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: harvesting organic avocados on row 0\n"
-                "avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: harvesting organic avocados on row 1\n"
-                "avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: harvesting organic avocados on row 2\n"
-                "avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic: Avocados are Gone\n"
-            ),
-        )
+        expected_tesult = [
+            "avocado.test.progress: 1-examples/tests/logging_streams.py:Plant.test_plant_organic:",
+            "logging_streams  L0017 INFO | preparing soil on row 0",
+            "logging_streams  L0017 INFO | preparing soil on row 1",
+            "logging_streams  L0017 INFO | preparing soil on row 2",
+            "logging_streams  L0021 INFO | letting soil rest before throwing seeds",
+            "logging_streams  L0026 INFO | throwing seeds on row 0",
+            "logging_streams  L0026 INFO | throwing seeds on row 1",
+            "logging_streams  L0026 INFO | throwing seeds on row 2",
+            "logging_streams  L0030 INFO | waiting for Avocados to grow",
+            "logging_streams  L0035 INFO | harvesting organic avocados on row 0",
+            "logging_streams  L0035 INFO | harvesting organic avocados on row 1",
+            "logging_streams  L0035 INFO | harvesting organic avocados on row 2",
+            "logging_streams  L0037 ERROR| Avocados are Gone",
+        ]
+        self.assertTrue(all([x in result.stdout_text for x in expected_tesult]))
 
     def test_silent_trumps_test(self):
         # Also verify --show=none can be supplied as run option

selftests/functional/streams.py

@@ -152,12 +152,15 @@ def test_job_log_separation(self):
         self.assertEqual(result.exit_status, exit_codes.AVOCADO_ALL_OK)
         with open(job_log_path, "rb") as job_log_file:
             wrong_lines = list(
-                filter(lambda x: b"avocado.job" not in x, job_log_file.readlines())
+                filter(
+                    lambda x: b"job" not in x and b"testlogs" not in x,
+                    job_log_file.readlines(),
+                )
             )
             self.assertEqual(
                 len(wrong_lines),
                 0,
-                "job.log has different logging streams that avocado.job",
+                "job.log has different logging streams than avocado.job",
             )
 
     def test_logs_duplication(self):