misc: send debug logs to journald (#87556)

- remove all code related to sending/parsing debug logs in
  /var/log/<app>/debug.
- add test on DebugLogFilter.
- configure JournalHandler to take debug logs if settings.DEBUG_LOG is True

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'],
+            'filters': ['request_context', 'debug_log'],
-            'handlers': ([] if DISABLE_GLOBAL_HANDLERS else ['syslog']) + ['mail_admins', 'debug'],
+            '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
+        try:
-    else:
+            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')

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
+try:
-from systemd._journal import sendv
+    # 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(
+            journal.send(
-                msg,
+                MESSAGE=msg,
                 PRIORITY=format(pri),
                 LOGGER=record.name,
                 THREAD_NAME=record.threadName,

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 <http://www.gnu.org/licenses/>.
 
-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()

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'

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 <http://www.gnu.org/licenses/>.
 
-import datetime
 import logging
 import logging.config
-import time
 
-import pytest
+from hobo.logger import ClampLogLevel, DebugLogFilter
-import pytz
-from tenant_schemas.utils import tenant_context
-
-from hobo.logger import ClampLogLevel, DebugLog
 
 
-@pytest.fixture
+def test_debug_log_filter(settings, tmp_path):
-def debug_log(settings, tmpdir):
+    log_path = tmp_path / 'debug.log'
-    debug_log_path = str(tmpdir / 'debug.log')
-    settings.DEBUG_LOG_PATH = debug_log_path
 
-    LOGGING = {
+    settings.DEBUG_LOG = False
-        '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)
 
-    logger = logging.getLogger('multitenant')
+    logger = logging.getLogger('test')
-    yield logger
+    handler = logging.FileHandler(str(log_path))
-    logger.removeHandler(logger.handlers[0])
+    handler.setLevel(logging.DEBUG)
+    handler.addFilter(DebugLogFilter())
+    logger.addHandler(handler)
+    logger.propagate = False
+    logger.setLevel(logging.DEBUG)
 
-
+    logger.info('barfoo')
-def test_debug_log(tenants, settings, app, rf, debug_log, freezer):
+    logger.debug('foobar')
-    freezer.move_to('2020-4-20')
+    assert log_path.read_text().count('barfoo') == 1
-    request = rf.get('/path/')
+    assert log_path.read_text().count('foobar') == 0
-    debug_log.info('test %s is ok', 1, extra={'request': request, 'tenant': 'yes'})
-    lines = list(DebugLog.lines())
-    assert len(lines) == 0
 
     settings.DEBUG_LOG = True
-    with tenant_context(tenants[0]):
+    logger.debug('foobar')
-        debug_log.info(
+    assert log_path.read_text().count('foobar') == 1
-            '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',
-    }
 
-    # check that seeking by cursor gives the same lines
+    settings.DEBUG_LOG = 'test.foobar,test.foobar2'
-    lines2 = list(DebugLog.lines(cursor=lines[0]['cursor']))
+    logger.debug('foobar')
-    assert len(lines2) == 1
+    assert log_path.read_text().count('foobar') == 1
-    assert lines[1] == lines2[0]
+
+    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):

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
+    assert len(sender.mock_calls) == 2
-    for tenant, (args, kwargs) in zip(tenants, sender.calls):
+    for tenant, call in zip(tenants, sender.mock_calls):
-        assert args == ('wat!',)
+        for key, value in [
-        assert kwargs['IP'] == '99.99.99.99'
+            ('APPLICATION', 'fake-agent'),
-        assert kwargs['TENANT'] == tenant.domain_url
+            ('IP', '99.99.99.99'),
-        assert kwargs['PATH'] == '/'
+            ('LEVELNAME', 'ERROR'),
-        assert kwargs['REQUEST_ID'].startswith('r:')
+            ('LEVELNO', 40),
-        assert kwargs['USER'] == user.username
+            ('LOGGER', 'hobo.test_urls'),
-        assert kwargs['USER_EMAIL'] == user.email
+            ('MESSAGE', 'wat!'),
-        assert kwargs['USER_NAME'] == user.username
+            ('MODULE', 'test_urls'),
-        assert kwargs['USER_DISPLAY_NAME'] == 'John Doe'
+            ('MSG', 'wat!'),
-        assert kwargs['USER_UUID'] == 'ab' * 16
+            ('NAME', 'hobo.test_urls'),
-        assert kwargs['APPLICATION'] == 'fake-agent'
+            ('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):

tests_passerelle/settings.py

@@ -32,4 +32,3 @@ LOGGING['loggers']['suds'] = {
     'handlers': ['mail_admins'],
     'propagate': True,
 }
-LOGGING['handlers']['debug']['filename'] = 'debug.log'