SysLogHandler can't send long messages

[lukaslalinsky]

BPO	11907
Nosy	@vsajip, @ngie-eign, @bitdancer, @matrixise

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/vsajip'
closed_at = <Date 2011-04-23.19:07:02.032>
created_at = <Date 2011-04-22.13:52:16.508>
labels = ['invalid', 'type-bug', 'library']
title = "SysLogHandler can't send long messages"
updated_at = <Date 2015-11-06.21:44:16.686>
user = 'https://bugs.python.org/lukaslalinsky'

bugs.python.org fields:

activity = <Date 2015-11-06.21:44:16.686>
actor = 'matrixise'
assignee = 'vinay.sajip'
closed = True
closed_date = <Date 2011-04-23.19:07:02.032>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2011-04-22.13:52:16.508>
creator = 'lukas.lalinsky'
dependencies = []
files = []
hgrepos = []
issue_num = 11907
keywords = []
message_count = 14.0
messages = ['134265', '134298', '134312', '134313', '134324', '134325', '134454', '134455', '219909', '219911', '230967', '254223', '254226', '254229']
nosy_count = 7.0
nosy_names = ['vinay.sajip', 'iElectric', 'ngie', 'r.david.murray', 'lukas.lalinsky', 'matrixise', 'Harsh Patel']
pr_nums = []
priority = 'normal'
resolution = 'not a bug'
stage = None
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue11907'
versions = ['Python 2.7']

[lukaslalinsky]

It seems that logging.handlers.SysLogHandler can't handle messages that can't be passed atomically via the socket. I'm not sure what is the right behavior (the syslog() function truncates the message), but I think it shouldn't propagate the exception to the application.

Python 2.7.1 (r271:86832, Apr 18 2011, 08:47:29) 
[GCC 4.2.1 20070719  [FreeBSD]] on freebsd8
Type "help", "copyright", "credits" or "license" for more information.
>>> import logging.handlers
>>> handler = logging.handlers.SysLogHandler('/dev/log')
>>> logger = logging.getLogger()
>>> logger.addHandler(handler)
>>> logger.warn('x' * 4096)
Traceback (most recent call last):
  File "/usr/local/lib/python2.7/logging/handlers.py", line 808, in emit
    self.socket.send(msg)
error: [Errno 40] Message too long
Logged from file <stdin>, line 1

[vsajip]

The entire part of emit() which sends to the socket is wrapped in an except: which should catch all except KeyboardInterrupt and SystemExit. The except clause calls the handleError method of the handler. See

http://hg.python.org/cpython/file/fa277cbd66bb/Lib/logging/handlers.py#l804

So I can't see exactly what's happening, and moreover I can't reproduce this on Linux even when sending messages of > 16384 on the Unix socket. I don't have access to a FreeBSD system.

Can you do a little more investigation, since I'm not sure what your source says? (The line nos. don't seem to match up exactly - in Mercurial, line 808 is an except socket.error clause).

[lukaslalinsky]

It seems that I was wrong, the exception is indeed not propagated to the application, but handled by the handleError() method. I was confused by seeing the traceback in my uWSGI log file.

I'm unable to find a way to determine the maximum allowed syslog message size, otherwise the proper behavior would be probably to truncate the message. Specifically on FreeBSD, the clib source code seems to be using a buffer with 2048 bytes for the whole syslog line and 1024 bytes for the message formatting, so they are just arbitrary numbers. :(

There probably isn't a way to solve this cleanly. Truncating the message would be much preferable to dropping it, but I really don't know what would be the right size.

I'll write a LocalSysLogHandler for me that uses the syslog module.

Regarding the line numbers, this is the version corresponding to the 2.7.1 release - http://hg.python.org/cpython/file/5395f96588d4/Lib/logging/handlers.py#l808

[vsajip]

I've managed to get access to a FreeBSD system and done some investigation. The system is working as designed, and the error message is being printed by the handleError() method of the handler. To handle the exception differently, you either set logging.raiseExceptions to False (which will cause logging to swallow the exception) or you need to implement your own handler which takes appropriate action (e.g truncates the message).

Closing as invalid.

[vsajip]

