Issue 6444: multiline exception logging via syslog handler (original) (raw)

Created on 2009-07-09 07:33 by LwarX, last changed 2022-04-11 14:56 by admin. This issue is now closed.

Messages (12)
msg90307 - (view) Author: Max Arnold (LwarX) Date: 2009-07-09 07:33
I use syslog message routing mechanism to log high-priority messages from my python code to separate file. When exceptions are logged, only first line routed to specified file, and the rest goes in /var/log/messages. Such problem exists when SyslogHandler instantiated with "/dev/log". If logging is performed to remote host via udp socket, then exception logged as one long string with all lines being concatenated. Probably multiline log messages should be automatically splitted and logged line-by-line with the same facility, severity and program name. Also it will be good to have special formatter tag which expands as empty string in first logged line, and as user-defined string in remaining ones. This can simplify automated log analysis.
msg90475 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2009-07-13 10:56
Why can't you either use %r in the format string if you know you'll be printing out multiple lines, or define your own handler/formatter to do exactly what you want? I can't see how to provide what you need in a generally useful way in the stdlib.
msg90510 - (view) Author: Max Arnold (LwarX) Date: 2009-07-14 04:47
> Why can't you either use %r in the format string, or define your own handler/formatter to do exactly what you want? I'm describing default behaviour of logger.exception(). Out of the box (with SyslogHandler and "/dev/log") I'm unable to use it, because of this problem. Can you please explain in more details how I can change my code to correcly log exceptions? For example: import logging, logging.handlers log = logging.getLogger() h = logging.handlers.SysLogHandler('/dev/log', logging.handlers.SysLogHandler.LOG_LOCAL0) h.setFormatter(logging.Formatter('%(name)s: %(levelname)s %(funcName)s/%(lineno)d %(message)s')) log.addHandler(h) try: a = 1/0 except: log.exception('division by zero')
msg90530 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2009-07-15 08:29
Well, I copied your script to "log1.py" and ran it twice. Here's a screenshot from my system log viewer: http://imgur.com/EYnfQ.png I know you can't see all the output in the screenshot, but if I scroll to the right as far as possible I can see that all the exception information is there.
msg90536 - (view) Author: Max Arnold (LwarX) Date: 2009-07-15 16:19
Which syslog daemon you use? I've encountered this on syslog-ng. There is stripped down syslog-ng.conf (messages with facility LOCAL0 are routed to /var/log/local.log and all others to /var/log/default.log): #------------------------------------------------------ options { chain_hostnames(off); use_dns (no); use_fqdn (no); sync(0); stats(43200); }; source src { unix-stream("/dev/log" max-connections(256)); internal(); file("/proc/kmsg"); }; template t_filetmpl { template("$YEAR-$MONTH-$DAY HOUR:HOUR:HOUR:MIN:$SEC HOSTHOST HOSTMSG\n"); }; # Create destinations destination default { file("/var/log/default.log" template(t_filetmpl) ); }; destination local { file("/var/log/local.log" template(t_filetmpl) ); }; # Create filters filter local { facility(local0) or program("^root.*"); }; # Connect source and destinations log { source(src); filter(local); destination(local); flags(final); }; log { source(src); destination(default); }; #------------------------------------------------------ And this is result: # first line landed in /var/log/local.log Jul 15 23:52:02 localhost root: ERROR /14 division by zero # remaining ones in /var/log/default.log Jul 15 23:52:02 localhost Traceback (most recent call last): Jul 15 23:52:02 localhost File "./test.py", line 12, in Jul 15 23:52:02 localhost a = 1/0 Jul 15 23:52:02 localhost ZeroDivisionError: integer division or modulo by zero Results like yours (which are not very readable but still appropriate for me) I get only when logging performed via udp socket.
msg90537 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2009-07-15 16:46
I'm using whatever came with my Ubuntu system - I supposes that's syslogd. Perhaps there's some additional configuration with syslog-ng which will give you the results you want? Plainly, logging is send all the information across, whether it's via UDP or a domain socket. And I'm not sure there are any other reports of this problem with syslog-ng (I'm pretty sure that at least some users of logging are using syslog-ng, and the problem you're seeing would show up whenever an exception is logged.)
msg90552 - (view) Author: Max Arnold (LwarX) Date: 2009-07-16 03:49
I'll try to investigate this issue a bit more in a few days. I plan to compare sysklogd, sylog-ng and probably metalog. Maybe this issue is specific to syslog-ng only.
msg90568 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-07-16 11:36
I can confirm the issue with syslog-ng, and also that it works fine with FreeBSD's syslogd. That said, in the googling I did I ran across code from another project that splits log lines at newlines and also if the logged line is too long...apparently some implementations of syslog don't handle long lines well.
msg91678 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2009-08-18 05:26
Marked as pending, as there has been no activity for a while. Will close if there is no followup.
msg91760 - (view) Author: Simon Litchfield (s29) Date: 2009-08-20 06:00
From the manual for logging.handlers.SysLogHandler -- emit(record) The record is formatted, and then sent to the syslog server. If exception information is present, it is not sent to the server. Ideal, for me, would be to have each traceback line logged as an individual DEBUG message. Maybe that should be an option. For now I'm using a custom handler to achieve this.
msg91764 - (view) Author: Max Arnold (LwarX) Date: 2009-08-20 09:19
Sorry for long delay, I was on vacation. I have installed sysklogd, metalog and syslog-ng on a virtual machine and executed test script. First two daemons log exception as single concatenated line. Syslog-ng splits it as described in original report. Do you suggest to file bug report to syslog-ng maintainer?
msg91806 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2009-08-21 07:15
> Do you suggest to file bug report to syslog-ng maintainer? Yes, I do. Otherwise you can't use it as a drop-in replacement, which people would expect to be possible.
History
Date User Action Args
2022-04-11 14:56:50 admin set github: 50693
2009-08-21 07:15:10 vinay.sajip set status: open -> closedmessages: +
2009-08-20 09:19:36 LwarX set messages: +
2009-08-20 06:00:05 s29 set status: pending -> opennosy: + s29messages: +
2009-08-18 05:26:08 vinay.sajip set status: open -> pendingmessages: +
2009-07-16 11:36:34 r.david.murray set priority: normalnosy: + r.david.murraymessages: +
2009-07-16 03:49:27 LwarX set status: pending -> openmessages: +
2009-07-15 16:46:08 vinay.sajip set status: open -> pendingmessages: +
2009-07-15 16:19:31 LwarX set status: pending -> openmessages: +
2009-07-15 08:29:17 vinay.sajip set status: open -> pendingresolution: works for memessages: +
2009-07-14 04:48:00 LwarX set status: pending -> openmessages: +
2009-07-13 10:56:20 vinay.sajip set status: open -> pendingnosy: + vinay.sajipmessages: + assignee: vinay.sajip
2009-07-09 07:33:58 LwarX create