debian: add debug log in /var/log/<app>/debug (#29149)

It's configured through the DEBUG_LOG settings:
* DEBUG_LOG = False, no debug log
* DEBUG_LOG = True, all debug log go to /var/log/<app>/debug
* DEBUG_LOG = app1,app2, only debug log of logger app1 and app2
  go to /var/log/<app>/debug

/var/log/<app>/debug is emptied everyday at midnight.

debian/debian_config_common.py

@@ -46,6 +46,12 @@ 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'
+)
+
 LOGGING = {
     'version': 1,
     'disable_existing_loggers': True,
@@ -62,26 +68,31 @@ LOGGING = {
         'force_debug': {
             '()': 'hobo.logger.ForceDebugFilter',
         },
+        'debug_log': {
+            '()': 'hobo.logger.DebugLogFilter',
+        },
     },
     'formatters': {
         'syslog': {
             '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',
         },
     },
     'handlers': {
         'syslog': {
-            'level': 'DEBUG',
+            'level': 'INFO',
             'address': '/dev/log',
             'class': 'logging.handlers.SysLogHandler',
             'formatter': 'syslog',
-            'filters': ['request_context'],
         },
         'syslog_no_filter': {
-            'level': 'DEBUG',
+            'level': 'INFO',
             'address': '/dev/log',
             'class': 'logging.handlers.SysLogHandler',
             'formatter': 'syslog_no_filter',
@@ -94,6 +105,16 @@ 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': ['debug_log'],
+        }
     },
     'loggers': {
         'django.db': {
@@ -157,9 +178,9 @@ LOGGING = {
             'propagate': False,
         },
         '': {
-            'level': hobo.logger.SettingsLogLevel(
+            'level': 'DEBUG',
-                default_log_level='INFO'),
+            'filters': ['request_context'],
-            'handlers': ['syslog', 'mail_admins'],
+            'handlers': ['syslog', 'mail_admins', 'debug'],
         },
     },
 }

hobo/logger.py

@@ -1,5 +1,5 @@
 # hobo - portal to configure and deploy applications
-# Copyright (C) 2015-2019  Entr'ouvert
+# Copyright (C) 2015-2020  Entr'ouvert
 #
 # This program is free software: you can redistribute it and/or modify it
 # under the terms of the GNU Affero General Public License as published
@@ -14,7 +14,13 @@
 # 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 pytz
+import time
 
 from django.conf import settings
 from django.db import connection
@@ -126,3 +132,107 @@ class ForceDebugFilter(logging.Filter):
         record.levelno = logging.DEBUG
         record.levelname = 'DEBUG'
         return super(ForceDebugFilter, self).filter(record)
+
+
+class LogRecord(logging.LogRecord):
+    '''Subclass LogRecord to make multiline log parseable'''
+    def getMessage(self):
+        return super(LogRecord, self).getMessage().replace('\n', '\n ')
+
+
+class TimedRotatingFileHandler(logging.handlers.TimedRotatingFileHandler):
+    def format(self, record):
+        old_class = record.__class__
+        record.__class__ = LogRecord
+        try:
+            return super(TimedRotatingFileHandler, self).format(record)
+        finally:
+            record.__class__ = old_class
+
+
+class DebugLogFilter(object):
+    '''Filter debug log records based on the DEBUG_LOG setting'''
+
+    def filter(self, record):
+        debug_log = getattr(settings, 'DEBUG_LOG', False)
+        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'):
+            # debug_log is a string
+            domains = [domain.strip() for domain in debug_log.split(',')]
+            return any(record.name == domain or (record.name.startswith(domain) and record.name[len(domain)] == '.')
+                       for domain in domains)
+        else:
+            return bool(debug_log)
+
+
+class DebugLog(object):
+    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
+        for record in cls(debug_log_path)._parse(cursor=cursor):
+            yield record

tests_authentic/settings.py

@@ -46,3 +46,5 @@ SESSION_COOKIE_SECURE = False
 CSRF_COOKIE_SECURE = False
 
 LANGUAGE_CODE = 'en'
+
+LOGGING['handlers']['debug']['filename'] = 'debug.log'

tests_multitenant/test_logger.py

@@ -0,0 +1,107 @@
+# hobo - portal to configure and deploy applications
+# Copyright (C) 2019  Entr'ouvert
+#
+# This program is free software: you can redistribute it and/or modify it
+# under the terms of the GNU Affero General Public License as published
+# by the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU Affero General Public License for more details.
+#
+# 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 pytz
+
+import pytest
+
+from tenant_schemas.utils import tenant_context
+
+from hobo.logger import DebugLog
+
+
+@pytest.fixture
+def debug_log(settings, tmpdir):
+    debug_log_path = str(tmpdir / 'debug.log')
+    settings.DEBUG_LOG_PATH = debug_log_path
+
+    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)
+
+    logger = logging.getLogger('multitenant')
+    yield logger
+    logger.removeHandler(logger.handlers[0])
+
+
+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
+
+    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',
+    }
+
+    # 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]

tests_multitenant/test_request_context_filter.py

@@ -3,7 +3,7 @@ from _pytest.logging import LogCaptureHandler
 
 import logging
 
-from hobo.logger import RequestContextFilter
+from hobo.logger import RequestContextFilter, DebugLogFilter
 
 from tenant_schemas.utils import tenant_context
 
@@ -105,3 +105,35 @@ def test_systemd(settings, tenants, client, journald_handler, sender):
         assert kwargs['USER_DISPLAY_NAME'] == 'John Doe'
         assert kwargs['USER_UUID'] == 'ab' * 16
         assert kwargs['APPLICATION'] == 'fake-agent'
+
+
+def test_debug_log_filter(caplog, settings):
+    # default caplog log level is INFO
+    caplog.set_level(logging.DEBUG)
+
+    root_logger = logging.getLogger()
+    caplog.handler.addFilter(DebugLogFilter())
+
+    root_logger.debug('l1')
+    assert 'l1' not in caplog.text
+
+    settings.DEBUG_LOG = True
+    root_logger.debug('l2')
+    assert 'l2' in caplog.text
+
+    settings.DEBUG_LOG = False
+    root_logger.debug('l3')
+    assert 'l3' not in caplog.text
+
+    settings.DEBUG_LOG = 'app1,app2'
+    root_logger.debug('l4')
+    assert 'l4' not in caplog.text
+
+    logging.getLogger('app3').debug('l5')
+    assert 'l5' not in caplog.text
+
+    logging.getLogger('app1').debug('l6')
+    assert 'l6' in caplog.text
+
+    logging.getLogger('app2').debug('l7')
+    assert 'l7' in caplog.text

tests_passerelle/settings.py

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