diff --git a/CHANGES b/CHANGES index 7530095..1eb202f 100644 --- a/CHANGES +++ b/CHANGES @@ -1,5 +1,11 @@ Logbook Changelog ================= + +Not yet released + +- Use correct record delimiters (null for UNIX, newline for network) in SyslogHandler (thanks Jonathan Kamens) +- Try to reconnect to SyslogHandler TCP sockets when they are disconnected (thanks Jonathan Kamens) +- Use RFC 5424 format for networking logging in SyslogHandler (thanks Jonathan Kamens) Here you can see the full list of changes between each Logbook release. diff --git a/logbook/handlers.py b/logbook/handlers.py index 3533445..15a19b0 100644 --- a/logbook/handlers.py +++ b/logbook/handlers.py @@ -498,8 +498,7 @@ if (not suppression_count and len(self._record_limits) >= self.max_record_cache): - cache_items = self._record_limits.items() - cache_items.sort() + cache_items = sorted(self._record_limits.items()) del cache_items[:int(self._record_limits) * self.record_cache_prune] self._record_limits = dict(cache_items) @@ -1535,7 +1534,7 @@ def __init__(self, application_name=None, address=None, facility='user', socktype=socket.SOCK_DGRAM, level=NOTSET, format_string=None, filter=None, - bubble=False): + bubble=False, record_delimiter=None): Handler.__init__(self, level, filter, bubble) StringFormatterHandlerMixin.__init__(self, format_string) self.application_name = application_name @@ -1546,14 +1545,24 @@ else: address = '/dev/log' - self.address = address + self.remote_address = self.address = address self.facility = facility self.socktype = socktype if isinstance(address, string_types): self._connect_unixsocket() + self.enveloper = self.unix_envelope + default_delimiter = u'\x00' else: self._connect_netsocket() + self.enveloper = self.net_envelope + default_delimiter = u'\n' + + self.record_delimiter = default_delimiter \ + if record_delimiter is None else record_delimiter + + self.connection_exception = getattr( + __builtins__, 'BrokenPipeError', socket.error) def _connect_unixsocket(self): self.unixsocket = True @@ -1569,7 +1578,7 @@ self.unixsocket = False self.socket = socket.socket(socket.AF_INET, self.socktype) if self.socktype == socket.SOCK_STREAM: - self.socket.connect(self.address) + self.socket.connect(self.remote_address) self.address = self.socket.getsockname() def encode_priority(self, record): @@ -1578,15 +1587,44 @@ self.LOG_WARNING) return (facility << 3) | priority + def wrap_segments(self, record, before): + msg = self.format(record) + segments = [segment for segment in msg.split(self.record_delimiter)] + return (before + segment + self.record_delimiter + for segment in segments) + + def unix_envelope(self, record): + before = u'<{}>{}'.format( + self.encode_priority(record), + self.application_name + ':' if self.application_name else '') + return self.wrap_segments(record, before) + + def net_envelope(self, record): + # Gross but effective + try: + format_string = self.format_string + application_name = self.application_name + if not application_name and record.channel and \ + '{record.channel}: ' in format_string: + self.format_string = format_string.replace( + '{record.channel}: ', '') + self.application_name = record.channel + # RFC 5424: version timestamp hostname app-name procid + # msgid structured-data message + before = u'<{}>1 {}Z {} {} {} - - '.format( + self.encode_priority(record), + record.time.isoformat(), + socket.gethostname(), + self.application_name if self.application_name else '-', + record.process) + return self.wrap_segments(record, before) + finally: + self.format_string = format_string + self.application_name = application_name + def emit(self, record): - prefix = u('') - if self.application_name is not None: - prefix = self.application_name + u(':') - self.send_to_socket((u('<%d>%s%s\x00') % ( - self.encode_priority(record), - prefix, - self.format(record) - )).encode('utf-8')) + for segment in self.enveloper(record): + self.send_to_socket(segment.encode('utf-8')) def send_to_socket(self, data): if self.unixsocket: @@ -1599,7 +1637,11 @@ # the flags are no longer optional on Python 3 self.socket.sendto(data, 0, self.address) else: - self.socket.sendall(data) + try: + self.socket.sendall(data) + except self.connection_exception: + self._connect_netsocket() + self.socket.send(data) def close(self): self.socket.close() diff --git a/tests/test_logging_compat.py b/tests/test_logging_compat.py index 31fdd40..7964993 100644 --- a/tests/test_logging_compat.py +++ b/tests/test_logging_compat.py @@ -33,7 +33,7 @@ with redirected_logging(set_root_logger_level): logger.debug('This is from the old system') logger.info('This is from the old system') - logger.warn('This is from the old %s', 'system') + logger.warning('This is from the old %s', 'system') logger.error('This is from the old system') logger.critical('This is from the old system') logger.error('This is a %(what)s %(where)s', {'what': 'mapping', 'where': 'test'}) diff --git a/tests/test_mail_handler.py b/tests/test_mail_handler.py index fd7730b..718d936 100644 --- a/tests/test_mail_handler.py +++ b/tests/test_mail_handler.py @@ -40,11 +40,11 @@ header, data = mail.split('\n\n', 1) if 'Content-Transfer-Encoding: base64' in header: data = base64.b64decode(data).decode('utf-8') - assert re.search('Message type:\s+ERROR', data) - assert re.search('Location:.*%s' % + assert re.search(r'Message type:\s+ERROR', data) + assert re.search(r'Location:.*%s' % re.escape(__file_without_pyc__), data) - assert re.search('Module:\s+%s' % __name__, data) - assert re.search('Function:\s+test_mail_handler', data) + assert re.search(r'Module:\s+%s' % __name__, data) + assert re.search(r'Function:\s+test_mail_handler', data) body = u('Viva la Espa\xf1a') if sys.version_info < (3, 0): body = body.encode('utf-8') @@ -72,14 +72,14 @@ body, rest = pieces rest = rest.replace('\r', '') - assert re.search('Message type:\s+ERROR', body) - assert re.search('Module:\s+%s' % __name__, body) - assert re.search('Function:\s+test_mail_handler_batching', body) + assert re.search(r'Message type:\s+ERROR', body) + assert re.search(r'Module:\s+%s' % __name__, body) + assert re.search(r'Function:\s+test_mail_handler_batching', body) related = rest.strip().split('\n\n') assert len(related) == 2 - assert re.search('Message type:\s+WARNING', related[0]) - assert re.search('Message type:\s+DEBUG', related[1]) + assert re.search(r'Message type:\s+WARNING', related[0]) + assert re.search(r'Message type:\s+DEBUG', related[1]) assert 'And this triggers it again' in mail_handler.mails[1][2] @@ -101,14 +101,14 @@ body, rest = pieces rest = rest.replace('\r', '') - assert re.search('Message type:\\s+ERROR', body) - assert re.search('Module:\s+' + __name__, body) - assert re.search('Function:\s+test_group_handler_mail_combo', body) + assert re.search(r'Message type:\s+ERROR', body) + assert re.search(r'Module:\s+' + __name__, body) + assert re.search(r'Function:\s+test_group_handler_mail_combo', body) related = rest.strip().split('\n\n') assert len(related) == 2 - assert re.search('Message type:\s+WARNING', related[0]) - assert re.search('Message type:\s+DEBUG', related[1]) + assert re.search(r'Message type:\s+WARNING', related[0]) + assert re.search(r'Message type:\s+DEBUG', related[1]) def test_mail_handler_arguments(): diff --git a/tests/test_syslog_handler.py b/tests/test_syslog_handler.py index 9772a2a..d19d3f2 100644 --- a/tests/test_syslog_handler.py +++ b/tests/test_syslog_handler.py @@ -1,4 +1,5 @@ import os +import re import socket from contextlib import closing @@ -7,33 +8,59 @@ import pytest +unix_socket = "/tmp/__unixsock_logbook.test" -def test_syslog_handler(logger, activation_strategy, unix_sock_path): - to_test = [ - (socket.AF_INET, ('127.0.0.1', 0)), - ] - if hasattr(socket, 'AF_UNIX'): - to_test.append((socket.AF_UNIX, unix_sock_path)) - for sock_family, address in to_test: - with closing(socket.socket(sock_family, socket.SOCK_DGRAM)) as inc: - inc.bind(address) - inc.settimeout(1) - for app_name in [None, 'Testing']: - handler = logbook.SyslogHandler(app_name, inc.getsockname()) - with activation_strategy(handler): - logger.warn('Syslog is weird') - try: +to_test = [ + (socket.AF_INET, socket.SOCK_DGRAM, ('127.0.0.1', 0)), + (socket.AF_INET, socket.SOCK_STREAM, ('127.0.0.1', 0)), +] +if hasattr(socket, 'AF_UNIX'): + to_test.append((socket.AF_UNIX, socket.SOCK_DGRAM, unix_socket)) + +@pytest.mark.usefixtures("unix_sock_path") +@pytest.mark.parametrize("sock_family,socktype,address", to_test) +def test_syslog_handler(logger, activation_strategy, + sock_family, socktype, address): + delimiter = {socket.AF_UNIX: '\x00', + socket.AF_INET: '\n'}[sock_family] + with closing(socket.socket(sock_family, socktype)) as inc: + inc.bind(address) + if socktype == socket.SOCK_STREAM: + inc.listen(0) + inc.settimeout(1) + for app_name in [None, 'Testing']: + if sock_family == socket.AF_UNIX: + expected = (r'^<12>%stestlogger: Syslog is weird%s$' % + (app_name + ':' if app_name else '', + delimiter)) + else: + expected = (r'^<12>1 \d{4}-\d\d-\d\dT\d\d:\d\d:\d\d(\.\d+)?Z %s %s %d ' + '- - %sSyslog is weird%s$' % + (socket.gethostname(), + app_name if app_name else 'testlogger', + os.getpid(), 'testlogger: ' if app_name else '', + delimiter)) + + handler = logbook.SyslogHandler(app_name, inc.getsockname(), + socktype=socktype) + with activation_strategy(handler): + logger.warn('Syslog is weird') + try: + if socktype == socket.SOCK_STREAM: + with closing(inc.accept()[0]) as inc2: + rv = inc2.recv(1024) + else: rv = inc.recvfrom(1024)[0] - except socket.error: - assert False, 'got timeout on socket' - assert rv == ( - u('<12>%stestlogger: Syslog is weird\x00') % - ((app_name and (app_name + u(':'))) or u(''))).encode('utf-8') + except socket.error: + assert False, 'got timeout on socket' + rv = rv.decode('utf-8') + assert re.match(expected, rv), \ + 'expected {}, got {}'.format(expected, rv) @pytest.fixture def unix_sock_path(request): - returned = "/tmp/__unixsock_logbook.test" + returned = unix_socket @request.addfinalizer def cleanup():