diff --git a/swh/core/logger.py b/swh/core/logger.py index 0a2511f..d75580f 100644 --- a/swh/core/logger.py +++ b/swh/core/logger.py @@ -1,104 +1,114 @@ # Copyright (C) 2015 The Software Heritage developers # See the AUTHORS file at the top-level directory of this distribution # License: GNU General Public License version 3, or any later version # See top-level LICENSE file for more information import datetime import logging +from typing import Any, Generator, List, Tuple from systemd.journal import JournalHandler as _JournalHandler, send try: from celery import current_task except ImportError: current_task = None EXTRA_LOGDATA_PREFIX = 'swh_' def db_level_of_py_level(lvl): """convert a log level of the logging module to a log level suitable for the logging Postgres DB """ return logging.getLevelName(lvl).lower() def get_extra_data(record, task_args=True): """Get the extra data to insert to the database from the logging record""" log_data = record.__dict__ extra_data = {k[len(EXTRA_LOGDATA_PREFIX):]: v for k, v in log_data.items() if k.startswith(EXTRA_LOGDATA_PREFIX)} args = log_data.get('args') if args: extra_data['logging_args'] = args # Retrieve Celery task info if current_task and current_task.request: extra_data['task'] = { 'id': current_task.request.id, 'name': current_task.name, } if task_args: extra_data['task'].update({ 'kwargs': current_task.request.kwargs, 'args': current_task.request.args, }) return extra_data -def flatten(data, separator='_'): +def flatten( + data: Any, + separator: str = "_" +) -> Generator[Tuple[str, Any], None, None]: """Flatten the data dictionary into a flat structure""" - def inner_flatten(data, prefix): + + def inner_flatten( + data: Any, prefix: List[str] + ) -> Generator[Tuple[List[str], Any], None, None]: if isinstance(data, dict): - for key, value in data.items(): - yield from inner_flatten(value, prefix + [key]) + if all(isinstance(key, str) for key in data): + for key, value in data.items(): + yield from inner_flatten(value, prefix + [key]) + else: + yield prefix, str(data) elif isinstance(data, (list, tuple)): for key, value in enumerate(data): yield from inner_flatten(value, prefix + [str(key)]) else: yield prefix, data for path, value in inner_flatten(data, []): yield separator.join(path), value def stringify(value): """Convert value to string""" if isinstance(value, datetime.datetime): return value.isoformat() return str(value) class JournalHandler(_JournalHandler): def emit(self, record): """Write `record` as a journal event. MESSAGE is taken from the message provided by the user, and PRIORITY, LOGGER, THREAD_NAME, CODE_{FILE,LINE,FUNC} fields are appended automatically. In addition, record.MESSAGE_ID will be used if present. """ try: extra_data = flatten(get_extra_data(record, task_args=False)) extra_data = { (EXTRA_LOGDATA_PREFIX + key).upper(): stringify(value) for key, value in extra_data } msg = self.format(record) pri = self.mapPriority(record.levelno) send(msg, PRIORITY=format(pri), LOGGER=record.name, THREAD_NAME=record.threadName, CODE_FILE=record.pathname, CODE_LINE=record.lineno, CODE_FUNC=record.funcName, **extra_data) except Exception: self.handleError(record) diff --git a/swh/core/tests/test_logger.py b/swh/core/tests/test_logger.py index 85727bf..e12d6eb 100644 --- a/swh/core/tests/test_logger.py +++ b/swh/core/tests/test_logger.py @@ -1,120 +1,130 @@ # Copyright (C) 2019 The Software Heritage developers # See the AUTHORS file at the top-level directory of this distribution # License: GNU General Public License version 3, or any later version # See top-level LICENSE file for more information from datetime import datetime import logging import pytz import inspect from unittest.mock import patch from swh.core import logger def lineno(): """Returns the current line number in our program.""" return inspect.currentframe().f_back.f_lineno def test_db_level(): assert logger.db_level_of_py_level(10) == 'debug' assert logger.db_level_of_py_level(20) == 'info' assert logger.db_level_of_py_level(30) == 'warning' assert logger.db_level_of_py_level(40) == 'error' assert logger.db_level_of_py_level(50) == 'critical' def test_flatten_scalar(): assert list(logger.flatten('')) == [('', '')] assert list(logger.flatten('toto')) == [('', 'toto')] assert list(logger.flatten(10)) == [('', 10)] assert list(logger.flatten(10.5)) == [('', 10.5)] def test_flatten_list(): assert list(logger.flatten([])) == [] assert list(logger.flatten([1])) == [('0', 1)] assert list(logger.flatten([1, 2, ['a', 'b']])) == [ ('0', 1), ('1', 2), ('2_0', 'a'), ('2_1', 'b'), ] assert list(logger.flatten([1, 2, ['a', ('x', 1)]])) == [ ('0', 1), ('1', 2), ('2_0', 'a'), ('2_1_0', 'x'), ('2_1_1', 1), ] def test_flatten_dict(): assert list(logger.flatten({})) == [] assert list(logger.flatten({'a': 1})) == [('a', 1)] assert sorted(logger.flatten({'a': 1, 'b': (2, 3,), 'c': {'d': 4, 'e': 'f'}})) == [ ('a', 1), ('b_0', 2), ('b_1', 3), ('c_d', 4), ('c_e', 'f'), ] +def test_flatten_dict_binary_keys(): + d = {b"a": "a"} + str_d = str(d) + assert list(logger.flatten(d)) == [("", str_d)] + assert list(logger.flatten({"a": d})) == [("a", str_d)] + assert list(logger.flatten({"a": [d, d]})) == [ + ("a_0", str_d), ("a_1", str_d) + ] + + def test_stringify(): assert logger.stringify(None) == 'None' assert logger.stringify(123) == '123' assert logger.stringify('abc') == 'abc' date = datetime(2019, 9, 1, 16, 32) assert logger.stringify(date) == '2019-09-01T16:32:00' tzdate = datetime(2019, 9, 1, 16, 32, tzinfo=pytz.utc) assert logger.stringify(tzdate) == '2019-09-01T16:32:00+00:00' @patch('swh.core.logger.send') def test_journal_handler(send): log = logging.getLogger('test_logger') log.addHandler(logger.JournalHandler()) log.setLevel(logging.DEBUG) _, ln = log.info('hello world'), lineno() send.assert_called_with( 'hello world', CODE_FILE=__file__, CODE_FUNC='test_journal_handler', CODE_LINE=ln, LOGGER='test_logger', PRIORITY='6', THREAD_NAME='MainThread') @patch('swh.core.logger.send') def test_journal_handler_w_data(send): log = logging.getLogger('test_logger') log.addHandler(logger.JournalHandler()) log.setLevel(logging.DEBUG) _, ln = log.debug('something cool %s', ['with', {'extra': 'data'}]), lineno() # noqa send.assert_called_with( "something cool ['with', {'extra': 'data'}]", CODE_FILE=__file__, CODE_FUNC='test_journal_handler_w_data', CODE_LINE=ln, LOGGER='test_logger', PRIORITY='7', THREAD_NAME='MainThread', SWH_LOGGING_ARGS_0_0='with', SWH_LOGGING_ARGS_0_1_EXTRA='data' )