Repository: getlogbook/logbook

Issue:
Should use newline character, not null, for TCP record terminator
As per https://github.com/getlogbook/logbook/blob/master/logbook/handlers.py#L1430, Logbook marks the end of SyslogHandler records with a null character.

I don't know whether this is correct when sending to a socket, but as far as I can tell, the correct record terminator when sending over TCP is newline, not null, and no terminator should be included at all when sending over UDP.

Because it's using a null character instead of a newline, rsyslogd doesn't properly interpret messages sent to it by Logbook via TCP.


Discussion:
coveralls: 
[![Coverage Status](https://coveralls.io/builds/12424876/badge)](https://coveralls.io/builds/12424876)

Coverage decreased (-1.09%) to 72.927% when pulling **ae5be3aa326f82ffbd0d7f6ff9f6c613b1f06d0d on quantopian:master** into **fec1913ddc87841da648018deebdbcbcf0ed9a3f on getlogbook:master**.

coveralls: 
[![Coverage Status](https://coveralls.io/builds/12424876/badge)](https://coveralls.io/builds/12424876)

Coverage decreased (-1.09%) to 72.927% when pulling **ae5be3aa326f82ffbd0d7f6ff9f6c613b1f06d0d on quantopian:master** into **fec1913ddc87841da648018deebdbcbcf0ed9a3f on getlogbook:master**.

coveralls: 
[![Coverage Status](https://coveralls.io/builds/12424876/badge)](https://coveralls.io/builds/12424876)

Coverage decreased (-1.09%) to 72.927% when pulling **ae5be3aa326f82ffbd0d7f6ff9f6c613b1f06d0d on quantopian:master** into **fec1913ddc87841da648018deebdbcbcf0ed9a3f on getlogbook:master**.

coveralls: 
[![Coverage Status](https://coveralls.io/builds/12425185/badge)](https://coveralls.io/builds/12425185)

Coverage increased (+0.1%) to 74.131% when pulling **8ecd7c280037cc8193384249e12354fd4d01cf0e on quantopian:master** into **fec1913ddc87841da648018deebdbcbcf0ed9a3f on getlogbook:master**.

coveralls: 
[![Coverage Status](https://coveralls.io/builds/12425185/badge)](https://coveralls.io/builds/12425185)

Coverage increased (+0.1%) to 74.131% when pulling **8ecd7c280037cc8193384249e12354fd4d01cf0e on quantopian:master** into **fec1913ddc87841da648018deebdbcbcf0ed9a3f on getlogbook:master**.

coveralls: 
[![Coverage Status](https://coveralls.io/builds/12465211/badge)](https://coveralls.io/builds/12465211)

Coverage increased (+0.1%) to 74.158% when pulling **6be7a6f0f3f552ecdcb10759ca430c1f4f12626d on quantopian:master** into **fec1913ddc87841da648018deebdbcbcf0ed9a3f on getlogbook:master**.

coveralls: 
[![Coverage Status](https://coveralls.io/builds/12465211/badge)](https://coveralls.io/builds/12465211)

Coverage increased (+0.1%) to 74.158% when pulling **6be7a6f0f3f552ecdcb10759ca430c1f4f12626d on quantopian:master** into **fec1913ddc87841da648018deebdbcbcf0ed9a3f on getlogbook:master**.

coveralls: 
[![Coverage Status](https://coveralls.io/builds/12465211/badge)](https://coveralls.io/builds/12465211)

Coverage increased (+0.1%) to 74.158% when pulling **6be7a6f0f3f552ecdcb10759ca430c1f4f12626d on quantopian:master** into **fec1913ddc87841da648018deebdbcbcf0ed9a3f on getlogbook:master**.

coveralls: 
[![Coverage Status](https://coveralls.io/builds/12466492/badge)](https://coveralls.io/builds/12466492)

Coverage increased (+0.1%) to 74.14% when pulling **4185f20938065922ee1ef5e3b6e47839bf2cb5d5 on quantopian:master** into **fec1913ddc87841da648018deebdbcbcf0ed9a3f on getlogbook:master**.

jikamens: Sorry about all the crap commits. I've squashed them into the actual functional commits and repushed.
coveralls: 
[![Coverage Status](https://coveralls.io/builds/12466850/badge)](https://coveralls.io/builds/12466850)

Coverage increased (+0.1%) to 74.131% when pulling **169fd69409ab5bf8890dba7b25a643612b6f4d74 on quantopian:master** into **fec1913ddc87841da648018deebdbcbcf0ed9a3f on getlogbook:master**.

coveralls: 
[![Coverage Status](https://coveralls.io/builds/12466973/badge)](https://coveralls.io/builds/12466973)

Coverage increased (+0.1%) to 74.131% when pulling **8a8f9456946a3d942935b5455bb9dbec2c001b6f on quantopian:master** into **fec1913ddc87841da648018deebdbcbcf0ed9a3f on getlogbook:master**.

jikquantopian: Ping?
vmalloc: Sorry - was a bit busy lately so didn't get around to it. I commented in two places for clarifications.

Thanks!
vmalloc: It also seems the Travis tests are failing... have any idea why?
jikamens: > It also seems the Travis tests are failing... have any idea why?

I didn't want to spend time working on the unit tests until I know y'all were comfortable with these changes conceptually. Let me know if you are, and I'll dig into why the tests are failing and whether fixes are needed to the tests or to my proposed changes.
vmalloc: @jikamens I think I'm fine with the changes as long as they don't break existing (reasonable) usage, and as long as they make sense logically...

Having said that, once we merge and release it, we could be seeing issues from people already using Logbook having issues with the change. Will you be available to aid in fixes? I have little time to actively commit to this project nowadays...
jikamens: OK, all issues you mentioned are addressed, I added a couple bonus fixes, I rebased against current getlogbook/master, and Travis is passing. And yes, I'll be around to help if there are bug reports or complaints. Please review, and if everything looks good I'll squash and rebase one more time before merge.

Patch:
diff --git a/CHANGES b/CHANGES
index 7530095..1eb202f 100644
--- a/CHANGES
+++ b/CHANGES
@@ -1,6 +1,12 @@
 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.
 
 Version 1.4.1
diff --git a/logbook/handlers.py b/logbook/handlers.py
index 3533445..72d7ebf 100644
--- a/logbook/handlers.py
+++ b/logbook/handlers.py
@@ -1535,7 +1535,7 @@ class SyslogHandler(Handler, StringFormatterHandlerMixin):
     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 +1546,24 @@ class SyslogHandler(Handler, StringFormatterHandlerMixin):
             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 +1579,7 @@ class SyslogHandler(Handler, StringFormatterHandlerMixin):
         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 +1588,44 @@ class SyslogHandler(Handler, StringFormatterHandlerMixin):
                                                self.LOG_WARNING)
         return (facility << 3) | priority
 
-    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') % (
+    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),
-            prefix,
-            self.format(record)
-        )).encode('utf-8'))
+            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: <PRIVAL>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):
+        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 +1638,11 @@ class SyslogHandler(Handler, StringFormatterHandlerMixin):
             # 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()


Test patch:
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 @@ def test_basic_compat(request, set_root_logger_level):
             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 @@ def test_mail_handler(activation_strategy, logger):
         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 @@ def test_mail_handler_batching(activation_strategy, logger):
     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 @@ def test_group_handler_mail_combo(activation_strategy, logger):
     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 @@ from logbook.helpers import u
 
 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():