diff --git a/debian/debian_config_common.py b/debian/debian_config_common.py
index 41e3105..6bae5f9 100644
--- a/debian/debian_config_common.py
+++ b/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(
- default_log_level='INFO'),
- 'handlers': ['syslog', 'mail_admins'],
+ 'level': 'DEBUG',
+ 'filters': ['request_context'],
+ 'handlers': ['syslog', 'mail_admins', 'debug'],
},
},
}
diff --git a/hobo/logger.py b/hobo/logger.py
index 08dee77..b47ee79 100644
--- a/hobo/logger.py
+++ b/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 .
+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
diff --git a/tests_authentic/settings.py b/tests_authentic/settings.py
index c6d8faa..5f13ac3 100644
--- a/tests_authentic/settings.py
+++ b/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'
diff --git a/tests_multitenant/test_logger.py b/tests_multitenant/test_logger.py
new file mode 100644
index 0000000..39f46c5
--- /dev/null
+++ b/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 .
+
+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]
diff --git a/tests_multitenant/test_request_context_filter.py b/tests_multitenant/test_request_context_filter.py
index c850819..3156532 100644
--- a/tests_multitenant/test_request_context_filter.py
+++ b/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
diff --git a/tests_passerelle/settings.py b/tests_passerelle/settings.py
index d489bc6..1d6d834 100644
--- a/tests_passerelle/settings.py
+++ b/tests_passerelle/settings.py
@@ -31,3 +31,4 @@ LOGGING['loggers']['suds'] = {
'handlers': ['mail_admins'],
'propagate': True,
}
+LOGGING['handlers']['debug']['filename'] = 'debug.log'