This package provides infrastructure for semi-structured log messages.
This means appending easily parseable information after the free-text log message to facilitate analysis of the logs later on. The logging
module of the Python standard library already has support for this, via the extra
parameter. gocept.logging provides a Formatter
that extracts these extra
values, formats them as key=value
pairs and appends them to the message:
>>> import gocept.logging
>>> import logging
>>> import sys
>>> handler = logging.StreamHandler(sys.stdout)
>>> handler.setFormatter(gocept.logging.SyslogKeyValueFormatter())
>>> log = logging.getLogger('example')
>>> log.addHandler(handler)
>>> log.warning('Hello, world!', extra={'foo': 'bar'})
Aug 24 12:10:08 localhost example: Hello, world! foo=bar
This package is tested to be compatible with Python version 2.7 and 3.3.
If you have extra
values that you always want to pass to your log messages (e.g things like the current user, session id, ...) you can wrap your logger with an LoggerAdapter that prefills these values. gocept.logging provides one that allows both stacking adapters and overriding the prefilled values:
>>> from gocept.logging.adapter import StaticDefaults
>>> import logging
>>> log = logging.getLogger('advanced')
>>> log = StaticDefaults(log, {'foo': 'bar', 'qux': 'baz'})
>>> log = StaticDefaults(log, {'blam': 'splat'})
>>> log.warning('Hello, world!', extra={'foo': 'override'})
# yields {'foo': 'override', 'qux': 'baz', 'blam': 'splat'}
To help inspecting the extra
values, gocept.logging comes with a specialized handler for testing:
>>> import gocept.logging
>>> import logging
>>> log = logging.getLogger('testing')
>>> handler = gocept.logging.TestingHandler()
>>> log.addHandler(handler)
>>> log.warning('Hello, world!', extra={'foo': 'bar'})
>>> handler.messages[0].extra['foo']
'bar'
The TestingHandler records each log message as a namedtuple of type gocept.logging.testing.LogMessage
so you an easily access all parts of the message.
Creating semi-structured log messages is the first half of the issue, while analysing them is the second half. We use logstash for that purpose.
The recommended setup is:
application -> syslogd on localhost -> logstash on central host (via UDP syslog input)
For development you might want to leave out the middle man and configure the application to send log messags via syslog protocol directly to logstash.
If you have a paste.ini for your application, you might use something like this:
[loggers]
keys = root
[handlers]
keys = console, syslog
[formatters]
keys = generic, keyvalue
[logger_root]
level = INFO
handlers = console, syslog
[handler_console]
class = StreamHandler
args = (sys.stderr,)
level = NOTSET
formatter = generic
[formatter_generic]
format = %(asctime)s %(levelname)-5.5s %(name)s: %(message)s
[handler_syslog]
class = logging.handlers.SysLogHandler
args = ()
formatter = keyvalue
[formatter_keyvalue]
class = gocept.logging.SyslogKeyValueFormatter
If you have a Zope application, you might use something like this:
<eventlog>
<logfile>
formatter zope.exceptions.log.Formatter
format %(asctime)s %(levelname)-5.5s %(name)s: %(message)s
path STDOUT
</logfile>
<syslog>
formatter gocept.logging.SyslogKeyValueFormatter
</syslog>
</eventlog>
rsyslog:
$EscapeControlCharactersOnReceive off
$MaxMessageSize 64k
user.* @localhost:5140
The first two lines are to support tracebacks, which are multiline and might take up some space. The last line tells rsyslogd to forward all messages of the user
facility (which is what stdlib logging
uses by default) via syslog UDP protocol to localhost port 5140 (where logstash might be listening).
input {
tcp {
host => "localhost"
port => 5140
type => syslog
}
udp {
host => "localhost"
port => 5140
type => syslog
}
}
filter {
grok {
type => "syslog"
pattern => [ "(?m)<%{POSINT:syslog_pri}>%{SYSLOGTIMESTAMP:syslog_timestamp} %{SYSLOGHOST:syslog_hostname} %{DATA:syslog_program}(?:\[%{POSINT:syslog_pid}\])?: %{GREEDYDATA:syslog_message}" ]
}
syslog_pri {
type => "syslog"
}
date {
type => "syslog"
match => [ "syslog_timestamp", "MMM d HH:mm:ss", "MMM dd HH:mm:ss" ]
}
mutate {
type => "syslog"
exclude_tags => "_grokparsefailure"
replace => [ "@source_host", "%{syslog_hostname}" ]
replace => [ "@message", "%{syslog_program}: %{syslog_message}" ]
}
mutate {
type => "syslog"
remove => [ "syslog_hostname", "syslog_timestamp" ]
}
kv {
exclude_tags => "_grokparsefailure"
type => "syslog"
}
}
output {
elasticsearch { embedded => true }
}
The provided gocept.logging.ArgumentParser
provides you with the ability to set a logging
level in you runscripts.:
from gocept.logging import ArgumentParser
parser = ArgumentParser()
# Optionally set a custom log format, defaults to ``logging.BASIC_FORMAT``
parser.LOG_FORMAT = 'LOG:%(message)s'
# add your arguments with parser.add_argument() here
options = parser.parse_args()
Use your_run_script --help
to see a help message about the arguments you can pass to set logging level.
If you log messages as unicode, e.g. log.info(u'foo')
, the SyslogHandler will (incorrectly) prepend a byte-order mark, which confuses the logstash parser, resulting in "_grokparsefailure". This is a known bug in the Python standard library that has been fixed in Python-2.7.4.