I'll write a LocalSysLogHandler for me that uses the syslog module.

Sure, but bear in mind that on some Linux systems at least, the syslog module
has thread safety issues because the underlying C APIs are not thread-safe. (I'm
not sure of the situation on FreeBSD.) This shouldn't be a problem if the only
calls to the module are from the handler, since logging has handler locks - but
it could be a problem if other code in your process calls syslog APIs directly.

[lukaslalinsky]

It will be called only from the handler, so I think it should be fine. The reason why I started using syslog was that I need to log into a single file from multiple processes, but it seems to be showing up as too much trouble.

[vsajip]

For other options you might like to consider, see:

http://plumberjack.blogspot.com/2010/09/improved-queuehandler-queuelistener.html

which refers to QueueHandler and QueueListener classes. These were added in 3.2 but are available for Python 2.x:

http://code.google.com/p/logutils/

[vsajip]

Also:

http://plumberjack.blogspot.com/2010/09/using-logging-with-multiprocessing.html

[ngie-eign]

The code doesn't appear to be conforming to RFC-3164 or RFC-5424:

(From RFC-3164):

4.1 syslog Message Parts

The full format of a syslog message seen on the wire has three
discernable parts. The first part is called the PRI, the second part
is the HEADER, and the third part is the MSG. The total length of
the packet MUST be 1024 bytes or less. There is no minimum length of
the syslog message although sending a syslog packet with no contents
is worthless and SHOULD NOT be transmitted.

(From RFC-5424)

The reason syslog transport receivers need only support receiving up
to and including 480 octets has, among other things, to do with
difficult delivery problems in a broken network. Syslog messages may
use a UDP transport mapping with this 480 octet restriction to avoid
session overhead and message fragmentation. In a network with
problems, the likelihood of getting one single-packet message
delivered successfully is higher than getting two message fragments
delivered successfully. Therefore, using a larger size may prevent
the operator from getting some critical information about the
problem, whereas using small messages might get that information to
the operator. It is recommended that messages intended for
troubleshooting purposes should not be larger than 480 octets. To
further strengthen this point, it has also been observed that some
UDP implementations generally do not support message sizes of more
than 480 octets. This behavior is very rare and may no longer be an
issue.

...

It must be noted that the IPv6 MTU is about 2.5 times 480. An
implementation targeted towards an IPv6-only environment might thus
assume this as a larger minimum size.

With MTUs being what they are by default with ethernet, using an MTU <1500 with UDP when jumbo frames aren't available seems like a foolhardy thing to do.

I believe part of the problem is that the socket send buffer size is not being set in the SysLogHandler via socket.setsockopt and it's trying to jam as much information as it can down the pipe and failing, but I need to do more digging...

[ngie-eign]

Please note that when I said "the code" I was looking at python 3.3 on OSX (compiled with MacPorts):

$ python3.3
Python 3.3.5 (default, Mar 11 2014, 15:08:59) 
[GCC 4.2.1 Compatible Apple LLVM 5.0 (clang-500.2.79)] on darwin
Type "help", "copyright", "credits" or "license" for more information.

It's of course similar in lineage (BSD-foundation), but not the same of course..

I have a couple FreeBSD systems I can test this out on as well..

[iElectric]

Note: same bug is relevant to DatagramHandler since it uses UDP transport.

[HarshPatel]

I know this has been closed as "Not a bug" but it would have been convenient if the message was broken down into multiple packets and transmitted, should it exceed the packet limit.
Raising an exception [Errno 40 or Errno 90] or silently ignoring the packet (by setting logging.raiseExceptions to False) doesn't help much in terms of robustness and reliability.
I eventually ended up extending these Handler classes and overriding the send to accomplish breaking messages into multiple parts

[bitdancer]

Writing your own handler is what Vinay recommended.

Is it even possible to determine the maximum message size? If we can't do that reliably, then the best we can do is recommend writing your own exception handler using local knowledge. If it can be determined reliably, you could open a new issue with that feature request.

[matrixise]

This issue will stay closed, BUT I propose you to create a new issue with a new title: Feature: Support message over 1024 bytes for the SysLogHandler. and propose a patch for this feature.