classification
Title: SysLogHandler can't send long messages
Type: behavior Stage:
Components: Library (Lib) Versions: Python 2.7
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: Harsh Patel, iElectric, lukas.lalinsky, matrixise, ngie, r.david.murray, vinay.sajip
Priority: normal Keywords:

Created on 2011-04-22 13:52 by lukas.lalinsky, last changed 2015-11-06 21:44 by matrixise. This issue is now closed.

Messages (14)
msg134265 - (view) Author: Lukáš Lalinský (lukas.lalinsky) Date: 2011-04-22 13:52
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
msg134298 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-04-23 10:24
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).
msg134312 - (view) Author: Lukáš Lalinský (lukas.lalinsky) Date: 2011-04-23 18:24
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
msg134313 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-04-23 19:07
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.
msg134324 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-04-24 05:26
> 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.
msg134325 - (view) Author: Lukáš Lalinský (lukas.lalinsky) Date: 2011-04-24 06:18
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.
msg134454 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-04-26 12:30
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/
msg134455 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2011-04-26 12:31
Also:

http://plumberjack.blogspot.com/2010/09/using-logging-with-multiprocessing.html
msg219909 - (view) Author: Enji Cooper (ngie) * Date: 2014-06-07 03:34
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...
msg219911 - (view) Author: Enji Cooper (ngie) * Date: 2014-06-07 03:37
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..
msg230967 - (view) Author: Domen Kožar (iElectric) Date: 2014-11-10 17:19
Note: same bug is relevant to DatagramHandler since it uses UDP transport.
msg254223 - (view) Author: Harsh Patel (Harsh Patel) Date: 2015-11-06 21:30
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
msg254226 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-11-06 21:35
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.
msg254229 - (view) Author: Stéphane Wirtel (matrixise) * (Python committer) Date: 2015-11-06 21:44
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.
History
Date User Action Args
2015-11-06 21:44:16matrixisesetnosy: + matrixise
messages: + msg254229
2015-11-06 21:35:16r.david.murraysetnosy: + r.david.murray
messages: + msg254226
2015-11-06 21:30:20Harsh Patelsetnosy: + Harsh Patel
messages: + msg254223
2014-11-10 17:19:07iElectricsetnosy: + iElectric
messages: + msg230967
2014-06-07 03:37:06ngiesetmessages: + msg219911
2014-06-07 03:34:59ngiesetnosy: + ngie
messages: + msg219909
2011-04-26 12:31:25vinay.sajipsetmessages: + msg134455
2011-04-26 12:30:35vinay.sajipsetmessages: + msg134454
2011-04-24 06:18:22lukas.lalinskysetmessages: + msg134325
2011-04-24 05:26:16vinay.sajipsetmessages: + msg134324
2011-04-23 19:07:02vinay.sajipsetstatus: open -> closed
resolution: not a bug
messages: + msg134313
2011-04-23 18:24:47lukas.lalinskysetstatus: pending -> open

messages: + msg134312
2011-04-23 10:24:34vinay.sajipsetstatus: open -> pending
versions: - Python 3.2, Python 3.3
messages: + msg134298

components: + Library (Lib)
type: crash -> behavior
2011-04-23 09:14:40vinay.sajipsetassignee: vinay.sajip

nosy: + vinay.sajip
versions: + Python 3.2, Python 3.3
2011-04-22 13:52:16lukas.lalinskycreate