From c9b19e9306d70eedfba6905b07c57d9906078467 Mon Sep 17 00:00:00 2001 From: Benjamin Dauvergne Date: Wed, 28 Feb 2024 07:42:54 +0100 Subject: [PATCH] misc: send debug logs to journald (#87556) - remove all code related to sending/parsing debug logs in /var/log//debug. - add test on DebugLogFilter. - configure JournalHandler to take debug logs if settings.DEBUG_LOG is True --- debian/debian_config_common.py | 36 ++---- hobo/journal.py | 69 ++---------- hobo/logger.py | 95 +--------------- tests_authentic/settings.py | 3 - tests_multitenant/test_logger.py | 105 +++++------------- .../test_request_context_filter.py | 42 ++++--- tests_passerelle/settings.py | 1 - 7 files changed, 74 insertions(+), 277 deletions(-) diff --git a/debian/debian_config_common.py b/debian/debian_config_common.py index 21edcfe..1560d3d 100644 --- a/debian/debian_config_common.py +++ b/debian/debian_config_common.py @@ -45,11 +45,6 @@ DISABLE_CRON_JOBS = False # mode for newly updated files FILE_UPLOAD_PERMISSIONS = 0o644 -DEBUG_LOG_PATH = '/var/log/%s/debug' % PROJECT_NAME -DEBUG_LOG_FORMAT = ( - '%(asctime)s \x1f%(tenant)s \x1f%(ip)s \x1f%(user)r \x1f%(request_id)s \x1f' - '%(levelname)s \x1f%(name)s \x1f%(message)s' -) DEBUG_PROVISIONNING_LOG_PATH = '/var/log/%s/provisionning-debug' % PROJECT_NAME DISABLE_GLOBAL_HANDLERS = os.environ.get('DISABLE_GLOBAL_HANDLERS') == '1' @@ -84,9 +79,6 @@ LOGGING = { 'format': '%(application)s %(levelname)s %(tenant)s %(ip)s %(user)s %(request_id)s' ' %(message)s', }, - 'debug': { - 'format': DEBUG_LOG_FORMAT, - }, 'syslog_no_filter': { 'format': '%(levelname)s %(message)s', }, @@ -113,16 +105,6 @@ LOGGING = { 'null': { 'class': 'logging.NullHandler', }, - 'debug': { - 'level': 'DEBUG', - 'class': 'hobo.logger.TimedRotatingFileHandler', - 'formatter': 'debug', - 'filename': DEBUG_LOG_PATH, - 'when': 'midnight', - 'backupCount': 1, - 'interval': 1, - 'filters': ['request_context', 'debug_log'], - }, }, 'loggers': { 'django.db': { @@ -186,23 +168,27 @@ LOGGING = { }, '': { 'level': 'DEBUG', - 'filters': ['request_context'], - 'handlers': ([] if DISABLE_GLOBAL_HANDLERS else ['syslog']) + ['mail_admins', 'debug'], + 'filters': ['request_context', 'debug_log'], + 'handlers': ([] if DISABLE_GLOBAL_HANDLERS else ['syslog']) + ['mail_admins'], }, }, } # Journald support if os.path.exists('/run/systemd/journal/socket') and not DISABLE_GLOBAL_HANDLERS: + systemd = None try: - from systemd import journal + import cysystemd as systemd except ImportError: - pass - else: + try: + import systemd + except ImportError: + pass + if systemd: LOGGING['handlers']['journald'] = { - 'level': 'INFO', + 'level': 'DEBUG', 'class': 'hobo.journal.JournalHandler', - 'filters': ['request_context'], + 'filters': ['request_context', 'debug_log'], 'formatter': 'syslog', } LOGGING['loggers']['']['handlers'].remove('syslog') diff --git a/hobo/journal.py b/hobo/journal.py index dce1e1b..53d162c 100644 --- a/hobo/journal.py +++ b/hobo/journal.py @@ -22,8 +22,11 @@ import sys as _sys import traceback as _traceback from syslog import LOG_ALERT, LOG_CRIT, LOG_DEBUG, LOG_ERR, LOG_INFO, LOG_WARNING -# noqa pylint: disable=import-error -from systemd._journal import sendv +try: + # more recent pythong binding is named cysystemd + from cysystemd import journal # noqa pylint: disable=import-error +except ImportError: + from systemd import journal # noqa pylint: disable=import-error _IDENT_CHARACTER = set('ABCDEFGHIJKLMNOPQRTSUVWXYZ_0123456789') @@ -32,61 +35,6 @@ def _valid_field_name(s): return not (set(s) - _IDENT_CHARACTER) -def _make_line(field, value): - if isinstance(value, bytes): - return field.encode('utf-8') + b'=' + value - elif isinstance(value, str): - return field + '=' + value - else: - return field + '=' + str(value) - - -def send(MESSAGE, MESSAGE_ID=None, CODE_FILE=None, CODE_LINE=None, CODE_FUNC=None, **kwargs): - r"""Send a message to the journal. - - >>> from systemd import journal - >>> journal.send('Hello world') - >>> journal.send('Hello, again, world', FIELD2='Greetings!') - >>> journal.send('Binary message', BINARY=b'\xde\xad\xbe\xef') - - Value of the MESSAGE argument will be used for the MESSAGE= field. MESSAGE - must be a string and will be sent as UTF-8 to the journal. - - MESSAGE_ID can be given to uniquely identify the type of message. It must be - a string or a uuid.UUID object. - - CODE_LINE, CODE_FILE, and CODE_FUNC can be specified to identify the caller. - Unless at least on of the three is given, values are extracted from the - stack frame of the caller of send(). CODE_FILE and CODE_FUNC must be - strings, CODE_LINE must be an integer. - - Additional fields for the journal entry can only be specified as keyword - arguments. The payload can be either a string or bytes. A string will be - sent as UTF-8, and bytes will be sent as-is to the journal. - - Other useful fields include PRIORITY, SYSLOG_FACILITY, SYSLOG_IDENTIFIER, - SYSLOG_PID. - """ - - args = ['MESSAGE=' + MESSAGE] - - if MESSAGE_ID is not None: - id = getattr(MESSAGE_ID, 'hex', MESSAGE_ID) - args.append('MESSAGE_ID=' + id) - - if CODE_LINE is CODE_FILE is CODE_FUNC is None: - CODE_FILE, CODE_LINE, CODE_FUNC = _traceback.extract_stack(limit=2)[0][:3] - if CODE_FILE is not None: - args.append('CODE_FILE=' + CODE_FILE) - if CODE_LINE is not None: - args.append(f'CODE_LINE={CODE_LINE:d}') - if CODE_FUNC is not None: - args.append('CODE_FUNC=' + CODE_FUNC) - - args.extend(_make_line(key, val) for key, val in kwargs.items()) - return sendv(*args) - - class JournalHandler(_logging.Handler): """Journal handler class for the Python logging framework. @@ -139,7 +87,7 @@ class JournalHandler(_logging.Handler): the `sender_function` parameter. """ - def __init__(self, level=_logging.NOTSET, sender_function=send, **kwargs): + def __init__(self, level=_logging.NOTSET, **kwargs): super().__init__(level) for name in kwargs: @@ -148,7 +96,6 @@ class JournalHandler(_logging.Handler): if 'SYSLOG_IDENTIFIER' not in kwargs: kwargs['SYSLOG_IDENTIFIER'] = _sys.argv[0] - self.send = sender_function self._extra = kwargs def emit(self, record): @@ -192,8 +139,8 @@ class JournalHandler(_logging.Handler): continue extras[key.upper()] = value - self.send( - msg, + journal.send( + MESSAGE=msg, PRIORITY=format(pri), LOGGER=record.name, THREAD_NAME=record.threadName, diff --git a/hobo/logger.py b/hobo/logger.py index b05c816..d05e87d 100644 --- a/hobo/logger.py +++ b/hobo/logger.py @@ -14,15 +14,10 @@ # You should have received a copy of the GNU Affero General Public License # along with this program. If not, see . -import ast -import datetime import logging import logging.handlers -import os -import time import warnings -import pytz from django.conf import settings from django.db import connection @@ -124,33 +119,17 @@ class ForceDebugFilter(logging.Filter): return super().filter(record) -class LogRecord(logging.LogRecord): - '''Subclass LogRecord to make multiline log parseable''' - - def getMessage(self): - return super().getMessage().replace('\n', '\n ') - - -class TimedRotatingFileHandler(logging.handlers.TimedRotatingFileHandler): - def format(self, record): - old_class = record.__class__ - record.__class__ = LogRecord - try: - return super().format(record) - finally: - record.__class__ = old_class - - class DebugLogFilter: '''Filter debug log records based on the DEBUG_LOG setting''' def filter(self, record): debug_log = getattr(settings, 'DEBUG_LOG', False) + if record.levelno > logging.DEBUG: + return True + if not debug_log: return False - # change class to add space after newlines in message - record.__class__ = LogRecord if debug_log is True: return True elif hasattr(debug_log, 'encode'): @@ -164,74 +143,6 @@ class DebugLogFilter: return bool(debug_log) -class DebugLog: - def __init__(self, path): - self.path = path - - def _pre_lines(self, cursor=0): - if not os.path.exists(self.path): - return - with open(self.path, 'rb') as fd: - accum = '' - - try: - fd.seek(cursor) - except Exception: - return - - for line in fd: - size = len(line) - cursor += size - line = line.decode('utf-8') - - if not accum: - accum = line - elif not line.startswith(' '): - yield cursor - size, accum - accum = line - else: - accum += line[1:] - if accum: - yield cursor, accum - - keys = ['tenant', 'ip', 'user', 'request_id', 'level', 'logger'] - - def _parse(self, cursor=0): - for cursor, line in self._pre_lines(cursor=cursor): - if line.endswith('\n'): - line = line[:-1] - parts = line.split(' \x1f', settings.DEBUG_LOG_FORMAT.count(' \x1f')) - try: - timestamp = datetime.datetime.strptime(parts[0], '%Y-%m-%d %H:%M:%S,%f') - timestamp = pytz.timezone(time.tzname[0]).localize(timestamp) - except ValueError: - continue - message = parts[-1] - d = {key: value for key, value in zip(self.keys, parts[1:-1])} - if 'user' in d: - try: - d['user'] = ast.literal_eval(d['user']) - except SyntaxError: - pass - d.update( - { - 'cursor': cursor, - 'timestamp': timestamp, - 'message': message, - } - ) - yield d - - @classmethod - def lines(cls, cursor=0): - debug_log_path = getattr(settings, 'DEBUG_LOG_PATH', None) - if not debug_log_path: - return - if not os.path.exists(debug_log_path): - return - yield from cls(debug_log_path)._parse(cursor=cursor) - - class ClampLogLevel(logging.Filter): def __init__(self, level): self.levelname = level.upper() diff --git a/tests_authentic/settings.py b/tests_authentic/settings.py index f039a57..eed61f6 100644 --- a/tests_authentic/settings.py +++ b/tests_authentic/settings.py @@ -48,6 +48,3 @@ SESSION_COOKIE_SECURE = False CSRF_COOKIE_SECURE = False LANGUAGE_CODE = 'en' - -# noqa pylint: disable=undefined-variable -LOGGING['handlers']['debug']['filename'] = 'debug.log' diff --git a/tests_multitenant/test_logger.py b/tests_multitenant/test_logger.py index a71aa81..cb94507 100644 --- a/tests_multitenant/test_logger.py +++ b/tests_multitenant/test_logger.py @@ -14,97 +14,42 @@ # You should have received a copy of the GNU Affero General Public License # along with this program. If not, see . -import datetime import logging import logging.config -import time -import pytest -import pytz -from tenant_schemas.utils import tenant_context - -from hobo.logger import ClampLogLevel, DebugLog +from hobo.logger import ClampLogLevel, DebugLogFilter -@pytest.fixture -def debug_log(settings, tmpdir): - debug_log_path = str(tmpdir / 'debug.log') - settings.DEBUG_LOG_PATH = debug_log_path +def test_debug_log_filter(settings, tmp_path): + log_path = tmp_path / 'debug.log' - LOGGING = { - 'version': 1, - 'disable_existing_loggers': True, - 'filters': { - 'debug_log': { - '()': 'hobo.logger.DebugLogFilter', - }, - 'request_context': { - '()': 'hobo.logger.RequestContextFilter', - }, - }, - 'formatters': { - 'debug': { - 'format': settings.DEBUG_LOG_FORMAT, - }, - }, - 'handlers': { - 'debug': { - 'level': 'DEBUG', - 'class': 'hobo.logger.TimedRotatingFileHandler', - 'formatter': 'debug', - 'filename': debug_log_path, - 'when': 'midnight', - 'backupCount': 1, - 'interval': 1, - 'filters': ['request_context', 'debug_log'], - } - }, - 'loggers': { - 'multitenant': { - 'level': 'DEBUG', - 'handlers': ['debug'], - }, - }, - } - logging.config.dictConfig(LOGGING) + settings.DEBUG_LOG = False - logger = logging.getLogger('multitenant') - yield logger - logger.removeHandler(logger.handlers[0]) + logger = logging.getLogger('test') + handler = logging.FileHandler(str(log_path)) + handler.setLevel(logging.DEBUG) + handler.addFilter(DebugLogFilter()) + logger.addHandler(handler) + logger.propagate = False + logger.setLevel(logging.DEBUG) - -def test_debug_log(tenants, settings, app, rf, debug_log, freezer): - freezer.move_to('2020-4-20') - request = rf.get('/path/') - debug_log.info('test %s is ok', 1, extra={'request': request, 'tenant': 'yes'}) - lines = list(DebugLog.lines()) - assert len(lines) == 0 + logger.info('barfoo') + logger.debug('foobar') + assert log_path.read_text().count('barfoo') == 1 + assert log_path.read_text().count('foobar') == 0 settings.DEBUG_LOG = True - with tenant_context(tenants[0]): - debug_log.info( - 'log %s is \nok', 2, extra={'request': request, 'tenant': 'tenant1', 'user': 'jean darmette'} - ) - debug_log.debug('log %s is \nok', 3, extra={'request': request}) - lines = list(DebugLog.lines()) - assert len(lines) == 2 - request_id = hex(id(request))[2:].upper() - assert lines[0] == { - 'cursor': 111, - 'ip': '127.0.0.1', - 'request_id': 'r:' + request_id, - 'message': 'log 2 is \nok', - 'level': 'INFO', - 'tenant': 'tenant1.example.net', - 'timestamp': pytz.timezone(time.tzname[0]).localize(datetime.datetime(2020, 4, 20, 2, 0)), - 'user': '-', - 'logger': 'multitenant', - } + logger.debug('foobar') + assert log_path.read_text().count('foobar') == 1 - # check that seeking by cursor gives the same lines - lines2 = list(DebugLog.lines(cursor=lines[0]['cursor'])) - assert len(lines2) == 1 - assert lines[1] == lines2[0] + settings.DEBUG_LOG = 'test.foobar,test.foobar2' + logger.debug('foobar') + assert log_path.read_text().count('foobar') == 1 + + logging.getLogger('test.foobar').debug('foobar') + logging.getLogger('test.foobar2').debug('foobar') + logging.getLogger('test.foobar3').debug('foobar') + assert log_path.read_text().count('foobar') == 3 def test_clamp_log_level(caplog): diff --git a/tests_multitenant/test_request_context_filter.py b/tests_multitenant/test_request_context_filter.py index 2e9baa0..84e8226 100644 --- a/tests_multitenant/test_request_context_filter.py +++ b/tests_multitenant/test_request_context_filter.py @@ -1,4 +1,5 @@ import logging +from unittest import mock import pytest from _pytest.logging import LogCaptureHandler @@ -75,13 +76,14 @@ def test_request_context_filter(caplog, settings, tenants, client): @pytest.fixture def sender(): - yield MockSender() + with mock.patch('hobo.journal.journal.send') as sender: + yield sender @pytest.fixture def journald_handler(sender): root_logger = logging.getLogger() - journald_handler = JournalHandler(sender_function=sender.send) + journald_handler = JournalHandler() journald_handler.addFilter(RequestContextFilter()) root_logger.handlers.insert(0, journald_handler) # head insert @@ -108,19 +110,29 @@ def test_systemd(settings, tenants, client, journald_handler, sender): client.login(username='john.doe', password='john.doe') client.get('/', SERVER_NAME=tenant.domain_url, HTTP_X_FORWARDED_FOR='99.99.99.99, 127.0.0.1') - assert len(sender.calls) == 2 - for tenant, (args, kwargs) in zip(tenants, sender.calls): - assert args == ('wat!',) - assert kwargs['IP'] == '99.99.99.99' - assert kwargs['TENANT'] == tenant.domain_url - assert kwargs['PATH'] == '/' - assert kwargs['REQUEST_ID'].startswith('r:') - assert kwargs['USER'] == user.username - assert kwargs['USER_EMAIL'] == user.email - assert kwargs['USER_NAME'] == user.username - assert kwargs['USER_DISPLAY_NAME'] == 'John Doe' - assert kwargs['USER_UUID'] == 'ab' * 16 - assert kwargs['APPLICATION'] == 'fake-agent' + assert len(sender.mock_calls) == 2 + for tenant, call in zip(tenants, sender.mock_calls): + for key, value in [ + ('APPLICATION', 'fake-agent'), + ('IP', '99.99.99.99'), + ('LEVELNAME', 'ERROR'), + ('LEVELNO', 40), + ('LOGGER', 'hobo.test_urls'), + ('MESSAGE', 'wat!'), + ('MODULE', 'test_urls'), + ('MSG', 'wat!'), + ('NAME', 'hobo.test_urls'), + ('PATH', '/'), + ('PRIORITY', '3'), + ('REQUEST_ID', mock.ANY), + ('TENANT', tenant.domain_url), + ('USER_DISPLAY_NAME', 'John Doe'), + ('USER_EMAIL', 'jodn.doe@example.com'), + ('USER', 'john.doe'), + ('USER_NAME', 'john.doe'), + ('USER_UUID', 'abababababababababababababababab'), + ]: + assert call.kwargs[key] == value def test_debug_log_filter(caplog, settings): diff --git a/tests_passerelle/settings.py b/tests_passerelle/settings.py index 6e479a0..89af0f1 100644 --- a/tests_passerelle/settings.py +++ b/tests_passerelle/settings.py @@ -32,4 +32,3 @@ LOGGING['loggers']['suds'] = { 'handlers': ['mail_admins'], 'propagate': True, } -LOGGING['handlers']['debug']['filename'] = 'debug.log'