Skip to content

Commit

Permalink
remove log_message attribute from log message
Browse files Browse the repository at this point in the history 
We use to re-log messages when avocado receives them from runner. For
this feature we supported the `log_message` attribute which split the
log message into two part, one with the real log and second log with
metadata. Unfortunately, this solution has an issue. When avocado
re-logs the message, it loses the logging metadata and logs shows wrong
lines and modules. This commit removes this mechanism and keep the
creation of log messages only to runners.

before this change:

2023-07-25 10:33:52,781 messages         L0378 INFO |
1-examples/tests/passtest.py:PassTest.test: INIT
1-examples/tests/passtest.py:PassTest.test
2023-07-25 10:33:52,781 messages         L0378 DEBUG|
1-examples/tests/passtest.py:PassTest.test: PARAMS (key=timeout, path=*,
default=None) => None

after this change:
1-examples/tests/passtest.py:PassTest.test: 2023-07-25 14:00:50,323 test
L0313 INFO | INIT 1-examples/tests/passtest.py:PassTest.test
1-examples/tests/passtest.py:PassTest.test: 2023-07-25 14:00:50,324
parameters       L0141 DEBUG| PARAMS (key=timeout, path=*, default=None)
=> None

Signed-off-by: Jan Richter <[email protected]>
  • Loading branch information
@richtja
richtja committed Jul 25, 2023
1 parent 268fe54 commit a8f5a44
Show file tree
Hide file tree
Showing 5 changed files with 51 additions and 26 deletions.
30 changes: 28 additions & 2 deletions avocado/core/job.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -221,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
Expand All @@ -235,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):
Expand Down
7 changes: 2 additions & 5 deletions avocado/core/messages.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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}
Expand All @@ -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] "
Expand All @@ -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)
Expand Down
5 changes: 5 additions & 0 deletions avocado/core/output.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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):

"""
Expand Down
2 changes: 0 additions & 2 deletions avocado/core/utils/messages.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand Down
33 changes: 16 additions & 17 deletions selftests/functional/output.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down

0 comments on commit a8f5a44

Please sign in to comment.