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'