classification
Title: multiline exception logging via syslog handler
Type: behavior Stage:
Components: Library (Lib) Versions: Python 2.5
process
Status: closed Resolution: works for me
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: LwarX, r.david.murray, s29, vinay.sajip
Priority: normal Keywords:

Created on 2009-07-09 07:33 by LwarX, last changed 2009-08-21 07:15 by vinay.sajip. 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:$MIN:$SEC $HOST $MSG\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 <module>/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 <module>
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
2009-08-21 07:15:10vinay.sajipsetstatus: open -> closed

messages: + msg91806
2009-08-20 09:19:36LwarXsetmessages: + msg91764
2009-08-20 06:00:05s29setstatus: pending -> open
nosy: + s29
messages: + msg91760

2009-08-18 05:26:08vinay.sajipsetstatus: open -> pending

messages: + msg91678
2009-07-16 11:36:34r.david.murraysetpriority: normal
nosy: + r.david.murray
messages: + msg90568

2009-07-16 03:49:27LwarXsetstatus: pending -> open

messages: + msg90552
2009-07-15 16:46:08vinay.sajipsetstatus: open -> pending

messages: + msg90537
2009-07-15 16:19:31LwarXsetstatus: pending -> open

messages: + msg90536
2009-07-15 08:29:17vinay.sajipsetstatus: open -> pending
resolution: works for me
messages: + msg90530
2009-07-14 04:48:00LwarXsetstatus: pending -> open

messages: + msg90510
2009-07-13 10:56:20vinay.sajipsetstatus: open -> pending

nosy: + vinay.sajip
messages: + msg90475

assignee: vinay.sajip
2009-07-09 07:33:58LwarXcreate